mirror of
https://github.com/navidrome/navidrome.git
synced 2026-10-08 02:17:25 +02:00
383 lines
12 KiB
Go
383 lines
12 KiB
Go
package log
|
|
|
|
import (
|
|
"bytes"
|
|
"context"
|
|
"encoding/json"
|
|
"errors"
|
|
"fmt"
|
|
"net/http"
|
|
"net/http/httptest"
|
|
"runtime"
|
|
"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)
|
|
_, _, line, _ := runtime.Caller(0)
|
|
Error("A crash happened")
|
|
Expect(hook.LastEntry().Data[" source"]).To(ContainSubstring(fmt.Sprintf("/log/log_test.go:%d", line+1)))
|
|
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"))
|
|
})
|
|
|
|
It("passes the call's context to hooks", func() {
|
|
ctx := WithSecrets(GinkgoT().Context(), "s3cr3t-value")
|
|
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-value")
|
|
|
|
var buf bytes.Buffer
|
|
l.SetOutput(&buf)
|
|
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"))
|
|
})
|
|
})
|
|
|
|
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"`))
|
|
})
|
|
})
|
|
})
|