Route GORM's logger through slog and bound it (closes #178)

GORM's default logger printed the fully interpolated SQL to standard
output on every statement that returned an error, including a plain
record-not-found. On /webhook/{uuid} and on the login form the
interpolated parameter is client-chosen and unbounded, so an
unauthenticated client sized the operator's log, one line per request,
at no level the operator could turn down.

Every gorm.Open in the service now installs internal/gormlog, a
gormlogger.Interface over the service's *slog.Logger. Its lines take
the level the operator set and the handler internal/logger selected; a
record-not-found is not logged as an error, since it is the expected
outcome on both of those paths and each handler already records its
own miss at DEBUG without the SQL; slow statements are kept at WARN
above the same 200ms threshold GORM used; and every value it emits is
spent through an encoded-byte budget.

Trace orders its cases exactly as GORM's own Trace orders them --
error-that-is-not-a-miss, then slow, then routine -- so a statement
that both missed and ran slow is still reported as slow. Ordering the
drop first would have made this adapter strictly less observant than
the IgnoreRecordNotFoundError option it was chosen over, on the two
lookups the issue is about, and a miss is the statement most likely to
be slow.

That budget is internal/middleware's truncateLogField, moved to a new
internal/logfield package now that a second writer needs it. The move
is unchanged logic. MaxAccessLogLineBytes bounds a GORM line too, and
internal/gormlog asserts each line against the constant directly.

The third gorm.Open, in the archive writer, was not named in the issue
and had the same default. All three sites are pinned independently:
internal/handlers covers the main and per-webhook databases,
internal/delivery covers the archive writer, whose type is unexported.
Reverting any one of the three to a bare &gorm.Config{} fails the
suite.

The flood test's per-line and volume assertions were vacuous, because
the replaced default logger wrote only to a buffer while everything
else went to the captured stdout. It now tees to stdout as GORM's real
default does, so a reverted call site lands in the same capture and
those assertions measure the whole writer set.

README: the ceiling now covers GORM, and the writers it does not cover
are re-derived by measuring rather than by reading. fx's console
logger and the Go runtime write to standard error. net/http's nil
ErrorLog is not a separate writer at all -- slog.SetDefault redirects
the log package's default logger into internal/logger's handler, so
those lines arrive on standard output at INFO. A handler panic reaches
that same path because chi's Recoverer crashes before writing, which
is filed as #187 and is also the widest line the service can write, at
2,772 bytes against the stated 2,560.

README.md

@@ -1152,6 +1152,80 @@ that the rate is not bounded by the limits above on every route:
 `/.well-known/healthcheck` and `/s/*` sit behind no limiter, so there
 the multiplier is whatever the deployment will serve.
 
+That figure is now the ceiling on a second writer as well. GORM's own
+default logger printed the fully interpolated SQL — parameters and all
+— to standard output on every statement that returned an error,
+including a plain record-not-found, at a level no operator setting
+reached. Two of this service's lookups miss by design on
+unauthenticated routes: the entrypoint lookup behind `/webhook/{uuid}`
+and the user lookup behind the login form, whose path segment and
+submitted username the client picks outright. Every `gorm.Open` in the
+service now installs the adapter in `internal/gormlog` instead. It
+writes through the same `slog` logger as everything else, so its lines
+take the level the operator set and the handler `internal/logger`
+selected, and every value it emits is spent through the same 512-byte
+encoded budget (`internal/logfield`). A record-not-found is not logged
+as an error: it is the expected outcome on both of those paths, and
+each handler already records its own miss at `DEBUG`, without the SQL.
+Slow statements are kept — at `WARN`, above the same 200 ms threshold
+GORM used, with the statement bounded — because that report is the one
+thing GORM's logger gave an operator that nothing else here does, and
+a statement that both missed and ran slow is still reported as slow.
+The adapter orders those cases exactly as GORM's own `Trace` orders
+them, so dropping the miss costs an operator no report that GORM's
+`IgnoreRecordNotFoundError` would have kept. A
+GORM line spends at most two of those budgets, the statement and the
+driver error, against a smaller fixed portion than the access log's;
+`internal/gormlog/gormlog_test.go` asserts each line against
+`MaxAccessLogLineBytes` directly rather than leaving it as arithmetic.
+
+**What the ceiling does not cover.** It is a per-line bound on the
+access log and on GORM's statement logging, not a bound on every line
+this service writes. The exceptions are named here because a bound
+that is true of one writer and silently false of another is worse than
+no stated bound at all.
+
+- Other `slog` calls that reach a client-chosen value — the
+  `MaxBodySize` rejection, the CSRF failure, the receiver rate-limit
+  rejection, and the two lookup misses above — still log the request
+  path or the submitted username untruncated.
+- The `log` delivery target (`internal/delivery/target_log.go`) writes
+  the entire inbound event, headers and body, to the log. That is what
+  the target is for. Each line is bounded per event by the 1 MB
+  receiver body cap, and it costs nothing unless an authenticated
+  operator creates a target of that type.
+- 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`.
+- `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
+  `internal/logger` calls `slog.SetDefault`, which redirects that
+  logger into whichever handler it installed. Those lines therefore
+  arrive on standard output, shaped like every other line, at `INFO`.
+  They are not truncated and they are not bounded by the ceiling: a
+  handler panic arrives as one record carrying a whole goroutine
+  stack, measured at 2,772 bytes against the ceiling's 2,560. The
+  value is the runtime's, not a client's.
+- A handler panic reaches that path rather than the one it looks like
+  it should. `internal/server/routes.go` installs chi's
+  `middleware.Recoverer` in front of every route, which is meant to
+  print the panic and its stack to standard error and answer 500. On
+  the Go version this service builds against it does neither: chi
+  v1.5.5's stack pretty-printer looks for a `panic(0x` frame that the
+  runtime no longer emits, walks past the end of its own slice, and
+  panics before writing a byte. That second panic escapes to
+  `net/http`, which drops the connection and reports it through the
+  nil `ErrorLog` above. Tracked separately in
+  https://git.eeqj.de/sneak/webhooker/issues/187.
+
 Every limiter here — receiver, login, and password change — identifies
 the client the same way, through one shared key function: the
 connection's own address, unless the peer is listed in
@@ -1390,6 +1464,10 @@ webhooker/
 │   │   └── webhook_db_manager.go  # Per-webhook DB lifecycle manager
 │   ├── globals/
 │   │   └── globals.go         # Build-time variables (appname, version, arch)
+│   ├── gormlog/
+│   │   └── gormlog.go         # GORM's logger.Interface on top of slog, bounded
+│   ├── logfield/
+│   │   └── logfield.go        # Encoded-byte budget for client-supplied log values
 │   ├── delivery/
 │   │   ├── engine.go          # Event-driven delivery engine (channel + timer based)
 │   │   ├── circuit_breaker.go # Per-target circuit breaker for http/slack targets with retries

internal/database/database.go

@@ -17,6 +17,7 @@ import (
 	"gorm.io/gorm"
 	_ "modernc.org/sqlite" // Pure Go SQLite driver
 	"sneak.berlin/go/webhooker/internal/config"
+	"sneak.berlin/go/webhooker/internal/gormlog"
 	"sneak.berlin/go/webhooker/internal/logger"
 )
 
