From bbd96c6f47046e11f47de06550dcd1c816aad71c Mon Sep 17 00:00:00 2001 From: Victor Stinner Date: Fri, 27 Jun 2014 12:28:41 +0200 Subject: asyncio, Tulip issue 137: In debug mode, add the traceback where the coroutine object was created to the "coroutine ... was never yield from" log --- Lib/asyncio/tasks.py | 17 ++++++++++------- Lib/test/test_asyncio/test_tasks.py | 32 ++++++++++++++++++++++++++++++++ 2 files changed, 42 insertions(+), 7 deletions(-) diff --git a/Lib/asyncio/tasks.py b/Lib/asyncio/tasks.py index 52ca33a..89ec3a4 100644 --- a/Lib/asyncio/tasks.py +++ b/Lib/asyncio/tasks.py @@ -43,6 +43,7 @@ class CoroWrapper: assert inspect.isgenerator(gen), gen self.gen = gen self.func = func + self._source_traceback = traceback.extract_stack(sys._getframe(1)) def __iter__(self): return self @@ -81,13 +82,13 @@ class CoroWrapper: gen = getattr(self, 'gen', None) frame = getattr(gen, 'gi_frame', None) if frame is not None and frame.f_lasti == -1: - func = self.func - code = func.__code__ - filename = code.co_filename - lineno = code.co_firstlineno - logger.error( - 'Coroutine %r defined at %s:%s was never yielded from', - func.__name__, filename, lineno) + func = events._format_callback(self.func, ()) + tb = ''.join(traceback.format_list(self._source_traceback)) + message = ('Coroutine %s was never yielded from\n' + 'Coroutine object created at (most recent call last):\n' + '%s' + % (func, tb.rstrip())) + logger.error(message) def coroutine(func): @@ -112,6 +113,8 @@ def coroutine(func): @functools.wraps(func) def wrapper(*args, **kwds): w = CoroWrapper(coro(*args, **kwds), func) + if w._source_traceback: + del w._source_traceback[-1] w.__name__ = func.__name__ if _PY35: w.__qualname__ = func.__qualname__ diff --git a/Lib/test/test_asyncio/test_tasks.py b/Lib/test/test_asyncio/test_tasks.py index 8fd3e28..c5eb92b 100644 --- a/Lib/test/test_asyncio/test_tasks.py +++ b/Lib/test/test_asyncio/test_tasks.py @@ -1,6 +1,7 @@ """Tests for tasks.py.""" import os.path +import re import sys import types import unittest @@ -1572,6 +1573,37 @@ class TaskTests(test_utils.TestCase): }) mock_handler.reset_mock() + @mock.patch('asyncio.tasks.logger') + def test_coroutine_never_yielded(self, m_log): + debug = asyncio.tasks._DEBUG + try: + asyncio.tasks._DEBUG = True + @asyncio.coroutine + def coro_noop(): + pass + finally: + asyncio.tasks._DEBUG = debug + + tb_filename = __file__ + tb_lineno = sys._getframe().f_lineno + 1 + coro = coro_noop() + coro = None + support.gc_collect() + + self.assertTrue(m_log.error.called) + message = m_log.error.call_args[0][0] + func_filename, func_lineno = test_utils.get_function_source(coro_noop) + regex = (r'^Coroutine %s\(\) at %s:%s was never yielded from\n' + r'Coroutine object created at \(most recent call last\):\n' + r'.*\n' + r' File "%s", line %s, in test_coroutine_never_yielded\n' + r' coro = coro_noop\(\)$' + % (re.escape(coro_noop.__qualname__), + func_filename, func_lineno, + tb_filename, tb_lineno)) + + self.assertRegex(message, re.compile(regex, re.DOTALL)) + class GatherTestsBase: -- cgit v0.12 From 80f53aa9a0b2af28c9d8052c46b452cccb8e0b41 Mon Sep 17 00:00:00 2001 From: Victor Stinner Date: Fri, 27 Jun 2014 13:52:20 +0200 Subject: 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 | 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 index b127142..90115e5 100644 --- a/Lib/asyncio/base_events.py +++ b/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) 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 @@ __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): 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 @@ 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) 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 @@ 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') diff --git a/Lib/test/test_asyncio/test_base_events.py b/Lib/test/test_asyncio/test_base_events.py index 6ad0804..adba082 100644 --- a/Lib/test/test_asyncio/test_base_events.py +++ b/Lib/test/test_asyncio/test_base_events.py @@ -406,19 +406,22 @@ class BaseEventLoopTests(test_utils.TestCase): 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 index d3dbd3a..beb6cec 100644 --- a/Lib/test/test_asyncio/test_events.py +++ b/Lib/test/test_asyncio/test_events.py @@ -1751,10 +1751,11 @@ def noop(*args): 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 @@ class HandleTests(unittest.TestCase): 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 @@ class HandleTests(unittest.TestCase): % (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 index 8485a5e..ee87261 100644 --- 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 @@ class FutureTests(test_utils.TestCase): 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: \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 index c5eb92b..54b29ba 100644 --- a/Lib/test/test_asyncio/test_tasks.py +++ b/Lib/test/test_asyncio/test_tasks.py @@ -1546,6 +1546,7 @@ class TaskTests(test_utils.TestCase): 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 @@ class TaskTests(test_utils.TestCase): # 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 @@ class TaskTests(test_utils.TestCase): 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 @@ class TaskTests(test_utils.TestCase): 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: -- cgit v0.12