diff --git a/README.md b/README.md index 6c940f9..c720813 100644 --- a/README.md +++ b/README.md @@ -928,8 +928,65 @@ 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 -its full URL, served or rejected alike. +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}`, +`/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. The log handler escapes a quotation mark, a backslash and a tab +to two bytes each and a non-printable rune to six, and Go's header +parser accepts all of them in a header value, so a budget counted raw +would buy a field twice 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 handler escapes, 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. Measured over a real connection, that 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 diff --git a/internal/middleware/accesslog_test.go b/internal/middleware/accesslog_test.go new file mode 100644 index 0000000..5a15d30 --- /dev/null +++ b/internal/middleware/accesslog_test.go @@ -0,0 +1,542 @@ +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 + 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 +} + +// 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 bytes Go's header parser accepts in a header + // value and the log handler then escapes, one byte in and two or + // more out. A budget counted in raw bytes lets any of them buy a + // field twice its nominal size, so every one of them gets a case. + escapeChars := map[string]string{ + "quote": `"`, + "backslash": `\`, + "tab": "\t", + } + + 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_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"]) +} diff --git a/internal/middleware/middleware.go b/internal/middleware/middleware.go index 975ecc0..51b75a3 100644 --- a/internal/middleware/middleware.go +++ b/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,71 @@ 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 the worse of the two + // handlers' escapes, and the text handler's fixed portion is the + // smaller of the two. + MaxAccessLogLineBytes = 2560 ) //nolint:revive // MiddlewareParams is a standard fx naming convention. @@ -94,6 +163,161 @@ 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. Its +// text handler quotes with strconv.Quote, which spells any +// non-printable rune the same six-byte way. Both pass printable runes +// through as their own UTF-8, so unicode.IsPrint separates the two +// cases for either handler. Go's header parser accepts quote, +// backslash, tab and non-printable multi-byte runes in a header value, +// so every one of these is reachable from a request. +func encodedLogFieldBytes(r rune) int { + const ( + // A backslash and the character itself. + shortEscapeBytes = 2 + // \uXXXX, which is also the width of \u00XX. + escapedRuneBytes = 6 + ) + + switch { + case r == '"' || r == '\\' || r == '\n' || r == '\r' || r == '\t': + return shortEscapeBytes + 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 +342,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, - "url", r.URL.String(), - "useragent", r.UserAgent(), - "request_id", requestID, - "referer", r.Referer(), + "method", truncateLogField( + r.Method, maxLogMethodBytes, + ), + "url", truncateLogField( + 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,