Merge lp:~canonical-isd-hackers/canonical-identity-provider/767454-lp-time into lp:canonical-identity-provider/release

[David Owen]

Log requests that take too long to complete.

[Simon Davy (bloodearnest)]

LGTM

=== modified file 'django_project/config_dev/config/devel.cfg'
--- django_project/config_dev/config/devel.cfg	2011-12-07 18:53:10 +0000
+++ django_project/config_dev/config/devel.cfg	2011-12-16 16:07:26 +0000
@@ -27,6 +27,7 @@
     saml2idp
     devserver
 middleware_classes =
+    identityprovider.middleware.time.TimeMiddleware
     identityprovider.middleware.dbfailover.DBFailoverMiddleware
     django.middleware.common.CommonMiddleware
     django.contrib.sessions.middleware.SessionMiddleware

=== modified file 'django_project/config_dev/config/main.cfg'
--- django_project/config_dev/config/main.cfg	2011-12-16 15:46:14 +0000
+++ django_project/config_dev/config/main.cfg	2011-12-16 16:07:26 +0000
@@ -55,6 +55,7 @@
 login_url = /+login
 managers = %(admins)s
 middleware_classes =
+    identityprovider.middleware.time.TimeMiddleware
 #    identityprovider.middleware.dbfailover.DBFailoverMiddleware
     django.middleware.common.CommonMiddleware
     django.contrib.sessions.middleware.SessionMiddleware

=== modified file 'identityprovider/middleware/exception.py'
--- identityprovider/middleware/exception.py	2011-12-15 22:07:59 +0000
+++ identityprovider/middleware/exception.py	2011-12-16 16:07:26 +0000
@@ -1,6 +1,7 @@
 # Copyright 2011 Canonical Ltd.  This software is licensed under the
 # GNU Affero General Public License version 3 (see the file LICENSE).
 
+import logging
 import sys
 import traceback
 
@@ -15,4 +16,5 @@
 class LogExceptionMiddleware(object):
 
     def process_exception(self, request, exception):
-        log_request(request)
+        logging.exception('Unhandled exception in application')
+        log_request(request, log_exception_trace=True)

=== added file 'identityprovider/middleware/time.py'
--- identityprovider/middleware/time.py	1970-01-01 00:00:00 +0000
+++ identityprovider/middleware/time.py	2011-12-16 16:07:26 +0000
@@ -0,0 +1,25 @@
+# Copyright 2011 Canonical Ltd.  This software is licensed under the
+# GNU Affero General Public License version 3 (see the file LICENSE).
+
+import datetime
+import logging as log
+
+from django.conf import settings
+
+from .util import log_request
+
+
+class TimeMiddleware(object):
+
+    def process_request(self, request):
+        request._time_start = datetime.datetime.now()
+        return None
+
+    def process_response(self, request, response):
+        time_taken = datetime.datetime.now() - request._time_start
+        limit = datetime.timedelta(milliseconds=settings.HANDLER_TIMEOUT_MILLIS)
+        if time_taken > limit:
+            log.warning('Took too long: %s' % time_taken)
+            log_request(request)
+
+        return response

=== modified file 'identityprovider/middleware/util.py'
--- identityprovider/middleware/util.py	2011-12-15 22:07:59 +0000
+++ identityprovider/middleware/util.py	2011-12-16 16:07:26 +0000
@@ -10,6 +10,7 @@
 from django.db import connection
 from django.views import debug
 
+
 debug.HIDDEN_SETTINGS = re.compile(
     'SECRET|PASSWORD|PROFANITIES_LIST|PRIVATE|secret|password|private')
 
@@ -85,16 +86,17 @@
         return frames
 
 
-def log_request(request):
+def log_request(request, log_exception_trace=False):
     """Log the request, so that it can be kept in the oops file"""
     request = _sanitize_request(request)
     reporter = _ExceptionReporter(request, *sys.exc_info())
+
     template_debug = settings.TEMPLATE_DEBUG
     settings.TEMPLATE_DEBUG = True
     try:
-        logging.exception('Unhandled exception in application')
         logging.warn(reporter.get_traceback_html())
-        logging.warn(traceback.format_exc())
+        if log_exception_trace:
+            logging.warn(traceback.format_exc())
         for query in connection.queries:
             logging.warn("time: %(time)s sql: %(sql)s" % query)
     finally:

