From: Ben Darnell Date: Sat, 17 Jan 2015 20:26:03 +0000 (-0500) Subject: Log more uncaught exceptions instead of suppressing them. X-Git-Tag: v4.1.0b1~30^2~1 X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=020301197c7bd5532e85b7e91a57be87c40b08a4;p=thirdparty%2Ftornado.git Log more uncaught exceptions instead of suppressing them. Add more docs about Future exception logging. --- diff --git a/tornado/concurrent.py b/tornado/concurrent.py index c49e01f70..acfbcd83e 100644 --- a/tornado/concurrent.py +++ b/tornado/concurrent.py @@ -149,6 +149,14 @@ class Future(object): if that package was available and fall back to the thread-unsafe implementation if it was not. + .. versionchanged:: 4.1 + If a `.Future` contains an error but that error is never observed + (by calling ``result()``, ``exception()``, or ``exc_info()``), + a stack trace will be logged when the `.Future` is garbage collected. + This normally indicates an error in the application, but in cases + where it results in undesired logging it may be necessary to + suppress the logging by ensuring that the exception is observed: + ``f.add_done_callback(lambda f: f.exception())``. """ def __init__(self): self._done = False @@ -412,11 +420,7 @@ def return_future(f): # If the initial synchronous part of f() raised an exception, # go ahead and raise it to the caller directly without waiting # for them to inspect the Future. - # - # "Consume" the exception from the future so it will not be logged - # as uncaught. - future.exception() - raise_exc_info(exc_info) + future.result() # If the caller passed in a callback, schedule it to be called # when the future resolves. It is important that this happens diff --git a/tornado/gen.py b/tornado/gen.py index b9b634195..e332d7a93 100644 --- a/tornado/gen.py +++ b/tornado/gen.py @@ -56,6 +56,7 @@ import types from tornado.concurrent import Future, TracebackFuture, is_future, chain_future from tornado.ioloop import IOLoop +from tornado.log import app_log from tornado import stack_context @@ -504,7 +505,7 @@ def maybe_future(x): return fut -def with_timeout(timeout, future, io_loop=None): +def with_timeout(timeout, future, io_loop=None, quiet_exceptions=()): """Wraps a `.Future` in a timeout. Raises `TimeoutError` if the input future does not complete before @@ -512,9 +513,17 @@ def with_timeout(timeout, future, io_loop=None): `.IOLoop.add_timeout` (i.e. a `datetime.timedelta` or an absolute time relative to `.IOLoop.time`) + If the wrapped `.Future` fails after it has timed out, the exception + will be logged unless it is of a type contained in ``quiet_exceptions`` + (which may be an exception type or a sequence of types). + Currently only supports Futures, not other `YieldPoint` classes. .. versionadded:: 4.0 + + .. versionchanged:: 4.1 + Added the ``quiet_exceptions`` argument and the logging of unhandled + exceptions. """ # TODO: allow yield points in addition to futures? # Tricky to do with stack_context semantics. @@ -528,9 +537,17 @@ def with_timeout(timeout, future, io_loop=None): chain_future(future, result) if io_loop is None: io_loop = IOLoop.current() + def error_callback(future): + try: + future.result() + except Exception as e: + if not isinstance(e, quiet_exceptions): + app_log.error("Exception in Future %r after timeout", + future, exc_info=True) def timeout_callback(): result.set_exception(TimeoutError("Timeout")) - future.add_done_callback(lambda f: f.exception()) + # In case the wrapped future goes on to fail, log it. + future.add_done_callback(error_callback) timeout_handle = io_loop.add_timeout( timeout, timeout_callback) if isinstance(future, Future): diff --git a/tornado/http1connection.py b/tornado/http1connection.py index 8f105d034..2d5fccd94 100644 --- a/tornado/http1connection.py +++ b/tornado/http1connection.py @@ -162,7 +162,8 @@ class HTTP1Connection(httputil.HTTPConnection): header_data = yield gen.with_timeout( self.stream.io_loop.time() + self.params.header_timeout, header_future, - io_loop=self.stream.io_loop) + io_loop=self.stream.io_loop, + quiet_exceptions=iostream.StreamClosedError) except gen.TimeoutError: self.close() raise gen.Return(False) @@ -221,7 +222,8 @@ class HTTP1Connection(httputil.HTTPConnection): try: yield gen.with_timeout( self.stream.io_loop.time() + self._body_timeout, - body_future, self.stream.io_loop) + body_future, self.stream.io_loop, + quiet_exceptions=iostream.StreamClosedError) except gen.TimeoutError: gen_log.info("Timeout reading body from %s", self.context) @@ -453,7 +455,9 @@ class HTTP1Connection(httputil.HTTPConnection): self._pending_write.add_done_callback(self._finish_request) def _on_write_complete(self, future): - future.exception() + exc = future.exception() + if exc is not None and not isinstance(exc, iostream.StreamClosedError): + future.result() if self._write_callback is not None: callback = self._write_callback self._write_callback = None diff --git a/tornado/iostream.py b/tornado/iostream.py index e13d4bacb..3cd905067 100644 --- a/tornado/iostream.py +++ b/tornado/iostream.py @@ -232,6 +232,8 @@ class BaseIOStream(object): return future except: if future is not None: + # Ensure that the future doesn't log an error because its + # failure was never examined. future.add_done_callback(lambda f: f.exception()) raise return future diff --git a/tornado/web.py b/tornado/web.py index 36032bd14..fb4d439ad 100755 --- a/tornado/web.py +++ b/tornado/web.py @@ -1915,9 +1915,10 @@ class _RequestDispatcher(httputil.HTTPMessageDelegate): # trapped in the Future it returns (which we are ignoring here). # However, that shouldn't happen because _execute has a blanket # except handler, and we cannot easily access the IOLoop here to - # call add_future. + # 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()) # XXX + 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)