asyncio, Tulip issue 137: In debug mode, save traceback where Future, Task and

Handle objects are created. Pass the traceback to call_exception_handler() in
the 'source_traceback' key.

The traceback is truncated to hide internal calls in asyncio, show only the
traceback from user code.

Add tests for the new source_traceback, and a test for the 'Future/Task
exception was never retrieved' log.

Lib/asyncio/base_events.py

@@ -21,6 +21,7 @@ import inspect
 import logging
 import socket
 import subprocess
+import traceback
 import time
 import os
 import sys
@@ -290,7 +291,10 @@ class BaseEventLoop(events.AbstractEventLoop):
         Any positional arguments after the callback will be passed to
         the callback when it is called.
         """
-        return self.call_at(self.time() + delay, callback, *args)
+        timer = self.call_at(self.time() + delay, callback, *args)
+        if timer._source_traceback:
+            del timer._source_traceback[-1]
+        return timer
 
     def call_at(self, when, callback, *args):
         """Like call_later(), but uses an absolute time."""
@@ -299,6 +303,8 @@ class BaseEventLoop(events.AbstractEventLoop):
         if self._debug:
             self._assert_is_current_event_loop()
         timer = events.TimerHandle(when, callback, args, self)
+        if timer._source_traceback:
+            del timer._source_traceback[-1]
         heapq.heappush(self._scheduled, timer)
         return timer
 
@@ -312,7 +318,10 @@ class BaseEventLoop(events.AbstractEventLoop):
         Any positional arguments after the callback will be passed to
         the callback when it is called.
         """
-        return self._call_soon(callback, args, check_loop=True)
+        handle = self._call_soon(callback, args, check_loop=True)
+        if handle._source_traceback:
+            del handle._source_traceback[-1]
+        return handle
 
     def _call_soon(self, callback, args, check_loop):
         if tasks.iscoroutinefunction(callback):
@@ -320,6 +329,8 @@ class BaseEventLoop(events.AbstractEventLoop):
         if self._debug and check_loop:
             self._assert_is_current_event_loop()
         handle = events.Handle(callback, args, self)
+        if handle._source_traceback:
+            del handle._source_traceback[-1]
         self._ready.append(handle)
         return handle
 
@@ -344,6 +355,8 @@ class BaseEventLoop(events.AbstractEventLoop):
     def call_soon_threadsafe(self, callback, *args):
         """Like call_soon(), but thread safe."""
         handle = self._call_soon(callback, args, check_loop=False)
+        if handle._source_traceback:
+            del handle._source_traceback[-1]
         self._write_to_self()
         return handle
 
@@ -757,7 +770,14 @@ class BaseEventLoop(events.AbstractEventLoop):
         for key in sorted(context):
             if key in {'message', 'exception'}:
                 continue
-            log_lines.append('{}: {!r}'.format(key, context[key]))
+            value = context[key]
+            if key == 'source_traceback':
+                tb = ''.join(traceback.format_list(value))
+                value = 'Object created at (most recent call last):\n'
+                value += tb.rstrip()
+            else:
+                value = repr(value)
+            log_lines.append('{}: {}'.format(key, value))
 
         logger.error('\n'.join(log_lines), exc_info=exc_info)
 

Lib/asyncio/events.py

