From ddcc611af35d9d78a27cdc975647488c76698d2d Mon Sep 17 00:00:00 2001 From: Deluan Date: Sat, 26 Sep 2026 13:42:50 -0400 Subject: [PATCH] refactor(log): redact caller-marked secret values in the log hook Replaces the statement-wide SQL arg redaction from the previous commit, which hid every arg of property and password writes (user names, emails, scanner properties) and made troubleshooting harder. log.WithSecrets marks values on a context, log calls now pass their context to the logrus entry, and the redaction hook replaces those values in the message and fields. logSQL logs the real args again; only the encrypted password, the API v1 key and the JWT secrets are marked. --- core/apiauth/signer.go | 4 +-- core/auth/auth.go | 2 +- log/log.go | 36 ++++++++++++++++++++- log/log_test.go | 21 ++++++++++++ log/redactrus.go | 38 ++++++++++++++++++++++ log/redactrus_test.go | 43 +++++++++++++++++++++++++ persistence/property_repository.go | 2 -- persistence/property_repository_test.go | 17 +++++++--- persistence/sql_base_repository.go | 21 +----------- persistence/user_repository.go | 4 +-- persistence/user_repository_test.go | 5 +-- 11 files changed, 159 insertions(+), 34 deletions(-) diff --git a/core/apiauth/signer.go b/core/apiauth/signer.go index 055f6a69e..b01ba273c 100644 --- a/core/apiauth/signer.go +++ b/core/apiauth/signer.go @@ -85,7 +85,7 @@ func loadKey(ctx context.Context, ds model.DataStore) (string, error) { if err != nil { return err } - if err := tx.Property().Put(ctx, consts.JWTAPIv1SecretKey, enc); err != nil { + if err := tx.Property().Put(log.WithSecrets(ctx, enc), consts.JWTAPIv1SecretKey, enc); err != nil { return err } key = k @@ -103,7 +103,7 @@ func createKey(ctx context.Context, ds model.DataStore) (string, error) { if err != nil { return "", err } - if err := ds.Property().PutIfAbsent(ctx, consts.JWTAPIv1SecretKey, enc); err != nil { + if err := ds.Property().PutIfAbsent(log.WithSecrets(ctx, enc), consts.JWTAPIv1SecretKey, enc); err != nil { return "", fmt.Errorf("storing API v1 key: %w", err) } return ds.Property().Get(ctx, consts.JWTAPIv1SecretKey) diff --git a/core/auth/auth.go b/core/auth/auth.go index 43314a7c1..8ecda9b75 100644 --- a/core/auth/auth.go +++ b/core/auth/auth.go @@ -176,7 +176,7 @@ func createNewSecret(ctx context.Context, ds model.DataStore, key string) string log.Error(ctx, "Could not encrypt JWT secret", err) return secret } - if err := ds.Property().Put(ctx, key, encSecret); err != nil { + if err := ds.Property().Put(log.WithSecrets(ctx, encSecret), key, encSecret); err != nil { log.Error(ctx, "Could not save JWT secret in DB", err) } return secret diff --git a/log/log.go b/log/log.go index da1d7622e..7f9cc42a8 100644 --- a/log/log.go +++ b/log/log.go @@ -72,7 +72,10 @@ const ( type contextKey string -const loggerCtxKey = contextKey("logger") +const ( + loggerCtxKey = contextKey("logger") + secretsCtxKey = contextKey("secrets") +) type levelPath struct { path string @@ -188,6 +191,31 @@ func NewContext(ctx context.Context, keyValuePairs ...any) context.Context { return ctx } +// WithSecrets returns a context whose log entries have every occurrence of values replaced by +// [REDACTED], when redacting is enabled. +func WithSecrets(ctx context.Context, values ...string) context.Context { + if ctx == nil { + ctx = context.Background() + } + secrets := slices.Clone(secretsFrom(ctx)) + for _, v := range values { + if v != "" { + secrets = append(secrets, v) + } + } + // Longest first, so a secret containing another is not left partly visible. + slices.SortStableFunc(secrets, func(a, b string) int { return cmp.Compare(len(b), len(a)) }) + return context.WithValue(ctx, secretsCtxKey, secrets) +} + +func secretsFrom(ctx context.Context) []string { + if ctx == nil { + return nil + } + secrets, _ := ctx.Value(secretsCtxKey).([]string) + return secrets +} + // SetDefaultLogger swaps the process-wide logger and returns the previous one, // so tests can restore the original (with its hooks and formatter) on cleanup. func SetDefaultLogger(l *logrus.Logger) *logrus.Logger { @@ -289,6 +317,12 @@ func parseArgs(args []any) (*logrus.Entry, string) { if err != nil { l = createNewLogger() } else { + switch ctx := args[0].(type) { + case context.Context: + l = l.WithContext(ctx) + case *http.Request: + l = l.WithContext(ctx.Context()) + } args = args[1:] } } diff --git a/log/log_test.go b/log/log_test.go index 184ff57db..d3dbe6c7d 100644 --- a/log/log_test.go +++ b/log/log_test.go @@ -1,6 +1,7 @@ package log import ( + "bytes" "context" "encoding/json" "errors" @@ -109,6 +110,26 @@ var _ = Describe("Logger", func() { Error("Simple Message", "key1", t) Expect(hook.LastEntry().Data["key1"]).To(Equal("nil")) }) + + It("passes the call's context to hooks", func() { + ctx := WithSecrets(GinkgoT().Context(), "s3cr3t") + Error(ctx, "Simple Message") + Expect(hook.LastEntry().Context).To(Equal(ctx)) + + Error(httptest.NewRequest("get", "/", nil).WithContext(ctx), "Simple Message") + Expect(hook.LastEntry().Context).To(Equal(ctx)) + }) + + It("redacts the context's secrets when redacting is on", func() { + l.AddHook(redacted) + ctx := WithSecrets(NewContext(GinkgoT().Context(), "user", "admin"), "s3cr3t") + + var buf bytes.Buffer + l.SetOutput(&buf) + Error(ctx, "Saving s3cr3t", "args", map[string]any{"value": "s3cr3t"}) + Expect(buf.String()).ToNot(ContainSubstring("s3cr3t")) + Expect(buf.String()).To(ContainSubstring("user=admin")) + }) }) Describe("Levels", func() { diff --git a/log/redactrus.go b/log/redactrus.go index fc642bfc0..a9cf5a981 100755 --- a/log/redactrus.go +++ b/log/redactrus.go @@ -7,6 +7,7 @@ import ( "fmt" "reflect" "regexp" + "strings" "github.com/sirupsen/logrus" ) @@ -35,6 +36,7 @@ func (h *Hook) Fire(e *logrus.Entry) error { if err := h.initRedaction(); err != nil { return err } + redactSecrets(e) for _, re := range h.redactionKeys { // Redact based on key matching in Data fields for k, v := range e.Data { @@ -64,6 +66,42 @@ func (h *Hook) Fire(e *logrus.Entry) error { return nil } +// redactSecrets hides the values marked with WithSecrets in the context the entry was logged with. +func redactSecrets(e *logrus.Entry) { + secrets := secretsFrom(e.Context) + if len(secrets) == 0 { + return + } + hide := func(s string) string { + for _, secret := range secrets { + s = strings.ReplaceAll(s, secret, "[REDACTED]") + } + return s + } + e.Message = hide(e.Message) + for k, v := range e.Data { + if v == nil { + continue + } + var s string + if err, ok := v.(error); ok { + s = err.Error() + } else { + switch reflect.TypeOf(v).Kind() { + case reflect.String: + s = reflect.ValueOf(v).String() + case reflect.Map: + s = fmt.Sprintf("%+v", v) + default: + continue + } + } + if hidden := hide(s); hidden != s { + e.Data[k] = hidden + } + } +} + func (h *Hook) initRedaction() error { if len(h.redactionKeys) == 0 { for _, redactionKey := range h.RedactionList { diff --git a/log/redactrus_test.go b/log/redactrus_test.go index a2bd13dda..b8cdfe879 100755 --- a/log/redactrus_test.go +++ b/log/redactrus_test.go @@ -1,6 +1,7 @@ package log import ( + "errors" "testing" "github.com/sirupsen/logrus" @@ -168,3 +169,45 @@ func TestFireRedactsNamedStringTypes(t *testing.T) { assert.Equal(t, "not_found", e.Data["code"]) assert.Equal(t, "/x?secret=[REDACTED]", e.Data["url"]) } + +func TestFireRedactsContextSecrets(t *testing.T) { + ctx := WithSecrets(t.Context(), "s3cr3t") + ctx = WithSecrets(ctx, "", "other-secret") + e := &logrus.Entry{ + Context: ctx, + Message: "value s3cr3t in message", + Data: logrus.Fields{ + "str": "has s3cr3t", + "named": namedString("named other-secret"), + "args": map[string]any{"p0": "s3cr3t", "p1": "plain"}, + "error": errors.New("failed with other-secret"), + "num": 42, + "clean": namedString("untouched"), + }, + } + + assert.Nil(t, (&Hook{}).Fire(e)) + assert.Equal(t, "value [REDACTED] in message", e.Message) + assert.Equal(t, "has [REDACTED]", e.Data["str"]) + assert.Equal(t, "named [REDACTED]", e.Data["named"]) + assert.Equal(t, "map[p0:[REDACTED] p1:plain]", e.Data["args"]) + assert.Equal(t, "failed with [REDACTED]", e.Data["error"]) + assert.Equal(t, 42, e.Data["num"]) + assert.Equal(t, namedString("untouched"), e.Data["clean"]) +} + +func TestFireWithoutContextSecretsLeavesEntryUnchanged(t *testing.T) { + args := map[string]any{"p0": "value"} + e := &logrus.Entry{Context: t.Context(), Message: "value", Data: logrus.Fields{"str": "value", "args": args}} + + assert.Nil(t, (&Hook{}).Fire(e)) + assert.Equal(t, "value", e.Message) + assert.Equal(t, logrus.Fields{"str": "value", "args": args}, e.Data) +} + +func TestFireRedactsLongerSecretsFirst(t *testing.T) { + e := &logrus.Entry{Context: WithSecrets(t.Context(), "abc", "abcdef"), Message: "abcdef"} + + assert.Nil(t, (&Hook{}).Fire(e)) + assert.Equal(t, "[REDACTED]", e.Message) +} diff --git a/persistence/property_repository.go b/persistence/property_repository.go index 916b16430..87d97491c 100644 --- a/persistence/property_repository.go +++ b/persistence/property_repository.go @@ -21,7 +21,6 @@ func NewPropertyRepository(db dbx.Builder) model.PropertyRepository { } func (r propertyRepository) Put(ctx context.Context, id string, value string) error { - ctx = withSecretArgs(ctx) update := Update(r.tableName).Set("value", value).Where(Eq{"id": id}) count, err := r.executeSQL(ctx, update) if err != nil { @@ -36,7 +35,6 @@ func (r propertyRepository) Put(ctx context.Context, id string, value string) er } func (r propertyRepository) PutIfAbsent(ctx context.Context, id string, value string) error { - ctx = withSecretArgs(ctx) insert := Insert(r.tableName).Columns("id", "value").Values(id, value).Options("OR IGNORE") _, err := r.executeSQL(ctx, insert) return err diff --git a/persistence/property_repository_test.go b/persistence/property_repository_test.go index f80fa0b36..01814f41f 100644 --- a/persistence/property_repository_test.go +++ b/persistence/property_repository_test.go @@ -40,16 +40,25 @@ var _ = Describe("Property Repository", func() { Expect(pr.Get(ctx, "pia")).To(Equal("first")) }) - It("never logs the values it writes, but still logs the SQL", func() { + It("hides values marked as secrets from the SQL log, but still logs the property id", func() { logs := captureTraceLogs() - Expect(pr.Put(ctx, "secret-prop", "inserted-secret")).To(Succeed()) - Expect(pr.Put(ctx, "secret-prop", "updated-secret")).To(Succeed()) - Expect(pr.PutIfAbsent(ctx, "secret-prop-2", "absent-secret")).To(Succeed()) + Expect(pr.Put(log.WithSecrets(ctx, "inserted-secret"), "secret-prop", "inserted-secret")).To(Succeed()) + Expect(pr.Put(log.WithSecrets(ctx, "updated-secret"), "secret-prop", "updated-secret")).To(Succeed()) + Expect(pr.PutIfAbsent(log.WithSecrets(ctx, "absent-secret"), "secret-prop-2", "absent-secret")).To(Succeed()) Expect(logs.String()).To(ContainSubstring("INSERT INTO property")) Expect(logs.String()).To(ContainSubstring("UPDATE property")) + Expect(logs.String()).To(ContainSubstring("secret-prop-2")) Expect(logs.String()).ToNot(ContainSubstring("inserted-secret")) Expect(logs.String()).ToNot(ContainSubstring("updated-secret")) Expect(logs.String()).ToNot(ContainSubstring("absent-secret")) }) + + It("logs the values of unmarked property writes", func() { + logs := captureTraceLogs() + Expect(pr.Put(ctx, "plain-prop", "plain-value")).To(Succeed()) + + Expect(logs.String()).To(ContainSubstring("plain-prop")) + Expect(logs.String()).To(ContainSubstring("plain-value")) + }) }) diff --git a/persistence/sql_base_repository.go b/persistence/sql_base_repository.go index d929e7ef4..03cc6a01b 100644 --- a/persistence/sql_base_repository.go +++ b/persistence/sql_base_repository.go @@ -658,28 +658,9 @@ func (r sqlRepository) deleteByID(ctx context.Context, id string) error { return nil } -type secretArgsKey struct{} - -// withSecretArgs hides a statement's args from the SQL log: stored secrets are encrypted with a key that may be the public default. -func withSecretArgs(ctx context.Context) context.Context { - return context.WithValue(ctx, secretArgsKey{}, true) -} - -func hasSecretArgs(ctx context.Context) bool { - if ctx == nil { - return false - } - secret, _ := ctx.Value(secretArgsKey{}).(bool) - return secret -} - func (r sqlRepository) logSQL(ctx context.Context, sql string, args dbx.Params, err error, rowsAffected int64, start time.Time) { elapsed := time.Since(start) - var logArgs any = args - if hasSecretArgs(ctx) { - logArgs = "[REDACTED]" - } - fields := []any{ctx, "SQL: `" + sql + "`", "args", logArgs, "rowsAffected", rowsAffected, "elapsedTime", elapsed} + fields := []any{ctx, "SQL: `" + sql + "`", "args", args, "rowsAffected", rowsAffected, "elapsedTime", elapsed} if err == nil || errors.Is(err, context.Canceled) { log.Trace(append(fields, err)...) return diff --git a/persistence/user_repository.go b/persistence/user_repository.go index a750bbef4..f53682bd5 100644 --- a/persistence/user_repository.go +++ b/persistence/user_repository.go @@ -118,8 +118,8 @@ func (r *userRepository) Put(ctx context.Context, u *model.User) error { } u.UpdatedAt = time.Now() if u.NewPassword != "" { - ctx = withSecretArgs(ctx) _ = r.encryptPassword(ctx, u) + ctx = log.WithSecrets(ctx, u.NewPassword) } values, err := toSQLArgs(*u) if err != nil { @@ -433,7 +433,7 @@ func (r *userRepository) initPasswordEncryptionKey(ctx context.Context) error { u.NewPassword = u.Password if err := r.encryptPassword(ctx, &u); err == nil { upd := Update(r.tableName).Set("password", u.NewPassword).Where(Eq{"id": u.ID}) - _, err = r.executeSQL(withSecretArgs(ctx), upd) + _, err = r.executeSQL(log.WithSecrets(ctx, u.NewPassword), upd) if err != nil { log.Error("Password NOT encrypted! This may cause problems!", "user", u.UserName, "id", u.ID, err) } else { diff --git a/persistence/user_repository_test.go b/persistence/user_repository_test.go index 4f907b447..f90da0db9 100644 --- a/persistence/user_repository_test.go +++ b/persistence/user_repository_test.go @@ -75,7 +75,7 @@ var _ = Describe("UserRepository", func() { Expect(err).ToNot(HaveOccurred()) Expect(actual.Password).To(Equal("newpass")) }) - It("never logs the stored password, on insert or update, but still logs the SQL", func() { + It("never logs the stored password, on insert or update, but still logs the user name", func() { logs := captureTraceLogs() storedPassword := func(id string) string { var enc string @@ -83,7 +83,7 @@ var _ = Describe("UserRepository", func() { Bind(dbx.Params{"id": id}).Row(&enc)).To(Succeed()) return enc } - u := model.User{ID: "u-logged", UserName: "u-logged", NewPassword: "first-secret"} + u := model.User{ID: "u-logged", UserName: "logged-user-name", NewPassword: "first-secret"} Expect(repo.Put(ctx, &u)).To(Succeed()) inserted := storedPassword(u.ID) u.NewPassword = "second-secret" @@ -92,6 +92,7 @@ var _ = Describe("UserRepository", func() { Expect(logs.String()).To(ContainSubstring("INSERT INTO user")) Expect(logs.String()).To(ContainSubstring("UPDATE user")) + Expect(logs.String()).To(ContainSubstring("logged-user-name")) for _, secret := range []string{inserted, updated, "first-secret", "second-secret"} { Expect(logs.String()).ToNot(ContainSubstring(secret)) }