-- Logs begin at Mon 2026-02-09 22:36:31 MSK, end at Mon 2026-02-09 22:41:37 MSK. -- Feb 09 22:40:00 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: qobuz , handleBrowseUri Feb 09 22:40:00 primo volumio[3119]: info: handleBrowseUri took 250 milliseconds Feb 09 22:40:00 primo volumio[3119]: info: Preload queue cleared Feb 09 22:40:00 primo volumio[3119]: info: Preloading song: qobuz://song/225588742 Feb 09 22:40:00 primo volumio[3119]: info: Exploding uri qobuz://song/225588742 in service qobuz Feb 09 22:40:00 primo volumio[3119]: https://prod.vlmapi.io/v2/qobuz/explodeUri Feb 09 22:40:00 primo volumio[3119]: info: Executing endpoint getSimilarAlbums Feb 09 22:40:00 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getSimilarAlbums Feb 09 22:40:01 primo volumio[3119]: info: explodeUri took 362 milliseconds Feb 09 22:40:02 primo volumio[3119]: info: Executing endpoint getSimilarAlbums Feb 09 22:40:02 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getSimilarAlbums Feb 09 22:40:02 primo volumio[3119]: info: Executing endpoint metavolumio Feb 09 22:40:02 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Feb 09 22:40:03 primo volumio[3119]: info: CoreCommandRouter::volumioAddQueueItems Feb 09 22:40:03 primo volumio[3119]: info: CoreStateMachine::addQueueItems Feb 09 22:40:03 primo volumio[3119]: info: CorePlayQueue::addQueueItems Feb 09 22:40:03 primo volumio[3119]: info: Preload queue cleared Feb 09 22:40:03 primo volumio[3119]: info: Adding Item to queue: qobuz://album/yzft6jaodl4nc Feb 09 22:40:03 primo volumio[3119]: info: Exploding uri qobuz://album/yzft6jaodl4nc in service qobuz Feb 09 22:40:03 primo volumio[3119]: https://prod.vlmapi.io/v2/qobuz/explodeUri Feb 09 22:40:03 primo volumio[3119]: info: explodeUri took 267 milliseconds Feb 09 22:40:03 primo volumio[3119]: info: CoreCommandRouter::volumioPushQueue Feb 09 22:40:03 primo volumio[3119]: info: CorePlayQueue::saveQueue Feb 09 22:40:03 primo volumio[3119]: info: CoreStateMachine::updateTrackBlock Feb 09 22:40:03 primo volumio[3119]: info: CorePlayQueue::getTrackBlock Feb 09 22:40:04 primo volumio[3119]: info: Preload queue cleared Feb 09 22:40:04 primo volumio[3119]: info: CoreCommandRouter::volumioReplaceandPlayItems Feb 09 22:40:04 primo volumio[3119]: info: CoreStateMachine::ClearQueue Feb 09 22:40:04 primo volumio[3119]: info: CoreStateMachine::stop Feb 09 22:40:04 primo volumio[3119]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 09 22:40:04 primo volumio[3119]: info: CoreStateMachine::updateTrackBlock Feb 09 22:40:04 primo volumio[3119]: info: CorePlayQueue::getTrackBlock Feb 09 22:40:04 primo volumio[3119]: info: CoreStateMachine::stPlaybackTimer Feb 09 22:40:04 primo volumio[3119]: info: CoreStateMachine::pushState Feb 09 22:40:04 primo volumio[3119]: info: CorePlayQueue::getTrack 2 Feb 09 22:40:04 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 09 22:40:04 primo volumio[3119]: info: CoreCommandRouter::volumioPushState Feb 09 22:40:04 primo volumio[3119]: info: CoreStateMachine::serviceStop Feb 09 22:40:04 primo volumio[3119]: info: CorePlayQueue::getTrack 2 Feb 09 22:40:04 primo volumio[3119]: info: CoreCommandRouter::serviceStop Feb 09 22:40:04 primo volumio[3119]: info: [1770666004540] ControllerQobuz::stop Feb 09 22:40:04 primo volumio[3119]: info: CoreStateMachine::setConsumeUpdateService mpd Feb 09 22:40:04 primo volumio[3119]: info: ControllerMpd::stop Feb 09 22:40:04 primo volumio[3119]: verbose: ControllerMpd::sendMpdCommand stop Feb 09 22:40:04 primo volumio[3119]: info: CorePlayQueue::clearPlayQueue Feb 09 22:40:04 primo volumio[3119]: info: CorePlayQueue::saveQueue Feb 09 22:40:04 primo volumio[3119]: info: CoreCommandRouter::volumioPushQueue Feb 09 22:40:04 primo volumio[3119]: info: CoreStateMachine::addQueueItems Feb 09 22:40:04 primo volumio[3119]: info: CorePlayQueue::addQueueItems Feb 09 22:40:04 primo volumio[3119]: info: Preload queue cleared Feb 09 22:40:04 primo volumio[3119]: info: Adding Item to queue: qobuz://song/225588742 Feb 09 22:40:04 primo volumio[3119]: info: Using cached record of: qobuz://song/225588742 Feb 09 22:40:04 primo volumio[3119]: info: CoreCommandRouter::volumioPushQueue Feb 09 22:40:04 primo volumio[3119]: info: CorePlayQueue::saveQueue Feb 09 22:40:04 primo volumio[3119]: info: CoreStateMachine::updateTrackBlock Feb 09 22:40:04 primo volumio[3119]: info: CorePlayQueue::getTrackBlock Feb 09 22:40:04 primo volumio[3119]: info: CoreCommandRouter::volumioPlay Feb 09 22:40:04 primo volumio[3119]: info: CoreStateMachine::play index 0 Feb 09 22:40:04 primo volumio[3119]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 09 22:40:04 primo volumio[3119]: info: CoreStateMachine::stop Feb 09 22:40:04 primo volumio[3119]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 09 22:40:04 primo volumio[3119]: info: CoreStateMachine::play index undefined Feb 09 22:40:04 primo volumio[3119]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 09 22:40:04 primo volumio[3119]: info: CorePlayQueue::getTrack 0 Feb 09 22:40:04 primo volumio[3119]: info: CoreStateMachine::startPlaybackTimer Feb 09 22:40:04 primo volumio[3119]: info: CorePlayQueue::getTrack 0 Feb 09 22:40:04 primo volumio[3119]: info: CoreCommandRouter::volumioGetVisibleSources Feb 09 22:40:04 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 09 22:40:04 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Feb 09 22:40:04 primo volumio[3119]: info: [1770666004573] ControllerQobuz::clearAddPlayTrack Feb 09 22:40:04 primo volumio[3119]: verbose: ControllerMpd::sendMpdCommand stop Feb 09 22:40:04 primo volumio[3119]: info: Updating RAAT Signal Path Feb 09 22:40:04 primo volumio[3119]: info: Feb 09 22:40:04 primo volumio[3119]: ---------------------------- MPD announces state update: player Feb 09 22:40:04 primo volumio[3119]: info: sendMpdCommand stop took 43 milliseconds Feb 09 22:40:04 primo volumio[3119]: info: ControllerMpd::getState Feb 09 22:40:04 primo volumio[3119]: verbose: ControllerMpd::sendMpdCommand status Feb 09 22:40:04 primo volumio[3119]: info: sendMpdCommand stop took 11 milliseconds Feb 09 22:40:04 primo volumio[3119]: verbose: ControllerMpd::sendMpdCommand clear Feb 09 22:40:04 primo volumio[3119]: info: Feb 09 22:40:04 primo volumio[3119]: ---------------------------- MPD announces state update: player Feb 09 22:40:04 primo volumio[3119]: info: ControllerMpd::getState Feb 09 22:40:04 primo volumio[3119]: verbose: ControllerMpd::sendMpdCommand status Feb 09 22:40:04 primo volumio[3119]: info: Feb 09 22:40:04 primo volumio[3119]: ---------------------------- MPD announces state update: player Feb 09 22:40:04 primo volumio[3119]: info: ControllerMpd::getState Feb 09 22:40:04 primo volumio5-onboarding[4373]: failed to bootstrap state: failed to get music providers: could not get available plugins: could not get available plugins: context deadline exceeded Feb 09 22:40:04 primo volumio[3119]: verbose: ControllerMpd::sendMpdCommand status Feb 09 22:40:04 primo systemd[1]: volumio5-onboarding.service: Main process exited, code=exited, status=1/FAILURE Feb 09 22:40:04 primo systemd[1]: volumio5-onboarding.service: Failed with result 'exit-code'. Feb 09 22:40:04 primo volumio[3119]: info: Feb 09 22:40:04 primo volumio[3119]: ---------------------------- MPD announces system playlist update Feb 09 22:40:04 primo volumio[3119]: info: Ignoring MPD Status Update Feb 09 22:40:04 primo volumio[3119]: info: sendMpdCommand status took 13 milliseconds Feb 09 22:40:04 primo volumio[3119]: info: sendMpdCommand clear took 12 milliseconds Feb 09 22:40:04 primo volumio[3119]: info: sendMpdCommand status took 11 milliseconds Feb 09 22:40:04 primo volumio[3119]: verbose: ControllerMpd::parseState Feb 09 22:40:04 primo volumio[3119]: verbose: ControllerMpd::sendMpdCommand playlistinfo Feb 09 22:40:04 primo volumio[3119]: verbose: ControllerMpd::sendMpdCommand load "http://127.0.0.1:3245?data=qobuz://song/225588742" Feb 09 22:40:04 primo volumio[3119]: verbose: ControllerMpd::parseState Feb 09 22:40:04 primo volumio[3119]: info: ControllerMpd::pushState Feb 09 22:40:04 primo volumio[3119]: info: CoreCommandRouter::servicePushState Feb 09 22:40:04 primo volumio[3119]: info: CoreStateMachine::pushState Feb 09 22:40:04 primo volumio[3119]: info: CorePlayQueue::getTrack 0 Feb 09 22:40:04 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 09 22:40:04 primo volumio[3119]: info: CoreCommandRouter::volumioPushState Feb 09 22:40:04 primo volumio[3119]: STREAMING PROXY: Handling url /?data=qobuz://song/225588742 Feb 09 22:40:04 primo volumio[3119]: info: CorePlayQueue::getTrack 0 Feb 09 22:40:04 primo volumio[3119]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current qobuz Received mpd Feb 09 22:40:04 primo volumio[3119]: info: ------------------------------ 30ms Feb 09 22:40:04 primo volumio[3119]: info: Feb 09 22:40:04 primo volumio[3119]: ---------------------------- MPD announces system playlist update Feb 09 22:40:04 primo volumio[3119]: info: Ignoring MPD Status Update Feb 09 22:40:04 primo volumio[3119]: info: Feb 09 22:40:04 primo volumio[3119]: ---------------------------- MPD announces system playlist update Feb 09 22:40:04 primo volumio[3119]: info: Ignoring MPD Status Update Feb 09 22:40:04 primo volumio[3119]: error: Upnp client error: Error: This socket has been ended by the other party Feb 09 22:40:04 primo volumio[3119]: info: sendMpdCommand status took 49 milliseconds Feb 09 22:40:04 primo volumio[3119]: verbose: ControllerMpd::parseState Feb 09 22:40:04 primo volumio[3119]: info: ControllerMpd::pushState Feb 09 22:40:04 primo volumio[3119]: info: CoreCommandRouter::servicePushState Feb 09 22:40:04 primo volumio[3119]: info: CoreStateMachine::pushState Feb 09 22:40:04 primo volumio[3119]: info: CorePlayQueue::getTrack 0 Feb 09 22:40:04 primo volumio[3119]: info: CoreCommandRouter::volumioPushState Feb 09 22:40:04 primo volumio[3119]: info: CorePlayQueue::getTrack 0 Feb 09 22:40:04 primo volumio[3119]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current qobuz Received mpd Feb 09 22:40:04 primo volumio[3119]: info: ------------------------------ 60ms Feb 09 22:40:04 primo volumio[3119]: info: Updating RAAT Signal Path Feb 09 22:40:04 primo volumio[3119]: info: Updating RAAT Signal Path Feb 09 22:40:04 primo volumio[3119]: info: Executing endpoint getStreamUrlqobuz Feb 09 22:40:04 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: qobuz , getStreamUrlAPI Feb 09 22:40:04 primo systemd[1]: volumio5-onboarding.service: Service RestartSec=100ms expired, scheduling restart. Feb 09 22:40:04 primo systemd[1]: volumio5-onboarding.service: Scheduled restart job, restart counter is at 6. Feb 09 22:40:04 primo systemd[1]: Stopped Volumio5 Onboarding Server. Feb 09 22:40:04 primo systemd[1]: Started Volumio5 Onboarding Server. Feb 09 22:40:04 primo volumio5-onboarding[4482]: time=2026-02-09T22:40:04.766+03:00 level=INFO msg="running volumio5-device-gateway" version=5bca5789+CHANGES buildDate=2025-12-11T14:07:23Z Feb 09 22:40:04 primo volumio[3119]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 7 Feb 09 22:40:04 primo volumio[3119]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 7 Feb 09 22:40:04 primo volumio5-onboarding[4482]: time=2026-02-09T22:40:04.815+03:00 level=INFO msg="listening for BLE messages" address=B8:2D:28:29:82:8D%00 Feb 09 22:40:04 primo volumio5-onboarding[4482]: time=2026-02-09T22:40:04.816+03:00 level=INFO msg="listening for WebSocket messages" address=[::]:7331 Feb 09 22:40:04 primo volumio[3119]: info: Received Get System Info Feb 09 22:40:04 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Feb 09 22:40:04 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Feb 09 22:40:04 primo volumio[3119]: info: Discovery: Getting this device information Feb 09 22:40:04 primo volumio[3119]: info: CoreCommandRouter::volumioGetState Feb 09 22:40:04 primo volumio[3119]: info: CorePlayQueue::getTrack 0 Feb 09 22:40:04 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 09 22:40:04 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Feb 09 22:40:04 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Feb 09 22:40:04 primo volumio5-onboarding[4482]: time=2026-02-09T22:40:04.830+03:00 level=INFO msg="BLE descriptor updated" deviceId=5caac58d64be6db5186fdaf1deb5d9a3 deviceName=Primo deviceModel=0x1e101e0 Feb 09 22:40:04 primo volumio5-onboarding[4482]: time=2026-02-09T22:40:04.830+03:00 level=INFO msg="mDNS descriptor updated" deviceId=5caac58d64be6db5186fdaf1deb5d9a3 deviceName=Primo deviceModel=0x1e101e0 Feb 09 22:40:04 primo volumio5-onboarding[4482]: time=2026-02-09T22:40:04.848+03:00 level=INFO msg="bootstrapping state" hasInternet=true Feb 09 22:40:04 primo volumio[3119]: info: Received Get System Info Feb 09 22:40:04 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Feb 09 22:40:04 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Feb 09 22:40:04 primo volumio[3119]: info: Discovery: Getting this device information Feb 09 22:40:04 primo volumio[3119]: info: CoreCommandRouter::volumioGetState Feb 09 22:40:04 primo volumio[3119]: info: CorePlayQueue::getTrack 0 Feb 09 22:40:04 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 09 22:40:04 primo volumio-remote-updater[2837]: No test mode Feb 09 22:40:04 primo volumio-remote-updater[2837]: No alpha test mode Feb 09 22:40:04 primo volumio[3119]: info: Update Ready: {"changeLogLink":"","description":"You're already on the latest version","title":"No Updates Available","updateavailable":false} Feb 09 22:40:04 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache Feb 09 22:40:04 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Feb 09 22:40:05 primo volumio[3119]: info: getStreamUrl took 333 milliseconds Feb 09 22:40:05 primo volumio[3119]: STREAMING PROXY: Got real url: https://streaming-qobuz-std.akamaized.net/file?uid=10410469&eid=225588742&fmt=6&profile=raw&app_id=539451548&cid=3860823&etsp=1770669604&hmac=1wg2elu65sz3mYN2RV0IlH6gljs Feb 09 22:40:05 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Feb 09 22:40:05 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Feb 09 22:40:05 primo volumio[3119]: info: Executing endpoint metavolumio Feb 09 22:40:05 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Feb 09 22:40:07 primo volumio[3119]: info: CoreCommandRouter::volumioPlay Feb 09 22:40:07 primo volumio[3119]: info: CoreStateMachine::play index undefined Feb 09 22:40:07 primo volumio[3119]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 09 22:40:07 primo volumio[3119]: info: CorePlayQueue::getTrack 0 Feb 09 22:40:07 primo volumio[3119]: info: CoreStateMachine::startPlaybackTimer Feb 09 22:40:07 primo volumio[3119]: info: CorePlayQueue::getTrack 0 Feb 09 22:40:07 primo volumio[3119]: info: CoreCommandRouter::volumioGetVisibleSources Feb 09 22:40:07 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 09 22:40:07 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Feb 09 22:40:07 primo volumio[3119]: info: [1770666007761] ControllerQobuz::clearAddPlayTrack Feb 09 22:40:07 primo volumio[3119]: verbose: ControllerMpd::sendMpdCommand stop Feb 09 22:40:14 primo volumio[3119]: info: CoreCommandRouter::volumioPlay Feb 09 22:40:14 primo volumio[3119]: info: CoreStateMachine::play index undefined Feb 09 22:40:14 primo volumio[3119]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 09 22:40:14 primo volumio[3119]: info: CorePlayQueue::getTrack 0 Feb 09 22:40:14 primo volumio[3119]: info: CoreStateMachine::startPlaybackTimer Feb 09 22:40:14 primo volumio[3119]: info: CorePlayQueue::getTrack 0 Feb 09 22:40:14 primo volumio[3119]: info: CoreCommandRouter::volumioGetVisibleSources Feb 09 22:40:14 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 09 22:40:14 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Feb 09 22:40:14 primo volumio[3119]: info: [1770666014214] ControllerQobuz::clearAddPlayTrack Feb 09 22:40:14 primo volumio[3119]: verbose: ControllerMpd::sendMpdCommand stop Feb 09 22:40:16 primo volumio[3119]: error: Cannot download Available plugins list: Error: ESOCKETTIMEDOUT Feb 09 22:40:18 primo mpd_monitor.sh[3689]: MPD Monitor Service: MPD Appears to be inactive, restarting Feb 09 22:40:18 primo systemd[1]: Stopping Music Player Daemon... Feb 09 22:40:18 primo volumio[3119]: ------------------------------------ BT MESSAGE: BT STATUS: running Feb 09 22:40:31 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: inputs , alsavolume Feb 09 22:40:31 primo volumio[3119]: info: CoreStateMachine::pushState Feb 09 22:40:31 primo volumio[3119]: info: CorePlayQueue::getTrack 0 Feb 09 22:40:31 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 09 22:40:31 primo volumio[3119]: info: CoreCommandRouter::volumioPushState Feb 09 22:40:31 primo volumio[3119]: info: Updating RAAT Signal Path Feb 09 22:40:31 primo volumio[3119]: info: CoreStateMachine::pushState Feb 09 22:40:31 primo volumio[3119]: info: CorePlayQueue::getTrack 0 Feb 09 22:40:31 primo volumio[3119]: info: CoreCommandRouter::volumioPushState Feb 09 22:40:31 primo volumio[3119]: info: Updating RAAT Signal Path Feb 09 22:40:34 primo volumio5-onboarding[4482]: failed to bootstrap state: failed to get music providers: could not get available plugins: could not get available plugins: context deadline exceeded Feb 09 22:40:34 primo systemd[1]: volumio5-onboarding.service: Main process exited, code=exited, status=1/FAILURE Feb 09 22:40:34 primo systemd[1]: volumio5-onboarding.service: Failed with result 'exit-code'. Feb 09 22:40:34 primo systemd[1]: volumio5-onboarding.service: Service RestartSec=100ms expired, scheduling restart. Feb 09 22:40:34 primo systemd[1]: volumio5-onboarding.service: Scheduled restart job, restart counter is at 7. Feb 09 22:40:34 primo systemd[1]: Stopped Volumio5 Onboarding Server. Feb 09 22:40:34 primo systemd[1]: Started Volumio5 Onboarding Server. Feb 09 22:40:35 primo volumio5-onboarding[4558]: time=2026-02-09T22:40:35.016+03:00 level=INFO msg="running volumio5-device-gateway" version=5bca5789+CHANGES buildDate=2025-12-11T14:07:23Z Feb 09 22:40:35 primo volumio[3119]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 7 Feb 09 22:40:35 primo volumio[3119]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 7 Feb 09 22:40:35 primo volumio5-onboarding[4558]: time=2026-02-09T22:40:35.064+03:00 level=INFO msg="listening for BLE messages" address=B8:2D:28:29:82:8D%00 Feb 09 22:40:35 primo volumio5-onboarding[4558]: time=2026-02-09T22:40:35.065+03:00 level=INFO msg="listening for WebSocket messages" address=[::]:7331 Feb 09 22:40:35 primo volumio[3119]: info: Received Get System Info Feb 09 22:40:35 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Feb 09 22:40:35 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Feb 09 22:40:35 primo volumio[3119]: info: Discovery: Getting this device information Feb 09 22:40:35 primo volumio[3119]: info: CoreCommandRouter::volumioGetState Feb 09 22:40:35 primo volumio[3119]: info: CorePlayQueue::getTrack 0 Feb 09 22:40:35 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 09 22:40:35 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Feb 09 22:40:35 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Feb 09 22:40:35 primo volumio5-onboarding[4558]: time=2026-02-09T22:40:35.081+03:00 level=INFO msg="BLE descriptor updated" deviceId=5caac58d64be6db5186fdaf1deb5d9a3 deviceName=Primo deviceModel=0x1702d90 Feb 09 22:40:35 primo volumio5-onboarding[4558]: time=2026-02-09T22:40:35.081+03:00 level=INFO msg="mDNS descriptor updated" deviceId=5caac58d64be6db5186fdaf1deb5d9a3 deviceName=Primo deviceModel=0x1702d90 Feb 09 22:40:35 primo volumio5-onboarding[4558]: time=2026-02-09T22:40:35.100+03:00 level=INFO msg="bootstrapping state" hasInternet=true Feb 09 22:40:35 primo volumio[3119]: info: Received Get System Info Feb 09 22:40:35 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Feb 09 22:40:35 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Feb 09 22:40:35 primo volumio[3119]: info: Discovery: Getting this device information Feb 09 22:40:35 primo volumio[3119]: info: CoreCommandRouter::volumioGetState Feb 09 22:40:35 primo volumio[3119]: info: CorePlayQueue::getTrack 0 Feb 09 22:40:35 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 09 22:40:35 primo volumio-remote-updater[2837]: No test mode Feb 09 22:40:35 primo volumio-remote-updater[2837]: No alpha test mode Feb 09 22:40:35 primo volumio[3119]: info: Update Ready: {"changeLogLink":"","description":"You're already on the latest version","title":"No Updates Available","updateavailable":false} Feb 09 22:40:35 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache Feb 09 22:40:35 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Feb 09 22:40:35 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Feb 09 22:40:35 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Feb 09 22:40:46 primo volumio[3119]: error: Cannot download Available plugins list: Error: ESOCKETTIMEDOUT Feb 09 22:40:46 primo volumio[3119]: info: CoreCommandRouter::volumioNext Feb 09 22:40:46 primo volumio[3119]: info: CoreStateMachine::next Feb 09 22:40:46 primo volumio[3119]: info: CoreStateMachine::stop Feb 09 22:40:46 primo volumio[3119]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 09 22:40:46 primo volumio[3119]: info: CoreStateMachine::play index undefined Feb 09 22:40:46 primo volumio[3119]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 09 22:40:46 primo volumio[3119]: info: CorePlayQueue::getTrack 0 Feb 09 22:40:46 primo volumio[3119]: info: CoreStateMachine::startPlaybackTimer Feb 09 22:40:46 primo volumio[3119]: info: CorePlayQueue::getTrack 0 Feb 09 22:40:46 primo volumio[3119]: info: CoreCommandRouter::volumioGetVisibleSources Feb 09 22:40:46 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 09 22:40:46 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Feb 09 22:40:46 primo volumio[3119]: info: [1770666046507] ControllerQobuz::clearAddPlayTrack Feb 09 22:40:46 primo volumio[3119]: verbose: ControllerMpd::sendMpdCommand stop Feb 09 22:40:46 primo volumio[3119]: info: CoreStateMachine::updateTrackBlock Feb 09 22:40:46 primo volumio[3119]: info: CorePlayQueue::getTrackBlock Feb 09 22:40:47 primo volumio[3119]: info: CoreCommandRouter::volumioPlay Feb 09 22:40:47 primo volumio[3119]: info: CoreStateMachine::play index undefined Feb 09 22:40:47 primo volumio[3119]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 09 22:40:47 primo volumio[3119]: info: CorePlayQueue::getTrack 0 Feb 09 22:40:47 primo volumio[3119]: info: CoreStateMachine::startPlaybackTimer Feb 09 22:40:47 primo volumio[3119]: info: CorePlayQueue::getTrack 0 Feb 09 22:40:47 primo volumio[3119]: info: CoreCommandRouter::volumioGetVisibleSources Feb 09 22:40:47 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 09 22:40:47 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Feb 09 22:40:47 primo volumio[3119]: info: [1770666047743] ControllerQobuz::clearAddPlayTrack Feb 09 22:40:47 primo volumio[3119]: verbose: ControllerMpd::sendMpdCommand stop Feb 09 22:40:48 primo sudo[4649]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Feb 09 22:40:48 primo sudo[4649]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 09 22:40:48 primo sudo[4649]: pam_unix(sudo:session): session closed for user root Feb 09 22:40:48 primo sudo[4651]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Feb 09 22:40:48 primo sudo[4651]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 09 22:40:48 primo sudo[4651]: pam_unix(sudo:session): session closed for user root Feb 09 22:40:49 primo volumio[3119]: verbose: New Socket.io Connection to 192.168.1.12 from 192.168.1.1 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_6_2 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/18.6 Mobile/15E148 Safari/604.1 Engine version: 3 Transport: polling Total Clients: 7 Feb 09 22:40:49 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Feb 09 22:40:49 primo volumio[3119]: info: CoreCommandRouter::volumioGetVisibleSources Feb 09 22:40:49 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 09 22:40:49 primo volumio[3119]: info: CoreCommandRouter::volumioGetState Feb 09 22:40:49 primo volumio[3119]: info: CorePlayQueue::getTrack 0 Feb 09 22:40:49 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Feb 09 22:40:49 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Feb 09 22:40:49 primo volumio[3119]: info: Received Get System Info Feb 09 22:40:49 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Feb 09 22:40:49 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Feb 09 22:40:49 primo volumio[3119]: info: Discovery: Getting this device information Feb 09 22:40:49 primo volumio[3119]: info: CoreCommandRouter::volumioGetState Feb 09 22:40:49 primo volumio[3119]: info: CorePlayQueue::getTrack 0 Feb 09 22:40:49 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 09 22:40:49 primo volumio[3119]: info: CoreCommandRouter::volumioGetState Feb 09 22:40:49 primo volumio[3119]: info: CorePlayQueue::getTrack 0 Feb 09 22:40:49 primo volumio[3119]: info: Listing playlists Feb 09 22:40:49 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Feb 09 22:40:49 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Feb 09 22:40:49 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Feb 09 22:40:50 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Feb 09 22:40:50 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Feb 09 22:40:50 primo volumio[3119]: info: Received Get System Info Feb 09 22:40:50 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Feb 09 22:40:50 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Feb 09 22:40:50 primo volumio[3119]: info: Discovery: Getting this device information Feb 09 22:40:50 primo volumio[3119]: info: CoreCommandRouter::volumioGetState Feb 09 22:40:50 primo volumio[3119]: info: CorePlayQueue::getTrack 0 Feb 09 22:40:50 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 09 22:40:51 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Feb 09 22:40:51 primo volumio[3119]: info: Received Get System Info Feb 09 22:40:51 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Feb 09 22:40:51 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Feb 09 22:40:51 primo volumio[3119]: info: Discovery: Getting this device information Feb 09 22:40:51 primo volumio[3119]: info: CoreCommandRouter::volumioGetState Feb 09 22:40:51 primo volumio[3119]: info: CorePlayQueue::getTrack 0 Feb 09 22:40:51 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 09 22:40:53 primo sudo[4658]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Feb 09 22:40:53 primo sudo[4658]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 09 22:40:53 primo sudo[4658]: pam_unix(sudo:session): session closed for user root Feb 09 22:40:53 primo sudo[4661]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Feb 09 22:40:53 primo sudo[4661]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 09 22:40:53 primo sudo[4661]: pam_unix(sudo:session): session closed for user root Feb 09 22:40:53 primo volumio[3119]: verbose: New Socket.io Connection to 192.168.1.12 from 192.168.1.1 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_6_2 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/18.6 Mobile/15E148 Safari/604.1 Engine version: 3 Transport: polling Total Clients: 7 Feb 09 22:40:53 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Feb 09 22:40:53 primo volumio[3119]: info: CoreCommandRouter::volumioGetVisibleSources Feb 09 22:40:53 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 09 22:40:53 primo volumio[3119]: info: CoreCommandRouter::volumioGetState Feb 09 22:40:53 primo volumio[3119]: info: CorePlayQueue::getTrack 0 Feb 09 22:40:53 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Feb 09 22:40:53 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Feb 09 22:40:53 primo volumio[3119]: info: Received Get System Info Feb 09 22:40:53 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Feb 09 22:40:53 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Feb 09 22:40:53 primo volumio[3119]: info: Discovery: Getting this device information Feb 09 22:40:53 primo volumio[3119]: info: CoreCommandRouter::volumioGetState Feb 09 22:40:53 primo volumio[3119]: info: CorePlayQueue::getTrack 0 Feb 09 22:40:53 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 09 22:40:53 primo volumio[3119]: info: CoreCommandRouter::volumioGetState Feb 09 22:40:53 primo volumio[3119]: info: CorePlayQueue::getTrack 0 Feb 09 22:40:53 primo volumio[3119]: info: Listing playlists Feb 09 22:40:53 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Feb 09 22:40:53 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Feb 09 22:40:53 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Feb 09 22:40:54 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Feb 09 22:40:55 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Feb 09 22:40:55 primo volumio[3119]: info: Received Get System Info Feb 09 22:40:55 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Feb 09 22:40:55 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Feb 09 22:40:55 primo volumio[3119]: info: Discovery: Getting this device information Feb 09 22:40:55 primo volumio[3119]: info: CoreCommandRouter::volumioGetState Feb 09 22:40:55 primo volumio[3119]: info: CorePlayQueue::getTrack 0 Feb 09 22:40:55 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 09 22:40:55 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Feb 09 22:40:55 primo volumio[3119]: info: Received Get System Info Feb 09 22:40:55 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Feb 09 22:40:55 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Feb 09 22:40:55 primo volumio[3119]: info: Discovery: Getting this device information Feb 09 22:40:55 primo volumio[3119]: info: CoreCommandRouter::volumioGetState Feb 09 22:40:55 primo volumio[3119]: info: CorePlayQueue::getTrack 0 Feb 09 22:40:55 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 09 22:41:03 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Feb 09 22:41:05 primo volumio5-onboarding[4558]: failed to bootstrap state: failed to get music providers: could not get available plugins: could not get available plugins: context deadline exceeded Feb 09 22:41:05 primo systemd[1]: volumio5-onboarding.service: Main process exited, code=exited, status=1/FAILURE Feb 09 22:41:05 primo systemd[1]: volumio5-onboarding.service: Failed with result 'exit-code'. Feb 09 22:41:05 primo systemd[1]: volumio5-onboarding.service: Service RestartSec=100ms expired, scheduling restart. Feb 09 22:41:05 primo systemd[1]: volumio5-onboarding.service: Scheduled restart job, restart counter is at 8. Feb 09 22:41:05 primo systemd[1]: Stopped Volumio5 Onboarding Server. Feb 09 22:41:05 primo systemd[1]: Started Volumio5 Onboarding Server. Feb 09 22:41:05 primo volumio5-onboarding[4690]: time=2026-02-09T22:41:05.265+03:00 level=INFO msg="running volumio5-device-gateway" version=5bca5789+CHANGES buildDate=2025-12-11T14:07:23Z Feb 09 22:41:05 primo volumio[3119]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 7 Feb 09 22:41:05 primo volumio[3119]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 7 Feb 09 22:41:05 primo volumio5-onboarding[4690]: time=2026-02-09T22:41:05.315+03:00 level=INFO msg="listening for BLE messages" address=B8:2D:28:29:82:8D%00 Feb 09 22:41:05 primo volumio5-onboarding[4690]: time=2026-02-09T22:41:05.316+03:00 level=INFO msg="listening for WebSocket messages" address=[::]:7331 Feb 09 22:41:05 primo volumio[3119]: info: Received Get System Info Feb 09 22:41:05 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Feb 09 22:41:05 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Feb 09 22:41:05 primo volumio[3119]: info: Discovery: Getting this device information Feb 09 22:41:05 primo volumio[3119]: info: CoreCommandRouter::volumioGetState Feb 09 22:41:05 primo volumio[3119]: info: CorePlayQueue::getTrack 0 Feb 09 22:41:05 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 09 22:41:05 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Feb 09 22:41:05 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Feb 09 22:41:05 primo volumio5-onboarding[4690]: time=2026-02-09T22:41:05.333+03:00 level=INFO msg="BLE descriptor updated" deviceId=5caac58d64be6db5186fdaf1deb5d9a3 deviceName=Primo deviceModel=0x1c27ca0 Feb 09 22:41:05 primo volumio5-onboarding[4690]: time=2026-02-09T22:41:05.333+03:00 level=INFO msg="mDNS descriptor updated" deviceId=5caac58d64be6db5186fdaf1deb5d9a3 deviceName=Primo deviceModel=0x1c27ca0 Feb 09 22:41:05 primo volumio5-onboarding[4690]: time=2026-02-09T22:41:05.352+03:00 level=INFO msg="bootstrapping state" hasInternet=true Feb 09 22:41:05 primo volumio[3119]: info: Received Get System Info Feb 09 22:41:05 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Feb 09 22:41:05 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Feb 09 22:41:05 primo volumio[3119]: info: Discovery: Getting this device information Feb 09 22:41:05 primo volumio[3119]: info: CoreCommandRouter::volumioGetState Feb 09 22:41:05 primo volumio[3119]: info: CorePlayQueue::getTrack 0 Feb 09 22:41:05 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 09 22:41:05 primo volumio-remote-updater[2837]: No test mode Feb 09 22:41:05 primo volumio-remote-updater[2837]: No alpha test mode Feb 09 22:41:05 primo volumio[3119]: info: Update Ready: {"changeLogLink":"","description":"You're already on the latest version","title":"No Updates Available","updateavailable":false} Feb 09 22:41:05 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache Feb 09 22:41:05 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Feb 09 22:41:05 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Feb 09 22:41:05 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Feb 09 22:41:06 primo volumio[3119]: info: CoreCommandRouter::volumioGetQueue Feb 09 22:41:06 primo volumio[3119]: info: CoreStateMachine::getQueue Feb 09 22:41:06 primo volumio[3119]: info: CorePlayQueue::getQueue Feb 09 22:41:06 primo volumio[3119]: info: Executing endpoint metavolumio Feb 09 22:41:06 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Feb 09 22:41:06 primo volumio[3119]: info: Executing endpoint metavolumio Feb 09 22:41:06 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Feb 09 22:41:08 primo volumio[3119]: info: Preload queue cleared Feb 09 22:41:08 primo volumio[3119]: info: CoreCommandRouter::volumioReplaceandPlayItems Feb 09 22:41:08 primo volumio[3119]: info: CoreStateMachine::ClearQueue Feb 09 22:41:08 primo volumio[3119]: info: CoreStateMachine::stop Feb 09 22:41:08 primo volumio[3119]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 09 22:41:08 primo volumio[3119]: info: CorePlayQueue::clearPlayQueue Feb 09 22:41:08 primo volumio[3119]: info: CorePlayQueue::saveQueue Feb 09 22:41:08 primo volumio[3119]: info: CoreCommandRouter::volumioPushQueue Feb 09 22:41:08 primo volumio[3119]: info: CoreStateMachine::addQueueItems Feb 09 22:41:08 primo volumio[3119]: info: CorePlayQueue::addQueueItems Feb 09 22:41:08 primo volumio[3119]: info: Preload queue cleared Feb 09 22:41:08 primo volumio[3119]: info: Adding Item to queue: qobuz://album/yzft6jaodl4nc Feb 09 22:41:08 primo volumio[3119]: info: Using cached record of: qobuz://album/yzft6jaodl4nc Feb 09 22:41:08 primo volumio[3119]: info: CoreCommandRouter::volumioPushQueue Feb 09 22:41:08 primo volumio[3119]: info: CorePlayQueue::saveQueue Feb 09 22:41:08 primo volumio[3119]: info: CoreStateMachine::updateTrackBlock Feb 09 22:41:08 primo volumio[3119]: info: CorePlayQueue::getTrackBlock Feb 09 22:41:08 primo volumio[3119]: info: CoreCommandRouter::volumioPlay Feb 09 22:41:08 primo volumio[3119]: info: CoreStateMachine::play index 0 Feb 09 22:41:08 primo volumio[3119]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 09 22:41:08 primo volumio[3119]: info: CoreStateMachine::stop Feb 09 22:41:08 primo volumio[3119]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 09 22:41:08 primo volumio[3119]: info: CoreStateMachine::play index undefined Feb 09 22:41:08 primo volumio[3119]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 09 22:41:08 primo volumio[3119]: info: CorePlayQueue::getTrack 0 Feb 09 22:41:08 primo volumio[3119]: info: CoreStateMachine::startPlaybackTimer Feb 09 22:41:08 primo volumio[3119]: info: CorePlayQueue::getTrack 0 Feb 09 22:41:08 primo volumio[3119]: info: CoreCommandRouter::volumioGetVisibleSources Feb 09 22:41:08 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 09 22:41:08 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Feb 09 22:41:08 primo volumio[3119]: info: [1770666068424] ControllerQobuz::clearAddPlayTrack Feb 09 22:41:08 primo volumio[3119]: verbose: ControllerMpd::sendMpdCommand stop Feb 09 22:41:11 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Feb 09 22:41:11 primo volumio[3119]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Feb 09 22:41:11 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Feb 09 22:41:11 primo volumio[3119]: info: Received Get System Version Feb 09 22:41:11 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Feb 09 22:41:11 primo volumio[3119]: info: Received Get System Info Feb 09 22:41:11 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Feb 09 22:41:11 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Feb 09 22:41:11 primo volumio[3119]: info: Discovery: Getting this device information Feb 09 22:41:11 primo volumio[3119]: info: CoreCommandRouter::volumioGetState Feb 09 22:41:11 primo volumio[3119]: info: CorePlayQueue::getTrack 0 Feb 09 22:41:11 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 09 22:41:16 primo volumio[3119]: info: CoreCommandRouter::getUIConfigOnPlugin Feb 09 22:41:16 primo volumio[3119]: xcb_connection_has_error() returned true Feb 09 22:41:16 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions Feb 09 22:41:16 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 09 22:41:16 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Feb 09 22:41:16 primo volumio[3119]: xcb_connection_has_error() returned true Feb 09 22:41:16 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 09 22:41:16 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 09 22:41:16 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 09 22:41:16 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 09 22:41:16 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 09 22:41:16 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 09 22:41:16 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 09 22:41:16 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: mpd , getPlaybackMode Feb 09 22:41:16 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus Feb 09 22:41:16 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: raat , getAdditionalUiSection Feb 09 22:41:16 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: inputs , getAdditionalUiSection Feb 09 22:41:16 primo volumio[3119]: error: Cannot download Available plugins list: Error: ESOCKETTIMEDOUT Feb 09 22:41:16 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 22:41:16 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 22:41:35 primo volumio5-onboarding[4690]: failed to bootstrap state: failed to get music providers: could not get available plugins: could not get available plugins: context deadline exceeded Feb 09 22:41:35 primo systemd[1]: volumio5-onboarding.service: Main process exited, code=exited, status=1/FAILURE Feb 09 22:41:35 primo systemd[1]: volumio5-onboarding.service: Failed with result 'exit-code'. Feb 09 22:41:35 primo systemd[1]: volumio5-onboarding.service: Service RestartSec=100ms expired, scheduling restart. Feb 09 22:41:35 primo systemd[1]: volumio5-onboarding.service: Scheduled restart job, restart counter is at 9. Feb 09 22:41:35 primo systemd[1]: Stopped Volumio5 Onboarding Server. Feb 09 22:41:35 primo systemd[1]: Started Volumio5 Onboarding Server. Feb 09 22:41:35 primo volumio5-onboarding[4763]: time=2026-02-09T22:41:35.521+03:00 level=INFO msg="running volumio5-device-gateway" version=5bca5789+CHANGES buildDate=2025-12-11T14:07:23Z Feb 09 22:41:35 primo volumio[3119]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 7 Feb 09 22:41:35 primo volumio[3119]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 7 Feb 09 22:41:35 primo volumio5-onboarding[4763]: time=2026-02-09T22:41:35.573+03:00 level=INFO msg="listening for BLE messages" address=B8:2D:28:29:82:8D%00 Feb 09 22:41:35 primo volumio5-onboarding[4763]: time=2026-02-09T22:41:35.574+03:00 level=INFO msg="listening for WebSocket messages" address=[::]:7331 Feb 09 22:41:35 primo volumio[3119]: info: Received Get System Info Feb 09 22:41:35 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Feb 09 22:41:35 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Feb 09 22:41:35 primo volumio[3119]: info: Discovery: Getting this device information Feb 09 22:41:35 primo volumio[3119]: info: CoreCommandRouter::volumioGetState Feb 09 22:41:35 primo volumio[3119]: info: CorePlayQueue::getTrack 0 Feb 09 22:41:35 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 09 22:41:35 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Feb 09 22:41:35 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Feb 09 22:41:35 primo volumio5-onboarding[4763]: time=2026-02-09T22:41:35.589+03:00 level=INFO msg="BLE descriptor updated" deviceId=5caac58d64be6db5186fdaf1deb5d9a3 deviceName=Primo deviceModel=0x1d90840 Feb 09 22:41:35 primo volumio5-onboarding[4763]: time=2026-02-09T22:41:35.590+03:00 level=INFO msg="mDNS descriptor updated" deviceId=5caac58d64be6db5186fdaf1deb5d9a3 deviceName=Primo deviceModel=0x1d90840 Feb 09 22:41:35 primo volumio5-onboarding[4763]: time=2026-02-09T22:41:35.608+03:00 level=INFO msg="bootstrapping state" hasInternet=true Feb 09 22:41:35 primo volumio[3119]: info: Received Get System Info Feb 09 22:41:35 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Feb 09 22:41:35 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Feb 09 22:41:35 primo volumio[3119]: info: Discovery: Getting this device information Feb 09 22:41:35 primo volumio[3119]: info: CoreCommandRouter::volumioGetState Feb 09 22:41:35 primo volumio[3119]: info: CorePlayQueue::getTrack 0 Feb 09 22:41:35 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 09 22:41:35 primo volumio-remote-updater[2837]: No test mode Feb 09 22:41:35 primo volumio-remote-updater[2837]: No alpha test mode Feb 09 22:41:35 primo volumio[3119]: info: Update Ready: {"changeLogLink":"","description":"You're already on the latest version","title":"No Updates Available","updateavailable":false} Feb 09 22:41:35 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache Feb 09 22:41:35 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Feb 09 22:41:35 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Feb 09 22:41:35 primo volumio[3119]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Feb 09 22:41:36 primo volumio[3119]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 09 22:41:36 primo volumio[3119]: Error: connect ETIMEDOUT 23.73.2.88:443 Feb 09 22:41:36 primo volumio[3119]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) { Feb 09 22:41:36 primo volumio[3119]: errno: -110, Feb 09 22:41:36 primo volumio[3119]: code: 'ETIMEDOUT', Feb 09 22:41:36 primo volumio[3119]: syscall: 'connect', Feb 09 22:41:36 primo volumio[3119]: address: '23.73.2.88', Feb 09 22:41:36 primo volumio[3119]: port: 443 Feb 09 22:41:36 primo volumio[3119]: } Feb 09 22:41:36 primo volumio[3119]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 09 22:41:37 primo sudo[4836]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2026-02-09 22:40 Feb 09 22:41:37 primo sudo[4836]: 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="primo2rev2" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Thu 11 Dec 2025 07:52:21 PM CET" VOLUMIO_VERSION="3.886" VOLUMIO_HARDWARE="mp1" VOLUMIO_DEVICENAME="Volumio MP1" VOLUMIO_VENDOR_MODEL="Volumio Primo" VOLUMIO_VENDOR="Volumio" VOLUMIO_MODEL="Primo" VOLUMIO_HASH="060c5b31331b90c840ee52059a8e3db0"