net/http: http.TimeoutHandler rewrites panic stack trace

[co11ter]

What version of Go are you using (go version)?

$ go version
go version go1.17.7 linux/amd64

Does this issue reproduce with the latest release?

Currently using the latest

What operating system and processor architecture are you using (go env)?

go env Output

$ go env
GO111MODULE="on"
GOARCH="amd64"
GOBIN=""
GOCACHE="/home/co11ter/.cache/go-build"
GOENV="/home/co11ter/.config/go/env"
GOEXE=""
GOEXPERIMENT=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOINSECURE=""
GOMODCACHE="/home/co11ter/go/pkg/mod"
GONOPROXY="xdevteam.com"
GONOSUMDB="xdevteam.com"
GOOS="linux"
GOPATH="/home/co11ter/go"
GOPRIVATE="xdevteam.com"
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/usr/lib/go"
GOSUMDB="off"
GOTMPDIR=""
GOTOOLDIR="/usr/lib/go/pkg/tool/linux_amd64"
GOVCS=""
GOVERSION="go1.17.6"
GCCGO="gccgo"
AR="ar"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
GOMOD="/dev/null"
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -m64 -pthread -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build1126018893=/tmp/go-build -gno-record-gcc-switches"

What did you do?

I use http.TimeoutHandler middleware and fire panic in handler.

Code to reproduce:

package main

import (
	"log"
	"net/http"
	"time"
)

func main() {
	mux := http.NewServeMux()

	handler := http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
		panic("panic")
	})

	mux.Handle("/", http.TimeoutHandler(handler, time.Second, "timeout"))

	log.Fatal(http.ListenAndServe(":8080", mux))
}

What did you expect to see?

When I send http request to http://localhost:8080 I expect to get original stack trace of panic like:

2022/03/10 15:15:30 http: panic serving [::1]:34108: panic
goroutine 6 [running]:
net/http.(*conn).serve.func1()
	/usr/lib/go/src/net/http/server.go:1802 +0xb9
panic({0x6058e0, 0x697da0})
	/usr/lib/go/src/runtime/panic.go:1047 +0x266
main.main.func1({0xffffffffffffffff, 0x72}, 0x0)
	/home/co11ter/go/softswiss/a8r/cmd/tt/main.go:12 +0x27
net/http.HandlerFunc.ServeHTTP(0x0, {0x69bde0, 0xc000184000}, 0x0)
	/usr/lib/go/src/net/http/server.go:2047 +0x2f
net/http.(*timeoutHandler).ServeHTTP(0xc000026280, {0x69e5c0, 0xc0001401c0}, 0xc000164100)
	/usr/lib/go/src/net/http/server.go:3342 +0x893
net/http.(*ServeMux).ServeHTTP(0x0, {0x69e5c0, 0xc0001401c0}, 0xc000164100)
	/usr/lib/go/src/net/http/server.go:2425 +0x149
net/http.serverHandler.ServeHTTP({0xc000090030}, {0x69e5c0, 0xc0001401c0}, 0xc000164100)
	/usr/lib/go/src/net/http/server.go:2879 +0x43b
net/http.(*conn).serve(0xc00010ea00, {0x69f3c0, 0xc00007edb0})
	/usr/lib/go/src/net/http/server.go:1930 +0xb08
created by net/http.(*Server).Serve
	/usr/lib/go/src/net/http/server.go:3034 +0x4e8

That allows to investigate every problem in handler layer.

What did you see instead?

I get stack trace of panic in console that doesn't point to problem:

2022/03/10 15:15:30 http: panic serving [::1]:34108: panic
goroutine 6 [running]:
net/http.(*conn).serve.func1()
	/usr/lib/go/src/net/http/server.go:1802 +0xb9
panic({0x6058e0, 0x697da0})
	/usr/lib/go/src/runtime/panic.go:1047 +0x266
net/http.(*timeoutHandler).ServeHTTP(0xc000026280, {0x69e5c0, 0xc0001401c0}, 0xc000164100)
	/usr/lib/go/src/net/http/server.go:3342 +0x893
net/http.(*ServeMux).ServeHTTP(0x0, {0x69e5c0, 0xc0001401c0}, 0xc000164100)
	/usr/lib/go/src/net/http/server.go:2425 +0x149
net/http.serverHandler.ServeHTTP({0xc000090030}, {0x69e5c0, 0xc0001401c0}, 0xc000164100)
	/usr/lib/go/src/net/http/server.go:2879 +0x43b
net/http.(*conn).serve(0xc00010ea00, {0x69f3c0, 0xc00007edb0})
	/usr/lib/go/src/net/http/server.go:1930 +0xb08
created by net/http.(*Server).Serve
	/usr/lib/go/src/net/http/server.go:3034 +0x4e8

Additional investigation

https://github.com/golang/go/blob/master/src/net/http/server.go#L3379

The source code in http.TimeoutHandler rewrites panic and breaks stack trace. Thus we can not to investigate the original problem on handlers layer.

       /* .... */
	
       go func() {
		defer func() {
			if p := recover(); p != nil {
				panicChan <- p
			}
		}()
		h.handler.ServeHTTP(tw, r)
		close(done)
	}()
	select {
	case p := <-panicChan:
		panic(p)

        /* .... */

[mengzhuo]

You mean dump the ServeHTTP stack

by using https://pkg.go.dev/runtime/debug#PrintStack ?

if p := recover(); p != nil {
  debug.PrintStack()             
  panicChan <- p
}

---

also cc @neild per owner

[co11ter]

yes, indeed!

[gopherbot]

Change https://go.dev/cl/391474 mentions this issue: net/http: dump handler stack in TimeoutHandler while panic

[AlexanderYastrebov]

Original issue #22084

[mengzhuo]

Change https://go.dev/cl/391474 mentions this issue: net/http: dump handler stack in TimeoutHandler while panic

FYI, I've abandon CL391474.