Partly losing control from Spotify to Volumio Connect2 plugin

mxjelle · December 3, 2020, 5:08pm

Hi all.

I just installed my first Volumio setup the other day, and I must say that I am blown away by the audio performance of this setup! This is MUCH better than using spotify from my win 10 PC in every way! Fantastic!

I am using the Volumio Spotify Connect2 plugin, however I am partly loosing control from the Spotify app on my PC and android devices. I am connected, everything plays and works and suddently after some time (maybe 15 min max) I cannot change to specific songs on my playlist by tapping them in the playlist anymore. Everything else seems to keep working. Play/pause, next/previous song, volume skipping into the song with the pull-bar and so on, all keeps working from spotify, it is only the “push to play” feature with stops working. I also have fine connection from Volumio to pause, skip and so on, and Spotify follows in sync as it is supposed to. So I have only lost the “tab to play” feature from my “control devices”.

One thing I have noted is, that if I inside Spotify opens the device list when this happens, it states that “This computer” is now a Spotify Connect device. “Listening on” is stated as Volumio as expected. But in some way, it seems like the Volumio connect device is confused/mixed with “This computer” and maybe this is the cause of the above stated problem.

It does not help to go back and play on "this computer"and reconnect to Volumio. The only thing which solves this problem is a Volumio reboot.

My setup:

Raspberry pi 3 - original PSU running on Wi-Fi.
SD card image made with Etcher.
Volumio v2.853 - I have tried to burn a fresh image to the SD card multiple times.
Volumio Spotify Connect2 plugin installed from the plugin management through the webUI. v1.0.5.
Spotify premium account
PC spotify version 1.1.47.684.g136419d9, but this also happened before updating to this version previoursly today.
Teralink x2 USB to coax conveter.

I really hope someone can help me with this problem, as Volumio seems awesome in every way expect from this bug.

Feel free to guide me to pull out logs and what else is necessary for helping with this problem.

Regards
Jesper

mxjelle · December 3, 2020, 5:20pm

I just found another thing which maybe can lead to the root cause.

I have been playing with my PC as controller for some time, and then shuts it down, in order to keep controlling my music from my android phone. I open the spotify app and press keep playing on Volumio and the status of the “current playing” is wrong. I am pretty sure it is still showing the song, where the problem occoured, and the “current time” of the song had parsed an hour and keep counting, even though the song is only 3.x minuttes long. So in some way, it might be “locked” to this song some where in the code.

ashthespy · December 4, 2020, 3:46pm

It sounds like Spotify might have changed their protocol yet again, and we need to reverse engineer things. But, haven’t heard rumblings from others yet, soo it could also be something else

So, could you share some logs?

Either from the /dev page using the livelog feature or via ssh.

# Volumio logs
journalctl -f 
# vollibrespot logs
journalctl -f -o cat -u volspotconnect2.service

Note you might need sudo before these commands depending on the version of Volumio your running

Ideally, try and minimise the noise by grabbing the logs when you notice your issues…

mxjelle · December 6, 2020, 8:31am

Thanks ashthespy, here is the log. This time I could not “press to play” a track rigth from the beginning, but just pressing play started playing where i left off last time:

