[PLUGIN] Volspotconnect2 - SpotifyConnect for Volumio2

totyc · December 24, 2018, 8:55pm

Hi,

i have some founding …

When changing output device in volumio UI ( Playback Option / Output Device),
there is a need to “restart” VSC2, eg. ON->OFF->ON. In this case startconnect.sh will be correctly updated. If it is not correctly updated,
volspotconnect2 daemon will hang up in never ending loop …
The most safety way to have running VSC2 is next :
- STOP VSC2 plugin
- CHANGE OUTPUT device
- REBOOT
- START VSC2 plugin
Topping D30 USB DAC issue is probably related to “BAD” mixer-name ‘XMOS Clock Selector,1’. If i choose in output device ‘XMOS Clock Selector’ instead of ‘XMOS Clock Selector,1’ daemon works as expected.
Change plugin settings in UI ( volume level from 100% to 50%), after pressing SAVE, generate message “Configuration has been sucessfully updated”, but the volume level is still 100%.

here is : /data/plugins/music_service/volspotconnect2/startconnect.sh :

and here is the log sudo journalctl -f -o cat -u volspotconnect2.service :

[Vollibrespot] : Connecting to AP “gew1-accesspoint-b-d4sn.ap.spotify.com:4070”
[Vollibrespot] : Authenticated as “totyc” !
[Vollibrespot] : Setting up new mixer: card:hw:2 mixer:XMOS Clock Selector index:0
[Vollibrespot] : Alsa min: 0 (MilliBel(-12700)[dB]) – max: 127 (MilliBel(0)[dB]) HW: true
[Vollibrespot] : Alsa min-db is not SND_CTL_TLV_DB_GAIN_MUTE!!
[Vollibrespot] : Using alsa sink
[Vollibrespot] : Current alsa volume: 127[i64] MilliBel(0)
[Vollibrespot] : Mapping volume [100.000%] 65535 [u16] ->> Alsa [0.000%] 0 [dB]
[Vollibrespot] : Metadata pipe established
[Vollibrespot] : Country: “HU”
[Vollibrespot] : SessionActive!
[Vollibrespot] : Loading track “London Calling - Remastered” with Spotify URI “spotify:track:5jzma6gCzYtKB1DbEwFZKH”
[Vollibrespot] : Track “London Calling - Remastered” loaded

Merry Christmas !

ashthespy · December 25, 2018, 1:21pm

totyc:

Hi,

i have some founding …

When changing output device in volumio UI ( Playback Option / Output Device),
there is a need to “restart” VSC2, eg. ON->OFF->ON. In this case startconnect.sh will be correctly updated. If it is not correctly updated,
volspotconnect2 daemon will hang up in never ending loop …

I believe this is due to a current limitation with the way Volumio handles output devices, and keeping compatibility with balbuze other equaliser plugins. There is a manual timer. But yeah, it should trigger on an event, and not need manual intervention - will fix this!

The most safety way to have running VSC2 is next :

STOP VSC2 plugin

CHANGE OUTPUT device

REBOOT

START VSC2 plugin

Topping D30 USB DAC issue is probably related to “BAD” mixer-name ‘XMOS Clock Selector,1’. If i choose in output device ‘XMOS Clock Selector’ instead of ‘XMOS Clock Selector,1’ daemon works as expected.

Has this always been the case - or did this behaviour start only from the 2.513? While it would be easy to strip out the ,1 from the plugin, don’t want to add more spaghetti code, if its an error from elsewhere!

Change plugin settings in UI ( volume level from 100% to 50%), after pressing SAVE, generate message “Configuration has been sucessfully updated”, but the volume level is still 100%.

My mistake here

Merry Christmas !

exiton · March 14, 2019, 9:25pm

Had donated to volumio a long time ago and shelved it. Heard about your plugin when searching for a way to get spotify out of my windows machine via ASIO or similar. Fired up a raspberry pi again with the new volumio and installed your dev plugin. It works great! For Spotify premium subscribers, this is the killer app! Thank you so much!

danielfelix · August 4, 2020, 1:53am

In 80% of the cases to listen to Spotify via VSC2 I must restart Spotify and restart the VSC2 plugin. This has no solution? It also happens to them?
Use RPI3 + Volumio + Allo Boss + SimpleEq Plugin

