-- Logs begin at Mon 2024-08-26 13:35:41 UTC, end at Thu 2024-08-29 18:49:47 UTC. -- Aug 29 18:49:27 volumio volumio[5172]: info: Tunnel connection is inactive, restarting it Aug 29 18:49:27 volumio volumio[5172]: info: Starting Tunnel 1 Aug 29 18:49:27 volumio volumio[5172]: info: Starting Tunnel Connection Checker Aug 29 18:49:27 volumio sudo[6799]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart sshtunnel.service Aug 29 18:49:27 volumio sudo[6799]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 29 18:49:27 volumio systemd[1]: Stopping MyVolumio SSH Tunnel... Aug 29 18:49:27 volumio autossh[6346]: received signal to exit (15) Aug 29 18:49:27 volumio systemd[1]: Starting MyVolumio SSH Tunnel... Aug 29 18:49:27 volumio volumio[5172]: ------------------------------------ BT MESSAGE: BT STATUS: running Aug 29 18:49:27 volumio volumio[5172]: BT PLUGIN MESSAGE: Playing: false Aug 29 18:49:27 volumio volumio[5172]: BT PLUGIN MESSAGE: VOLATILE: tidalconnect Aug 29 18:49:27 volumio volumio[5172]: BT PLUGIN MESSAGE: STATE:undefined Aug 29 18:49:27 volumio systemd[1]: Started MyVolumio SSH Tunnel. Aug 29 18:49:27 volumio sudo[6799]: pam_unix(sudo:session): session closed for user root Aug 29 18:49:27 volumio volumio[5172]: ------------------------------------ BT MESSAGE: BT STATUS: waiting Aug 29 18:49:27 volumio volumio[5172]: BT PLUGIN MESSAGE: Playing: false Aug 29 18:49:27 volumio volumio[5172]: BT PLUGIN MESSAGE: VOLATILE: tidalconnect Aug 29 18:49:27 volumio volumio[5172]: BT PLUGIN MESSAGE: STATE:undefined Aug 29 18:49:27 volumio autossh[6807]: port set to 0, monitoring disabled Aug 29 18:49:27 volumio autossh[6807]: starting ssh (count 1) Aug 29 18:49:27 volumio autossh[6807]: ssh child pid is 6812 Aug 29 18:49:27 volumio volumio[5172]: info: Remote SSH Started Aug 29 18:49:27 volumio volumio[5172]: info: CoreCommandRouter::volumioGetState Aug 29 18:49:27 volumio volumiossh-tunnel[6805]: Warning: Permanently added '[eu6.myvolumio.org]:2222,[207.154.233.230]:2222' (RSA) to the list of known hosts. Aug 29 18:49:44 volumio volumio[1193]: [Vollibrespot] : Connecting to AP "ap-gew4.spotify.com:443" Aug 29 18:49:44 volumio volumio[1193]: [Vollibrespot] : Authenticated as "2v1nl9ogkn359drrtcm3xi5h0" ! Aug 29 18:49:44 volumio volumio[1193]: [Vollibrespot] : Setting up new mixer: card:hw:2 mixer:DAC index:0 Aug 29 18:49:44 volumio volumio[1193]: [Vollibrespot] : Alsa Mixer info min: 0 (MilliBel(-9999999)[dB]) -- max: 240 (MilliBel(0)[dB]) HW: true Aug 29 18:49:44 volumio volumio[1193]: [Vollibrespot] : Using alsa sink Aug 29 18:49:44 volumio volumio[1193]: [Vollibrespot] : Metadata pipe established Aug 29 18:49:44 volumio volumio[1193]: [Vollibrespot] : Country: "DE" Aug 29 18:49:44 volumio volumio[1193]: [Vollibrespot] : Event: Volume { volume_to_mixer: 0 } Aug 29 18:49:44 volumio volumio[5172]: [SpotifyConnect] 0 Aug 29 18:49:44 volumio volumio[5172]: [SpotifyConnect] Volume: Spotify:0 Volumio: 0 Aug 29 18:49:44 volumio volumio[5172]: info: CoreStateMachine::pushState Aug 29 18:49:44 volumio volumio[5172]: info: CoreCommandRouter::volumioPushState Aug 29 18:49:44 volumio volumio[5172]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 29 18:49:44 volumio volumio[1193]: [Vollibrespot] : Fetching autoplay context uri Aug 29 18:49:44 volumio volumio[1193]: [Vollibrespot] : Event: SessionActive { became_active_at: 1724957384843 } Aug 29 18:49:44 volumio volumio[1193]: [Vollibrespot] : SessionActive! Aug 29 18:49:44 volumio volumio[1193]: [Vollibrespot] : Event: PlaybackStarted { track_id: SpotifyId { id: 13802543318361913678705268280981330387, audio_type: Track } } Aug 29 18:49:44 volumio volumio[1193]: [Vollibrespot] : Event: PlaybackLoading { track_id: SpotifyId { id: 13802543318361913678705268280981330387, audio_type: Track } } Aug 29 18:49:44 volumio volumio[1193]: [Vollibrespot] : Autoplay uri resolved to <"spotify:station:playlist:3lS5RbeJEI93QIZqAKnOxi"> Aug 29 18:49:44 volumio volumio[1193]: [Vollibrespot] : Resolving uri "spotify:station:playlist:3lS5RbeJEI93QIZqAKnOxi" Aug 29 18:49:44 volumio volumio[1193]: [Vollibrespot] : Event: GotToken { token: Token { access_token: "BQDYtv9z2zj_zjKCiDIat6_83spR4_gcZd-J69tLQklbXwtwLQSPfrg81jMIreKpsmW-6kA5VBsUvDulsH2w6AmzG8IQ61igrr1E-aoeespSyzEQGL70U8HNGt_Y6r__BIsNDQjYj4SzW3xh7B5MBeGK18sgFqi5VD-YhwABiKaZbMYH4ZoE0_FqGS8ifQu2crlYin493s1SFOfQAkZFvBsS_JORgQ7jqg", expires_in: 3600, token_type: "Bearer", scope: ["streaming", "user-read-playback-state", "user-modify-playback-state", "user-read-currently-playing", "user-read-private"] } } Aug 29 18:49:44 volumio volumio[1193]: [Vollibrespot] : Loading with Spotify URI Aug 29 18:49:45 volumio volumio[5172]: [SpotifyConnect] A connect session has begun Aug 29 18:49:45 volumio volumio[1193]: [Vollibrespot] : Resolved 50 tracks from <"spotify:playlist:3lS5RbeJEI93QIZqAKnOxi"> Aug 29 18:49:45 volumio volumio[5172]: [SpotifyConnect] Device palyback is active! Aug 29 18:49:45 volumio volumio[1193]: [Vollibrespot] : (304499 ms) loaded Aug 29 18:49:45 volumio volumio[1193]: [Vollibrespot] : Alsa error PCM open ALSA function 'snd_pcm_open' failed with error 'EBUSY: Device or resource busy' Aug 29 18:49:45 volumio volumio[1193]: [Vollibrespot] : Could not start audio: Alsa error: PCM open failed Aug 29 18:49:45 volumio volumio[1193]: [Vollibrespot] : Alsa error PCM open ALSA function 'snd_pcm_open' failed with error 'EBUSY: Device or resource busy' Aug 29 18:49:45 volumio volumio[1193]: [Vollibrespot] : Could not start audio: Alsa error: PCM open failed Aug 29 18:49:45 volumio volumio[1193]: [Vollibrespot] : Alsa error PCM open ALSA function 'snd_pcm_open' failed with error 'EBUSY: Device or resource busy' Aug 29 18:49:45 volumio volumio[1193]: [Vollibrespot] : Could not start audio: Alsa error: PCM open failed Aug 29 18:49:45 volumio volumio[1193]: 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 Aug 29 18:49:45 volumio volumio[1193]: stack backtrace: Aug 29 18:49:46 volumio volumio[1193]: 0: 0xa8133c - backtrace::backtrace::libunwind::trace::hae21a072c81e5842 Aug 29 18:49:46 volumio volumio[1193]: at /cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.46/src/backtrace/libunwind.rs:86 Aug 29 18:49:46 volumio volumio[1193]: 1: 0xa8133c - backtrace::backtrace::trace_unsynchronized::h0f9b260087e46e47 Aug 29 18:49:46 volumio volumio[1193]: at /cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.46/src/backtrace/mod.rs:66 Aug 29 18:49:46 volumio volumio[1193]: 2: 0xa8133c - std::sys_common::backtrace::_print_fmt::hbf1a59173a7860c3 Aug 29 18:49:46 volumio volumio[1193]: at src/libstd/sys_common/backtrace.rs:78 Aug 29 18:49:46 volumio volumio[1193]: 3: 0xa8133c - ::fmt::he1a5d6f378e506c4 Aug 29 18:49:46 volumio volumio[1193]: at src/libstd/sys_common/backtrace.rs:59 Aug 29 18:49:46 volumio volumio[1193]: 4: 0xaa1d5c - core::fmt::write::hb37ae5a5e0b70623 Aug 29 18:49:46 volumio volumio[1193]: at src/libcore/fmt/mod.rs:1076 Aug 29 18:49:46 volumio volumio[1193]: 5: 0xa7ac64 - std::io::Write::write_fmt::ha24bb3f5a858327b Aug 29 18:49:46 volumio volumio[1193]: at src/libstd/io/mod.rs:1537 Aug 29 18:49:46 volumio volumio[1193]: 6: 0xa83974 - std::sys_common::backtrace::_print::h47b03aa1342833e3 Aug 29 18:49:46 volumio volumio[1193]: at src/libstd/sys_common/backtrace.rs:62 Aug 29 18:49:46 volumio volumio[1193]: 7: 0xa83974 - std::sys_common::backtrace::print::h2217cbc390250439 Aug 29 18:49:46 volumio volumio[1193]: at src/libstd/sys_common/backtrace.rs:49 Aug 29 18:49:46 volumio volumio[1193]: 8: 0xa83974 - std::panicking::default_hook::{{closure}}::h179f5229ea1c8e30 Aug 29 18:49:46 volumio volumio[1193]: at src/libstd/panicking.rs:198 Aug 29 18:49:46 volumio volumio[1193]: 9: 0xa83640 - std::panicking::default_hook::h46ab82039cbc65eb Aug 29 18:49:46 volumio volumio[1193]: at src/libstd/panicking.rs:217 Aug 29 18:49:46 volumio volumio[1193]: 10: 0xa84054 - std::panicking::rust_panic_with_hook::h7326c48419bc7c33 Aug 29 18:49:46 volumio volumio[1193]: at src/libstd/panicking.rs:526 Aug 29 18:49:46 volumio volumio[1193]: 11: 0xa83c54 - rust_begin_unwind Aug 29 18:49:46 volumio volumio[1193]: at src/libstd/panicking.rs:437 Aug 29 18:49:46 volumio volumio[1193]: 12: 0xa9f594 - core::panicking::panic_fmt::ha292e19d5ae716ed Aug 29 18:49:46 volumio volumio[1193]: at src/libcore/panicking.rs:85 Aug 29 18:49:46 volumio volumio[1193]: 13: 0xa9f4f0 - core::panicking::panic::heb457f4fa750842b Aug 29 18:49:46 volumio volumio[1193]: at src/libcore/panicking.rs:50 Aug 29 18:49:46 volumio volumio[1193]: 14: 0x67eee8 - ::write::h5da62cd8da1289c3 Aug 29 18:49:46 volumio volumio[1193]: 15: 0x6583c4 - ::poll::h2bafd5dc8d40bf3f Aug 29 18:49:46 volumio volumio[1193]: 16: 0x568eec - futures::task_impl::std::set::h2116cb0e9a5165fe Aug 29 18:49:46 volumio volumio[1193]: 17: 0x55dc6c - futures::task_impl::Spawn::poll_future_notify::h20a5cc82ac41f2fa Aug 29 18:49:46 volumio volumio[1193]: 18: 0x5776a0 - futures::future::Future::wait::ha8819dd7a48bc248 Aug 29 18:49:46 volumio volumio[1193]: 19: 0x55f4b4 - std::sys_common::backtrace::__rust_begin_short_backtrace::habfd768f2a80dc30 Aug 29 18:49:46 volumio volumio[1193]: 20: 0x57e5a8 - core::ops::function::FnOnce::call_once{{vtable.shim}}::h0dcfa92cb8b4ff47 Aug 29 18:49:46 volumio volumio[1193]: 21: 0xa8746c - as core::ops::function::FnOnce>::call_once::hb2bcc0b96e754d10 Aug 29 18:49:46 volumio volumio[1193]: at /rustc/04488afe34512aa4c33566eb16d8c912a3ae04f9/src/liballoc/boxed.rs:1081 Aug 29 18:49:46 volumio volumio[1193]: 22: 0xa8746c - as core::ops::function::FnOnce>::call_once::h2dd73f7c66408260 Aug 29 18:49:46 volumio volumio[1193]: at /rustc/04488afe34512aa4c33566eb16d8c912a3ae04f9/src/liballoc/boxed.rs:1081 Aug 29 18:49:46 volumio volumio[1193]: 23: 0xa8746c - std::sys::unix::thread::Thread::new::thread_start::h6fc0046e32ed87dc Aug 29 18:49:46 volumio volumio[1193]: at src/libstd/sys/unix/thread.rs:87 Aug 29 18:49:46 volumio volumio[5172]: info: CoreCommandRouter::volumioGetState Aug 29 18:49:46 volumio volumio[5172]: [SpotifyConnect] Currently active: tidalconnect Aug 29 18:49:46 volumio volumio[5172]: [SpotifyConnect] Stopping currently active service Aug 29 18:49:46 volumio volumio[5172]: info: CoreCommandRouter::volumioStop Aug 29 18:49:46 volumio volumio[5172]: info: CoreStateMachine::stop Aug 29 18:49:46 volumio volumio[5172]: info: CoreStateMachine::serviceStop Aug 29 18:49:46 volumio volumio[5172]: info: CoreCommandRouter::serviceStop Aug 29 18:49:46 volumio volumio[5172]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 29 18:49:46 volumio volumio[5172]: TypeError: Cannot read property 'then' of undefined Aug 29 18:49:46 volumio volumio[5172]: at SpotConnEvents.SpotConn.on (/data/plugins/music_service/volspotconnect2/index.js:143:23) Aug 29 18:49:46 volumio volumio[5172]: at emitNone (events.js:106:13) Aug 29 18:49:46 volumio volumio[5172]: at SpotConnEvents.emit (events.js:208:7) Aug 29 18:49:46 volumio volumio[5172]: at SpotConnEvents.parseData (/data/plugins/music_service/volspotconnect2/SpotConnController.js:73:16) Aug 29 18:49:46 volumio volumio[5172]: at Socket.SpotConnEvents._udpsource.on.msg (/data/plugins/music_service/volspotconnect2/SpotConnController.js:15:12) Aug 29 18:49:46 volumio volumio[5172]: at emitTwo (events.js:126:13) Aug 29 18:49:46 volumio volumio[5172]: at Socket.emit (events.js:214:7) Aug 29 18:49:46 volumio volumio[5172]: at UDP.onMessage [as onmessage] (dgram.js:659:8) Aug 29 18:49:46 volumio volumio[5172]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 29 18:49:46 volumio vtcs[5590]: [2024-08-29 18:49:46.221] [tisoc] [warning] [PlaybackControllerImpl.cpp:472] Illegal state:0 Aug 29 18:49:47 volumio sudo[6863]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-08-29 18:48 Aug 29 18:49:47 volumio sudo[6863]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Raspbian GNU/Linux 8 (jessie)" NAME="Raspbian GNU/Linux" VERSION_ID="8" VERSION="8 (jessie)" ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="dd2a4339faaeb892c7f467e7dc8d424aefb0bd03" VOLUMIO_FE_VERSION="958dedc0edff114f244fa9acc70cf53089d9e5ae" VOLUMIO_BE_VERSION="fd3e37ffec12db034ec93f94dbc26e5495d5b91a" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Wed Oct 6 12:34:49 CEST 2021" VOLUMIO_VERSION="2.917" VOLUMIO_HARDWARE="pi" VOLUMIO_HASH="98c8f08c531a6f0456f17ab17795e35f"