@@ -11,6 +11,7 @@ __all__ = ['AbstractEventLoopPolicy',
 import functools
 import inspect
 import subprocess
+import traceback
 import threading
 import socket
 import sys
@@ -66,7 +67,8 @@ def _format_callback(func, args, suffix=''):
 class Handle:
     """Object returned by callback registration methods."""
 
-    __slots__ = ['_callback', '_args', '_cancelled', '_loop', '__weakref__']
+    __slots__ = ('_callback', '_args', '_cancelled', '_loop',
+                 '_source_traceback', '__weakref__')
 
     def __init__(self, callback, args, loop):
         assert not isinstance(callback, Handle), 'A Handle is not a callback'
@@ -74,6 +76,10 @@ class Handle:
         self._callback = callback
         self._args = args
         self._cancelled = False
+        if self._loop.get_debug():
+            self._source_traceback = traceback.extract_stack(sys._getframe(1))
+        else:
+            self._source_traceback = None
 
     def __repr__(self):
         info = []
@@ -91,11 +97,14 @@ class Handle:
         except Exception as exc:
             cb = _format_callback(self._callback, self._args)
             msg = 'Exception in callback {}'.format(cb)
-            self._loop.call_exception_handler({
+            context = {
                 'message': msg,
                 'exception': exc,
                 'handle': self,
-            })
+            }
+            if self._source_traceback:
+                context['source_traceback'] = self._source_traceback
+            self._loop.call_exception_handler(context)
         self = None  # Needed to break cycles when an exception occurs.
 
 
@@ -107,7 +116,8 @@ class TimerHandle(Handle):
     def __init__(self, when, callback, args, loop):
         assert when is not None
         super().__init__(callback, args, loop)
-
+        if self._source_traceback:
+            del self._source_traceback[-1]
         self._when = when
 
     def __repr__(self):

Lib/asyncio/futures.py

@@ -82,10 +82,11 @@ class _TracebackLogger:
     in a discussion about closing files when they are collected.
     """
 
-    __slots__ = ['exc', 'tb', 'loop']
+    __slots__ = ('loop', 'source_traceback', 'exc', 'tb')
 
-    def __init__(self, exc, loop):
-        self.loop = loop
+    def __init__(self, future, exc):
+        self.loop = future._loop
+        self.source_traceback = future._source_traceback
         self.exc = exc
         self.tb = None
 
@@ -102,11 +103,12 @@ class _TracebackLogger:
 
     def __del__(self):
         if self.tb:
-            msg = 'Future/Task exception was never retrieved:\n{tb}'
-            context = {
-                'message': msg.format(tb=''.join(self.tb)),
-            }
-            self.loop.call_exception_handler(context)
+            msg = 'Future/Task exception was never retrieved'
+            if self.source_traceback:
+                msg += '\nFuture/Task created at (most recent call last):\n'
+                msg += ''.join(traceback.format_list(self.source_traceback))
+            msg += ''.join(self.tb).rstrip()
+            self.loop.call_exception_handler({'message': msg})
 
 
 class Future:
@@ -149,6 +151,10 @@ class Future:
         else:
             self._loop = loop
         self._callbacks = []
+        if self._loop.get_debug():
+            self._source_traceback = traceback.extract_stack(sys._getframe(1))
+        else:
+            self._source_traceback = None
 
     def _format_callbacks(self):
         cb = self._callbacks
@@ -196,10 +202,13 @@ class Future:
                 return
             exc = self._exception
             context = {
-                'message': 'Future/Task exception was never retrieved',
+                'message': ('%s exception was never retrieved'
+                            % self.__class__.__name__),
                 'exception': exc,
                 'future': self,
             }
+            if self._source_traceback:
+                context['source_traceback'] = self._source_traceback
             self._loop.call_exception_handler(context)
 
     def cancel(self):
@@ -335,7 +344,7 @@ class Future:
         if _PY34:
             self._log_traceback = True
         else:
-            self._tb_logger = _TracebackLogger(exception, self._loop)
+            self._tb_logger = _TracebackLogger(self, exception)
             # Arrange for the logger to be activated after all callbacks
             # have had a chance to call result() or exception().
             self._loop.call_soon(self._tb_logger.activate)

Lib/asyncio/tasks.py

@@ -195,6 +195,8 @@ class Task(futures.Future):
     def __init__(self, coro, *, loop=None):
         assert iscoroutine(coro), repr(coro)  # Not a coroutine function!
         super().__init__(loop=loop)
+        if self._source_traceback:
+            del self._source_traceback[-1]
         self._coro = iter(coro)  # Use the iterator just in case.
         self._fut_waiter = None
         self._must_cancel = False
@@ -207,10 +209,13 @@ class Task(futures.Future):
     if _PY34:
         def __del__(self):
             if self._state == futures._PENDING:
-                self._loop.call_exception_handler({
+                context = {
                     'task': self,
                     'message': 'Task was destroyed but it is pending!',
-                })
+                }
+                if self._source_traceback:
+                    context['source_traceback'] = self._source_traceback
+                self._loop.call_exception_handler(context)
             futures.Future.__del__(self)
 
     def __repr__(self):
@@ -620,7 +625,10 @@ def async(coro_or_future, *, loop=None):
             raise ValueError('loop argument must agree with Future')
         return coro_or_future
     elif iscoroutine(coro_or_future):
-        return Task(coro_or_future, loop=loop)
+        task = Task(coro_or_future, loop=loop)
+        if task._source_traceback:
+            del task._source_traceback[-1]
+        return task
     else:
         raise TypeError('A Future or coroutine is required')