classification
Title: Improve traceback of cancelled tasks / add cancel() msg argument
Type: enhancement Stage: resolved
Components: asyncio Versions: Python 3.9
process
Status: closed Resolution: fixed
Dependencies: Superseder:
Assigned To: Nosy List: carljm, chris.jerdonek, lukasz.langa, matrixise, miss-islington, socketpair, thehesiod, yselivanov
Priority: normal Keywords: patch

Created on 2017-07-25 13:21 by socketpair, last changed 2020-05-19 02:14 by lukasz.langa. This issue is now closed.

Pull Requests
URL Status Linked Edit
PR 19951 merged chris.jerdonek, 2020-05-06 11:06
PR 19979 merged chris.jerdonek, 2020-05-07 13:57
PR 20173 merged chris.jerdonek, 2020-05-18 11:49
PR 20202 merged miss-islington, 2020-05-19 01:53
Messages (23)
msg299079 - (view) Author: Марк Коренберг (socketpair) * Date: 2017-07-25 13:21
History:

First, I tried to debug code around asyncio.Task() cancelling. So I wrote:
=====
try:
   ...
except Exception as e:
   print(e)
=====

When task was cancelled, an empty string printed. I wondered why. So I change the code to

====
print(repr(e))
====

and it printed 'CancelledError' as expected.

Next, I tried:

====
print(Exception())
====

It prints empty string too!

So I came up to propose API change. I propose to add argument to the .cancel() methods (for Task and for Future). This argument should be passed to the CancelledError constructor. This will greatly improves debugging -- it allows to easily know why Future/Task was cancelled.

Also, this change does not break current code. Argument must be optional.
msg299083 - (view) Author: Yury Selivanov (yselivanov) * (Python committer) Date: 2017-07-25 13:48
Well, don't use "print(e)" when you are printing errors in in Python. This is pretty standard behaviour for all Python code, not just asyncio. A lot of code in stdlib raises exceptions, almost none allows to customize them.
msg299084 - (view) Author: Stéphane Wirtel (matrixise) * (Python committer) Date: 2017-07-25 13:50
you could use gdb or pdb for the debugging.
msg299101 - (view) Author: Марк Коренберг (socketpair) * Date: 2017-07-25 15:18
Yes, I agree with you about my weird way of debugging. But anyway, changing API with adding ability to pass actual cause would be welcome.
msg299103 - (view) Author: Yury Selivanov (yselivanov) * (Python committer) Date: 2017-07-25 15:21
> Yes, I agree with you about my weird way of debugging. But anyway, changing API with adding ability to pass actual cause would be welcome.

I'm not opposed to the idea, btw. If we do decide to add an argument to 'cancel', we probably should do the same for concurrent.futures.

Another possibility would be to allow cancellation via Future.set_exception:

  task.set_exception(asyncio.CancelledError('message'))
msg299107 - (view) Author: Марк Коренберг (socketpair) * Date: 2017-07-25 15:29
Hmmm....

task.set_exception(Exception('xxx'))

Will it cancel whole chain of depending futures in a RIGHT way ?
Or we must require exception passed here to be subclassed from CancelledError ?
msg299112 - (view) Author: Yury Selivanov (yselivanov) * (Python committer) Date: 2017-07-25 15:34
> Will it cancel whole chain of depending futures in a RIGHT way ?

I was thinking about this:

  def Future.set_exception(exc):
      if isinstance(exc, asyncio.CancelledError):
          return self._cancel(exc)
      # here goes old code

  def Future.cancel():
      return self._cancel(asyncio.CancelledError())

Although now, that I'm looking at it, I don't like this idea, because setting as exception is a different operation from cancelling a task/future, and we shouldn't mix them.  It's OK to set a CancelledError without cancelling.  Also this would be a backwards incompatible change.

So back to square one -- we can consider passing extra args to .cancel() methods.
msg299891 - (view) Author: Chris Jerdonek (chris.jerdonek) * (Python committer) Date: 2017-08-08 02:15
A couple thoughts on this issue:

First, I think the OP's original issue could perhaps largely be addressed without having to change cancel()'s signature. Namely, simply passing a hard-coded string to CancelledError in the couple spots that CancelledError is raised would cause the exception to display:

