Randomly playing end of previously played track

mipper

I have repeatedly been seeing (hearing?) some strange behaviour from Strawberry recently. I tend to listen to playlists (both manually created and dynamic) on random play. I often use random albums. The issue I'm experiencing is that every now and again while listening to a track, the end of a previously played track will suddenly get blasted over the currently playing track. Once the errant track finishes, all goes back to normal. It should be noted that this random playing happens while the player is paused as well as while actively listening.

Has anyone else experienced this behaviour? Any tips as to what might be causing it?

Strawberry 1.1.3
Ubuntu Desktop 22.04.5 LTS
Gnome 42.9
X11

mipper

Just some further observations. I've checked the logs in journalctl when this happens and am not seeing any entries.

It is reallllllyyy annoying.

mipper

Doing some more digging. If I list all of the files that Strawberry currently has open I get a lot of stuff that I wouldn't have expected to see. Why is Strawberry holding these files open?

strawberr 7783 cevans   34r      REG              252,1  4867056 20715004 /srv/Music/S/Stone Sour/2010 - Audio Secrecy/16 - Anna [Bonus Track].ogg
strawberr 7783 cevans   45r      REG              252,1  7316768 20711189 /srv/Music/M/Muse/2006 - Black Holes and Revelations/09 - City of Delusion.mp3
strawberr 7783 cevans   82r      REG              252,1  1979266 20716076 /srv/Music/U/The Undertones/1994 - The Very Best Of The Undertones/03 - Get Over You.mp3
strawberr 7783 cevans   83r      REG              252,1  7287330 20583459 /srv/Music/H/Halestorm/2010 - Live in Philly/05 - I'm Not An Angel.ogg
strawberr 7783 cevans   89r      REG              252,1  5039107 20841203 /srv/Music/W/Whitesnake/2011 - Forevermore/08 - Love And Treat Me Right.ogg
strawberr 7783 cevans   90r      REG              252,1  2317616 20710164 /srv/Music/L/Live/2001 - V/04 - Like A Soldier.mp3
strawberr 7783 cevans   92r      REG              252,1  5683432 20581231 /srv/Music/D/Deep Purple/1984 - Perfect Strangers/02 - Under The Gun.ogg
strawberr 7783 cevans   97r      REG              252,1  8963208 20579310 /srv/Music/A/Avenged Sevenfold/2005 - City of Evil/06 - Seize the Day.mp3
strawberr 7783 cevans   98r      REG              252,1  8418372 20584965 /srv/Music/S/Spirit Adrift/2023 - Ghost At The Gallows/05 - Death Won't Stop Me.ogg
strawberr 7783 cevans   99r      REG              252,1  6689072 20582113 /srv/Music/E/Eminem/2009 - Relapse/03 - My Mom.ogg
strawberr 7783 cevans  109r      REG              252,1  6004363 20583176 /srv/Music/H/Hootie & the blowfish/1994 - Cracked Rear View/07 - Drowning.mp3
strawberr 7783 cevans  164r      REG              252,1  4348928 20582989 /srv/Music/G/Genesis/1977 - Seconds Out/03 - Robbery, assault and battery.mp3

Now at least three of these I can remember as being tracks that have started spontaneously playing. While this list was taken, Strawberry had Eminen paused and then, while still paused, played Hootie and the Blowfish for 10 seconds.

The Deep Purple track was last played (on purpose I mean) the previous day.

This may be coincidence, but when I look at the logs, 12 seconds before each track ends it starts queuing up the next track which is kicked off when this log line is output:

Oct  2 10:56:43 sydney org.strawberrymusicplayer.strawberry.desktop[7783]: 10:56:43.862 DEBUG GstEngine:583                    Stream from URL "file:///srv/Music/H/Halestorm/2010 - Live in Philly/05 - I'm Not An Angel.ogg" about to end in 12 seconds. Fuge: 1100 + Gap: 12000

Now I've just checked the Halestorm track the has randomly played a number of times, it always plays the same end section of the track and that section appears to perfectly match that 12 seconds length! Coincidence? (I'll try to confirm this on another song next time it happens.)

mipper

I'm supposed to be working, but this has got under my skin. Just found another possible clue. If we look at the file handles Strawbs has open:

lr-x------ 1 cevans cevans 64 Oct  3 13:18 34 -> /srv/Music/S/Stone Sour/2010 - Audio Secrecy/16 - Anna [Bonus Track].ogg
lr-x------ 1 cevans cevans 64 Oct  2 07:56 92 -> /srv/Music/D/Deep Purple/1984 - Perfect Strangers/02 - Under The Gun.ogg
lr-x------ 1 cevans cevans 64 Oct  1 16:28 89 -> /srv/Music/W/Whitesnake/2011 - Forevermore/08 - Love And Treat Me Right.ogg
lr-x------ 1 cevans cevans 64 Oct  1 13:15 90 -> /srv/Music/L/Live/2001 - V/04 - Like A Soldier.mp3
lr-x------ 1 cevans cevans 64 Oct  1 12:07 83 -> /srv/Music/H/Halestorm/2010 - Live in Philly/05 - I'm Not An Angel.ogg
lr-x------ 1 cevans cevans 64 Oct  1 12:07 82 -> /srv/Music/U/The Undertones/1994 - The Very Best Of The Undertones/03 - Get Over You.mp3
lr-x------ 1 cevans cevans 64 Sep 30 15:58 109 -> /srv/Music/H/Hootie & the blowfish/1994 - Cracked Rear View/07 - Drowning.mp3
lr-x------ 1 cevans cevans 64 Sep 30 15:44 100 -> /srv/Music/B/Black Sabbath/1982 - Live evil/09 - Heaven And Hell.mp3
lr-x------ 1 cevans cevans 64 Sep 30 15:44 97 -> /srv/Music/A/Avenged Sevenfold/2005 - City of Evil/06 - Seize the Day.mp3
lr-x------ 1 cevans cevans 64 Sep 30 15:44 99 -> /srv/Music/T/Talking Heads/1992 - Once in a lifetime- The best of/05 - This Must Be the Place (Naive Melody).mp3
lr-x------ 1 cevans cevans 64 Sep 30 15:44 98 -> /srv/Music/S/Spirit Adrift/2023 - Ghost At The Gallows/05 - Death Won't Stop Me.ogg
lr-x------ 1 cevans cevans 64 Sep 30 15:21 45 -> /srv/Music/M/Muse/2006 - Black Holes and Revelations/09 - City of Delusion.mp3

Live was one of the errant songs - the song that was played straight after it was the Whitesnake one! For Halestorm, the end of which I've heard too many times, was followed directly by The Undertones! Hootie and the Blowfish was immediately followed by Spirit Adrift!

mipper

Now we're really starting to get somewhere. In each of the three cases I've seen we're moving between mp3 & ogg files. It's now four cases as another happened as I was writing this.

Live (mp3) -> Whitesnake (ogg)
Hootie (mp3) -> Spirit Adrift (ogg)
Halestorm (ogg) -> The Undertones (mp3)
Muse (mp3) -> Stone Sour (ogg)

What's happening is that for some, as yet, unknown reason, there's an exception being thrown loading a plugin. When that happens we end up with both the track that's ending and the track that's about to start being left open inside Strawbs. After this the track that was finishing periodically plays the last 10-15 seconds of the track. I can't see an obvious way of attaching the relevant logs so I'll attempt to post examples of them after this pose though it's not ideal.

There's an example of each transition in the logs. I also noticed that Pausing was present in the logs in all cases which I'm guessing is part of the 'dealing with the error' code rather than me happening to have paused playback at just the wrong time, but thought I'd highlight it just in case.

If anyone who knows the code ever gets the chance to look into this, I hope all of the above helps.

mipper

