Mar 28 19:48:00 volumio volumio5-onboarding[1655]: time=2026-03-28T19:48:00.047+01:00 level=INFO msg="service successfully established" component=discovery/localnet Mar 28 19:48:00 volumio volumio-remote-updater[754]: [2026-03-28 19:48:00] [connect] Successful connection Mar 28 19:48:00 volumio volumio-remote-updater[754]: [2026-03-28 19:48:00] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1774723680 101 Mar 28 19:48:00 volumio volumio[2545]: 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: 4 Mar 28 19:48:00 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 8. Mar 28 19:48:00 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 28 19:48:00 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 28 19:48:00 volumio go-librespot[3055]: go-librespot daemon starting... Mar 28 19:48:00 volumio go-librespot[3056]: time="2026-03-28T19:48:00+01:00" level=info msg="running go-librespot 0.7.1" Mar 28 19:48:00 volumio go-librespot[3056]: time="2026-03-28T19:48:00+01:00" level=debug msg="app state loaded" Mar 28 19:48:00 volumio go-librespot[3056]: time="2026-03-28T19:48:00+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 28 19:48:00 volumio go-librespot[3056]: time="2026-03-28T19:48:00+01:00" level=fatal msg="failed running with username and spotify token" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": dial tcp: lookup apresolve.spotify.com: device or resource busy" Mar 28 19:48:00 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 28 19:48:00 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 28 19:48:01 volumio volumio[2545]: info: Initializing connection to go-librespot Websocket Mar 28 19:48:01 volumio volumio[2545]: info: Error connecting to go-librespot Websocket: AggregateError Mar 28 19:48:01 volumio volumio[2545]: info: Cannot call home: Error: Command failed: /usr/bin/curl -X POST --data-binary "device=pi&variante=volumio&version=4.119&uuid=b36084302a76a9c9561f9ed669915103" http://updates.volumio.org/downloader-v1/track-device Mar 28 19:48:01 volumio volumio[2545]: % Total % Received % Xferd Average Speed Time Time Time Current Mar 28 19:48:01 volumio volumio[2545]: Dload Upload Total Spent Left Speed Mar 28 19:48:01 volumio volumio[2545]: [132B blob data] Mar 28 19:48:01 volumio volumio[2545]: retrying in 5 seconds, trial 0 Mar 28 19:48:01 volumio volumio[2545]: info: Volumio Calling Home Mar 28 19:48:01 volumio sudo[3050]: pam_unix(sudo:session): session closed for user root Mar 28 19:48:01 volumio wireless.js[757]: WIRELESS.JS - INFO: SETTING APPROPRIATE REG DOMAIN: EU Mar 28 19:48:01 volumio sudo[3068]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iw reg set EU Mar 28 19:48:01 volumio sudo[3068]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 19:48:01 volumio sudo[3068]: pam_unix(sudo:session): session closed for user root Mar 28 19:48:01 volumio wireless.js[757]: WIRELESS.JS - INFO: SUCCESSFULLY SET NEW REGDOMAIN: EU Mar 28 19:48:01 volumio wireless.js[757]: WIRELESS.JS - INFO: Start wireless flow Mar 28 19:48:02 volumio wireless.js[757]: WIRELESS.JS - INFO: Stopped hotspot (if there).. Mar 28 19:48:02 volumio sudo[3078]: root : PWD=/ ; USER=root ; COMMAND=/sbin/ip addr flush dev wlan0 Mar 28 19:48:02 volumio sudo[3078]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Mar 28 19:48:02 volumio sudo[3078]: pam_unix(sudo:session): session closed for user root Mar 28 19:48:02 volumio sudo[3080]: root : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 down Mar 28 19:48:02 volumio sudo[3080]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Mar 28 19:48:02 volumio sudo[3080]: pam_unix(sudo:session): session closed for user root Mar 28 19:48:02 volumio volumio[2545]: info: Received Get System Info Mar 28 19:48:02 volumio volumio[2545]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 28 19:48:02 volumio volumio[2545]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 28 19:48:02 volumio volumio[2545]: info: Discovery: Getting this device information Mar 28 19:48:02 volumio volumio[2545]: info: CoreCommandRouter::volumioGetState Mar 28 19:48:02 volumio volumio[2545]: info: CorePlayQueue::getTrack 0 Mar 28 19:48:02 volumio volumio[2545]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 28 19:48:02 volumio volumio[2545]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Mar 28 19:48:02 volumio volumio[2545]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Mar 28 19:48:02 volumio wireless.js[757]: WIRELESS.JS - INFO: InterfaceValidator: READY - wlan0 is ready for operations Mar 28 19:48:02 volumio wireless.js[757]: WIRELESS.JS - INFO: STAGE 1: wlan0 validated and ready (MAC: b8:27:eb:a9:63:ec, USB: false) Mar 28 19:48:03 volumio volumio[2545]: info: Received Get System Info Mar 28 19:48:03 volumio volumio[2545]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 28 19:48:03 volumio volumio[2545]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 28 19:48:03 volumio volumio[2545]: info: Discovery: Getting this device information Mar 28 19:48:03 volumio volumio[2545]: info: CoreCommandRouter::volumioGetState Mar 28 19:48:03 volumio volumio[2545]: info: CorePlayQueue::getTrack 0 Mar 28 19:48:03 volumio volumio[2545]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 28 19:48:03 volumio volumio[2545]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Mar 28 19:48:03 volumio volumio[2545]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Mar 28 19:48:03 volumio wpa_supplicant[3086]: Successfully initialized wpa_supplicant Mar 28 19:48:03 volumio kernel: brcmfmac: brcmf_cfg80211_set_power_mgmt: power save disabled Mar 28 19:48:03 volumio dhcpcd[808]: eth0: carrier acquired Mar 28 19:48:03 volumio ifplugd(eth0)[976]: Link beat detected. Mar 28 19:48:03 volumio kernel: lan78xx 1-1.1.1:1.0 eth0: Link is Up - 1Gbps/Full - flow control rx/tx Mar 28 19:48:03 volumio dhcpcd[808]: eth0: IAID eb:fc:36:b9 Mar 28 19:48:03 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 9. Mar 28 19:48:03 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 28 19:48:03 volumio ifplugd(eth0)[976]: Executing '/etc/ifplugd/ifplugd.action eth0 up'. Mar 28 19:48:03 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 28 19:48:03 volumio go-librespot[3088]: go-librespot daemon starting... Mar 28 19:48:03 volumio wpa_supplicant[3086]: nl80211: kernel reports: Registration to specific type not supported Mar 28 19:48:03 volumio go-librespot[3094]: time="2026-03-28T19:48:03+01:00" level=info msg="running go-librespot 0.7.1" Mar 28 19:48:03 volumio go-librespot[3094]: time="2026-03-28T19:48:03+01:00" level=debug msg="app state loaded" Mar 28 19:48:03 volumio go-librespot[3094]: time="2026-03-28T19:48:03+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 28 19:48:03 volumio go-librespot[3094]: time="2026-03-28T19:48:03+01:00" level=fatal msg="failed running with username and spotify token" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": dial tcp: lookup apresolve.spotify.com: device or resource busy" Mar 28 19:48:03 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 28 19:48:03 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 28 19:48:04 volumio sudo[3116]: root : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 up Mar 28 19:48:04 volumio sudo[3116]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Mar 28 19:48:04 volumio dhcpcd[808]: control command: dhcpcd eth0 Mar 28 19:48:04 volumio sudo[3116]: pam_unix(sudo:session): session closed for user root Mar 28 19:48:04 volumio ifplugd(eth0)[976]: client: sending commands to dhcpcd process Mar 28 19:48:04 volumio volumio[2545]: info: Received Get System Info Mar 28 19:48:04 volumio dhcpcd[808]: control_free: No such file or directory Mar 28 19:48:04 volumio dhcpcd[808]: eth0: soliciting an IPv6 router Mar 28 19:48:04 volumio volumio[2545]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 28 19:48:04 volumio volumio[2545]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 28 19:48:04 volumio volumio[2545]: info: Discovery: Getting this device information Mar 28 19:48:04 volumio volumio[2545]: info: CoreCommandRouter::volumioGetState Mar 28 19:48:04 volumio volumio[2545]: info: CorePlayQueue::getTrack 0 Mar 28 19:48:04 volumio volumio[2545]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 28 19:48:04 volumio volumio[2545]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Mar 28 19:48:04 volumio volumio[2545]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Mar 28 19:48:04 volumio volumio[2545]: info: Initializing connection to go-librespot Websocket Mar 28 19:48:04 volumio volumio[2545]: info: Received Get System Info Mar 28 19:48:04 volumio volumio[2545]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 28 19:48:04 volumio volumio[2545]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 28 19:48:04 volumio volumio[2545]: info: Discovery: Getting this device information Mar 28 19:48:04 volumio volumio[2545]: info: CoreCommandRouter::volumioGetState Mar 28 19:48:04 volumio volumio[2545]: info: CorePlayQueue::getTrack 0 Mar 28 19:48:04 volumio volumio[2545]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 28 19:48:04 volumio volumio[2545]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Mar 28 19:48:04 volumio volumio[2545]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Mar 28 19:48:04 volumio volumio[2545]: info: Error connecting to go-librespot Websocket: AggregateError Mar 28 19:48:04 volumio ifplugd(eth0)[976]: Program executed successfully. Mar 28 19:48:05 volumio wpa_supplicant[3110]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=CORE type=WORLD Mar 28 19:48:05 volumio wireless.js[757]: WIRELESS.JS - INFO: DHCP IP fallback Mar 28 19:48:05 volumio wireless.js[757]: WIRELESS.JS - INFO: STAGE 2: Starting event-driven WPA state monitor Mar 28 19:48:05 volumio wireless.js[757]: WIRELESS.JS - INFO: WpaStateMachine: Starting state monitor for wlan0 Mar 28 19:48:05 volumio wireless.js[757]: WIRELESS.JS - INFO: === SNM TRANSITION === Mar 28 19:48:05 volumio wireless.js[757]: WIRELESS.JS - INFO: Previous ethernet state: disconnected Mar 28 19:48:05 volumio wireless.js[757]: WIRELESS.JS - INFO: New ethernet state: connected Mar 28 19:48:05 volumio wireless.js[757]: WIRELESS.JS - INFO: Single Network Mode: enabled Mar 28 19:48:05 volumio wireless.js[757]: WIRELESS.JS - INFO: First start: no Mar 28 19:48:05 volumio wireless.js[757]: WIRELESS.JS - INFO: Action: Switch to ethernet (WiFi scan mode) Mar 28 19:48:05 volumio wireless.js[757]: WIRELESS.JS - INFO: === END TRANSITION === Mar 28 19:48:05 volumio wireless.js[757]: WIRELESS.JS - INFO: SNM: Ethernet connected, switching to ethernet (WiFi scan mode) Mar 28 19:48:05 volumio sudo[3181]: root : PWD=/ ; USER=root ; COMMAND=/sbin/dhcpcd -k wlan0 Mar 28 19:48:05 volumio sudo[3181]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Mar 28 19:48:05 volumio dhcpcd[3182]: dhcpcd not running Mar 28 19:48:05 volumio sudo[3181]: pam_unix(sudo:session): session closed for user root Mar 28 19:48:05 volumio wireless.js[757]: dhcpcd not running Mar 28 19:48:05 volumio wireless.js[757]: WIRELESS.JS - INFO: Wireless.js initializing wireless flow Mar 28 19:48:05 volumio wpa_supplicant[3110]: p2p-dev-wlan0: CTRL-EVENT-DSCP-POLICY clear_all Mar 28 19:48:05 volumio wpa_supplicant[3110]: p2p-dev-wlan0: CTRL-EVENT-DSCP-POLICY clear_all Mar 28 19:48:05 volumio wpa_supplicant[3110]: nl80211: deinit ifname=p2p-dev-wlan0 disabled_11b_rates=0 Mar 28 19:48:05 volumio wpa_supplicant[3110]: p2p-dev-wlan0: CTRL-EVENT-TERMINATING Mar 28 19:48:05 volumio wpa_supplicant[3110]: wlan0: CTRL-EVENT-DSCP-POLICY clear_all Mar 28 19:48:05 volumio dhcpcd[808]: eth0: rebinding lease of 192.168.0.32 Mar 28 19:48:05 volumio wpa_supplicant[3110]: wlan0: CTRL-EVENT-DSCP-POLICY clear_all Mar 28 19:48:05 volumio wpa_supplicant[3110]: nl80211: deinit ifname=wlan0 disabled_11b_rates=0 Mar 28 19:48:06 volumio wpa_supplicant[3110]: wlan0: CTRL-EVENT-TERMINATING Mar 28 19:48:06 volumio volumio[2545]: info: Received Get System Info Mar 28 19:48:06 volumio volumio[2545]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 28 19:48:06 volumio volumio[2545]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 28 19:48:06 volumio volumio[2545]: info: Discovery: Getting this device information Mar 28 19:48:06 volumio volumio[2545]: info: CoreCommandRouter::volumioGetState Mar 28 19:48:06 volumio volumio[2545]: info: CorePlayQueue::getTrack 0 Mar 28 19:48:06 volumio volumio[2545]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 28 19:48:06 volumio volumio[2545]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Mar 28 19:48:06 volumio volumio[2545]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Mar 28 19:48:06 volumio dhcpcd[808]: eth0: probing address 192.168.0.32/24 Mar 28 19:48:06 volumio volumio[2545]: info: Received Get System Info Mar 28 19:48:06 volumio volumio[2545]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 28 19:48:06 volumio volumio[2545]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 28 19:48:06 volumio volumio[2545]: info: Discovery: Getting this device information Mar 28 19:48:06 volumio volumio[2545]: info: CoreCommandRouter::volumioGetState Mar 28 19:48:06 volumio volumio[2545]: info: CorePlayQueue::getTrack 0 Mar 28 19:48:06 volumio volumio[2545]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 28 19:48:06 volumio volumio[2545]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Mar 28 19:48:06 volumio volumio[2545]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Mar 28 19:48:07 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 10. Mar 28 19:48:07 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 28 19:48:07 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 28 19:48:07 volumio go-librespot[3194]: go-librespot daemon starting... Mar 28 19:48:07 volumio go-librespot[3195]: time="2026-03-28T19:48:07+01:00" level=info msg="running go-librespot 0.7.1" Mar 28 19:48:07 volumio go-librespot[3195]: time="2026-03-28T19:48:07+01:00" level=debug msg="app state loaded" Mar 28 19:48:07 volumio go-librespot[3195]: time="2026-03-28T19:48:07+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 28 19:48:07 volumio go-librespot[3195]: time="2026-03-28T19:48:07+01:00" level=fatal msg="failed running with username and spotify token" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": dial tcp: lookup apresolve.spotify.com: device or resource busy" Mar 28 19:48:07 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 28 19:48:07 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 28 19:48:07 volumio volumio[2545]: info: Initializing connection to go-librespot Websocket Mar 28 19:48:07 volumio volumio[2545]: info: Error connecting to go-librespot Websocket: AggregateError Mar 28 19:48:07 volumio wireless.js[757]: WIRELESS.JS - INFO: STAGE 2: Connection failed - wpa_supplicant error or crash Mar 28 19:48:07 volumio wireless.js[757]: WIRELESS.JS - INFO: STAGE 2: Failure details: wpa_supplicant not responding Mar 28 19:48:07 volumio wireless.js[757]: WIRELESS.JS - INFO: STAGE 2: Skipping afterAPStart loop, proceeding directly to hotspot evaluation Mar 28 19:48:07 volumio wireless.js[757]: WIRELESS.JS - INFO: Start ap Mar 28 19:48:07 volumio wireless.js[757]: WIRELESS.JS - INFO: STAGE 2: Connection already failed, skipping polling loop Mar 28 19:48:07 volumio wireless.js[757]: WIRELESS.JS - INFO: STAGE 2: Evaluating hotspot condition directly Mar 28 19:48:07 volumio sudo[3206]: root : PWD=/ ; USER=root ; COMMAND=/sbin/iw wlan0 scan Mar 28 19:48:07 volumio sudo[3206]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Mar 28 19:48:07 volumio sudo[3206]: pam_unix(sudo:session): session closed for user root Mar 28 19:48:07 volumio wireless.js[757]: command failed: Network is down (-100) Mar 28 19:48:07 volumio wireless.js[757]: WIRELESS.JS - INFO: No concurrent mode. Stopping STA and starting hotspot. Mar 28 19:48:07 volumio wireless.js[757]: WIRELESS.JS - INFO: Notified systemd about wireless ready Mar 28 19:48:08 volumio sudo[3217]: root : PWD=/ ; USER=root ; COMMAND=/sbin/ip addr flush dev wlan0 Mar 28 19:48:08 volumio sudo[3217]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Mar 28 19:48:08 volumio sudo[3217]: pam_unix(sudo:session): session closed for user root Mar 28 19:48:08 volumio sudo[3219]: root : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 down Mar 28 19:48:08 volumio sudo[3219]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Mar 28 19:48:08 volumio sudo[3219]: pam_unix(sudo:session): session closed for user root Mar 28 19:48:08 volumio wireless.js[757]: WIRELESS.JS - INFO: Cleaning previous... Mar 28 19:48:08 volumio sudo[3222]: root : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 up Mar 28 19:48:08 volumio sudo[3222]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Mar 28 19:48:08 volumio sudo[3222]: pam_unix(sudo:session): session closed for user root Mar 28 19:48:08 volumio kernel: brcmfmac: brcmf_cfg80211_set_power_mgmt: power save disabled Mar 28 19:48:08 volumio wireless.js[757]: WIRELESS.JS - INFO: InterfaceValidator: READY - wlan0 is ready for operations Mar 28 19:48:08 volumio wireless.js[757]: WIRELESS.JS - INFO: InterfaceValidator: wlan0 became ready after 1ms Mar 28 19:48:08 volumio wireless.js[757]: WIRELESS.JS - INFO: ensureInterfaceReady: Interface ready (MAC: b8:27:eb:a9:63:ec) Mar 28 19:48:08 volumio systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 14. Mar 28 19:48:08 volumio systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Mar 28 19:48:08 volumio sudo[3229]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iw reg get Mar 28 19:48:08 volumio sudo[3229]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 19:48:08 volumio systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Mar 28 19:48:08 volumio upmpdcli[3230]: Could not open config: /tmp/upmpdcli.conf Mar 28 19:48:08 volumio sudo[3229]: pam_unix(sudo:session): session closed for user root Mar 28 19:48:08 volumio systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Mar 28 19:48:08 volumio systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Mar 28 19:48:08 volumio sudo[3238]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iw wlan0 scan Mar 28 19:48:08 volumio sudo[3238]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 19:48:08 volumio volumio[2545]: info: Received Get System Info Mar 28 19:48:08 volumio volumio[2545]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 28 19:48:08 volumio volumio[2545]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 28 19:48:08 volumio volumio[2545]: info: Discovery: Getting this device information Mar 28 19:48:08 volumio volumio[2545]: info: CoreCommandRouter::volumioGetState Mar 28 19:48:08 volumio volumio[2545]: info: CorePlayQueue::getTrack 0 Mar 28 19:48:08 volumio volumio[2545]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 28 19:48:08 volumio volumio[2545]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Mar 28 19:48:08 volumio volumio[2545]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Mar 28 19:48:08 volumio volumio5-onboarding[1655]: time=2026-03-28T19:48:08.732+01:00 level=INFO msg="service successfully established" component=discovery/localnet Mar 28 19:48:09 volumio volumio5-onboarding[1655]: time=2026-03-28T19:48:09.736+01:00 level=INFO msg="service successfully established" component=discovery/localnet Mar 28 19:48:10 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 11. Mar 28 19:48:10 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 28 19:48:10 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 28 19:48:10 volumio go-librespot[3242]: go-librespot daemon starting... Mar 28 19:48:10 volumio volumio[2545]: info: Initializing connection to go-librespot Websocket Mar 28 19:48:10 volumio go-librespot[3243]: time="2026-03-28T19:48:10+01:00" level=info msg="running go-librespot 0.7.1" Mar 28 19:48:10 volumio go-librespot[3243]: time="2026-03-28T19:48:10+01:00" level=debug msg="app state loaded" Mar 28 19:48:10 volumio volumio[2545]: info: Error connecting to go-librespot Websocket: AggregateError Mar 28 19:48:10 volumio go-librespot[3243]: time="2026-03-28T19:48:10+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 28 19:48:10 volumio go-librespot[3243]: time="2026-03-28T19:48:10+01:00" level=fatal msg="failed running with username and spotify token" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": dial tcp: lookup apresolve.spotify.com: device or resource busy" Mar 28 19:48:10 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 28 19:48:10 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 28 19:48:11 volumio sudo[3238]: pam_unix(sudo:session): session closed for user root Mar 28 19:48:11 volumio wireless.js[757]: WIRELESS.JS - INFO: SETTING APPROPRIATE REG DOMAIN: EU Mar 28 19:48:11 volumio sudo[3253]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iw reg set EU Mar 28 19:48:11 volumio sudo[3253]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 19:48:11 volumio sudo[3253]: pam_unix(sudo:session): session closed for user root Mar 28 19:48:11 volumio wireless.js[757]: WIRELESS.JS - INFO: SUCCESSFULLY SET NEW REGDOMAIN: EU Mar 28 19:48:11 volumio wireless.js[757]: WIRELESS.JS - INFO: Single Network Mode: Ethernet active, maintaining WiFi scan capability Mar 28 19:48:11 volumio wireless.js[757]: WIRELESS.JS - INFO: SNM: Maintaining wlan0 UP without IP (scan mode) Mar 28 19:48:11 volumio wireless.js[757]: WIRELESS.JS - INFO: SNM: Users can configure WiFi via WebUI while ethernet is active Mar 28 19:48:11 volumio volumio[2545]: info: Received Get System Info Mar 28 19:48:11 volumio volumio[2545]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 28 19:48:11 volumio volumio[2545]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 28 19:48:11 volumio volumio[2545]: info: Discovery: Getting this device information Mar 28 19:48:11 volumio volumio[2545]: info: CoreCommandRouter::volumioGetState Mar 28 19:48:11 volumio volumio[2545]: info: CorePlayQueue::getTrack 0 Mar 28 19:48:11 volumio volumio[2545]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 28 19:48:11 volumio volumio[2545]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Mar 28 19:48:11 volumio volumio[2545]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Mar 28 19:48:11 volumio volumio[2545]: info: Cannot call home: Error: Command failed: /usr/bin/curl -X POST --data-binary "device=pi&variante=volumio&version=4.119&uuid=b36084302a76a9c9561f9ed669915103" http://updates.volumio.org/downloader-v1/track-device Mar 28 19:48:11 volumio volumio[2545]: % Total % Received % Xferd Average Speed Time Time Time Current Mar 28 19:48:11 volumio volumio[2545]: Dload Upload Total Spent Left Speed Mar 28 19:48:11 volumio volumio[2545]: [132B blob data] Mar 28 19:48:11 volumio volumio[2545]: retrying in 5 seconds, trial 1 Mar 28 19:48:11 volumio volumio[2545]: info: Volumio Calling Home Mar 28 19:48:12 volumio sudo[3265]: root : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 up Mar 28 19:48:12 volumio sudo[3265]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Mar 28 19:48:12 volumio sudo[3265]: pam_unix(sudo:session): session closed for user root Mar 28 19:48:12 volumio sudo[3270]: root : PWD=/ ; USER=root ; COMMAND=/sbin/ip addr flush dev wlan0 Mar 28 19:48:12 volumio sudo[3270]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Mar 28 19:48:12 volumio sudo[3270]: pam_unix(sudo:session): session closed for user root Mar 28 19:48:12 volumio wpa_supplicant[3273]: Successfully initialized wpa_supplicant Mar 28 19:48:12 volumio wpa_supplicant[3273]: nl80211: kernel reports: Registration to specific type not supported Mar 28 19:48:12 volumio wpa_supplicant[3277]: wlan0: CTRL-EVENT-DSCP-POLICY clear_all Mar 28 19:48:12 volumio dhcpcd[808]: eth0: leased 192.168.0.32 for 3600 seconds Mar 28 19:48:12 volumio avahi-daemon[730]: Joining mDNS multicast group on interface eth0.IPv4 with address 192.168.0.32. Mar 28 19:48:12 volumio avahi-daemon[730]: New relevant interface eth0.IPv4 for mDNS. Mar 28 19:48:12 volumio avahi-daemon[730]: Registering new address record for 192.168.0.32 on eth0.IPv4. Mar 28 19:48:12 volumio dhcpcd[808]: eth0: adding route to 192.168.0.0/24 Mar 28 19:48:12 volumio dhcpcd[808]: eth0: adding default route via 192.168.0.1 Mar 28 19:48:12 volumio wireless.js[757]: WIRELESS.JS - INFO: SNM: Transition to scan mode completed in 7205ms Mar 28 19:48:12 volumio wireless.js[757]: WIRELESS.JS - INFO: SNM: wlan0 is UP without IP, scan capable Mar 28 19:48:12 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Mar 28 19:48:12 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Mar 28 19:48:12 volumio systemd[1]: welcome.service: Deactivated successfully. Mar 28 19:48:12 volumio systemd[1]: Stopped welcome.service - Show a welcome message on console. Mar 28 19:48:12 volumio systemd[1]: Stopping welcome.service - Show a welcome message on console... Mar 28 19:48:12 volumio systemd[1]: Starting welcome.service - Show a welcome message on console... Mar 28 19:48:12 volumio welcome[3296]: Resolved ip:[1] 192.168.0.32 Mar 28 19:48:12 volumio systemd[1]: Finished welcome.service - Show a welcome message on console. Mar 28 19:48:12 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Mar 28 19:48:12 volumio volumio[2545]: info: Received Get System Info Mar 28 19:48:12 volumio volumio[2545]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 28 19:48:12 volumio volumio[2545]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 28 19:48:12 volumio volumio[2545]: info: Discovery: Getting this device information Mar 28 19:48:12 volumio volumio[2545]: info: CoreCommandRouter::volumioGetState Mar 28 19:48:12 volumio volumio[2545]: info: CorePlayQueue::getTrack 0 Mar 28 19:48:12 volumio volumio[2545]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 28 19:48:12 volumio wireless.js[757]: WIRELESS.JS - INFO: Notified systemd about wireless ready Mar 28 19:48:12 volumio volumio[2545]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Mar 28 19:48:12 volumio volumio[2545]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Mar 28 19:48:12 volumio volumio[2545]: info: Received Get System Info Mar 28 19:48:12 volumio volumio[2545]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 28 19:48:12 volumio volumio[2545]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 28 19:48:12 volumio volumio[2545]: info: Discovery: Getting this device information Mar 28 19:48:12 volumio volumio[2545]: info: CoreCommandRouter::volumioGetState Mar 28 19:48:12 volumio volumio[2545]: info: CorePlayQueue::getTrack 0 Mar 28 19:48:12 volumio volumio[2545]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 28 19:48:12 volumio volumio[2545]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Mar 28 19:48:12 volumio volumio[2545]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Mar 28 19:48:13 volumio volumio[2545]: info: Initializing connection to go-librespot Websocket Mar 28 19:48:13 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 12. Mar 28 19:48:13 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 28 19:48:13 volumio volumio[2545]: info: Discovery: this is already registered, 4ab60242-1478-4deb-94e8-dd4f3d76057d Mar 28 19:48:13 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 28 19:48:13 volumio volumio[2545]: info: Discovery: Found device Volumio Mar 28 19:48:13 volumio go-librespot[3317]: go-librespot daemon starting... Mar 28 19:48:13 volumio volumio[2545]: info: CoreCommandRouter::volumioGetState Mar 28 19:48:13 volumio volumio[2545]: info: CorePlayQueue::getTrack 0 Mar 28 19:48:13 volumio go-librespot[3318]: time="2026-03-28T19:48:13+01:00" level=info msg="running go-librespot 0.7.1" Mar 28 19:48:13 volumio volumio[2545]: info: Discovery: this is already registered, 4ab60242-1478-4deb-94e8-dd4f3d76057d Mar 28 19:48:13 volumio go-librespot[3318]: time="2026-03-28T19:48:13+01:00" level=debug msg="app state loaded" Mar 28 19:48:13 volumio volumio[2545]: info: Discovery: Found device Volumio Mar 28 19:48:13 volumio volumio[2545]: info: CoreCommandRouter::volumioGetState Mar 28 19:48:13 volumio volumio[2545]: info: CorePlayQueue::getTrack 0 Mar 28 19:48:13 volumio go-librespot[3318]: time="2026-03-28T19:48:13+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 28 19:48:13 volumio volumio[2545]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 28 19:48:14 volumio ntpd[946]: IO: Listen normally on 4 eth0 192.168.0.32:123 Mar 28 19:48:14 volumio ntpd[946]: IO: new interface(s) found: waking up resolver Mar 28 19:48:14 volumio wpa_supplicant[3277]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=CORE type=WORLD Mar 28 19:48:14 volumio volumio5-onboarding[1655]: time=2026-03-28T19:48:14.860+01:00 level=INFO msg="service successfully established" component=discovery/localnet Mar 28 19:48:15 volumio volumio[2545]: info: Volumio Network Manager: Network status updated: 1 Mar 28 19:48:15 volumio sudo[3343]: root : PWD=/ ; USER=root ; COMMAND=/sbin/ip addr flush dev wlan0 Mar 28 19:48:15 volumio sudo[3343]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Mar 28 19:48:15 volumio sudo[3343]: pam_unix(sudo:session): session closed for user root Mar 28 19:48:15 volumio volumio[2545]: error: MyVolumio Plugin failed to start in a timely fashion Mar 28 19:48:15 volumio volumio[2545]: [Metrics] CommandRouter: 58s 888.00ms Mar 28 19:48:15 volumio volumio[2545]: info: CoreCommandRouter::volumiosetStartupVolume Mar 28 19:48:15 volumio volumio[2545]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 19:48:15 volumio volumio[2545]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 28 19:48:15 volumio sudo[3345]: root : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 down Mar 28 19:48:15 volumio sudo[3345]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Mar 28 19:48:15 volumio volumio[2545]: info: CoreCommandRouter::Close All Modals sent Mar 28 19:48:15 volumio volumio[2545]: info: CoreCommandRouter::Close All Modals sent Mar 28 19:48:15 volumio volumio[2545]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 28 19:48:15 volumio volumio[2545]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 28 19:48:15 volumio volumio[2545]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Mar 28 19:48:15 volumio sudo[3345]: pam_unix(sudo:session): session closed for user root Mar 28 19:48:15 volumio volumio[2545]: info: Received Get System Info Mar 28 19:48:15 volumio volumio[2545]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 28 19:48:15 volumio volumio[2545]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 28 19:48:15 volumio volumio[2545]: info: Discovery: Getting this device information Mar 28 19:48:15 volumio volumio[2545]: info: CoreCommandRouter::volumioGetState Mar 28 19:48:15 volumio volumio[2545]: info: CorePlayQueue::getTrack 0 Mar 28 19:48:15 volumio volumio[2545]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 28 19:48:15 volumio avahi-daemon[730]: Joining mDNS multicast group on interface wlan0.IPv4 with address 192.168.211.1. Mar 28 19:48:15 volumio volumio[2545]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Mar 28 19:48:15 volumio volumio[2545]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Mar 28 19:48:15 volumio kernel: brcmfmac: brcmf_cfg80211_set_power_mgmt: power save disabled Mar 28 19:48:15 volumio avahi-daemon[730]: New relevant interface wlan0.IPv4 for mDNS. Mar 28 19:48:15 volumio avahi-daemon[730]: Registering new address record for 192.168.211.1 on wlan0.IPv4. Mar 28 19:48:15 volumio systemd[1]: welcome.service: Deactivated successfully. Mar 28 19:48:15 volumio systemd[1]: Stopped welcome.service - Show a welcome message on console. Mar 28 19:48:15 volumio systemd[1]: Stopping welcome.service - Show a welcome message on console... Mar 28 19:48:15 volumio systemd[1]: Starting welcome.service - Show a welcome message on console... Mar 28 19:48:15 volumio welcome[3356]: Resolved ip:[2] 192.168.0.32 192.168.211.1 Mar 28 19:48:15 volumio systemd[1]: Starting hostapd.service - Access point and authentication server for Wi-Fi and Ethernet... Mar 28 19:48:15 volumio systemd[1]: Finished welcome.service - Show a welcome message on console. Mar 28 19:48:15 volumio systemd[1]: Reached target ip-changed@wlan0.target - IP Address changed on wlan0. Mar 28 19:48:15 volumio wireless.js[757]: WIRELESS.JS - INFO: Notified systemd about wireless ready Mar 28 19:48:16 volumio dhcpcd[808]: wlan0: carrier acquired Mar 28 19:48:16 volumio hostapd[3364]: wlan0: interface state UNINITIALIZED->ENABLED Mar 28 19:48:16 volumio hostapd[3364]: wlan0: AP-ENABLED Mar 28 19:48:16 volumio systemd[1]: hostapd.service: Can't open PID file /run/hostapd.pid (yet?) after start: No such file or directory Mar 28 19:48:16 volumio systemd[1]: Started hostapd.service - Access point and authentication server for Wi-Fi and Ethernet. Mar 28 19:48:16 volumio dhcpcd[808]: wlan0: IAID eb:a9:63:ec Mar 28 19:48:16 volumio dhcpcd[808]: wlan0: adding address fe80::84b6:9ddf:6477:b1f5 Mar 28 19:48:16 volumio dhcpcd[808]: ipv6_addaddr1: Permission denied Mar 28 19:48:16 volumio volumio[2545]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable Mar 28 19:48:16 volumio volumio[2545]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Mar 28 19:48:16 volumio systemd[1]: Starting dnsmasq.service - dnsmasq - A lightweight DHCP and caching DNS server... Mar 28 19:48:16 volumio volumio[2545]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect Mar 28 19:48:16 volumio dhcpcd[808]: wlan0: soliciting a DHCP lease Mar 28 19:48:16 volumio dnsmasq[3374]: started, version 2.90 cachesize 150 Mar 28 19:48:16 volumio dnsmasq[3374]: compile time options: IPv6 GNU-getopt DBus no-UBus i18n IDN2 DHCP DHCPv6 no-Lua TFTP conntrack ipset nftset auth cryptohash DNSSEC loop-detect inotify dumpfile Mar 28 19:48:16 volumio dnsmasq-dhcp[3374]: DHCP, IP range 192.168.211.100 -- 192.168.211.200, lease time 1d Mar 28 19:48:16 volumio dnsmasq[3374]: reading /etc/resolv.conf Mar 28 19:48:16 volumio dnsmasq[3374]: using nameserver 87.204.204.204#53 Mar 28 19:48:16 volumio dnsmasq[3374]: using nameserver 62.233.233.233#53 Mar 28 19:48:16 volumio dnsmasq[3374]: using nameserver 208.67.222.222#53 Mar 28 19:48:16 volumio dnsmasq[3374]: using nameserver 208.67.220.220#53 Mar 28 19:48:16 volumio dnsmasq[3374]: read /etc/hosts - 16 names Mar 28 19:48:16 volumio systemd[1]: Started dnsmasq.service - dnsmasq - A lightweight DHCP and caching DNS server. Mar 28 19:48:16 volumio systemd[1]: Reached target nss-lookup.target - Host and Network Name Lookups. Mar 28 19:48:16 volumio volumio[2545]: info: Received Get System Info Mar 28 19:48:16 volumio volumio[2545]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 28 19:48:16 volumio volumio[2545]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 28 19:48:16 volumio volumio[2545]: info: Discovery: Getting this device information Mar 28 19:48:16 volumio volumio[2545]: info: CoreCommandRouter::volumioGetState Mar 28 19:48:16 volumio volumio[2545]: info: CorePlayQueue::getTrack 0 Mar 28 19:48:16 volumio volumio[2545]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 28 19:48:16 volumio volumio[2545]: info: Initializing connection to go-librespot Websocket Mar 28 19:48:16 volumio systemd[1]: Stopped target ip-changed@wlan0.target - IP Address changed on wlan0. Mar 28 19:48:16 volumio systemd[1]: Stopping ip-changed@wlan0.target - IP Address changed on wlan0... Mar 28 19:48:16 volumio systemd[1]: welcome.service: Deactivated successfully. Mar 28 19:48:16 volumio systemd[1]: Stopped welcome.service - Show a welcome message on console. Mar 28 19:48:16 volumio systemd[1]: Stopping welcome.service - Show a welcome message on console... Mar 28 19:48:16 volumio volumio[2545]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Mar 28 19:48:16 volumio volumio[2545]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Mar 28 19:48:16 volumio systemd[1]: Starting welcome.service - Show a welcome message on console... Mar 28 19:48:16 volumio welcome[3380]: Resolved ip:[2] 192.168.0.32 192.168.211.1 Mar 28 19:48:16 volumio systemd[1]: Finished welcome.service - Show a welcome message on console. Mar 28 19:48:16 volumio systemd[1]: Reached target ip-changed@wlan0.target - IP Address changed on wlan0. Mar 28 19:48:16 volumio volumio[2545]: info: Discovery: this is already registered, 4ab60242-1478-4deb-94e8-dd4f3d76057d Mar 28 19:48:16 volumio volumio[2545]: info: Discovery: Found device Volumio Mar 28 19:48:16 volumio volumio[2545]: info: CoreCommandRouter::volumioGetState Mar 28 19:48:16 volumio volumio[2545]: info: CorePlayQueue::getTrack 0 Mar 28 19:48:16 volumio volumio[2545]: info: Discovery: this is already registered, 4ab60242-1478-4deb-94e8-dd4f3d76057d Mar 28 19:48:16 volumio volumio[2545]: info: Discovery: Found device Volumio Mar 28 19:48:16 volumio volumio[2545]: info: CoreCommandRouter::volumioGetState Mar 28 19:48:16 volumio volumio[2545]: info: CorePlayQueue::getTrack 0 Mar 28 19:48:16 volumio dhcpcd[808]: wlan0: soliciting an IPv6 router Mar 28 19:48:17 volumio go-librespot[3318]: time="2026-03-28T19:48:17+01:00" level=debug msg="new websocket client" Mar 28 19:48:17 volumio volumio[2545]: info: Connection to go-librespot Websocket established Mar 28 19:48:17 volumio ntpd[946]: IO: Listen normally on 5 wlan0 192.168.211.1:123 Mar 28 19:48:17 volumio ntpd[946]: IO: new interface(s) found: waking up resolver Mar 28 19:48:20 volumio volumio[2545]: info: Getting Spotify volume Mar 28 19:48:20 volumio volumio[2545]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 5 Mar 28 19:48:20 volumio volumio[2545]: info: CoreCommandRouter::volumioGetState Mar 28 19:48:20 volumio volumio[2545]: info: CorePlayQueue::getTrack 0 Mar 28 19:48:20 volumio volumio[2545]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Mar 28 19:48:20 volumio volumio[2545]: SPOTIFY: SPOTIFY VOLUME undefined Mar 28 19:48:20 volumio volumio[2545]: SPOTIFY: VOLUMIO VOLUME 100 Mar 28 19:48:20 volumio volumio[2545]: info: Aligning Spotify Volume to Volumio Volume Mar 28 19:48:20 volumio volumio[2545]: info: CoreCommandRouter::volumioGetState Mar 28 19:48:20 volumio volumio[2545]: info: CorePlayQueue::getTrack 0 Mar 28 19:48:20 volumio volumio[2545]: info: Setting Spotify Volume from Volumio: 100 Mar 28 19:48:22 volumio volumio[2545]: info: BOOT COMPLETED Mar 28 19:48:22 volumio volumio[2545]: info: Cannot call home: Error: Command failed: /usr/bin/curl -X POST --data-binary "device=pi&variante=volumio&version=4.119&uuid=b36084302a76a9c9561f9ed669915103" http://updates.volumio.org/downloader-v1/track-device Mar 28 19:48:22 volumio volumio[2545]: curl: (6) Could not resolve host: updates.volumio.org Mar 28 19:48:22 volumio volumio[2545]: retrying in 5 seconds, trial 2 Mar 28 19:48:22 volumio volumio[2545]: info: Volumio Calling Home Mar 28 19:48:22 volumio volumio[2545]: SPOTIFY: SETTING SPOTIFY VOLUME 100 Mar 28 19:48:22 volumio volumio[2545]: info: Sending Spotify command with payload to local API: /player/volume Mar 28 19:48:22 volumio volumio[2545]: info: Volumio called home Mar 28 19:48:23 volumio systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 15. Mar 28 19:48:23 volumio systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Mar 28 19:48:23 volumio systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Mar 28 19:48:23 volumio upmpdcli[3389]: Could not open config: /tmp/upmpdcli.conf Mar 28 19:48:23 volumio systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Mar 28 19:48:23 volumio systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Mar 28 19:48:23 volumio go-librespot[3318]: time="2026-03-28T19:48:23+01:00" level=fatal msg="failed running with username and spotify token" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": net/http: TLS handshake timeout" Mar 28 19:48:23 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 28 19:48:23 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 28 19:48:23 volumio volumio[2545]: error: Failed to send command to Spotify local API: /player/volume: Error: socket hang up Mar 28 19:48:23 volumio volumio[2545]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 28 19:48:23 volumio volumio[2545]: Error: socket hang up Mar 28 19:48:23 volumio volumio[2545]: at connResetException (node:internal/errors:720:14) Mar 28 19:48:23 volumio volumio[2545]: at Socket.socketOnEnd (node:_http_client:519:23) Mar 28 19:48:23 volumio volumio[2545]: at Socket.emit (node:events:526:35) Mar 28 19:48:23 volumio volumio[2545]: at endReadableNT (node:internal/streams/readable:1376:12) Mar 28 19:48:23 volumio volumio[2545]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { Mar 28 19:48:23 volumio volumio[2545]: code: 'ECONNRESET', Mar 28 19:48:23 volumio volumio[2545]: response: undefined Mar 28 19:48:23 volumio volumio[2545]: } Mar 28 19:48:23 volumio volumio[2545]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 28 19:48:26 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 13. Mar 28 19:48:26 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 28 19:48:26 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 28 19:48:26 volumio go-librespot[3416]: go-librespot daemon starting... Mar 28 19:48:26 volumio go-librespot[3417]: time="2026-03-28T19:48:26+01:00" level=info msg="running go-librespot 0.7.1" Mar 28 19:48:26 volumio go-librespot[3417]: time="2026-03-28T19:48:26+01:00" level=debug msg="app state loaded" Mar 28 19:48:27 volumio go-librespot[3417]: time="2026-03-28T19:48:27+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 28 19:48:30 volumio sudo[3428]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-03-28 19:47' Mar 28 19:48:30 volumio sudo[3428]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 19:48:31 volumio sudo[3428]: pam_unix(sudo:session): session closed for user root Mar 28 19:48:32 volumio volumio-remote-updater[754]: [2026-03-28 19:48:32] [error] handle_read_frame error: asio.system:104 (Connection reset by peer) Mar 28 19:48:32 volumio volumio-remote-updater[754]: [2026-03-28 19:48:32] [disconnect] Disconnect close local:[1006,Connection reset by peer] remote:[1006] Mar 28 19:48:32 volumio systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Mar 28 19:48:32 volumio volumio5-onboarding[1655]: time=2026-03-28T19:48:32.827+01:00 level=ERROR msg="failed reading message" error="read tcp 127.0.0.1:37558->127.0.0.1:3000: read: connection reset by peer" Mar 28 19:48:32 volumio volumio5-onboarding[1655]: time=2026-03-28T19:48:32.830+01:00 level=WARN msg="reconnection attempt failed" error="dial tcp 127.0.0.1:3000: connect: connection refused" Mar 28 19:48:32 volumio systemd[1]: volumio.service: Failed with result 'exit-code'. Mar 28 19:48:32 volumio systemd[1]: volumio.service: Consumed 2min 41.311s CPU time. Mar 28 19:48:33 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Mar 28 19:48:33 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 3. Mar 28 19:48:33 volumio systemd[1]: Stopped volumio.service - Volumio Backend Module. Mar 28 19:48:33 volumio systemd[1]: volumio.service: Consumed 2min 41.311s CPU time. Mar 28 19:48:33 volumio systemd[1]: Started volumio.service - Volumio Backend Module. Mar 28 19:48:33 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Mar 28 19:48:33 volumio volumio5-onboarding[1655]: time=2026-03-28T19:48:33.833+01:00 level=WARN msg="reconnection attempt failed" error="dial tcp 127.0.0.1:3000: connect: connection refused" Mar 28 19:48:34 volumio volumio5-onboarding[1655]: time=2026-03-28T19:48:34.835+01:00 level=WARN msg="reconnection attempt failed" error="dial tcp 127.0.0.1:3000: connect: connection refused" Mar 28 19:48:35 volumio volumio5-onboarding[1655]: time=2026-03-28T19:48:35.838+01:00 level=WARN msg="reconnection attempt failed" error="dial tcp 127.0.0.1:3000: connect: connection refused" Mar 28 19:48:36 volumio volumio[3443]: info: ------------------------------------------- Mar 28 19:48:36 volumio volumio[3443]: info: ----- Volumio3 ---- Mar 28 19:48:36 volumio volumio[3443]: info: ------------------------------------------- Mar 28 19:48:36 volumio volumio[3443]: info: ----- System startup ---- Mar 28 19:48:36 volumio volumio[3443]: info: ------------------------------------------- Mar 28 19:48:37 volumio go-librespot[3417]: time="2026-03-28T19:48:37+01:00" level=fatal msg="failed running with username and spotify token" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": net/http: TLS handshake timeout" Mar 28 19:48:37 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 28 19:48:37 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 28 19:48:37 volumio volumio-remote-updater[754]: [2026-03-28 19:48:37] [connect] Successful connection Mar 28 19:48:38 volumio volumio[3443]: info: MYVOLUMIO Environment detected Mar 28 19:48:38 volumio volumio[3443]: info: Plugin folders cleanup Mar 28 19:48:38 volumio volumio[3443]: info: Scanning into folder /volumio/app/plugins/ Mar 28 19:48:38 volumio volumio[3443]: info: Scanning category audio_interface Mar 28 19:48:38 volumio volumio[3443]: info: Scanning category miscellanea Mar 28 19:48:38 volumio volumio[3443]: info: Scanning category music_service Mar 28 19:48:38 volumio volumio[3443]: info: Scanning category plugins.json Mar 28 19:48:38 volumio volumio[3443]: info: Scanning category system_controller Mar 28 19:48:38 volumio volumio[3443]: info: Scanning category user_interface Mar 28 19:48:38 volumio volumio[3443]: info: Scanning into folder /data/plugins/ Mar 28 19:48:38 volumio volumio[3443]: info: Scanning category music_service Mar 28 19:48:38 volumio volumio[3443]: info: Scanning category user_interface Mar 28 19:48:38 volumio volumio[3443]: info: Scanning category volumio-plugins Mar 28 19:48:38 volumio volumio[3443]: info: Plugin folders cleanup completed Mar 28 19:48:38 volumio volumio[3443]: info: ------------------------------------------- Mar 28 19:48:38 volumio volumio[3443]: info: ----- Core plugins startup ---- Mar 28 19:48:38 volumio volumio[3443]: info: ------------------------------------------- Mar 28 19:48:38 volumio volumio[3443]: info: Loading plugins from folder /volumio/app/plugins/ Mar 28 19:48:38 volumio volumio[3443]: info: Adding plugin upnp to MyMusic Plugins Mar 28 19:48:38 volumio volumio[3443]: info: Adding plugin airplay_emulation to MyMusic Plugins Mar 28 19:48:38 volumio volumio[3443]: info: Adding plugin upnp_browser to MyMusic Plugins Mar 28 19:48:38 volumio volumio[3443]: info: Loading plugins from folder /data/plugins/ Mar 28 19:48:38 volumio volumio[3443]: info: Loading plugin "system"... Mar 28 19:48:38 volumio systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 16. Mar 28 19:48:38 volumio systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Mar 28 19:48:38 volumio volumio[3443]: info: Loading plugin "appearance"... Mar 28 19:48:38 volumio systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Mar 28 19:48:38 volumio upmpdcli[3464]: Could not open config: /tmp/upmpdcli.conf Mar 28 19:48:38 volumio systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Mar 28 19:48:38 volumio systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Mar 28 19:48:40 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 14. Mar 28 19:48:40 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 28 19:48:40 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 28 19:48:40 volumio go-librespot[3469]: go-librespot daemon starting... Mar 28 19:48:40 volumio go-librespot[3470]: time="2026-03-28T19:48:40+01:00" level=info msg="running go-librespot 0.7.1" Mar 28 19:48:40 volumio go-librespot[3470]: time="2026-03-28T19:48:40+01:00" level=debug msg="app state loaded" Mar 28 19:48:40 volumio go-librespot[3470]: time="2026-03-28T19:48:40+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 28 19:48:40 volumio volumio[3443]: info: Loading plugin "network"... Mar 28 19:48:40 volumio volumio[3443]: info: Refreshing Cached IP Addresses Mar 28 19:48:40 volumio sudo[3480]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Mar 28 19:48:40 volumio sudo[3480]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 19:48:40 volumio sudo[3480]: pam_unix(sudo:session): session closed for user root Mar 28 19:48:40 volumio volumio[3443]: info: Loading plugin "services"... Mar 28 19:48:40 volumio volumio[3443]: info: Loading plugin "volumio5onboarding"... Mar 28 19:48:40 volumio sudo[3482]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 28 19:48:40 volumio sudo[3482]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 19:48:41 volumio sudo[3487]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Mar 28 19:48:41 volumio sudo[3487]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 19:48:41 volumio sudo[3482]: pam_unix(sudo:session): session closed for user root Mar 28 19:48:41 volumio volumio[3443]: info: Loading plugin "alsa_controller"... Mar 28 19:48:41 volumio sudo[3487]: pam_unix(sudo:session): session closed for user root Mar 28 19:48:41 volumio kernel: ieee80211 phy0: brcmf_vif_set_mgmt_ie: vndr ie set error : -52 Mar 28 19:48:41 volumio kernel: ieee80211 phy0: brcmf_cfg80211_scan: scan error (-52) Mar 28 19:48:41 volumio volumio[3443]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 28 19:48:41 volumio volumio[3443]: info: Loading plugin "wizard"... Mar 28 19:48:41 volumio volumio[3443]: info: Loading plugin "networkfs"... Mar 28 19:48:41 volumio volumio[3443]: info: Starting Udev Watcher for removable devices Mar 28 19:48:41 volumio volumio[3443]: info: Ignoring mount for partition: boot Mar 28 19:48:41 volumio volumio[3443]: info: Ignoring mount for partition: volumio Mar 28 19:48:41 volumio volumio[3443]: info: Ignoring mount for partition: volumio_data Mar 28 19:48:41 volumio volumio[3443]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Mar 28 19:48:41 volumio volumio[3443]: info: Loading plugin "volumio_command_line_client"... Mar 28 19:48:41 volumio volumio[3443]: info: Plugin upnp is not enabled Mar 28 19:48:41 volumio volumio[3443]: info: Loading plugin "my_music"... Mar 28 19:48:41 volumio volumio[3443]: info: Loading plugin "mpd"... Mar 28 19:48:41 volumio volumio[3443]: info: Plugin upnp_browser is not enabled Mar 28 19:48:41 volumio volumio[3443]: info: Loading plugin "alarm-clock"... Mar 28 19:48:42 volumio volumio[3443]: info: Plugin airplay_emulation is not enabled Mar 28 19:48:42 volumio volumio[3443]: info: Loading plugin "last_100"... Mar 28 19:48:42 volumio volumio[3443]: info: Loading plugin "webradio"... Mar 28 19:48:43 volumio volumio[3443]: info: Loading plugin "i2s_dacs"... Mar 28 19:48:43 volumio volumio[3443]: info: Loading plugin "volumiodiscovery"... Mar 28 19:48:43 volumio volumio[3443]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Mar 28 19:48:43 volumio volumio[3443]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 28 19:48:43 volumio volumio[3443]: *** WARNING *** For more information see Mar 28 19:48:43 volumio volumio[3443]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Mar 28 19:48:43 volumio volumio[3443]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 28 19:48:43 volumio volumio[3443]: *** WARNING *** For more information see Mar 28 19:48:43 volumio node[3443]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Mar 28 19:48:43 volumio node[3443]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 28 19:48:43 volumio node[3443]: *** WARNING *** For more information see Mar 28 19:48:43 volumio node[3443]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Mar 28 19:48:43 volumio node[3443]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 28 19:48:43 volumio node[3443]: *** WARNING *** For more information see Mar 28 19:48:43 volumio volumio[3443]: info: Applying required configuration parameters for plugin volumiodiscovery Mar 28 19:48:43 volumio volumio[3443]: info: Discovery: Started advertising with name: Volumio Mar 28 19:48:43 volumio volumio[3443]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Mar 28 19:48:43 volumio volumio[3443]: info: Loading plugin "spop"... Mar 28 19:48:46 volumio volumio[3443]: info: Loading plugin "now_playing"... Mar 28 19:48:46 volumio volumio5-onboarding[1655]: time=2026-03-28T19:48:46.840+01:00 level=WARN msg="reconnection attempt failed" error="read tcp 127.0.0.1:43298->127.0.0.1:3000: i/o timeout" Mar 28 19:48:48 volumio volumio[3443]: info: Loading plugin "outputs"... Mar 28 19:48:48 volumio volumio[3443]: info: Loading plugin "albumart"... Mar 28 19:48:48 volumio volumio[3443]: info: Plugin example_plugin is not enabled Mar 28 19:48:48 volumio volumio[3443]: info: Loading plugin "inputs"... Mar 28 19:48:48 volumio volumio[3443]: info: Loading plugin "updater_comm"... Mar 28 19:48:48 volumio volumio[3443]: info: Plugin mpdemulation is not enabled Mar 28 19:48:48 volumio volumio[3443]: info: Loading plugin "rest_api"... Mar 28 19:48:48 volumio volumio[3443]: info: Loading plugin "websocket"... Mar 28 19:48:49 volumio volumio[3443]: info: Starting Socket.io Server version 1.7.4 Mar 28 19:48:49 volumio volumio[3443]: info: Loading plugin "touch_display"... Mar 28 19:48:49 volumio volumio[3443]: info: Applying required configuration parameters for plugin touch_display Mar 28 19:48:49 volumio volumio[3443]: info: Plugin example_plugin is not enabled Mar 28 19:48:50 volumio volumio[3443]: info: Loading i18n strings for locale pl Mar 28 19:48:50 volumio volumio[3443]: error: touch_display: Fetching language file: Error: i18n file complementing the system language not found. Mar 28 19:48:50 volumio volumio[3443]: Updating browse sources language Mar 28 19:48:50 volumio volumio[3443]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 28 19:48:50 volumio volumio-remote-updater[754]: [2026-03-28 19:48:50] [connect] Successful connection Mar 28 19:48:50 volumio volumio[3443]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 28 19:48:50 volumio volumio[3443]: info: CoreCommandRouter::initPlayerControls Mar 28 19:48:50 volumio volumio[3443]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 19:48:50 volumio volumio[3443]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 19:48:50 volumio volumio[3443]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 19:48:50 volumio volumio[3443]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 19:48:50 volumio volumio[3443]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 19:48:50 volumio volumio[3443]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 19:48:50 volumio volumio[3443]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 19:48:50 volumio volumio[3443]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 19:48:50 volumio volumio[3443]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 28 19:48:50 volumio volumio[3443]: Express server listening on port 3000 Mar 28 19:48:50 volumio volumio[3443]: [Metrics] WebUI: 14s 565.47ms Mar 28 19:48:50 volumio volumio[3514]: Forking 3 albumart workers Mar 28 19:48:50 volumio volumio[3443]: info: CoreStateMachine::resetVolumioState Mar 28 19:48:50 volumio volumio[3443]: info: CoreStateMachine::getcurrentVolume Mar 28 19:48:50 volumio volumio[3443]: info: CoreCommandRouter::volumioRetrievevolume Mar 28 19:48:50 volumio go-librespot[3470]: time="2026-03-28T19:48:50+01:00" level=fatal msg="failed running with username and spotify token" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": net/http: TLS handshake timeout" Mar 28 19:48:50 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 28 19:48:50 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 28 19:48:50 volumio volumio[3443]: info: Volumio Network Manager: Network status updated: 1 Mar 28 19:48:50 volumio volumio[3443]: error: An error occurred while scanning: Error: Command failed: sudo /sbin/iwlist wlan0 scan Mar 28 19:48:50 volumio volumio[3443]: wlan0 Interface doesn't support scanning : Invalid exchange Mar 28 19:48:50 volumio volumio[3443]: info: Cannot use regular scanning, forcing with ap-force Mar 28 19:48:51 volumio sudo[3556]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iw dev wlan0 scan ap-force Mar 28 19:48:51 volumio sudo[3556]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 19:48:53 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 15. Mar 28 19:48:53 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 28 19:48:53 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 28 19:48:53 volumio go-librespot[3576]: go-librespot daemon starting... Mar 28 19:48:53 volumio systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 17. Mar 28 19:48:53 volumio systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Mar 28 19:48:53 volumio systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Mar 28 19:48:53 volumio go-librespot[3577]: time="2026-03-28T19:48:53+01:00" level=info msg="running go-librespot 0.7.1" Mar 28 19:48:53 volumio go-librespot[3577]: time="2026-03-28T19:48:53+01:00" level=debug msg="app state loaded" Mar 28 19:48:54 volumio upmpdcli[3581]: Could not open config: /tmp/upmpdcli.conf Mar 28 19:48:54 volumio go-librespot[3577]: time="2026-03-28T19:48:54+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 28 19:48:54 volumio systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Mar 28 19:48:54 volumio systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Mar 28 19:48:54 volumio volumio5-onboarding[1655]: time=2026-03-28T19:48:54.748+01:00 level=INFO msg="service successfully established" component=discovery/localnet Mar 28 19:48:55 volumio sudo[3556]: pam_unix(sudo:session): session closed for user root Mar 28 19:48:56 volumio volumio[3443]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 28 19:48:56 volumio volumio[3443]: info: Reloading queue from file Mar 28 19:48:56 volumio volumio[3443]: 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: 1 Mar 28 19:48:56 volumio volumio[3443]: info: VolumeController:: Volume=100 Mute =false Mar 28 19:48:56 volumio volumio[3443]: info: CoreStateMachine::pushState Mar 28 19:48:56 volumio volumio[3443]: info: CorePlayQueue::getTrack 0 Mar 28 19:48:56 volumio volumio[3443]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 28 19:48:56 volumio volumio[3443]: info: CoreCommandRouter::volumioPushState Mar 28 19:48:56 volumio volumio[3443]: info: CoreStateMachine::updateTrackBlock Mar 28 19:48:56 volumio volumio[3443]: info: CorePlayQueue::getTrackBlock Mar 28 19:48:56 volumio volumio[3443]: info: CoreCommandRouter::volumioRetrievevolume Mar 28 19:48:56 volumio volumio[3443]: info: CoreStateMachine::setRepeat null single undefined Mar 28 19:48:56 volumio volumio[3443]: info: CoreStateMachine::pushState Mar 28 19:48:56 volumio volumio[3443]: info: CorePlayQueue::getTrack 0 Mar 28 19:48:56 volumio volumio[3443]: info: CoreCommandRouter::volumioPushState Mar 28 19:48:56 volumio volumio[3443]: info: CoreStateMachine::setRandom null Mar 28 19:48:56 volumio volumio[3443]: info: CoreStateMachine::pushState Mar 28 19:48:56 volumio volumio[3443]: info: CorePlayQueue::getTrack 0 Mar 28 19:48:56 volumio volumio[3443]: info: CoreCommandRouter::volumioPushState Mar 28 19:48:57 volumio volumio[3443]: info: Setting Device type: Raspberry PI Mar 28 19:48:57 volumio volumio[3443]: 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: 1 Mar 28 19:48:57 volumio volumio[3443]: info: Received Get System Info Mar 28 19:48:57 volumio volumio[3443]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 28 19:48:57 volumio volumio[3443]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 28 19:48:57 volumio volumio[3443]: info: Discovery: Getting this device information Mar 28 19:48:57 volumio volumio[3443]: info: CoreCommandRouter::volumioGetState Mar 28 19:48:57 volumio volumio[3443]: info: CorePlayQueue::getTrack 0 Mar 28 19:48:57 volumio volumio[3443]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 28 19:48:57 volumio volumio[3443]: info: Completed loading Core Plugins Mar 28 19:48:57 volumio volumio[3443]: info: Preparing to generate the ALSA configuration file Mar 28 19:48:57 volumio volumio[3443]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Mar 28 19:48:57 volumio volumio[3443]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Mar 28 19:48:58 volumio volumio[3443]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Mar 28 19:48:58 volumio volumio[3443]: info: Discovery: adding 4ab60242-1478-4deb-94e8-dd4f3d76057d Mar 28 19:48:58 volumio volumio[3443]: info: Discovery: Found device Volumio Mar 28 19:48:58 volumio volumio[3443]: info: CoreCommandRouter::volumioGetState Mar 28 19:48:58 volumio volumio[3443]: info: CorePlayQueue::getTrack 0 Mar 28 19:48:58 volumio volumio[3443]: info: VolumeController:: Volume=100 Mute =false Mar 28 19:48:58 volumio volumio[3443]: info: CoreStateMachine::pushState Mar 28 19:48:58 volumio volumio[3443]: info: CorePlayQueue::getTrack 0 Mar 28 19:48:58 volumio volumio[3443]: info: CoreCommandRouter::volumioPushState Mar 28 19:48:58 volumio volumio[3443]: info: Asound.conf file unchanged, so no further update is needed Mar 28 19:48:58 volumio volumio[3443]: info: Output device has changed, restarting MPD Mar 28 19:48:59 volumio volumio[3443]: info: ___________ START PLUGINS ___________ Mar 28 19:48:59 volumio sudo[3599]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Mar 28 19:48:59 volumio volumio[3443]: info: ControllerMpd::onStart: Initializing MPD Mar 28 19:48:59 volumio volumio[3443]: info: Creating MPD Configuration file Mar 28 19:48:59 volumio sudo[3597]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Mar 28 19:48:59 volumio sudo[3597]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 19:48:59 volumio sudo[3599]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 19:48:59 volumio sudo[3597]: pam_unix(sudo:session): session closed for user root Mar 28 19:48:59 volumio volumio[3443]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 28 19:48:59 volumio volumio[3443]: info: [1774723739349] CoreMusicLibrary::Adding element Last_100 Mar 28 19:48:59 volumio volumio[3443]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 28 19:48:59 volumio sudo[3601]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumio5-onboarding.service Mar 28 19:48:59 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Mar 28 19:48:59 volumio sudo[3601]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 19:48:59 volumio systemd[1]: mpd.service: Deactivated successfully. Mar 28 19:48:59 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Mar 28 19:48:59 volumio volumio[3443]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 28 19:48:59 volumio volumio[3443]: info: [1774723739525] CoreMusicLibrary::Adding element Webradio Mar 28 19:48:59 volumio systemd[1]: mpd.service: Consumed 3.174s CPU time. Mar 28 19:48:59 volumio volumio[3443]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 28 19:48:59 volumio systemd[1]: mpd.socket: Deactivated successfully. Mar 28 19:48:59 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Mar 28 19:48:59 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Mar 28 19:48:59 volumio sudo[3605]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Mar 28 19:48:59 volumio sudo[3605]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 19:48:59 volumio sudo[3605]: pam_unix(sudo:session): session closed for user root Mar 28 19:48:59 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Mar 28 19:48:59 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Mar 28 19:48:59 volumio volumio[3443]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 28 19:48:59 volumio sudo[3607]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Mar 28 19:48:59 volumio sudo[3607]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 19:48:59 volumio volumio[3443]: info: Initializing BBC Radios Mar 28 19:48:59 volumio sudo[3611]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Mar 28 19:48:59 volumio sudo[3611]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Mar 28 19:48:59 volumio sudo[3611]: pam_unix(sudo:session): session closed for user root Mar 28 19:48:59 volumio systemd[1]: mpd.service: Deactivated successfully. Mar 28 19:48:59 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Mar 28 19:48:59 volumio systemd[1]: mpd.socket: Deactivated successfully. Mar 28 19:48:59 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Mar 28 19:48:59 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Mar 28 19:48:59 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Mar 28 19:48:59 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Mar 28 19:49:00 volumio sudo[3601]: pam_unix(sudo:session): session closed for user root Mar 28 19:49:00 volumio sudo[3620]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Mar 28 19:49:00 volumio sudo[3620]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Mar 28 19:49:00 volumio sudo[3620]: pam_unix(sudo:session): session closed for user root Mar 28 19:49:00 volumio volumio[3443]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 28 19:49:00 volumio volumio[3443]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 28 19:49:00 volumio volumio[3443]: info: Creating Spotify config file Mar 28 19:49:00 volumio volumio[3443]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 19:49:01 volumio volumio[3529]: Starting albumart workers Mar 28 19:49:01 volumio volumio[3528]: Starting albumart workers Mar 28 19:49:01 volumio volumio[3530]: Starting albumart workers Mar 28 19:49:03 volumio mpd[3626]: 2026-03-28T19:49:03 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Mar 28 19:49:03 volumio systemd[1]: Started mpd.service - Music Player Daemon. Mar 28 19:49:03 volumio sudo[3607]: pam_unix(sudo:session): session closed for user root Mar 28 19:49:03 volumio sudo[3599]: pam_unix(sudo:session): session closed for user root Mar 28 19:49:03 volumio volumio[3443]: info: [now-playing] ConfigUpdater: config is up to date. Mar 28 19:49:03 volumio volumio[3443]: info: Loading i18n strings for locale pl Mar 28 19:49:03 volumio volumio[3443]: error: touch_display: Fetching language file: Error: i18n file complementing the system language not found. Mar 28 19:49:03 volumio volumio[3443]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 28 19:49:03 volumio volumio[3443]: info: Volumio Calling Home Mar 28 19:49:03 volumio sudo[3652]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/mkdir -p /data/volumiokioskextensions/IframeKeyboardBridge Mar 28 19:49:03 volumio sudo[3652]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 19:49:04 volumio sudo[3652]: pam_unix(sudo:session): session closed for user root Mar 28 19:49:04 volumio go-librespot[3577]: time="2026-03-28T19:49:04+01:00" level=fatal msg="failed running with username and spotify token" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": net/http: TLS handshake timeout" Mar 28 19:49:04 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 28 19:49:04 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 28 19:49:04 volumio sudo[3657]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop getty@tty1.service Mar 28 19:49:04 volumio sudo[3657]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 19:49:04 volumio sudo[3659]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl disable getty@tty1.service Mar 28 19:49:04 volumio sudo[3659]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 19:49:04 volumio sudo[3661]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl daemon-reload Mar 28 19:49:04 volumio sudo[3661]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 19:49:04 volumio systemd[1]: Reloading. Mar 28 19:49:05 volumio volumio-remote-updater[754]: [2026-03-28 19:49:05] [connect] Successful connection Mar 28 19:49:06 volumio systemd[1]: /lib/systemd/system/go-librespot-daemon.service:9: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Mar 28 19:49:06 volumio systemd[1]: /lib/systemd/system/go-librespot-daemon.service:10: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Mar 28 19:49:06 volumio systemd[1]: Reloading. Mar 28 19:49:06 volumio volumio[3443]: error: [now-playing] Caught error in callback of WeatherAPI.#getFetchPromise(): Klucz API OpenWeatherMap nie skonfigurowany. Dodaj go w ustawieniach usługi pogody. Mar 28 19:49:06 volumio sudo[3659]: pam_unix(sudo:session): session closed for user root Mar 28 19:49:06 volumio volumio[3443]: info: [now-playing] App is listening on port 4004. Mar 28 19:49:07 volumio volumio[3443]: warn: [now-playing] MyBackgroundMonitor is now watching /data/INTERNAL/NowPlayingPlugin/My Backgrounds Mar 28 19:49:07 volumio volumio[3443]: info: touch_display: Backlight interface detected. Mar 28 19:49:07 volumio volumio[3443]: info: touch_display: systemctl disable getty@tty1.service succeeded. Mar 28 19:49:07 volumio volumio[3443]: info: MPD Permissions set Mar 28 19:49:08 volumio sudo[3707]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/cp -r /data/plugins/user_interface/touch_display/iframe_keyboard_bridge/content.js /data/plugins/user_interface/touch_display/iframe_keyboard_bridge/manifest.json /data/volumiokioskextensions/IframeKeyboardBridge/ Mar 28 19:49:08 volumio volumio[3443]: info: MPD Permissions set Mar 28 19:49:08 volumio sudo[3707]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 19:49:08 volumio systemd[1]: /lib/systemd/system/go-librespot-daemon.service:9: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Mar 28 19:49:08 volumio systemd[1]: /lib/systemd/system/go-librespot-daemon.service:10: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Mar 28 19:49:08 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 16. Mar 28 19:49:08 volumio sudo[3707]: pam_unix(sudo:session): session closed for user root Mar 28 19:49:08 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 28 19:49:08 volumio sudo[3661]: pam_unix(sudo:session): session closed for user root Mar 28 19:49:08 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 28 19:49:08 volumio go-librespot[3713]: go-librespot daemon starting... Mar 28 19:49:08 volumio sudo[3657]: pam_unix(sudo:session): session closed for user root Mar 28 19:49:08 volumio go-librespot[3719]: time="2026-03-28T19:49:08+01:00" level=info msg="running go-librespot 0.7.1" Mar 28 19:49:08 volumio go-librespot[3719]: time="2026-03-28T19:49:08+01:00" level=debug msg="app state loaded" Mar 28 19:49:08 volumio go-librespot[3719]: time="2026-03-28T19:49:08+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 28 19:49:08 volumio volumio[3443]: info: Spotify config file written Mar 28 19:49:08 volumio sudo[3735]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 28 19:49:09 volumio sudo[3735]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 19:49:09 volumio systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 18. Mar 28 19:49:09 volumio systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Mar 28 19:49:09 volumio systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Mar 28 19:49:09 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Mar 28 19:49:09 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Mar 28 19:49:09 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 28 19:49:09 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 28 19:49:09 volumio go-librespot[3738]: go-librespot daemon starting... Mar 28 19:49:09 volumio sudo[3735]: pam_unix(sudo:session): session closed for user root Mar 28 19:49:09 volumio upmpdcli[3737]: Could not open config: /tmp/upmpdcli.conf Mar 28 19:49:09 volumio systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Mar 28 19:49:09 volumio systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Mar 28 19:49:09 volumio go-librespot[3739]: time="2026-03-28T19:49:09+01:00" level=info msg="running go-librespot 0.7.1" Mar 28 19:49:09 volumio go-librespot[3739]: time="2026-03-28T19:49:09+01:00" level=debug msg="app state loaded" Mar 28 19:49:09 volumio go-librespot[3739]: time="2026-03-28T19:49:09+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 28 19:49:09 volumio volumio[3443]: error: MPD error: The expression evaluated to a falsy value: Mar 28 19:49:09 volumio volumio[3443]: assert.ok(self.idling) Mar 28 19:49:09 volumio volumio[3443]: error: The expression evaluated to a falsy value: Mar 28 19:49:09 volumio volumio[3443]: assert.ok(self.idling) Mar 28 19:49:09 volumio volumio-remote-updater[754]: [2026-03-28 19:49:09] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1774723745 101 Mar 28 19:49:09 volumio volumio[3443]: 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: 3 Mar 28 19:49:09 volumio volumio[3443]: info: touch_display: systemctl stop getty@tty1.service succeeded. Mar 28 19:49:09 volumio volumio[3443]: info: touch_display: systemctl daemon-reload succeeded. Mar 28 19:49:09 volumio volumio[3443]: info: touch_display: IframeKeyboardBridge extension installed successfully Mar 28 19:49:09 volumio volumio[3443]: info: MPD running with PID3626 Mar 28 19:49:09 volumio volumio[3443]: ,establishing connection Mar 28 19:49:09 volumio volumio[3443]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 19:49:09 volumio volumio[3443]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 19:49:09 volumio volumio[3443]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 19:49:09 volumio volumio[3443]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 19:49:09 volumio volumio[3443]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 19:49:09 volumio volumio[3443]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 19:49:09 volumio volumio[3443]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 19:49:09 volumio volumio[3443]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 19:49:09 volumio sudo[3748]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumio-kiosk.service Mar 28 19:49:09 volumio sudo[3748]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 19:49:10 volumio volumio[3443]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 28 19:49:10 volumio volumio[3443]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 19:49:10 volumio volumio[3443]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 19:49:10 volumio volumio[3443]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 19:49:10 volumio volumio[3443]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 19:49:10 volumio volumio[3443]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 19:49:10 volumio volumio[3443]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 19:49:10 volumio volumio[3443]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 19:49:10 volumio volumio[3443]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 19:49:10 volumio volumio[3443]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 19:49:10 volumio sudo[3748]: pam_unix(sudo:session): session closed for user root Mar 28 19:49:10 volumio volumio[3443]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 28 19:49:10 volumio volumio[3443]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 19:49:10 volumio volumio[3443]: info: No need to fix Spotify hosts Mar 28 19:49:10 volumio volumio[3443]: error: updateQueue error: null Mar 28 19:49:10 volumio volumio[3443]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 4 Mar 28 19:49:10 volumio volumio[3443]: info: Volumio called home Mar 28 19:49:10 volumio volumio[3443]: info: touch_display: systemctl start volumio-kiosk.service succeeded. Mar 28 19:49:10 volumio volumio[3443]: info: touch_display: Volumio Kiosk started. Mar 28 19:49:10 volumio volumio[3443]: info: CoreCommandRouter::volumioGetState Mar 28 19:49:10 volumio volumio[3443]: info: CorePlayQueue::getTrack 0 Mar 28 19:49:10 volumio volumio[3443]: info: Completed starting Core Plugins Mar 28 19:49:10 volumio volumio[3443]: info: ------------------------------------------- Mar 28 19:49:10 volumio volumio[3443]: info: ----- MyVolumio plugins startup ---- Mar 28 19:49:10 volumio volumio[3443]: info: ------------------------------------------- Mar 28 19:49:10 volumio volumio[3443]: info: [MyVolumio PluginManager] Fetching plans data.... Mar 28 19:49:10 volumio volumio[3443]: info: touch_display: Raspberry Pi Foundation touch screen detected. Mar 28 19:49:10 volumio sudo[3764]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod a+w /sys/class/backlight/10-0045/brightness Mar 28 19:49:10 volumio sudo[3764]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 19:49:10 volumio volumio[3443]: error: updateQueue error: null Mar 28 19:49:10 volumio sudo[3764]: pam_unix(sudo:session): session closed for user root Mar 28 19:49:10 volumio sudo[3766]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod a+rw /etc/X11/xorg.conf.d/99-vc4.conf Mar 28 19:49:10 volumio sudo[3766]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 19:49:10 volumio sudo[3769]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod a+rw /etc/X11/xorg.conf.d/95-touch_display-plugin.conf Mar 28 19:49:10 volumio sudo[3766]: pam_unix(sudo:session): session closed for user root Mar 28 19:49:10 volumio sudo[3769]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 19:49:11 volumio sudo[3769]: pam_unix(sudo:session): session closed for user root Mar 28 19:49:11 volumio volumio[3443]: info: touch_display: File permissions for /etc/X11/xorg.conf.d/95-touch_display-plugin.conf set. Mar 28 19:49:11 volumio volumio[3443]: info: touch_display: File permissions for /etc/X11/xorg.conf.d/99-vc4.conf set. Mar 28 19:49:11 volumio volumio[3443]: info: touch_display: File permissions for backlight brightness control set. Mar 28 19:49:11 volumio volumio[3443]: info: touch_display: X display number found: 0 Mar 28 19:49:11 volumio volumio[3443]: info: touch_display: Using Xserver unix domain socket /tmp/.X11-unix/X0 Mar 28 19:49:11 volumio volumio[3443]: info: CoreCommandRouter::volumioGetState Mar 28 19:49:11 volumio volumio[3443]: info: CorePlayQueue::getTrack 0 Mar 28 19:49:11 volumio volumio[3443]: info: touch_display: X display number found: 0 Mar 28 19:49:11 volumio volumio[3443]: info: New Spotify access tokenBQCgplfhl1... Mar 28 19:49:11 volumio volumio[3443]: info: Spotify credentials grant success - running version from March 24, 2019 Mar 28 19:49:11 volumio volumio[3443]: info: touch_display: Setting screensaver timeout to 120 seconds. Mar 28 19:49:12 volumio volumio[3443]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 28 19:49:12 volumio volumio[3443]: info: Discovery: Getting this device information Mar 28 19:49:12 volumio volumio[3443]: info: CoreCommandRouter::volumioGetState Mar 28 19:49:12 volumio volumio[3443]: info: CorePlayQueue::getTrack 0 Mar 28 19:49:12 volumio volumio[3443]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 28 19:49:12 volumio volumio[3443]: info: Discovery: this is already registered, 4ab60242-1478-4deb-94e8-dd4f3d76057d Mar 28 19:49:12 volumio volumio[3443]: info: Discovery: Found device Volumio Mar 28 19:49:12 volumio volumio[3443]: info: CoreCommandRouter::volumioGetState Mar 28 19:49:12 volumio volumio[3443]: info: CorePlayQueue::getTrack 0 Mar 28 19:49:13 volumio volumio[3443]: info: Discovery: this is already registered, 4ab60242-1478-4deb-94e8-dd4f3d76057d Mar 28 19:49:13 volumio volumio[3443]: info: Discovery: Found device Volumio Mar 28 19:49:13 volumio volumio[3443]: info: CoreCommandRouter::volumioGetState Mar 28 19:49:13 volumio volumio[3443]: info: CorePlayQueue::getTrack 0 Mar 28 19:49:13 volumio volumio[3443]: info: go-librespot daemon successfully initialized Mar 28 19:49:13 volumio volumio[3443]: info: CoreCommandRouter::volumioGetState Mar 28 19:49:13 volumio volumio[3443]: info: CorePlayQueue::getTrack 0 Mar 28 19:49:13 volumio volumio[3443]: info: CoreCommandRouter::volumioGetState Mar 28 19:49:13 volumio volumio[3443]: info: CorePlayQueue::getTrack 0 Mar 28 19:49:14 volumio volumio[3443]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Mar 28 19:49:14 volumio volumio[3443]: 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: 5 Mar 28 19:49:14 volumio volumio5-onboarding[1655]: time=2026-03-28T19:49:14.758+01:00 level=INFO msg="service successfully established" component=discovery/localnet Mar 28 19:49:15 volumio volumio[3443]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Mar 28 19:49:15 volumio volumio[3443]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Mar 28 19:49:15 volumio volumio[3443]: info: Listing playlists Mar 28 19:49:15 volumio volumio[3443]: info: CoreCommandRouter::volumioGetQueue Mar 28 19:49:15 volumio volumio[3443]: info: CoreStateMachine::getQueue Mar 28 19:49:15 volumio volumio[3443]: info: CorePlayQueue::getQueue Mar 28 19:49:15 volumio volumio[3443]: info: CoreCommandRouter::volumioGetVisibleSources Mar 28 19:49:15 volumio volumio[3443]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 28 19:49:15 volumio volumio[3443]: info: CoreCommandRouter::volumioGetState Mar 28 19:49:15 volumio volumio[3443]: info: CorePlayQueue::getTrack 0 Mar 28 19:49:16 volumio volumio5-onboarding[1655]: time=2026-03-28T19:49:16.009+01:00 level=INFO msg="established new WebSocket connection" component=conn/ws remoteAddr=192.168.0.15:38002 Mar 28 19:49:16 volumio volumio[3443]: error: [now-playing] Caught error in callback of WeatherAPI.#getFetchPromise(): Klucz API OpenWeatherMap nie skonfigurowany. Dodaj go w ustawieniach usługi pogody. Mar 28 19:49:16 volumio volumio[3443]: error: [now-playing] API endpoint weather/fetchInfo returned error: Error: Nie udało się pobrać pogody: Klucz API OpenWeatherMap nie skonfigurowany. Dodaj go w ustawieniach usługi pogody. Mar 28 19:49:16 volumio volumio[3443]: at WeatherAPI.fetchInfo (/data/plugins/user_interface/now_playing/dist/lib/api/WeatherAPI.js:108:25) Mar 28 19:49:16 volumio volumio[3443]: at process.processTicksAndRejections (node:internal/process/task_queues:95:5) Mar 28 19:49:16 volumio volumio[3443]: at async Object.api (/data/plugins/user_interface/now_playing/dist/app/Handler.js:126:28) Mar 28 19:49:16 volumio volumio[3443]: info: Initializing connection to go-librespot Websocket Mar 28 19:49:16 volumio go-librespot[3739]: time="2026-03-28T19:49:16+01:00" level=debug msg="new websocket client" Mar 28 19:49:16 volumio volumio[3443]: info: Connection to go-librespot Websocket established Mar 28 19:49:19 volumio go-librespot[3739]: time="2026-03-28T19:49:19+01:00" level=fatal msg="failed running with username and spotify token" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": net/http: TLS handshake timeout" Mar 28 19:49:19 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 28 19:49:19 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 28 19:49:19 volumio volumio[3443]: info: Connection to go-librespot Websocket closed Mar 28 19:49:20 volumio volumio[3443]: info: Getting Spotify volume Mar 28 19:49:20 volumio volumio[3443]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 28 19:49:20 volumio volumio[3443]: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 28 19:49:20 volumio volumio[3443]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Mar 28 19:49:20 volumio volumio[3443]: errno: -111, Mar 28 19:49:20 volumio volumio[3443]: code: 'ECONNREFUSED', Mar 28 19:49:20 volumio volumio[3443]: syscall: 'connect', Mar 28 19:49:20 volumio volumio[3443]: address: '127.0.0.1', Mar 28 19:49:20 volumio volumio[3443]: port: 9879, Mar 28 19:49:20 volumio volumio[3443]: response: undefined Mar 28 19:49:20 volumio volumio[3443]: } Mar 28 19:49:20 volumio volumio[3443]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 28 19:49:20 volumio sudo[3821]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-03-28 19:48' Mar 28 19:49:20 volumio sudo[3821]: 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"