launchpad-reviewers team mailing list archive

[John A Meinel <john@xxxxxxxxxxxxxxxxx>]

John A Meinel has proposed merging lp:~jameinel/launchpad/loggerhead-732481 into lp:launchpad.

Requested reviews:
  Launchpad code reviewers (launchpad-reviewers)
Related bugs:
  Bug #732481 in Launchpad itself: "internal error trying to serve HEAD"
  https://bugs.launchpad.net/launchpad/+bug/732481

For more details, see:
https://code.launchpad.net/~jameinel/launchpad/loggerhead-732481/+merge/52902

This fixes bug #732481. We had a logic snafu. The oops_middleware proxied the 'start_response' call until actual content was written. So that if a bug triggered between the time 'start_response' was called, and when actual content was written, it would have a chance to write its own oops response.

However, it would then only call start_response once it actually started writing content. But now that HEAD requests weren't writing any content, it wasn't actually calling start_response. The WSGI layer would then see that the app returned successfully and would start trying to write the empty-string, but would die because start_response was never called.

Long term, we really could use some black-box tests that actually 'start_loggerhead' and then make a couple requests to it. Probably 1 request on every major page, which would have helped prevent a silly regression like this. But I don't have a good feeling for how to set up a test like that.

I did make sure to do manual "HEAD" requests against a page. Which showed both that it used to fail, and that it is now fixed. As did the 'test_no_body_calls_start_response'
-- 
https://code.launchpad.net/~jameinel/launchpad/loggerhead-732481/+merge/52902
Your team Launchpad code reviewers is requested to review the proposed merge of lp:~jameinel/launchpad/loggerhead-732481 into lp:launchpad.

=== modified file 'lib/launchpad_loggerhead/app.py'
--- lib/launchpad_loggerhead/app.py	2011-03-07 13:08:14 +0000
+++ lib/launchpad_loggerhead/app.py	2011-03-10 18:44:14 +0000
@@ -295,12 +295,15 @@
             self.response_start += (exc_info,)
         return self.write_wrapper
 
-    def really_start(self):
+    def ensure_started(self):
+        if not self.body_started and self.response_start is not None:
+            self._really_start()
+
+    def _really_start(self):
         self._write_callable = self._real_start_response(*self.response_start)
 
     def write_wrapper(self, data):
-        if not self.body_started:
-            self.really_start()
+        self.ensure_started()
         self._write_callable(data)
 
     def generate_oops(self, environ, error_utility):
@@ -312,7 +315,7 @@
         oopsid = report_oops(environ, error_utility)
         if self.body_started:
             return False
-        write = self._real_start_response(_error_status, _error_headers)
+        write = self.start_response(_error_status, _error_headers)
         write(_oops_html_template % {'oopsid': oopsid})
         return True
 
@@ -341,14 +344,15 @@
             # Start processing this request, build the app
             app_iter = iter(app(environ, wrapped.start_response))
             # Start yielding the response
-            while True:
+            stopping = False
+            while not stopping:
                 try:
                     data = app_iter.next()
                 except StopIteration:
-                    return
-                if not wrapped.body_started:
-                    wrapped.really_start()
-                yield data
+                    stopping = True
+                wrapped.ensure_started()
+                if not stopping:
+                    yield data
         except httpserver.SocketErrors, e:
             # The Paste WSGIHandler suppresses these exceptions.
             # Generally it means something like 'EPIPE' because the

=== modified file 'lib/launchpad_loggerhead/tests.py'
--- lib/launchpad_loggerhead/tests.py	2011-03-07 13:08:14 +0000
+++ lib/launchpad_loggerhead/tests.py	2011-03-10 18:44:14 +0000
@@ -21,7 +21,11 @@
 from canonical.launchpad.webapp.errorlog import ErrorReport, ErrorReportEvent
 from canonical.launchpad.webapp.vhosts import allvhosts
 from canonical.testing.layers import DatabaseFunctionalLayer
-from launchpad_loggerhead.app import RootApp, oops_middleware
+from launchpad_loggerhead.app import (
+    _oops_html_template,
+    oops_middleware,
+    RootApp,
+    )
 from launchpad_loggerhead.session import SessionHandler
 from lp.testing import TestCase
 
@@ -152,6 +156,10 @@
 
 class TestOopsMiddleware(TestCase):
 
