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

README.md

@@ -457,6 +457,19 @@ Your proxy must therefore **append** the peer address to
 `option forwardfor`, Caddy and AWS ALB by default), and must append a
 bare address with no port.
 
+Every log line that names a client carries two addresses: `remoteIP`,
+the connecting peer, which behind a proxy is the proxy; and `clientIP`,
+the client the rate limiters identify by the rules above, which is the
+field to read when tracing who sent what. Those lines are the
+`http request` access log line, the rate-limit rejection lines
+(`login failure limit exceeded` among them), the
+`csrf: token validation failed` warning and the receiver's
+`webhook request received` line. `clientIP` is only as trustworthy as
+`TRUSTED_PROXIES`: for a request from a peer inside the list, it is
+read out of the `X-Forwarded-For` that peer sent, so a peer that does
+not belong in the list can make it name any address it likes. For a
+request from any other peer, both fields name the peer.
+
 #### Sessions
 
 Sessions are bounded by two independent clocks, and end at whichever
@@ -841,9 +854,9 @@ reports.
    was given, so on any port other than 443 `$host` makes every form
    POST — including login — fail with `403 origin invalid`, with
    nothing in the error naming the cause.
-5. **Keep the proxy's access log.** webhooker's own access log records
+5. **Keep the proxy's access log.** webhooker's own access log names
-   the peer address, which behind a proxy is always the proxy. The
+   the client in its `clientIP` field only while `TRUSTED_PROXIES`
-   proxy's log is the only record of which client sent what. nginx's
+   covers the proxy; the proxy's log names it regardless. nginx's
    default `combined` format already logs `$remote_addr`; do not
    replace it with one that drops the client address, and retain those
    logs as long as you would want to answer a question about traffic.
