Bound every slog line against client-chosen text (closes #176)

internal/middleware/logbound_test.go

@@ -0,0 +1,544 @@
+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,
+				)
+			})
+		}
+	}
+}