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 <andrew.svetlov@gmail.com> 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 <mehaase@gmail.com> 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 <module> 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 <module> 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 interested.

Cheers, Mark _______________________________________________ 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/

-- Thanks, Andrew Svetlov

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/23ab5ee667a9b29014f6f7f01797c611f63ff... --- 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 <njs@pobox.com> wrote:

On Tue, Nov 14, 2017 at 2:00 PM, Roger Pate <rogerpate@gmail.com> wrote:

...

On Tue, Nov 14, 2017 at 9:54 AM, Mark E. Haase <mehaase@gmail.com> 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 the tb object itself. This walks the traceback and prints each frame's module:

current = tb while current is not None: print("Next module", current.tb_frame.f_globals.get("__name__")) current = current.tb_next

-n

-- Nathaniel J. Smith -- https://vorpus.org