-- Logs begin at Thu 2019-02-14 03:11:59 MST, end at Sat 2024-04-27 12:53:01 MDT. -- Apr 27 12:52:02 volumio volumio[2387]: thread 'main' panicked at 'called `Result::unwrap()` on an `Err` value: SendError("...")', /build/cache/git/checkouts/librespot-6f197fd632ef9380/08d8bcc/playback/src/player.rs:232:61 Apr 27 12:52:02 volumio volumio[2387]: stack backtrace: Apr 27 12:52:02 volumio volumio[2387]: 0: 0x998444 - std::backtrace_rs::backtrace::libunwind::trace::h40a4eff66330a36d Apr 27 12:52:02 volumio volumio[2387]: at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/../../backtrace/src/backtrace/libunwind.rs:93:5 Apr 27 12:52:02 volumio volumio[2387]: 1: 0x998444 - std::backtrace_rs::backtrace::trace_unsynchronized::hbce01963451b0cd5 Apr 27 12:52:02 volumio volumio[2387]: at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/../../backtrace/src/backtrace/mod.rs:66:5 Apr 27 12:52:02 volumio volumio[2387]: 2: 0x998444 - std::sys_common::backtrace::_print_fmt::h95da650d09c7e00b Apr 27 12:52:02 volumio volumio[2387]: at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/sys_common/backtrace.rs:66:5 Apr 27 12:52:02 volumio volumio[2387]: 3: 0x998444 - ::fmt::h33b23b1d14f668ff Apr 27 12:52:02 volumio volumio[2387]: at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/sys_common/backtrace.rs:45:22 Apr 27 12:52:02 volumio volumio[2387]: 4: 0x9c10dc - core::fmt::write::h6320fb0e6ac90e58 Apr 27 12:52:02 volumio volumio[2387]: at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/core/src/fmt/mod.rs:1190:17 Apr 27 12:52:02 volumio volumio[2387]: 5: 0x9904c4 - std::io::Write::write_fmt::h33b25d4810ca481f Apr 27 12:52:02 volumio volumio[2387]: at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/io/mod.rs:1657:15 Apr 27 12:52:02 volumio volumio[2387]: 6: 0x99aef4 - std::sys_common::backtrace::_print::h7e61c5be69c715ef Apr 27 12:52:02 volumio volumio[2387]: at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/sys_common/backtrace.rs:48:5 Apr 27 12:52:02 volumio volumio[2387]: 7: 0x99aef4 - std::sys_common::backtrace::print::h3cee176d7c8dab8b Apr 27 12:52:02 volumio volumio[2387]: at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/sys_common/backtrace.rs:35:9 Apr 27 12:52:02 volumio volumio[2387]: 8: 0x99aef4 - std::panicking::default_hook::{{closure}}::h2d0211dd2e97dc43 Apr 27 12:52:02 volumio volumio[2387]: at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/panicking.rs:295:22 Apr 27 12:52:02 volumio volumio[2387]: 9: 0x99ab14 - std::panicking::default_hook::hcbdb3b7c40dca30c Apr 27 12:52:02 volumio volumio[2387]: at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/panicking.rs:314:9 Apr 27 12:52:02 volumio volumio[2387]: 10: 0x99b694 - std::panicking::rust_panic_with_hook::h4ce49e7a343dc12b Apr 27 12:52:02 volumio volumio[2387]: at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/panicking.rs:698:17 Apr 27 12:52:02 volumio volumio[2387]: 11: 0x99b304 - std::panicking::begin_panic_handler::{{closure}}::h4961100fae529fe9 Apr 27 12:52:02 volumio volumio[2387]: at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/panicking.rs:588:13 Apr 27 12:52:02 volumio volumio[2387]: 12: 0x9989c4 - std::sys_common::backtrace::__rust_end_short_backtrace::hf2e68e62c7a80f1f Apr 27 12:52:02 volumio volumio[2387]: at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/sys_common/backtrace.rs:138:18 Apr 27 12:52:02 volumio volumio[2387]: 13: 0x99b098 - rust_begin_unwind Apr 27 12:52:02 volumio volumio[2387]: at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/panicking.rs:584:5 Apr 27 12:52:02 volumio volumio[2387]: 14: 0x47e6f4 - core::panicking::panic_fmt::h84c42730e4a50809 Apr 27 12:52:02 volumio volumio[2387]: at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/core/src/panicking.rs:143:14 Apr 27 12:52:02 volumio volumio[2387]: 15: 0x47e7c8 - core::result::unwrap_failed::h43118a132315b545 Apr 27 12:52:02 volumio volumio[2387]: at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/core/src/result.rs:1749:5 Apr 27 12:52:02 volumio volumio[2387]: 16: 0x598d9c - librespot_playback::player::Player::command::h858bc51b80bfd51a Apr 27 12:52:02 volumio volumio[2387]: 17: 0x598efc - librespot_playback::player::Player::pause::hd499c51d7e4c4b4d Apr 27 12:52:02 volumio volumio[2387]: 18: 0x56c118 - librespot_connect::spirc::SpircTask::handle_pause::h79685f0925a21d35 Apr 27 12:52:02 volumio volumio[2387]: 19: 0x56b084 - ::poll::h2a7bff75029d3b82 Apr 27 12:52:02 volumio volumio[2387]: 20: 0x4a62ec - ::poll::h5fd9e3bcdeb25ad9 Apr 27 12:52:02 volumio volumio[2387]: 21: 0x4c33dc - futures::task_impl::std::set::h8f754e80bd562d0a Apr 27 12:52:02 volumio volumio[2387]: 22: 0x4da42c - std::thread::local::LocalKey::with::h71cfa1e374fcc0a0 Apr 27 12:52:02 volumio volumio[2387]: 23: 0x4bf99c - tokio_current_thread::Entered

