Compare commits

4 Commits

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

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

The sweep the issue asked for found five more call sites of the same
shape, all reachable unauthenticated, all now capped: the CSRF 403
(also registered ahead of RequireAuth), the rate limiters' 429 (the
per-entrypoint receiver limiter is unauthenticated), RequireAuth's own
DEBUG line, the unknown-entrypoint DEBUG line on the receiver, and the
failed-login DEBUG lines. DEBUG being off by default is not a bound: an
operator turning it on to diagnose a flood must not thereby hand the
flood an unbounded write. Every other slog call in the tree was read
and judged; the PR body lists all of them, including the ones left
alone and why.

Two further sites arrived in next with #171 after the first sweep was
written and are capped here as well: "login failure limit exceeded" in
loginguard.go and "password verification capacity exhausted" in
handlers/auth.go, both WARN on the unauthenticated login POST. Neither
was ever wide — chi routes that POST on a static pattern, so r.URL.Path
is the 12-byte constant /pages/login and each line lands near 120
bytes. They are capped because RecordLoginFailure is exported and takes
any *http.Request, so the bound rests on a routing invariant nobody
wrote down, and because the same message at handlers/profile.go logs no
path at all. No request through the mux can widen either line, so their
tests call those two entry points directly with the path a caller on a
parameterised route would supply; that is what the caps defend against,
and an unasserted cap is one a later edit removes for free.

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

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

Tests drive 8 KB of client-chosen text at all eight sites, through both
handlers internal/logger can install and through each character they
escape — including a bare C0 control, which costs six bytes on the line
against the one it cost to send and is the case a raw-byte budget
breaks on first. Each holds the encoded line to the ceiling and asserts
the markers at the far end of the input are absent, so a value that
merely happened to be short cannot pass; for the six sites a request
can widen, the whole flood's output is held to what that ceiling
allows. The two login lines past the username lookup, capped for
uniformity rather than need, are pinned too. internal/logfield gains a
test that measures the per-rune charge against what the handlers really
emit over roughly 3,000 code points on each, so an undercharged rune
fails a test instead of quietly falsifying the ceiling.

