[Python-checkins] cpython (3.4): asyncio, Tulip issue 137: In debug mode, save traceback where Future, Task and

27 Jun 2014

http://hg.python.org/cpython/rev/8fb489a8eb28
changeset:   91444:8fb489a8eb28
branch:      3.4
parent:      91442:84816348e809
user:        Victor Stinner <victor.stinner@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

    