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.