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.

4 files changed, 113 insertions, 6 deletions

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: <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
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: