README.md

@@ -994,8 +994,70 @@ 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` with
+bounded by neither limit: every request is recorded once at `INFO`,
-its full URL, served or rejected alike.
+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}`,
+`/user/{username}//`, or the literal `(unmatched)` when the request hit
+no route at all — in place of the concrete URL. Those are the outcomes
+an unauthenticated client can drive for free: 404 and 429 on any
+invented receiver path, a login redirect on any invented profile path.
+Logging the URL there would let a flood write text of its own choosing,
+at a length of its own choosing, into the log. 2xx and 5xx responses
+keep the concrete path — a success resolved against a static route or
+against the operator's own data (on the receiver, against a stored
+entrypoint UUID), and a 5xx is a bug in this service, where the exact
+path is the evidence and no client can provoke one at will.
+
+The query string is never logged; it is replaced by the fixed marker
+`?(redacted)`. It is client-chosen on every route, and
+`/.well-known/healthcheck` and `/s/*` answer 200 to anyone with no rate
+limiter in front of them, so a query on a fixed 200 URL would otherwise
+buy the same amplification as an invented path. Nothing debuggable is
+lost: `page`, on the authenticated pagination links, is the only query
+parameter this service reads.
+
+The remaining client-supplied fields are truncated rather than dropped,
+each to a fixed budget: 512 bytes for `url`, `useragent` and `referer`,
+128 for `request_id` (chi passes an inbound `X-Request-Id` header
+through), and 32 for `method`. A truncated `User-Agent` is still worth
+reading; an absent one is not. A cut value ends in `[truncated]`, which
+is charged on top of the budget rather than inside it.
+
+Each budget is spent in _encoded_ bytes, not in the bytes the client
+sent. Every rune is charged what the wider of the two log handlers
+emits for it: two bytes for a quotation mark, a backslash or a tab; six
+for a non-printable rune below U+10000; ten for one at or above it,
+which the text handler spells `\UXXXXXXXX`. Go's header parser accepts
+all of them in a header value, so a budget counted raw would buy a
+field several times its nominal size — and the line, not the header, is
+what an operator has to store. Plain ASCII encodes one byte for one, so
+a real browser's `User-Agent` still fits whole; a value built out of
+escapes keeps a proportionally shorter prefix, which is the right
+trade.
+
+Net: **one `INFO` line per request, of at most 2,560 bytes.** That
+ceiling is arithmetic, not an observation: 3 × (512 + 11) for `url`,
+`useragent` and `referer`, plus 128 + 11 for `request_id`, plus 32 + 11
+for `method`, plus a 336-byte fixed portion (the field names, the
+punctuation, both timestamps at their longest, an IPv6 `remoteIP` with
+a zone, the status and the latency) — 2,087 bytes, stated at 2,560 so
+the figure has headroom. `internal/middleware/accesslog_test.go`
+asserts it against 8 KB of client-chosen text in the path, in the
+query, and in each of `User-Agent`, `Referer` and `X-Request-Id`,
+including cases built from the characters the handlers escape, and
+against the widest line the service can be made to write: a 5xx that
+keeps its concrete path while all three header fields are also at their
+budget. Every case runs through both handlers `internal/logger` can
+select — the JSON one and the text one it installs on a tty — since the
+two do not escape alike and the ceiling is quoted unqualified. Measured
+over a real connection, the widest line is 1,972 bytes.
+
+Multiply that ceiling by the request rate to size log storage. Note
+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.
 
 Every limiter here — receiver, login, and password change — identifies
 the client the same way, through one shared key function: the

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

internal/middleware/middleware.go

