From 241956a6cdd1e96de7afe9355fc3dec303f2365e Mon Sep 17 00:00:00 2001 From: Ben Darnell Date: Thu, 11 Dec 2014 09:24:54 -0500 Subject: [PATCH] Add support for Future.exc_info when logging abandoned futures. Simplify some Future internals. Add enough magic calls to Future.exception that the test suite passes without warning (at least on py34) --- tornado/concurrent.py | 133 +++++++++++++++------------------- tornado/gen.py | 6 +- tornado/http1connection.py | 3 + tornado/iostream.py | 22 +++++- tornado/test/gen_test.py | 2 +- tornado/test/iostream_test.py | 7 +- tornado/web.py | 4 +- 7 files changed, 96 insertions(+), 81 deletions(-) diff --git a/tornado/concurrent.py b/tornado/concurrent.py index d32f2c6ec..c49e01f70 100644 --- a/tornado/concurrent.py +++ b/tornado/concurrent.py @@ -25,22 +25,25 @@ module. from __future__ import absolute_import, division, print_function, with_statement import functools +import platform import traceback import sys from tornado.log import app_log from tornado.stack_context import ExceptionStackContext, wrap from tornado.util import raise_exc_info, ArgReplacer -from tornado.log import app_log try: from concurrent import futures except ImportError: futures = None - -_PY34 = sys.version_info >= (3, 4) +# Can the garbage collector handle cycles that include __del__ methods? +# This is true in cpython beginning with version 3.4 (PEP 442). +_GC_CYCLE_FINALIZERS = (platform.python_implementation() == 'CPython' and + sys.version_info >= (3, 4)) + class ReturnValueIgnoredError(Exception): pass @@ -97,35 +100,26 @@ class _TracebackLogger(object): in a discussion about closing files when they are collected. """ - __slots__ = ('loop', 'source_traceback', 'exc', 'tb') + __slots__ = ('exc_info', 'formatted_tb') - def __init__(self, exc): - self.exc = exc - self.tb = None + def __init__(self, exc_info): + self.exc_info = exc_info + self.formatted_tb = None def activate(self): - exc = self.exc - if exc is not None: - self.exc = None - if hasattr(exc, '__traceback__'): - self.tb = traceback.format_exception(exc.__class__, exc, - exc.__traceback__) - else: - # could provide more information here - self.tb = traceback.format_exception_only(type(exc), - exc) + exc_info = self.exc_info + if exc_info is not None: + self.exc_info = None + self.formatted_tb = traceback.format_exception(*exc_info) def clear(self): - self.exc = None - self.tb = None + self.exc_info = None + self.formatted_tb = None def __del__(self): - if self.tb: - msg = 'Future exception was never retrieved: %s' % \ - ''.join(self.tb).rstrip() - - # HACK: should probably call something - app_log.error(msg) + if self.formatted_tb: + app_log.error('Future exception was never retrieved: %s', + ''.join(self.formatted_tb).rstrip()) class Future(object): @@ -159,12 +153,11 @@ class Future(object): def __init__(self): self._done = False self._result = None - self._exception = None self._exc_info = None - + self._log_traceback = False # Used for Python >= 3.4 self._tb_logger = None # Used for Python <= 3.3 - + self._callbacks = [] def cancel(self): @@ -191,20 +184,21 @@ class Future(object): """Returns True if the future has finished running.""" return self._done - def result(self, timeout=None): - """If the operation succeeded, return its result. If it failed, - re-raise its exception. - """ + def _clear_tb_log(self): self._log_traceback = False if self._tb_logger is not None: self._tb_logger.clear() self._tb_logger = None + + def result(self, timeout=None): + """If the operation succeeded, return its result. If it failed, + re-raise its exception. + """ + self._clear_tb_log() if self._result is not None: return self._result if self._exc_info is not None: raise_exc_info(self._exc_info) - elif self._exception is not None: - raise self._exception self._check_done() return self._result @@ -212,12 +206,9 @@ class Future(object): """If the operation raised an exception, return the `Exception` object. Otherwise returns None. """ - self._log_traceback = False - if self._tb_logger is not None: - self._tb_logger.clear() - self._tb_logger = None - if self._exception is not None: - return self._exception + self._clear_tb_log() + if self._exc_info is not None: + return self._exc_info[1] else: self._check_done() return None @@ -246,30 +237,17 @@ class Future(object): def set_exception(self, exception): """Sets the exception of a ``Future.``""" - self._exception = exception - if _PY34: - self._log_traceback = True - else: - self._tb_logger = _TracebackLogger(exception) - if hasattr(exception, '__traceback__'): - # Python 3: exception contains a link to the traceback - - # Arrange for the logger to be activated after all callbacks - # have had a chance to call result() or exception(). - - # HACK: circular dependencies - from tornado.ioloop import IOLoop - IOLoop.current().add_callback(self._tb_logger.activate) - else: - self._tb_logger.activate() - - self._set_done() + self.set_exc_info( + (exception.__class__, + exception, + getattr(exception, '__traceback__', None))) def exc_info(self): """Returns a tuple in the same format as `sys.exc_info` or None. .. versionadded:: 4.0 """ + self._clear_tb_log() return self._exc_info def set_exc_info(self, exc_info): @@ -280,7 +258,18 @@ class Future(object): .. versionadded:: 4.0 """ self._exc_info = exc_info - self.set_exception(exc_info[1]) + self._log_traceback = True + if not _GC_CYCLE_FINALIZERS: + self._tb_logger = _TracebackLogger(exc_info) + + try: + self._set_done() + finally: + # Activate the logger after all callbacks have had a + # chance to call result() or exception(). + if self._log_traceback and self._tb_logger is not None: + self._tb_logger.activate() + self._exc_info = exc_info def _check_done(self): if not self._done: @@ -295,27 +284,21 @@ class Future(object): app_log.exception('exception calling callback %r for %r', cb, self) self._callbacks = None - + # On Python 3.3 or older, objects with a destructor part of a reference - # cycle are never destroyed. It's not more the case on Python 3.4 thanks to + # cycle are never destroyed. It's no longer the case on Python 3.4 thanks to # the PEP 442. - if _PY34: + if _GC_CYCLE_FINALIZERS: def __del__(self): if not self._log_traceback: # set_exception() was not called, or result() or exception() # has consumed the exception return - - exc = self._exception - tb = traceback.format_exception(exc.__class__, exc, - exc.__traceback__) - - msg = '%s exception was never retrieved: %s' % \ - (self.__class__.__name__, ''.join(tb).rstrip()) - - # HACK: should probably call something - app_log.error(msg) - + + tb = traceback.format_exception(*self._exc_info) + + app_log.error('Future %r exception was never retrieved: %s', + self, ''.join(tb).rstrip()) TracebackFuture = Future @@ -429,6 +412,10 @@ 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) # If the caller passed in a callback, schedule it to be called diff --git a/tornado/gen.py b/tornado/gen.py index 2fc9b0c70..b9b634195 100644 --- a/tornado/gen.py +++ b/tornado/gen.py @@ -528,9 +528,11 @@ def with_timeout(timeout, future, io_loop=None): chain_future(future, result) if io_loop is None: io_loop = IOLoop.current() + def timeout_callback(): + result.set_exception(TimeoutError("Timeout")) + future.add_done_callback(lambda f: f.exception()) timeout_handle = io_loop.add_timeout( - timeout, - lambda: result.set_exception(TimeoutError("Timeout"))) + timeout, timeout_callback) if isinstance(future, Future): # We know this future will resolve on the IOLoop, so we don't # need the extra thread-safety of IOLoop.add_future (and we also diff --git a/tornado/http1connection.py b/tornado/http1connection.py index 90895cc94..8f105d034 100644 --- a/tornado/http1connection.py +++ b/tornado/http1connection.py @@ -374,6 +374,7 @@ class HTTP1Connection(httputil.HTTPConnection): if self.stream.closed(): future = self._write_future = Future() future.set_exception(iostream.StreamClosedError()) + future.exception() else: if callback is not None: self._write_callback = stack_context.wrap(callback) @@ -412,6 +413,7 @@ class HTTP1Connection(httputil.HTTPConnection): if self.stream.closed(): future = self._write_future = Future() self._write_future.set_exception(iostream.StreamClosedError()) + self._write_future.exception() else: if callback is not None: self._write_callback = stack_context.wrap(callback) @@ -451,6 +453,7 @@ class HTTP1Connection(httputil.HTTPConnection): self._pending_write.add_done_callback(self._finish_request) def _on_write_complete(self, future): + future.exception() 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 2d5df9923..e13d4bacb 100644 --- a/tornado/iostream.py +++ b/tornado/iostream.py @@ -230,6 +230,10 @@ class BaseIOStream(object): gen_log.info("Unsatisfiable read, closing connection: %s" % e) self.close(exc_info=True) return future + except: + if future is not None: + future.add_done_callback(lambda f: f.exception()) + raise return future def read_until(self, delimiter, callback=None, max_bytes=None): @@ -257,6 +261,10 @@ class BaseIOStream(object): gen_log.info("Unsatisfiable read, closing connection: %s" % e) self.close(exc_info=True) return future + except: + if future is not None: + future.add_done_callback(lambda f: f.exception()) + raise return future def read_bytes(self, num_bytes, callback=None, streaming_callback=None, @@ -281,7 +289,12 @@ class BaseIOStream(object): self._read_bytes = num_bytes self._read_partial = partial self._streaming_callback = stack_context.wrap(streaming_callback) - self._try_inline_read() + try: + self._try_inline_read() + except: + if future is not None: + future.add_done_callback(lambda f: f.exception()) + raise return future def read_until_close(self, callback=None, streaming_callback=None): @@ -305,7 +318,11 @@ class BaseIOStream(object): self._run_read_callback(self._read_buffer_size, False) return future self._read_until_close = True - self._try_inline_read() + try: + self._try_inline_read() + except: + future.add_done_callback(lambda f: f.exception()) + raise return future def write(self, data, callback=None): @@ -344,6 +361,7 @@ class BaseIOStream(object): future = None else: future = self._write_future = TracebackFuture() + future.add_done_callback(lambda f: f.exception()) if not self._connecting: self._handle_write() if self._write_buffer: diff --git a/tornado/test/gen_test.py b/tornado/test/gen_test.py index a15cdf73a..f07bdaa85 100644 --- a/tornado/test/gen_test.py +++ b/tornado/test/gen_test.py @@ -1039,7 +1039,7 @@ class WithTimeoutTest(AsyncTestCase): future = Future() self.io_loop.add_timeout( datetime.timedelta(seconds=0.1), - lambda: future.set_exception(ZeroDivisionError)) + lambda: future.set_exception(ZeroDivisionError())) with self.assertRaises(ZeroDivisionError): yield gen.with_timeout(datetime.timedelta(seconds=3600), future) diff --git a/tornado/test/iostream_test.py b/tornado/test/iostream_test.py index f54eed6bb..5d13184ba 100644 --- a/tornado/test/iostream_test.py +++ b/tornado/test/iostream_test.py @@ -249,7 +249,8 @@ class TestIOStreamMixin(object): # opendns and some ISPs return bogus addresses for nonexistent # domains instead of the proper error codes). with ExpectLog(gen_log, "Connect error"): - stream.connect(('an invalid domain', 54321)) + stream.connect(('an invalid domain', 54321), callback=self.stop) + self.wait() self.assertTrue(isinstance(stream.error, socket.gaierror), stream.error) def test_read_callback_error(self): @@ -874,12 +875,14 @@ class TestIOStreamStartTLS(AsyncTestCase): @gen_test def test_handshake_fail(self): - self.server_start_tls(_server_ssl_options()) + server_future = self.server_start_tls(_server_ssl_options()) client_future = self.client_start_tls( dict(cert_reqs=ssl.CERT_REQUIRED, ca_certs=certifi.where())) with ExpectLog(gen_log, "SSL Error"): with self.assertRaises(ssl.SSLError): yield client_future + with self.assertRaises(ssl.SSLError): + yield server_future @skipIfNonUnix diff --git a/tornado/web.py b/tornado/web.py index 6325f7f91..36032bd14 100755 --- a/tornado/web.py +++ b/tornado/web.py @@ -267,6 +267,7 @@ class RequestHandler(object): if _has_stream_request_body(self.__class__): if not self.request.body.done(): self.request.body.set_exception(iostream.StreamClosedError()) + self.request.body.exception() def clear(self): """Resets all headers and content for this response.""" @@ -1915,7 +1916,8 @@ class _RequestDispatcher(httputil.HTTPMessageDelegate): # However, that shouldn't happen because _execute has a blanket # except handler, and we cannot easily access the IOLoop here to # call add_future. - self.handler._execute(transforms, *self.path_args, **self.path_kwargs) + f = self.handler._execute(transforms, *self.path_args, **self.path_kwargs) + f.add_done_callback(lambda f: f.exception()) # XXX # 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) -- 2.47.2