Bound every slog line against client-chosen text (closes #176)

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.

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

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

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/<segment>.
+//
+// RawPath is cleared after parsing so chi routes on the decoded path
+// and the handler sees the raw bytes rather than their percent-escaped
+// spelling. That is the harder case for the budget: the escaped
+// spelling is plain ASCII, which costs one byte per byte, while the
+// decoded bytes are what the log handler has to escape.
+func postReceiver(
+	t *testing.T, router *chi.Mux, segment string,
+) int {
+	t.Helper()
+
+	req := httptest.NewRequestWithContext(
+		context.Background(),
+		http.MethodPost,
+		"/webhook/"+url.PathEscape(segment),
+		strings.NewReader(""),
+	)
+	req.URL.RawPath = ""
+
+	w := httptest.NewRecorder()
+	router.ServeHTTP(w, req)
+
+	return w.Code
+}
+
+// postLogin submits the login form with the given username and a
+// non-empty password.
+func postLogin(
+	t *testing.T, h *handlers.Handlers, username string,
+) int {
+	t.Helper()
+
+	return postLoginWithPassword(t, h, username, "not-the-password")
+}
+
+// postLoginWithPassword submits the login form with both credentials
+// chosen by the caller, so a test can reach the branches past the
+// username lookup.
+func postLoginWithPassword(
+	t *testing.T, h *handlers.Handlers, username, password string,
+) int {
+	t.Helper()
+
+	form := url.Values{
+		"username": {username},
+		"password": {password},
+	}
+
+	req := httptest.NewRequestWithContext(
+		context.Background(),
+		http.MethodPost,
+		"/pages/login",
+		strings.NewReader(form.Encode()),
+	)
+	req.Header.Set(
+		"Content-Type", "application/x-www-form-urlencoded",
+	)
+
+	w := httptest.NewRecorder()
+	h.HandleLoginSubmit().ServeHTTP(w, req)
+
+	return w.Code
+}
+
+// TestUnknownEntrypoint_LogLineDoesNotTrackPathSize drives 8 KB of
+// client-chosen path at the unauthenticated receiver's
+// unknown-entrypoint DEBUG line and holds it to the same ceiling the
+// access log states.
+func TestUnknownEntrypoint_LogLineDoesNotTrackPathSize(t *testing.T) {
+	t.Parallel()
+
+	for handlerName, newHandler := range logHandlers() {
+		for fillName, fill := range escapeFills() {
+			t.Run(handlerName+"/"+fillName, func(t *testing.T) {
+				t.Parallel()
+
+				h, buf := capturingHandlers(t, newHandler)
+				router := receiverRouter(h)
+
+				for i := range floodRequests {
+					assert.Equal(
+						t,
+						http.StatusNotFound,
+						postReceiver(
+							t, router,
+							oversizedFill(fill)+
+								strings.Repeat("y", i),
+						),
+					)
+				}
+
+				lines := logLines(
+					t, buf, 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,
+	)
+}

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)