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