Log tracebakcs for handles in debug mode

Author: 1st1

tests/test_base.py

@@ -64,6 +64,44 @@ def cb():
 
         self.assertFalse(self.loop.is_closed())
 
+    def test_calls_debug_reporting(self):
+        def run_test(debug, meth, stack_adj):
+            context = None
+
+            def handler(loop, ctx):
+                nonlocal context
+                context = ctx
+
+            self.loop.set_debug(debug)
+            self.loop.set_exception_handler(handler)
+
+            def cb():
+                1 / 0
+
+            meth(cb)
+            self.assertIsNone(context)
+            self.loop.run_until_complete(asyncio.sleep(0.05, loop=self.loop))
+
+            self.assertIs(type(context['exception']), ZeroDivisionError)
+            self.assertTrue(context['message'].startswith(
+                'Exception in callback'))
+
+            if debug:
+                tb = context['source_traceback']
+                self.assertEqual(tb[-1 + stack_adj].name, 'run_test')
+            else:
+                self.assertFalse('source_traceback' in context)
+
+        for flag in (True, False):
+            for meth_name, meth, stack_adj in (
+                ('call_soon',
+                    self.loop.call_soon, 0),
+                ('call_later',  # `-1` accounts for lambda
+                    lambda *args: self.loop.call_later(0.01, *args), -1)
+            ):
+                with self.subTest(debug=flag, meth_name=meth_name):
+                    run_test(flag, meth, stack_adj)
+
     def test_now_update(self):
         async def run():
             st = self.loop.time()

uvloop/cbhandles.pxd

@@ -10,6 +10,8 @@ cdef class Handle:
 
         object __weakref__
 
+        readonly _source_traceback
+
     cdef inline _set_loop(self, Loop loop)
     cdef inline _run(self)
     cdef _cancel(self)
@@ -23,5 +25,7 @@ cdef class TimerHandle:
         Loop loop
         object __weakref__
 
+        readonly _source_traceback
+
     cdef _run(self)
     cdef _cancel(self)

uvloop/cbhandles.pyx

@@ -4,12 +4,15 @@ cdef class Handle:
     def __cinit__(self):
         self.cancelled = 0
         self.cb_type = 0
+        self._source_traceback = None
 
     cdef inline _set_loop(self, Loop loop):
         self.loop = loop
         IF DEBUG:
             loop._debug_cb_handles_total += 1
             loop._debug_cb_handles_count += 1
+        if loop._debug:
+            self._source_traceback = tb_extract_stack(sys_getframe(0))
 
     IF DEBUG:
         def __dealloc__(self):
@@ -78,10 +81,16 @@ cdef class Handle:
             else:
                 msg = 'Exception in callback {}'.format(self.meth_name)
 
-            self.loop.call_exception_handler({
+            context = {
                 'message': msg,
-                'exception': ex
-            })
+                'exception': ex,
+                'handle': self,
+            }
+
+            if self._source_traceback is not None:
+                context['source_traceback'] = self._source_traceback
+
+            self.loop.call_exception_handler(context)
 
         finally:
             self.loop._executing_py_code = old_exec_py_code
@@ -117,6 +126,9 @@ cdef class TimerHandle:
         self.args = args
         self.closed = 0
 
+        if loop._debug:
+            self._source_traceback = tb_extract_stack(sys_getframe(0))
+
         self.timer = UVTimer.new(
             loop, <method_t*>&self._run, self, delay)
 
@@ -173,10 +185,16 @@ cdef class TimerHandle:
             else:
                 callback()
         except Exception as ex:
-            self.loop.call_exception_handler({
+            context = {
                 'message': 'Exception in callback {}'.format(callback),
-                'exception': ex
-            })
+                'exception': ex,
+                'handle': self,
+            }
+
+            if self._source_traceback is not None:
+                context['source_traceback'] = self._source_traceback
+
+            self.loop.call_exception_handler(context)
         finally:
             self.loop._executing_py_code = old_exec_py_code
             Py_DECREF(self)

uvloop/loop.pyx

@@ -1587,10 +1587,16 @@ cdef class Loop:
             if key in {'message', 'exception'}:
                 continue
             value = context[key]
-            try:
-                value = repr(value)
-            except Exception as ex:
-                value = 'Exception in __repr__ {!r}'.format(ex)
+            if key == 'source_traceback':
+                tb = ''.join(tb_format_list(value))
+                value = 'Object created at (most recent call last):\n'
+                value += tb.rstrip()
+            else:
+                try:
+                    value = repr(value)
+                except Exception as ex:
+                    value = ('Exception in __repr__ {!r}; '
+                             'value type: {!r}'.format(ex, type(value)))
             log_lines.append('{}: {}'.format(key, value))
 
         aio_logger.error('\n'.join(log_lines), exc_info=exc_info)