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.

README.md

@@ -1156,14 +1156,15 @@ the multiplier is whatever the deployment will serve.
 
 **The same ceiling covers every other line the service writes through
 `slog` that carries text an unauthenticated client supplies**, with one
-exception stated below it: the recovered-panic record, which spends the
+exception stated below it: the recovered-panic record, which carries a
-same per-field budgets but has its own wider ceiling. The access log is
+whole goroutine stack alongside its client-supplied fields and so has
-not the only line a client can put its own text into, and a budget that
+its own wider ceiling. The access log is not the only line a client can
-held for one line and not the others would be worse than no stated
+put its own text into, and a budget that held for one line and not the
-budget at all. Every `slog` call an unauthenticated request
+others would be worse than no stated budget at all. Every `slog` call an
-can reach spends the same per-field budget through `internal/logfield`,
+unauthenticated request can reach spends the same per-field budget
-and each carries strictly fewer client-supplied fields than the access
+through `internal/logfield`, and each carries strictly fewer
-log does, so none of them can be wider than it:
+client-supplied fields than the access log does, so none of them can be
+wider than it:
 
 | Log line                                   | Level   | Client-chosen value | Reachable unauthenticated                 |
 | ------------------------------------------ | ------- | ------------------- | ----------------------------------------- |
@@ -1305,23 +1306,31 @@ the fault behind it.
 
 That record is bounded the same way, in the same encoded bytes and
 through the same `internal/logfield` budget: 512 for the panic value,
-because a handler is free to build one out of the request, and 8,192 for
+because a handler is free to build one out of the request, 128 for the
-the stack, cut at its far end so that the panic site survives a cut and
+request id, which a client supplies outright through `X-Request-Id`,
-`net/http`'s accept frames are what is lost. Net: **at most 10,240
+and 8,192 for the stack, cut at its far end so that the panic site
-bytes, once per recovered panic** — 9,121 by the arithmetic (523 + 8,203
+survives a cut and `net/http`'s accept frames are what is lost. Net:
-+ 139 + a 256-byte fixed portion), stated at 10,240 for headroom.
+**at most 10,240 bytes, once per recovered panic** — 9,121 by the
-`internal/middleware/recoverer_test.go` measures 8,898 bytes with the
+arithmetic (523 + 8,203 + 139 + a 256-byte fixed portion), stated at
-stack and the panic value both driven past their budgets, over both
+10,240 for headroom.
-handlers; that figure carries no source paths and reproduces across
+
-checkouts. The real case is far below it: through the shipped middleware
+Those two numbers are the claim; the measurements below only
-chain the whole record measures roughly 3,960 bytes over a roughly
+illustrate it. `internal/middleware/recoverer_test.go` drives all
-3,690-byte stack, taken by `internal/server/recoverer_test.go` from the
+three growable fields past their budgets on one record, over both
-process's own file descriptors while driving a panic through the
+handlers, and measured 9,009 bytes on the JSON handler and
-production router over a real server in a subprocess. That pair is
+8,982–8,983 on the text one in one checkout. Neither is an invariant:
-**not** an invariant — `debug.Stack()` embeds absolute source paths, so
+the stack's own content decides where its cut lands, so the figures
-it moves with where the tree is checked out, and three checkouts have
+move by a byte or so between runs. The real case is far below both —
-reported 3,959, 3,961 and 4,026. What the tests assert is the ceiling
+through the shipped middleware chain the whole record measures
-and that the stack arrived uncut, never the number.
+roughly 3,960 bytes over a roughly 3,690-byte stack, taken by
+`internal/server/recoverer_test.go` from the process's own file
+descriptors while driving a panic through the production router over
+a real server in a subprocess. That pair moves further still, since
+`debug.Stack()` embeds absolute source paths and so depends on where
+the tree is checked out: four checkouts have reported 3,959, 3,961,
+3,984 and 4,026. What the tests assert is the ceiling, that every
+client-supplied field was cut, and that the shipped chain's stack
+arrived uncut — never the numbers.
 
 Every limiter here — receiver, login, and password change — identifies
 the client the same way, through one shared key function: the

