Record the 1.0.0 milestone as complete in TODO.md

The Status section claimed next held the completed 1.0.0 milestone with
every issue closed. Four are open (#176, #178, #186, #187), so a merge
of next to main would have shipped that claim to main.

Next Step still named #115 and #125 as open owner decisions; both
landed. It now names the real open items, #150 and #112, and the forced
merge order for the remaining four.

Completed Steps was seventeen units behind, back to 2026-08-12.

README.md

@@ -994,15 +994,16 @@ 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 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`
+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`
 requests and has the rest of its aggregate budget rejected there, so
-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.
+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.
 
 What the access log does bound is the _content_ of those lines. A 3xx
 or 4xx response logs the chi route pattern — `/webhook/{uuid}`,
@@ -1140,41 +1141,196 @@ 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: 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 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.
 
 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.
 
-One line is wider, and it is the widest this service writes: the record
-a recovered panic produces. The recover middleware in
-`internal/middleware` answers `500` and writes one `ERROR` record
-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.
+**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:
 
-That record is bounded the same way, in the same encoded bytes: 512 for
-the panic value, because a handler is free to build one out of the
-request, 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:
+| 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
+`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:
+
+- **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
+  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. `internal/middleware/recoverer_test.go` measures
-8,898 with the stack and the panic value both driven past their
-budgets, over both handlers. The real case is far below that: through
-the shipped middleware chain the whole record is 3,959 bytes, which
-`internal/server/recoverer_test.go` measures on the process's own file
-descriptors, driving a panic through the production router over a real
-server in a subprocess.
+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.
 
 Every limiter here — receiver, login, and password change — identifies
 the client the same way, through one shared key function: the
@@ -1414,6 +1570,10 @@ webhooker/
 │   │   └── webhook_db_manager.go  # Per-webhook DB lifecycle manager
 │   ├── globals/
 │   │   └── globals.go         # Build-time variables (appname, version, arch)
+│   ├── gormlog/
+│   │   └── gormlog.go         # GORM's logger.Interface on top of slog, bounded
+│   ├── logfield/
+│   │   └── logfield.go        # Encoded-byte budget for client-supplied log values
 │   ├── delivery/
 │   │   ├── engine.go          # Event-driven delivery engine (channel + timer based)
 │   │   ├── circuit_breaker.go # Per-target circuit breaker for http/slack targets with retries

REPO_POLICIES.md

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

TODO.md

@@ -24,30 +24,142 @@ 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 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
+`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
 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 to `main` and tag 1.0.0 from it.
+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.
 
-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`).
+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.
 
 # 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/database.go

@@ -17,6 +17,7 @@ import (
 	"gorm.io/gorm"
 	_ "modernc.org/sqlite" // Pure Go SQLite driver
 	"sneak.berlin/go/webhooker/internal/config"
+	"sneak.berlin/go/webhooker/internal/gormlog"
 	"sneak.berlin/go/webhooker/internal/logger"
 )
 
@@ -155,7 +156,10 @@ func (d *Database) connect() error {
 	// Then use it with GORM
 	db, err := gorm.Open(sqlite.Dialector{
 		Conn: sqlDB,
-	}, &gorm.Config{})
+	}, &gorm.Config{
+		// Never leave this at GORM's default. See internal/gormlog.
+		Logger: gormlog.New(d.log),
+	})
 	if err != nil {
 		d.log.Error(
 			"failed to connect to database",

internal/database/webhook_db_manager.go

@@ -14,6 +14,7 @@ import (
 	"gorm.io/driver/sqlite"
 	"gorm.io/gorm"
 	"sneak.berlin/go/webhooker/internal/config"
+	"sneak.berlin/go/webhooker/internal/gormlog"
 	"sneak.berlin/go/webhooker/internal/logger"
 )
 
@@ -248,7 +249,10 @@ func (m *WebhookDBManager) openDB(
 
 	db, err := gorm.Open(sqlite.Dialector{
 		Conn: sqlDB,
-	}, &gorm.Config{})
+	}, &gorm.Config{
+		// Never leave this at GORM's default. See internal/gormlog.
+		Logger: gormlog.New(m.log),
+	})
 	if err != nil {
 		_ = sqlDB.Close()
 

internal/database/webhook_db_manager_test.go

@@ -339,7 +339,12 @@ func TestWebhookDBManager_MultipleWebhooks(t *testing.T) {
 	var events []database.Event
 
 	require.NoError(t, db2.Find(&events).Error)
-	assert.Len(t, events, 1)
+
+	// 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.Equal(t, "PUT", events[0].Method)
 }
 

internal/delivery/target_database_archive.go

@@ -12,6 +12,7 @@ import (
 
 	"gorm.io/driver/sqlite"
 	"gorm.io/gorm"
+	"sneak.berlin/go/webhooker/internal/gormlog"
 )
 
 // archiveExpiryNever is the expiry sentinel (and default) that
@@ -282,7 +283,11 @@ func (w *archiveWriter) openMode(
 	}
 
 	gdb, err := gorm.Open(
-		sqlite.Dialector{Conn: sqlDB}, &gorm.Config{},
+		sqlite.Dialector{Conn: sqlDB}, &gorm.Config{
+			// Never leave this at GORM's default. See
+			// internal/gormlog.
+			Logger: gormlog.New(w.log),
+		},
 	)
 	if err != nil {
 		_ = sqlDB.Close()

internal/delivery/target_database_archive_gormlog_test.go

@@ -0,0 +1,155 @@
+package delivery_test
+
+import (
+	"bytes"
+	"log"
+	"log/slog"
+	"path/filepath"
+	"strings"
+	"sync"
+	"testing"
+	"time"
+
+	"github.com/stretchr/testify/assert"
+	"github.com/stretchr/testify/require"
+	"gorm.io/gorm"
+	gormlogger "gorm.io/gorm/logger"
+	"sneak.berlin/go/webhooker/internal/delivery"
+	"sneak.berlin/go/webhooker/internal/middleware"
+)
+
+// archiveGORMTailMarker sits at the far end of the value this file
+// drives into an archive lookup. Its presence in a log line means the
+// whole value reached the log, so nothing truncated it.
+const archiveGORMTailMarker = "ENDOFCLIENTVALUE"
+
+// archiveGORMFillBytes is how much text the lookup carries. It is far
+// past every budget in play.
+const archiveGORMFillBytes = 8 << 10
+
+// gormDefaultBuf collects what GORM's package-level default logger
+// writes, if anything reaches it.
+type gormDefaultBuf struct {
+	mu sync.Mutex
+	b  bytes.Buffer
+}
+
+func (g *gormDefaultBuf) Write(p []byte) (int, error) {
+	g.mu.Lock()
+	defer g.mu.Unlock()
+
+	return g.b.Write(p)
+}
+
+func (g *gormDefaultBuf) String() string {
+	g.mu.Lock()
+	defer g.mu.Unlock()
+
+	return g.b.String()
+}
+
+// captureArchiveGORMDefault replaces GORM's package-level default
+// logger with one configured exactly as GORM configures its own,
+// writing to a buffer.
+//
+// This duplicates the detector in internal/handlers rather than
+// sharing it: a test helper cannot cross a package's test boundary
+// without exporting production code to carry it, and a logging
+// detector is not worth a production symbol. What it detects is the
+// third gorm.Open in this service, at
+// internal/delivery/target_database_archive.go — the archive writer,
+// whose type is unexported, so nothing outside this package can drive
+// it.
+func captureArchiveGORMDefault(t *testing.T) *gormDefaultBuf {
+	t.Helper()
+
+	buf := &gormDefaultBuf{}
+	orig := gormlogger.Default
+
+	gormlogger.Default = gormlogger.New(
+		log.New(buf, "", log.LstdFlags),
+		gormlogger.Config{
+			SlowThreshold:             200 * time.Millisecond,
+			LogLevel:                  gormlogger.Warn,
+			IgnoreRecordNotFoundError: false,
+			Colorful:                  false,
+		},
+	)
+
+	t.Cleanup(func() { gormlogger.Default = orig })
+
+	return buf
+}
+
+// TestArchiveWriter_NeverUsesGORMsDefaultLogger pins the archive
+// writer's gorm.Open to the adapter.
+//
+// Restore a bare &gorm.Config{} at
+// internal/delivery/target_database_archive.go and this fails: the
+// default logger prints the fully interpolated SELECT on every
+// ErrRecordNotFound, so the client-chosen event id below arrives whole
+// and unbounded on stdout, answering to no level the operator set.
+//
+// Not parallel: gormlogger.Default is process-global. Go runs every
+// non-parallel top-level test to completion before it resumes the
+// parallel ones.
+//
+//nolint:paralleltest // Deliberately sequential; see above.
+func TestArchiveWriter_NeverUsesGORMsDefaultLogger(t *testing.T) {
+	var captured bytes.Buffer
+
+	gormDefault := captureArchiveGORMDefault(t)
+
+	w := delivery.NewExportArchiveWriter(
+		filepath.Join(t.TempDir(), "archive.db"),
+		slog.New(slog.NewTextHandler(
+			&captured, &slog.HandlerOptions{Level: slog.LevelDebug},
+		)),
+		0,
+	)
+
+	require.NoError(t, w.Open(0))
+
+	t.Cleanup(w.Evict)
+
+	// A lookup that misses, carrying a value the size of an inbound
+	// event id. Under the default logger this is the line that gets
+	// interpolated and printed.
+	value := strings.Repeat("\x01", archiveGORMFillBytes) +
+		archiveGORMTailMarker
+
+	var row delivery.ExportArchivedEvent
+
+	err := w.DB().Where("event_id = ?", value).First(&row).Error
+	require.ErrorIs(t, err, gorm.ErrRecordNotFound)
+
+	got := gormDefault.String()
+	assert.Empty(
+		t, got,
+		"GORM's default logger wrote %d bytes, so the archive "+
+			"writer's gorm.Open is back on a bare &gorm.Config{}; "+
+			"the first of them: %s",
+		len(got), got[:min(len(got), 300)],
+	)
+
+	// The adapter drops a miss, so this should be silent too — and
+	// whatever it does write stays inside the stated ceiling.
+	out := captured.String()
+
+	assert.NotContains(
+		t, out, archiveGORMTailMarker,
+		"the far end of the client-chosen value reached the log",
+	)
+
+	for line := range strings.SplitSeq(strings.TrimRight(out, "\n"), "\n") {
+		if line == "" {
+			continue
+		}
+
+		assert.LessOrEqual(
+			t, len(line), middleware.MaxAccessLogLineBytes,
+			"log line exceeded its bound: %s",
+			line[:min(len(line), 300)],
+		)
+	}
+}

internal/delivery/target_log.go

@@ -11,6 +11,17 @@ 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/export_test.go

@@ -0,0 +1,17 @@
+package gormlog
+
+import (
+	"log/slog"
+	"time"
+)
+
+// ExportNewWithSlowThreshold builds a Logger whose slow-statement
+// threshold is d rather than DefaultSlowThreshold, so a test can pin
+// which arm of Trace it is exercising instead of racing the clock on a
+// loaded machine. The threshold is set at construction, like every
+// other field, so the type's concurrency guarantee still holds.
+func ExportNewWithSlowThreshold(
+	log *slog.Logger, d time.Duration,
+) *Logger {
+	return &Logger{log: log, slowThreshold: d}
+}

internal/gormlog/gormlog.go

@@ -0,0 +1,168 @@
+// Package gormlog adapts GORM's logger onto the service's slog
+// logger.
+//
+// GORM's own default logger is not usable here. It is built at package
+// init with log.New(os.Stdout, ...) at LogLevel Warn with
+// IgnoreRecordNotFoundError false, so it writes the fully interpolated
+// SQL — parameters and all — for every statement that returns an
+// error, including gorm.ErrRecordNotFound. Two of this service's
+// lookups miss by design on unauthenticated routes: the entrypoint
+// lookup on /webhook/{uuid}, whose path segment the client picks
+// outright, and the user lookup behind the login form, whose username
+// the client picks outright. Under the default logger each of those
+// misses printed an unbounded, attacker-chosen string, at no level the
+// operator can turn down, past every handler internal/logger installs.
+//
+// This adapter fixes all three properties at once: the lines get a
+// level the operator controls, they are shaped by whichever handler
+// internal/logger selected, and every value a client can influence is
+// spent through logfield.Truncate.
+package gormlog
+
+import (
+	"context"
+	"errors"
+	"fmt"
+	"log/slog"
+	"time"
+
+	gormlogger "gorm.io/gorm/logger"
+	"sneak.berlin/go/webhooker/internal/logfield"
+)
+
+// DefaultSlowThreshold is the duration at or above which a statement
+// is logged as slow. It is GORM's own default, kept deliberately: slow
+// SQL is the one thing GORM's logger reports that nothing else in this
+// service does, so silencing the logger outright would have cost real
+// observability to fix a log-volume defect.
+const DefaultSlowThreshold = 200 * time.Millisecond
+
+// Logger implements gormlogger.Interface on top of an *slog.Logger.
+//
+// It is safe for concurrent use: every field is set at construction
+// and never written again.
+type Logger struct {
+	log           *slog.Logger
+	slowThreshold time.Duration
+}
+
+// Interface compliance is asserted here rather than discovered at the
+// gorm.Open call sites.
+var _ gormlogger.Interface = (*Logger)(nil)
+
+// New returns a GORM logger that writes through log.
+func New(log *slog.Logger) *Logger {
+	return &Logger{
+		log:           log,
+		slowThreshold: DefaultSlowThreshold,
+	}
+}
+
+// LogMode returns the logger unchanged.
+//
+// GORM's LogLevel is deliberately not honoured. Level is the operator's
+// decision and it is expressed once, through LOG_LEVEL and the
+// slog.LevelVar internal/logger holds; a second level knob inside the
+// database layer could only disagree with it. The mapping from GORM's
+// four categories onto slog levels is fixed in Trace below.
+//
+//nolint:ireturn // The interface return is GORM's signature, not a choice.
+func (l *Logger) LogMode(gormlogger.LogLevel) gormlogger.Interface {
+	return l
+}
+
+// Info logs one of GORM's own informational messages.
+func (l *Logger) Info(
+	ctx context.Context, msg string, data ...any,
+) {
+	l.log.InfoContext(ctx, "gorm", "message", format(msg, data...))
+}
+
+// Warn logs one of GORM's own warnings.
+func (l *Logger) Warn(
+	ctx context.Context, msg string, data ...any,
+) {
+	l.log.WarnContext(ctx, "gorm", "message", format(msg, data...))
+}
+
+// Error logs one of GORM's own errors.
+func (l *Logger) Error(
+	ctx context.Context, msg string, data ...any,
+) {
+	l.log.ErrorContext(ctx, "gorm", "message", format(msg, data...))
+}
+
+// Trace reports the outcome of a single statement. GORM calls it for
+// every statement it runs, so the cheap paths stay cheap: fc()
+// renders the interpolated SQL and is called only on a branch that
+// will actually emit.
+//
+// The arms are ordered exactly as GORM's own Trace orders them —
+// non-record-not-found error, then slow, then the routine case — so
+// that a statement which both misses and runs slow is still reported
+// as slow. A miss is the likeliest statement to be slow, since it is
+// the one that scans without finding a row, and ordering the drop
+// ahead of the slow arm would have made this adapter less observant
+// than the IgnoreRecordNotFoundError option it was chosen over.
+func (l *Logger) Trace(
+	ctx context.Context,
+	begin time.Time,
+	fc func() (string, int64),
+	err error,
+) {
+	elapsed := time.Since(begin)
+
+	switch {
+	case err != nil && !errors.Is(err, gormlogger.ErrRecordNotFound):
+		sql, rows := fc()
+		l.log.ErrorContext(ctx, "sql statement failed",
+			"error", logfield.Truncate(err.Error(), logfield.MaxBytes),
+			"sql", logfield.Truncate(sql, logfield.MaxBytes),
+			"rows", rows,
+			"elapsed_ms", elapsed.Milliseconds(),
+		)
+
+	case l.slowThreshold > 0 && elapsed >= l.slowThreshold:
+		sql, rows := fc()
+		l.log.WarnContext(ctx, "slow sql statement",
+			"sql", logfield.Truncate(sql, logfield.MaxBytes),
+			"rows", rows,
+			"elapsed_ms", elapsed.Milliseconds(),
+			"threshold_ms", l.slowThreshold.Milliseconds(),
+		)
+
+	case err != nil:
+		// gorm.ErrRecordNotFound is not an error on the paths that
+		// produce it here: an invented entrypoint UUID and an unknown
+		// username are the expected outcome of an unauthenticated
+		// request, not a fault. This is the IgnoreRecordNotFoundError
+		// behaviour, and it is unconditional rather than configurable
+		// because no caller in this service wants the other one — the
+		// two handlers that care already record the miss themselves,
+		// at DEBUG, without the SQL. A miss that ran slow has already
+		// been reported by the arm above.
+		return
+
+	case l.log.Enabled(ctx, slog.LevelDebug):
+		sql, rows := fc()
+		l.log.DebugContext(ctx, "sql statement",
+			"sql", logfield.Truncate(sql, logfield.MaxBytes),
+			"rows", rows,
+			"elapsed_ms", elapsed.Milliseconds(),
+		)
+	}
+}
+
+// format renders one of GORM's printf-style internal messages and
+// bounds it. GORM builds these itself, but they can quote a value the
+// statement carried, so they are spent through the same budget as
+// everything else rather than trusted.
+func format(msg string, data ...any) string {
+	if len(data) == 0 {
+		return logfield.Truncate(msg, logfield.MaxBytes)
+	}
+
+	return logfield.Truncate(
+		fmt.Sprintf(msg, data...), logfield.MaxBytes,
+	)
+}

internal/gormlog/gormlog_test.go

@@ -0,0 +1,436 @@
+package gormlog_test
+
+import (
+	"bytes"
+	"context"
+	"database/sql"
+	"fmt"
+	"log/slog"
+	"path/filepath"
+	"strings"
+	"testing"
+	"time"
+
+	"github.com/stretchr/testify/assert"
+	"github.com/stretchr/testify/require"
+	"gorm.io/driver/sqlite"
+	"gorm.io/gorm"
+	_ "modernc.org/sqlite" // Pure Go SQLite driver.
+	"sneak.berlin/go/webhooker/internal/gormlog"
+	"sneak.berlin/go/webhooker/internal/middleware"
+)
+
+// fillBytes is how much client-chosen text each case drives into the
+// statement. It is well past every budget in play, so a value that
+// arrives short arrived short because something cut it.
+const fillBytes = 8 << 10
+
+// tailMarker sits at the far end of every generated value. A line that
+// contains it carried the whole value, which means nothing cut it — so
+// a value that merely happened to be short cannot pass for a truncated
+// one.
+const tailMarker = "ENDOFCLIENTVALUE"
+
+// fills are the characters a client can drive into a SQL parameter,
+// chosen for what the log handlers charge for them rather than for
+// looking dangerous.
+//
+// The C0 control is the one that matters. Both handlers spell U+0001
+// as a six-byte escape for the single byte it costs a client to send,
+// which is the widest multiplier available in the basic multilingual
+// plane and the case a raw-byte budget breaks on first. The astral
+// non-printable costs ten under the text handler, four more than the
+// JSON handler ever spends.
+func fills() []struct {
+	name string
+	fill string
+} {
+	return []struct {
+		name string
+		fill string
+	}{
+		{"plain", "x"},
+		{"quote", `"`},
+		{"backslash", `\`},
+		{"tab", "\t"},
+		{"newline", "\n"},
+		{"c0_control", "\x01"},
+		{"astral_nonprintable", "\U0001000C"},
+	}
+}
+
+// clientValue builds a value of at least fillBytes raw bytes out of
+// fill, ending in tailMarker.
+func clientValue(fill string) string {
+	var b strings.Builder
+
+	for b.Len() < fillBytes {
+		b.WriteString(fill)
+	}
+
+	b.WriteString(tailMarker)
+
+	return b.String()
+}
+
+// handlers are the two slog handlers internal/logger can install. The
+// ceiling is quoted to operators unqualified, so every case is
+// asserted under both.
+func handlers() []struct {
+	name string
+	make func(*bytes.Buffer) slog.Handler
+} {
+	opts := &slog.HandlerOptions{Level: slog.LevelDebug}
+
+	return []struct {
+		name string
+		make func(*bytes.Buffer) slog.Handler
+	}{
+		{"json", func(b *bytes.Buffer) slog.Handler {
+			return slog.NewJSONHandler(b, opts)
+		}},
+		{"text", func(b *bytes.Buffer) slog.Handler {
+			return slog.NewTextHandler(b, opts)
+		}},
+	}
+}
+
+type thing struct {
+	ID   string `gorm:"primaryKey"`
+	Name string
+}
+
+// neverSlow is a slow-statement threshold no statement in this file
+// can reach. Cases that are about a non-slow arm of Trace set it, so
+// that a machine under load cannot turn a miss into a slow report and
+// decide the outcome for them.
+const neverSlow = time.Hour
+
+// alwaysSlow makes every statement count as slow, so the slow arm is
+// reached without the test waiting for it.
+const alwaysSlow = time.Nanosecond
+
+// openDB opens a real SQLite database behind the adapter under test,
+// so every assertion below is made against SQL that GORM actually
+// rendered rather than against a string a test wrote by hand. slow is
+// the adapter's slow-statement threshold.
+func openDB(
+	t *testing.T, buf *bytes.Buffer, h slog.Handler, slow time.Duration,
+) *gorm.DB {
+	t.Helper()
+
+	sqlDB, err := sql.Open("sqlite", fmt.Sprintf(
+		"file:%s?mode=rwc",
+		filepath.Join(t.TempDir(), "gormlog.db"),
+	))
+	require.NoError(t, err)
+
+	t.Cleanup(func() { _ = sqlDB.Close() })
+
+	gl := gormlog.ExportNewWithSlowThreshold(slog.New(h), slow)
+
+	gdb, err := gorm.Open(
+		sqlite.Dialector{Conn: sqlDB},
+		&gorm.Config{Logger: gl},
+	)
+	require.NoError(t, err)
+
+	require.NoError(t, gdb.AutoMigrate(&thing{}))
+
+	// Migration chatter is not what any of these cases is about.
+	buf.Reset()
+
+	return gdb
+}
+
+// assertBounded holds every line the adapter wrote to the stated
+// ceiling and proves each was cut rather than merely short.
+func assertBounded(t *testing.T, out string) {
+	t.Helper()
+
+	assert.NotContains(
+		t, out, tailMarker,
+		"the far end of the client value reached the log, so "+
+			"nothing truncated it",
+	)
+
+	for line := range strings.SplitSeq(
+		strings.TrimRight(out, "\n"), "\n",
+	) {
+		if line == "" {
+			continue
+		}
+
+		assert.LessOrEqual(
+			t, len(line), middleware.MaxAccessLogLineBytes,
+			"log line exceeded its bound: %s",
+			line[:min(len(line), 300)],
+		)
+	}
+}
+
+// TestRecordNotFound_WritesNothing is the defect itself. GORM's own
+// default logger prints the fully interpolated SELECT on every
+// ErrRecordNotFound, and on this service's two unauthenticated
+// lookups the interpolated parameter is whatever the client sent.
+func TestRecordNotFound_WritesNothing(t *testing.T) {
+	t.Parallel()
+
+	for _, h := range handlers() {
+		for _, f := range fills() {
+			t.Run(h.name+"/"+f.name, func(t *testing.T) {
+				t.Parallel()
+
+				var buf bytes.Buffer
+
+				gdb := openDB(t, &buf, h.make(&buf), neverSlow)
+
+				var got thing
+
+				err := gdb.Where(
+					"id = ?", clientValue(f.fill),
+				).First(&got).Error
+				require.ErrorIs(t, err, gorm.ErrRecordNotFound)
+
+				assert.Empty(
+					t, buf.String(),
+					"a miss on a client-chosen key must not "+
+						"write a log line",
+				)
+			})
+		}
+	}
+}
+
+// TestSlowRecordNotFound_IsStillReportedSlow pins the arm ordering in
+// Trace against the drop above.
+//
+// GORM's own Trace orders its cases error-that-is-not-a-miss, then
+// slow, then routine, so IgnoreRecordNotFoundError: true — the cheap
+// option this adapter was chosen over — still reports a miss that ran
+// slow. An adapter that dropped the miss first would be strictly less
+// observant than the option it replaced, on exactly the two lookups
+// this package exists for. A miss is also the statement most likely to
+// be slow, since it is the one that scans without finding a row.
+func TestSlowRecordNotFound_IsStillReportedSlow(t *testing.T) {
+	t.Parallel()
+
+	for _, h := range handlers() {
+		for _, f := range fills() {
+			t.Run(h.name+"/"+f.name, func(t *testing.T) {
+				t.Parallel()
+
+				var buf bytes.Buffer
+
+				gdb := openDB(t, &buf, h.make(&buf), alwaysSlow)
+
+				var got thing
+
+				err := gdb.Where(
+					"id = ?", clientValue(f.fill),
+				).First(&got).Error
+				require.ErrorIs(t, err, gorm.ErrRecordNotFound)
+
+				assert.Contains(
+					t, buf.String(), "slow sql statement",
+					"a slow statement that missed was not "+
+						"reported as slow",
+				)
+				assertBounded(t, buf.String())
+			})
+		}
+	}
+}
+
+// TestRecordNotFoundFlood_DoesNotGrowWithInput states the definition
+// of done directly: a flood of misses at two input sizes 64 times
+// apart must cost the same number of bytes of log.
+func TestRecordNotFoundFlood_DoesNotGrowWithInput(t *testing.T) {
+	t.Parallel()
+
+	const requests = 50
+
+	flood := func(t *testing.T, size int) int {
+		t.Helper()
+
+		var buf bytes.Buffer
+
+		gdb := openDB(
+			t, &buf,
+			slog.NewJSONHandler(&buf, &slog.HandlerOptions{
+				Level: slog.LevelDebug,
+			}),
+			neverSlow,
+		)
+
+		value := strings.Repeat("\x01", size)
+
+		for range requests {
+			var got thing
+
+			_ = gdb.Where("id = ?", value).First(&got).Error
+		}
+
+		return buf.Len()
+	}
+
+	small := flood(t, 128)
+	big := flood(t, 128*64)
+
+	assert.Equal(
+		t, small, big,
+		"log volume tracked the size of the client's input",
+	)
+}
+
+// TestStatementError_LineIsBounded covers the branch that does log.
+// A driver error is not ErrRecordNotFound, so the interpolated
+// statement is written — and on an insert the interpolated value is
+// still whatever the client supplied.
+func TestStatementError_LineIsBounded(t *testing.T) {
+	t.Parallel()
+
+	for _, h := range handlers() {
+		for _, f := range fills() {
+			t.Run(h.name+"/"+f.name, func(t *testing.T) {
+				t.Parallel()
+
+				var buf bytes.Buffer
+
+				gdb := openDB(t, &buf, h.make(&buf), neverSlow)
+
+				row := thing{ID: clientValue(f.fill), Name: "a"}
+
+				require.NoError(t, gdb.Create(&row).Error)
+
+				buf.Reset()
+
+				// The same primary key a second time: a UNIQUE
+				// constraint failure, which is an error GORM logs.
+				err := gdb.Create(&thing{
+					ID: row.ID, Name: "b",
+				}).Error
+				require.Error(t, err)
+
+				assert.Contains(
+					t, buf.String(), "sql statement failed",
+				)
+				assertBounded(t, buf.String())
+			})
+		}
+	}
+}
+
+// TestSucceedingStatement_LineIsBoundedOnEitherArm covers the two
+// arms a statement that returns no error can take, over the same
+// query, so neither can be bounded by accident of the other.
+//
+//   - slow. Silencing GORM outright would have been the cheaper fix
+//     and would have cost this report, which is the one thing GORM's
+//     logger gave an operator that nothing else in this service does.
+//   - routine. The branch an operator reaches by turning the level
+//     down to DEBUG: every statement is reported, so every
+//     statement's interpolated parameters have to be bounded too.
+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"},
+	}
+
+	for _, a := range arms {
+		for _, h := range handlers() {
+			for _, f := range fills() {
+				name := a.name + "/" + h.name + "/" + f.name
+
+				t.Run(name, func(t *testing.T) {
+					t.Parallel()
+
+					var buf bytes.Buffer
+
+					gdb := openDB(t, &buf, h.make(&buf), a.slow)
+
+					var got []thing
+
+					require.NoError(t, gdb.Where(
+						"name = ?", clientValue(f.fill),
+					).Find(&got).Error)
+
+					assert.Contains(t, buf.String(), a.want)
+
+					if a.notWant != "" {
+						assert.NotContains(
+							t, buf.String(), a.notWant,
+						)
+					}
+
+					assertBounded(t, buf.String())
+				})
+			}
+		}
+	}
+}
+
+// TestGORMOwnMessages_AreBounded covers the three printf-style
+// entry points. GORM builds these itself, but nothing stops one of
+// them quoting a value the statement carried.
+func TestGORMOwnMessages_AreBounded(t *testing.T) {
+	t.Parallel()
+
+	for _, h := range handlers() {
+		for _, f := range fills() {
+			t.Run(h.name+"/"+f.name, func(t *testing.T) {
+				t.Parallel()
+
+				var buf bytes.Buffer
+
+				gl := gormlog.New(slog.New(h.make(&buf)))
+				ctx := context.Background()
+				value := clientValue(f.fill)
+
+				gl.Info(ctx, "%s", value)
+				gl.Warn(ctx, "%s", value)
+				gl.Error(ctx, "%s", value)
+
+				// The no-argument form, which is how GORM reports
+				// most of its own conditions. Reached through a
+				// function value so the vet printf check does not
+				// read the message as a format string — which is
+				// also why the adapter does not.
+				noArgs := func(
+					f func(context.Context, string, ...any),
+					msg string,
+				) {
+					f(ctx, msg)
+				}
+				noArgs(gl.Info, value)
+
+				assertBounded(t, buf.String())
+			})
+		}
+	}
+}
+
+// TestLogMode_KeepsTheOperatorsLevel records that GORM's own level
+// knob is deliberately inert: level belongs to LOG_LEVEL, and a
+// second one inside the database layer could only disagree with it.
+func TestLogMode_KeepsTheOperatorsLevel(t *testing.T) {
+	t.Parallel()
+
+	var buf bytes.Buffer
+
+	gl := gormlog.New(slog.New(slog.NewJSONHandler(
+		&buf, &slog.HandlerOptions{Level: slog.LevelDebug},
+	)))
+
+	assert.Same(t, gl, gl.LogMode(0))
+}

internal/handlers/auth.go

@@ -5,6 +5,7 @@ import (
 	"strconv"
 
 	"sneak.berlin/go/webhooker/internal/database"
+	"sneak.berlin/go/webhooker/internal/logfield"
 )
 
 // HandleLoginPage returns a handler for the login page (GET)
@@ -70,7 +71,9 @@ func (h *Handlers) HandleLoginSubmit() http.HandlerFunc {
 
 		h.log.Info(
 			"user logged in",
-			"username", username,
+			"username", logfield.Truncate(
+				username, logfield.MaxBytes,
+			),
 			"user_id", user.ID,
 		)
 
@@ -117,7 +120,9 @@ func (h *Handlers) authenticateUser(
 	if !ok {
 		h.log.Warn(
 			"password verification capacity exhausted",
-			"path", r.URL.Path,
+			"path", logfield.Truncate(
+				r.URL.Path, logfield.MaxBytes,
+			),
 		)
 		h.renderLoginError(
 			w, r,
@@ -142,7 +147,17 @@ func (h *Handlers) authenticateUser(
 		h.dummyVerifications.Add(1)
 		database.VerifyDummyPassword(password)
 
-		h.log.Debug("user not found", "username", username)
+		// 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.rejectLogin(w, r, username)
 
 		return user, err
@@ -160,7 +175,17 @@ func (h *Handlers) authenticateUser(
 	}
 
 	if !valid {
-		h.log.Debug("invalid password", "username", username)
+		// 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.rejectLogin(w, r, username)
 
 		return user, errInvalidPassword

internal/handlers/export_test.go

@@ -2,11 +2,19 @@ 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

@@ -0,0 +1,462 @@
+package handlers_test
+
+import (
+	"bytes"
+	"context"
+	"io"
+	"log"
+	"net/http"
+	"net/http/httptest"
+	"os"
+	"strconv"
+	"strings"
+	"sync"
+	"testing"
+	"time"
+
+	"github.com/go-chi/chi"
+	"github.com/stretchr/testify/assert"
+	"github.com/stretchr/testify/require"
+	"gorm.io/gorm"
+	gormlogger "gorm.io/gorm/logger"
+	"sneak.berlin/go/webhooker/internal/database"
+	"sneak.berlin/go/webhooker/internal/handlers"
+	"sneak.berlin/go/webhooker/internal/middleware"
+)
+
+// gormBoundTailMarker sits at the far end of every client-chosen value
+// this file sends. Its presence in the log means the whole value
+// reached the log, so a value that merely happened to be short cannot
+// pass for a truncated one.
+const gormBoundTailMarker = "ENDOFCLIENTVALUE"
+
+// gormBoundFills are the characters a client can drive through the
+// receiver path segment and the login username, chosen for what a log
+// handler charges for them.
+//
+// The bare C0 control is the one that matters: both handlers spell
+// U+0001 as a six-byte escape for the one byte it costs to send, the
+// widest multiplier available below U+10000 and the case a raw-byte
+// budget breaks on first. GORM's default logger applies no budget at
+// all, so under the mutation every one of these arrives whole.
+func gormBoundFills() []struct {
+	name string
+	fill string
+} {
+	return []struct {
+		name string
+		fill string
+	}{
+		{"plain", "x"},
+		{"quote", `"`},
+		{"backslash", `\`},
+		{"tab", "\t"},
+		{"newline", "\n"},
+		{"c0_control", "\x01"},
+		{"astral_nonprintable", "\U0001000C"},
+	}
+}
+
+// syncBuf collects captured output from the goroutine draining the
+// pipe.
+type syncBuf struct {
+	mu sync.Mutex
+	b  bytes.Buffer
+}
+
+func (s *syncBuf) Write(p []byte) (int, error) {
+	s.mu.Lock()
+	defer s.mu.Unlock()
+
+	return s.b.Write(p)
+}
+
+func (s *syncBuf) String() string {
+	s.mu.Lock()
+	defer s.mu.Unlock()
+
+	return s.b.String()
+}
+
+func (s *syncBuf) reset() {
+	s.mu.Lock()
+	defer s.mu.Unlock()
+
+	s.b.Reset()
+}
+
+// stdoutCapture redirects os.Stdout for the duration of a test.
+//
+// internal/logger builds its handler over os.Stdout at construction
+// time, so redirecting the variable before the application is built
+// captures everything the service logger — and therefore the GORM
+// adapter, which writes through it — emits.
+type stdoutCapture struct {
+	buf  *syncBuf
+	r    *os.File
+	w    *os.File
+	orig *os.File
+	done chan struct{}
+	seq  int
+}
+
+func captureStdout(t *testing.T) *stdoutCapture {
+	t.Helper()
+
+	r, w, err := os.Pipe()
+	require.NoError(t, err)
+
+	c := &stdoutCapture{
+		buf:  &syncBuf{},
+		r:    r,
+		w:    w,
+		orig: os.Stdout,
+		done: make(chan struct{}),
+	}
+
+	os.Stdout = w
+
+	go func() {
+		defer close(c.done)
+
+		_, _ = io.Copy(c.buf, r)
+	}()
+
+	t.Cleanup(func() {
+		os.Stdout = c.orig
+		_ = w.Close()
+
+		<-c.done
+
+		_ = r.Close()
+	})
+
+	return c
+}
+
+// drain returns everything written since the previous drain and
+// clears the buffer.
+//
+// A sentinel is pushed through the same pipe and waited for, so the
+// draining goroutine is known to have caught up before the buffer is
+// read. Without it the comparison below would race the reader rather
+// than measure the writers.
+func (c *stdoutCapture) drain(t *testing.T) string {
+	t.Helper()
+
+	c.seq++
+
+	sentinel := "\n<<drain-" + strconv.Itoa(c.seq) + ">>\n"
+
+	_, err := c.w.WriteString(sentinel)
+	require.NoError(t, err)
+
+	deadline := time.Now().Add(10 * time.Second)
+	for !strings.Contains(c.buf.String(), sentinel) {
+		require.False(
+			t, time.Now().After(deadline),
+			"timed out waiting for captured output",
+		)
+		time.Sleep(time.Millisecond)
+	}
+
+	out := strings.Replace(c.buf.String(), sentinel, "", 1)
+
+	c.buf.reset()
+
+	return out
+}
+
+// teeStdout writes to a buffer and to whatever os.Stdout is at the
+// moment of the write.
+//
+// The second half is the point. GORM's package-level default logger
+// resolves os.Stdout once, at package init, so a logger built over the
+// variable would keep writing to the real terminal no matter what a
+// test redirects. Resolving it per write puts the bytes a defaulted
+// gorm.Config would cost in production into the same capture as
+// everything else internal/logger emits, which is what lets the volume
+// assertions below measure the whole writer set rather than one member
+// of it.
+type teeStdout struct {
+	buf *syncBuf
+}
+
+func (w teeStdout) Write(p []byte) (int, error) {
+	_, _ = os.Stdout.Write(p)
+
+	return w.buf.Write(p)
+}
+
+// captureGORMDefault replaces GORM's package-level default logger with
+// one configured exactly as GORM configures its own, writing to a
+// buffer and to os.Stdout.
+//
+// This is the mutation detector. gormlogger.Default is what a bare
+// &gorm.Config{} installs, and its config here is GORM's verbatim —
+// Warn, IgnoreRecordNotFoundError false — so a reverted call site
+// behaves as it would in production rather than as a test dialed it.
+// With every gorm.Open in this service naming its own logger, nothing
+// consults this value and the buffer stays empty; revert any one of
+// the three and the interpolated SQL lands here.
+func captureGORMDefault(t *testing.T) *syncBuf {
+	t.Helper()
+
+	buf := &syncBuf{}
+	orig := gormlogger.Default
+
+	gormlogger.Default = gormlogger.New(
+		log.New(teeStdout{buf: buf}, "", log.LstdFlags),
+		gormlogger.Config{
+			SlowThreshold:             200 * time.Millisecond,
+			LogLevel:                  gormlogger.Warn,
+			IgnoreRecordNotFoundError: false,
+			Colorful:                  false,
+		},
+	)
+
+	t.Cleanup(func() { gormlogger.Default = orig })
+
+	return buf
+}
+
+// floodUnauthenticated drives reps requests at each of the two
+// unauthenticated lookups that miss by design, for every fill, with a
+// client-chosen value of size raw bytes.
+func floodUnauthenticated(
+	t *testing.T, h *handlers.Handlers, size, reps int,
+) int {
+	t.Helper()
+
+	requests := 0
+
+	for _, f := range gormBoundFills() {
+		var b strings.Builder
+
+		for b.Len() < size {
+			b.WriteString(f.fill)
+		}
+
+		b.WriteString(gormBoundTailMarker)
+
+		value := b.String()
+
+		for range reps {
+			postWebhook(t, h, value)
+			postUnknownLogin(t, h, value)
+
+			requests += 2
+		}
+	}
+
+	return requests
+}
+
+// floodPerWebhook drives the same client-chosen values at the second
+// gorm.Open site, the per-webhook database internal/database's
+// WebhookDBManager opens.
+//
+// That site is behind authentication in production, so this is not
+// part of the unauthenticated flood above and is counted separately.
+// It is here because the ceiling the README states covers every
+// writer, and the manager is one of them: with nothing driving it, a
+// bare &gorm.Config{} could be restored at
+// internal/database/webhook_db_manager.go and the whole suite would
+// stay green.
+func floodPerWebhook(
+	t *testing.T, mgr *database.WebhookDBManager, size, reps int,
+) int {
+	t.Helper()
+
+	requests := 0
+
+	for _, f := range gormBoundFills() {
+		var b strings.Builder
+
+		for b.Len() < size {
+			b.WriteString(f.fill)
+		}
+
+		b.WriteString(gormBoundTailMarker)
+
+		value := b.String()
+
+		db, err := mgr.GetDB("pin-" + f.name)
+		require.NoError(t, err)
+
+		for range reps {
+			var got database.Event
+
+			err = db.Where("id = ?", value).First(&got).Error
+			require.ErrorIs(t, err, gorm.ErrRecordNotFound)
+
+			requests++
+		}
+	}
+
+	return requests
+}
+
+// postWebhook drives the receiver with an invented entrypoint path.
+// The route pattern matches any single segment, so every byte of the
+// value is the client's, and the lookup behind it misses by design.
+func postWebhook(
+	t *testing.T, h *handlers.Handlers, entrypoint string,
+) {
+	t.Helper()
+
+	req := httptest.NewRequestWithContext(
+		context.Background(), http.MethodPost, "/webhook/x",
+		strings.NewReader("{}"),
+	)
+
+	rctx := chi.NewRouteContext()
+	rctx.URLParams.Add("uuid", entrypoint)
+
+	req = req.WithContext(context.WithValue(
+		req.Context(), chi.RouteCtxKey, rctx,
+	))
+
+	w := httptest.NewRecorder()
+	h.HandleWebhook().ServeHTTP(w, req)
+
+	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(
+	t *testing.T, h *handlers.Handlers, username string,
+) {
+	t.Helper()
+
+	// 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
+	// test is here to drive.
+	require.Contains(
+		t,
+		[]int{http.StatusUnauthorized, http.StatusTooManyRequests},
+		postLogin(t, h, username),
+	)
+}
+
+// assertFloodBounded holds every captured line to the stated ceiling
+// and proves nothing carried a whole client value.
+func assertFloodBounded(t *testing.T, label, out string) {
+	t.Helper()
+
+	assert.NotContains(
+		t, out, gormBoundTailMarker,
+		"%s: the far end of a client-chosen value reached the "+
+			"log, so nothing truncated it", label,
+	)
+
+	for line := range strings.SplitSeq(
+		strings.TrimRight(out, "\n"), "\n",
+	) {
+		if line == "" {
+			continue
+		}
+
+		assert.LessOrEqual(
+			t, len(line), middleware.MaxAccessLogLineBytes,
+			"%s: log line exceeded its bound: %s",
+			label, line[:min(len(line), 300)],
+		)
+	}
+}
+
+// TestFlood_NoWriterGrowsWithTheInput is the definition of done for
+// the GORM logger defect, stated over every writer at once, for two of
+// this service's three gorm.Open sites: the main database behind the
+// two unauthenticated lookups, and the per-webhook database the
+// WebhookDBManager opens. The third, the archive writer, is pinned in
+// internal/delivery, where its type lives.
+//
+// What each assertion is worth, since two of the three would pass
+// against a service that had never been fixed if the capture were set
+// up differently:
+//
+//   - The gormDefault check is the sharp one. It fires the moment any
+//     gorm.Open in this service goes back to a bare &gorm.Config{}.
+//   - The volume and per-line checks bite only because the replaced
+//     default logger tees into os.Stdout, so a reverted call site
+//     shows up in the same capture as everything internal/logger
+//     writes — the way it would in production. Without that tee both
+//     were vacuous: at INFO the two handler misses log at DEBUG and
+//     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.
+//
+// It is deliberately not parallel: it redirects os.Stdout and replaces
+// gormlogger.Default, both of which are process-global. Go runs every
+// non-parallel top-level test to completion before it resumes the
+// parallel ones, so nothing else in this package is running while the
+// capture is installed.
+//
+//nolint:paralleltest // Deliberately sequential; see above.
+func TestFlood_NoWriterGrowsWithTheInput(t *testing.T) {
+	const (
+		smallBytes = 128
+		bigBytes   = 8 << 10
+		reps       = 5
+	)
+
+	gormDefault := captureGORMDefault(t)
+	capture := captureStdout(t)
+
+	var (
+		h   *handlers.Handlers
+		mgr *database.WebhookDBManager
+	)
+
+	app := newTestApp(t, &h, &mgr)
+	app.RequireStart()
+
+	t.Cleanup(app.RequireStop)
+
+	// Startup chatter is not what this test measures.
+	capture.drain(t)
+
+	floodUnauthenticated(t, h, smallBytes, reps)
+	floodPerWebhook(t, mgr, smallBytes, reps)
+
+	small := capture.drain(t)
+
+	requests := floodUnauthenticated(t, h, bigBytes, reps)
+	requests += floodPerWebhook(t, mgr, bigBytes, reps)
+	big := capture.drain(t)
+
+	assertFloodBounded(t, "small flood", small)
+	assertFloodBounded(t, "big flood", big)
+
+	// GORM's default logger is what the defect was. Nothing in this
+	// service may reach it.
+	got := gormDefault.String()
+	assert.Empty(
+		t, got,
+		"GORM's default logger wrote %d bytes; the first of them: %s",
+		len(got), got[:min(len(got), 300)],
+	)
+
+	// The same flood, with 64 times the client-chosen input, must not
+	// buy 64 times the log. A few bytes of slack covers a latency
+	// field changing width; the input grew by roughly half a megabyte.
+	const slackPerRequest = 64
+
+	assert.LessOrEqual(
+		t, len(big), len(small)+slackPerRequest*requests,
+		"log volume tracked the size of the client's input: "+
+			"%d bytes at %d bytes of input per request, %d bytes "+
+			"at %d",
+		len(small), smallBytes, len(big), bigBytes,
+	)
+}

internal/handlers/logbound_test.go

@@ -0,0 +1,543 @@
+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,6 +9,7 @@ import (
 	"gorm.io/gorm"
 	"sneak.berlin/go/webhooker/internal/database"
 	"sneak.berlin/go/webhooker/internal/delivery"
+	"sneak.berlin/go/webhooker/internal/logfield"
 )
 
 const (
@@ -125,9 +126,16 @@ 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", entrypointUUID,
+			"path", logfield.Truncate(
+				entrypointUUID, logfield.MaxBytes,
+			),
 		)
 		http.NotFound(w, r)
 

internal/logfield/logfield.go

@@ -0,0 +1,143 @@
+// Package logfield bounds the client-supplied values this service
+// writes into its logs.
+//
+// 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.
+package logfield
+
+import (
+	"strings"
+	"unicode"
+	"unicode/utf8"
+)
+
+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 = 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]"
+)
+
+// EncodedBytes is what r costs on the line once the log handler has
+// escaped it, taking the worse of the two handlers internal/logger
+// configures.
+//
+// slog's JSON handler escapes quote, backslash, newline, carriage
+// return and tab to two bytes each, and every other C0 control plus
+// LINE SEPARATOR and PARAGRAPH SEPARATOR to a six-byte \u escape; it
+// passes every other rune through as its own UTF-8. Its text handler
+// quotes with strconv.Quote, which spells a non-printable rune below
+// U+10000 as \uXXXX but one at or above U+10000 as \UXXXXXXXX — ten
+// bytes, not six. The text handler is therefore the worse of the two
+// for every non-printable rune, and by four bytes apiece for the
+// 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
+// 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
+// unicode.IsPrint separates the escaped cases from the plain ones for
+// either handler.
+func EncodedBytes(r rune) int {
+	const (
+		// A backslash and the character itself.
+		shortEscapeBytes = 2
+		// \uXXXX, which is also the width of \u00XX.
+		escapedRuneBytes = 6
+		// \UXXXXXXXX, strconv.Quote's spelling of a non-printable
+		// rune outside the basic multilingual plane.
+		escapedAstralRuneBytes = 10
+		// The first code point strconv.Quote spells with \U.
+		firstAstralRune = 0x10000
+	)
+
+	switch {
+	case r == '"' || r == '\\' || r == '\n' || r == '\r' || r == '\t':
+		return shortEscapeBytes
+	case !unicode.IsPrint(r) && r >= firstAstralRune:
+		return escapedAstralRuneBytes
+	case !unicode.IsPrint(r):
+		return escapedRuneBytes
+	default:
+		return utf8.RuneLen(r)
+	}
+}
+
+// Truncate caps s at maxBytes of ENCODED output, marking the value
+// when it cuts.
+//
+// Budgeting raw bytes would not bound the line. Escaping only ever
+// 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.
+//
+// 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.
+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
+	// client sent.
+	window, cut := s, false
+	if len(window) > maxBytes {
+		window, cut = window[:maxBytes], true
+	}
+
+	var (
+		kept  strings.Builder
+		spent int
+	)
+
+	for i := 0; i < len(window); {
+		r, size := utf8.DecodeRuneInString(window[i:])
+		if r == utf8.RuneError && size == 1 {
+			i += size
+
+			continue
+		}
+
+		cost := EncodedBytes(r)
+		if spent+cost > maxBytes {
+			cut = true
+
+			break
+		}
+
+		spent += cost
+
+		kept.WriteString(window[i : i+size])
+
+		i += size
+	}
+
+	if !cut {
+		return kept.String()
+	}
+
+	return kept.String() + TruncationMarker
+}

internal/logfield/logfield_test.go

@@ -0,0 +1,321 @@
+package logfield_test
+
+import (
+	"bytes"
+	"io"
+	"log/slog"
+	"strings"
+	"testing"
+	"unicode/utf8"
+
+	"github.com/stretchr/testify/assert"
+	"github.com/stretchr/testify/require"
+	"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 {
+	total := 0
+	for _, r := range s {
+		total += logfield.EncodedBytes(r)
+	}
+
+	return total
+}
+
+// TestTruncate_SpendsEncodedBytesNotRawBytes is the zero-headroom
+// version of TestTruncate_SpendsNoMoreThanTheBudget above, and 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.
+func TestTruncate_SpendsEncodedBytesNotRawBytes(t *testing.T) {
+	t.Parallel()
+
+	for name, r := range map[string]rune{
+		"plain":           'x',
+		"quote":           '"',
+		"backslash":       '\\',
+		"tab":             '\t',
+		"newline":         '\n',
+		"carriage_return": '\r',
+		"c0_control":      '\x01',
+		"del":             '\x7f',
+		// U+2028 LINE SEPARATOR, which only the JSON handler
+		// escapes.
+		"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',
+	} {
+		t.Run(name, func(t *testing.T) {
+			t.Parallel()
+
+			cost := logfield.EncodedBytes(r)
+			want := logfield.MaxBytes / cost
+
+			// Far past the budget under either accounting.
+			in := strings.Repeat(string(r), logfield.MaxBytes*2)
+
+			got := logfield.Truncate(in, logfield.MaxBytes)
+
+			require.True(
+				t, strings.HasSuffix(
+					got, logfield.TruncationMarker,
+				),
+				"a value past the budget must be marked",
+			)
+
+			kept := strings.TrimSuffix(
+				got, logfield.TruncationMarker,
+			)
+
+			assert.Equal(
+				t, want, utf8.RuneCountInString(kept),
+				"budget bought the wrong number of runes at "+
+					"%d encoded bytes each", cost,
+			)
+			assert.LessOrEqual(
+				t, encodedCost(kept), logfield.MaxBytes,
+			)
+		})
+	}
+}
+
+// TestTruncate_NeverSplitsARune covers a cut landing inside a
+// multi-byte encoding rather than between two of them.
+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.
+	in := strings.Repeat("€", logfield.MaxBytes)
+
+	for b := 1; b <= 16; b++ {
+		got := strings.TrimSuffix(
+			logfield.Truncate(in, b), logfield.TruncationMarker,
+		)
+
+		assert.True(
+			t, utf8.ValidString(got),
+			"budget %d produced invalid UTF-8", b,
+		)
+		assert.LessOrEqual(t, encodedCost(got), b)
+	}
+}

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 line the service can be made to write.
+	// the widest access log line the service can be made to write.
 	longPath := "/boom/" + strings.Repeat("x", oversizedSegmentBytes)
 	wantLongURL := longPath[:maxFieldBytes] + truncationSuffix
 

internal/middleware/csrf.go

@@ -4,6 +4,7 @@ import (
 	"net/http"
 
 	"github.com/gorilla/csrf"
+	"sneak.berlin/go/webhooker/internal/logfield"
 )
 
 // CSRFToken retrieves the CSRF token from the request context.
@@ -42,9 +43,22 @@ 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", r.Method,
-			"path", r.URL.Path,
+			"method", logfield.Truncate(
+				r.Method, maxLogMethodBytes,
+			),
+			"path", logfield.Truncate(
+				r.URL.Path, logfield.MaxBytes,
+			),
 			"remote_addr", r.RemoteAddr,
 			"reason", csrf.FailureReason(r),
 		)

internal/middleware/logbound_test.go

@@ -0,0 +1,544 @@
+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,6 +7,8 @@ import (
 	"net/http"
 	"sync"
 	"time"
+
+	"sneak.berlin/go/webhooker/internal/logfield"
 )
 
 const (
@@ -173,10 +175,38 @@ 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 first; the caller must then answer 503
-// without verifying anything. The returned function releases the
+// request was cancelled while waiting; 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.
@@ -344,8 +374,17 @@ 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", r.URL.Path,
+			"login failure limit exceeded",
+			"path", logfield.Truncate(
+				r.URL.Path, logfield.MaxBytes,
+			),
 		)
 	}
 

internal/middleware/loginguard_test.go

@@ -29,6 +29,15 @@ 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
@@ -224,6 +233,13 @@ 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)
@@ -233,12 +249,55 @@ 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
 			}
 
@@ -253,9 +312,12 @@ func TestLoginGuard_SemaphoreBoundsConcurrentVerifications(
 
 			mu.Unlock()
 
-			// Hold the slot long enough that the other workers are
-			// certainly contending for it.
-			time.Sleep(10 * time.Millisecond)
+			// Counted before signalling, so the barrier can never open
+			// while an admitted worker is still on its way to being
+			// counted.
+			recorded.Done()
+
+			<-overlapped
 
 			mu.Lock()
 			inside--
@@ -278,6 +340,14 @@ 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,
 ) {
@@ -305,13 +375,58 @@ func TestLoginGuard_SaturatedSemaphoreRefusesRatherThanQueueing(
 	release()
 
 	release, ok = g.AcquireForTest(context.Background())
-	assert.True(
+
+	// 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(
 		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.
@@ -388,13 +503,20 @@ 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 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
+		// 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
 	)
 
 	g := middleware.NewLoginGuardForTest(
@@ -413,22 +535,17 @@ func TestLoginGuard_ShedsPastTheQueueCap(t *testing.T) {
 	defer release()
 	defer fillQueue(t, g, maxWaiters)()
 
-	got := probeQueueCap(g, probeWait)
+	granted, answered := probeQueueCap(g, probePatience)
 
-	require.NotNil(
-		t, got,
+	require.True(
+		t, answered,
 		"a request arriving past the queue cap is still waiting to "+
 			"be queued; it must have been shed",
 	)
 	assert.False(
-		t, got.ok,
+		t, granted,
 		"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",
@@ -458,10 +575,14 @@ 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 },
-		time.Second, time.Millisecond,
+		5*time.Second, time.Millisecond,
 		"the waiters must reach the queue before the cap is tested",
 	)
 
@@ -471,41 +592,38 @@ func fillQueue(
 	}
 }
 
-// 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.
+// 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.
 //
 // 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,
-) *probeResult {
-	probed := make(chan probeResult, 1)
+) (bool, bool) {
+	probed := make(chan bool, 1)
 
 	go func() {
-		start := time.Now()
-
 		release, ok := g.AcquireForTest(context.Background())
 		if ok {
 			release()
 		}
 
-		probed <- probeResult{ok: ok, elapsed: time.Since(start)}
+		probed <- ok
 	}()
 
 	select {
 	case result := <-probed:
-		return &result
+		return result, true
 	case <-time.After(wait):
-		return nil
+		return false, false
 	}
 }

internal/middleware/middleware.go

@@ -6,11 +6,8 @@ import (
 	"log/slog"
 	"net"
 	"net/http"
-	"strings"
 	"sync"
 	"time"
-	"unicode"
-	"unicode/utf8"
 
 	basicauth "github.com/99designs/basicauth-go"
 	"github.com/go-chi/chi"
@@ -22,6 +19,7 @@ import (
 	"go.uber.org/fx"
 	"sneak.berlin/go/webhooker/internal/config"
 	"sneak.berlin/go/webhooker/internal/globals"
+	"sneak.berlin/go/webhooker/internal/logfield"
 	"sneak.berlin/go/webhooker/internal/logger"
 	"sneak.berlin/go/webhooker/internal/session"
 )
@@ -44,16 +42,6 @@ const (
 	// pick the size of the line it writes.
 	redactedQuery = "?(redacted)"
 
-	// maxLogFieldBytes bounds each access log field whose value the
-	// client supplies outright: the URL, the User-Agent and the
-	// Referer. The budget is spent in ENCODED bytes (see
-	// truncateLogField), 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.
-	maxLogFieldBytes = 512
-
 	// maxLogRequestIDBytes bounds the request id, which is also
 	// client-supplied: chi's RequestID middleware passes an inbound
 	// X-Request-Id header through verbatim. Its generated form is an
@@ -66,15 +54,10 @@ const (
 	// is half this.
 	maxLogMethodBytes = 32
 
-	// truncationMarker is appended to any field the access log 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]"
-
 	// 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 truncateLogField enforces in
+	// of the budgets above, 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
@@ -84,6 +67,9 @@ const (
 	//	                                        ----
 	//	                                        2087
 	//
+	// The 512 is logfield.MaxBytes; the 11 is the truncation marker,
+	// charged on top of each budget rather than inside it.
+	//
 	// The fixed portion is the JSON punctuation, the field names, the
 	// level and the message, both timestamps at their longest, an IPv6
 	// remoteIP with a zone, a three-digit status and a full-width int64
@@ -91,13 +77,68 @@ const (
 	// than sitting on the arithmetic.
 	//
 	// The tty text handler in internal/logger is covered by the same
-	// figure. encodedLogFieldBytes charges every rune at least what
+	// figure. logfield.EncodedBytes charges every rune at least what
 	// the wider of the two handlers emits for it — including the ten
 	// bytes strconv.Quote spends on a non-printable rune at or above
 	// U+10000, which is four more than the JSON handler ever spends —
 	// so each budget bounds the encoded field under either handler.
 	// 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 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.
 	MaxAccessLogLineBytes = 2560
 )
 
@@ -174,114 +215,6 @@ func (lrw *loggingResponseWriter) WriteHeader(code int) {
 	lrw.ResponseWriter.WriteHeader(code)
 }
 
-// encodedLogFieldBytes is what r costs on the line once the log
-// handler has escaped it, taking the worse of the two handlers
-// internal/logger configures.
-//
-// slog's JSON handler escapes quote, backslash, newline, carriage
-// return and tab to two bytes each, and every other C0 control plus
-// LINE SEPARATOR and PARAGRAPH SEPARATOR to a six-byte \u escape; it
-// passes every other rune through as its own UTF-8. Its text handler
-// quotes with strconv.Quote, which spells a non-printable rune below
-// U+10000 as \uXXXX but one at or above U+10000 as \UXXXXXXXX — ten
-// bytes, not six. The text handler is therefore the worse of the two
-// for every non-printable rune, and by four bytes apiece for the
-// 955,086 unassigned, private-use and format code points on planes 1
-// to 16.
-//
-// Charging ten there is what makes MaxAccessLogLineBytes 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
-// unicode.IsPrint separates the escaped cases from the plain ones for
-// either handler.
-func encodedLogFieldBytes(r rune) int {
-	const (
-		// A backslash and the character itself.
-		shortEscapeBytes = 2
-		// \uXXXX, which is also the width of \u00XX.
-		escapedRuneBytes = 6
-		// \UXXXXXXXX, strconv.Quote's spelling of a non-printable
-		// rune outside the basic multilingual plane.
-		escapedAstralRuneBytes = 10
-		// The first code point strconv.Quote spells with \U.
-		firstAstralRune = 0x10000
-	)
-
-	switch {
-	case r == '"' || r == '\\' || r == '\n' || r == '\r' || r == '\t':
-		return shortEscapeBytes
-	case !unicode.IsPrint(r) && r >= firstAstralRune:
-		return escapedAstralRuneBytes
-	case !unicode.IsPrint(r):
-		return escapedRuneBytes
-	default:
-		return utf8.RuneLen(r)
-	}
-}
-
-// truncateLogField caps s at maxBytes of ENCODED output, marking the
-// value when it cuts.
-//
-// Budgeting raw bytes would not bound the line. Escaping only ever
-// 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
-// MaxAccessLogLineBytes 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.
-func truncateLogField(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
-	// client sent.
-	window, cut := s, false
-	if len(window) > maxBytes {
-		window, cut = window[:maxBytes], true
-	}
-
-	var (
-		kept  strings.Builder
-		spent int
-	)
-
-	for i := 0; i < len(window); {
-		r, size := utf8.DecodeRuneInString(window[i:])
-		if r == utf8.RuneError && size == 1 {
-			i += size
-
-			continue
-		}
-
-		cost := encodedLogFieldBytes(r)
-		if spent+cost > maxBytes {
-			cut = true
-
-			break
-		}
-
-		spent += cost
-
-		kept.WriteString(window[i : i+size])
-
-		i += size
-	}
-
-	if !cut {
-		return kept.String()
-	}
-
-	return kept.String() + truncationMarker
-}
-
 // concreteLogURL renders the request's own URL for the access log
 // branches that keep it, with the query string replaced by a fixed
 // marker.
@@ -375,21 +308,21 @@ func (s *Middleware) Logging() func(http.Handler) http.Handler {
 				// line does not track the size of the request.
 				s.log.Info("http request",
 					"request_start", start,
-					"method", truncateLogField(
+					"method", logfield.Truncate(
 						r.Method, maxLogMethodBytes,
 					),
-					"url", truncateLogField(
+					"url", logfield.Truncate(
 						accessLogURL(r, lrw.statusCode),
-						maxLogFieldBytes,
+						logfield.MaxBytes,
 					),
-					"useragent", truncateLogField(
-						r.UserAgent(), maxLogFieldBytes,
+					"useragent", logfield.Truncate(
+						r.UserAgent(), logfield.MaxBytes,
 					),
-					"request_id", truncateLogField(
+					"request_id", logfield.Truncate(
 						requestID, maxLogRequestIDBytes,
 					),
-					"referer", truncateLogField(
-						r.Referer(), maxLogFieldBytes,
+					"referer", logfield.Truncate(
+						r.Referer(), logfield.MaxBytes,
 					),
 					"proto", r.Proto,
 					"remoteIP", ipFromHostPort(r.RemoteAddr),
@@ -457,10 +390,21 @@ 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", r.URL.Path,
-					"method", r.Method,
+					"path", logfield.Truncate(
+						r.URL.Path, logfield.MaxBytes,
+					),
+					"method", logfield.Truncate(
+						r.Method, maxLogMethodBytes,
+					),
 				)
 				http.Redirect(
 					w, r, "/pages/login", http.StatusSeeOther,
@@ -620,10 +564,26 @@ 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", r.Method,
-					"path", r.URL.Path,
+					"method", logfield.Truncate(
+						r.Method, maxLogMethodBytes,
+					),
+					"path", logfield.Truncate(
+						r.URL.Path, logfield.MaxBytes,
+					),
 					"content_length", r.ContentLength,
 					"limit", maxBytes,
 				)

internal/middleware/middleware_test.go

@@ -57,7 +57,21 @@ func testMiddlewareWithSessionClock(
 		SessionIdleTimeout: idleTimeout,
 	}
 
-	// Create a real session manager with a known key
+	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 {
 	key := make([]byte, testKeySize)
 
 	for i := range key {
@@ -79,11 +93,7 @@ func testMiddlewareWithSessionClock(
 		now = clock.Now
 	}
 
-	sessManager := session.NewForTest(store, cfg, log, key, now)
-
-	m := middleware.NewForTest(log, cfg, sessManager)
-
-	return m, sessManager, clock
+	return session.NewForTest(store, cfg, log, key, now)
 }
 
 // fakeClock is a manually advanced clock, so session expiry can be

internal/middleware/ratelimit.go

@@ -9,6 +9,7 @@ import (
 	"time"
 
 	"github.com/go-chi/httprate"
+	"sneak.berlin/go/webhooker/internal/logfield"
 )
 
 const (
@@ -225,11 +226,22 @@ 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", r.URL.Path)
+		m.log.Warn(
+			logMessage,
+			"path", logfield.Truncate(
+				r.URL.Path, logfield.MaxBytes,
+			),
+		)
 		http.Error(w, responseMessage, http.StatusTooManyRequests)
 	}
 }

internal/middleware/recoverer.go

@@ -7,6 +7,7 @@ import (
 	"runtime/debug"
 
 	"github.com/go-chi/chi/middleware"
+	"sneak.berlin/go/webhooker/internal/logfield"
 )
 
 const (
@@ -15,10 +16,10 @@ const (
 	// 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 = maxLogFieldBytes
+	maxPanicValueBytes = logfield.MaxBytes
 
 	// maxPanicStackBytes bounds the stack, in the same ENCODED bytes
-	// truncateLogField charges everywhere else. Nothing a client
+	// 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
@@ -26,19 +27,21 @@ const (
 	// site and the handler that reached it are at the near end and
 	// are always kept.
 	//
-	// Measured, a handler panicking under the full shipped
-	// middleware chain produces a 3,691-byte stack in a 3,959-byte
-	// record, so this budget holds better than twice the depth that
-	// case reaches. internal/server's
-	// TestPanicThroughProductionRouter pins it: that stack must
-	// arrive uncut.
+	// 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 the widest line this service can
-	// be made to write — wider than MaxAccessLogLineBytes, which
-	// bounds a line written once per request, where this one is
-	// written once per panic.
+	// 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
@@ -54,12 +57,19 @@ const (
 	// 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: encodedLogFieldBytes charges every
+	// the reason given there: logfield.EncodedBytes charges every
 	// rune the wider of the two.
 	//
-	// Measured, the widest line either handler produces with both
-	// the stack and the panic value driven past their budgets is
-	// 8,898 bytes (TestRecovererBoundsTheStack).
+	// 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
 )
 
@@ -176,21 +186,21 @@ func (s *Middleware) Recoverer() func(http.Handler) http.Handler {
 // 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 the widest line the service writes, to say a second
-// time what one join already says.
+// 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", truncateLogField(
+		"panic", logfield.Truncate(
 			fmt.Sprint(rvr), maxPanicValueBytes,
 		),
-		"stack", truncateLogField(
+		"stack", logfield.Truncate(
 			string(debug.Stack()), maxPanicStackBytes,
 		),
-		"request_id", truncateLogField(
+		"request_id", logfield.Truncate(
 			middleware.GetReqID(r.Context()),
 			maxLogRequestIDBytes,
 		),

internal/middleware/recoverer_test.go

@@ -98,11 +98,29 @@ func newRecovererProbe(
 func (p *recovererProbe) get(t *testing.T) (*http.Response, error) {
 	t.Helper()
 
+	return p.getWithRequestID(t, "")
+}
+
+// getWithRequestID drives the same request carrying a client-supplied
+// X-Request-Id. chi's RequestID middleware adopts that header verbatim
+// when it is present and only generates a value when it is absent, so
+// this is the third growable field on the panic record and the only
+// one a client fills outright.
+func (p *recovererProbe) getWithRequestID(
+	t *testing.T,
+	requestID string,
+) (*http.Response, error) {
+	t.Helper()
+
 	req, err := http.NewRequestWithContext(
 		t.Context(), http.MethodGet, p.server.URL+"/probe", nil,
 	)
 	require.NoError(t, err)
 
+	if requestID != "" {
+		req.Header.Set(chimw.RequestIDHeader, requestID)
+	}
+
 	return p.server.Client().Do(req)
 }
 
@@ -356,26 +374,17 @@ func TestRecovererKeepsAnImplicitlyCommittedResponse(t *testing.T) {
 	)
 }
 
-// panicFill is one construction for the oversized panic value the
-// bound tests raise, mirroring internal/middleware's access log fills:
-// 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.
-type panicFill struct {
+// 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
-	rune string
+	text bool
 }
 
-func panicFills() []panicFill {
-	return []panicFill{
-		{"plain", "x"},
-		{"quote", `"`},
-		{"backslash", `\`},
-		{"tab", "\t"},
-		{"newline", "\n"},
-		{"control", "\x01"},
-		{"astral", "\U0001000C"},
-	}
+func panicLogHandlers() []panicLogHandler {
+	return []panicLogHandler{{"json", false}, {"text", true}}
 }
 
 // TestRecovererBoundsThePanicRecord holds the record to its stated
@@ -385,16 +394,18 @@ func panicFills() []panicFill {
 func TestRecovererBoundsThePanicRecord(t *testing.T) {
 	t.Parallel()
 
-	for _, handler := range []struct {
-		name string
-		text bool
-	}{{"json", false}, {"text", true}} {
-		for _, fill := range panicFills() {
-			t.Run(handler.name+"/"+fill.name, func(t *testing.T) {
+	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(
-					fill.rune, oversizedSegmentBytes,
+					fillRune, oversizedSegmentBytes,
 				) + tailMarker
 
 				probe := newRecovererProbe(
@@ -444,47 +455,16 @@ func deepPanic(depth int, value string) int {
 	return deepPanic(depth-1, value) + 1
 }
 
-// TestRecovererBoundsTheStack is the widest line the service can be
-// made to write: an oversized stack and an oversized panic value on
-// the same record, 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.
-func TestRecovererBoundsTheStack(t *testing.T) {
-	t.Parallel()
+// 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()
 
-	for _, handler := range []struct {
-		name string
-		text bool
-	}{{"json", false}, {"text", true}} {
-		t.Run(handler.name, func(t *testing.T) {
-			t.Parallel()
-
-			// The escape-heavy fill is the expensive one: every rune
-			// costs two encoded bytes, so a budget counted raw would
-			// buy twice the field.
-			value := strings.Repeat(`"`, oversizedSegmentBytes) +
-				tailMarker
-
-			probe := newRecovererProbe(
-				t, handler.text,
-				func(http.ResponseWriter, *http.Request) {
-					_ = deepPanic(512, value)
-				},
-			)
-
-			resp, err := probe.get(t)
-			require.NoError(t, err)
-			require.NoError(t, resp.Body.Close())
-			require.Equal(
-				t, http.StatusInternalServerError, resp.StatusCode,
-			)
-			probe.wait()
-
-			// The text handler does not emit JSON, so the field-level
-			// assertions run on the JSON one; the line bound below
-			// is asserted on both, which is the point of the sweep.
-			if !handler.text {
-				stack, ok := probe.panicRecord(t)["stack"].(string)
+	stack, ok := record["stack"].(string)
 	require.True(t, ok)
 	assert.True(
 		t, strings.HasSuffix(stack, truncationSuffix),
@@ -498,6 +478,74 @@ func TestRecovererBoundsTheStack(t *testing.T) {
 		t, stack, "net/http.(*conn).serve",
 		"the far end is what a cut discards",
 	)
+
+	id, ok := record["request_id"].(string)
+	require.True(t, ok)
+	assert.True(
+		t, strings.HasSuffix(id, truncationSuffix),
+		"an oversized request id must be marked as cut",
+	)
+	assert.LessOrEqual(
+		t, len(id), maxRequestIDBytes+len(truncationSuffix),
+		"the request id must be held to its own budget",
+	)
+
+	value, ok := record["panic"].(string)
+	require.True(t, ok)
+	assert.True(
+		t, strings.HasSuffix(value, truncationSuffix),
+		"an oversized panic value must be marked as cut",
+	)
+}
+
+// TestRecovererBoundsTheStack drives every growable field on the
+// record past its budget at once — an oversized stack, an oversized
+// panic value and an oversized client-supplied X-Request-Id — over
+// both log handlers. It holds that line to the stated ceiling and
+// reports what it measured, and it pins that a cut stack keeps its
+// near end — the panic site — rather than its far one.
+//
+// The two fields the test picks the content of — the panic value and
+// the request id — are filled with the quotation mark. Both handlers
+// escape it to two bytes, which is exactly what logfield charges for
+// it, so each of those fields emits every byte of its budget; no fill
+// emits more, since logfield charges each rune the wider of the two
+// handlers and a field can therefore never emit more than it spent.
+// The stack is not a fill: recursion drives it past its budget and
+// the cut lands wherever its own content puts it, which is why the
+// measured widths move by a byte between runs.
+func TestRecovererBoundsTheStack(t *testing.T) {
+	t.Parallel()
+
+	for _, handler := range panicLogHandlers() {
+		t.Run(handler.name, func(t *testing.T) {
+			t.Parallel()
+
+			value := strings.Repeat(`"`, oversizedSegmentBytes) +
+				tailMarker
+			requestID := strings.Repeat(`"`, oversizedSegmentBytes) +
+				tailMarker
+
+			probe := newRecovererProbe(
+				t, handler.text,
+				func(http.ResponseWriter, *http.Request) {
+					_ = deepPanic(512, value)
+				},
+			)
+
+			resp, err := probe.getWithRequestID(t, requestID)
+			require.NoError(t, err)
+			require.NoError(t, resp.Body.Close())
+			require.Equal(
+				t, http.StatusInternalServerError, resp.StatusCode,
+			)
+			probe.wait()
+
+			// The text handler does not emit JSON, so the field-level
+			// assertions run on the JSON one; the line bound below
+			// is asserted on both, which is the point of the sweep.
+			if !handler.text {
+				assertEveryFieldWasCut(t, probe.panicRecord(t))
 			}
 
 			widest := 0

internal/server/routes.go

@@ -14,6 +14,28 @@ 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
@@ -102,8 +124,8 @@ func (s *Server) setupRoutes() {
 
 func (s *Server) setupPageRoutes() {
 	s.router.Route("/pages", func(r chi.Router) {
-		// MaxBodySize must precede CSRF: gorilla/csrf parses the
-		// form, so the cap has to be installed before it runs.
+		// MaxBodySize precedes CSRF and RequireAuth deliberately;
+		// see maxFormBodySize for why, and for what it costs.
 		r.Use(s.mw.MaxBodySize(maxFormBodySize))
 		r.Use(s.mw.CSRF())
 		r.Use(s.mw.NoCache())
@@ -123,8 +145,8 @@ func (s *Server) setupPageRoutes() {
 
 func (s *Server) setupUserRoutes() {
 	s.router.Route("/user/{username}", func(r chi.Router) {
-		// MaxBodySize must precede CSRF: gorilla/csrf parses the
-		// form, so the cap has to be installed before it runs.
+		// MaxBodySize precedes CSRF and RequireAuth deliberately;
+		// see maxFormBodySize for why, and for what it costs.
 		r.Use(s.mw.MaxBodySize(maxFormBodySize))
 		r.Use(s.mw.CSRF())
 		r.Use(s.mw.NoCache())
@@ -138,8 +160,8 @@ func (s *Server) setupUserRoutes() {
 
 func (s *Server) setupSourceRoutes() {
 	s.router.Route("/sources", func(r chi.Router) {
-		// MaxBodySize must precede CSRF: gorilla/csrf parses the
-		// form, so the cap has to be installed before it runs.
+		// MaxBodySize precedes CSRF and RequireAuth deliberately;
+		// see maxFormBodySize for why, and for what it costs.
 		r.Use(s.mw.MaxBodySize(maxFormBodySize))
 		r.Use(s.mw.CSRF())
 		r.Use(s.mw.NoCache())
@@ -150,8 +172,8 @@ func (s *Server) setupSourceRoutes() {
 	})
 
 	s.router.Route("/source/{sourceID}", func(r chi.Router) {
-		// MaxBodySize must precede CSRF: gorilla/csrf parses the
-		// form, so the cap has to be installed before it runs.
+		// MaxBodySize precedes CSRF and RequireAuth deliberately;
+		// see maxFormBodySize for why, and for what it costs.
 		r.Use(s.mw.MaxBodySize(maxFormBodySize))
 		r.Use(s.mw.CSRF())
 		r.Use(s.mw.NoCache())

script/test

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