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 at all, 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.

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.

README: the ceiling now covers GORM; the writers it does not cover are
named, including net/http's nil ErrorLog, fx's console logger and the
Go runtime, none of which carry a client-chosen value.

internal/gormlog/gormlog_test.go

@@ -0,0 +1,388 @@
+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
+}
+
+// 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.
+func openDB(
+	t *testing.T, buf *bytes.Buffer, h slog.Handler,
+) (*gorm.DB, *gormlog.Logger) {
+	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.New(slog.New(h))
+
+	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, gl
+}
+
+// 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))
+
+				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",
+				)
+			})
+		}
+	}
+}
+
+// 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,
+			}),
+		)
+
+		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))
+
+				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())
+			})
+		}
+	}
+}
+
+// TestSlowStatement_IsLoggedAndBounded proves the slow-statement
+// report survived the fix. Silencing GORM outright would have been
+// the cheaper change and would have cost this, which is the one thing
+// GORM's logger reports that nothing else in the service does.
+func TestSlowStatement_IsLoggedAndBounded(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, gl := openDB(t, &buf, h.make(&buf))
+
+				// Every statement counts as slow, so the branch is
+				// reached without making the test wait for it.
+				gl.ExportSetSlowThreshold(time.Nanosecond)
+
+				var got []thing
+
+				require.NoError(t, gdb.Where(
+					"name = ?", clientValue(f.fill),
+				).Find(&got).Error)
+
+				assert.Contains(
+					t, buf.String(), "slow sql statement",
+				)
+				assertBounded(t, buf.String())
+			})
+		}
+	}
+}
+
+// TestDebugStatement_LineIsBounded covers the branch an operator
+// reaches by turning the level down: every statement is reported, so
+// every statement's interpolated parameters have to be bounded too.
+func TestDebugStatement_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))
+
+				var got []thing
+
+				require.NoError(t, gdb.Where(
+					"name = ?", clientValue(f.fill),
+				).Find(&got).Error)
+
+				assert.Contains(t, buf.String(), "sql statement")
+				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))
+}