Ogg -> MP3
==========
Oct  2 10:56:43 sydney org.strawberrymusicplayer.strawberry.desktop[7783]: 10:56:43.862 DEBUG GstEngine:583                    Stream from URL "file:///srv/Music/H/Halestorm/2010 - Live in Philly/05 - I'm Not An Angel.ogg" about to end in 12 seconds. Fuge: 1100 + Gap: 12000
Oct  2 10:56:43 sydney org.strawberrymusicplayer.strawberry.desktop[7783]: 10:56:43.931 DEBUG GstEngine:1128                   Got stream info for "file:///srv/Music/U/The%20Undertones/1994%20-%20The%20Very%20Best%20Of%20The%20Undertones/03%20-%20Get%20Over%20You.mp3:" "MPE
G"
Oct  2 10:56:50 sydney org.strawberrymusicplayer.strawberry.desktop[7783]: 10:56:50.885 DEBUG GstEnginePipeline:1387           Stream from URL "file:///srv/Music/H/Halestorm/2010%20-%20Live%20in%20Philly/05%20-%20I'm%20Not%20An%20Angel.ogg" about to finish.
Oct  2 10:56:50 sydney org.strawberrymusicplayer.strawberry.desktop[7783]: 10:56:50.885 DEBUG GstEnginePipeline:2143           Setting next URL to "file:///srv/Music/U/The%20Undertones/1994%20-%20The%20Very%20Best%20Of%20The%20Undertones/03%20-%20Get%20Over%20You.mp3"
Oct  2 10:56:50 sydney org.strawberrymusicplayer.strawberry.desktop[7783]: 10:56:50.893 INFO  GstEnginePipeline:1565           Ignoring error 4535 12 "Your GStreamer installation is missing a plug-in." "../gst/playback/gsturidecodebin.c(1027): no_more_pads_full (): /GstPlay
Bin:pipeline-8-pipeline/GstURIDecodeBin:uridecodebin41:\nno suitable plugins found:\n../gst/playback/gstdecodebin2.c(4701): gst_decode_bin_expose (): /GstPlayBin:pipeline-8-pipeline/GstURIDecodeBin:uridecodebin41/GstDecodeBin:decodebin43:\nno suitable plugins found:\nMissin
g decoder: MPEG-1 Layer 3 (MP3) (audio/mpeg, mpegversion=(int)1, mpegaudioversion=(int)1, layer=(int)3, rate=(int)44100, channels=(int)2, parsed=(boolean)true)\n" when loading next track
Oct  2 10:56:50 sydney org.strawberrymusicplayer.strawberry.desktop[7783]: 10:56:50.906 INFO  GstEnginePipeline:1565           Ignoring error 4535 12 "Your GStreamer installation is missing a plug-in." "../gst/playback/gsturidecodebin.c(1027): no_more_pads_full (): /GstPlay
Bin:pipeline-8-pipeline/GstURIDecodeBin:uridecodebin41:\nno suitable plugins found:\n../gst/playback/gstdecodebin2.c(4701): gst_decode_bin_expose (): /GstPlayBin:pipeline-8-pipeline/GstURIDecodeBin:uridecodebin41/GstDecodeBin:decodebin43:\nno suitable plugins found:\nMissin
g decoder: MPEG-1 Layer 3 (MP3) (audio/mpeg, mpegversion=(int)1, mpegaudioversion=(int)1, layer=(int)3, rate=(int)44100, channels=(int)2, parsed=(boolean)true)\n" when loading next track
Oct  2 10:56:50 sydney org.strawberrymusicplayer.strawberry.desktop[7783]: 10:56:50.906 INFO  GstEnginePipeline:1565           Ignoring error 4534 1 "Internal data stream error." "../libs/gst/base/gstbaseparse.c(3681): gst_base_parse_loop (): /GstPlayBin:pipeline-8-pipeline
/GstURIDecodeBin:uridecodebin41/GstDecodeBin:decodebin43/GstMpegAudioParse:mpegaudioparse160:\nstreaming stopped, reason not-linked (-1)" when loading next track
Oct  2 10:56:50 sydney org.strawberrymusicplayer.strawberry.desktop[7783]: 10:56:50.906 INFO  GstEnginePipeline:1565           Ignoring error 4534 1 "Internal data stream error." "../libs/gst/base/gstbaseparse.c(3681): gst_base_parse_loop (): /GstPlayBin:pipeline-8-pipeline
/GstURIDecodeBin:uridecodebin41/GstDecodeBin:decodebin43/GstMpegAudioParse:mpegaudioparse160:\nstreaming stopped, reason not-linked (-1)" when loading next track
Oct  2 10:56:55 sydney org.strawberrymusicplayer.strawberry.desktop[7783]: 10:56:55.050 DEBUG GstEnginePipeline:181            Pipeline 8 deleted
Oct  2 10:56:55 sydney org.strawberrymusicplayer.strawberry.desktop[7783]: 10:56:55.050 DEBUG MainWindow:1467                  Song changed to "The Undertones" "The Very Best Of The Undertones" "Get Over You"
Oct  2 10:56:55 sydney org.strawberrymusicplayer.strawberry.desktop[7783]: 10:56:55.060 INFO  MoodbarLoader:175                Creating moodbar data for "/srv/Music/U/The Undertones/1994 - The Very Best Of The Undertones/03 - Get Over You.mp3"
Oct  2 10:56:55 sydney org.strawberrymusicplayer.strawberry.desktop[7783]: 10:56:55.061 DEBUG MusixmatchLyricsProvider:273     MusixmatchLyrics: Sending request for QUrl("https://www.musixmatch.com/lyrics/the-undertones/get-over-you")
Oct  2 10:56:55 sydney org.strawberrymusicplayer.strawberry.desktop[7783]: 10:56:55.061 DEBUG HtmlLyricsProvider:75            "songlyrics.com" Sending request for QUrl("https://www.songlyrics.com/the-undertones/get-over-you-lyrics/")
Oct  2 10:56:55 sydney org.strawberrymusicplayer.strawberry.desktop[7783]: 10:56:55.062 DEBUG HtmlLyricsProvider:75            "elyrics.net" Sending request for QUrl("https://www.elyrics.net/read/t/the-undertones-lyrics/get-over-you-lyrics.html")
Oct  2 10:56:55 sydney org.strawberrymusicplayer.strawberry.desktop[7783]: 10:56:55.063 DEBUG HtmlLyricsProvider:75            "azlyrics.com" Sending request for QUrl("https://www.azlyrics.com/lyrics/theundertones/getoveryou.html")
Oct  2 10:56:55 sydney org.strawberrymusicplayer.strawberry.desktop[7783]: 10:56:55.065 DEBUG Player:836                       Playing song "Get Over You" QUrl("file:///srv/Music/U/The Undertones/1994 - The Very Best Of The Undertones/03 - Get Over You.mp3") position 0
Oct  2 10:56:55 sydney org.strawberrymusicplayer.strawberry.desktop[7783]: 10:56:55.065 DEBUG GstEnginePipeline:639            "pulsesink" has volume, enabling volume synchronization.
Oct  2 10:56:55 sydney org.strawberrymusicplayer.strawberry.desktop[7783]: 10:56:55.065 DEBUG GstEnginePipeline:955            Connecting volume notify on 0x56e9141eec80
Oct  2 10:56:55 sydney org.strawberrymusicplayer.strawberry.desktop[7783]: 10:56:55.066 DEBUG GstEnginePipeline:810            Setting buffer duration: 4000000000 low watermark: 0.33 high watermark: 0.99
Oct  2 10:56:55 sydney org.strawberrymusicplayer.strawberry.desktop[7783]: 10:56:55.067 DEBUG GstEnginePipeline:1831           Setting pipeline 9 state to "Paused"
Oct  2 10:56:55 sydney org.strawberrymusicplayer.strawberry.desktop[7783]: 10:56:55.067 DEBUG GstEnginePipeline:1686           Pipeline state changed from "Null" to "Ready"
Oct  2 10:56:55 sydney org.strawberrymusicplayer.strawberry.desktop[7783]: 10:56:55.087 DEBUG GstEnginePipeline:1852           Pipeline 9 state successfully set to "Paused"
Oct  2 10:56:55 sydney org.strawberrymusicplayer.strawberry.desktop[7783]: 10:56:55.105 DEBUG GstEnginePipeline:1767           Buffering started
Oct  2 10:56:55 sydney org.strawberrymusicplayer.strawberry.desktop[7783]: 10:56:55.113 DEBUG CollectionModel:547              Container key for 5163 "Halestorm - I'm Not An Angel" is uchanged, only updating song metadata.
Oct  2 10:56:55 sydney org.strawberrymusicplayer.strawberry.desktop[7783]: 10:56:55.130 DEBUG GstEnginePipeline:1686           Pipeline state changed from "Null" to "Ready"
Oct  2 10:56:55 sydney org.strawberrymusicplayer.strawberry.desktop[7783]: 10:56:55.143 DEBUG CollectionModel:633              Song metadata for 5163 "Halestorm - I'm Not An Angel" changed
Oct  2 10:56:55 sydney org.strawberrymusicplayer.strawberry.desktop[7783]: 10:56:55.194 DEBUG GstEngine:1128                   Got stream info for "file:///srv/Music/U/The%20Undertones/1994%20-%20The%20Very%20Best%20Of%20The%20Undertones/03%20-%20Get%20Over%20You.mp3:" "MPE
G"
Oct  2 10:56:55 sydney org.strawberrymusicplayer.strawberry.desktop[7783]: 10:56:55.235 ERROR ChartLyricsProvider:143          ChartLyrics: "Error transferring http://api.chartlyrics.com/apiv1.asmx/SearchLyricDirect?artist=The Undertones&song=Get Over You - server replied: 
Internal Server Error (401)"
Oct  2 10:56:55 sydney org.strawberrymusicplayer.strawberry.desktop[7783]: 10:56:55.355 INFO  MoodbarLoader:188                Moodbar data generated successfully for "/srv/Music/U/The Undertones/1994 - The Very Best Of The Undertones/03 - Get Over You.mp3"
Oct  2 10:56:55 sydney org.strawberrymusicplayer.strawberry.desktop[7783]: 10:56:55.540 DEBUG HtmlLyricsProvider:114           "azlyrics.com" No lyrics for "The Undertones" "The Very Best Of The Undertones" "Get Over You"
Oct  2 10:56:55 sydney org.strawberrymusicplayer.strawberry.desktop[7783]: 10:56:55.552 DEBUG HtmlLyricsProvider:90            "elyrics.net" No lyrics for "The Undertones" "The Very Best Of The Undertones" "Get Over You"
Oct  2 10:56:55 sydney org.strawberrymusicplayer.strawberry.desktop[7783]: 10:56:55.686 DEBUG GstEnginePipeline:1686           Pipeline state changed from "Ready" to "Paused"
Oct  2 10:56:55 sydney org.strawberrymusicplayer.strawberry.desktop[7783]: 10:56:55.686 DEBUG GstEnginePipeline:1689           Pipeline is active
Oct  2 10:56:55 sydney org.strawberrymusicplayer.strawberry.desktop[7783]: 10:56:55.687 DEBUG GstEnginePipeline:1686           Pipeline state changed from "Ready" to "Paused"
Oct  2 10:56:55 sydney org.strawberrymusicplayer.strawberry.desktop[7783]: 10:56:55.690 DEBUG GstEnginePipeline:1778           Buffering finished
Oct  2 10:56:55 sydney org.strawberrymusicplayer.strawberry.desktop[7783]: 10:56:55.690 DEBUG GstEnginePipeline:1831           Setting pipeline 9 state to "Playing"
Oct  2 10:56:55 sydney org.strawberrymusicplayer.strawberry.desktop[7783]: 10:56:55.690 DEBUG GstEnginePipeline:980            9 event latency
Oct  2 10:56:55 sydney org.strawberrymusicplayer.strawberry.desktop[7783]: 10:56:55.690 DEBUG GstEnginePipeline:1686           Pipeline state changed from "Paused" to "Playing"
Oct  2 10:56:55 sydney org.strawberrymusicplayer.strawberry.desktop[7783]: 10:56:55.691 DEBUG GstEnginePipeline:1686           Pipeline state changed from "Paused" to "Playing"
Oct  2 10:56:56 sydney org.strawberrymusicplayer.strawberry.desktop[7783]: 10:56:56.059 DEBUG PlaylistBackend:339              Saving playlist 1
Oct  2 10:56:56 sydney org.strawberrymusicplayer.strawberry.desktop[7783]: 10:56:56.093 DEBUG LoloLyricsProvider:137           LoloLyrics: No lyrics for "The Undertones" "Get Over You" "Error transferring https://api.lololyrics.com/0.5/getLyric?artist=The Undertones&track=G
et Over You - server replied:  (203)"
Oct  2 10:56:56 sydney org.strawberrymusicplayer.strawberry.desktop[7783]: 10:56:56.502 DEBUG MusixmatchLyricsProvider:438     MusixmatchLyrics: Got lyrics for "The Undertones" "Get Over You"
Oct  2 10:56:56 sydney org.strawberrymusicplayer.strawberry.desktop[7783]: 10:56:56.604 DEBUG HtmlLyricsProvider:119           "songlyrics.com" Got lyrics for "The Undertones" "The Very Best Of The Undertones" "Get Over You"
Oct  2 10:56:57 sydney org.strawberrymusicplayer.strawberry.desktop[7783]: 10:56:57.910 DEBUG LyricsFetcherSearch:136          Using lyrics from "Musixmatch" for "The Undertones" "Get Over You" with score 2

