Bad interaction between asyncio task cancellation and trace functions (only 3.11)

Something about cancelling tasks is interfering with tracing, but only in 3.11. Versions 3.10 and 3.12 are unaffected. I'm sorry I don't understand enough to be more specific.

Here is traced.py:

import linecache, sys
import asyncio
from datetime import timedelta
import sys

def trace(frame, event, arg):
    # The weird globals here is to avoid a NameError on shutdown...
    if frame.f_code.co_filename == globals().get("__file__"):
        lineno = frame.f_lineno
        line = linecache.getline(__file__, lineno).rstrip()
        print("{} {}: {}".format(event[:4], lineno, line))
    return trace

print(sys.version)
sys.settrace(trace)

def main():
    async def cancel_task(task: asyncio.Task) -> None:
        task.cancel()

        try:
            await task
        except asyncio.CancelledError:
            pass

    class TTLDict:
        def __init__(self) -> None:
            self._data = {}
            self._expiration_tasks = {}

        def __setitem__(self, key, value) -> None:
            async def _waiter() -> None:
                await asyncio.sleep(1)

            self._data[key] = value
            self._expiration_tasks[key] = asyncio.create_task(_waiter())

        async def delete(self, key):
            await cancel_task(self._expiration_tasks.pop(key))
            return self._data.pop(key)

    async def _main():
        ttl_dict = TTLDict()
        ttl_dict['foo'] = 42
        await ttl_dict.delete('foo')
        print('FINISH')

    asyncio.run(_main())


main()

When run under Python 3.10.9:

3.10.9 (main, Dec  7 2022, 07:15:24) [Clang 12.0.0 (clang-1200.0.32.29)]
call 17: def main():
line 18:     async def cancel_task(task: asyncio.Task) -> None:
line 26:     class TTLDict:
call 26:     class TTLDict:
line 26:     class TTLDict:
line 27:         def __init__(self) -> None:
line 31:         def __setitem__(self, key, value) -> None:
line 38:         async def delete(self, key):
retu 38:         async def delete(self, key):
line 42:     async def _main():
line 48:     asyncio.run(_main())
call 42:     async def _main():
line 43:         ttl_dict = TTLDict()
call 27:         def __init__(self) -> None:
line 28:             self._data = {}
line 29:             self._expiration_tasks = {}
retu 29:             self._expiration_tasks = {}
line 44:         ttl_dict['foo'] = 42
call 31:         def __setitem__(self, key, value) -> None:
line 32:             async def _waiter() -> None:
line 35:             self._data[key] = value
line 36:             self._expiration_tasks[key] = asyncio.create_task(_waiter())
retu 36:             self._expiration_tasks[key] = asyncio.create_task(_waiter())
line 45:         await ttl_dict.delete('foo')
call 38:         async def delete(self, key):
line 39:             await cancel_task(self._expiration_tasks.pop(key))
call 18:     async def cancel_task(task: asyncio.Task) -> None:
line 19:         task.cancel()
line 21:         try:
line 22:             await task
retu 22:             await task
retu 39:             await cancel_task(self._expiration_tasks.pop(key))
retu 45:         await ttl_dict.delete('foo')
call 32:             async def _waiter() -> None:
exce 32:             async def _waiter() -> None:
retu 32:             async def _waiter() -> None:
call 22:             await task
exce 22:             await task
line 23:         except asyncio.CancelledError:
line 24:             pass
retu 24:             pass
call 39:             await cancel_task(self._expiration_tasks.pop(key))
line 40:             return self._data.pop(key)
retu 40:             return self._data.pop(key)
call 45:         await ttl_dict.delete('foo')
line 46:         print('FINISH')
FINISH
retu 46:         print('FINISH')
retu 48:     asyncio.run(_main())

Under 3.11.4:

