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

@@ -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)
 }
 

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"))
+	})
 })

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)

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

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

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"))
 		})
 	})

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)
+}

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"))

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 {

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