sneak/webhooker
1
0
Fork 0
Code Issues 34 Pull Requests 1 Actions Packages Projects Releases Wiki Activity

Compare commits

base: sneak:next
Branches Tags
sneak:main sneak:next sneak:feat/receiver-rate-limit sneak:issue-70-log-target
..
compare: sneak:04678d07e373e8561abc8cc2dba665254a99faf6
Branches Tags
sneak:next sneak:main sneak:feat/receiver-rate-limit sneak:issue-70-log-target

1 Commits
next ... 04678d07e3

Author SHA1 Message Date
clawbot
04678d07e3 Route GORM's logger through slog and bound it (closes #178)
All checks were successful
check / check (push) Successful in 3m31s
Details 
GORM's default logger printed the fully interpolated SQL to standard
output on every statement that returned an error, including a plain
record-not-found. On /webhook/{uuid} and on the login form the
interpolated parameter is client-chosen and unbounded, so an
unauthenticated client sized the operator's log, one line per request,
at no level the operator could turn down.

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

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

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

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

internal/logfield gains the zero-headroom budget assertion and the
rune-splitting case: a value built from one rune must keep exactly
MaxBytes/EncodedBytes(r) of them, which a raw-byte budget fails and a
LessOrEqual on the budget cannot catch.

README: the ceiling now covers GORM, and the writers it does not cover
are re-derived by measuring rather than by reading. fx's console
logger and the Go runtime write to standard error. net/http's nil
ErrorLog is not a separate writer at all -- slog.SetDefault redirects
the log package's default logger into internal/logger's handler, so
those lines arrive on standard output at INFO. A handler panic reaches
that same path because chi's Recoverer crashes before writing, filed
as #187, and is the widest
line the service can write: measured at roughly 2,770 bytes against
the stated 2,560, a width that moves with the goroutine number and the
source paths in the stack, so only the fact that it exceeds the
ceiling is stated as invariant.
 2026-08-18 04:18:36 +00:00
13 changed files with 84 additions and 1410 deletions
Expand all files Collapse all files

127
README.md
View File

