Deploy main eacf1e7 to prod

Replaces #559, which conflicted.

Model: opus-5-5

internal/middleware/accesslog_test.go

@@ -7,6 +7,7 @@ import (
 	"log/slog"
 	"net/http"
 	"net/http/httptest"
+	"strconv"
 	"strings"
 	"testing"
 
@@ -16,6 +17,7 @@ import (
 	"github.com/stretchr/testify/require"
 	"sneak.berlin/go/webhooker/internal/config"
 	"sneak.berlin/go/webhooker/internal/middleware"
+	"sneak.berlin/go/webhooker/internal/middleware/middlewaretest"
 )
 
 // floodRequests is the number of distinct invented paths each flood
@@ -26,6 +28,13 @@ const floodRequests = 64
 // line for a redirected or rejected request may contain it.
 const attackerMarker = "QQATTACKERTEXTQQ"
 
+// knownEntrypointUUID and failingEntrypointUUID are the UUIDs the
+// stand-in receiver in accessLogRouter answers 200 and 500 to.
+const (
+	knownEntrypointUUID   = "6f1e2a9c-4b7d-4e3a-9c2f-1d8b5a7e3c60"
+	failingEntrypointUUID = "0b7c3e5a-2d9f-4a61-8e4b-7c1d6f2a9e35"
+)
+
 // 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
@@ -63,6 +72,12 @@ const (
 // capturingMiddleware returns a Middleware whose logger writes JSON
 // lines into the returned buffer, so the access log can be asserted
 // on directly.
+//
+// It trusts 192.0.2.1, the peer address httptest.NewRequestWithContext
+// gives a request, as a proxy, the way a deployment trusts its reverse
+// proxy: a request built that way and carrying X-Forwarded-For is
+// logged with the client that header names as clientIP, and one
+// without it with the peer.
 func capturingMiddleware(t *testing.T) (*middleware.Middleware, *bytes.Buffer) {
 	t.Helper()
 
@@ -72,16 +87,19 @@ func capturingMiddleware(t *testing.T) (*middleware.Middleware, *bytes.Buffer) {
 		&slog.HandlerOptions{Level: slog.LevelInfo},
 	))
 
-	cfg := &config.Config{Environment: config.EnvironmentDev}
+	cfg := &config.Config{
+		Environment:    config.EnvironmentDev,
+		TrustedProxies: trustedProxies("192.0.2.1/32"),
+	}
 
-	return middleware.NewForTest(log, cfg, nil), buf
+	return middlewaretest.New(t, log, cfg, nil), buf
 }
 
 // capturingTextMiddleware is capturingMiddleware for the other handler
 // internal/logger can select: slog's text handler, which
 // internal/logger/logger.go installs when stderr is a tty. It escapes
 // differently from the JSON one, so the line bound has to be asserted
-// against both.
+// against both. It trusts the same peer.
 func capturingTextMiddleware(
 	t *testing.T,
 ) (*middleware.Middleware, *bytes.Buffer) {
@@ -93,9 +111,12 @@ func capturingTextMiddleware(
 		&slog.HandlerOptions{Level: slog.LevelInfo},
 	))
 
-	cfg := &config.Config{Environment: config.EnvironmentDev}
+	cfg := &config.Config{
+		Environment:    config.EnvironmentDev,
+		TrustedProxies: trustedProxies("192.0.2.1/32"),
+	}
 
-	return middleware.NewForTest(log, cfg, nil), buf
+	return middlewaretest.New(t, log, cfg, nil), buf
 }
 
 // accessLogRouter mirrors the production route shapes that an
@@ -119,17 +140,21 @@ func accessLogRouter(m *middleware.Middleware) *chi.Mux {
 	)
 
 	router.HandleFunc(
-		"/webhook/{uuid}",
+		middleware.ReceiverRoute,
 		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" {
+			// Stands in for the real handler: a known entrypoint
+			// UUID succeeds, a failing one is a server error, and
+			// any other 404s.
+			switch chi.URLParam(r, "uuid") {
+			case knownEntrypointUUID:
+				w.WriteHeader(http.StatusOK)
+			case failingEntrypointUUID:
+				http.Error(
+					w, "boom", http.StatusInternalServerError,
+				)
+			default:
 				http.Error(w, "not found", http.StatusNotFound)
-
-				return
 			}
-
-			w.WriteHeader(http.StatusOK)
 		},
 	)
 
@@ -271,11 +296,11 @@ func TestAccessLog_InventedReceiverPathsLogRoutePattern(t *testing.T) {
 	assertFloodIsBounded(
 		t,
 		func(i int) string {
-			return "/webhook/" + attackerMarker +
+			return "/h/" + attackerMarker +
 				strings.Repeat("x", i) + "?q=" + attackerMarker
 		},
 		http.StatusNotFound,
-		"/webhook/{uuid}",
+		"/h/{uuid}",
 	)
 }
 
