// Package gormlog adapts GORM's logger onto the service's slog // logger. // // GORM's own default logger is not usable here. It is built at package // init with log.New(os.Stdout, ...) at LogLevel Warn with // IgnoreRecordNotFoundError false, so it writes the fully interpolated // SQL — parameters and all — for every statement that returns an // error, including gorm.ErrRecordNotFound. Two of this service's // lookups miss by design on unauthenticated routes: the entrypoint // lookup on /webhook/{uuid}, whose path segment the client picks // outright, and the user lookup behind the login form, whose username // the client picks outright. Under the default logger each of those // misses printed an unbounded, attacker-chosen string, at no level the // operator can turn down, past every handler internal/logger installs. // // This adapter fixes all three properties at once: the lines get a // 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 ( "context" "errors" "fmt" "log/slog" "time" "gorm.io/gorm" gormlogger "gorm.io/gorm/logger" "sneak.berlin/go/webhooker/internal/logfield" ) // DefaultSlowThreshold is the duration at or above which a statement // is logged as slow. It is GORM's own default, kept deliberately: slow // SQL is the one thing GORM's logger reports that nothing else in this // service does, so silencing the logger outright would have cost real // observability to fix a log-volume defect. const DefaultSlowThreshold = 200 * time.Millisecond // Logger implements gormlogger.Interface on top of an *slog.Logger. // // It is safe for concurrent use: every field is set at construction // and never written again. type Logger struct { log *slog.Logger slowThreshold time.Duration } // Interface compliance is asserted here rather than discovered at the // 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 { return &Logger{ log: log, slowThreshold: DefaultSlowThreshold, } } // LogMode returns the logger unchanged. // // GORM's LogLevel is deliberately not honoured. Level is the operator's // decision and it is expressed once, through LOG_LEVEL and the // slog.LevelVar internal/logger holds; a second level knob inside the // database layer could only disagree with it. The mapping from GORM's // four categories onto slog levels is fixed in Trace below. // //nolint:ireturn // The interface return is GORM's signature, not a choice. 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, ) { l.log.InfoContext(ctx, "gorm", "message", format(msg, data...)) } // Warn logs one of GORM's own warnings. func (l *Logger) Warn( ctx context.Context, msg string, data ...any, ) { l.log.WarnContext(ctx, "gorm", "message", format(msg, data...)) } // Error logs one of GORM's own errors. func (l *Logger) Error( ctx context.Context, msg string, data ...any, ) { l.log.ErrorContext(ctx, "gorm", "message", format(msg, data...)) } // 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 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 // that a statement which both misses and runs slow is still reported // as slow. A miss is the likeliest statement to be slow, since it is // the one that scans without finding a row, and ordering the drop // ahead of the slow arm would have made this adapter less observant // than the IgnoreRecordNotFoundError option it was chosen over. func (l *Logger) Trace( ctx context.Context, begin time.Time, fc func() (string, int64), err error, ) { elapsed := time.Since(begin) switch { case err != nil && !errors.Is(err, gormlogger.ErrRecordNotFound): sql, rows := fc() l.log.ErrorContext(ctx, "sql statement failed", "error", logfield.Truncate(err.Error(), logfield.MaxBytes), "sql", logfield.Truncate(sql, logfield.MaxBytes), "rows", rows, "elapsed_ms", elapsed.Milliseconds(), ) case l.slowThreshold > 0 && elapsed >= l.slowThreshold: sql, rows := fc() l.log.WarnContext(ctx, "slow sql statement", "sql", logfield.Truncate(sql, logfield.MaxBytes), "rows", rows, "elapsed_ms", elapsed.Milliseconds(), "threshold_ms", l.slowThreshold.Milliseconds(), ) case err != nil: // gorm.ErrRecordNotFound is not an error on the paths that // produce it here: an invented entrypoint UUID and an unknown // username are the expected outcome of an unauthenticated // request, not a fault. This is the IgnoreRecordNotFoundError // behaviour, and it is unconditional rather than configurable // because no caller in this service wants the other one — the // two handlers that care already record the miss themselves, // at DEBUG, without the SQL. A miss that ran slow has already // been reported by the arm above. return case l.log.Enabled(ctx, slog.LevelDebug): sql, rows := fc() l.log.DebugContext(ctx, "sql statement", "sql", logfield.Truncate(sql, logfield.MaxBytes), "rows", rows, "elapsed_ms", elapsed.Milliseconds(), ) } } // format renders one of GORM's printf-style internal messages and // bounds it. GORM builds these itself, but they can quote a value the // statement carried, so they are spent through the same budget as // everything else rather than trusted. func format(msg string, data ...any) string { if len(data) == 0 { return logfield.Truncate(msg, logfield.MaxBytes) } return logfield.Truncate( fmt.Sprintf(msg, data...), logfield.MaxBytes, ) }