Soft crashes in Manjaro KDE Wayland: Songs re-start playing a few seconds in or skip on their own
-
I constantly have issues with Strawberry (1.0.22) on Manjaro KDE Wayland.
Many times when a song starts about 10-20 seconds into the song the song starts playing from the beginning. Sometimes there are perfectly fine songs (in other media players) that 'crash' midway through playing (meaning Strawberry skips to the next song midway). I'm pasting below the log when this happened. This is happening in both my desktop and my laptop, both running Manjaro KDE Wayland and Strawberry 1.0.22 installed through Flatpak.
17:54:18.591 INFO main:184 Strawberry 1.0.22 Qt "6.6.1" 17:54:18.592 INFO main:185 "KDE Flatpak runtime 6.6 - (linux 6.6.7-4-MANJARO) [x86_64]" 17:54:18.844 INFO main:47 TagReader worker connecting to "/run/flatpak/app/org.strawberrymusicplayer.strawberry/strawberry_38514500" 17:54:18.899 ERROR GlobalShortcutsBackendKDE:161 KGlobalAccel returned QList() when setting shortcut QList(QKeySequence("Media Next")) 17:54:18.907 ERROR GlobalShortcutsBackendKDE:161 KGlobalAccel returned QList() when setting shortcut QList(QKeySequence("Media Play")) 17:54:18.910 ERROR GlobalShortcutsBackendKDE:161 KGlobalAccel returned QList() when setting shortcut QList(QKeySequence("Media Previous")) 17:54:18.914 ERROR GlobalShortcutsBackendKDE:161 KGlobalAccel returned QList() when setting shortcut QList(QKeySequence("Media Stop")) 17:54:19.187 INFO Player:954 Registered URL handler for "subsonic" 17:54:19.200 INFO Player:954 Registered URL handler for "tidal" 17:54:19.235 INFO Player:954 Registered URL handler for "qobuz" 17:54:21.673 INFO MoodbarLoader:137 Loading cached moodbar data for "/home/alpha/Music/Nineties/Frank Popp Ensemble - The World Is Waiting.mp3" 17:54:22.387 ERROR MusixmatchLyricsProvider:404 MusixmatchLyrics: "Received status code 401, switching to URL based lookup." 17:54:22.475 INFO AlbumCoverFetcherSearch:391 Using QUrl("https://e-cdns-images.dzcdn.net/images/cover/e317460b1f8d466043f8f04d4851108e/1000x1000-000000-80-0-0.jpg") from "Deezer" with score 5.5 17:54:25.807 ERROR OVHLyricsProvider:111 OVHLyrics: "Error transferring https://api.lyrics.ovh/v1/Frank Popp Ensemble/The World Is Waiting - server replied: Not Found (203)" 17:54:25.807 ERROR OVHLyricsProvider:111 OVHLyrics: "No lyrics found" 17:57:24.065 INFO MoodbarLoader:137 Loading cached moodbar data for "/home/alpha/Music/Nineties/Depeche Mode - Strangelove.mp3" 17:57:24.083 INFO MoodbarLoader:173 Creating moodbar data for "/home/alpha/Music/Nineties/Anouk - Everything.mp3" 17:57:24.090 ERROR GstEnginePipeline:1348 ErrorMessageReceived ID: 2 Domain: 3461 Code: 1 Error: "Internal data stream error." 17:57:24.090 ERROR GstEnginePipeline:1349 ErrorMessageReceived ID: 2 Domain: 3461 Code: 1 Debug: "../libs/gst/base/gstbaseparse.c(3694): gst_base_parse_loop (): /GstPlayBin3:pipeline-2-pipeline/GstURIDecodeBin3:uridecodebin3/GstURISourceBin:urisourcebin1/GstParseBin:parsebin1/GstMpegAudioParse:mpegaudioparse3:\nstreaming stopped, reason not-linked (-1)" 17:57:24.107 INFO MoodbarLoader:173 Creating moodbar data for "/home/alpha/Music/Nineties/Nirvana - Lithium.mp3" 17:57:24.674 ERROR MusixmatchCoverProvider:212 Musixmatch: "Error transferring https://www.musixmatch.com/album/nirvana/never-mind - server replied: Not Found (203)" 17:57:25.376 INFO MoodbarLoader:186 Moodbar data generated successfully for "/home/alpha/Music/Nineties/Anouk - Everything.mp3" 17:57:25.386 INFO MoodbarLoader:186 Moodbar data generated successfully for "/home/alpha/Music/Nineties/Nirvana - Lithium.mp3" 17:57:25.662 ERROR OVHLyricsProvider:111 OVHLyrics: "Error transferring https://api.lyrics.ovh/v1/Nirvana/Lithium - server replied: Not Found (203)" 17:57:25.662 ERROR OVHLyricsProvider:111 OVHLyrics: "No lyrics found" 17:57:26.466 ERROR OVHLyricsProvider:111 OVHLyrics: "Error transferring https://api.lyrics.ovh/v1/Depeche Mode/Strangelove - server replied: Not Found (203)" 17:57:26.466 ERROR OVHLyricsProvider:111 OVHLyrics: "No lyrics found" 17:57:26.466 ERROR OVHLyricsProvider:111 OVHLyrics: "Error transferring https://api.lyrics.ovh/v1/Anouk/Everything - server replied: Not Found (203)" 17:57:26.466 ERROR OVHLyricsProvider:111 OVHLyrics: "No lyrics found" 17:57:32.573 ERROR AlbumCoverFetcherSearch:316 Error requesting QUrl("https://lastfm.freetls.fastly.net/i/u/740x0/3a541ee366cd4ad6a85298df077de329.png") "Operation canceled" 17:57:32.573 INFO AlbumCoverFetcherSearch:391 Using QUrl("https://e-cdns-images.dzcdn.net/images/cover/f0282817b697279e56df13909962a54a/1000x1000-000000-80-0-0.jpg") from "Deezer" with score 5.5
-
I am still looking for a solution for this. This did not use to happen with Clementine.
I uninstalled Strawberry from the official repositories and installed the Flatpak (1.0.23) and this keeps happening.
-
This problem can happen if there are issues with the files. Please validate the files using mp3check or similar: https://wiki.strawberrymusicplayer.org/wiki/Validate_audio_files
But of course, it could also be a bug, but I've not heard anyone else having this issue. Does it only happen with MP3?
The original debug output you pasted shows flatpak too. Did you try the native package?
Please set the GST_DEBUG to get more debug output. You can also set GST_DEBUG_FILE to avoid dumping all debug info in the terminal.
I don't know if this works with Flatpak.
export GST_DEBUG=*:5 export GST_DEBUG_FILE=/tmp/strawberry-gstreamer-debug.log strawberry
-
@jonas thank you for that.
It's interesting the first install was also flatpak, that was installed from the official arch repositories rather than flatpak. I wonder if they just use the flatpak for the repos?
How do I enable DEBUG at launch of Strawberry? This is the command to start the flatpak. How do I put the debug flag here?
usr/bin/flatpak run --branch=stable --arch=x86_64 --command=strawberry --file-forwarding org.strawberrymusicplayer.strawberry
Also, you may be right the mp3 files might have issues. However this is not an issue with other media players (previously with Clementine and in my Android phone with Musicolet) but in both my Desktop and my Laptop Strawberry behaves like that.
Below is the output of
mp3check -earsv
Sorry, the text file is enormous, I had to upload it somewhere
or
But basically the output says
683 files checked, 683 erroneous files found (663 anomalies found)
Some errors I saw in the output in multiple files:
- bitrate switching (192 -> 160)
- bitrate switching (160 -> 192)
- 191069 bytes of junk before first frame header
- anomaly: bitrate 320kbit/s
- anomaly: no crc
- anomaly: mode stereo
-
@br_shadow
You can ignore the errors for bitrate, crc and stereo mode, bitrate switching. You ran mp3check with the -a option, which means it will report all sort of stuff which isn't actually broken/corrupt files.
I suggest you run the command again without -a
The "191069 bytes of junk before first frame header" error might be that the software you used to rip cd's or download the mp3s with added some header on top of the data, I would think that this is just ignored by software in most cases, and if it causes the files to be unplayable it would be consistently unplayable. -
@br_shadow
I don't have much knowledge of Flatpak, so I don't know it's possible to get debug output, or run it through a debugger at all. Maybe ask Flatpak community support, or ask Manjaro how to get the native package. -
Thanks. I removed the Flatpak, as it had a bug anyway (could not enable Moodbar at all).
Okay here is the output of
mp3check -ersv /home/geo/Music/Lost\ in\ a\ Myth/
Again huge text file
The output of the following command (I pasted it as a single command):
export GST_DEBUG=*:5 export GST_DEBUG_FILE=/tmp/strawberry-gstreamer-debug.log strawberry
Output from bash:
[geo@desktop ~]$ export GST_DEBUG=*:5 export GST_DEBUG_FILE=/tmp/strawberry-gstreamer-debug.log strawberry 13:08:12.968 INFO main:184 Strawberry 1.0.22 Qt "6.6.1" 13:08:12.968 INFO main:185 "Manjaro Linux unknown - (linux 6.6.10-1-MANJARO) [x86_64]" 13:08:12.968 WARN unknown Could not find the Qt platform plugin "wayland" in "" 13:08:12.993 ERROR GlobalShortcutsBackendKDE:161 KGlobalAccel returned QList() when setting shortcut QList(QKeySequence("Media Next")) 13:08:12.993 ERROR GlobalShortcutsBackendKDE:161 KGlobalAccel returned QList() when setting shortcut QList(QKeySequence("Media Play")) 13:08:12.993 ERROR GlobalShortcutsBackendKDE:161 KGlobalAccel returned QList() when setting shortcut QList(QKeySequence("Media Previous")) 13:08:12.993 ERROR GlobalShortcutsBackendKDE:161 KGlobalAccel returned QList() when setting shortcut QList(QKeySequence("Media Stop")) 13:08:12.999 INFO main:47 TagReader worker connecting to "/tmp/strawberry_2373202606" 13:08:13.054 INFO Player:954 Registered URL handler for "subsonic" 13:08:13.056 INFO Player:954 Registered URL handler for "tidal" 13:08:13.063 INFO Player:954 Registered URL handler for "qobuz" 13:08:17.717 INFO MoodbarLoader:137 Loading cached moodbar data for "/home/geo/Music/Lost in a Myth/Howard Shore - Flight from Edoras.mp3" 13:08:18.504 ERROR MusixmatchLyricsProvider:404 MusixmatchLyrics: "Received status code 401, switching to URL based lookup." 13:08:19.502 ERROR OVHLyricsProvider:111 OVHLyrics: "Error transferring https://api.lyrics.ovh/v1/Howard Shore/Flight from Edoras - server replied: Not Found (203)" 13:08:19.502 ERROR OVHLyricsProvider:111 OVHLyrics: "No lyrics found" 13:10:31.221 INFO MoodbarLoader:137 Loading cached moodbar data for "/home/geo/Music/Lost in a Myth/Grant Kirkhope - Klurikon.mp3" 13:10:33.104 ERROR OVHLyricsProvider:111 OVHLyrics: "Error transferring https://api.lyrics.ovh/v1/Grant Kirkhope/Klurikon - server replied: Not Found (203)" 13:10:33.104 ERROR OVHLyricsProvider:111 OVHLyrics: "No lyrics found" 13:14:03.487 INFO MoodbarLoader:137 Loading cached moodbar data for "/home/geo/Music/Lost in a Myth/Kevin Riepl - Immutable Truth.mp3" 13:14:05.297 ERROR OVHLyricsProvider:111 OVHLyrics: "Error transferring https://api.lyrics.ovh/v1/Kevin Riepl/Immutable Truth - server replied: Not Found (203)" 13:14:05.297 ERROR OVHLyricsProvider:111 OVHLyrics: "No lyrics found"
Here is the strawberry-gstreamer-debug.log. I had to stop the process before the behavior manifested at all (usually it starts doing it 4-5 songs in) as the file had reached 1.5 GB. If you know of a way to make the debug log less verbose so I can stop it when the behaviour actually manifests, let me know.
-
@jonas confirming this is a bug in Strawberry. I have been using Clementine and this issue does not occur. It also does not occur with other media players. happy to help you further detect the bug
-
Please try
export GST_DEBUG=*:4
instead, it should reproduce less log output, but we might still get some useful output. -
This seems to be the same looking issue I saw on Debian (and I'm currently on a fully patched Bookworm), which I still cannot provoke reliably yet had it occur today (I'm still running .17 because it appears to happen less often that in newer versions). A track that will play properly most of the time will suddenly skip back in the early parts of the track, and then end early because the time runs out (as per the time bar) before the song ends. Sometimes the following tracks play perfectly, other times following tracks have the same skip issue.
Restarting Strawberry fixes it. Never saw this in Clementine with the same file.
My original post was at https://forum.strawberrymusicplayer.org/topic/1138/playback-issue-restarting-after-10ish-seconds, but as I couldn't reliably provoke it I didn't go futher. I might try the debug command and see if I can provoke it again - the problem being I might have to run Strawberry for a long time before it occurs, and restarting for me always clears the issue. No single track is guaranteed to make it happen.
-
Not sure if relevant - I do have mine skipping back in songs again, what I've noticed is that it appears to be coincidental with updating cover art (it's doing that automatically, not because I'm triggering a lookup manually whilst playing), and also I see a lot of what looks like a hex dump rapidly written to the screen. Are there specific markers I could look for for song start/when I press "Stop" on a repeating song so that I can try and trap just that part?
As an example:
26:23:05.088510589 1490048 0x7f09e4001460 INFO baseparse gstbaseparse.c:4898:gst_base_parse_set_upstream_tags:<mpegaudioparse346> upstream tags: taglist, album=(string)"Yesterday\ Once\ More", artist=(string)Carpenters, comment=(string)"Greatest\ Hits\ -\ 1969-1983\012YEAR:\ 1998\ \ ID3G:\ \ 17", album-disc-count=(uint)2, album-disc-number=(uint)2, genre=(string)Pop, replaygain-album-gain=(double)-2.1499999999999999, replaygain-album-peak=(double)1.057426, replaygain-track-gain=(double)-1.97, replaygain-track-peak=(double)0.82459300000000002, title=(string)"Because\ We\ Are\ in\ Love\ \(The\ Wedding\ Song\)", track-count=(uint)14, track-number=(uint)9, date=(date)1998-01-01, container-format=(string)"APE\ tag"; 26:23:05.094524047 1490048 0x7f09e4001460 INFO GST_EVENT gstevent.c:918:gst_event_new_caps: creating caps event audio/mpeg, mpegversion=(int)1, mpegaudioversion=(int)1, layer=(int)3, rate=(int)44100, channels=(int)2, parsed=(boolean)true 26:23:05.094547035 1490048 0x7f09e4001460 INFO GST_ELEMENT_PADS gstpad.c:2142:gst_pad_unlink: unlinking mpegaudioparse346:src(0x562fa1d640a0) and decodepad242:proxypad1648(0x562fa1bb71d0) 26:23:05.094557689 1490048 0x7f09e4001460 INFO GST_ELEMENT_PADS gstpad.c:2197:gst_pad_unlink: unlinked mpegaudioparse346:src and decodepad242:proxypad1648 26:23:05.094565626 1490048 0x7f09e4001460 INFO GST_PADS gstpad.c:2387:gst_pad_link_prepare: trying to link mpegaudioparse346:src and decodepad242:proxypad1648 26:23:05.094571611 1490048 0x7f09e4001460 INFO GST_PADS gstpad.c:2595:gst_pad_link_full: linked mpegaudioparse346:src and decodepad242:proxypad1648, successful 26:23:05.094575766 1490048 0x7f09e4001460 INFO GST_EVENT gstevent.c:1687:gst_event_new_reconfigure: creating reconfigure event 26:23:05.094759770 1490048 0x7f09e4001460 INFO GST_ELEMENT_PADS gstpad.c:2142:gst_pad_unlink: unlinking mpegaudioparse346:src(0x562fa1d640a0) and decodepad242:proxypad1648(0x562fa1bb71d0) 26:23:05.094768512 1490048 0x7f09e4001460 INFO GST_ELEMENT_PADS gstpad.c:2197:gst_pad_unlink: unlinked mpegaudioparse346:src and decodepad242:proxypad1648 26:23:05.094774934 1490048 0x7f09e4001460 INFO GST_PADS gstpad.c:2387:gst_pad_link_prepare: trying to link mpegaudioparse346:src and decodepad242:proxypad1648 26:23:05.094780071 1490048 0x7f09e4001460 INFO GST_PADS gstpad.c:2595:gst_pad_link_full: linked mpegaudioparse346:src and decodepad242:proxypad1648, successful 26:23:05.094784029 1490048 0x7f09e4001460 INFO GST_EVENT gstevent.c:1687:gst_event_new_reconfigure: creating reconfigure event 26:23:05.094795338 1490048 0x7f09e4001460 INFO GST_ELEMENT_PADS gstpad.c:2142:gst_pad_unlink: unlinking mpegaudioparse346:src(0x562fa1d640a0) and decodepad242:proxypad1648(0x562fa1bb71d0) 26:23:05.094801739 1490048 0x7f09e4001460 INFO GST_ELEMENT_PADS gstpad.c:2197:gst_pad_unlink: unlinked mpegaudioparse346:src and decodepad242:proxypad1648 26:23:05.094807814 1490048 0x7f09e4001460 INFO GST_PADS gstpad.c:2387:gst_pad_link_prepare: trying to link mpegaudioparse346:src and decodepad242:proxypad1648 26:23:05.094812782 1490048 0x7f09e4001460 INFO GST_PADS gstpad.c:2595:gst_pad_link_full: linked mpegaudioparse346:src and decodepad242:proxypad1648, successful 26:23:05.094816635 1490048 0x7f09e4001460 INFO GST_EVENT gstevent.c:1687:gst_event_new_reconfigure: creating reconfigure event 26:23:05.094827819 1490048 0x7f09e4001460 INFO GST_ELEMENT_PADS gstpad.c:2142:gst_pad_unlink: unlinking mpegaudioparse346:src(0x562fa1d640a0) and decodepad242:proxypad1648(0x562fa1bb71d0) 26:23:05.094833711 1490048 0x7f09e4001460 INFO GST_ELEMENT_PADS gstpad.c:2197:gst_pad_unlink: unlinked mpegaudioparse346:src and decodepad242:proxypad1648 26:23:05.094840054 1490048 0x7f09e4001460 INFO GST_ELEMENT_FACTORY gstelementfactory.c:489:gst_element_factory_create_with_properties: creating element "avdec_mp3" 26:23:05.094856260 1490048 0x7f09e4001460 INFO GST_ELEMENT_PADS gstelement.c:758:gst_element_add_pad:<GstAudioDecoder@0x7f09c8016230> adding pad 'sink' 26:23:05.094864552 1490048 0x7f09e4001460 INFO GST_ELEMENT_PADS gstelement.c:758:gst_element_add_pad:<GstAudioDecoder@0x7f09c8016230> adding pad 'src' 26:23:05.094892791 1490048 0x7f09e4001460 INFO GST_PADS gstpad.c:2387:gst_pad_link_prepare: trying to link mpegaudioparse346:src and avdec_mp3-327:sink 26:23:05.094899221 1490048 0x7f09e4001460 INFO GST_PADS gstpad.c:2595:gst_pad_link_full: linked mpegaudioparse346:src and avdec_mp3-327:sink, successful 26:23:05.094903181 1490048 0x7f09e4001460 INFO GST_EVENT gstevent.c:1687:gst_event_new_reconfigure: creating reconfigure event 26:23:05.094913462 1490048 0x7f09e4001460 INFO GST_STATES gstelement.c:2816:gst_element_continue_state:<avdec_mp3-327> completed state change to READY 26:23:05.094918882 1490048 0x7f09e4001460 INFO GST_STATES gstelement.c:2716:_priv_gst_element_state_changed:<avdec_mp3-327> notifying about state-changed NULL to READY (VOID_PENDING pending) 26:23:05.094932785 1490048 0x7f09e4001460 INFO GST_ELEMENT_PADS gstelement.c:1016:gst_element_get_static_pad: found pad avdec_mp3-327:src 26:23:05.094941939 1490048 0x7f09e4001460 INFO GST_PADS gstpad.c:2387:gst_pad_link_prepare: trying to link avdec_mp3-327:src and decodepad242:proxypad1648 26:23:05.094947031 1490048 0x7f09e4001460 INFO GST_PADS gstpad.c:2595:gst_pad_link_full: linked avdec_mp3-327:src and decodepad242:proxypad1648, successful 26:23:05.094950880 1490048 0x7f09e4001460 INFO GST_EVENT gstevent.c:1687:gst_event_new_reconfigure: creating reconfigure event 26:23:05.094955315 1490048 0x7f09e4001460 INFO GST_EVENT gstpad.c:5985:gst_pad_send_event_unchecked:<avdec_mp3-327:src> Received event on flushing pad. Discarding 26:23:05.094975336 1490048 0x7f09e4001460 INFO GST_STATES gstelement.c:2816:gst_element_continue_state:<avdec_mp3-327> completed state change to PAUSED 26:23:05.094981017 1490048 0x7f09e4001460 INFO GST_STATES gstelement.c:2716:_priv_gst_element_state_changed:<avdec_mp3-327> notifying about state-changed READY to PAUSED (VOID_PENDING pending) 26:23:05.101140200 1490048 0x7f09e4001460 INFO audiodecoder gstaudiodecoder.c:2525:gst_audio_decoder_sink_eventfunc:<avdec_mp3-327> upstream stream tags: taglist, title=(string)"Because\ We\ Are\ in\ Love\ \(The\ Wedding\ Song\)", artist=(string)Carpenters, album=(string)"Yesterday\ Once\ More", datetime=(datetime)1998, comment=(string)"Greatest\ Hits\ -\ 1969-1983\012YEAR:\ 1998\ \ ID3G:\ \ 17", track-number=(uint)9, genre=(string)Pop, container-format=(string)"ID3\ tag", track-count=(uint)14, album-disc-count=(uint)2, album-disc-number=(uint)2, artist-sortname=(string)Carpenters, musicbrainz-trackid=(string)e64ed6d5-4cca-4940-a2ca-efa814f81aab, private-id3v2-frame=(sample){ 545858580000001b000003414c42554d415254495354534f52540043617270656e74657273:None:c2VnbWVudCwgZmxhZ3M9KEdzdFNlZ21lbnRGbGFncylHU1RfU0VHTUVOVF9GTEFHX05PTkUsIHJhdGU9KGRvdWJsZSkxLCBhcHBsaWVkLXJhdGU9KGRvdWJsZSkxLCBmb3JtYXQ9KEdzdEZvcm1hdCl0aW1lLCBiYXNlPShndWludDY0KTAsIG9mZnNldD0oZ3VpbnQ2NCkwLCBzdGFydD0oZ3VpbnQ2NCkwLCBzdG9wPShndWlu (followed by many lines of hex)
This song skipped back whilst playing, but I've no idea what bit of log to trap.
Could I exclude lines that only state
GST_STATES gstbin.c:2069:gst_bin_get_state_func:<pipeline-86-pipeline> getting state
-
I can now reliably cause a skip-back by playing a file from an album that doesn't currently have cover art showing in the album collection list. It appears to occur as the image is linked somehow into the file.
Capture of *:4 debug when this occurred is at https://file.io/Mv1UzlzulrE0
This is on .17, I'll try and see if I can do the same on .23 (latest Debian)
-
This post is deleted! -
So far, not had this happen after installing .23 and the qt6 library it needed. It still autoloads a picture if it can, and closes part of the collection list if it finds one, but hasn't skipped back in the track.
-
@astrovark
If you have enabled to save album covers as embedded covers under the covers settings, this can happen, since the cover is saved at the same time the track is played if you have the "Automatically search for album cover" option on.