Debugging Keep Alives - Why is HttpToolsProtocol.connection_lost always called after each request?

[chiragjn]

I was trying to reproduce an intermittent 503 issue (from the reverse proxy) and my guess was because my reverse proxy's idle timeout is much higher than what uvicorn's default is there must be some race condition severing the connection.
When I try to test keep alive timeout without a proxy using a simple app

requirements.txt

fastapi==0.103.2
uvicorn[standard]==0.23.2

app.py

import asyncio
import os
from fastapi import FastAPI

import uvicorn

sleep_for = int(os.getenv("SLEEP_FOR", 5))

app = FastAPI()

@app.post("/hit")
async def hit():
    await asyncio.sleep(sleep_for)
    return "ok"

command

uvicorn  --port 8081 app:app --timeout-keep-alive 5 --log-level trace

and when I hit with curl

curl -v -X POST http://0.0.0.0:8081/hit
*   Trying 0.0.0.0:8081...
* Connected to 0.0.0.0 (127.0.0.1) port 8081 (#0)
> POST /hit HTTP/1.1
> Host: 0.0.0.0:8081
> User-Agent: curl/7.85.0
> Accept: */*
>
* Mark bundle as not supporting multiuse
< HTTP/1.1 200 OK
< date: Mon, 16 Oct 2023 14:09:56 GMT
< server: uvicorn
< content-length: 4
< content-type: application/json
<
* Connection #0 to host 0.0.0.0 left intact

From curl side connection is left intact, but from server side I notice connection is never closed?

INFO:     Started server process [58471]
INFO:     Waiting for application startup.
TRACE:    ASGI [1] Started scope={'type': 'lifespan', 'asgi': {'version': '3.0', 'spec_version': '2.0'}, 'state': {}}
TRACE:    ASGI [1] Receive {'type': 'lifespan.startup'}
TRACE:    ASGI [1] Send {'type': 'lifespan.startup.complete'}
INFO:     Application startup complete.
INFO:     Uvicorn running on http://127.0.0.1:8081 (Press CTRL+C to quit)
>>> [uvicorn] HttpToolsProtocol.__init__ ...
>>> [uvicorn] connection_made ...
TRACE:    127.0.0.1:64801 - HTTP connection made
>>> [uvicorn] data_received -> _unset_keepalive_if_required ...
TRACE:    127.0.0.1:64801 - ASGI [2] Started scope={'type': 'http', 'asgi': {'version': '3.0', 'spec_version': '2.3'}, 'http_version': '1.1', 'server': ('127.0.0.1', 8081), 'client': ('127.0.0.1', 64801), 'scheme': 'http', 'root_path': '', 'headers': '<...>', 'state': {}, 'method': 'POST', 'path': '/hit', 'raw_path': b'/hit', 'query_string': b''}
TRACE:    127.0.0.1:64801 - ASGI [2] Send {'type': 'http.response.start', 'status': 200, 'headers': '<...>'}
INFO:     127.0.0.1:64801 - "POST /hit HTTP/1.1" 200 OK
TRACE:    127.0.0.1:64801 - ASGI [2] Send {'type': 'http.response.body', 'body': '<4 bytes>'}
>>> [uvicorn] on_response_complete -> _unset_keepalive_if_required ...
>>> [uvicorn] Response completed Scheduling timeout_keep_alive_handler to run after 5s ...
TRACE:    127.0.0.1:64801 - ASGI [2] Completed
TRACE:    127.0.0.1:64801 - HTTP connection lost
>>> [uvicorn] connection_lost -> exc is None -> _unset_keepalive_if_required ...
>>> [uvicorn] Cancelling timeout_keep_alive_task ...

The >>> lines are added by me.

So how can connections be kept alive correctly?
I am running this on a M1 Mac

[chiragjn]

Nevermind,
I tried requests.Session and keep alive behaves as expected and server logs also don't have immediate connection_lost.

In [10]: import logging
    ...: import requests
    ...: import time
    ...:
    ...: logging.basicConfig(level=logging.DEBUG)
    ...:
    ...: def test1(duration):
    ...:     s = requests.Session()
    ...:     s.post("http://0.0.0.0:8081/hit")
    ...:     time.sleep(duration)
    ...:     s.post("http://0.0.0.0:8081/hit")
    ...:

In [11]: test1(3)
DEBUG:urllib3.connectionpool:Starting new HTTP connection (1): 0.0.0.0:8081
DEBUG:urllib3.connectionpool:http://0.0.0.0:8081 "POST /hit HTTP/1.1" 200 4
DEBUG:urllib3.connectionpool:http://0.0.0.0:8081 "POST /hit HTTP/1.1" 200 4

In [12]: test1(4)
DEBUG:urllib3.connectionpool:Starting new HTTP connection (1): 0.0.0.0:8081
DEBUG:urllib3.connectionpool:http://0.0.0.0:8081 "POST /hit HTTP/1.1" 200 4
DEBUG:urllib3.connectionpool:http://0.0.0.0:8081 "POST /hit HTTP/1.1" 200 4

In [13]: test1(5)
DEBUG:urllib3.connectionpool:Starting new HTTP connection (1): 0.0.0.0:8081
DEBUG:urllib3.connectionpool:http://0.0.0.0:8081 "POST /hit HTTP/1.1" 200 4
DEBUG:urllib3.connectionpool:Resetting dropped connection: 0.0.0.0
DEBUG:urllib3.connectionpool:http://0.0.0.0:8081 "POST /hit HTTP/1.1" 200 4

In [14]: test1(6)
DEBUG:urllib3.connectionpool:Starting new HTTP connection (1): 0.0.0.0:8081
DEBUG:urllib3.connectionpool:http://0.0.0.0:8081 "POST /hit HTTP/1.1" 200 4
DEBUG:urllib3.connectionpool:Resetting dropped connection: 0.0.0.0
DEBUG:urllib3.connectionpool:http://0.0.0.0:8081 "POST /hit HTTP/1.1" 200 4

And then I realised I was using curl wrong. Two different curl processes cannot use the same connection (Duh!). The correct way is to use curl -v -X POST http://0.0.0.0:8081/hit http://0.0.0.0:8081/hit
and then we correctly see re-use

TRACE:    127.0.0.1:55604 - HTTP connection made
TRACE:    127.0.0.1:55604 - ASGI [2] Started scope={'type': 'http', 'asgi': {'version': '3.0', 'spec_version': '2.3'}, 'http_version': '1.1', 'server': ('127.0.0.1', 8081), 'client': ('127.0.0.1', 55604), 'scheme': 'http', 'root_path': '', 'headers': '<...>', 'state': {}, 'method': 'POST', 'path': '/hit', 'raw_path': b'/hit', 'query_string': b''}
TRACE:    127.0.0.1:55604 - ASGI [2] Send {'type': 'http.response.start', 'status': 200, 'headers': '<...>'}
INFO:     127.0.0.1:55604 - "POST /hit HTTP/1.1" 200 OK
TRACE:    127.0.0.1:55604 - ASGI [2] Send {'type': 'http.response.body', 'body': '<4 bytes>'}
TRACE:    127.0.0.1:55604 - ASGI [2] Completed
TRACE:    127.0.0.1:55604 - ASGI [3] Started scope={'type': 'http', 'asgi': {'version': '3.0', 'spec_version': '2.3'}, 'http_version': '1.1', 'server': ('127.0.0.1', 8081), 'client': ('127.0.0.1', 55604), 'scheme': 'http', 'root_path': '', 'headers': '<...>', 'state': {}, 'method': 'POST', 'path': '/hit', 'raw_path': b'/hit', 'query_string': b''}
TRACE:    127.0.0.1:55604 - ASGI [3] Send {'type': 'http.response.start', 'status': 200, 'headers': '<...>'}
INFO:     127.0.0.1:55604 - "POST /hit HTTP/1.1" 200 OK
TRACE:    127.0.0.1:55604 - ASGI [3] Send {'type': 'http.response.body', 'body': '<4 bytes>'}
TRACE:    127.0.0.1:55604 - ASGI [3] Completed
TRACE:    127.0.0.1:55604 - HTTP connection lost