launchpad-reviewers team mailing list archive

[Robert Collins <robertc@xxxxxxxxxxxxxxxxx>]

Robert Collins has proposed merging lp:~lifeless/python-oops-wsgi/timeout into lp:python-oops-wsgi.

Requested reviews:
  Launchpad code reviewers (launchpad-reviewers)

For more details, see:
https://code.launchpad.net/~lifeless/python-oops-wsgi/timeout/+merge/85056

This will let us get slow-performance data out of bazaar.launchpad.net.
-- 
https://code.launchpad.net/~lifeless/python-oops-wsgi/timeout/+merge/85056
Your team Launchpad code reviewers is requested to review the proposed merge of lp:~lifeless/python-oops-wsgi/timeout into lp:python-oops-wsgi.

=== modified file 'NEWS'
--- NEWS	2011-12-09 03:24:22 +0000
+++ NEWS	2011-12-09 04:09:23 +0000
@@ -9,6 +9,10 @@
 * Added a Django helper to ease integration in older non-WSGI compatible Django
   versions. (James Henstridge, Robert Collins)
 
+* Passing ``soft_start_timeout`` to ``make_app`` allows the creation of OOPS
+  reports when the wrapped application is slow to start its response.
+  (Robert Collins)
+
 0.0.7
 -----
 

=== modified file 'oops_wsgi/middleware.py'
--- oops_wsgi/middleware.py	2011-11-13 21:57:57 +0000
+++ oops_wsgi/middleware.py	2011-12-09 04:09:23 +0000
@@ -19,6 +19,7 @@
 
 import socket
 import sys
+import time
 
 from paste.request import construct_url
 
@@ -46,9 +47,13 @@
     }
 
 
+class SoftRequestTimeout(Exception):
+    """Soft request timeout expired"""
+
+
 def make_app(app, config, template=default_error_template,
         content_type='text/html', error_render=None, oops_on_status=None,
-        map_environ=None, tracker=None):
+        map_environ=None, tracker=None, soft_start_timeout=None):
     """Construct a middleware around app that will forward errors via config.
 
     Any errors encountered by the app will be forwarded to config and an error
@@ -86,6 +91,13 @@
         See generator_tracker for the reference tracker used in regular WSGI
         environments. generator_tracker is used by default or when
         tracker=None.
+    :param soft_start_timeout: A duration in milliseconds for the creation of
+        reports on slow requests. If this is set and the duration between
+        calling into the app and start_response being called is greater than
+        the timeout value, then an OOPS will be created and the OOPS id added
+        to the response HTTP headers as normal. A backtrace leading into the
+        middleware is generated (this can be informative as start_response is
+        a callback) and the exception type is set to SoftRequestTimeout.
     :return: A WSGI app.
     """
     def oops_middleware(environ, start_response):
@@ -100,6 +112,8 @@
         """
         environ['oops.report'] = {}
         environ['oops.context'] = {}
+        if soft_start_timeout:
+            start_time = time.time()
         state = {}
         def make_context(exc_info=None):
             context = dict(url=construct_url(environ), wsgi_environ=environ)
@@ -125,9 +139,11 @@
             if exc_info is not None:
                 # The app is explicitly signalling an error (rather than
                 # returning a page describing the error). Capture that and then
-                # forward to the containing element verbatim. In future we might
-                # choose to add the OOPS id to the headers (but we can't fiddle
-                # the body as it is being generated by the contained app.
+                # forward to the containing element untouched except for the
+                # addition of the X-Oops-Id header. We don't touch the body
+                # because the application is handling the error and generating
+                # the body itself. We may in future provide an option to
+                # replace the body in this situation.
                 report = config.create(make_context(exc_info=exc_info))
                 ids = config.publish(report)
                 try:
@@ -139,12 +155,24 @@
                 finally:
                     del exc_info
             else:
+                do_oops = False
                 if oops_on_status:
                     for sniff_status in oops_on_status:
                         if status.startswith(sniff_status):
-                            report = config.create(make_context())
-                            report['HTTP_STATUS'] = status.split(' ')[0]
-                            config.publish(report)
+                            do_oops = True
+                if (soft_start_timeout and
+                    (time.time()-start_time)*1000 > soft_start_timeout):
+                    try:
+                        raise SoftRequestTimeout(
+                            "Start_response over timeout %s."
+                            % soft_start_timeout)
+                    except SoftRequestTimeout:
+                        exc_info = sys.exc_info()
+                    do_oops = True
+                if do_oops:
+                    report = config.create(make_context(exc_info=exc_info))
+                    report['HTTP_STATUS'] = status.split(' ')[0]
+                    config.publish(report)
                 state['response'] = (status, headers)
             return oops_write
         try:

=== modified file 'oops_wsgi/tests/test_middleware.py'
--- oops_wsgi/tests/test_middleware.py	2011-11-13 21:57:57 +0000
+++ oops_wsgi/tests/test_middleware.py	2011-12-09 04:09:23 +0000
@@ -21,6 +21,7 @@
 import socket
 import sys
 from textwrap import dedent
+import time
 
 from oops import (
     Config,
@@ -57,6 +58,8 @@
         self.checkkeys = checkkeys or {}
 
     def match(self, report):
+        if type(report) is not dict:
+            return Mismatch("Report is not a dict: '%s'" % (report,))
         sentinel = object()
         mismatches = []
         for key, value in self.checkkeys.items():
@@ -448,6 +451,8 @@
         self.assertEqual('bar', self.calls[0]['foo'])
 
     def test_sniff_404_not_published_does_not_error(self):
+        # If the OOPS is not published, the start_response just passes through
+        # as though we were not sniffing responses.
         def inner(environ, start_response):
             start_response('404 MISSING', [])
             yield 'pretty 404'
@@ -507,6 +512,39 @@
         app = make_app(myapp, Config(), tracker=mytracker)
         self.assertEqual('tracker', app({}, lambda status, headers:None))
 
+    def test_soft_start_timeout_below_threshold(self):
+        # When a request responds below the timeout, no OOPS is made.
+        def myapp(environ, start_response):
+            start_response('200 OK', [])
+            yield 'success'
+        config = self.config_for_oopsing()
+        body = self.wrap_and_run(
+            myapp, config, params=dict(soft_start_timeout=1000))
+        self.assertEqual('success', body)
+        expected_start_response = ('200 OK', [])
+        self.assertThat(self.calls, MatchesListwise([
+            Equals(expected_start_response),
+            ]))
+
+    def test_soft_start_timeout_above_threshold(self):
+        # When a request responds above the timeout, an OOPS is made with a
+        # SoftTimeout exception and backtrace.
+        def myapp(environ, start_response):
+            time.sleep(0.002)
+            start_response('200 OK', [])
+            yield 'success'
+        config = self.config_for_oopsing()
+        body = self.wrap_and_run(
+            myapp, config, params=dict(soft_start_timeout=1))
+        self.assertEqual('success', body)
+        expected_start_response = ('200 OK', [])
+        self.assertThat(self.calls, MatchesListwise([
+            # An OOPS is logged with the observed response code.
+            MatchesOOPS({'type': 'SoftRequestTimeout'}),
+            Equals(expected_start_response),
+            ]))
+
+
 
 class TestGeneratorTracker(TestCase):