@@ -322,11 +347,13 @@ func oversizedValue(ch string) string {
 }
 
 // oversizedHeaders fills every client-supplied header the access log
-// reads with the same value.
+// reads with the same value. The Referer carries it as the host of an
+// absolute URL, because the access log keeps only a Referer's scheme
+// and host.
 func oversizedHeaders(value string) map[string]string {
 	return map[string]string{
 		"User-Agent":   value,
-		"Referer":      value,
+		"Referer":      "http://" + value,
 		"X-Request-Id": value,
 	}
 }
@@ -334,11 +361,12 @@ func oversizedHeaders(value string) map[string]string {
 // sizeCase is one way of pointing 8 KB of client-chosen text at the
 // access log.
 type sizeCase struct {
-	target     string
-	headers    map[string]string
-	wantStatus int
-	wantURL    string
-	bound      int
+	target       string
+	headers      map[string]string
+	wantStatus   int
+	wantURL      string
+	wantClientIP string
+	bound        int
 }
 
 // lineSizeCases enumerates every part of a request that reaches the
@@ -346,10 +374,10 @@ type sizeCase struct {
 func lineSizeCases() map[string]sizeCase {
 	cases := map[string]sizeCase{
 		"oversized path segment": {
-			target: "/webhook/" + attackerMarker +
+			target: "/h/" + attackerMarker +
 				strings.Repeat("x", oversizedSegmentBytes),
 			wantStatus: http.StatusNotFound,
-			wantURL:    "/webhook/{uuid}",
+			wantURL:    "/h/{uuid}",
 			bound:      maxLineBytes,
 		},
 		// /.well-known/healthcheck answers 200 to anyone and has no
@@ -375,8 +403,7 @@ func lineSizeCases() map[string]sizeCase {
 	}
 
 	// The url field on a 5xx keeps the concrete path, so it reaches its
-	// own budget on the same line as the three header fields. That is
-	// the widest access log line the service can be made to write.
+	// own budget on the same line as the three header fields.
 	longPath := "/boom/" + strings.Repeat("x", oversizedSegmentBytes)
 	wantLongURL := longPath[:maxFieldBytes] + truncationSuffix
 
@@ -420,6 +447,29 @@ func lineSizeCases() map[string]sizeCase {
 			}
 	}
 
+	// From a trusted proxy, clientIP is read out of X-Forwarded-For,
+	// which the client writes. What bounds the field is that only one
+	// address from the header is written, and it is written parsed, with
+	// no zone. An IPv6 address with all eight groups at four digits is
+	// the longest such address; here it carries an 8 KB zone, which must
+	// not reach the line. It goes on the 5xx line with all three header
+	// fields at their budget.
+	const longestIPv6 = "ffff:ffff:ffff:ffff:ffff:ffff:ffff:ffff"
+
+	forwarded := oversizedHeaders(oversizedValue("h"))
+	forwarded[headerXFF] = oversizedValue("h") + ", " +
+		longestIPv6 + "%" + oversizedValue("h")
+
+	cases["oversized X-Forwarded-For from a trusted proxy "+
+		"with a 5xx concrete url"] = sizeCase{
+		target:       longPath,
+		headers:      forwarded,
+		wantStatus:   http.StatusInternalServerError,
+		wantURL:      wantLongURL,
+		wantClientIP: longestIPv6,
+		bound:        maxCappedLineBytes,
+	}
+
 	return cases
 }
 
@@ -460,6 +510,14 @@ func TestAccessLog_LineSizeDoesNotTrackInputSize(t *testing.T) {
 			require.Len(t, entries, 1)
 			assert.Equal(t, tc.wantURL, entries[0]["url"])
 
+			// Set only by the X-Forwarded-For case, where it proves
+			// the header was read rather than ignored.
+			if tc.wantClientIP != "" {
+				assert.Equal(
+					t, tc.wantClientIP, entries[0]["clientIP"],
+				)
+			}
+
 			// 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.
@@ -605,17 +663,111 @@ func TestAccessLog_SuccessKeepsConcretePathAndRedactsQuery(
 	router := accessLogRouter(m)
 
 	assert.Equal(
-		t, http.StatusOK, get(t, router, "/webhook/known?src=ci"),
+		t, http.StatusOK,
+		get(t, router, "/.well-known/healthcheck?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.Equal(
+		t, "/.well-known/healthcheck?(redacted)", entries[0]["url"],
+	)
 	assert.NotContains(t, buf.String(), "src=ci")
 }
 
+// TestAccessLog_ReceiverNeverLogsTheUUID covers the two statuses that
+// keep the concrete path on every other route. On the receiver that
+// path carries the entrypoint UUID, so the line names the route
+// pattern instead.
+func TestAccessLog_ReceiverNeverLogsTheUUID(t *testing.T) {
+	t.Parallel()
+
+	for entrypointUUID, wantStatus := range map[string]int{
+		knownEntrypointUUID:   http.StatusOK,
+		failingEntrypointUUID: http.StatusInternalServerError,
+	} {
+		t.Run(strconv.Itoa(wantStatus), func(t *testing.T) {
+			t.Parallel()
+
+			m, buf := capturingMiddleware(t)
+			router := accessLogRouter(m)
+
+			assert.Equal(
+				t, wantStatus,
+				get(t, router, "/h/"+entrypointUUID+"?src=ci"),
+			)
+
+			entries := accessLogEntries(t, buf)
+			require.Len(t, entries, 1)
+			assert.Equal(t, middleware.ReceiverRoute, entries[0]["url"])
+			assert.NotContains(t, buf.String(), entrypointUUID)
+		})
+	}
+}
+
+// TestAccessLog_ReceiverPreflightNeverLogsTheUUID sends a CORS
+// preflight to the receiver in dev, in the production middleware
+// order. CORS answers it with 200 before chi routes it, so the line
+// names no route and carries no UUID.
+func TestAccessLog_ReceiverPreflightNeverLogsTheUUID(t *testing.T) {
+	t.Parallel()
+
+	m, buf := capturingMiddleware(t)
+
+	router := chi.NewRouter()
+	router.Use(m.Logging())
+	router.Use(m.CORS())
+	router.HandleFunc(
+		middleware.ReceiverRoute,
+		func(w http.ResponseWriter, _ *http.Request) {
+			w.WriteHeader(http.StatusOK)
+		},
+	)
+
+	req := httptest.NewRequestWithContext(
+		context.Background(), http.MethodOptions,
+		"/h/"+knownEntrypointUUID, nil,
+	)
+	req.Header.Set("Origin", "https://sender.example")
+	req.Header.Set("Access-Control-Request-Method", http.MethodPost)
+
+	w := httptest.NewRecorder()
+	router.ServeHTTP(w, req)
+	assert.Equal(t, http.StatusOK, w.Code)
+
+	entries := accessLogEntries(t, buf)
+	require.Len(t, entries, 1)
+	assert.Equal(t, unmatchedRouteLiteral, entries[0]["url"])
+	assert.NotContains(t, buf.String(), knownEntrypointUUID)
+}
+
+// TestAccessLog_RefererNeverLogsTheUUID sends receiver requests whose
+// Referer is the entrypoint URL, as a sender's is after it follows a
+// redirect from http:// to https://. The referer field keeps only the
+// scheme and host, and a Referer without them is logged as a marker.
+func TestAccessLog_RefererNeverLogsTheUUID(t *testing.T) {
+	t.Parallel()
+
+	m, buf := capturingMiddleware(t)
+	router := accessLogRouter(m)
+
+	for _, referer := range []string{
+		"http://webhooker.example/h/" + knownEntrypointUUID + "?src=ci",
+		"/h/" + knownEntrypointUUID,
+	} {
+		assert.Equal(t, http.StatusOK, getWithHeaders(
+			t, router, "/h/"+knownEntrypointUUID,
+			map[string]string{"Referer": referer},
+		))
+	}
+
+	entries := accessLogEntries(t, buf)
+	require.Len(t, entries, 2)
+	assert.Equal(t, "http://webhooker.example", entries[0]["referer"])
+	assert.Equal(t, "(redacted)", entries[1]["referer"])
+	assert.NotContains(t, buf.String(), knownEntrypointUUID)
+}
+
 func TestAccessLog_ServerErrorKeepsConcreteURL(t *testing.T) {
 	t.Parallel()
 
@@ -640,7 +792,7 @@ func TestAccessLog_RetainsEveryOtherField(t *testing.T) {
 	assert.Equal(
 		t,
 		http.StatusNotFound,
-		get(t, router, "/webhook/"+attackerMarker),
+		get(t, router, "/h/"+attackerMarker),
 	)
 
 	entries := accessLogEntries(t, buf)
@@ -648,7 +800,8 @@ func TestAccessLog_RetainsEveryOtherField(t *testing.T) {
 
 	for _, key := range []string{
 		"request_start", "method", "url", "useragent", "request_id",
-		"referer", "proto", "remoteIP", "status", "latency_ms",
+		"referer", "proto", "remoteIP", "clientIP", "status",
+		"latency_ms",
 	} {
 		assert.Contains(t, entries[0], key)
 	}