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())