@@ -1143,11 +1143,10 @@ query, and in each of `User-Agent`, `Referer` and `X-Request-Id`,
including cases built from the characters the handlers escape, and including cases built from the characters the handlers escape, and
against the widest access log line the service can be made to write: a 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 5xx that keeps its concrete path while all three header fields are also
at their budget. Every case runs through both handlers at their budget. Every case runs through both handlers `internal/logger` can
`internal/logger` can select — the JSON one and the text one it installs select — the JSON one and the text one it installs on a tty — since the
on a tty — since the two do not escape alike and the ceiling is quoted two do not escape alike and the ceiling is quoted unqualified. Measured
unqualified. Measured over a real connection, the widest access log line over a real connection, the widest line is 1,972 bytes.
is 1,972 bytes.
Multiply that ceiling by the request rate to size log storage. Note 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: that the rate is not bounded by the limits above on every route:
@@ -1155,16 +1154,13 @@ that the rate is not bounded by the limits above on every route:
the multiplier is whatever the deployment will serve. the multiplier is whatever the deployment will serve.
**The same ceiling covers every other line the service writes through **The same ceiling covers every other line the service writes through
`slog` that carries text an unauthenticated client supplies**, with one `slog` that carries text an unauthenticated client supplies.** The
exception stated below it: the recovered-panic record, which carries a access log is not the only line a client can put its own text into, and
whole goroutine stack alongside its client-supplied fields and so has a budget that held for one line and not the others would be worse than
its own wider ceiling. The access log is not the only line a client can no stated budget at all. Every `slog` call an unauthenticated request
put its own text into, and a budget that held for one line and not the can reach spends the same per-field budget through `internal/logfield`,
others would be worse than no stated budget at all. Every `slog` call an and each carries strictly fewer client-supplied fields than the access
unauthenticated request can reach spends the same per-field budget log does, so none of them can be wider than it:
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 | | Log line | Level | Client-chosen value | Reachable unauthenticated |
| ------------------------------------------ | ------- | ------------------- | ----------------------------------------- | | ------------------------------------------ | ------- | ------------------- | ----------------------------------------- |
@@ -1220,11 +1216,10 @@ falsifying the ceiling.
**It covers GORM's statement logging as well.** GORM's own default **It covers GORM's statement logging as well.** GORM's own default
logger printed the fully interpolated SQL — parameters and all — to logger printed the fully interpolated SQL — parameters and all — to
standard output on every statement that returned an error, including a standard output on every statement that returned an error, including a
plain record-not-found, at a level no operator setting reached. Two of plain record-not-found, at a level no operator setting reached. Two of this service's lookups miss by design
this service's lookups miss by design on unauthenticated routes: the on unauthenticated routes: the entrypoint lookup behind
entrypoint lookup behind `/webhook/{uuid}` and the user lookup behind `/webhook/{uuid}` and the user lookup behind the login form, whose path
the login form, whose path segment and submitted username the client segment and submitted username the client picks outright. Every
picks outright. Every
`gorm.Open` in the service now installs the adapter in `gorm.Open` in the service now installs the adapter in
`internal/gormlog` instead. It writes through the same `slog` logger as `internal/gormlog` instead. It writes through the same `slog` logger as
everything else, so its lines take the level the operator set and the everything else, so its lines take the level the operator set and the
@@ -1283,54 +1278,23 @@ read as more than it is:
`internal/logger` calls `slog.SetDefault`, which redirects that logger `internal/logger` calls `slog.SetDefault`, which redirects that logger
into whichever handler it installed. Those lines therefore arrive on into whichever handler it installed. Those lines therefore arrive on
standard output, shaped like every other line, at `INFO`. They are not standard output, shaped like every other line, at `INFO`. They are not
truncated. A handler panic is no longer one of them: the recover truncated and they are not bounded by the ceiling: a handler panic
middleware below answers it and writes it as the bounded record arrives as one record carrying a whole goroutine stack, above the
described there instead, and `internal/server/recoverer_test.go` ceiling's 2,560 bytes — measured at roughly 2,770 in one checkout. The
requires that `http: panic serving` appear in neither of the process's exact width is not an invariant, since it moves with the goroutine
two streams when a panic is driven through the production router. The number and with the source paths baked into the stack; that it exceeds
one panic still handed back to `net/http` is `http.ErrAbortHandler`, the ceiling does not move. The value is the runtime's, not a client's.
which it special-cases and does not log at all. What is left on this - **A handler panic reaches that path** rather than the one it looks
path is `net/http`'s own diagnostics, whose values are the runtime's, like it should. `internal/server/routes.go` installs chi's
not a client's. `middleware.Recoverer` in front of every route, which is meant to
print the panic and its stack to standard error and answer 500. On the
Wider than that 2,560-byte ceiling, and stated separately rather than Go version this service builds against it does neither: chi v1.5.5's
carved out of it: the record a recovered panic produces. The recover stack pretty-printer looks for a `panic(0x` frame that the runtime no
middleware in `internal/middleware` answers `500` and writes one `ERROR` longer emits, walks past the end of its own slice, and panics before
record through `internal/logger` carrying the panic value, the stack and writing a byte. That second panic escapes to `net/http`, which drops
the request id — the same `request_id` the access log line for that the connection and reports it through the nil `ErrorLog` above.
request carries, which is how the two are joined. It replaced chi's Tracked separately in
`middleware.Recoverer`, which on a current Go release crashed inside its <https://git.eeqj.de/sneak/webhooker/issues/187>.
own stack pretty-printer: the connection was dropped rather than
answered, and what reached the operator described that crash rather than
the fault behind it.
That record is bounded the same way, in the same encoded bytes and
through the same `internal/logfield` budget: 512 for the panic value,
because a handler is free to build one out of the request, 128 for the
request id, which a client supplies outright through `X-Request-Id`,
and 8,192 for the stack, cut at its far end so that the panic site
survives a cut and `net/http`'s accept frames are what is lost. Net:
**at most 10,240 bytes, once per recovered panic** — 9,121 by the
arithmetic (523 + 8,203 + 139 + a 256-byte fixed portion), stated at
10,240 for headroom.
Those two numbers are the claim; the measurements below only
illustrate it. `internal/middleware/recoverer_test.go` drives all
three growable fields past their budgets on one record, over both
handlers, and measured 9,009 bytes on the JSON handler and
8,982–8,983 on the text one in one checkout. Neither is an invariant:
the stack's own content decides where its cut lands, so the figures
move by a byte or so between runs. The real case is far below both —
through the shipped middleware chain the whole record measures
roughly 3,960 bytes over a roughly 3,690-byte stack, taken by
`internal/server/recoverer_test.go` from the process's own file
descriptors while driving a panic through the production router over
a real server in a subprocess. That pair moves further still, since
`debug.Stack()` embeds absolute source paths and so depends on where
the tree is checked out: four checkouts have reported 3,959, 3,961,
3,984 and 4,026. What the tests assert is the ceiling, that every
client-supplied field was cut, and that the shipped chain's stack
arrived uncut — never the numbers.
Every limiter here — receiver, login, and password change — identifies Every limiter here — receiver, login, and password change — identifies
the client the same way, through one shared key function: the the client the same way, through one shared key function: the
@@ -1669,32 +1633,19 @@ to record results.
Applied to all routes in this order: Applied to all routes in this order:
1. **RequestID** — Generate unique request IDs (chi built-in) 1. **Recoverer** — Panic recovery (chi built-in)
2. **SecurityHeaders** — Production security headers on every response 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, (HSTS, X-Content-Type-Options, X-Frame-Options, CSP, Referrer-Policy,
Permissions-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) latency, remote IP, user agent, request ID)
4. **Metrics** — Prometheus HTTP metrics (if `METRICS_USERNAME` is set) 5. **Metrics** — Prometheus HTTP metrics (if `METRICS_USERNAME` is set)
5. **CORS** — Cross-origin resource sharing headers 6. **CORS** — Cross-origin resource sharing headers
6. **Timeout** — 60-second request timeout 7. **Timeout** — 60-second request timeout
7. **Recoverer** — Panic recovery: one `ERROR` record through
`internal/logger` and a `500`
8. **Sentry** — Error reporting to Sentry (if `SENTRY_DSN` is set; 8. **Sentry** — Error reporting to Sentry (if `SENTRY_DSN` is set;
configured with `Repanic: true` so panics still reach Recoverer) 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`, Additionally, form endpoints (`/pages`, `/user/*`, `/sources`,
`/source/*`) apply a **MaxBodySize** middleware that limits `/source/*`) apply a **MaxBodySize** middleware that limits
POST/PUT/PATCH request bodies to 1 MB. It is registered ahead of the POST/PUT/PATCH request bodies to 1 MB. It is registered ahead of the

20
REPO_POLICIES.md
View File

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

88
TODO.md
View File

@@ -24,84 +24,36 @@ event retention (#63), the database archiving target (#43), the admin
password change flow (#65), policy compliance (#6), pinned lint tooling password change flow (#65), policy compliance (#6), pinned lint tooling
(#55), and fail-loud configuration parsing (#80). (#55), and fail-loud configuration parsing (#80).
`next` holds the **complete 1.0.0 milestone**: every issue in it is `next` holds the 1.0.0 milestone less its final four issues (#176, #178,
closed, and it is verified green both by CI and by cache-defeated #186, #187 — all in review or held on merge order), and is verified
container runs (`docker build --no-cache-filter=lint green by cache-defeated container runs
--no-cache-filter=builder`). (`docker build --no-cache-filter=lint --no-cache-filter=builder`). The
CI status is not independently claimed here: a superseded run is
One caveat on reading a green check, narrower than it used to be. A recorded as `skipped` and still rolls up green, so a commit status on
docs-only commit deliberately replays from the layer cache (#119), so a `next` does not by itself evidence an executed check (#152). Before
green status on such a commit evidences a replay rather than an executed #119, a warm layer cache also let the gate report success without
run; a code commit invalidates the `COPY` layer and genuinely executes. executing anything, and replayed the previous build's console log so
Superseded runs are no longer the hazard they were: before #152 they the lie looked like a real run. Note: `TODO.md` was deliberately
were recorded as `skipped` and rolled up green, and before #119 a warm
layer cache let the gate report success without executing anything,
replaying the previous build's console log so the lie looked like a real
run. Both are fixed. Note: `TODO.md` was deliberately
deleted from this repo in f9a9569 (2026-03-01, #6); its content was deleted from this repo in f9a9569 (2026-03-01, #6); its content was
folded into the README TODO section, which this draft reconstructs as folded into the README TODO section, which this draft reconstructs as
of 2026-07-06. of 2026-07-06.
# Next Step # Next Step
Merge the milestone PR (#111) to `main` and tag 1.0.0 from it. The Land the last four 1.0.0 issues, then merge the milestone PR to `main`
milestone is empty and `next` is green; nothing else blocks the tag. and tag 1.0.0 from it. Merge order is forced by a real conflict on
`README.md` and `internal/middleware/middleware.go`: #186, then #176,
then #178, then #187.
Three items belong to the owner, none of them blocking. #150 was decided Two items belong to the owner, neither blocking the tag. #150 was
by the manager rather than left to stall the queue and is flagged on the decided by the manager rather than left to stall the queue and is
issue for reversal if that call was wrong. #112 (whether `Completed flagged on the issue for reversal if that call was wrong. #112 (whether
Steps` should exist at all, given it once conflicted on every unit) is `Completed Steps` should exist at all, given it once conflicted on every
unanswered; the provisional ruling in force is that issue branches do unit) is unanswered; the provisional ruling in force is that issue
not touch this file. #198 records that `make test` is past the org 20s branches do not touch this file.
target — 46s of test execution inside a 62.8s CI layer — and turns on
which quantity the 60s hard cap governs; it is scoped as the improvement
bug the 20-60s band requires, and should be milestoned instead if the
cap is read as covering the whole invocation.
After the tag, the largest open cluster is the unmilestoned follow-up
backlog these units generated: #183, #184, #185, #190, #191, #193 and
#198.
# Completed Steps # 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 - 2026-08-18 Send the chi route pattern to Sentry rather than the
concrete path. The receiver's path carries the entrypoint capability concrete path. The receiver's path carries the entrypoint capability
token, so every Sentry event from `/webhook/{uuid}` shipped a live token, so every Sentry event from `/webhook/{uuid}` shipped a live

2
internal/middleware/accesslog_test.go
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 // 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 // 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) longPath := "/boom/" + strings.Repeat("x", oversizedSegmentBytes)
wantLongURL := longPath[:maxFieldBytes] + truncationSuffix wantLongURL := longPath[:maxFieldBytes] + truncationSuffix

16
internal/middleware/middleware.go
View File

@@ -133,12 +133,16 @@ const (
// - The "log" delivery target, which exists to write the whole // - The "log" delivery target, which exists to write the whole
// inbound event to the log. Deliberate; see // inbound event to the log. Deliberate; see
// internal/delivery/target_log.go. // internal/delivery/target_log.go.
// - The record a recovered panic writes, which is not an access // - The widest line the service can write, which is neither an
// log line: its client-supplied fields are charged the same // access log line nor client-chosen. A handler panic arrives
// budgets, but it carries a whole goroutine stack as well and // through net/http's nil ErrorLog as one record carrying a
// is wider than this figure. It has its own stated ceiling, // whole goroutine stack, above this figure — measured at
// MaxPanicLogLineBytes in recoverer.go, and is written once // roughly 2,770 bytes. The exact width is not an invariant: it
// per recovered panic rather than once per request. // moves with the goroutine number and with the source paths
// baked into the stack. That it exceeds this ceiling does not
// move. The value is the runtime's, not a client's; see
// README.md and
// https://git.eeqj.de/sneak/webhooker/issues/187.
MaxAccessLogLineBytes = 2560 MaxAccessLogLineBytes = 2560
) )

209
internal/middleware/recoverer.go
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,
)
}

645
internal/middleware/recoverer_test.go
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))
}

37
internal/server/export_test.go
View File

@@ -54,40 +54,3 @@ func NewRouterForTest(
return s.router 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
}

285
internal/server/recoverer_test.go
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,
)
}

16
internal/server/routes.go
View File

@@ -51,6 +51,7 @@ func (s *Server) SetupRoutes() {
} }
func (s *Server) setupGlobalMiddleware() { func (s *Server) setupGlobalMiddleware() {
s.router.Use(middleware.Recoverer)
s.router.Use(middleware.RequestID) s.router.Use(middleware.RequestID)
s.router.Use(s.mw.SecurityHeaders()) s.router.Use(s.mw.SecurityHeaders())
s.router.Use(s.mw.Logging()) s.router.Use(s.mw.Logging())
@@ -63,21 +64,8 @@ func (s *Server) setupGlobalMiddleware() {
s.router.Use(s.mw.CORS()) s.router.Use(s.mw.CORS())
s.router.Use(middleware.Timeout(requestTimeout)) 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 // Sentry error reporting (if SENTRY_DSN is set). Repanic is
// true so panics still bubble up to the Recoverer middleware // true so panics still bubble up to the Recoverer middleware.
// registered immediately above.
if s.sentryEnabled { if s.sentryEnabled {
sentryHandler := sentryhttp.New(sentryhttp.Options{ sentryHandler := sentryhttp.New(sentryhttp.Options{
Repanic: true, Repanic: true,

13
internal/server/routes_test.go
View File

@@ -52,15 +52,6 @@ type testEnv struct {
sess *session.Session sess *session.Session
db *database.Database db *database.Database
dbMgr *database.WebhookDBManager 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 // newTestEnv wires the dependency graph with fx and builds the
@@ -109,10 +100,6 @@ func newTestEnv(t *testing.T) *testEnv {
sess: sess, sess: sess,
db: db, db: db,
dbMgr: dbMgr, dbMgr: dbMgr,
log: log,
cfg: cfg,
mw: mw,
hnd: hnd,
} }
} }

12
internal/server/sentry_test.go
View File

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

24
script/test
View File

@@ -1,34 +1,12 @@
#!/bin/sh #!/bin/sh
# script/test: run the test suite. # 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 set -eu
ROOT="$(cd "$(dirname "$0")/.." && pwd -P)" ROOT="$(cd "$(dirname "$0")/.." && pwd -P)"
main() { main() {
cd "$ROOT" cd "$ROOT"
go test -v -race -timeout 90s ./... go test -v -race -timeout 30s ./...
} }
main "$@" main "$@"