package middleware_test // This file covers the log lines OUTSIDE the access log that carry a // client-chosen value. accesslog_test.go bounds the one INFO line the // Logging middleware writes; these are the separate slog calls that // were never in that sweep and so never got the budget: // // - MaxBodySize's 413 rejection, at WARN, registered ahead of // RequireAuth and therefore reachable unauthenticated at a URL of // the client's choosing. // - CSRF's 403 rejection, at WARN, also registered ahead of // RequireAuth. // - The rate limiters' 429 rejection, at WARN, on the // unauthenticated receiver among others. // - RequireAuth's own unauthenticated-request line, at DEBUG. // - RecordLoginFailure's throttle rejection, at WARN. Its cap is // defensive rather than load-bearing today: chi pins the one // route that calls it to the constant path "/pages/login". The // method is exported and takes any *http.Request, so the test // below hands it the request a caller on a parameterised route // would, which is what the cap exists for. // // Every case here holds the ENCODED line to // middleware.MaxAccessLogLineBytes, under both handlers // internal/logger can install, against 8 KB of client-chosen text // built out of the characters those handlers escape. A budget spent // in raw bytes passes the plain-ASCII cases and fails the rest. import ( "bytes" "context" "io" "log/slog" "net/http" "net/http/httptest" "net/url" "strings" "testing" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" "sneak.berlin/go/webhooker/internal/config" "sneak.berlin/go/webhooker/internal/middleware" ) // bodyLimitBytes is the MaxBodySize cap these tests install. Any // declared Content-Length above it takes the 413 branch. const bodyLimitBytes = 1024 // declaredBodyBytes is the Content-Length an oversize request // declares. Nothing is actually sent: the 413 branch fires off the // declaration alone, which is what makes the attack free. const declaredBodyBytes = bodyLimitBytes * 2 // receiverLimitPerMinute is the per-entrypoint receiver limit these // tests install. The aggregate limiter sits at ten times this, so a // flood stays under it and the rejections come from the // per-entrypoint limiter, which is the one that logs the path. const receiverLimitPerMinute = 8 // escapeFills are the characters a client can put in a request that // the log handlers then escape, 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. // // U+1000C is the case the JSON handler alone does not reach: it 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 // while the JSON handler passes its four UTF-8 bytes through. Only // the text-handler shape of these tests holds that charge honest. func escapeFills() map[string]string { return map[string]string{ "plain": "x", "quote": `"`, "backslash": `\`, "tab": "\t", "newline": "\n", // A C0 control neither handler has a short escape for, so // each one costs six bytes on the line against the single // byte it cost to send. This is the widest multiplier a // client can drive, and the case a raw-byte budget breaks // on first. // // This fill is load-bearing, not decoration. Budgeting raw // bytes instead of encoded is caught by this fill alone, // and only under the JSON handler, at 3,072 bytes against // the 2,560 ceiling. Drop it and that mutation passes. "control": "\x01", "astral": "\U0001000C", } } // logHandlers are the two handlers internal/logger can install: the // JSON one, and the text one it selects when stderr is a tty. They do // not escape alike, and MaxAccessLogLineBytes is quoted unqualified, // so every case runs through both. func logHandlers() map[string]func( io.Writer, *slog.HandlerOptions, ) slog.Handler { return map[string]func( io.Writer, *slog.HandlerOptions, ) slog.Handler{ "json": func( w io.Writer, o *slog.HandlerOptions, ) slog.Handler { return slog.NewJSONHandler(w, o) }, "text": func( w io.Writer, o *slog.HandlerOptions, ) slog.Handler { return slog.NewTextHandler(w, o) }, } } // oversizedPathSegment builds an 8 KB client-chosen path segment out // of repetitions of ch, percent-encoded so it survives URL parsing // into r.URL.Path the way it would arriving off a socket. // // Both markers sit at the END, past every budget, so their absence // from the log is what proves the value was cut rather than merely // being short. The leading 'x' keeps the segment non-empty for fills // that a parser might otherwise fold away. func oversizedPathSegment(ch string) string { return url.PathEscape( "x" + strings.Repeat(ch, oversizedSegmentBytes) + attackerMarker + tailMarker, ) } // capturingLogger returns a logger at DEBUG writing into the returned // buffer through the named handler. func capturingLogger( newHandler func(io.Writer, *slog.HandlerOptions) slog.Handler, ) (*slog.Logger, *bytes.Buffer) { buf := new(bytes.Buffer) opts := &slog.HandlerOptions{Level: slog.LevelDebug} return slog.New(newHandler(buf, opts)), buf } // capturingBoundMiddleware builds a Middleware with a real session // manager (CSRF needs its key, RequireAuth needs its store) whose log // is captured at DEBUG. func capturingBoundMiddleware( t *testing.T, newHandler func(io.Writer, *slog.HandlerOptions) slog.Handler, ) (*middleware.Middleware, *bytes.Buffer) { t.Helper() log, buf := capturingLogger(newHandler) cfg := &config.Config{ Environment: config.EnvironmentDev, ReceiverRateLimit: receiverLimitPerMinute, } sess := newTestSessionManager(cfg, log, nil) return middleware.NewForTest(log, cfg, sess), buf } // unreachable is a next-handler that fails the test if the middleware // under test let the request through. Every site here rejects. func unreachable(t *testing.T) http.Handler { t.Helper() return http.HandlerFunc(func(http.ResponseWriter, *http.Request) { assert.Fail(t, "rejected request reached the next handler") }) } // logSite is one non-access-log call site that logs a client-chosen // path. drive sends requests at it that all take the rejecting // branch; linesPerRequest is how many log lines one such request // produces there. type logSite struct { // build wraps the site's middleware around a handler that must // not be reached. build func( t *testing.T, m *middleware.Middleware, ) http.Handler // send issues one request for the given client-chosen path and // returns the status. Some sites need a warm-up request before // they reject, which send performs itself. send func(h http.Handler, path string) int // wantStatus is the status the rejecting branch answers with. wantStatus int } // postOversize sends a POST whose declared Content-Length exceeds the // body limit without sending a body, which is the whole cost of the // attack on the MaxBodySize branch. func postOversize(h http.Handler, path string) int { req := httptest.NewRequestWithContext( context.Background(), http.MethodPost, path, nil, ) req.ContentLength = declaredBodyBytes req.Header.Set( "Content-Type", "application/x-www-form-urlencoded", ) w := httptest.NewRecorder() h.ServeHTTP(w, req) return w.Code } // postNoToken sends a POST carrying no CSRF token and no session // cookie, which is what an unauthenticated client sends. func postNoToken(h http.Handler, path string) int { req := httptest.NewRequestWithContext( context.Background(), http.MethodPost, path, strings.NewReader(""), ) req.Header.Set( "Content-Type", "application/x-www-form-urlencoded", ) w := httptest.NewRecorder() h.ServeHTTP(w, req) return w.Code } // getNoSession sends a GET with no session cookie. func getNoSession(h http.Handler, path string) int { req := httptest.NewRequestWithContext( context.Background(), http.MethodGet, path, nil, ) w := httptest.NewRecorder() h.ServeHTTP(w, req) return w.Code } // logSites enumerates the call sites under test. func logSites() map[string]logSite { return map[string]logSite{ // The site this file exists for: WARN, on by default, and // registered ahead of RequireAuth. "maxbodysize 413": { build: func( t *testing.T, m *middleware.Middleware, ) http.Handler { t.Helper() return m.MaxBodySize(bodyLimitBytes)( unreachable(t), ) }, send: postOversize, wantStatus: http.StatusRequestEntityTooLarge, }, // Also ahead of RequireAuth, also WARN. "csrf 403": { build: func( t *testing.T, m *middleware.Middleware, ) http.Handler { t.Helper() return m.CSRF()(unreachable(t)) }, send: postNoToken, wantStatus: http.StatusForbidden, }, // The per-entrypoint receiver limiter, unauthenticated. Its // bucket is keyed on the path, so the first request through a // fresh path is served and only the ones after it are // rejected; sendUntilLimited absorbs that. "receiver rate limit 429": { build: func( t *testing.T, m *middleware.Middleware, ) http.Handler { t.Helper() return m.ReceiverRateLimit()(okHandler()) }, send: sendUntilLimited, wantStatus: http.StatusTooManyRequests, }, // RequireAuth's own line. DEBUG is off in production by // default, but turning it on to diagnose a flood must not // restore an unbounded write. "requireauth redirect": { build: func( t *testing.T, m *middleware.Middleware, ) http.Handler { t.Helper() return m.RequireAuth()(unreachable(t)) }, send: getNoSession, wantStatus: http.StatusSeeOther, }, } } // sendUntilLimited drives the per-entrypoint receiver limiter past // its allowance on one path and returns the status of the rejected // request. Every request before the last is served, and only the last // one logs. func sendUntilLimited(h http.Handler, path string) int { code := http.StatusOK for range receiverLimitPerMinute + 1 { req := httptest.NewRequestWithContext( context.Background(), http.MethodPost, path, nil, ) req.RemoteAddr = "203.0.113.7:5555" w := httptest.NewRecorder() h.ServeHTTP(w, req) code = w.Code } return code } // logLines splits the captured buffer into non-empty lines, holding // each to bound bytes. func logLines(t *testing.T, buf *bytes.Buffer, bound int) []string { t.Helper() var lines []string for line := range strings.SplitSeq( strings.TrimSpace(buf.String()), "\n", ) { if line == "" { continue } require.LessOrEqual( t, len(line), bound, "log line exceeded its bound: %s", line, ) lines = append(lines, line) } return lines } // assertNoClientText fails if any marker from the far end of the // client-chosen input survived into the log. Their absence is what // distinguishes a real cut from a value that merely happened to be // short. func assertNoClientText(t *testing.T, buf *bytes.Buffer) { t.Helper() assert.NotContains( t, buf.String(), attackerMarker, "log carried attacker-chosen text", ) assert.NotContains( t, buf.String(), tailMarker, "log carried the tail of the attacker-chosen text", ) } // TestLogLines_ClientChosenPathDoesNotSizeTheLine points 8 KB of // client-chosen path at each non-access-log call site that logs one, // through both handlers and through every character those handlers // escape, and holds the resulting line to MaxAccessLogLineBytes. // // Removing any one of the logfield.Truncate calls at those sites // fails this test: the line grows to roughly the size of the input, // or to several times it on the escaping fills. func TestLogLines_ClientChosenPathDoesNotSizeTheLine(t *testing.T) { t.Parallel() for siteName, site := range logSites() { for handlerName, newHandler := range logHandlers() { for fillName, fill := range escapeFills() { name := siteName + "/" + handlerName + "/" + fillName t.Run(name, func(t *testing.T) { t.Parallel() m, buf := capturingBoundMiddleware( t, newHandler, ) path := "/source/" + oversizedPathSegment(fill) + "/edit" assert.Equal( t, site.wantStatus, site.send(site.build(t, m), path), ) lines := logLines( t, buf, middleware.MaxAccessLogLineBytes, ) require.NotEmpty( t, lines, "the site under test logged nothing, "+ "so the bound proves nothing", ) assertNoClientText(t, buf) }) } } } } // TestLoginThrottle_LogLineDoesNotTrackPathSize pins the cap on // RecordLoginFailure's "login failure limit exceeded" WARN line. // // That site does not fit logSites above: it is not a middleware // wrapping a handler but an exported method the login handler calls, // and the only route that calls it today is chi's static // "/pages/login", so no request through the mux can widen the line. // Driving the method directly is therefore the whole point rather // than a shortcut — it is exactly the call a second caller on a route // with a URL parameter would make, and without this test removing the // logfield.Truncate there fails nothing. func TestLoginThrottle_LogLineDoesNotTrackPathSize(t *testing.T) { t.Parallel() for handlerName, newHandler := range logHandlers() { for fillName, fill := range escapeFills() { t.Run(handlerName+"/"+fillName, func(t *testing.T) { t.Parallel() m, buf := capturingBoundMiddleware( t, newHandler, ) req := httptest.NewRequestWithContext( context.Background(), http.MethodPost, "/source/"+ oversizedPathSegment(fill)+"/login", nil, ) req.RemoteAddr = "203.0.113.9:5555" // The budget is spent per client and username, // so one more failure than the budget allows is // what takes the throttled branch. var throttled bool for range middleware.LoginRateLimitConst + 1 { throttled = m.RecordLoginFailure( req, "someone", ) } require.True( t, throttled, "the throttled branch never ran, so the "+ "bound proves nothing", ) lines := logLines( t, buf, middleware.MaxAccessLogLineBytes, ) require.NotEmpty(t, lines) assertNoClientText(t, buf) }) } } } // TestMaxBodySize_FloodOfOversizePathsDoesNotGrowTheLog is the // flood shape from the issue: an unauthenticated client posting // oversize declarations at invented 8 KB paths, as fast as it likes. // // It asserts the property directly rather than by proxy — the bytes // the flood writes to the operator's log do not track the bytes the // flood sent. The same flood at a one-character path is the control: // 8 KB of extra input per request buys at most the field budget, not // 8 KB of log. func TestMaxBodySize_FloodOfOversizePathsDoesNotGrowTheLog( t *testing.T, ) { t.Parallel() for handlerName, newHandler := range logHandlers() { for fillName, fill := range escapeFills() { t.Run(handlerName+"/"+fillName, func(t *testing.T) { t.Parallel() flood := func(segment func(i int) string) int { m, buf := capturingBoundMiddleware( t, newHandler, ) h := m.MaxBodySize(bodyLimitBytes)( unreachable(t), ) for i := range floodRequests { assert.Equal( t, http.StatusRequestEntityTooLarge, postOversize( h, "/source/"+segment(i)+"/edit", ), ) } lines := logLines( t, buf, middleware.MaxAccessLogLineBytes, ) require.Len(t, lines, floodRequests) assertNoClientText(t, buf) return buf.Len() } sent := oversizedSegmentBytes * floodRequests oversize := flood(func(i int) string { return oversizedPathSegment(fill) + strings.Repeat("y", i) }) control := flood(func(i int) string { return "a" + strings.Repeat("y", i) }) // The whole point: 8 KB per request of extra // client-chosen input bought a bounded amount of // log, not a proportional amount. assert.Less( t, oversize-control, sent/2, "log volume tracked the size of the flood's "+ "input", ) assert.LessOrEqual( t, oversize, floodRequests* middleware.MaxAccessLogLineBytes, ) }) } } }