internal/middleware/middleware.go

@@ -133,12 +133,12 @@ const (
 	//   - The "log" delivery target, which exists to write the whole
 	//     inbound event to the log. Deliberate; see
 	//     internal/delivery/target_log.go.
-	//   - The record a recovered panic writes, which is neither an
+	//   - The record a recovered panic writes, which is not an access
-	//     access log line nor client-chosen: it carries a whole
+	//     log line: its client-supplied fields are charged the same
-	//     goroutine stack and is wider than this figure. It has its
+	//     budgets, but it carries a whole goroutine stack as well and
-	//     own stated ceiling, MaxPanicLogLineBytes in recoverer.go,
+	//     is wider than this figure. It has its own stated ceiling,
-	//     and is written once per recovered panic rather than once
+	//     MaxPanicLogLineBytes in recoverer.go, and is written once
-	//     per request.
+	//     per recovered panic rather than once per request.
 	MaxAccessLogLineBytes = 2560
 )
 

internal/middleware/recoverer.go

@@ -32,8 +32,8 @@ const (
 	// record of roughly 3,960, so this budget holds better than
 	// twice the depth that case reaches. Neither number is an
 	// invariant — debug.Stack() embeds absolute source paths, so
-	// both move with where the tree sits, and three checkouts have
+	// both move with where the tree sits, and four checkouts have
-	// reported records of 3,959, 3,961 and 4,026 bytes.
+	// reported records of 3,959, 3,961, 3,984 and 4,026 bytes.
 	// internal/server's TestPanicThroughProductionRouter asserts the
 	// ceiling and that the stack arrived uncut, not the figures.
 	maxPanicStackBytes = 8192
@@ -60,10 +60,16 @@ const (
 	// the reason given there: logfield.EncodedBytes charges every
 	// rune the wider of the two.
 	//
-	// Measured, the widest line either handler produces with both
+	// The 9121 and the 10240 are the invariants here. What follows
-	// the stack and the panic value driven past their budgets is
+	// is illustration: with all three growable fields — the stack,
-	// 8,898 bytes (TestRecovererBoundsTheStack). That figure carries
+	// the panic value and a client-supplied X-Request-Id — driven
-	// no source paths and reproduces across checkouts.
+	// past their budgets at once, TestRecovererBoundsTheStack
+	// measured 9,009 bytes on the JSON handler and 8,982 to 8,983 on
+	// the text one in this checkout. Neither is fixed: the stack's
+	// own content decides where its cut lands, so the figures move by
+	// a byte or so between runs and with the checkout. The test
+	// asserts the ceiling and that every growable field was cut,
+	// never the figures.
 	MaxPanicLogLineBytes = 10240
 )
 

internal/middleware/recoverer_test.go

@@ -98,11 +98,29 @@ func newRecovererProbe(
 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)
 }
 
@@ -437,45 +455,16 @@ func deepPanic(depth int, value string) int {
 	return deepPanic(depth-1, value) + 1
 }
 
-// TestRecovererBoundsTheStack drives the widest record the recoverer
+// assertEveryFieldWasCut holds each of the record's three growable
-// can be made to write: an oversized stack and an oversized panic
+// fields to its own budget, which is what the ceiling is the sum of.
-// value on the same record, over both log handlers. It holds that
+// The stack is cut at its far end, so its near end — the panic site —
-// line to the stated ceiling and reports what it measured, and it
+// has to survive; the request id is the client's own bytes, so its
-// pins that a cut stack keeps its near end — the panic site — rather
+// cut is the one that bounds an attacker rather than our own call
-// than its far one.
+// depth.
-func TestRecovererBoundsTheStack(t *testing.T) {
+func assertEveryFieldWasCut(t *testing.T, record map[string]any) {
-	t.Parallel()
+	t.Helper()
 
-	for _, handler := range panicLogHandlers() {
+	stack, ok := record["stack"].(string)
-		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),
@@ -489,6 +478,74 @@ func TestRecovererBoundsTheStack(t *testing.T) {
 		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