From 7ae73fabd4a5ee892a22c8afa577be3d04105055 Mon Sep 17 00:00:00 2001
From: Tim Abbott <tabbott@humbughq.com>
Date: Wed, 14 Nov 2012 15:00:26 -0500
Subject: [PATCH] Log how long requests take to process.

(imported from commit 89915f859e4493ff04a34d198ac6df5541b743cc)
---
 humbug/settings.py   |  3 ++-
 zephyr/middleware.py | 14 ++++++++++++--
 2 files changed, 14 insertions(+), 3 deletions(-)

diff --git a/humbug/settings.py b/humbug/settings.py
index 30cc292409..5264e4638f 100644
--- a/humbug/settings.py
+++ b/humbug/settings.py
@@ -118,12 +118,13 @@ TEMPLATE_LOADERS = (
 )
 
 MIDDLEWARE_CLASSES = (
+    # Our logging middleware should be the first middleware item.
+    'zephyr.middleware.LogRequests',
     'django.middleware.common.CommonMiddleware',
     'django.contrib.sessions.middleware.SessionMiddleware',
     'django.middleware.csrf.CsrfViewMiddleware',
     'django.contrib.auth.middleware.AuthenticationMiddleware',
     'django.contrib.messages.middleware.MessageMiddleware',
-    'zephyr.middleware.LogRequests',
 )
 
 AUTHENTICATION_BACKENDS = ('humbug.backends.EmailAuthBackend',)
diff --git a/zephyr/middleware.py b/zephyr/middleware.py
index 2db3bf313e..d32589f0f8 100644
--- a/zephyr/middleware.py
+++ b/zephyr/middleware.py
@@ -1,8 +1,12 @@
 import logging
+import time
 
 logger = logging.getLogger('humbug.requests')
 
 class LogRequests(object):
+    def process_request(self, request):
+        request._time_started = time.time()
+
     def process_response(self, request, response):
 
         # The reverse proxy might have sent us the real external IP
@@ -10,6 +14,12 @@ class LogRequests(object):
         if remote_ip is None:
             remote_ip = request.META['REMOTE_ADDR']
 
-        logger.info('%-15s %-7s %3d %s'
-            % (remote_ip, request.method, response.status_code, request.get_full_path()))
+        time_delta = -1
+        # A time duration of -1 means the StartLogRequests middleware
+        # didn't run for some reason
+        if hasattr(request, '_time_started'):
+            time_delta = time.time() - request._time_started
+        logger.info('%-15s %-7s %3d %.3fs %s'
+            % (remote_ip, request.method, response.status_code,
+               time_delta, request.get_full_path()))
         return response