Panic in deferred write-timeout flush when an upgraded (hijacked) connection outlives write_timeout #8151

Issue Details

Since #7945 (first released in v2.11.5), Server.ServeHTTP flushes the response in a deferred func when an HTTP/1.x request that is being access-logged took at least write_timeout. If the handler hijacked the connection, e.g. reverse_proxy passing through a 101 Switching Protocols upgrade, that flush panics with a nil pointer dereference.

Reproduced on v2.11.6 and v2.11.7, stock build without plugins.

Reproduce

Caddyfile:

{
	admin off
	servers {
		timeouts {
			write 1s
		}
	}
}

:8080 {
	log
	reverse_proxy 127.0.0.1:9000
}

upstream.py: answers every request with 101 and holds the connection until the peer closes it.

import socket, threading

def serve(c):
    c.recv(65536)
    c.sendall(b"HTTP/1.1 101 Switching Protocols\r\nConnection: Upgrade\r\nUpgrade: test\r\n\r\n")
    while c.recv(65536):
        pass
    c.close()

s = socket.socket()
s.setsockopt(socket.SOL_SOCKET, socket.SO_REUSEADDR, 1)
s.bind(("127.0.0.1", 9000))
s.listen()
while True:
    threading.Thread(target=serve, args=(s.accept()[0],), daemon=True).start()

python3 upstream.py &
caddy run --config Caddyfile &
# keep the upgraded connection open longer than write_timeout
(printf 'GET / HTTP/1.1\r\nHost: localhost\r\nConnection: Upgrade\r\nUpgrade: test\r\n\r\n'; sleep 2) | nc 127.0.0.1 8080

The client gets the 101 and the tunnel works. When it closes, the access log entry is written as usual ("status":101, "duration" ≈ 2s), and then:

{"level":"error","logger":"http.stdlib","msg":"http: panic serving 127.0.0.1:56866: runtime error: invalid memory address or nil pointer dereference
goroutine 68 [running]:
net/http.(*conn).serve.func1()
	net/http/server.go:1907 +0xac
panic({0x107588320?, 0x107af6170?})
	runtime/panic.go:860 +0x12c
bufio.(*Writer).Flush(0x1078443d8?)
	bufio/bufio.go:636 +0x18
net/http.(*response).FlushError(0x637fdd514000)
	net/http/server.go:1728 +0x38
net/http.(*ResponseController).Flush(0x637fdd1f6460?)
	net/http/responsecontroller.go:52 +0xdc
github.com/caddyserver/caddy/v2/modules/caddyhttp.(*IdleTimeoutWriter).FlushError(0x637fdd1f6460)
	github.com/caddyserver/caddy/v2@v2.11.7/modules/caddyhttp/idletimeout.go:326 +0x38
net/http.(*ResponseController).Flush(0x1421bcc2e?)
	net/http/responsecontroller.go:52 +0xdc
github.com/caddyserver/caddy/v2/modules/caddyhttp.(*responseRecorder).FlushError(0x107b21d40?)
	github.com/caddyserver/caddy/v2@v2.11.7/modules/caddyhttp/responsewriter.go:244 +0x38
net/http.(*ResponseController).Flush(0x107b03ea0?)
	net/http/responsecontroller.go:52 +0xdc
github.com/caddyserver/caddy/v2/modules/caddyhttp.(*Server).ServeHTTP.func1()
	github.com/caddyserver/caddy/v2@v2.11.7/modules/caddyhttp/server.go:692 +0x88
github.com/caddyserver/caddy/v2/modules/caddyhttp.(*Server).ServeHTTP(0x637fdd1b6408, {0x10796f7a0, 0x637fdd514000}, 0x637fdd508500)
	github.com/caddyserver/caddy/v2@v2.11.7/modules/caddyhttp/server.go:711 +0xfc8
net/http.serverHandler.ServeHTTP({0x637fdd1ba8c0?}, {0x10796f7a0?, 0x637fdd514000?}, 0x1?)
	net/http/server.go:3311 +0xb0
net/http.(*conn).serve(0x637fdd3be630, {0x10797b9d0, 0x637fdd228150})
	net/http/server.go:2073 +0x51c
created by net/http.(*Server).Serve in goroutine 99
	net/http/server.go:3464 +0x37c

With sleep 0.2 (shorter than write_timeout) there is no panic, and neither is there for a plain long-running request without the upgrade.

Cause

The deferred func calls http.NewResponseController(wrec).Flush() and ignores http.ErrHijacked, which assumes Flush reports a hijacked response that way. It doesn't: (*response).Hijack releases the bufio writer and sets w.w = nil, and (*response).FlushError calls w.w.Flush() without checking for a hijack. Only Write and WriteHeader check hijacked() and return ErrHijacked.

Impact

net/http recovers the panic, and it fires only after the upgraded stream has ended, so clients don't notice. But every upgraded connection that lives longer than write_timeout ends with an error-level stack trace. We hit this in production with headscale behind reverse_proxy (/ts2021 control protocol and /derp, both HTTP/1.1 upgrades) and write 30s, so practically every client session produces one.

Possible fix

Let responseRecorder remember the hijack and report it from FlushError; the deferred func already skips http.ErrHijacked:

--- a/modules/caddyhttp/responsewriter.go
+++ b/modules/caddyhttp/responsewriter.go
@@ -70,6 +70,7 @@ type responseRecorder struct {
 	size         int
 	wroteHeader  bool
 	stream       bool
+	hijacked     bool
 
 	readSize *int
 }
@@ -239,6 +240,11 @@ func (rr *responseRecorder) WriteResponse() error {
 // FlushError will suppress actual flushing if the response is buffered. See:
 // https://github.com/caddyserver/caddy/issues/6144
 func (rr *responseRecorder) FlushError() error {
+	// after a hijack the underlying writer is gone; net/http's FlushError
+	// doesn't check for that and dereferences a nil bufio.Writer
+	if rr.hijacked {
+		return http.ErrHijacked
+	}
 	if rr.stream {
 		//nolint:bodyclose
 		return http.NewResponseController(rr.ResponseWriterWrapper).Flush()
@@ -258,6 +264,7 @@ func (rr *responseRecorder) Hijack() (net.Conn, *bufio.ReadWriter, error) {
 	if err != nil {
 		return nil, nil, err
 	}
+	rr.hijacked = true
 	// Per http documentation, returned bufio.Writer is empty, but bufio.Read maybe not
 	conn = &hijackedConn{conn, rr}
 	brw.Writer.Reset(conn)

With this patch on v2.11.7 the reproduction no longer panics, the access log entry stays the same ("status":101, no error), and go test ./modules/caddyhttp/ ./modules/caddyhttp/reverseproxy/ passes. Happy to open a PR with a regression test.

Assistance Disclosure

AI used

If AI was used, describe the extent to which it was used.

Claude traced the panic from our production logs, built the reproduction, tested the patch and drafted this issue; I reviewed it