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

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)
 			},
 		)
 	}

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.

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