Re: [Async-sig] Simplifying stack traces for tasks?

[Mark E. Haase]

Thanks for the feedback! I put this aside for a while but I'm coming back
to it now and cleaning it up.

The approach used in this first post was obviously very clumsy. In my
latest version I am using module instance directly (as shown in Nathaniel's
reply) and using the qualified package name (as suggested by Roger). I
created an explicit blacklist (incomplete--still needs more testing) of
functions to hide in my custom backtraces and refactored a bit so I can
write tests for it. Code below.

One interesting thing I learned while working on this is that the
backtraces change depending on the asyncio debug mode, because in debug
mode couroutines are wrapped in CoroWrapper[1], which adds a frame
everytime a coroutine sends, throws, etc. So I am now thinking that my
custom excepthook is probably most useful in debug mode, but probably not
good to enable in production.

I'm working on a more general asyncio task group library that will include
this excepthook. I'll release the whole thing on PyPI when it's done.

[1]
https://github.com/python/cpython/blob/23ab5ee667a9b29014f6f7f01797c611f63ff743/Lib/asyncio/coroutines.py#L25

---


def _async_excepthook(type_, exc, tb):
'''
An ``excepthook`` that hides event loop internals and displays
task group information.

:param type type_: the exception type
:param Exception exc: the exception itself
:param tb tb: a traceback of the exception
'''
print(_async_excepthook_format(type_, exc, tb))


def _async_excepthook_format(type_, exc, tb):
'''
This helper function is used for testing.

:param type type_: the exception type
:param Exception exc: the exception itself
:param tracetack tb: a traceback of the exception
:return: the formatted traceback as a string
'''
format_str = ''
cause_exc = None
cause_str = None

if exc.__cause__ is not None:
cause_exc = exc.__cause__
cause_str = 'The above exception was the direct cause ' \
'of the following exception:'
elif exc.__context__ is not None and not exc.__suppress_context__:
cause_exc = exc.__context__
cause_str = '\nDuring handling of the above exception, ' \
'another exception occurred:'

if cause_exc:
format_str += _async_excepthook_format(type(cause_exc), cause_exc,
cause_exc.__traceback__)

if cause_str:
format_str += '\n{}\n\n'.format(cause_str)

format_str += 'Async Traceback (most recent call last):\n'

# Need file, line, function, text
for frame, line_no in traceback.walk_tb(tb):
if _async_excepthook_exclude(frame):
format_str += '  ---\n'
else:
code = frame.f_code
filename = code.co_filename
line = linecache.getline(filename, line_no).strip()
format_str += '  File "{}", line {}, in {}\n' \
.format(filename, line_no, code.co_name)
format_str += '{}\n'.format(line)

format_str += '{}: {}'.format(type_.__name__, exc)
return format_str


_ASYNC_EXCEPTHOOK_BLACKLIST = {
'asyncio.base_events': ('_run_once', 'call_later', 'call_soon'),
'asyncio.coroutines': ('__next__', 'send', 'throw'),
'asyncio.events': ('__init__', '_run'),
'asyncio.tasks': ('_step', '_wakeup'),
'traceback': ('extract', 'extract_stack'),
}

def _async_excepthook_exclude(frame):
''' Return True if ``frame`` should be excluded from tracebacks. '''
module = frame.f_globals['__name__']
function = frame.f_code.co_name
return module in _ASYNC_EXCEPTHOOK_BLACKLIST and \
 function in _ASYNC_EXCEPTHOOK_BLACKLIST[module]


On Tue, Nov 14, 2017 at 7:15 PM, Nathaniel Smith  wrote:

> On Tue, Nov 14, 2017 at 2:00 PM, Roger Pate  wrote:
> > On Tue, Nov 14, 2017 at 9:54 AM, Mark E. Haase 
> wrote:
> > ...
> >> print('Async Traceback (most recent call last):')
> >> for frame in traceback.extract_tb(tb):
> >> head, tail = os.path.split(frame.filename)
> >> if (head.endswith('asyncio') or tail == 'traceback.py') and
> \
> >> frame.name.startswith('_'):
> > ...
> >> The meat of it is towards the bottom, "if head.endswith('asyncio')..."
> There
> >> are a lot of debatable details and this implementation is pretty hacky
> and
> >> clumsy, but I have found it valuable in my own usage, and I haven't yet
> >> missed the omitted stack frames.
> >
> > It would be better to determine if the qualified module name is
> > "traceback" or starts with "asyncio." (or topmost package is
> > "asyncio", etc.) rather than allow false positives for
> > random_package.asyncio.module._any_function or
> > random_package.traceback._any_function.  I don't see an easy way to
> > get the module object at this point in your hook; however:
>
> You can't get the module from the cooked data that extract_tb returns,
> but it's there in 

