openapi/v3: over HTTP/2, a write that fails because the client closed its connection is logged as "response failed"

[Zaba505]

What happens

Over HTTP/2, a client can cancel a streaming request and close its connection in one go. A client that keeps no idle connection does this, such as httpservertest.NewClient. When it does, the WriterTo's next write can fail with the connection's error, io: read/write on closed pipe on humustest's Host, while the request's context is still live. route.log checks ctx.Err() to decide whether the client went away, so the failure is logged as an ERROR record, "response failed", even though the client went away. The doc says a write that fails because the client went away goes on the span alone.

At 418776f, with Go 1.27, under -race: TestAPI_records_a_failed_write_after_the_client_went_away_on_the_span_only/over_HTTP/2, with its HTTP/2 client changed back to s.client (no idle connection), fails 28 times in 900 (-count=300 -cpu 1,2,4). The error is "a write that failed because the client went away isn't logged", and the record's exception.message is io: read/write on closed pipe. #1123 changed the test's client to one that keeps its connection, so the cancel resets only the stream. That test passes 900 times in 900, but the race is still there.

Repro, on top of 418776f, in openapi/v3/stream_test.go:

		{"over HTTP/2", func(s *server) *http.Client { return s.client }},

in place of the keep-alive client in that test, then:

go test -race -count=300 -cpu 1,2,4 -run 'TestAPI_records_a_failed_write_after_the_client_went_away_on_the_span_only' ./openapi/v3/

Why

The client's RST_STREAM and its connection close reach the server together. HTTP/2's server runs the handler's frame writes on a goroutine of their own and cancels a stream's context only once its serve loop processes the reset or sees the connection end. A frame write that fails on the closed connection can return its error to the handler first. So ctx.Err() is still nil when abort calls log.

On a real network the same order is possible, and latency usually hides it, because the server reads the reset before its write fails. Before #1123, humustest's unbuffered net.Pipe hid it too: the client's close couldn't complete until the server had read it.

Expected

A WriterTo's write that fails because the client went away, whether it reset the stream or closed the connection, goes on the span alone and isn't logged, as the doc of abort and log says.

References

• openapi/v3/serve.go: route.abort, route.log
• story(humustest): a TLS connection on the Host closes as on a real socket, even if its write deadline is reset during close_notify #1123, which exposed the race and changed the test's HTTP/2 client
• story(humustest): a TLS connection on the Host closes as on a real socket, even if its write deadline is reset during close_notify #1121, the story story(humustest): a TLS connection on the Host closes as on a real socket, even if its write deadline is reset during close_notify #1123 implemented

[Zaba505]

Triage

Verdict: a reproducible bug, not a misuse or a feature request. Over HTTP/2, a write that fails because the client closed its connection is logged as "response failed" whenever the failed write reaches the handler before the stream's context is cancelled. That happens without any test client quirk: it holds for every HTTP/2 client that goes away by closing its connection. HTTP/1.1 isn't affected. #1244 is filed to fix it.

Is this a misuse of humus?

No. The end user owns the WriterTo, and it does what the docs ask: it returns the write's error. humus owns what happens next. route.abort records the error and calls route.log, which decides whether the client went away.

The end user can't defend against it. When the write fails, the request's context is still live, so the WriterTo has nothing to tell a client that went away from a failure of its own.

Is it a feature request?

No. The behaviour contradicts these promises:

• doc.go: "When the request's context is done because the client went away, it goes on the span only."
• #760, revision 4: "A WriterTo that fails because the client went away is recorded on the span, and isn't logged."
• story(openapi): stream bodies both ways, and log a response that fails after its status #838's acceptance criteria: "a failure because the client went away: recorded on the span, and not logged".

doc.go names the request's context as the sign that the client went away. Over HTTP/1.1 the two always agree. Over HTTP/2 they don't, because the write fails before the context is done. The promise is about the client going away, and the context is how humus checks it.

A fix restores a promised behaviour. It changes no exported name, signature or default. Correcting doc.go's wording to match the fix isn't an API change.

Is it reproducible?

Yes. At 2c3726e, with Go 1.27.0, under -race, on humustest's Host:

