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