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())