Log the route pattern for redirected and rejected requests (closes #146)

The access log wrote one INFO line per request carrying
r.URL.String(). Registered with Use, it runs ahead of the route
limiter, so a client flooding the unauthenticated receiver with
invented paths wrote attacker-chosen text of attacker-chosen length
into the operator's log, one line per request.

3xx and 4xx responses now log the chi route pattern in place of the
concrete URL, and the fixed literal "(unmatched)" when routing matched
nothing at all. One line per request is retained, so real traffic
stays observable and rate accounting still works, but the line's
content is now bounded by the service's own route table. 2xx and 5xx
keep the full URL.

The pattern is only populated after routing, so it is read in the
deferred part of the handler rather than before next.ServeHTTP.

No other access-log field changes.

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
+bounded by neither limit: every request is recorded once at `INFO`,
-its full URL, served or rejected alike.
+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

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

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(),