Check the log charge against every code point (closes #172)

TestEncodedBytes_ChargesAtLeastWhatTheHandlersEmit now covers all of
Unicode, surrogates aside, in place of a dense range plus a sample.
Below U+1000 each code point is checked on its own against both
handlers, alone in a value and again in one the text handler quotes,
which writes U+007F there as \x7f. From U+1000 up code points are
logged 4,096 to a value, and each batch's summed charge must cover the
bytes the real handler writes for it, measured as a line carrying the
batch twice less one carrying it once. A failing batch is then
measured one code point at a time, so the failure names how many are
undercharged and the first of them.

Model: opus-5-5

README.md

@@ -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
-`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
@@ -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
-  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
@@ -2996,7 +3001,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,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/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
-// are. The handlers add a constant per field — a pair of quotes when
-// the value needs quoting — so the per-rune charge is only visible
-// once it is amortised over a run of them.
-const sampleRunes = 64
-
-// 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
+// batchRunes is how many consecutive code points the charge test logs
+// in one value from U+1000 up. Logging each of those on its own line
+// is too slow for the suite under the race detector; 4,096 at a time
+// is 271 batches, each logged on two lines, so 542 lines per handler.
+const batchRunes = 4096
 
 // 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:
-// every rune in the first two planes' worth of the BMP that the
-// handlers are most likely to treat specially, the separators that
-// only slog's JSON handler escapes, and a stratified sample across
-// the rest of Unicode so the astral charge is exercised on more than
-// one hand-picked rune.
-func chargeTestRunes() []rune {
-	const (
-		denseCeiling = 0x800
-		stride       = 1021
-		surrogateLo  = 0xD800
-		surrogateHi  = 0xDFFF
-	)
+// emittedBytes is what a handler writes for the runes of s alone, in a
+// value that starts with prefix: the width of a line carrying prefix
+// and then s twice, less that of a line carrying prefix and s once.
+// Both values start the same way and hold the same runes, so the text
+// handler quotes both or neither, and the quotes cancel along with the
+// prefix and everything else on the line.
+func emittedBytes(
+	newHandler func(io.Writer) slog.Handler,
+	prefix, s string,
+) int {
+	return renderedWidth(newHandler, prefix+s+s) -
+		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) {
-		if r >= surrogateLo && r <= surrogateHi {
-			return
+	for _, r := range s {
+		charge := logfield.EncodedBytes(r)
+		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) {
-		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
+	return first, count
 }
 
 // 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
-			// byte, so it is the zero point the other runes are
-			// measured against.
-			base := renderedWidth(
-				newHandler, strings.Repeat("a", sampleRunes),
-			)
-
-			for _, r := range chargeTestRunes() {
-				got := renderedWidth(
-					newHandler,
-					strings.Repeat(string(r), sampleRunes),
+			if first, count := firstUndercharged(newHandler, below.String()); count > 0 {
+				t.Errorf(
+					"%d code points below U+1000 cost more than "+
+						"EncodedBytes charges, the first U+%04X",
+					count, first,
 				)
-				charged := sampleRunes *
-					(logfield.EncodedBytes(r) - 1)
+			}
 
-				require.LessOrEqual(
-					t, got-base, charged+quotingSlack,
-					"U+%04X costs more on the line than "+
-						"EncodedBytes charges for it",
-					r,
+			emitted := make([]int, len(batches))
+			for i, batch := range batches {
+				emitted[i] = emittedBytes(newHandler, "", batch)
+			}
+
+			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/ratelimit.go

@@ -219,7 +219,11 @@ func (m *Middleware) clientKey(r *http.Request) string {
 		// 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
 	}
 

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