webradio playback status problem (conflicts with volspotconnect2)

[dmnc-net]

Steps to reproduce:

1. with Spotify Connect (using @balbuze volspotconnect2) start playing a song
2. in Volumio-UI overtake the playback by playing some webradio stream
3. watching via CLI volumio status ... results in Symptoms section
4. at this moment other plugins like thinks there is no playback and trying to play its content but webradio is still playing

Symptoms: CLI command volumio status: "status" became "play" for a quick moment and then turns to "stop" but music is playing and "seek" is changing. Also icon in the UI shows ▶ like if there is no playback.

Background: If Volumio is used by multiple users, some of them are using Volumio UI for webradio, other just Spotify Connect thru plugin, this could be a issue.

I'm not sure if this is volspotconnect issue because I'm not using any other plugin (youtube and Volumio's Spotify doesn't work at all).

Screencast: https://youtu.be/GSf4fcc1jCo (mirror ... because of YT rights management)

[ashthespy]

@dmnc-net What version of Volumio are you on? This shouldn't happen, and the sink should be released when a different source requests playback.

[dmnc-net]

Oh, silly me, I forgot to mention the version which was 2.668. Now, with v.2.699 and volspotconnect2 v.0.9.9 problem still remains. @ashthespy sorry for the long delay but please check it.

[ashthespy]

@dmnc-net Could you share your logs when this happens?

[unvirtual]

@ashthespy I think the issue I observe is strongly related to this one.

Steps to reproduce:

1. with Spotify Connect (using volspotconnect2) start playing a song (from Android phone)
2. in Volumio-UI overtake the playback by playing some webradio stream. Webradio plays correctly.
3. Spotify client on Android phone pauses and still appears to be connected to volumio (green icon). Not sure if correct.
4. Hitting play on Spotify client again doesn't stop webradio and exception below is thrown.

Symptoms Switching between spotify connect and webradio back and forth doesn't work reliably.

Volumio v.2.873 volspotconnect2 v1.0.5

