diff --git a/main.go b/main.go index ef18f50..ae68795 100644 --- a/main.go +++ b/main.go @@ -110,6 +110,9 @@ func main() { stop() log.Println("Shutting down...") + // First, and outside the graceful budget below: see stopDebugServer. + stopDebugServer(debugSrv) + // Safety net: force exit after timeout if graceful shutdown stalls. go func() { time.Sleep(5 * time.Second) @@ -130,11 +133,6 @@ func main() { if err := srv.Shutdown(shutdownCtx); err != nil { log.Printf("HTTP shutdown error: %v", err) } - if debugSrv != nil { - if err := debugSrv.Shutdown(shutdownCtx); err != nil { - log.Printf("debug HTTP shutdown error: %v", err) - } - } log.Println("Server stopped") } @@ -217,6 +215,27 @@ func serveDebug(srv *http.Server, listener net.Listener) { } } +// stopDebugServer closes the pprof listener and every connection on it. +// +// Close, not Shutdown. Shutdown waits for in-flight requests, and a pprof +// request can be a CPU profile or trace that runs for as many seconds as the +// caller asked. Sharing main's five-second shutdown context, one in-flight +// profile ran that context out: every such shutdown took the full five +// seconds, logged a debug shutdown error, and finished in a race with the +// force-exit watchdog, which is armed for the same five seconds and exits 1 +// if it wins. A profile cut short by a server that is going away is worth +// nothing, so the debug server takes no part in the graceful budget. Closing +// the connection cancels the request context, which ends pprof's wait and +// releases the CPU profiler. +func stopDebugServer(srv *http.Server) { + if srv == nil { + return + } + if err := srv.Close(); err != nil { + log.Printf("debug HTTP close error: %v", err) + } +} + func corsMiddleware(next http.Handler) http.Handler { return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { w.Header().Set("Access-Control-Allow-Origin", "*") diff --git a/main_test.go b/main_test.go index 1807d9f..716c354 100644 --- a/main_test.go +++ b/main_test.go @@ -5,10 +5,12 @@ import ( "context" "encoding/json" "errors" + "io" "log" "net" "net/http" "net/http/httptest" + "runtime/pprof" "strings" "testing" "time" @@ -323,6 +325,82 @@ func TestPublicMuxStillServesAfterTheDebugListenerDies(t *testing.T) { } } +// Shutdown must not wait on a pprof request. +// +// A CPU profile holds its request open for as many seconds as the caller asked. +// The test asks for 30 and requires stopDebugServer to return in well under the +// five seconds main gives the whole shutdown, and the profile request to end +// with it. Waiting on the CPU profiler itself makes "the profile is in flight" +// a fact rather than a sleep: StartCPUProfile fails while the handler holds it. +// That probe briefly holds the profiler too, so a request that lands inside it +// is refused with a 500 and simply asked again. +func TestStopDebugServerDoesNotWaitForAnInFlightProfile(t *testing.T) { + srv, err := startDebugServer(config.DebugConfig{Bind: "127.0.0.1:0"}) + if err != nil { + t.Fatalf("startDebugServer: %v", err) + } + t.Cleanup(func() { srv.Close() }) + + profileDone := make(chan struct{}) + go func() { + defer close(profileDone) + client := &http.Client{Timeout: 40 * time.Second} + for { + resp, err := client.Get("http://" + srv.Addr + "/debug/pprof/profile?seconds=30") + if err != nil { + return // the debug server closed the connection + } + io.Copy(io.Discard, resp.Body) + resp.Body.Close() + if resp.StatusCode != http.StatusInternalServerError { + return + } + time.Sleep(10 * time.Millisecond) + } + }() + + waitForCPUProfiler(t, true) + + start := time.Now() + stopDebugServer(srv) + if elapsed := time.Since(start); elapsed > time.Second { + t.Fatalf("stopDebugServer took %v with a profile in flight; want under 1s", elapsed) + } + + select { + case <-profileDone: + case <-time.After(5 * time.Second): + t.Fatal("profile request still open after the debug server stopped") + } + // The handler must also let go of the profiler, or the next profile fails. + waitForCPUProfiler(t, false) +} + +func TestStopDebugServerAcceptsNil(t *testing.T) { + stopDebugServer(nil) +} + +// waitForCPUProfiler waits until the process-wide CPU profiler is held by +// someone else (busy) or is free again (!busy). +func waitForCPUProfiler(t *testing.T, busy bool) { + t.Helper() + deadline := time.Now().Add(5 * time.Second) + for time.Now().Before(deadline) { + if err := pprof.StartCPUProfile(io.Discard); err != nil { + if busy { + return + } + } else { + pprof.StopCPUProfile() + if !busy { + return + } + } + time.Sleep(10 * time.Millisecond) + } + t.Fatalf("CPU profiler busy=%v never observed", busy) +} + // Display projection moved out of the binary into a plugin. A deployment that // configured it through [display] must keep working without being edited. func TestLegacyDisplayConfigReachesTheProjectorPlugin(t *testing.T) {