https://github.com/python/cpython/blob/733d0f63c562090a2b840859b96028d6ec0a4803/Lib/asyncio/futures.py#L153
https://github.com/python/cpython/blob/733d0f63c562090a2b840859b96028d6ec0a4803/Lib/asyncio/futures.py#L173

The "raise CancelledError" could be changed to "raise CancelledError('future is cancelled')", a bit like how InvalidStateError is handled a couple lines later:

    if self._state == _CANCELLED:
        raise CancelledError
    if self._state != _FINISHED:
        raise InvalidStateError('Result is not ready.')

Second, in terms of making cancellations easier to debug, is it a deliberate design decision that the CancelledError traceback "swallows" / doesn't show the point at which the coroutine was cancelled?

For example, running the following code--

    async def run():
        await asyncio.sleep(1000000)

    loop = asyncio.new_event_loop()
    task = asyncio.ensure_future(run(), loop=loop)
    loop.call_later(2, task.cancel)
    loop.run_until_complete(task)

Results in the following output:

    Traceback (most recent call last):
      File "test-cancel.py", line 46, in <module>
        loop.run_until_complete(task)
      File "/Users/.../python3.6/asyncio/base_events.py", line 466,
          in run_until_complete
        return future.result()
    concurrent.futures._base.CancelledError

In particular, it doesn't show that the task was waiting on asyncio.sleep(1000000) when the task was cancelled. It would be very useful to see full tracebacks in these cases. (Sorry in advance if this second point is off-topic for this issue.)
msg300152 - (view) Author: Марк Коренберг (socketpair) * Date: 2017-08-11 05:34
1. Yes, specifying argument to cancel in `raise CancelledError` would be perfect
2. specifying argument to `.cancel()` is still actual.
3. Yes, important part of exceptions should not be swallowed (please open separate issue). Also, it will be nice to show which code calls `.cancel()`, not only `sleep()` you menitioned.
msg314953 - (view) Author: Alexander Mohr (thehesiod) * Date: 2018-04-04 21:56
I was about to open a new bug, but I think my idea overlaps with this one.  From what I understand there are two ways to cancel tasks:

1) calling task.cancel()
2) explicitly raising a CancelledError

with #2 you can get a traceback by catching the exception which yields why the task was cancelled (per callstack, and you create the CancelledError with a custom message).

#1 I think is what this is talking about.

The most useful information IMHO is the callstack, and via #1 this callstack is completely lost.

I like the idea of having an argument to construct the CancelledError with, but I like even more the ability to tell the exception that will be raised to have the traceback of the point where the task was originally cancelled.

Right now I have to use forbidden fruit to override the Task.cancel method and store the callstack in a custom attribute.

I was talking with asvetlov and and he thought perhaps there could be an environment variable to enable this by default and then when the cancellation error is raised it can have the caller's callstack...I think ideally this would be the default if it could be done cheaply (given if a regular exception throw contains the callstack, then a cancellation exception should always as well.

Ideally I think when a task is cancelled it instantiates the exception with the callstack at that point, and then does something like a "with e" to raise the exception from the future so you get it when it's raised.
msg314954 - (view) Author: Yury Selivanov (yselivanov) * (Python committer) Date: 2018-04-04 22:04
> I like the idea of having an argument to construct the CancelledError with, but I like even more the ability to tell the exception that will be raised to have the traceback of the point where the task was originally cancelled.

Why don't we make CancelledErrors having proper traceback a default behaviour?
msg341967 - (view) Author: Alexander Mohr (thehesiod) * Date: 2019-05-09 05:33
@yselivanov even better :)
msg368236 - (view) Author: Chris Jerdonek (chris.jerdonek) * (Python committer) Date: 2020-05-06 11:22
I just posted a draft, proof-of-concept PR for one aspect of this issue: https://github.com/python/cpython/pull/19951

