Fix spurious LocalProtocolError errors when processing pipelined requests

[marcinsulikowski]

Summary

This is a fix for #1637 which was closed due to no reproduction. I was able to find the reproduction steps and and a fix (see my recent comment in the issue).

When uvicorn receives a request very soon after it sent the previous response, or when it receives pipelined requests, the second request may spuriously fail if the ASGI app takes more time to process it than uvicorn's timeout_keep_alive. This happens because uvicorn arms the keep-alive timer as the last step of handling the first request, which is after the second request was already received from the network (which normally is the only place where uvicorn disarms the keep-alive timer). In such cases the timer may fire while uvicorn is still waiting for a response from the ASGI app:

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 this happens, the connection is left in the ERROR state and when a response to the second request is ready to be sent, this fails:

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/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

We fix this by ensuring that the keep-alive timer is disarmed before starting to process a pipelined request.

Checklist

• I understand that this PR may be closed in case there was no previous discussion. (This doesn't apply to typos!)
• I've added a test for each change that was introduced, and I tried as much as possible to make a single atomic change.
• I've updated the documentation accordingly.

[Kludex]

This is not failing on httptools implementation, is it?

[marcinsulikowski]

Without this change, the unit test that I added would be failing – it finds self.timeout_keep_alive_task set after handling the first request, before handling the second, pipelined one.

But let me see on a real application with the reproduction script that I posted in #1637.

[marcinsulikowski]

So this is the test script for the httptools implementation:

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, http="httptools")
    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(1000):
        print(data.decode("utf-8"))
    print("Server closed the connection")
    server.should_exit = True
    await uvicorn_task


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

Without my changes, the client receives a response for its first request and then the connection is gracefully closed despite the second request still being in progress:

INFO:     Started server process [260529]
INFO:     Waiting for application startup.
INFO:     Application startup complete.
INFO:     Uvicorn running on http://127.0.0.1:8000 (Press CTRL+C to quit)
Sending requests
INFO:     127.0.0.1:59558 - "GET / HTTP/1.1" 200 OK
HTTP/1.1 200 OK
date: Fri, 09 Feb 2024 22:48:32 GMT
server: uvicorn
content-length: 21
content-type: application/json

{"msg":"Hello World"}                # One second pause after this line is printed
Server closed the connection
INFO:     Shutting down
INFO:     Waiting for background tasks to complete. (CTRL+C to force quit)
INFO:     Waiting for application shutdown.
INFO:     Application shutdown complete.
INFO:     Finished server process [260529]

The httptools implementation doesn't have the same state checks as h11 so it doesn't notice that it is closing a connection which is still needed and doesn't print the ugly stack traces, but this is still not the correct behavior.

With my changes from this PR, the client gets two responses, as expected, and the connection is closed a second after getting the second one, also as expected:

INFO:     Started server process [261908]
INFO:     Waiting for application startup.
INFO:     Application startup complete.
INFO:     Uvicorn running on http://127.0.0.1:8000 (Press CTRL+C to quit)
Sending requests
INFO:     127.0.0.1:54282 - "GET / HTTP/1.1" 200 OK
HTTP/1.1 200 OK
date: Fri, 09 Feb 2024 22:51:44 GMT
server: uvicorn
content-length: 21
content-type: application/json

{"msg":"Hello World"}
INFO:     127.0.0.1:54282 - "GET / HTTP/1.1" 200 OK
HTTP/1.1 200 OK
date: Fri, 09 Feb 2024 22:51:44 GMT
server: uvicorn
content-length: 21
content-type: application/json

{"msg":"Hello World"}
Server closed the connection
INFO:     Shutting down
INFO:     Waiting for application shutdown.
INFO:     Application shutdown complete.
INFO:     Finished server process [261908]

[Kludex]

Amazing work. Amazing explanation.

Best PR I received in a long time. Thanks! 🙏