webhooker/internal/gormlog/gormlog_test.go

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(), slowLine,
					"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 statement is
// written, and the driver's own error text can quote what the client
// supplied. The statement's parameters are no longer part of that —
// see TestBoundValues_NeverReachTheLog — but the budget is what holds
// the line when the statement itself, or the error, is the long part.
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(), errorLine,
				)
				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
//     has to be bounded too.
func TestSucceedingStatement_LineIsBoundedOnEitherArm(t *testing.T) {
	t.Parallel()

	// routineLine is a substring of slowLine, 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, slowLine, ""},
		{"routine", neverSlow, routineLine, slowLine},
	}

	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))
}