Record the 1.0.0 milestone as complete in TODO.md

README.md

@@ -1155,13 +1155,16 @@ that the rate is not bounded by the limits above on every route:
 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.** The
+`slog` that carries text an unauthenticated client supplies**, with one
-access log is not the only line a client can put its own text into, and
+exception stated below it: the recovered-panic record, which carries a
-a budget that held for one line and not the others would be worse than
+whole goroutine stack alongside its client-supplied fields and so has
-no stated budget at all. Every `slog` call an unauthenticated request
+its own wider ceiling. The access log is not the only line a client can
-can reach spends the same per-field budget through `internal/logfield`,
+put its own text into, and a budget that held for one line and not the
-and each carries strictly fewer client-supplied fields than the access
+others would be worse than no stated budget at all. Every `slog` call an
-log does, so none of them can be wider than it:
+unauthenticated request can reach spends the same per-field budget
+through `internal/logfield`, and each carries strictly fewer
+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                 |
 | ------------------------------------------ | ------- | ------------------- | ----------------------------------------- |
@@ -1303,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

REPO_POLICIES.md

@@ -1,6 +1,6 @@
 ---
 title: Repository Policies
-last_modified: 2026-07-06
+last_modified: 2026-08-07
 ---
 
 This document covers repository structure, tooling, and workflow standards. Code
@@ -189,8 +189,13 @@ 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 20 seconds. Add a 30-second timeout in the
+- `make test` must complete in under 60 seconds. That is the hard cap, and a
-  Makefile.
+  suite that exceeds it fails. Under 20 seconds is the target. A suite between
+  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
@@ -209,9 +214,9 @@ style conventions are in separate documents:
 
     ```makefile
     test:
-    	@go test -timeout 30s -race -cover ./... || \
+    	@go test -timeout 90s -race -cover ./... || \
     		{ echo "--- Rerunning with -v for details ---"; \
-    		  go test -timeout 30s -race -v ./...; exit 1; }
+    		  go test -timeout 90s -race -v ./...; exit 1; }
     ```
 
     Python example:
@@ -260,7 +265,10 @@ 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`.
+  `https://git.eeqj.de/sneak/prompts/raw/branch/main/.golangci.yml`. The
+  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,36 +24,84 @@ 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 1.0.0 milestone less its final four issues (#176, #178,
+`next` holds the **complete 1.0.0 milestone**: every issue in it is
-#186, #187 — all in review or held on merge order), and is verified
+closed, and it is verified green both by CI and by cache-defeated
-green by cache-defeated container runs
+container runs (`docker build --no-cache-filter=lint
-(`docker build --no-cache-filter=lint --no-cache-filter=builder`). The
+--no-cache-filter=builder`).
-CI status is not independently claimed here: a superseded run is
+
-recorded as `skipped` and still rolls up green, so a commit status on
+One caveat on reading a green check, narrower than it used to be. A
-`next` does not by itself evidence an executed check (#152). Before
+docs-only commit deliberately replays from the layer cache (#119), so a
-#119, a warm layer cache also let the gate report success without
+green status on such a commit evidences a replay rather than an executed
-executing anything, and replayed the previous build's console log so
+run; a code commit invalidates the `COPY` layer and genuinely executes.
-the lie looked like a real run. Note: `TODO.md` was deliberately
+Superseded runs are no longer the hazard they were: before #152 they
+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
 
-Land the last four 1.0.0 issues, then merge the milestone PR to `main`
+Merge the milestone PR (#111) to `main` and tag 1.0.0 from it. The
-and tag 1.0.0 from it. Merge order is forced by a real conflict on
+milestone is empty and `next` is green; nothing else blocks the tag.
-`README.md` and `internal/middleware/middleware.go`: #186, then #176,
-then #178, then #187.
 
-Two items belong to the owner, neither blocking the tag. #150 was
+Three items belong to the owner, none of them blocking. #150 was decided
-decided by the manager rather than left to stall the queue and is
+by the manager rather than left to stall the queue and is flagged on the
-flagged on the issue for reversal if that call was wrong. #112 (whether
+issue for reversal if that call was wrong. #112 (whether `Completed
-`Completed Steps` should exist at all, given it once conflicted on every
+Steps` should exist at all, given it once conflicted on every unit) is
-unit) is unanswered; the provisional ruling in force is that issue
+unanswered; the provisional ruling in force is that issue branches do
-branches do not touch this file.
+not touch this file. #198 records that `make test` is past the org 20s
+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 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,12 +455,65 @@ 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 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()
 
@@ -450,11 +521,10 @@ 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,
@@ -463,7 +533,7 @@ func TestRecovererBoundsTheStack(t *testing.T) {
 				},
 			)
 
-			resp, err := probe.get(t)
+			resp, err := probe.getWithRequestID(t, requestID)
 			require.NoError(t, err)
 			require.NoError(t, resp.Body.Close())
 			require.Equal(
@@ -475,20 +545,7 @@ 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 {
-				stack, ok := probe.panicRecord(t)["stack"].(string)
+				assertEveryFieldWasCut(t, probe.panicRecord(t))
-				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,12 +1,34 @@
 #!/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 30s ./...
+    go test -v -race -timeout 90s ./...
 }
 
 main "$@"