Save the traceback where a Future/Task was created

Save the traceback where a Future/Task was created

[yselivanov, 2014-02-18 19:06:02]

https://codereview.appspot.com/64900043/diff/1/asyncio/futures.py File asyncio/futures.py (right): https://codereview.appspot.com/64900043/diff/1/asyncio/futures.py#newcode199 asyncio/futures.py:199: '%s' I would make it more obvious how two tracebacks are different, i.e. something akin to: Created at: TB Actual traceback: TB2

[haypo_gmail, 2014-02-18 22:51:39]

https://codereview.appspot.com/64900043/diff/1/asyncio/futures.py File asyncio/futures.py (right): https://codereview.appspot.com/64900043/diff/1/asyncio/futures.py#newcode199 asyncio/futures.py:199: '%s' On 2014/02/18 19:06:02, yselivanov wrote: > I would make it more obvious how two tracebacks are different, i.e. something > akin to: > > Created at: > TB > > Actual traceback: > TB2 I agree that the current output is confusing.

[GvR, 2014-02-20 00:59:20]

This change is too late for 3.4.

[haypo_gmail, 2014-02-20 01:13:32]

On 2014/02/20 00:59:20, GvR wrote: > This change is too late for 3.4. Oh :-( The patch looks simple, why is it too late? When I discovered asyncio, I expected much easier debug than Twisted. In Twisted, the control flow is splitted in multiple callbacks, it's a pain to reconnect manually logs to understand what happened. In fact, it's almost the same with asyncio, you don't know the beginning of a task (where it was created), only the end, the traceback of the exception. On a trivial example, it's easy to understand what happened: http://docs.python.org/dev/library/asyncio-dev.html#detect-exceptions-not-con... On a real application, it's probably much harder. The set_debug() will feel alone without an user of the new _debug flag! (you already reused to use in _run_once) :-)

[GvR, 2014-02-20 02:03:22]

On 2014/02/20 01:13:32, haypo_gmail wrote: > On 2014/02/20 00:59:20, GvR wrote: > > This change is too late for 3.4. > > Oh :-( The patch looks simple, why is it too late? It doesn't look simple to me. > When I discovered asyncio, I expected much easier debug than Twisted. In > Twisted, the control flow is splitted in multiple callbacks, it's a pain to > reconnect manually logs to understand what happened. In fact, it's almost the > same with asyncio, you don't know the beginning of a task (where it was > created), only the end, the traceback of the exception. > > On a trivial example, it's easy to understand what happened: > http://docs.python.org/dev/library/asyncio-dev.html#detect-exceptions-not-con... > > On a real application, it's probably much harder. Understood, but I have debugged a fair number of asyncio apps and found it doable. The tracebacks that you do get are quite useful, usually. > The set_debug() will feel alone without an user of the new _debug flag! (you > already reused to use in _run_once) :-) The set/get_debug() patch was an API change. But this patch just changes the debugging experience, so we can do it in 3.4.1.

[yselivanov, 2014-02-20 05:12:06]

Couple of notes, one is pretty major. https://codereview.appspot.com/64900043/diff/40001/asyncio/futures.py File asyncio/futures.py (right): https://codereview.appspot.com/64900043/diff/40001/asyncio/futures.py#newcode46 asyncio/futures.py:46: msg += ('\n' I'd put '\n\n' here, otherwise it's still hard to read the output... https://codereview.appspot.com/64900043/diff/40001/asyncio/futures.py#newcode205 asyncio/futures.py:205: _log_unhandled_exception(self, self._create_tb, exc_tb, self._loop) I don't like that we are not passing 'exception' in context anymore. Please fix this.

[haypo_gmail, 2014-02-20 08:02:26]

https://codereview.appspot.com/64900043/diff/40001/asyncio/futures.py File asyncio/futures.py (right): https://codereview.appspot.com/64900043/diff/40001/asyncio/futures.py#newcode46 asyncio/futures.py:46: msg += ('\n' On 2014/02/20 05:12:06, yselivanov wrote: > I'd put '\n\n' here, otherwise it's still hard to read the output... Agreed. https://codereview.appspot.com/64900043/diff/40001/asyncio/futures.py#newcode205 asyncio/futures.py:205: _log_unhandled_exception(self, self._create_tb, exc_tb, self._loop) On 2014/02/20 05:12:06, yselivanov wrote: > I don't like that we are not passing 'exception' in context anymore. Please fix > this. I don't see how I could pass exception without logging it twice. Or the output should be reversed: --- Future/Task created at (most recent call last): ... Future/Task exception was never retrieved (most recent call last): <end filled by exception> ---

[haypo_gmail, 2014-02-20 08:03:59]

2014-02-20 3:03 GMT+01:00 <gvanrossum@gmail.com>: > The set/get_debug() patch was an API change. But this patch just changes > the debugging experience, so we can do it in 3.4.1. After thinking twice, you're right. It's perfectly fine to wait for 3.4.1 since it's not an API change, but "just" add more debug logs. Sorry, I'm stressed by any kind of deadline :-) 

[yselivanov, 2014-02-20 16:06:49]

https://codereview.appspot.com/64900043/diff/40001/asyncio/futures.py File asyncio/futures.py (right): https://codereview.appspot.com/64900043/diff/40001/asyncio/futures.py#newcode205 asyncio/futures.py:205: _log_unhandled_exception(self, self._create_tb, exc_tb, self._loop) > I don't see how I could pass exception without logging it twice Well, then rewrite your code. Let the default exception handler do its job, and provide the second traceback as an extra key in the context. We can modify 'default_exception_handler' to print str objects in 'context' as is (not repr) Exception objects are important. It's not just a formatted traceback -- its __context__ and __cause__ chains, it's attributes (like OSError.errno), etc. So omitting exception object from 'context' is *not* an option.