Mar 24 14:39:00 volumio go-librespot[32606]: time="2026-03-24T14:39:00+01:00" level=debug msg="connected to ap-gew4.spotify.com:443" Mar 24 14:39:00 volumio go-librespot[32606]: time="2026-03-24T14:39:00+01:00" level=debug msg="completed keyexchange" Mar 24 14:39:00 volumio go-librespot[32606]: time="2026-03-24T14:39:00+01:00" level=debug msg="completed challenge" Mar 24 14:39:00 volumio go-librespot[32606]: time="2026-03-24T14:39:00+01:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 14:39:01 volumio go-librespot[32606]: time="2026-03-24T14:39:01+01:00" level=debug msg="connected to ap-gew4.spotify.com:80" Mar 24 14:39:01 volumio go-librespot[32606]: time="2026-03-24T14:39:01+01:00" level=debug msg="completed keyexchange" Mar 24 14:39:01 volumio go-librespot[32606]: time="2026-03-24T14:39:01+01:00" level=debug msg="completed challenge" Mar 24 14:39:01 volumio go-librespot[32606]: time="2026-03-24T14:39:01+01:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 14:39:01 volumio volumio[32583]: info: Starting UPNP Browser Mar 24 14:39:01 volumio volumio[32583]: info: Loading plugin "alarm-clock"... Mar 24 14:39:01 volumio go-librespot[32606]: time="2026-03-24T14:39:01+01:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Mar 24 14:39:02 volumio go-librespot[32606]: time="2026-03-24T14:39:02+01:00" level=debug msg="completed keyexchange" Mar 24 14:39:02 volumio go-librespot[32606]: time="2026-03-24T14:39:02+01:00" level=debug msg="completed challenge" Mar 24 14:39:02 volumio volumio[32583]: info: Loading plugin "airplay_emulation"... Mar 24 14:39:02 volumio volumio[32583]: info: Starting Shairport Sync Mar 24 14:39:02 volumio volumio[32583]: info: Loading plugin "last_100"... Mar 24 14:39:02 volumio volumio[32583]: info: Loading plugin "webradio"... Mar 24 14:39:02 volumio go-librespot[32606]: time="2026-03-24T14:39:02+01:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 14:39:02 volumio volumio[32583]: info: Loading plugin "i2s_dacs"... Mar 24 14:39:02 volumio volumio[32583]: info: Loading plugin "volumiodiscovery"... Mar 24 14:39:02 volumio volumio[32583]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Mar 24 14:39:02 volumio volumio[32583]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 24 14:39:02 volumio volumio[32583]: *** WARNING *** For more information see Mar 24 14:39:02 volumio volumio[32583]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Mar 24 14:39:02 volumio volumio[32583]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 24 14:39:02 volumio volumio[32583]: *** WARNING *** For more information see Mar 24 14:39:02 volumio node[32583]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Mar 24 14:39:02 volumio node[32583]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 24 14:39:02 volumio node[32583]: *** WARNING *** For more information see Mar 24 14:39:02 volumio node[32583]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Mar 24 14:39:02 volumio node[32583]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 24 14:39:02 volumio node[32583]: *** WARNING *** For more information see Mar 24 14:39:02 volumio volumio[32583]: info: Applying required configuration parameters for plugin volumiodiscovery Mar 24 14:39:02 volumio volumio[32583]: info: Discovery: Started advertising with name: Volumio Mar 24 14:39:02 volumio volumio[32583]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Mar 24 14:39:02 volumio volumio[32583]: info: Loading plugin "spop"... Mar 24 14:39:02 volumio go-librespot[32606]: time="2026-03-24T14:39:02+01:00" level=debug msg="connected to ap-gue1.spotify.com:443" Mar 24 14:39:02 volumio go-librespot[32606]: time="2026-03-24T14:39:02+01:00" level=debug msg="completed keyexchange" Mar 24 14:39:02 volumio go-librespot[32606]: time="2026-03-24T14:39:02+01:00" level=debug msg="completed challenge" Mar 24 14:39:03 volumio go-librespot[32606]: time="2026-03-24T14:39:03+01:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 14:39:03 volumio go-librespot[32606]: time="2026-03-24T14:39:03+01:00" level=warning msg="failed to connect to AP ap-gae2.spotify.com:80, retrying with a different AP" error="dial tcp 104.199.241.202:80: connect: connection refused" Mar 24 14:39:03 volumio go-librespot[32606]: time="2026-03-24T14:39:03+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Mar 24 14:39:04 volumio go-librespot[32606]: time="2026-03-24T14:39:04+01:00" level=debug msg="completed keyexchange" Mar 24 14:39:04 volumio go-librespot[32606]: time="2026-03-24T14:39:04+01:00" level=debug msg="completed challenge" Mar 24 14:39:04 volumio go-librespot[32606]: time="2026-03-24T14:39:04+01:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 14:39:04 volumio go-librespot[32606]: time="2026-03-24T14:39:04+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Mar 24 14:39:04 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 24 14:39:04 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 24 14:39:04 volumio volumio5-onboarding[22591]: time=2026-03-24T14:39:04.398+01:00 level=WARN msg="reconnection attempt failed" component=volumio/socket error="read tcp 127.0.0.1:40354->127.0.0.1:3000: i/o timeout" Mar 24 14:39:04 volumio volumio[32583]: info: Loading plugin "outputs"... Mar 24 14:39:04 volumio volumio[32583]: info: Loading plugin "albumart"... Mar 24 14:39:04 volumio volumio[32583]: info: Plugin example_plugin is not enabled Mar 24 14:39:04 volumio volumio[32583]: info: Loading plugin "inputs"... Mar 24 14:39:04 volumio volumio[32583]: info: Loading plugin "updater_comm"... Mar 24 14:39:04 volumio volumio[32583]: info: Plugin mpdemulation is not enabled Mar 24 14:39:04 volumio volumio[32583]: info: Loading plugin "rest_api"... Mar 24 14:39:04 volumio volumio[32583]: info: Loading plugin "websocket"... Mar 24 14:39:04 volumio volumio[32583]: info: Starting Socket.io Server version 1.7.4 Mar 24 14:39:04 volumio volumio[32583]: info: Loading i18n strings for locale pl Mar 24 14:39:04 volumio volumio[32583]: Updating browse sources language Mar 24 14:39:04 volumio volumio[32583]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 24 14:39:05 volumio volumio[32583]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 24 14:39:05 volumio volumio[32583]: info: CoreCommandRouter::initPlayerControls Mar 24 14:39:05 volumio volumio[32583]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 14:39:05 volumio volumio[32583]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 14:39:05 volumio volumio[32583]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 14:39:05 volumio volumio[32583]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 14:39:05 volumio volumio[32583]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 14:39:05 volumio volumio[32583]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 14:39:05 volumio volumio[32583]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 14:39:05 volumio volumio[32583]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 14:39:05 volumio volumio[32583]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 24 14:39:05 volumio volumio[32651]: Forking 3 albumart workers Mar 24 14:39:05 volumio volumio[32583]: Express server listening on port 3000 Mar 24 14:39:05 volumio volumio[32583]: [Metrics] WebUI: 11s 457.97ms Mar 24 14:39:05 volumio volumio[32583]: info: CoreStateMachine::resetVolumioState Mar 24 14:39:05 volumio volumio[32583]: info: CoreStateMachine::getcurrentVolume Mar 24 14:39:05 volumio volumio[32583]: info: CoreCommandRouter::volumioRetrievevolume Mar 24 14:39:05 volumio volumio[32583]: info: Volumio Network Manager: Network status updated: 2 Mar 24 14:39:05 volumio volumio[32583]: info: CoreStateMachine::pushState Mar 24 14:39:05 volumio volumio[32583]: info: CorePlayQueue::getTrack 0 Mar 24 14:39:05 volumio volumio[32583]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 24 14:39:05 volumio volumio[32583]: info: CoreCommandRouter::volumioPushState Mar 24 14:39:05 volumio volumio[32583]: info: CoreStateMachine::updateTrackBlock Mar 24 14:39:05 volumio volumio[32583]: info: CorePlayQueue::getTrackBlock Mar 24 14:39:05 volumio volumio[32583]: info: CoreCommandRouter::volumioRetrievevolume Mar 24 14:39:05 volumio volumio[32583]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 24 14:39:05 volumio volumio[32583]: info: Reloading queue from file Mar 24 14:39:05 volumio volumio[32583]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 1 Mar 24 14:39:05 volumio volumio[32583]: info: CoreStateMachine::setRepeat null single undefined Mar 24 14:39:05 volumio volumio[32583]: info: CoreStateMachine::pushState Mar 24 14:39:05 volumio volumio[32583]: info: CorePlayQueue::getTrack 0 Mar 24 14:39:05 volumio volumio[32583]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 24 14:39:05 volumio volumio[32583]: info: CoreCommandRouter::volumioPushState Mar 24 14:39:05 volumio volumio[32583]: info: CoreStateMachine::setRandom null Mar 24 14:39:05 volumio volumio[32583]: info: CoreStateMachine::pushState Mar 24 14:39:05 volumio volumio[32583]: info: CorePlayQueue::getTrack 0 Mar 24 14:39:05 volumio volumio[32583]: info: CoreCommandRouter::volumioPushState Mar 24 14:39:05 volumio volumio[32583]: info: Setting Device type: Raspberry PI Mar 24 14:39:05 volumio volumio[32583]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Mar 24 14:39:05 volumio volumio[32583]: info: USB Boot Capable - System SBC Revision found in cpuinfo: 902120 Mar 24 14:39:05 volumio volumio[32583]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Mar 24 14:39:05 volumio volumio[32583]: info: CoreStateMachine::pushState Mar 24 14:39:05 volumio volumio[32583]: info: CorePlayQueue::getTrack 0 Mar 24 14:39:05 volumio volumio[32583]: info: CoreCommandRouter::volumioPushState Mar 24 14:39:05 volumio volumio[32583]: info: Completed loading Core Plugins Mar 24 14:39:05 volumio volumio[32583]: info: Preparing to generate the ALSA configuration file Mar 24 14:39:05 volumio volumio[32583]: info: The plugin alsa_controller has an ALSA contribution file softvolume.postVolume.conf Mar 24 14:39:05 volumio volumio[32583]: info: Reading ALSA contributions from plugins. Mar 24 14:39:05 volumio volumio[32583]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 1 Mar 24 14:39:05 volumio volumio[32583]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 1 Mar 24 14:39:05 volumio volumio[32583]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 1 Mar 24 14:39:05 volumio volumio[32583]: info: Asound.conf file unchanged, so no further update is needed Mar 24 14:39:05 volumio volumio[32583]: info: Output device has changed, restarting MPD Mar 24 14:39:06 volumio volumio[32583]: info: Output device has changed, restarting Shairport Sync Mar 24 14:39:06 volumio volumio[32583]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 14:39:06 volumio volumio[32583]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 24 14:39:06 volumio volumio[32583]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 24 14:39:06 volumio volumio[32583]: info: ___________ START PLUGINS ___________ Mar 24 14:39:06 volumio volumio[32583]: info: ControllerMpd::onStart: Initializing MPD Mar 24 14:39:06 volumio volumio[32583]: info: Creating MPD Configuration file Mar 24 14:39:06 volumio volumio[32583]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 24 14:39:06 volumio volumio[32583]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 24 14:39:06 volumio volumio[32583]: info: [1774359546180] CoreMusicLibrary::Adding element Serwery Mediów Mar 24 14:39:06 volumio volumio[32583]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 24 14:39:06 volumio sudo[32718]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Mar 24 14:39:06 volumio sudo[32724]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumio5-onboarding.service Mar 24 14:39:06 volumio sudo[32724]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 14:39:06 volumio sudo[32718]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 14:39:06 volumio sudo[32716]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Mar 24 14:39:06 volumio sudo[32716]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 14:39:06 volumio volumio[32583]: info: UPNP Browser: Client initialized successfully Mar 24 14:39:06 volumio sudo[32716]: pam_unix(sudo:session): session closed for user root Mar 24 14:39:06 volumio sudo[32726]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Mar 24 14:39:06 volumio sudo[32726]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 14:39:06 volumio sudo[32728]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Mar 24 14:39:06 volumio sudo[32726]: pam_unix(sudo:session): session closed for user root Mar 24 14:39:06 volumio volumio[32583]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 14:39:06 volumio volumio[32583]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 24 14:39:06 volumio sudo[32728]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 14:39:06 volumio volumio[32583]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 24 14:39:06 volumio volumio[32583]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 14:39:06 volumio volumio[32583]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 24 14:39:06 volumio volumio[32583]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 24 14:39:06 volumio volumio[32583]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 24 14:39:06 volumio volumio[32583]: info: [1774359546401] CoreMusicLibrary::Adding element Last_100 Mar 24 14:39:06 volumio volumio[32583]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 24 14:39:06 volumio volumio[32583]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 24 14:39:06 volumio volumio[32583]: info: [1774359546417] CoreMusicLibrary::Adding element Webradio Mar 24 14:39:06 volumio volumio[32583]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 24 14:39:06 volumio volumio[32583]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 24 14:39:06 volumio volumio[32583]: info: Initializing BBC Radios Mar 24 14:39:06 volumio volumio[32583]: /usr/bin/md5sum: /sys/class/net/eth0/address: No such file or directory Mar 24 14:39:06 volumio volumio[32583]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 24 14:39:06 volumio volumio[32583]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 24 14:39:06 volumio volumio[32583]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 24 14:39:06 volumio volumio[32583]: info: Creating Spotify config file Mar 24 14:39:06 volumio volumio[32583]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 14:39:06 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Mar 24 14:39:06 volumio sudo[32724]: pam_unix(sudo:session): session closed for user root Mar 24 14:39:07 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 7. Mar 24 14:39:07 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 24 14:39:07 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 24 14:39:07 volumio volumio[32583]: info: Volumio Calling Home Mar 24 14:39:07 volumio go-librespot[32755]: go-librespot daemon starting... Mar 24 14:39:07 volumio go-librespot[32756]: time="2026-03-24T14:39:07+01:00" level=info msg="running go-librespot 0.6.2" Mar 24 14:39:07 volumio volumio[32583]: info: Discovery: adding 2456885c-5bc0-4391-bb8e-47f9f2a2e3dd Mar 24 14:39:07 volumio volumio[32583]: info: Discovery: Found device Volumio Mar 24 14:39:07 volumio volumio[32583]: info: CoreCommandRouter::volumioGetState Mar 24 14:39:07 volumio volumio[32583]: info: CorePlayQueue::getTrack 0 Mar 24 14:39:07 volumio volumio[32583]: info: Discovery: this is already registered, 2456885c-5bc0-4391-bb8e-47f9f2a2e3dd Mar 24 14:39:07 volumio volumio[32583]: info: Discovery: Found device Volumio Mar 24 14:39:07 volumio volumio[32583]: info: CoreCommandRouter::volumioGetState Mar 24 14:39:07 volumio volumio[32583]: info: CorePlayQueue::getTrack 0 Mar 24 14:39:07 volumio volumio[32583]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 1 Mar 24 14:39:07 volumio volumio[32663]: Starting albumart workers Mar 24 14:39:07 volumio volumio[32583]: info: MPD Permissions set Mar 24 14:39:07 volumio volumio[32583]: info: MPD Permissions set Mar 24 14:39:07 volumio volumio[32661]: Starting albumart workers Mar 24 14:39:07 volumio volumio[32665]: Starting albumart workers Mar 24 14:39:08 volumio volumio[32583]: info: Spotify config file written Mar 24 14:39:08 volumio volumio[32583]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 1 Mar 24 14:39:08 volumio volumio[32583]: info: No need to fix Spotify hosts Mar 24 14:39:08 volumio volumio[32583]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 14:39:08 volumio volumio[32583]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 14:39:08 volumio volumio[32583]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 14:39:08 volumio volumio[32583]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 14:39:08 volumio volumio[32583]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 14:39:08 volumio volumio[32583]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 14:39:08 volumio volumio[32583]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 14:39:08 volumio volumio[32583]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 14:39:08 volumio sudo[303]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 24 14:39:08 volumio sudo[303]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 14:39:08 volumio volumio[32583]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 24 14:39:08 volumio volumio[32583]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 14:39:08 volumio volumio[32583]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 14:39:08 volumio volumio[32583]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 14:39:08 volumio volumio[32583]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 14:39:08 volumio volumio[32583]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 14:39:08 volumio volumio[32583]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 14:39:08 volumio volumio[32583]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 14:39:08 volumio volumio[32583]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 14:39:08 volumio volumio[32583]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 14:39:08 volumio volumio[32583]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 24 14:39:08 volumio volumio[32583]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 14:39:08 volumio go-librespot[32756]: time="2026-03-24T14:39:08+01:00" level=info msg="zeroconf server listening on port 41805" Mar 24 14:39:08 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Mar 24 14:39:08 volumio volumio-remote-updater[584]: [2026-03-24 14:39:08] [connect] Successful connection Mar 24 14:39:08 volumio systemd[1]: go-librespot-daemon.service: Killing process 32762 (n/a) with signal SIGKILL. Mar 24 14:39:08 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Mar 24 14:39:08 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 24 14:39:08 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 24 14:39:08 volumio sudo[303]: pam_unix(sudo:session): session closed for user root Mar 24 14:39:08 volumio volumio[32583]: 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 Mar 24 14:39:08 volumio go-librespot[319]: go-librespot daemon starting... Mar 24 14:39:08 volumio go-librespot[335]: time="2026-03-24T14:39:08+01:00" level=info msg="running go-librespot 0.6.2" Mar 24 14:39:09 volumio go-librespot[335]: time="2026-03-24T14:39:08+01:00" level=debug msg="app state loaded" Mar 24 14:39:09 volumio go-librespot[335]: time="2026-03-24T14:39:09+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 24 14:39:09 volumio sudo[344]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 24 14:39:09 volumio sudo[342]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Mar 24 14:39:09 volumio sudo[344]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 14:39:09 volumio sudo[342]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 14:39:09 volumio sudo[344]: pam_unix(sudo:session): session closed for user root Mar 24 14:39:09 volumio sudo[342]: pam_unix(sudo:session): session closed for user root Mar 24 14:39:09 volumio volumio-remote-updater[584]: [2026-03-24 14:39:09] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1774359548 101 Mar 24 14:39:09 volumio volumio[32583]: 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: 2 Mar 24 14:39:09 volumio volumio[32583]: info: Starting Shairport Sync Mar 24 14:39:09 volumio volumio[32583]: info: Starting Shairport Sync Mar 24 14:39:09 volumio volumio[32583]: info: Starting Shairport Sync Mar 24 14:39:09 volumio sudo[358]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Mar 24 14:39:09 volumio sudo[355]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Mar 24 14:39:09 volumio sudo[355]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 14:39:09 volumio sudo[358]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 14:39:09 volumio sudo[359]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Mar 24 14:39:09 volumio sudo[359]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 14:39:09 volumio volumio[32583]: 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 Mar 24 14:39:09 volumio volumio[32583]: info: Volumio called home Mar 24 14:39:09 volumio volumio[32583]: info: An error occurred while refreshing Spotify Token Error: Bad Request Mar 24 14:39:09 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Mar 24 14:39:09 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Mar 24 14:39:09 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Mar 24 14:39:09 volumio systemd[1]: shairport-sync.service: Consumed 2.416s CPU time. Mar 24 14:39:09 volumio go-librespot[335]: time="2026-03-24T14:39:09+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Mar 24 14:39:09 volumio go-librespot[335]: time="2026-03-24T14:39:09+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Mar 24 14:39:09 volumio go-librespot[335]: time="2026-03-24T14:39:09+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Mar 24 14:39:09 volumio go-librespot[335]: time="2026-03-24T14:39:09+01:00" level=info msg="zeroconf server listening on port 35057" Mar 24 14:39:09 volumio volumio[32583]: 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 Mar 24 14:39:09 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Mar 24 14:39:09 volumio sudo[355]: pam_unix(sudo:session): session closed for user root Mar 24 14:39:09 volumio sudo[359]: pam_unix(sudo:session): session closed for user root Mar 24 14:39:09 volumio sudo[358]: pam_unix(sudo:session): session closed for user root Mar 24 14:39:09 volumio volumio[32583]: info: Shairport-Sync Started Mar 24 14:39:09 volumio volumio[32583]: Error adding Membership: Error: addMembership EINVAL Mar 24 14:39:09 volumio go-librespot[335]: time="2026-03-24T14:39:09+01:00" level=debug msg="obtained new client token: AABnEL6pH4pu5pNDZ3/MvSSvihbtVp+1xIEU3EOxfsL133bTpg0M8RUFsvS6fi7TaWesSSMlr1iT0ByBtNjHi+Kz9XaCIqVm5zbzvilqfprvQBg2kcmL5sQ41aWix5g6tEXhQBOWQl2VCN2KoT3Ah1a2AjFySLWoYjNWT/5IQ/DWraRJc/ytT1GerOassDBx1f53VLwpKh2mKpdd4uNC5M+VTipNr+Am8GGEMrxNYfkkf0fgoGGdoIMeNg==" Mar 24 14:39:09 volumio volumio[32583]: 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 Mar 24 14:39:09 volumio volumio[32583]: info: Shairport-Sync Started Mar 24 14:39:09 volumio volumio[32583]: info: Shairport-Sync Started Mar 24 14:39:09 volumio volumio[32583]: info: CoreCommandRouter::volumioGetState Mar 24 14:39:09 volumio volumio[32583]: info: CorePlayQueue::getTrack 0 Mar 24 14:39:09 volumio go-librespot[335]: time="2026-03-24T14:39:09+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Mar 24 14:39:09 volumio sudo[367]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Mar 24 14:39:09 volumio sudo[367]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 14:39:09 volumio volumio[32583]: 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 Mar 24 14:39:09 volumio go-librespot[335]: time="2026-03-24T14:39:09+01:00" level=debug msg="completed keyexchange" Mar 24 14:39:09 volumio go-librespot[335]: time="2026-03-24T14:39:09+01:00" level=debug msg="completed challenge" Mar 24 14:39:09 volumio sudo[367]: pam_unix(sudo:session): session closed for user root Mar 24 14:39:09 volumio volumio[32583]: 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 Mar 24 14:39:09 volumio volumio[32583]: info: Upmpdcli Daemon Started Mar 24 14:39:09 volumio go-librespot[335]: time="2026-03-24T14:39:09+01:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 14:39:09 volumio volumio[32583]: 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 Mar 24 14:39:09 volumio volumio[32583]: 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 Mar 24 14:39:10 volumio volumio[32583]: 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 Mar 24 14:39:10 volumio volumio[32583]: 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 Mar 24 14:39:10 volumio volumio5-onboarding[22591]: time=2026-03-24T14:39:10.150+01: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" Mar 24 14:39:10 volumio go-librespot[335]: time="2026-03-24T14:39:10+01:00" level=warning msg="failed to connect to AP ap-gew4.spotify.com:443, retrying with a different AP" error="dial tcp 34.158.1.133:443: connect: connection refused" Mar 24 14:39:10 volumio go-librespot[335]: time="2026-03-24T14:39:10+01:00" level=debug msg="connected to ap-gew4.spotify.com:80" Mar 24 14:39:10 volumio go-librespot[335]: time="2026-03-24T14:39:10+01:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: EOF" Mar 24 14:39:11 volumio go-librespot[335]: time="2026-03-24T14:39:11+01:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Mar 24 14:39:11 volumio go-librespot[335]: time="2026-03-24T14:39:11+01:00" level=debug msg="completed keyexchange" Mar 24 14:39:11 volumio go-librespot[335]: time="2026-03-24T14:39:11+01:00" level=debug msg="completed challenge" Mar 24 14:39:11 volumio go-librespot[335]: time="2026-03-24T14:39:11+01:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 14:39:11 volumio volumio[32583]: info: go-librespot daemon successfully initialized Mar 24 14:39:12 volumio go-librespot[335]: time="2026-03-24T14:39:12+01:00" level=debug msg="connected to ap-gue1.spotify.com:443" Mar 24 14:39:12 volumio go-librespot[335]: time="2026-03-24T14:39:12+01:00" level=debug msg="completed keyexchange" Mar 24 14:39:12 volumio go-librespot[335]: time="2026-03-24T14:39:12+01:00" level=debug msg="completed challenge" Mar 24 14:39:12 volumio go-librespot[335]: time="2026-03-24T14:39:12+01:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 14:39:13 volumio go-librespot[335]: time="2026-03-24T14:39:13+01:00" level=debug msg="connected to ap-gew1.spotify.com:80" Mar 24 14:39:13 volumio go-librespot[335]: time="2026-03-24T14:39:13+01:00" level=debug msg="completed keyexchange" Mar 24 14:39:13 volumio go-librespot[335]: time="2026-03-24T14:39:13+01:00" level=debug msg="completed challenge" Mar 24 14:39:13 volumio go-librespot[335]: time="2026-03-24T14:39:13+01:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 14:39:13 volumio systemd[1]: mpd.service: Deactivated successfully. Mar 24 14:39:13 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Mar 24 14:39:13 volumio systemd[1]: mpd.service: Consumed 8.723s CPU time. Mar 24 14:39:13 volumio systemd[1]: mpd.socket: Deactivated successfully. Mar 24 14:39:13 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Mar 24 14:39:13 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Mar 24 14:39:13 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Mar 24 14:39:13 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Mar 24 14:39:13 volumio sudo[403]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Mar 24 14:39:13 volumio sudo[403]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Mar 24 14:39:13 volumio sudo[403]: pam_unix(sudo:session): session closed for user root Mar 24 14:39:13 volumio go-librespot[335]: time="2026-03-24T14:39:13+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Mar 24 14:39:13 volumio go-librespot[335]: time="2026-03-24T14:39:13+01:00" level=debug msg="completed keyexchange" Mar 24 14:39:13 volumio go-librespot[335]: time="2026-03-24T14:39:13+01:00" level=debug msg="completed challenge" Mar 24 14:39:13 volumio go-librespot[335]: time="2026-03-24T14:39:13+01:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 14:39:13 volumio go-librespot[335]: time="2026-03-24T14:39:13+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Mar 24 14:39:13 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 24 14:39:13 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 24 14:39:14 volumio volumio[32583]: info: Initializing connection to go-librespot Websocket Mar 24 14:39:14 volumio volumio[32583]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 24 14:39:17 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Mar 24 14:39:17 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 24 14:39:17 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 24 14:39:17 volumio go-librespot[406]: go-librespot daemon starting... Mar 24 14:39:17 volumio go-librespot[407]: time="2026-03-24T14:39:17+01:00" level=info msg="running go-librespot 0.6.2" Mar 24 14:39:17 volumio go-librespot[407]: time="2026-03-24T14:39:17+01:00" level=debug msg="app state loaded" Mar 24 14:39:17 volumio go-librespot[407]: time="2026-03-24T14:39:17+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 24 14:39:17 volumio volumio[32583]: info: Initializing connection to go-librespot Websocket Mar 24 14:39:17 volumio go-librespot[407]: time="2026-03-24T14:39:17+01:00" level=debug msg="new websocket client" Mar 24 14:39:17 volumio volumio[32583]: info: Connection to go-librespot Websocket established Mar 24 14:39:18 volumio go-librespot[407]: time="2026-03-24T14:39:18+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Mar 24 14:39:18 volumio go-librespot[407]: time="2026-03-24T14:39:18+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Mar 24 14:39:18 volumio go-librespot[407]: time="2026-03-24T14:39:18+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Mar 24 14:39:18 volumio go-librespot[407]: time="2026-03-24T14:39:18+01:00" level=info msg="zeroconf server listening on port 39251" Mar 24 14:39:18 volumio go-librespot[407]: time="2026-03-24T14:39:18+01:00" level=debug msg="obtained new client token: AAAzLrXSgQPtkyNkGmdbDjsMoYV41rp4ZpNh3u9XeWZTqu+wdDE/IXsW8A8R8m9wO0Gnjwne/k6lFZCq11IRMVSqY8vkyffI/gubTRX4RP1wfqzmc91aoGvQqiP3+uXEdYpco4csmJDLmanAHXk5HSMV4OgzeYbzX6xva7xPHWPa6TCgk8C8GR5eGuMirAZHw4/vh+G/37ivwSY9rN/MTuXC7Szr2+bUZVAG7alkFvMkvr96RKXcgoMW7Q==" Mar 24 14:39:18 volumio go-librespot[407]: time="2026-03-24T14:39:18+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Mar 24 14:39:18 volumio go-librespot[407]: time="2026-03-24T14:39:18+01:00" level=debug msg="completed keyexchange" Mar 24 14:39:18 volumio go-librespot[407]: time="2026-03-24T14:39:18+01:00" level=debug msg="completed challenge" Mar 24 14:39:18 volumio go-librespot[407]: time="2026-03-24T14:39:18+01:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 14:39:19 volumio go-librespot[407]: time="2026-03-24T14:39:19+01:00" level=warning msg="failed to connect to AP ap-gew4.spotify.com:443, retrying with a different AP" error="dial tcp 34.158.1.133:443: connect: connection refused" Mar 24 14:39:19 volumio go-librespot[407]: time="2026-03-24T14:39:19+01:00" level=warning msg="failed to connect to AP ap-gew4.spotify.com:80, retrying with a different AP" error="dial tcp 34.158.1.133:80: connect: connection refused" Mar 24 14:39:19 volumio go-librespot[407]: time="2026-03-24T14:39:19+01:00" level=warning msg="failed to connect to AP ap-guc3.spotify.com:4070, retrying with a different AP" error="dial tcp 104.154.127.247:4070: connect: connection refused" Mar 24 14:39:19 volumio go-librespot[407]: time="2026-03-24T14:39:19+01:00" level=debug msg="connected to ap-gue1.spotify.com:443" Mar 24 14:39:19 volumio go-librespot[407]: time="2026-03-24T14:39:19+01:00" level=debug msg="completed keyexchange" Mar 24 14:39:19 volumio go-librespot[407]: time="2026-03-24T14:39:19+01:00" level=debug msg="completed challenge" Mar 24 14:39:19 volumio go-librespot[407]: time="2026-03-24T14:39:19+01:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 14:39:20 volumio go-librespot[407]: time="2026-03-24T14:39:20+01:00" level=debug msg="connected to ap-gew1.spotify.com:80" Mar 24 14:39:20 volumio go-librespot[407]: time="2026-03-24T14:39:20+01:00" level=debug msg="completed keyexchange" Mar 24 14:39:20 volumio go-librespot[407]: time="2026-03-24T14:39:20+01:00" level=debug msg="completed challenge" Mar 24 14:39:20 volumio go-librespot[407]: time="2026-03-24T14:39:20+01:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 14:39:21 volumio volumio[32583]: info: Getting Spotify volume Mar 24 14:39:21 volumio volumio[32583]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 4 Mar 24 14:39:21 volumio volumio[32583]: info: CoreCommandRouter::volumioGetState Mar 24 14:39:21 volumio volumio[32583]: info: CorePlayQueue::getTrack 0 Mar 24 14:39:21 volumio volumio[32583]: SPOTIFY: RECEIVED VOLUMIO VOLUME 72 Mar 24 14:39:21 volumio volumio[32583]: SPOTIFY: SPOTIFY VOLUME undefined Mar 24 14:39:21 volumio volumio[32583]: SPOTIFY: VOLUMIO VOLUME 72 Mar 24 14:39:21 volumio volumio[32583]: info: Aligning Spotify Volume to Volumio Volume Mar 24 14:39:21 volumio volumio[32583]: info: CoreCommandRouter::volumioGetState Mar 24 14:39:21 volumio volumio[32583]: info: CorePlayQueue::getTrack 0 Mar 24 14:39:21 volumio volumio[32583]: info: Setting Spotify Volume from Volumio: 72 Mar 24 14:39:21 volumio go-librespot[407]: time="2026-03-24T14:39:21+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Mar 24 14:39:21 volumio go-librespot[407]: time="2026-03-24T14:39:21+01:00" level=debug msg="completed keyexchange" Mar 24 14:39:21 volumio go-librespot[407]: time="2026-03-24T14:39:21+01:00" level=debug msg="completed challenge" Mar 24 14:39:22 volumio go-librespot[407]: time="2026-03-24T14:39:22+01:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 14:39:22 volumio go-librespot[407]: time="2026-03-24T14:39:22+01:00" level=debug msg="connected to ap-gew4.spotify.com:443" Mar 24 14:39:22 volumio mpd[405]: 2026-03-24T14:39:22 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Mar 24 14:39:22 volumio go-librespot[407]: time="2026-03-24T14:39:22+01:00" level=debug msg="completed keyexchange" Mar 24 14:39:22 volumio go-librespot[407]: time="2026-03-24T14:39:22+01:00" level=debug msg="completed challenge" Mar 24 14:39:22 volumio go-librespot[407]: time="2026-03-24T14:39:22+01:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 14:39:22 volumio systemd[1]: Started mpd.service - Music Player Daemon. Mar 24 14:39:22 volumio volumio[32583]: SPOTIFY: SETTING SPOTIFY VOLUME 72 Mar 24 14:39:22 volumio volumio[32583]: info: Sending Spotify command with payload to local API: /player/volume Mar 24 14:39:22 volumio volumio[32583]: error: Failed to send command to Spotify local API: /player/volume: Error: Bad Request Mar 24 14:39:22 volumio sudo[32728]: pam_unix(sudo:session): session closed for user root Mar 24 14:39:22 volumio sudo[32718]: pam_unix(sudo:session): session closed for user root Mar 24 14:39:23 volumio go-librespot[407]: time="2026-03-24T14:39:23+01:00" level=debug msg="connected to ap-gew4.spotify.com:80" Mar 24 14:39:23 volumio go-librespot[407]: time="2026-03-24T14:39:23+01:00" level=debug msg="completed keyexchange" Mar 24 14:39:23 volumio go-librespot[407]: time="2026-03-24T14:39:23+01:00" level=debug msg="completed challenge" Mar 24 14:39:23 volumio go-librespot[407]: time="2026-03-24T14:39:23+01:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 14:39:23 volumio go-librespot[407]: time="2026-03-24T14:39:23+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Mar 24 14:39:23 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 24 14:39:23 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 24 14:39:23 volumio volumio[32583]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 24 14:39:23 volumio volumio[32583]: Error: socket hang up Mar 24 14:39:23 volumio volumio[32583]: at connResetException (node:internal/errors:720:14) Mar 24 14:39:23 volumio volumio[32583]: at Socket.socketOnEnd (node:_http_client:519:23) Mar 24 14:39:23 volumio volumio[32583]: at Socket.emit (node:events:526:35) Mar 24 14:39:23 volumio volumio[32583]: at endReadableNT (node:internal/streams/readable:1376:12) Mar 24 14:39:23 volumio volumio[32583]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { Mar 24 14:39:23 volumio volumio[32583]: code: 'ECONNRESET', Mar 24 14:39:23 volumio volumio[32583]: response: undefined Mar 24 14:39:23 volumio volumio[32583]: } Mar 24 14:39:23 volumio volumio[32583]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 24 14:39:26 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Mar 24 14:39:26 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 24 14:39:26 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 24 14:39:26 volumio go-librespot[447]: go-librespot daemon starting... Mar 24 14:39:26 volumio go-librespot[448]: time="2026-03-24T14:39:26+01:00" level=info msg="running go-librespot 0.6.2" Mar 24 14:39:26 volumio go-librespot[448]: time="2026-03-24T14:39:26+01:00" level=debug msg="app state loaded" Mar 24 14:39:26 volumio go-librespot[448]: time="2026-03-24T14:39:26+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 24 14:39:27 volumio go-librespot[448]: time="2026-03-24T14:39:27+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Mar 24 14:39:27 volumio go-librespot[448]: time="2026-03-24T14:39:27+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Mar 24 14:39:27 volumio go-librespot[448]: time="2026-03-24T14:39:27+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Mar 24 14:39:27 volumio go-librespot[448]: time="2026-03-24T14:39:27+01:00" level=info msg="zeroconf server listening on port 36865" Mar 24 14:39:27 volumio go-librespot[448]: time="2026-03-24T14:39:27+01:00" level=debug msg="obtained new client token: AACl6+RFN9QeJ1rJHuzyqT8yCbUtjD/m/SKrQfh6Ib6DuWMrml0X5cRHcbc3u3C5+j4brdQCZdxOMv3dIOADQPHwcYUItqHS3NXBiA0zw773g1UX7weMH6vnWifFafos5MoKCgO8XZ705EOCGRETQ4dUmIAxN9CqI2ufXGCydoa0r036AXAxQph0PcF216HuTnXnQDVi/0Xb9ifZpPADr2/bLXhsVIlzEyJrziLF7E5eE2cYW6pqzi2RcQ==" Mar 24 14:39:27 volumio go-librespot[448]: time="2026-03-24T14:39:27+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Mar 24 14:39:27 volumio go-librespot[448]: time="2026-03-24T14:39:27+01:00" level=debug msg="completed keyexchange" Mar 24 14:39:27 volumio go-librespot[448]: time="2026-03-24T14:39:27+01:00" level=debug msg="completed challenge" Mar 24 14:39:27 volumio sudo[460]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-03-24 14:38' Mar 24 14:39:27 volumio sudo[460]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 14:39:27 volumio go-librespot[448]: time="2026-03-24T14:39:27+01:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 14:39:28 volumio sudo[460]: pam_unix(sudo:session): session closed for user root Mar 24 14:39:28 volumio go-librespot[448]: time="2026-03-24T14:39:28+01:00" level=debug msg="connected to ap-gew4.spotify.com:443" Mar 24 14:39:28 volumio go-librespot[448]: time="2026-03-24T14:39:28+01:00" level=debug msg="completed keyexchange" Mar 24 14:39:28 volumio go-librespot[448]: time="2026-03-24T14:39:28+01:00" level=debug msg="completed challenge" Mar 24 14:39:28 volumio go-librespot[448]: time="2026-03-24T14:39:28+01:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 14:39:29 volumio go-librespot[448]: time="2026-03-24T14:39:29+01:00" level=warning msg="failed to connect to AP ap-gew4.spotify.com:80, retrying with a different AP" error="dial tcp 34.158.1.133:80: connect: connection refused" Mar 24 14:39:29 volumio go-librespot[448]: time="2026-03-24T14:39:29+01:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Mar 24 14:39:29 volumio go-librespot[448]: time="2026-03-24T14:39:29+01:00" level=debug msg="completed keyexchange" Mar 24 14:39:29 volumio go-librespot[448]: time="2026-03-24T14:39:29+01:00" level=debug msg="completed challenge" Mar 24 14:39:29 volumio go-librespot[448]: time="2026-03-24T14:39:29+01:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 14:39:29 volumio systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Mar 24 14:39:29 volumio systemd[1]: volumio.service: Failed with result 'exit-code'. Mar 24 14:39:29 volumio systemd[1]: volumio.service: Consumed 34.087s CPU time. Mar 24 14:39:30 volumio go-librespot[448]: time="2026-03-24T14:39:30+01:00" level=debug msg="connected to ap-gew1.spotify.com:443" Mar 24 14:39:30 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Mar 24 14:39:30 volumio go-librespot[448]: time="2026-03-24T14:39:30+01:00" level=debug msg="completed keyexchange" Mar 24 14:39:30 volumio go-librespot[448]: time="2026-03-24T14:39:30+01:00" level=debug msg="completed challenge" Mar 24 14:39:30 volumio volumio-remote-updater[584]: [2026-03-24 14:39:30] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Mar 24 14:39:30 volumio go-librespot[448]: time="2026-03-24T14:39:30+01:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 14:39:30 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 7352. Mar 24 14:39:30 volumio systemd[1]: Stopped volumio.service - Volumio Backend Module. Mar 24 14:39:30 volumio systemd[1]: volumio.service: Consumed 34.087s CPU time. Mar 24 14:39:30 volumio systemd[1]: Started volumio.service - Volumio Backend Module. Mar 24 14:39:30 volumio volumio-remote-updater[584]: [2026-03-24 14:39:30] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Mar 24 14:39:30 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Mar 24 14:39:30 volumio volumio5-onboarding[22591]: time=2026-03-24T14:39:30.513+01:00 level=ERROR msg="failed reading message" component=volumio/socket error="websocket: close 1006 (abnormal closure): unexpected EOF" Mar 24 14:39:30 volumio volumio5-onboarding[22591]: time=2026-03-24T14:39:30.789+01:00 level=WARN msg="reconnection attempt failed" component=volumio/socket error="dial tcp 127.0.0.1:3000: connect: connection refused" Mar 24 14:39:30 volumio go-librespot[448]: time="2026-03-24T14:39:30+01:00" level=warning msg="failed to connect to AP ap-gae2.spotify.com:80, retrying with a different AP" error="dial tcp 104.199.241.202:80: connect: connection refused" Mar 24 14:39:30 volumio go-librespot[448]: time="2026-03-24T14:39:30+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Mar 24 14:39:31 volumio go-librespot[448]: time="2026-03-24T14:39:31+01:00" level=debug msg="completed keyexchange" Mar 24 14:39:31 volumio go-librespot[448]: time="2026-03-24T14:39:31+01:00" level=debug msg="completed challenge" Mar 24 14:39:31 volumio go-librespot[448]: time="2026-03-24T14:39:31+01:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 14:39:31 volumio go-librespot[448]: time="2026-03-24T14:39:31+01:00" level=debug msg="connected to ap-gew4.spotify.com:443" Mar 24 14:39:31 volumio volumio5-onboarding[22591]: time=2026-03-24T14:39:31.804+01:00 level=WARN msg="reconnection attempt failed" component=volumio/socket error="dial tcp 127.0.0.1:3000: connect: connection refused" Mar 24 14:39:31 volumio go-librespot[448]: time="2026-03-24T14:39:31+01:00" level=debug msg="completed keyexchange" Mar 24 14:39:31 volumio go-librespot[448]: time="2026-03-24T14:39:31+01:00" level=debug msg="completed challenge" Mar 24 14:39:31 volumio go-librespot[448]: time="2026-03-24T14:39:31+01:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 14:39:31 volumio go-librespot[448]: time="2026-03-24T14:39:31+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Mar 24 14:39:31 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 24 14:39:31 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 24 14:39:33 volumio volumio[499]: info: ------------------------------------------- Mar 24 14:39:33 volumio volumio[499]: info: ----- Volumio3 ---- Mar 24 14:39:33 volumio volumio[499]: info: ------------------------------------------- Mar 24 14:39:33 volumio volumio[499]: info: ----- System startup ---- Mar 24 14:39:33 volumio volumio[499]: info: ------------------------------------------- Mar 24 14:39:34 volumio volumio[499]: info: MYVOLUMIO Environment detected Mar 24 14:39:34 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Mar 24 14:39:34 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 24 14:39:34 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 24 14:39:34 volumio go-librespot[523]: go-librespot daemon starting... Mar 24 14:39:34 volumio go-librespot[524]: time="2026-03-24T14:39:34+01:00" level=info msg="running go-librespot 0.6.2" Mar 24 14:39:34 volumio go-librespot[524]: time="2026-03-24T14:39:34+01:00" level=debug msg="app state loaded" Mar 24 14:39:34 volumio volumio[499]: info: Plugin folders cleanup Mar 24 14:39:34 volumio volumio[499]: info: Scanning into folder /volumio/app/plugins/ Mar 24 14:39:34 volumio volumio[499]: info: Scanning category audio_interface Mar 24 14:39:34 volumio go-librespot[524]: time="2026-03-24T14:39:34+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 24 14:39:35 volumio volumio[499]: info: Scanning category miscellanea Mar 24 14:39:35 volumio volumio[499]: info: Scanning category music_service Mar 24 14:39:35 volumio volumio[499]: info: Scanning category plugins.json Mar 24 14:39:35 volumio volumio[499]: info: Scanning category system_controller Mar 24 14:39:35 volumio volumio[499]: info: Scanning category user_interface Mar 24 14:39:35 volumio volumio[499]: info: Scanning into folder /data/plugins/ Mar 24 14:39:35 volumio volumio[499]: info: Scanning category music_service Mar 24 14:39:35 volumio volumio[499]: info: Plugin folders cleanup completed Mar 24 14:39:35 volumio volumio[499]: info: ------------------------------------------- Mar 24 14:39:35 volumio volumio[499]: info: ----- Core plugins startup ---- Mar 24 14:39:35 volumio volumio[499]: info: ------------------------------------------- Mar 24 14:39:35 volumio volumio[499]: info: Loading plugins from folder /volumio/app/plugins/ Mar 24 14:39:35 volumio volumio[499]: info: Adding plugin upnp to MyMusic Plugins Mar 24 14:39:35 volumio volumio[499]: info: Adding plugin airplay_emulation to MyMusic Plugins Mar 24 14:39:35 volumio volumio[499]: info: Adding plugin upnp_browser to MyMusic Plugins Mar 24 14:39:35 volumio volumio[499]: info: Loading plugins from folder /data/plugins/ Mar 24 14:39:35 volumio volumio[499]: info: Loading plugin "system"... Mar 24 14:39:35 volumio volumio[499]: info: Loading plugin "appearance"... Mar 24 14:39:35 volumio volumio-remote-updater[584]: [2026-03-24 14:39:35] [connect] Successful connection Mar 24 14:39:35 volumio go-librespot[524]: time="2026-03-24T14:39:35+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Mar 24 14:39:35 volumio go-librespot[524]: time="2026-03-24T14:39:35+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Mar 24 14:39:35 volumio go-librespot[524]: time="2026-03-24T14:39:35+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Mar 24 14:39:35 volumio go-librespot[524]: time="2026-03-24T14:39:35+01:00" level=info msg="zeroconf server listening on port 38861" Mar 24 14:39:35 volumio go-librespot[524]: time="2026-03-24T14:39:35+01:00" level=debug msg="obtained new client token: AABzwLtG/sv2txxG+f5k7FjwI59NstvbPHwabEBeSr2AGmdfSSwdhmWzuYNeJOfNfpw1R9yJJPX2/ROWteNEDCrPEydq/NNnat01wd5CnakWOOZWwEEDKl4NPyzAS6tEW9ohoNjvxLoDCyZ8l/Vvbu09HwhVykXdQn+gDf4PPSmNQExEcKTzphNsjR7Bu4YK6irHRrbZqxW5YluT7XQNKBEUlcDgQtL6BhctK/0GvBQ2yp1blU6Z+1CStg==" Mar 24 14:39:35 volumio go-librespot[524]: time="2026-03-24T14:39:35+01:00" level=warning msg="failed to connect to AP ap-gew4.spotify.com:4070, retrying with a different AP" error="dial tcp 34.158.1.133:4070: connect: connection refused" Mar 24 14:39:35 volumio go-librespot[524]: time="2026-03-24T14:39:35+01:00" level=debug msg="connected to ap-gew4.spotify.com:443" Mar 24 14:39:35 volumio go-librespot[524]: time="2026-03-24T14:39:35+01:00" level=debug msg="completed keyexchange" Mar 24 14:39:35 volumio go-librespot[524]: time="2026-03-24T14:39:35+01:00" level=debug msg="completed challenge" Mar 24 14:39:35 volumio go-librespot[524]: time="2026-03-24T14:39:35+01:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 14:39:36 volumio go-librespot[524]: time="2026-03-24T14:39:36+01:00" level=debug msg="connected to ap-gew4.spotify.com:80" Mar 24 14:39:36 volumio go-librespot[524]: time="2026-03-24T14:39:36+01:00" level=debug msg="completed keyexchange" Mar 24 14:39:36 volumio go-librespot[524]: time="2026-03-24T14:39:36+01:00" level=debug msg="completed challenge" Mar 24 14:39:37 volumio volumio[499]: info: Loading plugin "network"... Mar 24 14:39:37 volumio go-librespot[524]: time="2026-03-24T14:39:37+01:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 14:39:37 volumio volumio[499]: info: Refreshing Cached IP Addresses Mar 24 14:39:37 volumio sudo[539]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Mar 24 14:39:37 volumio sudo[539]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 14:39:37 volumio volumio[499]: info: Loading plugin "services"... Mar 24 14:39:37 volumio sudo[541]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 24 14:39:37 volumio sudo[541]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 14:39:37 volumio volumio[499]: info: Loading plugin "volumio5onboarding"... Mar 24 14:39:37 volumio sudo[541]: pam_unix(sudo:session): session closed for user root Mar 24 14:39:37 volumio sudo[539]: pam_unix(sudo:session): session closed for user root Mar 24 14:39:37 volumio sudo[550]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Mar 24 14:39:37 volumio sudo[550]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 14:39:37 volumio volumio[499]: info: Loading plugin "alsa_controller"... Mar 24 14:39:37 volumio volumio[499]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 24 14:39:37 volumio volumio[499]: info: Loading plugin "wizard"... Mar 24 14:39:37 volumio volumio[499]: info: Loading plugin "networkfs"... Mar 24 14:39:37 volumio volumio[499]: info: Starting Udev Watcher for removable devices Mar 24 14:39:37 volumio volumio[499]: info: Ignoring mount for partition: boot Mar 24 14:39:37 volumio volumio[499]: info: Ignoring mount for partition: volumio Mar 24 14:39:37 volumio volumio[499]: info: Ignoring mount for partition: volumio_data Mar 24 14:39:37 volumio volumio[499]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Mar 24 14:39:37 volumio volumio[499]: info: Loading plugin "volumio_command_line_client"... Mar 24 14:39:37 volumio volumio[499]: info: Loading plugin "upnp"... Mar 24 14:39:37 volumio volumio[499]: info: [1774359577589] Starting Upmpd Daemon Mar 24 14:39:37 volumio volumio[499]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Mar 24 14:39:37 volumio volumio[499]: info: Loading plugin "my_music"... Mar 24 14:39:37 volumio volumio[499]: info: Loading plugin "mpd"... Mar 24 14:39:37 volumio go-librespot[524]: time="2026-03-24T14:39:37+01:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Mar 24 14:39:38 volumio go-librespot[524]: time="2026-03-24T14:39:38+01:00" level=debug msg="completed keyexchange" Mar 24 14:39:38 volumio go-librespot[524]: time="2026-03-24T14:39:38+01:00" level=debug msg="completed challenge" Mar 24 14:39:38 volumio sudo[550]: pam_unix(sudo:session): session closed for user root Mar 24 14:39:38 volumio go-librespot[524]: time="2026-03-24T14:39:38+01:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 14:39:38 volumio volumio[499]: info: Loading plugin "upnp_browser"... Mar 24 14:39:38 volumio go-librespot[524]: time="2026-03-24T14:39:38+01:00" level=debug msg="connected to ap-gew1.spotify.com:443" Mar 24 14:39:38 volumio go-librespot[524]: time="2026-03-24T14:39:38+01:00" level=debug msg="completed keyexchange" Mar 24 14:39:38 volumio go-librespot[524]: time="2026-03-24T14:39:38+01:00" level=debug msg="completed challenge" Mar 24 14:39:38 volumio go-librespot[524]: time="2026-03-24T14:39:38+01:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 14:39:39 volumio go-librespot[524]: time="2026-03-24T14:39:39+01:00" level=debug msg="connected to ap-gae2.spotify.com:80" Mar 24 14:39:39 volumio go-librespot[524]: time="2026-03-24T14:39:39+01:00" level=debug msg="completed keyexchange" Mar 24 14:39:39 volumio go-librespot[524]: time="2026-03-24T14:39:39+01:00" level=debug msg="completed challenge" Mar 24 14:39:40 volumio go-librespot[524]: time="2026-03-24T14:39:40+01:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 14:39:40 volumio volumio[499]: info: Starting UPNP Browser Mar 24 14:39:40 volumio volumio[499]: info: Loading plugin "alarm-clock"... Mar 24 14:39:40 volumio volumio[499]: info: Loading plugin "airplay_emulation"... Mar 24 14:39:40 volumio go-librespot[524]: time="2026-03-24T14:39:40+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Mar 24 14:39:40 volumio volumio[499]: info: Starting Shairport Sync Mar 24 14:39:40 volumio volumio[499]: info: Loading plugin "last_100"... Mar 24 14:39:40 volumio volumio[499]: info: Loading plugin "webradio"... Mar 24 14:39:40 volumio go-librespot[524]: time="2026-03-24T14:39:40+01:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: read tcp 192.168.44.35:58392->34.158.1.133:4070: read: connection reset by peer" Mar 24 14:39:40 volumio go-librespot[524]: time="2026-03-24T14:39:40+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: read tcp 192.168.44.35:58392->34.158.1.133:4070: read: connection reset by peer" Mar 24 14:39:40 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 24 14:39:40 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 24 14:39:40 volumio volumio[499]: info: Loading plugin "i2s_dacs"... Mar 24 14:39:40 volumio volumio[499]: info: Loading plugin "volumiodiscovery"... Mar 24 14:39:41 volumio volumio[499]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Mar 24 14:39:41 volumio volumio[499]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 24 14:39:41 volumio node[499]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Mar 24 14:39:41 volumio volumio[499]: *** WARNING *** For more information see Mar 24 14:39:41 volumio volumio[499]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Mar 24 14:39:41 volumio volumio[499]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 24 14:39:41 volumio volumio[499]: *** WARNING *** For more information see Mar 24 14:39:41 volumio node[499]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 24 14:39:41 volumio node[499]: *** WARNING *** For more information see Mar 24 14:39:41 volumio node[499]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Mar 24 14:39:41 volumio node[499]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 24 14:39:41 volumio node[499]: *** WARNING *** For more information see Mar 24 14:39:41 volumio volumio[499]: info: Applying required configuration parameters for plugin volumiodiscovery Mar 24 14:39:41 volumio volumio[499]: info: Discovery: Started advertising with name: Volumio Mar 24 14:39:41 volumio volumio[499]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Mar 24 14:39:41 volumio volumio[499]: info: Loading plugin "spop"... Mar 24 14:39:42 volumio volumio5-onboarding[22591]: time=2026-03-24T14:39:42.807+01:00 level=WARN msg="reconnection attempt failed" component=volumio/socket error="read tcp 127.0.0.1:48420->127.0.0.1:3000: i/o timeout" Mar 24 14:39:43 volumio volumio[499]: info: Loading plugin "outputs"... Mar 24 14:39:43 volumio volumio[499]: info: Loading plugin "albumart"... Mar 24 14:39:43 volumio volumio[499]: info: Plugin example_plugin is not enabled Mar 24 14:39:43 volumio volumio[499]: info: Loading plugin "inputs"... Mar 24 14:39:43 volumio volumio[499]: info: Loading plugin "updater_comm"... Mar 24 14:39:43 volumio volumio[499]: info: Plugin mpdemulation is not enabled Mar 24 14:39:43 volumio volumio[499]: info: Loading plugin "rest_api"... Mar 24 14:39:43 volumio volumio[499]: info: Loading plugin "websocket"... Mar 24 14:39:43 volumio volumio[499]: info: Starting Socket.io Server version 1.7.4 Mar 24 14:39:43 volumio volumio[499]: info: Loading i18n strings for locale pl Mar 24 14:39:43 volumio volumio[499]: Updating browse sources language Mar 24 14:39:43 volumio volumio[499]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 24 14:39:43 volumio volumio[499]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 24 14:39:43 volumio volumio[499]: info: CoreCommandRouter::initPlayerControls Mar 24 14:39:43 volumio volumio[499]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 14:39:43 volumio volumio[499]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 14:39:43 volumio volumio[499]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 14:39:43 volumio volumio[499]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 14:39:43 volumio volumio[499]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 14:39:43 volumio volumio[499]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 14:39:43 volumio volumio[499]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 14:39:43 volumio volumio[499]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 14:39:43 volumio volumio[499]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 24 14:39:43 volumio volumio[499]: Express server listening on port 3000 Mar 24 14:39:43 volumio volumio[499]: [Metrics] WebUI: 11s 63.63ms Mar 24 14:39:43 volumio volumio[578]: Forking 3 albumart workers Mar 24 14:39:43 volumio volumio[499]: info: CoreStateMachine::resetVolumioState Mar 24 14:39:43 volumio volumio[499]: info: CoreStateMachine::getcurrentVolume Mar 24 14:39:43 volumio volumio[499]: info: CoreCommandRouter::volumioRetrievevolume Mar 24 14:39:43 volumio volumio[499]: info: Volumio Network Manager: Network status updated: 2 Mar 24 14:39:43 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 4. Mar 24 14:39:43 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 24 14:39:43 volumio volumio[499]: info: CoreStateMachine::pushState Mar 24 14:39:43 volumio volumio[499]: info: CorePlayQueue::getTrack 0 Mar 24 14:39:43 volumio volumio[499]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 24 14:39:43 volumio volumio[499]: info: CoreCommandRouter::volumioPushState Mar 24 14:39:43 volumio volumio[499]: info: CoreStateMachine::updateTrackBlock Mar 24 14:39:43 volumio volumio[499]: info: CorePlayQueue::getTrackBlock Mar 24 14:39:43 volumio volumio[499]: info: CoreCommandRouter::volumioRetrievevolume Mar 24 14:39:43 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 24 14:39:43 volumio go-librespot[629]: go-librespot daemon starting... Mar 24 14:39:44 volumio volumio[499]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 24 14:39:44 volumio volumio[499]: info: Reloading queue from file Mar 24 14:39:44 volumio volumio[499]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 1 Mar 24 14:39:44 volumio volumio[499]: info: CoreStateMachine::pushState Mar 24 14:39:44 volumio volumio[499]: info: CorePlayQueue::getTrack 0 Mar 24 14:39:44 volumio volumio[499]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 24 14:39:44 volumio volumio[499]: info: CoreCommandRouter::volumioPushState Mar 24 14:39:44 volumio volumio[499]: info: CoreStateMachine::setRepeat null single undefined Mar 24 14:39:44 volumio volumio[499]: info: CoreStateMachine::pushState Mar 24 14:39:44 volumio volumio[499]: info: CorePlayQueue::getTrack 0 Mar 24 14:39:44 volumio volumio[499]: info: CoreCommandRouter::volumioPushState Mar 24 14:39:44 volumio volumio[499]: info: CoreStateMachine::setRandom null Mar 24 14:39:44 volumio volumio[499]: info: CoreStateMachine::pushState Mar 24 14:39:44 volumio volumio[499]: info: CorePlayQueue::getTrack 0 Mar 24 14:39:44 volumio volumio[499]: info: CoreCommandRouter::volumioPushState Mar 24 14:39:44 volumio volumio[499]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 1 Mar 24 14:39:44 volumio volumio[499]: info: Received Get System Info Mar 24 14:39:44 volumio volumio[499]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 24 14:39:44 volumio volumio[499]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 24 14:39:44 volumio volumio[499]: info: Discovery: Getting this device information Mar 24 14:39:44 volumio volumio[499]: info: CoreCommandRouter::volumioGetState Mar 24 14:39:44 volumio volumio[499]: info: CorePlayQueue::getTrack 0 Mar 24 14:39:44 volumio volumio[499]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 24 14:39:44 volumio volumio[499]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Mar 24 14:39:44 volumio volumio[499]: info: USB Boot Capable - System SBC Revision found in cpuinfo: 902120 Mar 24 14:39:44 volumio volumio[499]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Mar 24 14:39:44 volumio volumio[499]: info: Setting Device type: Raspberry PI Mar 24 14:39:44 volumio volumio[499]: info: Completed loading Core Plugins Mar 24 14:39:44 volumio volumio[499]: info: Preparing to generate the ALSA configuration file Mar 24 14:39:44 volumio volumio[499]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Mar 24 14:39:44 volumio volumio[499]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Mar 24 14:39:44 volumio volumio[499]: info: The plugin alsa_controller has an ALSA contribution file softvolume.postVolume.conf Mar 24 14:39:44 volumio volumio[499]: info: Reading ALSA contributions from plugins. Mar 24 14:39:44 volumio volumio[499]: info: Asound.conf file unchanged, so no further update is needed Mar 24 14:39:44 volumio volumio[499]: info: Output device has changed, restarting MPD Mar 24 14:39:44 volumio volumio[499]: info: Output device has changed, restarting Shairport Sync Mar 24 14:39:44 volumio volumio[499]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 14:39:44 volumio volumio[499]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 24 14:39:44 volumio volumio[499]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 24 14:39:44 volumio volumio[499]: info: ___________ START PLUGINS ___________ Mar 24 14:39:44 volumio go-librespot[635]: time="2026-03-24T14:39:44+01:00" level=info msg="running go-librespot 0.6.2" Mar 24 14:39:44 volumio go-librespot[635]: time="2026-03-24T14:39:44+01:00" level=debug msg="app state loaded" Mar 24 14:39:44 volumio volumio[499]: info: ControllerMpd::onStart: Initializing MPD Mar 24 14:39:44 volumio volumio[499]: info: Creating MPD Configuration file Mar 24 14:39:44 volumio volumio[499]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 24 14:39:44 volumio volumio[499]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 24 14:39:44 volumio volumio[499]: info: [1774359584651] CoreMusicLibrary::Adding element Serwery Mediów Mar 24 14:39:44 volumio volumio[499]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 24 14:39:44 volumio volumio[499]: info: UPNP Browser: Client initialized successfully Mar 24 14:39:44 volumio volumio[499]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 14:39:44 volumio volumio[499]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 24 14:39:44 volumio go-librespot[635]: time="2026-03-24T14:39:44+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 24 14:39:44 volumio sudo[661]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumio5-onboarding.service Mar 24 14:39:44 volumio sudo[666]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Mar 24 14:39:44 volumio sudo[653]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Mar 24 14:39:44 volumio sudo[666]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 14:39:44 volumio sudo[653]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 14:39:44 volumio sudo[655]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Mar 24 14:39:44 volumio sudo[655]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 14:39:44 volumio sudo[661]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 14:39:44 volumio sudo[664]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Mar 24 14:39:44 volumio sudo[664]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 14:39:44 volumio sudo[653]: pam_unix(sudo:session): session closed for user root Mar 24 14:39:44 volumio sudo[664]: pam_unix(sudo:session): session closed for user root Mar 24 14:39:44 volumio volumio[499]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 24 14:39:44 volumio volumio[499]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 14:39:44 volumio volumio[499]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 24 14:39:44 volumio volumio[499]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 24 14:39:44 volumio volumio[499]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 24 14:39:44 volumio volumio[499]: info: [1774359584941] CoreMusicLibrary::Adding element Last_100 Mar 24 14:39:44 volumio volumio[499]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 24 14:39:44 volumio volumio[499]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 24 14:39:44 volumio volumio[499]: info: [1774359584953] CoreMusicLibrary::Adding element Webradio Mar 24 14:39:44 volumio volumio[499]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 24 14:39:44 volumio volumio[499]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 24 14:39:44 volumio volumio[499]: info: Initializing BBC Radios Mar 24 14:39:45 volumio volumio[499]: /usr/bin/md5sum: /sys/class/net/eth0/address: No such file or directory Mar 24 14:39:45 volumio volumio[499]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 24 14:39:45 volumio volumio[499]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 24 14:39:45 volumio volumio[499]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 24 14:39:45 volumio volumio[499]: info: Creating Spotify config file Mar 24 14:39:45 volumio volumio[499]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 14:39:45 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Mar 24 14:39:45 volumio sudo[661]: pam_unix(sudo:session): session closed for user root Mar 24 14:39:45 volumio go-librespot[635]: time="2026-03-24T14:39:45+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Mar 24 14:39:45 volumio go-librespot[635]: time="2026-03-24T14:39:45+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Mar 24 14:39:45 volumio go-librespot[635]: time="2026-03-24T14:39:45+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Mar 24 14:39:45 volumio go-librespot[635]: time="2026-03-24T14:39:45+01:00" level=info msg="zeroconf server listening on port 41187" Mar 24 14:39:45 volumio go-librespot[635]: time="2026-03-24T14:39:45+01:00" level=debug msg="obtained new client token: AABLqM9keAsQvIYoasFcBkPGpOMgtBSz2L/VIbYoGOf1aOS1gLBd2CRznd2ojyZ9QoJ7VE++rp01RepfhbPLObC82E3heKH3jPw6THcmp/R6S3TMZkCSPEROdFPZ/dnhZ2geA6mcLfwGukT5E+4VzhHhM63snCYJLHj997IFx9JHpSzQGgmmhF5peRcFSjuFoEI1DnFyhEVgtSATo5vv+XSVeU4ktgHlpo0fe1W4CNaSZq+dba67OAbAoQ==" Mar 24 14:39:45 volumio go-librespot[635]: time="2026-03-24T14:39:45+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Mar 24 14:39:45 volumio go-librespot[635]: time="2026-03-24T14:39:45+01:00" level=debug msg="completed keyexchange" Mar 24 14:39:45 volumio go-librespot[635]: time="2026-03-24T14:39:45+01:00" level=debug msg="completed challenge" Mar 24 14:39:45 volumio go-librespot[635]: time="2026-03-24T14:39:45+01:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 14:39:46 volumio volumio[499]: info: Volumio Calling Home Mar 24 14:39:46 volumio volumio[598]: Starting albumart workers Mar 24 14:39:46 volumio volumio[595]: Starting albumart workers Mar 24 14:39:46 volumio volumio[603]: Starting albumart workers Mar 24 14:39:46 volumio go-librespot[635]: time="2026-03-24T14:39:46+01:00" level=debug msg="connected to ap-gew4.spotify.com:443" Mar 24 14:39:46 volumio go-librespot[635]: time="2026-03-24T14:39:46+01:00" level=debug msg="completed keyexchange" Mar 24 14:39:46 volumio go-librespot[635]: time="2026-03-24T14:39:46+01:00" level=debug msg="completed challenge" Mar 24 14:39:46 volumio go-librespot[635]: time="2026-03-24T14:39:46+01:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 14:39:46 volumio volumio[499]: info: Discovery: adding 2456885c-5bc0-4391-bb8e-47f9f2a2e3dd Mar 24 14:39:46 volumio volumio[499]: info: Discovery: Found device Volumio Mar 24 14:39:46 volumio volumio[499]: info: CoreCommandRouter::volumioGetState Mar 24 14:39:46 volumio volumio[499]: info: CorePlayQueue::getTrack 0 Mar 24 14:39:46 volumio volumio[499]: info: Discovery: this is already registered, 2456885c-5bc0-4391-bb8e-47f9f2a2e3dd Mar 24 14:39:46 volumio volumio[499]: info: Discovery: Found device Volumio Mar 24 14:39:46 volumio volumio[499]: info: CoreCommandRouter::volumioGetState Mar 24 14:39:46 volumio volumio[499]: info: CorePlayQueue::getTrack 0 Mar 24 14:39:46 volumio volumio[499]: info: MPD Permissions set Mar 24 14:39:46 volumio volumio[499]: info: MPD Permissions set Mar 24 14:39:46 volumio volumio[499]: info: Volumio called home Mar 24 14:39:46 volumio volumio[499]: info: Spotify config file written Mar 24 14:39:47 volumio sudo[712]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 24 14:39:47 volumio sudo[712]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 14:39:47 volumio volumio[499]: 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 24 14:39:47 volumio volumio[499]: info: No need to fix Spotify hosts Mar 24 14:39:47 volumio volumio[499]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 14:39:47 volumio volumio[499]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 14:39:47 volumio volumio[499]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 14:39:47 volumio volumio[499]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 14:39:47 volumio volumio[499]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 14:39:47 volumio volumio[499]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 14:39:47 volumio volumio[499]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 14:39:47 volumio volumio[499]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 14:39:47 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Mar 24 14:39:47 volumio systemd[1]: go-librespot-daemon.service: Killing process 702 (n/a) with signal SIGKILL. Mar 24 14:39:47 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Mar 24 14:39:47 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 24 14:39:47 volumio volumio[499]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 24 14:39:47 volumio volumio[499]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 14:39:47 volumio volumio[499]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 14:39:47 volumio volumio[499]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 14:39:47 volumio volumio[499]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 14:39:47 volumio volumio[499]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 14:39:47 volumio volumio[499]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 14:39:47 volumio volumio[499]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 14:39:47 volumio volumio[499]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 14:39:47 volumio volumio[499]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 14:39:47 volumio volumio[499]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 24 14:39:47 volumio volumio[499]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 14:39:47 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 24 14:39:47 volumio sudo[712]: pam_unix(sudo:session): session closed for user root Mar 24 14:39:47 volumio go-librespot[720]: go-librespot daemon starting... Mar 24 14:39:47 volumio go-librespot[743]: time="2026-03-24T14:39:47+01:00" level=info msg="running go-librespot 0.6.2" Mar 24 14:39:47 volumio go-librespot[743]: time="2026-03-24T14:39:47+01:00" level=debug msg="app state loaded" Mar 24 14:39:47 volumio go-librespot[743]: time="2026-03-24T14:39:47+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 24 14:39:47 volumio volumio-remote-updater[584]: [2026-03-24 14:39:47] [connect] Successful connection Mar 24 14:39:47 volumio sudo[753]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Mar 24 14:39:47 volumio sudo[755]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 24 14:39:47 volumio sudo[755]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 14:39:47 volumio sudo[753]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 14:39:47 volumio volumio-remote-updater[584]: [2026-03-24 14:39:47] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1774359587 101 Mar 24 14:39:47 volumio sudo[755]: pam_unix(sudo:session): session closed for user root Mar 24 14:39:48 volumio volumio[499]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 3 Transport: websocket Total Clients: 3 Mar 24 14:39:48 volumio volumio[499]: info: Starting Shairport Sync Mar 24 14:39:48 volumio sudo[753]: pam_unix(sudo:session): session closed for user root Mar 24 14:39:48 volumio volumio[499]: info: Starting Shairport Sync Mar 24 14:39:48 volumio sudo[781]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Mar 24 14:39:48 volumio sudo[781]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 14:39:48 volumio volumio[499]: info: Starting Shairport Sync Mar 24 14:39:48 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Mar 24 14:39:48 volumio volumio[499]: info: An error occurred while refreshing Spotify Token Error: Bad Request Mar 24 14:39:48 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Mar 24 14:39:48 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Mar 24 14:39:48 volumio systemd[1]: shairport-sync.service: Consumed 2.314s CPU time. Mar 24 14:39:48 volumio sudo[793]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Mar 24 14:39:48 volumio sudo[793]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 14:39:48 volumio sudo[791]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Mar 24 14:39:48 volumio sudo[791]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 14:39:48 volumio go-librespot[743]: time="2026-03-24T14:39:48+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Mar 24 14:39:48 volumio go-librespot[743]: time="2026-03-24T14:39:48+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Mar 24 14:39:48 volumio go-librespot[743]: time="2026-03-24T14:39:48+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Mar 24 14:39:48 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Mar 24 14:39:48 volumio go-librespot[743]: time="2026-03-24T14:39:48+01:00" level=info msg="zeroconf server listening on port 45809" Mar 24 14:39:48 volumio sudo[781]: pam_unix(sudo:session): session closed for user root Mar 24 14:39:48 volumio volumio[499]: info: Shairport-Sync Started Mar 24 14:39:48 volumio volumio[499]: Error adding Membership: Error: addMembership EINVAL Mar 24 14:39:48 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Mar 24 14:39:48 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Mar 24 14:39:48 volumio volumio[499]: info: CoreCommandRouter::volumioGetState Mar 24 14:39:48 volumio volumio[499]: info: CorePlayQueue::getTrack 0 Mar 24 14:39:48 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Mar 24 14:39:48 volumio sudo[798]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Mar 24 14:39:48 volumio sudo[798]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 14:39:48 volumio go-librespot[743]: time="2026-03-24T14:39:48+01:00" level=debug msg="obtained new client token: AADqfn9kmn/BeqTXyo1p4DeTlS2EKJO0g8SQTvMXzxsNvTuUo+eMtsWSQaYTYKweYS6o6roJqQyrdnjfPlbaEn5elNvgGwEXu3rhwHtaRY5BMbzTQArrJFtXIoTeYAKz8JvG0O6o6YzHP9V9NX29wh6n5wUD14a0vZbJ2VzQHcA+q9nJqoqT/KhjlMdBAQ82vR4giqN6du0z1e0sw8V2SgIU7pXw1pdPd8HQu2hnXsOsfR4AqwZX3FmSeg==" Mar 24 14:39:48 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Mar 24 14:39:48 volumio sudo[791]: pam_unix(sudo:session): session closed for user root Mar 24 14:39:48 volumio sudo[793]: pam_unix(sudo:session): session closed for user root Mar 24 14:39:48 volumio volumio[499]: info: Shairport-Sync Started Mar 24 14:39:48 volumio volumio[499]: info: Shairport-Sync Started Mar 24 14:39:48 volumio go-librespot[743]: time="2026-03-24T14:39:48+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Mar 24 14:39:48 volumio sudo[798]: pam_unix(sudo:session): session closed for user root Mar 24 14:39:48 volumio volumio[499]: info: Upmpdcli Daemon Started Mar 24 14:39:48 volumio go-librespot[743]: time="2026-03-24T14:39:48+01:00" level=debug msg="completed keyexchange" Mar 24 14:39:48 volumio go-librespot[743]: time="2026-03-24T14:39:48+01:00" level=debug msg="completed challenge" Mar 24 14:39:48 volumio go-librespot[743]: time="2026-03-24T14:39:48+01:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 14:39:49 volumio go-librespot[743]: time="2026-03-24T14:39:49+01:00" level=debug msg="connected to ap-gew4.spotify.com:443" Mar 24 14:39:49 volumio go-librespot[743]: time="2026-03-24T14:39:49+01:00" level=debug msg="completed keyexchange" Mar 24 14:39:49 volumio go-librespot[743]: time="2026-03-24T14:39:49+01:00" level=debug msg="completed challenge" Mar 24 14:39:49 volumio go-librespot[743]: time="2026-03-24T14:39:49+01:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 14:39:49 volumio go-librespot[743]: time="2026-03-24T14:39:49+01:00" level=debug msg="connected to ap-gew4.spotify.com:80" Mar 24 14:39:50 volumio go-librespot[743]: time="2026-03-24T14:39:50+01:00" level=debug msg="completed keyexchange" Mar 24 14:39:50 volumio go-librespot[743]: time="2026-03-24T14:39:50+01:00" level=debug msg="completed challenge" Mar 24 14:39:50 volumio go-librespot[743]: time="2026-03-24T14:39:50+01:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 14:39:50 volumio go-librespot[743]: time="2026-03-24T14:39:50+01:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Mar 24 14:39:50 volumio volumio[499]: info: go-librespot daemon successfully initialized Mar 24 14:39:51 volumio go-librespot[743]: time="2026-03-24T14:39:51+01:00" level=debug msg="completed keyexchange" Mar 24 14:39:51 volumio go-librespot[743]: time="2026-03-24T14:39:51+01:00" level=debug msg="completed challenge" Mar 24 14:39:51 volumio go-librespot[743]: time="2026-03-24T14:39:51+01:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 14:39:51 volumio go-librespot[743]: time="2026-03-24T14:39:51+01:00" level=debug msg="connected to ap-gew1.spotify.com:443" Mar 24 14:39:51 volumio go-librespot[743]: time="2026-03-24T14:39:51+01:00" level=debug msg="completed keyexchange" Mar 24 14:39:51 volumio go-librespot[743]: time="2026-03-24T14:39:51+01:00" level=debug msg="completed challenge" Mar 24 14:39:51 volumio go-librespot[743]: time="2026-03-24T14:39:51+01:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 14:39:52 volumio systemd[1]: mpd.service: Deactivated successfully. Mar 24 14:39:52 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Mar 24 14:39:52 volumio systemd[1]: mpd.service: Consumed 8.169s CPU time. Mar 24 14:39:52 volumio systemd[1]: mpd.socket: Deactivated successfully. Mar 24 14:39:52 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Mar 24 14:39:52 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Mar 24 14:39:52 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Mar 24 14:39:52 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Mar 24 14:39:52 volumio sudo[817]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Mar 24 14:39:52 volumio sudo[817]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Mar 24 14:39:52 volumio sudo[817]: pam_unix(sudo:session): session closed for user root Mar 24 14:39:52 volumio go-librespot[743]: time="2026-03-24T14:39:52+01:00" level=warning msg="failed to connect to AP ap-gae2.spotify.com:80, retrying with a different AP" error="dial tcp 104.199.241.202:80: connect: connection refused" Mar 24 14:39:52 volumio go-librespot[743]: time="2026-03-24T14:39:52+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Mar 24 14:39:52 volumio go-librespot[743]: time="2026-03-24T14:39:52+01:00" level=debug msg="completed keyexchange" Mar 24 14:39:52 volumio go-librespot[743]: time="2026-03-24T14:39:52+01:00" level=debug msg="completed challenge" Mar 24 14:39:52 volumio go-librespot[743]: time="2026-03-24T14:39:52+01:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 14:39:52 volumio go-librespot[743]: time="2026-03-24T14:39:52+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Mar 24 14:39:52 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 24 14:39:52 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 24 14:39:53 volumio volumio[499]: info: Initializing connection to go-librespot Websocket Mar 24 14:39:53 volumio volumio[499]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 24 14:39:55 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Mar 24 14:39:55 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 24 14:39:55 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 24 14:39:56 volumio go-librespot[820]: go-librespot daemon starting... Mar 24 14:39:56 volumio go-librespot[821]: time="2026-03-24T14:39:56+01:00" level=info msg="running go-librespot 0.6.2" Mar 24 14:39:56 volumio go-librespot[821]: time="2026-03-24T14:39:56+01:00" level=debug msg="app state loaded" Mar 24 14:39:56 volumio go-librespot[821]: time="2026-03-24T14:39:56+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 24 14:39:56 volumio volumio[499]: info: Initializing connection to go-librespot Websocket Mar 24 14:39:56 volumio go-librespot[821]: time="2026-03-24T14:39:56+01:00" level=debug msg="new websocket client" Mar 24 14:39:56 volumio volumio[499]: info: Connection to go-librespot Websocket established Mar 24 14:39:57 volumio go-librespot[821]: time="2026-03-24T14:39:57+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Mar 24 14:39:57 volumio go-librespot[821]: time="2026-03-24T14:39:57+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Mar 24 14:39:57 volumio go-librespot[821]: time="2026-03-24T14:39:57+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Mar 24 14:39:57 volumio go-librespot[821]: time="2026-03-24T14:39:57+01:00" level=info msg="zeroconf server listening on port 35699" Mar 24 14:39:57 volumio go-librespot[821]: time="2026-03-24T14:39:57+01:00" level=debug msg="obtained new client token: AACLGsnzLXNgk6tXrKXejiqTOGYS2aNIteTM4bm+A3CFs2dVxwVbu5RfktionczHTyyg8h2GApv7DcZ/sBMvGgyOizvSzg8JWMRIY8itnhkqbq21IEszNml7n9lYmNgkVq0j3ygN+m/h9iXu3OlwyXtQFGsg+N/CzrsAULlM/ahlADTYlp2Po+9lw5FxcKxwO/QvhC0r4iGTpE4QY+GHTa0Zu/eEyfOQ4t16ZND/kPAx0fVSf/LK+No=" Mar 24 14:39:57 volumio go-librespot[821]: time="2026-03-24T14:39:57+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Mar 24 14:39:57 volumio go-librespot[821]: time="2026-03-24T14:39:57+01:00" level=debug msg="completed keyexchange" Mar 24 14:39:57 volumio go-librespot[821]: time="2026-03-24T14:39:57+01:00" level=debug msg="completed challenge" Mar 24 14:39:58 volumio go-librespot[821]: time="2026-03-24T14:39:58+01:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 14:39:58 volumio go-librespot[821]: time="2026-03-24T14:39:58+01:00" level=debug msg="connected to ap-gew4.spotify.com:443" Mar 24 14:39:58 volumio go-librespot[821]: time="2026-03-24T14:39:58+01:00" level=debug msg="completed keyexchange" Mar 24 14:39:58 volumio go-librespot[821]: time="2026-03-24T14:39:58+01:00" level=debug msg="completed challenge" Mar 24 14:39:58 volumio go-librespot[821]: time="2026-03-24T14:39:58+01:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 14:39:59 volumio go-librespot[821]: time="2026-03-24T14:39:59+01:00" level=debug msg="connected to ap-gew4.spotify.com:80" Mar 24 14:39:59 volumio go-librespot[821]: time="2026-03-24T14:39:59+01:00" level=debug msg="completed keyexchange" Mar 24 14:39:59 volumio go-librespot[821]: time="2026-03-24T14:39:59+01:00" level=debug msg="completed challenge" Mar 24 14:39:59 volumio go-librespot[821]: time="2026-03-24T14:39:59+01:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 14:40:00 volumio go-librespot[821]: time="2026-03-24T14:40:00+01:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Mar 24 14:40:00 volumio go-librespot[821]: time="2026-03-24T14:40:00+01:00" level=debug msg="completed keyexchange" Mar 24 14:40:00 volumio go-librespot[821]: time="2026-03-24T14:40:00+01:00" level=debug msg="completed challenge" Mar 24 14:40:00 volumio go-librespot[821]: time="2026-03-24T14:40:00+01:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 14:40:00 volumio volumio[499]: info: Getting Spotify volume Mar 24 14:40:00 volumio go-librespot[821]: time="2026-03-24T14:40:00+01:00" level=debug msg="connected to ap-gew1.spotify.com:443" Mar 24 14:40:01 volumio go-librespot[821]: time="2026-03-24T14:40:01+01:00" level=debug msg="completed keyexchange" Mar 24 14:40:01 volumio go-librespot[821]: time="2026-03-24T14:40:01+01:00" level=debug msg="completed challenge" Mar 24 14:40:01 volumio volumio[499]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 4 Mar 24 14:40:01 volumio go-librespot[821]: time="2026-03-24T14:40:01+01:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 14:40:01 volumio volumio[499]: info: CoreCommandRouter::volumioGetState Mar 24 14:40:01 volumio volumio[499]: info: CorePlayQueue::getTrack 0 Mar 24 14:40:01 volumio volumio[499]: SPOTIFY: RECEIVED VOLUMIO VOLUME 72 Mar 24 14:40:01 volumio volumio[499]: SPOTIFY: SPOTIFY VOLUME undefined Mar 24 14:40:01 volumio volumio[499]: SPOTIFY: VOLUMIO VOLUME 72 Mar 24 14:40:01 volumio volumio[499]: info: Aligning Spotify Volume to Volumio Volume Mar 24 14:40:01 volumio volumio[499]: info: CoreCommandRouter::volumioGetState Mar 24 14:40:01 volumio volumio[499]: info: CorePlayQueue::getTrack 0 Mar 24 14:40:01 volumio volumio[499]: info: Setting Spotify Volume from Volumio: 72 Mar 24 14:40:01 volumio go-librespot[821]: time="2026-03-24T14:40:01+01:00" level=debug msg="connected to ap-gae2.spotify.com:80" Mar 24 14:40:02 volumio go-librespot[821]: time="2026-03-24T14:40:02+01:00" level=debug msg="completed keyexchange" Mar 24 14:40:02 volumio go-librespot[821]: time="2026-03-24T14:40:02+01:00" level=debug msg="completed challenge" Mar 24 14:40:02 volumio mpd[819]: 2026-03-24T14:40:02 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Mar 24 14:40:02 volumio go-librespot[821]: time="2026-03-24T14:40:02+01:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 14:40:02 volumio go-librespot[821]: time="2026-03-24T14:40:02+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Mar 24 14:40:02 volumio systemd[1]: Started mpd.service - Music Player Daemon. Mar 24 14:40:02 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 24 14:40:02 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 24 14:40:02 volumio volumio[499]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 24 14:40:02 volumio sudo[666]: pam_unix(sudo:session): session closed for user root Mar 24 14:40:02 volumio sudo[655]: pam_unix(sudo:session): session closed for user root Mar 24 14:40:02 volumio volumio[499]: Error: socket hang up Mar 24 14:40:02 volumio volumio[499]: at connResetException (node:internal/errors:720:14) Mar 24 14:40:02 volumio volumio[499]: at Socket.socketOnEnd (node:_http_client:519:23) Mar 24 14:40:02 volumio volumio[499]: at Socket.emit (node:events:526:35) Mar 24 14:40:02 volumio volumio[499]: at endReadableNT (node:internal/streams/readable:1376:12) Mar 24 14:40:02 volumio volumio[499]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { Mar 24 14:40:02 volumio volumio[499]: code: 'ECONNRESET', Mar 24 14:40:02 volumio volumio[499]: response: undefined Mar 24 14:40:02 volumio volumio[499]: } Mar 24 14:40:02 volumio volumio[499]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 24 14:40:05 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Mar 24 14:40:05 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 24 14:40:05 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 24 14:40:05 volumio systemd[1]: Starting setdatetime-helper.service - Time Synchronization Helper Service... Mar 24 14:40:05 volumio go-librespot[862]: go-librespot daemon starting... Mar 24 14:40:05 volumio go-librespot[864]: time="2026-03-24T14:40:05+01:00" level=info msg="running go-librespot 0.6.2" Mar 24 14:40:05 volumio go-librespot[864]: time="2026-03-24T14:40:05+01:00" level=debug msg="app state loaded" Mar 24 14:40:05 volumio go-librespot[864]: time="2026-03-24T14:40:05+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 24 14:40:06 volumio go-librespot[864]: time="2026-03-24T14:40:06+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Mar 24 14:40:06 volumio go-librespot[864]: time="2026-03-24T14:40:06+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Mar 24 14:40:06 volumio go-librespot[864]: time="2026-03-24T14:40:06+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Mar 24 14:40:06 volumio go-librespot[864]: time="2026-03-24T14:40:06+01:00" level=info msg="zeroconf server listening on port 43207" Mar 24 14:40:06 volumio go-librespot[864]: time="2026-03-24T14:40:06+01:00" level=debug msg="obtained new client token: AAB36wxZndINPDmbrG6ooXkyDGMw3fm4ump0PRoQh59dGGbx6ANIyGiecpQFMsh4POpUBmTGQeXFA6n+oeB44VygRVMDwQQghxmfCNCPGWEx6iEVVKSRIZLgowbSxQF6dIUcVP3T4yb5TBvcDzxeR74vrBg9jytB9CaQxmVcCfdC279KOhugt0HXbsbGT4S4LXXa/rTzw6iaCZBNDDVM7ahqzGEVHvgltwQX9dGuQF1XQNyerVJwMDsLCA==" Mar 24 14:40:06 volumio sudo[894]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-03-24 14:39' Mar 24 14:40:06 volumio sudo[894]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 14:40:06 volumio go-librespot[864]: time="2026-03-24T14:40:06+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Mar 24 14:40:07 volumio sudo[894]: pam_unix(sudo:session): session closed for user root Mar 24 14:40:07 volumio go-librespot[864]: time="2026-03-24T14:40:07+01:00" level=debug msg="completed keyexchange" Mar 24 14:40:07 volumio go-librespot[864]: time="2026-03-24T14:40:07+01:00" level=debug msg="completed challenge" Mar 24 14:40:07 volumio go-librespot[864]: time="2026-03-24T14:40:07+01:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 14:40:07 volumio systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Mar 24 14:40:07 volumio systemd[1]: volumio.service: Failed with result 'exit-code'. Mar 24 14:40:07 volumio systemd[1]: volumio.service: Consumed 32.858s CPU time. Mar 24 14:40:07 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Mar 24 14:40:07 volumio volumio-remote-updater[584]: [2026-03-24 14:40:07] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Mar 24 14:40:07 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Mar 24 14:40:07 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 7353. Mar 24 14:40:07 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Mar 24 14:40:07 volumio systemd[1]: Stopped volumio.service - Volumio Backend Module. Mar 24 14:40:07 volumio systemd[1]: volumio.service: Consumed 32.858s CPU time. Mar 24 14:40:07 volumio systemd[1]: Started volumio.service - Volumio Backend Module. Mar 24 14:40:07 volumio volumio-remote-updater[584]: [2026-03-24 14:40:07] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Mar 24 14:40:07 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Mar 24 14:40:08 volumio go-librespot[864]: time="2026-03-24T14:40:08+01:00" level=debug msg="connected to ap-gew4.spotify.com:443" Mar 24 14:40:08 volumio volumio5-onboarding[22591]: time=2026-03-24T14:40:08.347+01:00 level=ERROR msg="failed reading message" component=volumio/socket error="websocket: close 1006 (abnormal closure): unexpected EOF" Mar 24 14:40:08 volumio go-librespot[864]: time="2026-03-24T14:40:08+01:00" level=debug msg="completed keyexchange" Mar 24 14:40:08 volumio go-librespot[864]: time="2026-03-24T14:40:08+01:00" level=debug msg="completed challenge" Mar 24 14:40:08 volumio volumio5-onboarding[22591]: time=2026-03-24T14:40:08.578+01:00 level=WARN msg="reconnection attempt failed" component=volumio/socket error="dial tcp 127.0.0.1:3000: connect: connection refused" Mar 24 14:40:08 volumio go-librespot[864]: time="2026-03-24T14:40:08+01:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 14:40:09 volumio systemd[1]: setdatetime-helper.service: Deactivated successfully. Mar 24 14:40:09 volumio systemd[1]: Finished setdatetime-helper.service - Time Synchronization Helper Service. Mar 24 14:40:09 volumio systemd[1]: setdatetime-helper.service: Consumed 2.253s CPU time. Mar 24 14:40:09 volumio go-librespot[864]: time="2026-03-24T14:40:09+01:00" level=debug msg="connected to ap-gew4.spotify.com:80" Mar 24 14:40:09 volumio volumio5-onboarding[22591]: time=2026-03-24T14:40:09.606+01:00 level=WARN msg="reconnection attempt failed" component=volumio/socket error="dial tcp 127.0.0.1:3000: connect: connection refused" Mar 24 14:40:09 volumio go-librespot[864]: time="2026-03-24T14:40:09+01:00" level=debug msg="completed keyexchange" Mar 24 14:40:09 volumio go-librespot[864]: time="2026-03-24T14:40:09+01:00" level=debug msg="completed challenge" Mar 24 14:40:10 volumio go-librespot[864]: time="2026-03-24T14:40:10+01:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 14:40:10 volumio go-librespot[864]: time="2026-03-24T14:40:10+01:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Mar 24 14:40:11 volumio go-librespot[864]: time="2026-03-24T14:40:11+01:00" level=debug msg="completed keyexchange" Mar 24 14:40:11 volumio go-librespot[864]: time="2026-03-24T14:40:11+01:00" level=debug msg="completed challenge" Mar 24 14:40:11 volumio go-librespot[864]: time="2026-03-24T14:40:11+01:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 14:40:11 volumio volumio[924]: info: ------------------------------------------- Mar 24 14:40:11 volumio volumio[924]: info: ----- Volumio3 ---- Mar 24 14:40:11 volumio volumio[924]: info: ------------------------------------------- Mar 24 14:40:11 volumio volumio[924]: info: ----- System startup ---- Mar 24 14:40:11 volumio volumio[924]: info: ------------------------------------------- Mar 24 14:40:11 volumio go-librespot[864]: time="2026-03-24T14:40:11+01:00" level=debug msg="connected to ap-gew1.spotify.com:443" Mar 24 14:40:11 volumio go-librespot[864]: time="2026-03-24T14:40:11+01:00" level=debug msg="completed keyexchange" Mar 24 14:40:11 volumio go-librespot[864]: time="2026-03-24T14:40:11+01:00" level=debug msg="completed challenge" Mar 24 14:40:11 volumio go-librespot[864]: time="2026-03-24T14:40:11+01:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 14:40:12 volumio go-librespot[864]: time="2026-03-24T14:40:12+01:00" level=warning msg="failed to connect to AP ap-gae2.spotify.com:80, retrying with a different AP" error="dial tcp 104.199.241.202:80: connect: connection refused" Mar 24 14:40:12 volumio volumio[924]: info: MYVOLUMIO Environment detected Mar 24 14:40:12 volumio volumio[924]: info: Plugin folders cleanup Mar 24 14:40:12 volumio volumio[924]: info: Scanning into folder /volumio/app/plugins/ Mar 24 14:40:12 volumio volumio[924]: info: Scanning category audio_interface Mar 24 14:40:12 volumio volumio[924]: info: Scanning category miscellanea Mar 24 14:40:12 volumio volumio[924]: info: Scanning category music_service Mar 24 14:40:12 volumio volumio[924]: info: Scanning category plugins.json Mar 24 14:40:12 volumio volumio[924]: info: Scanning category system_controller Mar 24 14:40:12 volumio volumio[924]: info: Scanning category user_interface Mar 24 14:40:12 volumio volumio[924]: info: Scanning into folder /data/plugins/ Mar 24 14:40:12 volumio volumio[924]: info: Scanning category music_service Mar 24 14:40:12 volumio volumio[924]: info: Plugin folders cleanup completed Mar 24 14:40:12 volumio volumio[924]: info: ------------------------------------------- Mar 24 14:40:12 volumio volumio[924]: info: ----- Core plugins startup ---- Mar 24 14:40:12 volumio volumio[924]: info: ------------------------------------------- Mar 24 14:40:12 volumio volumio[924]: info: Loading plugins from folder /volumio/app/plugins/ Mar 24 14:40:12 volumio volumio[924]: info: Adding plugin upnp to MyMusic Plugins Mar 24 14:40:12 volumio volumio[924]: info: Adding plugin airplay_emulation to MyMusic Plugins Mar 24 14:40:12 volumio volumio[924]: info: Adding plugin upnp_browser to MyMusic Plugins Mar 24 14:40:12 volumio volumio[924]: info: Loading plugins from folder /data/plugins/ Mar 24 14:40:12 volumio volumio[924]: info: Loading plugin "system"... Mar 24 14:40:12 volumio volumio[924]: info: Loading plugin "appearance"... Mar 24 14:40:12 volumio go-librespot[864]: time="2026-03-24T14:40:12+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Mar 24 14:40:12 volumio volumio-remote-updater[584]: [2026-03-24 14:40:12] [connect] Successful connection Mar 24 14:40:13 volumio go-librespot[864]: time="2026-03-24T14:40:13+01:00" level=debug msg="completed keyexchange" Mar 24 14:40:13 volumio go-librespot[864]: time="2026-03-24T14:40:13+01:00" level=debug msg="completed challenge" Mar 24 14:40:13 volumio go-librespot[864]: time="2026-03-24T14:40:13+01:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 14:40:13 volumio go-librespot[864]: time="2026-03-24T14:40:13+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Mar 24 14:40:13 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 24 14:40:13 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 24 14:40:14 volumio volumio[924]: info: Loading plugin "network"... Mar 24 14:40:14 volumio volumio[924]: info: Refreshing Cached IP Addresses Mar 24 14:40:14 volumio volumio[924]: info: Loading plugin "services"... Mar 24 14:40:14 volumio volumio[924]: info: Loading plugin "volumio5onboarding"... Mar 24 14:40:15 volumio volumio[924]: info: Loading plugin "alsa_controller"... Mar 24 14:40:15 volumio sudo[964]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 24 14:40:15 volumio sudo[967]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Mar 24 14:40:15 volumio sudo[962]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Mar 24 14:40:15 volumio sudo[967]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 14:40:15 volumio sudo[962]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 14:40:15 volumio sudo[964]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 14:40:15 volumio sudo[964]: pam_unix(sudo:session): session closed for user root Mar 24 14:40:15 volumio sudo[962]: pam_unix(sudo:session): session closed for user root Mar 24 14:40:15 volumio volumio[924]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 24 14:40:15 volumio volumio[924]: info: Loading plugin "wizard"... Mar 24 14:40:15 volumio volumio[924]: info: Loading plugin "networkfs"... Mar 24 14:40:15 volumio volumio[924]: info: Starting Udev Watcher for removable devices Mar 24 14:40:15 volumio volumio[924]: info: Ignoring mount for partition: boot Mar 24 14:40:15 volumio volumio[924]: info: Ignoring mount for partition: volumio Mar 24 14:40:15 volumio volumio[924]: info: Ignoring mount for partition: volumio_data Mar 24 14:40:15 volumio volumio[924]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Mar 24 14:40:15 volumio volumio[924]: info: Loading plugin "volumio_command_line_client"... Mar 24 14:40:15 volumio volumio[924]: info: Loading plugin "upnp"... Mar 24 14:40:15 volumio volumio[924]: info: [1774359615364] Starting Upmpd Daemon Mar 24 14:40:15 volumio volumio[924]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Mar 24 14:40:15 volumio volumio[924]: info: Loading plugin "my_music"... Mar 24 14:40:15 volumio volumio[924]: info: Loading plugin "mpd"... Mar 24 14:40:15 volumio volumio[924]: info: Loading plugin "upnp_browser"... Mar 24 14:40:16 volumio sudo[967]: pam_unix(sudo:session): session closed for user root Mar 24 14:40:16 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Mar 24 14:40:16 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 24 14:40:16 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 24 14:40:16 volumio go-librespot[995]: go-librespot daemon starting... Mar 24 14:40:16 volumio go-librespot[996]: time="2026-03-24T14:40:16+01:00" level=info msg="running go-librespot 0.6.2" Mar 24 14:40:16 volumio go-librespot[996]: time="2026-03-24T14:40:16+01:00" level=debug msg="app state loaded" Mar 24 14:40:16 volumio go-librespot[996]: time="2026-03-24T14:40:16+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 24 14:40:17 volumio go-librespot[996]: time="2026-03-24T14:40:17+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Mar 24 14:40:17 volumio go-librespot[996]: time="2026-03-24T14:40:17+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Mar 24 14:40:17 volumio go-librespot[996]: time="2026-03-24T14:40:17+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Mar 24 14:40:17 volumio go-librespot[996]: time="2026-03-24T14:40:17+01:00" level=info msg="zeroconf server listening on port 43289" Mar 24 14:40:17 volumio go-librespot[996]: time="2026-03-24T14:40:17+01:00" level=debug msg="obtained new client token: AAC7KREzmQlFn3Wb9zrldXeJiQuB9wbQ5bhVfUphgOXihZvjSlyBHywO2BvnHaFCz1s6Vyj0kroKBtQY/6eZYDGhUUXy3Ci5t45V8Ntktm6P0lC4aolEG+b7VO3f1JhP4GTY7K2hyb6GmNixAN1zLno/qYCS/Jqyhqae+ovifeYp51n8+DJMx5piNaaBAFxq7rtFoZM33TnumYn9M0Q7LI4ZjtdjeeV0JNMgfmxjn5iOsHh5VXmUUomy9A==" Mar 24 14:40:17 volumio go-librespot[996]: time="2026-03-24T14:40:17+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Mar 24 14:40:17 volumio go-librespot[996]: time="2026-03-24T14:40:17+01:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: EOF" Mar 24 14:40:18 volumio volumio[924]: info: Starting UPNP Browser Mar 24 14:40:18 volumio volumio[924]: info: Loading plugin "alarm-clock"... Mar 24 14:40:18 volumio go-librespot[996]: time="2026-03-24T14:40:18+01:00" level=debug msg="connected to ap-gew4.spotify.com:443" Mar 24 14:40:18 volumio go-librespot[996]: time="2026-03-24T14:40:18+01:00" level=debug msg="completed keyexchange" Mar 24 14:40:18 volumio go-librespot[996]: time="2026-03-24T14:40:18+01:00" level=debug msg="completed challenge" Mar 24 14:40:18 volumio go-librespot[996]: time="2026-03-24T14:40:18+01:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 14:40:18 volumio volumio[924]: info: Loading plugin "airplay_emulation"... Mar 24 14:40:18 volumio volumio[924]: info: Starting Shairport Sync Mar 24 14:40:18 volumio volumio[924]: info: Loading plugin "last_100"... Mar 24 14:40:18 volumio volumio[924]: info: Loading plugin "webradio"... Mar 24 14:40:18 volumio volumio[924]: info: Loading plugin "i2s_dacs"... Mar 24 14:40:18 volumio volumio[924]: info: Loading plugin "volumiodiscovery"... Mar 24 14:40:18 volumio volumio[924]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Mar 24 14:40:18 volumio volumio[924]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 24 14:40:18 volumio volumio[924]: *** WARNING *** For more information see Mar 24 14:40:18 volumio volumio[924]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Mar 24 14:40:18 volumio volumio[924]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 24 14:40:18 volumio volumio[924]: *** WARNING *** For more information see Mar 24 14:40:18 volumio node[924]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Mar 24 14:40:18 volumio node[924]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 24 14:40:18 volumio node[924]: *** WARNING *** For more information see Mar 24 14:40:18 volumio node[924]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Mar 24 14:40:18 volumio node[924]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 24 14:40:18 volumio node[924]: *** WARNING *** For more information see Mar 24 14:40:18 volumio volumio[924]: info: Applying required configuration parameters for plugin volumiodiscovery Mar 24 14:40:18 volumio volumio[924]: info: Discovery: Started advertising with name: Volumio Mar 24 14:40:19 volumio volumio[924]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Mar 24 14:40:19 volumio volumio[924]: info: Loading plugin "spop"... Mar 24 14:40:19 volumio go-librespot[996]: time="2026-03-24T14:40:19+01:00" level=warning msg="failed to connect to AP ap-gew4.spotify.com:80, retrying with a different AP" error="dial tcp 34.158.1.133:80: connect: connection refused" Mar 24 14:40:19 volumio go-librespot[996]: time="2026-03-24T14:40:19+01:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Mar 24 14:40:19 volumio go-librespot[996]: time="2026-03-24T14:40:19+01:00" level=debug msg="completed keyexchange" Mar 24 14:40:19 volumio go-librespot[996]: time="2026-03-24T14:40:19+01:00" level=debug msg="completed challenge" Mar 24 14:40:19 volumio go-librespot[996]: time="2026-03-24T14:40:19+01:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 14:40:20 volumio go-librespot[996]: time="2026-03-24T14:40:20+01:00" level=debug msg="connected to ap-gue1.spotify.com:443" Mar 24 14:40:20 volumio go-librespot[996]: time="2026-03-24T14:40:20+01:00" level=debug msg="completed keyexchange" Mar 24 14:40:20 volumio go-librespot[996]: time="2026-03-24T14:40:20+01:00" level=debug msg="completed challenge" Mar 24 14:40:20 volumio go-librespot[996]: time="2026-03-24T14:40:20+01:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 14:40:20 volumio volumio5-onboarding[22591]: time=2026-03-24T14:40:20.608+01:00 level=WARN msg="reconnection attempt failed" component=volumio/socket error="read tcp 127.0.0.1:52222->127.0.0.1:3000: i/o timeout" Mar 24 14:40:20 volumio volumio[924]: info: Loading plugin "outputs"... Mar 24 14:40:20 volumio volumio[924]: info: Loading plugin "albumart"... Mar 24 14:40:20 volumio volumio[924]: info: Plugin example_plugin is not enabled Mar 24 14:40:20 volumio volumio[924]: info: Loading plugin "inputs"... Mar 24 14:40:20 volumio volumio[924]: info: Loading plugin "updater_comm"... Mar 24 14:40:21 volumio volumio[924]: info: Plugin mpdemulation is not enabled Mar 24 14:40:21 volumio volumio[924]: info: Loading plugin "rest_api"... Mar 24 14:40:21 volumio volumio[924]: info: Loading plugin "websocket"... Mar 24 14:40:21 volumio volumio[924]: info: Starting Socket.io Server version 1.7.4 Mar 24 14:40:21 volumio volumio[924]: info: Loading i18n strings for locale pl Mar 24 14:40:21 volumio go-librespot[996]: time="2026-03-24T14:40:21+01:00" level=debug msg="connected to ap-gew1.spotify.com:80" Mar 24 14:40:21 volumio volumio[924]: Updating browse sources language Mar 24 14:40:21 volumio volumio[924]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 24 14:40:21 volumio go-librespot[996]: time="2026-03-24T14:40:21+01:00" level=debug msg="completed keyexchange" Mar 24 14:40:21 volumio go-librespot[996]: time="2026-03-24T14:40:21+01:00" level=debug msg="completed challenge" Mar 24 14:40:21 volumio go-librespot[996]: time="2026-03-24T14:40:21+01:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 14:40:21 volumio volumio[924]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 24 14:40:21 volumio volumio[924]: info: CoreCommandRouter::initPlayerControls Mar 24 14:40:21 volumio volumio[924]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 14:40:21 volumio volumio[924]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 14:40:21 volumio volumio[924]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 14:40:21 volumio volumio[924]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 14:40:21 volumio volumio[924]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 14:40:21 volumio volumio[924]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 14:40:21 volumio volumio[924]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 14:40:21 volumio volumio[924]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 14:40:21 volumio volumio[924]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 24 14:40:21 volumio volumio[924]: Express server listening on port 3000 Mar 24 14:40:21 volumio volumio[924]: [Metrics] WebUI: 10s 947.00ms Mar 24 14:40:21 volumio volumio[924]: info: CoreStateMachine::resetVolumioState Mar 24 14:40:21 volumio volumio[924]: info: CoreStateMachine::getcurrentVolume Mar 24 14:40:21 volumio volumio[924]: info: CoreCommandRouter::volumioRetrievevolume Mar 24 14:40:21 volumio volumio[1007]: Forking 3 albumart workers Mar 24 14:40:21 volumio volumio[924]: info: Volumio Network Manager: Network status updated: 2 Mar 24 14:40:21 volumio volumio[924]: info: CoreStateMachine::pushState Mar 24 14:40:21 volumio volumio[924]: info: CorePlayQueue::getTrack 0 Mar 24 14:40:21 volumio volumio[924]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 24 14:40:21 volumio volumio[924]: info: CoreCommandRouter::volumioPushState Mar 24 14:40:21 volumio volumio[924]: info: CoreStateMachine::updateTrackBlock Mar 24 14:40:21 volumio volumio[924]: info: CorePlayQueue::getTrackBlock Mar 24 14:40:21 volumio volumio[924]: info: CoreCommandRouter::volumioRetrievevolume Mar 24 14:40:21 volumio go-librespot[996]: time="2026-03-24T14:40:21+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Mar 24 14:40:21 volumio volumio[924]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 24 14:40:21 volumio volumio[924]: info: Reloading queue from file Mar 24 14:40:21 volumio volumio[924]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 1 Mar 24 14:40:21 volumio volumio[924]: info: CoreStateMachine::setRepeat null single undefined Mar 24 14:40:21 volumio volumio[924]: info: CoreStateMachine::pushState Mar 24 14:40:21 volumio volumio[924]: info: CorePlayQueue::getTrack 0 Mar 24 14:40:21 volumio volumio[924]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 24 14:40:21 volumio go-librespot[996]: time="2026-03-24T14:40:21+01:00" level=debug msg="completed keyexchange" Mar 24 14:40:21 volumio go-librespot[996]: time="2026-03-24T14:40:21+01:00" level=debug msg="completed challenge" Mar 24 14:40:21 volumio volumio[924]: info: CoreCommandRouter::volumioPushState Mar 24 14:40:21 volumio volumio[924]: info: CoreStateMachine::setRandom null Mar 24 14:40:21 volumio volumio[924]: info: CoreStateMachine::pushState Mar 24 14:40:21 volumio volumio[924]: info: CorePlayQueue::getTrack 0 Mar 24 14:40:21 volumio volumio[924]: info: CoreCommandRouter::volumioPushState Mar 24 14:40:21 volumio volumio[924]: info: Setting Device type: Raspberry PI Mar 24 14:40:21 volumio go-librespot[996]: time="2026-03-24T14:40:21+01:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 14:40:21 volumio go-librespot[996]: time="2026-03-24T14:40:21+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Mar 24 14:40:21 volumio volumio[924]: info: Completed loading Core Plugins Mar 24 14:40:21 volumio volumio[924]: info: Preparing to generate the ALSA configuration file Mar 24 14:40:21 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 24 14:40:21 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 24 14:40:21 volumio volumio[924]: info: CoreStateMachine::pushState Mar 24 14:40:21 volumio volumio[924]: info: CorePlayQueue::getTrack 0 Mar 24 14:40:21 volumio volumio[924]: info: CoreCommandRouter::volumioPushState Mar 24 14:40:21 volumio volumio[924]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Mar 24 14:40:21 volumio volumio[924]: info: USB Boot Capable - System SBC Revision found in cpuinfo: 902120 Mar 24 14:40:21 volumio volumio[924]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Mar 24 14:40:22 volumio volumio[924]: info: The plugin alsa_controller has an ALSA contribution file softvolume.postVolume.conf Mar 24 14:40:22 volumio volumio[924]: info: Reading ALSA contributions from plugins. Mar 24 14:40:22 volumio volumio[924]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 1 Mar 24 14:40:22 volumio volumio[924]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 1 Mar 24 14:40:22 volumio volumio[924]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 1 Mar 24 14:40:22 volumio volumio[924]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 1 Mar 24 14:40:22 volumio volumio[924]: info: Received Get System Info Mar 24 14:40:22 volumio volumio[924]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 24 14:40:22 volumio volumio[924]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 24 14:40:22 volumio volumio[924]: info: Discovery: Getting this device information Mar 24 14:40:22 volumio volumio[924]: info: CoreCommandRouter::volumioGetState Mar 24 14:40:22 volumio volumio[924]: info: CorePlayQueue::getTrack 0 Mar 24 14:40:22 volumio volumio[924]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 24 14:40:22 volumio volumio[924]: info: Discovery: adding 2456885c-5bc0-4391-bb8e-47f9f2a2e3dd Mar 24 14:40:22 volumio volumio[924]: info: Discovery: Found device Volumio Mar 24 14:40:22 volumio volumio[924]: info: CoreCommandRouter::volumioGetState Mar 24 14:40:22 volumio volumio[924]: info: CorePlayQueue::getTrack 0 Mar 24 14:40:22 volumio volumio[924]: info: Discovery: this is already registered, 2456885c-5bc0-4391-bb8e-47f9f2a2e3dd Mar 24 14:40:22 volumio volumio[924]: info: Discovery: Found device Volumio Mar 24 14:40:22 volumio volumio[924]: info: CoreCommandRouter::volumioGetState Mar 24 14:40:22 volumio volumio[924]: info: CorePlayQueue::getTrack 0 Mar 24 14:40:22 volumio volumio[924]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Mar 24 14:40:22 volumio volumio[924]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Mar 24 14:40:22 volumio volumio[924]: info: Asound.conf file unchanged, so no further update is needed Mar 24 14:40:22 volumio volumio[924]: info: Output device has changed, restarting MPD Mar 24 14:40:22 volumio volumio[924]: info: Output device has changed, restarting Shairport Sync Mar 24 14:40:22 volumio volumio[924]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 14:40:22 volumio volumio[924]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 24 14:40:22 volumio volumio[924]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 24 14:40:22 volumio volumio[924]: info: ___________ START PLUGINS ___________ Mar 24 14:40:22 volumio sudo[1079]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Mar 24 14:40:22 volumio sudo[1076]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Mar 24 14:40:22 volumio sudo[1076]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 14:40:22 volumio sudo[1079]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 14:40:22 volumio volumio[924]: info: ControllerMpd::onStart: Initializing MPD Mar 24 14:40:22 volumio volumio[924]: info: Creating MPD Configuration file Mar 24 14:40:22 volumio sudo[1076]: pam_unix(sudo:session): session closed for user root Mar 24 14:40:22 volumio sudo[1084]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumio5-onboarding.service Mar 24 14:40:22 volumio sudo[1084]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 14:40:22 volumio sudo[1088]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Mar 24 14:40:22 volumio volumio[924]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 24 14:40:22 volumio volumio[924]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 24 14:40:22 volumio volumio[924]: info: [1774359622422] CoreMusicLibrary::Adding element Serwery Mediów Mar 24 14:40:22 volumio volumio[924]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 24 14:40:22 volumio sudo[1088]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 14:40:22 volumio sudo[1088]: pam_unix(sudo:session): session closed for user root Mar 24 14:40:22 volumio volumio[924]: info: UPNP Browser: Client initialized successfully Mar 24 14:40:22 volumio sudo[1090]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Mar 24 14:40:22 volumio sudo[1090]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 14:40:22 volumio volumio[924]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 14:40:22 volumio volumio[924]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 24 14:40:22 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Mar 24 14:40:22 volumio volumio[924]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 24 14:40:22 volumio volumio[924]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 14:40:22 volumio volumio[924]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 24 14:40:22 volumio volumio[924]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 24 14:40:22 volumio volumio[924]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 24 14:40:22 volumio volumio[924]: info: [1774359622630] CoreMusicLibrary::Adding element Last_100 Mar 24 14:40:22 volumio volumio[924]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 24 14:40:22 volumio volumio[924]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 24 14:40:22 volumio volumio[924]: info: [1774359622644] CoreMusicLibrary::Adding element Webradio Mar 24 14:40:22 volumio volumio[924]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 24 14:40:22 volumio volumio[924]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 24 14:40:22 volumio volumio[924]: info: Initializing BBC Radios Mar 24 14:40:22 volumio sudo[1084]: pam_unix(sudo:session): session closed for user root Mar 24 14:40:22 volumio volumio[924]: /usr/bin/md5sum: /sys/class/net/eth0/address: No such file or directory Mar 24 14:40:22 volumio volumio[924]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 24 14:40:22 volumio volumio[924]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 24 14:40:22 volumio volumio[924]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 24 14:40:22 volumio volumio[924]: info: Creating Spotify config file Mar 24 14:40:22 volumio volumio[924]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 14:40:23 volumio volumio[924]: info: Volumio Calling Home Mar 24 14:40:24 volumio volumio[1029]: Starting albumart workers Mar 24 14:40:24 volumio volumio[1027]: Starting albumart workers Mar 24 14:40:24 volumio volumio[1028]: Starting albumart workers Mar 24 14:40:24 volumio volumio[924]: info: MPD Permissions set Mar 24 14:40:24 volumio volumio[924]: info: MPD Permissions set Mar 24 14:40:24 volumio volumio[924]: info: Spotify config file written Mar 24 14:40:24 volumio sudo[1125]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 24 14:40:24 volumio sudo[1125]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 14:40:24 volumio volumio[924]: 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 24 14:40:24 volumio volumio[924]: info: No need to fix Spotify hosts Mar 24 14:40:24 volumio volumio[924]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 14:40:24 volumio volumio[924]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 14:40:24 volumio volumio[924]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 14:40:24 volumio volumio[924]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 14:40:24 volumio volumio[924]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 14:40:24 volumio volumio[924]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 14:40:24 volumio volumio[924]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 14:40:24 volumio volumio[924]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 14:40:24 volumio volumio[924]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 24 14:40:24 volumio volumio[924]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 14:40:24 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 24 14:40:24 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 24 14:40:24 volumio sudo[1125]: pam_unix(sudo:session): session closed for user root Mar 24 14:40:24 volumio volumio[924]: info: Volumio called home Mar 24 14:40:24 volumio volumio[924]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 14:40:24 volumio volumio[924]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 14:40:24 volumio volumio[924]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 14:40:24 volumio volumio[924]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 14:40:24 volumio volumio[924]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 14:40:24 volumio volumio[924]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 14:40:24 volumio volumio[924]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 14:40:24 volumio volumio[924]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 14:40:24 volumio go-librespot[1133]: go-librespot daemon starting... Mar 24 14:40:24 volumio volumio[924]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 24 14:40:24 volumio volumio[924]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 14:40:25 volumio volumio[924]: info: Starting Shairport Sync Mar 24 14:40:25 volumio volumio[924]: info: Starting Shairport Sync Mar 24 14:40:25 volumio volumio[924]: info: Starting Shairport Sync Mar 24 14:40:25 volumio volumio[924]: info: An error occurred while refreshing Spotify Token Error: Bad Request Mar 24 14:40:25 volumio sudo[1146]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Mar 24 14:40:25 volumio sudo[1146]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 14:40:25 volumio sudo[1148]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Mar 24 14:40:25 volumio sudo[1148]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 14:40:25 volumio sudo[1152]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Mar 24 14:40:25 volumio sudo[1152]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 14:40:25 volumio volumio[924]: info: CoreCommandRouter::volumioGetState Mar 24 14:40:25 volumio volumio[924]: info: CorePlayQueue::getTrack 0 Mar 24 14:40:25 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Mar 24 14:40:25 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Mar 24 14:40:25 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Mar 24 14:40:25 volumio systemd[1]: shairport-sync.service: Consumed 2.305s CPU time. Mar 24 14:40:25 volumio sudo[1174]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Mar 24 14:40:25 volumio sudo[1174]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 14:40:25 volumio sudo[1175]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 24 14:40:25 volumio volumio-remote-updater[584]: [2026-03-24 14:40:25] [connect] Successful connection Mar 24 14:40:25 volumio sudo[1175]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 14:40:25 volumio sudo[1175]: pam_unix(sudo:session): session closed for user root Mar 24 14:40:25 volumio volumio-remote-updater[584]: [2026-03-24 14:40:25] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1774359625 101 Mar 24 14:40:25 volumio volumio[924]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 3 Transport: websocket Total Clients: 3 Mar 24 14:40:25 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Mar 24 14:40:25 volumio volumio[924]: info: Shairport-Sync Started Mar 24 14:40:25 volumio volumio[924]: Error adding Membership: Error: addMembership EINVAL Mar 24 14:40:25 volumio volumio[924]: info: Shairport-Sync Started Mar 24 14:40:25 volumio sudo[1146]: pam_unix(sudo:session): session closed for user root Mar 24 14:40:25 volumio sudo[1152]: pam_unix(sudo:session): session closed for user root Mar 24 14:40:25 volumio sudo[1148]: pam_unix(sudo:session): session closed for user root Mar 24 14:40:25 volumio volumio[924]: info: Shairport-Sync Started Mar 24 14:40:25 volumio sudo[1181]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Mar 24 14:40:25 volumio sudo[1181]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 14:40:25 volumio sudo[1181]: pam_unix(sudo:session): session closed for user root Mar 24 14:40:25 volumio volumio[924]: info: Upmpdcli Daemon Started Mar 24 14:40:25 volumio go-librespot[1139]: time="2026-03-24T14:40:25+01:00" level=info msg="running go-librespot 0.6.2" Mar 24 14:40:25 volumio go-librespot[1139]: time="2026-03-24T14:40:25+01:00" level=debug msg="app state loaded" Mar 24 14:40:26 volumio sudo[1174]: pam_unix(sudo:session): session closed for user root Mar 24 14:40:26 volumio go-librespot[1139]: time="2026-03-24T14:40:26+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 24 14:40:26 volumio go-librespot[1139]: time="2026-03-24T14:40:26+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Mar 24 14:40:26 volumio go-librespot[1139]: time="2026-03-24T14:40:26+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Mar 24 14:40:26 volumio go-librespot[1139]: time="2026-03-24T14:40:26+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Mar 24 14:40:26 volumio go-librespot[1139]: time="2026-03-24T14:40:26+01:00" level=info msg="zeroconf server listening on port 42063" Mar 24 14:40:26 volumio go-librespot[1139]: time="2026-03-24T14:40:26+01:00" level=debug msg="obtained new client token: AADRpkMOVzS4L642NT38Iq4LAKSzfaEzVV2SQ1p/NxAdQnkS5RH2tb6hGvvNHLnH0sfB2T9ku6xrw56KA1xllBoeGtNk4w9WFh8ugv0pshuHdQ46lRO5XMiKwZMe+NejUo7gB/b3vwDoITB0EhKb+QpRxdIrj6NU3WBDHlJUQMO4eEh6NTIy3WgDDQOIcD8i+R/vTOMGM/HRxelnLGQg3ncc7N2HSWVIFNLMwYbRkFnTgBpGVqq1ZyCvqw==" Mar 24 14:40:26 volumio go-librespot[1139]: time="2026-03-24T14:40:26+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Mar 24 14:40:27 volumio go-librespot[1139]: time="2026-03-24T14:40:27+01:00" level=debug msg="completed keyexchange" Mar 24 14:40:27 volumio go-librespot[1139]: time="2026-03-24T14:40:27+01:00" level=debug msg="completed challenge" Mar 24 14:40:27 volumio go-librespot[1139]: time="2026-03-24T14:40:27+01:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 14:40:27 volumio go-librespot[1139]: time="2026-03-24T14:40:27+01:00" level=debug msg="connected to ap-gew4.spotify.com:443" Mar 24 14:40:27 volumio go-librespot[1139]: time="2026-03-24T14:40:27+01:00" level=debug msg="completed keyexchange" Mar 24 14:40:27 volumio go-librespot[1139]: time="2026-03-24T14:40:27+01:00" level=debug msg="completed challenge" Mar 24 14:40:27 volumio go-librespot[1139]: time="2026-03-24T14:40:27+01:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 14:40:28 volumio volumio[924]: info: go-librespot daemon successfully initialized Mar 24 14:40:29 volumio go-librespot[1139]: time="2026-03-24T14:40:28+01:00" level=debug msg="connected to ap-gew4.spotify.com:80" Mar 24 14:40:29 volumio go-librespot[1139]: time="2026-03-24T14:40:28+01:00" level=debug msg="completed keyexchange" Mar 24 14:40:29 volumio go-librespot[1139]: time="2026-03-24T14:40:28+01:00" level=debug msg="completed challenge" Mar 24 14:40:29 volumio go-librespot[1139]: time="2026-03-24T14:40:28+01:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 14:40:29 volumio go-librespot[1139]: time="2026-03-24T14:40:29+01:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Mar 24 14:40:29 volumio go-librespot[1139]: time="2026-03-24T14:40:29+01:00" level=debug msg="completed keyexchange" Mar 24 14:40:29 volumio go-librespot[1139]: time="2026-03-24T14:40:29+01:00" level=debug msg="completed challenge" Mar 24 14:40:29 volumio go-librespot[1139]: time="2026-03-24T14:40:29+01:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 14:40:30 volumio go-librespot[1139]: time="2026-03-24T14:40:30+01:00" level=debug msg="connected to ap-gue1.spotify.com:443" Mar 24 14:40:30 volumio go-librespot[1139]: time="2026-03-24T14:40:30+01:00" level=debug msg="completed keyexchange" Mar 24 14:40:30 volumio go-librespot[1139]: time="2026-03-24T14:40:30+01:00" level=debug msg="completed challenge" Mar 24 14:40:30 volumio go-librespot[1139]: time="2026-03-24T14:40:30+01:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 14:40:30 volumio go-librespot[1139]: time="2026-03-24T14:40:30+01:00" level=debug msg="connected to ap-gew1.spotify.com:80" Mar 24 14:40:31 volumio go-librespot[1139]: time="2026-03-24T14:40:30+01:00" level=debug msg="completed keyexchange" Mar 24 14:40:31 volumio go-librespot[1139]: time="2026-03-24T14:40:30+01:00" level=debug msg="completed challenge" Mar 24 14:40:31 volumio go-librespot[1139]: time="2026-03-24T14:40:31+01:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 14:40:31 volumio go-librespot[1139]: time="2026-03-24T14:40:31+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Mar 24 14:40:31 volumio volumio[924]: info: Initializing connection to go-librespot Websocket Mar 24 14:40:31 volumio volumio[924]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 24 14:40:31 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 24 14:40:31 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 24 14:40:32 volumio systemd[1]: mpd.service: Deactivated successfully. Mar 24 14:40:32 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Mar 24 14:40:32 volumio systemd[1]: mpd.service: Consumed 8.055s CPU time. Mar 24 14:40:32 volumio systemd[1]: mpd.socket: Deactivated successfully. Mar 24 14:40:32 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Mar 24 14:40:32 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Mar 24 14:40:32 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Mar 24 14:40:32 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Mar 24 14:40:33 volumio sudo[1221]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Mar 24 14:40:33 volumio sudo[1221]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Mar 24 14:40:33 volumio sudo[1221]: pam_unix(sudo:session): session closed for user root Mar 24 14:40:34 volumio volumio[924]: info: Initializing connection to go-librespot Websocket Mar 24 14:40:34 volumio volumio[924]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 24 14:40:34 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 4. Mar 24 14:40:34 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 24 14:40:34 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 24 14:40:34 volumio go-librespot[1224]: go-librespot daemon starting... Mar 24 14:40:34 volumio go-librespot[1225]: time="2026-03-24T14:40:34+01:00" level=info msg="running go-librespot 0.6.2" Mar 24 14:40:34 volumio go-librespot[1225]: time="2026-03-24T14:40:34+01:00" level=debug msg="app state loaded" Mar 24 14:40:34 volumio go-librespot[1225]: time="2026-03-24T14:40:34+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 24 14:40:35 volumio go-librespot[1225]: time="2026-03-24T14:40:35+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Mar 24 14:40:35 volumio go-librespot[1225]: time="2026-03-24T14:40:35+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Mar 24 14:40:35 volumio go-librespot[1225]: time="2026-03-24T14:40:35+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Mar 24 14:40:35 volumio go-librespot[1225]: time="2026-03-24T14:40:35+01:00" level=info msg="zeroconf server listening on port 36599" Mar 24 14:40:35 volumio go-librespot[1225]: time="2026-03-24T14:40:35+01:00" level=debug msg="obtained new client token: AAD8D02q8US/rE4qITOMpl17BJKHE9Eo5X6DxLmFEKkwGDwMEeMvVOvbgM5F9yx7/5xtbufYKL2/e9bFGUROqE2Peoj0g3FM3lEax9Px6d8kZ9xedXpAcoffyle8/U/3x2x/walTOjEwfp9qSnVCIDjhZKYoRHsrW+n8BlQhxlnI55vuCIQBXhhksvFIV8uQPsgXW9cwWi4s/Y2d79iFoa/F8u02XMgybj935/6JvWhmpV7canFKqrF4nw==" Mar 24 14:40:35 volumio go-librespot[1225]: time="2026-03-24T14:40:35+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Mar 24 14:40:35 volumio go-librespot[1225]: time="2026-03-24T14:40:35+01:00" level=debug msg="completed keyexchange" Mar 24 14:40:35 volumio go-librespot[1225]: time="2026-03-24T14:40:35+01:00" level=debug msg="completed challenge" Mar 24 14:40:35 volumio go-librespot[1225]: time="2026-03-24T14:40:35+01:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 14:40:36 volumio go-librespot[1225]: time="2026-03-24T14:40:36+01:00" level=debug msg="connected to ap-gew4.spotify.com:443" Mar 24 14:40:36 volumio go-librespot[1225]: time="2026-03-24T14:40:36+01:00" level=debug msg="completed keyexchange" Mar 24 14:40:36 volumio go-librespot[1225]: time="2026-03-24T14:40:36+01:00" level=debug msg="completed challenge" Mar 24 14:40:36 volumio go-librespot[1225]: time="2026-03-24T14:40:36+01:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 14:40:36 volumio go-librespot[1225]: time="2026-03-24T14:40:36+01:00" level=debug msg="connected to ap-gew4.spotify.com:80" Mar 24 14:40:36 volumio go-librespot[1225]: time="2026-03-24T14:40:36+01:00" level=debug msg="completed keyexchange" Mar 24 14:40:36 volumio go-librespot[1225]: time="2026-03-24T14:40:36+01:00" level=debug msg="completed challenge" Mar 24 14:40:36 volumio go-librespot[1225]: time="2026-03-24T14:40:36+01:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 14:40:37 volumio volumio[924]: info: Initializing connection to go-librespot Websocket Mar 24 14:40:37 volumio go-librespot[1225]: time="2026-03-24T14:40:37+01:00" level=debug msg="new websocket client" Mar 24 14:40:37 volumio volumio[924]: info: Connection to go-librespot Websocket established Mar 24 14:40:37 volumio go-librespot[1225]: time="2026-03-24T14:40:37+01:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Mar 24 14:40:37 volumio go-librespot[1225]: time="2026-03-24T14:40:37+01:00" level=debug msg="completed keyexchange" Mar 24 14:40:37 volumio go-librespot[1225]: time="2026-03-24T14:40:37+01:00" level=debug msg="completed challenge" Mar 24 14:40:37 volumio go-librespot[1225]: time="2026-03-24T14:40:37+01:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 14:40:38 volumio go-librespot[1225]: time="2026-03-24T14:40:38+01:00" level=debug msg="connected to ap-gue1.spotify.com:443" Mar 24 14:40:38 volumio go-librespot[1225]: time="2026-03-24T14:40:38+01:00" level=debug msg="completed keyexchange" Mar 24 14:40:38 volumio go-librespot[1225]: time="2026-03-24T14:40:38+01:00" level=debug msg="completed challenge" Mar 24 14:40:38 volumio go-librespot[1225]: time="2026-03-24T14:40:38+01:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 14:40:39 volumio go-librespot[1225]: time="2026-03-24T14:40:39+01:00" level=debug msg="connected to ap-gew1.spotify.com:80" Mar 24 14:40:39 volumio go-librespot[1225]: time="2026-03-24T14:40:39+01:00" level=debug msg="completed keyexchange" Mar 24 14:40:39 volumio go-librespot[1225]: time="2026-03-24T14:40:39+01:00" level=debug msg="completed challenge" Mar 24 14:40:39 volumio go-librespot[1225]: time="2026-03-24T14:40:39+01:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 14:40:39 volumio go-librespot[1225]: time="2026-03-24T14:40:39+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Mar 24 14:40:39 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 24 14:40:39 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 24 14:40:39 volumio volumio[924]: info: Connection to go-librespot Websocket closed Mar 24 14:40:40 volumio volumio[924]: info: Getting Spotify volume Mar 24 14:40:40 volumio volumio[924]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 24 14:40:40 volumio volumio[924]: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 24 14:40:40 volumio volumio[924]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Mar 24 14:40:40 volumio volumio[924]: errno: -111, Mar 24 14:40:40 volumio volumio[924]: code: 'ECONNREFUSED', Mar 24 14:40:40 volumio volumio[924]: syscall: 'connect', Mar 24 14:40:40 volumio volumio[924]: address: '127.0.0.1', Mar 24 14:40:40 volumio volumio[924]: port: 9879, Mar 24 14:40:40 volumio volumio[924]: response: undefined Mar 24 14:40:40 volumio volumio[924]: } Mar 24 14:40:40 volumio volumio[924]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 24 14:40:42 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 5. Mar 24 14:40:42 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 24 14:40:42 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 24 14:40:43 volumio go-librespot[1251]: go-librespot daemon starting... Mar 24 14:40:43 volumio mpd[1223]: 2026-03-24T14:40:43 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Mar 24 14:40:44 volumio systemd[1]: Started mpd.service - Music Player Daemon. Mar 24 14:40:44 volumio go-librespot[1253]: time="2026-03-24T14:40:44+01:00" level=info msg="running go-librespot 0.6.2" Mar 24 14:40:44 volumio go-librespot[1253]: time="2026-03-24T14:40:44+01:00" level=debug msg="app state loaded" Mar 24 14:40:45 volumio sudo[1090]: pam_unix(sudo:session): session closed for user root Mar 24 14:40:45 volumio sudo[1079]: pam_unix(sudo:session): session closed for user root Mar 24 14:40:45 volumio go-librespot[1253]: time="2026-03-24T14:40:45+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 24 14:40:46 volumio go-librespot[1253]: time="2026-03-24T14:40:46+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Mar 24 14:40:46 volumio go-librespot[1253]: time="2026-03-24T14:40:46+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Mar 24 14:40:46 volumio go-librespot[1253]: time="2026-03-24T14:40:46+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Mar 24 14:40:46 volumio go-librespot[1253]: time="2026-03-24T14:40:46+01:00" level=info msg="zeroconf server listening on port 43925" Mar 24 14:40:46 volumio go-librespot[1253]: time="2026-03-24T14:40:46+01:00" level=debug msg="obtained new client token: AADHWLjWYd+piAfhitpeNbwHKxuo56f1KMr6cOos9DqGE6/7kqJ9XW0rcHAtDTVdQMqtKG3KSdxBrGwFlvFRV616yONG6TeAJrkdcPdb9TAj11lu4RMh9F0VWX7RFInAchEowDO63sz2cHQkBJCKpHPewkBR/Txdp3MWKqO+ymhuq2nZ1qp5TxU+yOnx1tmmg9G+EyN+enumHzjYj/Q3FYi7Sb6ektkjfZWMNdwGn9Nnm+ZmM53tG3NpDw==" Mar 24 14:40:46 volumio go-librespot[1253]: time="2026-03-24T14:40:46+01:00" level=warning msg="failed to connect to AP ap-gew4.spotify.com:4070, retrying with a different AP" error="dial tcp 34.158.1.133:4070: connect: connection refused" Mar 24 14:40:47 volumio go-librespot[1253]: time="2026-03-24T14:40:46+01:00" level=debug msg="connected to ap-gew4.spotify.com:443" Mar 24 14:40:47 volumio go-librespot[1253]: time="2026-03-24T14:40:47+01:00" level=debug msg="completed keyexchange" Mar 24 14:40:47 volumio go-librespot[1253]: time="2026-03-24T14:40:47+01:00" level=debug msg="completed challenge" Mar 24 14:40:47 volumio go-librespot[1253]: time="2026-03-24T14:40:47+01:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 14:40:47 volumio go-librespot[1253]: time="2026-03-24T14:40:47+01:00" level=debug msg="connected to ap-gew4.spotify.com:80" Mar 24 14:40:47 volumio go-librespot[1253]: time="2026-03-24T14:40:47+01:00" level=debug msg="completed keyexchange" Mar 24 14:40:47 volumio go-librespot[1253]: time="2026-03-24T14:40:47+01:00" level=debug msg="completed challenge" Mar 24 14:40:47 volumio go-librespot[1253]: time="2026-03-24T14:40:47+01:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 14:40:48 volumio go-librespot[1253]: time="2026-03-24T14:40:48+01:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Mar 24 14:40:48 volumio go-librespot[1253]: time="2026-03-24T14:40:48+01:00" level=debug msg="completed keyexchange" Mar 24 14:40:48 volumio go-librespot[1253]: time="2026-03-24T14:40:48+01:00" level=debug msg="completed challenge" Mar 24 14:40:48 volumio go-librespot[1253]: time="2026-03-24T14:40:48+01:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 14:40:49 volumio go-librespot[1253]: time="2026-03-24T14:40:49+01:00" level=debug msg="connected to ap-gue1.spotify.com:443" Mar 24 14:40:49 volumio go-librespot[1253]: time="2026-03-24T14:40:49+01:00" level=debug msg="completed keyexchange" Mar 24 14:40:49 volumio go-librespot[1253]: time="2026-03-24T14:40:49+01:00" level=debug msg="completed challenge" Mar 24 14:40:49 volumio go-librespot[1253]: time="2026-03-24T14:40:49+01:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 14:40:50 volumio sudo[1291]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-03-24 14:39' Mar 24 14:40:50 volumio sudo[1291]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 14:40:50 volumio go-librespot[1253]: time="2026-03-24T14:40:50+01:00" level=debug msg="connected to ap-gew1.spotify.com:80" Mar 24 14:40:50 volumio go-librespot[1253]: time="2026-03-24T14:40:50+01:00" level=debug msg="completed keyexchange" Mar 24 14:40:50 volumio go-librespot[1253]: time="2026-03-24T14:40:50+01:00" level=debug msg="completed challenge" Mar 24 14:40:50 volumio go-librespot[1253]: time="2026-03-24T14:40:50+01:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " 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="a78d359cf1dc63ac74e9d151015afd30d31a709a" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="c1ffe93b2136013fc1b5903a4ed7e3f34e0a7bec" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Thu Feb 5 14:07:07 UTC 2026" VOLUMIO_VERSION="4.096" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="5e37060f9823263a753eb5e84030104f"