From 1b5c68a20347a072996506a7772f7b9e0a1ef98f Mon Sep 17 00:00:00 2001 From: Deluan Date: Sat, 26 Sep 2026 13:55:28 -0400 Subject: [PATCH] refactor(log): mark secrets on their own line and cover session keys Mark secret values with log.WithSecrets on a separate line instead of nesting the call in argument lists. Also mark Last.fm/ListenBrainz session keys written through SessionKeys.Put and the PasswordEncryptionKey checksum, which still reached trace logs, and ignore values shorter than 8 characters so a short plaintext marked after a failed encryption cannot mangle SQL text or the [REDACTED] marker. --- core/agents/session_keys.go | 2 ++ core/agents/session_keys_test.go | 42 ++++++++++++++++++++++++- core/apiauth/signer.go | 6 ++-- core/auth/auth.go | 3 +- log/log.go | 7 +++-- log/log_test.go | 8 ++--- log/redactrus_test.go | 19 ++++++++--- persistence/property_repository_test.go | 9 ++++-- persistence/user_repository.go | 4 ++- persistence/user_repository_test.go | 31 ++++++++++++++++++ 10 files changed, 112 insertions(+), 19 deletions(-) diff --git a/core/agents/session_keys.go b/core/agents/session_keys.go index 1eb414b15..400c54fc7 100644 --- a/core/agents/session_keys.go +++ b/core/agents/session_keys.go @@ -3,6 +3,7 @@ package agents import ( "context" + "github.com/navidrome/navidrome/log" "github.com/navidrome/navidrome/model" ) @@ -13,6 +14,7 @@ type SessionKeys struct { } func (sk *SessionKeys) Put(ctx context.Context, userId, sessionKey string) error { + ctx = log.WithSecrets(ctx, sessionKey) return sk.DataStore.UserProps().Put(ctx, userId, sk.KeyName, sessionKey) } diff --git a/core/agents/session_keys_test.go b/core/agents/session_keys_test.go index e0232c08e..66eaf3a57 100644 --- a/core/agents/session_keys_test.go +++ b/core/agents/session_keys_test.go @@ -1,21 +1,31 @@ package agents import ( + "bytes" "context" + "database/sql" + "os" + "github.com/navidrome/navidrome/log" "github.com/navidrome/navidrome/model" + "github.com/navidrome/navidrome/persistence" "github.com/navidrome/navidrome/tests" + "github.com/pocketbase/dbx" . "github.com/onsi/ginkgo/v2" . "github.com/onsi/gomega" ) var _ = Describe("SessionKeys", func() { - ctx := context.Background() + var ctx context.Context user := model.User{ID: "u-1"} ds := &tests.MockDataStore{MockedUserProps: &tests.MockedUserPropsRepo{}} sk := SessionKeys{DataStore: ds, KeyName: "fakeSessionKey"} + BeforeEach(func() { + ctx = GinkgoT().Context() + }) + It("uses the assigned key name", func() { Expect(sk.KeyName).To(Equal("fakeSessionKey")) }) @@ -34,4 +44,34 @@ var _ = Describe("SessionKeys", func() { _, err := sk.Get(ctx, "u-2") Expect(err).To(MatchError(model.ErrNotFound)) }) + + It("never logs the session key, but still logs the user id and key name", func() { + conn, err := sql.Open("sqlite3", ":memory:") + Expect(err).ToNot(HaveOccurred()) + DeferCleanup(conn.Close) + conn.SetMaxOpenConns(1) + _, err = conn.ExecContext(ctx, "create table user_props (user_id varchar, key varchar, value varchar)") + Expect(err).ToNot(HaveOccurred()) + props := persistence.NewUserPropsRepository(dbx.NewFromDB(conn, "sqlite3")) + dbKeys := SessionKeys{DataStore: &tests.MockDataStore{MockedUserProps: props}, KeyName: "LastFMSessionKey"} + + logs := &bytes.Buffer{} + log.SetOutput(logs) + log.SetLevel(log.LevelTrace) + DeferCleanup(func() { + log.SetOutput(os.Stderr) + log.SetLevel(log.LevelFatal) + }) + + Expect(dbKeys.Put(ctx, "logged-user-id", "inserted-session-key")).To(Succeed()) + Expect(dbKeys.Put(ctx, "logged-user-id", "updated-session-key")).To(Succeed()) + + Expect(dbKeys.Get(ctx, "logged-user-id")).To(Equal("updated-session-key")) + Expect(logs.String()).To(ContainSubstring("INSERT INTO user_props")) + Expect(logs.String()).To(ContainSubstring("UPDATE user_props")) + Expect(logs.String()).To(ContainSubstring("logged-user-id")) + Expect(logs.String()).To(ContainSubstring("LastFMSessionKey")) + Expect(logs.String()).ToNot(ContainSubstring("inserted-session-key")) + Expect(logs.String()).ToNot(ContainSubstring("updated-session-key")) + }) }) diff --git a/core/apiauth/signer.go b/core/apiauth/signer.go index b01ba273c..a7f3b44d5 100644 --- a/core/apiauth/signer.go +++ b/core/apiauth/signer.go @@ -85,7 +85,8 @@ func loadKey(ctx context.Context, ds model.DataStore) (string, error) { if err != nil { return err } - if err := tx.Property().Put(log.WithSecrets(ctx, enc), consts.JWTAPIv1SecretKey, enc); err != nil { + ctx = log.WithSecrets(ctx, enc) + if err := tx.Property().Put(ctx, consts.JWTAPIv1SecretKey, enc); err != nil { return err } key = k @@ -103,7 +104,8 @@ func createKey(ctx context.Context, ds model.DataStore) (string, error) { if err != nil { return "", err } - if err := ds.Property().PutIfAbsent(log.WithSecrets(ctx, enc), consts.JWTAPIv1SecretKey, enc); err != nil { + ctx = log.WithSecrets(ctx, enc) + if err := ds.Property().PutIfAbsent(ctx, 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 8ecda9b75..1d521451a 100644 --- a/core/auth/auth.go +++ b/core/auth/auth.go @@ -176,7 +176,8 @@ 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(log.WithSecrets(ctx, encSecret), key, encSecret); err != nil { + ctx = log.WithSecrets(ctx, encSecret) + if err := ds.Property().Put(ctx, 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 7f9cc42a8..eb6f81cb8 100644 --- a/log/log.go +++ b/log/log.go @@ -191,15 +191,18 @@ func NewContext(ctx context.Context, keyValuePairs ...any) context.Context { return ctx } +// Shorter values could match unrelated log text, or the [REDACTED] marker itself. +const minSecretLen = 8 + // WithSecrets returns a context whose log entries have every occurrence of values replaced by -// [REDACTED], when redacting is enabled. +// [REDACTED], when redacting is enabled. Values shorter than minSecretLen are ignored. 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 != "" { + if len(v) >= minSecretLen { secrets = append(secrets, v) } } diff --git a/log/log_test.go b/log/log_test.go index d3dbe6c7d..389658df0 100644 --- a/log/log_test.go +++ b/log/log_test.go @@ -112,7 +112,7 @@ var _ = Describe("Logger", func() { }) It("passes the call's context to hooks", func() { - ctx := WithSecrets(GinkgoT().Context(), "s3cr3t") + ctx := WithSecrets(GinkgoT().Context(), "s3cr3t-value") Error(ctx, "Simple Message") Expect(hook.LastEntry().Context).To(Equal(ctx)) @@ -122,12 +122,12 @@ var _ = Describe("Logger", func() { It("redacts the context's secrets when redacting is on", func() { l.AddHook(redacted) - ctx := WithSecrets(NewContext(GinkgoT().Context(), "user", "admin"), "s3cr3t") + ctx := WithSecrets(NewContext(GinkgoT().Context(), "user", "admin"), "s3cr3t-value") var buf bytes.Buffer l.SetOutput(&buf) - Error(ctx, "Saving s3cr3t", "args", map[string]any{"value": "s3cr3t"}) - Expect(buf.String()).ToNot(ContainSubstring("s3cr3t")) + Error(ctx, "Saving s3cr3t-value", "args", map[string]any{"value": "s3cr3t-value"}) + Expect(buf.String()).ToNot(ContainSubstring("s3cr3t-value")) Expect(buf.String()).To(ContainSubstring("user=admin")) }) }) diff --git a/log/redactrus_test.go b/log/redactrus_test.go index b8cdfe879..6b8a0e5fe 100755 --- a/log/redactrus_test.go +++ b/log/redactrus_test.go @@ -171,15 +171,15 @@ func TestFireRedactsNamedStringTypes(t *testing.T) { } func TestFireRedactsContextSecrets(t *testing.T) { - ctx := WithSecrets(t.Context(), "s3cr3t") + ctx := WithSecrets(t.Context(), "s3cr3t-value") ctx = WithSecrets(ctx, "", "other-secret") e := &logrus.Entry{ Context: ctx, - Message: "value s3cr3t in message", + Message: "value s3cr3t-value in message", Data: logrus.Fields{ - "str": "has s3cr3t", + "str": "has s3cr3t-value", "named": namedString("named other-secret"), - "args": map[string]any{"p0": "s3cr3t", "p1": "plain"}, + "args": map[string]any{"p0": "s3cr3t-value", "p1": "plain"}, "error": errors.New("failed with other-secret"), "num": 42, "clean": namedString("untouched"), @@ -206,8 +206,17 @@ func TestFireWithoutContextSecretsLeavesEntryUnchanged(t *testing.T) { } func TestFireRedactsLongerSecretsFirst(t *testing.T) { - e := &logrus.Entry{Context: WithSecrets(t.Context(), "abc", "abcdef"), Message: "abcdef"} + ctx := WithSecrets(t.Context(), "abcdefgh", "abcdefghijkl") + e := &logrus.Entry{Context: ctx, Message: "abcdefghijkl"} assert.Nil(t, (&Hook{}).Fire(e)) assert.Equal(t, "[REDACTED]", e.Message) } + +func TestFireIgnoresShortSecrets(t *testing.T) { + ctx := WithSecrets(t.Context(), "abc") + e := &logrus.Entry{Context: ctx, Message: "abc in UPDATE ... abc"} + + assert.Nil(t, (&Hook{}).Fire(e)) + assert.Equal(t, "abc in UPDATE ... abc", e.Message) +} diff --git a/persistence/property_repository_test.go b/persistence/property_repository_test.go index 01814f41f..658a75b48 100644 --- a/persistence/property_repository_test.go +++ b/persistence/property_repository_test.go @@ -42,9 +42,12 @@ var _ = Describe("Property Repository", func() { It("hides values marked as secrets from the SQL log, but still logs the property id", func() { logs := captureTraceLogs() - 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()) + insertCtx := log.WithSecrets(ctx, "inserted-secret") + Expect(pr.Put(insertCtx, "secret-prop", "inserted-secret")).To(Succeed()) + updateCtx := log.WithSecrets(ctx, "updated-secret") + Expect(pr.Put(updateCtx, "secret-prop", "updated-secret")).To(Succeed()) + absentCtx := log.WithSecrets(ctx, "absent-secret") + Expect(pr.PutIfAbsent(absentCtx, "secret-prop-2", "absent-secret")).To(Succeed()) Expect(logs.String()).To(ContainSubstring("INSERT INTO property")) Expect(logs.String()).To(ContainSubstring("UPDATE property")) diff --git a/persistence/user_repository.go b/persistence/user_repository.go index f53682bd5..26f7b19d4 100644 --- a/persistence/user_repository.go +++ b/persistence/user_repository.go @@ -400,6 +400,7 @@ func (r *userRepository) initPasswordEncryptionKey(ctx context.Context) error { key := keyTo32Bytes(conf.Server.PasswordEncryptionKey) keySum := fmt.Sprintf("%x", sha256.Sum256(key)) + ctx = log.WithSecrets(ctx, keySum) props := NewPropertyRepository(r.db) savedKeySum, err := props.Get(ctx, consts.PasswordsEncryptedKey) @@ -433,7 +434,8 @@ 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(log.WithSecrets(ctx, u.NewPassword), upd) + userCtx := log.WithSecrets(ctx, u.NewPassword) + _, err = r.executeSQL(userCtx, 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 f90da0db9..156d43253 100644 --- a/persistence/user_repository_test.go +++ b/persistence/user_repository_test.go @@ -2,12 +2,16 @@ package persistence import ( "context" + "crypto/sha256" "errors" + "fmt" "slices" "sync" "github.com/Masterminds/squirrel" "github.com/deluan/rest" + "github.com/navidrome/navidrome/conf" + "github.com/navidrome/navidrome/conf/configtest" "github.com/navidrome/navidrome/consts" "github.com/navidrome/navidrome/log" "github.com/navidrome/navidrome/model" @@ -119,6 +123,33 @@ var _ = Describe("UserRepository", func() { }) }) + Describe("initPasswordEncryptionKey", func() { + It("never logs the encryption key checksum, but still logs its property id", func() { + DeferCleanup(configtest.SetupConfig()) + conf.Server.PasswordEncryptionKey = "a-new-password-encryption-key" + keySum := fmt.Sprintf("%x", sha256.Sum256(keyTo32Bytes(conf.Server.PasswordEncryptionKey))) + previousKey := encKey + DeferCleanup(func() { encKey = previousKey }) + tx, err := GetDBXBuilder().Begin() + Expect(err).ToNot(HaveOccurred()) + DeferCleanup(func() { _ = tx.Rollback() }) + _, err = tx.NewQuery("delete from user").Execute() + Expect(err).ToNot(HaveOccurred()) + txRepo := NewUserRepository(tx).(*userRepository) + Expect(txRepo.Put(ctx, &model.User{ID: "u-rekey", UserName: "rekeyed-user", NewPassword: "rekeyed-password"})).To(Succeed()) + + logs := captureTraceLogs() + Expect(txRepo.initPasswordEncryptionKey(ctx)).To(Succeed()) + + Expect(logs.String()).To(ContainSubstring("UPDATE user")) + Expect(logs.String()).To(ContainSubstring(consts.PasswordsEncryptedKey)) + Expect(logs.String()).ToNot(ContainSubstring(keySum)) + var rekeyed string + Expect(tx.NewQuery("select password from user where id = 'u-rekey'").Row(&rekeyed)).To(Succeed()) + Expect(logs.String()).ToNot(ContainSubstring(rekeyed)) + }) + }) + Describe("validatePasswordChange", func() { var loggedUser *model.User