Isolate config tests from the shell; any out-of-range PORT is ErrInvalidPort (closes #94)

Config tests, and the first-boot debug log test that builds a Config,
start from an empty environment: config.ClearEnvForTest unsets every
variable the process has and, when the test ends, leaves the
environment exactly as it found it, so nothing exported in the
developer's shell changes a result and nothing a test sets outlives it.
TestEnvPositiveInt and TestEnvPort share one table runner, and
TestEnvPort checks that the bad value appears in each error.

Every out-of-range PORT now wraps ErrInvalidPort: zero, negatives,
above 65535, and numbers too large or too small for an int.

The README configuration table and the Settings page say that a
RETENTION_SWEEP_INTERVAL that does not parse, or is zero or negative,
fails startup.

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
@@ -544,8 +557,8 @@ If it is lost, run `webhooker resetpw admin` on a stopped deployment.
 ```
 
 It is a banner rather than a log line because that is the only time it
-is ever shown: as one `INFO` record it sat among the roughly 45 fx
-`PROVIDE`/`RUN`/`HOOK` lines a boot writes, and under `docker run -d`
+is ever shown: as one `INFO` record it would sit among the records fx
+writes as each start hook runs, and under `docker run -d`
 it is one line in a log subject to rotation. The database stores only
 its Argon2id hash. There is no second account and no forgot-password
 flow, so the banner and the reset command below are the only two ways
@@ -615,7 +628,8 @@ Changing a password you still know needs none of this — use
 
 `DEBUG=true` lowers the log level to `DEBUG`, which turns on every
 statement GORM runs, the two by-design lookup misses on the
-unauthenticated routes, and the rate limiter's own rejections. It is
+unauthenticated routes, the rate limiter's own rejections, and fx's
+records of building the dependency graph at startup. It is
 meant to be safe to turn on while diagnosing a live service and safe to
 paste the output of into a bug report.
 
@@ -841,9 +855,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
-   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
+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
    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 +886,8 @@ server {
     # webhooker's message.
     client_max_body_size 1m;
 
-    # $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.
+    # $remote_addr is the client. webhooker's own log names it, as
+    # clientIP, only while TRUSTED_PROXIES covers this proxy.
     access_log /var/log/nginx/webhooker.access.log combined;
 
     location / {
@@ -2473,20 +2486,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
-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`,
+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`,
 including cases built from the characters the handlers escape, and
-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.
+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.
 
 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:
@@ -2624,16 +2638,20 @@ read as more than it is:
   that type on a specific webhook, and each line it writes is bounded
   per event by the 1 MB receiver body cap. Adding one is a decision to
   spend log volume on that webhook's payloads.
-- **Two writers that do not go through `internal/logger` at all**, both
-  on standard error. `fx` prints the dependency graph and the lifecycle
-  hooks through its default console logger at startup and shutdown —
-  nothing calls `fx.WithLogger`, and `fx.New` builds that logger over
-  `os.Stderr`. The Go runtime writes a panic or a fatal error itself; a
-  panic in a background worker rather than in a request handler is the
-  case that reaches it, since nothing recovers those. Neither carries a
-  client-chosen value at a client-chosen length: the five `panic` calls
-  in this service are invariant guards over constants and over
-  `crypto/rand`.
+- **The Go runtime**, which does not go through `internal/logger`. The
+  runtime writes an unrecovered panic or a fatal error itself, as plain
+  text on standard error, and that output cannot be redirected. A panic
+  in a background worker rather than in a request handler is the case
+  that reaches it, since nothing recovers those. It carries no
+  client-chosen value at a client-chosen length: the service's own
+  `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
@@ -2824,9 +2842,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
-record the proxy's address, not the client's (see
-[Deployment behind a reverse proxy](#deployment-behind-a-reverse-proxy)).
+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)).
 
 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
@@ -2984,7 +3002,7 @@ webhooker/
 │   ├── lifecycle/
 │   │   └── lifecycle.go       # Shared stop-hook waiter, bounded by the stop context
 │   ├── logger/
-│   │   └── logger.go          # slog setup with TTY detection
+│   │   └── logger.go          # slog setup with TTY detection; fx's event logger
 │   ├── metrics/
 │   │   └── metrics.go         # Delivery Prometheus collectors, labelled by target type
 │   ├── middleware/
@@ -3065,7 +3083,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

cmd/webhooker/main.go

@@ -8,6 +8,7 @@ import (
 	"time"
 
 	"go.uber.org/fx"
+	"go.uber.org/fx/fxevent"
 	"sneak.berlin/go/webhooker/internal/config"
 	"sneak.berlin/go/webhooker/internal/database"
 	"sneak.berlin/go/webhooker/internal/datadir"
@@ -168,6 +169,19 @@ func run(stderr io.Writer) int {
 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.
+		fx.WithLogger(
+			func(l *logger.Logger, _ *config.Config) fxevent.Logger {
+				return logger.NewFxLogger(l.Get())
+			},
+		),
 		fx.Provide(
 			globals.New,
 			logger.New,

cmd/webhooker/main_test.go

@@ -2,6 +2,12 @@ package main
 
 import (
 	"bytes"
+	"encoding/json"
+	"io"
+	"log/slog"
+	"net"
+	"os"
+	"strconv"
 	"strings"
 	"testing"
 	"time"
@@ -38,6 +44,99 @@ func TestNewApp_StopTimeout(t *testing.T) {
 	require.Less(t, got, dockerStopGrace)
 }
 
+// freePort returns a loopback TCP port that was free a moment ago, by
+// taking one and releasing it.
+func freePort(t *testing.T) int {
+	t.Helper()
+
+	var listenCfg net.ListenConfig
+
+	l, err := listenCfg.Listen(t.Context(), "tcp", "127.0.0.1:0")
+	require.NoError(t, err)
+
+	addr, ok := l.Addr().(*net.TCPAddr)
+	require.True(t, ok, "listener is not TCP")
+	require.NoError(t, l.Close())
+
+	return addr.Port
+}
+
+// TestNewApp_SendsFxEventsToTheLogger starts and stops the app main
+// runs, with DEBUG=true, and reads back what reached the service's
+// logger. fx's own events must arrive there as structured records:
+// the start at INFO, and at DEBUG the records of how the graph was
+// built.
+//
+// fx holds its events back until its logger is built and then replays
+// them all at once, so the earliest of them arriving shows the replay
+// ran at DEBUG: that globals.New was provided, which fx records before
+// anything is built, and the run of logger.New, which happens before
+// the configuration sets the level.
+func TestNewApp_SendsFxEventsToTheLogger(t *testing.T) {
+	t.Setenv("DATA_DIR", t.TempDir())
+	t.Setenv("PORT", strconv.Itoa(freePort(t)))
+	t.Setenv("DEBUG", "true")
+
+	// internal/logger writes to whatever os.Stdout is when it builds
+	// its handler. A file is not a terminal, so that handler is the
+	// JSON one the service uses in production.
+	out, err := os.CreateTemp(t.TempDir(), "stdout")
+	require.NoError(t, err)
+
+	stdout := os.Stdout
+	os.Stdout = out
+
+	t.Cleanup(func() {
+		os.Stdout = stdout
+		_ = out.Close()
+	})
+
+	app := newApp()
+	require.NoError(t, app.Start(t.Context()))
+	require.NoError(t, app.Stop(t.Context()))
+
+	_, err = out.Seek(0, io.SeekStart)
+	require.NoError(t, err)
+
+	written, err := io.ReadAll(out)
+	require.NoError(t, err)
+
+	type record struct {
+		Level       string `json:"level"`
+		Msg         string `json:"msg"`
+		Name        string `json:"name"`
+		Constructor string `json:"constructor"`
+	}
+
+	var records []record
+
+	for line := range strings.Lines(string(written)) {
+		var r record
+
+		// The first-boot banner is plain text, not a record.
+		if json.Unmarshal([]byte(line), &r) == nil {
+			records = append(records, r)
+		}
+	}
+
+	const pkg = "sneak.berlin/go/webhooker/internal/"
+
+	info := slog.LevelInfo.String()
+	debug := slog.LevelDebug.String()
+
+	assert.Contains(t, records, record{Level: info, Msg: "started"})
+	assert.Contains(t, records, record{
+		Level: debug, Msg: "provided", Constructor: pkg + "globals.New()",
+	})
+	assert.Contains(t, records, record{
+		Level: debug, Msg: "run", Name: pkg + "logger.New()",
+	})
+	assert.Contains(t, records, record{Level: debug, Msg: "invoking"})
+	assert.Contains(t, records, record{
+		Level: debug, Msg: "initialized custom fxevent.Logger",
+	})
+}
+
 // TestRunRefusesLockedDataDir pins what an operator's second start
 // does. The entry point must refuse before it builds the fx graph —
 // nothing may open a database in a DATA_DIR another process holds —

go.mod

@@ -20,7 +20,7 @@ require (
 	github.com/prometheus/client_model v0.5.0
 	github.com/slok/go-http-metrics v0.11.0
 	github.com/stretchr/testify v1.11.1
-	go.uber.org/fx v1.20.1
+	go.uber.org/fx v1.24.0
 	golang.org/x/crypto v0.38.0
 	gopkg.in/yaml.v3 v3.0.1
 	gorm.io/driver/sqlite v1.5.4
@@ -42,7 +42,6 @@ require (
 	github.com/jinzhu/now v1.1.5 // indirect
 	github.com/kballard/go-shellquote v0.0.0-20180428030007-95032a82bc51 // indirect
 	github.com/klauspost/cpuid/v2 v2.2.10 // indirect
-	github.com/kr/text v0.2.0 // indirect
 	github.com/mattn/go-isatty v0.0.20 // indirect
 	github.com/mattn/go-sqlite3 v1.14.17 // indirect
 	github.com/matttproud/golang_protobuf_extensions/v2 v2.0.0 // indirect
@@ -51,10 +50,9 @@ require (
 	github.com/prometheus/procfs v0.12.0 // indirect
 	github.com/remyoudompheng/bigfft v0.0.0-20230129092748-24d4a6f8daec // indirect
 	github.com/zeebo/xxh3 v1.0.2 // indirect
-	go.uber.org/atomic v1.9.0 // indirect
-	go.uber.org/dig v1.17.0 // indirect
-	go.uber.org/multierr v1.9.0 // indirect
-	go.uber.org/zap v1.23.0 // indirect
+	go.uber.org/dig v1.19.0 // indirect
+	go.uber.org/multierr v1.10.0 // indirect
+	go.uber.org/zap v1.26.0 // indirect
 	golang.org/x/mod v0.17.0 // indirect
 	golang.org/x/sync v0.14.0 // indirect
 	golang.org/x/sys v0.47.0 // indirect

go.sum

@@ -1,7 +1,5 @@
 github.com/99designs/basicauth-go v0.0.0-20230316000542-bf6f9cbbf0f8 h1:nMpu1t4amK3vJWBibQ5X/Nv0aXL+b69TQf2uK5PH7Go=
 github.com/99designs/basicauth-go v0.0.0-20230316000542-bf6f9cbbf0f8/go.mod h1:3cARGAK9CfW3HoxCy1a0G4TKrdiKke8ftOMEOHyySYs=
-github.com/benbjohnson/clock v1.3.0 h1:ip6w0uFQkncKQ979AypyG0ER7mqUSBdKLOgAle/AT8A=
-github.com/benbjohnson/clock v1.3.0/go.mod h1:J11/hYXuz8f4ySSvYwY0FKfm+ezbsZBKZxNJlLklBHA=
 github.com/beorn7/perks v1.0.1 h1:VlbKKnNfV8bJzeqoa4cOKqO6bYr3WgKZxO8Z16+hsOM=
 github.com/beorn7/perks v1.0.1/go.mod h1:G2ZrVWU2WbWT9wwq4/hrbKbnv/1ERSJQ0ibhJ6rlkpw=
 github.com/cespare/xxhash/v2 v2.2.0 h1:DC2CZ1Ep5Y4k3ZQ899DldepgrayRUGE6BBZ/cd9Cj44=
@@ -12,9 +10,6 @@ github.com/chromedp/chromedp v0.16.0 h1:rOO4deOm4CbZgBCa8mD9g2rDyIoNs0BkgvNrlbp5
 github.com/chromedp/chromedp v0.16.0/go.mod h1:rbuGKFT1vMcFcFqKfPIO1GpX/N+2s8onm2qMxZLbU5U=
 github.com/chromedp/sysutil v1.1.0 h1:PUFNv5EcprjqXZD9nJb9b/c9ibAbxiYo4exNWZyipwM=
 github.com/chromedp/sysutil v1.1.0/go.mod h1:WiThHUdltqCNKGc4gaU50XgYjwjYIhKWoHGPTUfWTJ8=
-github.com/creack/pty v1.1.9/go.mod h1:oKZEueFk5CKHvIhNR5MUki03XCEU+Q6VDXinZuGJ33E=
-github.com/davecgh/go-spew v1.1.0/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38=
-github.com/davecgh/go-spew v1.1.1/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38=
 github.com/davecgh/go-spew v1.1.2-0.20180830191138-d8f796af33cc h1:U9qPSI2PIWSS1VwoXQT9A3Wy9MM3WgvqSxFWenqJduM=
 github.com/davecgh/go-spew v1.1.2-0.20180830191138-d8f796af33cc/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38=
 github.com/dustin/go-humanize v1.0.1 h1:GzkhY7T5VNhEkwH0PVJgjz+fX1rhBrR7pRT3mDkpeCY=
@@ -83,7 +78,6 @@ github.com/pingcap/errors v0.11.4 h1:lFuQV/oaUMGcD2tqt+01ROSmJs75VG1ToEOkZIZ4nE4
 github.com/pingcap/errors v0.11.4/go.mod h1:Oi8TUi2kEtXXLMJk9l1cGmz20kV3TaQ0usTwv5KuLY8=
 github.com/pkg/errors v0.9.1 h1:FEBLx1zS214owpjy7qsBeixbURkuhQAwrK5UwLGTwt4=
 github.com/pkg/errors v0.9.1/go.mod h1:bwawxfHBFNV+L2hUp1rHADufV3IMtnDRdf1r5NINEl0=
-github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4=
 github.com/pmezard/go-difflib v1.0.1-0.20181226105442-5d4384ee4fb2 h1:Jamvg5psRIccs7FGNTlIRMkT8wgtp5eCXdBlqhYGL6U=
 github.com/pmezard/go-difflib v1.0.1-0.20181226105442-5d4384ee4fb2/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4=
 github.com/prometheus/client_golang v1.18.0 h1:HzFfmkOzH5Q8L8G+kSJKUx5dtG87sewO+FoDDqP5Tbk=
@@ -100,28 +94,24 @@ github.com/rogpeppe/go-internal v1.10.0 h1:TMyTOH3F/DB16zRVcYyreMH6GnZZrwQVAoYjR
 github.com/rogpeppe/go-internal v1.10.0/go.mod h1:UQnix2H7Ngw/k4C5ijL5+65zddjncjaFoBhdsK/akog=
 github.com/slok/go-http-metrics v0.11.0 h1:ABJUpekCZSkQT1wQrFvS4kGbhea/w6ndFJaWJeh3zL0=
 github.com/slok/go-http-metrics v0.11.0/go.mod h1:ZGKeYG1ET6TEJpQx18BqAJAvxw9jBAZXCHU7bWQqqAc=
-github.com/stretchr/objx v0.1.0/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+wExME=
 github.com/stretchr/objx v0.5.2 h1:xuMeJ0Sdp5ZMRXx/aWO6RZxdr3beISkG5/G/aIRr3pY=
 github.com/stretchr/objx v0.5.2/go.mod h1:FRsXN1f5AsAjCGJKqEizvkpNtU+EGNCLh3NxZ/8L+MA=
-github.com/stretchr/testify v1.3.0/go.mod h1:M5WIy9Dh21IEIfnGCwXGc5bZfKNJtfHm1UVUgZn+9EI=
 github.com/stretchr/testify v1.11.1 h1:7s2iGBzp5EwR7/aIZr8ao5+dra3wiQyKjjFuvgVKu7U=
 github.com/stretchr/testify v1.11.1/go.mod h1:wZwfW3scLgRK+23gO65QZefKpKQRnfz6sD981Nm4B6U=
 github.com/zeebo/assert v1.3.0 h1:g7C04CbJuIDKNPFHmsk4hwZDO5O+kntRxzaUoNXj+IQ=
 github.com/zeebo/assert v1.3.0/go.mod h1:Pq9JiuJQpG8JLJdtkwrJESF0Foym2/D9XMU5ciN/wJ0=
 github.com/zeebo/xxh3 v1.0.2 h1:xZmwmqxHZA8AI603jOQ0tMqmBr9lPeFwGg6d+xy9DC0=
 github.com/zeebo/xxh3 v1.0.2/go.mod h1:5NWz9Sef7zIDm2JHfFlcQvNekmcEl9ekUZQQKCYaDcA=
-go.uber.org/atomic v1.9.0 h1:ECmE8Bn/WFTYwEW/bpKD3M8VtR/zQVbavAoalC1PYyE=
-go.uber.org/atomic v1.9.0/go.mod h1:fEN4uk6kAWBTFdckzkM89CLk9XfWZrxpCo0nPH17wJc=
-go.uber.org/dig v1.17.0 h1:5Chju+tUvcC+N7N6EV08BJz41UZuO3BmHcN4A287ZLI=
-go.uber.org/dig v1.17.0/go.mod h1:rTxpf7l5I0eBTlE6/9RL+lDybC7WFwY2QH55ZSjy1mU=
-go.uber.org/fx v1.20.1 h1:zVwVQGS8zYvhh9Xxcu4w1M6ESyeMzebzj2NbSayZ4Mk=
-go.uber.org/fx v1.20.1/go.mod h1:iSYNbHf2y55acNCwCXKx7LbWb5WG1Bnue5RDXz1OREg=
-go.uber.org/goleak v1.1.11 h1:wy28qYRKZgnJTxGxvye5/wgWr1EKjmUDGYox5mGlRlI=
-go.uber.org/goleak v1.1.11/go.mod h1:cwTWslyiVhfpKIDGSZEM2HlOvcqm+tG4zioyIeLoqMQ=
-go.uber.org/multierr v1.9.0 h1:7fIwc/ZtS0q++VgcfqFDxSBZVv/Xo49/SYnDFupUwlI=
-go.uber.org/multierr v1.9.0/go.mod h1:X2jQV1h+kxSjClGpnseKVIxpmcjrj7MNnI0bnlfKTVQ=
-go.uber.org/zap v1.23.0 h1:OjGQ5KQDEUawVHxNwQgPpiypGHOxo2mNZsOqTak4fFY=
-go.uber.org/zap v1.23.0/go.mod h1:D+nX8jyLsMHMYrln8A0rJjFt/T/9/bGgIhAqxv5URuY=
+go.uber.org/dig v1.19.0 h1:BACLhebsYdpQ7IROQ1AGPjrXcP5dF80U3gKoFzbaq/4=
+go.uber.org/dig v1.19.0/go.mod h1:Us0rSJiThwCv2GteUN0Q7OKvU7n5J4dxZ9JKUXozFdE=
+go.uber.org/fx v1.24.0 h1:wE8mruvpg2kiiL1Vqd0CC+tr0/24XIB10Iwp2lLWzkg=
+go.uber.org/fx v1.24.0/go.mod h1:AmDeGyS+ZARGKM4tlH4FY2Jr63VjbEDJHtqXTGP5hbo=
+go.uber.org/goleak v1.2.0 h1:xqgm/S+aQvhWFTtR0XK3Jvg7z8kGV8P4X14IzwN3Eqk=
+go.uber.org/goleak v1.2.0/go.mod h1:XJYK+MuIchqpmGmUSAzotztawfKvYLUIgg7guXrwVUo=
+go.uber.org/multierr v1.10.0 h1:S0h4aNzvfcFsC3dRF1jLoaov7oRaKqRGC/pUEJ2yvPQ=
+go.uber.org/multierr v1.10.0/go.mod h1:20+QtiLqy0Nd6FdQB9TLXag12DsQkrbs3htMFfDN80Y=
+go.uber.org/zap v1.26.0 h1:sI7k6L95XOKS281NhVKOFCUNIvv9e0w4BF8N3u+tCRo=
+go.uber.org/zap v1.26.0/go.mod h1:dtElttAiwGvoJ/vj4IwHBS/gXsEu/pZ50mUIRWuG0so=
 golang.org/x/crypto v0.38.0 h1:jt+WWG8IZlBnVbomuhg2Mdq0+BBQaHbtqHEFEigjUV8=
 golang.org/x/crypto v0.38.0/go.mod h1:MvrbAqul58NNYPKnOra203SB9vpuZW0e+RRZV+Ggqjw=
 golang.org/x/mod v0.17.0 h1:zY54UmvipHiNd+pm+m0x9KhZ9hl1/7QNMyxXbc6ICqA=

internal/config/testing.go

@@ -7,14 +7,18 @@ import (
 )
 
 // ClearEnvForTest unsets every variable in the process environment
-// for the rest of the test and puts each back when the test ends, so
-// a test sees only the variables it sets itself, not whatever the
-// developer's shell exports.
+// for the rest of the test, so a test sees only the variables it sets
+// itself, not whatever the developer's shell exports. When the test
+// ends it leaves the environment exactly as it found it: each variable
+// it unset is put back, and any variable added since is removed.
 func ClearEnvForTest(t *testing.T) {
 	t.Helper()
 
+	present := make(map[string]bool)
+
 	for _, entry := range os.Environ() {
 		key, _, _ := strings.Cut(entry, "=")
+		present[key] = true
 
 		// t.Setenv registers the restore; the Unsetenv after it is
 		// what makes the key absent, since a key set to the empty
@@ -27,4 +31,20 @@ func ClearEnvForTest(t *testing.T) {
 			t.Fatalf("unsetting %s: %v", key, err)
 		}
 	}
+
+	// A variable the test adds other than through t.Setenv, as loading
+	// a .env file does, has no restore of its own.
+	t.Cleanup(func() {
+		for _, entry := range os.Environ() {
+			key, _, _ := strings.Cut(entry, "=")
+			if present[key] {
+				continue
+			}
+
+			err := os.Unsetenv(key)
+			if err != nil {
+				t.Errorf("unsetting %s: %v", key, err)
+			}
+		}
+	})
 }

internal/config/testing_test.go

@@ -0,0 +1,36 @@
+package config_test
+
+import (
+	"os"
+	"testing"
+
+	"github.com/stretchr/testify/assert"
+	"github.com/stretchr/testify/require"
+	"sneak.berlin/go/webhooker/internal/config"
+)
+
+// TestClearEnvForTest_RemovesAddedVariables pins that a variable set
+// after the clear other than through t.Setenv, as a test's .env file
+// sets one, is gone once the test ends, so it cannot reach the tests
+// that run after it.
+//
+//nolint:paralleltest // ClearEnvForTest uses t.Setenv.
+func TestClearEnvForTest_RemovesAddedVariables(t *testing.T) {
+	// The outer clear keeps a value of the key exported in the shell
+	// from making it a variable the inner clear has to put back.
+	config.ClearEnvForTest(t)
+
+	t.Run("loads a .env file after the clear", func(t *testing.T) {
+		config.ClearEnvForTest(t)
+
+		path := writeDotEnv(t, dotEnvKey+"=from-dot-env\n")
+		require.NoError(t, config.LoadDotEnvFileForTest(path))
+		require.Equal(t, "from-dot-env", os.Getenv(dotEnvKey))
+	})
+
+	_, present := os.LookupEnv(dotEnvKey)
+	assert.False(
+		t, present,
+		"a variable set after the clear must not outlive the test",
+	)
+}

internal/database/retention.go

@@ -184,16 +184,6 @@ 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) {
@@ -212,6 +202,13 @@ 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(
@@ -223,11 +220,6 @@ 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 rescued by the forever skip",
+		"the test value must not be treated as retain-forever",
 	)
 
 	webhookID := createWebhook(

internal/handlers/source_management.go

@@ -41,71 +41,51 @@ type WebhookListItem struct {
 // errMissingURL signals that a required URL was not provided.
 var errMissingURL = errors.New("missing URL")
 
-// 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.
+// 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.
 //
 // 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 an error rather than a silently substituted default.
+// or negative is refused rather than silently given a 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 a 400.
+// above that ceiling is therefore refused, and the message names the
+// ceiling rather than implying the input was not a number.
 //
 // 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, error) {
+func parseRetentionDays(raw string, fallback int) (int, string) {
 	raw = strings.TrimSpace(raw)
 	if raw == "" {
-		return fallback, nil
+		return fallback, ""
 	}
 
 	v, err := strconv.Atoi(raw)
 	if err != nil || v < 0 {
-		return 0, errInvalidRetention
+		return 0, "Retention must be a whole number of days, or 0 to " +
+			"retain events forever."
 	}
 
 	if v >= database.RetentionForeverDays {
-		return database.RetentionForeverDays, nil
+		return database.RetentionForeverDays, ""
 	}
 
 	if v > database.MaxFiniteRetentionDays {
-		return 0, errRetentionTooLarge
+		return 0, "Retention must be at most " +
+			strconv.Itoa(database.MaxFiniteRetentionDays) +
+			" days, or 0 to retain events forever."
 	}
 
-	return v, nil
+	return v, ""
 }
 
 // DeliveryView is the display-safe projection of a delivery
@@ -361,16 +341,13 @@ func (h *Handlers) HandleSourceCreateSubmit() http.HandlerFunc {
 			return
 		}
 
-		retentionDays, retErr := parseRetentionDays(
+		retentionDays, errMsg := parseRetentionDays(
 			retentionStr, database.DefaultRetentionDays,
 		)
-		if retErr != nil {
+		if errMsg != "" {
 			h.renderTemplateStatus(
 				w, r, "sources_new.html",
-				newSourceFormData(
-					retentionErrorMessage(retErr),
-					name, description,
-				),
+				newSourceFormData(errMsg, name, description),
 				http.StatusBadRequest,
 			)
 
@@ -655,13 +632,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, retErr := parseRetentionDays(
+	retentionDays, errMsg := parseRetentionDays(
 		r.PostFormValue("retention_days"), webhook.RetentionDays,
 	)
-	if retErr != nil {
+	if errMsg != "" {
 		data := map[string]any{
 			tmplKeyWebhook: webhook,
-			tmplKeyError:   retentionErrorMessage(retErr),
+			tmplKeyError:   errMsg,
 		}
 
 		h.renderTemplateStatus(w, r, "source_edit.html", data, http.StatusBadRequest)

internal/handlers/source_management_test.go

@@ -368,31 +368,42 @@ 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.
+// out of range. A value above the sentinel is stored as the sentinel.
 func TestHandleSourceCreateSubmit_SentinelIsAcceptedAsForever(
 	t *testing.T,
 ) {
 	t.Parallel()
 
-	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,
+	for _, days := range []int{
 		database.RetentionForeverDays,
-		storedRetentionDays(t, env.db, wh.ID),
-	)
+		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),
+			)
+		})
+	}
 }
 
 // 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.
+// form. Both values carry HTML-special characters, which must come
+// back escaped rather than as markup.
 func TestHandleSourceCreateSubmit_RejectedFormKeepsUserInput(
 	t *testing.T,
 ) {
@@ -401,8 +412,8 @@ func TestHandleSourceCreateSubmit_RejectedFormKeepsUserInput(
 	env := setupSourceTest(t)
 
 	const (
-		name        = "kept-name"
-		description = "a description worth not losing"
+		name        = `kept"><b>name`
+		description = `a </textarea> worth not losing`
 	)
 
 	form := url.Values{}
@@ -419,8 +430,10 @@ func TestHandleSourceCreateSubmit_RejectedFormKeepsUserInput(
 
 	body := w.Body.String()
 
-	assert.Contains(t, body, `value="`+name+`"`)
-	assert.Contains(t, body, description)
+	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)
 }
 
 // submitEdit posts the webhook edit form for the given webhook.

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/logger/logger.go

@@ -9,6 +9,7 @@ import (
 	"time"
 
 	"go.uber.org/fx"
+	"go.uber.org/fx/fxevent"
 	"sneak.berlin/go/webhooker/internal/globals"
 )
 
@@ -106,3 +107,40 @@ func (l *Logger) Identify() {
 func (l *Logger) Writer() io.Writer {
 	return os.Stdout
 }
+
+// FxLogger writes fx's own events through a slog logger: how the
+// dependency graph was built at DEBUG, since it repeats on every
+// start; the start and stop hooks, the start itself and the signal
+// that stops the service at INFO; every failure at ERROR.
+//
+// The formatting is fx's own fxevent.SlogLogger. That logger takes a
+// single level for every event that is not a failure, so FxLogger
+// holds one at each level and picks between them.
+type FxLogger struct {
+	graph     *fxevent.SlogLogger
+	lifecycle *fxevent.SlogLogger
+}
+
+// NewFxLogger returns an FxLogger that writes through log.
+func NewFxLogger(log *slog.Logger) *FxLogger {
+	graph := &fxevent.SlogLogger{Logger: log}
+	graph.UseLogLevel(slog.LevelDebug)
+
+	lifecycle := &fxevent.SlogLogger{Logger: log}
+	lifecycle.UseLogLevel(slog.LevelInfo)
+
+	return &FxLogger{graph: graph, lifecycle: lifecycle}
+}
+
+// LogEvent implements fxevent.Logger.
+func (f *FxLogger) LogEvent(event fxevent.Event) {
+	switch event.(type) {
+	case *fxevent.Supplied, *fxevent.Provided, *fxevent.Replaced,
+		*fxevent.Decorated, *fxevent.BeforeRun, *fxevent.Run,
+		*fxevent.Invoking, *fxevent.Invoked,
+		*fxevent.LoggerInitialized:
+		f.graph.LogEvent(event)
+	default:
+		f.lifecycle.LogEvent(event)
+	}
+}

internal/logger/logger_test.go

@@ -1,13 +1,23 @@
 package logger_test
 
 import (
+	"bytes"
+	"encoding/json"
+	"errors"
+	"log/slog"
 	"testing"
 
+	"github.com/stretchr/testify/assert"
+	"github.com/stretchr/testify/require"
+	"go.uber.org/fx"
+	"go.uber.org/fx/fxevent"
 	"go.uber.org/fx/fxtest"
 	"sneak.berlin/go/webhooker/internal/globals"
 	"sneak.berlin/go/webhooker/internal/logger"
 )
 
+var errStopHook = errors.New("stop hook failed on purpose")
+
 func testGlobals() *globals.Globals {
 	return &globals.Globals{
 		Appname: "test-app",
@@ -57,3 +67,47 @@ func TestEnableDebugLogging(t *testing.T) {
 	// Test debug logging
 	l.Get().Debug("debug message", "test", true)
 }
+
+// TestFxLogger_Levels starts and stops an fx app that reports its own
+// events through NewFxLogger, as cmd/webhooker does, and reads back
+// what reached the handler: the graph at DEBUG, the start at INFO and
+// a failed stop hook at ERROR, each as a structured record.
+func TestFxLogger_Levels(t *testing.T) {
+	t.Parallel()
+
+	var out bytes.Buffer
+
+	log := slog.New(slog.NewJSONHandler(
+		&out, &slog.HandlerOptions{Level: slog.LevelDebug},
+	))
+
+	app := fx.New(
+		fx.WithLogger(func() fxevent.Logger {
+			return logger.NewFxLogger(log)
+		}),
+		fx.Invoke(func(lc fx.Lifecycle) {
+			lc.Append(fx.StopHook(func() error { return errStopHook }))
+		}),
+	)
+
+	require.NoError(t, app.Start(t.Context()))
+	require.ErrorIs(t, app.Stop(t.Context()), errStopHook)
+
+	levels := map[string]string{}
+
+	decoder := json.NewDecoder(&out)
+	for decoder.More() {
+		var record struct {
+			Level string `json:"level"`
+			Msg   string `json:"msg"`
+		}
+
+		require.NoError(t, decoder.Decode(&record))
+
+		levels[record.Msg] = record.Level
+	}
+
+	assert.Equal(t, "DEBUG", levels["provided"])
+	assert.Equal(t, "INFO", levels["started"])
+	assert.Equal(t, "ERROR", levels["OnStop hook failed"])
+}

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
-	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 +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
-	// 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 +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
-		// accepted connection rather than by the client, and
+		// the access log. remoteIP and clientIP are the same
+		// 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
-	// 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.
+	// 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.
 	//
 	// 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,
-	// which puts its worst case at 2037.
+	// The text handler's fixed portion is 351, the smaller of the two,
+	// 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,44 +202,61 @@ func (m *Middleware) forwardedClientAddr(
 }
 
 // rateLimitKey is the client identity every rate limiter in this
-// 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.
+// package buckets on: the address clientAddr attributes the request
+// to, 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))
-	if err != nil {
+	addr, ok := m.clientAddr(r)
+	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
 		// path cannot silently collapse unrelated clients
 		// together. On a Unix-socket listener every peer
 		// carries the same RemoteAddr and so shares one bucket,
-		// which is the fail-closed direction.
+		// which is the fail-closed direction. An empty RemoteAddr
+		// is a different case, which net/http never produces for
+		// a TCP listener and only a hand-built request carries,
+		// but it fails closed the same way: every such request
+		// shares the one bucket keyed on the empty 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 +279,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 +305,12 @@ func (m *Middleware) tooManyRequests(
 func (m *Middleware) floodTooManyRequests(
 	logMessage, responseMessage string,
 ) http.HandlerFunc {
-	return func(w http.ResponseWriter, _ *http.Request) {
-		m.log.Debug(logMessage)
+	return func(w http.ResponseWriter, r *http.Request) {
+		m.log.Debug(
+			logMessage,
+			"remoteIP", RemoteIP(r),
+			"clientIP", ClientIP(r),
+		)
 		http.Error(w, responseMessage, http.StatusTooManyRequests)
 	}
 }

internal/middleware/ratelimit_test.go

@@ -1012,6 +1012,23 @@ func TestRateLimitKey_UnparseablePeerKeepsDistinctBuckets(
 	)
 }
 
+// TestRateLimitKey_EmptyPeerSharesOneBucket pins what the fallback
+// does with an empty RemoteAddr: it keys on the empty string, so every
+// such request shares one bucket. That is the fail-closed direction
+// and is kept on purpose; only a hand-built request carries an empty
+// RemoteAddr.
+func TestRateLimitKey_EmptyPeerSharesOneBucket(t *testing.T) {
+	t.Parallel()
+
+	m := rateLimitMiddleware(t, &config.Config{})
+
+	assert.Empty(
+		t, clientKeyFor(t, m, ""),
+		"every peer with an empty RemoteAddr must key on the "+
+			"empty string and so share one bucket",
+	)
+}
+
 // TestPostRateLimit_IPv6SharesBucketWithinSlash64 is the behavioural
 // half, and the regression test for the bypass itself: a client that
 // rotates source addresses inside its own routed /64 must stay in one