From aace4d77a9bff0afbcce00e8ee14d06348472c76 Mon Sep 17 00:00:00 2001 From: clawbot Date: Mon, 17 Aug 2026 23:43:26 +0000 Subject: [PATCH] Bound every slog line against client-chosen text (closes #176) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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, and removing either cap breaks no test. 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. MaxBodySize stays ahead of RequireAuth. An oversize body should be refused before the request buys a cookie decrypt and a session load, and rejecting first is what keeps an unauthenticated flood from choosing how much session work the process does. The ordering and what it costs are now written at the registration, on maxFormBodySize. MaxAccessLogLineBytes is restated as the ceiling on every slog line carrying text an UNAUTHENTICATED client supplies, not just the access log's: each of these lines carries strictly fewer client-supplied fields than the access log does, so none can be wider. That is asserted per line under both handlers rather than argued. The claim is qualified rather than universal because three kinds of writer are outside it, and the README and the constant now name all three: lines carrying an authenticated operator's own input, which are not truncated at all (the webhook name on "webhook created" reaches 600 KB on one line from a 100 KB form field, measured; the SSRF-rejection url and the target_name lines are the same shape) and are left uncapped deliberately, since truncating the operator's own configuration echoed back costs debuggability against no adversary; the log delivery target, which exists to emit the whole event; and GORM's default logger, which prints the interpolated SQL to stdout on a record-not-found and is unbounded on the receiver and login lookups. That last one is a real defect this audit turned up and is filed separately as #178, not fixed here. Tests drive 8 KB of client-chosen text at all six sites, through both handlers internal/logger can install and through each character they escape — including a bare C0 control, which costs six bytes on the line against the one it cost to send and is the case a raw-byte budget breaks on first. Each holds the encoded line to the ceiling, holds the whole flood's output to what that ceiling allows, and asserts the markers at the far end of the input are absent, so a value that merely happened to be short cannot pass. The two login lines past the username lookup, capped for uniformity rather than need, are pinned too. internal/logfield gains a test that measures the per-rune charge against what the handlers really emit over roughly 3,000 code points on each, so an undercharged rune fails a test instead of quietly falsifying the ceiling. Verified by mutation: reverting the MaxBodySize cap alone fails 28 subtests with a 16,583-byte line against the 2,560 ceiling; reverting the other five fails 70; uncapping 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. The two login-throttle WARN caps are the exception and are recorded as such: reverting them fails nothing, because the constant path gives the mutation nothing to widen. --- README.md | 95 ++++- internal/delivery/target_log.go | 11 + internal/handlers/auth.go | 33 +- internal/handlers/export_test.go | 8 + internal/handlers/logbound_test.go | 451 +++++++++++++++++++++++ internal/handlers/webhook.go | 10 +- internal/logfield/logfield.go | 143 ++++++++ internal/logfield/logfield_test.go | 221 ++++++++++++ internal/middleware/csrf.go | 18 +- internal/middleware/logbound_test.go | 480 +++++++++++++++++++++++++ internal/middleware/loginguard.go | 12 +- internal/middleware/middleware.go | 217 ++++------- internal/middleware/middleware_test.go | 22 +- internal/middleware/ratelimit.go | 14 +- internal/server/routes.go | 38 +- 15 files changed, 1602 insertions(+), 171 deletions(-) create mode 100644 internal/handlers/logbound_test.go create mode 100644 internal/logfield/logfield.go create mode 100644 internal/logfield/logfield_test.go create mode 100644 internal/middleware/logbound_test.go diff --git a/README.md b/README.md index d1edf4b..e750415 100644 --- a/README.md +++ b/README.md @@ -994,15 +994,16 @@ costs; log volume it caps rather than eliminates. A path that names no entrypoint is recorded by the handler at `DEBUG`, and the aggregate limiter logs its own rejections at `DEBUG` and without the path, so neither appears at all under the default level. The per-entrypoint -limiter is the loud one: it still logs every rejection at `WARN` with -the request path, which on this route is attacker-controlled text. A -client hammering a single invented path is served `RECEIVER_RATE_LIMIT` +limiter is the loud one: it logs every rejection at `WARN` with the +request path, which on this route is attacker-controlled text. A client +hammering a single invented path is served `RECEIVER_RATE_LIMIT` requests and has the rest of its aggregate budget rejected there, so -the aggregate limit is what bounds those `WARN` lines — to under ten -times `RECEIVER_RATE_LIMIT` per minute per client IP, 1080 at the -defaults, where before it there was no bound at all. The access log is -bounded by neither limit: every request is recorded once at `INFO`, -served or rejected alike. +the aggregate limit is what bounds the _number_ of those `WARN` lines — +to under ten times `RECEIVER_RATE_LIMIT` per minute per client IP, 1080 +at the defaults, where before it there was no bound at all. Their +_width_ is bounded by the field budgets below, the same ones the access +log spends. The access log is bounded by neither limit: every request +is recorded once at `INFO`, served or rejected alike. What the access log does bound is the _content_ of those lines. A 3xx or 4xx response logs the chi route pattern — `/webhook/{uuid}`, @@ -1152,6 +1153,84 @@ that the rate is not bounded by the limits above on every route: `/.well-known/healthcheck` and `/s/*` sit behind no limiter, so there the multiplier is whatever the deployment will serve. +**The same ceiling covers every other line the service writes through +`slog` that carries text an unauthenticated client supplies.** The +access log is not the only line a client can put its own text into, and +a budget that held for one line and not the others would be worse than +no stated budget at all. Every `slog` call an unauthenticated request +can reach spends the same per-field budget through `internal/logfield`, +and each carries strictly fewer client-supplied fields than the access +log does, so none of them can be wider than it: + +| Log line | Level | Client-chosen value | Reachable unauthenticated | +| ------------------------------------------ | ------- | ------------------- | ----------------------------------------- | +| `request body exceeds limit` (413) | `WARN` | path, method | yes — `MaxBodySize` precedes `RequireAuth` | +| `csrf: token validation failed` (403) | `WARN` | path, method | yes — `CSRF` precedes `RequireAuth` | +| `... rate limit exceeded` (429) | `WARN` | path | yes, on the receiver | +| `auth middleware: unauthenticated request` | `DEBUG` | path, method | yes, by definition | +| `entrypoint not found` | `DEBUG` | entrypoint UUID | yes, on the receiver | +| `user not found` / `invalid password` | `DEBUG` | username | yes, on the login form | +| `login failure limit exceeded` (429) | `WARN` | path | yes, on the login form | +| `password verification capacity exhausted` | `WARN` | path | yes, on the login form | + +`DEBUG` being off by default is not a bound. An operator turning it on +to diagnose a flood must not thereby hand the flood an unbounded write, +so those lines are capped too. + +The last two rows are capped defensively rather than against a +demonstrated width: chi routes `POST /pages/login` on a static pattern, +so `r.URL.Path` there is the 12-byte constant `/pages/login` and each +line lands near 120 bytes. `RecordLoginFailure` is nonetheless an +exported method taking any `*http.Request`, so a future caller on a +route with a URL parameter would widen the line with nothing failing. +Removing either cap therefore breaks no test — recorded here because a +cap whose absence is undetectable is worth saying so about. + +`internal/middleware/logbound_test.go` and +`internal/handlers/logbound_test.go` drive 8 KB of client-chosen text at +each of these, through both handlers and through every character the +handlers escape, and hold each line to the 2,560-byte ceiling — and the +whole flood's output to what that ceiling allows, which is the property +an operator actually cares about. +`internal/logfield/logfield_test.go` measures the per-rune charge +against what the handlers really emit, over roughly 3,000 code points on +each, so an undercharged rune fails a test rather than quietly +falsifying the ceiling. + +What that ceiling does **not** cover, stated here so the figure is not +read as more than it is: + +- **Lines carrying an authenticated operator's own input**, which are + not truncated at all. `webhook created` logs the submitted `name` + verbatim and `target URL blocked by SSRF protection` logs the target + host (both `internal/handlers/source_management.go`), as do the + `target_name` lines in `internal/delivery/engine.go` and + `internal/delivery/target_http.go`. The only bound on any of them is + the 1 MB form body cap, so a 100 KB `name` writes a single line of + roughly 600 KB — measured. This is deliberate: every one of these + requires an authenticated operator on a service with no + self-registration, and truncating the operator's own configuration + echoed back would cost debuggability against no adversary. It does + 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. +- **GORM's default logger**, which prints the fully interpolated SQL to + stdout on every record-not-found — including the client-chosen path + on `/webhook/{uuid}` and the submitted username on the login form. + This one is not deliberate and not yet fixed; it does not go through + `internal/logger` at all, so no level the operator sets and no budget + above applies to it. Tracked at + . Until it is fixed, + an unauthenticated flood can still write text of its own choosing and + its own length to the operator's stdout, and the ceiling above + describes only the `slog` half of the picture. + Every limiter here — receiver, login, and password change — identifies the client the same way, through one shared key function: the connection's own address, unless the peer is listed in diff --git a/internal/delivery/target_log.go b/internal/delivery/target_log.go index 2484bec..ce2d690 100644 --- a/internal/delivery/target_log.go +++ b/internal/delivery/target_log.go @@ -11,6 +11,17 @@ import ( // inbound webhook — the full request body and headers, plus // the method, content type, and the webhook and entrypoint // 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 { eng *Engine } diff --git a/internal/handlers/auth.go b/internal/handlers/auth.go index eaad8b6..39fa5dc 100644 --- a/internal/handlers/auth.go +++ b/internal/handlers/auth.go @@ -5,6 +5,7 @@ import ( "strconv" "sneak.berlin/go/webhooker/internal/database" + "sneak.berlin/go/webhooker/internal/logfield" ) // HandleLoginPage returns a handler for the login page (GET) @@ -70,7 +71,9 @@ func (h *Handlers) HandleLoginSubmit() http.HandlerFunc { h.log.Info( "user logged in", - "username", username, + "username", logfield.Truncate( + username, logfield.MaxBytes, + ), "user_id", user.ID, ) @@ -117,7 +120,9 @@ func (h *Handlers) authenticateUser( if !ok { h.log.Warn( "password verification capacity exhausted", - "path", r.URL.Path, + "path", logfield.Truncate( + r.URL.Path, logfield.MaxBytes, + ), ) h.renderLoginError( w, r, @@ -142,7 +147,17 @@ func (h *Handlers) authenticateUser( h.dummyVerifications.Add(1) database.VerifyDummyPassword(password) - h.log.Debug("user not found", "username", username) + // Login is unauthenticated, and the submitted username is + // 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) return user, err @@ -160,7 +175,17 @@ func (h *Handlers) authenticateUser( } if !valid { - h.log.Debug("invalid password", "username", username) + // Reached only once the username matched a stored row, so + // 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) return user, errInvalidPassword diff --git a/internal/handlers/export_test.go b/internal/handlers/export_test.go index b7d301f..1d420a2 100644 --- a/internal/handlers/export_test.go +++ b/internal/handlers/export_test.go @@ -2,11 +2,19 @@ package handlers import ( "html/template" + "log/slog" "net/http" "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 // to the handlers_test package. const MaxRenderedBodyBytesForTest = maxRenderedBodyBytes diff --git a/internal/handlers/logbound_test.go b/internal/handlers/logbound_test.go new file mode 100644 index 0000000..c8a03d8 --- /dev/null +++ b/internal/handlers/logbound_test.go @@ -0,0 +1,451 @@ +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. + +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 +} + +// capturingHandlersWithDB is capturingHandlers plus the database, for +// the call sites that write their line only once the client's value +// matched a stored row. +func capturingHandlersWithDB( + t *testing.T, + newHandler func(io.Writer, *slog.HandlerOptions) slog.Handler, +) (*handlers.Handlers, *database.Database, *bytes.Buffer) { + t.Helper() + + var ( + h *handlers.Handlers + db *database.Database + ) + + app := newTestApp(t, &h, &db) + app.RequireStart() + + t.Cleanup(app.RequireStop) + + buf := new(bytes.Buffer) + h.SetLogForTest(slog.New(newHandler( + buf, &slog.HandlerOptions{Level: slog.LevelDebug}, + ))) + + return h, db, buf +} + +// capturingHandlers builds a Handlers whose log is captured into the +// returned buffer at DEBUG through the named handler. +func capturingHandlers( + t *testing.T, + newHandler func(io.Writer, *slog.HandlerOptions) slog.Handler, +) (*handlers.Handlers, *bytes.Buffer) { + t.Helper() + + var h *handlers.Handlers + + app := newTestApp(t, &h) + 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 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 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/. +// +// 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, middleware.MaxAccessLogLineBytes, + ) + 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, middleware.MaxAccessLogLineBytes, + ) + 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() + + h, db, buf := capturingHandlersWithDB(t, newHandler) + + 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, middleware.MaxAccessLogLineBytes, + ) + require.Len(t, lines, 2*len(fills)) + 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, + ) +} diff --git a/internal/handlers/webhook.go b/internal/handlers/webhook.go index cb13320..1b1543f 100644 --- a/internal/handlers/webhook.go +++ b/internal/handlers/webhook.go @@ -9,6 +9,7 @@ import ( "gorm.io/gorm" "sneak.berlin/go/webhooker/internal/database" "sneak.berlin/go/webhooker/internal/delivery" + "sneak.berlin/go/webhooker/internal/logfield" ) const ( @@ -125,9 +126,16 @@ func (h *Handlers) lookupEntrypoint( "path = ?", entrypointUUID, ).First(&entrypoint) 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( "entrypoint not found", - "path", entrypointUUID, + "path", logfield.Truncate( + entrypointUUID, logfield.MaxBytes, + ), ) http.NotFound(w, r) diff --git a/internal/logfield/logfield.go b/internal/logfield/logfield.go new file mode 100644 index 0000000..fd5a56c --- /dev/null +++ b/internal/logfield/logfield.go @@ -0,0 +1,143 @@ +// Package logfield bounds the client-supplied values this service +// writes into its logs. +// +// Any log field whose content a client picks is spent against a budget +// here, in ENCODED bytes rather than in the bytes the client sent, so +// that escaping cannot multiply a field past its nominal size. One +// budget and one implementation serves the access log in +// 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 + +import ( + "strings" + "unicode" + "unicode/utf8" +) + +const ( + // MaxBytes is the default budget for a log field whose value the + // client supplies outright: a URL, a path, a header, a form value. + // The budget is spent in ENCODED bytes (see Truncate), so 512 still + // holds a real browser's User-Agent whole — those are plain ASCII, + // which encodes one byte for one — while a value built from + // characters the encoder escapes keeps a shorter prefix. That is + // the intended trade: 500 quotation marks are not a debugging + // asset. + MaxBytes = 512 + + // TruncationMarker is appended to any field that was cut, so a + // short value and a truncated one cannot be confused. It is charged + // on top of the budget, not inside it. + TruncationMarker = "[truncated]" +) + +// EncodedBytes is what r costs on the line once the log handler has +// escaped it, taking the worse of the two handlers internal/logger +// configures. +// +// slog's JSON handler escapes quote, backslash, newline, carriage +// return and tab to two bytes each, and every other C0 control plus +// LINE SEPARATOR and PARAGRAPH SEPARATOR to a six-byte \u escape; it +// passes every other rune through as its own UTF-8. Its text handler +// quotes with strconv.Quote, which spells a non-printable rune below +// U+10000 as \uXXXX but one at or above U+10000 as \UXXXXXXXX — ten +// bytes, not six. The text handler is therefore the worse of the two +// for every non-printable rune, and by four bytes apiece for the +// 955,086 unassigned, private-use and format code points on planes 1 +// to 16. +// +// Charging ten there is what makes the stated line ceilings hold for +// the tty handler as well: U+1000C encodes as F0 90 80 8C, every byte +// >= 0x80, which httpguts.ValidHeaderFieldValue accepts and +// 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 +// unicode.IsPrint separates the escaped cases from the plain ones for +// either handler. +func EncodedBytes(r rune) int { + const ( + // A backslash and the character itself. + shortEscapeBytes = 2 + // \uXXXX, which is also the width of \u00XX. + escapedRuneBytes = 6 + // \UXXXXXXXX, strconv.Quote's spelling of a non-printable + // rune outside the basic multilingual plane. + escapedAstralRuneBytes = 10 + // The first code point strconv.Quote spells with \U. + firstAstralRune = 0x10000 + ) + + switch { + case r == '"' || r == '\\' || r == '\n' || r == '\r' || r == '\t': + return shortEscapeBytes + case !unicode.IsPrint(r) && r >= firstAstralRune: + return escapedAstralRuneBytes + case !unicode.IsPrint(r): + return escapedRuneBytes + default: + return utf8.RuneLen(r) + } +} + +// Truncate caps s at maxBytes of ENCODED output, marking the value +// when it cuts. +// +// Budgeting raw bytes would not bound the line. Escaping only ever +// grows a value, so a raw budget spent on characters the encoder +// 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. +// Charging each rune what it will actually cost is what makes a stated +// ceiling true rather than merely larger. The visible consequence is +// that an escape-heavy value keeps a shorter prefix than a plain one, +// which is the correct trade. +// +// 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 +// valid UTF-8 to begin with; both are dropped rather than kept, since +// an encoder would otherwise spend six bytes replacing each one. +func Truncate(s string, maxBytes int) string { + // No rune encodes to fewer bytes than it occupies, so nothing past + // maxBytes raw can fit the budget. Slicing first bounds the scan + // below to the budget rather than to the size of the header the + // client sent. + window, cut := s, false + if len(window) > maxBytes { + window, cut = window[:maxBytes], true + } + + var ( + kept strings.Builder + spent int + ) + + for i := 0; i < len(window); { + r, size := utf8.DecodeRuneInString(window[i:]) + if r == utf8.RuneError && size == 1 { + i += size + + continue + } + + cost := EncodedBytes(r) + if spent+cost > maxBytes { + cut = true + + break + } + + spent += cost + + kept.WriteString(window[i : i+size]) + + i += size + } + + if !cut { + return kept.String() + } + + return kept.String() + TruncationMarker +} diff --git a/internal/logfield/logfield_test.go b/internal/logfield/logfield_test.go new file mode 100644 index 0000000..a75e475 --- /dev/null +++ b/internal/logfield/logfield_test.go @@ -0,0 +1,221 @@ +package logfield_test + +import ( + "bytes" + "io" + "log/slog" + "strings" + "testing" + "unicode/utf8" + + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + "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)) +} diff --git a/internal/middleware/csrf.go b/internal/middleware/csrf.go index b9e62f6..70b86ad 100644 --- a/internal/middleware/csrf.go +++ b/internal/middleware/csrf.go @@ -4,6 +4,7 @@ import ( "net/http" "github.com/gorilla/csrf" + "sneak.berlin/go/webhooker/internal/logfield" ) // CSRFToken retrieves the CSRF token from the request context. @@ -42,9 +43,22 @@ func isClientTLS(r *http.Request) bool { // csrf.Secure option is set at creation time, not per-request. func (m *Middleware) CSRF() func(http.Handler) http.Handler { 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//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", - "method", r.Method, - "path", r.URL.Path, + "method", logfield.Truncate( + r.Method, maxLogMethodBytes, + ), + "path", logfield.Truncate( + r.URL.Path, logfield.MaxBytes, + ), "remote_addr", r.RemoteAddr, "reason", csrf.FailureReason(r), ) diff --git a/internal/middleware/logbound_test.go b/internal/middleware/logbound_test.go new file mode 100644 index 0000000..d0a2c88 --- /dev/null +++ b/internal/middleware/logbound_test.go @@ -0,0 +1,480 @@ +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. +// +// 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) + }) + } + } + } +} + +// 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, + ) + }) + } + } +} diff --git a/internal/middleware/loginguard.go b/internal/middleware/loginguard.go index 984a8d2..19439e9 100644 --- a/internal/middleware/loginguard.go +++ b/internal/middleware/loginguard.go @@ -7,6 +7,8 @@ import ( "net/http" "sync" "time" + + "sneak.berlin/go/webhooker/internal/logfield" ) const ( @@ -344,8 +346,16 @@ func (m *Middleware) RecordLoginFailure( ) bool { throttled := m.guard().fail(m.clientKey(r), username) if throttled { + // Truncated even though chi pins this route's path to + // the 12-byte constant "/pages/login": RecordLoginFailure + // is exported and takes any *http.Request, so a caller on + // a route with a URL parameter would otherwise widen this + // line with nothing failing. m.log.Warn( - "login failure limit exceeded", "path", r.URL.Path, + "login failure limit exceeded", + "path", logfield.Truncate( + r.URL.Path, logfield.MaxBytes, + ), ) } diff --git a/internal/middleware/middleware.go b/internal/middleware/middleware.go index 56af5bc..ecd0b6d 100644 --- a/internal/middleware/middleware.go +++ b/internal/middleware/middleware.go @@ -6,11 +6,8 @@ import ( "log/slog" "net" "net/http" - "strings" "sync" "time" - "unicode" - "unicode/utf8" basicauth "github.com/99designs/basicauth-go" "github.com/go-chi/chi" @@ -22,6 +19,7 @@ import ( "go.uber.org/fx" "sneak.berlin/go/webhooker/internal/config" "sneak.berlin/go/webhooker/internal/globals" + "sneak.berlin/go/webhooker/internal/logfield" "sneak.berlin/go/webhooker/internal/logger" "sneak.berlin/go/webhooker/internal/session" ) @@ -44,16 +42,6 @@ const ( // pick the size of the line it writes. redactedQuery = "?(redacted)" - // maxLogFieldBytes bounds each access log field whose value the - // client supplies outright: the URL, the User-Agent and the - // Referer. The budget is spent in ENCODED bytes (see - // truncateLogField), so 512 still holds a real browser's User-Agent - // whole — those are plain ASCII, which encodes one byte for one — - // while a value built from characters the encoder escapes keeps a - // shorter prefix. That is the intended trade: 500 quotation marks - // are not a debugging asset. - maxLogFieldBytes = 512 - // maxLogRequestIDBytes bounds the request id, which is also // client-supplied: chi's RequestID middleware passes an inbound // X-Request-Id header through verbatim. Its generated form is an @@ -66,15 +54,10 @@ const ( // is half this. maxLogMethodBytes = 32 - // truncationMarker is appended to any field the access log cut, so - // a short value and a truncated one cannot be confused. It is - // charged on top of the budget, not inside it. - truncationMarker = "[truncated]" - // MaxAccessLogLineBytes is the ceiling on one JSON access log line, // 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 - // of the budgets above, each of which truncateLogField enforces in + // of the budgets above, each of which logfield.Truncate enforces in // ENCODED bytes, plus the part of the line no client can influence. // // url, useragent, referer 3*(512+11) = 1569 @@ -91,13 +74,48 @@ const ( // than sitting on the arithmetic. // // The tty text handler in internal/logger is covered by the same - // figure. encodedLogFieldBytes charges every rune at least what + // figure. logfield.EncodedBytes charges every rune at least what // the wider of the two handlers emits for it — including the ten // bytes strconv.Quote spends on a non-printable rune at or above // U+10000, which is four more than the JSON handler ever spends — // so each budget bounds the encoded field under either handler. // The text handler's fixed portion is 286, the smaller of the two, // which puts its worst case at 2037. + // + // It is also the ceiling on every OTHER line this service writes + // THROUGH SLOG that carries text an UNAUTHENTICATED client + // supplies. Those lines — the MaxBodySize rejection, the CSRF + // rejection, the rate-limit rejection, the unauthenticated-request + // and unknown-entrypoint DEBUG lines, the failed-login DEBUG + // lines, and the two login-throttle WARN lines ("login failure + // limit exceeded" in loginguard.go and "password verification + // capacity exhausted" in internal/handlers/auth.go) — spend the + // same per-field budgets, and each carries strictly fewer + // client-supplied fields than the access log does, + // 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. + // + // 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. + // - GORM's default logger, which prints the interpolated SQL to + // stdout on a record-not-found and so is unbounded on the + // receiver and login lookups. NOT deliberate; filed as + // https://git.eeqj.de/sneak/webhooker/issues/178. MaxAccessLogLineBytes = 2560 ) @@ -174,114 +192,6 @@ func (lrw *loggingResponseWriter) WriteHeader(code int) { lrw.ResponseWriter.WriteHeader(code) } -// encodedLogFieldBytes is what r costs on the line once the log -// handler has escaped it, taking the worse of the two handlers -// internal/logger configures. -// -// slog's JSON handler escapes quote, backslash, newline, carriage -// return and tab to two bytes each, and every other C0 control plus -// LINE SEPARATOR and PARAGRAPH SEPARATOR to a six-byte \u escape; it -// passes every other rune through as its own UTF-8. Its text handler -// quotes with strconv.Quote, which spells a non-printable rune below -// U+10000 as \uXXXX but one at or above U+10000 as \UXXXXXXXX — ten -// bytes, not six. The text handler is therefore the worse of the two -// for every non-printable rune, and by four bytes apiece for the -// 955,086 unassigned, private-use and format code points on planes 1 -// to 16. -// -// Charging ten there is what makes MaxAccessLogLineBytes hold for the -// tty handler as well: U+1000C encodes as F0 90 80 8C, every byte -// >= 0x80, which httpguts.ValidHeaderFieldValue accepts and -// 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 -// unicode.IsPrint separates the escaped cases from the plain ones for -// either handler. -func encodedLogFieldBytes(r rune) int { - const ( - // A backslash and the character itself. - shortEscapeBytes = 2 - // \uXXXX, which is also the width of \u00XX. - escapedRuneBytes = 6 - // \UXXXXXXXX, strconv.Quote's spelling of a non-printable - // rune outside the basic multilingual plane. - escapedAstralRuneBytes = 10 - // The first code point strconv.Quote spells with \U. - firstAstralRune = 0x10000 - ) - - switch { - case r == '"' || r == '\\' || r == '\n' || r == '\r' || r == '\t': - return shortEscapeBytes - case !unicode.IsPrint(r) && r >= firstAstralRune: - return escapedAstralRuneBytes - case !unicode.IsPrint(r): - return escapedRuneBytes - default: - return utf8.RuneLen(r) - } -} - -// truncateLogField caps s at maxBytes of ENCODED output, marking the -// value when it cuts. -// -// Budgeting raw bytes would not bound the line. Escaping only ever -// grows a value, so a raw budget spent on characters the encoder -// 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. -// Charging each rune what it will actually cost is what makes -// MaxAccessLogLineBytes true rather than merely larger. The visible -// consequence is that an escape-heavy value keeps a shorter prefix -// than a plain one, which is the correct trade. -// -// 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 -// valid UTF-8 to begin with; both are dropped rather than kept, since -// an encoder would otherwise spend six bytes replacing each one. -func truncateLogField(s string, maxBytes int) string { - // No rune encodes to fewer bytes than it occupies, so nothing past - // maxBytes raw can fit the budget. Slicing first bounds the scan - // below to the budget rather than to the size of the header the - // client sent. - window, cut := s, false - if len(window) > maxBytes { - window, cut = window[:maxBytes], true - } - - var ( - kept strings.Builder - spent int - ) - - for i := 0; i < len(window); { - r, size := utf8.DecodeRuneInString(window[i:]) - if r == utf8.RuneError && size == 1 { - i += size - - continue - } - - cost := encodedLogFieldBytes(r) - if spent+cost > maxBytes { - cut = true - - break - } - - spent += cost - - kept.WriteString(window[i : i+size]) - - i += size - } - - if !cut { - return kept.String() - } - - return kept.String() + truncationMarker -} - // concreteLogURL renders the request's own URL for the access log // branches that keep it, with the query string replaced by a fixed // marker. @@ -375,21 +285,21 @@ func (s *Middleware) Logging() func(http.Handler) http.Handler { // line does not track the size of the request. s.log.Info("http request", "request_start", start, - "method", truncateLogField( + "method", logfield.Truncate( r.Method, maxLogMethodBytes, ), - "url", truncateLogField( + "url", logfield.Truncate( accessLogURL(r, lrw.statusCode), - maxLogFieldBytes, + logfield.MaxBytes, ), - "useragent", truncateLogField( - r.UserAgent(), maxLogFieldBytes, + "useragent", logfield.Truncate( + r.UserAgent(), logfield.MaxBytes, ), - "request_id", truncateLogField( + "request_id", logfield.Truncate( requestID, maxLogRequestIDBytes, ), - "referer", truncateLogField( - r.Referer(), maxLogFieldBytes, + "referer", logfield.Truncate( + r.Referer(), logfield.MaxBytes, ), "proto", r.Proto, "remoteIP", ipFromHostPort(r.RemoteAddr), @@ -457,10 +367,21 @@ func (s *Middleware) RequireAuth() func(http.Handler) http.Handler { // session lands here and is sent back to the login // page. 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( "auth middleware: unauthenticated request", - "path", r.URL.Path, - "method", r.Method, + "path", logfield.Truncate( + r.URL.Path, logfield.MaxBytes, + ), + "method", logfield.Truncate( + r.Method, maxLogMethodBytes, + ), ) http.Redirect( w, r, "/pages/login", http.StatusSeeOther, @@ -620,10 +541,26 @@ func (s *Middleware) MaxBodySize( } 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( "request body exceeds limit", - "method", r.Method, - "path", r.URL.Path, + "method", logfield.Truncate( + r.Method, maxLogMethodBytes, + ), + "path", logfield.Truncate( + r.URL.Path, logfield.MaxBytes, + ), "content_length", r.ContentLength, "limit", maxBytes, ) diff --git a/internal/middleware/middleware_test.go b/internal/middleware/middleware_test.go index fa18f11..097162d 100644 --- a/internal/middleware/middleware_test.go +++ b/internal/middleware/middleware_test.go @@ -57,7 +57,21 @@ func testMiddlewareWithSessionClock( SessionIdleTimeout: idleTimeout, } - // Create a real session manager with a known key + sessManager := newTestSessionManager(cfg, log, clock) + + 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) for i := range key { @@ -79,11 +93,7 @@ func testMiddlewareWithSessionClock( now = clock.Now } - sessManager := session.NewForTest(store, cfg, log, key, now) - - m := middleware.NewForTest(log, cfg, sessManager) - - return m, sessManager, clock + return session.NewForTest(store, cfg, log, key, now) } // fakeClock is a manually advanced clock, so session expiry can be diff --git a/internal/middleware/ratelimit.go b/internal/middleware/ratelimit.go index 7efca06..a253c69 100644 --- a/internal/middleware/ratelimit.go +++ b/internal/middleware/ratelimit.go @@ -9,6 +9,7 @@ import ( "time" "github.com/go-chi/httprate" + "sneak.berlin/go/webhooker/internal/logfield" ) const ( @@ -225,11 +226,22 @@ func (m *Middleware) clientKey(r *http.Request) string { // rejection with logMessage and answers with responseMessage. // httprate adds the Retry-After header (RFC 6585). The aggregate // 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( logMessage, responseMessage string, ) http.HandlerFunc { return func(w http.ResponseWriter, r *http.Request) { - m.log.Warn(logMessage, "path", r.URL.Path) + m.log.Warn( + logMessage, + "path", logfield.Truncate( + r.URL.Path, logfield.MaxBytes, + ), + ) http.Error(w, responseMessage, http.StatusTooManyRequests) } } diff --git a/internal/server/routes.go b/internal/server/routes.go index cf24b9a..db017d5 100644 --- a/internal/server/routes.go +++ b/internal/server/routes.go @@ -14,6 +14,28 @@ import ( // maxFormBodySize is the maximum allowed request body size (in // bytes) for form POST endpoints. 1 MB is generous for any form // 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 // requestTimeout is the maximum time allowed for a single HTTP @@ -90,8 +112,8 @@ func (s *Server) setupRoutes() { func (s *Server) setupPageRoutes() { s.router.Route("/pages", func(r chi.Router) { - // MaxBodySize must precede CSRF: gorilla/csrf parses the - // form, so the cap has to be installed before it runs. + // MaxBodySize precedes CSRF and RequireAuth deliberately; + // see maxFormBodySize for why, and for what it costs. r.Use(s.mw.MaxBodySize(maxFormBodySize)) r.Use(s.mw.CSRF()) r.Use(s.mw.NoCache()) @@ -111,8 +133,8 @@ func (s *Server) setupPageRoutes() { func (s *Server) setupUserRoutes() { s.router.Route("/user/{username}", func(r chi.Router) { - // MaxBodySize must precede CSRF: gorilla/csrf parses the - // form, so the cap has to be installed before it runs. + // MaxBodySize precedes CSRF and RequireAuth deliberately; + // see maxFormBodySize for why, and for what it costs. r.Use(s.mw.MaxBodySize(maxFormBodySize)) r.Use(s.mw.CSRF()) r.Use(s.mw.NoCache()) @@ -126,8 +148,8 @@ func (s *Server) setupUserRoutes() { func (s *Server) setupSourceRoutes() { s.router.Route("/sources", func(r chi.Router) { - // MaxBodySize must precede CSRF: gorilla/csrf parses the - // form, so the cap has to be installed before it runs. + // MaxBodySize precedes CSRF and RequireAuth deliberately; + // see maxFormBodySize for why, and for what it costs. r.Use(s.mw.MaxBodySize(maxFormBodySize)) r.Use(s.mw.CSRF()) r.Use(s.mw.NoCache()) @@ -138,8 +160,8 @@ func (s *Server) setupSourceRoutes() { }) s.router.Route("/source/{sourceID}", func(r chi.Router) { - // MaxBodySize must precede CSRF: gorilla/csrf parses the - // form, so the cap has to be installed before it runs. + // MaxBodySize precedes CSRF and RequireAuth deliberately; + // see maxFormBodySize for why, and for what it costs. r.Use(s.mw.MaxBodySize(maxFormBodySize)) r.Use(s.mw.CSRF()) r.Use(s.mw.NoCache())