@@ -155,7 +156,10 @@ func (d *Database) connect() error {
 	// Then use it with GORM
 	db, err := gorm.Open(sqlite.Dialector{
 		Conn: sqlDB,
-	}, &gorm.Config{})
+	}, &gorm.Config{
+		// Never leave this at GORM's default. See internal/gormlog.
+		Logger: gormlog.New(d.log),
+	})
 	if err != nil {
 		d.log.Error(
 			"failed to connect to database",

internal/database/webhook_db_manager.go

@@ -14,6 +14,7 @@ import (
 	"gorm.io/driver/sqlite"
 	"gorm.io/gorm"
 	"sneak.berlin/go/webhooker/internal/config"
+	"sneak.berlin/go/webhooker/internal/gormlog"
 	"sneak.berlin/go/webhooker/internal/logger"
 )
 
@@ -248,7 +249,10 @@ func (m *WebhookDBManager) openDB(
 
 	db, err := gorm.Open(sqlite.Dialector{
 		Conn: sqlDB,
-	}, &gorm.Config{})
+	}, &gorm.Config{
+		// Never leave this at GORM's default. See internal/gormlog.
+		Logger: gormlog.New(m.log),
+	})
 	if err != nil {
 		_ = sqlDB.Close()
 

internal/delivery/target_database_archive.go

@@ -12,6 +12,7 @@ import (
 
 	"gorm.io/driver/sqlite"
 	"gorm.io/gorm"
+	"sneak.berlin/go/webhooker/internal/gormlog"
 )
 
 // archiveExpiryNever is the expiry sentinel (and default) that
@@ -282,7 +283,11 @@ func (w *archiveWriter) openMode(
 	}
 
 	gdb, err := gorm.Open(
-		sqlite.Dialector{Conn: sqlDB}, &gorm.Config{},
+		sqlite.Dialector{Conn: sqlDB}, &gorm.Config{
+			// Never leave this at GORM's default. See
+			// internal/gormlog.
+			Logger: gormlog.New(w.log),
+		},
 	)
 	if err != nil {
 		_ = sqlDB.Close()

internal/delivery/target_database_archive_gormlog_test.go

@@ -0,0 +1,155 @@
+package delivery_test
+
+import (
+	"bytes"
+	"log"
+	"log/slog"
+	"path/filepath"
+	"strings"
+	"sync"
+	"testing"
+	"time"
+
+	"github.com/stretchr/testify/assert"
+	"github.com/stretchr/testify/require"
+	"gorm.io/gorm"
+	gormlogger "gorm.io/gorm/logger"
+	"sneak.berlin/go/webhooker/internal/delivery"
+	"sneak.berlin/go/webhooker/internal/middleware"
+)
+
+// archiveGORMTailMarker sits at the far end of the value this file
+// drives into an archive lookup. Its presence in a log line means the
+// whole value reached the log, so nothing truncated it.
+const archiveGORMTailMarker = "ENDOFCLIENTVALUE"
+
+// archiveGORMFillBytes is how much text the lookup carries. It is far
+// past every budget in play.
+const archiveGORMFillBytes = 8 << 10
+
+// gormDefaultBuf collects what GORM's package-level default logger
+// writes, if anything reaches it.
+type gormDefaultBuf struct {
+	mu sync.Mutex
+	b  bytes.Buffer
+}
+
+func (g *gormDefaultBuf) Write(p []byte) (int, error) {
+	g.mu.Lock()
+	defer g.mu.Unlock()
+
+	return g.b.Write(p)
+}
+
+func (g *gormDefaultBuf) String() string {
+	g.mu.Lock()
+	defer g.mu.Unlock()
+
+	return g.b.String()
+}
+
+// captureArchiveGORMDefault replaces GORM's package-level default
+// logger with one configured exactly as GORM configures its own,
+// writing to a buffer.
+//
+// This duplicates the detector in internal/handlers rather than
+// sharing it: a test helper cannot cross a package's test boundary
+// without exporting production code to carry it, and a logging
+// detector is not worth a production symbol. What it detects is the
+// third gorm.Open in this service, at
+// internal/delivery/target_database_archive.go — the archive writer,
+// whose type is unexported, so nothing outside this package can drive
+// it.
+func captureArchiveGORMDefault(t *testing.T) *gormDefaultBuf {
+	t.Helper()
+
+	buf := &gormDefaultBuf{}
+	orig := gormlogger.Default
+
+	gormlogger.Default = gormlogger.New(
+		log.New(buf, "", log.LstdFlags),
+		gormlogger.Config{
+			SlowThreshold:             200 * time.Millisecond,
+			LogLevel:                  gormlogger.Warn,
+			IgnoreRecordNotFoundError: false,
+			Colorful:                  false,
+		},
+	)
+
+	t.Cleanup(func() { gormlogger.Default = orig })
+
+	return buf
+}
+
+// TestArchiveWriter_NeverUsesGORMsDefaultLogger pins the archive
+// writer's gorm.Open to the adapter.
+//
+// Restore a bare &gorm.Config{} at
+// internal/delivery/target_database_archive.go and this fails: the
+// default logger prints the fully interpolated SELECT on every
+// ErrRecordNotFound, so the client-chosen event id below arrives whole
+// and unbounded on stdout, answering to no level the operator set.
+//
+// Not parallel: gormlogger.Default is process-global. Go runs every
+// non-parallel top-level test to completion before it resumes the
+// parallel ones.
+//
+//nolint:paralleltest // Deliberately sequential; see above.
+func TestArchiveWriter_NeverUsesGORMsDefaultLogger(t *testing.T) {
+	var captured bytes.Buffer
+
+	gormDefault := captureArchiveGORMDefault(t)
+
+	w := delivery.NewExportArchiveWriter(
+		filepath.Join(t.TempDir(), "archive.db"),
+		slog.New(slog.NewTextHandler(
+			&captured, &slog.HandlerOptions{Level: slog.LevelDebug},
+		)),
+		0,
+	)
+
+	require.NoError(t, w.Open(0))
+
+	t.Cleanup(w.Evict)
+
+	// A lookup that misses, carrying a value the size of an inbound
+	// event id. Under the default logger this is the line that gets
+	// interpolated and printed.
+	value := strings.Repeat("\x01", archiveGORMFillBytes) +
+		archiveGORMTailMarker
+
+	var row delivery.ExportArchivedEvent
+
+	err := w.DB().Where("event_id = ?", value).First(&row).Error
+	require.ErrorIs(t, err, gorm.ErrRecordNotFound)
+
+	got := gormDefault.String()
+	assert.Empty(
+		t, got,
+		"GORM's default logger wrote %d bytes, so the archive "+
+			"writer's gorm.Open is back on a bare &gorm.Config{}; "+
+			"the first of them: %s",
+		len(got), got[:min(len(got), 300)],
+	)
+
+	// The adapter drops a miss, so this should be silent too — and
+	// whatever it does write stays inside the stated ceiling.
+	out := captured.String()
+
+	assert.NotContains(
+		t, out, archiveGORMTailMarker,
+		"the far end of the client-chosen value reached the log",
+	)
+
+	for line := range strings.SplitSeq(strings.TrimRight(out, "\n"), "\n") {
+		if line == "" {
+			continue
+		}
+
+		assert.LessOrEqual(
+			t, len(line), middleware.MaxAccessLogLineBytes,
+			"log line exceeded its bound: %s",
+			line[:min(len(line), 300)],
+		)
+	}
+}

internal/gormlog/export_test.go

@@ -0,0 +1,17 @@
+package gormlog
+
+import (
+	"log/slog"
+	"time"
+)
+
+// ExportNewWithSlowThreshold builds a Logger whose slow-statement
+// threshold is d rather than DefaultSlowThreshold, so a test can pin
+// which arm of Trace it is exercising instead of racing the clock on a
+// loaded machine. The threshold is set at construction, like every
+// other field, so the type's concurrency guarantee still holds.
+func ExportNewWithSlowThreshold(
+	log *slog.Logger, d time.Duration,
+) *Logger {
+	return &Logger{log: log, slowThreshold: d}
+}

internal/gormlog/gormlog.go

@@ -0,0 +1,168 @@
+// Package gormlog adapts GORM's logger onto the service's slog
+// logger.
+//
+// GORM's own default logger is not usable here. It is built at package
+// init with log.New(os.Stdout, ...) at LogLevel Warn with
+// IgnoreRecordNotFoundError false, so it writes the fully interpolated
+// SQL — parameters and all — for every statement that returns an
+// error, including gorm.ErrRecordNotFound. Two of this service's
+// lookups miss by design on unauthenticated routes: the entrypoint
+// lookup on /webhook/{uuid}, whose path segment the client picks
+// outright, and the user lookup behind the login form, whose username
+// the client picks outright. Under the default logger each of those
+// misses printed an unbounded, attacker-chosen string, at no level the
+// operator can turn down, past every handler internal/logger installs.
+//
+// This adapter fixes all three properties at once: the lines get a
+// level the operator controls, they are shaped by whichever handler
+// internal/logger selected, and every value a client can influence is
+// spent through logfield.Truncate.
+package gormlog
+
+import (
+	"context"
+	"errors"
+	"fmt"
+	"log/slog"
+	"time"
+
+	gormlogger "gorm.io/gorm/logger"
+	"sneak.berlin/go/webhooker/internal/logfield"
+)
+
+// DefaultSlowThreshold is the duration at or above which a statement
+// is logged as slow. It is GORM's own default, kept deliberately: slow
+// SQL is the one thing GORM's logger reports that nothing else in this
+// service does, so silencing the logger outright would have cost real
+// observability to fix a log-volume defect.
+const DefaultSlowThreshold = 200 * time.Millisecond
+
+// Logger implements gormlogger.Interface on top of an *slog.Logger.
+//
+// It is safe for concurrent use: every field is set at construction
+// and never written again.
+type Logger struct {
+	log           *slog.Logger
+	slowThreshold time.Duration
+}
+
+// Interface compliance is asserted here rather than discovered at the
+// gorm.Open call sites.
+var _ gormlogger.Interface = (*Logger)(nil)
+
+// New returns a GORM logger that writes through log.
+func New(log *slog.Logger) *Logger {
+	return &Logger{
+		log:           log,
+		slowThreshold: DefaultSlowThreshold,
+	}
+}
+
+// LogMode returns the logger unchanged.
+//
+// GORM's LogLevel is deliberately not honoured. Level is the operator's
+// decision and it is expressed once, through LOG_LEVEL and the
+// slog.LevelVar internal/logger holds; a second level knob inside the
+// database layer could only disagree with it. The mapping from GORM's
+// four categories onto slog levels is fixed in Trace below.
+//
+//nolint:ireturn // The interface return is GORM's signature, not a choice.
+func (l *Logger) LogMode(gormlogger.LogLevel) gormlogger.Interface {
+	return l
+}
+
+// Info logs one of GORM's own informational messages.
+func (l *Logger) Info(
+	ctx context.Context, msg string, data ...any,
+) {
+	l.log.InfoContext(ctx, "gorm", "message", format(msg, data...))
+}
+
+// Warn logs one of GORM's own warnings.
+func (l *Logger) Warn(
+	ctx context.Context, msg string, data ...any,
+) {
+	l.log.WarnContext(ctx, "gorm", "message", format(msg, data...))
+}
+
+// Error logs one of GORM's own errors.
+func (l *Logger) Error(
+	ctx context.Context, msg string, data ...any,
+) {
+	l.log.ErrorContext(ctx, "gorm", "message", format(msg, data...))
+}
+
+// Trace reports the outcome of a single statement. GORM calls it for
+// every statement it runs, so the cheap paths stay cheap: fc()
+// renders the interpolated SQL and is called only on a branch that
+// will actually emit.
+//
+// The arms are ordered exactly as GORM's own Trace orders them —
+// non-record-not-found error, then slow, then the routine case — so
+// that a statement which both misses and runs slow is still reported
+// as slow. A miss is the likeliest statement to be slow, since it is
+// the one that scans without finding a row, and ordering the drop
+// ahead of the slow arm would have made this adapter less observant
+// than the IgnoreRecordNotFoundError option it was chosen over.
+func (l *Logger) Trace(
+	ctx context.Context,
+	begin time.Time,
+	fc func() (string, int64),
+	err error,
+) {
+	elapsed := time.Since(begin)
+
+	switch {
+	case err != nil && !errors.Is(err, gormlogger.ErrRecordNotFound):
+		sql, rows := fc()
+		l.log.ErrorContext(ctx, "sql statement failed",
+			"error", logfield.Truncate(err.Error(), logfield.MaxBytes),
+			"sql", logfield.Truncate(sql, logfield.MaxBytes),
+			"rows", rows,
+			"elapsed_ms", elapsed.Milliseconds(),
+		)
+
+	case l.slowThreshold > 0 && elapsed >= l.slowThreshold:
+		sql, rows := fc()
+		l.log.WarnContext(ctx, "slow sql statement",
+			"sql", logfield.Truncate(sql, logfield.MaxBytes),
+			"rows", rows,
+			"elapsed_ms", elapsed.Milliseconds(),
+			"threshold_ms", l.slowThreshold.Milliseconds(),
+		)
+
+	case err != nil:
+		// gorm.ErrRecordNotFound is not an error on the paths that
+		// produce it here: an invented entrypoint UUID and an unknown
+		// username are the expected outcome of an unauthenticated
+		// request, not a fault. This is the IgnoreRecordNotFoundError
+		// behaviour, and it is unconditional rather than configurable
+		// because no caller in this service wants the other one — the
+		// two handlers that care already record the miss themselves,
+		// at DEBUG, without the SQL. A miss that ran slow has already
+		// been reported by the arm above.
+		return
+
+	case l.log.Enabled(ctx, slog.LevelDebug):
+		sql, rows := fc()
+		l.log.DebugContext(ctx, "sql statement",
+			"sql", logfield.Truncate(sql, logfield.MaxBytes),
+			"rows", rows,
+			"elapsed_ms", elapsed.Milliseconds(),
+		)
+	}
+}
+
+// format renders one of GORM's printf-style internal messages and
+// bounds it. GORM builds these itself, but they can quote a value the
+// statement carried, so they are spent through the same budget as
+// everything else rather than trusted.
+func format(msg string, data ...any) string {
+	if len(data) == 0 {
+		return logfield.Truncate(msg, logfield.MaxBytes)
+	}
+
+	return logfield.Truncate(
+		fmt.Sprintf(msg, data...), logfield.MaxBytes,
+	)
+}

internal/gormlog/gormlog_test.go

@@ -0,0 +1,425 @@
+package gormlog_test
+
+import (
+	"bytes"
+	"context"
+	"database/sql"
+	"fmt"
+	"log/slog"
+	"path/filepath"
+	"strings"
+	"testing"
+	"time"
+
+	"github.com/stretchr/testify/assert"
+	"github.com/stretchr/testify/require"
+	"gorm.io/driver/sqlite"
+	"gorm.io/gorm"
+	_ "modernc.org/sqlite" // Pure Go SQLite driver.
+	"sneak.berlin/go/webhooker/internal/gormlog"
+	"sneak.berlin/go/webhooker/internal/middleware"
+)
+
+// fillBytes is how much client-chosen text each case drives into the
+// statement. It is well past every budget in play, so a value that
+// arrives short arrived short because something cut it.
+const fillBytes = 8 << 10
+
+// tailMarker sits at the far end of every generated value. A line that
+// contains it carried the whole value, which means nothing cut it — so
+// a value that merely happened to be short cannot pass for a truncated
+// one.
+const tailMarker = "ENDOFCLIENTVALUE"
+
+// fills are the characters a client can drive into a SQL parameter,
+// chosen for what the log handlers charge for them rather than for
+// looking dangerous.
+//
+// The C0 control is the one that matters. Both handlers spell U+0001
+// as a six-byte escape for the single byte it costs a client to send,
+// which is the widest multiplier available in the basic multilingual
+// plane and the case a raw-byte budget breaks on first. The astral
+// non-printable costs ten under the text handler, four more than the
+// JSON handler ever spends.
+func fills() []struct {
+	name string
+	fill string
+} {
+	return []struct {
+		name string
+		fill string
+	}{
+		{"plain", "x"},
+		{"quote", `"`},
+		{"backslash", `\`},
+		{"tab", "\t"},
+		{"newline", "\n"},
+		{"c0_control", "\x01"},
+		{"astral_nonprintable", "\U0001000C"},
+	}
+}
+
+// clientValue builds a value of at least fillBytes raw bytes out of
+// fill, ending in tailMarker.
+func clientValue(fill string) string {
+	var b strings.Builder
+
+	for b.Len() < fillBytes {
+		b.WriteString(fill)
+	}
+
+	b.WriteString(tailMarker)
+
+	return b.String()
+}
+
+// handlers are the two slog handlers internal/logger can install. The
+// ceiling is quoted to operators unqualified, so every case is
+// asserted under both.
+func handlers() []struct {
+	name string
+	make func(*bytes.Buffer) slog.Handler
+} {
+	opts := &slog.HandlerOptions{Level: slog.LevelDebug}
+
+	return []struct {
+		name string
+		make func(*bytes.Buffer) slog.Handler
+	}{
+		{"json", func(b *bytes.Buffer) slog.Handler {
+			return slog.NewJSONHandler(b, opts)
+		}},
+		{"text", func(b *bytes.Buffer) slog.Handler {
+			return slog.NewTextHandler(b, opts)
+		}},
+	}
+}
+
+type thing struct {
+	ID   string `gorm:"primaryKey"`
+	Name string
+}
+
+// neverSlow is a slow-statement threshold no statement in this file
+// can reach. Cases that are about a non-slow arm of Trace set it, so
+// that a machine under load cannot turn a miss into a slow report and
+// decide the outcome for them.
+const neverSlow = time.Hour
+
+// alwaysSlow makes every statement count as slow, so the slow arm is
+// reached without the test waiting for it.
+const alwaysSlow = time.Nanosecond
+
+// openDB opens a real SQLite database behind the adapter under test,
+// so every assertion below is made against SQL that GORM actually
+// rendered rather than against a string a test wrote by hand. slow is
+// the adapter's slow-statement threshold.
+func openDB(
+	t *testing.T, buf *bytes.Buffer, h slog.Handler, slow time.Duration,
+) *gorm.DB {
+	t.Helper()
+
+	sqlDB, err := sql.Open("sqlite", fmt.Sprintf(
+		"file:%s?mode=rwc",
+		filepath.Join(t.TempDir(), "gormlog.db"),
+	))
+	require.NoError(t, err)
+
+	t.Cleanup(func() { _ = sqlDB.Close() })
+
+	gl := gormlog.ExportNewWithSlowThreshold(slog.New(h), slow)
+
+	gdb, err := gorm.Open(
+		sqlite.Dialector{Conn: sqlDB},
+		&gorm.Config{Logger: gl},
+	)
+	require.NoError(t, err)
+
+	require.NoError(t, gdb.AutoMigrate(&thing{}))
+
+	// Migration chatter is not what any of these cases is about.
+	buf.Reset()
+
+	return gdb
+}
+
+// assertBounded holds every line the adapter wrote to the stated
+// ceiling and proves each was cut rather than merely short.
+func assertBounded(t *testing.T, out string) {
+	t.Helper()
+
+	assert.NotContains(
+		t, out, tailMarker,
+		"the far end of the client value reached the log, so "+
+			"nothing truncated it",
+	)
+
+	for line := range strings.SplitSeq(
+		strings.TrimRight(out, "\n"), "\n",
+	) {
+		if line == "" {
+			continue
+		}
+
+		assert.LessOrEqual(
+			t, len(line), middleware.MaxAccessLogLineBytes,
+			"log line exceeded its bound: %s",
+			line[:min(len(line), 300)],
+		)
+	}
+}
+
+// TestRecordNotFound_WritesNothing is the defect itself. GORM's own
+// default logger prints the fully interpolated SELECT on every
+// ErrRecordNotFound, and on this service's two unauthenticated
+// lookups the interpolated parameter is whatever the client sent.
+func TestRecordNotFound_WritesNothing(t *testing.T) {
+	t.Parallel()
+
+	for _, h := range handlers() {
+		for _, f := range fills() {
+			t.Run(h.name+"/"+f.name, func(t *testing.T) {
+				t.Parallel()
+
+				var buf bytes.Buffer
+
+				gdb := openDB(t, &buf, h.make(&buf), neverSlow)
+
+				var got thing
+
+				err := gdb.Where(
+					"id = ?", clientValue(f.fill),
+				).First(&got).Error
+				require.ErrorIs(t, err, gorm.ErrRecordNotFound)
+
+				assert.Empty(
+					t, buf.String(),
+					"a miss on a client-chosen key must not "+
+						"write a log line",
+				)
+			})
+		}
+	}
+}
+
+// TestSlowRecordNotFound_IsStillReportedSlow pins the arm ordering in
+// Trace against the drop above.
+//
+// GORM's own Trace orders its cases error-that-is-not-a-miss, then
+// slow, then routine, so IgnoreRecordNotFoundError: true — the cheap
+// option this adapter was chosen over — still reports a miss that ran
+// slow. An adapter that dropped the miss first would be strictly less
+// observant than the option it replaced, on exactly the two lookups
+// this package exists for. A miss is also the statement most likely to
+// be slow, since it is the one that scans without finding a row.
+func TestSlowRecordNotFound_IsStillReportedSlow(t *testing.T) {
+	t.Parallel()
+
+	for _, h := range handlers() {
+		for _, f := range fills() {
+			t.Run(h.name+"/"+f.name, func(t *testing.T) {
+				t.Parallel()
+
+				var buf bytes.Buffer
+
+				gdb := openDB(t, &buf, h.make(&buf), alwaysSlow)
+
+				var got thing
+
+				err := gdb.Where(
+					"id = ?", clientValue(f.fill),
+				).First(&got).Error
+				require.ErrorIs(t, err, gorm.ErrRecordNotFound)
+
+				assert.Contains(
+					t, buf.String(), "slow sql statement",
+					"a slow statement that missed was not "+
+						"reported as slow",
+				)
+				assertBounded(t, buf.String())
+			})
+		}
+	}
+}
+
+// TestRecordNotFoundFlood_DoesNotGrowWithInput states the definition
+// of done directly: a flood of misses at two input sizes 64 times
+// apart must cost the same number of bytes of log.
+func TestRecordNotFoundFlood_DoesNotGrowWithInput(t *testing.T) {
+	t.Parallel()
+
+	const requests = 50
+
+	flood := func(t *testing.T, size int) int {
+		t.Helper()
+
+		var buf bytes.Buffer
+
+		gdb := openDB(
+			t, &buf,
+			slog.NewJSONHandler(&buf, &slog.HandlerOptions{
+				Level: slog.LevelDebug,
+			}),
+			neverSlow,
+		)
+
+		value := strings.Repeat("\x01", size)
+
+		for range requests {
+			var got thing
+
+			_ = gdb.Where("id = ?", value).First(&got).Error
+		}
+
+		return buf.Len()
+	}
+
+	small := flood(t, 128)
+	big := flood(t, 128*64)
+
+	assert.Equal(
+		t, small, big,
+		"log volume tracked the size of the client's input",
+	)
+}
+
+// TestStatementError_LineIsBounded covers the branch that does log.
+// A driver error is not ErrRecordNotFound, so the interpolated
+// statement is written — and on an insert the interpolated value is
+// still whatever the client supplied.
+func TestStatementError_LineIsBounded(t *testing.T) {
+	t.Parallel()
+
+	for _, h := range handlers() {
+		for _, f := range fills() {
+			t.Run(h.name+"/"+f.name, func(t *testing.T) {
+				t.Parallel()
+
+				var buf bytes.Buffer
+
+				gdb := openDB(t, &buf, h.make(&buf), neverSlow)
+
+				row := thing{ID: clientValue(f.fill), Name: "a"}
+
+				require.NoError(t, gdb.Create(&row).Error)
+
+				buf.Reset()
+
+				// The same primary key a second time: a UNIQUE
+				// constraint failure, which is an error GORM logs.
+				err := gdb.Create(&thing{
+					ID: row.ID, Name: "b",
+				}).Error
+				require.Error(t, err)
+
+				assert.Contains(
+					t, buf.String(), "sql statement failed",
+				)
+				assertBounded(t, buf.String())
+			})
+		}
+	}
+}
+
+// TestSucceedingStatement_LineIsBoundedOnEitherArm covers the two
+// arms a statement that returns no error can take, over the same
+// query, so neither can be bounded by accident of the other.
+//
+//   - slow. Silencing GORM outright would have been the cheaper fix
+//     and would have cost this report, which is the one thing GORM's
+//     logger gave an operator that nothing else in this service does.
+//   - routine. The branch an operator reaches by turning the level
+//     down to DEBUG: every statement is reported, so every
+//     statement's interpolated parameters have to be bounded too.
+func TestSucceedingStatement_LineIsBoundedOnEitherArm(t *testing.T) {
+	t.Parallel()
+
+	arms := []struct {
+		name string
+		slow time.Duration
+		want string
+	}{
+		{"slow", alwaysSlow, "slow sql statement"},
+		{"routine", neverSlow, "sql statement"},
+	}
+
+	for _, a := range arms {
+		for _, h := range handlers() {
+			for _, f := range fills() {
+				name := a.name + "/" + h.name + "/" + f.name
+
+				t.Run(name, func(t *testing.T) {
+					t.Parallel()
+
+					var buf bytes.Buffer
+
+					gdb := openDB(t, &buf, h.make(&buf), a.slow)
+
+					var got []thing
+
+					require.NoError(t, gdb.Where(
+						"name = ?", clientValue(f.fill),
+					).Find(&got).Error)
+
+					assert.Contains(t, buf.String(), a.want)
+					assertBounded(t, buf.String())
+				})
+			}
+		}
+	}
+}
+
+// TestGORMOwnMessages_AreBounded covers the three printf-style
+// entry points. GORM builds these itself, but nothing stops one of
+// them quoting a value the statement carried.
+func TestGORMOwnMessages_AreBounded(t *testing.T) {
+	t.Parallel()
+
+	for _, h := range handlers() {
+		for _, f := range fills() {
+			t.Run(h.name+"/"+f.name, func(t *testing.T) {
+				t.Parallel()
+
+				var buf bytes.Buffer
+
+				gl := gormlog.New(slog.New(h.make(&buf)))
+				ctx := context.Background()
+				value := clientValue(f.fill)
+
+				gl.Info(ctx, "%s", value)
+				gl.Warn(ctx, "%s", value)
+				gl.Error(ctx, "%s", value)
+
+				// The no-argument form, which is how GORM reports
+				// most of its own conditions. Reached through a
+				// function value so the vet printf check does not
+				// read the message as a format string — which is
+				// also why the adapter does not.
+				noArgs := func(
+					f func(context.Context, string, ...any),
+					msg string,
+				) {
+					f(ctx, msg)
+				}
+				noArgs(gl.Info, value)
+
+				assertBounded(t, buf.String())
+			})
+		}
+	}
+}
+
+// TestLogMode_KeepsTheOperatorsLevel records that GORM's own level
+// knob is deliberately inert: level belongs to LOG_LEVEL, and a
+// second one inside the database layer could only disagree with it.
+func TestLogMode_KeepsTheOperatorsLevel(t *testing.T) {
+	t.Parallel()
+
+	var buf bytes.Buffer
+
+	gl := gormlog.New(slog.New(slog.NewJSONHandler(
+		&buf, &slog.HandlerOptions{Level: slog.LevelDebug},
+	)))
+
+	assert.Same(t, gl, gl.LogMode(0))
+}

internal/handlers/gormlogbound_test.go

@@ -0,0 +1,477 @@
+package handlers_test
+
+import (
+	"bytes"
+	"context"
+	"io"
+	"log"
+	"net/http"
+	"net/http/httptest"
+	"net/url"
+	"os"
+	"strconv"
+	"strings"
+	"sync"
+	"testing"
+	"time"
+
+	"github.com/go-chi/chi"
+	"github.com/stretchr/testify/assert"
+	"github.com/stretchr/testify/require"
+	"gorm.io/gorm"
+	gormlogger "gorm.io/gorm/logger"
+	"sneak.berlin/go/webhooker/internal/database"
+	"sneak.berlin/go/webhooker/internal/handlers"
+	"sneak.berlin/go/webhooker/internal/middleware"
+)
+
+// gormBoundTailMarker sits at the far end of every client-chosen value
+// this file sends. Its presence in the log means the whole value
+// reached the log, so a value that merely happened to be short cannot
+// pass for a truncated one.
+const gormBoundTailMarker = "ENDOFCLIENTVALUE"
+
+// gormBoundFills are the characters a client can drive through the
+// receiver path segment and the login username, chosen for what a log
+// handler charges for them.
+//
+// The bare C0 control is the one that matters: both handlers spell
+// U+0001 as a six-byte escape for the one byte it costs to send, the
+// widest multiplier available below U+10000 and the case a raw-byte
+// budget breaks on first. GORM's default logger applies no budget at
+// all, so under the mutation every one of these arrives whole.
+func gormBoundFills() []struct {
+	name string
+	fill string
+} {
+	return []struct {
+		name string
+		fill string
+	}{
+		{"plain", "x"},
+		{"quote", `"`},
+		{"backslash", `\`},
+		{"tab", "\t"},
+		{"newline", "\n"},
+		{"c0_control", "\x01"},
+		{"astral_nonprintable", "\U0001000C"},
+	}
+}
+
+// syncBuf collects captured output from the goroutine draining the
+// pipe.
+type syncBuf struct {
+	mu sync.Mutex
+	b  bytes.Buffer
+}
+
+func (s *syncBuf) Write(p []byte) (int, error) {
+	s.mu.Lock()
+	defer s.mu.Unlock()
+
+	return s.b.Write(p)
+}
+
+func (s *syncBuf) String() string {
+	s.mu.Lock()
+	defer s.mu.Unlock()
+
+	return s.b.String()
+}
+
+func (s *syncBuf) reset() {
+	s.mu.Lock()
+	defer s.mu.Unlock()
+
+	s.b.Reset()
+}
+
+// stdoutCapture redirects os.Stdout for the duration of a test.
+//
+// internal/logger builds its handler over os.Stdout at construction
+// time, so redirecting the variable before the application is built
+// captures everything the service logger — and therefore the GORM
+// adapter, which writes through it — emits.
+type stdoutCapture struct {
+	buf  *syncBuf
+	r    *os.File
+	w    *os.File
+	orig *os.File
+	done chan struct{}
+	seq  int
+}
+
+func captureStdout(t *testing.T) *stdoutCapture {
+	t.Helper()
+
+	r, w, err := os.Pipe()
+	require.NoError(t, err)
+
+	c := &stdoutCapture{
+		buf:  &syncBuf{},
+		r:    r,
+		w:    w,
+		orig: os.Stdout,
+		done: make(chan struct{}),
+	}
+
+	os.Stdout = w
+
+	go func() {
+		defer close(c.done)
+
+		_, _ = io.Copy(c.buf, r)
+	}()
+
+	t.Cleanup(func() {
+		os.Stdout = c.orig
+		_ = w.Close()
+
+		<-c.done
+
+		_ = r.Close()
+	})
+
+	return c
+}
+
+// drain returns everything written since the previous drain and
+// clears the buffer.
+//
+// A sentinel is pushed through the same pipe and waited for, so the
+// draining goroutine is known to have caught up before the buffer is
+// read. Without it the comparison below would race the reader rather
+// than measure the writers.
+func (c *stdoutCapture) drain(t *testing.T) string {
+	t.Helper()
+
+	c.seq++
+
+	sentinel := "\n<<drain-" + strconv.Itoa(c.seq) + ">>\n"
+
+	_, err := c.w.WriteString(sentinel)
+	require.NoError(t, err)
+
+	deadline := time.Now().Add(10 * time.Second)
+	for !strings.Contains(c.buf.String(), sentinel) {
+		require.False(
+			t, time.Now().After(deadline),
+			"timed out waiting for captured output",
+		)
+		time.Sleep(time.Millisecond)
+	}
+
+	out := strings.Replace(c.buf.String(), sentinel, "", 1)
+
+	c.buf.reset()
+
+	return out
+}
+
+// teeStdout writes to a buffer and to whatever os.Stdout is at the
+// moment of the write.
+//
+// The second half is the point. GORM's package-level default logger
+// resolves os.Stdout once, at package init, so a logger built over the
+// variable would keep writing to the real terminal no matter what a
+// test redirects. Resolving it per write puts the bytes a defaulted
+// gorm.Config would cost in production into the same capture as
+// everything else internal/logger emits, which is what lets the volume
+// assertions below measure the whole writer set rather than one member
+// of it.
+type teeStdout struct {
+	buf *syncBuf
+}
+
+func (w teeStdout) Write(p []byte) (int, error) {
+	_, _ = os.Stdout.Write(p)
+
+	return w.buf.Write(p)
+}
+
+// captureGORMDefault replaces GORM's package-level default logger with
+// one configured exactly as GORM configures its own, writing to a
+// buffer and to os.Stdout.
+//
+// This is the mutation detector. gormlogger.Default is what a bare
+// &gorm.Config{} installs, and its config here is GORM's verbatim —
+// Warn, IgnoreRecordNotFoundError false — so a reverted call site
+// behaves as it would in production rather than as a test dialed it.
+// With every gorm.Open in this service naming its own logger, nothing
+// consults this value and the buffer stays empty; revert any one of
+// the three and the interpolated SQL lands here.
+func captureGORMDefault(t *testing.T) *syncBuf {
+	t.Helper()
+
+	buf := &syncBuf{}
+	orig := gormlogger.Default
+
+	gormlogger.Default = gormlogger.New(
+		log.New(teeStdout{buf: buf}, "", log.LstdFlags),
+		gormlogger.Config{
+			SlowThreshold:             200 * time.Millisecond,
+			LogLevel:                  gormlogger.Warn,
+			IgnoreRecordNotFoundError: false,
+			Colorful:                  false,
+		},
+	)
+
+	t.Cleanup(func() { gormlogger.Default = orig })
+
+	return buf
+}
+
+// floodUnauthenticated drives reps requests at each of the two
+// unauthenticated lookups that miss by design, for every fill, with a
+// client-chosen value of size raw bytes.
+func floodUnauthenticated(
+	t *testing.T, h *handlers.Handlers, size, reps int,
+) int {
+	t.Helper()
+
+	requests := 0
+
+	for _, f := range gormBoundFills() {
+		var b strings.Builder
+
+		for b.Len() < size {
+			b.WriteString(f.fill)
+		}
+
+		b.WriteString(gormBoundTailMarker)
+
+		value := b.String()
+
+		for range reps {
+			postWebhook(t, h, value)
+			postLogin(t, h, value)
+
+			requests += 2
+		}
+	}
+
+	return requests
+}
+
+// floodPerWebhook drives the same client-chosen values at the second
+// gorm.Open site, the per-webhook database internal/database's
+// WebhookDBManager opens.
+//
+// That site is behind authentication in production, so this is not
+// part of the unauthenticated flood above and is counted separately.
+// It is here because the ceiling the README states covers every
+// writer, and the manager is one of them: with nothing driving it, a
+// bare &gorm.Config{} could be restored at
+// internal/database/webhook_db_manager.go and the whole suite would
+// stay green.
+func floodPerWebhook(
+	t *testing.T, mgr *database.WebhookDBManager, size, reps int,
+) int {
+	t.Helper()
+
+	requests := 0
+
+	for _, f := range gormBoundFills() {
+		var b strings.Builder
+
+		for b.Len() < size {
+			b.WriteString(f.fill)
+		}
+
+		b.WriteString(gormBoundTailMarker)
+
+		value := b.String()
+
+		db, err := mgr.GetDB("pin-" + f.name)
+		require.NoError(t, err)
+
+		for range reps {
+			var got database.Event
+
+			err = db.Where("id = ?", value).First(&got).Error
+			require.ErrorIs(t, err, gorm.ErrRecordNotFound)
+
+			requests++
+		}
+	}
+
+	return requests
+}
+
+// postWebhook drives the receiver with an invented entrypoint path.
+// The route pattern matches any single segment, so every byte of the
+// value is the client's, and the lookup behind it misses by design.
+func postWebhook(
+	t *testing.T, h *handlers.Handlers, entrypoint string,
+) {
+	t.Helper()
+
+	req := httptest.NewRequestWithContext(
+		context.Background(), http.MethodPost, "/webhook/x",
+		strings.NewReader("{}"),
+	)
+
+	rctx := chi.NewRouteContext()
+	rctx.URLParams.Add("uuid", entrypoint)
+
+	req = req.WithContext(context.WithValue(
+		req.Context(), chi.RouteCtxKey, rctx,
+	))
+
+	w := httptest.NewRecorder()
+	h.HandleWebhook().ServeHTTP(w, req)
+
+	require.Equal(t, http.StatusNotFound, w.Code)
+}
+
+// postLogin submits the login form with an unknown username. The
+// field is bounded only by the 1 MB body cap, and the lookup behind
+// it misses by design.
+func postLogin(
+	t *testing.T, h *handlers.Handlers, username string,
+) {
+	t.Helper()
+
+	form := url.Values{}
+	form.Set("username", username)
+	form.Set("password", "not-the-password")
+
+	req := httptest.NewRequestWithContext(
+		context.Background(), http.MethodPost, "/pages/login",
+		strings.NewReader(form.Encode()),
+	)
+	req.Header.Set(
+		"Content-Type", "application/x-www-form-urlencoded",
+	)
+
+	w := httptest.NewRecorder()
+	h.HandleLoginSubmit().ServeHTTP(w, req)
+
+	// 401 while the client still has failure budget against this
+	// username, 429 once the login guard has taken it away. Both
+	// outcomes sit behind the user lookup, which is the query this
+	// test is here to drive.
+	require.Contains(
+		t,
+		[]int{http.StatusUnauthorized, http.StatusTooManyRequests},
+		w.Code,
+	)
+}
+
+// assertFloodBounded holds every captured line to the stated ceiling
+// and proves nothing carried a whole client value.
+func assertFloodBounded(t *testing.T, label, out string) {
+	t.Helper()
+
+	assert.NotContains(
+		t, out, gormBoundTailMarker,
+		"%s: the far end of a client-chosen value reached the "+
+			"log, so nothing truncated it", label,
+	)
+
+	for line := range strings.SplitSeq(
+		strings.TrimRight(out, "\n"), "\n",
+	) {
+		if line == "" {
+			continue
+		}
+
+		assert.LessOrEqual(
+			t, len(line), middleware.MaxAccessLogLineBytes,
+			"%s: log line exceeded its bound: %s",
+			label, line[:min(len(line), 300)],
+		)
+	}
+}
+
+// TestFlood_NoWriterGrowsWithTheInput is the definition of done for
+// the GORM logger defect, stated over every writer at once, for two of
+// this service's three gorm.Open sites: the main database behind the
+// two unauthenticated lookups, and the per-webhook database the
+// WebhookDBManager opens. The third, the archive writer, is pinned in
+// internal/delivery, where its type lives.
+//
+// What each assertion is worth, since two of the three would pass
+// against a service that had never been fixed if the capture were set
+// up differently:
+//
+//   - The gormDefault check is the sharp one. It fires the moment any
+//     gorm.Open in this service goes back to a bare &gorm.Config{}.
+//   - The volume and per-line checks bite only because the replaced
+//     default logger tees into os.Stdout, so a reverted call site
+//     shows up in the same capture as everything internal/logger
+//     writes — the way it would in production. Without that tee both
+//     were vacuous: at INFO the two handler misses log at DEBUG and
+//     the adapter drops the record-not-found, so the capture holds
+//     nothing but fixed-string warnings.
+//
+// The level is left where newTestApp leaves it, at INFO, deliberately.
+// At DEBUG the handlers' own miss lines log the client-chosen
+// entrypoint and username untruncated — the first carve-out in the
+// README's ceiling section, and https://git.eeqj.de/sneak/webhooker/issues/176's
+// to fix, not this one's.
+//
+// It is deliberately not parallel: it redirects os.Stdout and replaces
+// gormlogger.Default, both of which are process-global. Go runs every
+// non-parallel top-level test to completion before it resumes the
+// parallel ones, so nothing else in this package is running while the
+// capture is installed.
+//
+//nolint:paralleltest // Deliberately sequential; see above.
+func TestFlood_NoWriterGrowsWithTheInput(t *testing.T) {
+	const (
+		smallBytes = 128
+		bigBytes   = 8 << 10
+		reps       = 5
+	)
+
+	gormDefault := captureGORMDefault(t)
+	capture := captureStdout(t)
+
+	var (
+		h   *handlers.Handlers
+		mgr *database.WebhookDBManager
+	)
+
+	app := newTestApp(t, &h, &mgr)
+	app.RequireStart()
+
+	t.Cleanup(app.RequireStop)
+
+	// Startup chatter is not what this test measures.
+	capture.drain(t)
+
+	floodUnauthenticated(t, h, smallBytes, reps)
+	floodPerWebhook(t, mgr, smallBytes, reps)
+
+	small := capture.drain(t)
+
+	requests := floodUnauthenticated(t, h, bigBytes, reps)
+	requests += floodPerWebhook(t, mgr, bigBytes, reps)
+	big := capture.drain(t)
+
+	assertFloodBounded(t, "small flood", small)
+	assertFloodBounded(t, "big flood", big)
+
+	// GORM's default logger is what the defect was. Nothing in this
+	// service may reach it.
+	got := gormDefault.String()
+	assert.Empty(
+		t, got,
+		"GORM's default logger wrote %d bytes; the first of them: %s",
+		len(got), got[:min(len(got), 300)],
+	)
+
+	// The same flood, with 64 times the client-chosen input, must not
+	// buy 64 times the log. A few bytes of slack covers a latency
+	// field changing width; the input grew by roughly half a megabyte.
+	const slackPerRequest = 64
+
+	assert.LessOrEqual(
+		t, len(big), len(small)+slackPerRequest*requests,
+		"log volume tracked the size of the client's input: "+
+			"%d bytes at %d bytes of input per request, %d bytes "+
+			"at %d",
+		len(small), smallBytes, len(big), bigBytes,
+	)
+}

internal/logfield/logfield.go

@@ -0,0 +1,140 @@
+// Package logfield bounds a client-supplied value against what the log
+// handler will actually emit for it, so a line's size is set by this
+// service rather than by the client that provoked it.
+//
+// It lives outside internal/middleware because more than one writer
+// needs it: the access log, and the GORM adapter in internal/gormlog,
+// which logs SQL with the client-chosen parameters interpolated into
+// it. One budget, one implementation.
+package logfield
+
+import (
+	"strings"
+	"unicode"
+	"unicode/utf8"
+)
+
+const (
+	// MaxBytes is the default budget for a field whose value the
+	// client supplies outright. It is spent in ENCODED bytes (see
+	// Truncate), so 512 still holds a real browser's User-Agent whole
+	// — those are plain ASCII, which encodes one byte for one — while
+	// a value built from characters the encoder escapes keeps a
+	// shorter prefix. That is the intended trade: 500 quotation marks
+	// are not a debugging asset.
+	MaxBytes = 512
+
+	// truncationMarker is appended to any value Truncate cut, so a
+	// short value and a truncated one cannot be confused. It is
+	// charged on top of the budget, not inside it.
+	truncationMarker = "[truncated]"
+)
+
+// EncodedBytes is what r costs on the line once the log handler has
+// escaped it, taking the worse of the two handlers internal/logger
+// configures.
+//
+// slog's JSON handler escapes quote, backslash, newline, carriage
+// return and tab to two bytes each, and every other C0 control plus
+// LINE SEPARATOR and PARAGRAPH SEPARATOR to a six-byte \u escape; it
+// passes every other rune through as its own UTF-8. Its text handler
+// quotes with strconv.Quote, which spells a non-printable rune below
+// U+10000 as \uXXXX but one at or above U+10000 as \UXXXXXXXX — ten
+// bytes, not six. The text handler is therefore the worse of the two
+// for every non-printable rune, and by four bytes apiece for the
+// 955,086 unassigned, private-use and format code points on planes 1
+// to 16.
+//
+// Charging ten there is what makes the stated per-line ceiling hold
+// for the tty handler as well: U+1000C encodes as F0 90 80 8C, every
+// byte >= 0x80, which httpguts.ValidHeaderFieldValue accepts and
+// net/textproto does not strip, so a header can be filled with them.
+//
+// Both handlers pass printable runes through as their own UTF-8, so
+// unicode.IsPrint separates the escaped cases from the plain ones for
+// either handler.
+func EncodedBytes(r rune) int {
+	const (
+		// A backslash and the character itself.
+		shortEscapeBytes = 2
+		// \uXXXX, which is also the width of \u00XX.
+		escapedRuneBytes = 6
+		// \UXXXXXXXX, strconv.Quote's spelling of a non-printable
+		// rune outside the basic multilingual plane.
+		escapedAstralRuneBytes = 10
+		// The first code point strconv.Quote spells with \U.
+		firstAstralRune = 0x10000
+	)
+
+	switch {
+	case r == '"' || r == '\\' || r == '\n' || r == '\r' || r == '\t':
+		return shortEscapeBytes
+	case !unicode.IsPrint(r) && r >= firstAstralRune:
+		return escapedAstralRuneBytes
+	case !unicode.IsPrint(r):
+		return escapedRuneBytes
+	default:
+		return utf8.RuneLen(r)
+	}
+}
+
+// Truncate caps s at maxBytes of ENCODED output, marking the value
+// when it cuts.
+//
+// Budgeting raw bytes would not bound the line. Escaping only ever
+// grows a value, so a raw budget spent on characters the encoder
+// escapes buys a field several times its nominal size — and the line
+// is the thing an operator is told to multiply by their request rate.
+// Charging each rune what it will actually cost is what makes the
+// stated ceiling true rather than merely larger. The visible
+// consequence is that an escape-heavy value keeps a shorter prefix
+// than a plain one, which is the correct trade.
+//
+// The result is always valid UTF-8. A cut on a byte boundary can split
+// a multi-byte rune, and a header — or a SQL literal — can carry bytes
+// that were never valid UTF-8 to begin with; both are dropped rather
+// than kept, since an encoder would otherwise spend six bytes
+// replacing each one.
+func Truncate(s string, maxBytes int) string {
+	// No rune encodes to fewer bytes than it occupies, so nothing past
+	// maxBytes raw can fit the budget. Slicing first bounds the scan
+	// below to the budget rather than to the size of the value the
+	// client sent.
+	window, cut := s, false
+	if len(window) > maxBytes {
+		window, cut = window[:maxBytes], true
+	}
+
+	var (
+		kept  strings.Builder
+		spent int
+	)
+
+	for i := 0; i < len(window); {
+		r, size := utf8.DecodeRuneInString(window[i:])
+		if r == utf8.RuneError && size == 1 {
+			i += size
+
+			continue
+		}
+
+		cost := EncodedBytes(r)
+		if spent+cost > maxBytes {
+			cut = true
+
+			break
+		}
+
+		spent += cost
+
+		kept.WriteString(window[i : i+size])
+
+		i += size
+	}
+
+	if !cut {
+		return kept.String()
+	}
+
+	return kept.String() + truncationMarker
+}

internal/logfield/logfield_test.go

@@ -0,0 +1,202 @@
+package logfield_test
+
+import (
+	"bytes"
+	"log/slog"
+	"strings"
+	"testing"
+	"unicode/utf8"
+
+	"github.com/stretchr/testify/assert"
+	"github.com/stretchr/testify/require"
+	"sneak.berlin/go/webhooker/internal/logfield"
+)
+
+// encodedCost is what a whole string costs on a line, by the same
+// accounting Truncate spends its budget with.
+func encodedCost(s string) int {
+	total := 0
+	for _, r := range s {
+		total += logfield.EncodedBytes(r)
+	}
+
+	return total
+}
+
+// TestTruncate_SpendsEncodedBytesNotRawBytes is the zero-headroom
+// version of the line-length assertions elsewhere.
+//
+// A line ceiling has slack in it by construction, so a line-level
+// assertion only catches a raw-byte budget for the fills with the
+// widest multiplier. Here the budget is checked against exactly what
+// it bought: a value built from a single rune must keep exactly
+// MaxBytes/EncodedBytes(r) of them, for every rune, with nothing
+// spare.
+func TestTruncate_SpendsEncodedBytesNotRawBytes(t *testing.T) {
+	t.Parallel()
+
+	for name, r := range map[string]rune{
+		"plain":                'x',
+		"quote":                '"',
+		"backslash":            '\\',
+		"tab":                  '\t',
+		"newline":              '\n',
+		"carriage_return":      '\r',
+		"c0_control":           '
',
+		"del":                  '',
+		"line_separator":       '
',
+		"astral_nonprintable":  '\U0001000C',
+		"multibyte_printable":  'é',
+		"three_byte_printable": '€',
+		"emoji_printable":      '\U0001F600',
+	} {
+		t.Run(name, func(t *testing.T) {
+			t.Parallel()
+
+			cost := logfield.EncodedBytes(r)
+			want := logfield.MaxBytes / cost
+
+			// Far past the budget under either accounting.
+			in := strings.Repeat(string(r), logfield.MaxBytes*2)
+
+			got := logfield.Truncate(in, logfield.MaxBytes)
+
+			assert.True(
+				t, strings.HasSuffix(got, "[truncated]"),
+				"a value past the budget must be marked",
+			)
+
+			kept := strings.TrimSuffix(got, "[truncated]")
+
+			assert.Equal(
+				t, want, utf8.RuneCountInString(kept),
+				"budget bought the wrong number of runes at "+
+					"%d encoded bytes each", cost,
+			)
+			assert.LessOrEqual(
+				t, encodedCost(kept), logfield.MaxBytes,
+			)
+		})
+	}
+}
+
+// TestEncodedBytes_CoversWhatTheHandlersActuallyEmit measures the
+// charge against what slog really writes rather than against a
+// reading of its source, over both handlers internal/logger can
+// install. An undercharged rune fails here rather than quietly
+// falsifying every stated line ceiling.
+func TestEncodedBytes_CoversWhatTheHandlersActuallyEmit(t *testing.T) {
+	t.Parallel()
+
+	emitted := func(h func(*bytes.Buffer) slog.Handler, r rune) int {
+		var withValue, withoutValue bytes.Buffer
+
+		slog.New(h(&withValue)).Info("m", "v", string(r))
+		slog.New(h(&withoutValue)).Info("m", "v", "")
+
+		return withValue.Len() - withoutValue.Len()
+	}
+
+	jsonHandler := func(b *bytes.Buffer) slog.Handler {
+		return slog.NewJSONHandler(b, &slog.HandlerOptions{
+			ReplaceAttr: dropTime,
+		})
+	}
+	textHandler := func(b *bytes.Buffer) slog.Handler {
+		return slog.NewTextHandler(b, &slog.HandlerOptions{
+			ReplaceAttr: dropTime,
+		})
+	}
+
+	// Every code point below U+0800 densely — which covers all of C0,
+	// DEL, C1 and the two-byte range — plus the separators only the
+	// JSON handler escapes, plus a stratified walk across the rest of
+	// the assigned space and into the astral planes.
+	var runes []rune
+
+	for r := rune(1); r < 0x800; r++ {
+		runes = append(runes, r)
+	}
+
+	runes = append(
+		runes,
+		'
',          // LINE SEPARATOR, escaped only by the JSON handler
+		'
',          // PARAGRAPH SEPARATOR, likewise
+		rune(0xFEFF), // ZERO WIDTH NO-BREAK SPACE
+		rune(0xFFFD), // REPLACEMENT CHARACTER
+	)
+
+	for r := rune(0x800); r <= 0x10FFFF; r += 0x1D1 {
+		runes = append(runes, r)
+	}
+
+	for _, r := range runes {
+		if !utf8.ValidRune(r) {
+			continue
+		}
+
+		charged := logfield.EncodedBytes(r)
+
+		require.LessOrEqual(
+			t, emitted(jsonHandler, r), charged,
+			"json handler spends more than U+%04X is charged", r,
+		)
+		require.LessOrEqual(
+			t, emitted(textHandler, r), charged,
+			"text handler spends more than U+%04X is charged", r,
+		)
+	}
+}
+
+func dropTime(_ []string, a slog.Attr) slog.Attr {
+	if a.Key == slog.TimeKey {
+		return slog.Attr{}
+	}
+
+	return a
+}
+
+// TestTruncate_LeavesShortValuesAlone keeps the marker meaningful: a
+// value that fits is returned untouched, so a reader can tell a short
+// value from a cut one.
+func TestTruncate_LeavesShortValuesAlone(t *testing.T) {
+	t.Parallel()
+
+	const in = "Mozilla/5.0 (X11; Linux x86_64)"
+
+	assert.Equal(t, in, logfield.Truncate(in, logfield.MaxBytes))
+}
+
+// TestTruncate_DropsInvalidUTF8 covers a value that was never valid
+// UTF-8 — a SQL parameter or a header can carry one. Replacing each
+// bad byte would cost six encoded bytes apiece, so they are dropped.
+func TestTruncate_DropsInvalidUTF8(t *testing.T) {
+	t.Parallel()
+
+	got := logfield.Truncate("a\xffb\xfec", logfield.MaxBytes)
+
+	assert.Equal(t, "abc", got)
+	assert.True(t, utf8.ValidString(got))
+}
+
+// TestTruncate_NeverSplitsARune covers a cut landing inside a
+// multi-byte encoding.
+func TestTruncate_NeverSplitsARune(t *testing.T) {
+	t.Parallel()
+
+	// A three-byte printable rune, so a small budget lands inside the
+	// encoding rather than between two of them.
+	in := strings.Repeat("€", logfield.MaxBytes)
+
+	for budget := 1; budget <= 16; budget++ {
+		got := strings.TrimSuffix(
+			logfield.Truncate(in, budget), "[truncated]",
+		)
+
+		assert.True(
+			t, utf8.ValidString(got),
+			"budget %d produced invalid UTF-8", budget,
+		)
+		assert.LessOrEqual(t, encodedCost(got), budget)
+	}
+}

internal/middleware/middleware.go

@@ -6,11 +6,8 @@ import (
 	"log/slog"
 	"net"
 	"net/http"
-	"strings"
 	"sync"
 	"time"
-	"unicode"
-	"unicode/utf8"
 
 	basicauth "github.com/99designs/basicauth-go"
 	"github.com/go-chi/chi"
@@ -22,6 +19,7 @@ import (
 	"go.uber.org/fx"
 	"sneak.berlin/go/webhooker/internal/config"
 	"sneak.berlin/go/webhooker/internal/globals"
+	"sneak.berlin/go/webhooker/internal/logfield"
 	"sneak.berlin/go/webhooker/internal/logger"
 	"sneak.berlin/go/webhooker/internal/session"
 )
@@ -44,16 +42,6 @@ const (
 	// pick the size of the line it writes.
 	redactedQuery = "?(redacted)"
 
-	// maxLogFieldBytes bounds each access log field whose value the
-	// client supplies outright: the URL, the User-Agent and the
-	// Referer. The budget is spent in ENCODED bytes (see
-	// truncateLogField), so 512 still holds a real browser's User-Agent
-	// whole — those are plain ASCII, which encodes one byte for one —
-	// while a value built from characters the encoder escapes keeps a
-	// shorter prefix. That is the intended trade: 500 quotation marks
-	// are not a debugging asset.
-	maxLogFieldBytes = 512
-
 	// maxLogRequestIDBytes bounds the request id, which is also
 	// client-supplied: chi's RequestID middleware passes an inbound
 	// X-Request-Id header through verbatim. Its generated form is an
@@ -66,15 +54,10 @@ const (
 	// is half this.
 	maxLogMethodBytes = 32
 
-	// truncationMarker is appended to any field the access log cut, so
-	// a short value and a truncated one cannot be confused. It is
-	// charged on top of the budget, not inside it.
-	truncationMarker = "[truncated]"
-
 	// MaxAccessLogLineBytes is the ceiling on one JSON access log line,
 	// and the number an operator multiplies by the request rate to size
 	// log storage. It is not an observation of a sample: it is the sum
-	// of the budgets above, each of which truncateLogField enforces in
+	// of the field budgets, each of which logfield.Truncate enforces in
 	// ENCODED bytes, plus the part of the line no client can influence.
 	//
 	//	url, useragent, referer   3*(512+11) = 1569
@@ -84,6 +67,9 @@ const (
 	//	                                        ----
 	//	                                        2087
 	//
+	// The 512 is logfield.MaxBytes; the 11 is the truncation marker,
+	// charged on top of each budget rather than inside it.
+	//
 	// The fixed portion is the JSON punctuation, the field names, the
 	// level and the message, both timestamps at their longest, an IPv6
 	// remoteIP with a zone, a three-digit status and a full-width int64
@@ -91,13 +77,29 @@ const (
 	// than sitting on the arithmetic.
 	//
 	// The tty text handler in internal/logger is covered by the same
-	// figure. encodedLogFieldBytes charges every rune at least what
+	// figure. logfield.EncodedBytes charges every rune at least what
 	// the wider of the two handlers emits for it — including the ten
 	// 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 access log is the widest line this service writes that
+	// carries client-chosen text, so the figure is also the ceiling on
+	// the other writer that does: the GORM adapter in
+	// internal/gormlog, whose widest line spends two logfield.MaxBytes
+	// budgets (the interpolated SQL and the driver error) against a
+	// fixed portion smaller than this one's.
+	// internal/gormlog/gormlog_test.go asserts that against this
+	// constant directly rather than leaving it as arithmetic.
+	//
+	// It is not the widest line the service can write. A handler panic
+	// arrives through net/http's nil ErrorLog as one record carrying a
+	// whole goroutine stack, measured at 2,772 bytes. That value is
+	// the runtime's, not a client's, so it is a carve-out this ceiling
+	// states rather than covers; see README.md and
+	// https://git.eeqj.de/sneak/webhooker/issues/187.
 	MaxAccessLogLineBytes = 2560
 )
 
@@ -174,114 +176,6 @@ func (lrw *loggingResponseWriter) WriteHeader(code int) {
 	lrw.ResponseWriter.WriteHeader(code)
 }
 
-// encodedLogFieldBytes is what r costs on the line once the log
-// handler has escaped it, taking the worse of the two handlers
-// internal/logger configures.
-//
-// slog's JSON handler escapes quote, backslash, newline, carriage
-// return and tab to two bytes each, and every other C0 control plus
-// LINE SEPARATOR and PARAGRAPH SEPARATOR to a six-byte \u escape; it
-// passes every other rune through as its own UTF-8. Its text handler
-// quotes with strconv.Quote, which spells a non-printable rune below
-// U+10000 as \uXXXX but one at or above U+10000 as \UXXXXXXXX — ten
-// bytes, not six. The text handler is therefore the worse of the two
-// for every non-printable rune, and by four bytes apiece for the
-// 955,086 unassigned, private-use and format code points on planes 1
-// to 16.
-//
-// Charging ten there is what makes MaxAccessLogLineBytes hold for the
-// tty handler as well: U+1000C encodes as F0 90 80 8C, every byte
-// >= 0x80, which httpguts.ValidHeaderFieldValue accepts and
-// net/textproto does not strip, so a header can be filled with them.
-//
-// Both handlers pass printable runes through as their own UTF-8, so
-// unicode.IsPrint separates the escaped cases from the plain ones for
-// either handler.
-func encodedLogFieldBytes(r rune) int {
-	const (
-		// A backslash and the character itself.
-		shortEscapeBytes = 2
-		// \uXXXX, which is also the width of \u00XX.
-		escapedRuneBytes = 6
-		// \UXXXXXXXX, strconv.Quote's spelling of a non-printable
-		// rune outside the basic multilingual plane.
-		escapedAstralRuneBytes = 10
-		// The first code point strconv.Quote spells with \U.
-		firstAstralRune = 0x10000
-	)
-
-	switch {
-	case r == '"' || r == '\\' || r == '\n' || r == '\r' || r == '\t':
-		return shortEscapeBytes
-	case !unicode.IsPrint(r) && r >= firstAstralRune:
-		return escapedAstralRuneBytes
-	case !unicode.IsPrint(r):
-		return escapedRuneBytes
-	default:
-		return utf8.RuneLen(r)
-	}
-}
-
-// truncateLogField caps s at maxBytes of ENCODED output, marking the
-// value when it cuts.
-//
-// Budgeting raw bytes would not bound the line. Escaping only ever
-// grows a value, so a raw budget spent on characters the encoder
-// escapes buys a field several times its nominal size — and the line
-// is the thing an operator is told to multiply by their request rate.
-// Charging each rune what it will actually cost is what makes
-// MaxAccessLogLineBytes true rather than merely larger. The visible
-// consequence is that an escape-heavy value keeps a shorter prefix
-// than a plain one, which is the correct trade.
-//
-// The result is always valid UTF-8. A cut on a byte boundary can split
-// a multi-byte rune, and a header can carry bytes that were never
-// valid UTF-8 to begin with; both are dropped rather than kept, since
-// an encoder would otherwise spend six bytes replacing each one.
-func truncateLogField(s string, maxBytes int) string {
-	// No rune encodes to fewer bytes than it occupies, so nothing past
-	// maxBytes raw can fit the budget. Slicing first bounds the scan
-	// below to the budget rather than to the size of the header the
-	// client sent.
-	window, cut := s, false
-	if len(window) > maxBytes {
-		window, cut = window[:maxBytes], true
-	}
-
-	var (
-		kept  strings.Builder
-		spent int
-	)
-
-	for i := 0; i < len(window); {
-		r, size := utf8.DecodeRuneInString(window[i:])
-		if r == utf8.RuneError && size == 1 {
-			i += size
-
-			continue
-		}
-
-		cost := encodedLogFieldBytes(r)
-		if spent+cost > maxBytes {
-			cut = true
-
-			break
-		}
-
-		spent += cost
-
-		kept.WriteString(window[i : i+size])
-
-		i += size
-	}
-
-	if !cut {
-		return kept.String()
-	}
-
-	return kept.String() + truncationMarker
-}
-
 // concreteLogURL renders the request's own URL for the access log
 // branches that keep it, with the query string replaced by a fixed
 // marker.
@@ -375,21 +269,21 @@ func (s *Middleware) Logging() func(http.Handler) http.Handler {
 				// line does not track the size of the request.
 				s.log.Info("http request",
 					"request_start", start,
-					"method", truncateLogField(
+					"method", logfield.Truncate(
 						r.Method, maxLogMethodBytes,
 					),
-					"url", truncateLogField(
+					"url", logfield.Truncate(
 						accessLogURL(r, lrw.statusCode),
-						maxLogFieldBytes,
+						logfield.MaxBytes,
 					),
-					"useragent", truncateLogField(
+					"useragent", logfield.Truncate(
-						r.UserAgent(), maxLogFieldBytes,
+						r.UserAgent(), logfield.MaxBytes,
 					),
-					"request_id", truncateLogField(
+					"request_id", logfield.Truncate(
 						requestID, maxLogRequestIDBytes,
 					),
-					"referer", truncateLogField(
+					"referer", logfield.Truncate(
-						r.Referer(), maxLogFieldBytes,
+						r.Referer(), logfield.MaxBytes,
 					),
 					"proto", r.Proto,
 					"remoteIP", ipFromHostPort(r.RemoteAddr),