diff --git a/README.md b/README.md index 2bb6e23..db52d2f 100644 --- a/README.md +++ b/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: 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..9d831c4 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,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 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/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, + ) + } +}