Route GORM's logger through slog and bound it (closes #178)

GORM's default logger printed the fully interpolated SQL to standard
output on every statement that returned an error, including a plain
record-not-found. On /webhook/{uuid} and on the login form the
interpolated parameter is client-chosen and unbounded, so an
unauthenticated client sized the operator's log, one line per request,
at no level the operator could turn down.

Every gorm.Open in the service now installs internal/gormlog, a
gormlogger.Interface over the service's *slog.Logger. Its lines take
the level the operator set and the handler internal/logger selected; a
record-not-found is not logged as an error, since it is the expected
outcome on both of those paths and each handler already records its
own miss at DEBUG without the SQL; slow statements are kept at WARN
above the same 200ms threshold GORM used; and every value it emits is
spent through an encoded-byte budget.

Trace orders its cases exactly as GORM's own Trace orders them --
error-that-is-not-a-miss, then slow, then routine -- so a statement
that both missed and ran slow is still reported as slow. Ordering the
drop first would have made this adapter strictly less observant than
the IgnoreRecordNotFoundError option it was chosen over, on the two
lookups the issue is about, and a miss is the statement most likely to
be slow.

That budget is internal/middleware's truncateLogField, moved to a new
internal/logfield package now that a second writer needs it. The move
is unchanged logic. MaxAccessLogLineBytes bounds a GORM line too, and
internal/gormlog asserts each line against the constant directly.

The third gorm.Open, in the archive writer, was not named in the issue
and had the same default. All three sites are pinned independently:
internal/handlers covers the main and per-webhook databases,
internal/delivery covers the archive writer, whose type is unexported.
Reverting any one of the three to a bare &gorm.Config{} fails the
suite.

The flood test's per-line and volume assertions were vacuous, because
the replaced default logger wrote only to a buffer while everything
else went to the captured stdout. It now tees to stdout as GORM's real
default does, so a reverted call site lands in the same capture and
those assertions measure the whole writer set.

README: the ceiling now covers GORM, and the writers it does not cover
are re-derived by measuring rather than by reading. fx's console
logger and the Go runtime write to standard error. net/http's nil
ErrorLog is not a separate writer at all -- slog.SetDefault redirects
the log package's default logger into internal/logger's handler, so
those lines arrive on standard output at INFO. A handler panic reaches
that same path because chi's Recoverer crashes before writing, which
is filed as #187 and is also the widest line the service can write, at
2,772 bytes against the stated 2,560.

README.md

@@ -994,16 +994,15 @@ costs; log volume it caps rather than eliminates. A path that names no
 entrypoint is recorded by the handler at `DEBUG`, and the aggregate
 limiter logs its own rejections at `DEBUG` and without the path, so
 neither appears at all under the default level. The per-entrypoint
-limiter is the loud one: it logs every rejection at `WARN` with the
-request path, which on this route is attacker-controlled text. A client
-hammering a single invented path is served `RECEIVER_RATE_LIMIT`
+limiter is the loud one: it still logs every rejection at `WARN` with
+the request path, which on this route is attacker-controlled text. A
+client hammering a single invented path is served `RECEIVER_RATE_LIMIT`
 requests and has the rest of its aggregate budget rejected there, so
-the aggregate limit is what bounds the _number_ of those `WARN` lines —
-to under ten times `RECEIVER_RATE_LIMIT` per minute per client IP, 1080
-at the defaults, where before it there was no bound at all. Their
-_width_ is bounded by the field budgets below, the same ones the access
-log spends. The access log is bounded by neither limit: every request
-is recorded once at `INFO`, served or rejected alike.
+the aggregate limit is what bounds those `WARN` lines — to under ten
+times `RECEIVER_RATE_LIMIT` per minute per client IP, 1080 at the
+defaults, where before it there was no bound at all. The access log is
+bounded by neither limit: every request is recorded once at `INFO`,
+served or rejected alike.
 
 What the access log does bound is the _content_ of those lines. A 3xx
 or 4xx response logs the chi route pattern — `/webhook/{uuid}`,
@@ -1141,196 +1140,91 @@ the figure has headroom. `internal/middleware/accesslog_test.go`
 asserts it against 8 KB of client-chosen text in the path, in the
 query, and in each of `User-Agent`, `Referer` and `X-Request-Id`,
 including cases built from the characters the handlers escape, and
-against the widest access log line the service can be made to write: a
-5xx that keeps its concrete path while all three header fields are also
-at their budget. Every case runs through both handlers
-`internal/logger` can select — the JSON one and the text one it installs
-on a tty — since the two do not escape alike and the ceiling is quoted
-unqualified. Measured over a real connection, the widest access log line
-is 1,972 bytes.
+against the widest line the service can be made to write: a 5xx that
+keeps its concrete path while all three header fields are also at their
+budget. Every case runs through both handlers `internal/logger` can
+select — the JSON one and the text one it installs on a tty — since the
+two do not escape alike and the ceiling is quoted unqualified. Measured
+over a real connection, the widest line is 1,972 bytes.
 
 Multiply that ceiling by the request rate to size log storage. Note
 that the rate is not bounded by the limits above on every route:
 `/.well-known/healthcheck` and `/s/*` sit behind no limiter, so there
 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
-whole goroutine stack alongside its client-supplied fields and so has
-its own wider ceiling. The access log is not the only line a client can
-put its own text into, and a budget that held for one line and not the
-others would be worse than no stated budget at all. Every `slog` call an
-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                 |
-| ------------------------------------------ | ------- | ------------------- | ----------------------------------------- |
-| `request body exceeds limit` (413)         | `WARN`  | path, method        | yes — `MaxBodySize` precedes `RequireAuth` |
-| `csrf: token validation failed` (403)      | `WARN`  | path, method        | yes — `CSRF` precedes `RequireAuth`        |
-| `... rate limit exceeded` (429)            | `WARN`  | path                | yes, on the receiver                       |
-| `auth middleware: unauthenticated request` | `DEBUG` | path, method        | yes, by definition                         |
-| `entrypoint not found`                     | `DEBUG` | entrypoint UUID     | yes, on the receiver                       |
-| `user not found` / `invalid password`      | `DEBUG` | username            | yes, on the login form                     |
-| `login failure limit exceeded` (429)       | `WARN`  | path                | yes, on the login form                     |
-| `password verification capacity exhausted` | `WARN`  | path                | yes, on the login form                     |
-
-`DEBUG` being off by default is not a bound. An operator turning it on
-to diagnose a flood must not thereby hand the flood an unbounded write,
-so those lines are capped too.
-
-The last two rows are capped defensively rather than against a
-demonstrated width: chi routes `POST /pages/login` on a static pattern,
-so `r.URL.Path` there is the 12-byte constant `/pages/login` and each
-line lands near 120 bytes. `RecordLoginFailure` is nonetheless an
-exported method taking any `*http.Request`, and a future caller on a
-route with a URL parameter would widen the line. Since no request
-through the mux can, both caps are pinned by tests that call those two
-entry points directly with the path such a caller would supply.
-Removing either cap fails 14 subtests.
-
-`internal/middleware/logbound_test.go` and
-`internal/handlers/logbound_test.go` drive 8 KB of client-chosen text
-at each of these — 1 KB at `invalid password`, whose accounts are
-shared with the successful-login line, where a username past 4 KB
-overflows the session cookie and answers 500 before that line is
-written — through both handlers, and through seven fills: plain text
-as the baseline, and then the quotation mark, backslash, tab, newline,
-C0 control and astral non-printable, six characters the wider of the
-two handlers spends more on than the client spent sending them. Every
-case holds each line to the 2,560-byte ceiling. That per-line ceiling
-is what the figure above states, and every row establishes it.
-
-Three of the sites go further and bound the whole flood's output — the
-total bytes a run of distinct invented values wrote, which is the
-shape an operator sizing storage cares about. They are
-`request body exceeds limit`
-(`TestMaxBodySize_FloodOfOversizePathsDoesNotGrowTheLog`),
-`entrypoint not found` and `user not found` (the last two through
-`assertBoundedFlood`). The other rows carry no aggregate assertion;
-the per-line ceiling is what they establish.
-
-`internal/logfield/logfield_test.go` measures the per-rune charge
-against what the handlers really emit, over roughly 3,000 code points on
-each, so an undercharged rune fails a test rather than quietly
-falsifying the ceiling.
-
-**It covers GORM's statement logging as well.** GORM's own default
-logger printed the fully interpolated SQL — parameters and all — to
-standard output on every statement that returned an error, including a
-plain record-not-found, at a level no operator setting reached. Two of
-this service's lookups miss by design on unauthenticated routes: the
-entrypoint lookup behind `/webhook/{uuid}` and the user lookup behind
-the login form, whose path segment and submitted username the client
-picks outright. Every
-`gorm.Open` in the service now installs the adapter in
-`internal/gormlog` instead. It writes through the same `slog` logger as
-everything else, so its lines take the level the operator set and the
-handler `internal/logger` selected, and every value it emits is spent
-through the same `internal/logfield` budget. A record-not-found is not
-logged as an error: it is the expected outcome on both of those paths,
-and each handler already records its own miss at `DEBUG` — bounded, per
-the table above — without the SQL. Slow statements are kept, at `WARN`,
-above the same 200 ms threshold GORM used and with the statement
-bounded, because that report is the one thing GORM's logger gave an
-operator that nothing else here does. The adapter orders its cases
-exactly as GORM's own `Trace` orders them, so a statement that both
-missed and ran slow is still reported as slow, and dropping the miss
-costs an operator no report `IgnoreRecordNotFoundError` would have
-kept. A GORM line spends at most two of those budgets — the statement
-and the driver error — against a smaller fixed portion than the access
-log's, and `internal/gormlog/gormlog_test.go` asserts each line against
+That figure is now the ceiling on a second writer as well. GORM's own
+default logger printed the fully interpolated SQL — parameters and all
+— to standard output on every statement that returned an error,
+including a plain record-not-found, at a level no operator setting
+reached. Two of this service's lookups miss by design on
+unauthenticated routes: the entrypoint lookup behind `/webhook/{uuid}`
+and the user lookup behind the login form, whose path segment and
+submitted username the client picks outright. Every `gorm.Open` in the
+service now installs the adapter in `internal/gormlog` instead. It
+writes through the same `slog` logger as everything else, so its lines
+take the level the operator set and the handler `internal/logger`
+selected, and every value it emits is spent through the same 512-byte
+encoded budget (`internal/logfield`). A record-not-found is not logged
+as an error: it is the expected outcome on both of those paths, and
+each handler already records its own miss at `DEBUG`, without the SQL.
+Slow statements are kept — at `WARN`, above the same 200 ms threshold
+GORM used, with the statement bounded — because that report is the one
+thing GORM's logger gave an operator that nothing else here does, and
+a statement that both missed and ran slow is still reported as slow.
+The adapter orders those cases exactly as GORM's own `Trace` orders
+them, so dropping the miss costs an operator no report that GORM's
+`IgnoreRecordNotFoundError` would have kept. A
+GORM line spends at most two of those budgets, the statement and the
+driver error, against a smaller fixed portion than the access log's;
+`internal/gormlog/gormlog_test.go` asserts each line against
 `MaxAccessLogLineBytes` directly rather than leaving it as arithmetic.
 
-What that ceiling does **not** cover, stated here so the figure is not
-read as more than it is:
+**What the ceiling does not cover.** It is a per-line bound on the
+access log and on GORM's statement logging, not a bound on every line
+this service writes. The exceptions are named here because a bound
+that is true of one writer and silently false of another is worse than
+no stated bound at all.
 
-- **Lines carrying an authenticated operator's own input**, which are
-  not truncated at all. `webhook created` logs the submitted `name`
-  verbatim and `target URL blocked by SSRF protection` logs the target
-  host (both `internal/handlers/source_management.go`), as do the
-  `target_name` lines in `internal/delivery/engine.go` and
-  `internal/delivery/target_http.go`. The only bound on any of them is
-  the 1 MB form body cap, so a 100 KB `name` writes a single line of
-  roughly 600 KB — measured. This is deliberate: every one of these
-  requires an authenticated operator on a service with no
-  self-registration, and truncating the operator's own configuration
-  echoed back would cost debuggability against no adversary. It does
-  mean the 2,560-byte figure sizes unauthenticated traffic, not the
-  operator's own administrative requests.
-- The **`log` delivery target**, which writes the whole inbound event —
-  headers and body — to the log. This one is deliberate: capping it
-  would defeat the target, since emitting the payload is the delivery.
-  It costs nothing unless an authenticated operator creates a target of
-  that type on a specific webhook, and each line it writes is bounded
-  per event by the 1 MB receiver body cap. Adding one is a decision to
-  spend log volume on that webhook's payloads.
-- **Two writers that do not go through `internal/logger` at all**, both
-  on standard error. `fx` prints the dependency graph and the lifecycle
+- Other `slog` calls that reach a client-chosen value — the
+  `MaxBodySize` rejection, the CSRF failure, the receiver rate-limit
+  rejection, and the two lookup misses above — still log the request
+  path or the submitted username untruncated.
+- The `log` delivery target (`internal/delivery/target_log.go`) writes
+  the entire inbound event, headers and body, to the log. That is what
+  the target is for. Each line is bounded per event by the 1 MB
+  receiver body cap, and it costs nothing unless an authenticated
+  operator creates a target of that type.
+- Two writers that do not go through `internal/logger` at all, both on
+  standard error. `fx` prints the dependency graph and the lifecycle
   hooks through its default console logger at startup and shutdown —
   nothing calls `fx.WithLogger`, and `fx.New` builds that logger over
-  `os.Stderr`. The Go runtime writes a panic or a fatal error itself; a
-  panic in a background worker rather than in a request handler is the
-  case that reaches it, since nothing recovers those. Neither carries a
-  client-chosen value at a client-chosen length: the five `panic` calls
-  in this service are invariant guards over constants and over
-  `crypto/rand`.
-- **`net/http`'s own faults**, which are _not_ a separate writer.
-  `internal/server/http.go` builds its server with a nil `ErrorLog`, so
-  `net/http` falls back to the `log` package's default logger — and
-  `internal/logger` calls `slog.SetDefault`, which redirects that logger
-  into whichever handler it installed. Those lines therefore arrive on
-  standard output, shaped like every other line, at `INFO`. They are not
-  truncated. A handler panic is no longer one of them: the recover
-  middleware below answers it and writes it as the bounded record
-  described there instead, and `internal/server/recoverer_test.go`
-  requires that `http: panic serving` appear in neither of the process's
-  two streams when a panic is driven through the production router. The
-  one panic still handed back to `net/http` is `http.ErrAbortHandler`,
-  which it special-cases and does not log at all. What is left on this
-  path is `net/http`'s own diagnostics, whose values are the runtime's,
-  not a client's.
-
-Wider than that 2,560-byte ceiling, and stated separately rather than
-carved out of it: the record a recovered panic produces. The recover
-middleware in `internal/middleware` answers `500` and writes one `ERROR`
-record through `internal/logger` carrying the panic value, the stack and
-the request id — the same `request_id` the access log line for that
-request carries, which is how the two are joined. It replaced chi's
-`middleware.Recoverer`, which on a current Go release crashed inside its
-own stack pretty-printer: the connection was dropped rather than
-answered, and what reached the operator described that crash rather than
-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
-request id, which a client supplies outright through `X-Request-Id`,
-and 8,192 for the stack, cut at its far end so that the panic site
-survives a cut and `net/http`'s accept frames are what is lost. Net:
-**at most 10,240 bytes, once per recovered panic** — 9,121 by the
-arithmetic (523 + 8,203 + 139 + a 256-byte fixed portion), stated at
-10,240 for headroom.
-
-Those two numbers are the claim; the measurements below only
-illustrate it. `internal/middleware/recoverer_test.go` drives all
-three growable fields past their budgets on one record, over both
-handlers, and measured 9,009 bytes on the JSON handler and
-8,982–8,983 on the text one in one checkout. Neither is an invariant:
-the stack's own content decides where its cut lands, so the figures
-move by a byte or so between runs. The real case is far below both —
-through the shipped middleware chain the whole record measures
-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.
+  `os.Stderr`. The Go runtime writes a panic or a fatal error itself;
+  a panic in a background worker rather than in a request handler is
+  the case that reaches it, since nothing recovers those. Neither
+  carries a client-chosen value at a client-chosen length: the five
+  `panic` calls in this service are invariant guards over constants
+  and over `crypto/rand`.
+- `net/http`'s own faults, which are **not** a separate writer.
+  `internal/server/http.go` builds its server with a nil `ErrorLog`,
+  so `net/http` falls back to the `log` package's default logger — and
+  `internal/logger` calls `slog.SetDefault`, which redirects that
+  logger into whichever handler it installed. Those lines therefore
+  arrive on standard output, shaped like every other line, at `INFO`.
+  They are not truncated and they are not bounded by the ceiling: a
+  handler panic arrives as one record carrying a whole goroutine
+  stack, measured at 2,772 bytes against the ceiling's 2,560. The
+  value is the runtime's, not a client's.
+- A handler panic reaches that path rather than the one it looks like
+  it should. `internal/server/routes.go` installs chi's
+  `middleware.Recoverer` in front of every route, which is meant to
+  print the panic and its stack to standard error and answer 500. On
+  the Go version this service builds against it does neither: chi
+  v1.5.5's stack pretty-printer looks for a `panic(0x` frame that the
+  runtime no longer emits, walks past the end of its own slice, and
+  panics before writing a byte. That second panic escapes to
+  `net/http`, which drops the connection and reports it through the
+  nil `ErrorLog` above. Tracked separately in
+  https://git.eeqj.de/sneak/webhooker/issues/187.
 
 Every limiter here — receiver, login, and password change — identifies
 the client the same way, through one shared key function: the