3.11.4 (main, Jun  7 2023, 08:42:37) [Clang 14.0.3 (clang-1403.0.22.14.1)]
call 17: def main():
line 18:     async def cancel_task(task: asyncio.Task) -> None:
line 26:     class TTLDict:
call 26:     class TTLDict:
line 26:     class TTLDict:
line 27:         def __init__(self) -> None:
line 31:         def __setitem__(self, key, value) -> None:
line 38:         async def delete(self, key):
retu 38:         async def delete(self, key):
line 42:     async def _main():
line 48:     asyncio.run(_main())
call 42:     async def _main():
line 43:         ttl_dict = TTLDict()
call 27:         def __init__(self) -> None:
line 28:             self._data = {}
line 29:             self._expiration_tasks = {}
retu 29:             self._expiration_tasks = {}
line 44:         ttl_dict['foo'] = 42
call 31:         def __setitem__(self, key, value) -> None:
line 32:             async def _waiter() -> None:
line 35:             self._data[key] = value
line 36:             self._expiration_tasks[key] = asyncio.create_task(_waiter())
retu 36:             self._expiration_tasks[key] = asyncio.create_task(_waiter())
line 45:         await ttl_dict.delete('foo')
call 38:         async def delete(self, key):
line 39:             await cancel_task(self._expiration_tasks.pop(key))
call 18:     async def cancel_task(task: asyncio.Task) -> None:
line 19:         task.cancel()
line 21:         try:
line 22:             await task
retu 22:             await task
retu 39:             await cancel_task(self._expiration_tasks.pop(key))
retu 45:         await ttl_dict.delete('foo')
call 32:             async def _waiter() -> None:
exce 32:             async def _waiter() -> None:
retu 32:             async def _waiter() -> None:
call 22:             await task
exce 22:             await task
line 23:         except asyncio.CancelledError:
line 24:             pass
retu 24:             pass
line 40:             return self._data.pop(key)
retu 40:             return self._data.pop(key)
line 46:         print('FINISH')
FINISH
retu 46:         print('FINISH')
retu 48:     asyncio.run(_main())

Under 3.12.0b4:

3.12.0b4 (main, Jul 11 2023, 20:38:26) [Clang 14.0.3 (clang-1403.0.22.14.1)]
call 17: def main():
line 18:     async def cancel_task(task: asyncio.Task) -> None:
line 26:     class TTLDict:
call 26:     class TTLDict:
line 26:     class TTLDict:
line 27:         def __init__(self) -> None:
line 31:         def __setitem__(self, key, value) -> None:
line 38:         async def delete(self, key):
retu 38:         async def delete(self, key):
line 42:     async def _main():
line 48:     asyncio.run(_main())
call 42:     async def _main():
line 43:         ttl_dict = TTLDict()
call 27:         def __init__(self) -> None:
line 28:             self._data = {}
line 29:             self._expiration_tasks = {}
retu 29:             self._expiration_tasks = {}
line 44:         ttl_dict['foo'] = 42
call 31:         def __setitem__(self, key, value) -> None:
line 32:             async def _waiter() -> None:
line 35:             self._data[key] = value
line 36:             self._expiration_tasks[key] = asyncio.create_task(_waiter())
retu 36:             self._expiration_tasks[key] = asyncio.create_task(_waiter())
line 45:         await ttl_dict.delete('foo')
call 38:         async def delete(self, key):
line 39:             await cancel_task(self._expiration_tasks.pop(key))
call 18:     async def cancel_task(task: asyncio.Task) -> None:
line 19:         task.cancel()
line 21:         try:
line 22:             await task
retu 22:             await task
retu 39:             await cancel_task(self._expiration_tasks.pop(key))
retu 45:         await ttl_dict.delete('foo')
call 32:             async def _waiter() -> None:
exce 32:             async def _waiter() -> None:
retu 32:             async def _waiter() -> None:
call 22:             await task
exce 22:             await task
line 23:         except asyncio.CancelledError:
line 24:             pass
retu 24:             pass
call 39:             await cancel_task(self._expiration_tasks.pop(key))
exce 39:             await cancel_task(self._expiration_tasks.pop(key))
line 39:             await cancel_task(self._expiration_tasks.pop(key))
line 40:             return self._data.pop(key)
retu 40:             return self._data.pop(key)
call 45:         await ttl_dict.delete('foo')
exce 45:         await ttl_dict.delete('foo')
line 45:         await ttl_dict.delete('foo')
line 46:         print('FINISH')
FINISH
retu 46:         print('FINISH')
retu 48:     asyncio.run(_main())