ashthespy · August 4, 2020, 3:27pm

Could you share some logs?

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

# Volumio logs
journalctl -f -o cat
# 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

danielfelix · August 4, 2020, 10:18pm

Here the entire sequence:
1 - stop web radio
2 - start Spotify, Play
3 - does not work
4 - Close Spotify
5 - disable and re-enable the VolSpot plugin
6 - Start Spotify
7 - It works normally

Starting Live Log...
wlan0: CTRL-EVENT-DISCONNECTED bssid=3c:b7:4b:3a:4d:50 reason=7 locally_generated=1
wlan0: CTRL-EVENT-REGDOM-CHANGE init=CORE type=WORLD
wlan0: Trying to associate with SSID 'Mapear 2.4 GHz'
wlan0: Associated with 3c:b7:4b:3a:4d:50
wlan0: WPA: Key negotiation completed with 3c:b7:4b:3a:4d:50 [PTK=CCMP GTK=TKIP]
wlan0: CTRL-EVENT-CONNECTED - Connection to 3c:b7:4b:3a:4d:50 completed [id=0 id_str=]
wlan0: CTRL-EVENT-REGDOM-CHANGE init=COUNTRY_IE type=COUNTRY alpha2=AR
info: CALLMETHOD: system_controller system enableLiveLog true
info: CoreCommandRouter::executeOnPlugin: system , enableLiveLog
info: Launching a new LiveLog session
info: CoreCommandRouter::volumioGetState
info: CorePlayQueue::getTrack 0
info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom
info: Listing playlists
info: CoreCommandRouter::volumioGetQueue
info: CoreStateMachine::getQueue
info: CorePlayQueue::getQueue
info: CoreCommandRouter::volumioGetVisibleSources
info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
info: CoreCommandRouter::volumioPause
info: CoreStateMachine::pause
info: CoreStateMachine::stPlaybackTimer
info: CoreStateMachine::servicePause
info: CorePlayQueue::getTrack 0
info: CoreCommandRouter::servicePause

info:
---------------------------- MPD announces state update: player
info: ControllerMpd::getState

info: CorePlayQueue::getTrack 0
info: CoreCommandRouter::servicePushState
info: CorePlayQueue::getTrack 0


info: CoreStateMachine::syncState   stateService pause
info: CoreStateMachine::syncState   currentStatus pause
info: CoreStateMachine::pushState
info: CorePlayQueue::getTrack 0
info: CoreCommandRouter::volumioPushState
info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
info: CoreStateMachine::stPlaybackTimer
info:
---------------------------- MPD announces state update: player
info: ControllerMpd::getState







info: ControllerMpd::pushState
info: CoreCommandRouter::servicePushState
info: CorePlayQueue::getTrack 0
info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current radio_paradise Received mpd
info: ControllerMpd::pushState
info: CoreCommandRouter::servicePushState
info: CorePlayQueue::getTrack 0
info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current radio_paradise Received mpd
info: ------------------------------ 42ms
info: ------------------------------ 21ms
[Vollibrespot] : Connecting to AP "guc3-accesspoint-b-wdpz.ap.spotify.com:443"
[Vollibrespot] : Authenticated as "danielfelix" !
[Vollibrespot] : Setting up new mixer: card:hw:2 mixer:Digital index:0
[Vollibrespot] : Alsa Mixer info min: 0 (MilliBel(-9999999)[dB]) -- max: 207 (MilliBel(0)[dB]) HW: true
[Vollibrespot] : Using alsa sink
[Vollibrespot] : Metadata pipe established
[Vollibrespot] : Event: Volume { volume_to_mixer: 13107 }
[Vollibrespot] : Country: "AR"
[SpotifyConnect]  20
[SpotifyConnect] Volume: Spotify:20 Volumio: 20
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: 1596579087456 }
[Vollibrespot] : SessionActive!
[Vollibrespot] : Event: PlaybackStarted { track_id: SpotifyId { id: 181526245921843748686528109162483859992, audio_type: Track } }
[Vollibrespot] : Event: PlaybackLoading { track_id: SpotifyId { id: 181526245921843748686528109162483859992, audio_type: Track } }
[SpotifyConnect]  A connect session has begun
[SpotifyConnect]  Device palyback is active!
info: CoreCommandRouter::volumioGetState
info: CorePlayQueue::getTrack 0
[SpotifyConnect] Currently active: radio_paradise
[SpotifyConnect] Stopping currently active service
info: CoreCommandRouter::volumioStop
info: CoreStateMachine::stop
info: CoreStateMachine::setConsumeUpdateService undefined
UNSET VOLATILE
info: CoreStateMachine::updateTrackBlock
info: CorePlayQueue::getTrackBlock
info: CoreStateMachine::stPlaybackTimer
info: CoreStateMachine::pushState
info: CorePlayQueue::getTrack 0
info: CoreCommandRouter::volumioPushState
info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
info: CoreStateMachine::serviceStop
info: CorePlayQueue::getTrack 0
info: CoreCommandRouter::serviceStop
info: ControllerMpd::stop

