x/net/http2: should not panic if func "called after Handler finished"

[markus-wa]

The way the stdlib http package handles duplicate calls to WriteHeader is by logging them, e.g.

2024/02/21 14:01:46 http: superfluous response.WriteHeader call from main.main.func1 (main.go:17)

The x/net/http2 pkg instead panics in the same situation (e.g. WriteHeader called after Handler finished). This is problematic as it makes it more difficult to implement something like a timeout middleware.

Is there a strict reason why x/net/http2 should behave differently to http in this scenario? Or can the implementation be changed to resemble the http behaviour more closely?

http example:

package main

import (
    "context"
    "fmt"
    "net/http"
    "time"
)

// longRunningHandler simulates a task that takes 2 seconds to complete
func longRunningHandler(w http.ResponseWriter, r *http.Request) {
    time.Sleep(2 * time.Second)
    w.WriteHeader(200)
    fmt.Fprintln(w, "Operation completed")
}

// timeoutMiddleware wraps an http.Handler and adds a timeout of 1 second
func timeoutMiddleware(next http.Handler) http.Handler {
    return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
        ctx, cancel := context.WithTimeout(r.Context(), 1*time.Second)
        defer cancel()

        finished := make(chan bool)
        go func() {
            next.ServeHTTP(w, r.WithContext(ctx))
            finished <- true
        }()

        select {
        case <-finished:
            // Request finished within timeout
        case <-ctx.Done():
            // Timeout occurred
            http.Error(w, "Request timed out", http.StatusGatewayTimeout)
        }
    })
}

func main() {
    mux := http.NewServeMux()
    mux.Handle("/", timeoutMiddleware(http.HandlerFunc(longRunningHandler)))

    server := &http.Server{
        Addr:    ":8080",
        Handler: mux,
    }

    fmt.Println("Starting http server on :8080")
    if err := server.ListenAndServe(); err != nil {
        fmt.Println("Server error:", err)
    }
}

This works fine with

 curl localhost:8080

x/net/http2 example:

package main

import (
    "context"
    "fmt"
    "net/http"
    "time"

    "golang.org/x/net/http2"
    "golang.org/x/net/http2/h2c"
)

// longRunningHandler simulates a task that takes 2 seconds to complete
func longRunningHandler(w http.ResponseWriter, r *http.Request) {
    time.Sleep(2 * time.Second)
    w.WriteHeader(200)
    fmt.Fprintln(w, "Operation completed")
}

// timeoutMiddleware wraps an http.Handler and adds a timeout of 1 second
func timeoutMiddleware(next http.Handler) http.Handler {
    return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
        ctx, cancel := context.WithTimeout(r.Context(), 1*time.Second)
        defer cancel()

        finished := make(chan bool)
        go func() {
            next.ServeHTTP(w, r.WithContext(ctx))
            finished <- true
        }()

        select {
        case <-finished:
            // Request finished within timeout
        case <-ctx.Done():
            // Timeout occurred
            http.Error(w, "Request timed out", http.StatusGatewayTimeout)
        }
    })
}

func main() {
    mux := http.NewServeMux()
    mux.Handle("/", timeoutMiddleware(http.HandlerFunc(longRunningHandler)))

    server := &http.Server{
        Addr:    ":8080",
        Handler: h2c.NewHandler(mux, &http2.Server{}),
    }

    fmt.Println("Starting H2C server on :8080")
    if err := server.ListenAndServe(); err != nil {
        fmt.Println("Server error:", err)
    }
}

This crashes the server:

curl --http2-prior-knowledge localhost:8080

This "works" (with warning log):

curl localhost:8080

[panjf2000]

Could you provide the stack info when the crash happened? Thanks!

[panjf2000]

Also the output of go env would be helpful for the diagnosis.

[panjf2000]

CC @neild

[markus-wa]

:warning: The below is just one occasion where this happens - sometimes the panic happens elsewhere, e.g. in func (w *responseWriter) FlushError() error {

stack trace

$ go run  cmd/main.go
Starting H2C server on :8080
panic: WriteHeader called after Handler finished

goroutine 11 [running]:
golang.org/x/net/http2.(*responseWriter).WriteHeader(0x77359400?, 0xc000058f48?)
        /home/mark/go/pkg/mod/golang.org/x/net@v0.21.0/http2/server.go:2892 +0x34
main.longRunningHandler({0x73db60, 0xc00005a098}, 0xc00005a098?)
        /home/mark/dev/esportal/cbb/services/cbb/cmd/main.go:16 +0x3b
net/http.HandlerFunc.ServeHTTP(0xc0000ba900?, {0x73db60?, 0xc00005a098?}, 0xc000058fd0?)
        /usr/lib/go/src/net/http/server.go:2166 +0x29
main.main.timeoutMiddleware.func1.1()
        /home/mark/dev/esportal/cbb/services/cbb/cmd/main.go:28 +0x69
created by main.main.timeoutMiddleware.func1 in goroutine 10
        /home/mark/dev/esportal/cbb/services/cbb/cmd/main.go:27 +0x13d
exit status 2

go env

GO111MODULE=''
GOARCH='amd64'
GOBIN=''
GOCACHE='/home/mark/.cache/go-build'
GOENV='/home/mark/.config/go/env'
GOEXE=''
GOEXPERIMENT=''
GOFLAGS=''
GOHOSTARCH='amd64'
GOHOSTOS='linux'
GOINSECURE=''
GOMODCACHE='/home/mark/go/pkg/mod'
GONOPROXY=''
GONOSUMDB=''
GOOS='linux'
GOPATH='/home/mark/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.0'
GCCGO='gccgo'
GOAMD64='v1'
AR='ar'
CC='gcc'
CXX='g++'
CGO_ENABLED='1'
GOMOD='/dev/null'
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-build3872931079=/tmp/go-build -gno-record-gcc-switches'

[panjf2000]

The relevant commits for net/http: flesh out http server and bufio:, Break responseWriter into small and large parts for x/net/http2.

Although I see no particular reasons for x/net/http2 to behave differently from net/http in this issue, I wonder why you would create a new goroutine for your handler in middleware, this is not the usual pattern that people would do with net/http, could you explain it a bit?

[markus-wa]

Well, http.TimeoutHandler also creates a goroutine - I don't know how you would implement a custom timeout middleware without a goroutine to be honest.

But that said, http.TimeoutHandler actually works with the current x/net/http2 implementation - so maybe my implementation is just too naive and I just need to use that approach of using something like a timeoutWriter - but this seems like a very easy mistake to make and one where we could spare users pain by aligning implementations.

I guess I mostly filed this issue to raise awareness of the differences between the two and that it can lead to confusion and very hard to debug problems. e.g. calling curl with or without --http2-prior-knowledge will either crash the server or "work" with the same code, which is quite a stark difference.

[panjf2000]

Thanks for the explanation and you're right about http.TimeoutHandler. But still, something like that is not the common pattern, may I ask why you chose to implement your handmade timeout handler instead of using http.TimeoutHandler, any particular reasons behind this?

Nevertheless, I do agree with you about the inconsistency between net/http and x/net/http2 leading to confusion for users. Maybe we should consider keeping this synchronized on this behavior? @neild

[markus-wa]

@panjf2000 we've had a case where we wanted a different http status code when timeouts were coming from our app rather than from somewhere on the way (pretty non-standard indeed). Other usecases I could imagine would be things like running some code (e.g. metrics / logging) when a timeout occurs.