Starting Live Log...
info: CoreCommandRouter::executeOnPlugin: system , enableLiveLog
info: Launching a new LiveLog session
info: Live Log process terminated: null
info: CALLMETHOD: system_controller system enableLiveLog false
info: CoreCommandRouter::executeOnPlugin: system , enableLiveLog
info: Launching a new LiveLog session
wlan0: Failed to initiate sched scan
info: CALLMETHOD: system_controller system enableLiveLog true
info: CoreCommandRouter::executeOnPlugin: system , enableLiveLog
info: Launching a new LiveLog session
wlan0: Failed to initiate sched scan
wlan0: Failed to initiate sched scan
wlan0: Failed to initiate sched scan
[Vollibrespot] : Connecting to AP "gew1-accesspoint-b-hfcq.ap.spotify.com:443"
[Vollibrespot] : Authenticated as "1110728370" !
[Vollibrespot] : Setting up new mixer: card:hw:5 mixer:PCM index:0
[Vollibrespot] : Alsa min-db is not SND_CTL_TLV_DB_GAIN_MUTE!!
[Vollibrespot] : Alsa Mixer info min: 0 (MilliBel(-5500)[dB]) -- max: 110 (MilliBel(0)[dB]) HW: true
[Vollibrespot] : Alsa min-db is not SND_CTL_TLV_DB_GAIN_MUTE!!
[Vollibrespot] : Using alsa sink
[Vollibrespot] : Metadata pipe established
[Vollibrespot] : Country: "DK"
[Vollibrespot] : Event: Volume { volume_to_mixer: 65535 }
[SpotifyConnect]  100
[SpotifyConnect] Volume: Spotify:100 Volumio: 100
info: CoreStateMachine::pushState
info: CorePlayQueue::getTrack 0
info: CoreCommandRouter::volumioPushState
info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
[Vollibrespot] : Fetching autoplay context uri
[Vollibrespot] : Event: SessionActive { became_active_at: 1607206632726 }
[Vollibrespot] : SessionActive!
[Vollibrespot] : Event: PlaybackStarted { track_id: SpotifyId { id: 178351449040151128206985408278749626771, audio_type: Track } }
[Vollibrespot] : Event: PlaybackLoading { track_id: SpotifyId { id: 178351449040151128206985408278749626771, audio_type: Track } }
[SpotifyConnect]  A connect session has begun
[SpotifyConnect]  Device palyback is active!
info: CoreCommandRouter::volumioGetState
info: CorePlayQueue::getTrack 0
[SpotifyConnect] Currently active: mpd
[SpotifyConnect] Stopping currently active service
info: CoreCommandRouter::volumioStop
info: CoreStateMachine::stop
info: CoreStateMachine::setConsumeUpdateService undefined
UNSET VOLATILE
[SpotifyConnect] Vollibrespot Active
info: CoreCommandRouter::volumioGetState
info: CorePlayQueue::getTrack 0
[SpotifyConnect] Currently active: mpd
[SpotifyConnect] Setting Volatile state to Volspotconnect2
info: CoreStateMachine::setConsumeUpdateService undefined
info: CoreCommandRouter::servicePushState
info: CoreStateMachine::pushState
info: CoreCommandRouter::volumioPushState
info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
info: CoreCommandRouter::volumioGetState
[SpotifyConnect] Currently active: volspotconnect2
[SpotifyConnect] Pushing new state :: true
info: CoreCommandRouter::servicePushState
info: CoreStateMachine::pushState
info: CoreCommandRouter::volumioPushState
info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
[Vollibrespot] : Autoplay uri resolved to <"spotify:station:user:1110728370:playlist:2uEjoqvU4yyNOJJS6zFg0q">
[Vollibrespot] : Resolving uri "spotify:station:user:1110728370:playlist:2uEjoqvU4yyNOJJS6zFg0q"
[Vollibrespot] : Loading  with Spotify URI 
[Vollibrespot] : Event: GotToken { token: Token { access_token: "BQB9giVDZsq72xolFmYdEa0WHcB1JqZUO6aEg-sdeEZd0v1ICIDKSargNpzmJm3fRFHfK8ygcH-tubXZr3ENJrn3WRkMnzCPPYi8czm57nmtXDrfC9puQnZ0v84Abo3BN02aor6_oUL4MUXAwVYTjMIQiQ5dSCNrou5nfg", expires_in: 3600, token_type: "Bearer", scope: ["streaming", "user-read-playback-state", "user-modify-playback-state", "user-read-currently-playing", "user-read-private"] } }
[SpotifyConnect]  BQB9giVDZsq72xolFmYdEa0WHcB1JqZUO6aEg-sdeEZd0v1ICIDKSargNpzmJm3fRFHfK8ygcH-tubXZr3ENJrn3WRkMnzCPPYi8czm57nmtXDrfC9puQnZ0v84Abo3BN02aor6_oUL4MUXAwVYTjMIQiQ5dSCNrou5nfg
[SpotifyConnect] Setting VLS device_id: c6e56cf6b68c07041768b06e2f29a439e7724b0e
[Vollibrespot] : Resolved 50 tracks from <"spotify:user:1110728370:playlist:2uEjoqvU4yyNOJJS6zFg0q">
[Vollibrespot] :  (169265 ms) loaded
[Vollibrespot] : Event: PlaybackStopped { track_id: SpotifyId { id: 178351449040151128206985408278749626771, audio_type: Track } }
[SpotifyConnect]  Device palyback is inactive
[SpotifyConnect] Device Session is_active: true
wlan0: Failed to initiate sched scan
wlan0: Failed to initiate sched scan
wlan0: Failed to initiate sched scan
wlan0: Failed to initiate sched scan
wlan0: Failed to initiate sched scan
wlan0: Failed to initiate sched scan
wlan0: Failed to initiate sched scan
wlan0: Failed to initiate sched scan
wlan0: Failed to initiate sched scan
wlan0: Failed to initiate sched scan
wlan0: Failed to initiate sched scan
wlan0: Failed to initiate sched scan
wlan0: Failed to initiate sched scan
wlan0: Failed to initiate sched scan
wlan0: Failed to initiate sched scan
wlan0: Failed to initiate sched scan
wlan0: Failed to initiate sched scan
wlan0: Failed to initiate sched scan
wlan0: Failed to initiate sched scan
wlan0: Failed to initiate sched scan
wlan0: Failed to initiate sched scan
wlan0: Failed to initiate sched scan
wlan0: Failed to initiate sched scan
wlan0: Failed to initiate sched scan
[Vollibrespot] : Event: Play { track_id: SpotifyId { id: 178351449040151128206985408278749626771, audio_type: Track }, position_ms: 6770 }
[SpotifyConnect]  play
[Vollibrespot] : Event: SinkActive
[SpotifyConnect]  you broke me first
[SpotifyConnect] Pushing metadata
info: CoreCommandRouter::volumioGetState
[SpotifyConnect] Currently active: volspotconnect2
[SpotifyConnect] Pushing new state :: true
info: CoreCommandRouter::servicePushState
info: CoreStateMachine::pushState
info: CoreCommandRouter::volumioPushState
info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
[SpotifyConnect]  Sink acquired
info: CoreCommandRouter::volumioGetState
[SpotifyConnect] Currently active: volspotconnect2
[SpotifyConnect] Pushing new state :: true
info: CoreCommandRouter::servicePushState
info: CoreStateMachine::pushState
info: CoreCommandRouter::volumioPushState
info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
wlan0: Failed to initiate sched scan

