1 Commits

Author SHA1 Message Date
4884581fc5 Bound every slog line against client-chosen text (closes #176)
All checks were successful
check / check (push) Successful in 2m53s
MaxBodySize logged r.URL.Path untruncated at WARN, and routes.go
registers it ahead of RequireAuth, so an unauthenticated
POST /source/<8 KB>/edit with an oversize declared Content-Length wrote
attacker-chosen text of attacker-chosen length into the operator's log,
for the cost of a request with no body. The 2,560-byte per-line budget
from #146 did not reach it: that budget lives in the access log's field
capping and this is a separate slog call.

The capping mechanism moves out of internal/middleware into
internal/logfield so there is one budget and one implementation rather
than a second ad-hoc truncation. Truncate and EncodedBytes are
unchanged; the access log now spends logfield.MaxBytes where it spent
maxLogFieldBytes.

The sweep the issue asked for found five more call sites of the same
shape, all reachable unauthenticated, all now capped: the CSRF 403
(also registered ahead of RequireAuth), the rate limiters' 429 (the
per-entrypoint receiver limiter is unauthenticated), RequireAuth's own
DEBUG line, the unknown-entrypoint DEBUG line on the receiver, and the
failed-login DEBUG lines. 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. Every other slog call in the tree was read
and judged; the PR body lists all of them, including the ones left
alone and why.

MaxBodySize stays ahead of RequireAuth. An oversize body should be
refused before the request buys a cookie decrypt and a session load,
and rejecting first is what keeps an unauthenticated flood from
choosing how much session work the process does. The ordering and what
it costs are now written at the registration, on maxFormBodySize.

MaxAccessLogLineBytes is restated as the ceiling on every slog line
carrying text an UNAUTHENTICATED client supplies, not just the access
log's: each of these lines carries strictly fewer client-supplied
fields than the access log does, so none can be wider. That is asserted
per line under both handlers rather than argued. The claim is qualified
rather than universal because three kinds of writer are outside it, and
the README and the constant now name all three: lines carrying an
authenticated operator's own input, which are not truncated at all (the
webhook name on "webhook created" reaches 600 KB on one line from a
100 KB form field, measured; the SSRF-rejection url and the target_name
lines are the same shape) and are left uncapped deliberately, since
truncating the operator's own configuration echoed back costs
debuggability against no adversary; the log delivery target, which
exists to emit the whole event; and GORM's default logger, which prints
the interpolated SQL to stdout on a record-not-found and is unbounded
on the receiver and login lookups. That last one is a real defect this
audit turned up and is filed separately as #178, not fixed here.

Tests drive 8 KB of client-chosen text at all six sites, through both
handlers internal/logger can install and through each character they
escape — including a bare C0 control, which costs six bytes on the line
against the one it cost to send and is the case a raw-byte budget
breaks on first. Each holds the encoded line to the ceiling, holds the
whole flood's output to what that ceiling allows, and asserts the
markers at the far end of the input are absent, so a value that merely
happened to be short cannot pass. The two login lines past the username
lookup, capped for uniformity rather than need, are pinned too.
internal/logfield gains a test that 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 instead of quietly
falsifying the ceiling.

Verified by mutation: reverting the MaxBodySize cap alone fails 28
subtests with a 16,583-byte line against the 2,560 ceiling; reverting
the other five fails 70; uncapping the two login lines past the lookup
fails 2; budgeting raw bytes instead of encoded ones fails 23 across
three packages.
2026-08-18 00:24:08 +00:00
29 changed files with 233 additions and 3819 deletions

298
README.md
View File

