Log the client address next to the peer address (closes #270)

The access log, the rate-limit rejection lines, the CSRF warning and
the receiver's "webhook request received" line now carry clientIP,
the address the rate limiters key on, next to remoteIP, the
connecting peer. Logging works it out once per request from the same
code the rate limiters use and stores it on the request context for
the other lines. The CSRF and receiver lines name the peer as
remoteIP instead of remote_addr. The README documents the field and
that it is only as trustworthy as TRUSTED_PROXIES.

Model: opus-5-5

internal/middleware/accesslog_test.go

@@ -63,6 +63,11 @@ 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 httptest sends every request from, as
+// a proxy, the way a deployment trusts its reverse proxy: a request
+// 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,7 +77,10 @@ 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
 }
@@ -81,7 +89,7 @@ func capturingMiddleware(t *testing.T) (*middleware.Middleware, *bytes.Buffer) {
 // 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,7 +101,10 @@ 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
 }
@@ -334,11 +345,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
@@ -375,8 +387,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 +431,26 @@ func lineSizeCases() map[string]sizeCase {
 			}
 	}
 
+	// From a trusted proxy, clientIP is read out of X-Forwarded-For,
+	// which the client writes. Only the address the header ends in may
+	// reach the line, and an IPv6 address with all eight groups at four
+	// digits is that address at its longest. 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
+
+	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 +491,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.
@@ -648,7 +687,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)
 	}