Starting Live Log...
[SpotifyConnect]  62.0004577706569
[SpotifyConnect] Volume: Spotify:62.0004577706569 Volumio: 62
info: CoreStateMachine::pushState
info: CoreCommandRouter::volumioPushState
info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion
info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
info: CALLMETHOD: system_controller system enableLiveLog true
info: CoreCommandRouter::executeOnPlugin: system , enableLiveLog
info: Launching a new LiveLog session
[Vollibrespot] : Event: Pause { track_id: SpotifyId { id: 102876374306587101830094222322942557107, audio_type: Track }, position_ms: 114038 }
[SpotifyConnect]  pause
[SpotifyConnect]  Fracture
[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
[Vollibrespot] : Event: SinkInactive
[Vollibrespot] : Event: PlaybackStopped { track_id: SpotifyId { id: 102876374306587101830094222322942557107, audio_type: Track } }
[SpotifyConnect]  Sink released
info: CoreCommandRouter::servicePushState
info: CoreStateMachine::pushState
info: CoreCommandRouter::volumioPushState
info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
[SpotifyConnect]  Device palyback is inactive
[SpotifyConnect] Device is paused
[Vollibrespot] : Event: Play { track_id: SpotifyId { id: 102876374306587101830094222322942557107, audio_type: Track }, position_ms: 114495 }
[SpotifyConnect]  play
[Vollibrespot] : Event: SinkActive
[SpotifyConnect]  Fracture
[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
info: CoreCommandRouter::volumioReplaceandPlayItems
info: CoreStateMachine::ClearQueue
info: CoreStateMachine::stop
info: CoreStateMachine::serviceStop
info: CoreCommandRouter::serviceStop
[SpotifyConnect] Received stop
info: CorePlayQueue::clearPlayQueue
info: CorePlayQueue::saveQueue
info: CoreCommandRouter::volumioPushState
info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
info: CoreCommandRouter::volumioPushQueue
info: CoreStateMachine::addQueueItems
info: CorePlayQueue::addQueueItems
info: Adding Item to queue: http://opml.radiotime.com/Tune.ashx?id=s14991
info: CoreCommandRouter::executeOnPlugin: webradio , explodeUri
[Vollibrespot] : Pause
[Vollibrespot] : Event: Pause { track_id: SpotifyId { id: 102876374306587101830094222322942557107, audio_type: Track }, position_ms: 137091 }
[SpotifyConnect]  Pause
[SpotifyConnect]  pause
[SpotifyConnect]  Fracture
[SpotifyConnect] Not pushing metadata: { active: true, isStopping: true }
info: CorePlayQueue::saveQueue
info: CoreCommandRouter::volumioPushQueue
info: CoreStateMachine::updateTrackBlock
info: CorePlayQueue::getTrackBlock
info: CoreCommandRouter::volumioPlay
UNSET VOLATILE
[SpotifyConnect] unSetVolatile called
[SpotifyConnect] Relinquishing Volumio State to another service
[SpotifyConnect] Received stop
info: CoreStateMachine::play index 0
info: CoreStateMachine::setConsumeUpdateService undefined
info: CoreStateMachine::stop
info: CoreStateMachine::setConsumeUpdateService undefined
UNSET VOLATILE
info: CoreStateMachine::stPlaybackTimer
info: CoreStateMachine::updateTrackBlock
info: CorePlayQueue::getTrackBlock
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: [1617821787812] ControllerWebradio::stop

info: sendMpdCommand stop took 16 milliseconds
info: CoreStateMachine::play index undefined
info: CoreStateMachine::setConsumeUpdateService undefined
info: CorePlayQueue::getTrack 0
info: CoreStateMachine::startPlaybackTimer
info: CorePlayQueue::getTrack 0
info: [1617821787832] ControllerWebradio::clearAddPlayTrack

info: sendMpdCommand stop took 12 milliseconds

info:
---------------------------- MPD announces system playlist update
info: Ignoring MPD Status Update
info: sendMpdCommand clear took 5 milliseconds

error: updateQueue error: null
info: ------------------------------ 9ms

info:
---------------------------- MPD announces system playlist update
info: Ignoring MPD Status Update
info: sendMpdCommand add "http://addrad.io/444y2wj" took 3 milliseconds
info: CoreStateMachine::setConsumeUpdateService mpd

info: ------------------------------ 5ms
info: sendMpdCommand play took 3 milliseconds
[Vollibrespot] : Event: SinkInactive
[Vollibrespot] : Pause
[Vollibrespot] : Event: PlaybackStopped { track_id: SpotifyId { id: 102876374306587101830094222322942557107, audio_type: Track } }
[SpotifyConnect]  Sink released
[SpotifyConnect] Not pushing Pause { active: true, isStopping: true}
[SpotifyConnect] ResolvedStop in  0s 610.95ms 
[SpotifyConnect] ResolvedStop in  0s 289.12ms 
[SpotifyConnect]  Pause
[SpotifyConnect]  Device palyback is inactive
[SpotifyConnect] Device is paused
info:
---------------------------- MPD announces state update: player
info: ControllerMpd::getState

info:
---------------------------- MPD announces system playlist update
info: Ignoring MPD Status Update
info:
---------------------------- MPD announces state update: player
info:
---------------------------- MPD announces system playlist update
info: Ignoring MPD Status Update
info:
---------------------------- MPD announces state update: player
info: ControllerMpd::getState

info: sendMpdCommand status took 15 milliseconds
info: ControllerMpd::getState



info: ------------------------------ 15ms
info: sendMpdCommand status took 13 milliseconds
info: ------------------------------ 16ms
info: sendMpdCommand status took 11 milliseconds
info: sendMpdCommand playlistinfo took 9 milliseconds





info: ControllerMpd::pushState
info: CoreCommandRouter::servicePushState
info: CorePlayQueue::getTrack 0


info: CoreStateMachine::syncState   stateService play
info: CoreStateMachine::syncState   currentStatus stop
info: CoreStateMachine::pushState
info: CoreCommandRouter::volumioPushState
info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
info: ------------------------------ 48ms
info: sendMpdCommand playlistinfo took 21 milliseconds
info: sendMpdCommand playlistinfo took 20 milliseconds


info: ControllerMpd::pushState
info: CoreCommandRouter::servicePushState
info: CorePlayQueue::getTrack 0


info: CoreStateMachine::syncState   stateService play
info: CoreStateMachine::syncState   currentStatus play
info: Received an update from plugin. extracting info from payload
info: CoreStateMachine::pushState
info: CoreCommandRouter::volumioPushState
info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
info: CoreStateMachine::pushState
info: CoreCommandRouter::volumioPushState
info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
info: ControllerMpd::pushState
info: CoreCommandRouter::servicePushState
info: CorePlayQueue::getTrack 0


info: CoreStateMachine::syncState   stateService play
info: CoreStateMachine::syncState   currentStatus play
info: Received an update from plugin. extracting info from payload
info: CoreStateMachine::pushState
info: CoreCommandRouter::volumioPushState
info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
info: CoreStateMachine::pushState
info: CoreCommandRouter::volumioPushState
info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
info: ------------------------------ 96ms
info: ------------------------------ 97ms
info:
---------------------------- MPD announces system playlist update
info: Ignoring MPD Status Update
info:
---------------------------- MPD announces state update: player
info: ControllerMpd::getState

info: ------------------------------ 11ms
info: sendMpdCommand status took 8 milliseconds


info: sendMpdCommand playlistinfo took 7 milliseconds

info: ControllerMpd::pushState
info: CoreCommandRouter::servicePushState
info: CorePlayQueue::getTrack 0


info: CoreStateMachine::syncState   stateService play
info: CoreStateMachine::syncState   currentStatus play
info: Received an update from plugin. extracting info from payload
info: CoreStateMachine::pushState
info: CoreCommandRouter::volumioPushState
info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
info: CoreStateMachine::pushState
info: CoreCommandRouter::volumioPushState
info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
info: ------------------------------ 38ms
wlan0: WPA: Group rekeying completed with cc:ce:1e:ee:e0:d4 [GTK=CCMP]
info:
---------------------------- MPD announces system playlist update
info: Ignoring MPD Status Update
info:
---------------------------- MPD announces state update: player
info: ControllerMpd::getState

info: ------------------------------ 3ms
info: sendMpdCommand status took 2 milliseconds


info: sendMpdCommand playlistinfo took 5 milliseconds

info: ControllerMpd::pushState
info: CoreCommandRouter::servicePushState
info: CorePlayQueue::getTrack 0


info: CoreStateMachine::syncState   stateService play
info: CoreStateMachine::syncState   currentStatus play
info: Received an update from plugin. extracting info from payload
info: CoreStateMachine::pushState
info: CoreCommandRouter::volumioPushState
info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
info: CoreStateMachine::pushState
info: CoreCommandRouter::volumioPushState
info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
info: ------------------------------ 30ms
[Vollibrespot] : Event: Play { track_id: SpotifyId { id: 102876374306587101830094222322942557107, audio_type: Track }, position_ms: 137509 }
[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
[SpotifyConnect]  play
thread '' panicked at 'called `Option::unwrap()` on a `None` value', /build/cache/git/checkouts/librespot-6f197fd632ef9380/08d8bcc/playback/src/audio_backend/alsa.rs:129:35
stack backtrace:
[SpotifyConnect]  Fracture
[SpotifyConnect] Pushing metadata
info: CoreCommandRouter::volumioGetState
[SpotifyConnect] Currently active: webradio
[SpotifyConnect] Pushing new state :: false
info: CoreCommandRouter::servicePushState
info: CorePlayQueue::getTrack 0
info: CONSUME SERVICE: Received update from a service different from the one supposed to be playing music. Skipping notification. Current mpd Received volspotconnect2
0:   0x9d333c - backtrace::backtrace::libunwind::trace::hae21a072c81e5842
at /cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.46/src/backtrace/libunwind.rs:86
1:   0x9d333c - backtrace::backtrace::trace_unsynchronized::h0f9b260087e46e47
at /cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.46/src/backtrace/mod.rs:66
2:   0x9d333c - std::sys_common::backtrace::_print_fmt::hbf1a59173a7860c3
at src/libstd/sys_common/backtrace.rs:78
3:   0x9d333c - ::fmt::he1a5d6f378e506c4
at src/libstd/sys_common/backtrace.rs:59
4:   0x9f3d5c - core::fmt::write::hb37ae5a5e0b70623
at src/libcore/fmt/mod.rs:1076
5:   0x9ccc64 - std::io::Write::write_fmt::ha24bb3f5a858327b
at src/libstd/io/mod.rs:1537
6:   0x9d5974 - std::sys_common::backtrace::_print::h47b03aa1342833e3
at src/libstd/sys_common/backtrace.rs:62
7:   0x9d5974 - std::sys_common::backtrace::print::h2217cbc390250439
at src/libstd/sys_common/backtrace.rs:49
8:   0x9d5974 - std::panicking::default_hook::{{closure}}::h179f5229ea1c8e30
at src/libstd/panicking.rs:198
9:   0x9d5640 - std::panicking::default_hook::h46ab82039cbc65eb
at src/libstd/panicking.rs:217
10:   0x9d6054 - std::panicking::rust_panic_with_hook::h7326c48419bc7c33
at src/libstd/panicking.rs:526
11:   0x9d5c54 - rust_begin_unwind
at src/libstd/panicking.rs:437
12:   0x9f1594 - core::panicking::panic_fmt::ha292e19d5ae716ed
at src/libcore/panicking.rs:85
13:   0x9f14f0 - core::panicking::panic::heb457f4fa750842b
at src/libcore/panicking.rs:50
14:   0x5d0ee8 - ::write::h5da62cd8da1289c3
15:   0x5aa3c4 - ::poll::h2bafd5dc8d40bf3f
16:   0x4baeec - futures::task_impl::std::set::h2116cb0e9a5165fe
17:   0x4afc6c - futures::task_impl::Spawn::poll_future_notify::h20a5cc82ac41f2fa
18:   0x4c96a0 - futures::future::Future::wait::ha8819dd7a48bc248
19:   0x4b14b4 - std::sys_common::backtrace::__rust_begin_short_backtrace::habfd768f2a80dc30
20:   0x4d05a8 - core::ops::function::FnOnce::call_once{{vtable.shim}}::h0dcfa92cb8b4ff47
21:   0x9d946c -  as core::ops::function::FnOnce>::call_once::hb2bcc0b96e754d10
at /rustc/04488afe34512aa4c33566eb16d8c912a3ae04f9/src/liballoc/boxed.rs:1081
22:   0x9d946c -  as core::ops::function::FnOnce>::call_once::h2dd73f7c66408260
at /rustc/04488afe34512aa4c33566eb16d8c912a3ae04f9/src/liballoc/boxed.rs:1081
23:   0x9d946c - std::sys::unix::thread::Thread::new::thread_start::h6fc0046e32ed87dc
at src/libstd/sys/unix/thread.rs:87