Compare commits
5 Commits
65148ab678
...
next
| Author | SHA1 | Date | |
|---|---|---|---|
| aa463213f5 | |||
| 1326f82a0b | |||
| a55b6f4e55 | |||
| 33e4fa4faa | |||
| 0c64c411cc |
162
README.md
162
README.md
@@ -1141,12 +1141,13 @@ 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 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.
|
||||
against the widest access log line the service can be made to write: a
|
||||
5xx that keeps its concrete path while all three header fields are also
|
||||
at their budget. Every case runs through both handlers
|
||||
`internal/logger` can select — the JSON one and the text one it installs
|
||||
on a tty — since the two do not escape alike and the ceiling is quoted
|
||||
unqualified. Measured over a real connection, the widest access log line
|
||||
is 1,972 bytes.
|
||||
|
||||
Multiply that ceiling by the request rate to size log storage. Note
|
||||
that the rate is not bounded by the limits above on every route:
|
||||
@@ -1154,13 +1155,16 @@ that the rate is not bounded by the limits above on every route:
|
||||
the multiplier is whatever the deployment will serve.
|
||||
|
||||
**The same ceiling covers every other line the service writes through
|
||||
`slog` that carries text an unauthenticated client supplies.** The
|
||||
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**, with one
|
||||
exception stated below it: the recovered-panic record, which carries a
|
||||
whole goroutine stack alongside its client-supplied fields and so has
|
||||
its own wider ceiling. The access log is not the only line a client can
|
||||
put its own text into, and a budget that held for one line and not the
|
||||
others would be worse than no stated budget at all. Every `slog` call an
|
||||
unauthenticated request can reach spends the same per-field budget
|
||||
through `internal/logfield`, and each carries strictly fewer
|
||||
client-supplied fields than the access log does, so none of them can be
|
||||
wider than it:
|
||||
|
||||
| Log line | Level | Client-chosen value | Reachable unauthenticated |
|
||||
| ------------------------------------------ | ------- | ------------------- | ----------------------------------------- |
|
||||
@@ -1213,6 +1217,33 @@ 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:
|
||||
|
||||
@@ -1236,16 +1267,70 @@ 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.
|
||||
- **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.
|
||||
- **Two writers that do not go through `internal/logger` at all**, both
|
||||
on standard error. `fx` prints the dependency graph and the lifecycle
|
||||
hooks through its default console logger at startup and shutdown —
|
||||
nothing calls `fx.WithLogger`, and `fx.New` builds that logger over
|
||||
`os.Stderr`. The Go runtime writes a panic or a fatal error itself; a
|
||||
panic in a background worker rather than in a request handler is the
|
||||
case that reaches it, since nothing recovers those. Neither carries a
|
||||
client-chosen value at a client-chosen length: the five `panic` calls
|
||||
in this service are invariant guards over constants and over
|
||||
`crypto/rand`.
|
||||
- **`net/http`'s own faults**, which are _not_ a separate writer.
|
||||
`internal/server/http.go` builds its server with a nil `ErrorLog`, so
|
||||
`net/http` falls back to the `log` package's default logger — and
|
||||
`internal/logger` calls `slog.SetDefault`, which redirects that logger
|
||||
into whichever handler it installed. Those lines therefore arrive on
|
||||
standard output, shaped like every other line, at `INFO`. They are not
|
||||
truncated. A handler panic is no longer one of them: the recover
|
||||
middleware below answers it and writes it as the bounded record
|
||||
described there instead, and `internal/server/recoverer_test.go`
|
||||
requires that `http: panic serving` appear in neither of the process's
|
||||
two streams when a panic is driven through the production router. The
|
||||
one panic still handed back to `net/http` is `http.ErrAbortHandler`,
|
||||
which it special-cases and does not log at all. What is left on this
|
||||
path is `net/http`'s own diagnostics, whose values are the runtime's,
|
||||
not a client's.
|
||||
|
||||
Wider than that 2,560-byte ceiling, and stated separately rather than
|
||||
carved out of it: the record a recovered panic produces. The recover
|
||||
middleware in `internal/middleware` answers `500` and writes one `ERROR`
|
||||
record through `internal/logger` carrying the panic value, the stack and
|
||||
the request id — the same `request_id` the access log line for that
|
||||
request carries, which is how the two are joined. It replaced chi's
|
||||
`middleware.Recoverer`, which on a current Go release crashed inside its
|
||||
own stack pretty-printer: the connection was dropped rather than
|
||||
answered, and what reached the operator described that crash rather than
|
||||
the fault behind it.
|
||||
|
||||
That record is bounded the same way, in the same encoded bytes and
|
||||
through the same `internal/logfield` budget: 512 for the panic value,
|
||||
because a handler is free to build one out of the request, 128 for the
|
||||
request id, which a client supplies outright through `X-Request-Id`,
|
||||
and 8,192 for the stack, cut at its far end so that the panic site
|
||||
survives a cut and `net/http`'s accept frames are what is lost. Net:
|
||||
**at most 10,240 bytes, once per recovered panic** — 9,121 by the
|
||||
arithmetic (523 + 8,203 + 139 + a 256-byte fixed portion), stated at
|
||||
10,240 for headroom.
|
||||
|
||||
Those two numbers are the claim; the measurements below only
|
||||
illustrate it. `internal/middleware/recoverer_test.go` drives all
|
||||
three growable fields past their budgets on one record, over both
|
||||
handlers, and measured 9,009 bytes on the JSON handler and
|
||||
8,982–8,983 on the text one in one checkout. Neither is an invariant:
|
||||
the stack's own content decides where its cut lands, so the figures
|
||||
move by a byte or so between runs. The real case is far below both —
|
||||
through the shipped middleware chain the whole record measures
|
||||
roughly 3,960 bytes over a roughly 3,690-byte stack, taken by
|
||||
`internal/server/recoverer_test.go` from the process's own file
|
||||
descriptors while driving a panic through the production router over
|
||||
a real server in a subprocess. That pair moves further still, since
|
||||
`debug.Stack()` embeds absolute source paths and so depends on where
|
||||
the tree is checked out: four checkouts have reported 3,959, 3,961,
|
||||
3,984 and 4,026. What the tests assert is the ceiling, that every
|
||||
client-supplied field was cut, and that the shipped chain's stack
|
||||
arrived uncut — never the numbers.
|
||||
|
||||
Every limiter here — receiver, login, and password change — identifies
|
||||
the client the same way, through one shared key function: the
|
||||
@@ -1485,6 +1570,10 @@ webhooker/
|
||||
│ │ └── webhook_db_manager.go # Per-webhook DB lifecycle manager
|
||||
│ ├── globals/
|
||||
│ │ └── globals.go # Build-time variables (appname, version, arch)
|
||||
│ ├── gormlog/
|
||||
│ │ └── gormlog.go # GORM's logger.Interface on top of slog, bounded
|
||||
│ ├── logfield/
|
||||
│ │ └── logfield.go # Encoded-byte budget for client-supplied log values
|
||||
│ ├── delivery/
|
||||
│ │ ├── engine.go # Event-driven delivery engine (channel + timer based)
|
||||
│ │ ├── circuit_breaker.go # Per-target circuit breaker for http/slack targets with retries
|
||||
@@ -1580,19 +1669,32 @@ to record results.
|
||||
|
||||
Applied to all routes in this order:
|
||||
|
||||
1. **Recoverer** — Panic recovery (chi built-in)
|
||||
2. **RequestID** — Generate unique request IDs (chi built-in)
|
||||
3. **SecurityHeaders** — Production security headers on every response
|
||||
1. **RequestID** — Generate unique request IDs (chi built-in)
|
||||
2. **SecurityHeaders** — Production security headers on every response
|
||||
(HSTS, X-Content-Type-Options, X-Frame-Options, CSP, Referrer-Policy,
|
||||
Permissions-Policy)
|
||||
4. **Logging** — Structured request logging (method, URL, status,
|
||||
3. **Logging** — Structured request logging (method, URL, status,
|
||||
latency, remote IP, user agent, request ID)
|
||||
5. **Metrics** — Prometheus HTTP metrics (if `METRICS_USERNAME` is set)
|
||||
6. **CORS** — Cross-origin resource sharing headers
|
||||
7. **Timeout** — 60-second request timeout
|
||||
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`
|
||||
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
|
||||
|
||||
@@ -1,6 +1,6 @@
|
||||
---
|
||||
title: Repository Policies
|
||||
last_modified: 2026-07-06
|
||||
last_modified: 2026-08-07
|
||||
---
|
||||
|
||||
This document covers repository structure, tooling, and workflow standards. Code
|
||||
@@ -189,8 +189,13 @@ style conventions are in separate documents:
|
||||
module under test to verify it compiles/parses. There is no excuse for
|
||||
`make test` to be a no-op.
|
||||
|
||||
- `make test` must complete in under 20 seconds. Add a 30-second timeout in the
|
||||
Makefile.
|
||||
- `make test` must complete in under 60 seconds. That is the hard cap, and a
|
||||
suite that exceeds it fails. Under 20 seconds is the target. A suite between
|
||||
20 and 60 seconds is still green, but the overage must be filed as an
|
||||
improvement bug against that repo. Add a 90-second timeout to the test
|
||||
invocation in the Makefile (`go test -timeout 90s`). The backstop deliberately
|
||||
sits above the hard cap so that it catches a genuinely hung test rather than a
|
||||
merely slow one.
|
||||
|
||||
- **`make test` should use the conditional verbose rerun pattern.** Run tests
|
||||
without `-v` (verbose) first. If tests fail, automatically rerun with `-v` to
|
||||
@@ -209,9 +214,9 @@ style conventions are in separate documents:
|
||||
|
||||
```makefile
|
||||
test:
|
||||
@go test -timeout 30s -race -cover ./... || \
|
||||
@go test -timeout 90s -race -cover ./... || \
|
||||
{ echo "--- Rerunning with -v for details ---"; \
|
||||
go test -timeout 30s -race -v ./...; exit 1; }
|
||||
go test -timeout 90s -race -v ./...; exit 1; }
|
||||
```
|
||||
|
||||
Python example:
|
||||
@@ -260,7 +265,10 @@ style conventions are in separate documents:
|
||||
|
||||
- `.golangci.yml` is standardized and must _NEVER_ be modified by an agent, only
|
||||
manually by the user. Fetch from
|
||||
`https://git.eeqj.de/sneak/prompts/raw/branch/main/.golangci.yml`.
|
||||
`https://git.eeqj.de/sneak/prompts/raw/branch/main/.golangci.yml`. The
|
||||
canonical golangci-lint version is v2.12.2 (released 2026-05-06), installed
|
||||
commit-pinned via
|
||||
`go install github.com/golangci/golangci-lint/v2/cmd/golangci-lint@c0d3ddc9cf3faa61a4e378e879ece580256d76e5`.
|
||||
|
||||
- When pinning images or packages by hash, add a comment above the reference
|
||||
with the version and date (YYYY-MM-DD).
|
||||
|
||||
88
TODO.md
88
TODO.md
@@ -24,36 +24,84 @@ event retention (#63), the database archiving target (#43), the admin
|
||||
password change flow (#65), policy compliance (#6), pinned lint tooling
|
||||
(#55), and fail-loud configuration parsing (#80).
|
||||
|
||||
`next` holds the 1.0.0 milestone less its final four issues (#176, #178,
|
||||
#186, #187 — all in review or held on merge order), and is verified
|
||||
green by cache-defeated container runs
|
||||
(`docker build --no-cache-filter=lint --no-cache-filter=builder`). The
|
||||
CI status is not independently claimed here: a superseded run is
|
||||
recorded as `skipped` and still rolls up green, so a commit status on
|
||||
`next` does not by itself evidence an executed check (#152). Before
|
||||
#119, a warm layer cache also let the gate report success without
|
||||
executing anything, and replayed the previous build's console log so
|
||||
the lie looked like a real run. Note: `TODO.md` was deliberately
|
||||
`next` holds the **complete 1.0.0 milestone**: every issue in it is
|
||||
closed, and it is verified green both by CI and by cache-defeated
|
||||
container runs (`docker build --no-cache-filter=lint
|
||||
--no-cache-filter=builder`).
|
||||
|
||||
One caveat on reading a green check, narrower than it used to be. A
|
||||
docs-only commit deliberately replays from the layer cache (#119), so a
|
||||
green status on such a commit evidences a replay rather than an executed
|
||||
run; a code commit invalidates the `COPY` layer and genuinely executes.
|
||||
Superseded runs are no longer the hazard they were: before #152 they
|
||||
were recorded as `skipped` and rolled up green, and before #119 a warm
|
||||
layer cache let the gate report success without executing anything,
|
||||
replaying the previous build's console log so the lie looked like a real
|
||||
run. Both are fixed. Note: `TODO.md` was deliberately
|
||||
deleted from this repo in f9a9569 (2026-03-01, #6); its content was
|
||||
folded into the README TODO section, which this draft reconstructs as
|
||||
of 2026-07-06.
|
||||
|
||||
# Next Step
|
||||
|
||||
Land the last four 1.0.0 issues, then merge the milestone PR to `main`
|
||||
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.
|
||||
Merge the milestone PR (#111) to `main` and tag 1.0.0 from it. The
|
||||
milestone is empty and `next` is green; nothing else blocks the tag.
|
||||
|
||||
Two items belong to the owner, neither blocking the tag. #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.
|
||||
Three items belong to the owner, none of them blocking. #150 was decided
|
||||
by the manager rather than left to stall the queue and is flagged on the
|
||||
issue for reversal if that call was wrong. #112 (whether `Completed
|
||||
Steps` should exist at all, given it once conflicted on every unit) is
|
||||
unanswered; the provisional ruling in force is that issue branches do
|
||||
not touch this file. #198 records that `make test` is past the org 20s
|
||||
target — 46s of test execution inside a 62.8s CI layer — and turns on
|
||||
which quantity the 60s hard cap governs; it is scoped as the improvement
|
||||
bug the 20-60s band requires, and should be milestoned instead if the
|
||||
cap is read as covering the whole invocation.
|
||||
|
||||
After the tag, the largest open cluster is the unmilestoned follow-up
|
||||
backlog these units generated: #183, #184, #185, #190, #191, #193 and
|
||||
#198.
|
||||
|
||||
# Completed Steps
|
||||
|
||||
- 2026-08-18 Raise `script/test`'s per-package timeout from 30s to 90s,
|
||||
matching the org-wide backstop. `go test` applies `-timeout` per
|
||||
package, and `internal/handlers` had grown past the old budget: a
|
||||
cache-defeated build failed outright at `GOMAXPROCS=4`, and every run
|
||||
under deliberate host load breached 30s. The measurement table lives
|
||||
in the script (#194)
|
||||
- 2026-08-18 Re-sync `REPO_POLICIES.md` from `prompts`. The local copy
|
||||
was stale and still mandated a 20s test target with a 30s timeout,
|
||||
which the org replaced with a 60s cap and a 90s backstop. A synced
|
||||
copy is not a source; reading it as one nearly produced a PR against
|
||||
`prompts` proposing a change already merged there (#196)
|
||||
- 2026-08-18 Report handler panics through the logger and answer 500.
|
||||
chi v1.5.5's `Recoverer` scans for a `panic(0x` frame the runtime no
|
||||
longer emits, then indexes `pkg[-1:]`, so it panicked inside its own
|
||||
stack printer before writing a byte: the recovery never ran, the
|
||||
client got a dropped connection instead of a 500, and the original
|
||||
panic was lost. A local middleware replaces it, bounded by
|
||||
`MaxPanicLogLineBytes` (#187)
|
||||
- 2026-08-18 Route GORM's logger through `slog` and bound it. Every
|
||||
`gorm.Open` left `logger.Default` in place at `Warn` with
|
||||
`IgnoreRecordNotFoundError` false, so **every record-not-found
|
||||
printed the fully interpolated SQL to stdout** — including the
|
||||
client-chosen path on `/webhook/{uuid}` and the submitted username on
|
||||
the login form, at no level the operator set and outside
|
||||
`internal/logger` entirely. Three call sites, not the two the issue
|
||||
named (#178)
|
||||
- 2026-08-18 Bound every `slog` line against client-chosen text. Eight
|
||||
sites reachable unauthenticated, found by reading every `slog` call in
|
||||
the tree rather than only the one reported; the budget moved to a
|
||||
shared `internal/logfield` so no second truncation exists. `DEBUG`
|
||||
being off by default is not a bound and is not treated as one (#176)
|
||||
- 2026-08-18 Stop a slow host turning a login-guard test into a
|
||||
segfault. A non-fatal `assert` on an acquire result was dereferenced
|
||||
on the next line, so one timing miss killed the whole
|
||||
`internal/middleware` binary and reddened CI for unrelated PRs. The
|
||||
fix also removed a real production race — `acquire` could shed a
|
||||
request with a slot standing free, because Go picks uniformly among
|
||||
ready `select` cases (#186)
|
||||
- 2026-08-18 Send the chi route pattern to Sentry rather than the
|
||||
concrete path. The receiver's path carries the entrypoint capability
|
||||
token, so every Sentry event from `/webhook/{uuid}` shipped a live
|
||||
|
||||
@@ -17,6 +17,7 @@ import (
|
||||
"gorm.io/gorm"
|
||||
_ "modernc.org/sqlite" // Pure Go SQLite driver
|
||||
"sneak.berlin/go/webhooker/internal/config"
|
||||
"sneak.berlin/go/webhooker/internal/gormlog"
|
||||
"sneak.berlin/go/webhooker/internal/logger"
|
||||
)
|
||||
|
||||
@@ -155,7 +156,10 @@ func (d *Database) connect() error {
|
||||
// Then use it with GORM
|
||||
db, err := gorm.Open(sqlite.Dialector{
|
||||
Conn: sqlDB,
|
||||
}, &gorm.Config{})
|
||||
}, &gorm.Config{
|
||||
// Never leave this at GORM's default. See internal/gormlog.
|
||||
Logger: gormlog.New(d.log),
|
||||
})
|
||||
if err != nil {
|
||||
d.log.Error(
|
||||
"failed to connect to database",
|
||||
|
||||
@@ -14,6 +14,7 @@ import (
|
||||
"gorm.io/driver/sqlite"
|
||||
"gorm.io/gorm"
|
||||
"sneak.berlin/go/webhooker/internal/config"
|
||||
"sneak.berlin/go/webhooker/internal/gormlog"
|
||||
"sneak.berlin/go/webhooker/internal/logger"
|
||||
)
|
||||
|
||||
@@ -248,7 +249,10 @@ func (m *WebhookDBManager) openDB(
|
||||
|
||||
db, err := gorm.Open(sqlite.Dialector{
|
||||
Conn: sqlDB,
|
||||
}, &gorm.Config{})
|
||||
}, &gorm.Config{
|
||||
// Never leave this at GORM's default. See internal/gormlog.
|
||||
Logger: gormlog.New(m.log),
|
||||
})
|
||||
if err != nil {
|
||||
_ = sqlDB.Close()
|
||||
|
||||
|
||||
@@ -12,6 +12,7 @@ import (
|
||||
|
||||
"gorm.io/driver/sqlite"
|
||||
"gorm.io/gorm"
|
||||
"sneak.berlin/go/webhooker/internal/gormlog"
|
||||
)
|
||||
|
||||
// archiveExpiryNever is the expiry sentinel (and default) that
|
||||
@@ -282,7 +283,11 @@ func (w *archiveWriter) openMode(
|
||||
}
|
||||
|
||||
gdb, err := gorm.Open(
|
||||
sqlite.Dialector{Conn: sqlDB}, &gorm.Config{},
|
||||
sqlite.Dialector{Conn: sqlDB}, &gorm.Config{
|
||||
// Never leave this at GORM's default. See
|
||||
// internal/gormlog.
|
||||
Logger: gormlog.New(w.log),
|
||||
},
|
||||
)
|
||||
if err != nil {
|
||||
_ = sqlDB.Close()
|
||||
|
||||
155
internal/delivery/target_database_archive_gormlog_test.go
Normal file
155
internal/delivery/target_database_archive_gormlog_test.go
Normal file
@@ -0,0 +1,155 @@
|
||||
package delivery_test
|
||||
|
||||
import (
|
||||
"bytes"
|
||||
"log"
|
||||
"log/slog"
|
||||
"path/filepath"
|
||||
"strings"
|
||||
"sync"
|
||||
"testing"
|
||||
"time"
|
||||
|
||||
"github.com/stretchr/testify/assert"
|
||||
"github.com/stretchr/testify/require"
|
||||
"gorm.io/gorm"
|
||||
gormlogger "gorm.io/gorm/logger"
|
||||
"sneak.berlin/go/webhooker/internal/delivery"
|
||||
"sneak.berlin/go/webhooker/internal/middleware"
|
||||
)
|
||||
|
||||
// archiveGORMTailMarker sits at the far end of the value this file
|
||||
// drives into an archive lookup. Its presence in a log line means the
|
||||
// whole value reached the log, so nothing truncated it.
|
||||
const archiveGORMTailMarker = "ENDOFCLIENTVALUE"
|
||||
|
||||
// archiveGORMFillBytes is how much text the lookup carries. It is far
|
||||
// past every budget in play.
|
||||
const archiveGORMFillBytes = 8 << 10
|
||||
|
||||
// gormDefaultBuf collects what GORM's package-level default logger
|
||||
// writes, if anything reaches it.
|
||||
type gormDefaultBuf struct {
|
||||
mu sync.Mutex
|
||||
b bytes.Buffer
|
||||
}
|
||||
|
||||
func (g *gormDefaultBuf) Write(p []byte) (int, error) {
|
||||
g.mu.Lock()
|
||||
defer g.mu.Unlock()
|
||||
|
||||
return g.b.Write(p)
|
||||
}
|
||||
|
||||
func (g *gormDefaultBuf) String() string {
|
||||
g.mu.Lock()
|
||||
defer g.mu.Unlock()
|
||||
|
||||
return g.b.String()
|
||||
}
|
||||
|
||||
// captureArchiveGORMDefault replaces GORM's package-level default
|
||||
// logger with one configured exactly as GORM configures its own,
|
||||
// writing to a buffer.
|
||||
//
|
||||
// This duplicates the detector in internal/handlers rather than
|
||||
// sharing it: a test helper cannot cross a package's test boundary
|
||||
// without exporting production code to carry it, and a logging
|
||||
// detector is not worth a production symbol. What it detects is the
|
||||
// third gorm.Open in this service, at
|
||||
// internal/delivery/target_database_archive.go — the archive writer,
|
||||
// whose type is unexported, so nothing outside this package can drive
|
||||
// it.
|
||||
func captureArchiveGORMDefault(t *testing.T) *gormDefaultBuf {
|
||||
t.Helper()
|
||||
|
||||
buf := &gormDefaultBuf{}
|
||||
orig := gormlogger.Default
|
||||
|
||||
gormlogger.Default = gormlogger.New(
|
||||
log.New(buf, "", log.LstdFlags),
|
||||
gormlogger.Config{
|
||||
SlowThreshold: 200 * time.Millisecond,
|
||||
LogLevel: gormlogger.Warn,
|
||||
IgnoreRecordNotFoundError: false,
|
||||
Colorful: false,
|
||||
},
|
||||
)
|
||||
|
||||
t.Cleanup(func() { gormlogger.Default = orig })
|
||||
|
||||
return buf
|
||||
}
|
||||
|
||||
// TestArchiveWriter_NeverUsesGORMsDefaultLogger pins the archive
|
||||
// writer's gorm.Open to the adapter.
|
||||
//
|
||||
// Restore a bare &gorm.Config{} at
|
||||
// internal/delivery/target_database_archive.go and this fails: the
|
||||
// default logger prints the fully interpolated SELECT on every
|
||||
// ErrRecordNotFound, so the client-chosen event id below arrives whole
|
||||
// and unbounded on stdout, answering to no level the operator set.
|
||||
//
|
||||
// Not parallel: gormlogger.Default is process-global. Go runs every
|
||||
// non-parallel top-level test to completion before it resumes the
|
||||
// parallel ones.
|
||||
//
|
||||
//nolint:paralleltest // Deliberately sequential; see above.
|
||||
func TestArchiveWriter_NeverUsesGORMsDefaultLogger(t *testing.T) {
|
||||
var captured bytes.Buffer
|
||||
|
||||
gormDefault := captureArchiveGORMDefault(t)
|
||||
|
||||
w := delivery.NewExportArchiveWriter(
|
||||
filepath.Join(t.TempDir(), "archive.db"),
|
||||
slog.New(slog.NewTextHandler(
|
||||
&captured, &slog.HandlerOptions{Level: slog.LevelDebug},
|
||||
)),
|
||||
0,
|
||||
)
|
||||
|
||||
require.NoError(t, w.Open(0))
|
||||
|
||||
t.Cleanup(w.Evict)
|
||||
|
||||
// A lookup that misses, carrying a value the size of an inbound
|
||||
// event id. Under the default logger this is the line that gets
|
||||
// interpolated and printed.
|
||||
value := strings.Repeat("\x01", archiveGORMFillBytes) +
|
||||
archiveGORMTailMarker
|
||||
|
||||
var row delivery.ExportArchivedEvent
|
||||
|
||||
err := w.DB().Where("event_id = ?", value).First(&row).Error
|
||||
require.ErrorIs(t, err, gorm.ErrRecordNotFound)
|
||||
|
||||
got := gormDefault.String()
|
||||
assert.Empty(
|
||||
t, got,
|
||||
"GORM's default logger wrote %d bytes, so the archive "+
|
||||
"writer's gorm.Open is back on a bare &gorm.Config{}; "+
|
||||
"the first of them: %s",
|
||||
len(got), got[:min(len(got), 300)],
|
||||
)
|
||||
|
||||
// The adapter drops a miss, so this should be silent too — and
|
||||
// whatever it does write stays inside the stated ceiling.
|
||||
out := captured.String()
|
||||
|
||||
assert.NotContains(
|
||||
t, out, archiveGORMTailMarker,
|
||||
"the far end of the client-chosen value reached the log",
|
||||
)
|
||||
|
||||
for line := range strings.SplitSeq(strings.TrimRight(out, "\n"), "\n") {
|
||||
if line == "" {
|
||||
continue
|
||||
}
|
||||
|
||||
assert.LessOrEqual(
|
||||
t, len(line), middleware.MaxAccessLogLineBytes,
|
||||
"log line exceeded its bound: %s",
|
||||
line[:min(len(line), 300)],
|
||||
)
|
||||
}
|
||||
}
|
||||
17
internal/gormlog/export_test.go
Normal file
17
internal/gormlog/export_test.go
Normal file
@@ -0,0 +1,17 @@
|
||||
package gormlog
|
||||
|
||||
import (
|
||||
"log/slog"
|
||||
"time"
|
||||
)
|
||||
|
||||
// ExportNewWithSlowThreshold builds a Logger whose slow-statement
|
||||
// threshold is d rather than DefaultSlowThreshold, so a test can pin
|
||||
// which arm of Trace it is exercising instead of racing the clock on a
|
||||
// loaded machine. The threshold is set at construction, like every
|
||||
// other field, so the type's concurrency guarantee still holds.
|
||||
func ExportNewWithSlowThreshold(
|
||||
log *slog.Logger, d time.Duration,
|
||||
) *Logger {
|
||||
return &Logger{log: log, slowThreshold: d}
|
||||
}
|
||||
168
internal/gormlog/gormlog.go
Normal file
168
internal/gormlog/gormlog.go
Normal file
@@ -0,0 +1,168 @@
|
||||
// Package gormlog adapts GORM's logger onto the service's slog
|
||||
// logger.
|
||||
//
|
||||
// GORM's own default logger is not usable here. It is built at package
|
||||
// init with log.New(os.Stdout, ...) at LogLevel Warn with
|
||||
// IgnoreRecordNotFoundError false, so it writes the fully interpolated
|
||||
// SQL — parameters and all — for every statement that returns an
|
||||
// error, including gorm.ErrRecordNotFound. Two of this service's
|
||||
// lookups miss by design on unauthenticated routes: the entrypoint
|
||||
// lookup on /webhook/{uuid}, whose path segment the client picks
|
||||
// outright, and the user lookup behind the login form, whose username
|
||||
// the client picks outright. Under the default logger each of those
|
||||
// misses printed an unbounded, attacker-chosen string, at no level the
|
||||
// operator can turn down, past every handler internal/logger installs.
|
||||
//
|
||||
// This adapter fixes all three properties at once: the lines get a
|
||||
// level the operator controls, they are shaped by whichever handler
|
||||
// internal/logger selected, and every value a client can influence is
|
||||
// spent through logfield.Truncate.
|
||||
package gormlog
|
||||
|
||||
import (
|
||||
"context"
|
||||
"errors"
|
||||
"fmt"
|
||||
"log/slog"
|
||||
"time"
|
||||
|
||||
gormlogger "gorm.io/gorm/logger"
|
||||
"sneak.berlin/go/webhooker/internal/logfield"
|
||||
)
|
||||
|
||||
// DefaultSlowThreshold is the duration at or above which a statement
|
||||
// is logged as slow. It is GORM's own default, kept deliberately: slow
|
||||
// SQL is the one thing GORM's logger reports that nothing else in this
|
||||
// service does, so silencing the logger outright would have cost real
|
||||
// observability to fix a log-volume defect.
|
||||
const DefaultSlowThreshold = 200 * time.Millisecond
|
||||
|
||||
// Logger implements gormlogger.Interface on top of an *slog.Logger.
|
||||
//
|
||||
// It is safe for concurrent use: every field is set at construction
|
||||
// and never written again.
|
||||
type Logger struct {
|
||||
log *slog.Logger
|
||||
slowThreshold time.Duration
|
||||
}
|
||||
|
||||
// Interface compliance is asserted here rather than discovered at the
|
||||
// gorm.Open call sites.
|
||||
var _ gormlogger.Interface = (*Logger)(nil)
|
||||
|
||||
// New returns a GORM logger that writes through log.
|
||||
func New(log *slog.Logger) *Logger {
|
||||
return &Logger{
|
||||
log: log,
|
||||
slowThreshold: DefaultSlowThreshold,
|
||||
}
|
||||
}
|
||||
|
||||
// LogMode returns the logger unchanged.
|
||||
//
|
||||
// GORM's LogLevel is deliberately not honoured. Level is the operator's
|
||||
// decision and it is expressed once, through LOG_LEVEL and the
|
||||
// slog.LevelVar internal/logger holds; a second level knob inside the
|
||||
// database layer could only disagree with it. The mapping from GORM's
|
||||
// four categories onto slog levels is fixed in Trace below.
|
||||
//
|
||||
//nolint:ireturn // The interface return is GORM's signature, not a choice.
|
||||
func (l *Logger) LogMode(gormlogger.LogLevel) gormlogger.Interface {
|
||||
return l
|
||||
}
|
||||
|
||||
// Info logs one of GORM's own informational messages.
|
||||
func (l *Logger) Info(
|
||||
ctx context.Context, msg string, data ...any,
|
||||
) {
|
||||
l.log.InfoContext(ctx, "gorm", "message", format(msg, data...))
|
||||
}
|
||||
|
||||
// Warn logs one of GORM's own warnings.
|
||||
func (l *Logger) Warn(
|
||||
ctx context.Context, msg string, data ...any,
|
||||
) {
|
||||
l.log.WarnContext(ctx, "gorm", "message", format(msg, data...))
|
||||
}
|
||||
|
||||
// Error logs one of GORM's own errors.
|
||||
func (l *Logger) Error(
|
||||
ctx context.Context, msg string, data ...any,
|
||||
) {
|
||||
l.log.ErrorContext(ctx, "gorm", "message", format(msg, data...))
|
||||
}
|
||||
|
||||
// Trace reports the outcome of a single statement. GORM calls it for
|
||||
// every statement it runs, so the cheap paths stay cheap: fc()
|
||||
// renders the interpolated SQL and is called only on a branch that
|
||||
// will actually emit.
|
||||
//
|
||||
// The arms are ordered exactly as GORM's own Trace orders them —
|
||||
// non-record-not-found error, then slow, then the routine case — so
|
||||
// that a statement which both misses and runs slow is still reported
|
||||
// as slow. A miss is the likeliest statement to be slow, since it is
|
||||
// the one that scans without finding a row, and ordering the drop
|
||||
// ahead of the slow arm would have made this adapter less observant
|
||||
// than the IgnoreRecordNotFoundError option it was chosen over.
|
||||
func (l *Logger) Trace(
|
||||
ctx context.Context,
|
||||
begin time.Time,
|
||||
fc func() (string, int64),
|
||||
err error,
|
||||
) {
|
||||
elapsed := time.Since(begin)
|
||||
|
||||
switch {
|
||||
case err != nil && !errors.Is(err, gormlogger.ErrRecordNotFound):
|
||||
sql, rows := fc()
|
||||
l.log.ErrorContext(ctx, "sql statement failed",
|
||||
"error", logfield.Truncate(err.Error(), logfield.MaxBytes),
|
||||
"sql", logfield.Truncate(sql, logfield.MaxBytes),
|
||||
"rows", rows,
|
||||
"elapsed_ms", elapsed.Milliseconds(),
|
||||
)
|
||||
|
||||
case l.slowThreshold > 0 && elapsed >= l.slowThreshold:
|
||||
sql, rows := fc()
|
||||
l.log.WarnContext(ctx, "slow sql statement",
|
||||
"sql", logfield.Truncate(sql, logfield.MaxBytes),
|
||||
"rows", rows,
|
||||
"elapsed_ms", elapsed.Milliseconds(),
|
||||
"threshold_ms", l.slowThreshold.Milliseconds(),
|
||||
)
|
||||
|
||||
case err != nil:
|
||||
// gorm.ErrRecordNotFound is not an error on the paths that
|
||||
// produce it here: an invented entrypoint UUID and an unknown
|
||||
// username are the expected outcome of an unauthenticated
|
||||
// request, not a fault. This is the IgnoreRecordNotFoundError
|
||||
// behaviour, and it is unconditional rather than configurable
|
||||
// because no caller in this service wants the other one — the
|
||||
// two handlers that care already record the miss themselves,
|
||||
// at DEBUG, without the SQL. A miss that ran slow has already
|
||||
// been reported by the arm above.
|
||||
return
|
||||
|
||||
case l.log.Enabled(ctx, slog.LevelDebug):
|
||||
sql, rows := fc()
|
||||
l.log.DebugContext(ctx, "sql statement",
|
||||
"sql", logfield.Truncate(sql, logfield.MaxBytes),
|
||||
"rows", rows,
|
||||
"elapsed_ms", elapsed.Milliseconds(),
|
||||
)
|
||||
}
|
||||
}
|
||||
|
||||
// format renders one of GORM's printf-style internal messages and
|
||||
// bounds it. GORM builds these itself, but they can quote a value the
|
||||
// statement carried, so they are spent through the same budget as
|
||||
// everything else rather than trusted.
|
||||
func format(msg string, data ...any) string {
|
||||
if len(data) == 0 {
|
||||
return logfield.Truncate(msg, logfield.MaxBytes)
|
||||
}
|
||||
|
||||
return logfield.Truncate(
|
||||
fmt.Sprintf(msg, data...), logfield.MaxBytes,
|
||||
)
|
||||
}
|
||||
436
internal/gormlog/gormlog_test.go
Normal file
436
internal/gormlog/gormlog_test.go
Normal file
@@ -0,0 +1,436 @@
|
||||
package gormlog_test
|
||||
|
||||
import (
|
||||
"bytes"
|
||||
"context"
|
||||
"database/sql"
|
||||
"fmt"
|
||||
"log/slog"
|
||||
"path/filepath"
|
||||
"strings"
|
||||
"testing"
|
||||
"time"
|
||||
|
||||
"github.com/stretchr/testify/assert"
|
||||
"github.com/stretchr/testify/require"
|
||||
"gorm.io/driver/sqlite"
|
||||
"gorm.io/gorm"
|
||||
_ "modernc.org/sqlite" // Pure Go SQLite driver.
|
||||
"sneak.berlin/go/webhooker/internal/gormlog"
|
||||
"sneak.berlin/go/webhooker/internal/middleware"
|
||||
)
|
||||
|
||||
// fillBytes is how much client-chosen text each case drives into the
|
||||
// statement. It is well past every budget in play, so a value that
|
||||
// arrives short arrived short because something cut it.
|
||||
const fillBytes = 8 << 10
|
||||
|
||||
// tailMarker sits at the far end of every generated value. A line that
|
||||
// contains it carried the whole value, which means nothing cut it — so
|
||||
// a value that merely happened to be short cannot pass for a truncated
|
||||
// one.
|
||||
const tailMarker = "ENDOFCLIENTVALUE"
|
||||
|
||||
// fills are the characters a client can drive into a SQL parameter,
|
||||
// chosen for what the log handlers charge for them rather than for
|
||||
// looking dangerous.
|
||||
//
|
||||
// The C0 control is the one that matters. Both handlers spell U+0001
|
||||
// as a six-byte escape for the single byte it costs a client to send,
|
||||
// which is the widest multiplier available in the basic multilingual
|
||||
// plane and the case a raw-byte budget breaks on first. The astral
|
||||
// non-printable costs ten under the text handler, four more than the
|
||||
// JSON handler ever spends.
|
||||
func fills() []struct {
|
||||
name string
|
||||
fill string
|
||||
} {
|
||||
return []struct {
|
||||
name string
|
||||
fill string
|
||||
}{
|
||||
{"plain", "x"},
|
||||
{"quote", `"`},
|
||||
{"backslash", `\`},
|
||||
{"tab", "\t"},
|
||||
{"newline", "\n"},
|
||||
{"c0_control", "\x01"},
|
||||
{"astral_nonprintable", "\U0001000C"},
|
||||
}
|
||||
}
|
||||
|
||||
// clientValue builds a value of at least fillBytes raw bytes out of
|
||||
// fill, ending in tailMarker.
|
||||
func clientValue(fill string) string {
|
||||
var b strings.Builder
|
||||
|
||||
for b.Len() < fillBytes {
|
||||
b.WriteString(fill)
|
||||
}
|
||||
|
||||
b.WriteString(tailMarker)
|
||||
|
||||
return b.String()
|
||||
}
|
||||
|
||||
// handlers are the two slog handlers internal/logger can install. The
|
||||
// ceiling is quoted to operators unqualified, so every case is
|
||||
// asserted under both.
|
||||
func handlers() []struct {
|
||||
name string
|
||||
make func(*bytes.Buffer) slog.Handler
|
||||
} {
|
||||
opts := &slog.HandlerOptions{Level: slog.LevelDebug}
|
||||
|
||||
return []struct {
|
||||
name string
|
||||
make func(*bytes.Buffer) slog.Handler
|
||||
}{
|
||||
{"json", func(b *bytes.Buffer) slog.Handler {
|
||||
return slog.NewJSONHandler(b, opts)
|
||||
}},
|
||||
{"text", func(b *bytes.Buffer) slog.Handler {
|
||||
return slog.NewTextHandler(b, opts)
|
||||
}},
|
||||
}
|
||||
}
|
||||
|
||||
type thing struct {
|
||||
ID string `gorm:"primaryKey"`
|
||||
Name string
|
||||
}
|
||||
|
||||
// neverSlow is a slow-statement threshold no statement in this file
|
||||
// can reach. Cases that are about a non-slow arm of Trace set it, so
|
||||
// that a machine under load cannot turn a miss into a slow report and
|
||||
// decide the outcome for them.
|
||||
const neverSlow = time.Hour
|
||||
|
||||
// alwaysSlow makes every statement count as slow, so the slow arm is
|
||||
// reached without the test waiting for it.
|
||||
const alwaysSlow = time.Nanosecond
|
||||
|
||||
// openDB opens a real SQLite database behind the adapter under test,
|
||||
// so every assertion below is made against SQL that GORM actually
|
||||
// rendered rather than against a string a test wrote by hand. slow is
|
||||
// the adapter's slow-statement threshold.
|
||||
func openDB(
|
||||
t *testing.T, buf *bytes.Buffer, h slog.Handler, slow time.Duration,
|
||||
) *gorm.DB {
|
||||
t.Helper()
|
||||
|
||||
sqlDB, err := sql.Open("sqlite", fmt.Sprintf(
|
||||
"file:%s?mode=rwc",
|
||||
filepath.Join(t.TempDir(), "gormlog.db"),
|
||||
))
|
||||
require.NoError(t, err)
|
||||
|
||||
t.Cleanup(func() { _ = sqlDB.Close() })
|
||||
|
||||
gl := gormlog.ExportNewWithSlowThreshold(slog.New(h), slow)
|
||||
|
||||
gdb, err := gorm.Open(
|
||||
sqlite.Dialector{Conn: sqlDB},
|
||||
&gorm.Config{Logger: gl},
|
||||
)
|
||||
require.NoError(t, err)
|
||||
|
||||
require.NoError(t, gdb.AutoMigrate(&thing{}))
|
||||
|
||||
// Migration chatter is not what any of these cases is about.
|
||||
buf.Reset()
|
||||
|
||||
return gdb
|
||||
}
|
||||
|
||||
// assertBounded holds every line the adapter wrote to the stated
|
||||
// ceiling and proves each was cut rather than merely short.
|
||||
func assertBounded(t *testing.T, out string) {
|
||||
t.Helper()
|
||||
|
||||
assert.NotContains(
|
||||
t, out, tailMarker,
|
||||
"the far end of the client value reached the log, so "+
|
||||
"nothing truncated it",
|
||||
)
|
||||
|
||||
for line := range strings.SplitSeq(
|
||||
strings.TrimRight(out, "\n"), "\n",
|
||||
) {
|
||||
if line == "" {
|
||||
continue
|
||||
}
|
||||
|
||||
assert.LessOrEqual(
|
||||
t, len(line), middleware.MaxAccessLogLineBytes,
|
||||
"log line exceeded its bound: %s",
|
||||
line[:min(len(line), 300)],
|
||||
)
|
||||
}
|
||||
}
|
||||
|
||||
// TestRecordNotFound_WritesNothing is the defect itself. GORM's own
|
||||
// default logger prints the fully interpolated SELECT on every
|
||||
// ErrRecordNotFound, and on this service's two unauthenticated
|
||||
// lookups the interpolated parameter is whatever the client sent.
|
||||
func TestRecordNotFound_WritesNothing(t *testing.T) {
|
||||
t.Parallel()
|
||||
|
||||
for _, h := range handlers() {
|
||||
for _, f := range fills() {
|
||||
t.Run(h.name+"/"+f.name, func(t *testing.T) {
|
||||
t.Parallel()
|
||||
|
||||
var buf bytes.Buffer
|
||||
|
||||
gdb := openDB(t, &buf, h.make(&buf), neverSlow)
|
||||
|
||||
var got thing
|
||||
|
||||
err := gdb.Where(
|
||||
"id = ?", clientValue(f.fill),
|
||||
).First(&got).Error
|
||||
require.ErrorIs(t, err, gorm.ErrRecordNotFound)
|
||||
|
||||
assert.Empty(
|
||||
t, buf.String(),
|
||||
"a miss on a client-chosen key must not "+
|
||||
"write a log line",
|
||||
)
|
||||
})
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
// TestSlowRecordNotFound_IsStillReportedSlow pins the arm ordering in
|
||||
// Trace against the drop above.
|
||||
//
|
||||
// GORM's own Trace orders its cases error-that-is-not-a-miss, then
|
||||
// slow, then routine, so IgnoreRecordNotFoundError: true — the cheap
|
||||
// option this adapter was chosen over — still reports a miss that ran
|
||||
// slow. An adapter that dropped the miss first would be strictly less
|
||||
// observant than the option it replaced, on exactly the two lookups
|
||||
// this package exists for. A miss is also the statement most likely to
|
||||
// be slow, since it is the one that scans without finding a row.
|
||||
func TestSlowRecordNotFound_IsStillReportedSlow(t *testing.T) {
|
||||
t.Parallel()
|
||||
|
||||
for _, h := range handlers() {
|
||||
for _, f := range fills() {
|
||||
t.Run(h.name+"/"+f.name, func(t *testing.T) {
|
||||
t.Parallel()
|
||||
|
||||
var buf bytes.Buffer
|
||||
|
||||
gdb := openDB(t, &buf, h.make(&buf), alwaysSlow)
|
||||
|
||||
var got thing
|
||||
|
||||
err := gdb.Where(
|
||||
"id = ?", clientValue(f.fill),
|
||||
).First(&got).Error
|
||||
require.ErrorIs(t, err, gorm.ErrRecordNotFound)
|
||||
|
||||
assert.Contains(
|
||||
t, buf.String(), "slow sql statement",
|
||||
"a slow statement that missed was not "+
|
||||
"reported as slow",
|
||||
)
|
||||
assertBounded(t, buf.String())
|
||||
})
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
// TestRecordNotFoundFlood_DoesNotGrowWithInput states the definition
|
||||
// of done directly: a flood of misses at two input sizes 64 times
|
||||
// apart must cost the same number of bytes of log.
|
||||
func TestRecordNotFoundFlood_DoesNotGrowWithInput(t *testing.T) {
|
||||
t.Parallel()
|
||||
|
||||
const requests = 50
|
||||
|
||||
flood := func(t *testing.T, size int) int {
|
||||
t.Helper()
|
||||
|
||||
var buf bytes.Buffer
|
||||
|
||||
gdb := openDB(
|
||||
t, &buf,
|
||||
slog.NewJSONHandler(&buf, &slog.HandlerOptions{
|
||||
Level: slog.LevelDebug,
|
||||
}),
|
||||
neverSlow,
|
||||
)
|
||||
|
||||
value := strings.Repeat("\x01", size)
|
||||
|
||||
for range requests {
|
||||
var got thing
|
||||
|
||||
_ = gdb.Where("id = ?", value).First(&got).Error
|
||||
}
|
||||
|
||||
return buf.Len()
|
||||
}
|
||||
|
||||
small := flood(t, 128)
|
||||
big := flood(t, 128*64)
|
||||
|
||||
assert.Equal(
|
||||
t, small, big,
|
||||
"log volume tracked the size of the client's input",
|
||||
)
|
||||
}
|
||||
|
||||
// TestStatementError_LineIsBounded covers the branch that does log.
|
||||
// A driver error is not ErrRecordNotFound, so the interpolated
|
||||
// statement is written — and on an insert the interpolated value is
|
||||
// still whatever the client supplied.
|
||||
func TestStatementError_LineIsBounded(t *testing.T) {
|
||||
t.Parallel()
|
||||
|
||||
for _, h := range handlers() {
|
||||
for _, f := range fills() {
|
||||
t.Run(h.name+"/"+f.name, func(t *testing.T) {
|
||||
t.Parallel()
|
||||
|
||||
var buf bytes.Buffer
|
||||
|
||||
gdb := openDB(t, &buf, h.make(&buf), neverSlow)
|
||||
|
||||
row := thing{ID: clientValue(f.fill), Name: "a"}
|
||||
|
||||
require.NoError(t, gdb.Create(&row).Error)
|
||||
|
||||
buf.Reset()
|
||||
|
||||
// The same primary key a second time: a UNIQUE
|
||||
// constraint failure, which is an error GORM logs.
|
||||
err := gdb.Create(&thing{
|
||||
ID: row.ID, Name: "b",
|
||||
}).Error
|
||||
require.Error(t, err)
|
||||
|
||||
assert.Contains(
|
||||
t, buf.String(), "sql statement failed",
|
||||
)
|
||||
assertBounded(t, buf.String())
|
||||
})
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
// TestSucceedingStatement_LineIsBoundedOnEitherArm covers the two
|
||||
// arms a statement that returns no error can take, over the same
|
||||
// query, so neither can be bounded by accident of the other.
|
||||
//
|
||||
// - slow. Silencing GORM outright would have been the cheaper fix
|
||||
// and would have cost this report, which is the one thing GORM's
|
||||
// logger gave an operator that nothing else in this service does.
|
||||
// - routine. The branch an operator reaches by turning the level
|
||||
// down to DEBUG: every statement is reported, so every
|
||||
// statement's interpolated parameters have to be bounded too.
|
||||
func TestSucceedingStatement_LineIsBoundedOnEitherArm(t *testing.T) {
|
||||
t.Parallel()
|
||||
|
||||
// "sql statement" is a substring of "slow sql statement", so the
|
||||
// routine arm carries notWant as well: Contains alone cannot tell
|
||||
// the two arms apart in that direction.
|
||||
arms := []struct {
|
||||
name string
|
||||
slow time.Duration
|
||||
want string
|
||||
notWant string
|
||||
}{
|
||||
{"slow", alwaysSlow, "slow sql statement", ""},
|
||||
{"routine", neverSlow, "sql statement", "slow sql statement"},
|
||||
}
|
||||
|
||||
for _, a := range arms {
|
||||
for _, h := range handlers() {
|
||||
for _, f := range fills() {
|
||||
name := a.name + "/" + h.name + "/" + f.name
|
||||
|
||||
t.Run(name, func(t *testing.T) {
|
||||
t.Parallel()
|
||||
|
||||
var buf bytes.Buffer
|
||||
|
||||
gdb := openDB(t, &buf, h.make(&buf), a.slow)
|
||||
|
||||
var got []thing
|
||||
|
||||
require.NoError(t, gdb.Where(
|
||||
"name = ?", clientValue(f.fill),
|
||||
).Find(&got).Error)
|
||||
|
||||
assert.Contains(t, buf.String(), a.want)
|
||||
|
||||
if a.notWant != "" {
|
||||
assert.NotContains(
|
||||
t, buf.String(), a.notWant,
|
||||
)
|
||||
}
|
||||
|
||||
assertBounded(t, buf.String())
|
||||
})
|
||||
}
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
// TestGORMOwnMessages_AreBounded covers the three printf-style
|
||||
// entry points. GORM builds these itself, but nothing stops one of
|
||||
// them quoting a value the statement carried.
|
||||
func TestGORMOwnMessages_AreBounded(t *testing.T) {
|
||||
t.Parallel()
|
||||
|
||||
for _, h := range handlers() {
|
||||
for _, f := range fills() {
|
||||
t.Run(h.name+"/"+f.name, func(t *testing.T) {
|
||||
t.Parallel()
|
||||
|
||||
var buf bytes.Buffer
|
||||
|
||||
gl := gormlog.New(slog.New(h.make(&buf)))
|
||||
ctx := context.Background()
|
||||
value := clientValue(f.fill)
|
||||
|
||||
gl.Info(ctx, "%s", value)
|
||||
gl.Warn(ctx, "%s", value)
|
||||
gl.Error(ctx, "%s", value)
|
||||
|
||||
// The no-argument form, which is how GORM reports
|
||||
// most of its own conditions. Reached through a
|
||||
// function value so the vet printf check does not
|
||||
// read the message as a format string — which is
|
||||
// also why the adapter does not.
|
||||
noArgs := func(
|
||||
f func(context.Context, string, ...any),
|
||||
msg string,
|
||||
) {
|
||||
f(ctx, msg)
|
||||
}
|
||||
noArgs(gl.Info, value)
|
||||
|
||||
assertBounded(t, buf.String())
|
||||
})
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
// TestLogMode_KeepsTheOperatorsLevel records that GORM's own level
|
||||
// knob is deliberately inert: level belongs to LOG_LEVEL, and a
|
||||
// second one inside the database layer could only disagree with it.
|
||||
func TestLogMode_KeepsTheOperatorsLevel(t *testing.T) {
|
||||
t.Parallel()
|
||||
|
||||
var buf bytes.Buffer
|
||||
|
||||
gl := gormlog.New(slog.New(slog.NewJSONHandler(
|
||||
&buf, &slog.HandlerOptions{Level: slog.LevelDebug},
|
||||
)))
|
||||
|
||||
assert.Same(t, gl, gl.LogMode(0))
|
||||
}
|
||||
462
internal/handlers/gormlogbound_test.go
Normal file
462
internal/handlers/gormlogbound_test.go
Normal file
@@ -0,0 +1,462 @@
|
||||
package handlers_test
|
||||
|
||||
import (
|
||||
"bytes"
|
||||
"context"
|
||||
"io"
|
||||
"log"
|
||||
"net/http"
|
||||
"net/http/httptest"
|
||||
"os"
|
||||
"strconv"
|
||||
"strings"
|
||||
"sync"
|
||||
"testing"
|
||||
"time"
|
||||
|
||||
"github.com/go-chi/chi"
|
||||
"github.com/stretchr/testify/assert"
|
||||
"github.com/stretchr/testify/require"
|
||||
"gorm.io/gorm"
|
||||
gormlogger "gorm.io/gorm/logger"
|
||||
"sneak.berlin/go/webhooker/internal/database"
|
||||
"sneak.berlin/go/webhooker/internal/handlers"
|
||||
"sneak.berlin/go/webhooker/internal/middleware"
|
||||
)
|
||||
|
||||
// gormBoundTailMarker sits at the far end of every client-chosen value
|
||||
// this file sends. Its presence in the log means the whole value
|
||||
// reached the log, so a value that merely happened to be short cannot
|
||||
// pass for a truncated one.
|
||||
const gormBoundTailMarker = "ENDOFCLIENTVALUE"
|
||||
|
||||
// gormBoundFills are the characters a client can drive through the
|
||||
// receiver path segment and the login username, chosen for what a log
|
||||
// handler charges for them.
|
||||
//
|
||||
// The bare C0 control is the one that matters: both handlers spell
|
||||
// U+0001 as a six-byte escape for the one byte it costs to send, the
|
||||
// widest multiplier available below U+10000 and the case a raw-byte
|
||||
// budget breaks on first. GORM's default logger applies no budget at
|
||||
// all, so under the mutation every one of these arrives whole.
|
||||
func gormBoundFills() []struct {
|
||||
name string
|
||||
fill string
|
||||
} {
|
||||
return []struct {
|
||||
name string
|
||||
fill string
|
||||
}{
|
||||
{"plain", "x"},
|
||||
{"quote", `"`},
|
||||
{"backslash", `\`},
|
||||
{"tab", "\t"},
|
||||
{"newline", "\n"},
|
||||
{"c0_control", "\x01"},
|
||||
{"astral_nonprintable", "\U0001000C"},
|
||||
}
|
||||
}
|
||||
|
||||
// syncBuf collects captured output from the goroutine draining the
|
||||
// pipe.
|
||||
type syncBuf struct {
|
||||
mu sync.Mutex
|
||||
b bytes.Buffer
|
||||
}
|
||||
|
||||
func (s *syncBuf) Write(p []byte) (int, error) {
|
||||
s.mu.Lock()
|
||||
defer s.mu.Unlock()
|
||||
|
||||
return s.b.Write(p)
|
||||
}
|
||||
|
||||
func (s *syncBuf) String() string {
|
||||
s.mu.Lock()
|
||||
defer s.mu.Unlock()
|
||||
|
||||
return s.b.String()
|
||||
}
|
||||
|
||||
func (s *syncBuf) reset() {
|
||||
s.mu.Lock()
|
||||
defer s.mu.Unlock()
|
||||
|
||||
s.b.Reset()
|
||||
}
|
||||
|
||||
// stdoutCapture redirects os.Stdout for the duration of a test.
|
||||
//
|
||||
// internal/logger builds its handler over os.Stdout at construction
|
||||
// time, so redirecting the variable before the application is built
|
||||
// captures everything the service logger — and therefore the GORM
|
||||
// adapter, which writes through it — emits.
|
||||
type stdoutCapture struct {
|
||||
buf *syncBuf
|
||||
r *os.File
|
||||
w *os.File
|
||||
orig *os.File
|
||||
done chan struct{}
|
||||
seq int
|
||||
}
|
||||
|
||||
func captureStdout(t *testing.T) *stdoutCapture {
|
||||
t.Helper()
|
||||
|
||||
r, w, err := os.Pipe()
|
||||
require.NoError(t, err)
|
||||
|
||||
c := &stdoutCapture{
|
||||
buf: &syncBuf{},
|
||||
r: r,
|
||||
w: w,
|
||||
orig: os.Stdout,
|
||||
done: make(chan struct{}),
|
||||
}
|
||||
|
||||
os.Stdout = w
|
||||
|
||||
go func() {
|
||||
defer close(c.done)
|
||||
|
||||
_, _ = io.Copy(c.buf, r)
|
||||
}()
|
||||
|
||||
t.Cleanup(func() {
|
||||
os.Stdout = c.orig
|
||||
_ = w.Close()
|
||||
|
||||
<-c.done
|
||||
|
||||
_ = r.Close()
|
||||
})
|
||||
|
||||
return c
|
||||
}
|
||||
|
||||
// drain returns everything written since the previous drain and
|
||||
// clears the buffer.
|
||||
//
|
||||
// A sentinel is pushed through the same pipe and waited for, so the
|
||||
// draining goroutine is known to have caught up before the buffer is
|
||||
// read. Without it the comparison below would race the reader rather
|
||||
// than measure the writers.
|
||||
func (c *stdoutCapture) drain(t *testing.T) string {
|
||||
t.Helper()
|
||||
|
||||
c.seq++
|
||||
|
||||
sentinel := "\n<<drain-" + strconv.Itoa(c.seq) + ">>\n"
|
||||
|
||||
_, err := c.w.WriteString(sentinel)
|
||||
require.NoError(t, err)
|
||||
|
||||
deadline := time.Now().Add(10 * time.Second)
|
||||
for !strings.Contains(c.buf.String(), sentinel) {
|
||||
require.False(
|
||||
t, time.Now().After(deadline),
|
||||
"timed out waiting for captured output",
|
||||
)
|
||||
time.Sleep(time.Millisecond)
|
||||
}
|
||||
|
||||
out := strings.Replace(c.buf.String(), sentinel, "", 1)
|
||||
|
||||
c.buf.reset()
|
||||
|
||||
return out
|
||||
}
|
||||
|
||||
// teeStdout writes to a buffer and to whatever os.Stdout is at the
|
||||
// moment of the write.
|
||||
//
|
||||
// The second half is the point. GORM's package-level default logger
|
||||
// resolves os.Stdout once, at package init, so a logger built over the
|
||||
// variable would keep writing to the real terminal no matter what a
|
||||
// test redirects. Resolving it per write puts the bytes a defaulted
|
||||
// gorm.Config would cost in production into the same capture as
|
||||
// everything else internal/logger emits, which is what lets the volume
|
||||
// assertions below measure the whole writer set rather than one member
|
||||
// of it.
|
||||
type teeStdout struct {
|
||||
buf *syncBuf
|
||||
}
|
||||
|
||||
func (w teeStdout) Write(p []byte) (int, error) {
|
||||
_, _ = os.Stdout.Write(p)
|
||||
|
||||
return w.buf.Write(p)
|
||||
}
|
||||
|
||||
// captureGORMDefault replaces GORM's package-level default logger with
|
||||
// one configured exactly as GORM configures its own, writing to a
|
||||
// buffer and to os.Stdout.
|
||||
//
|
||||
// This is the mutation detector. gormlogger.Default is what a bare
|
||||
// &gorm.Config{} installs, and its config here is GORM's verbatim —
|
||||
// Warn, IgnoreRecordNotFoundError false — so a reverted call site
|
||||
// behaves as it would in production rather than as a test dialed it.
|
||||
// With every gorm.Open in this service naming its own logger, nothing
|
||||
// consults this value and the buffer stays empty; revert any one of
|
||||
// the three and the interpolated SQL lands here.
|
||||
func captureGORMDefault(t *testing.T) *syncBuf {
|
||||
t.Helper()
|
||||
|
||||
buf := &syncBuf{}
|
||||
orig := gormlogger.Default
|
||||
|
||||
gormlogger.Default = gormlogger.New(
|
||||
log.New(teeStdout{buf: buf}, "", log.LstdFlags),
|
||||
gormlogger.Config{
|
||||
SlowThreshold: 200 * time.Millisecond,
|
||||
LogLevel: gormlogger.Warn,
|
||||
IgnoreRecordNotFoundError: false,
|
||||
Colorful: false,
|
||||
},
|
||||
)
|
||||
|
||||
t.Cleanup(func() { gormlogger.Default = orig })
|
||||
|
||||
return buf
|
||||
}
|
||||
|
||||
// floodUnauthenticated drives reps requests at each of the two
|
||||
// unauthenticated lookups that miss by design, for every fill, with a
|
||||
// client-chosen value of size raw bytes.
|
||||
func floodUnauthenticated(
|
||||
t *testing.T, h *handlers.Handlers, size, reps int,
|
||||
) int {
|
||||
t.Helper()
|
||||
|
||||
requests := 0
|
||||
|
||||
for _, f := range gormBoundFills() {
|
||||
var b strings.Builder
|
||||
|
||||
for b.Len() < size {
|
||||
b.WriteString(f.fill)
|
||||
}
|
||||
|
||||
b.WriteString(gormBoundTailMarker)
|
||||
|
||||
value := b.String()
|
||||
|
||||
for range reps {
|
||||
postWebhook(t, h, value)
|
||||
postUnknownLogin(t, h, value)
|
||||
|
||||
requests += 2
|
||||
}
|
||||
}
|
||||
|
||||
return requests
|
||||
}
|
||||
|
||||
// floodPerWebhook drives the same client-chosen values at the second
|
||||
// gorm.Open site, the per-webhook database internal/database's
|
||||
// WebhookDBManager opens.
|
||||
//
|
||||
// That site is behind authentication in production, so this is not
|
||||
// part of the unauthenticated flood above and is counted separately.
|
||||
// It is here because the ceiling the README states covers every
|
||||
// writer, and the manager is one of them: with nothing driving it, a
|
||||
// bare &gorm.Config{} could be restored at
|
||||
// internal/database/webhook_db_manager.go and the whole suite would
|
||||
// stay green.
|
||||
func floodPerWebhook(
|
||||
t *testing.T, mgr *database.WebhookDBManager, size, reps int,
|
||||
) int {
|
||||
t.Helper()
|
||||
|
||||
requests := 0
|
||||
|
||||
for _, f := range gormBoundFills() {
|
||||
var b strings.Builder
|
||||
|
||||
for b.Len() < size {
|
||||
b.WriteString(f.fill)
|
||||
}
|
||||
|
||||
b.WriteString(gormBoundTailMarker)
|
||||
|
||||
value := b.String()
|
||||
|
||||
db, err := mgr.GetDB("pin-" + f.name)
|
||||
require.NoError(t, err)
|
||||
|
||||
for range reps {
|
||||
var got database.Event
|
||||
|
||||
err = db.Where("id = ?", value).First(&got).Error
|
||||
require.ErrorIs(t, err, gorm.ErrRecordNotFound)
|
||||
|
||||
requests++
|
||||
}
|
||||
}
|
||||
|
||||
return requests
|
||||
}
|
||||
|
||||
// postWebhook drives the receiver with an invented entrypoint path.
|
||||
// The route pattern matches any single segment, so every byte of the
|
||||
// value is the client's, and the lookup behind it misses by design.
|
||||
func postWebhook(
|
||||
t *testing.T, h *handlers.Handlers, entrypoint string,
|
||||
) {
|
||||
t.Helper()
|
||||
|
||||
req := httptest.NewRequestWithContext(
|
||||
context.Background(), http.MethodPost, "/webhook/x",
|
||||
strings.NewReader("{}"),
|
||||
)
|
||||
|
||||
rctx := chi.NewRouteContext()
|
||||
rctx.URLParams.Add("uuid", entrypoint)
|
||||
|
||||
req = req.WithContext(context.WithValue(
|
||||
req.Context(), chi.RouteCtxKey, rctx,
|
||||
))
|
||||
|
||||
w := httptest.NewRecorder()
|
||||
h.HandleWebhook().ServeHTTP(w, req)
|
||||
|
||||
require.Equal(t, http.StatusNotFound, w.Code)
|
||||
}
|
||||
|
||||
// postUnknownLogin submits the login form with an unknown username,
|
||||
// through the postLogin helper in logbound_test.go. The field is
|
||||
// bounded only by the 1 MB body cap, and the lookup behind it misses
|
||||
// by design.
|
||||
func postUnknownLogin(
|
||||
t *testing.T, h *handlers.Handlers, username string,
|
||||
) {
|
||||
t.Helper()
|
||||
|
||||
// 401 while the client still has failure budget against this
|
||||
// username, 429 once the login guard has taken it away. Both
|
||||
// outcomes sit behind the user lookup, which is the query this
|
||||
// test is here to drive.
|
||||
require.Contains(
|
||||
t,
|
||||
[]int{http.StatusUnauthorized, http.StatusTooManyRequests},
|
||||
postLogin(t, h, username),
|
||||
)
|
||||
}
|
||||
|
||||
// assertFloodBounded holds every captured line to the stated ceiling
|
||||
// and proves nothing carried a whole client value.
|
||||
func assertFloodBounded(t *testing.T, label, out string) {
|
||||
t.Helper()
|
||||
|
||||
assert.NotContains(
|
||||
t, out, gormBoundTailMarker,
|
||||
"%s: the far end of a client-chosen value reached the "+
|
||||
"log, so nothing truncated it", label,
|
||||
)
|
||||
|
||||
for line := range strings.SplitSeq(
|
||||
strings.TrimRight(out, "\n"), "\n",
|
||||
) {
|
||||
if line == "" {
|
||||
continue
|
||||
}
|
||||
|
||||
assert.LessOrEqual(
|
||||
t, len(line), middleware.MaxAccessLogLineBytes,
|
||||
"%s: log line exceeded its bound: %s",
|
||||
label, line[:min(len(line), 300)],
|
||||
)
|
||||
}
|
||||
}
|
||||
|
||||
// TestFlood_NoWriterGrowsWithTheInput is the definition of done for
|
||||
// the GORM logger defect, stated over every writer at once, for two of
|
||||
// this service's three gorm.Open sites: the main database behind the
|
||||
// two unauthenticated lookups, and the per-webhook database the
|
||||
// WebhookDBManager opens. The third, the archive writer, is pinned in
|
||||
// internal/delivery, where its type lives.
|
||||
//
|
||||
// What each assertion is worth, since two of the three would pass
|
||||
// against a service that had never been fixed if the capture were set
|
||||
// up differently:
|
||||
//
|
||||
// - The gormDefault check is the sharp one. It fires the moment any
|
||||
// gorm.Open in this service goes back to a bare &gorm.Config{}.
|
||||
// - The volume and per-line checks bite only because the replaced
|
||||
// default logger tees into os.Stdout, so a reverted call site
|
||||
// shows up in the same capture as everything internal/logger
|
||||
// writes — the way it would in production. Without that tee both
|
||||
// were vacuous: at INFO the two handler misses log at DEBUG and
|
||||
// the adapter drops the record-not-found, so the capture holds
|
||||
// nothing but fixed-string warnings.
|
||||
//
|
||||
// The level is left where newTestApp leaves it, at INFO: the level an
|
||||
// operator runs at by default, and the one the defect was visible at.
|
||||
// The handlers' own miss lines sit at DEBUG and spend the same
|
||||
// logfield budget as everything else, so they are not what makes
|
||||
// either assertion above bite at any level.
|
||||
//
|
||||
// It is deliberately not parallel: it redirects os.Stdout and replaces
|
||||
// gormlogger.Default, both of which are process-global. Go runs every
|
||||
// non-parallel top-level test to completion before it resumes the
|
||||
// parallel ones, so nothing else in this package is running while the
|
||||
// capture is installed.
|
||||
//
|
||||
//nolint:paralleltest // Deliberately sequential; see above.
|
||||
func TestFlood_NoWriterGrowsWithTheInput(t *testing.T) {
|
||||
const (
|
||||
smallBytes = 128
|
||||
bigBytes = 8 << 10
|
||||
reps = 5
|
||||
)
|
||||
|
||||
gormDefault := captureGORMDefault(t)
|
||||
capture := captureStdout(t)
|
||||
|
||||
var (
|
||||
h *handlers.Handlers
|
||||
mgr *database.WebhookDBManager
|
||||
)
|
||||
|
||||
app := newTestApp(t, &h, &mgr)
|
||||
app.RequireStart()
|
||||
|
||||
t.Cleanup(app.RequireStop)
|
||||
|
||||
// Startup chatter is not what this test measures.
|
||||
capture.drain(t)
|
||||
|
||||
floodUnauthenticated(t, h, smallBytes, reps)
|
||||
floodPerWebhook(t, mgr, smallBytes, reps)
|
||||
|
||||
small := capture.drain(t)
|
||||
|
||||
requests := floodUnauthenticated(t, h, bigBytes, reps)
|
||||
requests += floodPerWebhook(t, mgr, bigBytes, reps)
|
||||
big := capture.drain(t)
|
||||
|
||||
assertFloodBounded(t, "small flood", small)
|
||||
assertFloodBounded(t, "big flood", big)
|
||||
|
||||
// GORM's default logger is what the defect was. Nothing in this
|
||||
// service may reach it.
|
||||
got := gormDefault.String()
|
||||
assert.Empty(
|
||||
t, got,
|
||||
"GORM's default logger wrote %d bytes; the first of them: %s",
|
||||
len(got), got[:min(len(got), 300)],
|
||||
)
|
||||
|
||||
// The same flood, with 64 times the client-chosen input, must not
|
||||
// buy 64 times the log. A few bytes of slack covers a latency
|
||||
// field changing width; the input grew by roughly half a megabyte.
|
||||
const slackPerRequest = 64
|
||||
|
||||
assert.LessOrEqual(
|
||||
t, len(big), len(small)+slackPerRequest*requests,
|
||||
"log volume tracked the size of the client's input: "+
|
||||
"%d bytes at %d bytes of input per request, %d bytes "+
|
||||
"at %d",
|
||||
len(small), smallBytes, len(big), bigBytes,
|
||||
)
|
||||
}
|
||||
@@ -219,3 +219,103 @@ 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)
|
||||
}
|
||||
}
|
||||
|
||||
@@ -376,7 +376,7 @@ func lineSizeCases() map[string]sizeCase {
|
||||
|
||||
// The url field on a 5xx keeps the concrete path, so it reaches its
|
||||
// own budget on the same line as the three header fields. That is
|
||||
// the widest line the service can be made to write.
|
||||
// the widest access log line the service can be made to write.
|
||||
longPath := "/boom/" + strings.Repeat("x", oversizedSegmentBytes)
|
||||
wantLongURL := longPath[:maxFieldBytes] + truncationSuffix
|
||||
|
||||
|
||||
@@ -67,6 +67,9 @@ const (
|
||||
// ----
|
||||
// 2087
|
||||
//
|
||||
// The 512 is logfield.MaxBytes; the 11 is the truncation marker,
|
||||
// charged on top of each budget rather than inside it.
|
||||
//
|
||||
// The fixed portion is the JSON punctuation, the field names, the
|
||||
// level and the message, both timestamps at their longest, an IPv6
|
||||
// remoteIP with a zone, a three-digit status and a full-width int64
|
||||
@@ -104,6 +107,17 @@ const (
|
||||
// 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:
|
||||
//
|
||||
@@ -119,10 +133,12 @@ const (
|
||||
// - The "log" delivery target, which exists to write the whole
|
||||
// inbound event to the log. Deliberate; see
|
||||
// internal/delivery/target_log.go.
|
||||
// - 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.
|
||||
// - The record a recovered panic writes, which is not an access
|
||||
// log line: its client-supplied fields are charged the same
|
||||
// budgets, but it carries a whole goroutine stack as well and
|
||||
// is wider than this figure. It has its own stated ceiling,
|
||||
// MaxPanicLogLineBytes in recoverer.go, and is written once
|
||||
// per recovered panic rather than once per request.
|
||||
MaxAccessLogLineBytes = 2560
|
||||
)
|
||||
|
||||
|
||||
209
internal/middleware/recoverer.go
Normal file
209
internal/middleware/recoverer.go
Normal file
@@ -0,0 +1,209 @@
|
||||
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
Normal file
645
internal/middleware/recoverer_test.go
Normal file
@@ -0,0 +1,645 @@
|
||||
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))
|
||||
}
|
||||
@@ -54,3 +54,40 @@ 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
|
||||
}
|
||||
|
||||
285
internal/server/recoverer_test.go
Normal file
285
internal/server/recoverer_test.go
Normal file
@@ -0,0 +1,285 @@
|
||||
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,
|
||||
)
|
||||
}
|
||||
@@ -51,7 +51,6 @@ 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())
|
||||
@@ -64,8 +63,21 @@ 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.
|
||||
// true so panics still bubble up to the Recoverer middleware
|
||||
// registered immediately above.
|
||||
if s.sentryEnabled {
|
||||
sentryHandler := sentryhttp.New(sentryhttp.Options{
|
||||
Repanic: true,
|
||||
|
||||
@@ -52,6 +52,15 @@ 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
|
||||
@@ -100,6 +109,10 @@ func newTestEnv(t *testing.T) *testEnv {
|
||||
sess: sess,
|
||||
db: db,
|
||||
dbMgr: dbMgr,
|
||||
log: log,
|
||||
cfg: cfg,
|
||||
mw: mw,
|
||||
hnd: hnd,
|
||||
}
|
||||
}
|
||||
|
||||
|
||||
@@ -127,12 +127,14 @@ func (c sentryCase) capture(t *testing.T) []*sentry.Event {
|
||||
return transport.events
|
||||
}
|
||||
|
||||
// router mirrors setupGlobalMiddleware's ordering over the two route
|
||||
// patterns these tests need: a recovering middleware first, then the
|
||||
// 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 registers it. The local recover stands in for chi's
|
||||
// middleware.Recoverer, which holds that slot in production; it is
|
||||
// here only to keep panic stacks out of the test output.
|
||||
// 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
|
||||
|
||||
24
script/test
24
script/test
@@ -1,12 +1,34 @@
|
||||
#!/bin/sh
|
||||
# script/test: run the test suite.
|
||||
#
|
||||
# -timeout is applied by `go test` per package, not to the run as a whole, so
|
||||
# it only has to clear the slowest single package. That is internal/handlers,
|
||||
# measured in a cache-defeated builder stage on the 48-core shared build host
|
||||
# (2026-08-18); load- and host-dependent, not invariants:
|
||||
#
|
||||
# 16.9s host load 5-20, GOMAXPROCS 48
|
||||
# 45.9s / 47.3s / 49.0s three runs at deliberate host load 31-73
|
||||
# 30.6s / 39.7s host load 5-20, GOMAXPROCS 6 / 4
|
||||
# 67.3s / 97.5s host load 5-20, GOMAXPROCS 2 / 1
|
||||
# 67.3s GOMAXPROCS 4 at deliberate host load 52-68
|
||||
#
|
||||
# The old 30s budget was breached by every loaded run and by every GOMAXPROCS
|
||||
# at or below 6; at GOMAXPROCS 4 it failed outright ("panic: test timed out
|
||||
# after 30s"), reproduced on 33e4fa4 with no other change.
|
||||
#
|
||||
# 90s matches the org-wide backstop in REPO_POLICIES.md and is sized here
|
||||
# against the figures above: the worst case under native parallelism is 49.0s,
|
||||
# and the compound GOMAXPROCS-4-under-load case at 67.3s sits at 75% of it.
|
||||
# The one figure above 90s is GOMAXPROCS 1, a synthetic core floor rather than
|
||||
# a condition CI runs under. If a CPU-limited runner ever puts a real run near
|
||||
# 67s, that is the datum to revisit the org figure with.
|
||||
set -eu
|
||||
|
||||
ROOT="$(cd "$(dirname "$0")/.." && pwd -P)"
|
||||
|
||||
main() {
|
||||
cd "$ROOT"
|
||||
go test -v -race -timeout 30s ./...
|
||||
go test -v -race -timeout 90s ./...
|
||||
}
|
||||
|
||||
main "$@"
|
||||
|
||||
Reference in New Issue
Block a user