classification
Title: asyncio.wait_for() TimeoutError doesn't provide full traceback
Type: behavior Stage: resolved
Components: asyncio, Library (Lib) Versions: Python 3.9
process
Status: closed Resolution: duplicate
Dependencies: Superseder: Improve traceback of cancelled tasks / add cancel() msg argument
View: 31033
Assigned To: Nosy List: chris.jerdonek, snihalani, yselivanov
Priority: normal Keywords:

Created on 2017-08-07 11:06 by chris.jerdonek, last changed 2020-05-18 06:06 by chris.jerdonek. This issue is now closed.

Messages (3)
msg299845 - (view) Author: Chris Jerdonek (chris.jerdonek) * (Python committer) Date: 2017-08-07 11:06
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)
msg302909 - (view) Author: Suren Nihalani (snihalani) * Date: 2017-09-25 03:16
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.
msg369182 - (view) Author: Chris Jerdonek (chris.jerdonek) * (Python committer) Date: 2020-05-18 06:06
This issue was just resolved by the combination of #40607 followed by #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).
History
Date User Action Args
2020-05-18 06:06:59chris.jerdoneksetstatus: open -> closed
versions: + Python 3.9, - Python 3.6
superseder: Improve traceback of cancelled tasks / add cancel() msg argument
messages: + msg369182

resolution: duplicate
stage: resolved
2017-09-25 03:16:32snihalanisetnosy: + snihalani
messages: + msg302909
2017-08-07 11:06:35chris.jerdonekcreate