Refine logging in http1connection.py.

Exceptions raised by delegate methods go to app_log; all others to gen_log.

diff --git a/tornado/http1connection.py b/tornado/http1connection.py
index 9f474e1b63fc1b22973e1a42fe74d2c0d1d39082..edaa5d9e108a3937993b3cd830500caa1f9a1b58 100644 (file)
--- a/tornado/http1connection.py
+++ b/tornado/http1connection.py
@@ -31,6 +31,26 @@ from tornado import stack_context
 from tornado.util import GzipDecompressor
 
 
+class _QuietException(Exception):
+    def __init__(self):
+        pass
+
+class _ExceptionLoggingContext(object):
+    """Used with the ``with`` statement when calling delegate methods to
+    log any exceptions with the given logger.  Any exceptions caught are
+    converted to _QuietException
+    """
+    def __init__(self, logger):
+        self.logger = logger
+
+    def __enter__(self):
+        pass
+
+    def __exit__(self, typ, value, tb):
+        if value is not None:
+            self.logger.error("Uncaught exception", exc_info=(typ, value, tb))
+            raise _QuietException
+
 class HTTP1ConnectionParameters(object):
     """Parameters for `.HTTP1Connection` and `.HTTP1ServerConnection`.
     """
@@ -155,9 +175,10 @@ class HTTP1Connection(httputil.HTTPConnection):
             self._disconnect_on_finish = not self._can_keep_alive(
                 start_line, headers)
             need_delegate_close = True
-            header_future = delegate.headers_received(start_line, headers)
-            if header_future is not None:
-                yield header_future
+            with _ExceptionLoggingContext(app_log):
+                header_future = delegate.headers_received(start_line, headers)
+                if header_future is not None:
+                    yield header_future
             if self.stream is None:
                 # We've been detached.
                 need_delegate_close = False
@@ -196,7 +217,8 @@ class HTTP1Connection(httputil.HTTPConnection):
             self._read_finished = True
             if not self._write_finished or self.is_client:
                 need_delegate_close = False
-                delegate.finish()
+                with _ExceptionLoggingContext(app_log):
+                    delegate.finish()
             # If we're waiting for the application to produce an asynchronous
             # response, and we're not detached, register a close callback
             # on the stream (we didn't need one while we were reading)
@@ -216,7 +238,8 @@ class HTTP1Connection(httputil.HTTPConnection):
             raise gen.Return(False)
         finally:
             if need_delegate_close:
-                delegate.on_connection_close()
+                with _ExceptionLoggingContext(app_log):
+                    delegate.on_connection_close()
             self._clear_callbacks()
         raise gen.Return(True)
 
@@ -478,7 +501,8 @@ class HTTP1Connection(httputil.HTTPConnection):
                 min(self.params.chunk_size, content_length), partial=True)
             content_length -= len(body)
             if not self._write_finished or self.is_client:
-                yield gen.maybe_future(delegate.data_received(body))
+                with _ExceptionLoggingContext(app_log):
+                    yield gen.maybe_future(delegate.data_received(body))
 
     @gen.coroutine
     def _read_chunked_body(self, delegate):
@@ -498,8 +522,8 @@ class HTTP1Connection(httputil.HTTPConnection):
                     min(bytes_to_read, self.params.chunk_size), partial=True)
                 bytes_to_read -= len(chunk)
                 if not self._write_finished or self.is_client:
-                    yield gen.maybe_future(
-                        delegate.data_received(chunk))
+                    with _ExceptionLoggingContext(app_log):
+                        yield gen.maybe_future(delegate.data_received(chunk))
             # chunk ends with \r\n
             crlf = yield self.stream.read_bytes(2)
             assert crlf == b"\r\n"
@@ -508,7 +532,8 @@ class HTTP1Connection(httputil.HTTPConnection):
     def _read_body_until_close(self, delegate):
         body = yield self.stream.read_until_close()
         if not self._write_finished or self.is_client:
-            delegate.data_received(body)
+            with _ExceptionLoggingContext(app_log):
+                delegate.data_received(body)
 
 
 class _GzipMessageDelegate(httputil.HTTPMessageDelegate):
@@ -610,11 +635,12 @@ class HTTP1ServerConnection(object):
                 except (iostream.StreamClosedError,
                         iostream.UnsatisfiableReadError):
                     return
+                except _QuietException:
+                    # This exception was already logged.
+                    conn.close()
+                    return
                 except Exception:
-                    # TODO: this is probably too broad; it would be better to
-                    # wrap all delegate calls in something that writes to app_log,
-                    # and then errors that reach this point can be gen_log.
-                    app_log.error("Uncaught exception", exc_info=True)
+                    gen_log.error("Uncaught exception", exc_info=True)
                     conn.close()
                     return
                 if not ret:

diff --git a/tornado/test/httpserver_test.py b/tornado/test/httpserver_test.py
index 4701569d5ff102b6a95bdfece14ae04bc805c62a..f5e5679d9e4d2aac5598624ddd80d4ad4196c55a 100644 (file)
--- a/tornado/test/httpserver_test.py
+++ b/tornado/test/httpserver_test.py
@@ -111,9 +111,7 @@ class SSLTestMixin(object):
         # connection, rather than waiting for a timeout or otherwise
         # misbehaving.
         with ExpectLog(gen_log, '(SSL Error|uncaught exception)'):
-            # TODO: this should go to gen_log, not app_log.  See TODO
-            # in http1connection.py (_server_request_loop)
-            with ExpectLog(app_log, 'Uncaught exception', required=False):
+            with ExpectLog(gen_log, 'Uncaught exception', required=False):
                 self.http_client.fetch(
                     self.get_url("/").replace('https:', 'http:'),
                     self.stop,

diff --git a/tornado/test/simple_httpclient_test.py b/tornado/test/simple_httpclient_test.py
index e1a1b420528aba035afa08a18ede5536a493426c..cdf248c731f40f5a5e74974b16afe7c213176853 100644 (file)
--- a/tornado/test/simple_httpclient_test.py
+++ b/tornado/test/simple_httpclient_test.py
@@ -14,7 +14,7 @@ from tornado import gen
 from tornado.httpclient import AsyncHTTPClient
 from tornado.httputil import HTTPHeaders
 from tornado.ioloop import IOLoop
-from tornado.log import gen_log
+from tornado.log import gen_log, app_log
 from tornado.netutil import Resolver
 from tornado.simple_httpclient import SimpleAsyncHTTPClient, _default_ca_certs
 from tornado.test.httpclient_test import ChunkHandler, CountdownHandler, HelloWorldHandler
@@ -295,7 +295,8 @@ class SimpleHTTPClientTestMixin(object):
         self.assertEqual(response.headers["Content-length"], "0")
 
         # 204 status with non-zero content length is malformed
-        response = self.fetch("/no_content?error=1")
+        with ExpectLog(app_log, "Uncaught exception"):
+            response = self.fetch("/no_content?error=1")
         self.assertEqual(response.code, 599)
 
     def test_host_header(self):