+    def setUp(self):
+        super(TestOopsMiddleware, self).setUp()
+        self.start_response_called = False
+
     def assertContainsRe(self, haystack, needle_re, flags=0):
         """Assert that a contains something matching a regular expression."""
         # There is: self.assertTextMatchesExpressionIgnoreWhitespace
@@ -188,10 +196,12 @@
             yield None
         raise socket.error(errno.EPIPE, 'Connection closed')
 
-    def noop_start_response(self, status, response_headers, exc_info=None):
-        def noop_write(chunk):
-            pass
-        return noop_write
+    def logging_start_response(self, status, response_headers, exc_info=None):
+        self._response_chunks = []
+        def _write(chunk):
+            self._response_chunks.append(chunk)
+        self.start_response_called = True
+        return _write
 
     def success_app(self, environ, start_response):
         writer = start_response('200 OK', {})
@@ -201,6 +211,7 @@
     def failing_start_response(self, status, response_headers, exc_info=None):
         def fail_write(chunk):
             raise socket.error(errno.EPIPE, 'Connection closed')
+        self.start_response_called = True
         return fail_write
 
     def multi_yielding_app(self, environ, start_response):
@@ -209,6 +220,10 @@
         yield 'I want\n'
         yield 'to give to the user\n'
 
+    def no_body_app(self, environ, start_response):
+        writer = start_response('200 OK', {})
+        return []
+
     def _get_default_environ(self):
         return {'wsgi.version': (1, 0),
                 'wsgi.url_scheme': 'http',
@@ -226,7 +241,7 @@
         if failing_write:
             result = list(app(environ, self.failing_start_response))
         else:
-            result = list(app(environ, self.noop_start_response))
+            result = list(app(environ, self.logging_start_response))
         return result
 
     def test_exception_triggers_oops(self):
@@ -236,6 +251,11 @@
         self.assertEqual(1, len(self.oopses))
         oops = self.oopses[0]
         self.assertEqual('RuntimeError', oops.type)
+        # runtime_failing_app doesn't call start_response, but oops_middleware
+        # does because it tries to send the OOPS information to the user.
+        self.assertTrue(self.start_response_called)
+        self.assertEqual(_oops_html_template % {'oopsid': oops.id},
+                         ''.join(self._response_chunks))
 
     def test_ignores_socket_exceptions(self):
         self.catchLogEvents()
@@ -243,6 +263,9 @@
         self.assertEqual(0, len(self.oopses))
         self.assertContainsRe(self.log_stream.getvalue(),
             'Caught socket exception from <unknown>:.*Connection closed')
+        # start_response doesn't get called because the app fails first,
+        # and oops_middleware knows not to do anything with a closed socket.
+        self.assertFalse(self.start_response_called)
 
     def test_ignores_writer_failures(self):
         self.catchLogEvents()
@@ -250,6 +273,8 @@
         self.assertEqual(0, len(self.oopses))
         self.assertContainsRe(self.log_stream.getvalue(),
             'Caught socket exception from <unknown>:.*Connection closed')
+        # success_app calls start_response, so this should get passed on.
+        self.assertTrue(self.start_response_called)
 
     def test_stopping_early_no_oops(self):
         # See bug #726985.
@@ -259,7 +284,7 @@
         self.catchLogEvents()
         app = oops_middleware(self.multi_yielding_app)
         environ = self._get_default_environ()
-        result = app(environ, self.noop_start_response)
+        result = app(environ, self.logging_start_response)
         self.assertEqual('content\n', result.next())
         # At this point, we intentionally kill the app and the response, so
         # that they will get GeneratorExit
@@ -267,6 +292,17 @@
         self.assertEqual([], self.oopses)
         self.assertContainsRe(self.log_stream.getvalue(),
             'Caught GeneratorExit from <unknown>')
+        # Body content was yielded, we must have called start_response
+        self.assertTrue(self.start_response_called)
+
+    def test_no_body_calls_start_response(self):
+        # See bug #732481, even if we don't have a body, if we have headers to
+        # send, we must call start_response
+        result = self.wrap_and_run(self.no_body_app)
+        self.assertEqual([], result)
+        self.assertTrue(self.start_response_called)
+        # Output content is empty because of no_body_app
+        self.assertEqual('', ''.join(self._response_chunks))
 
 
 def test_suite():