diff --git a/TODO.md b/TODO.md index 53f31f5..4ae40cd 100644 --- a/TODO.md +++ b/TODO.md @@ -22,6 +22,12 @@ Decide whether the repo moves to the layout `REPO_POLICIES.md` gives, with # 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-07: the files shared from `sneak/prompts` are its copies at commit `dd4027b` ([#113](https://git.eeqj.de/sneak/netwatch/issues/113)), with this repository's own entries after the shared content in `.gitignore`, diff --git a/backend/internal/middleware/middleware.go b/backend/internal/middleware/middleware.go index 6d97b6e..f428f10 100644 --- a/backend/internal/middleware/middleware.go +++ b/backend/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/backend/internal/middleware/middleware_test.go b/backend/internal/middleware/middleware_test.go index bbfa7c1..ac4c1f9 100644 --- a/backend/internal/middleware/middleware_test.go +++ b/backend/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,161 @@ 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. +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) + } + + got := requestLogStatus(t, logbuf.Bytes()) + if got != http.StatusInternalServerError { + t.Errorf("request log status = %d, want %d", + got, http.StatusInternalServerError) + } + + 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) + } + } +} + +// requestLogStatus returns the status of the "request" line in the JSON +// log lines in logged. +func requestLogStatus(t *testing.T, logged []byte) int { + t.Helper() + + dec := json.NewDecoder(bytes.NewReader(logged)) + + for { + var line struct { + Msg string `json:"msg"` + Status int `json:"status"` + } + + err := dec.Decode(&line) + if err != nil { + t.Fatalf("no request line in the log: %v (%q)", err, logged) + } + + if line.Msg == "request" { + return line.Status + } + } +} + +// 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/backend/internal/server/routes.go b/backend/internal/server/routes.go index d13ecf6..73e715f 100644 --- a/backend/internal/server/routes.go +++ b/backend/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())