Jan 10 19:10:00 volumio go-librespot[27028]: time="2026-01-10T19:10:00-06:00" level=info msg="running go-librespot 0.4.0" Jan 10 19:10:00 volumio go-librespot[27028]: time="2026-01-10T19:10:00-06:00" level=debug msg="app state loaded" Jan 10 19:10:00 volumio go-librespot[27028]: time="2026-01-10T19:10:00-06:00" level=debug msg="stored credentials not found" Jan 10 19:10:00 volumio go-librespot[27028]: time="2026-01-10T19:10:00-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 10 19:10:00 volumio volumio[26873]: info: Plugin calmradio is not enabled Jan 10 19:10:00 volumio volumio[26873]: info: Loading plugin "soundcloud"... Jan 10 19:10:00 volumio go-librespot[27028]: time="2026-01-10T19:10:00-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 10 19:10:00 volumio go-librespot[27028]: time="2026-01-10T19:10:00-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 10 19:10:00 volumio go-librespot[27028]: time="2026-01-10T19:10:00-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 10 19:10:00 volumio go-librespot[27028]: time="2026-01-10T19:10:00-06:00" level=info msg="zeroconf server listening on port 44011" Jan 10 19:10:00 volumio go-librespot[27028]: time="2026-01-10T19:10:00-06:00" level=debug msg="obtained new client token: AACkZFuzQVuOvtZpogMJ7oi7Huap7NzAmS8qcDLNC51+9LYoH1p5YAbjC5Tc0WDABcTXT5WywOAdGO48wHh8NtGI5Pm69O2nJkJ/l81o9zUV4R+kowo6d3PUTyTFphRSap9cqyTohpjhTlGDw80Fvl/qsw03gspZiKuVybHXykGZlZE8gb6X/1Hr1j4fl3DVMzJ9arXSx3Q3SBNAq9m+p2aK2+YFjVOFekDiDCYtkstk6sDaKjbXQ853lw==" Jan 10 19:10:00 volumio go-librespot[27028]: time="2026-01-10T19:10:00-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 10 19:10:00 volumio go-librespot[27028]: time="2026-01-10T19:10:00-06:00" level=debug msg="completed keyexchange" Jan 10 19:10:00 volumio go-librespot[27028]: time="2026-01-10T19:10:00-06:00" level=debug msg="completed challenge" Jan 10 19:10:00 volumio go-librespot[27028]: time="2026-01-10T19:10:00-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Jan 10 19:10:00 volumio volumio[26873]: info: Loading plugin "spop"... Jan 10 19:10:00 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 10 19:10:00 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 10 19:10:00 volumio kernel: hwmon hwmon1: Voltage normalised Jan 10 19:10:01 volumio volumio[26873]: info: Loading plugin "squeezelite_mc"... Jan 10 19:10:02 volumio volumio[26873]: info: Loading plugin "youtube2"... Jan 10 19:10:02 volumio kernel: hwmon hwmon1: Undervoltage detected! Jan 10 19:10:03 volumio volumio[26873]: info: Loading plugin "ytcr"... Jan 10 19:10:03 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.105.134 Jan 10 19:10:03 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Jan 10 19:10:03 volumio avahi-daemon[664]: Registering new address record for 169.254.105.134 on eth0.IPv4. Jan 10 19:10:03 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 19:10:03 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 10 19:10:03 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 19:10:03 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 7. Jan 10 19:10:03 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 10 19:10:03 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 10 19:10:03 volumio go-librespot[27053]: go-librespot daemon starting... Jan 10 19:10:03 volumio go-librespot[27054]: time="2026-01-10T19:10:03-06:00" level=info msg="running go-librespot 0.4.0" Jan 10 19:10:03 volumio go-librespot[27054]: time="2026-01-10T19:10:03-06:00" level=debug msg="app state loaded" Jan 10 19:10:03 volumio go-librespot[27054]: time="2026-01-10T19:10:03-06:00" level=debug msg="stored credentials not found" Jan 10 19:10:03 volumio go-librespot[27054]: time="2026-01-10T19:10:03-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 10 19:10:04 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.105.134 Jan 10 19:10:04 volumio go-librespot[27054]: time="2026-01-10T19:10:04-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 10 19:10:04 volumio go-librespot[27054]: time="2026-01-10T19:10:04-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 10 19:10:04 volumio go-librespot[27054]: time="2026-01-10T19:10:04-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 10 19:10:04 volumio go-librespot[27054]: time="2026-01-10T19:10:04-06:00" level=info msg="zeroconf server listening on port 41557" Jan 10 19:10:04 volumio go-librespot[27054]: time="2026-01-10T19:10:04-06:00" level=debug msg="obtained new client token: AABy0znjfur6une4YQy11S2R8mtd123jy2S+NInPy1Sbgk52NFcA7q+dh4u93VPZ/Teqb1C4ACoRCmv35aJ5ot2sTcYzjrA2Q845RffoCJLrSUWPishcklAK7NaaJJdTBa7csBlV+6PeeaRxrVm63z8z6xP4rmzEBnzfnpY2GAFD18frVx6EyqucDF3I6WKeL1kyMYGleliPPBv0QnACAi/m6P/IrDpiEC7mg3oavPBP0f4BQ1pwWWMeyQ==" Jan 10 19:10:04 volumio ntpd[872]: IO: Listen normally on 11861 eth0 169.254.105.134:123 Jan 10 19:10:04 volumio ntpd[872]: IO: new interface(s) found: waking up resolver Jan 10 19:10:04 volumio go-librespot[27054]: time="2026-01-10T19:10:04-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 10 19:10:04 volumio go-librespot[27054]: time="2026-01-10T19:10:04-06:00" level=debug msg="completed keyexchange" Jan 10 19:10:04 volumio go-librespot[27054]: time="2026-01-10T19:10:04-06:00" level=debug msg="completed challenge" Jan 10 19:10:04 volumio go-librespot[27054]: time="2026-01-10T19:10:04-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Jan 10 19:10:04 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.105.134 Jan 10 19:10:04 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.105.134 Jan 10 19:10:04 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Jan 10 19:10:04 volumio avahi-daemon[664]: Withdrawing address record for 169.254.105.134 on eth0. Jan 10 19:10:04 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 10 19:10:04 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 10 19:10:04 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 19:10:04 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 10 19:10:04 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 19:10:04 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Jan 10 19:10:05 volumio volumio[26873]: info: Loading plugin "ytmusic"... Jan 10 19:10:06 volumio volumio[26873]: info: Plugin now_playing is not enabled Jan 10 19:10:06 volumio volumio[26873]: info: Loading plugin "outputs"... Jan 10 19:10:06 volumio volumio[26873]: info: Loading plugin "albumart"... Jan 10 19:10:06 volumio volumio[26873]: info: Plugin example_plugin is not enabled Jan 10 19:10:06 volumio volumio[26873]: info: Loading plugin "inputs"... Jan 10 19:10:06 volumio volumio[26873]: info: Loading plugin "updater_comm"... Jan 10 19:10:06 volumio ntpd[872]: IO: Deleting interface #11861 eth0, 169.254.105.134#123, interface stats: received=0, sent=0, dropped=0, active_time=2 secs Jan 10 19:10:06 volumio volumio[26873]: info: Plugin mpdemulation is not enabled Jan 10 19:10:06 volumio volumio[26873]: info: Loading plugin "rest_api"... Jan 10 19:10:06 volumio volumio[26873]: info: Loading plugin "websocket"... Jan 10 19:10:06 volumio volumio[26873]: info: Starting Socket.io Server version 1.7.4 Jan 10 19:10:06 volumio volumio[26873]: info: Plugin fusiondsp is not enabled Jan 10 19:10:06 volumio volumio[26873]: info: Plugin mpdoutput is not enabled Jan 10 19:10:06 volumio volumio[26873]: info: Plugin RoonBridge is not enabled Jan 10 19:10:06 volumio volumio[26873]: info: Loading plugin "podcast"... Jan 10 19:10:06 volumio volumio[26873]: info: ControllerPodcast::constructor Jan 10 19:10:06 volumio volumio[26873]: info: Loading plugin "volusonic"... Jan 10 19:10:06 volumio volumio[27096]: Forking 3 albumart workers Jan 10 19:10:07 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 8. Jan 10 19:10:07 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 10 19:10:07 volumio volumio-remote-updater[14193]: [2026-01-10 19:10:07] [connect] Successful connection Jan 10 19:10:07 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 10 19:10:07 volumio go-librespot[27136]: go-librespot daemon starting... Jan 10 19:10:07 volumio go-librespot[27137]: time="2026-01-10T19:10:07-06:00" level=info msg="running go-librespot 0.4.0" Jan 10 19:10:07 volumio go-librespot[27137]: time="2026-01-10T19:10:07-06:00" level=debug msg="app state loaded" Jan 10 19:10:07 volumio go-librespot[27137]: time="2026-01-10T19:10:07-06:00" level=debug msg="stored credentials not found" Jan 10 19:10:07 volumio go-librespot[27137]: time="2026-01-10T19:10:07-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 10 19:10:08 volumio go-librespot[27137]: time="2026-01-10T19:10:08-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 10 19:10:08 volumio go-librespot[27137]: time="2026-01-10T19:10:08-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 10 19:10:08 volumio go-librespot[27137]: time="2026-01-10T19:10:08-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 10 19:10:08 volumio go-librespot[27137]: time="2026-01-10T19:10:08-06:00" level=info msg="zeroconf server listening on port 39611" Jan 10 19:10:08 volumio go-librespot[27137]: time="2026-01-10T19:10:08-06:00" level=debug msg="obtained new client token: AAALRqOdWgvDUf+8FLFtiaoCSFuGqMMZ2Z+0TthYPvq4nsM3Cxlc7nw6r5fN1BjVhfufSGeh8soe9f2zTTcq6tOaa0G8NQkNViR3Lh+ytsQzI2xRsI/hlkP4iRUtfYbLHm3E9yg/Zx5YI0iJxaA3ge6Wxnv1hYyDRqasi38tkxtmncgI8wWSVmGMuuYUrULPEWBqTHUqNkDrLMyi0gj15RPkkrC0EVW1ghG5sVCo5wl9cyzpBy3ZJcZnnQ==" Jan 10 19:10:08 volumio go-librespot[27137]: time="2026-01-10T19:10:08-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 10 19:10:08 volumio go-librespot[27137]: time="2026-01-10T19:10:08-06:00" level=debug msg="completed keyexchange" Jan 10 19:10:08 volumio go-librespot[27137]: time="2026-01-10T19:10:08-06:00" level=debug msg="completed challenge" Jan 10 19:10:08 volumio go-librespot[27137]: time="2026-01-10T19:10:08-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Jan 10 19:10:08 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 10 19:10:08 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 10 19:10:09 volumio volumio[26873]: info: Applying required configuration parameters for plugin volusonic Jan 10 19:10:09 volumio volumio[26873]: info: Loading plugin "backup_restore"... Jan 10 19:10:09 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.186.98 Jan 10 19:10:09 volumio avahi-daemon[664]: Registering new address record for 169.254.186.98 on eth0.IPv4. Jan 10 19:10:09 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Jan 10 19:10:09 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 19:10:09 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 10 19:10:09 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 19:10:09 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.186.98 Jan 10 19:10:09 volumio volumio[27107]: Starting albumart workers Jan 10 19:10:09 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.186.98 Jan 10 19:10:09 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.186.98 Jan 10 19:10:09 volumio avahi-daemon[664]: Withdrawing address record for 169.254.186.98 on eth0. Jan 10 19:10:09 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Jan 10 19:10:09 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 19:10:09 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 10 19:10:09 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 19:10:09 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Jan 10 19:10:09 volumio volumio[27106]: Starting albumart workers Jan 10 19:10:09 volumio volumio[27108]: Starting albumart workers Jan 10 19:10:09 volumio volumio[26873]: info: Applying required configuration parameters for plugin backup_restore Jan 10 19:10:09 volumio volumio[26873]: info: Plugin rpi_eeprom_config is not enabled Jan 10 19:10:09 volumio volumio[26873]: info: Plugin rpi_eeprom_updater is not enabled Jan 10 19:10:09 volumio volumio[26873]: info: Loading plugin "scheduledrestart"... Jan 10 19:10:10 volumio volumio[26873]: info: Applying required configuration parameters for plugin scheduledrestart Jan 10 19:10:10 volumio volumio[26873]: info: Plugin Bluetoothremote is not enabled Jan 10 19:10:10 volumio volumio[26873]: info: Plugin music_services_shield is not enabled Jan 10 19:10:10 volumio volumio[26873]: info: Loading plugin "Systeminfo"... Jan 10 19:10:10 volumio volumio[26873]: info: Plugin peppymeterbasic is not enabled Jan 10 19:10:10 volumio volumio[26873]: info: Loading plugin "peppyspectrum"... Jan 10 19:10:11 volumio volumio[26873]: info: Loading i18n strings for locale en Jan 10 19:10:11 volumio volumio[26873]: info: Plugin peppyspectrum has duplicated i18n key SAVE. It is ignored. Jan 10 19:10:11 volumio volumio[26873]: Updating browse sources language Jan 10 19:10:11 volumio volumio[26873]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 10 19:10:11 volumio volumio[26873]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 10 19:10:11 volumio volumio[26873]: info: CoreCommandRouter::initPlayerControls Jan 10 19:10:11 volumio volumio[26873]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:10:11 volumio volumio[26873]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:10:11 volumio volumio[26873]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:10:11 volumio volumio[26873]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:10:11 volumio volumio[26873]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:10:11 volumio volumio[26873]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:10:11 volumio volumio[26873]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:10:11 volumio volumio[26873]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:10:11 volumio volumio[26873]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 10 19:10:11 volumio volumio[26873]: Express server listening on port 3000 Jan 10 19:10:11 volumio volumio[26873]: [Metrics] WebUI: 19s 201.47ms Jan 10 19:10:11 volumio volumio[26873]: info: CoreStateMachine::resetVolumioState Jan 10 19:10:11 volumio volumio[26873]: info: CoreStateMachine::getcurrentVolume Jan 10 19:10:11 volumio volumio[26873]: info: CoreCommandRouter::volumioRetrievevolume Jan 10 19:10:11 volumio volumio[26873]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 19:10:11 volumio sudo[27200]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 10 19:10:11 volumio sudo[27200]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 19:10:11 volumio sudo[27200]: pam_unix(sudo:session): session closed for user root Jan 10 19:10:11 volumio sudo[27202]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 10 19:10:11 volumio sudo[27202]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 19:10:11 volumio sudo[27202]: pam_unix(sudo:session): session closed for user root Jan 10 19:10:11 volumio volumio[26873]: info: Volumio Network Manager: Network status updated: 1 Jan 10 19:10:11 volumio volumio[26873]: info: VolumeController:: Volume=100 Mute =false Jan 10 19:10:11 volumio volumio[26873]: info: CoreStateMachine::pushState Jan 10 19:10:11 volumio volumio[26873]: info: CorePlayQueue::getTrack 0 Jan 10 19:10:11 volumio volumio[26873]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 10 19:10:11 volumio volumio[26873]: info: CoreCommandRouter::volumioPushState Jan 10 19:10:11 volumio volumio[26873]: info: CoreStateMachine::updateTrackBlock Jan 10 19:10:11 volumio volumio[26873]: info: CorePlayQueue::getTrackBlock Jan 10 19:10:11 volumio volumio[26873]: info: CoreCommandRouter::volumioRetrievevolume Jan 10 19:10:11 volumio volumio-remote-updater[14193]: [2026-01-10 19:10:11] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1768093807 101 Jan 10 19:10:11 volumio volumio[26873]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 3 Transport: websocket Total Clients: 1 Jan 10 19:10:11 volumio volumio[26873]: info: Reloading queue from file Jan 10 19:10:11 volumio volumio[26873]: info: CoreStateMachine::setRepeat null single undefined Jan 10 19:10:11 volumio volumio[26873]: info: CoreStateMachine::pushState Jan 10 19:10:11 volumio volumio[26873]: info: CorePlayQueue::getTrack 0 Jan 10 19:10:11 volumio volumio[26873]: info: CoreCommandRouter::volumioPushState Jan 10 19:10:11 volumio volumio[26873]: info: CoreStateMachine::setRandom null Jan 10 19:10:11 volumio volumio[26873]: info: CoreStateMachine::pushState Jan 10 19:10:11 volumio volumio[26873]: info: CorePlayQueue::getTrack 0 Jan 10 19:10:11 volumio volumio[26873]: info: CoreCommandRouter::volumioPushState Jan 10 19:10:11 volumio volumio[26873]: info: Setting Device type: Raspberry PI Jan 10 19:10:11 volumio volumio[26873]: info: VolumeController:: Volume=100 Mute =false Jan 10 19:10:11 volumio volumio[26873]: info: CoreStateMachine::pushState Jan 10 19:10:11 volumio volumio[26873]: info: CorePlayQueue::getTrack 0 Jan 10 19:10:11 volumio volumio[26873]: info: CoreCommandRouter::volumioPushState Jan 10 19:10:11 volumio volumio[26873]: info: Completed loading Core Plugins Jan 10 19:10:11 volumio volumio[26873]: info: Preparing to generate the ALSA configuration file Jan 10 19:10:11 volumio sudo[27216]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Jan 10 19:10:11 volumio sudo[27216]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 19:10:11 volumio volumio[26873]: info: Discovery: adding a135e40e-a404-457b-98f5-36bf71c75954 Jan 10 19:10:11 volumio volumio[26873]: info: Discovery: Found device Volumio Jan 10 19:10:11 volumio volumio[26873]: info: CoreCommandRouter::volumioGetState Jan 10 19:10:11 volumio volumio[26873]: info: CorePlayQueue::getTrack 0 Jan 10 19:10:11 volumio volumio[26873]: info: The plugin peppyspectrum has an ALSA contribution file peppy_in.peppy_out.6.conf Jan 10 19:10:11 volumio volumio[26873]: info: Reading ALSA contributions from plugins. Jan 10 19:10:11 volumio volumio[26873]: info: Asound.conf file unchanged, so no further update is needed Jan 10 19:10:11 volumio volumio[26873]: info: Output device has changed, restarting MPD Jan 10 19:10:11 volumio sudo[27216]: pam_unix(sudo:session): session closed for user root Jan 10 19:10:11 volumio volumio[26873]: info: Output device has changed, restarting Shairport Sync Jan 10 19:10:11 volumio volumio[26873]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:10:11 volumio volumio[26873]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 19:10:11 volumio sudo[27219]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 10 19:10:11 volumio sudo[27219]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 19:10:11 volumio sudo[27221]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 10 19:10:11 volumio sudo[27221]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 19:10:11 volumio sudo[27219]: pam_unix(sudo:session): session closed for user root Jan 10 19:10:11 volumio volumio[26873]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 10 19:10:11 volumio volumio[26873]: info: ___________ START PLUGINS ___________ Jan 10 19:10:11 volumio volumio[26873]: info: ControllerMpd::onStart: Initializing MPD Jan 10 19:10:11 volumio volumio[26873]: info: Creating MPD Configuration file Jan 10 19:10:11 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 9. Jan 10 19:10:11 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 10 19:10:11 volumio volumio[26873]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 10 19:10:11 volumio volumio[26873]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 10 19:10:11 volumio volumio[26873]: info: [1768093811944] CoreMusicLibrary::Adding element Media Servers Jan 10 19:10:11 volumio volumio[26873]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 10 19:10:11 volumio sudo[27229]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 10 19:10:11 volumio sudo[27229]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 19:10:11 volumio sudo[27229]: pam_unix(sudo:session): session closed for user root Jan 10 19:10:11 volumio sudo[27231]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 10 19:10:11 volumio sudo[27231]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 19:10:11 volumio volumio[26873]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:10:11 volumio volumio[26873]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 19:10:12 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 10 19:10:12 volumio go-librespot[27233]: go-librespot daemon starting... Jan 10 19:10:12 volumio volumio[26873]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 10 19:10:12 volumio volumio[26873]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:10:12 volumio volumio[26873]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 19:10:12 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Jan 10 19:10:12 volumio go-librespot[27239]: time="2026-01-10T19:10:12-06:00" level=info msg="running go-librespot 0.4.0" Jan 10 19:10:12 volumio go-librespot[27239]: time="2026-01-10T19:10:12-06:00" level=debug msg="app state loaded" Jan 10 19:10:12 volumio go-librespot[27239]: time="2026-01-10T19:10:12-06:00" level=debug msg="stored credentials not found" Jan 10 19:10:12 volumio go-librespot[27239]: time="2026-01-10T19:10:12-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 10 19:10:12 volumio volumio[26873]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 10 19:10:12 volumio volumio[26873]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 10 19:10:12 volumio volumio[26873]: info: [1768093812067] CoreMusicLibrary::Adding element Last_100 Jan 10 19:10:12 volumio volumio[26873]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 10 19:10:12 volumio volumio[26873]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 10 19:10:12 volumio volumio[26873]: info: [1768093812073] CoreMusicLibrary::Adding element Webradio Jan 10 19:10:12 volumio volumio[26873]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 10 19:10:12 volumio volumio[26873]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 10 19:10:12 volumio volumio[26873]: info: Initializing BBC Radios Jan 10 19:10:12 volumio systemd[1]: mpd.service: Deactivated successfully. Jan 10 19:10:12 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Jan 10 19:10:12 volumio systemd[1]: mpd.service: Consumed 5.557s CPU time. Jan 10 19:10:12 volumio systemd[1]: mpd.socket: Deactivated successfully. Jan 10 19:10:12 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jan 10 19:10:12 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jan 10 19:10:12 volumio volumio[26873]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 10 19:10:12 volumio volumio[26873]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 19:10:12 volumio volumio[26873]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 10 19:10:12 volumio volumio[26873]: info: [1768093812176] CoreMusicLibrary::Adding element Bandcamp Discover Jan 10 19:10:12 volumio volumio[26873]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 10 19:10:12 volumio volumio[26873]: Cannot find translation for source Bandcamp Discover Jan 10 19:10:12 volumio volumio[26873]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 10 19:10:12 volumio volumio[26873]: info: [1768093812188] CoreMusicLibrary::Adding element SoundCloud Jan 10 19:10:12 volumio volumio[26873]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 10 19:10:12 volumio volumio[26873]: Cannot find translation for source Bandcamp Discover Jan 10 19:10:12 volumio volumio[26873]: Cannot find translation for source SoundCloud Jan 10 19:10:12 volumio volumio[26873]: info: Creating Spotify config file Jan 10 19:10:12 volumio volumio[26873]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:10:12 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jan 10 19:10:12 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Jan 10 19:10:12 volumio go-librespot[27239]: time="2026-01-10T19:10:12-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Jan 10 19:10:12 volumio go-librespot[27239]: time="2026-01-10T19:10:12-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Jan 10 19:10:12 volumio go-librespot[27239]: time="2026-01-10T19:10:12-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Jan 10 19:10:12 volumio go-librespot[27239]: time="2026-01-10T19:10:12-06:00" level=info msg="zeroconf server listening on port 39505" Jan 10 19:10:12 volumio go-librespot[27239]: time="2026-01-10T19:10:12-06:00" level=debug msg="obtained new client token: AACazIstfyHxSmTs1QDya2rphSElqNm2rO8DLrNrkZpmg2pF5WK3AkgUQPLMr/a+ZlYmcOpOwn9TflabDEX8rVNYBlag8k1rKkaa0UiRQLHumyJN+XX2euafi4p2VKtNdGYXC2ou059XcJKnjrpmW/EKhr4DljrgnpP4AnTA1YMj/jKk26jsBtvJBRYJOQALumSJWGTqaBGU0W/rQSe9SvZYCRcd4K8aJ/zaB7RstiXPQDLhnjkjdeh+HA==" Jan 10 19:10:12 volumio sudo[27264]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jan 10 19:10:12 volumio sudo[27264]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Jan 10 19:10:12 volumio sudo[27264]: pam_unix(sudo:session): session closed for user root Jan 10 19:10:12 volumio go-librespot[27239]: time="2026-01-10T19:10:12-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 10 19:10:12 volumio volumio[26873]: info: [squeezelite_mc] Starting proxy server... Jan 10 19:10:12 volumio go-librespot[27239]: time="2026-01-10T19:10:12-06:00" level=debug msg="completed keyexchange" Jan 10 19:10:12 volumio go-librespot[27239]: time="2026-01-10T19:10:12-06:00" level=debug msg="completed challenge" Jan 10 19:10:12 volumio volumio[26873]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 10 19:10:12 volumio volumio[26873]: info: [1768093812562] CoreMusicLibrary::Adding element YouTube2 Jan 10 19:10:12 volumio volumio[26873]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 10 19:10:12 volumio volumio[26873]: Cannot find translation for source Bandcamp Discover Jan 10 19:10:12 volumio volumio[26873]: Cannot find translation for source SoundCloud Jan 10 19:10:12 volumio volumio[26873]: Cannot find translation for source YouTube2 Jan 10 19:10:12 volumio volumio[26873]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 10 19:10:12 volumio volumio[26873]: info: [1768093812584] CoreMusicLibrary::Adding element YouTube Music Jan 10 19:10:12 volumio volumio[26873]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 10 19:10:12 volumio volumio[26873]: Cannot find translation for source Bandcamp Discover Jan 10 19:10:12 volumio volumio[26873]: Cannot find translation for source SoundCloud Jan 10 19:10:12 volumio volumio[26873]: Cannot find translation for source YouTube2 Jan 10 19:10:12 volumio volumio[26873]: Cannot find translation for source YouTube Music Jan 10 19:10:12 volumio volumio[26873]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 10 19:10:12 volumio volumio[26873]: info: [1768093812597] CoreMusicLibrary::Adding element Podcast Jan 10 19:10:12 volumio volumio[26873]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 10 19:10:12 volumio volumio[26873]: Cannot find translation for source Bandcamp Discover Jan 10 19:10:12 volumio volumio[26873]: Cannot find translation for source SoundCloud Jan 10 19:10:12 volumio volumio[26873]: Cannot find translation for source YouTube2 Jan 10 19:10:12 volumio volumio[26873]: Cannot find translation for source YouTube Music Jan 10 19:10:12 volumio volumio[26873]: Cannot find translation for source Podcast Jan 10 19:10:12 volumio go-librespot[27239]: time="2026-01-10T19:10:12-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Jan 10 19:10:12 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 10 19:10:12 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 10 19:10:12 volumio volumio[26873]: info: Loading i18n strings for locale en Jan 10 19:10:12 volumio volumio[26873]: info: Plugin peppyspectrum has duplicated i18n key SAVE. It is ignored. Jan 10 19:10:12 volumio volumio[26873]: Updating browse sources language Jan 10 19:10:12 volumio volumio[26873]: Cannot find translation for source Bandcamp Discover Jan 10 19:10:12 volumio volumio[26873]: Cannot find translation for source SoundCloud Jan 10 19:10:12 volumio volumio[26873]: Cannot find translation for source YouTube2 Jan 10 19:10:12 volumio volumio[26873]: Cannot find translation for source YouTube Music Jan 10 19:10:12 volumio volumio[26873]: Cannot find translation for source Podcast Jan 10 19:10:12 volumio volumio[26873]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 10 19:10:12 volumio volumio[26873]: Cannot find translation for source Bandcamp Discover Jan 10 19:10:12 volumio volumio[26873]: Cannot find translation for source SoundCloud Jan 10 19:10:12 volumio volumio[26873]: Cannot find translation for source YouTube2 Jan 10 19:10:12 volumio volumio[26873]: Cannot find translation for source YouTube Music Jan 10 19:10:12 volumio volumio[26873]: Cannot find translation for source Podcast Jan 10 19:10:12 volumio volumio[26873]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 10 19:10:12 volumio volumio[26873]: info: [1768093812650] CoreMusicLibrary::Adding element Volusonic Jan 10 19:10:12 volumio volumio[26873]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 10 19:10:12 volumio volumio[26873]: Cannot find translation for source Bandcamp Discover Jan 10 19:10:12 volumio volumio[26873]: Cannot find translation for source SoundCloud Jan 10 19:10:12 volumio volumio[26873]: Cannot find translation for source YouTube2 Jan 10 19:10:12 volumio volumio[26873]: Cannot find translation for source YouTube Music Jan 10 19:10:12 volumio volumio[26873]: Cannot find translation for source Podcast Jan 10 19:10:12 volumio volumio[26873]: Cannot find translation for source Volusonic Jan 10 19:10:12 volumio volumio[26873]: info: Scheduling reboots with hours: 0, minutes: 0 in timezone: America/Chicago Jan 10 19:10:12 volumio volumio[26873]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , updateALSAConfigFile Jan 10 19:10:12 volumio volumio[26873]: info: Volumio Calling Home Jan 10 19:10:12 volumio volumio[26873]: info: [squeezelite_mc] Proxy server started on port 40833 Jan 10 19:10:12 volumio volumio[26873]: info: Preparing to generate the ALSA configuration file Jan 10 19:10:12 volumio volumio[26873]: info: CoreCommandRouter::volumioRetrievevolume Jan 10 19:10:12 volumio volumio[26873]: info: Discovery: this is already registered, a135e40e-a404-457b-98f5-36bf71c75954 Jan 10 19:10:12 volumio volumio[26873]: info: Discovery: Found device Volumio Jan 10 19:10:12 volumio volumio[26873]: info: CoreCommandRouter::volumioGetState Jan 10 19:10:12 volumio volumio[26873]: info: CorePlayQueue::getTrack 0 Jan 10 19:10:12 volumio volumio[26873]: info: The plugin peppyspectrum has an ALSA contribution file peppy_in.peppy_out.6.conf Jan 10 19:10:12 volumio volumio[26873]: info: Reading ALSA contributions from plugins. Jan 10 19:10:12 volumio volumio[26873]: info: MPD Permissions set Jan 10 19:10:12 volumio volumio[26873]: info: MPD Permissions set Jan 10 19:10:12 volumio volumio[26873]: info: Upmpdcli Daemon Started Jan 10 19:10:12 volumio volumio[26873]: info: Spotify config file written Jan 10 19:10:13 volumio sudo[27273]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jan 10 19:10:13 volumio sudo[27273]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 19:10:13 volumio volumio[26873]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Jan 10 19:10:13 volumio volumio[26873]: info: VolumeController:: Volume=100 Mute =false Jan 10 19:10:13 volumio volumio[26873]: info: CoreStateMachine::pushState Jan 10 19:10:13 volumio volumio[26873]: info: CorePlayQueue::getTrack 0 Jan 10 19:10:13 volumio volumio[26873]: info: CoreCommandRouter::volumioPushState Jan 10 19:10:13 volumio volumio[26873]: info: [squeezelite_mc] Server discovery started Jan 10 19:10:13 volumio volumio[26873]: info: [squeezelite_mc] Player finder started Jan 10 19:10:13 volumio volumio[26873]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:10:13 volumio volumio[26873]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:10:13 volumio volumio[26873]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:10:13 volumio volumio[26873]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 10 19:10:13 volumio volumio[26873]: info: [squeezelite_mc] Executing aplay -D hw:1 --nonblock -f MPEG /dev/zero 2>&1 || true Jan 10 19:10:13 volumio volumio[26873]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:10:13 volumio volumio[26873]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:10:13 volumio volumio[26873]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:10:13 volumio volumio[26873]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:10:13 volumio volumio[26873]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:10:13 volumio volumio[26873]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:10:13 volumio volumio[26873]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:10:13 volumio volumio[26873]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:10:13 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 10 19:10:13 volumio volumio[26873]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 19:10:13 volumio volumio[26873]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:10:13 volumio volumio[26873]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:10:13 volumio volumio[26873]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:10:13 volumio volumio[26873]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:10:13 volumio volumio[26873]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:10:13 volumio volumio[26873]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:10:13 volumio volumio[26873]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:10:13 volumio volumio[26873]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:10:13 volumio volumio[26873]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:10:13 volumio volumio[26873]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 19:10:13 volumio volumio[26873]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:10:13 volumio volumio[26873]: info: No need to fix Spotify hosts Jan 10 19:10:13 volumio go-librespot[27279]: go-librespot daemon starting... Jan 10 19:10:13 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 10 19:10:13 volumio sudo[27273]: pam_unix(sudo:session): session closed for user root Jan 10 19:10:13 volumio go-librespot[27288]: time="2026-01-10T19:10:13-06:00" level=info msg="running go-librespot 0.4.0" Jan 10 19:10:13 volumio go-librespot[27288]: time="2026-01-10T19:10:13-06:00" level=debug msg="app state loaded" Jan 10 19:10:13 volumio go-librespot[27288]: time="2026-01-10T19:10:13-06:00" level=debug msg="stored credentials not found" Jan 10 19:10:13 volumio go-librespot[27288]: time="2026-01-10T19:10:13-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 10 19:10:13 volumio kernel: hwmon hwmon1: Voltage normalised Jan 10 19:10:13 volumio volumio[26873]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Jan 10 19:10:13 volumio volumio[26873]: info: [squeezelite_mc] Card 1 supports the following ALSA formats: ["U8","S16_LE"] Jan 10 19:10:13 volumio volumio[26873]: info: [squeezelite_mc] Starting Squeezelite service with params: {"type":"basic","playerName":"volumio","dsdFormat":null,"card":"1","mixerType":"Hardware","mixer":"PCM"} Jan 10 19:10:13 volumio volumio[26873]: info: [squeezelite_mc] Executing cp /data/plugins/music_service/squeezelite_mc/dist/lib/../templates/alsa/100-squeezelite.conf.template.out /etc/alsa/conf.d/100-squeezelite.conf Jan 10 19:10:13 volumio volumio[26873]: info: Volumio called home Jan 10 19:10:13 volumio volumio[26873]: info: Starting Shairport Sync Jan 10 19:10:13 volumio volumio[26873]: info: Starting Shairport Sync Jan 10 19:10:13 volumio volumio[26873]: info: Starting Shairport Sync Jan 10 19:10:13 volumio sudo[27299]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 10 19:10:13 volumio sudo[27297]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/cp /data/plugins/music_service/squeezelite_mc/dist/lib/../templates/alsa/100-squeezelite.conf.template.out /etc/alsa/conf.d/100-squeezelite.conf Jan 10 19:10:13 volumio sudo[27299]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 19:10:13 volumio sudo[27297]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 19:10:13 volumio sudo[27301]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 10 19:10:13 volumio sudo[27301]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 19:10:13 volumio sudo[27297]: pam_unix(sudo:session): session closed for user root Jan 10 19:10:13 volumio sudo[27303]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 10 19:10:13 volumio sudo[27303]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 19:10:13 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jan 10 19:10:13 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Jan 10 19:10:13 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 10 19:10:13 volumio systemd[1]: shairport-sync.service: Consumed 2.058s CPU time. Jan 10 19:10:13 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 10 19:10:13 volumio go-librespot[27288]: time="2026-01-10T19:10:13-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 10 19:10:13 volumio go-librespot[27288]: time="2026-01-10T19:10:13-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 10 19:10:13 volumio go-librespot[27288]: time="2026-01-10T19:10:13-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 10 19:10:13 volumio go-librespot[27288]: time="2026-01-10T19:10:13-06:00" level=info msg="zeroconf server listening on port 40435" Jan 10 19:10:13 volumio sudo[27301]: pam_unix(sudo:session): session closed for user root Jan 10 19:10:13 volumio volumio[26873]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jan 10 19:10:13 volumio volumio[26873]: SPOTIFY: BQBYbmRBFqYDX34z-oBT5ZO_N_90I-lYiJBLVh4y13tcJvgox8-m-ySqyCHD939PfSgJIM-On9qJklvuqHOjLRmazioiTNxPDNXgagMDGY4RWRgFt9QhSwoarxmCf9-AxmZ_f3JdMVEpkVFwL0QLeYgVPyWtE5cmcBrcw_guQgwmCERSKaJpUpl2R4swKd7poamwJtAL_j07PUO-B26gqsQoXKUMUJAaITIyfRA Jan 10 19:10:13 volumio volumio[26873]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jan 10 19:10:13 volumio volumio[26873]: info: New Spotify access token = BQBYbmRBFqYDX34z-oBT5ZO_N_90I-lYiJBLVh4y13tcJvgox8-m-ySqyCHD939PfSgJIM-On9qJklvuqHOjLRmazioiTNxPDNXgagMDGY4RWRgFt9QhSwoarxmCf9-AxmZ_f3JdMVEpkVFwL0QLeYgVPyWtE5cmcBrcw_guQgwmCERSKaJpUpl2R4swKd7poamwJtAL_j07PUO-B26gqsQoXKUMUJAaITIyfRA Jan 10 19:10:13 volumio volumio[26873]: info: Spotify credentials grant success - running version from March 24, 2019 Jan 10 19:10:13 volumio sudo[27299]: pam_unix(sudo:session): session closed for user root Jan 10 19:10:13 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jan 10 19:10:13 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Jan 10 19:10:13 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 10 19:10:13 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 10 19:10:13 volumio sudo[27303]: pam_unix(sudo:session): session closed for user root Jan 10 19:10:13 volumio volumio[26873]: info: [squeezelite_mc] Executing alsactl -L -R nrestore Jan 10 19:10:13 volumio volumio[26873]: info: Asound.conf file unchanged, so no further update is needed Jan 10 19:10:13 volumio volumio[26873]: info: Output device has changed, restarting MPD Jan 10 19:10:13 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.71.127 Jan 10 19:10:13 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Jan 10 19:10:13 volumio avahi-daemon[664]: Registering new address record for 169.254.71.127 on eth0.IPv4. Jan 10 19:10:13 volumio go-librespot[27288]: time="2026-01-10T19:10:13-06:00" level=debug msg="obtained new client token: AADlKmiwxoaAoDRf4TKbM103P8WmyuzqeQoClcJBCw/OlgBmQwDYQNJxN7mQv/PGm6Ax32EuVW5TfOvfQ6rzPDb4u1IyUG3WSQ1ugMEywPYpsDH9iK2XINSotGvPH9KWuouGtUI6hyTlPvpAt40ik5Ve3Dcif3s6T1yXlWgFcOH3lclrnQ7SnAwDa75+P314mx2ImhSqFtKBGZjXeytFHfpgHIq5SGTtwRDAK574e5SQbaCccxosvPR0qw==" Jan 10 19:10:13 volumio volumio[26873]: info: Output device has changed, restarting Shairport Sync Jan 10 19:10:13 volumio volumio[26873]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:10:13 volumio volumio[26873]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 19:10:13 volumio sudo[27313]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/sbin/alsactl -L -R nrestore Jan 10 19:10:13 volumio sudo[27313]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 19:10:13 volumio go-librespot[27288]: time="2026-01-10T19:10:13-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 10 19:10:13 volumio sudo[27313]: pam_unix(sudo:session): session closed for user root Jan 10 19:10:13 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 19:10:13 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 10 19:10:13 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 19:10:14 volumio sudo[27333]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 10 19:10:14 volumio sudo[27333]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 19:10:14 volumio sudo[27334]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 10 19:10:14 volumio sudo[27334]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 19:10:14 volumio sudo[27333]: pam_unix(sudo:session): session closed for user root Jan 10 19:10:14 volumio go-librespot[27288]: time="2026-01-10T19:10:14-06:00" level=debug msg="completed keyexchange" Jan 10 19:10:14 volumio go-librespot[27288]: time="2026-01-10T19:10:14-06:00" level=debug msg="completed challenge" Jan 10 19:10:14 volumio volumio[26873]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 10 19:10:14 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.71.127 Jan 10 19:10:14 volumio go-librespot[27288]: time="2026-01-10T19:10:14-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Jan 10 19:10:14 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 10 19:10:14 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 10 19:10:14 volumio systemd[1]: mpd.service: Deactivated successfully. Jan 10 19:10:14 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Jan 10 19:10:14 volumio systemd[1]: mpd.service: Consumed 1.647s CPU time. Jan 10 19:10:14 volumio systemd[1]: mpd.socket: Deactivated successfully. Jan 10 19:10:14 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jan 10 19:10:14 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jan 10 19:10:14 volumio volumio[26873]: info: Shairport-Sync Started Jan 10 19:10:14 volumio volumio[26873]: Error adding Membership: Error: addMembership EINVAL Jan 10 19:10:14 volumio volumio[26873]: info: Shairport-Sync Started Jan 10 19:10:14 volumio volumio[26873]: info: Shairport-Sync Started Jan 10 19:10:14 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jan 10 19:10:14 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Jan 10 19:10:14 volumio volumio[26873]: info: MPD Permissions set Jan 10 19:10:14 volumio volumio[26873]: info: [squeezelite_mc] Executing cp /data/plugins/music_service/squeezelite_mc/dist/lib/../templates/systemd/squeezelite.service.template.out /etc/systemd/system/squeezelite.service Jan 10 19:10:14 volumio volumio[26873]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:10:14 volumio volumio[26873]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:10:14 volumio volumio[26873]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:10:14 volumio volumio[26873]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:10:14 volumio volumio[26873]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:10:14 volumio volumio[26873]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:10:14 volumio volumio[26873]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:10:14 volumio volumio[26873]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:10:14 volumio volumio[26873]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 19:10:14 volumio volumio[26873]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:10:14 volumio sudo[27363]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/cp /data/plugins/music_service/squeezelite_mc/dist/lib/../templates/systemd/squeezelite.service.template.out /etc/systemd/system/squeezelite.service Jan 10 19:10:14 volumio volumio[26873]: info: CoreCommandRouter::volumioGetState Jan 10 19:10:14 volumio volumio[26873]: info: CorePlayQueue::getTrack 0 Jan 10 19:10:14 volumio sudo[27363]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 19:10:14 volumio volumio[26873]: info: Starting Shairport Sync Jan 10 19:10:14 volumio sudo[27363]: pam_unix(sudo:session): session closed for user root Jan 10 19:10:14 volumio sudo[27360]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jan 10 19:10:14 volumio sudo[27360]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Jan 10 19:10:14 volumio sudo[27360]: pam_unix(sudo:session): session closed for user root Jan 10 19:10:14 volumio volumio[26873]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl daemon-reload || true Jan 10 19:10:14 volumio sudo[27372]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 10 19:10:14 volumio sudo[27372]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 19:10:14 volumio volumio[26873]: SPOTIFY: User informations: {"display_name":"Clint Smith","external_urls":{"spotify":"https://open.spotify.com/user/clintsmith1"},"followers":{"href":null,"total":7},"href":"https://api.spotify.com/v1/users/clintsmith1","id":"clintsmith1","images":[{"height":300,"url":"https://i.scdn.co/image/ab6775700000ee856520409d25d9cc210472a0fd","width":300},{"height":64,"url":"https://i.scdn.co/image/ab67757000003b826520409d25d9cc210472a0fd","width":64}],"type":"user","uri":"spotify:user:clintsmith1"} Jan 10 19:10:14 volumio volumio[26873]: info: Spotify Successfully logged in Jan 10 19:10:14 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.71.127 Jan 10 19:10:14 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.71.127 Jan 10 19:10:14 volumio avahi-daemon[664]: Withdrawing address record for 169.254.71.127 on eth0. Jan 10 19:10:14 volumio sudo[27375]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl daemon-reload Jan 10 19:10:14 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Jan 10 19:10:14 volumio sudo[27375]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 19:10:14 volumio volumio[26873]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 10 19:10:14 volumio volumio[26873]: info: [1768093814659] CoreMusicLibrary::Adding element Spotify Jan 10 19:10:14 volumio volumio[26873]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 10 19:10:14 volumio volumio[26873]: Cannot find translation for source Bandcamp Discover Jan 10 19:10:14 volumio volumio[26873]: Cannot find translation for source SoundCloud Jan 10 19:10:14 volumio volumio[26873]: Cannot find translation for source YouTube2 Jan 10 19:10:14 volumio volumio[26873]: Cannot find translation for source YouTube Music Jan 10 19:10:14 volumio volumio[26873]: Cannot find translation for source Podcast Jan 10 19:10:14 volumio volumio[26873]: Cannot find translation for source Volusonic Jan 10 19:10:14 volumio volumio[26873]: Cannot find translation for source Spotify Jan 10 19:10:14 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Jan 10 19:10:14 volumio systemd[1]: Reloading. Jan 10 19:10:15 volumio kernel: hwmon hwmon1: Undervoltage detected! Jan 10 19:10:15 volumio volumio[26873]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:10:15 volumio volumio[26873]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:10:15 volumio volumio[26873]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:10:15 volumio volumio[26873]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 10 19:10:16 volumio volumio[26873]: info: go-librespot daemon successfully initialized Jan 10 19:10:17 volumio systemd[1]: /lib/systemd/system/go-librespot-daemon.service:9: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Jan 10 19:10:17 volumio systemd[1]: /lib/systemd/system/go-librespot-daemon.service:10: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Jan 10 19:10:17 volumio sudo[27375]: pam_unix(sudo:session): session closed for user root Jan 10 19:10:17 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 10. Jan 10 19:10:18 volumio volumio[26873]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Jan 10 19:10:18 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 19:10:18 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 10 19:10:18 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 19:10:18 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 10 19:10:18 volumio sudo[27426]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Jan 10 19:10:18 volumio sudo[27426]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 19:10:18 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 10 19:10:18 volumio go-librespot[27427]: go-librespot daemon starting... Jan 10 19:10:18 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jan 10 19:10:18 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Jan 10 19:10:18 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 10 19:10:18 volumio systemd[1]: shairport-sync.service: Consumed 1.344s CPU time. Jan 10 19:10:18 volumio go-librespot[27429]: time="2026-01-10T19:10:18-06:00" level=info msg="running go-librespot 0.4.0" Jan 10 19:10:18 volumio go-librespot[27429]: time="2026-01-10T19:10:18-06:00" level=debug msg="app state loaded" Jan 10 19:10:18 volumio go-librespot[27429]: time="2026-01-10T19:10:18-06:00" level=debug msg="stored credentials not found" Jan 10 19:10:18 volumio go-librespot[27429]: time="2026-01-10T19:10:18-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 10 19:10:18 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 10 19:10:18 volumio sudo[27372]: pam_unix(sudo:session): session closed for user root Jan 10 19:10:18 volumio volumio[26873]: info: Shairport-Sync Started Jan 10 19:10:18 volumio sudo[27426]: pam_unix(sudo:session): session closed for user root Jan 10 19:10:18 volumio volumio[26873]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl stop squeezelite || true Jan 10 19:10:18 volumio sudo[27452]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop squeezelite Jan 10 19:10:18 volumio sudo[27452]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 19:10:18 volumio systemd[1]: Stopping squeezelite.service - Squeezelite lightweight headless Squeezebox emulator... Jan 10 19:10:18 volumio go-librespot[27429]: time="2026-01-10T19:10:18-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 10 19:10:18 volumio go-librespot[27429]: time="2026-01-10T19:10:18-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 10 19:10:18 volumio go-librespot[27429]: time="2026-01-10T19:10:18-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 10 19:10:18 volumio go-librespot[27429]: time="2026-01-10T19:10:18-06:00" level=info msg="zeroconf server listening on port 45209" Jan 10 19:10:18 volumio systemd[1]: squeezelite.service: Deactivated successfully. Jan 10 19:10:18 volumio systemd[1]: Stopped squeezelite.service - Squeezelite lightweight headless Squeezebox emulator. Jan 10 19:10:18 volumio go-librespot[27429]: time="2026-01-10T19:10:18-06:00" level=debug msg="obtained new client token: AACjWjOBRGSU1zeVY5ZKVqF/TvPq+qE3V5AXHQavWGPX2TAuelssbmaWBeg84Hvg1en7kw/l60ZGoHlTftK7zwneFOmVFIPUwmNEJSvINY01aEbB7cvaNm0yve3dZzagO/I18CCwuoRbbz/nVUxX/iamaUAx19D5G02qqhx/c0fG34dDlH4xebFD48Unq2bSJDPDAnUEaKzC6/BfS4skE4tXq2upu7b194zFWWBJCGX2RYFlG2wR4u64Rw==" Jan 10 19:10:18 volumio sudo[27452]: pam_unix(sudo:session): session closed for user root Jan 10 19:10:18 volumio go-librespot[27429]: time="2026-01-10T19:10:18-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 10 19:10:18 volumio go-librespot[27429]: time="2026-01-10T19:10:18-06:00" level=debug msg="completed keyexchange" Jan 10 19:10:18 volumio go-librespot[27429]: time="2026-01-10T19:10:18-06:00" level=debug msg="completed challenge" Jan 10 19:10:18 volumio go-librespot[27429]: time="2026-01-10T19:10:18-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Jan 10 19:10:18 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 10 19:10:18 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 10 19:10:19 volumio volumio[26873]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Jan 10 19:10:19 volumio sudo[27456]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Jan 10 19:10:19 volumio sudo[27456]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 19:10:19 volumio sudo[27456]: pam_unix(sudo:session): session closed for user root Jan 10 19:10:19 volumio volumio[26873]: info: [squeezelite_mc] Executing rm /tmp/squeezelite.log Jan 10 19:10:19 volumio sudo[27460]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/rm /tmp/squeezelite.log Jan 10 19:10:19 volumio sudo[27460]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 19:10:19 volumio sudo[27460]: pam_unix(sudo:session): session closed for user root Jan 10 19:10:19 volumio volumio[26873]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl start squeezelite || true Jan 10 19:10:19 volumio sudo[27463]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start squeezelite Jan 10 19:10:19 volumio sudo[27463]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 19:10:19 volumio volumio[26873]: info: Initializing connection to go-librespot Websocket Jan 10 19:10:19 volumio systemd[1]: Starting squeezelite.service - Squeezelite lightweight headless Squeezebox emulator... Jan 10 19:10:19 volumio systemd[1]: Started squeezelite.service - Squeezelite lightweight headless Squeezebox emulator. Jan 10 19:10:19 volumio sudo[27463]: pam_unix(sudo:session): session closed for user root Jan 10 19:10:19 volumio volumio[26873]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 10 19:10:19 volumio mpd[27373]: 2026-01-10T19:10:19 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jan 10 19:10:19 volumio systemd[1]: Started mpd.service - Music Player Daemon. Jan 10 19:10:19 volumio sudo[27231]: pam_unix(sudo:session): session closed for user root Jan 10 19:10:19 volumio sudo[27221]: pam_unix(sudo:session): session closed for user root Jan 10 19:10:19 volumio sudo[27334]: pam_unix(sudo:session): session closed for user root Jan 10 19:10:19 volumio volumio[26873]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Jan 10 19:10:19 volumio sudo[27472]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Jan 10 19:10:19 volumio sudo[27472]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 19:10:20 volumio sudo[27472]: pam_unix(sudo:session): session closed for user root Jan 10 19:10:20 volumio volumio[26873]: error: MPD error: The expression evaluated to a falsy value: Jan 10 19:10:20 volumio volumio[26873]: assert.ok(self.idling) Jan 10 19:10:20 volumio volumio[26873]: error: The expression evaluated to a falsy value: Jan 10 19:10:20 volumio volumio[26873]: assert.ok(self.idling) Jan 10 19:10:20 volumio volumio[26873]: error: MPD error: The expression evaluated to a falsy value: Jan 10 19:10:20 volumio volumio[26873]: assert.ok(self.idling) Jan 10 19:10:20 volumio volumio[26873]: error: The expression evaluated to a falsy value: Jan 10 19:10:20 volumio volumio[26873]: assert.ok(self.idling) Jan 10 19:10:20 volumio volumio[26873]: error: updateQueue error: null Jan 10 19:10:20 volumio volumio[26873]: info: MPD running with PID27373 Jan 10 19:10:20 volumio volumio[26873]: ,establishing connection Jan 10 19:10:20 volumio volumio[26873]: error: updateQueue error: null Jan 10 19:10:20 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.55.117 Jan 10 19:10:20 volumio avahi-daemon[664]: Registering new address record for 169.254.55.117 on eth0.IPv4. Jan 10 19:10:20 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Jan 10 19:10:20 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 19:10:20 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 10 19:10:20 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 19:10:20 volumio volumio[26873]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Jan 10 19:10:20 volumio sudo[27493]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Jan 10 19:10:20 volumio sudo[27493]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 19:10:20 volumio sudo[27493]: pam_unix(sudo:session): session closed for user root Jan 10 19:10:20 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.55.117 Jan 10 19:10:21 volumio volumio[26873]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Jan 10 19:10:21 volumio sudo[27496]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Jan 10 19:10:21 volumio sudo[27496]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 19:10:21 volumio sudo[27496]: pam_unix(sudo:session): session closed for user root Jan 10 19:10:21 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.55.117 Jan 10 19:10:21 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.55.117 Jan 10 19:10:21 volumio avahi-daemon[664]: Withdrawing address record for 169.254.55.117 on eth0. Jan 10 19:10:21 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Jan 10 19:10:21 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Jan 10 19:10:21 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 19:10:21 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 10 19:10:21 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 19:10:21 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 11. Jan 10 19:10:21 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 10 19:10:21 volumio volumio[26873]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Jan 10 19:10:22 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 10 19:10:22 volumio go-librespot[27514]: go-librespot daemon starting... Jan 10 19:10:22 volumio sudo[27516]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Jan 10 19:10:22 volumio sudo[27516]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 19:10:22 volumio go-librespot[27517]: time="2026-01-10T19:10:22-06:00" level=info msg="running go-librespot 0.4.0" Jan 10 19:10:22 volumio go-librespot[27517]: time="2026-01-10T19:10:22-06:00" level=debug msg="app state loaded" Jan 10 19:10:22 volumio go-librespot[27517]: time="2026-01-10T19:10:22-06:00" level=debug msg="stored credentials not found" Jan 10 19:10:22 volumio go-librespot[27517]: time="2026-01-10T19:10:22-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 10 19:10:22 volumio sudo[27516]: pam_unix(sudo:session): session closed for user root Jan 10 19:10:22 volumio volumio[26873]: info: Initializing connection to go-librespot Websocket Jan 10 19:10:22 volumio go-librespot[27517]: time="2026-01-10T19:10:22-06:00" level=debug msg="new websocket client" Jan 10 19:10:22 volumio go-librespot[27517]: time="2026-01-10T19:10:22-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Jan 10 19:10:22 volumio go-librespot[27517]: time="2026-01-10T19:10:22-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Jan 10 19:10:22 volumio volumio[26873]: info: Connection to go-librespot Websocket established Jan 10 19:10:22 volumio go-librespot[27517]: time="2026-01-10T19:10:22-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Jan 10 19:10:22 volumio go-librespot[27517]: time="2026-01-10T19:10:22-06:00" level=info msg="zeroconf server listening on port 44275" Jan 10 19:10:22 volumio go-librespot[27517]: time="2026-01-10T19:10:22-06:00" level=debug msg="obtained new client token: AACn/jSyEiFxdX+neWtLYzvVqTX+7qRewZ/tAnvZdbGc2G7LerldctfN06tvILCa6j3L7jiP9qDuIAJiYZRPbtNy0CdTwEosedW9jgD81xzwKB6vfyiF05+cB12D9S2xsOWDSfl+VLEJaGcqniphEFpClEs7eDiu4J5jk1gByQEfbZObiSHKCSTtG6htspkdK1i/ioNzSvStgGGoEum7pEdv2soxQh8tWZBkSape8gsFd5bG705kGAE7Lg==" Jan 10 19:10:22 volumio volumio[26873]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Jan 10 19:10:22 volumio go-librespot[27517]: time="2026-01-10T19:10:22-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 10 19:10:22 volumio sudo[27526]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Jan 10 19:10:22 volumio sudo[27526]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 19:10:22 volumio go-librespot[27517]: time="2026-01-10T19:10:22-06:00" level=debug msg="completed keyexchange" Jan 10 19:10:22 volumio go-librespot[27517]: time="2026-01-10T19:10:22-06:00" level=debug msg="completed challenge" Jan 10 19:10:22 volumio sudo[27526]: pam_unix(sudo:session): session closed for user root Jan 10 19:10:22 volumio go-librespot[27517]: time="2026-01-10T19:10:22-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Jan 10 19:10:22 volumio volumio[26873]: info: Completed starting Core Plugins Jan 10 19:10:22 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 10 19:10:22 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 10 19:10:22 volumio volumio[26873]: info: ------------------------------------------- Jan 10 19:10:22 volumio volumio[26873]: info: ----- MyVolumio plugins startup ---- Jan 10 19:10:22 volumio volumio[26873]: info: ------------------------------------------- Jan 10 19:10:22 volumio volumio[26873]: info: [MyVolumio PluginManager] Fetching plans data.... Jan 10 19:10:22 volumio volumio[26873]: info: Connection to go-librespot Websocket closed Jan 10 19:10:22 volumio sudo[27529]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Jan 10 19:10:22 volumio sudo[27529]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 19:10:23 volumio sudo[27531]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Jan 10 19:10:23 volumio sudo[27531]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 19:10:23 volumio sudo[27534]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Jan 10 19:10:23 volumio sudo[27534]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 19:10:23 volumio systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Jan 10 19:10:23 volumio systemd[1]: mpd_monitor.service: Deactivated successfully. Jan 10 19:10:23 volumio systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Jan 10 19:10:23 volumio systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Jan 10 19:10:23 volumio sudo[27534]: pam_unix(sudo:session): session closed for user root Jan 10 19:10:23 volumio sudo[27531]: pam_unix(sudo:session): session closed for user root Jan 10 19:10:23 volumio sudo[27529]: pam_unix(sudo:session): session closed for user root Jan 10 19:10:23 volumio volumio[26873]: info: Successfully started MPD Monitor Jan 10 19:10:23 volumio mpd_monitor.sh[27537]: MPD Monitor Service: Starting MPD Monitor Service Jan 10 19:10:23 volumio volumio[26873]: info: Successfully started MPD Monitor Jan 10 19:10:23 volumio volumio[26873]: info: Successfully started MPD Monitor Jan 10 19:10:25 volumio volumio[26873]: info: Getting Spotify volume Jan 10 19:10:25 volumio volumio[26873]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 10 19:10:25 volumio volumio[26873]: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 10 19:10:25 volumio volumio[26873]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Jan 10 19:10:25 volumio volumio[26873]: errno: -111, Jan 10 19:10:25 volumio volumio[26873]: code: 'ECONNREFUSED', Jan 10 19:10:25 volumio volumio[26873]: syscall: 'connect', Jan 10 19:10:25 volumio volumio[26873]: address: '127.0.0.1', Jan 10 19:10:25 volumio volumio[26873]: port: 9879, Jan 10 19:10:25 volumio volumio[26873]: response: undefined Jan 10 19:10:25 volumio volumio[26873]: } Jan 10 19:10:25 volumio volumio[26873]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 10 19:10:25 volumio kernel: hwmon hwmon1: Voltage normalised Jan 10 19:10:25 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 12. Jan 10 19:10:25 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 10 19:10:26 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 10 19:10:26 volumio go-librespot[27569]: go-librespot daemon starting... Jan 10 19:10:26 volumio go-librespot[27570]: time="2026-01-10T19:10:26-06:00" level=info msg="running go-librespot 0.4.0" Jan 10 19:10:26 volumio go-librespot[27570]: time="2026-01-10T19:10:26-06:00" level=debug msg="app state loaded" Jan 10 19:10:26 volumio go-librespot[27570]: time="2026-01-10T19:10:26-06:00" level=debug msg="stored credentials not found" Jan 10 19:10:26 volumio go-librespot[27570]: time="2026-01-10T19:10:26-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 10 19:10:26 volumio sudo[27579]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-01-10 19:09' Jan 10 19:10:26 volumio sudo[27579]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 19:10:26 volumio go-librespot[27570]: time="2026-01-10T19:10:26-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Jan 10 19:10:26 volumio go-librespot[27570]: time="2026-01-10T19:10:26-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Jan 10 19:10:26 volumio go-librespot[27570]: time="2026-01-10T19:10:26-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Jan 10 19:10:26 volumio go-librespot[27570]: time="2026-01-10T19:10:26-06:00" level=info msg="zeroconf server listening on port 35313" Jan 10 19:10:26 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.204.213 Jan 10 19:10:26 volumio avahi-daemon[664]: Registering new address record for 169.254.204.213 on eth0.IPv4. Jan 10 19:10:26 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Jan 10 19:10:26 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 19:10:26 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 10 19:10:26 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 19:10:26 volumio go-librespot[27570]: time="2026-01-10T19:10:26-06:00" level=debug msg="obtained new client token: AAD7zkYliDBymjdl5mTx0kyBOlHvsb+mNYmMBLwVY/6VpEHmlN19coUEOGQOIQfOA8Au9tR/0bbOnzZPSQlE9DmNI0fKlnCWs2juk2WApuV1OGYEtB/gBEz/YPQCenWywNvpa0DymCi1U2brPG1Wb+twWWmUM+vLTuQZr4MKfFWtol0WV9p6ly1qK6/DMz4K5PDMEYU2eXIm0rXx1Egj42Gcurvsiz7Iva2NcZCN2nZyw2QdObHzoX+pmQ==" Jan 10 19:10:26 volumio go-librespot[27570]: time="2026-01-10T19:10:26-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 10 19:10:26 volumio go-librespot[27570]: time="2026-01-10T19:10:26-06:00" level=debug msg="completed keyexchange" Jan 10 19:10:26 volumio go-librespot[27570]: time="2026-01-10T19:10:26-06:00" level=debug msg="completed challenge" Jan 10 19:10:26 volumio sudo[27579]: pam_unix(sudo:session): session closed for user root Jan 10 19:10:26 volumio go-librespot[27570]: time="2026-01-10T19:10:26-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Jan 10 19:10:26 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 10 19:10:26 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 10 19:10:26 volumio volumio-remote-updater[14193]: [2026-01-10 19:10:26] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Jan 10 19:10:26 volumio volumio-remote-updater[14193]: [2026-01-10 19:10:26] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Jan 10 19:10:26 volumio systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Jan 10 19:10:26 volumio systemd[1]: volumio.service: Failed with result 'exit-code'. Jan 10 19:10:26 volumio systemd[1]: volumio.service: Consumed 45.405s CPU time. Jan 10 19:10:26 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Jan 10 19:10:26 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Jan 10 19:10:26 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.204.213 Jan 10 19:10:26 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 18488. Jan 10 19:10:26 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Jan 10 19:10:26 volumio systemd[1]: Stopped volumio.service - Volumio Backend Module. Jan 10 19:10:26 volumio systemd[1]: volumio.service: Consumed 45.405s CPU time. Jan 10 19:10:26 volumio systemd[1]: Started volumio.service - Volumio Backend Module. Jan 10 19:10:27 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Jan 10 19:10:27 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.204.213 Jan 10 19:10:27 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.204.213 Jan 10 19:10:27 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Jan 10 19:10:27 volumio avahi-daemon[664]: Withdrawing address record for 169.254.204.213 on eth0. Jan 10 19:10:27 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 19:10:27 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 10 19:10:27 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 19:10:27 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Jan 10 19:10:28 volumio volumio[27607]: info: ------------------------------------------- Jan 10 19:10:28 volumio volumio[27607]: info: ----- Volumio3 ---- Jan 10 19:10:28 volumio volumio[27607]: info: ------------------------------------------- Jan 10 19:10:28 volumio volumio[27607]: info: ----- System startup ---- Jan 10 19:10:28 volumio volumio[27607]: info: ------------------------------------------- Jan 10 19:10:29 volumio volumio[27607]: info: MYVOLUMIO Environment detected Jan 10 19:10:29 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 13. Jan 10 19:10:29 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 10 19:10:29 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 10 19:10:29 volumio go-librespot[27647]: go-librespot daemon starting... Jan 10 19:10:29 volumio go-librespot[27648]: time="2026-01-10T19:10:29-06:00" level=info msg="running go-librespot 0.4.0" Jan 10 19:10:29 volumio go-librespot[27648]: time="2026-01-10T19:10:29-06:00" level=debug msg="app state loaded" Jan 10 19:10:29 volumio go-librespot[27648]: time="2026-01-10T19:10:29-06:00" level=debug msg="stored credentials not found" Jan 10 19:10:29 volumio go-librespot[27648]: time="2026-01-10T19:10:29-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 10 19:10:29 volumio volumio[27607]: info: Plugin folders cleanup Jan 10 19:10:29 volumio volumio[27607]: info: Scanning into folder /volumio/app/plugins/ Jan 10 19:10:29 volumio volumio[27607]: info: Scanning category audio_interface Jan 10 19:10:29 volumio volumio[27607]: info: Scanning category miscellanea Jan 10 19:10:29 volumio volumio[27607]: info: Scanning category music_service Jan 10 19:10:29 volumio volumio[27607]: info: Scanning category plugins.json Jan 10 19:10:29 volumio volumio[27607]: info: Scanning category system_controller Jan 10 19:10:29 volumio volumio[27607]: info: Scanning category user_interface Jan 10 19:10:29 volumio volumio[27607]: info: Scanning into folder /data/plugins/ Jan 10 19:10:29 volumio volumio[27607]: info: Scanning category audio_interface Jan 10 19:10:29 volumio volumio[27607]: info: Scanning category music_service Jan 10 19:10:29 volumio volumio[27607]: info: Scanning category system_controller Jan 10 19:10:29 volumio volumio[27607]: info: Scanning category system_hardware Jan 10 19:10:29 volumio volumio[27607]: info: Scanning category user_interface Jan 10 19:10:29 volumio volumio[27607]: info: Plugin folders cleanup completed Jan 10 19:10:29 volumio volumio[27607]: info: ------------------------------------------- Jan 10 19:10:29 volumio volumio[27607]: info: ----- Core plugins startup ---- Jan 10 19:10:29 volumio volumio[27607]: info: ------------------------------------------- Jan 10 19:10:29 volumio volumio[27607]: info: Loading plugins from folder /volumio/app/plugins/ Jan 10 19:10:29 volumio volumio[27607]: info: Adding plugin upnp to MyMusic Plugins Jan 10 19:10:29 volumio volumio[27607]: info: Adding plugin airplay_emulation to MyMusic Plugins Jan 10 19:10:29 volumio volumio[27607]: info: Adding plugin upnp_browser to MyMusic Plugins Jan 10 19:10:29 volumio volumio[27607]: info: Loading plugins from folder /data/plugins/ Jan 10 19:10:29 volumio volumio[27607]: info: Loading plugin "system"... Jan 10 19:10:29 volumio volumio[27607]: info: Loading plugin "appearance"... Jan 10 19:10:30 volumio go-librespot[27648]: time="2026-01-10T19:10:30-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 10 19:10:30 volumio go-librespot[27648]: time="2026-01-10T19:10:30-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 10 19:10:30 volumio go-librespot[27648]: time="2026-01-10T19:10:30-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 10 19:10:30 volumio go-librespot[27648]: time="2026-01-10T19:10:30-06:00" level=info msg="zeroconf server listening on port 35781" Jan 10 19:10:30 volumio go-librespot[27648]: time="2026-01-10T19:10:30-06:00" level=debug msg="obtained new client token: AABEgaPHkj/bIkRdUE7fzMdey/ziGjDePXq5NIS6S3SKTY2aBR5gJ9d1HXwfTignVz4vA6p/nHEtIdEdmFJ8SmLO/gz7L0QjhH6nzzzSZaxJjG63yWzhxGoQNiJx8ZLtLWxw3F7xfVSCkXXDk+bfUaxxNL90ow5k5aSTZvrmw3oLUAsyOo6NUeFw7bvhPa4JU4k9tlX6IHHlf4yZ7MIb8guw/CgjnaOnOYvm1JwyLPw+HwX2Ptln8k4=" Jan 10 19:10:30 volumio go-librespot[27648]: time="2026-01-10T19:10:30-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 10 19:10:30 volumio go-librespot[27648]: time="2026-01-10T19:10:30-06:00" level=debug msg="completed keyexchange" Jan 10 19:10:30 volumio go-librespot[27648]: time="2026-01-10T19:10:30-06:00" level=debug msg="completed challenge" Jan 10 19:10:30 volumio go-librespot[27648]: time="2026-01-10T19:10:30-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Jan 10 19:10:30 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 10 19:10:30 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 10 19:10:30 volumio volumio[27607]: info: Loading plugin "network"... Jan 10 19:10:30 volumio volumio[27607]: info: Refreshing Cached IP Addresses Jan 10 19:10:31 volumio sudo[27660]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 10 19:10:31 volumio sudo[27660]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 19:10:31 volumio sudo[27662]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 10 19:10:31 volumio sudo[27662]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 19:10:31 volumio sudo[27660]: pam_unix(sudo:session): session closed for user root Jan 10 19:10:31 volumio volumio[27607]: info: Loading plugin "services"... Jan 10 19:10:31 volumio volumio[27607]: info: Loading plugin "alsa_controller"... Jan 10 19:10:31 volumio sudo[27662]: pam_unix(sudo:session): session closed for user root Jan 10 19:10:31 volumio sudo[27670]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Jan 10 19:10:31 volumio sudo[27670]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 19:10:31 volumio volumio[27607]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 10 19:10:31 volumio volumio[27607]: info: Loading plugin "wizard"... Jan 10 19:10:31 volumio volumio[27607]: info: Loading plugin "networkfs"... Jan 10 19:10:31 volumio volumio[27607]: info: Starting Udev Watcher for removable devices Jan 10 19:10:31 volumio volumio[27607]: info: Ignoring mount for partition: boot Jan 10 19:10:31 volumio volumio[27607]: info: Ignoring mount for partition: volumio Jan 10 19:10:31 volumio volumio[27607]: info: Ignoring mount for partition: volumio_data Jan 10 19:10:31 volumio volumio[27607]: info: Mounting Device Wikipedia Jan 10 19:10:31 volumio sudo[27699]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mount /dev/sda1 /mnt/USB/Wikipedia -o noatime Jan 10 19:10:31 volumio sudo[27699]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 19:10:31 volumio sudo[27699]: pam_unix(sudo:session): session closed for user root Jan 10 19:10:31 volumio volumio[27607]: mount: /media/Wikipedia: /dev/sda1 already mounted on /media/Wikipedia. Jan 10 19:10:31 volumio volumio[27607]: dmesg(1) may have more information after failed mount system call. Jan 10 19:10:31 volumio volumio[27607]: error: Failed to mount Wikipedia: Error: Command failed: /usr/bin/sudo /bin/mount "/dev/sda1" "/mnt/USB/Wikipedia" -o noatime Jan 10 19:10:31 volumio volumio[27607]: mount: /media/Wikipedia: /dev/sda1 already mounted on /media/Wikipedia. Jan 10 19:10:31 volumio volumio[27607]: dmesg(1) may have more information after failed mount system call. Jan 10 19:10:31 volumio volumio[27607]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 10 19:10:31 volumio volumio[27607]: info: Loading plugin "volumio_command_line_client"... Jan 10 19:10:31 volumio volumio[27607]: info: Loading plugin "upnp"... Jan 10 19:10:31 volumio volumio[27607]: info: [1768093831388] Starting Upmpd Daemon Jan 10 19:10:31 volumio volumio[27607]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 10 19:10:31 volumio volumio[27607]: info: Loading plugin "my_music"... Jan 10 19:10:31 volumio volumio[27607]: info: Loading plugin "mpd"... Jan 10 19:10:31 volumio volumio-remote-updater[14193]: [2026-01-10 19:10:31] [connect] Successful connection Jan 10 19:10:31 volumio sudo[27670]: pam_unix(sudo:session): session closed for user root Jan 10 19:10:31 volumio kernel: hwmon hwmon1: Undervoltage detected! Jan 10 19:10:32 volumio volumio[27607]: info: Loading plugin "upnp_browser"... Jan 10 19:10:32 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.227.43 Jan 10 19:10:32 volumio avahi-daemon[664]: Registering new address record for 169.254.227.43 on eth0.IPv4. Jan 10 19:10:32 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Jan 10 19:10:32 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 19:10:32 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 10 19:10:32 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 19:10:32 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.227.43 Jan 10 19:10:33 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 14. Jan 10 19:10:33 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 10 19:10:33 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.227.43 Jan 10 19:10:33 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.227.43 Jan 10 19:10:33 volumio avahi-daemon[664]: Withdrawing address record for 169.254.227.43 on eth0. Jan 10 19:10:33 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Jan 10 19:10:33 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 10 19:10:33 volumio go-librespot[27718]: go-librespot daemon starting... Jan 10 19:10:33 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 19:10:33 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 10 19:10:33 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 19:10:33 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Jan 10 19:10:33 volumio go-librespot[27724]: time="2026-01-10T19:10:33-06:00" level=info msg="running go-librespot 0.4.0" Jan 10 19:10:33 volumio go-librespot[27724]: time="2026-01-10T19:10:33-06:00" level=debug msg="app state loaded" Jan 10 19:10:33 volumio go-librespot[27724]: time="2026-01-10T19:10:33-06:00" level=debug msg="stored credentials not found" Jan 10 19:10:33 volumio go-librespot[27724]: time="2026-01-10T19:10:33-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 10 19:10:34 volumio go-librespot[27724]: time="2026-01-10T19:10:34-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 10 19:10:34 volumio go-librespot[27724]: time="2026-01-10T19:10:34-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 10 19:10:34 volumio go-librespot[27724]: time="2026-01-10T19:10:34-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 10 19:10:34 volumio go-librespot[27724]: time="2026-01-10T19:10:34-06:00" level=info msg="zeroconf server listening on port 36937" Jan 10 19:10:34 volumio go-librespot[27724]: time="2026-01-10T19:10:34-06:00" level=debug msg="obtained new client token: AABA/ajQOa1scMJhn/0zCLnz2insaBNueIe0abIkg0KXUbO6JWkQKsHq6l6VS/EVDNsjHpF+Xrc3/elYTN3bL2tcTiZPxara+2WCb9z8JTSbVqNHRT6qBWYElQTzKxYhpLv/mSBo5KqP1x7bXk2ZqC1ofYV2B5skGFTZgnbvdih1VE1DgO6uQQovkQSp5vH0QMPqRHszh0BFLlRx67MZvqK7B0+CGpACYp7PeZv5CGiM2y+qMSYTT2o=" Jan 10 19:10:34 volumio go-librespot[27724]: time="2026-01-10T19:10:34-06: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" Jan 10 19:10:34 volumio go-librespot[27724]: time="2026-01-10T19:10:34-06:00" level=debug msg="connected to ap-guc3.spotify.com:443" Jan 10 19:10:34 volumio go-librespot[27724]: time="2026-01-10T19:10:34-06:00" level=debug msg="completed keyexchange" Jan 10 19:10:34 volumio go-librespot[27724]: time="2026-01-10T19:10:34-06:00" level=debug msg="completed challenge" Jan 10 19:10:34 volumio go-librespot[27724]: time="2026-01-10T19:10:34-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Jan 10 19:10:34 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 10 19:10:34 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 10 19:10:34 volumio volumio[27607]: info: Loading plugin "alarm-clock"... Jan 10 19:10:34 volumio volumio[27607]: info: Loading plugin "airplay_emulation"... Jan 10 19:10:34 volumio volumio[27607]: info: Starting Shairport Sync Jan 10 19:10:34 volumio volumio[27607]: info: Loading plugin "last_100"... Jan 10 19:10:34 volumio volumio[27607]: info: Loading plugin "webradio"... Jan 10 19:10:34 volumio volumio[27607]: info: Loading plugin "i2s_dacs"... Jan 10 19:10:34 volumio volumio[27607]: info: I2S DAC not set, start Auto-detection Jan 10 19:10:35 volumio volumio[27607]: info: Loading plugin "volumiodiscovery"... Jan 10 19:10:35 volumio volumio[27607]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jan 10 19:10:35 volumio volumio[27607]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 10 19:10:35 volumio volumio[27607]: *** WARNING *** For more information see Jan 10 19:10:35 volumio volumio[27607]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jan 10 19:10:35 volumio volumio[27607]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 10 19:10:35 volumio volumio[27607]: *** WARNING *** For more information see Jan 10 19:10:35 volumio node[27607]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jan 10 19:10:35 volumio node[27607]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 10 19:10:35 volumio node[27607]: *** WARNING *** For more information see Jan 10 19:10:35 volumio node[27607]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jan 10 19:10:35 volumio node[27607]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 10 19:10:35 volumio node[27607]: *** WARNING *** For more information see Jan 10 19:10:35 volumio volumio[27607]: info: Applying required configuration parameters for plugin volumiodiscovery Jan 10 19:10:35 volumio volumio[27607]: info: Discovery: Started advertising with name: Volumio Jan 10 19:10:35 volumio volumio[27607]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 10 19:10:35 volumio volumio[27607]: info: Loading plugin "bandcamp"... Jan 10 19:10:36 volumio volumio[27607]: info: Plugin calmradio is not enabled Jan 10 19:10:36 volumio volumio[27607]: info: Loading plugin "soundcloud"... Jan 10 19:10:36 volumio volumio[27607]: info: Loading plugin "spop"... Jan 10 19:10:37 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 15. Jan 10 19:10:37 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 10 19:10:37 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 10 19:10:37 volumio go-librespot[27744]: go-librespot daemon starting... Jan 10 19:10:37 volumio go-librespot[27745]: time="2026-01-10T19:10:37-06:00" level=info msg="running go-librespot 0.4.0" Jan 10 19:10:37 volumio go-librespot[27745]: time="2026-01-10T19:10:37-06:00" level=debug msg="app state loaded" Jan 10 19:10:37 volumio go-librespot[27745]: time="2026-01-10T19:10:37-06:00" level=debug msg="stored credentials not found" Jan 10 19:10:37 volumio go-librespot[27745]: time="2026-01-10T19:10:37-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 10 19:10:37 volumio volumio[27607]: info: Loading plugin "squeezelite_mc"... Jan 10 19:10:37 volumio go-librespot[27745]: time="2026-01-10T19:10:37-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Jan 10 19:10:37 volumio go-librespot[27745]: time="2026-01-10T19:10:37-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Jan 10 19:10:37 volumio go-librespot[27745]: time="2026-01-10T19:10:37-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Jan 10 19:10:37 volumio go-librespot[27745]: time="2026-01-10T19:10:37-06:00" level=info msg="zeroconf server listening on port 38763" Jan 10 19:10:37 volumio go-librespot[27745]: time="2026-01-10T19:10:37-06:00" level=debug msg="obtained new client token: AABd/FugagxqSFRDQB+3QilwKrMAIw+OOWIpUTh+wunaFsK9enhNnnQD/ZRPc5sy91wD/dFmr8tfPxJbntJVZya+1LnOvvXeXnXnpqfaT//UFi4/KDA0oBDroNNd1/bnN1M1Y7SZfdOWekLOeFgODZ1vfgm2VCh2gx0YCLp+KLwN8UMBzPEnJsTvhodTMJvA+QTxGN7kZLAhXzoehSJO6+WU3DqycyL+OdqZnovraBbIXNyzluEo5gPzPg==" Jan 10 19:10:37 volumio go-librespot[27745]: time="2026-01-10T19:10:37-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 10 19:10:38 volumio go-librespot[27745]: time="2026-01-10T19:10:38-06:00" level=debug msg="completed keyexchange" Jan 10 19:10:38 volumio go-librespot[27745]: time="2026-01-10T19:10:38-06:00" level=debug msg="completed challenge" Jan 10 19:10:38 volumio go-librespot[27745]: time="2026-01-10T19:10:38-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Jan 10 19:10:38 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 10 19:10:38 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 10 19:10:38 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.131.82 Jan 10 19:10:38 volumio avahi-daemon[664]: Registering new address record for 169.254.131.82 on eth0.IPv4. Jan 10 19:10:38 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Jan 10 19:10:38 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 19:10:38 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 10 19:10:38 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 19:10:38 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.131.82 Jan 10 19:10:38 volumio kernel: hwmon hwmon1: Voltage normalised Jan 10 19:10:38 volumio volumio[27607]: info: Loading plugin "youtube2"... Jan 10 19:10:38 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.131.82 Jan 10 19:10:38 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.131.82 Jan 10 19:10:38 volumio avahi-daemon[664]: Withdrawing address record for 169.254.131.82 on eth0. Jan 10 19:10:38 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Jan 10 19:10:39 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Jan 10 19:10:39 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 19:10:39 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 10 19:10:39 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 19:10:39 volumio volumio[27607]: info: Loading plugin "ytcr"... Jan 10 19:10:40 volumio kernel: hwmon hwmon1: Undervoltage detected! Jan 10 19:10:41 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 16. Jan 10 19:10:41 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 10 19:10:41 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 10 19:10:41 volumio go-librespot[27799]: go-librespot daemon starting... Jan 10 19:10:41 volumio go-librespot[27800]: time="2026-01-10T19:10:41-06:00" level=info msg="running go-librespot 0.4.0" Jan 10 19:10:41 volumio go-librespot[27800]: time="2026-01-10T19:10:41-06:00" level=debug msg="app state loaded" Jan 10 19:10:41 volumio go-librespot[27800]: time="2026-01-10T19:10:41-06:00" level=debug msg="stored credentials not found" Jan 10 19:10:41 volumio go-librespot[27800]: time="2026-01-10T19:10:41-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 10 19:10:41 volumio volumio[27607]: info: Loading plugin "ytmusic"... Jan 10 19:10:41 volumio go-librespot[27800]: time="2026-01-10T19:10:41-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 10 19:10:41 volumio go-librespot[27800]: time="2026-01-10T19:10:41-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 10 19:10:41 volumio go-librespot[27800]: time="2026-01-10T19:10:41-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 10 19:10:41 volumio go-librespot[27800]: time="2026-01-10T19:10:41-06:00" level=info msg="zeroconf server listening on port 35671" Jan 10 19:10:41 volumio go-librespot[27800]: time="2026-01-10T19:10:41-06:00" level=debug msg="obtained new client token: AAAOB4tBRwmnUYj4NS7aAePDoePXlSFy9/t0ldkELCCZxhy+PXJaKj0ARyESki5Rp0Pkw62R3BRHTze30mnVvHdGc1Ca7mRc/gIcswpU5lI0FxDmFQGeZTY1IRTYII+yIb33whUIkZiX9+ETPaiUCmW/DDpb0jQuSOadWiFP1kfXe57gLigiBH+QjyOeMEoqvHpNBprQKmrO+ndEKU2S3LWAiNKpLqySw75+rNObi2p0/GKdtGvRJXpnlA==" Jan 10 19:10:42 volumio go-librespot[27800]: time="2026-01-10T19:10:42-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 10 19:10:42 volumio go-librespot[27800]: time="2026-01-10T19:10:42-06:00" level=debug msg="completed keyexchange" Jan 10 19:10:42 volumio go-librespot[27800]: time="2026-01-10T19:10:42-06:00" level=debug msg="completed challenge" Jan 10 19:10:42 volumio go-librespot[27800]: time="2026-01-10T19:10:42-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Jan 10 19:10:42 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 10 19:10:42 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 10 19:10:42 volumio volumio[27607]: info: Plugin now_playing is not enabled Jan 10 19:10:42 volumio volumio[27607]: info: Loading plugin "outputs"... Jan 10 19:10:42 volumio volumio[27607]: info: Loading plugin "albumart"... Jan 10 19:10:42 volumio volumio[27607]: info: Plugin example_plugin is not enabled Jan 10 19:10:42 volumio volumio[27607]: info: Loading plugin "inputs"... Jan 10 19:10:42 volumio volumio[27607]: info: Loading plugin "updater_comm"... Jan 10 19:10:42 volumio volumio[27607]: info: Plugin mpdemulation is not enabled Jan 10 19:10:42 volumio volumio[27607]: info: Loading plugin "rest_api"... Jan 10 19:10:42 volumio volumio[27607]: info: Loading plugin "websocket"... Jan 10 19:10:42 volumio volumio[27607]: info: Starting Socket.io Server version 1.7.4 Jan 10 19:10:42 volumio volumio[27607]: info: Plugin fusiondsp is not enabled Jan 10 19:10:42 volumio volumio[27607]: info: Plugin mpdoutput is not enabled Jan 10 19:10:42 volumio volumio[27607]: info: Plugin RoonBridge is not enabled Jan 10 19:10:42 volumio volumio[27607]: info: Loading plugin "podcast"... Jan 10 19:10:42 volumio volumio[27607]: info: ControllerPodcast::constructor Jan 10 19:10:42 volumio volumio[27607]: info: Loading plugin "volusonic"... Jan 10 19:10:43 volumio volumio[27808]: Forking 3 albumart workers Jan 10 19:10:44 volumio volumio-remote-updater[14193]: [2026-01-10 19:10:44] [connect] Successful connection Jan 10 19:10:44 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.90.110 Jan 10 19:10:44 volumio avahi-daemon[664]: Registering new address record for 169.254.90.110 on eth0.IPv4. Jan 10 19:10:44 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Jan 10 19:10:44 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 19:10:44 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 10 19:10:44 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 19:10:45 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 17. Jan 10 19:10:45 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 10 19:10:45 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 10 19:10:45 volumio go-librespot[27867]: go-librespot daemon starting... Jan 10 19:10:45 volumio go-librespot[27868]: time="2026-01-10T19:10:45-06:00" level=info msg="running go-librespot 0.4.0" Jan 10 19:10:45 volumio go-librespot[27868]: time="2026-01-10T19:10:45-06:00" level=debug msg="app state loaded" Jan 10 19:10:45 volumio go-librespot[27868]: time="2026-01-10T19:10:45-06:00" level=debug msg="stored credentials not found" Jan 10 19:10:45 volumio go-librespot[27868]: time="2026-01-10T19:10:45-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 10 19:10:45 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.90.110 Jan 10 19:10:45 volumio volumio[27607]: info: Applying required configuration parameters for plugin volusonic Jan 10 19:10:45 volumio volumio[27607]: info: Loading plugin "backup_restore"... Jan 10 19:10:45 volumio volumio[27819]: Starting albumart workers Jan 10 19:10:45 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.90.110 Jan 10 19:10:45 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.90.110 Jan 10 19:10:45 volumio avahi-daemon[664]: Withdrawing address record for 169.254.90.110 on eth0. Jan 10 19:10:45 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Jan 10 19:10:45 volumio volumio[27818]: Starting albumart workers Jan 10 19:10:45 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 19:10:45 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 10 19:10:45 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 19:10:45 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Jan 10 19:10:45 volumio volumio[27820]: Starting albumart workers Jan 10 19:10:45 volumio volumio[27607]: info: Applying required configuration parameters for plugin backup_restore Jan 10 19:10:45 volumio volumio[27607]: info: Plugin rpi_eeprom_config is not enabled Jan 10 19:10:45 volumio volumio[27607]: info: Plugin rpi_eeprom_updater is not enabled Jan 10 19:10:45 volumio volumio[27607]: info: Loading plugin "scheduledrestart"... Jan 10 19:10:46 volumio volumio[27607]: info: Applying required configuration parameters for plugin scheduledrestart Jan 10 19:10:46 volumio volumio[27607]: info: Plugin Bluetoothremote is not enabled Jan 10 19:10:46 volumio volumio[27607]: info: Plugin music_services_shield is not enabled Jan 10 19:10:46 volumio volumio[27607]: info: Loading plugin "Systeminfo"... Jan 10 19:10:46 volumio go-librespot[27868]: time="2026-01-10T19:10:46-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 10 19:10:46 volumio go-librespot[27868]: time="2026-01-10T19:10:46-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 10 19:10:46 volumio go-librespot[27868]: time="2026-01-10T19:10:46-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 10 19:10:46 volumio go-librespot[27868]: time="2026-01-10T19:10:46-06:00" level=info msg="zeroconf server listening on port 37131" Jan 10 19:10:46 volumio go-librespot[27868]: time="2026-01-10T19:10:46-06:00" level=debug msg="obtained new client token: AADN3YCbkbyUWtl7d01aPkn9MNiiTixQSMGJuLXQos9jqq6LIxG6mA7STs8v1SAsAz8n+oBdE8HoIKhGxN7Dv+SXxNm5Alu3XeNq0WdEu5yktHzLjOEgpf3nnNVMSBC7UYsG3me9nu2oWUNKhXQfmWzf+Ybfmigsfh6uGBfQLOtSe5EEETfD8CuAGPkbn+c5U67zsjiJJ18VXrSi/ZiBwlzFh2GmoJfvu5BeGQTtaruM+rISwBIAm4Vmjg==" Jan 10 19:10:47 volumio go-librespot[27868]: time="2026-01-10T19:10:47-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 10 19:10:47 volumio volumio[27607]: info: Plugin peppymeterbasic is not enabled Jan 10 19:10:47 volumio volumio[27607]: info: Loading plugin "peppyspectrum"... Jan 10 19:10:47 volumio go-librespot[27868]: time="2026-01-10T19:10:47-06:00" level=debug msg="completed keyexchange" Jan 10 19:10:47 volumio go-librespot[27868]: time="2026-01-10T19:10:47-06:00" level=debug msg="completed challenge" Jan 10 19:10:47 volumio go-librespot[27868]: time="2026-01-10T19:10:47-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Jan 10 19:10:47 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 10 19:10:47 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 10 19:10:47 volumio volumio[27607]: info: Loading i18n strings for locale en Jan 10 19:10:47 volumio volumio[27607]: info: Plugin peppyspectrum has duplicated i18n key SAVE. It is ignored. Jan 10 19:10:47 volumio volumio[27607]: Updating browse sources language Jan 10 19:10:47 volumio volumio[27607]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 10 19:10:47 volumio volumio[27607]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 10 19:10:47 volumio volumio[27607]: info: CoreCommandRouter::initPlayerControls Jan 10 19:10:47 volumio volumio[27607]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:10:47 volumio volumio[27607]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:10:47 volumio volumio[27607]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:10:47 volumio volumio[27607]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:10:47 volumio volumio[27607]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:10:47 volumio volumio[27607]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:10:47 volumio volumio[27607]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:10:47 volumio volumio[27607]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:10:47 volumio volumio[27607]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 10 19:10:47 volumio volumio[27607]: Express server listening on port 3000 Jan 10 19:10:47 volumio volumio[27607]: [Metrics] WebUI: 19s 160.15ms Jan 10 19:10:47 volumio volumio[27607]: info: CoreStateMachine::resetVolumioState Jan 10 19:10:47 volumio volumio[27607]: info: CoreStateMachine::getcurrentVolume Jan 10 19:10:47 volumio volumio[27607]: info: CoreCommandRouter::volumioRetrievevolume Jan 10 19:10:47 volumio volumio[27607]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 19:10:47 volumio sudo[27915]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 10 19:10:47 volumio sudo[27915]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 19:10:47 volumio sudo[27917]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 10 19:10:47 volumio sudo[27915]: pam_unix(sudo:session): session closed for user root Jan 10 19:10:47 volumio sudo[27917]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 19:10:47 volumio sudo[27917]: pam_unix(sudo:session): session closed for user root Jan 10 19:10:47 volumio volumio[27607]: info: Volumio Network Manager: Network status updated: 1 Jan 10 19:10:47 volumio volumio[27607]: info: VolumeController:: Volume=100 Mute =false Jan 10 19:10:47 volumio volumio[27607]: info: CoreStateMachine::pushState Jan 10 19:10:47 volumio volumio[27607]: info: CorePlayQueue::getTrack 0 Jan 10 19:10:47 volumio volumio[27607]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 10 19:10:47 volumio volumio[27607]: info: CoreCommandRouter::volumioPushState Jan 10 19:10:47 volumio volumio[27607]: info: CoreStateMachine::updateTrackBlock Jan 10 19:10:47 volumio volumio[27607]: info: CorePlayQueue::getTrackBlock Jan 10 19:10:47 volumio volumio[27607]: info: CoreCommandRouter::volumioRetrievevolume Jan 10 19:10:47 volumio volumio-remote-updater[14193]: [2026-01-10 19:10:47] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1768093844 101 Jan 10 19:10:47 volumio volumio[27607]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 3 Transport: websocket Total Clients: 1 Jan 10 19:10:47 volumio volumio[27607]: info: Reloading queue from file Jan 10 19:10:47 volumio volumio[27607]: info: CoreStateMachine::setRepeat null single undefined Jan 10 19:10:47 volumio volumio[27607]: info: CoreStateMachine::pushState Jan 10 19:10:47 volumio volumio[27607]: info: CorePlayQueue::getTrack 0 Jan 10 19:10:47 volumio volumio[27607]: info: CoreCommandRouter::volumioPushState Jan 10 19:10:47 volumio volumio[27607]: info: CoreStateMachine::setRandom null Jan 10 19:10:47 volumio volumio[27607]: info: CoreStateMachine::pushState Jan 10 19:10:47 volumio volumio[27607]: info: CorePlayQueue::getTrack 0 Jan 10 19:10:47 volumio volumio[27607]: info: CoreCommandRouter::volumioPushState Jan 10 19:10:47 volumio volumio[27607]: info: Setting Device type: Raspberry PI Jan 10 19:10:47 volumio volumio[27607]: info: VolumeController:: Volume=100 Mute =false Jan 10 19:10:47 volumio volumio[27607]: info: CoreStateMachine::pushState Jan 10 19:10:47 volumio volumio[27607]: info: CorePlayQueue::getTrack 0 Jan 10 19:10:47 volumio volumio[27607]: info: CoreCommandRouter::volumioPushState Jan 10 19:10:48 volumio volumio[27607]: info: Completed loading Core Plugins Jan 10 19:10:48 volumio volumio[27607]: info: Preparing to generate the ALSA configuration file Jan 10 19:10:48 volumio sudo[27931]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Jan 10 19:10:48 volumio sudo[27931]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 19:10:48 volumio volumio[27607]: info: Discovery: adding a135e40e-a404-457b-98f5-36bf71c75954 Jan 10 19:10:48 volumio volumio[27607]: info: Discovery: Found device Volumio Jan 10 19:10:48 volumio volumio[27607]: info: CoreCommandRouter::volumioGetState Jan 10 19:10:48 volumio volumio[27607]: info: CorePlayQueue::getTrack 0 Jan 10 19:10:48 volumio volumio[27607]: info: Discovery: this is already registered, a135e40e-a404-457b-98f5-36bf71c75954 Jan 10 19:10:48 volumio volumio[27607]: info: Discovery: Found device Volumio Jan 10 19:10:48 volumio volumio[27607]: info: CoreCommandRouter::volumioGetState Jan 10 19:10:48 volumio volumio[27607]: info: CorePlayQueue::getTrack 0 Jan 10 19:10:48 volumio sudo[27931]: pam_unix(sudo:session): session closed for user root Jan 10 19:10:48 volumio volumio[27607]: info: The plugin peppyspectrum has an ALSA contribution file peppy_in.peppy_out.6.conf Jan 10 19:10:48 volumio volumio[27607]: info: Reading ALSA contributions from plugins. Jan 10 19:10:48 volumio volumio[27607]: info: Upmpdcli Daemon Started Jan 10 19:10:48 volumio volumio[27607]: info: Asound.conf file unchanged, so no further update is needed Jan 10 19:10:48 volumio volumio[27607]: info: Output device has changed, restarting MPD Jan 10 19:10:48 volumio volumio[27607]: info: Output device has changed, restarting Shairport Sync Jan 10 19:10:48 volumio volumio[27607]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:10:48 volumio volumio[27607]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 19:10:48 volumio sudo[27934]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 10 19:10:48 volumio sudo[27934]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 19:10:48 volumio sudo[27934]: pam_unix(sudo:session): session closed for user root Jan 10 19:10:48 volumio sudo[27936]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 10 19:10:48 volumio sudo[27936]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 19:10:48 volumio volumio[27607]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 10 19:10:48 volumio volumio[27607]: info: ___________ START PLUGINS ___________ Jan 10 19:10:48 volumio volumio[27607]: info: ControllerMpd::onStart: Initializing MPD Jan 10 19:10:48 volumio volumio[27607]: info: Creating MPD Configuration file Jan 10 19:10:48 volumio volumio[27607]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 10 19:10:48 volumio volumio[27607]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 10 19:10:48 volumio volumio[27607]: info: [1768093848182] CoreMusicLibrary::Adding element Media Servers Jan 10 19:10:48 volumio volumio[27607]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 10 19:10:48 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Jan 10 19:10:48 volumio sudo[27944]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 10 19:10:48 volumio sudo[27944]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 19:10:48 volumio volumio[27607]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:10:48 volumio volumio[27607]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 19:10:48 volumio sudo[27946]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 10 19:10:48 volumio sudo[27946]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 19:10:48 volumio sudo[27944]: pam_unix(sudo:session): session closed for user root Jan 10 19:10:48 volumio volumio[27607]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 10 19:10:48 volumio volumio[27607]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:10:48 volumio volumio[27607]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 19:10:48 volumio volumio[27607]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 10 19:10:48 volumio volumio[27607]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 10 19:10:48 volumio systemd[1]: mpd.service: Deactivated successfully. Jan 10 19:10:48 volumio volumio[27607]: info: [1768093848355] CoreMusicLibrary::Adding element Last_100 Jan 10 19:10:48 volumio volumio[27607]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 10 19:10:48 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Jan 10 19:10:48 volumio systemd[1]: mpd.service: Consumed 5.931s CPU time. Jan 10 19:10:48 volumio systemd[1]: mpd.socket: Deactivated successfully. Jan 10 19:10:48 volumio volumio[27607]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 10 19:10:48 volumio volumio[27607]: info: [1768093848367] CoreMusicLibrary::Adding element Webradio Jan 10 19:10:48 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jan 10 19:10:48 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jan 10 19:10:48 volumio volumio[27607]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 10 19:10:48 volumio volumio[27607]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 10 19:10:48 volumio volumio[27607]: info: Initializing BBC Radios Jan 10 19:10:48 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jan 10 19:10:48 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Jan 10 19:10:48 volumio volumio[27607]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 10 19:10:48 volumio volumio[27607]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 19:10:48 volumio volumio[27607]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 10 19:10:48 volumio volumio[27607]: info: [1768093848497] CoreMusicLibrary::Adding element Bandcamp Discover Jan 10 19:10:48 volumio volumio[27607]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 10 19:10:48 volumio volumio[27607]: Cannot find translation for source Bandcamp Discover Jan 10 19:10:48 volumio volumio[27607]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 10 19:10:48 volumio volumio[27607]: info: [1768093848528] CoreMusicLibrary::Adding element SoundCloud Jan 10 19:10:48 volumio volumio[27607]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 10 19:10:48 volumio volumio[27607]: Cannot find translation for source Bandcamp Discover Jan 10 19:10:48 volumio volumio[27607]: Cannot find translation for source SoundCloud Jan 10 19:10:48 volumio volumio[27607]: info: Creating Spotify config file Jan 10 19:10:48 volumio volumio[27607]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:10:48 volumio sudo[27966]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jan 10 19:10:48 volumio sudo[27966]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Jan 10 19:10:48 volumio sudo[27966]: pam_unix(sudo:session): session closed for user root Jan 10 19:10:49 volumio volumio[27607]: info: [squeezelite_mc] Starting proxy server... Jan 10 19:10:49 volumio volumio[27607]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 10 19:10:49 volumio volumio[27607]: info: [1768093849209] CoreMusicLibrary::Adding element YouTube2 Jan 10 19:10:49 volumio volumio[27607]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 10 19:10:49 volumio volumio[27607]: Cannot find translation for source Bandcamp Discover Jan 10 19:10:49 volumio volumio[27607]: Cannot find translation for source SoundCloud Jan 10 19:10:49 volumio volumio[27607]: Cannot find translation for source YouTube2 Jan 10 19:10:49 volumio volumio[27607]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 10 19:10:49 volumio volumio[27607]: info: [1768093849240] CoreMusicLibrary::Adding element YouTube Music Jan 10 19:10:49 volumio volumio[27607]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 10 19:10:49 volumio volumio[27607]: Cannot find translation for source Bandcamp Discover Jan 10 19:10:49 volumio volumio[27607]: Cannot find translation for source SoundCloud Jan 10 19:10:49 volumio volumio[27607]: Cannot find translation for source YouTube2 Jan 10 19:10:49 volumio volumio[27607]: Cannot find translation for source YouTube Music Jan 10 19:10:49 volumio volumio[27607]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 10 19:10:49 volumio volumio[27607]: info: [1768093849259] CoreMusicLibrary::Adding element Podcast Jan 10 19:10:49 volumio volumio[27607]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 10 19:10:49 volumio volumio[27607]: Cannot find translation for source Bandcamp Discover Jan 10 19:10:49 volumio volumio[27607]: Cannot find translation for source SoundCloud Jan 10 19:10:49 volumio volumio[27607]: Cannot find translation for source YouTube2 Jan 10 19:10:49 volumio volumio[27607]: Cannot find translation for source YouTube Music Jan 10 19:10:49 volumio volumio[27607]: Cannot find translation for source Podcast Jan 10 19:10:49 volumio volumio[27607]: info: Loading i18n strings for locale en Jan 10 19:10:49 volumio volumio[27607]: info: Plugin peppyspectrum has duplicated i18n key SAVE. It is ignored. Jan 10 19:10:49 volumio volumio[27607]: Updating browse sources language Jan 10 19:10:49 volumio volumio[27607]: Cannot find translation for source Bandcamp Discover Jan 10 19:10:49 volumio volumio[27607]: Cannot find translation for source SoundCloud Jan 10 19:10:49 volumio volumio[27607]: Cannot find translation for source YouTube2 Jan 10 19:10:49 volumio volumio[27607]: Cannot find translation for source YouTube Music Jan 10 19:10:49 volumio volumio[27607]: Cannot find translation for source Podcast Jan 10 19:10:49 volumio volumio[27607]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 10 19:10:49 volumio volumio[27607]: Cannot find translation for source Bandcamp Discover Jan 10 19:10:49 volumio volumio[27607]: Cannot find translation for source SoundCloud Jan 10 19:10:49 volumio volumio[27607]: Cannot find translation for source YouTube2 Jan 10 19:10:49 volumio volumio[27607]: Cannot find translation for source YouTube Music Jan 10 19:10:49 volumio volumio[27607]: Cannot find translation for source Podcast Jan 10 19:10:49 volumio volumio[27607]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 10 19:10:49 volumio volumio[27607]: info: [1768093849341] CoreMusicLibrary::Adding element Volusonic Jan 10 19:10:49 volumio volumio[27607]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 10 19:10:49 volumio volumio[27607]: Cannot find translation for source Bandcamp Discover Jan 10 19:10:49 volumio volumio[27607]: Cannot find translation for source SoundCloud Jan 10 19:10:49 volumio volumio[27607]: Cannot find translation for source YouTube2 Jan 10 19:10:49 volumio volumio[27607]: Cannot find translation for source YouTube Music Jan 10 19:10:49 volumio volumio[27607]: Cannot find translation for source Podcast Jan 10 19:10:49 volumio volumio[27607]: Cannot find translation for source Volusonic Jan 10 19:10:49 volumio volumio[27607]: info: Scheduling reboots with hours: 0, minutes: 0 in timezone: America/Chicago Jan 10 19:10:49 volumio volumio[27607]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , updateALSAConfigFile Jan 10 19:10:49 volumio volumio[27607]: info: Volumio Calling Home Jan 10 19:10:49 volumio volumio[27607]: info: [squeezelite_mc] Proxy server started on port 43483 Jan 10 19:10:49 volumio volumio[27607]: info: Preparing to generate the ALSA configuration file Jan 10 19:10:49 volumio volumio[27607]: info: CoreCommandRouter::volumioRetrievevolume Jan 10 19:10:49 volumio volumio[27607]: info: The plugin peppyspectrum has an ALSA contribution file peppy_in.peppy_out.6.conf Jan 10 19:10:49 volumio volumio[27607]: info: Reading ALSA contributions from plugins. Jan 10 19:10:49 volumio volumio[27607]: info: MPD Permissions set Jan 10 19:10:49 volumio volumio[27607]: info: MPD Permissions set Jan 10 19:10:49 volumio volumio[27607]: info: Spotify config file written Jan 10 19:10:49 volumio sudo[27980]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jan 10 19:10:49 volumio sudo[27980]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 19:10:50 volumio volumio[27607]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Jan 10 19:10:50 volumio volumio[27607]: info: Volumio called home Jan 10 19:10:50 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 10 19:10:50 volumio volumio[27607]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:10:50 volumio volumio[27607]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:10:50 volumio volumio[27607]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:10:50 volumio volumio[27607]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:10:50 volumio volumio[27607]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:10:50 volumio volumio[27607]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:10:50 volumio volumio[27607]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:10:50 volumio volumio[27607]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:10:50 volumio volumio[27607]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 19:10:50 volumio volumio[27607]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:10:50 volumio volumio[27607]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:10:50 volumio volumio[27607]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:10:50 volumio volumio[27607]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:10:50 volumio volumio[27607]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:10:50 volumio volumio[27607]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:10:50 volumio volumio[27607]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:10:50 volumio volumio[27607]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:10:50 volumio volumio[27607]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:10:50 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 10 19:10:50 volumio go-librespot[27982]: go-librespot daemon starting... Jan 10 19:10:50 volumio volumio[27607]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 19:10:50 volumio sudo[27980]: pam_unix(sudo:session): session closed for user root Jan 10 19:10:50 volumio volumio[27607]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:10:50 volumio volumio[27607]: info: No need to fix Spotify hosts Jan 10 19:10:50 volumio go-librespot[27992]: time="2026-01-10T19:10:50-06:00" level=info msg="running go-librespot 0.4.0" Jan 10 19:10:50 volumio go-librespot[27992]: time="2026-01-10T19:10:50-06:00" level=debug msg="app state loaded" Jan 10 19:10:50 volumio go-librespot[27992]: time="2026-01-10T19:10:50-06:00" level=debug msg="stored credentials not found" Jan 10 19:10:50 volumio go-librespot[27992]: time="2026-01-10T19:10:50-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 10 19:10:50 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.118.241 Jan 10 19:10:50 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Jan 10 19:10:50 volumio avahi-daemon[664]: Registering new address record for 169.254.118.241 on eth0.IPv4. Jan 10 19:10:50 volumio volumio[27607]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Jan 10 19:10:50 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 19:10:50 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 10 19:10:50 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 19:10:50 volumio volumio[27607]: info: VolumeController:: Volume=100 Mute =false Jan 10 19:10:50 volumio volumio[27607]: info: CoreStateMachine::pushState Jan 10 19:10:50 volumio volumio[27607]: info: CorePlayQueue::getTrack 0 Jan 10 19:10:50 volumio volumio[27607]: info: CoreCommandRouter::volumioPushState Jan 10 19:10:50 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.118.241 Jan 10 19:10:50 volumio volumio[27607]: info: [squeezelite_mc] Server discovery started Jan 10 19:10:50 volumio volumio[27607]: info: [squeezelite_mc] Player finder started Jan 10 19:10:50 volumio volumio[27607]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:10:50 volumio volumio[27607]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:10:50 volumio volumio[27607]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:10:50 volumio volumio[27607]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 10 19:10:50 volumio volumio[27607]: info: [squeezelite_mc] Executing aplay -D hw:1 --nonblock -f MPEG /dev/zero 2>&1 || true Jan 10 19:10:50 volumio go-librespot[27992]: time="2026-01-10T19:10:50-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Jan 10 19:10:50 volumio go-librespot[27992]: time="2026-01-10T19:10:50-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Jan 10 19:10:50 volumio go-librespot[27992]: time="2026-01-10T19:10:50-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Jan 10 19:10:50 volumio go-librespot[27992]: time="2026-01-10T19:10:50-06:00" level=info msg="zeroconf server listening on port 44375" Jan 10 19:10:50 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.118.241 Jan 10 19:10:50 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.118.241 Jan 10 19:10:50 volumio avahi-daemon[664]: Withdrawing address record for 169.254.118.241 on eth0. Jan 10 19:10:50 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Jan 10 19:10:50 volumio volumio[27607]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jan 10 19:10:50 volumio volumio[27607]: SPOTIFY: BQAvE4WeAkpHcEcQoql20sJKvpDNCUwCDNAsBJvKNlBYwFdKzPiSN3bsNSK_Ot2VmgB7M0xHcmUgTt28Gr_Ufty77DYjKPYvHxsuKwH6fT8DxJgJh_iQkX50rXrHVbQLWHnJg5KWQWZy-8ryZvSf4pE7YmmQk8BTgvWVBL-_2dJXPw4ng92WL-F3KZEhtggJuFa5p_2lWmGwrfmjsiEy85HRtwXQSHbVQCCd9Zw Jan 10 19:10:50 volumio volumio[27607]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jan 10 19:10:50 volumio volumio[27607]: info: New Spotify access token = BQAvE4WeAkpHcEcQoql20sJKvpDNCUwCDNAsBJvKNlBYwFdKzPiSN3bsNSK_Ot2VmgB7M0xHcmUgTt28Gr_Ufty77DYjKPYvHxsuKwH6fT8DxJgJh_iQkX50rXrHVbQLWHnJg5KWQWZy-8ryZvSf4pE7YmmQk8BTgvWVBL-_2dJXPw4ng92WL-F3KZEhtggJuFa5p_2lWmGwrfmjsiEy85HRtwXQSHbVQCCd9Zw Jan 10 19:10:50 volumio volumio[27607]: info: Spotify credentials grant success - running version from March 24, 2019 Jan 10 19:10:50 volumio volumio[27607]: info: [squeezelite_mc] Card 1 supports the following ALSA formats: ["U8","S16_LE"] Jan 10 19:10:50 volumio volumio[27607]: info: [squeezelite_mc] Starting Squeezelite service with params: {"type":"basic","playerName":"volumio","dsdFormat":null,"card":"1","mixerType":"Hardware","mixer":"PCM"} Jan 10 19:10:50 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 19:10:50 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 10 19:10:50 volumio volumio[27607]: info: [squeezelite_mc] Executing cp /data/plugins/music_service/squeezelite_mc/dist/lib/../templates/alsa/100-squeezelite.conf.template.out /etc/alsa/conf.d/100-squeezelite.conf Jan 10 19:10:50 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 19:10:50 volumio go-librespot[27992]: time="2026-01-10T19:10:50-06:00" level=debug msg="obtained new client token: AADztR/itGeUBs6LVl+MTKBViRuvuKE3Ot2TbSXlG+9IFxSeQ/BIAv6H9IGjIOcnPEE6hs7mKO6WgGob6CpZXFz23taobX4+X3lRAzAlli2+aK/LPNN3VUgnXxF9+z0b1v3wyccl/AvfB7DsjE2IyApN9EF0oRy6Arii0/owWk6GS4sLQ4asccpJEX3/mklE2TH2XIZItxKXQhXYmVLbG5nn2Zp8+Pjq7q9KQdFRJu+XxGXWiplzHLdhJA==" Jan 10 19:10:50 volumio volumio[27607]: info: Starting Shairport Sync Jan 10 19:10:51 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Jan 10 19:10:51 volumio volumio[27607]: info: Starting Shairport Sync Jan 10 19:10:51 volumio volumio[27607]: info: Starting Shairport Sync Jan 10 19:10:51 volumio sudo[28040]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 10 19:10:51 volumio go-librespot[27992]: time="2026-01-10T19:10:51-06: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" Jan 10 19:10:51 volumio sudo[28040]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 19:10:51 volumio sudo[28043]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 10 19:10:51 volumio go-librespot[27992]: time="2026-01-10T19:10:51-06:00" level=debug msg="connected to ap-guc3.spotify.com:443" Jan 10 19:10:51 volumio sudo[28043]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 19:10:51 volumio sudo[28044]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 10 19:10:51 volumio sudo[28044]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 19:10:51 volumio go-librespot[27992]: time="2026-01-10T19:10:51-06:00" level=debug msg="completed keyexchange" Jan 10 19:10:51 volumio go-librespot[27992]: time="2026-01-10T19:10:51-06:00" level=debug msg="completed challenge" Jan 10 19:10:51 volumio go-librespot[27992]: time="2026-01-10T19:10:51-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Jan 10 19:10:51 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jan 10 19:10:51 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Jan 10 19:10:51 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 10 19:10:51 volumio systemd[1]: shairport-sync.service: Consumed 2.012s CPU time. Jan 10 19:10:51 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 10 19:10:51 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 10 19:10:51 volumio volumio[27607]: info: Asound.conf file unchanged, so no further update is needed Jan 10 19:10:51 volumio volumio[27607]: info: Output device has changed, restarting MPD Jan 10 19:10:51 volumio sudo[28037]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/cp /data/plugins/music_service/squeezelite_mc/dist/lib/../templates/alsa/100-squeezelite.conf.template.out /etc/alsa/conf.d/100-squeezelite.conf Jan 10 19:10:51 volumio sudo[28037]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 19:10:51 volumio sudo[28037]: pam_unix(sudo:session): session closed for user root Jan 10 19:10:51 volumio volumio[27607]: info: Output device has changed, restarting Shairport Sync Jan 10 19:10:51 volumio volumio[27607]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:10:51 volumio volumio[27607]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 19:10:51 volumio sudo[28064]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 10 19:10:51 volumio sudo[28064]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 19:10:51 volumio sudo[28064]: pam_unix(sudo:session): session closed for user root Jan 10 19:10:51 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 10 19:10:51 volumio sudo[28040]: pam_unix(sudo:session): session closed for user root Jan 10 19:10:51 volumio sudo[28043]: pam_unix(sudo:session): session closed for user root Jan 10 19:10:51 volumio sudo[28067]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 10 19:10:51 volumio sudo[28067]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 19:10:51 volumio volumio[27607]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 10 19:10:51 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jan 10 19:10:51 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Jan 10 19:10:51 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 10 19:10:51 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 10 19:10:51 volumio sudo[28044]: pam_unix(sudo:session): session closed for user root Jan 10 19:10:51 volumio systemd[1]: mpd.service: Deactivated successfully. Jan 10 19:10:51 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Jan 10 19:10:51 volumio systemd[1]: mpd.service: Consumed 3.038s CPU time. Jan 10 19:10:51 volumio systemd[1]: mpd.socket: Deactivated successfully. Jan 10 19:10:51 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jan 10 19:10:51 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jan 10 19:10:51 volumio volumio[27607]: info: MPD Permissions set Jan 10 19:10:51 volumio volumio[27607]: info: Shairport-Sync Started Jan 10 19:10:51 volumio volumio[27607]: Error adding Membership: Error: addMembership EINVAL Jan 10 19:10:51 volumio volumio[27607]: info: Shairport-Sync Started Jan 10 19:10:51 volumio volumio[27607]: info: [squeezelite_mc] Executing alsactl -L -R nrestore Jan 10 19:10:51 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jan 10 19:10:51 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Jan 10 19:10:51 volumio sudo[28092]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/sbin/alsactl -L -R nrestore Jan 10 19:10:51 volumio sudo[28092]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 19:10:51 volumio sudo[28092]: pam_unix(sudo:session): session closed for user root Jan 10 19:10:51 volumio volumio[27607]: info: Shairport-Sync Started Jan 10 19:10:51 volumio volumio[27607]: info: [squeezelite_mc] Executing cp /data/plugins/music_service/squeezelite_mc/dist/lib/../templates/systemd/squeezelite.service.template.out /etc/systemd/system/squeezelite.service Jan 10 19:10:51 volumio volumio[27607]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:10:51 volumio volumio[27607]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:10:51 volumio volumio[27607]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:10:51 volumio volumio[27607]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:10:51 volumio volumio[27607]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:10:51 volumio volumio[27607]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:10:51 volumio volumio[27607]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:10:51 volumio volumio[27607]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:10:52 volumio volumio[27607]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 19:10:52 volumio volumio[27607]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:10:52 volumio sudo[28081]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jan 10 19:10:52 volumio sudo[28081]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Jan 10 19:10:52 volumio sudo[28081]: pam_unix(sudo:session): session closed for user root Jan 10 19:10:52 volumio sudo[28101]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/cp /data/plugins/music_service/squeezelite_mc/dist/lib/../templates/systemd/squeezelite.service.template.out /etc/systemd/system/squeezelite.service Jan 10 19:10:52 volumio sudo[28101]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 19:10:52 volumio sudo[28101]: pam_unix(sudo:session): session closed for user root Jan 10 19:10:52 volumio volumio[27607]: info: CoreCommandRouter::volumioGetState Jan 10 19:10:52 volumio volumio[27607]: info: CorePlayQueue::getTrack 0 Jan 10 19:10:52 volumio volumio[27607]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl daemon-reload || true Jan 10 19:10:52 volumio volumio[27607]: info: Starting Shairport Sync Jan 10 19:10:52 volumio volumio[27607]: SPOTIFY: User informations: {"display_name":"Clint Smith","external_urls":{"spotify":"https://open.spotify.com/user/clintsmith1"},"followers":{"href":null,"total":7},"href":"https://api.spotify.com/v1/users/clintsmith1","id":"clintsmith1","images":[{"height":300,"url":"https://i.scdn.co/image/ab6775700000ee856520409d25d9cc210472a0fd","width":300},{"height":64,"url":"https://i.scdn.co/image/ab67757000003b826520409d25d9cc210472a0fd","width":64}],"type":"user","uri":"spotify:user:clintsmith1"} Jan 10 19:10:52 volumio volumio[27607]: info: Spotify Successfully logged in Jan 10 19:10:52 volumio volumio[27607]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 10 19:10:52 volumio volumio[27607]: info: [1768093852184] CoreMusicLibrary::Adding element Spotify Jan 10 19:10:52 volumio volumio[27607]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 10 19:10:52 volumio volumio[27607]: Cannot find translation for source Bandcamp Discover Jan 10 19:10:52 volumio volumio[27607]: Cannot find translation for source SoundCloud Jan 10 19:10:52 volumio volumio[27607]: Cannot find translation for source YouTube2 Jan 10 19:10:52 volumio volumio[27607]: Cannot find translation for source YouTube Music Jan 10 19:10:52 volumio volumio[27607]: Cannot find translation for source Podcast Jan 10 19:10:52 volumio volumio[27607]: Cannot find translation for source Volusonic Jan 10 19:10:52 volumio volumio[27607]: Cannot find translation for source Spotify Jan 10 19:10:52 volumio sudo[28111]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl daemon-reload Jan 10 19:10:52 volumio sudo[28111]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 19:10:52 volumio sudo[28113]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 10 19:10:52 volumio sudo[28113]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 19:10:52 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jan 10 19:10:52 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Jan 10 19:10:52 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 10 19:10:52 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 10 19:10:52 volumio sudo[28113]: pam_unix(sudo:session): session closed for user root Jan 10 19:10:52 volumio systemd[1]: Reloading. Jan 10 19:10:52 volumio volumio[27607]: info: Shairport-Sync Started Jan 10 19:10:53 volumio volumio[27607]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:10:53 volumio volumio[27607]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:10:53 volumio volumio[27607]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:10:53 volumio volumio[27607]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 10 19:10:53 volumio volumio[27607]: info: go-librespot daemon successfully initialized Jan 10 19:10:55 volumio systemd[1]: /lib/systemd/system/go-librespot-daemon.service:9: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Jan 10 19:10:55 volumio systemd[1]: /lib/systemd/system/go-librespot-daemon.service:10: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Jan 10 19:10:55 volumio sudo[28111]: pam_unix(sudo:session): session closed for user root Jan 10 19:10:55 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 18. Jan 10 19:10:55 volumio volumio[27607]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Jan 10 19:10:55 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 10 19:10:55 volumio sudo[28149]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Jan 10 19:10:55 volumio sudo[28149]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 19:10:55 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.191.124 Jan 10 19:10:55 volumio avahi-daemon[664]: Registering new address record for 169.254.191.124 on eth0.IPv4. Jan 10 19:10:55 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Jan 10 19:10:55 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 10 19:10:55 volumio go-librespot[28150]: go-librespot daemon starting... Jan 10 19:10:55 volumio go-librespot[28167]: time="2026-01-10T19:10:55-06:00" level=info msg="running go-librespot 0.4.0" Jan 10 19:10:55 volumio go-librespot[28167]: time="2026-01-10T19:10:55-06:00" level=debug msg="app state loaded" Jan 10 19:10:55 volumio go-librespot[28167]: time="2026-01-10T19:10:55-06:00" level=debug msg="stored credentials not found" Jan 10 19:10:55 volumio go-librespot[28167]: time="2026-01-10T19:10:55-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 10 19:10:55 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 19:10:55 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 10 19:10:55 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 19:10:55 volumio sudo[28149]: pam_unix(sudo:session): session closed for user root Jan 10 19:10:55 volumio volumio[27607]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl stop squeezelite || true Jan 10 19:10:55 volumio sudo[28175]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop squeezelite Jan 10 19:10:55 volumio sudo[28175]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 19:10:56 volumio systemd[1]: Stopping squeezelite.service - Squeezelite lightweight headless Squeezebox emulator... Jan 10 19:10:56 volumio systemd[1]: squeezelite.service: Deactivated successfully. Jan 10 19:10:56 volumio systemd[1]: Stopped squeezelite.service - Squeezelite lightweight headless Squeezebox emulator. Jan 10 19:10:56 volumio sudo[28175]: pam_unix(sudo:session): session closed for user root Jan 10 19:10:56 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.191.124 Jan 10 19:10:56 volumio go-librespot[28167]: time="2026-01-10T19:10:56-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Jan 10 19:10:56 volumio go-librespot[28167]: time="2026-01-10T19:10:56-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Jan 10 19:10:56 volumio go-librespot[28167]: time="2026-01-10T19:10:56-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Jan 10 19:10:56 volumio go-librespot[28167]: time="2026-01-10T19:10:56-06:00" level=info msg="zeroconf server listening on port 41703" Jan 10 19:10:56 volumio go-librespot[28167]: time="2026-01-10T19:10:56-06:00" level=debug msg="obtained new client token: AADXkmqXXlAN3x8HJfMP2/lnX0L1k1e9/QKhnO2FZ1CH3dZoogVcm08LTdx7a+F3x+kWsP6+1a+wV8l0CRPgpq9iPOlfNT/lZjSpsgx7ZbJAJs/Mk68DN33bI+g137pmQMHbOSBcVnniLWHo1iElmXyKOvvLt+bZNKCRmDIKh8iOa9c7l3Zq+but/rA+IBZDSKnUw+qUBl/VIA/LwuE8rcXMFfLPIIRhBQtPVXizuknp0g40ZkPr+faBJw==" Jan 10 19:10:56 volumio go-librespot[28167]: time="2026-01-10T19:10:56-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 10 19:10:56 volumio go-librespot[28167]: time="2026-01-10T19:10:56-06:00" level=debug msg="completed keyexchange" Jan 10 19:10:56 volumio go-librespot[28167]: time="2026-01-10T19:10:56-06:00" level=debug msg="completed challenge" Jan 10 19:10:56 volumio go-librespot[28167]: time="2026-01-10T19:10:56-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Jan 10 19:10:56 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.191.124 Jan 10 19:10:56 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.191.124 Jan 10 19:10:56 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Jan 10 19:10:56 volumio avahi-daemon[664]: Withdrawing address record for 169.254.191.124 on eth0. Jan 10 19:10:56 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 10 19:10:56 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 10 19:10:56 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 19:10:56 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 10 19:10:56 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 19:10:56 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Jan 10 19:10:56 volumio volumio[27607]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Jan 10 19:10:56 volumio volumio[27607]: info: Initializing connection to go-librespot Websocket Jan 10 19:10:56 volumio volumio[27607]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 10 19:10:56 volumio sudo[28195]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Jan 10 19:10:56 volumio sudo[28195]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 19:10:56 volumio sudo[28195]: pam_unix(sudo:session): session closed for user root Jan 10 19:10:56 volumio volumio[27607]: info: [squeezelite_mc] Executing rm /tmp/squeezelite.log Jan 10 19:10:56 volumio sudo[28199]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/rm /tmp/squeezelite.log Jan 10 19:10:56 volumio sudo[28199]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 19:10:56 volumio sudo[28199]: pam_unix(sudo:session): session closed for user root Jan 10 19:10:56 volumio volumio[27607]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl start squeezelite || true Jan 10 19:10:56 volumio sudo[28202]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start squeezelite Jan 10 19:10:56 volumio sudo[28202]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 19:10:57 volumio systemd[1]: Starting squeezelite.service - Squeezelite lightweight headless Squeezebox emulator... Jan 10 19:10:57 volumio systemd[1]: Started squeezelite.service - Squeezelite lightweight headless Squeezebox emulator. Jan 10 19:10:57 volumio sudo[28202]: pam_unix(sudo:session): session closed for user root Jan 10 19:10:57 volumio mpd[28109]: 2026-01-10T19:10:57 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jan 10 19:10:57 volumio systemd[1]: Started mpd.service - Music Player Daemon. Jan 10 19:10:57 volumio sudo[28067]: pam_unix(sudo:session): session closed for user root Jan 10 19:10:57 volumio sudo[27936]: pam_unix(sudo:session): session closed for user root Jan 10 19:10:57 volumio sudo[27946]: pam_unix(sudo:session): session closed for user root Jan 10 19:10:57 volumio volumio[27607]: error: MPD error: The expression evaluated to a falsy value: Jan 10 19:10:57 volumio volumio[27607]: assert.ok(self.idling) Jan 10 19:10:57 volumio volumio[27607]: error: The expression evaluated to a falsy value: Jan 10 19:10:57 volumio volumio[27607]: assert.ok(self.idling) Jan 10 19:10:57 volumio volumio[27607]: error: MPD error: The expression evaluated to a falsy value: Jan 10 19:10:57 volumio volumio[27607]: assert.ok(self.idling) Jan 10 19:10:57 volumio volumio[27607]: error: The expression evaluated to a falsy value: Jan 10 19:10:57 volumio volumio[27607]: assert.ok(self.idling) Jan 10 19:10:57 volumio volumio[27607]: info: MPD running with PID28109 Jan 10 19:10:57 volumio volumio[27607]: ,establishing connection Jan 10 19:10:57 volumio volumio[27607]: error: updateQueue error: null Jan 10 19:10:57 volumio volumio[27607]: error: updateQueue error: null Jan 10 19:10:57 volumio volumio[27607]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Jan 10 19:10:57 volumio sudo[28213]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Jan 10 19:10:57 volumio sudo[28213]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 19:10:57 volumio sudo[28213]: pam_unix(sudo:session): session closed for user root Jan 10 19:10:58 volumio volumio[27607]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Jan 10 19:10:58 volumio sudo[28216]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Jan 10 19:10:58 volumio sudo[28216]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 19:10:58 volumio sudo[28216]: pam_unix(sudo:session): session closed for user root Jan 10 19:10:58 volumio volumio[27607]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Jan 10 19:10:58 volumio sudo[28219]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Jan 10 19:10:58 volumio sudo[28219]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 19:10:58 volumio sudo[28219]: pam_unix(sudo:session): session closed for user root Jan 10 19:10:59 volumio kernel: hwmon hwmon1: Voltage normalised Jan 10 19:10:59 volumio volumio[27607]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Jan 10 19:10:59 volumio sudo[28223]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Jan 10 19:10:59 volumio sudo[28223]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 19:10:59 volumio sudo[28223]: pam_unix(sudo:session): session closed for user root Jan 10 19:10:59 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 19. Jan 10 19:10:59 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 10 19:10:59 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 10 19:10:59 volumio go-librespot[28225]: go-librespot daemon starting... Jan 10 19:10:59 volumio go-librespot[28226]: time="2026-01-10T19:10:59-06:00" level=info msg="running go-librespot 0.4.0" Jan 10 19:10:59 volumio go-librespot[28226]: time="2026-01-10T19:10:59-06:00" level=debug msg="app state loaded" Jan 10 19:10:59 volumio go-librespot[28226]: time="2026-01-10T19:10:59-06:00" level=debug msg="stored credentials not found" Jan 10 19:10:59 volumio go-librespot[28226]: time="2026-01-10T19:10:59-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 10 19:10:59 volumio volumio[27607]: info: Initializing connection to go-librespot Websocket Jan 10 19:10:59 volumio go-librespot[28226]: time="2026-01-10T19:10:59-06:00" level=debug msg="new websocket client" Jan 10 19:10:59 volumio volumio[27607]: info: Connection to go-librespot Websocket established Jan 10 19:10:59 volumio volumio[27607]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Jan 10 19:10:59 volumio go-librespot[28226]: time="2026-01-10T19:10:59-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 10 19:10:59 volumio go-librespot[28226]: time="2026-01-10T19:10:59-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 10 19:10:59 volumio go-librespot[28226]: time="2026-01-10T19:10:59-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 10 19:10:59 volumio go-librespot[28226]: time="2026-01-10T19:10:59-06:00" level=info msg="zeroconf server listening on port 45001" Jan 10 19:11:00 volumio sudo[28234]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Jan 10 19:11:00 volumio sudo[28234]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 19:11:00 volumio sudo[28234]: pam_unix(sudo:session): session closed for user root Jan 10 19:11:00 volumio volumio[27607]: info: Completed starting Core Plugins Jan 10 19:11:00 volumio volumio[27607]: info: ------------------------------------------- Jan 10 19:11:00 volumio volumio[27607]: info: ----- MyVolumio plugins startup ---- Jan 10 19:11:00 volumio volumio[27607]: info: ------------------------------------------- Jan 10 19:11:00 volumio volumio[27607]: info: [MyVolumio PluginManager] Fetching plans data.... Jan 10 19:11:00 volumio go-librespot[28226]: time="2026-01-10T19:11:00-06:00" level=debug msg="obtained new client token: AAAOfQe7R+H1yvBfxytuqYGaAR1273+IC9iQZZlcT/YU0+x82gCFkUcsM3QgVrUgtib22lXhUsNTHOWWb6+cSRbJ8q4hVBREBAHrSDD3oPw3Plaw/vWhfT3vy477+cNpkNXEJ4xK9zwB0QU3GdeICwTQmujnX5yxLG4nbGjqcJ5k/fpopkeY3eemrK76lQzpEqD1fYX2LlII24i2MpSkfvrYrF1yNKj2Nl5Z5s2TdKlkH84XaKo9QuE=" Jan 10 19:11:00 volumio go-librespot[28226]: time="2026-01-10T19:11:00-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 10 19:11:00 volumio go-librespot[28226]: time="2026-01-10T19:11:00-06:00" level=debug msg="completed keyexchange" Jan 10 19:11:00 volumio go-librespot[28226]: time="2026-01-10T19:11:00-06:00" level=debug msg="completed challenge" Jan 10 19:11:00 volumio go-librespot[28226]: time="2026-01-10T19:11:00-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Jan 10 19:11:00 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 10 19:11:00 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 10 19:11:00 volumio volumio[27607]: info: Connection to go-librespot Websocket closed Jan 10 19:11:00 volumio sudo[28237]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Jan 10 19:11:00 volumio sudo[28237]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 19:11:00 volumio sudo[28239]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Jan 10 19:11:00 volumio sudo[28239]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 19:11:00 volumio sudo[28241]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Jan 10 19:11:00 volumio sudo[28241]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 19:11:00 volumio systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Jan 10 19:11:00 volumio systemd[1]: mpd_monitor.service: Deactivated successfully. Jan 10 19:11:00 volumio systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Jan 10 19:11:00 volumio systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Jan 10 19:11:00 volumio sudo[28239]: pam_unix(sudo:session): session closed for user root Jan 10 19:11:00 volumio sudo[28241]: pam_unix(sudo:session): session closed for user root Jan 10 19:11:00 volumio volumio[27607]: info: Successfully started MPD Monitor Jan 10 19:11:00 volumio sudo[28237]: pam_unix(sudo:session): session closed for user root Jan 10 19:11:00 volumio mpd_monitor.sh[28245]: MPD Monitor Service: Starting MPD Monitor Service Jan 10 19:11:00 volumio volumio[27607]: info: Successfully started MPD Monitor Jan 10 19:11:00 volumio volumio[27607]: info: Successfully started MPD Monitor Jan 10 19:11:01 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.113.14 Jan 10 19:11:01 volumio avahi-daemon[664]: Registering new address record for 169.254.113.14 on eth0.IPv4. Jan 10 19:11:01 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Jan 10 19:11:01 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.113.14 Jan 10 19:11:01 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 19:11:01 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 10 19:11:01 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 19:11:02 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.113.14 Jan 10 19:11:02 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.113.14 Jan 10 19:11:02 volumio avahi-daemon[664]: Withdrawing address record for 169.254.113.14 on eth0. Jan 10 19:11:02 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Jan 10 19:11:02 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Jan 10 19:11:02 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 19:11:02 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 10 19:11:02 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 19:11:02 volumio volumio[27607]: info: Getting Spotify volume Jan 10 19:11:02 volumio volumio[27607]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 10 19:11:02 volumio volumio[27607]: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 10 19:11:02 volumio volumio[27607]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Jan 10 19:11:02 volumio volumio[27607]: errno: -111, Jan 10 19:11:02 volumio volumio[27607]: code: 'ECONNREFUSED', Jan 10 19:11:02 volumio volumio[27607]: syscall: 'connect', Jan 10 19:11:02 volumio volumio[27607]: address: '127.0.0.1', Jan 10 19:11:02 volumio volumio[27607]: port: 9879, Jan 10 19:11:02 volumio volumio[27607]: response: undefined Jan 10 19:11:02 volumio volumio[27607]: } Jan 10 19:11:02 volumio volumio[27607]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 10 19:11:03 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 20. Jan 10 19:11:03 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 10 19:11:03 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 10 19:11:03 volumio go-librespot[28307]: go-librespot daemon starting... Jan 10 19:11:03 volumio go-librespot[28308]: time="2026-01-10T19:11:03-06:00" level=info msg="running go-librespot 0.4.0" Jan 10 19:11:03 volumio go-librespot[28308]: time="2026-01-10T19:11:03-06:00" level=debug msg="app state loaded" Jan 10 19:11:03 volumio go-librespot[28308]: time="2026-01-10T19:11:03-06:00" level=debug msg="stored credentials not found" Jan 10 19:11:03 volumio go-librespot[28308]: time="2026-01-10T19:11:03-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 10 19:11:03 volumio sudo[28316]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-01-10 19:10' Jan 10 19:11:03 volumio sudo[28316]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 19:11:03 volumio go-librespot[28308]: time="2026-01-10T19:11:03-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 10 19:11:03 volumio go-librespot[28308]: time="2026-01-10T19:11:03-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 10 19:11:03 volumio go-librespot[28308]: time="2026-01-10T19:11:03-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 10 19:11:03 volumio go-librespot[28308]: time="2026-01-10T19:11:03-06:00" level=info msg="zeroconf server listening on port 40613" Jan 10 19:11:03 volumio sudo[28316]: pam_unix(sudo:session): session closed for user root Jan 10 19:11:03 volumio go-librespot[28308]: time="2026-01-10T19:11:03-06:00" level=debug msg="obtained new client token: AAB+7vzS8arDHvzMsSKl67aSJMPAKL9QOexHLVmOvULV9UL9/zcMGJg+iaL23uw2r51ZLUOxVhNaxXqNfSeu/RehoVOLQEWNxo9n+QgNKHz/XYAefj6WPTr21kME7rBNi4rwma1jzBfsB5SuRhaHi6st3IezyzbrkYidA2PeUs4gQZBMtn/8J/AlLC4QqDIb1HHwLp9FAefuWVfNwC0dmJ0Fm8oFMGFhkLDjgHHTzMp1Xq+WtKYFcliR5w==" Jan 10 19:11:03 volumio go-librespot[28308]: time="2026-01-10T19:11:03-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 10 19:11:03 volumio volumio-remote-updater[14193]: [2026-01-10 19:11:03] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Jan 10 19:11:03 volumio volumio-remote-updater[14193]: [2026-01-10 19:11:03] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Jan 10 19:11:03 volumio systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Jan 10 19:11:03 volumio systemd[1]: volumio.service: Failed with result 'exit-code'. Jan 10 19:11:03 volumio systemd[1]: volumio.service: Consumed 46.083s CPU time. Jan 10 19:11:04 volumio go-librespot[28308]: time="2026-01-10T19:11:04-06:00" level=debug msg="completed keyexchange" Jan 10 19:11:04 volumio go-librespot[28308]: time="2026-01-10T19:11:04-06:00" level=debug msg="completed challenge" Jan 10 19:11:04 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Jan 10 19:11:04 volumio go-librespot[28308]: time="2026-01-10T19:11:04-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Jan 10 19:11:04 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Jan 10 19:11:04 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 10 19:11:04 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 10 19:11:04 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 18489. Jan 10 19:11:04 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Jan 10 19:11:04 volumio systemd[1]: Stopped volumio.service - Volumio Backend Module. Jan 10 19:11:04 volumio systemd[1]: volumio.service: Consumed 46.083s CPU time. Jan 10 19:11:04 volumio systemd[1]: Started volumio.service - Volumio Backend Module. Jan 10 19:11:04 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Jan 10 19:11:06 volumio volumio[28329]: info: ------------------------------------------- Jan 10 19:11:06 volumio volumio[28329]: info: ----- Volumio3 ---- Jan 10 19:11:06 volumio volumio[28329]: info: ------------------------------------------- Jan 10 19:11:06 volumio volumio[28329]: info: ----- System startup ---- Jan 10 19:11:06 volumio volumio[28329]: info: ------------------------------------------- Jan 10 19:11:06 volumio volumio[28329]: info: MYVOLUMIO Environment detected Jan 10 19:11:07 volumio volumio[28329]: info: Plugin folders cleanup Jan 10 19:11:07 volumio volumio[28329]: info: Scanning into folder /volumio/app/plugins/ Jan 10 19:11:07 volumio volumio[28329]: info: Scanning category audio_interface Jan 10 19:11:07 volumio volumio[28329]: info: Scanning category miscellanea Jan 10 19:11:07 volumio volumio[28329]: info: Scanning category music_service Jan 10 19:11:07 volumio volumio[28329]: info: Scanning category plugins.json Jan 10 19:11:07 volumio volumio[28329]: info: Scanning category system_controller Jan 10 19:11:07 volumio volumio[28329]: info: Scanning category user_interface Jan 10 19:11:07 volumio volumio[28329]: info: Scanning into folder /data/plugins/ Jan 10 19:11:07 volumio volumio[28329]: info: Scanning category audio_interface Jan 10 19:11:07 volumio volumio[28329]: info: Scanning category music_service Jan 10 19:11:07 volumio volumio[28329]: info: Scanning category system_controller Jan 10 19:11:07 volumio volumio[28329]: info: Scanning category system_hardware Jan 10 19:11:07 volumio volumio[28329]: info: Scanning category user_interface Jan 10 19:11:07 volumio volumio[28329]: info: Plugin folders cleanup completed Jan 10 19:11:07 volumio volumio[28329]: info: ------------------------------------------- Jan 10 19:11:07 volumio volumio[28329]: info: ----- Core plugins startup ---- Jan 10 19:11:07 volumio volumio[28329]: info: ------------------------------------------- Jan 10 19:11:07 volumio volumio[28329]: info: Loading plugins from folder /volumio/app/plugins/ Jan 10 19:11:07 volumio volumio[28329]: info: Adding plugin upnp to MyMusic Plugins Jan 10 19:11:07 volumio volumio[28329]: info: Adding plugin airplay_emulation to MyMusic Plugins Jan 10 19:11:07 volumio volumio[28329]: info: Adding plugin upnp_browser to MyMusic Plugins Jan 10 19:11:07 volumio volumio[28329]: info: Loading plugins from folder /data/plugins/ Jan 10 19:11:07 volumio volumio[28329]: info: Loading plugin "system"... Jan 10 19:11:07 volumio volumio[28329]: info: Loading plugin "appearance"... Jan 10 19:11:07 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 21. Jan 10 19:11:07 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 10 19:11:07 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 10 19:11:07 volumio go-librespot[28357]: go-librespot daemon starting... Jan 10 19:11:07 volumio go-librespot[28358]: time="2026-01-10T19:11:07-06:00" level=info msg="running go-librespot 0.4.0" Jan 10 19:11:07 volumio go-librespot[28358]: time="2026-01-10T19:11:07-06:00" level=debug msg="app state loaded" Jan 10 19:11:07 volumio go-librespot[28358]: time="2026-01-10T19:11:07-06:00" level=debug msg="stored credentials not found" Jan 10 19:11:07 volumio go-librespot[28358]: time="2026-01-10T19:11:07-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 10 19:11:07 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.37.113 Jan 10 19:11:07 volumio avahi-daemon[664]: Registering new address record for 169.254.37.113 on eth0.IPv4. Jan 10 19:11:07 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Jan 10 19:11:07 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 19:11:07 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 10 19:11:07 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 19:11:07 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.37.113 Jan 10 19:11:07 volumio go-librespot[28358]: time="2026-01-10T19:11:07-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 10 19:11:07 volumio go-librespot[28358]: time="2026-01-10T19:11:07-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 10 19:11:07 volumio go-librespot[28358]: time="2026-01-10T19:11:07-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 10 19:11:07 volumio go-librespot[28358]: time="2026-01-10T19:11:07-06:00" level=info msg="zeroconf server listening on port 37707" Jan 10 19:11:07 volumio go-librespot[28358]: time="2026-01-10T19:11:07-06:00" level=debug msg="obtained new client token: AAAJgpku2UMFPAfLGEwken0xUB8YF21fUeZ8Bzg/upK7yGuTH+p6CbbJbeBQlc/aCg8CzKnKz67i37im8w2pLtoxmGmq4fm3nTadPnwMgFh6b98R2oLeAuiLJt/+WzxgDlAwGQCKd2tzSne5YVIKTOV3DBP1pcYV8z4+tFqWDG0CClFlFTyfsp4N9ePvqHwD/6HTdcK/dkC4vEZ0Y1jtli4Dm/qOmw+RGhROqunsHKMkJD6vIwqxhBAQaA==" Jan 10 19:11:07 volumio go-librespot[28358]: time="2026-01-10T19:11:07-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 10 19:11:07 volumio go-librespot[28358]: time="2026-01-10T19:11:07-06:00" level=debug msg="completed keyexchange" Jan 10 19:11:07 volumio go-librespot[28358]: time="2026-01-10T19:11:07-06:00" level=debug msg="completed challenge" Jan 10 19:11:07 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.37.113 Jan 10 19:11:07 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.37.113 Jan 10 19:11:07 volumio avahi-daemon[664]: Withdrawing address record for 169.254.37.113 on eth0. Jan 10 19:11:07 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Jan 10 19:11:07 volumio go-librespot[28358]: time="2026-01-10T19:11:07-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Jan 10 19:11:07 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 10 19:11:07 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 10 19:11:07 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Jan 10 19:11:07 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 19:11:07 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 10 19:11:07 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 19:11:08 volumio volumio[28329]: info: Loading plugin "network"... Jan 10 19:11:08 volumio volumio[28329]: info: Refreshing Cached IP Addresses Jan 10 19:11:08 volumio sudo[28398]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 10 19:11:08 volumio sudo[28398]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 19:11:08 volumio sudo[28398]: pam_unix(sudo:session): session closed for user root Jan 10 19:11:08 volumio sudo[28400]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 10 19:11:08 volumio sudo[28400]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 19:11:08 volumio volumio[28329]: info: Loading plugin "services"... Jan 10 19:11:08 volumio sudo[28400]: pam_unix(sudo:session): session closed for user root Jan 10 19:11:08 volumio volumio[28329]: info: Loading plugin "alsa_controller"... Jan 10 19:11:08 volumio sudo[28408]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Jan 10 19:11:08 volumio sudo[28408]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 19:11:08 volumio volumio[28329]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 10 19:11:08 volumio volumio[28329]: info: Loading plugin "wizard"... Jan 10 19:11:08 volumio volumio[28329]: info: Loading plugin "networkfs"... Jan 10 19:11:08 volumio volumio[28329]: info: Starting Udev Watcher for removable devices Jan 10 19:11:08 volumio volumio[28329]: info: Ignoring mount for partition: boot Jan 10 19:11:08 volumio volumio[28329]: info: Ignoring mount for partition: volumio Jan 10 19:11:08 volumio volumio[28329]: info: Ignoring mount for partition: volumio_data Jan 10 19:11:08 volumio volumio[28329]: info: Mounting Device Wikipedia Jan 10 19:11:08 volumio sudo[28437]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mount /dev/sda1 /mnt/USB/Wikipedia -o noatime Jan 10 19:11:08 volumio sudo[28437]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 19:11:08 volumio sudo[28437]: pam_unix(sudo:session): session closed for user root Jan 10 19:11:08 volumio volumio[28329]: mount: /media/Wikipedia: /dev/sda1 already mounted on /media/Wikipedia. Jan 10 19:11:08 volumio volumio[28329]: dmesg(1) may have more information after failed mount system call. Jan 10 19:11:08 volumio volumio[28329]: error: Failed to mount Wikipedia: Error: Command failed: /usr/bin/sudo /bin/mount "/dev/sda1" "/mnt/USB/Wikipedia" -o noatime Jan 10 19:11:08 volumio volumio[28329]: mount: /media/Wikipedia: /dev/sda1 already mounted on /media/Wikipedia. Jan 10 19:11:08 volumio volumio[28329]: dmesg(1) may have more information after failed mount system call. Jan 10 19:11:08 volumio volumio[28329]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 10 19:11:08 volumio volumio[28329]: info: Loading plugin "volumio_command_line_client"... Jan 10 19:11:08 volumio volumio[28329]: info: Loading plugin "upnp"... Jan 10 19:11:08 volumio volumio[28329]: info: [1768093868725] Starting Upmpd Daemon Jan 10 19:11:08 volumio volumio[28329]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 10 19:11:08 volumio volumio[28329]: info: Loading plugin "my_music"... Jan 10 19:11:08 volumio volumio[28329]: info: Loading plugin "mpd"... Jan 10 19:11:08 volumio volumio-remote-updater[14193]: [2026-01-10 19:11:08] [connect] Successful connection Jan 10 19:11:08 volumio sudo[28408]: pam_unix(sudo:session): session closed for user root Jan 10 19:11:09 volumio volumio[28329]: info: Loading plugin "upnp_browser"... Jan 10 19:11:09 volumio kernel: hwmon hwmon1: Undervoltage detected! Jan 10 19:11:10 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 22. Jan 10 19:11:10 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 10 19:11:11 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 10 19:11:11 volumio go-librespot[28440]: go-librespot daemon starting... Jan 10 19:11:11 volumio go-librespot[28441]: time="2026-01-10T19:11:11-06:00" level=info msg="running go-librespot 0.4.0" Jan 10 19:11:11 volumio go-librespot[28441]: time="2026-01-10T19:11:11-06:00" level=debug msg="app state loaded" Jan 10 19:11:11 volumio go-librespot[28441]: time="2026-01-10T19:11:11-06:00" level=debug msg="stored credentials not found" Jan 10 19:11:11 volumio go-librespot[28441]: time="2026-01-10T19:11:11-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 10 19:11:11 volumio go-librespot[28441]: time="2026-01-10T19:11:11-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 10 19:11:11 volumio go-librespot[28441]: time="2026-01-10T19:11:11-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 10 19:11:11 volumio go-librespot[28441]: time="2026-01-10T19:11:11-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 10 19:11:11 volumio go-librespot[28441]: time="2026-01-10T19:11:11-06:00" level=info msg="zeroconf server listening on port 40627" Jan 10 19:11:11 volumio go-librespot[28441]: time="2026-01-10T19:11:11-06:00" level=debug msg="obtained new client token: AAAb6WX1eaor4gulnHZaRTtEXZ78qjt80MqdMCvn/aM9dr4LNjK1SN5QQEX9BUKMQp10T4UjHi9o5HhDAQDlkgs7dtD0MHyne+WtXoUl76eLu/pxaCUpr4L2mUQhdTfzsuekXVeNT6LCmcTFMPrOzqldZG8k51f/cUhJo20XSDlbtKM8FZm8tem1xXfk+lOySsvRiGgsTVLwzcQNvmTmwvhZXK8F8PWkv7d6gSlkhEVnOEFhGn9Y3Wr5Tw==" Jan 10 19:11:11 volumio go-librespot[28441]: time="2026-01-10T19:11:11-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 10 19:11:11 volumio go-librespot[28441]: time="2026-01-10T19:11:11-06:00" level=debug msg="completed keyexchange" Jan 10 19:11:11 volumio go-librespot[28441]: time="2026-01-10T19:11:11-06:00" level=debug msg="completed challenge" Jan 10 19:11:11 volumio go-librespot[28441]: time="2026-01-10T19:11:11-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Jan 10 19:11:11 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 10 19:11:11 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 10 19:11:12 volumio volumio[28329]: info: Loading plugin "alarm-clock"... Jan 10 19:11:12 volumio volumio[28329]: info: Loading plugin "airplay_emulation"... Jan 10 19:11:12 volumio volumio[28329]: info: Starting Shairport Sync Jan 10 19:11:12 volumio volumio[28329]: info: Loading plugin "last_100"... Jan 10 19:11:12 volumio volumio[28329]: info: Loading plugin "webradio"... Jan 10 19:11:12 volumio volumio[28329]: info: Loading plugin "i2s_dacs"... Jan 10 19:11:12 volumio volumio[28329]: info: I2S DAC not set, start Auto-detection Jan 10 19:11:12 volumio volumio[28329]: info: Loading plugin "volumiodiscovery"... Jan 10 19:11:12 volumio volumio[28329]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jan 10 19:11:12 volumio volumio[28329]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 10 19:11:12 volumio volumio[28329]: *** WARNING *** For more information see Jan 10 19:11:12 volumio volumio[28329]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jan 10 19:11:12 volumio volumio[28329]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 10 19:11:12 volumio volumio[28329]: *** WARNING *** For more information see Jan 10 19:11:12 volumio node[28329]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jan 10 19:11:12 volumio node[28329]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 10 19:11:12 volumio node[28329]: *** WARNING *** For more information see Jan 10 19:11:12 volumio node[28329]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jan 10 19:11:12 volumio node[28329]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 10 19:11:12 volumio node[28329]: *** WARNING *** For more information see Jan 10 19:11:12 volumio volumio[28329]: info: Applying required configuration parameters for plugin volumiodiscovery Jan 10 19:11:12 volumio volumio[28329]: info: Discovery: Started advertising with name: Volumio Jan 10 19:11:12 volumio volumio[28329]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 10 19:11:12 volumio volumio[28329]: info: Loading plugin "bandcamp"... Jan 10 19:11:12 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.229.160 Jan 10 19:11:12 volumio avahi-daemon[664]: Registering new address record for 169.254.229.160 on eth0.IPv4. Jan 10 19:11:12 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Jan 10 19:11:12 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 19:11:12 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 10 19:11:12 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 19:11:13 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.229.160 Jan 10 19:11:13 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.229.160 Jan 10 19:11:13 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.229.160 Jan 10 19:11:13 volumio avahi-daemon[664]: Withdrawing address record for 169.254.229.160 on eth0. Jan 10 19:11:13 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Jan 10 19:11:13 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 19:11:13 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 10 19:11:13 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 19:11:13 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Jan 10 19:11:13 volumio volumio[28329]: info: Plugin calmradio is not enabled Jan 10 19:11:13 volumio volumio[28329]: info: Loading plugin "soundcloud"... Jan 10 19:11:14 volumio volumio[28329]: info: Loading plugin "spop"... Jan 10 19:11:14 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 23. Jan 10 19:11:14 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 10 19:11:15 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 10 19:11:15 volumio go-librespot[28483]: go-librespot daemon starting... Jan 10 19:11:15 volumio go-librespot[28484]: time="2026-01-10T19:11:15-06:00" level=info msg="running go-librespot 0.4.0" Jan 10 19:11:15 volumio go-librespot[28484]: time="2026-01-10T19:11:15-06:00" level=debug msg="app state loaded" Jan 10 19:11:15 volumio go-librespot[28484]: time="2026-01-10T19:11:15-06:00" level=debug msg="stored credentials not found" Jan 10 19:11:15 volumio go-librespot[28484]: time="2026-01-10T19:11:15-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 10 19:11:15 volumio volumio[28329]: info: Loading plugin "squeezelite_mc"... Jan 10 19:11:15 volumio go-librespot[28484]: time="2026-01-10T19:11:15-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 10 19:11:15 volumio go-librespot[28484]: time="2026-01-10T19:11:15-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 10 19:11:15 volumio go-librespot[28484]: time="2026-01-10T19:11:15-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 10 19:11:15 volumio go-librespot[28484]: time="2026-01-10T19:11:15-06:00" level=info msg="zeroconf server listening on port 34125" Jan 10 19:11:15 volumio go-librespot[28484]: time="2026-01-10T19:11:15-06:00" level=debug msg="obtained new client token: AABCThbW792QfwMGC8M9NhNr4kmC59EweK611PJVumiThDPsApcs+JdqhH5giEFXEcug1zKOBzQswnysQzA7flj//hMDU1EwJc1pU3NflP4RybumwCTEKoMGFStbNA4JnDYsx0/F2O/qKrzngJ6FSP2KUqZndB+Jq17PnBREAPCYyELDP4NMeBbtyE4ApdM3AhFe3QGwOETM5jPHFo+7lehVyFaD25dHiXZ2QT86UTmFdyrdRQoj5UNLfA==" Jan 10 19:11:15 volumio go-librespot[28484]: time="2026-01-10T19:11:15-06: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" Jan 10 19:11:15 volumio go-librespot[28484]: time="2026-01-10T19:11:15-06:00" level=debug msg="connected to ap-guc3.spotify.com:443" Jan 10 19:11:15 volumio go-librespot[28484]: time="2026-01-10T19:11:15-06:00" level=debug msg="completed keyexchange" Jan 10 19:11:15 volumio go-librespot[28484]: time="2026-01-10T19:11:15-06:00" level=debug msg="completed challenge" Jan 10 19:11:15 volumio go-librespot[28484]: time="2026-01-10T19:11:15-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Jan 10 19:11:15 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 10 19:11:15 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 10 19:11:15 volumio kernel: hwmon hwmon1: Voltage normalised Jan 10 19:11:15 volumio volumio[28329]: info: Loading plugin "youtube2"... Jan 10 19:11:16 volumio volumio[28329]: info: Loading plugin "ytcr"... Jan 10 19:11:17 volumio volumio[28329]: info: Loading plugin "ytmusic"... Jan 10 19:11:18 volumio volumio[28329]: info: Plugin now_playing is not enabled Jan 10 19:11:18 volumio volumio[28329]: info: Loading plugin "outputs"... Jan 10 19:11:18 volumio volumio[28329]: info: Loading plugin "albumart"... Jan 10 19:11:18 volumio volumio[28329]: info: Plugin example_plugin is not enabled Jan 10 19:11:18 volumio volumio[28329]: info: Loading plugin "inputs"... Jan 10 19:11:18 volumio volumio[28329]: info: Loading plugin "updater_comm"... Jan 10 19:11:18 volumio volumio[28329]: info: Plugin mpdemulation is not enabled Jan 10 19:11:18 volumio volumio[28329]: info: Loading plugin "rest_api"... Jan 10 19:11:18 volumio volumio[28329]: info: Loading plugin "websocket"... Jan 10 19:11:18 volumio volumio[28329]: info: Starting Socket.io Server version 1.7.4 Jan 10 19:11:18 volumio volumio[28329]: info: Plugin fusiondsp is not enabled Jan 10 19:11:18 volumio volumio[28329]: info: Plugin mpdoutput is not enabled Jan 10 19:11:18 volumio volumio[28329]: info: Plugin RoonBridge is not enabled Jan 10 19:11:18 volumio volumio[28329]: info: Loading plugin "podcast"... Jan 10 19:11:18 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 24. Jan 10 19:11:18 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 10 19:11:18 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 10 19:11:18 volumio go-librespot[28516]: go-librespot daemon starting... Jan 10 19:11:18 volumio go-librespot[28517]: time="2026-01-10T19:11:18-06:00" level=info msg="running go-librespot 0.4.0" Jan 10 19:11:18 volumio go-librespot[28517]: time="2026-01-10T19:11:18-06:00" level=debug msg="app state loaded" Jan 10 19:11:18 volumio go-librespot[28517]: time="2026-01-10T19:11:18-06:00" level=debug msg="stored credentials not found" Jan 10 19:11:18 volumio volumio[28329]: info: ControllerPodcast::constructor Jan 10 19:11:18 volumio go-librespot[28517]: time="2026-01-10T19:11:18-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 10 19:11:18 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.150.67 Jan 10 19:11:18 volumio avahi-daemon[664]: Registering new address record for 169.254.150.67 on eth0.IPv4. Jan 10 19:11:18 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Jan 10 19:11:18 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 19:11:18 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 10 19:11:18 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 19:11:18 volumio volumio[28329]: info: Loading plugin "volusonic"... Jan 10 19:11:19 volumio volumio[28495]: Forking 3 albumart workers Jan 10 19:11:19 volumio go-librespot[28517]: time="2026-01-10T19:11:19-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Jan 10 19:11:19 volumio go-librespot[28517]: time="2026-01-10T19:11:19-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Jan 10 19:11:19 volumio go-librespot[28517]: time="2026-01-10T19:11:19-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Jan 10 19:11:19 volumio go-librespot[28517]: time="2026-01-10T19:11:19-06:00" level=info msg="zeroconf server listening on port 46019" Jan 10 19:11:19 volumio go-librespot[28517]: time="2026-01-10T19:11:19-06:00" level=debug msg="obtained new client token: AAAAbln0YqhKjG+F8XHpgNkrIA2i++tSKCu7TSJUL6xyreyWUgoykBLDSbzjSa2/nwxt8fD+hDpSIh/2SIK6UtT9K6u0R67NOvBx8wtWZsasXVktc/cIcc7jG1mWdF2S6i79KvqUlxIHpY9+Qvur707YdDKxXy2GXxmiKWLZiD7iVzibXmVwHTDbS1aEsFrboPc9pZDk+KrVKTAVtndCF1r1OxJ91beRE8elBUMCCjX8Fwy/dcGdxpc=" Jan 10 19:11:19 volumio go-librespot[28517]: time="2026-01-10T19:11:19-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 10 19:11:19 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.150.67 Jan 10 19:11:19 volumio go-librespot[28517]: time="2026-01-10T19:11:19-06:00" level=debug msg="completed keyexchange" Jan 10 19:11:19 volumio go-librespot[28517]: time="2026-01-10T19:11:19-06:00" level=debug msg="completed challenge" Jan 10 19:11:19 volumio go-librespot[28517]: time="2026-01-10T19:11:19-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Jan 10 19:11:19 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.150.67 Jan 10 19:11:19 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.150.67 Jan 10 19:11:19 volumio avahi-daemon[664]: Withdrawing address record for 169.254.150.67 on eth0. Jan 10 19:11:19 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Jan 10 19:11:19 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 10 19:11:19 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 10 19:11:19 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 19:11:19 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 10 19:11:19 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 19:11:19 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Jan 10 19:11:19 volumio kernel: hwmon hwmon1: Undervoltage detected! Jan 10 19:11:21 volumio volumio[28329]: info: Applying required configuration parameters for plugin volusonic Jan 10 19:11:21 volumio volumio[28329]: info: Loading plugin "backup_restore"... Jan 10 19:11:21 volumio volumio-remote-updater[14193]: [2026-01-10 19:11:21] [connect] Successful connection Jan 10 19:11:21 volumio volumio[28540]: Starting albumart workers Jan 10 19:11:21 volumio volumio[28541]: Starting albumart workers Jan 10 19:11:21 volumio volumio[28329]: info: Applying required configuration parameters for plugin backup_restore Jan 10 19:11:21 volumio volumio[28329]: info: Plugin rpi_eeprom_config is not enabled Jan 10 19:11:21 volumio volumio[28329]: info: Plugin rpi_eeprom_updater is not enabled Jan 10 19:11:21 volumio volumio[28329]: info: Loading plugin "scheduledrestart"... Jan 10 19:11:21 volumio volumio[28542]: Starting albumart workers Jan 10 19:11:22 volumio volumio[28329]: info: Applying required configuration parameters for plugin scheduledrestart Jan 10 19:11:22 volumio volumio[28329]: info: Plugin Bluetoothremote is not enabled Jan 10 19:11:22 volumio volumio[28329]: info: Plugin music_services_shield is not enabled Jan 10 19:11:22 volumio volumio[28329]: info: Loading plugin "Systeminfo"... Jan 10 19:11:22 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 25. Jan 10 19:11:22 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 10 19:11:22 volumio go-librespot[28590]: go-librespot daemon starting... Jan 10 19:11:22 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 10 19:11:22 volumio go-librespot[28591]: time="2026-01-10T19:11:22-06:00" level=info msg="running go-librespot 0.4.0" Jan 10 19:11:22 volumio go-librespot[28591]: time="2026-01-10T19:11:22-06:00" level=debug msg="app state loaded" Jan 10 19:11:22 volumio go-librespot[28591]: time="2026-01-10T19:11:22-06:00" level=debug msg="stored credentials not found" Jan 10 19:11:22 volumio volumio[28329]: info: Plugin peppymeterbasic is not enabled Jan 10 19:11:22 volumio volumio[28329]: info: Loading plugin "peppyspectrum"... Jan 10 19:11:22 volumio go-librespot[28591]: time="2026-01-10T19:11:22-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 10 19:11:23 volumio go-librespot[28591]: time="2026-01-10T19:11:23-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 10 19:11:23 volumio go-librespot[28591]: time="2026-01-10T19:11:23-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 10 19:11:23 volumio go-librespot[28591]: time="2026-01-10T19:11:23-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 10 19:11:23 volumio go-librespot[28591]: time="2026-01-10T19:11:23-06:00" level=info msg="zeroconf server listening on port 40733" Jan 10 19:11:23 volumio go-librespot[28591]: time="2026-01-10T19:11:23-06:00" level=debug msg="obtained new client token: AACvTTy6mgN7fjR9/WcIdzsGlPb7iRDqUEh3v1n1D/0GaWJU9pey/jImj0ijUuP/u/bGla8CmBea3h2qP6rO5K1XOkBa+01ZBLfydbVzbiASyxXgybLAGbygnJQwWrDw8EGRHaYKUbE+cCf1+XUndv6fBZ7xTAKEBAtZFvFIu0GXfdZyjRaMY+5K+EFzgMoXPzfvbY1btoa0MY726Auc2fZYyYv212BYqwV12b6LprsrzEinEI9nNn+E/Q==" Jan 10 19:11:23 volumio go-librespot[28591]: time="2026-01-10T19:11:23-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 10 19:11:23 volumio go-librespot[28591]: time="2026-01-10T19:11:23-06:00" level=debug msg="completed keyexchange" Jan 10 19:11:23 volumio go-librespot[28591]: time="2026-01-10T19:11:23-06:00" level=debug msg="completed challenge" Jan 10 19:11:23 volumio go-librespot[28591]: time="2026-01-10T19:11:23-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Jan 10 19:11:23 volumio volumio[28329]: info: Loading i18n strings for locale en Jan 10 19:11:23 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 10 19:11:23 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 10 19:11:23 volumio volumio[28329]: info: Plugin peppyspectrum has duplicated i18n key SAVE. It is ignored. Jan 10 19:11:23 volumio volumio[28329]: Updating browse sources language Jan 10 19:11:23 volumio volumio[28329]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 10 19:11:23 volumio volumio[28329]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 10 19:11:23 volumio volumio[28329]: info: CoreCommandRouter::initPlayerControls Jan 10 19:11:23 volumio volumio[28329]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:11:23 volumio volumio[28329]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:11:23 volumio volumio[28329]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:11:23 volumio volumio[28329]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:11:23 volumio volumio[28329]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:11:23 volumio volumio[28329]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:11:23 volumio volumio[28329]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:11:23 volumio volumio[28329]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:11:23 volumio volumio[28329]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 10 19:11:23 volumio volumio[28329]: Express server listening on port 3000 Jan 10 19:11:23 volumio volumio[28329]: [Metrics] WebUI: 18s 225.51ms Jan 10 19:11:23 volumio volumio[28329]: info: CoreStateMachine::resetVolumioState Jan 10 19:11:23 volumio volumio[28329]: info: CoreStateMachine::getcurrentVolume Jan 10 19:11:23 volumio volumio[28329]: info: CoreCommandRouter::volumioRetrievevolume Jan 10 19:11:24 volumio volumio[28329]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 19:11:24 volumio sudo[28621]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 10 19:11:24 volumio sudo[28621]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 19:11:24 volumio sudo[28621]: pam_unix(sudo:session): session closed for user root Jan 10 19:11:24 volumio sudo[28623]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 10 19:11:24 volumio sudo[28623]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 19:11:24 volumio sudo[28623]: pam_unix(sudo:session): session closed for user root Jan 10 19:11:24 volumio volumio[28329]: info: Volumio Network Manager: Network status updated: 1 Jan 10 19:11:24 volumio volumio[28329]: info: VolumeController:: Volume=100 Mute =false Jan 10 19:11:24 volumio volumio[28329]: info: CoreStateMachine::pushState Jan 10 19:11:24 volumio volumio[28329]: info: CorePlayQueue::getTrack 0 Jan 10 19:11:24 volumio volumio[28329]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 10 19:11:24 volumio volumio[28329]: info: CoreCommandRouter::volumioPushState Jan 10 19:11:24 volumio volumio[28329]: info: CoreStateMachine::updateTrackBlock Jan 10 19:11:24 volumio volumio[28329]: info: CorePlayQueue::getTrackBlock Jan 10 19:11:24 volumio volumio[28329]: info: CoreCommandRouter::volumioRetrievevolume Jan 10 19:11:24 volumio volumio-remote-updater[14193]: [2026-01-10 19:11:24] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1768093881 101 Jan 10 19:11:24 volumio volumio[28329]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 3 Transport: websocket Total Clients: 1 Jan 10 19:11:24 volumio volumio[28329]: info: Reloading queue from file Jan 10 19:11:24 volumio volumio[28329]: info: CoreStateMachine::setRepeat null single undefined Jan 10 19:11:24 volumio volumio[28329]: info: CoreStateMachine::pushState Jan 10 19:11:24 volumio volumio[28329]: info: CorePlayQueue::getTrack 0 Jan 10 19:11:24 volumio volumio[28329]: info: CoreCommandRouter::volumioPushState Jan 10 19:11:24 volumio volumio[28329]: info: CoreStateMachine::setRandom null Jan 10 19:11:24 volumio volumio[28329]: info: CoreStateMachine::pushState Jan 10 19:11:24 volumio volumio[28329]: info: CorePlayQueue::getTrack 0 Jan 10 19:11:24 volumio volumio[28329]: info: CoreCommandRouter::volumioPushState Jan 10 19:11:24 volumio volumio[28329]: info: Setting Device type: Raspberry PI Jan 10 19:11:24 volumio volumio[28329]: info: VolumeController:: Volume=100 Mute =false Jan 10 19:11:24 volumio volumio[28329]: info: CoreStateMachine::pushState Jan 10 19:11:24 volumio volumio[28329]: info: CorePlayQueue::getTrack 0 Jan 10 19:11:24 volumio volumio[28329]: info: CoreCommandRouter::volumioPushState Jan 10 19:11:24 volumio volumio[28329]: info: Completed loading Core Plugins Jan 10 19:11:24 volumio volumio[28329]: info: Preparing to generate the ALSA configuration file Jan 10 19:11:24 volumio sudo[28636]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Jan 10 19:11:24 volumio sudo[28636]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 19:11:24 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.240.130 Jan 10 19:11:24 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Jan 10 19:11:24 volumio avahi-daemon[664]: Registering new address record for 169.254.240.130 on eth0.IPv4. Jan 10 19:11:24 volumio volumio[28329]: info: Discovery: adding a135e40e-a404-457b-98f5-36bf71c75954 Jan 10 19:11:24 volumio volumio[28329]: info: Discovery: Found device Volumio Jan 10 19:11:24 volumio volumio[28329]: info: CoreCommandRouter::volumioGetState Jan 10 19:11:24 volumio volumio[28329]: info: CorePlayQueue::getTrack 0 Jan 10 19:11:24 volumio volumio[28329]: info: Discovery: this is already registered, a135e40e-a404-457b-98f5-36bf71c75954 Jan 10 19:11:24 volumio volumio[28329]: info: Discovery: Found device Volumio Jan 10 19:11:24 volumio volumio[28329]: info: CoreCommandRouter::volumioGetState Jan 10 19:11:24 volumio volumio[28329]: info: CorePlayQueue::getTrack 0 Jan 10 19:11:24 volumio volumio[28329]: info: The plugin peppyspectrum has an ALSA contribution file peppy_in.peppy_out.6.conf Jan 10 19:11:24 volumio volumio[28329]: info: Reading ALSA contributions from plugins. Jan 10 19:11:24 volumio volumio[28329]: info: Asound.conf file unchanged, so no further update is needed Jan 10 19:11:24 volumio volumio[28329]: info: Output device has changed, restarting MPD Jan 10 19:11:24 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 19:11:24 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 10 19:11:24 volumio volumio[28329]: info: Output device has changed, restarting Shairport Sync Jan 10 19:11:24 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 19:11:24 volumio volumio[28329]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:11:24 volumio volumio[28329]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 19:11:24 volumio sudo[28657]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 10 19:11:24 volumio sudo[28636]: pam_unix(sudo:session): session closed for user root Jan 10 19:11:24 volumio sudo[28655]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 10 19:11:24 volumio sudo[28655]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 19:11:24 volumio sudo[28657]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 19:11:24 volumio sudo[28655]: pam_unix(sudo:session): session closed for user root Jan 10 19:11:24 volumio volumio[28329]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 10 19:11:24 volumio volumio[28329]: info: ___________ START PLUGINS ___________ Jan 10 19:11:24 volumio volumio[28329]: info: ControllerMpd::onStart: Initializing MPD Jan 10 19:11:24 volumio volumio[28329]: info: Creating MPD Configuration file Jan 10 19:11:24 volumio volumio[28329]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 10 19:11:24 volumio volumio[28329]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 10 19:11:24 volumio volumio[28329]: info: [1768093884970] CoreMusicLibrary::Adding element Media Servers Jan 10 19:11:24 volumio volumio[28329]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 10 19:11:24 volumio sudo[28665]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 10 19:11:24 volumio sudo[28665]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 19:11:24 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Jan 10 19:11:25 volumio sudo[28665]: pam_unix(sudo:session): session closed for user root Jan 10 19:11:25 volumio volumio[28329]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:11:25 volumio volumio[28329]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 19:11:25 volumio sudo[28667]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 10 19:11:25 volumio sudo[28667]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 19:11:25 volumio volumio[28329]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 10 19:11:25 volumio volumio[28329]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:11:25 volumio volumio[28329]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 19:11:25 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.240.130 Jan 10 19:11:25 volumio volumio[28329]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 10 19:11:25 volumio systemd[1]: mpd.service: Deactivated successfully. Jan 10 19:11:25 volumio volumio[28329]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 10 19:11:25 volumio volumio[28329]: info: [1768093885175] CoreMusicLibrary::Adding element Last_100 Jan 10 19:11:25 volumio volumio[28329]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 10 19:11:25 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Jan 10 19:11:25 volumio systemd[1]: mpd.service: Consumed 5.687s CPU time. Jan 10 19:11:25 volumio volumio[28329]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 10 19:11:25 volumio volumio[28329]: info: [1768093885183] CoreMusicLibrary::Adding element Webradio Jan 10 19:11:25 volumio volumio[28329]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 10 19:11:25 volumio systemd[1]: mpd.socket: Deactivated successfully. Jan 10 19:11:25 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jan 10 19:11:25 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jan 10 19:11:25 volumio volumio[28329]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 10 19:11:25 volumio volumio[28329]: info: Initializing BBC Radios Jan 10 19:11:25 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jan 10 19:11:25 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Jan 10 19:11:25 volumio volumio[28329]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 10 19:11:25 volumio volumio[28329]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 19:11:25 volumio volumio[28329]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 10 19:11:25 volumio volumio[28329]: info: [1768093885318] CoreMusicLibrary::Adding element Bandcamp Discover Jan 10 19:11:25 volumio volumio[28329]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 10 19:11:25 volumio volumio[28329]: Cannot find translation for source Bandcamp Discover Jan 10 19:11:25 volumio volumio[28329]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 10 19:11:25 volumio volumio[28329]: info: [1768093885338] CoreMusicLibrary::Adding element SoundCloud Jan 10 19:11:25 volumio volumio[28329]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 10 19:11:25 volumio volumio[28329]: Cannot find translation for source Bandcamp Discover Jan 10 19:11:25 volumio volumio[28329]: Cannot find translation for source SoundCloud Jan 10 19:11:25 volumio volumio[28329]: info: Creating Spotify config file Jan 10 19:11:25 volumio volumio[28329]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:11:25 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.240.130 Jan 10 19:11:25 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.240.130 Jan 10 19:11:25 volumio avahi-daemon[664]: Withdrawing address record for 169.254.240.130 on eth0. Jan 10 19:11:25 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Jan 10 19:11:25 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Jan 10 19:11:25 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 19:11:25 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 10 19:11:25 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 19:11:25 volumio sudo[28687]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jan 10 19:11:25 volumio sudo[28687]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Jan 10 19:11:25 volumio sudo[28687]: pam_unix(sudo:session): session closed for user root Jan 10 19:11:26 volumio volumio[28329]: info: [squeezelite_mc] Starting proxy server... Jan 10 19:11:26 volumio volumio[28329]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 10 19:11:26 volumio volumio[28329]: info: [1768093886063] CoreMusicLibrary::Adding element YouTube2 Jan 10 19:11:26 volumio volumio[28329]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 10 19:11:26 volumio volumio[28329]: Cannot find translation for source Bandcamp Discover Jan 10 19:11:26 volumio volumio[28329]: Cannot find translation for source SoundCloud Jan 10 19:11:26 volumio volumio[28329]: Cannot find translation for source YouTube2 Jan 10 19:11:26 volumio volumio[28329]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 10 19:11:26 volumio volumio[28329]: info: [1768093886094] CoreMusicLibrary::Adding element YouTube Music Jan 10 19:11:26 volumio volumio[28329]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 10 19:11:26 volumio volumio[28329]: Cannot find translation for source Bandcamp Discover Jan 10 19:11:26 volumio volumio[28329]: Cannot find translation for source SoundCloud Jan 10 19:11:26 volumio volumio[28329]: Cannot find translation for source YouTube2 Jan 10 19:11:26 volumio volumio[28329]: Cannot find translation for source YouTube Music Jan 10 19:11:26 volumio volumio[28329]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 10 19:11:26 volumio volumio[28329]: info: [1768093886113] CoreMusicLibrary::Adding element Podcast Jan 10 19:11:26 volumio volumio[28329]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 10 19:11:26 volumio volumio[28329]: Cannot find translation for source Bandcamp Discover Jan 10 19:11:26 volumio volumio[28329]: Cannot find translation for source SoundCloud Jan 10 19:11:26 volumio volumio[28329]: Cannot find translation for source YouTube2 Jan 10 19:11:26 volumio volumio[28329]: Cannot find translation for source YouTube Music Jan 10 19:11:26 volumio volumio[28329]: Cannot find translation for source Podcast Jan 10 19:11:26 volumio volumio[28329]: info: Loading i18n strings for locale en Jan 10 19:11:26 volumio volumio[28329]: info: Plugin peppyspectrum has duplicated i18n key SAVE. It is ignored. Jan 10 19:11:26 volumio volumio[28329]: Updating browse sources language Jan 10 19:11:26 volumio volumio[28329]: Cannot find translation for source Bandcamp Discover Jan 10 19:11:26 volumio volumio[28329]: Cannot find translation for source SoundCloud Jan 10 19:11:26 volumio volumio[28329]: Cannot find translation for source YouTube2 Jan 10 19:11:26 volumio volumio[28329]: Cannot find translation for source YouTube Music Jan 10 19:11:26 volumio volumio[28329]: Cannot find translation for source Podcast Jan 10 19:11:26 volumio volumio[28329]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 10 19:11:26 volumio volumio[28329]: Cannot find translation for source Bandcamp Discover Jan 10 19:11:26 volumio volumio[28329]: Cannot find translation for source SoundCloud Jan 10 19:11:26 volumio volumio[28329]: Cannot find translation for source YouTube2 Jan 10 19:11:26 volumio volumio[28329]: Cannot find translation for source YouTube Music Jan 10 19:11:26 volumio volumio[28329]: Cannot find translation for source Podcast Jan 10 19:11:26 volumio volumio[28329]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 10 19:11:26 volumio volumio[28329]: info: [1768093886194] CoreMusicLibrary::Adding element Volusonic Jan 10 19:11:26 volumio volumio[28329]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 10 19:11:26 volumio volumio[28329]: Cannot find translation for source Bandcamp Discover Jan 10 19:11:26 volumio volumio[28329]: Cannot find translation for source SoundCloud Jan 10 19:11:26 volumio volumio[28329]: Cannot find translation for source YouTube2 Jan 10 19:11:26 volumio volumio[28329]: Cannot find translation for source YouTube Music Jan 10 19:11:26 volumio volumio[28329]: Cannot find translation for source Podcast Jan 10 19:11:26 volumio volumio[28329]: Cannot find translation for source Volusonic Jan 10 19:11:26 volumio volumio[28329]: info: Scheduling reboots with hours: 0, minutes: 0 in timezone: America/Chicago Jan 10 19:11:26 volumio volumio[28329]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , updateALSAConfigFile Jan 10 19:11:26 volumio volumio[28329]: info: Volumio Calling Home Jan 10 19:11:26 volumio volumio[28329]: info: [squeezelite_mc] Proxy server started on port 45385 Jan 10 19:11:26 volumio volumio[28329]: info: Preparing to generate the ALSA configuration file Jan 10 19:11:26 volumio volumio[28329]: info: CoreCommandRouter::volumioRetrievevolume Jan 10 19:11:26 volumio volumio[28329]: info: The plugin peppyspectrum has an ALSA contribution file peppy_in.peppy_out.6.conf Jan 10 19:11:26 volumio volumio[28329]: info: Reading ALSA contributions from plugins. Jan 10 19:11:26 volumio volumio[28329]: info: MPD Permissions set Jan 10 19:11:26 volumio volumio[28329]: info: MPD Permissions set Jan 10 19:11:26 volumio volumio[28329]: info: Upmpdcli Daemon Started Jan 10 19:11:26 volumio volumio[28329]: info: Spotify config file written Jan 10 19:11:26 volumio sudo[28721]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jan 10 19:11:26 volumio sudo[28721]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 19:11:26 volumio volumio[28329]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Jan 10 19:11:26 volumio volumio[28329]: info: VolumeController:: Volume=100 Mute =false Jan 10 19:11:26 volumio volumio[28329]: info: CoreStateMachine::pushState Jan 10 19:11:26 volumio volumio[28329]: info: CorePlayQueue::getTrack 0 Jan 10 19:11:26 volumio volumio[28329]: info: CoreCommandRouter::volumioPushState Jan 10 19:11:26 volumio volumio[28329]: info: [squeezelite_mc] Server discovery started Jan 10 19:11:26 volumio volumio[28329]: info: [squeezelite_mc] Player finder started Jan 10 19:11:26 volumio volumio[28329]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:11:26 volumio volumio[28329]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:11:26 volumio volumio[28329]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:11:26 volumio volumio[28329]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 10 19:11:26 volumio volumio[28329]: info: [squeezelite_mc] Executing aplay -D hw:1 --nonblock -f MPEG /dev/zero 2>&1 || true Jan 10 19:11:26 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 10 19:11:26 volumio volumio[28329]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:11:26 volumio volumio[28329]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:11:26 volumio volumio[28329]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:11:26 volumio volumio[28329]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:11:26 volumio volumio[28329]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:11:26 volumio volumio[28329]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:11:26 volumio volumio[28329]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:11:26 volumio volumio[28329]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:11:26 volumio volumio[28329]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 19:11:26 volumio volumio[28329]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:11:26 volumio volumio[28329]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:11:26 volumio volumio[28329]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:11:26 volumio volumio[28329]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:11:26 volumio volumio[28329]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:11:26 volumio volumio[28329]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:11:26 volumio volumio[28329]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:11:26 volumio volumio[28329]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:11:26 volumio volumio[28329]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:11:26 volumio volumio[28329]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 19:11:26 volumio volumio[28329]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:11:26 volumio volumio[28329]: info: No need to fix Spotify hosts Jan 10 19:11:26 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 10 19:11:26 volumio go-librespot[28725]: go-librespot daemon starting... Jan 10 19:11:26 volumio sudo[28721]: pam_unix(sudo:session): session closed for user root Jan 10 19:11:26 volumio go-librespot[28736]: time="2026-01-10T19:11:26-06:00" level=info msg="running go-librespot 0.4.0" Jan 10 19:11:26 volumio go-librespot[28736]: time="2026-01-10T19:11:26-06:00" level=debug msg="app state loaded" Jan 10 19:11:26 volumio go-librespot[28736]: time="2026-01-10T19:11:26-06:00" level=debug msg="stored credentials not found" Jan 10 19:11:26 volumio go-librespot[28736]: time="2026-01-10T19:11:26-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 10 19:11:26 volumio volumio[28329]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Jan 10 19:11:26 volumio volumio[28329]: info: Volumio called home Jan 10 19:11:27 volumio go-librespot[28736]: time="2026-01-10T19:11:27-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 10 19:11:27 volumio go-librespot[28736]: time="2026-01-10T19:11:27-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 10 19:11:27 volumio go-librespot[28736]: time="2026-01-10T19:11:27-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 10 19:11:27 volumio volumio[28329]: info: [squeezelite_mc] Card 1 supports the following ALSA formats: ["U8","S16_LE"] Jan 10 19:11:27 volumio volumio[28329]: info: [squeezelite_mc] Starting Squeezelite service with params: {"type":"basic","playerName":"volumio","dsdFormat":null,"card":"1","mixerType":"Hardware","mixer":"PCM"} Jan 10 19:11:27 volumio go-librespot[28736]: time="2026-01-10T19:11:27-06:00" level=info msg="zeroconf server listening on port 37129" Jan 10 19:11:27 volumio volumio[28329]: info: [squeezelite_mc] Executing cp /data/plugins/music_service/squeezelite_mc/dist/lib/../templates/alsa/100-squeezelite.conf.template.out /etc/alsa/conf.d/100-squeezelite.conf Jan 10 19:11:27 volumio volumio[28329]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jan 10 19:11:27 volumio volumio[28329]: SPOTIFY: BQCAq3IIvpcOuFrYk4jeyHUhqXIePWTO5-JEv8VGSK32Umvv0zui3jV46WhKXwmXM8DR25WLQrAkhaJNoio_KPsfy3yJBsSNat0J70ywpM_321cYx1ZXi26yDiag65mIp_YzLtKQ59c5gH4uxpU1ka6ZL_FMWXwe3VgUaOzjL6QmWHgoBiRGHdylSzjivl441zdBpNoZcmpUQ9u-X6ISsVaqb6tAF2Zr5RwzH94 Jan 10 19:11:27 volumio volumio[28329]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jan 10 19:11:27 volumio volumio[28329]: info: New Spotify access token = BQCAq3IIvpcOuFrYk4jeyHUhqXIePWTO5-JEv8VGSK32Umvv0zui3jV46WhKXwmXM8DR25WLQrAkhaJNoio_KPsfy3yJBsSNat0J70ywpM_321cYx1ZXi26yDiag65mIp_YzLtKQ59c5gH4uxpU1ka6ZL_FMWXwe3VgUaOzjL6QmWHgoBiRGHdylSzjivl441zdBpNoZcmpUQ9u-X6ISsVaqb6tAF2Zr5RwzH94 Jan 10 19:11:27 volumio volumio[28329]: info: Spotify credentials grant success - running version from March 24, 2019 Jan 10 19:11:27 volumio volumio[28329]: info: Starting Shairport Sync Jan 10 19:11:27 volumio volumio[28329]: info: Starting Shairport Sync Jan 10 19:11:27 volumio volumio[28329]: info: Starting Shairport Sync Jan 10 19:11:27 volumio go-librespot[28736]: time="2026-01-10T19:11:27-06:00" level=debug msg="obtained new client token: AABhxS4e5C1y+Y5qe024cnBNsGI0AYLSzV7ntryDy10Yt/X1eEuydlw6AvPEadFFA3vOXzhdNmfptC53xou03LnCWzwyTSdzdsClr6BJvWjUUfWk589jvPc+4t24am9S6dnh6h1iWnI2InyG9B5fM0D3Ws39a/1aMeRvzCdugOg44ilYnJrchn97zn+Z4Ffhg/6YZJtFwfwwj82LM6s0ljV/yAb56Pctr1TVTifR8IEIFwbJoHQK2ag=" Jan 10 19:11:27 volumio sudo[28746]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/cp /data/plugins/music_service/squeezelite_mc/dist/lib/../templates/alsa/100-squeezelite.conf.template.out /etc/alsa/conf.d/100-squeezelite.conf Jan 10 19:11:27 volumio sudo[28746]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 19:11:27 volumio sudo[28750]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 10 19:11:27 volumio sudo[28750]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 19:11:27 volumio sudo[28748]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 10 19:11:27 volumio sudo[28746]: pam_unix(sudo:session): session closed for user root Jan 10 19:11:27 volumio sudo[28748]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 19:11:27 volumio go-librespot[28736]: time="2026-01-10T19:11:27-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 10 19:11:27 volumio sudo[28752]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 10 19:11:27 volumio sudo[28752]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 19:11:27 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jan 10 19:11:27 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Jan 10 19:11:27 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 10 19:11:27 volumio systemd[1]: shairport-sync.service: Consumed 1.989s CPU time. Jan 10 19:11:27 volumio volumio[28329]: info: [squeezelite_mc] Executing alsactl -L -R nrestore Jan 10 19:11:27 volumio volumio[28329]: info: Asound.conf file unchanged, so no further update is needed Jan 10 19:11:27 volumio volumio[28329]: info: Output device has changed, restarting MPD Jan 10 19:11:27 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 10 19:11:27 volumio volumio[28329]: info: Output device has changed, restarting Shairport Sync Jan 10 19:11:27 volumio volumio[28329]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:11:27 volumio volumio[28329]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 19:11:27 volumio sudo[28752]: pam_unix(sudo:session): session closed for user root Jan 10 19:11:27 volumio sudo[28750]: pam_unix(sudo:session): session closed for user root Jan 10 19:11:27 volumio sudo[28760]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/sbin/alsactl -L -R nrestore Jan 10 19:11:27 volumio sudo[28760]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 19:11:27 volumio sudo[28748]: pam_unix(sudo:session): session closed for user root Jan 10 19:11:27 volumio sudo[28762]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 10 19:11:27 volumio sudo[28762]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 19:11:27 volumio sudo[28762]: pam_unix(sudo:session): session closed for user root Jan 10 19:11:27 volumio volumio[28329]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 10 19:11:27 volumio sudo[28760]: pam_unix(sudo:session): session closed for user root Jan 10 19:11:27 volumio sudo[28764]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 10 19:11:27 volumio sudo[28764]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 19:11:27 volumio systemd[1]: mpd.service: Deactivated successfully. Jan 10 19:11:27 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Jan 10 19:11:27 volumio systemd[1]: mpd.service: Consumed 2.213s CPU time. Jan 10 19:11:27 volumio systemd[1]: mpd.socket: Deactivated successfully. Jan 10 19:11:27 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jan 10 19:11:27 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jan 10 19:11:27 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jan 10 19:11:27 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Jan 10 19:11:27 volumio volumio[28329]: info: MPD Permissions set Jan 10 19:11:27 volumio volumio[28329]: info: [squeezelite_mc] Executing cp /data/plugins/music_service/squeezelite_mc/dist/lib/../templates/systemd/squeezelite.service.template.out /etc/systemd/system/squeezelite.service Jan 10 19:11:27 volumio volumio[28329]: info: Shairport-Sync Started Jan 10 19:11:27 volumio volumio[28329]: Error adding Membership: Error: addMembership EINVAL Jan 10 19:11:27 volumio volumio[28329]: info: Shairport-Sync Started Jan 10 19:11:27 volumio volumio[28329]: info: Shairport-Sync Started Jan 10 19:11:27 volumio volumio[28329]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:11:27 volumio volumio[28329]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:11:27 volumio volumio[28329]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:11:27 volumio volumio[28329]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:11:27 volumio volumio[28329]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:11:27 volumio volumio[28329]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:11:27 volumio volumio[28329]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:11:27 volumio volumio[28329]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:11:27 volumio volumio[28329]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 19:11:27 volumio volumio[28329]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:11:27 volumio sudo[28794]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/cp /data/plugins/music_service/squeezelite_mc/dist/lib/../templates/systemd/squeezelite.service.template.out /etc/systemd/system/squeezelite.service Jan 10 19:11:27 volumio sudo[28794]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 19:11:27 volumio sudo[28794]: pam_unix(sudo:session): session closed for user root Jan 10 19:11:27 volumio volumio[28329]: info: CoreCommandRouter::volumioGetState Jan 10 19:11:27 volumio volumio[28329]: info: CorePlayQueue::getTrack 0 Jan 10 19:11:27 volumio volumio[28329]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl daemon-reload || true Jan 10 19:11:28 volumio volumio[28329]: info: Starting Shairport Sync Jan 10 19:11:28 volumio sudo[28791]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jan 10 19:11:28 volumio sudo[28791]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Jan 10 19:11:28 volumio sudo[28791]: pam_unix(sudo:session): session closed for user root Jan 10 19:11:28 volumio sudo[28802]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl daemon-reload Jan 10 19:11:28 volumio sudo[28802]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 19:11:28 volumio sudo[28804]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 10 19:11:28 volumio sudo[28804]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 19:11:28 volumio systemd[1]: Reloading. Jan 10 19:11:28 volumio volumio[28329]: SPOTIFY: User informations: {"display_name":"Clint Smith","external_urls":{"spotify":"https://open.spotify.com/user/clintsmith1"},"followers":{"href":null,"total":7},"href":"https://api.spotify.com/v1/users/clintsmith1","id":"clintsmith1","images":[{"height":300,"url":"https://i.scdn.co/image/ab6775700000ee856520409d25d9cc210472a0fd","width":300},{"height":64,"url":"https://i.scdn.co/image/ab67757000003b826520409d25d9cc210472a0fd","width":64}],"type":"user","uri":"spotify:user:clintsmith1"} Jan 10 19:11:28 volumio volumio[28329]: info: Spotify Successfully logged in Jan 10 19:11:28 volumio volumio[28329]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 10 19:11:28 volumio volumio[28329]: info: [1768093888367] CoreMusicLibrary::Adding element Spotify Jan 10 19:11:28 volumio volumio[28329]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 10 19:11:28 volumio volumio[28329]: Cannot find translation for source Bandcamp Discover Jan 10 19:11:28 volumio volumio[28329]: Cannot find translation for source SoundCloud Jan 10 19:11:28 volumio volumio[28329]: Cannot find translation for source YouTube2 Jan 10 19:11:28 volumio volumio[28329]: Cannot find translation for source YouTube Music Jan 10 19:11:28 volumio volumio[28329]: Cannot find translation for source Podcast Jan 10 19:11:28 volumio volumio[28329]: Cannot find translation for source Volusonic Jan 10 19:11:28 volumio volumio[28329]: Cannot find translation for source Spotify Jan 10 19:11:29 volumio volumio[28329]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:11:29 volumio volumio[28329]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:11:29 volumio volumio[28329]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 19:11:29 volumio volumio[28329]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 10 19:11:29 volumio go-librespot[28736]: time="2026-01-10T19:11:29-06:00" level=debug msg="completed keyexchange" Jan 10 19:11:29 volumio go-librespot[28736]: time="2026-01-10T19:11:29-06:00" level=debug msg="completed challenge" Jan 10 19:11:29 volumio go-librespot[28736]: time="2026-01-10T19:11:29-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Jan 10 19:11:30 volumio volumio[28329]: info: go-librespot daemon successfully initialized Jan 10 19:11:30 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.123.170 Jan 10 19:11:30 volumio avahi-daemon[664]: Registering new address record for 169.254.123.170 on eth0.IPv4. Jan 10 19:11:30 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Jan 10 19:11:30 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.123.170 Jan 10 19:11:30 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.123.170 Jan 10 19:11:30 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.123.170 Jan 10 19:11:30 volumio avahi-daemon[664]: Withdrawing address record for 169.254.123.170 on eth0. Jan 10 19:11:30 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Jan 10 19:11:30 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Jan 10 19:11:31 volumio systemd[1]: /lib/systemd/system/go-librespot-daemon.service:9: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Jan 10 19:11:31 volumio systemd[1]: /lib/systemd/system/go-librespot-daemon.service:10: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Jan 10 19:11:31 volumio volumio[28329]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 10 19:11:31 volumio volumio[28329]: Error: addMembership ENODEV Jan 10 19:11:31 volumio volumio[28329]: at Socket.addMembership (node:dgram:860:11) Jan 10 19:11:31 volumio volumio[28329]: at addMembership (/volumio/node_modules/node-ssdp/lib/index.js:264:16) { Jan 10 19:11:31 volumio volumio[28329]: errno: -19, Jan 10 19:11:31 volumio volumio[28329]: code: 'ENODEV', Jan 10 19:11:31 volumio volumio[28329]: syscall: 'addMembership' Jan 10 19:11:31 volumio volumio[28329]: } Jan 10 19:11:31 volumio volumio[28329]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 10 19:11:31 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 10 19:11:31 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 10 19:11:31 volumio sudo[28802]: pam_unix(sudo:session): session closed for user root Jan 10 19:11:31 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 19:11:31 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 10 19:11:31 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 19:11:31 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jan 10 19:11:31 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Jan 10 19:11:31 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 10 19:11:31 volumio systemd[1]: shairport-sync.service: Consumed 1.416s CPU time. Jan 10 19:11:31 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 10 19:11:31 volumio sudo[28804]: pam_unix(sudo:session): session closed for user root Jan 10 19:11:31 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 19:11:31 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 10 19:11:31 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 19:11:32 volumio sudo[28901]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-01-10 19:10' Jan 10 19:11:32 volumio sudo[28901]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) PRETTY_NAME="Raspbian GNU/Linux 12 (bookworm)" NAME="Raspbian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="ac7dd5922ede329d1459d48b226ddc71f5209a2c" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="3441cddd43405c36fe444484553f10f2f5bc830b" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Thu Nov 13 11:04:27 UTC 2025" VOLUMIO_VERSION="4.069" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="7da8d6d9f8baf8621af4ec2af5a00f00"