Re: [Async-sig] Simplifying stack traces for tasks?

[Nathaniel Smith]

On Tue, Nov 14, 2017 at 6:54 AM, Mark E. Haase  wrote:
> If an exception is thrown while the `asyncio` event loop is running, the
> stack trace is pretty complicated. Here's an example:
>
[...]
>
> I'm posting here to get constructive criticism on the concept and would also
> like to hear if Curio or Trio have done anything like this. (Based on a
> quick skim of the docs, I don't think they are.) I might publish a PyPI
> package if anybody is interested.

Trio does jump through hoops to try to make its tracebacks more
readable, but so far this is mostly aimed at cases where there are
multiple exceptions happening concurrently, and there is still an
unpleasant amount of internal gibberish that can overwhelm the parts
the user actually cares about. Doing something about this is on my
todo list [1], and it shouldn't be *too* hard given that Trio already
has to take over sys.excepthook, but I'm not 100% sure how to best
track which frames are pure bookkeeping noise and which are
interesting -- it's a bit more subtle than just "in the trio namespace
or not". (I'd also like to annotate the traceback with more
information, e.g. showing where an exception jumped between tasks.)

Messing with tracebacks like this does feel a bit weird, but async
libraries are in a weird position. The interpreter hides traceback
lines all the time, because every time you go into C then the
traceback disappears; Python's tracebacks are specifically designed to
show user code, not interpreter internals. Async libraries are doing
the same work the interpreter does, like implementing exception
propagation machinery, but they're doing it in Python code, so it
messes up the normal heuristic that C = low-level interpreter
machinery, Python = user code.

-n

[1] https://github.com/python-trio/trio/issues/56

-- 
Nathaniel J. Smith -- https://vorpus.org
___
Async-sig mailing list
Async-sig@python.org
https://mail.python.org/mailman/listinfo/async-sig
Code of Conduct: https://www.python.org/psf/codeofconduct/

Re: [Async-sig] Simplifying stack traces for tasks?

[Roger Pate]

On Tue, Nov 14, 2017 at 9:54 AM, Mark E. Haase  wrote:
...
> print('Async Traceback (most recent call last):')
> for frame in traceback.extract_tb(tb):
> head, tail = os.path.split(frame.filename)
> if (head.endswith('asyncio') or tail == 'traceback.py') and \
> frame.name.startswith('_'):
...
> The meat of it is towards the bottom, "if head.endswith('asyncio')..."There
> are a lot of debatable details and this implementation is pretty hacky and
> clumsy, but I have found it valuable in my own usage, and I haven't yet
> missed the omitted stack frames.

It would be better to determine if the qualified module name is
"traceback" or starts with "asyncio." (or topmost package is
"asyncio", etc.) rather than allow false positives for
random_package.asyncio.module._any_function or
random_package.traceback._any_function.  I don't see an easy way to
get the module object at this point in your hook; however:

import asyncio, traceback
excluded = [
asyncio.__file__[-len(os.path.basename(asyncio.__file__)):],  #
preserve existing separator to attempt being platform-agnostic
traceback.__file__,
]
...
for frame in traceback.extract_tb(tb):
if not any(frame.filename.startswith(x) for x in excluded) and
frame.name.startswith("_"):

Functions starting with "_" in any module can now be excluded from
tracebacks.  I'm not fond of this implementation, but I hope it serves
to illustrate.
___
Async-sig mailing list
Async-sig@python.org
https://mail.python.org/mailman/listinfo/async-sig
Code of Conduct: https://www.python.org/psf/codeofconduct/

Re: [Async-sig] Simplifying stack traces for tasks?

[Mark E. Haase]

I'm not asking to change Python's default behavior. I'm asking if anybody
else likes this idea, has ideas to make it better, and would use it if I
published some form of it on PyPI.

On Tue, Nov 14, 2017 at 10:08 AM, Andrew Svetlov 
wrote:

