Request is not cancelled on timeout, its response is returned for the next request

[pavlin99th]

Describe the bug

I see this strange behaviour in version 3.9.0 when I iterate to retry timed out request. It started with version 3.9.0b1.
Version 3.9.0b0 works as expected.

The probelm is when the initial request times out it should get cancelled, and indeed that iteration catches TimeoutError. The next iteration, which retries the request with new parameters somehow returns the response of the inittial cancelled request...

Please see the minimal reproducing example.

To Reproduce

import asyncio

import aiohttp


async def minimum_error():
    url = "http://httpbin.org/delay/10"
    timeout = aiohttp.ClientTimeout(total=7)
    async with aiohttp.ClientSession(timeout=timeout) as session:
        for i in range(2):
            print(f"iteration {i} start")
            try:
                async with session.get(url, params={"iteration": i}) as resp:
                    print("ok", resp.status)
                    print(await resp.text())
            except TimeoutError:
                print("aiohttp timeout")
                await asyncio.sleep(1)
                continue
            except asyncio.CancelledError:
                print("aiohttp cancelled???")
                raise
            finally:
                print(f"iteration {i} done")


asyncio.run(minimum_error())

Expected behavior

Correct results with 3.9.0b0

iteration 0 start
aiohttp timeout
iteration 0 done
iteration 1 start
aiohttp timeout
iteration 1 done

Logs/tracebacks

Actual results with 3.9.0:

iteration 0 start
aiohttp timeout
iteration 0 done
iteration 1 start
ok 200
{
  "args": {
    "iteration": "0"
  }, 
  "data": "", 
  "files": {}, 
  "form": {}, 
  "headers": {
    "Accept": "*/*", 
    "Accept-Encoding": "gzip, deflate, br", 
    "Host": "httpbin.org", 
    "User-Agent": "Python/3.12 aiohttp/3.9.0"
  }, 
  "url": "http://httpbin.org/delay/10?iteration=0"
}

iteration 1 done

Python Version

$ python --version
Python 3.12.0

aiohttp Version

$ python -m pip show aiohttp
Name: aiohttp
Version: 3.9.0
Summary: Async http client/server framework (asyncio)
Home-page: https://github.com/aio-libs/aiohttp
Author: 
Author-email: 
License: Apache 2
Location: /home/andy/.local/lib/python3.12/site-packages
Requires: aiosignal, attrs, frozenlist, multidict, yarl
Required-by: web3

multidict Version

$ python -m pip show multidict
Name: multidict
Version: 6.0.4
Summary: multidict implementation
Home-page: https://github.com/aio-libs/multidict
Author: Andrew Svetlov
Author-email: andrew.svetlov@gmail.com
License: Apache 2
Location: /home/andy/.local/lib/python3.12/site-packages
Requires: 
Required-by: aiohttp, yarl

yarl Version

$ python -m pip show yarl
Name: yarl
Version: 1.9.3
Summary: Yet another URL library
Home-page: https://github.com/aio-libs/yarl
Author: Andrew Svetlov
Author-email: andrew.svetlov@gmail.com
License: Apache-2.0
Location: /home/andy/.local/lib/python3.12/site-packages
Requires: idna, multidict
Required-by: aiohttp, gql

OS

Ubuntu Linux

Related component

Client

Additional context

No response

Code of Conduct

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

[pquentin]

Hello, I can confirm we've hit the same issue in Rally (Elasticsearch benchmarking tool). elastic/rally#1804

[bdraco]

This might be a side effect of using the callback done running with a call soon

[hanse]

I see similar issues in our application. The following code exposes a problem on my machine (Python 3.11):

import asyncio
import random
from typing import Any

import aiohttp


async def main() -> None:
    # Usually works when this is `<= 100`
    num_calls = 120

    client = aiohttp.ClientSession()

    async def call(n: int) -> Any:
        # This service echoes the request body in the response
        # The random timeout is key here, it works when `timeout=None`
        response = await client.put(
            "http://localhost:3000/", timeout=random.random(), json={"n": n}
        )
        body = await response.text()
        return (n, body)

    results = await asyncio.gather(
        *[call(i) for i in range(num_calls)], return_exceptions=True
    )

    for result in results:
        if isinstance(result, Exception):
            print(type(result))
        else:
            print(result)

    await client.close()


asyncio.run(main())

On version 3.8.6 this does what you would expect with the n in the request and in the response matching:

(95, '{"n":95}')
<class 'TimeoutError'>
<class 'TimeoutError'>
<class 'TimeoutError'>
(99, '{"n":99}')
(100, '{"n":100}')
<class 'TimeoutError'>
(102, '{"n":102}')
<class 'TimeoutError'>
(104, '{"n":104}')
(105, '{"n":105}')
<class 'TimeoutError'>
(107, '{"n":107}')
<class 'TimeoutError'>
<class 'TimeoutError'>
(110, '{"n":110}')
<class 'TimeoutError'>
<class 'TimeoutError'>
(113, '{"n":113}')
(114, '{"n":114}')
(115, '{"n":115}')
(116, '{"n":116}')
(117, '{"n":117}')
<class 'TimeoutError'>
<class 'TimeoutError'>

However, on 3.9.0, we see this:
(Seemingly recycling responses after 100 when at least one timed out)

(98, '{"n":98}')
<class 'TimeoutError'>
<class 'TimeoutError'>
<class 'TimeoutError'>
<class 'TimeoutError'>
(103, '{"n":60}')
(104, '{"n":58}')
(105, '{"n":71}')
<class 'TimeoutError'>
<class 'TimeoutError'>
(108, '{"n":77}')
(109, '{"n":100}')
<class 'TimeoutError'>
<class 'TimeoutError'>
<class 'TimeoutError'>
(113, '{"n":26}')
<class 'TimeoutError'>
(115, '{"n":2}')
<class 'TimeoutError'>
(117, '{"n":25}')
(118, '{"n":31}')
<class 'TimeoutError'>

We also saw other unexplainable behaviour that could be caused by this, but I have no evidence nor re-production of that.

[bdraco]

Does anyone have a working test case we can merge as an xfail test so we can validate a fix?

[bdraco]

bisected this to #7764

[Dreamsorcerer]

bisected this to #7764

Yeah, I already assumed it would be related to that. Something to do with us previously closing the connection and now we're trying to reuse it.