@@ -872,9 +885,8 @@ server {
     # webhooker's message.
     client_max_body_size 1m;
 
-    # $remote_addr is the client. webhooker's own log records this
+    # $remote_addr is the client. webhooker's own log names it, as
-    # proxy and nothing else, so this file is the only place the
+    # clientIP, only while TRUSTED_PROXIES covers this proxy.
-    # client's address is written down.
     access_log /var/log/nginx/webhooker.access.log combined;
 
     location / {
@@ -2473,20 +2485,21 @@ trade.
 Net: **one `INFO` line per request, of at most 2,560 bytes.** That
 ceiling is arithmetic, not an observation: 3 × (512 + 11) for `url`,
 `useragent` and `referer`, plus 128 + 11 for `request_id`, plus 32 + 11
-for `method`, plus a 336-byte fixed portion (the field names, the
+for `method`, plus a 405-byte fixed portion (the field names, the
-punctuation, both timestamps at their longest, an IPv6 `remoteIP` with
+punctuation, both timestamps at their longest, `remoteIP` and
-a zone, the status and the latency) — 2,087 bytes, stated at 2,560 so
+`clientIP` each charged as an IPv6 address with a zone, the status and
-the figure has headroom. `internal/middleware/accesslog_test.go`
+the latency) — 2,156 bytes, stated at 2,560 so the figure has headroom.
-asserts it against 8 KB of client-chosen text in the path, in the
+`internal/middleware/accesslog_test.go` asserts it against 8 KB of
-query, and in each of `User-Agent`, `Referer` and `X-Request-Id`,
+client-chosen text in the path, in the query, and in each of
+`User-Agent`, `Referer`, `X-Request-Id` and `X-Forwarded-For`,
 including cases built from the characters the handlers escape, and
-against the widest access log line the service can be made to write: a
+against a 5xx that keeps its concrete path while all three header fields
-5xx that keeps its concrete path while all three header fields are also
+are also at their budget and an `X-Forwarded-For` sent from a trusted
-at their budget. Every case runs through both handlers
+proxy ends in an IPv6 client address at its longest followed by an 8 KB
-`internal/logger` can select — the JSON one and the text one it installs
+zone, where `clientIP` must name the address without the zone. Every
-on a tty — since the two do not escape alike and the ceiling is quoted
+case runs through both handlers `internal/logger` can select — the JSON
-unqualified. Measured over a real connection, the widest access log line
+one and the text one it installs on a tty — since the two do not escape
-is 1,972 bytes.
+alike and the ceiling is quoted unqualified.
 
 Multiply that ceiling by the request rate to size log storage. Note
 that the rate is not bounded by the limits above on every route:
@@ -2824,9 +2837,9 @@ remedies are to block the source at the reverse proxy, or to
 rate-limit `POST /pages/login` there — the one place a limit can be
 applied without reintroducing the lockout, because the proxy sees the
 real client address. `TRUSTED_PROXIES` does not stop the saturation.
-The flood's source is in the proxy's access log: webhooker's own logs
+The flood's source is in the `clientIP` field of webhooker's access
-record the proxy's address, not the client's (see
+log while `TRUSTED_PROXIES` covers the proxy, and in the proxy's own
-[Deployment behind a reverse proxy](#deployment-behind-a-reverse-proxy)).
+access log either way (see [Trusted proxies](#trusted-proxies)).
 
 Finer-grained per-webhook rate limits (configured in the web UI and
 enforced in the webhook handler) can layer on top of this env-level
@@ -3064,7 +3077,7 @@ Applied to all routes in this order:
    (HSTS, X-Content-Type-Options, X-Frame-Options, CSP, Referrer-Policy,
    Permissions-Policy)
 3. **Logging** — Structured request logging (method, URL, status,
-   latency, remote IP, user agent, request ID)
+   latency, remote IP, client IP, user agent, request ID)
 4. **Metrics** — Prometheus HTTP metrics (if `METRICS_USERNAME` and
    `METRICS_PASSWORD` are both set)
 5. **CORS** — Cross-origin resource sharing headers

internal/database/totals_test.go

@@ -102,6 +102,13 @@ func TestWebhookDBManager_TotalsSurviveReopen(t *testing.T) {
 // seedExpiredEvents stores count events created at the given time,
 // each with a delivered delivery to one target and a failed delivery
 // to the other, and one attempt for each delivery.
+//
+// It and seedBareEvents insert 50 rows per statement, not more. The
+// SQLite driver looks up each parameter's value by scanning the
+// statement's arguments from the first until it reaches that
+// parameter's, so the time to bind a statement grows with the square of
+// its parameter count: at 500 rows, several thousand parameters, the
+// seeding took most of these tests' time under -race.
 func seedExpiredEvents(
 	t *testing.T,
 	db *gorm.DB,
@@ -138,8 +145,8 @@ func seedExpiredEvents(
 		)
 	}
 
-	require.NoError(t, db.CreateInBatches(events, 500).Error)
+	require.NoError(t, db.CreateInBatches(events, 50).Error)
-	require.NoError(t, db.CreateInBatches(deliveries, 500).Error)
+	require.NoError(t, db.CreateInBatches(deliveries, 50).Error)
 
 	results := make([]database.DeliveryResult, len(deliveries))
 	for i := range deliveries {
@@ -148,7 +155,7 @@ func seedExpiredEvents(
 		}
 	}
 
-	require.NoError(t, db.CreateInBatches(results, 500).Error)
+	require.NoError(t, db.CreateInBatches(results, 50).Error)
 }
 
 // seedBareEvents stores count events created at the given time, with
@@ -172,7 +179,7 @@ func seedBareEvents(
 		events[i].CreatedAt = createdAt
 	}
 
-	require.NoError(t, db.CreateInBatches(events, 500).Error)
+	require.NoError(t, db.CreateInBatches(events, 50).Error)
 }
 
 // TestRetentionReaper_PrunesMoreThanOneBatch verifies that a prune

internal/handlers/webhook.go

@@ -11,6 +11,7 @@ import (
 	"sneak.berlin/go/webhooker/internal/database"
 	"sneak.berlin/go/webhooker/internal/delivery"
 	"sneak.berlin/go/webhooker/internal/logfield"
+	"sneak.berlin/go/webhooker/internal/middleware"
 )
 
 const (
@@ -57,7 +58,8 @@ func (h *Handlers) HandleWebhook() http.HandlerFunc {
 		h.log.Info("webhook request received",
 			"entrypoint_uuid", entrypointUUID,
 			"method", r.Method,
-			"remote_addr", r.RemoteAddr,
+			"remoteIP", middleware.RemoteIP(r),
+			"clientIP", middleware.ClientIP(r),
 		)
 
 		if !entrypoint.Active {

internal/handlers/webhook_test.go

@@ -0,0 +1,124 @@
+package handlers_test
+
+import (
+	"bytes"
+	"context"
+	"encoding/json"
+	"log/slog"
+	"net/http"
+	"net/http/httptest"
+	"net/netip"
+	"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/database"
+	"sneak.berlin/go/webhooker/internal/handlers"
+	"sneak.berlin/go/webhooker/internal/middleware"
+)
+
+// TestHandleWebhook_LogsClientNextToThePeer checks that the
+// receiver's "webhook request received" line carries both addresses:
+// remoteIP, the connecting peer, and clientIP, the client the access
+// log attributes the request to.
+func TestHandleWebhook_LogsClientNextToThePeer(t *testing.T) {
+	t.Parallel()
+
+	// untrustedPeer is outside the trusted 10.0.0.0/8, so its
+	// X-Forwarded-For is ignored and it is the client.
+	const untrustedPeer = "192.0.2.10"
+
+	cases := map[string]struct {
+		peer       string
+		wantRemote string
+		wantClient string
+	}{
+		"trusted proxy with a forwarded chain": {
+			peer:       "10.0.0.1:44444",
+			wantRemote: "10.0.0.1",
+			wantClient: "198.51.100.7",
+		},
+		"untrusted peer": {
+			peer:       untrustedPeer + ":5555",
+			wantRemote: untrustedPeer,
+			wantClient: untrustedPeer,
+		},
+	}
+
+	for name, tc := range cases {
+		t.Run(name, func(t *testing.T) {
+			t.Parallel()
+
+			var (
+				h  *handlers.Handlers
+				mw *middleware.Middleware
+				db *database.Database
+			)
+
+			app := newTestAppWithConfig(t, &config.Config{
+				DataDir: t.TempDir(),
+				TrustedProxies: []netip.Prefix{
+					netip.MustParsePrefix("10.0.0.0/8"),
+				},
+			}, &h, &mw, &db)
+			app.RequireStart()
+
+			t.Cleanup(app.RequireStop)
+
+			buf := new(bytes.Buffer)
+			h.SetLogForTest(slog.New(slog.NewJSONHandler(buf, nil)))
+
+			webhook := seedWebhook(t, db)
+			seedEntrypoint(t, db, webhook.ID)
+
+			// Logging is what works the client address out, so the
+			// request goes through it as it does in production.
+			router := chi.NewRouter()
+			router.Use(mw.Logging())
+			router.Post("/h/{uuid}", h.HandleWebhook())
+
+			req := httptest.NewRequestWithContext(
+				context.Background(), http.MethodPost,
+				"/h/ep-"+webhook.ID, strings.NewReader("{}"),
+			)
+			req.RemoteAddr = tc.peer
+			req.Header.Set("X-Forwarded-For", "198.51.100.7, 10.0.0.2")
+
+			w := httptest.NewRecorder()
+			router.ServeHTTP(w, req)
+
+			require.Equal(t, http.StatusOK, w.Code)
+
+			line := receivedLine(t, buf)
+			assert.Equal(t, tc.wantRemote, line["remoteIP"])
+			assert.Equal(t, tc.wantClient, line["clientIP"])
+		})
+	}
+}
+
+// receivedLine returns the one "webhook request received" line in the
+// captured JSON log.
+func receivedLine(t *testing.T, buf *bytes.Buffer) map[string]any {
+	t.Helper()
+
+	var found []map[string]any
+
+	for line := range strings.SplitSeq(
+		strings.TrimSpace(buf.String()), "\n",
+	) {
+		var entry map[string]any
+
+		require.NoError(t, json.Unmarshal([]byte(line), &entry))
+
+		if entry["msg"] == "webhook request received" {
+			found = append(found, entry)
+		}
+	}
+
+	require.Len(t, found, 1)
+
+	return found[0]
+}

internal/middleware/accesslog_test.go

@@ -63,6 +63,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,7 +78,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 +90,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 +102,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 +346,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
+	target       string
-	headers    map[string]string
+	headers      map[string]string
-	wantStatus int
+	wantStatus   int
-	wantURL    string
+	wantURL      string
-	bound      int
+	wantClientIP string
+	bound        int
 }
 
 // lineSizeCases enumerates every part of a request that reaches the
@@ -375,8 +388,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
+	// own budget on the same line as the three header fields.
-	// the widest access log line the service can be made to write.
 	longPath := "/boom/" + strings.Repeat("x", oversizedSegmentBytes)
 	wantLongURL := longPath[:maxFieldBytes] + truncationSuffix
 
@@ -420,6 +432,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 +495,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 +691,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)
 	}

internal/middleware/clientip_test.go

@@ -0,0 +1,200 @@
+package middleware_test
+
+import (
+	"bytes"
+	"context"
+	"log/slog"
+	"net/http"
+	"net/http/httptest"
+	"testing"
+
+	"github.com/stretchr/testify/assert"
+	"github.com/stretchr/testify/require"
+	"sneak.berlin/go/webhooker/internal/config"
+	"sneak.berlin/go/webhooker/internal/middleware"
+)
+
+const (
+	// forwardedChain is the X-Forwarded-For a request arrives with:
+	// the client, then a second proxy inside trustedProxyCIDR that the
+	// request passed through before reaching trustedPeer.
+	forwardedChain = clientIPv4 + ", 10.0.0.2"
+
+	// untrustedPeer is a peer outside trustedProxyCIDR, so its
+	// X-Forwarded-For is ignored and the peer is the client.
+	untrustedPeer = "192.0.2.10:5555"
+
+	// oneRequestPerMinute is the receiver limit these tests install:
+	// the second request on a path is rejected, and the aggregate
+	// limit is ReceiverAggregateMultiplierConst.
+	oneRequestPerMinute = 1
+)
+
+// clientLogSite is one log line that names the client. build wraps the
+// middleware that writes it around a handler, and requests is how many
+// identical requests it takes before the line is written.
+type clientLogSite struct {
+	build    func(m *middleware.Middleware) http.Handler
+	requests int
+}
+
+// clientLogSites maps the message of each line that names the client
+// to the way to make it be written.
+func clientLogSites() map[string]clientLogSite {
+	served := func(*middleware.Middleware) http.Handler {
+		return okHandler()
+	}
+
+	receiver := func(m *middleware.Middleware) http.Handler {
+		return m.ReceiverRateLimit()(okHandler())
+	}
+
+	login := func(m *middleware.Middleware) http.Handler {
+		return http.HandlerFunc(
+			func(w http.ResponseWriter, r *http.Request) {
+				m.RecordLoginFailure(r, "someone")
+				w.WriteHeader(http.StatusUnauthorized)
+			},
+		)
+	}
+
+	csrf := func(m *middleware.Middleware) http.Handler {
+		return m.CSRF(http.HandlerFunc(forbidden))(okHandler())
+	}
+
+	passwordChange := func(m *middleware.Middleware) http.Handler {
+		return m.PasswordChangeRateLimit()(okHandler())
+	}
+
+	replay := func(m *middleware.Middleware) http.Handler {
+		return m.ReplayRateLimit()(okHandler())
+	}
+
+	resubmit := func(m *middleware.Middleware) http.Handler {
+		return m.ResubmitRateLimit()(okHandler())
+	}
+
+	return map[string]clientLogSite{
+		"http request": {
+			build:    served,
+			requests: 1,
+		},
+		"webhook receiver rate limit exceeded": {
+			build:    receiver,
+			requests: oneRequestPerMinute + 1,
+		},
+		// The aggregate limit sits in front of the per-entrypoint
+		// one, so the requests that one rejects count towards it.
+		"webhook receiver aggregate rate limit exceeded": {
+			build: receiver,
+			requests: middleware.ReceiverAggregateMultiplierConst*
+				oneRequestPerMinute + 1,
+		},
+		"login failure limit exceeded": {
+			build:    login,
+			requests: middleware.LoginRateLimitConst + 1,
+		},
+		"csrf: token validation failed": {
+			build:    csrf,
+			requests: 1,
+		},
+		"password change rate limit exceeded": {
+			build:    passwordChange,
+			requests: middleware.PasswordChangeRateLimitConst + 1,
+		},
+		"delivery replay rate limit exceeded": {
+			build:    replay,
+			requests: middleware.ReplayRateLimitConst + 1,
+		},
+		"event resubmit rate limit exceeded": {
+			build:    resubmit,
+			requests: middleware.ResubmitRateLimitConst + 1,
+		},
+	}
+}
+
+// clientLogLines sends the site's requests from peer, each carrying
+// forwardedChain, through Logging and then the site, as production
+// does, and returns the logged lines whose message is msg.
+func clientLogLines(
+	t *testing.T, site clientLogSite, msg, peer string,
+) []map[string]any {
+	t.Helper()
+
+	buf := new(bytes.Buffer)
+	log := slog.New(slog.NewJSONHandler(
+		buf,
+		&slog.HandlerOptions{Level: slog.LevelDebug},
+	))
+
+	cfg := &config.Config{
+		Environment:       config.EnvironmentDev,
+		ReceiverRateLimit: oneRequestPerMinute,
+		TrustedProxies:    trustedProxies(trustedProxyCIDR),
+	}
+
+	m := middleware.NewForTest(
+		log, cfg, newTestSessionManager(cfg, log, nil),
+	)
+	handler := m.Logging()(site.build(m))
+
+	for range site.requests {
+		req := httptest.NewRequestWithContext(
+			context.Background(), http.MethodPost, "/h/x", nil,
+		)
+		req.RemoteAddr = peer
+		req.Header.Set(headerXFF, forwardedChain)
+
+		handler.ServeHTTP(httptest.NewRecorder(), req)
+	}
+
+	var lines []map[string]any
+
+	for _, entry := range accessLogEntries(t, buf) {
+		if entry["msg"] == msg {
+			lines = append(lines, entry)
+		}
+	}
+
+	return lines
+}
+
+// TestClientIP_LoggedNextToThePeer checks that every line that names
+// the client carries both addresses: remoteIP, the connecting peer,
+// and clientIP, the client the rate limiters key on.
+func TestClientIP_LoggedNextToThePeer(t *testing.T) {
+	t.Parallel()
+
+	cases := map[string]struct {
+		peer       string
+		wantRemote string
+		wantClient string
+	}{
+		"trusted proxy with a forwarded chain": {
+			peer:       trustedPeer,
+			wantRemote: "10.0.0.1",
+			wantClient: clientIPv4,
+		},
+		"untrusted peer": {
+			peer:       untrustedPeer,
+			wantRemote: "192.0.2.10",
+			wantClient: "192.0.2.10",
+		},
+	}
+
+	for msg, site := range clientLogSites() {
+		for name, tc := range cases {
+			t.Run(msg+"/"+name, func(t *testing.T) {
+				t.Parallel()
+
+				lines := clientLogLines(t, site, msg, tc.peer)
+				require.NotEmpty(t, lines, "%q was never logged", msg)
+
+				for _, line := range lines {
+					assert.Equal(t, tc.wantRemote, line["remoteIP"])
+					assert.Equal(t, tc.wantClient, line["clientIP"])
+				}
+			})
+		}
+	}
+}

internal/middleware/csrf.go

@@ -45,10 +45,10 @@ func (m *Middleware) CSRF(
 		// unauthenticated client: a POST with no token to
 		// /hook/<any length of any text>/edit lands here. The
 		// method and path are capped against the same budgets as
-		// the access log. remote_addr is set by net/http from the
+		// the access log. remoteIP and clientIP are the same
-		// accepted connection rather than by the client, and
+		// addresses the access log carries, and
 		// csrf.FailureReason returns one of gorilla/csrf's own
-		// fixed error values, so neither is client-sized.
+		// fixed error values, so none of them is client-sized.
 		m.log.Warn("csrf: token validation failed",
 			"method", logfield.Truncate(
 				r.Method, maxLogMethodBytes,
@@ -56,7 +56,8 @@ func (m *Middleware) CSRF(
 			"path", logfield.Truncate(
 				r.URL.Path, logfield.MaxBytes,
 			),
-			"remote_addr", r.RemoteAddr,
+			"remoteIP", RemoteIP(r),
+			"clientIP", ClientIP(r),
 			"reason", csrf.FailureReason(r),
 		)
 		forbidden.ServeHTTP(w, r)

internal/middleware/export_test.go

@@ -132,6 +132,12 @@ func (g *LoginGuard) TrackedKeysForTest() (int, int) {
 // passwordChangeRateLimit constant.
 const PasswordChangeRateLimitConst = passwordChangeRateLimit
 
+// ReplayRateLimitConst exposes the replayRateLimit constant.
+const ReplayRateLimitConst = replayRateLimit
+
+// ResubmitRateLimitConst exposes the resubmitRateLimit constant.
+const ResubmitRateLimitConst = resubmitRateLimit
+
 // ReceiverAggregateMultiplierConst exposes the
 // receiverAggregateMultiplier constant.
 const ReceiverAggregateMultiplierConst = receiverAggregateMultiplier

internal/middleware/loginguard.go

@@ -385,6 +385,8 @@ func (m *Middleware) RecordLoginFailure(
 			"path", logfield.Truncate(
 				r.URL.Path, logfield.MaxBytes,
 			),
+			"remoteIP", RemoteIP(r),
+			"clientIP", ClientIP(r),
 		)
 	}
 

internal/middleware/middleware.go

@@ -3,6 +3,7 @@
 package middleware
 
 import (
+	"context"
 	"log/slog"
 	"net"
 	"net/http"
@@ -69,18 +70,19 @@ const (
 	//	url, useragent, referer   3*(512+11) = 1569
 	//	request_id                    128+11 =  139
 	//	method                         32+11 =   43
-	//	fixed portion                        =  336
+	//	fixed portion                        =  405
 	//	                                        ----
-	//	                                        2087
+	//	                                        2156
 	//
 	// The 512 is logfield.MaxBytes; the 11 is the truncation marker,
 	// charged on top of each budget rather than inside it.
 	//
 	// The fixed portion is the JSON punctuation, the field names, the
-	// level and the message, both timestamps at their longest, an IPv6
+	// level and the message, both timestamps at their longest, remoteIP
-	// remoteIP with a zone, a three-digit status and a full-width int64
+	// and clientIP each charged as an IPv6 address with a zone, a
-	// latency. Stated at 2560 so the figure carries headroom rather
+	// three-digit status and a full-width int64 latency. Stated at 2560
-	// than sitting on the arithmetic.
+	// so the figure carries headroom rather than sitting on the
+	// arithmetic.
 	//
 	// The tty text handler in internal/logger is covered by the same
 	// figure. logfield.EncodedBytes charges every rune at least what
@@ -88,8 +90,8 @@ const (
 	// bytes strconv.Quote spends on a non-printable rune at or above
 	// U+10000, which is four more than the JSON handler ever spends —
 	// so each budget bounds the encoded field under either handler.
-	// The text handler's fixed portion is 286, the smaller of the two,
+	// The text handler's fixed portion is 351, the smaller of the two,
-	// which puts its worst case at 2037.
+	// which puts its worst case at 2102.
 	//
 	// It is also the ceiling on every OTHER line this service writes
 	// THROUGH SLOG that carries text an UNAUTHENTICATED client
@@ -215,6 +217,28 @@ func ipFromHostPort(hp string) string {
 	return h
 }
 
+// RemoteIP returns the address of the connecting peer, without its
+// port. Behind a reverse proxy it is the proxy. Every log line that
+// names the client logs it as remoteIP, next to clientIP.
+func RemoteIP(r *http.Request) string {
+	return ipFromHostPort(r.RemoteAddr)
+}
+
+// clientIPKey is the request context key under which Logging stores
+// the value ClientIP returns.
+type clientIPKey struct{}
+
+// ClientIP returns the address the request is attributed to, which
+// Logging works out once per request with clientAddr in ratelimit.go
+// and logs as clientIP. The other lines that name the client read it
+// from here, so all of them agree. It is empty for a request Logging
+// has not seen.
+func ClientIP(r *http.Request) string {
+	ip, _ := r.Context().Value(clientIPKey{}).(string)
+
+	return ip
+}
+
 type loggingResponseWriter struct {
 	http.ResponseWriter
 
@@ -316,6 +340,13 @@ func (s *Middleware) Logging() func(http.Handler) http.Handler {
 			lrw := newLoggingResponseWriter(w)
 			ctx := r.Context()
 
+			// When RemoteAddr is not an address, the peer's own
+			// text is all the request can be attributed to.
+			clientIP := RemoteIP(r)
+			if addr, ok := s.clientAddr(r); ok {
+				clientIP = addr.String()
+			}
+
 			defer func() {
 				latency := time.Since(start)
 				requestID := ""
@@ -350,13 +381,16 @@ func (s *Middleware) Logging() func(http.Handler) http.Handler {
 						r.Referer(), logfield.MaxBytes,
 					),
 					"proto", r.Proto,
-					"remoteIP", ipFromHostPort(r.RemoteAddr),
+					"remoteIP", RemoteIP(r),
+					"clientIP", clientIP,
 					"status", lrw.statusCode,
 					"latency_ms", latency.Milliseconds(),
 				)
 			}()
 
-			next.ServeHTTP(lrw, r)
+			next.ServeHTTP(lrw, r.WithContext(
+				context.WithValue(ctx, clientIPKey{}, clientIP),
+			))
 		})
 	}
 }

internal/middleware/ratelimit.go

@@ -202,24 +202,17 @@ func (m *Middleware) forwardedClientAddr(
 }
 
 // rateLimitKey is the client identity every rate limiter in this
-// package buckets on. Forwarded headers are honoured only when the
+// package buckets on: the address clientAddr attributes the request
-// direct peer (RemoteAddr) is inside the configured trusted-proxy
+// to, reduced to a bucket by bucketKey — full address for IPv4, /64
-// set; otherwise the peer address itself is the key. Without that
+// prefix for IPv6.
-// gate any client could mint a fresh bucket per request, or starve
-// another client's bucket, by picking an X-Forwarded-For value —
-// which makes every limit here decorative against a deliberate
-// attacker.
-//
-// The address that identifies the client is then reduced to a bucket
-// by bucketKey: full address for IPv4, /64 prefix for IPv6.
 func (m *Middleware) rateLimitKey(r *http.Request) (string, error) {
 	return m.clientKey(r), nil
 }
 
 // clientKey computes the bucket key described on rateLimitKey.
 func (m *Middleware) clientKey(r *http.Request) string {
-	peer, err := netip.ParseAddr(ipFromHostPort(r.RemoteAddr))
+	addr, ok := m.clientAddr(r)
-	if err != nil {
+	if !ok {
 		// Not an address we can reason about; key on the raw
 		// value, the most specific identity left. Distinct
 		// RemoteAddr values stay in distinct buckets, so this
@@ -230,16 +223,36 @@ func (m *Middleware) clientKey(r *http.Request) string {
 		return r.RemoteAddr
 	}
 
+	return bucketKey(addr)
+}
+
+// clientAddr is the address a request is attributed to. The rate
+// limiters key on it and the logs name it as clientIP.
+//
+// Forwarded headers are honoured only when the direct peer
+// (RemoteAddr) is inside the configured trusted-proxy set; otherwise
+// the peer address itself is the client. Without that gate any client
+// could mint a fresh bucket per request, or starve another client's
+// bucket, by picking an X-Forwarded-For value — which makes every
+// limit here decorative against a deliberate attacker.
+//
+// ok is false when RemoteAddr is not an address at all.
+func (m *Middleware) clientAddr(r *http.Request) (netip.Addr, bool) {
+	peer, err := netip.ParseAddr(ipFromHostPort(r.RemoteAddr))
+	if err != nil {
+		return netip.Addr{}, false
+	}
+
 	peer = normalizeAddr(peer)
 	if !m.isTrustedProxy(peer) {
-		return bucketKey(peer)
+		return peer, true
 	}
 
 	if addr, ok := m.forwardedClientAddr(r); ok {
-		return bucketKey(addr)
+		return addr, true
 	}
 
-	return bucketKey(peer)
+	return peer, true
 }
 
 // tooManyRequests returns the 429 handler used by the
@@ -262,6 +275,8 @@ func (m *Middleware) tooManyRequests(
 			"path", logfield.Truncate(
 				r.URL.Path, logfield.MaxBytes,
 			),
+			"remoteIP", RemoteIP(r),
+			"clientIP", ClientIP(r),
 		)
 		http.Error(w, responseMessage, http.StatusTooManyRequests)
 	}
@@ -286,8 +301,12 @@ func (m *Middleware) tooManyRequests(
 func (m *Middleware) floodTooManyRequests(
 	logMessage, responseMessage string,
 ) http.HandlerFunc {
-	return func(w http.ResponseWriter, _ *http.Request) {
+	return func(w http.ResponseWriter, r *http.Request) {
-		m.log.Debug(logMessage)
+		m.log.Debug(
+			logMessage,
+			"remoteIP", RemoteIP(r),
+			"clientIP", ClientIP(r),
+		)
 		http.Error(w, responseMessage, http.StatusTooManyRequests)
 	}
 }

script/test

@@ -27,7 +27,11 @@
 # Those figures predate tests hashing the admin password at 1 MB instead of
 # 64 MB (https://git.eeqj.de/sneak/webhooker/pulls/404). After that change, in
 # a cache-defeated build at host load 44-109 (2026-10-02), internal/handlers
-# took 8.5s and the slowest package was internal/database at 15.8s.
+# took 8.5s and the slowest package was internal/database at 15.8s. Once its
+# retention tests seeded 50 rows per insert instead of 500
+# (https://git.eeqj.de/sneak/webhooker/issues/198), internal/database took
+# 7.3s and the slowest package was internal/handlers at 8.1s to 10.0s, at host
+# load 25-48 (2026-10-02).
 #
 # -p 4 -parallel 8 keep the run under 2 GB of memory: at most four test
 # binaries build or run at once, each with at most eight parallel tests. Under