Merge lp:~james-w/python-timeline-django/start-end-request into lp:python-timeline-django

[James Westby]

Add signals for the start of the wsgi request and start of the response.

The django signal for request-finished fires when the client has consumed
the response. However, when generating an oops it can be done before this
meaning that the timeline doesn't have a reference for an end point.
This defines a response-started signal that fires when start_response
is called in the wsgi stack, making it more likely that there will be
an end point in the timeline.

Hi,

This is best described by the commit message, but should get us oopses
that better reflect the duration of the request.

Thanks,

James

[Natalia Bidart (nataliabidart)]

Looks good!

review: Approve

=== modified file 'timeline_django/hooks.py'
--- timeline_django/hooks.py	2013-08-24 19:44:21 +0000
+++ timeline_django/hooks.py	2013-08-26 15:18:27 +0000
@@ -19,6 +19,8 @@
 import django.core.signals
 import django.db.backends.signals
 
+from . import signals
+
 
 class TimelineReceiver(object):
     """Converts django signals in to `Timeline` entries.
@@ -30,6 +32,8 @@
     REQUEST_CATEGORY = "request"
     REQUEST_EXCEPTION_CATEGORY = "request-exception"
     CONNECTION_CREATED_CATEGORY = "connection-created"
+    WSGI_REQUEST_CATEGORY = "wsgi_request-start"
+    WSGI_RESPONSE_CATEGORY = "wsgi_response-start"
 
     def __init__(self, timeline_factory):
         """Create a TimelineReceiver.
@@ -99,9 +103,19 @@
         self._do_instantaneous_action(self.CONNECTION_CREATED_CATEGORY,
                 connection_name)
 
+    def wsgi_request_started(self, sender, **kwargs):
+        self._do_instantaneous_action(self.WSGI_REQUEST_CATEGORY,
+                self._model_name(sender))
+
+    def wsgi_response_started(self, sender, **kwargs):
+        self._do_instantaneous_action(self.WSGI_RESPONSE_CATEGORY,
+                self._model_name(sender))
+
     def connect_to_signals(self):
         """Connect the callbacks to their corresponding signals."""
         django.core.signals.request_started.connect(self.request_started, weak=False)
         django.core.signals.request_finished.connect(self.request_finished, weak=False)
         django.core.signals.got_request_exception.connect(self.got_request_exception, weak=False)
         django.db.backends.signals.connection_created.connect(self.connection_created, weak=False)
+        signals.wsgi_request_started.connect(self.wsgi_request_started, weak=False)
+        signals.wsgi_response_started.connect(self.wsgi_response_started, weak=False)

=== added file 'timeline_django/signals.py'
--- timeline_django/signals.py	1970-01-01 00:00:00 +0000
+++ timeline_django/signals.py	2013-08-26 15:18:27 +0000
@@ -0,0 +1,5 @@
+from django.dispatch import Signal
+
+
+wsgi_request_started = Signal(providing_args=['environ'])
+wsgi_response_started = Signal(providing_args=['environ'])

=== modified file 'timeline_django/tests/test_hooks.py'
--- timeline_django/tests/test_hooks.py	2013-08-24 19:44:21 +0000
+++ timeline_django/tests/test_hooks.py	2013-08-26 15:18:27 +0000
@@ -21,6 +21,7 @@
 from testtools import TestCase
 from timeline import Timeline
 
+from .. import signals
 from ..hooks import TimelineReceiver
 
 
@@ -138,6 +139,64 @@
         receiver.got_request_exception(TestModel)
         self.assertEqual(timedelta(), timeline.actions[0].duration)
 
+    def test_wsgi_request_started_with_no_timeline(self):
+        receiver = TimelineReceiver(lambda: None)
+        # Mustn't crash due to trying to use a None timeline
+        receiver.wsgi_request_started(TestModel)
+
+    def test_wsgi_request_started_adds_action(self):
+        receiver, timeline = self.get_timeline_receiver()
+        receiver.wsgi_request_started(TestModel)
+        self.assertEqual(1, len(timeline.actions))
+
+    def test_wsgi_request_started_sets_wsgi_request_as_category(self):
+        receiver, timeline = self.get_timeline_receiver()
+        receiver.wsgi_request_started(TestModel)
+        # -start is appended as this is a nestable action
+        self.assertEqual('wsgi_request-start', timeline.actions[0].category)
+
+    def test_wsgi_request_started_sets_sender_as_detail(self):
+        receiver, timeline = self.get_timeline_receiver()
+        receiver.wsgi_request_started(TestModel)
+        self.assertEqual(TestModel.NAME, timeline.actions[0].detail)
+
+    def test_wsgi_request_started_finishes_action(self):
+        receiver, timeline = self.get_timeline_receiver()
+        receiver.wsgi_request_started(TestModel)
+        # If this passes it means the action was completed as an
+        # instantaneous action. This is so nesting can be done,
+        # as the action may well trigger SQL
+        self.assertEqual(timedelta(), timeline.actions[0].duration)
+
+    def test_wsgi_response_started_with_no_timeline(self):
+        receiver = TimelineReceiver(lambda: None)
+        # Mustn't crash due to trying to use a None timeline
+        receiver.wsgi_response_started(TestModel)
+
+    def test_wsgi_response_started_adds_action(self):
+        receiver, timeline = self.get_timeline_receiver()
+        receiver.wsgi_response_started(TestModel)
+        self.assertEqual(1, len(timeline.actions))
+
+    def test_wsgi_response_started_sets_wsgi_response_as_category(self):
+        receiver, timeline = self.get_timeline_receiver()
+        receiver.wsgi_response_started(TestModel)
+        # -start is appended as this is a nestable action
+        self.assertEqual('wsgi_response-start', timeline.actions[0].category)
+
+    def test_wsgi_response_started_sets_sender_as_detail(self):
+        receiver, timeline = self.get_timeline_receiver()
+        receiver.wsgi_response_started(TestModel)
+        self.assertEqual(TestModel.NAME, timeline.actions[0].detail)
+
+    def test_wsgi_response_started_finishes_action(self):
+        receiver, timeline = self.get_timeline_receiver()
+        receiver.wsgi_response_started(TestModel)
+        # If this passes it means the action was completed as an
+        # instantaneous action. This is so nesting can be done,
+        # as the action may well trigger SQL
+        self.assertEqual(timedelta(), timeline.actions[0].duration)
+
     def test_connection_created_with_no_timeline(self):
         receiver = TimelineReceiver(lambda: None)
         connection = TestConnection()