Namely, the PR makes it so that cancelled tasks have full tracebacks, all the way to where the code first gets interrupted. I did the C implementation, but I still need to do the pure Python implementation. (Note that it doesn't show where `task.cancel()` was *called*, but rather the first line of code that is cancelled. That other aspect can be handled in a separate PR.)

As an example, for this code--

    import asyncio

    async def nested():
        await asyncio.sleep(1)

    async def run():
        task = asyncio.create_task(nested())
        await asyncio.sleep(0)
        task.cancel()
        await task

    loop = asyncio.new_event_loop()
    try:
        loop.run_until_complete(run())
    finally:
        loop.close()

Python currently (before the PR) does this:

Traceback (most recent call last):
  File "/.../cpython/test-cancel.py", line 15, in <module>
    loop.run_until_complete(run())
  File "/.../cpython/Lib/asyncio/base_events.py", line 642, in run_until_complete
    return future.result()
asyncio.exceptions.CancelledError

With the PR, it looks like this. In particular, you can see that it includes "await asyncio.sleep(1)", as well as the intermediate await:

Traceback (most recent call last):
  File "/.../cpython/test-cancel.py", line 5, in nested
    await asyncio.sleep(1)
  File "/.../cpython/Lib/asyncio/tasks.py", line 657, in sleep
    return await future
asyncio.exceptions.CancelledError

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/.../cpython/test-cancel.py", line 11, in run
    await task
asyncio.exceptions.CancelledError

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/.../cpython/test-cancel.py", line 15, in <module>
    loop.run_until_complete(run())
  File "/.../cpython/Lib/asyncio/base_events.py", line 642, in run_until_complete
    return future.result()
asyncio.exceptions.CancelledError
msg368243 - (view) Author: Chris Jerdonek (chris.jerdonek) * (Python committer) Date: 2020-05-06 12:58
Okay, I completed my draft PR (both C and pure Python implementations are done).
msg368405 - (view) Author: Chris Jerdonek (chris.jerdonek) * (Python committer) Date: 2020-05-08 02:27
I also posted a second PR (separate from the first) that adds a "msg" argument to Future.cancel() and Task.cancel(). That PR is also now ready for review:
https://github.com/python/cpython/pull/19979

The other PR is simpler and more essential though, so I think should be reviewed before this.
msg368987 - (view) Author: Chris Jerdonek (chris.jerdonek) * (Python committer) Date: 2020-05-15 23:55
New changeset 1ce5841eca6d96b1b1e8c213d04f2e92b1619bb5 by Chris Jerdonek in branch 'master':
bpo-31033: Add a msg argument to Future.cancel() and Task.cancel() (GH-19979)
https://github.com/python/cpython/commit/1ce5841eca6d96b1b1e8c213d04f2e92b1619bb5
msg368988 - (view) Author: Chris Jerdonek (chris.jerdonek) * (Python committer) Date: 2020-05-16 00:00
The msg argument has now been added (second PR). I'm going to keep this issue open until the traceback issue has also been addressed (the other PR), as that was one part of the discussions here.
msg368993 - (view) Author: Chris Jerdonek (chris.jerdonek) * (Python committer) Date: 2020-05-16 01:06
I just want to flag one issue after rebasing my traceback PR onto what was merged. If task.cancel() is called like this--

    task.cancel("POSSIBLY LONG CANCEL MESSAGE")

There is the question of whether the passed message should be repeated each time the CancelledError is raised, or only show it in the innermost, originating exception. My preference is to do the latter because it is simpler, less verbose, and seems more correct from a Python perspective. But I wanted to flag this because the message won't be visible in the leading, outermost exception.

There is a third alternative which is to mutate the exception each time (delete the message from the earlier exception and add it to the new exception). But that seems more fraught and what I'd consider surprising behavior.

Lastly, to illustrate, here is the more verbose option (the one I think it **shouldn't** look like):

Traceback (most recent call last):
  File "/.../cpython/test-cancel.py", line 4, in nested
    await asyncio.sleep(1)
  File "/.../cpython/Lib/asyncio/tasks.py", line 670, in sleep
    return await future
asyncio.exceptions.CancelledError: POSSIBLY LONG CANCEL MESSAGE

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/.../cpython/test-cancel.py", line 11, in run
    await task
asyncio.exceptions.CancelledError: POSSIBLY LONG CANCEL MESSAGE

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/.../cpython/test-cancel.py", line 15, in <module>
    loop.run_until_complete(run())
  File "/.../cpython/Lib/asyncio/base_events.py", line 642, in run_until_complete
    return future.result()
asyncio.exceptions.CancelledError: POSSIBLY LONG CANCEL MESSAGE
msg369173 - (view) Author: Yury Selivanov (yselivanov) * (Python committer) Date: 2020-05-18 04:06
Elevating to release blocker to make sure it's included. The PR is good.
msg369179 - (view) Author: Chris Jerdonek (chris.jerdonek) * (Python committer) Date: 2020-05-18 05:47
New changeset da742ba826721da84140abc785856d4ccc2d787f by Chris Jerdonek in branch 'master':
bpo-31033: Improve the traceback for cancelled asyncio tasks (GH-19951)
https://github.com/python/cpython/commit/da742ba826721da84140abc785856d4ccc2d787f
msg369180 - (view) Author: Chris Jerdonek (chris.jerdonek) * (Python committer) Date: 2020-05-18 05:56
Thanks so much, Yury.

(Removing the "release blocker" flag now that it has been merged.)
msg369305 - (view) Author: Chris Jerdonek (chris.jerdonek) * (Python committer) Date: 2020-05-18 22:36
New changeset ff7a8b03c49153021d6de5d0b2fa8b5163059ed6 by Chris Jerdonek in branch 'master':
Use _PyErr_ChainStackItem() inside gen_send_ex(). (GH-20173)
https://github.com/python/cpython/commit/ff7a8b03c49153021d6de5d0b2fa8b5163059ed6
msg369315 - (view) Author: Łukasz Langa (lukasz.langa) * (Python committer) Date: 2020-05-19 02:14
New changeset f02c3048dc2f22053a2ba56ef5987967b89c4be3 by Miss Islington (bot) in branch '3.9':
Use _PyErr_ChainStackItem() inside gen_send_ex(). (GH-20173) (#20202)
https://github.com/python/cpython/commit/f02c3048dc2f22053a2ba56ef5987967b89c4be3
History
Date User Action Args
2020-05-19 02:14:19lukasz.langasetnosy: + lukasz.langa
messages: + msg369315
2020-05-19 01:53:10miss-islingtonsetnosy: + miss-islington

pull_requests: + pull_request19500
2020-05-18 22:36:16chris.jerdoneksetmessages: + msg369305
2020-05-18 11:49:27chris.jerdoneksetpull_requests: + pull_request19472
2020-05-18 06:06:59chris.jerdoneklinkissue31131 superseder
2020-05-18 05:56:13chris.jerdoneksetstatus: open -> closed
priority: release blocker -> normal
title: Add argument to .cancel() of Task and Future -> Improve traceback of cancelled tasks / add cancel() msg argument
messages: + msg369180

resolution: fixed
stage: patch review -> resolved
2020-05-18 05:47:38chris.jerdoneksetmessages: + msg369179
2020-05-18 04:06:53yselivanovsetmessages: + msg369173
2020-05-18 04:06:33yselivanovsetpriority: normal -> release blocker
2020-05-16 01:06:27chris.jerdoneksetmessages: + msg368993
versions: + Python 3.9, - Python 3.5, Python 3.6, Python 3.7
2020-05-16 00:00:15chris.jerdoneksetmessages: + msg368988
2020-05-15 23:55:57chris.jerdoneksetmessages: + msg368987
2020-05-08 02:27:38chris.jerdoneksetmessages: + msg368405
2020-05-07 13:57:54chris.jerdoneksetpull_requests: + pull_request19295
2020-05-06 12:58:42chris.jerdoneksetmessages: + msg368243
2020-05-06 11:22:08chris.jerdoneksetmessages: + msg368236
2020-05-06 11:06:24chris.jerdoneksetkeywords: + patch
stage: patch review
pull_requests: + pull_request19267
2019-05-09 05:33:18thehesiodsetmessages: + msg341967
2019-05-08 17:30:14carljmsetnosy: + carljm
2018-04-04 22:04:42yselivanovsetmessages: + msg314954
2018-04-04 21:56:12thehesiodsetnosy: + thehesiod
messages: + msg314953
2017-08-11 05:34:50socketpairsetmessages: + msg300152
2017-08-08 02:15:28chris.jerdoneksetmessages: + msg299891
2017-08-08 01:12:27chris.jerdoneksetnosy: + chris.jerdonek
2017-07-25 15:34:11yselivanovsetmessages: + msg299112
2017-07-25 15:29:04socketpairsetmessages: + msg299107
2017-07-25 15:21:42yselivanovsetmessages: + msg299103
2017-07-25 15:18:40socketpairsetmessages: + msg299101
2017-07-25 13:50:07matrixisesetnosy: + matrixise
messages: + msg299084
2017-07-25 13:48:27yselivanovsetmessages: + msg299083
2017-07-25 13:21:40socketpaircreate