mipper

MP3 -> Ogg

Oct 2 13:05:35 sydney org.strawberrymusicplayer.strawberry.desktop[7783]: 13:05:35.863 DEBUG GstEngine:583 Oct 2 13:05:35 sydney org.strawberrymusicplayer.strawberry.desktop[7783]: 13:05:35.883 DEBUG GstEngine:1128 Oct 2 13:05:42 sydney org.strawberrymusicplayer.strawberry.desktop[7783]: 13:05:42.862 DEBUG GstEnginePipeline:1387 Oct 2 13:05:42 sydney org.strawberrymusicplayer.strawberry.desktop[7783]: 13:05:42.862 DEBUG GstEnginePipeline:2143 Oct 2 13:05:42 sydney org.strawberrymusicplayer.strawberry.desktop[7783]: 13:05:42.866 INFO GstEnginePipeline:1565 Oct 2 13:05:42 sydney org.strawberrymusicplayer.strawberry.desktop[7783]: 13:05:42.991 INFO GstEnginePipeline:1565 Oct 2 13:05:42 sydney org.strawberrymusicplayer.strawberry.desktop[7783]: 13:05:42.991 INFO GstEnginePipeline:1565 Oct 2 13:05:42 sydney org.strawberrymusicplayer.strawberry.desktop[7783]: 13:05:42.992 INFO GstEnginePipeline:1565 Oct 2 13:05:47 sydney org.strawberrymusicplayer.strawberry.desktop[7783]: 13:05:47.160 DEBUG GstEnginePipeline:181 Oct 2 13:05:47 sydney org.strawberrymusicplayer.strawberry.desktop[7783]: 13:05:47.161 DEBUG MainWindow:1467 Oct 2 13:05:47 sydney org.strawberrymusicplayer.strawberry.desktop[7783]: 13:05:47.163 DEBUG MusixmatchLyricsProvider:273 Oct 2 13:05:47 sydney org.strawberrymusicplayer.strawberry.desktop[7783]: 13:05:47.163 DEBUG HtmlLyricsProvider:75 Oct 2 13:05:47 sydney org.strawberrymusicplayer.strawberry.desktop[7783]: 13:05:47.165 DEBUG HtmlLyricsProvider:75 Oct 2 13:05:47 sydney org.strawberrymusicplayer.strawberry.desktop[7783]: 13:05:47.166 DEBUG HtmlLyricsProvider:75 Oct 2 13:05:47 sydney org.strawberrymusicplayer.strawberry.desktop[7783]: 13:05:47.170 INFO MoodbarLoader:175 Oct 2 13:05:47 sydney org.strawberrymusicplayer.strawberry.desktop[7783]: 13:05:47.172 DEBUG Player:836 Oct 2 13:05:47 sydney org.strawberrymusicplayer.strawberry.desktop[7783]: 13:05:47.172 DEBUG GstEnginePipeline:639 Oct 2 13:05:47 sydney org.strawberrymusicplayer.strawberry.desktop[7783]: 13:05:47.172 DEBUG GstEnginePipeline:955 Oct 2 13:05:47 sydney org.strawberrymusicplayer.strawberry.desktop[7783]: 13:05:47.172 DEBUG GstEnginePipeline:810 Oct 2 13:05:47 sydney org.strawberrymusicplayer.strawberry.desktop[7783]: 13:05:47.173 DEBUG GstEnginePipeline:1831 Oct 2 13:05:47 sydney org.strawberrymusicplayer.strawberry.desktop[7783]: 13:05:47.173 DEBUG GstEnginePipeline:1686 Oct 2 13:05:47 sydney org.strawberrymusicplayer.strawberry.desktop[7783]: 13:05:47.182 DEBUG GstEnginePipeline:1852 Oct 2 13:05:47 sydney org.strawberrymusicplayer.strawberry.desktop[7783]: 13:05:47.199 DEBUG GstEnginePipeline:1767 Oct 2 13:05:47 sydney org.strawberrymusicplayer.strawberry.desktop[7783]: 13:05:47.214 DEBUG GstEnginePipeline:1686 Oct 2 13:05:47 sydney org.strawberrymusicplayer.strawberry.desktop[7783]: 13:05:47.218 DEBUG CollectionModel:547 Oct 2 13:05:47 sydney org.strawberrymusicplayer.strawberry.desktop[7783]: 13:05:47.218 DEBUG GstEngine:1128 Oct 2 13:05:47 sydney org.strawberrymusicplayer.strawberry.desktop[7783]: 13:05:47.239 DEBUG CollectionModel:633 Oct 2 13:05:47 sydney org.strawberrymusicplayer.strawberry.desktop[7783]: 13:05:47.363 DEBUG ChartLyricsProvider:134 Oct 2 13:05:47 sydney org.strawberrymusicplayer.strawberry.desktop[7783]: 13:05:47.492 DEBUG GstEnginePipeline:1686 Oct 2 13:05:47 sydney org.strawberrymusicplayer.strawberry.desktop[7783]: 13:05:47.493 DEBUG GstEnginePipeline:1689 Oct 2 13:05:47 sydney org.strawberrymusicplayer.strawberry.desktop[7783]: 13:05:47.493 DEBUG GstEnginePipeline:1686 Oct 2 13:05:47 sydney org.strawberrymusicplayer.strawberry.desktop[7783]: 13:05:47.497 DEBUG OVHLyricsProvider:104 Oct 2 13:05:47 sydney org.strawberrymusicplayer.strawberry.desktop[7783]: 13:05:47.498 DEBUG GstEnginePipeline:1778 Oct 2 13:05:47 sydney org.strawberrymusicplayer.strawberry.desktop[7783]: 13:05:47.498 DEBUG GstEnginePipeline:1831 Oct 2 13:05:47 sydney org.strawberrymusicplayer.strawberry.desktop[7783]: 13:05:47.498 DEBUG GstEnginePipeline:980 Oct 2 13:05:47 sydney org.strawberrymusicplayer.strawberry.desktop[7783]: 13:05:47.499 DEBUG GstEnginePipeline:1686 Oct 2 13:05:47 sydney org.strawberrymusicplayer.strawberry.desktop[7783]: 13:05:47.499 DEBUG GstEnginePipeline:1686 Oct 2 13:05:47 sydney org.strawberrymusicplayer.strawberry.desktop[7783]: 13:05:47.634 DEBUG HtmlLyricsProvider:114 Oct 2 13:05:47 sydney org.strawberrymusicplayer.strawberry.desktop[7783]: 13:05:47.719 INFO MoodbarLoader:188 Oct 2 13:05:47 sydney org.strawberrymusicplayer.strawberry.desktop[7783]: 13:05:47.754 DEBUG HtmlLyricsProvider:119 Oct 2 13:05:47 sydney org.strawberrymusicplayer.strawberry.desktop[7783]: 13:05:47.920 DEBUG LoloLyricsProvider:137 Oct 2 13:05:48 sydney org.strawberrymusicplayer.strawberry.desktop[7783]: 13:05:48.063 DEBUG PlaylistBackend:339 Stream from URL "file:///srv/Music/L/Live/2001 - V/04 - Like A Soldier.mp3" about to end in 12 seconds. Fuge: 1100 + Gap: 12000
Got stream info for "file:///srv/Music/W/Whitesnake/2011%20-%20Forevermore/08%20-%20Love%20And%20Treat%20Me%20Right.ogg:" "Ogg Vorbis"
Stream from URL "file:///srv/Music/L/Live/2001%20-%20V/04%20-%20Like%20A%20Soldier.mp3" about to finish.
Setting next URL to "file:///srv/Music/W/Whitesnake/2011%20-%20Forevermore/08%20-%20Love%20And%20Treat%20Me%20Right.ogg"
Ignoring error 4535 12 "Your GStreamer installation is missing a plug-in." "../gst/playback/gsturidecodebin.c(1027): no_more_pads_full (): /GstPlayBin:pipeline-11-pipeline/GstURIDecodeBin:uridecodebin70:\nno suitable plugins found:\n../gst/playback/gstdecodebin2.c(4701): gst_decode_bin_expose (): /GstPlayBin:pipeline-11-pipeline/GstURIDecodeBin:uridecodebin70/GstDecodeBin:decodebin72:\nno suitable plugins found:\nMissing decoder: Vorbis (audio/x-vorbis, rate=(int)44100, channels=(int)2, streamheader=(buffer)< 01766f72626973000000000244ac0000ffffffffa0800200ffffffffb801, 03766f726269732d000000586970682e4f7267206c6962566f7262697320492032303130313130312028536368617566656e756767657429060000001d0000005449544c453d4c6f766520416e64205472656174204d65205269676874110000004152544953543d5768697465736e616b6511000000414c42554d3d466f72657665726d6f726509000000444154453d323031310e000000545241434b4e554d4245523d30380a00000047454e52453d526f636b01, 05766f7262697329424356010008000000314c20c580d0905500001000006024290e93664929a594a128799894484929a594c53089989489c518638c31c618638c31c618638c20346415000004008028098ea3e6496ace396718278e72a039694e38a720078a51e03909c2f526636ea6b4a66b6ece2925080d590500000200404821851452482185146288218618628821871c72c821a79c720a2aa8a0820a32c820834c32e9a4934e3ae9a8a38e3aea28b4d0420b2db4d24a4c31d55663aebd065d7c73ce39e79c73ce39e79c73ce0942435601002000000442061964104208218514528829a698720a32c880d0905500002000800000000047911449b114cbb11ccdd1244ff22c511335d1334553544d55555555755d577665d77675d7767d5998855bb87d59b8855bd8855df78561188661188661188661f87ddff77ddff77d2034641500200100a0233996e329a2221aa2e239a2038486ac02006400000400200992222992a349a6666aae699bb668abb66dcbb22ccbb20c8486ac0200000100040000000000a0699aa6699aa6699aa6699aa6699aa6699aa6699a66599665599665599665599665599665599665599665599665599665599665599665599665594068c82a0040020040c7711cc77124455224c7722c07080d590500c80000080040522cc57234477334c7733cc7733c477444c9944ccdf44c0f080d59050000020008000000000040311cc5711cc9d1244f522dd3723557733dd7734dd7755d575555555555555555555555555555555555555555555555555555555555555555555581d090550000040000219d66966a800833906120346415008000000018a108430c080d5905000004000088a1e4209ad09af3cd390e9ae5a0a9149bd3c189549b27b9a9989b73ce39e79c6cce19e39c73ce29ca99c5a099d09a73ce490c9aa5a099d09a73ce79129b07ada9d29a73ce19e79c0ec619619c73ce69d29a07a9d9589b73ce59d09ae6a8b9149b73ce89949b27b5b9549b73ce39e79c73ce39e79c73cea95e9ccec139e19c73ce89da9b6bb9095d9c73cef9649ceecd09e19c73ce39e79c73ce39e79c73ce0942435601004000000461d818c69d82207d8e06621421a621931e748f0e93a031c829a41e8d8e464aa98350521927a57482d0905500002000008410524821851452482185145248218618628821a79c720a2aa8a4928a2aca28b3cc32cb2cb3cc32cbacc3ce3aebb0c310430c31b4d24a2c35d556638db5e69e73ae39486ba5b5d65a2ba594524a29a52034641500000200402064904106198514524821869872ca29a7a0820a080d59050000020008000000f024cf111dd1111dd1111dd1111dd1111dcff11c511225511225d1322d53333d55545557766d599775dbb7855dd875dfd77ddfd78d5f1786655996655996655996655996655996650942435601002000000042082184145248218594628c31c79c834e420981d09055000020008000000000477114c7911cc991244bb2244dd22ccdf2344ff334d1134551344d53155dd11575d3166553365dd33565d35565d57665d9b6655bb77d59b67ddff77ddff77ddff77ddff77ddfd7752034641500200100a023399222299222398ee34892048486ac02006400000400a0288ee2388e23499224599226799667899aa9999ee9a9a20a8486ac0200000100040000000000a0688aa7988aa7888ae7888e28899669899aaab9a26ccaaeebbaaeebbaaeebbaaeebbaaeebbaaeebbaaeebbaaeebbaaeebbaaeebbaaeebbaaeebba4068c82a004002004047722447722445522445722407080d590500c800000800c0311c435224c7b22c4df3344ff334d1133dd1333d55744517080d590500000200080000000000c0900c4bb11ccdd12451522dd55235d5522d55543d555555555555555555555555555555555555555555555555555555555555555555d5344dd33481d090950000190000e4a4a6d47a0e126290398941680849c41cc55c3ae99ca35c8c8790234649ed2153cc1004b598d0498514d4e25a6a1d73548b8dad6448412db6c65221e5a8074243560800a119000ec7011c4d031c4b030000000000000049d3004d1401cd1301000000000000c0d13440133d40134500000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000001c4d03345104345104000000000000004d1401d15401d13401000000000000401345c0334540345500000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000001c4d03345104345104000000000000004d14015135014f340100000000000040134540344d40544d000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000010000010e0000011642a1212b028038010087e340922049f034806359f03c781a4c13e058163c0f9a07d30400000000000000000040f234781e3c0fa60990340f9e07cf83690200000000000000000020791e3c0f9e07d304489e07cf83e7c13401000000000000000000f04c13a609d1846a023cd38469c23461aa0000000000000000000000000000000000000000000080000080010700800013ca40a1212b028038010087a348120000389264590000a048926501008065599e0700009265791e0000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000080000080010700800013ca40a1212b018028000087a25816701ccb028e635940922c0b6059004d03781a4014018000008002070080001b342516072834642500100500e07014cbd23451e43896a569a2c8712c4bd3449165699aa68922344bd344119ee779a609cff33cd384288aa2690251344d010000050e00000136684a2c0e5068c84a00202400c0e13896e579a2288aa6699aaaca712ccbf34451144d53555d97e35896e789a2289aa6aaba2ecbd234cf134551344d55755d689ae789a2289aa6aaba2e344d144dd3345555555d179ae689a6699aaaaaaaae0bcf1345d3344d55755dd705a2689aa6a9aaaeebba40144dd33455d5755d1788a2689aa6aabaaeeb02d3344d55555dd795658069aaaaaabaae2c035455555dd7956519a0aaaaeabaae2bcb00d7755dd995655906e0baae2bcbb22c0000e0c0010020c0083ac9a8b2081b4db8f000141ab22200880200008c614a31a50c6312420aa1614c4248216452522a29a50a422a2595524148a5a452324a2da59652052195924aa920a45252290500801d3800801d58088586ac0400f2000008639462cc39e724424a31e69c731221a51873ce39a91463ce39e79c949231e79c734e4ac99873ce3927a564cc39e79c93523ae79c730e4a29a574ce39e7a4945242e89c73524a299d73ce39010040050e000001368a6c4e30125468c84a00201500c0e03896a5699e278aa6694992a6799e279aa6696a92a4699e278aa6699a3ccff34451144d5355799ee789a2289aa6aa725d51144dd3344d5525cba2288aa6a9aaaa0ad3344dd354555585699aa669aaaaebc2b65555555dd77561dbaaaaaaaeebbac0755dd7756519b8aeebbaae2c0b00004f7000002ab061758493a2b1c04243560200190000843108298410520621a4104248298590000080010700800013ca40a1212b018070000080108c31c618638c31368c618c31c618638c31710a638c31c618638c31c618638c31c618638c31c618638c31c618638c31c618638c31c618638c31c618638c31c618638c31c618638c31c618638c31c618638c31c618638c31c618638c31c618638c31c618638c31c618638c31c618638c31c618638c31c618638c31c618638c31c618638c31c6d85a6badb5560018ce85034059848d33ac249d158e06171ab21200080900008c418831e82494924a4a15428c39282595965a8aad42883108a5a4d45a6c3116cf3907a1a4945a8a29b6e239e7a4a4d45a8c31c65a5c0b21a5945
Ignoring error 4535 12 "Your GStreamer installation is missing a plug-in." "../gst/playback/gsturidecodebin.c(1027): no_more_pads_full (): /GstPlayBin:pipeline-11-pipeline/GstURIDecodeBin:uridecodebin70:\nno suitable plugins found:\n../gst/playback/gstdecodebin2.c(4701): gst_decode_bin_expose (): /GstPlayBin:pipeline-11-pipeline/GstURIDecodeBin:uridecodebin70/GstDecodeBin:decodebin72:\nno suitable plugins found:\nMissing decoder: Vorbis (audio/x-vorbis, rate=(int)44100, channels=(int)2, streamheader=(buffer)< 01766f72626973000000000244ac0000ffffffffa0800200ffffffffb801, 03766f726269732d000000586970682e4f7267206c6962566f7262697320492032303130313130312028536368617566656e756767657429060000001d0000005449544c453d4c6f766520416e64205472656174204d65205269676874110000004152544953543d5768697465736e616b6511000000414c42554d3d466f72657665726d6f726509000000444154453d323031310e000000545241434b4e554d4245523d30380a00000047454e52453d526f636b01, 05766f7262697329424356010008000000314c20c580d0905500001000006024290e93664929a594a128799894484929a594c53089989489c518638c31c618638c31c618638c20346415000004008028098ea3e6496ace396718278e72a039694e38a720078a51e03909c2f526636ea6b4a66b6ece2925080d590500000200404821851452482185146288218618628821871c72c821a79c720a2aa8a0820a32c820834c32e9a4934e3ae9a8a38e3aea28b4d0420b2db4d24a4c31d55663aebd065d7c73ce39e79c73ce39e79c73ce0942435601002000000442061964104208218514528829a698720a32c880d0905500002000800000000047911449b114cbb11ccdd1244ff22c511335d1334553544d55555555755d577665d77675d7767d5998855bb87d59b8855bd8855df78561188661188661188661f87ddff77ddff77d2034641500200100a0233996e329a2221aa2e239a2038486ac02006400000400200992222992a349a6666aae699bb668abb66dcbb22ccbb20c8486ac0200000100040000000000a0699aa6699aa6699aa6699aa6699aa6699aa6699a66599665599665599665599665599665599665599665599665599665599665599665599665594068c82a0040020040c7711cc77124455224c7722c07080d590500c80000080040522cc57234477334c7733cc7733c477444c9944ccdf44c0f080d59050000020008000000000040311cc5711cc9d1244f522dd3723557733dd7734dd7755d575555555555555555555555555555555555555555555555555555555555555555555581d090550000040000219d66966a800833906120346415008000000018a108430c080d5905000004000088a1e4209ad09af3cd390e9ae5a0a9149bd3c189549b27b9a9989b73ce39e79c6cce19e39c73ce29ca99c5a099d09a73ce490c9aa5a099d09a73ce79129b07ada9d29a73ce19e79c0ec619619c73ce69d29a07a9d9589b73ce59d09ae6a8b9149b73ce89949b27b5b9549b73ce39e79c73ce39e79c73cea95e9ccec139e19c73ce89da9b6bb9095d9c73cef9649ceecd09e19c73ce39e79c73ce39e79c73ce0942435601004000000461d818c69d82207d8e06621421a621931e748f0e93a031c829a41e8d8e464aa98350521927a57482d0905500002000008410524821851452482185145248218618628821a79c720a2aa8a4928a2aca28b3cc32cb2cb3cc32cbacc3ce3aebb0c310430c31b4d24a2c35d556638db5e69e73ae39486ba5b5d65a2ba594524a29a52034641500000200402064904106198514524821869872ca29a7a0820a080d59050000020008000000f024cf111dd1111dd1111dd1111dd1111dcff11c511225511225d1322d53333d55545557766d599775dbb7855dd875dfd77ddfd78d5f1786655996655996655996655996655996650942435601002000000042082184145248218594628c31c79c834e420981d09055000020008000000000477114c7911cc991244bb2244dd22ccdf2344ff334d1134551344d53155dd11575d3166553365dd33565d35565d57665d9b6655bb77d59b67ddff77ddff77ddff77ddff77ddfd7752034641500200100a023399222299222398ee34892048486ac02006400000400a0288ee2388e23499224599226799667899aa9999ee9a9a20a8486ac0200000100040000000000a0688aa7988aa7888ae7888e28899669899aaab9a26ccaaeebbaaeebbaaeebbaaeebbaaeebbaaeebbaaeebbaaeebbaaeebbaaeebbaaeebbaaeebba4068c82a004002004047722447722445522445722407080d590500c800000800c0311c435224c7b22c4df3344ff334d1133dd1333d55744517080d590500000200080000000000c0900c4bb11ccdd12451522dd55235d5522d55543d555555555555555555555555555555555555555555555555555555555555555555d5344dd33481d090950000190000e4a4a6d47a0e126290398941680849c41cc55c3ae99ca35c8c8790234649ed2153cc1004b598d0498514d4e25a6a1d73548b8dad6448412db6c65221e5a8074243560800a119000ec7011c4d031c4b030000000000000049d3004d1401cd1301000000000000c0d13440133d40134500000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000001c4d03345104345104000000000000004d1401d15401d13401000000000000401345c0334540345500000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000001c4d03345104345104000000000000004d14015135014f340100000000000040134540344d40544d000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000010000010e0000011642a1212b028038010087e340922049f034806359f03c781a4c13e058163c0f9a07d30400000000000000000040f234781e3c0fa60990340f9e07cf83690200000000000000000020791e3c0f9e07d304489e07cf83e7c13401000000000000000000f04c13a609d1846a023cd38469c23461aa0000000000000000000000000000000000000000000080000080010700800013ca40a1212b028038010087a348120000389264590000a048926501008065599e0700009265791e0000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000080000080010700800013ca40a1212b018028000087a25816701ccb028e635940922c0b6059004d03781a4014018000008002070080001b342516072834642500100500e07014cbd23451e43896a569a2c8712c4bd3449165699aa68922344bd344119ee779a609cff33cd384288aa2690251344d010000050e00000136684a2c0e5068c84a00202400c0e13896e579a2288aa6699aaaca712ccbf34451144d53555d97e35896e789a2289aa6aaba2ecbd234cf134551344d55755d689ae789a2289aa6aaba2e344d144dd3345555555d179ae689a6699aaaaaaaae0bcf1345d3344d55755dd705a2689aa6a9aaaeebba40144dd33455d5755d1788a2689aa6aabaaeeb02d3344d55555dd795658069aaaaaabaae2c035455555dd7956519a0aaaaeabaae2bcb00d7755dd995655906e0baae2bcbb22c0000e0c0010020c0083ac9a8b2081b4db8f000141ab22200880200008c614a31a50c6312420aa1614c4248216452522a29a50a422a2595524148a5a452324a2da59652052195924aa920a45252290500801d3800801d58088586ac0400f2000008639462cc39e724424a31e69c731221a51873ce39a91463ce39e79c949231e79c734e4ac99873ce3927a564cc39e79c93523ae79c730e4a29a574ce39e7a4945242e89c73524a299d73ce39010040050e000001368a6c4e30125468c84a00201500c0e03896a5699e278aa6694992a6799e279aa6696a92a4699e278aa6699a3ccff34451144d5355799ee789a2289aa6aa725d51144dd3344d5525cba2288aa6a9aaaa0ad3344dd354555585699aa669aaaaebc2b65555555dd77561dbaaaaaaaeebbac0755dd7756519b8aeebbaae2c0b00004f7000002ab061758493a2b1c04243560200190000843108298410520621a4104248298590000080010700800013ca40a1212b018070000080108c31c618638c31368c618c31c618638c31710a638c31c618638c31c618638c31c618638c31c618638c31c618638c31c618638c31c618638c31c618638c31c618638c31c618638c31c618638c31c618638c31c618638c31c618638c31c618638c31c618638c31c618638c31c618638c31c618638c31c618638c31c618638c31c618638c31c6d85a6badb5560018ce85034059848d33ac249d158e06171ab21200080900008c418831e82494924a4a15428c39282595965a8aad42883108a5a4d45a6c3116cf3907a1a4945a8a29b6e239e7a4a4d45a8c31c65a5c0b21a5945
Ignoring error 4534 1 "Internal data stream error." "../ext/ogg/gstoggdemux.c(5013): gst_ogg_demux_loop (): /GstPlayBin:pipeline-11-pipeline/GstURIDecodeBin:uridecodebin70/GstDecodeBin:decodebin72/GstOggDemux:oggdemux86:\nstreaming stopped, reason not-linked (-1)" when loading next track
Ignoring error 4534 1 "Internal data stream error." "../ext/ogg/gstoggdemux.c(5013): gst_ogg_demux_loop (): /GstPlayBin:pipeline-11-pipeline/GstURIDecodeBin:uridecodebin70/GstDecodeBin:decodebin72/GstOggDemux:oggdemux86:\nstreaming stopped, reason not-linked (-1)" when loading next track
Pipeline 11 deleted
Song changed to "Whitesnake" "Forevermore" "Love And Treat Me Right"
MusixmatchLyrics: Sending request for QUrl("https://www.musixmatch.com/lyrics/whitesnake/love-and-treat-me-right")
"songlyrics.com" Sending request for QUrl("https://www.songlyrics.com/whitesnake/love-and-treat-me-right-lyrics/")
"elyrics.net" Sending request for QUrl("https://www.elyrics.net/read/w/whitesnake-lyrics/love-and-treat-me-right-lyrics.html")
"azlyrics.com" Sending request for QUrl("https://www.azlyrics.com/lyrics/whitesnake/loveandtreatmeright.html")
Creating moodbar data for "/srv/Music/W/Whitesnake/2011 - Forevermore/08 - Love And Treat Me Right.ogg"
Playing song "Love And Treat Me Right" QUrl("file:///srv/Music/W/Whitesnake/2011 - Forevermore/08 - Love And Treat Me Right.ogg") position 0
"pulsesink" has volume, enabling volume synchronization.
Connecting volume notify on 0x56e914783300
Setting buffer duration: 4000000000 low watermark: 0.33 high watermark: 0.99
Setting pipeline 12 state to "Paused"
Pipeline state changed from "Null" to "Ready"
Pipeline 12 state successfully set to "Paused"
Buffering started
Pipeline state changed from "Null" to "Ready"
Container key for 4549 "Live - Like A Soldier" is uchanged, only updating song metadata.
Got stream info for "file:///srv/Music/W/Whitesnake/2011%20-%20Forevermore/08%20-%20Love%20And%20Treat%20Me%20Right.ogg:" "Ogg Vorbis"
Song metadata for 4549 "Live - Like A Soldier" changed
ChartLyrics: Got lyrics for "Whitesnake" "Love And Treat Me Right"
Pipeline state changed from "Ready" to "Paused"
Pipeline is active
Pipeline state changed from "Ready" to "Paused"
OVHLyrics: Got lyrics for "Whitesnake" "Love And Treat Me Right"
Buffering finished
Setting pipeline 12 state to "Playing"
12 event latency
Pipeline state changed from "Paused" to "Playing"
Pipeline state changed from "Paused" to "Playing"
"azlyrics.com" No lyrics for "Whitesnake" "Forevermore" "Love And Treat Me Right"
Moodbar data generated successfully for "/srv/Music/W/Whitesnake/2011 - Forevermore/08 - Love And Treat Me Right.ogg"
"elyrics.net" Got lyrics for "Whitesnake" "Forevermore" "Love And Treat Me Right"
LoloLyrics: No lyrics for "Whitesnake" "Love And Treat Me Right" "Error transferring https://api.lololyrics.com/0.5/getLyric?artist=Whitesnake&track=Love And Treat Me Right - server replied: (203)"
Saving playlist 1

