diff --git a/core/lyrics/lyrics_test.go b/core/lyrics/lyrics_test.go index 6baacbe71..b00bcd576 100644 --- a/core/lyrics/lyrics_test.go +++ b/core/lyrics/lyrics_test.go @@ -21,10 +21,15 @@ var _ = Describe("Lyrics", func() { var mf model.MediaFile var ctx context.Context - const badLyrics = "This is a set of lyrics\nThat is not good" - unsyncedList, _ := model.ParseLyrics(".lrc", "xxx", []byte(badLyrics)) - unsynced, _ := unsyncedList.Main() - embeddedLyrics := model.LyricList{unsynced} + embeddedLyrics := model.LyricList{ + model.Lyrics{ + Lang: "xxx", + Line: []model.Line{ + {Value: "This is a set of lyrics"}, + {Value: "That is not good"}, + }, + }, + } syncedLyrics := model.LyricList{ model.Lyrics{ @@ -390,7 +395,7 @@ var _ = Describe("Lyrics", func() { }) It("resolves lyrics from the matched media files", func() { - embeddedList, err := model.ParseLyrics(".lrc", "eng", []byte("Embedded lyrics line")) + embeddedList, err := model.ParseLyrics(ctx, ".lrc", "eng", []byte("Embedded lyrics line")) Expect(err).ToNot(HaveOccurred()) embedded, _ := embeddedList.Main() embeddedJSON, err := json.Marshal(model.LyricList{embedded}) diff --git a/core/lyrics/sources.go b/core/lyrics/sources.go index 9de2f6a18..23c20122d 100644 --- a/core/lyrics/sources.go +++ b/core/lyrics/sources.go @@ -28,6 +28,7 @@ func fromEmbedded(ctx context.Context, mf *model.MediaFile) (model.LyricList, er func fromExternalFile(ctx context.Context, mf *model.MediaFile, suffix string) (model.LyricList, error) { ext := path.Ext(mf.Path) sidecarRelPath := mf.Path[0:len(mf.Path)-len(ext)] + suffix + ctx = log.NewContext(ctx, "file", sidecarRelPath) store, err := storage.For(mf.LibraryPath) if err != nil { @@ -40,7 +41,7 @@ func fromExternalFile(ctx context.Context, mf *model.MediaFile, suffix string) ( f, err := fsys.Open(sidecarRelPath) if errors.Is(err, fs.ErrNotExist) { - log.Trace(ctx, "no lyrics found at path", "path", sidecarRelPath) + log.Trace(ctx, "no lyrics found at path") return nil, nil } else if err != nil { return nil, err @@ -52,18 +53,18 @@ func fromExternalFile(ctx context.Context, mf *model.MediaFile, suffix string) ( return nil, err } - list, err := model.ParseLyrics(suffix, "xxx", contents) + list, err := model.ParseLyrics(ctx, suffix, "xxx", contents) if err != nil { - log.Error(ctx, "error parsing external lyric file", "path", sidecarRelPath, err) + log.Error(ctx, "error parsing external lyric file", err) return nil, err } if len(list) == 0 { - log.Trace(ctx, "empty lyrics from external file", "path", sidecarRelPath) + log.Trace(ctx, "empty lyrics from external file") return nil, nil } - log.Trace(ctx, "retrieved lyrics from external file", "path", sidecarRelPath) + log.Trace(ctx, "retrieved lyrics from external file") return list, nil } diff --git a/core/lyrics/sources_test.go b/core/lyrics/sources_test.go index 68f45424e..7c7922bfd 100644 --- a/core/lyrics/sources_test.go +++ b/core/lyrics/sources_test.go @@ -11,7 +11,11 @@ import ( ) var _ = Describe("sources", func() { - ctx := context.Background() + var ctx context.Context + + BeforeEach(func() { + ctx = GinkgoT().Context() + }) Describe("fromEmbedded", func() { It("should return nothing for a media file with no lyrics", func() { @@ -26,8 +30,8 @@ var _ = Describe("sources", func() { const syncedLyrics = "[00:18.80]We're no strangers to love\n[00:22.801]You know the rules and so do I" const unsyncedLyrics = "We're no strangers to love\nYou know the rules and so do I" - syncedList, _ := model.ParseLyrics(".lrc", "eng", []byte(syncedLyrics)) - unsyncedList, _ := model.ParseLyrics(".lrc", "xxx", []byte(unsyncedLyrics)) + syncedList, _ := model.ParseLyrics(ctx, ".lrc", "eng", []byte(syncedLyrics)) + unsyncedList, _ := model.ParseLyrics(ctx, ".lrc", "xxx", []byte(unsyncedLyrics)) synced, _ := syncedList.Main() unsynced, _ := unsyncedList.Main() diff --git a/db/migrations/20231209211223_alter_lyric_column.go b/db/migrations/20231209211223_alter_lyric_column.go index 259a37745..7f1ad2f38 100644 --- a/db/migrations/20231209211223_alter_lyric_column.go +++ b/db/migrations/20231209211223_alter_lyric_column.go @@ -46,7 +46,7 @@ func upAlterLyricColumn(ctx context.Context, tx *sql.Tx) error { continue } - parsed, err := model.ParseLyrics(".lrc", "xxx", []byte(lyrics.String)) + parsed, err := model.ParseLyrics(ctx, ".lrc", "xxx", []byte(lyrics.String)) if err != nil { return err } diff --git a/log/log.go b/log/log.go index b1d6eee10..eaea75fb9 100644 --- a/log/log.go +++ b/log/log.go @@ -175,10 +175,14 @@ func NewContext(ctx context.Context, keyValuePairs ...any) context.Context { return ctx } -func SetDefaultLogger(l *logrus.Logger) { +// 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 { loggerMu.Lock() defer loggerMu.Unlock() + prev := defaultLogger defaultLogger = l + return prev } func CurrentLevel() Level { diff --git a/model/lyrics_benchmark_test.go b/model/lyrics_benchmark_test.go index 0de2549e7..5a7d7871e 100644 --- a/model/lyrics_benchmark_test.go +++ b/model/lyrics_benchmark_test.go @@ -24,7 +24,7 @@ func benchmarkParse(b *testing.B, suffix, fixture string) { b.ReportAllocs() b.SetBytes(int64(len(contents))) for b.Loop() { - if _, err := ParseLyrics(suffix, "eng", contents); err != nil { + if _, err := ParseLyrics(b.Context(), suffix, "eng", contents); err != nil { b.Fatal(err) } } diff --git a/model/lyrics_parse.go b/model/lyrics_parse.go index 4bfaa29e8..8aa095c50 100644 --- a/model/lyrics_parse.go +++ b/model/lyrics_parse.go @@ -2,6 +2,7 @@ package model import ( "bytes" + "context" "fmt" "slices" "strings" @@ -28,7 +29,10 @@ var lyricFormats = []struct { // ParseLyrics is the single entry point for parsing lyrics. A known suffix routes // to that format's parser; an empty or "auto" suffix content-sniffs. Either way, // a structured parser that does not match falls back to the LRC/plain-text floor. -func ParseLyrics(suffix, lang string, contents []byte) (LyricList, error) { +// +// Parse failures are logged through ctx; callers that know the source should +// attach it for attribution, e.g. log.NewContext(ctx, "file", path). +func ParseLyrics(ctx context.Context, suffix, lang string, contents []byte) (LyricList, error) { contents = stripBOM(contents) suffix = strings.ToLower(suffix) sniff := suffix == "" || suffix == "auto" @@ -41,17 +45,24 @@ func ParseLyrics(suffix, lang string, contents []byte) (LyricList, error) { candidates = append(candidates, f.parse) } } - return parseFirstMatch(lang, contents, candidates...) + return parseFirstMatch(ctx, sniff, lang, contents, candidates...) } -func parseFirstMatch(lang string, contents []byte, candidates ...lyricParser) (LyricList, error) { +func parseFirstMatch(ctx context.Context, sniff bool, lang string, contents []byte, candidates ...lyricParser) (LyricList, error) { for _, parse := range candidates { list, err := parse(lang, contents) if err == nil && len(list) > 0 { return list, nil } if err != nil { - log.Warn("Error parsing lyrics, falling back to plain text", "error", err) + // While sniffing, a probe rejecting content it does not own is expected + // control flow, so keep it at trace. A failure under an explicit suffix + // means the declared format is malformed and deserves a warning. + if sniff { + log.Trace(ctx, "Lyrics probe did not match, trying next format", err) + } else { + log.Warn(ctx, "Error parsing lyrics, falling back to plain text", err) + } } } return plainLRC(lang, contents) diff --git a/model/lyrics_parse_test.go b/model/lyrics_parse_test.go index eb58a29ef..0b47e55e9 100644 --- a/model/lyrics_parse_test.go +++ b/model/lyrics_parse_test.go @@ -3,14 +3,17 @@ package model import ( "strings" + "github.com/navidrome/navidrome/log" . "github.com/onsi/ginkgo/v2" . "github.com/onsi/gomega" + "github.com/sirupsen/logrus" + "github.com/sirupsen/logrus/hooks/test" ) var _ = Describe("ParseLyrics", func() { DescribeTable("known suffix routes to the matching parser", func(suffix, contents string, wantSynced bool, wantFirst string) { - list, err := ParseLyrics(suffix, "eng", []byte(contents)) + list, err := ParseLyrics(GinkgoT().Context(), suffix, "eng", []byte(contents)) Expect(err).ToNot(HaveOccurred()) Expect(list).To(HaveLen(1)) Expect(list[0].Synced).To(Equal(wantSynced)) @@ -25,7 +28,7 @@ var _ = Describe("ParseLyrics", func() { It("empty suffix content-sniffs (TTML)", func() { ttml := `

auto ttml

` - list, err := ParseLyrics("", "eng", []byte(ttml)) + list, err := ParseLyrics(GinkgoT().Context(), "", "eng", []byte(ttml)) Expect(err).ToNot(HaveOccurred()) Expect(list).To(HaveLen(1)) Expect(list[0].Line[0].Value).To(Equal("auto ttml")) @@ -33,19 +36,72 @@ var _ = Describe("ParseLyrics", func() { It("empty suffix content-sniffs (YAML)", func() { yaml := "version: \"1.0\"\nmetadata:\n language: eng\nlines:\n - text: auto yaml\n start_ms: 1000\n" - list, err := ParseLyrics("auto", "eng", []byte(yaml)) + list, err := ParseLyrics(GinkgoT().Context(), "auto", "eng", []byte(yaml)) Expect(err).ToNot(HaveOccurred()) Expect(list).To(HaveLen(1)) Expect(list[0].Line[0].Value).To(Equal("auto yaml")) }) It("falls back to plain text when a known suffix fails to parse structurally", func() { - list, err := ParseLyrics(".srt", "eng", []byte("not actually an srt file")) + list, err := ParseLyrics(GinkgoT().Context(), ".srt", "eng", []byte("not actually an srt file")) Expect(err).ToNot(HaveOccurred()) Expect(list).To(HaveLen(1)) Expect(list[0].Synced).To(BeFalse()) Expect(list[0].Line[0].Value).To(Equal("not actually an srt file")) }) + + Describe("logging on parser probe failures", func() { + var hook *test.Hook + + BeforeEach(func() { + prevLevel := log.CurrentLevel() + l, h := test.NewNullLogger() + hook = h + // Swap the logger before raising the level: SetLevel also forces the + // current default logger to logrus.TraceLevel, and the null logger would + // otherwise stay at Info and drop Trace entries before the hook sees them. + prevLogger := log.SetDefaultLogger(l) + log.SetLevel(log.LevelTrace) + DeferCleanup(func() { + log.SetDefaultLogger(prevLogger) + log.SetLevel(prevLevel) + }) + }) + + // This is the source of the full-scan log spam: embedded lyrics are parsed + // with an empty suffix (sniff mode), so every plain-text lyric fails the + // YAML/SRT/TTML probes on its way to the plain-text fallback. A probe miss + // during sniffing is expected control flow, not a warning. + It("logs sniff probe misses at trace only, with file attribution", func() { + ctx := log.NewContext(GinkgoT().Context(), "file", "/music/song.mp3") + list, err := ParseLyrics(ctx, "", "eng", []byte("Just a plain\nlyric line\n")) + + Expect(err).ToNot(HaveOccurred()) + Expect(list).To(HaveLen(1)) + Expect(list[0].Line[0].Value).To(Equal("Just a plain")) + entries := hook.AllEntries() + Expect(entries).ToNot(BeEmpty(), "probe misses should be observable at trace") + for _, e := range entries { + Expect(e.Level).To(Equal(logrus.TraceLevel), + "sniff-mode probe misses must not be logged above Trace") + Expect(e.Data).To(HaveKeyWithValue("file", "/music/song.mp3")) + } + }) + + // A specific suffix means the user declared the format, so a structural + // failure is worth surfacing loudly — and it must name the file. + It("warns and names the file when a requested suffix fails to parse", func() { + ctx := log.NewContext(GinkgoT().Context(), "file", "/music/song.yaml") + list, err := ParseLyrics(ctx, ".yaml", "eng", []byte("not: [valid, yaml\n")) + + Expect(err).ToNot(HaveOccurred()) + Expect(list).To(HaveLen(1)) // still falls back to plain text + entry := hook.LastEntry() + Expect(entry).ToNot(BeNil()) + Expect(entry.Level).To(Equal(logrus.WarnLevel)) + Expect(entry.Data).To(HaveKeyWithValue("file", "/music/song.yaml")) + }) + }) }) var _ = Describe("ParseLyrics content-sniffing", func() { @@ -67,7 +123,7 @@ var _ = Describe("ParseLyrics content-sniffing", func() { ` - list, err := ParseLyrics("", "ENG", []byte(content)) + list, err := ParseLyrics(GinkgoT().Context(), "", "ENG", []byte(content)) // ParseLyrics's job is to detect TTML and apply the tag language as the // default; the parser's cue/agent details are covered in lyrics_ttml_test.go. @@ -104,7 +160,7 @@ var _ = Describe("ParseLyrics content-sniffing", func() { ` - list, err := ParseLyrics("", "eng", []byte(content)) + list, err := ParseLyrics(GinkgoT().Context(), "", "eng", []byte(content)) Expect(err).ToNot(HaveOccurred()) Expect(list).To(HaveLen(3)) @@ -129,7 +185,7 @@ We're from subtitles 00:00:22,801 --> 00:00:26,000 Another subtitle line` - list, err := ParseLyrics("", "POR", []byte(content)) + list, err := ParseLyrics(GinkgoT().Context(), "", "POR", []byte(content)) Expect(err).ToNot(HaveOccurred()) Expect(list).To(Equal(LyricList{ @@ -155,7 +211,7 @@ Another subtitle line` It("should parse embedded SRT blocks separated by whitespace-only blank lines", func() { content := "1\n00:00:01,000 --> 00:00:02,000\nFirst subtitle\n \n2\n00:00:03,000 --> 00:00:04,000\nSecond subtitle" - list, err := ParseLyrics("", "eng", []byte(content)) + list, err := ParseLyrics(GinkgoT().Context(), "", "eng", []byte(content)) Expect(err).ToNot(HaveOccurred()) Expect(list).To(HaveLen(1)) @@ -168,7 +224,7 @@ Another subtitle line` It("should keep embedded enhanced LRC cues", func() { content := "[00:01.00]<00:01.00>Lead <00:01.50>words" - list, err := ParseLyrics("", "eng", []byte(content)) + list, err := ParseLyrics(GinkgoT().Context(), "", "eng", []byte(content)) Expect(err).ToNot(HaveOccurred()) Expect(list).To(HaveLen(1)) @@ -185,7 +241,7 @@ Another subtitle line` ` - list, err := ParseLyrics("", "eng", []byte(content)) + list, err := ParseLyrics(GinkgoT().Context(), "", "eng", []byte(content)) Expect(err).ToNot(HaveOccurred()) Expect(list).To(HaveLen(1)) @@ -202,7 +258,7 @@ Another subtitle line` It("detects a Lyricsfile YAML payload via content-sniffing", func() { yaml := "version: \"1.0\"\nmetadata:\n title: Song\n language: eng\nlines:\n - text: sniffed yaml line\n start_ms: 1000\n" - list, err := ParseLyrics("", "eng", []byte(yaml)) + list, err := ParseLyrics(GinkgoT().Context(), "", "eng", []byte(yaml)) Expect(err).ToNot(HaveOccurred()) Expect(list).To(HaveLen(1)) diff --git a/model/metadata/map_mediafile.go b/model/metadata/map_mediafile.go index de2ba813e..b3ce4ef02 100644 --- a/model/metadata/map_mediafile.go +++ b/model/metadata/map_mediafile.go @@ -2,6 +2,7 @@ package metadata import ( "cmp" + "context" "encoding/json" "maps" "math" @@ -139,13 +140,14 @@ func (md Metadata) mapLyrics() string { lyricList := make(model.LyricList, 0, len(rawLyrics)) + ctx := log.NewContext(context.Background(), "file", md.filePath) for _, raw := range rawLyrics { lang := raw.Key() text := raw.Value() - lyrics, err := model.ParseLyrics("", lang, []byte(text)) + lyrics, err := model.ParseLyrics(ctx, "", lang, []byte(text)) if err != nil { - log.Warn("Unexpected failure occurred when parsing lyrics", "file", md.filePath, err) + log.Warn(ctx, "Unexpected failure occurred when parsing lyrics", err) continue } for _, lyric := range lyrics { diff --git a/plugins/lyrics_adapter.go b/plugins/lyrics_adapter.go index 12d84f60d..281f022fb 100644 --- a/plugins/lyrics_adapter.go +++ b/plugins/lyrics_adapter.go @@ -44,15 +44,19 @@ func (l *LyricsPlugin) GetLyrics(ctx context.Context, mf *model.MediaFile) (mode return nil, err } + // The lyric text comes from the plugin, not the media file's own tags, so + // attribute logs to both the plugin and the track it was fetched for. + ctx = log.NewContext(ctx, "plugin", l.name, "file", mf.Path) + var result model.LyricList for _, lt := range resp.Lyrics { lang := lt.Lang if lang == "" { lang = "xxx" } - parsed, err := model.ParseLyrics("", lang, []byte(lt.Text)) + parsed, err := model.ParseLyrics(ctx, "", lang, []byte(lt.Text)) if err != nil { - log.Warn(ctx, "Error parsing plugin lyrics", "plugin", l.name, err) + log.Warn(ctx, "Error parsing plugin lyrics", err) continue } for _, lyric := range parsed { diff --git a/scanner/metadata_old/metadata.go b/scanner/metadata_old/metadata.go index 8cde586b9..2906a2c09 100644 --- a/scanner/metadata_old/metadata.go +++ b/scanner/metadata_old/metadata.go @@ -1,6 +1,7 @@ package metadata_old import ( + "context" "encoding/json" "fmt" "math" @@ -205,7 +206,7 @@ func (t Tags) Lyrics() string { basicLyrics := t.getAllTagValues("lyrics", "unsynced_lyrics", "unsynced lyrics", "unsyncedlyrics") for _, value := range basicLyrics { - parsed, err := model.ParseLyrics(".lrc", "xxx", []byte(value)) + parsed, err := model.ParseLyrics(context.Background(), ".lrc", "xxx", []byte(value)) if err != nil { log.Warn("Unexpected failure occurred when parsing lyrics", "file", t.filePath, "error", err) continue @@ -224,7 +225,7 @@ func (t Tags) Lyrics() string { } for _, text := range value { - parsed, err := model.ParseLyrics(".lrc", language, []byte(text)) + parsed, err := model.ParseLyrics(context.Background(), ".lrc", language, []byte(text)) if err != nil { log.Warn("Unexpected failure occurred when parsing lyrics", "file", t.filePath, "error", err) continue diff --git a/server/subsonic/lyrics_test.go b/server/subsonic/lyrics_test.go index 3d9881872..8713b7a3b 100644 --- a/server/subsonic/lyrics_test.go +++ b/server/subsonic/lyrics_test.go @@ -100,8 +100,8 @@ var _ = Describe("GetLyricsBySongId", func() { It("should return mixed lyrics", func() { r := newGetRequest("id=1") - syncedList, _ := model.ParseLyrics(".lrc", "eng", []byte(syncedLyrics)) - unsyncedList, _ := model.ParseLyrics(".lrc", "xxx", []byte(unsyncedLyrics)) + syncedList, _ := model.ParseLyrics(GinkgoT().Context(), ".lrc", "eng", []byte(syncedLyrics)) + unsyncedList, _ := model.ParseLyrics(GinkgoT().Context(), ".lrc", "xxx", []byte(unsyncedLyrics)) synced, _ := syncedList.Main() unsynced, _ := unsyncedList.Main() lyricsJson, err := json.Marshal(model.LyricList{ @@ -158,7 +158,7 @@ var _ = Describe("GetLyricsBySongId", func() { It("should parse lrc metadata", func() { r := newGetRequest("id=1") - syncedList, _ := model.ParseLyrics(".lrc", "eng", []byte(metadata+"\n"+syncedLyrics)) + syncedList, _ := model.ParseLyrics(GinkgoT().Context(), ".lrc", "eng", []byte(metadata+"\n"+syncedLyrics)) synced, _ := syncedList.Main() lyricsJson, err := json.Marshal(model.LyricList{ synced, diff --git a/server/subsonic/media_retrieval_test.go b/server/subsonic/media_retrieval_test.go index 228427d5a..9331dfbe4 100644 --- a/server/subsonic/media_retrieval_test.go +++ b/server/subsonic/media_retrieval_test.go @@ -78,7 +78,7 @@ var _ = Describe("MediaRetrievalController", func() { When("client disconnects (context is cancelled)", func() { It("should not call the service if cancelled before the call", func() { - ctx, cancel := context.WithCancel(context.Background()) + ctx, cancel := context.WithCancel(GinkgoT().Context()) r := newGetRequest("id=34", "size=128", "square=true") r = r.WithContext(ctx) cancel() @@ -93,7 +93,7 @@ var _ = Describe("MediaRetrievalController", func() { }) It("should not return data if cancelled during the call", func() { - ctx, cancel := context.WithCancel(context.Background()) + ctx, cancel := context.WithCancel(GinkgoT().Context()) defer cancel() r := newGetRequest("id=34", "size=128", "square=true") r = r.WithContext(ctx) @@ -113,7 +113,7 @@ var _ = Describe("MediaRetrievalController", func() { Describe("GetLyrics", func() { It("should return data for given artist & title", func() { r := newGetRequest("artist=Rick+Astley", "title=Never+Gonna+Give+You+Up") - lyricsList, _ := model.ParseLyrics(".lrc", "eng", []byte("[00:18.80]We're no strangers to love\n[00:22.80]You know the rules and so do I")) + lyricsList, _ := model.ParseLyrics(GinkgoT().Context(), ".lrc", "eng", []byte("[00:18.80]We're no strangers to love\n[00:22.80]You know the rules and so do I")) lyrics, _ := lyricsList.Main() lyricsJson, err := json.Marshal(model.LyricList{ lyrics,