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