webhooker/internal/gormlog/gormlog.go

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