[Python-checkins] cpython (3.4): asyncio, Tulip issue 137: In debug mode, save traceback where Future, Task and
victor.stinner
python-checkins at python.org
Fri Jun 27 14:00:17 CEST 2014
http://hg.python.org/cpython/rev/8fb489a8eb28
changeset: 91444:8fb489a8eb28
branch: 3.4
parent: 91442:84816348e809
user: Victor Stinner <victor.stinner at gmail.com>
date: Fri Jun 27 13:52:20 2014 +0200
summary:
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.
files:
Lib/asyncio/base_events.py | 26 ++++-
Lib/asyncio/events.py | 18 ++-
Lib/asyncio/futures.py | 29 +++-
Lib/asyncio/tasks.py | 14 ++-
Lib/test/test_asyncio/test_base_events.py | 9 +-
Lib/test/test_asyncio/test_events.py | 37 ++++++-
Lib/test/test_asyncio/test_futures.py | 59 +++++++++++
Lib/test/test_asyncio/test_tasks.py | 14 ++
8 files changed, 180 insertions(+), 26 deletions(-)
diff --git a/Lib/asyncio/base_events.py b/Lib/asyncio/base_events.py
--- 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
--- 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
--- 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
--- 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')
diff --git a/Lib/test/test_asyncio/test_base_events.py b/Lib/test/test_asyncio/test_base_events.py
--- a/Lib/test/test_asyncio/test_base_events.py
+++ b/Lib/test/test_asyncio/test_base_events.py
@@ -406,19 +406,22 @@
1/0
def run_loop():
- self.loop.call_soon(zero_error)
+ handle = self.loop.call_soon(zero_error)
self.loop._run_once()
+ return handle
+ self.loop.set_debug(True)
self.loop._process_events = mock.Mock()
mock_handler = mock.Mock()
self.loop.set_exception_handler(mock_handler)
- run_loop()
+ handle = run_loop()
mock_handler.assert_called_with(self.loop, {
'exception': MOCK_ANY,
'message': test_utils.MockPattern(
'Exception in callback.*zero_error'),
- 'handle': MOCK_ANY,
+ 'handle': handle,
+ 'source_traceback': handle._source_traceback,
})
mock_handler.reset_mock()
diff --git a/Lib/test/test_asyncio/test_events.py b/Lib/test/test_asyncio/test_events.py
--- a/Lib/test/test_asyncio/test_events.py
+++ b/Lib/test/test_asyncio/test_events.py
@@ -1751,10 +1751,11 @@
pass
-class HandleTests(unittest.TestCase):
+class HandleTests(test_utils.TestCase):
def setUp(self):
- self.loop = None
+ self.loop = mock.Mock()
+ self.loop.get_debug.return_value = True
def test_handle(self):
def callback(*args):
@@ -1789,7 +1790,8 @@
self.loop.call_exception_handler.assert_called_with({
'message': test_utils.MockPattern('Exception in callback.*'),
'exception': mock.ANY,
- 'handle': h
+ 'handle': h,
+ 'source_traceback': h._source_traceback,
})
def test_handle_weakref(self):
@@ -1837,6 +1839,35 @@
% (cb_regex, re.escape(filename), lineno))
self.assertRegex(repr(h), regex)
+ def test_handle_source_traceback(self):
+ loop = asyncio.get_event_loop_policy().new_event_loop()
+ loop.set_debug(True)
+ self.set_event_loop(loop)
+
+ def check_source_traceback(h):
+ lineno = sys._getframe(1).f_lineno - 1
+ self.assertIsInstance(h._source_traceback, list)
+ self.assertEqual(h._source_traceback[-1][:3],
+ (__file__,
+ lineno,
+ 'test_handle_source_traceback'))
+
+ # call_soon
+ h = loop.call_soon(noop)
+ check_source_traceback(h)
+
+ # call_soon_threadsafe
+ h = loop.call_soon_threadsafe(noop)
+ check_source_traceback(h)
+
+ # call_later
+ h = loop.call_later(0, noop)
+ check_source_traceback(h)
+
+ # call_at
+ h = loop.call_later(0, noop)
+ check_source_traceback(h)
+
class TimerTests(unittest.TestCase):
diff --git a/Lib/test/test_asyncio/test_futures.py b/Lib/test/test_asyncio/test_futures.py
--- a/Lib/test/test_asyncio/test_futures.py
+++ b/Lib/test/test_asyncio/test_futures.py
@@ -2,8 +2,10 @@
import concurrent.futures
import re
+import sys
import threading
import unittest
+from test import support
from unittest import mock
import asyncio
@@ -284,6 +286,63 @@
self.assertEqual(f1.result(), 42)
self.assertTrue(f2.cancelled())
+ def test_future_source_traceback(self):
+ self.loop.set_debug(True)
+
+ future = asyncio.Future(loop=self.loop)
+ lineno = sys._getframe().f_lineno - 1
+ self.assertIsInstance(future._source_traceback, list)
+ self.assertEqual(future._source_traceback[-1][:3],
+ (__file__,
+ lineno,
+ 'test_future_source_traceback'))
+
+ @mock.patch('asyncio.base_events.logger')
+ def test_future_exception_never_retrieved(self, m_log):
+ self.loop.set_debug(True)
+
+ def memroy_error():
+ try:
+ raise MemoryError()
+ except BaseException as exc:
+ return exc
+ exc = memroy_error()
+
+ future = asyncio.Future(loop=self.loop)
+ source_traceback = future._source_traceback
+ future.set_exception(exc)
+ future = None
+ test_utils.run_briefly(self.loop)
+ support.gc_collect()
+
+ if sys.version_info >= (3, 4):
+ frame = source_traceback[-1]
+ regex = (r'^Future exception was never retrieved\n'
+ r'future: <Future finished exception=MemoryError\(\)>\n'
+ r'source_traceback: Object created at \(most recent call last\):\n'
+ r' File'
+ r'.*\n'
+ r' File "%s", line %s, in test_future_exception_never_retrieved\n'
+ r' future = asyncio\.Future\(loop=self\.loop\)$'
+ % (frame[0], frame[1]))
+ exc_info = (type(exc), exc, exc.__traceback__)
+ m_log.error.assert_called_once_with(mock.ANY, exc_info=exc_info)
+ else:
+ frame = source_traceback[-1]
+ regex = (r'^Future/Task exception was never retrieved\n'
+ r'Future/Task created at \(most recent call last\):\n'
+ r' File'
+ r'.*\n'
+ r' File "%s", line %s, in test_future_exception_never_retrieved\n'
+ r' future = asyncio\.Future\(loop=self\.loop\)\n'
+ r'Traceback \(most recent call last\):\n'
+ r'.*\n'
+ r'MemoryError$'
+ % (frame[0], frame[1]))
+ m_log.error.assert_called_once_with(mock.ANY, exc_info=False)
+ message = m_log.error.call_args[0][0]
+ self.assertRegex(message, re.compile(regex, re.DOTALL))
+
class FutureDoneCallbackTests(test_utils.TestCase):
diff --git a/Lib/test/test_asyncio/test_tasks.py b/Lib/test/test_asyncio/test_tasks.py
--- a/Lib/test/test_asyncio/test_tasks.py
+++ b/Lib/test/test_asyncio/test_tasks.py
@@ -1546,6 +1546,7 @@
raise Exception("code never reached")
mock_handler = mock.Mock()
+ self.loop.set_debug(True)
self.loop.set_exception_handler(mock_handler)
# schedule the task
@@ -1560,6 +1561,7 @@
# remove the future used in kill_me(), and references to the task
del coro.gi_frame.f_locals['future']
coro = None
+ source_traceback = task._source_traceback
task = None
# no more reference to kill_me() task: the task is destroyed by the GC
@@ -1570,6 +1572,7 @@
mock_handler.assert_called_with(self.loop, {
'message': 'Task was destroyed but it is pending!',
'task': mock.ANY,
+ 'source_traceback': source_traceback,
})
mock_handler.reset_mock()
@@ -1604,6 +1607,17 @@
self.assertRegex(message, re.compile(regex, re.DOTALL))
+ def test_task_source_traceback(self):
+ self.loop.set_debug(True)
+
+ task = asyncio.Task(coroutine_function(), loop=self.loop)
+ lineno = sys._getframe().f_lineno - 1
+ self.assertIsInstance(task._source_traceback, list)
+ self.assertEqual(task._source_traceback[-1][:3],
+ (__file__,
+ lineno,
+ 'test_task_source_traceback'))
+
class GatherTestsBase:
--
Repository URL: http://hg.python.org/cpython
More information about the Python-checkins
mailing list