@@ -1038,77 +1038,38 @@ reduces the headers to a fixed allowlist — `Accept`, `Content-Length`,
`Content-Type`, `Host`, `Origin`, `Referer`, `User-Agent` and
`X-Request-Id`.
The same hook rewrites the request URL. The SDK builds it as
`scheme://host/path` from the concrete path, which on the receiver
route is `/webhook/<uuid>` in full — and that UUID is a write
capability, not an identifier: anyone holding it can post events this
service accepts and its targets then deliver. A tracker has its own
retention, access control and deletion policy, so the rule the access
log follows above does not carry across that boundary. What is sent is
the chi route pattern instead: `http://host/webhook/{uuid}`.
The scheme and the host are kept, and everything else in the URL is
discarded rather than edited, so a future SDK version that starts
appending a query string cannot widen this. The scheme has to survive
for the reason given below. The host is whatever the request's `Host`
header carried — this service validates no hostname, so on a directly
exposed deployment a client sets it — and that same header is on the
allowlist above, so scrubbing the host out of the URL would withhold
nothing that is not sent anyway.
The body, the query string and the URL are all handled on every route
rather than filtered by route. For the URL that is also what keeps the
event locatable: an error event is grouped by its exception and stack
trace, not by its URL, so replacing the path with the pattern costs no
grouping and the pattern still names the route in the UI. And an
unconditional rule cannot leak on a route somebody forgets to add to
it, which a route-conditional one can. For the body there is a second
reason: nothing debuggable is lost, because every handler reads its
fields with `PostFormValue`, so the body is exactly where the
credentials are — the target destination URL, the login password, both
password-change fields — and the one route whose body is genuine
signal is the receiver, whose body is already stored on the event and
served from the UI, so a tracker is not where anyone reads it.
The route is reachable from the hook only on the error dispatch.
`sentryhttp`'s recover path puts the request on the context it hands
to `RecoverWithContext`, and the SDK carries that context through to
`BeforeSend` as `hint.Context`, so
The body is replaced on every route rather than filtered by route, and
that is a choice rather than a limitation: the route is reachable from
the hook. `sentryhttp`'s recover path puts the request on the context
it hands to `RecoverWithContext`, and the SDK carries that context
through to `BeforeSend` as `hint.Context`, so
`hint.Context.Value(sentry.RequestContextKey)` yields the live request
and chi's `RoutePattern()` yields the matched pattern off it. The
transaction dispatch has no such request: a finished span captures
with a nil hint, which the client replaces with an empty one, so
`BeforeSendTransaction` sees no context at all. Tracing is off in this
service, so no transaction event is produced today, but the hook is
installed on both dispatches as a floor.
and chi's `RoutePattern()` yields the matched pattern off it. There
are two reasons to redact unconditionally anyway. Nothing debuggable
is lost:
every handler reads its fields with `PostFormValue`, so the body is
exactly where the credentials are — the target destination URL, the
login password, both password-change fields — and the one route whose
body is genuine signal is the receiver, whose body is already stored
on the event and served from the UI, so a tracker is not where anyone
reads it. And an unconditional rule cannot leak on a route somebody
forgets to add to it, which a route-conditional one can.
Where the pattern is out of reach — the transaction dispatch, an event
captured outside the router, or a request that matched no route — the
fallback is never the concrete path. The path becomes the literal
`/(redacted)`, so the URL reads `http://host/(redacted)`; a URL the
rewrite cannot parse into a scheme is withheld whole. A transaction
event additionally carries the SDK's own `METHOD /path` name, built
from the concrete path as well; it is rewritten on the same terms, to
`POST /webhook/{uuid}` where the pattern is known and `POST
/(redacted)` where it is not.
The headers are an allowlist for the same reason the rules above are
unconditional: the SDK's own filter removes four names and passes
everything else, which would ship `X-CSRF-Token` and the shared
secrets senders put on the receiver route. What survives still names
the failing route — scheme, host, route pattern, method — and
`X-Request-Id` ties the event to the local access log line that holds
the rest. Nothing dropped is needed for the likeliest use, debugging a
CSRF rejection. Its three inputs are the TLS decision, `Origin` and
`Referer`; the latter two are kept, and the first is the scheme of the
retained URL, because the SDK derives that scheme from
`r.TLS != nil || r.Header.Get("X-Forwarded-Proto") == "https"` — byte
for byte the predicate `internal/middleware/csrf.go` uses to choose
between the `csrf.Secure(true)` and `csrf.Secure(false)` handlers.
That is what the rewrite above preserves it for, and it is why
dropping `X-Forwarded-Proto` costs nothing. The dropped provider
headers (`X-GitHub-Event`, `X-Gitlab-Event` and the like) are real
signal but are recorded locally on the event, and
The headers are an allowlist for that second reason: the SDK's own
filter removes four names and passes everything else, which would ship
`X-CSRF-Token` and the shared secrets senders put on the receiver
route. What survives still names the failing route — scheme, host,
path, method — and `X-Request-Id` ties the event to the local access
log line that holds the rest. Nothing dropped is needed for the
likeliest use, debugging a CSRF rejection. Its three inputs are the
TLS decision, `Origin` and `Referer`; the latter two are kept, and the
first is already in the retained URL, because the SDK derives that
URL's scheme from `r.TLS != nil || r.Header.Get("X-Forwarded-Proto") == "https"`
byte for byte the predicate `internal/middleware/csrf.go` uses to
choose between the `csrf.Secure(true)` and `csrf.Secure(false)`
handlers. So dropping `X-Forwarded-Proto` costs nothing. The dropped
provider headers (`X-GitHub-Event`, `X-Gitlab-Event` and the like) are
real signal but are recorded locally on the event, and
`Sentry-Trace`/`Baggage` are already reflected in the event's trace
context.
@@ -1141,13 +1102,12 @@ the figure has headroom. `internal/middleware/accesslog_test.go`
asserts it against 8 KB of client-chosen text in the path, in the
query, and in each of `User-Agent`, `Referer` and `X-Request-Id`,
including cases built from the characters the handlers escape, and
against the widest access log line the service can be made to write: a
5xx that keeps its concrete path while all three header fields are also
at their budget. Every case runs through both handlers
`internal/logger` can select — the JSON one and the text one it installs
on a tty — since the two do not escape alike and the ceiling is quoted
unqualified. Measured over a real connection, the widest access log line
is 1,972 bytes.
against the widest line the service can be made to write: a 5xx that
keeps its concrete path while all three header fields are also at their
budget. Every case runs through both handlers `internal/logger` can
select — the JSON one and the text one it installs on a tty — since the
two do not escape alike and the ceiling is quoted unqualified. Measured
over a real connection, the widest line is 1,972 bytes.
Multiply that ceiling by the request rate to size log storage. Note
that the rate is not bounded by the limits above on every route:
@@ -1155,16 +1115,13 @@ that the rate is not bounded by the limits above on every route:
the multiplier is whatever the deployment will serve.
**The same ceiling covers every other line the service writes through
`slog` that carries text an unauthenticated client supplies**, 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:
`slog` that carries text an unauthenticated client supplies.** The
access log is not the only line a client can put its own text into, and
a budget that held for one line and not the others would be worse than
no stated budget at all. Every `slog` call an unauthenticated request
can reach spends the same per-field budget through `internal/logfield`,
and each carries strictly fewer client-supplied fields than the access
log does, so none of them can be wider than it:
| Log line | Level | Client-chosen value | Reachable unauthenticated |
| ------------------------------------------ | ------- | ------------------- | ----------------------------------------- |
@@ -1174,76 +1131,22 @@ wider than it:
| `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/handlers/logbound_test.go` drive 8 KB of client-chosen text at
each of these, through both handlers and through every character the
handlers escape, and hold each line to the 2,560-byte ceiling — and the
whole flood's output to what that ceiling allows, which is the property
an operator actually cares about.
`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:
@@ -1267,70 +1170,16 @@ read as more than it is:
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.
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,9828,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.
- **GORM's default logger**, which prints the fully interpolated SQL to
stdout on every record-not-found — including the client-chosen path
on `/webhook/{uuid}` and the submitted username on the login form.
This one is not deliberate and not yet fixed; it does not go through
`internal/logger` at all, so no level the operator sets and no budget
above applies to it. Tracked at
<https://git.eeqj.de/sneak/webhooker/issues/178>. Until it is fixed,
an unauthenticated flood can still write text of its own choosing and
its own length to the operator's stdout, and the ceiling above
describes only the `slog` half of the picture.
Every limiter here — receiver, login, and password change — identifies
the client the same way, through one shared key function: the
@@ -1570,10 +1419,6 @@ 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
@@ -1669,32 +1514,19 @@ to record results.
Applied to all routes in this order:
1. **RequestID**Generate unique request IDs (chi built-in)
2. **SecurityHeaders** — Production security headers on every response
1. **Recoverer**Panic recovery (chi built-in)
2. **RequestID** — Generate unique request IDs (chi built-in)
3. **SecurityHeaders** — Production security headers on every response
(HSTS, X-Content-Type-Options, X-Frame-Options, CSP, Referrer-Policy,
Permissions-Policy)
3. **Logging** — Structured request logging (method, URL, status,
4. **Logging** — Structured request logging (method, URL, status,
latency, remote IP, user agent, request ID)
4. **Metrics** — Prometheus HTTP metrics (if `METRICS_USERNAME` is set)
5. **CORS** — Cross-origin resource sharing headers
6. **Timeout** — 60-second request timeout
7. **Recoverer** — Panic recovery: one `ERROR` record through
`internal/logger` and a `500`
5. **Metrics** — Prometheus HTTP metrics (if `METRICS_USERNAME` is set)
6. **CORS** — Cross-origin resource sharing headers
7. **Timeout** — 60-second request timeout
8. **Sentry** — Error reporting to Sentry (if `SENTRY_DSN` is set;
configured with `Repanic: true` so panics still reach Recoverer)
Recoverer sits seventh rather than first, and both neighbours are the
reason. It runs **inside** everything that observes the response, so
the `500` it writes for a panicking handler is the status the access
log records and the metrics count; registered first, as chi's own
`middleware.Recoverer` was, the same request was logged as a `200` that
the client never received. It runs **outside** the Sentry handler, so
`Repanic: true` has something to re-raise into: an operator with
`SENTRY_DSN` set keeps the report, and one without it now gets the
local record instead of nothing. What that placement gives up is
recovery of a panic in the six entries above it, none of which does
more than set a header or start a timer.
Additionally, form endpoints (`/pages`, `/user/*`, `/sources`,
`/source/*`) apply a **MaxBodySize** middleware that limits
POST/PUT/PATCH request bodies to 1 MB. It is registered ahead of the

View File

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

140
TODO.md
View File

@@ -24,142 +24,30 @@ event retention (#63), the database archiving target (#43), the admin
password change flow (#65), policy compliance (#6), pinned lint tooling
(#55), and fail-loud configuration parsing (#80).
`next` holds the **complete 1.0.0 milestone**: every issue in it is
closed, and it is verified green both by CI and by cache-defeated
container runs (`docker build --no-cache-filter=lint
--no-cache-filter=builder`).
One caveat on reading a green check, narrower than it used to be. A
docs-only commit deliberately replays from the layer cache (#119), so a
green status on such a commit evidences a replay rather than an executed
run; a code commit invalidates the `COPY` layer and genuinely executes.
Superseded runs are no longer the hazard they were: before #152 they
were recorded as `skipped` and rolled up green, and before #119 a warm
layer cache let the gate report success without executing anything,
replaying the previous build's console log so the lie looked like a real
run. Both are fixed. Note: `TODO.md` was deliberately
`next` holds the completed 1.0.0 milestone: every issue in it is closed,
and it is verified green by cache-defeated container runs
(`docker build --no-cache-filter=lint --no-cache-filter=builder`). The
CI status is not independently claimed here: a superseded run is
recorded as `skipped` and still rolls up green, so a commit status on
`next` does not by itself evidence an executed check (#152). Before
#119, a warm layer cache also let the gate report success without
executing anything, and replayed the previous build's console log so
the lie looked like a real run. Note: `TODO.md` was deliberately
deleted from this repo in f9a9569 (2026-03-01, #6); its content was
folded into the README TODO section, which this draft reconstructs as
of 2026-07-06.
# Next Step
Merge the milestone PR (#111) to `main` and tag 1.0.0 from it. The
milestone is empty and `next` is green; nothing else blocks the tag.
Merge the milestone PR to `main` and tag 1.0.0 from it.
Three items belong to the owner, none of them blocking. #150 was decided
by the manager rather than left to stall the queue and is flagged on the
issue for reversal if that call was wrong. #112 (whether `Completed
Steps` should exist at all, given it once conflicted on every unit) is
unanswered; the provisional ruling in force is that issue branches do
not touch this file. #198 records that `make test` is past the org 20s
target — 46s of test execution inside a 62.8s CI layer — and turns on
which quantity the 60s hard cap governs; it is scoped as the improvement
bug the 20-60s band requires, and should be milestoned instead if the
cap is read as covering the whole invocation.
After the tag, the largest open cluster is the unmilestoned follow-up
backlog these units generated: #183, #184, #185, #190, #191, #193 and
#198.
Two decisions are open and belong to the owner, neither blocking the
tag: #115 (mask the `http` target's destination URL, implemented
speculatively and awaiting a yes or no) and #125 (whether IPv6
rate-limit keys should bucket by `/64`).
# Completed Steps
- 2026-08-18 Raise `script/test`'s per-package timeout from 30s to 90s,
matching the org-wide backstop. `go test` applies `-timeout` per
package, and `internal/handlers` had grown past the old budget: a
cache-defeated build failed outright at `GOMAXPROCS=4`, and every run
under deliberate host load breached 30s. The measurement table lives
in the script (#194)
- 2026-08-18 Re-sync `REPO_POLICIES.md` from `prompts`. The local copy
was stale and still mandated a 20s test target with a 30s timeout,
which the org replaced with a 60s cap and a 90s backstop. A synced
copy is not a source; reading it as one nearly produced a PR against
`prompts` proposing a change already merged there (#196)
- 2026-08-18 Report handler panics through the logger and answer 500.
chi v1.5.5's `Recoverer` scans for a `panic(0x` frame the runtime no
longer emits, then indexes `pkg[-1:]`, so it panicked inside its own
stack printer before writing a byte: the recovery never ran, the
client got a dropped connection instead of a 500, and the original
panic was lost. A local middleware replaces it, bounded by
`MaxPanicLogLineBytes` (#187)
- 2026-08-18 Route GORM's logger through `slog` and bound it. Every
`gorm.Open` left `logger.Default` in place at `Warn` with
`IgnoreRecordNotFoundError` false, so **every record-not-found
printed the fully interpolated SQL to stdout** — including the
client-chosen path on `/webhook/{uuid}` and the submitted username on
the login form, at no level the operator set and outside
`internal/logger` entirely. Three call sites, not the two the issue
named (#178)
- 2026-08-18 Bound every `slog` line against client-chosen text. Eight
sites reachable unauthenticated, found by reading every `slog` call in
the tree rather than only the one reported; the budget moved to a
shared `internal/logfield` so no second truncation exists. `DEBUG`
being off by default is not a bound and is not treated as one (#176)
- 2026-08-18 Stop a slow host turning a login-guard test into a
segfault. A non-fatal `assert` on an acquire result was dereferenced
on the next line, so one timing miss killed the whole
`internal/middleware` binary and reddened CI for unrelated PRs. The
fix also removed a real production race — `acquire` could shed a
request with a slot standing free, because Go picks uniformly among
ready `select` cases (#186)
- 2026-08-18 Send the chi route pattern to Sentry rather than the
concrete path. The receiver's path carries the entrypoint capability
token, so every Sentry event from `/webhook/{uuid}` shipped a live
credential to a third party. Request `Data`, `QueryString`, `Cookies`
and `Env` are dropped and headers reduced to an allowlist (#179)
- 2026-08-18 Read form fields from the POST body only. `r.FormValue`
merges the query string, so a login could be driven by URL parameters
— putting the password somewhere that lands in access logs, proxy
logs and browser history (#160)
- 2026-08-18 Verify login credentials before spending rate-limit
budget, so a flood of wrong passwords cannot lock out the account it
is guessing at. The manager took this decision rather than stall the
queue; it is flagged on the issue for reversal (#150)
- 2026-08-18 Run all linting in Docker via `Dockerfile.lint`. Host lint
was wrong in both directions from version skew and shared caches.
`script/lint` asserts the summary line, because `--no-cache-filter`
silently ignores a stage name it does not match — the flag that makes
the gate meaningful fails open (#109)
- 2026-08-18 Serve an event's full stored body over HTTP. The list
query truncates for rendering, and that truncated value was the only
way to read a body, so the full payload was unreachable (#157)
- 2026-08-18 Bound the access log line against client-chosen text.
`internal/logfield` budgets by *encoded* bytes, not runes, so a
handler's JSON escaping cannot multiply a field past its allowance
(#146)
- 2026-08-18 Mark superseded CI commits `failure` rather than
`skipped`. A skipped run rolls up green, so a commit that was never
tested reported success (#152)
- 2026-08-18 Set `fx.StopTimeout` inside the container stop grace, so
shutdown hooks are bounded by a deadline the orchestrator will
actually honour rather than being killed mid-flush (#134)
- 2026-08-17 Bucket IPv6 rate-limit keys by `/64`. A single allocation
hands out 2^64 addresses, so per-address keying let one client mint
unlimited buckets. Manager decision, recorded on the issue (#125)
- 2026-08-17 Correct release-blocking README and startup-warning
inaccuracies, including claims about behaviour the code does not have
(#151)
- 2026-08-17 Fetch and verify Alpine.js at build time against
`static/vendor.sha256` instead of committing the minified blob, so
the dependency is pinned by hash rather than by trust (#145)
- 2026-08-17 Bound the event log's rendered bodies in the query itself,
so a large stored payload cannot be read into memory just to be
truncated for display (#135)
- 2026-08-17 Mask the `http` target's destination URL in the UI: it can
carry a bearer credential in its path or query, and was rendered
verbatim. Manager decision to mask unconditionally (#115)
- 2026-08-14 Bound shutdown hooks by their stop context, so a hook that
hangs cannot hold the process past its grace period (#102)
- 2026-08-14 Render templates via a buffer rather than the
`ResponseWriter`, so a template error part-way through cannot commit
a 200 and then fail — the response is written only once it is whole
(#123)
- 2026-08-14 Align the session codec's max-age with the 7-day absolute
cap. The codec accepted cookies the session layer considered expired,
so the cap was enforced in one place and not the other (#108)
- 2026-08-12 Warn when `TRUSTED_PROXIES` is empty in production, where
the safe default silently discards forwarded headers and every client
rate-limits as the proxy's address (#149)
- 2026-08-12 Bound the receiver rate limit per client IP across the
whole `/webhook/*` route. The existing limiter keyed on the request
path and `/webhook/{uuid}` matches any single segment, so a client

View File

@@ -17,7 +17,6 @@ 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"
)
@@ -156,10 +155,7 @@ func (d *Database) connect() error {
// Then use it with GORM
db, err := gorm.Open(sqlite.Dialector{
Conn: sqlDB,
}, &gorm.Config{
// Never leave this at GORM's default. See internal/gormlog.
Logger: gormlog.New(d.log),
})
}, &gorm.Config{})
if err != nil {
d.log.Error(
"failed to connect to database",

View File

@@ -14,7 +14,6 @@ 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"
)
@@ -249,10 +248,7 @@ func (m *WebhookDBManager) openDB(
db, err := gorm.Open(sqlite.Dialector{
Conn: sqlDB,
}, &gorm.Config{
// Never leave this at GORM's default. See internal/gormlog.
Logger: gormlog.New(m.log),
})
}, &gorm.Config{})
if err != nil {
_ = sqlDB.Close()

View File

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

View File

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

View File

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

View File

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

View File

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

View File

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

View File

@@ -120,9 +120,7 @@ func (h *Handlers) authenticateUser(
if !ok {
h.log.Warn(
"password verification capacity exhausted",
"path", logfield.Truncate(
r.URL.Path, logfield.MaxBytes,
),
"path", r.URL.Path,
)
h.renderLoginError(
w, r,

View File

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

View File

@@ -19,12 +19,6 @@ package handlers_test
// 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"
@@ -117,23 +111,44 @@ func oversizedFill(ch string) string {
attackerMarker + tailMarker
}
// capturingHandlersWithDB is capturingHandlers plus the database, for
// the call sites that write their line only once the client's value
// matched a stored row.
func capturingHandlersWithDB(
t *testing.T,
newHandler func(io.Writer, *slog.HandlerOptions) slog.Handler,
) (*handlers.Handlers, *database.Database, *bytes.Buffer) {
t.Helper()
var (
h *handlers.Handlers
db *database.Database
)
app := newTestApp(t, &h, &db)
app.RequireStart()
t.Cleanup(app.RequireStop)
buf := new(bytes.Buffer)
h.SetLogForTest(slog.New(newHandler(
buf, &slog.HandlerOptions{Level: slog.LevelDebug},
)))
return h, db, buf
}
// 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 := newTestApp(t, &h)
app.RequireStart()
t.Cleanup(app.RequireStop)
@@ -147,8 +162,8 @@ func capturingHandlers(
}
// 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 {
// each to bound bytes.
func logLines(t *testing.T, buf *bytes.Buffer, bound int) []string {
t.Helper()
var lines []string
@@ -161,7 +176,7 @@ func logLines(t *testing.T, buf *bytes.Buffer) []string {
}
require.LessOrEqual(
t, len(line), middleware.MaxAccessLogLineBytes,
t, len(line), bound,
"log line exceeded its bound: %s", line,
)
@@ -287,7 +302,9 @@ func TestUnknownEntrypoint_LogLineDoesNotTrackPathSize(t *testing.T) {
)
}
lines := logLines(t, buf)
lines := logLines(
t, buf, middleware.MaxAccessLogLineBytes,
)
require.Len(t, lines, floodRequests)
assertNoClientText(t, buf)
@@ -322,7 +339,9 @@ func TestFailedLogin_LogLineDoesNotTrackUsernameSize(t *testing.T) {
)
}
lines := logLines(t, buf)
lines := logLines(
t, buf, middleware.MaxAccessLogLineBytes,
)
require.Len(t, lines, floodRequests)
assertNoClientText(t, buf)
@@ -370,9 +389,7 @@ func TestStoredUsername_LogLinesDoNotTrackUsernameSize(t *testing.T) {
t.Run(handlerName, func(t *testing.T) {
t.Parallel()
var db *database.Database
h, buf := capturingHandlers(t, newHandler, &db)
h, db, buf := capturingHandlersWithDB(t, newHandler)
hash, err := database.HashPassword(storedUserPassword)
require.NoError(t, err)
@@ -405,124 +422,15 @@ func TestStoredUsername_LogLinesDoNotTrackUsernameSize(t *testing.T) {
)
}
lines := logLines(t, buf)
lines := logLines(
t, buf, middleware.MaxAccessLogLineBytes,
)
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;

View File

@@ -219,103 +219,3 @@ func TestTruncate_DropsInvalidUTF8(t *testing.T) {
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)
}
}

View File

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

View File

@@ -13,12 +13,6 @@ package middleware_test
// - 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
@@ -408,64 +402,6 @@ func TestLogLines_ClientChosenPathDoesNotSizeTheLine(t *testing.T) {
}
}
// 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.

View File

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

View File

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

View File

@@ -67,9 +67,6 @@ 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
@@ -89,35 +86,14 @@ const (
// 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,
// and unknown-entrypoint DEBUG lines, and the failed-login DEBUG
// lines — 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:
//
@@ -133,12 +109,10 @@ const (
// - The "log" delivery target, which exists to write the whole
// inbound event to the log. Deliberate; see
// internal/delivery/target_log.go.
// - The record a recovered panic writes, which is not an access
// 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.
// - GORM's default logger, which prints the interpolated SQL to
// stdout on a record-not-found and so is unbounded on the
// receiver and login lookups. NOT deliberate; filed as
// https://git.eeqj.de/sneak/webhooker/issues/178.
MaxAccessLogLineBytes = 2560
)

View File

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

View File

@@ -1,645 +0,0 @@
package middleware_test
import (
"bytes"
"encoding/json"
"io"
"log"
"net/http"
"net/http/httptest"
"strings"
"testing"
"github.com/go-chi/chi"
chimw "github.com/go-chi/chi/middleware"
"github.com/stretchr/testify/assert"
"github.com/stretchr/testify/require"
"sneak.berlin/go/webhooker/internal/middleware"
)
// panicMarker is the panic value the probe handlers raise. The
// recoverer's whole job is to put this string, and not some second
// panic's, in front of an operator.
const panicMarker = "QQORIGINALPANICVALUEQQ"
// probeFuncName appears in the stack of every panic raised below,
// since that is the function raising it. Its presence is how these
// tests tell a real stack from an empty field.
const probeFuncName = "panicProbe"
// committedStatus is the status a handler sends before panicking in
// the already-committed case. It is deliberately not 200, so a test
// cannot pass on net/http's implicit default.
const committedStatus = http.StatusMultiStatus
// recovererProbe is a test server carrying one panicking route,
// behind the production recoverer.
type recovererProbe struct {
server *httptest.Server
// logs holds every record the middleware wrote.
logs *bytes.Buffer
// serverErrors holds everything net/http wrote to its own error
// log. A working recoverer leaves it empty: net/http only reports
// a request when a panic escapes the handler chain, which is the
// failure this issue is about.
serverErrors *bytes.Buffer
}
// newRecovererProbe stands up a real HTTP server — a real listener, a
// real connection, a real client — behind the production recoverer.
//
// A real server rather than an httptest.ResponseRecorder, because a
// recorder cannot express the outcome that made this a defect: chi's
// Recoverer left net/http to close the connection, which a recorder
// records as an ordinary unwritten response while a client sees EOF.
// The status a client actually receives is only observable over a
// socket.
func newRecovererProbe(
t *testing.T,
textHandler bool,
handler http.HandlerFunc,
) *recovererProbe {
t.Helper()
newMiddleware := capturingMiddleware
if textHandler {
newMiddleware = capturingTextMiddleware
}
m, logs := newMiddleware(t)
router := chi.NewRouter()
// The registration order the production router uses: RequestID
// outside so the recoverer's record can name the request,
// Logging outside so the recovered 500 is the status it records.
router.Use(chimw.RequestID)
router.Use(m.Logging())
router.Use(m.Recoverer())
router.Get("/probe", handler)
serverErrors := new(bytes.Buffer)
server := httptest.NewUnstartedServer(router)
server.Config.ErrorLog = log.New(serverErrors, "", 0)
server.Start()
t.Cleanup(server.Close)
return &recovererProbe{
server: server,
logs: logs,
serverErrors: serverErrors,
}
}
// get drives one request at the probe route and returns the response,
// or the transport error if the connection was dropped instead.
func (p *recovererProbe) get(t *testing.T) (*http.Response, error) {
t.Helper()
return p.getWithRequestID(t, "")
}
// getWithRequestID drives the same request carrying a client-supplied
// X-Request-Id. chi's RequestID middleware adopts that header verbatim
// when it is present and only generates a value when it is absent, so
// this is the third growable field on the panic record and the only
// one a client fills outright.
func (p *recovererProbe) getWithRequestID(
t *testing.T,
requestID string,
) (*http.Response, error) {
t.Helper()
req, err := http.NewRequestWithContext(
t.Context(), http.MethodGet, p.server.URL+"/probe", nil,
)
require.NoError(t, err)
if requestID != "" {
req.Header.Set(chimw.RequestIDHeader, requestID)
}
return p.server.Client().Do(req)
}
// wait shuts the server down and blocks until every in-flight request
// has finished, which is what makes the log buffer safe to read.
//
// A client returns as soon as the response is complete — or, for a
// deliberately aborted connection, as soon as it is closed — while the
// access log line for the same request is still being written on the
// server goroutine. It is idempotent, so a test may call it directly
// before reading the buffer itself.
func (p *recovererProbe) wait() {
p.server.Close()
}
// records decodes every JSON log line the probe captured.
func (p *recovererProbe) records(t *testing.T) []map[string]any {
t.Helper()
p.wait()
var out []map[string]any
for line := range strings.SplitSeq(
strings.TrimSpace(p.logs.String()), "\n",
) {
if line == "" {
continue
}
record := map[string]any{}
require.NoError(t, json.Unmarshal([]byte(line), &record))
out = append(out, record)
}
return out
}
// panicRecord returns the single "handler panic" record, failing if
// there is not exactly one.
func (p *recovererProbe) panicRecord(t *testing.T) map[string]any {
t.Helper()
var found []map[string]any
for _, record := range p.records(t) {
if record["msg"] == "handler panic" {
found = append(found, record)
}
}
require.Len(
t, found, 1,
"exactly one panic record expected, log was:\n%s",
p.logs.String(),
)
return found[0]
}
// panicProbe panics with the marker. It is a named function so the
// stack assertions have something to look for.
func panicProbe(http.ResponseWriter, *http.Request) {
panic(panicMarker)
}
func TestRecovererAnswers500AndLogsTheOriginalPanic(t *testing.T) {
t.Parallel()
probe := newRecovererProbe(t, false, panicProbe)
resp, err := probe.get(t)
require.NoError(
t, err,
"a panicking handler must answer, not drop the connection",
)
defer func() { _ = resp.Body.Close() }()
body, err := io.ReadAll(resp.Body)
require.NoError(t, err)
assert.Equal(t, http.StatusInternalServerError, resp.StatusCode)
assert.Contains(t, string(body), "Internal Server Error")
record := probe.panicRecord(t)
assert.Equal(t, "ERROR", record["level"])
assert.Equal(t, panicMarker, record["panic"])
assert.Equal(t, false, record["response_committed"])
stack, ok := record["stack"].(string)
require.True(t, ok, "the record must carry a stack")
assert.Contains(
t, stack, probeFuncName,
"the stack must reach the function that panicked",
)
assert.NotContains(
t, stack, "slice bounds out of range",
"a secondary panic must not have occurred",
)
assert.Empty(
t, probe.serverErrors.String(),
"net/http must not have had to report anything",
)
}
// TestRecovererStatusReachesTheAccessLog pins the placement. The
// recoverer runs inside the logging middleware precisely so the status
// it writes is the one the access log records; registered outside it,
// as chi's Recoverer was, the same request is logged as a 200 that the
// client never received.
func TestRecovererStatusReachesTheAccessLog(t *testing.T) {
t.Parallel()
probe := newRecovererProbe(t, false, panicProbe)
resp, err := probe.get(t)
require.NoError(t, err)
require.NoError(t, resp.Body.Close())
require.Equal(t, http.StatusInternalServerError, resp.StatusCode)
var access map[string]any
for _, record := range probe.records(t) {
if record["msg"] == "http request" {
access = record
}
}
require.NotNil(t, access, "the request must still be logged")
assert.EqualValues(
t, http.StatusInternalServerError, access["status"],
"the access log must record the status the client got",
)
// The panic record identifies its request by request_id alone,
// so that join has to work.
assert.Equal(
t, access["request_id"],
probe.panicRecord(t)["request_id"],
)
assert.NotEmpty(t, access["request_id"])
}
// TestRecovererRepanicsErrAbortHandler covers the one panic value that
// must not be turned into a 500. net/http documents it as the way a
// handler abandons a connection deliberately and special-cases it,
// suppressing both the response and its own stack report.
func TestRecovererRepanicsErrAbortHandler(t *testing.T) {
t.Parallel()
probe := newRecovererProbe(
t, false,
func(http.ResponseWriter, *http.Request) {
panic(http.ErrAbortHandler)
},
)
resp, err := probe.get(t)
if err == nil {
_ = resp.Body.Close()
}
require.Error(
t, err,
"an aborted handler must not answer with a status",
)
for _, record := range probe.records(t) {
assert.NotEqual(
t, "handler panic", record["msg"],
"a deliberate abort is not a fault to report",
)
}
assert.Empty(
t, probe.serverErrors.String(),
"net/http suppresses ErrAbortHandler; it must still see it",
)
}
// TestRecovererKeepsAnAlreadyCommittedResponse covers a handler that
// panics after sending its status. The bytes are already on the wire,
// so a second WriteHeader would change nothing the client sees and
// would draw net/http's "superfluous response.WriteHeader" report.
func TestRecovererKeepsAnAlreadyCommittedResponse(t *testing.T) {
t.Parallel()
probe := newRecovererProbe(
t, false,
func(w http.ResponseWriter, _ *http.Request) {
w.WriteHeader(committedStatus)
_, _ = w.Write([]byte("partial"))
panic(panicMarker)
},
)
resp, err := probe.get(t)
require.NoError(t, err)
defer func() { _ = resp.Body.Close() }()
body, err := io.ReadAll(resp.Body)
require.NoError(t, err)
assert.Equal(t, committedStatus, resp.StatusCode)
assert.Equal(t, "partial", string(body))
record := probe.panicRecord(t)
assert.Equal(t, panicMarker, record["panic"])
assert.Equal(
t, true, record["response_committed"],
"the record must say why no 500 was sent",
)
assert.NotContains(
t, probe.serverErrors.String(),
"superfluous response.WriteHeader",
)
}
// TestRecovererKeepsAnImplicitlyCommittedResponse is the same case
// without an explicit WriteHeader: a bare Write commits the response
// to 200 just as surely.
func TestRecovererKeepsAnImplicitlyCommittedResponse(t *testing.T) {
t.Parallel()
probe := newRecovererProbe(
t, false,
func(w http.ResponseWriter, _ *http.Request) {
_, _ = w.Write([]byte("partial"))
panic(panicMarker)
},
)
resp, err := probe.get(t)
require.NoError(t, err)
require.NoError(t, resp.Body.Close())
assert.Equal(t, http.StatusOK, resp.StatusCode)
assert.Equal(
t, true, probe.panicRecord(t)["response_committed"],
)
assert.NotContains(
t, probe.serverErrors.String(),
"superfluous response.WriteHeader",
)
}
// panicLogHandler names one of the two handlers internal/logger can
// install. The recoverer's probe selects between them with a bool
// rather than by constructing one, which is why this does not reuse
// logHandlers() the way the fills reuse escapeFills().
type panicLogHandler struct {
name string
text bool
}
func panicLogHandlers() []panicLogHandler {
return []panicLogHandler{{"json", false}, {"text", true}}
}
// TestRecovererBoundsThePanicRecord holds the record to its stated
// ceiling with a panic value the size of a request. A handler is free
// to build a panic value out of what the client sent, so the value is
// charged a client-sized budget even though the stack is not.
func TestRecovererBoundsThePanicRecord(t *testing.T) {
t.Parallel()
for _, handler := range panicLogHandlers() {
// The fills are internal/middleware's own access log fills,
// shared rather than restated: plain text, the characters
// both handlers escape to two bytes, a bare C0 control, and
// an astral non-printable the text handler spells with a
// ten-byte \U escape.
for fillName, fillRune := range escapeFills() {
t.Run(handler.name+"/"+fillName, func(t *testing.T) {
t.Parallel()
value := strings.Repeat(
fillRune, oversizedSegmentBytes,
) + tailMarker
probe := newRecovererProbe(
t, handler.text,
func(http.ResponseWriter, *http.Request) {
panic(value)
},
)
resp, err := probe.get(t)
require.NoError(t, err)
require.NoError(t, resp.Body.Close())
require.Equal(
t, http.StatusInternalServerError,
resp.StatusCode,
)
probe.wait()
for line := range strings.SplitSeq(
strings.TrimSpace(probe.logs.String()), "\n",
) {
assert.LessOrEqual(
t, len(line),
middleware.MaxPanicLogLineBytes,
"log line exceeded its stated bound",
)
assert.NotContains(
t, line, tailMarker,
"the far end of the panic value reached "+
"the log, so nothing truncated it",
)
}
})
}
}
}
// deepPanic recurses to depth and then panics, so the stack itself
// overruns its budget. It is the only way to exercise the stack cut:
// the shipped middleware chain does not come close (see
// TestPanicThroughProductionRouter in internal/server).
func deepPanic(depth int, value string) int {
if depth == 0 {
panic(value)
}
return deepPanic(depth-1, value) + 1
}
// assertEveryFieldWasCut holds each of the record's three growable
// fields to its own budget, which is what the ceiling is the sum of.
// The stack is cut at its far end, so its near end — the panic site —
// has to survive; the request id is the client's own bytes, so its
// cut is the one that bounds an attacker rather than our own call
// depth.
func assertEveryFieldWasCut(t *testing.T, record map[string]any) {
t.Helper()
stack, ok := record["stack"].(string)
require.True(t, ok)
assert.True(
t, strings.HasSuffix(stack, truncationSuffix),
"an oversized stack must be marked as cut",
)
assert.Contains(
t, stack, "deepPanic",
"the near end of the stack must survive the cut",
)
assert.NotContains(
t, stack, "net/http.(*conn).serve",
"the far end is what a cut discards",
)
id, ok := record["request_id"].(string)
require.True(t, ok)
assert.True(
t, strings.HasSuffix(id, truncationSuffix),
"an oversized request id must be marked as cut",
)
assert.LessOrEqual(
t, len(id), maxRequestIDBytes+len(truncationSuffix),
"the request id must be held to its own budget",
)
value, ok := record["panic"].(string)
require.True(t, ok)
assert.True(
t, strings.HasSuffix(value, truncationSuffix),
"an oversized panic value must be marked as cut",
)
}
// TestRecovererBoundsTheStack drives every growable field on the
// record past its budget at once — an oversized stack, an oversized
// panic value and an oversized client-supplied X-Request-Id — over
// both log handlers. It holds that line to the stated ceiling and
// reports what it measured, and it pins that a cut stack keeps its
// near end — the panic site — rather than its far one.
//
// The two fields the test picks the content of — the panic value and
// the request id — are filled with the quotation mark. Both handlers
// escape it to two bytes, which is exactly what logfield charges for
// it, so each of those fields emits every byte of its budget; no fill
// emits more, since logfield charges each rune the wider of the two
// handlers and a field can therefore never emit more than it spent.
// The stack is not a fill: recursion drives it past its budget and
// the cut lands wherever its own content puts it, which is why the
// measured widths move by a byte between runs.
func TestRecovererBoundsTheStack(t *testing.T) {
t.Parallel()
for _, handler := range panicLogHandlers() {
t.Run(handler.name, func(t *testing.T) {
t.Parallel()
value := strings.Repeat(`"`, oversizedSegmentBytes) +
tailMarker
requestID := strings.Repeat(`"`, oversizedSegmentBytes) +
tailMarker
probe := newRecovererProbe(
t, handler.text,
func(http.ResponseWriter, *http.Request) {
_ = deepPanic(512, value)
},
)
resp, err := probe.getWithRequestID(t, requestID)
require.NoError(t, err)
require.NoError(t, resp.Body.Close())
require.Equal(
t, http.StatusInternalServerError, resp.StatusCode,
)
probe.wait()
// The text handler does not emit JSON, so the field-level
// assertions run on the JSON one; the line bound below
// is asserted on both, which is the point of the sweep.
if !handler.text {
assertEveryFieldWasCut(t, probe.panicRecord(t))
}
widest := 0
for line := range strings.SplitSeq(
strings.TrimSpace(probe.logs.String()), "\n",
) {
assert.LessOrEqual(
t, len(line), middleware.MaxPanicLogLineBytes,
)
assert.NotContains(t, line, tailMarker)
widest = max(widest, len(line))
}
t.Logf(
"widest line measured: %d bytes (ceiling %d)",
widest, middleware.MaxPanicLogLineBytes,
)
})
}
}
// TestRecovererIgnoresANonPanickingHandler is the negative control:
// the middleware must be inert on the ordinary path.
func TestRecovererIgnoresANonPanickingHandler(t *testing.T) {
t.Parallel()
probe := newRecovererProbe(
t, false,
func(w http.ResponseWriter, _ *http.Request) {
w.WriteHeader(http.StatusTeapot)
},
)
resp, err := probe.get(t)
require.NoError(t, err)
require.NoError(t, resp.Body.Close())
assert.Equal(t, http.StatusTeapot, resp.StatusCode)
for _, record := range probe.records(t) {
assert.NotEqual(t, "handler panic", record["msg"])
}
}
// TestRecovererKeepsResponseControllerWorking pins the Unwrap method.
// The middleware wraps the ResponseWriter to learn whether the
// response was committed, and a wrapper without Unwrap hides
// net/http's own writer from http.ResponseController, so a handler
// that flushes or sets a deadline starts failing.
//
// The recoverer is the only middleware in the chain here. The access
// logger's own wrapper does not implement Unwrap, so a chain
// containing it fails this regardless of what the recoverer does;
// what is being pinned is that the recoverer adds no such opacity of
// its own.
func TestRecovererKeepsResponseControllerWorking(t *testing.T) {
t.Parallel()
m, _ := capturingMiddleware(t)
handler := m.Recoverer()(http.HandlerFunc(
func(w http.ResponseWriter, _ *http.Request) {
_, _ = w.Write([]byte("chunk"))
flushErr := http.NewResponseController(w).Flush()
if flushErr != nil {
http.Error(
w, "flush failed",
http.StatusInternalServerError,
)
return
}
},
))
server := httptest.NewServer(handler)
t.Cleanup(server.Close)
req, err := http.NewRequestWithContext(
t.Context(), http.MethodGet, server.URL, nil,
)
require.NoError(t, err)
resp, err := server.Client().Do(req)
require.NoError(t, err)
defer func() { _ = resp.Body.Close() }()
body, err := io.ReadAll(resp.Body)
require.NoError(t, err)
assert.Equal(t, http.StatusOK, resp.StatusCode)
assert.Equal(t, "chunk", string(body))
}

View File

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

View File

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

View File

@@ -51,6 +51,7 @@ func (s *Server) SetupRoutes() {
}
func (s *Server) setupGlobalMiddleware() {
s.router.Use(middleware.Recoverer)
s.router.Use(middleware.RequestID)
s.router.Use(s.mw.SecurityHeaders())
s.router.Use(s.mw.Logging())
@@ -63,21 +64,8 @@ func (s *Server) setupGlobalMiddleware() {
s.router.Use(s.mw.CORS())
s.router.Use(middleware.Timeout(requestTimeout))
// Panic recovery, deliberately here rather than first. It has to
// run inside every middleware that observes the response, so the
// 500 it writes is the status the access log records and the
// metrics count, and outside the sentryhttp handler below, whose
// Repanic option needs something further out to catch what it
// re-raises. chi's own middleware.Recoverer held the first slot
// until it was measured: on a current Go release it crashes
// inside its stack pretty-printer instead of recovering, so the
// connection dropped and the original panic was never reported.
// See https://git.eeqj.de/sneak/webhooker/issues/187.
s.router.Use(s.mw.Recoverer())
// Sentry error reporting (if SENTRY_DSN is set). Repanic is
// true so panics still bubble up to the Recoverer middleware
// registered immediately above.
// true so panics still bubble up to the Recoverer middleware.
if s.sentryEnabled {
sentryHandler := sentryhttp.New(sentryhttp.Options{
Repanic: true,

View File

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

View File

@@ -2,11 +2,8 @@ package server
import (
"net/http"
"net/url"
"strings"
"github.com/getsentry/sentry-go"
"github.com/go-chi/chi"
)
// sentryRedacted stands in for a withheld field on every event shipped
@@ -14,12 +11,6 @@ import (
// can tell a suppressed value from an absent one.
const sentryRedacted = "(redacted)"
// sentryRedactedPath is what stands in for the request path when the
// route pattern is not reachable. It is deliberately not the concrete
// path: on the receiver route that path carries the entrypoint UUID,
// which is a write capability rather than an identifier.
const sentryRedactedPath = "/" + sentryRedacted
// sentryClientOptions builds the options the SDK is initialised with.
// It is its own function so a test can stand up a client wired exactly
// as production is, with only the transport swapped.
@@ -53,43 +44,18 @@ func sentryClientOptions(dsn, release string) sentry.ClientOptions {
// login password and both password-change fields. None of that may
// reach a third-party service.
//
// URL is the third such field. NewRequest builds it as
// scheme://host/path (interfaces.go:183), and on the receiver route
// that path is /webhook/<uuid> in full — a write capability, not an
// identifier. It is rebuilt here from the chi route pattern, on every
// route, keeping the scheme and the host.
//
// This hook is a floor, not a default: the fields it clears stay
// cleared even if SendDefaultPII is ever turned on.
func scrubSentryRequest(
event *sentry.Event,
hint *sentry.EventHint,
_ *sentry.EventHint,
) *sentry.Event {
if event == nil {
return event
}
pattern := sentryRoutePattern(hint)
// Only transaction events carry a Transaction name, and the SDK
// builds it from the concrete path too (sentryhttp.go:105 via
// tracing.go:553). Rewritten on the same terms.
if event.Transaction != "" {
event.Transaction = sentryTransactionName(
event.Transaction, pattern,
)
}
if event.Request == nil {
if event == nil || event.Request == nil {
return event
}
req := event.Request
if req.URL != "" {
req.URL = sentryRouteURL(req.URL, pattern)
}
if req.QueryString != "" {
req.QueryString = sentryRedacted
}
@@ -105,91 +71,6 @@ func scrubSentryRequest(
return event
}
// sentryRoutePattern returns the chi route pattern for the request the
// hint carries, or "" when it is not reachable.
//
// The request is reachable on the error dispatch only. sentryhttp's
// recover path calls RecoverWithContext with the request on the
// context under sentry.RequestContextKey (sentryhttp.go:124-125), and
// the client copies that context onto the hint (client.go:484-485)
// before handing it to BeforeSend (client.go:631). chi's routing
// context is a pointer placed on the request context before the
// middleware chain runs (chi mux.go:84) and filled in as the mux
// routes, so by the time a handler panics it names the matched route.
//
// The transaction dispatch has no such request: Span.doFinish calls
// hub.CaptureEvent (tracing.go:356), which passes a nil hint that the
// client replaces with an empty one (client.go:620-622). The pattern
// is therefore always "" there, and the callers fall back.
func sentryRoutePattern(hint *sentry.EventHint) string {
if hint == nil || hint.Context == nil {
return ""
}
req, ok := hint.Context.Value(
sentry.RequestContextKey,
).(*http.Request)
if !ok || req == nil {
return ""
}
rctx := chi.RouteContext(req.Context())
if rctx == nil {
return ""
}
// Empty when no route matched, which is the fallback case too.
return rctx.RoutePattern()
}
// sentryRouteURL rebuilds an event's request URL with the route
// pattern in place of the concrete path.
//
// The scheme is load-bearing and is kept: the SDK derives it from
// r.TLS != nil || r.Header.Get("X-Forwarded-Proto") == "https"
// (interfaces.go:180), byte for byte the predicate
// internal/middleware/csrf.go uses, so it is the CSRF TLS decision and
// the reason dropping X-Forwarded-Proto from the header allowlist
// costs nothing. The host is parsed.Host of the SDK's
// scheme://r.Host/path, so it is whatever the client's Host header
// carried: this service validates no hostname. It is kept because that
// same header is on the allowlist, so scrubbing it here would withhold
// nothing that is not sent anyway.
//
// Everything else in the URL is discarded rather than edited, so a
// future SDK that starts appending a query string cannot widen this.
func sentryRouteURL(rawURL, pattern string) string {
parsed, err := url.Parse(rawURL)
if err != nil || parsed.Scheme == "" {
// Not a shape this can safely take apart.
return sentryRedacted
}
if pattern == "" {
pattern = sentryRedactedPath
}
return parsed.Scheme + "://" + parsed.Host + pattern
}
// sentryTransactionName rebuilds the SDK's "METHOD /path" transaction
// name with the route pattern in place of the concrete path. Method is
// kept for the same reason Request.Method is: net/http admits only a
// bounded token there. A name in any other shape is withheld whole,
// since nothing can be said about which part of it is a path.
func sentryTransactionName(name, pattern string) string {
method, _, found := strings.Cut(name, " ")
if !found {
return sentryRedacted
}
if pattern == "" {
pattern = sentryRedactedPath
}
return method + " " + pattern
}
// keptSentryHeaders returns the subset of headers an event may carry
// off-host. Dropping by allowlist rather than by blocklist is what
// makes an unrecognised header safe: the SDK's own filter removes four

View File

@@ -13,13 +13,12 @@ import (
"github.com/getsentry/sentry-go"
sentryhttp "github.com/getsentry/sentry-go/http"
"github.com/go-chi/chi"
"github.com/stretchr/testify/assert"
"github.com/stretchr/testify/require"
"sneak.berlin/go/webhooker/internal/server"
)
// The four markers below are the credentials a captured event could
// The three markers below are the credentials a captured event could
// carry off-host, one per field of sentry.Request that the SDK fills
// from the request without a SendDefaultPII guard.
const (
@@ -34,12 +33,6 @@ const (
// sentryHeaderMarker rides X-Csrf-Token, which gorilla/csrf
// accepts in place of the form field.
sentryHeaderMarker = "QQSENTRYHEADERMARKERQQ"
// sentryReceiverUUID is the entrypoint identifier in the path of
// a receiver request. It is a write capability: anyone holding
// it can POST events this service accepts and its targets then
// deliver, so it may not reach a third-party tracker.
sentryReceiverUUID = "6d1f9c2a-3b7e-4f58-9a0d-c0ffeebadc0d"
)
// sentryKeptUserAgent is a non-secret header value planted so the
@@ -65,41 +58,19 @@ func (c *captureTransport) SendEvent(event *sentry.Event) {
c.events = append(c.events, event)
}
// sentryCase drives one request through the real sentryhttp middleware
// inside a real chi router and returns the events the SDK produced.
// captureThroughSentryHTTP panics inside a form handler wrapped in the
// real sentryhttp middleware and returns the event the SDK produced.
//
// Routing through a chi mux is load-bearing, not decoration. chi puts
// its routing context on the request context before the middleware
// chain runs and fills it in as it matches, so a hand-built request
// carries no route pattern at all and could not distinguish the hook
// working from the hook falling back.
// This is the only construction path on which Request.Data appears:
// sentryhttp calls Scope.SetRequest, which tees r.Body into a 10 KiB
// buffer, ParseForm drains the tee, and Scope.ApplyToEvent copies the
// buffer into the event inside prepareEvent — before BeforeSend runs.
// A hand-built sentry.NewRequest never reads the body and so cannot
// regress-test any of it.
//
// This is also the only construction path on which Request.Data
// appears: sentryhttp calls Scope.SetRequest, which tees r.Body into a
// 10 KiB buffer, ParseForm drains the tee, and Scope.ApplyToEvent
// copies the buffer into the event inside prepareEvent — before
// BeforeSend runs. A hand-built sentry.NewRequest never reads the body
// and so cannot regress-test any of it.
type sentryCase struct {
// scrub selects whether the production BeforeSend hooks are
// installed, so the same path shows both what the SDK collects
// and what survives.
scrub bool
// tracing enables the transaction dispatch, which the service
// leaves off. With it on, a served request produces a
// transaction event through BeforeSendTransaction.
tracing bool
// panics selects the error dispatch, via BeforeSend.
panics bool
// request builds the request to serve, given the client whose
// hub it must carry.
request func(*sentry.Client) *http.Request
}
func (c sentryCase) capture(t *testing.T) []*sentry.Event {
// scrub selects whether the production BeforeSend hooks are installed,
// so the same path shows both what the SDK collects and what survives.
func captureThroughSentryHTTP(t *testing.T, scrub bool) *sentry.Event {
t.Helper()
transport := &captureTransport{}
@@ -109,109 +80,57 @@ func (c sentryCase) capture(t *testing.T) []*sentry.Event {
)
opts.Transport = transport
if !c.scrub {
if !scrub {
opts.BeforeSend = nil
opts.BeforeSendTransaction = nil
}
if c.tracing {
opts.EnableTracing = true
opts.TracesSampleRate = 1.0
}
client, err := sentry.NewClient(opts)
require.NoError(t, err)
c.router().ServeHTTP(httptest.NewRecorder(), c.request(client))
handler := sentryhttp.New(sentryhttp.Options{}).Handle(
http.HandlerFunc(func(_ http.ResponseWriter, r *http.Request) {
// This call is what drains the tee and fills the
// buffer. Its success is asserted by the unscrubbed
// case below, which sees the body in the event.
_ = r.ParseForm()
return transport.events
}
// router mirrors the one ordering these tests depend on, over the two
// route patterns they need: a recovering middleware outside, then the
// sentryhttp handler registered with Use and Repanic set, exactly as
// routes.go orders the two. The bare recover stands in for
// Middleware.Recoverer, which holds that outer slot in production; it
// is here only to keep panic stacks out of the test output. That the
// production one really does catch what sentryhttp re-raises is
// pinned separately, by TestSentryStillSeesAPanic.
func (c sentryCase) router() http.Handler {
handler := func(_ http.ResponseWriter, r *http.Request) {
// This call is what drains the body tee and fills the
// buffer. Its success is asserted by the unscrubbed case
// below, which sees the body in the event.
_ = r.ParseForm()
if c.panics {
panic("boom")
}
}
router := chi.NewRouter()
router.Use(recoveringMiddleware)
router.Use(
sentryhttp.New(sentryhttp.Options{Repanic: true}).Handle,
}),
)
router.HandleFunc("/pages/login", handler)
router.HandleFunc("/webhook/{uuid}", handler)
return router
handler.ServeHTTP(
httptest.NewRecorder(),
sentryLoginRequest(client),
)
require.Len(t, transport.events, 1)
return transport.events[0]
}
func recoveringMiddleware(next http.Handler) http.Handler {
return http.HandlerFunc(
func(w http.ResponseWriter, r *http.Request) {
defer func() { _ = recover() }()
next.ServeHTTP(w, r)
},
)
}
// sentryLoginRequest builds the password POST most cases drive, with a
// credential planted in the body, the query and a header.
// sentryLoginRequest builds the password POST the capture above drives,
// with a credential planted in the body, the query and a header.
func sentryLoginRequest(client *sentry.Client) *http.Request {
form := url.Values{}
form.Set("username", "admin")
form.Set("password", sentryBodyMarker)
req := sentryRequest(
client,
"/pages/login?url=https://hooks.slack.com/services/"+
sentryQueryMarker,
form.Encode(),
)
req.Header.Set("X-Csrf-Token", sentryHeaderMarker)
return req
}
// sentryReceiverRequest builds a POST to the receiver route, whose
// concrete path carries the entrypoint capability.
func sentryReceiverRequest(client *sentry.Client) *http.Request {
return sentryRequest(
client, "/webhook/"+sentryReceiverUUID, "payload=hello",
)
}
func sentryRequest(
client *sentry.Client,
target, body string,
) *http.Request {
req := httptest.NewRequestWithContext(
sentry.SetHubOnContext(
context.Background(),
sentry.NewHub(client, sentry.NewScope()),
),
http.MethodPost,
target,
strings.NewReader(body),
"/pages/login?url=https://hooks.slack.com/services/"+
sentryQueryMarker,
strings.NewReader(form.Encode()),
)
req.Header.Set(
"Content-Type", "application/x-www-form-urlencoded",
)
req.Header.Set("X-Csrf-Token", sentryHeaderMarker)
req.Header.Set("User-Agent", sentryKeptUserAgent)
return req
@@ -227,27 +146,15 @@ func marshalEvent(t *testing.T, event *sentry.Event) string {
return string(encoded)
}
// onlyEvent asserts a single event was captured and returns it.
func onlyEvent(t *testing.T, events []*sentry.Event) *sentry.Event {
t.Helper()
require.Len(t, events, 1)
require.NotNil(t, events[0].Request)
return events[0]
}
// TestSentryScrub_SDKCollectsTheRequestUnscrubbed pins the premise the
// hook exists for. Without it the SDK ships the whole POST body, the
// raw query, the CSRF header and the concrete request path, none of
// which SendDefaultPII=false suppresses.
// raw query and the CSRF header, none of which SendDefaultPII=false
// suppresses.
func TestSentryScrub_SDKCollectsTheRequestUnscrubbed(t *testing.T) {
t.Parallel()
event := onlyEvent(t, sentryCase{
panics: true,
request: sentryLoginRequest,
}.capture(t))
event := captureThroughSentryHTTP(t, false)
require.NotNil(t, event.Request)
assert.Contains(
t, event.Request.Data, sentryBodyMarker,
@@ -258,18 +165,6 @@ func TestSentryScrub_SDKCollectsTheRequestUnscrubbed(t *testing.T) {
assert.Contains(
t, marshalEvent(t, event), sentryHeaderMarker,
)
receiver := onlyEvent(t, sentryCase{
panics: true,
request: sentryReceiverRequest,
}.capture(t))
assert.Contains(
t, receiver.Request.URL, sentryReceiverUUID,
"the SDK is expected to build Request.URL from the "+
"concrete path; if it no longer does, the route "+
"pattern rewrite's premise changed",
)
}
// TestSentryScrub_RedactsTheCapturedRequest is the regression test: no
@@ -278,11 +173,8 @@ func TestSentryScrub_SDKCollectsTheRequestUnscrubbed(t *testing.T) {
func TestSentryScrub_RedactsTheCapturedRequest(t *testing.T) {
t.Parallel()
event := onlyEvent(t, sentryCase{
scrub: true,
panics: true,
request: sentryLoginRequest,
}.capture(t))
event := captureThroughSentryHTTP(t, true)
require.NotNil(t, event.Request)
encoded := marshalEvent(t, event)
@@ -297,45 +189,16 @@ func TestSentryScrub_RedactsTheCapturedRequest(t *testing.T) {
assert.Empty(t, event.Request.Env)
}
// TestSentryScrub_ReplacesTheCapabilityPathWithTheRoutePattern is the
// regression test for the receiver URL: the entrypoint UUID is a write
// capability and may not reach the tracker, while the route it names
// must still be readable there.
func TestSentryScrub_ReplacesTheCapabilityPathWithTheRoutePattern(
t *testing.T,
) {
t.Parallel()
event := onlyEvent(t, sentryCase{
scrub: true,
panics: true,
request: sentryReceiverRequest,
}.capture(t))
assert.NotContains(
t, marshalEvent(t, event), sentryReceiverUUID,
)
assert.Equal(
t, "http://example.com/webhook/{uuid}", event.Request.URL,
)
}
// TestSentryScrub_KeepsTheRoutingContext checks the hook does not cost
// the debugging signal: the route, its scheme and host, the method and
// the metadata headers still identify what failed. On a static route
// the pattern is the path, so the URL is unchanged there.
// the debugging signal: the route, the method and the metadata headers
// still identify what failed.
func TestSentryScrub_KeepsTheRoutingContext(t *testing.T) {
t.Parallel()
event := onlyEvent(t, sentryCase{
scrub: true,
panics: true,
request: sentryLoginRequest,
}.capture(t))
event := captureThroughSentryHTTP(t, true)
require.NotNil(t, event.Request)
assert.Equal(
t, "http://example.com/pages/login", event.Request.URL,
)
assert.Contains(t, event.Request.URL, "/pages/login")
assert.Equal(t, http.MethodPost, event.Request.Method)
assert.Equal(
t,
@@ -349,127 +212,6 @@ func TestSentryScrub_KeepsTheRoutingContext(t *testing.T) {
)
}
// TestSentryScrub_RedactsTheTransactionDispatch covers the other hook.
// Span.doFinish captures with a nil hint, so BeforeSendTransaction
// gets one with no context and no request: the route pattern is out of
// reach and both the URL and the SDK-built transaction name have to
// fall back. Tracing is off in this service, so no transaction event
// is produced today; the hook is a floor against that changing.
func TestSentryScrub_RedactsTheTransactionDispatch(t *testing.T) {
t.Parallel()
events := sentryCase{
scrub: true,
tracing: true,
request: sentryReceiverRequest,
}.capture(t)
event := onlyEvent(t, events)
require.Equal(t, "transaction", event.Type)
assert.NotContains(
t, marshalEvent(t, event), sentryReceiverUUID,
)
assert.Equal(
t, "http://example.com/(redacted)", event.Request.URL,
)
assert.Equal(t, "POST /(redacted)", event.Transaction)
}
// TestSentryScrub_TransactionDispatchIsUnscrubbedWithoutTheHook pins
// that dispatch's premise the same way, since it is the one the
// service does not exercise today.
func TestSentryScrub_TransactionDispatchIsUnscrubbedWithoutTheHook(
t *testing.T,
) {
t.Parallel()
event := onlyEvent(t, sentryCase{
tracing: true,
request: sentryReceiverRequest,
}.capture(t))
require.Equal(t, "transaction", event.Type)
assert.Contains(t, event.Request.URL, sentryReceiverUUID)
assert.Contains(t, event.Transaction, sentryReceiverUUID)
}
// TestSentryScrub_FallsBackWithoutARoutePattern covers every way the
// pattern can be missing. None of them may fall back to the concrete
// path, and all of them keep the scheme, which is the CSRF TLS
// decision.
func TestSentryScrub_FallsBackWithoutARoutePattern(t *testing.T) {
t.Parallel()
concrete := "https://example.com/webhook/" + sentryReceiverUUID
// A request with no chi routing context on it at all, which is
// what an event captured outside the router would carry.
unrouted := httptest.NewRequestWithContext(
context.Background(), http.MethodPost, concrete, nil,
)
for name, hint := range map[string]*sentry.EventHint{
"no hint": nil,
"no context": {},
"no request": {Context: context.Background()},
"unrouted request": {
Context: context.WithValue(
context.Background(),
sentry.RequestContextKey,
unrouted,
),
},
} {
t.Run(name, func(t *testing.T) {
t.Parallel()
event := sentry.NewEvent()
event.Request = &sentry.Request{URL: concrete}
event.Transaction = "POST /webhook/" +
sentryReceiverUUID
scrubbed := server.ScrubSentryRequestForTest(
event, hint,
)
require.NotNil(t, scrubbed)
assert.Equal(
t,
"https://example.com/(redacted)",
scrubbed.Request.URL,
)
assert.Equal(
t, "POST /(redacted)", scrubbed.Transaction,
)
assert.NotContains(
t,
marshalEvent(t, scrubbed),
sentryReceiverUUID,
)
})
}
}
// TestSentryScrub_WithholdsUnparseableValues covers the shapes the
// rewrite cannot take apart. Withholding them whole is the safe
// answer, since nothing can be said about which part is a path.
func TestSentryScrub_WithholdsUnparseableValues(t *testing.T) {
t.Parallel()
event := sentry.NewEvent()
event.Request = &sentry.Request{
URL: "/webhook/" + sentryReceiverUUID,
}
event.Transaction = "/webhook/" + sentryReceiverUUID
scrubbed := server.ScrubSentryRequestForTest(event, nil)
require.NotNil(t, scrubbed)
assert.Equal(t, "(redacted)", scrubbed.Request.URL)
assert.Equal(t, "(redacted)", scrubbed.Transaction)
}
// TestSentryScrub_ToleratesEventsWithoutARequest covers the events the
// hook sees outside an HTTP handler, where no request is attached.
func TestSentryScrub_ToleratesEventsWithoutARequest(t *testing.T) {
@@ -481,6 +223,5 @@ func TestSentryScrub_ToleratesEventsWithoutARequest(t *testing.T) {
require.NotNil(t, scrubbed)
assert.Nil(t, scrubbed.Request)
assert.Empty(t, scrubbed.Transaction)
assert.Nil(t, server.ScrubSentryRequestForTest(nil, nil))
}

View File

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