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

2026-08-18 07:17:43 +02:00
parent 563e834cf2
commit 0c64c411cc
11 changed files with 1447 additions and 21 deletions
--- a/internal/gormlog/gormlog_test.go
+++ b/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))
+}