Volumio 3.742 + Spotify plugin 4.10 Bugs

[Darmur]

@TubularBells

For reference, this system is running the following additional plugins: System Information, Touch Display, and FusionDSP.

Try to disable and uninstall FusionDSP

[TubularBells]

FusionDSP uninstalled and system restarted. It feels faster off the bat, so I’ll reinstall Spotify and monitor from here on.

[Wolf2]

I got the same problem with Spotify 4.1.1 not working anymore, using the incredible sounding Swiss Made HifiBerry DAC2 HD. The problem may be in the DAC driver, as Volumio only got this one working a few weeks ago; it was working before with other platforms. Tried everything, fresh install, no Fusion. System otherwise working fine incl. internet radio.

[TubularBells]

Hi. I’ve tried this in 2 systems; one with a USB dac (Zen Dac V2) and another with an Innomaker Dac Pro I2S hat. After prolonged use, both systems run into the same issues eventually, and without fusion DSP installed on either.

Random disconnects, connection lock-ups with Spotify. I’ve uninstalled the plugin entirely and am operating without it as it seems to be creating even more issues for me than other functionalities like Tidal Connect, which at the moment appears more stable.

[Wolf2]

So that means the problem quite definitively lies within the Spotify plugin and not within the DAC configuration!

[MP3Kitty]

“So that means the problem quite definitively lies within the Spotify plugin and not within the DAC configuration!”

I think so. It was working perfect under 4.10 plugin. Even mine is NOT a genuine brand, still chipsests are chipsets. (That is what I observe in my 30 years+ system integration experience.)

[MP3Kitty]

I just created another thread under Plugin since this prob seems to be a chipset specific.

Spotify plugin 4.1.1 not working with HiFiBerry DAC plus (PCM 5122)

After upgrading Spotify plugin to 4.1.1., DAC stop working. It is HiFiBerry DAC plus (PCM 5122) compatible and I noticed other users are having the same problem. We figured it out it is a driver issue for this particular chipset. Did anyone find a solution for this?

[sciensys]

I have been observing daily stops of playback by the Spotify plugin for 2-3 weeks now.
The latest update of Volumio has been installed.

at the same time, in the web interface, switching to a new track occurs, but time does not go by; if you refresh the browser, the time is updated, counted for a couple of seconds and stopped again, but there is no sound.

Log, after playback has stopped:

– Logs begin at Thu 2019-02-14 13:11:59 +03. –
Oct 03 13:16:15 main volumio[892]: SPOTIFY: RECEIVED VOLUMIO VOLUME 60

Oct 03 13:20:04 main volumio[892]: info: CorePlayQueue::getTrack 6
Oct 03 13:20:04 main volumio[892]: info: CorePlayQueue::getTrack 7
Oct 03 13:20:04 main volumio[892]: info: Prefetching next song
Oct 03 13:20:04 main volumio[892]: info: [1727950804963] ControllerSpotify::prefetch
Oct 03 13:20:04 main volumio[892]: info: Sending Spotify command with payload to local API: /player/add_to_queue
Oct 03 13:20:05 main go-librespot[3976]: time=“2024-10-03T13:20:05+03:00” level=debug msg=“put connect state because PLAYER_STATE_CHANGED”
Oct 03 13:20:09 main volumio[892]: info: CoreStateMachine::startPlaybackTimer
Oct 03 13:20:09 main volumio[892]: info: CorePlayQueue::getTrack 7
Oct 03 13:20:09 main volumio[892]: info: CoreStateMachine::pushState
Oct 03 13:20:09 main volumio[892]: info: CorePlayQueue::getTrack 7
Oct 03 13:20:09 main volumio[892]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Oct 03 13:20:09 main volumio[892]: info: CoreCommandRouter::volumioPushState
Oct 03 13:20:09 main volumio[892]: SPOTIFY: RECEIVED VOLUMIO VOLUME 60
Oct 03 13:22:39 main volumio[892]: info: CorePlayQueue::getTrack 7
Oct 03 13:22:39 main volumio[892]: info: CorePlayQueue::getTrack 8
Oct 03 13:22:39 main volumio[892]: info: Prefetching next song
Oct 03 13:22:39 main volumio[892]: info: [1727950959623] ControllerSpotify::prefetch
Oct 03 13:22:39 main volumio[892]: info: Sending Spotify command with payload to local API: /player/add_to_queue
Oct 03 13:22:39 main go-librespot[3976]: time=“2024-10-03T13:22:39+03:00” level=debug msg=“put connect state because PLAYER_STATE_CHANGED”
Oct 03 13:22:44 main volumio[892]: info: CoreStateMachine::startPlaybackTimer
Oct 03 13:22:44 main volumio[892]: info: CorePlayQueue::getTrack 8
Oct 03 13:22:44 main volumio[892]: info: CoreStateMachine::pushState
Oct 03 13:22:44 main volumio[892]: info: CorePlayQueue::getTrack 8
Oct 03 13:22:44 main volumio[892]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Oct 03 13:22:44 main volumio[892]: info: CoreCommandRouter::volumioPushState
Oct 03 13:22:44 main volumio[892]: SPOTIFY: RECEIVED VOLUMIO VOLUME 60
Oct 03 13:25:38 main volumio[892]: info: CorePlayQueue::getTrack 8
Oct 03 13:25:38 main volumio[892]: info: CorePlayQueue::getTrack 9
Oct 03 13:25:38 main volumio[892]: info: Prefetching next song
Oct 03 13:25:38 main volumio[892]: info: [1727951138315] ControllerSpotify::prefetch
Oct 03 13:25:38 main volumio[892]: info: Sending Spotify command with payload to local API: /player/add_to_queue
Oct 03 13:25:38 main go-librespot[3976]: time=“2024-10-03T13:25:38+03:00” level=debug msg=“put connect state because PLAYER_STATE_CHANGED”
Oct 03 13:25:42 main volumio[892]: info: CoreStateMachine::startPlaybackTimer
Oct 03 13:25:42 main volumio[892]: info: CorePlayQueue::getTrack 9
Oct 03 13:25:43 main volumio[892]: info: CoreStateMachine::pushState
Oct 03 13:25:43 main volumio[892]: info: CorePlayQueue::getTrack 9
Oct 03 13:25:43 main volumio[892]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Oct 03 13:25:43 main volumio[892]: info: CoreCommandRouter::volumioPushState
Oct 03 13:25:43 main volumio[892]: SPOTIFY: RECEIVED VOLUMIO VOLUME 60

