golang / go

The Go programming language
https://go.dev
BSD 3-Clause "New" or "Revised" License
122.98k stars 17.54k forks source link

x/net/http2: response Write on HEAD fails with "http2: request body closed due to handler exiting" #66812

Open c4rlo opened 5 months ago

c4rlo commented 5 months ago

Go version

go version go1.22.2 linux/amd64

Output of go env in your module/workspace:

GO111MODULE=''
GOARCH='amd64'
GOBIN=''
GOCACHE='<some-path>/.cache/go-build'
GOENV='<some-path>/.config/go/env'
GOEXE=''
GOEXPERIMENT=''
GOFLAGS=''
GOHOSTARCH='amd64'
GOHOSTOS='linux'
GOINSECURE=''
GOMODCACHE='<some-path>/go/pkg/mod'
GONOPROXY=''
GONOSUMDB=''
GOOS='linux'
GOPATH='<some-path>/go'
GOPRIVATE=''
GOPROXY='https://proxy.golang.org,direct'
GOROOT='/usr/lib/go'
GOSUMDB='sum.golang.org'
GOTMPDIR=''
GOTOOLCHAIN='auto'
GOTOOLDIR='/usr/lib/go/pkg/tool/linux_amd64'
GOVCS=''
GOVERSION='go1.22.2'
GCCGO='gccgo'
GOAMD64='v1'
AR='ar'
CC='gcc'
CXX='g++'
CGO_ENABLED='1'
GOMOD='<some-path>/go.mod'
GOWORK=''
CGO_CFLAGS='-O2 -g'
CGO_CPPFLAGS=''
CGO_CXXFLAGS='-O2 -g'
CGO_FFLAGS='-O2 -g'
CGO_LDFLAGS='-O2 -g'
PKG_CONFIG='pkg-config'
GOGCCFLAGS='-fPIC -m64 -pthread -Wl,--no-gc-sections -fmessage-length=0 -ffile-prefix-map=/tmp/go-build4138323568=/tmp/go-build -gno-record-gcc-switches'

What did you do?

Implement a trivial net/http Server that listens via HTTPS (using a self-signed cert for dev purposes) and responds with a fixed 5KB response:

package main

import (
    "io"
    "log"
    "net/http"
    "strings"
)

func main() {
    http.HandleFunc("GET /{$}", func(w http.ResponseWriter, r *http.Request) {
        w.Header().Set("Content-Type", "text/plain; charset=utf-8")
        response := strings.Repeat("A", 5000) + "\n"
        if n, err := io.WriteString(w, response); err != nil {
            log.Printf("Failed to send response, wrote %d/%d bytes: %v", n, len(response), err)
        } else {
            log.Printf("Sent %d/%d response bytes", n, len(response))
        }
    })
    log.Println("Listening")
    log.Fatal(http.ListenAndServeTLS("127.0.0.1:8443", "server.cer.pem", "server.key.pem", nil))
}

What did you see happen?

When hitting the server with:

$ curl -k -I https://127.0.0.1:8443/

The response is as expected (i.e. code 200 but empty), but the server logs an error:

$ go run .
2024/04/13 17:21:22 Listening
2024/04/13 17:21:23 Failed to send response, wrote 4096/5001 bytes: http2: request body closed due to handler exiting

What did you expect to see?

No error logged.


Note that an error is only logged when using HTTP/2, and only when the response exceeds 4096 bytes.

Interestingly, a different error is logged if I remove the explicit setting of the Content-Type header (in which case the same header+value still ends up in the response, presumably because net/http auto-detects the content type):

2024/04/13 17:44:48 Failed to send response, wrote 4096/5001 bytes: short write
c4rlo commented 5 months ago

Looking into this a bit more, what seems to be happening is that ResponseWriter.Write ends up calling http2responseWriterState.writeChunk. That one has some special handling that should make it swallow Writes for HEAD requests:

https://github.com/golang/go/blob/519f6a00e4dabb871eadaefc8ac295c09fd9b56f/src/net/http/h2_bundle.go#L6514-L6516

