Can't handle event type ConnectionClosed when role=SERVER and state=SEND_RESPONSE

[Yangruipis]

Related to #111 #1636 may be a solution

Reproducing

1. server code

import asyncio
from fastapi import FastAPI, Request

app = FastAPI()

# !!!middleware is required to reproduce this!!!
@app.middleware("http")
async def add_process_time_header(request: Request, call_next):
    response = await call_next(request)
    return response

@app.post(
    "/test",
)
async def test(query: dict) -> dict:
    await asyncio.sleep(1)
    return {"foo": "bar"}

2. locust client

# client.py
from locust import HttpUser, task

class WebsiteUser(HttpUser):
    @task
    def inference(self):
        rtn = self.client.post(
            "/test",
            headers={"accept": "application/json"},
            json={"query": "test"},
        )

3. call

locust -f client.py  -u 10 -r 10 --headless -t 10min -H http://localhost:8000

It will take 30s to reproduce this issue

Traceback logs

Exception in callback H11Protocol.timeout_keep_alive_handler()
handle: <TimerHandle when=3544453.523044797 H11Protocol.timeout_keep_alive_handler()>
Traceback (most recent call last):
  File "/home/r.yang/miniconda3/envs/py37/lib/python3.7/asyncio/events.py", line 88, in _run
    self._context.run(self._callback, *self._args)
  File "/home/r.yang/miniconda3/envs/py37/lib/python3.7/site-packages/uvicorn/protocols/http/h11_impl.py", line 360, in timeout_keep_alive_handler
    self.conn.send(event)
  File "/home/r.yang/miniconda3/envs/py37/lib/python3.7/site-packages/h11/_connection.py", line 510, in send
    data_list = self.send_with_data_passthrough(event)
  File "/home/r.yang/miniconda3/envs/py37/lib/python3.7/site-packages/h11/_connection.py", line 535, in send_with_data_passthrough
    self._process_event(self.our_role, event)
  File "/home/r.yang/miniconda3/envs/py37/lib/python3.7/site-packages/h11/_connection.py", line 272, in _process_event
    self._cstate.process_event(role, type(event), server_switch_event)
  File "/home/r.yang/miniconda3/envs/py37/lib/python3.7/site-packages/h11/_state.py", line 289, in process_event
    self._fire_event_triggered_transitions(role, _event_type)
  File "/home/r.yang/miniconda3/envs/py37/lib/python3.7/site-packages/h11/_state.py", line 311, in _fire_event_triggered_transitions
    ) from None
h11._util.LocalProtocolError: can't handle event type ConnectionClosed when role=SERVER and state=SEND_RESPONSE

[Yangruipis]

>>> here is more information <<<

how to start the server

uvicorn app:app --reload --host 0.0.0.0 --timeout-keep-alive 1

versions

python==3.7
uvicorn==0.18.3
fastapi==0.81.0
h11==0.13.0
starlette==0.19.1

[Kludex]

I cannot reproduce it. :eyes:

[liranbg]

For other people encountering such issue - This might be caused when your server has CPU starvation.

So each client, making a request, expect a keep alive that is configured by uvicorn to 5 by default. That keepalive, if the server process is starved, wont happen on time and thus, client will bail the connection with an execute of "RemoteDisconnect" while the server will show a traceback as mentioned on the PR description.

The solution here, would be to allow more CPU for the process or find the bottleneck on the server process to allow it sending the keepalive on time. (or, course, increase the default keepalive on the server from 5 to whatever is needed, but i guess, that would mask other issues)

[marcinsulikowski]

@Yangruipis, @Kludex, I am hitting this error very frequently in a quite complex application I am working on. After looking at the problem a bit closer, it happens when the server receives a request very fast after sending a response for the previous one on the same connection, before it manages to call H11Protocol.on_response_complete. When this happens, H11Protocol.on_response_complete arms the keep-alive timer and then starts processing the second request, without disarming that timer first (it is normally only disarmed in H11Protocol.data_received).

It could not create a simple and reliable reproducer of the scenario above, but the same problem can be very reliably reproduced in another way: by pipelining two requests, when the second request takes longer than timeout_keep_alive to be processed. Here's a standalone Python script that shows the problem:

import asyncio

import uvicorn
from fastapi import FastAPI

app = FastAPI()


@app.get("/")
async def root():
    await asyncio.sleep(3)
    return {"msg": "Hello World"}


async def main():
    # Start uvicorn in a background task
    config = uvicorn.Config(app, port=8000, timeout_keep_alive=1)
    server = uvicorn.Server(config)
    uvicorn_task = asyncio.create_task(server.serve())

    # After it starts, try making two HTTP requests.
    await asyncio.sleep(1)
    print("Sending requests")
    reader, writer = await asyncio.open_connection("localhost", 8000)
    writer.write(b"GET / HTTP/1.1\r\nHost: localhost\r\nConnection: keep-alive\r\n\r\n")
    writer.write(b"GET / HTTP/1.1\r\nHost: localhost\r\nConnection: keep-alive\r\n\r\n")
    await writer.drain()
    while data := await reader.read(100):
        print(data.decode("utf-8"))
    print("Server closed the connection")
    server.should_exit = True
    await uvicorn_task


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

