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.
diff --git a/Lib/asyncio/base_events.py b/Lib/asyncio/base_events.py
index b127142..90115e5 100644
--- a/Lib/asyncio/base_events.py
+++ b/Lib/asyncio/base_events.py
@@ -21,6 +21,7 @@
import logging
import socket
import subprocess
+import traceback
import time
import os
import sys
@@ -290,7 +291,10 @@
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 @@
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 @@
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 @@
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 @@
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 @@
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)
diff --git a/Lib/asyncio/events.py b/Lib/asyncio/events.py
index 58c6bd5..b389cfb 100644
--- a/Lib/asyncio/events.py
+++ b/Lib/asyncio/events.py
@@ -11,6 +11,7 @@
import functools
import inspect
import subprocess
+import traceback
import threading
import socket
import sys
@@ -66,7 +67,8 @@
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 @@
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 @@
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 @@
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):
diff --git a/Lib/asyncio/futures.py b/Lib/asyncio/futures.py
index 3103fe1..fcc90d1 100644
--- a/Lib/asyncio/futures.py
+++ b/Lib/asyncio/futures.py
@@ -82,10 +82,11 @@
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 @@
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 @@
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 @@
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 @@
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)
diff --git a/Lib/asyncio/tasks.py b/Lib/asyncio/tasks.py
index 89ec3a4..db0bbf3 100644
--- a/Lib/asyncio/tasks.py
+++ b/Lib/asyncio/tasks.py
@@ -195,6 +195,8 @@
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 @@
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 @@
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')