Log how long requests take to process.

(imported from commit 89915f859e4493ff04a34d198ac6df5541b743cc)

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',)

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