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, 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, 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 line either handler produces is 8898, a figure that carries
no source paths and reproduces across checkouts. The real case through
the shipped chain measures roughly 3960 bytes; that one moves with the
checkout, because debug.Stack() embeds absolute source paths, so it is
stated as a measurement rather than as an invariant and no test asserts
it.

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

REPO_POLICIES.md

@@ -1,6 +1,6 @@
 ---
 title: Repository Policies
-last_modified: 2026-08-07
+last_modified: 2026-07-06
 ---
 
 This document covers repository structure, tooling, and workflow standards. Code
@@ -189,13 +189,8 @@ style conventions are in separate documents:
   module under test to verify it compiles/parses. There is no excuse for
   `make test` to be a no-op.
 
-- `make test` must complete in under 60 seconds. That is the hard cap, and a
+- `make test` must complete in under 20 seconds. Add a 30-second timeout in the
-  suite that exceeds it fails. Under 20 seconds is the target. A suite between
+  Makefile.
-  20 and 60 seconds is still green, but the overage must be filed as an
-  improvement bug against that repo. Add a 90-second timeout to the test
-  invocation in the Makefile (`go test -timeout 90s`). The backstop deliberately
-  sits above the hard cap so that it catches a genuinely hung test rather than a
-  merely slow one.
 
 - **`make test` should use the conditional verbose rerun pattern.** Run tests
   without `-v` (verbose) first. If tests fail, automatically rerun with `-v` to
@@ -214,9 +209,9 @@ style conventions are in separate documents:
 
     ```makefile
     test:
-    	@go test -timeout 90s -race -cover ./... || \
+    	@go test -timeout 30s -race -cover ./... || \
     		{ echo "--- Rerunning with -v for details ---"; \
-    		  go test -timeout 90s -race -v ./...; exit 1; }
+    		  go test -timeout 30s -race -v ./...; exit 1; }
     ```
 
     Python example:
@@ -265,10 +260,7 @@ style conventions are in separate documents:
 
 - `.golangci.yml` is standardized and must _NEVER_ be modified by an agent, only
   manually by the user. Fetch from
-  `https://git.eeqj.de/sneak/prompts/raw/branch/main/.golangci.yml`. The
+  `https://git.eeqj.de/sneak/prompts/raw/branch/main/.golangci.yml`.
-  canonical golangci-lint version is v2.12.2 (released 2026-05-06), installed
-  commit-pinned via
-  `go install github.com/golangci/golangci-lint/v2/cmd/golangci-lint@c0d3ddc9cf3faa61a4e378e879ece580256d76e5`.
 
 - When pinning images or packages by hash, add a comment above the reference
   with the version and date (YYYY-MM-DD).

TODO.md

