Connect only times out after 4x the specified timeout

[JelleZijlstra]

I am observing that if I set a timeout of N seconds and httpx is unable to connect to the requested URL, the timeout only happens after 4 * N seconds.

I used the following example script:

import httpx
import time

def check_timeout(t):
    before = time.time()
    try: httpx.get('http://restricted.googleapis.com/', timeout=t)
    except: pass
    after = time.time()
    print(f"timeout={t} took {after-before} seconds")

And I consistently see numbers like this:

>>> check_timeout(1)
timeout=1 took 4.1316306591033936 seconds
>>> check_timeout(2)
timeout=2 took 8.029097080230713 seconds
>>> check_timeout(3)
timeout=3 took 12.025130987167358 seconds

Relevant versions:

>>> importlib.metadata.version('httpx')
'0.25.2'
>>> importlib.metadata.version('httpcore')
'1.0.2'
>>> importlib.metadata.version('anyio')
'3.6.2'
>>> sys.version
'3.11.1 (main, Dec 21 2022, 16:19:04) [Clang 14.0.0 (clang-1400.0.29.202)]'

(Also saw this on 3.9.)

Possibly it's trying 4 times and applying the 1 s timeout every time, but as a user I'd expect that if I say the timeout is 1 s, the call will definitely complete within 1 s (plus some small overhead).

[cknv]

As far as I can tell default client used by .get uses a pretty default HTTPTransport, and its retries is 0, so I would think that the retrying hypothesis is quite unlikely.

I have seen something similar own some systems of my own, but I cannot yet rule out that I have misconfigured the connection pool, or the pool gets poisoned by idle connections being kept alive.

[tomchristie]

It's possible that this is now resolved. I'd suggest installing the latest httpcore and httpx versions and trying again.

Here's the kind of output I'm currently seeing...

import httpx
import time

def check_timeout(t):
    before = time.time()
    try:
        r = httpx.get('http://restricted.googleapis.com/', timeout=t)
    except:
        after = time.time()
        print(f"timeout={t} took {after-before} seconds")
    else:
        print(r)


check_timeout(1)
check_timeout(2)
check_timeout(3)

$ python ./example.py
timeout=1 took 1.0594310760498047 seconds
timeout=2 took 2.019294023513794 seconds
timeout=3 took 3.018738269805908 seconds
$ python ./example.py
timeout=1 took 1.010772943496704 seconds
timeout=2 took 2.0196681022644043 seconds
timeout=3 took 3.0175437927246094 seconds
$ python ./example.py
timeout=1 took 1.009714126586914 seconds
timeout=2 took 2.0156030654907227 seconds
timeout=3 took 3.018308162689209 seconds

[cknv]

Just to round this off: after adding some more logging to gain insights into our connection pool, I think what I am seeing is a "reverse slowloris" as is being discussed in #1450, which is probably unrelated to the hopefully otherwise resolved issue in this discussion.

I will take my insights (if any) over there.