Merge lp:~jameinel/launchpad/suppress-generator-exit-726985 into lp:launchpad

[John A Meinel]

[r=benji] [bug=726985] Suppress bogus OOPS entries when clients disconnect early on streamed pages.

Adding another kind of exception for Loggerhead to treat as a non-OOPS.

There are only a few pages that do streamed bodies, but when one of those is stopped early, we get a GeneratorExit exception (when the generator loses its last reference.)

The test for this requires CPython's refcounting semantics (throw a GeneratorExit exception as soon as we call 'del app'). I'm pretty sure this is safe for Launchpad, but I figured I would mention it.

GeneratorExit itself never really cares any other context, so I don't think we could say that there is any reason to decide we really do want an oops here, rather than just always suppressing it. If we get 1 more of these, we should probably unify their logging, etc a bit. But for right now, 2 didn't seem to imply a trend.

Note that I was unable to actually reproduce the failure with custom "GET ../download/" and stopping early. So if we want, we can put this off until we actually see this being the #1 OOPS failure. Though according to wgrant, it was.

[Benji York (benji)]

This branch looks good.

> The test for this requires CPython's refcounting semantics (throw a
> GeneratorExit exception as soon as we call 'del app'). I'm pretty sure
> this is safe for Launchpad, but I figured I would mention it.

Yeah, I agree that it's safe, especially because the failure mode would
result in a test failing (always good) while the app would continue to
work correctly.

> Note that I was unable to actually reproduce the failure with custom
> "GET ../download/" and stopping early. So if we want, we can put this
> off until we actually see this being the #1 OOPS failure. Though
> according to wgrant, it was.

I am a little concerned about not being unable to trigger the behavior
we're trying to remedy "for real". This may indicate that we're not
really fixing the problem, but the change as given appears to be a pure
win, so there's no reason not to do it.

review: Approve (benji)

[Benji York (benji)]

review: Approve (code)

=== modified file 'lib/launchpad_loggerhead/app.py'
--- lib/launchpad_loggerhead/app.py	2011-02-09 00:43:53 +0000
+++ lib/launchpad_loggerhead/app.py	2011-03-07 13:48:19 +0000
@@ -356,8 +356,16 @@
             # just because the connection was closed prematurely.
             logger = logging.getLogger('lp-loggerhead')
             logger.info('Caught socket exception from %s: %s %s'
-                         % (environ.get('REMOTE_ADDR', '<unknown>'),
-                            e.__class__, e,))
+                        % (environ.get('REMOTE_ADDR', '<unknown>'),
+                           e.__class__, e,))
+            return
+        except GeneratorExit, e:
+            # This generally means a client closed early during a streaming
+            # body. Nothing to worry about. GeneratorExit doesn't usually have
+            # any context associated with it, so not worth printing to the log.
+            logger = logging.getLogger('lp-loggerhead')
+            logger.info('Caught GeneratorExit from %s'
+                        % (environ.get('REMOTE_ADDR', '<unknown>')))
             return
         except:
             error_page_sent = wrapped.generate_oops(environ, error_utility)

=== modified file 'lib/launchpad_loggerhead/tests.py'
--- lib/launchpad_loggerhead/tests.py	2011-02-23 17:26:26 +0000
+++ lib/launchpad_loggerhead/tests.py	2011-03-07 13:48:19 +0000
@@ -203,17 +203,26 @@
             raise socket.error(errno.EPIPE, 'Connection closed')
         return fail_write
 
+    def multi_yielding_app(self, environ, start_response):
+        writer = start_response('200 OK', {})
+        yield 'content\n'
+        yield 'I want\n'
+        yield 'to give to the user\n'
+
+    def _get_default_environ(self):
+        return {'wsgi.version': (1, 0),
+                'wsgi.url_scheme': 'http',
+                'PATH_INFO': '/test/path',
+                'REQUEST_METHOD': 'GET',
+                'SERVER_NAME': 'localhost',
+                'SERVER_PORT': '8080',
+               }
+
     def wrap_and_run(self, app, failing_write=False):
         app = oops_middleware(app)
         # Just random env data, rather than setting up a whole wsgi stack just
         # to pass in values for this dict
-        environ = {'wsgi.version': (1, 0),
-                   'wsgi.url_scheme': 'http',
-                   'PATH_INFO': '/test/path',
-                   'REQUEST_METHOD': 'GET',
-                   'SERVER_NAME': 'localhost',
-                   'SERVER_PORT': '8080',
-                  }
+        environ = self._get_default_environ()
         if failing_write:
             result = list(app(environ, self.failing_start_response))
         else:
@@ -242,6 +251,23 @@
         self.assertContainsRe(self.log_stream.getvalue(),
             'Caught socket exception from <unknown>:.*Connection closed')
 
+    def test_stopping_early_no_oops(self):
+        # See bug #726985.
+        # If content is being streamed, and the pipe closes, we'll get a
+        # 'GeneratorExit', because it is closed before finishing. This doesn't
+        # need to become an OOPS.
+        self.catchLogEvents()
+        app = oops_middleware(self.multi_yielding_app)
+        environ = self._get_default_environ()
+        result = app(environ, self.noop_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
+        del app, result
+        self.assertEqual([], self.oopses)
+        self.assertContainsRe(self.log_stream.getvalue(),
+            'Caught GeneratorExit from <unknown>')
+
 
 def test_suite():
     return unittest.TestLoader().loadTestsFromName(__name__)