diff --git a/README.md b/README.md index 570f087..a1c4a3d 100644 --- a/README.md +++ b/README.md @@ -904,8 +904,24 @@ 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. The pattern comes from +the service's own route table, so an operator sizing log storage can +multiply a fixed per-line cost by the request rate the rate limits +allow. 2xx and 5xx responses keep the full URL, query string included: +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 URL is the evidence and no +client can provoke one at will. 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..26ea64c --- /dev/null +++ b/internal/middleware/accesslog_test.go @@ -0,0 +1,293 @@ +package middleware_test + +import ( + "bytes" + "context" + "encoding/json" + "log/slog" + "net/http" + "net/http/httptest" + "strings" + "testing" + + "github.com/go-chi/chi" + "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. Well above what the +// fixed fields need, well below the length of the oversized path the +// amplification test sends. +const maxLineBytes = 1024 + +// oversizedSegmentBytes is the length of the single attacker-chosen +// path segment used to show line size does not track input size. +const oversizedSegmentBytes = 8192 + +// 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), and a plain static route. +func accessLogRouter(m *middleware.Middleware) *chi.Mux { + router := chi.NewRouter() + router.Use(m.Logging()) + + 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. +func accessLogEntries( + t *testing.T, + buf *bytes.Buffer, +) []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), maxLineBytes, + "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() + + req := httptest.NewRequestWithContext( + context.Background(), http.MethodGet, target, nil, + ) + 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)", + ) +} + +func TestAccessLog_LineSizeDoesNotTrackInputSize(t *testing.T) { + t.Parallel() + + m, buf := capturingMiddleware(t) + router := accessLogRouter(m) + + target := "/webhook/" + attackerMarker + + strings.Repeat("x", oversizedSegmentBytes) + + assert.Equal(t, http.StatusNotFound, get(t, router, target)) + + // accessLogEntries enforces maxLineBytes, which is far smaller + // than the path just sent. + entries := accessLogEntries(t, buf) + require.Len(t, entries, 1) + assert.Equal(t, "/webhook/{uuid}", entries[0]["url"]) + assert.NotContains(t, buf.String(), attackerMarker) +} + +func TestAccessLog_SuccessKeepsConcreteURL(t *testing.T) { + t.Parallel() + + m, buf := capturingMiddleware(t) + router := accessLogRouter(m) + + assert.Equal( + t, http.StatusOK, get(t, router, "/webhook/known?src=ci"), + ) + + entries := accessLogEntries(t, buf) + require.Len(t, entries, 1) + assert.Equal(t, "/webhook/known?src=ci", entries[0]["url"]) +} + +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..c36028f 100644 --- a/internal/middleware/middleware.go +++ b/internal/middleware/middleware.go @@ -9,6 +9,7 @@ import ( "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 +26,12 @@ 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)" ) //nolint:revive // MiddlewareParams is a standard fx naming convention. @@ -94,6 +101,40 @@ func (lrw *loggingResponseWriter) WriteHeader(code int) { lrw.ResponseWriter.WriteHeader(code) } +// accessLogURL returns the value for the access log's url field. +// +// 2xx and 5xx responses get the concrete URL. 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 r.URL.String() + } + + 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 { @@ -121,7 +162,7 @@ func (s *Middleware) Logging() func(http.Handler) http.Handler { s.log.Info("http request", "request_start", start, "method", r.Method, - "url", r.URL.String(), + "url", accessLogURL(r, lrw.statusCode), "useragent", r.UserAgent(), "request_id", requestID, "referer", r.Referer(),