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

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.