Sep 08 16:32:00 volumio volumio5-onboarding[1675]: time=2026-09-08T16:32:00.873+02:00 level=WARN msg="reconnection attempt failed" error="read tcp 127.0.0.1:38386->127.0.0.1:3000: i/o timeout" Sep 08 16:32:01 volumio sudo[2196]: pam_unix(sudo:session): session closed for user root Sep 08 16:32:03 volumio go-librespot[2171]: time="2026-09-08T16:32:03+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Sep 08 16:32:03 volumio go-librespot[2171]: time="2026-09-08T16:32:03+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Sep 08 16:32:03 volumio go-librespot[2171]: time="2026-09-08T16:32:03+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Sep 08 16:32:03 volumio go-librespot[2171]: time="2026-09-08T16:32:03+02:00" level=info msg="zeroconf server listening on port 44017" Sep 08 16:32:03 volumio go-librespot[2171]: time="2026-09-08T16:32:03+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Sep 08 16:32:04 volumio volumio[2136]: info: Starting UPNP Browser Sep 08 16:32:04 volumio volumio[2136]: info: Loading plugin "alarm-clock"... Sep 08 16:32:04 volumio volumio[2136]: info: Loading plugin "airplay_emulation"... Sep 08 16:32:04 volumio go-librespot[2171]: time="2026-09-08T16:32:04+02:00" level=debug msg="avahi service \"Volumio\" established" Sep 08 16:32:04 volumio volumio[2136]: info: Starting Shairport Sync Sep 08 16:32:04 volumio volumio[2136]: info: Loading plugin "last_100"... Sep 08 16:32:04 volumio volumio[2136]: info: Loading plugin "webradio"... Sep 08 16:32:05 volumio volumio[2136]: info: Loading plugin "i2s_dacs"... Sep 08 16:32:05 volumio volumio[2136]: info: Loading plugin "volumiodiscovery"... Sep 08 16:32:05 volumio volumio[2136]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Sep 08 16:32:05 volumio node[2136]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Sep 08 16:32:05 volumio volumio[2136]: *** WARNING *** Please fix your application to use the native API of Avahi! Sep 08 16:32:05 volumio node[2136]: *** WARNING *** Please fix your application to use the native API of Avahi! Sep 08 16:32:05 volumio volumio[2136]: *** WARNING *** For more information see Sep 08 16:32:05 volumio node[2136]: *** WARNING *** For more information see Sep 08 16:32:05 volumio volumio[2136]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Sep 08 16:32:05 volumio node[2136]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Sep 08 16:32:05 volumio volumio[2136]: *** WARNING *** Please fix your application to use the native API of Avahi! Sep 08 16:32:05 volumio node[2136]: *** WARNING *** Please fix your application to use the native API of Avahi! Sep 08 16:32:05 volumio volumio[2136]: *** WARNING *** For more information see Sep 08 16:32:05 volumio node[2136]: *** WARNING *** For more information see Sep 08 16:32:05 volumio volumio[2136]: info: Applying required configuration parameters for plugin volumiodiscovery Sep 08 16:32:05 volumio volumio[2136]: info: Discovery: Started advertising with name: Volumio Sep 08 16:32:05 volumio volumio[2136]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Sep 08 16:32:05 volumio volumio[2136]: info: Loading plugin "spop"... Sep 08 16:32:08 volumio volumio[2136]: info: Loading plugin "outputs"... Sep 08 16:32:08 volumio volumio[2136]: info: Loading plugin "albumart"... Sep 08 16:32:08 volumio volumio[2136]: info: Plugin example_plugin is not enabled Sep 08 16:32:08 volumio volumio[2136]: info: Loading plugin "inputs"... Sep 08 16:32:08 volumio volumio[2136]: info: Loading plugin "updater_comm"... Sep 08 16:32:09 volumio volumio[2136]: info: Plugin mpdemulation is not enabled Sep 08 16:32:09 volumio volumio[2136]: info: Loading plugin "rest_api"... Sep 08 16:32:09 volumio volumio[2136]: info: Loading plugin "websocket"... Sep 08 16:32:09 volumio volumio[2136]: info: Starting Socket.io Server version 1.7.4 Sep 08 16:32:09 volumio volumio[2136]: info: Loading i18n strings for locale en Sep 08 16:32:09 volumio volumio[2136]: Updating browse sources language Sep 08 16:32:09 volumio volumio[2136]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 08 16:32:10 volumio volumio[2136]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Sep 08 16:32:10 volumio volumio[2136]: info: CoreCommandRouter::initPlayerControls Sep 08 16:32:10 volumio volumio[2136]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 08 16:32:10 volumio volumio[2136]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 08 16:32:10 volumio volumio[2136]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 08 16:32:10 volumio volumio[2136]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 08 16:32:10 volumio volumio[2136]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 08 16:32:10 volumio volumio[2136]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 08 16:32:10 volumio volumio[2136]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 08 16:32:10 volumio volumio[2136]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 08 16:32:10 volumio volumio[2136]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Sep 08 16:32:10 volumio volumio[2136]: Express server listening on port 3000 Sep 08 16:32:10 volumio volumio[2136]: [Metrics] WebUI: 20s 793.97ms Sep 08 16:32:11 volumio volumio[2136]: info: CoreStateMachine::resetVolumioState Sep 08 16:32:11 volumio volumio[2136]: info: CoreStateMachine::getcurrentVolume Sep 08 16:32:11 volumio volumio[2136]: info: CoreCommandRouter::volumioRetrievevolume Sep 08 16:32:11 volumio sudo[2265]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Sep 08 16:32:11 volumio sudo[2265]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 08 16:32:11 volumio sudo[2265]: pam_unix(sudo:session): session closed for user root Sep 08 16:32:11 volumio sudo[2267]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Sep 08 16:32:11 volumio sudo[2267]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 08 16:32:11 volumio sudo[2267]: pam_unix(sudo:session): session closed for user root Sep 08 16:32:11 volumio volumio[2136]: info: Volumio Network Manager: Network status updated: 2 Sep 08 16:32:11 volumio volumio5-onboarding[1675]: time=2026-09-08T16:32:11.875+02:00 level=WARN msg="reconnection attempt failed" error="read tcp 127.0.0.1:52580->127.0.0.1:3000: i/o timeout" Sep 08 16:32:12 volumio volumio5-onboarding[1675]: time=2026-09-08T16:32:12.059+02:00 level=ERROR msg="failed to update discovery on Wi-Fi info change" error="failed to get system info: could not get system info: context deadline exceeded" Sep 08 16:32:12 volumio volumio[2250]: Forking 3 albumart workers Sep 08 16:32:12 volumio volumio-remote-updater[686]: [2026-09-08 16:32:12] [connect] Successful connection Sep 08 16:32:13 volumio volumio[2136]: info: VolumeController:: Volume=50 Mute =false Sep 08 16:32:13 volumio volumio[2136]: info: CoreStateMachine::pushState Sep 08 16:32:13 volumio volumio[2136]: info: CorePlayQueue::getTrack 0 Sep 08 16:32:13 volumio volumio[2136]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 08 16:32:13 volumio volumio[2136]: info: CoreCommandRouter::volumioPushState Sep 08 16:32:13 volumio volumio[2136]: info: CoreStateMachine::updateTrackBlock Sep 08 16:32:13 volumio volumio[2136]: info: CorePlayQueue::getTrackBlock Sep 08 16:32:13 volumio volumio[2136]: info: CoreCommandRouter::volumioRetrievevolume Sep 08 16:32:13 volumio volumio[2136]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 08 16:32:13 volumio volumio[2136]: info: Reloading queue from file Sep 08 16:32:14 volumio volumio[2136]: info: CoreStateMachine::setRepeat null single undefined Sep 08 16:32:14 volumio volumio[2136]: info: CoreStateMachine::pushState Sep 08 16:32:14 volumio volumio[2136]: info: CorePlayQueue::getTrack 0 Sep 08 16:32:14 volumio volumio[2136]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 08 16:32:14 volumio volumio[2136]: info: CoreCommandRouter::volumioPushState Sep 08 16:32:14 volumio volumio[2136]: info: CoreStateMachine::setRandom null Sep 08 16:32:14 volumio volumio[2136]: info: CoreStateMachine::pushState Sep 08 16:32:14 volumio volumio[2136]: info: CorePlayQueue::getTrack 0 Sep 08 16:32:14 volumio volumio[2136]: info: CoreCommandRouter::volumioPushState Sep 08 16:32:14 volumio volumio[2136]: info: Setting Device type: Raspberry PI Sep 08 16:32:14 volumio volumio-remote-updater[686]: [2026-09-08 16:32:14] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1788877932 101 Sep 08 16:32:14 volumio volumio[2136]: 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 Sep 08 16:32:14 volumio volumio[2136]: info: Completed loading Core Plugins Sep 08 16:32:14 volumio volumio[2136]: info: Preparing to generate the ALSA configuration file Sep 08 16:32:15 volumio volumio[2136]: 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: 2 Sep 08 16:32:16 volumio volumio[2136]: info: VolumeController:: Volume=50 Mute =false Sep 08 16:32:16 volumio volumio[2136]: info: CoreStateMachine::pushState Sep 08 16:32:16 volumio volumio[2136]: info: CorePlayQueue::getTrack 0 Sep 08 16:32:16 volumio volumio[2136]: info: CoreCommandRouter::volumioPushState Sep 08 16:32:16 volumio sudo[2310]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Sep 08 16:32:16 volumio sudo[2310]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 08 16:32:16 volumio volumio[2136]: 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: 2 Sep 08 16:32:16 volumio volumio[2136]: info: Asound.conf file unchanged, so no further update is needed Sep 08 16:32:16 volumio volumio[2136]: info: Output device has changed, restarting MPD Sep 08 16:32:16 volumio volumio[2136]: info: Output device has changed, restarting Shairport Sync Sep 08 16:32:16 volumio volumio[2136]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 08 16:32:16 volumio sudo[2310]: pam_unix(sudo:session): session closed for user root Sep 08 16:32:16 volumio volumio[2136]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 08 16:32:16 volumio sudo[2314]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Sep 08 16:32:17 volumio sudo[2314]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 08 16:32:17 volumio sudo[2315]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Sep 08 16:32:17 volumio volumio[2136]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Sep 08 16:32:17 volumio volumio[2136]: info: ___________ START PLUGINS ___________ Sep 08 16:32:17 volumio sudo[2315]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 08 16:32:17 volumio sudo[2315]: pam_unix(sudo:session): session closed for user root Sep 08 16:32:17 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Sep 08 16:32:17 volumio volumio[2136]: info: ControllerMpd::onStart: Initializing MPD Sep 08 16:32:17 volumio volumio[2136]: info: Creating MPD Configuration file Sep 08 16:32:17 volumio volumio[2136]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Sep 08 16:32:17 volumio sudo[2339]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Sep 08 16:32:17 volumio volumio[2136]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Sep 08 16:32:17 volumio volumio[2136]: info: [1788877937874] CoreMusicLibrary::Adding element Media Servers Sep 08 16:32:17 volumio volumio[2136]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 08 16:32:17 volumio sudo[2337]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumio5-onboarding.service Sep 08 16:32:17 volumio sudo[2339]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 08 16:32:17 volumio sudo[2339]: pam_unix(sudo:session): session closed for user root Sep 08 16:32:17 volumio sudo[2337]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 08 16:32:18 volumio sudo[2341]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Sep 08 16:32:18 volumio sudo[2341]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 08 16:32:18 volumio volumio[2136]: info: UPNP Browser: Client initialized successfully Sep 08 16:32:18 volumio systemd[1]: mpd.service: Deactivated successfully. Sep 08 16:32:18 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Sep 08 16:32:18 volumio systemd[1]: mpd.service: Consumed 10.432s CPU time. Sep 08 16:32:18 volumio sudo[2337]: pam_unix(sudo:session): session closed for user root Sep 08 16:32:18 volumio systemd[1]: mpd.socket: Deactivated successfully. Sep 08 16:32:18 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Sep 08 16:32:18 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Sep 08 16:32:18 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Sep 08 16:32:18 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Sep 08 16:32:18 volumio systemd[1]: mpd.service: Deactivated successfully. Sep 08 16:32:18 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Sep 08 16:32:18 volumio systemd[1]: mpd.socket: Deactivated successfully. Sep 08 16:32:18 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Sep 08 16:32:18 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Sep 08 16:32:18 volumio volumio[2136]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 08 16:32:18 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Sep 08 16:32:18 volumio volumio[2136]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 08 16:32:18 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Sep 08 16:32:19 volumio sudo[2362]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Sep 08 16:32:19 volumio sudo[2362]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Sep 08 16:32:19 volumio sudo[2362]: pam_unix(sudo:session): session closed for user root Sep 08 16:32:19 volumio volumio[2136]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Sep 08 16:32:19 volumio volumio[2136]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 08 16:32:19 volumio volumio[2136]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 08 16:32:19 volumio volumio[2136]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Sep 08 16:32:19 volumio volumio[2136]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Sep 08 16:32:19 volumio volumio[2136]: info: [1788877939767] CoreMusicLibrary::Adding element Last_100 Sep 08 16:32:19 volumio volumio[2136]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 08 16:32:19 volumio volumio[2136]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Sep 08 16:32:19 volumio volumio[2136]: info: [1788877939807] CoreMusicLibrary::Adding element Webradio Sep 08 16:32:19 volumio volumio[2136]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 08 16:32:19 volumio volumio[2136]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Sep 08 16:32:20 volumio volumio[2136]: info: Initializing BBC Radios Sep 08 16:32:21 volumio volumio[2136]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Sep 08 16:32:21 volumio volumio[2136]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 08 16:32:21 volumio volumio[2136]: info: Creating Spotify config file Sep 08 16:32:22 volumio volumio[2136]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 08 16:32:24 volumio mpd[2368]: 2026-09-08T16:32:24 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Sep 08 16:32:24 volumio systemd[1]: Started mpd.service - Music Player Daemon. Sep 08 16:32:24 volumio sudo[2314]: pam_unix(sudo:session): session closed for user root Sep 08 16:32:24 volumio sudo[2341]: pam_unix(sudo:session): session closed for user root Sep 08 16:32:26 volumio volumio5-onboarding[1675]: time=2026-09-08T16:32:26.378+02:00 level=WARN msg="reconnection attempt failed" error="read tcp 127.0.0.1:48050->127.0.0.1:3000: i/o timeout" Sep 08 16:32:27 volumio volumio[2136]: info: Volumio Calling Home Sep 08 16:32:31 volumio volumio[2136]: info: Discovery: adding ebae9b1b-5ab7-4208-997e-e30a97a0b805 Sep 08 16:32:31 volumio volumio[2136]: info: Discovery: Found device Volumio Sep 08 16:32:31 volumio volumio[2136]: info: CoreCommandRouter::volumioGetState Sep 08 16:32:31 volumio volumio[2136]: info: CorePlayQueue::getTrack 0 Sep 08 16:32:31 volumio volumio[2271]: Starting albumart workers Sep 08 16:32:32 volumio volumio[2136]: info: Discovery: this is already registered, ebae9b1b-5ab7-4208-997e-e30a97a0b805 Sep 08 16:32:32 volumio volumio[2136]: info: Discovery: Found device Volumio Sep 08 16:32:32 volumio volumio[2136]: info: CoreCommandRouter::volumioGetState Sep 08 16:32:32 volumio volumio[2136]: info: CorePlayQueue::getTrack 0 Sep 08 16:32:33 volumio volumio[2272]: Starting albumart workers Sep 08 16:32:33 volumio volumio[2273]: Starting albumart workers Sep 08 16:32:33 volumio volumio[2136]: info: MPD Permissions set Sep 08 16:32:33 volumio volumio[2136]: info: Completed starting Core Plugins Sep 08 16:32:33 volumio volumio[2136]: info: ------------------------------------------- Sep 08 16:32:33 volumio volumio[2136]: info: ----- MyVolumio plugins startup ---- Sep 08 16:32:33 volumio volumio[2136]: info: ------------------------------------------- Sep 08 16:32:33 volumio volumio[2136]: info: [MyVolumio PluginManager] Fetching plans data.... Sep 08 16:32:34 volumio volumio[2136]: info: MPD Permissions set Sep 08 16:32:34 volumio volumio[2136]: info: Upmpdcli Daemon Started Sep 08 16:32:34 volumio volumio[2136]: 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: 2 Sep 08 16:32:34 volumio volumio[2136]: info: Volumio called home Sep 08 16:32:34 volumio volumio[2136]: info: Spotify config file written Sep 08 16:32:35 volumio sudo[2423]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Sep 08 16:32:35 volumio sudo[2423]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 08 16:32:35 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Sep 08 16:32:35 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Sep 08 16:32:35 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Sep 08 16:32:35 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Sep 08 16:32:35 volumio go-librespot[2425]: go-librespot daemon starting... Sep 08 16:32:35 volumio sudo[2423]: pam_unix(sudo:session): session closed for user root Sep 08 16:32:35 volumio volumio[2136]: info: An error occurred while refreshing Spotify Token Error: certificate is not yet valid Sep 08 16:32:35 volumio go-librespot[2426]: time="2026-09-08T16:32:35+02:00" level=info msg="running go-librespot 0.9.0" Sep 08 16:32:35 volumio go-librespot[2426]: time="2026-09-08T16:32:35+02:00" level=info msg="api server listening on 127.0.0.1:9879" Sep 08 16:32:35 volumio go-librespot[2426]: time="2026-09-08T16:32:35+02:00" level=debug msg="app state loaded" Sep 08 16:32:38 volumio volumio[2136]: error: MPD error: The expression evaluated to a falsy value: Sep 08 16:32:38 volumio volumio[2136]: assert.ok(self.idling) Sep 08 16:32:38 volumio volumio[2136]: error: The expression evaluated to a falsy value: Sep 08 16:32:38 volumio volumio[2136]: assert.ok(self.idling) Sep 08 16:32:39 volumio volumio[2136]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Sep 08 16:32:39 volumio volumio[2136]: info: MPD running with PID2368 Sep 08 16:32:39 volumio volumio[2136]: ,establishing connection Sep 08 16:32:39 volumio volumio[2136]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 08 16:32:39 volumio volumio[2136]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 08 16:32:39 volumio volumio[2136]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 08 16:32:39 volumio volumio[2136]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 08 16:32:39 volumio volumio[2136]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 08 16:32:39 volumio volumio[2136]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 08 16:32:39 volumio volumio[2136]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 08 16:32:39 volumio volumio[2136]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 08 16:32:39 volumio volumio[2136]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 08 16:32:39 volumio volumio[2136]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 08 16:32:39 volumio volumio[2136]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 08 16:32:39 volumio volumio[2136]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 08 16:32:39 volumio volumio[2136]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 08 16:32:39 volumio volumio[2136]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 08 16:32:39 volumio volumio[2136]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 08 16:32:39 volumio volumio[2136]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 08 16:32:39 volumio volumio[2136]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 08 16:32:39 volumio volumio[2136]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 08 16:32:40 volumio volumio[2136]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 08 16:32:40 volumio volumio[2136]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 08 16:32:40 volumio volumio[2136]: info: No need to fix Spotify hosts Sep 08 16:32:40 volumio volumio[2136]: error: updateQueue error: null Sep 08 16:32:40 volumio volumio[2136]: 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: 3 Sep 08 16:32:41 volumio volumio[2136]: error: updateQueue error: null Sep 08 16:32:41 volumio volumio[2136]: 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: 3 Sep 08 16:32:41 volumio volumio[2136]: info: Starting Shairport Sync Sep 08 16:32:41 volumio volumio[2136]: info: Starting Shairport Sync Sep 08 16:32:41 volumio volumio[2136]: info: Starting Shairport Sync Sep 08 16:32:41 volumio sudo[2468]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Sep 08 16:32:41 volumio sudo[2471]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Sep 08 16:32:41 volumio sudo[2471]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 08 16:32:41 volumio sudo[2468]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 08 16:32:41 volumio sudo[2472]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Sep 08 16:32:41 volumio sudo[2472]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 08 16:32:42 volumio volumio[2136]: 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: 3 Sep 08 16:32:42 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Sep 08 16:32:42 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Sep 08 16:32:42 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Sep 08 16:32:42 volumio systemd[1]: shairport-sync.service: Consumed 2.816s CPU time. Sep 08 16:32:42 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Sep 08 16:32:42 volumio sudo[2468]: pam_unix(sudo:session): session closed for user root Sep 08 16:32:42 volumio sudo[2472]: pam_unix(sudo:session): session closed for user root Sep 08 16:32:42 volumio sudo[2471]: pam_unix(sudo:session): session closed for user root Sep 08 16:32:42 volumio volumio[2136]: 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: 3 Sep 08 16:32:43 volumio volumio[2136]: info: CoreCommandRouter::volumioGetState Sep 08 16:32:43 volumio volumio[2136]: info: CorePlayQueue::getTrack 0 Sep 08 16:32:43 volumio volumio[2136]: info: Shairport-Sync Started Sep 08 16:32:43 volumio volumio[2136]: Error adding Membership: Error: addMembership EINVAL Sep 08 16:32:43 volumio volumio[2136]: info: Shairport-Sync Started Sep 08 16:32:43 volumio volumio[2136]: info: Shairport-Sync Started Sep 08 16:32:43 volumio volumio[2136]: info: go-librespot daemon successfully initialized Sep 08 16:32:44 volumio volumio[2136]: 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: 3 Sep 08 16:32:44 volumio volumio[2136]: 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: 3 Sep 08 16:32:44 volumio volumio[2136]: 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: 3 Sep 08 16:32:44 volumio volumio[2136]: 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: 3 Sep 08 16:32:44 volumio volumio[2136]: 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: 3 Sep 08 16:32:44 volumio volumio[2136]: 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: 3 Sep 08 16:32:45 volumio volumio[2136]: 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: 3 Sep 08 16:32:45 volumio volumio[2136]: 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: 3 Sep 08 16:32:45 volumio volumio[2136]: 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: 3 Sep 08 16:32:45 volumio volumio[2136]: 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: 3 Sep 08 16:32:45 volumio volumio[2136]: 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: 3 Sep 08 16:32:46 volumio volumio[2136]: info: Initializing connection to go-librespot Websocket Sep 08 16:32:47 volumio go-librespot[2426]: time="2026-09-08T16:32:47+02:00" level=debug msg="new websocket client" Sep 08 16:32:47 volumio volumio[2136]: info: Connection to go-librespot Websocket established Sep 08 16:32:50 volumio volumio[2136]: info: Getting Spotify volume Sep 08 16:32:53 volumio volumio[2136]: error: MyVolumio Plugin failed to start in a timely fashion Sep 08 16:32:53 volumio volumio[2136]: [Metrics] CommandRouter: 62s 68.78ms Sep 08 16:32:53 volumio volumio[2136]: info: CoreCommandRouter::volumiosetStartupVolume Sep 08 16:32:53 volumio volumio[2136]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 08 16:32:53 volumio volumio[2136]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 08 16:32:53 volumio volumio[2136]: info: CoreCommandRouter::Close All Modals sent Sep 08 16:32:53 volumio volumio[2136]: info: CoreCommandRouter::Close All Modals sent Sep 08 16:32:54 volumio volumio[2136]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable Sep 08 16:32:54 volumio volumio[2136]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Sep 08 16:32:54 volumio volumio[2136]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect Sep 08 16:32:57 volumio volumio[2136]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Sep 08 16:32:57 volumio volumio[2136]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 08 16:32:57 volumio volumio[2136]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Sep 08 16:33:00 volumio volumio[2136]: info: BOOT COMPLETED Sep 08 16:33:03 volumio go-librespot[2426]: time="2026-09-08T16:33:03+02:00" level=fatal msg="daemon exited with error" 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" Sep 08 16:33:03 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 08 16:33:03 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 08 16:33:03 volumio volumio[2136]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Sep 08 16:33:03 volumio volumio[2136]: Error: socket hang up Sep 08 16:33:03 volumio volumio[2136]: at connResetException (node:internal/errors:720:14) Sep 08 16:33:03 volumio volumio[2136]: at Socket.socketOnEnd (node:_http_client:519:23) Sep 08 16:33:03 volumio volumio[2136]: at Socket.emit (node:events:526:35) Sep 08 16:33:03 volumio volumio[2136]: at endReadableNT (node:internal/streams/readable:1376:12) Sep 08 16:33:03 volumio volumio[2136]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { Sep 08 16:33:03 volumio volumio[2136]: code: 'ECONNRESET', Sep 08 16:33:03 volumio volumio[2136]: response: undefined Sep 08 16:33:03 volumio volumio[2136]: } Sep 08 16:33:03 volumio volumio[2136]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Sep 08 16:33:05 volumio sudo[2573]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-09-08 16:32' Sep 08 16:33:05 volumio sudo[2573]: 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"