The script should print two {"msg": "Hello World"}, wait a second and shut down. However, instead it does this:

• It gets the first response and prints it.
• A second after, while processing the second pipelined request, uvicorn tries to close the connection; this fails because its state is SEND_RESPONSE and leaves that connection in the ERROR state:

Exception in callback H11Protocol.timeout_keep_alive_handler()
handle: <TimerHandle when=335245.867740771 H11Protocol.timeout_keep_alive_handler()>
Traceback (most recent call last):
  File "/usr/lib/python3.12/asyncio/events.py", line 84, in _run
    self._context.run(self._callback, *self._args)
  File "venv/lib/python3.12/site-packages/uvicorn/protocols/http/h11_impl.py", line 363, in timeout_keep_alive_handler
    self.conn.send(event)
  File "venv/lib/python3.12/site-packages/h11/_connection.py", line 512, in send
    data_list = self.send_with_data_passthrough(event)
                ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "venv/lib/python3.12/site-packages/h11/_connection.py", line 537, in send_with_data_passthrough
    self._process_event(self.our_role, event)
  File "venv/lib/python3.12/site-packages/h11/_connection.py", line 272, in _process_event
    self._cstate.process_event(role, type(event), server_switch_event)
  File "venv/lib/python3.12/site-packages/h11/_state.py", line 293, in process_event
    self._fire_event_triggered_transitions(role, _event_type)
  File "venv/lib/python3.12/site-packages/h11/_state.py", line 311, in _fire_event_triggered_transitions
    raise LocalProtocolError(
h11._util.LocalProtocolError: can't handle event type ConnectionClosed when role=SERVER and state=SEND_RESPONSE

• When the response is generated by the ASGI app and is ready to be sent, uvicorn tries to send it but because the state of the connection is ERROR, it simply disconnects:

INFO:     127.0.0.1:47416 - "GET / HTTP/1.1" 200 OK
ERROR:    Exception in ASGI application
Traceback (most recent call last):
  File "venv/lib/python3.12/site-packages/uvicorn/protocols/http/h11_impl.py", line 408, in run_asgi
    result = await app(  # type: ignore[func-returns-value]
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "venv/lib/python3.12/site-packages/uvicorn/middleware/proxy_headers.py", line 84, in __call__
    return await self.app(scope, receive, send)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "venv/lib/python3.12/site-packages/fastapi/applications.py", line 1106, in __call__
    await super().__call__(scope, receive, send)
  File "venv/lib/python3.12/site-packages/starlette/applications.py", line 122, in __call__
    await self.middleware_stack(scope, receive, send)
  File "venv/lib/python3.12/site-packages/starlette/middleware/errors.py", line 184, in __call__
    raise exc
  File "venv/lib/python3.12/site-packages/starlette/middleware/errors.py", line 162, in __call__
    await self.app(scope, receive, _send)
  File "venv/lib/python3.12/site-packages/starlette/middleware/exceptions.py", line 79, in __call__
    raise exc
  File "venv/lib/python3.12/site-packages/starlette/middleware/exceptions.py", line 68, in __call__
    await self.app(scope, receive, sender)
  File "venv/lib/python3.12/site-packages/fastapi/middleware/asyncexitstack.py", line 20, in __call__
    raise e
  File "venv/lib/python3.12/site-packages/fastapi/middleware/asyncexitstack.py", line 17, in __call__
    await self.app(scope, receive, send)
  File "venv/lib/python3.12/site-packages/starlette/routing.py", line 718, in __call__
    await route.handle(scope, receive, send)
  File "venv/lib/python3.12/site-packages/starlette/routing.py", line 276, in handle
    await self.app(scope, receive, send)
  File "venv/lib/python3.12/site-packages/starlette/routing.py", line 69, in app
    await response(scope, receive, send)
  File "venv/lib/python3.12/site-packages/starlette/responses.py", line 164, in __call__
    await send(
  File "venv/lib/python3.12/site-packages/starlette/middleware/exceptions.py", line 65, in sender
    await send(message)
  File "venv/lib/python3.12/site-packages/starlette/middleware/errors.py", line 159, in _send
    await send(message)
  File "venv/lib/python3.12/site-packages/uvicorn/protocols/http/h11_impl.py", line 490, in send
    output = self.conn.send(event=response)
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "venv/lib/python3.12/site-packages/h11/_connection.py", line 512, in send
    data_list = self.send_with_data_passthrough(event)
                ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "venv/lib/python3.12/site-packages/h11/_connection.py", line 527, in send_with_data_passthrough
    raise LocalProtocolError("Can't send data when our state is ERROR")
h11._util.LocalProtocolError: Can't send data when our state is ERROR

See PR #2243 for a proposal which fixes the problem.

[Kludex]

I've reopened. I'll check this in some days. Thanks.

[Kludex]

• Closed by https://github.com/encode/uvicorn/pull/2243

[hackrole]

It seems unregister keepalive before RequestResponseCycle not fix the root cause. According @marcinsulikowski description, It still depends on the call order of the on_response_complete and run_asgi. Is this correct??

Whether would it be good to use a locked counter to count the processing request and only trigger the keepalive handler while the count is 0?