Send fx's own events through the service's logger (closes #183)

fx printed its dependency graph and its start and stop hooks through
its console logger on standard error. fx.WithLogger now hands those
events to the service's logger: building the graph at DEBUG, the hooks,
the start and the stopping signal at INFO, failures at ERROR. The fx
logger's constructor takes the configuration, so the level DEBUG=true
sets is in force before fx replays the events it held back. fx's
SlogLogger takes one level for everything that is not a failure, so
FxLogger in internal/logger holds one at each level. fx moves from
v1.20.1, which has no SlogLogger, to v1.24.0. The README names the Go
runtime as a writer whose output cannot be redirected.

Model: opus-5-5

README.md

@@ -457,19 +457,6 @@ 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
@@ -855,9 +842,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 names
-   the client in its `clientIP` field only while `TRUSTED_PROXIES`
-   covers the proxy; the proxy's log names it regardless. nginx's
+5. **Keep the proxy's access log.** webhooker's own access log records
+   the peer address, which behind a proxy is always the proxy. The
+   proxy's log is the only record of which client sent what. 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.
@@ -886,8 +873,9 @@ server {
     # webhooker's message.
     client_max_body_size 1m;
 
-    # $remote_addr is the client. webhooker's own log names it, as
-    # clientIP, only while TRUSTED_PROXIES covers this proxy.
+    # $remote_addr is the client. webhooker's own log records this
+    # proxy and nothing else, so this file is the only place the
+    # client's address is written down.
     access_log /var/log/nginx/webhooker.access.log combined;
 
     location / {
@@ -2486,21 +2474,20 @@ 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 405-byte fixed portion (the field names, the
-punctuation, both timestamps at their longest, `remoteIP` and
-`clientIP` each charged as an IPv6 address with a zone, the status and
-the latency) — 2,156 bytes, stated at 2,560 so the figure has headroom.
-`internal/middleware/accesslog_test.go` asserts it against 8 KB of
-client-chosen text in the path, in the query, and in each of
-`User-Agent`, `Referer`, `X-Request-Id` and `X-Forwarded-For`,
+for `method`, plus a 336-byte fixed portion (the field names, the
+punctuation, both timestamps at their longest, an IPv6 `remoteIP` with
+a zone, the status and the latency) — 2,087 bytes, stated at 2,560 so
+the figure has headroom. `internal/middleware/accesslog_test.go`
+asserts it against 8 KB of client-chosen text in the path, in the
+query, and in each of `User-Agent`, `Referer` and `X-Request-Id`,
 including cases built from the characters the handlers escape, and
-against a 5xx that keeps its concrete path while all three header fields
-are also at their budget and an `X-Forwarded-For` sent from a trusted
-proxy ends in an IPv6 client address at its longest followed by an 8 KB
-zone, where `clientIP` must name the address without the zone. Every
-case runs through both handlers `internal/logger` can select — the JSON
-one and the text one it installs on a tty — since the two do not escape
-alike and the ceiling is quoted unqualified.
+against the widest access log line the service can be made to write: a
+5xx that keeps its concrete path while all three header fields are also
+at their budget. Every case runs through both handlers
+`internal/logger` can select — the JSON one and the text one it installs
+on a tty — since the two do not escape alike and the ceiling is quoted
+unqualified. Measured over a real connection, the widest access log line
+is 1,972 bytes.
 
 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:
@@ -2647,11 +2634,6 @@ read as more than it is:
   `panic` calls are invariant guards over constants and over
   `crypto/rand`, apart from the one that hands `http.ErrAbortHandler`
   back to `net/http`, described below.
-- **A failure before fx's logger is built**, such as an invalid
-  configuration value. fx's logger takes the configuration, so when
-  that fails fx's own console logger still prints the failure as plain
-  text on standard error. Its values come from the operator's
-  environment, not from a client.
 - **`net/http`'s own faults**, which are _not_ a separate writer.
   `internal/server/http.go` builds its server with a nil `ErrorLog`, so
   `net/http` falls back to the `log` package's default logger — and
@@ -2842,9 +2824,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 `clientIP` field of webhooker's access
-log while `TRUSTED_PROXIES` covers the proxy, and in the proxy's own
-access log either way (see [Trusted proxies](#trusted-proxies)).
+The flood's source is in the proxy's access log: webhooker's own logs
+record the proxy's address, not the client's (see
+[Deployment behind a reverse proxy](#deployment-behind-a-reverse-proxy)).
 
 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
@@ -3082,7 +3064,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, client IP, user agent, request ID)
+   latency, remote 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

cmd/webhooker/main.go

@@ -170,13 +170,11 @@ func newApp() *fx.App {
 	return fx.New(
 		fx.StopTimeout(stopTimeout),
 		// fx's own events go through the service's logger, not fx's
-		// console logger on standard error. The exception is a failure
-		// before this logger is built, such as an invalid configuration
-		// value, which fx's console logger still prints there. fx holds
-		// its events back until this logger is built and then replays
-		// them, so it takes the configuration, which sets the level
-		// DEBUG=true asks for: without it the replay would run at INFO
-		// and drop every record of how the graph was built.
+		// console logger on standard error. fx holds its events back
+		// until this logger is built and then replays them, so it takes
+		// the configuration, which sets the level DEBUG=true asks for:
+		// without it the replay would run at INFO and drop every record
+		// of how the graph was built.
 		fx.WithLogger(
 			func(l *logger.Logger, _ *config.Config) fxevent.Logger {
 				return logger.NewFxLogger(l.Get())

internal/database/retention.go

@@ -184,6 +184,16 @@ func (r *RetentionReaper) sweep(ctx context.Context) {
 
 		wh := webhooks[i]
 
+		// Skip retain-forever webhooks before building any query.
+		// RetainsForever covers both the RetentionForeverDays
+		// sentinel and the non-positive values that predate it: the
+		// sentinel is a positive number, so without this the reaper
+		// would compute a cutoff a thousand years in the past and
+		// issue a DELETE matching nothing on every single sweep.
+		if wh.RetainsForever() {
+			continue
+		}
+
 		// Nothing to reap if the per-webhook database has never
 		// been created.
 		if !r.dbManager.DBExists(wh.ID) {
@@ -202,13 +212,6 @@ func (r *RetentionReaper) reapWebhook(
 	webhookID string,
 	retentionDays int,
 ) {
-	// A retain-forever webhook has no cutoff, so its database is not
-	// even opened.
-	cutoff, ok := retentionCutoff(time.Now(), retentionDays)
-	if !ok {
-		return
-	}
-
 	db, err := r.dbManager.GetDB(webhookID)
 	if err != nil {
 		r.log.Error(
@@ -220,6 +223,11 @@ func (r *RetentionReaper) reapWebhook(
 		return
 	}
 
+	cutoff, ok := retentionCutoff(time.Now(), retentionDays)
+	if !ok {
+		return
+	}
+
 	deleted, err := reapExpired(ctx, db, cutoff)
 	if err != nil {
 		r.log.Error(

internal/database/retention_test.go

@@ -362,7 +362,7 @@ func TestRetentionReaper_HugeFiniteRetentionRetainsRecentEvents(
 		t,
 		overflowingRetentionDays,
 		database.RetentionForeverDays,
-		"the test value must not be treated as retain-forever",
+		"the test value must not be rescued by the forever skip",
 	)
 
 	webhookID := createWebhook(

internal/handlers/source_management.go

@@ -41,51 +41,71 @@ type WebhookListItem struct {
 // errMissingURL signals that a required URL was not provided.
 var errMissingURL = errors.New("missing URL")
 
-// parseRetentionDays interprets a retention_days form value. It
-// returns the number of days, or, for a value it refuses, the message
-// the create and edit forms show; the message is empty when the value
-// is accepted.
+// errInvalidRetention signals a retention_days form value that is not
+// a non-negative whole number.
+var errInvalidRetention = errors.New("invalid retention days")
+
+// errRetentionTooLarge signals a retention_days form value that is a
+// whole number but larger than the reaper's cutoff arithmetic can
+// represent. It is distinguished from errInvalidRetention so the form
+// can tell the user the actual ceiling instead of implying their input
+// was not a number.
+var errRetentionTooLarge = errors.New("retention days out of range")
+
+// retentionErrorMessage returns the message the create and edit forms
+// show the user for a rejected retention_days value. Any error other
+// than errRetentionTooLarge falls back to the generic wording, so an
+// unrecognised parse failure still produces a sensible 400 rather than
+// an empty alert.
+func retentionErrorMessage(err error) string {
+	if errors.Is(err, errRetentionTooLarge) {
+		return "Retention must be at most " +
+			strconv.Itoa(database.MaxFiniteRetentionDays) +
+			" days, or 0 to retain events forever."
+	}
+
+	return "Retention must be a whole number of days, or 0 to " +
+		"retain events forever."
+}
+
+// parseRetentionDays interprets a retention_days form value.
 //
 // An empty value yields fallback, which lets the create path apply the
 // default and the edit path leave the stored value unchanged. A value
 // of 0 is returned as 0 and is rewritten to the retain-forever
 // sentinel by database.Webhook's BeforeSave hook. Anything unparseable
-// or negative is refused rather than silently given a default.
+// or negative is an error rather than a silently substituted default.
 //
 // The upper bound is not cosmetic. The reaper computes its cutoff as a
 // time.Duration, an int64 nanosecond count, so a day count above
 // database.MaxFiniteRetentionDays overflows, puts the cutoff in the
 // future, and deletes every event the webhook has. A finite value
-// above that ceiling is therefore refused, and the message names the
-// ceiling rather than implying the input was not a number.
+// above that ceiling is therefore a 400.
 //
 // A value at or above the retain-forever sentinel is not out of range:
 // it is what the edit form pre-fills for a retain-forever webhook, so
 // submitting the form back unchanged has to keep meaning "forever"
 // rather than being rejected.
-func parseRetentionDays(raw string, fallback int) (int, string) {
+func parseRetentionDays(raw string, fallback int) (int, error) {
 	raw = strings.TrimSpace(raw)
 	if raw == "" {
-		return fallback, ""
+		return fallback, nil
 	}
 
 	v, err := strconv.Atoi(raw)
 	if err != nil || v < 0 {
-		return 0, "Retention must be a whole number of days, or 0 to " +
-			"retain events forever."
+		return 0, errInvalidRetention
 	}
 
 	if v >= database.RetentionForeverDays {
-		return database.RetentionForeverDays, ""
+		return database.RetentionForeverDays, nil
 	}
 
 	if v > database.MaxFiniteRetentionDays {
-		return 0, "Retention must be at most " +
-			strconv.Itoa(database.MaxFiniteRetentionDays) +
-			" days, or 0 to retain events forever."
+		return 0, errRetentionTooLarge
 	}
 
-	return v, ""
+	return v, nil
 }
 
 // DeliveryView is the display-safe projection of a delivery
@@ -341,13 +361,16 @@ func (h *Handlers) HandleSourceCreateSubmit() http.HandlerFunc {
 			return
 		}
 
-		retentionDays, errMsg := parseRetentionDays(
+		retentionDays, retErr := parseRetentionDays(
 			retentionStr, database.DefaultRetentionDays,
 		)
-		if errMsg != "" {
+		if retErr != nil {
 			h.renderTemplateStatus(
 				w, r, "sources_new.html",
-				newSourceFormData(errMsg, name, description),
+				newSourceFormData(
+					retentionErrorMessage(retErr),
+					name, description,
+				),
 				http.StatusBadRequest,
 			)
 
@@ -632,13 +655,13 @@ func (h *Handlers) applyWebhookEdit(
 
 	// An empty field falls back to the stored value, so submitting the
 	// form without touching retention leaves the policy alone.
-	retentionDays, errMsg := parseRetentionDays(
+	retentionDays, retErr := parseRetentionDays(
 		r.PostFormValue("retention_days"), webhook.RetentionDays,
 	)
-	if errMsg != "" {
+	if retErr != nil {
 		data := map[string]any{
 			tmplKeyWebhook: webhook,
-			tmplKeyError:   errMsg,
+			tmplKeyError:   retentionErrorMessage(retErr),
 		}
 
 		h.renderTemplateStatus(w, r, "source_edit.html", data, http.StatusBadRequest)

internal/handlers/source_management_test.go

@@ -368,42 +368,31 @@ func TestHandleSourceCreateSubmit_OverflowingRetentionIsRejected(
 // boundary between "too large to represent" and "retain forever": the
 // sentinel is above MaxFiniteRetentionDays, but it is the value the
 // edit form pre-fills, so it must be accepted rather than rejected as
-// out of range. A value above the sentinel is stored as the sentinel.
+// out of range.
 func TestHandleSourceCreateSubmit_SentinelIsAcceptedAsForever(
 	t *testing.T,
 ) {
 	t.Parallel()
 
-	for _, days := range []int{
+	env := setupSourceTest(t)
+	sentinel := strconv.Itoa(database.RetentionForeverDays)
+
+	w := submitCreate(t, env.handlers, env.cookies, "forever", &sentinel)
+	require.Equal(t, http.StatusSeeOther, w.Code)
+
+	wh := onlyWebhook(t, env.db)
+	assert.Equal(
+		t,
 		database.RetentionForeverDays,
-		database.RetentionForeverDays + 1,
-	} {
-		raw := strconv.Itoa(days)
-
-		t.Run(raw, func(t *testing.T) {
-			t.Parallel()
-
-			env := setupSourceTest(t)
-
-			w := submitCreate(t, env.handlers, env.cookies, "forever", &raw)
-			require.Equal(t, http.StatusSeeOther, w.Code)
-
-			wh := onlyWebhook(t, env.db)
-			assert.Equal(
-				t,
-				database.RetentionForeverDays,
-				storedRetentionDays(t, env.db, wh.ID),
-			)
-		})
-	}
+		storedRetentionDays(t, env.db, wh.ID),
+	)
 }
 
 // TestHandleSourceCreateSubmit_RejectedFormKeepsUserInput checks that a
 // validation failure hands the user's typing back, matching what the
 // edit form already does. Losing a long description to a mistyped
 // retention value is the kind of thing that makes people give up on a
-// form. Both values carry HTML-special characters, which must come
-// back escaped rather than as markup.
+// form.
 func TestHandleSourceCreateSubmit_RejectedFormKeepsUserInput(
 	t *testing.T,
 ) {
@@ -412,8 +401,8 @@ func TestHandleSourceCreateSubmit_RejectedFormKeepsUserInput(
 	env := setupSourceTest(t)
 
 	const (
-		name        = `kept"><b>name`
-		description = `a </textarea> worth not losing`
+		name        = "kept-name"
+		description = "a description worth not losing"
 	)
 
 	form := url.Values{}
@@ -430,10 +419,8 @@ func TestHandleSourceCreateSubmit_RejectedFormKeepsUserInput(
 
 	body := w.Body.String()
 
-	assert.Contains(t, body, `value="kept&#34;&gt;&lt;b&gt;name"`)
-	assert.Contains(t, body, `a &lt;/textarea&gt; worth not losing`)
-	assert.NotContains(t, body, name)
-	assert.NotContains(t, body, description)
+	assert.Contains(t, body, `value="`+name+`"`)
+	assert.Contains(t, body, description)
 }
 
 // submitEdit posts the webhook edit form for the given webhook.

internal/handlers/webhook.go

@@ -11,7 +11,6 @@ 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 (
@@ -58,8 +57,7 @@ func (h *Handlers) HandleWebhook() http.HandlerFunc {
 		h.log.Info("webhook request received",
 			"entrypoint_uuid", entrypointUUID,
 			"method", r.Method,
-			"remoteIP", middleware.RemoteIP(r),
-			"clientIP", middleware.ClientIP(r),
+			"remote_addr", r.RemoteAddr,
 		)
 
 		if !entrypoint.Active {

internal/handlers/webhook_test.go

@@ -1,124 +0,0 @@
-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,12 +63,6 @@ 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()
 
@@ -78,10 +72,7 @@ func capturingMiddleware(t *testing.T) (*middleware.Middleware, *bytes.Buffer) {
 		&slog.HandlerOptions{Level: slog.LevelInfo},
 	))
 
-	cfg := &config.Config{
-		Environment:    config.EnvironmentDev,
-		TrustedProxies: trustedProxies("192.0.2.1/32"),
-	}
+	cfg := &config.Config{Environment: config.EnvironmentDev}
 
 	return middleware.NewForTest(log, cfg, nil), buf
 }
@@ -90,7 +81,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. It trusts the same peer.
+// against both.
 func capturingTextMiddleware(
 	t *testing.T,
 ) (*middleware.Middleware, *bytes.Buffer) {
@@ -102,10 +93,7 @@ func capturingTextMiddleware(
 		&slog.HandlerOptions{Level: slog.LevelInfo},
 	))
 
-	cfg := &config.Config{
-		Environment:    config.EnvironmentDev,
-		TrustedProxies: trustedProxies("192.0.2.1/32"),
-	}
+	cfg := &config.Config{Environment: config.EnvironmentDev}
 
 	return middleware.NewForTest(log, cfg, nil), buf
 }
@@ -346,12 +334,11 @@ 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
-	wantClientIP string
-	bound        int
+	target     string
+	headers    map[string]string
+	wantStatus int
+	wantURL    string
+	bound      int
 }
 
 // lineSizeCases enumerates every part of a request that reaches the
@@ -388,7 +375,8 @@ 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.
+	// 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.
 	longPath := "/boom/" + strings.Repeat("x", oversizedSegmentBytes)
 	wantLongURL := longPath[:maxFieldBytes] + truncationSuffix
 
@@ -432,29 +420,6 @@ 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
 }
 
@@ -495,14 +460,6 @@ 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.
@@ -691,8 +648,7 @@ func TestAccessLog_RetainsEveryOtherField(t *testing.T) {
 
 	for _, key := range []string{
 		"request_start", "method", "url", "useragent", "request_id",
-		"referer", "proto", "remoteIP", "clientIP", "status",
-		"latency_ms",
+		"referer", "proto", "remoteIP", "status", "latency_ms",
 	} {
 		assert.Contains(t, entries[0], key)
 	}

internal/middleware/clientip_test.go

@@ -1,200 +0,0 @@
-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. remoteIP and clientIP are the same
-		// addresses the access log carries, and
+		// the access log. remote_addr is set by net/http from the
+		// accepted connection rather than by the client, and
 		// csrf.FailureReason returns one of gorilla/csrf's own
-		// fixed error values, so none of them is client-sized.
+		// fixed error values, so neither is client-sized.
 		m.log.Warn("csrf: token validation failed",
 			"method", logfield.Truncate(
 				r.Method, maxLogMethodBytes,
@@ -56,8 +56,7 @@ func (m *Middleware) CSRF(
 			"path", logfield.Truncate(
 				r.URL.Path, logfield.MaxBytes,
 			),
-			"remoteIP", RemoteIP(r),
-			"clientIP", ClientIP(r),
+			"remote_addr", r.RemoteAddr,
 			"reason", csrf.FailureReason(r),
 		)
 		forbidden.ServeHTTP(w, r)

internal/middleware/export_test.go

@@ -132,12 +132,6 @@ 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,8 +385,6 @@ func (m *Middleware) RecordLoginFailure(
 			"path", logfield.Truncate(
 				r.URL.Path, logfield.MaxBytes,
 			),
-			"remoteIP", RemoteIP(r),
-			"clientIP", ClientIP(r),
 		)
 	}
 

internal/middleware/middleware.go

@@ -3,7 +3,6 @@
 package middleware
 
 import (
-	"context"
 	"log/slog"
 	"net"
 	"net/http"
@@ -70,19 +69,18 @@ const (
 	//	url, useragent, referer   3*(512+11) = 1569
 	//	request_id                    128+11 =  139
 	//	method                         32+11 =   43
-	//	fixed portion                        =  405
+	//	fixed portion                        =  336
 	//	                                        ----
-	//	                                        2156
+	//	                                        2087
 	//
 	// 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, remoteIP
-	// and clientIP each charged as an IPv6 address with a zone, a
-	// three-digit status and a full-width int64 latency. Stated at 2560
-	// so the figure carries headroom rather than sitting on the
-	// arithmetic.
+	// level and the message, both timestamps at their longest, an IPv6
+	// remoteIP with a zone, a three-digit status and a full-width int64
+	// latency. Stated at 2560 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
@@ -90,8 +88,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 351, the smaller of the two,
-	// which puts its worst case at 2102.
+	// The text handler's fixed portion is 286, the smaller of the two,
+	// which puts its worst case at 2037.
 	//
 	// It is also the ceiling on every OTHER line this service writes
 	// THROUGH SLOG that carries text an UNAUTHENTICATED client
@@ -217,28 +215,6 @@ 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
 
@@ -340,13 +316,6 @@ 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 := ""
@@ -381,16 +350,13 @@ func (s *Middleware) Logging() func(http.Handler) http.Handler {
 						r.Referer(), logfield.MaxBytes,
 					),
 					"proto", r.Proto,
-					"remoteIP", RemoteIP(r),
-					"clientIP", clientIP,
+					"remoteIP", ipFromHostPort(r.RemoteAddr),
 					"status", lrw.statusCode,
 					"latency_ms", latency.Milliseconds(),
 				)
 			}()
 
-			next.ServeHTTP(lrw, r.WithContext(
-				context.WithValue(ctx, clientIPKey{}, clientIP),
-			))
+			next.ServeHTTP(lrw, r)
 		})
 	}
 }

internal/middleware/ratelimit.go

@@ -202,17 +202,24 @@ func (m *Middleware) forwardedClientAddr(
 }
 
 // rateLimitKey is the client identity every rate limiter in this
-// package buckets on: the address clientAddr attributes the request
-// to, reduced to a bucket by bucketKey — full address for IPv4, /64
-// prefix for IPv6.
+// package buckets on. Forwarded headers are honoured only when the
+// direct peer (RemoteAddr) is inside the configured trusted-proxy
+// set; otherwise the peer address itself is the key. 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.
+//
+// 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 {
-	addr, ok := m.clientAddr(r)
-	if !ok {
+	peer, err := netip.ParseAddr(ipFromHostPort(r.RemoteAddr))
+	if err != nil {
 		// 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
@@ -223,36 +230,16 @@ 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 peer, true
+		return bucketKey(peer)
 	}
 
 	if addr, ok := m.forwardedClientAddr(r); ok {
-		return addr, true
+		return bucketKey(addr)
 	}
 
-	return peer, true
+	return bucketKey(peer)
 }
 
 // tooManyRequests returns the 429 handler used by the
@@ -275,8 +262,6 @@ func (m *Middleware) tooManyRequests(
 			"path", logfield.Truncate(
 				r.URL.Path, logfield.MaxBytes,
 			),
-			"remoteIP", RemoteIP(r),
-			"clientIP", ClientIP(r),
 		)
 		http.Error(w, responseMessage, http.StatusTooManyRequests)
 	}
@@ -301,12 +286,8 @@ func (m *Middleware) tooManyRequests(
 func (m *Middleware) floodTooManyRequests(
 	logMessage, responseMessage string,
 ) http.HandlerFunc {
-	return func(w http.ResponseWriter, r *http.Request) {
-		m.log.Debug(
-			logMessage,
-			"remoteIP", RemoteIP(r),
-			"clientIP", ClientIP(r),
-		)
+	return func(w http.ResponseWriter, _ *http.Request) {
+		m.log.Debug(logMessage)
 		http.Error(w, responseMessage, http.StatusTooManyRequests)
 	}
 }