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

Jump to bottom

net/http: on panic http.server re-runs the handler multiple times on Windows #57588

Closed
groenspans opened this issue Jan 4, 2023 · 4 comments
Closed

net/http: on panic http.server re-runs the handler multiple times on Windows #57588

groenspans opened this issue Jan 4, 2023 · 4 comments
Labels
FrozenDueToAge NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided.
Milestone
Go1.21

Comments

@groenspans
Copy link

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

$ go version
go version go1.19.4 windows/amd64

Does this issue reproduce with the latest release?

Yes

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

go env Output
$ go env
set GO111MODULE=
set GOARCH=amd64
set GOBIN=
set GOCACHE=C:\Users\Aljosja\AppData\Local\go-build
set GOENV=C:\Users\Aljosja\AppData\Roaming\go\env
set GOEXE=.exe
set GOEXPERIMENT=
set GOFLAGS=
set GOHOSTARCH=amd64
set GOHOSTOS=windows
set GOINSECURE=
set GOMODCACHE=C:\Users\Aljosja\go\pkg\mod
set GONOPROXY=
set GONOSUMDB=
set GOOS=windows
set GOPATH=C:\Users\Aljosja\go
set GOPRIVATE=
set GOPROXY=https://proxy.golang.org,direct
set GOROOT=C:\Program Files\Go
set GOSUMDB=sum.golang.org
set GOTMPDIR=
set GOTOOLDIR=C:\Program Files\Go\pkg\tool\windows_amd64
set GOVCS=
set GOVERSION=go1.19.4
set GCCGO=gccgo
set GOAMD64=v1
set AR=ar
set CC=gcc
set CXX=g++
set CGO_ENABLED=1
set GOMOD=C:\Users\Aljosja\documents\code\u4tools\go.mod
set GOWORK=
set CGO_CFLAGS=-g -O2
set CGO_CPPFLAGS=
set CGO_CXXFLAGS=-g -O2
set CGO_FFLAGS=-g -O2
set CGO_LDFLAGS=-g -O2
set PKG_CONFIG=pkg-config
set GOGCCFLAGS=-m64 -mthreads -fno-caret-diagnostics -Qunused-arguments -Wl,--no-gc-sections -fmessage-length=0 -fdebug-prefix-map=C:\Users\Aljosja\AppData\Local\Temp\go-build1729482487=/tmp/go-build -gno-record-gcc-switches

What did you do?

In a simple HTTP server with a handler that panics (either through calling panic() or by dereferencing a nil pointer) on Windows, the server runs the handler again multiple times for the same request. On Linux, the handler runs only once.

package main

import (
	"fmt"
	"net/http"
)