@@ -6,9 +6,13 @@ import (
 	"log/slog"
 	"net"
 	"net/http"
+	"strings"
 	"time"
+	"unicode"
+	"unicode/utf8"
 
 	basicauth "github.com/99designs/basicauth-go"
+	"github.com/go-chi/chi"
 	"github.com/go-chi/chi/middleware"
 	"github.com/go-chi/cors"
 	metrics "github.com/slok/go-http-metrics/metrics/prometheus"
@@ -25,6 +29,75 @@ const (
 	// corsMaxAge is the maximum time (in seconds) that a
 	// preflight response can be cached.
 	corsMaxAge = 300
+
+	// unmatchedRoute is logged in the access log's url field when a
+	// redirected or rejected request matched no route pattern at
+	// all. Every byte of such a path is client-chosen, so none of it
+	// is logged.
+	unmatchedRoute = "(unmatched)"
+
+	// redactedQuery stands in for the query string on the access log
+	// branches that keep the concrete URL. The query is client-chosen
+	// on every route, including the ones that answer an
+	// unauthenticated 200, so logging it verbatim would let a client
+	// 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
+	// order of magnitude shorter than this.
+	maxLogRequestIDBytes = 128
+
+	// maxLogMethodBytes bounds the method. Go accepts any RFC 7230
+	// token there, bounded only by the header size limit, so it is
+	// client-chosen text like the rest. The longest registered method
+	// 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
+	// ENCODED bytes, plus the part of the line no client can influence.
+	//
+	//	url, useragent, referer   3*(512+11) = 1569
+	//	request_id                    128+11 =  139
+	//	method                         32+11 =   43
+	//	fixed portion                        =  336
+	//	                                        ----
+	//	                                        2087
+	//
+	// The fixed portion is the JSON punctuation, the field names, the
+	// level and the message, both timestamps at their longest, an IPv6
+	// remoteIP with a zone, a three-digit status and a full-width int64
+	// latency. Stated at 2560 so the figure carries headroom rather
+	// 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
+	// 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.
+	MaxAccessLogLineBytes = 2560
 )
 
 //nolint:revive // MiddlewareParams is a standard fx naming convention.
@@ -94,6 +167,178 @@ 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.
+//
+// The path on those branches is bounded by the service's routes or by
+// the operator's data — a 2xx on the receiver means the UUID named a
+// stored entrypoint, a 2xx under /s means the file is in the embedded
+// tree. The query is not bounded by anything: /.well-known/healthcheck
+// and /s/* take no authentication and sit behind no rate limiter, and
+// /pages/login behind only the login limiter, so any of them will
+// answer 200 to a URL carrying an arbitrary number of arbitrary bytes
+// after the '?'. Keeping the path and dropping the query is what makes
+// this branch as bounded as the pattern branches below.
+//
+// Nothing debuggable is lost. One route in the service reads a query
+// parameter at all — `page`, on the authenticated pagination links in
+// internal/handlers/source_management.go — and the alternatives that
+// would preserve more (a key count, a key allowlist) all require
+// parsing an attacker-sized query on every request, which is work an
+// unauthenticated client would then be choosing for us.
+func concreteLogURL(r *http.Request) string {
+	path := r.URL.EscapedPath()
+
+	if r.URL.RawQuery == "" && !r.URL.ForceQuery {
+		return path
+	}
+
+	return path + redactedQuery
+}
+
+// accessLogURL returns the value for the access log's url field.
+//
+// 2xx and 5xx responses get the concrete path (see concreteLogURL). A
+// success resolved against a static route or against the operator's
+// own data — on the receiver, a 2xx means the UUID named a stored
+// entrypoint — and a server error is our own bug, where the exact URL
+// is the primary evidence and which no client can provoke at will.
+//
+// 3xx and 4xx responses get the chi route pattern instead. Those are
+// the outcomes an unauthenticated client drives for free: 404 or 429
+// on any invented /webhook/ path, 303 to the login page on any
+// invented /user/ path. Logging the concrete URL there lets a flood
+// write attacker-chosen text, of attacker-chosen length, into the
+// operator's log at one line per request. The pattern comes from the
+// router's own table, so it is bounded by the service's routes while
+// still naming which class of request was rejected.
+//
+// The pattern is only populated once routing has run, so this must be
+// called after the handler returns, not before.
+func accessLogURL(r *http.Request, status int) string {
+	if status < http.StatusMultipleChoices ||
+		status >= http.StatusInternalServerError {
+		return concreteLogURL(r)
+	}
+
+	if rc := chi.RouteContext(r.Context()); rc != nil {
+		if pattern := rc.RoutePattern(); pattern != "" {
+			return pattern
+		}
+	}
+
+	return unmatchedRoute
+}
+
 // Logging returns middleware that logs each HTTP request with
 // timing and metadata.
 func (s *Middleware) Logging() func(http.Handler) http.Handler {
@@ -118,13 +363,27 @@ func (s *Middleware) Logging() func(http.Handler) http.Handler {
 					}
 				}
 
+				// Every field below that a client can influence is
+				// truncated to a fixed budget, so the size of this
+				// line does not track the size of the request.
 				s.log.Info("http request",
 					"request_start", start,
-					"method", r.Method,
+					"method", truncateLogField(
-					"url", r.URL.String(),
+						r.Method, maxLogMethodBytes,
-					"useragent", r.UserAgent(),
+					),
-					"request_id", requestID,
+					"url", truncateLogField(
-					"referer", r.Referer(),
+						accessLogURL(r, lrw.statusCode),
+						maxLogFieldBytes,
+					),
+					"useragent", truncateLogField(
+						r.UserAgent(), maxLogFieldBytes,
+					),
+					"request_id", truncateLogField(
+						requestID, maxLogRequestIDBytes,
+					),
+					"referer", truncateLogField(
+						r.Referer(), maxLogFieldBytes,
+					),
 					"proto", r.Proto,
 					"remoteIP", ipFromHostPort(r.RemoteAddr),
 					"status", lrw.statusCode,