jonas

@mipper
What settings do you have for the fading options in Settings / Backend?

mipper

@jonas Screenshot from 2024-10-04 07-59-35.png

jonas

@mipper
Maybe it's happening only when switching between MP3 and Ogg Vorbis songs, I'll try to reproduce it.

jonas

I could not reproduce this.
Maye this is the same bug as https://github.com/strawberrymusicplayer/strawberry/issues/1535?

mipper

@jonas I don't think it's the same as the linked bug. This issue occurs some time after the song ended. It also repeats over time; the same song ending can be played multiple times with a fair amount of time passing between them, and indeed other songs chipping in in between.

It looks like the idea of swapping between mp3/ogg may have been a red herring. I've had an example this today which involved only mp3 files.

Oct  7 09:29:10 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 09:29:10.723 DEBUG GstEngine:583                    Stream from URL "file:///srv/Music/T/Temple Of The Dog/1991 - Temple Of The Dog/09 - Four Walled World.mp3" about to end in 12 seconds. Fuge: 1100 + Gap: 12000
Oct  7 09:29:10 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 09:29:10.740 DEBUG GstEngine:1128                   Got stream info for "file:///srv/Music/L/lostprophets/2012%20-%20Weapons/10%20-%20Can't%20Get%20Enough.mp3:" "MPEG"
Oct  7 09:29:18 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 09:29:18.252 DEBUG GstEnginePipeline:1387           Stream from URL "file:///srv/Music/T/Temple%20Of%20The%20Dog/1991%20-%20Temple%20Of%20The%20Dog/09%20-%20Four%20Walled%20World.mp3" about to finish.
Oct  7 09:29:18 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 09:29:18.252 DEBUG GstEnginePipeline:2143           Setting next URL to "file:///srv/Music/L/lostprophets/2012%20-%20Weapons/10%20-%20Can't%20Get%20Enough.mp3"
Oct  7 09:29:18 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 09:29:18.274 INFO  GstEnginePipeline:1565           Ignoring error 4536 12 "Your GStreamer installation is missing a plug-in." "../gst/playback/gsturidecodebin.c(1027): no_more_pads_full (): /GstPlayBin:pipeline-2-pipeline/GstURIDecodeBin:uridecodebin11:\nno suitable plugins found:\n../gst/playback/gstdecodebin2.c(4701): gst_decode_bin_expose (): /GstPlayBin:pipeline-2-pipeline/GstURIDecodeBin:uridecodebin11/GstDecodeBin:decodebin13:\nno suitable plugins found:\nMissing decoder: MPEG-1 Layer 3 (MP3) (audio/mpeg, mpegversion=(int)1, mpegaudioversion=(int)1, layer=(int)3, rate=(int)44100, channels=(int)2, parsed=(boolean)true)\n" when loading next track
Oct  7 09:29:18 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 09:29:18.359 INFO  GstEnginePipeline:1565           Ignoring error 4536 12 "Your GStreamer installation is missing a plug-in." "../gst/playback/gsturidecodebin.c(1027): no_more_pads_full (): /GstPlayBin:pipeline-2-pipeline/GstURIDecodeBin:uridecodebin11:\nno suitable plugins found:\n../gst/playback/gstdecodebin2.c(4701): gst_decode_bin_expose (): /GstPlayBin:pipeline-2-pipeline/GstURIDecodeBin:uridecodebin11/GstDecodeBin:decodebin13:\nno suitable plugins found:\nMissing decoder: MPEG-1 Layer 3 (MP3) (audio/mpeg, mpegversion=(int)1, mpegaudioversion=(int)1, layer=(int)3, rate=(int)44100, channels=(int)2, parsed=(boolean)true)\n" when loading next track
Oct  7 09:29:18 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 09:29:18.359 INFO  GstEnginePipeline:1565           Ignoring error 4535 1 "Internal data stream error." "../libs/gst/base/gstbaseparse.c(3681): gst_base_parse_loop (): /GstPlayBin:pipeline-2-pipeline/GstURIDecodeBin:uridecodebin11/GstDecodeBin:decodebin13/GstMpegAudioParse:mpegaudioparse167:\nstreaming stopped, reason not-linked (-1)" when loading next track
Oct  7 09:29:18 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 09:29:18.360 INFO  GstEnginePipeline:1565           Ignoring error 4535 1 "Internal data stream error." "../libs/gst/base/gstbaseparse.c(3681): gst_base_parse_loop (): /GstPlayBin:pipeline-2-pipeline/GstURIDecodeBin:uridecodebin11/GstDecodeBin:decodebin13/GstMpegAudioParse:mpegaudioparse167:\nstreaming stopped, reason not-linked (-1)" when loading next track
Oct  7 09:29:22 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 09:29:22.527 DEBUG GstEnginePipeline:181            Pipeline 2 deleted
Oct  7 09:29:22 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 09:29:22.527 DEBUG MainWindow:1467                  Song changed to "lostprophets" "Weapons" "Can't Get Enough"
Oct  7 09:29:22 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 09:29:22.537 INFO  MoodbarLoader:175                Creating moodbar data for "/srv/Music/L/lostprophets/2012 - Weapons/10 - Can't Get Enough.mp3"
Oct  7 09:29:22 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 09:29:22.537 DEBUG HtmlLyricsProvider:75            "songlyrics.com" Sending request for QUrl("https://www.songlyrics.com/lostprophets/can-t-get-enough-lyrics/")
Oct  7 09:29:22 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 09:29:22.539 DEBUG Player:836                       Playing song "Can't Get Enough" QUrl("file:///srv/Music/L/lostprophets/2012 - Weapons/10 - Can't Get Enough.mp3") position 0
Oct  7 09:29:22 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 09:29:22.539 DEBUG GstEnginePipeline:639            "pulsesink" has volume, enabling volume synchronization.
Oct  7 09:29:22 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 09:29:22.539 DEBUG GstEnginePipeline:955            Connecting volume notify on 0x5e2eaafec7b0
Oct  7 09:29:22 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 09:29:22.539 DEBUG GstEnginePipeline:810            Setting buffer duration: 4000000000 low watermark: 0.33 high watermark: 0.99
Oct  7 09:29:22 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 09:29:22.539 DEBUG GstEnginePipeline:1831           Setting pipeline 3 state to "Paused"
Oct  7 09:29:22 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 09:29:22.539 DEBUG GstEnginePipeline:1686           Pipeline state changed from "Null" to "Ready"
Oct  7 09:29:22 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 09:29:22.545 DEBUG GstEnginePipeline:1852           Pipeline 3 state successfully set to "Paused"
Oct  7 09:29:22 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 09:29:22.558 DEBUG GstEnginePipeline:1686           Pipeline state changed from "Null" to "Ready"
Oct  7 09:29:22 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 09:29:22.567 DEBUG GstEnginePipeline:1767           Buffering started
Oct  7 09:29:22 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 09:29:22.577 DEBUG CollectionModel:547              Container key for 465 "Temple Of The Dog - Four Walled World" is uchanged, only updating song metadata.
Oct  7 09:29:22 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 09:29:22.578 DEBUG GstEngine:1128                   Got stream info for "file:///srv/Music/L/lostprophets/2012%20-%20Weapons/10%20-%20Can't%20Get%20Enough.mp3:" "MPEG"
Oct  7 09:29:22 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 09:29:22.598 DEBUG GstEnginePipeline:1686           Pipeline state changed from "Ready" to "Paused"
Oct  7 09:29:22 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 09:29:22.598 DEBUG GstEnginePipeline:1689           Pipeline is active
Oct  7 09:29:22 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 09:29:22.598 DEBUG CollectionModel:633              Song metadata for 465 "Temple Of The Dog - Four Walled World" changed
Oct  7 09:29:22 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 09:29:22.602 DEBUG GstEnginePipeline:1686           Pipeline state changed from "Ready" to "Paused"
Oct  7 09:29:22 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 09:29:22.605 DEBUG GstEnginePipeline:1778           Buffering finished
Oct  7 09:29:22 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 09:29:22.605 DEBUG GstEnginePipeline:1831           Setting pipeline 3 state to "Playing"
Oct  7 09:29:22 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 09:29:22.605 DEBUG GstEnginePipeline:980            3 event latency
Oct  7 09:29:22 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 09:29:22.605 DEBUG GstEnginePipeline:1686           Pipeline state changed from "Paused" to "Playing"
Oct  7 09:29:22 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 09:29:22.606 DEBUG GstEnginePipeline:1686           Pipeline state changed from "Paused" to "Playing"
Oct  7 09:29:23 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 09:29:23.065 INFO  MoodbarLoader:188                Moodbar data generated successfully for "/srv/Music/L/lostprophets/2012 - Weapons/10 - Can't Get Enough.mp3"
Oct  7 09:29:23 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 09:29:23.423 DEBUG PlaylistBackend:339              Saving playlist 1
Oct  7 09:29:23 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 09:29:23.522 DEBUG HtmlLyricsProvider:119           "songlyrics.com" Got lyrics for "lostprophets" "Weapons" "Can't Get Enough"
Oct  7 09:29:23 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 09:29:23.522 DEBUG LyricsFetcherSearch:136          Using lyrics from "songlyrics.com" for "lostprophets" "Can't Get Enough" with score -0.5
Oct  7 09:29:43 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 09:29:43.864 DEBUG GstEnginePipeline:1831           Setting pipeline 3 state to "Paused"
Oct  7 09:29:43 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 09:29:43.865 DEBUG GstEnginePipeline:1686           Pipeline state changed from "Playing" to "Paused"
Oct  7 09:29:43 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 09:29:43.870 DEBUG GstEnginePipeline:1852           Pipeline 3 state successfully set to "Paused"
Oct  7 09:29:43 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 09:29:43.872 DEBUG GstEnginePipeline:1686           Pipeline state changed from "Playing" to "Paused"
Oct  7 09:57:57 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 09:57:57.293 DEBUG GstEnginePipeline:1831           Setting pipeline 3 state to "Playing"
Oct  7 09:57:57 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 09:57:57.294 DEBUG GstEnginePipeline:980            3 event latency
Oct  7 09:57:57 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 09:57:57.295 DEBUG GstEnginePipeline:1686           Pipeline state changed from "Paused" to "Playing"
Oct  7 09:57:57 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 09:57:57.298 DEBUG GstEnginePipeline:1852           Pipeline 3 state successfully set to "Playing"
Oct  7 09:57:57 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 09:57:57.300 DEBUG GstEnginePipeline:1686           Pipeline state changed from "Paused" to "Playing"
Oct  7 10:02:25 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 10:02:25.223 DEBUG GstEngine:583                    Stream from URL "file:///srv/Music/L/lostprophets/2012 - Weapons/10 - Can't Get Enough.mp3" about to end in 12 seconds. Fuge: 1100 + Gap: 120

