Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Open
c4rlo opened this issue Apr 13, 2024 · 11 comments
Labels
NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Milestone

Comments

@c4rlo
Copy link

c4rlo commented Apr 13, 2024

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
Copy link
Author

c4rlo commented Apr 13, 2024

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:

go/src/net/http/h2_bundle.go

Lines 6514 to 6516 in 519f6a0

if isHeadResp {
return len(p), nil
}

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:

go/src/net/http/h2_bundle.go

Lines 6245 to 6246 in 519f6a0

case <-st.cw:
return http2errStreamClosed

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

go/src/net/http/h2_bundle.go

Lines 6401 to 6405 in 519f6a0

if err == http2errStreamClosed {
// If writing failed because the stream has been closed,
// return the reason it was closed.
err = cw.rws.stream.closeErr
}

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
Copy link
Author

c4rlo commented Apr 13, 2024

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:

endStream := (rws.handlerDone && !rws.hasTrailers() && len(p) == 0) || isHeadResp

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

go/src/net/http/h2_bundle.go

Lines 4777 to 4778 in 519f6a0

case res := <-sc.wroteFrameCh:
sc.wroteFrame(res)

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

if http2writeEndsStream(wr.write) {

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

go/src/net/http/h2_bundle.go

Lines 5141 to 5142 in 519f6a0

case http2stateHalfClosedRemote:
sc.closeStream(st, http2errHandlerComplete)

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

st.cw.Close() // signals Handler's CloseNotifier, unblocks writes, etc

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
Copy link
Author

c4rlo commented Apr 13, 2024

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
Copy link
Author

c4rlo commented Apr 14, 2024

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
Copy link
Member

cc @neild

@cherrymui cherrymui added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Apr 16, 2024
@cherrymui cherrymui added this to the Unreleased milestone Apr 16, 2024
@neild
Copy link
Contributor

neild commented Apr 16, 2024

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
Copy link
Author

c4rlo commented Apr 17, 2024

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:

  • As you say, this is what happens with HTTP/1. I do think it is quite unfortunate for the behaviour to differ between HTTP/1 and HTTP/2, and it adds to the confusion.
  • The net/http library invokes GET handlers for HEAD requests, as seen in my example above. For that to make sense, especially given this behaviour isn't documented, I think it's is reasonable to expect things to "just work" when that happens. 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.

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
Copy link
Contributor

neild commented Apr 18, 2024

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
Copy link
Author

c4rlo commented Apr 21, 2024

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
Copy link
Author

c4rlo commented Apr 28, 2024

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
Copy link
Author

c4rlo commented May 11, 2024

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

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Projects
None yet
Development

No branches or pull requests

4 participants