Improve debug support for asyncio futures

When in debug mode, asyncio returns the instantiation place of a Future
and places it in its repr(), for example:

  <Future finished result=None created at /home/antoine/distributed/distributed/worker.py:1223>

This is useful when asyncio logs cancelled futures or futures that were not
waited upon after erroring out.

However, when using @gen.coroutine, we need to fix the recorded stack trace
otherwise the display is much less useful:

  <Future finished result=None created at /home/antoine/tornado/tornado/gen.py:295>

diff --git a/tornado/gen.py b/tornado/gen.py
index 533ccb749d99df9ecf76c881981ec3ddd801f45b..038f6f0fa7ab93341021caec4d8ff13171f6bf47 100644 (file)
--- a/tornado/gen.py
+++ b/tornado/gen.py
@@ -169,6 +169,21 @@ def _value_from_stopiteration(e):
         return None
 
 
+def _create_future():
+    future = Future()
+    # Fixup asyncio debug info by removing extraneous stack entries
+    source_traceback = getattr(future, "_source_traceback", ())
+    while source_traceback:
+        # Each traceback entry is equivalent to a
+        # (filename, self.lineno, self.name, self.line) tuple
+        filename = source_traceback[-1][0]
+        if filename == __file__:
+            del source_traceback[-1]
+        else:
+            break
+    return future
+
+
 def engine(func):
     """Callback-oriented decorator for asynchronous generators.
 
@@ -277,7 +292,7 @@ def _make_coroutine_wrapper(func, replace_callback):
 
     @functools.wraps(wrapped)
     def wrapper(*args, **kwargs):
-        future = Future()
+        future = _create_future()
 
         if replace_callback and 'callback' in kwargs:
             callback = kwargs.pop('callback')
@@ -302,7 +317,7 @@ def _make_coroutine_wrapper(func, replace_callback):
                     orig_stack_contexts = stack_context._state.contexts
                     yielded = next(result)
                     if stack_context._state.contexts is not orig_stack_contexts:
-                        yielded = Future()
+                        yielded = _create_future()
                         yielded.set_exception(
                             stack_context.StackContextInconsistentError(
                                 'stack_context inconsistency (probably caused '
@@ -601,7 +616,7 @@ def Task(func, *args, **kwargs):
        a subclass of `YieldPoint`.  It still behaves the same way when
        yielded.
     """
-    future = Future()
+    future = _create_future()
 
     def handle_exception(typ, value, tb):
         if future.done():
@@ -810,7 +825,7 @@ def multi_future(children, quiet_exceptions=()):
     assert all(is_future(i) for i in children)
     unfinished_children = set(children)
 
-    future = Future()
+    future = _create_future()
     if not children:
         future.set_result({} if keys is not None else [])
 
@@ -858,7 +873,7 @@ def maybe_future(x):
     if is_future(x):
         return x
     else:
-        fut = Future()
+        fut = _create_future()
         fut.set_result(x)
         return fut
 
@@ -895,7 +910,7 @@ def with_timeout(timeout, future, quiet_exceptions=()):
     # callers and B) concurrent futures can only be cancelled while they are
     # in the queue, so cancellation cannot reliably bound our waiting time.
     future = convert_yielded(future)
-    result = Future()
+    result = _create_future()
     chain_future(future, result)
     io_loop = IOLoop.current()
 
@@ -942,7 +957,7 @@ def sleep(duration):
 
     .. versionadded:: 4.1
     """
-    f = Future()
+    f = _create_future()
     IOLoop.current().call_later(duration, lambda: f.set_result(None))
     return f
 

diff --git a/tornado/test/gen_test.py b/tornado/test/gen_test.py
index 87302eeb9e2790426832e1f2f9ecbe5a0976a012..0be49062590d80942b776a9e4d0d01cd638f5593 100644 (file)
--- a/tornado/test/gen_test.py
+++ b/tornado/test/gen_test.py
@@ -26,6 +26,11 @@ try:
 except ImportError:
     futures = None
 
+try:
+    import asyncio
+except ImportError:
+    asyncio = None
+
 
 class GenEngineTest(AsyncTestCase):
     def setUp(self):
@@ -1042,6 +1047,27 @@ class GenCoroutineTest(AsyncTestCase):
         self.assertIs(self.local_ref(), None)
         self.finished = True
 
+    @unittest.skipIf(sys.version_info < (3,),
+                     "test only relevant with asyncio Futures")
+    def test_asyncio_future_debug_info(self):
+        self.finished = True
+        # Enable debug mode
+        asyncio_loop = asyncio.get_event_loop()
+        self.addCleanup(asyncio_loop.set_debug, asyncio_loop.get_debug())
+        asyncio_loop.set_debug(True)
+
+        def f():
+            yield gen.moment
+
+        coro = gen.coroutine(f)()
+        self.assertIsInstance(coro, asyncio.Future)
+        # We expect the coroutine repr() to show the place where
+        # it was instantiated
+        expected = ("created at %s:%d"
+                    % (__file__, f.__code__.co_firstlineno + 3))
+        actual = repr(coro)
+        self.assertIn(expected, actual)
+
 
 class GenSequenceHandler(RequestHandler):
     @asynchronous