3.10.9 and 3.12.0b4 produce call events for lines 39 and 45, but 3.11.4 does not.

For comparison, here's the diff between the output for 3.10.9 and 3.11.4:

1c1
< 3.10.9 (main, Dec  7 2022, 07:15:24) [Clang 12.0.0 (clang-1200.0.32.29)]
---
> 3.11.4 (main, Jun  7 2023, 08:42:37) [Clang 14.0.3 (clang-1403.0.22.14.1)]
43d42
< call 39:             await cancel_task(self._expiration_tasks.pop(key))
46d44
< call 45:         await ttl_dict.delete('foo')

And here's the difference between 3.11.4 and 3.12.0b4:

1c1
< 3.11.4 (main, Jun  7 2023, 08:42:37) [Clang 14.0.3 (clang-1403.0.22.14.1)]
---
> 3.12.0b4 (main, Jul 11 2023, 20:38:26) [Clang 14.0.3 (clang-1403.0.22.14.1)]
42a43,45
> call 39:             await cancel_task(self._expiration_tasks.pop(key))
> exce 39:             await cancel_task(self._expiration_tasks.pop(key))
> line 39:             await cancel_task(self._expiration_tasks.pop(key))
44a48,50
> call 45:         await ttl_dict.delete('foo')
> exce 45:         await ttl_dict.delete('foo')
> line 45:         await ttl_dict.delete('foo')

This was originally reported as coveragepy/coveragepy#1648

@brandtbucher

cc @brandtbucher @markshannon

@nedbat

I've bisected this issue with the following results.

In the 3.11 branch the last good commit was 3e43fac after which in e028ae9 the following error started appearing on call to the linecache.getline:

File "/home/xxx/main.py", line 12, in trace
    line = linecache.getline(__file__, lineno).rstrip()
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/xxx/cpython/Lib/linecache.py", line 31, in getline
    if 1 <= lineno <= len(lines):
    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
TypeError: '<=' not supported between instances of 'int' and 'NoneType'

This error disappeared with commit b04dfbb but since that there was a problem described by @nedbat and it got fixed later by commit 5bfb3c3 in the 3.12 branch.

Since this is fixed in 3.12 onwards, and 3.11 is in security fix only mode, I'm closing this.

backport: coverage — lax-no-cover post-unwind asserts on 3.11+lowest-…

Simplify the stdio client transport

Simplify stdio client shutdown internals

refactor: consolidate coverage-tracer resync workarounds into one helper

Exclude post-teardown header checks from 3.11 coverage measurement

Heal 3.11 coverage tracing in the new dispatcher tests

DirectDispatcher: resync coverage tracer after each request

Exclude two coverage gaps that only the Windows and Python 3.11 legs …

Fix the CI coverage gate and wrong examples in the docs (#502)

Navigation Menu

Repository navigation

Bad interaction between asyncio task cancellation and trace functions (only 3.11) #106749

Metadata

Assignees

Labels

Projects

Milestone

Relationships

Development

Bad interaction between asyncio task cancellation and trace functions (only 3.11) #106749

Description

Activity

kumaraditya303 commented on Jul 16, 2023

pszpetkowski commented on Aug 13, 2024

markshannon commented on May 6, 2025

Metadata

Metadata

Assignees

Labels

Projects

Milestone

Relationships

Development

Issue actions