Duplicate access logs

[TomiBelan]

Under some conditions, Hypercorn HTTP requests are written twice to the access log.

Steps to reproduce

This uses the trio worker, curl as a client, localhost, and compliance/h2spec/server.py as an example ASGI app.

Server:

cd .../hypercorn/
hypercorn -k trio compliance.h2spec.server:app -b localhost:5047 --access-logfile -

Client:

i=0; while curl http://localhost:5047/foo$((++i)); do true; done

Output:

[2026-05-24 15:34:59 +0200] [2172700] [INFO] Running on http://127.0.0.1:5047 (CTRL + C to quit)
[2026-05-24 15:35:01 +0200] [2172700] [INFO] 127.0.0.1:40084 - - [24/May/2026:15:35:01 +0200] "GET /foo1 1.1" - - "-" "curl/8.5.0"
[2026-05-24 15:35:01 +0200] [2172700] [INFO] 127.0.0.1:40084 - - [24/May/2026:15:35:01 +0200] "GET /foo1 1.1" 200 5 "-" "curl/8.5.0"
[2026-05-24 15:35:01 +0200] [2172700] [INFO] 127.0.0.1:40094 - - [24/May/2026:15:35:01 +0200] "GET /foo2 1.1" - - "-" "curl/8.5.0"
[2026-05-24 15:35:01 +0200] [2172700] [INFO] 127.0.0.1:40094 - - [24/May/2026:15:35:01 +0200] "GET /foo2 1.1" 200 5 "-" "curl/8.5.0"
[2026-05-24 15:35:01 +0200] [2172700] [INFO] 127.0.0.1:40110 - - [24/May/2026:15:35:01 +0200] "GET /foo3 1.1" - - "-" "curl/8.5.0"
[2026-05-24 15:35:01 +0200] [2172700] [INFO] 127.0.0.1:40110 - - [24/May/2026:15:35:01 +0200] "GET /foo3 1.1" 200 5 "-" "curl/8.5.0"
[2026-05-24 15:35:01 +0200] [2172700] [INFO] 127.0.0.1:40124 - - [24/May/2026:15:35:01 +0200] "GET /foo4 1.1" 200 5 "-" "curl/8.5.0"
[2026-05-24 15:35:01 +0200] [2172700] [INFO] 127.0.0.1:40140 - - [24/May/2026:15:35:01 +0200] "GET /foo5 1.1" - - "-" "curl/8.5.0"
[2026-05-24 15:35:01 +0200] [2172700] [INFO] 127.0.0.1:40140 - - [24/May/2026:15:35:01 +0200] "GET /foo5 1.1" 200 5 "-" "curl/8.5.0"
[2026-05-24 15:35:01 +0200] [2172700] [INFO] 127.0.0.1:40154 - - [24/May/2026:15:35:01 +0200] "GET /foo6 1.1" - - "-" "curl/8.5.0"
[2026-05-24 15:35:01 +0200] [2172700] [INFO] 127.0.0.1:40154 - - [24/May/2026:15:35:01 +0200] "GET /foo6 1.1" 200 5 "-" "curl/8.5.0"
[2026-05-24 15:35:01 +0200] [2172700] [INFO] 127.0.0.1:40166 - - [24/May/2026:15:35:01 +0200] "GET /foo7 1.1" - - "-" "curl/8.5.0"
[2026-05-24 15:35:01 +0200] [2172700] [INFO] 127.0.0.1:40166 - - [24/May/2026:15:35:01 +0200] "GET /foo7 1.1" 200 5 "-" "curl/8.5.0"
[2026-05-24 15:35:01 +0200] [2172700] [INFO] 127.0.0.1:40172 - - [24/May/2026:15:35:01 +0200] "GET /foo8 1.1" - - "-" "curl/8.5.0"
[2026-05-24 15:35:01 +0200] [2172700] [INFO] 127.0.0.1:40172 - - [24/May/2026:15:35:01 +0200] "GET /foo8 1.1" 200 5 "-" "curl/8.5.0"
...

In this output, foo4 was logged correctly (once) and others were logged incorrectly (twice).

I tried on 3 different Linux machines -- the rate of duplicates varies, but all reproduced it.

What causes the bug

The duplicate log is a race condition that happens when this sequence of events occurs:

1. The ASGI app ends the response.
2. Hypercorn writes the HTTP response to the connected socket - HTTPStream._send_closed() calls await send(EndBody(...)).
3. curl reads the response and immediately closes the connection.
4. By the next time Python wakes up, the connection is closed. 2 tasks are ready to run: _send_closed wants to continue running, and the reader task wants to handle the socket closure.
5. The event loop scheduler decides that the reader task can run next.
6. The reader calls HTTPStream.handle(StreamClosed(...)). It checks self.state != ASGIHTTPState.CLOSED and logs the request with response=None. This produces the first log line, with status - -.
7. _send_closed is resumed after await send(EndBody(...)). It sets self.state = ASGIHTTPState.CLOSED and logs the request with response=self.response. This produces the second log line, with status 200.

Why only Trio?

You can't reproduce the problem with -k asyncio or -k uvloop. Does that mean it's a bug in the hypercorn/trio/ worker? No, it's just a quirk of task scheduling.

In asyncio, await self.writer.drain() doesn't always pause: "When there is nothing to wait for, the drain() returns immediately." If _send_closed returns immediately, then self.state is immediately set to CLOSED. Even if the task suspends, asyncio might preferentially wake it first (these details are not precisely documented).

(But in theory, maybe it could be reproducible in asyncio too, if you write a longer HTTP response.)

In trio, "If you call an async function provided by Trio (await <something in trio>), and it doesn’t raise an exception, then it always acts as a checkpoint." and "Currently we use a simple round-robin scheduling strategy." As a consequence, it is quite common that the reader task is scheduled to run before _send_closed can continue.

For testing, there is an artificial way to reproduce the problem with asyncio: just add a small sleep after writes.

diff --git i/src/hypercorn/asyncio/tcp_server.py w/src/hypercorn/asyncio/tcp_server.py
index 5612214..1a8e66e 100644
--- i/src/hypercorn/asyncio/tcp_server.py
+++ w/src/hypercorn/asyncio/tcp_server.py
@@ -82,6 +82,7 @@ class TCPServer:
                 try:
                     self.writer.write(event.data)
                     await self.writer.drain()
+                    await asyncio.sleep(0.001)
                 except (ConnectionError, RuntimeError):
                     await self.protocol.handle(Closed())
         elif isinstance(event, Closed):

How to fix it

Reorder statements in HTTPStream._send_closed (and HTTPStream._send_error_response, for symmetry) so self.state = ASGIHTTPState.CLOSED happens first.

This ensures that only _send_closed logs the request. Even if the client closes the connection before we get to close it, HTTPStream.handle() won't log it.

Is that fix safe?

Yes. Doing the self.state assignment sooner is not a breaking change.

HTTPStream.state is used for only two things:

1. It determines whether handle() calls log.access(). That's the subject of this bug.
2. It determines which ASGI messages are valid in app_send() when. With or without the fix, on successful completion of app_send(), the state will be CLOSED. The difference is observable only if:
   • ... the app makes multiple parallel calls to app_send(). Well-behaved ASGI apps are not supposed to do that, and AIUI Hypercorn already assumes they won't.
   • ... _send_closed() throws. Given lack of error handling in HTTPStream, I can't be certain, but if we tried and failed to close the connection, blocking further app_send() looks reasonable to me.

Plus: WSStream already does it. Both WSStream._accept and WSStream._send_rejection perform self.state = ... assignment before they call await self.send(...).