From: Ben Darnell Date: Sun, 1 Jun 2014 22:14:14 +0000 (-0400) Subject: Refine logging in http1connection.py. X-Git-Tag: v4.0.0b1~29 X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=f271140892036c300d6443f8735923067a8cb86e;p=thirdparty%2Ftornado.git 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 9f474e1b6..edaa5d9e1 100644 --- 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 4701569d5..f5e5679d9 100644 --- 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 e1a1b4205..cdf248c73 100644 --- 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):