@@ -24,84 +24,36 @@ event retention (#63), the database archiving target (#43), the admin
 password change flow (#65), policy compliance (#6), pinned lint tooling
 (#55), and fail-loud configuration parsing (#80).
 
-`next` holds the **complete 1.0.0 milestone**: every issue in it is
+`next` holds the 1.0.0 milestone less its final four issues (#176, #178,
-closed, and it is verified green both by CI and by cache-defeated
+#186, #187 — all in review or held on merge order), and is verified
-container runs (`docker build --no-cache-filter=lint
+green by cache-defeated container runs
---no-cache-filter=builder`).
+(`docker build --no-cache-filter=lint --no-cache-filter=builder`). The
-
+CI status is not independently claimed here: a superseded run is
-One caveat on reading a green check, narrower than it used to be. A
+recorded as `skipped` and still rolls up green, so a commit status on
-docs-only commit deliberately replays from the layer cache (#119), so a
+`next` does not by itself evidence an executed check (#152). Before
-green status on such a commit evidences a replay rather than an executed
+#119, a warm layer cache also let the gate report success without
-run; a code commit invalidates the `COPY` layer and genuinely executes.
+executing anything, and replayed the previous build's console log so
-Superseded runs are no longer the hazard they were: before #152 they
+the lie looked like a real run. Note: `TODO.md` was deliberately
-were recorded as `skipped` and rolled up green, and before #119 a warm
-layer cache let the gate report success without executing anything,
-replaying the previous build's console log so the lie looked like a real
-run. Both are fixed. Note: `TODO.md` was deliberately
 deleted from this repo in f9a9569 (2026-03-01, #6); its content was
 folded into the README TODO section, which this draft reconstructs as
 of 2026-07-06.
 
 # Next Step
 
-Merge the milestone PR (#111) to `main` and tag 1.0.0 from it. The
+Land the last four 1.0.0 issues, then merge the milestone PR to `main`
-milestone is empty and `next` is green; nothing else blocks the tag.
+and tag 1.0.0 from it. Merge order is forced by a real conflict on
+`README.md` and `internal/middleware/middleware.go`: #186, then #176,
+then #178, then #187.
 
-Three items belong to the owner, none of them blocking. #150 was decided
+Two items belong to the owner, neither blocking the tag. #150 was
-by the manager rather than left to stall the queue and is flagged on the
+decided by the manager rather than left to stall the queue and is
-issue for reversal if that call was wrong. #112 (whether `Completed
+flagged on the issue for reversal if that call was wrong. #112 (whether
-Steps` should exist at all, given it once conflicted on every unit) is
+`Completed Steps` should exist at all, given it once conflicted on every
-unanswered; the provisional ruling in force is that issue branches do
+unit) is unanswered; the provisional ruling in force is that issue
-not touch this file. #198 records that `make test` is past the org 20s
+branches do not touch this file.
-target — 46s of test execution inside a 62.8s CI layer — and turns on
-which quantity the 60s hard cap governs; it is scoped as the improvement
-bug the 20-60s band requires, and should be milestoned instead if the
-cap is read as covering the whole invocation.
-
-After the tag, the largest open cluster is the unmilestoned follow-up
-backlog these units generated: #183, #184, #185, #190, #191, #193 and
-#198.
 
 # Completed Steps
 
-- 2026-08-18 Raise `script/test`'s per-package timeout from 30s to 90s,
-  matching the org-wide backstop. `go test` applies `-timeout` per
-  package, and `internal/handlers` had grown past the old budget: a
-  cache-defeated build failed outright at `GOMAXPROCS=4`, and every run
-  under deliberate host load breached 30s. The measurement table lives
-  in the script (#194)
-- 2026-08-18 Re-sync `REPO_POLICIES.md` from `prompts`. The local copy
-  was stale and still mandated a 20s test target with a 30s timeout,
-  which the org replaced with a 60s cap and a 90s backstop. A synced
-  copy is not a source; reading it as one nearly produced a PR against
-  `prompts` proposing a change already merged there (#196)
-- 2026-08-18 Report handler panics through the logger and answer 500.
-  chi v1.5.5's `Recoverer` scans for a `panic(0x` frame the runtime no
-  longer emits, then indexes `pkg[-1:]`, so it panicked inside its own
-  stack printer before writing a byte: the recovery never ran, the
-  client got a dropped connection instead of a 500, and the original
-  panic was lost. A local middleware replaces it, bounded by
-  `MaxPanicLogLineBytes` (#187)
-- 2026-08-18 Route GORM's logger through `slog` and bound it. Every
-  `gorm.Open` left `logger.Default` in place at `Warn` with
-  `IgnoreRecordNotFoundError` false, so **every record-not-found
-  printed the fully interpolated SQL to stdout** — including the
-  client-chosen path on `/webhook/{uuid}` and the submitted username on
-  the login form, at no level the operator set and outside
-  `internal/logger` entirely. Three call sites, not the two the issue
-  named (#178)
-- 2026-08-18 Bound every `slog` line against client-chosen text. Eight
-  sites reachable unauthenticated, found by reading every `slog` call in
-  the tree rather than only the one reported; the budget moved to a
-  shared `internal/logfield` so no second truncation exists. `DEBUG`
-  being off by default is not a bound and is not treated as one (#176)
-- 2026-08-18 Stop a slow host turning a login-guard test into a
-  segfault. A non-fatal `assert` on an acquire result was dereferenced
-  on the next line, so one timing miss killed the whole
-  `internal/middleware` binary and reddened CI for unrelated PRs. The
-  fix also removed a real production race — `acquire` could shed a
-  request with a slot standing free, because Go picks uniformly among
-  ready `select` cases (#186)
 - 2026-08-18 Send the chi route pattern to Sentry rather than the
   concrete path. The receiver's path carries the entrypoint capability
   token, so every Sentry event from `/webhook/{uuid}` shipped a live

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 not an access
+	//   - The record a recovered panic writes, which is neither an
-	//     log line: its client-supplied fields are charged the same
+	//     access log line nor client-chosen: it carries a whole
-	//     budgets, but it carries a whole goroutine stack as well and
+	//     goroutine stack and is wider than this figure. It has its
-	//     is wider than this figure. It has its own stated ceiling,
+	//     own stated ceiling, MaxPanicLogLineBytes in recoverer.go,
-	//     MaxPanicLogLineBytes in recoverer.go, and is written once
+	//     and is written once per recovered panic rather than once
-	//     per recovered panic rather than once per request.
+	//     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 four checkouts have
+	// both move with where the tree sits, and three checkouts have
-	// reported records of 3,959, 3,961, 3,984 and 4,026 bytes.
+	// reported records of 3,959, 3,961 and 4,026 bytes.
 	// internal/server's TestPanicThroughProductionRouter asserts the
 	// ceiling and that the stack arrived uncut, not the figures.
 	maxPanicStackBytes = 8192
@@ -60,16 +60,10 @@ const (
 	// the reason given there: logfield.EncodedBytes charges every
 	// rune the wider of the two.
 	//
-	// The 9121 and the 10240 are the invariants here. What follows
+	// Measured, the widest line either handler produces with both
-	// is illustration: with all three growable fields — the stack,
+	// the stack and the panic value driven past their budgets is
-	// the panic value and a client-supplied X-Request-Id — driven
+	// 8,898 bytes (TestRecovererBoundsTheStack). That figure carries
-	// past their budgets at once, TestRecovererBoundsTheStack
+	// no source paths and reproduces across checkouts.
-	// 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,29 +98,11 @@ 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)
 }
 
@@ -455,65 +437,12 @@ func deepPanic(depth int, value string) int {
 	return deepPanic(depth-1, value) + 1
 }
 
-// assertEveryFieldWasCut holds each of the record's three growable
+// TestRecovererBoundsTheStack drives the widest record the recoverer
-// fields to its own budget, which is what the ceiling is the sum of.
+// can be made to write: an oversized stack and an oversized panic
-// The stack is cut at its far end, so its near end — the panic site —
+// value on the same record, over both log handlers. It holds that
-// has to survive; the request id is the client's own bytes, so its
+// line to the stated ceiling and reports what it measured, and it
-// cut is the one that bounds an attacker rather than our own call
+// pins that a cut stack keeps its near end — the panic site — rather
-// depth.
+// than its far one.
-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()
 
@@ -521,10 +450,11 @@ func TestRecovererBoundsTheStack(t *testing.T) {
 		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
-			requestID := strings.Repeat(`"`, oversizedSegmentBytes) +
-				tailMarker
 
 			probe := newRecovererProbe(
 				t, handler.text,
@@ -533,7 +463,7 @@ func TestRecovererBoundsTheStack(t *testing.T) {
 				},
 			)
 
-			resp, err := probe.getWithRequestID(t, requestID)
+			resp, err := probe.get(t)
 			require.NoError(t, err)
 			require.NoError(t, resp.Body.Close())
 			require.Equal(
@@ -545,7 +475,20 @@ func TestRecovererBoundsTheStack(t *testing.T) {
 			// 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))
+				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

script/test

@@ -1,34 +1,12 @@
 #!/bin/sh
 # script/test: run the test suite.
-#
-# -timeout is applied by `go test` per package, not to the run as a whole, so
-# it only has to clear the slowest single package. That is internal/handlers,
-# measured in a cache-defeated builder stage on the 48-core shared build host
-# (2026-08-18); load- and host-dependent, not invariants:
-#
-#   16.9s                  host load 5-20, GOMAXPROCS 48
-#   45.9s / 47.3s / 49.0s  three runs at deliberate host load 31-73
-#   30.6s / 39.7s          host load 5-20, GOMAXPROCS 6 / 4
-#   67.3s / 97.5s          host load 5-20, GOMAXPROCS 2 / 1
-#   67.3s                  GOMAXPROCS 4 at deliberate host load 52-68
-#
-# The old 30s budget was breached by every loaded run and by every GOMAXPROCS
-# at or below 6; at GOMAXPROCS 4 it failed outright ("panic: test timed out
-# after 30s"), reproduced on 33e4fa4 with no other change.
-#
-# 90s matches the org-wide backstop in REPO_POLICIES.md and is sized here
-# against the figures above: the worst case under native parallelism is 49.0s,
-# and the compound GOMAXPROCS-4-under-load case at 67.3s sits at 75% of it.
-# The one figure above 90s is GOMAXPROCS 1, a synthetic core floor rather than
-# a condition CI runs under. If a CPU-limited runner ever puts a real run near
-# 67s, that is the datum to revisit the org figure with.
 set -eu
 
 ROOT="$(cd "$(dirname "$0")/.." && pwd -P)"
 
 main() {
     cd "$ROOT"
-    go test -v -race -timeout 90s ./...
+    go test -v -race -timeout 30s ./...
 }
 
 main "$@"