Merge lp:~elachuni/rnr-server/app-timeout into lp:rnr-server

[Anthony Lenton]

Added SoftTimeoutMiddleware to trigger an oops report before haproxy times out

This branch adds a "Soft Timeout" middleware to keep an oops report when a request exceeds a configurable length of time. The oops report will include the total time used by the request, and all sql queries performed.

To allow QA to test the timeout middleware I also provided a 'delay' view that can delay the response for any amount before returning.

While I was adding tests for the middleware I found that ExceptionMiddlewareTestCase hadn't been added to __all__, so those tests weren't being run at all :/ And, they failed miserably for several reasons, so I also made those pass.

=== modified file 'django_project/config_dev/config/main.cfg'
--- django_project/config_dev/config/main.cfg	2011-09-08 13:55:52 +0000
+++ django_project/config_dev/config/main.cfg	2012-03-21 22:21:27 +0000
@@ -52,7 +52,8 @@
     django.template.loaders.app_directories.load_template_source
     django.template.loaders.eggs.load_template_source
 
-middleware_classes = django.middleware.http.ConditionalGetMiddleware
+middleware_classes = reviewsapp.middleware.timeouts.SoftTimeoutMiddleware
+    django.middleware.http.ConditionalGetMiddleware
     django.middleware.cache.UpdateCacheMiddleware
     django.middleware.common.CommonMiddleware
     django.contrib.csrf.middleware.CsrfMiddleware

=== modified file 'src/reviewsapp/middleware/exception.py'
--- src/reviewsapp/middleware/exception.py	2011-03-30 16:32:11 +0000
+++ src/reviewsapp/middleware/exception.py	2012-03-21 22:21:27 +0000
@@ -104,6 +104,7 @@
         template_debug = settings.TEMPLATE_DEBUG
         settings.TEMPLATE_DEBUG = True
         try:
+            logging.warn(reporter.get_traceback_html())
             logging.warn(traceback.format_exc())
             for query in connection.queries:
                 logging.warn("time: %(time)s sql: %(sql)s" % query)

=== added file 'src/reviewsapp/middleware/timeouts.py'
--- src/reviewsapp/middleware/timeouts.py	1970-01-01 00:00:00 +0000
+++ src/reviewsapp/middleware/timeouts.py	2012-03-21 22:21:27 +0000
@@ -0,0 +1,50 @@
+#   This file is part of Software Center Ratings and Reviews
+#   Copyright (C) 2010 Canonical Ltd.
+#
+#   This program is free software: you can redistribute it and/or modify
+#   it under the terms of the GNU Affero General Public License as
+#   published by the Free Software Foundation, either version 3 of the
+#   License, or (at your option) any later version.
+#
+#   This program is distributed in the hope that it will be useful,
+#   but WITHOUT ANY WARRANTY; without even the implied warranty of
+#   MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+#   GNU Affero General Public License for more details.
+#
+#   You should have received a copy of the GNU Affero General Public License
+#   along with this program.  If not, see <http://www.gnu.org/licenses/>.
+
+"""A response middleware that uses oops reports for soft timeouts."""
+
+from __future__ import absolute_import
+
+__metaclass__ = type
+__all__ = [
+    'SoftTimeoutMiddleware',
+    ]
+
+import logging
+from time import time
+
+from django.conf import settings
+from django.core.exceptions import MiddlewareNotUsed
+from django.db import connection
+
+
+class SoftTimeoutMiddleware(object):
+    def __init__(self):
+        if settings.SOFT_REQUEST_TIMEOUT == 0:
+            raise MiddlewareNotUsed()
+
+    def process_request(self, request):
+        request._start_time = time()
+
+    def process_response(self, request, response):
+        if hasattr(request, '_start_time'):
+            total = time() - request._start_time
+            if total > settings.SOFT_REQUEST_TIMEOUT:
+                logging.warn('Request took %.3f seconds to return' % total)
+                for query in connection.queries:
+                    logging.warn("time: %(time)s sql: %(sql)s" % query)
+                request.environ['dump-oops'] = 'yes'
+        return response

=== modified file 'src/reviewsapp/schema.py'
--- src/reviewsapp/schema.py	2012-01-27 12:55:57 +0000
+++ src/reviewsapp/schema.py	2012-03-21 22:21:27 +0000
@@ -25,6 +25,7 @@
     serve_static_media = BoolConfigOption()
     extra_pythonpath = LinesConfigOption(item=StringConfigOption())
     default_timeout = IntConfigOption(default=None)
+    soft_request_timeout = IntConfigOption(default=20)
 
     # openid
     openid = ConfigSection()

=== modified file 'src/reviewsapp/tests/test_middleware.py'
--- src/reviewsapp/tests/test_middleware.py	2012-01-25 16:13:06 +0000
+++ src/reviewsapp/tests/test_middleware.py	2012-03-21 22:21:27 +0000
@@ -21,17 +21,25 @@
 __metaclass__ = type
 __all__ = [
     'StatsLoggingTestCase',
+    'ExceptionMiddlewareTestCase',
+    'SoftTimeoutMiddlewareTestCase',
     ]
 
 import logging
+import sys
 import time
 
+from django.http import HttpRequest
+from django.conf import settings
 from django.core.urlresolvers import reverse
 from django.test import TestCase
 from mock import patch, MagicMock, Mock
 
 from reviewsapp.middleware.stats import StatisticsLoggingMiddleware