But I have a new theory. I believe the example above occurred when I restarted playback this morning. Temple of the Dog was playing as I put my machine to sleep on Friday night with playback paused. This morning when I restarted we saw the issue. My theory now is the exception we're seeing is somehow connected to periods where the player is unpaused after being paused for some kind of extended period.

mipper

I'm almost sure being on pause for an extended period is causing this. I have just come back from lunch and restarted playback. Boom! Got the missing plugin error and it's left the file that was playing and the next file open. I paused the track at 12:14:13 and restarted at 12:51:11 so around 36 minutes between those two events.

Now, if I remember correctly, when I restarted playback I also reset the song back to the begining. In fact, looking at the logs, I may have paused the track again shortly after resetting it. Can't be sure but maybe you can tell from the logs:

Oct  7 12:14:13 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 12:14:13.465 DEBUG GstEnginePipeline:1852           Pipeline 3 state successfully set to "Paused"
Oct  7 12:14:13 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 12:14:13.467 DEBUG GstEnginePipeline:1686           Pipeline state changed from "Playing" to "Paused"
Oct  7 12:51:11 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 12:51:11.587 DEBUG GstEnginePipeline:1831           Setting pipeline 3 state to "Playing"
Oct  7 12:51:11 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 12:51:11.589 DEBUG GstEnginePipeline:980            3 event latency
Oct  7 12:51:11 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 12:51:11.589 DEBUG GstEnginePipeline:1686           Pipeline state changed from "Paused" to "Playing"
Oct  7 12:51:11 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 12:51:11.594 DEBUG GstEnginePipeline:1852           Pipeline 3 state successfully set to "Playing"
Oct  7 12:51:11 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 12:51:11.595 DEBUG GstEnginePipeline:1686           Pipeline state changed from "Paused" to "Playing"
Oct  7 12:51:13 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 12:51:13.980 DEBUG MainWindow:1467                  Song changed to "Trust" "Trust IV" "Par Compromission"
Oct  7 12:51:13 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 12:51:13.981 INFO  MoodbarLoader:139                Loading cached moodbar data for "/srv/Music/T/Trust/1983 - Trust IV/01 - Par Compromission.mp3"
Oct  7 12:51:13 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 12:51:13.981 DEBUG Player:836                       Playing song "Par Compromission" QUrl("file:///srv/Music/T/Trust/1983 - Trust IV/01 - Par Compromission.mp3") position 0
Oct  7 12:51:13 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 12:51:13.990 DEBUG GstEnginePipeline:639            "pulsesink" has volume, enabling volume synchronization.
Oct  7 12:51:13 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 12:51:13.990 DEBUG GstEnginePipeline:955            Connecting volume notify on 0x5e2eaba9ff30
Oct  7 12:51:13 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 12:51:13.991 DEBUG GstEnginePipeline:810            Setting buffer duration: 4000000000 low watermark: 0.33 high watermark: 0.99
Oct  7 12:51:13 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 12:51:13.992 DEBUG GstEnginePipeline:388            Finishing pipeline 3
Oct  7 12:51:13 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 12:51:13.992 DEBUG GstEnginePipeline:1831           Setting pipeline 3 state to "Null"
Oct  7 12:51:13 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 12:51:13.993 DEBUG GstEnginePipeline:1831           Setting pipeline 4 state to "Paused"
Oct  7 12:51:13 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 12:51:13.994 DEBUG GstEnginePipeline:1686           Pipeline state changed from "Null" to "Ready"
Oct  7 12:51:13 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 12:51:13.997 DEBUG GstEnginePipeline:1852           Pipeline 4 state successfully set to "Paused"
Oct  7 12:51:14 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 12:51:14.013 DEBUG GstEnginePipeline:1852           Pipeline 3 state successfully set to "Null"
Oct  7 12:51:14 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 12:51:14.013 DEBUG GstEngine:961                    Pipeline 3 finished
Oct  7 12:51:14 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 12:51:14.014 DEBUG GstEnginePipeline:181            Pipeline 3 deleted
Oct  7 12:51:14 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 12:51:14.014 DEBUG GstEngine:986                    1 pipelines are active
Oct  7 12:51:14 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 12:51:14.021 DEBUG GstEnginePipeline:1686           Pipeline state changed from "Null" to "Ready"
Oct  7 12:51:14 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 12:51:14.025 DEBUG GstEnginePipeline:1767           Buffering started
Oct  7 12:51:14 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 12:51:14.072 DEBUG GstEngine:1128                   Got stream info for "file:///srv/Music/T/Trust/1983%20-%20Trust%20IV/01%20-%20Par%20Compromission.mp3:" "MPEG"
Oct  7 12:51:14 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 12:51:14.073 DEBUG CollectionModel:547              Container key for 601 "Trust - Par Compromission" is uchanged, only updating song metadata.
Oct  7 12:51:14 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 12:51:14.076 DEBUG GstEnginePipeline:1686           Pipeline state changed from "Ready" to "Paused"
Oct  7 12:51:14 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 12:51:14.076 DEBUG GstEnginePipeline:1689           Pipeline is active
Oct  7 12:51:14 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 12:51:14.080 DEBUG GstEnginePipeline:1686           Pipeline state changed from "Ready" to "Paused"
Oct  7 12:51:14 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 12:51:14.082 DEBUG GstEnginePipeline:1778           Buffering finished
Oct  7 12:51:14 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 12:51:14.082 DEBUG GstEnginePipeline:1831           Setting pipeline 4 state to "Playing"
Oct  7 12:51:14 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 12:51:14.082 DEBUG GstEnginePipeline:980            4 event latency
Oct  7 12:51:14 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 12:51:14.082 DEBUG GstEnginePipeline:1686           Pipeline state changed from "Paused" to "Playing"
Oct  7 12:51:14 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 12:51:14.082 DEBUG GstEnginePipeline:1686           Pipeline state changed from "Paused" to "Playing"
Oct  7 12:51:14 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 12:51:14.094 DEBUG CollectionModel:633              Song metadata for 601 "Trust - Par Compromission" changed
Oct  7 12:51:14 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 12:51:14.923 DEBUG PlaylistBackend:339              Saving playlist 1
Oct  7 12:52:30 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 12:52:30.650 DEBUG GstEnginePipeline:1831           Setting pipeline 4 state to "Paused"
Oct  7 12:52:30 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 12:52:30.651 DEBUG GstEnginePipeline:1686           Pipeline state changed from "Playing" to "Paused"
Oct  7 12:52:30 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 12:52:30.653 DEBUG GstEnginePipeline:1852           Pipeline 4 state successfully set to "Paused"
Oct  7 12:52:30 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 12:52:30.653 DEBUG GstEnginePipeline:1686           Pipeline state changed from "Playing" to "Paused"
Oct  7 13:09:30 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 13:09:30.467 DEBUG GstEnginePipeline:1831           Setting pipeline 4 state to "Playing"
Oct  7 13:09:30 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 13:09:30.478 DEBUG GstEnginePipeline:980            4 event latency
Oct  7 13:09:30 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 13:09:30.478 DEBUG GstEnginePipeline:1686           Pipeline state changed from "Paused" to "Playing"
Oct  7 13:09:30 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 13:09:30.478 DEBUG GstEnginePipeline:1852           Pipeline 4 state successfully set to "Playing"
Oct  7 13:09:30 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 13:09:30.478 DEBUG GstEnginePipeline:1686           Pipeline state changed from "Paused" to "Playing"
Oct  7 13:09:54 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 13:09:54.172 DEBUG GstEnginePipeline:1831           Setting pipeline 4 state to "Paused"
Oct  7 13:09:54 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 13:09:54.173 DEBUG GstEnginePipeline:1686           Pipeline state changed from "Playing" to "Paused"
Oct  7 13:09:54 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 13:09:54.178 DEBUG GstEnginePipeline:1852           Pipeline 4 state successfully set to "Paused"
Oct  7 13:09:54 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 13:09:54.181 DEBUG GstEnginePipeline:1686           Pipeline state changed from "Playing" to "Paused"
Oct  7 13:10:18 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 13:10:18.808 DEBUG GstEnginePipeline:1831           Setting pipeline 4 state to "Playing"
Oct  7 13:10:18 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 13:10:18.809 DEBUG GstEnginePipeline:980            4 event latency
Oct  7 13:10:18 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 13:10:18.809 DEBUG GstEnginePipeline:1686           Pipeline state changed from "Paused" to "Playing"
Oct  7 13:10:18 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 13:10:18.813 DEBUG GstEnginePipeline:1852           Pipeline 4 state successfully set to "Playing"
Oct  7 13:10:18 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 13:10:18.816 DEBUG GstEnginePipeline:1686           Pipeline state changed from "Paused" to "Playing"
Oct  7 13:12:44 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 13:12:44.723 DEBUG GstEngine:583                    Stream from URL "file:///srv/Music/T/Trust/1983 - Trust IV/01 - Par Compromission.mp3" about to end in 12 seconds. Fuge: 1100 + Gap: 12000
Oct  7 13:12:44 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 13:12:44.747 DEBUG GstEngine:1128                   Got stream info for "file:///srv/Music/M/Metallica/2023%20-%2072%20Seasons/11%20-%20Room%20of%20Mirrors.ogg:" "Ogg Vorbis"
Oct  7 13:12:51 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 13:12:51.680 DEBUG GstEnginePipeline:1387           Stream from URL "file:///srv/Music/T/Trust/1983%20-%20Trust%20IV/01%20-%20Par%20Compromission.mp3" about to finish.
Oct  7 13:12:51 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 13:12:51.680 DEBUG GstEnginePipeline:2143           Setting next URL to "file:///srv/Music/M/Metallica/2023%20-%2072%20Seasons/11%20-%20Room%20of%20Mirrors.ogg"
Oct  7 13:12:51 sydney org.strawberrymusicplayer.strawberry.desktop[670555]: 13:12:51.754 INFO  GstEnginePipeline:1565           Ignoring error 4536 12 "Your GStreamer installation is missing a plug-in." "../gst/playback/gsturidecodebin.c(1027): no_more_pads_full (): /GstPlayBin:pipeline-4-pipeline/GstURIDecodeBin:uridecodebin56:\nno suitable plugins found:\n../gst/playback/gstdecodebin2.c(4701): gst_decode_bin_expose (): /GstPlayBin:pipeline-4-pipeline/GstURIDecodeBin:uridecodebin56/GstDecodeBin:decodebin58:\nno suitable plugins found:\nMissing decoder: Vorbis (audio/x-vorbis, rate=(int)44100, channels=(int)2, streamheader=(buffer)< 01766f72626973000000000244ac00000000000000e8030000000000b801, 03766f7262697334000000586970682e4f7267206c6962566f72626973204920323032303037303420285265647563