info:
---------------------------- MPD announces state update: player
info: ControllerMpd::getState

info: CoreCommandRouter::servicePushState
info: CoreStateMachine::pushState
info: CorePlayQueue::getTrack 0
info: CoreCommandRouter::volumioPushState
info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
info: CorePlayQueue::getTrack 0


info: CoreStateMachine::syncState   stateService stop
info: CoreStateMachine::syncState   currentStatus stop
info: CoreStateMachine::pushState
info: CorePlayQueue::getTrack 0
info: CoreCommandRouter::volumioPushState
info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
info: No code
info: CoreStateMachine::pushState
info: CorePlayQueue::getTrack 0
info: CoreCommandRouter::volumioPushState
info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
[SpotifyConnect] Vollibrespot Active
info: CoreCommandRouter::volumioGetState
info: CorePlayQueue::getTrack 0
[SpotifyConnect] Currently active: radio_paradise
[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: CorePlayQueue::getTrack 0
info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current radio_paradise Received volspotconnect2
info: CoreCommandRouter::volumioGetState
[SpotifyConnect] Currently active: undefined
[SpotifyConnect] Pushing new state :: true
info: CoreCommandRouter::servicePushState
info: CoreStateMachine::pushState
info: CoreCommandRouter::volumioPushState
info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
info: CorePlayQueue::getTrack 0
info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current radio_paradise Received volspotconnect2


info:
---------------------------- MPD announces state update: player
info: ControllerMpd::getState




info: ControllerMpd::pushState
info: CoreCommandRouter::servicePushState
info: CoreStateMachine::pushState
info: CoreCommandRouter::volumioPushState
info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
info: CorePlayQueue::getTrack 0
info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current radio_paradise Received mpd
info: ------------------------------ 81ms

info: ControllerMpd::pushState
info: CoreCommandRouter::servicePushState
info: CoreStateMachine::pushState
info: CoreCommandRouter::volumioPushState
info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
info: CorePlayQueue::getTrack 0
info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current radio_paradise Received mpd
info: ------------------------------ 45ms
[Vollibrespot] : No autoplay_uri found
[Vollibrespot] : AutoplayError: MercuryError
[Vollibrespot] : Event: GotToken { token: Token { access_token: "BQCPebyLQxpHQ6SibGmaNKDiwBDTmCdsIi6V19xUOtaas1KZ-9j7ww8TSReKmsqPf5K8Mlc6UFJytaLBQX5hCy0fW3nPkhExOQvqxm1WYNRNA0cyIuhNzvGNS-bGkXfcLXwRcavd0cJthT-fIq78Tr_Ke1Xnp0wranDm-QM", expires_in: 3600, token_type: "Bearer", scope: ["streaming", "user-read-playback-state", "user-modify-playback-state", "user-read-currently-playing", "user-read-private"] } }
[SpotifyConnect]  BQCPebyLQxpHQ6SibGmaNKDiwBDTmCdsIi6V19xUOtaas1KZ-9j7ww8TSReKmsqPf5K8Mlc6UFJytaLBQX5hCy0fW3nPkhExOQvqxm1WYNRNA0cyIuhNzvGNS-bGkXfcLXwRcavd0cJthT-fIq78Tr_Ke1Xnp0wranDm-QM
[Vollibrespot] : Loading  with Spotify URI 
[SpotifyConnect] Setting VLS device_id: c6e56cf6b68c07041768b06e2f29a439e7724b0e
[Vollibrespot] :  (409640 ms) loaded
[Vollibrespot] : Event: PlaybackStopped { track_id: SpotifyId { id: 181526245921843748686528109162483859992, audio_type: Track } }
[SpotifyConnect]  Device palyback is inactive
[SpotifyConnect] Device Session is_active: true
[Vollibrespot] : Fetching autoplay context uri
[Vollibrespot] : Event: TrackChanged { old_track_id: SpotifyId { id: 181526245921843748686528109162483859992, audio_type: Track }, track_id: SpotifyId { id: 145388607699475846999067032348438672553, audio_type: Track } }
[Vollibrespot] : No autoplay_uri found
[Vollibrespot] : AutoplayError: MercuryError
[Vollibrespot] : Loading  with Spotify URI 
[Vollibrespot] :  (206800 ms) loaded
[Vollibrespot] : Alsa error PCM open ALSA function 'snd_pcm_open' failed with error 'EBUSY: Device or resource busy'
[Vollibrespot] : Could not start audio: Alsa error: PCM open failed
[Vollibrespot] : Alsa error PCM open ALSA function 'snd_pcm_open' failed with error 'EBUSY: Device or resource busy'
[Vollibrespot] : Could not start audio: Alsa error: PCM open failed
[Vollibrespot] : Alsa error PCM open ALSA function 'snd_pcm_open' failed with error 'EBUSY: Device or resource busy'
[Vollibrespot] : Could not start audio: Alsa error: PCM open failed
thread '' panicked at 'called `Option::unwrap()` on a `None` value', /build/cache/git/checkouts/librespot-6f197fd632ef9380/659de68/playback/src/audio_backend/alsa.rs:128:19
stack backtrace:
0:   0xad1828 - backtrace::backtrace::libunwind::trace::h100c6c70e4af496c
at /cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.40/src/backtrace/libunwind.rs:88
1:   0xad1828 - backtrace::backtrace::trace_unsynchronized::hf78ddc194bf45009
at /cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.40/src/backtrace/mod.rs:66
2:   0xad1828 - std::sys_common::backtrace::_print_fmt::h967a212a8894e4a4
at src/libstd/sys_common/backtrace.rs:77
3:   0xad1828 - ::fmt::h5fe383ce2118859a
at src/libstd/sys_common/backtrace.rs:59
4:   0xaed03c - core::fmt::write::h937f59172f6eeeaf
at src/libcore/fmt/mod.rs:1052
5:   0xacb6ec - std::io::Write::write_fmt::hc70e2634948b89c8
at src/libstd/io/mod.rs:1426
6:   0xad3cf0 - std::sys_common::backtrace::_print::hbfc81757b29a60f4
at src/libstd/sys_common/backtrace.rs:62
7:   0xad3cf0 - std::sys_common::backtrace::print::h8bc349c117633211
at src/libstd/sys_common/backtrace.rs:49
8:   0xad3cf0 - std::panicking::default_hook::{{closure}}::h82c47dcbb8503118
at src/libstd/panicking.rs:204
9:   0xad3964 - std::panicking::default_hook::hc04800be16711189
at src/libstd/panicking.rs:224
10:   0xad43a0 - std::panicking::rust_panic_with_hook::h2413ff75e44cd581
at src/libstd/panicking.rs:472
11:   0xad3fb4 - rust_begin_unwind
at src/libstd/panicking.rs:380
12:   0xaeaaa8 - core::panicking::panic_fmt::h2c56481ca2ee7c2f
at src/libcore/panicking.rs:85
13:   0xaeaa04 - core::panicking::panic::h858859fb9e6c3f07
at src/libcore/panicking.rs:52
14:   0x69bf40 - ::write::h72619216e3588ead
15:   0x676e38 - ::poll::h8c3aa347eb5050fe
16:   0x578b0c - futures::task_impl::std::set::h959dffae037fa8a9
17:   0x573048 - futures::task_impl::Spawn::poll_future_notify::h3ba01a9dfc1d022c
18:   0x57f6d4 - std::sys_common::backtrace::__rust_begin_short_backtrace::h53457226459490b1
19:   0x590e08 - std::panicking::try::do_call::h3a2683b9b75c33db
20:   0xad85f8 - __rust_maybe_catch_panic
at src/libpanic_unwind/lib.rs:86
21:   0x591140 - core::ops::function::FnOnce::call_once{{vtable.shim}}::he4fab1c16e3e7b3d
22:   0xac4488 -  as core::ops::function::FnOnce>::call_once::h0eb934bdc214e7b7
at /rustc/b8cedc00407a4c56a3bda1ed605c6fc166655447/src/liballoc/boxed.rs:1015
23:   0xad78f8 -  as core::ops::function::FnOnce>::call_once::h4eeee9ec160fd74c
at /rustc/b8cedc00407a4c56a3bda1ed605c6fc166655447/src/liballoc/boxed.rs:1015
24:   0xad78f8 - std::sys_common::thread::start_thread::hd648575d6de17db0
at src/libstd/sys_common/thread.rs:13
25:   0xad78f8 - std::sys::unix::thread::Thread::new::thread_start::hc1903f20153f9439
at src/libstd/sys/unix/thread.rs:80
[Vollibrespot] : Event: PlaybackLoading { track_id: SpotifyId { id: 145388607699475846999067032348438672553, audio_type: Track } }
[SpotifyConnect]  Apenas Floto
[SpotifyConnect] Pushing metadata
info: CoreCommandRouter::volumioGetState
[SpotifyConnect] Currently active: undefined
[SpotifyConnect] Pushing new state :: true
info: CoreCommandRouter::servicePushState
info: CoreStateMachine::pushState
info: CoreCommandRouter::volumioPushState
info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
info: CorePlayQueue::getTrack 0
info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current radio_paradise Received volspotconnect2
info: CoreCommandRouter::executeOnPlugin: my_volumio , detectVolumioHardware
info: Could not detect Volumio Device: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0
[SpotifyConnect] Relinquishing Volumio State
UNSET VOLATILE
[SpotifyConnect] unSetVolatile called
[SpotifyConnect] Relinquishing Volumio State to another service
[SpotifyConnect] Received stop
[SpotifyConnect] Stopping Vollibrespot daemon
[SpotifyConnect] Closing metadata listener
info: CoreStateMachine::resetVolumioState
info: CoreStateMachine::getcurrentVolume
info: CoreCommandRouter::volumioRetrievevolume
volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop volspotconnect2.service
pam_unix(sudo:session): session opened for user root by (uid=0)
info: Disabling plugin volspotconnect2
info: Done.
Stopping Volspotconnect2 Daemon...
Stopped Volspotconnect2 Daemon.
pam_unix(sudo:session): session closed for user root
[SpotifyConnect] Vollibrespot Daemon service stoped!
info: VolumeController:: Volume=20 Mute =false
info: CoreStateMachine::pushState
info: CorePlayQueue::getTrack 0
info: CoreCommandRouter::volumioPushState
info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
info: CoreStateMachine::updateTrackBlock
info: CorePlayQueue::getTrackBlock
info: CoreCommandRouter::volumioRetrievevolume
info: VolumeController:: Volume=20 Mute =false
info: CoreStateMachine::pushState
info: CorePlayQueue::getTrack 0
info: CoreCommandRouter::volumioPushState
info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
info: Enabling plugin volspotconnect2
info: Loading plugin "volspotconnect2"...
info: PLUGIN START: volspotconnect2
[SpotifyConnect] Creating VLS config file
info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
[SpotifyConnect] Starting metadata listener
volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volspotconnect2.service
pam_unix(sudo:session): session opened for user root by (uid=0)
Starting Volspotconnect2 Daemon...
Started Volspotconnect2 Daemon.
pam_unix(sudo:session): session closed for user root
vollibrespot v0.2.1 1438440 2020-05-15 (librespot 659de68 2020-05-10) -- Built On 2020-05-15
Reading Config from "volspotify.toml"
[Vollibrespot] : Using Alsa backend with device: plughw:Loopback
[SpotifyConnect] Vollibrespot Daemon service started!
e[34m [Metrics] e[39m SpotifyConnect: e[31m 0s 103.86ms e[39m
info: Done.
[Vollibrespot] : Failed to register IPv6 receiver: Os { code: 19, kind: Other, message: "No such device" }
[Vollibrespot] : Connecting to AP "guc3-accesspoint-b-qsg4.ap.spotify.com:443"
[Vollibrespot] : Authenticated as "danielfelix" !
[Vollibrespot] : Setting up new mixer: card:hw:2 mixer:Digital index:0
[Vollibrespot] : Alsa Mixer info min: 0 (MilliBel(-9999999)[dB]) -- max: 207 (MilliBel(0)[dB]) HW: true
[Vollibrespot] : Using alsa sink
[Vollibrespot] : Metadata pipe established
[Vollibrespot] : Country: "AR"
[Vollibrespot] : Event: Volume { volume_to_mixer: 13107 }
[SpotifyConnect]  20
[SpotifyConnect] Volume: Spotify:20 Volumio: 20
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: 1596579216043 }
[Vollibrespot] : SessionActive!
[Vollibrespot] : Event: PlaybackStarted { track_id: SpotifyId { id: 145388607699475846999067032348438672553, audio_type: Track } }
[Vollibrespot] : Event: PlaybackLoading { track_id: SpotifyId { id: 145388607699475846999067032348438672553, audio_type: Track } }
[SpotifyConnect]  A connect session has begun
[SpotifyConnect]  Device palyback is active!
info: CoreCommandRouter::volumioGetState
info: CorePlayQueue::getTrack 0
[SpotifyConnect] Currently active: radio_paradise
[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: radio_paradise
[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: CorePlayQueue::getTrack 0
info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current radio_paradise Received volspotconnect2
info: CoreCommandRouter::volumioGetState
[SpotifyConnect] Currently active: undefined
[SpotifyConnect] Pushing new state :: true
info: CoreCommandRouter::servicePushState
info: CoreStateMachine::pushState
info: CoreCommandRouter::volumioPushState
info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
info: CorePlayQueue::getTrack 0
info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current radio_paradise Received volspotconnect2
[Vollibrespot] : No autoplay_uri found
[Vollibrespot] : AutoplayError: MercuryError
[Vollibrespot] : Event: GotToken { token: Token { access_token: "BQB0Apw4ZCdb8LaOXCHJrav_-Y_aSqDpTn552JY1kNq18_SsaIwe9hjxaDd3kLjPL1riJ6eGL_cym-p1hrXtdj-S-NA0QenKeu6gpzvaz-McmRrJG0hQoASJAPqo3T4fH0wYCxz9xwayhTCMSPL4VSgGtG1klVacVemxRCw", expires_in: 3600, token_type: "Bearer", scope: ["streaming", "user-read-playback-state", "user-modify-playback-state", "user-read-currently-playing", "user-read-private"] } }
[SpotifyConnect]  BQB0Apw4ZCdb8LaOXCHJrav_-Y_aSqDpTn552JY1kNq18_SsaIwe9hjxaDd3kLjPL1riJ6eGL_cym-p1hrXtdj-S-NA0QenKeu6gpzvaz-McmRrJG0hQoASJAPqo3T4fH0wYCxz9xwayhTCMSPL4VSgGtG1klVacVemxRCw
[Vollibrespot] : Loading  with Spotify URI 
[SpotifyConnect] Setting VLS device_id: c6e56cf6b68c07041768b06e2f29a439e7724b0e
[Vollibrespot] :  (206800 ms) loaded
[Vollibrespot] : Event: PlaybackStopped { track_id: SpotifyId { id: 145388607699475846999067032348438672553, audio_type: Track } }
[SpotifyConnect]  Device palyback is inactive
[SpotifyConnect] Device Session is_active: true
[Vollibrespot] : Resolving uri "spotify:station:user:spotify:playlist:37i9dQZEVXcMU5Gn41qZ9Y"
[Vollibrespot] : Event: TrackChanged { old_track_id: SpotifyId { id: 145388607699475846999067032348438672553, audio_type: Track }, track_id: SpotifyId { id: 22747588139279626277758005283872091704, audio_type: Track } }
[Vollibrespot] : Loading  with Spotify URI 
[Vollibrespot] : Resolved 50 tracks from <"spotify:station:user:spotify:playlist:37i9dQZEVXcMU5Gn41qZ9Y">
[Vollibrespot] :  (186466 ms) loaded
[SpotifyConnect]  Mrs. Cold
[SpotifyConnect] Pushing metadata
info: CoreCommandRouter::volumioGetState
[SpotifyConnect] Currently active: undefined
[SpotifyConnect] Pushing new state :: true
[Vollibrespot] : Event: PlaybackLoading { track_id: SpotifyId { id: 22747588139279626277758005283872091704, audio_type: Track } }
[Vollibrespot] : Event: SinkActive
info: CoreCommandRouter::servicePushState
info: CoreStateMachine::pushState
info: CoreCommandRouter::volumioPushState
info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
info: CorePlayQueue::getTrack 0
info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current radio_paradise Received volspotconnect2
[SpotifyConnect]  Sink acquired
info: CoreCommandRouter::volumioGetState
[SpotifyConnect] Currently active: undefined
[SpotifyConnect] Pushing new state :: true
info: CoreCommandRouter::servicePushState
info: CoreStateMachine::pushState
info: CoreCommandRouter::volumioPushState
info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
CIFS VFS: Server 192.168.0.18 has not responded in 180 seconds. Reconnecting...

ashthespy · August 5, 2020, 10:42am

Thanks for the log!

Now it’s clear(er) what is happening - there seems to be some issues with the playback notification. When you stop radio_paradise - it does pasue, but there seems to be some conflict with a second state update from mpd

info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current radio_paradise Received mpd
info: ControllerMpd::pushState
info: CoreCommandRouter::servicePushState
info: CorePlayQueue::getTrack 0
info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current radio_paradise Received mpd

So then, for some reason, when the plugin requests Volumio to stop the currently active service, it fails.

[SpotifyConnect] Currently active: radio_paradise
[SpotifyConnect] Stopping currently active service
info: CoreCommandRouter::volumioStop
info: CoreStateMachine::stop
info: CoreStateMachine::setConsumeUpdateService undefined
UNSET VOLATILE
info: CoreStateMachine::updateTrackBlock
info: CorePlayQueue::getTrackBlock
info: CoreStateMachine::stPlaybackTimer
info: CoreStateMachine::pushState
info: CorePlayQueue::getTrack 0
info: CoreCommandRouter::volumioPushState
info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
info: CoreStateMachine::serviceStop
info: CorePlayQueue::getTrack 0
info: CoreCommandRouter::serviceStop
info: ControllerMpd::stop
info:
---------------------------- MPD announces state update: player
info: ControllerMpd::getState
info: CoreCommandRouter::servicePushState
info: CoreStateMachine::pushState
info: CorePlayQueue::getTrack 0
info: CoreCommandRouter::volumioPushState
info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
info: CorePlayQueue::getTrack 0
info: CoreStateMachine::syncState   stateService stop
info: CoreStateMachine::syncState   currentStatus stop
info: CoreStateMachine::pushState
info: CorePlayQueue::getTrack 0
info: CoreCommandRouter::volumioPushState
info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
info: No code
info: CoreStateMachine::pushState
info: CorePlayQueue::getTrack 0
info: CoreCommandRouter::volumioPushState
info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
[SpotifyConnect] Vollibrespot Active
info: CoreCommandRouter::volumioGetState
info: CorePlayQueue::getTrack 0
[SpotifyConnect] Currently active: radio_paradise
[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: CorePlayQueue::getTrack 0
info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current radio_paradise Received volspotconnect2
info: CoreCommandRouter::volumioGetState
[SpotifyConnect] Currently active: undefined
[SpotifyConnect] Pushing new state :: true
info: CoreCommandRouter::servicePushState
info: CoreStateMachine::pushState
info: CoreCommandRouter::volumioPushState
info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
info: CorePlayQueue::getTrack 0
info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current radio_paradise Received volspotconnect2

This then means that the ALSA sink is still held by the previous service radio_paradise and when the VLS daemon starts playing, it can’t access the sink and crashes.

[Vollibrespot] : Alsa error PCM open ALSA function 'snd_pcm_open' failed with error 'EBUSY: Device or resource busy'
[Vollibrespot] : Could not start audio: Alsa error: PCM open failed

Does this happen only with the radio_paradise plugin?

danielfelix · August 5, 2020, 2:48pm

Ok, now that we know that it fails when the RP Plugin is in use, I will see what happens in another situation and I will tell you about it.
Thanks for your time!

danielfelix · August 6, 2020, 12:37am

I’m testing … so far the simplest solution when Spotify can’t play is to make mpc stop from Putty. After that it works properly.
I also found that it not only fails with the RP Plugin.

getshket · April 12, 2021, 7:39pm

Hi! I used google translate, sorry. I`m user beaglebone black and Volumio 2.779. Plugin Spotify 2.0.3 working, volumio spotify connect 2 1.0.5 not working. DNS 8.8.8.8 and 8.8.4.4. I do not understand Linux, please, help!

getshket · April 12, 2021, 7:46pm

Downloading plugin at http://plugins.volumio.org/plugins/volumio/armhf/music_service/volspotconnect2/volspotconnect2.zip
END DOWNLOAD: http://plugins.volumio.org/plugins/volumio/armhf/music_service/volspotconnect2/volspotconnect2.zip
Creating install location
Unpacking plugin
Checking for duplicate plugin
Copying plugin to location
Installing necessary utilities
Launching a bash shell
Installing volspotconnect2 dependencies
Detected cpu architecture as armv7l
Plugin installation script failed!!
An error occurred while installing the plugin Error

balbuze · April 13, 2021, 6:03am

Why don’t you install it simply from the UI plugin page?

getshket · April 13, 2021, 8:44am

Doesn’t get up.

getshket · April 13, 2021, 8:45am

photo_2021-04-11_15-05-36

ashthespy · April 13, 2021, 9:19am

Enable ssh, and follow the journal logs while trying to install the plugin. Please post the full log

getshket · April 13, 2021, 9:25am

Starting Live Log…
info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom
error: Could not retrieve plugin audio_interface multiroom
info: Listing playlists
info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings
info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard
info: CoreCommandRouter::executeOnPlugin: system , getShowWizard
info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings
info: CALLMETHOD: system_controller system enableLiveLog true
info: CoreCommandRouter::executeOnPlugin: system , enableLiveLog
info: Launching a new LiveLog session
info: Downloading plugin at http://plugins.volumio.org/plugins/volumio/armhf/music_service/volspotconnect2/volspotconnect2.zip
info: END DOWNLOAD: http://plugins.volumio.org/plugins/volumio/armhf/music_service/volspotconnect2/volspotconnect2.zip
info: Folder /tmp/plugins removed
info: Checking if plugin already exists
info: Rename folder
info: Folder /tmp/downloaded_plugin.zip removed
info: Move to category
info: Checking if install.sh is present
info: Executing install.sh
volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/sh /data/plugins/music_service/volspotconnect2/install.sh
pam_unix(sudo:session): session opened for user root by (uid=0)
info: Launching a bash shell
info: Installing volspotconnect2 dependencies
info: Detected cpu architecture as armv7l
pam_unix(sudo:session): session closed for user root
info: Plugin installation script failed!!
info: Install script return the error Error: Command failed: echo volumio | sudo -S sh /data/plugins/music_service/volspotconnect2/install.sh > /tmp/installog
[sudo] password for volumio:
info: An error occurred installing the plugin. Rolling back config
info: Plugin folders cleanup
info: Scanning into folder /volumio/app/plugins/
info: Scanning category audio_interface
info: Scanning category miscellanea
info: Scanning category music_service
info: Scanning category plugins.json
info: Scanning category system_controller
info: Scanning category user_interface
info: Scanning into folder /data/plugins/
info: Scanning category music_service
info: Plugin folders cleanup completed
info: Error: Error
info: Folder /tmp/plugins removed
info: Folder /tmp/downloaded_plugin.zip removed
info: Folder /data/temp removed

ashthespy · April 13, 2021, 2:33pm

Plugin installs won’t work if you change your password… Reset it back it it should work!

angus · June 10, 2021, 7:30am

Hi there,

I’ve installed the Spotify Connect2 v 1.0.5 plug in. When I open up Spotify, I see ‘Volumio’ as a device option, however, when I tap on Volumio it tries to connect, but then fails - reverting to the existing playback source.

I’m not too technical, can anyone help out with this?

hifiswede · July 14, 2021, 6:26am

Hi, podcast support does no longer work again.

Thanks for your work

julesolivier · July 29, 2021, 10:50pm

I have this exact same issue, does anyone have a solution ?