Hello, I am encountering an issue with the Spotify plugin on 3.0.9. Specifically, the playback frequently stops unexpectedly after a few songs.
Additionally, I have noticed that Volumio becomes unresponsive when I try to resume playback after manually stopping a Spotify song and returning a few hours later. To continue playing, I usually have to restart Volumio.
Here my log of a short session in which it stopped after one or two songs.
Here´s my logfile:
[http://logs.volumio.org/volumio/utWagzx.html]
All other things like internetradio and youtube work fine.
Pi4 with DAC, Spotify premium.
Problem: Can´t start playing song in spotify, browsing works fine.
Please remove the youtube plugin as your log is full with errors.
Mar 10 17:28:28 volumiobuero volumio[820]: Failed to parse renderer: TypeError: Cannot read property 'reduce' of undefined
Mar 10 17:28:28 volumiobuero volumio[820]: at parseChannelRenderer (/data/plugins/music_service/youtube2/node_modules/youtube-scrape/scraper.js:208:79)
Mar 10 17:28:28 volumiobuero volumio[820]: at /data/plugins/music_service/youtube2/node_modules/youtube-scrape/scraper.js:167:47
Mar 10 17:28:28 volumiobuero volumio[820]: at Array.forEach ()
Mar 10 17:28:28 volumiobuero volumio[820]: at /data/plugins/music_service/youtube2/node_modules/youtube-scrape/scraper.js:164:58
You start playing Spotify before the boot is ready,
Mar 10 17:28:42 volumiobuero volumio[820]: info: BOOT COMPLETED
I have the following issue with the spotify plugin since 3.0.6:
Spotify connect only works on mobile devices. Neither Pc nor Laptop will connect.
This is kinda fixed if I connect first via mobile. After that I’m able to connect via Pc aswell (with the same account). Unfortunately Spotify behaves a bit weird then and does not show the currently played track inside a playlist.
Here the logs:
Starting Live Log...
info: CoreCommandRouter::volumioGetState
info: CorePlayQueue::getTrack 0
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] : Connecting to AP "ap-gew4.spotify.com:443"
[Vollibrespot] : Authenticated as "xxx" !
[Vollibrespot] : Using alsa sink
[Vollibrespot] : Metadata pipe established
[Vollibrespot] : Country: "CH"
[Vollibrespot] : Event: Volume { volume_to_mixer: 17627 }
[SpotifyConnect] Volume Spotify: 26.897077897306783 Volumio: 27
[Vollibrespot] : Fetching autoplay context uri
[Vollibrespot] : Event: SessionActive { became_active_at: 1679151569686 }
[Vollibrespot] : SessionActive!
[Vollibrespot] : Event: PlaybackStarted { track_id: SpotifyId { id: 71453761429729184779793147365141245289, audio_type: Track } }
[Vollibrespot] : Event: PlaybackLoading { track_id: SpotifyId { id: 71453761429729184779793147365141245289, audio_type: Track } }
[SpotifyConnect] A connect session has begun
info: Acquiring new spotify session
info: CoreCommandRouter::volumioStop
info: CoreStateMachine::stop
info: CoreStateMachine::setConsumeUpdateService undefined
info: Checking Spotify Web API
[SpotifyConnect] Vollibrespot Active
info: CoreStateMachine::setConsumeUpdateService undefined
info: [1679151569702] ControllerSpotify::pushState
info: CoreCommandRouter::servicePushState
info: CoreStateMachine::pushState
info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
info: CoreCommandRouter::volumioPushState
[Vollibrespot] : error 403 for uri hm://keymaster/token/authenticated?client_id=xxx&scope=streaming,user-read-playback-state,user-modify-playback-state,user-read-currently-playing,user-read-private
[Vollibrespot] : Error: MercuryError
[Vollibrespot] : No autoplay_uri found
[Vollibrespot] : AutoplayError: MercuryError
thread 'main' panicked at 'cannot poll Map twice', /build/cache/registry/src/github.com-1ecc6299db9ec823/futures-0.1.31/src/future/map.rs:35:29
stack backtrace:
[SpotifyConnect] Device palyback is active!
[SpotifyConnect] Device palyback is loading
0: 0xa58444 - std::backtrace_rs::backtrace::libunwind::trace::h40a4eff66330a36d
at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/../../backtrace/src/backtrace/libunwind.rs:93:5
1: 0xa58444 - std::backtrace_rs::backtrace::trace_unsynchronized::hbce01963451b0cd5
at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/../../backtrace/src/backtrace/mod.rs:66:5
2: 0xa58444 - std::sys_common::backtrace::_print_fmt::h95da650d09c7e00b
at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/sys_common/backtrace.rs:66:5
3: 0xa58444 - ::fmt::h33b23b1d14f668ff
at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/sys_common/backtrace.rs:45:22
4: 0xa810dc - core::fmt::write::h6320fb0e6ac90e58
at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/core/src/fmt/mod.rs:1190:17
5: 0xa504c4 - std::io::Write::write_fmt::h33b25d4810ca481f
at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/io/mod.rs:1657:15
6: 0xa5aef4 - std::sys_common::backtrace::_print::h7e61c5be69c715ef
at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/sys_common/backtrace.rs:48:5
7: 0xa5aef4 - std::sys_common::backtrace::print::h3cee176d7c8dab8b
at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/sys_common/backtrace.rs:35:9
8: 0xa5aef4 - std::panicking::default_hook::{{closure}}::h2d0211dd2e97dc43
at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/panicking.rs:295:22
9: 0xa5ab14 - std::panicking::default_hook::hcbdb3b7c40dca30c
at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/panicking.rs:314:9
10: 0xa5b694 - std::panicking::rust_panic_with_hook::h4ce49e7a343dc12b
at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/panicking.rs:698:17
11: 0xa5b304 - std::panicking::begin_panic_handler::{{closure}}::h4961100fae529fe9
at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/panicking.rs:588:13
12: 0xa589c4 - std::sys_common::backtrace::__rust_end_short_backtrace::hf2e68e62c7a80f1f
at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/sys_common/backtrace.rs:138:18
13: 0xa5b098 - rust_begin_unwind
at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/panicking.rs:584:5
14: 0x53e6f4 - core::panicking::panic_fmt::h84c42730e4a50809
at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/core/src/panicking.rs:143:14
15: 0xa7df88 - core::panicking::panic_display::he50fbe261a13d083
at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/core/src/panicking.rs:73:5
16: 0xa7df38 - core::panicking::panic_str::h6e4cfb6a94cf14e8
at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/core/src/panicking.rs:56:5
17: 0x53e57c - core::option::expect_failed::h5f2b901fbc810215
at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/core/src/option.rs:1852:5
18: 0x7a0e18 - as futures::future::Future>::poll::h794cc547cc6bc145
19: 0x629d78 - ::poll::h2a7bff75029d3b82
20: 0x5662ec - ::poll::h5fd9e3bcdeb25ad9
21: 0x5833dc - futures::task_impl::std::set::h8f754e80bd562d0a
22: 0x59a42c - std::thread::local::LocalKey::with::h71cfa1e374fcc0a0
23: 0x57f99c - tokio_current_thread::Entered
::block_on::hde55cdf28eabe6d5
24: 0x59a6f0 - std::thread::local::LocalKey::with::hedba3cfe41326627
25: 0x582880 - tokio::runtime::current_thread::runtime::Runtime::block_on::h6
0d5b89560100ed8
26: 0x568eb0 - vollibrespot::main::h35555355ed947dd1
27: 0x588c50 - std::sys_common::backtrace::__rust_begin_short_backtrace::hef626a10d324c12a
28: 0x5ae52c - std::rt::lang_start::{{closure}}::hd80188e4bcac5072
29: 0xa57b28 - core::ops::function::impls:: for &F>::call_once::h0567da839a080232
at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/core/src/ops/function.rs:259:13
30: 0xa57b28 - std::panicking::try::do_call::hdf194554a41aa3cc
at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/panicking.rs:492:40
31: 0xa57b28 - std::panicking::try::hbf4b7be9f9ffa5f8
at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/panicking.rs:456:19
32: 0xa57b28 - std::panic::catch_unwind::h45f392a39f2fe48c
at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/panic.rs:137:14
33: 0xa57b28 - std::rt::lang_start_internal::{{closure}}::hd772cb03c2060671
at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/rt.rs:128:48
34: 0xa57b28 - std::panicking::try::do_call::hd126f715b519ff2a
at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/panicking.rs:492:40
35: 0xa57b28 - std::panicking::try::h80b7148ce71893dc
at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/panicking.rs:456:19
36: 0xa57b28 - std::panic::catch_unwind::h1562f0b2e8a9cb0d
at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/panic.rs:137:14
37: 0xa57b28 - std::rt::lang_start_internal::h3daa586a0b835507
at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/rt.rs:128:20
38: 0x56ae80 - main
39: 0x76c8f718 - __libc_start_main
[Vollibrespot] : EventSender disconnected
[SpotifyConnect] PlaybackInactive
info: [1679151570095] ControllerSpotify::pushState
info: CoreCommandRouter::servicePushState
info: CoreStateMachine::pushState
info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
info: CoreCommandRouter::volumioPushState
info: CorePlayQueue::getTrack 0
info: CoreStateMachine::syncState stateService stop
info: CoreStateMachine::syncState currentStatus play
info: CoreCommandRouter::volumioPushState
info: CoreStateMachine::stPlaybackTimer
volspotconnect.service: Main process exited, code=exited, status=101/n/a
volspotconnect.service: Failed with result 'exit-code'.
volspotconnect.service: Service RestartSec=2s expired, scheduling restart.
volspotconnect.service: Scheduled restart job, restart counter is at 1.
Stopped Volspotconnect2 Daemon.
Started Volspotconnect2 Daemon.
vollibrespot v0.2.5 8922128 2022-05-31 (librespot 08d8bcc 2020-10-07) -- Built On 2022-05-31
Reading Config from "/tmp/volspotify.toml"
[Vollibrespot] : Using Alsa backend with device: volumio
[Vollibrespot] : Failed to register IPv6 receiver: Os { code: 19, kind: Uncategorized, message: "No such device" }
[Vollibrespot] : dropping truncated packet from 192.168.1.1:5353
[Vollibrespot] : dropping truncated packet from 192.168.1.1:5353
Running RPI 4b Volumio 3 with Spotify plugin. Music always stops at the end of a song after 2-8 tracks been played. Sometime it’s possible to restart the song after a couple of minutes, sometimes a restart is required. Had this problem with Volumio 2 as well. Network through cable. Any ideas? Not very well versed in reading the log unfortunately.
I have removed the Spotify Connect plug in. Only Spotify running. The same result, music halts after7-8 tracks. The iOS app shows the song, as normal but the progressbar and seconds are standing still. Thanks for your support, I appreciate it.
I have issues when I try to stream through Spotify Connect. It starts to play whatever the last song was that I played through my local/NAS music library. And when I try to do it again, I get static mixed with the song that’s playing from the local library. Really weird.
I also only recently upgraded to the latest version of Volumio, coming from whatever version was available around Feb of last year and using the other Spotify Connect plugin initially (which is now uninstalled).
Already tried uninstalling Spotify pluging, and re-installed it, but I get the same results.
Still problem with music stopping a couple of tracks in. Flashed SD with fresh reinstall yesterday, latest Volumio, running Spotify, RPI4b. Network connected through cable (network working fine).