Dec 30 06:18:00 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 30 06:18:00 volumio sudo[16699]: pam_unix(sudo:session): session closed for user root Dec 30 06:18:00 volumio volumio[16162]: info: Shairport-Sync Started Dec 30 06:18:00 volumio systemd[1]: Stopping squeezelite.service - Squeezelite lightweight headless Squeezebox emulator... Dec 30 06:18:00 volumio systemd[1]: squeezelite.service: Deactivated successfully. Dec 30 06:18:00 volumio systemd[1]: Stopped squeezelite.service - Squeezelite lightweight headless Squeezebox emulator. Dec 30 06:18:00 volumio go-librespot[16727]: time="2025-12-30T06:18: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]" Dec 30 06:18:00 volumio go-librespot[16727]: time="2025-12-30T06:18: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]" Dec 30 06:18:00 volumio go-librespot[16727]: time="2025-12-30T06:18: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]" Dec 30 06:18:00 volumio sudo[16724]: pam_unix(sudo:session): session closed for user root Dec 30 06:18:00 volumio go-librespot[16727]: time="2025-12-30T06:18:00-06:00" level=info msg="zeroconf server listening on port 33133" Dec 30 06:18:00 volumio go-librespot[16727]: time="2025-12-30T06:18:00-06:00" level=debug msg="obtained new client token: AADUvvvhCuDfD7DfiUl34wP4tp06koiKjdtZSg/A3NuiMzZvjailEM5AFrkxDsJVMr7m7W3qNv+opcVll0b3aOPKaonXJx8aMgXyeDWjsVNQbvifTrw4N7Cox+fF1srGTRH7W3q2BFHJzETDuCu4/zdoMHpWwHxpVthoXAO3yQZtqo/LeFjpZ/QofeE7ZEr2Gk1EemdxaS1QdhUjaVn7L9SVQ874EsWab714zQuvks5Z6yjxj24csC7z/A==" Dec 30 06:18:00 volumio go-librespot[16727]: time="2025-12-30T06:18:00-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 06:18:00 volumio go-librespot[16727]: time="2025-12-30T06:18:00-06:00" level=debug msg="completed keyexchange" Dec 30 06:18:00 volumio go-librespot[16727]: time="2025-12-30T06:18:00-06:00" level=debug msg="completed challenge" Dec 30 06:18:00 volumio go-librespot[16727]: time="2025-12-30T06:18: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 " Dec 30 06:18:00 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 06:18:00 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 06:18:00 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.230.127 Dec 30 06:18:00 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Dec 30 06:18:00 volumio avahi-daemon[664]: Registering new address record for 169.254.230.127 on eth0.IPv4. Dec 30 06:18:00 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:18:00 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 06:18:00 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:18:00 volumio volumio[16162]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 30 06:18:00 volumio sudo[16782]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 30 06:18:00 volumio sudo[16782]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:18:01 volumio sudo[16782]: pam_unix(sudo:session): session closed for user root Dec 30 06:18:01 volumio volumio[16162]: info: [squeezelite_mc] Executing rm /tmp/squeezelite.log Dec 30 06:18:01 volumio sudo[16786]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/rm /tmp/squeezelite.log Dec 30 06:18:01 volumio sudo[16786]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:18:01 volumio sudo[16786]: pam_unix(sudo:session): session closed for user root Dec 30 06:18:01 volumio volumio[16162]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl start squeezelite || true Dec 30 06:18:01 volumio sudo[16789]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start squeezelite Dec 30 06:18:01 volumio sudo[16789]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:18:01 volumio volumio[16162]: info: Initializing connection to go-librespot Websocket Dec 30 06:18:01 volumio volumio[16162]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 30 06:18:01 volumio systemd[1]: Starting squeezelite.service - Squeezelite lightweight headless Squeezebox emulator... Dec 30 06:18:01 volumio systemd[1]: Started squeezelite.service - Squeezelite lightweight headless Squeezebox emulator. Dec 30 06:18:01 volumio sudo[16789]: pam_unix(sudo:session): session closed for user root Dec 30 06:18:01 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.230.127 Dec 30 06:18:01 volumio volumio[16162]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 30 06:18:01 volumio sudo[16796]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 30 06:18:01 volumio sudo[16796]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:18:02 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.230.127 Dec 30 06:18:02 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.230.127 Dec 30 06:18:02 volumio avahi-daemon[664]: Withdrawing address record for 169.254.230.127 on eth0. Dec 30 06:18:02 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Dec 30 06:18:02 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Dec 30 06:18:02 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:18:02 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 06:18:02 volumio sudo[16796]: pam_unix(sudo:session): session closed for user root Dec 30 06:18:02 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:18:02 volumio volumio[16162]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 30 06:18:02 volumio sudo[16816]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 30 06:18:02 volumio sudo[16816]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:18:02 volumio sudo[16816]: pam_unix(sudo:session): session closed for user root Dec 30 06:18:03 volumio volumio[16162]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 30 06:18:03 volumio sudo[16820]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 30 06:18:03 volumio sudo[16820]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:18:03 volumio sudo[16820]: pam_unix(sudo:session): session closed for user root Dec 30 06:18:03 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 21. Dec 30 06:18:03 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 06:18:03 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 06:18:03 volumio go-librespot[16822]: go-librespot daemon starting... Dec 30 06:18:03 volumio go-librespot[16823]: time="2025-12-30T06:18:03-06:00" level=info msg="running go-librespot 0.4.0" Dec 30 06:18:03 volumio go-librespot[16823]: time="2025-12-30T06:18:03-06:00" level=debug msg="app state loaded" Dec 30 06:18:03 volumio go-librespot[16823]: time="2025-12-30T06:18:03-06:00" level=debug msg="stored credentials not found" Dec 30 06:18:03 volumio go-librespot[16823]: time="2025-12-30T06:18:03-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 06:18:04 volumio volumio[16162]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 30 06:18:04 volumio sudo[16831]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 30 06:18:04 volumio sudo[16831]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:18:04 volumio sudo[16831]: pam_unix(sudo:session): session closed for user root Dec 30 06:18:04 volumio volumio[16162]: info: Initializing connection to go-librespot Websocket Dec 30 06:18:04 volumio go-librespot[16823]: time="2025-12-30T06:18:04-06:00" level=debug msg="new websocket client" Dec 30 06:18:04 volumio volumio[16162]: info: Connection to go-librespot Websocket established Dec 30 06:18:04 volumio go-librespot[16823]: time="2025-12-30T06:18: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]" Dec 30 06:18:04 volumio go-librespot[16823]: time="2025-12-30T06:18: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]" Dec 30 06:18:04 volumio go-librespot[16823]: time="2025-12-30T06:18: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]" Dec 30 06:18:04 volumio go-librespot[16823]: time="2025-12-30T06:18:04-06:00" level=info msg="zeroconf server listening on port 43481" Dec 30 06:18:04 volumio go-librespot[16823]: time="2025-12-30T06:18:04-06:00" level=debug msg="obtained new client token: AADG1rwTdna8CIP0dUWqZqFMD+yxupzIffti4/WCgiFJNST2vLON6DSDCUESUUAn0Oe272je5aYcdy4LwgLqU2CI/jpxZwQGmj3eyd3cWQWYBW1ZBM/j6jkK4DFyvrx5ljAqV6RDWiSdQuk8xbmZ45beRCrP5ickq2TtdEBXvbApVjoZQGoZrUgIiLYSVB9dDjK+fa8G6loY8gk8z7Mu68XGUc84tVzCiHD6vCthn8DwC4TIA4mQubKtZg==" Dec 30 06:18:04 volumio go-librespot[16823]: time="2025-12-30T06:18:04-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 06:18:04 volumio mpd[16718]: 2025-12-30T06:18:04 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Dec 30 06:18:04 volumio go-librespot[16823]: time="2025-12-30T06:18:04-06:00" level=debug msg="completed keyexchange" Dec 30 06:18:04 volumio go-librespot[16823]: time="2025-12-30T06:18:04-06:00" level=debug msg="completed challenge" Dec 30 06:18:04 volumio go-librespot[16823]: time="2025-12-30T06:18: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 " Dec 30 06:18:04 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 06:18:04 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 06:18:04 volumio volumio[16162]: info: Connection to go-librespot Websocket closed Dec 30 06:18:04 volumio systemd[1]: Started mpd.service - Music Player Daemon. Dec 30 06:18:04 volumio mpd_monitor.sh[15947]: MPD Monitor Service: MPD restarted due to no mpc output. Dec 30 06:18:04 volumio sudo[16516]: pam_unix(sudo:session): session closed for user root Dec 30 06:18:04 volumio sudo[16653]: pam_unix(sudo:session): session closed for user root Dec 30 06:18:04 volumio sudo[16526]: pam_unix(sudo:session): session closed for user root Dec 30 06:18:04 volumio volumio[16162]: error: MPD error: The expression evaluated to a falsy value: Dec 30 06:18:04 volumio volumio[16162]: assert.ok(self.idling) Dec 30 06:18:04 volumio volumio[16162]: error: The expression evaluated to a falsy value: Dec 30 06:18:04 volumio volumio[16162]: assert.ok(self.idling) Dec 30 06:18:04 volumio volumio[16162]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 30 06:18:04 volumio volumio[16162]: error: MPD error: The expression evaluated to a falsy value: Dec 30 06:18:04 volumio volumio[16162]: assert.ok(self.idling) Dec 30 06:18:04 volumio volumio[16162]: error: The expression evaluated to a falsy value: Dec 30 06:18:04 volumio volumio[16162]: assert.ok(self.idling) Dec 30 06:18:04 volumio volumio[16162]: info: MPD running with PID16718 Dec 30 06:18:04 volumio volumio[16162]: ,establishing connection Dec 30 06:18:04 volumio volumio[16162]: error: updateQueue error: null Dec 30 06:18:04 volumio volumio[16162]: error: updateQueue error: null Dec 30 06:18:04 volumio sudo[16839]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 30 06:18:04 volumio sudo[16839]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:18:04 volumio sudo[16839]: pam_unix(sudo:session): session closed for user root Dec 30 06:18:04 volumio volumio[16162]: info: Completed starting Core Plugins Dec 30 06:18:04 volumio volumio[16162]: info: ------------------------------------------- Dec 30 06:18:04 volumio volumio[16162]: info: ----- MyVolumio plugins startup ---- Dec 30 06:18:04 volumio volumio[16162]: info: ------------------------------------------- Dec 30 06:18:04 volumio volumio[16162]: info: [MyVolumio PluginManager] Fetching plans data.... Dec 30 06:18:05 volumio systemd[1]: apt-daily-upgrade.service: Deactivated successfully. Dec 30 06:18:05 volumio systemd[1]: Finished apt-daily-upgrade.service - Daily apt upgrade and clean activities. Dec 30 06:18:05 volumio systemd[1]: apt-daily-upgrade.service: Consumed 2.463s CPU time. Dec 30 06:18:07 volumio kernel: hwmon hwmon1: Voltage normalised Dec 30 06:18:07 volumio volumio[16162]: info: Getting Spotify volume Dec 30 06:18:07 volumio volumio[16162]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 30 06:18:07 volumio volumio[16162]: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 30 06:18:07 volumio volumio[16162]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Dec 30 06:18:07 volumio volumio[16162]: errno: -111, Dec 30 06:18:07 volumio volumio[16162]: code: 'ECONNREFUSED', Dec 30 06:18:07 volumio volumio[16162]: syscall: 'connect', Dec 30 06:18:07 volumio volumio[16162]: address: '127.0.0.1', Dec 30 06:18:07 volumio volumio[16162]: port: 9879, Dec 30 06:18:07 volumio volumio[16162]: response: undefined Dec 30 06:18:07 volumio volumio[16162]: } Dec 30 06:18:07 volumio volumio[16162]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 30 06:18:07 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.208.114 Dec 30 06:18:07 volumio avahi-daemon[664]: Registering new address record for 169.254.208.114 on eth0.IPv4. Dec 30 06:18:07 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Dec 30 06:18:07 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:18:07 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 06:18:07 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:18:07 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 22. Dec 30 06:18:07 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 06:18:07 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 06:18:07 volumio go-librespot[16913]: go-librespot daemon starting... Dec 30 06:18:07 volumio go-librespot[16914]: time="2025-12-30T06:18:07-06:00" level=info msg="running go-librespot 0.4.0" Dec 30 06:18:07 volumio go-librespot[16914]: time="2025-12-30T06:18:07-06:00" level=debug msg="app state loaded" Dec 30 06:18:07 volumio go-librespot[16914]: time="2025-12-30T06:18:07-06:00" level=debug msg="stored credentials not found" Dec 30 06:18:07 volumio go-librespot[16914]: time="2025-12-30T06:18:07-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 06:18:07 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.208.114 Dec 30 06:18:07 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.208.114 Dec 30 06:18:07 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.208.114 Dec 30 06:18:07 volumio avahi-daemon[664]: Withdrawing address record for 169.254.208.114 on eth0. Dec 30 06:18:07 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Dec 30 06:18:08 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:18:08 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 06:18:08 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:18:08 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Dec 30 06:18:08 volumio go-librespot[16914]: time="2025-12-30T06:18: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-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Dec 30 06:18:08 volumio go-librespot[16914]: time="2025-12-30T06:18:08-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]" Dec 30 06:18:08 volumio go-librespot[16914]: time="2025-12-30T06:18:08-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]" Dec 30 06:18:08 volumio go-librespot[16914]: time="2025-12-30T06:18:08-06:00" level=info msg="zeroconf server listening on port 37353" Dec 30 06:18:08 volumio go-librespot[16914]: time="2025-12-30T06:18:08-06:00" level=debug msg="obtained new client token: AAD7rLu49CVtVYMFeLFUTiyQVLW2HTPkCeOQgMMwSihon9HyGLP7DLnr5cAN8IU52Yap5VRvMfSPBFYPxmavfod/XcMk6tWeJ3sj5ocGpVrryFLw0FROYhNgHBilp9MKUYuaNhoS62ciWoyx4qqk8CgTN23i10OjlPvXLYWwdSdaVVhH4QGD8YSFrWYmYlwlgfrkgpNrcFM1vTtagTYqjeUNrR0zn7agOBbOTc4yjmEwQD5ScHcndJY=" Dec 30 06:18:08 volumio sudo[16939]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-30 06:17' Dec 30 06:18:08 volumio sudo[16939]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:18:08 volumio go-librespot[16914]: time="2025-12-30T06:18:08-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 06:18:08 volumio go-librespot[16914]: time="2025-12-30T06:18:08-06:00" level=debug msg="completed keyexchange" Dec 30 06:18:08 volumio go-librespot[16914]: time="2025-12-30T06:18:08-06:00" level=debug msg="completed challenge" Dec 30 06:18:08 volumio go-librespot[16914]: time="2025-12-30T06:18: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 " Dec 30 06:18:08 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 06:18:08 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 06:18:08 volumio sudo[16939]: pam_unix(sudo:session): session closed for user root Dec 30 06:18:08 volumio volumio-remote-updater[702]: [2025-12-30 06:18:08] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Dec 30 06:18:08 volumio volumio-remote-updater[702]: [2025-12-30 06:18:08] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Dec 30 06:18:08 volumio systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Dec 30 06:18:08 volumio systemd[1]: volumio.service: Failed with result 'exit-code'. Dec 30 06:18:08 volumio systemd[1]: volumio.service: Consumed 46.090s CPU time. Dec 30 06:18:08 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Dec 30 06:18:08 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Dec 30 06:18:08 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 394. Dec 30 06:18:08 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Dec 30 06:18:08 volumio systemd[1]: Stopped volumio.service - Volumio Backend Module. Dec 30 06:18:08 volumio systemd[1]: volumio.service: Consumed 46.090s CPU time. Dec 30 06:18:08 volumio systemd[1]: Started volumio.service - Volumio Backend Module. Dec 30 06:18:08 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Dec 30 06:18:10 volumio volumio[16953]: info: ------------------------------------------- Dec 30 06:18:10 volumio volumio[16953]: info: ----- Volumio3 ---- Dec 30 06:18:10 volumio volumio[16953]: info: ------------------------------------------- Dec 30 06:18:10 volumio volumio[16953]: info: ----- System startup ---- Dec 30 06:18:10 volumio volumio[16953]: info: ------------------------------------------- Dec 30 06:18:11 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 23. Dec 30 06:18:11 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 06:18:11 volumio volumio[16953]: info: MYVOLUMIO Environment detected Dec 30 06:18:11 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 06:18:11 volumio go-librespot[16974]: go-librespot daemon starting... Dec 30 06:18:11 volumio go-librespot[16978]: time="2025-12-30T06:18:11-06:00" level=info msg="running go-librespot 0.4.0" Dec 30 06:18:11 volumio go-librespot[16978]: time="2025-12-30T06:18:11-06:00" level=debug msg="app state loaded" Dec 30 06:18:11 volumio go-librespot[16978]: time="2025-12-30T06:18:11-06:00" level=debug msg="stored credentials not found" Dec 30 06:18:11 volumio go-librespot[16978]: time="2025-12-30T06:18:11-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 06:18:11 volumio volumio[16953]: info: Plugin folders cleanup Dec 30 06:18:11 volumio volumio[16953]: info: Scanning into folder /volumio/app/plugins/ Dec 30 06:18:11 volumio volumio[16953]: info: Scanning category audio_interface Dec 30 06:18:11 volumio volumio[16953]: info: Scanning category miscellanea Dec 30 06:18:11 volumio volumio[16953]: info: Scanning category music_service Dec 30 06:18:11 volumio volumio[16953]: info: Scanning category plugins.json Dec 30 06:18:11 volumio volumio[16953]: info: Scanning category system_controller Dec 30 06:18:11 volumio volumio[16953]: info: Scanning category user_interface Dec 30 06:18:11 volumio volumio[16953]: info: Scanning into folder /data/plugins/ Dec 30 06:18:11 volumio volumio[16953]: info: Scanning category audio_interface Dec 30 06:18:11 volumio volumio[16953]: info: Scanning category music_service Dec 30 06:18:11 volumio volumio[16953]: info: Scanning category system_controller Dec 30 06:18:11 volumio volumio[16953]: info: Scanning category system_hardware Dec 30 06:18:11 volumio volumio[16953]: info: Scanning category user_interface Dec 30 06:18:11 volumio volumio[16953]: info: Plugin folders cleanup completed Dec 30 06:18:11 volumio volumio[16953]: info: ------------------------------------------- Dec 30 06:18:11 volumio volumio[16953]: info: ----- Core plugins startup ---- Dec 30 06:18:11 volumio volumio[16953]: info: ------------------------------------------- Dec 30 06:18:11 volumio volumio[16953]: info: Loading plugins from folder /volumio/app/plugins/ Dec 30 06:18:11 volumio volumio[16953]: info: Adding plugin upnp to MyMusic Plugins Dec 30 06:18:11 volumio volumio[16953]: info: Adding plugin airplay_emulation to MyMusic Plugins Dec 30 06:18:11 volumio volumio[16953]: info: Adding plugin upnp_browser to MyMusic Plugins Dec 30 06:18:11 volumio volumio[16953]: info: Loading plugins from folder /data/plugins/ Dec 30 06:18:11 volumio volumio[16953]: info: Loading plugin "system"... Dec 30 06:18:11 volumio volumio[16953]: info: Loading plugin "appearance"... Dec 30 06:18:11 volumio go-librespot[16978]: time="2025-12-30T06:18: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]" Dec 30 06:18:11 volumio go-librespot[16978]: time="2025-12-30T06:18: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]" Dec 30 06:18:11 volumio go-librespot[16978]: time="2025-12-30T06:18: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]" Dec 30 06:18:11 volumio go-librespot[16978]: time="2025-12-30T06:18:11-06:00" level=info msg="zeroconf server listening on port 44705" Dec 30 06:18:11 volumio go-librespot[16978]: time="2025-12-30T06:18:11-06:00" level=debug msg="obtained new client token: AADmCPv4MAAwaJ2Xw1hOCDvQ8WTYhApVcwlMFaAh0dfnE579JqNTmlLjO3dW3Dm+zyi41HlO41iyjGu2P7Fri+JZNS9lZjD1o0r3q0ueDpyW1RFSkqcNVMKrf7e3yswz4LIH2JNvi/H3umiqAa9mktkKOSbcn04nKa1p8vSVJ9gsP0N4aD05p7z/Ng8x0Mtq0u8xyloYdbv4P2LXfq+s2err+jy+tgoKArRa3koarPVXSCISSZTaxtM3Qw==" Dec 30 06:18:11 volumio go-librespot[16978]: time="2025-12-30T06:18:11-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 06:18:12 volumio go-librespot[16978]: time="2025-12-30T06:18:12-06:00" level=debug msg="completed keyexchange" Dec 30 06:18:12 volumio go-librespot[16978]: time="2025-12-30T06:18:12-06:00" level=debug msg="completed challenge" Dec 30 06:18:12 volumio go-librespot[16978]: time="2025-12-30T06:18: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 " Dec 30 06:18:12 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 06:18:12 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 06:18:12 volumio volumio[16953]: info: Loading plugin "network"... Dec 30 06:18:12 volumio volumio[16953]: info: Refreshing Cached IP Addresses Dec 30 06:18:12 volumio sudo[16990]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 30 06:18:12 volumio sudo[16990]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:18:12 volumio sudo[16992]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 30 06:18:12 volumio sudo[16992]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:18:12 volumio volumio[16953]: info: Loading plugin "services"... Dec 30 06:18:12 volumio sudo[16990]: pam_unix(sudo:session): session closed for user root Dec 30 06:18:12 volumio volumio[16953]: info: Loading plugin "alsa_controller"... Dec 30 06:18:12 volumio sudo[16992]: pam_unix(sudo:session): session closed for user root Dec 30 06:18:12 volumio sudo[17000]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Dec 30 06:18:12 volumio sudo[17000]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:18:12 volumio volumio[16953]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 30 06:18:12 volumio volumio[16953]: info: Loading plugin "wizard"... Dec 30 06:18:12 volumio volumio[16953]: info: Loading plugin "networkfs"... Dec 30 06:18:12 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.96.31 Dec 30 06:18:12 volumio avahi-daemon[664]: Registering new address record for 169.254.96.31 on eth0.IPv4. Dec 30 06:18:12 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Dec 30 06:18:13 volumio volumio[16953]: info: Starting Udev Watcher for removable devices Dec 30 06:18:13 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:18:13 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 06:18:13 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:18:13 volumio volumio[16953]: info: Ignoring mount for partition: boot Dec 30 06:18:13 volumio volumio[16953]: info: Ignoring mount for partition: volumio Dec 30 06:18:13 volumio volumio[16953]: info: Ignoring mount for partition: volumio_data Dec 30 06:18:13 volumio volumio[16953]: info: Mounting Device Wikipedia Dec 30 06:18:13 volumio sudo[17045]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mount /dev/sda1 /mnt/USB/Wikipedia -o noatime Dec 30 06:18:13 volumio sudo[17045]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:18:13 volumio sudo[17045]: pam_unix(sudo:session): session closed for user root Dec 30 06:18:13 volumio volumio[16953]: mount: /media/Wikipedia: /dev/sda1 already mounted on /media/Wikipedia. Dec 30 06:18:13 volumio volumio[16953]: dmesg(1) may have more information after failed mount system call. Dec 30 06:18:13 volumio volumio[16953]: error: Failed to mount Wikipedia: Error: Command failed: /usr/bin/sudo /bin/mount "/dev/sda1" "/mnt/USB/Wikipedia" -o noatime Dec 30 06:18:13 volumio volumio[16953]: mount: /media/Wikipedia: /dev/sda1 already mounted on /media/Wikipedia. Dec 30 06:18:13 volumio volumio[16953]: dmesg(1) may have more information after failed mount system call. Dec 30 06:18:13 volumio volumio[16953]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 30 06:18:13 volumio volumio[16953]: info: Loading plugin "volumio_command_line_client"... Dec 30 06:18:13 volumio volumio[16953]: info: Loading plugin "upnp"... Dec 30 06:18:13 volumio volumio[16953]: info: [1767097093248] Starting Upmpd Daemon Dec 30 06:18:13 volumio volumio[16953]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 30 06:18:13 volumio volumio[16953]: info: Loading plugin "my_music"... Dec 30 06:18:13 volumio volumio[16953]: info: Loading plugin "mpd"... Dec 30 06:18:13 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.96.31 Dec 30 06:18:13 volumio kernel: hwmon hwmon1: Undervoltage detected! Dec 30 06:18:13 volumio sudo[17000]: pam_unix(sudo:session): session closed for user root Dec 30 06:18:13 volumio volumio-remote-updater[702]: [2025-12-30 06:18:13] [connect] Successful connection Dec 30 06:18:13 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.96.31 Dec 30 06:18:13 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.96.31 Dec 30 06:18:13 volumio avahi-daemon[664]: Withdrawing address record for 169.254.96.31 on eth0. Dec 30 06:18:13 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Dec 30 06:18:13 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Dec 30 06:18:13 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:18:13 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 06:18:13 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:18:13 volumio volumio[16953]: info: Loading plugin "upnp_browser"... Dec 30 06:18:15 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 24. Dec 30 06:18:15 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 06:18:15 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 06:18:15 volumio go-librespot[17064]: go-librespot daemon starting... Dec 30 06:18:15 volumio go-librespot[17065]: time="2025-12-30T06:18:15-06:00" level=info msg="running go-librespot 0.4.0" Dec 30 06:18:15 volumio go-librespot[17065]: time="2025-12-30T06:18:15-06:00" level=debug msg="app state loaded" Dec 30 06:18:15 volumio go-librespot[17065]: time="2025-12-30T06:18:15-06:00" level=debug msg="stored credentials not found" Dec 30 06:18:15 volumio go-librespot[17065]: time="2025-12-30T06:18:15-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 06:18:15 volumio go-librespot[17065]: time="2025-12-30T06:18: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-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 30 06:18:15 volumio go-librespot[17065]: time="2025-12-30T06:18:15-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]" Dec 30 06:18:15 volumio go-librespot[17065]: time="2025-12-30T06:18:15-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]" Dec 30 06:18:15 volumio go-librespot[17065]: time="2025-12-30T06:18:15-06:00" level=info msg="zeroconf server listening on port 38911" Dec 30 06:18:15 volumio go-librespot[17065]: time="2025-12-30T06:18:15-06:00" level=debug msg="obtained new client token: AAAFJtDOqQNC8Cj64PdDg7vMi+EbBaTZKtMd0JMU7+You+vByBFDX7TConyarUFVw3fsqPLGHT+hHyheY4Cpc4f+GMDsMHUVRSLVHwfCUcnIqqQjyDEsrc+2cTXvadvING0cxdOJ3WCdw+dX7+fn1ujEVzMta1T53UtqxTAfZXMRQSDoJFGBa1v2NPJnQz7/ea3zKw7Er+Vh4aGxo6BJnqGnLVy+MrKMm5oFHPg+upz096axK5nsEbTfTQ==" Dec 30 06:18:15 volumio go-librespot[17065]: time="2025-12-30T06:18:15-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 06:18:16 volumio go-librespot[17065]: time="2025-12-30T06:18:16-06:00" level=debug msg="completed keyexchange" Dec 30 06:18:16 volumio go-librespot[17065]: time="2025-12-30T06:18:16-06:00" level=debug msg="completed challenge" Dec 30 06:18:16 volumio go-librespot[17065]: time="2025-12-30T06:18:16-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 " Dec 30 06:18:16 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 06:18:16 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 06:18:16 volumio volumio[16953]: info: Loading plugin "alarm-clock"... Dec 30 06:18:16 volumio volumio[16953]: info: Loading plugin "airplay_emulation"... Dec 30 06:18:16 volumio volumio[16953]: info: Starting Shairport Sync Dec 30 06:18:16 volumio volumio[16953]: info: Loading plugin "last_100"... Dec 30 06:18:16 volumio volumio[16953]: info: Loading plugin "webradio"... Dec 30 06:18:16 volumio volumio[16953]: info: Loading plugin "i2s_dacs"... Dec 30 06:18:16 volumio volumio[16953]: info: I2S DAC not set, start Auto-detection Dec 30 06:18:16 volumio volumio[16953]: info: Loading plugin "volumiodiscovery"... Dec 30 06:18:16 volumio volumio[16953]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 30 06:18:16 volumio volumio[16953]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 30 06:18:16 volumio volumio[16953]: *** WARNING *** For more information see Dec 30 06:18:16 volumio volumio[16953]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 30 06:18:16 volumio volumio[16953]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 30 06:18:16 volumio volumio[16953]: *** WARNING *** For more information see Dec 30 06:18:16 volumio node[16953]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 30 06:18:16 volumio node[16953]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 30 06:18:16 volumio node[16953]: *** WARNING *** For more information see Dec 30 06:18:16 volumio node[16953]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 30 06:18:16 volumio node[16953]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 30 06:18:16 volumio node[16953]: *** WARNING *** For more information see Dec 30 06:18:16 volumio volumio[16953]: info: Applying required configuration parameters for plugin volumiodiscovery Dec 30 06:18:16 volumio volumio[16953]: info: Discovery: Started advertising with name: Volumio Dec 30 06:18:16 volumio volumio[16953]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 30 06:18:16 volumio volumio[16953]: info: Loading plugin "bandcamp"... Dec 30 06:18:18 volumio volumio[16953]: info: Plugin calmradio is not enabled Dec 30 06:18:18 volumio volumio[16953]: info: Loading plugin "soundcloud"... Dec 30 06:18:18 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.214.89 Dec 30 06:18:18 volumio avahi-daemon[664]: Registering new address record for 169.254.214.89 on eth0.IPv4. Dec 30 06:18:18 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Dec 30 06:18:18 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:18:18 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 06:18:18 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:18:18 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.214.89 Dec 30 06:18:18 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.214.89 Dec 30 06:18:18 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.214.89 Dec 30 06:18:18 volumio avahi-daemon[664]: Withdrawing address record for 169.254.214.89 on eth0. Dec 30 06:18:18 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Dec 30 06:18:19 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Dec 30 06:18:19 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:18:19 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 06:18:19 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:18:19 volumio volumio[16953]: info: Loading plugin "spop"... Dec 30 06:18:19 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 25. Dec 30 06:18:19 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 06:18:19 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 06:18:19 volumio go-librespot[17106]: go-librespot daemon starting... Dec 30 06:18:19 volumio go-librespot[17107]: time="2025-12-30T06:18:19-06:00" level=info msg="running go-librespot 0.4.0" Dec 30 06:18:19 volumio go-librespot[17107]: time="2025-12-30T06:18:19-06:00" level=debug msg="app state loaded" Dec 30 06:18:19 volumio go-librespot[17107]: time="2025-12-30T06:18:19-06:00" level=debug msg="stored credentials not found" Dec 30 06:18:19 volumio go-librespot[17107]: time="2025-12-30T06:18:19-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 06:18:19 volumio go-librespot[17107]: time="2025-12-30T06:18: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-gew4.spotify.com:80]" Dec 30 06:18:19 volumio go-librespot[17107]: time="2025-12-30T06:18:19-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]" Dec 30 06:18:19 volumio go-librespot[17107]: time="2025-12-30T06:18:19-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]" Dec 30 06:18:19 volumio go-librespot[17107]: time="2025-12-30T06:18:19-06:00" level=info msg="zeroconf server listening on port 43503" Dec 30 06:18:19 volumio go-librespot[17107]: time="2025-12-30T06:18:19-06:00" level=debug msg="obtained new client token: AAAnIuOUjcqE1vTpCX4NDipfTD0r7+stfGbFMn/3Y9ECKkpeTobCDQ9ck7ic+U4Hz9Tm53gZZF+jj9zem1Etmd5srZOhdvCs7VRl6AsgnhkDsOVIm03E16CW4w0jQ9taD2Fnt/8zWziqAxy6GU2u8PMz2Qey6SgJTVE5LR8mAVpXDdUG75GM4j1dzCCsneBPQgP9Q0XGrCYmG7ZBGKzfpQXeBw8tRJIaoFRvxJ1BH8et5SYhRS69r6ERxA==" Dec 30 06:18:20 volumio go-librespot[17107]: time="2025-12-30T06:18:20-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 06:18:20 volumio go-librespot[17107]: time="2025-12-30T06:18:20-06:00" level=debug msg="completed keyexchange" Dec 30 06:18:20 volumio go-librespot[17107]: time="2025-12-30T06:18:20-06:00" level=debug msg="completed challenge" Dec 30 06:18:20 volumio go-librespot[17107]: time="2025-12-30T06:18:20-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 " Dec 30 06:18:20 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 06:18:20 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 06:18:20 volumio volumio[16953]: info: Loading plugin "squeezelite_mc"... Dec 30 06:18:21 volumio volumio[16953]: info: Loading plugin "youtube2"... Dec 30 06:18:22 volumio volumio[16953]: info: Loading plugin "ytcr"... Dec 30 06:18:23 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 26. Dec 30 06:18:23 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 06:18:23 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 06:18:23 volumio go-librespot[17129]: go-librespot daemon starting... Dec 30 06:18:23 volumio go-librespot[17130]: time="2025-12-30T06:18:23-06:00" level=info msg="running go-librespot 0.4.0" Dec 30 06:18:23 volumio go-librespot[17130]: time="2025-12-30T06:18:23-06:00" level=debug msg="app state loaded" Dec 30 06:18:23 volumio go-librespot[17130]: time="2025-12-30T06:18:23-06:00" level=debug msg="stored credentials not found" Dec 30 06:18:23 volumio go-librespot[17130]: time="2025-12-30T06:18:23-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 06:18:23 volumio go-librespot[17130]: time="2025-12-30T06:18: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-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Dec 30 06:18:23 volumio go-librespot[17130]: time="2025-12-30T06:18:23-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]" Dec 30 06:18:23 volumio go-librespot[17130]: time="2025-12-30T06:18:23-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]" Dec 30 06:18:23 volumio go-librespot[17130]: time="2025-12-30T06:18:23-06:00" level=info msg="zeroconf server listening on port 33887" Dec 30 06:18:23 volumio go-librespot[17130]: time="2025-12-30T06:18:23-06:00" level=debug msg="obtained new client token: AABhsVBA8SjyuEiClkIIA+GmHmYkJc8w1NO0HPrbWLD76PPXdYM5fhbYbnBY4DXtLcRHoUuI1sRWsLIvoQvQ2pkZtSf7FHHxZIpsOZ1dlJ9j55aWOaocbE0uBKVAQdaknQFuXs3dhLpfM9o1hIQe8AbNzcjekZKxR2SZn7oQMxyU+9Szl3pb7thBsGNSBls4oLEwhbuSp2okwdH4xP/4IOo/4AT64CwHW8kFtpOFmYUATg8DW7mATQUyfA==" Dec 30 06:18:23 volumio volumio[16953]: info: Loading plugin "ytmusic"... Dec 30 06:18:23 volumio go-librespot[17130]: time="2025-12-30T06:18:23-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 06:18:23 volumio go-librespot[17130]: time="2025-12-30T06:18:23-06:00" level=debug msg="completed keyexchange" Dec 30 06:18:23 volumio go-librespot[17130]: time="2025-12-30T06:18:23-06:00" level=debug msg="completed challenge" Dec 30 06:18:23 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.214.176 Dec 30 06:18:23 volumio avahi-daemon[664]: Registering new address record for 169.254.214.176 on eth0.IPv4. Dec 30 06:18:23 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Dec 30 06:18:23 volumio go-librespot[17130]: time="2025-12-30T06:18: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 " Dec 30 06:18:23 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 06:18:23 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 06:18:23 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:18:23 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 06:18:23 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:18:24 volumio volumio[16953]: info: Plugin now_playing is not enabled Dec 30 06:18:24 volumio volumio[16953]: info: Loading plugin "outputs"... Dec 30 06:18:24 volumio volumio[16953]: info: Loading plugin "albumart"... Dec 30 06:18:24 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.214.176 Dec 30 06:18:24 volumio volumio[16953]: info: Plugin example_plugin is not enabled Dec 30 06:18:24 volumio volumio[16953]: info: Loading plugin "inputs"... Dec 30 06:18:24 volumio volumio[16953]: info: Loading plugin "updater_comm"... Dec 30 06:18:24 volumio volumio[16953]: info: Plugin mpdemulation is not enabled Dec 30 06:18:24 volumio volumio[16953]: info: Loading plugin "rest_api"... Dec 30 06:18:24 volumio volumio[16953]: info: Loading plugin "websocket"... Dec 30 06:18:24 volumio volumio[16953]: info: Starting Socket.io Server version 1.7.4 Dec 30 06:18:24 volumio volumio[16953]: info: Plugin fusiondsp is not enabled Dec 30 06:18:24 volumio volumio[16953]: info: Plugin mpdoutput is not enabled Dec 30 06:18:24 volumio volumio[16953]: info: Plugin RoonBridge is not enabled Dec 30 06:18:24 volumio volumio[16953]: info: Loading plugin "podcast"... Dec 30 06:18:25 volumio volumio[16953]: info: ControllerPodcast::constructor Dec 30 06:18:25 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.214.176 Dec 30 06:18:25 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.214.176 Dec 30 06:18:25 volumio avahi-daemon[664]: Withdrawing address record for 169.254.214.176 on eth0. Dec 30 06:18:25 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Dec 30 06:18:25 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:18:25 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 06:18:25 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:18:25 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Dec 30 06:18:25 volumio volumio[16953]: info: Loading plugin "volusonic"... Dec 30 06:18:25 volumio volumio[17153]: Forking 3 albumart workers Dec 30 06:18:25 volumio volumio-remote-updater[702]: [2025-12-30 06:18:25] [connect] Successful connection Dec 30 06:18:26 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 27. Dec 30 06:18:26 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 06:18:27 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 06:18:27 volumio go-librespot[17212]: go-librespot daemon starting... Dec 30 06:18:27 volumio go-librespot[17213]: time="2025-12-30T06:18:27-06:00" level=info msg="running go-librespot 0.4.0" Dec 30 06:18:27 volumio go-librespot[17213]: time="2025-12-30T06:18:27-06:00" level=debug msg="app state loaded" Dec 30 06:18:27 volumio go-librespot[17213]: time="2025-12-30T06:18:27-06:00" level=debug msg="stored credentials not found" Dec 30 06:18:27 volumio go-librespot[17213]: time="2025-12-30T06:18:27-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 06:18:27 volumio go-librespot[17213]: time="2025-12-30T06:18: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-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Dec 30 06:18:27 volumio go-librespot[17213]: time="2025-12-30T06:18:27-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]" Dec 30 06:18:27 volumio go-librespot[17213]: time="2025-12-30T06:18:27-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]" Dec 30 06:18:27 volumio go-librespot[17213]: time="2025-12-30T06:18:27-06:00" level=info msg="zeroconf server listening on port 37967" Dec 30 06:18:27 volumio go-librespot[17213]: time="2025-12-30T06:18:27-06:00" level=debug msg="obtained new client token: AACItJEWBUL7qNeXA2gt3XrW1yZ6AXpSyIQMRtyURQH7es3M6KAsOi2JP1BU2QmuaZeXlkGiFs14xEQmx0uR26i1sPkeiWpsvY/ZSI51xwTKm1aOrQxQkIGs2uybHXGS9frQQ9WZuYrp7hcLmpAIGvQ78CsB8bKbAPKyJiA/iP2tqwaAaa9XVtp92A6hnA73Xe9XJ67d9lF6h/2sRU0HLpElmiKzo4Sw7Dwck56kdtRrnar5e9ouEeT3Yw==" Dec 30 06:18:27 volumio go-librespot[17213]: time="2025-12-30T06:18:27-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 06:18:27 volumio go-librespot[17213]: time="2025-12-30T06:18:27-06:00" level=debug msg="completed keyexchange" Dec 30 06:18:27 volumio go-librespot[17213]: time="2025-12-30T06:18:27-06:00" level=debug msg="completed challenge" Dec 30 06:18:27 volumio go-librespot[17213]: time="2025-12-30T06:18:27-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 " Dec 30 06:18:27 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 06:18:27 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 06:18:27 volumio volumio[16953]: info: Applying required configuration parameters for plugin volusonic Dec 30 06:18:27 volumio volumio[16953]: info: Loading plugin "backup_restore"... Dec 30 06:18:28 volumio volumio[17182]: Starting albumart workers Dec 30 06:18:28 volumio volumio[17183]: Starting albumart workers Dec 30 06:18:28 volumio volumio[17184]: Starting albumart workers Dec 30 06:18:28 volumio volumio[16953]: info: Applying required configuration parameters for plugin backup_restore Dec 30 06:18:28 volumio volumio[16953]: info: Plugin rpi_eeprom_config is not enabled Dec 30 06:18:28 volumio volumio[16953]: info: Plugin rpi_eeprom_updater is not enabled Dec 30 06:18:28 volumio volumio[16953]: info: Loading plugin "scheduledrestart"... Dec 30 06:18:28 volumio volumio[16953]: info: Applying required configuration parameters for plugin scheduledrestart Dec 30 06:18:28 volumio volumio[16953]: info: Plugin Bluetoothremote is not enabled Dec 30 06:18:28 volumio volumio[16953]: info: Plugin music_services_shield is not enabled Dec 30 06:18:28 volumio volumio[16953]: info: Loading plugin "Systeminfo"... Dec 30 06:18:29 volumio volumio[16953]: info: Plugin peppymeterbasic is not enabled Dec 30 06:18:29 volumio volumio[16953]: info: Loading plugin "peppyspectrum"... Dec 30 06:18:29 volumio volumio[16953]: info: Loading i18n strings for locale en Dec 30 06:18:29 volumio volumio[16953]: info: Plugin peppyspectrum has duplicated i18n key SAVE. It is ignored. Dec 30 06:18:29 volumio volumio[16953]: Updating browse sources language Dec 30 06:18:29 volumio volumio[16953]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 06:18:30 volumio volumio[16953]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 30 06:18:30 volumio volumio[16953]: info: CoreCommandRouter::initPlayerControls Dec 30 06:18:30 volumio volumio[16953]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:18:30 volumio volumio[16953]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:18:30 volumio volumio[16953]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:18:30 volumio volumio[16953]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:18:30 volumio volumio[16953]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:18:30 volumio volumio[16953]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:18:30 volumio volumio[16953]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:18:30 volumio volumio[16953]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:18:30 volumio volumio[16953]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 30 06:18:30 volumio volumio[16953]: Express server listening on port 3000 Dec 30 06:18:30 volumio volumio[16953]: [Metrics] WebUI: 19s 966.92ms Dec 30 06:18:30 volumio volumio[16953]: info: CoreStateMachine::resetVolumioState Dec 30 06:18:30 volumio volumio[16953]: info: CoreStateMachine::getcurrentVolume Dec 30 06:18:30 volumio volumio[16953]: info: CoreCommandRouter::volumioRetrievevolume Dec 30 06:18:30 volumio volumio[16953]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 06:18:30 volumio sudo[17243]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 30 06:18:30 volumio sudo[17243]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:18:30 volumio sudo[17245]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 30 06:18:30 volumio sudo[17245]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:18:30 volumio sudo[17245]: pam_unix(sudo:session): session closed for user root Dec 30 06:18:30 volumio sudo[17243]: pam_unix(sudo:session): session closed for user root Dec 30 06:18:30 volumio volumio[16953]: info: Volumio Network Manager: Network status updated: 1 Dec 30 06:18:30 volumio volumio-remote-updater[702]: [2025-12-30 06:18:30] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1767097105 101 Dec 30 06:18:30 volumio volumio[16953]: 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 Dec 30 06:18:30 volumio volumio[16953]: info: VolumeController:: Volume=100 Mute =false Dec 30 06:18:30 volumio volumio[16953]: info: CoreStateMachine::pushState Dec 30 06:18:30 volumio volumio[16953]: info: CorePlayQueue::getTrack 0 Dec 30 06:18:30 volumio volumio[16953]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 30 06:18:30 volumio volumio[16953]: info: CoreCommandRouter::volumioPushState Dec 30 06:18:30 volumio volumio[16953]: info: CoreStateMachine::updateTrackBlock Dec 30 06:18:30 volumio volumio[16953]: info: CorePlayQueue::getTrackBlock Dec 30 06:18:30 volumio volumio[16953]: info: CoreCommandRouter::volumioRetrievevolume Dec 30 06:18:30 volumio volumio[16953]: info: Reloading queue from file Dec 30 06:18:30 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.71.191 Dec 30 06:18:30 volumio avahi-daemon[664]: Registering new address record for 169.254.71.191 on eth0.IPv4. Dec 30 06:18:30 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Dec 30 06:18:30 volumio volumio[16953]: info: CoreStateMachine::setRepeat null single undefined Dec 30 06:18:30 volumio volumio[16953]: info: CoreStateMachine::pushState Dec 30 06:18:30 volumio volumio[16953]: info: CorePlayQueue::getTrack 0 Dec 30 06:18:30 volumio volumio[16953]: info: CoreCommandRouter::volumioPushState Dec 30 06:18:30 volumio volumio[16953]: info: CoreStateMachine::setRandom null Dec 30 06:18:30 volumio volumio[16953]: info: CoreStateMachine::pushState Dec 30 06:18:30 volumio volumio[16953]: info: CorePlayQueue::getTrack 0 Dec 30 06:18:30 volumio volumio[16953]: info: CoreCommandRouter::volumioPushState Dec 30 06:18:30 volumio volumio[16953]: info: Setting Device type: Raspberry PI Dec 30 06:18:30 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:18:30 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 06:18:30 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:18:30 volumio volumio[16953]: info: VolumeController:: Volume=100 Mute =false Dec 30 06:18:30 volumio volumio[16953]: info: CoreStateMachine::pushState Dec 30 06:18:30 volumio volumio[16953]: info: CorePlayQueue::getTrack 0 Dec 30 06:18:30 volumio volumio[16953]: info: CoreCommandRouter::volumioPushState Dec 30 06:18:30 volumio volumio[16953]: info: Completed loading Core Plugins Dec 30 06:18:30 volumio volumio[16953]: info: Preparing to generate the ALSA configuration file Dec 30 06:18:30 volumio sudo[17274]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Dec 30 06:18:30 volumio sudo[17274]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:18:30 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 28. Dec 30 06:18:30 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 06:18:30 volumio volumio[16953]: info: Discovery: adding a135e40e-a404-457b-98f5-36bf71c75954 Dec 30 06:18:30 volumio volumio[16953]: info: Discovery: Found device Volumio Dec 30 06:18:30 volumio volumio[16953]: info: CoreCommandRouter::volumioGetState Dec 30 06:18:30 volumio volumio[16953]: info: CorePlayQueue::getTrack 0 Dec 30 06:18:30 volumio volumio[16953]: info: Discovery: this is already registered, a135e40e-a404-457b-98f5-36bf71c75954 Dec 30 06:18:30 volumio volumio[16953]: info: Discovery: Found device Volumio Dec 30 06:18:30 volumio volumio[16953]: info: CoreCommandRouter::volumioGetState Dec 30 06:18:30 volumio volumio[16953]: info: CorePlayQueue::getTrack 0 Dec 30 06:18:31 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 06:18:31 volumio go-librespot[17276]: go-librespot daemon starting... Dec 30 06:18:31 volumio volumio[16953]: info: The plugin peppyspectrum has an ALSA contribution file peppy_in.peppy_out.6.conf Dec 30 06:18:31 volumio volumio[16953]: info: Reading ALSA contributions from plugins. Dec 30 06:18:31 volumio volumio[16953]: info: Asound.conf file unchanged, so no further update is needed Dec 30 06:18:31 volumio volumio[16953]: info: Output device has changed, restarting MPD Dec 30 06:18:31 volumio go-librespot[17277]: time="2025-12-30T06:18:31-06:00" level=info msg="running go-librespot 0.4.0" Dec 30 06:18:31 volumio go-librespot[17277]: time="2025-12-30T06:18:31-06:00" level=debug msg="app state loaded" Dec 30 06:18:31 volumio go-librespot[17277]: time="2025-12-30T06:18:31-06:00" level=debug msg="stored credentials not found" Dec 30 06:18:31 volumio go-librespot[17277]: time="2025-12-30T06:18:31-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 06:18:31 volumio sudo[17274]: pam_unix(sudo:session): session closed for user root Dec 30 06:18:31 volumio volumio[16953]: info: Output device has changed, restarting Shairport Sync Dec 30 06:18:31 volumio volumio[16953]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:18:31 volumio volumio[16953]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 06:18:31 volumio sudo[17284]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 30 06:18:31 volumio sudo[17284]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:18:31 volumio sudo[17286]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 30 06:18:31 volumio sudo[17284]: pam_unix(sudo:session): session closed for user root Dec 30 06:18:31 volumio sudo[17286]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:18:31 volumio volumio[16953]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 30 06:18:31 volumio volumio[16953]: info: ___________ START PLUGINS ___________ Dec 30 06:18:31 volumio volumio[16953]: info: ControllerMpd::onStart: Initializing MPD Dec 30 06:18:31 volumio volumio[16953]: info: Creating MPD Configuration file Dec 30 06:18:31 volumio volumio[16953]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 30 06:18:31 volumio volumio[16953]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 06:18:31 volumio volumio[16953]: info: [1767097111258] CoreMusicLibrary::Adding element Media Servers Dec 30 06:18:31 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Dec 30 06:18:31 volumio volumio[16953]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 06:18:31 volumio sudo[17294]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 30 06:18:31 volumio sudo[17294]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:18:31 volumio sudo[17296]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 30 06:18:31 volumio sudo[17296]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:18:31 volumio sudo[17294]: pam_unix(sudo:session): session closed for user root Dec 30 06:18:31 volumio volumio[16953]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:18:31 volumio volumio[16953]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 06:18:31 volumio volumio[16953]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 30 06:18:31 volumio volumio[16953]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:18:31 volumio volumio[16953]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 06:18:31 volumio systemd[1]: mpd.service: Deactivated successfully. Dec 30 06:18:31 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 30 06:18:31 volumio systemd[1]: mpd.service: Consumed 5.596s CPU time. Dec 30 06:18:31 volumio systemd[1]: mpd.socket: Deactivated successfully. Dec 30 06:18:31 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 30 06:18:31 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 30 06:18:31 volumio volumio[16953]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 30 06:18:31 volumio volumio[16953]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 06:18:31 volumio volumio[16953]: info: [1767097111506] CoreMusicLibrary::Adding element Last_100 Dec 30 06:18:31 volumio volumio[16953]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 06:18:31 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.71.191 Dec 30 06:18:31 volumio volumio[16953]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 06:18:31 volumio volumio[16953]: info: [1767097111517] CoreMusicLibrary::Adding element Webradio Dec 30 06:18:31 volumio volumio[16953]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 06:18:31 volumio volumio[16953]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 30 06:18:31 volumio volumio[16953]: info: Initializing BBC Radios Dec 30 06:18:31 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 30 06:18:31 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Dec 30 06:18:31 volumio go-librespot[17277]: time="2025-12-30T06:18:31-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]" Dec 30 06:18:31 volumio go-librespot[17277]: time="2025-12-30T06:18:31-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]" Dec 30 06:18:31 volumio go-librespot[17277]: time="2025-12-30T06:18:31-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]" Dec 30 06:18:31 volumio go-librespot[17277]: time="2025-12-30T06:18:31-06:00" level=info msg="zeroconf server listening on port 46079" Dec 30 06:18:31 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.71.191 Dec 30 06:18:31 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.71.191 Dec 30 06:18:31 volumio avahi-daemon[664]: Withdrawing address record for 169.254.71.191 on eth0. Dec 30 06:18:31 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Dec 30 06:18:31 volumio volumio[16953]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 30 06:18:31 volumio volumio[16953]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 06:18:31 volumio volumio[16953]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 06:18:31 volumio volumio[16953]: info: [1767097111619] CoreMusicLibrary::Adding element Bandcamp Discover Dec 30 06:18:31 volumio volumio[16953]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 06:18:31 volumio volumio[16953]: Cannot find translation for source Bandcamp Discover Dec 30 06:18:31 volumio volumio[16953]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 06:18:31 volumio volumio[16953]: info: [1767097111641] CoreMusicLibrary::Adding element SoundCloud Dec 30 06:18:31 volumio volumio[16953]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 06:18:31 volumio volumio[16953]: Cannot find translation for source Bandcamp Discover Dec 30 06:18:31 volumio volumio[16953]: Cannot find translation for source SoundCloud Dec 30 06:18:31 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:18:31 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 06:18:31 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:18:31 volumio volumio[16953]: info: Creating Spotify config file Dec 30 06:18:31 volumio volumio[16953]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:18:31 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Dec 30 06:18:31 volumio go-librespot[17277]: time="2025-12-30T06:18:31-06:00" level=debug msg="obtained new client token: AAAGMiUNR/TgYIFOOEzcYn7xTt9dMFI/i4w6gpUO2PV9fMLdLwdRZ7vrOqL/RCps2aLb7jbqqz5QRIZ4sMpOf7PU2ZRtsl2fjC54+sDs08khFm6l3wJUCS+Qf7VEybpIRlEUZAsEQkMvgXr/zrTnnAEk8ic+EX6ygngK9XOJqDdaPli9YvWtadswk02Rzrv+SBfDUR//YOt3F20trxAFLTz6osdoHFYpWuDHeVjPx61lE8MARCQW1jOLJA==" Dec 30 06:18:31 volumio go-librespot[17277]: time="2025-12-30T06:18:31-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 06:18:31 volumio sudo[17314]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 30 06:18:31 volumio sudo[17314]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 30 06:18:31 volumio go-librespot[17277]: time="2025-12-30T06:18:31-06:00" level=debug msg="completed keyexchange" Dec 30 06:18:31 volumio go-librespot[17277]: time="2025-12-30T06:18:31-06:00" level=debug msg="completed challenge" Dec 30 06:18:31 volumio sudo[17314]: pam_unix(sudo:session): session closed for user root Dec 30 06:18:31 volumio go-librespot[17277]: time="2025-12-30T06:18:31-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 " Dec 30 06:18:31 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 06:18:31 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 06:18:32 volumio volumio[16953]: info: [squeezelite_mc] Starting proxy server... Dec 30 06:18:32 volumio volumio[16953]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 06:18:32 volumio volumio[16953]: info: [1767097112033] CoreMusicLibrary::Adding element YouTube2 Dec 30 06:18:32 volumio volumio[16953]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 06:18:32 volumio volumio[16953]: Cannot find translation for source Bandcamp Discover Dec 30 06:18:32 volumio volumio[16953]: Cannot find translation for source SoundCloud Dec 30 06:18:32 volumio volumio[16953]: Cannot find translation for source YouTube2 Dec 30 06:18:32 volumio volumio[16953]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 06:18:32 volumio volumio[16953]: info: [1767097112054] CoreMusicLibrary::Adding element YouTube Music Dec 30 06:18:32 volumio volumio[16953]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 06:18:32 volumio volumio[16953]: Cannot find translation for source Bandcamp Discover Dec 30 06:18:32 volumio volumio[16953]: Cannot find translation for source SoundCloud Dec 30 06:18:32 volumio volumio[16953]: Cannot find translation for source YouTube2 Dec 30 06:18:32 volumio volumio[16953]: Cannot find translation for source YouTube Music Dec 30 06:18:32 volumio volumio[16953]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 06:18:32 volumio volumio[16953]: info: [1767097112068] CoreMusicLibrary::Adding element Podcast Dec 30 06:18:32 volumio volumio[16953]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 06:18:32 volumio volumio[16953]: Cannot find translation for source Bandcamp Discover Dec 30 06:18:32 volumio volumio[16953]: Cannot find translation for source SoundCloud Dec 30 06:18:32 volumio volumio[16953]: Cannot find translation for source YouTube2 Dec 30 06:18:32 volumio volumio[16953]: Cannot find translation for source YouTube Music Dec 30 06:18:32 volumio volumio[16953]: Cannot find translation for source Podcast Dec 30 06:18:32 volumio volumio[16953]: info: Loading i18n strings for locale en Dec 30 06:18:32 volumio volumio[16953]: info: Plugin peppyspectrum has duplicated i18n key SAVE. It is ignored. Dec 30 06:18:32 volumio volumio[16953]: Updating browse sources language Dec 30 06:18:32 volumio volumio[16953]: Cannot find translation for source Bandcamp Discover Dec 30 06:18:32 volumio volumio[16953]: Cannot find translation for source SoundCloud Dec 30 06:18:32 volumio volumio[16953]: Cannot find translation for source YouTube2 Dec 30 06:18:32 volumio volumio[16953]: Cannot find translation for source YouTube Music Dec 30 06:18:32 volumio volumio[16953]: Cannot find translation for source Podcast Dec 30 06:18:32 volumio volumio[16953]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 06:18:32 volumio volumio[16953]: Cannot find translation for source Bandcamp Discover Dec 30 06:18:32 volumio volumio[16953]: Cannot find translation for source SoundCloud Dec 30 06:18:32 volumio volumio[16953]: Cannot find translation for source YouTube2 Dec 30 06:18:32 volumio volumio[16953]: Cannot find translation for source YouTube Music Dec 30 06:18:32 volumio volumio[16953]: Cannot find translation for source Podcast Dec 30 06:18:32 volumio volumio[16953]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 06:18:32 volumio volumio[16953]: info: [1767097112127] CoreMusicLibrary::Adding element Volusonic Dec 30 06:18:32 volumio volumio[16953]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 06:18:32 volumio volumio[16953]: Cannot find translation for source Bandcamp Discover Dec 30 06:18:32 volumio volumio[16953]: Cannot find translation for source SoundCloud Dec 30 06:18:32 volumio volumio[16953]: Cannot find translation for source YouTube2 Dec 30 06:18:32 volumio volumio[16953]: Cannot find translation for source YouTube Music Dec 30 06:18:32 volumio volumio[16953]: Cannot find translation for source Podcast Dec 30 06:18:32 volumio volumio[16953]: Cannot find translation for source Volusonic Dec 30 06:18:32 volumio volumio[16953]: info: Scheduling reboots with hours: 0, minutes: 0 in timezone: America/Chicago Dec 30 06:18:32 volumio volumio[16953]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , updateALSAConfigFile Dec 30 06:18:32 volumio volumio[16953]: info: Volumio Calling Home Dec 30 06:18:32 volumio volumio[16953]: info: [squeezelite_mc] Proxy server started on port 36901 Dec 30 06:18:32 volumio volumio[16953]: info: Preparing to generate the ALSA configuration file Dec 30 06:18:32 volumio volumio[16953]: info: CoreCommandRouter::volumioRetrievevolume Dec 30 06:18:32 volumio volumio[16953]: info: The plugin peppyspectrum has an ALSA contribution file peppy_in.peppy_out.6.conf Dec 30 06:18:32 volumio volumio[16953]: info: Reading ALSA contributions from plugins. Dec 30 06:18:32 volumio volumio[16953]: info: MPD Permissions set Dec 30 06:18:32 volumio volumio[16953]: info: MPD Permissions set Dec 30 06:18:32 volumio volumio[16953]: info: Upmpdcli Daemon Started Dec 30 06:18:32 volumio volumio[16953]: info: Spotify config file written Dec 30 06:18:32 volumio sudo[17349]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 30 06:18:32 volumio sudo[17349]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:18:32 volumio volumio[16953]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Dec 30 06:18:32 volumio volumio[16953]: info: VolumeController:: Volume=100 Mute =false Dec 30 06:18:32 volumio volumio[16953]: info: CoreStateMachine::pushState Dec 30 06:18:32 volumio volumio[16953]: info: CorePlayQueue::getTrack 0 Dec 30 06:18:32 volumio volumio[16953]: info: CoreCommandRouter::volumioPushState Dec 30 06:18:32 volumio volumio[16953]: info: [squeezelite_mc] Server discovery started Dec 30 06:18:32 volumio volumio[16953]: info: [squeezelite_mc] Player finder started Dec 30 06:18:32 volumio volumio[16953]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:18:32 volumio volumio[16953]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:18:32 volumio volumio[16953]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:18:32 volumio volumio[16953]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 30 06:18:32 volumio volumio[16953]: info: [squeezelite_mc] Executing aplay -D hw:1 --nonblock -f MPEG /dev/zero 2>&1 || true Dec 30 06:18:32 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 06:18:32 volumio volumio[16953]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:18:32 volumio volumio[16953]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:18:32 volumio volumio[16953]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:18:32 volumio volumio[16953]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:18:32 volumio volumio[16953]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:18:32 volumio volumio[16953]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:18:32 volumio volumio[16953]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:18:32 volumio volumio[16953]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:18:32 volumio volumio[16953]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 06:18:32 volumio volumio[16953]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:18:32 volumio volumio[16953]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:18:32 volumio volumio[16953]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:18:32 volumio volumio[16953]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:18:32 volumio volumio[16953]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:18:32 volumio volumio[16953]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:18:32 volumio volumio[16953]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:18:32 volumio volumio[16953]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:18:32 volumio volumio[16953]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:18:32 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 06:18:32 volumio go-librespot[17352]: go-librespot daemon starting... Dec 30 06:18:32 volumio volumio[16953]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 06:18:32 volumio volumio[16953]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:18:32 volumio sudo[17349]: pam_unix(sudo:session): session closed for user root Dec 30 06:18:32 volumio volumio[16953]: info: No need to fix Spotify hosts Dec 30 06:18:32 volumio go-librespot[17363]: time="2025-12-30T06:18:32-06:00" level=info msg="running go-librespot 0.4.0" Dec 30 06:18:32 volumio go-librespot[17363]: time="2025-12-30T06:18:32-06:00" level=debug msg="app state loaded" Dec 30 06:18:32 volumio go-librespot[17363]: time="2025-12-30T06:18:32-06:00" level=debug msg="stored credentials not found" Dec 30 06:18:32 volumio go-librespot[17363]: time="2025-12-30T06:18:32-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 06:18:32 volumio volumio[16953]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Dec 30 06:18:32 volumio volumio[16953]: info: Volumio called home Dec 30 06:18:32 volumio go-librespot[17363]: time="2025-12-30T06:18:32-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]" Dec 30 06:18:32 volumio go-librespot[17363]: time="2025-12-30T06:18:32-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]" Dec 30 06:18:32 volumio go-librespot[17363]: time="2025-12-30T06:18:32-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]" Dec 30 06:18:32 volumio go-librespot[17363]: time="2025-12-30T06:18:32-06:00" level=info msg="zeroconf server listening on port 42599" Dec 30 06:18:32 volumio volumio[16953]: info: [squeezelite_mc] Card 1 supports the following ALSA formats: ["U8","S16_LE"] Dec 30 06:18:32 volumio volumio[16953]: info: [squeezelite_mc] Starting Squeezelite service with params: {"type":"basic","playerName":"volumio","dsdFormat":null,"card":"1","mixerType":"Hardware","mixer":"PCM"} Dec 30 06:18:32 volumio volumio[16953]: 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 Dec 30 06:18:33 volumio volumio[16953]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 30 06:18:33 volumio volumio[16953]: SPOTIFY: BQA6_9FPU-lrKLf1d-_2xuNmqyrKoroNSskpnbTo18_dxXkP-6UpVpNTSVX2h2Y4U86oc4D69WFoL8ZHVvvqZrgyFaAf0-ec-J55FbGsvk6mFYWQQKqcWmTmwkYK5fu1RdL-nhTxqZmLirNHLclKFJS_t6Q9Dn-y-5LAnNd9g45S1y6zvbbyjB3eXOLwHLTWrzsX6ZluY0QDDsyxjH64xuvlN6nlB_YUA7nO2p0 Dec 30 06:18:33 volumio volumio[16953]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 30 06:18:33 volumio volumio[16953]: info: New Spotify access token = BQA6_9FPU-lrKLf1d-_2xuNmqyrKoroNSskpnbTo18_dxXkP-6UpVpNTSVX2h2Y4U86oc4D69WFoL8ZHVvvqZrgyFaAf0-ec-J55FbGsvk6mFYWQQKqcWmTmwkYK5fu1RdL-nhTxqZmLirNHLclKFJS_t6Q9Dn-y-5LAnNd9g45S1y6zvbbyjB3eXOLwHLTWrzsX6ZluY0QDDsyxjH64xuvlN6nlB_YUA7nO2p0 Dec 30 06:18:33 volumio volumio[16953]: info: Spotify credentials grant success - running version from March 24, 2019 Dec 30 06:18:33 volumio sudo[17384]: 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 Dec 30 06:18:33 volumio sudo[17384]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:18:33 volumio volumio[16953]: info: Starting Shairport Sync Dec 30 06:18:33 volumio sudo[17384]: pam_unix(sudo:session): session closed for user root Dec 30 06:18:33 volumio volumio[16953]: info: Starting Shairport Sync Dec 30 06:18:33 volumio go-librespot[17363]: time="2025-12-30T06:18:33-06:00" level=debug msg="obtained new client token: AAAh1LkBa3JvqPN6ZGRpM/L8hBLvMC5Jwch8scgEFhna4oomgDBsNSC990TFwzN3PoTQqwaqA7792d8sADVQfeFdtPYD7bNjP4a4LMbVdOyHipT8Ui2hcamqPbFvBJNfUik7EKveaH641LYLOFrx+vSuK0fR0vjD9OClsaiYh9dnxyP0YG+rTtPRR30lSI0y3V8TU5Pk5m0OG4HxQPpkPphM8rFqfyYM2o48JCn8jjsu14aTzUCVJvs=" Dec 30 06:18:33 volumio volumio[16953]: info: Starting Shairport Sync Dec 30 06:18:33 volumio sudo[17391]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 30 06:18:33 volumio sudo[17391]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:18:33 volumio sudo[17393]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 30 06:18:33 volumio sudo[17393]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:18:33 volumio go-librespot[17363]: time="2025-12-30T06:18:33-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 06:18:33 volumio sudo[17396]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 30 06:18:33 volumio sudo[17396]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:18:33 volumio go-librespot[17363]: time="2025-12-30T06:18:33-06:00" level=debug msg="completed keyexchange" Dec 30 06:18:33 volumio go-librespot[17363]: time="2025-12-30T06:18:33-06:00" level=debug msg="completed challenge" Dec 30 06:18:33 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 30 06:18:33 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Dec 30 06:18:33 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 30 06:18:33 volumio systemd[1]: shairport-sync.service: Consumed 2.048s CPU time. Dec 30 06:18:33 volumio go-librespot[17363]: time="2025-12-30T06:18:33-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 " Dec 30 06:18:33 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 30 06:18:33 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 06:18:33 volumio sudo[17396]: pam_unix(sudo:session): session closed for user root Dec 30 06:18:33 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 06:18:33 volumio sudo[17393]: pam_unix(sudo:session): session closed for user root Dec 30 06:18:33 volumio sudo[17391]: pam_unix(sudo:session): session closed for user root Dec 30 06:18:33 volumio volumio[16953]: info: [squeezelite_mc] Executing alsactl -L -R nrestore Dec 30 06:18:33 volumio volumio[16953]: info: Asound.conf file unchanged, so no further update is needed Dec 30 06:18:33 volumio volumio[16953]: info: Output device has changed, restarting MPD Dec 30 06:18:33 volumio sudo[17403]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/sbin/alsactl -L -R nrestore Dec 30 06:18:33 volumio sudo[17403]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:18:33 volumio volumio[16953]: info: Output device has changed, restarting Shairport Sync Dec 30 06:18:33 volumio volumio[16953]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:18:33 volumio volumio[16953]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 06:18:33 volumio sudo[17403]: pam_unix(sudo:session): session closed for user root Dec 30 06:18:33 volumio sudo[17405]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 30 06:18:33 volumio sudo[17421]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 30 06:18:33 volumio sudo[17421]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:18:33 volumio sudo[17405]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:18:33 volumio sudo[17405]: pam_unix(sudo:session): session closed for user root Dec 30 06:18:33 volumio volumio[16953]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 30 06:18:33 volumio systemd[1]: mpd.service: Deactivated successfully. Dec 30 06:18:33 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 30 06:18:33 volumio systemd[1]: mpd.service: Consumed 1.840s CPU time. Dec 30 06:18:33 volumio systemd[1]: mpd.socket: Deactivated successfully. Dec 30 06:18:33 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 30 06:18:33 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 30 06:18:33 volumio volumio[16953]: info: Shairport-Sync Started Dec 30 06:18:33 volumio volumio[16953]: Error adding Membership: Error: addMembership EINVAL Dec 30 06:18:33 volumio volumio[16953]: info: Shairport-Sync Started Dec 30 06:18:33 volumio volumio[16953]: info: Shairport-Sync Started Dec 30 06:18:33 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 30 06:18:33 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Dec 30 06:18:33 volumio volumio[16953]: info: MPD Permissions set Dec 30 06:18:33 volumio volumio[16953]: info: [squeezelite_mc] Executing cp /data/plugins/music_service/squeezelite_mc/dist/lib/../templates/systemd/squeezelite.service.template.out /etc/systemd/system/squeezelite.service Dec 30 06:18:33 volumio sudo[17436]: 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 Dec 30 06:18:33 volumio sudo[17436]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:18:33 volumio sudo[17436]: pam_unix(sudo:session): session closed for user root Dec 30 06:18:33 volumio volumio[16953]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:18:33 volumio volumio[16953]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:18:33 volumio volumio[16953]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:18:33 volumio volumio[16953]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:18:33 volumio volumio[16953]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:18:33 volumio volumio[16953]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:18:33 volumio volumio[16953]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:18:33 volumio volumio[16953]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:18:33 volumio volumio[16953]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 06:18:33 volumio volumio[16953]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:18:33 volumio volumio[16953]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl daemon-reload || true Dec 30 06:18:33 volumio volumio[16953]: info: CoreCommandRouter::volumioGetState Dec 30 06:18:33 volumio volumio[16953]: info: CorePlayQueue::getTrack 0 Dec 30 06:18:33 volumio sudo[17444]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl daemon-reload Dec 30 06:18:33 volumio volumio[16953]: info: Starting Shairport Sync Dec 30 06:18:33 volumio sudo[17444]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:18:33 volumio sudo[17433]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 30 06:18:33 volumio sudo[17433]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 30 06:18:34 volumio sudo[17433]: pam_unix(sudo:session): session closed for user root Dec 30 06:18:34 volumio volumio[16953]: 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"} Dec 30 06:18:34 volumio volumio[16953]: info: Spotify Successfully logged in Dec 30 06:18:34 volumio volumio[16953]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 06:18:34 volumio volumio[16953]: info: [1767097114049] CoreMusicLibrary::Adding element Spotify Dec 30 06:18:34 volumio volumio[16953]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 06:18:34 volumio volumio[16953]: Cannot find translation for source Bandcamp Discover Dec 30 06:18:34 volumio volumio[16953]: Cannot find translation for source SoundCloud Dec 30 06:18:34 volumio volumio[16953]: Cannot find translation for source YouTube2 Dec 30 06:18:34 volumio volumio[16953]: Cannot find translation for source YouTube Music Dec 30 06:18:34 volumio volumio[16953]: Cannot find translation for source Podcast Dec 30 06:18:34 volumio volumio[16953]: Cannot find translation for source Volusonic Dec 30 06:18:34 volumio volumio[16953]: Cannot find translation for source Spotify Dec 30 06:18:34 volumio sudo[17447]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 30 06:18:34 volumio sudo[17447]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:18:34 volumio systemd[1]: Reloading. Dec 30 06:18:35 volumio volumio[16953]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:18:35 volumio volumio[16953]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:18:35 volumio volumio[16953]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:18:35 volumio volumio[16953]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 30 06:18:35 volumio volumio[16953]: info: go-librespot daemon successfully initialized Dec 30 06:18:36 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. Dec 30 06:18:36 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. Dec 30 06:18:37 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.156.197 Dec 30 06:18:37 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Dec 30 06:18:37 volumio avahi-daemon[664]: Registering new address record for 169.254.156.197 on eth0.IPv4. Dec 30 06:18:37 volumio volumio[16953]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 30 06:18:37 volumio volumio[16953]: Error: addMembership ENODEV Dec 30 06:18:37 volumio volumio[16953]: at Socket.addMembership (node:dgram:860:11) Dec 30 06:18:37 volumio volumio[16953]: at addMembership (/volumio/node_modules/node-ssdp/lib/index.js:264:16) { Dec 30 06:18:37 volumio volumio[16953]: errno: -19, Dec 30 06:18:37 volumio volumio[16953]: code: 'ENODEV', Dec 30 06:18:37 volumio volumio[16953]: syscall: 'addMembership' Dec 30 06:18:37 volumio volumio[16953]: } Dec 30 06:18:37 volumio volumio[16953]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 30 06:18:37 volumio sudo[17444]: pam_unix(sudo:session): session closed for user root Dec 30 06:18:37 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 29. Dec 30 06:18:37 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:18:37 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 06:18:37 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:18:37 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 06:18:37 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 06:18:37 volumio go-librespot[17495]: go-librespot daemon starting... Dec 30 06:18:37 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 30 06:18:37 volumio go-librespot[17496]: time="2025-12-30T06:18:37-06:00" level=info msg="running go-librespot 0.4.0" Dec 30 06:18:37 volumio go-librespot[17496]: time="2025-12-30T06:18:37-06:00" level=debug msg="app state loaded" Dec 30 06:18:37 volumio go-librespot[17496]: time="2025-12-30T06:18:37-06:00" level=debug msg="stored credentials not found" Dec 30 06:18:37 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Dec 30 06:18:37 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 30 06:18:37 volumio systemd[1]: shairport-sync.service: Consumed 1.460s CPU time. Dec 30 06:18:37 volumio go-librespot[17496]: time="2025-12-30T06:18:37-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 06:18:37 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 30 06:18:37 volumio sudo[17447]: pam_unix(sudo:session): session closed for user root Dec 30 06:18:37 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.156.197 Dec 30 06:18:37 volumio go-librespot[17496]: time="2025-12-30T06:18: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]" Dec 30 06:18:37 volumio go-librespot[17496]: time="2025-12-30T06:18: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]" Dec 30 06:18:37 volumio go-librespot[17496]: time="2025-12-30T06:18: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]" Dec 30 06:18:37 volumio go-librespot[17496]: time="2025-12-30T06:18:37-06:00" level=info msg="zeroconf server listening on port 34889" Dec 30 06:18:37 volumio go-librespot[17496]: time="2025-12-30T06:18:37-06:00" level=debug msg="obtained new client token: AABqjqIwzNxO93VsTtFSuklYKXJpkUXKoiJSQXT9/7Km+P+OFSF5S96MW3dHLNvSsoU/nx2AwKLiK4Mrnw8AXRvfV7tJbXE9YkingM/MeJfJg71hyuhhyD4ldLhxbtWO8gNYBXd/4QybZY/5UX+lohNr/GXjVqHw3xmaKNSE+H7seu84ireRw0ouMXmfqKYduPv/I0hXpGDlBJWt5Reo/dJgNL+WT8UTgl+TXWFhAM/qp2fQuHtTReSIqw==" Dec 30 06:18:37 volumio go-librespot[17496]: time="2025-12-30T06:18:37-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 06:18:38 volumio go-librespot[17496]: time="2025-12-30T06:18:38-06:00" level=debug msg="completed keyexchange" Dec 30 06:18:38 volumio go-librespot[17496]: time="2025-12-30T06:18:38-06:00" level=debug msg="completed challenge" Dec 30 06:18:38 volumio go-librespot[17496]: time="2025-12-30T06:18: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 " Dec 30 06:18:38 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 06:18:38 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 06:18:38 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.156.197 Dec 30 06:18:38 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.156.197 Dec 30 06:18:38 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Dec 30 06:18:38 volumio avahi-daemon[664]: Withdrawing address record for 169.254.156.197 on eth0. Dec 30 06:18:38 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:18:38 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 06:18:38 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:18:38 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Dec 30 06:18:38 volumio sudo[17537]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-30 06:17' Dec 30 06:18:38 volumio sudo[17537]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:18:39 volumio sudo[17537]: pam_unix(sudo:session): session closed for user root Dec 30 06:18:39 volumio mpd[17449]: 2025-12-30T06:18:39 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Dec 30 06:18:40 volumio systemd[1]: Started mpd.service - Music Player Daemon. Dec 30 06:18:40 volumio sudo[17421]: pam_unix(sudo:session): session closed for user root Dec 30 06:18:40 volumio sudo[17296]: pam_unix(sudo:session): session closed for user root Dec 30 06:18:40 volumio sudo[17286]: pam_unix(sudo:session): session closed for user root Dec 30 06:18:40 volumio volumio-remote-updater[702]: [2025-12-30 06:18:40] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Dec 30 06:18:40 volumio volumio-remote-updater[702]: [2025-12-30 06:18:40] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Dec 30 06:18:40 volumio systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Dec 30 06:18:40 volumio systemd[1]: volumio.service: Failed with result 'exit-code'. Dec 30 06:18:40 volumio systemd[1]: volumio.service: Consumed 45.570s CPU time. Dec 30 06:18:40 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Dec 30 06:18:40 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Dec 30 06:18:40 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 395. Dec 30 06:18:40 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Dec 30 06:18:40 volumio systemd[1]: Stopped volumio.service - Volumio Backend Module. Dec 30 06:18:40 volumio systemd[1]: volumio.service: Consumed 45.570s CPU time. Dec 30 06:18:40 volumio systemd[1]: Started volumio.service - Volumio Backend Module. Dec 30 06:18:40 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Dec 30 06:18:41 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 30. Dec 30 06:18:41 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 06:18:41 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 06:18:41 volumio go-librespot[17573]: go-librespot daemon starting... Dec 30 06:18:41 volumio go-librespot[17574]: time="2025-12-30T06:18:41-06:00" level=info msg="running go-librespot 0.4.0" Dec 30 06:18:41 volumio go-librespot[17574]: time="2025-12-30T06:18:41-06:00" level=debug msg="app state loaded" Dec 30 06:18:41 volumio go-librespot[17574]: time="2025-12-30T06:18:41-06:00" level=debug msg="stored credentials not found" Dec 30 06:18:41 volumio go-librespot[17574]: time="2025-12-30T06:18:41-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 06:18:41 volumio go-librespot[17574]: time="2025-12-30T06:18: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]" Dec 30 06:18:41 volumio go-librespot[17574]: time="2025-12-30T06:18: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]" Dec 30 06:18:41 volumio go-librespot[17574]: time="2025-12-30T06:18: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]" Dec 30 06:18:41 volumio go-librespot[17574]: time="2025-12-30T06:18:41-06:00" level=info msg="zeroconf server listening on port 44005" Dec 30 06:18:41 volumio go-librespot[17574]: time="2025-12-30T06:18:41-06:00" level=debug msg="obtained new client token: AAB0WHc5sh981NKXvaVbBVr5FyMr5SznO1KYy9++g0I8zQnO4Am79SnJlCfRdVAXs85ZIGr9Z69icfIkt/vB+lZUrO4kR4cjzkGVEPUwo+7MxZA6/ClK30FBkh17oJ3pAd81scxptFv1F27kL9mFsygYwCguFL2QNQHYcMvlI8Q/35KRAn793n/okv1z7St6uzBeZRt3O7bdaad3RCW3onCCyChtyQVgnatx2s2UHBdnjRB70OZascmo0Q==" Dec 30 06:18:41 volumio go-librespot[17574]: time="2025-12-30T06:18:41-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 06:18:41 volumio go-librespot[17574]: time="2025-12-30T06:18:41-06:00" level=debug msg="completed keyexchange" Dec 30 06:18:41 volumio go-librespot[17574]: time="2025-12-30T06:18:41-06:00" level=debug msg="completed challenge" Dec 30 06:18:41 volumio go-librespot[17574]: time="2025-12-30T06:18:41-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 " Dec 30 06:18:41 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 06:18:41 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 06:18:42 volumio volumio[17558]: info: ------------------------------------------- Dec 30 06:18:42 volumio volumio[17558]: info: ----- Volumio3 ---- Dec 30 06:18:42 volumio volumio[17558]: info: ------------------------------------------- Dec 30 06:18:42 volumio volumio[17558]: info: ----- System startup ---- Dec 30 06:18:42 volumio volumio[17558]: info: ------------------------------------------- Dec 30 06:18:43 volumio volumio[17558]: info: MYVOLUMIO Environment detected Dec 30 06:18:43 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.152.13 Dec 30 06:18:43 volumio avahi-daemon[664]: Registering new address record for 169.254.152.13 on eth0.IPv4. Dec 30 06:18:43 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Dec 30 06:18:43 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:18:43 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 06:18:43 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:18:43 volumio volumio[17558]: info: Plugin folders cleanup Dec 30 06:18:43 volumio volumio[17558]: info: Scanning into folder /volumio/app/plugins/ Dec 30 06:18:43 volumio volumio[17558]: info: Scanning category audio_interface Dec 30 06:18:43 volumio volumio[17558]: info: Scanning category miscellanea Dec 30 06:18:43 volumio volumio[17558]: info: Scanning category music_service Dec 30 06:18:43 volumio volumio[17558]: info: Scanning category plugins.json Dec 30 06:18:43 volumio volumio[17558]: info: Scanning category system_controller Dec 30 06:18:43 volumio volumio[17558]: info: Scanning category user_interface Dec 30 06:18:43 volumio volumio[17558]: info: Scanning into folder /data/plugins/ Dec 30 06:18:43 volumio volumio[17558]: info: Scanning category audio_interface Dec 30 06:18:43 volumio volumio[17558]: info: Scanning category music_service Dec 30 06:18:43 volumio volumio[17558]: info: Scanning category system_controller Dec 30 06:18:43 volumio volumio[17558]: info: Scanning category system_hardware Dec 30 06:18:43 volumio volumio[17558]: info: Scanning category user_interface Dec 30 06:18:43 volumio volumio[17558]: info: Plugin folders cleanup completed Dec 30 06:18:43 volumio volumio[17558]: info: ------------------------------------------- Dec 30 06:18:43 volumio volumio[17558]: info: ----- Core plugins startup ---- Dec 30 06:18:43 volumio volumio[17558]: info: ------------------------------------------- Dec 30 06:18:43 volumio volumio[17558]: info: Loading plugins from folder /volumio/app/plugins/ Dec 30 06:18:43 volumio volumio[17558]: info: Adding plugin upnp to MyMusic Plugins Dec 30 06:18:43 volumio volumio[17558]: info: Adding plugin airplay_emulation to MyMusic Plugins Dec 30 06:18:43 volumio volumio[17558]: info: Adding plugin upnp_browser to MyMusic Plugins Dec 30 06:18:43 volumio volumio[17558]: info: Loading plugins from folder /data/plugins/ Dec 30 06:18:43 volumio volumio[17558]: info: Loading plugin "system"... Dec 30 06:18:43 volumio volumio[17558]: info: Loading plugin "appearance"... Dec 30 06:18:44 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.152.13 Dec 30 06:18:44 volumio kernel: hwmon hwmon1: Voltage normalised Dec 30 06:18:44 volumio volumio[17558]: info: Loading plugin "network"... Dec 30 06:18:44 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.152.13 Dec 30 06:18:44 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.152.13 Dec 30 06:18:44 volumio avahi-daemon[664]: Withdrawing address record for 169.254.152.13 on eth0. Dec 30 06:18:44 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Dec 30 06:18:44 volumio volumio[17558]: info: Refreshing Cached IP Addresses Dec 30 06:18:45 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 31. Dec 30 06:18:45 volumio sudo[17622]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 30 06:18:45 volumio sudo[17622]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:18:45 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:18:45 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 06:18:45 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:18:45 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Dec 30 06:18:45 volumio sudo[17627]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 30 06:18:45 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 06:18:45 volumio sudo[17627]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:18:45 volumio sudo[17622]: pam_unix(sudo:session): session closed for user root Dec 30 06:18:45 volumio volumio[17558]: info: Loading plugin "services"... Dec 30 06:18:45 volumio volumio[17558]: info: Loading plugin "alsa_controller"... Dec 30 06:18:45 volumio sudo[17627]: pam_unix(sudo:session): session closed for user root Dec 30 06:18:45 volumio sudo[17641]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Dec 30 06:18:45 volumio sudo[17641]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:18:45 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 06:18:45 volumio go-librespot[17646]: go-librespot daemon starting... Dec 30 06:18:45 volumio go-librespot[17660]: time="2025-12-30T06:18:45-06:00" level=info msg="running go-librespot 0.4.0" Dec 30 06:18:45 volumio go-librespot[17660]: time="2025-12-30T06:18:45-06:00" level=debug msg="app state loaded" Dec 30 06:18:45 volumio go-librespot[17660]: time="2025-12-30T06:18:45-06:00" level=debug msg="stored credentials not found" Dec 30 06:18:45 volumio go-librespot[17660]: time="2025-12-30T06:18:45-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 06:18:45 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 30 06:18:45 volumio volumio[17558]: info: Loading plugin "wizard"... Dec 30 06:18:45 volumio volumio[17558]: info: Loading plugin "networkfs"... Dec 30 06:18:45 volumio volumio[17558]: info: Starting Udev Watcher for removable devices Dec 30 06:18:45 volumio volumio-remote-updater[702]: [2025-12-30 06:18:45] [connect] Successful connection Dec 30 06:18:45 volumio volumio[17558]: info: Ignoring mount for partition: boot Dec 30 06:18:45 volumio volumio[17558]: info: Ignoring mount for partition: volumio Dec 30 06:18:45 volumio volumio[17558]: info: Ignoring mount for partition: volumio_data Dec 30 06:18:45 volumio volumio[17558]: info: Mounting Device Wikipedia Dec 30 06:18:45 volumio sudo[17678]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mount /dev/sda1 /mnt/USB/Wikipedia -o noatime Dec 30 06:18:45 volumio sudo[17678]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:18:45 volumio sudo[17678]: pam_unix(sudo:session): session closed for user root Dec 30 06:18:45 volumio volumio[17558]: mount: /media/Wikipedia: /dev/sda1 already mounted on /media/Wikipedia. Dec 30 06:18:45 volumio volumio[17558]: dmesg(1) may have more information after failed mount system call. Dec 30 06:18:45 volumio volumio[17558]: error: Failed to mount Wikipedia: Error: Command failed: /usr/bin/sudo /bin/mount "/dev/sda1" "/mnt/USB/Wikipedia" -o noatime Dec 30 06:18:45 volumio volumio[17558]: mount: /media/Wikipedia: /dev/sda1 already mounted on /media/Wikipedia. Dec 30 06:18:45 volumio volumio[17558]: dmesg(1) may have more information after failed mount system call. Dec 30 06:18:45 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 30 06:18:45 volumio volumio[17558]: info: Loading plugin "volumio_command_line_client"... Dec 30 06:18:45 volumio volumio[17558]: info: Loading plugin "upnp"... Dec 30 06:18:45 volumio volumio[17558]: info: [1767097125427] Starting Upmpd Daemon Dec 30 06:18:45 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 30 06:18:45 volumio volumio[17558]: info: Loading plugin "my_music"... Dec 30 06:18:45 volumio volumio[17558]: info: Loading plugin "mpd"... Dec 30 06:18:45 volumio go-librespot[17660]: time="2025-12-30T06:18:45-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]" Dec 30 06:18:45 volumio go-librespot[17660]: time="2025-12-30T06:18:45-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]" Dec 30 06:18:45 volumio go-librespot[17660]: time="2025-12-30T06:18:45-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]" Dec 30 06:18:45 volumio go-librespot[17660]: time="2025-12-30T06:18:45-06:00" level=info msg="zeroconf server listening on port 40015" Dec 30 06:18:45 volumio go-librespot[17660]: time="2025-12-30T06:18:45-06:00" level=debug msg="obtained new client token: AACi3ef6CN4xiUcFt16hdIWq/J71y8nDd+BWCHhu/wZGp/gmY4G3GQtc1kYXF1rv8czLjTJquAhi9Jb7B7ompgtqWgZTrLxRYKg8zQRsldze5+3fvxlChls1vqvEJzjBlDJPbpkHEqzz5Uv77lTdD55M8588sl/PB5c4r6o9u1hmKW/YVNgAXbbHY6V2xDzCghIchfNbziI89LfOa3rPvaXIn+WdBIb1av5GKiDNFwfFJ2XNiqLlZtNOaQ==" Dec 30 06:18:45 volumio sudo[17641]: pam_unix(sudo:session): session closed for user root Dec 30 06:18:45 volumio go-librespot[17660]: time="2025-12-30T06:18:45-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 06:18:45 volumio go-librespot[17660]: time="2025-12-30T06:18:45-06:00" level=debug msg="completed keyexchange" Dec 30 06:18:45 volumio go-librespot[17660]: time="2025-12-30T06:18:45-06:00" level=debug msg="completed challenge" Dec 30 06:18:45 volumio go-librespot[17660]: time="2025-12-30T06:18:45-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 " Dec 30 06:18:45 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 06:18:45 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 06:18:46 volumio volumio[17558]: info: Loading plugin "upnp_browser"... Dec 30 06:18:46 volumio kernel: hwmon hwmon1: Undervoltage detected! Dec 30 06:18:48 volumio volumio[17558]: info: Loading plugin "alarm-clock"... Dec 30 06:18:48 volumio volumio[17558]: info: Loading plugin "airplay_emulation"... Dec 30 06:18:48 volumio volumio[17558]: info: Starting Shairport Sync Dec 30 06:18:48 volumio volumio[17558]: info: Loading plugin "last_100"... Dec 30 06:18:48 volumio volumio[17558]: info: Loading plugin "webradio"... Dec 30 06:18:48 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 32. Dec 30 06:18:48 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 06:18:48 volumio volumio[17558]: info: Loading plugin "i2s_dacs"... Dec 30 06:18:49 volumio volumio[17558]: info: I2S DAC not set, start Auto-detection Dec 30 06:18:49 volumio volumio[17558]: info: Loading plugin "volumiodiscovery"... Dec 30 06:18:49 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 06:18:49 volumio go-librespot[17681]: go-librespot daemon starting... Dec 30 06:18:49 volumio go-librespot[17682]: time="2025-12-30T06:18:49-06:00" level=info msg="running go-librespot 0.4.0" Dec 30 06:18:49 volumio go-librespot[17682]: time="2025-12-30T06:18:49-06:00" level=debug msg="app state loaded" Dec 30 06:18:49 volumio go-librespot[17682]: time="2025-12-30T06:18:49-06:00" level=debug msg="stored credentials not found" Dec 30 06:18:49 volumio volumio[17558]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 30 06:18:49 volumio volumio[17558]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 30 06:18:49 volumio volumio[17558]: *** WARNING *** For more information see Dec 30 06:18:49 volumio volumio[17558]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 30 06:18:49 volumio volumio[17558]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 30 06:18:49 volumio volumio[17558]: *** WARNING *** For more information see Dec 30 06:18:49 volumio go-librespot[17682]: time="2025-12-30T06:18:49-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 06:18:49 volumio node[17558]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 30 06:18:49 volumio node[17558]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 30 06:18:49 volumio node[17558]: *** WARNING *** For more information see Dec 30 06:18:49 volumio node[17558]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 30 06:18:49 volumio node[17558]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 30 06:18:49 volumio node[17558]: *** WARNING *** For more information see Dec 30 06:18:49 volumio volumio[17558]: info: Applying required configuration parameters for plugin volumiodiscovery Dec 30 06:18:49 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.23.140 Dec 30 06:18:49 volumio avahi-daemon[664]: Registering new address record for 169.254.23.140 on eth0.IPv4. Dec 30 06:18:49 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Dec 30 06:18:49 volumio volumio[17558]: info: Discovery: Started advertising with name: Volumio Dec 30 06:18:49 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:18:49 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 06:18:49 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:18:49 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 30 06:18:49 volumio volumio[17558]: info: Loading plugin "bandcamp"... Dec 30 06:18:49 volumio go-librespot[17682]: time="2025-12-30T06:18:49-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]" Dec 30 06:18:49 volumio go-librespot[17682]: time="2025-12-30T06:18:49-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]" Dec 30 06:18:49 volumio go-librespot[17682]: time="2025-12-30T06:18:49-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]" Dec 30 06:18:49 volumio go-librespot[17682]: time="2025-12-30T06:18:49-06:00" level=info msg="zeroconf server listening on port 45377" Dec 30 06:18:49 volumio go-librespot[17682]: time="2025-12-30T06:18:49-06:00" level=debug msg="obtained new client token: AAC+ZabkgzBAmotJSSMXYHcWbtLc9LM4O9rCeU92gGsVrMrLGecLyCc+fpLL/xfvRe/Y1+rbDpWtGaWJMz3OSs/K1/7mv8MvgkGg9bivFeSohkM0rGlezhNjy3AoqOkn8Zfvsc06KUtAvAHxIq8/RYxBQWb8QsuaSYVNtVGdz/e4SeZf+kLixZfr0odcZSYyndCbSLfyNkZFiWDISLJUIRBZJd19Nm1AB7iuKp2pu3FZSXliH8YXN70qLQ==" Dec 30 06:18:49 volumio go-librespot[17682]: time="2025-12-30T06:18:49-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 06:18:49 volumio go-librespot[17682]: time="2025-12-30T06:18:49-06:00" level=debug msg="completed keyexchange" Dec 30 06:18:49 volumio go-librespot[17682]: time="2025-12-30T06:18:49-06:00" level=debug msg="completed challenge" Dec 30 06:18:49 volumio go-librespot[17682]: time="2025-12-30T06:18:49-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 " Dec 30 06:18:49 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 06:18:49 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 06:18:49 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.23.140 Dec 30 06:18:50 volumio ntpd[872]: IO: Listen normally on 294 eth0 169.254.23.140:123 Dec 30 06:18:50 volumio ntpd[872]: IO: new interface(s) found: waking up resolver Dec 30 06:18:50 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.23.140 Dec 30 06:18:50 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.23.140 Dec 30 06:18:50 volumio avahi-daemon[664]: Withdrawing address record for 169.254.23.140 on eth0. Dec 30 06:18:50 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Dec 30 06:18:50 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Dec 30 06:18:50 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:18:50 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 06:18:50 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:18:50 volumio volumio[17558]: info: Plugin calmradio is not enabled Dec 30 06:18:50 volumio volumio[17558]: info: Loading plugin "soundcloud"... Dec 30 06:18:51 volumio volumio[17558]: info: Loading plugin "spop"... Dec 30 06:18:52 volumio ntpd[872]: IO: Deleting interface #294 eth0, 169.254.23.140#123, interface stats: received=0, sent=0, dropped=0, active_time=2 secs Dec 30 06:18:52 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 33. Dec 30 06:18:52 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 06:18:52 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 06:18:52 volumio go-librespot[17723]: go-librespot daemon starting... Dec 30 06:18:52 volumio go-librespot[17724]: time="2025-12-30T06:18:52-06:00" level=info msg="running go-librespot 0.4.0" Dec 30 06:18:52 volumio go-librespot[17724]: time="2025-12-30T06:18:52-06:00" level=debug msg="app state loaded" Dec 30 06:18:52 volumio go-librespot[17724]: time="2025-12-30T06:18:52-06:00" level=debug msg="stored credentials not found" Dec 30 06:18:52 volumio go-librespot[17724]: time="2025-12-30T06:18:52-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 06:18:52 volumio volumio[17558]: info: Loading plugin "squeezelite_mc"... Dec 30 06:18:53 volumio go-librespot[17724]: time="2025-12-30T06:18:53-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]" Dec 30 06:18:53 volumio go-librespot[17724]: time="2025-12-30T06:18:53-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]" Dec 30 06:18:53 volumio go-librespot[17724]: time="2025-12-30T06:18:53-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]" Dec 30 06:18:53 volumio go-librespot[17724]: time="2025-12-30T06:18:53-06:00" level=info msg="zeroconf server listening on port 45257" Dec 30 06:18:53 volumio go-librespot[17724]: time="2025-12-30T06:18:53-06:00" level=debug msg="obtained new client token: AADCw0OBAzJZ8/PWx+Bbp7woii3tODYLt729Nd7jHGLshzX4UfMuDKMNLedaUnMgjtr4c8uxsouEBdbuxgEyo2tIYMZL5jT6lO6LAc8WEGCVtiqE9a8hEjFhJRSUzCPx19CY2EkTItuyVmIBI6PDsw3IfFd2bTBjgsOmayUsfB3dpbGe2LxxGqV2u8ZJYPOI5GzYH3N5b6Iup/L/li9jYy5zhVqhyWtpYY9RWtvLl18IzTxDVyDbOo2yag==" Dec 30 06:18:53 volumio go-librespot[17724]: time="2025-12-30T06:18:53-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 06:18:53 volumio go-librespot[17724]: time="2025-12-30T06:18:53-06:00" level=debug msg="completed keyexchange" Dec 30 06:18:53 volumio go-librespot[17724]: time="2025-12-30T06:18:53-06:00" level=debug msg="completed challenge" Dec 30 06:18:53 volumio go-librespot[17724]: time="2025-12-30T06:18:53-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 " Dec 30 06:18:53 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 06:18:53 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 06:18:53 volumio volumio[17558]: info: Loading plugin "youtube2"... Dec 30 06:18:54 volumio volumio[17558]: info: Loading plugin "ytcr"... Dec 30 06:18:55 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.99.135 Dec 30 06:18:55 volumio avahi-daemon[664]: Registering new address record for 169.254.99.135 on eth0.IPv4. Dec 30 06:18:55 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Dec 30 06:18:55 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.99.135 Dec 30 06:18:55 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:18:55 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 06:18:55 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:18:56 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.99.135 Dec 30 06:18:56 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.99.135 Dec 30 06:18:56 volumio avahi-daemon[664]: Withdrawing address record for 169.254.99.135 on eth0. Dec 30 06:18:56 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Dec 30 06:18:56 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Dec 30 06:18:56 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:18:56 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 06:18:56 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:18:56 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 34. Dec 30 06:18:56 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 06:18:56 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 06:18:56 volumio go-librespot[17778]: go-librespot daemon starting... Dec 30 06:18:56 volumio go-librespot[17779]: time="2025-12-30T06:18:56-06:00" level=info msg="running go-librespot 0.4.0" Dec 30 06:18:56 volumio go-librespot[17779]: time="2025-12-30T06:18:56-06:00" level=debug msg="app state loaded" Dec 30 06:18:56 volumio go-librespot[17779]: time="2025-12-30T06:18:56-06:00" level=debug msg="stored credentials not found" Dec 30 06:18:56 volumio go-librespot[17779]: time="2025-12-30T06:18:56-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 06:18:57 volumio volumio[17558]: info: Loading plugin "ytmusic"... Dec 30 06:18:57 volumio go-librespot[17779]: time="2025-12-30T06:18:57-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]" Dec 30 06:18:57 volumio go-librespot[17779]: time="2025-12-30T06:18:57-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]" Dec 30 06:18:57 volumio go-librespot[17779]: time="2025-12-30T06:18:57-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]" Dec 30 06:18:57 volumio go-librespot[17779]: time="2025-12-30T06:18:57-06:00" level=info msg="zeroconf server listening on port 33311" Dec 30 06:18:57 volumio go-librespot[17779]: time="2025-12-30T06:18:57-06:00" level=debug msg="obtained new client token: AACw4/fE4gTUqny8VuRB1U6Ur6cIj8b9QakrI72/CiPchHqpZR4aCYDl26BwJEFr6PmupYD591vLib1mhrF/nHaByeE9MDVbhQCyjcz3pEMFvtZFjo1axealSv0AlApqmtdUAG5vId7+HZ5SqcCxgpQKW8e0HDxwtVhz2agBxV0xeQtRewUnyLEXC0yEuBO5v/pED8RXJb8v8qWF/agBsHs3CNbe4Q9SooGHyRuPd1ttTFCbxJCBJtcfmQ==" Dec 30 06:18:57 volumio go-librespot[17779]: time="2025-12-30T06:18:57-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 06:18:57 volumio go-librespot[17779]: time="2025-12-30T06:18:57-06:00" level=debug msg="completed keyexchange" Dec 30 06:18:57 volumio go-librespot[17779]: time="2025-12-30T06:18:57-06:00" level=debug msg="completed challenge" Dec 30 06:18:57 volumio go-librespot[17779]: time="2025-12-30T06:18:57-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 " Dec 30 06:18:57 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 06:18:57 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 06:18:57 volumio volumio-remote-updater[702]: [2025-12-30 06:18:57] [connect] Successful connection Dec 30 06:18:58 volumio volumio[17558]: info: Plugin now_playing is not enabled Dec 30 06:18:58 volumio volumio[17558]: info: Loading plugin "outputs"... Dec 30 06:18:58 volumio volumio[17558]: info: Loading plugin "albumart"... Dec 30 06:18:58 volumio volumio[17558]: info: Plugin example_plugin is not enabled Dec 30 06:18:58 volumio volumio[17558]: info: Loading plugin "inputs"... Dec 30 06:18:58 volumio volumio[17558]: info: Loading plugin "updater_comm"... Dec 30 06:18:58 volumio volumio[17558]: info: Plugin mpdemulation is not enabled Dec 30 06:18:58 volumio volumio[17558]: info: Loading plugin "rest_api"... Dec 30 06:18:58 volumio volumio[17558]: info: Loading plugin "websocket"... Dec 30 06:18:58 volumio volumio[17558]: info: Starting Socket.io Server version 1.7.4 Dec 30 06:18:58 volumio volumio[17558]: info: Plugin fusiondsp is not enabled Dec 30 06:18:58 volumio volumio[17558]: info: Plugin mpdoutput is not enabled Dec 30 06:18:58 volumio volumio[17558]: info: Plugin RoonBridge is not enabled Dec 30 06:18:58 volumio volumio[17558]: info: Loading plugin "podcast"... Dec 30 06:18:58 volumio volumio[17558]: info: ControllerPodcast::constructor Dec 30 06:18:58 volumio volumio[17558]: info: Loading plugin "volusonic"... Dec 30 06:18:58 volumio volumio[17787]: Forking 3 albumart workers Dec 30 06:19:00 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.17.234 Dec 30 06:19:00 volumio avahi-daemon[664]: Registering new address record for 169.254.17.234 on eth0.IPv4. Dec 30 06:19:00 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Dec 30 06:19:00 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 35. Dec 30 06:19:00 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 06:19:00 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 06:19:00 volumio go-librespot[17843]: go-librespot daemon starting... Dec 30 06:19:00 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:19:00 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 06:19:00 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:19:00 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.17.234 Dec 30 06:19:00 volumio go-librespot[17844]: time="2025-12-30T06:19:00-06:00" level=info msg="running go-librespot 0.4.0" Dec 30 06:19:00 volumio go-librespot[17844]: time="2025-12-30T06:19:00-06:00" level=debug msg="app state loaded" Dec 30 06:19:00 volumio go-librespot[17844]: time="2025-12-30T06:19:00-06:00" level=debug msg="stored credentials not found" Dec 30 06:19:00 volumio go-librespot[17844]: time="2025-12-30T06:19:00-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 06:19:01 volumio volumio[17558]: info: Applying required configuration parameters for plugin volusonic Dec 30 06:19:01 volumio volumio[17558]: info: Loading plugin "backup_restore"... Dec 30 06:19:01 volumio volumio[17797]: Starting albumart workers Dec 30 06:19:01 volumio go-librespot[17844]: time="2025-12-30T06:19:01-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]" Dec 30 06:19:01 volumio go-librespot[17844]: time="2025-12-30T06:19:01-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]" Dec 30 06:19:01 volumio go-librespot[17844]: time="2025-12-30T06:19:01-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]" Dec 30 06:19:01 volumio volumio[17799]: Starting albumart workers Dec 30 06:19:01 volumio go-librespot[17844]: time="2025-12-30T06:19:01-06:00" level=info msg="zeroconf server listening on port 36555" Dec 30 06:19:01 volumio go-librespot[17844]: time="2025-12-30T06:19:01-06:00" level=debug msg="obtained new client token: AAD5oJBqmJ4tLWAwjiyaDUGeGPi8MXDQ2f0BeycBtZBzEu5l6y8bxFw7W84G6lW20fCb97zXb7EKgmzboDVOB7UqUkk199mND6Ljrl4NkIf+r/y/8XcLDGSd2f5mNegPz4TQk2rLt0sDYjXViQj++khOFrOs1fRgrl6LPfYA2shiRDTenoBOGP5rY8u42f8JEYHtgQg8bYFeRrbESCMLlvwZW6dbOV80pivfGWNjJ3x3K6735U/n/zlfgg==" Dec 30 06:19:01 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.17.234 Dec 30 06:19:01 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.17.234 Dec 30 06:19:01 volumio avahi-daemon[664]: Withdrawing address record for 169.254.17.234 on eth0. Dec 30 06:19:01 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Dec 30 06:19:01 volumio go-librespot[17844]: time="2025-12-30T06:19:01-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 06:19:01 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Dec 30 06:19:01 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:19:01 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 06:19:01 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:19:01 volumio go-librespot[17844]: time="2025-12-30T06:19:01-06:00" level=debug msg="completed keyexchange" Dec 30 06:19:01 volumio go-librespot[17844]: time="2025-12-30T06:19:01-06:00" level=debug msg="completed challenge" Dec 30 06:19:01 volumio volumio[17558]: info: Applying required configuration parameters for plugin backup_restore Dec 30 06:19:01 volumio go-librespot[17844]: time="2025-12-30T06:19:01-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 " Dec 30 06:19:01 volumio volumio[17798]: Starting albumart workers Dec 30 06:19:01 volumio volumio[17558]: info: Plugin rpi_eeprom_config is not enabled Dec 30 06:19:01 volumio volumio[17558]: info: Plugin rpi_eeprom_updater is not enabled Dec 30 06:19:01 volumio volumio[17558]: info: Loading plugin "scheduledrestart"... Dec 30 06:19:01 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 06:19:01 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 06:19:02 volumio volumio[17558]: info: Applying required configuration parameters for plugin scheduledrestart Dec 30 06:19:02 volumio volumio[17558]: info: Plugin Bluetoothremote is not enabled Dec 30 06:19:02 volumio volumio[17558]: info: Plugin music_services_shield is not enabled Dec 30 06:19:02 volumio volumio[17558]: info: Loading plugin "Systeminfo"... Dec 30 06:19:02 volumio volumio[17558]: info: Plugin peppymeterbasic is not enabled Dec 30 06:19:02 volumio volumio[17558]: info: Loading plugin "peppyspectrum"... Dec 30 06:19:02 volumio volumio[17558]: info: Loading i18n strings for locale en Dec 30 06:19:02 volumio volumio[17558]: info: Plugin peppyspectrum has duplicated i18n key SAVE. It is ignored. Dec 30 06:19:02 volumio volumio[17558]: Updating browse sources language Dec 30 06:19:02 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 06:19:03 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 30 06:19:03 volumio volumio[17558]: info: CoreCommandRouter::initPlayerControls Dec 30 06:19:03 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:03 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:03 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:03 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:03 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:03 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:03 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:03 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:03 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 30 06:19:03 volumio volumio[17558]: Express server listening on port 3000 Dec 30 06:19:03 volumio volumio[17558]: [Metrics] WebUI: 20s 604.36ms Dec 30 06:19:03 volumio volumio[17558]: info: CoreStateMachine::resetVolumioState Dec 30 06:19:03 volumio volumio[17558]: info: CoreStateMachine::getcurrentVolume Dec 30 06:19:03 volumio volumio[17558]: info: CoreCommandRouter::volumioRetrievevolume Dec 30 06:19:03 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 06:19:03 volumio sudo[17891]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 30 06:19:03 volumio sudo[17891]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:03 volumio sudo[17891]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:03 volumio sudo[17893]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 30 06:19:03 volumio sudo[17893]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:03 volumio sudo[17893]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:03 volumio volumio[17558]: info: Volumio Network Manager: Network status updated: 1 Dec 30 06:19:03 volumio volumio[17558]: info: VolumeController:: Volume=100 Mute =false Dec 30 06:19:03 volumio volumio[17558]: info: CoreStateMachine::pushState Dec 30 06:19:03 volumio volumio[17558]: info: CorePlayQueue::getTrack 0 Dec 30 06:19:03 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 30 06:19:03 volumio volumio[17558]: info: CoreCommandRouter::volumioPushState Dec 30 06:19:03 volumio volumio[17558]: info: CoreStateMachine::updateTrackBlock Dec 30 06:19:03 volumio volumio[17558]: info: CorePlayQueue::getTrackBlock Dec 30 06:19:03 volumio volumio[17558]: info: CoreCommandRouter::volumioRetrievevolume Dec 30 06:19:03 volumio volumio[17558]: info: Reloading queue from file Dec 30 06:19:03 volumio volumio[17558]: info: CoreStateMachine::setRepeat null single undefined Dec 30 06:19:03 volumio volumio[17558]: info: CoreStateMachine::pushState Dec 30 06:19:03 volumio volumio[17558]: info: CorePlayQueue::getTrack 0 Dec 30 06:19:03 volumio volumio[17558]: info: CoreCommandRouter::volumioPushState Dec 30 06:19:03 volumio volumio[17558]: info: CoreStateMachine::setRandom null Dec 30 06:19:03 volumio volumio[17558]: info: CoreStateMachine::pushState Dec 30 06:19:03 volumio volumio[17558]: info: CorePlayQueue::getTrack 0 Dec 30 06:19:03 volumio volumio[17558]: info: CoreCommandRouter::volumioPushState Dec 30 06:19:03 volumio volumio[17558]: info: Setting Device type: Raspberry PI Dec 30 06:19:03 volumio volumio[17558]: info: VolumeController:: Volume=100 Mute =false Dec 30 06:19:03 volumio volumio[17558]: info: CoreStateMachine::pushState Dec 30 06:19:03 volumio volumio[17558]: info: CorePlayQueue::getTrack 0 Dec 30 06:19:03 volumio volumio[17558]: info: CoreCommandRouter::volumioPushState Dec 30 06:19:03 volumio volumio[17558]: info: Completed loading Core Plugins Dec 30 06:19:03 volumio volumio[17558]: info: Preparing to generate the ALSA configuration file Dec 30 06:19:03 volumio sudo[17907]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Dec 30 06:19:03 volumio sudo[17907]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:03 volumio volumio[17558]: info: Discovery: adding a135e40e-a404-457b-98f5-36bf71c75954 Dec 30 06:19:03 volumio volumio[17558]: info: Discovery: Found device Volumio Dec 30 06:19:03 volumio volumio[17558]: info: CoreCommandRouter::volumioGetState Dec 30 06:19:03 volumio volumio[17558]: info: CorePlayQueue::getTrack 0 Dec 30 06:19:03 volumio volumio[17558]: info: Discovery: this is already registered, a135e40e-a404-457b-98f5-36bf71c75954 Dec 30 06:19:03 volumio volumio[17558]: info: Discovery: Found device Volumio Dec 30 06:19:03 volumio volumio[17558]: info: CoreCommandRouter::volumioGetState Dec 30 06:19:03 volumio volumio[17558]: info: CorePlayQueue::getTrack 0 Dec 30 06:19:03 volumio volumio[17558]: info: The plugin peppyspectrum has an ALSA contribution file peppy_in.peppy_out.6.conf Dec 30 06:19:03 volumio volumio[17558]: info: Reading ALSA contributions from plugins. Dec 30 06:19:03 volumio volumio[17558]: info: Asound.conf file unchanged, so no further update is needed Dec 30 06:19:03 volumio volumio[17558]: info: Output device has changed, restarting MPD Dec 30 06:19:03 volumio sudo[17907]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:03 volumio volumio[17558]: info: Output device has changed, restarting Shairport Sync Dec 30 06:19:03 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:03 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 06:19:03 volumio sudo[17910]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 30 06:19:03 volumio sudo[17910]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:03 volumio sudo[17910]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:03 volumio sudo[17912]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 30 06:19:03 volumio sudo[17912]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:03 volumio volumio[17558]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 30 06:19:03 volumio volumio[17558]: info: ___________ START PLUGINS ___________ Dec 30 06:19:03 volumio volumio[17558]: info: ControllerMpd::onStart: Initializing MPD Dec 30 06:19:03 volumio volumio[17558]: info: Creating MPD Configuration file Dec 30 06:19:03 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 30 06:19:03 volumio volumio[17558]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 06:19:03 volumio volumio[17558]: info: [1767097143901] CoreMusicLibrary::Adding element Media Servers Dec 30 06:19:03 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 06:19:03 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Dec 30 06:19:03 volumio sudo[17922]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 30 06:19:03 volumio sudo[17920]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 30 06:19:03 volumio sudo[17922]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:03 volumio sudo[17920]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:03 volumio sudo[17920]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:03 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:03 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 06:19:04 volumio volumio[17558]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 30 06:19:04 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:04 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 06:19:04 volumio volumio[17558]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 30 06:19:04 volumio systemd[1]: mpd.service: Deactivated successfully. Dec 30 06:19:04 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 30 06:19:04 volumio systemd[1]: mpd.service: Consumed 6.153s CPU time. Dec 30 06:19:04 volumio volumio[17558]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 06:19:04 volumio volumio[17558]: info: [1767097144079] CoreMusicLibrary::Adding element Last_100 Dec 30 06:19:04 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 06:19:04 volumio systemd[1]: mpd.socket: Deactivated successfully. Dec 30 06:19:04 volumio volumio[17558]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 06:19:04 volumio volumio[17558]: info: [1767097144089] CoreMusicLibrary::Adding element Webradio Dec 30 06:19:04 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 30 06:19:04 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 30 06:19:04 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 06:19:04 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 30 06:19:04 volumio volumio[17558]: info: Initializing BBC Radios Dec 30 06:19:04 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 30 06:19:04 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Dec 30 06:19:04 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 30 06:19:04 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 06:19:04 volumio volumio[17558]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 06:19:04 volumio volumio[17558]: info: [1767097144229] CoreMusicLibrary::Adding element Bandcamp Discover Dec 30 06:19:04 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 06:19:04 volumio volumio[17558]: Cannot find translation for source Bandcamp Discover Dec 30 06:19:04 volumio volumio[17558]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 06:19:04 volumio volumio[17558]: info: [1767097144248] CoreMusicLibrary::Adding element SoundCloud Dec 30 06:19:04 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 06:19:04 volumio volumio[17558]: Cannot find translation for source Bandcamp Discover Dec 30 06:19:04 volumio volumio[17558]: Cannot find translation for source SoundCloud Dec 30 06:19:04 volumio volumio[17558]: info: Creating Spotify config file Dec 30 06:19:04 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:04 volumio sudo[17947]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 30 06:19:04 volumio sudo[17947]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 30 06:19:04 volumio sudo[17947]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:04 volumio volumio[17558]: info: [squeezelite_mc] Starting proxy server... Dec 30 06:19:04 volumio volumio[17558]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 06:19:04 volumio volumio[17558]: info: [1767097144928] CoreMusicLibrary::Adding element YouTube2 Dec 30 06:19:04 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 06:19:04 volumio volumio[17558]: Cannot find translation for source Bandcamp Discover Dec 30 06:19:04 volumio volumio[17558]: Cannot find translation for source SoundCloud Dec 30 06:19:04 volumio volumio[17558]: Cannot find translation for source YouTube2 Dec 30 06:19:04 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 36. Dec 30 06:19:04 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 06:19:04 volumio volumio[17558]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 06:19:04 volumio volumio[17558]: info: [1767097144962] CoreMusicLibrary::Adding element YouTube Music Dec 30 06:19:04 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 06:19:04 volumio volumio[17558]: Cannot find translation for source Bandcamp Discover Dec 30 06:19:04 volumio volumio[17558]: Cannot find translation for source SoundCloud Dec 30 06:19:04 volumio volumio[17558]: Cannot find translation for source YouTube2 Dec 30 06:19:04 volumio volumio[17558]: Cannot find translation for source YouTube Music Dec 30 06:19:04 volumio volumio[17558]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 06:19:04 volumio volumio[17558]: info: [1767097144984] CoreMusicLibrary::Adding element Podcast Dec 30 06:19:04 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 06:19:04 volumio volumio[17558]: Cannot find translation for source Bandcamp Discover Dec 30 06:19:04 volumio volumio[17558]: Cannot find translation for source SoundCloud Dec 30 06:19:04 volumio volumio[17558]: Cannot find translation for source YouTube2 Dec 30 06:19:04 volumio volumio[17558]: Cannot find translation for source YouTube Music Dec 30 06:19:04 volumio volumio[17558]: Cannot find translation for source Podcast Dec 30 06:19:05 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 06:19:05 volumio go-librespot[17952]: go-librespot daemon starting... Dec 30 06:19:05 volumio volumio[17558]: info: Loading i18n strings for locale en Dec 30 06:19:05 volumio volumio[17558]: info: Plugin peppyspectrum has duplicated i18n key SAVE. It is ignored. Dec 30 06:19:05 volumio volumio[17558]: Updating browse sources language Dec 30 06:19:05 volumio volumio[17558]: Cannot find translation for source Bandcamp Discover Dec 30 06:19:05 volumio volumio[17558]: Cannot find translation for source SoundCloud Dec 30 06:19:05 volumio volumio[17558]: Cannot find translation for source YouTube2 Dec 30 06:19:05 volumio volumio[17558]: Cannot find translation for source YouTube Music Dec 30 06:19:05 volumio volumio[17558]: Cannot find translation for source Podcast Dec 30 06:19:05 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 06:19:05 volumio volumio[17558]: Cannot find translation for source Bandcamp Discover Dec 30 06:19:05 volumio volumio[17558]: Cannot find translation for source SoundCloud Dec 30 06:19:05 volumio volumio[17558]: Cannot find translation for source YouTube2 Dec 30 06:19:05 volumio volumio[17558]: Cannot find translation for source YouTube Music Dec 30 06:19:05 volumio volumio[17558]: Cannot find translation for source Podcast Dec 30 06:19:05 volumio volumio[17558]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 06:19:05 volumio volumio[17558]: info: [1767097145078] CoreMusicLibrary::Adding element Volusonic Dec 30 06:19:05 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 06:19:05 volumio volumio[17558]: Cannot find translation for source Bandcamp Discover Dec 30 06:19:05 volumio volumio[17558]: Cannot find translation for source SoundCloud Dec 30 06:19:05 volumio volumio[17558]: Cannot find translation for source YouTube2 Dec 30 06:19:05 volumio volumio[17558]: Cannot find translation for source YouTube Music Dec 30 06:19:05 volumio volumio[17558]: Cannot find translation for source Podcast Dec 30 06:19:05 volumio volumio[17558]: Cannot find translation for source Volusonic Dec 30 06:19:05 volumio go-librespot[17953]: time="2025-12-30T06:19:05-06:00" level=info msg="running go-librespot 0.4.0" Dec 30 06:19:05 volumio volumio[17558]: info: Scheduling reboots with hours: 0, minutes: 0 in timezone: America/Chicago Dec 30 06:19:05 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , updateALSAConfigFile Dec 30 06:19:05 volumio volumio[17558]: info: Volumio Calling Home Dec 30 06:19:05 volumio volumio[17558]: info: [squeezelite_mc] Proxy server started on port 34299 Dec 30 06:19:05 volumio volumio[17558]: info: Preparing to generate the ALSA configuration file Dec 30 06:19:05 volumio volumio[17558]: info: CoreCommandRouter::volumioRetrievevolume Dec 30 06:19:05 volumio volumio[17558]: info: The plugin peppyspectrum has an ALSA contribution file peppy_in.peppy_out.6.conf Dec 30 06:19:05 volumio volumio[17558]: info: Reading ALSA contributions from plugins. Dec 30 06:19:05 volumio go-librespot[17953]: time="2025-12-30T06:19:05-06:00" level=info msg="zeroconf server listening on port 46211" Dec 30 06:19:05 volumio volumio[17558]: info: MPD Permissions set Dec 30 06:19:05 volumio volumio[17558]: info: MPD Permissions set Dec 30 06:19:05 volumio volumio[17558]: info: Upmpdcli Daemon Started Dec 30 06:19:05 volumio volumio[17558]: info: Volumio called home Dec 30 06:19:05 volumio volumio[17558]: info: Spotify config file written Dec 30 06:19:05 volumio sudo[17980]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 30 06:19:05 volumio sudo[17980]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:05 volumio volumio[17558]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 1 Dec 30 06:19:05 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Dec 30 06:19:05 volumio volumio[17558]: info: VolumeController:: Volume=100 Mute =false Dec 30 06:19:05 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Dec 30 06:19:05 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 06:19:05 volumio volumio[17558]: info: CoreStateMachine::pushState Dec 30 06:19:05 volumio volumio[17558]: info: CorePlayQueue::getTrack 0 Dec 30 06:19:05 volumio volumio[17558]: info: CoreCommandRouter::volumioPushState Dec 30 06:19:05 volumio volumio[17558]: info: [squeezelite_mc] Server discovery started Dec 30 06:19:05 volumio volumio[17558]: info: [squeezelite_mc] Player finder started Dec 30 06:19:05 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:05 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:05 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:05 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 30 06:19:05 volumio volumio[17558]: info: [squeezelite_mc] Executing aplay -D hw:1 --nonblock -f MPEG /dev/zero 2>&1 || true Dec 30 06:19:05 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:05 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:05 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:05 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:05 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:05 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:05 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:05 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:05 volumio go-librespot[17982]: go-librespot daemon starting... Dec 30 06:19:05 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 06:19:06 volumio sudo[17980]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:06 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 06:19:06 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:06 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:06 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:06 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:06 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:06 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:06 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:06 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:06 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:06 volumio go-librespot[17985]: time="2025-12-30T06:19:06-06:00" level=info msg="running go-librespot 0.4.0" Dec 30 06:19:06 volumio go-librespot[17985]: time="2025-12-30T06:19:06-06:00" level=debug msg="app state loaded" Dec 30 06:19:06 volumio go-librespot[17985]: time="2025-12-30T06:19:06-06:00" level=debug msg="stored credentials not found" Dec 30 06:19:06 volumio go-librespot[17985]: time="2025-12-30T06:19:06-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 06:19:06 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 06:19:06 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:06 volumio volumio[17558]: info: No need to fix Spotify hosts Dec 30 06:19:06 volumio volumio[17558]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Dec 30 06:19:06 volumio go-librespot[17985]: time="2025-12-30T06:19:06-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]" Dec 30 06:19:06 volumio go-librespot[17985]: time="2025-12-30T06:19:06-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]" Dec 30 06:19:06 volumio go-librespot[17985]: time="2025-12-30T06:19:06-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]" Dec 30 06:19:06 volumio go-librespot[17985]: time="2025-12-30T06:19:06-06:00" level=info msg="zeroconf server listening on port 42681" Dec 30 06:19:06 volumio volumio[17558]: info: [squeezelite_mc] Card 1 supports the following ALSA formats: ["U8","S16_LE"] Dec 30 06:19:06 volumio volumio[17558]: info: [squeezelite_mc] Starting Squeezelite service with params: {"type":"basic","playerName":"volumio","dsdFormat":null,"card":"1","mixerType":"Hardware","mixer":"PCM"} Dec 30 06:19:06 volumio volumio[17558]: 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 Dec 30 06:19:06 volumio volumio[17558]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 30 06:19:06 volumio volumio[17558]: SPOTIFY: BQBiNCS9WwXkYptb9ZJe6puZ0h7I74ZPQIz4usJLBe0WIQf_gXYhoqQIurhx1UxWQFgQfhZ4UWbBB3ecbUoZuGNkRxM9-ipAKStEIMRLC4ytackQYWz8dHDjjfbG48qtvU7uaJXnLCqksv0jZ5tYvnoqqjNLxBxCEd8_zhtlsbDTQYRreXjBHpZxweORoTm4v6YrKZBl-KFyrWa8mi9_Eee2jo1PmqhkR3SkiXQ Dec 30 06:19:06 volumio volumio[17558]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 30 06:19:06 volumio volumio[17558]: info: New Spotify access token = BQBiNCS9WwXkYptb9ZJe6puZ0h7I74ZPQIz4usJLBe0WIQf_gXYhoqQIurhx1UxWQFgQfhZ4UWbBB3ecbUoZuGNkRxM9-ipAKStEIMRLC4ytackQYWz8dHDjjfbG48qtvU7uaJXnLCqksv0jZ5tYvnoqqjNLxBxCEd8_zhtlsbDTQYRreXjBHpZxweORoTm4v6YrKZBl-KFyrWa8mi9_Eee2jo1PmqhkR3SkiXQ Dec 30 06:19:06 volumio volumio[17558]: info: Spotify credentials grant success - running version from March 24, 2019 Dec 30 06:19:06 volumio sudo[18005]: 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 Dec 30 06:19:06 volumio sudo[18005]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:06 volumio sudo[18005]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:06 volumio volumio[17558]: info: Starting Shairport Sync Dec 30 06:19:06 volumio go-librespot[17985]: time="2025-12-30T06:19:06-06:00" level=debug msg="obtained new client token: AACW5XYRyfMpVhEANoT3MQG8Q79twFCgPw6yTul3jCzYFauWk0va8mBQWOyuAFm3nOABBCUEeeGbqmZStaKwRq4xix2V0eWX3PaNg6Dz8KrTLbVAXO0DsyRsTm4rCe20ms9dHmEcbD3G+m64hy1ABsXdqz+GFlvm9xb/3k387l58EeDpmVfYlh/qffFbu67XkXaHoW1QP+BBexgLle+9W/ajpHHwCuOvd1RCcVdvkSusW88vPy1QvL65GQ==" Dec 30 06:19:06 volumio volumio[17558]: info: Starting Shairport Sync Dec 30 06:19:06 volumio volumio[17558]: info: Starting Shairport Sync Dec 30 06:19:06 volumio sudo[18009]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 30 06:19:06 volumio sudo[18009]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:06 volumio sudo[18011]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 30 06:19:06 volumio sudo[18011]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:06 volumio go-librespot[17985]: time="2025-12-30T06:19:06-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 06:19:06 volumio sudo[18014]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 30 06:19:06 volumio sudo[18014]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:06 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.128.54 Dec 30 06:19:06 volumio avahi-daemon[664]: Registering new address record for 169.254.128.54 on eth0.IPv4. Dec 30 06:19:06 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Dec 30 06:19:06 volumio go-librespot[17985]: time="2025-12-30T06:19:06-06:00" level=debug msg="completed keyexchange" Dec 30 06:19:06 volumio go-librespot[17985]: time="2025-12-30T06:19:06-06:00" level=debug msg="completed challenge" Dec 30 06:19:06 volumio go-librespot[17985]: time="2025-12-30T06:19:06-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 " Dec 30 06:19:06 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 06:19:06 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 06:19:06 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:19:06 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 06:19:06 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:19:06 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 30 06:19:06 volumio volumio[17558]: info: [squeezelite_mc] Executing alsactl -L -R nrestore Dec 30 06:19:06 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Dec 30 06:19:06 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 30 06:19:06 volumio systemd[1]: shairport-sync.service: Consumed 2.096s CPU time. Dec 30 06:19:06 volumio sudo[18036]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/sbin/alsactl -L -R nrestore Dec 30 06:19:06 volumio sudo[18036]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:06 volumio sudo[18036]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:06 volumio volumio[17558]: info: Asound.conf file unchanged, so no further update is needed Dec 30 06:19:06 volumio volumio[17558]: info: Output device has changed, restarting MPD Dec 30 06:19:06 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 30 06:19:06 volumio volumio[17558]: info: Output device has changed, restarting Shairport Sync Dec 30 06:19:06 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:06 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 06:19:06 volumio sudo[18011]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:06 volumio sudo[18014]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:07 volumio sudo[18009]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:07 volumio sudo[18040]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 30 06:19:07 volumio sudo[18040]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:07 volumio sudo[18042]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 30 06:19:07 volumio sudo[18042]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:07 volumio sudo[18040]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:07 volumio volumio[17558]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 30 06:19:07 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.128.54 Dec 30 06:19:07 volumio systemd[1]: mpd.service: Deactivated successfully. Dec 30 06:19:07 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 30 06:19:07 volumio systemd[1]: mpd.service: Consumed 2.694s CPU time. Dec 30 06:19:07 volumio systemd[1]: mpd.socket: Deactivated successfully. Dec 30 06:19:07 volumio mpd_monitor.sh[17951]: MPD error: Connection reset by peer Dec 30 06:19:07 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 30 06:19:07 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 30 06:19:07 volumio mpd_monitor.sh[15947]: MPD Monitor Service: MPD Appears to be inactive, restarting Dec 30 06:19:07 volumio mpd_monitor.sh[18065]: mpd: no process found Dec 30 06:19:07 volumio volumio[17558]: info: [squeezelite_mc] Executing cp /data/plugins/music_service/squeezelite_mc/dist/lib/../templates/systemd/squeezelite.service.template.out /etc/systemd/system/squeezelite.service Dec 30 06:19:07 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 30 06:19:07 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Dec 30 06:19:07 volumio sudo[18071]: 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 Dec 30 06:19:07 volumio sudo[18071]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:07 volumio sudo[18071]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:07 volumio systemd[1]: mpd.service: Deactivated successfully. Dec 30 06:19:07 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 30 06:19:07 volumio systemd[1]: mpd.socket: Deactivated successfully. Dec 30 06:19:07 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 30 06:19:07 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 30 06:19:07 volumio volumio[17558]: info: MPD Permissions set Dec 30 06:19:07 volumio volumio[17558]: info: Shairport-Sync Started Dec 30 06:19:07 volumio volumio[17558]: Error adding Membership: Error: addMembership EINVAL Dec 30 06:19:07 volumio volumio[17558]: info: Shairport-Sync Started Dec 30 06:19:07 volumio volumio[17558]: info: Shairport-Sync Started Dec 30 06:19:07 volumio volumio[17558]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl daemon-reload || true Dec 30 06:19:07 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:07 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:07 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:07 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:07 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:07 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:07 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:07 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:07 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 30 06:19:07 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Dec 30 06:19:07 volumio sudo[18076]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl daemon-reload Dec 30 06:19:07 volumio sudo[18076]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:07 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 06:19:07 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:07 volumio systemd[1]: Reloading. Dec 30 06:19:07 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.128.54 Dec 30 06:19:07 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.128.54 Dec 30 06:19:07 volumio avahi-daemon[664]: Withdrawing address record for 169.254.128.54 on eth0. Dec 30 06:19:07 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Dec 30 06:19:07 volumio volumio[17558]: info: CoreCommandRouter::volumioGetState Dec 30 06:19:07 volumio volumio[17558]: info: CorePlayQueue::getTrack 0 Dec 30 06:19:07 volumio volumio[17558]: info: Starting Shairport Sync Dec 30 06:19:07 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Dec 30 06:19:07 volumio volumio[17558]: 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"} Dec 30 06:19:07 volumio volumio[17558]: info: Spotify Successfully logged in Dec 30 06:19:07 volumio volumio[17558]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 06:19:07 volumio volumio[17558]: info: [1767097147904] CoreMusicLibrary::Adding element Spotify Dec 30 06:19:07 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 06:19:07 volumio volumio[17558]: Cannot find translation for source Bandcamp Discover Dec 30 06:19:07 volumio volumio[17558]: Cannot find translation for source SoundCloud Dec 30 06:19:07 volumio volumio[17558]: Cannot find translation for source YouTube2 Dec 30 06:19:07 volumio volumio[17558]: Cannot find translation for source YouTube Music Dec 30 06:19:07 volumio volumio[17558]: Cannot find translation for source Podcast Dec 30 06:19:07 volumio volumio[17558]: Cannot find translation for source Volusonic Dec 30 06:19:07 volumio volumio[17558]: Cannot find translation for source Spotify Dec 30 06:19:07 volumio sudo[18102]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 30 06:19:07 volumio sudo[18102]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:08 volumio sudo[18079]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 30 06:19:08 volumio sudo[18079]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 30 06:19:08 volumio sudo[18079]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:08 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:08 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:08 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:08 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 30 06:19:09 volumio volumio[17558]: info: go-librespot daemon successfully initialized Dec 30 06:19:10 volumio systemd[1]: /lib/systemd/system/go-librespot-daemon.service:9: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Dec 30 06:19:10 volumio systemd[1]: /lib/systemd/system/go-librespot-daemon.service:10: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Dec 30 06:19:10 volumio sudo[18076]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:10 volumio volumio[17558]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 30 06:19:10 volumio sudo[18124]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 30 06:19:10 volumio sudo[18124]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:10 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Dec 30 06:19:11 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:19:11 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 06:19:11 volumio sudo[18124]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:11 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:19:11 volumio volumio[17558]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl stop squeezelite || true Dec 30 06:19:11 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 06:19:11 volumio sudo[18128]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop squeezelite Dec 30 06:19:11 volumio sudo[18128]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:11 volumio go-librespot[18127]: go-librespot daemon starting... Dec 30 06:19:11 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 06:19:11 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 30 06:19:11 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Dec 30 06:19:11 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 30 06:19:11 volumio systemd[1]: shairport-sync.service: Consumed 1.361s CPU time. Dec 30 06:19:11 volumio go-librespot[18130]: time="2025-12-30T06:19:11-06:00" level=info msg="running go-librespot 0.4.0" Dec 30 06:19:11 volumio go-librespot[18130]: time="2025-12-30T06:19:11-06:00" level=debug msg="app state loaded" Dec 30 06:19:11 volumio go-librespot[18130]: time="2025-12-30T06:19:11-06:00" level=debug msg="stored credentials not found" Dec 30 06:19:11 volumio go-librespot[18130]: time="2025-12-30T06:19:11-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 06:19:11 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 30 06:19:11 volumio sudo[18102]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:11 volumio volumio[17558]: info: Shairport-Sync Started Dec 30 06:19:11 volumio systemd[1]: Stopping squeezelite.service - Squeezelite lightweight headless Squeezebox emulator... Dec 30 06:19:11 volumio systemd[1]: squeezelite.service: Deactivated successfully. Dec 30 06:19:11 volumio systemd[1]: Stopped squeezelite.service - Squeezelite lightweight headless Squeezebox emulator. Dec 30 06:19:11 volumio go-librespot[18130]: time="2025-12-30T06:19: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]" Dec 30 06:19:11 volumio go-librespot[18130]: time="2025-12-30T06:19: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]" Dec 30 06:19:11 volumio go-librespot[18130]: time="2025-12-30T06:19: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]" Dec 30 06:19:11 volumio sudo[18128]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:11 volumio go-librespot[18130]: time="2025-12-30T06:19:11-06:00" level=info msg="zeroconf server listening on port 33311" Dec 30 06:19:11 volumio go-librespot[18130]: time="2025-12-30T06:19:11-06:00" level=debug msg="obtained new client token: AADsx4+pYkWGNz0TWzgLJQ3wzwjvS8yV5WHq+dWrijwmzUW7xoudSuz3HMXmtInYKiMxrVEDnuqOyxHTBWpV6lYWEcRl0EGLRuzH2fY11kugdP5zcPFz76yZv5epk8yNTgoWXJaaxTT/dScx5zE97OYb8+y+iUBR55OTgeAMy8vnQKNAxHC+WdBkTEReA3fNHuZw6o3aIrWY1j5KaJZz8Em/CnGejIADmCDFK1o3FR1AFiHvplC4obXtcg==" Dec 30 06:19:11 volumio go-librespot[18130]: time="2025-12-30T06:19:11-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 06:19:11 volumio go-librespot[18130]: time="2025-12-30T06:19:11-06:00" level=debug msg="completed keyexchange" Dec 30 06:19:11 volumio go-librespot[18130]: time="2025-12-30T06:19:11-06:00" level=debug msg="completed challenge" Dec 30 06:19:11 volumio go-librespot[18130]: time="2025-12-30T06:19: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 " Dec 30 06:19:11 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 06:19:11 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 06:19:11 volumio volumio[17558]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 30 06:19:11 volumio sudo[18153]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 30 06:19:11 volumio sudo[18153]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:12 volumio sudo[18153]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:12 volumio volumio[17558]: info: [squeezelite_mc] Executing rm /tmp/squeezelite.log Dec 30 06:19:12 volumio sudo[18157]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/rm /tmp/squeezelite.log Dec 30 06:19:12 volumio sudo[18157]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:12 volumio sudo[18157]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:12 volumio volumio[17558]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl start squeezelite || true Dec 30 06:19:12 volumio sudo[18160]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start squeezelite Dec 30 06:19:12 volumio sudo[18160]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:12 volumio systemd[1]: Starting squeezelite.service - Squeezelite lightweight headless Squeezebox emulator... Dec 30 06:19:12 volumio systemd[1]: Started squeezelite.service - Squeezelite lightweight headless Squeezebox emulator. Dec 30 06:19:12 volumio sudo[18160]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:12 volumio volumio[17558]: info: Initializing connection to go-librespot Websocket Dec 30 06:19:12 volumio volumio[17558]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 30 06:19:12 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.75.189 Dec 30 06:19:12 volumio avahi-daemon[664]: Registering new address record for 169.254.75.189 on eth0.IPv4. Dec 30 06:19:12 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Dec 30 06:19:12 volumio volumio-remote-updater[702]: [2025-12-30 06:19:12] [connect] Successful connection Dec 30 06:19:12 volumio volumio-remote-updater[702]: [2025-12-30 06:19:12] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1767097152 101 Dec 30 06:19:12 volumio volumio[17558]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 3 Transport: websocket Total Clients: 3 Dec 30 06:19:12 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:19:12 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 06:19:12 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:19:12 volumio volumio[17558]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 30 06:19:12 volumio sudo[18183]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 30 06:19:12 volumio sudo[18183]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:12 volumio sudo[18183]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:13 volumio volumio[17558]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 30 06:19:13 volumio sudo[18186]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 30 06:19:13 volumio sudo[18186]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:13 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.75.189 Dec 30 06:19:13 volumio sudo[18186]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:13 volumio kernel: hwmon hwmon1: Voltage normalised Dec 30 06:19:14 volumio volumio[17558]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 30 06:19:14 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.75.189 Dec 30 06:19:14 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.75.189 Dec 30 06:19:14 volumio avahi-daemon[664]: Withdrawing address record for 169.254.75.189 on eth0. Dec 30 06:19:14 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Dec 30 06:19:14 volumio mpd[18122]: 2025-12-30T06:19:14 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Dec 30 06:19:14 volumio sudo[18190]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 30 06:19:14 volumio sudo[18190]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:14 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Dec 30 06:19:14 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:19:14 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 06:19:14 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:19:14 volumio sudo[18190]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:14 volumio systemd[1]: Started mpd.service - Music Player Daemon. Dec 30 06:19:14 volumio sudo[18042]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:14 volumio mpd_monitor.sh[15947]: MPD Monitor Service: MPD restarted due to no mpc output. Dec 30 06:19:14 volumio sudo[17922]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:14 volumio sudo[17912]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:14 volumio volumio[17558]: error: MPD error: The expression evaluated to a falsy value: Dec 30 06:19:14 volumio volumio[17558]: assert.ok(self.idling) Dec 30 06:19:14 volumio volumio[17558]: error: The expression evaluated to a falsy value: Dec 30 06:19:14 volumio volumio[17558]: assert.ok(self.idling) Dec 30 06:19:14 volumio volumio[17558]: error: MPD error: The expression evaluated to a falsy value: Dec 30 06:19:14 volumio volumio[17558]: assert.ok(self.idling) Dec 30 06:19:14 volumio volumio[17558]: error: The expression evaluated to a falsy value: Dec 30 06:19:14 volumio volumio[17558]: assert.ok(self.idling) Dec 30 06:19:14 volumio volumio[17558]: info: MPD running with PID18122 Dec 30 06:19:14 volumio volumio[17558]: ,establishing connection Dec 30 06:19:14 volumio volumio[17558]: error: updateQueue error: null Dec 30 06:19:14 volumio volumio[17558]: error: updateQueue error: null Dec 30 06:19:14 volumio volumio[17558]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 30 06:19:14 volumio sudo[18214]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 30 06:19:14 volumio sudo[18214]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:14 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Dec 30 06:19:14 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 06:19:14 volumio sudo[18214]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:14 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 06:19:14 volumio go-librespot[18216]: go-librespot daemon starting... Dec 30 06:19:14 volumio go-librespot[18217]: time="2025-12-30T06:19:14-06:00" level=info msg="running go-librespot 0.4.0" Dec 30 06:19:14 volumio go-librespot[18217]: time="2025-12-30T06:19:14-06:00" level=debug msg="app state loaded" Dec 30 06:19:14 volumio go-librespot[18217]: time="2025-12-30T06:19:14-06:00" level=debug msg="stored credentials not found" Dec 30 06:19:14 volumio go-librespot[18217]: time="2025-12-30T06:19:14-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 06:19:15 volumio go-librespot[18217]: time="2025-12-30T06:19: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-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 30 06:19:15 volumio go-librespot[18217]: time="2025-12-30T06:19:15-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]" Dec 30 06:19:15 volumio go-librespot[18217]: time="2025-12-30T06:19:15-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]" Dec 30 06:19:15 volumio go-librespot[18217]: time="2025-12-30T06:19:15-06:00" level=info msg="zeroconf server listening on port 39543" Dec 30 06:19:15 volumio go-librespot[18217]: time="2025-12-30T06:19:15-06:00" level=debug msg="obtained new client token: AABtQhpy8+C+Qc/RKG8NfRDwTwX5Ho8ypp7iQGe69+Xw4ztxx73C6X2nhGNYsUAhtQoSW4r9uBosKR4VpXIHyKQKoN/7Q7Bt253NGtYEhXOUL6TYM4UXKHBz9HKi2BZfziZaECPk4BdbL3sCT+JCfAIJ7M/N7tQlnVx57qe48PMs3MK/REZdzBkrjBJIP37tyezp6Vk2iqirx/Bj/VqSHG3dYYOMxLWfppaRyERDXaA1FPmWOXmIhyQ=" Dec 30 06:19:15 volumio go-librespot[18217]: time="2025-12-30T06:19:15-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 06:19:15 volumio volumio[17558]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 30 06:19:15 volumio go-librespot[18217]: time="2025-12-30T06:19:15-06:00" level=debug msg="completed keyexchange" Dec 30 06:19:15 volumio go-librespot[18217]: time="2025-12-30T06:19:15-06:00" level=debug msg="completed challenge" Dec 30 06:19:15 volumio sudo[18225]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 30 06:19:15 volumio sudo[18225]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:15 volumio go-librespot[18217]: time="2025-12-30T06:19: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 " Dec 30 06:19:15 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 06:19:15 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 06:19:15 volumio sudo[18225]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:15 volumio volumio[17558]: info: Completed starting Core Plugins Dec 30 06:19:15 volumio volumio[17558]: info: ------------------------------------------- Dec 30 06:19:15 volumio volumio[17558]: info: ----- MyVolumio plugins startup ---- Dec 30 06:19:15 volumio volumio[17558]: info: ------------------------------------------- Dec 30 06:19:15 volumio volumio[17558]: info: [MyVolumio PluginManager] Fetching plans data.... Dec 30 06:19:15 volumio volumio[17558]: info: Initializing connection to go-librespot Websocket Dec 30 06:19:15 volumio volumio[17558]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 30 06:19:17 volumio sudo[18242]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 30 06:19:17 volumio sudo[18242]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:17 volumio sudo[18244]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 30 06:19:17 volumio sudo[18244]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:17 volumio sudo[18246]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 30 06:19:17 volumio sudo[18246]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:17 volumio systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Dec 30 06:19:17 volumio systemd[1]: mpd_monitor.service: Deactivated successfully. Dec 30 06:19:17 volumio systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Dec 30 06:19:17 volumio systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Dec 30 06:19:17 volumio sudo[18244]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:17 volumio sudo[18246]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:17 volumio mpd_monitor.sh[18250]: MPD Monitor Service: Starting MPD Monitor Service Dec 30 06:19:17 volumio sudo[18242]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:17 volumio volumio[17558]: info: Successfully started MPD Monitor Dec 30 06:19:17 volumio volumio[17558]: info: Successfully started MPD Monitor Dec 30 06:19:17 volumio volumio[17558]: info: Successfully started MPD Monitor Dec 30 06:19:18 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Dec 30 06:19:18 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 06:19:18 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 06:19:18 volumio go-librespot[18254]: go-librespot daemon starting... Dec 30 06:19:18 volumio go-librespot[18255]: time="2025-12-30T06:19:18-06:00" level=info msg="running go-librespot 0.4.0" Dec 30 06:19:18 volumio go-librespot[18255]: time="2025-12-30T06:19:18-06:00" level=debug msg="app state loaded" Dec 30 06:19:18 volumio go-librespot[18255]: time="2025-12-30T06:19:18-06:00" level=debug msg="stored credentials not found" Dec 30 06:19:18 volumio go-librespot[18255]: time="2025-12-30T06:19:18-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 06:19:18 volumio volumio[17558]: info: Initializing connection to go-librespot Websocket Dec 30 06:19:18 volumio go-librespot[18255]: time="2025-12-30T06:19:18-06:00" level=debug msg="new websocket client" Dec 30 06:19:18 volumio volumio[17558]: info: Connection to go-librespot Websocket established Dec 30 06:19:18 volumio go-librespot[18255]: time="2025-12-30T06:19: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-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 30 06:19:18 volumio go-librespot[18255]: time="2025-12-30T06:19:18-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]" Dec 30 06:19:18 volumio go-librespot[18255]: time="2025-12-30T06:19:18-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]" Dec 30 06:19:18 volumio go-librespot[18255]: time="2025-12-30T06:19:18-06:00" level=info msg="zeroconf server listening on port 40283" Dec 30 06:19:18 volumio go-librespot[18255]: time="2025-12-30T06:19:18-06:00" level=debug msg="obtained new client token: AACAOw2KOTHfGgSh4gf2zbfFDf7PQhci9EYnB6AIWva7Gi1mlmHrDhj0ZzM7ZxBHItohbrt3g1fRgC9ICX1wSuu6uCy3K08NDX00VnTBnBmGSX73O04P14N/ggWpFb0Zc84x8cLrwYo6yUb1wNiocvsLVCmwGiUI4b7SQ4ubVZmGYnUergVpV/5z7T3/sUrqKko0La2Q3XL6sQJJc+Ydgvb261hvPJwqvzR6+6UpSQyfFb1Wp9I65g55Tg==" Dec 30 06:19:18 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.53.93 Dec 30 06:19:18 volumio avahi-daemon[664]: Registering new address record for 169.254.53.93 on eth0.IPv4. Dec 30 06:19:18 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Dec 30 06:19:18 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:19:18 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 06:19:18 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:19:18 volumio go-librespot[18255]: time="2025-12-30T06:19:18-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 06:19:18 volumio go-librespot[18255]: time="2025-12-30T06:19:18-06:00" level=debug msg="completed keyexchange" Dec 30 06:19:18 volumio go-librespot[18255]: time="2025-12-30T06:19:18-06:00" level=debug msg="completed challenge" Dec 30 06:19:19 volumio go-librespot[18255]: time="2025-12-30T06:19: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 " Dec 30 06:19:19 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 06:19:19 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 06:19:19 volumio volumio[17558]: info: Connection to go-librespot Websocket closed Dec 30 06:19:19 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.53.93 Dec 30 06:19:19 volumio kernel: hwmon hwmon1: Undervoltage detected! Dec 30 06:19:20 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.53.93 Dec 30 06:19:20 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.53.93 Dec 30 06:19:20 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Dec 30 06:19:20 volumio avahi-daemon[664]: Withdrawing address record for 169.254.53.93 on eth0. Dec 30 06:19:20 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Dec 30 06:19:20 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:19:20 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 06:19:20 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:19:21 volumio volumio[17558]: info: Getting Spotify volume Dec 30 06:19:21 volumio volumio[17558]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 30 06:19:21 volumio volumio[17558]: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 30 06:19:21 volumio volumio[17558]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Dec 30 06:19:21 volumio volumio[17558]: errno: -111, Dec 30 06:19:21 volumio volumio[17558]: code: 'ECONNREFUSED', Dec 30 06:19:21 volumio volumio[17558]: syscall: 'connect', Dec 30 06:19:21 volumio volumio[17558]: address: '127.0.0.1', Dec 30 06:19:21 volumio volumio[17558]: port: 9879, Dec 30 06:19:21 volumio volumio[17558]: response: undefined Dec 30 06:19:21 volumio volumio[17558]: } Dec 30 06:19:21 volumio volumio[17558]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 30 06:19:22 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 4. Dec 30 06:19:22 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 06:19:22 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 06:19:22 volumio go-librespot[18308]: go-librespot daemon starting... Dec 30 06:19:22 volumio go-librespot[18309]: time="2025-12-30T06:19:22-06:00" level=info msg="running go-librespot 0.4.0" Dec 30 06:19:22 volumio go-librespot[18309]: time="2025-12-30T06:19:22-06:00" level=debug msg="app state loaded" Dec 30 06:19:22 volumio go-librespot[18309]: time="2025-12-30T06:19:22-06:00" level=debug msg="stored credentials not found" Dec 30 06:19:22 volumio go-librespot[18309]: time="2025-12-30T06:19:22-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 06:19:22 volumio go-librespot[18309]: time="2025-12-30T06:19: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-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 30 06:19:22 volumio go-librespot[18309]: time="2025-12-30T06:19:22-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]" Dec 30 06:19:22 volumio go-librespot[18309]: time="2025-12-30T06:19:22-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]" Dec 30 06:19:22 volumio go-librespot[18309]: time="2025-12-30T06:19:22-06:00" level=info msg="zeroconf server listening on port 36477" Dec 30 06:19:22 volumio go-librespot[18309]: time="2025-12-30T06:19:22-06:00" level=debug msg="obtained new client token: AACpasZSFBlCnHq9qpxQ5Zm/5HqWDBybGTHy0m+Tp5+AgK4o6WvknsEm6z0HMDdTNj+mAVZZ7uDDV2K5ZvKLVKTp/N6VW03LZOvJF9+2++HCmccdvYEn6Cu9Aew9vRpDyo4SkRERokyearfKJt0ic7OlrcvJC4Y/JBPO8wIGTHr3MNFZeZpmrvLlg8WY/TP8f+AZA/BhMuK7LKVUjEzeSD7Bs7Kx64J/Fp3+8EsqT7iQWgYDMXaR+Ssd5w==" Dec 30 06:19:22 volumio go-librespot[18309]: time="2025-12-30T06:19:22-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 06:19:22 volumio go-librespot[18309]: time="2025-12-30T06:19:22-06:00" level=debug msg="completed keyexchange" Dec 30 06:19:22 volumio go-librespot[18309]: time="2025-12-30T06:19:22-06:00" level=debug msg="completed challenge" Dec 30 06:19:23 volumio go-librespot[18309]: time="2025-12-30T06:19: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 " Dec 30 06:19:23 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 06:19:23 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 06:19:23 volumio sudo[18318]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-30 06:18' Dec 30 06:19:23 volumio sudo[18318]: 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"