-from reviewsapp.middleware.exception import LogExceptionMiddleware
+from reviewsapp.middleware.exception import (
+    LogExceptionMiddleware,
+    SanitizedExceptionReporter,
+    )
 from reviewsapp.tests.factory import TestCaseWithFactory
 from reviewsapp.tests.helpers import patch_settings
 
@@ -184,6 +192,22 @@
             self.assertFalse('CPU' in logged[0])
 
 
+class MockRequest(HttpRequest):
+
+    def __init__(self, path):
+        super(HttpRequest, self).__init__()
+        self.path = path
+
+        class MockSession(dict):
+            def flush(self):
+                pass
+
+        self.session = MockSession()
+
+    def get_full_path(self):
+        return self.path
+
+
 class ExceptionMiddlewareTestCase(TestCase):
 
     POST_PASSWORD = 'P1!2@3#'
@@ -227,8 +251,8 @@
         try:
             x = 2 / 0
         except:
-            reporter = self.middleware.get_reporter(self.request,
-                                                    *sys.exc_info())
+            reporter = SanitizedExceptionReporter(self.request,
+                                                  *sys.exc_info())
             html = reporter.get_traceback_html()
         self.assertFalse(self.PRIVATE_SETTING in html)
         self.assertTrue(self.PUBLIC_SETTING in html)
@@ -238,14 +262,15 @@
             FRAME_PASSWORD = self.FRAME_VAR
             public_variable = 2 / 0
         except:
-            reporter = self.middleware.get_reporter(self.request,
-                                                    *sys.exc_info())
+            reporter = SanitizedExceptionReporter(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 = self.middleware.sanitize_request(self.request)
+        reporter = SanitizedExceptionReporter(self.request, None, None, None)
+        req = reporter.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())
@@ -263,3 +288,24 @@
         #  Make sure public data is unaffected
         self.assertEquals(req.POST['post_public'], self.POST_PUBLIC)
         self.assertEquals(req.GET['get_public'], self.GET_PUBLIC)
+
+
+class SoftTimeoutMiddlewareTestCase(TestCase):
+    @patch('django.test.client.RequestFactory._base_environ')
+    def test_delay_triggers_oops_report(self, mock_environ):
+        environ = {
+            'REQUEST_METHOD': 'GET',
+            'SERVER_NAME': 'testserver',
+            'SERVER_PORT': '80',
+            }
+
+        def get_environ(**request):
+            environ.update(request)
+            return environ
+        mock_environ.side_effect = get_environ
+        # soft_request_timeout is an IntConfigOption, but a float works too
+        with patch_settings(ENABLE_ARTIFICIAL_OOPS=True,
+                            SOFT_REQUEST_TIMEOUT=0.1):
+            response = self.client.get('/reviews/delay/0.1/')
+
+        self.assertTrue('dump-oops' in environ)

=== modified file 'src/reviewsapp/tests/test_views.py'
--- src/reviewsapp/tests/test_views.py	2012-01-25 16:13:06 +0000
+++ src/reviewsapp/tests/test_views.py	2012-03-21 22:21:27 +0000
@@ -531,3 +531,23 @@
                 '/reviews/die/')
 
         reload(reviewsapp.urls)
+
+    def test_delay(self):
+        with patch_settings(ENABLE_ARTIFICIAL_OOPS=True):
+            # We need to reload urls.py to recalculate all urls
+            reload(reviewsapp.urls)
+
+            response = self.client.get('/reviews/delay/0.1/')
+
+        reload(reviewsapp.urls)
+        self.assertContains(response, 'Slept for 0.1 seconds')
+
+    def test_delay_invalid_amount(self):
+        with patch_settings(ENABLE_ARTIFICIAL_OOPS=True):
+            # We need to reload urls.py to recalculate all urls
+            reload(reviewsapp.urls)
+
+            response = self.client.get('/reviews/delay/0.1.2/')
+
+        reload(reviewsapp.urls)
+        self.assertContains(response, 'Invalid delay amount "0.1.2"')

=== modified file 'src/reviewsapp/urls.py'
--- src/reviewsapp/urls.py	2011-04-20 16:47:48 +0000
+++ src/reviewsapp/urls.py	2012-03-21 22:21:27 +0000
@@ -61,5 +61,6 @@
 
 if getattr(settings, 'ENABLE_ARTIFICIAL_OOPS', False):
     urlpatterns += patterns('reviewsapp.views',
-        (r'^die/', 'die'),
+        (r'^die/$', 'die'),
+        (r'^delay/(?P<amount>[\d.]+)/$', 'delay'),
     )

=== modified file 'src/reviewsapp/views/__init__.py'
--- src/reviewsapp/views/__init__.py	2011-04-20 16:47:48 +0000
+++ src/reviewsapp/views/__init__.py	2012-03-21 22:21:27 +0000
@@ -22,6 +22,9 @@
     'die'
     ]
 
+from time import sleep
+
+from django.http import HttpResponse
 from django.shortcuts import render_to_response
 
 from reviewsapp.models import ReviewModeration
@@ -45,3 +48,12 @@
 def die(request):
     """Just trigger an oops report"""
     raise ZeroDivisionError()
+
+
+def delay(request, amount):
+    try:
+        amount = float(amount)
+    except ValueError:
+        return HttpResponse('Invalid delay amount "%s"' % amount)
+    sleep(amount)
+    return HttpResponse('Slept for %s seconds' % amount)