Bound the access log line against client-chosen text (closes #146)

The access log wrote one INFO line per request carrying the full
attacker-controlled URL, on the unauthenticated public receiver, so a
client inventing paths wrote unbounded arbitrary text into the
operator's logs.

Rejected requests now log the chi route pattern instead of the concrete
URL — extended to 3xx as well as 4xx, because RequireAuth answers 303
and so /user/<anything> was an unauthenticated path-varying vector. The
query is redacted on the branches that keep a concrete path, and every
client-supplied field is capped: url, useragent and referer at 512
bytes, request_id at 128, method at 32. The caps are spent in ENCODED
bytes, so escaping cannot multiply them.

One INFO line per request, at most 2,560 bytes — a figure derived
arithmetically rather than observed, with the fixed portion measured at
336 (JSON) and 286 (text).

Independently reviewed four times, and broken three of those times on
the same class of defect: a stated bound the code did not have. Round 1
left the 2xx query and the headers unbounded; round 2 counted raw bytes
against an encoded ceiling and broke at 2,611; round 3 charged 6 bytes
for every non-printable when strconv.Quote spells astral ones as
\UXXXXXXXX, and broke at 2,676. Two independent exhaustive audits over
all 1,112,064 code points, built by different methods, now both report
zero undercharged runes on either handler. Measured worst case over a
real TCP socket is 1,972 bytes, 77% of the ceiling.

Follow-up filed to assert that charge against every code point in the
suite, so the ceiling defends itself rather than resting on one
hand-picked rune.

internal/middleware/accesslog_test.go

@@ -0,0 +1,658 @@
+package middleware_test
+
+import (
+	"bytes"
+	"context"
+	"encoding/json"
+	"log/slog"
+	"net/http"
+	"net/http/httptest"
+	"strings"
+	"testing"
+
+	"github.com/go-chi/chi"
+	chimw "github.com/go-chi/chi/middleware"
+	"github.com/stretchr/testify/assert"
+	"github.com/stretchr/testify/require"
+	"sneak.berlin/go/webhooker/internal/config"
+	"sneak.berlin/go/webhooker/internal/middleware"
+)
+
+// floodRequests is the number of distinct invented paths each flood
+// test drives through the access log.
+const floodRequests = 64
+
+// attackerMarker is embedded in every invented path. No access log
+// line for a redirected or rejected request may contain it.
+const attackerMarker = "QQATTACKERTEXTQQ"
+
+// maxLineBytes bounds a single access log line whose client-supplied
+// fields are of ordinary size. Well above what the fixed fields need,
+// well below the length of the oversized input the amplification tests
+// send.
+const maxLineBytes = 1024
+
+// maxCappedLineBytes bounds a single access log line when every
+// client-supplied field arrives oversized and is truncated to its
+// budget. This is the number the README quotes as the per-line cost an
+// operator sizes log storage against, and it is a bound on the
+// ENCODED line, which is what the operator's disk holds.
+const maxCappedLineBytes = 2560
+
+// oversizedSegmentBytes is the length of the single attacker-chosen
+// path segment, query string or header used to show line size does not
+// track input size.
+const oversizedSegmentBytes = 8192
+
+// tailMarker is placed at the END of an oversized header value, so its
+// absence from the log proves the value was truncated rather than
+// merely being short.
+const tailMarker = "QQTRUNCATEDTAILQQ"
+
+// These mirror the middleware's own budgets, which are unexported.
+// They are duplicated rather than exported so that widening a budget
+// in the middleware has to be restated here deliberately.
+const (
+	maxFieldBytes         = 512
+	maxRequestIDBytes     = 128
+	maxMethodBytes        = 32
+	truncationSuffix      = "[truncated]"
+	unmatchedRouteLiteral = "(unmatched)"
+)
+
+// capturingMiddleware returns a Middleware whose logger writes JSON
+// lines into the returned buffer, so the access log can be asserted
+// on directly.
+func capturingMiddleware(t *testing.T) (*middleware.Middleware, *bytes.Buffer) {
+	t.Helper()
+
+	buf := new(bytes.Buffer)
+	log := slog.New(slog.NewJSONHandler(
+		buf,
+		&slog.HandlerOptions{Level: slog.LevelInfo},
+	))
+
+	cfg := &config.Config{Environment: config.EnvironmentDev}
+
+	return middleware.NewForTest(log, cfg, nil), buf
+}
+
+// capturingTextMiddleware is capturingMiddleware for the other handler
+// internal/logger can select: slog's text handler, which
+// internal/logger/logger.go installs when stderr is a tty. It escapes
+// differently from the JSON one, so the line bound has to be asserted
+// against both.
+func capturingTextMiddleware(
+	t *testing.T,
+) (*middleware.Middleware, *bytes.Buffer) {
+	t.Helper()
+
+	buf := new(bytes.Buffer)
+	log := slog.New(slog.NewTextHandler(
+		buf,
+		&slog.HandlerOptions{Level: slog.LevelInfo},
+	))
+
+	cfg := &config.Config{Environment: config.EnvironmentDev}
+
+	return middleware.NewForTest(log, cfg, nil), buf
+}
+
+// accessLogRouter mirrors the production route shapes that an
+// unauthenticated client can reach: the public receiver, the
+// authenticated profile route (which redirects to login rather than
+// rejecting outright), the health check (which answers 200 to anyone,
+// behind no rate limiter at all), and a plain static route.
+func accessLogRouter(m *middleware.Middleware) *chi.Mux {
+	router := chi.NewRouter()
+	// Production registers RequestID ahead of Logging, and chi's
+	// RequestID passes an inbound X-Request-Id header straight
+	// through, so the request_id field is client-supplied too.
+	router.Use(chimw.RequestID)
+	router.Use(m.Logging())
+
+	router.Get(
+		"/.well-known/healthcheck",
+		func(w http.ResponseWriter, _ *http.Request) {
+			w.WriteHeader(http.StatusOK)
+		},
+	)
+
+	router.HandleFunc(
+		"/webhook/{uuid}",
+		func(w http.ResponseWriter, r *http.Request) {
+			// Stands in for the real handler: an unknown entrypoint
+			// UUID 404s, a known one succeeds.
+			if chi.URLParam(r, "uuid") != "known" {
+				http.Error(w, "not found", http.StatusNotFound)
+
+				return
+			}
+
+			w.WriteHeader(http.StatusOK)
+		},
+	)
+
+	router.Route("/user/{username}", func(r chi.Router) {
+		r.Get("/", func(w http.ResponseWriter, r *http.Request) {
+			http.Redirect(
+				w, r, "/pages/login", http.StatusSeeOther,
+			)
+		})
+	})
+
+	boom := func(w http.ResponseWriter, _ *http.Request) {
+		http.Error(w, "boom", http.StatusInternalServerError)
+	}
+
+	router.Get("/boom", boom)
+	// The 5xx branch keeps the concrete path, so it needs a route that
+	// answers 500 to a path of the client's choosing: that is where the
+	// url field and the header fields are both at their budget on the
+	// same line.
+	router.Get("/boom/*", boom)
+
+	return router
+}
+
+// accessLogEntries decodes the captured buffer into one map per
+// logged line, holding every line to maxLineBytes.
+func accessLogEntries(
+	t *testing.T,
+	buf *bytes.Buffer,
+) []map[string]any {
+	t.Helper()
+
+	return accessLogEntriesWithin(t, buf, maxLineBytes)
+}
+
+// accessLogEntriesWithin decodes the captured buffer into one map per
+// logged line, holding every line to bound bytes.
+func accessLogEntriesWithin(
+	t *testing.T,
+	buf *bytes.Buffer,
+	bound int,
+) []map[string]any {
+	t.Helper()
+
+	var entries []map[string]any
+
+	for line := range strings.SplitSeq(
+		strings.TrimSpace(buf.String()), "\n",
+	) {
+		if line == "" {
+			continue
+		}
+
+		require.LessOrEqual(
+			t, len(line), bound,
+			"access log line exceeded its bound",
+		)
+
+		var entry map[string]any
+
+		require.NoError(t, json.Unmarshal([]byte(line), &entry))
+
+		entries = append(entries, entry)
+	}
+
+	return entries
+}
+
+// get drives one GET through the router.
+func get(t *testing.T, router *chi.Mux, target string) int {
+	t.Helper()
+
+	return getWithHeaders(t, router, target, nil)
+}
+
+// getWithHeaders drives one GET through the router with the supplied
+// request headers set.
+func getWithHeaders(
+	t *testing.T,
+	router *chi.Mux,
+	target string,
+	headers map[string]string,
+) int {
+	t.Helper()
+
+	req := httptest.NewRequestWithContext(
+		context.Background(), http.MethodGet, target, nil,
+	)
+
+	for name, value := range headers {
+		req.Header.Set(name, value)
+	}
+
+	w := httptest.NewRecorder()
+	router.ServeHTTP(w, req)
+
+	return w.Code
+}
+
+// assertFloodIsBounded drives floodRequests distinct invented paths
+// built by pathFor and asserts every logged line names wantURL, that
+// none carries the invented text, and that the line count is exactly
+// one per request.
+func assertFloodIsBounded(
+	t *testing.T,
+	pathFor func(i int) string,
+	wantStatus int,
+	wantURL string,
+) {
+	t.Helper()
+
+	m, buf := capturingMiddleware(t)
+	router := accessLogRouter(m)
+
+	for i := range floodRequests {
+		assert.Equal(t, wantStatus, get(t, router, pathFor(i)))
+	}
+
+	assert.NotContains(
+		t, buf.String(), attackerMarker,
+		"access log carried attacker-chosen path text",
+	)
+
+	entries := accessLogEntries(t, buf)
+	require.Len(t, entries, floodRequests)
+
+	for _, entry := range entries {
+		assert.Equal(t, wantURL, entry["url"])
+		assert.InDelta(
+			t, float64(wantStatus), entry["status"], 0,
+		)
+	}
+}
+
+func TestAccessLog_InventedReceiverPathsLogRoutePattern(t *testing.T) {
+	t.Parallel()
+
+	assertFloodIsBounded(
+		t,
+		func(i int) string {
+			return "/webhook/" + attackerMarker +
+				strings.Repeat("x", i) + "?q=" + attackerMarker
+		},
+		http.StatusNotFound,
+		"/webhook/{uuid}",
+	)
+}
+
+func TestAccessLog_InventedProfilePathsLogRoutePattern(t *testing.T) {
+	t.Parallel()
+
+	// The login redirect is a 3xx, not a 4xx, but it is just as free
+	// for an unauthenticated client to drive with invented input.
+	// The doubled slash is what chi's RoutePattern yields for a
+	// mounted subrouter's index route.
+	assertFloodIsBounded(
+		t,
+		func(i int) string {
+			return "/user/" + attackerMarker +
+				strings.Repeat("x", i) + "/"
+		},
+		http.StatusSeeOther,
+		"/user/{username}//",
+	)
+}
+
+func TestAccessLog_UnroutablePathsLogFixedLiteral(t *testing.T) {
+	t.Parallel()
+
+	assertFloodIsBounded(
+		t,
+		func(i int) string {
+			return "/" + attackerMarker + strings.Repeat("x", i)
+		},
+		http.StatusNotFound,
+		"(unmatched)",
+	)
+}
+
+// oversizedValue builds an 8 KB header value out of repetitions of ch,
+// with the tail marker at its end.
+//
+// The leading 'x' is load-bearing for tab: net/textproto strips leading
+// and trailing whitespace from a header value, so a value that were
+// nothing but tabs would arrive empty over a real connection and the
+// case would prove nothing.
+func oversizedValue(ch string) string {
+	return "x" + strings.Repeat(ch, oversizedSegmentBytes) + tailMarker
+}
+
+// oversizedHeaders fills every client-supplied header the access log
+// reads with the same value.
+func oversizedHeaders(value string) map[string]string {
+	return map[string]string{
+		"User-Agent":   value,
+		"Referer":      value,
+		"X-Request-Id": value,
+	}
+}
+
+// sizeCase is one way of pointing 8 KB of client-chosen text at the
+// access log.
+type sizeCase struct {
+	target     string
+	headers    map[string]string
+	wantStatus int
+	wantURL    string
+	bound      int
+}
+
+// lineSizeCases enumerates every part of a request that reaches the
+// access log, at 8 KB apiece.
+func lineSizeCases() map[string]sizeCase {
+	cases := map[string]sizeCase{
+		"oversized path segment": {
+			target: "/webhook/" + attackerMarker +
+				strings.Repeat("x", oversizedSegmentBytes),
+			wantStatus: http.StatusNotFound,
+			wantURL:    "/webhook/{uuid}",
+			bound:      maxLineBytes,
+		},
+		// /.well-known/healthcheck answers 200 to anyone and has no
+		// rate limiter in front of it, so an oversized query appended
+		// to it would otherwise buy the same amplification as an
+		// invented 404 path, unauthenticated and unthrottled.
+		"oversized query on an unauthenticated 200": {
+			target: "/.well-known/healthcheck?q=" + attackerMarker +
+				strings.Repeat("x", oversizedSegmentBytes),
+			wantStatus: http.StatusOK,
+			wantURL:    "/.well-known/healthcheck?(redacted)",
+			bound:      maxLineBytes,
+		},
+		// These reach the line on every request, including one whose
+		// url field is correctly redacted.
+		"oversized headers": {
+			target:     "/" + attackerMarker,
+			headers:    oversizedHeaders(oversizedValue("h")),
+			wantStatus: http.StatusNotFound,
+			wantURL:    unmatchedRouteLiteral,
+			bound:      maxCappedLineBytes,
+		},
+	}
+
+	// The url field on a 5xx keeps the concrete path, so it reaches its
+	// own budget on the same line as the three header fields. That is
+	// the widest line the service can be made to write.
+	longPath := "/boom/" + strings.Repeat("x", oversizedSegmentBytes)
+	wantLongURL := longPath[:maxFieldBytes] + truncationSuffix
+
+	// escapeChars are the runes Go's header parser accepts in a header
+	// value and the log handler then escapes, 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, so every one of them
+	// gets a case.
+	//
+	// The astral one is the case the JSON handler alone does not
+	// reach: U+1000C 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. The JSON handler passes it through as
+	// its four UTF-8 bytes, so only the text-handler shape of this
+	// test holds the ten-byte charge honest.
+	escapeChars := map[string]string{
+		"quote":     `"`,
+		"backslash": `\`,
+		"tab":       "\t",
+		"astral":    "\U0001000C",
+	}
+
+	for kind, char := range escapeChars {
+		fill := oversizedValue(char)
+
+		cases["oversized "+kind+" headers"] = sizeCase{
+			target:     "/" + attackerMarker,
+			headers:    oversizedHeaders(fill),
+			wantStatus: http.StatusNotFound,
+			wantURL:    unmatchedRouteLiteral,
+			bound:      maxCappedLineBytes,
+		}
+
+		cases["oversized "+kind+" headers with a 5xx concrete url"] =
+			sizeCase{
+				target:     longPath,
+				headers:    oversizedHeaders(fill),
+				wantStatus: http.StatusInternalServerError,
+				wantURL:    wantLongURL,
+				bound:      maxCappedLineBytes,
+			}
+	}
+
+	return cases
+}
+
+// TestAccessLog_LineSizeDoesNotTrackInputSize drives 8 KB of
+// client-chosen text at the access log through each part of the
+// request that reaches it, and holds the resulting line to a fixed
+// bound in every case.
+//
+// The bound is on the ENCODED line, so the cases built out of
+// characters the handler escapes are the ones that matter: a budget
+// spent in raw bytes passes every plain-ASCII case here and still
+// writes a line half again as long as the stated ceiling.
+func TestAccessLog_LineSizeDoesNotTrackInputSize(t *testing.T) {
+	t.Parallel()
+
+	require.Equal(
+		t, middleware.MaxAccessLogLineBytes, maxCappedLineBytes,
+		"the README quotes this ceiling and the middleware derives "+
+			"it; they have to agree",
+	)
+
+	for name, tc := range lineSizeCases() {
+		t.Run(name, func(t *testing.T) {
+			t.Parallel()
+
+			m, buf := capturingMiddleware(t)
+			router := accessLogRouter(m)
+
+			assert.Equal(
+				t,
+				tc.wantStatus,
+				getWithHeaders(t, router, tc.target, tc.headers),
+			)
+
+			// accessLogEntriesWithin enforces the bound, which is
+			// orders of magnitude smaller than the input just sent.
+			entries := accessLogEntriesWithin(t, buf, tc.bound)
+			require.Len(t, entries, 1)
+			assert.Equal(t, tc.wantURL, entries[0]["url"])
+
+			// The markers sit at the far end of the client-chosen
+			// text, so their absence is what proves the redaction and
+			// the truncation actually ran.
+			assert.NotContains(
+				t, buf.String(), attackerMarker,
+				"access log carried attacker-chosen text",
+			)
+			assert.NotContains(
+				t, buf.String(), tailMarker,
+				"access log carried an untruncated client field",
+			)
+		})
+	}
+}
+
+// TestAccessLog_LineSizeDoesNotTrackInputSizeOnTheTextHandler runs the
+// same cases through slog's text handler, which internal/logger
+// selects on a tty.
+//
+// MaxAccessLogLineBytes is quoted to operators unqualified, so it has
+// to hold for whichever handler is installed — and the two do not
+// escape alike. The astral case is the one that separates them: the
+// JSON handler emits U+1000C as its four UTF-8 bytes, while
+// strconv.Quote spells it \U0001000C at ten. Charging six for it, as
+// this code did, put a real 2,676-byte line on the wire here while
+// every JSON case stayed comfortably inside the bound.
+//
+// Only the size bound is asserted; the url field's contents are the
+// JSON shape's business above.
+func TestAccessLog_LineSizeDoesNotTrackInputSizeOnTheTextHandler(
+	t *testing.T,
+) {
+	t.Parallel()
+
+	for name, tc := range lineSizeCases() {
+		t.Run(name, func(t *testing.T) {
+			t.Parallel()
+
+			m, buf := capturingTextMiddleware(t)
+			router := accessLogRouter(m)
+
+			assert.Equal(
+				t,
+				tc.wantStatus,
+				getWithHeaders(t, router, tc.target, tc.headers),
+			)
+
+			line := strings.TrimSpace(buf.String())
+
+			require.NotEmpty(t, line)
+			assert.NotContains(
+				t, line, "\n", "expected exactly one log line",
+			)
+			require.LessOrEqual(
+				t, len(line), tc.bound,
+				"access log line exceeded its bound",
+			)
+			assert.Contains(t, line, "url=")
+			assert.NotContains(
+				t, line, attackerMarker,
+				"access log carried attacker-chosen text",
+			)
+			assert.NotContains(
+				t, line, tailMarker,
+				"access log carried an untruncated client field",
+			)
+		})
+	}
+}
+
+// TestAccessLog_OversizedMethodIsTruncated covers the last term in the
+// MaxAccessLogLineBytes arithmetic that the size cases above cannot
+// reach: Go accepts any RFC 7230 token as a method, and getWithHeaders
+// only ever sends GET.
+func TestAccessLog_OversizedMethodIsTruncated(t *testing.T) {
+	t.Parallel()
+
+	m, buf := capturingMiddleware(t)
+	router := accessLogRouter(m)
+
+	method := strings.Repeat("M", oversizedSegmentBytes) + attackerMarker
+	req := httptest.NewRequestWithContext(
+		context.Background(), method, "/"+attackerMarker, nil,
+	)
+	rec := httptest.NewRecorder()
+	router.ServeHTTP(rec, req)
+
+	entries := accessLogEntriesWithin(t, buf, maxLineBytes)
+	require.Len(t, entries, 1)
+	assert.Equal(
+		t,
+		strings.Repeat("M", maxMethodBytes)+truncationSuffix,
+		entries[0]["method"],
+	)
+	assert.NotContains(
+		t, buf.String(), attackerMarker,
+		"access log carried attacker-chosen text",
+	)
+}
+
+// TestAccessLog_OversizedHeadersKeepATruncatedPrefix checks the other
+// half of the header cap: the fields are cut, not dropped, so a
+// truncated User-Agent is still worth reading.
+func TestAccessLog_OversizedHeadersKeepATruncatedPrefix(t *testing.T) {
+	t.Parallel()
+
+	m, buf := capturingMiddleware(t)
+	router := accessLogRouter(m)
+
+	assert.Equal(
+		t,
+		http.StatusNotFound,
+		getWithHeaders(
+			t, router, "/nope",
+			oversizedHeaders(oversizedValue("h")),
+		),
+	)
+
+	entries := accessLogEntriesWithin(t, buf, maxCappedLineBytes)
+	require.Len(t, entries, 1)
+
+	for key, budget := range map[string]int{
+		"useragent":  maxFieldBytes,
+		"referer":    maxFieldBytes,
+		"request_id": maxRequestIDBytes,
+	} {
+		value, ok := entries[0][key].(string)
+		require.True(t, ok, key)
+		assert.LessOrEqual(
+			t, len(value), budget+len(truncationSuffix), key,
+		)
+		assert.Contains(t, value, truncationSuffix, key)
+		assert.Contains(t, value, "hhhh", key)
+	}
+}
+
+func TestAccessLog_SuccessKeepsConcretePathAndRedactsQuery(
+	t *testing.T,
+) {
+	t.Parallel()
+
+	m, buf := capturingMiddleware(t)
+	router := accessLogRouter(m)
+
+	assert.Equal(
+		t, http.StatusOK, get(t, router, "/webhook/known?src=ci"),
+	)
+
+	// The path resolved against a stored entrypoint, so it stays. The
+	// query never does: see TestAccessLog_UnauthenticatedSuccess...
+	entries := accessLogEntries(t, buf)
+	require.Len(t, entries, 1)
+	assert.Equal(t, "/webhook/known?(redacted)", entries[0]["url"])
+	assert.NotContains(t, buf.String(), "src=ci")
+}
+
+func TestAccessLog_ServerErrorKeepsConcreteURL(t *testing.T) {
+	t.Parallel()
+
+	m, buf := capturingMiddleware(t)
+	router := accessLogRouter(m)
+
+	assert.Equal(
+		t, http.StatusInternalServerError, get(t, router, "/boom"),
+	)
+
+	entries := accessLogEntries(t, buf)
+	require.Len(t, entries, 1)
+	assert.Equal(t, "/boom", entries[0]["url"])
+}
+
+func TestAccessLog_RetainsEveryOtherField(t *testing.T) {
+	t.Parallel()
+
+	m, buf := capturingMiddleware(t)
+	router := accessLogRouter(m)
+
+	assert.Equal(
+		t,
+		http.StatusNotFound,
+		get(t, router, "/webhook/"+attackerMarker),
+	)
+
+	entries := accessLogEntries(t, buf)
+	require.Len(t, entries, 1)
+
+	for _, key := range []string{
+		"request_start", "method", "url", "useragent", "request_id",
+		"referer", "proto", "remoteIP", "status", "latency_ms",
+	} {
+		assert.Contains(t, entries[0], key)
+	}
+
+	assert.Equal(t, http.MethodGet, entries[0]["method"])
+	assert.Equal(t, "HTTP/1.1", entries[0]["proto"])
+}