::block_on::hde55cdf28eabe6d5 Apr 27 12:52:02 volumio volumio[2387]: 24: 0x4da6f0 - std::thread::local::LocalKey::with::hedba3cfe41326627 Apr 27 12:52:02 volumio volumio[2387]: 25: 0x4c2880 - tokio::runtime::current_thread::runtime::Runtime::block_on::h60d5b89560100ed8 Apr 27 12:52:02 volumio volumio[2387]: 26: 0x4a8eb0 - vollibrespot::main::h35555355ed947dd1 Apr 27 12:52:02 volumio volumio[2387]: 27: 0x4c8c50 - std::sys_common::backtrace::__rust_begin_short_backtrace::hef626a10d324c12a Apr 27 12:52:02 volumio volumio[2387]: 28: 0x4ee52c - std::rt::lang_start::{{closure}}::hd80188e4bcac5072 Apr 27 12:52:02 volumio volumio[2387]: 29: 0x997b28 - core::ops::function::impls:: for &F>::call_once::h0567da839a080232 Apr 27 12:52:02 volumio volumio[2387]: at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/core/src/ops/function.rs:259:13 Apr 27 12:52:02 volumio volumio[2387]: 30: 0x997b28 - std::panicking::try::do_call::hdf194554a41aa3cc Apr 27 12:52:02 volumio volumio[2387]: at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/panicking.rs:492:40 Apr 27 12:52:02 volumio volumio[2387]: 31: 0x997b28 - std::panicking::try::hbf4b7be9f9ffa5f8 Apr 27 12:52:02 volumio volumio[2387]: at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/panicking.rs:456:19 Apr 27 12:52:02 volumio volumio[2387]: 36: 0x997b28 - std::panic::catch_unwind::h1562f0b2e8a9cb0d Apr 27 12:52:02 volumio volumio[2387]: at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/panic.rs:137:14 Apr 27 12:52:02 volumio volumio[2387]: 37: 0x997b28 - std::rt::lang_start_internal::h3daa586a0b835507 Apr 27 12:52:02 volumio volumio[2387]: at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/rt.rs:128:20 Apr 27 12:52:02 volumio volumio[2387]: 38: 0x4aae80 - main Apr 27 12:52:02 volumio volumio[2387]: 39: 0xb6ca4718 - __libc_start_main Apr 27 12:52:02 volumio volumio[2387]: [Vollibrespot] : Player thread panicked! Apr 27 12:52:02 volumio volumio[2387]: [Vollibrespot] : EventSender disconnected Apr 27 12:52:02 volumio systemd[1]: volspotconnect.service: Main process exited, code=exited, status=101/n/a Apr 27 12:52:02 volumio volumio[846]: [SpotifyConnect] PlaybackInactive Apr 27 12:52:02 volumio volumio[846]: info: [1714243922198] ControllerSpotify::pushState Apr 27 12:52:02 volumio volumio[846]: info: CoreCommandRouter::servicePushState Apr 27 12:52:02 volumio volumio[846]: info: CoreStateMachine::pushState Apr 27 12:52:02 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 27 12:52:02 volumio volumio[846]: info: CoreCommandRouter::volumioPushState Apr 27 12:52:02 volumio systemd[1]: volspotconnect.service: Failed with result 'exit-code'. Apr 27 12:52:02 volumio volumio[846]: info: touch_display: Setting screensaver timeout to 15 seconds. Apr 27 12:52:04 volumio systemd[1]: volspotconnect.service: Service RestartSec=2s expired, scheduling restart. Apr 27 12:52:04 volumio systemd[1]: volspotconnect.service: Scheduled restart job, restart counter is at 1. Apr 27 12:52:04 volumio systemd[1]: Stopped Volspotconnect2 Daemon. Apr 27 12:52:04 volumio systemd[1]: Started Volspotconnect2 Daemon. Apr 27 12:52:04 volumio volumio[2444]: vollibrespot v0.2.5 8922128 2022-05-31 (librespot 08d8bcc 2020-10-07) -- Built On 2022-05-31 Apr 27 12:52:04 volumio volumio[2444]: Reading Config from "/tmp/volspotify.toml" Apr 27 12:52:04 volumio volumio[2444]: [Vollibrespot] : Using Alsa backend with device: peppyalsa Apr 27 12:52:04 volumio volumio[2444]: [Vollibrespot] : Failed to register IPv6 receiver: Os { code: 19, kind: Uncategorized, message: "No such device" } Apr 27 12:52:04 volumio volumio[2444]: [Vollibrespot] : Connecting to AP "ap-guc3.spotify.com:443" Apr 27 12:52:04 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 27 12:52:04 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 27 12:52:04 volumio volumio[846]: info: Discovery: Getting this device information Apr 27 12:52:04 volumio volumio[846]: info: CoreCommandRouter::volumioGetState Apr 27 12:52:04 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 27 12:52:04 volumio volumio[2444]: [Vollibrespot] : Authenticated as "12183471479" ! Apr 27 12:52:04 volumio volumio[2444]: [Vollibrespot] : Using alsa sink Apr 27 12:52:04 volumio volumio[2444]: [Vollibrespot] : Metadata pipe established Apr 27 12:52:04 volumio volumio[2444]: [Vollibrespot] : Country: "CA" Apr 27 12:52:04 volumio volumio[2444]: [Vollibrespot] : Event: Volume { volume_to_mixer: 49151 } Apr 27 12:52:04 volumio volumio[846]: [SpotifyConnect] Volume Spotify: 74.99961852445259 Volumio: 75 Apr 27 12:52:05 volumio volumio[846]: verbose: New Socket.io Connection to 192.168.1.40 from 192.168.1.221 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 17_4_1 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Total Clients: 10 Apr 27 12:52:05 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Apr 27 12:52:05 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Apr 27 12:52:05 volumio volumio[846]: info: CoreCommandRouter::volumioGetVisibleSources Apr 27 12:52:05 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 27 12:52:05 volumio volumio[846]: info: CoreCommandRouter::volumioGetState Apr 27 12:52:05 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Apr 27 12:52:05 volumio volumio[846]: info: Received Get System Info Apr 27 12:52:05 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 27 12:52:05 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 27 12:52:05 volumio volumio[846]: info: Discovery: Getting this device information Apr 27 12:52:05 volumio volumio[846]: info: CoreCommandRouter::volumioGetState Apr 27 12:52:05 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 27 12:52:05 volumio volumio[846]: info: CoreCommandRouter::volumioGetState Apr 27 12:52:05 volumio volumio[846]: info: Listing playlists Apr 27 12:52:06 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Apr 27 12:52:09 volumio volumio[846]: info: CoreCommandRouter::volumioVolatilePlay Apr 27 12:52:09 volumio volumio[846]: info: CoreStateMachine::volatilePlay Apr 27 12:52:09 volumio volumio[846]: info: Spotify Play Apr 27 12:52:09 volumio volumio[846]: [SpotifyConnect] Not Found Apr 27 12:52:15 volumio volumio[846]: info: CoreCommandRouter::volumioGetQueue Apr 27 12:52:15 volumio volumio[846]: info: CoreStateMachine::getQueue Apr 27 12:52:15 volumio volumio[846]: info: CorePlayQueue::getQueue Apr 27 12:52:16 volumio volumio[846]: info: CoreCommandRouter::volumioPlay Apr 27 12:52:16 volumio volumio[846]: verbose: UNSET VOLATILE: Service: spop Apr 27 12:52:16 volumio volumio[846]: [SpotifyConnect] unSetVolatile called Apr 27 12:52:16 volumio volumio[846]: info: Spotify Unset Volatile called Apr 27 12:52:16 volumio volumio[846]: [SpotifyConnect] Relinquishing Volumio State to another service Apr 27 12:52:16 volumio volumio[846]: [SpotifyConnect] Spotify Received stop Apr 27 12:52:16 volumio volumio[846]: info: CoreStateMachine::play index 5 Apr 27 12:52:16 volumio volumio[846]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 27 12:52:16 volumio volumio[846]: info: CoreStateMachine::stop Apr 27 12:52:16 volumio volumio[846]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 27 12:52:16 volumio volumio[846]: info: CoreStateMachine::updateTrackBlock Apr 27 12:52:16 volumio volumio[846]: info: CorePlayQueue::getTrackBlock Apr 27 12:52:16 volumio volumio[846]: info: CoreStateMachine::stPlaybackTimer Apr 27 12:52:16 volumio volumio[846]: info: CoreStateMachine::pushState Apr 27 12:52:16 volumio volumio[846]: info: CorePlayQueue::getTrack 69 Apr 27 12:52:16 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 27 12:52:16 volumio volumio[846]: info: CoreCommandRouter::volumioPushState Apr 27 12:52:16 volumio volumio[846]: info: CoreStateMachine::serviceStop Apr 27 12:52:16 volumio volumio[846]: info: CorePlayQueue::getTrack 69 Apr 27 12:52:16 volumio volumio[846]: info: CoreCommandRouter::serviceStop Apr 27 12:52:16 volumio volumio[846]: info: ControllerMpd::stop Apr 27 12:52:16 volumio volumio[846]: verbose: ControllerMpd::sendMpdCommand stop Apr 27 12:52:16 volumio volumio[846]: info: Apr 27 12:52:16 volumio volumio[846]: ---------------------------- MPD announces state update: player Apr 27 12:52:16 volumio volumio[846]: info: sendMpdCommand stop took 135 milliseconds Apr 27 12:52:16 volumio volumio[846]: info: ControllerMpd::getState Apr 27 12:52:16 volumio volumio[846]: verbose: ControllerMpd::sendMpdCommand status Apr 27 12:52:16 volumio volumio[846]: info: CoreStateMachine::play index undefined Apr 27 12:52:16 volumio volumio[846]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 27 12:52:16 volumio volumio[846]: info: CorePlayQueue::getTrack 5 Apr 27 12:52:16 volumio volumio[846]: info: CoreStateMachine::startPlaybackTimer Apr 27 12:52:16 volumio volumio[846]: info: CorePlayQueue::getTrack 5 Apr 27 12:52:16 volumio volumio[846]: verbose: ControllerMpd::clearAddPlayTracks NAS/Music/Carla Bruni/(2003) Quelqu'Un M'a Dit/1 - Quelqu'Un M'a Dit.mp3 Apr 27 12:52:16 volumio volumio[846]: verbose: ControllerMpd::sendMpdCommand stop Apr 27 12:52:16 volumio volumio[846]: info: sendMpdCommand status took 3 milliseconds Apr 27 12:52:16 volumio volumio[846]: info: sendMpdCommand stop took 1 milliseconds Apr 27 12:52:16 volumio volumio[846]: verbose: ControllerMpd::parseState Apr 27 12:52:16 volumio volumio[846]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 27 12:52:16 volumio volumio[846]: verbose: ControllerMpd::sendMpdCommand clear Apr 27 12:52:16 volumio volumio[846]: info: Apr 27 12:52:16 volumio volumio[846]: ---------------------------- MPD announces system playlist update Apr 27 12:52:16 volumio volumio[846]: info: Ignoring MPD Status Update Apr 27 12:52:16 volumio volumio[846]: info: sendMpdCommand playlistinfo took 2 milliseconds Apr 27 12:52:16 volumio volumio[846]: info: sendMpdCommand clear took 2 milliseconds Apr 27 12:52:16 volumio volumio[846]: verbose: ControllerMpd::parseTrackInfo Apr 27 12:52:16 volumio volumio[846]: verbose: ControllerMpd::sendMpdCommand add "NAS/Music/Carla Bruni/(2003) Quelqu'Un M'a Dit/1 - Quelqu'Un M'a Dit.mp3" Apr 27 12:52:16 volumio volumio[846]: info: ControllerMpd::pushState Apr 27 12:52:16 volumio volumio[846]: info: CoreCommandRouter::servicePushState Apr 27 12:52:16 volumio volumio[846]: info: CoreStateMachine::pushState Apr 27 12:52:16 volumio volumio[846]: info: CorePlayQueue::getTrack 5 Apr 27 12:52:16 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 27 12:52:16 volumio volumio[846]: info: CoreCommandRouter::volumioPushState Apr 27 12:52:17 volumio volumio[846]: info: CorePlayQueue::getTrack 5 Apr 27 12:52:17 volumio volumio[846]: verbose: STATE SERVICE {"status":"stop","position":0,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"Another Love","artist":"Tom Odell","album":"Long Way Down (Deluxe)","uri":"NAS/Music/Tom Odell/(2013) Long Way Down (Deluxe)/03 - Another Love.flac","trackType":"flac"} Apr 27 12:52:17 volumio volumio[846]: verbose: CURRENT POSITION 5 Apr 27 12:52:17 volumio volumio[846]: info: CoreStateMachine::syncState stateService stop Apr 27 12:52:17 volumio volumio[846]: info: CoreStateMachine::syncState currentStatus stop Apr 27 12:52:17 volumio volumio[846]: info: CoreStateMachine::pushState Apr 27 12:52:17 volumio volumio[846]: info: CorePlayQueue::getTrack 5 Apr 27 12:52:17 volumio volumio[846]: info: CoreCommandRouter::volumioPushState Apr 27 12:52:17 volumio volumio[846]: info: No code Apr 27 12:52:17 volumio volumio[846]: info: CoreStateMachine::pushState Apr 27 12:52:17 volumio volumio[846]: info: CorePlayQueue::getTrack 5 Apr 27 12:52:17 volumio volumio[846]: info: CoreCommandRouter::volumioPushState Apr 27 12:52:17 volumio volumio[846]: info: ------------------------------ 92ms Apr 27 12:52:17 volumio volumio[846]: error: updateQueue error: null Apr 27 12:52:17 volumio volumio[846]: info: Apr 27 12:52:17 volumio volumio[846]: ---------------------------- MPD announces system playlist update Apr 27 12:52:17 volumio volumio[846]: info: Ignoring MPD Status Update Apr 27 12:52:17 volumio volumio[846]: info: ------------------------------ 90ms Apr 27 12:52:17 volumio volumio[846]: info: sendMpdCommand add "NAS/Music/Carla Bruni/(2003) Quelqu'Un M'a Dit/1 - Quelqu'Un M'a Dit.mp3" took 88 milliseconds Apr 27 12:52:17 volumio volumio[846]: verbose: ControllerMpd::sendMpdCommand play Apr 27 12:52:17 volumio volumio[846]: info: ------------------------------ 20ms Apr 27 12:52:17 volumio volumio[846]: info: sendMpdCommand play took 18 milliseconds Apr 27 12:52:17 volumio volumio[846]: info: Apr 27 12:52:17 volumio volumio[846]: ---------------------------- MPD announces state update: player Apr 27 12:52:17 volumio volumio[846]: info: ControllerMpd::getState Apr 27 12:52:17 volumio volumio[846]: verbose: ControllerMpd::sendMpdCommand status Apr 27 12:52:17 volumio volumio[846]: info: Apr 27 12:52:17 volumio volumio[846]: ---------------------------- MPD announces state update: player Apr 27 12:52:17 volumio volumio[846]: info: sendMpdCommand status took 22 milliseconds Apr 27 12:52:17 volumio volumio[846]: info: ControllerMpd::getState Apr 27 12:52:17 volumio volumio[846]: verbose: ControllerMpd::sendMpdCommand status Apr 27 12:52:17 volumio volumio[846]: verbose: ControllerMpd::parseState Apr 27 12:52:17 volumio volumio[846]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 27 12:52:17 volumio volumio[846]: info: sendMpdCommand status took 4 milliseconds Apr 27 12:52:17 volumio volumio[846]: info: sendMpdCommand playlistinfo took 3 milliseconds Apr 27 12:52:17 volumio volumio[846]: verbose: ControllerMpd::parseState Apr 27 12:52:17 volumio volumio[846]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 27 12:52:17 volumio volumio[846]: verbose: ControllerMpd::parseTrackInfo Apr 27 12:52:17 volumio volumio[846]: info: ControllerMpd::pushState Apr 27 12:52:17 volumio volumio[846]: info: CoreCommandRouter::servicePushState Apr 27 12:52:17 volumio volumio[846]: info: CorePlayQueue::getTrack 5 Apr 27 12:52:17 volumio volumio[846]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":167,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"32 Kbps","isStreaming":false,"title":"Quelqu'Un M'a Dit","artist":"Carla Bruni","album":"Quelqu'Un M'a Dit","uri":"NAS/Music/Carla Bruni/(2003) Quelqu'Un M'a Dit/1 - Quelqu'Un M'a Dit.mp3","trackType":"mp3"} Apr 27 12:52:17 volumio volumio[846]: verbose: CURRENT POSITION 5 Apr 27 12:52:17 volumio volumio[846]: info: CoreStateMachine::syncState stateService play Apr 27 12:52:17 volumio volumio[846]: info: CoreStateMachine::syncState currentStatus stop Apr 27 12:52:17 volumio volumio[846]: info: ------------------------------ 38ms Apr 27 12:52:17 volumio volumio[846]: info: sendMpdCommand playlistinfo took 7 milliseconds Apr 27 12:52:17 volumio volumio[846]: verbose: ControllerMpd::parseTrackInfo Apr 27 12:52:17 volumio volumio[846]: info: ControllerMpd::pushState Apr 27 12:52:17 volumio volumio[846]: info: CoreCommandRouter::servicePushState Apr 27 12:52:17 volumio volumio[846]: info: CorePlayQueue::getTrack 5 Apr 27 12:52:17 volumio volumio[846]: verbose: STATE SERVICE {"status":"play","position":0,"seek":731,"duration":167,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"224 Kbps","isStreaming":false,"title":"Quelqu'Un M'a Dit","artist":"Carla Bruni","album":"Quelqu'Un M'a Dit","uri":"NAS/Music/Carla Bruni/(2003) Quelqu'Un M'a Dit/1 - Quelqu'Un M'a Dit.mp3","trackType":"mp3"} Apr 27 12:52:17 volumio volumio[846]: verbose: CURRENT POSITION 5 Apr 27 12:52:17 volumio volumio[846]: info: CoreStateMachine::syncState stateService play Apr 27 12:52:17 volumio volumio[846]: info: CoreStateMachine::syncState currentStatus play Apr 27 12:52:17 volumio volumio[846]: info: Received an update from plugin. extracting info from payload Apr 27 12:52:17 volumio volumio[846]: info: CoreStateMachine::pushState Apr 27 12:52:17 volumio volumio[846]: info: CorePlayQueue::getTrack 5 Apr 27 12:52:17 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 27 12:52:17 volumio volumio[846]: info: CoreCommandRouter::volumioPushState Apr 27 12:52:17 volumio volumio[846]: info: CoreStateMachine::pushState Apr 27 12:52:17 volumio volumio[846]: info: CorePlayQueue::getTrack 5 Apr 27 12:52:17 volumio volumio[846]: info: CoreCommandRouter::volumioPushState Apr 27 12:52:17 volumio volumio[846]: info: ------------------------------ 72ms Apr 27 12:52:17 volumio volumio[2444]: [Vollibrespot] : Pause Apr 27 12:52:17 volumio volumio[846]: [SpotifyConnect] Pause Apr 27 12:52:17 volumio volumio[846]: info: touch_display: Setting screensaver timeout to 0 seconds. Apr 27 12:52:19 volumio volumio[846]: info: CoreCommandRouter::volumioPause Apr 27 12:52:19 volumio volumio[846]: info: CoreStateMachine::pause Apr 27 12:52:19 volumio volumio[846]: info: CoreStateMachine::stPlaybackTimer Apr 27 12:52:19 volumio volumio[846]: info: CoreStateMachine::servicePause Apr 27 12:52:19 volumio volumio[846]: info: CorePlayQueue::getTrack 5 Apr 27 12:52:19 volumio volumio[846]: info: CoreCommandRouter::servicePause Apr 27 12:52:19 volumio volumio[846]: info: ControllerMpd::pause Apr 27 12:52:19 volumio volumio[846]: verbose: ControllerMpd::sendMpdCommand pause Apr 27 12:52:19 volumio volumio[846]: info: Apr 27 12:52:19 volumio volumio[846]: ---------------------------- MPD announces state update: player Apr 27 12:52:19 volumio volumio[846]: info: sendMpdCommand pause took 87 milliseconds Apr 27 12:52:19 volumio volumio[846]: info: ControllerMpd::getState Apr 27 12:52:19 volumio volumio[846]: verbose: ControllerMpd::sendMpdCommand status Apr 27 12:52:19 volumio volumio[846]: info: sendMpdCommand status took 1 milliseconds Apr 27 12:52:19 volumio volumio[846]: verbose: ControllerMpd::parseState Apr 27 12:52:19 volumio volumio[846]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 27 12:52:19 volumio volumio[846]: info: sendMpdCommand playlistinfo took 1 milliseconds Apr 27 12:52:19 volumio volumio[846]: verbose: ControllerMpd::parseTrackInfo Apr 27 12:52:19 volumio volumio[846]: info: ControllerMpd::pushState Apr 27 12:52:19 volumio volumio[846]: info: CoreCommandRouter::servicePushState Apr 27 12:52:19 volumio volumio[846]: info: CorePlayQueue::getTrack 5 Apr 27 12:52:19 volumio volumio[846]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":2765,"duration":167,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"192 Kbps","isStreaming":false,"title":"Quelqu'Un M'a Dit","artist":"Carla Bruni","album":"Quelqu'Un M'a Dit","uri":"NAS/Music/Carla Bruni/(2003) Quelqu'Un M'a Dit/1 - Quelqu'Un M'a Dit.mp3","trackType":"mp3"} Apr 27 12:52:19 volumio volumio[846]: verbose: CURRENT POSITION 5 Apr 27 12:52:19 volumio volumio[846]: info: CoreStateMachine::syncState stateService pause Apr 27 12:52:19 volumio volumio[846]: info: CoreStateMachine::syncState currentStatus pause Apr 27 12:52:19 volumio volumio[846]: info: CoreStateMachine::pushState Apr 27 12:52:19 volumio volumio[846]: info: CorePlayQueue::getTrack 5 Apr 27 12:52:19 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 27 12:52:19 volumio volumio[846]: info: CoreCommandRouter::volumioPushState Apr 27 12:52:19 volumio volumio[846]: info: CoreStateMachine::stPlaybackTimer Apr 27 12:52:19 volumio volumio[846]: info: ------------------------------ 23ms Apr 27 12:52:19 volumio volumio[846]: info: touch_display: Setting screensaver timeout to 15 seconds. Apr 27 12:52:25 volumio volumio[2444]: [Vollibrespot] : Event: SessionActive { became_active_at: 1714243945002 } Apr 27 12:52:25 volumio volumio[2444]: [Vollibrespot] : SessionActive! Apr 27 12:52:25 volumio volumio[846]: [SpotifyConnect] A connect session has begun Apr 27 12:52:25 volumio volumio[846]: info: Acquiring new spotify session Apr 27 12:52:25 volumio volumio[846]: info: CoreCommandRouter::volumioStop Apr 27 12:52:25 volumio volumio[846]: info: CoreStateMachine::stop Apr 27 12:52:25 volumio volumio[846]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 27 12:52:25 volumio volumio[846]: info: CoreStateMachine::updateTrackBlock Apr 27 12:52:25 volumio volumio[846]: info: CorePlayQueue::getTrackBlock Apr 27 12:52:25 volumio volumio[846]: info: CoreStateMachine::stPlaybackTimer Apr 27 12:52:25 volumio volumio[846]: info: CoreStateMachine::pushState Apr 27 12:52:25 volumio volumio[846]: info: CorePlayQueue::getTrack 5 Apr 27 12:52:25 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 27 12:52:25 volumio volumio[846]: info: CoreCommandRouter::volumioPushState Apr 27 12:52:25 volumio volumio[2444]: [Vollibrespot] : Fetching autoplay context uri Apr 27 12:52:25 volumio volumio[2444]: [Vollibrespot] : Event: PlaybackStarted { track_id: SpotifyId { id: 189350768725515119474995331378653767417, audio_type: Track } } Apr 27 12:52:25 volumio volumio[2444]: [Vollibrespot] : Event: PlaybackLoading { track_id: SpotifyId { id: 189350768725515119474995331378653767417, audio_type: Track } } Apr 27 12:52:25 volumio volumio[846]: info: CoreStateMachine::serviceStop Apr 27 12:52:25 volumio volumio[846]: info: CorePlayQueue::getTrack 5 Apr 27 12:52:25 volumio volumio[846]: info: CoreCommandRouter::serviceStop Apr 27 12:52:25 volumio volumio[846]: info: ControllerMpd::stop Apr 27 12:52:25 volumio volumio[846]: verbose: ControllerMpd::sendMpdCommand stop Apr 27 12:52:25 volumio volumio[846]: [SpotifyConnect] Device palyback is active! Apr 27 12:52:25 volumio volumio[846]: [SpotifyConnect] Device palyback is loading Apr 27 12:52:25 volumio volumio[846]: info: Apr 27 12:52:25 volumio volumio[846]: ---------------------------- MPD announces state update: player Apr 27 12:52:25 volumio volumio[846]: info: sendMpdCommand stop took 22 milliseconds Apr 27 12:52:25 volumio volumio[846]: info: ControllerMpd::getState Apr 27 12:52:25 volumio volumio[846]: verbose: ControllerMpd::sendMpdCommand status Apr 27 12:52:25 volumio volumio[846]: info: Checking Spotify Web API Apr 27 12:52:25 volumio volumio[846]: [SpotifyConnect] Vollibrespot Active Apr 27 12:52:25 volumio volumio[846]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 27 12:52:25 volumio volumio[846]: info: [1714243945038] ControllerSpotify::pushState Apr 27 12:52:25 volumio volumio[846]: info: CoreCommandRouter::servicePushState Apr 27 12:52:25 volumio volumio[846]: info: CoreStateMachine::pushState Apr 27 12:52:25 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 27 12:52:25 volumio volumio[846]: info: CoreCommandRouter::volumioPushState Apr 27 12:52:25 volumio volumio[846]: info: sendMpdCommand status took 17 milliseconds Apr 27 12:52:25 volumio volumio[846]: verbose: ControllerMpd::parseState Apr 27 12:52:25 volumio volumio[846]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 27 12:52:25 volumio volumio[2444]: [Vollibrespot] : Autoplay uri resolved to <"spotify:station:playlist:07Ywfj7rHULpJsL8HioxTX"> Apr 27 12:52:25 volumio volumio[2444]: [Vollibrespot] : Resolving uri "spotify:station:playlist:07Ywfj7rHULpJsL8HioxTX" Apr 27 12:52:25 volumio volumio[2444]: [Vollibrespot] : Loading with Spotify URI Apr 27 12:52:25 volumio volumio[846]: info: sendMpdCommand playlistinfo took 29 milliseconds Apr 27 12:52:25 volumio volumio[846]: verbose: ControllerMpd::parseTrackInfo Apr 27 12:52:25 volumio volumio[846]: info: ControllerMpd::pushState Apr 27 12:52:25 volumio volumio[846]: info: CoreCommandRouter::servicePushState Apr 27 12:52:25 volumio volumio[846]: info: CoreStateMachine::pushState Apr 27 12:52:25 volumio volumio[846]: info: CoreCommandRouter::volumioPushState Apr 27 12:52:25 volumio volumio[846]: info: CorePlayQueue::getTrack 5 Apr 27 12:52:25 volumio volumio[846]: verbose: STATE SERVICE {"status":"stop","position":0,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"Quelqu'Un M'a Dit","artist":"Carla Bruni","album":"Quelqu'Un M'a Dit","uri":"NAS/Music/Carla Bruni/(2003) Quelqu'Un M'a Dit/1 - Quelqu'Un M'a Dit.mp3","trackType":"mp3"} Apr 27 12:52:25 volumio volumio[846]: verbose: CURRENT POSITION 5 Apr 27 12:52:25 volumio volumio[846]: info: CoreStateMachine::syncState stateService stop Apr 27 12:52:25 volumio volumio[846]: info: CoreStateMachine::syncState currentStatus play Apr 27 12:52:25 volumio volumio[846]: info: CoreStateMachine::play index undefined Apr 27 12:52:25 volumio volumio[846]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 27 12:52:25 volumio volumio[846]: info: CoreStateMachine::pushState Apr 27 12:52:25 volumio volumio[846]: info: CoreCommandRouter::volumioPushState Apr 27 12:52:25 volumio volumio[846]: info: CorePlayQueue::getTrack 111 Apr 27 12:52:25 volumio volumio[846]: info: CoreStateMachine::startPlaybackTimer Apr 27 12:52:25 volumio volumio[846]: info: CorePlayQueue::getTrack 111 Apr 27 12:52:25 volumio volumio[846]: verbose: ControllerMpd::clearAddPlayTracks NAS/Music/Sungha Jung/(2013) Paint It Acoustic/02 - The Phantom Of The Opera.flac Apr 27 12:52:25 volumio volumio[846]: verbose: ControllerMpd::sendMpdCommand stop Apr 27 12:52:25 volumio volumio[846]: info: ------------------------------ 91ms Apr 27 12:52:25 volumio volumio[846]: info: CoreStateMachine::pushState Apr 27 12:52:25 volumio volumio[846]: info: CoreCommandRouter::volumioPushState Apr 27 12:52:25 volumio volumio[2444]: [Vollibrespot] : Event: GotToken { token: Token { access_token: "BQBTWgWGgUzz3BYSrqb9L77GrgyU1FLi5XUydVUCBaFnRefWHj5qzSFvk4wIiXVMRuZ-ou8QKTp2UKMYV1wFa8N9kDukvzxh0lN8v-7bvZ0TzzW-1UALF8UAwrWw5jhRjOkLVikqTW5ZOMk4SA7nxfgqck_BDEfhxZz2pzVelGzd9DqSJJgSRbfxdrg_S3LaMZD_Tqk", expires_in: 3600, token_type: "Bearer", scope: ["streaming", "user-read-playback-state", "user-modify-playback-state", "user-read-currently-playing", "user-read-private"] } } Apr 27 12:52:25 volumio volumio[846]: info: sendMpdCommand stop took 43 milliseconds Apr 27 12:52:25 volumio volumio[846]: verbose: ControllerMpd::sendMpdCommand clear Apr 27 12:52:25 volumio volumio[846]: error: Received malformed Token, ignoring Apr 27 12:52:25 volumio volumio[846]: info: Apr 27 12:52:25 volumio volumio[846]: ---------------------------- MPD announces system playlist update Apr 27 12:52:25 volumio volumio[846]: info: Ignoring MPD Status Update Apr 27 12:52:25 volumio volumio[846]: info: sendMpdCommand clear took 24 milliseconds Apr 27 12:52:25 volumio volumio[846]: verbose: ControllerMpd::sendMpdCommand add "NAS/Music/Sungha Jung/(2013) Paint It Acoustic/02 - The Phantom Of The Opera.flac" Apr 27 12:52:25 volumio volumio[846]: info: touch_display: Setting screensaver timeout to 0 seconds. Apr 27 12:52:25 volumio volumio[846]: error: updateQueue error: null Apr 27 12:52:25 volumio volumio[846]: info: Apr 27 12:52:25 volumio volumio[846]: ---------------------------- MPD announces system playlist update Apr 27 12:52:25 volumio volumio[846]: info: Ignoring MPD Status Update Apr 27 12:52:25 volumio volumio[846]: info: ------------------------------ 7ms Apr 27 12:52:25 volumio volumio[846]: info: sendMpdCommand add "NAS/Music/Sungha Jung/(2013) Paint It Acoustic/02 - The Phantom Of The Opera.flac" took 4 milliseconds Apr 27 12:52:25 volumio volumio[846]: verbose: ControllerMpd::sendMpdCommand play Apr 27 12:52:25 volumio volumio[846]: info: ------------------------------ 3ms Apr 27 12:52:25 volumio volumio[846]: info: sendMpdCommand play took 2 milliseconds Apr 27 12:52:25 volumio volumio[846]: info: Apr 27 12:52:25 volumio volumio[846]: ---------------------------- MPD announces state update: player Apr 27 12:52:25 volumio volumio[846]: info: ControllerMpd::getState Apr 27 12:52:25 volumio volumio[846]: verbose: ControllerMpd::sendMpdCommand status Apr 27 12:52:25 volumio volumio[846]: info: Apr 27 12:52:25 volumio volumio[846]: ---------------------------- MPD announces state update: player Apr 27 12:52:25 volumio volumio[846]: info: sendMpdCommand status took 19 milliseconds Apr 27 12:52:25 volumio volumio[846]: info: ControllerMpd::getState Apr 27 12:52:25 volumio volumio[846]: verbose: ControllerMpd::sendMpdCommand status Apr 27 12:52:25 volumio volumio[846]: verbose: ControllerMpd::parseState Apr 27 12:52:25 volumio volumio[846]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 27 12:52:25 volumio volumio[846]: info: sendMpdCommand status took 3 milliseconds Apr 27 12:52:25 volumio volumio[846]: info: sendMpdCommand playlistinfo took 2 milliseconds Apr 27 12:52:25 volumio volumio[846]: verbose: ControllerMpd::parseState Apr 27 12:52:25 volumio volumio[846]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 27 12:52:25 volumio volumio[846]: verbose: ControllerMpd::parseTrackInfo Apr 27 12:52:25 volumio volumio[846]: info: ControllerMpd::pushState Apr 27 12:52:25 volumio volumio[846]: info: CoreCommandRouter::servicePushState Apr 27 12:52:25 volumio volumio[846]: info: CoreStateMachine::pushState Apr 27 12:52:25 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 27 12:52:25 volumio volumio[846]: info: CoreCommandRouter::volumioPushState Apr 27 12:52:25 volumio volumio[846]: info: ------------------------------ 62ms Apr 27 12:52:25 volumio volumio[846]: info: sendMpdCommand playlistinfo took 27 milliseconds Apr 27 12:52:25 volumio volumio[846]: verbose: ControllerMpd::parseTrackInfo Apr 27 12:52:25 volumio volumio[846]: info: ControllerMpd::pushState Apr 27 12:52:25 volumio volumio[846]: info: CoreCommandRouter::servicePushState Apr 27 12:52:25 volumio volumio[846]: info: CoreStateMachine::pushState Apr 27 12:52:25 volumio volumio[846]: info: CoreCommandRouter::volumioPushState Apr 27 12:52:25 volumio volumio[846]: info: ------------------------------ 68ms Apr 27 12:52:25 volumio volumio[2444]: [Vollibrespot] : Resolved 50 tracks from <"spotify:playlist:07Ywfj7rHULpJsL8HioxTX"> Apr 27 12:52:26 volumio volumio[2444]: [Vollibrespot] : (112421 ms) loaded Apr 27 12:52:26 volumio volumio[2444]: [Vollibrespot] : Alsa error PCM open ALSA function 'snd_pcm_open' failed with error 'EBUSY: Device or resource busy' Apr 27 12:52:26 volumio volumio[2444]: [Vollibrespot] : Could not start audio: Alsa error: PCM open failed Apr 27 12:52:26 volumio volumio[2444]: [Vollibrespot] : Alsa error PCM open ALSA function 'snd_pcm_open' failed with error 'EBUSY: Device or resource busy' Apr 27 12:52:26 volumio volumio[2444]: [Vollibrespot] : Could not start audio: Alsa error: PCM open failed Apr 27 12:52:26 volumio volumio[2444]: [Vollibrespot] : Alsa error PCM open ALSA function 'snd_pcm_open' failed with error 'EBUSY: Device or resource busy' Apr 27 12:52:26 volumio volumio[2444]: [Vollibrespot] : Could not start audio: Alsa error: PCM open failed Apr 27 12:52:26 volumio volumio[2444]: 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 Apr 27 12:52:26 volumio volumio[2444]: stack backtrace: Apr 27 12:52:26 volumio volumio[2444]: 0: 0x988444 - std::backtrace_rs::backtrace::libunwind::trace::h40a4eff66330a36d Apr 27 12:52:26 volumio volumio[2444]: at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/../../backtrace/src/backtrace/libunwind.rs:93:5 Apr 27 12:52:26 volumio volumio[2444]: 1: 0x988444 - std::backtrace_rs::backtrace::trace_unsynchronized::hbce01963451b0cd5 Apr 27 12:52:26 volumio volumio[2444]: at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/../../backtrace/src/backtrace/mod.rs:66:5 Apr 27 12:52:26 volumio volumio[2444]: 2: 0x988444 - std::sys_common::backtrace::_print_fmt::h95da650d09c7e00b Apr 27 12:52:26 volumio volumio[2444]: at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/sys_common/backtrace.rs:66:5 Apr 27 12:52:26 volumio volumio[2444]: 3: 0x988444 - ::fmt::h33b23b1d14f668ff Apr 27 12:52:26 volumio volumio[2444]: at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/sys_common/backtrace.rs:45:22 Apr 27 12:52:26 volumio volumio[2444]: 4: 0x9b10dc - core::fmt::write::h6320fb0e6ac90e58 Apr 27 12:52:26 volumio volumio[2444]: at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/core/src/fmt/mod.rs:1190:17 Apr 27 12:52:26 volumio volumio[2444]: 5: 0x9804c4 - std::io::Write::write_fmt::h33b25d4810ca481f Apr 27 12:52:26 volumio volumio[2444]: at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/io/mod.rs:1657:15 Apr 27 12:52:26 volumio volumio[2444]: 6: 0x98aef4 - std::sys_common::backtrace::_print::h7e61c5be69c715ef Apr 27 12:52:26 volumio volumio[2444]: at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/sys_common/backtrace.rs:48:5 Apr 27 12:52:26 volumio volumio[2444]: 7: 0x98aef4 - std::sys_common::backtrace::print::h3cee176d7c8dab8b Apr 27 12:52:26 volumio volumio[2444]: at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/sys_common/backtrace.rs:35:9 Apr 27 12:52:26 volumio volumio[2444]: 8: 0x98aef4 - std::panicking::default_hook::{{closure}}::h2d0211dd2e97dc43 Apr 27 12:52:26 volumio volumio[2444]: at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/panicking.rs:295:22 Apr 27 12:52:26 volumio volumio[2444]: 9: 0x98ab14 - std::panicking::default_hook::hcbdb3b7c40dca30c Apr 27 12:52:26 volumio volumio[2444]: at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/panicking.rs:314:9 Apr 27 12:52:26 volumio volumio[2444]: 10: 0x98b694 - std::panicking::rust_panic_with_hook::h4ce49e7a343dc12b Apr 27 12:52:26 volumio volumio[2444]: at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/panicking.rs:698:17 Apr 27 12:52:26 volumio volumio[2444]: 11: 0x98b360 - std::panicking::begin_panic_handler::{{closure}}::h4961100fae529fe9 Apr 27 12:52:26 volumio volumio[2444]: at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/panicking.rs:586:13 Apr 27 12:52:26 volumio volumio[2444]: 12: 0x9889c4 - std::sys_common::backtrace::__rust_end_short_backtrace::hf2e68e62c7a80f1f Apr 27 12:52:26 volumio volumio[2444]: at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/sys_common/backtrace.rs:138:18 Apr 27 12:52:26 volumio volumio[2444]: 13: 0x98b098 - rust_begin_unwind Apr 27 12:52:26 volumio volumio[2444]: at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/panicking.rs:584:5 Apr 27 12:52:26 volumio volumio[2444]: 14: 0x46e6f4 - core::panicking::panic_fmt::h84c42730e4a50809 Apr 27 12:52:26 volumio volumio[2444]: at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/core/src/panicking.rs:143:14 Apr 27 12:52:26 volumio volumio[2444]: 15: 0x46e5c8 - core::panicking::panic::h929d4344847bfdba Apr 27 12:52:26 volumio volumio[2444]: at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/core/src/panicking.rs:48:5 Apr 27 12:52:26 volumio volumio[2444]: 16: 0x5a9158 - ::write::h2857e81996e06a1e Apr 27 12:52:26 volumio volumio[2444]: 17: 0x58b814 - ::poll::hf6331a81451dbb28 Apr 27 12:52:26 volumio volumio[2444]: 18: 0x4b36c0 - futures::task_impl::std::set::hb731921744f9247e Apr 27 12:52:26 volumio volumio[2444]: 19: 0x4a4708 - futures::task_impl::Spawn::poll_future_notify::h08f2c87ba9a4eead Apr 27 12:52:26 volumio volumio[2444]: 20: 0x4b8158 - std::sys_common::backtrace::__rust_begin_short_backtrace::hb598e9d2970dbf13 Apr 27 12:52:26 volumio volumio[2444]: 21: 0x4e4e70 - core::ops::function::FnOnce::call_once{{vtable.shim}}::h7f140b0cfa5289e1 Apr 27 12:52:26 volumio volumio[2444]: 22: 0x98febc - as core::ops::function::FnOnce>::call_once::hbc4d03a1815e028a Apr 27 12:52:26 volumio volumio[2444]: at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/alloc/src/boxed.rs:1853:9 Apr 27 12:52:26 volumio volumio[2444]: 23: 0x98febc - as core::ops::function::FnOnce>::call_once::h6055603e421418e8 Apr 27 12:52:26 volumio volumio[2444]: at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/alloc/src/boxed.rs:1853:9 Apr 27 12:52:26 volumio volumio[2444]: 24: 0x98febc - std::sys::unix::thread::Thread::new::thread_start::h0518d9d0e6b0ba31 Apr 27 12:52:26 volumio volumio[2444]: at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/sys/unix/thread.rs:108:17 Apr 27 12:52:29 volumio volumio[2444]: thread 'main' panicked at 'called `Result::unwrap()` on an `Err` value: SendError("...")', /build/cache/git/checkouts/librespot-6f197fd632ef9380/08d8bcc/playback/src/player.rs:232:61 Apr 27 12:52:29 volumio volumio[2444]: stack backtrace: Apr 27 12:52:29 volumio volumio[2444]: 0: 0x988444 - std::backtrace_rs::backtrace::libunwind::trace::h40a4eff66330a36d Apr 27 12:52:29 volumio volumio[2444]: at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/../../backtrace/src/backtrace/libunwind.rs:93:5 Apr 27 12:52:29 volumio volumio[2444]: 1: 0x988444 - std::backtrace_rs::backtrace::trace_unsynchronized::hbce01963451b0cd5 Apr 27 12:52:29 volumio volumio[2444]: at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/../../backtrace/src/backtrace/mod.rs:66:5 Apr 27 12:52:29 volumio volumio[2444]: 2: 0x988444 - std::sys_common::backtrace::_print_fmt::h95da650d09c7e00b Apr 27 12:52:29 volumio volumio[2444]: at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/sys_common/backtrace.rs:66:5 Apr 27 12:52:29 volumio volumio[2444]: 3: 0x988444 - ::fmt::h33b23b1d14f668ff Apr 27 12:52:29 volumio volumio[2444]: at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/sys_common/backtrace.rs:45:22 Apr 27 12:52:29 volumio volumio[2444]: 4: 0x9b10dc - core::fmt::write::h6320fb0e6ac90e58 Apr 27 12:52:29 volumio volumio[2444]: at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/core/src/fmt/mod.rs:1190:17 Apr 27 12:52:29 volumio volumio[2444]: 5: 0x9804c4 - std::io::Write::write_fmt::h33b25d4810ca481f Apr 27 12:52:29 volumio volumio[2444]: at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/io/mod.rs:1657:15 Apr 27 12:52:29 volumio volumio[2444]: 6: 0x98aef4 - std::sys_common::backtrace::_print::h7e61c5be69c715ef Apr 27 12:52:29 volumio volumio[2444]: at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/sys_common/backtrace.rs:48:5 Apr 27 12:52:29 volumio volumio[2444]: 7: 0x98aef4 - std::sys_common::backtrace::print::h3cee176d7c8dab8b Apr 27 12:52:29 volumio volumio[2444]: at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/sys_common/backtrace.rs:35:9 Apr 27 12:52:29 volumio volumio[2444]: 8: 0x98aef4 - std::panicking::default_hook::{{closure}}::h2d0211dd2e97dc43 Apr 27 12:52:29 volumio volumio[2444]: at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/panicking.rs:295:22 Apr 27 12:52:29 volumio volumio[2444]: 9: 0x98ab14 - std::panicking::default_hook::hcbdb3b7c40dca30c Apr 27 12:52:29 volumio volumio[2444]: at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/panicking.rs:314:9 Apr 27 12:52:29 volumio volumio[2444]: 10: 0x98b694 - std::panicking::rust_panic_with_hook::h4ce49e7a343dc12b Apr 27 12:52:29 volumio volumio[2444]: at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/panicking.rs:698:17 Apr 27 12:52:29 volumio volumio[2444]: 11: 0x98b304 - std::panicking::begin_panic_handler::{{closure}}::h4961100fae529fe9 Apr 27 12:52:29 volumio volumio[2444]: at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/panicking.rs:588:13 Apr 27 12:52:29 volumio volumio[2444]: 12: 0x9889c4 - std::sys_common::backtrace::__rust_end_short_backtrace::hf2e68e62c7a80f1f Apr 27 12:52:29 volumio volumio[2444]: at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/sys_common/backtrace.rs:138:18 Apr 27 12:52:29 volumio volumio[2444]: 13: 0x98b098 - rust_begin_unwind Apr 27 12:52:29 volumio volumio[2444]: at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/panicking.rs:584:5 Apr 27 12:52:29 volumio volumio[2444]: 14: 0x46e6f4 - core::panicking::panic_fmt::h84c42730e4a50809 Apr 27 12:52:29 volumio volumio[2444]: at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/core/src/panicking.rs:143:14 Apr 27 12:52:29 volumio volumio[2444]: 15: 0x46e7c8 - core::result::unwrap_failed::h43118a132315b545 Apr 27 12:52:29 volumio volumio[2444]: at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/core/src/result.rs:1749:5 Apr 27 12:52:29 volumio volumio[2444]: 16: 0x588d9c - librespot_playback::player::Player::command::h858bc51b80bfd51a Apr 27 12:52:29 volumio volumio[2444]: 17: 0x588e78 - librespot_playback::player::Player::load::h459ab75b63e85c77 Apr 27 12:52:29 volumio volumio[2444]: 18: 0x55e0e8 - librespot_connect::spirc::SpircTask::load_track::h0f2f2105e3286684 Apr 27 12:52:29 volumio volumio[2444]: 19: 0x55c88c - librespot_connect::spirc::SpircTask::handle_next::h85b0afb871d54f63 Apr 27 12:52:29 volumio volumio[2444]: 20: 0x55b0d0 - ::poll::h2a7bff75029d3b82 Apr 27 12:52:29 volumio volumio[2444]: 21: 0x4962ec - ::poll::h5fd9e3bcdeb25ad9 Apr 27 12:52:29 volumio volumio[2444]: 22: 0x4b33dc - futures::task_impl::std::set::h8f754e80bd562d0a Apr 27 12:52:29 volumio volumio[2444]: 23: 0x4ca42c - std::thread::local::LocalKey::with::h71cfa1e374fcc0a0 Apr 27 12:52:29 volumio volumio[2444]: 24: 0x4af99c - tokio_current_thread::Entered