However, it never gets that far. Instead, because !rws.sentHeader, it first calls rws.conn.writeHeaders, and that one queues the write and then – for some reason – gets to this select case:

https://github.com/golang/go/blob/519f6a00e4dabb871eadaefc8ac295c09fd9b56f/src/net/http/h2_bundle.go#L6245-L6246

That http2errStreamClosed then gets translated into a different error up the stack in http2chunkWriter.Write:

https://github.com/golang/go/blob/519f6a00e4dabb871eadaefc8ac295c09fd9b56f/src/net/http/h2_bundle.go#L6401-L6405

And that cw.rws.stream.closeErr ends up being the error we see (e.g. "http2: request body closed due to handler exiting" = http2errHandlerComplete).

That's as far as I got for now.

c4rlo commented 5 months ago

Ok, let's go deeper. We already mentioned that http2responseWriterState.writeChunk calls rws.conn.writeHeaders. In doing so, it passes it a http2writeResHeaders struct, one of whose fields is endStream. In the HEAD case, that gets set to true by this:

https://github.com/golang/go/blob/519f6a00e4dabb871eadaefc8ac295c09fd9b56f/src/net/http/h2_bundle.go#L6497

Let's now turn to http2serverConn.serve; after some initialisation, it consists of a for/select loop, with one of the select cases being:

https://github.com/golang/go/blob/519f6a00e4dabb871eadaefc8ac295c09fd9b56f/src/net/http/h2_bundle.go#L4777-L4778

Ok, so after writing each frame (we presume), it calls sc.wroteFrame. Looking into that, we see:

https://github.com/golang/go/blob/519f6a00e4dabb871eadaefc8ac295c09fd9b56f/src/net/http/h2_bundle.go#L5118

And http2writeEndsStream checks the endStream field mentioned above, hence returns true. It then ends up here (in my testing):

https://github.com/golang/go/blob/519f6a00e4dabb871eadaefc8ac295c09fd9b56f/src/net/http/h2_bundle.go#L5141-L5142

And one of the things that http2serverConn.closeStream does is:

https://github.com/golang/go/blob/519f6a00e4dabb871eadaefc8ac295c09fd9b56f/src/net/http/h2_bundle.go#L5499

Which (cw being of a type that is a thin wrapper around a channel) probably explains why we get into the case <-st.cw in http2serverConn.writeHeaders as mentioned in my previous comment.

Summarising: writeChunk calls writeHeaders in such a way that it closes the stream immediately afterwards, which (indirectly) causes writeHeaders to return http2errStreamClosed. And writeChunk is seemingly not expecting that, hence it passes that error on to its caller.

c4rlo commented 5 months ago

The following seems to be a fix – it fixes my example, at least:

diff --git a/src/net/http/h2_bundle.go b/src/net/http/h2_bundle.go
index 75454dba38..397f21ce9d 100644
--- a/src/net/http/h2_bundle.go
+++ b/src/net/http/h2_bundle.go
@@ -6483,12 +6483,12 @@ func (rws *http2responseWriterState) writeChunk(p []byte) (n int, err error) {
                        contentLength: clen,
                        date:          date,
                })
+               if endStream && (err == nil || err == http2errStreamClosed) {
+                       return len(p), nil
+               }
                if err != nil {
                        return 0, err
                }
-               if endStream {
-                       return 0, nil
-               }
        }
        if isHeadResp {
                return len(p), nil
c4rlo commented 5 months ago

If the maintainers agree that this fix goes in the right direction, I'd be happy to contribute it to the x/net/http2 package (I'm aware that's where the standard libary's h2_bundle.go is taken from).

seankhliao commented 5 months ago

cc @neild

neild commented 5 months ago

You're sending a HEAD request to a handler that writes a response body.

HEAD requests don't have a response body, of course, so the server needs to discard it.