This time i also had a problem with getting volumio started. It took 4-5 power cycles before at actually started and I could connect to it through the webUI. I was also not able to get it on Wi-Fi and had to plug in an ethernet cable. This is also clearly seen in the logs.

mxjelle · December 10, 2020, 4:50pm

Due to the booting problems, I have now used another SD card. New download og the Volumio image and clean format and flash of the image. I am also only using lan now, and no wifi. Straight away i was not able to “tab to play” songs in Spotify. Nothing is even registrerer in the live log, no event or anything, but the livelog updated nicely when skipping to next track and other working functionalities.

Starting Live Log...
info: CoreCommandRouter::executeOnPlugin: system , getShowWizard
info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings
info: CoreCommandRouter::volumioGetState
info: CoreCommandRouter::volumioGetQueue
info: CoreStateMachine::getQueue
info: CorePlayQueue::getQueue
info: CoreCommandRouter::executeOnPlugin: system , getHwuuid
info: CALLMETHOD: system_controller system enableLiveLog true
info: CoreCommandRouter::executeOnPlugin: system , enableLiveLog
info: Launching a new LiveLog session
[Vollibrespot] : Event: SessionInactive { became_inactive_at: 1607615577919 }
[Vollibrespot] : Event: PlaybackStopped { track_id: SpotifyId { id: 128065648340621942603361025372174951577, audio_type: Track } }
[SpotifyConnect]  Connect Session has ended
[SpotifyConnect] Relinquishing Volumio State
UNSET VOLATILE
[SpotifyConnect] unSetVolatile called
[SpotifyConnect] Relinquishing Volumio State to another service
[SpotifyConnect] Received stop
info: CoreStateMachine::resetVolumioState
info: CoreStateMachine::getcurrentVolume
info: CoreCommandRouter::volumioRetrievevolume
info: CoreStateMachine::pushState
info: CorePlayQueue::getTrack 0
info: CoreCommandRouter::volumioPushState
info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
[SpotifyConnect]  Device palyback is inactive
[SpotifyConnect] Device is paused
[Vollibrespot] : Pause
[SpotifyConnect]  Pause
[Vollibrespot] : Event: SessionActive { became_active_at: 1607615580164 }
[Vollibrespot] : SessionActive!
[Vollibrespot] : Fetching autoplay context uri
[SpotifyConnect]  A connect session has begun
[Vollibrespot] : Event: PlaybackStarted { track_id: SpotifyId { id: 128065648340621942603361025372174951577, audio_type: Track } }
[Vollibrespot] : Event: PlaybackLoading { track_id: SpotifyId { id: 128065648340621942603361025372174951577, audio_type: Track } }
[SpotifyConnect]  Device palyback is active!
info: CoreCommandRouter::volumioGetState
info: CorePlayQueue::getTrack 0
[SpotifyConnect] Currently active: mpd
[SpotifyConnect] Stopping currently active service
info: CoreCommandRouter::volumioStop
info: CoreStateMachine::stop
info: CoreStateMachine::setConsumeUpdateService undefined
UNSET VOLATILE
[SpotifyConnect] Vollibrespot Active
info: CoreCommandRouter::volumioGetState
info: CorePlayQueue::getTrack 0
[SpotifyConnect] Currently active: mpd
[SpotifyConnect] Setting Volatile state to Volspotconnect2
info: CoreStateMachine::setConsumeUpdateService undefined
info: CoreCommandRouter::servicePushState
info: CoreStateMachine::pushState
info: CoreCommandRouter::volumioPushState
info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
info: CoreCommandRouter::volumioGetState
[SpotifyConnect] Currently active: volspotconnect2
[SpotifyConnect] Pushing new state :: true
info: CoreCommandRouter::servicePushState
info: CoreStateMachine::pushState
info: CoreCommandRouter::volumioPushState
info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
[Vollibrespot] : Autoplay uri resolved to <"spotify:station:user:1110728370:playlist:2uEjoqvU4yyNOJJS6zFg0q">
[Vollibrespot] : Resolving uri "spotify:station:user:1110728370:playlist:2uEjoqvU4yyNOJJS6zFg0q"
[Vollibrespot] : Event: GotToken { token: Token { access_token: "BQAlNH8zD_QzJDd3RHRpT3wz_Y8fNak4TWh4MjlA2E8iMtXV6CyMhZMzES7pfUYDB9eAippQV4YxCwgnOFC7P2NBdIroPLhEusjFh6THy-Q1idZJbJqUkA5ynKh5S6elrdrY29Zp9u9u0a6C5y-1vgGZoY5bit29NxePUA", expires_in: 3600, token_type: "Bearer", scope: ["streaming", "user-read-playback-state", "user-modify-playback-state", "user-read-currently-playing", "user-read-private"] } }
[Vollibrespot] : Loading  with Spotify URI 
[SpotifyConnect]  BQAlNH8zD_QzJDd3RHRpT3wz_Y8fNak4TWh4MjlA2E8iMtXV6CyMhZMzES7pfUYDB9eAippQV4YxCwgnOFC7P2NBdIroPLhEusjFh6THy-Q1idZJbJqUkA5ynKh5S6elrdrY29Zp9u9u0a6C5y-1vgGZoY5bit29NxePUA
[SpotifyConnect] Setting VLS device_id: c6e56cf6b68c07041768b06e2f29a439e7724b0e
[Vollibrespot] : Resolved 50 tracks from <"spotify:user:1110728370:playlist:2uEjoqvU4yyNOJJS6zFg0q">
[Vollibrespot] :  (211200 ms) loaded
[Vollibrespot] : Event: PlaybackStopped { track_id: SpotifyId { id: 128065648340621942603361025372174951577, audio_type: Track } }
[SpotifyConnect]  Device palyback is inactive
[SpotifyConnect] Device is paused
[Vollibrespot] : Event: Play { track_id: SpotifyId { id: 128065648340621942603361025372174951577, audio_type: Track }, position_ms: 40752 }
[SpotifyConnect]  play
[Vollibrespot] : Event: SinkActive
[SpotifyConnect]  Confessions Part II - Confessions Special Edition Version
[SpotifyConnect] Not pushing metadata: { active: true, isStopping: true }
[SpotifyConnect]  Sink acquired
info: CoreCommandRouter::volumioGetState
[SpotifyConnect] Currently active: volspotconnect2
[SpotifyConnect] Pushing new state :: true
info: CoreCommandRouter::servicePushState
info: CoreStateMachine::pushState
info: CoreCommandRouter::volumioPushState
info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
[Vollibrespot] : Event: Next { track_id: SpotifyId { id: 277766139657055844002905951918577409116, audio_type: Track } }
info: CoreCommandRouter::volumioGetState
info: CoreCommandRouter::volumioGetQueue
info: CoreStateMachine::getQueue
info: CorePlayQueue::getQueue
info: CoreCommandRouter::executeOnPlugin: system , getHwuuid
info: CoreCommandRouter::volumioGetState
info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom
[Vollibrespot] : Event: Next { track_id: SpotifyId { id: 130829602709436918889266842571688035939, audio_type: Track } }
[Vollibrespot] : Event: SinkInactive
[Vollibrespot] : Event: TrackChanged { old_track_id: SpotifyId { id: 277766139657055844002905951918577409116, audio_type: Track }, track_id: SpotifyId { id: 130829602709436918889266842571688035939, audio_type: Track } }
[SpotifyConnect]  Sink released
info: CoreCommandRouter::servicePushState
info: CoreStateMachine::pushState
info: CoreCommandRouter::volumioPushState
info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
[Vollibrespot] : Loading  with Spotify URI 
[Vollibrespot] :  (191493 ms) loaded
[Vollibrespot] : Event: PlaybackLoading { track_id: SpotifyId { id: 130829602709436918889266842571688035939, audio_type: Track } }
[Vollibrespot] : Event: SinkActive
[SpotifyConnect]  Supernova
[SpotifyConnect] Pushing metadata
info: CoreCommandRouter::volumioGetState
[SpotifyConnect] Currently active: volspotconnect2
[SpotifyConnect] Pushing new state :: true
info: CoreCommandRouter::servicePushState
info: CoreStateMachine::pushState
info: CoreCommandRouter::volumioPushState
info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
[SpotifyConnect]  Sink acquired
info: CoreCommandRouter::volumioGetState
[SpotifyConnect] Currently active: volspotconnect2
[SpotifyConnect] Pushing new state :: true
info: CoreCommandRouter::servicePushState
info: CoreStateMachine::pushState
info: CoreCommandRouter::volumioPushState
info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo

ashthespy · December 10, 2020, 7:03pm

@mxjelle Just to confirm what exactly do you mean by Tab to play? The logs show that the daemon didn’t receive any commands from Spotify’s servers.
You could check by tracking progress on a web browser with open.spotify.com - if that device receives your tab to play then we have to dig deeper into the protocol.

mxjelle · December 12, 2020, 1:35pm

@ashthespy By press to play i mean that i on a mobile device press a song name in a playlist or on PC double tabt the songname to play it. It however does no difference if a press the play button in front of the song.

I have some interesting news regarding your last post! If I use the webplayer and remote control it like i would with Volumio, i see the same problem! The press to play feature does not work on the webplayer, and it does not change song. I have further figured out, that the problem (both on the webplayer and on Volumio) only exists on my normal playlist. Every other playlist I have tried works! I guess it is a Spotify problem, as my normal playlist is a very big list of 8k+ songs, which i normally just press shuffle on.

I previuosly wrote that it worked for some time before it stopped, but I guess I just used other playlist for initial tests, before actually changing to the long one. So I it seems that the problem is out of your hands now and it is a Spotify problem. I’ll try to read a bit about it and if I do not find anything, I will create a bug at Spotify.

Thanks for your help!