::block_on::hde55cdf28eabe6d5 Apr 27 12:52:29 volumio volumio[2444]: 25: 0x4ca6f0 - std::thread::local::LocalKey::with::hedba3cfe41326627 Apr 27 12:52:29 volumio volumio[2444]: 26: 0x4b2880 - tokio::runtime::current_thread::runtime::Runtime::block_on::h60d5b89560100ed8 Apr 27 12:52:29 volumio volumio[2444]: 27: 0x498eb0 - vollibrespot::main::h35555355ed947dd1 Apr 27 12:52:29 volumio volumio[2444]: 28: 0x4b8c50 - std::sys_common::backtrace::__rust_begin_short_backtrace::hef626a10d324c12a Apr 27 12:52:29 volumio volumio[2444]: 29: 0x4de52c - std::rt::lang_start::{{closure}}::hd80188e4bcac5072 Apr 27 12:52:29 volumio volumio[2444]: 30: 0x987b28 - core::ops::function::impls:: for &F>::call_once::h0567da839a080232 Apr 27 12:52:29 volumio volumio[2444]: at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/core/src/ops/function.rs:259:13 Apr 27 12:52:29 volumio volumio[2444]: 31: 0x987b28 - std::panicking::try::do_call::hdf194554a41aa3cc Apr 27 12:52:29 volumio volumio[2444]: at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/panicking.rs:492:40 Apr 27 12:52:29 volumio volumio[2444]: 32: 0x987b28 - std::panicking::try::hbf4b7be9f9ffa5f8 Apr 27 12:52:29 volumio volumio[2444]: at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/panicking.rs:456:19 Apr 27 12:52:29 volumio volumio[2444]: 33: 0x987b28 - std::panic::catch_unwind::h45f392a39f2fe48c Apr 27 12:52:29 volumio volumio[2444]: at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/panic.rs:137:14 Apr 27 12:52:29 volumio volumio[2444]: 34: 0x987b28 - std::rt::lang_start_internal::{{closure}}::hd772cb03c2060671 Apr 27 12:52:29 volumio volumio[2444]: at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/rt.rs:128:48 Apr 27 12:52:29 volumio volumio[2444]: 35: 0x987b28 - std::panicking::try::do_call::hd126f715b519ff2a Apr 27 12:52:29 volumio volumio[2444]: at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/panicking.rs:492:40 Apr 27 12:52:29 volumio volumio[2444]: 36: 0x987b28 - std::panicking::try::h80b7148ce71893dc Apr 27 12:52:29 volumio volumio[2444]: at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/panicking.rs:456:19 Apr 27 12:52:29 volumio volumio[2444]: 37: 0x987b28 - std::panic::catch_unwind::h1562f0b2e8a9cb0d Apr 27 12:52:29 volumio volumio[2444]: at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/panic.rs:137:14 Apr 27 12:52:29 volumio volumio[2444]: 38: 0x987b28 - std::rt::lang_start_internal::h3daa586a0b835507 Apr 27 12:52:29 volumio volumio[2444]: at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/rt.rs:128:20 Apr 27 12:52:29 volumio volumio[2444]: 39: 0x49ae80 - main Apr 27 12:52:29 volumio volumio[2444]: 40: 0xb6bdd718 - __libc_start_main Apr 27 12:52:29 volumio volumio[2444]: [Vollibrespot] : Player thread panicked! Apr 27 12:52:29 volumio volumio[2444]: [Vollibrespot] : EventSender disconnected Apr 27 12:52:29 volumio volumio[846]: [SpotifyConnect] PlaybackInactive Apr 27 12:52:29 volumio volumio[846]: info: [1714243949535] ControllerSpotify::pushState Apr 27 12:52:29 volumio volumio[846]: info: CoreCommandRouter::servicePushState Apr 27 12:52:29 volumio volumio[846]: info: CoreStateMachine::pushState Apr 27 12:52:29 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 27 12:52:29 volumio volumio[846]: info: CoreCommandRouter::volumioPushState Apr 27 12:52:29 volumio systemd[1]: volspotconnect.service: Main process exited, code=exited, status=101/n/a Apr 27 12:52:29 volumio systemd[1]: volspotconnect.service: Failed with result 'exit-code'. Apr 27 12:52:29 volumio volumio[846]: info: touch_display: Setting screensaver timeout to 15 seconds. Apr 27 12:52:31 volumio systemd[1]: volspotconnect.service: Service RestartSec=2s expired, scheduling restart. Apr 27 12:52:31 volumio systemd[1]: volspotconnect.service: Scheduled restart job, restart counter is at 2. Apr 27 12:52:31 volumio systemd[1]: Stopped Volspotconnect2 Daemon. Apr 27 12:52:31 volumio systemd[1]: Started Volspotconnect2 Daemon. Apr 27 12:52:31 volumio volumio[2468]: vollibrespot v0.2.5 8922128 2022-05-31 (librespot 08d8bcc 2020-10-07) -- Built On 2022-05-31 Apr 27 12:52:31 volumio volumio[2468]: Reading Config from "/tmp/volspotify.toml" Apr 27 12:52:31 volumio volumio[2468]: [Vollibrespot] : Using Alsa backend with device: peppyalsa Apr 27 12:52:31 volumio volumio[2468]: [Vollibrespot] : Failed to register IPv6 receiver: Os { code: 19, kind: Uncategorized, message: "No such device" } Apr 27 12:52:31 volumio volumio[2468]: [Vollibrespot] : Connecting to AP "ap-guc3.spotify.com:443" Apr 27 12:52:32 volumio volumio[2468]: [Vollibrespot] : Authenticated as "12183471479" ! Apr 27 12:52:32 volumio volumio[2468]: [Vollibrespot] : Using alsa sink Apr 27 12:52:32 volumio volumio[2468]: [Vollibrespot] : Metadata pipe established Apr 27 12:52:32 volumio volumio[2468]: [Vollibrespot] : Country: "CA" Apr 27 12:52:32 volumio volumio[2468]: [Vollibrespot] : Event: Volume { volume_to_mixer: 49151 } Apr 27 12:52:32 volumio volumio[846]: [SpotifyConnect] Volume Spotify: 74.99961852445259 Volumio: 75 Apr 27 12:52:43 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 27 12:52:43 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 27 12:52:43 volumio volumio[846]: info: Discovery: Getting this device information Apr 27 12:52:43 volumio volumio[846]: info: CoreCommandRouter::volumioGetState Apr 27 12:52:43 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 27 12:52:44 volumio volumio[846]: verbose: New Socket.io Connection to 192.168.1.40 from 192.168.1.221 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 17_4_1 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Total Clients: 9 Apr 27 12:52:46 volumio sudo[2479]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Apr 27 12:52:46 volumio sudo[2479]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 27 12:52:46 volumio sudo[2479]: pam_unix(sudo:session): session closed for user root Apr 27 12:52:46 volumio sudo[2481]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Apr 27 12:52:46 volumio sudo[2481]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 27 12:52:46 volumio sudo[2481]: pam_unix(sudo:session): session closed for user root Apr 27 12:52:46 volumio volumio[846]: verbose: New Socket.io Connection to 192.168.1.40 from 192.168.1.221 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 17_4_1 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Total Clients: 10 Apr 27 12:52:47 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Apr 27 12:52:47 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Apr 27 12:52:47 volumio volumio[846]: info: CoreCommandRouter::volumioGetVisibleSources Apr 27 12:52:47 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 27 12:52:47 volumio volumio[846]: info: CoreCommandRouter::volumioGetState Apr 27 12:52:47 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Apr 27 12:52:47 volumio volumio[846]: info: Received Get System Info Apr 27 12:52:47 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 27 12:52:47 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 27 12:52:47 volumio volumio[846]: info: Discovery: Getting this device information Apr 27 12:52:47 volumio volumio[846]: info: CoreCommandRouter::volumioGetState Apr 27 12:52:47 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 27 12:52:47 volumio volumio[846]: info: CoreCommandRouter::volumioGetState Apr 27 12:52:47 volumio volumio[846]: info: Listing playlists Apr 27 12:52:47 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Apr 27 12:52:47 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Apr 27 12:52:47 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Apr 27 12:52:48 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Apr 27 12:52:48 volumio volumio[846]: info: Received Get System Info Apr 27 12:52:48 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 27 12:52:48 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 27 12:52:48 volumio volumio[846]: info: Discovery: Getting this device information Apr 27 12:52:48 volumio volumio[846]: info: CoreCommandRouter::volumioGetState Apr 27 12:52:48 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 27 12:52:49 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Apr 27 12:52:49 volumio volumio[846]: info: Received Get System Info Apr 27 12:52:49 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 27 12:52:49 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 27 12:52:49 volumio volumio[846]: info: Discovery: Getting this device information Apr 27 12:52:49 volumio volumio[846]: info: CoreCommandRouter::volumioGetState Apr 27 12:52:49 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 27 12:52:51 volumio volumio[846]: info: CoreCommandRouter::volumioVolatilePlay Apr 27 12:52:51 volumio volumio[846]: info: CoreStateMachine::volatilePlay Apr 27 12:52:51 volumio volumio[846]: info: Spotify Play Apr 27 12:52:52 volumio volumio[846]: info: CoreCommandRouter::volumioGetQueue Apr 27 12:52:52 volumio volumio[846]: info: CoreStateMachine::getQueue Apr 27 12:52:52 volumio volumio[846]: info: CorePlayQueue::getQueue Apr 27 12:52:53 volumio volumio[846]: info: CoreCommandRouter::volumioPlay Apr 27 12:52:53 volumio volumio[846]: verbose: UNSET VOLATILE: Service: spop Apr 27 12:52:53 volumio volumio[846]: [SpotifyConnect] unSetVolatile called Apr 27 12:52:53 volumio volumio[846]: info: Spotify Unset Volatile called Apr 27 12:52:53 volumio volumio[846]: [SpotifyConnect] Relinquishing Volumio State to another service Apr 27 12:52:53 volumio volumio[846]: [SpotifyConnect] Spotify Received stop Apr 27 12:52:53 volumio volumio[846]: info: CoreStateMachine::play index 4 Apr 27 12:52:53 volumio volumio[846]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 27 12:52:53 volumio volumio[846]: info: CoreStateMachine::stop Apr 27 12:52:53 volumio volumio[846]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 27 12:52:53 volumio volumio[846]: info: CoreStateMachine::updateTrackBlock Apr 27 12:52:53 volumio volumio[846]: info: CorePlayQueue::getTrackBlock Apr 27 12:52:53 volumio volumio[846]: info: CoreStateMachine::stPlaybackTimer Apr 27 12:52:53 volumio volumio[846]: info: CoreStateMachine::pushState Apr 27 12:52:53 volumio volumio[846]: info: CorePlayQueue::getTrack 111 Apr 27 12:52:53 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 27 12:52:53 volumio volumio[846]: info: CoreCommandRouter::volumioPushState Apr 27 12:52:53 volumio volumio[846]: info: CoreStateMachine::serviceStop Apr 27 12:52:53 volumio volumio[846]: info: CorePlayQueue::getTrack 111 Apr 27 12:52:53 volumio volumio[846]: info: CoreCommandRouter::serviceStop Apr 27 12:52:53 volumio volumio[846]: info: ControllerMpd::stop Apr 27 12:52:53 volumio volumio[846]: verbose: ControllerMpd::sendMpdCommand stop Apr 27 12:52:53 volumio volumio[2468]: [Vollibrespot] : Pause Apr 27 12:52:53 volumio volumio[846]: [SpotifyConnect] Pause Apr 27 12:52:53 volumio kernel: usb 1-1.2: USB disconnect, device number 11 Apr 27 12:52:53 volumio volumio[846]: info: Apr 27 12:52:53 volumio volumio[846]: ---------------------------- MPD announces state update: player Apr 27 12:52:53 volumio volumio[846]: info: sendMpdCommand stop took 135 milliseconds Apr 27 12:52:53 volumio volumio[846]: info: ControllerMpd::getState Apr 27 12:52:53 volumio volumio[846]: verbose: ControllerMpd::sendMpdCommand status Apr 27 12:52:53 volumio volumio[846]: info: CoreStateMachine::play index undefined Apr 27 12:52:53 volumio volumio[846]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 27 12:52:53 volumio volumio[846]: info: CorePlayQueue::getTrack 4 Apr 27 12:52:53 volumio volumio[846]: info: CoreStateMachine::startPlaybackTimer Apr 27 12:52:53 volumio volumio[846]: info: CorePlayQueue::getTrack 4 Apr 27 12:52:53 volumio volumio[846]: verbose: ControllerMpd::clearAddPlayTracks NAS/Music/Capital Cities/(2013) In a Tidal Wave of Mystery/01 - Safe and Sound.flac Apr 27 12:52:53 volumio volumio[846]: verbose: ControllerMpd::sendMpdCommand stop Apr 27 12:52:53 volumio volumio[846]: info: sendMpdCommand status took 2 milliseconds Apr 27 12:52:53 volumio volumio[846]: verbose: ControllerMpd::parseState Apr 27 12:52:53 volumio volumio[846]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 27 12:52:53 volumio volumio[846]: info: sendMpdCommand stop took 2 milliseconds Apr 27 12:52:53 volumio volumio[846]: info: sendMpdCommand playlistinfo took 1 milliseconds Apr 27 12:52:53 volumio volumio[846]: verbose: ControllerMpd::sendMpdCommand clear Apr 27 12:52:53 volumio volumio[846]: verbose: ControllerMpd::parseTrackInfo Apr 27 12:52:53 volumio volumio[846]: info: ControllerMpd::pushState Apr 27 12:52:53 volumio volumio[846]: info: CoreCommandRouter::servicePushState Apr 27 12:52:53 volumio volumio[846]: info: CoreStateMachine::pushState Apr 27 12:52:53 volumio volumio[846]: info: CorePlayQueue::getTrack 4 Apr 27 12:52:53 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 27 12:52:53 volumio volumio[846]: info: CoreCommandRouter::volumioPushState Apr 27 12:52:53 volumio volumio[846]: info: CorePlayQueue::getTrack 4 Apr 27 12:52:53 volumio volumio[846]: verbose: STATE SERVICE {"status":"stop","position":0,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"The Phantom Of The Opera","artist":"Sungha Jung","album":"Paint It Acoustic","uri":"NAS/Music/Sungha Jung/(2013) Paint It Acoustic/02 - The Phantom Of The Opera.flac","trackType":"flac"} Apr 27 12:52:53 volumio volumio[846]: verbose: CURRENT POSITION 4 Apr 27 12:52:53 volumio volumio[846]: info: CoreStateMachine::syncState stateService stop Apr 27 12:52:53 volumio volumio[846]: info: CoreStateMachine::syncState currentStatus stop Apr 27 12:52:53 volumio volumio[846]: info: CoreStateMachine::pushState Apr 27 12:52:53 volumio volumio[846]: info: CorePlayQueue::getTrack 4 Apr 27 12:52:53 volumio volumio[846]: info: CoreCommandRouter::volumioPushState Apr 27 12:52:53 volumio volumio[846]: info: No code Apr 27 12:52:53 volumio volumio[846]: info: CoreStateMachine::pushState Apr 27 12:52:53 volumio volumio[846]: info: CorePlayQueue::getTrack 4 Apr 27 12:52:53 volumio volumio[846]: info: CoreCommandRouter::volumioPushState Apr 27 12:52:53 volumio volumio[846]: info: ------------------------------ 77ms Apr 27 12:52:53 volumio volumio[846]: info: Apr 27 12:52:53 volumio volumio[846]: ---------------------------- MPD announces system playlist update Apr 27 12:52:53 volumio volumio[846]: info: Ignoring MPD Status Update Apr 27 12:52:53 volumio volumio[846]: info: sendMpdCommand clear took 78 milliseconds Apr 27 12:52:53 volumio volumio[846]: verbose: ControllerMpd::sendMpdCommand add "NAS/Music/Capital Cities/(2013) In a Tidal Wave of Mystery/01 - Safe and Sound.flac" Apr 27 12:52:53 volumio volumio[846]: error: updateQueue error: null Apr 27 12:52:53 volumio volumio[846]: info: Apr 27 12:52:53 volumio volumio[846]: ---------------------------- MPD announces system playlist update Apr 27 12:52:53 volumio volumio[846]: info: Ignoring MPD Status Update Apr 27 12:52:53 volumio volumio[846]: info: ------------------------------ 21ms Apr 27 12:52:53 volumio volumio[846]: info: sendMpdCommand add "NAS/Music/Capital Cities/(2013) In a Tidal Wave of Mystery/01 - Safe and Sound.flac" took 16 milliseconds Apr 27 12:52:53 volumio volumio[846]: verbose: ControllerMpd::sendMpdCommand play Apr 27 12:52:53 volumio volumio[846]: info: ------------------------------ 27ms Apr 27 12:52:53 volumio volumio[846]: info: sendMpdCommand play took 26 milliseconds Apr 27 12:52:53 volumio volumio[846]: info: Apr 27 12:52:53 volumio volumio[846]: ---------------------------- USB Audio Device Detached Apr 27 12:52:53 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , usbAudioDetach Apr 27 12:52:53 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Apr 27 12:52:53 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: raat , onStop Apr 27 12:52:53 volumio volumio[846]: info: Apr 27 12:52:53 volumio volumio[846]: ---------------------------- MPD announces state update: player Apr 27 12:52:53 volumio volumio[846]: info: ControllerMpd::getState Apr 27 12:52:53 volumio volumio[846]: verbose: ControllerMpd::sendMpdCommand status Apr 27 12:52:53 volumio volumio[846]: info: Apr 27 12:52:53 volumio volumio[846]: ---------------------------- MPD announces state update: player Apr 27 12:52:53 volumio volumio[846]: info: ControllerMpd::getState Apr 27 12:52:53 volumio volumio[846]: verbose: ControllerMpd::sendMpdCommand status Apr 27 12:52:53 volumio volumio[846]: info: sendMpdCommand status took 12 milliseconds Apr 27 12:52:53 volumio volumio[846]: verbose: ControllerMpd::parseState Apr 27 12:52:53 volumio volumio[846]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 27 12:52:53 volumio volumio[846]: info: sendMpdCommand status took 5 milliseconds Apr 27 12:52:53 volumio volumio[846]: info: sendMpdCommand playlistinfo took 5 milliseconds Apr 27 12:52:53 volumio volumio[846]: verbose: ControllerMpd::parseState Apr 27 12:52:53 volumio volumio[846]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 27 12:52:53 volumio volumio[846]: verbose: ControllerMpd::parseTrackInfo Apr 27 12:52:53 volumio volumio[846]: info: ControllerMpd::pushState Apr 27 12:52:53 volumio volumio[846]: info: CoreCommandRouter::servicePushState Apr 27 12:52:53 volumio volumio[846]: info: CorePlayQueue::getTrack 4 Apr 27 12:52:53 volumio volumio[846]: verbose: STATE SERVICE {"status":"play","position":0,"seek":708,"duration":193,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"522 Kbps","isStreaming":false,"title":"Safe and Sound","artist":"Capital Cities","album":"In a Tidal Wave of Mystery","uri":"NAS/Music/Capital Cities/(2013) In a Tidal Wave of Mystery/01 - Safe and Sound.flac","trackType":"flac"} Apr 27 12:52:53 volumio volumio[846]: verbose: CURRENT POSITION 4 Apr 27 12:52:53 volumio volumio[846]: info: CoreStateMachine::syncState stateService play Apr 27 12:52:53 volumio volumio[846]: info: CoreStateMachine::syncState currentStatus stop Apr 27 12:52:53 volumio volumio[846]: info: ------------------------------ 27ms Apr 27 12:52:53 volumio volumio[846]: info: sendMpdCommand playlistinfo took 12 milliseconds Apr 27 12:52:53 volumio volumio[846]: verbose: ControllerMpd::parseTrackInfo Apr 27 12:52:53 volumio volumio[846]: info: ControllerMpd::pushState Apr 27 12:52:53 volumio volumio[846]: info: CoreCommandRouter::servicePushState Apr 27 12:52:53 volumio volumio[846]: info: CorePlayQueue::getTrack 4 Apr 27 12:52:53 volumio volumio[846]: verbose: STATE SERVICE {"status":"play","position":0,"seek":708,"duration":193,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"522 Kbps","isStreaming":false,"title":"Safe and Sound","artist":"Capital Cities","album":"In a Tidal Wave of Mystery","uri":"NAS/Music/Capital Cities/(2013) In a Tidal Wave of Mystery/01 - Safe and Sound.flac","trackType":"flac"} Apr 27 12:52:53 volumio volumio[846]: verbose: CURRENT POSITION 4 Apr 27 12:52:53 volumio volumio[846]: info: CoreStateMachine::syncState stateService play Apr 27 12:52:53 volumio volumio[846]: info: CoreStateMachine::syncState currentStatus play Apr 27 12:52:53 volumio volumio[846]: info: Received an update from plugin. extracting info from payload Apr 27 12:52:53 volumio volumio[846]: info: CoreStateMachine::pushState Apr 27 12:52:53 volumio volumio[846]: info: CorePlayQueue::getTrack 4 Apr 27 12:52:53 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 27 12:52:53 volumio volumio[846]: info: CoreCommandRouter::volumioPushState Apr 27 12:52:53 volumio volumio[846]: info: CoreStateMachine::pushState Apr 27 12:52:53 volumio volumio[846]: info: CorePlayQueue::getTrack 4 Apr 27 12:52:53 volumio volumio[846]: info: CoreCommandRouter::volumioPushState Apr 27 12:52:53 volumio kernel: usb 1-1.2: new high-speed USB device number 12 using xhci_hcd Apr 27 12:52:53 volumio volumio[846]: info: ------------------------------ 72ms Apr 27 12:52:53 volumio kernel: usb 1-1.2: New USB device found, idVendor=152a, idProduct=8750, bcdDevice= 1.02 Apr 27 12:52:53 volumio kernel: usb 1-1.2: New USB device strings: Mfr=1, Product=3, SerialNumber=0 Apr 27 12:52:53 volumio kernel: usb 1-1.2: Product: D10 Apr 27 12:52:53 volumio kernel: usb 1-1.2: Manufacturer: Topping Apr 27 12:52:53 volumio kernel: usb 1-1.2: 1:3 : unsupported format bits 0x100000000 Apr 27 12:52:53 volumio volumio[846]: info: CoreCommandRouter::volumioGetState Apr 27 12:52:53 volumio volumio[846]: info: CorePlayQueue::getTrack 4 Apr 27 12:52:54 volumio volumio[846]: info: touch_display: Setting screensaver timeout to 0 seconds. Apr 27 12:52:54 volumio volumio[846]: info: touch_display: Using Xserver unix domain socket /tmp/.X11-unix/X0 Apr 27 12:52:54 volumio volumio[846]: info: touch_display: Setting screensaver timeout to 0 seconds. Apr 27 12:52:54 volumio volumio[846]: info: Apr 27 12:52:54 volumio volumio[846]: ---------------------------- USB Audio Device Attached Apr 27 12:52:54 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , usbAudioAttach Apr 27 12:52:54 volumio volumio[846]: info: CoreCommandRouter::Close All Modals sent Apr 27 12:52:54 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Apr 27 12:52:54 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Apr 27 12:52:54 volumio volumio[846]: info: Setting mixer D10 for card D10 Apr 27 12:52:54 volumio volumio[846]: [SpotifyConnect] Creating VLS config file Apr 27 12:52:54 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 27 12:52:54 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 27 12:52:54 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 27 12:52:54 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 27 12:52:54 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 27 12:52:54 volumio volumio[846]: [SpotifyConnect] Creating VLS config file Apr 27 12:52:54 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 27 12:52:54 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 27 12:52:54 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 27 12:52:54 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 27 12:52:54 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 27 12:52:54 volumio volumio[846]: info: CoreCommandRouter::volumioUpdateVolumeSettings Apr 27 12:52:54 volumio volumio[846]: info: Updating Volume Controller Parameters: Device: 5 Name: D10 Mixer: D10 Max Vol: 100 Vol Curve; logarithmic Vol Steps: 1 Apr 27 12:52:54 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , setExternalVolume Apr 27 12:52:54 volumio volumio[846]: info: Disabling external Volume Control Apr 27 12:52:54 volumio volumio[846]: info: CoreCommandRouter::getUIConfigOnPlugin Apr 27 12:52:54 volumio volumio[846]: info: Preparing to generate the ALSA configuration file Apr 27 12:52:54 volumio volumio[846]: [SpotifyConnect] Restarting Vollibrespot Daemon Apr 27 12:52:54 volumio volumio[846]: [SpotifyConnect] Restarting Vollibrespot Daemon Apr 27 12:52:54 volumio volumio[846]: info: The plugin peppy_screensaver has an ALSA contribution file Peppyalsa.postPeppyalsa.5.conf Apr 27 12:52:54 volumio volumio[846]: info: Reading ALSA contributions from plugins. Apr 27 12:52:54 volumio sudo[2520]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volspotconnect.service Apr 27 12:52:54 volumio sudo[2520]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 27 12:52:54 volumio sudo[2521]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volspotconnect.service Apr 27 12:52:54 volumio sudo[2521]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 27 12:52:54 volumio systemd[1]: Stopping Volspotconnect2 Daemon... Apr 27 12:52:54 volumio systemd[1]: volspotconnect.service: Main process exited, code=killed, status=15/TERM Apr 27 12:52:54 volumio systemd[1]: volspotconnect.service: Succeeded. Apr 27 12:52:54 volumio systemd[1]: Stopped Volspotconnect2 Daemon. Apr 27 12:52:54 volumio systemd[1]: Started Volspotconnect2 Daemon. Apr 27 12:52:54 volumio sudo[2520]: pam_unix(sudo:session): session closed for user root Apr 27 12:52:54 volumio sudo[2521]: pam_unix(sudo:session): session closed for user root Apr 27 12:52:54 volumio volumio[2525]: vollibrespot v0.2.5 8922128 2022-05-31 (librespot 08d8bcc 2020-10-07) -- Built On 2022-05-31 Apr 27 12:52:54 volumio volumio[2525]: Reading Config from "/tmp/volspotify.toml" Apr 27 12:52:54 volumio volumio[2525]: [Vollibrespot] : Using Alsa backend with device: peppyalsa Apr 27 12:52:54 volumio volumio[2525]: [Vollibrespot] : Failed to register IPv6 receiver: Os { code: 19, kind: Uncategorized, message: "No such device" } Apr 27 12:52:54 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions Apr 27 12:52:54 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 27 12:52:54 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Apr 27 12:52:54 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Apr 27 12:52:54 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Apr 27 12:52:54 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Apr 27 12:52:54 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Apr 27 12:52:54 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Apr 27 12:52:54 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Apr 27 12:52:54 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Apr 27 12:52:54 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: mpd , getPlaybackMode Apr 27 12:52:54 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus Apr 27 12:52:54 volumio volumio[846]: [SpotifyConnect] Vollibrespot Daemon service restarted! Apr 27 12:52:54 volumio volumio[846]: [SpotifyConnect] Vollibrespot Daemon service restarted! Apr 27 12:52:54 volumio volumio[846]: info: VolumeController:: Volume=100 Mute =false Apr 27 12:52:54 volumio volumio[846]: info: CoreStateMachine::pushState Apr 27 12:52:54 volumio volumio[846]: info: CorePlayQueue::getTrack 4 Apr 27 12:52:54 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 27 12:52:54 volumio volumio[846]: info: CoreCommandRouter::volumioPushState Apr 27 12:52:54 volumio volumio[2525]: [Vollibrespot] : Connecting to AP "ap-guc3.spotify.com:443" Apr 27 12:52:55 volumio volumio[846]: info: Asound.conf file unchanged, so no further update is needed Apr 27 12:52:55 volumio volumio[846]: info: Output device has changed, restarting MPD Apr 27 12:52:55 volumio volumio[846]: info: Output device has changed, restarting Shairport Sync Apr 27 12:52:55 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 27 12:52:55 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 27 12:52:55 volumio sudo[2536]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Apr 27 12:52:55 volumio sudo[2536]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 27 12:52:55 volumio sudo[2538]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Apr 27 12:52:55 volumio sudo[2536]: pam_unix(sudo:session): session closed for user root Apr 27 12:52:55 volumio sudo[2538]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 27 12:52:55 volumio systemd[1]: Stopping Music Player Daemon... Apr 27 12:52:55 volumio volumio[846]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Apr 27 12:52:55 volumio volumio[846]: [SpotifyConnect] Creating VLS config file Apr 27 12:52:55 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 27 12:52:55 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 27 12:52:55 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 27 12:52:55 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 27 12:52:55 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 27 12:52:55 volumio volumio[846]: [SpotifyConnect] Creating VLS config file Apr 27 12:52:55 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 27 12:52:55 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 27 12:52:55 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 27 12:52:55 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 27 12:52:55 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 27 12:52:55 volumio volumio[846]: [SpotifyConnect] Restarting Vollibrespot Daemon Apr 27 12:52:55 volumio volumio[846]: [SpotifyConnect] Restarting Vollibrespot Daemon Apr 27 12:52:55 volumio sudo[2545]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volspotconnect.service Apr 27 12:52:55 volumio sudo[2545]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 27 12:52:55 volumio systemd[1]: Stopping Volspotconnect2 Daemon... Apr 27 12:52:55 volumio systemd[1]: volspotconnect.service: Main process exited, code=killed, status=15/TERM Apr 27 12:52:55 volumio systemd[1]: volspotconnect.service: Succeeded. Apr 27 12:52:55 volumio systemd[1]: Stopped Volspotconnect2 Daemon. Apr 27 12:52:55 volumio volumio[846]: [SpotifyConnect] Internal Server Error Apr 27 12:52:55 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: raat , restartRaat Apr 27 12:52:55 volumio systemd[1]: Started Volspotconnect2 Daemon. Apr 27 12:52:55 volumio volumio[846]: info: MPD Permissions set Apr 27 12:52:55 volumio sudo[2545]: pam_unix(sudo:session): session closed for user root Apr 27 12:52:55 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 27 12:52:55 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 27 12:52:55 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 27 12:52:55 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 27 12:52:55 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 27 12:52:55 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 27 12:52:55 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 27 12:52:55 volumio sudo[2548]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volspotconnect.service Apr 27 12:52:55 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 27 12:52:55 volumio sudo[2548]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 27 12:52:55 volumio volumio[2549]: vollibrespot v0.2.5 8922128 2022-05-31 (librespot 08d8bcc 2020-10-07) -- Built On 2022-05-31 Apr 27 12:52:55 volumio volumio[2549]: Reading Config from "/tmp/volspotify.toml" Apr 27 12:52:55 volumio volumio[2549]: [Vollibrespot] : Using Alsa backend with device: peppyalsa Apr 27 12:52:55 volumio systemd[1]: mpd.service: Succeeded. Apr 27 12:52:55 volumio systemd[1]: Stopped Music Player Daemon. Apr 27 12:52:55 volumio systemd[1]: Starting Music Player Daemon... Apr 27 12:52:55 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 27 12:52:55 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 27 12:52:55 volumio volumio[846]: [SpotifyConnect] Vollibrespot Daemon service restarted! Apr 27 12:52:55 volumio volumio[846]: info: Starting Shairport Sync Apr 27 12:52:55 volumio systemd[1]: Stopping Volspotconnect2 Daemon... Apr 27 12:52:55 volumio systemd[1]: volspotconnect.service: Main process exited, code=killed, status=15/TERM Apr 27 12:52:55 volumio systemd[1]: volspotconnect.service: Succeeded. Apr 27 12:52:55 volumio systemd[1]: Stopped Volspotconnect2 Daemon. Apr 27 12:52:55 volumio systemd[1]: Started Volspotconnect2 Daemon. Apr 27 12:52:55 volumio sudo[2548]: pam_unix(sudo:session): session closed for user root Apr 27 12:52:55 volumio volumio[2559]: vollibrespot v0.2.5 8922128 2022-05-31 (librespot 08d8bcc 2020-10-07) -- Built On 2022-05-31 Apr 27 12:52:55 volumio volumio[2559]: Reading Config from "/tmp/volspotify.toml" Apr 27 12:52:55 volumio volumio[2559]: [Vollibrespot] : Using Alsa backend with device: peppyalsa Apr 27 12:52:55 volumio volumio[846]: [SpotifyConnect] Vollibrespot Daemon service restarted! Apr 27 12:52:55 volumio sudo[2561]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Apr 27 12:52:55 volumio sudo[2561]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 27 12:52:55 volumio volumio[2559]: [Vollibrespot] : Failed to register IPv6 receiver: Os { code: 19, kind: Uncategorized, message: "No such device" } Apr 27 12:52:55 volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Apr 27 12:52:55 volumio systemd[1]: shairport-sync.service: Succeeded. Apr 27 12:52:55 volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Apr 27 12:52:55 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Apr 27 12:52:55 volumio sudo[2561]: pam_unix(sudo:session): session closed for user root Apr 27 12:52:55 volumio volumio[846]: info: Shairport-Sync Started Apr 27 12:52:55 volumio volumio[2559]: [Vollibrespot] : Connecting to AP "ap-guc3.spotify.com:443" Apr 27 12:52:55 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 27 12:52:55 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 27 12:52:56 volumio mpd[2571]: Apr 27 12:52 : exception: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Apr 27 12:52:56 volumio volumio[2559]: [Vollibrespot] : Authenticated as "12183471479" ! Apr 27 12:52:56 volumio volumio[2559]: [Vollibrespot] : Using alsa sink Apr 27 12:52:56 volumio volumio[2559]: [Vollibrespot] : Metadata pipe established Apr 27 12:52:56 volumio volumio[2559]: [Vollibrespot] : Country: "CA" Apr 27 12:52:56 volumio volumio[2559]: [Vollibrespot] : Event: Volume { volume_to_mixer: 49151 } Apr 27 12:52:56 volumio volumio[846]: [SpotifyConnect] Volume Spotify: 74.99961852445259 Volumio: 75 Apr 27 12:52:56 volumio mpd[2571]: Apr 27 12:52 : exception: Input plugin 'tidal' is unavailable: No Tidal application token configured Apr 27 12:52:56 volumio mpd[2571]: Apr 27 12:52 : exception: Input plugin 'qobuz' is unavailable: No Qobuz app_id configured Apr 27 12:52:56 volumio systemd[1]: Started Music Player Daemon. Apr 27 12:52:56 volumio sudo[2538]: pam_unix(sudo:session): session closed for user root Apr 27 12:52:56 volumio volumio[846]: error: updateQueue error: null Apr 27 12:52:57 volumio volumio[846]: info: CoreCommandRouter::volumioPlay Apr 27 12:52:57 volumio volumio[846]: info: CoreStateMachine::play index 9 Apr 27 12:52:57 volumio volumio[846]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 27 12:52:57 volumio volumio[846]: info: CoreStateMachine::stop Apr 27 12:52:57 volumio volumio[846]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 27 12:52:57 volumio volumio[846]: info: CoreStateMachine::stPlaybackTimer Apr 27 12:52:57 volumio volumio[846]: info: CoreStateMachine::updateTrackBlock Apr 27 12:52:57 volumio volumio[846]: info: CorePlayQueue::getTrackBlock Apr 27 12:52:57 volumio volumio[846]: info: CoreStateMachine::pushState Apr 27 12:52:57 volumio volumio[846]: info: CorePlayQueue::getTrack 4 Apr 27 12:52:57 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 27 12:52:57 volumio volumio[846]: info: CoreCommandRouter::volumioPushState Apr 27 12:52:57 volumio volumio[846]: info: CoreStateMachine::serviceStop Apr 27 12:52:57 volumio volumio[846]: info: CorePlayQueue::getTrack 4 Apr 27 12:52:57 volumio volumio[846]: info: CoreCommandRouter::serviceStop Apr 27 12:52:57 volumio volumio[846]: info: ControllerMpd::stop Apr 27 12:52:57 volumio volumio[846]: verbose: ControllerMpd::sendMpdCommand stop Apr 27 12:52:57 volumio volumio[846]: info: sendMpdCommand stop took 14 milliseconds Apr 27 12:52:57 volumio volumio[846]: info: CoreStateMachine::play index undefined Apr 27 12:52:57 volumio volumio[846]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 27 12:52:57 volumio volumio[846]: info: CorePlayQueue::getTrack 9 Apr 27 12:52:57 volumio volumio[846]: info: CoreStateMachine::startPlaybackTimer Apr 27 12:52:57 volumio volumio[846]: info: CorePlayQueue::getTrack 9 Apr 27 12:52:57 volumio volumio[846]: verbose: ControllerMpd::clearAddPlayTracks NAS/Music/Ariana Grande/(2014) My Everything/03 - One Last Time.flac Apr 27 12:52:57 volumio volumio[846]: verbose: ControllerMpd::sendMpdCommand stop Apr 27 12:52:57 volumio volumio[846]: info: sendMpdCommand stop took 1 milliseconds Apr 27 12:52:57 volumio volumio[846]: verbose: ControllerMpd::sendMpdCommand clear Apr 27 12:52:57 volumio volumio[846]: info: Apr 27 12:52:57 volumio volumio[846]: ---------------------------- MPD announces system playlist update Apr 27 12:52:57 volumio volumio[846]: info: Ignoring MPD Status Update Apr 27 12:52:57 volumio volumio[846]: info: sendMpdCommand clear took 32 milliseconds Apr 27 12:52:57 volumio volumio[846]: verbose: ControllerMpd::sendMpdCommand add "NAS/Music/Ariana Grande/(2014) My Everything/03 - One Last Time.flac" Apr 27 12:52:57 volumio volumio[846]: error: updateQueue error: null Apr 27 12:52:57 volumio volumio[846]: info: Apr 27 12:52:57 volumio volumio[846]: ---------------------------- MPD announces system playlist update Apr 27 12:52:57 volumio volumio[846]: info: Ignoring MPD Status Update Apr 27 12:52:57 volumio volumio[846]: info: ------------------------------ 3ms Apr 27 12:52:57 volumio volumio[846]: info: sendMpdCommand add "NAS/Music/Ariana Grande/(2014) My Everything/03 - One Last Time.flac" took 2 milliseconds Apr 27 12:52:57 volumio volumio[846]: verbose: ControllerMpd::sendMpdCommand play Apr 27 12:52:57 volumio volumio[846]: info: ------------------------------ 4ms Apr 27 12:52:57 volumio volumio[846]: info: sendMpdCommand play took 3 milliseconds Apr 27 12:52:57 volumio volumio[846]: info: touch_display: Setting screensaver timeout to 15 seconds. Apr 27 12:52:57 volumio volumio[846]: info: Apr 27 12:52:57 volumio volumio[846]: ---------------------------- MPD announces state update: player Apr 27 12:52:57 volumio volumio[846]: info: ControllerMpd::getState Apr 27 12:52:57 volumio volumio[846]: verbose: ControllerMpd::sendMpdCommand status Apr 27 12:52:58 volumio volumio[846]: info: Apr 27 12:52:58 volumio volumio[846]: ---------------------------- MPD announces state update: player Apr 27 12:52:58 volumio volumio[846]: info: sendMpdCommand status took 77 milliseconds Apr 27 12:52:58 volumio volumio[846]: info: ControllerMpd::getState Apr 27 12:52:58 volumio volumio[846]: verbose: ControllerMpd::sendMpdCommand status Apr 27 12:52:58 volumio volumio[846]: verbose: ControllerMpd::parseState Apr 27 12:52:58 volumio volumio[846]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 27 12:52:58 volumio volumio[846]: info: sendMpdCommand status took 2 milliseconds Apr 27 12:52:58 volumio volumio[846]: verbose: ControllerMpd::parseState Apr 27 12:52:58 volumio volumio[846]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 27 12:52:58 volumio volumio[846]: info: sendMpdCommand playlistinfo took 2 milliseconds Apr 27 12:52:58 volumio volumio[846]: info: sendMpdCommand playlistinfo took 2 milliseconds Apr 27 12:52:58 volumio volumio[846]: verbose: ControllerMpd::parseTrackInfo Apr 27 12:52:58 volumio volumio[846]: verbose: ControllerMpd::parseTrackInfo Apr 27 12:52:58 volumio volumio[846]: info: ControllerMpd::pushState Apr 27 12:52:58 volumio volumio[846]: info: CoreCommandRouter::servicePushState Apr 27 12:52:58 volumio volumio[846]: info: CorePlayQueue::getTrack 9 Apr 27 12:52:58 volumio volumio[846]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":197,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"504 Kbps","isStreaming":false,"title":"One Last Time","artist":"Ariana Grande","album":"My Everything","uri":"NAS/Music/Ariana Grande/(2014) My Everything/03 - One Last Time.flac","trackType":"flac"} Apr 27 12:52:58 volumio volumio[846]: verbose: CURRENT POSITION 9 Apr 27 12:52:58 volumio volumio[846]: info: CoreStateMachine::syncState stateService play Apr 27 12:52:58 volumio volumio[846]: info: CoreStateMachine::syncState currentStatus stop Apr 27 12:52:58 volumio volumio[846]: info: ControllerMpd::pushState Apr 27 12:52:58 volumio volumio[846]: info: CoreCommandRouter::servicePushState Apr 27 12:52:58 volumio volumio[846]: info: CorePlayQueue::getTrack 9 Apr 27 12:52:58 volumio volumio[846]: verbose: STATE SERVICE {"status":"play","position":0,"seek":708,"duration":197,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"510 Kbps","isStreaming":false,"title":"One Last Time","artist":"Ariana Grande","album":"My Everything","uri":"NAS/Music/Ariana Grande/(2014) My Everything/03 - One Last Time.flac","trackType":"flac"} Apr 27 12:52:58 volumio volumio[846]: verbose: CURRENT POSITION 9 Apr 27 12:52:58 volumio volumio[846]: info: CoreStateMachine::syncState stateService play Apr 27 12:52:58 volumio volumio[846]: info: CoreStateMachine::syncState currentStatus play Apr 27 12:52:58 volumio volumio[846]: info: Received an update from plugin. extracting info from payload Apr 27 12:52:58 volumio volumio[846]: info: CoreStateMachine::pushState Apr 27 12:52:58 volumio volumio[846]: info: CorePlayQueue::getTrack 9 Apr 27 12:52:58 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 27 12:52:58 volumio volumio[846]: info: CoreCommandRouter::volumioPushState Apr 27 12:52:58 volumio volumio[846]: info: CoreStateMachine::pushState Apr 27 12:52:58 volumio volumio[846]: info: CorePlayQueue::getTrack 9 Apr 27 12:52:58 volumio volumio[846]: info: CoreCommandRouter::volumioPushState Apr 27 12:52:58 volumio volumio[846]: info: ------------------------------ 99ms Apr 27 12:52:58 volumio volumio[846]: info: ------------------------------ 43ms Apr 27 12:52:58 volumio volumio[846]: info: touch_display: Setting screensaver timeout to 0 seconds. Apr 27 12:52:58 volumio volumio[846]: info: CoreCommandRouter::volumioRetrieveVolumeLevels Apr 27 12:52:58 volumio volumio[846]: info: CoreStateMachine::getcurrentVolume Apr 27 12:52:58 volumio volumio[846]: info: CoreCommandRouter::volumioRetrievevolume Apr 27 12:52:58 volumio volumio[846]: info: VolumeController:: Volume=100 Mute =false Apr 27 12:52:58 volumio volumio[846]: info: CoreStateMachine::pushState Apr 27 12:52:58 volumio volumio[846]: info: CorePlayQueue::getTrack 9 Apr 27 12:52:58 volumio volumio[846]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 27 12:52:58 volumio volumio[846]: info: CoreCommandRouter::volumioPushState Apr 27 12:52:58 volumio volumio[846]: info: CoreStateMachine::updateTrackBlock Apr 27 12:52:58 volumio volumio[846]: info: CorePlayQueue::getTrackBlock Apr 27 12:52:58 volumio volumio[846]: info: CoreCommandRouter::volumioRetrievevolume Apr 27 12:52:58 volumio volumio[846]: info: VolumeController:: Volume=100 Mute =false Apr 27 12:52:58 volumio volumio[846]: info: CoreStateMachine::pushState Apr 27 12:52:58 volumio volumio[846]: info: CorePlayQueue::getTrack 9 Apr 27 12:52:58 volumio volumio[846]: info: CoreCommandRouter::volumioPushState Apr 27 12:53:00 volumio volumio[846]: info: Checking Spotify Web API Apr 27 12:53:00 volumio volumio[846]: info: Checking Spotify Web API Apr 27 12:53:00 volumio volumio[846]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 27 12:53:00 volumio volumio[846]: Error [ERR_SOCKET_DGRAM_NOT_RUNNING]: Not running Apr 27 12:53:00 volumio volumio[846]: at healthCheck (dgram.js:897:11) Apr 27 12:53:00 volumio volumio[846]: at Socket.send (dgram.js:622:3) Apr 27 12:53:00 volumio volumio[846]: at SpotConnEvents.sendmsg (/data/plugins/music_service/spop/SpotConnController.js:121:21) Apr 27 12:53:00 volumio volumio[846]: at ControllerSpotify.checkWebApi (/data/plugins/music_service/spop/index.js:2383:23) Apr 27 12:53:00 volumio volumio[846]: at Timeout._onTimeout (/data/plugins/music_service/spop/index.js:2723:18) Apr 27 12:53:00 volumio volumio[846]: at listOnTimeout (internal/timers.js:554:17) Apr 27 12:53:00 volumio volumio[846]: at processTimers (internal/timers.js:497:7) { Apr 27 12:53:00 volumio volumio[846]: code: 'ERR_SOCKET_DGRAM_NOT_RUNNING' Apr 27 12:53:00 volumio volumio[846]: } Apr 27 12:53:00 volumio volumio[846]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 27 12:53:01 volumio sudo[2600]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-04-27 12:52 Apr 27 12:53:01 volumio sudo[2600]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Raspbian GNU/Linux 10 (buster)" NAME="Raspbian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster 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="c87c6e2b1ae33dc5801986cbcbe970898b92e7b4" VOLUMIO_FE_VERSION="c433755e569617abac52264d17ad61be303ef463" VOLUMIO_FE3_VERSION="2419ddd8e895c5bdc456962163c9dc7c0f187aa7" VOLUMIO_BE_VERSION="b949d6001d7e656b4668f31c119d2247cdf45158" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Thu 30 Mar 2023 05:45:03 PM CEST" VOLUMIO_VERSION="3.449" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="6428d8e2c06e98483f5c5d77e8f01989"