Verified by mutation: reverting the MaxBodySize cap alone fails 28
subtests with a 16,583-byte line against the 2,560 ceiling; reverting
the other five fails 70; reverting either login-throttle WARN cap fails
14, through the direct calls those caps exist for; uncapping either of
the two login lines past the username lookup fails both handlers on its
own, so those two are independently pinned rather than jointly;
budgeting raw bytes instead of encoded ones fails 23 across three
packages.
2026-08-18 03:15:10 +00:00
f6ec78e2c8 Stop a slow host turning a login-guard test into a segfault (closes #186)
All checks were successful
check / check (push) Successful in 2m49s
2026-08-18 05:01:13 +02:00
9313b0fb41 Merge pull request 'Correct TODO.md milestone state and record seventeen landed units' (#192) from todo-md-milestone-state into next
All checks were successful
check / check (push) Successful in 6s
2026-08-18 04:07:39 +02:00
clawbot
d2cebb5783 Correct TODO.md milestone state and record seventeen landed units
All checks were successful
check / check (push) Successful in 6s
The Status section claimed next held the completed 1.0.0 milestone with
every issue closed. Four are open (#176, #178, #186, #187), so a merge
of next to main would have shipped that claim to main.

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

Completed Steps was seventeen units behind, back to 2026-08-12.
2026-08-18 02:06:43 +00:00
8 changed files with 480 additions and 100 deletions

View File

@@ -1181,17 +1181,18 @@ The last two rows are capped defensively rather than against a
demonstrated width: chi routes `POST /pages/login` on a static pattern, 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 so `r.URL.Path` there is the 12-byte constant `/pages/login` and each
line lands near 120 bytes. `RecordLoginFailure` is nonetheless an line lands near 120 bytes. `RecordLoginFailure` is nonetheless an
exported method taking any `*http.Request`, so a future caller on a exported method taking any `*http.Request`, and a future caller on a
route with a URL parameter would widen the line with nothing failing. route with a URL parameter would widen the line. Since no request
Removing either cap therefore breaks no test — recorded here because a through the mux can, both caps are pinned by tests that call those two
cap whose absence is undetectable is worth saying so about. entry points directly with the path such a caller would supply.
Removing either cap fails 14 subtests.
`internal/middleware/logbound_test.go` and `internal/middleware/logbound_test.go` and
`internal/handlers/logbound_test.go` drive 8 KB of client-chosen text at `internal/handlers/logbound_test.go` drive 8 KB of client-chosen text at
each of these, through both handlers and through every character the each of these, through both handlers and through every character the
handlers escape, and hold each line to the 2,560-byte ceiling — and the handlers escape, and hold each line to the 2,560-byte ceiling — and, for
whole flood's output to what that ceiling allows, which is the property the six rows a request can widen, the whole flood's output to what that
an operator actually cares about. ceiling allows, which is the property an operator actually cares about.
`internal/logfield/logfield_test.go` measures the per-rune charge `internal/logfield/logfield_test.go` measures the per-rune charge
against what the handlers really emit, over roughly 3,000 code points on against what the handlers really emit, over roughly 3,000 code points on
each, so an undercharged rune fails a test rather than quietly each, so an undercharged rune fails a test rather than quietly

78
TODO.md
View File

@@ -24,8 +24,9 @@ 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 completed 1.0.0 milestone: every issue in it is closed, `next` holds the 1.0.0 milestone less its final four issues (#176, #178,
and it is verified green by cache-defeated container runs #186, #187 — all in review or held on merge order), and is verified
green by cache-defeated container runs
(`docker build --no-cache-filter=lint --no-cache-filter=builder`). The (`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
@@ -39,15 +40,78 @@ of 2026-07-06.
# Next Step # Next Step
Merge the milestone PR to `main` and tag 1.0.0 from it. Land the last four 1.0.0 issues, then merge the milestone PR to `main`
and tag 1.0.0 from it. Merge order is forced by a real conflict on
`README.md` and `internal/middleware/middleware.go`: #186, then #176,
then #178, then #187.
Two decisions are open and belong to the owner, neither blocking the Two items belong to the owner, neither blocking the tag. #150 was
tag: #115 (mask the `http` target's destination URL, implemented decided by the manager rather than left to stall the queue and is
speculatively and awaiting a yes or no) and #125 (whether IPv6 flagged on the issue for reversal if that call was wrong. #112 (whether
rate-limit keys should bucket by `/64`). `Completed Steps` should exist at all, given it once conflicted on every
unit) is unanswered; the provisional ruling in force is that issue
branches do not touch this file.
# 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

View File

@@ -339,7 +339,12 @@ 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)
} }

View File

@@ -19,6 +19,12 @@ package handlers_test
// and "user logged in" — carry the same cap without needing it, since // 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 // 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. // 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 ( import (
"bytes" "bytes"
@@ -111,44 +117,23 @@ func oversizedFill(ch string) string {
attackerMarker + tailMarker attackerMarker + tailMarker
} }
// capturingHandlersWithDB is capturingHandlers plus the database, for
// the call sites that write their line only once the client's value
// matched a stored row.
func capturingHandlersWithDB(
t *testing.T,
newHandler func(io.Writer, *slog.HandlerOptions) slog.Handler,
) (*handlers.Handlers, *database.Database, *bytes.Buffer) {
t.Helper()
var (
h *handlers.Handlers
db *database.Database
)
app := newTestApp(t, &h, &db)
app.RequireStart()
t.Cleanup(app.RequireStop)
buf := new(bytes.Buffer)
h.SetLogForTest(slog.New(newHandler(
buf, &slog.HandlerOptions{Level: slog.LevelDebug},
)))
return h, db, buf
}
// capturingHandlers builds a Handlers whose log is captured into the // capturingHandlers builds a Handlers whose log is captured into the
// returned buffer at DEBUG through the named handler. // 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( func capturingHandlers(
t *testing.T, t *testing.T,
newHandler func(io.Writer, *slog.HandlerOptions) slog.Handler, newHandler func(io.Writer, *slog.HandlerOptions) slog.Handler,
extra ...any,
) (*handlers.Handlers, *bytes.Buffer) { ) (*handlers.Handlers, *bytes.Buffer) {
t.Helper() t.Helper()
var h *handlers.Handlers var h *handlers.Handlers
app := newTestApp(t, &h) app := newTestApp(t, append([]any{&h}, extra...)...)
app.RequireStart() app.RequireStart()
t.Cleanup(app.RequireStop) t.Cleanup(app.RequireStop)
@@ -162,8 +147,8 @@ func capturingHandlers(
} }
// logLines splits the captured buffer into non-empty lines, holding // logLines splits the captured buffer into non-empty lines, holding
// each to bound bytes. // each to the stated per-line ceiling.
func logLines(t *testing.T, buf *bytes.Buffer, bound int) []string { func logLines(t *testing.T, buf *bytes.Buffer) []string {
t.Helper() t.Helper()
var lines []string var lines []string
@@ -176,7 +161,7 @@ func logLines(t *testing.T, buf *bytes.Buffer, bound int) []string {
} }
require.LessOrEqual( require.LessOrEqual(
t, len(line), bound, t, len(line), middleware.MaxAccessLogLineBytes,
"log line exceeded its bound: %s", line, "log line exceeded its bound: %s", line,
) )
@@ -302,9 +287,7 @@ func TestUnknownEntrypoint_LogLineDoesNotTrackPathSize(t *testing.T) {
) )
} }
lines := logLines( lines := logLines(t, buf)
t, buf, middleware.MaxAccessLogLineBytes,
)
require.Len(t, lines, floodRequests) require.Len(t, lines, floodRequests)
assertNoClientText(t, buf) assertNoClientText(t, buf)
@@ -339,9 +322,7 @@ func TestFailedLogin_LogLineDoesNotTrackUsernameSize(t *testing.T) {
) )
} }
lines := logLines( lines := logLines(t, buf)
t, buf, middleware.MaxAccessLogLineBytes,
)
require.Len(t, lines, floodRequests) require.Len(t, lines, floodRequests)
assertNoClientText(t, buf) assertNoClientText(t, buf)
@@ -389,7 +370,9 @@ func TestStoredUsername_LogLinesDoNotTrackUsernameSize(t *testing.T) {
t.Run(handlerName, func(t *testing.T) { t.Run(handlerName, func(t *testing.T) {
t.Parallel() t.Parallel()
h, db, buf := capturingHandlersWithDB(t, newHandler) var db *database.Database
h, buf := capturingHandlers(t, newHandler, &db)
hash, err := database.HashPassword(storedUserPassword) hash, err := database.HashPassword(storedUserPassword)
require.NoError(t, err) require.NoError(t, err)
@@ -422,15 +405,124 @@ func TestStoredUsername_LogLinesDoNotTrackUsernameSize(t *testing.T) {
) )
} }
lines := logLines( lines := logLines(t, buf)
t, buf, middleware.MaxAccessLogLineBytes,
)
require.Len(t, lines, 2*len(fills)) require.Len(t, lines, 2*len(fills))
assertNoClientText(t, buf) 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 // assertBoundedFlood holds the whole flood's log output to what the
// stated per-line ceiling allows. The flood sent // stated per-line ceiling allows. The flood sent
// floodRequests * oversizedFillBytes bytes of client-chosen text; // floodRequests * oversizedFillBytes bytes of client-chosen text;

View File

@@ -13,6 +13,12 @@ package middleware_test
// - The rate limiters' 429 rejection, at WARN, on the // - The rate limiters' 429 rejection, at WARN, on the
// unauthenticated receiver among others. // unauthenticated receiver among others.
// - RequireAuth's own unauthenticated-request line, at DEBUG. // - 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 // Every case here holds the ENCODED line to
// middleware.MaxAccessLogLineBytes, under both handlers // middleware.MaxAccessLogLineBytes, under both handlers
@@ -402,6 +408,64 @@ func TestLogLines_ClientChosenPathDoesNotSizeTheLine(t *testing.T) {
} }
} }
// TestLoginThrottle_LogLineDoesNotTrackPathSize pins the cap on
// RecordLoginFailure's "login failure limit exceeded" WARN line.
//
// That site does not fit logSites above: it is not a middleware
// wrapping a handler but an exported method the login handler calls,
// and the only route that calls it today is chi's static
// "/pages/login", so no request through the mux can widen the line.
// Driving the method directly is therefore the whole point rather
// than a shortcut — it is exactly the call a second caller on a route
// with a URL parameter would make, and without this test removing the
// logfield.Truncate there fails nothing.
func TestLoginThrottle_LogLineDoesNotTrackPathSize(t *testing.T) {
t.Parallel()
for handlerName, newHandler := range logHandlers() {
for fillName, fill := range escapeFills() {
t.Run(handlerName+"/"+fillName, func(t *testing.T) {
t.Parallel()
m, buf := capturingBoundMiddleware(
t, newHandler,
)
req := httptest.NewRequestWithContext(
context.Background(),
http.MethodPost,
"/source/"+
oversizedPathSegment(fill)+"/login",
nil,
)
req.RemoteAddr = "203.0.113.9:5555"
// The budget is spent per client and username,
// so one more failure than the budget allows is
// what takes the throttled branch.
var throttled bool
for range middleware.LoginRateLimitConst + 1 {
throttled = m.RecordLoginFailure(
req, "someone",
)
}
require.True(
t, throttled,
"the throttled branch never ran, so the "+
"bound proves nothing",
)
lines := logLines(
t, buf, middleware.MaxAccessLogLineBytes,
)
require.NotEmpty(t, lines)
assertNoClientText(t, buf)
})
}
}
}
// TestMaxBodySize_FloodOfOversizePathsDoesNotGrowTheLog is the // TestMaxBodySize_FloodOfOversizePathsDoesNotGrowTheLog is the
// flood shape from the issue: an unauthenticated client posting // flood shape from the issue: an unauthenticated client posting
// oversize declarations at invented 8 KB paths, as fast as it likes. // oversize declarations at invented 8 KB paths, as fast as it likes.

View File

@@ -175,10 +175,38 @@ 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 first; the caller must then answer 503 // request was cancelled while waiting; the caller must then answer
// without verifying anything. The returned function releases the // 503 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.
@@ -350,7 +378,8 @@ func (m *Middleware) RecordLoginFailure(
// the 12-byte constant "/pages/login": RecordLoginFailure // the 12-byte constant "/pages/login": RecordLoginFailure
// is exported and takes any *http.Request, so a caller on // is exported and takes any *http.Request, so a caller on
// a route with a URL parameter would otherwise widen this // a route with a URL parameter would otherwise widen this
// line with nothing failing. // 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", logfield.Truncate( "path", logfield.Truncate(

View File

@@ -29,6 +29,15 @@ 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
@@ -224,21 +233,71 @@ 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
} }
@@ -253,9 +312,12 @@ func TestLoginGuard_SemaphoreBoundsConcurrentVerifications(
mu.Unlock() mu.Unlock()
// Hold the slot long enough that the other workers are // Counted before signalling, so the barrier can never open
// certainly contending for it. // while an admitted worker is still on its way to being
time.Sleep(10 * time.Millisecond) // counted.
recorded.Done()
<-overlapped
mu.Lock() mu.Lock()
inside-- inside--
@@ -278,6 +340,14 @@ 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,
) { ) {
@@ -305,13 +375,58 @@ 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.
@@ -388,13 +503,20 @@ 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 on the elapsed time // the probe instead of shedding it fails here rather than
// rather than hanging until the package test timeout. // hanging until the package test timeout.
probeWait = 200 * time.Millisecond //
// This is a patience budget, not a margin to be won. A shed
// Shedding takes no measurable time; queueing takes the whole // returns in microseconds and a probe that queued instead
// probeWait. Anything under half of it is unambiguous. // would not return for neverElapses, so the two are a whole
shedFast = probeWait / 2 // minute apart and any budget between them separates them. It
// is set far above any scheduling stall a loaded host can
// produce, because the previous 200 ms — and the 100 ms
// elapsed-time assertion it fed — bounded the latency of a
// goroutine hand-off, which is a false red waiting to happen
// on the machine this suite runs on. What actually proves the
// probe was not queued is the queue depth asserted below.
probePatience = 5 * time.Second
) )
g := middleware.NewLoginGuardForTest( g := middleware.NewLoginGuardForTest(
@@ -413,22 +535,17 @@ func TestLoginGuard_ShedsPastTheQueueCap(t *testing.T) {
defer release() defer release()
defer fillQueue(t, g, maxWaiters)() defer fillQueue(t, g, maxWaiters)()
got := probeQueueCap(g, probeWait) granted, answered := probeQueueCap(g, probePatience)
require.NotNil( require.True(
t, got, t, answered,
"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, got.ok, t, granted,
"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",
@@ -458,10 +575,14 @@ func fillQueue(
}) })
} }
// Patience budget, not a margin: the waiters park in microseconds
// and nothing releases them, so the only way to exhaust this is a
// guard that never queues. One second is the same order as the
// scheduling stalls this suite has to survive, so it is not one.
require.Eventually( require.Eventually(
t, t,
func() bool { return g.QueuedWaitersForTest() == n }, func() bool { return g.QueuedWaitersForTest() == n },
time.Second, time.Millisecond, 5*time.Second, time.Millisecond,
"the waiters must reach the queue before the cap is tested", "the waiters must reach the queue before the cap is tested",
) )
@@ -471,41 +592,38 @@ func fillQueue(
} }
} }
// probeResult is what the queue-cap probe reports: whether it got a // probeQueueCap acquires from another goroutine. It reports, in
// slot, and how long it took to find out. // order, whether the call was granted a slot and whether it was
type probeResult struct { // answered at all within wait; a call that never returned reports
ok bool // false for both.
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,
) *probeResult { ) (bool, bool) {
probed := make(chan probeResult, 1) probed := make(chan bool, 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 <- probeResult{ok: ok, elapsed: time.Since(start)} probed <- ok
}() }()
select { select {
case result := <-probed: case result := <-probed:
return &result return result, true
case <-time.After(wait): case <-time.After(wait):
return nil return false, false
} }
} }

View File

@@ -97,6 +97,13 @@ const (
// left to the reasoning: see logbound_test.go in this package and // left to the reasoning: see logbound_test.go in this package and
// in internal/handlers. // in internal/handlers.
// //
// The two login-throttle lines are capped defensively: chi pins
// their route to the constant path "/pages/login", so no request
// through the mux can widen either one. Their assertions call
// RecordLoginFailure and the login handler directly with the path
// a caller on a parameterised route would supply, which is the
// only way those caps can be pinned at all.
//
// What it does NOT cover, so that the figure above is not read as // What it does NOT cover, so that the figure above is not read as
// more than it is: // more than it is:
// //