From 5af161ef60bd01449ba6e6070a0f3aa91bbb013a Mon Sep 17 00:00:00 2001 From: clawbot Date: Thu, 20 Aug 2026 07:20:59 +0200 Subject: [PATCH] Log SQL with placeholders, never bound values (closes #207) (#222) --- README.md | 63 +++++++ internal/gormlog/firstboot_test.go | 229 ++++++++++++++++++++++++ internal/gormlog/gormlog.go | 61 ++++++- internal/gormlog/gormlog_test.go | 26 +-- internal/gormlog/scan_guard_test.go | 260 ++++++++++++++++++++++++++++ internal/gormlog/values_test.go | 185 ++++++++++++++++++++ 6 files changed, 807 insertions(+), 17 deletions(-) create mode 100644 internal/gormlog/firstboot_test.go create mode 100644 internal/gormlog/scan_guard_test.go create mode 100644 internal/gormlog/values_test.go diff --git a/README.md b/README.md index d17cc7d..ad8be86 100644 --- a/README.md +++ b/README.md @@ -256,6 +256,51 @@ On first startup, webhooker creates an `admin` user with a randomly generated password and logs it to stdout. This password is only displayed once. +#### What `DEBUG=true` exposes + +`DEBUG=true` lowers the log level to `DEBUG`, which turns on every +statement GORM runs, the two by-design lookup misses on the +unauthenticated routes, and the rate limiter's own rejections. It is +meant to be safe to turn on while diagnosing a live service and safe to +paste the output of into a bug report. + +What it does **not** put in the log: + +- **Values bound to a SQL statement.** Statements are logged with their + placeholders, never with the values substituted into them, at every + level. That is what keeps the session encryption key out of the first + boot's `INSERT INTO settings` and the `admin` account's Argon2id + password hash out of its `INSERT INTO users` — the two statements + that made a debug log worth stealing. It applies to every table and + every statement rather than to a list of tables known to hold a + secret, so a table added later is covered without anyone remembering + to add it. The cost is that a failing statement can no longer be + replayed from the log alone: the statement, the table, the driver + error and the row count are all still there, but its values have to + come from the database. + `internal/gormlog/firstboot_test.go` boots the real graph with + `DEBUG=true` against an empty `DATA_DIR` and asserts that neither + secret appears in what that boot wrote to stdout. + The one exception is `(*gorm.DB).Scan`, which GORM logs through its + own trace recorder rather than through this filter. No production + code path calls it, and `internal/gormlog/scan_guard_test.go` fails + if a non-test file adds one. +- **Session cookies, API keys or target credentials.** None of these is + logged at any level. + +What is in the log regardless of `DEBUG`, and is not a debug-logging +decision: + +- **The initial `admin` password**, in the clear, once, at `INFO`, on + the first boot that creates the account. That line is the only place + it is ever shown; the database stores the hash. A first boot's output + is not safe to paste anywhere until that account's password has been + changed. +- **An authenticated operator's own configuration**, echoed back + untruncated — webhook names, target hostnames. See the logging + section under Security for the full list and for the per-line size + bound that covers unauthenticated traffic. + ### Running with Docker ```bash @@ -1464,6 +1509,24 @@ and the driver error — against a smaller fixed portion than the access log's, and `internal/gormlog/gormlog_test.go` asserts each line against `MaxAccessLogLineBytes` directly rather than leaving it as arithmetic. +The adapter also logs no bound value at all: it implements +`gorm.ParamsFilter` and discards the parameters, so GORM renders the +statement with its placeholders intact instead of substituting the +values into it. That is a separate property from the size bound and it +is what a bound is no substitute for — the session encryption key is 44 +base64 characters and an Argon2id hash under 100, so both fit inside +every budget above and a truncated secret is still a secret. It holds +on all three arms of `Trace`, including the routine one an operator +reaches at `DEBUG`, which is the only level at which a successful +`INSERT` is written at all. One GORM path does not consult the filter — +`(*gorm.DB).Scan`, which records the statement through GORM's own trace +recorder. No production code path calls it; its one caller is +`internal/database/database_test.go:91`, whose `SELECT 1` binds +nothing, and `internal/gormlog/scan_guard_test.go` fails if a non-test +file calls it. `Pluck`, `Row` and `Raw` all run through the normal +callback processor and are filtered. +See `#### What DEBUG=true exposes` under Configuration. + What that ceiling does **not** cover, stated here so the figure is not read as more than it is: diff --git a/internal/gormlog/firstboot_test.go b/internal/gormlog/firstboot_test.go new file mode 100644 index 0000000..6fab1a5 --- /dev/null +++ b/internal/gormlog/firstboot_test.go @@ -0,0 +1,229 @@ +package gormlog_test + +import ( + "context" + "database/sql" + "os" + "path/filepath" + "testing" + + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + "go.uber.org/fx" + "go.uber.org/fx/fxtest" + _ "modernc.org/sqlite" // Pure Go SQLite driver. + "sneak.berlin/go/webhooker/internal/config" + "sneak.berlin/go/webhooker/internal/database" + "sneak.berlin/go/webhooker/internal/globals" + "sneak.berlin/go/webhooker/internal/logger" + "sneak.berlin/go/webhooker/internal/session" +) + +// argon2Prefix opens every encoded Argon2id hash this service +// produces. It is asserted on separately from the hash itself, so that +// a change to the password encoding cannot quietly turn the hash +// assertion into a comparison against a string the log never held. +const argon2Prefix = "$argon2id$" + +// settingsInsert and usersInsert are the two statements a first boot +// runs that carry a secret. The sqlite dialector quotes identifiers +// with backticks. +const ( + settingsInsert = "INSERT INTO `settings`" + usersInsert = "INSERT INTO `users`" +) + +// captureStdoutToFile redirects os.Stdout into a file for the rest of +// the test and returns a function that reads back everything written +// to it. +// +// A file rather than a pipe: internal/logger writes synchronously to +// whatever os.Stdout is when it builds its handler, so once fx's start +// returns, every byte the boot produced is already in the file and no +// draining goroutine is needed to prove it. Redirecting the variable +// before the application is built is what puts the service logger — +// and therefore the GORM adapter, which writes through it — into the +// capture. +// +// The redirect also decides the handler: a regular file is not a +// character device, so internal/logger installs its JSON handler, the +// one it installs in production under a log collector. +func captureStdoutToFile(t *testing.T) func() string { + t.Helper() + + path := filepath.Join(t.TempDir(), "stdout.log") + + //nolint:gosec // The path is this test's own t.TempDir(). + f, err := os.Create(path) + require.NoError(t, err) + + orig := os.Stdout + os.Stdout = f + + t.Cleanup(func() { + os.Stdout = orig + _ = f.Close() + }) + + return func() string { + require.NoError(t, f.Sync()) + + //nolint:gosec // As above. + b, readErr := os.ReadFile(path) + require.NoError(t, readErr) + + return string(b) + } +} + +// firstBootSecrets are the two values a first boot generates and +// stores, read back out of the database. +type firstBootSecrets struct { + sessionKey string + passwordHash string +} + +// readFirstBootSecrets reads those two secrets straight out of the +// SQLite file with database/sql rather than through GORM, so that +// reading them cannot itself add a line to the log under test. +func readFirstBootSecrets( + t *testing.T, dataDir string, +) firstBootSecrets { + t.Helper() + + db, err := sql.Open("sqlite", filepath.Join( + dataDir, "webhooker.db", + )) + require.NoError(t, err) + + defer func() { require.NoError(t, db.Close()) }() + + ctx := context.Background() + + var got firstBootSecrets + + require.NoError(t, db.QueryRowContext( + ctx, `SELECT value FROM settings WHERE key = 'session_key'`, + ).Scan(&got.sessionKey)) + + require.NoError(t, db.QueryRowContext( + ctx, `SELECT password FROM users WHERE username = 'admin'`, + ).Scan(&got.passwordHash)) + + require.NotEmpty(t, got.sessionKey) + require.Contains(t, got.passwordHash, argon2Prefix) + + return got +} + +// bootAtDebug starts and stops the real application graph against +// dataDir with DEBUG=true, and returns everything it wrote to standard +// output. +// +// config.New reads DEBUG from the environment exactly as the binary +// does, internal/logger builds the handler it builds in production, +// database.New runs the migrations and creates the admin user, and +// session.New takes the session key. Those four are the whole of the +// path that writes either secret. +func bootAtDebug(t *testing.T, dataDir string) string { + t.Helper() + + t.Setenv("DEBUG", "true") + t.Setenv("DATA_DIR", dataDir) + + read := captureStdoutToFile(t) + + var sess *session.Session + + app := fxtest.New( + t, + fx.Provide( + globals.New, + logger.New, + config.New, + database.New, + session.New, + ), + fx.Populate(&sess), + ) + + app.RequireStart() + app.RequireStop() + + return read() +} + +// requireFirstBootWasLogged is the non-vacuity half of the test below. +// Without it a build that logged no SQL at all, or that never reached +// DEBUG, would satisfy every absence assertion. +func requireFirstBootWasLogged(t *testing.T, out string) { + t.Helper() + + require.Contains( + t, out, `"level":"DEBUG"`, + "DEBUG=true did not reach the logger", + ) + require.Contains( + t, out, settingsInsert, + "the session key INSERT was not logged, so its absence "+ + "proves nothing", + ) + require.Contains( + t, out, usersInsert, + "the admin user INSERT was not logged, so its absence "+ + "proves nothing", + ) +} + +// TestFirstBootAtDebug_LogsNeitherSecret is the definition of done. +// +// A first boot is the only boot that writes either secret. The +// settings INSERT carries the base64 session encryption key, which is +// the whole of the session security model: anyone holding it can forge +// an authenticated session cookie. The users INSERT carries the admin +// account's Argon2id hash. Under interpolated statement logging both +// landed in the log an operator diagnosing a startup problem pastes +// into an issue. +// +// The secrets are read back out of the database file afterwards, so +// the assertions are made against the values this boot actually +// generated rather than against a pattern that might not match them. +// +// What this test does not cover: the initial admin password itself, +// which internal/database logs once in the clear, on purpose, because +// that line is the only place an operator ever sees it. That is a +// separate decision from the SQL log, and it is documented in the +// README rather than asserted here. +// +// Not parallel: it redirects os.Stdout and sets environment variables, +// both process-global. +// +//nolint:paralleltest // Deliberately sequential; see above. +func TestFirstBootAtDebug_LogsNeitherSecret(t *testing.T) { + dataDir := t.TempDir() + + // An empty DATA_DIR is what makes this a first boot: with a + // database already in place neither INSERT runs. + entries, err := os.ReadDir(dataDir) + require.NoError(t, err) + require.Empty(t, entries, "DATA_DIR was not empty") + + out := bootAtDebug(t, dataDir) + + requireFirstBootWasLogged(t, out) + + secrets := readFirstBootSecrets(t, dataDir) + + assert.NotContains( + t, out, secrets.sessionKey, + "the session encryption key reached the debug log", + ) + assert.NotContains( + t, out, secrets.passwordHash, + "the admin password hash reached the debug log", + ) + assert.NotContains( + t, out, argon2Prefix, + "an encoded Argon2id hash reached the debug log", + ) +} diff --git a/internal/gormlog/gormlog.go b/internal/gormlog/gormlog.go index 38ff5ec..a44dd03 100644 --- a/internal/gormlog/gormlog.go +++ b/internal/gormlog/gormlog.go @@ -17,6 +17,10 @@ // level the operator controls, they are shaped by whichever handler // internal/logger selected, and every value a client can influence is // spent through logfield.Truncate. +// +// It also logs no bound value at all. See ParamsFilter: the statement +// is written with its placeholders intact, at every level, so the +// values a statement carries never reach the log in the first place. package gormlog import ( @@ -26,6 +30,7 @@ import ( "log/slog" "time" + "gorm.io/gorm" gormlogger "gorm.io/gorm/logger" "sneak.berlin/go/webhooker/internal/logfield" ) @@ -47,8 +52,14 @@ type Logger struct { } // Interface compliance is asserted here rather than discovered at the -// gorm.Open call sites. -var _ gormlogger.Interface = (*Logger)(nil) +// gorm.Open call sites. gorm.ParamsFilter is the optional half: GORM +// type-asserts for it and silently keeps interpolating if it is +// missing, so losing it would cost no build error and no test that +// does not look at the emitted SQL. +var ( + _ gormlogger.Interface = (*Logger)(nil) + _ gorm.ParamsFilter = (*Logger)(nil) +) // New returns a GORM logger that writes through log. func New(log *slog.Logger) *Logger { @@ -71,6 +82,46 @@ func (l *Logger) LogMode(gormlogger.LogLevel) gormlogger.Interface { return l } +// ParamsFilter drops every bound value before GORM renders a statement +// for the log, so what is logged is the statement's shape — its +// placeholders — and never the values in it. +// +// GORM builds the string it hands to Trace by calling +// Dialector.Explain(sql, vars...), which substitutes each value into +// the statement. Discarding vars here leaves the '?' placeholders in +// place, because ExplainSQL only substitutes while it still has a +// value for the next one. That happens before Trace is reached, so it +// holds on all three of its arms: the failed statement, the slow one, +// and the routine one an operator sees at DEBUG. +// +// This is the whole of the fix, and it is deliberately unconditional +// rather than a list of tables to redact. At first boot the two +// statements that carry a secret are the INSERT into settings holding +// the base64 session key — which is the entire session security model, +// since anyone with it can mint a valid cookie — and the INSERT into +// users holding the Argon2id hash. A denylist would have had to be +// extended by hand for every table added afterwards, and the cost of +// missing one is a credential in a log that gets pasted into issues. +// +// What is given up is the ability to read a value out of the log. The +// statement, the table, the error and the row count are all still +// there, which is what identifies a failing statement; reproducing it +// needs the values, and those an operator now gets from the database +// rather than from the log. +// +// One GORM path does not consult this: (*gorm.DB).Scan records the +// statement through gorm's own traceRecorder, which does not implement +// this interface. No production code path calls it; its one caller is +// internal/database/database_test.go:91, whose SELECT 1 binds nothing. +// scan_guard_test.go fails if a non-test file calls it. +// (*gorm.DB).Pluck, Row and Raw all run through the normal callback +// processor and are filtered. +func (l *Logger) ParamsFilter( + _ context.Context, sql string, _ ...any, +) (string, []any) { + return sql, nil +} + // Info logs one of GORM's own informational messages. func (l *Logger) Info( ctx context.Context, msg string, data ...any, @@ -93,9 +144,9 @@ func (l *Logger) Error( } // Trace reports the outcome of a single statement. GORM calls it for -// every statement it runs, so the cheap paths stay cheap: fc() -// renders the interpolated SQL and is called only on a branch that -// will actually emit. +// every statement it runs, so the cheap paths stay cheap: fc() renders +// the statement — with placeholders, per ParamsFilter — and is called +// only on a branch that will actually emit. // // The arms are ordered exactly as GORM's own Trace orders them — // non-record-not-found error, then slow, then the routine case — so diff --git a/internal/gormlog/gormlog_test.go b/internal/gormlog/gormlog_test.go index d8e53cc..084f98f 100644 --- a/internal/gormlog/gormlog_test.go +++ b/internal/gormlog/gormlog_test.go @@ -232,7 +232,7 @@ func TestSlowRecordNotFound_IsStillReportedSlow(t *testing.T) { require.ErrorIs(t, err, gorm.ErrRecordNotFound) assert.Contains( - t, buf.String(), "slow sql statement", + t, buf.String(), slowLine, "a slow statement that missed was not "+ "reported as slow", ) @@ -284,9 +284,11 @@ func TestRecordNotFoundFlood_DoesNotGrowWithInput(t *testing.T) { } // 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. +// 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() @@ -313,7 +315,7 @@ func TestStatementError_LineIsBounded(t *testing.T) { require.Error(t, err) assert.Contains( - t, buf.String(), "sql statement failed", + t, buf.String(), errorLine, ) assertBounded(t, buf.String()) }) @@ -329,22 +331,22 @@ func TestStatementError_LineIsBounded(t *testing.T) { // 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. +// down to DEBUG: every statement is reported, so every statement +// has 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. + // 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, "slow sql statement", ""}, - {"routine", neverSlow, "sql statement", "slow sql statement"}, + {"slow", alwaysSlow, slowLine, ""}, + {"routine", neverSlow, routineLine, slowLine}, } for _, a := range arms { diff --git a/internal/gormlog/scan_guard_test.go b/internal/gormlog/scan_guard_test.go new file mode 100644 index 0000000..13a1de5 --- /dev/null +++ b/internal/gormlog/scan_guard_test.go @@ -0,0 +1,260 @@ +package gormlog_test + +import ( + "fmt" + "go/ast" + "go/parser" + "go/token" + "io/fs" + "os" + "path/filepath" + "strings" + "testing" + + "github.com/stretchr/testify/require" +) + +// minNonTestFiles guards the walk below against passing because it +// found nothing to look at. The tree held 60 non-test .go files when +// this was written. +const minNonTestFiles = 40 + +// isRowProducer reports whether name is a method that returns a +// database/sql row handle. GORM's Row and Rows return *sql.Row and +// *sql.Rows, so Scan on the result of one of them is database/sql's +// Scan and never (*gorm.DB).Scan. +func isRowProducer(name string) bool { + switch name { + case "Row", "Rows", "QueryRow", "QueryRowContext": + return true + default: + return false + } +} + +// receiverIsRowHandle reports whether x is syntactically a call to a +// row producer, which is the only receiver form this check accepts for +// a Scan. +func receiverIsRowHandle(x ast.Expr) bool { + call, ok := x.(*ast.CallExpr) + if !ok { + return false + } + + sel, ok := call.Fun.(*ast.SelectorExpr) + if !ok { + return false + } + + return isRowProducer(sel.Sel.Name) +} + +// unguardedScans returns the position of every Scan call in file whose +// receiver is not a row handle. It fails closed: a receiver it cannot +// resolve syntactically — a local variable, a struct field — is +// reported rather than assumed safe. +func unguardedScans( + fset *token.FileSet, file *ast.File, +) []token.Position { + var found []token.Position + + ast.Inspect(file, func(n ast.Node) bool { + call, ok := n.(*ast.CallExpr) + if !ok { + return true + } + + sel, ok := call.Fun.(*ast.SelectorExpr) + if !ok || sel.Sel.Name != "Scan" { + return true + } + + if !receiverIsRowHandle(sel.X) { + found = append(found, fset.Position(sel.Sel.Pos())) + } + + return true + }) + + return found +} + +// moduleRoot walks up from the working directory to the directory +// holding go.mod. +func moduleRoot(t *testing.T) string { + t.Helper() + + dir, err := os.Getwd() + require.NoError(t, err) + + for { + _, statErr := os.Stat(filepath.Join(dir, "go.mod")) + if statErr == nil { + return dir + } + + parent := filepath.Dir(dir) + require.NotEqual(t, parent, dir, "no go.mod above %s", dir) + + dir = parent + } +} + +// skipDir reports whether a directory holds no source this check +// governs. +func skipDir(name string) bool { + switch name { + case ".git", "bin", "node_modules", "testdata": + return true + default: + return false + } +} + +// walkNonTestGo parses every non-test .go file under root and returns +// how many it parsed along with every unguarded Scan it found. +func walkNonTestGo(t *testing.T, root string) (int, []string) { + t.Helper() + + var ( + parsed int + hits []string + ) + + fset := token.NewFileSet() + + require.NoError(t, filepath.WalkDir( + root, + func(path string, d fs.DirEntry, err error) error { + if err != nil { + return err + } + + if d.IsDir() { + if skipDir(d.Name()) { + return fs.SkipDir + } + + return nil + } + + if !isNonTestGo(d.Name()) { + return nil + } + + file, err := parser.ParseFile(fset, path, nil, 0) + if err != nil { + return err + } + + parsed++ + + for _, pos := range unguardedScans(fset, file) { + hits = append(hits, relPosition(root, pos)) + } + + return nil + }, + )) + + return parsed, hits +} + +// isNonTestGo reports whether a file name is Go source this check +// governs. +func isNonTestGo(name string) bool { + return strings.HasSuffix(name, ".go") && + !strings.HasSuffix(name, "_test.go") +} + +// relPosition renders pos with its path relative to root, so a failure +// names the file the way the repository does. +func relPosition(root string, pos token.Position) string { + name := pos.Filename + + rel, err := filepath.Rel(root, name) + if err == nil { + name = rel + } + + return fmt.Sprintf("%s:%d:%d", name, pos.Line, pos.Column) +} + +// TestGormScanIsNeverCalledOutsideTests keeps (*gorm.DB).Scan out of +// non-test code. +// +// It is the one statement path (*Logger).ParamsFilter does not reach: +// Scan swaps GORM's own trace recorder in for the adapter, and that +// recorder does not implement gorm.ParamsFilter, so the statement is +// logged with its values interpolated. The package comment states the +// limit; this fails when someone adds a call site anyway. +// +// The current tree has one caller, internal/database/database_test.go, +// which this check does not govern: it is test-only and its SELECT 1 +// binds nothing. +func TestGormScanIsNeverCalledOutsideTests(t *testing.T) { + t.Parallel() + + parsed, offenders := walkNonTestGo(t, moduleRoot(t)) + + require.GreaterOrEqual( + t, parsed, minNonTestFiles, + "parsed %d non-test .go files, so this check found "+ + "nothing to look at", parsed, + ) + require.Empty( + t, offenders, + "Scan called on a receiver this check cannot show is a "+ + "database/sql row handle. (*gorm.DB).Scan logs the "+ + "statement with its bound values interpolated — use "+ + "Find, Pluck, or Raw(...).Row().Scan instead. A "+ + "database/sql Scan reached through a variable is "+ + "reported too; write it as ().Scan rather "+ + "than widening this check.", + ) +} + +// scanGuardCase is one planted snippet and whether the check above +// should report it. +type scanGuardCase struct { + name string + body string + want int +} + +func scanGuardCases() []scanGuardCase { + return []scanGuardCase{ + {"gorm chain", `db.DB().Raw("SELECT 1").Scan(&v)`, 1}, + {"gorm receiver", `gdb.Scan(&v)`, 1}, + {"gorm via variable", "q := gdb.Raw(\"x\")\nq.Scan(&v)", 1}, + {"gorm model chain", `gdb.Model(&x).Scan(&v)`, 1}, + {"sql row", `gdb.Raw("SELECT 1").Row().Scan(&v)`, 0}, + {"sql rows", `gdb.Raw("SELECT 1").Rows().Scan(&v)`, 0}, + {"unrelated call", `gdb.Find(&v)`, 0}, + } +} + +// TestScanGuard_ReportsPlantedCalls proves the check fires. Without it +// a detector that matched nothing would satisfy the walk above no +// matter what the tree contained. +func TestScanGuard_ReportsPlantedCalls(t *testing.T) { + t.Parallel() + + for _, tc := range scanGuardCases() { + t.Run(tc.name, func(t *testing.T) { + t.Parallel() + + fset := token.NewFileSet() + src := fmt.Sprintf( + "package p\n\nfunc f() {\n\t%s\n}\n", tc.body, + ) + + file, err := parser.ParseFile( + fset, tc.name+".go", src, 0, + ) + require.NoError(t, err) + + require.Len(t, unguardedScans(fset, file), tc.want) + }) + } +} diff --git a/internal/gormlog/values_test.go b/internal/gormlog/values_test.go new file mode 100644 index 0000000..8d05a50 --- /dev/null +++ b/internal/gormlog/values_test.go @@ -0,0 +1,185 @@ +package gormlog_test + +import ( + "bytes" + "strings" + "testing" + "time" + + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + "gorm.io/gorm" +) + +// secretValue is bound as a parameter by every case below. Nothing +// else in this package writes it, so finding it in captured output +// means a bound value was rendered into the log. +const secretValue = "QQBOUNDVALUEMARKERQQ" + +// The three messages Trace emits under, one per arm. +// +// routineLine is a substring of slowLine, so a case that wants the +// routine arm has to rule the slow one out as well rather than rely on +// Contains alone. +const ( + routineLine = "sql statement" + slowLine = "slow sql statement" + errorLine = "sql statement failed" +) + +// boundValueCase is one arm of Trace, driven by a statement that binds +// secretValue. +type boundValueCase struct { + name string + slow time.Duration + want string + drive func(t *testing.T, gdb *gorm.DB) +} + +// insertSecret returns a driver that inserts one row whose Name is the +// secret. +func insertSecret(id string) func(*testing.T, *gorm.DB) { + return func(t *testing.T, gdb *gorm.DB) { + t.Helper() + + require.NoError(t, gdb.Create(&thing{ + ID: id, Name: secretValue, + }).Error) + } +} + +// insertSecretTwice drives the error arm: the same primary key a +// second time is a UNIQUE constraint failure, which is an error GORM +// logs with the statement. +func insertSecretTwice(t *testing.T, gdb *gorm.DB) { + t.Helper() + + require.NoError(t, gdb.Create(&thing{ + ID: secretValue, Name: secretValue, + }).Error) + require.Error(t, gdb.Create(&thing{ + ID: secretValue, Name: "other", + }).Error) +} + +// selectSecret drives a query whose WHERE clause binds the secret, +// covering the read side as well as the write side. +func selectSecret(t *testing.T, gdb *gorm.DB) { + t.Helper() + + var got []thing + + require.NoError( + t, gdb.Where("name = ?", secretValue).Find(&got).Error, + ) +} + +func boundValueCases() []boundValueCase { + return []boundValueCase{ + { + name: "routine", slow: neverSlow, + want: routineLine, drive: insertSecret("routine"), + }, + { + name: "slow", slow: alwaysSlow, + want: slowLine, drive: insertSecret("slow"), + }, + { + name: "error", slow: neverSlow, + want: errorLine, drive: insertSecretTwice, + }, + { + name: "select", slow: neverSlow, + want: routineLine, drive: selectSecret, + }, + } +} + +// TestBoundValues_NeverReachTheLog states the values-off property +// directly, on each arm of Trace that emits. +// +// Truncation is not what is being asserted. A bounded secret is still +// a secret: the session key is 44 base64 characters and an Argon2id +// hash under 100, so both fit inside every budget this package +// applies. What keeps them out is that the adapter logs the +// statement's shape and discards its parameters — see +// (*Logger).ParamsFilter — and that has to hold at DEBUG as much as on +// an error, because DEBUG is the level at which a successful INSERT is +// written at all. +// +// Each case also requires a placeholder in the logged statement. +// Without that, the absence of the value would be satisfied by a +// logger that wrote nothing useful. +func TestBoundValues_NeverReachTheLog(t *testing.T) { + t.Parallel() + + for _, tc := range boundValueCases() { + for _, h := range handlers() { + t.Run(tc.name+"/"+h.name, func(t *testing.T) { + t.Parallel() + + var buf bytes.Buffer + + gdb := openDB(t, &buf, h.make(&buf), tc.slow) + + tc.drive(t, gdb) + + assertNoBoundValue(t, buf.String(), tc.want) + }) + } + } +} + +// assertNoBoundValue holds one captured arm to the property: it wrote +// the line it was supposed to write, that line kept its placeholders, +// and it carried no bound value. +func assertNoBoundValue(t *testing.T, out, want string) { + t.Helper() + + require.Contains( + t, out, want, + "the arm under test wrote nothing, so the assertions "+ + "below are vacuous", + ) + assert.NotContains( + t, out, secretValue, + "a bound parameter was rendered into the log", + ) + assert.Contains( + t, out, "?", + "the statement was logged without its placeholders", + ) +} + +// TestInsert_KeepsOnePlaceholderPerBoundValue pins the shape of the +// INSERT specifically, since that is the statement that carries both +// first-boot secrets. A statement that dropped one value and kept the +// other would satisfy the assertions above. +func TestInsert_KeepsOnePlaceholderPerBoundValue(t *testing.T) { + t.Parallel() + + var buf bytes.Buffer + + gdb := openDB(t, &buf, handlers()[0].make(&buf), neverSlow) + + require.NoError(t, gdb.Create(&thing{ + ID: "m", Name: secretValue, + }).Error) + + out := buf.String() + + require.Contains(t, out, "INSERT INTO") + assert.NotContains(t, out, secretValue) + + for line := range strings.SplitSeq(out, "\n") { + if !strings.Contains(line, "INSERT INTO") { + continue + } + + assert.GreaterOrEqual( + t, strings.Count(line, "?"), 2, + "insert logged fewer placeholders than it bound "+ + "values: %s", line, + ) + } +}