Report handler panics through the logger and answer 500 (closes #187)

chi v1.5.5's middleware.Recoverer neither logged a handler panic nor
answered 500. Its pretty-printer scans the stack for a frame beginning
"panic(0x", which the runtime no longer emits, so the scan never
terminates early and every line reaches decorateFuncCallLine, which
slices pkg[strings.Index(pkg, "."):] without checking for -1. That
second panic escaped chi's own deferred function, so its
WriteHeader(500) never ran: net/http closed the connection and reported
its own crash, losing the original panic value entirely.

Middleware.Recoverer replaces it. It writes one ERROR record through
internal/logger carrying the panic value, the stack and the request id,
and answers 500. http.ErrAbortHandler is re-panicked rather than
swallowed, and a response the handler already committed is left alone
rather than overwritten.

It is registered inside every middleware that observes the response, so
the 500 is the status the access log records and the metrics count, and
outside the sentryhttp handler, whose Repanic option needs something
further out to catch what it re-raises.

Both fields are bounded in encoded bytes, as the access log's are: 512
for the panic value, since a handler may build one out of the request,
and 8192 for the stack, cut at its far end so the panic site survives.
MaxPanicLogLineBytes states the resulting ceiling at 10240; measured,
the widest either handler produces is 8898, and the real case through
the shipped chain is 3959.

internal/middleware/recoverer_test.go

@@ -0,0 +1,597 @@
+package middleware_test
+
+import (
+	"bytes"
+	"encoding/json"
+	"io"
+	"log"
+	"net/http"
+	"net/http/httptest"
+	"strings"
+	"testing"
+
+	"github.com/go-chi/chi"
+	chimw "github.com/go-chi/chi/middleware"
+	"github.com/stretchr/testify/assert"
+	"github.com/stretchr/testify/require"
+	"sneak.berlin/go/webhooker/internal/middleware"
+)
+
+// panicMarker is the panic value the probe handlers raise. The
+// recoverer's whole job is to put this string, and not some second
+// panic's, in front of an operator.
+const panicMarker = "QQORIGINALPANICVALUEQQ"
+
+// probeFuncName appears in the stack of every panic raised below,
+// since that is the function raising it. Its presence is how these
+// tests tell a real stack from an empty field.
+const probeFuncName = "panicProbe"
+
+// committedStatus is the status a handler sends before panicking in
+// the already-committed case. It is deliberately not 200, so a test
+// cannot pass on net/http's implicit default.
+const committedStatus = http.StatusMultiStatus
+
+// recovererProbe is a test server carrying one panicking route,
+// behind the production recoverer.
+type recovererProbe struct {
+	server *httptest.Server
+
+	// logs holds every record the middleware wrote.
+	logs *bytes.Buffer
+
+	// serverErrors holds everything net/http wrote to its own error
+	// log. A working recoverer leaves it empty: net/http only reports
+	// a request when a panic escapes the handler chain, which is the
+	// failure this issue is about.
+	serverErrors *bytes.Buffer
+}
+
+// newRecovererProbe stands up a real HTTP server — a real listener, a
+// real connection, a real client — behind the production recoverer.
+//
+// A real server rather than an httptest.ResponseRecorder, because a
+// recorder cannot express the outcome that made this a defect: chi's
+// Recoverer left net/http to close the connection, which a recorder
+// records as an ordinary unwritten response while a client sees EOF.
+// The status a client actually receives is only observable over a
+// socket.
+func newRecovererProbe(
+	t *testing.T,
+	textHandler bool,
+	handler http.HandlerFunc,
+) *recovererProbe {
+	t.Helper()
+
+	newMiddleware := capturingMiddleware
+	if textHandler {
+		newMiddleware = capturingTextMiddleware
+	}
+
+	m, logs := newMiddleware(t)
+
+	router := chi.NewRouter()
+	// The registration order the production router uses: RequestID
+	// outside so the recoverer's record can name the request,
+	// Logging outside so the recovered 500 is the status it records.
+	router.Use(chimw.RequestID)
+	router.Use(m.Logging())
+	router.Use(m.Recoverer())
+	router.Get("/probe", handler)
+
+	serverErrors := new(bytes.Buffer)
+
+	server := httptest.NewUnstartedServer(router)
+	server.Config.ErrorLog = log.New(serverErrors, "", 0)
+	server.Start()
+	t.Cleanup(server.Close)
+
+	return &recovererProbe{
+		server:       server,
+		logs:         logs,
+		serverErrors: serverErrors,
+	}
+}
+
+// get drives one request at the probe route and returns the response,
+// or the transport error if the connection was dropped instead.
+func (p *recovererProbe) get(t *testing.T) (*http.Response, error) {
+	t.Helper()
+
+	req, err := http.NewRequestWithContext(
+		t.Context(), http.MethodGet, p.server.URL+"/probe", nil,
+	)
+	require.NoError(t, err)
+
+	return p.server.Client().Do(req)
+}
+
+// wait shuts the server down and blocks until every in-flight request
+// has finished, which is what makes the log buffer safe to read.
+//
+// A client returns as soon as the response is complete — or, for a
+// deliberately aborted connection, as soon as it is closed — while the
+// access log line for the same request is still being written on the
+// server goroutine. It is idempotent, so a test may call it directly
+// before reading the buffer itself.
+func (p *recovererProbe) wait() {
+	p.server.Close()
+}
+
+// records decodes every JSON log line the probe captured.
+func (p *recovererProbe) records(t *testing.T) []map[string]any {
+	t.Helper()
+
+	p.wait()
+
+	var out []map[string]any
+
+	for line := range strings.SplitSeq(
+		strings.TrimSpace(p.logs.String()), "\n",
+	) {
+		if line == "" {
+			continue
+		}
+
+		record := map[string]any{}
+		require.NoError(t, json.Unmarshal([]byte(line), &record))
+
+		out = append(out, record)
+	}
+
+	return out
+}
+
+// panicRecord returns the single "handler panic" record, failing if
+// there is not exactly one.
+func (p *recovererProbe) panicRecord(t *testing.T) map[string]any {
+	t.Helper()
+
+	var found []map[string]any
+
+	for _, record := range p.records(t) {
+		if record["msg"] == "handler panic" {
+			found = append(found, record)
+		}
+	}
+
+	require.Len(
+		t, found, 1,
+		"exactly one panic record expected, log was:\n%s",
+		p.logs.String(),
+	)
+
+	return found[0]
+}
+
+// panicProbe panics with the marker. It is a named function so the
+// stack assertions have something to look for.
+func panicProbe(http.ResponseWriter, *http.Request) {
+	panic(panicMarker)
+}
+
+func TestRecovererAnswers500AndLogsTheOriginalPanic(t *testing.T) {
+	t.Parallel()
+
+	probe := newRecovererProbe(t, false, panicProbe)
+
+	resp, err := probe.get(t)
+	require.NoError(
+		t, err,
+		"a panicking handler must answer, not drop the connection",
+	)
+
+	defer func() { _ = resp.Body.Close() }()
+
+	body, err := io.ReadAll(resp.Body)
+	require.NoError(t, err)
+
+	assert.Equal(t, http.StatusInternalServerError, resp.StatusCode)
+	assert.Contains(t, string(body), "Internal Server Error")
+
+	record := probe.panicRecord(t)
+	assert.Equal(t, "ERROR", record["level"])
+	assert.Equal(t, panicMarker, record["panic"])
+	assert.Equal(t, false, record["response_committed"])
+
+	stack, ok := record["stack"].(string)
+	require.True(t, ok, "the record must carry a stack")
+	assert.Contains(
+		t, stack, probeFuncName,
+		"the stack must reach the function that panicked",
+	)
+	assert.NotContains(
+		t, stack, "slice bounds out of range",
+		"a secondary panic must not have occurred",
+	)
+
+	assert.Empty(
+		t, probe.serverErrors.String(),
+		"net/http must not have had to report anything",
+	)
+}
+
+// TestRecovererStatusReachesTheAccessLog pins the placement. The
+// recoverer runs inside the logging middleware precisely so the status
+// it writes is the one the access log records; registered outside it,
+// as chi's Recoverer was, the same request is logged as a 200 that the
+// client never received.
+func TestRecovererStatusReachesTheAccessLog(t *testing.T) {
+	t.Parallel()
+
+	probe := newRecovererProbe(t, false, panicProbe)
+
+	resp, err := probe.get(t)
+	require.NoError(t, err)
+	require.NoError(t, resp.Body.Close())
+	require.Equal(t, http.StatusInternalServerError, resp.StatusCode)
+
+	var access map[string]any
+
+	for _, record := range probe.records(t) {
+		if record["msg"] == "http request" {
+			access = record
+		}
+	}
+
+	require.NotNil(t, access, "the request must still be logged")
+	assert.EqualValues(
+		t, http.StatusInternalServerError, access["status"],
+		"the access log must record the status the client got",
+	)
+
+	// The panic record identifies its request by request_id alone,
+	// so that join has to work.
+	assert.Equal(
+		t, access["request_id"],
+		probe.panicRecord(t)["request_id"],
+	)
+	assert.NotEmpty(t, access["request_id"])
+}
+
+// TestRecovererRepanicsErrAbortHandler covers the one panic value that
+// must not be turned into a 500. net/http documents it as the way a
+// handler abandons a connection deliberately and special-cases it,
+// suppressing both the response and its own stack report.
+func TestRecovererRepanicsErrAbortHandler(t *testing.T) {
+	t.Parallel()
+
+	probe := newRecovererProbe(
+		t, false,
+		func(http.ResponseWriter, *http.Request) {
+			panic(http.ErrAbortHandler)
+		},
+	)
+
+	resp, err := probe.get(t)
+	if err == nil {
+		_ = resp.Body.Close()
+	}
+
+	require.Error(
+		t, err,
+		"an aborted handler must not answer with a status",
+	)
+
+	for _, record := range probe.records(t) {
+		assert.NotEqual(
+			t, "handler panic", record["msg"],
+			"a deliberate abort is not a fault to report",
+		)
+	}
+
+	assert.Empty(
+		t, probe.serverErrors.String(),
+		"net/http suppresses ErrAbortHandler; it must still see it",
+	)
+}
+
+// TestRecovererKeepsAnAlreadyCommittedResponse covers a handler that
+// panics after sending its status. The bytes are already on the wire,
+// so a second WriteHeader would change nothing the client sees and
+// would draw net/http's "superfluous response.WriteHeader" report.
+func TestRecovererKeepsAnAlreadyCommittedResponse(t *testing.T) {
+	t.Parallel()
+
+	probe := newRecovererProbe(
+		t, false,
+		func(w http.ResponseWriter, _ *http.Request) {
+			w.WriteHeader(committedStatus)
+			_, _ = w.Write([]byte("partial"))
+
+			panic(panicMarker)
+		},
+	)
+
+	resp, err := probe.get(t)
+	require.NoError(t, err)
+
+	defer func() { _ = resp.Body.Close() }()
+
+	body, err := io.ReadAll(resp.Body)
+	require.NoError(t, err)
+
+	assert.Equal(t, committedStatus, resp.StatusCode)
+	assert.Equal(t, "partial", string(body))
+
+	record := probe.panicRecord(t)
+	assert.Equal(t, panicMarker, record["panic"])
+	assert.Equal(
+		t, true, record["response_committed"],
+		"the record must say why no 500 was sent",
+	)
+
+	assert.NotContains(
+		t, probe.serverErrors.String(),
+		"superfluous response.WriteHeader",
+	)
+}
+
+// TestRecovererKeepsAnImplicitlyCommittedResponse is the same case
+// without an explicit WriteHeader: a bare Write commits the response
+// to 200 just as surely.
+func TestRecovererKeepsAnImplicitlyCommittedResponse(t *testing.T) {
+	t.Parallel()
+
+	probe := newRecovererProbe(
+		t, false,
+		func(w http.ResponseWriter, _ *http.Request) {
+			_, _ = w.Write([]byte("partial"))
+
+			panic(panicMarker)
+		},
+	)
+
+	resp, err := probe.get(t)
+	require.NoError(t, err)
+	require.NoError(t, resp.Body.Close())
+
+	assert.Equal(t, http.StatusOK, resp.StatusCode)
+	assert.Equal(
+		t, true, probe.panicRecord(t)["response_committed"],
+	)
+	assert.NotContains(
+		t, probe.serverErrors.String(),
+		"superfluous response.WriteHeader",
+	)
+}
+
+// panicFill is one construction for the oversized panic value the
+// bound tests raise, mirroring internal/middleware's access log fills:
+// plain text, the characters both handlers escape to two bytes, a bare
+// C0 control, and an astral non-printable the text handler spells with
+// a ten-byte \U escape.
+type panicFill struct {
+	name string
+	rune string
+}
+
+func panicFills() []panicFill {
+	return []panicFill{
+		{"plain", "x"},
+		{"quote", `"`},
+		{"backslash", `\`},
+		{"tab", "\t"},
+		{"newline", "\n"},
+		{"control", "\x01"},
+		{"astral", "\U0001000C"},
+	}
+}
+
+// TestRecovererBoundsThePanicRecord holds the record to its stated
+// ceiling with a panic value the size of a request. A handler is free
+// to build a panic value out of what the client sent, so the value is
+// charged a client-sized budget even though the stack is not.
+func TestRecovererBoundsThePanicRecord(t *testing.T) {
+	t.Parallel()
+
+	for _, handler := range []struct {
+		name string
+		text bool
+	}{{"json", false}, {"text", true}} {
+		for _, fill := range panicFills() {
+			t.Run(handler.name+"/"+fill.name, func(t *testing.T) {
+				t.Parallel()
+
+				value := strings.Repeat(
+					fill.rune, oversizedSegmentBytes,
+				) + tailMarker
+
+				probe := newRecovererProbe(
+					t, handler.text,
+					func(http.ResponseWriter, *http.Request) {
+						panic(value)
+					},
+				)
+
+				resp, err := probe.get(t)
+				require.NoError(t, err)
+				require.NoError(t, resp.Body.Close())
+				require.Equal(
+					t, http.StatusInternalServerError,
+					resp.StatusCode,
+				)
+				probe.wait()
+
+				for line := range strings.SplitSeq(
+					strings.TrimSpace(probe.logs.String()), "\n",
+				) {
+					assert.LessOrEqual(
+						t, len(line),
+						middleware.MaxPanicLogLineBytes,
+						"log line exceeded its stated bound",
+					)
+					assert.NotContains(
+						t, line, tailMarker,
+						"the far end of the panic value reached "+
+							"the log, so nothing truncated it",
+					)
+				}
+			})
+		}
+	}
+}
+
+// deepPanic recurses to depth and then panics, so the stack itself
+// overruns its budget. It is the only way to exercise the stack cut:
+// the shipped middleware chain does not come close (see
+// TestPanicThroughProductionRouter in internal/server).
+func deepPanic(depth int, value string) int {
+	if depth == 0 {
+		panic(value)
+	}
+
+	return deepPanic(depth-1, value) + 1
+}
+
+// TestRecovererBoundsTheStack is the widest line the service can be
+// made to write: an oversized stack and an oversized panic value on
+// the same record, over both log handlers. It holds that line to the
+// stated ceiling and reports what it measured, and it pins that a cut
+// stack keeps its near end — the panic site — rather than its far one.
+func TestRecovererBoundsTheStack(t *testing.T) {
+	t.Parallel()
+
+	for _, handler := range []struct {
+		name string
+		text bool
+	}{{"json", false}, {"text", true}} {
+		t.Run(handler.name, func(t *testing.T) {
+			t.Parallel()
+
+			// The escape-heavy fill is the expensive one: every rune
+			// costs two encoded bytes, so a budget counted raw would
+			// buy twice the field.
+			value := strings.Repeat(`"`, oversizedSegmentBytes) +
+				tailMarker
+
+			probe := newRecovererProbe(
+				t, handler.text,
+				func(http.ResponseWriter, *http.Request) {
+					_ = deepPanic(512, value)
+				},
+			)
+
+			resp, err := probe.get(t)
+			require.NoError(t, err)
+			require.NoError(t, resp.Body.Close())
+			require.Equal(
+				t, http.StatusInternalServerError, resp.StatusCode,
+			)
+			probe.wait()
+
+			// The text handler does not emit JSON, so the field-level
+			// assertions run on the JSON one; the line bound below
+			// is asserted on both, which is the point of the sweep.
+			if !handler.text {
+				stack, ok := probe.panicRecord(t)["stack"].(string)
+				require.True(t, ok)
+				assert.True(
+					t, strings.HasSuffix(stack, truncationSuffix),
+					"an oversized stack must be marked as cut",
+				)
+				assert.Contains(
+					t, stack, "deepPanic",
+					"the near end of the stack must survive the cut",
+				)
+				assert.NotContains(
+					t, stack, "net/http.(*conn).serve",
+					"the far end is what a cut discards",
+				)
+			}
+
+			widest := 0
+
+			for line := range strings.SplitSeq(
+				strings.TrimSpace(probe.logs.String()), "\n",
+			) {
+				assert.LessOrEqual(
+					t, len(line), middleware.MaxPanicLogLineBytes,
+				)
+				assert.NotContains(t, line, tailMarker)
+
+				widest = max(widest, len(line))
+			}
+
+			t.Logf(
+				"widest line measured: %d bytes (ceiling %d)",
+				widest, middleware.MaxPanicLogLineBytes,
+			)
+		})
+	}
+}
+
+// TestRecovererIgnoresANonPanickingHandler is the negative control:
+// the middleware must be inert on the ordinary path.
+func TestRecovererIgnoresANonPanickingHandler(t *testing.T) {
+	t.Parallel()
+
+	probe := newRecovererProbe(
+		t, false,
+		func(w http.ResponseWriter, _ *http.Request) {
+			w.WriteHeader(http.StatusTeapot)
+		},
+	)
+
+	resp, err := probe.get(t)
+	require.NoError(t, err)
+	require.NoError(t, resp.Body.Close())
+
+	assert.Equal(t, http.StatusTeapot, resp.StatusCode)
+
+	for _, record := range probe.records(t) {
+		assert.NotEqual(t, "handler panic", record["msg"])
+	}
+}
+
+// TestRecovererKeepsResponseControllerWorking pins the Unwrap method.
+// The middleware wraps the ResponseWriter to learn whether the
+// response was committed, and a wrapper without Unwrap hides
+// net/http's own writer from http.ResponseController, so a handler
+// that flushes or sets a deadline starts failing.
+//
+// The recoverer is the only middleware in the chain here. The access
+// logger's own wrapper does not implement Unwrap, so a chain
+// containing it fails this regardless of what the recoverer does;
+// what is being pinned is that the recoverer adds no such opacity of
+// its own.
+func TestRecovererKeepsResponseControllerWorking(t *testing.T) {
+	t.Parallel()
+
+	m, _ := capturingMiddleware(t)
+
+	handler := m.Recoverer()(http.HandlerFunc(
+		func(w http.ResponseWriter, _ *http.Request) {
+			_, _ = w.Write([]byte("chunk"))
+
+			flushErr := http.NewResponseController(w).Flush()
+			if flushErr != nil {
+				http.Error(
+					w, "flush failed",
+					http.StatusInternalServerError,
+				)
+
+				return
+			}
+		},
+	))
+
+	server := httptest.NewServer(handler)
+	t.Cleanup(server.Close)
+
+	req, err := http.NewRequestWithContext(
+		t.Context(), http.MethodGet, server.URL, nil,
+	)
+	require.NoError(t, err)
+
+	resp, err := server.Client().Do(req)
+	require.NoError(t, err)
+
+	defer func() { _ = resp.Body.Close() }()
+
+	body, err := io.ReadAll(resp.Body)
+	require.NoError(t, err)
+
+	assert.Equal(t, http.StatusOK, resp.StatusCode)
+	assert.Equal(t, "chunk", string(body))
+}