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

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

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

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:]
 		}
 	}

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() {

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 {

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

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

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

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

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 {

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