]> git.ipfire.org Git - thirdparty/tornado.git/commitdiff
Add support for Future.exc_info when logging abandoned futures.
authorBen Darnell <ben@bendarnell.com>
Thu, 11 Dec 2014 14:24:54 +0000 (09:24 -0500)
committerBen Darnell <ben@bendarnell.com>
Fri, 12 Dec 2014 05:00:55 +0000 (00:00 -0500)
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
tornado/gen.py
tornado/http1connection.py
tornado/iostream.py
tornado/test/gen_test.py
tornado/test/iostream_test.py
tornado/web.py

index d32f2c6ecdea708cd11472ba01ff5589a6759543..c49e01f7022f7deb0cba1b799ed11f509f9d949a 100644 (file)
@@ -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
index 2fc9b0c70538bcb7694872049e5fe4a8e07ab07c..b9b63419582294460f0df753922efa18b41c26bf 100644 (file)
@@ -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
index 90895cc94393d8ef0fd662f759bc4b1d76f0d931..8f105d034541ce2fc356e1bf00fba74b46d3e947 100644 (file)
@@ -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
index 2d5df992329c29f26256e3e3879a3d004b37882f..e13d4bacbd4b908ec7396c1945e050c8d09fd2a9 100644 (file)
@@ -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:
index a15cdf73a152f970986937d233ecc06f42ecd0d1..f07bdaa85d50075f63665d467e4a38b8ff189862 100644 (file)
@@ -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)
 
index f54eed6bb8113c4eb320174005513c2779b2c95a..5d13184baf0f3bb8c2cc8304550d40d9da132744 100644 (file)
@@ -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
index 6325f7f9126508790675656addb04a33768a675b..36032bd146fdc9cef787bb084edfaced3c2fa62f 100755 (executable)
@@ -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)