Mar 28 04:11:00 volumio systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 1. Mar 28 04:11:00 volumio systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Mar 28 04:11:00 volumio systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Mar 28 04:11:00 volumio upmpdcli[1498]: Could not open config: /tmp/upmpdcli.conf Mar 28 04:11:00 volumio systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Mar 28 04:11:00 volumio systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Mar 28 04:11:03 volumio wpa_supplicant[1432]: wlan0: Failed to initiate sched scan Mar 28 04:11:06 volumio wireless.js[977]: WIRELESS.JS - INFO: WpaStateMachine: SCANNING timeout - network not found Mar 28 04:11:06 volumio wireless.js[977]: WIRELESS.JS - INFO: STAGE 2: Connection failed - Network not found - check SSID and signal strength Mar 28 04:11:06 volumio wireless.js[977]: WIRELESS.JS - INFO: STAGE 2: Failure details: Network not found after scanning Mar 28 04:11:06 volumio wireless.js[977]: WIRELESS.JS - INFO: STAGE 2: Skipping afterAPStart loop, proceeding directly to hotspot evaluation Mar 28 04:11:06 volumio wireless.js[977]: WIRELESS.JS - INFO: Start ap Mar 28 04:11:06 volumio wireless.js[977]: WIRELESS.JS - INFO: STAGE 2: Connection already failed, skipping polling loop Mar 28 04:11:06 volumio wireless.js[977]: WIRELESS.JS - INFO: STAGE 2: Evaluating hotspot condition directly Mar 28 04:11:06 volumio sudo[1538]: root : PWD=/ ; USER=root ; COMMAND=/sbin/iw wlan0 scan Mar 28 04:11:06 volumio sudo[1538]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Mar 28 04:11:06 volumio kernel: brcmfmac: brcmf_cfg80211_set_power_mgmt: power save disabled Mar 28 04:11:06 volumio systemd[1]: Started wireless.service - Wireless Services. Mar 28 04:11:06 volumio systemd[1]: Started volumio.service - Volumio Backend Module. Mar 28 04:11:06 volumio systemd[1]: Starting plymouth-quit.service - Terminate Plymouth Boot Screen... Mar 28 04:11:06 volumio systemd[1]: Started volumio_cpu_tweak.service - Volumio Cpu Tweaker. Mar 28 04:11:06 volumio systemd[1]: Received SIGRTMIN+21 from PID 419 (plymouthd). Mar 28 04:11:06 volumio volumio-cpu-tweak[1545]: Setting RT Priority for mpd Mar 28 04:11:06 volumio volumio-cpu-tweak[1559]: pid 35's current scheduling policy: SCHED_OTHER Mar 28 04:11:06 volumio volumio-cpu-tweak[1559]: pid 35's current scheduling priority: 0 Mar 28 04:11:06 volumio volumio-cpu-tweak[1545]: Setting MPD Affinity Mar 28 04:11:06 volumio volumio-cpu-tweak[1560]: pid 3's current affinity mask: f Mar 28 04:11:06 volumio volumio-cpu-tweak[1545]: /bin/volumio_cpu_tweak: line 27: warning: command substitution: ignored null byte in input Mar 28 04:11:06 volumio volumio-cpu-tweak[1545]: VOLUMIO CPU TWEAK: Setting CPU Governor: conservative Mar 28 04:11:06 volumio systemd[1]: volumio_cpu_tweak.service: Deactivated successfully. Mar 28 04:11:06 volumio systemd[1]: Received SIGRTMIN+21 from PID 419 (plymouthd). Mar 28 04:11:06 volumio systemd[1]: Finished plymouth-quit-wait.service - Hold until boot process finishes up. Mar 28 04:11:06 volumio systemd[1]: Finished plymouth-quit.service - Terminate Plymouth Boot Screen. Mar 28 04:11:06 volumio systemd[1]: Started serial-getty@ttyAMA10.service - Serial Getty on ttyAMA10. Mar 28 04:11:06 volumio systemd[1]: Reached target getty.target - Login Prompts. Mar 28 04:11:06 volumio volumio[1543]: info: ------------------------------------------- Mar 28 04:11:06 volumio volumio[1543]: info: ----- Volumio3 ---- Mar 28 04:11:06 volumio volumio[1543]: info: ------------------------------------------- Mar 28 04:11:06 volumio volumio[1543]: info: ----- System startup ---- Mar 28 04:11:06 volumio volumio[1543]: info: ------------------------------------------- Mar 28 04:11:07 volumio volumio[1543]: info: MYVOLUMIO Environment detected Mar 28 04:11:07 volumio volumio[1543]: info: Plugin folders cleanup Mar 28 04:11:07 volumio volumio[1543]: info: Scanning into folder /volumio/app/plugins/ Mar 28 04:11:07 volumio volumio[1543]: info: Scanning category audio_interface Mar 28 04:11:07 volumio volumio[1543]: info: Scanning category miscellanea Mar 28 04:11:07 volumio volumio[1543]: info: Scanning category music_service Mar 28 04:11:07 volumio volumio[1543]: info: Scanning category plugins.json Mar 28 04:11:07 volumio volumio[1543]: info: Scanning category system_controller Mar 28 04:11:07 volumio volumio[1543]: info: Scanning category user_interface Mar 28 04:11:07 volumio volumio[1543]: info: Scanning into folder /data/plugins/ Mar 28 04:11:07 volumio volumio[1543]: info: Scanning category music_service Mar 28 04:11:07 volumio volumio[1543]: info: Scanning category system_controller Mar 28 04:11:07 volumio volumio[1543]: info: Scanning category system_hardware Mar 28 04:11:07 volumio volumio[1543]: info: Scanning category user_interface Mar 28 04:11:07 volumio volumio[1543]: info: Plugin folders cleanup completed Mar 28 04:11:07 volumio volumio[1543]: info: ------------------------------------------- Mar 28 04:11:07 volumio volumio[1543]: info: ----- Core plugins startup ---- Mar 28 04:11:07 volumio volumio[1543]: info: ------------------------------------------- Mar 28 04:11:07 volumio volumio[1543]: info: Loading plugins from folder /volumio/app/plugins/ Mar 28 04:11:07 volumio volumio[1543]: info: Adding plugin upnp to MyMusic Plugins Mar 28 04:11:07 volumio volumio[1543]: info: Adding plugin airplay_emulation to MyMusic Plugins Mar 28 04:11:07 volumio volumio[1543]: info: Adding plugin upnp_browser to MyMusic Plugins Mar 28 04:11:07 volumio volumio[1543]: info: Loading plugins from folder /data/plugins/ Mar 28 04:11:07 volumio volumio[1543]: info: Loading plugin "system"... Mar 28 04:11:07 volumio volumio-remote-updater[974]: [2026-03-28 04:11:07] [connect] Successful connection Mar 28 04:11:07 volumio volumio[1543]: info: Loading plugin "appearance"... Mar 28 04:11:07 volumio volumio[1543]: info: Loading plugin "network"... Mar 28 04:11:07 volumio volumio[1543]: info: Refreshing Cached IP Addresses Mar 28 04:11:07 volumio sudo[1578]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Mar 28 04:11:07 volumio sudo[1578]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 04:11:07 volumio sudo[1580]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 28 04:11:07 volumio sudo[1580]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 04:11:07 volumio sudo[1578]: pam_unix(sudo:session): session closed for user root Mar 28 04:11:07 volumio sudo[1580]: pam_unix(sudo:session): session closed for user root Mar 28 04:11:07 volumio volumio[1543]: info: Loading plugin "services"... Mar 28 04:11:07 volumio volumio[1543]: info: Loading plugin "volumio5onboarding"... Mar 28 04:11:07 volumio sudo[1593]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Mar 28 04:11:07 volumio sudo[1593]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 04:11:07 volumio sudo[1593]: pam_unix(sudo:session): session closed for user root Mar 28 04:11:07 volumio volumio[1543]: info: Loading plugin "alsa_controller"... Mar 28 04:11:07 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 28 04:11:07 volumio volumio[1543]: info: Loading plugin "wizard"... Mar 28 04:11:07 volumio volumio[1543]: info: Loading plugin "networkfs"... Mar 28 04:11:07 volumio volumio[1543]: info: Starting Udev Watcher for removable devices Mar 28 04:11:07 volumio volumio[1543]: info: Ignoring mount for partition: boot Mar 28 04:11:07 volumio volumio[1543]: info: Ignoring mount for partition: volumio Mar 28 04:11:07 volumio volumio[1543]: info: Ignoring mount for partition: volumio_data Mar 28 04:11:07 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Mar 28 04:11:07 volumio volumio[1543]: info: Loading plugin "pi_screen_setup"... Mar 28 04:11:08 volumio volumio[1543]: info: Loading plugin "volumio_command_line_client"... Mar 28 04:11:08 volumio volumio[1543]: info: Loading plugin "upnp"... Mar 28 04:11:08 volumio volumio[1543]: info: [1774692668082] Starting Upmpd Daemon Mar 28 04:11:08 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Mar 28 04:11:08 volumio volumio[1543]: info: Loading plugin "my_music"... Mar 28 04:11:08 volumio volumio[1543]: info: Loading plugin "mpd"... Mar 28 04:11:08 volumio volumio[1543]: info: Plugin upnp_browser is not enabled Mar 28 04:11:08 volumio volumio[1543]: info: Loading plugin "alarm-clock"... Mar 28 04:11:08 volumio volumio[1543]: info: Loading plugin "airplay_emulation"... Mar 28 04:11:08 volumio volumio[1543]: info: Starting Shairport Sync Mar 28 04:11:08 volumio volumio[1543]: info: Loading plugin "last_100"... Mar 28 04:11:08 volumio volumio[1543]: info: Loading plugin "webradio"... Mar 28 04:11:08 volumio volumio[1543]: info: Loading plugin "i2s_dacs"... Mar 28 04:11:08 volumio volumio[1543]: info: Loading plugin "volumiodiscovery"... Mar 28 04:11:08 volumio volumio[1543]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Mar 28 04:11:08 volumio volumio[1543]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 28 04:11:08 volumio volumio[1543]: *** WARNING *** For more information see Mar 28 04:11:08 volumio volumio[1543]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Mar 28 04:11:08 volumio node[1543]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Mar 28 04:11:08 volumio volumio[1543]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 28 04:11:08 volumio volumio[1543]: *** WARNING *** For more information see Mar 28 04:11:08 volumio node[1543]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 28 04:11:08 volumio node[1543]: *** WARNING *** For more information see Mar 28 04:11:08 volumio node[1543]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Mar 28 04:11:08 volumio node[1543]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 28 04:11:08 volumio node[1543]: *** WARNING *** For more information see Mar 28 04:11:08 volumio volumio[1543]: info: Applying required configuration parameters for plugin volumiodiscovery Mar 28 04:11:08 volumio volumio[1543]: info: Discovery: Started advertising with name: Volumio Mar 28 04:11:08 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Mar 28 04:11:08 volumio volumio[1543]: info: Loading plugin "spop"... Mar 28 04:11:09 volumio volumio[1543]: info: Plugin now_playing is not enabled Mar 28 04:11:09 volumio volumio[1543]: info: Loading plugin "outputs"... Mar 28 04:11:09 volumio volumio[1543]: info: Loading plugin "albumart"... Mar 28 04:11:09 volumio volumio[1543]: info: Plugin example_plugin is not enabled Mar 28 04:11:09 volumio volumio[1543]: info: Loading plugin "inputs"... Mar 28 04:11:09 volumio volumio[1543]: info: Loading plugin "updater_comm"... Mar 28 04:11:09 volumio volumio[1543]: info: Plugin mpdemulation is not enabled Mar 28 04:11:09 volumio volumio[1543]: info: Loading plugin "rest_api"... Mar 28 04:11:09 volumio volumio[1543]: info: Loading plugin "websocket"... Mar 28 04:11:09 volumio volumio[1543]: info: Starting Socket.io Server version 1.7.4 Mar 28 04:11:09 volumio volumio[1543]: info: Loading plugin "backup_restore"... Mar 28 04:11:09 volumio volumio[1613]: Forking 3 albumart workers Mar 28 04:11:09 volumio volumio[1543]: info: Applying required configuration parameters for plugin backup_restore Mar 28 04:11:09 volumio volumio[1543]: info: Plugin Bluetoothremote is not enabled Mar 28 04:11:09 volumio volumio[1543]: info: Loading plugin "touch_display"... Mar 28 04:11:09 volumio volumio[1543]: info: Applying required configuration parameters for plugin touch_display Mar 28 04:11:09 volumio volumio[1543]: info: Loading i18n strings for locale es Mar 28 04:11:09 volumio volumio[1623]: Starting albumart workers Mar 28 04:11:09 volumio volumio[1543]: error: touch_display: Fetching language file: Error: i18n file complementing the system language not found. Mar 28 04:11:09 volumio volumio[1543]: Updating browse sources language Mar 28 04:11:09 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 28 04:11:09 volumio volumio[1624]: Starting albumart workers Mar 28 04:11:09 volumio volumio[1625]: Starting albumart workers Mar 28 04:11:09 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 28 04:11:09 volumio volumio[1543]: info: CoreCommandRouter::initPlayerControls Mar 28 04:11:09 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 04:11:09 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 04:11:09 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 04:11:09 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 04:11:09 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 04:11:09 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 04:11:09 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 04:11:09 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 04:11:09 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 28 04:11:09 volumio volumio[1543]: Express server listening on port 3000 Mar 28 04:11:09 volumio volumio[1543]: [Metrics] WebUI: 2s 857.00ms Mar 28 04:11:09 volumio volumio[1543]: info: CoreStateMachine::resetVolumioState Mar 28 04:11:09 volumio volumio[1543]: info: CoreStateMachine::getcurrentVolume Mar 28 04:11:09 volumio volumio[1543]: info: CoreCommandRouter::volumioRetrievevolume Mar 28 04:11:09 volumio volumio[1543]: info: Volumio Network Manager: Network status updated: 0 Mar 28 04:11:09 volumio volumio[1543]: error: An error occurred while scanning: Error: Command failed: sudo /sbin/iwlist wlan0 scan Mar 28 04:11:09 volumio volumio[1543]: wlan0 Interface doesn't support scanning : Device or resource busy Mar 28 04:11:09 volumio volumio[1543]: info: Cannot use regular scanning, forcing with ap-force Mar 28 04:11:09 volumio sudo[1667]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iw dev wlan0 scan ap-force Mar 28 04:11:09 volumio sudo[1667]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 04:11:09 volumio sudo[1667]: pam_unix(sudo:session): session closed for user root Mar 28 04:11:09 volumio volumio[1543]: command failed: Device or resource busy (-16) Mar 28 04:11:09 volumio volumio[1543]: error: Cannot use fallback scanning method: Error: Command failed: /usr/bin/sudo /sbin/iw dev wlan0 scan ap-force Mar 28 04:11:09 volumio volumio[1543]: command failed: Device or resource busy (-16) Mar 28 04:11:09 volumio volumio-remote-updater[974]: [2026-03-28 04:11:09] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1774692667 101 Mar 28 04:11:09 volumio volumio[1543]: 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: 1 Mar 28 04:11:09 volumio volumio[1543]: 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 04:11:09 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 28 04:11:09 volumio volumio[1543]: info: Reloading queue from file Mar 28 04:11:09 volumio volumio[1543]: info: VolumeController:: Volume=86 Mute =false Mar 28 04:11:09 volumio volumio[1543]: info: CoreStateMachine::pushState Mar 28 04:11:09 volumio volumio[1543]: info: CorePlayQueue::getTrack 0 Mar 28 04:11:09 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 28 04:11:09 volumio volumio[1543]: info: CoreCommandRouter::volumioPushState Mar 28 04:11:09 volumio volumio[1543]: info: CoreStateMachine::updateTrackBlock Mar 28 04:11:09 volumio volumio[1543]: info: CorePlayQueue::getTrackBlock Mar 28 04:11:09 volumio volumio[1543]: info: CoreCommandRouter::volumioRetrievevolume Mar 28 04:11:09 volumio volumio[1543]: info: CoreStateMachine::setRepeat false single undefined Mar 28 04:11:09 volumio volumio[1543]: info: CoreStateMachine::pushState Mar 28 04:11:09 volumio volumio[1543]: info: CorePlayQueue::getTrack 0 Mar 28 04:11:09 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 28 04:11:09 volumio volumio[1543]: info: CoreCommandRouter::volumioPushState Mar 28 04:11:09 volumio volumio[1543]: info: CoreStateMachine::setRandom null Mar 28 04:11:09 volumio volumio[1543]: info: CoreStateMachine::pushState Mar 28 04:11:09 volumio volumio[1543]: info: CorePlayQueue::getTrack 0 Mar 28 04:11:09 volumio volumio[1543]: info: CoreCommandRouter::volumioPushState Mar 28 04:11:09 volumio volumio[1543]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Mar 28 04:11:09 volumio volumio[1543]: info: USB Boot Capable - System SBC Revision found in cpuinfo: c04170 Mar 28 04:11:09 volumio volumio[1543]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Mar 28 04:11:09 volumio volumio[1543]: info: Setting Device type: Raspberry PI Mar 28 04:11:09 volumio volumio[1543]: info: Completed loading Core Plugins Mar 28 04:11:09 volumio volumio[1543]: info: Preparing to generate the ALSA configuration file Mar 28 04:11:09 volumio volumio[1543]: info: Discovery: adding 32e04bf9-53d2-46d7-ba2f-8921ce0b8ce4 Mar 28 04:11:09 volumio volumio[1543]: info: Discovery: Found device Volumio Mar 28 04:11:09 volumio volumio[1543]: info: CoreCommandRouter::volumioGetState Mar 28 04:11:09 volumio volumio[1543]: info: CorePlayQueue::getTrack 0 Mar 28 04:11:09 volumio volumio[1543]: info: VolumeController:: Volume=86 Mute =false Mar 28 04:11:09 volumio volumio[1543]: info: CoreStateMachine::pushState Mar 28 04:11:09 volumio volumio[1543]: info: CorePlayQueue::getTrack 0 Mar 28 04:11:09 volumio volumio[1543]: info: CoreCommandRouter::volumioPushState Mar 28 04:11:09 volumio volumio[1543]: info: Asound.conf file unchanged, so no further update is needed Mar 28 04:11:09 volumio volumio[1543]: info: Output device has changed, restarting MPD Mar 28 04:11:09 volumio volumio[1543]: info: Output device has changed, restarting Shairport Sync Mar 28 04:11:09 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 04:11:09 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 28 04:11:09 volumio sudo[1692]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Mar 28 04:11:09 volumio sudo[1692]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 04:11:09 volumio sudo[1694]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Mar 28 04:11:09 volumio volumio[1543]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 28 04:11:09 volumio sudo[1694]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 04:11:09 volumio volumio[1543]: info: ___________ START PLUGINS ___________ Mar 28 04:11:09 volumio sudo[1692]: pam_unix(sudo:session): session closed for user root Mar 28 04:11:09 volumio volumio[1543]: info: pi_screen_setup: Starting plugin Mar 28 04:11:09 volumio sudo[1702]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumio5-onboarding.service Mar 28 04:11:09 volumio sudo[1702]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 04:11:09 volumio volumio[1543]: info: pi_screen_setup: Loaded cached presets v1.5.6 Mar 28 04:11:09 volumio volumio[1543]: info: pi_screen_setup: Active presets source: cached, 227 presets loaded Mar 28 04:11:09 volumio volumio[1543]: info: pi_screen_setup: Detected model: Raspberry Pi 5 Model B Rev 1.0 Mar 28 04:11:09 volumio volumio[1543]: info: pi_screen_setup: Detected SoC: bcm2712 Mar 28 04:11:09 volumio volumio[1543]: info: pi_screen_setup: Detected RAM: 3997 MB Mar 28 04:11:09 volumio volumio[1543]: info: pi_screen_setup: Hardware detection complete - {"model":"Pi 5","model_raw":"Raspberry Pi 5 Model B Rev 1.0","soc":"bcm2712","ram_mb":3997,"hdmi_ports":2,"dsi_ports":["dsi0","dsi1"],"has_composite":true,"kms_supported":true,"kms_overlay":"vc4-kms-v3d-pi5","is_pi":true} Mar 28 04:11:09 volumio volumio[1543]: info: ControllerMpd::onStart: Initializing MPD Mar 28 04:11:09 volumio volumio[1543]: info: Creating MPD Configuration file Mar 28 04:11:09 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 04:11:09 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 28 04:11:09 volumio sudo[1708]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Mar 28 04:11:09 volumio sudo[1706]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Mar 28 04:11:09 volumio sudo[1706]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 04:11:09 volumio sudo[1708]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 04:11:09 volumio volumio[1543]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 28 04:11:09 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 04:11:09 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 28 04:11:09 volumio sudo[1706]: pam_unix(sudo:session): session closed for user root Mar 28 04:11:09 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Mar 28 04:11:09 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Mar 28 04:11:09 volumio volumio[1543]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 28 04:11:09 volumio volumio[1543]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 28 04:11:09 volumio volumio[1543]: info: [1774692669873] CoreMusicLibrary::Adding element Last_100 Mar 28 04:11:09 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 28 04:11:09 volumio volumio[1543]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 28 04:11:09 volumio volumio[1543]: info: [1774692669874] CoreMusicLibrary::Adding element Webradio Mar 28 04:11:09 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 28 04:11:09 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 28 04:11:09 volumio volumio[1543]: info: Initializing BBC Radios Mar 28 04:11:09 volumio systemd[1]: Started volumio5-onboarding.service - Volumio5 Onboarding Server. Mar 28 04:11:09 volumio sudo[1702]: pam_unix(sudo:session): session closed for user root Mar 28 04:11:09 volumio systemd[1]: mpd.service: Deactivated successfully. Mar 28 04:11:09 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Mar 28 04:11:09 volumio systemd[1]: mpd.socket: Deactivated successfully. Mar 28 04:11:09 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Mar 28 04:11:09 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Mar 28 04:11:09 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Mar 28 04:11:09 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Mar 28 04:11:09 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 28 04:11:09 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 28 04:11:09 volumio volumio[1543]: info: Creating Spotify config file Mar 28 04:11:09 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 04:11:09 volumio sudo[1730]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Mar 28 04:11:09 volumio sudo[1730]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Mar 28 04:11:09 volumio sudo[1739]: /bin/chown: cannot access '/var/log/mpd.log': No such file or directory Mar 28 04:11:09 volumio sudo[1730]: pam_unix(sudo:session): session closed for user root Mar 28 04:11:09 volumio volumio[1543]: info: Loading i18n strings for locale es Mar 28 04:11:09 volumio volumio[1543]: error: touch_display: Fetching language file: Error: i18n file complementing the system language not found. Mar 28 04:11:09 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 28 04:11:09 volumio volumio[1543]: info: Volumio Calling Home Mar 28 04:11:09 volumio sudo[1748]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/mkdir -p /data/volumiokioskextensions/IframeKeyboardBridge Mar 28 04:11:09 volumio sudo[1748]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 04:11:10 volumio volumio[1543]: info: pi_screen_setup: Detected prior configuration (backup=true, banner=true) - restoring wizard_complete Mar 28 04:11:10 volumio sudo[1748]: pam_unix(sudo:session): session closed for user root Mar 28 04:11:10 volumio volumio[1543]: info: pi_screen_setup: Boot validation - {"valid":false,"drift_detected":true,"missing_videoconfig":false,"missing_include":true,"config_mismatch":true,"volumioconfig_mismatch":true,"errors":["ERR_INCLUDE_MISSING","ERR_CONFIG_MISMATCH","ERR_VOLUMIOCONFIG_MISMATCH"]} Mar 28 04:11:10 volumio volumio[1543]: info: pi_screen_setup: Management server started on port 4567 Mar 28 04:11:10 volumio sudo[1756]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl disable getty@tty1.service Mar 28 04:11:10 volumio sudo[1756]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 04:11:10 volumio sudo[1754]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop getty@tty1.service Mar 28 04:11:10 volumio sudo[1754]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 04:11:10 volumio sudo[1758]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl daemon-reload Mar 28 04:11:10 volumio sudo[1758]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 04:11:10 volumio systemd[1]: Reloading. Mar 28 04:11:10 volumio volumio[1543]: info: An error occurred while refreshing Spotify Token Error: getaddrinfo EBUSY oauth-performer.prod.vlmapi.io Mar 28 04:11:10 volumio volumio[1543]: info: touch_display: Backlight interface detected. Mar 28 04:11:10 volumio volumio[1543]: info: MPD Permissions set Mar 28 04:11:10 volumio volumio[1543]: info: MPD Permissions set Mar 28 04:11:10 volumio volumio[1543]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Mar 28 04:11:10 volumio volumio5-onboarding[1722]: time=2026-03-28T04:11:10.209-06:00 level=INFO msg="running volumio5-device-gateway" version=6370e0a8+CHANGES buildDate=2026-03-06T16:29:42Z Mar 28 04:11:10 volumio volumio[1543]: info: Spotify config file written Mar 28 04:11:10 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 04:11:10 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 04:11:10 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 04:11:10 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 04:11:10 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 04:11:10 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 04:11:10 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 04:11:10 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 04:11:10 volumio sudo[1781]: 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 04:11:10 volumio sudo[1781]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 04:11:10 volumio sudo[1789]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 28 04:11:10 volumio sudo[1789]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 04:11:10 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 28 04:11:10 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 04:11:10 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 04:11:10 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 04:11:10 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 04:11:10 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 04:11:10 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 04:11:10 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 04:11:10 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 04:11:10 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 04:11:10 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 28 04:11:10 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 04:11:10 volumio volumio[1543]: info: No need to fix Spotify hosts Mar 28 04:11:10 volumio sudo[1781]: pam_unix(sudo:session): session closed for user root Mar 28 04:11:10 volumio volumio[1543]: 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: 4 Mar 28 04:11:10 volumio volumio[1543]: info: touch_display: Raspberry Pi Foundation touch screen detected. Mar 28 04:11:10 volumio sudo[1803]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod a+w /sys/class/backlight/10-0045/brightness Mar 28 04:11:10 volumio sudo[1803]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 04:11:10 volumio sudo[1806]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod a+rw /etc/X11/xorg.conf.d/99-vc4.conf Mar 28 04:11:10 volumio sudo[1806]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 04:11:10 volumio sudo[1803]: pam_unix(sudo:session): session closed for user root Mar 28 04:11:10 volumio volumio[1543]: info: touch_display: IframeKeyboardBridge extension installed successfully Mar 28 04:11:10 volumio sudo[1806]: pam_unix(sudo:session): session closed for user root Mar 28 04:11:10 volumio sudo[1808]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod a+rw /etc/X11/xorg.conf.d/95-touch_display-plugin.conf Mar 28 04:11:10 volumio volumio[1543]: 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: 4 Mar 28 04:11:10 volumio volumio[1543]: info: Received Get System Info Mar 28 04:11:10 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 28 04:11:10 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 28 04:11:10 volumio sudo[1808]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 04:11:10 volumio sudo[1808]: pam_unix(sudo:session): session closed for user root Mar 28 04:11:10 volumio volumio[1543]: info: Discovery: Getting this device information Mar 28 04:11:10 volumio volumio[1543]: info: CoreCommandRouter::volumioGetState Mar 28 04:11:10 volumio volumio[1543]: info: CorePlayQueue::getTrack 0 Mar 28 04:11:10 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 28 04:11:10 volumio volumio5-onboarding[1722]: time=2026-03-28T04:11:10.304-06:00 level=INFO msg="system info for b1a3ee25d4507e8012d6836e70f54052" deviceName=Volumio deviceVariant=volumio deviceModel= softwareVersion=4.119 Mar 28 04:11:10 volumio volumio5-onboarding[1722]: time=2026-03-28T04:11:10.306-06:00 level=INFO msg="bootstrapping state" hasInternet=false Mar 28 04:11:10 volumio volumio[1543]: info: touch_display: File permissions for backlight brightness control set. Mar 28 04:11:10 volumio volumio[1543]: info: Starting Shairport Sync Mar 28 04:11:10 volumio volumio[1543]: info: Starting Shairport Sync Mar 28 04:11:10 volumio sudo[1813]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Mar 28 04:11:10 volumio sudo[1813]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 04:11:10 volumio volumio[1543]: info: Starting Shairport Sync Mar 28 04:11:10 volumio volumio[1543]: info: Received Get System Info Mar 28 04:11:10 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 28 04:11:10 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 28 04:11:10 volumio volumio[1543]: info: Discovery: Getting this device information Mar 28 04:11:10 volumio volumio[1543]: info: CoreCommandRouter::volumioGetState Mar 28 04:11:10 volumio volumio[1543]: info: CorePlayQueue::getTrack 0 Mar 28 04:11:10 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 28 04:11:10 volumio sudo[1818]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Mar 28 04:11:10 volumio volumio[1543]: info: touch_display: File permissions for /etc/X11/xorg.conf.d/95-touch_display-plugin.conf set. Mar 28 04:11:10 volumio sudo[1816]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Mar 28 04:11:10 volumio sudo[1816]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 04:11:10 volumio sudo[1818]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 04:11:10 volumio volumio[1543]: info: touch_display: File permissions for /etc/X11/xorg.conf.d/99-vc4.conf set. Mar 28 04:11:10 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Mar 28 04:11:10 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Mar 28 04:11:10 volumio volumio5-onboarding[1722]: time=2026-03-28T04:11:10.350-06:00 level=INFO msg="enabling local network discovery" Mar 28 04:11:10 volumio volumio[1543]: info: CoreCommandRouter::volumioGetState Mar 28 04:11:10 volumio volumio[1543]: info: CorePlayQueue::getTrack 0 Mar 28 04:11:10 volumio volumio5-onboarding[1722]: time=2026-03-28T04:11:10.360-06:00 level=INFO msg="enabling BLE discovery" Mar 28 04:11:10 volumio systemd[1]: Reloading. Mar 28 04:11:10 volumio sudo[1758]: pam_unix(sudo:session): session closed for user root Mar 28 04:11:10 volumio volumio[1543]: info: touch_display: systemctl daemon-reload succeeded. Mar 28 04:11:10 volumio sudo[1826]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumio-kiosk.service Mar 28 04:11:10 volumio sudo[1826]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 04:11:10 volumio sudo[1756]: pam_unix(sudo:session): session closed for user root Mar 28 04:11:10 volumio volumio[1543]: info: touch_display: systemctl disable getty@tty1.service succeeded. Mar 28 04:11:10 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 04:11:10 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 04:11:10 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 28 04:11:10 volumio go-librespot[1845]: go-librespot daemon starting... Mar 28 04:11:10 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Mar 28 04:11:10 volumio sudo[1789]: pam_unix(sudo:session): session closed for user root Mar 28 04:11:10 volumio systemd[1]: Started volumio-kiosk.service - Volumio Kiosk. Mar 28 04:11:10 volumio sudo[1826]: pam_unix(sudo:session): session closed for user root Mar 28 04:11:11 volumio volumio[1543]: info: touch_display: systemctl start volumio-kiosk.service succeeded. Mar 28 04:11:11 volumio volumio[1543]: info: touch_display: Volumio Kiosk started. Mar 28 04:11:11 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Mar 28 04:11:11 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Mar 28 04:11:11 volumio systemd[1]: shairport-sync.service: Consumed 1.612s CPU time. Mar 28 04:11:11 volumio volumio[1543]: info: CoreCommandRouter::volumioGetState Mar 28 04:11:11 volumio volumio[1543]: info: CorePlayQueue::getTrack 0 Mar 28 04:11:11 volumio volumio[1543]: info: CoreCommandRouter::volumioGetState Mar 28 04:11:11 volumio volumio[1543]: info: CorePlayQueue::getTrack 0 Mar 28 04:11:11 volumio sudo[1754]: pam_unix(sudo:session): session closed for user root Mar 28 04:11:11 volumio volumio[1543]: info: touch_display: systemctl stop getty@tty1.service succeeded. Mar 28 04:11:11 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Mar 28 04:11:11 volumio sudo[1818]: pam_unix(sudo:session): session closed for user root Mar 28 04:11:11 volumio sudo[1816]: pam_unix(sudo:session): session closed for user root Mar 28 04:11:11 volumio sudo[1813]: pam_unix(sudo:session): session closed for user root Mar 28 04:11:11 volumio volumio[1543]: info: Shairport-Sync Started Mar 28 04:11:11 volumio volumio[1543]: Error adding Membership: Error: addMembership EINVAL Mar 28 04:11:11 volumio volumio[1543]: info: Shairport-Sync Started Mar 28 04:11:11 volumio volumio[1543]: info: Shairport-Sync Started Mar 28 04:11:11 volumio volumio[1543]: info: touch_display: X display number found: Mar 28 04:11:11 volumio volumio[1543]: info: touch_display: X display number found: 0 Mar 28 04:11:11 volumio startx[1891]: X.Org X Server 1.21.1.7 Mar 28 04:11:11 volumio startx[1891]: X Protocol Version 11, Revision 0 Mar 28 04:11:11 volumio startx[1891]: Current Operating System: Linux volumio 6.12.74-v8+ #1948 SMP PREEMPT Mon Mar 2 11:30:34 GMT 2026 aarch64 Mar 28 04:11:11 volumio startx[1891]: Kernel command line: reboot=w coherent_pool=1M 8250.nr_uarts=1 pci=pcie_bus_safe cgroup_disable=memory numa_policy=interleave nvme.max_host_mem_size_mb=0 numa=fake=8 system_heap.max_order=0 iommu_dma_numa_policy=interleave smsc95xx.macaddr=2C:CF:67:03:8A:17 vc_mem.mem_base=0x3fc00000 vc_mem.mem_size=0x40000000 splash plymouth.ignore-serial-consoles dwc_otg.fiq_enable=1 dwc_otg.fiq_fsm_enable=1 dwc_otg.fiq_fsm_mask=0xF dwc_otg.nak_holdoff=1 quiet console=ttyAMA10,115200 console=tty1 imgpart=UUID=b0b466fc-4556-43af-9f97-ebe56fe4abe4 imgfile=/volumio_current.sqsh bootpart=UUID=0428-C7E4 datapart=UUID=82051e0e-a859-4f54-aa9f-0cc23a932af8 uuidconfig=cmdline.txt rootwait bootdelay=7 logo.nologo vt.global_cursor_default=0 net.ifnames=0 snd_bcm2835.enable_hdmi=1 snd_bcm2835.enable_headphones=1 loglevel=0 nodebug use_kmsg=no Mar 28 04:11:11 volumio startx[1891]: xorg-server 2:21.1.7-3+rpt3+deb12u11 (https://www.debian.org/support) Mar 28 04:11:11 volumio startx[1891]: Current version of pixman: 0.44.0 Mar 28 04:11:11 volumio startx[1891]: Before reporting problems, check http://wiki.x.org Mar 28 04:11:11 volumio startx[1891]: to make sure that you have the latest version. Mar 28 04:11:11 volumio startx[1891]: Markers: (--) probed, (**) from config file, (==) default setting, Mar 28 04:11:11 volumio startx[1891]: (++) from command line, (!!) notice, (II) informational, Mar 28 04:11:11 volumio startx[1891]: (WW) warning, (EE) error, (NI) not implemented, (??) unknown. Mar 28 04:11:11 volumio startx[1891]: (==) Log file: "/var/log/Xorg.0.log", Time: Sat Mar 28 04:11:11 2026 Mar 28 04:11:11 volumio startx[1891]: (==) Using config directory: "/etc/X11/xorg.conf.d" Mar 28 04:11:11 volumio startx[1891]: (==) Using system config directory "/usr/share/X11/xorg.conf.d" Mar 28 04:11:11 volumio volumio[1543]: info: touch_display: Using Xserver unix domain socket /tmp/.X11-unix/X0 Mar 28 04:11:11 volumio volumio[1543]: info: touch_display: X display number found: 0 Mar 28 04:11:11 volumio volumio5-onboarding[1722]: time=2026-03-28T04:11:11.268-06:00 level=INFO msg="service successfully established" component=discovery/localnet Mar 28 04:11:11 volumio go-librespot[1846]: time="2026-03-28T04:11:11-06:00" level=info msg="running go-librespot 0.6.2" Mar 28 04:11:11 volumio go-librespot[1846]: time="2026-03-28T04:11:11-06:00" level=debug msg="app state loaded" Mar 28 04:11:11 volumio go-librespot[1846]: time="2026-03-28T04:11:11-06:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 28 04:11:11 volumio go-librespot[1846]: time="2026-03-28T04:11:11-06: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 04:11:11 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 28 04:11:11 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 28 04:11:11 volumio wpa_supplicant[1432]: wlan0: Failed to initiate sched scan Mar 28 04:11:12 volumio mpd[1740]: 2026-03-28T04:11:12 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Mar 28 04:11:12 volumio systemd[1]: Started mpd.service - Music Player Daemon. Mar 28 04:11:12 volumio sudo[1694]: pam_unix(sudo:session): session closed for user root Mar 28 04:11:12 volumio sudo[1708]: pam_unix(sudo:session): session closed for user root Mar 28 04:11:12 volumio volumio[1543]: info: Completed starting Core Plugins Mar 28 04:11:12 volumio volumio[1543]: info: ------------------------------------------- Mar 28 04:11:12 volumio volumio[1543]: info: ----- MyVolumio plugins startup ---- Mar 28 04:11:12 volumio volumio[1543]: info: ------------------------------------------- Mar 28 04:11:12 volumio volumio[1543]: info: [MyVolumio PluginManager] Fetching plans data.... Mar 28 04:11:12 volumio volumio[1543]: error: MPD error: The expression evaluated to a falsy value: Mar 28 04:11:12 volumio volumio[1543]: assert.ok(self.idling) Mar 28 04:11:12 volumio volumio[1543]: error: The expression evaluated to a falsy value: Mar 28 04:11:12 volumio volumio[1543]: assert.ok(self.idling) Mar 28 04:11:12 volumio volumio[1543]: info: MPD running with PID1740 Mar 28 04:11:12 volumio volumio[1543]: ,establishing connection Mar 28 04:11:12 volumio volumio[1543]: error: MPD error: The expression evaluated to a falsy value: Mar 28 04:11:12 volumio volumio[1543]: assert.ok(self.idling) Mar 28 04:11:12 volumio volumio[1543]: error: The expression evaluated to a falsy value: Mar 28 04:11:12 volumio volumio[1543]: assert.ok(self.idling) Mar 28 04:11:12 volumio volumio[1543]: error: updateQueue error: null Mar 28 04:11:12 volumio volumio[1543]: info: Received Get System Info Mar 28 04:11:12 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 28 04:11:12 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 28 04:11:12 volumio volumio[1543]: info: Discovery: Getting this device information Mar 28 04:11:12 volumio volumio[1543]: info: CoreCommandRouter::volumioGetState Mar 28 04:11:12 volumio volumio[1543]: info: CorePlayQueue::getTrack 0 Mar 28 04:11:12 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 28 04:11:12 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Mar 28 04:11:12 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Mar 28 04:11:12 volumio startx[1890]: Mar 28 04:11:12 volumio volumio[1543]: info: CoreCommandRouter::volumioGetState Mar 28 04:11:12 volumio volumio[1543]: info: CorePlayQueue::getTrack 0 Mar 28 04:11:12 volumio kernel: drm-rp1-dsi 1f00118000.dsi: [drm] rp1dsi: Command time (outvact): 33 Mar 28 04:11:12 volumio kernel: drm-rp1-dsi 1f00118000.dsi: [drm] rp1dsi: Nominal Byte clock 90000000 DPI clock 30000000 (parent rate 90000000) Mar 28 04:11:13 volumio volumio[1543]: info: touch_display: Setting screensaver timeout to 120 seconds. Mar 28 04:11:13 volumio volumio5-onboarding[1722]: time=2026-03-28T04:11:13.236-06:00 level=INFO msg="service successfully established" component=discovery/localnet Mar 28 04:11:13 volumio startx[1890]: waiting for X server to begin accepting connections . Mar 28 04:11:13 volumio kernel: drm-rp1-dsi 1f00118000.dsi: [drm] rp1dsi: Command time (outvact): 33 Mar 28 04:11:13 volumio kernel: drm-rp1-dsi 1f00118000.dsi: [drm] rp1dsi: Nominal Byte clock 90000000 DPI clock 30000000 (parent rate 90000000) Mar 28 04:11:13 volumio systemd[1]: systemd-fsckd.service: Deactivated successfully. Mar 28 04:11:13 volumio volumio[1543]: info: go-librespot daemon successfully initialized Mar 28 04:11:14 volumio sh[943]: timed out Mar 28 04:11:14 volumio dhcpcd[954]: timed out Mar 28 04:11:14 volumio sh[887]: ifup: failed to bring up eth0 Mar 28 04:11:14 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Mar 28 04:11:14 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 28 04:11:14 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 28 04:11:14 volumio systemd[1]: ifup@eth0.service: Main process exited, code=exited, status=1/FAILURE Mar 28 04:11:14 volumio go-librespot[1981]: go-librespot daemon starting... Mar 28 04:11:14 volumio systemd[1]: ifup@eth0.service: Failed with result 'exit-code'. Mar 28 04:11:14 volumio go-librespot[1986]: time="2026-03-28T04:11:14-06:00" level=info msg="running go-librespot 0.6.2" Mar 28 04:11:14 volumio go-librespot[1986]: time="2026-03-28T04:11:14-06:00" level=debug msg="app state loaded" Mar 28 04:11:14 volumio go-librespot[1986]: time="2026-03-28T04:11:14-06:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 28 04:11:14 volumio go-librespot[1986]: time="2026-03-28T04:11:14-06: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 04:11:14 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 28 04:11:14 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 28 04:11:14 volumio systemd[1]: systemd-hostnamed.service: Deactivated successfully. Mar 28 04:11:15 volumio systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 2. Mar 28 04:11:15 volumio systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Mar 28 04:11:15 volumio systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Mar 28 04:11:15 volumio upmpdcli[2031]: Could not open config: /tmp/upmpdcli.conf Mar 28 04:11:15 volumio systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Mar 28 04:11:15 volumio systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Mar 28 04:11:16 volumio volumio[1543]: info: Initializing connection to go-librespot Websocket Mar 28 04:11:17 volumio volumio[1543]: info: Error connecting to go-librespot Websocket: AggregateError Mar 28 04:11:17 volumio volumio[1543]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Mar 28 04:11:17 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Mar 28 04:11:17 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 28 04:11:17 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 28 04:11:17 volumio go-librespot[2128]: go-librespot daemon starting... Mar 28 04:11:17 volumio go-librespot[2129]: time="2026-03-28T04:11:17-06:00" level=info msg="running go-librespot 0.6.2" Mar 28 04:11:17 volumio go-librespot[2129]: time="2026-03-28T04:11:17-06:00" level=debug msg="app state loaded" Mar 28 04:11:17 volumio go-librespot[2129]: time="2026-03-28T04:11:17-06:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 28 04:11:17 volumio go-librespot[2129]: time="2026-03-28T04:11:17-06: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 04:11:17 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 28 04:11:17 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 28 04:11:18 volumio sudo[2138]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 28 04:11:18 volumio sudo[2138]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 04:11:18 volumio sudo[2138]: pam_unix(sudo:session): session closed for user root Mar 28 04:11:18 volumio sudo[2136]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Mar 28 04:11:18 volumio sudo[2136]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 04:11:18 volumio sudo[2136]: pam_unix(sudo:session): session closed for user root Mar 28 04:11:18 volumio sudo[2142]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Mar 28 04:11:18 volumio sudo[2142]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 28 04:11:18 volumio volumio[1543]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: Mozilla/5.0 (X11; CrOS x86_64 14541.0.0) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/144.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 5 Mar 28 04:11:18 volumio volumio[1543]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: Mozilla/5.0 (X11; CrOS x86_64 14541.0.0) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/144.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 6 Mar 28 04:11:18 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Mar 28 04:11:18 volumio volumio[1543]: info: CoreCommandRouter::volumioGetVisibleSources Mar 28 04:11:18 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 28 04:11:18 volumio volumio[1543]: info: CoreCommandRouter::volumioGetState Mar 28 04:11:18 volumio volumio[1543]: info: CorePlayQueue::getTrack 0 Mar 28 04:11:18 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Mar 28 04:11:18 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Mar 28 04:11:18 volumio volumio[1543]: info: Received Get System Info Mar 28 04:11:18 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 28 04:11:18 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 28 04:11:18 volumio volumio[1543]: info: Discovery: Getting this device information Mar 28 04:11:18 volumio volumio[1543]: info: CoreCommandRouter::volumioGetState Mar 28 04:11:18 volumio volumio[1543]: info: CorePlayQueue::getTrack 0 Mar 28 04:11:18 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 28 04:11:18 volumio volumio[1543]: info: CoreCommandRouter::volumioGetState Mar 28 04:11:18 volumio volumio[1543]: info: CorePlayQueue::getTrack 0 Mar 28 04:11:18 volumio volumio[1543]: info: Listing playlists Mar 28 04:11:18 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Mar 28 04:11:18 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Mar 28 04:11:19 volumio wpa_supplicant[1432]: wlan0: Trying to associate with e0:d3:62:03:4b:ab (SSID='TP-Link_4BAC' freq=2452 MHz) Mar 28 04:11:19 volumio wpa_supplicant[1432]: wlan0: Associated with e0:d3:62:03:4b:ab Mar 28 04:11:19 volumio wpa_supplicant[1432]: wlan0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0 Mar 28 04:11:19 volumio wpa_supplicant[1432]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=COUNTRY_IE type=COUNTRY alpha2=US Mar 28 04:11:20 volumio volumio[1543]: info: Initializing connection to go-librespot Websocket Mar 28 04:11:20 volumio volumio[1543]: info: Error connecting to go-librespot Websocket: AggregateError Mar 28 04:11:20 volumio volumio[1543]: info: Cannot call home: Error: Command failed: /usr/bin/curl -X POST --data-binary "device=pi&variante=volumio&version=4.119&uuid=b1a3ee25d4507e8012d6836e70f54052" http://updates.volumio.org/downloader-v1/track-device Mar 28 04:11:20 volumio volumio[1543]: % Total % Received % Xferd Average Speed Time Time Time Current Mar 28 04:11:20 volumio volumio[1543]: Dload Upload Total Spent Left Speed Mar 28 04:11:20 volumio volumio[1543]: [132B blob data] Mar 28 04:11:20 volumio volumio[1543]: retrying in 5 seconds, trial 0 Mar 28 04:11:20 volumio volumio[1543]: info: Volumio Calling Home Mar 28 04:11:20 volumio volumio[1543]: info: Received Get System Info Mar 28 04:11:20 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 28 04:11:20 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 28 04:11:20 volumio volumio[1543]: info: Discovery: Getting this device information Mar 28 04:11:20 volumio volumio[1543]: info: CoreCommandRouter::volumioGetState Mar 28 04:11:20 volumio volumio[1543]: info: CorePlayQueue::getTrack 0 Mar 28 04:11:20 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 28 04:11:20 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Mar 28 04:11:20 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Mar 28 04:11:20 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Mar 28 04:11:20 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Mar 28 04:11:20 volumio volumio[1543]: info: Received Get System Info Mar 28 04:11:20 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 28 04:11:20 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 28 04:11:20 volumio volumio[1543]: info: Discovery: Getting this device information Mar 28 04:11:20 volumio volumio[1543]: info: CoreCommandRouter::volumioGetState Mar 28 04:11:20 volumio volumio[1543]: info: CorePlayQueue::getTrack 0 Mar 28 04:11:20 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 28 04:11:20 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Mar 28 04:11:20 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 28 04:11:21 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 28 04:11:21 volumio go-librespot[2149]: go-librespot daemon starting... Mar 28 04:11:21 volumio go-librespot[2150]: time="2026-03-28T04:11:21-06:00" level=info msg="running go-librespot 0.6.2" Mar 28 04:11:21 volumio go-librespot[2150]: time="2026-03-28T04:11:21-06:00" level=debug msg="app state loaded" Mar 28 04:11:21 volumio go-librespot[2150]: time="2026-03-28T04:11:21-06:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 28 04:11:21 volumio go-librespot[2150]: time="2026-03-28T04:11:21-06: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 04:11:21 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 28 04:11:21 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 28 04:11:21 volumio volumio5-onboarding[1722]: time=2026-03-28T04:11:21.182-06:00 level=INFO msg="service successfully established" component=discovery/localnet Mar 28 04:11:22 volumio wpa_supplicant[1432]: wlan0: CTRL-EVENT-DISCONNECTED bssid=e0:d3:62:03:4b:ab reason=2 Mar 28 04:11:22 volumio wpa_supplicant[1432]: wlan0: WPA: 4-Way Handshake failed - pre-shared key may be incorrect Mar 28 04:11:22 volumio wpa_supplicant[1432]: wlan0: CTRL-EVENT-SSID-TEMP-DISABLED id=2 ssid="TP-Link_4BAC" auth_failures=1 duration=10 reason=WRONG_KEY Mar 28 04:11:22 volumio dhcpcd[988]: wlan0: carrier lost Mar 28 04:11:22 volumio wpa_supplicant[1432]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=CORE type=WORLD Mar 28 04:11:23 volumio volumio[1543]: info: Initializing connection to go-librespot Websocket Mar 28 04:11:23 volumio volumio[1543]: info: Error connecting to go-librespot Websocket: AggregateError Mar 28 04:11:23 volumio volumio[1543]: info: Received Get System Info Mar 28 04:11:23 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 28 04:11:23 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 28 04:11:23 volumio volumio[1543]: info: Discovery: Getting this device information Mar 28 04:11:23 volumio volumio[1543]: info: CoreCommandRouter::volumioGetState Mar 28 04:11:23 volumio volumio[1543]: info: CorePlayQueue::getTrack 0 Mar 28 04:11:23 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 28 04:11:23 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Mar 28 04:11:23 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Mar 28 04:11:24 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 4. Mar 28 04:11:24 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 28 04:11:24 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 28 04:11:24 volumio go-librespot[2163]: go-librespot daemon starting... Mar 28 04:11:24 volumio go-librespot[2164]: time="2026-03-28T04:11:24-06:00" level=info msg="running go-librespot 0.6.2" Mar 28 04:11:24 volumio go-librespot[2164]: time="2026-03-28T04:11:24-06:00" level=debug msg="app state loaded" Mar 28 04:11:24 volumio go-librespot[2164]: time="2026-03-28T04:11:24-06:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 28 04:11:24 volumio go-librespot[2164]: time="2026-03-28T04:11:24-06: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 04:11:24 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 28 04:11:24 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 28 04:11:24 volumio volumio5-onboarding[1722]: time=2026-03-28T04:11:24.305-06:00 level=INFO msg="service successfully established" component=discovery/localnet Mar 28 04:11:26 volumio volumio[1543]: info: Initializing connection to go-librespot Websocket Mar 28 04:11:26 volumio volumio[1543]: info: Error connecting to go-librespot Websocket: AggregateError Mar 28 04:11:26 volumio volumio[1543]: info: Received Get System Info Mar 28 04:11:26 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 28 04:11:26 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 28 04:11:26 volumio volumio[1543]: info: Discovery: Getting this device information Mar 28 04:11:26 volumio volumio[1543]: info: CoreCommandRouter::volumioGetState Mar 28 04:11:26 volumio volumio[1543]: info: CorePlayQueue::getTrack 0 Mar 28 04:11:26 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 28 04:11:26 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Mar 28 04:11:26 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Mar 28 04:11:27 volumio volumio5-onboarding[1722]: time=2026-03-28T04:11:27.164-06:00 level=INFO msg="service successfully established" component=discovery/localnet Mar 28 04:11:27 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 5. Mar 28 04:11:27 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 28 04:11:27 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 28 04:11:27 volumio go-librespot[2170]: go-librespot daemon starting... Mar 28 04:11:27 volumio go-librespot[2171]: time="2026-03-28T04:11:27-06:00" level=info msg="running go-librespot 0.6.2" Mar 28 04:11:27 volumio go-librespot[2171]: time="2026-03-28T04:11:27-06:00" level=debug msg="app state loaded" Mar 28 04:11:27 volumio go-librespot[2171]: time="2026-03-28T04:11:27-06:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 28 04:11:27 volumio go-librespot[2171]: time="2026-03-28T04:11:27-06: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 04:11:27 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 28 04:11:27 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 28 04:11:28 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Mar 28 04:11:29 volumio volumio[1543]: info: Initializing connection to go-librespot Websocket Mar 28 04:11:29 volumio volumio[1543]: info: Error connecting to go-librespot Websocket: AggregateError Mar 28 04:11:30 volumio volumio[1543]: info: Cannot call home: Error: Command failed: /usr/bin/curl -X POST --data-binary "device=pi&variante=volumio&version=4.119&uuid=b1a3ee25d4507e8012d6836e70f54052" http://updates.volumio.org/downloader-v1/track-device Mar 28 04:11:30 volumio volumio[1543]: % Total % Received % Xferd Average Speed Time Time Time Current Mar 28 04:11:30 volumio volumio[1543]: Dload Upload Total Spent Left Speed Mar 28 04:11:30 volumio volumio[1543]: [132B blob data] Mar 28 04:11:30 volumio volumio[1543]: retrying in 5 seconds, trial 1 Mar 28 04:11:30 volumio volumio[1543]: info: Volumio Calling Home Mar 28 04:11:30 volumio systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 3. Mar 28 04:11:30 volumio systemd[1]: Starting setdatetime-helper.service - Time Synchronization Helper Service... Mar 28 04:11:30 volumio systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Mar 28 04:11:30 volumio systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Mar 28 04:11:30 volumio sudo[2142]: pam_unix(sudo:session): session closed for user root Mar 28 04:11:30 volumio volumio[1543]: info: Upmpdcli Daemon Started Mar 28 04:11:30 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6. Mar 28 04:11:30 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 28 04:11:30 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 28 04:11:30 volumio go-librespot[2214]: go-librespot daemon starting... Mar 28 04:11:30 volumio go-librespot[2217]: time="2026-03-28T04:11:30-06:00" level=info msg="running go-librespot 0.6.2" Mar 28 04:11:30 volumio go-librespot[2217]: time="2026-03-28T04:11:30-06:00" level=debug msg="app state loaded" Mar 28 04:11:30 volumio go-librespot[2217]: time="2026-03-28T04:11:30-06:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 28 04:11:30 volumio go-librespot[2217]: time="2026-03-28T04:11:30-06: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 04:11:30 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 28 04:11:30 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 28 04:11:32 volumio volumio[1543]: info: Initializing connection to go-librespot Websocket Mar 28 04:11:32 volumio volumio[1543]: info: Error connecting to go-librespot Websocket: AggregateError Mar 28 04:11:32 volumio volumio[1543]: error: MyVolumio Plugin failed to start in a timely fashion Mar 28 04:11:32 volumio volumio[1543]: [Metrics] CommandRouter: 25s 267.36ms Mar 28 04:11:32 volumio volumio[1543]: info: CoreCommandRouter::volumiosetStartupVolume Mar 28 04:11:32 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 28 04:11:32 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 28 04:11:32 volumio volumio[1543]: info: CoreCommandRouter::Close All Modals sent Mar 28 04:11:32 volumio volumio[1543]: info: CoreCommandRouter::Close All Modals sent Mar 28 04:11:33 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable Mar 28 04:11:33 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Mar 28 04:11:33 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect Mar 28 04:11:33 volumio wpa_supplicant[1432]: wlan0: Trying to associate with e2:d3:62:03:4b:aa (SSID='TP-Link_Guest_4BAC_5G' freq=5805 MHz) Mar 28 04:11:33 volumio wpa_supplicant[1432]: wlan0: Associated with e2:d3:62:03:4b:aa Mar 28 04:11:33 volumio wpa_supplicant[1432]: wlan0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0 Mar 28 04:11:33 volumio wpa_supplicant[1432]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=COUNTRY_IE type=COUNTRY alpha2=US Mar 28 04:11:33 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 7. Mar 28 04:11:33 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 28 04:11:33 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 28 04:11:33 volumio go-librespot[2244]: go-librespot daemon starting... Mar 28 04:11:33 volumio go-librespot[2245]: time="2026-03-28T04:11:33-06:00" level=info msg="running go-librespot 0.6.2" Mar 28 04:11:33 volumio go-librespot[2245]: time="2026-03-28T04:11:33-06:00" level=debug msg="app state loaded" Mar 28 04:11:33 volumio go-librespot[2245]: time="2026-03-28T04:11:33-06:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 28 04:11:33 volumio go-librespot[2245]: time="2026-03-28T04:11:33-06: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 04:11:33 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 28 04:11:33 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 28 04:11:33 volumio wpa_supplicant[1432]: wlan0: WPA: Key negotiation completed with e2:d3:62:03:4b:aa [PTK=CCMP GTK=CCMP] Mar 28 04:11:33 volumio wpa_supplicant[1432]: wlan0: CTRL-EVENT-CONNECTED - Connection to e2:d3:62:03:4b:aa completed [id=1 id_str=] Mar 28 04:11:33 volumio dhcpcd[988]: wlan0: carrier acquired Mar 28 04:11:33 volumio dhcpcd[988]: wlan0: connected to Access Point: TP-Link_Guest_4BAC_5G Mar 28 04:11:33 volumio dhcpcd[988]: wlan0: IAID 67:03:8a:18 Mar 28 04:11:33 volumio dhcpcd[988]: wlan0: adding address fe80::bf9c:62ad:3931:b87b Mar 28 04:11:33 volumio dhcpcd[988]: ipv6_addaddr1: Permission denied Mar 28 04:11:33 volumio dhcpcd[988]: wlan0: soliciting an IPv6 router Mar 28 04:11:34 volumio dhcpcd[988]: wlan0: soliciting a DHCP lease Mar 28 04:11:34 volumio volumio[1543]: info: Received Get System Info Mar 28 04:11:34 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 28 04:11:34 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 28 04:11:34 volumio volumio[1543]: info: Discovery: Getting this device information Mar 28 04:11:34 volumio volumio[1543]: info: CoreCommandRouter::volumioGetState Mar 28 04:11:34 volumio volumio[1543]: info: CorePlayQueue::getTrack 0 Mar 28 04:11:34 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 28 04:11:34 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Mar 28 04:11:34 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Mar 28 04:11:35 volumio volumio[1543]: info: Initializing connection to go-librespot Websocket Mar 28 04:11:35 volumio volumio[1543]: info: Error connecting to go-librespot Websocket: AggregateError Mar 28 04:11:35 volumio volumio5-onboarding[1722]: time=2026-03-28T04:11:35.154-06:00 level=INFO msg="service successfully established" component=discovery/localnet Mar 28 04:11:35 volumio bash[2196]: setdatetime-helper: all HTTPS Date fallbacks failed Mar 28 04:11:35 volumio systemd[1]: setdatetime-helper.service: Deactivated successfully. Mar 28 04:11:35 volumio systemd[1]: Finished setdatetime-helper.service - Time Synchronization Helper Service. Mar 28 04:11:36 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 8. Mar 28 04:11:36 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 28 04:11:37 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 28 04:11:37 volumio go-librespot[2266]: go-librespot daemon starting... Mar 28 04:11:37 volumio go-librespot[2267]: time="2026-03-28T04:11:37-06:00" level=info msg="running go-librespot 0.6.2" Mar 28 04:11:37 volumio go-librespot[2267]: time="2026-03-28T04:11:37-06:00" level=debug msg="app state loaded" Mar 28 04:11:37 volumio go-librespot[2267]: time="2026-03-28T04:11:37-06:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 28 04:11:37 volumio go-librespot[2267]: time="2026-03-28T04:11:37-06: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 04:11:37 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 28 04:11:37 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 28 04:11:38 volumio volumio[1543]: info: Initializing connection to go-librespot Websocket Mar 28 04:11:38 volumio volumio[1543]: info: Error connecting to go-librespot Websocket: AggregateError Mar 28 04:11:39 volumio volumio[1543]: info: BOOT COMPLETED Mar 28 04:11:39 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 28 04:11:39 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 28 04:11:39 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Mar 28 04:11:40 volumio volumio[1543]: info: Cannot call home: Error: Command failed: /usr/bin/curl -X POST --data-binary "device=pi&variante=volumio&version=4.119&uuid=b1a3ee25d4507e8012d6836e70f54052" http://updates.volumio.org/downloader-v1/track-device Mar 28 04:11:40 volumio volumio[1543]: % Total % Received % Xferd Average Speed Time Time Time Current Mar 28 04:11:40 volumio volumio[1543]: Dload Upload Total Spent Left Speed Mar 28 04:11:40 volumio volumio[1543]: [132B blob data] Mar 28 04:11:40 volumio volumio[1543]: retrying in 5 seconds, trial 2 Mar 28 04:11:40 volumio volumio[1543]: info: Volumio Calling Home Mar 28 04:11:40 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 9. Mar 28 04:11:40 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 28 04:11:40 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 28 04:11:40 volumio go-librespot[2293]: go-librespot daemon starting... Mar 28 04:11:40 volumio go-librespot[2294]: time="2026-03-28T04:11:40-06:00" level=info msg="running go-librespot 0.6.2" Mar 28 04:11:40 volumio go-librespot[2294]: time="2026-03-28T04:11:40-06:00" level=debug msg="app state loaded" Mar 28 04:11:40 volumio go-librespot[2294]: time="2026-03-28T04:11:40-06:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 28 04:11:40 volumio go-librespot[2294]: time="2026-03-28T04:11:40-06: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 04:11:40 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 28 04:11:40 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 28 04:11:41 volumio volumio[1543]: info: Initializing connection to go-librespot Websocket Mar 28 04:11:41 volumio volumio[1543]: info: Error connecting to go-librespot Websocket: AggregateError Mar 28 04:11:41 volumio dhcpcd[988]: wlan0: offered 192.168.0.155 from 192.168.0.1 Mar 28 04:11:41 volumio dhcpcd[988]: wlan0: probing address 192.168.0.155/24 Mar 28 04:11:43 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 10. Mar 28 04:11:43 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 28 04:11:43 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 28 04:11:43 volumio go-librespot[2301]: go-librespot daemon starting... Mar 28 04:11:43 volumio go-librespot[2302]: time="2026-03-28T04:11:43-06:00" level=info msg="running go-librespot 0.6.2" Mar 28 04:11:43 volumio go-librespot[2302]: time="2026-03-28T04:11:43-06:00" level=debug msg="app state loaded" Mar 28 04:11:43 volumio go-librespot[2302]: time="2026-03-28T04:11:43-06:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 28 04:11:43 volumio go-librespot[2302]: time="2026-03-28T04:11:43-06: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 04:11:43 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 28 04:11:43 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 28 04:11:44 volumio volumio[1543]: info: Initializing connection to go-librespot Websocket Mar 28 04:11:44 volumio volumio[1543]: info: Error connecting to go-librespot Websocket: AggregateError Mar 28 04:11:46 volumio dhcpcd[988]: wlan0: leased 192.168.0.155 for 7200 seconds Mar 28 04:11:46 volumio avahi-daemon[961]: Joining mDNS multicast group on interface wlan0.IPv4 with address 192.168.0.155. Mar 28 04:11:46 volumio avahi-daemon[961]: New relevant interface wlan0.IPv4 for mDNS. Mar 28 04:11:46 volumio avahi-daemon[961]: Registering new address record for 192.168.0.155 on wlan0.IPv4. Mar 28 04:11:46 volumio dhcpcd[988]: wlan0: adding route to 192.168.0.0/24 Mar 28 04:11:46 volumio systemd[1]: welcome.service: Deactivated successfully. Mar 28 04:11:46 volumio systemd[1]: Stopped welcome.service - Show a welcome message on console. Mar 28 04:11:46 volumio systemd[1]: Stopping welcome.service - Show a welcome message on console... Mar 28 04:11:46 volumio systemd[1]: Starting welcome.service - Show a welcome message on console... Mar 28 04:11:46 volumio welcome[2326]: Resolved ip:[1] 192.168.0.155 Mar 28 04:11:46 volumio systemd[1]: Finished welcome.service - Show a welcome message on console. Mar 28 04:11:46 volumio dhcpcd[988]: wlan0: adding default route via 192.168.0.1 Mar 28 04:11:46 volumio systemd[1]: Reached target ip-changed@wlan0.target - IP Address changed on wlan0. Mar 28 04:11:46 volumio systemd[1]: Started nmbd.service - Samba NMB Daemon. Mar 28 04:11:46 volumio systemd[1]: Starting winbind.service - Samba Winbind Daemon... Mar 28 04:11:46 volumio winbindd[2340]: [2026/03/28 04:11:46.564662, 0] ../../source3/winbindd/winbindd.c:1440(main) Mar 28 04:11:46 volumio winbindd[2340]: winbindd version 4.17.8-Raspbian started. Mar 28 04:11:46 volumio winbindd[2340]: Copyright Andrew Tridgell and the Samba Team 1992-2022 Mar 28 04:11:46 volumio winbindd[2340]: [2026/03/28 04:11:46.569278, 0] ../../source3/winbindd/winbindd_cache.c:3116(initialize_winbindd_cache) Mar 28 04:11:46 volumio winbindd[2340]: initialize_winbindd_cache: clearing cache and re-creating with version number 2 Mar 28 04:11:46 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 11. Mar 28 04:11:46 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 28 04:11:46 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 28 04:11:46 volumio systemd[1]: Started winbind.service - Samba Winbind Daemon. Mar 28 04:11:46 volumio go-librespot[2343]: go-librespot daemon starting... Mar 28 04:11:46 volumio systemd[1]: Starting smbd.service - Samba SMB Daemon... Mar 28 04:11:46 volumio go-librespot[2346]: time="2026-03-28T04:11:46-06:00" level=info msg="running go-librespot 0.6.2" Mar 28 04:11:46 volumio go-librespot[2346]: time="2026-03-28T04:11:46-06:00" level=debug msg="app state loaded" Mar 28 04:11:46 volumio go-librespot[2346]: time="2026-03-28T04:11:46-06:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 28 04:11:46 volumio smbd[2355]: [2026/03/28 04:11:46.708396, 0] ../../source3/smbd/server.c:1741(main) Mar 28 04:11:46 volumio smbd[2355]: smbd version 4.17.8-Raspbian started. Mar 28 04:11:46 volumio smbd[2355]: Copyright Andrew Tridgell and the Samba Team 1992-2022 Mar 28 04:11:46 volumio volumio[1543]: info: Received Get System Info Mar 28 04:11:46 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 28 04:11:46 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 28 04:11:46 volumio volumio[1543]: info: Discovery: Getting this device information Mar 28 04:11:46 volumio volumio[1543]: info: CoreCommandRouter::volumioGetState Mar 28 04:11:46 volumio volumio[1543]: info: CorePlayQueue::getTrack 0 Mar 28 04:11:46 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 28 04:11:46 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Mar 28 04:11:46 volumio volumio[1543]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Mar 28 04:11:46 volumio systemd[1]: Started smbd.service - Samba SMB Daemon. Mar 28 04:11:46 volumio systemd[1]: Reached target multi-user.target - Multi-User System. Mar 28 04:11:46 volumio systemd[1]: Reached target graphical.target - Graphical Interface. Mar 28 04:11:46 volumio systemd[1]: Starting systemd-update-utmp-runlevel.service - Record Runlevel Change in UTMP... Mar 28 04:11:46 volumio systemd[1]: systemd-update-utmp-runlevel.service: Deactivated successfully. Mar 28 04:11:46 volumio systemd[1]: Finished systemd-update-utmp-runlevel.service - Record Runlevel Change in UTMP. Mar 28 04:11:46 volumio systemd[1]: Startup finished in 12.111s (kernel) + 1min 4.400s (userspace) = 1min 16.512s. Mar 28 04:11:47 volumio volumio[1543]: info: Initializing connection to go-librespot Websocket Mar 28 04:11:47 volumio volumio[1543]: info: Connection to go-librespot Websocket established Mar 28 04:11:47 volumio go-librespot[2346]: time="2026-03-28T04:11:47-06:00" level=debug msg="new websocket client" Mar 28 04:11:47 volumio volumio5-onboarding[1722]: time=2026-03-28T04:11:47.750-06:00 level=INFO msg="service successfully established" component=discovery/localnet Mar 28 04:11:47 volumio volumio[1543]: info: Volumio Network Manager: Network status updated: 2 Mar 28 04:11:48 volumio ntpd[1244]: IO: Listen normally on 3 wlan0 192.168.0.155:123 Mar 28 04:11:48 volumio ntpd[1244]: IO: new interface(s) found: waking up resolver Mar 28 04:11:48 volumio ntpd[1244]: DNS: dns_probe: 3.debian.pool.ntp.org, cast_flags:8, flags:101 Mar 28 04:11:50 volumio volumio[1543]: info: Getting Spotify volume Mar 28 04:11:50 volumio volumio[1543]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Mar 28 04:11:50 volumio volumio[1543]: info: CoreCommandRouter::volumioGetState Mar 28 04:11:50 volumio volumio[1543]: info: CorePlayQueue::getTrack 0 Mar 28 04:11:50 volumio volumio[1543]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Mar 28 04:11:50 volumio volumio[1543]: SPOTIFY: SPOTIFY VOLUME undefined Mar 28 04:11:50 volumio volumio[1543]: SPOTIFY: VOLUMIO VOLUME 86 Mar 28 04:11:50 volumio volumio[1543]: info: Aligning Spotify Volume to Volumio Volume Mar 28 04:11:50 volumio volumio[1543]: info: CoreCommandRouter::volumioGetState Mar 28 04:11:50 volumio volumio[1543]: info: CorePlayQueue::getTrack 0 Mar 28 04:11:50 volumio volumio[1543]: info: Setting Spotify Volume from Volumio: 86 Mar 28 04:11:51 volumio volumio[1543]: SPOTIFY: SETTING SPOTIFY VOLUME 86 Mar 28 04:11:51 volumio volumio[1543]: info: Sending Spotify command with payload to local API: /player/volume Mar 28 04:11:52 volumio upmpdcli[2398]: writing RSA key Mar 28 04:12:04 volumio go-librespot[2346]: time="2026-03-28T04:12:04-06: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 04:12:04 volumio volumio[1543]: error: Failed to send command to Spotify local API: /player/volume: Error: socket hang up Mar 28 04:12:04 volumio volumio[1543]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 28 04:12:04 volumio volumio[1543]: Error: socket hang up Mar 28 04:12:04 volumio volumio[1543]: at connResetException (node:internal/errors:720:14) Mar 28 04:12:04 volumio volumio[1543]: at Socket.socketOnEnd (node:_http_client:519:23) Mar 28 04:12:04 volumio volumio[1543]: at Socket.emit (node:events:526:35) Mar 28 04:12:04 volumio volumio[1543]: at endReadableNT (node:internal/streams/readable:1376:12) Mar 28 04:12:04 volumio volumio[1543]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { Mar 28 04:12:04 volumio volumio[1543]: code: 'ECONNRESET', Mar 28 04:12:04 volumio volumio[1543]: response: undefined Mar 28 04:12:04 volumio volumio[1543]: } Mar 28 04:12:04 volumio volumio[1543]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 28 04:12:04 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 28 04:12:04 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 28 04:12:04 volumio sudo[2433]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-03-28 04:11' Mar 28 04:12:04 volumio sudo[2433]: 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"