Aug 26 17:27:02 volumio volumio-remote-updater[808]: [2026-08-26 17:27:02] [connect] Successful connection Aug 26 17:27:05 volumio volumio5-onboarding[2302]: failed to create app: failed to initialize host: failed to create socket connection: could not connect to socket.io server: read tcp 127.0.0.1:37934->127.0.0.1:3000: i/o timeout Aug 26 17:27:05 volumio systemd[1]: volumio5-onboarding.service: Main process exited, code=exited, status=1/FAILURE Aug 26 17:27:05 volumio systemd[1]: volumio5-onboarding.service: Failed with result 'exit-code'. Aug 26 17:27:06 volumio systemd[1]: volumio5-onboarding.service: Scheduled restart job, restart counter is at 5. Aug 26 17:27:06 volumio systemd[1]: Stopped volumio5-onboarding.service - Volumio5 Onboarding Server. Aug 26 17:27:06 volumio systemd[1]: Started volumio5-onboarding.service - Volumio5 Onboarding Server. Aug 26 17:27:06 volumio volumio5-onboarding[2322]: time=2026-08-26T17:27:06.425+03:00 level=INFO msg="running volumio5-device-gateway" version=6370e0a8+CHANGES buildDate=2026-03-06T16:29:42Z Aug 26 17:27:15 volumio dhcpcd[921]: eth0: carrier lost Aug 26 17:27:15 volumio kernel: bcmgenet fd580000.ethernet eth0: Link is Down Aug 26 17:27:15 volumio avahi-daemon[780]: Withdrawing address record for 192.168.62.25 on eth0. Aug 26 17:27:15 volumio avahi-daemon[780]: Leaving mDNS multicast group on interface eth0.IPv4 with address 192.168.62.25. Aug 26 17:27:15 volumio avahi-daemon[780]: Interface eth0.IPv4 no longer relevant for mDNS. Aug 26 17:27:15 volumio dhcpcd[921]: eth0: deleting route to 192.168.62.0/24 Aug 26 17:27:15 volumio dhcpcd[921]: eth0: deleting default route via 192.168.62.1 Aug 26 17:27:15 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Aug 26 17:27:15 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Aug 26 17:27:15 volumio systemd[1]: welcome.service: Deactivated successfully. Aug 26 17:27:15 volumio systemd[1]: Stopped welcome.service - Show a welcome message on console. Aug 26 17:27:15 volumio systemd[1]: Stopping welcome.service - Show a welcome message on console... Aug 26 17:27:15 volumio systemd[1]: Starting welcome.service - Show a welcome message on console... Aug 26 17:27:15 volumio welcome[2374]: Resolved ip:[0] Aug 26 17:27:15 volumio systemd[1]: Finished welcome.service - Show a welcome message on console. Aug 26 17:27:15 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Aug 26 17:27:15 volumio ifplugd(eth0)[1083]: Link beat lost. Aug 26 17:27:16 volumio volumio5-onboarding[2322]: failed to create app: failed to initialize host: failed to create socket connection: could not connect to socket.io server: read tcp 127.0.0.1:59836->127.0.0.1:3000: i/o timeout Aug 26 17:27:16 volumio systemd[1]: volumio5-onboarding.service: Main process exited, code=exited, status=1/FAILURE Aug 26 17:27:16 volumio systemd[1]: volumio5-onboarding.service: Failed with result 'exit-code'. Aug 26 17:27:16 volumio systemd[1]: volumio5-onboarding.service: Scheduled restart job, restart counter is at 6. Aug 26 17:27:16 volumio systemd[1]: Stopped volumio5-onboarding.service - Volumio5 Onboarding Server. Aug 26 17:27:16 volumio systemd[1]: Started volumio5-onboarding.service - Volumio5 Onboarding Server. Aug 26 17:27:16 volumio ntpd[1060]: IO: Deleting interface #3 eth0, 192.168.62.25#123, interface stats: received=163, sent=163, dropped=0, active_time=178 secs Aug 26 17:27:16 volumio ntpd[1060]: PROTO: 162.159.200.123 unlink local addr 192.168.62.25 -> Aug 26 17:27:16 volumio ntpd[1060]: PROTO: 162.159.200.1 unlink local addr 192.168.62.25 -> Aug 26 17:27:16 volumio ntpd[1060]: PROTO: 195.85.215.8 unlink local addr 192.168.62.25 -> Aug 26 17:27:16 volumio ntpd[1060]: PROTO: 193.238.174.38 unlink local addr 192.168.62.25 -> Aug 26 17:27:16 volumio ntpd[1060]: PROTO: 77.236.182.128 unlink local addr 192.168.62.25 -> Aug 26 17:27:16 volumio ntpd[1060]: PROTO: 108.165.233.229 unlink local addr 192.168.62.25 -> Aug 26 17:27:16 volumio ntpd[1060]: PROTO: 82.118.235.227 unlink local addr 192.168.62.25 -> Aug 26 17:27:16 volumio ntpd[1060]: PROTO: 193.19.172.5 unlink local addr 192.168.62.25 -> Aug 26 17:27:16 volumio ntpd[1060]: PROTO: 78.159.131.45 unlink local addr 192.168.62.25 -> Aug 26 17:27:16 volumio ntpd[1060]: PROTO: 185.117.82.71 unlink local addr 192.168.62.25 -> Aug 26 17:27:16 volumio ntpd[1060]: PROTO: 78.83.137.244 unlink local addr 192.168.62.25 -> Aug 26 17:27:16 volumio ntpd[1060]: PROTO: 195.85.215.215 unlink local addr 192.168.62.25 -> Aug 26 17:27:16 volumio ntpd[1060]: PROTO: 94.72.140.160 unlink local addr 192.168.62.25 -> Aug 26 17:27:16 volumio ntpd[1060]: PROTO: 185.117.82.66 unlink local addr 192.168.62.25 -> Aug 26 17:27:16 volumio ntpd[1060]: PROTO: 87.120.244.14 unlink local addr 192.168.62.25 -> Aug 26 17:27:16 volumio ntpd[1060]: PROTO: 213.91.190.205 unlink local addr 192.168.62.25 -> Aug 26 17:27:16 volumio volumio5-onboarding[2386]: time=2026-08-26T17:27:16.689+03:00 level=INFO msg="running volumio5-device-gateway" version=6370e0a8+CHANGES buildDate=2026-03-06T16:29:42Z Aug 26 17:27:16 volumio volumio[1200]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Aug 26 17:27:16 volumio volumio[1200]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Aug 26 17:27:16 volumio volumio[1200]: info: Streaming services startup Aug 26 17:27:16 volumio volumio[1200]: info: Starting Streaming Daemon Aug 26 17:27:17 volumio volumio-remote-updater[808]: [2026-08-26 17:27:17] [connect] Successful connection Aug 26 17:27:17 volumio sudo[2393]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Aug 26 17:27:17 volumio volumio[1200]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Aug 26 17:27:17 volumio sudo[2393]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 26 17:27:18 volumio sudo[2393]: pam_unix(sudo:session): session closed for user root Aug 26 17:27:18 volumio volumio[1200]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Mozilla/5.0 (X11; CrOS x86_64 14541.0.0) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/146.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 13 Aug 26 17:27:18 volumio volumio[1200]: info: AutoStart - Check #8/60 - VOLUMIO_SYSTEM_STATUS = starting Aug 26 17:27:18 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 17:27:18 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 17:27:18 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam Aug 26 17:27:18 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam Aug 26 17:27:18 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Aug 26 17:27:18 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Aug 26 17:27:18 volumio volumio[1200]: info: CoreCommandRouter::volumioGetBrowseSources Aug 26 17:27:18 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 26 17:27:19 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Aug 26 17:27:20 volumio volumio[1200]: error: MyVolumio got a network error: A network error (such as timeout, interrupted connection or unreachable host) has occurred. Aug 26 17:27:20 volumio volumio[1200]: info: Retrying Login Due to Network Error Aug 26 17:27:20 volumio dhcpcd[921]: eth0: carrier acquired Aug 26 17:27:20 volumio kernel: bcmgenet fd580000.ethernet eth0: Link is Up - 1Gbps/Full - flow control rx/tx Aug 26 17:27:20 volumio dhcpcd[921]: eth0: IAID 01:0e:93:3d Aug 26 17:27:20 volumio dhcpcd[921]: eth0: probing address 192.168.62.25/24 Aug 26 17:27:21 volumio ifplugd(eth0)[1083]: Link beat detected. Aug 26 17:27:21 volumio dhcpcd[921]: eth0: soliciting an IPv6 router Aug 26 17:27:21 volumio volumio[1200]: error: Cannot start Volumio Streaming Daemon Aug 26 17:27:21 volumio volumio[1200]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Aug 26 17:27:21 volumio volumio[1200]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Aug 26 17:27:24 volumio volumio[1200]: warn: [ROTARYENCODER2] Socket disconnected: transport error Aug 26 17:27:25 volumio upmpdcli[2421]: writing RSA key Aug 26 17:27:25 volumio volumio[1200]: info: Volumio Network Manager: Network status updated: 0 Aug 26 17:27:26 volumio volumio[1200]: info: AutoStart - Check #9/60 - VOLUMIO_SYSTEM_STATUS = starting Aug 26 17:27:26 volumio avahi-daemon[780]: Joining mDNS multicast group on interface eth0.IPv4 with address 192.168.62.25. Aug 26 17:27:26 volumio dhcpcd[921]: eth0: using static address 192.168.62.25/24 Aug 26 17:27:26 volumio dhcpcd[921]: eth0: adding route to 192.168.62.0/24 Aug 26 17:27:26 volumio dhcpcd[921]: eth0: adding default route via 192.168.62.1 Aug 26 17:27:26 volumio avahi-daemon[780]: New relevant interface eth0.IPv4 for mDNS. Aug 26 17:27:26 volumio avahi-daemon[780]: Registering new address record for 192.168.62.25 on eth0.IPv4. Aug 26 17:27:26 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Aug 26 17:27:26 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Aug 26 17:27:26 volumio systemd[1]: welcome.service: Deactivated successfully. Aug 26 17:27:26 volumio systemd[1]: Stopped welcome.service - Show a welcome message on console. Aug 26 17:27:26 volumio systemd[1]: Stopping welcome.service - Show a welcome message on console... Aug 26 17:27:26 volumio systemd[1]: Starting welcome.service - Show a welcome message on console... Aug 26 17:27:26 volumio welcome[2435]: Resolved ip:[1] 192.168.62.25 Aug 26 17:27:26 volumio systemd[1]: Finished welcome.service - Show a welcome message on console. Aug 26 17:27:26 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Aug 26 17:27:26 volumio volumio5-onboarding[2386]: failed to create app: failed to initialize host: failed to create socket connection: could not connect to socket.io server: read tcp 127.0.0.1:46260->127.0.0.1:3000: i/o timeout Aug 26 17:27:26 volumio systemd[1]: volumio5-onboarding.service: Main process exited, code=exited, status=1/FAILURE Aug 26 17:27:26 volumio systemd[1]: volumio5-onboarding.service: Failed with result 'exit-code'. Aug 26 17:27:26 volumio systemd[1]: volumio5-onboarding.service: Scheduled restart job, restart counter is at 7. Aug 26 17:27:26 volumio systemd[1]: Stopped volumio5-onboarding.service - Volumio5 Onboarding Server. Aug 26 17:27:26 volumio systemd[1]: Started volumio5-onboarding.service - Volumio5 Onboarding Server. Aug 26 17:27:26 volumio volumio5-onboarding[2448]: time=2026-08-26T17:27:26.961+03:00 level=INFO msg="running volumio5-device-gateway" version=6370e0a8+CHANGES buildDate=2026-03-06T16:29:42Z Aug 26 17:27:27 volumio volumio[1200]: info: CoreCommandRouter::volumioGetState Aug 26 17:27:27 volumio volumio[1200]: info: CorePlayQueue::getTrack 0 Aug 26 17:27:27 volumio volumio[1200]: info: Discovery: A device disappeared from network Aug 26 17:27:27 volumio ntpd[1060]: IO: Listen normally on 4 eth0 192.168.62.25:123 Aug 26 17:27:27 volumio ntpd[1060]: IO: new interface(s) found: waking up resolver Aug 26 17:27:28 volumio volumio[1200]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Mozilla/5.0 (X11; CrOS x86_64 14541.0.0) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/146.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 12 Aug 26 17:27:28 volumio volumio[1200]: info: Discovery: adding 4b395812-8711-4d9f-95ab-5010e4102a2a Aug 26 17:27:28 volumio volumio[1200]: info: Discovery: Found device Volumio Aug 26 17:27:28 volumio volumio[1200]: info: CoreCommandRouter::volumioGetState Aug 26 17:27:28 volumio volumio[1200]: info: CorePlayQueue::getTrack 0 Aug 26 17:27:28 volumio volumio[1200]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Mozilla/5.0 (X11; CrOS x86_64 14541.0.0) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/146.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 13 Aug 26 17:27:29 volumio volumio[1200]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 14 Aug 26 17:27:29 volumio volumio[1200]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 15 Aug 26 17:27:29 volumio volumio[1200]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 16 Aug 26 17:27:29 volumio volumio[1200]: info: [ROTARYENCODER2] Socket reconnected after 1 attempts Aug 26 17:27:29 volumio volumio[1200]: 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: 17 Aug 26 17:27:29 volumio volumio[1200]: 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: 17 Aug 26 17:27:29 volumio volumio[1200]: info: Received Get System Info Aug 26 17:27:29 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 26 17:27:29 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 26 17:27:29 volumio volumio[1200]: info: Discovery: Getting this device information Aug 26 17:27:29 volumio volumio[1200]: info: CoreCommandRouter::volumioGetState Aug 26 17:27:29 volumio volumio[1200]: info: CorePlayQueue::getTrack 0 Aug 26 17:27:29 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 26 17:27:29 volumio volumio5-onboarding[2448]: time=2026-08-26T17:27:29.682+03:00 level=INFO msg="system info for cb42ef6fe90861a5c5c68087d72bdd2b" deviceName=Volumio deviceVariant=volumio deviceModel= softwareVersion=4.119 Aug 26 17:27:29 volumio volumio5-onboarding[2448]: time=2026-08-26T17:27:29.687+03:00 level=INFO msg="bootstrapping state" hasInternet=true Aug 26 17:27:29 volumio volumio[1200]: info: Received Get System Info Aug 26 17:27:29 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 26 17:27:29 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 26 17:27:29 volumio volumio[1200]: info: Discovery: Getting this device information Aug 26 17:27:29 volumio volumio[1200]: info: CoreCommandRouter::volumioGetState Aug 26 17:27:29 volumio volumio[1200]: info: CorePlayQueue::getTrack 0 Aug 26 17:27:29 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 26 17:27:30 volumio volumio[1200]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 18 Aug 26 17:27:30 volumio volumio[1200]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 19 Aug 26 17:27:30 volumio volumio[1200]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Mozilla/5.0 (X11; CrOS x86_64 14541.0.0) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/146.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 20 Aug 26 17:27:30 volumio volumio[1200]: info: CoreCommandRouter::volumioToggle Aug 26 17:27:30 volumio volumio[1200]: info: CorePlayQueue::getTrack 0 Aug 26 17:27:30 volumio volumio[1200]: info: CoreStateMachine::play index undefined Aug 26 17:27:30 volumio volumio[1200]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 26 17:27:30 volumio volumio[1200]: info: CorePlayQueue::getTrack 0 Aug 26 17:27:30 volumio volumio[1200]: info: CoreStateMachine::startPlaybackTimer Aug 26 17:27:30 volumio volumio[1200]: info: CorePlayQueue::getTrack 0 Aug 26 17:27:30 volumio volumio[1200]: info: [1787754450430] ControllerWebradio::clearAddPlayTrack Aug 26 17:27:30 volumio volumio[1200]: verbose: ControllerMpd::sendMpdCommand stop Aug 26 17:27:30 volumio volumio[1200]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Aug 26 17:27:30 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Aug 26 17:27:30 volumio volumio[1200]: info: Listing playlists Aug 26 17:27:30 volumio volumio[1200]: info: CoreCommandRouter::volumioGetQueue Aug 26 17:27:30 volumio volumio[1200]: info: CoreStateMachine::getQueue Aug 26 17:27:30 volumio volumio[1200]: info: CorePlayQueue::getQueue Aug 26 17:27:30 volumio volumio[1200]: info: CoreCommandRouter::volumioGetVisibleSources Aug 26 17:27:30 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 26 17:27:30 volumio volumio[1200]: info: CoreCommandRouter::volumioGetState Aug 26 17:27:30 volumio volumio[1200]: info: CorePlayQueue::getTrack 0 Aug 26 17:27:30 volumio volumio[1200]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Aug 26 17:27:30 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Aug 26 17:27:30 volumio volumio[1200]: info: Listing playlists Aug 26 17:27:30 volumio volumio[1200]: info: CoreCommandRouter::volumioGetQueue Aug 26 17:27:30 volumio volumio[1200]: info: CoreStateMachine::getQueue Aug 26 17:27:30 volumio volumio[1200]: info: CorePlayQueue::getQueue Aug 26 17:27:30 volumio volumio[1200]: info: CoreCommandRouter::volumioGetVisibleSources Aug 26 17:27:30 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 26 17:27:30 volumio volumio[1200]: info: CoreCommandRouter::volumioGetState Aug 26 17:27:30 volumio volumio[1200]: info: CorePlayQueue::getTrack 0 Aug 26 17:27:30 volumio volumio[1200]: info: sendMpdCommand stop took 263 milliseconds Aug 26 17:27:30 volumio volumio[1200]: verbose: ControllerMpd::sendMpdCommand clear Aug 26 17:27:30 volumio volumio[1200]: info: MyVolumio login type: Token Aug 26 17:27:30 volumio volumio[1200]: info: Aug 26 17:27:30 volumio volumio[1200]: ---------------------------- MPD announces system playlist update Aug 26 17:27:31 volumio volumio[1200]: info: Ignoring MPD Status Update Aug 26 17:27:31 volumio volumio[1200]: info: sendMpdCommand clear took 254 milliseconds Aug 26 17:27:31 volumio volumio[1200]: verbose: ControllerMpd::sendMpdCommand load "https://stream.vanillaradio.com:8012/stream" Aug 26 17:27:31 volumio volumio[1200]: info: Aug 26 17:27:31 volumio volumio[1200]: ---------------------------- MPD announces system playlist update Aug 26 17:27:31 volumio volumio[1200]: info: Ignoring MPD Status Update Aug 26 17:27:31 volumio volumio[1200]: info: Aug 26 17:27:31 volumio volumio[1200]: ---------------------------- MPD announces system playlist update Aug 26 17:27:31 volumio volumio[1200]: info: Ignoring MPD Status Update Aug 26 17:27:31 volumio volumio[1200]: error: updateQueue error: null Aug 26 17:27:31 volumio volumio[1200]: info: ------------------------------ 202ms Aug 26 17:27:31 volumio volumio[1200]: info: AutoStart - Check #10/60 - VOLUMIO_SYSTEM_STATUS = starting Aug 26 17:27:31 volumio volumio[1200]: error: MyVolumio Custom Token format not valid, refreshing it Aug 26 17:27:32 volumio volumio[1200]: info: [ROTARYENCODER2] Socket connected to Volumio Aug 26 17:27:32 volumio volumio[1200]: error: updateQueue error: null Aug 26 17:27:32 volumio volumio[1200]: error: updateQueue error: null Aug 26 17:27:32 volumio volumio[1200]: verbose: ControllerMpd::sendMpdCommand add "https://stream.vanillaradio.com:8012/stream" Aug 26 17:27:32 volumio volumio[1200]: info: ------------------------------ 1283ms Aug 26 17:27:32 volumio volumio[1200]: info: ------------------------------ 1282ms Aug 26 17:27:32 volumio volumio-remote-updater[808]: [2026-08-26 17:27:32] [connect] Successful connection Aug 26 17:27:32 volumio volumio[1200]: info: Aug 26 17:27:32 volumio volumio[1200]: ---------------------------- MPD announces system playlist update Aug 26 17:27:32 volumio volumio[1200]: info: Ignoring MPD Status Update Aug 26 17:27:32 volumio volumio[1200]: info: sendMpdCommand add "https://stream.vanillaradio.com:8012/stream" took 168 milliseconds Aug 26 17:27:32 volumio volumio[1200]: info: CoreStateMachine::setConsumeUpdateService mpd Aug 26 17:27:32 volumio volumio[1200]: verbose: ControllerMpd::sendMpdCommand play Aug 26 17:27:32 volumio volumio[1200]: info: Aug 26 17:27:32 volumio volumio[1200]: ---------------------------- MPD announces system playlist update Aug 26 17:27:32 volumio volumio[1200]: info: Ignoring MPD Status Update Aug 26 17:27:32 volumio volumio[1200]: info: Aug 26 17:27:32 volumio volumio[1200]: ---------------------------- MPD announces system playlist update Aug 26 17:27:32 volumio volumio[1200]: info: Ignoring MPD Status Update Aug 26 17:27:32 volumio volumio[1200]: info: ------------------------------ 317ms Aug 26 17:27:32 volumio volumio[1200]: info: sendMpdCommand play took 298 milliseconds Aug 26 17:27:32 volumio volumio[1200]: info: ------------------------------ 190ms Aug 26 17:27:32 volumio volumio[1200]: info: ------------------------------ 167ms Aug 26 17:27:33 volumio volumio[1200]: info: Aug 26 17:27:33 volumio volumio[1200]: ---------------------------- MPD announces state update: player Aug 26 17:27:33 volumio volumio[1200]: info: ControllerMpd::getState Aug 26 17:27:33 volumio volumio[1200]: verbose: ControllerMpd::sendMpdCommand status Aug 26 17:27:33 volumio volumio[1200]: info: Aug 26 17:27:33 volumio volumio[1200]: ---------------------------- MPD announces state update: player Aug 26 17:27:33 volumio volumio[1200]: info: ControllerMpd::getState Aug 26 17:27:33 volumio volumio[1200]: verbose: ControllerMpd::sendMpdCommand status Aug 26 17:27:33 volumio volumio[1200]: info: Aug 26 17:27:33 volumio volumio[1200]: ---------------------------- MPD announces state update: player Aug 26 17:27:33 volumio volumio[1200]: info: Aug 26 17:27:33 volumio volumio[1200]: ---------------------------- MPD announces system playlist update Aug 26 17:27:33 volumio volumio[1200]: info: Ignoring MPD Status Update Aug 26 17:27:33 volumio volumio[1200]: info: Aug 26 17:27:33 volumio volumio[1200]: ---------------------------- MPD announces state update: player Aug 26 17:27:33 volumio volumio[1200]: info: ControllerMpd::getState Aug 26 17:27:33 volumio volumio[1200]: verbose: ControllerMpd::sendMpdCommand status Aug 26 17:27:33 volumio volumio[1200]: info: sendMpdCommand status took 15 milliseconds Aug 26 17:27:33 volumio volumio[1200]: info: ControllerMpd::getState Aug 26 17:27:34 volumio volumio[1200]: verbose: ControllerMpd::sendMpdCommand status Aug 26 17:27:34 volumio volumio[1200]: info: sendMpdCommand status took 57 milliseconds Aug 26 17:27:34 volumio volumio[1200]: verbose: ControllerMpd::parseState Aug 26 17:27:34 volumio volumio[1200]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 26 17:27:34 volumio volumio[1200]: verbose: ControllerMpd::parseState Aug 26 17:27:34 volumio volumio[1200]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 26 17:27:34 volumio volumio[1200]: info: CoreCommandRouter::volumioGetState Aug 26 17:27:34 volumio volumio[1200]: info: Aug 26 17:27:34 volumio volumio[1200]: ---------------------------- MPD announces system playlist update Aug 26 17:27:34 volumio volumio[1200]: info: Ignoring MPD Status Update Aug 26 17:27:34 volumio volumio[1200]: info: Aug 26 17:27:34 volumio volumio[1200]: ---------------------------- MPD announces state update: player Aug 26 17:27:34 volumio volumio[1200]: info: ControllerMpd::getState Aug 26 17:27:34 volumio volumio[1200]: verbose: ControllerMpd::sendMpdCommand status Aug 26 17:27:34 volumio volumio[1200]: info: Aug 26 17:27:34 volumio volumio[1200]: ---------------------------- MPD announces system playlist update Aug 26 17:27:34 volumio volumio[1200]: info: Ignoring MPD Status Update Aug 26 17:27:34 volumio volumio[1200]: info: Aug 26 17:27:34 volumio volumio[1200]: ---------------------------- MPD announces state update: player Aug 26 17:27:34 volumio volumio[1200]: info: ControllerMpd::getState Aug 26 17:27:34 volumio volumio[1200]: verbose: ControllerMpd::sendMpdCommand status Aug 26 17:27:34 volumio volumio[1200]: info: sendMpdCommand status took 322 milliseconds Aug 26 17:27:34 volumio volumio[1200]: info: ------------------------------ 332ms Aug 26 17:27:34 volumio volumio[1200]: info: sendMpdCommand status took 275 milliseconds Aug 26 17:27:34 volumio volumio[1200]: info: sendMpdCommand playlistinfo took 274 milliseconds Aug 26 17:27:34 volumio volumio[1200]: info: sendMpdCommand playlistinfo took 274 milliseconds Aug 26 17:27:34 volumio volumio[1200]: info: ------------------------------ 84ms Aug 26 17:27:34 volumio volumio[1200]: info: sendMpdCommand status took 83 milliseconds Aug 26 17:27:34 volumio volumio[1200]: info: ------------------------------ 83ms Aug 26 17:27:34 volumio volumio[1200]: info: sendMpdCommand status took 82 milliseconds Aug 26 17:27:34 volumio volumio[1200]: verbose: ControllerMpd::parseState Aug 26 17:27:34 volumio volumio[1200]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 26 17:27:34 volumio volumio[1200]: verbose: ControllerMpd::parseState Aug 26 17:27:34 volumio volumio[1200]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 26 17:27:34 volumio volumio[1200]: verbose: ControllerMpd::parseTrackInfo Aug 26 17:27:34 volumio volumio[1200]: verbose: ControllerMpd::parseTrackInfo Aug 26 17:27:34 volumio volumio[1200]: verbose: ControllerMpd::parseState Aug 26 17:27:34 volumio volumio[1200]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 26 17:27:34 volumio volumio[1200]: verbose: ControllerMpd::parseState Aug 26 17:27:34 volumio volumio[1200]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 26 17:27:34 volumio volumio[1200]: info: ControllerMpd::pushState Aug 26 17:27:34 volumio volumio[1200]: info: CoreCommandRouter::servicePushState Aug 26 17:27:34 volumio volumio[1200]: info: CorePlayQueue::getTrack 0 Aug 26 17:27:34 volumio volumio[1200]: verbose: STATE SERVICE {"status":"play","position":0,"seek":1184,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"Tina Charles - I Love To Love (But My Baby Loves To Dance) (Dj Pantelis Remix)","artist":"Vanilla Radio Deep Flavors","album":null,"uri":"https://stream.vanillaradio.com:8012/stream","trackType":""} Aug 26 17:27:34 volumio volumio[1200]: verbose: CURRENT POSITION 0 Aug 26 17:27:34 volumio volumio[1200]: info: CoreStateMachine::syncState stateService play Aug 26 17:27:34 volumio volumio[1200]: info: CoreStateMachine::syncState currentStatus stop Aug 26 17:27:34 volumio volumio[1200]: info: ControllerMpd::pushState Aug 26 17:27:34 volumio volumio[1200]: info: CoreCommandRouter::servicePushState Aug 26 17:27:34 volumio volumio[1200]: info: CorePlayQueue::getTrack 0 Aug 26 17:27:34 volumio volumio[1200]: verbose: STATE SERVICE {"status":"play","position":0,"seek":1184,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"Tina Charles - I Love To Love (But My Baby Loves To Dance) (Dj Pantelis Remix)","artist":"Vanilla Radio Deep Flavors","album":null,"uri":"https://stream.vanillaradio.com:8012/stream","trackType":""} Aug 26 17:27:34 volumio volumio[1200]: verbose: CURRENT POSITION 0 Aug 26 17:27:34 volumio volumio[1200]: info: CoreStateMachine::syncState stateService play Aug 26 17:27:34 volumio volumio[1200]: info: CoreStateMachine::syncState currentStatus play Aug 26 17:27:34 volumio volumio[1200]: info: Received an update from plugin. extracting info from payload Aug 26 17:27:34 volumio volumio[1200]: info: CoreStateMachine::pushState Aug 26 17:27:34 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 26 17:27:34 volumio volumio[1200]: info: CoreCommandRouter::volumioPushState Aug 26 17:27:34 volumio volumio[1200]: info: CoreStateMachine::pushState Aug 26 17:27:34 volumio volumio[1200]: info: CoreCommandRouter::volumioPushState Aug 26 17:27:34 volumio volumio[1200]: info: ------------------------------ 606ms Aug 26 17:27:34 volumio volumio[1200]: info: ------------------------------ 661ms Aug 26 17:27:34 volumio volumio[1200]: info: sendMpdCommand playlistinfo took 600 milliseconds Aug 26 17:27:34 volumio volumio[1200]: info: sendMpdCommand playlistinfo took 604 milliseconds Aug 26 17:27:34 volumio volumio[1200]: info: sendMpdCommand playlistinfo took 607 milliseconds Aug 26 17:27:34 volumio volumio[1200]: info: sendMpdCommand playlistinfo took 615 milliseconds Aug 26 17:27:34 volumio volumio[1200]: verbose: ControllerMpd::parseTrackInfo Aug 26 17:27:34 volumio volumio[1200]: verbose: ControllerMpd::parseTrackInfo Aug 26 17:27:34 volumio volumio[1200]: verbose: ControllerMpd::parseTrackInfo Aug 26 17:27:34 volumio volumio[1200]: verbose: ControllerMpd::parseTrackInfo Aug 26 17:27:34 volumio volumio[1200]: info: ControllerMpd::pushState Aug 26 17:27:34 volumio volumio[1200]: info: CoreCommandRouter::servicePushState Aug 26 17:27:34 volumio volumio[1200]: info: CorePlayQueue::getTrack 0 Aug 26 17:27:34 volumio volumio[1200]: verbose: STATE SERVICE {"status":"play","position":0,"seek":1184,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"Tina Charles - I Love To Love (But My Baby Loves To Dance) (Dj Pantelis Remix)","artist":"Vanilla Radio Deep Flavors","album":null,"uri":"https://stream.vanillaradio.com:8012/stream","trackType":""} Aug 26 17:27:34 volumio volumio[1200]: verbose: CURRENT POSITION 0 Aug 26 17:27:34 volumio volumio[1200]: info: CoreStateMachine::syncState stateService play Aug 26 17:27:34 volumio volumio[1200]: info: CoreStateMachine::syncState currentStatus play Aug 26 17:27:34 volumio volumio[1200]: info: Received an update from plugin. extracting info from payload Aug 26 17:27:34 volumio volumio[1200]: info: CoreStateMachine::pushState Aug 26 17:27:34 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 26 17:27:34 volumio volumio[1200]: info: CoreCommandRouter::volumioPushState Aug 26 17:27:34 volumio volumio[1200]: info: CoreStateMachine::pushState Aug 26 17:27:34 volumio volumio[1200]: info: CoreCommandRouter::volumioPushState Aug 26 17:27:34 volumio volumio[1200]: info: ControllerMpd::pushState Aug 26 17:27:35 volumio volumio[1200]: info: CoreCommandRouter::servicePushState Aug 26 17:27:35 volumio volumio[1200]: info: CorePlayQueue::getTrack 0 Aug 26 17:27:35 volumio volumio[1200]: verbose: STATE SERVICE {"status":"play","position":0,"seek":1184,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"Tina Charles - I Love To Love (But My Baby Loves To Dance) (Dj Pantelis Remix)","artist":"Vanilla Radio Deep Flavors","album":null,"uri":"https://stream.vanillaradio.com:8012/stream","trackType":""} Aug 26 17:27:35 volumio volumio[1200]: verbose: CURRENT POSITION 0 Aug 26 17:27:35 volumio volumio[1200]: info: CoreStateMachine::syncState stateService play Aug 26 17:27:35 volumio volumio[1200]: info: CoreStateMachine::syncState currentStatus play Aug 26 17:27:35 volumio volumio[1200]: info: Received an update from plugin. extracting info from payload Aug 26 17:27:35 volumio volumio[1200]: info: CoreStateMachine::pushState Aug 26 17:27:35 volumio volumio[1200]: info: CoreCommandRouter::volumioPushState Aug 26 17:27:35 volumio volumio[1200]: info: CoreStateMachine::pushState Aug 26 17:27:35 volumio volumio[1200]: info: CoreCommandRouter::volumioPushState Aug 26 17:27:35 volumio volumio[1200]: info: ControllerMpd::pushState Aug 26 17:27:35 volumio volumio[1200]: info: CoreCommandRouter::servicePushState Aug 26 17:27:35 volumio volumio[1200]: info: CorePlayQueue::getTrack 0 Aug 26 17:27:35 volumio volumio[1200]: verbose: STATE SERVICE {"status":"play","position":0,"seek":1378,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"Tina Charles - I Love To Love (But My Baby Loves To Dance) (Dj Pantelis Remix)","artist":"Vanilla Radio Deep Flavors","album":null,"uri":"https://stream.vanillaradio.com:8012/stream","trackType":""} Aug 26 17:27:35 volumio volumio[1200]: verbose: CURRENT POSITION 0 Aug 26 17:27:35 volumio volumio[1200]: info: CoreStateMachine::syncState stateService play Aug 26 17:27:35 volumio volumio[1200]: info: CoreStateMachine::syncState currentStatus play Aug 26 17:27:35 volumio volumio[1200]: info: Received an update from plugin. extracting info from payload Aug 26 17:27:35 volumio volumio[1200]: info: CoreStateMachine::pushState Aug 26 17:27:35 volumio volumio[1200]: info: CoreCommandRouter::volumioPushState Aug 26 17:27:35 volumio volumio[1200]: info: CoreStateMachine::pushState Aug 26 17:27:35 volumio volumio[1200]: info: CoreCommandRouter::volumioPushState Aug 26 17:27:35 volumio volumio[1200]: info: ControllerMpd::pushState Aug 26 17:27:35 volumio volumio[1200]: info: CoreCommandRouter::servicePushState Aug 26 17:27:35 volumio volumio[1200]: info: CorePlayQueue::getTrack 0 Aug 26 17:27:35 volumio volumio[1200]: verbose: STATE SERVICE {"status":"play","position":0,"seek":1378,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"Tina Charles - I Love To Love (But My Baby Loves To Dance) (Dj Pantelis Remix)","artist":"Vanilla Radio Deep Flavors","album":null,"uri":"https://stream.vanillaradio.com:8012/stream","trackType":""} Aug 26 17:27:35 volumio volumio[1200]: verbose: CURRENT POSITION 0 Aug 26 17:27:35 volumio volumio[1200]: info: CoreStateMachine::syncState stateService play Aug 26 17:27:35 volumio volumio[1200]: info: CoreStateMachine::syncState currentStatus play Aug 26 17:27:35 volumio volumio[1200]: info: Received an update from plugin. extracting info from payload Aug 26 17:27:35 volumio volumio[1200]: info: CoreStateMachine::pushState Aug 26 17:27:35 volumio volumio[1200]: info: CoreCommandRouter::volumioPushState Aug 26 17:27:35 volumio volumio[1200]: info: CoreStateMachine::pushState Aug 26 17:27:35 volumio volumio[1200]: info: CoreCommandRouter::volumioPushState Aug 26 17:27:35 volumio volumio[1200]: info: ------------------------------ 1475ms Aug 26 17:27:35 volumio volumio[1200]: info: ------------------------------ 1474ms Aug 26 17:27:35 volumio volumio[1200]: info: ------------------------------ 1226ms Aug 26 17:27:35 volumio volumio[1200]: info: ------------------------------ 1225ms Aug 26 17:27:35 volumio volumio[1200]: info: MyVolumio login type: Token Aug 26 17:27:36 volumio volumio[1200]: SPOTIFY: RECEIVED VOLUMIO VOLUME 91 Aug 26 17:27:36 volumio volumio[1200]: SPOTIFY: SPOTIFY VOLUME undefined Aug 26 17:27:36 volumio volumio[1200]: SPOTIFY: VOLUMIO VOLUME 91 Aug 26 17:27:36 volumio volumio[1200]: info: Aligning Spotify Volume to Volumio Volume Aug 26 17:27:36 volumio volumio[1200]: info: CoreCommandRouter::volumioGetState Aug 26 17:27:36 volumio volumio[1200]: info: Setting Spotify Volume from Volumio: 91 Aug 26 17:27:36 volumio volumio[1200]: SPOTIFY: RECEIVED VOLUMIO VOLUME 91 Aug 26 17:27:36 volumio volumio[1200]: SPOTIFY: RECEIVED VOLUMIO VOLUME 91 Aug 26 17:27:36 volumio volumio-remote-updater[808]: [2026-08-26 17:27:36] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1787754452 101 Aug 26 17:27:36 volumio volumio[1200]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 3 Transport: websocket Total Clients: 20 Aug 26 17:27:36 volumio volumio[1200]: info: AutoStart - Check #11/60 - VOLUMIO_SYSTEM_STATUS = starting Aug 26 17:27:36 volumio volumio[1200]: info: Volumio Network Manager: Network status updated: 1 Aug 26 17:27:36 volumio volumio[1200]: info: CoreCommandRouter::volumioGetState Aug 26 17:27:36 volumio volumio[1200]: SPOTIFY: RECEIVED VOLUMIO VOLUME 91 Aug 26 17:27:36 volumio volumio[1200]: SPOTIFY: RECEIVED VOLUMIO VOLUME 91 Aug 26 17:27:36 volumio volumio[1200]: SPOTIFY: RECEIVED VOLUMIO VOLUME 91 Aug 26 17:27:36 volumio volumio[1200]: SPOTIFY: RECEIVED VOLUMIO VOLUME 91 Aug 26 17:27:36 volumio volumio[1200]: SPOTIFY: RECEIVED VOLUMIO VOLUME 91 Aug 26 17:27:36 volumio volumio[1200]: SPOTIFY: RECEIVED VOLUMIO VOLUME 91 Aug 26 17:27:36 volumio volumio[1200]: SPOTIFY: RECEIVED VOLUMIO VOLUME 91 Aug 26 17:27:36 volumio volumio[1200]: SPOTIFY: RECEIVED VOLUMIO VOLUME 91 Aug 26 17:27:37 volumio volumio[1200]: info: CoreCommandRouter::volumioGetState Aug 26 17:27:37 volumio volumio[1200]: SPOTIFY: SETTING SPOTIFY VOLUME 91 Aug 26 17:27:37 volumio volumio[1200]: info: Sending Spotify command with payload to local API: /player/volume Aug 26 17:27:37 volumio volumio[1200]: error: MyVolumio Plugin failed to authenticate in a timely fashion Aug 26 17:27:37 volumio volumio[1200]: info: Completed starting MyVolumio Plugin Aug 26 17:27:37 volumio volumio[1200]: [Metrics] CommandRouter: 190s 100.64ms Aug 26 17:27:37 volumio volumio[1200]: info: CoreCommandRouter::volumiosetStartupVolume Aug 26 17:27:37 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 17:27:37 volumio volumio[1200]: info: VolumeController:: Setting startup Volume 90 Aug 26 17:27:37 volumio volumio[1200]: info: VolumeController::SetAlsaVolume90 Aug 26 17:27:37 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 26 17:27:38 volumio volumio[1200]: info: CoreCommandRouter::Close All Modals sent Aug 26 17:27:38 volumio volumio[1200]: info: CoreCommandRouter::Close All Modals sent Aug 26 17:27:38 volumio volumio[1200]: info: CoreStateMachine::pushState Aug 26 17:27:38 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 26 17:27:38 volumio volumio[1200]: info: CoreCommandRouter::volumioPushState Aug 26 17:27:38 volumio volumio[1200]: SPOTIFY: RECEIVED VOLUMIO VOLUME 90 Aug 26 17:27:38 volumio volumio[1200]: SPOTIFY: SPOTIFY VOLUME 91 Aug 26 17:27:38 volumio volumio[1200]: SPOTIFY: VOLUMIO VOLUME 90 Aug 26 17:27:38 volumio volumio[1200]: SPOTIFY: DELTA VOLUME ENOUGH: false Aug 26 17:27:38 volumio volumio[1200]: info: Cannot play startup sound: Error: Command failed: /usr/bin/aplay -D volumio /volumio/app/startup.wav Aug 26 17:27:38 volumio volumio[1200]: aplay: main:831: audio open error: Device or resource busy Aug 26 17:27:38 volumio volumio[1200]: info: CoreCommandRouter::volumioGetState Aug 26 17:27:39 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable Aug 26 17:27:39 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Aug 26 17:27:39 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect Aug 26 17:27:40 volumio volumio[1200]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Aug 26 17:27:41 volumio volumio[1200]: info: MyVolumio token set successfully Aug 26 17:27:41 volumio volumio[1200]: info: MYVOLUMIO: Adding device Aug 26 17:27:41 volumio volumio[1200]: info: MYVOLUMIO: Evaluating Server Aug 26 17:27:41 volumio volumio[1200]: info: AutoStart - Check #12/60 - VOLUMIO_SYSTEM_STATUS = starting Aug 26 17:27:43 volumio volumio[1200]: info: MyVolumio status changed Aug 26 17:27:43 volumio volumio[1200]: info: Streaming services startup Aug 26 17:27:43 volumio volumio[1200]: info: Starting Streaming Daemon Aug 26 17:27:43 volumio volumio[1200]: info: Removing browser output: myVolumio user plan is not superstar Aug 26 17:27:43 volumio volumio[1200]: info: Removing audio output: Aug 26 17:27:43 volumio volumio[1200]: info: Stoppping Tunnel 1 Aug 26 17:27:44 volumio sudo[2587]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Aug 26 17:27:44 volumio sudo[2587]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 26 17:27:44 volumio sudo[2596]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service Aug 26 17:27:44 volumio volumio[1200]: info: Setting Geolocation for MyVolumio to eu4 Aug 26 17:27:44 volumio sudo[2596]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 26 17:27:44 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 26 17:27:44 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 26 17:27:44 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 26 17:27:44 volumio volumio[1200]: Upnp client error: Error: This socket has been ended by the other party Aug 26 17:27:44 volumio sudo[2587]: pam_unix(sudo:session): session closed for user root Aug 26 17:27:44 volumio volumio[1200]: error: Cannot start Volumio Streaming Daemon Aug 26 17:27:44 volumio volumio[1200]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Aug 26 17:27:44 volumio volumio[1200]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Aug 26 17:27:44 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Aug 26 17:27:44 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Aug 26 17:27:44 volumio volumio[1200]: info: CoreCommandRouter::volumioGetState Aug 26 17:27:44 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Aug 26 17:27:44 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Aug 26 17:27:44 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Aug 26 17:27:44 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Aug 26 17:27:44 volumio sudo[2596]: pam_unix(sudo:session): session closed for user root Aug 26 17:27:44 volumio volumio[1200]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Aug 26 17:27:45 volumio volumio[1200]: info: Remote SSH Stopped Aug 26 17:27:45 volumio volumio[1200]: info: BOOT COMPLETED Aug 26 17:27:45 volumio volumio[1200]: info: Aug 26 17:27:45 volumio volumio[1200]: ---------------------------- Client requests Volume 90 Aug 26 17:27:45 volumio volumio[1200]: info: VolumeController::SetAlsaVolume90 Aug 26 17:27:45 volumio volumio[1200]: info: CoreStateMachine::pushState Aug 26 17:27:45 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 26 17:27:45 volumio volumio[1200]: info: CoreCommandRouter::volumioPushState Aug 26 17:27:45 volumio volumio[1200]: info: Updating MyVolumio device info Aug 26 17:27:45 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 26 17:27:45 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 26 17:27:45 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 26 17:27:45 volumio volumio[1200]: SPOTIFY: RECEIVED VOLUMIO VOLUME 90 Aug 26 17:27:45 volumio volumio[1200]: SPOTIFY: SPOTIFY VOLUME 91 Aug 26 17:27:45 volumio volumio[1200]: SPOTIFY: VOLUMIO VOLUME 90 Aug 26 17:27:45 volumio volumio[1200]: SPOTIFY: DELTA VOLUME ENOUGH: false Aug 26 17:27:46 volumio volumio[1200]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Aug 26 17:27:46 volumio volumio[1200]: info: AutoStart - Check #13/60 - VOLUMIO_SYSTEM_STATUS = ready Aug 26 17:27:46 volumio volumio[1200]: info: AutoStart - System ready state CONFIRMED after 13 checks Aug 26 17:27:46 volumio volumio[1200]: info: AutoStart - Applying additional delay of 5000ms before playback Aug 26 17:27:46 volumio sudo[2620]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Aug 26 17:27:46 volumio sudo[2620]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 26 17:27:46 volumio sudo[2623]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Aug 26 17:27:46 volumio sudo[2623]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 26 17:27:46 volumio sudo[2620]: pam_unix(sudo:session): session closed for user root Aug 26 17:27:46 volumio sudo[2623]: pam_unix(sudo:session): session closed for user root Aug 26 17:27:47 volumio volumio[1200]: verbose: New Socket.io Connection to 192.168.62.25 from 192.168.62.176 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/150.0.0.0 Safari/537.36 OPR/134.0.0.0 Engine version: 3 Transport: polling Total Clients: 18 Aug 26 17:27:47 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Aug 26 17:27:47 volumio volumio[1200]: info: CoreCommandRouter::volumioGetVisibleSources Aug 26 17:27:47 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 26 17:27:47 volumio volumio[1200]: info: CoreCommandRouter::volumioGetState Aug 26 17:27:47 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Aug 26 17:27:47 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Aug 26 17:27:47 volumio volumio[1200]: info: Received Get System Info Aug 26 17:27:47 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 26 17:27:47 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 26 17:27:47 volumio volumio[1200]: info: Discovery: Getting this device information Aug 26 17:27:47 volumio volumio[1200]: info: CoreCommandRouter::volumioGetState Aug 26 17:27:47 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 26 17:27:47 volumio volumio[1200]: info: CoreCommandRouter::volumioGetState Aug 26 17:27:48 volumio volumio[1200]: info: Listing playlists Aug 26 17:27:48 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Aug 26 17:27:48 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Aug 26 17:27:48 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 26 17:27:48 volumio volumio[1200]: info: Received Get System Info Aug 26 17:27:48 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 26 17:27:48 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 26 17:27:48 volumio volumio[1200]: info: Discovery: Getting this device information Aug 26 17:27:48 volumio volumio[1200]: info: CoreCommandRouter::volumioGetState Aug 26 17:27:48 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 26 17:27:48 volumio volumio[1200]: info: CoreCommandRouter::volumioGetState Aug 26 17:27:48 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Aug 26 17:27:49 volumio volumio[1200]: info: MYVOLUMIO: Adding device Aug 26 17:27:49 volumio volumio[1200]: info: MYVOLUMIO: Evaluating Server Aug 26 17:27:49 volumio volumio[1200]: info: CoreCommandRouter::volumioGetState Aug 26 17:27:51 volumio volumio[1200]: info: AutoStart - startPlayback called Aug 26 17:27:51 volumio volumio[1200]: info: CoreCommandRouter::volumioGetQueue Aug 26 17:27:51 volumio volumio[1200]: info: CoreStateMachine::getQueue Aug 26 17:27:51 volumio volumio[1200]: info: CorePlayQueue::getQueue Aug 26 17:27:51 volumio volumio[1200]: info: AutoStart - Queue has 1 items Aug 26 17:27:51 volumio volumio[1200]: info: AutoStart - Playing from position 0 Aug 26 17:27:51 volumio volumio[1200]: info: CoreCommandRouter::volumioPlay Aug 26 17:27:51 volumio volumio[1200]: info: CoreStateMachine::play index 0 Aug 26 17:27:51 volumio volumio[1200]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 26 17:27:51 volumio volumio[1200]: info: CoreStateMachine::stop Aug 26 17:27:51 volumio volumio[1200]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 26 17:27:51 volumio volumio[1200]: info: CoreStateMachine::stPlaybackTimer Aug 26 17:27:51 volumio volumio[1200]: info: CoreStateMachine::updateTrackBlock Aug 26 17:27:51 volumio volumio[1200]: info: CorePlayQueue::getTrackBlock Aug 26 17:27:51 volumio volumio[1200]: info: CoreStateMachine::pushState Aug 26 17:27:51 volumio volumio[1200]: info: CorePlayQueue::getTrack 0 Aug 26 17:27:51 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 26 17:27:51 volumio volumio[1200]: info: CoreCommandRouter::volumioPushState Aug 26 17:27:51 volumio volumio[1200]: info: CoreStateMachine::serviceStop Aug 26 17:27:51 volumio volumio[1200]: info: CorePlayQueue::getTrack 0 Aug 26 17:27:51 volumio volumio[1200]: info: CoreCommandRouter::serviceStop Aug 26 17:27:51 volumio volumio[1200]: info: [1787754471964] ControllerWebradio::stop Aug 26 17:27:51 volumio volumio[1200]: verbose: ControllerMpd::sendMpdCommand stop Aug 26 17:27:52 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 26 17:27:52 volumio volumio[1200]: info: Received Get System Info Aug 26 17:27:52 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 26 17:27:52 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 26 17:27:52 volumio volumio[1200]: info: Discovery: Getting this device information Aug 26 17:27:52 volumio volumio[1200]: info: CoreCommandRouter::volumioGetState Aug 26 17:27:52 volumio volumio[1200]: info: CorePlayQueue::getTrack 0 Aug 26 17:27:52 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 26 17:27:52 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Aug 26 17:27:53 volumio volumio[1200]: SPOTIFY: RECEIVED VOLUMIO VOLUME 90 Aug 26 17:27:53 volumio volumio[1200]: SPOTIFY: SPOTIFY VOLUME 91 Aug 26 17:27:53 volumio volumio[1200]: SPOTIFY: VOLUMIO VOLUME 90 Aug 26 17:27:53 volumio volumio[1200]: SPOTIFY: DELTA VOLUME ENOUGH: false Aug 26 17:27:53 volumio volumio[1200]: info: Aug 26 17:27:53 volumio volumio[1200]: ---------------------------- MPD announces state update: player Aug 26 17:27:53 volumio volumio[1200]: info: sendMpdCommand stop took 1769 milliseconds Aug 26 17:27:53 volumio volumio[1200]: info: ControllerMpd::getState Aug 26 17:27:53 volumio volumio[1200]: verbose: ControllerMpd::sendMpdCommand status Aug 26 17:27:53 volumio volumio[1200]: info: CoreStateMachine::play index undefined Aug 26 17:27:53 volumio volumio[1200]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 26 17:27:53 volumio volumio[1200]: info: CorePlayQueue::getTrack 0 Aug 26 17:27:53 volumio volumio[1200]: info: CoreStateMachine::startPlaybackTimer Aug 26 17:27:53 volumio volumio[1200]: info: CorePlayQueue::getTrack 0 Aug 26 17:27:53 volumio volumio[1200]: info: [1787754473778] ControllerWebradio::clearAddPlayTrack Aug 26 17:27:53 volumio volumio[1200]: verbose: ControllerMpd::sendMpdCommand stop Aug 26 17:27:53 volumio volumio[1200]: info: Aug 26 17:27:53 volumio volumio[1200]: ---------------------------- MPD announces state update: player Aug 26 17:27:53 volumio volumio[1200]: info: ControllerMpd::getState Aug 26 17:27:53 volumio volumio[1200]: verbose: ControllerMpd::sendMpdCommand status Aug 26 17:27:53 volumio volumio[1200]: info: Aug 26 17:27:53 volumio volumio[1200]: ---------------------------- MPD announces state update: player Aug 26 17:27:53 volumio volumio[1200]: info: ControllerMpd::getState Aug 26 17:27:53 volumio volumio[1200]: verbose: ControllerMpd::sendMpdCommand status Aug 26 17:27:54 volumio volumio[1200]: info: Setting Geolocation for MyVolumio to eu4 Aug 26 17:27:54 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 26 17:27:54 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 26 17:27:54 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 26 17:27:54 volumio volumio[1200]: info: Aug 26 17:27:54 volumio volumio[1200]: ---------------------------- Client requests Volume 90 Aug 26 17:27:54 volumio volumio[1200]: info: VolumeController::SetAlsaVolume90 Aug 26 17:27:54 volumio volumio[1200]: info: CoreStateMachine::pushState Aug 26 17:27:54 volumio volumio[1200]: info: CorePlayQueue::getTrack 0 Aug 26 17:27:54 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 26 17:27:54 volumio volumio[1200]: info: CoreCommandRouter::volumioPushState Aug 26 17:27:54 volumio volumio[1200]: info: sendMpdCommand status took 689 milliseconds Aug 26 17:27:54 volumio volumio[1200]: info: sendMpdCommand stop took 674 milliseconds Aug 26 17:27:54 volumio volumio[1200]: info: sendMpdCommand status took 674 milliseconds Aug 26 17:27:54 volumio volumio[1200]: info: sendMpdCommand status took 676 milliseconds Aug 26 17:27:54 volumio volumio[1200]: verbose: ControllerMpd::parseState Aug 26 17:27:54 volumio volumio[1200]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 26 17:27:54 volumio volumio[1200]: verbose: ControllerMpd::sendMpdCommand clear Aug 26 17:27:54 volumio volumio[1200]: verbose: ControllerMpd::parseState Aug 26 17:27:54 volumio volumio[1200]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 26 17:27:54 volumio volumio[1200]: verbose: ControllerMpd::parseState Aug 26 17:27:54 volumio volumio[1200]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 26 17:27:54 volumio volumio[1200]: Upnp client error: Error: This socket has been ended by the other party Aug 26 17:27:54 volumio volumio[1200]: info: CoreCommandRouter::volumioGetState Aug 26 17:27:54 volumio volumio[1200]: info: CorePlayQueue::getTrack 0 Aug 26 17:27:54 volumio volumio[1200]: info: Aug 26 17:27:54 volumio volumio[1200]: ---------------------------- MPD announces system playlist update Aug 26 17:27:54 volumio volumio[1200]: info: Ignoring MPD Status Update Aug 26 17:27:54 volumio volumio[1200]: info: sendMpdCommand playlistinfo took 176 milliseconds Aug 26 17:27:54 volumio volumio[1200]: info: sendMpdCommand clear took 175 milliseconds Aug 26 17:27:54 volumio volumio[1200]: info: sendMpdCommand playlistinfo took 170 milliseconds Aug 26 17:27:54 volumio volumio[1200]: info: sendMpdCommand playlistinfo took 171 milliseconds Aug 26 17:27:54 volumio volumio[1200]: verbose: ControllerMpd::parseTrackInfo Aug 26 17:27:54 volumio volumio[1200]: verbose: ControllerMpd::sendMpdCommand load "https://stream.vanillaradio.com:8012/stream" Aug 26 17:27:54 volumio volumio[1200]: verbose: ControllerMpd::parseTrackInfo Aug 26 17:27:54 volumio volumio[1200]: verbose: ControllerMpd::parseTrackInfo Aug 26 17:27:54 volumio volumio[1200]: info: ControllerMpd::pushState Aug 26 17:27:54 volumio volumio[1200]: info: CoreCommandRouter::servicePushState Aug 26 17:27:54 volumio volumio[1200]: info: CoreStateMachine::pushState Aug 26 17:27:54 volumio volumio[1200]: info: CorePlayQueue::getTrack 0 Aug 26 17:27:54 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 26 17:27:54 volumio volumio[1200]: info: CoreCommandRouter::volumioPushState Aug 26 17:27:54 volumio volumio[1200]: info: CorePlayQueue::getTrack 0 Aug 26 17:27:54 volumio volumio[1200]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current webradio Received mpd Aug 26 17:27:54 volumio volumio[1200]: error: ControllerMpd::pushError: TypeError: Cannot read properties of undefined (reading 'split') Aug 26 17:27:54 volumio volumio[1200]: error: ControllerMpd::pushError: TypeError: Cannot read properties of undefined (reading 'split') Aug 26 17:27:54 volumio volumio[1200]: info: ------------------------------ 1121ms Aug 26 17:27:54 volumio volumio[1200]: info: ------------------------------ 1019ms Aug 26 17:27:54 volumio volumio[1200]: info: ------------------------------ 1022ms Aug 26 17:27:54 volumio volumio[1200]: SPOTIFY: RECEIVED VOLUMIO VOLUME 90 Aug 26 17:27:54 volumio volumio[1200]: SPOTIFY: SPOTIFY VOLUME 91 Aug 26 17:27:54 volumio volumio[1200]: SPOTIFY: VOLUMIO VOLUME 90 Aug 26 17:27:54 volumio volumio[1200]: SPOTIFY: DELTA VOLUME ENOUGH: false Aug 26 17:27:54 volumio volumio[1200]: SPOTIFY: RECEIVED VOLUMIO VOLUME 90 Aug 26 17:27:54 volumio volumio[1200]: SPOTIFY: SPOTIFY VOLUME 91 Aug 26 17:27:54 volumio volumio[1200]: SPOTIFY: VOLUMIO VOLUME 90 Aug 26 17:27:54 volumio volumio[1200]: SPOTIFY: DELTA VOLUME ENOUGH: false Aug 26 17:27:55 volumio volumio[1200]: info: Aug 26 17:27:55 volumio volumio[1200]: ---------------------------- MPD announces system playlist update Aug 26 17:27:55 volumio volumio[1200]: info: Ignoring MPD Status Update Aug 26 17:27:55 volumio volumio[1200]: info: Aug 26 17:27:55 volumio volumio[1200]: ---------------------------- MPD announces system playlist update Aug 26 17:27:55 volumio volumio[1200]: info: Ignoring MPD Status Update Aug 26 17:27:55 volumio volumio[1200]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 14 Aug 26 17:27:55 volumio volumio[1200]: info: Updating MyVolumio device info Aug 26 17:27:55 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 26 17:27:55 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 26 17:27:55 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 26 17:27:55 volumio volumio[1200]: error: updateQueue error: null Aug 26 17:27:55 volumio volumio[1200]: info: ------------------------------ 594ms Aug 26 17:27:55 volumio volumio[1200]: info: Aug 26 17:27:55 volumio volumio[1200]: ---------------------------- Client requests Volume 90 Aug 26 17:27:55 volumio volumio[1200]: info: VolumeController::SetAlsaVolume90 Aug 26 17:27:55 volumio volumio[1200]: info: CoreStateMachine::pushState Aug 26 17:27:55 volumio volumio[1200]: info: CorePlayQueue::getTrack 0 Aug 26 17:27:55 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 26 17:27:55 volumio volumio[1200]: info: CoreCommandRouter::volumioPushState Aug 26 17:27:56 volumio volumio[1200]: SPOTIFY: RECEIVED VOLUMIO VOLUME 90 Aug 26 17:27:56 volumio volumio[1200]: SPOTIFY: SPOTIFY VOLUME 91 Aug 26 17:27:56 volumio volumio[1200]: SPOTIFY: VOLUMIO VOLUME 90 Aug 26 17:27:56 volumio volumio[1200]: SPOTIFY: DELTA VOLUME ENOUGH: false Aug 26 17:27:56 volumio volumio[1200]: error: updateQueue error: null Aug 26 17:27:56 volumio volumio[1200]: error: updateQueue error: null Aug 26 17:27:56 volumio volumio[1200]: verbose: ControllerMpd::sendMpdCommand add "https://stream.vanillaradio.com:8012/stream" Aug 26 17:27:56 volumio volumio[1200]: info: ------------------------------ 1273ms Aug 26 17:27:56 volumio volumio[1200]: info: ------------------------------ 1246ms Aug 26 17:27:56 volumio volumio[1200]: info: Aug 26 17:27:56 volumio volumio[1200]: ---------------------------- MPD announces system playlist update Aug 26 17:27:56 volumio volumio[1200]: info: Ignoring MPD Status Update Aug 26 17:27:56 volumio volumio[1200]: info: sendMpdCommand add "https://stream.vanillaradio.com:8012/stream" took 131 milliseconds Aug 26 17:27:56 volumio volumio[1200]: info: CoreStateMachine::setConsumeUpdateService mpd Aug 26 17:27:56 volumio volumio[1200]: verbose: ControllerMpd::sendMpdCommand play Aug 26 17:27:56 volumio volumio[1200]: info: Aug 26 17:27:56 volumio volumio[1200]: ---------------------------- MPD announces system playlist update Aug 26 17:27:56 volumio volumio[1200]: info: Ignoring MPD Status Update Aug 26 17:27:56 volumio volumio[1200]: info: Aug 26 17:27:56 volumio volumio[1200]: ---------------------------- MPD announces system playlist update Aug 26 17:27:56 volumio volumio[1200]: info: Ignoring MPD Status Update Aug 26 17:27:56 volumio volumio[1200]: info: ------------------------------ 173ms Aug 26 17:27:56 volumio volumio[1200]: info: sendMpdCommand play took 260 milliseconds Aug 26 17:27:56 volumio volumio[1200]: info: ------------------------------ 260ms Aug 26 17:27:56 volumio volumio[1200]: info: ------------------------------ 204ms Aug 26 17:27:56 volumio volumio[1200]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Aug 26 17:27:56 volumio volumio[1200]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Aug 26 17:27:57 volumio volumio[1200]: info: CoreCommandRouter::volumioGetState Aug 26 17:27:57 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Aug 26 17:27:57 volumio volumio[1200]: info: Aug 26 17:27:57 volumio volumio[1200]: ---------------------------- Client requests Volume 90 Aug 26 17:27:57 volumio volumio[1200]: info: VolumeController::SetAlsaVolume90 Aug 26 17:27:57 volumio volumio[1200]: info: CoreStateMachine::pushState Aug 26 17:27:57 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 26 17:27:57 volumio volumio[1200]: info: CoreCommandRouter::volumioPushState Aug 26 17:27:57 volumio volumio[1200]: SPOTIFY: RECEIVED VOLUMIO VOLUME 90 Aug 26 17:27:57 volumio volumio[1200]: SPOTIFY: SPOTIFY VOLUME 91 Aug 26 17:27:57 volumio volumio[1200]: SPOTIFY: VOLUMIO VOLUME 90 Aug 26 17:27:57 volumio volumio[1200]: SPOTIFY: DELTA VOLUME ENOUGH: false Aug 26 17:27:57 volumio volumio[1200]: info: Aug 26 17:27:57 volumio volumio[1200]: ---------------------------- MPD announces state update: player Aug 26 17:27:57 volumio volumio[1200]: info: ControllerMpd::getState Aug 26 17:27:57 volumio volumio[1200]: verbose: ControllerMpd::sendMpdCommand status Aug 26 17:27:57 volumio volumio[1200]: info: Aug 26 17:27:57 volumio volumio[1200]: ---------------------------- MPD announces state update: player Aug 26 17:27:57 volumio volumio[1200]: info: ControllerMpd::getState Aug 26 17:27:57 volumio volumio[1200]: verbose: ControllerMpd::sendMpdCommand status Aug 26 17:27:57 volumio volumio[1200]: info: Aug 26 17:27:57 volumio volumio[1200]: ---------------------------- MPD announces state update: player Aug 26 17:27:57 volumio volumio[1200]: info: Aug 26 17:27:57 volumio volumio[1200]: ---------------------------- MPD announces system playlist update Aug 26 17:27:57 volumio volumio[1200]: info: Ignoring MPD Status Update Aug 26 17:27:57 volumio volumio[1200]: info: Aug 26 17:27:57 volumio volumio[1200]: ---------------------------- MPD announces state update: player Aug 26 17:27:57 volumio volumio[1200]: info: ControllerMpd::getState Aug 26 17:27:57 volumio volumio[1200]: verbose: ControllerMpd::sendMpdCommand status Aug 26 17:27:57 volumio volumio[1200]: info: sendMpdCommand status took 9 milliseconds Aug 26 17:27:57 volumio volumio[1200]: info: ControllerMpd::getState Aug 26 17:27:57 volumio volumio[1200]: verbose: ControllerMpd::sendMpdCommand status Aug 26 17:27:57 volumio volumio[1200]: verbose: ControllerMpd::parseState Aug 26 17:27:57 volumio volumio[1200]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 26 17:27:57 volumio volumio[1200]: info: Aug 26 17:27:57 volumio volumio[1200]: ---------------------------- MPD announces state update: player Aug 26 17:27:57 volumio volumio[1200]: info: ControllerMpd::getState Aug 26 17:27:57 volumio volumio[1200]: verbose: ControllerMpd::sendMpdCommand status Aug 26 17:27:57 volumio volumio[1200]: info: Aug 26 17:27:57 volumio volumio[1200]: ---------------------------- MPD announces system playlist update Aug 26 17:27:57 volumio volumio[1200]: info: Ignoring MPD Status Update Aug 26 17:27:57 volumio volumio[1200]: info: Aug 26 17:27:57 volumio volumio[1200]: ---------------------------- MPD announces state update: player Aug 26 17:27:57 volumio volumio[1200]: info: ControllerMpd::getState Aug 26 17:27:57 volumio volumio[1200]: verbose: ControllerMpd::sendMpdCommand status Aug 26 17:27:57 volumio volumio[1200]: info: sendMpdCommand status took 51 milliseconds Aug 26 17:27:57 volumio volumio[1200]: info: sendMpdCommand status took 50 milliseconds Aug 26 17:27:57 volumio volumio[1200]: info: ------------------------------ 51ms Aug 26 17:27:57 volumio volumio[1200]: info: sendMpdCommand status took 50 milliseconds Aug 26 17:27:57 volumio volumio[1200]: info: sendMpdCommand playlistinfo took 49 milliseconds Aug 26 17:27:57 volumio volumio[1200]: info: sendMpdCommand status took 2 milliseconds Aug 26 17:27:57 volumio volumio[1200]: info: ------------------------------ 2ms Aug 26 17:27:57 volumio volumio[1200]: info: sendMpdCommand status took 1 milliseconds Aug 26 17:27:57 volumio volumio[1200]: verbose: ControllerMpd::parseState Aug 26 17:27:57 volumio volumio[1200]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 26 17:27:57 volumio volumio[1200]: verbose: ControllerMpd::parseState Aug 26 17:27:57 volumio volumio[1200]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 26 17:27:57 volumio volumio[1200]: verbose: ControllerMpd::parseState Aug 26 17:27:57 volumio volumio[1200]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 26 17:27:57 volumio volumio[1200]: verbose: ControllerMpd::parseTrackInfo Aug 26 17:27:57 volumio volumio[1200]: verbose: ControllerMpd::parseState Aug 26 17:27:57 volumio volumio[1200]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 26 17:27:57 volumio volumio[1200]: verbose: ControllerMpd::parseState Aug 26 17:27:57 volumio volumio[1200]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 26 17:27:57 volumio volumio[1200]: info: ControllerMpd::pushState Aug 26 17:27:57 volumio volumio[1200]: info: CoreCommandRouter::servicePushState Aug 26 17:27:57 volumio volumio[1200]: info: CorePlayQueue::getTrack 0 Aug 26 17:27:57 volumio volumio[1200]: verbose: STATE SERVICE {"status":"play","position":0,"seek":881,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"Tina Charles - I Love To Love (But My Baby Loves To Dance) (Dj Pantelis Remix)","artist":"Vanilla Radio Deep Flavors","album":null,"uri":"https://stream.vanillaradio.com:8012/stream","trackType":""} Aug 26 17:27:57 volumio volumio[1200]: verbose: CURRENT POSITION 0 Aug 26 17:27:57 volumio volumio[1200]: info: CoreStateMachine::syncState stateService play Aug 26 17:27:57 volumio volumio[1200]: info: CoreStateMachine::syncState currentStatus stop Aug 26 17:27:57 volumio volumio[1200]: info: ------------------------------ 141ms Aug 26 17:27:58 volumio volumio[1200]: info: Aug 26 17:27:58 volumio volumio[1200]: ---------------------------- MPD announces system playlist update Aug 26 17:27:58 volumio volumio[1200]: info: Ignoring MPD Status Update Aug 26 17:27:58 volumio volumio[1200]: info: Aug 26 17:27:58 volumio volumio[1200]: ---------------------------- MPD announces state update: player Aug 26 17:27:58 volumio volumio[1200]: info: ControllerMpd::getState Aug 26 17:27:58 volumio volumio[1200]: verbose: ControllerMpd::sendMpdCommand status Aug 26 17:27:58 volumio volumio[1200]: info: sendMpdCommand playlistinfo took 161 milliseconds Aug 26 17:27:58 volumio volumio[1200]: info: sendMpdCommand playlistinfo took 168 milliseconds Aug 26 17:27:58 volumio volumio[1200]: info: sendMpdCommand playlistinfo took 139 milliseconds Aug 26 17:27:58 volumio volumio[1200]: info: sendMpdCommand playlistinfo took 138 milliseconds Aug 26 17:27:58 volumio volumio[1200]: info: sendMpdCommand playlistinfo took 136 milliseconds Aug 26 17:27:58 volumio volumio[1200]: info: ------------------------------ 27ms Aug 26 17:27:58 volumio volumio[1200]: info: sendMpdCommand status took 20 milliseconds Aug 26 17:27:58 volumio volumio[1200]: verbose: ControllerMpd::parseTrackInfo Aug 26 17:27:58 volumio volumio[1200]: verbose: ControllerMpd::parseTrackInfo Aug 26 17:27:58 volumio volumio[1200]: verbose: ControllerMpd::parseTrackInfo Aug 26 17:27:58 volumio volumio[1200]: verbose: ControllerMpd::parseTrackInfo Aug 26 17:27:58 volumio volumio[1200]: verbose: ControllerMpd::parseTrackInfo Aug 26 17:27:58 volumio volumio[1200]: verbose: ControllerMpd::parseState Aug 26 17:27:58 volumio volumio[1200]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 26 17:27:58 volumio volumio[1200]: info: ControllerMpd::pushState Aug 26 17:27:58 volumio volumio[1200]: info: CoreCommandRouter::servicePushState Aug 26 17:27:58 volumio volumio[1200]: info: CorePlayQueue::getTrack 0 Aug 26 17:27:58 volumio volumio[1200]: verbose: STATE SERVICE {"status":"play","position":0,"seek":881,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"Tina Charles - I Love To Love (But My Baby Loves To Dance) (Dj Pantelis Remix)","artist":"Vanilla Radio Deep Flavors","album":null,"uri":"https://stream.vanillaradio.com:8012/stream","trackType":""} Aug 26 17:27:58 volumio volumio[1200]: verbose: CURRENT POSITION 0 Aug 26 17:27:58 volumio volumio[1200]: info: CoreStateMachine::syncState stateService play Aug 26 17:27:58 volumio volumio[1200]: info: CoreStateMachine::syncState currentStatus play Aug 26 17:27:58 volumio volumio[1200]: info: Received an update from plugin. extracting info from payload Aug 26 17:27:58 volumio volumio[1200]: info: CoreStateMachine::pushState Aug 26 17:27:58 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 26 17:27:58 volumio volumio[1200]: info: CoreCommandRouter::volumioPushState Aug 26 17:27:58 volumio volumio[1200]: info: CoreStateMachine::pushState Aug 26 17:27:58 volumio volumio[1200]: info: CoreCommandRouter::volumioPushState Aug 26 17:27:58 volumio volumio[1200]: info: ControllerMpd::pushState Aug 26 17:27:58 volumio volumio[1200]: info: CoreCommandRouter::servicePushState Aug 26 17:27:58 volumio volumio[1200]: info: CorePlayQueue::getTrack 0 Aug 26 17:27:58 volumio volumio[1200]: verbose: STATE SERVICE {"status":"play","position":0,"seek":881,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"Tina Charles - I Love To Love (But My Baby Loves To Dance) (Dj Pantelis Remix)","artist":"Vanilla Radio Deep Flavors","album":null,"uri":"https://stream.vanillaradio.com:8012/stream","trackType":""} Aug 26 17:27:58 volumio volumio[1200]: verbose: CURRENT POSITION 0 Aug 26 17:27:58 volumio volumio[1200]: info: CoreStateMachine::syncState stateService play Aug 26 17:27:58 volumio volumio[1200]: info: CoreStateMachine::syncState currentStatus play Aug 26 17:27:58 volumio volumio[1200]: info: Received an update from plugin. extracting info from payload Aug 26 17:27:58 volumio volumio[1200]: info: CoreStateMachine::pushState Aug 26 17:27:58 volumio volumio[1200]: info: CoreCommandRouter::volumioPushState Aug 26 17:27:58 volumio volumio[1200]: info: CoreStateMachine::pushState Aug 26 17:27:58 volumio volumio[1200]: info: CoreCommandRouter::volumioPushState Aug 26 17:27:58 volumio volumio[1200]: info: ControllerMpd::pushState Aug 26 17:27:58 volumio volumio[1200]: info: CoreCommandRouter::servicePushState Aug 26 17:27:58 volumio volumio[1200]: info: CorePlayQueue::getTrack 0 Aug 26 17:27:58 volumio volumio[1200]: verbose: STATE SERVICE {"status":"play","position":0,"seek":881,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"Tina Charles - I Love To Love (But My Baby Loves To Dance) (Dj Pantelis Remix)","artist":"Vanilla Radio Deep Flavors","album":null,"uri":"https://stream.vanillaradio.com:8012/stream","trackType":""} Aug 26 17:27:58 volumio volumio[1200]: verbose: CURRENT POSITION 0 Aug 26 17:27:58 volumio volumio[1200]: info: CoreStateMachine::syncState stateService play Aug 26 17:27:58 volumio volumio[1200]: info: CoreStateMachine::syncState currentStatus play Aug 26 17:27:58 volumio volumio[1200]: info: Received an update from plugin. extracting info from payload Aug 26 17:27:58 volumio volumio[1200]: info: CoreStateMachine::pushState Aug 26 17:27:58 volumio volumio[1200]: info: CoreCommandRouter::volumioPushState Aug 26 17:27:58 volumio volumio[1200]: info: CoreStateMachine::pushState Aug 26 17:27:58 volumio volumio[1200]: info: CoreCommandRouter::volumioPushState Aug 26 17:27:58 volumio volumio[1200]: info: ControllerMpd::pushState Aug 26 17:27:58 volumio volumio[1200]: info: CoreCommandRouter::servicePushState Aug 26 17:27:58 volumio volumio[1200]: info: CorePlayQueue::getTrack 0 Aug 26 17:27:58 volumio volumio[1200]: verbose: STATE SERVICE {"status":"play","position":0,"seek":881,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"Tina Charles - I Love To Love (But My Baby Loves To Dance) (Dj Pantelis Remix)","artist":"Vanilla Radio Deep Flavors","album":null,"uri":"https://stream.vanillaradio.com:8012/stream","trackType":""} Aug 26 17:27:58 volumio volumio[1200]: verbose: CURRENT POSITION 0 Aug 26 17:27:58 volumio volumio[1200]: info: CoreStateMachine::syncState stateService play Aug 26 17:27:58 volumio volumio[1200]: info: CoreStateMachine::syncState currentStatus play Aug 26 17:27:58 volumio volumio[1200]: info: Received an update from plugin. extracting info from payload Aug 26 17:27:58 volumio volumio[1200]: info: CoreStateMachine::pushState Aug 26 17:27:58 volumio volumio[1200]: info: CoreCommandRouter::volumioPushState Aug 26 17:27:58 volumio volumio[1200]: info: CoreStateMachine::pushState Aug 26 17:27:58 volumio volumio[1200]: info: CoreCommandRouter::volumioPushState Aug 26 17:27:58 volumio volumio[1200]: info: ControllerMpd::pushState Aug 26 17:27:58 volumio volumio[1200]: info: CoreCommandRouter::servicePushState Aug 26 17:27:58 volumio volumio[1200]: info: CorePlayQueue::getTrack 0 Aug 26 17:27:58 volumio volumio[1200]: verbose: STATE SERVICE {"status":"play","position":0,"seek":881,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"Tina Charles - I Love To Love (But My Baby Loves To Dance) (Dj Pantelis Remix)","artist":"Vanilla Radio Deep Flavors","album":null,"uri":"https://stream.vanillaradio.com:8012/stream","trackType":""} Aug 26 17:27:58 volumio volumio[1200]: verbose: CURRENT POSITION 0 Aug 26 17:27:58 volumio volumio[1200]: info: CoreStateMachine::syncState stateService play Aug 26 17:27:58 volumio volumio[1200]: info: CoreStateMachine::syncState currentStatus play Aug 26 17:27:58 volumio volumio[1200]: info: Received an update from plugin. extracting info from payload Aug 26 17:27:58 volumio volumio[1200]: info: CoreStateMachine::pushState Aug 26 17:27:58 volumio volumio[1200]: info: CoreCommandRouter::volumioPushState Aug 26 17:27:58 volumio volumio[1200]: info: CoreStateMachine::pushState Aug 26 17:27:58 volumio volumio[1200]: info: CoreCommandRouter::volumioPushState Aug 26 17:27:59 volumio volumio[1200]: info: ------------------------------ 1715ms Aug 26 17:27:59 volumio volumio[1200]: info: ------------------------------ 1722ms Aug 26 17:27:59 volumio volumio[1200]: info: ------------------------------ 1729ms Aug 26 17:27:59 volumio volumio[1200]: info: ------------------------------ 1698ms Aug 26 17:27:59 volumio volumio[1200]: info: ------------------------------ 1689ms Aug 26 17:27:59 volumio volumio[1200]: info: sendMpdCommand playlistinfo took 1550 milliseconds Aug 26 17:27:59 volumio volumio[1200]: verbose: ControllerMpd::parseTrackInfo Aug 26 17:27:59 volumio volumio[1200]: info: ControllerMpd::pushState Aug 26 17:27:59 volumio volumio[1200]: info: CoreCommandRouter::servicePushState Aug 26 17:27:59 volumio volumio[1200]: info: CorePlayQueue::getTrack 0 Aug 26 17:27:59 volumio volumio[1200]: verbose: STATE SERVICE {"status":"play","position":0,"seek":1081,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"Tina Charles - I Love To Love (But My Baby Loves To Dance) (Dj Pantelis Remix)","artist":"Vanilla Radio Deep Flavors","album":null,"uri":"https://stream.vanillaradio.com:8012/stream","trackType":""} Aug 26 17:27:59 volumio volumio[1200]: verbose: CURRENT POSITION 0 Aug 26 17:27:59 volumio volumio[1200]: info: CoreStateMachine::syncState stateService play Aug 26 17:27:59 volumio volumio[1200]: info: CoreStateMachine::syncState currentStatus play Aug 26 17:27:59 volumio volumio[1200]: info: Received an update from plugin. extracting info from payload Aug 26 17:27:59 volumio volumio[1200]: info: CoreStateMachine::pushState Aug 26 17:27:59 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 26 17:27:59 volumio volumio[1200]: info: CoreCommandRouter::volumioPushState Aug 26 17:27:59 volumio volumio5-onboarding[2448]: failed to bootstrap state: failed to check for software update: could not check for updates: context deadline exceeded Aug 26 17:27:59 volumio systemd[1]: volumio5-onboarding.service: Main process exited, code=exited, status=1/FAILURE Aug 26 17:27:59 volumio systemd[1]: volumio5-onboarding.service: Failed with result 'exit-code'. Aug 26 17:27:59 volumio volumio[1200]: info: CoreStateMachine::pushState Aug 26 17:27:59 volumio volumio[1200]: info: CoreCommandRouter::volumioPushState Aug 26 17:27:59 volumio systemd[1]: volumio5-onboarding.service: Scheduled restart job, restart counter is at 8. Aug 26 17:27:59 volumio systemd[1]: Stopped volumio5-onboarding.service - Volumio5 Onboarding Server. Aug 26 17:27:59 volumio systemd[1]: Started volumio5-onboarding.service - Volumio5 Onboarding Server. Aug 26 17:27:59 volumio volumio5-onboarding[2749]: time=2026-08-26T17:27:59.899+03:00 level=INFO msg="running volumio5-device-gateway" version=6370e0a8+CHANGES buildDate=2026-03-06T16:29:42Z Aug 26 17:27:59 volumio volumio[1200]: info: ------------------------------ 1924ms Aug 26 17:28:00 volumio volumio[1200]: SPOTIFY: RECEIVED VOLUMIO VOLUME 90 Aug 26 17:28:00 volumio volumio[1200]: SPOTIFY: SPOTIFY VOLUME 91 Aug 26 17:28:00 volumio volumio[1200]: SPOTIFY: VOLUMIO VOLUME 90 Aug 26 17:28:00 volumio volumio[1200]: SPOTIFY: DELTA VOLUME ENOUGH: false Aug 26 17:28:00 volumio volumio[1200]: SPOTIFY: RECEIVED VOLUMIO VOLUME 90 Aug 26 17:28:00 volumio volumio[1200]: SPOTIFY: SPOTIFY VOLUME 91 Aug 26 17:28:00 volumio volumio[1200]: SPOTIFY: VOLUMIO VOLUME 90 Aug 26 17:28:00 volumio volumio[1200]: SPOTIFY: DELTA VOLUME ENOUGH: false Aug 26 17:28:00 volumio volumio[1200]: SPOTIFY: RECEIVED VOLUMIO VOLUME 90 Aug 26 17:28:00 volumio volumio[1200]: SPOTIFY: SPOTIFY VOLUME 91 Aug 26 17:28:00 volumio volumio[1200]: SPOTIFY: VOLUMIO VOLUME 90 Aug 26 17:28:00 volumio volumio[1200]: SPOTIFY: DELTA VOLUME ENOUGH: false Aug 26 17:28:00 volumio volumio[1200]: SPOTIFY: RECEIVED VOLUMIO VOLUME 90 Aug 26 17:28:00 volumio volumio[1200]: SPOTIFY: SPOTIFY VOLUME 91 Aug 26 17:28:00 volumio volumio[1200]: SPOTIFY: VOLUMIO VOLUME 90 Aug 26 17:28:00 volumio volumio[1200]: SPOTIFY: DELTA VOLUME ENOUGH: false Aug 26 17:28:00 volumio volumio[1200]: SPOTIFY: RECEIVED VOLUMIO VOLUME 90 Aug 26 17:28:00 volumio volumio[1200]: SPOTIFY: SPOTIFY VOLUME 91 Aug 26 17:28:00 volumio volumio[1200]: SPOTIFY: VOLUMIO VOLUME 90 Aug 26 17:28:00 volumio volumio[1200]: SPOTIFY: DELTA VOLUME ENOUGH: false Aug 26 17:28:00 volumio volumio[1200]: SPOTIFY: RECEIVED VOLUMIO VOLUME 90 Aug 26 17:28:00 volumio volumio[1200]: SPOTIFY: SPOTIFY VOLUME 91 Aug 26 17:28:00 volumio volumio[1200]: SPOTIFY: VOLUMIO VOLUME 90 Aug 26 17:28:00 volumio volumio[1200]: SPOTIFY: DELTA VOLUME ENOUGH: false Aug 26 17:28:00 volumio volumio[1200]: SPOTIFY: RECEIVED VOLUMIO VOLUME 90 Aug 26 17:28:00 volumio volumio[1200]: SPOTIFY: SPOTIFY VOLUME 91 Aug 26 17:28:00 volumio volumio[1200]: SPOTIFY: VOLUMIO VOLUME 90 Aug 26 17:28:00 volumio volumio[1200]: SPOTIFY: DELTA VOLUME ENOUGH: false Aug 26 17:28:00 volumio volumio[1200]: SPOTIFY: RECEIVED VOLUMIO VOLUME 90 Aug 26 17:28:00 volumio volumio[1200]: SPOTIFY: SPOTIFY VOLUME 91 Aug 26 17:28:00 volumio volumio[1200]: SPOTIFY: VOLUMIO VOLUME 90 Aug 26 17:28:00 volumio volumio[1200]: SPOTIFY: DELTA VOLUME ENOUGH: false Aug 26 17:28:00 volumio volumio[1200]: SPOTIFY: RECEIVED VOLUMIO VOLUME 90 Aug 26 17:28:00 volumio volumio[1200]: SPOTIFY: SPOTIFY VOLUME 91 Aug 26 17:28:00 volumio volumio[1200]: SPOTIFY: VOLUMIO VOLUME 90 Aug 26 17:28:00 volumio volumio[1200]: SPOTIFY: DELTA VOLUME ENOUGH: false Aug 26 17:28:00 volumio volumio[1200]: SPOTIFY: RECEIVED VOLUMIO VOLUME 90 Aug 26 17:28:00 volumio volumio[1200]: SPOTIFY: SPOTIFY VOLUME 91 Aug 26 17:28:00 volumio volumio[1200]: SPOTIFY: VOLUMIO VOLUME 90 Aug 26 17:28:00 volumio volumio[1200]: SPOTIFY: DELTA VOLUME ENOUGH: false Aug 26 17:28:00 volumio volumio[1200]: SPOTIFY: RECEIVED VOLUMIO VOLUME 90 Aug 26 17:28:00 volumio volumio[1200]: SPOTIFY: SPOTIFY VOLUME 91 Aug 26 17:28:00 volumio volumio[1200]: SPOTIFY: VOLUMIO VOLUME 90 Aug 26 17:28:00 volumio volumio[1200]: SPOTIFY: DELTA VOLUME ENOUGH: false Aug 26 17:28:00 volumio volumio[1200]: SPOTIFY: RECEIVED VOLUMIO VOLUME 90 Aug 26 17:28:00 volumio volumio[1200]: SPOTIFY: SPOTIFY VOLUME 91 Aug 26 17:28:00 volumio volumio[1200]: SPOTIFY: VOLUMIO VOLUME 90 Aug 26 17:28:00 volumio volumio[1200]: SPOTIFY: DELTA VOLUME ENOUGH: false Aug 26 17:28:00 volumio volumio[1200]: info: touch_display: Setting screensaver timeout to 0 seconds. Aug 26 17:28:01 volumio volumio[1200]: 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: 14 Aug 26 17:28:01 volumio volumio[1200]: 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: 14 Aug 26 17:28:01 volumio volumio[1200]: info: Received Get System Info Aug 26 17:28:01 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 26 17:28:01 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 26 17:28:01 volumio volumio[1200]: info: Discovery: Getting this device information Aug 26 17:28:01 volumio volumio[1200]: info: CoreCommandRouter::volumioGetState Aug 26 17:28:01 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 26 17:28:01 volumio volumio5-onboarding[2749]: time=2026-08-26T17:28:01.064+03:00 level=INFO msg="system info for cb42ef6fe90861a5c5c68087d72bdd2b" deviceName=Volumio deviceVariant=volumio deviceModel= softwareVersion=4.119 Aug 26 17:28:01 volumio volumio5-onboarding[2749]: time=2026-08-26T17:28:01.069+03:00 level=INFO msg="bootstrapping state" hasInternet=true Aug 26 17:28:01 volumio volumio[1200]: info: Received Get System Info Aug 26 17:28:01 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 26 17:28:01 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 26 17:28:01 volumio volumio[1200]: info: Discovery: Getting this device information Aug 26 17:28:01 volumio volumio[1200]: info: CoreCommandRouter::volumioGetState Aug 26 17:28:01 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 26 17:28:01 volumio volumio-remote-updater[808]: Test mode disabled Aug 26 17:28:01 volumio volumio-remote-updater[808]: Alpha mode disabled Aug 26 17:28:01 volumio volumio-remote-updater[808]: Alpha legacy test mode disabled Aug 26 17:28:01 volumio volumio[1200]: info: Update Ready: {"changeLogLink":"","description":"You're already on the latest version","title":"No Updates Available","updateavailable":false} Aug 26 17:28:01 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache Aug 26 17:28:01 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 26 17:28:01 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 26 17:28:01 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Aug 26 17:28:03 volumio volumio5-onboarding[2749]: time=2026-08-26T17:28:03.061+03:00 level=WARN msg="could not read OAuth data for music provider" component=volumio provider=tidal error="could not open plugin config file for \"tidal\": open /data/configuration/music_service/tidal/config.json: no such file or directory" Aug 26 17:28:03 volumio volumio5-onboarding[2749]: time=2026-08-26T17:28:03.063+03:00 level=WARN msg="could not read OAuth data for music provider" component=volumio provider=qobuz error="could not open plugin config file for \"qobuz\": open /data/configuration/music_service/qobuz/config.json: no such file or directory" Aug 26 17:28:03 volumio volumio5-onboarding[2749]: time=2026-08-26T17:28:03.065+03:00 level=WARN msg="could not read username/password data for music provider" component=volumio provider=hi_res_audio error="could not open plugin config file for \"hi_res_audio\": open /data/configuration/music_service/hi_res_audio/config.json: no such file or directory" Aug 26 17:28:03 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 26 17:28:03 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 26 17:28:03 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Aug 26 17:28:03 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 26 17:28:03 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Aug 26 17:28:04 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Aug 26 17:28:04 volumio volumio[1200]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Aug 26 17:28:04 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Aug 26 17:28:04 volumio volumio[1200]: info: Received Get System Version Aug 26 17:28:04 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 26 17:28:04 volumio volumio[1200]: info: Received Get System Info Aug 26 17:28:04 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 26 17:28:04 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 26 17:28:04 volumio volumio[1200]: info: Discovery: Getting this device information Aug 26 17:28:04 volumio volumio[1200]: info: CoreCommandRouter::volumioGetState Aug 26 17:28:04 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 26 17:28:05 volumio volumio5-onboarding[2749]: time=2026-08-26T17:28:05.637+03:00 level=INFO msg="authenticated Firebase client" component=volumio/firebase userId=rmJjgpzo6KSiFvXbLn9Tonupuzg2 tokenExpiry=2026-08-26T18:28:05.637+03:00 Aug 26 17:28:05 volumio volumio[1200]: info: CoreCommandRouter::volumioStop Aug 26 17:28:05 volumio volumio[1200]: info: CoreStateMachine::stop Aug 26 17:28:05 volumio volumio[1200]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 26 17:28:05 volumio volumio[1200]: info: CoreStateMachine::stPlaybackTimer Aug 26 17:28:05 volumio volumio[1200]: info: CoreStateMachine::updateTrackBlock Aug 26 17:28:05 volumio volumio[1200]: info: CorePlayQueue::getTrackBlock Aug 26 17:28:05 volumio volumio[1200]: info: CoreStateMachine::pushState Aug 26 17:28:05 volumio volumio[1200]: info: CorePlayQueue::getTrack 0 Aug 26 17:28:05 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 26 17:28:05 volumio volumio[1200]: info: CoreCommandRouter::volumioPushState Aug 26 17:28:06 volumio volumio[1200]: info: CoreStateMachine::serviceStop Aug 26 17:28:06 volumio volumio[1200]: info: CorePlayQueue::getTrack 0 Aug 26 17:28:06 volumio volumio[1200]: info: CoreCommandRouter::serviceStop Aug 26 17:28:06 volumio volumio[1200]: info: [1787754486132] ControllerWebradio::stop Aug 26 17:28:06 volumio volumio[1200]: verbose: ControllerMpd::sendMpdCommand stop Aug 26 17:28:06 volumio volumio[1200]: SPOTIFY: RECEIVED VOLUMIO VOLUME 90 Aug 26 17:28:06 volumio volumio[1200]: SPOTIFY: SPOTIFY VOLUME 91 Aug 26 17:28:06 volumio volumio[1200]: SPOTIFY: VOLUMIO VOLUME 90 Aug 26 17:28:06 volumio volumio[1200]: SPOTIFY: DELTA VOLUME ENOUGH: false Aug 26 17:28:06 volumio volumio[1200]: info: Aug 26 17:28:06 volumio volumio[1200]: ---------------------------- MPD announces state update: player Aug 26 17:28:06 volumio volumio[1200]: info: sendMpdCommand stop took 337 milliseconds Aug 26 17:28:06 volumio volumio[1200]: info: ControllerMpd::getState Aug 26 17:28:06 volumio volumio[1200]: verbose: ControllerMpd::sendMpdCommand status Aug 26 17:28:06 volumio volumio[1200]: info: sendMpdCommand status took 1 milliseconds Aug 26 17:28:06 volumio volumio[1200]: verbose: ControllerMpd::parseState Aug 26 17:28:06 volumio volumio[1200]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 26 17:28:06 volumio volumio[1200]: info: Aug 26 17:28:06 volumio volumio[1200]: ---------------------------- MPD announces state update: player Aug 26 17:28:06 volumio volumio[1200]: info: ControllerMpd::getState Aug 26 17:28:06 volumio volumio[1200]: verbose: ControllerMpd::sendMpdCommand status Aug 26 17:28:06 volumio volumio[1200]: info: Aug 26 17:28:06 volumio volumio[1200]: ---------------------------- MPD announces state update: player Aug 26 17:28:06 volumio volumio[1200]: info: ControllerMpd::getState Aug 26 17:28:06 volumio volumio[1200]: verbose: ControllerMpd::sendMpdCommand status Aug 26 17:28:06 volumio volumio[1200]: info: Received Get System Info Aug 26 17:28:06 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 26 17:28:06 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 26 17:28:06 volumio volumio[1200]: info: Discovery: Getting this device information Aug 26 17:28:06 volumio volumio[1200]: info: CoreCommandRouter::volumioGetState Aug 26 17:28:06 volumio volumio[1200]: info: CorePlayQueue::getTrack 0 Aug 26 17:28:06 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 26 17:28:06 volumio volumio[1200]: info: sendMpdCommand playlistinfo took 154 milliseconds Aug 26 17:28:06 volumio volumio[1200]: info: sendMpdCommand status took 181 milliseconds Aug 26 17:28:06 volumio volumio[1200]: info: sendMpdCommand status took 181 milliseconds Aug 26 17:28:06 volumio volumio[1200]: verbose: ControllerMpd::parseTrackInfo Aug 26 17:28:06 volumio volumio[1200]: verbose: ControllerMpd::parseState Aug 26 17:28:06 volumio volumio[1200]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 26 17:28:06 volumio volumio[1200]: verbose: ControllerMpd::parseState Aug 26 17:28:06 volumio volumio[1200]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 26 17:28:06 volumio volumio[1200]: info: ControllerMpd::pushState Aug 26 17:28:06 volumio volumio[1200]: info: CoreCommandRouter::servicePushState Aug 26 17:28:06 volumio volumio[1200]: info: CoreStateMachine::pushState Aug 26 17:28:06 volumio volumio[1200]: info: CorePlayQueue::getTrack 0 Aug 26 17:28:06 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 26 17:28:06 volumio volumio[1200]: info: CoreCommandRouter::volumioPushState Aug 26 17:28:06 volumio volumio[1200]: info: CorePlayQueue::getTrack 0 Aug 26 17:28:06 volumio volumio[1200]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current webradio Received mpd Aug 26 17:28:06 volumio volumio[1200]: info: ------------------------------ 400ms Aug 26 17:28:06 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Aug 26 17:28:06 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Aug 26 17:28:06 volumio volumio5-onboarding[2749]: time=2026-08-26T17:28:06.870+03:00 level=INFO msg="enabling local network discovery" Aug 26 17:28:06 volumio volumio[1200]: info: sendMpdCommand playlistinfo took 204 milliseconds Aug 26 17:28:06 volumio volumio[1200]: info: sendMpdCommand playlistinfo took 209 milliseconds Aug 26 17:28:06 volumio volumio[1200]: verbose: ControllerMpd::parseTrackInfo Aug 26 17:28:06 volumio volumio[1200]: verbose: ControllerMpd::parseTrackInfo Aug 26 17:28:06 volumio volumio[1200]: info: ControllerMpd::pushState Aug 26 17:28:06 volumio volumio[1200]: info: CoreCommandRouter::servicePushState Aug 26 17:28:06 volumio volumio[1200]: info: CoreStateMachine::pushState Aug 26 17:28:06 volumio volumio5-onboarding[2749]: time=2026-08-26T17:28:06.904+03:00 level=INFO msg="enabling BLE discovery" Aug 26 17:28:06 volumio volumio[1200]: info: CorePlayQueue::getTrack 0 Aug 26 17:28:06 volumio volumio[1200]: info: CoreCommandRouter::volumioPushState Aug 26 17:28:07 volumio volumio[1200]: info: CorePlayQueue::getTrack 0 Aug 26 17:28:07 volumio volumio[1200]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current webradio Received mpd Aug 26 17:28:07 volumio volumio[1200]: info: ControllerMpd::pushState Aug 26 17:28:07 volumio volumio[1200]: info: CoreCommandRouter::servicePushState Aug 26 17:28:07 volumio volumio[1200]: info: CoreStateMachine::pushState Aug 26 17:28:07 volumio volumio[1200]: info: CorePlayQueue::getTrack 0 Aug 26 17:28:07 volumio volumio[1200]: info: CoreCommandRouter::volumioPushState Aug 26 17:28:07 volumio volumio[1200]: info: CorePlayQueue::getTrack 0 Aug 26 17:28:07 volumio volumio[1200]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current webradio Received mpd Aug 26 17:28:07 volumio volumio[1200]: info: ------------------------------ 870ms Aug 26 17:28:07 volumio volumio[1200]: info: ------------------------------ 897ms Aug 26 17:28:07 volumio volumio[1200]: SPOTIFY: RECEIVED VOLUMIO VOLUME 90 Aug 26 17:28:07 volumio volumio[1200]: SPOTIFY: SPOTIFY VOLUME 91 Aug 26 17:28:07 volumio volumio[1200]: SPOTIFY: VOLUMIO VOLUME 90 Aug 26 17:28:07 volumio volumio[1200]: SPOTIFY: DELTA VOLUME ENOUGH: false Aug 26 17:28:07 volumio volumio[1200]: SPOTIFY: RECEIVED VOLUMIO VOLUME 90 Aug 26 17:28:07 volumio volumio[1200]: SPOTIFY: SPOTIFY VOLUME 91 Aug 26 17:28:07 volumio volumio[1200]: SPOTIFY: VOLUMIO VOLUME 90 Aug 26 17:28:07 volumio volumio[1200]: SPOTIFY: DELTA VOLUME ENOUGH: false Aug 26 17:28:07 volumio volumio[1200]: SPOTIFY: RECEIVED VOLUMIO VOLUME 90 Aug 26 17:28:07 volumio volumio[1200]: SPOTIFY: SPOTIFY VOLUME 91 Aug 26 17:28:07 volumio volumio[1200]: SPOTIFY: VOLUMIO VOLUME 90 Aug 26 17:28:07 volumio volumio[1200]: SPOTIFY: DELTA VOLUME ENOUGH: false Aug 26 17:28:07 volumio volumio[1200]: info: touch_display: Setting screensaver timeout to 300 seconds. Aug 26 17:28:07 volumio volumio[1200]: info: CoreCommandRouter::volumioPlay Aug 26 17:28:07 volumio volumio[1200]: info: CoreStateMachine::play index undefined Aug 26 17:28:07 volumio volumio[1200]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 26 17:28:07 volumio volumio[1200]: info: CorePlayQueue::getTrack 0 Aug 26 17:28:07 volumio volumio[1200]: info: CoreStateMachine::startPlaybackTimer Aug 26 17:28:07 volumio volumio[1200]: info: CorePlayQueue::getTrack 0 Aug 26 17:28:07 volumio volumio[1200]: info: [1787754487808] ControllerWebradio::clearAddPlayTrack Aug 26 17:28:07 volumio volumio[1200]: verbose: ControllerMpd::sendMpdCommand stop Aug 26 17:28:07 volumio volumio[1200]: info: sendMpdCommand stop took 2 milliseconds Aug 26 17:28:07 volumio volumio[1200]: verbose: ControllerMpd::sendMpdCommand clear Aug 26 17:28:07 volumio volumio[1200]: info: Aug 26 17:28:07 volumio volumio[1200]: ---------------------------- MPD announces system playlist update Aug 26 17:28:07 volumio volumio[1200]: info: Ignoring MPD Status Update Aug 26 17:28:07 volumio volumio[1200]: info: sendMpdCommand clear took 0 milliseconds Aug 26 17:28:07 volumio volumio[1200]: verbose: ControllerMpd::sendMpdCommand load "https://stream.vanillaradio.com:8012/stream" Aug 26 17:28:07 volumio volumio[1200]: info: Aug 26 17:28:07 volumio volumio[1200]: ---------------------------- MPD announces system playlist update Aug 26 17:28:07 volumio volumio[1200]: info: Ignoring MPD Status Update Aug 26 17:28:07 volumio volumio[1200]: info: Aug 26 17:28:07 volumio volumio[1200]: ---------------------------- MPD announces system playlist update Aug 26 17:28:07 volumio volumio[1200]: info: Ignoring MPD Status Update Aug 26 17:28:07 volumio volumio[1200]: error: updateQueue error: null Aug 26 17:28:07 volumio volumio[1200]: info: ------------------------------ 24ms Aug 26 17:28:07 volumio volumio5-onboarding[2749]: time=2026-08-26T17:28:07.942+03:00 level=INFO msg="service successfully established" component=discovery/localnet Aug 26 17:28:08 volumio volumio[1200]: error: updateQueue error: null Aug 26 17:28:08 volumio volumio[1200]: error: updateQueue error: null Aug 26 17:28:08 volumio volumio[1200]: verbose: ControllerMpd::sendMpdCommand add "https://stream.vanillaradio.com:8012/stream" Aug 26 17:28:08 volumio volumio[1200]: info: ------------------------------ 1120ms Aug 26 17:28:08 volumio volumio[1200]: info: ------------------------------ 1126ms Aug 26 17:28:08 volumio volumio[1200]: info: Aug 26 17:28:08 volumio volumio[1200]: ---------------------------- MPD announces system playlist update Aug 26 17:28:08 volumio volumio[1200]: info: Ignoring MPD Status Update Aug 26 17:28:08 volumio volumio[1200]: info: sendMpdCommand add "https://stream.vanillaradio.com:8012/stream" took 20 milliseconds Aug 26 17:28:08 volumio volumio[1200]: info: CoreStateMachine::setConsumeUpdateService mpd Aug 26 17:28:08 volumio volumio[1200]: verbose: ControllerMpd::sendMpdCommand play Aug 26 17:28:08 volumio volumio[1200]: info: Aug 26 17:28:08 volumio volumio[1200]: ---------------------------- MPD announces system playlist update Aug 26 17:28:08 volumio volumio[1200]: info: Ignoring MPD Status Update Aug 26 17:28:08 volumio volumio[1200]: info: Aug 26 17:28:08 volumio volumio[1200]: ---------------------------- MPD announces system playlist update Aug 26 17:28:09 volumio volumio[1200]: info: Ignoring MPD Status Update Aug 26 17:28:09 volumio volumio[1200]: info: ------------------------------ 75ms Aug 26 17:28:09 volumio volumio[1200]: info: sendMpdCommand play took 65 milliseconds Aug 26 17:28:09 volumio volumio[1200]: info: ------------------------------ 64ms Aug 26 17:28:09 volumio volumio[1200]: info: ------------------------------ 51ms Aug 26 17:28:10 volumio volumio[1200]: info: Aug 26 17:28:10 volumio volumio[1200]: ---------------------------- MPD announces state update: player Aug 26 17:28:10 volumio volumio[1200]: info: ControllerMpd::getState Aug 26 17:28:10 volumio volumio[1200]: verbose: ControllerMpd::sendMpdCommand status Aug 26 17:28:10 volumio volumio[1200]: info: Aug 26 17:28:10 volumio volumio[1200]: ---------------------------- MPD announces state update: player Aug 26 17:28:10 volumio volumio[1200]: info: ControllerMpd::getState Aug 26 17:28:10 volumio volumio[1200]: verbose: ControllerMpd::sendMpdCommand status Aug 26 17:28:10 volumio volumio[1200]: info: Aug 26 17:28:10 volumio volumio[1200]: ---------------------------- MPD announces state update: player Aug 26 17:28:10 volumio volumio[1200]: info: Aug 26 17:28:10 volumio volumio[1200]: ---------------------------- MPD announces state update: player Aug 26 17:28:10 volumio volumio[1200]: info: ControllerMpd::getState Aug 26 17:28:10 volumio volumio[1200]: verbose: ControllerMpd::sendMpdCommand status Aug 26 17:28:10 volumio volumio[1200]: info: sendMpdCommand status took 22 milliseconds Aug 26 17:28:10 volumio volumio[1200]: info: ControllerMpd::getState Aug 26 17:28:10 volumio volumio[1200]: verbose: ControllerMpd::sendMpdCommand status Aug 26 17:28:10 volumio volumio[1200]: info: sendMpdCommand status took 40 milliseconds Aug 26 17:28:10 volumio volumio[1200]: verbose: ControllerMpd::parseState Aug 26 17:28:10 volumio volumio[1200]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 26 17:28:10 volumio volumio[1200]: verbose: ControllerMpd::parseState Aug 26 17:28:10 volumio volumio[1200]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 26 17:28:10 volumio volumio[1200]: info: Aug 26 17:28:10 volumio volumio[1200]: ---------------------------- MPD announces state update: player Aug 26 17:28:10 volumio volumio[1200]: info: ControllerMpd::getState Aug 26 17:28:10 volumio volumio[1200]: verbose: ControllerMpd::sendMpdCommand status Aug 26 17:28:10 volumio volumio[1200]: info: Aug 26 17:28:10 volumio volumio[1200]: ---------------------------- MPD announces state update: player Aug 26 17:28:10 volumio volumio[1200]: info: ControllerMpd::getState Aug 26 17:28:10 volumio volumio[1200]: verbose: ControllerMpd::sendMpdCommand status Aug 26 17:28:10 volumio volumio[1200]: info: Aug 26 17:28:10 volumio volumio[1200]: ---------------------------- MPD announces system playlist update Aug 26 17:28:10 volumio volumio[1200]: info: Ignoring MPD Status Update Aug 26 17:28:10 volumio volumio[1200]: info: Aug 26 17:28:10 volumio volumio[1200]: ---------------------------- MPD announces state update: player Aug 26 17:28:10 volumio volumio[1200]: info: Aug 26 17:28:10 volumio volumio[1200]: ---------------------------- MPD announces system playlist update Aug 26 17:28:10 volumio volumio[1200]: info: Ignoring MPD Status Update Aug 26 17:28:10 volumio volumio[1200]: info: Aug 26 17:28:10 volumio volumio[1200]: ---------------------------- MPD announces state update: player Aug 26 17:28:10 volumio volumio[1200]: info: ControllerMpd::getState Aug 26 17:28:10 volumio volumio[1200]: verbose: ControllerMpd::sendMpdCommand status Aug 26 17:28:10 volumio volumio[1200]: info: sendMpdCommand status took 53 milliseconds Aug 26 17:28:10 volumio volumio[1200]: info: ControllerMpd::getState Aug 26 17:28:10 volumio volumio[1200]: verbose: ControllerMpd::sendMpdCommand status Aug 26 17:28:10 volumio volumio[1200]: info: sendMpdCommand status took 36 milliseconds Aug 26 17:28:10 volumio volumio[1200]: info: sendMpdCommand playlistinfo took 27 milliseconds Aug 26 17:28:10 volumio volumio[1200]: info: sendMpdCommand playlistinfo took 16 milliseconds Aug 26 17:28:10 volumio volumio[1200]: info: sendMpdCommand status took 3 milliseconds Aug 26 17:28:10 volumio volumio[1200]: info: sendMpdCommand status took 2 milliseconds Aug 26 17:28:10 volumio volumio[1200]: verbose: ControllerMpd::parseState Aug 26 17:28:10 volumio volumio[1200]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 26 17:28:10 volumio volumio[1200]: verbose: ControllerMpd::parseState Aug 26 17:28:10 volumio volumio[1200]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 26 17:28:10 volumio volumio[1200]: verbose: ControllerMpd::parseTrackInfo Aug 26 17:28:10 volumio volumio[1200]: verbose: ControllerMpd::parseTrackInfo Aug 26 17:28:10 volumio volumio[1200]: verbose: ControllerMpd::parseState Aug 26 17:28:10 volumio volumio[1200]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 26 17:28:10 volumio volumio[1200]: verbose: ControllerMpd::parseState Aug 26 17:28:10 volumio volumio[1200]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 26 17:28:10 volumio volumio[1200]: info: ControllerMpd::pushState Aug 26 17:28:10 volumio volumio[1200]: info: CoreCommandRouter::servicePushState Aug 26 17:28:10 volumio volumio[1200]: info: CorePlayQueue::getTrack 0 Aug 26 17:28:10 volumio volumio[1200]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"Tina Charles - I Love To Love (But My Baby Loves To Dance) (Dj Pantelis Remix)","artist":"Vanilla Radio Deep Flavors","album":null,"uri":"https://stream.vanillaradio.com:8012/stream","trackType":""} Aug 26 17:28:10 volumio volumio[1200]: verbose: CURRENT POSITION 0 Aug 26 17:28:10 volumio volumio[1200]: info: CoreStateMachine::syncState stateService play Aug 26 17:28:10 volumio volumio[1200]: info: CoreStateMachine::syncState currentStatus stop Aug 26 17:28:10 volumio volumio[1200]: info: ControllerMpd::pushState Aug 26 17:28:10 volumio volumio[1200]: info: CoreCommandRouter::servicePushState Aug 26 17:28:10 volumio volumio[1200]: info: CorePlayQueue::getTrack 0 Aug 26 17:28:10 volumio volumio[1200]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"Tina Charles - I Love To Love (But My Baby Loves To Dance) (Dj Pantelis Remix)","artist":"Vanilla Radio Deep Flavors","album":null,"uri":"https://stream.vanillaradio.com:8012/stream","trackType":""} Aug 26 17:28:10 volumio volumio[1200]: verbose: CURRENT POSITION 0 Aug 26 17:28:10 volumio volumio[1200]: info: CoreStateMachine::syncState stateService play Aug 26 17:28:10 volumio volumio[1200]: info: CoreStateMachine::syncState currentStatus play Aug 26 17:28:10 volumio volumio[1200]: info: Received an update from plugin. extracting info from payload Aug 26 17:28:10 volumio volumio[1200]: info: CoreStateMachine::pushState Aug 26 17:28:10 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 26 17:28:10 volumio volumio[1200]: info: CoreCommandRouter::volumioPushState Aug 26 17:28:10 volumio volumio[1200]: info: CoreStateMachine::pushState Aug 26 17:28:10 volumio volumio[1200]: info: CoreCommandRouter::volumioPushState Aug 26 17:28:10 volumio volumio[1200]: info: ------------------------------ 321ms Aug 26 17:28:10 volumio volumio[1200]: info: ------------------------------ 608ms Aug 26 17:28:10 volumio volumio[1200]: info: Aug 26 17:28:10 volumio volumio[1200]: ---------------------------- MPD announces system playlist update Aug 26 17:28:10 volumio volumio[1200]: info: Ignoring MPD Status Update Aug 26 17:28:10 volumio volumio[1200]: info: Aug 26 17:28:10 volumio volumio[1200]: ---------------------------- MPD announces state update: player Aug 26 17:28:10 volumio volumio[1200]: info: ControllerMpd::getState Aug 26 17:28:10 volumio volumio[1200]: verbose: ControllerMpd::sendMpdCommand status Aug 26 17:28:10 volumio volumio[1200]: info: Aug 26 17:28:10 volumio volumio[1200]: ---------------------------- MPD announces system playlist update Aug 26 17:28:10 volumio volumio[1200]: info: Ignoring MPD Status Update Aug 26 17:28:10 volumio volumio[1200]: info: Aug 26 17:28:10 volumio volumio[1200]: ---------------------------- MPD announces state update: player Aug 26 17:28:10 volumio volumio[1200]: info: ControllerMpd::getState Aug 26 17:28:10 volumio volumio[1200]: verbose: ControllerMpd::sendMpdCommand status Aug 26 17:28:10 volumio volumio[1200]: info: ------------------------------ 632ms Aug 26 17:28:10 volumio volumio[1200]: info: sendMpdCommand status took 637 milliseconds Aug 26 17:28:10 volumio volumio[1200]: info: ------------------------------ 658ms Aug 26 17:28:10 volumio volumio[1200]: info: sendMpdCommand status took 658 milliseconds Aug 26 17:28:10 volumio volumio[1200]: info: sendMpdCommand playlistinfo took 660 milliseconds Aug 26 17:28:10 volumio volumio[1200]: info: sendMpdCommand playlistinfo took 661 milliseconds Aug 26 17:28:10 volumio volumio[1200]: info: sendMpdCommand playlistinfo took 608 milliseconds Aug 26 17:28:10 volumio volumio[1200]: info: sendMpdCommand playlistinfo took 607 milliseconds Aug 26 17:28:10 volumio volumio[1200]: info: ------------------------------ 67ms Aug 26 17:28:10 volumio volumio[1200]: info: sendMpdCommand status took 67 milliseconds Aug 26 17:28:10 volumio volumio[1200]: info: ------------------------------ 66ms Aug 26 17:28:10 volumio volumio[1200]: info: sendMpdCommand status took 66 milliseconds Aug 26 17:28:10 volumio volumio[1200]: verbose: ControllerMpd::parseState Aug 26 17:28:10 volumio volumio[1200]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 26 17:28:10 volumio volumio[1200]: verbose: ControllerMpd::parseState Aug 26 17:28:10 volumio volumio[1200]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 26 17:28:10 volumio volumio[1200]: verbose: ControllerMpd::parseTrackInfo Aug 26 17:28:10 volumio volumio[1200]: verbose: ControllerMpd::parseTrackInfo Aug 26 17:28:10 volumio volumio[1200]: verbose: ControllerMpd::parseTrackInfo Aug 26 17:28:10 volumio volumio[1200]: verbose: ControllerMpd::parseTrackInfo Aug 26 17:28:10 volumio volumio[1200]: verbose: ControllerMpd::parseState Aug 26 17:28:10 volumio volumio[1200]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 26 17:28:10 volumio volumio[1200]: verbose: ControllerMpd::parseState Aug 26 17:28:10 volumio volumio[1200]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 26 17:28:10 volumio volumio[1200]: info: ControllerMpd::pushState Aug 26 17:28:10 volumio volumio[1200]: info: CoreCommandRouter::servicePushState Aug 26 17:28:10 volumio volumio[1200]: info: CorePlayQueue::getTrack 0 Aug 26 17:28:10 volumio volumio[1200]: verbose: STATE SERVICE {"status":"play","position":0,"seek":881,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"Tina Charles - I Love To Love (But My Baby Loves To Dance) (Dj Pantelis Remix)","artist":"Vanilla Radio Deep Flavors","album":null,"uri":"https://stream.vanillaradio.com:8012/stream","trackType":""} Aug 26 17:28:10 volumio volumio[1200]: verbose: CURRENT POSITION 0 Aug 26 17:28:10 volumio volumio[1200]: info: CoreStateMachine::syncState stateService play Aug 26 17:28:10 volumio volumio[1200]: info: CoreStateMachine::syncState currentStatus play Aug 26 17:28:10 volumio volumio[1200]: info: Received an update from plugin. extracting info from payload Aug 26 17:28:10 volumio volumio[1200]: info: CoreStateMachine::pushState Aug 26 17:28:10 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 26 17:28:10 volumio volumio[1200]: info: CoreCommandRouter::volumioPushState Aug 26 17:28:11 volumio volumio[1200]: info: CoreStateMachine::pushState Aug 26 17:28:11 volumio volumio[1200]: info: CoreCommandRouter::volumioPushState Aug 26 17:28:11 volumio volumio[1200]: info: ControllerMpd::pushState Aug 26 17:28:11 volumio volumio[1200]: info: CoreCommandRouter::servicePushState Aug 26 17:28:11 volumio volumio[1200]: info: CorePlayQueue::getTrack 0 Aug 26 17:28:11 volumio volumio[1200]: verbose: STATE SERVICE {"status":"play","position":0,"seek":881,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"Tina Charles - I Love To Love (But My Baby Loves To Dance) (Dj Pantelis Remix)","artist":"Vanilla Radio Deep Flavors","album":null,"uri":"https://stream.vanillaradio.com:8012/stream","trackType":""} Aug 26 17:28:11 volumio volumio[1200]: verbose: CURRENT POSITION 0 Aug 26 17:28:11 volumio volumio[1200]: info: CoreStateMachine::syncState stateService play Aug 26 17:28:11 volumio volumio[1200]: info: CoreStateMachine::syncState currentStatus play Aug 26 17:28:11 volumio volumio[1200]: info: Received an update from plugin. extracting info from payload Aug 26 17:28:11 volumio volumio[1200]: info: CoreStateMachine::pushState Aug 26 17:28:11 volumio volumio[1200]: info: CoreCommandRouter::volumioPushState Aug 26 17:28:11 volumio volumio[1200]: info: CoreStateMachine::pushState Aug 26 17:28:11 volumio volumio[1200]: info: CoreCommandRouter::volumioPushState Aug 26 17:28:11 volumio volumio[1200]: info: ControllerMpd::pushState Aug 26 17:28:11 volumio volumio[1200]: info: CoreCommandRouter::servicePushState Aug 26 17:28:11 volumio volumio[1200]: info: CorePlayQueue::getTrack 0 Aug 26 17:28:11 volumio volumio[1200]: verbose: STATE SERVICE {"status":"play","position":0,"seek":881,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"Tina Charles - I Love To Love (But My Baby Loves To Dance) (Dj Pantelis Remix)","artist":"Vanilla Radio Deep Flavors","album":null,"uri":"https://stream.vanillaradio.com:8012/stream","trackType":""} Aug 26 17:28:11 volumio volumio[1200]: verbose: CURRENT POSITION 0 Aug 26 17:28:11 volumio volumio[1200]: info: CoreStateMachine::syncState stateService play Aug 26 17:28:11 volumio volumio[1200]: info: CoreStateMachine::syncState currentStatus play Aug 26 17:28:11 volumio volumio[1200]: info: Received an update from plugin. extracting info from payload Aug 26 17:28:11 volumio volumio[1200]: info: CoreStateMachine::pushState Aug 26 17:28:11 volumio volumio[1200]: info: CoreCommandRouter::volumioPushState Aug 26 17:28:11 volumio volumio[1200]: info: CoreStateMachine::pushState Aug 26 17:28:11 volumio volumio[1200]: info: CoreCommandRouter::volumioPushState Aug 26 17:28:11 volumio volumio[1200]: info: ControllerMpd::pushState Aug 26 17:28:11 volumio volumio[1200]: info: CoreCommandRouter::servicePushState Aug 26 17:28:11 volumio volumio[1200]: info: CorePlayQueue::getTrack 0 Aug 26 17:28:11 volumio volumio[1200]: verbose: STATE SERVICE {"status":"play","position":0,"seek":881,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"Tina Charles - I Love To Love (But My Baby Loves To Dance) (Dj Pantelis Remix)","artist":"Vanilla Radio Deep Flavors","album":null,"uri":"https://stream.vanillaradio.com:8012/stream","trackType":""} Aug 26 17:28:11 volumio volumio[1200]: verbose: CURRENT POSITION 0 Aug 26 17:28:11 volumio volumio[1200]: info: CoreStateMachine::syncState stateService play Aug 26 17:28:11 volumio volumio[1200]: info: CoreStateMachine::syncState currentStatus play Aug 26 17:28:11 volumio volumio[1200]: info: Received an update from plugin. extracting info from payload Aug 26 17:28:11 volumio volumio[1200]: info: CoreStateMachine::pushState Aug 26 17:28:11 volumio volumio[1200]: info: CoreCommandRouter::volumioPushState Aug 26 17:28:11 volumio volumio[1200]: info: CoreStateMachine::pushState Aug 26 17:28:11 volumio volumio[1200]: info: CoreCommandRouter::volumioPushState Aug 26 17:28:12 volumio volumio[1200]: info: ------------------------------ 1951ms Aug 26 17:28:12 volumio volumio[1200]: info: ------------------------------ 1951ms Aug 26 17:28:12 volumio volumio[1200]: info: ------------------------------ 1906ms Aug 26 17:28:12 volumio volumio[1200]: info: ------------------------------ 1905ms Aug 26 17:28:12 volumio volumio[1200]: SPOTIFY: RECEIVED VOLUMIO VOLUME 90 Aug 26 17:28:12 volumio volumio[1200]: SPOTIFY: SPOTIFY VOLUME 91 Aug 26 17:28:12 volumio volumio[1200]: SPOTIFY: VOLUMIO VOLUME 90 Aug 26 17:28:12 volumio volumio[1200]: SPOTIFY: DELTA VOLUME ENOUGH: false Aug 26 17:28:12 volumio volumio[1200]: SPOTIFY: RECEIVED VOLUMIO VOLUME 90 Aug 26 17:28:12 volumio volumio[1200]: SPOTIFY: SPOTIFY VOLUME 91 Aug 26 17:28:12 volumio volumio[1200]: SPOTIFY: VOLUMIO VOLUME 90 Aug 26 17:28:12 volumio volumio[1200]: SPOTIFY: DELTA VOLUME ENOUGH: false Aug 26 17:28:12 volumio volumio[1200]: SPOTIFY: RECEIVED VOLUMIO VOLUME 90 Aug 26 17:28:12 volumio volumio[1200]: SPOTIFY: SPOTIFY VOLUME 91 Aug 26 17:28:12 volumio volumio[1200]: SPOTIFY: VOLUMIO VOLUME 90 Aug 26 17:28:12 volumio volumio[1200]: SPOTIFY: DELTA VOLUME ENOUGH: false Aug 26 17:28:12 volumio volumio[1200]: SPOTIFY: RECEIVED VOLUMIO VOLUME 90 Aug 26 17:28:12 volumio volumio[1200]: SPOTIFY: SPOTIFY VOLUME 91 Aug 26 17:28:12 volumio volumio[1200]: SPOTIFY: VOLUMIO VOLUME 90 Aug 26 17:28:12 volumio volumio[1200]: SPOTIFY: DELTA VOLUME ENOUGH: false Aug 26 17:28:12 volumio volumio[1200]: SPOTIFY: RECEIVED VOLUMIO VOLUME 90 Aug 26 17:28:12 volumio volumio[1200]: SPOTIFY: SPOTIFY VOLUME 91 Aug 26 17:28:12 volumio volumio[1200]: SPOTIFY: VOLUMIO VOLUME 90 Aug 26 17:28:12 volumio volumio[1200]: SPOTIFY: DELTA VOLUME ENOUGH: false Aug 26 17:28:12 volumio volumio[1200]: SPOTIFY: RECEIVED VOLUMIO VOLUME 90 Aug 26 17:28:12 volumio volumio[1200]: SPOTIFY: SPOTIFY VOLUME 91 Aug 26 17:28:12 volumio volumio[1200]: SPOTIFY: VOLUMIO VOLUME 90 Aug 26 17:28:12 volumio volumio[1200]: SPOTIFY: DELTA VOLUME ENOUGH: false Aug 26 17:28:12 volumio volumio[1200]: SPOTIFY: RECEIVED VOLUMIO VOLUME 90 Aug 26 17:28:12 volumio volumio[1200]: SPOTIFY: SPOTIFY VOLUME 91 Aug 26 17:28:12 volumio volumio[1200]: SPOTIFY: VOLUMIO VOLUME 90 Aug 26 17:28:12 volumio volumio[1200]: SPOTIFY: DELTA VOLUME ENOUGH: false Aug 26 17:28:12 volumio volumio[1200]: SPOTIFY: RECEIVED VOLUMIO VOLUME 90 Aug 26 17:28:12 volumio volumio[1200]: SPOTIFY: SPOTIFY VOLUME 91 Aug 26 17:28:12 volumio volumio[1200]: SPOTIFY: VOLUMIO VOLUME 90 Aug 26 17:28:12 volumio volumio[1200]: SPOTIFY: DELTA VOLUME ENOUGH: false Aug 26 17:28:12 volumio volumio[1200]: SPOTIFY: RECEIVED VOLUMIO VOLUME 90 Aug 26 17:28:12 volumio volumio[1200]: SPOTIFY: SPOTIFY VOLUME 91 Aug 26 17:28:12 volumio volumio[1200]: SPOTIFY: VOLUMIO VOLUME 90 Aug 26 17:28:12 volumio volumio[1200]: SPOTIFY: DELTA VOLUME ENOUGH: false Aug 26 17:28:12 volumio volumio[1200]: SPOTIFY: RECEIVED VOLUMIO VOLUME 90 Aug 26 17:28:12 volumio volumio[1200]: SPOTIFY: SPOTIFY VOLUME 91 Aug 26 17:28:12 volumio volumio[1200]: SPOTIFY: VOLUMIO VOLUME 90 Aug 26 17:28:12 volumio volumio[1200]: SPOTIFY: DELTA VOLUME ENOUGH: false Aug 26 17:28:12 volumio volumio[1200]: info: sendMpdCommand playlistinfo took 1822 milliseconds Aug 26 17:28:12 volumio volumio[1200]: info: sendMpdCommand playlistinfo took 1831 milliseconds Aug 26 17:28:12 volumio volumio[1200]: info: sendMpdCommand playlistinfo took 1835 milliseconds Aug 26 17:28:12 volumio volumio[1200]: info: sendMpdCommand playlistinfo took 1835 milliseconds Aug 26 17:28:12 volumio volumio[1200]: verbose: ControllerMpd::parseTrackInfo Aug 26 17:28:12 volumio volumio[1200]: verbose: ControllerMpd::parseTrackInfo Aug 26 17:28:12 volumio volumio[1200]: verbose: ControllerMpd::parseTrackInfo Aug 26 17:28:12 volumio volumio[1200]: verbose: ControllerMpd::parseTrackInfo Aug 26 17:28:12 volumio volumio[1200]: info: ControllerMpd::pushState Aug 26 17:28:12 volumio volumio[1200]: info: CoreCommandRouter::servicePushState Aug 26 17:28:12 volumio volumio[1200]: info: CorePlayQueue::getTrack 0 Aug 26 17:28:12 volumio volumio[1200]: verbose: STATE SERVICE {"status":"play","position":0,"seek":881,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"Tina Charles - I Love To Love (But My Baby Loves To Dance) (Dj Pantelis Remix)","artist":"Vanilla Radio Deep Flavors","album":null,"uri":"https://stream.vanillaradio.com:8012/stream","trackType":""} Aug 26 17:28:12 volumio volumio[1200]: verbose: CURRENT POSITION 0 Aug 26 17:28:12 volumio volumio[1200]: info: CoreStateMachine::syncState stateService play Aug 26 17:28:12 volumio volumio[1200]: info: CoreStateMachine::syncState currentStatus play Aug 26 17:28:12 volumio volumio[1200]: info: Received an update from plugin. extracting info from payload Aug 26 17:28:12 volumio volumio[1200]: info: CoreStateMachine::pushState Aug 26 17:28:12 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 26 17:28:12 volumio volumio[1200]: info: CoreCommandRouter::volumioPushState Aug 26 17:28:12 volumio volumio[1200]: info: CoreStateMachine::pushState Aug 26 17:28:12 volumio volumio[1200]: info: CoreCommandRouter::volumioPushState Aug 26 17:28:12 volumio volumio[1200]: info: ControllerMpd::pushState Aug 26 17:28:12 volumio volumio[1200]: info: CoreCommandRouter::servicePushState Aug 26 17:28:12 volumio volumio[1200]: info: CorePlayQueue::getTrack 0 Aug 26 17:28:12 volumio volumio[1200]: verbose: STATE SERVICE {"status":"play","position":0,"seek":881,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"Tina Charles - I Love To Love (But My Baby Loves To Dance) (Dj Pantelis Remix)","artist":"Vanilla Radio Deep Flavors","album":null,"uri":"https://stream.vanillaradio.com:8012/stream","trackType":""} Aug 26 17:28:12 volumio volumio[1200]: verbose: CURRENT POSITION 0 Aug 26 17:28:12 volumio volumio[1200]: info: CoreStateMachine::syncState stateService play Aug 26 17:28:12 volumio volumio[1200]: info: CoreStateMachine::syncState currentStatus play Aug 26 17:28:12 volumio volumio[1200]: info: Received an update from plugin. extracting info from payload Aug 26 17:28:12 volumio volumio[1200]: info: CoreStateMachine::pushState Aug 26 17:28:12 volumio volumio[1200]: info: CoreCommandRouter::volumioPushState Aug 26 17:28:12 volumio volumio[1200]: info: CoreStateMachine::pushState Aug 26 17:28:12 volumio volumio[1200]: info: CoreCommandRouter::volumioPushState Aug 26 17:28:12 volumio volumio[1200]: info: ControllerMpd::pushState Aug 26 17:28:12 volumio volumio[1200]: info: CoreCommandRouter::servicePushState Aug 26 17:28:12 volumio volumio[1200]: info: CorePlayQueue::getTrack 0 Aug 26 17:28:12 volumio volumio[1200]: verbose: STATE SERVICE {"status":"play","position":0,"seek":1481,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"Tina Charles - I Love To Love (But My Baby Loves To Dance) (Dj Pantelis Remix)","artist":"Vanilla Radio Deep Flavors","album":null,"uri":"https://stream.vanillaradio.com:8012/stream","trackType":""} Aug 26 17:28:12 volumio volumio[1200]: verbose: CURRENT POSITION 0 Aug 26 17:28:12 volumio volumio[1200]: info: CoreStateMachine::syncState stateService play Aug 26 17:28:12 volumio volumio[1200]: info: CoreStateMachine::syncState currentStatus play Aug 26 17:28:12 volumio volumio[1200]: info: Received an update from plugin. extracting info from payload Aug 26 17:28:12 volumio volumio[1200]: info: CoreStateMachine::pushState Aug 26 17:28:12 volumio volumio[1200]: info: CoreCommandRouter::volumioPushState Aug 26 17:28:12 volumio volumio[1200]: info: CoreStateMachine::pushState Aug 26 17:28:12 volumio volumio[1200]: info: CoreCommandRouter::volumioPushState Aug 26 17:28:12 volumio volumio[1200]: info: ControllerMpd::pushState Aug 26 17:28:12 volumio volumio[1200]: info: CoreCommandRouter::servicePushState Aug 26 17:28:12 volumio volumio[1200]: info: CorePlayQueue::getTrack 0 Aug 26 17:28:12 volumio volumio[1200]: verbose: STATE SERVICE {"status":"play","position":0,"seek":1481,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"Tina Charles - I Love To Love (But My Baby Loves To Dance) (Dj Pantelis Remix)","artist":"Vanilla Radio Deep Flavors","album":null,"uri":"https://stream.vanillaradio.com:8012/stream","trackType":""} Aug 26 17:28:12 volumio volumio[1200]: verbose: CURRENT POSITION 0 Aug 26 17:28:12 volumio volumio[1200]: info: CoreStateMachine::syncState stateService play Aug 26 17:28:12 volumio volumio[1200]: info: CoreStateMachine::syncState currentStatus play Aug 26 17:28:12 volumio volumio[1200]: info: Received an update from plugin. extracting info from payload Aug 26 17:28:12 volumio volumio[1200]: info: CoreStateMachine::pushState Aug 26 17:28:12 volumio volumio[1200]: info: CoreCommandRouter::volumioPushState Aug 26 17:28:12 volumio volumio[1200]: info: CoreStateMachine::pushState Aug 26 17:28:12 volumio volumio[1200]: info: CoreCommandRouter::volumioPushState Aug 26 17:28:13 volumio volumio[1200]: info: ------------------------------ 3328ms Aug 26 17:28:13 volumio volumio[1200]: info: ------------------------------ 3332ms Aug 26 17:28:13 volumio volumio[1200]: info: ------------------------------ 2744ms Aug 26 17:28:13 volumio volumio[1200]: info: ------------------------------ 2743ms Aug 26 17:28:13 volumio volumio[1200]: SPOTIFY: RECEIVED VOLUMIO VOLUME 90 Aug 26 17:28:13 volumio volumio[1200]: SPOTIFY: SPOTIFY VOLUME 91 Aug 26 17:28:13 volumio volumio[1200]: SPOTIFY: VOLUMIO VOLUME 90 Aug 26 17:28:13 volumio volumio[1200]: SPOTIFY: DELTA VOLUME ENOUGH: false Aug 26 17:28:13 volumio volumio[1200]: SPOTIFY: RECEIVED VOLUMIO VOLUME 90 Aug 26 17:28:13 volumio volumio[1200]: SPOTIFY: SPOTIFY VOLUME 91 Aug 26 17:28:13 volumio volumio[1200]: SPOTIFY: VOLUMIO VOLUME 90 Aug 26 17:28:13 volumio volumio[1200]: SPOTIFY: DELTA VOLUME ENOUGH: false Aug 26 17:28:13 volumio volumio[1200]: SPOTIFY: RECEIVED VOLUMIO VOLUME 90 Aug 26 17:28:13 volumio volumio[1200]: SPOTIFY: SPOTIFY VOLUME 91 Aug 26 17:28:13 volumio volumio[1200]: SPOTIFY: VOLUMIO VOLUME 90 Aug 26 17:28:13 volumio volumio[1200]: SPOTIFY: DELTA VOLUME ENOUGH: false Aug 26 17:28:13 volumio volumio[1200]: SPOTIFY: RECEIVED VOLUMIO VOLUME 90 Aug 26 17:28:13 volumio volumio[1200]: SPOTIFY: SPOTIFY VOLUME 91 Aug 26 17:28:13 volumio volumio[1200]: SPOTIFY: VOLUMIO VOLUME 90 Aug 26 17:28:13 volumio volumio[1200]: SPOTIFY: DELTA VOLUME ENOUGH: false Aug 26 17:28:13 volumio volumio[1200]: SPOTIFY: RECEIVED VOLUMIO VOLUME 90 Aug 26 17:28:13 volumio volumio[1200]: SPOTIFY: SPOTIFY VOLUME 91 Aug 26 17:28:13 volumio volumio[1200]: SPOTIFY: VOLUMIO VOLUME 90 Aug 26 17:28:13 volumio volumio[1200]: SPOTIFY: DELTA VOLUME ENOUGH: false Aug 26 17:28:13 volumio volumio[1200]: SPOTIFY: RECEIVED VOLUMIO VOLUME 90 Aug 26 17:28:13 volumio volumio[1200]: SPOTIFY: SPOTIFY VOLUME 91 Aug 26 17:28:13 volumio volumio[1200]: SPOTIFY: VOLUMIO VOLUME 90 Aug 26 17:28:13 volumio volumio[1200]: SPOTIFY: DELTA VOLUME ENOUGH: false Aug 26 17:28:13 volumio volumio[1200]: SPOTIFY: RECEIVED VOLUMIO VOLUME 90 Aug 26 17:28:13 volumio volumio[1200]: SPOTIFY: SPOTIFY VOLUME 91 Aug 26 17:28:13 volumio volumio[1200]: SPOTIFY: VOLUMIO VOLUME 90 Aug 26 17:28:13 volumio volumio[1200]: SPOTIFY: DELTA VOLUME ENOUGH: false Aug 26 17:28:13 volumio volumio[1200]: SPOTIFY: RECEIVED VOLUMIO VOLUME 90 Aug 26 17:28:13 volumio volumio[1200]: SPOTIFY: SPOTIFY VOLUME 91 Aug 26 17:28:13 volumio volumio[1200]: SPOTIFY: VOLUMIO VOLUME 90 Aug 26 17:28:13 volumio volumio[1200]: SPOTIFY: DELTA VOLUME ENOUGH: false Aug 26 17:28:14 volumio volumio[1200]: info: touch_display: Setting screensaver timeout to 0 seconds. Aug 26 17:28:14 volumio volumio[1200]: info: CoreCommandRouter::volumioGetState Aug 26 17:28:14 volumio volumio[1200]: info: Aug 26 17:28:14 volumio volumio[1200]: ---------------------------- Client requests Volume 90 Aug 26 17:28:14 volumio volumio[1200]: info: VolumeController::SetAlsaVolume90 Aug 26 17:28:14 volumio volumio[1200]: info: CoreStateMachine::pushState Aug 26 17:28:14 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 26 17:28:14 volumio volumio[1200]: info: CoreCommandRouter::volumioPushState Aug 26 17:28:15 volumio volumio[1200]: SPOTIFY: RECEIVED VOLUMIO VOLUME 90 Aug 26 17:28:15 volumio volumio[1200]: SPOTIFY: SPOTIFY VOLUME 91 Aug 26 17:28:15 volumio volumio[1200]: SPOTIFY: VOLUMIO VOLUME 90 Aug 26 17:28:15 volumio volumio[1200]: SPOTIFY: DELTA VOLUME ENOUGH: false Aug 26 17:28:27 volumio volumio[1200]: info: CoreCommandRouter::volumioGetQueue Aug 26 17:28:27 volumio volumio[1200]: info: CoreStateMachine::getQueue Aug 26 17:28:27 volumio volumio[1200]: info: CorePlayQueue::getQueue Aug 26 17:28:29 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri Aug 26 17:28:29 volumio volumio[1200]: info: CURURI: music-library Aug 26 17:28:29 volumio volumio[1200]: info: Preload queue cleared Aug 26 17:28:31 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri Aug 26 17:28:31 volumio volumio[1200]: info: CURURI: music-library/NAS Aug 26 17:28:31 volumio volumio[1200]: info: Preload queue cleared Aug 26 17:28:32 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri Aug 26 17:28:32 volumio volumio[1200]: info: CURURI: music-library/NAS/Data2 Aug 26 17:28:32 volumio volumio[1200]: info: Preload queue cleared Aug 26 17:28:32 volumio volumio[1200]: info: Preloading song: music-library/NAS/Data2/Adorable Deep Mix Deep House, Soundeo Mixtape.mp3 Aug 26 17:28:32 volumio volumio[1200]: info: Preloading song: music-library/NAS/Data2/Armin van Buuren's Top 30 Trance Songs.mp3 Aug 26 17:28:32 volumio volumio[1200]: info: Preloading song: music-library/NAS/Data2/Imram - Saishvari (Full Album) (320 kbps).mp3 Aug 26 17:28:33 volumio volumio[1200]: info: Exploding uri music-library/NAS/Data2/Adorable Deep Mix Deep House, Soundeo Mixtape.mp3 in service mpd Aug 26 17:28:33 volumio volumio[1200]: info: Exploding uri music-library/NAS/Data2/Armin van Buuren's Top 30 Trance Songs.mp3 in service mpd Aug 26 17:28:33 volumio volumio[1200]: info: Exploding uri music-library/NAS/Data2/Imram - Saishvari (Full Album) (320 kbps).mp3 in service mpd Aug 26 17:28:33 volumio volumio[1200]: info: ALBUMART /albumart?cacheid=400&web=//extralarge&path=%2Fmnt%2FNAS%2FData2%2FAdorable%20Deep%20Mix%20Deep%20House%2C%20Soundeo%20Mixtape.mp3&metadata=false Aug 26 17:28:33 volumio volumio[1200]: info: URI /mnt/NAS/Data2/Adorable Deep Mix Deep House, Soundeo Mixtape.mp3 Aug 26 17:28:33 volumio volumio[1200]: info: ALBUMART /albumart?cacheid=400&web=//extralarge&path=%2Fmnt%2FNAS%2FData2%2FArmin%20van%20Buuren's%20Top%2030%20Trance%20Songs.mp3&metadata=false Aug 26 17:28:33 volumio volumio[1200]: info: URI /mnt/NAS/Data2/Armin van Buuren's Top 30 Trance Songs.mp3 Aug 26 17:28:33 volumio volumio[1200]: info: ALBUMART /albumart?cacheid=400&web=//extralarge&path=%2Fmnt%2FNAS%2FData2%2FImram%20-%20Saishvari%20(Full%20Album)%20(320%20kbps).mp3&metadata=false Aug 26 17:28:33 volumio volumio[1200]: info: URI /mnt/NAS/Data2/Imram - Saishvari (Full Album) (320 kbps).mp3 Aug 26 17:28:38 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri Aug 26 17:28:38 volumio volumio[1200]: info: CURURI: music-library/NAS/Data2/For Music player Aug 26 17:28:38 volumio volumio[1200]: info: Preload queue cleared Aug 26 17:28:41 volumio volumio[1200]: info: Preload queue cleared Aug 26 17:28:41 volumio volumio[1200]: info: CoreCommandRouter::volumioReplaceandPlayItems Aug 26 17:28:42 volumio volumio[1200]: info: CoreStateMachine::ClearQueue Aug 26 17:28:42 volumio volumio[1200]: info: CoreStateMachine::stop Aug 26 17:28:42 volumio volumio[1200]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 26 17:28:42 volumio volumio[1200]: info: CoreStateMachine::stPlaybackTimer Aug 26 17:28:42 volumio volumio[1200]: info: CoreStateMachine::updateTrackBlock Aug 26 17:28:42 volumio volumio[1200]: info: CorePlayQueue::getTrackBlock Aug 26 17:28:42 volumio volumio[1200]: info: CoreStateMachine::pushState Aug 26 17:28:42 volumio volumio[1200]: info: CorePlayQueue::getTrack 0 Aug 26 17:28:42 volumio volumio[1200]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 26 17:28:42 volumio volumio[1200]: info: CoreCommandRouter::volumioPushState Aug 26 17:28:42 volumio volumio[1200]: info: CoreStateMachine::serviceStop Aug 26 17:28:42 volumio volumio[1200]: info: CorePlayQueue::getTrack 0 Aug 26 17:28:42 volumio volumio[1200]: info: CoreCommandRouter::serviceStop Aug 26 17:28:42 volumio volumio[1200]: info: [1787754522077] ControllerWebradio::stop Aug 26 17:28:42 volumio volumio[1200]: verbose: ControllerMpd::sendMpdCommand stop Aug 26 17:28:42 volumio volumio[1200]: info: CorePlayQueue::clearPlayQueue Aug 26 17:28:42 volumio volumio[1200]: info: CorePlayQueue::saveQueue Aug 26 17:28:42 volumio volumio[1200]: info: CoreCommandRouter::volumioPushQueue Aug 26 17:28:42 volumio volumio[1200]: info: CoreStateMachine::addQueueItems Aug 26 17:28:42 volumio volumio[1200]: info: CorePlayQueue::addQueueItems Aug 26 17:28:42 volumio volumio[1200]: info: Preload queue cleared Aug 26 17:28:42 volumio volumio[1200]: info: Adding Item to queue: music-library/NAS/Data2/For Music player/Adele - Greatest Hits [2012] Aug 26 17:28:42 volumio volumio[1200]: info: Exploding uri music-library/NAS/Data2/For Music player/Adele - Greatest Hits [2012] in service mpd Aug 26 17:28:42 volumio volumio[1200]: SPOTIFY: RECEIVED VOLUMIO VOLUME 90 Aug 26 17:28:42 volumio volumio[1200]: SPOTIFY: SPOTIFY VOLUME 91 Aug 26 17:28:42 volumio volumio[1200]: SPOTIFY: VOLUMIO VOLUME 90 Aug 26 17:28:42 volumio volumio[1200]: SPOTIFY: DELTA VOLUME ENOUGH: false Aug 26 17:28:42 volumio volumio[1200]: info: Aug 26 17:28:42 volumio volumio[1200]: ---------------------------- MPD announces state update: player Aug 26 17:28:42 volumio volumio[1200]: info: ALBUMART /albumart?cacheid=400&web=Adele/Greatest%20Hits%20%5BCD%5D/extralarge&path=%2Fmnt%2FNAS%2FData2%2FFor%20Music%20player%2FAdele%20-%20Greatest%20Hits%20%5B2012%5D%2FCD%2FAdele%20-%20Greatest%20Hits%20%5BCD%5D.cue&metadata=false Aug 26 17:28:42 volumio volumio[1200]: info: URI /mnt/NAS/Data2/For Music player/Adele - Greatest Hits [2012]/CD/Adele - Greatest Hits [CD].cue Aug 26 17:28:42 volumio volumio[1200]: info: ALBUMART /albumart?cacheid=400&web=Adele/Greatest%20Hits%20%5BCD%5D/extralarge&path=%2Fmnt%2FNAS%2FData2%2FFor%20Music%20player%2FAdele%20-%20Greatest%20Hits%20%5B2012%5D%2FCD%2FAdele%20-%20Greatest%20Hits%20%5BCD%5D.cue&metadata=false Aug 26 17:28:42 volumio volumio[1200]: info: URI /mnt/NAS/Data2/For Music player/Adele - Greatest Hits [2012]/CD/Adele - Greatest Hits [CD].cue Aug 26 17:28:42 volumio volumio[1200]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 26 17:28:42 volumio volumio[1200]: Error: Unable to resolve or reject the same promise twice Aug 26 17:28:42 volumio volumio[1200]: at Promise.resolve (/volumio/node_modules/kew/kew.js:140:43) Aug 26 17:28:42 volumio volumio[1200]: at /volumio/app/plugins/music_service/mpd/index.js:2582:21 Aug 26 17:28:42 volumio volumio[1200]: at MpdClient.handleMessage (/volumio/app/plugins/music_service/mpd/lib/mpd.js:77:3) Aug 26 17:28:42 volumio volumio[1200]: at MpdClient.receive (/volumio/app/plugins/music_service/mpd/lib/mpd.js:68:12) Aug 26 17:28:42 volumio volumio[1200]: at Socket. (/volumio/app/plugins/music_service/mpd/lib/mpd.js:43:12) Aug 26 17:28:42 volumio volumio[1200]: at Socket.emit (node:events:514:28) Aug 26 17:28:42 volumio volumio[1200]: at addChunk (node:internal/streams/readable:343:12) Aug 26 17:28:42 volumio volumio[1200]: at readableAddChunk (node:internal/streams/readable:312:11) Aug 26 17:28:42 volumio volumio[1200]: at Readable.push (node:internal/streams/readable:253:10) Aug 26 17:28:42 volumio volumio[1200]: at Pipe.onStreamRead (node:internal/stream_base_commons:190:23) Aug 26 17:28:42 volumio volumio[1200]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 26 17:28:49 volumio sudo[2952]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-08-26 17:27' Aug 26 17:28:49 volumio sudo[2952]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) PRETTY_NAME="Raspbian GNU/Linux 12 (bookworm)" NAME="Raspbian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="18952480e8d8c63f22208e9007a0f47a9563eae6" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="0e58f1861fa88e02087981b8d91f7511f0e7011b" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue Mar 24 17:20:52 UTC 2026" VOLUMIO_VERSION="4.119" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="d0c2fd9dbc5e70e58c32413c12353563"