From e628dfe6cfb0dbc756d8d87acc5ae8c43f641567 Mon Sep 17 00:00:00 2001 From: clawbot <35+clawbot@noreply.example.org> Date: Wed, 14 Oct 2026 13:30:11 +0200 Subject: [PATCH] A handler's panic is logged and counted as 500 (closes #125) Recoverer comes first, so it wrote the 500 only after the panic had passed the request log and the metrics, which both recorded 200. Write500OnPanic, placed after the request log and after the metrics, writes the 500 as the panic passes and panics again, so Sentry and Recoverer still get it. Recoverer now writes its 500 only when no status was written, so the server logs no superfluous WriteHeader call. The test also requires Recoverer's log line for the handler's panic, so it fails if Write500OnPanic stops passing the panic on. Model: opus-5-5 --- TODO.md | 6 + internal/middleware/middleware.go | 45 ++++++- internal/middleware/middleware_test.go | 169 +++++++++++++++++++++++++ internal/server/routes.go | 9 +- 4 files changed, 223 insertions(+), 6 deletions(-) diff --git a/TODO.md b/TODO.md index 9cc6b21..0740d63 100644 --- a/TODO.md +++ b/TODO.md @@ -21,6 +21,12 @@ Run `make frontend-viewport-test` in CI as its own step; it is not part of # Completed Steps +- 2026-10-14: a request whose handler panics is logged with status 500 and + counted with `code` 500 in the metrics + ([#125](https://git.eeqj.de/sneak/netwatch/issues/125)), not 200. `Recoverer` + is still the first middleware; `Write500OnPanic`, after the request log and + after the metrics, writes the 500 as the panic passes and lets it go on to + Sentry and `Recoverer`, which now writes a 500 only when no status was written - 2026-10-14: with `TRUSTED_PROXIES` unset, the container's nginx trusts the three private ranges of RFC 1918, `10.0.0.0/8`, `172.16.0.0/12` and `192.168.0.0/16` ([#119](https://git.eeqj.de/sneak/netwatch/issues/119)), as diff --git a/internal/middleware/middleware.go b/internal/middleware/middleware.go index 6d97b6e..f428f10 100644 --- a/internal/middleware/middleware.go +++ b/internal/middleware/middleware.go @@ -297,12 +297,16 @@ func (s *Middleware) MaxBodyBytes( // Recoverer returns middleware that recovers from a panic in a // downstream handler, logs the panic and stack trace through -// slog, and responds 500 with no body. http.ErrAbortHandler is -// re-panicked so the server can abort the response as intended. +// slog, and responds 500 with no body, unless a status was already +// written, as Write500OnPanic writes one for a handler's panic. +// http.ErrAbortHandler is re-panicked so the server can abort the +// response as intended. func (s *Middleware) Recoverer() func(http.Handler) http.Handler { return func(next http.Handler) http.Handler { return http.HandlerFunc( func(w http.ResponseWriter, r *http.Request) { + ww := middleware.NewWrapResponseWriter(w, r.ProtoMajor) + defer func() { rec := recover() if rec == nil { @@ -320,10 +324,43 @@ func (s *Middleware) Recoverer() func(http.Handler) http.Handler { "stack", string(debug.Stack()), ) - w.WriteHeader(http.StatusInternalServerError) + if ww.Status() == 0 { + ww.WriteHeader(http.StatusInternalServerError) + } }() - next.ServeHTTP(w, r) + next.ServeHTTP(ww, r) + }, + ) + } +} + +// Write500OnPanic returns middleware that writes 500 when a downstream +// handler panics before writing a status, and lets the panic go on to +// Sentry and Recoverer. Recoverer, which comes first, would write its +// 500 only after the request log and the metrics had recorded the +// status they saw; placed after each of them, this makes them record +// the 500. +func (s *Middleware) Write500OnPanic() func(http.Handler) http.Handler { + return func(next http.Handler) http.Handler { + return http.HandlerFunc( + func(w http.ResponseWriter, r *http.Request) { + ww := middleware.NewWrapResponseWriter(w, r.ProtoMajor) + + defer func() { + rec := recover() + if rec == nil { + return + } + + if ww.Status() == 0 { + ww.WriteHeader(http.StatusInternalServerError) + } + + panic(rec) + }() + + next.ServeHTTP(ww, r) }, ) } diff --git a/internal/middleware/middleware_test.go b/internal/middleware/middleware_test.go index bbfa7c1..5d3fe51 100644 --- a/internal/middleware/middleware_test.go +++ b/internal/middleware/middleware_test.go @@ -4,6 +4,7 @@ import ( "bytes" "encoding/json" "errors" + "log" "log/slog" "net/http" "net/http/httptest" @@ -16,7 +17,9 @@ import ( "sneak.berlin/go/netwatch/internal/logger" "sneak.berlin/go/netwatch/internal/middleware" + "github.com/go-chi/chi/v5" chimiddleware "github.com/go-chi/chi/v5/middleware" + "github.com/prometheus/client_golang/prometheus" ) const ( @@ -323,6 +326,172 @@ func TestRecovererRepanicsOnAbortHandler(t *testing.T) { } } +// TestHandlerPanicIsLoggedAndCountedAs500 sends a request to a handler +// that panics through the middleware SetupRoutes puts around a route +// with metrics, in its order, leaving out those that write no status +// for a panic and Sentry, which TestSentry covers. The request log line +// and the metrics must give the 500 the client gets, and the panic must +// still reach Recoverer, which logs it. +func TestHandlerPanicIsLoggedAndCountedAs500(t *testing.T) { + t.Parallel() + + var logbuf bytes.Buffer + + mw := middleware.NewWithLogger( + slog.New(slog.NewJSONHandler(&logbuf, nil)), + ) + registry := prometheus.NewRegistry() + + handler := chi.Chain( + mw.Recoverer(), + chimiddleware.RequestID, + mw.Logging(), + mw.Write500OnPanic(), + mw.Metrics(registry), + mw.Write500OnPanic(), + ).HandlerFunc(func(http.ResponseWriter, *http.Request) { + panic("boom") + }) + + rec := httptest.NewRecorder() + req := httptest.NewRequestWithContext(t.Context(), http.MethodGet, "/", http.NoBody) + handler.ServeHTTP(rec, req) + + if rec.Code != http.StatusInternalServerError { + t.Fatalf("status = %d, want %d", + rec.Code, http.StatusInternalServerError) + } + + request := findLogLine(t, logbuf.Bytes(), "request") + if request.Status != http.StatusInternalServerError { + t.Errorf("request log status = %d, want %d", + request.Status, http.StatusInternalServerError) + } + + recovered := findLogLine(t, logbuf.Bytes(), "panic recovered") + if recovered.Panic != "boom" { + t.Errorf("panic recovered line has panic %q, want %q", + recovered.Panic, "boom") + } + + for _, name := range []string{ + "http_request_duration_seconds", "http_response_size_bytes", + } { + codes := metricCodes(t, registry, name) + if len(codes) != 1 || codes[0] != "500" { + t.Errorf("%s code labels = %v, want [500]", name, codes) + } + } +} + +// loggedLine holds the fields the tests read from a JSON log line. +type loggedLine struct { + Msg string `json:"msg"` + Status int `json:"status"` + Panic string `json:"panic"` +} + +// findLogLine returns the first of the JSON log lines in logged whose +// message is msg. +func findLogLine(t *testing.T, logged []byte, msg string) loggedLine { + t.Helper() + + dec := json.NewDecoder(bytes.NewReader(logged)) + + for { + var line loggedLine + + err := dec.Decode(&line) + if err != nil { + t.Fatalf("no %q line in the log: %v (%q)", msg, err, logged) + } + + if line.Msg == msg { + return line + } + } +} + +// metricCodes returns the code label of each series of the metric +// family name in registry. +func metricCodes( + t *testing.T, + registry *prometheus.Registry, + name string, +) []string { + t.Helper() + + families, err := registry.Gather() + if err != nil { + t.Fatalf("gather metrics: %v", err) + } + + var codes []string + + for _, family := range families { + if family.GetName() != name { + continue + } + + for _, metric := range family.GetMetric() { + for _, label := range metric.GetLabel() { + if label.GetName() == "code" { + codes = append(codes, label.GetValue()) + } + } + } + } + + return codes +} + +// TestRecovererWritesNoSecondStatus checks, on a real server, that +// Recoverer does not write its 500 again after Write500OnPanic has +// written one, which the server would log as a superfluous +// WriteHeader call. +func TestRecovererWritesNoSecondStatus(t *testing.T) { + t.Parallel() + + var serverLog bytes.Buffer + + mw := middleware.NewWithLogger(slog.New(slog.DiscardHandler)) + + server := httptest.NewUnstartedServer(chi.Chain( + mw.Recoverer(), + mw.Write500OnPanic(), + ).HandlerFunc(func(http.ResponseWriter, *http.Request) { + panic("boom") + })) + server.Config.ErrorLog = log.New(&serverLog, "", 0) + server.Start() + + req, err := http.NewRequestWithContext(t.Context(), + http.MethodGet, server.URL, http.NoBody) + if err != nil { + t.Fatalf("new request: %v", err) + } + + resp, err := server.Client().Do(req) + if err != nil { + t.Fatalf("request: %v", err) + } + + _ = resp.Body.Close() + + // Close waits for the handler to return, so whatever the server + // logs for this request is in serverLog after it. + server.Close() + + if resp.StatusCode != http.StatusInternalServerError { + t.Errorf("status = %d, want %d", + resp.StatusCode, http.StatusInternalServerError) + } + + if serverLog.Len() != 0 { + t.Errorf("server logged %q", serverLog.String()) + } +} + // TestLoggingCutsRequestStringsToBound sends an over-long URL and // over-long header values, and checks the request log writes each // one cut to logger.MaxLoggedFieldBytes. diff --git a/internal/server/routes.go b/internal/server/routes.go index d13ecf6..73e715f 100644 --- a/internal/server/routes.go +++ b/internal/server/routes.go @@ -34,13 +34,16 @@ func (s *Server) SetupRoutes() { s.router.Use(s.mw.Recoverer()) s.router.Use(middleware.RequestID) s.router.Use(s.mw.Logging()) + // s.mw.Recoverer would write a panic's 500 only after the panic has + // passed the request log, so it is written here, where the log sees it. + s.router.Use(s.mw.Write500OnPanic()) s.router.Use(s.mw.SecurityHeaders()) s.router.Use(s.mw.CORS(s.params.Config.CORSAllowedOrigins)) s.router.Use(s.mw.MaxBodyBytes(maxRequestBodyBytes)) s.router.Use(middleware.Timeout(requestTimeout)) - // Sentry reports a panic, then panics again, so that s.mw.Recoverer - // still answers 500. + // Sentry reports a panic, then panics again, so that it still + // reaches s.mw.Recoverer. if s.params.Config.SentryDSN != "" { s.router.Use(sentryhttp.New(sentryhttp.Options{Repanic: true}).Handle) } @@ -64,6 +67,8 @@ func (s *Server) SetupRoutes() { // other. if s.params.Config.MetricsUsername != "" { r.Use(s.mw.Metrics(registry)) + // Likewise inside the metrics. + r.Use(s.mw.Write500OnPanic()) } r.Get("/.well-known/healthcheck", s.h.HandleHealthCheck())