There seems to be some divergence in how the HTTP/1 and HTTP/2 servers deal with the case of a handler writing a body in response to a HEAD request. (None of this is in my working memory, so I'm going off of a quick glance at the code, and I may be getting some of the details wrong.)

Both the HTTP/1 and HTTP/2 paths will buffer writes to the response body. If the entire body fits in the response buffer, then the server will send a Content-Length header based on how much was written before the handler exited. If the body doesn't fit in the response buffer, or if the handler flushes the buffer explicitly, then the server will send headers when the buffer fills. In this case it won't send a Content-Length unless the handler provided one.

Once the server has sent headers in response to a HEAD request, there's no point in the handler writing more of the response body--the server doesn't have anything to do with it, and all it can do is discard the bytes.

The HTTP/1 ResponseWriter silently discards the response bytes and returns success.

The HTTP/2 ResponseWriter discards the response bytes and returns an error. The error is confusing and wrong: "http2: response body closed due to handler exiting", but the handler hasn't exited.

I think returning an error is the better behavior here, since it lets the handler exit quickly. (Perhaps we should change the HTTP/1 server to do so as well, although Hyrum's Law probably applies here.) The error shouldn't lie about the handler being complete when it isn't, and ideally would explain what's going on: "stream closed" would be terse but accurate, "response body for HEAD request closed" might be more explanatory.

I don't think suppressing the error is the right option, though.

c4rlo commented 5 months ago

I think returning an error is the better behavior here, since it lets the handler exit quickly.

Fair point. However, there are also good arguments for why not returning an error is the right thing:

On balance, silently discarding writes for HTTP/2 (matching HTTP/1 behaviour) seems like the better way forward to me.

Or if we want to return an error, then I feel like we should find some way to make this the behaviour for both HTTP/1 and HTTP/2 – which as you point out is a breaking change (albeit of undocumented behaviour) so requires care.

neild commented 5 months ago

Which I'd argue implies that Write calls to the ResponseWriter should not return an error; that way, an existing handler written for a GET request is almost guaranteed to magically do the right thing for HEAD requests.

But a naive GET handler does do the right thing for HEAD requests: The server responds to the HEAD request with appropriate headers.

ResponseWriter.Write returning an error is a normal and expected condition, indicating that the handler can stop writing the response body because the client isn't reading it. This happens when a connection breaks mid-response (due to a network error, the client going away, or--in HTTP/2--the client canceling the request), or in this case when the response isn't being sent to the client at all.

Changing the HTTP/2 server to silently discard writes seems like a strict degradation of functionality.

c4rlo commented 5 months ago

But a naive GET handler does do the right thing for HEAD requests: The server responds to the HEAD request with appropriate headers.

True. Apart from the potentially confusing error trace in the logs (which is how I stumbled on this).

Regarding your comparison with other errors returned from ResponseWriter.Write: well, those are for transient conditions, whereas here we are systematically returning an error for a particular case where nothing even went wrong.

So yeah, it would certainly help to improve the error message wording. Something like "not writing data in response to HEAD request" maybe.

Ideally, also introduce a dedicated Err* value for this, enabling users to suppress it (in a non-brittle way). Given that this case is just part of the expected behaviour, and does not indicate any bad/abortive/unusual behaviour by either client, server, the network, or anything else.

Changing the HTTP/2 server to silently discard writes seems like a strict degradation of functionality.

I agree, there are downsides to doing this (causing the handler to do unnecessary work, and being a change in behaviour).

On the other hand, just tweaking the error message as suggested above also leaves the downside that (some) users will end up writing extra lines of code to suppress these non-error errors, and that it does not address (pre-existing) the inconsistency between HTTP/1 and HTTP/2.

But given that I seem to be the first one reporting this, that may be a reasonable trade-off; it would certainly be the more conservative change.

c4rlo commented 4 months ago

If the maintainers prefer the approach of merely tweaking the error message (and possibly exposing that error value as a public Err* variable), I'd be happy to have a go at implementing it.

c4rlo commented 4 months ago

Checking in here. Still happy to help out, once there is agreement from the maintainers on what the fix should look like.