@@ -204,3 +263,13 @@
         signal, receiver = self.register_signal(django.db.backends.signals, 'connection_created')
         self.assertEqual(1, len(signal.receivers))
         self.assertEqual(receiver.connection_created, signal.receivers[0][1])
+
+    def test_register_signals_registers_wsgi_request_started(self):
+        signal, receiver = self.register_signal(signals, 'wsgi_request_started')
+        self.assertEqual(1, len(signal.receivers))
+        self.assertEqual(receiver.wsgi_request_started, signal.receivers[0][1])
+
+    def test_register_signals_registers_wsgi_response_started(self):
+        signal, receiver = self.register_signal(signals, 'wsgi_response_started')
+        self.assertEqual(1, len(signal.receivers))
+        self.assertEqual(receiver.wsgi_response_started, signal.receivers[0][1])

=== modified file 'timeline_django/tests/test_wsgi.py'
--- timeline_django/tests/test_wsgi.py	2012-09-22 09:00:56 +0000
+++ timeline_django/tests/test_wsgi.py	2013-08-26 15:18:27 +0000
@@ -15,10 +15,15 @@
 
 import threading
 
+from django.dispatch import Signal
+
 from testtools import TestCase
 from testtools.matchers import Is
 
-from .. import wsgi
+from .. import (
+    signals,
+    wsgi,
+)
 
 
 class TestWSGI(TestCase):
@@ -38,3 +43,34 @@
         out = app(environ, start_response)
         self.assertEqual(["foo"], out)
         self.assertThat(wsgi.get_environ(), Is(environ))
+
+    def patch_signal(self, name):
+        signal = Signal()
+        self.patch(signals, name, signal)
+        return signal
+
+    def test_sends_wsgi_request_started_signal(self):
+        signal = self.patch_signal('wsgi_request_started')
+        called_environs = []
+        def capture_signal(sender, environ, signal=None):
+            called_environs.append(environ)
+        signal.connect(capture_signal)
+        wrapped_app = wsgi.make_app(lambda environ, start_response: None)
+        environ = object()
+        wrapped_app(environ, None)
+        self.assertEqual([environ], called_environs)
+
+    def test_sends_wsgi_response_started_signal(self):
+        signal = self.patch_signal('wsgi_response_started')
+        called_environs = []
+        def capture_signal(sender, environ, signal=None):
+            called_environs.append(environ)
+        signal.connect(capture_signal)
+        def app(environ, start_response):
+            start_response()
+        wrapped_app = wsgi.make_app(app)
+        environ = object()
+        def start_response(*args, **kwargs):
+            pass
+        wrapped_app(environ, start_response)
+        self.assertEqual([environ], called_environs)

=== modified file 'timeline_django/wsgi.py'
--- timeline_django/wsgi.py	2012-09-22 09:00:56 +0000
+++ timeline_django/wsgi.py	2013-08-26 15:18:27 +0000
@@ -17,6 +17,8 @@
 
 import threading
 
+from timeline_django import signals
+
 
 _thread_local = threading.local()
 
@@ -34,7 +36,7 @@
 def make_app(application):
     """Create a WSGI application that stores the environ in a thread-local.
 
-    This is useful when dealing with non-WSGI code or code that runs in 
+    This is useful when dealing with non-WSGI code or code that runs in
     global contexts such as ORMs, and you wish to work with something in the
     WSGI environ.
 
@@ -43,6 +45,12 @@
     :return: A WSGI app wrapping application.
     """
     def save_environ(environ, start_response):
+        signals.wsgi_request_started.send(sender=save_environ,
+                                          environ=environ)
         _thread_local.environ = environ
-        return application(environ, start_response)
+        def signalled_start_response(*args, **kwargs):
+            signals.wsgi_response_started.send(sender=save_environ,
+                                               environ=environ)
+            return start_response(*args, **kwargs)
+        return application(environ, signalled_start_response)
     return save_environ