From 279baa3e57a244aaf2aa793c8757de8913151d63 Mon Sep 17 00:00:00 2001 From: Cristian Magherusan-Stanciu Date: Wed, 30 Sep 2026 00:51:26 +0200 Subject: [PATCH] fix(db): redact bound query arguments at every log level Keep failed-query logs from exposing session tokens, password hashes, and approval tokens unless bind-parameter logging is explicitly enabled. Closes #231 --- internal/database/connection.go | 12 +- .../query_logging_integration_test.go | 86 +++++++++ internal/database/security_test.go | 171 +++++++----------- 3 files changed, 160 insertions(+), 109 deletions(-) create mode 100644 internal/database/query_logging_integration_test.go diff --git a/internal/database/connection.go b/internal/database/connection.go index c3485c04c..d09419214 100644 --- a/internal/database/connection.go +++ b/internal/database/connection.go @@ -417,18 +417,16 @@ func isSensitiveKey(k string) bool { return k == "password" || k == "secret" || k == "token" } -// sanitizeLogData returns a copy of data with sensitive fields removed. -// At debug level, the pgx "args" key (SQL bound parameters) is also removed -// unless DB_LOG_BIND_PARAMETERS=true is set, because bound values can carry -// session tokens, bcrypt hashes, or approval tokens. -func sanitizeLogData(level tracelog.LogLevel, data map[string]any) map[string]any { +// Bound parameters can carry credentials even when a query fails. +// Only DB_LOG_BIND_PARAMETERS=true opts into logging them at any level. +func sanitizeLogData(data map[string]any) map[string]any { bindParams := os.Getenv("DB_LOG_BIND_PARAMETERS") == "true" safe := make(map[string]any, len(data)) for k, v := range data { if isSensitiveKey(k) { continue } - if k == "args" && level == tracelog.LogLevelDebug && !bindParams { + if k == "args" && !bindParams { continue } safe[k] = v @@ -437,7 +435,7 @@ func sanitizeLogData(level tracelog.LogLevel, data map[string]any) map[string]an } func (l *stdLogger) Log(ctx context.Context, level tracelog.LogLevel, msg string, data map[string]any) { - safeData := sanitizeLogData(level, data) + safeData := sanitizeLogData(data) switch level { case tracelog.LogLevelDebug: diff --git a/internal/database/query_logging_integration_test.go b/internal/database/query_logging_integration_test.go new file mode 100644 index 000000000..b6139032c --- /dev/null +++ b/internal/database/query_logging_integration_test.go @@ -0,0 +1,86 @@ +//go:build integration + +package database_test + +import ( + "bytes" + "context" + "strings" + "sync" + "testing" + + "github.com/LeanerCloud/cloud-commitments-go/pkg/logging" + "github.com/LeanerCloud/cloud-commitments-platform/internal/database/postgres/testhelpers" + "github.com/jackc/pgx/v5/pgconn" + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" +) + +type queryLogBuffer struct { + mu sync.Mutex + buf bytes.Buffer +} + +func (b *queryLogBuffer) Write(p []byte) (int, error) { + b.mu.Lock() + defer b.mu.Unlock() + return b.buf.Write(p) +} + +func (b *queryLogBuffer) take() string { + b.mu.Lock() + defer b.mu.Unlock() + text := b.buf.String() + b.buf.Reset() + return text +} + +func TestQueryLogging_RedactsBoundSecretsOnFailure(t *testing.T) { + ctx := context.Background() + container := testhelpers.RequirePostgresContainer(ctx, t) + var output queryLogBuffer + previousOutput := logging.SetOutput(&output) + previousLevel := logging.GetLevel() + logging.SetLevelValue(logging.LevelDebug) + t.Cleanup(func() { + assert.NoError(t, container.Cleanup(context.Background())) + logging.SetOutput(previousOutput) + logging.SetLevelValue(previousLevel) + }) + + _, err := container.DB.Exec(ctx, `CREATE TABLE query_logging_secrets ( + session_token text, password_hash text, approval_token text, + accepted integer CHECK (accepted > 0))`) + require.NoError(t, err) + secrets := []string{strings.Repeat("a", 64), strings.Repeat("b", 60), strings.Repeat("c", 64)} + for _, optIn := range []string{"", "true"} { + t.Run("bind_parameters="+optIn, func(t *testing.T) { + t.Setenv("DB_LOG_BIND_PARAMETERS", optIn) + output.take() + _, err := container.DB.Exec(ctx, + `INSERT INTO query_logging_secrets VALUES ($1, $2, $3, $4)`, + secrets[0], secrets[1], secrets[2], 0) + var pgErr *pgconn.PgError + require.ErrorAs(t, err, &pgErr) + require.Equal(t, "23514", pgErr.Code) + for _, secret := range secrets { + require.NotContains(t, pgErr.Error(), secret) + } + logged := output.take() + assert.Contains(t, logged, "Query") + assert.Contains(t, logged, pgErr.Error()) + for _, secret := range secrets { + if optIn == "true" { + assert.Contains(t, logged, secret) + } else { + assert.NotContains(t, logged, secret) + } + } + if optIn == "true" { + assert.Contains(t, logged, "args:") + } else { + assert.NotContains(t, logged, "args:") + } + }) + } +} diff --git a/internal/database/security_test.go b/internal/database/security_test.go index 98ba8fa30..3fccea584 100644 --- a/internal/database/security_test.go +++ b/internal/database/security_test.go @@ -8,6 +8,7 @@ import ( "testing" "time" + "github.com/LeanerCloud/cloud-commitments-go/pkg/logging" "github.com/jackc/pgx/v5/tracelog" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" @@ -155,85 +156,34 @@ func TestBuildPoolConfig_ParseError_NoPasswordLeak(t *testing.T) { // The placeholder "REDACTED" may appear, which is acceptable. } -// TestSanitizeLogData_ArgsKeyStrippedAtDebugByDefault is a regression test for -// issue #446: pgx logs SQL bound parameters under the "args" key at debug -// level. Without the fix, these would be included in log output and could -// expose session tokens, bcrypt hashes, or approval tokens. -// -// By default (DB_LOG_BIND_PARAMETERS not set) the "args" key must be stripped -// from debug-level log data. -func TestSanitizeLogData_ArgsKeyStrippedAtDebugByDefault(t *testing.T) { - t.Setenv("DB_LOG_BIND_PARAMETERS", "") - - tests := []struct { - inputData map[string]any - name string - level tracelog.LogLevel - wantArgsInOut bool - }{ - { - name: "args stripped at debug level by default", - inputData: map[string]any{ - "args": []any{"session-token-abc", "bcrypt-hash-xyz"}, - "sql": "SELECT * FROM users WHERE token = $1", - }, - level: tracelog.LogLevelDebug, - wantArgsInOut: false, - }, - { - name: "args kept at warn level", - inputData: map[string]any{ - "args": []any{"value"}, - "sql": "SELECT 1", - }, - level: tracelog.LogLevelWarn, - wantArgsInOut: true, - }, - { - name: "args kept at error level", - inputData: map[string]any{ - "args": []any{"value"}, - }, - level: tracelog.LogLevelError, - wantArgsInOut: true, - }, - { - name: "password always stripped at warn level", - inputData: map[string]any{ - "password": "secret", - "safe": "ok", - }, - level: tracelog.LogLevelWarn, - wantArgsInOut: false, // "args" key not in input, not relevant - }, +func TestSanitizeLogData_BoundArgumentsRequireExplicitOptIn(t *testing.T) { + input := map[string]any{ + "args": []any{"session-token", "bcrypt-hash"}, + "sql": "SELECT $1", "err": "query failed", + "password": "private-password", "secret": "private-secret", "token": "private-token", } - - for _, tc := range tests { - t.Run(tc.name, func(t *testing.T) { - safe := sanitizeLogData(tc.level, tc.inputData) - _, hasArgs := safe["args"] - assert.Equal(t, tc.wantArgsInOut, hasArgs, - "args key presence mismatch for level %v", tc.level) + for _, optIn := range []string{"", "false", "TRUE", "1", "true"} { + t.Run("bind_parameters="+optIn, func(t *testing.T) { + t.Setenv("DB_LOG_BIND_PARAMETERS", optIn) + safe := sanitizeLogData(input) + assert.Equal(t, input["sql"], safe["sql"]) + assert.Equal(t, input["err"], safe["err"]) + for _, key := range []string{"password", "secret", "token"} { + assert.NotContains(t, safe, key) + assert.Contains(t, input, key) + } + if optIn == "true" { + assert.Equal(t, input["args"], safe["args"]) + } else { + assert.NotContains(t, safe, "args") + } + assert.Equal(t, []any{"session-token", "bcrypt-hash"}, input["args"]) + safe["sql"] = "changed" + assert.Equal(t, "SELECT $1", input["sql"]) }) } } -// TestSanitizeLogData_ArgsKeyKeptWhenOptedIn verifies that setting -// DB_LOG_BIND_PARAMETERS=true allows the "args" key through at debug level. -func TestSanitizeLogData_ArgsKeyKeptWhenOptedIn(t *testing.T) { - t.Setenv("DB_LOG_BIND_PARAMETERS", "true") - - inputData := map[string]any{ - "args": []any{"param1", "param2"}, - "sql": "SELECT 1", - } - - safe := sanitizeLogData(tracelog.LogLevelDebug, inputData) - _, hasArgs := safe["args"] - assert.True(t, hasArgs, - "args key must be preserved when DB_LOG_BIND_PARAMETERS=true") -} - // TestIsSensitiveKey verifies the sensitive-key predicate covers all expected names. func TestIsSensitiveKey(t *testing.T) { assert.True(t, isSensitiveKey("password")) @@ -244,33 +194,54 @@ func TestIsSensitiveKey(t *testing.T) { assert.False(t, isSensitiveKey("host")) } -// TestStdLogger_DoesNotPanicWithArgsKey exercises the live stdLogger.Log path -// with an "args" entry to confirm it does not panic when the key is filtered. -func TestStdLogger_DoesNotPanicWithArgsKey(t *testing.T) { - t.Setenv("DB_LOG_BIND_PARAMETERS", "") - - logger := &stdLogger{} - ctx := context.Background() +func TestStdLogger_RedactsBoundArguments(t *testing.T) { + var output bytes.Buffer + previousOutput := logging.SetOutput(&output) + previousLevel := logging.GetLevel() + logging.SetLevelValue(logging.LevelDebug) + t.Cleanup(func() { + logging.SetOutput(previousOutput) + logging.SetLevelValue(previousLevel) + }) data := map[string]any{ "args": []any{"session-token", "hash-value"}, "sql": "INSERT INTO sessions VALUES ($1, $2)", - "password": "should-be-stripped", + "password": "private-password", "secret": "private-secret", "token": "private-token", + } + for _, optIn := range []string{"", "true"} { + t.Run("bind_parameters="+optIn, func(t *testing.T) { + t.Setenv("DB_LOG_BIND_PARAMETERS", optIn) + for _, level := range []tracelog.LogLevel{tracelog.LogLevelDebug, tracelog.LogLevelInfo, tracelog.LogLevelWarn, tracelog.LogLevelError} { + t.Run(level.String(), func(t *testing.T) { + output.Reset() + (&stdLogger{}).Log(context.Background(), level, "Query", data) + logged := output.String() + assert.Contains(t, logged, "Query") + for _, value := range []string{"private-password", "private-secret", "private-token"} { + assert.NotContains(t, logged, value) + } + if optIn == "true" && level != tracelog.LogLevelInfo { + assert.Contains(t, logged, "args:") + assert.Contains(t, logged, "session-token") + assert.Contains(t, logged, "hash-value") + } else { + assert.NotContains(t, logged, "args:") + assert.NotContains(t, logged, "session-token") + assert.NotContains(t, logged, "hash-value") + } + if level == tracelog.LogLevelInfo { + assert.NotContains(t, logged, "sql:") + } else { + assert.Contains(t, logged, data["sql"]) + } + }) + } + }) } - - assert.NotPanics(t, func() { - logger.Log(ctx, tracelog.LogLevelDebug, "Query", data) - }) - assert.NotPanics(t, func() { - logger.Log(ctx, tracelog.LogLevelInfo, "Query", data) - }) } -// TestSanitizeLogData_PasswordStrippedAtAllLevels confirms password/secret/token -// keys are removed regardless of log level. -func TestSanitizeLogData_PasswordStrippedAtAllLevels(t *testing.T) { - t.Setenv("DB_LOG_BIND_PARAMETERS", "") - +func TestSanitizeLogData_SensitiveKeysWithoutArgs(t *testing.T) { sensitive := map[string]any{ "password": "my-password", "secret": "my-secret", @@ -278,14 +249,10 @@ func TestSanitizeLogData_PasswordStrippedAtAllLevels(t *testing.T) { "safe": "visible", } - for _, level := range []tracelog.LogLevel{ - tracelog.LogLevelDebug, - tracelog.LogLevelInfo, - tracelog.LogLevelWarn, - tracelog.LogLevelError, - } { - t.Run(level.String(), func(t *testing.T) { - safe := sanitizeLogData(level, sensitive) + for _, optIn := range []string{"", "true"} { + t.Run("bind_parameters="+optIn, func(t *testing.T) { + t.Setenv("DB_LOG_BIND_PARAMETERS", optIn) + safe := sanitizeLogData(sensitive) assert.NotContains(t, safe, "password") assert.NotContains(t, safe, "secret") assert.NotContains(t, safe, "token")