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 internal/logfield, the same encoded-byte budget the
access log spends. MaxAccessLogLineBytes bounds a GORM line too, and
internal/gormlog asserts each line against the constant directly.

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.

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.

internal/logfield gains the zero-headroom budget assertion and the
rune-splitting case: a value built from one rune must keep exactly
MaxBytes/EncodedBytes(r) of them, which a raw-byte budget fails and a
LessOrEqual on the budget cannot catch.

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, filed
as #187, and is the widest
line the service can write: measured at roughly 2,770 bytes against
the stated 2,560, a width that moves with the goroutine number and the
source paths in the stack, so only the fact that it exceeds the
ceiling is stated as invariant.

internal/gormlog/gormlog_test.go

@@ -0,0 +1,436 @@
+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()
+
+	// "sql statement" is a substring of "slow sql statement", so the
+	// routine arm carries notWant as well: Contains alone cannot tell
+	// the two arms apart in that direction.
+	arms := []struct {
+		name    string
+		slow    time.Duration
+		want    string
+		notWant string
+	}{
+		{"slow", alwaysSlow, "slow sql statement", ""},
+		{"routine", neverSlow, "sql statement", "slow 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)
+
+					if a.notWant != "" {
+						assert.NotContains(
+							t, buf.String(), a.notWant,
+						)
+					}
+
+					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))
+}