-- Logs begin at Thu 2025-12-25 09:21:50 GMT, end at Thu 2025-12-25 21:30:49 GMT. -- Dec 25 21:29:10 rivo go-librespot[4162]: time="2025-12-25T21:29:10Z" level=trace msg="sent dealer ping" Dec 25 21:29:10 rivo go-librespot[4162]: time="2025-12-25T21:29:10Z" level=trace msg="received dealer pong" Dec 25 21:29:40 rivo go-librespot[4162]: time="2025-12-25T21:29:40Z" level=trace msg="sent dealer ping" Dec 25 21:29:40 rivo go-librespot[4162]: time="2025-12-25T21:29:40Z" level=trace msg="received dealer pong" Dec 25 21:30:08 rivo sudo[3222]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 25 21:30:08 rivo sudo[3224]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 25 21:30:08 rivo sudo[3224]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 25 21:30:08 rivo sudo[3222]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 25 21:30:08 rivo sudo[3224]: pam_unix(sudo:session): session closed for user root Dec 25 21:30:08 rivo sudo[3222]: pam_unix(sudo:session): session closed for user root Dec 25 21:30:08 rivo volumio[3140]: verbose: New Socket.io Connection to 192.168.0.165 from 192.168.0.25 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/143.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 7 Dec 25 21:30:08 rivo volumio[3140]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Dec 25 21:30:08 rivo volumio[3140]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Dec 25 21:30:08 rivo sudo[3230]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 25 21:30:08 rivo sudo[3230]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 25 21:30:08 rivo sudo[3230]: pam_unix(sudo:session): session closed for user root Dec 25 21:30:08 rivo sudo[3233]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 25 21:30:08 rivo sudo[3233]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 25 21:30:08 rivo sudo[3233]: pam_unix(sudo:session): session closed for user root Dec 25 21:30:09 rivo volumio[3140]: verbose: New Socket.io Connection to 192.168.0.165 from 192.168.0.25 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/143.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 8 Dec 25 21:30:09 rivo volumio[3140]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Dec 25 21:30:09 rivo volumio[3140]: info: CoreCommandRouter::volumioGetVisibleSources Dec 25 21:30:09 rivo volumio[3140]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 25 21:30:09 rivo volumio[3140]: info: CoreCommandRouter::volumioGetState Dec 25 21:30:09 rivo volumio[3140]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Dec 25 21:30:09 rivo volumio[3140]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Dec 25 21:30:09 rivo volumio[3140]: info: Received Get System Info Dec 25 21:30:09 rivo volumio[3140]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 25 21:30:09 rivo volumio[3140]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 25 21:30:09 rivo volumio[3140]: info: Discovery: Getting this device information Dec 25 21:30:09 rivo volumio[3140]: info: CoreCommandRouter::volumioGetState Dec 25 21:30:09 rivo volumio[3140]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 25 21:30:09 rivo volumio[3140]: info: CoreCommandRouter::volumioGetState Dec 25 21:30:09 rivo volumio[3140]: info: Listing playlists Dec 25 21:30:09 rivo volumio[3140]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Dec 25 21:30:09 rivo volumio[3140]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Dec 25 21:30:09 rivo volumio[3140]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Dec 25 21:30:10 rivo volumio[3140]: info: CoreCommandRouter::volumioGetState Dec 25 21:30:10 rivo volumio[3140]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Dec 25 21:30:10 rivo go-librespot[4162]: time="2025-12-25T21:30:10Z" level=trace msg="sent dealer ping" Dec 25 21:30:10 rivo volumio[3140]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Dec 25 21:30:10 rivo volumio[3140]: info: Received Get System Info Dec 25 21:30:10 rivo volumio[3140]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 25 21:30:10 rivo volumio[3140]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 25 21:30:10 rivo volumio[3140]: info: Discovery: Getting this device information Dec 25 21:30:10 rivo volumio[3140]: info: CoreCommandRouter::volumioGetState Dec 25 21:30:10 rivo volumio[3140]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 25 21:30:10 rivo go-librespot[4162]: time="2025-12-25T21:30:10Z" level=trace msg="received dealer pong" Dec 25 21:30:11 rivo go-librespot[4162]: time="2025-12-25T21:30:11Z" level=trace msg="received accesspoint ping" Dec 25 21:30:11 rivo go-librespot[4162]: time="2025-12-25T21:30:11Z" level=trace msg="received accesspoint pong ack" Dec 25 21:30:11 rivo volumio[3140]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Dec 25 21:30:11 rivo volumio[3140]: info: Received Get System Info Dec 25 21:30:11 rivo volumio[3140]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 25 21:30:11 rivo volumio[3140]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 25 21:30:11 rivo volumio[3140]: info: Discovery: Getting this device information Dec 25 21:30:11 rivo volumio[3140]: info: CoreCommandRouter::volumioGetState Dec 25 21:30:11 rivo volumio[3140]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 25 21:30:17 rivo volumio[3140]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 25 21:30:17 rivo volumio[3140]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 25 21:30:17 rivo volumio[3140]: info: Retrieving Cloud Streaming UI Dec 25 21:30:17 rivo volumio[3140]: info: Getting Tidal Cloud Configuration Dec 25 21:30:17 rivo volumio[3140]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 25 21:30:17 rivo volumio[3140]: info: Getting Qobuz Cloud Configuration Dec 25 21:30:17 rivo volumio[3140]: info: Asking plugin for UI Config Dec 25 21:30:17 rivo volumio[3140]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 25 21:30:17 rivo volumio[3140]: info: Getting Spotify Cloud Configuration Dec 25 21:30:17 rivo volumio[3140]: info: Asking plugin for UI Config Dec 25 21:30:17 rivo volumio[3140]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 25 21:30:17 rivo volumio[3140]: info: Saving Spotify Acccount Dec 25 21:30:17 rivo volumio[3140]: info: Got it Dec 25 21:30:17 rivo volumio[3140]: error: Could not retrieve Spotify Config from plugin Spotify: no section found Dec 25 21:30:17 rivo volumio[3140]: info: Got Tidal Cloud Configuration Dec 25 21:30:17 rivo volumio[3140]: info: Got it Dec 25 21:30:17 rivo volumio[3140]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 25 21:30:17 rivo volumio[3140]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus Dec 25 21:30:17 rivo volumio[3140]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Dec 25 21:30:17 rivo volumio[3140]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Dec 25 21:30:17 rivo volumio[3140]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Dec 25 21:30:17 rivo volumio[3140]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 25 21:30:17 rivo volumio[3140]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 25 21:30:17 rivo volumio[3140]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 25 21:30:17 rivo volumio[3140]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 25 21:30:17 rivo volumio[3140]: info: CoreCommandRouter::volumioGetBrowseSources Dec 25 21:30:17 rivo volumio[3140]: info: CoreCommandRouter::volumioGetBrowseSources Dec 25 21:30:17 rivo volumio[3140]: info: CoreCommandRouter::volumioGetBrowseSources Dec 25 21:30:17 rivo volumio[3140]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Dec 25 21:30:17 rivo volumio[3140]: info: CoreCommandRouter::executeOnPlugin: networkfs , listShares Dec 25 21:30:19 rivo volumio[3140]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Dec 25 21:30:21 rivo volumio[3140]: info: CoreCommandRouter::executeOnPlugin: mpd , updateDb Dec 25 21:30:21 rivo volumio[3140]: verbose: ControllerMpd::sendMpdCommand update Dec 25 21:30:21 rivo volumio[3140]: verbose: ControllerMpd::sendMpdCommand status Dec 25 21:30:21 rivo volumio[3140]: info: Dec 25 21:30:21 rivo volumio[3140]: ---------------------------- MPD announces state update: update Dec 25 21:30:21 rivo volumio[3140]: info: sendMpdCommand update took 19 milliseconds Dec 25 21:30:21 rivo volumio[3140]: info: ControllerMpd::getState Dec 25 21:30:21 rivo volumio[3140]: verbose: ControllerMpd::sendMpdCommand status Dec 25 21:30:21 rivo volumio[3140]: info: sendMpdCommand status took 8 milliseconds Dec 25 21:30:21 rivo volumio[3140]: info: sendMpdCommand status took 3 milliseconds Dec 25 21:30:21 rivo volumio[3140]: verbose: ControllerMpd::parseState Dec 25 21:30:21 rivo volumio[3140]: info: Command Router : Notfying DB Updatetrue Dec 25 21:30:21 rivo volumio[3140]: verbose: ControllerMpd::parseState Dec 25 21:30:21 rivo volumio[3140]: info: ControllerMpd::pushState Dec 25 21:30:21 rivo volumio[3140]: info: CoreCommandRouter::servicePushState Dec 25 21:30:21 rivo volumio[3140]: info: CoreStateMachine::pushState Dec 25 21:30:21 rivo volumio[3140]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 25 21:30:21 rivo volumio[3140]: info: CoreCommandRouter::volumioPushState Dec 25 21:30:21 rivo volumio[3140]: info: CoreCommandRouter::volumioGetState Dec 25 21:30:21 rivo volumio[3140]: info: CorePlayQueue::getTrack 0 Dec 25 21:30:21 rivo volumio[3140]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":true,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Dec 25 21:30:21 rivo volumio[3140]: verbose: CURRENT POSITION 0 Dec 25 21:30:21 rivo volumio[3140]: info: CoreStateMachine::syncState stateService stop Dec 25 21:30:21 rivo volumio[3140]: info: CoreStateMachine::syncState currentStatus play Dec 25 21:30:21 rivo volumio[3140]: info: CoreCommandRouter::volumioPushState Dec 25 21:30:21 rivo volumio[3140]: info: CoreCommandRouter::volumioGetState Dec 25 21:30:21 rivo volumio[3140]: info: CoreStateMachine::stPlaybackTimer Dec 25 21:30:21 rivo volumio[3140]: info: ------------------------------ 106ms Dec 25 21:30:21 rivo volumio[3140]: verbose: ControllerMpd::sendMpdCommand status Dec 25 21:30:21 rivo volumio[3140]: info: Dec 25 21:30:21 rivo volumio[3140]: ---------------------------- MPD announces state update: update Dec 25 21:30:21 rivo volumio[3140]: info: ControllerMpd::getState Dec 25 21:30:21 rivo volumio[3140]: verbose: ControllerMpd::sendMpdCommand status Dec 25 21:30:21 rivo volumio[3140]: verbose: ControllerMpd::sendMpdCommand status Dec 25 21:30:21 rivo volumio[3140]: info: Dec 25 21:30:21 rivo volumio[3140]: ---------------------------- MPD announces state update: update Dec 25 21:30:21 rivo volumio[3140]: info: ControllerMpd::getState Dec 25 21:30:21 rivo volumio[3140]: verbose: ControllerMpd::sendMpdCommand status Dec 25 21:30:21 rivo volumio[3140]: info: sendMpdCommand status took 8 milliseconds Dec 25 21:30:21 rivo volumio[3140]: info: sendMpdCommand status took 7 milliseconds Dec 25 21:30:21 rivo volumio[3140]: verbose: ControllerMpd::parseState Dec 25 21:30:21 rivo volumio[3140]: info: Command Router : Notfying DB Updatetrue Dec 25 21:30:21 rivo volumio[3140]: info: CoreCommandRouter::Close All Modals sent Dec 25 21:30:21 rivo volumio[3140]: verbose: ControllerMpd::parseState Dec 25 21:30:21 rivo volumio[3140]: info: ControllerMpd::pushState Dec 25 21:30:21 rivo volumio[3140]: info: CoreCommandRouter::servicePushState Dec 25 21:30:21 rivo volumio[3140]: info: CoreStateMachine::pushState Dec 25 21:30:21 rivo volumio[3140]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 25 21:30:21 rivo volumio[3140]: info: CoreCommandRouter::volumioPushState Dec 25 21:30:21 rivo volumio[3140]: info: CoreCommandRouter::volumioGetState Dec 25 21:30:21 rivo volumio[3140]: info: CorePlayQueue::getTrack 0 Dec 25 21:30:21 rivo volumio[3140]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":true,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Dec 25 21:30:21 rivo volumio[3140]: verbose: CURRENT POSITION 0 Dec 25 21:30:21 rivo volumio[3140]: info: CoreStateMachine::syncState stateService stop Dec 25 21:30:21 rivo volumio[3140]: info: CoreStateMachine::syncState currentStatus stop Dec 25 21:30:21 rivo volumio[3140]: info: CoreStateMachine::pushState Dec 25 21:30:21 rivo volumio[3140]: info: CoreCommandRouter::volumioPushState Dec 25 21:30:21 rivo volumio[3140]: info: CoreCommandRouter::volumioGetState Dec 25 21:30:21 rivo volumio[3140]: info: No code Dec 25 21:30:21 rivo volumio[3140]: info: CoreStateMachine::pushState Dec 25 21:30:21 rivo volumio[3140]: info: CoreCommandRouter::volumioPushState Dec 25 21:30:21 rivo volumio[3140]: info: CoreCommandRouter::volumioGetState Dec 25 21:30:21 rivo volumio[3140]: info: ------------------------------ 77ms Dec 25 21:30:21 rivo volumio[3140]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Dec 25 21:30:21 rivo volumio[3140]: info: Signalling Playback active due to playback status change Dec 25 21:30:21 rivo volumio[3140]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Dec 25 21:30:21 rivo volumio[3140]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Dec 25 21:30:21 rivo volumio[3140]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Dec 25 21:30:21 rivo volumio[3140]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Dec 25 21:30:21 rivo volumio[3140]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Dec 25 21:30:21 rivo volumio[3140]: info: sendMpdCommand status took 118 milliseconds Dec 25 21:30:21 rivo volumio[3140]: info: sendMpdCommand status took 117 milliseconds Dec 25 21:30:21 rivo volumio[3140]: verbose: ControllerMpd::parseState Dec 25 21:30:21 rivo volumio[3140]: info: Command Router : Notfying DB Updatetrue Dec 25 21:30:21 rivo volumio[3140]: info: CoreCommandRouter::Close All Modals sent Dec 25 21:30:21 rivo volumio[3140]: verbose: ControllerMpd::parseState Dec 25 21:30:21 rivo volumio[3140]: info: ControllerMpd::pushState Dec 25 21:30:21 rivo volumio[3140]: info: CoreCommandRouter::servicePushState Dec 25 21:30:21 rivo volumio[3140]: info: CoreStateMachine::pushState Dec 25 21:30:21 rivo volumio[3140]: info: CoreCommandRouter::volumioPushState Dec 25 21:30:21 rivo volumio[3140]: info: CoreCommandRouter::volumioGetState Dec 25 21:30:21 rivo volumio[3140]: info: CorePlayQueue::getTrack 0 Dec 25 21:30:21 rivo volumio[3140]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":true,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Dec 25 21:30:21 rivo volumio[3140]: verbose: CURRENT POSITION 0 Dec 25 21:30:21 rivo volumio[3140]: info: CoreStateMachine::syncState stateService stop Dec 25 21:30:21 rivo volumio[3140]: info: CoreStateMachine::syncState currentStatus stop Dec 25 21:30:21 rivo volumio[3140]: info: CoreStateMachine::pushState Dec 25 21:30:21 rivo volumio[3140]: info: CoreCommandRouter::volumioPushState Dec 25 21:30:21 rivo volumio[3140]: info: CoreCommandRouter::volumioGetState Dec 25 21:30:21 rivo volumio[3140]: info: No code Dec 25 21:30:21 rivo volumio[3140]: info: CoreStateMachine::pushState Dec 25 21:30:21 rivo volumio[3140]: info: CoreCommandRouter::volumioPushState Dec 25 21:30:21 rivo volumio[3140]: info: CoreCommandRouter::volumioGetState Dec 25 21:30:22 rivo volumio[3140]: info: ------------------------------ 183ms Dec 25 21:30:22 rivo volumio[3140]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Dec 25 21:30:22 rivo volumio[3140]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Dec 25 21:30:22 rivo volumio[3140]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Dec 25 21:30:22 rivo volumio[3140]: info: MCU Signalled Playback Inactive Dec 25 21:30:22 rivo volumio[3140]: info: MCU Signalled Playback Active Dec 25 21:30:22 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:22.152Z level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=3 Dec 25 21:30:22 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:22.452Z level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=3 Dec 25 21:30:22 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:22.753Z level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=3 Dec 25 21:30:23 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:23.054Z level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=3 Dec 25 21:30:23 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:23.355Z level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=3 Dec 25 21:30:23 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:23.655Z level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=3 Dec 25 21:30:23 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:23.956Z level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=3 Dec 25 21:30:24 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:24.256Z level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=3 Dec 25 21:30:24 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:24.558Z level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=3 Dec 25 21:30:24 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:24.859Z level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=3 Dec 25 21:30:25 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:25.160Z level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=3 Dec 25 21:30:25 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:25.161Z level=ERROR msg="pending write exceeded maximum retries, dropping" component=conn/ble addr=3 chunks=1 index=0 Dec 25 21:30:25 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:25.164Z level=ERROR msg="failed to send event" component=server dst="00:00:00:00:00:00%03 @ 0x1a6dd10" event=SERVER_EVENT_TYPE_PLAYER_STATE_CHANGED error="peer is gone" Dec 25 21:30:25 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:25.461Z level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=3 Dec 25 21:30:25 rivo volumio[3140]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Dec 25 21:30:25 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:25.762Z level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=3 Dec 25 21:30:26 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:26.063Z level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=3 Dec 25 21:30:26 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:26.363Z level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=3 Dec 25 21:30:26 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:26.663Z level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=3 Dec 25 21:30:26 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:26.964Z level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=3 Dec 25 21:30:27 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:27.265Z level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=3 Dec 25 21:30:27 rivo volumio[3140]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Dec 25 21:30:27 rivo volumio[3140]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Dec 25 21:30:27 rivo volumio[3140]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Dec 25 21:30:27 rivo volumio[3140]: info: Received Get System Version Dec 25 21:30:27 rivo volumio[3140]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 25 21:30:27 rivo volumio[3140]: info: Received Get System Info Dec 25 21:30:27 rivo volumio[3140]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 25 21:30:27 rivo volumio[3140]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 25 21:30:27 rivo volumio[3140]: info: Discovery: Getting this device information Dec 25 21:30:27 rivo volumio[3140]: info: CoreCommandRouter::volumioGetState Dec 25 21:30:27 rivo volumio[3140]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 25 21:30:27 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:27.566Z level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=3 Dec 25 21:30:27 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:27.866Z level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=3 Dec 25 21:30:28 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:28.168Z level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=3 Dec 25 21:30:28 rivo volumio[3140]: info: MPD Database updated - AlbumList cache refreshed Dec 25 21:30:28 rivo volumio[3140]: info: Dec 25 21:30:28 rivo volumio[3140]: ---------------------------- MPD announces state update: database Dec 25 21:30:28 rivo volumio[3140]: verbose: ControllerMpd::sendMpdCommand status Dec 25 21:30:28 rivo volumio[3140]: info: Dec 25 21:30:28 rivo volumio[3140]: ---------------------------- MPD announces state update: update Dec 25 21:30:28 rivo volumio[3140]: info: ControllerMpd::getState Dec 25 21:30:28 rivo volumio[3140]: verbose: ControllerMpd::sendMpdCommand status Dec 25 21:30:28 rivo volumio[3140]: info: ControllerMpd::getState Dec 25 21:30:28 rivo volumio[3140]: verbose: ControllerMpd::sendMpdCommand status Dec 25 21:30:28 rivo volumio[3140]: info: MPD Database updated - AlbumList cache refreshed Dec 25 21:30:28 rivo volumio[3140]: info: Dec 25 21:30:28 rivo volumio[3140]: ---------------------------- MPD announces state update: database Dec 25 21:30:28 rivo volumio[3140]: verbose: ControllerMpd::sendMpdCommand status Dec 25 21:30:28 rivo volumio[3140]: info: Dec 25 21:30:28 rivo volumio[3140]: ---------------------------- MPD announces state update: update Dec 25 21:30:28 rivo volumio[3140]: info: ControllerMpd::getState Dec 25 21:30:28 rivo volumio[3140]: verbose: ControllerMpd::sendMpdCommand status Dec 25 21:30:28 rivo volumio[3140]: info: ControllerMpd::getState Dec 25 21:30:28 rivo volumio[3140]: verbose: ControllerMpd::sendMpdCommand status Dec 25 21:30:28 rivo volumio[3140]: info: MPD Database updated - AlbumList cache refreshed Dec 25 21:30:28 rivo volumio[3140]: info: Dec 25 21:30:28 rivo volumio[3140]: ---------------------------- MPD announces state update: database Dec 25 21:30:28 rivo volumio[3140]: verbose: ControllerMpd::sendMpdCommand status Dec 25 21:30:28 rivo volumio[3140]: info: Dec 25 21:30:28 rivo volumio[3140]: ---------------------------- MPD announces state update: update Dec 25 21:30:28 rivo volumio[3140]: info: ControllerMpd::getState Dec 25 21:30:28 rivo volumio[3140]: verbose: ControllerMpd::sendMpdCommand status Dec 25 21:30:28 rivo volumio[3140]: info: ControllerMpd::getState Dec 25 21:30:28 rivo volumio[3140]: verbose: ControllerMpd::sendMpdCommand status Dec 25 21:30:28 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:28.468Z level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=3 Dec 25 21:30:28 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:28.468Z level=ERROR msg="pending write exceeded maximum retries, dropping" component=conn/ble addr=3 chunks=1 index=0 Dec 25 21:30:28 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:28.469Z level=ERROR msg="failed to send event" component=server dst="00:00:00:00:00:00%03 @ 0x1a6dd10" event=SERVER_EVENT_TYPE_PLAYER_STATE_CHANGED error="peer is gone" Dec 25 21:30:28 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:28.769Z level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=3 Dec 25 21:30:29 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:29.070Z level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=3 Dec 25 21:30:29 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:29.371Z level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=3 Dec 25 21:30:29 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:29.672Z level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=3 Dec 25 21:30:29 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:29.973Z level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=3 Dec 25 21:30:30 rivo volumio[3140]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Dec 25 21:30:30 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:30.274Z level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=3 Dec 25 21:30:30 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:30.574Z level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=3 Dec 25 21:30:30 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:30.875Z level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=3 Dec 25 21:30:31 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:31.176Z level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=3 Dec 25 21:30:31 rivo volumio[3140]: Cannot compose Albumart path Dec 25 21:30:31 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:31.476Z level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=3 Dec 25 21:30:31 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:31.777Z level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=3 Dec 25 21:30:31 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:31.778Z level=ERROR msg="pending write exceeded maximum retries, dropping" component=conn/ble addr=3 chunks=1 index=0 Dec 25 21:30:31 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:31.778Z level=ERROR msg="failed to send event" component=server dst="00:00:00:00:00:00%03 @ 0x1a6dd10" event=SERVER_EVENT_TYPE_PLAYER_STATE_CHANGED error="peer is gone" Dec 25 21:30:31 rivo volumio[3140]: info: sendMpdCommand status took 3588 milliseconds Dec 25 21:30:31 rivo volumio[3140]: info: sendMpdCommand status took 3586 milliseconds Dec 25 21:30:31 rivo volumio[3140]: info: sendMpdCommand status took 3585 milliseconds Dec 25 21:30:31 rivo volumio[3140]: verbose: ControllerMpd::parseState Dec 25 21:30:31 rivo volumio[3140]: info: Command Router : Notfying DB Updatefalse Dec 25 21:30:31 rivo volumio[3140]: info: CoreCommandRouter::Close All Modals sent Dec 25 21:30:31 rivo volumio[3140]: verbose: ControllerMpd::parseState Dec 25 21:30:31 rivo volumio[3140]: verbose: ControllerMpd::parseState Dec 25 21:30:31 rivo volumio[3140]: info: ControllerMpd::pushState Dec 25 21:30:31 rivo volumio[3140]: info: CoreCommandRouter::servicePushState Dec 25 21:30:31 rivo volumio[3140]: info: CoreStateMachine::pushState Dec 25 21:30:31 rivo volumio[3140]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 25 21:30:31 rivo volumio[3140]: info: CoreCommandRouter::volumioPushState Dec 25 21:30:31 rivo volumio[3140]: info: CoreCommandRouter::volumioGetState Dec 25 21:30:31 rivo volumio[3140]: info: CorePlayQueue::getTrack 0 Dec 25 21:30:31 rivo volumio[3140]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Dec 25 21:30:31 rivo volumio[3140]: verbose: CURRENT POSITION 0 Dec 25 21:30:31 rivo volumio[3140]: info: CoreStateMachine::syncState stateService stop Dec 25 21:30:31 rivo volumio[3140]: info: CoreStateMachine::syncState currentStatus stop Dec 25 21:30:31 rivo volumio[3140]: info: CoreStateMachine::pushState Dec 25 21:30:31 rivo volumio[3140]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 25 21:30:31 rivo volumio[3140]: info: CoreCommandRouter::volumioPushState Dec 25 21:30:31 rivo volumio[3140]: info: CoreCommandRouter::volumioGetState Dec 25 21:30:31 rivo volumio[3140]: info: No code Dec 25 21:30:31 rivo volumio[3140]: info: CoreStateMachine::pushState Dec 25 21:30:31 rivo volumio[3140]: info: CoreCommandRouter::volumioPushState Dec 25 21:30:31 rivo volumio[3140]: info: CoreCommandRouter::volumioGetState Dec 25 21:30:31 rivo volumio[3140]: info: ControllerMpd::pushState Dec 25 21:30:31 rivo volumio[3140]: info: CoreCommandRouter::servicePushState Dec 25 21:30:31 rivo volumio[3140]: info: CoreStateMachine::pushState Dec 25 21:30:31 rivo volumio[3140]: info: CoreCommandRouter::volumioPushState Dec 25 21:30:31 rivo volumio[3140]: info: CoreCommandRouter::volumioGetState Dec 25 21:30:31 rivo volumio[3140]: info: CorePlayQueue::getTrack 0 Dec 25 21:30:31 rivo volumio[3140]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Dec 25 21:30:31 rivo volumio[3140]: verbose: CURRENT POSITION 0 Dec 25 21:30:31 rivo volumio[3140]: info: CoreStateMachine::syncState stateService stop Dec 25 21:30:31 rivo volumio[3140]: info: CoreStateMachine::syncState currentStatus stop Dec 25 21:30:31 rivo volumio[3140]: info: CoreStateMachine::pushState Dec 25 21:30:31 rivo volumio[3140]: info: CoreCommandRouter::volumioPushState Dec 25 21:30:31 rivo volumio[3140]: info: CoreCommandRouter::volumioGetState Dec 25 21:30:31 rivo volumio[3140]: info: No code Dec 25 21:30:31 rivo volumio[3140]: info: CoreStateMachine::pushState Dec 25 21:30:31 rivo volumio[3140]: info: CoreCommandRouter::volumioPushState Dec 25 21:30:31 rivo volumio[3140]: info: CoreCommandRouter::volumioGetState Dec 25 21:30:31 rivo volumio[3140]: info: ------------------------------ 3686ms Dec 25 21:30:31 rivo volumio[3140]: info: ------------------------------ 3688ms Dec 25 21:30:32 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:32.079Z level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=3 Dec 25 21:30:32 rivo volumio[3140]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Dec 25 21:30:32 rivo volumio[3140]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Dec 25 21:30:32 rivo volumio[3140]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Dec 25 21:30:32 rivo volumio[3140]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Dec 25 21:30:32 rivo volumio[3140]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Dec 25 21:30:32 rivo volumio[3140]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Dec 25 21:30:32 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:32.380Z level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=3 Dec 25 21:30:32 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:32.681Z level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=3 Dec 25 21:30:32 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:32.982Z level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=3 Dec 25 21:30:33 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:33.283Z level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=3 Dec 25 21:30:33 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:33.583Z level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=3 Dec 25 21:30:33 rivo volumio[3140]: Cannot compose Albumart path Dec 25 21:30:33 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:33.883Z level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=3 Dec 25 21:30:34 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:34.184Z level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=3 Dec 25 21:30:34 rivo volumio[3140]: info: sendMpdCommand status took 6118 milliseconds Dec 25 21:30:34 rivo volumio[3140]: info: sendMpdCommand status took 6117 milliseconds Dec 25 21:30:34 rivo volumio[3140]: info: sendMpdCommand status took 6117 milliseconds Dec 25 21:30:34 rivo volumio[3140]: verbose: ControllerMpd::parseState Dec 25 21:30:34 rivo volumio[3140]: info: Command Router : Notfying DB Updatefalse Dec 25 21:30:34 rivo volumio[3140]: info: CoreCommandRouter::Close All Modals sent Dec 25 21:30:34 rivo volumio[3140]: verbose: ControllerMpd::parseState Dec 25 21:30:34 rivo volumio[3140]: verbose: ControllerMpd::parseState Dec 25 21:30:34 rivo volumio[3140]: info: ControllerMpd::pushState Dec 25 21:30:34 rivo volumio[3140]: info: CoreCommandRouter::servicePushState Dec 25 21:30:34 rivo volumio[3140]: info: CoreStateMachine::pushState Dec 25 21:30:34 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:34.484Z level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=3 Dec 25 21:30:34 rivo volumio[3140]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 25 21:30:34 rivo volumio[3140]: info: CoreCommandRouter::volumioPushState Dec 25 21:30:34 rivo volumio[3140]: info: CoreCommandRouter::volumioGetState Dec 25 21:30:34 rivo volumio[3140]: info: CorePlayQueue::getTrack 0 Dec 25 21:30:34 rivo volumio[3140]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Dec 25 21:30:34 rivo volumio[3140]: verbose: CURRENT POSITION 0 Dec 25 21:30:34 rivo volumio[3140]: info: CoreStateMachine::syncState stateService stop Dec 25 21:30:34 rivo volumio[3140]: info: CoreStateMachine::syncState currentStatus stop Dec 25 21:30:34 rivo volumio[3140]: info: CoreStateMachine::pushState Dec 25 21:30:34 rivo volumio[3140]: info: CoreCommandRouter::volumioPushState Dec 25 21:30:34 rivo volumio[3140]: info: CoreCommandRouter::volumioGetState Dec 25 21:30:34 rivo volumio[3140]: info: No code Dec 25 21:30:34 rivo volumio[3140]: info: CoreStateMachine::pushState Dec 25 21:30:34 rivo volumio[3140]: info: CoreCommandRouter::volumioPushState Dec 25 21:30:34 rivo volumio[3140]: info: CoreCommandRouter::volumioGetState Dec 25 21:30:34 rivo volumio[3140]: info: ControllerMpd::pushState Dec 25 21:30:34 rivo volumio[3140]: info: CoreCommandRouter::servicePushState Dec 25 21:30:34 rivo volumio[3140]: info: CoreStateMachine::pushState Dec 25 21:30:34 rivo volumio[3140]: info: CoreCommandRouter::volumioPushState Dec 25 21:30:34 rivo volumio[3140]: info: CoreCommandRouter::volumioGetState Dec 25 21:30:34 rivo volumio[3140]: info: CorePlayQueue::getTrack 0 Dec 25 21:30:34 rivo volumio[3140]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Dec 25 21:30:34 rivo volumio[3140]: verbose: CURRENT POSITION 0 Dec 25 21:30:34 rivo volumio[3140]: info: CoreStateMachine::syncState stateService stop Dec 25 21:30:34 rivo volumio[3140]: info: CoreStateMachine::syncState currentStatus stop Dec 25 21:30:34 rivo volumio[3140]: info: CoreStateMachine::pushState Dec 25 21:30:34 rivo volumio[3140]: info: CoreCommandRouter::volumioPushState Dec 25 21:30:34 rivo volumio[3140]: info: CoreCommandRouter::volumioGetState Dec 25 21:30:34 rivo volumio[3140]: info: No code Dec 25 21:30:34 rivo volumio[3140]: info: CoreStateMachine::pushState Dec 25 21:30:34 rivo volumio[3140]: info: CoreCommandRouter::volumioPushState Dec 25 21:30:34 rivo volumio[3140]: info: CoreCommandRouter::volumioGetState Dec 25 21:30:34 rivo volumio[3140]: info: ------------------------------ 6218ms Dec 25 21:30:34 rivo volumio[3140]: info: ------------------------------ 6219ms Dec 25 21:30:34 rivo volumio[3140]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Dec 25 21:30:34 rivo volumio[3140]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Dec 25 21:30:34 rivo volumio[3140]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Dec 25 21:30:34 rivo volumio[3140]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Dec 25 21:30:34 rivo volumio[3140]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Dec 25 21:30:34 rivo volumio[3140]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Dec 25 21:30:34 rivo volumio[3140]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Dec 25 21:30:34 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:34.785Z level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=3 Dec 25 21:30:35 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:35.086Z level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=3 Dec 25 21:30:35 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:35.086Z level=ERROR msg="pending write exceeded maximum retries, dropping" component=conn/ble addr=3 chunks=1 index=0 Dec 25 21:30:35 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:35.087Z level=ERROR msg="failed to send event" component=server dst="00:00:00:00:00:00%03 @ 0x1a6dd10" event=SERVER_EVENT_TYPE_PLAYER_STATE_CHANGED error="peer is gone" Dec 25 21:30:35 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:35.387Z level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=3 Dec 25 21:30:35 rivo volumio[3140]: info: CoreCommandRouter::volumioGetState Dec 25 21:30:35 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:35.688Z level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=3 Dec 25 21:30:35 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:35.988Z level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=3 Dec 25 21:30:36 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:36.290Z level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=3 Dec 25 21:30:36 rivo volumio[3140]: Cannot compose Albumart path Dec 25 21:30:36 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:36.590Z level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=3 Dec 25 21:30:36 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:36.891Z level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=3 Dec 25 21:30:36 rivo volumio[3140]: info: sendMpdCommand status took 8643 milliseconds Dec 25 21:30:36 rivo volumio[3140]: info: sendMpdCommand status took 8643 milliseconds Dec 25 21:30:36 rivo volumio[3140]: info: sendMpdCommand status took 8642 milliseconds Dec 25 21:30:36 rivo volumio[3140]: verbose: ControllerMpd::parseState Dec 25 21:30:36 rivo volumio[3140]: info: Command Router : Notfying DB Updatefalse Dec 25 21:30:36 rivo volumio[3140]: info: CoreCommandRouter::Close All Modals sent Dec 25 21:30:37 rivo volumio[3140]: verbose: ControllerMpd::parseState Dec 25 21:30:37 rivo volumio[3140]: verbose: ControllerMpd::parseState Dec 25 21:30:37 rivo volumio[3140]: info: ControllerMpd::pushState Dec 25 21:30:37 rivo volumio[3140]: info: CoreCommandRouter::servicePushState Dec 25 21:30:37 rivo volumio[3140]: info: CoreStateMachine::pushState Dec 25 21:30:37 rivo volumio[3140]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 25 21:30:37 rivo volumio[3140]: info: CoreCommandRouter::volumioPushState Dec 25 21:30:37 rivo volumio[3140]: info: CoreCommandRouter::volumioGetState Dec 25 21:30:37 rivo volumio[3140]: info: CorePlayQueue::getTrack 0 Dec 25 21:30:37 rivo volumio[3140]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Dec 25 21:30:37 rivo volumio[3140]: verbose: CURRENT POSITION 0 Dec 25 21:30:37 rivo volumio[3140]: info: CoreStateMachine::syncState stateService stop Dec 25 21:30:37 rivo volumio[3140]: info: CoreStateMachine::syncState currentStatus stop Dec 25 21:30:37 rivo volumio[3140]: info: CoreStateMachine::pushState Dec 25 21:30:37 rivo volumio[3140]: info: CoreCommandRouter::volumioPushState Dec 25 21:30:37 rivo volumio[3140]: info: CoreCommandRouter::volumioGetState Dec 25 21:30:37 rivo volumio[3140]: info: No code Dec 25 21:30:37 rivo volumio[3140]: info: CoreStateMachine::pushState Dec 25 21:30:37 rivo volumio[3140]: info: CoreCommandRouter::volumioPushState Dec 25 21:30:37 rivo volumio[3140]: info: CoreCommandRouter::volumioGetState Dec 25 21:30:37 rivo volumio[3140]: info: ControllerMpd::pushState Dec 25 21:30:37 rivo volumio[3140]: info: CoreCommandRouter::servicePushState Dec 25 21:30:37 rivo volumio[3140]: info: CoreStateMachine::pushState Dec 25 21:30:37 rivo volumio[3140]: info: CoreCommandRouter::volumioPushState Dec 25 21:30:37 rivo volumio[3140]: info: CoreCommandRouter::volumioGetState Dec 25 21:30:37 rivo volumio[3140]: info: CorePlayQueue::getTrack 0 Dec 25 21:30:37 rivo volumio[3140]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Dec 25 21:30:37 rivo volumio[3140]: verbose: CURRENT POSITION 0 Dec 25 21:30:37 rivo volumio[3140]: info: CoreStateMachine::syncState stateService stop Dec 25 21:30:37 rivo volumio[3140]: info: CoreStateMachine::syncState currentStatus stop Dec 25 21:30:37 rivo volumio[3140]: info: CoreStateMachine::pushState Dec 25 21:30:37 rivo volumio[3140]: info: CoreCommandRouter::volumioPushState Dec 25 21:30:37 rivo volumio[3140]: info: CoreCommandRouter::volumioGetState Dec 25 21:30:37 rivo volumio[3140]: info: No code Dec 25 21:30:37 rivo volumio[3140]: info: CoreStateMachine::pushState Dec 25 21:30:37 rivo volumio[3140]: info: CoreCommandRouter::volumioPushState Dec 25 21:30:37 rivo volumio[3140]: info: CoreCommandRouter::volumioGetState Dec 25 21:30:37 rivo volumio[3140]: info: ------------------------------ 8729ms Dec 25 21:30:37 rivo volumio[3140]: info: ------------------------------ 8731ms Dec 25 21:30:37 rivo volumio[3140]: info: CoreCommandRouter::volumioGetQueue Dec 25 21:30:37 rivo volumio[3140]: info: CoreStateMachine::getQueue Dec 25 21:30:37 rivo volumio[3140]: info: CorePlayQueue::getQueue Dec 25 21:30:37 rivo volumio[3140]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Dec 25 21:30:37 rivo volumio[3140]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Dec 25 21:30:37 rivo volumio[3140]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Dec 25 21:30:37 rivo volumio[3140]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Dec 25 21:30:37 rivo volumio[3140]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Dec 25 21:30:37 rivo volumio[3140]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Dec 25 21:30:37 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:37.191Z level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=3 Dec 25 21:30:37 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:37.492Z level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=3 Dec 25 21:30:37 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:37.792Z level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=3 Dec 25 21:30:38 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:38.093Z level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=3 Dec 25 21:30:38 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:38.394Z level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=3 Dec 25 21:30:38 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:38.395Z level=ERROR msg="pending write exceeded maximum retries, dropping" component=conn/ble addr=3 chunks=1 index=0 Dec 25 21:30:38 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:38.395Z level=ERROR msg="failed to send event" component=server dst="00:00:00:00:00:00%03 @ 0x1a6dd10" event=SERVER_EVENT_TYPE_PLAYER_STATE_CHANGED error="peer is gone" Dec 25 21:30:38 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:38.695Z level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=3 Dec 25 21:30:38 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:38.996Z level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=3 Dec 25 21:30:39 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:39.297Z level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=3 Dec 25 21:30:39 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:39.598Z level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=3 Dec 25 21:30:39 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:39.899Z level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=3 Dec 25 21:30:40 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:40.200Z level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=3 Dec 25 21:30:40 rivo volumio[3140]: info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri Dec 25 21:30:40 rivo volumio[3140]: info: CURURI: artists:// Dec 25 21:30:40 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:40.500Z level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=3 Dec 25 21:30:40 rivo volumio[3140]: info: Preload queue cleared Dec 25 21:30:40 rivo go-librespot[4162]: time="2025-12-25T21:30:40Z" level=trace msg="sent dealer ping" Dec 25 21:30:40 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:40.801Z level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=3 Dec 25 21:30:40 rivo go-librespot[4162]: time="2025-12-25T21:30:40Z" level=trace msg="received dealer pong" Dec 25 21:30:41 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:41.102Z level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=3 Dec 25 21:30:41 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:41.402Z level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=3 Dec 25 21:30:41 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:41.702Z level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=3 Dec 25 21:30:41 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:41.703Z level=ERROR msg="pending write exceeded maximum retries, dropping" component=conn/ble addr=3 chunks=1 index=0 Dec 25 21:30:41 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:41.703Z level=ERROR msg="failed to send event" component=server dst="00:00:00:00:00:00%03 @ 0x1a6dd10" event=SERVER_EVENT_TYPE_PLAYER_STATE_CHANGED error="peer is gone" Dec 25 21:30:42 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:42.003Z level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=3 Dec 25 21:30:42 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:42.303Z level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=3 Dec 25 21:30:42 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:42.604Z level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=3 Dec 25 21:30:42 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:42.904Z level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=3 Dec 25 21:30:43 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:43.205Z level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=3 Dec 25 21:30:43 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:43.506Z level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=3 Dec 25 21:30:43 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:43.807Z level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=3 Dec 25 21:30:44 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:44.108Z level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=3 Dec 25 21:30:44 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:44.409Z level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=3 Dec 25 21:30:44 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:44.710Z level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=3 Dec 25 21:30:45 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:45.010Z level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=3 Dec 25 21:30:45 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:45.010Z level=ERROR msg="pending write exceeded maximum retries, dropping" component=conn/ble addr=3 chunks=1 index=0 Dec 25 21:30:45 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:45.011Z level=ERROR msg="failed to send event" component=server dst="00:00:00:00:00:00%03 @ 0x1a6dd10" event=SERVER_EVENT_TYPE_PLAYER_STATE_CHANGED error="peer is gone" Dec 25 21:30:45 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:45.311Z level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=3 Dec 25 21:30:45 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:45.612Z level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=3 Dec 25 21:30:45 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:45.912Z level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=3 Dec 25 21:30:46 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:46.213Z level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=3 Dec 25 21:30:46 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:46.513Z level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=3 Dec 25 21:30:46 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:46.815Z level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=3 Dec 25 21:30:47 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:47.116Z level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=3 Dec 25 21:30:47 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:47.417Z level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=3 Dec 25 21:30:47 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:47.718Z level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=3 Dec 25 21:30:48 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:48.019Z level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=3 Dec 25 21:30:48 rivo volumio[3140]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 25 21:30:48 rivo volumio[3140]: TypeError: Cannot read property 'slice' of null Dec 25 21:30:48 rivo volumio[3140]: at download (/volumio/app/plugins/miscellanea/albumart/albumart.js:718:41) Dec 25 21:30:48 rivo volumio[3140]: at ClientRequest. (/volumio/app/plugins/miscellanea/albumart/albumart.js:728:7) Dec 25 21:30:48 rivo volumio[3140]: at Object.onceWrapper (events.js:520:26) Dec 25 21:30:48 rivo volumio[3140]: at ClientRequest.emit (events.js:400:28) Dec 25 21:30:48 rivo volumio[3140]: at HTTPParser.parserOnIncomingClient [as onIncoming] (_http_client.js:647:27) Dec 25 21:30:48 rivo volumio[3140]: at HTTPParser.parserOnHeadersComplete (_http_common.js:127:17) Dec 25 21:30:48 rivo volumio[3140]: at TLSSocket.socketOnData (_http_client.js:515:22) Dec 25 21:30:48 rivo volumio[3140]: at TLSSocket.emit (events.js:400:28) Dec 25 21:30:48 rivo volumio[3140]: at addChunk (internal/streams/readable.js:293:12) Dec 25 21:30:48 rivo volumio[3140]: at readableAddChunk (internal/streams/readable.js:267:9) Dec 25 21:30:48 rivo volumio[3140]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 25 21:30:48 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:48.320Z level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=3 Dec 25 21:30:48 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:48.321Z level=ERROR msg="pending write exceeded maximum retries, dropping" component=conn/ble addr=3 chunks=1 index=0 Dec 25 21:30:48 rivo volumio5-onboarding[3737]: time=2025-12-25T21:30:48.321Z level=ERROR msg="failed to send event" component=server dst="00:00:00:00:00:00%03 @ 0x1a6dd10" event=SERVER_EVENT_TYPE_PLAYER_STATE_CHANGED error="peer is gone" Dec 25 21:30:49 rivo sudo[3435]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-12-25 21:29 Dec 25 21:30:49 rivo sudo[3435]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Debian GNU/Linux 10 (buster)" NAME="Debian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=debian HOME_URL="https://www.debian.org/" SUPPORT_URL="https://www.debian.org/support" BUG_REPORT_URL="https://bugs.debian.org/" VOLUMIO_BUILD_VERSION="b43c85cc0006d3f1efecba101311ec96e334d1fd" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="2f25e1a98e53e2dbc4f3878604e250b0379f3ea4" VOLUMIO_ARCH="armv7" VOLUMIO_VARIANT="rivo" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Thu 11 Dec 2025 07:07:40 PM CET" VOLUMIO_VERSION="3.886" VOLUMIO_HARDWARE="mp1" VOLUMIO_DEVICENAME="Volumio MP1" VOLUMIO_VENDOR_MODEL="Volumio Rivo" VOLUMIO_VENDOR="Volumio" VOLUMIO_MODEL="Rivo" VOLUMIO_HASH="90457dc663650a5d2f936402ef6c7dc1"