> AFAIK Python never hides stdlib codelines in tracebacks.
> Why we should start to do it in asyncio?
>
> On Tue, Nov 14, 2017 at 4:54 PM Mark E. Haase  wrote:
>
>> If an exception is thrown while the `asyncio` event loop is running, the
>> stack trace is pretty complicated. Here's an example:
>>
>> Traceback (most recent call last):
>>   File "sample_client.py", line 616, in 
>> loop.run_until_complete(main_task)
>>   File "/usr/lib/python3.6/asyncio/base_events.py", line 437, in
>> run_until_complete
>> self.run_forever()
>>   File "/usr/lib/python3.6/asyncio/base_events.py", line 405, in
>> run_forever
>> self._run_once()
>>   File "/usr/lib/python3.6/asyncio/base_events.py", line 1382, in
>> _run_once
>> handle._run()
>>   File "/usr/lib/python3.6/asyncio/events.py", line 126, in _run
>> self._callback(*self._args)
>>   File "/usr/lib/python3.6/asyncio/tasks.py", line 315, in _wakeup
>> self._step()
>>   File "/usr/lib/python3.6/asyncio/tasks.py", line 239, in _step
>> result = coro.send(None)
>>   File "sample_client.py", line 319, in main
>> await actions[args.action](args, socket)
>>   File "/usr/lib/python3.6/asyncio/coroutines.py", line 105, in
>> __next__
>> return self.gen.send(None)
>>   File "sample_client.py", line 558, in sync_job
>> await asyncio.sleep(args.delay)
>>   File "/usr/lib/python3.6/asyncio/coroutines.py", line 105, in
>> __next__
>> return self.gen.send(None)
>>   File "/usr/lib/python3.6/asyncio/tasks.py", line 522, in sleep
>> future, result)
>>   File "/usr/lib/python3.6/asyncio/base_events.py", line 525, in
>> call_later
>> timer = self.call_at(self.time() + delay, callback, *args)
>>   File "/usr/lib/python3.6/asyncio/base_events.py", line 541, in
>> call_at
>> timer = events.TimerHandle(when, callback, args, self)
>>   File "/usr/lib/python3.6/asyncio/events.py", line 148, in __init__
>> super().__init__(callback, args, loop)
>>   File "/usr/lib/python3.6/asyncio/events.py", line 92, in __init__
>> self._source_traceback = traceback.extract_stack(sys._
>> getframe(1))
>>   File "/usr/lib/python3.6/traceback.py", line 207, in extract_stack
>> stack = StackSummary.extract(walk_stack(f), limit=limit)
>>   File "/usr/lib/python3.6/traceback.py", line 352, in extract
>> filename, lineno, name, lookup_line=False, locals=f_locals))
>> KeyboardInterrupt
>>
>> Most of the stack frames are inside asyncio (_run, _wakeup, _step) and
>> reveal the mechanics of the event loop. The stack trace would be a lot
>> easier to read (and more similar to a stack trace of an equivalent
>> synchronous program) if it looked like this:
>>
>> Traceback (most recent call last):
>>   File "sample_client.py", line 616, in 
>> loop.run_until_complete(main_task)
>>   ...
>>   File "sample_client.py", line 319, in main
>> await actions[args.action](args, socket)
>>   ...
>>   File "sample_client.py", line 558, in sync_job
>> await asyncio.sleep(args.delay)
>> KeyboardInterrupt
>>
>> I recognize that the event loop mechanics are probably useful in some
>> circumstances, but in my experience working with asyncio for the last year,
>> I've found the stack traces are generally too noisy. For a while, I was
>> pasting stack traces into a text editor and cleaning them up by hand, but a
>> few months ago I wrote a custom excepthook that generates stack traces
>> similar to the one above.
>>
>> def async_excepthook(type_, exc, tb):
>> cause_exc = None
>> cause_str = None
>>
>> if exc.__cause__ is not None:
>> cause_exc = exc.__cause__
>> cause_str = 'The above exception was the direct cause ' \
>> 'of the following exception:'
>> elif exc.__context__ is not None and not exc.__suppress_context__:
>> cause_exc = exc.__context__
>> cause_str = 'During handling of the above exception, ' \
>> 'another exception occurred:'
>>
>> if cause_exc:
>> async_excepthook(type(cause_exc), cause_exc,
>> cause_exc.__traceback__)
>>
>> if cause_str:
>> print('\n{}\n'.format(cause_str))
>>
>> print('Async Traceback (most recent call last):')
>> for frame in traceback.extract_tb(tb):
>> head, tail = os.path.split(frame.filename)
>> if (head.endswith('asyncio') or tail == 'traceback.py') and \
>> frame.name.startswith('_'):
>> print('  ...')
>> 

Re: [Async-sig] Simplifying stack traces for tasks?

[Andrew Svetlov]

AFAIK Python never hides stdlib codelines in tracebacks.
Why we should start to do it in asyncio?

On Tue, Nov 14, 2017 at 4:54 PM Mark E. Haase  wrote:

