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
#146 established did not reach it: that budget lives in the access-log
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.

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 a client-supplied value, 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. Two writers are called out as NOT
covered, so the figure is not read as more than it is: the log delivery
target, which exists to emit the whole event and is deliberate, 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 second 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. 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 12
subtests with a 16,583-byte line against the 2,560 ceiling; reverting
the other five fails 70; budgeting raw bytes instead of encoded ones
fails 23 across three packages.

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))
+}