=== modified file 'identityprovider/schema.py'
--- identityprovider/schema.py	2011-11-21 19:38:07 +0000
+++ identityprovider/schema.py	2011-12-16 16:07:26 +0000
@@ -40,6 +40,7 @@
     db_statement_timeout_millis = IntConfigOption(
         default=0, help='0 disables timeout')
     extra_pythonpath = LinesConfigOption(item=StringConfigOption())
+    handler_timeout_millis = IntConfigOption(default=10000)
     oops_dir = StringConfigOption(help='Absolute path to the directory oops'
         ' reports will be stored in')
     pgconnect_timeout = IntConfigOption(default=10)

=== modified file 'identityprovider/tests/test_middleware.py'
--- identityprovider/tests/test_middleware.py	2011-12-15 22:07:59 +0000
+++ identityprovider/tests/test_middleware.py	2011-12-16 16:07:26 +0000
@@ -1,23 +1,28 @@
-# Copyright 2010 Canonical Ltd.  This software is licensed under the
+# Copyright 2011 Canonical Ltd.  This software is licensed under the
 # GNU Affero General Public License version 3 (see the file LICENSE).
 
-import logging
 import re
 import sys
+from time import sleep
 
 from django.conf import settings
+from django.core.urlresolvers import reverse
+from django.http import HttpResponse
 from django.test import TestCase
 from django.contrib.auth.models import User, AnonymousUser
 
+from mock import patch
+
 from openid.message import IDENTIFIER_SELECT, OPENID1_URL_LIMIT, OPENID2_NS
 
-from identityprovider.tests.utils import MockRequest
-from identityprovider.models import Account, EmailAddress, OpenIDRPConfig
 from identityprovider.middleware import exception, util as middleware_util
 from identityprovider.middleware.useraccount import (
     UserAccountConversionMiddleware)
+from identityprovider.models import Account, EmailAddress, OpenIDRPConfig
+from identityprovider.tests.utils import MockRequest
+from identityprovider.views import testing as test_views
 
-from .utils import SSOBaseTestCase
+from .utils import SSOBaseTestCase, patch_settings
 
 
 def _extract_csrf_token(response):
@@ -72,7 +77,7 @@
         self.assertTrue(isinstance(request.user, AnonymousUser))
 
 
-class ExceptionMiddlewareTestCase(TestCase):
+class UtilTestCase(TestCase):
 
     POST_PASSWORD = 'P1!2@3#'
     POST_SECRET = 'P2@3#4$'
@@ -83,16 +88,8 @@
     POST_PUBLIC = 'Canonical Rocks!'
     GET_PUBLIC = 'Canonical Rocks!'
     asterisks = '********'
-    PRIVATE_SETTING = '7&8*9('
-    PUBLIC_SETTING = 'Something public'
-    FRAME_VAR = '*8*8*8*8'
-
-    LOG_FILENAME = '/tmp/logging_example.out'
-    logging.basicConfig(filename=LOG_FILENAME, level=logging.DEBUG)
-
-    logging.debug('This message should go to the log file')
-
-    def setUp(self):
+
+    def test_request_sanitization(self):
         request = MockRequest('/login')
         request.POST = {}
         request.GET = {}
@@ -106,34 +103,9 @@
         request.GET['get_secret'] = self.GET_SECRET
         request.GET['get_private'] = self.GET_PRIVATE
         request.GET['get_public'] = self.GET_PUBLIC
-        self.request = request
-        self.middleware = exception.LogExceptionMiddleware()
-        settings.PRIVATE_SETTING = self.PRIVATE_SETTING
-        settings.PUBLIC_SETTING = self.PUBLIC_SETTING
-
-    def test_settings_sanitization(self):
-        try:
-            x = 2 / 0
-        except:
-            reporter = middleware_util._ExceptionReporter(self.request,
-                                                          *sys.exc_info())
-            html = reporter.get_traceback_html()
-        self.assertFalse(self.PRIVATE_SETTING in html)
-        self.assertTrue(self.PUBLIC_SETTING in html)
-
-    def test_frames_sanitization(self):
-        try:
-            FRAME_PASSWORD = self.FRAME_VAR
-            public_variable = 2 / 0
-        except:
-            reporter = middleware_util._ExceptionReporter(self.request,
-                                                          *sys.exc_info())
-            html = reporter.get_traceback_html()
-        self.assertFalse(self.FRAME_VAR in html)
-        self.assertTrue('public_variable' in html)
-
-    def test_request_sanitization(self):
-        req = middleware_util._sanitize_request(self.request)
+
+        req = middleware_util._sanitize_request(request)
+
         #  Make sure sensitive data is no longer in the request
         self.assertFalse(self.POST_PASSWORD in req.POST.values())
         self.assertFalse(self.POST_SECRET in req.POST.values())
