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.

Every growable field on the record is bounded in encoded bytes, through
the same internal/logfield budget the access log spends: 512 for the
panic value, since a handler may build one out of the request, 128 for
the request id, which a client supplies outright through X-Request-Id,
and 8192 for the stack, cut at its far end so the panic site survives.
MaxPanicLogLineBytes states the resulting ceiling at 10240 over an
arithmetic sum of 9121. Driving all three past their budgets at once
measured 9009 bytes on the JSON handler and 8982 to 8983 on the text
one in one checkout, and the real case through the shipped chain
measures roughly 3960. Those figures are illustrations rather than
invariants: the stack's own content decides where its cut lands, and
debug.Stack() embeds absolute source paths, so both move. No test
asserts a figure; the tests assert the ceiling and that each growable
field was cut.

Because the panic record no longer reaches net/http's error log, the
carve-outs in README.md and in the MaxAccessLogLineBytes doc comment
that described that path are removed rather than reworded. What
replaces them states the ceiling the record is now written under, and
internal/server/recoverer_test.go asserts that "http: panic serving"
appears in neither of the process's streams.

internal/middleware/recoverer_test.go

@@ -0,0 +1,645 @@
+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()
+
+	return p.getWithRequestID(t, "")
+}
+
+// getWithRequestID drives the same request carrying a client-supplied
+// X-Request-Id. chi's RequestID middleware adopts that header verbatim
+// when it is present and only generates a value when it is absent, so
+// this is the third growable field on the panic record and the only
+// one a client fills outright.
+func (p *recovererProbe) getWithRequestID(
+	t *testing.T,
+	requestID string,
+) (*http.Response, error) {
+	t.Helper()
+
+	req, err := http.NewRequestWithContext(
+		t.Context(), http.MethodGet, p.server.URL+"/probe", nil,
+	)
+	require.NoError(t, err)
+
+	if requestID != "" {
+		req.Header.Set(chimw.RequestIDHeader, requestID)
+	}
+
+	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",
+	)
+}
+
+// panicLogHandler names one of the two handlers internal/logger can
+// install. The recoverer's probe selects between them with a bool
+// rather than by constructing one, which is why this does not reuse
+// logHandlers() the way the fills reuse escapeFills().
+type panicLogHandler struct {
+	name string
+	text bool
+}
+
+func panicLogHandlers() []panicLogHandler {
+	return []panicLogHandler{{"json", false}, {"text", true}}
+}
+
+// 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 panicLogHandlers() {
+		// The fills are internal/middleware's own access log fills,
+		// shared rather than restated: 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.
+		for fillName, fillRune := range escapeFills() {
+			t.Run(handler.name+"/"+fillName, func(t *testing.T) {
+				t.Parallel()
+
+				value := strings.Repeat(
+					fillRune, 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
+}
+
+// assertEveryFieldWasCut holds each of the record's three growable
+// fields to its own budget, which is what the ceiling is the sum of.
+// The stack is cut at its far end, so its near end — the panic site —
+// has to survive; the request id is the client's own bytes, so its
+// cut is the one that bounds an attacker rather than our own call
+// depth.
+func assertEveryFieldWasCut(t *testing.T, record map[string]any) {
+	t.Helper()
+
+	stack, ok := record["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",
+	)
+
+	id, ok := record["request_id"].(string)
+	require.True(t, ok)
+	assert.True(
+		t, strings.HasSuffix(id, truncationSuffix),
+		"an oversized request id must be marked as cut",
+	)
+	assert.LessOrEqual(
+		t, len(id), maxRequestIDBytes+len(truncationSuffix),
+		"the request id must be held to its own budget",
+	)
+
+	value, ok := record["panic"].(string)
+	require.True(t, ok)
+	assert.True(
+		t, strings.HasSuffix(value, truncationSuffix),
+		"an oversized panic value must be marked as cut",
+	)
+}
+
+// TestRecovererBoundsTheStack drives every growable field on the
+// record past its budget at once — an oversized stack, an oversized
+// panic value and an oversized client-supplied X-Request-Id — 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.
+//
+// The two fields the test picks the content of — the panic value and
+// the request id — are filled with the quotation mark. Both handlers
+// escape it to two bytes, which is exactly what logfield charges for
+// it, so each of those fields emits every byte of its budget; no fill
+// emits more, since logfield charges each rune the wider of the two
+// handlers and a field can therefore never emit more than it spent.
+// The stack is not a fill: recursion drives it past its budget and
+// the cut lands wherever its own content puts it, which is why the
+// measured widths move by a byte between runs.
+func TestRecovererBoundsTheStack(t *testing.T) {
+	t.Parallel()
+
+	for _, handler := range panicLogHandlers() {
+		t.Run(handler.name, func(t *testing.T) {
+			t.Parallel()
+
+			value := strings.Repeat(`"`, oversizedSegmentBytes) +
+				tailMarker
+			requestID := strings.Repeat(`"`, oversizedSegmentBytes) +
+				tailMarker
+
+			probe := newRecovererProbe(
+				t, handler.text,
+				func(http.ResponseWriter, *http.Request) {
+					_ = deepPanic(512, value)
+				},
+			)
+
+			resp, err := probe.getWithRequestID(t, requestID)
+			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 {
+				assertEveryFieldWasCut(t, probe.panicRecord(t))
+			}
+
+			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))
+}