then, if you click play next track, the plugin starts playing:

– Logs begin at Thu 2019-02-14 13:11:59 +03. –
Oct 03 13:29:33 main volumio[892]: info: Received an update from plugin. extracting info from payload
Oct 03 13:29:33 main volumio[892]: info: CoreStateMachine::pushState
Oct 03 13:29:33 main volumio[892]: info: CorePlayQueue::getTrack 10
Oct 03 13:29:33 main volumio[892]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Oct 03 13:29:33 main volumio[892]: info: CoreCommandRouter::volumioPushState
Oct 03 13:29:33 main volumio[892]: info: CoreStateMachine::pushState
Oct 03 13:29:33 main volumio[892]: info: CorePlayQueue::getTrack 10
Oct 03 13:29:33 main volumio[892]: info: CoreCommandRouter::volumioPushState
Oct 03 13:29:33 main volumio[892]: SPOTIFY: RECEIVED VOLUMIO VOLUME 60
Oct 03 13:29:33 main volumio[892]: SPOTIFY: RECEIVED VOLUMIO VOLUME 60
Oct 03 13:29:44 main go-librespot[3976]: time=“2024-10-03T13:29:44+03:00” level=debug msg=“fetched chunk 4/15, size: 524288” uri=“spotify:track:3F4WWA3JqsX2VmvqHywxEA”
Oct 03 13:29:57 main go-librespot[3976]: time=“2024-10-03T13:29:57+03:00” level=debug msg=“fetched chunk 5/15, size: 524288” uri=“spotify:track:3F4WWA3JqsX2VmvqHywxEA”
Oct 03 13:30:10 main go-librespot[3976]: time=“2024-10-03T13:30:10+03:00” level=debug msg=“fetched chunk 6/15, size: 524288” uri=“spotify:track:3F4WWA3JqsX2VmvqHywxEA”
Oct 03 13:30:22 main go-librespot[3976]: time=“2024-10-03T13:30:22+03:00” level=debug msg=“fetched chunk 7/15, size: 524288” uri=“spotify:track:3F4WWA3JqsX2VmvqHywxEA”
Oct 03 13:30:34 main go-librespot[3976]: time=“2024-10-03T13:30:34+03:00” level=debug msg=“fetched chunk 8/15, size: 524288” uri=“spotify:track:3F4WWA3JqsX2VmvqHywxEA”
Oct 03 13:30:46 main go-librespot[3976]: time=“2024-10-03T13:30:46+03:00” level=debug msg=“fetched chunk 9/15, size: 524288” uri=“spotify:track:3F4WWA3JqsX2VmvqHywxEA”
Oct 03 13:30:59 main go-librespot[3976]: time=“2024-10-03T13:30:59+03:00” level=debug msg=“fetched chunk 10/15, size: 524288” uri=“spotify:track:3F4WWA3JqsX2VmvqHywxEA”
Oct 03 13:31:11 main go-librespot[3976]: time=“2024-10-03T13:31:11+03:00” level=debug msg=“fetched chunk 11/15, size: 524288” uri=“spotify:track:3F4WWA3JqsX2VmvqHywxEA”
Oct 03 13:31:23 main go-librespot[3976]: time=“2024-10-03T13:31:23+03:00” level=debug msg=“fetched chunk 12/15, size: 524288” uri=“spotify:track:3F4WWA3JqsX2VmvqHywxEA”
Oct 03 13:31:35 main go-librespot[3976]: time=“2024-10-03T13:31:35+03:00” level=debug msg=“fetched chunk 13/15, size: 524288” uri=“spotify:track:3F4WWA3JqsX2VmvqHywxEA”
Oct 03 13:31:48 main go-librespot[3976]: time=“2024-10-03T13:31:48+03:00” level=debug msg=“fetched chunk 14/15, size: 524288” uri=“spotify:track:3F4WWA3JqsX2VmvqHywxEA”
Oct 03 13:32:01 main go-librespot[3976]: time=“2024-10-03T13:32:01+03:00” level=debug msg=“fetched chunk 15/15, size: 180848” uri=“spotify:track:3F4WWA3JqsX2VmvqHywxEA”
Oct 03 13:32:39 main volumio[892]: info: CorePlayQueue::getTrack 10
Oct 03 13:32:39 main volumio[892]: info: CorePlayQueue::getTrack 11
Oct 03 13:32:39 main volumio[892]: info: Prefetching next song
Oct 03 13:32:39 main volumio[892]: info: [1727951559703] ControllerSpotify::prefetch
Oct 03 13:32:39 main volumio[892]: info: Sending Spotify command with payload to local API: /player/add_to_queue
Oct 03 13:32:39 main go-librespot[3976]: time=“2024-10-03T13:32:39+03:00” level=debug msg=“put connect state because PLAYER_STATE_CHANGED”
Oct 03 13:32:39 main go-librespot[3976]: time=“2024-10-03T13:32:39+03:00” level=debug msg=“prefetching next track” uri=“spotify:track:7tqhbajSfrz2F7E1Z75ASX”
Oct 03 13:32:39 main go-librespot[3976]: time=“2024-10-03T13:32:39+03:00” level=debug msg=“selected format OGG_VORBIS_320 (06ba4f7c2ee894c6f78a885692b02348aff47632)” uri=“spotify:track:7tqhbajSfrz2F7E1Z75ASX”
Oct 03 13:32:39 main go-librespot[3976]: time=“2024-10-03T13:32:39+03:00” level=debug msg=“requested aes key for file 06ba4f7c2ee894c6f78a885692b02348aff47632, gid: 7tqhbajSfrz2F7E1Z75ASX”
Oct 03 13:32:40 main go-librespot[3976]: time=“2024-10-03T13:32:40+03:00” level=debug msg=“fetched first chunk of 12, total size is 6222788 bytes” uri=“spotify:track:7tqhbajSfrz2F7E1Z75ASX”
Oct 03 13:32:40 main go-librespot[3976]: time=“2024-10-03T13:32:40+03:00” level=trace msg=“seek to 0ms (diff: 0ms, samples: 0, bytes: 0)” uri=“spotify:track:7tqhbajSfrz2F7E1Z75ASX”
Oct 03 13:32:40 main go-librespot[3976]: time=“2024-10-03T13:32:40+03:00” level=info msg=“prefetched track "Ain’t No Mountain High Enough" (duration: 151666ms)” uri=“spotify:track:7tqhbajSfrz2F7E1Z75ASX”
Oct 03 13:32:40 main go-librespot[3976]: time=“2024-10-03T13:32:40+03:00” level=debug msg=“fetched chunk 2/11, size: 524288” uri=“spotify:track:7tqhbajSfrz2F7E1Z75ASX”
Oct 03 13:32:40 main go-librespot[3976]: time=“2024-10-03T13:32:40+03:00” level=debug msg=“fetched chunk 1/11, size: 524288” uri=“spotify:track:7tqhbajSfrz2F7E1Z75ASX”
Oct 03 13:32:40 main go-librespot[3976]: time=“2024-10-03T13:32:40+03:00” level=debug msg=“fetched chunk 3/11, size: 524288” uri=“spotify:track:7tqhbajSfrz2F7E1Z75ASX”
Oct 03 13:32:43 main go-librespot[3976]: time=“2024-10-03T13:32:43+03:00” level=trace msg=“emitting websocket event: not_playing”
Oct 03 13:32:43 main go-librespot[3976]: time=“2024-10-03T13:32:43+03:00” level=debug msg=“loading track (paused: false, position: 0ms)” uri=“spotify:track:7tqhbajSfrz2F7E1Z75ASX”
Oct 03 13:32:43 main volumio[892]: SPOTIFY: received: {“type”:“not_playing”,“data”:{“uri”:“spotify:track:3F4WWA3JqsX2VmvqHywxEA”,“play_origin”:“go-librespot”}}
Oct 03 13:32:43 main volumio[892]: error: Failed to decode event: not_playing
Oct 03 13:32:43 main go-librespot[3976]: time=“2024-10-03T13:32:43+03:00” level=debug msg=“put connect state because PLAYER_STATE_CHANGED”
Oct 03 13:32:43 main go-librespot[3976]: time=“2024-10-03T13:32:43+03:00” level=trace msg=“emitting websocket event: will_play”
Oct 03 13:32:43 main volumio[892]: SPOTIFY: received: {“type”:“will_play”,“data”:{“uri”:“spotify:track:7tqhbajSfrz2F7E1Z75ASX”,“play_origin”:“go-librespot”}}
Oct 03 13:32:43 main go-librespot[3976]: time=“2024-10-03T13:32:43+03:00” level=info msg=“loaded track "Ain’t No Mountain High Enough" (paused: false, position: 0ms, duration: 151666ms, prefetched: true)” uri=“spotify:track:7tqhbajSfrz2F7E1Z75ASX”
Oct 03 13:32:43 main go-librespot[3976]: time=“2024-10-03T13:32:43+03:00” level=debug msg=“put connect state because PLAYER_STATE_CHANGED”
Oct 03 13:32:43 main go-librespot[3976]: time=“2024-10-03T13:32:43+03:00” level=trace msg=“scheduling prefetch in 121s”
Oct 03 13:32:43 main go-librespot[3976]: time=“2024-10-03T13:32:43+03:00” level=trace msg=“emitting websocket event: metadata”
Oct 03 13:32:43 main volumio[892]: SPOTIFY: received: {“type”:“metadata”,“data”:{“uri”:“spotify:track:7tqhbajSfrz2F7E1Z75ASX”,“name”:“Ain’t No Mountain High Enough”,“artist_names”:[“Marvin Gaye”,“Tammi Terrell”],“album_name”:“United”,“album_cover_url”:“https://i.scdn.co/image/ab67616d00001e029173e50e99bdea2400222f02",“position”:0,“duration”:151666,“release_date”:"year:1967 month:8 day:29”,“track_number”:1,“disc_number”:1}}
Oct 03 13:32:44 main go-librespot[3976]: time=“2024-10-03T13:32:44+03:00” level=debug msg=“put connect state because PLAYER_STATE_CHANGED”
Oct 03 13:32:44 main go-librespot[3976]: time=“2024-10-03T13:32:44+03:00” level=trace msg=“emitting websocket event: playing”
Oct 03 13:32:44 main volumio[892]: SPOTIFY: received: {“type”:“playing”,“data”:{“uri”:“spotify:track:7tqhbajSfrz2F7E1Z75ASX”,“play_origin”:“go-librespot”}}
Oct 03 13:32:44 main volumio[892]: SPOTIFY: PUSH STATE SPOTIFY
Oct 03 13:32:44 main volumio[892]: SPOTIFY: {“status”:“play”,“service”:“spop”,“title”:“Ain’t No Mountain High Enough”,“artist”:“Marvin Gaye, Tammi Terrell”,“album”:“United”,“albumart”:“https://i.scdn.co/image/ab67616d00001e029173e50e99bdea2400222f02",“uri”:“spotify:track:7tqhbajSfrz2F7E1Z75ASX”,“trackType”:“spotify”,“seek”:0,“duration”:151,“samplerate”:"44.1 KHz”,“bitdepth”:“16 bit”,“bitrate”:“320 kbps”,“codec”:“ogg”,“channels”:2,“random”:null,“repeat”:null,“repeatSingle”:null}
Oct 03 13:32:44 main volumio[892]: info: CoreCommandRouter::servicePushState
Oct 03 13:32:44 main volumio[892]: info: CorePlayQueue::getTrack 10
Oct 03 13:32:44 main volumio[892]: verbose: STATE SERVICE {“status”:“play”,“service”:“spop”,“title”:“Ain’t No Mountain High Enough”,“artist”:“Marvin Gaye, Tammi Terrell”,“album”:“United”,“albumart”:“https://i.scdn.co/image/ab67616d00001e029173e50e99bdea2400222f02",“uri”:“spotify:track:7tqhbajSfrz2F7E1Z75ASX”,“trackType”:“spotify”,“seek”:0,“duration”:151,“samplerate”:"44.1 KHz”,“bitdepth”:“16 bit”,“bitrate”:“320 kbps”,“codec”:“ogg”,“channels”:2,“random”:null,“repeat”:null,“repeatSingle”:null}
Oct 03 13:32:44 main volumio[892]: verbose: CURRENT POSITION 10
Oct 03 13:32:44 main volumio[892]: info: CoreStateMachine::syncState stateService play
Oct 03 13:32:44 main volumio[892]: info: CoreStateMachine::syncState currentStatus play
Oct 03 13:32:44 main volumio[892]: info: Received an update from plugin. extracting info from payload
Oct 03 13:32:44 main volumio[892]: info: CoreStateMachine::pushState
Oct 03 13:32:44 main volumio[892]: info: CorePlayQueue::getTrack 10
Oct 03 13:32:44 main volumio[892]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Oct 03 13:32:44 main volumio[892]: info: CoreCommandRouter::volumioPushState
Oct 03 13:32:44 main volumio[892]: info: CoreStateMachine::pushState
Oct 03 13:32:44 main volumio[892]: info: CorePlayQueue::getTrack 10
Oct 03 13:32:44 main volumio[892]: info: CoreCommandRouter::volumioPushState
Oct 03 13:32:44 main volumio[892]: SPOTIFY: RECEIVED VOLUMIO VOLUME 60
Oct 03 13:32:44 main volumio[892]: SPOTIFY: RECEIVED VOLUMIO VOLUME 60
Oct 03 13:32:44 main volumio[892]: info: CoreStateMachine::startPlaybackTimer
Oct 03 13:32:44 main volumio[892]: info: CorePlayQueue::getTrack 11
Oct 03 13:32:44 main volumio[892]: SPOTIFY: PUSH STATE SPOTIFY
Oct 03 13:32:44 main volumio[892]: SPOTIFY: {“status”:“play”,“service”:“spop”,“title”:“Ain’t No Mountain High Enough”,“artist”:“Marvin Gaye, Tammi Terrell”,“album”:“United”,“albumart”:“https://i.scdn.co/image/ab67616d00001e029173e50e99bdea2400222f02",“uri”:“spotify:track:7tqhbajSfrz2F7E1Z75ASX”,“trackType”:“spotify”,“seek”:1000,“duration”:151,“samplerate”:"44.1 KHz”,“bitdepth”:“16 bit”,“bitrate”:“320 kbps”,“codec”:“ogg”,“channels”:2,“random”:null,“repeat”:null,“repeatSingle”:null}
Oct 03 13:32:44 main volumio[892]: info: CoreCommandRouter::servicePushState
Oct 03 13:32:44 main volumio[892]: info: CorePlayQueue::getTrack 11
Oct 03 13:32:44 main volumio[892]: verbose: STATE SERVICE {“status”:“play”,“service”:“spop”,“title”:“Ain’t No Mountain High Enough”,“artist”:“Marvin Gaye, Tammi Terrell”,“album”:“United”,“albumart”:“https://i.scdn.co/image/ab67616d00001e029173e50e99bdea2400222f02",“uri”:“spotify:track:7tqhbajSfrz2F7E1Z75ASX”,“trackType”:“spotify”,“seek”:1000,“duration”:151,“samplerate”:"44.1 KHz”,“bitdepth”:“16 bit”,“bitrate”:“320 kbps”,“codec”:“ogg”,“channels”:2,“random”:null,“repeat”:null,“repeatSingle”:null}
Oct 03 13:32:44 main volumio[892]: verbose: CURRENT POSITION 11
Oct 03 13:32:44 main volumio[892]: info: CoreStateMachine::syncState stateService play
Oct 03 13:32:44 main volumio[892]: info: CoreStateMachine::syncState currentStatus play
Oct 03 13:32:44 main volumio[892]: info: Received an update from plugin. extracting info from payload
Oct 03 13:32:44 main volumio[892]: info: CoreStateMachine::pushState
Oct 03 13:32:44 main volumio[892]: info: CorePlayQueue::getTrack 11
Oct 03 13:32:44 main volumio[892]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Oct 03 13:32:44 main volumio[892]: info: CoreCommandRouter::volumioPushState
Oct 03 13:32:44 main volumio[892]: info: CoreStateMachine::pushState
Oct 03 13:32:44 main volumio[892]: info: CorePlayQueue::getTrack 11
Oct 03 13:32:44 main volumio[892]: info: CoreCommandRouter::volumioPushState
Oct 03 13:32:44 main volumio[892]: SPOTIFY: RECEIVED VOLUMIO VOLUME 60
Oct 03 13:32:44 main volumio[892]: SPOTIFY: RECEIVED VOLUMIO VOLUME 60
Oct 03 13:32:44 main volumio[892]: info: CoreStateMachine::pushState
Oct 03 13:32:44 main volumio[892]: info: CorePlayQueue::getTrack 11
Oct 03 13:32:44 main volumio[892]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Oct 03 13:32:44 main volumio[892]: info: CoreCommandRouter::volumioPushState
Oct 03 13:32:44 main volumio[892]: SPOTIFY: RECEIVED VOLUMIO VOLUME 60
Oct 03 13:32:55 main go-librespot[3976]: time=“2024-10-03T13:32:55+03:00” level=debug msg=“fetched chunk 4/11, size: 524288” uri=“spotify:track:7tqhbajSfrz2F7E1Z75ASX”
Oct 03 13:33:08 main go-librespot[3976]: time=“2024-10-03T13:33:08+03:00” level=debug msg=“fetched chunk 5/11, size: 524288” uri=“spotify:track:7tqhbajSfrz2F7E1Z75ASX”
Oct 03 13:33:10 main volumio[892]: info: CoreCommandRouter::volumioPause
Oct 03 13:33:10 main volumio[892]: info: CoreStateMachine::pause
Oct 03 13:33:10 main volumio[892]: info: CoreStateMachine::stPlaybackTimer
Oct 03 13:33:10 main volumio[892]: info: CoreStateMachine::servicePause
Oct 03 13:33:10 main volumio[892]: info: CorePlayQueue::getTrack 11
Oct 03 13:33:10 main volumio[892]: info: CoreCommandRouter::servicePause
Oct 03 13:33:10 main volumio[892]: info: Spotify Received pause
Oct 03 13:33:10 main volumio[892]: SPOTIFY: SPOTIFY PAUSE
Oct 03 13:33:10 main volumio[892]: SPOTIFY: {“status”:“play”,“position”:11,“title”:“Ain’t No Mountain High Enough”,“artist”:“Marvin Gaye”,“album”:“United”,“albumart”:“https://i.scdn.co/image/ab67616d0000b2739173e50e99bdea2400222f02",“uri”:“spotify:track:7tqhbajSfrz2F7E1Z75ASX”,“trackType”:“spotify”,“codec”:“ogg”,“seek”:1250,“duration”:151,“samplerate”:"320 kbps”,“bitdepth”:“16 bit”,“channels”:2,“random”:false,“repeat”:true,“repeatSingle”:false,“consume”:false,“volume”:60,“dbVolume”:null,“disableVolumeControl”:false,“mute”:false,“stream”:“spotify”,“volatile”:false,“service”:“spop”}
Oct 03 13:33:10 main volumio[892]: info: Sending Spotify command to local API: /player/pause
Oct 03 13:33:10 main go-librespot[3976]: time=“2024-10-03T13:33:10+03:00” level=debug msg=“pause track at 26298ms”
Oct 03 13:33:10 main go-librespot[3976]: time=“2024-10-03T13:33:10+03:00” level=debug msg=“put connect state because PLAYER_STATE_CHANGED”
Oct 03 13:33:10 main go-librespot[3976]: time=“2024-10-03T13:33:10+03:00” level=debug msg=“put connect state because PLAYER_STATE_CHANGED”
Oct 03 13:33:10 main go-librespot[3976]: time=“2024-10-03T13:33:10+03:00” level=trace msg=“emitting websocket event: paused”
Oct 03 13:33:10 main volumio[892]: SPOTIFY: received: {“type”:“paused”,“data”:{“uri”:“spotify:track:7tqhbajSfrz2F7E1Z75ASX”,“play_origin”:“go-librespot”}}
Oct 03 13:33:10 main volumio[892]: SPOTIFY: PUSH STATE SPOTIFY
Oct 03 13:33:10 main volumio[892]: SPOTIFY: {“status”:“pause”,“service”:“spop”,“title”:“Ain’t No Mountain High Enough”,“artist”:“Marvin Gaye, Tammi Terrell”,“album”:“United”,“albumart”:“https://i.scdn.co/image/ab67616d00001e029173e50e99bdea2400222f02",“uri”:“spotify:track:7tqhbajSfrz2F7E1Z75ASX”,“trackType”:“spotify”,“seek”:26000,“duration”:151,“samplerate”:"44.1 KHz”,“bitdepth”:“16 bit”,“bitrate”:“320 kbps”,“codec”:“ogg”,“channels”:2,“random”:null,“repeat”:null,“repeatSingle”:null}
Oct 03 13:33:10 main volumio[892]: info: CoreCommandRouter::servicePushState
Oct 03 13:33:10 main volumio[892]: info: CorePlayQueue::getTrack 11
Oct 03 13:33:10 main volumio[892]: verbose: STATE SERVICE {“status”:“pause”,“service”:“spop”,“title”:“Ain’t No Mountain High Enough”,“artist”:“Marvin Gaye, Tammi Terrell”,“album”:“United”,“albumart”:“https://i.scdn.co/image/ab67616d00001e029173e50e99bdea2400222f02",“uri”:“spotify:track:7tqhbajSfrz2F7E1Z75ASX”,“trackType”:“spotify”,“seek”:26000,“duration”:151,“samplerate”:"44.1 KHz”,“bitdepth”:“16 bit”,“bitrate”:“320 kbps”,“codec”:“ogg”,“channels”:2,“random”:null,“repeat”:null,“repeatSingle”:null}
Oct 03 13:33:10 main volumio[892]: verbose: CURRENT POSITION 11
Oct 03 13:33:10 main volumio[892]: info: CoreStateMachine::syncState stateService pause
Oct 03 13:33:10 main volumio[892]: info: CoreStateMachine::syncState currentStatus pause
Oct 03 13:33:10 main volumio[892]: info: CoreStateMachine::pushState
Oct 03 13:33:10 main volumio[892]: info: CorePlayQueue::getTrack 11
Oct 03 13:33:10 main volumio[892]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Oct 03 13:33:10 main volumio[892]: info: CoreCommandRouter::volumioPushState
Oct 03 13:33:10 main volumio[892]: info: CoreStateMachine::stPlaybackTimer
Oct 03 13:33:10 main volumio[892]: SPOTIFY: RECEIVED VOLUMIO VOLUME 60

[TubularBells]

@sciensys

Oct 03 13:20:05 main go-librespot[3976]: time=“2024-10-03T13:20:05+03:00” level=debug msg=“put connect state because PLAYER_STATE_CHANGED”

I also noticed a lot of these messages on my own logs, with the same behavior, in between playback. And the same when tracks couldn’t be played and caused random skipping.

It seems it’s been addressed before when looking into go-librespot:

Some tracks do not play · Issue #55 · devgianlu/go-librespot · GitHub

Looks like these issues with the Spotify plugin haven’t been resolved yet.

[MP3Kitty]

Are you using USB DAC or Raspi heder attached DAC?
I only have a prob with Raspi DAC (PCM 5122).

[MP3Kitty]

I am not very good at reading those logs
All I can say is that the only prob I have with Volumio 3.742 + Spotify plugin 4.10
is PCM 5122 DAC. PCM 5102 DAC is working.

[TubularBells]

I’ve encountered the issues with both a BB/TI DSD1793 usb DAC and an I2S (hat) ESS ES9038Q2M, so I think it’s not related to a specific driver.

[sciensys]

yesterday I changed the playlist to another standard one recommended by Spotify,
and the plugin still plays without stopping!

I assume that the plugin playback stops may be directly related to the content itself, its codec, the presence of track information, and so on.
But this is not certain.

It would be nice, in case of such problems with content - just play the next track.
Now the playback just stops, but in the web interface the tracks change, without a working track time counter.

[sciensys]

I catched the plugin stop:

Oct 12 19:48:58 living go-librespot[1056]: time="2024-10-12T19:48:58+03:00" level=debug msg="created new output device"
Oct 12 19:48:58 living go-librespot[1056]: time="2024-10-12T19:48:58+03:00" level=info msg="loaded track \"What Lovers Do (feat. SZA)\" (paused: true, position: 0ms, duration: 199849ms, prefetched: false)" uri="spotify:track:0GxQ1A5L9xnMOytbP6eKBG"
Oct 12 19:48:58 living go-librespot[1056]: time="2024-10-12T19:48:58+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
Oct 12 19:48:58 living go-librespot[1056]: time="2024-10-12T19:48:58+03:00" level=trace msg="emitting websocket event: metadata"
Oct 12 19:48:58 living go-librespot[1056]: time="2024-10-12T19:48:58+03:00" level=trace msg="emitting websocket event: stopped"
Oct 12 19:48:58 living volumio[851]: SPOTIFY: received: {"type":"stopped","data":{"play_origin":"go-librespot"}}
Oct 12 19:48:58 living go-librespot[1056]: time="2024-10-12T19:48:58+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
Oct 12 19:48:58 living go-librespot[1056]: time="2024-10-12T19:48:58+03:00" level=trace msg="emitting websocket event: stopped"
Oct 12 19:48:58 living volumio[851]: SPOTIFY: received: {"type":"stopped","data":{"play_origin":"go-librespot"}}
Oct 12 19:48:58 living go-librespot[1056]: time="2024-10-12T19:48:58+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
Oct 12 19:48:58 living go-librespot[1056]: time="2024-10-12T19:48:58+03:00" level=trace msg="emitting websocket event: paused"

After that no sound, but tracks changing, no time counts

follow the full log, till was pressed “Play next track”, then you will see fetched chunks and music becomes playing.

Oct 12 19:48:58 living go-librespot[1056]: time="2024-10-12T19:48:58+03:00" level=debug msg="fetched chunk 2/16, size: 524288" uri="spotify:track:0GxQ1A5L9xnMOytbP6eKBG"
Oct 12 19:48:58 living go-librespot[1056]: time="2024-10-12T19:48:58+03:00" level=debug msg="fetched chunk 1/16, size: 524288" uri="spotify:track:0GxQ1A5L9xnMOytbP6eKBG"
Oct 12 19:48:58 living go-librespot[1056]: time="2024-10-12T19:48:58+03:00" level=debug msg="fetched chunk 3/16, size: 524288" uri="spotify:track:0GxQ1A5L9xnMOytbP6eKBG"
Oct 12 19:48:58 living go-librespot[1056]: time="2024-10-12T19:48:58+03:00" level=trace msg="cleared closed output device"
Oct 12 19:48:58 living go-librespot[1056]: time="2024-10-12T19:48:58+03:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 5102 us, period size = 225 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 98 frames"
Oct 12 19:48:58 living go-librespot[1056]: time="2024-10-12T19:48:58+03:00" level=debug msg="created new output device"
Oct 12 19:48:58 living go-librespot[1056]: time="2024-10-12T19:48:58+03:00" level=info msg="loaded track \"What Lovers Do (feat. SZA)\" (paused: true, position: 0ms, duration: 199849ms, prefetched: false)" uri="spotify:track:0GxQ1A5L9xnMOytbP6eKBG"
Oct 12 19:48:58 living go-librespot[1056]: time="2024-10-12T19:48:58+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
Oct 12 19:48:58 living go-librespot[1056]: time="2024-10-12T19:48:58+03:00" level=trace msg="emitting websocket event: metadata"
Oct 12 19:48:58 living go-librespot[1056]: time="2024-10-12T19:48:58+03:00" level=trace msg="emitting websocket event: stopped"
Oct 12 19:48:58 living volumio[851]: SPOTIFY: received: {"type":"stopped","data":{"play_origin":"go-librespot"}}
Oct 12 19:48:58 living go-librespot[1056]: time="2024-10-12T19:48:58+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
Oct 12 19:48:58 living go-librespot[1056]: time="2024-10-12T19:48:58+03:00" level=trace msg="emitting websocket event: stopped"
Oct 12 19:48:58 living volumio[851]: SPOTIFY: received: {"type":"stopped","data":{"play_origin":"go-librespot"}}
Oct 12 19:48:58 living go-librespot[1056]: time="2024-10-12T19:48:58+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
Oct 12 19:48:58 living go-librespot[1056]: time="2024-10-12T19:48:58+03:00" level=trace msg="emitting websocket event: paused"
Oct 12 19:48:58 living volumio[851]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:0GxQ1A5L9xnMOytbP6eKBG","play_origin":"go-librespot"}}
Oct 12 19:52:40 living go-librespot[1056]: time="2024-10-12T19:52:40+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
Oct 12 19:56:17 living go-librespot[1056]: time="2024-10-12T19:56:17+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
Oct 12 19:59:58 living go-librespot[1056]: time="2024-10-12T19:59:58+03:00" level=debug msg="resolved context of track" uri="spotify:track:5MqFJxMwbZ5nyNogTDVTeL"
Oct 12 19:59:58 living go-librespot[1056]: time="2024-10-12T19:59:58+03:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:5MqFJxMwbZ5nyNogTDVTeL"
Oct 12 19:59:58 living go-librespot[1056]: time="2024-10-12T19:59:58+03:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:5MqFJxMwbZ5nyNogTDVTeL"
Oct 12 19:59:58 living go-librespot[1056]: time="2024-10-12T19:59:58+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
Oct 12 19:59:58 living go-librespot[1056]: time="2024-10-12T19:59:58+03:00" level=trace msg="emitting websocket event: will_play"
Oct 12 19:59:58 living volumio[851]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:5MqFJxMwbZ5nyNogTDVTeL","play_origin":"go-librespot"}}
Oct 12 19:59:58 living go-librespot[1056]: time="2024-10-12T19:59:58+03:00" level=debug msg="selected format OGG_VORBIS_320 (2aeb773fcb588ce3bc7b262ac72607b53b2c47b6)" uri="spotify:track:5MqFJxMwbZ5nyNogTDVTeL"
Oct 12 19:59:58 living go-librespot[1056]: time="2024-10-12T19:59:58+03:00" level=debug msg="requested aes key for file 2aeb773fcb588ce3bc7b262ac72607b53b2c47b6, gid: 5MqFJxMwbZ5nyNogTDVTeL"
Oct 12 19:59:58 living go-librespot[1056]: time="2024-10-12T19:59:58+03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1730"
Oct 12 19:59:58 living go-librespot[1056]: time="2024-10-12T19:59:58+03:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update
Oct 12 19:59:58 living go-librespot[1056]: time="2024-10-12T19:59:58+03:00" level=debug msg="fetched first chunk of 18, total size is 9222612 bytes" uri="spotify:track:5MqFJxMwbZ5nyNogTDVTeL"
Oct 12 19:59:58 living go-librespot[1056]: time="2024-10-12T19:59:58+03:00" level=trace msg="seek to 0ms (diff: 0ms, samples: 0, bytes: 0)" uri="spotify:track:5MqFJxMwbZ5nyNogTDVTeL"
Oct 12 19:59:58 living go-librespot[1056]: time="2024-10-12T19:59:58+03:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 5102 us, period size = 225 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 98 frames"
Oct 12 19:59:58 living go-librespot[1056]: time="2024-10-12T19:59:58+03:00" level=info msg="loaded track \"(I Just) Died In Your Arms (Original Radio Edit)\" (paused: false, position: 0ms, duration: 215109ms, prefetched: false)" uri="spotify:track:5MqFJxMwbZ5nyNogTDVTeL"
Oct 12 19:59:58 living go-librespot[1056]: time="2024-10-12T19:59:58+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
Oct 12 19:59:58 living go-librespot[1056]: time="2024-10-12T19:59:58+03:00" level=debug msg="fetched chunk 2/17, size: 524288" uri="spotify:track:5MqFJxMwbZ5nyNogTDVTeL"
Oct 12 19:59:58 living go-librespot[1056]: time="2024-10-12T19:59:58+03:00" level=trace msg="scheduling prefetch in 185s"
Oct 12 19:59:58 living go-librespot[1056]: time="2024-10-12T19:59:58+03:00" level=trace msg="emitting websocket event: metadata"
Oct 12 19:59:58 living go-librespot[1056]: time="2024-10-12T19:59:58+03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 241"
Oct 12 19:59:58 living go-librespot[1056]: time="2024-10-12T19:59:58+03:00" level=debug msg="fetched chunk 3/17, size: 524288" uri="spotify:track:5MqFJxMwbZ5nyNogTDVTeL"
Oct 12 19:59:58 living go-librespot[1056]: time="2024-10-12T19:59:58+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
Oct 12 19:59:58 living go-librespot[1056]: time="2024-10-12T19:59:58+03:00" level=trace msg="emitting websocket event: playing"
Oct 12 19:59:58 living volumio[851]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:5MqFJxMwbZ5nyNogTDVTeL","play_origin":"go-librespot"}}
Oct 12 19:59:58 living go-librespot[1056]: time="2024-10-12T19:59:58+03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1726"
Oct 12 19:59:58 living go-librespot[1056]: time="2024-10-12T19:59:58+03:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update
Oct 12 19:59:58 living go-librespot[1056]: time="2024-10-12T19:59:58+03:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update
Oct 12 19:59:58 living go-librespot[1056]: time="2024-10-12T19:59:58+03:00" level=debug msg="fetched chunk 1/17, size: 524288" uri="spotify:track:5MqFJxMwbZ5nyNogTDVTeL"
Oct 12 19:59:59 living go-librespot[1056]: time="2024-10-12T19:59:59+03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1324"
Oct 12 19:59:59 living go-librespot[1056]: time="2024-10-12T19:59:59+03:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update
Oct 12 20:00:10 living go-librespot[1056]: time="2024-10-12T20:00:10+03:00" level=debug msg="fetched chunk 4/17, size: 524288" uri="spotify:track:5MqFJxMwbZ5nyNogTDVTeL"
Oct 12 20:00:22 living go-librespot[1056]: time="2024-10-12T20:00:22+03:00" level=debug msg="fetched chunk 5/17, size: 524288" uri="spotify:track:5MqFJxMwbZ5nyNogTDVTeL"

[sciensys]

I started playing the next…
and after a while I see the following:

time=“2024-10-12T20:12:04+03:00” level=debug msg=“handling pause player command from f31797b295a4877779106bc88a9f72e4cb409336”

how do I understand this?
all the devices I use to control Volumio are lying nearby!
Someone is pressing pause? Who?

Oct 12 20:12:04 living volumio[851]: SPOTIFY: received: {“type”:“paused”,“data”:{“uri”:“spotify:track:6e0LjNPkRqxIAlmmdjWSV8”,“play_origin”:“go-librespot”}}

Oct 12 20:10:52 living go-librespot[1056]: time="2024-10-12T20:10:52+03:00" level=debug msg="fetched chunk 4/21, size: 524288" uri="spotify:track:6e0LjNPkRqxIAlmmdjWSV8"
Oct 12 20:11:05 living go-librespot[1056]: time="2024-10-12T20:11:05+03:00" level=debug msg="fetched chunk 5/21, size: 524288" uri="spotify:track:6e0LjNPkRqxIAlmmdjWSV8"
Oct 12 20:11:18 living go-librespot[1056]: time="2024-10-12T20:11:18+03:00" level=debug msg="fetched chunk 6/21, size: 524288" uri="spotify:track:6e0LjNPkRqxIAlmmdjWSV8"
Oct 12 20:11:30 living go-librespot[1056]: time="2024-10-12T20:11:30+03:00" level=debug msg="fetched chunk 7/21, size: 524288" uri="spotify:track:6e0LjNPkRqxIAlmmdjWSV8"
Oct 12 20:11:42 living go-librespot[1056]: time="2024-10-12T20:11:42+03:00" level=debug msg="fetched chunk 8/21, size: 524288" uri="spotify:track:6e0LjNPkRqxIAlmmdjWSV8"
Oct 12 20:11:54 living go-librespot[1056]: time="2024-10-12T20:11:54+03:00" level=debug msg="fetched chunk 9/21, size: 524288" uri="spotify:track:6e0LjNPkRqxIAlmmdjWSV8"
Oct 12 20:12:04 living go-librespot[1056]: time="2024-10-12T20:12:04+03:00" level=debug msg="handling pause player command from f31797b295a4877779106bc88a9f72e4cb409336"
Oct 12 20:12:04 living go-librespot[1056]: time="2024-10-12T20:12:04+03:00" level=debug msg="pause track at 85221ms"
Oct 12 20:12:04 living go-librespot[1056]: time="2024-10-12T20:12:04+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
Oct 12 20:12:04 living go-librespot[1056]: time="2024-10-12T20:12:04+03:00" level=debug msg="sending successful reply for dealer request"
Oct 12 20:12:04 living go-librespot[1056]: time="2024-10-12T20:12:04+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
Oct 12 20:12:04 living go-librespot[1056]: time="2024-10-12T20:12:04+03:00" level=trace msg="emitting websocket event: paused"
Oct 12 20:12:04 living volumio[851]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:6e0LjNPkRqxIAlmmdjWSV8","play_origin":"go-librespot"}}
bash-5.0# journalctl -f
-- Logs begin at Sat 2024-10-12 03:32:49 +03. --
Oct 12 20:12:04 living volumio[851]: info: CoreCommandRouter::servicePushState
Oct 12 20:12:04 living volumio[851]: info: CorePlayQueue::getTrack 95
Oct 12 20:12:04 living volumio[851]: verbose: STATE SERVICE {"status":"pause","service":"spop","title":"Moi... Lolita","artist":"Alizée","album":"Gourmandises","albumart":"https://i.scdn.co/image/ab67616d00001e0270e4990047a33f297882afe9","uri":"spotify:track:6e0LjNPkRqxIAlmmdjWSV8","trackType":"spotify","seek":85000,"duration":264,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null}
Oct 12 20:12:04 living volumio[851]: verbose: CURRENT POSITION 95
Oct 12 20:12:04 living volumio[851]: info: CoreStateMachine::syncState   stateService pause
Oct 12 20:12:04 living volumio[851]: info: CoreStateMachine::syncState   currentStatus play
Oct 12 20:12:04 living volumio[851]: info: CoreStateMachine::pushState
Oct 12 20:12:04 living volumio[851]: info: CorePlayQueue::getTrack 95
Oct 12 20:12:04 living volumio[851]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Oct 12 20:12:04 living volumio[851]: info: CoreCommandRouter::volumioPushState

[devgianlu]

@sciensys The playback pausing randomly does not seem to be an issue with go-librespot, but it may be with Volumio plugin.

The tracks not playing issue is very weird because since the first report I have never encountered the issue myself. This could rather be an issue related to the the network which might have been fixed with this commit.

[TubularBells]

Hi. Here’s a way you may try to replicate the issue with tracks not playing, on this link to a post of mine on another thread:

New 2023 Spotify Plugin

Hello, I’ve managed to replicate the track skipping error in albums or playlists with the 4.1.1 plugin. This is using Volumio’s latest version, 3.757. In this situation, I was playing the “Songs to test headphones with” playlist, here: The playlist was going fine, until it switched to the 48th track, “Golden” by Jill Scott: It skipped to Solsbury Hill by Peter Gabriel. And no matter how many times I tried to play the track via Spotify Connect, it would revert to Solsbury Hill. This is wh…

There are many songs/entries within this Spotify playlist:

that produce this specific error from Librespot:

time=“2024-10-09T10:09:13-05:00” level=warning msg=“failed seeking to track in context spotify:playlist:37i9dQZF1DWZtZ8vUCzche” error=“could not find track”

@devgianlu Please let me know if you’re able to track it. For example, this song:

also presents the same error but, somehow, can be played from the actual album even though the desktop and mobile apps indicate that the track isn’t available and a random network issue.

As mentioned in the other thread, it is only Volumio that is presenting the issue. Other systems that are on the same network - like an AVR, for example, or another brand’s streamer - can play the full list with no problems.

[TubularBells]

Could this behavior be similar to what’s reported in this bug/issue report?

Can't jump to specific track in playlist

@devgianlu

[michel8166]

may not be exactly the same problem but I have a streamer here running on picoreplayer and every now and then I experience the same problem with spotify and fast forwarding to the next song and no control anymore.
the only solution is to reboot.

[Wheaten]

yes, it’s not restricted to Volumio. It happens also with piCore, LMS to name a few.
You do have some influence by not skipping tracks too fast. if you skip, wait for Spotify to load the track, then skip to the next track.
Not ideal but more stable.