unexpected asyncio.exceptions.CancelledError

[vitidev]

Describe the bug

Sometimes after raising asyncio.exceptions.TimeoutError next awaits of coroutines causes asyncio.exceptions.CancelledError

To Reproduce

Emulate server with random timeouts

import asyncio
import datetime
import random
from aiohttp import web

async def uptime_handler(request):
    chance = random.randint(1, 4)
    if chance == 0:
        await asyncio.sleep(50)
        return
    response = web.StreamResponse()
    response.headers['Content-Type'] = 'text/html'
    await response.prepare(request)

    for i in range(100000):
        formatted_date = datetime.datetime.now().strftime("%Y-%m-%d %H:%M:%S")
        message = f'{formatted_date}<br>'
        await response.write(message.encode('utf-8'))
        await asyncio.sleep(0.01)

if __name__ == '__main__':
    app = web.Application()
    app.add_routes([ web.get('/', uptime_handler),])
    web.run_app(app)

and a client that "downloads files" in parallel

import asyncio
import random
import traceback

import aiohttp

URL = 'http://127.0.0.1:8080/'

__http__: aiohttp.ClientSession = None
__semaphore__: asyncio.Semaphore = None

async def download_file(client, url: str):
    try:
        r = await client.get(url, timeout=random.randint(5, 15))
        async for data in r.content.iter_chunked(8192):
            await asyncio.sleep(0.01)
        stub = 2 + 2
        foo = "bar"  # garbage code
    except asyncio.exceptions.TimeoutError:
        try:
            print(f'catch TIMEOUT in download_file')
            await asyncio.sleep(5)
        except asyncio.exceptions.CancelledError:
            print('ALARM ' + traceback.format_exc())

async def _download(client, idx) -> int:
    try:
        for i in range(10):
            print(f'{idx} start')
            try:
                await download_file(client, URL)
            except aiohttp.client.ClientPayloadError:
                break
    except BaseException as e:
        print('**********' + traceback.format_exc())
    finally:
        print(f'{idx} finish')
        __semaphore__.release()
    return idx

async def main():
    global __semaphore__
    __semaphore__ = asyncio.BoundedSemaphore(10)
    async with aiohttp.ClientSession()as client:
        i = 0
        while True:
            i += 1
            await __semaphore__.acquire()
            asyncio.ensure_future(_download(client, i % 10))

if __name__ == '__main__':
    asyncio.run(main())

Expected behavior

await asyncio.sleep() in TimeoutError handler should not throw asyncio.exceptions.CancelledError, because no one cancels this coroutine. We should never see ALARM in output.

Logs/tracebacks

1 start
...
0 start
catch TIMEOUT in download_file
catch TIMEOUT in download_file
catch TIMEOUT in download_file
8 start
...
0 start
catch TIMEOUT in download_file
catch TIMEOUT in download_file
ALARM Traceback (most recent call last):
  File "F:\dev\test\asynciotest\test_sleep3.9.py", line 15, in download_file
    async for data in r.content.iter_chunked(8192):
  File "C:\Python\lib\site-packages\aiohttp\streams.py", line 39, in __anext__
    rv = await self.read_func()
  File "C:\Python\lib\site-packages\aiohttp\streams.py", line 380, in read
    await self._wait("read")
  File "C:\Python\lib\site-packages\aiohttp\streams.py", line 305, in _wait
    with self._timer:
  File "C:\Python\lib\site-packages\aiohttp\helpers.py", line 641, in __enter__
    raise asyncio.TimeoutError from None
asyncio.exceptions.TimeoutError

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "F:\dev\test\asynciotest\test_sleep3.9.py", line 22, in download_file
    await asyncio.sleep(5)
  File "C:\Python\lib\asyncio\tasks.py", line 654, in sleep
    return await future
asyncio.exceptions.CancelledError

3 start

Python Version

$ python --version
Python 3.7.9
Python 3.9.5
Python 3.9.6
Python 3.8.3

aiohttp Version

$ python -m pip show aiohttp
Name: aiohttp
Version: 3.7.4.post0
Summary: Async http client/server framework (asyncio)
Home-page: https://github.com/aio-libs/aiohttp
Author: Nikolay Kim
Author-email: [email protected]
License: Apache 2
Location: c:\python\lib\site-packages
Requires: chardet, typing-extensions, attrs, async-timeout, multidict, yarl
Required-by: aiohttp-proxy, aiocfscrape

multidict Version

$ python -m pip show multidict
Name: multidict
Version: 5.1.0
Summary: multidict implementation
Home-page: https://github.com/aio-libs/multidict
Author: Andrew Svetlov
Author-email: [email protected]
License: Apache 2
Location: c:\python\lib\site-packages
Requires:
Required-by: yarl, aiohttp

yarl Version

$ python -m pip show yarl
Name: yarl
Version: 1.6.3
Summary: Yet another URL library
Home-page: https://github.com/aio-libs/yarl/
Author: Andrew Svetlov
Author-email: [email protected]
License: Apache 2
Location: c:\python\lib\site-packages
Requires: multidict, idna
Required-by: aiohttp, aiohttp-proxy

OS

Win10x64 (1909)
Centos 8

Related component

Client

Additional context

I'm not sure if this is a aiohttp issue, because if remove await ... from async for-scope, then the side effect magically disappears, but I already excluded aiorun and aiofiles and it's time for aiohttp

Code of Conduct

• I agree to follow the aio-libs Code of Conduct

[Dreamsorcerer]

Minimal example:

import asyncio
import aiohttp
import traceback

async def main():
    async with aiohttp.ClientSession() as client:
        try:
            async with client.get('http://127.0.0.1:8080/', timeout=1) as r:
                async for data in r.content.iter_chunked(8192):
                    await asyncio.sleep(0.01)
        except asyncio.exceptions.TimeoutError:
            print(traceback.format_exc())
            print("TIMEOUT")
            await asyncio.sleep(5)

asyncio.run(main())

The code is very timing dependent.
If the first sleep delay is increased, then it's likely that the code doesn't timeout at all. This seems to be because it never calls _wait() as the data is always ready.
If the delay is decreased, then it seems likely that the code works as expected without the cancellation.

The reason for this depends on whether the timeout happens before or during the timer's with block.
If it gets the timeout before entering the with, then it cancels the current task: https://github.com/aio-libs/aiohttp/blob/master/aiohttp/helpers.py#L675
If it gets the timeout during the with, then it raises when exiting, but does not cancel the task (or rather, it catches it's own cancellation): https://github.com/aio-libs/aiohttp/blob/master/aiohttp/helpers.py#L691

I'm not really sure what the idea is behind cancelling the current task (in addition to raising a TimeoutError). The more I look at it, the more it looks like a mistake.