From fbd2a6c1352c2eb4e6cb02283b94efb1f2c8300e Mon Sep 17 00:00:00 2001 From: Andriy Palamarchuk Date: Sat, 3 Oct 2026 15:37:22 -0400 Subject: [PATCH] fix(proxy): log pprof serve errors instead of clean shutdowns The pprof goroutine logged an error only when Serve returned http.ErrServerClosed, which is the expected result of Stop. So every clean shutdown with --pprof logged "pprof server error: http: Server closed", and real serve failures were dropped silently. Invert the check and move the goroutine body into servePprof so a test can cover both cases. Co-Authored-By: Claude Opus 5.5 (1M context) --- proxy/proxy.go | 18 ++++++++++------- proxy/proxy_test.go | 48 +++++++++++++++++++++++++++++++++++++++++++++ 2 files changed, 59 insertions(+), 7 deletions(-) diff --git a/proxy/proxy.go b/proxy/proxy.go index d3ec4c6..be250f3 100644 --- a/proxy/proxy.go +++ b/proxy/proxy.go @@ -120,13 +120,7 @@ func (p *Server) Start() error { return fmt.Errorf("failed to listen on port %v for pprof server: %v", p.pprofPort, err) } - go func() { - p.logger.Info("Serving pprof on existing listener", "port", p.pprofPort) - if err := p.pprofServer.Serve(ln); err != nil && errors.Is(err, http.ErrServerClosed) { - p.logger.Error("pprof server error", "error", err) - } - }() - + go p.servePprof(ln) } var err error @@ -158,6 +152,16 @@ func (p *Server) Start() error { return nil } +// servePprof serves pprof on ln until the pprof server is shut down. Serve +// always returns a non-nil error, and http.ErrServerClosed is the expected +// result of Stop, so only other errors are logged. +func (p *Server) servePprof(ln net.Listener) { + p.logger.Info("Serving pprof on existing listener", "port", p.pprofPort) + if err := p.pprofServer.Serve(ln); err != nil && !errors.Is(err, http.ErrServerClosed) { + p.logger.Error("pprof server error", "error", err) + } +} + // Stops proxy server func (p *Server) Stop() error { if p.isStopped() { diff --git a/proxy/proxy_test.go b/proxy/proxy_test.go index ffd1c8d..703c447 100644 --- a/proxy/proxy_test.go +++ b/proxy/proxy_test.go @@ -1,7 +1,14 @@ package proxy import ( + "bytes" + "context" + "log/slog" + "net" + "net/http" "testing" + + "github.com/stretchr/testify/require" ) // TestProxyServerBasicHTTP tests basic HTTP request handling @@ -63,3 +70,44 @@ func TestProxyServerBasicHTTPS(t *testing.T) { pt.ExpectDeny("https://localhost:8080/", "example.com") }) } + +// TestServePprofLogsOnlyUnexpectedErrors verifies that a normal pprof +// shutdown is not reported as an error, while a real serve failure is. +func TestServePprofLogsOnlyUnexpectedErrors(t *testing.T) { + newServer := func(logs *bytes.Buffer) *Server { + return &Server{ + logger: slog.New(slog.NewTextHandler(logs, nil)), + pprofServer: &http.Server{}, + } + } + + t.Run("ShutdownIsNotAnError", func(t *testing.T) { + var logs bytes.Buffer + p := newServer(&logs) + ln, err := net.Listen("tcp", "127.0.0.1:0") + require.NoError(t, err) + + done := make(chan struct{}) + go func() { + p.servePprof(ln) + close(done) + }() + require.NoError(t, p.pprofServer.Shutdown(context.Background())) + <-done + + require.NotContains(t, logs.String(), "pprof server error") + }) + + t.Run("ServeFailureIsLogged", func(t *testing.T) { + var logs bytes.Buffer + p := newServer(&logs) + ln, err := net.Listen("tcp", "127.0.0.1:0") + require.NoError(t, err) + // Serve fails immediately on a closed listener. + require.NoError(t, ln.Close()) + + p.servePprof(ln) + + require.Contains(t, logs.String(), "pprof server error") + }) +}