diff --git a/README.md b/README.md index 570f087..e003529 100644 --- a/README.md +++ b/README.md @@ -904,8 +904,44 @@ 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]`. + +Net: **one `INFO` line per request, of at most 2,560 bytes** — +`internal/middleware/accesslog_test.go` asserts that ceiling against a +request carrying an 8 KB query, an 8 KB `User-Agent`, an 8 KB `Referer` +and an 8 KB `X-Request-Id`, which together produce a 1,460-byte line. +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..844424e --- /dev/null +++ b/internal/middleware/accesslog_test.go @@ -0,0 +1,470 @@ +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. +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, + ) + }) + }) + + router.Get( + "/boom", + func(w http.ResponseWriter, _ *http.Request) { + http.Error(w, "boom", http.StatusInternalServerError) + }, + ) + + 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)", + ) +} + +// 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. +func TestAccessLog_LineSizeDoesNotTrackInputSize(t *testing.T) { + t.Parallel() + + oversized := strings.Repeat("h", oversizedSegmentBytes) + tailMarker + + tests := map[string]struct { + target string + headers map[string]string + wantStatus int + wantURL string + bound int + }{ + "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: map[string]string{ + "User-Agent": oversized, + "Referer": oversized, + "X-Request-Id": oversized, + }, + wantStatus: http.StatusNotFound, + wantURL: unmatchedRouteLiteral, + bound: maxCappedLineBytes, + }, + } + + for name, tc := range tests { + 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) + + oversized := strings.Repeat("h", oversizedSegmentBytes) + tailMarker + + assert.Equal( + t, + http.StatusNotFound, + getWithHeaders( + t, router, "/nope", + map[string]string{ + "User-Agent": oversized, + "Referer": oversized, + "X-Request-Id": oversized, + }, + ), + ) + + 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..fcf9ccb 100644 --- a/internal/middleware/middleware.go +++ b/internal/middleware/middleware.go @@ -6,9 +6,11 @@ import ( "log/slog" "net" "net/http" + "strings" "time" 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 +27,41 @@ 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. 512 bytes holds a real browser's User-Agent whole, so a + // truncated one is still worth having. + 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. + truncationMarker = "[truncated]" ) //nolint:revive // MiddlewareParams is a standard fx naming convention. @@ -94,6 +131,85 @@ func (lrw *loggingResponseWriter) WriteHeader(code int) { lrw.ResponseWriter.WriteHeader(code) } +// truncateLogField caps s at maxBytes, marking the value when it cuts. +// +// The result is always valid UTF-8: a byte-boundary cut can split a +// multi-byte rune, and a header can carry bytes that were never valid +// UTF-8 to begin with, either of which a JSON encoder expands to six +// bytes apiece. Dropping them keeps the encoded field inside the same +// budget as the raw one. +func truncateLogField(s string, maxBytes int) string { + if len(s) <= maxBytes { + return strings.ToValidUTF8(s, "") + } + + return strings.ToValidUTF8(s[:maxBytes], "") + 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 +234,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,