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

nedbat

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