@@ -153,6 +125,65 @@
         self.assertEquals(req.GET['get_public'], self.GET_PUBLIC)
 
 
+class ExceptionMiddlewareTestCase(TestCase):
+
+    PRIVATE_SETTING = '7&8*9('
+    PUBLIC_SETTING = 'Something public'
+    FRAME_VAR = '*8*8*8*8'
+
+    def setUp(self):
+        self.request = MockRequest('/login')
+        self.request.META = {'SERVER_NAME': 'localhost', 'SERVER_PORT': 80}
+        self.middleware = exception.LogExceptionMiddleware()
+
+    def _get_traceback_html(self):
+        reporter = middleware_util._ExceptionReporter(
+            self.request, *sys.exc_info())
+        return reporter.get_traceback_html()
+
+    def test_settings_sanitization(self):
+        settings.PRIVATE_SETTING = self.PRIVATE_SETTING
+        settings.PUBLIC_SETTING = self.PUBLIC_SETTING
+
+        try:
+            x = 2 / 0
+        except:
+            html = self._get_traceback_html()
+
+        self.assertFalse(self.PRIVATE_SETTING in html)
+        self.assertTrue(self.PUBLIC_SETTING in html)
+
+    def test_frames_sanitization(self):
+        try:
+            FRAME_PASSWORD = self.FRAME_VAR
+            public_variable = 2 / 0
+        except:
+            html = self._get_traceback_html()
+
+        self.assertFalse(self.FRAME_VAR in html)
+        self.assertTrue('public_variable' in html)
+
+
+class TimeMiddlewareTestCase(TestCase):
+
+    @patch('identityprovider.middleware.time.log_request')
+    @patch.object(test_views, 'dummy_hook')
+    def _check(self, timeout_millis, sleep_secs, calls, hook, log):
+        hook.return_value = HttpResponse('DONE')
+        hook.side_effect = sleep(sleep_secs)
+        path = reverse(test_views.dummy)
+        with patch_settings(HANDLER_TIMEOUT_MILLIS=timeout_millis):
+            self.client.get(path)
+        self.assertEquals(hook.call_count, 1)
+        self.assertEquals(log.call_count, calls)
+
+    def test_under_time(self):
+        self._check(5000, 0, 0)
+
+    def test_over_time(self):
+        self._check(1, 0.1, 1)
+
+
 # The CSRF middleware requires a session cookie in order to activate.
 # The tests perform a login in order to acquire this session cookie.
 class CSRFMiddlewareTestCase(SSOBaseTestCase):

=== modified file 'identityprovider/urls.py'
--- identityprovider/urls.py	2011-12-15 18:35:03 +0000
+++ identityprovider/urls.py	2011-12-16 16:07:26 +0000
@@ -122,6 +122,9 @@
     urlpatterns += patterns('identityprovider.views.account',
         (r'^%(optional_token)s\+deactivate$' % repls, 'account_deactivate'),
     )
+    urlpatterns += patterns('identityprovider.views.testing',
+        (r'^dummy$', 'dummy'),
+    )
 
 # Keep this at the end, so no important URL will be overridden
 if settings.BRAND.lower() == 'ubuntu':

=== modified file 'identityprovider/views/testing.py'
--- identityprovider/views/testing.py	2010-11-02 19:45:33 +0000
+++ identityprovider/views/testing.py	2011-12-16 16:07:26 +0000
@@ -75,3 +75,11 @@
   <input type="submit" value="Lock">
 </form>
 ''')
+
+# This gives mock & patch a nice easy location to patch a wait into
+# the handler.
+def dummy_hook():
+    return HttpResponse('DONE')
+
+def dummy(request):
+    return dummy_hook()