> If an exception is thrown while the `asyncio` event loop is running, the
> stack trace is pretty complicated. Here's an example:
>
> Traceback (most recent call last):
>   File "sample_client.py", line 616, in 
> loop.run_until_complete(main_task)
>   File "/usr/lib/python3.6/asyncio/base_events.py", line 437, in
> run_until_complete
> self.run_forever()
>   File "/usr/lib/python3.6/asyncio/base_events.py", line 405, in
> run_forever
> self._run_once()
>   File "/usr/lib/python3.6/asyncio/base_events.py", line 1382, in
> _run_once
> handle._run()
>   File "/usr/lib/python3.6/asyncio/events.py", line 126, in _run
> self._callback(*self._args)
>   File "/usr/lib/python3.6/asyncio/tasks.py", line 315, in _wakeup
> self._step()
>   File "/usr/lib/python3.6/asyncio/tasks.py", line 239, in _step
> result = coro.send(None)
>   File "sample_client.py", line 319, in main
> await actions[args.action](args, socket)
>   File "/usr/lib/python3.6/asyncio/coroutines.py", line 105, in
> __next__
> return self.gen.send(None)
>   File "sample_client.py", line 558, in sync_job
> await asyncio.sleep(args.delay)
>   File "/usr/lib/python3.6/asyncio/coroutines.py", line 105, in
> __next__
> return self.gen.send(None)
>   File "/usr/lib/python3.6/asyncio/tasks.py", line 522, in sleep
> future, result)
>   File "/usr/lib/python3.6/asyncio/base_events.py", line 525, in
> call_later
> timer = self.call_at(self.time() + delay, callback, *args)
>   File "/usr/lib/python3.6/asyncio/base_events.py", line 541, in
> call_at
> timer = events.TimerHandle(when, callback, args, self)
>   File "/usr/lib/python3.6/asyncio/events.py", line 148, in __init__
> super().__init__(callback, args, loop)
>   File "/usr/lib/python3.6/asyncio/events.py", line 92, in __init__
> self._source_traceback = traceback.extract_stack(sys._getframe(1))
>   File "/usr/lib/python3.6/traceback.py", line 207, in extract_stack
> stack = StackSummary.extract(walk_stack(f), limit=limit)
>   File "/usr/lib/python3.6/traceback.py", line 352, in extract
> filename, lineno, name, lookup_line=False, locals=f_locals))
> KeyboardInterrupt
>
> Most of the stack frames are inside asyncio (_run, _wakeup, _step) and
> reveal the mechanics of the event loop. The stack trace would be a lot
> easier to read (and more similar to a stack trace of an equivalent
> synchronous program) if it looked like this:
>
> Traceback (most recent call last):
>   File "sample_client.py", line 616, in 
> loop.run_until_complete(main_task)
>   ...
>   File "sample_client.py", line 319, in main
> await actions[args.action](args, socket)
>   ...
>   File "sample_client.py", line 558, in sync_job
> await asyncio.sleep(args.delay)
> KeyboardInterrupt
>
> I recognize that the event loop mechanics are probably useful in some
> circumstances, but in my experience working with asyncio for the last year,
> I've found the stack traces are generally too noisy. For a while, I was
> pasting stack traces into a text editor and cleaning them up by hand, but a
> few months ago I wrote a custom excepthook that generates stack traces
> similar to the one above.
>
> def async_excepthook(type_, exc, tb):
> cause_exc = None
> cause_str = None
>
> if exc.__cause__ is not None:
> cause_exc = exc.__cause__
> cause_str = 'The above exception was the direct cause ' \
> 'of the following exception:'
> elif exc.__context__ is not None and not exc.__suppress_context__:
> cause_exc = exc.__context__
> cause_str = 'During handling of the above exception, ' \
> 'another exception occurred:'
>
> if cause_exc:
> async_excepthook(type(cause_exc), cause_exc,
> cause_exc.__traceback__)
>
> if cause_str:
> print('\n{}\n'.format(cause_str))
>
> print('Async Traceback (most recent call last):')
> for frame in traceback.extract_tb(tb):
> head, tail = os.path.split(frame.filename)
> if (head.endswith('asyncio') or tail == 'traceback.py') and \
> frame.name.startswith('_'):
> print('  ...')
> continue
> print('  File "{}", line {}, in {}'
> .format(frame.filename, frame.lineno, frame.name))
> print('{}'.format(frame.line))
> print('{}: {}'.format(type_.__name__, exc))
>
> The meat of it is towards the bottom, "if
> head.endswith('asyncio')..."There are a lot of debatable details and this
> 

[Async-sig] Simplifying stack traces for tasks?

[Mark E. Haase]

