Timeout unexpectedly not raised

[valsteen]

Hi, this is a question I originally asked in httpx: encode/httpx#2861

If you don't mind, since the same conditions apply, I paste again the question below, on the bottom I will add my findings in httpcore:

---

I was investigating why I sometimes have requests that take much longer than the timeout. I could isolate and reproduce the scenario:

I have those versions, on Python 3.11.3:

httpx 0.25.0 The next generation HTTP client.
├── certifi *
├── httpcore >=0.18.0,<0.19.0
│   ├── anyio >=3.0,<5.0 
│   │   ├── idna >=2.8 
│   │   └── sniffio >=1.1 
│   ├── certifi * 
│   ├── h11 >=0.13,<0.15 
│   └── sniffio ==1.* (circular dependency aborted here)
├── idna *
└── sniffio *

let's have this minimal server which just sleeps 2 seconds

import asyncio
from fastapi import FastAPI

app = FastAPI()


@app.get("/")
async def root():
    await asyncio.sleep(2)

I name it simple.py and run uvicorn simple:app

And here is the test:

import asyncio
import time

from httpx import Limits, AsyncClient, Timeout


async def read():
    start = time.time()
    try:
        response = await http.get("http://127.0.0.1:8000")
        response.raise_for_status()
    except Exception as ex:
        print(f"failed: {ex.__class__}")

    print(f"time: {time.time()-start}")


async def main():
    tasks = []
    for x in range(100):
        tasks.append(asyncio.create_task(read()))
    await asyncio.gather(*tasks, return_exceptions=True)


if __name__ == "__main__":
    limits = Limits(
        max_keepalive_connections=None,
        max_connections=3,
    )
    http = AsyncClient(
        limits=limits,
        timeout=Timeout(5, read=5, pool=5),
    )

    asyncio.get_event_loop().run_until_complete(main())

I get timings way above 5 seconds, but I don't understand why ; I would expect a pool timeout.

I can probably work around this by having a timeout on the task itself ( like here: asyncio.wait_for(read(), 5) ), but did I misunderstand the functionality, or is this scenario not supported ?

---

Following this, I tracked down where the PoolTimeout logic originates from, and it's this status.wait_for_connection(timeout=timeout)

httpcore/httpcore/_async/connection_pool.py

Lines 229 to 234 in 94ffb33

	while True:
	timeouts = request.extensions.get("timeout", {})
	timeout = timeouts.get("pool", None)
	try:
	connection = await status.wait_for_connection(timeout=timeout)
	except BaseException as exc:

after that, it can fail with ConnectionNotAvailable

httpcore/httpcore/_async/connection_pool.py

Lines 246 to 250 in 94ffb33

	except ConnectionNotAvailable:
	# The ConnectionNotAvailable exception is a special case, that
	# indicates we need to retry the request on a new connection.
	#
	# The most common case where this can occur is when multiple

but then it loops and tries again with the same timeout, and depending on the size of the backlog this can go way beyond the intended timeout.

To validate this assumption, I tried this very rough patch:

        started = time.time()

        while True:
            timeouts = request.extensions.get("timeout", {})
            timeout = timeouts.get("pool", None)

            timeout = max(0, timeout - (time.time() - started))

            try:
                connection = await status.wait_for_connection(timeout=timeout)

Following that, the example worked as I expected.

I presume this is not intentional, but please correct me if I'm wrong.

[zanieb]

Thanks for the thorough description! This looks like a bug to me. If another maintainer agrees we can work on a fix.

[karpetrosyan]

Hi @valsteen!

Thank you for providing such a clear description.
We actually expect this behavior, and it applies not only to the pool, but also to read/write operations (waiting longer than the timeout).

You can see #732 where we discussed what to do in such cases for read/write timeouts, but in the end we decided to keep it simple and not change anything ( Refs: OverallTimeout class ).

Applying your solution appears reasonable to me, but we may encounter the same issues with read/write operations. For example, setting the read timeout to 5 may cause you to hang indefinitely because the server may send 1 byte every 4 seconds.

I get timings way above 5 seconds, but I don't understand why ; I would expect a pool timeout.

We should probably resolve this if the difference is significant enough.

[GalaxySnail]

the timeout is really more about fine-tuning the detection of stale connections than any guarantee of maximum total processing time.

That's right. If you want something to limit the total processing time, trio.move_on_after() or anyio.move_on_after() can be helpful. For details, please refer to: https://vorpus.org/blog/timeouts-and-cancellation-for-humans/

[karpetrosyan]

I thought at first there was a problem with our instrumentation or metrics, and this is were I tried the scenario above where I could exceed the given pool timeout. Given a sufficient amount of concurrent slow reads and a max_connection setting, new requests are blocked in a loop trying to acquire a connection from the pool, fail to do so, and try again waiting for the same time. So many requests get queued that it fills up memory and we get a OOM.

I'm aware that ultimately, controlling resource usage should be done at infrastructure level, something like 1/ the readiness probe should fail if the pool is full, so new requests don't get routed to that pod 2/ it should autoscale so there is always a connection readily available.

after that, it can fail with ConnectionNotAvailable

It's very interesting; we do not expect the connection to wait for a stream for such a long time. We also do not expect the exception ConnectionNotAvailable to be frequent.
 

From there, I investigated further the application's behaviour and this was my surprise: despite the timeout, some requests take up to 8 minutes. If I count the amount of requests that exceeds 60 seconds, I get a huge spike of up to 15K http calls.

For sure, if the connection could hang in the connection pool for 8 minutes, we should probably apply the solution that you have shown.

Still, if the documentation of an open source library gives me false impressions, I'd better report it so it can be improved for everyone else. It can be just a mention in the doc saying that the timeout is not a guarantee ; that cuts short debates among teams using it: just point out the doc, and proceed with appropriate measures - such as using a task with a deadline, knowing that it's perfectly expected and not due to a misuse.

I completely agree with you. This should be mentioned in the documentation (if it's not going to be changed).

[valsteen]

@GalaxySnail yes thank you I'm aware of this. On my side I had this suggestion of custom transport using wait_for ( which for the sake of event loop compatibility, should probably use anyio instead of asyncio ) : encode/httpx#2861 (comment)

[karpetrosyan]

@valsteen
Can we have a minimum code example to reproduce this issue?

[valsteen]

@karpetrosyan the first message of this discussion has a reproducible example, is there a problem with it ?

[karpetrosyan]

There is the same example that @valsteen has provided, but just using the httpcore library and using trio instead of asyncio like we do for our issues.

file: test.py

import time
import trio
from httpcore import AsyncConnectionPool

TIMEOUTS = {"read": 5, "write": 5, "pool": 5, "connect": 5}


async def read():
    start = time.time()
    try:
        response = await http.request(
            "GET", "http://127.0.0.1:8000", extensions={"timeout": TIMEOUTS}
        )
        if response.status // 100 != 2:
            raise RuntimeError
    except Exception as ex:
        print(f"failed: {ex.__class__}")

    print(f"time: {time.time()-start}")


async def main():
    async with trio.open_nursery() as nursery:
        for _ in range(100):
            nursery.start_soon(read)


if __name__ == "__main__":
    http = AsyncConnectionPool(
        max_connections=3,
        max_keepalive_connections=3,
    )
    trio.run(main)

[valsteen]

this is solved:

• issue: Pool timeout doesn't work #822
• PR : Ensure pool timeout is applied, even after attempts leading to ConnectionNotAvailable #823