From: Ben Darnell <ben@bendarnell.com>
Date: Sun, 8 Mar 2015 14:23:05 +0000 (-0400)
Subject: Improve logging when _handle_request_exception fails.
X-Git-Tag: v4.2.0b1~75
X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=4092f9dd9149cd66051f176945a845e9bfd0fc3a;p=thirdparty%2Ftornado.git

Improve logging when _handle_request_exception fails.

Stop discarding the exception returned by _execute.
---

diff --git a/tornado/test/web_test.py b/tornado/test/web_test.py
index f9fa56bbb..d7a11187f 100644
--- a/tornado/test/web_test.py
+++ b/tornado/test/web_test.py
@@ -1535,6 +1535,22 @@ class ExceptionHandlerTest(SimpleHandlerTestCase):
             self.assertEqual(response.code, 403)
 
 
+@wsgi_safe
+class BuggyLoggingTest(SimpleHandlerTestCase):
+    class Handler(RequestHandler):
+        def get(self):
+            1/0
+
+        def log_exception(self, typ, value, tb):
+            1/0
+
+    def test_buggy_log_exception(self):
+        # Something gets logged even though the application's
+        # logger is broken.
+        with ExpectLog(app_log, '.*'):
+            self.fetch('/')
+
+
 @wsgi_safe
 class UIMethodUIModuleTest(SimpleHandlerTestCase):
     """Test that UI methods and modules are created correctly and
@@ -2072,7 +2088,8 @@ class IncorrectContentLengthTest(SimpleHandlerTestCase):
         # the server.
         with ExpectLog(app_log, "Uncaught exception"):
             with ExpectLog(gen_log,
-                           "Cannot send error response after headers written"):
+                           "(Cannot send error response after headers written"
+                           "|Failed to flush partial response)"):
                 response = self.fetch("/high")
         self.assertEqual(response.code, 599)
         self.assertEqual(str(self.server_error),
@@ -2084,7 +2101,8 @@ class IncorrectContentLengthTest(SimpleHandlerTestCase):
         # complete (which would be a framing error).
         with ExpectLog(app_log, "Uncaught exception"):
             with ExpectLog(gen_log,
-                           "Cannot send error response after headers written"):
+                           "(Cannot send error response after headers written"
+                           "|Failed to flush partial response)"):
                 response = self.fetch("/low")
         self.assertEqual(response.code, 599)
         self.assertEqual(str(self.server_error),
diff --git a/tornado/web.py b/tornado/web.py
index 6d37f7050..6de42d27d 100644
--- a/tornado/web.py
+++ b/tornado/web.py
@@ -940,7 +940,15 @@ class RequestHandler(object):
         if self._headers_written:
             gen_log.error("Cannot send error response after headers written")
             if not self._finished:
-                self.finish()
+                # If we get an error between writing headers and finishing,
+                # we are unlikely to be able to finish due to a
+                # Content-Length mismatch. Try anyway to release the
+                # socket.
+                try:
+                    self.finish()
+                except Exception:
+                    gen_log.error("Failed to flush partial response",
+                                  exc_info=True)
             return
         self.clear()
 
@@ -1396,7 +1404,10 @@ class RequestHandler(object):
             if self._auto_finish and not self._finished:
                 self.finish()
         except Exception as e:
-            self._handle_request_exception(e)
+            try:
+                self._handle_request_exception(e)
+            except Exception:
+                app_log.error("Exception in exception handler", exc_info=True)
             if (self._prepared_future is not None and
                     not self._prepared_future.done()):
                 # In case we failed before setting _prepared_future, do it
@@ -1430,7 +1441,12 @@ class RequestHandler(object):
             if not self._finished:
                 self.finish()
             return
-        self.log_exception(*sys.exc_info())
+        try:
+            self.log_exception(*sys.exc_info())
+        except Exception:
+            # An error here should still get a best-effort send_error()
+            # to avoid leaking the connection.
+            app_log.error("Error in exception logger", exc_info=True)
         if self._finished:
             # Extra errors after the request has been finished should
             # be logged, but there is no reason to continue to try and
@@ -1975,14 +1991,14 @@ class _RequestDispatcher(httputil.HTTPMessageDelegate):
         if self.stream_request_body:
             self.handler._prepared_future = Future()
         # Note that if an exception escapes handler._execute it will be
-        # trapped in the Future it returns (which we are ignoring here).
+        # trapped in the Future it returns (which we are ignoring here,
+        # leaving it to be logged when the Future is GC'd).
         # However, that shouldn't happen because _execute has a blanket
         # except handler, and we cannot easily access the IOLoop here to
         # call add_future (because of the requirement to remain compatible
         # with WSGI)
         f = self.handler._execute(transforms, *self.path_args,
                                   **self.path_kwargs)
-        f.add_done_callback(lambda f: f.exception())
         # If we are streaming the request body, then execute() is finished
         # when the handler has prepared to receive the body.  If not,
         # it doesn't matter when execute() finishes (so we return None)