asyncio.wait_for() TimeoutError doesn't provide full traceback

[cjerdonek]

BPO	31131
Nosy	@cjerdonek, @1st1, @SurenNihalani
Superseder	bpo-31033: Improve traceback of cancelled tasks / add cancel() msg argument

^{Note: these values reflect the state of the issue at the time it was migrated and might not reflect the current state.}

Show more details

GitHub fields:

assignee = None
closed_at = <Date 2020-05-18.06:06:59.249>
created_at = <Date 2017-08-07.11:06:35.168>
labels = ['type-bug', 'library', '3.9', 'expert-asyncio']
title = "asyncio.wait_for() TimeoutError doesn't provide full traceback"
updated_at = <Date 2020-05-18.06:06:59.248>
user = 'https://github.com/cjerdonek'

bugs.python.org fields:

activity = <Date 2020-05-18.06:06:59.248>
actor = 'chris.jerdonek'
assignee = 'none'
closed = True
closed_date = <Date 2020-05-18.06:06:59.249>
closer = 'chris.jerdonek'
components = ['Library (Lib)', 'asyncio']
creation = <Date 2017-08-07.11:06:35.168>
creator = 'chris.jerdonek'
dependencies = []
files = []
hgrepos = []
issue_num = 31131
keywords = []
message_count = 3.0
messages = ['299845', '302909', '369182']
nosy_count = 3.0
nosy_names = ['chris.jerdonek', 'yselivanov', 'snihalani']
pr_nums = []
priority = 'normal'
resolution = 'duplicate'
stage = 'resolved'
status = 'closed'
superseder = '31033'
type = 'behavior'
url = 'https://bugs.python.org/issue31131'
versions = ['Python 3.9']

[cjerdonek]

In Python 3.6.1, if asyncio.wait_for() times out with a TimeoutError, the traceback doesn't show what line the code was waiting on when the timeout occurred. This makes it more difficult to diagnose the cause of a timeout.

To reproduce, you can use the following code:

    import asyncio

    async def run():
        print('running...')
        await asyncio.sleep(1000000)

    def main(coro):
        loop = asyncio.new_event_loop()
        future = asyncio.wait_for(coro, timeout=1)
        loop.run_until_complete(future)

    main(run())

It gives the following output (notice that the sleep() line is missing):

    $ python test-timeouterror.py 
    running...
    Traceback (most recent call last):
      File "test-timeouterror.py", line 12, in <module>
        main(run())
      File "test-timeouterror.py", line 10, in main
        loop.run_until_complete(future)
      File "/Users/.../python3.6/asyncio/base_events.py", line 466,
         in run_until_complete
        return future.result()
      File "/Users/.../python3.6/asyncio/tasks.py", line 356, in wait_for
        raise futures.TimeoutError()
    concurrent.futures._base.TimeoutError

It seems like it should be possible to show the full traceback because, for example, if I register a signal handler with loop.add_signal_handler() as described here:
https://mail.python.org/pipermail/async-sig/2017-August/000374.html
and press Control-C before the timeout occurs, I do get a full traceback showing the line:

await asyncio.sleep(1000000)

[SurenNihalani]

this'd be useful to me as well. I'd propose we pass the future in the exception object.

Can write a write a tiny patch for this if someone would approve.

[cjerdonek]

This issue was just resolved by the combination of bpo-40607 followed by bpo-31033 (merged for 3.9.0 beta 1).

Running the example code above now results in the following:

Traceback (most recent call last):
  File "/.../cpython/test-31131.py", line 5, in run
    await asyncio.sleep(1000000)
  File "/.../cpython/Lib/asyncio/tasks.py", line 669, in sleep
    return await future
asyncio.exceptions.CancelledError

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/.../cpython/Lib/asyncio/tasks.py", line 507, in wait_for
    fut.result()
asyncio.exceptions.CancelledError

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/.../cpython/test-31131.py", line 15, in <module>
    main(run())
  File "/.../cpython/test-31131.py", line 11, in main
    loop.run_until_complete(future)
  File "/.../cpython/Lib/asyncio/base_events.py", line 642, in run_until_complete
    return future.result()
  File "/.../cpython/Lib/asyncio/tasks.py", line 509, in wait_for
    raise exceptions.TimeoutError() from exc
asyncio.exceptions.TimeoutError

As you can see the traceback now includes the exception chain from the TimeoutError to the point of interruption: await asyncio.sleep(1000000).