Jan 12 22:44:00 volumio volumio[6346]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:44:00 volumio volumio[6346]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:44:00 volumio volumio[6346]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:44:00 volumio volumio[6346]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 12 22:44:00 volumio kernel: hwmon hwmon1: Undervoltage detected! Jan 12 22:44:01 volumio volumio[6346]: info: go-librespot daemon successfully initialized Jan 12 22:44:02 volumio systemd[1]: /lib/systemd/system/go-librespot-daemon.service:9: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Jan 12 22:44:02 volumio systemd[1]: /lib/systemd/system/go-librespot-daemon.service:10: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Jan 12 22:44:02 volumio sudo[6827]: pam_unix(sudo:session): session closed for user root Jan 12 22:44:02 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Jan 12 22:44:02 volumio volumio[6346]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Jan 12 22:44:02 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 12 22:44:02 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 12 22:44:02 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 12 22:44:02 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 12 22:44:02 volumio sudo[6893]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Jan 12 22:44:02 volumio sudo[6893]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 22:44:02 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 12 22:44:02 volumio go-librespot[6894]: go-librespot daemon starting... Jan 12 22:44:02 volumio go-librespot[6896]: time="2026-01-12T22:44:02-06:00" level=info msg="running go-librespot 0.4.0" Jan 12 22:44:02 volumio go-librespot[6896]: time="2026-01-12T22:44:02-06:00" level=debug msg="app state loaded" Jan 12 22:44:02 volumio go-librespot[6896]: time="2026-01-12T22:44:02-06:00" level=debug msg="stored credentials not found" Jan 12 22:44:02 volumio go-librespot[6896]: time="2026-01-12T22:44:02-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 12 22:44:02 volumio sudo[6893]: pam_unix(sudo:session): session closed for user root Jan 12 22:44:02 volumio volumio[6346]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl stop squeezelite || true Jan 12 22:44:03 volumio sudo[6903]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop squeezelite Jan 12 22:44:03 volumio sudo[6903]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 22:44:03 volumio systemd[1]: Stopping squeezelite.service - Squeezelite lightweight headless Squeezebox emulator... Jan 12 22:44:03 volumio systemd[1]: squeezelite.service: Deactivated successfully. Jan 12 22:44:03 volumio systemd[1]: Stopped squeezelite.service - Squeezelite lightweight headless Squeezebox emulator. Jan 12 22:44:03 volumio go-librespot[6896]: time="2026-01-12T22:44:03-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 12 22:44:03 volumio go-librespot[6896]: time="2026-01-12T22:44:03-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 12 22:44:03 volumio go-librespot[6896]: time="2026-01-12T22:44:03-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 12 22:44:03 volumio go-librespot[6896]: time="2026-01-12T22:44:03-06:00" level=info msg="zeroconf server listening on port 39549" Jan 12 22:44:03 volumio sudo[6903]: pam_unix(sudo:session): session closed for user root Jan 12 22:44:03 volumio go-librespot[6896]: time="2026-01-12T22:44:03-06:00" level=debug msg="obtained new client token: AADLfv12NtAgAahRMTxXI8xtnbPTxL5N9RsFHqNmkA+gezT10iBNcsV2TuyFZc7jHjlqG3Dm0VfpQne8WlbhE124FQFADDWbzfnDSPLee9C9vWwIqcdAZPVmg6PWNyYf0/9GlowNVxvGNMrAWVId+IrQ2UYUe/X3WZLLw7cvzx8mZVVhckyJwoxA9RjmP8zcTMmvTY3YxybB5efh1krczpouMbEvtTCTMwY8rlynzZL7qP+8CDOCNwSRvw==" Jan 12 22:44:03 volumio go-librespot[6896]: time="2026-01-12T22:44:03-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 12 22:44:03 volumio go-librespot[6896]: time="2026-01-12T22:44:03-06:00" level=debug msg="completed keyexchange" Jan 12 22:44:03 volumio go-librespot[6896]: time="2026-01-12T22:44:03-06:00" level=debug msg="completed challenge" Jan 12 22:44:03 volumio go-librespot[6896]: time="2026-01-12T22:44:03-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Jan 12 22:44:03 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 12 22:44:03 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 12 22:44:03 volumio volumio[6346]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Jan 12 22:44:03 volumio sudo[6909]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Jan 12 22:44:03 volumio sudo[6909]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 22:44:03 volumio sudo[6909]: pam_unix(sudo:session): session closed for user root Jan 12 22:44:03 volumio volumio[6346]: info: [squeezelite_mc] Executing rm /tmp/squeezelite.log Jan 12 22:44:03 volumio sudo[6913]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/rm /tmp/squeezelite.log Jan 12 22:44:03 volumio sudo[6913]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 22:44:03 volumio sudo[6913]: pam_unix(sudo:session): session closed for user root Jan 12 22:44:03 volumio volumio[6346]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl start squeezelite || true Jan 12 22:44:03 volumio mpd[6824]: 2026-01-12T22:44:03 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jan 12 22:44:03 volumio sudo[6916]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start squeezelite Jan 12 22:44:03 volumio sudo[6916]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 22:44:04 volumio volumio[6346]: info: Initializing connection to go-librespot Websocket Jan 12 22:44:04 volumio volumio[6346]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 12 22:44:04 volumio systemd[1]: Starting squeezelite.service - Squeezelite lightweight headless Squeezebox emulator... Jan 12 22:44:04 volumio systemd[1]: Started squeezelite.service - Squeezelite lightweight headless Squeezebox emulator. Jan 12 22:44:04 volumio sudo[6916]: pam_unix(sudo:session): session closed for user root Jan 12 22:44:04 volumio systemd[1]: Started mpd.service - Music Player Daemon. Jan 12 22:44:04 volumio sudo[6657]: pam_unix(sudo:session): session closed for user root Jan 12 22:44:04 volumio sudo[6667]: pam_unix(sudo:session): session closed for user root Jan 12 22:44:04 volumio sudo[6780]: pam_unix(sudo:session): session closed for user root Jan 12 22:44:04 volumio volumio[6346]: error: MPD error: The expression evaluated to a falsy value: Jan 12 22:44:04 volumio volumio[6346]: assert.ok(self.idling) Jan 12 22:44:04 volumio volumio[6346]: error: The expression evaluated to a falsy value: Jan 12 22:44:04 volumio volumio[6346]: assert.ok(self.idling) Jan 12 22:44:04 volumio volumio[6346]: error: MPD error: The expression evaluated to a falsy value: Jan 12 22:44:04 volumio volumio[6346]: assert.ok(self.idling) Jan 12 22:44:04 volumio volumio[6346]: error: The expression evaluated to a falsy value: Jan 12 22:44:04 volumio volumio[6346]: assert.ok(self.idling) Jan 12 22:44:04 volumio volumio[6346]: info: MPD running with PID6824 Jan 12 22:44:04 volumio volumio[6346]: ,establishing connection Jan 12 22:44:04 volumio volumio[6346]: error: updateQueue error: null Jan 12 22:44:04 volumio volumio[6346]: error: updateQueue error: null Jan 12 22:44:04 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.247.122 Jan 12 22:44:04 volumio avahi-daemon[664]: Registering new address record for 169.254.247.122 on eth0.IPv4. Jan 12 22:44:04 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Jan 12 22:44:04 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 12 22:44:04 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 12 22:44:04 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 12 22:44:04 volumio volumio[6346]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Jan 12 22:44:04 volumio sudo[6944]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Jan 12 22:44:04 volumio sudo[6944]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 22:44:04 volumio sudo[6944]: pam_unix(sudo:session): session closed for user root Jan 12 22:44:04 volumio kernel: hwmon hwmon1: Voltage normalised Jan 12 22:44:05 volumio volumio[6346]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Jan 12 22:44:05 volumio sudo[6948]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Jan 12 22:44:05 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.247.122 Jan 12 22:44:05 volumio sudo[6948]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 22:44:05 volumio sudo[6948]: pam_unix(sudo:session): session closed for user root Jan 12 22:44:05 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.247.122 Jan 12 22:44:05 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.247.122 Jan 12 22:44:05 volumio avahi-daemon[664]: Withdrawing address record for 169.254.247.122 on eth0. Jan 12 22:44:05 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Jan 12 22:44:05 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Jan 12 22:44:05 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 12 22:44:05 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 12 22:44:05 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 12 22:44:05 volumio volumio[6346]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Jan 12 22:44:05 volumio sudo[6967]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Jan 12 22:44:05 volumio sudo[6967]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 22:44:05 volumio sudo[6967]: pam_unix(sudo:session): session closed for user root Jan 12 22:44:06 volumio volumio[6346]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Jan 12 22:44:06 volumio sudo[6971]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Jan 12 22:44:06 volumio sudo[6971]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 22:44:06 volumio sudo[6971]: pam_unix(sudo:session): session closed for user root Jan 12 22:44:06 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Jan 12 22:44:06 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 12 22:44:06 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 12 22:44:06 volumio go-librespot[6973]: go-librespot daemon starting... Jan 12 22:44:06 volumio go-librespot[6974]: time="2026-01-12T22:44:06-06:00" level=info msg="running go-librespot 0.4.0" Jan 12 22:44:06 volumio go-librespot[6974]: time="2026-01-12T22:44:06-06:00" level=debug msg="app state loaded" Jan 12 22:44:06 volumio go-librespot[6974]: time="2026-01-12T22:44:06-06:00" level=debug msg="stored credentials not found" Jan 12 22:44:06 volumio go-librespot[6974]: time="2026-01-12T22:44:06-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 12 22:44:07 volumio volumio[6346]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Jan 12 22:44:07 volumio go-librespot[6974]: time="2026-01-12T22:44:07-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 12 22:44:07 volumio go-librespot[6974]: time="2026-01-12T22:44:07-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 12 22:44:07 volumio go-librespot[6974]: time="2026-01-12T22:44:07-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 12 22:44:07 volumio sudo[6982]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Jan 12 22:44:07 volumio sudo[6982]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 22:44:07 volumio go-librespot[6974]: time="2026-01-12T22:44:07-06:00" level=info msg="zeroconf server listening on port 34075" Jan 12 22:44:07 volumio volumio[6346]: info: Initializing connection to go-librespot Websocket Jan 12 22:44:07 volumio go-librespot[6974]: time="2026-01-12T22:44:07-06:00" level=debug msg="new websocket client" Jan 12 22:44:07 volumio sudo[6982]: pam_unix(sudo:session): session closed for user root Jan 12 22:44:07 volumio volumio[6346]: info: Connection to go-librespot Websocket established Jan 12 22:44:07 volumio volumio[6346]: info: Completed starting Core Plugins Jan 12 22:44:07 volumio volumio[6346]: info: ------------------------------------------- Jan 12 22:44:07 volumio volumio[6346]: info: ----- MyVolumio plugins startup ---- Jan 12 22:44:07 volumio volumio[6346]: info: ------------------------------------------- Jan 12 22:44:07 volumio volumio[6346]: info: [MyVolumio PluginManager] Fetching plans data.... Jan 12 22:44:07 volumio go-librespot[6974]: time="2026-01-12T22:44:07-06:00" level=debug msg="obtained new client token: AACGOQsbv7w2+EFX6dV7mqIuVi5b6rqgabAq4x3reTFdFM11PGYmGFxF4qLAZRCBtKIOvGv7SSQ8SCFyp51lrmg2QmUj1C6lFJA4/KlKqHBo/AV30K5axnsklZqApMYKu/TcwuWqsFBsEY+p0hefDVQzV57i6iqDj32Tyllxw+N+sL07oeU25LORn4Kq9zc/nbH6WQZlcnDdDFOS08aePIO1iO49kHoDTj6zFFRkrrAIYF+MEoApTq4=" Jan 12 22:44:07 volumio sudo[6985]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Jan 12 22:44:07 volumio sudo[6985]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 22:44:07 volumio go-librespot[6974]: time="2026-01-12T22:44:07-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 12 22:44:07 volumio sudo[6987]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Jan 12 22:44:07 volumio sudo[6987]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 22:44:07 volumio sudo[6990]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Jan 12 22:44:07 volumio sudo[6990]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 22:44:07 volumio go-librespot[6974]: time="2026-01-12T22:44:07-06:00" level=debug msg="completed keyexchange" Jan 12 22:44:07 volumio go-librespot[6974]: time="2026-01-12T22:44:07-06:00" level=debug msg="completed challenge" Jan 12 22:44:07 volumio systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Jan 12 22:44:07 volumio systemd[1]: mpd_monitor.service: Deactivated successfully. Jan 12 22:44:07 volumio systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Jan 12 22:44:07 volumio go-librespot[6974]: time="2026-01-12T22:44:07-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Jan 12 22:44:07 volumio volumio[6346]: info: Connection to go-librespot Websocket closed Jan 12 22:44:07 volumio systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Jan 12 22:44:07 volumio sudo[6987]: pam_unix(sudo:session): session closed for user root Jan 12 22:44:07 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 12 22:44:07 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 12 22:44:07 volumio sudo[6990]: pam_unix(sudo:session): session closed for user root Jan 12 22:44:07 volumio sudo[6985]: pam_unix(sudo:session): session closed for user root Jan 12 22:44:07 volumio mpd_monitor.sh[6993]: MPD Monitor Service: Starting MPD Monitor Service Jan 12 22:44:07 volumio volumio[6346]: info: Successfully started MPD Monitor Jan 12 22:44:07 volumio volumio[6346]: info: Successfully started MPD Monitor Jan 12 22:44:07 volumio volumio[6346]: info: Successfully started MPD Monitor Jan 12 22:44:10 volumio volumio[6346]: info: Getting Spotify volume Jan 12 22:44:10 volumio volumio[6346]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 12 22:44:10 volumio volumio[6346]: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 12 22:44:10 volumio volumio[6346]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Jan 12 22:44:10 volumio volumio[6346]: errno: -111, Jan 12 22:44:10 volumio volumio[6346]: code: 'ECONNREFUSED', Jan 12 22:44:10 volumio volumio[6346]: syscall: 'connect', Jan 12 22:44:10 volumio volumio[6346]: address: '127.0.0.1', Jan 12 22:44:10 volumio volumio[6346]: port: 9879, Jan 12 22:44:10 volumio volumio[6346]: response: undefined Jan 12 22:44:10 volumio volumio[6346]: } Jan 12 22:44:10 volumio volumio[6346]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 12 22:44:10 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Jan 12 22:44:10 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 12 22:44:10 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 12 22:44:10 volumio go-librespot[7008]: go-librespot daemon starting... Jan 12 22:44:10 volumio go-librespot[7009]: time="2026-01-12T22:44:10-06:00" level=info msg="running go-librespot 0.4.0" Jan 12 22:44:10 volumio go-librespot[7009]: time="2026-01-12T22:44:10-06:00" level=debug msg="app state loaded" Jan 12 22:44:10 volumio go-librespot[7009]: time="2026-01-12T22:44:10-06:00" level=debug msg="stored credentials not found" Jan 12 22:44:10 volumio go-librespot[7009]: time="2026-01-12T22:44:10-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 12 22:44:10 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.186.43 Jan 12 22:44:10 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Jan 12 22:44:10 volumio avahi-daemon[664]: Registering new address record for 169.254.186.43 on eth0.IPv4. Jan 12 22:44:10 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 12 22:44:10 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 12 22:44:10 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 12 22:44:11 volumio go-librespot[7009]: time="2026-01-12T22:44: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-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 12 22:44:11 volumio go-librespot[7009]: time="2026-01-12T22:44:11-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 12 22:44:11 volumio go-librespot[7009]: time="2026-01-12T22:44:11-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 12 22:44:11 volumio go-librespot[7009]: time="2026-01-12T22:44:11-06:00" level=info msg="zeroconf server listening on port 45613" Jan 12 22:44:11 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.186.43 Jan 12 22:44:11 volumio kernel: hwmon hwmon1: Undervoltage detected! Jan 12 22:44:11 volumio go-librespot[7009]: time="2026-01-12T22:44:11-06:00" level=debug msg="obtained new client token: AABmq6JbUC5zcFl9Wa1ggvzx0CXtblamEHSxC7E1T28qhH2osq2nnLJl0cS3b5WqovLqilnaZOrrYQXRgGLx+QhDVqYlNZVNItWqohgnv60HYLJs7NvX2W5OkrbTD/PIO6xjeDtFwVbFBCOy9gwpUvvRaMy+Js6dlvdwkJCqkCuGfMhjAgCCvxD7Wi9/NxitJpy238uk1kv8A2P5zjzPdgyXoJN0d9VSU/EKUhrcB3w/3ypTAhl22zk=" Jan 12 22:44:11 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.186.43 Jan 12 22:44:11 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.186.43 Jan 12 22:44:11 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Jan 12 22:44:11 volumio avahi-daemon[664]: Withdrawing address record for 169.254.186.43 on eth0. Jan 12 22:44:11 volumio go-librespot[7009]: time="2026-01-12T22:44:11-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 12 22:44:11 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 12 22:44:11 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 12 22:44:11 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 12 22:44:11 volumio go-librespot[7009]: time="2026-01-12T22:44:11-06:00" level=debug msg="completed keyexchange" Jan 12 22:44:11 volumio go-librespot[7009]: time="2026-01-12T22:44:11-06:00" level=debug msg="completed challenge" Jan 12 22:44:11 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Jan 12 22:44:11 volumio go-librespot[7009]: time="2026-01-12T22:44:11-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Jan 12 22:44:11 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 12 22:44:11 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 12 22:44:11 volumio sudo[7053]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-01-12 22:43' Jan 12 22:44:11 volumio sudo[7053]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 22:44:12 volumio sudo[7053]: pam_unix(sudo:session): session closed for user root Jan 12 22:44:12 volumio volumio-remote-updater[14193]: [2026-01-12 22:44:12] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Jan 12 22:44:12 volumio volumio-remote-updater[14193]: [2026-01-12 22:44:12] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Jan 12 22:44:12 volumio systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Jan 12 22:44:12 volumio systemd[1]: volumio.service: Failed with result 'exit-code'. Jan 12 22:44:12 volumio systemd[1]: volumio.service: Consumed 41.738s CPU time. Jan 12 22:44:12 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Jan 12 22:44:12 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Jan 12 22:44:12 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 22082. Jan 12 22:44:12 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Jan 12 22:44:12 volumio systemd[1]: Stopped volumio.service - Volumio Backend Module. Jan 12 22:44:12 volumio systemd[1]: volumio.service: Consumed 41.738s CPU time. Jan 12 22:44:12 volumio systemd[1]: Started volumio.service - Volumio Backend Module. Jan 12 22:44:12 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Jan 12 22:44:14 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 4. Jan 12 22:44:14 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 12 22:44:14 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 12 22:44:14 volumio go-librespot[7093]: go-librespot daemon starting... Jan 12 22:44:14 volumio go-librespot[7094]: time="2026-01-12T22:44:14-06:00" level=info msg="running go-librespot 0.4.0" Jan 12 22:44:14 volumio go-librespot[7094]: time="2026-01-12T22:44:14-06:00" level=debug msg="app state loaded" Jan 12 22:44:14 volumio go-librespot[7094]: time="2026-01-12T22:44:14-06:00" level=debug msg="stored credentials not found" Jan 12 22:44:14 volumio go-librespot[7094]: time="2026-01-12T22:44:14-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 12 22:44:15 volumio volumio[7078]: info: ------------------------------------------- Jan 12 22:44:15 volumio volumio[7078]: info: ----- Volumio3 ---- Jan 12 22:44:15 volumio volumio[7078]: info: ------------------------------------------- Jan 12 22:44:15 volumio volumio[7078]: info: ----- System startup ---- Jan 12 22:44:15 volumio volumio[7078]: info: ------------------------------------------- Jan 12 22:44:15 volumio go-librespot[7094]: time="2026-01-12T22:44: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]" Jan 12 22:44:15 volumio go-librespot[7094]: time="2026-01-12T22:44: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]" Jan 12 22:44:15 volumio go-librespot[7094]: time="2026-01-12T22:44: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]" Jan 12 22:44:15 volumio go-librespot[7094]: time="2026-01-12T22:44:15-06:00" level=info msg="zeroconf server listening on port 39939" Jan 12 22:44:15 volumio go-librespot[7094]: time="2026-01-12T22:44:15-06:00" level=debug msg="obtained new client token: AAB1QtLSvHGZZRukepDDQhe6JtWdCxu96l/G9I5JrvVD+mKhd1Bzm2VLXupFirxYZ4SOtdnKFygs4mdzJlfnUpMpkoNwdHM7lKp1NIoshPg7Z5H1FbBxZQlPwAxC55QGAeh57JSZOww6/jsZG5xnjj+MhHf8YW8G/YhR6h93MIJPMUArxGmPqw1QDn8gCba6tMxhYbCQzsMyUndHiZLSauYpuDo1PzOrJmm88tdn2ZWok+81xiUozpU=" Jan 12 22:44:15 volumio go-librespot[7094]: time="2026-01-12T22:44:15-06:00" level=warning msg="failed to connect to AP ap-guc3.spotify.com:4070, retrying with a different AP" error="dial tcp 104.154.127.247:4070: connect: connection refused" Jan 12 22:44:15 volumio go-librespot[7094]: time="2026-01-12T22:44:15-06:00" level=debug msg="connected to ap-guc3.spotify.com:443" Jan 12 22:44:15 volumio go-librespot[7094]: time="2026-01-12T22:44:15-06:00" level=debug msg="completed keyexchange" Jan 12 22:44:15 volumio go-librespot[7094]: time="2026-01-12T22:44:15-06:00" level=debug msg="completed challenge" Jan 12 22:44:15 volumio go-librespot[7094]: time="2026-01-12T22:44:15-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Jan 12 22:44:15 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 12 22:44:15 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 12 22:44:15 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.69.69 Jan 12 22:44:15 volumio avahi-daemon[664]: Registering new address record for 169.254.69.69 on eth0.IPv4. Jan 12 22:44:15 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Jan 12 22:44:15 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 12 22:44:15 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 12 22:44:15 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 12 22:44:15 volumio volumio[7078]: info: MYVOLUMIO Environment detected Jan 12 22:44:15 volumio volumio[7078]: info: Plugin folders cleanup Jan 12 22:44:15 volumio volumio[7078]: info: Scanning into folder /volumio/app/plugins/ Jan 12 22:44:15 volumio volumio[7078]: info: Scanning category audio_interface Jan 12 22:44:15 volumio volumio[7078]: info: Scanning category miscellanea Jan 12 22:44:15 volumio volumio[7078]: info: Scanning category music_service Jan 12 22:44:15 volumio volumio[7078]: info: Scanning category plugins.json Jan 12 22:44:15 volumio volumio[7078]: info: Scanning category system_controller Jan 12 22:44:15 volumio volumio[7078]: info: Scanning category user_interface Jan 12 22:44:15 volumio volumio[7078]: info: Scanning into folder /data/plugins/ Jan 12 22:44:15 volumio volumio[7078]: info: Scanning category audio_interface Jan 12 22:44:15 volumio volumio[7078]: info: Scanning category music_service Jan 12 22:44:15 volumio volumio[7078]: info: Scanning category system_controller Jan 12 22:44:15 volumio volumio[7078]: info: Scanning category system_hardware Jan 12 22:44:15 volumio volumio[7078]: info: Scanning category user_interface Jan 12 22:44:15 volumio volumio[7078]: info: Plugin folders cleanup completed Jan 12 22:44:15 volumio volumio[7078]: info: ------------------------------------------- Jan 12 22:44:15 volumio volumio[7078]: info: ----- Core plugins startup ---- Jan 12 22:44:15 volumio volumio[7078]: info: ------------------------------------------- Jan 12 22:44:15 volumio volumio[7078]: info: Loading plugins from folder /volumio/app/plugins/ Jan 12 22:44:15 volumio volumio[7078]: info: Adding plugin upnp to MyMusic Plugins Jan 12 22:44:15 volumio volumio[7078]: info: Adding plugin airplay_emulation to MyMusic Plugins Jan 12 22:44:15 volumio volumio[7078]: info: Adding plugin upnp_browser to MyMusic Plugins Jan 12 22:44:15 volumio volumio[7078]: info: Loading plugins from folder /data/plugins/ Jan 12 22:44:15 volumio volumio[7078]: info: Loading plugin "system"... Jan 12 22:44:15 volumio volumio[7078]: info: Loading plugin "appearance"... Jan 12 22:44:16 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.69.69 Jan 12 22:44:16 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.69.69 Jan 12 22:44:16 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.69.69 Jan 12 22:44:16 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Jan 12 22:44:16 volumio avahi-daemon[664]: Withdrawing address record for 169.254.69.69 on eth0. Jan 12 22:44:16 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Jan 12 22:44:16 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 12 22:44:16 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 12 22:44:16 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 12 22:44:17 volumio volumio[7078]: info: Loading plugin "network"... Jan 12 22:44:17 volumio volumio[7078]: info: Refreshing Cached IP Addresses Jan 12 22:44:17 volumio sudo[7147]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 12 22:44:17 volumio sudo[7147]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 22:44:17 volumio sudo[7147]: pam_unix(sudo:session): session closed for user root Jan 12 22:44:17 volumio volumio[7078]: info: Loading plugin "services"... Jan 12 22:44:17 volumio sudo[7149]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 12 22:44:17 volumio volumio[7078]: info: Loading plugin "alsa_controller"... Jan 12 22:44:17 volumio sudo[7149]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 22:44:17 volumio sudo[7149]: pam_unix(sudo:session): session closed for user root Jan 12 22:44:17 volumio sudo[7161]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Jan 12 22:44:17 volumio sudo[7161]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 22:44:17 volumio volumio[7078]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 12 22:44:17 volumio volumio[7078]: info: Loading plugin "wizard"... Jan 12 22:44:17 volumio volumio[7078]: info: Loading plugin "networkfs"... Jan 12 22:44:17 volumio volumio[7078]: info: Starting Udev Watcher for removable devices Jan 12 22:44:17 volumio volumio[7078]: info: Ignoring mount for partition: boot Jan 12 22:44:17 volumio volumio[7078]: info: Ignoring mount for partition: volumio Jan 12 22:44:17 volumio volumio[7078]: info: Ignoring mount for partition: volumio_data Jan 12 22:44:17 volumio volumio[7078]: info: Mounting Device Wikipedia Jan 12 22:44:17 volumio volumio-remote-updater[14193]: [2026-01-12 22:44:17] [connect] Successful connection Jan 12 22:44:17 volumio sudo[7186]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mount /dev/sda1 /mnt/USB/Wikipedia -o noatime Jan 12 22:44:17 volumio sudo[7186]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 22:44:17 volumio sudo[7186]: pam_unix(sudo:session): session closed for user root Jan 12 22:44:17 volumio volumio[7078]: mount: /media/Wikipedia: /dev/sda1 already mounted on /media/Wikipedia. Jan 12 22:44:17 volumio volumio[7078]: dmesg(1) may have more information after failed mount system call. Jan 12 22:44:17 volumio volumio[7078]: error: Failed to mount Wikipedia: Error: Command failed: /usr/bin/sudo /bin/mount "/dev/sda1" "/mnt/USB/Wikipedia" -o noatime Jan 12 22:44:17 volumio volumio[7078]: mount: /media/Wikipedia: /dev/sda1 already mounted on /media/Wikipedia. Jan 12 22:44:17 volumio volumio[7078]: dmesg(1) may have more information after failed mount system call. Jan 12 22:44:17 volumio volumio[7078]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 12 22:44:17 volumio volumio[7078]: info: Loading plugin "volumio_command_line_client"... Jan 12 22:44:17 volumio volumio[7078]: info: Loading plugin "upnp"... Jan 12 22:44:17 volumio volumio[7078]: info: [1768279457535] Starting Upmpd Daemon Jan 12 22:44:17 volumio volumio[7078]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 12 22:44:17 volumio volumio[7078]: info: Loading plugin "my_music"... Jan 12 22:44:17 volumio volumio[7078]: info: Loading plugin "mpd"... Jan 12 22:44:17 volumio sudo[7161]: pam_unix(sudo:session): session closed for user root Jan 12 22:44:18 volumio volumio[7078]: info: Loading plugin "upnp_browser"... Jan 12 22:44:18 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 5. Jan 12 22:44:18 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 12 22:44:18 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 12 22:44:18 volumio go-librespot[7188]: go-librespot daemon starting... Jan 12 22:44:18 volumio go-librespot[7189]: time="2026-01-12T22:44:18-06:00" level=info msg="running go-librespot 0.4.0" Jan 12 22:44:18 volumio go-librespot[7189]: time="2026-01-12T22:44:18-06:00" level=debug msg="app state loaded" Jan 12 22:44:18 volumio go-librespot[7189]: time="2026-01-12T22:44:18-06:00" level=debug msg="stored credentials not found" Jan 12 22:44:18 volumio go-librespot[7189]: time="2026-01-12T22:44:18-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 12 22:44:19 volumio go-librespot[7189]: time="2026-01-12T22:44: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-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 12 22:44:19 volumio go-librespot[7189]: time="2026-01-12T22:44:19-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 12 22:44:19 volumio go-librespot[7189]: time="2026-01-12T22:44:19-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 12 22:44:19 volumio go-librespot[7189]: time="2026-01-12T22:44:19-06:00" level=info msg="zeroconf server listening on port 36749" Jan 12 22:44:19 volumio go-librespot[7189]: time="2026-01-12T22:44:19-06:00" level=debug msg="obtained new client token: AABU5BY+nf/3cSpd1aCcZ5hICgwrzzC0oaL66QExn80rgtAeeXDZ5SydKipzWNLcaGXk3HkYnOeY3tdvMVCeJIeMUyyEhVFirBBW8aoGBRRWcFMw4PnxkadrheXaffAlNDyE57Dq3p/VRjtRwPO/7y9x1JekLJ6cELNNEh9TdawZoR7PFHJ11KQYxPDMyUhHvrMJC4zc+tMeMPlreBAYfKsArwRHeClcQPh7727KsvMURzEWhLmeny8xqQ==" Jan 12 22:44:19 volumio go-librespot[7189]: time="2026-01-12T22:44:19-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 12 22:44:20 volumio go-librespot[7189]: time="2026-01-12T22:44:20-06:00" level=debug msg="completed keyexchange" Jan 12 22:44:20 volumio go-librespot[7189]: time="2026-01-12T22:44:20-06:00" level=debug msg="completed challenge" Jan 12 22:44:20 volumio go-librespot[7189]: time="2026-01-12T22:44: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 " Jan 12 22:44:20 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 12 22:44:20 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 12 22:44:20 volumio volumio[7078]: info: Loading plugin "alarm-clock"... Jan 12 22:44:20 volumio volumio[7078]: info: Loading plugin "airplay_emulation"... Jan 12 22:44:20 volumio volumio[7078]: info: Starting Shairport Sync Jan 12 22:44:20 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.210.116 Jan 12 22:44:21 volumio volumio[7078]: info: Loading plugin "last_100"... Jan 12 22:44:21 volumio avahi-daemon[664]: Registering new address record for 169.254.210.116 on eth0.IPv4. Jan 12 22:44:21 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Jan 12 22:44:21 volumio volumio[7078]: info: Loading plugin "webradio"... Jan 12 22:44:21 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 12 22:44:21 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 12 22:44:21 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 12 22:44:21 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.210.116 Jan 12 22:44:21 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.210.116 Jan 12 22:44:21 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.210.116 Jan 12 22:44:21 volumio avahi-daemon[664]: Withdrawing address record for 169.254.210.116 on eth0. Jan 12 22:44:21 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Jan 12 22:44:21 volumio volumio[7078]: info: Loading plugin "i2s_dacs"... Jan 12 22:44:21 volumio volumio[7078]: info: I2S DAC not set, start Auto-detection Jan 12 22:44:21 volumio volumio[7078]: info: Loading plugin "volumiodiscovery"... Jan 12 22:44:21 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 12 22:44:21 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 12 22:44:21 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 12 22:44:21 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Jan 12 22:44:21 volumio volumio[7078]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jan 12 22:44:21 volumio volumio[7078]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 12 22:44:21 volumio volumio[7078]: *** WARNING *** For more information see Jan 12 22:44:21 volumio volumio[7078]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jan 12 22:44:21 volumio volumio[7078]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 12 22:44:21 volumio volumio[7078]: *** WARNING *** For more information see Jan 12 22:44:21 volumio node[7078]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jan 12 22:44:21 volumio node[7078]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 12 22:44:21 volumio node[7078]: *** WARNING *** For more information see Jan 12 22:44:21 volumio node[7078]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jan 12 22:44:21 volumio node[7078]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 12 22:44:21 volumio node[7078]: *** WARNING *** For more information see Jan 12 22:44:21 volumio volumio[7078]: info: Applying required configuration parameters for plugin volumiodiscovery Jan 12 22:44:21 volumio volumio[7078]: info: Discovery: Started advertising with name: Volumio Jan 12 22:44:21 volumio volumio[7078]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 12 22:44:21 volumio volumio[7078]: info: Loading plugin "bandcamp"... Jan 12 22:44:22 volumio volumio[7078]: info: Plugin calmradio is not enabled Jan 12 22:44:22 volumio volumio[7078]: info: Loading plugin "soundcloud"... Jan 12 22:44:22 volumio volumio[7078]: info: Loading plugin "spop"... Jan 12 22:44:23 volumio kernel: hwmon hwmon1: Voltage normalised Jan 12 22:44:23 volumio volumio[7078]: info: Loading plugin "squeezelite_mc"... Jan 12 22:44:23 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6. Jan 12 22:44:23 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 12 22:44:23 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 12 22:44:23 volumio go-librespot[7231]: go-librespot daemon starting... Jan 12 22:44:24 volumio go-librespot[7232]: time="2026-01-12T22:44:24-06:00" level=info msg="running go-librespot 0.4.0" Jan 12 22:44:24 volumio go-librespot[7232]: time="2026-01-12T22:44:24-06:00" level=debug msg="app state loaded" Jan 12 22:44:24 volumio go-librespot[7232]: time="2026-01-12T22:44:24-06:00" level=debug msg="stored credentials not found" Jan 12 22:44:24 volumio go-librespot[7232]: time="2026-01-12T22:44:24-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 12 22:44:24 volumio go-librespot[7232]: time="2026-01-12T22:44:24-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 12 22:44:24 volumio go-librespot[7232]: time="2026-01-12T22:44:24-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 12 22:44:24 volumio go-librespot[7232]: time="2026-01-12T22:44:24-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 12 22:44:24 volumio go-librespot[7232]: time="2026-01-12T22:44:24-06:00" level=info msg="zeroconf server listening on port 41059" Jan 12 22:44:24 volumio go-librespot[7232]: time="2026-01-12T22:44:24-06:00" level=debug msg="obtained new client token: AABI3cLbRfkQPS9Yp1veXogpHAv7EvQ8VptfQ+jw+1rkQvuEo8PWZ+lPcoA8YPu+vxLXTmR00GpM2h4UXfKq+Y0Gb9RqkUtdAerprHlqGZzFkKIHYjOwjYG+JAErsVQb26j1uoqpRSJrZhyXxhc0lAdd3RE2qs9WqSPnFkUuqJe6Zt3pBaN+RVal1QemJT6NH46/f0AnAtKRk6LCPIR8xrM1hcwDoUBLoylqw+zRtuvO+QoIqm/LXeVX+A==" Jan 12 22:44:24 volumio volumio[7078]: info: Loading plugin "youtube2"... Jan 12 22:44:24 volumio go-librespot[7232]: time="2026-01-12T22:44:24-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 12 22:44:24 volumio go-librespot[7232]: time="2026-01-12T22:44:24-06:00" level=debug msg="completed keyexchange" Jan 12 22:44:24 volumio go-librespot[7232]: time="2026-01-12T22:44:24-06:00" level=debug msg="completed challenge" Jan 12 22:44:24 volumio go-librespot[7232]: time="2026-01-12T22:44:24-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Jan 12 22:44:24 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 12 22:44:24 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 12 22:44:25 volumio volumio[7078]: info: Loading plugin "ytcr"... Jan 12 22:44:25 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.106.114 Jan 12 22:44:25 volumio avahi-daemon[664]: Registering new address record for 169.254.106.114 on eth0.IPv4. Jan 12 22:44:25 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Jan 12 22:44:25 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 12 22:44:25 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 12 22:44:25 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 12 22:44:26 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.106.114 Jan 12 22:44:26 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.106.114 Jan 12 22:44:26 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.106.114 Jan 12 22:44:26 volumio avahi-daemon[664]: Withdrawing address record for 169.254.106.114 on eth0. Jan 12 22:44:26 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Jan 12 22:44:26 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Jan 12 22:44:26 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 12 22:44:26 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 12 22:44:26 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 12 22:44:26 volumio volumio[7078]: info: Loading plugin "ytmusic"... Jan 12 22:44:27 volumio volumio[7078]: info: Plugin now_playing is not enabled Jan 12 22:44:27 volumio volumio[7078]: info: Loading plugin "outputs"... Jan 12 22:44:27 volumio volumio[7078]: info: Loading plugin "albumart"... Jan 12 22:44:27 volumio volumio[7078]: info: Plugin example_plugin is not enabled Jan 12 22:44:27 volumio volumio[7078]: info: Loading plugin "inputs"... Jan 12 22:44:27 volumio volumio[7078]: info: Loading plugin "updater_comm"... Jan 12 22:44:27 volumio volumio[7078]: info: Plugin mpdemulation is not enabled Jan 12 22:44:27 volumio volumio[7078]: info: Loading plugin "rest_api"... Jan 12 22:44:27 volumio volumio[7078]: info: Loading plugin "websocket"... Jan 12 22:44:27 volumio volumio[7078]: info: Starting Socket.io Server version 1.7.4 Jan 12 22:44:27 volumio volumio[7078]: info: Plugin fusiondsp is not enabled Jan 12 22:44:27 volumio volumio[7078]: info: Plugin mpdoutput is not enabled Jan 12 22:44:27 volumio volumio[7078]: info: Plugin RoonBridge is not enabled Jan 12 22:44:27 volumio volumio[7078]: info: Loading plugin "podcast"... Jan 12 22:44:27 volumio volumio[7078]: info: ControllerPodcast::constructor Jan 12 22:44:27 volumio volumio[7078]: info: Loading plugin "volusonic"... Jan 12 22:44:27 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 7. Jan 12 22:44:27 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 12 22:44:27 volumio volumio[7272]: Forking 3 albumart workers Jan 12 22:44:27 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 12 22:44:27 volumio go-librespot[7299]: go-librespot daemon starting... Jan 12 22:44:27 volumio go-librespot[7319]: time="2026-01-12T22:44:27-06:00" level=info msg="running go-librespot 0.4.0" Jan 12 22:44:27 volumio go-librespot[7319]: time="2026-01-12T22:44:27-06:00" level=debug msg="app state loaded" Jan 12 22:44:27 volumio go-librespot[7319]: time="2026-01-12T22:44:27-06:00" level=debug msg="stored credentials not found" Jan 12 22:44:27 volumio go-librespot[7319]: time="2026-01-12T22:44:27-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 12 22:44:28 volumio go-librespot[7319]: time="2026-01-12T22:44:28-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 12 22:44:28 volumio go-librespot[7319]: time="2026-01-12T22:44:28-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 12 22:44:28 volumio go-librespot[7319]: time="2026-01-12T22:44:28-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 12 22:44:28 volumio go-librespot[7319]: time="2026-01-12T22:44:28-06:00" level=info msg="zeroconf server listening on port 39641" Jan 12 22:44:28 volumio go-librespot[7319]: time="2026-01-12T22:44:28-06:00" level=debug msg="obtained new client token: AACt/i/wTAEaDUKFelYpnyZBjCGiGkiTurzBwcQPnu+iSnixIUDEVxvyPzK3NK7lPnm9s2zLr0WgW9LpPTZuZ+fgvHLfodw+zsu4tJgHuaNtma1el8/d3SiME+78EYuMBwrhBWT2D4h/qfb/lzRBJaiMx3cHzMjJHrHgaJLDH9xqYyeYnEMXUZJB3XnhbYXdF5ivwX2xq6942Pbc69QRT5U6YkZFV1MlfpPr+bf7shXGDV69LYm4RXsFVA==" Jan 12 22:44:28 volumio go-librespot[7319]: time="2026-01-12T22:44:28-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 12 22:44:28 volumio go-librespot[7319]: time="2026-01-12T22:44:28-06:00" level=debug msg="completed keyexchange" Jan 12 22:44:28 volumio go-librespot[7319]: time="2026-01-12T22:44:28-06:00" level=debug msg="completed challenge" Jan 12 22:44:28 volumio go-librespot[7319]: time="2026-01-12T22:44:28-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Jan 12 22:44:28 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 12 22:44:28 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 12 22:44:29 volumio volumio[7078]: info: Applying required configuration parameters for plugin volusonic Jan 12 22:44:29 volumio volumio[7078]: info: Loading plugin "backup_restore"... Jan 12 22:44:29 volumio volumio[7301]: Starting albumart workers Jan 12 22:44:29 volumio volumio[7300]: Starting albumart workers Jan 12 22:44:29 volumio volumio[7078]: info: Applying required configuration parameters for plugin backup_restore Jan 12 22:44:29 volumio volumio[7078]: info: Plugin rpi_eeprom_config is not enabled Jan 12 22:44:29 volumio volumio[7078]: info: Plugin rpi_eeprom_updater is not enabled Jan 12 22:44:29 volumio volumio[7078]: info: Loading plugin "scheduledrestart"... Jan 12 22:44:29 volumio kernel: hwmon hwmon1: Undervoltage detected! Jan 12 22:44:29 volumio volumio-remote-updater[14193]: [2026-01-12 22:44:29] [connect] Successful connection Jan 12 22:44:29 volumio volumio[7302]: Starting albumart workers Jan 12 22:44:30 volumio volumio[7078]: info: Applying required configuration parameters for plugin scheduledrestart Jan 12 22:44:30 volumio volumio[7078]: info: Plugin Bluetoothremote is not enabled Jan 12 22:44:30 volumio volumio[7078]: info: Plugin music_services_shield is not enabled Jan 12 22:44:30 volumio volumio[7078]: info: Loading plugin "Systeminfo"... Jan 12 22:44:30 volumio volumio[7078]: info: Plugin peppymeterbasic is not enabled Jan 12 22:44:30 volumio volumio[7078]: info: Loading plugin "peppyspectrum"... Jan 12 22:44:31 volumio volumio[7078]: info: Loading i18n strings for locale en Jan 12 22:44:31 volumio volumio[7078]: info: Plugin peppyspectrum has duplicated i18n key SAVE. It is ignored. Jan 12 22:44:31 volumio volumio[7078]: Updating browse sources language Jan 12 22:44:31 volumio volumio[7078]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 12 22:44:31 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 8. Jan 12 22:44:31 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 12 22:44:31 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 12 22:44:31 volumio go-librespot[7356]: go-librespot daemon starting... Jan 12 22:44:31 volumio volumio[7078]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 12 22:44:31 volumio volumio[7078]: info: CoreCommandRouter::initPlayerControls Jan 12 22:44:31 volumio go-librespot[7357]: time="2026-01-12T22:44:31-06:00" level=info msg="running go-librespot 0.4.0" Jan 12 22:44:31 volumio go-librespot[7357]: time="2026-01-12T22:44:31-06:00" level=debug msg="app state loaded" Jan 12 22:44:31 volumio go-librespot[7357]: time="2026-01-12T22:44:31-06:00" level=debug msg="stored credentials not found" Jan 12 22:44:31 volumio volumio[7078]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:44:31 volumio volumio[7078]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:44:31 volumio go-librespot[7357]: time="2026-01-12T22:44:31-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 12 22:44:31 volumio volumio[7078]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:44:31 volumio volumio[7078]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:44:31 volumio volumio[7078]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:44:31 volumio volumio[7078]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:44:31 volumio volumio[7078]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:44:31 volumio volumio[7078]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:44:31 volumio volumio[7078]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 12 22:44:31 volumio volumio[7078]: Express server listening on port 3000 Jan 12 22:44:31 volumio volumio[7078]: [Metrics] WebUI: 17s 404.46ms Jan 12 22:44:31 volumio volumio[7078]: info: CoreStateMachine::resetVolumioState Jan 12 22:44:31 volumio volumio[7078]: info: CoreStateMachine::getcurrentVolume Jan 12 22:44:31 volumio volumio[7078]: info: CoreCommandRouter::volumioRetrievevolume Jan 12 22:44:31 volumio volumio[7078]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 12 22:44:32 volumio sudo[7371]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 12 22:44:32 volumio sudo[7371]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 22:44:32 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.72.233 Jan 12 22:44:32 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Jan 12 22:44:32 volumio avahi-daemon[664]: Registering new address record for 169.254.72.233 on eth0.IPv4. Jan 12 22:44:32 volumio sudo[7369]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 12 22:44:32 volumio sudo[7369]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 22:44:32 volumio sudo[7371]: pam_unix(sudo:session): session closed for user root Jan 12 22:44:32 volumio sudo[7369]: pam_unix(sudo:session): session closed for user root Jan 12 22:44:32 volumio volumio[7078]: info: Volumio Network Manager: Network status updated: 1 Jan 12 22:44:32 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 12 22:44:32 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 12 22:44:32 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 12 22:44:32 volumio go-librespot[7357]: time="2026-01-12T22:44: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]" Jan 12 22:44:32 volumio go-librespot[7357]: time="2026-01-12T22:44: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]" Jan 12 22:44:32 volumio go-librespot[7357]: time="2026-01-12T22:44: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]" Jan 12 22:44:32 volumio go-librespot[7357]: time="2026-01-12T22:44:32-06:00" level=info msg="zeroconf server listening on port 43431" Jan 12 22:44:32 volumio volumio-remote-updater[14193]: [2026-01-12 22:44:32] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1768279469 101 Jan 12 22:44:32 volumio volumio[7078]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 3 Transport: websocket Total Clients: 1 Jan 12 22:44:32 volumio volumio[7078]: info: VolumeController:: Volume=100 Mute =false Jan 12 22:44:32 volumio volumio[7078]: info: CoreStateMachine::pushState Jan 12 22:44:32 volumio volumio[7078]: info: CorePlayQueue::getTrack 0 Jan 12 22:44:32 volumio volumio[7078]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 12 22:44:32 volumio volumio[7078]: info: CoreCommandRouter::volumioPushState Jan 12 22:44:32 volumio volumio[7078]: info: CoreStateMachine::updateTrackBlock Jan 12 22:44:32 volumio volumio[7078]: info: CorePlayQueue::getTrackBlock Jan 12 22:44:32 volumio volumio[7078]: info: CoreCommandRouter::volumioRetrievevolume Jan 12 22:44:32 volumio volumio[7078]: info: Reloading queue from file Jan 12 22:44:32 volumio volumio[7078]: info: CoreStateMachine::setRepeat null single undefined Jan 12 22:44:32 volumio volumio[7078]: info: CoreStateMachine::pushState Jan 12 22:44:32 volumio volumio[7078]: info: CorePlayQueue::getTrack 0 Jan 12 22:44:32 volumio volumio[7078]: info: CoreCommandRouter::volumioPushState Jan 12 22:44:32 volumio volumio[7078]: info: CoreStateMachine::setRandom null Jan 12 22:44:32 volumio volumio[7078]: info: CoreStateMachine::pushState Jan 12 22:44:32 volumio volumio[7078]: info: CorePlayQueue::getTrack 0 Jan 12 22:44:32 volumio volumio[7078]: info: CoreCommandRouter::volumioPushState Jan 12 22:44:32 volumio volumio[7078]: info: Setting Device type: Raspberry PI Jan 12 22:44:32 volumio go-librespot[7357]: time="2026-01-12T22:44:32-06:00" level=debug msg="obtained new client token: AABZFS2u/wSk594mI/0WAeD4JWCfe/8vEySp5ubnfyJOONxw9KfDoo2UgvjyL4HkMrus7kG2t1JbNclN9t7mIANlUC065kpKtsFr+R0m3zvHhtjwUw4R5qlvq7zuqqYXKkjBOXxELe01u4qZKylhOs2j/27XabPfg3IyPwxi3PspkxjlYtWIxtJqs0yrrycy2ll/GXZySiWbsBgL/vSI+TUOL1XbgktjBpAgHOCR4xZF4wZ3lDV8Xm0Chw==" Jan 12 22:44:32 volumio volumio[7078]: info: VolumeController:: Volume=100 Mute =false Jan 12 22:44:32 volumio volumio[7078]: info: CoreStateMachine::pushState Jan 12 22:44:32 volumio volumio[7078]: info: CorePlayQueue::getTrack 0 Jan 12 22:44:32 volumio volumio[7078]: info: CoreCommandRouter::volumioPushState Jan 12 22:44:32 volumio volumio[7078]: info: Completed loading Core Plugins Jan 12 22:44:32 volumio sudo[7401]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Jan 12 22:44:32 volumio volumio[7078]: info: Preparing to generate the ALSA configuration file Jan 12 22:44:32 volumio sudo[7401]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 22:44:32 volumio go-librespot[7357]: time="2026-01-12T22:44:32-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 12 22:44:32 volumio volumio[7078]: info: Discovery: adding a135e40e-a404-457b-98f5-36bf71c75954 Jan 12 22:44:32 volumio volumio[7078]: info: Discovery: Found device Volumio Jan 12 22:44:32 volumio volumio[7078]: info: CoreCommandRouter::volumioGetState Jan 12 22:44:32 volumio volumio[7078]: info: CorePlayQueue::getTrack 0 Jan 12 22:44:32 volumio volumio[7078]: info: Discovery: this is already registered, a135e40e-a404-457b-98f5-36bf71c75954 Jan 12 22:44:32 volumio volumio[7078]: info: Discovery: Found device Volumio Jan 12 22:44:32 volumio volumio[7078]: info: CoreCommandRouter::volumioGetState Jan 12 22:44:32 volumio volumio[7078]: info: CorePlayQueue::getTrack 0 Jan 12 22:44:32 volumio volumio[7078]: info: The plugin peppyspectrum has an ALSA contribution file peppy_in.peppy_out.6.conf Jan 12 22:44:32 volumio volumio[7078]: info: Reading ALSA contributions from plugins. Jan 12 22:44:32 volumio sudo[7401]: pam_unix(sudo:session): session closed for user root Jan 12 22:44:32 volumio volumio[7078]: info: Upmpdcli Daemon Started Jan 12 22:44:32 volumio go-librespot[7357]: time="2026-01-12T22:44:32-06:00" level=debug msg="completed keyexchange" Jan 12 22:44:32 volumio go-librespot[7357]: time="2026-01-12T22:44:32-06:00" level=debug msg="completed challenge" Jan 12 22:44:32 volumio volumio[7078]: info: Asound.conf file unchanged, so no further update is needed Jan 12 22:44:32 volumio volumio[7078]: info: Output device has changed, restarting MPD Jan 12 22:44:32 volumio volumio[7078]: info: Output device has changed, restarting Shairport Sync Jan 12 22:44:32 volumio volumio[7078]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:44:32 volumio volumio[7078]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 12 22:44:32 volumio sudo[7404]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 12 22:44:32 volumio sudo[7404]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 22:44:32 volumio go-librespot[7357]: time="2026-01-12T22:44:32-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Jan 12 22:44:32 volumio sudo[7406]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 12 22:44:32 volumio sudo[7406]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 22:44:32 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 12 22:44:32 volumio sudo[7404]: pam_unix(sudo:session): session closed for user root Jan 12 22:44:32 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 12 22:44:32 volumio volumio[7078]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 12 22:44:32 volumio volumio[7078]: info: ___________ START PLUGINS ___________ Jan 12 22:44:32 volumio volumio[7078]: info: ControllerMpd::onStart: Initializing MPD Jan 12 22:44:32 volumio volumio[7078]: info: Creating MPD Configuration file Jan 12 22:44:32 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Jan 12 22:44:32 volumio volumio[7078]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 12 22:44:32 volumio volumio[7078]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 12 22:44:32 volumio volumio[7078]: info: [1768279472763] CoreMusicLibrary::Adding element Media Servers Jan 12 22:44:32 volumio volumio[7078]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 12 22:44:32 volumio sudo[7414]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 12 22:44:32 volumio sudo[7414]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 22:44:32 volumio sudo[7416]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 12 22:44:32 volumio sudo[7416]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 22:44:32 volumio sudo[7414]: pam_unix(sudo:session): session closed for user root Jan 12 22:44:32 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.72.233 Jan 12 22:44:32 volumio volumio[7078]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:44:32 volumio volumio[7078]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 12 22:44:32 volumio volumio[7078]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 12 22:44:32 volumio volumio[7078]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:44:32 volumio volumio[7078]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 12 22:44:32 volumio systemd[1]: mpd.service: Deactivated successfully. Jan 12 22:44:32 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Jan 12 22:44:32 volumio systemd[1]: mpd.service: Consumed 5.649s CPU time. Jan 12 22:44:32 volumio systemd[1]: mpd.socket: Deactivated successfully. Jan 12 22:44:32 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jan 12 22:44:32 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jan 12 22:44:32 volumio volumio[7078]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 12 22:44:32 volumio volumio[7078]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 12 22:44:32 volumio volumio[7078]: info: [1768279472878] CoreMusicLibrary::Adding element Last_100 Jan 12 22:44:32 volumio volumio[7078]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 12 22:44:32 volumio volumio[7078]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 12 22:44:32 volumio volumio[7078]: info: [1768279472886] CoreMusicLibrary::Adding element Webradio Jan 12 22:44:32 volumio volumio[7078]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 12 22:44:32 volumio volumio[7078]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 12 22:44:32 volumio volumio[7078]: info: Initializing BBC Radios Jan 12 22:44:32 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.72.233 Jan 12 22:44:32 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.72.233 Jan 12 22:44:32 volumio avahi-daemon[664]: Withdrawing address record for 169.254.72.233 on eth0. Jan 12 22:44:32 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Jan 12 22:44:32 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jan 12 22:44:32 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Jan 12 22:44:32 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 12 22:44:32 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 12 22:44:32 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 12 22:44:32 volumio volumio[7078]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 12 22:44:32 volumio volumio[7078]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 12 22:44:33 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Jan 12 22:44:33 volumio volumio[7078]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 12 22:44:33 volumio volumio[7078]: info: [1768279473002] CoreMusicLibrary::Adding element Bandcamp Discover Jan 12 22:44:33 volumio volumio[7078]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 12 22:44:33 volumio volumio[7078]: Cannot find translation for source Bandcamp Discover Jan 12 22:44:33 volumio volumio[7078]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 12 22:44:33 volumio volumio[7078]: info: [1768279473015] CoreMusicLibrary::Adding element SoundCloud Jan 12 22:44:33 volumio volumio[7078]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 12 22:44:33 volumio volumio[7078]: Cannot find translation for source Bandcamp Discover Jan 12 22:44:33 volumio volumio[7078]: Cannot find translation for source SoundCloud Jan 12 22:44:33 volumio volumio[7078]: info: Creating Spotify config file Jan 12 22:44:33 volumio volumio[7078]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:44:33 volumio sudo[7437]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jan 12 22:44:33 volumio sudo[7437]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Jan 12 22:44:33 volumio sudo[7437]: pam_unix(sudo:session): session closed for user root Jan 12 22:44:33 volumio volumio[7078]: info: [squeezelite_mc] Starting proxy server... Jan 12 22:44:33 volumio volumio[7078]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 12 22:44:33 volumio volumio[7078]: info: [1768279473386] CoreMusicLibrary::Adding element YouTube2 Jan 12 22:44:33 volumio volumio[7078]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 12 22:44:33 volumio volumio[7078]: Cannot find translation for source Bandcamp Discover Jan 12 22:44:33 volumio volumio[7078]: Cannot find translation for source SoundCloud Jan 12 22:44:33 volumio volumio[7078]: Cannot find translation for source YouTube2 Jan 12 22:44:33 volumio volumio[7078]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 12 22:44:33 volumio volumio[7078]: info: [1768279473404] CoreMusicLibrary::Adding element YouTube Music Jan 12 22:44:33 volumio volumio[7078]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 12 22:44:33 volumio volumio[7078]: Cannot find translation for source Bandcamp Discover Jan 12 22:44:33 volumio volumio[7078]: Cannot find translation for source SoundCloud Jan 12 22:44:33 volumio volumio[7078]: Cannot find translation for source YouTube2 Jan 12 22:44:33 volumio volumio[7078]: Cannot find translation for source YouTube Music Jan 12 22:44:33 volumio volumio[7078]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 12 22:44:33 volumio volumio[7078]: info: [1768279473416] CoreMusicLibrary::Adding element Podcast Jan 12 22:44:33 volumio volumio[7078]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 12 22:44:33 volumio volumio[7078]: Cannot find translation for source Bandcamp Discover Jan 12 22:44:33 volumio volumio[7078]: Cannot find translation for source SoundCloud Jan 12 22:44:33 volumio volumio[7078]: Cannot find translation for source YouTube2 Jan 12 22:44:33 volumio volumio[7078]: Cannot find translation for source YouTube Music Jan 12 22:44:33 volumio volumio[7078]: Cannot find translation for source Podcast Jan 12 22:44:33 volumio volumio[7078]: info: Loading i18n strings for locale en Jan 12 22:44:33 volumio volumio[7078]: info: Plugin peppyspectrum has duplicated i18n key SAVE. It is ignored. Jan 12 22:44:33 volumio volumio[7078]: Updating browse sources language Jan 12 22:44:33 volumio volumio[7078]: Cannot find translation for source Bandcamp Discover Jan 12 22:44:33 volumio volumio[7078]: Cannot find translation for source SoundCloud Jan 12 22:44:33 volumio volumio[7078]: Cannot find translation for source YouTube2 Jan 12 22:44:33 volumio volumio[7078]: Cannot find translation for source YouTube Music Jan 12 22:44:33 volumio volumio[7078]: Cannot find translation for source Podcast Jan 12 22:44:33 volumio volumio[7078]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 12 22:44:33 volumio volumio[7078]: Cannot find translation for source Bandcamp Discover Jan 12 22:44:33 volumio volumio[7078]: Cannot find translation for source SoundCloud Jan 12 22:44:33 volumio volumio[7078]: Cannot find translation for source YouTube2 Jan 12 22:44:33 volumio volumio[7078]: Cannot find translation for source YouTube Music Jan 12 22:44:33 volumio volumio[7078]: Cannot find translation for source Podcast Jan 12 22:44:33 volumio volumio[7078]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 12 22:44:33 volumio volumio[7078]: info: [1768279473464] CoreMusicLibrary::Adding element Volusonic Jan 12 22:44:33 volumio volumio[7078]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 12 22:44:33 volumio volumio[7078]: Cannot find translation for source Bandcamp Discover Jan 12 22:44:33 volumio volumio[7078]: Cannot find translation for source SoundCloud Jan 12 22:44:33 volumio volumio[7078]: Cannot find translation for source YouTube2 Jan 12 22:44:33 volumio volumio[7078]: Cannot find translation for source YouTube Music Jan 12 22:44:33 volumio volumio[7078]: Cannot find translation for source Podcast Jan 12 22:44:33 volumio volumio[7078]: Cannot find translation for source Volusonic Jan 12 22:44:33 volumio volumio[7078]: info: Scheduling reboots with hours: 0, minutes: 0 in timezone: America/Chicago Jan 12 22:44:33 volumio volumio[7078]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , updateALSAConfigFile Jan 12 22:44:33 volumio volumio[7078]: info: Volumio Calling Home Jan 12 22:44:33 volumio volumio[7078]: info: [squeezelite_mc] Proxy server started on port 42157 Jan 12 22:44:33 volumio volumio[7078]: info: Preparing to generate the ALSA configuration file Jan 12 22:44:33 volumio volumio[7078]: info: CoreCommandRouter::volumioRetrievevolume Jan 12 22:44:33 volumio volumio[7078]: info: The plugin peppyspectrum has an ALSA contribution file peppy_in.peppy_out.6.conf Jan 12 22:44:33 volumio volumio[7078]: info: Reading ALSA contributions from plugins. Jan 12 22:44:33 volumio volumio[7078]: info: MPD Permissions set Jan 12 22:44:33 volumio volumio[7078]: info: MPD Permissions set Jan 12 22:44:33 volumio volumio[7078]: info: Spotify config file written Jan 12 22:44:33 volumio sudo[7468]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jan 12 22:44:33 volumio sudo[7468]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 22:44:33 volumio volumio[7078]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Jan 12 22:44:33 volumio volumio[7078]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:44:33 volumio volumio[7078]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:44:33 volumio volumio[7078]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:44:33 volumio volumio[7078]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:44:33 volumio volumio[7078]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:44:33 volumio volumio[7078]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:44:33 volumio volumio[7078]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:44:33 volumio volumio[7078]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:44:33 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 12 22:44:33 volumio volumio[7078]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 12 22:44:33 volumio volumio[7078]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:44:33 volumio volumio[7078]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:44:33 volumio volumio[7078]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:44:33 volumio volumio[7078]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:44:33 volumio volumio[7078]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:44:33 volumio volumio[7078]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:44:33 volumio volumio[7078]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:44:33 volumio volumio[7078]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:44:33 volumio volumio[7078]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:44:33 volumio volumio[7078]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 12 22:44:33 volumio volumio[7078]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:44:33 volumio volumio[7078]: info: No need to fix Spotify hosts Jan 12 22:44:33 volumio go-librespot[7475]: go-librespot daemon starting... Jan 12 22:44:33 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 12 22:44:33 volumio sudo[7468]: pam_unix(sudo:session): session closed for user root Jan 12 22:44:33 volumio go-librespot[7481]: time="2026-01-12T22:44:33-06:00" level=info msg="running go-librespot 0.4.0" Jan 12 22:44:33 volumio go-librespot[7481]: time="2026-01-12T22:44:33-06:00" level=debug msg="app state loaded" Jan 12 22:44:33 volumio go-librespot[7481]: time="2026-01-12T22:44:33-06:00" level=debug msg="stored credentials not found" Jan 12 22:44:33 volumio go-librespot[7481]: time="2026-01-12T22:44:33-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 12 22:44:34 volumio volumio[7078]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Jan 12 22:44:34 volumio volumio[7078]: info: VolumeController:: Volume=100 Mute =false Jan 12 22:44:34 volumio volumio[7078]: info: CoreStateMachine::pushState Jan 12 22:44:34 volumio volumio[7078]: info: CorePlayQueue::getTrack 0 Jan 12 22:44:34 volumio volumio[7078]: info: CoreCommandRouter::volumioPushState Jan 12 22:44:34 volumio volumio[7078]: info: [squeezelite_mc] Server discovery started Jan 12 22:44:34 volumio volumio[7078]: info: [squeezelite_mc] Player finder started Jan 12 22:44:34 volumio volumio[7078]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:44:34 volumio volumio[7078]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:44:34 volumio volumio[7078]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:44:34 volumio volumio[7078]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 12 22:44:34 volumio volumio[7078]: info: [squeezelite_mc] Executing aplay -D hw:1 --nonblock -f MPEG /dev/zero 2>&1 || true Jan 12 22:44:34 volumio volumio[7078]: info: Volumio called home Jan 12 22:44:34 volumio volumio[7078]: info: [squeezelite_mc] Card 1 supports the following ALSA formats: ["U8","S16_LE"] Jan 12 22:44:34 volumio volumio[7078]: info: [squeezelite_mc] Starting Squeezelite service with params: {"type":"basic","playerName":"volumio","dsdFormat":null,"card":"1","mixerType":"Hardware","mixer":"PCM"} Jan 12 22:44:34 volumio volumio[7078]: info: [squeezelite_mc] Executing cp /data/plugins/music_service/squeezelite_mc/dist/lib/../templates/alsa/100-squeezelite.conf.template.out /etc/alsa/conf.d/100-squeezelite.conf Jan 12 22:44:34 volumio volumio[7078]: info: Starting Shairport Sync Jan 12 22:44:34 volumio volumio[7078]: info: Starting Shairport Sync Jan 12 22:44:34 volumio volumio[7078]: info: Starting Shairport Sync Jan 12 22:44:34 volumio sudo[7494]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 12 22:44:34 volumio sudo[7494]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 22:44:34 volumio go-librespot[7481]: time="2026-01-12T22:44:34-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 12 22:44:34 volumio go-librespot[7481]: time="2026-01-12T22:44:34-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 12 22:44:34 volumio go-librespot[7481]: time="2026-01-12T22:44:34-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 12 22:44:34 volumio go-librespot[7481]: time="2026-01-12T22:44:34-06:00" level=info msg="zeroconf server listening on port 35591" Jan 12 22:44:34 volumio sudo[7496]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 12 22:44:34 volumio sudo[7496]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 22:44:34 volumio sudo[7498]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 12 22:44:34 volumio sudo[7498]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 22:44:34 volumio sudo[7492]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/cp /data/plugins/music_service/squeezelite_mc/dist/lib/../templates/alsa/100-squeezelite.conf.template.out /etc/alsa/conf.d/100-squeezelite.conf Jan 12 22:44:34 volumio sudo[7492]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 22:44:34 volumio sudo[7492]: pam_unix(sudo:session): session closed for user root Jan 12 22:44:34 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jan 12 22:44:34 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Jan 12 22:44:34 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 12 22:44:34 volumio systemd[1]: shairport-sync.service: Consumed 2.012s CPU time. Jan 12 22:44:34 volumio go-librespot[7481]: time="2026-01-12T22:44:34-06:00" level=debug msg="obtained new client token: AAAAgudl4pVEsYNYeZrPz1/iv8PG2w1H/EZiehxRHUIvZsQ+KWK7wl2QpbuiJFbF/WyiufQs+x8uB0Xx+8MOV/Z/0K0ktSqVHbyWd49fxSB2ySNFSWnVj5Cjet2kfOVTFlen5z4oPFpgm1cz1YEoP5lOVIu0eNRc10v/wHHXz8BGe6Ng4T42Qf8nBqEyeg59tOMLg92dUhIzbUuyOlse+1bhHMQNEdHO/ax0L2ubuOmcXT9bg1NoT2WM9g==" Jan 12 22:44:34 volumio volumio[7078]: info: Asound.conf file unchanged, so no further update is needed Jan 12 22:44:34 volumio volumio[7078]: info: Output device has changed, restarting MPD Jan 12 22:44:34 volumio go-librespot[7481]: time="2026-01-12T22:44:34-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 12 22:44:34 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 12 22:44:34 volumio sudo[7496]: pam_unix(sudo:session): session closed for user root Jan 12 22:44:34 volumio volumio[7078]: info: Output device has changed, restarting Shairport Sync Jan 12 22:44:34 volumio volumio[7078]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:44:34 volumio sudo[7498]: pam_unix(sudo:session): session closed for user root Jan 12 22:44:34 volumio sudo[7494]: pam_unix(sudo:session): session closed for user root Jan 12 22:44:34 volumio sudo[7506]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 12 22:44:34 volumio volumio[7078]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 12 22:44:34 volumio sudo[7506]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 22:44:34 volumio sudo[7506]: pam_unix(sudo:session): session closed for user root Jan 12 22:44:34 volumio go-librespot[7481]: time="2026-01-12T22:44:34-06:00" level=debug msg="completed keyexchange" Jan 12 22:44:34 volumio go-librespot[7481]: time="2026-01-12T22:44:34-06:00" level=debug msg="completed challenge" Jan 12 22:44:34 volumio volumio[7078]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 12 22:44:34 volumio sudo[7508]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 12 22:44:34 volumio sudo[7508]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 22:44:34 volumio go-librespot[7481]: time="2026-01-12T22:44:34-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Jan 12 22:44:34 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 12 22:44:34 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 12 22:44:34 volumio volumio[7078]: info: [squeezelite_mc] Executing alsactl -L -R nrestore Jan 12 22:44:34 volumio systemd[1]: mpd.service: Deactivated successfully. Jan 12 22:44:34 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Jan 12 22:44:34 volumio systemd[1]: mpd.service: Consumed 1.668s CPU time. Jan 12 22:44:34 volumio systemd[1]: mpd.socket: Deactivated successfully. Jan 12 22:44:34 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jan 12 22:44:34 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jan 12 22:44:34 volumio volumio[7078]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jan 12 22:44:34 volumio volumio[7078]: SPOTIFY: BQAUrZmjvDRSkuXSaSMgSt59Q0MMpuAV6uhlB6JGa3I07sXsTQ3960vL7qDq_0ZpVTDsTGBm01JnExBIdP9tWD4onz-FpGIeeObxWrvr1ydiNdiAHIXL68g8K0hd_6qJMTPkS3tsZc5gp4A1nQlVeMLZ0p2NaDzjZ1bXtHwm1WW0iKBLozaztmEJn3pIXssZLK3P28Kk1tqecipYIDrqlJCtu-gDHghE1jOR_xY Jan 12 22:44:34 volumio volumio[7078]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jan 12 22:44:34 volumio volumio[7078]: info: New Spotify access token = BQAUrZmjvDRSkuXSaSMgSt59Q0MMpuAV6uhlB6JGa3I07sXsTQ3960vL7qDq_0ZpVTDsTGBm01JnExBIdP9tWD4onz-FpGIeeObxWrvr1ydiNdiAHIXL68g8K0hd_6qJMTPkS3tsZc5gp4A1nQlVeMLZ0p2NaDzjZ1bXtHwm1WW0iKBLozaztmEJn3pIXssZLK3P28Kk1tqecipYIDrqlJCtu-gDHghE1jOR_xY Jan 12 22:44:34 volumio volumio[7078]: info: Spotify credentials grant success - running version from March 24, 2019 Jan 12 22:44:34 volumio sudo[7534]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/sbin/alsactl -L -R nrestore Jan 12 22:44:34 volumio sudo[7534]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 22:44:34 volumio sudo[7534]: pam_unix(sudo:session): session closed for user root Jan 12 22:44:34 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jan 12 22:44:34 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Jan 12 22:44:34 volumio volumio[7078]: info: MPD Permissions set Jan 12 22:44:34 volumio volumio[7078]: info: Shairport-Sync Started Jan 12 22:44:34 volumio volumio[7078]: Error adding Membership: Error: addMembership EINVAL Jan 12 22:44:34 volumio volumio[7078]: info: Shairport-Sync Started Jan 12 22:44:34 volumio volumio[7078]: info: Shairport-Sync Started Jan 12 22:44:34 volumio volumio[7078]: info: [squeezelite_mc] Executing cp /data/plugins/music_service/squeezelite_mc/dist/lib/../templates/systemd/squeezelite.service.template.out /etc/systemd/system/squeezelite.service Jan 12 22:44:35 volumio volumio[7078]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:44:35 volumio volumio[7078]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:44:35 volumio volumio[7078]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:44:35 volumio volumio[7078]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:44:35 volumio volumio[7078]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:44:35 volumio volumio[7078]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:44:35 volumio volumio[7078]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:44:35 volumio volumio[7078]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:44:35 volumio volumio[7078]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 12 22:44:35 volumio volumio[7078]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:44:35 volumio volumio[7078]: info: CoreCommandRouter::volumioGetState Jan 12 22:44:35 volumio volumio[7078]: info: CorePlayQueue::getTrack 0 Jan 12 22:44:35 volumio sudo[7540]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/cp /data/plugins/music_service/squeezelite_mc/dist/lib/../templates/systemd/squeezelite.service.template.out /etc/systemd/system/squeezelite.service Jan 12 22:44:35 volumio volumio[7078]: info: Starting Shairport Sync Jan 12 22:44:35 volumio sudo[7540]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 22:44:35 volumio sudo[7537]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jan 12 22:44:35 volumio sudo[7537]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Jan 12 22:44:35 volumio sudo[7540]: pam_unix(sudo:session): session closed for user root Jan 12 22:44:35 volumio sudo[7537]: pam_unix(sudo:session): session closed for user root Jan 12 22:44:35 volumio volumio[7078]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl daemon-reload || true Jan 12 22:44:35 volumio sudo[7549]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 12 22:44:35 volumio sudo[7549]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 22:44:35 volumio sudo[7553]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl daemon-reload Jan 12 22:44:35 volumio sudo[7553]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 22:44:35 volumio volumio[7078]: SPOTIFY: User informations: {"display_name":"Clint Smith","external_urls":{"spotify":"https://open.spotify.com/user/clintsmith1"},"followers":{"href":null,"total":7},"href":"https://api.spotify.com/v1/users/clintsmith1","id":"clintsmith1","images":[{"height":300,"url":"https://i.scdn.co/image/ab6775700000ee856520409d25d9cc210472a0fd","width":300},{"height":64,"url":"https://i.scdn.co/image/ab67757000003b826520409d25d9cc210472a0fd","width":64}],"type":"user","uri":"spotify:user:clintsmith1"} Jan 12 22:44:35 volumio volumio[7078]: info: Spotify Successfully logged in Jan 12 22:44:35 volumio volumio[7078]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 12 22:44:35 volumio volumio[7078]: info: [1768279475461] CoreMusicLibrary::Adding element Spotify Jan 12 22:44:35 volumio volumio[7078]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 12 22:44:35 volumio volumio[7078]: Cannot find translation for source Bandcamp Discover Jan 12 22:44:35 volumio volumio[7078]: Cannot find translation for source SoundCloud Jan 12 22:44:35 volumio volumio[7078]: Cannot find translation for source YouTube2 Jan 12 22:44:35 volumio volumio[7078]: Cannot find translation for source YouTube Music Jan 12 22:44:35 volumio volumio[7078]: Cannot find translation for source Podcast Jan 12 22:44:35 volumio volumio[7078]: Cannot find translation for source Volusonic Jan 12 22:44:35 volumio volumio[7078]: Cannot find translation for source Spotify Jan 12 22:44:35 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jan 12 22:44:35 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Jan 12 22:44:35 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 12 22:44:35 volumio systemd[1]: Reloading. Jan 12 22:44:36 volumio volumio[7078]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:44:36 volumio volumio[7078]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:44:36 volumio volumio[7078]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:44:36 volumio volumio[7078]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 12 22:44:37 volumio volumio[7078]: info: go-librespot daemon successfully initialized Jan 12 22:44:38 volumio systemd[1]: /lib/systemd/system/go-librespot-daemon.service:9: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Jan 12 22:44:38 volumio systemd[1]: /lib/systemd/system/go-librespot-daemon.service:10: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Jan 12 22:44:38 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.215.245 Jan 12 22:44:38 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Jan 12 22:44:38 volumio avahi-daemon[664]: Registering new address record for 169.254.215.245 on eth0.IPv4. Jan 12 22:44:38 volumio volumio[7078]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 12 22:44:38 volumio volumio[7078]: Error: addMembership ENODEV Jan 12 22:44:38 volumio volumio[7078]: at Socket.addMembership (node:dgram:860:11) Jan 12 22:44:38 volumio volumio[7078]: at addMembership (/volumio/node_modules/node-ssdp/lib/index.js:264:16) { Jan 12 22:44:38 volumio volumio[7078]: errno: -19, Jan 12 22:44:38 volumio volumio[7078]: code: 'ENODEV', Jan 12 22:44:38 volumio volumio[7078]: syscall: 'addMembership' Jan 12 22:44:38 volumio volumio[7078]: } Jan 12 22:44:38 volumio volumio[7078]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 12 22:44:38 volumio sudo[7553]: pam_unix(sudo:session): session closed for user root Jan 12 22:44:38 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 9. Jan 12 22:44:38 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 12 22:44:38 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 12 22:44:38 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 12 22:44:38 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 12 22:44:38 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 12 22:44:38 volumio go-librespot[7613]: go-librespot daemon starting... Jan 12 22:44:38 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 12 22:44:38 volumio sudo[7549]: pam_unix(sudo:session): session closed for user root Jan 12 22:44:38 volumio go-librespot[7615]: time="2026-01-12T22:44:38-06:00" level=info msg="running go-librespot 0.4.0" Jan 12 22:44:38 volumio go-librespot[7615]: time="2026-01-12T22:44:38-06:00" level=debug msg="app state loaded" Jan 12 22:44:38 volumio go-librespot[7615]: time="2026-01-12T22:44:38-06:00" level=debug msg="stored credentials not found" Jan 12 22:44:38 volumio go-librespot[7615]: time="2026-01-12T22:44:38-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 12 22:44:39 volumio go-librespot[7615]: time="2026-01-12T22:44:39-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Jan 12 22:44:39 volumio go-librespot[7615]: time="2026-01-12T22:44:39-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Jan 12 22:44:39 volumio go-librespot[7615]: time="2026-01-12T22:44:39-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Jan 12 22:44:39 volumio go-librespot[7615]: time="2026-01-12T22:44:39-06:00" level=info msg="zeroconf server listening on port 34279" Jan 12 22:44:39 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.215.245 Jan 12 22:44:39 volumio go-librespot[7615]: time="2026-01-12T22:44:39-06:00" level=debug msg="obtained new client token: AACUWLGHhH8NfOJi/Ob51cmSz02/xuaOv1ym/HV3ynJOX4WsfhiCG1D4nVkrUklZzumDtvPLqg1Bvw+WntdRZEovXp3INYO4hUNOlwCiR8RxADKlyccFEMq8LV+7AAJQgCJi0Tf/li/4vbx8ta5eN5ptvH3/cLTvO848TuHG83SaiKRmYkHDurQxaQjNPVrfcruJSHBNxfUb9krP50jrALAfTHm0frELAk2U3eKZOBt8VPb58rt6YDhHWw==" Jan 12 22:44:39 volumio go-librespot[7615]: time="2026-01-12T22:44:39-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 12 22:44:39 volumio go-librespot[7615]: time="2026-01-12T22:44:39-06:00" level=debug msg="completed keyexchange" Jan 12 22:44:39 volumio go-librespot[7615]: time="2026-01-12T22:44:39-06:00" level=debug msg="completed challenge" Jan 12 22:44:39 volumio go-librespot[7615]: time="2026-01-12T22:44:39-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Jan 12 22:44:39 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 12 22:44:39 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 12 22:44:39 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.215.245 Jan 12 22:44:39 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.215.245 Jan 12 22:44:39 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Jan 12 22:44:39 volumio avahi-daemon[664]: Withdrawing address record for 169.254.215.245 on eth0. Jan 12 22:44:39 volumio sudo[7640]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-01-12 22:43' Jan 12 22:44:39 volumio sudo[7640]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 22:44:39 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Jan 12 22:44:39 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 12 22:44:39 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 12 22:44:39 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 12 22:44:40 volumio sudo[7640]: pam_unix(sudo:session): session closed for user root Jan 12 22:44:40 volumio mpd[7550]: 2026-01-12T22:44:40 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jan 12 22:44:41 volumio systemd[1]: Started mpd.service - Music Player Daemon. Jan 12 22:44:41 volumio sudo[7508]: pam_unix(sudo:session): session closed for user root Jan 12 22:44:41 volumio sudo[7406]: pam_unix(sudo:session): session closed for user root Jan 12 22:44:41 volumio sudo[7416]: pam_unix(sudo:session): session closed for user root Jan 12 22:44:41 volumio volumio-remote-updater[14193]: [2026-01-12 22:44:41] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Jan 12 22:44:41 volumio volumio-remote-updater[14193]: [2026-01-12 22:44:41] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Jan 12 22:44:41 volumio systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Jan 12 22:44:41 volumio systemd[1]: volumio.service: Failed with result 'exit-code'. Jan 12 22:44:41 volumio systemd[1]: volumio.service: Consumed 41.955s CPU time. Jan 12 22:44:41 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Jan 12 22:44:41 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 22083. Jan 12 22:44:41 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Jan 12 22:44:41 volumio systemd[1]: Stopped volumio.service - Volumio Backend Module. Jan 12 22:44:41 volumio systemd[1]: volumio.service: Consumed 41.955s CPU time. Jan 12 22:44:41 volumio systemd[1]: Started volumio.service - Volumio Backend Module. Jan 12 22:44:42 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 10. Jan 12 22:44:42 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 12 22:44:42 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 12 22:44:42 volumio go-librespot[7682]: go-librespot daemon starting... Jan 12 22:44:42 volumio go-librespot[7683]: time="2026-01-12T22:44:42-06:00" level=info msg="running go-librespot 0.4.0" Jan 12 22:44:42 volumio go-librespot[7683]: time="2026-01-12T22:44:42-06:00" level=debug msg="app state loaded" Jan 12 22:44:42 volumio go-librespot[7683]: time="2026-01-12T22:44:42-06:00" level=debug msg="stored credentials not found" Jan 12 22:44:42 volumio go-librespot[7683]: time="2026-01-12T22:44:42-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 12 22:44:43 volumio go-librespot[7683]: time="2026-01-12T22:44:43-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 12 22:44:43 volumio go-librespot[7683]: time="2026-01-12T22:44:43-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 12 22:44:43 volumio go-librespot[7683]: time="2026-01-12T22:44:43-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 12 22:44:43 volumio go-librespot[7683]: time="2026-01-12T22:44:43-06:00" level=info msg="zeroconf server listening on port 39031" Jan 12 22:44:43 volumio go-librespot[7683]: time="2026-01-12T22:44:43-06:00" level=debug msg="obtained new client token: AACsKIiwT5cbIGiXzxnjCdst7lOf12cixfCqMJlbVR2vkuYW04zn6vobC1RlBHgao97T15MVZC5r4K7/fjdD6rSA07M4G9RQ/4ZbSN/y7KUQH/5wmyvr+TrO3+4K1NAO68fiRHA/FnmtyiNWWm6BybONl7pXbVYQIA4DW7BTDnTNYRErdLoIpdfoTqwQ4Sm3ZvZv7Mr4FuGEdBs+7IGxiHOtSUNjv0Nasf4ikE3YuL7hgrXgPm0BrsM=" Jan 12 22:44:43 volumio go-librespot[7683]: time="2026-01-12T22:44:43-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 12 22:44:43 volumio go-librespot[7683]: time="2026-01-12T22:44:43-06:00" level=debug msg="completed keyexchange" Jan 12 22:44:43 volumio go-librespot[7683]: time="2026-01-12T22:44:43-06:00" level=debug msg="completed challenge" Jan 12 22:44:43 volumio go-librespot[7683]: time="2026-01-12T22:44:43-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Jan 12 22:44:43 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 12 22:44:43 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 12 22:44:44 volumio volumio[7672]: info: ------------------------------------------- Jan 12 22:44:44 volumio volumio[7672]: info: ----- Volumio3 ---- Jan 12 22:44:44 volumio volumio[7672]: info: ------------------------------------------- Jan 12 22:44:44 volumio volumio[7672]: info: ----- System startup ---- Jan 12 22:44:44 volumio volumio[7672]: info: ------------------------------------------- Jan 12 22:44:44 volumio volumio[7672]: info: MYVOLUMIO Environment detected Jan 12 22:44:45 volumio volumio[7672]: info: Plugin folders cleanup Jan 12 22:44:45 volumio volumio[7672]: info: Scanning into folder /volumio/app/plugins/ Jan 12 22:44:45 volumio volumio[7672]: info: Scanning category audio_interface Jan 12 22:44:45 volumio volumio[7672]: info: Scanning category miscellanea Jan 12 22:44:45 volumio volumio[7672]: info: Scanning category music_service Jan 12 22:44:45 volumio volumio[7672]: info: Scanning category plugins.json Jan 12 22:44:45 volumio volumio[7672]: info: Scanning category system_controller Jan 12 22:44:45 volumio volumio[7672]: info: Scanning category user_interface Jan 12 22:44:45 volumio volumio[7672]: info: Scanning into folder /data/plugins/ Jan 12 22:44:45 volumio volumio[7672]: info: Scanning category audio_interface Jan 12 22:44:45 volumio volumio[7672]: info: Scanning category music_service Jan 12 22:44:45 volumio volumio[7672]: info: Scanning category system_controller Jan 12 22:44:45 volumio volumio[7672]: info: Scanning category system_hardware Jan 12 22:44:45 volumio volumio[7672]: info: Scanning category user_interface Jan 12 22:44:45 volumio volumio[7672]: info: Plugin folders cleanup completed Jan 12 22:44:45 volumio volumio[7672]: info: ------------------------------------------- Jan 12 22:44:45 volumio volumio[7672]: info: ----- Core plugins startup ---- Jan 12 22:44:45 volumio volumio[7672]: info: ------------------------------------------- Jan 12 22:44:45 volumio volumio[7672]: info: Loading plugins from folder /volumio/app/plugins/ Jan 12 22:44:45 volumio volumio[7672]: info: Adding plugin upnp to MyMusic Plugins Jan 12 22:44:45 volumio volumio[7672]: info: Adding plugin airplay_emulation to MyMusic Plugins Jan 12 22:44:45 volumio volumio[7672]: info: Adding plugin upnp_browser to MyMusic Plugins Jan 12 22:44:45 volumio volumio[7672]: info: Loading plugins from folder /data/plugins/ Jan 12 22:44:45 volumio volumio[7672]: info: Loading plugin "system"... Jan 12 22:44:45 volumio volumio[7672]: info: Loading plugin "appearance"... Jan 12 22:44:45 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.104.170 Jan 12 22:44:45 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Jan 12 22:44:45 volumio avahi-daemon[664]: Registering new address record for 169.254.104.170 on eth0.IPv4. Jan 12 22:44:45 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 12 22:44:45 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 12 22:44:45 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 12 22:44:45 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.104.170 Jan 12 22:44:46 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.104.170 Jan 12 22:44:46 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.104.170 Jan 12 22:44:46 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Jan 12 22:44:46 volumio avahi-daemon[664]: Withdrawing address record for 169.254.104.170 on eth0. Jan 12 22:44:46 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 12 22:44:46 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 12 22:44:46 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 12 22:44:46 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Jan 12 22:44:46 volumio volumio[7672]: info: Loading plugin "network"... Jan 12 22:44:46 volumio volumio[7672]: info: Refreshing Cached IP Addresses Jan 12 22:44:46 volumio sudo[7735]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 12 22:44:46 volumio sudo[7735]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 22:44:46 volumio volumio[7672]: info: Loading plugin "services"... Jan 12 22:44:46 volumio sudo[7735]: pam_unix(sudo:session): session closed for user root Jan 12 22:44:46 volumio sudo[7737]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 12 22:44:46 volumio sudo[7737]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 22:44:46 volumio volumio[7672]: info: Loading plugin "alsa_controller"... Jan 12 22:44:46 volumio sudo[7737]: pam_unix(sudo:session): session closed for user root Jan 12 22:44:46 volumio sudo[7749]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Jan 12 22:44:46 volumio sudo[7749]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 22:44:46 volumio volumio[7672]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 12 22:44:46 volumio volumio[7672]: info: Loading plugin "wizard"... Jan 12 22:44:46 volumio volumio[7672]: info: Loading plugin "networkfs"... Jan 12 22:44:46 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 11. Jan 12 22:44:46 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 12 22:44:46 volumio volumio[7672]: info: Starting Udev Watcher for removable devices Jan 12 22:44:46 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 12 22:44:46 volumio go-librespot[7769]: go-librespot daemon starting... Jan 12 22:44:46 volumio volumio-remote-updater[14193]: [2026-01-12 22:44:46] [connect] Successful connection Jan 12 22:44:46 volumio go-librespot[7770]: time="2026-01-12T22:44:46-06:00" level=info msg="running go-librespot 0.4.0" Jan 12 22:44:46 volumio go-librespot[7770]: time="2026-01-12T22:44:46-06:00" level=debug msg="app state loaded" Jan 12 22:44:46 volumio go-librespot[7770]: time="2026-01-12T22:44:46-06:00" level=debug msg="stored credentials not found" Jan 12 22:44:46 volumio go-librespot[7770]: time="2026-01-12T22:44:46-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 12 22:44:46 volumio volumio[7672]: info: Ignoring mount for partition: boot Jan 12 22:44:46 volumio volumio[7672]: info: Ignoring mount for partition: volumio Jan 12 22:44:46 volumio volumio[7672]: info: Ignoring mount for partition: volumio_data Jan 12 22:44:46 volumio volumio[7672]: info: Mounting Device Wikipedia Jan 12 22:44:46 volumio sudo[7782]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mount /dev/sda1 /mnt/USB/Wikipedia -o noatime Jan 12 22:44:46 volumio sudo[7782]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 22:44:46 volumio sudo[7782]: pam_unix(sudo:session): session closed for user root Jan 12 22:44:46 volumio volumio[7672]: mount: /media/Wikipedia: /dev/sda1 already mounted on /media/Wikipedia. Jan 12 22:44:46 volumio volumio[7672]: dmesg(1) may have more information after failed mount system call. Jan 12 22:44:46 volumio volumio[7672]: error: Failed to mount Wikipedia: Error: Command failed: /usr/bin/sudo /bin/mount "/dev/sda1" "/mnt/USB/Wikipedia" -o noatime Jan 12 22:44:46 volumio volumio[7672]: mount: /media/Wikipedia: /dev/sda1 already mounted on /media/Wikipedia. Jan 12 22:44:46 volumio volumio[7672]: dmesg(1) may have more information after failed mount system call. Jan 12 22:44:46 volumio volumio[7672]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 12 22:44:46 volumio volumio[7672]: info: Loading plugin "volumio_command_line_client"... Jan 12 22:44:46 volumio volumio[7672]: info: Loading plugin "upnp"... Jan 12 22:44:46 volumio volumio[7672]: info: [1768279486751] Starting Upmpd Daemon Jan 12 22:44:46 volumio volumio[7672]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 12 22:44:46 volumio volumio[7672]: info: Loading plugin "my_music"... Jan 12 22:44:46 volumio volumio[7672]: info: Loading plugin "mpd"... Jan 12 22:44:46 volumio sudo[7749]: pam_unix(sudo:session): session closed for user root Jan 12 22:44:47 volumio go-librespot[7770]: time="2026-01-12T22:44:47-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 12 22:44:47 volumio go-librespot[7770]: time="2026-01-12T22:44:47-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 12 22:44:47 volumio go-librespot[7770]: time="2026-01-12T22:44:47-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 12 22:44:47 volumio go-librespot[7770]: time="2026-01-12T22:44:47-06:00" level=info msg="zeroconf server listening on port 46173" Jan 12 22:44:47 volumio go-librespot[7770]: time="2026-01-12T22:44:47-06:00" level=debug msg="obtained new client token: AAAi72kJUtnBFgpfXOdNsy5Vq6IUA6S139QKwJo/7pRSOO12bgiadbyDv2+3ueqde6OeAOcZm8zA03A7ajHY+M8hJMalvcpNQ7wYzRQXW/cHoHm2WSNBJ3mXnloSLA1IhuW4Hemtnvu/QP9LRc16kx8lMQggqT32i3Z28lELJiJV1EYR1uOp/yId7O81VgPnIoTos3J7Gyr+phYxs+AtBDz14EPpHqu7+TtwlhrtjUEINF9qwNQLDC4=" Jan 12 22:44:47 volumio go-librespot[7770]: time="2026-01-12T22:44:47-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 12 22:44:47 volumio go-librespot[7770]: time="2026-01-12T22:44:47-06:00" level=debug msg="completed keyexchange" Jan 12 22:44:47 volumio go-librespot[7770]: time="2026-01-12T22:44:47-06:00" level=debug msg="completed challenge" Jan 12 22:44:47 volumio go-librespot[7770]: time="2026-01-12T22:44:47-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Jan 12 22:44:47 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 12 22:44:47 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 12 22:44:47 volumio volumio[7672]: info: Loading plugin "upnp_browser"... Jan 12 22:44:50 volumio volumio[7672]: info: Loading plugin "alarm-clock"... Jan 12 22:44:50 volumio volumio[7672]: info: Loading plugin "airplay_emulation"... Jan 12 22:44:50 volumio volumio[7672]: info: Starting Shairport Sync Jan 12 22:44:50 volumio volumio[7672]: info: Loading plugin "last_100"... Jan 12 22:44:50 volumio volumio[7672]: info: Loading plugin "webradio"... Jan 12 22:44:50 volumio volumio[7672]: info: Loading plugin "i2s_dacs"... Jan 12 22:44:50 volumio volumio[7672]: info: I2S DAC not set, start Auto-detection Jan 12 22:44:50 volumio volumio[7672]: info: Loading plugin "volumiodiscovery"... Jan 12 22:44:50 volumio volumio[7672]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jan 12 22:44:50 volumio volumio[7672]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 12 22:44:50 volumio volumio[7672]: *** WARNING *** For more information see Jan 12 22:44:50 volumio volumio[7672]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jan 12 22:44:50 volumio volumio[7672]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 12 22:44:50 volumio volumio[7672]: *** WARNING *** For more information see Jan 12 22:44:50 volumio node[7672]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jan 12 22:44:50 volumio node[7672]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 12 22:44:50 volumio node[7672]: *** WARNING *** For more information see Jan 12 22:44:50 volumio node[7672]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jan 12 22:44:50 volumio node[7672]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 12 22:44:50 volumio node[7672]: *** WARNING *** For more information see Jan 12 22:44:50 volumio volumio[7672]: info: Applying required configuration parameters for plugin volumiodiscovery Jan 12 22:44:50 volumio volumio[7672]: info: Discovery: Started advertising with name: Volumio Jan 12 22:44:50 volumio volumio[7672]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 12 22:44:50 volumio volumio[7672]: info: Loading plugin "bandcamp"... Jan 12 22:44:50 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 12. Jan 12 22:44:50 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 12 22:44:50 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 12 22:44:50 volumio go-librespot[7790]: go-librespot daemon starting... Jan 12 22:44:50 volumio go-librespot[7791]: time="2026-01-12T22:44:50-06:00" level=info msg="running go-librespot 0.4.0" Jan 12 22:44:50 volumio go-librespot[7791]: time="2026-01-12T22:44:50-06:00" level=debug msg="app state loaded" Jan 12 22:44:50 volumio go-librespot[7791]: time="2026-01-12T22:44:50-06:00" level=debug msg="stored credentials not found" Jan 12 22:44:50 volumio go-librespot[7791]: time="2026-01-12T22:44:50-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 12 22:44:50 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.227.117 Jan 12 22:44:50 volumio avahi-daemon[664]: Registering new address record for 169.254.227.117 on eth0.IPv4. Jan 12 22:44:50 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Jan 12 22:44:50 volumio go-librespot[7791]: time="2026-01-12T22:44:50-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 12 22:44:50 volumio go-librespot[7791]: time="2026-01-12T22:44:50-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 12 22:44:50 volumio go-librespot[7791]: time="2026-01-12T22:44:50-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 12 22:44:50 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 12 22:44:50 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 12 22:44:50 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 12 22:44:50 volumio go-librespot[7791]: time="2026-01-12T22:44:50-06:00" level=info msg="zeroconf server listening on port 34097" Jan 12 22:44:50 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.227.117 Jan 12 22:44:50 volumio go-librespot[7791]: time="2026-01-12T22:44:50-06:00" level=debug msg="obtained new client token: AAAE6OGgbyzyzmacji41A7AwBv5TitoqJqzBSechwSViWI2tOcu2qZKLV+gXv6EBZKf6Ra9GbVaGwKMeyy7i5g7btPowB+UnKu6oDvjPiQ4Tb4PuVMeBmOuqxfs6znT6aMT3e96WthE1J1Q+V8Fqdt0m57KyLGw6lCgbTfQu7bkw2DxfWYZC8/aFP1FSd8vGX+/bbB4FvX5d4WZaPGFG3aQK/7ECik+vBcST22sR8eLFf7Y6naDnZoLEzw==" Jan 12 22:44:51 volumio go-librespot[7791]: time="2026-01-12T22:44:51-06:00" level=warning msg="failed to connect to AP ap-guc3.spotify.com:4070, retrying with a different AP" error="dial tcp 104.154.127.247:4070: connect: connection refused" Jan 12 22:44:51 volumio go-librespot[7791]: time="2026-01-12T22:44:51-06:00" level=debug msg="connected to ap-guc3.spotify.com:443" Jan 12 22:44:51 volumio go-librespot[7791]: time="2026-01-12T22:44:51-06:00" level=debug msg="completed keyexchange" Jan 12 22:44:51 volumio go-librespot[7791]: time="2026-01-12T22:44:51-06:00" level=debug msg="completed challenge" Jan 12 22:44:51 volumio go-librespot[7791]: time="2026-01-12T22:44:51-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Jan 12 22:44:51 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 12 22:44:51 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 12 22:44:51 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.227.117 Jan 12 22:44:51 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.227.117 Jan 12 22:44:51 volumio avahi-daemon[664]: Withdrawing address record for 169.254.227.117 on eth0. Jan 12 22:44:51 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Jan 12 22:44:51 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 12 22:44:51 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 12 22:44:51 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 12 22:44:51 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Jan 12 22:44:51 volumio volumio[7672]: info: Plugin calmradio is not enabled Jan 12 22:44:51 volumio volumio[7672]: info: Loading plugin "soundcloud"... Jan 12 22:44:52 volumio volumio[7672]: info: Loading plugin "spop"... Jan 12 22:44:52 volumio kernel: hwmon hwmon1: Voltage normalised Jan 12 22:44:53 volumio volumio[7672]: info: Loading plugin "squeezelite_mc"... Jan 12 22:44:53 volumio volumio[7672]: info: Loading plugin "youtube2"... Jan 12 22:44:54 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 13. Jan 12 22:44:54 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 12 22:44:54 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 12 22:44:54 volumio go-librespot[7831]: go-librespot daemon starting... Jan 12 22:44:54 volumio volumio[7672]: info: Loading plugin "ytcr"... Jan 12 22:44:54 volumio go-librespot[7832]: time="2026-01-12T22:44:54-06:00" level=info msg="running go-librespot 0.4.0" Jan 12 22:44:54 volumio go-librespot[7832]: time="2026-01-12T22:44:54-06:00" level=debug msg="app state loaded" Jan 12 22:44:54 volumio go-librespot[7832]: time="2026-01-12T22:44:54-06:00" level=debug msg="stored credentials not found" Jan 12 22:44:54 volumio go-librespot[7832]: time="2026-01-12T22:44:54-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 12 22:44:54 volumio kernel: hwmon hwmon1: Undervoltage detected! Jan 12 22:44:55 volumio go-librespot[7832]: time="2026-01-12T22:44:55-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 12 22:44:55 volumio go-librespot[7832]: time="2026-01-12T22:44:55-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 12 22:44:55 volumio go-librespot[7832]: time="2026-01-12T22:44:55-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 12 22:44:55 volumio go-librespot[7832]: time="2026-01-12T22:44:55-06:00" level=info msg="zeroconf server listening on port 37029" Jan 12 22:44:55 volumio go-librespot[7832]: time="2026-01-12T22:44:55-06:00" level=debug msg="obtained new client token: AABpas/n/0o0cpwlOq4+STV6P7OqPBr7ikFb+uK4sWB6yM1ERPY2ErDtjFBmiMzpDND9luErSDNeu5UniODBcHF7pt3LRaQ71I2pEsSCJtwqtYXUN0dMhMrQrGn3sj7/C7/g1muspCkT+m51fBRn+y/Pwf3CvLUdSumBIrNF3UF3r9ZXCDRNTrGQD+YqlspfUaxW0uUDLI24w394cfZzqM3H3QE/y2I45aKqj2jx7Kf/yW4y1w/twQQ=" Jan 12 22:44:55 volumio go-librespot[7832]: time="2026-01-12T22:44:55-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 12 22:44:55 volumio go-librespot[7832]: time="2026-01-12T22:44:55-06:00" level=debug msg="completed keyexchange" Jan 12 22:44:55 volumio go-librespot[7832]: time="2026-01-12T22:44:55-06:00" level=debug msg="completed challenge" Jan 12 22:44:55 volumio go-librespot[7832]: time="2026-01-12T22:44:55-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Jan 12 22:44:55 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 12 22:44:55 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 12 22:44:56 volumio volumio[7672]: info: Loading plugin "ytmusic"... Jan 12 22:44:56 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.175.163 Jan 12 22:44:56 volumio avahi-daemon[664]: Registering new address record for 169.254.175.163 on eth0.IPv4. Jan 12 22:44:56 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Jan 12 22:44:57 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 12 22:44:57 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 12 22:44:57 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 12 22:44:57 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.175.163 Jan 12 22:44:57 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.175.163 Jan 12 22:44:57 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.175.163 Jan 12 22:44:57 volumio avahi-daemon[664]: Withdrawing address record for 169.254.175.163 on eth0. Jan 12 22:44:57 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Jan 12 22:44:57 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Jan 12 22:44:57 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 12 22:44:57 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 12 22:44:57 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 12 22:44:57 volumio volumio[7672]: info: Plugin now_playing is not enabled Jan 12 22:44:57 volumio volumio[7672]: info: Loading plugin "outputs"... Jan 12 22:44:57 volumio volumio[7672]: info: Loading plugin "albumart"... Jan 12 22:44:57 volumio volumio[7672]: info: Plugin example_plugin is not enabled Jan 12 22:44:57 volumio volumio[7672]: info: Loading plugin "inputs"... Jan 12 22:44:57 volumio volumio[7672]: info: Loading plugin "updater_comm"... Jan 12 22:44:57 volumio volumio[7672]: info: Plugin mpdemulation is not enabled Jan 12 22:44:57 volumio volumio[7672]: info: Loading plugin "rest_api"... Jan 12 22:44:57 volumio volumio[7672]: info: Loading plugin "websocket"... Jan 12 22:44:57 volumio volumio[7672]: info: Starting Socket.io Server version 1.7.4 Jan 12 22:44:57 volumio volumio[7672]: info: Plugin fusiondsp is not enabled Jan 12 22:44:57 volumio volumio[7672]: info: Plugin mpdoutput is not enabled Jan 12 22:44:57 volumio volumio[7672]: info: Plugin RoonBridge is not enabled Jan 12 22:44:57 volumio volumio[7672]: info: Loading plugin "podcast"... Jan 12 22:44:58 volumio volumio[7672]: info: ControllerPodcast::constructor Jan 12 22:44:58 volumio volumio[7672]: info: Loading plugin "volusonic"... Jan 12 22:44:58 volumio volumio[7885]: Forking 3 albumart workers Jan 12 22:44:58 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 14. Jan 12 22:44:58 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 12 22:44:58 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 12 22:44:58 volumio go-librespot[7922]: go-librespot daemon starting... Jan 12 22:44:58 volumio go-librespot[7926]: time="2026-01-12T22:44:58-06:00" level=info msg="running go-librespot 0.4.0" Jan 12 22:44:58 volumio go-librespot[7926]: time="2026-01-12T22:44:58-06:00" level=debug msg="app state loaded" Jan 12 22:44:58 volumio go-librespot[7926]: time="2026-01-12T22:44:58-06:00" level=debug msg="stored credentials not found" Jan 12 22:44:58 volumio go-librespot[7926]: time="2026-01-12T22:44:58-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 12 22:44:58 volumio go-librespot[7926]: time="2026-01-12T22:44:58-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 12 22:44:58 volumio go-librespot[7926]: time="2026-01-12T22:44:58-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 12 22:44:58 volumio go-librespot[7926]: time="2026-01-12T22:44:58-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 12 22:44:58 volumio go-librespot[7926]: time="2026-01-12T22:44:58-06:00" level=info msg="zeroconf server listening on port 43971" Jan 12 22:44:59 volumio volumio-remote-updater[14193]: [2026-01-12 22:44:59] [connect] Successful connection Jan 12 22:44:59 volumio go-librespot[7926]: time="2026-01-12T22:44:59-06:00" level=debug msg="obtained new client token: AACzrOjPH3oomxL1VX4BX1JnhJWK8TGwgnnCkOI39DMwYPG/IhMFxB0AXBuULU9bZ2jVc8LLDcF94Byxy9YqW4HbZG72ho7rxQU5z3bM7tBsARiPzWl9C4A/toU9MquCueqhyx288uCEToUeaJR+uOCfHneeJ5PPiPVH/Aq0mclHvujK1KQW7BbTu3bcrx5Nyh4DoLPYfOuuvYQc8d3uf4wk3OvS2j788jG0pKVgb/bsaHsJCeP8fjY=" Jan 12 22:44:59 volumio go-librespot[7926]: time="2026-01-12T22:44:59-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 12 22:44:59 volumio go-librespot[7926]: time="2026-01-12T22:44:59-06:00" level=debug msg="completed keyexchange" Jan 12 22:44:59 volumio go-librespot[7926]: time="2026-01-12T22:44:59-06:00" level=debug msg="completed challenge" Jan 12 22:44:59 volumio go-librespot[7926]: time="2026-01-12T22:44:59-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Jan 12 22:44:59 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 12 22:44:59 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 12 22:45:00 volumio volumio[7672]: info: Applying required configuration parameters for plugin volusonic Jan 12 22:45:00 volumio volumio[7672]: info: Loading plugin "backup_restore"... Jan 12 22:45:00 volumio volumio[7896]: Starting albumart workers Jan 12 22:45:00 volumio volumio[7897]: Starting albumart workers Jan 12 22:45:00 volumio volumio[7895]: Starting albumart workers Jan 12 22:45:00 volumio volumio[7672]: info: Applying required configuration parameters for plugin backup_restore Jan 12 22:45:00 volumio volumio[7672]: info: Plugin rpi_eeprom_config is not enabled Jan 12 22:45:00 volumio volumio[7672]: info: Plugin rpi_eeprom_updater is not enabled Jan 12 22:45:00 volumio volumio[7672]: info: Loading plugin "scheduledrestart"... Jan 12 22:45:01 volumio volumio[7672]: info: Applying required configuration parameters for plugin scheduledrestart Jan 12 22:45:01 volumio volumio[7672]: info: Plugin Bluetoothremote is not enabled Jan 12 22:45:01 volumio volumio[7672]: info: Plugin music_services_shield is not enabled Jan 12 22:45:01 volumio volumio[7672]: info: Loading plugin "Systeminfo"... Jan 12 22:45:01 volumio volumio[7672]: info: Plugin peppymeterbasic is not enabled Jan 12 22:45:01 volumio volumio[7672]: info: Loading plugin "peppyspectrum"... Jan 12 22:45:02 volumio volumio[7672]: info: Loading i18n strings for locale en Jan 12 22:45:02 volumio volumio[7672]: info: Plugin peppyspectrum has duplicated i18n key SAVE. It is ignored. Jan 12 22:45:02 volumio volumio[7672]: Updating browse sources language Jan 12 22:45:02 volumio volumio[7672]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 12 22:45:02 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.1.184 Jan 12 22:45:02 volumio avahi-daemon[664]: Registering new address record for 169.254.1.184 on eth0.IPv4. Jan 12 22:45:02 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Jan 12 22:45:02 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.1.184 Jan 12 22:45:02 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 15. Jan 12 22:45:02 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 12 22:45:02 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 12 22:45:02 volumio go-librespot[7968]: go-librespot daemon starting... Jan 12 22:45:02 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 12 22:45:02 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 12 22:45:02 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 12 22:45:02 volumio volumio[7672]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 12 22:45:02 volumio volumio[7672]: info: CoreCommandRouter::initPlayerControls Jan 12 22:45:02 volumio go-librespot[7969]: time="2026-01-12T22:45:02-06:00" level=info msg="running go-librespot 0.4.0" Jan 12 22:45:02 volumio go-librespot[7969]: time="2026-01-12T22:45:02-06:00" level=debug msg="app state loaded" Jan 12 22:45:02 volumio go-librespot[7969]: time="2026-01-12T22:45:02-06:00" level=debug msg="stored credentials not found" Jan 12 22:45:02 volumio volumio[7672]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:45:02 volumio volumio[7672]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:45:02 volumio volumio[7672]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:45:02 volumio volumio[7672]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:45:02 volumio go-librespot[7969]: time="2026-01-12T22:45:02-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 12 22:45:02 volumio volumio[7672]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:45:02 volumio volumio[7672]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:45:02 volumio volumio[7672]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:45:02 volumio volumio[7672]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:45:02 volumio volumio[7672]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 12 22:45:02 volumio volumio[7672]: Express server listening on port 3000 Jan 12 22:45:02 volumio volumio[7672]: [Metrics] WebUI: 18s 883.92ms Jan 12 22:45:02 volumio volumio[7672]: info: CoreStateMachine::resetVolumioState Jan 12 22:45:02 volumio volumio[7672]: info: CoreStateMachine::getcurrentVolume Jan 12 22:45:02 volumio volumio[7672]: info: CoreCommandRouter::volumioRetrievevolume Jan 12 22:45:02 volumio volumio[7672]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 12 22:45:02 volumio sudo[7982]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 12 22:45:02 volumio sudo[7982]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 22:45:02 volumio sudo[7984]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 12 22:45:02 volumio sudo[7984]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 22:45:02 volumio sudo[7982]: pam_unix(sudo:session): session closed for user root Jan 12 22:45:02 volumio sudo[7984]: pam_unix(sudo:session): session closed for user root Jan 12 22:45:02 volumio volumio[7672]: info: Volumio Network Manager: Network status updated: 1 Jan 12 22:45:03 volumio volumio[7672]: info: VolumeController:: Volume=100 Mute =false Jan 12 22:45:03 volumio volumio[7672]: info: CoreStateMachine::pushState Jan 12 22:45:03 volumio volumio[7672]: info: CorePlayQueue::getTrack 0 Jan 12 22:45:03 volumio volumio[7672]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 12 22:45:03 volumio volumio[7672]: info: CoreCommandRouter::volumioPushState Jan 12 22:45:03 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.1.184 Jan 12 22:45:03 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.1.184 Jan 12 22:45:03 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Jan 12 22:45:03 volumio avahi-daemon[664]: Withdrawing address record for 169.254.1.184 on eth0. Jan 12 22:45:03 volumio go-librespot[7969]: time="2026-01-12T22:45:03-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 12 22:45:03 volumio go-librespot[7969]: time="2026-01-12T22:45:03-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 12 22:45:03 volumio go-librespot[7969]: time="2026-01-12T22:45:03-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 12 22:45:03 volumio volumio[7672]: info: CoreStateMachine::updateTrackBlock Jan 12 22:45:03 volumio volumio[7672]: info: CorePlayQueue::getTrackBlock Jan 12 22:45:03 volumio volumio[7672]: info: CoreCommandRouter::volumioRetrievevolume Jan 12 22:45:03 volumio go-librespot[7969]: time="2026-01-12T22:45:03-06:00" level=info msg="zeroconf server listening on port 36107" Jan 12 22:45:03 volumio volumio-remote-updater[14193]: [2026-01-12 22:45:03] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1768279499 101 Jan 12 22:45:03 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Jan 12 22:45:03 volumio volumio[7672]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 3 Transport: websocket Total Clients: 1 Jan 12 22:45:03 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 12 22:45:03 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 12 22:45:03 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 12 22:45:03 volumio volumio[7672]: info: Reloading queue from file Jan 12 22:45:03 volumio volumio[7672]: info: CoreStateMachine::setRepeat null single undefined Jan 12 22:45:03 volumio volumio[7672]: info: CoreStateMachine::pushState Jan 12 22:45:03 volumio volumio[7672]: info: CorePlayQueue::getTrack 0 Jan 12 22:45:03 volumio volumio[7672]: info: CoreCommandRouter::volumioPushState Jan 12 22:45:03 volumio volumio[7672]: info: CoreStateMachine::setRandom null Jan 12 22:45:03 volumio volumio[7672]: info: CoreStateMachine::pushState Jan 12 22:45:03 volumio volumio[7672]: info: CorePlayQueue::getTrack 0 Jan 12 22:45:03 volumio volumio[7672]: info: CoreCommandRouter::volumioPushState Jan 12 22:45:03 volumio volumio[7672]: info: Setting Device type: Raspberry PI Jan 12 22:45:03 volumio volumio[7672]: info: VolumeController:: Volume=100 Mute =false Jan 12 22:45:03 volumio volumio[7672]: info: CoreStateMachine::pushState Jan 12 22:45:03 volumio volumio[7672]: info: CorePlayQueue::getTrack 0 Jan 12 22:45:03 volumio volumio[7672]: info: CoreCommandRouter::volumioPushState Jan 12 22:45:03 volumio go-librespot[7969]: time="2026-01-12T22:45:03-06:00" level=debug msg="obtained new client token: AAC0Hyr1bG1wJQvQZWbr3Jzx4zek4eYrvwV6+g7FPfV0GbyOzfslQuG31mCRxJA2KR2vpzHFIkMQMr2PcejFwkIDwCV2XWCaDcrL9lGyGRPjGGz/e2cCiTPqa4vwgJIQZa0Y5mgUuX9VyxO1ZZpu9SARVUZ4MS5DSP7TkgJLQ24rS6QMCJvVYbi4nU1RYUZF9LPZa0IgoVqIbCh60bZuvg50HJnUC80TtibBbIr/xOya6wfqKj2Zk6U=" Jan 12 22:45:03 volumio volumio[7672]: info: Completed loading Core Plugins Jan 12 22:45:03 volumio volumio[7672]: info: Preparing to generate the ALSA configuration file Jan 12 22:45:03 volumio sudo[8014]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Jan 12 22:45:03 volumio sudo[8014]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 22:45:03 volumio go-librespot[7969]: time="2026-01-12T22:45:03-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 12 22:45:03 volumio volumio[7672]: info: Discovery: adding a135e40e-a404-457b-98f5-36bf71c75954 Jan 12 22:45:03 volumio volumio[7672]: info: Discovery: Found device Volumio Jan 12 22:45:03 volumio volumio[7672]: info: CoreCommandRouter::volumioGetState Jan 12 22:45:03 volumio volumio[7672]: info: CorePlayQueue::getTrack 0 Jan 12 22:45:03 volumio volumio[7672]: info: Discovery: this is already registered, a135e40e-a404-457b-98f5-36bf71c75954 Jan 12 22:45:03 volumio volumio[7672]: info: Discovery: Found device Volumio Jan 12 22:45:03 volumio volumio[7672]: info: CoreCommandRouter::volumioGetState Jan 12 22:45:03 volumio volumio[7672]: info: CorePlayQueue::getTrack 0 Jan 12 22:45:03 volumio volumio[7672]: info: The plugin peppyspectrum has an ALSA contribution file peppy_in.peppy_out.6.conf Jan 12 22:45:03 volumio volumio[7672]: info: Reading ALSA contributions from plugins. Jan 12 22:45:03 volumio sudo[8014]: pam_unix(sudo:session): session closed for user root Jan 12 22:45:03 volumio volumio[7672]: info: Upmpdcli Daemon Started Jan 12 22:45:03 volumio volumio[7672]: info: Asound.conf file unchanged, so no further update is needed Jan 12 22:45:03 volumio volumio[7672]: info: Output device has changed, restarting MPD Jan 12 22:45:03 volumio go-librespot[7969]: time="2026-01-12T22:45:03-06:00" level=debug msg="completed keyexchange" Jan 12 22:45:03 volumio go-librespot[7969]: time="2026-01-12T22:45:03-06:00" level=debug msg="completed challenge" Jan 12 22:45:03 volumio volumio[7672]: info: Output device has changed, restarting Shairport Sync Jan 12 22:45:03 volumio volumio[7672]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:45:03 volumio volumio[7672]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 12 22:45:03 volumio sudo[8017]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 12 22:45:03 volumio sudo[8017]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 22:45:03 volumio sudo[8019]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 12 22:45:03 volumio sudo[8019]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 22:45:03 volumio sudo[8017]: pam_unix(sudo:session): session closed for user root Jan 12 22:45:03 volumio volumio[7672]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 12 22:45:03 volumio volumio[7672]: info: ___________ START PLUGINS ___________ Jan 12 22:45:03 volumio go-librespot[7969]: time="2026-01-12T22:45:03-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Jan 12 22:45:03 volumio volumio[7672]: info: ControllerMpd::onStart: Initializing MPD Jan 12 22:45:03 volumio volumio[7672]: info: Creating MPD Configuration file Jan 12 22:45:03 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 12 22:45:03 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 12 22:45:03 volumio volumio[7672]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 12 22:45:03 volumio volumio[7672]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 12 22:45:03 volumio volumio[7672]: info: [1768279503408] CoreMusicLibrary::Adding element Media Servers Jan 12 22:45:03 volumio volumio[7672]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 12 22:45:03 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Jan 12 22:45:03 volumio sudo[8027]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 12 22:45:03 volumio sudo[8027]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 22:45:03 volumio sudo[8027]: pam_unix(sudo:session): session closed for user root Jan 12 22:45:03 volumio sudo[8029]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 12 22:45:03 volumio volumio[7672]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:45:03 volumio volumio[7672]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 12 22:45:03 volumio sudo[8029]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 22:45:03 volumio volumio[7672]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 12 22:45:03 volumio volumio[7672]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:45:03 volumio volumio[7672]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 12 22:45:03 volumio volumio[7672]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 12 22:45:03 volumio volumio[7672]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 12 22:45:03 volumio volumio[7672]: info: [1768279503525] CoreMusicLibrary::Adding element Last_100 Jan 12 22:45:03 volumio volumio[7672]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 12 22:45:03 volumio volumio[7672]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 12 22:45:03 volumio volumio[7672]: info: [1768279503531] CoreMusicLibrary::Adding element Webradio Jan 12 22:45:03 volumio volumio[7672]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 12 22:45:03 volumio volumio[7672]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 12 22:45:03 volumio systemd[1]: mpd.service: Deactivated successfully. Jan 12 22:45:03 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Jan 12 22:45:03 volumio systemd[1]: mpd.service: Consumed 6.033s CPU time. Jan 12 22:45:03 volumio systemd[1]: mpd.socket: Deactivated successfully. Jan 12 22:45:03 volumio volumio[7672]: info: Initializing BBC Radios Jan 12 22:45:03 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jan 12 22:45:03 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jan 12 22:45:03 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jan 12 22:45:03 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Jan 12 22:45:03 volumio volumio[7672]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 12 22:45:03 volumio volumio[7672]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 12 22:45:03 volumio volumio[7672]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 12 22:45:03 volumio volumio[7672]: info: [1768279503662] CoreMusicLibrary::Adding element Bandcamp Discover Jan 12 22:45:03 volumio volumio[7672]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 12 22:45:03 volumio volumio[7672]: Cannot find translation for source Bandcamp Discover Jan 12 22:45:03 volumio volumio[7672]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 12 22:45:03 volumio volumio[7672]: info: [1768279503682] CoreMusicLibrary::Adding element SoundCloud Jan 12 22:45:03 volumio volumio[7672]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 12 22:45:03 volumio volumio[7672]: Cannot find translation for source Bandcamp Discover Jan 12 22:45:03 volumio volumio[7672]: Cannot find translation for source SoundCloud Jan 12 22:45:03 volumio volumio[7672]: info: Creating Spotify config file Jan 12 22:45:03 volumio volumio[7672]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:45:04 volumio sudo[8054]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jan 12 22:45:04 volumio sudo[8054]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Jan 12 22:45:04 volumio sudo[8054]: pam_unix(sudo:session): session closed for user root Jan 12 22:45:04 volumio volumio[7672]: info: [squeezelite_mc] Starting proxy server... Jan 12 22:45:04 volumio volumio[7672]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 12 22:45:04 volumio volumio[7672]: info: [1768279504358] CoreMusicLibrary::Adding element YouTube2 Jan 12 22:45:04 volumio volumio[7672]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 12 22:45:04 volumio volumio[7672]: Cannot find translation for source Bandcamp Discover Jan 12 22:45:04 volumio volumio[7672]: Cannot find translation for source SoundCloud Jan 12 22:45:04 volumio volumio[7672]: Cannot find translation for source YouTube2 Jan 12 22:45:04 volumio volumio[7672]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 12 22:45:04 volumio volumio[7672]: info: [1768279504390] CoreMusicLibrary::Adding element YouTube Music Jan 12 22:45:04 volumio volumio[7672]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 12 22:45:04 volumio volumio[7672]: Cannot find translation for source Bandcamp Discover Jan 12 22:45:04 volumio volumio[7672]: Cannot find translation for source SoundCloud Jan 12 22:45:04 volumio volumio[7672]: Cannot find translation for source YouTube2 Jan 12 22:45:04 volumio volumio[7672]: Cannot find translation for source YouTube Music Jan 12 22:45:04 volumio volumio[7672]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 12 22:45:04 volumio volumio[7672]: info: [1768279504409] CoreMusicLibrary::Adding element Podcast Jan 12 22:45:04 volumio volumio[7672]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 12 22:45:04 volumio volumio[7672]: Cannot find translation for source Bandcamp Discover Jan 12 22:45:04 volumio volumio[7672]: Cannot find translation for source SoundCloud Jan 12 22:45:04 volumio volumio[7672]: Cannot find translation for source YouTube2 Jan 12 22:45:04 volumio volumio[7672]: Cannot find translation for source YouTube Music Jan 12 22:45:04 volumio volumio[7672]: Cannot find translation for source Podcast Jan 12 22:45:04 volumio volumio[7672]: info: Loading i18n strings for locale en Jan 12 22:45:04 volumio volumio[7672]: info: Plugin peppyspectrum has duplicated i18n key SAVE. It is ignored. Jan 12 22:45:04 volumio volumio[7672]: Updating browse sources language Jan 12 22:45:04 volumio volumio[7672]: Cannot find translation for source Bandcamp Discover Jan 12 22:45:04 volumio volumio[7672]: Cannot find translation for source SoundCloud Jan 12 22:45:04 volumio volumio[7672]: Cannot find translation for source YouTube2 Jan 12 22:45:04 volumio volumio[7672]: Cannot find translation for source YouTube Music Jan 12 22:45:04 volumio volumio[7672]: Cannot find translation for source Podcast Jan 12 22:45:04 volumio volumio[7672]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 12 22:45:04 volumio volumio[7672]: Cannot find translation for source Bandcamp Discover Jan 12 22:45:04 volumio volumio[7672]: Cannot find translation for source SoundCloud Jan 12 22:45:04 volumio volumio[7672]: Cannot find translation for source YouTube2 Jan 12 22:45:04 volumio volumio[7672]: Cannot find translation for source YouTube Music Jan 12 22:45:04 volumio volumio[7672]: Cannot find translation for source Podcast Jan 12 22:45:04 volumio volumio[7672]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 12 22:45:04 volumio volumio[7672]: info: [1768279504500] CoreMusicLibrary::Adding element Volusonic Jan 12 22:45:04 volumio volumio[7672]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 12 22:45:04 volumio volumio[7672]: Cannot find translation for source Bandcamp Discover Jan 12 22:45:04 volumio volumio[7672]: Cannot find translation for source SoundCloud Jan 12 22:45:04 volumio volumio[7672]: Cannot find translation for source YouTube2 Jan 12 22:45:04 volumio volumio[7672]: Cannot find translation for source YouTube Music Jan 12 22:45:04 volumio volumio[7672]: Cannot find translation for source Podcast Jan 12 22:45:04 volumio volumio[7672]: Cannot find translation for source Volusonic Jan 12 22:45:04 volumio volumio[7672]: info: Scheduling reboots with hours: 0, minutes: 0 in timezone: America/Chicago Jan 12 22:45:04 volumio volumio[7672]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , updateALSAConfigFile Jan 12 22:45:04 volumio volumio[7672]: info: Volumio Calling Home Jan 12 22:45:04 volumio volumio[7672]: info: [squeezelite_mc] Proxy server started on port 40307 Jan 12 22:45:04 volumio volumio[7672]: info: Preparing to generate the ALSA configuration file Jan 12 22:45:04 volumio volumio[7672]: info: CoreCommandRouter::volumioRetrievevolume Jan 12 22:45:04 volumio volumio[7672]: info: The plugin peppyspectrum has an ALSA contribution file peppy_in.peppy_out.6.conf Jan 12 22:45:04 volumio volumio[7672]: info: Reading ALSA contributions from plugins. Jan 12 22:45:05 volumio volumio[7672]: info: MPD Permissions set Jan 12 22:45:05 volumio volumio[7672]: info: MPD Permissions set Jan 12 22:45:05 volumio volumio[7672]: info: Spotify config file written Jan 12 22:45:05 volumio sudo[8064]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jan 12 22:45:05 volumio sudo[8064]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 22:45:05 volumio volumio[7672]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Jan 12 22:45:05 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 12 22:45:05 volumio volumio[7672]: info: VolumeController:: Volume=100 Mute =false Jan 12 22:45:05 volumio volumio[7672]: info: CoreStateMachine::pushState Jan 12 22:45:05 volumio volumio[7672]: info: CorePlayQueue::getTrack 0 Jan 12 22:45:05 volumio volumio[7672]: info: CoreCommandRouter::volumioPushState Jan 12 22:45:05 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 12 22:45:05 volumio go-librespot[8066]: go-librespot daemon starting... Jan 12 22:45:05 volumio volumio[7672]: info: [squeezelite_mc] Server discovery started Jan 12 22:45:05 volumio volumio[7672]: info: [squeezelite_mc] Player finder started Jan 12 22:45:05 volumio volumio[7672]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:45:05 volumio volumio[7672]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:45:05 volumio sudo[8064]: pam_unix(sudo:session): session closed for user root Jan 12 22:45:05 volumio volumio[7672]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:45:05 volumio volumio[7672]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 12 22:45:05 volumio volumio[7672]: info: [squeezelite_mc] Executing aplay -D hw:1 --nonblock -f MPEG /dev/zero 2>&1 || true Jan 12 22:45:05 volumio go-librespot[8067]: time="2026-01-12T22:45:05-06:00" level=info msg="running go-librespot 0.4.0" Jan 12 22:45:05 volumio go-librespot[8067]: time="2026-01-12T22:45:05-06:00" level=debug msg="app state loaded" Jan 12 22:45:05 volumio go-librespot[8067]: time="2026-01-12T22:45:05-06:00" level=debug msg="stored credentials not found" Jan 12 22:45:05 volumio go-librespot[8067]: time="2026-01-12T22:45:05-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 12 22:45:05 volumio volumio[7672]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:45:05 volumio volumio[7672]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:45:05 volumio volumio[7672]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:45:05 volumio volumio[7672]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:45:05 volumio volumio[7672]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:45:05 volumio volumio[7672]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:45:05 volumio volumio[7672]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:45:05 volumio volumio[7672]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:45:05 volumio volumio[7672]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 12 22:45:05 volumio volumio[7672]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:45:05 volumio volumio[7672]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:45:05 volumio volumio[7672]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:45:05 volumio volumio[7672]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:45:05 volumio volumio[7672]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:45:05 volumio volumio[7672]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:45:05 volumio volumio[7672]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:45:05 volumio volumio[7672]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:45:05 volumio volumio[7672]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:45:05 volumio volumio[7672]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 12 22:45:05 volumio volumio[7672]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:45:05 volumio volumio[7672]: info: No need to fix Spotify hosts Jan 12 22:45:05 volumio volumio[7672]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Jan 12 22:45:05 volumio volumio[7672]: info: Volumio called home Jan 12 22:45:05 volumio go-librespot[8067]: time="2026-01-12T22:45:05-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 12 22:45:05 volumio go-librespot[8067]: time="2026-01-12T22:45:05-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 12 22:45:05 volumio go-librespot[8067]: time="2026-01-12T22:45:05-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 12 22:45:05 volumio go-librespot[8067]: time="2026-01-12T22:45:05-06:00" level=info msg="zeroconf server listening on port 35327" Jan 12 22:45:05 volumio volumio[7672]: info: [squeezelite_mc] Card 1 supports the following ALSA formats: ["U8","S16_LE"] Jan 12 22:45:05 volumio volumio[7672]: info: [squeezelite_mc] Starting Squeezelite service with params: {"type":"basic","playerName":"volumio","dsdFormat":null,"card":"1","mixerType":"Hardware","mixer":"PCM"} Jan 12 22:45:05 volumio volumio[7672]: info: [squeezelite_mc] Executing cp /data/plugins/music_service/squeezelite_mc/dist/lib/../templates/alsa/100-squeezelite.conf.template.out /etc/alsa/conf.d/100-squeezelite.conf Jan 12 22:45:06 volumio volumio[7672]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jan 12 22:45:06 volumio volumio[7672]: SPOTIFY: BQDTCICWnAt6PZp_GidVq2r1zS1rCskF_if8APSp-MGqarSXYRu6hex_H9YWL5VB6A89lp6F2FXdmQJuMPLyq-TF3dt0OoHHwojEF0WiCkypFtXbHrs-seWW_JZAyMWTuXhShz-5Sq_cArEKp9WNWjD75RFGbwt0xtCDYiIifPxg9aVQyTrLmD7Kdxsw3hlKnrCeJykjnk_eQg-wOp7Ecpdo-xMWiwXNht6UVSA Jan 12 22:45:06 volumio volumio[7672]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jan 12 22:45:06 volumio volumio[7672]: info: New Spotify access token = BQDTCICWnAt6PZp_GidVq2r1zS1rCskF_if8APSp-MGqarSXYRu6hex_H9YWL5VB6A89lp6F2FXdmQJuMPLyq-TF3dt0OoHHwojEF0WiCkypFtXbHrs-seWW_JZAyMWTuXhShz-5Sq_cArEKp9WNWjD75RFGbwt0xtCDYiIifPxg9aVQyTrLmD7Kdxsw3hlKnrCeJykjnk_eQg-wOp7Ecpdo-xMWiwXNht6UVSA Jan 12 22:45:06 volumio volumio[7672]: info: Spotify credentials grant success - running version from March 24, 2019 Jan 12 22:45:06 volumio go-librespot[8067]: time="2026-01-12T22:45:06-06:00" level=debug msg="obtained new client token: AADvI8DP82okbFwKFnlieNvDBhB9xuBiVC/P4iYfdD5KcLzGNDrExGNa2EkHtszW67sXFvGDnIZS6aKgDeHwPuofnXZUAcb85UmxaViPckgiD7ST0KCzHisGvY8zB6FrxBixlxBFI9LOMFMoE3SK4su6sERu/RykrqrbvSyc1Pd39g1q8NEZS1boydLbQovi17HnApr+8yMQ8VjVxcp9UjYylNz6LnOfm+3N9FuXyT8pyT3LvST9ims=" Jan 12 22:45:06 volumio volumio[7672]: info: Starting Shairport Sync Jan 12 22:45:06 volumio volumio[7672]: info: Starting Shairport Sync Jan 12 22:45:06 volumio go-librespot[8067]: time="2026-01-12T22:45:06-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 12 22:45:06 volumio volumio[7672]: info: Starting Shairport Sync Jan 12 22:45:06 volumio sudo[8090]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 12 22:45:06 volumio go-librespot[8067]: time="2026-01-12T22:45:06-06:00" level=debug msg="completed keyexchange" Jan 12 22:45:06 volumio go-librespot[8067]: time="2026-01-12T22:45:06-06:00" level=debug msg="completed challenge" Jan 12 22:45:06 volumio sudo[8090]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 22:45:06 volumio sudo[8094]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 12 22:45:06 volumio go-librespot[8067]: time="2026-01-12T22:45: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 " Jan 12 22:45:06 volumio sudo[8092]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 12 22:45:06 volumio sudo[8094]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 22:45:06 volumio sudo[8092]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 22:45:06 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 12 22:45:06 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 12 22:45:06 volumio volumio[7672]: info: Asound.conf file unchanged, so no further update is needed Jan 12 22:45:06 volumio volumio[7672]: info: Output device has changed, restarting MPD Jan 12 22:45:06 volumio sudo[8088]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/cp /data/plugins/music_service/squeezelite_mc/dist/lib/../templates/alsa/100-squeezelite.conf.template.out /etc/alsa/conf.d/100-squeezelite.conf Jan 12 22:45:06 volumio sudo[8088]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 22:45:06 volumio volumio[7672]: info: Output device has changed, restarting Shairport Sync Jan 12 22:45:06 volumio sudo[8088]: pam_unix(sudo:session): session closed for user root Jan 12 22:45:06 volumio volumio[7672]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:45:06 volumio volumio[7672]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 12 22:45:06 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jan 12 22:45:06 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Jan 12 22:45:06 volumio sudo[8100]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 12 22:45:06 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 12 22:45:06 volumio systemd[1]: shairport-sync.service: Consumed 1.927s CPU time. Jan 12 22:45:06 volumio sudo[8100]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 22:45:06 volumio sudo[8104]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 12 22:45:06 volumio sudo[8104]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 22:45:06 volumio sudo[8100]: pam_unix(sudo:session): session closed for user root Jan 12 22:45:06 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 12 22:45:06 volumio sudo[8094]: pam_unix(sudo:session): session closed for user root Jan 12 22:45:06 volumio sudo[8090]: pam_unix(sudo:session): session closed for user root Jan 12 22:45:06 volumio sudo[8092]: pam_unix(sudo:session): session closed for user root Jan 12 22:45:06 volumio volumio[7672]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 12 22:45:06 volumio systemd[1]: mpd.service: Deactivated successfully. Jan 12 22:45:06 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Jan 12 22:45:06 volumio systemd[1]: mpd.service: Consumed 2.977s CPU time. Jan 12 22:45:06 volumio systemd[1]: mpd.socket: Deactivated successfully. Jan 12 22:45:06 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jan 12 22:45:06 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jan 12 22:45:06 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jan 12 22:45:06 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Jan 12 22:45:06 volumio volumio[7672]: info: MPD Permissions set Jan 12 22:45:06 volumio volumio[7672]: info: Shairport-Sync Started Jan 12 22:45:06 volumio volumio[7672]: Error adding Membership: Error: addMembership EINVAL Jan 12 22:45:06 volumio volumio[7672]: info: Shairport-Sync Started Jan 12 22:45:06 volumio volumio[7672]: info: Shairport-Sync Started Jan 12 22:45:06 volumio volumio[7672]: info: [squeezelite_mc] Executing alsactl -L -R nrestore Jan 12 22:45:07 volumio sudo[8147]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/sbin/alsactl -L -R nrestore Jan 12 22:45:07 volumio sudo[8147]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 22:45:07 volumio sudo[8147]: pam_unix(sudo:session): session closed for user root Jan 12 22:45:07 volumio volumio[7672]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:45:07 volumio volumio[7672]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:45:07 volumio volumio[7672]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:45:07 volumio volumio[7672]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:45:07 volumio volumio[7672]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:45:07 volumio volumio[7672]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:45:07 volumio volumio[7672]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:45:07 volumio volumio[7672]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:45:07 volumio volumio[7672]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 12 22:45:07 volumio volumio[7672]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:45:07 volumio volumio[7672]: info: [squeezelite_mc] Executing cp /data/plugins/music_service/squeezelite_mc/dist/lib/../templates/systemd/squeezelite.service.template.out /etc/systemd/system/squeezelite.service Jan 12 22:45:07 volumio volumio[7672]: info: CoreCommandRouter::volumioGetState Jan 12 22:45:07 volumio volumio[7672]: info: CorePlayQueue::getTrack 0 Jan 12 22:45:07 volumio volumio[7672]: info: Starting Shairport Sync Jan 12 22:45:07 volumio sudo[8144]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jan 12 22:45:07 volumio sudo[8144]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Jan 12 22:45:07 volumio sudo[8144]: pam_unix(sudo:session): session closed for user root Jan 12 22:45:07 volumio sudo[8156]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/cp /data/plugins/music_service/squeezelite_mc/dist/lib/../templates/systemd/squeezelite.service.template.out /etc/systemd/system/squeezelite.service Jan 12 22:45:07 volumio sudo[8156]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 22:45:07 volumio sudo[8156]: pam_unix(sudo:session): session closed for user root Jan 12 22:45:07 volumio sudo[8158]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 12 22:45:07 volumio sudo[8158]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 22:45:07 volumio volumio[7672]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl daemon-reload || true Jan 12 22:45:07 volumio volumio[7672]: SPOTIFY: User informations: {"display_name":"Clint Smith","external_urls":{"spotify":"https://open.spotify.com/user/clintsmith1"},"followers":{"href":null,"total":7},"href":"https://api.spotify.com/v1/users/clintsmith1","id":"clintsmith1","images":[{"height":300,"url":"https://i.scdn.co/image/ab6775700000ee856520409d25d9cc210472a0fd","width":300},{"height":64,"url":"https://i.scdn.co/image/ab67757000003b826520409d25d9cc210472a0fd","width":64}],"type":"user","uri":"spotify:user:clintsmith1"} Jan 12 22:45:07 volumio sudo[8164]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl daemon-reload Jan 12 22:45:07 volumio sudo[8164]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 22:45:07 volumio volumio[7672]: info: Spotify Successfully logged in Jan 12 22:45:07 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jan 12 22:45:07 volumio volumio[7672]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 12 22:45:07 volumio volumio[7672]: info: [1768279507337] CoreMusicLibrary::Adding element Spotify Jan 12 22:45:07 volumio volumio[7672]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 12 22:45:07 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Jan 12 22:45:07 volumio volumio[7672]: Cannot find translation for source Bandcamp Discover Jan 12 22:45:07 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 12 22:45:07 volumio volumio[7672]: Cannot find translation for source SoundCloud Jan 12 22:45:07 volumio volumio[7672]: Cannot find translation for source YouTube2 Jan 12 22:45:07 volumio volumio[7672]: Cannot find translation for source YouTube Music Jan 12 22:45:07 volumio volumio[7672]: Cannot find translation for source Podcast Jan 12 22:45:07 volumio volumio[7672]: Cannot find translation for source Volusonic Jan 12 22:45:07 volumio volumio[7672]: Cannot find translation for source Spotify Jan 12 22:45:07 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 12 22:45:07 volumio sudo[8158]: pam_unix(sudo:session): session closed for user root Jan 12 22:45:07 volumio volumio[7672]: info: Shairport-Sync Started Jan 12 22:45:07 volumio systemd[1]: Reloading. Jan 12 22:45:08 volumio volumio[7672]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:45:08 volumio volumio[7672]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:45:08 volumio volumio[7672]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 22:45:08 volumio volumio[7672]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 12 22:45:08 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.201.120 Jan 12 22:45:08 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Jan 12 22:45:08 volumio avahi-daemon[664]: Registering new address record for 169.254.201.120 on eth0.IPv4. Jan 12 22:45:08 volumio volumio[7672]: info: go-librespot daemon successfully initialized Jan 12 22:45:09 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.201.120 Jan 12 22:45:09 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.201.120 Jan 12 22:45:09 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.201.120 Jan 12 22:45:09 volumio avahi-daemon[664]: Withdrawing address record for 169.254.201.120 on eth0. Jan 12 22:45:09 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Jan 12 22:45:09 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Jan 12 22:45:09 volumio systemd[1]: /lib/systemd/system/go-librespot-daemon.service:9: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Jan 12 22:45:09 volumio systemd[1]: /lib/systemd/system/go-librespot-daemon.service:10: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Jan 12 22:45:10 volumio sudo[8164]: pam_unix(sudo:session): session closed for user root Jan 12 22:45:10 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 16. Jan 12 22:45:10 volumio volumio[7672]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Jan 12 22:45:10 volumio sudo[8232]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Jan 12 22:45:10 volumio sudo[8232]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 22:45:10 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 12 22:45:10 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 12 22:45:10 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 12 22:45:10 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 12 22:45:10 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 12 22:45:10 volumio go-librespot[8235]: go-librespot daemon starting... Jan 12 22:45:10 volumio go-librespot[8236]: time="2026-01-12T22:45:10-06:00" level=info msg="running go-librespot 0.4.0" Jan 12 22:45:10 volumio go-librespot[8236]: time="2026-01-12T22:45:10-06:00" level=debug msg="app state loaded" Jan 12 22:45:10 volumio go-librespot[8236]: time="2026-01-12T22:45:10-06:00" level=debug msg="stored credentials not found" Jan 12 22:45:10 volumio go-librespot[8236]: time="2026-01-12T22:45:10-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 12 22:45:10 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 12 22:45:10 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 12 22:45:10 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 12 22:45:11 volumio sudo[8232]: pam_unix(sudo:session): session closed for user root Jan 12 22:45:11 volumio volumio[7672]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl stop squeezelite || true Jan 12 22:45:11 volumio sudo[8243]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop squeezelite Jan 12 22:45:11 volumio sudo[8243]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 22:45:11 volumio systemd[1]: Stopping squeezelite.service - Squeezelite lightweight headless Squeezebox emulator... Jan 12 22:45:11 volumio go-librespot[8236]: time="2026-01-12T22:45: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-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 12 22:45:11 volumio go-librespot[8236]: time="2026-01-12T22:45:11-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 12 22:45:11 volumio go-librespot[8236]: time="2026-01-12T22:45:11-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 12 22:45:11 volumio go-librespot[8236]: time="2026-01-12T22:45:11-06:00" level=info msg="zeroconf server listening on port 33637" Jan 12 22:45:11 volumio systemd[1]: squeezelite.service: Deactivated successfully. Jan 12 22:45:11 volumio systemd[1]: Stopped squeezelite.service - Squeezelite lightweight headless Squeezebox emulator. Jan 12 22:45:11 volumio sudo[8243]: pam_unix(sudo:session): session closed for user root Jan 12 22:45:11 volumio go-librespot[8236]: time="2026-01-12T22:45:11-06:00" level=debug msg="obtained new client token: AABLiZf33hCczFyGJgHdjX/u1oN3XN6Xdoej7SCzuvC/2HmN9Y6EMQ8RMCjmHCgiQRVJPoXT2C3UMJBZa6fUZKRK9Zro/SXvq8rzYbLpgAXxH+lzTuNHSN458+64dujdMhn3ZJvggR+s+WLR35MPiY644DLCLrwH9HN7bQqzJ59Uf92jzeXipQdTuANslKqJoMWsAvP4u7th0kA22gyYuWrx3Q3snSWhTDBF1UeMJ4ONmlMbOAg/MKv5Ug==" Jan 12 22:45:11 volumio go-librespot[8236]: time="2026-01-12T22:45:11-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 12 22:45:11 volumio go-librespot[8236]: time="2026-01-12T22:45:11-06:00" level=debug msg="completed keyexchange" Jan 12 22:45:11 volumio go-librespot[8236]: time="2026-01-12T22:45:11-06:00" level=debug msg="completed challenge" Jan 12 22:45:11 volumio go-librespot[8236]: time="2026-01-12T22:45:11-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Jan 12 22:45:11 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 12 22:45:11 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 12 22:45:11 volumio volumio[7672]: info: Initializing connection to go-librespot Websocket Jan 12 22:45:11 volumio volumio[7672]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 12 22:45:11 volumio volumio[7672]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Jan 12 22:45:12 volumio sudo[8247]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Jan 12 22:45:12 volumio sudo[8247]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 22:45:12 volumio sudo[8247]: pam_unix(sudo:session): session closed for user root Jan 12 22:45:12 volumio volumio[7672]: info: [squeezelite_mc] Executing rm /tmp/squeezelite.log Jan 12 22:45:12 volumio sudo[8251]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/rm /tmp/squeezelite.log Jan 12 22:45:12 volumio sudo[8251]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 22:45:12 volumio sudo[8251]: pam_unix(sudo:session): session closed for user root Jan 12 22:45:12 volumio volumio[7672]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl start squeezelite || true Jan 12 22:45:12 volumio sudo[8254]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start squeezelite Jan 12 22:45:12 volumio sudo[8254]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 22:45:12 volumio mpd[8161]: 2026-01-12T22:45:12 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jan 12 22:45:12 volumio systemd[1]: Starting squeezelite.service - Squeezelite lightweight headless Squeezebox emulator... Jan 12 22:45:12 volumio systemd[1]: Started squeezelite.service - Squeezelite lightweight headless Squeezebox emulator. Jan 12 22:45:12 volumio sudo[8254]: pam_unix(sudo:session): session closed for user root Jan 12 22:45:12 volumio systemd[1]: Started mpd.service - Music Player Daemon. Jan 12 22:45:12 volumio sudo[8104]: pam_unix(sudo:session): session closed for user root Jan 12 22:45:12 volumio sudo[8019]: pam_unix(sudo:session): session closed for user root Jan 12 22:45:12 volumio sudo[8029]: pam_unix(sudo:session): session closed for user root Jan 12 22:45:12 volumio volumio[7672]: error: MPD error: The expression evaluated to a falsy value: Jan 12 22:45:12 volumio volumio[7672]: assert.ok(self.idling) Jan 12 22:45:12 volumio volumio[7672]: error: The expression evaluated to a falsy value: Jan 12 22:45:12 volumio volumio[7672]: assert.ok(self.idling) Jan 12 22:45:12 volumio volumio[7672]: error: MPD error: The expression evaluated to a falsy value: Jan 12 22:45:12 volumio volumio[7672]: assert.ok(self.idling) Jan 12 22:45:12 volumio volumio[7672]: error: The expression evaluated to a falsy value: Jan 12 22:45:12 volumio volumio[7672]: assert.ok(self.idling) Jan 12 22:45:12 volumio volumio[7672]: info: MPD running with PID8161 Jan 12 22:45:12 volumio volumio[7672]: ,establishing connection Jan 12 22:45:12 volumio volumio[7672]: error: MPD error: The expression evaluated to a falsy value: Jan 12 22:45:12 volumio volumio[7672]: assert.ok(self.idling) Jan 12 22:45:12 volumio volumio[7672]: error: The expression evaluated to a falsy value: Jan 12 22:45:12 volumio volumio[7672]: assert.ok(self.idling) Jan 12 22:45:12 volumio volumio[7672]: error: updateQueue error: null Jan 12 22:45:12 volumio volumio[7672]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Jan 12 22:45:12 volumio sudo[8266]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Jan 12 22:45:12 volumio sudo[8266]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 22:45:12 volumio sudo[8266]: pam_unix(sudo:session): session closed for user root Jan 12 22:45:13 volumio volumio[7672]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Jan 12 22:45:13 volumio sudo[8269]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Jan 12 22:45:13 volumio sudo[8269]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 22:45:13 volumio sudo[8269]: pam_unix(sudo:session): session closed for user root Jan 12 22:45:13 volumio kernel: hwmon hwmon1: Voltage normalised Jan 12 22:45:14 volumio volumio[7672]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Jan 12 22:45:14 volumio sudo[8273]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Jan 12 22:45:14 volumio sudo[8273]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 22:45:14 volumio sudo[8273]: pam_unix(sudo:session): session closed for user root Jan 12 22:45:14 volumio volumio[7672]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Jan 12 22:45:14 volumio sudo[8276]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Jan 12 22:45:14 volumio sudo[8276]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 22:45:14 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 17. Jan 12 22:45:14 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 12 22:45:14 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 12 22:45:14 volumio go-librespot[8278]: go-librespot daemon starting... Jan 12 22:45:14 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.54.144 Jan 12 22:45:14 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Jan 12 22:45:14 volumio avahi-daemon[664]: Registering new address record for 169.254.54.144 on eth0.IPv4. Jan 12 22:45:14 volumio go-librespot[8279]: time="2026-01-12T22:45:14-06:00" level=info msg="running go-librespot 0.4.0" Jan 12 22:45:14 volumio go-librespot[8279]: time="2026-01-12T22:45:14-06:00" level=debug msg="app state loaded" Jan 12 22:45:14 volumio go-librespot[8279]: time="2026-01-12T22:45:14-06:00" level=debug msg="stored credentials not found" Jan 12 22:45:14 volumio go-librespot[8279]: time="2026-01-12T22:45:14-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 12 22:45:14 volumio sudo[8276]: pam_unix(sudo:session): session closed for user root Jan 12 22:45:14 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.54.144 Jan 12 22:45:14 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 12 22:45:14 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 12 22:45:14 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 12 22:45:14 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.54.144 Jan 12 22:45:14 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.54.144 Jan 12 22:45:14 volumio avahi-daemon[664]: Withdrawing address record for 169.254.54.144 on eth0. Jan 12 22:45:14 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Jan 12 22:45:14 volumio volumio[7672]: info: Initializing connection to go-librespot Websocket Jan 12 22:45:14 volumio go-librespot[8279]: time="2026-01-12T22:45:14-06:00" level=debug msg="new websocket client" Jan 12 22:45:14 volumio volumio[7672]: info: Connection to go-librespot Websocket established Jan 12 22:45:14 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 12 22:45:14 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Jan 12 22:45:14 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 12 22:45:14 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 12 22:45:15 volumio go-librespot[8279]: time="2026-01-12T22:45: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-gew1.spotify.com:80]" Jan 12 22:45:15 volumio go-librespot[8279]: time="2026-01-12T22:45:15-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Jan 12 22:45:15 volumio go-librespot[8279]: time="2026-01-12T22:45:15-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Jan 12 22:45:15 volumio go-librespot[8279]: time="2026-01-12T22:45:15-06:00" level=info msg="zeroconf server listening on port 46051" Jan 12 22:45:15 volumio go-librespot[8279]: time="2026-01-12T22:45:15-06:00" level=debug msg="obtained new client token: AAAItYw9bsd5J/b3n+QRyMbYwDCd4ShMVkKrXh+HHFUCExRjDKwSz4Mapz4Kpk7Xk5WCTJkpueoWBdsaOtDm4ZAzmsFpKA0pEusWs2sKmdpnmWmE+W8MkcRjm3K/S1y2jyVXBSwcLyVMbpFXDRNEEsgtJwvHGiEgyUwXS11mTzR9AX1be7H1DRppzw/sLkRb8mbQUwI/qYTYOjTcr2UNppXWu8tQh5Eaq+yuBBZRnwmpOi1JDn0cS2c=" Jan 12 22:45:15 volumio go-librespot[8279]: time="2026-01-12T22:45:15-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 12 22:45:15 volumio volumio[7672]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Jan 12 22:45:15 volumio sudo[8319]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Jan 12 22:45:15 volumio go-librespot[8279]: time="2026-01-12T22:45:15-06:00" level=debug msg="completed keyexchange" Jan 12 22:45:15 volumio go-librespot[8279]: time="2026-01-12T22:45:15-06:00" level=debug msg="completed challenge" Jan 12 22:45:15 volumio sudo[8319]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 22:45:15 volumio go-librespot[8279]: time="2026-01-12T22:45:15-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Jan 12 22:45:15 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 12 22:45:15 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 12 22:45:15 volumio sudo[8319]: pam_unix(sudo:session): session closed for user root Jan 12 22:45:15 volumio volumio[7672]: info: Connection to go-librespot Websocket closed Jan 12 22:45:15 volumio volumio[7672]: info: Completed starting Core Plugins Jan 12 22:45:15 volumio volumio[7672]: info: ------------------------------------------- Jan 12 22:45:15 volumio volumio[7672]: info: ----- MyVolumio plugins startup ---- Jan 12 22:45:15 volumio volumio[7672]: info: ------------------------------------------- Jan 12 22:45:15 volumio volumio[7672]: info: [MyVolumio PluginManager] Fetching plans data.... Jan 12 22:45:15 volumio sudo[8322]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Jan 12 22:45:15 volumio sudo[8322]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 22:45:15 volumio sudo[8324]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Jan 12 22:45:15 volumio sudo[8324]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 22:45:15 volumio systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Jan 12 22:45:15 volumio systemd[1]: mpd_monitor.service: Deactivated successfully. Jan 12 22:45:15 volumio systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Jan 12 22:45:15 volumio sudo[8329]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Jan 12 22:45:15 volumio sudo[8329]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 22:45:15 volumio systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Jan 12 22:45:15 volumio sudo[8322]: pam_unix(sudo:session): session closed for user root Jan 12 22:45:15 volumio sudo[8324]: pam_unix(sudo:session): session closed for user root Jan 12 22:45:15 volumio mpd_monitor.sh[8327]: MPD Monitor Service: Starting MPD Monitor Service Jan 12 22:45:15 volumio volumio[7672]: info: Successfully started MPD Monitor Jan 12 22:45:15 volumio volumio[7672]: info: Successfully started MPD Monitor Jan 12 22:45:15 volumio systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Jan 12 22:45:15 volumio systemd[1]: mpd_monitor.service: Deactivated successfully. Jan 12 22:45:15 volumio systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Jan 12 22:45:15 volumio systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Jan 12 22:45:15 volumio mpd_monitor.sh[8335]: MPD Monitor Service: Starting MPD Monitor Service Jan 12 22:45:15 volumio sudo[8329]: pam_unix(sudo:session): session closed for user root Jan 12 22:45:15 volumio volumio[7672]: info: Successfully started MPD Monitor Jan 12 22:45:17 volumio volumio[7672]: info: Getting Spotify volume Jan 12 22:45:17 volumio volumio[7672]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 12 22:45:17 volumio volumio[7672]: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 12 22:45:17 volumio volumio[7672]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Jan 12 22:45:17 volumio volumio[7672]: errno: -111, Jan 12 22:45:17 volumio volumio[7672]: code: 'ECONNREFUSED', Jan 12 22:45:17 volumio volumio[7672]: syscall: 'connect', Jan 12 22:45:17 volumio volumio[7672]: address: '127.0.0.1', Jan 12 22:45:17 volumio volumio[7672]: port: 9879, Jan 12 22:45:17 volumio volumio[7672]: response: undefined Jan 12 22:45:17 volumio volumio[7672]: } Jan 12 22:45:17 volumio volumio[7672]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 12 22:45:18 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 18. Jan 12 22:45:18 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 12 22:45:18 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 12 22:45:18 volumio go-librespot[8365]: go-librespot daemon starting... Jan 12 22:45:18 volumio go-librespot[8366]: time="2026-01-12T22:45:18-06:00" level=info msg="running go-librespot 0.4.0" Jan 12 22:45:18 volumio go-librespot[8366]: time="2026-01-12T22:45:18-06:00" level=debug msg="app state loaded" Jan 12 22:45:18 volumio go-librespot[8366]: time="2026-01-12T22:45:18-06:00" level=debug msg="stored credentials not found" Jan 12 22:45:18 volumio go-librespot[8366]: time="2026-01-12T22:45:18-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 12 22:45:18 volumio sudo[8375]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-01-12 22:44' Jan 12 22:45:18 volumio sudo[8375]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 22:45:18 volumio go-librespot[8366]: time="2026-01-12T22:45: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]" Jan 12 22:45:18 volumio go-librespot[8366]: time="2026-01-12T22:45: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]" Jan 12 22:45:18 volumio go-librespot[8366]: time="2026-01-12T22:45: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]" Jan 12 22:45:18 volumio go-librespot[8366]: time="2026-01-12T22:45:18-06:00" level=info msg="zeroconf server listening on port 41799" 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"