I'm trying to reproduce the issue by pausing a track for 30 minutes. Will let you know if I succeed.

mipper

Well I'm struggling to get a repeatable process, I can confirm it continues to happen but I haven't identified the cause. The only common thing is the no suitable plugin error. Something about how that gets handled is leaving the two files open. I'll keep trying to reproduce it.

jonas

@mipper

I've set up pipewire and set output to PulseAudio, tested playing for many hours a playlist on repeat containing MP3 and MP4 files, I still can't reproduce this, I've checked that no more than 1 file is open at a time.

If cross fading is disabled, it's hard to understand why several files are kept open at the same time.

jonas

Do you have any of the features replay gain, ebur128 or bs2b enabled in the backend settings?

mipper

@jonas Apologies. I didn't get any notification that you'd asked other questions so didn't see this until now. Looking at your conversation in #1582 it sounds promising that you may have tracked it down with brilliant help from jirislaby (Kudos, jirislaby. This has been driving me nuts! )

If I see any further issues after upgrading to a release with the fix in I'll let you know.

Many thanks to you both.

jonas

@mipper

The issue with Strawberry leaving open pipelines which leads to open files should be fixed in version 1.2.1. However the new version won't work on Ubuntu 22.04 as Strawberry now requires a newer Qt version than is available on that Ubuntu version, consider upgrading to Ubuntu 24.04 (Noble).

The "Your GStreamer installation is missing a plug-in" error could be a GStreamer bug, maybe a newer GStreamer version solves that.