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.

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