Clear the environment in the cmd/webhooker tests that build a Config (closes #452)

The two cmd/webhooker tests that build the app graph, TestNewApp_StopTimeout and TestNewApp_SendsFxEventsToTheLogger, built a Config without clearing the environment, so a variable exported in the developer's shell changed their result: a METRICS_USERNAME without METRICS_PASSWORD failed the second. Both now call config.ClearEnvForTest before setting their own variables, as the config tests and the first-boot test already do. No other test outside internal/config builds a Config through config.New. Test change only.

Model: opus-5-5

README.md

@@ -139,7 +139,7 @@ TTY detection, and security headers are always applied.
 | `METRICS_USERNAME`      | Basic auth username for `/metrics`. Must be set together with `METRICS_PASSWORD`; one without the other fails startup | `""`     |
 | `METRICS_PASSWORD`      | Basic auth password for `/metrics`. Must be set together with `METRICS_USERNAME`; one without the other fails startup | `""`     |
 | `SENTRY_DSN`            | Sentry error reporting DSN. Unset leaves error reporting off; a value the Sentry SDK cannot parse fails startup rather than serving with reporting silently off | `""`     |
-| `RETENTION_SWEEP_INTERVAL` | How often the retention reaper and archive sweeper run (Go duration, must be positive) | `1h` |
+| `RETENTION_SWEEP_INTERVAL` | How often the retention reaper and archive sweeper run (Go duration, must be positive). A value that does not parse, or is zero or negative, fails startup | `1h` |
 | `SESSION_IDLE_TIMEOUT`  | Idle session timeout (Go duration)  | `24h`    |
 | `RECEIVER_RATE_LIMIT`   | Receiver requests/minute per IP per entrypoint (10x that per IP across the route) | `120` |
 | `TRUSTED_PROXIES`       | CIDRs whose forwarded headers are trusted. A set value replaces the default. If any client can reach webhooker, or the proxy in front of it, from an RFC 1918 source address, set it to the proxy's address alone. See [Trusted proxies](#trusted-proxies) | `10.0.0.0/8,172.16.0.0/12,192.168.0.0/16` (RFC 1918) |
@@ -557,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
+is ever shown: as one `INFO` record it would sit among the records fx
-`PROVIDE`/`RUN`/`HOOK` lines a boot writes, and under `docker run -d`
+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
@@ -628,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.
 
@@ -2637,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
+- **The Go runtime**, which does not go through `internal/logger`. The
-  on standard error. `fx` prints the dependency graph and the lifecycle
+  runtime writes an unrecovered panic or a fatal error itself, as plain
-  hooks through its default console logger at startup and shutdown —
+  text on standard error, and that output cannot be redirected. A panic
-  nothing calls `fx.WithLogger`, and `fx.New` builds that logger over
+  in a background worker rather than in a request handler is the case
-  `os.Stderr`. The Go runtime writes a panic or a fatal error itself; a
+  that reaches it, since nothing recovers those. It carries no
-  panic in a background worker rather than in a request handler is the
+  client-chosen value at a client-chosen length: the service's own
-  case that reaches it, since nothing recovers those. Neither carries a
+  `panic` calls are invariant guards over constants and over
-  client-chosen value at a client-chosen length: the five `panic` calls
+  `crypto/rand`, apart from the one that hands `http.ErrAbortHandler`
-  in this service are invariant guards over constants and over
+  back to `net/http`, described below.
-  `crypto/rand`.
+- **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
@@ -2937,7 +2942,8 @@ webhooker/
 │   ├── resetpw/
 │   │   └── resetpw.go         # `webhooker resetpw`: set an account's password, stopped deployments only
 │   ├── config/
-│   │   └── config.go          # Configuration loading from environment variables
+│   │   ├── config.go          # Configuration loading from environment variables
+│   │   └── testing.go         # ClearEnvForTest: an empty environment for one test
 │   ├── database/
 │   │   ├── base_model.go      # BaseModel with UUID primary keys
 │   │   ├── database.go        # GORM connection, migrations, admin seed
@@ -2996,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/

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,12 +2,19 @@ package main
 
 import (
 	"bytes"
+	"encoding/json"
+	"io"
+	"log/slog"
+	"net"
+	"os"
+	"strconv"
 	"strings"
 	"testing"
 	"time"
 
 	"github.com/stretchr/testify/assert"
 	"github.com/stretchr/testify/require"
+	"sneak.berlin/go/webhooker/internal/config"
 	"sneak.berlin/go/webhooker/internal/datadir"
 	"sneak.berlin/go/webhooker/internal/resetpw"
 	"sneak.berlin/go/webhooker/internal/server"
@@ -30,6 +37,7 @@ const dockerStopGrace = 10 * time.Second
 // fx.New applies options before it executes invokes, so the timeout
 // is set whether or not the graph itself can be constructed here.
 func TestNewApp_StopTimeout(t *testing.T) {
+	config.ClearEnvForTest(t)
 	t.Setenv("DATA_DIR", t.TempDir())
 
 	got := newApp().StopTimeout()
@@ -38,6 +46,100 @@ 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) {
+	config.ClearEnvForTest(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.19.0 // indirect
-	go.uber.org/dig v1.17.0 // indirect
+	go.uber.org/multierr v1.10.0 // indirect
-	go.uber.org/multierr v1.9.0 // indirect
+	go.uber.org/zap v1.26.0 // indirect
-	go.uber.org/zap v1.23.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/dig v1.19.0 h1:BACLhebsYdpQ7IROQ1AGPjrXcP5dF80U3gKoFzbaq/4=
-go.uber.org/atomic v1.9.0/go.mod h1:fEN4uk6kAWBTFdckzkM89CLk9XfWZrxpCo0nPH17wJc=
+go.uber.org/dig v1.19.0/go.mod h1:Us0rSJiThwCv2GteUN0Q7OKvU7n5J4dxZ9JKUXozFdE=
-go.uber.org/dig v1.17.0 h1:5Chju+tUvcC+N7N6EV08BJz41UZuO3BmHcN4A287ZLI=
+go.uber.org/fx v1.24.0 h1:wE8mruvpg2kiiL1Vqd0CC+tr0/24XIB10Iwp2lLWzkg=
-go.uber.org/dig v1.17.0/go.mod h1:rTxpf7l5I0eBTlE6/9RL+lDybC7WFwY2QH55ZSjy1mU=
+go.uber.org/fx v1.24.0/go.mod h1:AmDeGyS+ZARGKM4tlH4FY2Jr63VjbEDJHtqXTGP5hbo=
-go.uber.org/fx v1.20.1 h1:zVwVQGS8zYvhh9Xxcu4w1M6ESyeMzebzj2NbSayZ4Mk=
+go.uber.org/goleak v1.2.0 h1:xqgm/S+aQvhWFTtR0XK3Jvg7z8kGV8P4X14IzwN3Eqk=
-go.uber.org/fx v1.20.1/go.mod h1:iSYNbHf2y55acNCwCXKx7LbWb5WG1Bnue5RDXz1OREg=
+go.uber.org/goleak v1.2.0/go.mod h1:XJYK+MuIchqpmGmUSAzotztawfKvYLUIgg7guXrwVUo=
-go.uber.org/goleak v1.1.11 h1:wy28qYRKZgnJTxGxvye5/wgWr1EKjmUDGYox5mGlRlI=
+go.uber.org/multierr v1.10.0 h1:S0h4aNzvfcFsC3dRF1jLoaov7oRaKqRGC/pUEJ2yvPQ=
-go.uber.org/goleak v1.1.11/go.mod h1:cwTWslyiVhfpKIDGSZEM2HlOvcqm+tG4zioyIeLoqMQ=
+go.uber.org/multierr v1.10.0/go.mod h1:20+QtiLqy0Nd6FdQB9TLXag12DsQkrbs3htMFfDN80Y=
-go.uber.org/multierr v1.9.0 h1:7fIwc/ZtS0q++VgcfqFDxSBZVv/Xo49/SYnDFupUwlI=
+go.uber.org/zap v1.26.0 h1:sI7k6L95XOKS281NhVKOFCUNIvv9e0w4BF8N3u+tCRo=
-go.uber.org/multierr v1.9.0/go.mod h1:X2jQV1h+kxSjClGpnseKVIxpmcjrj7MNnI0bnlfKTVQ=
+go.uber.org/zap v1.26.0/go.mod h1:dtElttAiwGvoJ/vj4IwHBS/gXsEu/pZ50mUIRWuG0so=
-go.uber.org/zap v1.23.0 h1:OjGQ5KQDEUawVHxNwQgPpiypGHOxo2mNZsOqTak4fFY=
-go.uber.org/zap v1.23.0/go.mod h1:D+nX8jyLsMHMYrln8A0rJjFt/T/9/bGgIhAqxv5URuY=
 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/config.go

@@ -80,8 +80,7 @@ const (
 	// process over a Docker network or a private LAN connects from.
 	defaultTrustedProxies = "10.0.0.0/8,172.16.0.0/12,192.168.0.0/16"
 
-	// maxPort is the highest valid TCP port number. The lower
+	// maxPort is the highest valid TCP port number.
-	// bound (at least 1) is enforced by envPositiveInt.
 	maxPort = 65535
 
 	// mappedV4Offset is the number of leading bits an IPv4-mapped
@@ -105,7 +104,7 @@ var ErrInvalidEnvironment = errors.New("invalid environment")
 var ErrNonPositiveValue = errors.New("value must be positive")
 
 // ErrInvalidPort is returned when an environment variable holding a
-// TCP port number is set above the valid port range.
+// TCP port number is set to a number outside 1 to 65535.
 var ErrInvalidPort = errors.New("invalid port")
 
 // ErrInvalidCIDR is returned when an environment variable holding a
@@ -363,17 +362,27 @@ func envPositiveInt(
 // envPort returns the value of the named environment variable parsed
 // as a TCP port number. Returns defaultValue if not set. A set value
 // that is unparseable, below 1, or above maxPort is a hard error
-// naming the key and the bad value.
+// naming the key and the bad value; every out-of-range value wraps
+// ErrInvalidPort, including one too large or too small for an int.
 func envPort(key string, defaultValue int) (int, error) {
-	port, err := envPositiveInt(key, defaultValue)
+	v := os.Getenv(key)
-	if err != nil {
+	if v == "" {
-		return 0, err
+		return defaultValue, nil
 	}
 
-	if port > maxPort {
+	// strconv.ErrRange means a number too large or too small for an
+	// int, which is outside the port range as well.
+	port, err := strconv.Atoi(v)
+	if err != nil && !errors.Is(err, strconv.ErrRange) {
 		return 0, fmt.Errorf(
-			"%w: %s must be at most %d, got %d",
+			"invalid integer for %s: %q: %w", key, v, err,
-			ErrInvalidPort, key, maxPort, port,
+		)
+	}
+
+	if err != nil || port < 1 || port > maxPort {
+		return 0, fmt.Errorf(
+			"%w: %s must be from 1 to %d, got %q",
+			ErrInvalidPort, key, maxPort, v,
 		)
 	}
 

internal/config/config_test.go

@@ -3,7 +3,6 @@ package config_test
 import (
 	"bytes"
 	"log/slog"
-	"os"
 	"testing"
 	"time"
 
@@ -71,14 +70,12 @@ func TestEnvironmentConfig(t *testing.T) {
 		t.Run(tt.name, func(t *testing.T) {
 			// Cannot use t.Parallel() here because t.Setenv
 			// is incompatible with parallel subtests.
+			config.ClearEnvForTest(t)
+
 			if tt.envValue != "" {
 				t.Setenv(
 					"WEBHOOKER_ENVIRONMENT", tt.envValue,
 				)
-			} else {
-				require.NoError(t, os.Unsetenv(
-					"WEBHOOKER_ENVIRONMENT",
-				))
 			}
 
 			for k, v := range tt.envVars {
@@ -199,14 +196,11 @@ func TestRetentionSweepInterval(t *testing.T) {
 		t.Run(tt.name, func(t *testing.T) {
 			// Cannot use t.Parallel() here because t.Setenv
 			// is incompatible with parallel subtests.
+			config.ClearEnvForTest(t)
 			t.Setenv("WEBHOOKER_ENVIRONMENT", "dev")
 
 			if tt.set {
 				t.Setenv("RETENTION_SWEEP_INTERVAL", tt.value)
-			} else {
-				require.NoError(t, os.Unsetenv(
-					"RETENTION_SWEEP_INTERVAL",
-				))
 			}
 
 			if tt.expectError {
@@ -341,14 +335,11 @@ func TestSessionIdleTimeout(t *testing.T) {
 		t.Run(tt.name, func(t *testing.T) {
 			// Cannot use t.Parallel() here because t.Setenv
 			// is incompatible with parallel subtests.
+			config.ClearEnvForTest(t)
 			t.Setenv("WEBHOOKER_ENVIRONMENT", "dev")
 
 			if tt.set {
 				t.Setenv("SESSION_IDLE_TIMEOUT", tt.value)
-			} else {
-				require.NoError(t, os.Unsetenv(
-					"SESSION_IDLE_TIMEOUT",
-				))
 			}
 
 			if tt.expectError {
@@ -397,16 +388,12 @@ func TestDefaultDataDir(t *testing.T) {
 		t.Run("env="+name, func(t *testing.T) {
 			// Cannot use t.Parallel() here because t.Setenv
 			// is incompatible with parallel subtests.
+			config.ClearEnvForTest(t)
+
 			if env != "" {
 				t.Setenv("WEBHOOKER_ENVIRONMENT", env)
-			} else {
-				require.NoError(t, os.Unsetenv(
-					"WEBHOOKER_ENVIRONMENT",
-				))
 			}
 
-			require.NoError(t, os.Unsetenv("DATA_DIR"))
-
 			var cfg *config.Config
 
 			app := fxtest.New(
@@ -446,9 +433,9 @@ func TestDataDirHelper(t *testing.T) {
 		t.Run(name, func(t *testing.T) {
 			// Cannot use t.Parallel() here because t.Setenv
 			// is incompatible with parallel subtests.
-			if set == "" {
+			config.ClearEnvForTest(t)
-				require.NoError(t, os.Unsetenv("DATA_DIR"))
+
-			} else {
+			if set != "" {
 				t.Setenv("DATA_DIR", set)
 			}
 
@@ -511,14 +498,11 @@ func TestReceiverRateLimit(t *testing.T) {
 		t.Run(tt.name, func(t *testing.T) {
 			// Cannot use t.Parallel() here because t.Setenv
 			// is incompatible with parallel subtests.
+			config.ClearEnvForTest(t)
 			t.Setenv("WEBHOOKER_ENVIRONMENT", "dev")
 
 			if tt.set {
 				t.Setenv("RECEIVER_RATE_LIMIT", tt.value)
-			} else {
-				require.NoError(t, os.Unsetenv(
-					"RECEIVER_RATE_LIMIT",
-				))
 			}
 
 			if tt.expectError {
@@ -630,12 +614,11 @@ func TestTrustedProxies(t *testing.T) {
 		t.Run(tt.name, func(t *testing.T) {
 			// Cannot use t.Parallel() here because t.Setenv
 			// is incompatible with parallel subtests.
+			config.ClearEnvForTest(t)
 			t.Setenv("WEBHOOKER_ENVIRONMENT", "dev")
 
 			if tt.set {
 				t.Setenv("TRUSTED_PROXIES", tt.value)
-			} else {
-				require.NoError(t, os.Unsetenv("TRUSTED_PROXIES"))
 			}
 
 			if tt.expectError {
@@ -742,14 +725,11 @@ func TestAllowedEgressCIDRs(t *testing.T) {
 		t.Run(tt.name, func(t *testing.T) {
 			// Cannot use t.Parallel() here because t.Setenv
 			// is incompatible with parallel subtests.
+			config.ClearEnvForTest(t)
 			t.Setenv("WEBHOOKER_ENVIRONMENT", "dev")
 
 			if tt.set {
 				t.Setenv("ALLOWED_EGRESS_CIDRS", tt.value)
-			} else {
-				require.NoError(
-					t, os.Unsetenv("ALLOWED_EGRESS_CIDRS"),
-				)
 			}
 
 			if tt.expectError {
@@ -817,13 +797,10 @@ func TestEgressAllowlistWarning(t *testing.T) {
 		t.Run(tt.name, func(t *testing.T) {
 			// Cannot use t.Parallel() here because t.Setenv
 			// is incompatible with parallel subtests.
+			config.ClearEnvForTest(t)
 			t.Setenv("WEBHOOKER_ENVIRONMENT", config.EnvironmentDev)
 
-			if tt.allowed == "" {
+			if tt.allowed != "" {
-				require.NoError(
-					t, os.Unsetenv("ALLOWED_EGRESS_CIDRS"),
-				)
-			} else {
 				t.Setenv("ALLOWED_EGRESS_CIDRS", tt.allowed)
 			}
 
@@ -956,20 +933,14 @@ func TestMetricsAuthConfig(t *testing.T) {
 		t.Run(tt.name, func(t *testing.T) {
 			// Cannot use t.Parallel() here because t.Setenv
 			// is incompatible with parallel subtests.
+			config.ClearEnvForTest(t)
+
 			if tt.username.set {
 				t.Setenv("METRICS_USERNAME", tt.username.value)
-			} else {
-				require.NoError(
-					t, os.Unsetenv("METRICS_USERNAME"),
-				)
 			}
 
 			if tt.password.set {
 				t.Setenv("METRICS_PASSWORD", tt.password.value)
-			} else {
-				require.NoError(
-					t, os.Unsetenv("METRICS_PASSWORD"),
-				)
 			}
 
 			if tt.expectError {

internal/config/dotenv_test.go

@@ -22,17 +22,6 @@ const malformedDotEnv = "PORT 19615\n" +
 	"this is not = valid ! syntax\n" +
 	"\"unclosed\n"
 
-// unsetDotEnvKey makes dotEnvKey genuinely absent for the duration of
-// the test and restores it afterwards. t.Setenv registers the restore;
-// the Unsetenv that follows is what the test actually needs, because a
-// variable set to the empty string is still present in os.Environ and
-// godotenv would refuse to overwrite it.
-func unsetDotEnvKey(t *testing.T) {
-	t.Helper()
-	t.Setenv(dotEnvKey, "placeholder")
-	require.NoError(t, os.Unsetenv(dotEnvKey))
-}
-
 // writeDotEnv writes contents to a .env file in a fresh temporary
 // directory and returns its path.
 func writeDotEnv(t *testing.T, contents string) string {
@@ -50,9 +39,9 @@ func writeDotEnv(t *testing.T, contents string) string {
 // normally rather than be refused for a file it was never meant to
 // have.
 //
-//nolint:paralleltest // unsetDotEnvKey uses t.Setenv.
+//nolint:paralleltest // ClearEnvForTest uses t.Setenv.
 func TestLoadDotEnv_MissingFileIsFine(t *testing.T) {
-	unsetDotEnvKey(t)
+	config.ClearEnvForTest(t)
 
 	absent := filepath.Join(t.TempDir(), config.DotEnvPath)
 	require.NoError(t, config.LoadDotEnvFileForTest(absent))
@@ -65,9 +54,9 @@ func TestLoadDotEnv_MissingFileIsFine(t *testing.T) {
 // reaches the environment, which is the whole reason the file is read
 // at all.
 //
-//nolint:paralleltest // unsetDotEnvKey uses t.Setenv.
+//nolint:paralleltest // ClearEnvForTest uses t.Setenv.
 func TestLoadDotEnv_AppliesValues(t *testing.T) {
-	unsetDotEnvKey(t)
+	config.ClearEnvForTest(t)
 
 	path := writeDotEnv(t, "# a comment\n"+dotEnvKey+"=from-dot-env\n")
 
@@ -93,9 +82,9 @@ func TestLoadDotEnv_RealEnvironmentWins(t *testing.T) {
 // reverts to its default; the process used to start that way with no
 // log line naming the file at all.
 //
-//nolint:paralleltest // unsetDotEnvKey uses t.Setenv.
+//nolint:paralleltest // ClearEnvForTest uses t.Setenv.
 func TestLoadDotEnv_MalformedFileAborts(t *testing.T) {
-	unsetDotEnvKey(t)
+	config.ClearEnvForTest(t)
 
 	path := writeDotEnv(
 		t, malformedDotEnv+dotEnvKey+"=from-dot-env\n",
@@ -143,7 +132,7 @@ func TestLoadDotEnv_UnreadableFileAborts(t *testing.T) {
 //
 //nolint:paralleltest // t.Chdir moves the whole process.
 func TestLoadDotEnv_ReadsTheWorkingDirectory(t *testing.T) {
-	unsetDotEnvKey(t)
+	config.ClearEnvForTest(t)
 
 	dir := t.TempDir()
 	require.NoError(t, os.WriteFile(

internal/config/env_test.go

@@ -1,7 +1,6 @@
 package config_test
 
 import (
-	"os"
 	"testing"
 
 	"github.com/stretchr/testify/assert"
@@ -121,10 +120,10 @@ func TestEnvBool(t *testing.T) {
 		t.Run(tt.name, func(t *testing.T) {
 			// Cannot use t.Parallel() here because t.Setenv
 			// is incompatible with parallel subtests.
+			config.ClearEnvForTest(t)
+
 			if tt.set {
 				t.Setenv(testEnvKey, tt.value)
-			} else {
-				require.NoError(t, os.Unsetenv(testEnvKey))
 			}
 
 			got, err := config.EnvBoolForTest(
@@ -145,17 +144,62 @@ func TestEnvBool(t *testing.T) {
 	}
 }
 
+// envIntCase is one row of the envPositiveInt and envPort tables.
+type envIntCase struct {
+	name        string
+	set         bool
+	value       string
+	expectError bool
+	errIs       error
+	expected    int
+}
+
+// runEnvIntCases runs each row through parse, which is
+// envPositiveInt or envPort, with testEnvKey set to the row's value
+// or left unset.
+func runEnvIntCases(
+	t *testing.T,
+	parse func(key string, defaultValue int) (int, error),
+	defaultValue int,
+	tests []envIntCase,
+) {
+	t.Helper()
+
+	for _, tt := range tests {
+		t.Run(tt.name, func(t *testing.T) {
+			// Cannot use t.Parallel() here because t.Setenv
+			// is incompatible with parallel subtests.
+			config.ClearEnvForTest(t)
+
+			if tt.set {
+				t.Setenv(testEnvKey, tt.value)
+			}
+
+			got, err := parse(testEnvKey, defaultValue)
+
+			if tt.expectError {
+				require.Error(t, err)
+				assert.Contains(t, err.Error(), testEnvKey)
+				assert.Contains(t, err.Error(), tt.value)
+
+				if tt.errIs != nil {
+					require.ErrorIs(t, err, tt.errIs)
+				}
+
+				return
+			}
+
+			require.NoError(t, err)
+			assert.Equal(t, tt.expected, got)
+		})
+	}
+}
+
+//nolint:paralleltest // runEnvIntCases uses t.Setenv.
 func TestEnvPositiveInt(t *testing.T) {
 	const defaultValue = 7
 
-	tests := []struct {
+	runEnvIntCases(t, config.EnvPositiveIntForTest, defaultValue, []envIntCase{
-		name        string
-		set         bool
-		value       string
-		expectError bool
-		errIs       error
-		expected    int
-	}{
 		{
 			name:     "unset returns the default integer",
 			expected: defaultValue,
@@ -192,51 +236,14 @@ func TestEnvPositiveInt(t *testing.T) {
 			expectError: true,
 			errIs:       config.ErrNonPositiveValue,
 		},
-	}
+	})
-
-	for _, tt := range tests {
-		t.Run(tt.name, func(t *testing.T) {
-			// Cannot use t.Parallel() here because t.Setenv
-			// is incompatible with parallel subtests.
-			if tt.set {
-				t.Setenv(testEnvKey, tt.value)
-			} else {
-				require.NoError(t, os.Unsetenv(testEnvKey))
-			}
-
-			got, err := config.EnvPositiveIntForTest(
-				testEnvKey, defaultValue,
-			)
-
-			if tt.expectError {
-				require.Error(t, err)
-				assert.Contains(t, err.Error(), testEnvKey)
-				assert.Contains(t, err.Error(), tt.value)
-
-				if tt.errIs != nil {
-					require.ErrorIs(t, err, tt.errIs)
-				}
-
-				return
-			}
-
-			require.NoError(t, err)
-			assert.Equal(t, tt.expected, got)
-		})
-	}
 }
 
+//nolint:paralleltest // runEnvIntCases uses t.Setenv.
 func TestEnvPort(t *testing.T) {
 	const defaultValue = 8080
 
-	tests := []struct {
+	runEnvIntCases(t, config.EnvPortForTest, defaultValue, []envIntCase{
-		name        string
-		set         bool
-		value       string
-		expectError bool
-		errIs       error
-		expected    int
-	}{
 		{
 			name:     "unset returns the default port",
 			expected: defaultValue,
@@ -264,7 +271,14 @@ func TestEnvPort(t *testing.T) {
 			set:         true,
 			value:       "0",
 			expectError: true,
-			errIs:       config.ErrNonPositiveValue,
+			errIs:       config.ErrInvalidPort,
+		},
+		{
+			name:        "negative is rejected",
+			set:         true,
+			value:       "-1",
+			expectError: true,
+			errIs:       config.ErrInvalidPort,
 		},
 		{
 			name:        "above the port range is rejected",
@@ -273,37 +287,14 @@ func TestEnvPort(t *testing.T) {
 			expectError: true,
 			errIs:       config.ErrInvalidPort,
 		},
-	}
+		{
-
+			name:        "too large for an int is rejected",
-	for _, tt := range tests {
+			set:         true,
-		t.Run(tt.name, func(t *testing.T) {
+			value:       "99999999999999999999",
-			// Cannot use t.Parallel() here because t.Setenv
+			expectError: true,
-			// is incompatible with parallel subtests.
+			errIs:       config.ErrInvalidPort,
-			if tt.set {
+		},
-				t.Setenv(testEnvKey, tt.value)
+	})
-			} else {
-				require.NoError(t, os.Unsetenv(testEnvKey))
-			}
-
-			got, err := config.EnvPortForTest(
-				testEnvKey, defaultValue,
-			)
-
-			if tt.expectError {
-				require.Error(t, err)
-				assert.Contains(t, err.Error(), testEnvKey)
-
-				if tt.errIs != nil {
-					require.ErrorIs(t, err, tt.errIs)
-				}
-
-				return
-			}
-
-			require.NoError(t, err)
-			assert.Equal(t, tt.expected, got)
-		})
-	}
 }
 
 // TestEnvBindAddress covers BIND_ADDRESS parsing.
@@ -319,10 +310,10 @@ func TestEnvBindAddress(t *testing.T) {
 		t.Run(tt.name, func(t *testing.T) {
 			// Cannot use t.Parallel() here because t.Setenv
 			// is incompatible with parallel subtests.
+			config.ClearEnvForTest(t)
+
 			if tt.set {
 				t.Setenv(testEnvKey, tt.value)
-			} else {
-				require.NoError(t, os.Unsetenv(testEnvKey))
 			}
 
 			got, err := config.EnvBindAddressForTest(
@@ -485,6 +476,7 @@ func TestNewRejectsBadEnvValues(t *testing.T) {
 		t.Run(tt.name, func(t *testing.T) {
 			// Cannot use t.Parallel() here because t.Setenv
 			// is incompatible with parallel subtests.
+			config.ClearEnvForTest(t)
 			t.Setenv("WEBHOOKER_ENVIRONMENT", "dev")
 			t.Setenv(tt.key, tt.value)
 
@@ -646,14 +638,9 @@ func sentryEnvValueCases() []badEnvValueCase {
 // break the legitimate unset case: absent variables still get their
 // documented defaults.
 func TestNewUsesDefaultsWhenUnset(t *testing.T) {
+	config.ClearEnvForTest(t)
 	t.Setenv("WEBHOOKER_ENVIRONMENT", "dev")
 
-	for _, key := range []string{
-		envKeyPort, envKeyDebug, envKeyBindAddress, envKeySentryDSN,
-	} {
-		require.NoError(t, os.Unsetenv(key))
-	}
-
 	cfg, err := buildConfig(t)
 	require.NoError(t, err)
 	require.NotNil(t, cfg)

internal/config/sentry_test.go

@@ -1,7 +1,6 @@
 package config_test
 
 import (
-	"os"
 	"testing"
 
 	"github.com/stretchr/testify/assert"
@@ -101,10 +100,10 @@ func TestEnvSentryDSN(t *testing.T) {
 		t.Run(tt.name, func(t *testing.T) {
 			// Cannot use t.Parallel() here because t.Setenv
 			// is incompatible with parallel subtests.
+			config.ClearEnvForTest(t)
+
 			if tt.set {
 				t.Setenv(envKeySentryDSN, tt.value)
-			} else {
-				require.NoError(t, os.Unsetenv(envKeySentryDSN))
 			}
 
 			got, err := config.EnvSentryDSNForTest(envKeySentryDSN)

internal/config/testing.go

@@ -0,0 +1,50 @@
+package config
+
+import (
+	"os"
+	"strings"
+	"testing"
+)
+
+// ClearEnvForTest unsets every variable in the process environment
+// 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
+		// string is still present, and godotenv will not overwrite a
+		// present key.
+		t.Setenv(key, "")
+
+		err := os.Unsetenv(key)
+		if err != nil {
+			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/delivery/engine_integration_test.go

@@ -355,9 +355,14 @@ func TestProcessRetryTask_SuccessfulRetry(t *testing.T) {
 
 	s := newISetup(t)
 
+	var receivedBody string
+
 	ts := httptest.NewServer(
 		http.HandlerFunc(
-			func(w http.ResponseWriter, _ *http.Request) {
+			func(w http.ResponseWriter, r *http.Request) {
+				body, _ := io.ReadAll(r.Body)
+				receivedBody = string(body)
+
 				w.WriteHeader(http.StatusOK)
 			},
 		),
@@ -397,6 +402,8 @@ func TestProcessRetryTask_SuccessfulRetry(t *testing.T) {
 		context.TODO(), &task,
 	)
 
+	assert.Equal(t, event.Body, receivedBody)
+
 	iAssertStatus(t, s.WebhookDB, d.ID,
 		database.DeliveryStatusDelivered,
 	)
@@ -443,9 +450,14 @@ func TestProcessRetryTask_LargeBody_FetchFromDB(
 
 	s := newISetup(t)
 
+	var receivedBody string
+
 	ts := httptest.NewServer(
 		http.HandlerFunc(
-			func(w http.ResponseWriter, _ *http.Request) {
+			func(w http.ResponseWriter, r *http.Request) {
+				body, _ := io.ReadAll(r.Body)
+				receivedBody = string(body)
+
 				w.WriteHeader(http.StatusOK)
 			},
 		),
@@ -482,6 +494,8 @@ func TestProcessRetryTask_LargeBody_FetchFromDB(
 		context.TODO(), &task,
 	)
 
+	assert.Equal(t, largeBody, receivedBody)
+
 	iAssertStatus(t, s.WebhookDB, d.ID,
 		database.DeliveryStatusDelivered,
 	)

internal/gormlog/firstboot_test.go

@@ -117,8 +117,8 @@ func readFirstBootSecrets(
 }
 
 // bootAtDebug starts and stops the real application graph against
-// dataDir with DEBUG=true, and returns everything it wrote to standard
+// dataDir with DEBUG=true and nothing else set, and returns everything
-// output.
+// it wrote to standard output.
 //
 // config.New reads DEBUG from the environment exactly as the binary
 // does, internal/logger builds the handler it builds in production,
@@ -128,6 +128,7 @@ func readFirstBootSecrets(
 func bootAtDebug(t *testing.T, dataDir string) string {
 	t.Helper()
 
+	config.ClearEnvForTest(t)
 	t.Setenv("DEBUG", "true")
 	t.Setenv("DATA_DIR", dataDir)
 

internal/handlers/settings.go

@@ -77,7 +77,8 @@ func settingRows(cfg *config.Config) []settingRow {
 		{
 			"RETENTION_SWEEP_INTERVAL",
 			"How often the retention reaper and archive sweeper run " +
-				"(Go duration, must be positive)",
+				"(Go duration, must be positive). A value that does " +
+				"not parse, or is zero or negative, fails startup",
 			cfg.RetentionSweepInterval.String(),
 		},
 		{

internal/logfield/logfield_test.go

@@ -5,6 +5,7 @@ import (
 	"io"
 	"log/slog"
 	"strings"
+	"sync"
 	"testing"
 	"unicode/utf8"
 
@@ -18,15 +19,11 @@ import (
 // width.
 const budget = 64
 
-// sampleRunes is how many runes wide the values in the charge test
+// batchRunes is how many consecutive code points the charge test logs
-// are. The handlers add a constant per field — a pair of quotes when
+// in one value from U+1000 up. Logging each of those on its own line
-// the value needs quoting — so the per-rune charge is only visible
+// is too slow for the suite under the race detector; 4,096 at a time
-// once it is amortised over a run of them.
+// is 271 batches, each logged on two lines, so 542 lines per handler.
-const sampleRunes = 64
+const batchRunes = 4096
-
-// quotingSlack is that constant: the pair of quotes a handler adds to
-// a value that needs them and omits from one that does not.
-const quotingSlack = 2
 
 // newHandlers are the two handlers internal/logger can install. Time
 // is dropped so a line's width is a function of its value alone —
@@ -66,46 +63,48 @@ func renderedWidth(
 	return buf.Len()
 }
 
-// chargeTestRunes is the set of code points the charge test measures:
+// emittedBytes is what a handler writes for the runes of s alone, in a
-// every rune in the first two planes' worth of the BMP that the
+// value that starts with prefix: the width of a line carrying prefix
-// handlers are most likely to treat specially, the separators that
+// and then s twice, less that of a line carrying prefix and s once.
-// only slog's JSON handler escapes, and a stratified sample across
+// Both values start the same way and hold the same runes, so the text
-// the rest of Unicode so the astral charge is exercised on more than
+// handler quotes both or neither, and the quotes cancel along with the
-// one hand-picked rune.
+// prefix and everything else on the line.
-func chargeTestRunes() []rune {
+func emittedBytes(
-	const (
+	newHandler func(io.Writer) slog.Handler,
-		denseCeiling = 0x800
+	prefix, s string,
-		stride       = 1021
+) int {
-		surrogateLo  = 0xD800
+	return renderedWidth(newHandler, prefix+s+s) -
-		surrogateHi  = 0xDFFF
+		renderedWidth(newHandler, prefix+s)
-	)
+}
 
-	var runes []rune
+// firstUndercharged returns the first rune in s that the handler
+// writes in more bytes than EncodedBytes charges for it, and how many
+// runes in s are undercharged that way. It measures one rune per line,
+// in a value of that rune alone and again after a space, which makes
+// the text handler quote the value. The charge test calls it on the
+// code points below U+1000, and from there up only on a batch that has
+// already failed, to name the code points rather than just their range.
+func firstUndercharged(
+	newHandler func(io.Writer) slog.Handler,
+	s string,
+) (rune, int) {
+	first, count := rune(-1), 0
 
-	keep := func(r rune) {
+	for _, r := range s {
-		if r >= surrogateLo && r <= surrogateHi {
+		charge := logfield.EncodedBytes(r)
-			return
+		if emittedBytes(newHandler, "", string(r)) <= charge &&
+			emittedBytes(newHandler, " ", string(r)) <= charge {
+			continue
 		}
 
-		runes = append(runes, r)
+		if count == 0 {
+			first = r
+		}
+
+		count++
 	}
 
-	for r := range rune(denseCeiling) {
+	return first, count
-		keep(r)
-	}
-
-	for _, r := range []rune{
-		0x2028, 0x2029, 0x200B, 0x4E00, 0xE000, 0xFFFD,
-		0x1000C, 0x1F600, 0xE0001, 0x10FFFF,
-	} {
-		keep(r)
-	}
-
-	for r := rune(denseCeiling); r <= utf8.MaxRune; r += stride {
-		keep(r)
-	}
-
-	return runes
 }
 
 // TestEncodedBytes_ChargesAtLeastWhatTheHandlersEmit is the property
@@ -114,33 +113,93 @@ func chargeTestRunes() []rune {
 // how a stated ceiling becomes false without any test noticing, so
 // the charge is measured against what the handlers actually write
 // rather than against the escaping rules as read.
+//
+// Every code point below U+1000 is checked on its own, for both
+// handlers. That range holds the quote, the backslash and the control
+// characters the handlers escape, next to code points each handler
+// writes in fewer bytes than their charge, which in a sum would cover
+// a neighbour charged too little. Each is measured in a value of it
+// alone and again in one the text handler quotes, because that handler
+// writes U+007F as one raw byte in a value it leaves bare but as \x7f,
+// four bytes, in one it quotes.
+//
+// From U+1000 up the text handler writes every code point in exactly
+// its charge, so the rest of Unicode is checked batchRunes at a time:
+// each batch's summed charge must cover what the handler writes for
+// the whole batch. The sums there can miss the JSON handler alone
+// writing one code point in more bytes than its charge, when it writes
+// others in the same batch in fewer.
 func TestEncodedBytes_ChargesAtLeastWhatTheHandlersEmit(t *testing.T) {
 	t.Parallel()
 
+	var below strings.Builder
+	for r := range rune(0x1000) {
+		below.WriteRune(r)
+	}
+
+	var batches []string
+
+	for lo := rune(0x1000); lo <= utf8.MaxRune; lo += batchRunes {
+		var batch strings.Builder
+
+		for r := lo; r < lo+batchRunes; r++ {
+			// Surrogate halves are not runes a string can carry.
+			if utf8.ValidRune(r) {
+				batch.WriteRune(r)
+			}
+		}
+
+		batches = append(batches, batch.String())
+	}
+
+	// What EncodedBytes charges for each batch. Under -race -cover this
+	// takes longer than logging the batches, so it is worked out once,
+	// by whichever handler finishes logging first, while the other is
+	// still logging.
+	charged := sync.OnceValue(func() []int {
+		costs := make([]int, len(batches))
+
+		for i, batch := range batches {
+			for _, r := range batch {
+				costs[i] += logfield.EncodedBytes(r)
+			}
+		}
+
+		return costs
+	})
+
 	for name, newHandler := range newHandlers() {
 		t.Run(name, func(t *testing.T) {
 			t.Parallel()
 
-			// 'a' is a printable ASCII rune, charged exactly one
+			if first, count := firstUndercharged(newHandler, below.String()); count > 0 {
-			// byte, so it is the zero point the other runes are
+				t.Errorf(
-			// measured against.
+					"%d code points below U+1000 cost more than "+
-			base := renderedWidth(
+						"EncodedBytes charges, the first U+%04X",
-				newHandler, strings.Repeat("a", sampleRunes),
+					count, first,
-			)
-
-			for _, r := range chargeTestRunes() {
-				got := renderedWidth(
-					newHandler,
-					strings.Repeat(string(r), sampleRunes),
 				)
-				charged := sampleRunes *
+			}
-					(logfield.EncodedBytes(r) - 1)
 
-				require.LessOrEqual(
+			emitted := make([]int, len(batches))
-					t, got-base, charged+quotingSlack,
+			for i, batch := range batches {
-					"U+%04X costs more on the line than "+
+				emitted[i] = emittedBytes(newHandler, "", batch)
-						"EncodedBytes charges for it",
+			}
-					r,
+
+			for i, cost := range charged() {
+				if emitted[i] <= cost {
+					continue
+				}
+
+				lo := rune(0x1000 + i*batchRunes)
+				first, count := firstUndercharged(
+					newHandler, batches[i],
+				)
+				t.Errorf(
+					"U+%04X to U+%04X emit %d bytes but are "+
+						"charged %d; %d of them cost more than "+
+						"EncodedBytes charges, the first U+%04X",
+					lo, lo+batchRunes-1, emitted[i], cost,
+					count, first,
 				)
 			}
 		})

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

@@ -600,7 +600,10 @@ func bodyLimitedMethod(method string) bool {
 }
 
 // MaxBodySize returns middleware that limits the size of
-// POST/PUT/PATCH request bodies to maxBytes. It must be registered
+// POST/PUT/PATCH request bodies to maxBytes. A request with any other
+// method passes through uncapped, deliberately: no route behind it
+// reads a body on GET, HEAD or DELETE. A handler that starts to needs
+// its method added to bodyLimitedMethod first. It must be registered
 // before any middleware that parses the body — notably CSRF, which
 // calls r.PostFormValue — so that form parsing happens under this
 // cap rather than net/http's 10 MB default.

internal/middleware/middleware_test.go

@@ -730,10 +730,8 @@ func TestNoCache_SetsHeaders(t *testing.T) {
 
 const testBodyLimit int64 = 64
 
-// maxBodySizeHandler wraps a sentinel handler in MaxBodySize with
+// maxBodySizeResult is what runMaxBodySize's sentinel handler saw,
-// testBodyLimit. The sentinel records whether it ran and how much of
+// together with the response.
-// the body it managed to read, so tests can distinguish "never
-// reached" from "reached but truncated".
 type maxBodySizeResult struct {
 	called   bool
 	read     int
@@ -741,6 +739,10 @@ type maxBodySizeResult struct {
 	response *httptest.ResponseRecorder
 }
 
+// runMaxBodySize wraps a sentinel handler in MaxBodySize with
+// testBodyLimit and serves req through it. The sentinel records
+// whether it ran and how much of the body it managed to read, so
+// tests can distinguish "never reached" from "reached but truncated".
 func runMaxBodySize(
 	t *testing.T,
 	req *http.Request,

internal/server/error_page_test.go

@@ -191,7 +191,7 @@ func TestErrorPage_PanicOnAdminPage(t *testing.T) {
 
 	w := serve(
 		server.NewRouterWithPageProbeForTest(
-			env.log.Get(), env.cfg, env.mw, env.hnd,
+			t, env.log, env.cfg, env.mw, env.hnd,
 			true, panicProbeHandler,
 		),
 		server.PageProbePattern,
@@ -200,7 +200,7 @@ func TestErrorPage_PanicOnAdminPage(t *testing.T) {
 
 	w = serve(
 		server.NewRouterWithProbeForTest(
-			env.log.Get(), env.cfg, env.mw, env.hnd,
+			t, env.log, env.cfg, env.mw, env.hnd,
 			true, panicProbeHandler,
 		),
 		server.ProbePattern,

internal/server/export_test.go

@@ -1,13 +1,16 @@
 package server
 
 import (
-	"log/slog"
 	"net/http"
+	"testing"
 
 	"github.com/getsentry/sentry-go"
 	"github.com/go-chi/chi"
+	"github.com/stretchr/testify/require"
+	"go.uber.org/fx/fxtest"
 	"sneak.berlin/go/webhooker/internal/config"
 	"sneak.berlin/go/webhooker/internal/handlers"
+	"sneak.berlin/go/webhooker/internal/logger"
 	"sneak.berlin/go/webhooker/internal/middleware"
 )
 
@@ -34,23 +37,45 @@ func SentryClientOptionsForTest(
 	return sentryClientOptions(dsn, release)
 }
 
+// newServerForTest builds a Server through New, as the application
+// does, on a lifecycle that is never started: the hooks New adds to
+// it never run, so nothing listens.
+func newServerForTest(
+	t *testing.T,
+	log *logger.Logger,
+	cfg *config.Config,
+	mw *middleware.Middleware,
+	h *handlers.Handlers,
+) *Server {
+	t.Helper()
+
+	s, err := New(fxtest.NewLifecycle(t), ServerParams{
+		Logger:     log,
+		Config:     cfg,
+		Middleware: mw,
+		Handlers:   h,
+	})
+	require.NoError(t, err)
+
+	return s
+}
+
 // NewRouterForTest builds the real route tree via SetupRoutes with
-// the supplied middleware and handlers, bypassing the fx lifecycle
+// the supplied middleware and handlers, on a Server from New whose
-// and the HTTP listener. Tests use it so that route-group middleware
+// lifecycle is never started, so no HTTP listener runs. Tests use it
-// registration order is exercised exactly as it ships, rather than
+// so that route-group middleware registration order is exercised
-// against a hand-rebuilt chain that could drift from routes.go.
+// exactly as it ships, rather than against a hand-rebuilt chain that
+// could drift from routes.go.
 func NewRouterForTest(
-	log *slog.Logger,
+	t *testing.T,
+	log *logger.Logger,
 	cfg *config.Config,
 	mw *middleware.Middleware,
 	h *handlers.Handlers,
 ) http.Handler {
-	s := &Server{
+	t.Helper()
-		log:    log,
+
-		mw:     mw,
+	s := newServerForTest(t, log, cfg, mw, h)
-		h:      h,
-		params: ServerParams{Config: cfg},
-	}
 	s.SetupRoutes()
 
 	return s.router
@@ -83,19 +108,17 @@ const ProbePattern = "/probe"
 // option and the recoverer registered outside it is the thing a test
 // has to be able to pin.
 func NewRouterWithProbeForTest(
-	log *slog.Logger,
+	t *testing.T,
+	log *logger.Logger,
 	cfg *config.Config,
 	mw *middleware.Middleware,
 	h *handlers.Handlers,
 	sentryEnabled bool,
 	probe http.HandlerFunc,
 ) http.Handler {
-	s := &Server{
+	t.Helper()
-		log:    log,
+
-		mw:     mw,
+	s := newServerForTest(t, log, cfg, mw, h)
-		h:      h,
-		params: ServerParams{Config: cfg},
-	}
 	s.sentryEnabled.Store(sentryEnabled)
 	s.SetupRoutes()
 	s.router.Handle(ProbePattern, probe)
@@ -113,19 +136,17 @@ const PageProbePattern = "/pages/probe"
 // it, so the probe runs behind that group's own middleware exactly as
 // the group's real routes do.
 func NewRouterWithPageProbeForTest(
-	log *slog.Logger,
+	t *testing.T,
+	log *logger.Logger,
 	cfg *config.Config,
 	mw *middleware.Middleware,
 	h *handlers.Handlers,
 	sentryEnabled bool,
 	probe http.HandlerFunc,
 ) http.Handler {
-	s := &Server{
+	t.Helper()
-		log:    log,
+
-		mw:     mw,
+	s := newServerForTest(t, log, cfg, mw, h)
-		h:      h,
-		params: ServerParams{Config: cfg},
-	}
 	s.sentryEnabled.Store(sentryEnabled)
 	s.SetupRoutes()
 

internal/server/recoverer_test.go

@@ -199,7 +199,7 @@ func TestPanicProbeChild(t *testing.T) {
 	env := newTestEnv(t)
 
 	router := server.NewRouterWithProbeForTest(
-		env.log.Get(), env.cfg, env.mw, env.hnd,
+		t, env.log, env.cfg, env.mw, env.hnd,
 		false, panicProbeHandler,
 	)
 
@@ -253,7 +253,7 @@ func TestSentryStillSeesAPanic(t *testing.T) {
 	require.NoError(t, err)
 
 	router := server.NewRouterWithProbeForTest(
-		env.log.Get(), env.cfg, env.mw, env.hnd,
+		t, env.log, env.cfg, env.mw, env.hnd,
 		true, panicProbeHandler,
 	)
 

internal/server/response_controller_test.go

@@ -67,11 +67,11 @@ func TestResponseControllerThroughProductionRouter(t *testing.T) {
 
 			routers := map[string]http.Handler{
 				server.ProbePattern: server.NewRouterWithProbeForTest(
-					env.log.Get(), env.cfg, env.mw, env.hnd,
+					t, env.log, env.cfg, env.mw, env.hnd,
 					tc.sentryEnabled, probe,
 				),
 				server.PageProbePattern: server.NewRouterWithPageProbeForTest(
-					env.log.Get(), env.cfg, env.mw, env.hnd,
+					t, env.log, env.cfg, env.mw, env.hnd,
 					tc.sentryEnabled, probe,
 				),
 			}

internal/server/routes_test.go

@@ -136,7 +136,7 @@ func newTestEnvWithConfig(
 	t.Cleanup(app.RequireStop)
 
 	return &testEnv{
-		router: server.NewRouterForTest(log.Get(), cfg, mw, hnd),
+		router: server.NewRouterForTest(t, log, cfg, mw, hnd),
 		sess:   sess,
 		db:     db,
 		dbMgr:  dbMgr,
@@ -531,6 +531,48 @@ func TestStaticServesOnlyGetAndHead(t *testing.T) {
 	}
 }
 
+// --- every page route group ---
+
+// TestPageRouteGroups_OversizeBody_RejectedBeforeCSRF pins the body
+// cap ahead of CSRF and RequireAuth in every page route group. The
+// requests carry no session and no CSRF token, so if either ran first
+// the answer would be a 403 or a redirect to the login page rather
+// than 413, and CSRF would issue its cookie (see
+// TestPagesLogin_UnderLimit_NoToken_CSRFRejects). /settings has no
+// POST route, but its group's middleware runs before the method is
+// matched, so a POST there still reaches CSRF's form parsing if the
+// cap moves after it. The user and webhook in the paths need not
+// exist: nothing after the cap runs.
+func TestPageRouteGroups_OversizeBody_RejectedBeforeCSRF(
+	t *testing.T,
+) {
+	t.Parallel()
+
+	env := newTestEnv(t)
+
+	form := url.Values{}
+	form.Set("name", oversizeValue())
+
+	for _, path := range []string{
+		"/pages/login",
+		"/user/nobody/password",
+		"/settings/",
+		"/hooks/new",
+		"/hook/nonexistent/edit",
+	} {
+		w := env.post(path, form, nil)
+
+		assert.Equal(
+			t, http.StatusRequestEntityTooLarge, w.Code, path,
+		)
+		assert.False(
+			t, csrfCookieSet(w),
+			"CSRF middleware must not run for an oversized body to %s",
+			path,
+		)
+	}
+}
+
 // --- /pages group ---
 
 // TestPagesLogin_OversizeBody_RejectedBeforeCSRF proves the cap runs
@@ -1610,7 +1652,7 @@ func TestTwoMetricsRoutersInOneProcess(t *testing.T) {
 	)
 	third := &testEnv{
 		router: server.NewRouterForTest(
-			first.log.Get(), first.cfg, first.mw, first.hnd,
+			t, first.log, first.cfg, first.mw, first.hnd,
 		),
 	}