@@ -1669,32 +1563,19 @@ to record results.
 
 Applied to all routes in this order:
 
-1. **RequestID** — Generate unique request IDs (chi built-in)
-2. **SecurityHeaders** — Production security headers on every response
+1. **Recoverer** — Panic recovery (chi built-in)
+2. **RequestID** — Generate unique request IDs (chi built-in)
+3. **SecurityHeaders** — Production security headers on every response
    (HSTS, X-Content-Type-Options, X-Frame-Options, CSP, Referrer-Policy,
    Permissions-Policy)
-3. **Logging** — Structured request logging (method, URL, status,
+4. **Logging** — Structured request logging (method, URL, status,
    latency, remote IP, user agent, request ID)
-4. **Metrics** — Prometheus HTTP metrics (if `METRICS_USERNAME` is set)
-5. **CORS** — Cross-origin resource sharing headers
-6. **Timeout** — 60-second request timeout
-7. **Recoverer** — Panic recovery: one `ERROR` record through
-   `internal/logger` and a `500`
+5. **Metrics** — Prometheus HTTP metrics (if `METRICS_USERNAME` is set)
+6. **CORS** — Cross-origin resource sharing headers
+7. **Timeout** — 60-second request timeout
 8. **Sentry** — Error reporting to Sentry (if `SENTRY_DSN` is set;
    configured with `Repanic: true` so panics still reach Recoverer)
 
-Recoverer sits seventh rather than first, and both neighbours are the
-reason. It runs **inside** everything that observes the response, so
-the `500` it writes for a panicking handler is the status the access
-log records and the metrics count; registered first, as chi's own
-`middleware.Recoverer` was, the same request was logged as a `200` that
-the client never received. It runs **outside** the Sentry handler, so
-`Repanic: true` has something to re-raise into: an operator with
-`SENTRY_DSN` set keeps the report, and one without it now gets the
-local record instead of nothing. What that placement gives up is
-recovery of a panic in the six entries above it, none of which does
-more than set a header or start a timer.
-
 Additionally, form endpoints (`/pages`, `/user/*`, `/sources`,
 `/source/*`) apply a **MaxBodySize** middleware that limits
 POST/PUT/PATCH request bodies to 1 MB. It is registered ahead of 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
-  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` must complete in under 20 seconds. Add a 30-second timeout in the
+  Makefile.
 
 - **`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
-  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`.
+  `https://git.eeqj.de/sneak/prompts/raw/branch/main/.golangci.yml`.
 
 - When pinning images or packages by hash, add a comment above the reference
   with the version and date (YYYY-MM-DD).

TODO.md

@@ -24,142 +24,30 @@ 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
-closed, and it is verified green both by CI and by cache-defeated
-container runs (`docker build --no-cache-filter=lint
---no-cache-filter=builder`).
-
-One caveat on reading a green check, narrower than it used to be. A
-docs-only commit deliberately replays from the layer cache (#119), so a
-green status on such a commit evidences a replay rather than an executed
-run; a code commit invalidates the `COPY` layer and genuinely executes.
-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
+`next` holds the completed 1.0.0 milestone: every issue in it is closed,
+and it is verified green by cache-defeated container runs
+(`docker build --no-cache-filter=lint --no-cache-filter=builder`). The
+CI status is not independently claimed here: a superseded run is
+recorded as `skipped` and still rolls up green, so a commit status on
+`next` does not by itself evidence an executed check (#152). Before
+#119, a warm layer cache also let the gate report success without
+executing anything, and replayed the previous build's console log so
+the lie looked like a real run. 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
-milestone is empty and `next` is green; nothing else blocks the tag.
+Merge the milestone PR to `main` and tag 1.0.0 from it.
 
-Three items belong to the owner, none of them blocking. #150 was decided
-by the manager rather than left to stall the queue and is flagged on the
-issue for reversal if that call was wrong. #112 (whether `Completed
-Steps` should exist at all, given it once conflicted on every unit) is
-unanswered; the provisional ruling in force is that issue branches do
-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.
+Two decisions are open and belong to the owner, neither blocking the
+tag: #115 (mask the `http` target's destination URL, implemented
+speculatively and awaiting a yes or no) and #125 (whether IPv6
+rate-limit keys should bucket by `/64`).
 
 # 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
-  credential to a third party. Request `Data`, `QueryString`, `Cookies`
-  and `Env` are dropped and headers reduced to an allowlist (#179)
-- 2026-08-18 Read form fields from the POST body only. `r.FormValue`
-  merges the query string, so a login could be driven by URL parameters
-  — putting the password somewhere that lands in access logs, proxy
-  logs and browser history (#160)
-- 2026-08-18 Verify login credentials before spending rate-limit
-  budget, so a flood of wrong passwords cannot lock out the account it
-  is guessing at. The manager took this decision rather than stall the
-  queue; it is flagged on the issue for reversal (#150)
-- 2026-08-18 Run all linting in Docker via `Dockerfile.lint`. Host lint
-  was wrong in both directions from version skew and shared caches.
-  `script/lint` asserts the summary line, because `--no-cache-filter`
-  silently ignores a stage name it does not match — the flag that makes
-  the gate meaningful fails open (#109)
-- 2026-08-18 Serve an event's full stored body over HTTP. The list
-  query truncates for rendering, and that truncated value was the only
-  way to read a body, so the full payload was unreachable (#157)
-- 2026-08-18 Bound the access log line against client-chosen text.
-  `internal/logfield` budgets by *encoded* bytes, not runes, so a
-  handler's JSON escaping cannot multiply a field past its allowance
-  (#146)
-- 2026-08-18 Mark superseded CI commits `failure` rather than
-  `skipped`. A skipped run rolls up green, so a commit that was never
-  tested reported success (#152)
-- 2026-08-18 Set `fx.StopTimeout` inside the container stop grace, so
-  shutdown hooks are bounded by a deadline the orchestrator will
-  actually honour rather than being killed mid-flush (#134)
-- 2026-08-17 Bucket IPv6 rate-limit keys by `/64`. A single allocation
-  hands out 2^64 addresses, so per-address keying let one client mint
-  unlimited buckets. Manager decision, recorded on the issue (#125)
-- 2026-08-17 Correct release-blocking README and startup-warning
-  inaccuracies, including claims about behaviour the code does not have
-  (#151)
-- 2026-08-17 Fetch and verify Alpine.js at build time against
-  `static/vendor.sha256` instead of committing the minified blob, so
-  the dependency is pinned by hash rather than by trust (#145)
-- 2026-08-17 Bound the event log's rendered bodies in the query itself,
-  so a large stored payload cannot be read into memory just to be
-  truncated for display (#135)
-- 2026-08-17 Mask the `http` target's destination URL in the UI: it can
-  carry a bearer credential in its path or query, and was rendered
-  verbatim. Manager decision to mask unconditionally (#115)
-- 2026-08-14 Bound shutdown hooks by their stop context, so a hook that
-  hangs cannot hold the process past its grace period (#102)
-- 2026-08-14 Render templates via a buffer rather than the
-  `ResponseWriter`, so a template error part-way through cannot commit
-  a 200 and then fail — the response is written only once it is whole
-  (#123)
-- 2026-08-14 Align the session codec's max-age with the 7-day absolute
-  cap. The codec accepted cookies the session layer considered expired,
-  so the cap was enforced in one place and not the other (#108)
-- 2026-08-12 Warn when `TRUSTED_PROXIES` is empty in production, where
-  the safe default silently discards forwarded headers and every client
-  rate-limits as the proxy's address (#149)
 - 2026-08-12 Bound the receiver rate limit per client IP across the
   whole `/webhook/*` route. The existing limiter keyed on the request
   path and `/webhook/{uuid}` matches any single segment, so a client

internal/database/webhook_db_manager_test.go

@@ -339,12 +339,7 @@ func TestWebhookDBManager_MultipleWebhooks(t *testing.T) {
 	var events []database.Event
 
 	require.NoError(t, db2.Find(&events).Error)
-
-	// require, not assert: this is exactly the regression the test
-	// guards, so the empty slice is the expected failure, and a
-	// non-fatal length check would index into it on the next line and
-	// panic the whole package test binary instead of failing here.
-	require.Len(t, events, 1)
+	assert.Len(t, events, 1)
 	assert.Equal(t, "PUT", events[0].Method)
 }
 

internal/delivery/target_log.go

@@ -11,17 +11,6 @@ import (
 // inbound webhook — the full request body and headers, plus
 // the method, content type, and the webhook and entrypoint
 // ids — then records a single successful attempt.
-//
-// This is the one log call in the service that deliberately writes
-// unbounded client-chosen bytes, so it is the one exception to the
-// per-field budgets in internal/logfield and to the ceiling stated on
-// middleware.MaxAccessLogLineBytes. Capping here would defeat the
-// target: emitting the payload IS the delivery. It costs nothing by
-// default — an authenticated operator has to create a target of this
-// type on a specific webhook before a single line is written — and the
-// bytes it writes are bounded per event by maxWebhookBodySize (1 MB).
-// An operator who adds one is choosing to spend log volume on the
-// payloads that webhook receives.
 type logTarget struct {
 	eng *Engine
 }

internal/gormlog/gormlog_test.go

@@ -334,17 +334,13 @@ func TestStatementError_LineIsBounded(t *testing.T) {
 func TestSucceedingStatement_LineIsBoundedOnEitherArm(t *testing.T) {
 	t.Parallel()
 
-	// "sql statement" is a substring of "slow sql statement", so the
-	// routine arm carries notWant as well: Contains alone cannot tell
-	// the two arms apart in that direction.
 	arms := []struct {
 		name string
 		slow time.Duration
 		want string
-		notWant string
 	}{
-		{"slow", alwaysSlow, "slow sql statement", ""},
-		{"routine", neverSlow, "sql statement", "slow sql statement"},
+		{"slow", alwaysSlow, "slow sql statement"},
+		{"routine", neverSlow, "sql statement"},
 	}
 
 	for _, a := range arms {
@@ -366,13 +362,6 @@ func TestSucceedingStatement_LineIsBoundedOnEitherArm(t *testing.T) {
 					).Find(&got).Error)
 
 					assert.Contains(t, buf.String(), a.want)
-
-					if a.notWant != "" {
-						assert.NotContains(
-							t, buf.String(), a.notWant,
-						)
-					}
-
 					assertBounded(t, buf.String())
 				})
 			}

internal/handlers/auth.go

@@ -5,7 +5,6 @@ import (
 	"strconv"
 
 	"sneak.berlin/go/webhooker/internal/database"
-	"sneak.berlin/go/webhooker/internal/logfield"
 )
 
 // HandleLoginPage returns a handler for the login page (GET)
@@ -71,9 +70,7 @@ func (h *Handlers) HandleLoginSubmit() http.HandlerFunc {
 
 		h.log.Info(
 			"user logged in",
-			"username", logfield.Truncate(
-				username, logfield.MaxBytes,
-			),
+			"username", username,
 			"user_id", user.ID,
 		)
 
@@ -120,9 +117,7 @@ func (h *Handlers) authenticateUser(
 	if !ok {
 		h.log.Warn(
 			"password verification capacity exhausted",
-			"path", logfield.Truncate(
-				r.URL.Path, logfield.MaxBytes,
-			),
+			"path", r.URL.Path,
 		)
 		h.renderLoginError(
 			w, r,
@@ -147,17 +142,7 @@ func (h *Handlers) authenticateUser(
 		h.dummyVerifications.Add(1)
 		database.VerifyDummyPassword(password)
 
-		// Login is unauthenticated, and the submitted username is
-		// a form field the client fills to any length the 1 MB
-		// body cap allows. On this branch it matched no row, so
-		// nothing else bounds it. The rate limiter caps how often
-		// the line is written, not how wide it is.
-		h.log.Debug(
-			"user not found",
-			"username", logfield.Truncate(
-				username, logfield.MaxBytes,
-			),
-		)
+		h.log.Debug("user not found", "username", username)
 		h.rejectLogin(w, r, username)
 
 		return user, err
@@ -175,17 +160,7 @@ func (h *Handlers) authenticateUser(
 	}
 
 	if !valid {
-		// Reached only once the username matched a stored row, so
-		// it is bounded by the operator's own data. Capped anyway,
-		// so that every username this unauthenticated endpoint
-		// logs is capped and no reader has to work out which
-		// branch narrowed it.
-		h.log.Debug(
-			"invalid password",
-			"username", logfield.Truncate(
-				username, logfield.MaxBytes,
-			),
-		)
+		h.log.Debug("invalid password", "username", username)
 		h.rejectLogin(w, r, username)
 
 		return user, errInvalidPassword

internal/handlers/export_test.go

@@ -2,19 +2,11 @@ package handlers
 
 import (
 	"html/template"
-	"log/slog"
 	"net/http"
 
 	"sneak.berlin/go/webhooker/internal/database"
 )
 
-// SetLogForTest replaces the handler's logger, so the handlers_test
-// package can assert on what a log line actually contains rather than
-// on what it is meant to contain.
-func (s *Handlers) SetLogForTest(log *slog.Logger) {
-	s.log = log
-}
-
 // MaxRenderedBodyBytesForTest exposes the event log's body cap
 // to the handlers_test package.
 const MaxRenderedBodyBytesForTest = maxRenderedBodyBytes

internal/handlers/gormlogbound_test.go

@@ -7,6 +7,7 @@ import (
 	"log"
 	"net/http"
 	"net/http/httptest"
+	"net/url"
 	"os"
 	"strconv"
 	"strings"
@@ -243,7 +244,7 @@ func floodUnauthenticated(
 
 		for range reps {
 			postWebhook(t, h, value)
-			postUnknownLogin(t, h, value)
+			postLogin(t, h, value)
 
 			requests += 2
 		}
@@ -323,15 +324,29 @@ func postWebhook(
 	require.Equal(t, http.StatusNotFound, w.Code)
 }
 
-// postUnknownLogin submits the login form with an unknown username,
-// through the postLogin helper in logbound_test.go. The field is
-// bounded only by the 1 MB body cap, and the lookup behind it misses
-// by design.
-func postUnknownLogin(
+// postLogin submits the login form with an unknown username. The
+// field is bounded only by the 1 MB body cap, and the lookup behind
+// it misses by design.
+func postLogin(
 	t *testing.T, h *handlers.Handlers, username string,
 ) {
 	t.Helper()
 
+	form := url.Values{}
+	form.Set("username", username)
+	form.Set("password", "not-the-password")
+
+	req := httptest.NewRequestWithContext(
+		context.Background(), http.MethodPost, "/pages/login",
+		strings.NewReader(form.Encode()),
+	)
+	req.Header.Set(
+		"Content-Type", "application/x-www-form-urlencoded",
+	)
+
+	w := httptest.NewRecorder()
+	h.HandleLoginSubmit().ServeHTTP(w, req)
+
 	// 401 while the client still has failure budget against this
 	// username, 429 once the login guard has taken it away. Both
 	// outcomes sit behind the user lookup, which is the query this
@@ -339,7 +354,7 @@ func postUnknownLogin(
 	require.Contains(
 		t,
 		[]int{http.StatusUnauthorized, http.StatusTooManyRequests},
-		postLogin(t, h, username),
+		w.Code,
 	)
 }
 
@@ -390,11 +405,11 @@ func assertFloodBounded(t *testing.T, label, out string) {
 //     the adapter drops the record-not-found, so the capture holds
 //     nothing but fixed-string warnings.
 //
-// The level is left where newTestApp leaves it, at INFO: the level an
-// operator runs at by default, and the one the defect was visible at.
-// The handlers' own miss lines sit at DEBUG and spend the same
-// logfield budget as everything else, so they are not what makes
-// either assertion above bite at any level.
+// The level is left where newTestApp leaves it, at INFO, deliberately.
+// At DEBUG the handlers' own miss lines log the client-chosen
+// entrypoint and username untruncated — the first carve-out in the
+// README's ceiling section, and https://git.eeqj.de/sneak/webhooker/issues/176's
+// to fix, not this one's.
 //
 // It is deliberately not parallel: it redirects os.Stdout and replaces
 // gormlogger.Default, both of which are process-global. Go runs every

internal/handlers/logbound_test.go

@@ -1,543 +0,0 @@
-package handlers_test
-
-// The handler-side half of the log-field audit. Two slog calls in
-// this package reach a value an UNAUTHENTICATED client picks outright
-// and of a length it picks outright:
-//
-//   - the unknown-entrypoint DEBUG line on /webhook/{uuid}, whose
-//     path segment matched no stored entrypoint and so is bounded by
-//     nothing;
-//   - the failed-login DEBUG lines, whose username is a form field.
-//
-// Both are at DEBUG, which is off in production by default. That is
-// not a bound: an operator turning DEBUG on to diagnose a flood must
-// not thereby hand the flood an unbounded write. Both spend the same
-// internal/logfield budget as the access log, and both are held here
-// to middleware.MaxAccessLogLineBytes.
-//
-// The two login lines past the username lookup — "invalid password"
-// and "user logged in" — carry the same cap without needing it, since
-// by then the value is a stored row rather than the client's. They are
-// pinned here too, so the caps cannot be dropped silently.
-//
-// So is the "password verification capacity exhausted" WARN line,
-// whose path chi pins to the constant "/pages/login" on the one route
-// that reaches it. Its cap is defensive, and the test below drives the
-// handler directly with the path a parameterised route would give it,
-// because an unasserted cap is one a later edit removes for free.
-
-import (
-	"bytes"
-	"context"
-	"io"
-	"log/slog"
-	"net/http"
-	"net/http/httptest"
-	"net/url"
-	"strings"
-	"testing"
-
-	"github.com/go-chi/chi"
-	"github.com/stretchr/testify/assert"
-	"github.com/stretchr/testify/require"
-	"sneak.berlin/go/webhooker/internal/database"
-	"sneak.berlin/go/webhooker/internal/handlers"
-	"sneak.berlin/go/webhooker/internal/middleware"
-)
-
-// floodRequests is the number of distinct invented values each flood
-// drives through the call site under test.
-const floodRequests = 32
-
-// oversizedFillBytes is the length of the single client-chosen value
-// used to show that line size does not track input size.
-const oversizedFillBytes = 8192
-
-// attackerMarker and tailMarker sit at the END of every oversized
-// value, past every budget. Their absence from the log is what
-// proves the value was cut rather than merely being short.
-const (
-	attackerMarker = "QQATTACKERTEXTQQ"
-	tailMarker     = "QQTRUNCATEDTAILQQ"
-)
-
-// escapeFills are the characters the log handlers escape, so a value
-// built out of them costs more on the line than it did on the wire. A
-// budget counted in raw bytes passes the plain case and fails these.
-//
-// U+1000C is unassigned, hence non-printable, and strconv.Quote
-// spells it as a ten-byte \UXXXXXXXX while the JSON handler passes
-// its four UTF-8 bytes through; only the text shape of these tests
-// reaches that charge.
-func escapeFills() map[string]string {
-	return map[string]string{
-		"plain":     "x",
-		"quote":     `"`,
-		"backslash": `\`,
-		"tab":       "\t",
-		"newline":   "\n",
-		// A C0 control neither handler has a short escape for, so
-		// each one costs six bytes on the line against the single
-		// byte it cost to send: the widest multiplier a client can
-		// drive, and the case a raw-byte budget breaks on first.
-		//
-		// This fill is load-bearing, not decoration. Budgeting raw
-		// bytes instead of encoded is caught by this fill alone,
-		// and only under the JSON handler, at 3,072 bytes against
-		// the 2,560 ceiling. Drop it and that mutation passes.
-		"control": "\x01",
-		"astral":  "\U0001000C",
-	}
-}
-
-// logHandlers are the two handlers internal/logger can install.
-func logHandlers() map[string]func(
-	io.Writer, *slog.HandlerOptions,
-) slog.Handler {
-	return map[string]func(
-		io.Writer, *slog.HandlerOptions,
-	) slog.Handler{
-		"json": func(
-			w io.Writer, o *slog.HandlerOptions,
-		) slog.Handler {
-			return slog.NewJSONHandler(w, o)
-		},
-		"text": func(
-			w io.Writer, o *slog.HandlerOptions,
-		) slog.Handler {
-			return slog.NewTextHandler(w, o)
-		},
-	}
-}
-
-// oversizedFill builds an 8 KB client-chosen value out of
-// repetitions of ch, with both markers at its far end.
-func oversizedFill(ch string) string {
-	return "x" + strings.Repeat(ch, oversizedFillBytes) +
-		attackerMarker + tailMarker
-}
-
-// capturingHandlers builds a Handlers whose log is captured into the
-// returned buffer at DEBUG through the named handler.
-//
-// extra is passed to fx.Populate alongside the Handlers, for the call
-// sites that also need the database the client's value is looked up
-// in, or the Middleware whose resource has to be exhausted before the
-// branch under test is reached.
-func capturingHandlers(
-	t *testing.T,
-	newHandler func(io.Writer, *slog.HandlerOptions) slog.Handler,
-	extra ...any,
-) (*handlers.Handlers, *bytes.Buffer) {
-	t.Helper()
-
-	var h *handlers.Handlers
-
-	app := newTestApp(t, append([]any{&h}, extra...)...)
-	app.RequireStart()
-
-	t.Cleanup(app.RequireStop)
-
-	buf := new(bytes.Buffer)
-	h.SetLogForTest(slog.New(newHandler(
-		buf, &slog.HandlerOptions{Level: slog.LevelDebug},
-	)))
-
-	return h, buf
-}
-
-// logLines splits the captured buffer into non-empty lines, holding
-// each to the stated per-line ceiling.
-func logLines(t *testing.T, buf *bytes.Buffer) []string {
-	t.Helper()
-
-	var lines []string
-
-	for line := range strings.SplitSeq(
-		strings.TrimSpace(buf.String()), "\n",
-	) {
-		if line == "" {
-			continue
-		}
-
-		require.LessOrEqual(
-			t, len(line), middleware.MaxAccessLogLineBytes,
-			"log line exceeded its bound: %s", line,
-		)
-
-		lines = append(lines, line)
-	}
-
-	return lines
-}
-
-// assertNoClientText fails if the far end of the client-chosen input
-// survived into the log.
-func assertNoClientText(t *testing.T, buf *bytes.Buffer) {
-	t.Helper()
-
-	assert.NotContains(
-		t, buf.String(), attackerMarker,
-		"log carried attacker-chosen text",
-	)
-	assert.NotContains(
-		t, buf.String(), tailMarker,
-		"log carried the tail of the attacker-chosen text",
-	)
-}
-
-// receiverRouter mounts the real receiver handler at the production
-// route pattern.
-func receiverRouter(h *handlers.Handlers) *chi.Mux {
-	router := chi.NewRouter()
-	router.Post("/webhook/{uuid}", h.HandleWebhook())
-
-	return router
-}
-
-// postReceiver sends one POST at /webhook/<segment>.
-//
-// RawPath is cleared after parsing so chi routes on the decoded path
-// and the handler sees the raw bytes rather than their percent-escaped
-// spelling. That is the harder case for the budget: the escaped
-// spelling is plain ASCII, which costs one byte per byte, while the
-// decoded bytes are what the log handler has to escape.
-func postReceiver(
-	t *testing.T, router *chi.Mux, segment string,
-) int {
-	t.Helper()
-
-	req := httptest.NewRequestWithContext(
-		context.Background(),
-		http.MethodPost,
-		"/webhook/"+url.PathEscape(segment),
-		strings.NewReader(""),
-	)
-	req.URL.RawPath = ""
-
-	w := httptest.NewRecorder()
-	router.ServeHTTP(w, req)
-
-	return w.Code
-}
-
-// postLogin submits the login form with the given username and a
-// non-empty password.
-func postLogin(
-	t *testing.T, h *handlers.Handlers, username string,
-) int {
-	t.Helper()
-
-	return postLoginWithPassword(t, h, username, "not-the-password")
-}
-
-// postLoginWithPassword submits the login form with both credentials
-// chosen by the caller, so a test can reach the branches past the
-// username lookup.
-func postLoginWithPassword(
-	t *testing.T, h *handlers.Handlers, username, password string,
-) int {
-	t.Helper()
-
-	form := url.Values{
-		"username": {username},
-		"password": {password},
-	}
-
-	req := httptest.NewRequestWithContext(
-		context.Background(),
-		http.MethodPost,
-		"/pages/login",
-		strings.NewReader(form.Encode()),
-	)
-	req.Header.Set(
-		"Content-Type", "application/x-www-form-urlencoded",
-	)
-
-	w := httptest.NewRecorder()
-	h.HandleLoginSubmit().ServeHTTP(w, req)
-
-	return w.Code
-}
-
-// TestUnknownEntrypoint_LogLineDoesNotTrackPathSize drives 8 KB of
-// client-chosen path at the unauthenticated receiver's
-// unknown-entrypoint DEBUG line and holds it to the same ceiling the
-// access log states.
-func TestUnknownEntrypoint_LogLineDoesNotTrackPathSize(t *testing.T) {
-	t.Parallel()
-
-	for handlerName, newHandler := range logHandlers() {
-		for fillName, fill := range escapeFills() {
-			t.Run(handlerName+"/"+fillName, func(t *testing.T) {
-				t.Parallel()
-
-				h, buf := capturingHandlers(t, newHandler)
-				router := receiverRouter(h)
-
-				for i := range floodRequests {
-					assert.Equal(
-						t,
-						http.StatusNotFound,
-						postReceiver(
-							t, router,
-							oversizedFill(fill)+
-								strings.Repeat("y", i),
-						),
-					)
-				}
-
-				lines := logLines(t, buf)
-				require.Len(t, lines, floodRequests)
-				assertNoClientText(t, buf)
-
-				assertBoundedFlood(t, buf.Len())
-			})
-		}
-	}
-}
-
-// TestFailedLogin_LogLineDoesNotTrackUsernameSize drives 8 KB of
-// client-chosen username at the unauthenticated login endpoint's
-// DEBUG line and holds it to the same ceiling.
-func TestFailedLogin_LogLineDoesNotTrackUsernameSize(t *testing.T) {
-	t.Parallel()
-
-	for handlerName, newHandler := range logHandlers() {
-		for fillName, fill := range escapeFills() {
-			t.Run(handlerName+"/"+fillName, func(t *testing.T) {
-				t.Parallel()
-
-				h, buf := capturingHandlers(t, newHandler)
-
-				for i := range floodRequests {
-					assert.Equal(
-						t,
-						http.StatusUnauthorized,
-						postLogin(
-							t, h,
-							oversizedFill(fill)+
-								strings.Repeat("y", i),
-						),
-					)
-				}
-
-				lines := logLines(t, buf)
-				require.Len(t, lines, floodRequests)
-				assertNoClientText(t, buf)
-
-				assertBoundedFlood(t, buf.Len())
-			})
-		}
-	}
-}
-
-// storedUserPassword is the password held by the oversize accounts
-// the test below creates.
-const storedUserPassword = "correct-horse-battery-staple"
-
-// storedFillBytes is the raw length of the client-chosen value in
-// those accounts' usernames. It is well past the 512-byte field
-// budget, so the line is still truncated, but short enough that the
-// session cookie a successful login writes stays inside
-// securecookie's 4 KB limit: the cookie is written BEFORE the
-// "user logged in" line, so an 8 KB username answers 500 and never
-// reaches it.
-const storedFillBytes = 1024
-
-// storedFill builds a username fill of storedFillBytes raw bytes out
-// of repetitions of ch, with both markers at its far end.
-func storedFill(ch string) string {
-	return "x" + strings.Repeat(ch, storedFillBytes/len(ch)) +
-		attackerMarker + tailMarker
-}
-
-// TestStoredUsername_LogLinesDoNotTrackUsernameSize pins the two
-// login lines that are reached only AFTER the username matched a
-// stored row: "invalid password" and "user logged in". Neither
-// strictly needs its cap — the value is the operator's own data by
-// then, not the client's — but both carry one so that every username
-// this unauthenticated endpoint logs is capped, and an unasserted cap
-// is one a later edit removes for free.
-//
-// One app per handler with the accounts created inside it, and no
-// parallelism below that level: every account costs an Argon2id hash
-// and every attempt costs a verification.
-func TestStoredUsername_LogLinesDoNotTrackUsernameSize(t *testing.T) {
-	t.Parallel()
-
-	for handlerName, newHandler := range logHandlers() {
-		t.Run(handlerName, func(t *testing.T) {
-			t.Parallel()
-
-			var db *database.Database
-
-			h, buf := capturingHandlers(t, newHandler, &db)
-
-			hash, err := database.HashPassword(storedUserPassword)
-			require.NoError(t, err)
-
-			fills := escapeFills()
-			for fillName, fill := range fills {
-				username := storedFill(fill) + fillName
-
-				require.NoError(t, db.DB().Create(&database.User{
-					Username: username,
-					Password: hash,
-				}).Error)
-
-				// Matched the row, wrong secret: "invalid
-				// password".
-				assert.Equal(
-					t, http.StatusUnauthorized,
-					postLoginWithPassword(
-						t, h, username, "not-the-password",
-					),
-				)
-
-				// Matched the row, right secret: "user logged
-				// in".
-				assert.Equal(
-					t, http.StatusSeeOther,
-					postLoginWithPassword(
-						t, h, username, storedUserPassword,
-					),
-				)
-			}
-
-			lines := logLines(t, buf)
-			require.Len(t, lines, 2*len(fills))
-			assertNoClientText(t, buf)
-		})
-	}
-}
-
-// maxVerificationSlots bounds how many slots the loop below will
-// take before it gives up, so a semaphore that never fills fails the
-// test instead of hanging it. It is deliberately larger than the
-// real concurrency bound, which is not exported to this package.
-const maxVerificationSlots = 64
-
-// canceledContext returns a context that is already done. A
-// verification request carrying one takes the ctx.Done() branch of
-// the semaphore's bounded wait immediately, so these cases turn on
-// the semaphore being full rather than on a five-second timer firing.
-// Nothing here is timing-dependent.
-func canceledContext() context.Context {
-	ctx, cancel := context.WithCancel(context.Background())
-	cancel()
-
-	return ctx
-}
-
-// holdEveryVerificationSlot takes verification slots until one is
-// refused, and releases them when the test ends. A free slot is
-// handed out before any context is consulted, so a canceled context
-// cannot make this loop stop early: it stops exactly when the slots
-// are gone.
-func holdEveryVerificationSlot(
-	t *testing.T, mw *middleware.Middleware,
-) {
-	t.Helper()
-
-	for range maxVerificationSlots {
-		release, ok := mw.BeginPasswordVerification(canceledContext())
-		if !ok {
-			return
-		}
-
-		t.Cleanup(release)
-	}
-
-	require.Fail(t, "the verification semaphore never filled")
-}
-
-// postLoginAtPath submits the login form at a path of the caller's
-// choosing, with a canceled context.
-func postLoginAtPath(
-	t *testing.T, h *handlers.Handlers, path string,
-) int {
-	t.Helper()
-
-	form := url.Values{
-		"username": {"someone"},
-		"password": {"not-the-password"},
-	}
-
-	req := httptest.NewRequestWithContext(
-		canceledContext(),
-		http.MethodPost,
-		path,
-		strings.NewReader(form.Encode()),
-	)
-	req.Header.Set(
-		"Content-Type", "application/x-www-form-urlencoded",
-	)
-
-	w := httptest.NewRecorder()
-	h.HandleLoginSubmit().ServeHTTP(w, req)
-
-	return w.Code
-}
-
-// TestVerificationCapacity_LogLineDoesNotTrackPathSize pins the cap
-// on the "password verification capacity exhausted" WARN line.
-//
-// The one route that reaches it is chi's static "/pages/login", so no
-// request through the mux can widen the line; the handler is driven
-// directly here with the path a parameterised route would give it,
-// which is what that cap exists for. Without this test, removing the
-// logfield.Truncate there fails nothing.
-func TestVerificationCapacity_LogLineDoesNotTrackPathSize(
-	t *testing.T,
-) {
-	t.Parallel()
-
-	for handlerName, newHandler := range logHandlers() {
-		for fillName, fill := range escapeFills() {
-			t.Run(handlerName+"/"+fillName, func(t *testing.T) {
-				t.Parallel()
-
-				var mw *middleware.Middleware
-
-				h, buf := capturingHandlers(t, newHandler, &mw)
-
-				holdEveryVerificationSlot(t, mw)
-
-				assert.Equal(
-					t,
-					http.StatusServiceUnavailable,
-					postLoginAtPath(
-						t, h,
-						"/source/"+url.PathEscape(
-							oversizedFill(fill),
-						)+"/login",
-					),
-				)
-
-				lines := logLines(t, buf)
-				require.Len(t, lines, 1)
-				assertNoClientText(t, buf)
-			})
-		}
-	}
-}
-
-// assertBoundedFlood holds the whole flood's log output to what the
-// stated per-line ceiling allows. The flood sent
-// floodRequests * oversizedFillBytes bytes of client-chosen text;
-// this is the assertion that the log did not grow with it.
-func assertBoundedFlood(t *testing.T, got int) {
-	t.Helper()
-
-	sent := floodRequests * oversizedFillBytes
-
-	require.Less(
-		t, got, sent/2,
-		"log volume tracked the size of the flood's input",
-	)
-	require.LessOrEqual(
-		t, got,
-		floodRequests*middleware.MaxAccessLogLineBytes,
-	)
-}

internal/handlers/webhook.go

@@ -9,7 +9,6 @@ import (
 	"gorm.io/gorm"
 	"sneak.berlin/go/webhooker/internal/database"
 	"sneak.berlin/go/webhooker/internal/delivery"
-	"sneak.berlin/go/webhooker/internal/logfield"
 )
 
 const (
@@ -126,16 +125,9 @@ func (h *Handlers) lookupEntrypoint(
 		"path = ?", entrypointUUID,
 	).First(&entrypoint)
 	if result.Error != nil {
-		// The receiver is unauthenticated and /webhook/{uuid}
-		// matches any single segment, so this value is entirely
-		// client-chosen on exactly the branch where the lookup
-		// failed. DEBUG is off by default; the cap is what keeps
-		// turning it on from restoring an unbounded write.
 		h.log.Debug(
 			"entrypoint not found",
-			"path", logfield.Truncate(
-				entrypointUUID, logfield.MaxBytes,
-			),
+			"path", entrypointUUID,
 		)
 		http.NotFound(w, r)
 

internal/logfield/logfield.go

@@ -1,14 +1,11 @@
-// Package logfield bounds the client-supplied values this service
-// writes into its logs.
+// Package logfield bounds a client-supplied value against what the log
+// handler will actually emit for it, so a line's size is set by this
+// service rather than by the client that provoked it.
 //
-// Any log field whose content a client picks is spent against a budget
-// here, in ENCODED bytes rather than in the bytes the client sent, so
-// that escaping cannot multiply a field past its nominal size. One
-// budget and one implementation serves the access log in
-// internal/middleware and every other slog call that reaches a
-// client-chosen path, header or form value; a second, ad-hoc
-// truncation somewhere else in the tree is the thing this package
-// exists to prevent.
+// It lives outside internal/middleware because more than one writer
+// needs it: the access log, and the GORM adapter in internal/gormlog,
+// which logs SQL with the client-chosen parameters interpolated into
+// it. One budget, one implementation.
 package logfield
 
 import (
@@ -18,20 +15,19 @@ import (
 )
 
 const (
-	// MaxBytes is the default budget for a log field whose value the
-	// client supplies outright: a URL, a path, a header, a form value.
-	// The budget is spent in ENCODED bytes (see Truncate), so 512 still
-	// holds a real browser's User-Agent whole — those are plain ASCII,
-	// which encodes one byte for one — while a value built from
-	// characters the encoder escapes keeps a shorter prefix. That is
-	// the intended trade: 500 quotation marks are not a debugging
-	// asset.
+	// MaxBytes is the default budget for a field whose value the
+	// client supplies outright. It is spent in ENCODED bytes (see
+	// Truncate), so 512 still holds a real browser's User-Agent whole
+	// — those are plain ASCII, which encodes one byte for one — while
+	// a value built from characters the encoder escapes keeps a
+	// shorter prefix. That is the intended trade: 500 quotation marks
+	// are not a debugging asset.
 	MaxBytes = 512
 
-	// TruncationMarker is appended to any field that was cut, so a
-	// short value and a truncated one cannot be confused. It is charged
-	// on top of the budget, not inside it.
-	TruncationMarker = "[truncated]"
+	// truncationMarker is appended to any value Truncate cut, so a
+	// short value and a truncated one cannot be confused. It is
+	// charged on top of the budget, not inside it.
+	truncationMarker = "[truncated]"
 )
 
 // EncodedBytes is what r costs on the line once the log handler has
@@ -49,9 +45,9 @@ const (
 // 955,086 unassigned, private-use and format code points on planes 1
 // to 16.
 //
-// Charging ten there is what makes the stated line ceilings hold for
-// the tty handler as well: U+1000C encodes as F0 90 80 8C, every byte
-// >= 0x80, which httpguts.ValidHeaderFieldValue accepts and
+// Charging ten there is what makes the stated per-line ceiling hold
+// for the tty handler as well: U+1000C encodes as F0 90 80 8C, every
+// byte >= 0x80, which httpguts.ValidHeaderFieldValue accepts and
 // net/textproto does not strip, so a header can be filled with them.
 //
 // Both handlers pass printable runes through as their own UTF-8, so
@@ -89,19 +85,20 @@ func EncodedBytes(r rune) int {
 // grows a value, so a raw budget spent on characters the encoder
 // escapes buys a field several times its nominal size — and the line
 // is the thing an operator is told to multiply by their request rate.
-// Charging each rune what it will actually cost is what makes a stated
-// ceiling true rather than merely larger. The visible consequence is
-// that an escape-heavy value keeps a shorter prefix than a plain one,
-// which is the correct trade.
+// Charging each rune what it will actually cost is what makes the
+// stated ceiling true rather than merely larger. The visible
+// consequence is that an escape-heavy value keeps a shorter prefix
+// than a plain one, which is the correct trade.
 //
 // The result is always valid UTF-8. A cut on a byte boundary can split
-// a multi-byte rune, and a header can carry bytes that were never
-// valid UTF-8 to begin with; both are dropped rather than kept, since
-// an encoder would otherwise spend six bytes replacing each one.
+// a multi-byte rune, and a header — or a SQL literal — can carry bytes
+// that were never valid UTF-8 to begin with; both are dropped rather
+// than kept, since an encoder would otherwise spend six bytes
+// replacing each one.
 func Truncate(s string, maxBytes int) string {
 	// No rune encodes to fewer bytes than it occupies, so nothing past
 	// maxBytes raw can fit the budget. Slicing first bounds the scan
-	// below to the budget rather than to the size of the header the
+	// below to the budget rather than to the size of the value the
 	// client sent.
 	window, cut := s, false
 	if len(window) > maxBytes {
@@ -139,5 +136,5 @@ func Truncate(s string, maxBytes int) string {
 		return kept.String()
 	}
 
-	return kept.String() + TruncationMarker
+	return kept.String() + truncationMarker
 }

internal/logfield/logfield_test.go

@@ -2,7 +2,6 @@ package logfield_test
 
 import (
 	"bytes"
-	"io"
 	"log/slog"
 	"strings"
 	"testing"
@@ -13,213 +12,6 @@ import (
 	"sneak.berlin/go/webhooker/internal/logfield"
 )
 
-// budget is the field budget these tests spend. Small enough that a
-// cut is unambiguous, large enough to hold several runes of every
-// width.
-const budget = 64
-
-// sampleRunes is how many runes wide the values in the charge test
-// are. The handlers add a constant per field — a pair of quotes when
-// the value needs quoting — so the per-rune charge is only visible
-// once it is amortised over a run of them.
-const sampleRunes = 64
-
-// quotingSlack is that constant: the pair of quotes a handler adds to
-// a value that needs them and omits from one that does not.
-const quotingSlack = 2
-
-// newHandlers are the two handlers internal/logger can install. Time
-// is dropped so a line's width is a function of its value alone —
-// RFC3339Nano trims trailing zeros, so two consecutive timestamps do
-// not render to the same number of bytes.
-func newHandlers() map[string]func(io.Writer) slog.Handler {
-	opts := &slog.HandlerOptions{
-		Level: slog.LevelDebug,
-		ReplaceAttr: func(_ []string, a slog.Attr) slog.Attr {
-			if a.Key == slog.TimeKey {
-				return slog.Attr{}
-			}
-
-			return a
-		},
-	}
-
-	return map[string]func(io.Writer) slog.Handler{
-		"json": func(w io.Writer) slog.Handler {
-			return slog.NewJSONHandler(w, opts)
-		},
-		"text": func(w io.Writer) slog.Handler {
-			return slog.NewTextHandler(w, opts)
-		},
-	}
-}
-
-// renderedWidth is the number of bytes a handler writes for a line
-// carrying value in a single attribute.
-func renderedWidth(
-	newHandler func(io.Writer) slog.Handler,
-	value string,
-) int {
-	buf := new(bytes.Buffer)
-	slog.New(newHandler(buf)).Info("m", "v", value)
-
-	return buf.Len()
-}
-
-// chargeTestRunes is the set of code points the charge test measures:
-// every rune in the first two planes' worth of the BMP that the
-// handlers are most likely to treat specially, the separators that
-// only slog's JSON handler escapes, and a stratified sample across
-// the rest of Unicode so the astral charge is exercised on more than
-// one hand-picked rune.
-func chargeTestRunes() []rune {
-	const (
-		denseCeiling = 0x800
-		stride       = 1021
-		surrogateLo  = 0xD800
-		surrogateHi  = 0xDFFF
-	)
-
-	var runes []rune
-
-	keep := func(r rune) {
-		if r >= surrogateLo && r <= surrogateHi {
-			return
-		}
-
-		runes = append(runes, r)
-	}
-
-	for r := range rune(denseCeiling) {
-		keep(r)
-	}
-
-	for _, r := range []rune{
-		0x2028, 0x2029, 0x200B, 0x4E00, 0xE000, 0xFFFD,
-		0x1000C, 0x1F600, 0xE0001, 0x10FFFF,
-	} {
-		keep(r)
-	}
-
-	for r := rune(denseCeiling); r <= utf8.MaxRune; r += stride {
-		keep(r)
-	}
-
-	return runes
-}
-
-// TestEncodedBytes_ChargesAtLeastWhatTheHandlersEmit is the property
-// the whole capping scheme rests on: a rune may not cost more on the
-// line than the budget was charged for it. An undercharged rune is
-// how a stated ceiling becomes false without any test noticing, so
-// the charge is measured against what the handlers actually write
-// rather than against the escaping rules as read.
-func TestEncodedBytes_ChargesAtLeastWhatTheHandlersEmit(t *testing.T) {
-	t.Parallel()
-
-	for name, newHandler := range newHandlers() {
-		t.Run(name, func(t *testing.T) {
-			t.Parallel()
-
-			// 'a' is a printable ASCII rune, charged exactly one
-			// byte, so it is the zero point the other runes are
-			// measured against.
-			base := renderedWidth(
-				newHandler, strings.Repeat("a", sampleRunes),
-			)
-
-			for _, r := range chargeTestRunes() {
-				got := renderedWidth(
-					newHandler,
-					strings.Repeat(string(r), sampleRunes),
-				)
-				charged := sampleRunes *
-					(logfield.EncodedBytes(r) - 1)
-
-				require.LessOrEqual(
-					t, got-base, charged+quotingSlack,
-					"U+%04X costs more on the line than "+
-						"EncodedBytes charges for it",
-					r,
-				)
-			}
-		})
-	}
-}
-
-// TestTruncate_SpendsNoMoreThanTheBudget holds the result to the
-// budget in ENCODED bytes, which is the unit the budget is stated in.
-// A raw-byte cap passes the ASCII case here and fails every other
-// one.
-func TestTruncate_SpendsNoMoreThanTheBudget(t *testing.T) {
-	t.Parallel()
-
-	for name, fill := range map[string]string{
-		"plain":     "x",
-		"quote":     `"`,
-		"backslash": `\`,
-		"tab":       "\t",
-		"newline":   "\n",
-		"control":   "\x01",
-		"astral":    "\U0001000C",
-		// U+4E00, a printable multi-byte rune, charged its three
-		// UTF-8 bytes rather than an escape. Spelled numerically
-		// because gosmopolitan rejects Han in a string literal.
-		"cjk": string(rune(0x4E00)),
-	} {
-		t.Run(name, func(t *testing.T) {
-			t.Parallel()
-
-			got := logfield.Truncate(
-				strings.Repeat(fill, budget*8), budget,
-			)
-
-			require.True(
-				t, strings.HasSuffix(
-					got, logfield.TruncationMarker,
-				),
-				"an oversized value must be marked as cut",
-			)
-
-			spent := 0
-			for _, r := range strings.TrimSuffix(
-				got, logfield.TruncationMarker,
-			) {
-				spent += logfield.EncodedBytes(r)
-			}
-
-			assert.LessOrEqual(t, spent, budget)
-			assert.True(t, utf8.ValidString(got))
-		})
-	}
-}
-
-// TestTruncate_LeavesShortValuesAlone keeps the marker meaningful: a
-// value that fits comes back byte for byte, so a marked value is
-// always a cut one.
-func TestTruncate_LeavesShortValuesAlone(t *testing.T) {
-	t.Parallel()
-
-	for _, s := range []string{
-		"", "GET", "/source/abc/edit", "Mozilla/5.0 (X11)",
-	} {
-		assert.Equal(t, s, logfield.Truncate(s, budget))
-	}
-}
-
-// TestTruncate_DropsInvalidUTF8 covers the bytes a header can carry
-// that were never valid UTF-8. Keeping them would make the encoder
-// spend six bytes apiece replacing them, which is exactly the
-// amplification the budget exists to prevent.
-func TestTruncate_DropsInvalidUTF8(t *testing.T) {
-	t.Parallel()
-
-	got := logfield.Truncate("a\xffb\xfe\xfec", budget)
-
-	assert.Equal(t, "abc", got)
-	assert.True(t, utf8.ValidString(got))
-}
-
 // encodedCost is what a whole string costs on a line, by the same
 // accounting Truncate spends its budget with.
 func encodedCost(s string) int {
@@ -232,16 +24,14 @@ func encodedCost(s string) int {
 }
 
 // TestTruncate_SpendsEncodedBytesNotRawBytes is the zero-headroom
-// version of TestTruncate_SpendsNoMoreThanTheBudget above, and of the
-// line-length assertions elsewhere.
+// version of the line-length assertions elsewhere.
 //
-// A line ceiling has slack in it by construction, and a LessOrEqual
-// against the budget cannot tell a budget spent exactly from one
-// spent under. Here the budget is checked against exactly what it
-// bought: a value built from a single rune must keep exactly
-// MaxBytes/EncodedBytes(r) of them, with nothing spare. A raw-byte
-// budget — cost := utf8.RuneLen(r) — fails this for every rune the
-// handlers escape.
+// A line ceiling has slack in it by construction, so a line-level
+// assertion only catches a raw-byte budget for the fills with the
+// widest multiplier. Here the budget is checked against exactly what
+// it bought: a value built from a single rune must keep exactly
+// MaxBytes/EncodedBytes(r) of them, for every rune, with nothing
+// spare.
 func TestTruncate_SpendsEncodedBytesNotRawBytes(t *testing.T) {
 	t.Parallel()
 
@@ -252,15 +42,11 @@ func TestTruncate_SpendsEncodedBytesNotRawBytes(t *testing.T) {
 		"tab":                  '\t',
 		"newline":              '\n',
 		"carriage_return":      '\r',
-		"c0_control":      '\x01',
-		"del":             '\x7f',
-		// U+2028 LINE SEPARATOR, which only the JSON handler
-		// escapes.
+		"c0_control":           '
',
+		"del":                  '',
 		"line_separator":       '
',
 		"astral_nonprintable":  '\U0001000C',
 		"multibyte_printable":  'é',
-		// U+20AC, a three-byte printable rune, charged its own
-		// UTF-8 bytes rather than an escape.
 		"three_byte_printable": '€',
 		"emoji_printable":      '\U0001F600',
 	} {
@@ -275,16 +61,12 @@ func TestTruncate_SpendsEncodedBytesNotRawBytes(t *testing.T) {
 
 			got := logfield.Truncate(in, logfield.MaxBytes)
 
-			require.True(
-				t, strings.HasSuffix(
-					got, logfield.TruncationMarker,
-				),
+			assert.True(
+				t, strings.HasSuffix(got, "[truncated]"),
 				"a value past the budget must be marked",
 			)
 
-			kept := strings.TrimSuffix(
-				got, logfield.TruncationMarker,
-			)
+			kept := strings.TrimSuffix(got, "[truncated]")
 
 			assert.Equal(
 				t, want, utf8.RuneCountInString(kept),
@@ -298,24 +80,123 @@ func TestTruncate_SpendsEncodedBytesNotRawBytes(t *testing.T) {
 	}
 }
 
+// TestEncodedBytes_CoversWhatTheHandlersActuallyEmit measures the
+// charge against what slog really writes rather than against a
+// reading of its source, over both handlers internal/logger can
+// install. An undercharged rune fails here rather than quietly
+// falsifying every stated line ceiling.
+func TestEncodedBytes_CoversWhatTheHandlersActuallyEmit(t *testing.T) {
+	t.Parallel()
+
+	emitted := func(h func(*bytes.Buffer) slog.Handler, r rune) int {
+		var withValue, withoutValue bytes.Buffer
+
+		slog.New(h(&withValue)).Info("m", "v", string(r))
+		slog.New(h(&withoutValue)).Info("m", "v", "")
+
+		return withValue.Len() - withoutValue.Len()
+	}
+
+	jsonHandler := func(b *bytes.Buffer) slog.Handler {
+		return slog.NewJSONHandler(b, &slog.HandlerOptions{
+			ReplaceAttr: dropTime,
+		})
+	}
+	textHandler := func(b *bytes.Buffer) slog.Handler {
+		return slog.NewTextHandler(b, &slog.HandlerOptions{
+			ReplaceAttr: dropTime,
+		})
+	}
+
+	// Every code point below U+0800 densely — which covers all of C0,
+	// DEL, C1 and the two-byte range — plus the separators only the
+	// JSON handler escapes, plus a stratified walk across the rest of
+	// the assigned space and into the astral planes.
+	var runes []rune
+
+	for r := rune(1); r < 0x800; r++ {
+		runes = append(runes, r)
+	}
+
+	runes = append(
+		runes,
+		'
',          // LINE SEPARATOR, escaped only by the JSON handler
+		'
',          // PARAGRAPH SEPARATOR, likewise
+		rune(0xFEFF), // ZERO WIDTH NO-BREAK SPACE
+		rune(0xFFFD), // REPLACEMENT CHARACTER
+	)
+
+	for r := rune(0x800); r <= 0x10FFFF; r += 0x1D1 {
+		runes = append(runes, r)
+	}
+
+	for _, r := range runes {
+		if !utf8.ValidRune(r) {
+			continue
+		}
+
+		charged := logfield.EncodedBytes(r)
+
+		require.LessOrEqual(
+			t, emitted(jsonHandler, r), charged,
+			"json handler spends more than U+%04X is charged", r,
+		)
+		require.LessOrEqual(
+			t, emitted(textHandler, r), charged,
+			"text handler spends more than U+%04X is charged", r,
+		)
+	}
+}
+
+func dropTime(_ []string, a slog.Attr) slog.Attr {
+	if a.Key == slog.TimeKey {
+		return slog.Attr{}
+	}
+
+	return a
+}
+
+// TestTruncate_LeavesShortValuesAlone keeps the marker meaningful: a
+// value that fits is returned untouched, so a reader can tell a short
+// value from a cut one.
+func TestTruncate_LeavesShortValuesAlone(t *testing.T) {
+	t.Parallel()
+
+	const in = "Mozilla/5.0 (X11; Linux x86_64)"
+
+	assert.Equal(t, in, logfield.Truncate(in, logfield.MaxBytes))
+}
+
+// TestTruncate_DropsInvalidUTF8 covers a value that was never valid
+// UTF-8 — a SQL parameter or a header can carry one. Replacing each
+// bad byte would cost six encoded bytes apiece, so they are dropped.
+func TestTruncate_DropsInvalidUTF8(t *testing.T) {
+	t.Parallel()
+
+	got := logfield.Truncate("a\xffb\xfec", logfield.MaxBytes)
+
+	assert.Equal(t, "abc", got)
+	assert.True(t, utf8.ValidString(got))
+}
+
 // TestTruncate_NeverSplitsARune covers a cut landing inside a
-// multi-byte encoding rather than between two of them.
+// multi-byte encoding.
 func TestTruncate_NeverSplitsARune(t *testing.T) {
 	t.Parallel()
 
-	// U+20AC, three bytes and printable, so a small budget lands
-	// inside an encoding rather than on a boundary.
+	// A three-byte printable rune, so a small budget lands inside the
+	// encoding rather than between two of them.
 	in := strings.Repeat("€", logfield.MaxBytes)
 
-	for b := 1; b <= 16; b++ {
+	for budget := 1; budget <= 16; budget++ {
 		got := strings.TrimSuffix(
-			logfield.Truncate(in, b), logfield.TruncationMarker,
+			logfield.Truncate(in, budget), "[truncated]",
 		)
 
 		assert.True(
 			t, utf8.ValidString(got),
-			"budget %d produced invalid UTF-8", b,
+			"budget %d produced invalid UTF-8", budget,
 		)
-		assert.LessOrEqual(t, encodedCost(got), b)
+		assert.LessOrEqual(t, encodedCost(got), budget)
 	}
 }

internal/middleware/accesslog_test.go

@@ -376,7 +376,7 @@ func lineSizeCases() map[string]sizeCase {
 
 	// The url field on a 5xx keeps the concrete path, so it reaches its
 	// own budget on the same line as the three header fields. That is
-	// the widest access log line the service can be made to write.
+	// the widest line the service can be made to write.
 	longPath := "/boom/" + strings.Repeat("x", oversizedSegmentBytes)
 	wantLongURL := longPath[:maxFieldBytes] + truncationSuffix
 

internal/middleware/csrf.go

@@ -4,7 +4,6 @@ import (
 	"net/http"
 
 	"github.com/gorilla/csrf"
-	"sneak.berlin/go/webhooker/internal/logfield"
 )
 
 // CSRFToken retrieves the CSRF token from the request context.
@@ -43,22 +42,9 @@ func isClientTLS(r *http.Request) bool {
 // csrf.Secure option is set at creation time, not per-request.
 func (m *Middleware) CSRF() func(http.Handler) http.Handler {
 	csrfErrorHandler := http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
-		// CSRF is registered ahead of RequireAuth on every route
-		// group that uses it, so this WARN is reachable by an
-		// unauthenticated client: a POST with no token to
-		// /source/<any length of any text>/edit lands here. The
-		// method and path are capped against the same budgets as
-		// the access log. remote_addr is set by net/http from the
-		// accepted connection rather than by the client, and
-		// csrf.FailureReason returns one of gorilla/csrf's own
-		// fixed error values, so neither is client-sized.
 		m.log.Warn("csrf: token validation failed",
-			"method", logfield.Truncate(
-				r.Method, maxLogMethodBytes,
-			),
-			"path", logfield.Truncate(
-				r.URL.Path, logfield.MaxBytes,
-			),
+			"method", r.Method,
+			"path", r.URL.Path,
 			"remote_addr", r.RemoteAddr,
 			"reason", csrf.FailureReason(r),
 		)

internal/middleware/logbound_test.go

@@ -1,544 +0,0 @@
-package middleware_test
-
-// This file covers the log lines OUTSIDE the access log that carry a
-// client-chosen value. accesslog_test.go bounds the one INFO line the
-// Logging middleware writes; these are the separate slog calls that
-// were never in that sweep and so never got the budget:
-//
-//   - MaxBodySize's 413 rejection, at WARN, registered ahead of
-//     RequireAuth and therefore reachable unauthenticated at a URL of
-//     the client's choosing.
-//   - CSRF's 403 rejection, at WARN, also registered ahead of
-//     RequireAuth.
-//   - The rate limiters' 429 rejection, at WARN, on the
-//     unauthenticated receiver among others.
-//   - RequireAuth's own unauthenticated-request line, at DEBUG.
-//   - RecordLoginFailure's throttle rejection, at WARN. Its cap is
-//     defensive rather than load-bearing today: chi pins the one
-//     route that calls it to the constant path "/pages/login". The
-//     method is exported and takes any *http.Request, so the test
-//     below hands it the request a caller on a parameterised route
-//     would, which is what the cap exists for.
-//
-// Every case here holds the ENCODED line to
-// middleware.MaxAccessLogLineBytes, under both handlers
-// internal/logger can install, against 8 KB of client-chosen text
-// built out of the characters those handlers escape. A budget spent
-// in raw bytes passes the plain-ASCII cases and fails the rest.
-
-import (
-	"bytes"
-	"context"
-	"io"
-	"log/slog"
-	"net/http"
-	"net/http/httptest"
-	"net/url"
-	"strings"
-	"testing"
-
-	"github.com/stretchr/testify/assert"
-	"github.com/stretchr/testify/require"
-	"sneak.berlin/go/webhooker/internal/config"
-	"sneak.berlin/go/webhooker/internal/middleware"
-)
-
-// bodyLimitBytes is the MaxBodySize cap these tests install. Any
-// declared Content-Length above it takes the 413 branch.
-const bodyLimitBytes = 1024
-
-// declaredBodyBytes is the Content-Length an oversize request
-// declares. Nothing is actually sent: the 413 branch fires off the
-// declaration alone, which is what makes the attack free.
-const declaredBodyBytes = bodyLimitBytes * 2
-
-// receiverLimitPerMinute is the per-entrypoint receiver limit these
-// tests install. The aggregate limiter sits at ten times this, so a
-// flood stays under it and the rejections come from the
-// per-entrypoint limiter, which is the one that logs the path.
-const receiverLimitPerMinute = 8
-
-// escapeFills are the characters a client can put in a request that
-// the log handlers then escape, coming out wider than they went in.
-// A budget counted in raw bytes lets any of them buy a field several
-// times its nominal size.
-//
-// U+1000C is the case the JSON handler alone does not reach: it is
-// unassigned, so it is non-printable, and strconv.Quote spells a
-// non-printable rune at or above U+10000 as a ten-byte \UXXXXXXXX
-// while the JSON handler passes its four UTF-8 bytes through. Only
-// the text-handler shape of these tests holds that charge honest.
-func escapeFills() map[string]string {
-	return map[string]string{
-		"plain":     "x",
-		"quote":     `"`,
-		"backslash": `\`,
-		"tab":       "\t",
-		"newline":   "\n",
-		// A C0 control neither handler has a short escape for, so
-		// each one costs six bytes on the line against the single
-		// byte it cost to send. This is the widest multiplier a
-		// client can drive, and the case a raw-byte budget breaks
-		// on first.
-		//
-		// This fill is load-bearing, not decoration. Budgeting raw
-		// bytes instead of encoded is caught by this fill alone,
-		// and only under the JSON handler, at 3,072 bytes against
-		// the 2,560 ceiling. Drop it and that mutation passes.
-		"control": "\x01",
-		"astral":  "\U0001000C",
-	}
-}
-
-// logHandlers are the two handlers internal/logger can install: the
-// JSON one, and the text one it selects when stderr is a tty. They do
-// not escape alike, and MaxAccessLogLineBytes is quoted unqualified,
-// so every case runs through both.
-func logHandlers() map[string]func(
-	io.Writer, *slog.HandlerOptions,
-) slog.Handler {
-	return map[string]func(
-		io.Writer, *slog.HandlerOptions,
-	) slog.Handler{
-		"json": func(
-			w io.Writer, o *slog.HandlerOptions,
-		) slog.Handler {
-			return slog.NewJSONHandler(w, o)
-		},
-		"text": func(
-			w io.Writer, o *slog.HandlerOptions,
-		) slog.Handler {
-			return slog.NewTextHandler(w, o)
-		},
-	}
-}
-
-// oversizedPathSegment builds an 8 KB client-chosen path segment out
-// of repetitions of ch, percent-encoded so it survives URL parsing
-// into r.URL.Path the way it would arriving off a socket.
-//
-// Both markers sit at the END, past every budget, so their absence
-// from the log is what proves the value was cut rather than merely
-// being short. The leading 'x' keeps the segment non-empty for fills
-// that a parser might otherwise fold away.
-func oversizedPathSegment(ch string) string {
-	return url.PathEscape(
-		"x" + strings.Repeat(ch, oversizedSegmentBytes) +
-			attackerMarker + tailMarker,
-	)
-}
-
-// capturingLogger returns a logger at DEBUG writing into the returned
-// buffer through the named handler.
-func capturingLogger(
-	newHandler func(io.Writer, *slog.HandlerOptions) slog.Handler,
-) (*slog.Logger, *bytes.Buffer) {
-	buf := new(bytes.Buffer)
-	opts := &slog.HandlerOptions{Level: slog.LevelDebug}
-
-	return slog.New(newHandler(buf, opts)), buf
-}
-
-// capturingBoundMiddleware builds a Middleware with a real session
-// manager (CSRF needs its key, RequireAuth needs its store) whose log
-// is captured at DEBUG.
-func capturingBoundMiddleware(
-	t *testing.T,
-	newHandler func(io.Writer, *slog.HandlerOptions) slog.Handler,
-) (*middleware.Middleware, *bytes.Buffer) {
-	t.Helper()
-
-	log, buf := capturingLogger(newHandler)
-
-	cfg := &config.Config{
-		Environment:       config.EnvironmentDev,
-		ReceiverRateLimit: receiverLimitPerMinute,
-	}
-
-	sess := newTestSessionManager(cfg, log, nil)
-
-	return middleware.NewForTest(log, cfg, sess), buf
-}
-
-// unreachable is a next-handler that fails the test if the middleware
-// under test let the request through. Every site here rejects.
-func unreachable(t *testing.T) http.Handler {
-	t.Helper()
-
-	return http.HandlerFunc(func(http.ResponseWriter, *http.Request) {
-		assert.Fail(t, "rejected request reached the next handler")
-	})
-}
-
-// logSite is one non-access-log call site that logs a client-chosen
-// path. drive sends requests at it that all take the rejecting
-// branch; linesPerRequest is how many log lines one such request
-// produces there.
-type logSite struct {
-	// build wraps the site's middleware around a handler that must
-	// not be reached.
-	build func(
-		t *testing.T, m *middleware.Middleware,
-	) http.Handler
-	// send issues one request for the given client-chosen path and
-	// returns the status. Some sites need a warm-up request before
-	// they reject, which send performs itself.
-	send func(h http.Handler, path string) int
-	// wantStatus is the status the rejecting branch answers with.
-	wantStatus int
-}
-
-// postOversize sends a POST whose declared Content-Length exceeds the
-// body limit without sending a body, which is the whole cost of the
-// attack on the MaxBodySize branch.
-func postOversize(h http.Handler, path string) int {
-	req := httptest.NewRequestWithContext(
-		context.Background(), http.MethodPost, path, nil,
-	)
-	req.ContentLength = declaredBodyBytes
-	req.Header.Set(
-		"Content-Type", "application/x-www-form-urlencoded",
-	)
-
-	w := httptest.NewRecorder()
-	h.ServeHTTP(w, req)
-
-	return w.Code
-}
-
-// postNoToken sends a POST carrying no CSRF token and no session
-// cookie, which is what an unauthenticated client sends.
-func postNoToken(h http.Handler, path string) int {
-	req := httptest.NewRequestWithContext(
-		context.Background(), http.MethodPost, path,
-		strings.NewReader(""),
-	)
-	req.Header.Set(
-		"Content-Type", "application/x-www-form-urlencoded",
-	)
-
-	w := httptest.NewRecorder()
-	h.ServeHTTP(w, req)
-
-	return w.Code
-}
-
-// getNoSession sends a GET with no session cookie.
-func getNoSession(h http.Handler, path string) int {
-	req := httptest.NewRequestWithContext(
-		context.Background(), http.MethodGet, path, nil,
-	)
-
-	w := httptest.NewRecorder()
-	h.ServeHTTP(w, req)
-
-	return w.Code
-}
-
-// logSites enumerates the call sites under test.
-func logSites() map[string]logSite {
-	return map[string]logSite{
-		// The site this file exists for: WARN, on by default, and
-		// registered ahead of RequireAuth.
-		"maxbodysize 413": {
-			build: func(
-				t *testing.T, m *middleware.Middleware,
-			) http.Handler {
-				t.Helper()
-
-				return m.MaxBodySize(bodyLimitBytes)(
-					unreachable(t),
-				)
-			},
-			send:       postOversize,
-			wantStatus: http.StatusRequestEntityTooLarge,
-		},
-		// Also ahead of RequireAuth, also WARN.
-		"csrf 403": {
-			build: func(
-				t *testing.T, m *middleware.Middleware,
-			) http.Handler {
-				t.Helper()
-
-				return m.CSRF()(unreachable(t))
-			},
-			send:       postNoToken,
-			wantStatus: http.StatusForbidden,
-		},
-		// The per-entrypoint receiver limiter, unauthenticated. Its
-		// bucket is keyed on the path, so the first request through a
-		// fresh path is served and only the ones after it are
-		// rejected; sendUntilLimited absorbs that.
-		"receiver rate limit 429": {
-			build: func(
-				t *testing.T, m *middleware.Middleware,
-			) http.Handler {
-				t.Helper()
-
-				return m.ReceiverRateLimit()(okHandler())
-			},
-			send:       sendUntilLimited,
-			wantStatus: http.StatusTooManyRequests,
-		},
-		// RequireAuth's own line. DEBUG is off in production by
-		// default, but turning it on to diagnose a flood must not
-		// restore an unbounded write.
-		"requireauth redirect": {
-			build: func(
-				t *testing.T, m *middleware.Middleware,
-			) http.Handler {
-				t.Helper()
-
-				return m.RequireAuth()(unreachable(t))
-			},
-			send:       getNoSession,
-			wantStatus: http.StatusSeeOther,
-		},
-	}
-}
-
-// sendUntilLimited drives the per-entrypoint receiver limiter past
-// its allowance on one path and returns the status of the rejected
-// request. Every request before the last is served, and only the last
-// one logs.
-func sendUntilLimited(h http.Handler, path string) int {
-	code := http.StatusOK
-
-	for range receiverLimitPerMinute + 1 {
-		req := httptest.NewRequestWithContext(
-			context.Background(), http.MethodPost, path, nil,
-		)
-		req.RemoteAddr = "203.0.113.7:5555"
-
-		w := httptest.NewRecorder()
-		h.ServeHTTP(w, req)
-		code = w.Code
-	}
-
-	return code
-}
-
-// logLines splits the captured buffer into non-empty lines, holding
-// each to bound bytes.
-func logLines(t *testing.T, buf *bytes.Buffer, bound int) []string {
-	t.Helper()
-
-	var lines []string
-
-	for line := range strings.SplitSeq(
-		strings.TrimSpace(buf.String()), "\n",
-	) {
-		if line == "" {
-			continue
-		}
-
-		require.LessOrEqual(
-			t, len(line), bound,
-			"log line exceeded its bound: %s", line,
-		)
-
-		lines = append(lines, line)
-	}
-
-	return lines
-}
-
-// assertNoClientText fails if any marker from the far end of the
-// client-chosen input survived into the log. Their absence is what
-// distinguishes a real cut from a value that merely happened to be
-// short.
-func assertNoClientText(t *testing.T, buf *bytes.Buffer) {
-	t.Helper()
-
-	assert.NotContains(
-		t, buf.String(), attackerMarker,
-		"log carried attacker-chosen text",
-	)
-	assert.NotContains(
-		t, buf.String(), tailMarker,
-		"log carried the tail of the attacker-chosen text",
-	)
-}
-
-// TestLogLines_ClientChosenPathDoesNotSizeTheLine points 8 KB of
-// client-chosen path at each non-access-log call site that logs one,
-// through both handlers and through every character those handlers
-// escape, and holds the resulting line to MaxAccessLogLineBytes.
-//
-// Removing any one of the logfield.Truncate calls at those sites
-// fails this test: the line grows to roughly the size of the input,
-// or to several times it on the escaping fills.
-func TestLogLines_ClientChosenPathDoesNotSizeTheLine(t *testing.T) {
-	t.Parallel()
-
-	for siteName, site := range logSites() {
-		for handlerName, newHandler := range logHandlers() {
-			for fillName, fill := range escapeFills() {
-				name := siteName + "/" + handlerName + "/" + fillName
-
-				t.Run(name, func(t *testing.T) {
-					t.Parallel()
-
-					m, buf := capturingBoundMiddleware(
-						t, newHandler,
-					)
-
-					path := "/source/" +
-						oversizedPathSegment(fill) + "/edit"
-
-					assert.Equal(
-						t,
-						site.wantStatus,
-						site.send(site.build(t, m), path),
-					)
-
-					lines := logLines(
-						t, buf,
-						middleware.MaxAccessLogLineBytes,
-					)
-					require.NotEmpty(
-						t, lines,
-						"the site under test logged nothing, "+
-							"so the bound proves nothing",
-					)
-					assertNoClientText(t, buf)
-				})
-			}
-		}
-	}
-}
-
-// TestLoginThrottle_LogLineDoesNotTrackPathSize pins the cap on
-// RecordLoginFailure's "login failure limit exceeded" WARN line.
-//
-// That site does not fit logSites above: it is not a middleware
-// wrapping a handler but an exported method the login handler calls,
-// and the only route that calls it today is chi's static
-// "/pages/login", so no request through the mux can widen the line.
-// Driving the method directly is therefore the whole point rather
-// than a shortcut — it is exactly the call a second caller on a route
-// with a URL parameter would make, and without this test removing the
-// logfield.Truncate there fails nothing.
-func TestLoginThrottle_LogLineDoesNotTrackPathSize(t *testing.T) {
-	t.Parallel()
-
-	for handlerName, newHandler := range logHandlers() {
-		for fillName, fill := range escapeFills() {
-			t.Run(handlerName+"/"+fillName, func(t *testing.T) {
-				t.Parallel()
-
-				m, buf := capturingBoundMiddleware(
-					t, newHandler,
-				)
-
-				req := httptest.NewRequestWithContext(
-					context.Background(),
-					http.MethodPost,
-					"/source/"+
-						oversizedPathSegment(fill)+"/login",
-					nil,
-				)
-				req.RemoteAddr = "203.0.113.9:5555"
-
-				// The budget is spent per client and username,
-				// so one more failure than the budget allows is
-				// what takes the throttled branch.
-				var throttled bool
-				for range middleware.LoginRateLimitConst + 1 {
-					throttled = m.RecordLoginFailure(
-						req, "someone",
-					)
-				}
-
-				require.True(
-					t, throttled,
-					"the throttled branch never ran, so the "+
-						"bound proves nothing",
-				)
-
-				lines := logLines(
-					t, buf, middleware.MaxAccessLogLineBytes,
-				)
-				require.NotEmpty(t, lines)
-				assertNoClientText(t, buf)
-			})
-		}
-	}
-}
-
-// TestMaxBodySize_FloodOfOversizePathsDoesNotGrowTheLog is the
-// flood shape from the issue: an unauthenticated client posting
-// oversize declarations at invented 8 KB paths, as fast as it likes.
-//
-// It asserts the property directly rather than by proxy — the bytes
-// the flood writes to the operator's log do not track the bytes the
-// flood sent. The same flood at a one-character path is the control:
-// 8 KB of extra input per request buys at most the field budget, not
-// 8 KB of log.
-func TestMaxBodySize_FloodOfOversizePathsDoesNotGrowTheLog(
-	t *testing.T,
-) {
-	t.Parallel()
-
-	for handlerName, newHandler := range logHandlers() {
-		for fillName, fill := range escapeFills() {
-			t.Run(handlerName+"/"+fillName, func(t *testing.T) {
-				t.Parallel()
-
-				flood := func(segment func(i int) string) int {
-					m, buf := capturingBoundMiddleware(
-						t, newHandler,
-					)
-					h := m.MaxBodySize(bodyLimitBytes)(
-						unreachable(t),
-					)
-
-					for i := range floodRequests {
-						assert.Equal(
-							t,
-							http.StatusRequestEntityTooLarge,
-							postOversize(
-								h,
-								"/source/"+segment(i)+"/edit",
-							),
-						)
-					}
-
-					lines := logLines(
-						t, buf,
-						middleware.MaxAccessLogLineBytes,
-					)
-					require.Len(t, lines, floodRequests)
-					assertNoClientText(t, buf)
-
-					return buf.Len()
-				}
-
-				sent := oversizedSegmentBytes * floodRequests
-
-				oversize := flood(func(i int) string {
-					return oversizedPathSegment(fill) +
-						strings.Repeat("y", i)
-				})
-				control := flood(func(i int) string {
-					return "a" + strings.Repeat("y", i)
-				})
-
-				// The whole point: 8 KB per request of extra
-				// client-chosen input bought a bounded amount of
-				// log, not a proportional amount.
-				assert.Less(
-					t, oversize-control, sent/2,
-					"log volume tracked the size of the flood's "+
-						"input",
-				)
-				assert.LessOrEqual(
-					t,
-					oversize,
-					floodRequests*
-						middleware.MaxAccessLogLineBytes,
-				)
-			})
-		}
-	}
-}

internal/middleware/loginguard.go

@@ -7,8 +7,6 @@ import (
 	"net/http"
 	"sync"
 	"time"
-
-	"sneak.berlin/go/webhooker/internal/logfield"
 )
 
 const (
@@ -175,38 +173,10 @@ func newLoginGuard(
 // acquire reserves a verification slot, waiting up to the guard's
 // wait for one. It reports false when the queue of waiters is
 // already full, when no slot became available in time, or when the
-// request was cancelled while waiting; the caller must then answer
-// 503 without verifying anything. The returned function releases the
+// request was cancelled first; the caller must then answer 503
+// without verifying anything. The returned function releases the
 // slot and must be called exactly once.
-//
-// ctx is consulted only once the request has to wait: a slot that is
-// free on arrival is handed out without looking at it, so an
-// already-cancelled request can be granted one. That is deliberate
-// and matches lifecycle.waitDone — the caller abandons the work on
-// its own ctx and releases the slot immediately, so nothing is spent
-// on it, and refusing instead would mean shedding a request with
-// capacity standing free.
 func (g *loginGuard) acquire(ctx context.Context) (func(), bool) {
-	// A free slot is taken before any timer is armed, and before a
-	// queue place is claimed: a request that never waits is not a
-	// waiter. Without this preamble the bounded select below can find
-	// its slot send and an already-expired timer ready at the same
-	// time, and Go picks among ready cases uniformly at random — so a
-	// process descheduled for longer than the wait sheds a request
-	// with slots standing free, which is precisely when shedding is
-	// least defensible.
-	//
-	// This cannot let a late arrival barge past a queued waiter. A
-	// waiter can only be parked on a FULL buffer, and a release
-	// refills that buffer from the head of the send queue under the
-	// channel lock, so the buffer never appears non-full while anyone
-	// is parked and this send fails whenever there is a waiter.
-	select {
-	case g.slots <- struct{}{}:
-		return func() { <-g.slots }, true
-	default:
-	}
-
 	// Shedding past the queue depth is what keeps waiting memory
 	// bounded; the wait alone only bounds how long one waiter holds
 	// its parsed form, not how many hold one at once.
@@ -374,17 +344,8 @@ func (m *Middleware) RecordLoginFailure(
 ) bool {
 	throttled := m.guard().fail(m.clientKey(r), username)
 	if throttled {
-		// Truncated even though chi pins this route's path to
-		// the 12-byte constant "/pages/login": RecordLoginFailure
-		// is exported and takes any *http.Request, so a caller on
-		// a route with a URL parameter would otherwise widen this
-		// line. logbound_test.go pins the cap by making exactly
-		// that call, since no request through the mux can.
 		m.log.Warn(
-			"login failure limit exceeded",
-			"path", logfield.Truncate(
-				r.URL.Path, logfield.MaxBytes,
-			),
+			"login failure limit exceeded", "path", r.URL.Path,
 		)
 	}
 

internal/middleware/loginguard_test.go

@@ -29,15 +29,6 @@ const (
 
 	guardClient = "198.51.100.7"
 	guardUser   = "admin"
-
-	// racePasses is how many times a both-cases-ready select race is
-	// run. A pass can only go the wrong way once the zero-duration
-	// timer has fired, so the per-pass detection probability is
-	// somewhere below 1/2 rather than exactly it; the bound that
-	// matters is that passes are independent, so a regression that
-	// survives is exponentially unlikely in N. The test still waits
-	// on nothing.
-	racePasses = 1000
 )
 
 // newGuard builds a guard with production-shaped defaults and the
@@ -233,13 +224,6 @@ func TestLoginGuard_SemaphoreBoundsConcurrentVerifications(
 	const (
 		concurrency = 2
 		workers     = 12
-
-		// rendezvousDeadlock is the deadlock guard described below.
-		// It is orders of magnitude longer than any scheduling delay,
-		// so it never decides the result, and well inside script/test's
-		// 30s timeout, so a wedge fails on the assertion instead of
-		// blowing the package timeout.
-		rendezvousDeadlock = 5 * time.Second
 	)
 
 	g := newGuard(middleware.LoginFailureMaxKeysConst, concurrency)
@@ -249,55 +233,12 @@ func TestLoginGuard_SemaphoreBoundsConcurrentVerifications(
 		inside  int
 		highest int
 		wg      sync.WaitGroup
-		recorded sync.WaitGroup
-		once     sync.Once
 	)
 
-	// Slot holders rendezvous instead of sleeping, and they hold until
-	// every worker has been answered. A sleep only makes overlap
-	// likely — on a host loaded enough to deschedule a goroutine for
-	// longer than the sleep the workers serialise and the maximum
-	// observed comes back as 1 — so the rendezvous is what makes the
-	// overlap a fact rather than a race won.
-	//
-	// The barrier must not open at the concurrency-th holder, which
-	// would fix the lower bound at the cost of the upper one this test
-	// exists to enforce: holders would leave as soon as the count
-	// reached concurrency, so a guard admitting extra requests would
-	// let them arrive after the first holders had already left and
-	// highest would report concurrency however many were really let
-	// in. It opens instead once every worker's acquire has returned
-	// and any slot it won has been counted, so under a broken guard
-	// every admitted worker is inside simultaneously and highest is
-	// the true maximum. Under a correct guard the refused workers
-	// return within the guard's own wait, which decides nothing beyond
-	// how long that takes.
-	overlapped := make(chan struct{})
-	closeOverlapped := func() {
-		once.Do(func() { close(overlapped) })
-	}
-
-	// Deadlock guard, not a timing margin: no assertion depends on its
-	// length, and the only way to reach it is a worker that never
-	// returns from acquire at all. It is here so that such a wedge
-	// fails legibly on the assertion below instead of hanging until
-	// the package test timeout.
-	abandon := time.AfterFunc(rendezvousDeadlock, closeOverlapped)
-	defer abandon.Stop()
-
-	recorded.Add(workers)
-
-	go func() {
-		recorded.Wait()
-		closeOverlapped()
-	}()
-
 	for range workers {
 		wg.Go(func() {
 			release, ok := g.AcquireForTest(context.Background())
 			if !ok {
-				recorded.Done()
-
 				return
 			}
 
@@ -312,12 +253,9 @@ func TestLoginGuard_SemaphoreBoundsConcurrentVerifications(
 
 			mu.Unlock()
 
-			// Counted before signalling, so the barrier can never open
-			// while an admitted worker is still on its way to being
-			// counted.
-			recorded.Done()
-
-			<-overlapped
+			// Hold the slot long enough that the other workers are
+			// certainly contending for it.
+			time.Sleep(10 * time.Millisecond)
 
 			mu.Lock()
 			inside--
@@ -340,14 +278,6 @@ func TestLoginGuard_SemaphoreBoundsConcurrentVerifications(
 // what happens when every slot is taken for longer than the wait: the
 // request is refused, so the caller answers 503 without allocating
 // another 64 MB hash.
-//
-// Neither half of this rides on the wait being long enough. The
-// refusal holds the only slot across the whole of the second call, so
-// there is no wait it could get lucky with — the wait fixes only how
-// long the refusal takes, not whether it happens. The reuse after
-// release is settled by acquire's non-blocking preamble, which is
-// pinned separately by TestLoginGuard_FreeSlotBeatsAnExpiredWait. So
-// the wait below is sized to keep the test quick, not to win a race.
 func TestLoginGuard_SaturatedSemaphoreRefusesRatherThanQueueing(
 	t *testing.T,
 ) {
@@ -375,58 +305,13 @@ func TestLoginGuard_SaturatedSemaphoreRefusesRatherThanQueueing(
 	release()
 
 	release, ok = g.AcquireForTest(context.Background())
-
-	// require, not assert: acquire returns a nil release alongside a
-	// false ok, so calling it after a non-fatal assertion turns one
-	// failed test into a segfault that takes the whole package test
-	// binary down. Every assertion whose value is dereferenced later
-	// has to stop the test.
-	require.True(
+	assert.True(
 		t, ok, "the slot must be reusable once released",
 	)
 
 	release()
 }
 
-// TestLoginGuard_FreeSlotBeatsAnExpiredWait is the determinism this
-// file used to lack. acquire selects over a slot send and a wait
-// timer, and Go chooses among ready cases uniformly at random, so a
-// call made after the timer had already fired was a coin flip: on a
-// loaded host the previous test's third acquire could be refused
-// with its slot standing free, and then dereference the nil release
-// it got back.
-//
-// The wait here is already elapsed on arrival, which is the worst
-// case that scheduling can produce, so a free slot must still be
-// granted every time. Without acquire's non-blocking preamble each
-// pass is an independent coin flip and the loop fails within a few
-// passes; with it the property holds by construction and no wall
-// clock is involved.
-func TestLoginGuard_FreeSlotBeatsAnExpiredWait(t *testing.T) {
-	t.Parallel()
-
-	g := middleware.NewLoginGuardForTest(
-		middleware.LoginRateLimitConst,
-		guardInterval,
-		middleware.LoginFailureMaxKeysConst,
-		1,
-		middleware.PasswordVerifyMaxWaitersConst,
-		0,
-	)
-
-	for pass := range racePasses {
-		release, ok := g.AcquireForTest(context.Background())
-		require.Truef(
-			t, ok,
-			"pass %d was refused a slot that was free; an expired "+
-				"wait must never beat an available slot",
-			pass,
-		)
-
-		release()
-	}
-}
-
 // TestLoginGuard_AcquireHonoursCancellation proves a client that
 // disconnects while queued frees its place immediately instead of
 // holding it for the full wait.
@@ -503,20 +388,13 @@ func TestLoginGuard_ShedsPastTheQueueCap(t *testing.T) {
 		neverElapses = time.Minute
 
 		// The probe carries its own deadline, so a guard that queues
-		// the probe instead of shedding it fails here rather than
-		// hanging until the package test timeout.
-		//
-		// This is a patience budget, not a margin to be won. A shed
-		// returns in microseconds and a probe that queued instead
-		// would not return for neverElapses, so the two are a whole
-		// minute apart and any budget between them separates them. It
-		// is set far above any scheduling stall a loaded host can
-		// produce, because the previous 200 ms — and the 100 ms
-		// elapsed-time assertion it fed — bounded the latency of a
-		// goroutine hand-off, which is a false red waiting to happen
-		// on the machine this suite runs on. What actually proves the
-		// probe was not queued is the queue depth asserted below.
-		probePatience = 5 * time.Second
+		// the probe instead of shedding it fails on the elapsed time
+		// rather than hanging until the package test timeout.
+		probeWait = 200 * time.Millisecond
+
+		// Shedding takes no measurable time; queueing takes the whole
+		// probeWait. Anything under half of it is unambiguous.
+		shedFast = probeWait / 2
 	)
 
 	g := middleware.NewLoginGuardForTest(
@@ -535,17 +413,22 @@ func TestLoginGuard_ShedsPastTheQueueCap(t *testing.T) {
 	defer release()
 	defer fillQueue(t, g, maxWaiters)()
 
-	granted, answered := probeQueueCap(g, probePatience)
+	got := probeQueueCap(g, probeWait)
 
-	require.True(
-		t, answered,
+	require.NotNil(
+		t, got,
 		"a request arriving past the queue cap is still waiting to "+
 			"be queued; it must have been shed",
 	)
 	assert.False(
-		t, granted,
+		t, got.ok,
 		"a request arriving past the queue cap must be shed",
 	)
+	assert.Less(
+		t, got.elapsed, shedFast,
+		"shedding must be immediate; waiting for a place in the "+
+			"queue is the memory growth this bounds",
+	)
 	assert.Equal(
 		t, maxWaiters, g.QueuedWaitersForTest(),
 		"a shed request must not have grown the queue",
@@ -575,14 +458,10 @@ func fillQueue(
 		})
 	}
 
-	// Patience budget, not a margin: the waiters park in microseconds
-	// and nothing releases them, so the only way to exhaust this is a
-	// guard that never queues. One second is the same order as the
-	// scheduling stalls this suite has to survive, so it is not one.
 	require.Eventually(
 		t,
 		func() bool { return g.QueuedWaitersForTest() == n },
-		5*time.Second, time.Millisecond,
+		time.Second, time.Millisecond,
 		"the waiters must reach the queue before the cap is tested",
 	)
 
@@ -592,38 +471,41 @@ func fillQueue(
 	}
 }
 
-// probeQueueCap acquires from another goroutine. It reports, in
-// order, whether the call was granted a slot and whether it was
-// answered at all within wait; a call that never returned reports
-// false for both.
+// probeResult is what the queue-cap probe reports: whether it got a
+// slot, and how long it took to find out.
+type probeResult struct {
+	ok      bool
+	elapsed time.Duration
+}
+
+// probeQueueCap acquires from another goroutine and reports the
+// result, or nil if the call was still blocked after wait.
 //
 // It runs off the test goroutine deliberately. Joining a full queue
 // is not cancellable by context — refusing to join is the property
 // under test — so a guard that fails this would otherwise hang the
 // package until the test timeout instead of failing here.
-//
-// It reports no elapsed time. Timing a goroutine hand-off measures
-// the host, not the guard, and the caller distinguishes shedding from
-// queueing by the queue depth instead.
 func probeQueueCap(
 	g *middleware.LoginGuard,
 	wait time.Duration,
-) (bool, bool) {
-	probed := make(chan bool, 1)
+) *probeResult {
+	probed := make(chan probeResult, 1)
 
 	go func() {
+		start := time.Now()
+
 		release, ok := g.AcquireForTest(context.Background())
 		if ok {
 			release()
 		}
 
-		probed <- ok
+		probed <- probeResult{ok: ok, elapsed: time.Since(start)}
 	}()
 
 	select {
 	case result := <-probed:
-		return result, true
+		return &result
 	case <-time.After(wait):
-		return false, false
+		return nil
 	}
 }

internal/middleware/middleware.go

@@ -57,7 +57,7 @@ const (
 	// MaxAccessLogLineBytes is the ceiling on one JSON access log line,
 	// and the number an operator multiplies by the request rate to size
 	// log storage. It is not an observation of a sample: it is the sum
-	// of the budgets above, each of which logfield.Truncate enforces in
+	// of the field budgets, each of which logfield.Truncate enforces in
 	// ENCODED bytes, plus the part of the line no client can influence.
 	//
 	//	url, useragent, referer   3*(512+11) = 1569
@@ -85,60 +85,21 @@ const (
 	// The text handler's fixed portion is 286, the smaller of the two,
 	// which puts its worst case at 2037.
 	//
-	// It is also the ceiling on every OTHER line this service writes
-	// THROUGH SLOG that carries text an UNAUTHENTICATED client
-	// supplies. Those lines — the MaxBodySize rejection, the CSRF
-	// rejection, the rate-limit rejection, the unauthenticated-request
-	// and unknown-entrypoint DEBUG lines, the failed-login DEBUG
-	// lines, and the two login-throttle WARN lines ("login failure
-	// limit exceeded" in loginguard.go and "password verification
-	// capacity exhausted" in internal/handlers/auth.go) — spend the
-	// same per-field budgets, and each carries strictly fewer
-	// client-supplied fields than the access log does,
-	// so none of them can reach a width the access log cannot. That is
-	// asserted directly, per line and under both handlers, rather than
-	// left to the reasoning: see logbound_test.go in this package and
-	// in internal/handlers.
+	// The access log is the widest line this service writes that
+	// carries client-chosen text, so the figure is also the ceiling on
+	// the other writer that does: the GORM adapter in
+	// internal/gormlog, whose widest line spends two logfield.MaxBytes
+	// budgets (the interpolated SQL and the driver error) against a
+	// fixed portion smaller than this one's.
+	// internal/gormlog/gormlog_test.go asserts that against this
+	// constant directly rather than leaving it as arithmetic.
 	//
-	// The two login-throttle lines are capped defensively: chi pins
-	// their route to the constant path "/pages/login", so no request
-	// through the mux can widen either one. Their assertions call
-	// RecordLoginFailure and the login handler directly with the path
-	// a caller on a parameterised route would supply, which is the
-	// only way those caps can be pinned at all.
-	//
-	// One writer in that set is not a handler's own slog call. The
-	// GORM adapter in internal/gormlog logs the statement with the
-	// client-chosen parameter already interpolated into it, which on
-	// the receiver and login lookups is exactly the value the budgets
-	// above exist for. Its widest line spends two logfield.MaxBytes
-	// budgets — the statement and the driver error — against a fixed
-	// portion smaller than this one's, and
-	// internal/gormlog/gormlog_test.go asserts every line it emits
-	// against this constant directly rather than leaving it as
-	// arithmetic.
-	//
-	// What it does NOT cover, so that the figure above is not read as
-	// more than it is:
-	//
-	//   - Lines carrying an AUTHENTICATED operator's own input, which
-	//     are not truncated at all: the webhook name on "webhook
-	//     created" and the target host on "target URL blocked by SSRF
-	//     protection" (both internal/handlers/source_management.go),
-	//     and target_name in internal/delivery/engine.go and
-	//     target_http.go. Each is bounded only by the 1 MB form body
-	//     cap, so a 100 KB name writes one line of roughly 600 KB.
-	//     Deliberate: truncating the operator's own configuration
-	//     echoed back costs debuggability against no adversary.
-	//   - 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
-	//     log line: its client-supplied fields are charged the same
-	//     budgets, but it carries a whole goroutine stack as well and
-	//     is wider than this figure. It has its own stated ceiling,
-	//     MaxPanicLogLineBytes in recoverer.go, and is written once
-	//     per recovered panic rather than once per request.
+	// It is not the widest line the service can write. A handler panic
+	// arrives through net/http's nil ErrorLog as one record carrying a
+	// whole goroutine stack, measured at 2,772 bytes. That value is
+	// the runtime's, not a client's, so it is a carve-out this ceiling
+	// states rather than covers; see README.md and
+	// https://git.eeqj.de/sneak/webhooker/issues/187.
 	MaxAccessLogLineBytes = 2560
 )
 
@@ -390,21 +351,10 @@ func (s *Middleware) RequireAuth() func(http.Handler) http.Handler {
 			// session lands here and is sent back to the login
 			// page.
 			if !s.session.IsAuthenticated(sess) {
-				// This is the unauthenticated branch, so both
-				// fields are entirely client-chosen and neither
-				// is bounded by anything the router did. DEBUG
-				// is off by default, but turning it on to
-				// diagnose a problem must not hand a client an
-				// unbounded write into the log, so the same
-				// budgets apply here as in the access log.
 				s.log.Debug(
 					"auth middleware: unauthenticated request",
-					"path", logfield.Truncate(
-						r.URL.Path, logfield.MaxBytes,
-					),
-					"method", logfield.Truncate(
-						r.Method, maxLogMethodBytes,
-					),
+					"path", r.URL.Path,
+					"method", r.Method,
 				)
 				http.Redirect(
 					w, r, "/pages/login", http.StatusSeeOther,
@@ -564,26 +514,10 @@ func (s *Middleware) MaxBodySize(
 			}
 
 			if r.ContentLength > maxBytes {
-				// This runs ahead of RequireAuth (see
-				// setupUserRoutes and friends in
-				// internal/server/routes.go), so an
-				// unauthenticated client reaches it with a path
-				// of its own choosing and its own length —
-				// POST /source/<8 KB>/edit with an oversize
-				// declared Content-Length costs nothing to
-				// send. At WARN, on by default, that is a
-				// write into the operator's log sized by the
-				// attacker unless the path is capped. Same
-				// budgets as the access log, so this line
-				// cannot be wider than that one.
 				s.log.Warn(
 					"request body exceeds limit",
-					"method", logfield.Truncate(
-						r.Method, maxLogMethodBytes,
-					),
-					"path", logfield.Truncate(
-						r.URL.Path, logfield.MaxBytes,
-					),
+					"method", r.Method,
+					"path", r.URL.Path,
 					"content_length", r.ContentLength,
 					"limit", maxBytes,
 				)

internal/middleware/middleware_test.go

@@ -57,21 +57,7 @@ func testMiddlewareWithSessionClock(
 		SessionIdleTimeout: idleTimeout,
 	}
 
-	sessManager := newTestSessionManager(cfg, log, clock)
-
-	m := middleware.NewForTest(log, cfg, sessManager)
-
-	return m, sessManager, clock
-}
-
-// newTestSessionManager builds the real session.Session the
-// middleware tests run against: an in-memory cookie store with a
-// known key, and optionally a manually advanced clock.
-func newTestSessionManager(
-	cfg *config.Config,
-	log *slog.Logger,
-	clock *fakeClock,
-) *session.Session {
+	// Create a real session manager with a known key
 	key := make([]byte, testKeySize)
 
 	for i := range key {
@@ -93,7 +79,11 @@ func newTestSessionManager(
 		now = clock.Now
 	}
 
-	return session.NewForTest(store, cfg, log, key, now)
+	sessManager := session.NewForTest(store, cfg, log, key, now)
+
+	m := middleware.NewForTest(log, cfg, sessManager)
+
+	return m, sessManager, clock
 }
 
 // fakeClock is a manually advanced clock, so session expiry can be

internal/middleware/ratelimit.go

@@ -9,7 +9,6 @@ import (
 	"time"
 
 	"github.com/go-chi/httprate"
-	"sneak.berlin/go/webhooker/internal/logfield"
 )
 
 const (
@@ -226,22 +225,11 @@ func (m *Middleware) clientKey(r *http.Request) string {
 // rejection with logMessage and answers with responseMessage.
 // httprate adds the Retry-After header (RFC 6585). The aggregate
 // receiver limiter uses floodTooManyRequests instead.
-//
-// The path is capped against the same budget as the access log's url
-// field. The per-entrypoint receiver limiter is unauthenticated and
-// its path is a client-chosen segment of client-chosen length, so at
-// WARN an uncapped path would let a sender pick the size of the line
-// it writes — the same defect the access log capping closed.
 func (m *Middleware) tooManyRequests(
 	logMessage, responseMessage string,
 ) http.HandlerFunc {
 	return func(w http.ResponseWriter, r *http.Request) {
-		m.log.Warn(
-			logMessage,
-			"path", logfield.Truncate(
-				r.URL.Path, logfield.MaxBytes,
-			),
-		)
+		m.log.Warn(logMessage, "path", r.URL.Path)
 		http.Error(w, responseMessage, http.StatusTooManyRequests)
 	}
 }

internal/middleware/recoverer.go

@@ -1,209 +0,0 @@
-package middleware
-
-import (
-	"errors"
-	"fmt"
-	"net/http"
-	"runtime/debug"
-
-	"github.com/go-chi/chi/middleware"
-	"sneak.berlin/go/webhooker/internal/logfield"
-)
-
-const (
-	// maxPanicValueBytes bounds the recovered panic value. The value
-	// is our own text, but a handler is free to build one out of the
-	// request — panic(fmt.Sprintf("bad %q", r.URL.Path)) — so it is
-	// charged the same budget the access log gives a field the
-	// client supplies outright.
-	maxPanicValueBytes = logfield.MaxBytes
-
-	// maxPanicStackBytes bounds the stack, in the same ENCODED bytes
-	// logfield.Truncate charges everywhere else. Nothing a client
-	// sends chooses the depth of our own call stack, so this is not
-	// a safety limit; it is what makes MaxPanicLogLineBytes an
-	// arithmetic ceiling rather than an observation. A stack is cut
-	// at its far end, which is net/http's accept frames — the panic
-	// site and the handler that reached it are at the near end and
-	// are always kept.
-	//
-	// For scale: a handler panicking under the full shipped
-	// middleware chain produces a stack of roughly 3,690 bytes in a
-	// 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
-	// 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
-
-	// MaxPanicLogLineBytes is the ceiling on the single line a
-	// recovered panic writes. It is wider than
-	// MaxAccessLogLineBytes, which bounds a line written once per
-	// request, where this one is written once per recovered panic.
-	//
-	//	panic                     512+11 =  523
-	//	stack                    8192+11 = 8203
-	//	request_id                128+11 =  139
-	//	fixed portion                    =  256
-	//	                                    ----
-	//	                                    9121
-	//
-	// The fixed portion is the JSON punctuation, the field names,
-	// the level, the message, the timestamp at its longest and the
-	// response_committed boolean.
-	//
-	// Stated at 10240 so the figure carries headroom rather than
-	// sitting on the arithmetic, exactly as MaxAccessLogLineBytes
-	// is. Both handlers internal/logger can install are covered, for
-	// 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
-	// is illustration: with all three growable fields — the stack,
-	// the panic value and a client-supplied X-Request-Id — driven
-	// 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
-)
-
-// recoverResponseWriter records whether the response has been
-// committed, which is the one thing the recoverer cannot learn from
-// the panic itself: a handler that panics after writing a status has
-// already spent the response, and a second WriteHeader would only
-// draw net/http's "superfluous response.WriteHeader" complaint
-// without changing what the client received.
-type recoverResponseWriter struct {
-	http.ResponseWriter
-
-	committed bool
-}
-
-func (w *recoverResponseWriter) WriteHeader(code int) {
-	w.committed = true
-
-	w.ResponseWriter.WriteHeader(code)
-}
-
-func (w *recoverResponseWriter) Write(b []byte) (int, error) {
-	// An unheralded Write commits the response just as surely as
-	// WriteHeader does: net/http sends 200 in front of it.
-	w.committed = true
-
-	//nolint:wrapcheck // Pass the writer's own error through unchanged.
-	return w.ResponseWriter.Write(b)
-}
-
-// Unwrap lets http.ResponseController reach the writer underneath, so
-// a handler can still flush or set a write deadline through this
-// wrapper.
-func (w *recoverResponseWriter) Unwrap() http.ResponseWriter {
-	return w.ResponseWriter
-}
-
-// Recoverer returns middleware that turns a handler panic into one
-// structured ERROR record and a 500, rather than a dropped
-// connection.
-//
-// It replaces chi's middleware.Recoverer, which does neither on a
-// current Go release. chi v1.5.5's pretty-printer scans the stack for
-// a frame beginning "panic(0x", which the runtime has not emitted
-// since it started printing "panic({0x...}"; the scan therefore never
-// terminates early, every line reaches decorateFuncCallLine, and that
-// function slices pkg[strings.Index(pkg, "."):] without checking for
-// -1. The resulting second panic escapes chi's own deferred function,
-// so its WriteHeader(500) never runs and net/http closes the
-// connection reporting its own crash instead of the original one.
-// See https://git.eeqj.de/sneak/webhooker/issues/187.
-//
-// chi v5.3.1 has since fixed both halves of that — it scans for
-// "panic(" and guards the index — so upgrading would restore the 500.
-// It would not give what this does: v5 still writes an ANSI-coloured
-// pretty stack straight to os.Stderr, outside internal/logger, outside
-// any budget, at no level the operator set.
-//
-// Where this sits in the chain is load-bearing, and routes.go states
-// it: inside everything that observes the response, so the 500 is
-// what the access log records and the metrics count, and outside the
-// sentryhttp handler, whose Repanic option depends on something
-// further out recovering what it re-raises.
-func (s *Middleware) Recoverer() func(http.Handler) http.Handler {
-	return func(next http.Handler) http.Handler {
-		return http.HandlerFunc(func(
-			w http.ResponseWriter,
-			r *http.Request,
-		) {
-			rw := &recoverResponseWriter{ResponseWriter: w}
-
-			defer func() {
-				rvr := recover()
-				if rvr == nil {
-					return
-				}
-
-				// http.ErrAbortHandler is a handler stating that it
-				// is abandoning the connection on purpose, not a
-				// fault. net/http special-cases it, suppressing both
-				// the stack trace and any response, so it is passed
-				// straight back out rather than logged and answered.
-				err, isError := rvr.(error)
-				if isError &&
-					errors.Is(err, http.ErrAbortHandler) {
-					panic(rvr)
-				}
-
-				s.logPanic(r, rvr, rw.committed)
-
-				if rw.committed {
-					return
-				}
-
-				http.Error(
-					rw,
-					http.StatusText(
-						http.StatusInternalServerError,
-					),
-					http.StatusInternalServerError,
-				)
-			}()
-
-			next.ServeHTTP(rw, r)
-		})
-	}
-}
-
-// logPanic writes the record. Every field it can grow is truncated to
-// a fixed budget, so MaxPanicLogLineBytes holds.
-//
-// The request is identified by request_id alone rather than by
-// repeating the method, URL and address: the access log line for the
-// same request carries all of those, already bounded, and — because
-// the recoverer runs inside the logging middleware — now carries the
-// 500 as its status too. Repeating them here would double those
-// budgets against a line already wider than the access log's ceiling,
-// to say a second time what one join already says.
-func (s *Middleware) logPanic(
-	r *http.Request,
-	rvr any,
-	committed bool,
-) {
-	s.log.Error("handler panic",
-		"panic", logfield.Truncate(
-			fmt.Sprint(rvr), maxPanicValueBytes,
-		),
-		"stack", logfield.Truncate(
-			string(debug.Stack()), maxPanicStackBytes,
-		),
-		"request_id", logfield.Truncate(
-			middleware.GetReqID(r.Context()),
-			maxLogRequestIDBytes,
-		),
-		"response_committed", committed,
-	)
-}

internal/middleware/recoverer_test.go

@@ -1,645 +0,0 @@
-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))
-}

internal/server/export_test.go

@@ -54,40 +54,3 @@ func NewRouterForTest(
 
 	return s.router
 }
-
-// ProbePattern is the route NewRouterWithProbeForTest adds to the
-// production route tree.
-const ProbePattern = "/probe"
-
-// NewRouterWithProbeForTest builds the production route tree exactly
-// as NewRouterForTest does and then registers probe at ProbePattern,
-// so a test can drive a handler that panics through the shipped
-// global middleware chain rather than a hand-assembled one. Nothing
-// about the chain is rebuilt here: the probe is an extra leaf under
-// the same Use() registrations every other route gets.
-//
-// sentryEnabled selects whether the sentryhttp handler is registered,
-// which in production a configured SENTRY_DSN decides. It is a
-// parameter because the relationship between that handler's Repanic
-// option and the recoverer registered outside it is the thing a test
-// has to be able to pin.
-func NewRouterWithProbeForTest(
-	log *slog.Logger,
-	cfg *config.Config,
-	mw *middleware.Middleware,
-	h *handlers.Handlers,
-	sentryEnabled bool,
-	probe http.HandlerFunc,
-) http.Handler {
-	s := &Server{
-		log:           log,
-		mw:            mw,
-		h:             h,
-		params:        ServerParams{Config: cfg},
-		sentryEnabled: sentryEnabled,
-	}
-	s.SetupRoutes()
-	s.router.Handle(ProbePattern, probe)
-
-	return s.router
-}

internal/server/recoverer_test.go

@@ -1,285 +0,0 @@
-package server_test
-
-import (
-	"bytes"
-	"context"
-	"encoding/json"
-	"fmt"
-	"net/http"
-	"net/http/httptest"
-	"os"
-	"os/exec"
-	"strings"
-	"testing"
-
-	"github.com/getsentry/sentry-go"
-	"github.com/stretchr/testify/assert"
-	"github.com/stretchr/testify/require"
-	"sneak.berlin/go/webhooker/internal/middleware"
-	"sneak.berlin/go/webhooker/internal/server"
-)
-
-// panicProbeMarker is the value the probe handler panics with. The
-// defect this pins lost it entirely: what reached the operator was the
-// recoverer's own secondary panic, naming chi's decorateFuncCallLine
-// and nothing about the fault that caused it.
-const panicProbeMarker = "QQPRODUCTIONPANICVALUEQQ"
-
-// panicChildEnv, when set, tells the re-executed test binary to run
-// the child half of the fd-level probe below.
-const panicChildEnv = "WEBHOOKER_PANIC_PROBE_CHILD"
-
-// panicChildResultPrefix labels the child's own one-line report of
-// what the HTTP client saw, so the parent can find it among whatever
-// else lands on the child's standard output.
-const panicChildResultPrefix = "PANIC-PROBE-RESULT "
-
-// stackTruncationMarker mirrors what internal/middleware appends to a
-// field it cut. It is duplicated rather than exported, as the access
-// log's budgets are, so that changing it has to be restated here
-// deliberately.
-const stackTruncationMarker = "[truncated]"
-
-// TestPanicThroughProductionRouter drives a handler panic through the
-// shipped router, over a real server, in a subprocess whose actual
-// file descriptors are captured.
-//
-// Every part of that is load-bearing.
-//
-// A subprocess, because the question is what reaches fd 1 and fd 2 of
-// the process an operator runs. The defect's signature was 0 bytes on
-// standard error and a 2,772-byte record on standard output describing
-// chi's own crash, and neither is visible to a test that swaps the
-// logger for a buffer.
-//
-// A real server, because a panicking handler under chi's Recoverer
-// dropped the connection: the client got EOF, not a status. An
-// httptest.ResponseRecorder has no connection to drop and would have
-// recorded the same unwritten response either way, which is why this
-// defect survived the existing suite.
-//
-// The production router, because the placement of the recoverer among
-// the other global middleware is part of the fix.
-func TestPanicThroughProductionRouter(t *testing.T) {
-	t.Parallel()
-
-	if os.Getenv(panicChildEnv) != "" {
-		t.Skip("child half; run by the parent below")
-	}
-
-	//nolint:gosec // Re-executing this test binary, with a fixed arg.
-	cmd := exec.CommandContext(
-		t.Context(), os.Args[0],
-		"-test.run", "^TestPanicProbeChild$",
-	)
-
-	cmd.Env = append(os.Environ(), panicChildEnv+"=1")
-
-	var stdout, stderr bytes.Buffer
-
-	cmd.Stdout = &stdout
-	cmd.Stderr = &stderr
-
-	require.NoError(
-		t, cmd.Run(),
-		"child failed\nstdout:\n%s\nstderr:\n%s",
-		stdout.String(), stderr.String(),
-	)
-
-	assertPanicProbeOutput(t, stdout.String(), stderr.String())
-}
-
-// assertPanicProbeOutput holds the child's descriptors to what a
-// working recoverer produces.
-func assertPanicProbeOutput(t *testing.T, stdout, stderr string) {
-	t.Helper()
-
-	result := ""
-
-	var record map[string]any
-
-	for line := range strings.SplitSeq(stdout, "\n") {
-		if after, found := strings.CutPrefix(
-			line, panicChildResultPrefix,
-		); found {
-			result = after
-
-			continue
-		}
-
-		if !strings.HasPrefix(line, `{"time"`) {
-			continue
-		}
-
-		decoded := map[string]any{}
-		if json.Unmarshal([]byte(line), &decoded) != nil {
-			continue
-		}
-
-		if decoded["msg"] == "handler panic" {
-			require.Nil(
-				t, record, "one panic record expected, got two",
-			)
-
-			record = decoded
-
-			assert.LessOrEqual(
-				t, len(line), middleware.MaxPanicLogLineBytes,
-				"the panic record must hold its stated ceiling",
-			)
-
-			t.Logf(
-				"panic record through the shipped chain: %d bytes "+
-					"(ceiling %d)",
-				len(line), middleware.MaxPanicLogLineBytes,
-			)
-		}
-	}
-
-	// What the client got. Under the defect this read
-	// `status=0 err=... EOF`.
-	require.Equal(
-		t, "status=500 err=<nil>", result,
-		"the client must receive a 500, not a dropped connection",
-	)
-
-	// What the operator got. Under the defect there was no such
-	// record: standard output carried net/http reporting chi's own
-	// crash, at INFO, with the original panic value nowhere in it.
-	require.NotNil(
-		t, record,
-		"no structured panic record reached standard output",
-	)
-	assert.Equal(t, "ERROR", record["level"])
-	assert.Equal(t, panicProbeMarker, record["panic"])
-	assert.Equal(t, false, record["response_committed"])
-
-	stack, ok := record["stack"].(string)
-	require.True(t, ok)
-	assert.Contains(t, stack, "panicProbeHandler")
-	assert.NotContains(
-		t, stack, stackTruncationMarker,
-		"the shipped middleware chain's own stack must fit the "+
-			"stack budget without being cut",
-	)
-	t.Logf("stack through the shipped chain: %d bytes", len(stack))
-
-	// The secondary panic, in every form it took. net/http's report
-	// is the tell: it only logs a request when something escaped the
-	// handler chain.
-	assert.NotContains(t, stdout, "http: panic serving")
-	assert.NotContains(t, stdout, "slice bounds out of range")
-	assert.NotContains(t, stdout, "decorateFuncCallLine")
-	assert.Empty(
-		t, strings.TrimSpace(stderr),
-		"nothing may reach standard error",
-	)
-}
-
-// panicProbeHandler is the panicking route the child installs. It is a
-// named function so the stack assertion has something to look for.
-func panicProbeHandler(http.ResponseWriter, *http.Request) {
-	panic(panicProbeMarker)
-}
-
-// TestPanicProbeChild is the child half of the probe above. It runs
-// only when re-executed with panicChildEnv set; in an ordinary run it
-// returns immediately.
-//
-// It writes its result to standard output with a prefix rather than
-// asserting, because the assertions belong to the parent, which is the
-// only side that can see both descriptors.
-func TestPanicProbeChild(t *testing.T) {
-	t.Parallel()
-
-	if os.Getenv(panicChildEnv) == "" {
-		return
-	}
-
-	env := newTestEnv(t)
-
-	router := server.NewRouterWithProbeForTest(
-		env.log.Get(), env.cfg, env.mw, env.hnd,
-		false, panicProbeHandler,
-	)
-
-	srv := httptest.NewServer(router)
-	defer srv.Close()
-
-	req, err := http.NewRequestWithContext(
-		context.Background(), http.MethodGet,
-		srv.URL+server.ProbePattern, nil,
-	)
-	require.NoError(t, err)
-
-	status := 0
-
-	resp, err := srv.Client().Do(req)
-	if err == nil {
-		status = resp.StatusCode
-
-		_ = resp.Body.Close()
-	}
-
-	// Written to the descriptor rather than through the testing
-	// package's own output, because fd 1 is exactly what the parent
-	// is measuring.
-	_, writeErr := fmt.Fprintf(
-		os.Stdout, "%sstatus=%d err=%v\n",
-		panicChildResultPrefix, status, err,
-	)
-	require.NoError(t, writeErr)
-}
-
-// TestSentryStillSeesAPanic pins the relationship the recoverer's
-// placement has to preserve. sentryhttp is registered with
-// Repanic: true, inside the recoverer, so an operator with SENTRY_DSN
-// set keeps the report and the client still gets a 500. Registered the
-// other way round, the SDK would swallow the panic and the recoverer
-// would never see it.
-func TestSentryStillSeesAPanic(t *testing.T) {
-	t.Parallel()
-
-	env := newTestEnv(t)
-
-	transport := &captureTransport{}
-
-	opts := server.SentryClientOptionsForTest(
-		"https://public@sentry.invalid/1", "webhooker-test",
-	)
-	opts.Transport = transport
-
-	client, err := sentry.NewClient(opts)
-	require.NoError(t, err)
-
-	router := server.NewRouterWithProbeForTest(
-		env.log.Get(), env.cfg, env.mw, env.hnd,
-		true, panicProbeHandler,
-	)
-
-	req := httptest.NewRequestWithContext(
-		sentry.SetHubOnContext(
-			context.Background(),
-			sentry.NewHub(client, sentry.NewScope()),
-		),
-		http.MethodGet, server.ProbePattern, nil,
-	)
-
-	w := httptest.NewRecorder()
-	router.ServeHTTP(w, req)
-
-	assert.Equal(
-		t, http.StatusInternalServerError, w.Code,
-		"the recoverer must still answer what sentryhttp re-raised",
-	)
-
-	events := transport.events
-	require.Len(t, events, 1, "Sentry must still see the panic")
-	assert.Equal(t, sentry.LevelFatal, events[0].Level)
-	// The SDK renders a string panic value as the event message
-	// rather than an exception, so the whole payload is checked for
-	// the value rather than one field of it.
-	assert.Contains(
-		t, marshalEvent(t, events[0]), panicProbeMarker,
-	)
-}

internal/server/routes.go

@@ -14,28 +14,6 @@ import (
 // maxFormBodySize is the maximum allowed request body size (in
 // bytes) for form POST endpoints. 1 MB is generous for any form
 // submission while preventing abuse from oversized payloads.
-//
-// Every route group below installs MaxBodySize(maxFormBodySize) as
-// its FIRST middleware, ahead of both CSRF and RequireAuth. Both
-// orderings are deliberate.
-//
-// Ahead of CSRF because gorilla/csrf parses the form. The cap has to
-// be installed before anything reads the body, or the parse runs
-// under net/http's 10 MB default instead of this one.
-//
-// Ahead of RequireAuth because an oversize body should be refused
-// before the request buys a cookie decrypt, a session load and the
-// database read behind it. Rejecting first is the cheaper failure,
-// and it is the ordering that keeps an unauthenticated flood from
-// choosing how much session work the process does.
-//
-// What that ordering costs: the 413 branch is reachable
-// unauthenticated, at a URL of the client's choosing and of the
-// client's chosen length. So is the CSRF rejection, which sits in
-// front of RequireAuth for the same reason. Both log that path, so
-// both cap it — see the log calls in Middleware.MaxBodySize and
-// Middleware.CSRF, which spend the same per-field budget as the
-// access log.
 const maxFormBodySize int64 = 1 * 1024 * 1024 // 1 MB
 
 // requestTimeout is the maximum time allowed for a single HTTP
@@ -51,6 +29,7 @@ func (s *Server) SetupRoutes() {
 }
 
 func (s *Server) setupGlobalMiddleware() {
+	s.router.Use(middleware.Recoverer)
 	s.router.Use(middleware.RequestID)
 	s.router.Use(s.mw.SecurityHeaders())
 	s.router.Use(s.mw.Logging())
@@ -63,21 +42,8 @@ func (s *Server) setupGlobalMiddleware() {
 	s.router.Use(s.mw.CORS())
 	s.router.Use(middleware.Timeout(requestTimeout))
 
-	// Panic recovery, deliberately here rather than first. It has to
-	// run inside every middleware that observes the response, so the
-	// 500 it writes is the status the access log records and the
-	// metrics count, and outside the sentryhttp handler below, whose
-	// Repanic option needs something further out to catch what it
-	// re-raises. chi's own middleware.Recoverer held the first slot
-	// until it was measured: on a current Go release it crashes
-	// inside its stack pretty-printer instead of recovering, so the
-	// connection dropped and the original panic was never reported.
-	// See https://git.eeqj.de/sneak/webhooker/issues/187.
-	s.router.Use(s.mw.Recoverer())
-
 	// Sentry error reporting (if SENTRY_DSN is set). Repanic is
-	// true so panics still bubble up to the Recoverer middleware
-	// registered immediately above.
+	// true so panics still bubble up to the Recoverer middleware.
 	if s.sentryEnabled {
 		sentryHandler := sentryhttp.New(sentryhttp.Options{
 			Repanic: true,
@@ -124,8 +90,8 @@ func (s *Server) setupRoutes() {
 
 func (s *Server) setupPageRoutes() {
 	s.router.Route("/pages", func(r chi.Router) {
-		// MaxBodySize precedes CSRF and RequireAuth deliberately;
-		// see maxFormBodySize for why, and for what it costs.
+		// MaxBodySize must precede CSRF: gorilla/csrf parses the
+		// form, so the cap has to be installed before it runs.
 		r.Use(s.mw.MaxBodySize(maxFormBodySize))
 		r.Use(s.mw.CSRF())
 		r.Use(s.mw.NoCache())
@@ -145,8 +111,8 @@ func (s *Server) setupPageRoutes() {
 
 func (s *Server) setupUserRoutes() {
 	s.router.Route("/user/{username}", func(r chi.Router) {
-		// MaxBodySize precedes CSRF and RequireAuth deliberately;
-		// see maxFormBodySize for why, and for what it costs.
+		// MaxBodySize must precede CSRF: gorilla/csrf parses the
+		// form, so the cap has to be installed before it runs.
 		r.Use(s.mw.MaxBodySize(maxFormBodySize))
 		r.Use(s.mw.CSRF())
 		r.Use(s.mw.NoCache())
@@ -160,8 +126,8 @@ func (s *Server) setupUserRoutes() {
 
 func (s *Server) setupSourceRoutes() {
 	s.router.Route("/sources", func(r chi.Router) {
-		// MaxBodySize precedes CSRF and RequireAuth deliberately;
-		// see maxFormBodySize for why, and for what it costs.
+		// MaxBodySize must precede CSRF: gorilla/csrf parses the
+		// form, so the cap has to be installed before it runs.
 		r.Use(s.mw.MaxBodySize(maxFormBodySize))
 		r.Use(s.mw.CSRF())
 		r.Use(s.mw.NoCache())
@@ -172,8 +138,8 @@ func (s *Server) setupSourceRoutes() {
 	})
 
 	s.router.Route("/source/{sourceID}", func(r chi.Router) {
-		// MaxBodySize precedes CSRF and RequireAuth deliberately;
-		// see maxFormBodySize for why, and for what it costs.
+		// MaxBodySize must precede CSRF: gorilla/csrf parses the
+		// form, so the cap has to be installed before it runs.
 		r.Use(s.mw.MaxBodySize(maxFormBodySize))
 		r.Use(s.mw.CSRF())
 		r.Use(s.mw.NoCache())

internal/server/routes_test.go

@@ -52,15 +52,6 @@ type testEnv struct {
 	sess   *session.Session
 	db     *database.Database
 	dbMgr  *database.WebhookDBManager
-
-	// The collaborators the router was built from, kept so a test
-	// that needs a second router over the same graph — one carrying
-	// a panicking probe route, or one with Sentry registered — can
-	// build it without wiring the graph again.
-	log *logger.Logger
-	cfg *config.Config
-	mw  *middleware.Middleware
-	hnd *handlers.Handlers
 }
 
 // newTestEnv wires the dependency graph with fx and builds the
@@ -109,10 +100,6 @@ func newTestEnv(t *testing.T) *testEnv {
 		sess:   sess,
 		db:     db,
 		dbMgr:  dbMgr,
-		log:    log,
-		cfg:    cfg,
-		mw:     mw,
-		hnd:    hnd,
 	}
 }
 

internal/server/sentry_test.go

@@ -127,14 +127,12 @@ func (c sentryCase) capture(t *testing.T) []*sentry.Event {
 	return transport.events
 }
 
-// router mirrors the one ordering these tests depend on, over the two
-// route patterns they need: a recovering middleware outside, then the
+// router mirrors setupGlobalMiddleware's ordering over the two route
+// patterns these tests need: a recovering middleware first, then the
 // sentryhttp handler registered with Use and Repanic set, exactly as
-// routes.go orders the two. The bare recover stands in for
-// Middleware.Recoverer, which holds that outer slot in production; it
-// is here only to keep panic stacks out of the test output. That the
-// production one really does catch what sentryhttp re-raises is
-// pinned separately, by TestSentryStillSeesAPanic.
+// routes.go registers it. The local recover stands in for chi's
+// middleware.Recoverer, which holds that slot in production; it is
+// here only to keep panic stacks out of the test output.
 func (c sentryCase) router() http.Handler {
 	handler := func(_ http.ResponseWriter, r *http.Request) {
 		// This call is what drains the body tee and fills the

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 "$@"