func main() {
	mux := http.NewServeMux()
	mux.HandleFunc("/panic", func(w http.ResponseWriter, r *http.Request) {
		fmt.Println("hello world!")
		panic("damn")
	})
	mux.HandleFunc("/npe", func(w http.ResponseWriter, r *http.Request) {
		fmt.Println("hello world!")
		var err error
		fmt.Println("Error: %s", err.Error())
	})
	mux.HandleFunc("/success", func(w http.ResponseWriter, r *http.Request) {
		fmt.Println("hello world!")
	})

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

What did you expect to see?

I expect the console log to show one stack trace indicating a panic, and the HTTP connection to close. (This is the behaviour on Linux.)

What did you see instead?

The HTTP connection remains open, and the console log shows several stack traces.

Example log file. This log file is for a single request.
$  go run cmd/main.go
hello world!
2023/01/04 21:31:18 http: panic serving [::1]:54121: runtime error: invalid memory address or nil pointer dereference
goroutine 6 [running]:
net/http.(*conn).serve.func1()
        C:/Program Files/Go/src/net/http/server.go:1850 +0xbf
panic({0x718c00, 0x923ae0})
        C:/Program Files/Go/src/runtime/panic.go:890 +0x262
main.main.func2({0x3b?, 0xffffffffffffffff?}, 0x58eada?)
        C:/Users/Aljosja/documents/code/u4tools/cmd/main.go:17 +0x58
net/http.HandlerFunc.ServeHTTP(0xc00006faf0?, {0x7c8348?, 0xc0001a8000?}, 0x0?)
        C:/Program Files/Go/src/net/http/server.go:2109 +0x2f
net/http.(*ServeMux).ServeHTTP(0x0?, {0x7c8348, 0xc0001a8000}, 0xc000142000)
        C:/Program Files/Go/src/net/http/server.go:2487 +0x149
net/http.serverHandler.ServeHTTP({0xc0001011a0?}, {0x7c8348, 0xc0001a8000}, 0xc000142000)
        C:/Program Files/Go/src/net/http/server.go:2947 +0x30c
net/http.(*conn).serve(0xc000000be0, {0x7c8720, 0xc0001010b0})
        C:/Program Files/Go/src/net/http/server.go:1991 +0x607
created by net/http.(*Server).Serve
        C:/Program Files/Go/src/net/http/server.go:3102 +0x4db
hello world!
2023/01/04 21:31:19 http: panic serving [::1]:54122: runtime error: invalid memory address or nil pointer dereference
goroutine 34 [running]:
net/http.(*conn).serve.func1()
        C:/Program Files/Go/src/net/http/server.go:1850 +0xbf
panic({0x718c00, 0x923ae0})
        C:/Program Files/Go/src/runtime/panic.go:890 +0x262
main.main.func2({0x3b?, 0xffffffffffffffff?}, 0x58eada?)
        C:/Users/Aljosja/documents/code/u4tools/cmd/main.go:17 +0x58
net/http.HandlerFunc.ServeHTTP(0xc000097af0?, {0x7c8348?, 0xc000148000?}, 0x0?)
        C:/Program Files/Go/src/net/http/server.go:2109 +0x2f
net/http.(*ServeMux).ServeHTTP(0x0?, {0x7c8348, 0xc000148000}, 0xc0000a8000)
        C:/Program Files/Go/src/net/http/server.go:2487 +0x149
net/http.serverHandler.ServeHTTP({0xc00008a090?}, {0x7c8348, 0xc000148000}, 0xc0000a8000)
        C:/Program Files/Go/src/net/http/server.go:2947 +0x30c
net/http.(*conn).serve(0xc00008e000, {0x7c8720, 0xc0001010b0})
        C:/Program Files/Go/src/net/http/server.go:1991 +0x607
created by net/http.(*Server).Serve
        C:/Program Files/Go/src/net/http/server.go:3102 +0x4db
hello world!
2023/01/04 21:31:19 http: panic serving [::1]:54124: runtime error: invalid memory address or nil pointer dereference
goroutine 35 [running]:
net/http.(*conn).serve.func1()
        C:/Program Files/Go/src/net/http/server.go:1850 +0xbf
panic({0x718c00, 0x923ae0})
        C:/Program Files/Go/src/runtime/panic.go:890 +0x262
main.main.func2({0x3b?, 0xffffffffffffffff?}, 0x58eada?)
        C:/Users/Aljosja/documents/code/u4tools/cmd/main.go:17 +0x58
net/http.HandlerFunc.ServeHTTP(0xc000099af0?, {0x7c8348?, 0xc0001480e0?}, 0x0?)
        C:/Program Files/Go/src/net/http/server.go:2109 +0x2f
net/http.(*ServeMux).ServeHTTP(0x0?, {0x7c8348, 0xc0001480e0}, 0xc0000a8100)
        C:/Program Files/Go/src/net/http/server.go:2487 +0x149
net/http.serverHandler.ServeHTTP({0xc00008a180?}, {0x7c8348, 0xc0001480e0}, 0xc0000a8100)
        C:/Program Files/Go/src/net/http/server.go:2947 +0x30c
net/http.(*conn).serve(0xc00008e0a0, {0x7c8720, 0xc0001010b0})
        C:/Program Files/Go/src/net/http/server.go:1991 +0x607
created by net/http.(*Server).Serve
        C:/Program Files/Go/src/net/http/server.go:3102 +0x4db
hello world!
2023/01/04 21:31:19 http: panic serving [::1]:54125: runtime error: invalid memory address or nil pointer dereference
goroutine 9 [running]:
net/http.(*conn).serve.func1()
        C:/Program Files/Go/src/net/http/server.go:1850 +0xbf
panic({0x718c00, 0x923ae0})
        C:/Program Files/Go/src/runtime/panic.go:890 +0x262
main.main.func2({0x3b?, 0xffffffffffffffff?}, 0x58eada?)
        C:/Users/Aljosja/documents/code/u4tools/cmd/main.go:17 +0x58
net/http.HandlerFunc.ServeHTTP(0xc00005baf0?, {0x7c8348?, 0xc0001a80e0?}, 0x0?)
        C:/Program Files/Go/src/net/http/server.go:2109 +0x2f
net/http.(*ServeMux).ServeHTTP(0x0?, {0x7c8348, 0xc0001a80e0}, 0xc0000a8200)
        C:/Program Files/Go/src/net/http/server.go:2487 +0x149
net/http.serverHandler.ServeHTTP({0xc00008a210?}, {0x7c8348, 0xc0001a80e0}, 0xc0000a8200)
        C:/Program Files/Go/src/net/http/server.go:2947 +0x30c
net/http.(*conn).serve(0xc000000c80, {0x7c8720, 0xc0001010b0})
        C:/Program Files/Go/src/net/http/server.go:1991 +0x607
created by net/http.(*Server).Serve
        C:/Program Files/Go/src/net/http/server.go:3102 +0x4db
hello world!
2023/01/04 21:31:24 http: panic serving [::1]:54134: runtime error: invalid memory address or nil pointer dereference
goroutine 20 [running]:
net/http.(*conn).serve.func1()
        C:/Program Files/Go/src/net/http/server.go:1850 +0xbf
panic({0x718c00, 0x923ae0})
        C:/Program Files/Go/src/runtime/panic.go:890 +0x262
main.main.func2({0x3b?, 0xffffffffffffffff?}, 0x58eada?)
        C:/Users/Aljosja/documents/code/u4tools/cmd/main.go:17 +0x58
net/http.HandlerFunc.ServeHTTP(0xc00005baf0?, {0x7c8348?, 0xc0001a81c0?}, 0x0?)
        C:/Program Files/Go/src/net/http/server.go:2109 +0x2f
net/http.(*ServeMux).ServeHTTP(0x0?, {0x7c8348, 0xc0001a81c0}, 0xc000184300)
        C:/Program Files/Go/src/net/http/server.go:2487 +0x149
net/http.serverHandler.ServeHTTP({0xc000186210?}, {0x7c8348, 0xc0001a81c0}, 0xc000184300)
        C:/Program Files/Go/src/net/http/server.go:2947 +0x30c
net/http.(*conn).serve(0xc000218000, {0x7c8720, 0xc0001010b0})
        C:/Program Files/Go/src/net/http/server.go:1991 +0x607
created by net/http.(*Server).Serve
        C:/Program Files/Go/src/net/http/server.go:3102 +0x4db
hello world!
2023/01/04 21:31:54 http: panic serving [::1]:54135: runtime error: invalid memory address or nil pointer dereference
goroutine 36 [running]:
net/http.(*conn).serve.func1()
        C:/Program Files/Go/src/net/http/server.go:1850 +0xbf
panic({0x718c00, 0x923ae0})
        C:/Program Files/Go/src/runtime/panic.go:890 +0x262
main.main.func2({0x3b?, 0xffffffffffffffff?}, 0x58eada?)
        C:/Users/Aljosja/documents/code/u4tools/cmd/main.go:17 +0x58
net/http.HandlerFunc.ServeHTTP(0xc000093af0?, {0x7c8348?, 0xc0001a82a0?}, 0x0?)
        C:/Program Files/Go/src/net/http/server.go:2109 +0x2f
net/http.(*ServeMux).ServeHTTP(0x0?, {0x7c8348, 0xc0001a82a0}, 0xc0000a8300)
        C:/Program Files/Go/src/net/http/server.go:2487 +0x149
net/http.serverHandler.ServeHTTP({0xc00008a2d0?}, {0x7c8348, 0xc0001a82a0}, 0xc0000a8300)
        C:/Program Files/Go/src/net/http/server.go:2947 +0x30c
net/http.(*conn).serve(0xc00008e140, {0x7c8720, 0xc0001010b0})
        C:/Program Files/Go/src/net/http/server.go:1991 +0x607
created by net/http.(*Server).Serve
        C:/Program Files/Go/src/net/http/server.go:3102 +0x4db
hello world!
2023/01/04 21:31:54 http: panic serving [::1]:54183: runtime error: invalid memory address or nil pointer dereference
goroutine 23 [running]:
net/http.(*conn).serve.func1()
        C:/Program Files/Go/src/net/http/server.go:1850 +0xbf
panic({0x718c00, 0x923ae0})
        C:/Program Files/Go/src/runtime/panic.go:890 +0x262
main.main.func2({0x3b?, 0xffffffffffffffff?}, 0x58eada?)
        C:/Users/Aljosja/documents/code/u4tools/cmd/main.go:17 +0x58
net/http.HandlerFunc.ServeHTTP(0xc000057af0?, {0x7c8348?, 0xc0001481c0?}, 0x0?)
        C:/Program Files/Go/src/net/http/server.go:2109 +0x2f
net/http.(*ServeMux).ServeHTTP(0x0?, {0x7c8348, 0xc0001481c0}, 0xc000184600)
        C:/Program Files/Go/src/net/http/server.go:2487 +0x149
net/http.serverHandler.ServeHTTP({0xc0001863f0?}, {0x7c8348, 0xc0001481c0}, 0xc000184600)
        C:/Program Files/Go/src/net/http/server.go:2947 +0x30c
net/http.(*conn).serve(0xc0002180a0, {0x7c8720, 0xc0001010b0})
        C:/Program Files/Go/src/net/http/server.go:1991 +0x607
created by net/http.(*Server).Serve
        C:/Program Files/Go/src/net/http/server.go:3102 +0x4db
exit status 0xc000013a
@heschi
Copy link
Contributor

heschi commented Jan 4, 2023

cc @neild

@heschi heschi added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Jan 4, 2023
@heschi heschi added this to the Go1.21 milestone Jan 4, 2023
@seankhliao
Copy link
Member

how are you making the requests?
The "http: panic serving [::1]:54122" lines each have a different port, pointing at separate requests / connections, which can't be from the same handler being run multiple times.

@seankhliao seankhliao added the WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided. label Jan 4, 2023
@groenspans
Copy link
Author

Thanks for looking with me and very sharp observation about the different port numbers, I hadn't noticed that yet. The requests from the example log were made through Chrome, Firefox and Edge. I now tried a curl through Windows PowerShell which resulted in 2 retries, a curl from Git Bash gave the expected 1. Interestingly enough the devtools in the browsers don't seem to show they're making new requests, but apparently they are doing that silently (as is PowerShell doing once).

@antichris
Copy link

The Chromium family browsers automatically retry requests on certain errors (see bug 143425), and ERR_EMPTY_RESPONSE (which happens when a handler panics) is among those.

@golang golang locked and limited conversation to collaborators Jan 10, 2024
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
FrozenDueToAge NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided.
Projects
None yet
Milestone
Go1.21
Development

No branches or pull requests
5 participants
@antichris @gopherbot @seankhliao @heschi @groenspans