scenario	runs failed
Over HTTP/2, the server's reads held from the client's cancel	4 of 4
Over HTTP/1.1, the server's reads held from the client's cancel	0 of 4
The report's repro: over HTTP/2 with httpservertest.NewClient, nothing held, -count=300 -cpu 1,2,4	4 of 4: 35, 35, 48 and 33 failures in 900
The existing TestAPI_records_a_failed_write_after_the_client_went_away_on_the_span_only, -count=300 -cpu 1,2,4	0 of 4: 0 failures in 900, each

Over HTTP/2, the reads held: the failed write is logged. The test wraps the Host's listener so that from the client's cancel, every read the server makes waits until the test releases it. The server then can't read the client's RST_STREAM or see the connection end. This forces the order the report describes. The client is httpservertest.NewClient, which keeps no idle connection.

1. The client reads row 0, cancels, and closes its connection.
2. The WriterTo's next write fails: the WriterTo's write failed with "io: read/write on closed pipe"; the request's context then: <nil>.
3. Before the server reads anything the client sent after its cancel, there is already a record: ERROR "response failed" map[error.type:*errors.errorString exception.message:io: read/write on closed pipe http.request.method:GET http.route:/rows].
4. The span has the exception, ["io: read/write on closed pipe"], with status Error. That part is as promised.

Over HTTP/1.1, the same: not logged. The write fails with the same error, but the context is already done: the request's context then: context canceled. No record is emitted.

Unheld, the race is wider than the failures show. Across the report's repro's 3600 iterations, the write failed with the context still live 179 times. 151 of those were logged. In the other 28, the context was cancelled between the failed write and log's check. So two goroutines race: the handler's, from the failed write to ctx.Err(), and the serve loop's, which cancels the stream.

This confirms the report: 28 in 900 at 418776f is the same rate as the 33–48 in 900 I saw at 2c3726e. The existing test passes because its client keeps its connection, so the cancel resets only the stream, and nothing makes a write fail.

Why

Go's HTTP/2 server runs each frame write on a goroutine of its own, and the serve loop handles its result in wroteFrame. When the write failed, wroteFrame closes the connection (L1196-L1198) and replies to the handler with the error (L1241). It cancels no stream. A stream's context is cancelled only by closeStream, which runs when the serve loop processes the client's RST_STREAM (processResetStream) or when it reads the connection's end and returns (closeAllStreamsOnConnClose). Reproduced: the held test shows the handler logging before either.

The serve loop also handles a pending write result before a frame it has read (L831-L839). So even when the client's reset reached the server first, the failed write is replied to first. I got that from Go's code and didn't reproduce it separately.

HTTP/1.1 cancels the request's context in checkConnErrorWriter.Write, before it returns a write's error. Reproduced: the held test over HTTP/1.1 sees context canceled when its write fails.

The same path is taken by any write after the status that fails on a closed HTTP/2 connection. That includes the catch-all's answer, which route.write also passes to abort, and a client that loses its connection without resetting the stream. I reasoned that from humus's and Go's code, and tested only a WriterTo that the client cancelled.

On the report's explanation: it holds. The reset doesn't have to arrive late for the failure to be logged, though: the serve loop orders a failed write ahead of a frame it has read.

#1244 is filed to fix it:

• over HTTP/2, a write that fails because the client closed its connection goes on the span alone, whichever the server does first;
• a WriterTo's own failure is still logged;
• the triage's reproductions join stream_test.go;
• doc.go, Encoder.Encode and the comments on abort and log say how the client going away is decided.

[Zaba505]

Fixed by #1249 (story #1244), merged as 02f0286.

The writer a WriterTo is handed now notes when a write or a flush fails because the connection did. A write the server refuses, a body for a status that has none or more bytes than the WriterTo's Len, still counts as the server's failure. A WriterTo failure is taken to be the client going away when the request's context is done, or when such a write failed. In that case it goes on the request's span alone, with the span's status set to Error, and no "response failed" record is emitted. So over HTTP/2, a write that fails on a closed connection before the server cancels the stream's context is no longer logged.

stream_test.go now holds the triage's reproductions: one with the server's reads held, over HTTP/2 and HTTP/1.1, and the report's repro over HTTP/2 with httpservertest.NewClient. Before the fix the report's repro failed 44 times in 900; after it, 900 in 900 passed.