Compare commits
1 Commits
04678d07e3
...
f9d9a2c8d7
| Author | SHA1 | Date | |
|---|---|---|---|
| f9d9a2c8d7 |
226
README.md
226
README.md
@@ -994,16 +994,15 @@ costs; log volume it caps rather than eliminates. A path that names no
|
|||||||
entrypoint is recorded by the handler at `DEBUG`, and the aggregate
|
entrypoint is recorded by the handler at `DEBUG`, and the aggregate
|
||||||
limiter logs its own rejections at `DEBUG` and without the path, so
|
limiter logs its own rejections at `DEBUG` and without the path, so
|
||||||
neither appears at all under the default level. The per-entrypoint
|
neither appears at all under the default level. The per-entrypoint
|
||||||
limiter is the loud one: it logs every rejection at `WARN` with the
|
limiter is the loud one: it still logs every rejection at `WARN` with
|
||||||
request path, which on this route is attacker-controlled text. A client
|
the request path, which on this route is attacker-controlled text. A
|
||||||
hammering a single invented path is served `RECEIVER_RATE_LIMIT`
|
client hammering a single invented path is served `RECEIVER_RATE_LIMIT`
|
||||||
requests and has the rest of its aggregate budget rejected there, so
|
requests and has the rest of its aggregate budget rejected there, so
|
||||||
the aggregate limit is what bounds the _number_ of those `WARN` lines —
|
the aggregate limit is what bounds those `WARN` lines — to under ten
|
||||||
to under ten times `RECEIVER_RATE_LIMIT` per minute per client IP, 1080
|
times `RECEIVER_RATE_LIMIT` per minute per client IP, 1080 at the
|
||||||
at the defaults, where before it there was no bound at all. Their
|
defaults, where before it there was no bound at all. The access log is
|
||||||
_width_ is bounded by the field budgets below, the same ones the access
|
bounded by neither limit: every request is recorded once at `INFO`,
|
||||||
log spends. The access log is bounded by neither limit: every request
|
served or rejected alike.
|
||||||
is recorded once at `INFO`, served or rejected alike.
|
|
||||||
|
|
||||||
What the access log does bound is the _content_ of those lines. A 3xx
|
What the access log does bound is the _content_ of those lines. A 3xx
|
||||||
or 4xx response logs the chi route pattern — `/webhook/{uuid}`,
|
or 4xx response logs the chi route pattern — `/webhook/{uuid}`,
|
||||||
@@ -1141,9 +1140,9 @@ the figure has headroom. `internal/middleware/accesslog_test.go`
|
|||||||
asserts it against 8 KB of client-chosen text in the path, in the
|
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`,
|
query, and in each of `User-Agent`, `Referer` and `X-Request-Id`,
|
||||||
including cases built from the characters the handlers escape, and
|
including cases built from the characters the handlers escape, and
|
||||||
against the widest access log line the service can be made to write: a
|
against the widest line the service can be made to write: a 5xx that
|
||||||
5xx that keeps its concrete path while all three header fields are also
|
keeps its concrete path while all three header fields are also at their
|
||||||
at their budget. Every case runs through both handlers `internal/logger` can
|
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
|
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
|
two do not escape alike and the ceiling is quoted unqualified. Measured
|
||||||
over a real connection, the widest line is 1,972 bytes.
|
over a real connection, the widest line is 1,972 bytes.
|
||||||
@@ -1153,148 +1152,79 @@ that the rate is not bounded by the limits above on every route:
|
|||||||
`/.well-known/healthcheck` and `/s/*` sit behind no limiter, so there
|
`/.well-known/healthcheck` and `/s/*` sit behind no limiter, so there
|
||||||
the multiplier is whatever the deployment will serve.
|
the multiplier is whatever the deployment will serve.
|
||||||
|
|
||||||
**The same ceiling covers every other line the service writes through
|
That figure is now the ceiling on a second writer as well. GORM's own
|
||||||
`slog` that carries text an unauthenticated client supplies.** The
|
default logger printed the fully interpolated SQL — parameters and all
|
||||||
access log is not the only line a client can put its own text into, and
|
— to standard output on every statement that returned an error,
|
||||||
a budget that held for one line and not the others would be worse than
|
including a plain record-not-found, at a level no operator setting
|
||||||
no stated budget at all. Every `slog` call an unauthenticated request
|
reached. Two of this service's lookups miss by design on
|
||||||
can reach spends the same per-field budget through `internal/logfield`,
|
unauthenticated routes: the entrypoint lookup behind `/webhook/{uuid}`
|
||||||
and each carries strictly fewer client-supplied fields than the access
|
and the user lookup behind the login form, whose path segment and
|
||||||
log does, so none of them can be wider than it:
|
submitted username the client picks outright. Every `gorm.Open` in the
|
||||||
|
service now installs the adapter in `internal/gormlog` instead. It
|
||||||
| Log line | Level | Client-chosen value | Reachable unauthenticated |
|
writes through the same `slog` logger as everything else, so its lines
|
||||||
| ------------------------------------------ | ------- | ------------------- | ----------------------------------------- |
|
take the level the operator set and the handler `internal/logger`
|
||||||
| `request body exceeds limit` (413) | `WARN` | path, method | yes — `MaxBodySize` precedes `RequireAuth` |
|
selected, and every value it emits is spent through the same 512-byte
|
||||||
| `csrf: token validation failed` (403) | `WARN` | path, method | yes — `CSRF` precedes `RequireAuth` |
|
encoded budget (`internal/logfield`). A record-not-found is not logged
|
||||||
| `... rate limit exceeded` (429) | `WARN` | path | yes, on the receiver |
|
as an error: it is the expected outcome on both of those paths, and
|
||||||
| `auth middleware: unauthenticated request` | `DEBUG` | path, method | yes, by definition |
|
each handler already records its own miss at `DEBUG`, without the SQL.
|
||||||
| `entrypoint not found` | `DEBUG` | entrypoint UUID | yes, on the receiver |
|
Slow statements are kept — at `WARN`, above the same 200 ms threshold
|
||||||
| `user not found` / `invalid password` | `DEBUG` | username | yes, on the login form |
|
GORM used, with the statement bounded — because that report is the one
|
||||||
| `login failure limit exceeded` (429) | `WARN` | path | yes, on the login form |
|
thing GORM's logger gave an operator that nothing else here does, and
|
||||||
| `password verification capacity exhausted` | `WARN` | path | yes, on the login form |
|
a statement that both missed and ran slow is still reported as slow.
|
||||||
|
The adapter orders those cases exactly as GORM's own `Trace` orders
|
||||||
`DEBUG` being off by default is not a bound. An operator turning it on
|
them, so dropping the miss costs an operator no report that GORM's
|
||||||
to diagnose a flood must not thereby hand the flood an unbounded write,
|
`IgnoreRecordNotFoundError` would have kept. A
|
||||||
so those lines are capped too.
|
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;
|
||||||
The last two rows are capped defensively rather than against a
|
`internal/gormlog/gormlog_test.go` asserts each line against
|
||||||
demonstrated width: chi routes `POST /pages/login` on a static pattern,
|
|
||||||
so `r.URL.Path` there is the 12-byte constant `/pages/login` and each
|
|
||||||
line lands near 120 bytes. `RecordLoginFailure` is nonetheless an
|
|
||||||
exported method taking any `*http.Request`, and a future caller on a
|
|
||||||
route with a URL parameter would widen the line. Since no request
|
|
||||||
through the mux can, both caps are pinned by tests that call those two
|
|
||||||
entry points directly with the path such a caller would supply.
|
|
||||||
Removing either cap fails 14 subtests.
|
|
||||||
|
|
||||||
`internal/middleware/logbound_test.go` and
|
|
||||||
`internal/handlers/logbound_test.go` drive 8 KB of client-chosen text
|
|
||||||
at each of these — 1 KB at `invalid password`, whose accounts are
|
|
||||||
shared with the successful-login line, where a username past 4 KB
|
|
||||||
overflows the session cookie and answers 500 before that line is
|
|
||||||
written — through both handlers, and through seven fills: plain text
|
|
||||||
as the baseline, and then the quotation mark, backslash, tab, newline,
|
|
||||||
C0 control and astral non-printable, six characters the wider of the
|
|
||||||
two handlers spends more on than the client spent sending them. Every
|
|
||||||
case holds each line to the 2,560-byte ceiling. That per-line ceiling
|
|
||||||
is what the figure above states, and every row establishes it.
|
|
||||||
|
|
||||||
Three of the sites go further and bound the whole flood's output — the
|
|
||||||
total bytes a run of distinct invented values wrote, which is the
|
|
||||||
shape an operator sizing storage cares about. They are
|
|
||||||
`request body exceeds limit`
|
|
||||||
(`TestMaxBodySize_FloodOfOversizePathsDoesNotGrowTheLog`),
|
|
||||||
`entrypoint not found` and `user not found` (the last two through
|
|
||||||
`assertBoundedFlood`). The other rows carry no aggregate assertion;
|
|
||||||
the per-line ceiling is what they establish.
|
|
||||||
|
|
||||||
`internal/logfield/logfield_test.go` measures the per-rune charge
|
|
||||||
against what the handlers really emit, over roughly 3,000 code points on
|
|
||||||
each, so an undercharged rune fails a test rather than quietly
|
|
||||||
falsifying the ceiling.
|
|
||||||
|
|
||||||
**It covers GORM's statement logging as well.** GORM's own default
|
|
||||||
logger printed the fully interpolated SQL — parameters and all — to
|
|
||||||
standard output on every statement that returned an error, including a
|
|
||||||
plain record-not-found, at a level no operator setting reached. Two of this service's lookups miss by design
|
|
||||||
on unauthenticated routes: the entrypoint lookup behind
|
|
||||||
`/webhook/{uuid}` and the user lookup behind the login form, whose path
|
|
||||||
segment and submitted username the client picks outright. Every
|
|
||||||
`gorm.Open` in the service now installs the adapter in
|
|
||||||
`internal/gormlog` instead. It writes through the same `slog` logger as
|
|
||||||
everything else, so its lines take the level the operator set and the
|
|
||||||
handler `internal/logger` selected, and every value it emits is spent
|
|
||||||
through the same `internal/logfield` budget. A record-not-found is not
|
|
||||||
logged as an error: it is the expected outcome on both of those paths,
|
|
||||||
and each handler already records its own miss at `DEBUG` — bounded, per
|
|
||||||
the table above — without the SQL. Slow statements are kept, at `WARN`,
|
|
||||||
above the same 200 ms threshold GORM used and with the statement
|
|
||||||
bounded, because that report is the one thing GORM's logger gave an
|
|
||||||
operator that nothing else here does. The adapter orders its cases
|
|
||||||
exactly as GORM's own `Trace` orders them, so a statement that both
|
|
||||||
missed and ran slow is still reported as slow, and dropping the miss
|
|
||||||
costs an operator no report `IgnoreRecordNotFoundError` would have
|
|
||||||
kept. A GORM line spends at most two of those budgets — the statement
|
|
||||||
and the driver error — against a smaller fixed portion than the access
|
|
||||||
log's, and `internal/gormlog/gormlog_test.go` asserts each line against
|
|
||||||
`MaxAccessLogLineBytes` directly rather than leaving it as arithmetic.
|
`MaxAccessLogLineBytes` directly rather than leaving it as arithmetic.
|
||||||
|
|
||||||
What that ceiling does **not** cover, stated here so the figure is not
|
**What the ceiling does not cover.** It is a per-line bound on the
|
||||||
read as more than it is:
|
access log and on GORM's statement logging, not a bound on every line
|
||||||
|
this service writes. The exceptions are named here because a bound
|
||||||
|
that is true of one writer and silently false of another is worse than
|
||||||
|
no stated bound at all.
|
||||||
|
|
||||||
- **Lines carrying an authenticated operator's own input**, which are
|
- Other `slog` calls that reach a client-chosen value — the
|
||||||
not truncated at all. `webhook created` logs the submitted `name`
|
`MaxBodySize` rejection, the CSRF failure, the receiver rate-limit
|
||||||
verbatim and `target URL blocked by SSRF protection` logs the target
|
rejection, and the two lookup misses above — still log the request
|
||||||
host (both `internal/handlers/source_management.go`), as do the
|
path or the submitted username untruncated.
|
||||||
`target_name` lines in `internal/delivery/engine.go` and
|
- The `log` delivery target (`internal/delivery/target_log.go`) writes
|
||||||
`internal/delivery/target_http.go`. The only bound on any of them is
|
the entire inbound event, headers and body, to the log. That is what
|
||||||
the 1 MB form body cap, so a 100 KB `name` writes a single line of
|
the target is for. Each line is bounded per event by the 1 MB
|
||||||
roughly 600 KB — measured. This is deliberate: every one of these
|
receiver body cap, and it costs nothing unless an authenticated
|
||||||
requires an authenticated operator on a service with no
|
operator creates a target of that type.
|
||||||
self-registration, and truncating the operator's own configuration
|
- Two writers that do not go through `internal/logger` at all, both on
|
||||||
echoed back would cost debuggability against no adversary. It does
|
standard error. `fx` prints the dependency graph and the lifecycle
|
||||||
mean the 2,560-byte figure sizes unauthenticated traffic, not the
|
|
||||||
operator's own administrative requests.
|
|
||||||
- The **`log` delivery target**, which writes the whole inbound event —
|
|
||||||
headers and body — to the log. This one is deliberate: capping it
|
|
||||||
would defeat the target, since emitting the payload is the delivery.
|
|
||||||
It costs nothing unless an authenticated operator creates a target of
|
|
||||||
that type on a specific webhook, and each line it writes is bounded
|
|
||||||
per event by the 1 MB receiver body cap. Adding one is a decision to
|
|
||||||
spend log volume on that webhook's payloads.
|
|
||||||
- **Two writers that do not go through `internal/logger` at all**, both
|
|
||||||
on standard error. `fx` prints the dependency graph and the lifecycle
|
|
||||||
hooks through its default console logger at startup and shutdown —
|
hooks through its default console logger at startup and shutdown —
|
||||||
nothing calls `fx.WithLogger`, and `fx.New` builds that logger over
|
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
|
`os.Stderr`. The Go runtime writes a panic or a fatal error itself;
|
||||||
panic in a background worker rather than in a request handler is the
|
a panic in a background worker rather than in a request handler is
|
||||||
case that reaches it, since nothing recovers those. Neither carries a
|
the case that reaches it, since nothing recovers those. Neither
|
||||||
client-chosen value at a client-chosen length: the five `panic` calls
|
carries a client-chosen value at a client-chosen length: the five
|
||||||
in this service are invariant guards over constants and over
|
`panic` calls in this service are invariant guards over constants
|
||||||
`crypto/rand`.
|
and over `crypto/rand`.
|
||||||
- **`net/http`'s own faults**, which are _not_ a separate writer.
|
- `net/http`'s own faults, which are **not** a separate writer.
|
||||||
`internal/server/http.go` builds its server with a nil `ErrorLog`, so
|
`internal/server/http.go` builds its server with a nil `ErrorLog`,
|
||||||
`net/http` falls back to the `log` package's default logger — and
|
so `net/http` falls back to the `log` package's default logger — and
|
||||||
`internal/logger` calls `slog.SetDefault`, which redirects that logger
|
`internal/logger` calls `slog.SetDefault`, which redirects that
|
||||||
into whichever handler it installed. Those lines therefore arrive on
|
logger into whichever handler it installed. Those lines therefore
|
||||||
standard output, shaped like every other line, at `INFO`. They are not
|
arrive on standard output, shaped like every other line, at `INFO`.
|
||||||
truncated and they are not bounded by the ceiling: a handler panic
|
They are not truncated and they are not bounded by the ceiling: a
|
||||||
arrives as one record carrying a whole goroutine stack, above the
|
handler panic arrives as one record carrying a whole goroutine
|
||||||
ceiling's 2,560 bytes — measured at roughly 2,770 in one checkout. The
|
stack, measured at 2,772 bytes against the ceiling's 2,560. The
|
||||||
exact width is not an invariant, since it moves with the goroutine
|
value is the runtime's, not a client's.
|
||||||
number and with the source paths baked into the stack; that it exceeds
|
- A handler panic reaches that path rather than the one it looks like
|
||||||
the ceiling does not move. The value is the runtime's, not a client's.
|
it should. `internal/server/routes.go` installs chi's
|
||||||
- **A handler panic reaches that path** rather than the one it looks
|
|
||||||
like it should. `internal/server/routes.go` installs chi's
|
|
||||||
`middleware.Recoverer` in front of every route, which is meant to
|
`middleware.Recoverer` in front of every route, which is meant to
|
||||||
print the panic and its stack to standard error and answer 500. On the
|
print the panic and its stack to standard error and answer 500. On
|
||||||
Go version this service builds against it does neither: chi v1.5.5's
|
the Go version this service builds against it does neither: chi
|
||||||
stack pretty-printer looks for a `panic(0x` frame that the runtime no
|
v1.5.5's stack pretty-printer looks for a `panic(0x` frame that the
|
||||||
longer emits, walks past the end of its own slice, and panics before
|
runtime no longer emits, walks past the end of its own slice, and
|
||||||
writing a byte. That second panic escapes to `net/http`, which drops
|
panics before writing a byte. That second panic escapes to
|
||||||
the connection and reports it through the nil `ErrorLog` above.
|
`net/http`, which drops the connection and reports it through the
|
||||||
Tracked separately in
|
nil `ErrorLog` above. Tracked separately in
|
||||||
<https://git.eeqj.de/sneak/webhooker/issues/187>.
|
https://git.eeqj.de/sneak/webhooker/issues/187.
|
||||||
|
|
||||||
Every limiter here — receiver, login, and password change — identifies
|
Every limiter here — receiver, login, and password change — identifies
|
||||||
the client the same way, through one shared key function: the
|
the client the same way, through one shared key function: the
|
||||||
|
|||||||
78
TODO.md
78
TODO.md
@@ -24,9 +24,8 @@ event retention (#63), the database archiving target (#43), the admin
|
|||||||
password change flow (#65), policy compliance (#6), pinned lint tooling
|
password change flow (#65), policy compliance (#6), pinned lint tooling
|
||||||
(#55), and fail-loud configuration parsing (#80).
|
(#55), and fail-loud configuration parsing (#80).
|
||||||
|
|
||||||
`next` holds the 1.0.0 milestone less its final four issues (#176, #178,
|
`next` holds the completed 1.0.0 milestone: every issue in it is closed,
|
||||||
#186, #187 — all in review or held on merge order), and is verified
|
and it is verified green by cache-defeated container runs
|
||||||
green by cache-defeated container runs
|
|
||||||
(`docker build --no-cache-filter=lint --no-cache-filter=builder`). The
|
(`docker build --no-cache-filter=lint --no-cache-filter=builder`). The
|
||||||
CI status is not independently claimed here: a superseded run is
|
CI status is not independently claimed here: a superseded run is
|
||||||
recorded as `skipped` and still rolls up green, so a commit status on
|
recorded as `skipped` and still rolls up green, so a commit status on
|
||||||
@@ -40,78 +39,15 @@ of 2026-07-06.
|
|||||||
|
|
||||||
# Next Step
|
# Next Step
|
||||||
|
|
||||||
Land the last four 1.0.0 issues, then merge the milestone PR to `main`
|
Merge the milestone PR to `main` and tag 1.0.0 from it.
|
||||||
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.
|
|
||||||
|
|
||||||
Two items belong to the owner, neither blocking the tag. #150 was
|
Two decisions are open and belong to the owner, neither blocking the
|
||||||
decided by the manager rather than left to stall the queue and is
|
tag: #115 (mask the `http` target's destination URL, implemented
|
||||||
flagged on the issue for reversal if that call was wrong. #112 (whether
|
speculatively and awaiting a yes or no) and #125 (whether IPv6
|
||||||
`Completed Steps` should exist at all, given it once conflicted on every
|
rate-limit keys should bucket by `/64`).
|
||||||
unit) is unanswered; the provisional ruling in force is that issue
|
|
||||||
branches do not touch this file.
|
|
||||||
|
|
||||||
# Completed Steps
|
# Completed Steps
|
||||||
|
|
||||||
- 2026-08-18 Send the chi route pattern to Sentry rather than the
|
|
||||||
concrete path. The receiver's path carries the entrypoint capability
|
|
||||||
token, so every Sentry event from `/webhook/{uuid}` shipped a live
|
|
||||||
credential to a third party. Request `Data`, `QueryString`, `Cookies`
|
|
||||||
and `Env` are dropped and headers reduced to an allowlist (#179)
|
|
||||||
- 2026-08-18 Read form fields from the POST body only. `r.FormValue`
|
|
||||||
merges the query string, so a login could be driven by URL parameters
|
|
||||||
— putting the password somewhere that lands in access logs, proxy
|
|
||||||
logs and browser history (#160)
|
|
||||||
- 2026-08-18 Verify login credentials before spending rate-limit
|
|
||||||
budget, so a flood of wrong passwords cannot lock out the account it
|
|
||||||
is guessing at. The manager took this decision rather than stall the
|
|
||||||
queue; it is flagged on the issue for reversal (#150)
|
|
||||||
- 2026-08-18 Run all linting in Docker via `Dockerfile.lint`. Host lint
|
|
||||||
was wrong in both directions from version skew and shared caches.
|
|
||||||
`script/lint` asserts the summary line, because `--no-cache-filter`
|
|
||||||
silently ignores a stage name it does not match — the flag that makes
|
|
||||||
the gate meaningful fails open (#109)
|
|
||||||
- 2026-08-18 Serve an event's full stored body over HTTP. The list
|
|
||||||
query truncates for rendering, and that truncated value was the only
|
|
||||||
way to read a body, so the full payload was unreachable (#157)
|
|
||||||
- 2026-08-18 Bound the access log line against client-chosen text.
|
|
||||||
`internal/logfield` budgets by *encoded* bytes, not runes, so a
|
|
||||||
handler's JSON escaping cannot multiply a field past its allowance
|
|
||||||
(#146)
|
|
||||||
- 2026-08-18 Mark superseded CI commits `failure` rather than
|
|
||||||
`skipped`. A skipped run rolls up green, so a commit that was never
|
|
||||||
tested reported success (#152)
|
|
||||||
- 2026-08-18 Set `fx.StopTimeout` inside the container stop grace, so
|
|
||||||
shutdown hooks are bounded by a deadline the orchestrator will
|
|
||||||
actually honour rather than being killed mid-flush (#134)
|
|
||||||
- 2026-08-17 Bucket IPv6 rate-limit keys by `/64`. A single allocation
|
|
||||||
hands out 2^64 addresses, so per-address keying let one client mint
|
|
||||||
unlimited buckets. Manager decision, recorded on the issue (#125)
|
|
||||||
- 2026-08-17 Correct release-blocking README and startup-warning
|
|
||||||
inaccuracies, including claims about behaviour the code does not have
|
|
||||||
(#151)
|
|
||||||
- 2026-08-17 Fetch and verify Alpine.js at build time against
|
|
||||||
`static/vendor.sha256` instead of committing the minified blob, so
|
|
||||||
the dependency is pinned by hash rather than by trust (#145)
|
|
||||||
- 2026-08-17 Bound the event log's rendered bodies in the query itself,
|
|
||||||
so a large stored payload cannot be read into memory just to be
|
|
||||||
truncated for display (#135)
|
|
||||||
- 2026-08-17 Mask the `http` target's destination URL in the UI: it can
|
|
||||||
carry a bearer credential in its path or query, and was rendered
|
|
||||||
verbatim. Manager decision to mask unconditionally (#115)
|
|
||||||
- 2026-08-14 Bound shutdown hooks by their stop context, so a hook that
|
|
||||||
hangs cannot hold the process past its grace period (#102)
|
|
||||||
- 2026-08-14 Render templates via a buffer rather than the
|
|
||||||
`ResponseWriter`, so a template error part-way through cannot commit
|
|
||||||
a 200 and then fail — the response is written only once it is whole
|
|
||||||
(#123)
|
|
||||||
- 2026-08-14 Align the session codec's max-age with the 7-day absolute
|
|
||||||
cap. The codec accepted cookies the session layer considered expired,
|
|
||||||
so the cap was enforced in one place and not the other (#108)
|
|
||||||
- 2026-08-12 Warn when `TRUSTED_PROXIES` is empty in production, where
|
|
||||||
the safe default silently discards forwarded headers and every client
|
|
||||||
rate-limits as the proxy's address (#149)
|
|
||||||
- 2026-08-12 Bound the receiver rate limit per client IP across the
|
- 2026-08-12 Bound the receiver rate limit per client IP across the
|
||||||
whole `/webhook/*` route. The existing limiter keyed on the request
|
whole `/webhook/*` route. The existing limiter keyed on the request
|
||||||
path and `/webhook/{uuid}` matches any single segment, so a client
|
path and `/webhook/{uuid}` matches any single segment, so a client
|
||||||
|
|||||||
@@ -339,12 +339,7 @@ func TestWebhookDBManager_MultipleWebhooks(t *testing.T) {
|
|||||||
var events []database.Event
|
var events []database.Event
|
||||||
|
|
||||||
require.NoError(t, db2.Find(&events).Error)
|
require.NoError(t, db2.Find(&events).Error)
|
||||||
|
assert.Len(t, events, 1)
|
||||||
// require, not assert: this is exactly the regression the test
|
|
||||||
// guards, so the empty slice is the expected failure, and a
|
|
||||||
// non-fatal length check would index into it on the next line and
|
|
||||||
// panic the whole package test binary instead of failing here.
|
|
||||||
require.Len(t, events, 1)
|
|
||||||
assert.Equal(t, "PUT", events[0].Method)
|
assert.Equal(t, "PUT", events[0].Method)
|
||||||
}
|
}
|
||||||
|
|
||||||
|
|||||||
@@ -11,17 +11,6 @@ import (
|
|||||||
// inbound webhook — the full request body and headers, plus
|
// inbound webhook — the full request body and headers, plus
|
||||||
// the method, content type, and the webhook and entrypoint
|
// the method, content type, and the webhook and entrypoint
|
||||||
// ids — then records a single successful attempt.
|
// ids — then records a single successful attempt.
|
||||||
//
|
|
||||||
// This is the one log call in the service that deliberately writes
|
|
||||||
// unbounded client-chosen bytes, so it is the one exception to the
|
|
||||||
// per-field budgets in internal/logfield and to the ceiling stated on
|
|
||||||
// middleware.MaxAccessLogLineBytes. Capping here would defeat the
|
|
||||||
// target: emitting the payload IS the delivery. It costs nothing by
|
|
||||||
// default — an authenticated operator has to create a target of this
|
|
||||||
// type on a specific webhook before a single line is written — and the
|
|
||||||
// bytes it writes are bounded per event by maxWebhookBodySize (1 MB).
|
|
||||||
// An operator who adds one is choosing to spend log volume on the
|
|
||||||
// payloads that webhook receives.
|
|
||||||
type logTarget struct {
|
type logTarget struct {
|
||||||
eng *Engine
|
eng *Engine
|
||||||
}
|
}
|
||||||
|
|||||||
@@ -334,17 +334,13 @@ func TestStatementError_LineIsBounded(t *testing.T) {
|
|||||||
func TestSucceedingStatement_LineIsBoundedOnEitherArm(t *testing.T) {
|
func TestSucceedingStatement_LineIsBoundedOnEitherArm(t *testing.T) {
|
||||||
t.Parallel()
|
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 {
|
arms := []struct {
|
||||||
name string
|
name string
|
||||||
slow time.Duration
|
slow time.Duration
|
||||||
want string
|
want string
|
||||||
notWant string
|
|
||||||
}{
|
}{
|
||||||
{"slow", alwaysSlow, "slow sql statement", ""},
|
{"slow", alwaysSlow, "slow sql statement"},
|
||||||
{"routine", neverSlow, "sql statement", "slow sql statement"},
|
{"routine", neverSlow, "sql statement"},
|
||||||
}
|
}
|
||||||
|
|
||||||
for _, a := range arms {
|
for _, a := range arms {
|
||||||
@@ -366,13 +362,6 @@ func TestSucceedingStatement_LineIsBoundedOnEitherArm(t *testing.T) {
|
|||||||
).Find(&got).Error)
|
).Find(&got).Error)
|
||||||
|
|
||||||
assert.Contains(t, buf.String(), a.want)
|
assert.Contains(t, buf.String(), a.want)
|
||||||
|
|
||||||
if a.notWant != "" {
|
|
||||||
assert.NotContains(
|
|
||||||
t, buf.String(), a.notWant,
|
|
||||||
)
|
|
||||||
}
|
|
||||||
|
|
||||||
assertBounded(t, buf.String())
|
assertBounded(t, buf.String())
|
||||||
})
|
})
|
||||||
}
|
}
|
||||||
|
|||||||
@@ -5,7 +5,6 @@ import (
|
|||||||
"strconv"
|
"strconv"
|
||||||
|
|
||||||
"sneak.berlin/go/webhooker/internal/database"
|
"sneak.berlin/go/webhooker/internal/database"
|
||||||
"sneak.berlin/go/webhooker/internal/logfield"
|
|
||||||
)
|
)
|
||||||
|
|
||||||
// HandleLoginPage returns a handler for the login page (GET)
|
// HandleLoginPage returns a handler for the login page (GET)
|
||||||
@@ -71,9 +70,7 @@ func (h *Handlers) HandleLoginSubmit() http.HandlerFunc {
|
|||||||
|
|
||||||
h.log.Info(
|
h.log.Info(
|
||||||
"user logged in",
|
"user logged in",
|
||||||
"username", logfield.Truncate(
|
"username", username,
|
||||||
username, logfield.MaxBytes,
|
|
||||||
),
|
|
||||||
"user_id", user.ID,
|
"user_id", user.ID,
|
||||||
)
|
)
|
||||||
|
|
||||||
@@ -120,9 +117,7 @@ func (h *Handlers) authenticateUser(
|
|||||||
if !ok {
|
if !ok {
|
||||||
h.log.Warn(
|
h.log.Warn(
|
||||||
"password verification capacity exhausted",
|
"password verification capacity exhausted",
|
||||||
"path", logfield.Truncate(
|
"path", r.URL.Path,
|
||||||
r.URL.Path, logfield.MaxBytes,
|
|
||||||
),
|
|
||||||
)
|
)
|
||||||
h.renderLoginError(
|
h.renderLoginError(
|
||||||
w, r,
|
w, r,
|
||||||
@@ -147,17 +142,7 @@ func (h *Handlers) authenticateUser(
|
|||||||
h.dummyVerifications.Add(1)
|
h.dummyVerifications.Add(1)
|
||||||
database.VerifyDummyPassword(password)
|
database.VerifyDummyPassword(password)
|
||||||
|
|
||||||
// Login is unauthenticated, and the submitted username is
|
h.log.Debug("user not found", "username", username)
|
||||||
// a form field the client fills to any length the 1 MB
|
|
||||||
// body cap allows. On this branch it matched no row, so
|
|
||||||
// nothing else bounds it. The rate limiter caps how often
|
|
||||||
// the line is written, not how wide it is.
|
|
||||||
h.log.Debug(
|
|
||||||
"user not found",
|
|
||||||
"username", logfield.Truncate(
|
|
||||||
username, logfield.MaxBytes,
|
|
||||||
),
|
|
||||||
)
|
|
||||||
h.rejectLogin(w, r, username)
|
h.rejectLogin(w, r, username)
|
||||||
|
|
||||||
return user, err
|
return user, err
|
||||||
@@ -175,17 +160,7 @@ func (h *Handlers) authenticateUser(
|
|||||||
}
|
}
|
||||||
|
|
||||||
if !valid {
|
if !valid {
|
||||||
// Reached only once the username matched a stored row, so
|
h.log.Debug("invalid password", "username", username)
|
||||||
// it is bounded by the operator's own data. Capped anyway,
|
|
||||||
// so that every username this unauthenticated endpoint
|
|
||||||
// logs is capped and no reader has to work out which
|
|
||||||
// branch narrowed it.
|
|
||||||
h.log.Debug(
|
|
||||||
"invalid password",
|
|
||||||
"username", logfield.Truncate(
|
|
||||||
username, logfield.MaxBytes,
|
|
||||||
),
|
|
||||||
)
|
|
||||||
h.rejectLogin(w, r, username)
|
h.rejectLogin(w, r, username)
|
||||||
|
|
||||||
return user, errInvalidPassword
|
return user, errInvalidPassword
|
||||||
|
|||||||
@@ -2,19 +2,11 @@ package handlers
|
|||||||
|
|
||||||
import (
|
import (
|
||||||
"html/template"
|
"html/template"
|
||||||
"log/slog"
|
|
||||||
"net/http"
|
"net/http"
|
||||||
|
|
||||||
"sneak.berlin/go/webhooker/internal/database"
|
"sneak.berlin/go/webhooker/internal/database"
|
||||||
)
|
)
|
||||||
|
|
||||||
// SetLogForTest replaces the handler's logger, so the handlers_test
|
|
||||||
// package can assert on what a log line actually contains rather than
|
|
||||||
// on what it is meant to contain.
|
|
||||||
func (s *Handlers) SetLogForTest(log *slog.Logger) {
|
|
||||||
s.log = log
|
|
||||||
}
|
|
||||||
|
|
||||||
// MaxRenderedBodyBytesForTest exposes the event log's body cap
|
// MaxRenderedBodyBytesForTest exposes the event log's body cap
|
||||||
// to the handlers_test package.
|
// to the handlers_test package.
|
||||||
const MaxRenderedBodyBytesForTest = maxRenderedBodyBytes
|
const MaxRenderedBodyBytesForTest = maxRenderedBodyBytes
|
||||||
|
|||||||
@@ -7,6 +7,7 @@ import (
|
|||||||
"log"
|
"log"
|
||||||
"net/http"
|
"net/http"
|
||||||
"net/http/httptest"
|
"net/http/httptest"
|
||||||
|
"net/url"
|
||||||
"os"
|
"os"
|
||||||
"strconv"
|
"strconv"
|
||||||
"strings"
|
"strings"
|
||||||
@@ -243,7 +244,7 @@ func floodUnauthenticated(
|
|||||||
|
|
||||||
for range reps {
|
for range reps {
|
||||||
postWebhook(t, h, value)
|
postWebhook(t, h, value)
|
||||||
postUnknownLogin(t, h, value)
|
postLogin(t, h, value)
|
||||||
|
|
||||||
requests += 2
|
requests += 2
|
||||||
}
|
}
|
||||||
@@ -323,15 +324,29 @@ func postWebhook(
|
|||||||
require.Equal(t, http.StatusNotFound, w.Code)
|
require.Equal(t, http.StatusNotFound, w.Code)
|
||||||
}
|
}
|
||||||
|
|
||||||
// postUnknownLogin submits the login form with an unknown username,
|
// postLogin submits the login form with an unknown username. The
|
||||||
// through the postLogin helper in logbound_test.go. The field is
|
// field is bounded only by the 1 MB body cap, and the lookup behind
|
||||||
// bounded only by the 1 MB body cap, and the lookup behind it misses
|
// it misses by design.
|
||||||
// by design.
|
func postLogin(
|
||||||
func postUnknownLogin(
|
|
||||||
t *testing.T, h *handlers.Handlers, username string,
|
t *testing.T, h *handlers.Handlers, username string,
|
||||||
) {
|
) {
|
||||||
t.Helper()
|
t.Helper()
|
||||||
|
|
||||||
|
form := url.Values{}
|
||||||
|
form.Set("username", username)
|
||||||
|
form.Set("password", "not-the-password")
|
||||||
|
|
||||||
|
req := httptest.NewRequestWithContext(
|
||||||
|
context.Background(), http.MethodPost, "/pages/login",
|
||||||
|
strings.NewReader(form.Encode()),
|
||||||
|
)
|
||||||
|
req.Header.Set(
|
||||||
|
"Content-Type", "application/x-www-form-urlencoded",
|
||||||
|
)
|
||||||
|
|
||||||
|
w := httptest.NewRecorder()
|
||||||
|
h.HandleLoginSubmit().ServeHTTP(w, req)
|
||||||
|
|
||||||
// 401 while the client still has failure budget against this
|
// 401 while the client still has failure budget against this
|
||||||
// username, 429 once the login guard has taken it away. Both
|
// username, 429 once the login guard has taken it away. Both
|
||||||
// outcomes sit behind the user lookup, which is the query this
|
// outcomes sit behind the user lookup, which is the query this
|
||||||
@@ -339,7 +354,7 @@ func postUnknownLogin(
|
|||||||
require.Contains(
|
require.Contains(
|
||||||
t,
|
t,
|
||||||
[]int{http.StatusUnauthorized, http.StatusTooManyRequests},
|
[]int{http.StatusUnauthorized, http.StatusTooManyRequests},
|
||||||
postLogin(t, h, username),
|
w.Code,
|
||||||
)
|
)
|
||||||
}
|
}
|
||||||
|
|
||||||
@@ -390,11 +405,11 @@ func assertFloodBounded(t *testing.T, label, out string) {
|
|||||||
// the adapter drops the record-not-found, so the capture holds
|
// the adapter drops the record-not-found, so the capture holds
|
||||||
// nothing but fixed-string warnings.
|
// nothing but fixed-string warnings.
|
||||||
//
|
//
|
||||||
// The level is left where newTestApp leaves it, at INFO: the level an
|
// The level is left where newTestApp leaves it, at INFO, deliberately.
|
||||||
// operator runs at by default, and the one the defect was visible at.
|
// At DEBUG the handlers' own miss lines log the client-chosen
|
||||||
// The handlers' own miss lines sit at DEBUG and spend the same
|
// entrypoint and username untruncated — the first carve-out in the
|
||||||
// logfield budget as everything else, so they are not what makes
|
// README's ceiling section, and https://git.eeqj.de/sneak/webhooker/issues/176's
|
||||||
// either assertion above bite at any level.
|
// to fix, not this one's.
|
||||||
//
|
//
|
||||||
// It is deliberately not parallel: it redirects os.Stdout and replaces
|
// It is deliberately not parallel: it redirects os.Stdout and replaces
|
||||||
// gormlogger.Default, both of which are process-global. Go runs every
|
// gormlogger.Default, both of which are process-global. Go runs every
|
||||||
|
|||||||
@@ -1,543 +0,0 @@
|
|||||||
package handlers_test
|
|
||||||
|
|
||||||
// The handler-side half of the log-field audit. Two slog calls in
|
|
||||||
// this package reach a value an UNAUTHENTICATED client picks outright
|
|
||||||
// and of a length it picks outright:
|
|
||||||
//
|
|
||||||
// - the unknown-entrypoint DEBUG line on /webhook/{uuid}, whose
|
|
||||||
// path segment matched no stored entrypoint and so is bounded by
|
|
||||||
// nothing;
|
|
||||||
// - the failed-login DEBUG lines, whose username is a form field.
|
|
||||||
//
|
|
||||||
// Both are at DEBUG, which is off in production by default. That is
|
|
||||||
// not a bound: an operator turning DEBUG on to diagnose a flood must
|
|
||||||
// not thereby hand the flood an unbounded write. Both spend the same
|
|
||||||
// internal/logfield budget as the access log, and both are held here
|
|
||||||
// to middleware.MaxAccessLogLineBytes.
|
|
||||||
//
|
|
||||||
// The two login lines past the username lookup — "invalid password"
|
|
||||||
// and "user logged in" — carry the same cap without needing it, since
|
|
||||||
// by then the value is a stored row rather than the client's. They are
|
|
||||||
// pinned here too, so the caps cannot be dropped silently.
|
|
||||||
//
|
|
||||||
// So is the "password verification capacity exhausted" WARN line,
|
|
||||||
// whose path chi pins to the constant "/pages/login" on the one route
|
|
||||||
// that reaches it. Its cap is defensive, and the test below drives the
|
|
||||||
// handler directly with the path a parameterised route would give it,
|
|
||||||
// because an unasserted cap is one a later edit removes for free.
|
|
||||||
|
|
||||||
import (
|
|
||||||
"bytes"
|
|
||||||
"context"
|
|
||||||
"io"
|
|
||||||
"log/slog"
|
|
||||||
"net/http"
|
|
||||||
"net/http/httptest"
|
|
||||||
"net/url"
|
|
||||||
"strings"
|
|
||||||
"testing"
|
|
||||||
|
|
||||||
"github.com/go-chi/chi"
|
|
||||||
"github.com/stretchr/testify/assert"
|
|
||||||
"github.com/stretchr/testify/require"
|
|
||||||
"sneak.berlin/go/webhooker/internal/database"
|
|
||||||
"sneak.berlin/go/webhooker/internal/handlers"
|
|
||||||
"sneak.berlin/go/webhooker/internal/middleware"
|
|
||||||
)
|
|
||||||
|
|
||||||
// floodRequests is the number of distinct invented values each flood
|
|
||||||
// drives through the call site under test.
|
|
||||||
const floodRequests = 32
|
|
||||||
|
|
||||||
// oversizedFillBytes is the length of the single client-chosen value
|
|
||||||
// used to show that line size does not track input size.
|
|
||||||
const oversizedFillBytes = 8192
|
|
||||||
|
|
||||||
// attackerMarker and tailMarker sit at the END of every oversized
|
|
||||||
// value, past every budget. Their absence from the log is what
|
|
||||||
// proves the value was cut rather than merely being short.
|
|
||||||
const (
|
|
||||||
attackerMarker = "QQATTACKERTEXTQQ"
|
|
||||||
tailMarker = "QQTRUNCATEDTAILQQ"
|
|
||||||
)
|
|
||||||
|
|
||||||
// escapeFills are the characters the log handlers escape, so a value
|
|
||||||
// built out of them costs more on the line than it did on the wire. A
|
|
||||||
// budget counted in raw bytes passes the plain case and fails these.
|
|
||||||
//
|
|
||||||
// U+1000C is unassigned, hence non-printable, and strconv.Quote
|
|
||||||
// spells it as a ten-byte \UXXXXXXXX while the JSON handler passes
|
|
||||||
// its four UTF-8 bytes through; only the text shape of these tests
|
|
||||||
// reaches that charge.
|
|
||||||
func escapeFills() map[string]string {
|
|
||||||
return map[string]string{
|
|
||||||
"plain": "x",
|
|
||||||
"quote": `"`,
|
|
||||||
"backslash": `\`,
|
|
||||||
"tab": "\t",
|
|
||||||
"newline": "\n",
|
|
||||||
// A C0 control neither handler has a short escape for, so
|
|
||||||
// each one costs six bytes on the line against the single
|
|
||||||
// byte it cost to send: the widest multiplier a client can
|
|
||||||
// drive, and the case a raw-byte budget breaks on first.
|
|
||||||
//
|
|
||||||
// This fill is load-bearing, not decoration. Budgeting raw
|
|
||||||
// bytes instead of encoded is caught by this fill alone,
|
|
||||||
// and only under the JSON handler, at 3,072 bytes against
|
|
||||||
// the 2,560 ceiling. Drop it and that mutation passes.
|
|
||||||
"control": "\x01",
|
|
||||||
"astral": "\U0001000C",
|
|
||||||
}
|
|
||||||
}
|
|
||||||
|
|
||||||
// logHandlers are the two handlers internal/logger can install.
|
|
||||||
func logHandlers() map[string]func(
|
|
||||||
io.Writer, *slog.HandlerOptions,
|
|
||||||
) slog.Handler {
|
|
||||||
return map[string]func(
|
|
||||||
io.Writer, *slog.HandlerOptions,
|
|
||||||
) slog.Handler{
|
|
||||||
"json": func(
|
|
||||||
w io.Writer, o *slog.HandlerOptions,
|
|
||||||
) slog.Handler {
|
|
||||||
return slog.NewJSONHandler(w, o)
|
|
||||||
},
|
|
||||||
"text": func(
|
|
||||||
w io.Writer, o *slog.HandlerOptions,
|
|
||||||
) slog.Handler {
|
|
||||||
return slog.NewTextHandler(w, o)
|
|
||||||
},
|
|
||||||
}
|
|
||||||
}
|
|
||||||
|
|
||||||
// oversizedFill builds an 8 KB client-chosen value out of
|
|
||||||
// repetitions of ch, with both markers at its far end.
|
|
||||||
func oversizedFill(ch string) string {
|
|
||||||
return "x" + strings.Repeat(ch, oversizedFillBytes) +
|
|
||||||
attackerMarker + tailMarker
|
|
||||||
}
|
|
||||||
|
|
||||||
// capturingHandlers builds a Handlers whose log is captured into the
|
|
||||||
// returned buffer at DEBUG through the named handler.
|
|
||||||
//
|
|
||||||
// extra is passed to fx.Populate alongside the Handlers, for the call
|
|
||||||
// sites that also need the database the client's value is looked up
|
|
||||||
// in, or the Middleware whose resource has to be exhausted before the
|
|
||||||
// branch under test is reached.
|
|
||||||
func capturingHandlers(
|
|
||||||
t *testing.T,
|
|
||||||
newHandler func(io.Writer, *slog.HandlerOptions) slog.Handler,
|
|
||||||
extra ...any,
|
|
||||||
) (*handlers.Handlers, *bytes.Buffer) {
|
|
||||||
t.Helper()
|
|
||||||
|
|
||||||
var h *handlers.Handlers
|
|
||||||
|
|
||||||
app := newTestApp(t, append([]any{&h}, extra...)...)
|
|
||||||
app.RequireStart()
|
|
||||||
|
|
||||||
t.Cleanup(app.RequireStop)
|
|
||||||
|
|
||||||
buf := new(bytes.Buffer)
|
|
||||||
h.SetLogForTest(slog.New(newHandler(
|
|
||||||
buf, &slog.HandlerOptions{Level: slog.LevelDebug},
|
|
||||||
)))
|
|
||||||
|
|
||||||
return h, buf
|
|
||||||
}
|
|
||||||
|
|
||||||
// logLines splits the captured buffer into non-empty lines, holding
|
|
||||||
// each to the stated per-line ceiling.
|
|
||||||
func logLines(t *testing.T, buf *bytes.Buffer) []string {
|
|
||||||
t.Helper()
|
|
||||||
|
|
||||||
var lines []string
|
|
||||||
|
|
||||||
for line := range strings.SplitSeq(
|
|
||||||
strings.TrimSpace(buf.String()), "\n",
|
|
||||||
) {
|
|
||||||
if line == "" {
|
|
||||||
continue
|
|
||||||
}
|
|
||||||
|
|
||||||
require.LessOrEqual(
|
|
||||||
t, len(line), middleware.MaxAccessLogLineBytes,
|
|
||||||
"log line exceeded its bound: %s", line,
|
|
||||||
)
|
|
||||||
|
|
||||||
lines = append(lines, line)
|
|
||||||
}
|
|
||||||
|
|
||||||
return lines
|
|
||||||
}
|
|
||||||
|
|
||||||
// assertNoClientText fails if the far end of the client-chosen input
|
|
||||||
// survived into the log.
|
|
||||||
func assertNoClientText(t *testing.T, buf *bytes.Buffer) {
|
|
||||||
t.Helper()
|
|
||||||
|
|
||||||
assert.NotContains(
|
|
||||||
t, buf.String(), attackerMarker,
|
|
||||||
"log carried attacker-chosen text",
|
|
||||||
)
|
|
||||||
assert.NotContains(
|
|
||||||
t, buf.String(), tailMarker,
|
|
||||||
"log carried the tail of the attacker-chosen text",
|
|
||||||
)
|
|
||||||
}
|
|
||||||
|
|
||||||
// receiverRouter mounts the real receiver handler at the production
|
|
||||||
// route pattern.
|
|
||||||
func receiverRouter(h *handlers.Handlers) *chi.Mux {
|
|
||||||
router := chi.NewRouter()
|
|
||||||
router.Post("/webhook/{uuid}", h.HandleWebhook())
|
|
||||||
|
|
||||||
return router
|
|
||||||
}
|
|
||||||
|
|
||||||
// postReceiver sends one POST at /webhook/<segment>.
|
|
||||||
//
|
|
||||||
// RawPath is cleared after parsing so chi routes on the decoded path
|
|
||||||
// and the handler sees the raw bytes rather than their percent-escaped
|
|
||||||
// spelling. That is the harder case for the budget: the escaped
|
|
||||||
// spelling is plain ASCII, which costs one byte per byte, while the
|
|
||||||
// decoded bytes are what the log handler has to escape.
|
|
||||||
func postReceiver(
|
|
||||||
t *testing.T, router *chi.Mux, segment string,
|
|
||||||
) int {
|
|
||||||
t.Helper()
|
|
||||||
|
|
||||||
req := httptest.NewRequestWithContext(
|
|
||||||
context.Background(),
|
|
||||||
http.MethodPost,
|
|
||||||
"/webhook/"+url.PathEscape(segment),
|
|
||||||
strings.NewReader(""),
|
|
||||||
)
|
|
||||||
req.URL.RawPath = ""
|
|
||||||
|
|
||||||
w := httptest.NewRecorder()
|
|
||||||
router.ServeHTTP(w, req)
|
|
||||||
|
|
||||||
return w.Code
|
|
||||||
}
|
|
||||||
|
|
||||||
// postLogin submits the login form with the given username and a
|
|
||||||
// non-empty password.
|
|
||||||
func postLogin(
|
|
||||||
t *testing.T, h *handlers.Handlers, username string,
|
|
||||||
) int {
|
|
||||||
t.Helper()
|
|
||||||
|
|
||||||
return postLoginWithPassword(t, h, username, "not-the-password")
|
|
||||||
}
|
|
||||||
|
|
||||||
// postLoginWithPassword submits the login form with both credentials
|
|
||||||
// chosen by the caller, so a test can reach the branches past the
|
|
||||||
// username lookup.
|
|
||||||
func postLoginWithPassword(
|
|
||||||
t *testing.T, h *handlers.Handlers, username, password string,
|
|
||||||
) int {
|
|
||||||
t.Helper()
|
|
||||||
|
|
||||||
form := url.Values{
|
|
||||||
"username": {username},
|
|
||||||
"password": {password},
|
|
||||||
}
|
|
||||||
|
|
||||||
req := httptest.NewRequestWithContext(
|
|
||||||
context.Background(),
|
|
||||||
http.MethodPost,
|
|
||||||
"/pages/login",
|
|
||||||
strings.NewReader(form.Encode()),
|
|
||||||
)
|
|
||||||
req.Header.Set(
|
|
||||||
"Content-Type", "application/x-www-form-urlencoded",
|
|
||||||
)
|
|
||||||
|
|
||||||
w := httptest.NewRecorder()
|
|
||||||
h.HandleLoginSubmit().ServeHTTP(w, req)
|
|
||||||
|
|
||||||
return w.Code
|
|
||||||
}
|
|
||||||
|
|
||||||
// TestUnknownEntrypoint_LogLineDoesNotTrackPathSize drives 8 KB of
|
|
||||||
// client-chosen path at the unauthenticated receiver's
|
|
||||||
// unknown-entrypoint DEBUG line and holds it to the same ceiling the
|
|
||||||
// access log states.
|
|
||||||
func TestUnknownEntrypoint_LogLineDoesNotTrackPathSize(t *testing.T) {
|
|
||||||
t.Parallel()
|
|
||||||
|
|
||||||
for handlerName, newHandler := range logHandlers() {
|
|
||||||
for fillName, fill := range escapeFills() {
|
|
||||||
t.Run(handlerName+"/"+fillName, func(t *testing.T) {
|
|
||||||
t.Parallel()
|
|
||||||
|
|
||||||
h, buf := capturingHandlers(t, newHandler)
|
|
||||||
router := receiverRouter(h)
|
|
||||||
|
|
||||||
for i := range floodRequests {
|
|
||||||
assert.Equal(
|
|
||||||
t,
|
|
||||||
http.StatusNotFound,
|
|
||||||
postReceiver(
|
|
||||||
t, router,
|
|
||||||
oversizedFill(fill)+
|
|
||||||
strings.Repeat("y", i),
|
|
||||||
),
|
|
||||||
)
|
|
||||||
}
|
|
||||||
|
|
||||||
lines := logLines(t, buf)
|
|
||||||
require.Len(t, lines, floodRequests)
|
|
||||||
assertNoClientText(t, buf)
|
|
||||||
|
|
||||||
assertBoundedFlood(t, buf.Len())
|
|
||||||
})
|
|
||||||
}
|
|
||||||
}
|
|
||||||
}
|
|
||||||
|
|
||||||
// TestFailedLogin_LogLineDoesNotTrackUsernameSize drives 8 KB of
|
|
||||||
// client-chosen username at the unauthenticated login endpoint's
|
|
||||||
// DEBUG line and holds it to the same ceiling.
|
|
||||||
func TestFailedLogin_LogLineDoesNotTrackUsernameSize(t *testing.T) {
|
|
||||||
t.Parallel()
|
|
||||||
|
|
||||||
for handlerName, newHandler := range logHandlers() {
|
|
||||||
for fillName, fill := range escapeFills() {
|
|
||||||
t.Run(handlerName+"/"+fillName, func(t *testing.T) {
|
|
||||||
t.Parallel()
|
|
||||||
|
|
||||||
h, buf := capturingHandlers(t, newHandler)
|
|
||||||
|
|
||||||
for i := range floodRequests {
|
|
||||||
assert.Equal(
|
|
||||||
t,
|
|
||||||
http.StatusUnauthorized,
|
|
||||||
postLogin(
|
|
||||||
t, h,
|
|
||||||
oversizedFill(fill)+
|
|
||||||
strings.Repeat("y", i),
|
|
||||||
),
|
|
||||||
)
|
|
||||||
}
|
|
||||||
|
|
||||||
lines := logLines(t, buf)
|
|
||||||
require.Len(t, lines, floodRequests)
|
|
||||||
assertNoClientText(t, buf)
|
|
||||||
|
|
||||||
assertBoundedFlood(t, buf.Len())
|
|
||||||
})
|
|
||||||
}
|
|
||||||
}
|
|
||||||
}
|
|
||||||
|
|
||||||
// storedUserPassword is the password held by the oversize accounts
|
|
||||||
// the test below creates.
|
|
||||||
const storedUserPassword = "correct-horse-battery-staple"
|
|
||||||
|
|
||||||
// storedFillBytes is the raw length of the client-chosen value in
|
|
||||||
// those accounts' usernames. It is well past the 512-byte field
|
|
||||||
// budget, so the line is still truncated, but short enough that the
|
|
||||||
// session cookie a successful login writes stays inside
|
|
||||||
// securecookie's 4 KB limit: the cookie is written BEFORE the
|
|
||||||
// "user logged in" line, so an 8 KB username answers 500 and never
|
|
||||||
// reaches it.
|
|
||||||
const storedFillBytes = 1024
|
|
||||||
|
|
||||||
// storedFill builds a username fill of storedFillBytes raw bytes out
|
|
||||||
// of repetitions of ch, with both markers at its far end.
|
|
||||||
func storedFill(ch string) string {
|
|
||||||
return "x" + strings.Repeat(ch, storedFillBytes/len(ch)) +
|
|
||||||
attackerMarker + tailMarker
|
|
||||||
}
|
|
||||||
|
|
||||||
// TestStoredUsername_LogLinesDoNotTrackUsernameSize pins the two
|
|
||||||
// login lines that are reached only AFTER the username matched a
|
|
||||||
// stored row: "invalid password" and "user logged in". Neither
|
|
||||||
// strictly needs its cap — the value is the operator's own data by
|
|
||||||
// then, not the client's — but both carry one so that every username
|
|
||||||
// this unauthenticated endpoint logs is capped, and an unasserted cap
|
|
||||||
// is one a later edit removes for free.
|
|
||||||
//
|
|
||||||
// One app per handler with the accounts created inside it, and no
|
|
||||||
// parallelism below that level: every account costs an Argon2id hash
|
|
||||||
// and every attempt costs a verification.
|
|
||||||
func TestStoredUsername_LogLinesDoNotTrackUsernameSize(t *testing.T) {
|
|
||||||
t.Parallel()
|
|
||||||
|
|
||||||
for handlerName, newHandler := range logHandlers() {
|
|
||||||
t.Run(handlerName, func(t *testing.T) {
|
|
||||||
t.Parallel()
|
|
||||||
|
|
||||||
var db *database.Database
|
|
||||||
|
|
||||||
h, buf := capturingHandlers(t, newHandler, &db)
|
|
||||||
|
|
||||||
hash, err := database.HashPassword(storedUserPassword)
|
|
||||||
require.NoError(t, err)
|
|
||||||
|
|
||||||
fills := escapeFills()
|
|
||||||
for fillName, fill := range fills {
|
|
||||||
username := storedFill(fill) + fillName
|
|
||||||
|
|
||||||
require.NoError(t, db.DB().Create(&database.User{
|
|
||||||
Username: username,
|
|
||||||
Password: hash,
|
|
||||||
}).Error)
|
|
||||||
|
|
||||||
// Matched the row, wrong secret: "invalid
|
|
||||||
// password".
|
|
||||||
assert.Equal(
|
|
||||||
t, http.StatusUnauthorized,
|
|
||||||
postLoginWithPassword(
|
|
||||||
t, h, username, "not-the-password",
|
|
||||||
),
|
|
||||||
)
|
|
||||||
|
|
||||||
// Matched the row, right secret: "user logged
|
|
||||||
// in".
|
|
||||||
assert.Equal(
|
|
||||||
t, http.StatusSeeOther,
|
|
||||||
postLoginWithPassword(
|
|
||||||
t, h, username, storedUserPassword,
|
|
||||||
),
|
|
||||||
)
|
|
||||||
}
|
|
||||||
|
|
||||||
lines := logLines(t, buf)
|
|
||||||
require.Len(t, lines, 2*len(fills))
|
|
||||||
assertNoClientText(t, buf)
|
|
||||||
})
|
|
||||||
}
|
|
||||||
}
|
|
||||||
|
|
||||||
// maxVerificationSlots bounds how many slots the loop below will
|
|
||||||
// take before it gives up, so a semaphore that never fills fails the
|
|
||||||
// test instead of hanging it. It is deliberately larger than the
|
|
||||||
// real concurrency bound, which is not exported to this package.
|
|
||||||
const maxVerificationSlots = 64
|
|
||||||
|
|
||||||
// canceledContext returns a context that is already done. A
|
|
||||||
// verification request carrying one takes the ctx.Done() branch of
|
|
||||||
// the semaphore's bounded wait immediately, so these cases turn on
|
|
||||||
// the semaphore being full rather than on a five-second timer firing.
|
|
||||||
// Nothing here is timing-dependent.
|
|
||||||
func canceledContext() context.Context {
|
|
||||||
ctx, cancel := context.WithCancel(context.Background())
|
|
||||||
cancel()
|
|
||||||
|
|
||||||
return ctx
|
|
||||||
}
|
|
||||||
|
|
||||||
// holdEveryVerificationSlot takes verification slots until one is
|
|
||||||
// refused, and releases them when the test ends. A free slot is
|
|
||||||
// handed out before any context is consulted, so a canceled context
|
|
||||||
// cannot make this loop stop early: it stops exactly when the slots
|
|
||||||
// are gone.
|
|
||||||
func holdEveryVerificationSlot(
|
|
||||||
t *testing.T, mw *middleware.Middleware,
|
|
||||||
) {
|
|
||||||
t.Helper()
|
|
||||||
|
|
||||||
for range maxVerificationSlots {
|
|
||||||
release, ok := mw.BeginPasswordVerification(canceledContext())
|
|
||||||
if !ok {
|
|
||||||
return
|
|
||||||
}
|
|
||||||
|
|
||||||
t.Cleanup(release)
|
|
||||||
}
|
|
||||||
|
|
||||||
require.Fail(t, "the verification semaphore never filled")
|
|
||||||
}
|
|
||||||
|
|
||||||
// postLoginAtPath submits the login form at a path of the caller's
|
|
||||||
// choosing, with a canceled context.
|
|
||||||
func postLoginAtPath(
|
|
||||||
t *testing.T, h *handlers.Handlers, path string,
|
|
||||||
) int {
|
|
||||||
t.Helper()
|
|
||||||
|
|
||||||
form := url.Values{
|
|
||||||
"username": {"someone"},
|
|
||||||
"password": {"not-the-password"},
|
|
||||||
}
|
|
||||||
|
|
||||||
req := httptest.NewRequestWithContext(
|
|
||||||
canceledContext(),
|
|
||||||
http.MethodPost,
|
|
||||||
path,
|
|
||||||
strings.NewReader(form.Encode()),
|
|
||||||
)
|
|
||||||
req.Header.Set(
|
|
||||||
"Content-Type", "application/x-www-form-urlencoded",
|
|
||||||
)
|
|
||||||
|
|
||||||
w := httptest.NewRecorder()
|
|
||||||
h.HandleLoginSubmit().ServeHTTP(w, req)
|
|
||||||
|
|
||||||
return w.Code
|
|
||||||
}
|
|
||||||
|
|
||||||
// TestVerificationCapacity_LogLineDoesNotTrackPathSize pins the cap
|
|
||||||
// on the "password verification capacity exhausted" WARN line.
|
|
||||||
//
|
|
||||||
// The one route that reaches it is chi's static "/pages/login", so no
|
|
||||||
// request through the mux can widen the line; the handler is driven
|
|
||||||
// directly here with the path a parameterised route would give it,
|
|
||||||
// which is what that cap exists for. Without this test, removing the
|
|
||||||
// logfield.Truncate there fails nothing.
|
|
||||||
func TestVerificationCapacity_LogLineDoesNotTrackPathSize(
|
|
||||||
t *testing.T,
|
|
||||||
) {
|
|
||||||
t.Parallel()
|
|
||||||
|
|
||||||
for handlerName, newHandler := range logHandlers() {
|
|
||||||
for fillName, fill := range escapeFills() {
|
|
||||||
t.Run(handlerName+"/"+fillName, func(t *testing.T) {
|
|
||||||
t.Parallel()
|
|
||||||
|
|
||||||
var mw *middleware.Middleware
|
|
||||||
|
|
||||||
h, buf := capturingHandlers(t, newHandler, &mw)
|
|
||||||
|
|
||||||
holdEveryVerificationSlot(t, mw)
|
|
||||||
|
|
||||||
assert.Equal(
|
|
||||||
t,
|
|
||||||
http.StatusServiceUnavailable,
|
|
||||||
postLoginAtPath(
|
|
||||||
t, h,
|
|
||||||
"/source/"+url.PathEscape(
|
|
||||||
oversizedFill(fill),
|
|
||||||
)+"/login",
|
|
||||||
),
|
|
||||||
)
|
|
||||||
|
|
||||||
lines := logLines(t, buf)
|
|
||||||
require.Len(t, lines, 1)
|
|
||||||
assertNoClientText(t, buf)
|
|
||||||
})
|
|
||||||
}
|
|
||||||
}
|
|
||||||
}
|
|
||||||
|
|
||||||
// assertBoundedFlood holds the whole flood's log output to what the
|
|
||||||
// stated per-line ceiling allows. The flood sent
|
|
||||||
// floodRequests * oversizedFillBytes bytes of client-chosen text;
|
|
||||||
// this is the assertion that the log did not grow with it.
|
|
||||||
func assertBoundedFlood(t *testing.T, got int) {
|
|
||||||
t.Helper()
|
|
||||||
|
|
||||||
sent := floodRequests * oversizedFillBytes
|
|
||||||
|
|
||||||
require.Less(
|
|
||||||
t, got, sent/2,
|
|
||||||
"log volume tracked the size of the flood's input",
|
|
||||||
)
|
|
||||||
require.LessOrEqual(
|
|
||||||
t, got,
|
|
||||||
floodRequests*middleware.MaxAccessLogLineBytes,
|
|
||||||
)
|
|
||||||
}
|
|
||||||
@@ -9,7 +9,6 @@ import (
|
|||||||
"gorm.io/gorm"
|
"gorm.io/gorm"
|
||||||
"sneak.berlin/go/webhooker/internal/database"
|
"sneak.berlin/go/webhooker/internal/database"
|
||||||
"sneak.berlin/go/webhooker/internal/delivery"
|
"sneak.berlin/go/webhooker/internal/delivery"
|
||||||
"sneak.berlin/go/webhooker/internal/logfield"
|
|
||||||
)
|
)
|
||||||
|
|
||||||
const (
|
const (
|
||||||
@@ -126,16 +125,9 @@ func (h *Handlers) lookupEntrypoint(
|
|||||||
"path = ?", entrypointUUID,
|
"path = ?", entrypointUUID,
|
||||||
).First(&entrypoint)
|
).First(&entrypoint)
|
||||||
if result.Error != nil {
|
if result.Error != nil {
|
||||||
// The receiver is unauthenticated and /webhook/{uuid}
|
|
||||||
// matches any single segment, so this value is entirely
|
|
||||||
// client-chosen on exactly the branch where the lookup
|
|
||||||
// failed. DEBUG is off by default; the cap is what keeps
|
|
||||||
// turning it on from restoring an unbounded write.
|
|
||||||
h.log.Debug(
|
h.log.Debug(
|
||||||
"entrypoint not found",
|
"entrypoint not found",
|
||||||
"path", logfield.Truncate(
|
"path", entrypointUUID,
|
||||||
entrypointUUID, logfield.MaxBytes,
|
|
||||||
),
|
|
||||||
)
|
)
|
||||||
http.NotFound(w, r)
|
http.NotFound(w, r)
|
||||||
|
|
||||||
|
|||||||
@@ -1,14 +1,11 @@
|
|||||||
// Package logfield bounds the client-supplied values this service
|
// Package logfield bounds a client-supplied value against what the log
|
||||||
// writes into its logs.
|
// handler will actually emit for it, so a line's size is set by this
|
||||||
|
// service rather than by the client that provoked it.
|
||||||
//
|
//
|
||||||
// Any log field whose content a client picks is spent against a budget
|
// It lives outside internal/middleware because more than one writer
|
||||||
// here, in ENCODED bytes rather than in the bytes the client sent, so
|
// needs it: the access log, and the GORM adapter in internal/gormlog,
|
||||||
// that escaping cannot multiply a field past its nominal size. One
|
// which logs SQL with the client-chosen parameters interpolated into
|
||||||
// budget and one implementation serves the access log in
|
// it. One budget, one implementation.
|
||||||
// internal/middleware and every other slog call that reaches a
|
|
||||||
// client-chosen path, header or form value; a second, ad-hoc
|
|
||||||
// truncation somewhere else in the tree is the thing this package
|
|
||||||
// exists to prevent.
|
|
||||||
package logfield
|
package logfield
|
||||||
|
|
||||||
import (
|
import (
|
||||||
@@ -18,20 +15,19 @@ import (
|
|||||||
)
|
)
|
||||||
|
|
||||||
const (
|
const (
|
||||||
// MaxBytes is the default budget for a log field whose value the
|
// MaxBytes is the default budget for a field whose value the
|
||||||
// client supplies outright: a URL, a path, a header, a form value.
|
// client supplies outright. It is spent in ENCODED bytes (see
|
||||||
// The budget is spent in ENCODED bytes (see Truncate), so 512 still
|
// Truncate), so 512 still holds a real browser's User-Agent whole
|
||||||
// holds a real browser's User-Agent whole — those are plain ASCII,
|
// — those are plain ASCII, which encodes one byte for one — while
|
||||||
// which encodes one byte for one — while a value built from
|
// a value built from characters the encoder escapes keeps a
|
||||||
// characters the encoder escapes keeps a shorter prefix. That is
|
// shorter prefix. That is the intended trade: 500 quotation marks
|
||||||
// the intended trade: 500 quotation marks are not a debugging
|
// are not a debugging asset.
|
||||||
// asset.
|
|
||||||
MaxBytes = 512
|
MaxBytes = 512
|
||||||
|
|
||||||
// TruncationMarker is appended to any field that was cut, so a
|
// truncationMarker is appended to any value Truncate cut, so a
|
||||||
// short value and a truncated one cannot be confused. It is charged
|
// short value and a truncated one cannot be confused. It is
|
||||||
// on top of the budget, not inside it.
|
// charged on top of the budget, not inside it.
|
||||||
TruncationMarker = "[truncated]"
|
truncationMarker = "[truncated]"
|
||||||
)
|
)
|
||||||
|
|
||||||
// EncodedBytes is what r costs on the line once the log handler has
|
// EncodedBytes is what r costs on the line once the log handler has
|
||||||
@@ -49,9 +45,9 @@ const (
|
|||||||
// 955,086 unassigned, private-use and format code points on planes 1
|
// 955,086 unassigned, private-use and format code points on planes 1
|
||||||
// to 16.
|
// to 16.
|
||||||
//
|
//
|
||||||
// Charging ten there is what makes the stated line ceilings hold for
|
// Charging ten there is what makes the stated per-line ceiling hold
|
||||||
// the tty handler as well: U+1000C encodes as F0 90 80 8C, every byte
|
// for the tty handler as well: U+1000C encodes as F0 90 80 8C, every
|
||||||
// >= 0x80, which httpguts.ValidHeaderFieldValue accepts and
|
// byte >= 0x80, which httpguts.ValidHeaderFieldValue accepts and
|
||||||
// net/textproto does not strip, so a header can be filled with them.
|
// net/textproto does not strip, so a header can be filled with them.
|
||||||
//
|
//
|
||||||
// Both handlers pass printable runes through as their own UTF-8, so
|
// Both handlers pass printable runes through as their own UTF-8, so
|
||||||
@@ -89,19 +85,20 @@ func EncodedBytes(r rune) int {
|
|||||||
// grows a value, so a raw budget spent on characters the encoder
|
// grows a value, so a raw budget spent on characters the encoder
|
||||||
// escapes buys a field several times its nominal size — and the line
|
// escapes buys a field several times its nominal size — and the line
|
||||||
// is the thing an operator is told to multiply by their request rate.
|
// is the thing an operator is told to multiply by their request rate.
|
||||||
// Charging each rune what it will actually cost is what makes a stated
|
// Charging each rune what it will actually cost is what makes the
|
||||||
// ceiling true rather than merely larger. The visible consequence is
|
// stated ceiling true rather than merely larger. The visible
|
||||||
// that an escape-heavy value keeps a shorter prefix than a plain one,
|
// consequence is that an escape-heavy value keeps a shorter prefix
|
||||||
// which is the correct trade.
|
// than a plain one, which is the correct trade.
|
||||||
//
|
//
|
||||||
// The result is always valid UTF-8. A cut on a byte boundary can split
|
// The result is always valid UTF-8. A cut on a byte boundary can split
|
||||||
// a multi-byte rune, and a header can carry bytes that were never
|
// a multi-byte rune, and a header — or a SQL literal — can carry bytes
|
||||||
// valid UTF-8 to begin with; both are dropped rather than kept, since
|
// that were never valid UTF-8 to begin with; both are dropped rather
|
||||||
// an encoder would otherwise spend six bytes replacing each one.
|
// than kept, since an encoder would otherwise spend six bytes
|
||||||
|
// replacing each one.
|
||||||
func Truncate(s string, maxBytes int) string {
|
func Truncate(s string, maxBytes int) string {
|
||||||
// No rune encodes to fewer bytes than it occupies, so nothing past
|
// No rune encodes to fewer bytes than it occupies, so nothing past
|
||||||
// maxBytes raw can fit the budget. Slicing first bounds the scan
|
// maxBytes raw can fit the budget. Slicing first bounds the scan
|
||||||
// below to the budget rather than to the size of the header the
|
// below to the budget rather than to the size of the value the
|
||||||
// client sent.
|
// client sent.
|
||||||
window, cut := s, false
|
window, cut := s, false
|
||||||
if len(window) > maxBytes {
|
if len(window) > maxBytes {
|
||||||
@@ -139,5 +136,5 @@ func Truncate(s string, maxBytes int) string {
|
|||||||
return kept.String()
|
return kept.String()
|
||||||
}
|
}
|
||||||
|
|
||||||
return kept.String() + TruncationMarker
|
return kept.String() + truncationMarker
|
||||||
}
|
}
|
||||||
|
|||||||
@@ -2,7 +2,6 @@ package logfield_test
|
|||||||
|
|
||||||
import (
|
import (
|
||||||
"bytes"
|
"bytes"
|
||||||
"io"
|
|
||||||
"log/slog"
|
"log/slog"
|
||||||
"strings"
|
"strings"
|
||||||
"testing"
|
"testing"
|
||||||
@@ -13,213 +12,6 @@ import (
|
|||||||
"sneak.berlin/go/webhooker/internal/logfield"
|
"sneak.berlin/go/webhooker/internal/logfield"
|
||||||
)
|
)
|
||||||
|
|
||||||
// budget is the field budget these tests spend. Small enough that a
|
|
||||||
// cut is unambiguous, large enough to hold several runes of every
|
|
||||||
// width.
|
|
||||||
const budget = 64
|
|
||||||
|
|
||||||
// sampleRunes is how many runes wide the values in the charge test
|
|
||||||
// are. The handlers add a constant per field — a pair of quotes when
|
|
||||||
// the value needs quoting — so the per-rune charge is only visible
|
|
||||||
// once it is amortised over a run of them.
|
|
||||||
const sampleRunes = 64
|
|
||||||
|
|
||||||
// quotingSlack is that constant: the pair of quotes a handler adds to
|
|
||||||
// a value that needs them and omits from one that does not.
|
|
||||||
const quotingSlack = 2
|
|
||||||
|
|
||||||
// newHandlers are the two handlers internal/logger can install. Time
|
|
||||||
// is dropped so a line's width is a function of its value alone —
|
|
||||||
// RFC3339Nano trims trailing zeros, so two consecutive timestamps do
|
|
||||||
// not render to the same number of bytes.
|
|
||||||
func newHandlers() map[string]func(io.Writer) slog.Handler {
|
|
||||||
opts := &slog.HandlerOptions{
|
|
||||||
Level: slog.LevelDebug,
|
|
||||||
ReplaceAttr: func(_ []string, a slog.Attr) slog.Attr {
|
|
||||||
if a.Key == slog.TimeKey {
|
|
||||||
return slog.Attr{}
|
|
||||||
}
|
|
||||||
|
|
||||||
return a
|
|
||||||
},
|
|
||||||
}
|
|
||||||
|
|
||||||
return map[string]func(io.Writer) slog.Handler{
|
|
||||||
"json": func(w io.Writer) slog.Handler {
|
|
||||||
return slog.NewJSONHandler(w, opts)
|
|
||||||
},
|
|
||||||
"text": func(w io.Writer) slog.Handler {
|
|
||||||
return slog.NewTextHandler(w, opts)
|
|
||||||
},
|
|
||||||
}
|
|
||||||
}
|
|
||||||
|
|
||||||
// renderedWidth is the number of bytes a handler writes for a line
|
|
||||||
// carrying value in a single attribute.
|
|
||||||
func renderedWidth(
|
|
||||||
newHandler func(io.Writer) slog.Handler,
|
|
||||||
value string,
|
|
||||||
) int {
|
|
||||||
buf := new(bytes.Buffer)
|
|
||||||
slog.New(newHandler(buf)).Info("m", "v", value)
|
|
||||||
|
|
||||||
return buf.Len()
|
|
||||||
}
|
|
||||||
|
|
||||||
// chargeTestRunes is the set of code points the charge test measures:
|
|
||||||
// every rune in the first two planes' worth of the BMP that the
|
|
||||||
// handlers are most likely to treat specially, the separators that
|
|
||||||
// only slog's JSON handler escapes, and a stratified sample across
|
|
||||||
// the rest of Unicode so the astral charge is exercised on more than
|
|
||||||
// one hand-picked rune.
|
|
||||||
func chargeTestRunes() []rune {
|
|
||||||
const (
|
|
||||||
denseCeiling = 0x800
|
|
||||||
stride = 1021
|
|
||||||
surrogateLo = 0xD800
|
|
||||||
surrogateHi = 0xDFFF
|
|
||||||
)
|
|
||||||
|
|
||||||
var runes []rune
|
|
||||||
|
|
||||||
keep := func(r rune) {
|
|
||||||
if r >= surrogateLo && r <= surrogateHi {
|
|
||||||
return
|
|
||||||
}
|
|
||||||
|
|
||||||
runes = append(runes, r)
|
|
||||||
}
|
|
||||||
|
|
||||||
for r := range rune(denseCeiling) {
|
|
||||||
keep(r)
|
|
||||||
}
|
|
||||||
|
|
||||||
for _, r := range []rune{
|
|
||||||
0x2028, 0x2029, 0x200B, 0x4E00, 0xE000, 0xFFFD,
|
|
||||||
0x1000C, 0x1F600, 0xE0001, 0x10FFFF,
|
|
||||||
} {
|
|
||||||
keep(r)
|
|
||||||
}
|
|
||||||
|
|
||||||
for r := rune(denseCeiling); r <= utf8.MaxRune; r += stride {
|
|
||||||
keep(r)
|
|
||||||
}
|
|
||||||
|
|
||||||
return runes
|
|
||||||
}
|
|
||||||
|
|
||||||
// TestEncodedBytes_ChargesAtLeastWhatTheHandlersEmit is the property
|
|
||||||
// the whole capping scheme rests on: a rune may not cost more on the
|
|
||||||
// line than the budget was charged for it. An undercharged rune is
|
|
||||||
// how a stated ceiling becomes false without any test noticing, so
|
|
||||||
// the charge is measured against what the handlers actually write
|
|
||||||
// rather than against the escaping rules as read.
|
|
||||||
func TestEncodedBytes_ChargesAtLeastWhatTheHandlersEmit(t *testing.T) {
|
|
||||||
t.Parallel()
|
|
||||||
|
|
||||||
for name, newHandler := range newHandlers() {
|
|
||||||
t.Run(name, func(t *testing.T) {
|
|
||||||
t.Parallel()
|
|
||||||
|
|
||||||
// 'a' is a printable ASCII rune, charged exactly one
|
|
||||||
// byte, so it is the zero point the other runes are
|
|
||||||
// measured against.
|
|
||||||
base := renderedWidth(
|
|
||||||
newHandler, strings.Repeat("a", sampleRunes),
|
|
||||||
)
|
|
||||||
|
|
||||||
for _, r := range chargeTestRunes() {
|
|
||||||
got := renderedWidth(
|
|
||||||
newHandler,
|
|
||||||
strings.Repeat(string(r), sampleRunes),
|
|
||||||
)
|
|
||||||
charged := sampleRunes *
|
|
||||||
(logfield.EncodedBytes(r) - 1)
|
|
||||||
|
|
||||||
require.LessOrEqual(
|
|
||||||
t, got-base, charged+quotingSlack,
|
|
||||||
"U+%04X costs more on the line than "+
|
|
||||||
"EncodedBytes charges for it",
|
|
||||||
r,
|
|
||||||
)
|
|
||||||
}
|
|
||||||
})
|
|
||||||
}
|
|
||||||
}
|
|
||||||
|
|
||||||
// TestTruncate_SpendsNoMoreThanTheBudget holds the result to the
|
|
||||||
// budget in ENCODED bytes, which is the unit the budget is stated in.
|
|
||||||
// A raw-byte cap passes the ASCII case here and fails every other
|
|
||||||
// one.
|
|
||||||
func TestTruncate_SpendsNoMoreThanTheBudget(t *testing.T) {
|
|
||||||
t.Parallel()
|
|
||||||
|
|
||||||
for name, fill := range map[string]string{
|
|
||||||
"plain": "x",
|
|
||||||
"quote": `"`,
|
|
||||||
"backslash": `\`,
|
|
||||||
"tab": "\t",
|
|
||||||
"newline": "\n",
|
|
||||||
"control": "\x01",
|
|
||||||
"astral": "\U0001000C",
|
|
||||||
// U+4E00, a printable multi-byte rune, charged its three
|
|
||||||
// UTF-8 bytes rather than an escape. Spelled numerically
|
|
||||||
// because gosmopolitan rejects Han in a string literal.
|
|
||||||
"cjk": string(rune(0x4E00)),
|
|
||||||
} {
|
|
||||||
t.Run(name, func(t *testing.T) {
|
|
||||||
t.Parallel()
|
|
||||||
|
|
||||||
got := logfield.Truncate(
|
|
||||||
strings.Repeat(fill, budget*8), budget,
|
|
||||||
)
|
|
||||||
|
|
||||||
require.True(
|
|
||||||
t, strings.HasSuffix(
|
|
||||||
got, logfield.TruncationMarker,
|
|
||||||
),
|
|
||||||
"an oversized value must be marked as cut",
|
|
||||||
)
|
|
||||||
|
|
||||||
spent := 0
|
|
||||||
for _, r := range strings.TrimSuffix(
|
|
||||||
got, logfield.TruncationMarker,
|
|
||||||
) {
|
|
||||||
spent += logfield.EncodedBytes(r)
|
|
||||||
}
|
|
||||||
|
|
||||||
assert.LessOrEqual(t, spent, budget)
|
|
||||||
assert.True(t, utf8.ValidString(got))
|
|
||||||
})
|
|
||||||
}
|
|
||||||
}
|
|
||||||
|
|
||||||
// TestTruncate_LeavesShortValuesAlone keeps the marker meaningful: a
|
|
||||||
// value that fits comes back byte for byte, so a marked value is
|
|
||||||
// always a cut one.
|
|
||||||
func TestTruncate_LeavesShortValuesAlone(t *testing.T) {
|
|
||||||
t.Parallel()
|
|
||||||
|
|
||||||
for _, s := range []string{
|
|
||||||
"", "GET", "/source/abc/edit", "Mozilla/5.0 (X11)",
|
|
||||||
} {
|
|
||||||
assert.Equal(t, s, logfield.Truncate(s, budget))
|
|
||||||
}
|
|
||||||
}
|
|
||||||
|
|
||||||
// TestTruncate_DropsInvalidUTF8 covers the bytes a header can carry
|
|
||||||
// that were never valid UTF-8. Keeping them would make the encoder
|
|
||||||
// spend six bytes apiece replacing them, which is exactly the
|
|
||||||
// amplification the budget exists to prevent.
|
|
||||||
func TestTruncate_DropsInvalidUTF8(t *testing.T) {
|
|
||||||
t.Parallel()
|
|
||||||
|
|
||||||
got := logfield.Truncate("a\xffb\xfe\xfec", budget)
|
|
||||||
|
|
||||||
assert.Equal(t, "abc", got)
|
|
||||||
assert.True(t, utf8.ValidString(got))
|
|
||||||
}
|
|
||||||
|
|
||||||
// encodedCost is what a whole string costs on a line, by the same
|
// encodedCost is what a whole string costs on a line, by the same
|
||||||
// accounting Truncate spends its budget with.
|
// accounting Truncate spends its budget with.
|
||||||
func encodedCost(s string) int {
|
func encodedCost(s string) int {
|
||||||
@@ -232,35 +24,29 @@ func encodedCost(s string) int {
|
|||||||
}
|
}
|
||||||
|
|
||||||
// TestTruncate_SpendsEncodedBytesNotRawBytes is the zero-headroom
|
// TestTruncate_SpendsEncodedBytesNotRawBytes is the zero-headroom
|
||||||
// version of TestTruncate_SpendsNoMoreThanTheBudget above, and of the
|
// version of the line-length assertions elsewhere.
|
||||||
// line-length assertions elsewhere.
|
|
||||||
//
|
//
|
||||||
// A line ceiling has slack in it by construction, and a LessOrEqual
|
// A line ceiling has slack in it by construction, so a line-level
|
||||||
// against the budget cannot tell a budget spent exactly from one
|
// assertion only catches a raw-byte budget for the fills with the
|
||||||
// spent under. Here the budget is checked against exactly what it
|
// widest multiplier. Here the budget is checked against exactly what
|
||||||
// bought: a value built from a single rune must keep exactly
|
// it bought: a value built from a single rune must keep exactly
|
||||||
// MaxBytes/EncodedBytes(r) of them, with nothing spare. A raw-byte
|
// MaxBytes/EncodedBytes(r) of them, for every rune, with nothing
|
||||||
// budget — cost := utf8.RuneLen(r) — fails this for every rune the
|
// spare.
|
||||||
// handlers escape.
|
|
||||||
func TestTruncate_SpendsEncodedBytesNotRawBytes(t *testing.T) {
|
func TestTruncate_SpendsEncodedBytesNotRawBytes(t *testing.T) {
|
||||||
t.Parallel()
|
t.Parallel()
|
||||||
|
|
||||||
for name, r := range map[string]rune{
|
for name, r := range map[string]rune{
|
||||||
"plain": 'x',
|
"plain": 'x',
|
||||||
"quote": '"',
|
"quote": '"',
|
||||||
"backslash": '\\',
|
"backslash": '\\',
|
||||||
"tab": '\t',
|
"tab": '\t',
|
||||||
"newline": '\n',
|
"newline": '\n',
|
||||||
"carriage_return": '\r',
|
"carriage_return": '\r',
|
||||||
"c0_control": '\x01',
|
"c0_control": '',
|
||||||
"del": '\x7f',
|
"del": '',
|
||||||
// U+2028 LINE SEPARATOR, which only the JSON handler
|
"line_separator": '
',
|
||||||
// escapes.
|
"astral_nonprintable": '\U0001000C',
|
||||||
"line_separator": '
',
|
"multibyte_printable": 'é',
|
||||||
"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": '€',
|
"three_byte_printable": '€',
|
||||||
"emoji_printable": '\U0001F600',
|
"emoji_printable": '\U0001F600',
|
||||||
} {
|
} {
|
||||||
@@ -275,16 +61,12 @@ func TestTruncate_SpendsEncodedBytesNotRawBytes(t *testing.T) {
|
|||||||
|
|
||||||
got := logfield.Truncate(in, logfield.MaxBytes)
|
got := logfield.Truncate(in, logfield.MaxBytes)
|
||||||
|
|
||||||
require.True(
|
assert.True(
|
||||||
t, strings.HasSuffix(
|
t, strings.HasSuffix(got, "[truncated]"),
|
||||||
got, logfield.TruncationMarker,
|
|
||||||
),
|
|
||||||
"a value past the budget must be marked",
|
"a value past the budget must be marked",
|
||||||
)
|
)
|
||||||
|
|
||||||
kept := strings.TrimSuffix(
|
kept := strings.TrimSuffix(got, "[truncated]")
|
||||||
got, logfield.TruncationMarker,
|
|
||||||
)
|
|
||||||
|
|
||||||
assert.Equal(
|
assert.Equal(
|
||||||
t, want, utf8.RuneCountInString(kept),
|
t, want, utf8.RuneCountInString(kept),
|
||||||
@@ -298,24 +80,123 @@ func TestTruncate_SpendsEncodedBytesNotRawBytes(t *testing.T) {
|
|||||||
}
|
}
|
||||||
}
|
}
|
||||||
|
|
||||||
|
// TestEncodedBytes_CoversWhatTheHandlersActuallyEmit measures the
|
||||||
|
// charge against what slog really writes rather than against a
|
||||||
|
// reading of its source, over both handlers internal/logger can
|
||||||
|
// install. An undercharged rune fails here rather than quietly
|
||||||
|
// falsifying every stated line ceiling.
|
||||||
|
func TestEncodedBytes_CoversWhatTheHandlersActuallyEmit(t *testing.T) {
|
||||||
|
t.Parallel()
|
||||||
|
|
||||||
|
emitted := func(h func(*bytes.Buffer) slog.Handler, r rune) int {
|
||||||
|
var withValue, withoutValue bytes.Buffer
|
||||||
|
|
||||||
|
slog.New(h(&withValue)).Info("m", "v", string(r))
|
||||||
|
slog.New(h(&withoutValue)).Info("m", "v", "")
|
||||||
|
|
||||||
|
return withValue.Len() - withoutValue.Len()
|
||||||
|
}
|
||||||
|
|
||||||
|
jsonHandler := func(b *bytes.Buffer) slog.Handler {
|
||||||
|
return slog.NewJSONHandler(b, &slog.HandlerOptions{
|
||||||
|
ReplaceAttr: dropTime,
|
||||||
|
})
|
||||||
|
}
|
||||||
|
textHandler := func(b *bytes.Buffer) slog.Handler {
|
||||||
|
return slog.NewTextHandler(b, &slog.HandlerOptions{
|
||||||
|
ReplaceAttr: dropTime,
|
||||||
|
})
|
||||||
|
}
|
||||||
|
|
||||||
|
// Every code point below U+0800 densely — which covers all of C0,
|
||||||
|
// DEL, C1 and the two-byte range — plus the separators only the
|
||||||
|
// JSON handler escapes, plus a stratified walk across the rest of
|
||||||
|
// the assigned space and into the astral planes.
|
||||||
|
var runes []rune
|
||||||
|
|
||||||
|
for r := rune(1); r < 0x800; r++ {
|
||||||
|
runes = append(runes, r)
|
||||||
|
}
|
||||||
|
|
||||||
|
runes = append(
|
||||||
|
runes,
|
||||||
|
'
', // LINE SEPARATOR, escaped only by the JSON handler
|
||||||
|
'
', // PARAGRAPH SEPARATOR, likewise
|
||||||
|
rune(0xFEFF), // ZERO WIDTH NO-BREAK SPACE
|
||||||
|
rune(0xFFFD), // REPLACEMENT CHARACTER
|
||||||
|
)
|
||||||
|
|
||||||
|
for r := rune(0x800); r <= 0x10FFFF; r += 0x1D1 {
|
||||||
|
runes = append(runes, r)
|
||||||
|
}
|
||||||
|
|
||||||
|
for _, r := range runes {
|
||||||
|
if !utf8.ValidRune(r) {
|
||||||
|
continue
|
||||||
|
}
|
||||||
|
|
||||||
|
charged := logfield.EncodedBytes(r)
|
||||||
|
|
||||||
|
require.LessOrEqual(
|
||||||
|
t, emitted(jsonHandler, r), charged,
|
||||||
|
"json handler spends more than U+%04X is charged", r,
|
||||||
|
)
|
||||||
|
require.LessOrEqual(
|
||||||
|
t, emitted(textHandler, r), charged,
|
||||||
|
"text handler spends more than U+%04X is charged", r,
|
||||||
|
)
|
||||||
|
}
|
||||||
|
}
|
||||||
|
|
||||||
|
func dropTime(_ []string, a slog.Attr) slog.Attr {
|
||||||
|
if a.Key == slog.TimeKey {
|
||||||
|
return slog.Attr{}
|
||||||
|
}
|
||||||
|
|
||||||
|
return a
|
||||||
|
}
|
||||||
|
|
||||||
|
// TestTruncate_LeavesShortValuesAlone keeps the marker meaningful: a
|
||||||
|
// value that fits is returned untouched, so a reader can tell a short
|
||||||
|
// value from a cut one.
|
||||||
|
func TestTruncate_LeavesShortValuesAlone(t *testing.T) {
|
||||||
|
t.Parallel()
|
||||||
|
|
||||||
|
const in = "Mozilla/5.0 (X11; Linux x86_64)"
|
||||||
|
|
||||||
|
assert.Equal(t, in, logfield.Truncate(in, logfield.MaxBytes))
|
||||||
|
}
|
||||||
|
|
||||||
|
// TestTruncate_DropsInvalidUTF8 covers a value that was never valid
|
||||||
|
// UTF-8 — a SQL parameter or a header can carry one. Replacing each
|
||||||
|
// bad byte would cost six encoded bytes apiece, so they are dropped.
|
||||||
|
func TestTruncate_DropsInvalidUTF8(t *testing.T) {
|
||||||
|
t.Parallel()
|
||||||
|
|
||||||
|
got := logfield.Truncate("a\xffb\xfec", logfield.MaxBytes)
|
||||||
|
|
||||||
|
assert.Equal(t, "abc", got)
|
||||||
|
assert.True(t, utf8.ValidString(got))
|
||||||
|
}
|
||||||
|
|
||||||
// TestTruncate_NeverSplitsARune covers a cut landing inside a
|
// TestTruncate_NeverSplitsARune covers a cut landing inside a
|
||||||
// multi-byte encoding rather than between two of them.
|
// multi-byte encoding.
|
||||||
func TestTruncate_NeverSplitsARune(t *testing.T) {
|
func TestTruncate_NeverSplitsARune(t *testing.T) {
|
||||||
t.Parallel()
|
t.Parallel()
|
||||||
|
|
||||||
// U+20AC, three bytes and printable, so a small budget lands
|
// A three-byte printable rune, so a small budget lands inside the
|
||||||
// inside an encoding rather than on a boundary.
|
// encoding rather than between two of them.
|
||||||
in := strings.Repeat("€", logfield.MaxBytes)
|
in := strings.Repeat("€", logfield.MaxBytes)
|
||||||
|
|
||||||
for b := 1; b <= 16; b++ {
|
for budget := 1; budget <= 16; budget++ {
|
||||||
got := strings.TrimSuffix(
|
got := strings.TrimSuffix(
|
||||||
logfield.Truncate(in, b), logfield.TruncationMarker,
|
logfield.Truncate(in, budget), "[truncated]",
|
||||||
)
|
)
|
||||||
|
|
||||||
assert.True(
|
assert.True(
|
||||||
t, utf8.ValidString(got),
|
t, utf8.ValidString(got),
|
||||||
"budget %d produced invalid UTF-8", b,
|
"budget %d produced invalid UTF-8", budget,
|
||||||
)
|
)
|
||||||
assert.LessOrEqual(t, encodedCost(got), b)
|
assert.LessOrEqual(t, encodedCost(got), budget)
|
||||||
}
|
}
|
||||||
}
|
}
|
||||||
|
|||||||
@@ -4,7 +4,6 @@ import (
|
|||||||
"net/http"
|
"net/http"
|
||||||
|
|
||||||
"github.com/gorilla/csrf"
|
"github.com/gorilla/csrf"
|
||||||
"sneak.berlin/go/webhooker/internal/logfield"
|
|
||||||
)
|
)
|
||||||
|
|
||||||
// CSRFToken retrieves the CSRF token from the request context.
|
// CSRFToken retrieves the CSRF token from the request context.
|
||||||
@@ -43,22 +42,9 @@ func isClientTLS(r *http.Request) bool {
|
|||||||
// csrf.Secure option is set at creation time, not per-request.
|
// csrf.Secure option is set at creation time, not per-request.
|
||||||
func (m *Middleware) CSRF() func(http.Handler) http.Handler {
|
func (m *Middleware) CSRF() func(http.Handler) http.Handler {
|
||||||
csrfErrorHandler := http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
|
csrfErrorHandler := http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
|
||||||
// CSRF is registered ahead of RequireAuth on every route
|
|
||||||
// group that uses it, so this WARN is reachable by an
|
|
||||||
// unauthenticated client: a POST with no token to
|
|
||||||
// /source/<any length of any text>/edit lands here. The
|
|
||||||
// method and path are capped against the same budgets as
|
|
||||||
// the access log. remote_addr is set by net/http from the
|
|
||||||
// accepted connection rather than by the client, and
|
|
||||||
// csrf.FailureReason returns one of gorilla/csrf's own
|
|
||||||
// fixed error values, so neither is client-sized.
|
|
||||||
m.log.Warn("csrf: token validation failed",
|
m.log.Warn("csrf: token validation failed",
|
||||||
"method", logfield.Truncate(
|
"method", r.Method,
|
||||||
r.Method, maxLogMethodBytes,
|
"path", r.URL.Path,
|
||||||
),
|
|
||||||
"path", logfield.Truncate(
|
|
||||||
r.URL.Path, logfield.MaxBytes,
|
|
||||||
),
|
|
||||||
"remote_addr", r.RemoteAddr,
|
"remote_addr", r.RemoteAddr,
|
||||||
"reason", csrf.FailureReason(r),
|
"reason", csrf.FailureReason(r),
|
||||||
)
|
)
|
||||||
|
|||||||
@@ -1,544 +0,0 @@
|
|||||||
package middleware_test
|
|
||||||
|
|
||||||
// This file covers the log lines OUTSIDE the access log that carry a
|
|
||||||
// client-chosen value. accesslog_test.go bounds the one INFO line the
|
|
||||||
// Logging middleware writes; these are the separate slog calls that
|
|
||||||
// were never in that sweep and so never got the budget:
|
|
||||||
//
|
|
||||||
// - MaxBodySize's 413 rejection, at WARN, registered ahead of
|
|
||||||
// RequireAuth and therefore reachable unauthenticated at a URL of
|
|
||||||
// the client's choosing.
|
|
||||||
// - CSRF's 403 rejection, at WARN, also registered ahead of
|
|
||||||
// RequireAuth.
|
|
||||||
// - The rate limiters' 429 rejection, at WARN, on the
|
|
||||||
// unauthenticated receiver among others.
|
|
||||||
// - RequireAuth's own unauthenticated-request line, at DEBUG.
|
|
||||||
// - RecordLoginFailure's throttle rejection, at WARN. Its cap is
|
|
||||||
// defensive rather than load-bearing today: chi pins the one
|
|
||||||
// route that calls it to the constant path "/pages/login". The
|
|
||||||
// method is exported and takes any *http.Request, so the test
|
|
||||||
// below hands it the request a caller on a parameterised route
|
|
||||||
// would, which is what the cap exists for.
|
|
||||||
//
|
|
||||||
// Every case here holds the ENCODED line to
|
|
||||||
// middleware.MaxAccessLogLineBytes, under both handlers
|
|
||||||
// internal/logger can install, against 8 KB of client-chosen text
|
|
||||||
// built out of the characters those handlers escape. A budget spent
|
|
||||||
// in raw bytes passes the plain-ASCII cases and fails the rest.
|
|
||||||
|
|
||||||
import (
|
|
||||||
"bytes"
|
|
||||||
"context"
|
|
||||||
"io"
|
|
||||||
"log/slog"
|
|
||||||
"net/http"
|
|
||||||
"net/http/httptest"
|
|
||||||
"net/url"
|
|
||||||
"strings"
|
|
||||||
"testing"
|
|
||||||
|
|
||||||
"github.com/stretchr/testify/assert"
|
|
||||||
"github.com/stretchr/testify/require"
|
|
||||||
"sneak.berlin/go/webhooker/internal/config"
|
|
||||||
"sneak.berlin/go/webhooker/internal/middleware"
|
|
||||||
)
|
|
||||||
|
|
||||||
// bodyLimitBytes is the MaxBodySize cap these tests install. Any
|
|
||||||
// declared Content-Length above it takes the 413 branch.
|
|
||||||
const bodyLimitBytes = 1024
|
|
||||||
|
|
||||||
// declaredBodyBytes is the Content-Length an oversize request
|
|
||||||
// declares. Nothing is actually sent: the 413 branch fires off the
|
|
||||||
// declaration alone, which is what makes the attack free.
|
|
||||||
const declaredBodyBytes = bodyLimitBytes * 2
|
|
||||||
|
|
||||||
// receiverLimitPerMinute is the per-entrypoint receiver limit these
|
|
||||||
// tests install. The aggregate limiter sits at ten times this, so a
|
|
||||||
// flood stays under it and the rejections come from the
|
|
||||||
// per-entrypoint limiter, which is the one that logs the path.
|
|
||||||
const receiverLimitPerMinute = 8
|
|
||||||
|
|
||||||
// escapeFills are the characters a client can put in a request that
|
|
||||||
// the log handlers then escape, coming out wider than they went in.
|
|
||||||
// A budget counted in raw bytes lets any of them buy a field several
|
|
||||||
// times its nominal size.
|
|
||||||
//
|
|
||||||
// U+1000C is the case the JSON handler alone does not reach: it is
|
|
||||||
// unassigned, so it is non-printable, and strconv.Quote spells a
|
|
||||||
// non-printable rune at or above U+10000 as a ten-byte \UXXXXXXXX
|
|
||||||
// while the JSON handler passes its four UTF-8 bytes through. Only
|
|
||||||
// the text-handler shape of these tests holds that charge honest.
|
|
||||||
func escapeFills() map[string]string {
|
|
||||||
return map[string]string{
|
|
||||||
"plain": "x",
|
|
||||||
"quote": `"`,
|
|
||||||
"backslash": `\`,
|
|
||||||
"tab": "\t",
|
|
||||||
"newline": "\n",
|
|
||||||
// A C0 control neither handler has a short escape for, so
|
|
||||||
// each one costs six bytes on the line against the single
|
|
||||||
// byte it cost to send. This is the widest multiplier a
|
|
||||||
// client can drive, and the case a raw-byte budget breaks
|
|
||||||
// on first.
|
|
||||||
//
|
|
||||||
// This fill is load-bearing, not decoration. Budgeting raw
|
|
||||||
// bytes instead of encoded is caught by this fill alone,
|
|
||||||
// and only under the JSON handler, at 3,072 bytes against
|
|
||||||
// the 2,560 ceiling. Drop it and that mutation passes.
|
|
||||||
"control": "\x01",
|
|
||||||
"astral": "\U0001000C",
|
|
||||||
}
|
|
||||||
}
|
|
||||||
|
|
||||||
// logHandlers are the two handlers internal/logger can install: the
|
|
||||||
// JSON one, and the text one it selects when stderr is a tty. They do
|
|
||||||
// not escape alike, and MaxAccessLogLineBytes is quoted unqualified,
|
|
||||||
// so every case runs through both.
|
|
||||||
func logHandlers() map[string]func(
|
|
||||||
io.Writer, *slog.HandlerOptions,
|
|
||||||
) slog.Handler {
|
|
||||||
return map[string]func(
|
|
||||||
io.Writer, *slog.HandlerOptions,
|
|
||||||
) slog.Handler{
|
|
||||||
"json": func(
|
|
||||||
w io.Writer, o *slog.HandlerOptions,
|
|
||||||
) slog.Handler {
|
|
||||||
return slog.NewJSONHandler(w, o)
|
|
||||||
},
|
|
||||||
"text": func(
|
|
||||||
w io.Writer, o *slog.HandlerOptions,
|
|
||||||
) slog.Handler {
|
|
||||||
return slog.NewTextHandler(w, o)
|
|
||||||
},
|
|
||||||
}
|
|
||||||
}
|
|
||||||
|
|
||||||
// oversizedPathSegment builds an 8 KB client-chosen path segment out
|
|
||||||
// of repetitions of ch, percent-encoded so it survives URL parsing
|
|
||||||
// into r.URL.Path the way it would arriving off a socket.
|
|
||||||
//
|
|
||||||
// Both markers sit at the END, past every budget, so their absence
|
|
||||||
// from the log is what proves the value was cut rather than merely
|
|
||||||
// being short. The leading 'x' keeps the segment non-empty for fills
|
|
||||||
// that a parser might otherwise fold away.
|
|
||||||
func oversizedPathSegment(ch string) string {
|
|
||||||
return url.PathEscape(
|
|
||||||
"x" + strings.Repeat(ch, oversizedSegmentBytes) +
|
|
||||||
attackerMarker + tailMarker,
|
|
||||||
)
|
|
||||||
}
|
|
||||||
|
|
||||||
// capturingLogger returns a logger at DEBUG writing into the returned
|
|
||||||
// buffer through the named handler.
|
|
||||||
func capturingLogger(
|
|
||||||
newHandler func(io.Writer, *slog.HandlerOptions) slog.Handler,
|
|
||||||
) (*slog.Logger, *bytes.Buffer) {
|
|
||||||
buf := new(bytes.Buffer)
|
|
||||||
opts := &slog.HandlerOptions{Level: slog.LevelDebug}
|
|
||||||
|
|
||||||
return slog.New(newHandler(buf, opts)), buf
|
|
||||||
}
|
|
||||||
|
|
||||||
// capturingBoundMiddleware builds a Middleware with a real session
|
|
||||||
// manager (CSRF needs its key, RequireAuth needs its store) whose log
|
|
||||||
// is captured at DEBUG.
|
|
||||||
func capturingBoundMiddleware(
|
|
||||||
t *testing.T,
|
|
||||||
newHandler func(io.Writer, *slog.HandlerOptions) slog.Handler,
|
|
||||||
) (*middleware.Middleware, *bytes.Buffer) {
|
|
||||||
t.Helper()
|
|
||||||
|
|
||||||
log, buf := capturingLogger(newHandler)
|
|
||||||
|
|
||||||
cfg := &config.Config{
|
|
||||||
Environment: config.EnvironmentDev,
|
|
||||||
ReceiverRateLimit: receiverLimitPerMinute,
|
|
||||||
}
|
|
||||||
|
|
||||||
sess := newTestSessionManager(cfg, log, nil)
|
|
||||||
|
|
||||||
return middleware.NewForTest(log, cfg, sess), buf
|
|
||||||
}
|
|
||||||
|
|
||||||
// unreachable is a next-handler that fails the test if the middleware
|
|
||||||
// under test let the request through. Every site here rejects.
|
|
||||||
func unreachable(t *testing.T) http.Handler {
|
|
||||||
t.Helper()
|
|
||||||
|
|
||||||
return http.HandlerFunc(func(http.ResponseWriter, *http.Request) {
|
|
||||||
assert.Fail(t, "rejected request reached the next handler")
|
|
||||||
})
|
|
||||||
}
|
|
||||||
|
|
||||||
// logSite is one non-access-log call site that logs a client-chosen
|
|
||||||
// path. drive sends requests at it that all take the rejecting
|
|
||||||
// branch; linesPerRequest is how many log lines one such request
|
|
||||||
// produces there.
|
|
||||||
type logSite struct {
|
|
||||||
// build wraps the site's middleware around a handler that must
|
|
||||||
// not be reached.
|
|
||||||
build func(
|
|
||||||
t *testing.T, m *middleware.Middleware,
|
|
||||||
) http.Handler
|
|
||||||
// send issues one request for the given client-chosen path and
|
|
||||||
// returns the status. Some sites need a warm-up request before
|
|
||||||
// they reject, which send performs itself.
|
|
||||||
send func(h http.Handler, path string) int
|
|
||||||
// wantStatus is the status the rejecting branch answers with.
|
|
||||||
wantStatus int
|
|
||||||
}
|
|
||||||
|
|
||||||
// postOversize sends a POST whose declared Content-Length exceeds the
|
|
||||||
// body limit without sending a body, which is the whole cost of the
|
|
||||||
// attack on the MaxBodySize branch.
|
|
||||||
func postOversize(h http.Handler, path string) int {
|
|
||||||
req := httptest.NewRequestWithContext(
|
|
||||||
context.Background(), http.MethodPost, path, nil,
|
|
||||||
)
|
|
||||||
req.ContentLength = declaredBodyBytes
|
|
||||||
req.Header.Set(
|
|
||||||
"Content-Type", "application/x-www-form-urlencoded",
|
|
||||||
)
|
|
||||||
|
|
||||||
w := httptest.NewRecorder()
|
|
||||||
h.ServeHTTP(w, req)
|
|
||||||
|
|
||||||
return w.Code
|
|
||||||
}
|
|
||||||
|
|
||||||
// postNoToken sends a POST carrying no CSRF token and no session
|
|
||||||
// cookie, which is what an unauthenticated client sends.
|
|
||||||
func postNoToken(h http.Handler, path string) int {
|
|
||||||
req := httptest.NewRequestWithContext(
|
|
||||||
context.Background(), http.MethodPost, path,
|
|
||||||
strings.NewReader(""),
|
|
||||||
)
|
|
||||||
req.Header.Set(
|
|
||||||
"Content-Type", "application/x-www-form-urlencoded",
|
|
||||||
)
|
|
||||||
|
|
||||||
w := httptest.NewRecorder()
|
|
||||||
h.ServeHTTP(w, req)
|
|
||||||
|
|
||||||
return w.Code
|
|
||||||
}
|
|
||||||
|
|
||||||
// getNoSession sends a GET with no session cookie.
|
|
||||||
func getNoSession(h http.Handler, path string) int {
|
|
||||||
req := httptest.NewRequestWithContext(
|
|
||||||
context.Background(), http.MethodGet, path, nil,
|
|
||||||
)
|
|
||||||
|
|
||||||
w := httptest.NewRecorder()
|
|
||||||
h.ServeHTTP(w, req)
|
|
||||||
|
|
||||||
return w.Code
|
|
||||||
}
|
|
||||||
|
|
||||||
// logSites enumerates the call sites under test.
|
|
||||||
func logSites() map[string]logSite {
|
|
||||||
return map[string]logSite{
|
|
||||||
// The site this file exists for: WARN, on by default, and
|
|
||||||
// registered ahead of RequireAuth.
|
|
||||||
"maxbodysize 413": {
|
|
||||||
build: func(
|
|
||||||
t *testing.T, m *middleware.Middleware,
|
|
||||||
) http.Handler {
|
|
||||||
t.Helper()
|
|
||||||
|
|
||||||
return m.MaxBodySize(bodyLimitBytes)(
|
|
||||||
unreachable(t),
|
|
||||||
)
|
|
||||||
},
|
|
||||||
send: postOversize,
|
|
||||||
wantStatus: http.StatusRequestEntityTooLarge,
|
|
||||||
},
|
|
||||||
// Also ahead of RequireAuth, also WARN.
|
|
||||||
"csrf 403": {
|
|
||||||
build: func(
|
|
||||||
t *testing.T, m *middleware.Middleware,
|
|
||||||
) http.Handler {
|
|
||||||
t.Helper()
|
|
||||||
|
|
||||||
return m.CSRF()(unreachable(t))
|
|
||||||
},
|
|
||||||
send: postNoToken,
|
|
||||||
wantStatus: http.StatusForbidden,
|
|
||||||
},
|
|
||||||
// The per-entrypoint receiver limiter, unauthenticated. Its
|
|
||||||
// bucket is keyed on the path, so the first request through a
|
|
||||||
// fresh path is served and only the ones after it are
|
|
||||||
// rejected; sendUntilLimited absorbs that.
|
|
||||||
"receiver rate limit 429": {
|
|
||||||
build: func(
|
|
||||||
t *testing.T, m *middleware.Middleware,
|
|
||||||
) http.Handler {
|
|
||||||
t.Helper()
|
|
||||||
|
|
||||||
return m.ReceiverRateLimit()(okHandler())
|
|
||||||
},
|
|
||||||
send: sendUntilLimited,
|
|
||||||
wantStatus: http.StatusTooManyRequests,
|
|
||||||
},
|
|
||||||
// RequireAuth's own line. DEBUG is off in production by
|
|
||||||
// default, but turning it on to diagnose a flood must not
|
|
||||||
// restore an unbounded write.
|
|
||||||
"requireauth redirect": {
|
|
||||||
build: func(
|
|
||||||
t *testing.T, m *middleware.Middleware,
|
|
||||||
) http.Handler {
|
|
||||||
t.Helper()
|
|
||||||
|
|
||||||
return m.RequireAuth()(unreachable(t))
|
|
||||||
},
|
|
||||||
send: getNoSession,
|
|
||||||
wantStatus: http.StatusSeeOther,
|
|
||||||
},
|
|
||||||
}
|
|
||||||
}
|
|
||||||
|
|
||||||
// sendUntilLimited drives the per-entrypoint receiver limiter past
|
|
||||||
// its allowance on one path and returns the status of the rejected
|
|
||||||
// request. Every request before the last is served, and only the last
|
|
||||||
// one logs.
|
|
||||||
func sendUntilLimited(h http.Handler, path string) int {
|
|
||||||
code := http.StatusOK
|
|
||||||
|
|
||||||
for range receiverLimitPerMinute + 1 {
|
|
||||||
req := httptest.NewRequestWithContext(
|
|
||||||
context.Background(), http.MethodPost, path, nil,
|
|
||||||
)
|
|
||||||
req.RemoteAddr = "203.0.113.7:5555"
|
|
||||||
|
|
||||||
w := httptest.NewRecorder()
|
|
||||||
h.ServeHTTP(w, req)
|
|
||||||
code = w.Code
|
|
||||||
}
|
|
||||||
|
|
||||||
return code
|
|
||||||
}
|
|
||||||
|
|
||||||
// logLines splits the captured buffer into non-empty lines, holding
|
|
||||||
// each to bound bytes.
|
|
||||||
func logLines(t *testing.T, buf *bytes.Buffer, bound int) []string {
|
|
||||||
t.Helper()
|
|
||||||
|
|
||||||
var lines []string
|
|
||||||
|
|
||||||
for line := range strings.SplitSeq(
|
|
||||||
strings.TrimSpace(buf.String()), "\n",
|
|
||||||
) {
|
|
||||||
if line == "" {
|
|
||||||
continue
|
|
||||||
}
|
|
||||||
|
|
||||||
require.LessOrEqual(
|
|
||||||
t, len(line), bound,
|
|
||||||
"log line exceeded its bound: %s", line,
|
|
||||||
)
|
|
||||||
|
|
||||||
lines = append(lines, line)
|
|
||||||
}
|
|
||||||
|
|
||||||
return lines
|
|
||||||
}
|
|
||||||
|
|
||||||
// assertNoClientText fails if any marker from the far end of the
|
|
||||||
// client-chosen input survived into the log. Their absence is what
|
|
||||||
// distinguishes a real cut from a value that merely happened to be
|
|
||||||
// short.
|
|
||||||
func assertNoClientText(t *testing.T, buf *bytes.Buffer) {
|
|
||||||
t.Helper()
|
|
||||||
|
|
||||||
assert.NotContains(
|
|
||||||
t, buf.String(), attackerMarker,
|
|
||||||
"log carried attacker-chosen text",
|
|
||||||
)
|
|
||||||
assert.NotContains(
|
|
||||||
t, buf.String(), tailMarker,
|
|
||||||
"log carried the tail of the attacker-chosen text",
|
|
||||||
)
|
|
||||||
}
|
|
||||||
|
|
||||||
// TestLogLines_ClientChosenPathDoesNotSizeTheLine points 8 KB of
|
|
||||||
// client-chosen path at each non-access-log call site that logs one,
|
|
||||||
// through both handlers and through every character those handlers
|
|
||||||
// escape, and holds the resulting line to MaxAccessLogLineBytes.
|
|
||||||
//
|
|
||||||
// Removing any one of the logfield.Truncate calls at those sites
|
|
||||||
// fails this test: the line grows to roughly the size of the input,
|
|
||||||
// or to several times it on the escaping fills.
|
|
||||||
func TestLogLines_ClientChosenPathDoesNotSizeTheLine(t *testing.T) {
|
|
||||||
t.Parallel()
|
|
||||||
|
|
||||||
for siteName, site := range logSites() {
|
|
||||||
for handlerName, newHandler := range logHandlers() {
|
|
||||||
for fillName, fill := range escapeFills() {
|
|
||||||
name := siteName + "/" + handlerName + "/" + fillName
|
|
||||||
|
|
||||||
t.Run(name, func(t *testing.T) {
|
|
||||||
t.Parallel()
|
|
||||||
|
|
||||||
m, buf := capturingBoundMiddleware(
|
|
||||||
t, newHandler,
|
|
||||||
)
|
|
||||||
|
|
||||||
path := "/source/" +
|
|
||||||
oversizedPathSegment(fill) + "/edit"
|
|
||||||
|
|
||||||
assert.Equal(
|
|
||||||
t,
|
|
||||||
site.wantStatus,
|
|
||||||
site.send(site.build(t, m), path),
|
|
||||||
)
|
|
||||||
|
|
||||||
lines := logLines(
|
|
||||||
t, buf,
|
|
||||||
middleware.MaxAccessLogLineBytes,
|
|
||||||
)
|
|
||||||
require.NotEmpty(
|
|
||||||
t, lines,
|
|
||||||
"the site under test logged nothing, "+
|
|
||||||
"so the bound proves nothing",
|
|
||||||
)
|
|
||||||
assertNoClientText(t, buf)
|
|
||||||
})
|
|
||||||
}
|
|
||||||
}
|
|
||||||
}
|
|
||||||
}
|
|
||||||
|
|
||||||
// TestLoginThrottle_LogLineDoesNotTrackPathSize pins the cap on
|
|
||||||
// RecordLoginFailure's "login failure limit exceeded" WARN line.
|
|
||||||
//
|
|
||||||
// That site does not fit logSites above: it is not a middleware
|
|
||||||
// wrapping a handler but an exported method the login handler calls,
|
|
||||||
// and the only route that calls it today is chi's static
|
|
||||||
// "/pages/login", so no request through the mux can widen the line.
|
|
||||||
// Driving the method directly is therefore the whole point rather
|
|
||||||
// than a shortcut — it is exactly the call a second caller on a route
|
|
||||||
// with a URL parameter would make, and without this test removing the
|
|
||||||
// logfield.Truncate there fails nothing.
|
|
||||||
func TestLoginThrottle_LogLineDoesNotTrackPathSize(t *testing.T) {
|
|
||||||
t.Parallel()
|
|
||||||
|
|
||||||
for handlerName, newHandler := range logHandlers() {
|
|
||||||
for fillName, fill := range escapeFills() {
|
|
||||||
t.Run(handlerName+"/"+fillName, func(t *testing.T) {
|
|
||||||
t.Parallel()
|
|
||||||
|
|
||||||
m, buf := capturingBoundMiddleware(
|
|
||||||
t, newHandler,
|
|
||||||
)
|
|
||||||
|
|
||||||
req := httptest.NewRequestWithContext(
|
|
||||||
context.Background(),
|
|
||||||
http.MethodPost,
|
|
||||||
"/source/"+
|
|
||||||
oversizedPathSegment(fill)+"/login",
|
|
||||||
nil,
|
|
||||||
)
|
|
||||||
req.RemoteAddr = "203.0.113.9:5555"
|
|
||||||
|
|
||||||
// The budget is spent per client and username,
|
|
||||||
// so one more failure than the budget allows is
|
|
||||||
// what takes the throttled branch.
|
|
||||||
var throttled bool
|
|
||||||
for range middleware.LoginRateLimitConst + 1 {
|
|
||||||
throttled = m.RecordLoginFailure(
|
|
||||||
req, "someone",
|
|
||||||
)
|
|
||||||
}
|
|
||||||
|
|
||||||
require.True(
|
|
||||||
t, throttled,
|
|
||||||
"the throttled branch never ran, so the "+
|
|
||||||
"bound proves nothing",
|
|
||||||
)
|
|
||||||
|
|
||||||
lines := logLines(
|
|
||||||
t, buf, middleware.MaxAccessLogLineBytes,
|
|
||||||
)
|
|
||||||
require.NotEmpty(t, lines)
|
|
||||||
assertNoClientText(t, buf)
|
|
||||||
})
|
|
||||||
}
|
|
||||||
}
|
|
||||||
}
|
|
||||||
|
|
||||||
// TestMaxBodySize_FloodOfOversizePathsDoesNotGrowTheLog is the
|
|
||||||
// flood shape from the issue: an unauthenticated client posting
|
|
||||||
// oversize declarations at invented 8 KB paths, as fast as it likes.
|
|
||||||
//
|
|
||||||
// It asserts the property directly rather than by proxy — the bytes
|
|
||||||
// the flood writes to the operator's log do not track the bytes the
|
|
||||||
// flood sent. The same flood at a one-character path is the control:
|
|
||||||
// 8 KB of extra input per request buys at most the field budget, not
|
|
||||||
// 8 KB of log.
|
|
||||||
func TestMaxBodySize_FloodOfOversizePathsDoesNotGrowTheLog(
|
|
||||||
t *testing.T,
|
|
||||||
) {
|
|
||||||
t.Parallel()
|
|
||||||
|
|
||||||
for handlerName, newHandler := range logHandlers() {
|
|
||||||
for fillName, fill := range escapeFills() {
|
|
||||||
t.Run(handlerName+"/"+fillName, func(t *testing.T) {
|
|
||||||
t.Parallel()
|
|
||||||
|
|
||||||
flood := func(segment func(i int) string) int {
|
|
||||||
m, buf := capturingBoundMiddleware(
|
|
||||||
t, newHandler,
|
|
||||||
)
|
|
||||||
h := m.MaxBodySize(bodyLimitBytes)(
|
|
||||||
unreachable(t),
|
|
||||||
)
|
|
||||||
|
|
||||||
for i := range floodRequests {
|
|
||||||
assert.Equal(
|
|
||||||
t,
|
|
||||||
http.StatusRequestEntityTooLarge,
|
|
||||||
postOversize(
|
|
||||||
h,
|
|
||||||
"/source/"+segment(i)+"/edit",
|
|
||||||
),
|
|
||||||
)
|
|
||||||
}
|
|
||||||
|
|
||||||
lines := logLines(
|
|
||||||
t, buf,
|
|
||||||
middleware.MaxAccessLogLineBytes,
|
|
||||||
)
|
|
||||||
require.Len(t, lines, floodRequests)
|
|
||||||
assertNoClientText(t, buf)
|
|
||||||
|
|
||||||
return buf.Len()
|
|
||||||
}
|
|
||||||
|
|
||||||
sent := oversizedSegmentBytes * floodRequests
|
|
||||||
|
|
||||||
oversize := flood(func(i int) string {
|
|
||||||
return oversizedPathSegment(fill) +
|
|
||||||
strings.Repeat("y", i)
|
|
||||||
})
|
|
||||||
control := flood(func(i int) string {
|
|
||||||
return "a" + strings.Repeat("y", i)
|
|
||||||
})
|
|
||||||
|
|
||||||
// The whole point: 8 KB per request of extra
|
|
||||||
// client-chosen input bought a bounded amount of
|
|
||||||
// log, not a proportional amount.
|
|
||||||
assert.Less(
|
|
||||||
t, oversize-control, sent/2,
|
|
||||||
"log volume tracked the size of the flood's "+
|
|
||||||
"input",
|
|
||||||
)
|
|
||||||
assert.LessOrEqual(
|
|
||||||
t,
|
|
||||||
oversize,
|
|
||||||
floodRequests*
|
|
||||||
middleware.MaxAccessLogLineBytes,
|
|
||||||
)
|
|
||||||
})
|
|
||||||
}
|
|
||||||
}
|
|
||||||
}
|
|
||||||
@@ -7,8 +7,6 @@ import (
|
|||||||
"net/http"
|
"net/http"
|
||||||
"sync"
|
"sync"
|
||||||
"time"
|
"time"
|
||||||
|
|
||||||
"sneak.berlin/go/webhooker/internal/logfield"
|
|
||||||
)
|
)
|
||||||
|
|
||||||
const (
|
const (
|
||||||
@@ -175,38 +173,10 @@ func newLoginGuard(
|
|||||||
// acquire reserves a verification slot, waiting up to the guard's
|
// acquire reserves a verification slot, waiting up to the guard's
|
||||||
// wait for one. It reports false when the queue of waiters is
|
// wait for one. It reports false when the queue of waiters is
|
||||||
// already full, when no slot became available in time, or when the
|
// already full, when no slot became available in time, or when the
|
||||||
// request was cancelled while waiting; the caller must then answer
|
// request was cancelled first; the caller must then answer 503
|
||||||
// 503 without verifying anything. The returned function releases the
|
// without verifying anything. The returned function releases the
|
||||||
// slot and must be called exactly once.
|
// slot and must be called exactly once.
|
||||||
//
|
|
||||||
// ctx is consulted only once the request has to wait: a slot that is
|
|
||||||
// free on arrival is handed out without looking at it, so an
|
|
||||||
// already-cancelled request can be granted one. That is deliberate
|
|
||||||
// and matches lifecycle.waitDone — the caller abandons the work on
|
|
||||||
// its own ctx and releases the slot immediately, so nothing is spent
|
|
||||||
// on it, and refusing instead would mean shedding a request with
|
|
||||||
// capacity standing free.
|
|
||||||
func (g *loginGuard) acquire(ctx context.Context) (func(), bool) {
|
func (g *loginGuard) acquire(ctx context.Context) (func(), bool) {
|
||||||
// A free slot is taken before any timer is armed, and before a
|
|
||||||
// queue place is claimed: a request that never waits is not a
|
|
||||||
// waiter. Without this preamble the bounded select below can find
|
|
||||||
// its slot send and an already-expired timer ready at the same
|
|
||||||
// time, and Go picks among ready cases uniformly at random — so a
|
|
||||||
// process descheduled for longer than the wait sheds a request
|
|
||||||
// with slots standing free, which is precisely when shedding is
|
|
||||||
// least defensible.
|
|
||||||
//
|
|
||||||
// This cannot let a late arrival barge past a queued waiter. A
|
|
||||||
// waiter can only be parked on a FULL buffer, and a release
|
|
||||||
// refills that buffer from the head of the send queue under the
|
|
||||||
// channel lock, so the buffer never appears non-full while anyone
|
|
||||||
// is parked and this send fails whenever there is a waiter.
|
|
||||||
select {
|
|
||||||
case g.slots <- struct{}{}:
|
|
||||||
return func() { <-g.slots }, true
|
|
||||||
default:
|
|
||||||
}
|
|
||||||
|
|
||||||
// Shedding past the queue depth is what keeps waiting memory
|
// Shedding past the queue depth is what keeps waiting memory
|
||||||
// bounded; the wait alone only bounds how long one waiter holds
|
// bounded; the wait alone only bounds how long one waiter holds
|
||||||
// its parsed form, not how many hold one at once.
|
// its parsed form, not how many hold one at once.
|
||||||
@@ -374,17 +344,8 @@ func (m *Middleware) RecordLoginFailure(
|
|||||||
) bool {
|
) bool {
|
||||||
throttled := m.guard().fail(m.clientKey(r), username)
|
throttled := m.guard().fail(m.clientKey(r), username)
|
||||||
if throttled {
|
if throttled {
|
||||||
// Truncated even though chi pins this route's path to
|
|
||||||
// the 12-byte constant "/pages/login": RecordLoginFailure
|
|
||||||
// is exported and takes any *http.Request, so a caller on
|
|
||||||
// a route with a URL parameter would otherwise widen this
|
|
||||||
// line. logbound_test.go pins the cap by making exactly
|
|
||||||
// that call, since no request through the mux can.
|
|
||||||
m.log.Warn(
|
m.log.Warn(
|
||||||
"login failure limit exceeded",
|
"login failure limit exceeded", "path", r.URL.Path,
|
||||||
"path", logfield.Truncate(
|
|
||||||
r.URL.Path, logfield.MaxBytes,
|
|
||||||
),
|
|
||||||
)
|
)
|
||||||
}
|
}
|
||||||
|
|
||||||
|
|||||||
@@ -29,15 +29,6 @@ const (
|
|||||||
|
|
||||||
guardClient = "198.51.100.7"
|
guardClient = "198.51.100.7"
|
||||||
guardUser = "admin"
|
guardUser = "admin"
|
||||||
|
|
||||||
// racePasses is how many times a both-cases-ready select race is
|
|
||||||
// run. A pass can only go the wrong way once the zero-duration
|
|
||||||
// timer has fired, so the per-pass detection probability is
|
|
||||||
// somewhere below 1/2 rather than exactly it; the bound that
|
|
||||||
// matters is that passes are independent, so a regression that
|
|
||||||
// survives is exponentially unlikely in N. The test still waits
|
|
||||||
// on nothing.
|
|
||||||
racePasses = 1000
|
|
||||||
)
|
)
|
||||||
|
|
||||||
// newGuard builds a guard with production-shaped defaults and the
|
// newGuard builds a guard with production-shaped defaults and the
|
||||||
@@ -233,71 +224,21 @@ func TestLoginGuard_SemaphoreBoundsConcurrentVerifications(
|
|||||||
const (
|
const (
|
||||||
concurrency = 2
|
concurrency = 2
|
||||||
workers = 12
|
workers = 12
|
||||||
|
|
||||||
// rendezvousDeadlock is the deadlock guard described below.
|
|
||||||
// It is orders of magnitude longer than any scheduling delay,
|
|
||||||
// so it never decides the result, and well inside script/test's
|
|
||||||
// 30s timeout, so a wedge fails on the assertion instead of
|
|
||||||
// blowing the package timeout.
|
|
||||||
rendezvousDeadlock = 5 * time.Second
|
|
||||||
)
|
)
|
||||||
|
|
||||||
g := newGuard(middleware.LoginFailureMaxKeysConst, concurrency)
|
g := newGuard(middleware.LoginFailureMaxKeysConst, concurrency)
|
||||||
|
|
||||||
var (
|
var (
|
||||||
mu sync.Mutex
|
mu sync.Mutex
|
||||||
inside int
|
inside int
|
||||||
highest int
|
highest int
|
||||||
wg sync.WaitGroup
|
wg sync.WaitGroup
|
||||||
recorded sync.WaitGroup
|
|
||||||
once sync.Once
|
|
||||||
)
|
)
|
||||||
|
|
||||||
// Slot holders rendezvous instead of sleeping, and they hold until
|
|
||||||
// every worker has been answered. A sleep only makes overlap
|
|
||||||
// likely — on a host loaded enough to deschedule a goroutine for
|
|
||||||
// longer than the sleep the workers serialise and the maximum
|
|
||||||
// observed comes back as 1 — so the rendezvous is what makes the
|
|
||||||
// overlap a fact rather than a race won.
|
|
||||||
//
|
|
||||||
// The barrier must not open at the concurrency-th holder, which
|
|
||||||
// would fix the lower bound at the cost of the upper one this test
|
|
||||||
// exists to enforce: holders would leave as soon as the count
|
|
||||||
// reached concurrency, so a guard admitting extra requests would
|
|
||||||
// let them arrive after the first holders had already left and
|
|
||||||
// highest would report concurrency however many were really let
|
|
||||||
// in. It opens instead once every worker's acquire has returned
|
|
||||||
// and any slot it won has been counted, so under a broken guard
|
|
||||||
// every admitted worker is inside simultaneously and highest is
|
|
||||||
// the true maximum. Under a correct guard the refused workers
|
|
||||||
// return within the guard's own wait, which decides nothing beyond
|
|
||||||
// how long that takes.
|
|
||||||
overlapped := make(chan struct{})
|
|
||||||
closeOverlapped := func() {
|
|
||||||
once.Do(func() { close(overlapped) })
|
|
||||||
}
|
|
||||||
|
|
||||||
// Deadlock guard, not a timing margin: no assertion depends on its
|
|
||||||
// length, and the only way to reach it is a worker that never
|
|
||||||
// returns from acquire at all. It is here so that such a wedge
|
|
||||||
// fails legibly on the assertion below instead of hanging until
|
|
||||||
// the package test timeout.
|
|
||||||
abandon := time.AfterFunc(rendezvousDeadlock, closeOverlapped)
|
|
||||||
defer abandon.Stop()
|
|
||||||
|
|
||||||
recorded.Add(workers)
|
|
||||||
|
|
||||||
go func() {
|
|
||||||
recorded.Wait()
|
|
||||||
closeOverlapped()
|
|
||||||
}()
|
|
||||||
|
|
||||||
for range workers {
|
for range workers {
|
||||||
wg.Go(func() {
|
wg.Go(func() {
|
||||||
release, ok := g.AcquireForTest(context.Background())
|
release, ok := g.AcquireForTest(context.Background())
|
||||||
if !ok {
|
if !ok {
|
||||||
recorded.Done()
|
|
||||||
|
|
||||||
return
|
return
|
||||||
}
|
}
|
||||||
|
|
||||||
@@ -312,12 +253,9 @@ func TestLoginGuard_SemaphoreBoundsConcurrentVerifications(
|
|||||||
|
|
||||||
mu.Unlock()
|
mu.Unlock()
|
||||||
|
|
||||||
// Counted before signalling, so the barrier can never open
|
// Hold the slot long enough that the other workers are
|
||||||
// while an admitted worker is still on its way to being
|
// certainly contending for it.
|
||||||
// counted.
|
time.Sleep(10 * time.Millisecond)
|
||||||
recorded.Done()
|
|
||||||
|
|
||||||
<-overlapped
|
|
||||||
|
|
||||||
mu.Lock()
|
mu.Lock()
|
||||||
inside--
|
inside--
|
||||||
@@ -340,14 +278,6 @@ func TestLoginGuard_SemaphoreBoundsConcurrentVerifications(
|
|||||||
// what happens when every slot is taken for longer than the wait: the
|
// what happens when every slot is taken for longer than the wait: the
|
||||||
// request is refused, so the caller answers 503 without allocating
|
// request is refused, so the caller answers 503 without allocating
|
||||||
// another 64 MB hash.
|
// another 64 MB hash.
|
||||||
//
|
|
||||||
// Neither half of this rides on the wait being long enough. The
|
|
||||||
// refusal holds the only slot across the whole of the second call, so
|
|
||||||
// there is no wait it could get lucky with — the wait fixes only how
|
|
||||||
// long the refusal takes, not whether it happens. The reuse after
|
|
||||||
// release is settled by acquire's non-blocking preamble, which is
|
|
||||||
// pinned separately by TestLoginGuard_FreeSlotBeatsAnExpiredWait. So
|
|
||||||
// the wait below is sized to keep the test quick, not to win a race.
|
|
||||||
func TestLoginGuard_SaturatedSemaphoreRefusesRatherThanQueueing(
|
func TestLoginGuard_SaturatedSemaphoreRefusesRatherThanQueueing(
|
||||||
t *testing.T,
|
t *testing.T,
|
||||||
) {
|
) {
|
||||||
@@ -375,58 +305,13 @@ func TestLoginGuard_SaturatedSemaphoreRefusesRatherThanQueueing(
|
|||||||
release()
|
release()
|
||||||
|
|
||||||
release, ok = g.AcquireForTest(context.Background())
|
release, ok = g.AcquireForTest(context.Background())
|
||||||
|
assert.True(
|
||||||
// require, not assert: acquire returns a nil release alongside a
|
|
||||||
// false ok, so calling it after a non-fatal assertion turns one
|
|
||||||
// failed test into a segfault that takes the whole package test
|
|
||||||
// binary down. Every assertion whose value is dereferenced later
|
|
||||||
// has to stop the test.
|
|
||||||
require.True(
|
|
||||||
t, ok, "the slot must be reusable once released",
|
t, ok, "the slot must be reusable once released",
|
||||||
)
|
)
|
||||||
|
|
||||||
release()
|
release()
|
||||||
}
|
}
|
||||||
|
|
||||||
// TestLoginGuard_FreeSlotBeatsAnExpiredWait is the determinism this
|
|
||||||
// file used to lack. acquire selects over a slot send and a wait
|
|
||||||
// timer, and Go chooses among ready cases uniformly at random, so a
|
|
||||||
// call made after the timer had already fired was a coin flip: on a
|
|
||||||
// loaded host the previous test's third acquire could be refused
|
|
||||||
// with its slot standing free, and then dereference the nil release
|
|
||||||
// it got back.
|
|
||||||
//
|
|
||||||
// The wait here is already elapsed on arrival, which is the worst
|
|
||||||
// case that scheduling can produce, so a free slot must still be
|
|
||||||
// granted every time. Without acquire's non-blocking preamble each
|
|
||||||
// pass is an independent coin flip and the loop fails within a few
|
|
||||||
// passes; with it the property holds by construction and no wall
|
|
||||||
// clock is involved.
|
|
||||||
func TestLoginGuard_FreeSlotBeatsAnExpiredWait(t *testing.T) {
|
|
||||||
t.Parallel()
|
|
||||||
|
|
||||||
g := middleware.NewLoginGuardForTest(
|
|
||||||
middleware.LoginRateLimitConst,
|
|
||||||
guardInterval,
|
|
||||||
middleware.LoginFailureMaxKeysConst,
|
|
||||||
1,
|
|
||||||
middleware.PasswordVerifyMaxWaitersConst,
|
|
||||||
0,
|
|
||||||
)
|
|
||||||
|
|
||||||
for pass := range racePasses {
|
|
||||||
release, ok := g.AcquireForTest(context.Background())
|
|
||||||
require.Truef(
|
|
||||||
t, ok,
|
|
||||||
"pass %d was refused a slot that was free; an expired "+
|
|
||||||
"wait must never beat an available slot",
|
|
||||||
pass,
|
|
||||||
)
|
|
||||||
|
|
||||||
release()
|
|
||||||
}
|
|
||||||
}
|
|
||||||
|
|
||||||
// TestLoginGuard_AcquireHonoursCancellation proves a client that
|
// TestLoginGuard_AcquireHonoursCancellation proves a client that
|
||||||
// disconnects while queued frees its place immediately instead of
|
// disconnects while queued frees its place immediately instead of
|
||||||
// holding it for the full wait.
|
// holding it for the full wait.
|
||||||
@@ -503,20 +388,13 @@ func TestLoginGuard_ShedsPastTheQueueCap(t *testing.T) {
|
|||||||
neverElapses = time.Minute
|
neverElapses = time.Minute
|
||||||
|
|
||||||
// The probe carries its own deadline, so a guard that queues
|
// The probe carries its own deadline, so a guard that queues
|
||||||
// the probe instead of shedding it fails here rather than
|
// the probe instead of shedding it fails on the elapsed time
|
||||||
// hanging until the package test timeout.
|
// rather than hanging until the package test timeout.
|
||||||
//
|
probeWait = 200 * time.Millisecond
|
||||||
// This is a patience budget, not a margin to be won. A shed
|
|
||||||
// returns in microseconds and a probe that queued instead
|
// Shedding takes no measurable time; queueing takes the whole
|
||||||
// would not return for neverElapses, so the two are a whole
|
// probeWait. Anything under half of it is unambiguous.
|
||||||
// minute apart and any budget between them separates them. It
|
shedFast = probeWait / 2
|
||||||
// is set far above any scheduling stall a loaded host can
|
|
||||||
// produce, because the previous 200 ms — and the 100 ms
|
|
||||||
// elapsed-time assertion it fed — bounded the latency of a
|
|
||||||
// goroutine hand-off, which is a false red waiting to happen
|
|
||||||
// on the machine this suite runs on. What actually proves the
|
|
||||||
// probe was not queued is the queue depth asserted below.
|
|
||||||
probePatience = 5 * time.Second
|
|
||||||
)
|
)
|
||||||
|
|
||||||
g := middleware.NewLoginGuardForTest(
|
g := middleware.NewLoginGuardForTest(
|
||||||
@@ -535,17 +413,22 @@ func TestLoginGuard_ShedsPastTheQueueCap(t *testing.T) {
|
|||||||
defer release()
|
defer release()
|
||||||
defer fillQueue(t, g, maxWaiters)()
|
defer fillQueue(t, g, maxWaiters)()
|
||||||
|
|
||||||
granted, answered := probeQueueCap(g, probePatience)
|
got := probeQueueCap(g, probeWait)
|
||||||
|
|
||||||
require.True(
|
require.NotNil(
|
||||||
t, answered,
|
t, got,
|
||||||
"a request arriving past the queue cap is still waiting to "+
|
"a request arriving past the queue cap is still waiting to "+
|
||||||
"be queued; it must have been shed",
|
"be queued; it must have been shed",
|
||||||
)
|
)
|
||||||
assert.False(
|
assert.False(
|
||||||
t, granted,
|
t, got.ok,
|
||||||
"a request arriving past the queue cap must be shed",
|
"a request arriving past the queue cap must be shed",
|
||||||
)
|
)
|
||||||
|
assert.Less(
|
||||||
|
t, got.elapsed, shedFast,
|
||||||
|
"shedding must be immediate; waiting for a place in the "+
|
||||||
|
"queue is the memory growth this bounds",
|
||||||
|
)
|
||||||
assert.Equal(
|
assert.Equal(
|
||||||
t, maxWaiters, g.QueuedWaitersForTest(),
|
t, maxWaiters, g.QueuedWaitersForTest(),
|
||||||
"a shed request must not have grown the queue",
|
"a shed request must not have grown the queue",
|
||||||
@@ -575,14 +458,10 @@ func fillQueue(
|
|||||||
})
|
})
|
||||||
}
|
}
|
||||||
|
|
||||||
// Patience budget, not a margin: the waiters park in microseconds
|
|
||||||
// and nothing releases them, so the only way to exhaust this is a
|
|
||||||
// guard that never queues. One second is the same order as the
|
|
||||||
// scheduling stalls this suite has to survive, so it is not one.
|
|
||||||
require.Eventually(
|
require.Eventually(
|
||||||
t,
|
t,
|
||||||
func() bool { return g.QueuedWaitersForTest() == n },
|
func() bool { return g.QueuedWaitersForTest() == n },
|
||||||
5*time.Second, time.Millisecond,
|
time.Second, time.Millisecond,
|
||||||
"the waiters must reach the queue before the cap is tested",
|
"the waiters must reach the queue before the cap is tested",
|
||||||
)
|
)
|
||||||
|
|
||||||
@@ -592,38 +471,41 @@ func fillQueue(
|
|||||||
}
|
}
|
||||||
}
|
}
|
||||||
|
|
||||||
// probeQueueCap acquires from another goroutine. It reports, in
|
// probeResult is what the queue-cap probe reports: whether it got a
|
||||||
// order, whether the call was granted a slot and whether it was
|
// slot, and how long it took to find out.
|
||||||
// answered at all within wait; a call that never returned reports
|
type probeResult struct {
|
||||||
// false for both.
|
ok bool
|
||||||
|
elapsed time.Duration
|
||||||
|
}
|
||||||
|
|
||||||
|
// probeQueueCap acquires from another goroutine and reports the
|
||||||
|
// result, or nil if the call was still blocked after wait.
|
||||||
//
|
//
|
||||||
// It runs off the test goroutine deliberately. Joining a full queue
|
// It runs off the test goroutine deliberately. Joining a full queue
|
||||||
// is not cancellable by context — refusing to join is the property
|
// is not cancellable by context — refusing to join is the property
|
||||||
// under test — so a guard that fails this would otherwise hang the
|
// under test — so a guard that fails this would otherwise hang the
|
||||||
// package until the test timeout instead of failing here.
|
// package until the test timeout instead of failing here.
|
||||||
//
|
|
||||||
// It reports no elapsed time. Timing a goroutine hand-off measures
|
|
||||||
// the host, not the guard, and the caller distinguishes shedding from
|
|
||||||
// queueing by the queue depth instead.
|
|
||||||
func probeQueueCap(
|
func probeQueueCap(
|
||||||
g *middleware.LoginGuard,
|
g *middleware.LoginGuard,
|
||||||
wait time.Duration,
|
wait time.Duration,
|
||||||
) (bool, bool) {
|
) *probeResult {
|
||||||
probed := make(chan bool, 1)
|
probed := make(chan probeResult, 1)
|
||||||
|
|
||||||
go func() {
|
go func() {
|
||||||
|
start := time.Now()
|
||||||
|
|
||||||
release, ok := g.AcquireForTest(context.Background())
|
release, ok := g.AcquireForTest(context.Background())
|
||||||
if ok {
|
if ok {
|
||||||
release()
|
release()
|
||||||
}
|
}
|
||||||
|
|
||||||
probed <- ok
|
probed <- probeResult{ok: ok, elapsed: time.Since(start)}
|
||||||
}()
|
}()
|
||||||
|
|
||||||
select {
|
select {
|
||||||
case result := <-probed:
|
case result := <-probed:
|
||||||
return result, true
|
return &result
|
||||||
case <-time.After(wait):
|
case <-time.After(wait):
|
||||||
return false, false
|
return nil
|
||||||
}
|
}
|
||||||
}
|
}
|
||||||
|
|||||||
@@ -57,7 +57,7 @@ const (
|
|||||||
// MaxAccessLogLineBytes is the ceiling on one JSON access log line,
|
// MaxAccessLogLineBytes is the ceiling on one JSON access log line,
|
||||||
// and the number an operator multiplies by the request rate to size
|
// and the number an operator multiplies by the request rate to size
|
||||||
// log storage. It is not an observation of a sample: it is the sum
|
// log storage. It is not an observation of a sample: it is the sum
|
||||||
// of the budgets above, each of which logfield.Truncate enforces in
|
// of the field budgets, each of which logfield.Truncate enforces in
|
||||||
// ENCODED bytes, plus the part of the line no client can influence.
|
// ENCODED bytes, plus the part of the line no client can influence.
|
||||||
//
|
//
|
||||||
// url, useragent, referer 3*(512+11) = 1569
|
// url, useragent, referer 3*(512+11) = 1569
|
||||||
@@ -85,64 +85,21 @@ const (
|
|||||||
// The text handler's fixed portion is 286, the smaller of the two,
|
// The text handler's fixed portion is 286, the smaller of the two,
|
||||||
// which puts its worst case at 2037.
|
// which puts its worst case at 2037.
|
||||||
//
|
//
|
||||||
// It is also the ceiling on every OTHER line this service writes
|
// The access log is the widest line this service writes that
|
||||||
// THROUGH SLOG that carries text an UNAUTHENTICATED client
|
// carries client-chosen text, so the figure is also the ceiling on
|
||||||
// supplies. Those lines — the MaxBodySize rejection, the CSRF
|
// the other writer that does: the GORM adapter in
|
||||||
// rejection, the rate-limit rejection, the unauthenticated-request
|
// internal/gormlog, whose widest line spends two logfield.MaxBytes
|
||||||
// and unknown-entrypoint DEBUG lines, the failed-login DEBUG
|
// budgets (the interpolated SQL and the driver error) against a
|
||||||
// lines, and the two login-throttle WARN lines ("login failure
|
// fixed portion smaller than this one's.
|
||||||
// limit exceeded" in loginguard.go and "password verification
|
// internal/gormlog/gormlog_test.go asserts that against this
|
||||||
// capacity exhausted" in internal/handlers/auth.go) — spend the
|
// constant directly rather than leaving it as arithmetic.
|
||||||
// same per-field budgets, and each carries strictly fewer
|
|
||||||
// client-supplied fields than the access log does,
|
|
||||||
// so none of them can reach a width the access log cannot. That is
|
|
||||||
// asserted directly, per line and under both handlers, rather than
|
|
||||||
// left to the reasoning: see logbound_test.go in this package and
|
|
||||||
// in internal/handlers.
|
|
||||||
//
|
//
|
||||||
// The two login-throttle lines are capped defensively: chi pins
|
// It is not the widest line the service can write. A handler panic
|
||||||
// their route to the constant path "/pages/login", so no request
|
// arrives through net/http's nil ErrorLog as one record carrying a
|
||||||
// through the mux can widen either one. Their assertions call
|
// whole goroutine stack, measured at 2,772 bytes. That value is
|
||||||
// RecordLoginFailure and the login handler directly with the path
|
// the runtime's, not a client's, so it is a carve-out this ceiling
|
||||||
// a caller on a parameterised route would supply, which is the
|
// states rather than covers; see README.md and
|
||||||
// only way those caps can be pinned at all.
|
// https://git.eeqj.de/sneak/webhooker/issues/187.
|
||||||
//
|
|
||||||
// One writer in that set is not a handler's own slog call. The
|
|
||||||
// GORM adapter in internal/gormlog logs the statement with the
|
|
||||||
// client-chosen parameter already interpolated into it, which on
|
|
||||||
// the receiver and login lookups is exactly the value the budgets
|
|
||||||
// above exist for. Its widest line spends two logfield.MaxBytes
|
|
||||||
// budgets — the statement and the driver error — against a fixed
|
|
||||||
// portion smaller than this one's, and
|
|
||||||
// internal/gormlog/gormlog_test.go asserts every line it emits
|
|
||||||
// against this constant directly rather than leaving it as
|
|
||||||
// arithmetic.
|
|
||||||
//
|
|
||||||
// What it does NOT cover, so that the figure above is not read as
|
|
||||||
// more than it is:
|
|
||||||
//
|
|
||||||
// - Lines carrying an AUTHENTICATED operator's own input, which
|
|
||||||
// are not truncated at all: the webhook name on "webhook
|
|
||||||
// created" and the target host on "target URL blocked by SSRF
|
|
||||||
// protection" (both internal/handlers/source_management.go),
|
|
||||||
// and target_name in internal/delivery/engine.go and
|
|
||||||
// target_http.go. Each is bounded only by the 1 MB form body
|
|
||||||
// cap, so a 100 KB name writes one line of roughly 600 KB.
|
|
||||||
// Deliberate: truncating the operator's own configuration
|
|
||||||
// echoed back costs debuggability against no adversary.
|
|
||||||
// - The "log" delivery target, which exists to write the whole
|
|
||||||
// inbound event to the log. Deliberate; see
|
|
||||||
// internal/delivery/target_log.go.
|
|
||||||
// - The widest line the service can write, which is neither an
|
|
||||||
// access log line nor client-chosen. A handler panic arrives
|
|
||||||
// through net/http's nil ErrorLog as one record carrying a
|
|
||||||
// whole goroutine stack, above this figure — measured at
|
|
||||||
// roughly 2,770 bytes. The exact width is not an invariant: it
|
|
||||||
// moves with the goroutine number and with the source paths
|
|
||||||
// baked into the stack. That it exceeds this ceiling does not
|
|
||||||
// move. The value is the runtime's, not a client's; see
|
|
||||||
// README.md and
|
|
||||||
// https://git.eeqj.de/sneak/webhooker/issues/187.
|
|
||||||
MaxAccessLogLineBytes = 2560
|
MaxAccessLogLineBytes = 2560
|
||||||
)
|
)
|
||||||
|
|
||||||
@@ -394,21 +351,10 @@ func (s *Middleware) RequireAuth() func(http.Handler) http.Handler {
|
|||||||
// session lands here and is sent back to the login
|
// session lands here and is sent back to the login
|
||||||
// page.
|
// page.
|
||||||
if !s.session.IsAuthenticated(sess) {
|
if !s.session.IsAuthenticated(sess) {
|
||||||
// This is the unauthenticated branch, so both
|
|
||||||
// fields are entirely client-chosen and neither
|
|
||||||
// is bounded by anything the router did. DEBUG
|
|
||||||
// is off by default, but turning it on to
|
|
||||||
// diagnose a problem must not hand a client an
|
|
||||||
// unbounded write into the log, so the same
|
|
||||||
// budgets apply here as in the access log.
|
|
||||||
s.log.Debug(
|
s.log.Debug(
|
||||||
"auth middleware: unauthenticated request",
|
"auth middleware: unauthenticated request",
|
||||||
"path", logfield.Truncate(
|
"path", r.URL.Path,
|
||||||
r.URL.Path, logfield.MaxBytes,
|
"method", r.Method,
|
||||||
),
|
|
||||||
"method", logfield.Truncate(
|
|
||||||
r.Method, maxLogMethodBytes,
|
|
||||||
),
|
|
||||||
)
|
)
|
||||||
http.Redirect(
|
http.Redirect(
|
||||||
w, r, "/pages/login", http.StatusSeeOther,
|
w, r, "/pages/login", http.StatusSeeOther,
|
||||||
@@ -568,26 +514,10 @@ func (s *Middleware) MaxBodySize(
|
|||||||
}
|
}
|
||||||
|
|
||||||
if r.ContentLength > maxBytes {
|
if r.ContentLength > maxBytes {
|
||||||
// This runs ahead of RequireAuth (see
|
|
||||||
// setupUserRoutes and friends in
|
|
||||||
// internal/server/routes.go), so an
|
|
||||||
// unauthenticated client reaches it with a path
|
|
||||||
// of its own choosing and its own length —
|
|
||||||
// POST /source/<8 KB>/edit with an oversize
|
|
||||||
// declared Content-Length costs nothing to
|
|
||||||
// send. At WARN, on by default, that is a
|
|
||||||
// write into the operator's log sized by the
|
|
||||||
// attacker unless the path is capped. Same
|
|
||||||
// budgets as the access log, so this line
|
|
||||||
// cannot be wider than that one.
|
|
||||||
s.log.Warn(
|
s.log.Warn(
|
||||||
"request body exceeds limit",
|
"request body exceeds limit",
|
||||||
"method", logfield.Truncate(
|
"method", r.Method,
|
||||||
r.Method, maxLogMethodBytes,
|
"path", r.URL.Path,
|
||||||
),
|
|
||||||
"path", logfield.Truncate(
|
|
||||||
r.URL.Path, logfield.MaxBytes,
|
|
||||||
),
|
|
||||||
"content_length", r.ContentLength,
|
"content_length", r.ContentLength,
|
||||||
"limit", maxBytes,
|
"limit", maxBytes,
|
||||||
)
|
)
|
||||||
|
|||||||
@@ -57,21 +57,7 @@ func testMiddlewareWithSessionClock(
|
|||||||
SessionIdleTimeout: idleTimeout,
|
SessionIdleTimeout: idleTimeout,
|
||||||
}
|
}
|
||||||
|
|
||||||
sessManager := newTestSessionManager(cfg, log, clock)
|
// Create a real session manager with a known key
|
||||||
|
|
||||||
m := middleware.NewForTest(log, cfg, sessManager)
|
|
||||||
|
|
||||||
return m, sessManager, clock
|
|
||||||
}
|
|
||||||
|
|
||||||
// newTestSessionManager builds the real session.Session the
|
|
||||||
// middleware tests run against: an in-memory cookie store with a
|
|
||||||
// known key, and optionally a manually advanced clock.
|
|
||||||
func newTestSessionManager(
|
|
||||||
cfg *config.Config,
|
|
||||||
log *slog.Logger,
|
|
||||||
clock *fakeClock,
|
|
||||||
) *session.Session {
|
|
||||||
key := make([]byte, testKeySize)
|
key := make([]byte, testKeySize)
|
||||||
|
|
||||||
for i := range key {
|
for i := range key {
|
||||||
@@ -93,7 +79,11 @@ func newTestSessionManager(
|
|||||||
now = clock.Now
|
now = clock.Now
|
||||||
}
|
}
|
||||||
|
|
||||||
return session.NewForTest(store, cfg, log, key, now)
|
sessManager := session.NewForTest(store, cfg, log, key, now)
|
||||||
|
|
||||||
|
m := middleware.NewForTest(log, cfg, sessManager)
|
||||||
|
|
||||||
|
return m, sessManager, clock
|
||||||
}
|
}
|
||||||
|
|
||||||
// fakeClock is a manually advanced clock, so session expiry can be
|
// fakeClock is a manually advanced clock, so session expiry can be
|
||||||
|
|||||||
@@ -9,7 +9,6 @@ import (
|
|||||||
"time"
|
"time"
|
||||||
|
|
||||||
"github.com/go-chi/httprate"
|
"github.com/go-chi/httprate"
|
||||||
"sneak.berlin/go/webhooker/internal/logfield"
|
|
||||||
)
|
)
|
||||||
|
|
||||||
const (
|
const (
|
||||||
@@ -226,22 +225,11 @@ func (m *Middleware) clientKey(r *http.Request) string {
|
|||||||
// rejection with logMessage and answers with responseMessage.
|
// rejection with logMessage and answers with responseMessage.
|
||||||
// httprate adds the Retry-After header (RFC 6585). The aggregate
|
// httprate adds the Retry-After header (RFC 6585). The aggregate
|
||||||
// receiver limiter uses floodTooManyRequests instead.
|
// receiver limiter uses floodTooManyRequests instead.
|
||||||
//
|
|
||||||
// The path is capped against the same budget as the access log's url
|
|
||||||
// field. The per-entrypoint receiver limiter is unauthenticated and
|
|
||||||
// its path is a client-chosen segment of client-chosen length, so at
|
|
||||||
// WARN an uncapped path would let a sender pick the size of the line
|
|
||||||
// it writes — the same defect the access log capping closed.
|
|
||||||
func (m *Middleware) tooManyRequests(
|
func (m *Middleware) tooManyRequests(
|
||||||
logMessage, responseMessage string,
|
logMessage, responseMessage string,
|
||||||
) http.HandlerFunc {
|
) http.HandlerFunc {
|
||||||
return func(w http.ResponseWriter, r *http.Request) {
|
return func(w http.ResponseWriter, r *http.Request) {
|
||||||
m.log.Warn(
|
m.log.Warn(logMessage, "path", r.URL.Path)
|
||||||
logMessage,
|
|
||||||
"path", logfield.Truncate(
|
|
||||||
r.URL.Path, logfield.MaxBytes,
|
|
||||||
),
|
|
||||||
)
|
|
||||||
http.Error(w, responseMessage, http.StatusTooManyRequests)
|
http.Error(w, responseMessage, http.StatusTooManyRequests)
|
||||||
}
|
}
|
||||||
}
|
}
|
||||||
|
|||||||
@@ -14,28 +14,6 @@ import (
|
|||||||
// maxFormBodySize is the maximum allowed request body size (in
|
// maxFormBodySize is the maximum allowed request body size (in
|
||||||
// bytes) for form POST endpoints. 1 MB is generous for any form
|
// bytes) for form POST endpoints. 1 MB is generous for any form
|
||||||
// submission while preventing abuse from oversized payloads.
|
// submission while preventing abuse from oversized payloads.
|
||||||
//
|
|
||||||
// Every route group below installs MaxBodySize(maxFormBodySize) as
|
|
||||||
// its FIRST middleware, ahead of both CSRF and RequireAuth. Both
|
|
||||||
// orderings are deliberate.
|
|
||||||
//
|
|
||||||
// Ahead of CSRF because gorilla/csrf parses the form. The cap has to
|
|
||||||
// be installed before anything reads the body, or the parse runs
|
|
||||||
// under net/http's 10 MB default instead of this one.
|
|
||||||
//
|
|
||||||
// Ahead of RequireAuth because an oversize body should be refused
|
|
||||||
// before the request buys a cookie decrypt, a session load and the
|
|
||||||
// database read behind it. Rejecting first is the cheaper failure,
|
|
||||||
// and it is the ordering that keeps an unauthenticated flood from
|
|
||||||
// choosing how much session work the process does.
|
|
||||||
//
|
|
||||||
// What that ordering costs: the 413 branch is reachable
|
|
||||||
// unauthenticated, at a URL of the client's choosing and of the
|
|
||||||
// client's chosen length. So is the CSRF rejection, which sits in
|
|
||||||
// front of RequireAuth for the same reason. Both log that path, so
|
|
||||||
// both cap it — see the log calls in Middleware.MaxBodySize and
|
|
||||||
// Middleware.CSRF, which spend the same per-field budget as the
|
|
||||||
// access log.
|
|
||||||
const maxFormBodySize int64 = 1 * 1024 * 1024 // 1 MB
|
const maxFormBodySize int64 = 1 * 1024 * 1024 // 1 MB
|
||||||
|
|
||||||
// requestTimeout is the maximum time allowed for a single HTTP
|
// requestTimeout is the maximum time allowed for a single HTTP
|
||||||
@@ -112,8 +90,8 @@ func (s *Server) setupRoutes() {
|
|||||||
|
|
||||||
func (s *Server) setupPageRoutes() {
|
func (s *Server) setupPageRoutes() {
|
||||||
s.router.Route("/pages", func(r chi.Router) {
|
s.router.Route("/pages", func(r chi.Router) {
|
||||||
// MaxBodySize precedes CSRF and RequireAuth deliberately;
|
// MaxBodySize must precede CSRF: gorilla/csrf parses the
|
||||||
// see maxFormBodySize for why, and for what it costs.
|
// form, so the cap has to be installed before it runs.
|
||||||
r.Use(s.mw.MaxBodySize(maxFormBodySize))
|
r.Use(s.mw.MaxBodySize(maxFormBodySize))
|
||||||
r.Use(s.mw.CSRF())
|
r.Use(s.mw.CSRF())
|
||||||
r.Use(s.mw.NoCache())
|
r.Use(s.mw.NoCache())
|
||||||
@@ -133,8 +111,8 @@ func (s *Server) setupPageRoutes() {
|
|||||||
|
|
||||||
func (s *Server) setupUserRoutes() {
|
func (s *Server) setupUserRoutes() {
|
||||||
s.router.Route("/user/{username}", func(r chi.Router) {
|
s.router.Route("/user/{username}", func(r chi.Router) {
|
||||||
// MaxBodySize precedes CSRF and RequireAuth deliberately;
|
// MaxBodySize must precede CSRF: gorilla/csrf parses the
|
||||||
// see maxFormBodySize for why, and for what it costs.
|
// form, so the cap has to be installed before it runs.
|
||||||
r.Use(s.mw.MaxBodySize(maxFormBodySize))
|
r.Use(s.mw.MaxBodySize(maxFormBodySize))
|
||||||
r.Use(s.mw.CSRF())
|
r.Use(s.mw.CSRF())
|
||||||
r.Use(s.mw.NoCache())
|
r.Use(s.mw.NoCache())
|
||||||
@@ -148,8 +126,8 @@ func (s *Server) setupUserRoutes() {
|
|||||||
|
|
||||||
func (s *Server) setupSourceRoutes() {
|
func (s *Server) setupSourceRoutes() {
|
||||||
s.router.Route("/sources", func(r chi.Router) {
|
s.router.Route("/sources", func(r chi.Router) {
|
||||||
// MaxBodySize precedes CSRF and RequireAuth deliberately;
|
// MaxBodySize must precede CSRF: gorilla/csrf parses the
|
||||||
// see maxFormBodySize for why, and for what it costs.
|
// form, so the cap has to be installed before it runs.
|
||||||
r.Use(s.mw.MaxBodySize(maxFormBodySize))
|
r.Use(s.mw.MaxBodySize(maxFormBodySize))
|
||||||
r.Use(s.mw.CSRF())
|
r.Use(s.mw.CSRF())
|
||||||
r.Use(s.mw.NoCache())
|
r.Use(s.mw.NoCache())
|
||||||
@@ -160,8 +138,8 @@ func (s *Server) setupSourceRoutes() {
|
|||||||
})
|
})
|
||||||
|
|
||||||
s.router.Route("/source/{sourceID}", func(r chi.Router) {
|
s.router.Route("/source/{sourceID}", func(r chi.Router) {
|
||||||
// MaxBodySize precedes CSRF and RequireAuth deliberately;
|
// MaxBodySize must precede CSRF: gorilla/csrf parses the
|
||||||
// see maxFormBodySize for why, and for what it costs.
|
// form, so the cap has to be installed before it runs.
|
||||||
r.Use(s.mw.MaxBodySize(maxFormBodySize))
|
r.Use(s.mw.MaxBodySize(maxFormBodySize))
|
||||||
r.Use(s.mw.CSRF())
|
r.Use(s.mw.CSRF())
|
||||||
r.Use(s.mw.NoCache())
|
r.Use(s.mw.NoCache())
|
||||||
|
|||||||
Reference in New Issue
Block a user