mirror of
https://github.com/navidrome/navidrome.git
synced 2026-10-08 10:27:08 +02:00
46c432719fThe startup Configuration dump is rendered with pretty.Sprintf("%# v"), which
pads multi-line struct fields with spaces after the colon. The ApiKey and
Secret redaction patterns required the quote right after the colon, so
LastFM.ApiKey and LastFM.Secret were logged in clear text even with
EnableLogRedacting on. Allow optional whitespace after the colon, like the
other config patterns already do.
Prometheus.Password had no redaction pattern at all. Add one that also skips
escaped quotes, since the password can hold any character and pretty prints
it Go-quoted.
Add tests for the padded and unpadded forms, plus one that redacts a real
pretty.Sprintf dump of LastFM- and Prometheus-shaped structs so a padding
change in pretty can't bring the leak back.
Reported in https://github.com/navidrome/navidrome/discussions/6232
360 lines
11 KiB
Go
360 lines
11 KiB
Go
package log
|
|
|
|
import (
|
|
"context"
|
|
"encoding/json"
|
|
"errors"
|
|
"net/http"
|
|
"net/http/httptest"
|
|
"testing"
|
|
"time"
|
|
|
|
"github.com/kr/pretty"
|
|
. "github.com/onsi/ginkgo/v2"
|
|
. "github.com/onsi/gomega"
|
|
"github.com/sirupsen/logrus"
|
|
"github.com/sirupsen/logrus/hooks/test"
|
|
)
|
|
|
|
func TestLog(t *testing.T) {
|
|
SetLevel(LevelInfo)
|
|
RegisterFailHandler(Fail)
|
|
RunSpecs(t, "Log Suite")
|
|
}
|
|
|
|
var _ = Describe("Logger", func() {
|
|
var l *logrus.Logger
|
|
var hook *test.Hook
|
|
|
|
BeforeEach(func() {
|
|
l, hook = test.NewNullLogger()
|
|
SetLevel(LevelTrace)
|
|
SetDefaultLogger(l)
|
|
})
|
|
|
|
Describe("Logging", func() {
|
|
It("logs a simple message", func() {
|
|
Error("Simple Message")
|
|
Expect(hook.LastEntry().Message).To(Equal("Simple Message"))
|
|
Expect(hook.LastEntry().Data).To(BeEmpty())
|
|
})
|
|
|
|
It("logs a message when context is nil", func() {
|
|
Error(nil, "Simple Message")
|
|
Expect(hook.LastEntry().Message).To(Equal("Simple Message"))
|
|
Expect(hook.LastEntry().Data).To(BeEmpty())
|
|
})
|
|
|
|
It("Empty context", func() {
|
|
Error(context.TODO(), "Simple Message")
|
|
Expect(hook.LastEntry().Message).To(Equal("Simple Message"))
|
|
Expect(hook.LastEntry().Data).To(BeEmpty())
|
|
})
|
|
|
|
It("logs messages with two kv pairs", func() {
|
|
Error("Simple Message", "key1", "value1", "key2", "value2")
|
|
Expect(hook.LastEntry().Message).To(Equal("Simple Message"))
|
|
Expect(hook.LastEntry().Data["key1"]).To(Equal("value1"))
|
|
Expect(hook.LastEntry().Data["key2"]).To(Equal("value2"))
|
|
Expect(hook.LastEntry().Data).To(HaveLen(2))
|
|
})
|
|
|
|
It("logs error objects as simple messages", func() {
|
|
Error(errors.New("error test"))
|
|
Expect(hook.LastEntry().Message).To(Equal("error test"))
|
|
Expect(hook.LastEntry().Data).To(BeEmpty())
|
|
})
|
|
|
|
It("logs errors passed as last argument", func() {
|
|
Error("Error scrobbling track", "id", 1, errors.New("some issue"))
|
|
Expect(hook.LastEntry().Message).To(Equal("Error scrobbling track"))
|
|
Expect(hook.LastEntry().Data["id"]).To(Equal(1))
|
|
Expect(hook.LastEntry().Data["error"]).To(Equal("some issue"))
|
|
Expect(hook.LastEntry().Data).To(HaveLen(2))
|
|
})
|
|
|
|
It("can get data from the request's context", func() {
|
|
ctx := NewContext(context.TODO(), "foo", "bar")
|
|
req := httptest.NewRequest("get", "/", nil).WithContext(ctx)
|
|
|
|
Error(req, "Simple Message", "key1", "value1")
|
|
|
|
Expect(hook.LastEntry().Message).To(Equal("Simple Message"))
|
|
Expect(hook.LastEntry().Data["foo"]).To(Equal("bar"))
|
|
Expect(hook.LastEntry().Data["key1"]).To(Equal("value1"))
|
|
Expect(hook.LastEntry().Data).To(HaveLen(2))
|
|
})
|
|
|
|
It("does not log anything if level is lower", func() {
|
|
SetLevel(LevelError)
|
|
Info("Simple Message")
|
|
Expect(hook.LastEntry()).To(BeNil())
|
|
})
|
|
|
|
It("logs source file and line number, if requested", func() {
|
|
SetLogSourceLine(true)
|
|
Error("A crash happened")
|
|
// NOTE: This assertion breaks if the line number above changes
|
|
Expect(hook.LastEntry().Data[" source"]).To(ContainSubstring("/log/log_test.go:96"))
|
|
Expect(hook.LastEntry().Message).To(Equal("A crash happened"))
|
|
})
|
|
|
|
It("logs fmt.Stringer as a string", func() {
|
|
t := time.Now()
|
|
Error("Simple Message", "key1", t)
|
|
Expect(hook.LastEntry().Data["key1"]).To(Equal(t.String()))
|
|
})
|
|
It("logs nil fmt.Stringer as nil", func() {
|
|
var t *time.Time
|
|
Error("Simple Message", "key1", t)
|
|
Expect(hook.LastEntry().Data["key1"]).To(Equal("nil"))
|
|
})
|
|
})
|
|
|
|
Describe("Levels", func() {
|
|
BeforeEach(func() {
|
|
SetLevel(LevelTrace)
|
|
})
|
|
It("logs error messages", func() {
|
|
Error("msg")
|
|
Expect(hook.LastEntry().Level).To(Equal(logrus.ErrorLevel))
|
|
})
|
|
It("logs warn messages", func() {
|
|
Warn("msg")
|
|
Expect(hook.LastEntry().Level).To(Equal(logrus.WarnLevel))
|
|
})
|
|
It("logs info messages", func() {
|
|
Info("msg")
|
|
Expect(hook.LastEntry().Level).To(Equal(logrus.InfoLevel))
|
|
})
|
|
It("logs debug messages", func() {
|
|
Debug("msg")
|
|
Expect(hook.LastEntry().Level).To(Equal(logrus.DebugLevel))
|
|
})
|
|
It("logs trace messages", func() {
|
|
Trace("msg")
|
|
Expect(hook.LastEntry().Level).To(Equal(logrus.TraceLevel))
|
|
})
|
|
})
|
|
|
|
Describe("LogLevels", func() {
|
|
BeforeEach(func() {
|
|
SetLevel(LevelFatal)
|
|
SetLogLevels(nil)
|
|
})
|
|
|
|
DescribeTable("logs at specific levels", func(logger func(...any), level Level) {
|
|
logger("message 1")
|
|
Expect(hook.LastEntry()).To(BeNil())
|
|
|
|
Log(level, "message 1.5")
|
|
Expect(hook.LastEntry()).To(BeNil())
|
|
|
|
SetLogLevels(map[string]string{"log/log_test": "trace"})
|
|
|
|
logger("message 2")
|
|
Expect(hook.LastEntry().Message).To(Equal("message 2"))
|
|
|
|
Log(level, "message 2.5")
|
|
Expect(hook.LastEntry().Message).To(Equal("message 2.5"))
|
|
},
|
|
Entry("Error", Error, LevelError),
|
|
Entry("Warn", Warn, LevelWarn),
|
|
Entry("Info", Info, LevelInfo),
|
|
Entry("Debug", Debug, LevelDebug),
|
|
Entry("Trace", Trace, LevelTrace),
|
|
)
|
|
})
|
|
|
|
Describe("IsGreaterOrEqualTo", func() {
|
|
BeforeEach(func() {
|
|
SetLogLevels(nil)
|
|
})
|
|
|
|
It("returns false if log level is below provided level", func() {
|
|
SetLevel(LevelError)
|
|
Expect(IsGreaterOrEqualTo(LevelWarn)).To(BeFalse())
|
|
})
|
|
|
|
It("returns true if log level is equal to provided level", func() {
|
|
SetLevel(LevelWarn)
|
|
Expect(IsGreaterOrEqualTo(LevelWarn)).To(BeTrue())
|
|
})
|
|
|
|
It("returns true if log level is above provided level", func() {
|
|
SetLevel(LevelTrace)
|
|
Expect(IsGreaterOrEqualTo(LevelDebug)).To(BeTrue())
|
|
})
|
|
|
|
It("returns true if log level for the current code path is equal provided level", func() {
|
|
SetLevel(LevelError)
|
|
SetLogLevels(map[string]string{
|
|
"log/log_test": "debug",
|
|
})
|
|
|
|
// Need to nest it in a function to get the correct code path
|
|
var result = func() bool {
|
|
return IsGreaterOrEqualTo(LevelDebug)
|
|
}()
|
|
|
|
Expect(result).To(BeTrue())
|
|
})
|
|
})
|
|
|
|
Describe("extractLogger", func() {
|
|
It("returns an error if the context is nil", func() {
|
|
_, err := extractLogger(nil)
|
|
Expect(err).ToNot(BeNil())
|
|
})
|
|
|
|
It("returns an error if the context is a string", func() {
|
|
_, err := extractLogger("any msg")
|
|
Expect(err).ToNot(BeNil())
|
|
})
|
|
|
|
It("returns the logger from context if it has one", func() {
|
|
logger := logrus.NewEntry(logrus.New())
|
|
ctx := context.Background()
|
|
ctx = context.WithValue(ctx, loggerCtxKey, logger)
|
|
|
|
Expect(extractLogger(ctx)).To(Equal(logger))
|
|
})
|
|
|
|
It("returns the logger from request's context if it has one", func() {
|
|
logger := logrus.NewEntry(logrus.New())
|
|
ctx := context.Background()
|
|
ctx = context.WithValue(ctx, loggerCtxKey, logger)
|
|
req := httptest.NewRequest("get", "/", nil).WithContext(ctx)
|
|
|
|
Expect(extractLogger(req)).To(Equal(logger))
|
|
})
|
|
})
|
|
|
|
Describe("SetLevelString", func() {
|
|
It("converts Fatal level", func() {
|
|
SetLevelString("Fatal")
|
|
Expect(CurrentLevel()).To(Equal(LevelFatal))
|
|
})
|
|
It("converts Error level", func() {
|
|
SetLevelString("ERROR")
|
|
Expect(CurrentLevel()).To(Equal(LevelError))
|
|
})
|
|
It("converts Warn level", func() {
|
|
SetLevelString("warn")
|
|
Expect(CurrentLevel()).To(Equal(LevelWarn))
|
|
})
|
|
It("converts Info level", func() {
|
|
SetLevelString("info")
|
|
Expect(CurrentLevel()).To(Equal(LevelInfo))
|
|
})
|
|
It("converts Debug level", func() {
|
|
SetLevelString("debug")
|
|
Expect(CurrentLevel()).To(Equal(LevelDebug))
|
|
})
|
|
It("converts Trace level", func() {
|
|
SetLevelString("trace")
|
|
Expect(CurrentLevel()).To(Equal(LevelTrace))
|
|
})
|
|
})
|
|
|
|
Describe("Redact", func() {
|
|
Describe("Subsonic API password", func() {
|
|
msg := "getLyrics.view?v=1.2.0&c=iSub&u=user_name&p=first%20and%20other%20words&title=Title"
|
|
Expect(Redact(msg)).To(Equal("getLyrics.view?v=1.2.0&c=iSub&u=user_name&p=[REDACTED]&title=Title"))
|
|
})
|
|
|
|
It("redacts a whole JWT in api_key, not just up to its first dot", func() {
|
|
msg := "/jellyfin/Audio/abc/universal?static=true&api_key=eyJhbGciOiJIUzI1NiJ9.eyJzdWIiOiJhZG1pbiJ9.c2ln-X_1&other=1"
|
|
Expect(Redact(msg)).To(Equal("/jellyfin/Audio/abc/universal?static=true&api_key=[REDACTED]&other=1"))
|
|
})
|
|
|
|
DescribeTable("redacts every api_key spelling the Jellyfin API accepts",
|
|
func(param string) {
|
|
msg := "/jellyfin/Audio/abc/File?" + param + "=SECRET&other=1"
|
|
Expect(Redact(msg)).To(Equal("/jellyfin/Audio/abc/File?" + param + "=[REDACTED]&other=1"))
|
|
},
|
|
Entry("api_key", "api_key"),
|
|
Entry("apikey", "apikey"),
|
|
Entry("ApiKey", "ApiKey"),
|
|
Entry("APIKEY", "APIKEY"),
|
|
)
|
|
|
|
It("redacts sensitive request headers in a logged header blob", func() {
|
|
h := http.Header{
|
|
"Authorization": {`MediaBrowser Client="Finamp", Token="jwt-secret"`},
|
|
"X-Emby-Token": {"emby-secret"},
|
|
"X-Mediabrowser-Token": {"mb-secret"},
|
|
"X-Nd-Authorization": {"Bearer nd-secret"},
|
|
"User-Agent": {"Finamp/1.0"},
|
|
}
|
|
blob, _ := json.Marshal(h)
|
|
got := Redact(string(blob))
|
|
Expect(got).ToNot(ContainSubstring("secret"))
|
|
Expect(got).To(ContainSubstring(`"User-Agent":["Finamp/1.0"]`))
|
|
})
|
|
|
|
// https://github.com/navidrome/navidrome/discussions/6232
|
|
DescribeTable("redacts config keys in the startup Configuration dump",
|
|
func(line, expected string) {
|
|
Expect(Redact(line)).To(Equal(expected))
|
|
},
|
|
Entry("unpadded ApiKey", `ApiKey:"0123456789abcdef0123456789abcdef"`, `ApiKey:"[REDACTED]"`),
|
|
Entry("unpadded Secret", `Secret:"fedcba9876543210fedcba9876543210"`, `Secret:"[REDACTED]"`),
|
|
Entry("padded ApiKey", ` ApiKey: "0123456789abcdef0123456789abcdef",`,
|
|
` ApiKey: "[REDACTED]",`),
|
|
Entry("padded Secret", ` Secret: "fedcba9876543210fedcba9876543210",`,
|
|
` Secret: "[REDACTED]",`),
|
|
Entry("unpadded Prometheus Password", `Password:"p@ss w0rd!"`, `Password:"[REDACTED]"`),
|
|
Entry("padded Prometheus Password", ` Password: "p@ss w0rd!",`, ` Password: "[REDACTED]",`),
|
|
Entry("Prometheus Password with escaped quotes", ` Password: "a\"b\\\"c",`,
|
|
` Password: "[REDACTED]",`),
|
|
)
|
|
|
|
It("redacts secrets in a pretty-printed config struct", func() {
|
|
// Mirrors conf.lastfmOptions and conf.prometheusOptions (conf imports log, so it can't be
|
|
// used here). pretty only breaks a struct into padded lines when it is long enough, so
|
|
// keep all the fields.
|
|
type lastfmOptions struct {
|
|
Enabled bool
|
|
ApiKey string
|
|
Secret string
|
|
Language string
|
|
ScrobbleFirstArtistOnly bool
|
|
Languages []string
|
|
}
|
|
type prometheusOptions struct {
|
|
Enabled bool
|
|
MetricsPath string
|
|
Password string
|
|
}
|
|
type configOptions struct {
|
|
Address string
|
|
LastFM lastfmOptions
|
|
Prometheus prometheusOptions
|
|
}
|
|
cfg := configOptions{
|
|
Address: "0.0.0.0",
|
|
LastFM: lastfmOptions{ //nolint:gosec
|
|
Enabled: true,
|
|
ApiKey: "0123456789abcdef0123456789abcdef",
|
|
Secret: "fedcba9876543210fedcba9876543210",
|
|
Language: "en",
|
|
Languages: []string{"en"},
|
|
},
|
|
Prometheus: prometheusOptions{ //nolint:gosec
|
|
Enabled: true,
|
|
MetricsPath: "/metrics",
|
|
Password: `prom"pass-tail`,
|
|
},
|
|
}
|
|
dump := pretty.Sprintf("Configuration: %# v", cfg)
|
|
Expect(dump).To(MatchRegexp(`ApiKey:\s{2,}"`), "the dump must use the padded layout")
|
|
|
|
got := Redact(dump)
|
|
Expect(got).ToNot(ContainSubstring(cfg.LastFM.ApiKey))
|
|
Expect(got).ToNot(ContainSubstring(cfg.LastFM.Secret))
|
|
Expect(got).ToNot(ContainSubstring("pass-tail"))
|
|
Expect(got).To(ContainSubstring(`"en"`))
|
|
})
|
|
})
|
|
})
|