Log SQL with placeholders, never bound values (closes #207)

With DEBUG=true the GORM adapter logged fully interpolated statements.
On a first boot that put two secrets in the log: the INSERT into
settings carrying the base64 session encryption key -- which is the
whole of the session security model, since anyone holding it can forge
an authenticated session cookie -- and the INSERT into users carrying
the admin account's Argon2id password hash. Debug logs get pasted into
issues and chats.

internal/gormlog.Logger now implements gorm.ParamsFilter and discards
the bound values, so GORM renders the statement with its placeholders
intact instead of substituting them in. This is unconditional rather
than a denylist of tables known to hold a secret: a table added later
is covered without anyone remembering to add it, and the cost of
missing one is a credential in a log. It applies at every level,
including the routine arm an operator reaches at DEBUG, which is the
only level at which a successful INSERT is written at all.

Truncation was never a fix for this. The session key is 44 base64
characters and an Argon2id hash under 100, so both fit inside every
budget the adapter applies; a truncated secret is still a secret.

internal/gormlog/firstboot_test.go boots the real graph -- config.New
reading DEBUG from the environment, internal/logger building its
production handler, database.New migrating and creating the admin
user, session.New taking the session key -- against an empty DATA_DIR,
captures stdout, and asserts that neither the session key nor the
password hash appears in it. It reads both secrets back out of the
SQLite file afterwards, so the assertions are made against the values
that boot actually generated. Three requires guard against vacuity:
the capture has to contain a DEBUG line and both INSERTs, or the
absence of the secrets proves nothing. values_test.go pins the same
property per arm of Trace, and that an INSERT keeps one placeholder
per value it bound.

Removing the filter fails all three new tests.

README documents what DEBUG=true does and does not expose, including
the one secret still logged in the clear on purpose: the initial admin
password, at INFO, once, because that line is the only place an
operator ever sees it.

README.md

@@ -244,6 +244,47 @@ 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.
+- **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
@@ -1406,6 +1447,21 @@ 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 — and nothing in this service 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:
 

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",
+	)
+}

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,44 @@ 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. Nothing in this service 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 +142,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

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 {

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