If an exception is thrown while the `asyncio` event loop is running, the
stack trace is pretty complicated. Here's an example:

Traceback (most recent call last):
  File "sample_client.py", line 616, in 
loop.run_until_complete(main_task)
  File "/usr/lib/python3.6/asyncio/base_events.py", line 437, in
run_until_complete
self.run_forever()
  File "/usr/lib/python3.6/asyncio/base_events.py", line 405, in
run_forever
self._run_once()
  File "/usr/lib/python3.6/asyncio/base_events.py", line 1382, in
_run_once
handle._run()
  File "/usr/lib/python3.6/asyncio/events.py", line 126, in _run
self._callback(*self._args)
  File "/usr/lib/python3.6/asyncio/tasks.py", line 315, in _wakeup
self._step()
  File "/usr/lib/python3.6/asyncio/tasks.py", line 239, in _step
result = coro.send(None)
  File "sample_client.py", line 319, in main
await actions[args.action](args, socket)
  File "/usr/lib/python3.6/asyncio/coroutines.py", line 105, in __next__
return self.gen.send(None)
  File "sample_client.py", line 558, in sync_job
await asyncio.sleep(args.delay)
  File "/usr/lib/python3.6/asyncio/coroutines.py", line 105, in __next__
return self.gen.send(None)
  File "/usr/lib/python3.6/asyncio/tasks.py", line 522, in sleep
future, result)
  File "/usr/lib/python3.6/asyncio/base_events.py", line 525, in
call_later
timer = self.call_at(self.time() + delay, callback, *args)
  File "/usr/lib/python3.6/asyncio/base_events.py", line 541, in call_at
timer = events.TimerHandle(when, callback, args, self)
  File "/usr/lib/python3.6/asyncio/events.py", line 148, in __init__
super().__init__(callback, args, loop)
  File "/usr/lib/python3.6/asyncio/events.py", line 92, in __init__
self._source_traceback = traceback.extract_stack(sys._getframe(1))
  File "/usr/lib/python3.6/traceback.py", line 207, in extract_stack
stack = StackSummary.extract(walk_stack(f), limit=limit)
  File "/usr/lib/python3.6/traceback.py", line 352, in extract
filename, lineno, name, lookup_line=False, locals=f_locals))
KeyboardInterrupt

Most of the stack frames are inside asyncio (_run, _wakeup, _step) and
reveal the mechanics of the event loop. The stack trace would be a lot
easier to read (and more similar to a stack trace of an equivalent
synchronous program) if it looked like this:

Traceback (most recent call last):
  File "sample_client.py", line 616, in 
loop.run_until_complete(main_task)
  ...
  File "sample_client.py", line 319, in main
await actions[args.action](args, socket)
  ...
  File "sample_client.py", line 558, in sync_job
await asyncio.sleep(args.delay)
KeyboardInterrupt

I recognize that the event loop mechanics are probably useful in some
circumstances, but in my experience working with asyncio for the last year,
I've found the stack traces are generally too noisy. For a while, I was
pasting stack traces into a text editor and cleaning them up by hand, but a
few months ago I wrote a custom excepthook that generates stack traces
similar to the one above.

def async_excepthook(type_, exc, tb):
cause_exc = None
cause_str = None

if exc.__cause__ is not None:
cause_exc = exc.__cause__
cause_str = 'The above exception was the direct cause ' \
'of the following exception:'
elif exc.__context__ is not None and not exc.__suppress_context__:
cause_exc = exc.__context__
cause_str = 'During handling of the above exception, ' \
'another exception occurred:'

if cause_exc:
async_excepthook(type(cause_exc), cause_exc,
cause_exc.__traceback__)

if cause_str:
print('\n{}\n'.format(cause_str))

print('Async Traceback (most recent call last):')
for frame in traceback.extract_tb(tb):
head, tail = os.path.split(frame.filename)
if (head.endswith('asyncio') or tail == 'traceback.py') and \
frame.name.startswith('_'):
print('  ...')
continue
print('  File "{}", line {}, in {}'
.format(frame.filename, frame.lineno, frame.name))
print('{}'.format(frame.line))
print('{}: {}'.format(type_.__name__, exc))

The meat of it is towards the bottom, "if head.endswith('asyncio')..."There
are a lot of debatable details and this implementation is pretty hacky and
clumsy, but I have found it valuable in my own usage, and I haven't yet
missed the omitted stack frames.

I'm posting here to get constructive criticism on the concept and would
also like to hear if Curio or Trio have done anything like this. (Based on
a quick skim of the docs, I don't think they are.) I might publish a PyPI
package if anybody is