Jan 11 14:29:00 music go-librespot[25233]: time="2026-01-11T14:29:00-05:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 11 14:29:00 music volumio[25059]: 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 11 14:29:00 music sudo[25240]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jan 11 14:29:00 music sudo[25240]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:29:00 music volumio[25059]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:29:00 music volumio[25059]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:29:00 music volumio[25059]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:29:00 music volumio[25149]: Starting albumart workers Jan 11 14:29:00 music volumio[25059]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:29:00 music volumio[25059]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:29:00 music volumio[25059]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:29:00 music volumio[25059]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:29:00 music volumio[25059]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:29:00 music systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Jan 11 14:29:00 music volumio[25059]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 11 14:29:00 music volumio[25059]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:29:00 music systemd[1]: go-librespot-daemon.service: Deactivated successfully. Jan 11 14:29:00 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 11 14:29:00 music volumio[25059]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:29:00 music volumio[25059]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:29:00 music volumio[25059]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:29:00 music volumio[25059]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:29:00 music volumio[25059]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:29:00 music volumio[25059]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:29:00 music volumio[25059]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:29:00 music volumio[25059]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:29:00 music volumio[25059]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 11 14:29:00 music volumio[25059]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:29:00 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 11 14:29:00 music go-librespot[25249]: go-librespot daemon starting... Jan 11 14:29:00 music volumio[25059]: info: No need to fix Spotify hosts Jan 11 14:29:00 music sudo[25240]: pam_unix(sudo:session): session closed for user root Jan 11 14:29:00 music go-librespot[25255]: time="2026-01-11T14:29:00-05:00" level=info msg="running go-librespot 0.6.2" Jan 11 14:29:00 music go-librespot[25255]: time="2026-01-11T14:29:00-05:00" level=debug msg="app state loaded" Jan 11 14:29:00 music volumio[25148]: Starting albumart workers Jan 11 14:29:00 music go-librespot[25255]: time="2026-01-11T14:29:00-05:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 11 14:29:00 music volumio[25147]: Starting albumart workers Jan 11 14:29:00 music go-librespot[25255]: time="2026-01-11T14:29:00-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 11 14:29:00 music go-librespot[25255]: time="2026-01-11T14:29:00-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 11 14:29:00 music go-librespot[25255]: time="2026-01-11T14:29:00-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 11 14:29:00 music go-librespot[25255]: time="2026-01-11T14:29:00-05:00" level=info msg="zeroconf server listening on port 43209" Jan 11 14:29:00 music go-librespot[25255]: time="2026-01-11T14:29:00-05:00" level=debug msg="obtained new client token: AAAvClKm29/1S9Bj/GWKNqNj37VC9awOOV+Uyt1/LwLUBr1FpagseRLcxqnT8uVjn3TNdkqk18sJchguQoej6Riu9iBKh2f47/IDcbMNHr5GMFzJiRtgcVcixkT30llIk4Dt9CcOrimGaCNVvtDgauToKxIiFFPI7fk1jG3Fx3+MmuqY3gvEQHBRQCEDTclGOYn2z3h9EBk30x9kiwOrmfqd8m2f3vMVB3nNjOeet9R0XD/jl0kCmOw=" Jan 11 14:29:01 music volumio[25059]: info: Starting Shairport Sync Jan 11 14:29:01 music volumio[25059]: info: Starting Shairport Sync Jan 11 14:29:01 music go-librespot[25255]: time="2026-01-11T14:29:01-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Jan 11 14:29:01 music volumio[25059]: info: Starting Shairport Sync Jan 11 14:29:01 music volumio[25059]: info: An error occurred while refreshing Spotify Token Error: Bad Request Jan 11 14:29:01 music sudo[25267]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 11 14:29:01 music sudo[25267]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:29:01 music go-librespot[25255]: time="2026-01-11T14:29:01-05:00" level=debug msg="completed keyexchange" Jan 11 14:29:01 music go-librespot[25255]: time="2026-01-11T14:29:01-05:00" level=debug msg="completed challenge" Jan 11 14:29:01 music sudo[25268]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 11 14:29:01 music sudo[25268]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:29:01 music sudo[25270]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 11 14:29:01 music sudo[25270]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:29:01 music go-librespot[25255]: time="2026-01-11T14:29:01-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:29:01 music systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jan 11 14:29:01 music systemd[1]: shairport-sync.service: Deactivated successfully. Jan 11 14:29:01 music systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 11 14:29:01 music systemd[1]: shairport-sync.service: Consumed 1.876s CPU time. Jan 11 14:29:01 music systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 11 14:29:01 music sudo[25267]: pam_unix(sudo:session): session closed for user root Jan 11 14:29:01 music sudo[25268]: pam_unix(sudo:session): session closed for user root Jan 11 14:29:01 music sudo[25270]: pam_unix(sudo:session): session closed for user root Jan 11 14:29:01 music volumio[25059]: info: Shairport-Sync Started Jan 11 14:29:01 music volumio[25059]: Error adding Membership: Error: addMembership EINVAL Jan 11 14:29:01 music volumio[25059]: info: Shairport-Sync Started Jan 11 14:29:01 music volumio[25059]: info: Shairport-Sync Started Jan 11 14:29:01 music volumio[25059]: info: CoreCommandRouter::volumioGetState Jan 11 14:29:01 music volumio[25059]: info: CorePlayQueue::getTrack 0 Jan 11 14:29:01 music go-librespot[25255]: time="2026-01-11T14:29:01-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Jan 11 14:29:01 music go-librespot[25255]: time="2026-01-11T14:29:01-05:00" level=debug msg="completed keyexchange" Jan 11 14:29:01 music go-librespot[25255]: time="2026-01-11T14:29:01-05:00" level=debug msg="completed challenge" Jan 11 14:29:01 music go-librespot[25255]: time="2026-01-11T14:29:01-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:29:02 music go-librespot[25255]: time="2026-01-11T14:29:02-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Jan 11 14:29:02 music go-librespot[25255]: time="2026-01-11T14:29:02-05:00" level=debug msg="completed keyexchange" Jan 11 14:29:02 music go-librespot[25255]: time="2026-01-11T14:29:02-05:00" level=debug msg="completed challenge" Jan 11 14:29:02 music go-librespot[25255]: time="2026-01-11T14:29:02-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:29:03 music go-librespot[25255]: time="2026-01-11T14:29:03-05:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 11 14:29:03 music go-librespot[25255]: time="2026-01-11T14:29:03-05:00" level=debug msg="completed keyexchange" Jan 11 14:29:03 music go-librespot[25255]: time="2026-01-11T14:29:03-05:00" level=debug msg="completed challenge" Jan 11 14:29:03 music go-librespot[25255]: time="2026-01-11T14:29:03-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:29:03 music mpd[25227]: 2026-01-11T14:29:03 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jan 11 14:29:03 music systemd[1]: Started mpd.service - Music Player Daemon. Jan 11 14:29:03 music sudo[25189]: pam_unix(sudo:session): session closed for user root Jan 11 14:29:03 music sudo[25198]: pam_unix(sudo:session): session closed for user root Jan 11 14:29:03 music volumio[25059]: info: Completed starting Core Plugins Jan 11 14:29:03 music volumio[25059]: info: ------------------------------------------- Jan 11 14:29:03 music volumio[25059]: info: ----- MyVolumio plugins startup ---- Jan 11 14:29:03 music volumio[25059]: info: ------------------------------------------- Jan 11 14:29:03 music volumio[25059]: info: [MyVolumio PluginManager] Fetching plans data.... Jan 11 14:29:03 music volumio[25059]: error: MPD error: The expression evaluated to a falsy value: Jan 11 14:29:03 music volumio[25059]: assert.ok(self.idling) Jan 11 14:29:03 music volumio[25059]: error: The expression evaluated to a falsy value: Jan 11 14:29:03 music volumio[25059]: assert.ok(self.idling) Jan 11 14:29:03 music volumio[25059]: info: MPD running with PID25227 Jan 11 14:29:03 music volumio[25059]: ,establishing connection Jan 11 14:29:03 music volumio[25059]: error: updateQueue error: null Jan 11 14:29:03 music volumio[25059]: error: updateQueue error: null Jan 11 14:29:03 music go-librespot[25255]: time="2026-01-11T14:29:03-05:00" level=debug msg="connected to ap-gew1.spotify.com:443" Jan 11 14:29:03 music volumio[25059]: info: go-librespot daemon successfully initialized Jan 11 14:29:03 music go-librespot[25255]: time="2026-01-11T14:29:03-05:00" level=debug msg="completed keyexchange" Jan 11 14:29:03 music go-librespot[25255]: time="2026-01-11T14:29:03-05:00" level=debug msg="completed challenge" Jan 11 14:29:04 music sudo[25329]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 11 14:29:04 music sudo[25329]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:29:04 music go-librespot[25255]: time="2026-01-11T14:29:04-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:29:04 music sudo[25329]: pam_unix(sudo:session): session closed for user root Jan 11 14:29:04 music sudo[25331]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 11 14:29:04 music sudo[25331]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:29:04 music sudo[25331]: pam_unix(sudo:session): session closed for user root Jan 11 14:29:04 music sudo[25334]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Jan 11 14:29:04 music sudo[25334]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:29:04 music sudo[25334]: pam_unix(sudo:session): session closed for user root Jan 11 14:29:04 music volumio[25059]: info: Upmpdcli Daemon Started Jan 11 14:29:04 music go-librespot[25255]: time="2026-01-11T14:29:04-05:00" level=debug msg="connected to ap-gew4.spotify.com:80" Jan 11 14:29:04 music go-librespot[25255]: time="2026-01-11T14:29:04-05:00" level=debug msg="completed keyexchange" Jan 11 14:29:04 music go-librespot[25255]: time="2026-01-11T14:29:04-05:00" level=debug msg="completed challenge" Jan 11 14:29:04 music volumio[25059]: info: CoreCommandRouter::volumioGetState Jan 11 14:29:04 music volumio[25059]: info: CorePlayQueue::getTrack 0 Jan 11 14:29:04 music go-librespot[25255]: time="2026-01-11T14:29:04-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:29:04 music go-librespot[25255]: time="2026-01-11T14:29:04-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:29:04 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 11 14:29:04 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 11 14:29:06 music sudo[25338]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Jan 11 14:29:06 music sudo[25338]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:29:06 music sudo[25340]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Jan 11 14:29:06 music sudo[25340]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:29:06 music systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Jan 11 14:29:06 music systemd[1]: mpd_monitor.service: Deactivated successfully. Jan 11 14:29:06 music systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Jan 11 14:29:06 music systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Jan 11 14:29:06 music sudo[25338]: pam_unix(sudo:session): session closed for user root Jan 11 14:29:06 music sudo[25340]: pam_unix(sudo:session): session closed for user root Jan 11 14:29:06 music volumio[25059]: info: Successfully started MPD Monitor Jan 11 14:29:06 music volumio[25059]: info: Successfully started MPD Monitor Jan 11 14:29:06 music mpd_monitor.sh[25343]: MPD Monitor Service: Starting MPD Monitor Service Jan 11 14:29:06 music volumio[25059]: info: Initializing connection to go-librespot Websocket Jan 11 14:29:06 music volumio[25059]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 11 14:29:08 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Jan 11 14:29:08 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 11 14:29:08 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 11 14:29:08 music go-librespot[25347]: go-librespot daemon starting... Jan 11 14:29:08 music go-librespot[25348]: time="2026-01-11T14:29:08-05:00" level=info msg="running go-librespot 0.6.2" Jan 11 14:29:08 music go-librespot[25348]: time="2026-01-11T14:29:08-05:00" level=debug msg="app state loaded" Jan 11 14:29:08 music go-librespot[25348]: time="2026-01-11T14:29:08-05:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 11 14:29:08 music volumio[25059]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Jan 11 14:29:08 music go-librespot[25348]: time="2026-01-11T14:29:08-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew4.spotify.com:80]" Jan 11 14:29:08 music go-librespot[25348]: time="2026-01-11T14:29:08-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 11 14:29:08 music go-librespot[25348]: time="2026-01-11T14:29:08-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 11 14:29:08 music go-librespot[25348]: time="2026-01-11T14:29:08-05:00" level=info msg="zeroconf server listening on port 46619" Jan 11 14:29:08 music go-librespot[25348]: time="2026-01-11T14:29:08-05:00" level=debug msg="obtained new client token: AADacSVz3p8hxwdD9fWE7xSDOCbkF7iX5ExoSqRzwaVCMxMcrHNVBgNfptSMtrRQJXp9TpmBxqJcyn43ZhqShwE5268+qQNN/L1Iu1+B26XOpXaTPXukWr/N/RbaPZE5GbmzpekTfjo22psVA7Xr5qh45Db24hW1ipXRNH2HfhURtlBx/ySzNWpuw/l9uiKkEMnab2n61D5/CJlAkQHBn3lDu7y29lHoPyaHPXo0Vz87oAku7VfPeLw=" Jan 11 14:29:08 music go-librespot[25348]: time="2026-01-11T14:29:08-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Jan 11 14:29:08 music go-librespot[25348]: time="2026-01-11T14:29:08-05:00" level=debug msg="completed keyexchange" Jan 11 14:29:08 music go-librespot[25348]: time="2026-01-11T14:29:08-05:00" level=debug msg="completed challenge" Jan 11 14:29:08 music go-librespot[25348]: time="2026-01-11T14:29:08-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:29:09 music go-librespot[25348]: time="2026-01-11T14:29:09-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Jan 11 14:29:09 music go-librespot[25348]: time="2026-01-11T14:29:09-05:00" level=debug msg="completed keyexchange" Jan 11 14:29:09 music go-librespot[25348]: time="2026-01-11T14:29:09-05:00" level=debug msg="completed challenge" Jan 11 14:29:09 music go-librespot[25348]: time="2026-01-11T14:29:09-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:29:09 music volumio[25059]: info: Initializing connection to go-librespot Websocket Jan 11 14:29:09 music go-librespot[25348]: time="2026-01-11T14:29:09-05:00" level=debug msg="new websocket client" Jan 11 14:29:09 music volumio[25059]: info: Connection to go-librespot Websocket established Jan 11 14:29:10 music go-librespot[25348]: time="2026-01-11T14:29:10-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Jan 11 14:29:10 music go-librespot[25348]: time="2026-01-11T14:29:10-05:00" level=debug msg="completed keyexchange" Jan 11 14:29:10 music go-librespot[25348]: time="2026-01-11T14:29:10-05:00" level=debug msg="completed challenge" Jan 11 14:29:10 music go-librespot[25348]: time="2026-01-11T14:29:10-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:29:10 music go-librespot[25348]: time="2026-01-11T14:29:10-05:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 11 14:29:10 music go-librespot[25348]: time="2026-01-11T14:29:10-05:00" level=debug msg="completed keyexchange" Jan 11 14:29:10 music go-librespot[25348]: time="2026-01-11T14:29:10-05:00" level=debug msg="completed challenge" Jan 11 14:29:10 music go-librespot[25348]: time="2026-01-11T14:29:10-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:29:11 music volumio[25059]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Jan 11 14:29:11 music volumio[25059]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Jan 11 14:29:11 music volumio[25059]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Jan 11 14:29:11 music volumio[25059]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Jan 11 14:29:11 music volumio[25059]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Jan 11 14:29:11 music volumio[25059]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Jan 11 14:29:11 music volumio[25059]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Jan 11 14:29:11 music volumio[25059]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Jan 11 14:29:11 music volumio[25059]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Jan 11 14:29:11 music volumio[25059]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Jan 11 14:29:11 music volumio[25059]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Jan 11 14:29:11 music volumio[25059]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Jan 11 14:29:11 music volumio[25059]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Jan 11 14:29:11 music volumio[25059]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Jan 11 14:29:11 music volumio[25059]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Jan 11 14:29:11 music volumio[25059]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Jan 11 14:29:11 music volumio[25059]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Jan 11 14:29:11 music volumio[25059]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Jan 11 14:29:11 music volumio[25059]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Jan 11 14:29:11 music volumio[25059]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Jan 11 14:29:11 music volumio[25059]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Jan 11 14:29:11 music volumio[25059]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Jan 11 14:29:11 music volumio[25059]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Jan 11 14:29:11 music volumio[25059]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Jan 11 14:29:11 music volumio[25059]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Jan 11 14:29:11 music volumio[25059]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Jan 11 14:29:11 music volumio[25059]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Jan 11 14:29:11 music volumio[25059]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Jan 11 14:29:11 music volumio[25059]: info: Adding plugin bluetooth to MyMusic Plugins Jan 11 14:29:11 music volumio[25059]: info: Adding plugin multiroom to MyMusic Plugins Jan 11 14:29:11 music volumio[25059]: info: Adding plugin metavolumio to MyMusic Plugins Jan 11 14:29:11 music volumio[25059]: info: Adding plugin cd_controller to MyMusic Plugins Jan 11 14:29:11 music volumio[25059]: info: Adding plugin qobuzconnect to MyMusic Plugins Jan 11 14:29:11 music volumio[25059]: info: Adding plugin smart_inputs to MyMusic Plugins Jan 11 14:29:11 music volumio[25059]: info: Adding plugin tidalconnect to MyMusic Plugins Jan 11 14:29:11 music volumio[25059]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Jan 11 14:29:11 music go-librespot[25348]: time="2026-01-11T14:29:11-05:00" level=debug msg="connected to ap-gae2.spotify.com:443" Jan 11 14:29:11 music go-librespot[25348]: time="2026-01-11T14:29:11-05:00" level=debug msg="completed keyexchange" Jan 11 14:29:11 music go-librespot[25348]: time="2026-01-11T14:29:11-05:00" level=debug msg="completed challenge" Jan 11 14:29:12 music go-librespot[25348]: time="2026-01-11T14:29:12-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:29:12 music volumio[25059]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Jan 11 14:29:12 music volumio[25059]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Jan 11 14:29:12 music volumio[25059]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 11 14:29:12 music volumio[25059]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 11 14:29:12 music volumio[25059]: info: Starting MyVolumio Remote Streaming Endpoints Jan 11 14:29:12 music go-librespot[25348]: time="2026-01-11T14:29:12-05:00" level=debug msg="connected to ap-gew4.spotify.com:80" Jan 11 14:29:12 music volumio[25059]: info: MyVolumio login type: Token Jan 11 14:29:12 music volumio[25059]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Jan 11 14:29:12 music volumio[25059]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Jan 11 14:29:12 music go-librespot[25348]: time="2026-01-11T14:29:12-05:00" level=debug msg="completed keyexchange" Jan 11 14:29:12 music go-librespot[25348]: time="2026-01-11T14:29:12-05:00" level=debug msg="completed challenge" Jan 11 14:29:13 music go-librespot[25348]: time="2026-01-11T14:29:13-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:29:13 music go-librespot[25348]: time="2026-01-11T14:29:13-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:29:13 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 11 14:29:13 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 11 14:29:13 music volumio[25059]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Jan 11 14:29:13 music volumio[25059]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Jan 11 14:29:13 music volumio[25059]: info: Streaming services startup Jan 11 14:29:13 music volumio[25059]: info: Starting Streaming Daemon Jan 11 14:29:13 music sudo[25358]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Jan 11 14:29:13 music sudo[25358]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:29:13 music volumio[25059]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Jan 11 14:29:13 music sudo[25358]: pam_unix(sudo:session): session closed for user root Jan 11 14:29:13 music volumio[25059]: info: Getting Spotify volume Jan 11 14:29:13 music volumio[25059]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 11 14:29:13 music volumio[25059]: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 11 14:29:13 music volumio[25059]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Jan 11 14:29:13 music volumio[25059]: errno: -111, Jan 11 14:29:13 music volumio[25059]: code: 'ECONNREFUSED', Jan 11 14:29:13 music volumio[25059]: syscall: 'connect', Jan 11 14:29:13 music volumio[25059]: address: '127.0.0.1', Jan 11 14:29:13 music volumio[25059]: port: 9879, Jan 11 14:29:13 music volumio[25059]: response: undefined Jan 11 14:29:13 music volumio[25059]: } Jan 11 14:29:13 music volumio[25059]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 11 14:29:14 music sudo[25393]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-01-11 14:28' Jan 11 14:29:14 music sudo[25393]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:29:14 music sudo[25393]: pam_unix(sudo:session): session closed for user root Jan 11 14:29:14 music volumio-remote-updater[22000]: [2026-01-11 14:29:14] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Jan 11 14:29:14 music volumio-remote-updater[22000]: [2026-01-11 14:29:14] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Jan 11 14:29:14 music systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Jan 11 14:29:14 music systemd[1]: volumio.service: Failed with result 'exit-code'. Jan 11 14:29:14 music systemd[1]: volumio.service: Consumed 26.325s CPU time. Jan 11 14:29:14 music systemd[1]: Started dynamicswap.service - dynamicswap service. Jan 11 14:29:14 music systemd[1]: dynamicswap.service: Deactivated successfully. Jan 11 14:29:15 music systemd[1]: volumio.service: Scheduled restart job, restart counter is at 5273. Jan 11 14:29:15 music systemd[1]: Started dynamicswap.service - dynamicswap service. Jan 11 14:29:15 music systemd[1]: Stopped volumio.service - Volumio Backend Module. Jan 11 14:29:15 music systemd[1]: volumio.service: Consumed 26.325s CPU time. Jan 11 14:29:15 music systemd[1]: Started volumio.service - Volumio Backend Module. Jan 11 14:29:15 music systemd[1]: dynamicswap.service: Deactivated successfully. Jan 11 14:29:16 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Jan 11 14:29:16 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 11 14:29:16 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 11 14:29:16 music go-librespot[25420]: go-librespot daemon starting... Jan 11 14:29:16 music go-librespot[25421]: time="2026-01-11T14:29:16-05:00" level=info msg="running go-librespot 0.6.2" Jan 11 14:29:16 music go-librespot[25421]: time="2026-01-11T14:29:16-05:00" level=debug msg="app state loaded" Jan 11 14:29:16 music go-librespot[25421]: time="2026-01-11T14:29:16-05:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 11 14:29:16 music go-librespot[25421]: time="2026-01-11T14:29:16-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew1.spotify.com:80]" Jan 11 14:29:16 music go-librespot[25421]: time="2026-01-11T14:29:16-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Jan 11 14:29:16 music go-librespot[25421]: time="2026-01-11T14:29:16-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Jan 11 14:29:16 music go-librespot[25421]: time="2026-01-11T14:29:16-05:00" level=info msg="zeroconf server listening on port 35995" Jan 11 14:29:16 music go-librespot[25421]: time="2026-01-11T14:29:16-05:00" level=debug msg="obtained new client token: AABBpwAvaeIF6L9bxi42LGsSYQSbDXTC4QMR4/bvbVLP9e+2AxrU4cqnOq5JCr0VkAt8HE/XPfs20QSheNRxewwV7pAwxmQtaSKSiLUQgqDeYvLUezzzjcEd7LXL5ZdDGVv7g4q0CnIV42L94XLIiqLe0EXLCIC8hL8+SVQCzVmv5K8Amw9irjpa8+l8kSpcO52O2zP9gry1SumPRBM5RiP523vl+bWzyOGc+4sWO4RNooOD6Se5y/M=" Jan 11 14:29:16 music go-librespot[25421]: time="2026-01-11T14:29:16-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Jan 11 14:29:17 music go-librespot[25421]: time="2026-01-11T14:29:17-05:00" level=debug msg="completed keyexchange" Jan 11 14:29:17 music go-librespot[25421]: time="2026-01-11T14:29:17-05:00" level=debug msg="completed challenge" Jan 11 14:29:17 music go-librespot[25421]: time="2026-01-11T14:29:17-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:29:17 music volumio[25405]: info: ------------------------------------------- Jan 11 14:29:17 music volumio[25405]: info: ----- Volumio3 ---- Jan 11 14:29:17 music volumio[25405]: info: ------------------------------------------- Jan 11 14:29:17 music volumio[25405]: info: ----- System startup ---- Jan 11 14:29:17 music volumio[25405]: info: ------------------------------------------- Jan 11 14:29:17 music go-librespot[25421]: time="2026-01-11T14:29:17-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Jan 11 14:29:17 music go-librespot[25421]: time="2026-01-11T14:29:17-05:00" level=debug msg="completed keyexchange" Jan 11 14:29:17 music go-librespot[25421]: time="2026-01-11T14:29:17-05:00" level=debug msg="completed challenge" Jan 11 14:29:17 music go-librespot[25421]: time="2026-01-11T14:29:17-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:29:17 music volumio[25405]: info: MYVOLUMIO Environment detected Jan 11 14:29:18 music volumio[25405]: info: Plugin folders cleanup Jan 11 14:29:18 music volumio[25405]: info: Scanning into folder /volumio/app/plugins/ Jan 11 14:29:18 music volumio[25405]: info: Scanning category audio_interface Jan 11 14:29:18 music volumio[25405]: info: Scanning category miscellanea Jan 11 14:29:18 music volumio[25405]: info: Scanning category music_service Jan 11 14:29:18 music volumio[25405]: info: Scanning category plugins.json Jan 11 14:29:18 music volumio[25405]: info: Scanning category system_controller Jan 11 14:29:18 music volumio[25405]: info: Scanning category user_interface Jan 11 14:29:18 music volumio[25405]: info: Scanning into folder /data/plugins/ Jan 11 14:29:18 music volumio[25405]: info: Scanning category music_service Jan 11 14:29:18 music volumio[25405]: info: Plugin folders cleanup completed Jan 11 14:29:18 music volumio[25405]: info: ------------------------------------------- Jan 11 14:29:18 music volumio[25405]: info: ----- Core plugins startup ---- Jan 11 14:29:18 music volumio[25405]: info: ------------------------------------------- Jan 11 14:29:18 music volumio[25405]: info: Loading plugins from folder /volumio/app/plugins/ Jan 11 14:29:18 music volumio[25405]: info: Adding plugin upnp to MyMusic Plugins Jan 11 14:29:18 music volumio[25405]: info: Adding plugin airplay_emulation to MyMusic Plugins Jan 11 14:29:18 music volumio[25405]: info: Adding plugin upnp_browser to MyMusic Plugins Jan 11 14:29:18 music volumio[25405]: info: Loading plugins from folder /data/plugins/ Jan 11 14:29:18 music volumio[25405]: info: Loading plugin "system"... Jan 11 14:29:18 music volumio[25405]: info: Loading plugin "appearance"... Jan 11 14:29:18 music go-librespot[25421]: time="2026-01-11T14:29:18-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Jan 11 14:29:18 music go-librespot[25421]: time="2026-01-11T14:29:18-05:00" level=debug msg="completed keyexchange" Jan 11 14:29:18 music go-librespot[25421]: time="2026-01-11T14:29:18-05:00" level=debug msg="completed challenge" Jan 11 14:29:18 music go-librespot[25421]: time="2026-01-11T14:29:18-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:29:19 music go-librespot[25421]: time="2026-01-11T14:29:19-05:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 11 14:29:19 music volumio[25405]: info: Loading plugin "network"... Jan 11 14:29:19 music go-librespot[25421]: time="2026-01-11T14:29:19-05:00" level=debug msg="completed keyexchange" Jan 11 14:29:19 music go-librespot[25421]: time="2026-01-11T14:29:19-05:00" level=debug msg="completed challenge" Jan 11 14:29:19 music volumio[25405]: info: Refreshing Cached IP Addresses Jan 11 14:29:19 music sudo[25443]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 11 14:29:19 music sudo[25443]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:29:19 music sudo[25445]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 11 14:29:19 music sudo[25445]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:29:19 music sudo[25443]: pam_unix(sudo:session): session closed for user root Jan 11 14:29:19 music volumio[25405]: info: Loading plugin "services"... Jan 11 14:29:19 music sudo[25445]: pam_unix(sudo:session): session closed for user root Jan 11 14:29:19 music go-librespot[25421]: time="2026-01-11T14:29:19-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:29:19 music volumio[25405]: info: Loading plugin "alsa_controller"... Jan 11 14:29:19 music sudo[25450]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Jan 11 14:29:19 music sudo[25450]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:29:19 music volumio[25405]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 11 14:29:19 music volumio[25405]: info: Loading plugin "wizard"... Jan 11 14:29:19 music volumio[25405]: info: Loading plugin "networkfs"... Jan 11 14:29:19 music volumio[25405]: info: Starting Udev Watcher for removable devices Jan 11 14:29:19 music volumio[25405]: info: Ignoring mount for partition: boot Jan 11 14:29:19 music volumio[25405]: info: Ignoring mount for partition: volumio Jan 11 14:29:19 music volumio[25405]: info: Ignoring mount for partition: volumio_data Jan 11 14:29:19 music volumio[25405]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 11 14:29:19 music volumio[25405]: info: Loading plugin "volumio_command_line_client"... Jan 11 14:29:19 music volumio[25405]: info: Loading plugin "upnp"... Jan 11 14:29:19 music volumio[25405]: info: [1768159759416] Starting Upmpd Daemon Jan 11 14:29:19 music volumio[25405]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 11 14:29:19 music volumio[25405]: info: Loading plugin "my_music"... Jan 11 14:29:19 music volumio[25405]: info: Loading plugin "mpd"... Jan 11 14:29:19 music volumio[25405]: info: Loading plugin "upnp_browser"... Jan 11 14:29:19 music volumio-remote-updater[22000]: [2026-01-11 14:29:19] [connect] Successful connection Jan 11 14:29:19 music sudo[25450]: pam_unix(sudo:session): session closed for user root Jan 11 14:29:19 music go-librespot[25421]: time="2026-01-11T14:29:19-05:00" level=debug msg="connected to ap-gae2.spotify.com:443" Jan 11 14:29:20 music go-librespot[25421]: time="2026-01-11T14:29:20-05:00" level=debug msg="completed keyexchange" Jan 11 14:29:20 music go-librespot[25421]: time="2026-01-11T14:29:20-05:00" level=debug msg="completed challenge" Jan 11 14:29:20 music go-librespot[25421]: time="2026-01-11T14:29:20-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:29:21 music go-librespot[25421]: time="2026-01-11T14:29:21-05:00" level=debug msg="connected to ap-gew1.spotify.com:80" Jan 11 14:29:21 music go-librespot[25421]: time="2026-01-11T14:29:21-05:00" level=debug msg="completed keyexchange" Jan 11 14:29:21 music go-librespot[25421]: time="2026-01-11T14:29:21-05:00" level=debug msg="completed challenge" Jan 11 14:29:21 music go-librespot[25421]: time="2026-01-11T14:29:21-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:29:21 music go-librespot[25421]: time="2026-01-11T14:29:21-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:29:21 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 11 14:29:21 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 11 14:29:21 music volumio[25405]: info: Starting UPNP Browser Jan 11 14:29:21 music volumio[25405]: info: Loading plugin "alarm-clock"... Jan 11 14:29:21 music volumio[25405]: info: Loading plugin "airplay_emulation"... Jan 11 14:29:21 music volumio[25405]: info: Starting Shairport Sync Jan 11 14:29:21 music volumio[25405]: info: Loading plugin "last_100"... Jan 11 14:29:21 music volumio[25405]: info: Loading plugin "webradio"... Jan 11 14:29:21 music volumio[25405]: info: Loading plugin "i2s_dacs"... Jan 11 14:29:21 music volumio[25405]: info: I2S DAC not set, start Auto-detection Jan 11 14:29:21 music volumio[25405]: info: Loading plugin "volumiodiscovery"... Jan 11 14:29:21 music volumio[25405]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jan 11 14:29:21 music volumio[25405]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 11 14:29:21 music volumio[25405]: *** WARNING *** For more information see Jan 11 14:29:21 music volumio[25405]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jan 11 14:29:21 music volumio[25405]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 11 14:29:21 music volumio[25405]: *** WARNING *** For more information see Jan 11 14:29:21 music node[25405]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jan 11 14:29:21 music node[25405]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 11 14:29:21 music node[25405]: *** WARNING *** For more information see Jan 11 14:29:21 music node[25405]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jan 11 14:29:21 music node[25405]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 11 14:29:21 music node[25405]: *** WARNING *** For more information see Jan 11 14:29:21 music volumio[25405]: info: Applying required configuration parameters for plugin volumiodiscovery Jan 11 14:29:21 music volumio[25405]: info: Discovery: Started advertising with name: music Jan 11 14:29:21 music volumio[25405]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 11 14:29:21 music volumio[25405]: info: Loading plugin "spop"... Jan 11 14:29:22 music volumio[25405]: info: Loading plugin "outputs"... Jan 11 14:29:22 music volumio[25405]: info: Loading plugin "albumart"... Jan 11 14:29:22 music volumio[25405]: info: Plugin example_plugin is not enabled Jan 11 14:29:22 music volumio[25405]: info: Loading plugin "inputs"... Jan 11 14:29:22 music volumio[25405]: info: Loading plugin "updater_comm"... Jan 11 14:29:22 music volumio[25405]: info: Plugin mpdemulation is not enabled Jan 11 14:29:22 music volumio[25405]: info: Loading plugin "rest_api"... Jan 11 14:29:22 music volumio[25405]: info: Loading plugin "websocket"... Jan 11 14:29:23 music volumio[25405]: info: Starting Socket.io Server version 1.7.4 Jan 11 14:29:23 music volumio[25405]: info: Loading i18n strings for locale en Jan 11 14:29:23 music volumio[25405]: Updating browse sources language Jan 11 14:29:23 music volumio[25405]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 11 14:29:23 music volumio[25405]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 11 14:29:23 music volumio[25405]: info: CoreCommandRouter::initPlayerControls Jan 11 14:29:23 music volumio[25405]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:29:23 music volumio[25405]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:29:23 music volumio[25405]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:29:23 music volumio[25405]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:29:23 music volumio[25405]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:29:23 music volumio[25405]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:29:23 music volumio[25405]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:29:23 music volumio[25405]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:29:23 music volumio[25405]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 11 14:29:23 music volumio[25405]: Express server listening on port 3000 Jan 11 14:29:23 music volumio[25405]: [Metrics] WebUI: 6s 599.28ms Jan 11 14:29:23 music volumio[25405]: info: CoreStateMachine::resetVolumioState Jan 11 14:29:23 music volumio[25405]: info: CoreStateMachine::getcurrentVolume Jan 11 14:29:23 music volumio[25405]: info: CoreCommandRouter::volumioRetrievevolume Jan 11 14:29:23 music volumio[25405]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 11 14:29:23 music volumio[25405]: info: Volumio Network Manager: Network status updated: 1 Jan 11 14:29:23 music volumio-remote-updater[22000]: [2026-01-11 14:29:23] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1768159759 101 Jan 11 14:29:23 music volumio[25478]: Forking 3 albumart workers Jan 11 14:29:23 music volumio[25405]: 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 11 14:29:23 music volumio[25405]: info: VolumeController:: Volume=86 Mute =false Jan 11 14:29:23 music volumio[25405]: info: CoreStateMachine::pushState Jan 11 14:29:23 music volumio[25405]: info: CorePlayQueue::getTrack 0 Jan 11 14:29:23 music volumio[25405]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 11 14:29:23 music volumio[25405]: info: CoreCommandRouter::volumioPushState Jan 11 14:29:23 music volumio[25405]: info: CoreStateMachine::updateTrackBlock Jan 11 14:29:23 music volumio[25405]: info: CorePlayQueue::getTrackBlock Jan 11 14:29:23 music volumio[25405]: info: CoreCommandRouter::volumioRetrievevolume Jan 11 14:29:23 music volumio[25405]: info: Reloading queue from file Jan 11 14:29:23 music volumio[25405]: info: CoreStateMachine::setRepeat null single undefined Jan 11 14:29:23 music volumio[25405]: info: CoreStateMachine::pushState Jan 11 14:29:23 music volumio[25405]: info: CorePlayQueue::getTrack 0 Jan 11 14:29:23 music volumio[25405]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 11 14:29:23 music volumio[25405]: info: CoreCommandRouter::volumioPushState Jan 11 14:29:23 music volumio[25405]: info: CoreStateMachine::setRandom null Jan 11 14:29:23 music volumio[25405]: info: CoreStateMachine::pushState Jan 11 14:29:23 music volumio[25405]: info: CorePlayQueue::getTrack 0 Jan 11 14:29:23 music volumio[25405]: info: CoreCommandRouter::volumioPushState Jan 11 14:29:23 music volumio[25405]: info: Setting Device type: Raspberry PI Jan 11 14:29:23 music volumio[25405]: info: VolumeController:: Volume=86 Mute =false Jan 11 14:29:23 music volumio[25405]: info: CoreStateMachine::pushState Jan 11 14:29:23 music volumio[25405]: info: CorePlayQueue::getTrack 0 Jan 11 14:29:23 music volumio[25405]: info: CoreCommandRouter::volumioPushState Jan 11 14:29:23 music volumio[25405]: info: Completed loading Core Plugins Jan 11 14:29:23 music volumio[25405]: info: Preparing to generate the ALSA configuration file Jan 11 14:29:23 music volumio[25405]: info: Discovery: adding 4a29b7a7-c637-4926-a2bd-fb4e2f55145e Jan 11 14:29:23 music volumio[25405]: info: Discovery: Found device music Jan 11 14:29:23 music volumio[25405]: info: CoreCommandRouter::volumioGetState Jan 11 14:29:23 music volumio[25405]: info: CorePlayQueue::getTrack 0 Jan 11 14:29:23 music volumio[25405]: info: Discovery: this is already registered, 4a29b7a7-c637-4926-a2bd-fb4e2f55145e Jan 11 14:29:23 music volumio[25405]: info: Discovery: Found device music Jan 11 14:29:23 music volumio[25405]: info: CoreCommandRouter::volumioGetState Jan 11 14:29:23 music volumio[25405]: info: CorePlayQueue::getTrack 0 Jan 11 14:29:23 music volumio[25405]: info: Asound.conf file unchanged, so no further update is needed Jan 11 14:29:23 music volumio[25405]: info: Output device has changed, restarting MPD Jan 11 14:29:23 music volumio[25405]: info: Output device has changed, restarting Shairport Sync Jan 11 14:29:23 music volumio[25405]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:29:23 music volumio[25405]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 11 14:29:23 music volumio[25405]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 11 14:29:23 music volumio[25405]: info: ___________ START PLUGINS ___________ Jan 11 14:29:23 music sudo[25533]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 11 14:29:23 music sudo[25533]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:29:23 music volumio[25405]: info: ControllerMpd::onStart: Initializing MPD Jan 11 14:29:23 music sudo[25533]: pam_unix(sudo:session): session closed for user root Jan 11 14:29:23 music volumio[25405]: info: Creating MPD Configuration file Jan 11 14:29:23 music sudo[25535]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 11 14:29:23 music sudo[25535]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:29:23 music volumio[25405]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 11 14:29:23 music volumio[25405]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 11 14:29:23 music volumio[25405]: info: [1768159763889] CoreMusicLibrary::Adding element Media Servers Jan 11 14:29:23 music volumio[25405]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 11 14:29:23 music sudo[25544]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 11 14:29:23 music sudo[25544]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:29:23 music sudo[25544]: pam_unix(sudo:session): session closed for user root Jan 11 14:29:23 music volumio[25405]: info: UPNP Browser: Client initialized successfully Jan 11 14:29:23 music sudo[25545]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 11 14:29:23 music sudo[25545]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:29:23 music systemd[1]: Stopping mpd.service - Music Player Daemon... Jan 11 14:29:24 music volumio[25405]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:29:24 music volumio[25405]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 11 14:29:24 music systemd[1]: mpd.service: Deactivated successfully. Jan 11 14:29:24 music systemd[1]: Stopped mpd.service - Music Player Daemon. Jan 11 14:29:24 music systemd[1]: mpd.service: Consumed 4.068s CPU time. Jan 11 14:29:24 music systemd[1]: mpd.socket: Deactivated successfully. Jan 11 14:29:24 music systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jan 11 14:29:24 music systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jan 11 14:29:24 music volumio[25405]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 11 14:29:24 music volumio[25405]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:29:24 music volumio[25405]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 11 14:29:24 music systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jan 11 14:29:24 music volumio[25405]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 11 14:29:24 music volumio[25405]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 11 14:29:24 music volumio[25405]: info: [1768159764114] CoreMusicLibrary::Adding element Last_100 Jan 11 14:29:24 music volumio[25405]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 11 14:29:24 music volumio[25405]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 11 14:29:24 music volumio[25405]: info: [1768159764122] CoreMusicLibrary::Adding element Webradio Jan 11 14:29:24 music systemd[1]: Starting mpd.service - Music Player Daemon... Jan 11 14:29:24 music volumio[25405]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 11 14:29:24 music volumio[25405]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 11 14:29:24 music volumio[25405]: info: Initializing BBC Radios Jan 11 14:29:24 music volumio[25405]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 11 14:29:24 music volumio[25405]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 11 14:29:24 music volumio[25405]: info: Creating Spotify config file Jan 11 14:29:24 music volumio[25405]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:29:24 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Jan 11 14:29:24 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 11 14:29:24 music sudo[25557]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jan 11 14:29:24 music sudo[25557]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Jan 11 14:29:24 music go-librespot[25571]: go-librespot daemon starting... Jan 11 14:29:24 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 11 14:29:24 music sudo[25557]: pam_unix(sudo:session): session closed for user root Jan 11 14:29:24 music go-librespot[25573]: time="2026-01-11T14:29:24-05:00" level=info msg="running go-librespot 0.6.2" Jan 11 14:29:24 music volumio[25405]: info: Volumio Calling Home Jan 11 14:29:24 music go-librespot[25573]: time="2026-01-11T14:29:24-05:00" level=info msg="zeroconf server listening on port 33429" Jan 11 14:29:25 music volumio[25405]: info: MPD Permissions set Jan 11 14:29:25 music volumio[25405]: info: MPD Permissions set Jan 11 14:29:25 music volumio[25405]: info: Spotify config file written Jan 11 14:29:25 music volumio[25405]: info: CoreCommandRouter::volumioGetState Jan 11 14:29:25 music volumio[25405]: info: CorePlayQueue::getTrack 0 Jan 11 14:29:25 music sudo[25587]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jan 11 14:29:25 music sudo[25587]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:29:25 music systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Jan 11 14:29:25 music volumio[25405]: 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 11 14:29:25 music systemd[1]: go-librespot-daemon.service: Deactivated successfully. Jan 11 14:29:25 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 11 14:29:25 music volumio[25405]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:29:25 music volumio[25405]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:29:25 music volumio[25405]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:29:25 music volumio[25405]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:29:25 music volumio[25405]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:29:25 music volumio[25405]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:29:25 music volumio[25405]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:29:25 music volumio[25405]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:29:25 music volumio[25405]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 11 14:29:25 music volumio[25405]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:29:25 music volumio[25405]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:29:25 music volumio[25405]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:29:25 music volumio[25405]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:29:25 music volumio[25405]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:29:25 music volumio[25405]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:29:25 music volumio[25405]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:29:25 music volumio[25405]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:29:25 music volumio[25405]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:29:25 music volumio[25405]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 11 14:29:25 music volumio[25405]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:29:25 music volumio[25405]: info: No need to fix Spotify hosts Jan 11 14:29:25 music go-librespot[25590]: go-librespot daemon starting... Jan 11 14:29:25 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 11 14:29:25 music sudo[25587]: pam_unix(sudo:session): session closed for user root Jan 11 14:29:25 music go-librespot[25600]: time="2026-01-11T14:29:25-05:00" level=info msg="running go-librespot 0.6.2" Jan 11 14:29:25 music go-librespot[25600]: time="2026-01-11T14:29:25-05:00" level=debug msg="app state loaded" Jan 11 14:29:25 music volumio[25496]: Starting albumart workers Jan 11 14:29:25 music go-librespot[25600]: time="2026-01-11T14:29:25-05:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 11 14:29:25 music volumio[25495]: Starting albumart workers Jan 11 14:29:25 music volumio[25494]: Starting albumart workers Jan 11 14:29:26 music volumio[25405]: info: Volumio called home Jan 11 14:29:26 music volumio[25405]: info: Listing playlists Jan 11 14:29:26 music volumio[25405]: info: Listing playlists Jan 11 14:29:26 music go-librespot[25600]: time="2026-01-11T14:29:26-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew1.spotify.com:80]" Jan 11 14:29:26 music go-librespot[25600]: time="2026-01-11T14:29:26-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Jan 11 14:29:26 music go-librespot[25600]: time="2026-01-11T14:29:26-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Jan 11 14:29:26 music go-librespot[25600]: time="2026-01-11T14:29:26-05:00" level=info msg="zeroconf server listening on port 40849" Jan 11 14:29:26 music volumio[25405]: info: Starting Shairport Sync Jan 11 14:29:26 music volumio[25405]: info: Starting Shairport Sync Jan 11 14:29:26 music volumio[25405]: info: Starting Shairport Sync Jan 11 14:29:26 music go-librespot[25600]: time="2026-01-11T14:29:26-05:00" level=debug msg="obtained new client token: AAD3Gu92u4t2Al41FqHgQ8v2nAa0QII8W0HWI91dbG6RuASppiQT1g+6BAC1qtJb1hexNAK/zSVCEiWXJ6QTR7HWp/FNP2OIQst0c4GQAUyjAuhTjDQzvTJa5qlpL1WAk5c/+8FENTQthCqiYuLFZL9UvAEj7mvEHoKmPUtLiWYDoDoi5ZNSSiYLkZWFTd7qBDyN6+qT+uQmnmormzoNvasc/bLuJ49f5XR4rEwaE7rCTPxeRu/b80M=" Jan 11 14:29:26 music sudo[25613]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 11 14:29:26 music sudo[25613]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:29:26 music sudo[25615]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 11 14:29:26 music go-librespot[25600]: time="2026-01-11T14:29:26-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Jan 11 14:29:26 music sudo[25615]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:29:26 music systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jan 11 14:29:26 music systemd[1]: shairport-sync.service: Deactivated successfully. Jan 11 14:29:26 music volumio[25405]: info: An error occurred while refreshing Spotify Token Error: Bad Request Jan 11 14:29:26 music systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 11 14:29:26 music systemd[1]: shairport-sync.service: Consumed 1.797s CPU time. Jan 11 14:29:26 music go-librespot[25600]: time="2026-01-11T14:29:26-05:00" level=debug msg="completed keyexchange" Jan 11 14:29:26 music go-librespot[25600]: time="2026-01-11T14:29:26-05:00" level=debug msg="completed challenge" Jan 11 14:29:26 music sudo[25618]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 11 14:29:26 music sudo[25618]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:29:26 music go-librespot[25600]: time="2026-01-11T14:29:26-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:29:26 music systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 11 14:29:26 music sudo[25613]: pam_unix(sudo:session): session closed for user root Jan 11 14:29:26 music systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jan 11 14:29:26 music systemd[1]: shairport-sync.service: Deactivated successfully. Jan 11 14:29:26 music systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 11 14:29:26 music systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 11 14:29:26 music sudo[25615]: pam_unix(sudo:session): session closed for user root Jan 11 14:29:26 music sudo[25618]: pam_unix(sudo:session): session closed for user root Jan 11 14:29:27 music volumio[25405]: info: Shairport-Sync Started Jan 11 14:29:27 music volumio[25405]: Error adding Membership: Error: addMembership EINVAL Jan 11 14:29:27 music volumio[25405]: info: Shairport-Sync Started Jan 11 14:29:27 music volumio[25405]: info: Shairport-Sync Started Jan 11 14:29:27 music volumio[25405]: info: CoreCommandRouter::volumioGetState Jan 11 14:29:27 music volumio[25405]: info: CorePlayQueue::getTrack 0 Jan 11 14:29:27 music go-librespot[25600]: time="2026-01-11T14:29:27-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Jan 11 14:29:27 music go-librespot[25600]: time="2026-01-11T14:29:27-05:00" level=debug msg="completed keyexchange" Jan 11 14:29:27 music go-librespot[25600]: time="2026-01-11T14:29:27-05:00" level=debug msg="completed challenge" Jan 11 14:29:27 music go-librespot[25600]: time="2026-01-11T14:29:27-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:29:28 music go-librespot[25600]: time="2026-01-11T14:29:28-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Jan 11 14:29:28 music go-librespot[25600]: time="2026-01-11T14:29:28-05:00" level=debug msg="completed keyexchange" Jan 11 14:29:28 music go-librespot[25600]: time="2026-01-11T14:29:28-05:00" level=debug msg="completed challenge" Jan 11 14:29:28 music go-librespot[25600]: time="2026-01-11T14:29:28-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:29:28 music mpd[25579]: 2026-01-11T14:29:28 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jan 11 14:29:28 music systemd[1]: Started mpd.service - Music Player Daemon. Jan 11 14:29:28 music sudo[25535]: pam_unix(sudo:session): session closed for user root Jan 11 14:29:28 music sudo[25545]: pam_unix(sudo:session): session closed for user root Jan 11 14:29:28 music volumio[25405]: info: Completed starting Core Plugins Jan 11 14:29:28 music volumio[25405]: info: ------------------------------------------- Jan 11 14:29:28 music volumio[25405]: info: ----- MyVolumio plugins startup ---- Jan 11 14:29:28 music volumio[25405]: info: ------------------------------------------- Jan 11 14:29:28 music volumio[25405]: info: [MyVolumio PluginManager] Fetching plans data.... Jan 11 14:29:28 music volumio[25405]: error: MPD error: The expression evaluated to a falsy value: Jan 11 14:29:28 music volumio[25405]: assert.ok(self.idling) Jan 11 14:29:28 music volumio[25405]: error: The expression evaluated to a falsy value: Jan 11 14:29:28 music volumio[25405]: assert.ok(self.idling) Jan 11 14:29:28 music volumio[25405]: info: MPD running with PID25579 Jan 11 14:29:28 music volumio[25405]: ,establishing connection Jan 11 14:29:28 music volumio[25405]: error: updateQueue error: null Jan 11 14:29:28 music volumio[25405]: error: updateQueue error: null Jan 11 14:29:28 music go-librespot[25600]: time="2026-01-11T14:29:28-05:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 11 14:29:28 music go-librespot[25600]: time="2026-01-11T14:29:28-05:00" level=debug msg="completed keyexchange" Jan 11 14:29:28 music go-librespot[25600]: time="2026-01-11T14:29:28-05:00" level=debug msg="completed challenge" Jan 11 14:29:28 music go-librespot[25600]: time="2026-01-11T14:29:28-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:29:29 music volumio[25405]: info: go-librespot daemon successfully initialized Jan 11 14:29:29 music sudo[25675]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 11 14:29:29 music sudo[25675]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:29:29 music sudo[25675]: pam_unix(sudo:session): session closed for user root Jan 11 14:29:29 music sudo[25677]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 11 14:29:29 music sudo[25677]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:29:29 music sudo[25677]: pam_unix(sudo:session): session closed for user root Jan 11 14:29:29 music sudo[25680]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Jan 11 14:29:29 music sudo[25680]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:29:29 music sudo[25680]: pam_unix(sudo:session): session closed for user root Jan 11 14:29:29 music volumio[25405]: info: Upmpdcli Daemon Started Jan 11 14:29:29 music go-librespot[25600]: time="2026-01-11T14:29:29-05:00" level=debug msg="connected to ap-gae2.spotify.com:443" Jan 11 14:29:29 music go-librespot[25600]: time="2026-01-11T14:29:29-05:00" level=debug msg="completed keyexchange" Jan 11 14:29:29 music go-librespot[25600]: time="2026-01-11T14:29:29-05:00" level=debug msg="completed challenge" Jan 11 14:29:29 music go-librespot[25600]: time="2026-01-11T14:29:29-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:29:30 music go-librespot[25600]: time="2026-01-11T14:29:30-05:00" level=debug msg="connected to ap-gew1.spotify.com:80" Jan 11 14:29:30 music go-librespot[25600]: time="2026-01-11T14:29:30-05:00" level=debug msg="completed keyexchange" Jan 11 14:29:30 music go-librespot[25600]: time="2026-01-11T14:29:30-05:00" level=debug msg="completed challenge" Jan 11 14:29:30 music go-librespot[25600]: time="2026-01-11T14:29:30-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:29:30 music go-librespot[25600]: time="2026-01-11T14:29:30-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:29:30 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 11 14:29:30 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 11 14:29:31 music sudo[25684]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Jan 11 14:29:31 music sudo[25684]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:29:31 music sudo[25686]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Jan 11 14:29:31 music sudo[25686]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:29:31 music systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Jan 11 14:29:31 music systemd[1]: mpd_monitor.service: Deactivated successfully. Jan 11 14:29:31 music systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Jan 11 14:29:31 music systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Jan 11 14:29:31 music mpd_monitor.sh[25689]: MPD Monitor Service: Starting MPD Monitor Service Jan 11 14:29:31 music sudo[25686]: pam_unix(sudo:session): session closed for user root Jan 11 14:29:31 music sudo[25684]: pam_unix(sudo:session): session closed for user root Jan 11 14:29:31 music volumio[25405]: info: Successfully started MPD Monitor Jan 11 14:29:31 music volumio[25405]: info: Successfully started MPD Monitor Jan 11 14:29:32 music volumio[25405]: info: Initializing connection to go-librespot Websocket Jan 11 14:29:32 music volumio[25405]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 11 14:29:33 music volumio[25405]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Jan 11 14:29:34 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Jan 11 14:29:34 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 11 14:29:34 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 11 14:29:34 music go-librespot[25693]: go-librespot daemon starting... Jan 11 14:29:34 music go-librespot[25694]: time="2026-01-11T14:29:34-05:00" level=info msg="running go-librespot 0.6.2" Jan 11 14:29:34 music go-librespot[25694]: time="2026-01-11T14:29:34-05:00" level=debug msg="app state loaded" Jan 11 14:29:34 music go-librespot[25694]: time="2026-01-11T14:29:34-05:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 11 14:29:34 music go-librespot[25694]: time="2026-01-11T14:29:34-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew4.spotify.com:80]" Jan 11 14:29:34 music go-librespot[25694]: time="2026-01-11T14:29:34-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 11 14:29:34 music go-librespot[25694]: time="2026-01-11T14:29:34-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 11 14:29:34 music go-librespot[25694]: time="2026-01-11T14:29:34-05:00" level=info msg="zeroconf server listening on port 43903" Jan 11 14:29:34 music go-librespot[25694]: time="2026-01-11T14:29:34-05:00" level=debug msg="obtained new client token: AABrLE6TtWRfUCloSdyOd1o9QKxZVY7jnf9n5gSAnfp4Hgv1VyRCp8fa5DvfrZy12gyeClTMpHpXaUuNG5Ct44Y8eJsqqNtGGlW+d1F1+8Lqp6rhi9346hF9st0HnLJckJ2W5a8JkabamjcJ9Da0hTflROON11+7ZRcU3BETOo4btVJbqtK2vzxvqXU43KUpRpVVygcGajhCCkilqvu30fJejQKQ2GzYcJSbnOZwHyJgQ1iDNVprDQE=" Jan 11 14:29:34 music go-librespot[25694]: time="2026-01-11T14:29:34-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Jan 11 14:29:34 music go-librespot[25694]: time="2026-01-11T14:29:34-05:00" level=debug msg="completed keyexchange" Jan 11 14:29:34 music go-librespot[25694]: time="2026-01-11T14:29:34-05:00" level=debug msg="completed challenge" Jan 11 14:29:34 music go-librespot[25694]: time="2026-01-11T14:29:34-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:29:34 music volumio[25405]: info: CoreCommandRouter::volumioGetState Jan 11 14:29:34 music volumio[25405]: info: CorePlayQueue::getTrack 0 Jan 11 14:29:35 music volumio[25405]: info: Initializing connection to go-librespot Websocket Jan 11 14:29:35 music go-librespot[25694]: time="2026-01-11T14:29:35-05:00" level=debug msg="new websocket client" Jan 11 14:29:35 music volumio[25405]: info: Connection to go-librespot Websocket established Jan 11 14:29:35 music go-librespot[25694]: time="2026-01-11T14:29:35-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Jan 11 14:29:35 music go-librespot[25694]: time="2026-01-11T14:29:35-05:00" level=debug msg="completed keyexchange" Jan 11 14:29:35 music go-librespot[25694]: time="2026-01-11T14:29:35-05:00" level=debug msg="completed challenge" Jan 11 14:29:35 music go-librespot[25694]: time="2026-01-11T14:29:35-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:29:36 music go-librespot[25694]: time="2026-01-11T14:29:36-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Jan 11 14:29:36 music go-librespot[25694]: time="2026-01-11T14:29:36-05:00" level=debug msg="completed keyexchange" Jan 11 14:29:36 music go-librespot[25694]: time="2026-01-11T14:29:36-05:00" level=debug msg="completed challenge" Jan 11 14:29:36 music go-librespot[25694]: time="2026-01-11T14:29:36-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:29:36 music go-librespot[25694]: time="2026-01-11T14:29:36-05: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 11 14:29:36 music volumio[25405]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Jan 11 14:29:36 music volumio[25405]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Jan 11 14:29:36 music volumio[25405]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Jan 11 14:29:36 music volumio[25405]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Jan 11 14:29:36 music volumio[25405]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Jan 11 14:29:36 music volumio[25405]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Jan 11 14:29:36 music volumio[25405]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Jan 11 14:29:36 music volumio[25405]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Jan 11 14:29:36 music volumio[25405]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Jan 11 14:29:36 music volumio[25405]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Jan 11 14:29:36 music volumio[25405]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Jan 11 14:29:36 music volumio[25405]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Jan 11 14:29:36 music volumio[25405]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Jan 11 14:29:36 music volumio[25405]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Jan 11 14:29:36 music volumio[25405]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Jan 11 14:29:36 music volumio[25405]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Jan 11 14:29:36 music volumio[25405]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Jan 11 14:29:36 music volumio[25405]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Jan 11 14:29:36 music volumio[25405]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Jan 11 14:29:36 music volumio[25405]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Jan 11 14:29:36 music volumio[25405]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Jan 11 14:29:36 music volumio[25405]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Jan 11 14:29:36 music volumio[25405]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Jan 11 14:29:36 music volumio[25405]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Jan 11 14:29:36 music volumio[25405]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Jan 11 14:29:36 music volumio[25405]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Jan 11 14:29:36 music volumio[25405]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Jan 11 14:29:36 music volumio[25405]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Jan 11 14:29:36 music volumio[25405]: info: Adding plugin bluetooth to MyMusic Plugins Jan 11 14:29:36 music volumio[25405]: info: Adding plugin multiroom to MyMusic Plugins Jan 11 14:29:36 music volumio[25405]: info: Adding plugin metavolumio to MyMusic Plugins Jan 11 14:29:36 music volumio[25405]: info: Adding plugin cd_controller to MyMusic Plugins Jan 11 14:29:36 music volumio[25405]: info: Adding plugin qobuzconnect to MyMusic Plugins Jan 11 14:29:36 music volumio[25405]: info: Adding plugin smart_inputs to MyMusic Plugins Jan 11 14:29:36 music volumio[25405]: info: Adding plugin tidalconnect to MyMusic Plugins Jan 11 14:29:36 music volumio[25405]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Jan 11 14:29:37 music go-librespot[25694]: time="2026-01-11T14:29:37-05:00" level=debug msg="connected to ap-gae2.spotify.com:443" Jan 11 14:29:37 music go-librespot[25694]: time="2026-01-11T14:29:37-05:00" level=debug msg="completed keyexchange" Jan 11 14:29:37 music go-librespot[25694]: time="2026-01-11T14:29:37-05:00" level=debug msg="completed challenge" Jan 11 14:29:37 music go-librespot[25694]: time="2026-01-11T14:29:37-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:29:38 music volumio[25405]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Jan 11 14:29:38 music volumio[25405]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Jan 11 14:29:38 music volumio[25405]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 11 14:29:38 music volumio[25405]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 11 14:29:38 music go-librespot[25694]: time="2026-01-11T14:29:38-05:00" level=debug msg="connected to ap-gew4.spotify.com:80" Jan 11 14:29:38 music volumio[25405]: info: Starting MyVolumio Remote Streaming Endpoints Jan 11 14:29:38 music volumio[25405]: info: MyVolumio login type: Token Jan 11 14:29:38 music volumio[25405]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Jan 11 14:29:38 music volumio[25405]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Jan 11 14:29:38 music go-librespot[25694]: time="2026-01-11T14:29:38-05:00" level=debug msg="completed keyexchange" Jan 11 14:29:38 music go-librespot[25694]: time="2026-01-11T14:29:38-05:00" level=debug msg="completed challenge" Jan 11 14:29:38 music go-librespot[25694]: time="2026-01-11T14:29:38-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:29:38 music go-librespot[25694]: time="2026-01-11T14:29:38-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Jan 11 14:29:38 music go-librespot[25694]: time="2026-01-11T14:29:38-05:00" level=debug msg="completed keyexchange" Jan 11 14:29:38 music go-librespot[25694]: time="2026-01-11T14:29:38-05:00" level=debug msg="completed challenge" Jan 11 14:29:38 music go-librespot[25694]: time="2026-01-11T14:29:38-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:29:38 music go-librespot[25694]: time="2026-01-11T14:29:38-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:29:38 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 11 14:29:38 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 11 14:29:39 music volumio[25405]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Jan 11 14:29:39 music volumio[25405]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Jan 11 14:29:39 music volumio[25405]: info: Streaming services startup Jan 11 14:29:39 music volumio[25405]: info: Starting Streaming Daemon Jan 11 14:29:39 music sudo[25704]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Jan 11 14:29:39 music sudo[25704]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:29:39 music volumio[25405]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Jan 11 14:29:39 music sudo[25704]: pam_unix(sudo:session): session closed for user root Jan 11 14:29:39 music volumio[25405]: info: Getting Spotify volume Jan 11 14:29:39 music volumio[25405]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 11 14:29:39 music volumio[25405]: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 11 14:29:39 music volumio[25405]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Jan 11 14:29:39 music volumio[25405]: errno: -111, Jan 11 14:29:39 music volumio[25405]: code: 'ECONNREFUSED', Jan 11 14:29:39 music volumio[25405]: syscall: 'connect', Jan 11 14:29:39 music volumio[25405]: address: '127.0.0.1', Jan 11 14:29:39 music volumio[25405]: port: 9879, Jan 11 14:29:39 music volumio[25405]: response: undefined Jan 11 14:29:39 music volumio[25405]: } Jan 11 14:29:39 music volumio[25405]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 11 14:29:39 music sudo[25739]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-01-11 14:28' Jan 11 14:29:39 music sudo[25739]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:29:40 music sudo[25739]: pam_unix(sudo:session): session closed for user root Jan 11 14:29:40 music volumio-remote-updater[22000]: [2026-01-11 14:29:40] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Jan 11 14:29:40 music volumio-remote-updater[22000]: [2026-01-11 14:29:40] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Jan 11 14:29:40 music systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Jan 11 14:29:40 music systemd[1]: volumio.service: Failed with result 'exit-code'. Jan 11 14:29:40 music systemd[1]: volumio.service: Consumed 26.367s CPU time. Jan 11 14:29:40 music systemd[1]: Started dynamicswap.service - dynamicswap service. Jan 11 14:29:40 music systemd[1]: dynamicswap.service: Deactivated successfully. Jan 11 14:29:40 music systemd[1]: volumio.service: Scheduled restart job, restart counter is at 5274. Jan 11 14:29:40 music systemd[1]: Started dynamicswap.service - dynamicswap service. Jan 11 14:29:40 music systemd[1]: Stopped volumio.service - Volumio Backend Module. Jan 11 14:29:40 music systemd[1]: volumio.service: Consumed 26.367s CPU time. Jan 11 14:29:40 music systemd[1]: Started volumio.service - Volumio Backend Module. Jan 11 14:29:40 music systemd[1]: dynamicswap.service: Deactivated successfully. Jan 11 14:29:42 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Jan 11 14:29:42 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 11 14:29:42 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 11 14:29:42 music go-librespot[25766]: go-librespot daemon starting... Jan 11 14:29:42 music go-librespot[25767]: time="2026-01-11T14:29:42-05:00" level=info msg="running go-librespot 0.6.2" Jan 11 14:29:42 music go-librespot[25767]: time="2026-01-11T14:29:42-05:00" level=debug msg="app state loaded" Jan 11 14:29:42 music go-librespot[25767]: time="2026-01-11T14:29:42-05:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 11 14:29:42 music volumio[25751]: info: ------------------------------------------- Jan 11 14:29:42 music volumio[25751]: info: ----- Volumio3 ---- Jan 11 14:29:42 music volumio[25751]: info: ------------------------------------------- Jan 11 14:29:42 music volumio[25751]: info: ----- System startup ---- Jan 11 14:29:42 music volumio[25751]: info: ------------------------------------------- Jan 11 14:29:42 music go-librespot[25767]: time="2026-01-11T14:29:42-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 11 14:29:42 music go-librespot[25767]: time="2026-01-11T14:29:42-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 11 14:29:42 music go-librespot[25767]: time="2026-01-11T14:29:42-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 11 14:29:42 music go-librespot[25767]: time="2026-01-11T14:29:42-05:00" level=info msg="zeroconf server listening on port 34377" Jan 11 14:29:42 music go-librespot[25767]: time="2026-01-11T14:29:42-05:00" level=debug msg="obtained new client token: AABYZ18EEbS+KYy6UHfeabM73M7mIdIIlOI5vG0awkPtqhCrSEohIF1102mLKYaWA0TtPietKt2/sXCLxaTgswR1MH7uNERzwjSgw9tOTCyYR+oVDeKIRUHeCaWTNrhcYLNHkGNx2gp+HX1hhXyIppMdt8FXga03miFBV88SiTkHyNKbRgFeknUeywlMmX0KAachLV01IPxoYxtZ5vVp/m1kMw/67j1kfSLkwAXhOVBWVflO86HcLlQ=" Jan 11 14:29:42 music go-librespot[25767]: time="2026-01-11T14:29:42-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Jan 11 14:29:42 music go-librespot[25767]: time="2026-01-11T14:29:42-05:00" level=debug msg="completed keyexchange" Jan 11 14:29:42 music go-librespot[25767]: time="2026-01-11T14:29:42-05:00" level=debug msg="completed challenge" Jan 11 14:29:42 music go-librespot[25767]: time="2026-01-11T14:29:42-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:29:43 music volumio[25751]: info: MYVOLUMIO Environment detected Jan 11 14:29:43 music volumio[25751]: info: Plugin folders cleanup Jan 11 14:29:43 music volumio[25751]: info: Scanning into folder /volumio/app/plugins/ Jan 11 14:29:43 music volumio[25751]: info: Scanning category audio_interface Jan 11 14:29:43 music volumio[25751]: info: Scanning category miscellanea Jan 11 14:29:43 music volumio[25751]: info: Scanning category music_service Jan 11 14:29:43 music volumio[25751]: info: Scanning category plugins.json Jan 11 14:29:43 music volumio[25751]: info: Scanning category system_controller Jan 11 14:29:43 music volumio[25751]: info: Scanning category user_interface Jan 11 14:29:43 music volumio[25751]: info: Scanning into folder /data/plugins/ Jan 11 14:29:43 music volumio[25751]: info: Scanning category music_service Jan 11 14:29:43 music volumio[25751]: info: Plugin folders cleanup completed Jan 11 14:29:43 music volumio[25751]: info: ------------------------------------------- Jan 11 14:29:43 music volumio[25751]: info: ----- Core plugins startup ---- Jan 11 14:29:43 music volumio[25751]: info: ------------------------------------------- Jan 11 14:29:43 music volumio[25751]: info: Loading plugins from folder /volumio/app/plugins/ Jan 11 14:29:43 music volumio[25751]: info: Adding plugin upnp to MyMusic Plugins Jan 11 14:29:43 music volumio[25751]: info: Adding plugin airplay_emulation to MyMusic Plugins Jan 11 14:29:43 music volumio[25751]: info: Adding plugin upnp_browser to MyMusic Plugins Jan 11 14:29:43 music volumio[25751]: info: Loading plugins from folder /data/plugins/ Jan 11 14:29:43 music volumio[25751]: info: Loading plugin "system"... Jan 11 14:29:43 music volumio[25751]: info: Loading plugin "appearance"... Jan 11 14:29:43 music go-librespot[25767]: time="2026-01-11T14:29:43-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Jan 11 14:29:43 music go-librespot[25767]: time="2026-01-11T14:29:43-05:00" level=debug msg="completed keyexchange" Jan 11 14:29:43 music go-librespot[25767]: time="2026-01-11T14:29:43-05:00" level=debug msg="completed challenge" Jan 11 14:29:43 music go-librespot[25767]: time="2026-01-11T14:29:43-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:29:44 music go-librespot[25767]: time="2026-01-11T14:29:44-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Jan 11 14:29:44 music go-librespot[25767]: time="2026-01-11T14:29:44-05:00" level=debug msg="completed keyexchange" Jan 11 14:29:44 music go-librespot[25767]: time="2026-01-11T14:29:44-05:00" level=debug msg="completed challenge" Jan 11 14:29:44 music go-librespot[25767]: time="2026-01-11T14:29:44-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:29:44 music volumio[25751]: info: Loading plugin "network"... Jan 11 14:29:44 music volumio[25751]: info: Refreshing Cached IP Addresses Jan 11 14:29:44 music sudo[25789]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 11 14:29:44 music sudo[25789]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:29:44 music sudo[25789]: pam_unix(sudo:session): session closed for user root Jan 11 14:29:44 music sudo[25791]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 11 14:29:44 music sudo[25791]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:29:44 music volumio[25751]: info: Loading plugin "services"... Jan 11 14:29:44 music volumio[25751]: info: Loading plugin "alsa_controller"... Jan 11 14:29:44 music sudo[25791]: pam_unix(sudo:session): session closed for user root Jan 11 14:29:44 music sudo[25799]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Jan 11 14:29:44 music sudo[25799]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:29:44 music volumio[25751]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 11 14:29:44 music volumio[25751]: info: Loading plugin "wizard"... Jan 11 14:29:44 music volumio[25751]: info: Loading plugin "networkfs"... Jan 11 14:29:44 music volumio[25751]: info: Starting Udev Watcher for removable devices Jan 11 14:29:44 music volumio[25751]: info: Ignoring mount for partition: boot Jan 11 14:29:44 music volumio[25751]: info: Ignoring mount for partition: volumio Jan 11 14:29:44 music volumio[25751]: info: Ignoring mount for partition: volumio_data Jan 11 14:29:44 music volumio[25751]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 11 14:29:44 music volumio[25751]: info: Loading plugin "volumio_command_line_client"... Jan 11 14:29:44 music volumio[25751]: info: Loading plugin "upnp"... Jan 11 14:29:44 music volumio[25751]: info: [1768159784739] Starting Upmpd Daemon Jan 11 14:29:44 music volumio[25751]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 11 14:29:44 music volumio[25751]: info: Loading plugin "my_music"... Jan 11 14:29:44 music volumio[25751]: info: Loading plugin "mpd"... Jan 11 14:29:44 music go-librespot[25767]: time="2026-01-11T14:29:44-05:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 11 14:29:44 music go-librespot[25767]: time="2026-01-11T14:29:44-05:00" level=debug msg="completed keyexchange" Jan 11 14:29:44 music go-librespot[25767]: time="2026-01-11T14:29:44-05:00" level=debug msg="completed challenge" Jan 11 14:29:45 music volumio[25751]: info: Loading plugin "upnp_browser"... Jan 11 14:29:45 music go-librespot[25767]: time="2026-01-11T14:29:45-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:29:45 music sudo[25799]: pam_unix(sudo:session): session closed for user root Jan 11 14:29:45 music volumio-remote-updater[22000]: [2026-01-11 14:29:45] [connect] Successful connection Jan 11 14:29:45 music go-librespot[25767]: time="2026-01-11T14:29:45-05:00" level=debug msg="connected to ap-gew1.spotify.com:443" Jan 11 14:29:45 music go-librespot[25767]: time="2026-01-11T14:29:45-05:00" level=debug msg="completed keyexchange" Jan 11 14:29:45 music go-librespot[25767]: time="2026-01-11T14:29:45-05:00" level=debug msg="completed challenge" Jan 11 14:29:46 music go-librespot[25767]: time="2026-01-11T14:29:46-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:29:46 music volumio[25751]: info: Starting UPNP Browser Jan 11 14:29:46 music volumio[25751]: info: Loading plugin "alarm-clock"... Jan 11 14:29:46 music go-librespot[25767]: time="2026-01-11T14:29:46-05:00" level=debug msg="connected to ap-gew4.spotify.com:80" Jan 11 14:29:46 music go-librespot[25767]: time="2026-01-11T14:29:46-05:00" level=debug msg="completed keyexchange" Jan 11 14:29:46 music go-librespot[25767]: time="2026-01-11T14:29:46-05:00" level=debug msg="completed challenge" Jan 11 14:29:46 music volumio[25751]: info: Loading plugin "airplay_emulation"... Jan 11 14:29:46 music volumio[25751]: info: Starting Shairport Sync Jan 11 14:29:46 music volumio[25751]: info: Loading plugin "last_100"... Jan 11 14:29:46 music volumio[25751]: info: Loading plugin "webradio"... Jan 11 14:29:46 music go-librespot[25767]: time="2026-01-11T14:29:46-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:29:46 music go-librespot[25767]: time="2026-01-11T14:29:46-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:29:46 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 11 14:29:46 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 11 14:29:46 music volumio[25751]: info: Loading plugin "i2s_dacs"... Jan 11 14:29:46 music volumio[25751]: info: I2S DAC not set, start Auto-detection Jan 11 14:29:46 music volumio[25751]: info: Loading plugin "volumiodiscovery"... Jan 11 14:29:47 music volumio[25751]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jan 11 14:29:47 music volumio[25751]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 11 14:29:47 music volumio[25751]: *** WARNING *** For more information see Jan 11 14:29:47 music volumio[25751]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jan 11 14:29:47 music volumio[25751]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 11 14:29:47 music volumio[25751]: *** WARNING *** For more information see Jan 11 14:29:47 music node[25751]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jan 11 14:29:47 music node[25751]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 11 14:29:47 music node[25751]: *** WARNING *** For more information see Jan 11 14:29:47 music node[25751]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jan 11 14:29:47 music node[25751]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 11 14:29:47 music node[25751]: *** WARNING *** For more information see Jan 11 14:29:47 music volumio[25751]: info: Applying required configuration parameters for plugin volumiodiscovery Jan 11 14:29:47 music volumio[25751]: info: Discovery: Started advertising with name: music Jan 11 14:29:47 music volumio[25751]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 11 14:29:47 music volumio[25751]: info: Loading plugin "spop"... Jan 11 14:29:48 music volumio[25751]: info: Loading plugin "outputs"... Jan 11 14:29:48 music volumio[25751]: info: Loading plugin "albumart"... Jan 11 14:29:48 music volumio[25751]: info: Plugin example_plugin is not enabled Jan 11 14:29:48 music volumio[25751]: info: Loading plugin "inputs"... Jan 11 14:29:48 music volumio[25751]: info: Loading plugin "updater_comm"... Jan 11 14:29:48 music volumio[25751]: info: Plugin mpdemulation is not enabled Jan 11 14:29:48 music volumio[25751]: info: Loading plugin "rest_api"... Jan 11 14:29:48 music volumio[25751]: info: Loading plugin "websocket"... Jan 11 14:29:48 music volumio[25751]: info: Starting Socket.io Server version 1.7.4 Jan 11 14:29:48 music volumio[25751]: info: Loading i18n strings for locale en Jan 11 14:29:48 music volumio[25751]: Updating browse sources language Jan 11 14:29:48 music volumio[25751]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 11 14:29:48 music volumio[25751]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 11 14:29:48 music volumio[25751]: info: CoreCommandRouter::initPlayerControls Jan 11 14:29:48 music volumio[25751]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:29:48 music volumio[25751]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:29:48 music volumio[25751]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:29:48 music volumio[25751]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:29:48 music volumio[25751]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:29:48 music volumio[25751]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:29:48 music volumio[25751]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:29:48 music volumio[25751]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:29:48 music volumio[25751]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 11 14:29:48 music volumio[25751]: Express server listening on port 3000 Jan 11 14:29:48 music volumio[25751]: [Metrics] WebUI: 6s 671.39ms Jan 11 14:29:48 music volumio[25751]: info: CoreStateMachine::resetVolumioState Jan 11 14:29:48 music volumio[25751]: info: CoreStateMachine::getcurrentVolume Jan 11 14:29:48 music volumio[25751]: info: CoreCommandRouter::volumioRetrievevolume Jan 11 14:29:48 music volumio[25751]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 11 14:29:48 music volumio[25751]: info: Volumio Network Manager: Network status updated: 1 Jan 11 14:29:48 music volumio[25751]: info: VolumeController:: Volume=86 Mute =false Jan 11 14:29:48 music volumio[25751]: info: CoreStateMachine::pushState Jan 11 14:29:48 music volumio[25751]: info: CorePlayQueue::getTrack 0 Jan 11 14:29:48 music volumio[25751]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 11 14:29:48 music volumio[25751]: info: CoreCommandRouter::volumioPushState Jan 11 14:29:48 music volumio[25751]: info: CoreStateMachine::updateTrackBlock Jan 11 14:29:48 music volumio[25751]: info: CorePlayQueue::getTrackBlock Jan 11 14:29:48 music volumio[25751]: info: CoreCommandRouter::volumioRetrievevolume Jan 11 14:29:48 music volumio[25824]: Forking 3 albumart workers Jan 11 14:29:48 music volumio[25751]: info: CoreCommandRouter::volumioGetState Jan 11 14:29:48 music volumio[25751]: info: CorePlayQueue::getTrack 0 Jan 11 14:29:48 music volumio-remote-updater[22000]: [2026-01-11 14:29:48] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1768159785 101 Jan 11 14:29:48 music volumio[25751]: 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 11 14:29:48 music volumio[25751]: info: Reloading queue from file Jan 11 14:29:48 music volumio[25751]: info: CoreStateMachine::setRepeat null single undefined Jan 11 14:29:48 music volumio[25751]: info: CoreStateMachine::pushState Jan 11 14:29:48 music volumio[25751]: info: CorePlayQueue::getTrack 0 Jan 11 14:29:48 music volumio[25751]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 11 14:29:48 music volumio[25751]: info: CoreCommandRouter::volumioPushState Jan 11 14:29:48 music volumio[25751]: info: CoreStateMachine::setRandom null Jan 11 14:29:48 music volumio[25751]: info: CoreStateMachine::pushState Jan 11 14:29:48 music volumio[25751]: info: CorePlayQueue::getTrack 0 Jan 11 14:29:48 music volumio[25751]: info: CoreCommandRouter::volumioPushState Jan 11 14:29:49 music volumio[25751]: info: Setting Device type: Raspberry PI Jan 11 14:29:49 music volumio[25751]: info: Listing playlists Jan 11 14:29:49 music volumio[25751]: info: Listing playlists Jan 11 14:29:49 music volumio[25751]: info: VolumeController:: Volume=86 Mute =false Jan 11 14:29:49 music volumio[25751]: info: CoreStateMachine::pushState Jan 11 14:29:49 music volumio[25751]: info: CorePlayQueue::getTrack 0 Jan 11 14:29:49 music volumio[25751]: info: CoreCommandRouter::volumioPushState Jan 11 14:29:49 music volumio[25751]: info: Completed loading Core Plugins Jan 11 14:29:49 music volumio[25751]: info: Preparing to generate the ALSA configuration file Jan 11 14:29:49 music volumio[25751]: info: Discovery: adding 4a29b7a7-c637-4926-a2bd-fb4e2f55145e Jan 11 14:29:49 music volumio[25751]: info: Discovery: Found device music Jan 11 14:29:49 music volumio[25751]: info: CoreCommandRouter::volumioGetState Jan 11 14:29:49 music volumio[25751]: info: CorePlayQueue::getTrack 0 Jan 11 14:29:49 music volumio[25751]: info: Discovery: this is already registered, 4a29b7a7-c637-4926-a2bd-fb4e2f55145e Jan 11 14:29:49 music volumio[25751]: info: Discovery: Found device music Jan 11 14:29:49 music volumio[25751]: info: CoreCommandRouter::volumioGetState Jan 11 14:29:49 music volumio[25751]: info: CorePlayQueue::getTrack 0 Jan 11 14:29:49 music volumio[25751]: info: Asound.conf file unchanged, so no further update is needed Jan 11 14:29:49 music volumio[25751]: info: Output device has changed, restarting MPD Jan 11 14:29:49 music volumio[25751]: info: Output device has changed, restarting Shairport Sync Jan 11 14:29:49 music volumio[25751]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:29:49 music volumio[25751]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 11 14:29:49 music sudo[25880]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 11 14:29:49 music sudo[25880]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:29:49 music sudo[25883]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 11 14:29:49 music sudo[25883]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:29:49 music sudo[25880]: pam_unix(sudo:session): session closed for user root Jan 11 14:29:49 music volumio[25751]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 11 14:29:49 music volumio[25751]: info: ___________ START PLUGINS ___________ Jan 11 14:29:49 music volumio[25751]: info: ControllerMpd::onStart: Initializing MPD Jan 11 14:29:49 music volumio[25751]: info: Creating MPD Configuration file Jan 11 14:29:49 music systemd[1]: Stopping mpd.service - Music Player Daemon... Jan 11 14:29:49 music volumio[25751]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 11 14:29:49 music volumio[25751]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 11 14:29:49 music sudo[25889]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 11 14:29:49 music sudo[25889]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:29:49 music sudo[25889]: pam_unix(sudo:session): session closed for user root Jan 11 14:29:49 music volumio[25751]: info: [1768159789359] CoreMusicLibrary::Adding element Media Servers Jan 11 14:29:49 music volumio[25751]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 11 14:29:49 music systemd[1]: mpd.service: Deactivated successfully. Jan 11 14:29:49 music systemd[1]: Stopped mpd.service - Music Player Daemon. Jan 11 14:29:49 music systemd[1]: mpd.service: Consumed 4.189s CPU time. Jan 11 14:29:49 music systemd[1]: mpd.socket: Deactivated successfully. Jan 11 14:29:49 music systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jan 11 14:29:49 music systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jan 11 14:29:49 music sudo[25891]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 11 14:29:49 music sudo[25891]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:29:49 music volumio[25751]: info: UPNP Browser: Client initialized successfully Jan 11 14:29:49 music systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jan 11 14:29:49 music systemd[1]: Starting mpd.service - Music Player Daemon... Jan 11 14:29:49 music volumio[25751]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:29:49 music volumio[25751]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 11 14:29:49 music systemd[1]: mpd.service: Deactivated successfully. Jan 11 14:29:49 music systemd[1]: Stopped mpd.service - Music Player Daemon. Jan 11 14:29:49 music systemd[1]: mpd.socket: Deactivated successfully. Jan 11 14:29:49 music systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jan 11 14:29:49 music systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jan 11 14:29:49 music systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jan 11 14:29:49 music systemd[1]: Starting mpd.service - Music Player Daemon... Jan 11 14:29:49 music volumio[25751]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 11 14:29:49 music volumio[25751]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:29:49 music volumio[25751]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 11 14:29:49 music volumio[25751]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 11 14:29:49 music volumio[25751]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 11 14:29:49 music volumio[25751]: info: [1768159789619] CoreMusicLibrary::Adding element Last_100 Jan 11 14:29:49 music volumio[25751]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 11 14:29:49 music volumio[25751]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 11 14:29:49 music volumio[25751]: info: [1768159789629] CoreMusicLibrary::Adding element Webradio Jan 11 14:29:49 music volumio[25751]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 11 14:29:49 music volumio[25751]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 11 14:29:49 music volumio[25751]: info: Initializing BBC Radios Jan 11 14:29:49 music volumio[25751]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 11 14:29:49 music volumio[25751]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 11 14:29:49 music volumio[25751]: info: Creating Spotify config file Jan 11 14:29:49 music volumio[25751]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:29:49 music sudo[25901]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jan 11 14:29:49 music sudo[25901]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Jan 11 14:29:49 music sudo[25901]: pam_unix(sudo:session): session closed for user root Jan 11 14:29:50 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Jan 11 14:29:50 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 11 14:29:50 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 11 14:29:50 music go-librespot[25921]: go-librespot daemon starting... Jan 11 14:29:50 music go-librespot[25922]: time="2026-01-11T14:29:50-05:00" level=info msg="running go-librespot 0.6.2" Jan 11 14:29:50 music volumio[25751]: info: Volumio Calling Home Jan 11 14:29:50 music go-librespot[25922]: time="2026-01-11T14:29:50-05:00" level=info msg="zeroconf server listening on port 39509" Jan 11 14:29:50 music volumio[25751]: info: MPD Permissions set Jan 11 14:29:50 music volumio[25751]: info: MPD Permissions set Jan 11 14:29:50 music volumio[25843]: Starting albumart workers Jan 11 14:29:50 music volumio[25751]: info: Spotify config file written Jan 11 14:29:50 music volumio[25751]: 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 11 14:29:50 music volumio[25751]: info: Volumio called home Jan 11 14:29:50 music volumio[25842]: Starting albumart workers Jan 11 14:29:50 music volumio[25751]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:29:50 music volumio[25751]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:29:50 music volumio[25751]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:29:50 music volumio[25751]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:29:50 music volumio[25751]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:29:50 music volumio[25751]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:29:50 music volumio[25751]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:29:50 music volumio[25751]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:29:50 music sudo[25936]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jan 11 14:29:50 music sudo[25936]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:29:50 music volumio[25751]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 11 14:29:50 music volumio[25751]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:29:50 music volumio[25751]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:29:50 music volumio[25751]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:29:50 music volumio[25751]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:29:50 music volumio[25751]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:29:50 music volumio[25751]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:29:50 music volumio[25751]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:29:50 music volumio[25751]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:29:51 music systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Jan 11 14:29:51 music systemd[1]: go-librespot-daemon.service: Deactivated successfully. Jan 11 14:29:51 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 11 14:29:51 music volumio[25751]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:29:51 music volumio[25751]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 11 14:29:51 music volumio[25751]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:29:51 music volumio[25751]: info: No need to fix Spotify hosts Jan 11 14:29:51 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 11 14:29:51 music go-librespot[25943]: go-librespot daemon starting... Jan 11 14:29:51 music sudo[25936]: pam_unix(sudo:session): session closed for user root Jan 11 14:29:51 music go-librespot[25949]: time="2026-01-11T14:29:51-05:00" level=info msg="running go-librespot 0.6.2" Jan 11 14:29:51 music go-librespot[25949]: time="2026-01-11T14:29:51-05:00" level=debug msg="app state loaded" Jan 11 14:29:51 music go-librespot[25949]: time="2026-01-11T14:29:51-05:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 11 14:29:51 music volumio[25841]: Starting albumart workers Jan 11 14:29:51 music go-librespot[25949]: time="2026-01-11T14:29:51-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew4.spotify.com:80]" Jan 11 14:29:51 music go-librespot[25949]: time="2026-01-11T14:29:51-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 11 14:29:51 music go-librespot[25949]: time="2026-01-11T14:29:51-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 11 14:29:51 music go-librespot[25949]: time="2026-01-11T14:29:51-05:00" level=info msg="zeroconf server listening on port 33731" Jan 11 14:29:51 music volumio[25751]: info: Starting Shairport Sync Jan 11 14:29:51 music volumio[25751]: info: Starting Shairport Sync Jan 11 14:29:51 music volumio[25751]: info: Starting Shairport Sync Jan 11 14:29:51 music sudo[25961]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 11 14:29:51 music sudo[25961]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:29:51 music volumio[25751]: info: An error occurred while refreshing Spotify Token Error: Bad Request Jan 11 14:29:51 music go-librespot[25949]: time="2026-01-11T14:29:51-05:00" level=debug msg="obtained new client token: AACnECqx3ZkYdmyAxGOEbvMP+R3v/48pQzBLb1D18N5v961peNBA9CxFgRqZiPhN7WYoGP2VFZbUcPcLCpGn2+KvKik3duV+4DInJbAz/FjqX/Wy3p33QgWSsYc0OU59WxpfjeIrPTKqOvlhcdWRF9AZrV3WvNkwi7o2Y5YtUX4C6YK0fnha0HFAwb/i//tKAEqHgrkqpN5Jzym964ZwwWfjrS6arvI4amUYUMcELQKXoVXUxDxqls4=" Jan 11 14:29:51 music sudo[25959]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 11 14:29:51 music systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jan 11 14:29:51 music go-librespot[25949]: time="2026-01-11T14:29:51-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Jan 11 14:29:51 music systemd[1]: shairport-sync.service: Deactivated successfully. Jan 11 14:29:51 music systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 11 14:29:51 music systemd[1]: shairport-sync.service: Consumed 1.799s CPU time. Jan 11 14:29:51 music sudo[25959]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:29:51 music sudo[25963]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 11 14:29:51 music volumio[25751]: info: CoreCommandRouter::volumioGetState Jan 11 14:29:51 music sudo[25963]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:29:51 music volumio[25751]: info: CorePlayQueue::getTrack 0 Jan 11 14:29:51 music go-librespot[25949]: time="2026-01-11T14:29:51-05:00" level=debug msg="completed keyexchange" Jan 11 14:29:51 music systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 11 14:29:51 music go-librespot[25949]: time="2026-01-11T14:29:51-05:00" level=debug msg="completed challenge" Jan 11 14:29:52 music sudo[25961]: pam_unix(sudo:session): session closed for user root Jan 11 14:29:52 music go-librespot[25949]: time="2026-01-11T14:29:52-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:29:52 music systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jan 11 14:29:52 music systemd[1]: shairport-sync.service: Deactivated successfully. Jan 11 14:29:52 music systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 11 14:29:52 music volumio[25751]: info: Shairport-Sync Started Jan 11 14:29:52 music volumio[25751]: Error adding Membership: Error: addMembership EINVAL Jan 11 14:29:52 music systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 11 14:29:52 music sudo[25959]: pam_unix(sudo:session): session closed for user root Jan 11 14:29:52 music sudo[25963]: pam_unix(sudo:session): session closed for user root Jan 11 14:29:52 music volumio[25751]: info: Shairport-Sync Started Jan 11 14:29:52 music volumio[25751]: info: Shairport-Sync Started Jan 11 14:29:52 music go-librespot[25949]: time="2026-01-11T14:29:52-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Jan 11 14:29:52 music go-librespot[25949]: time="2026-01-11T14:29:52-05:00" level=debug msg="completed keyexchange" Jan 11 14:29:52 music go-librespot[25949]: time="2026-01-11T14:29:52-05:00" level=debug msg="completed challenge" Jan 11 14:29:52 music go-librespot[25949]: time="2026-01-11T14:29:52-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:29:53 music go-librespot[25949]: time="2026-01-11T14:29:53-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Jan 11 14:29:53 music go-librespot[25949]: time="2026-01-11T14:29:53-05:00" level=debug msg="completed keyexchange" Jan 11 14:29:53 music go-librespot[25949]: time="2026-01-11T14:29:53-05:00" level=debug msg="completed challenge" Jan 11 14:29:53 music go-librespot[25949]: time="2026-01-11T14:29:53-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:29:54 music mpd[25920]: 2026-01-11T14:29:53 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jan 11 14:29:54 music systemd[1]: Started mpd.service - Music Player Daemon. Jan 11 14:29:54 music sudo[25883]: pam_unix(sudo:session): session closed for user root Jan 11 14:29:54 music sudo[25891]: pam_unix(sudo:session): session closed for user root Jan 11 14:29:54 music volumio[25751]: info: Completed starting Core Plugins Jan 11 14:29:54 music volumio[25751]: info: ------------------------------------------- Jan 11 14:29:54 music volumio[25751]: info: ----- MyVolumio plugins startup ---- Jan 11 14:29:54 music volumio[25751]: info: ------------------------------------------- Jan 11 14:29:54 music volumio[25751]: info: [MyVolumio PluginManager] Fetching plans data.... Jan 11 14:29:54 music go-librespot[25949]: time="2026-01-11T14:29:54-05:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 11 14:29:54 music volumio[25751]: error: MPD error: The expression evaluated to a falsy value: Jan 11 14:29:54 music volumio[25751]: assert.ok(self.idling) Jan 11 14:29:54 music volumio[25751]: error: The expression evaluated to a falsy value: Jan 11 14:29:54 music volumio[25751]: assert.ok(self.idling) Jan 11 14:29:54 music volumio[25751]: info: MPD running with PID25920 Jan 11 14:29:54 music volumio[25751]: ,establishing connection Jan 11 14:29:54 music volumio[25751]: error: updateQueue error: null Jan 11 14:29:54 music volumio[25751]: error: updateQueue error: null Jan 11 14:29:54 music go-librespot[25949]: time="2026-01-11T14:29:54-05:00" level=debug msg="completed keyexchange" Jan 11 14:29:54 music go-librespot[25949]: time="2026-01-11T14:29:54-05:00" level=debug msg="completed challenge" Jan 11 14:29:54 music go-librespot[25949]: time="2026-01-11T14:29:54-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:29:54 music volumio[25751]: info: go-librespot daemon successfully initialized Jan 11 14:29:54 music sudo[26033]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 11 14:29:54 music sudo[26033]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:29:54 music sudo[26033]: pam_unix(sudo:session): session closed for user root Jan 11 14:29:54 music sudo[26035]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 11 14:29:54 music sudo[26035]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:29:54 music sudo[26035]: pam_unix(sudo:session): session closed for user root Jan 11 14:29:54 music sudo[26038]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Jan 11 14:29:54 music sudo[26038]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:29:54 music sudo[26038]: pam_unix(sudo:session): session closed for user root Jan 11 14:29:54 music volumio[25751]: info: Upmpdcli Daemon Started Jan 11 14:29:54 music go-librespot[25949]: time="2026-01-11T14:29:54-05:00" level=debug msg="connected to ap-gae2.spotify.com:443" Jan 11 14:29:54 music volumio[25751]: info: CoreCommandRouter::volumioGetState Jan 11 14:29:54 music volumio[25751]: info: CorePlayQueue::getTrack 0 Jan 11 14:29:55 music go-librespot[25949]: time="2026-01-11T14:29:55-05:00" level=debug msg="completed keyexchange" Jan 11 14:29:55 music go-librespot[25949]: time="2026-01-11T14:29:55-05:00" level=debug msg="completed challenge" Jan 11 14:29:55 music go-librespot[25949]: time="2026-01-11T14:29:55-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:29:55 music go-librespot[25949]: time="2026-01-11T14:29:55-05:00" level=debug msg="connected to ap-gew4.spotify.com:80" Jan 11 14:29:56 music go-librespot[25949]: time="2026-01-11T14:29:56-05:00" level=debug msg="completed keyexchange" Jan 11 14:29:56 music go-librespot[25949]: time="2026-01-11T14:29:56-05:00" level=debug msg="completed challenge" Jan 11 14:29:56 music go-librespot[25949]: time="2026-01-11T14:29:56-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:29:56 music go-librespot[25949]: time="2026-01-11T14:29:56-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:29:56 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 11 14:29:56 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 11 14:29:57 music sudo[26042]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Jan 11 14:29:57 music sudo[26042]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:29:57 music sudo[26044]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Jan 11 14:29:57 music sudo[26044]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:29:57 music systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Jan 11 14:29:57 music systemd[1]: mpd_monitor.service: Deactivated successfully. Jan 11 14:29:57 music systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Jan 11 14:29:57 music systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Jan 11 14:29:57 music sudo[26044]: pam_unix(sudo:session): session closed for user root Jan 11 14:29:57 music sudo[26042]: pam_unix(sudo:session): session closed for user root Jan 11 14:29:57 music volumio[25751]: info: Successfully started MPD Monitor Jan 11 14:29:57 music mpd_monitor.sh[26047]: MPD Monitor Service: Starting MPD Monitor Service Jan 11 14:29:57 music volumio[25751]: info: Successfully started MPD Monitor Jan 11 14:29:57 music volumio[25751]: info: Initializing connection to go-librespot Websocket Jan 11 14:29:57 music volumio[25751]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 11 14:29:59 music volumio[25751]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Jan 11 14:29:59 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Jan 11 14:29:59 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 11 14:29:59 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 11 14:29:59 music go-librespot[26051]: go-librespot daemon starting... Jan 11 14:29:59 music go-librespot[26052]: time="2026-01-11T14:29:59-05:00" level=info msg="running go-librespot 0.6.2" Jan 11 14:29:59 music go-librespot[26052]: time="2026-01-11T14:29:59-05:00" level=debug msg="app state loaded" Jan 11 14:29:59 music go-librespot[26052]: time="2026-01-11T14:29:59-05:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 11 14:29:59 music go-librespot[26052]: time="2026-01-11T14:29:59-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 11 14:29:59 music go-librespot[26052]: time="2026-01-11T14:29:59-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 11 14:29:59 music go-librespot[26052]: time="2026-01-11T14:29:59-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 11 14:29:59 music go-librespot[26052]: time="2026-01-11T14:29:59-05:00" level=info msg="zeroconf server listening on port 46773" Jan 11 14:29:59 music go-librespot[26052]: time="2026-01-11T14:29:59-05:00" level=debug msg="obtained new client token: AADsIF6ocGm89MsW+E7LGf8AewWx7jlrdclmHajyqPfFuGgckotQFO0X2OA2un1bx8Z4XCW+03oDMLAjPAnviKaW8tO7oL6rJyD8VdeiVAla4pNc9JsiE2DUMpq5A32qCGXnBSrlsCAvrEM+EB4myHR47wtblrSul8YxuIA41NP8wePuXiqkeDcBXAACoPrgX2YRqpdecqVoeZ+iXZ6jmIHYCNOS/aEUFSa5mIgg6k/GCL7P4GcUb3E=" Jan 11 14:29:59 music go-librespot[26052]: time="2026-01-11T14:29:59-05:00" level=warning msg="failed to connect to AP ap-gue1.spotify.com:4070, retrying with a different AP" error="dial tcp 34.158.255.62:4070: connect: connection refused" Jan 11 14:29:59 music go-librespot[26052]: time="2026-01-11T14:29:59-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Jan 11 14:30:00 music go-librespot[26052]: time="2026-01-11T14:30:00-05:00" level=debug msg="completed keyexchange" Jan 11 14:30:00 music go-librespot[26052]: time="2026-01-11T14:30:00-05:00" level=debug msg="completed challenge" Jan 11 14:30:00 music go-librespot[26052]: time="2026-01-11T14:30:00-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:30:00 music volumio[25751]: info: Initializing connection to go-librespot Websocket Jan 11 14:30:00 music go-librespot[26052]: time="2026-01-11T14:30:00-05:00" level=debug msg="new websocket client" Jan 11 14:30:00 music go-librespot[26052]: time="2026-01-11T14:30:00-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Jan 11 14:30:00 music volumio[25751]: info: Connection to go-librespot Websocket established Jan 11 14:30:00 music go-librespot[26052]: time="2026-01-11T14:30:00-05:00" level=debug msg="completed keyexchange" Jan 11 14:30:00 music go-librespot[26052]: time="2026-01-11T14:30:00-05:00" level=debug msg="completed challenge" Jan 11 14:30:00 music go-librespot[26052]: time="2026-01-11T14:30:00-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:30:01 music go-librespot[26052]: time="2026-01-11T14:30:01-05:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 11 14:30:01 music go-librespot[26052]: time="2026-01-11T14:30:01-05:00" level=debug msg="completed keyexchange" Jan 11 14:30:01 music go-librespot[26052]: time="2026-01-11T14:30:01-05:00" level=debug msg="completed challenge" Jan 11 14:30:01 music go-librespot[26052]: time="2026-01-11T14:30:01-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:30:02 music go-librespot[26052]: time="2026-01-11T14:30:02-05:00" level=warning msg="failed to connect to AP ap-gew1.spotify.com:443, retrying with a different AP" error="dial tcp 104.199.65.9:443: connect: connection refused" Jan 11 14:30:02 music go-librespot[26052]: time="2026-01-11T14:30:02-05:00" level=debug msg="connected to ap-gew4.spotify.com:80" Jan 11 14:30:02 music volumio[25751]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Jan 11 14:30:02 music volumio[25751]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Jan 11 14:30:02 music volumio[25751]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Jan 11 14:30:02 music volumio[25751]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Jan 11 14:30:02 music volumio[25751]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Jan 11 14:30:02 music volumio[25751]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Jan 11 14:30:02 music volumio[25751]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Jan 11 14:30:02 music volumio[25751]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Jan 11 14:30:02 music volumio[25751]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Jan 11 14:30:02 music volumio[25751]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Jan 11 14:30:02 music volumio[25751]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Jan 11 14:30:02 music volumio[25751]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Jan 11 14:30:02 music volumio[25751]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Jan 11 14:30:02 music volumio[25751]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Jan 11 14:30:02 music volumio[25751]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Jan 11 14:30:02 music volumio[25751]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Jan 11 14:30:02 music volumio[25751]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Jan 11 14:30:02 music volumio[25751]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Jan 11 14:30:02 music volumio[25751]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Jan 11 14:30:02 music volumio[25751]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Jan 11 14:30:02 music volumio[25751]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Jan 11 14:30:02 music volumio[25751]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Jan 11 14:30:02 music volumio[25751]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Jan 11 14:30:02 music volumio[25751]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Jan 11 14:30:02 music volumio[25751]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Jan 11 14:30:02 music volumio[25751]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Jan 11 14:30:02 music volumio[25751]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Jan 11 14:30:02 music volumio[25751]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Jan 11 14:30:02 music volumio[25751]: info: Adding plugin bluetooth to MyMusic Plugins Jan 11 14:30:02 music volumio[25751]: info: Adding plugin multiroom to MyMusic Plugins Jan 11 14:30:02 music volumio[25751]: info: Adding plugin metavolumio to MyMusic Plugins Jan 11 14:30:02 music volumio[25751]: info: Adding plugin cd_controller to MyMusic Plugins Jan 11 14:30:02 music volumio[25751]: info: Adding plugin qobuzconnect to MyMusic Plugins Jan 11 14:30:02 music volumio[25751]: info: Adding plugin smart_inputs to MyMusic Plugins Jan 11 14:30:02 music volumio[25751]: info: Adding plugin tidalconnect to MyMusic Plugins Jan 11 14:30:02 music volumio[25751]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Jan 11 14:30:02 music go-librespot[26052]: time="2026-01-11T14:30:02-05:00" level=debug msg="completed keyexchange" Jan 11 14:30:02 music go-librespot[26052]: time="2026-01-11T14:30:02-05:00" level=debug msg="completed challenge" Jan 11 14:30:02 music go-librespot[26052]: time="2026-01-11T14:30:02-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:30:03 music go-librespot[26052]: time="2026-01-11T14:30:03-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Jan 11 14:30:03 music go-librespot[26052]: time="2026-01-11T14:30:03-05:00" level=debug msg="completed keyexchange" Jan 11 14:30:03 music go-librespot[26052]: time="2026-01-11T14:30:03-05:00" level=debug msg="completed challenge" Jan 11 14:30:03 music go-librespot[26052]: time="2026-01-11T14:30:03-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:30:03 music volumio[25751]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Jan 11 14:30:03 music volumio[25751]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Jan 11 14:30:03 music volumio[25751]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 11 14:30:03 music volumio[25751]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 11 14:30:03 music volumio[25751]: info: Starting MyVolumio Remote Streaming Endpoints Jan 11 14:30:03 music volumio[25751]: info: MyVolumio login type: Token Jan 11 14:30:03 music volumio[25751]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Jan 11 14:30:03 music volumio[25751]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Jan 11 14:30:03 music go-librespot[26052]: time="2026-01-11T14:30:03-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Jan 11 14:30:03 music go-librespot[26052]: time="2026-01-11T14:30:03-05:00" level=debug msg="completed keyexchange" Jan 11 14:30:03 music go-librespot[26052]: time="2026-01-11T14:30:03-05:00" level=debug msg="completed challenge" Jan 11 14:30:03 music go-librespot[26052]: time="2026-01-11T14:30:03-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:30:03 music go-librespot[26052]: time="2026-01-11T14:30:03-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:30:03 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 11 14:30:03 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 11 14:30:04 music volumio[25751]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Jan 11 14:30:04 music volumio[25751]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Jan 11 14:30:04 music volumio[25751]: info: Streaming services startup Jan 11 14:30:04 music volumio[25751]: info: Starting Streaming Daemon Jan 11 14:30:04 music sudo[26062]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Jan 11 14:30:04 music sudo[26062]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:30:04 music volumio[25751]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Jan 11 14:30:04 music sudo[26062]: pam_unix(sudo:session): session closed for user root Jan 11 14:30:04 music volumio[25751]: info: Getting Spotify volume Jan 11 14:30:04 music volumio[25751]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 11 14:30:04 music volumio[25751]: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 11 14:30:04 music volumio[25751]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Jan 11 14:30:04 music volumio[25751]: errno: -111, Jan 11 14:30:04 music volumio[25751]: code: 'ECONNREFUSED', Jan 11 14:30:04 music volumio[25751]: syscall: 'connect', Jan 11 14:30:04 music volumio[25751]: address: '127.0.0.1', Jan 11 14:30:04 music volumio[25751]: port: 9879, Jan 11 14:30:04 music volumio[25751]: response: undefined Jan 11 14:30:04 music volumio[25751]: } Jan 11 14:30:04 music volumio[25751]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 11 14:30:05 music sudo[26097]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-01-11 14:29' Jan 11 14:30:05 music sudo[26097]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:30:05 music sudo[26097]: pam_unix(sudo:session): session closed for user root Jan 11 14:30:05 music volumio-remote-updater[22000]: [2026-01-11 14:30:05] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Jan 11 14:30:05 music volumio-remote-updater[22000]: [2026-01-11 14:30:05] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Jan 11 14:30:05 music systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Jan 11 14:30:05 music systemd[1]: volumio.service: Failed with result 'exit-code'. Jan 11 14:30:05 music systemd[1]: volumio.service: Consumed 26.518s CPU time. Jan 11 14:30:05 music systemd[1]: Started dynamicswap.service - dynamicswap service. Jan 11 14:30:05 music systemd[1]: dynamicswap.service: Deactivated successfully. Jan 11 14:30:05 music systemd[1]: volumio.service: Scheduled restart job, restart counter is at 5275. Jan 11 14:30:05 music systemd[1]: Started dynamicswap.service - dynamicswap service. Jan 11 14:30:05 music systemd[1]: Stopped volumio.service - Volumio Backend Module. Jan 11 14:30:05 music systemd[1]: volumio.service: Consumed 26.518s CPU time. Jan 11 14:30:05 music systemd[1]: Started volumio.service - Volumio Backend Module. Jan 11 14:30:05 music systemd[1]: dynamicswap.service: Deactivated successfully. Jan 11 14:30:07 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Jan 11 14:30:07 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 11 14:30:07 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 11 14:30:07 music go-librespot[26124]: go-librespot daemon starting... Jan 11 14:30:07 music go-librespot[26125]: time="2026-01-11T14:30:07-05:00" level=info msg="running go-librespot 0.6.2" Jan 11 14:30:07 music go-librespot[26125]: time="2026-01-11T14:30:07-05:00" level=debug msg="app state loaded" Jan 11 14:30:07 music go-librespot[26125]: time="2026-01-11T14:30:07-05:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 11 14:30:07 music go-librespot[26125]: time="2026-01-11T14:30:07-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 11 14:30:07 music go-librespot[26125]: time="2026-01-11T14:30:07-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 11 14:30:07 music go-librespot[26125]: time="2026-01-11T14:30:07-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 11 14:30:07 music go-librespot[26125]: time="2026-01-11T14:30:07-05:00" level=info msg="zeroconf server listening on port 41649" Jan 11 14:30:07 music go-librespot[26125]: time="2026-01-11T14:30:07-05:00" level=debug msg="obtained new client token: AAAzgO8jNnWrvlOSh4TvfFsh5cxjnUFOf8thhRs4HILneBEbPYnyYGJvDX1us9skI3ptlEE6DzmjhBW5URuRSG7f1AtwcwN935QMR6uyqufibLFKurcN1cYRlt5+y7mfEBZCr/BL/A9F9kF2u/QhsF2Df1ToDR9TD1F8wmJnSt9RVxB1PtT3Mzw3mL/GRzCufkEffReL6JKyT7SnKXpgiUYRWkeduJEolklBwr5TgC4XjO/tLZiX2as=" Jan 11 14:30:07 music go-librespot[26125]: time="2026-01-11T14:30:07-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Jan 11 14:30:07 music go-librespot[26125]: time="2026-01-11T14:30:07-05:00" level=debug msg="completed keyexchange" Jan 11 14:30:07 music go-librespot[26125]: time="2026-01-11T14:30:07-05:00" level=debug msg="completed challenge" Jan 11 14:30:07 music go-librespot[26125]: time="2026-01-11T14:30:07-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:30:07 music volumio[26109]: info: ------------------------------------------- Jan 11 14:30:07 music volumio[26109]: info: ----- Volumio3 ---- Jan 11 14:30:07 music volumio[26109]: info: ------------------------------------------- Jan 11 14:30:07 music volumio[26109]: info: ----- System startup ---- Jan 11 14:30:07 music volumio[26109]: info: ------------------------------------------- Jan 11 14:30:08 music go-librespot[26125]: time="2026-01-11T14:30:08-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Jan 11 14:30:08 music go-librespot[26125]: time="2026-01-11T14:30:08-05:00" level=debug msg="completed keyexchange" Jan 11 14:30:08 music go-librespot[26125]: time="2026-01-11T14:30:08-05:00" level=debug msg="completed challenge" Jan 11 14:30:08 music go-librespot[26125]: time="2026-01-11T14:30:08-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:30:08 music volumio[26109]: info: MYVOLUMIO Environment detected Jan 11 14:30:08 music volumio[26109]: info: Plugin folders cleanup Jan 11 14:30:08 music volumio[26109]: info: Scanning into folder /volumio/app/plugins/ Jan 11 14:30:08 music volumio[26109]: info: Scanning category audio_interface Jan 11 14:30:08 music volumio[26109]: info: Scanning category miscellanea Jan 11 14:30:08 music volumio[26109]: info: Scanning category music_service Jan 11 14:30:08 music volumio[26109]: info: Scanning category plugins.json Jan 11 14:30:08 music volumio[26109]: info: Scanning category system_controller Jan 11 14:30:08 music volumio[26109]: info: Scanning category user_interface Jan 11 14:30:08 music volumio[26109]: info: Scanning into folder /data/plugins/ Jan 11 14:30:08 music volumio[26109]: info: Scanning category music_service Jan 11 14:30:08 music volumio[26109]: info: Plugin folders cleanup completed Jan 11 14:30:08 music volumio[26109]: info: ------------------------------------------- Jan 11 14:30:08 music volumio[26109]: info: ----- Core plugins startup ---- Jan 11 14:30:08 music volumio[26109]: info: ------------------------------------------- Jan 11 14:30:08 music volumio[26109]: info: Loading plugins from folder /volumio/app/plugins/ Jan 11 14:30:08 music volumio[26109]: info: Adding plugin upnp to MyMusic Plugins Jan 11 14:30:08 music volumio[26109]: info: Adding plugin airplay_emulation to MyMusic Plugins Jan 11 14:30:08 music volumio[26109]: info: Adding plugin upnp_browser to MyMusic Plugins Jan 11 14:30:08 music volumio[26109]: info: Loading plugins from folder /data/plugins/ Jan 11 14:30:08 music volumio[26109]: info: Loading plugin "system"... Jan 11 14:30:08 music volumio[26109]: info: Loading plugin "appearance"... Jan 11 14:30:09 music go-librespot[26125]: time="2026-01-11T14:30:09-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Jan 11 14:30:09 music go-librespot[26125]: time="2026-01-11T14:30:09-05:00" level=debug msg="completed keyexchange" Jan 11 14:30:09 music go-librespot[26125]: time="2026-01-11T14:30:09-05:00" level=debug msg="completed challenge" Jan 11 14:30:09 music go-librespot[26125]: time="2026-01-11T14:30:09-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:30:09 music go-librespot[26125]: time="2026-01-11T14:30:09-05:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 11 14:30:09 music go-librespot[26125]: time="2026-01-11T14:30:09-05:00" level=debug msg="completed keyexchange" Jan 11 14:30:09 music go-librespot[26125]: time="2026-01-11T14:30:09-05:00" level=debug msg="completed challenge" Jan 11 14:30:09 music go-librespot[26125]: time="2026-01-11T14:30:09-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:30:09 music volumio[26109]: info: Loading plugin "network"... Jan 11 14:30:09 music volumio[26109]: info: Refreshing Cached IP Addresses Jan 11 14:30:09 music sudo[26147]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 11 14:30:09 music sudo[26147]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:30:09 music sudo[26147]: pam_unix(sudo:session): session closed for user root Jan 11 14:30:09 music sudo[26149]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 11 14:30:09 music sudo[26149]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:30:09 music sudo[26149]: pam_unix(sudo:session): session closed for user root Jan 11 14:30:09 music volumio[26109]: info: Loading plugin "services"... Jan 11 14:30:09 music volumio[26109]: info: Loading plugin "alsa_controller"... Jan 11 14:30:09 music sudo[26157]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Jan 11 14:30:09 music sudo[26157]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:30:10 music volumio[26109]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 11 14:30:10 music volumio[26109]: info: Loading plugin "wizard"... Jan 11 14:30:10 music volumio[26109]: info: Loading plugin "networkfs"... Jan 11 14:30:10 music volumio[26109]: info: Starting Udev Watcher for removable devices Jan 11 14:30:10 music volumio[26109]: info: Ignoring mount for partition: boot Jan 11 14:30:10 music volumio[26109]: info: Ignoring mount for partition: volumio Jan 11 14:30:10 music volumio[26109]: info: Ignoring mount for partition: volumio_data Jan 11 14:30:10 music volumio[26109]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 11 14:30:10 music volumio[26109]: info: Loading plugin "volumio_command_line_client"... Jan 11 14:30:10 music volumio[26109]: info: Loading plugin "upnp"... Jan 11 14:30:10 music volumio[26109]: info: [1768159810129] Starting Upmpd Daemon Jan 11 14:30:10 music volumio[26109]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 11 14:30:10 music volumio[26109]: info: Loading plugin "my_music"... Jan 11 14:30:10 music volumio[26109]: info: Loading plugin "mpd"... Jan 11 14:30:10 music volumio-remote-updater[22000]: [2026-01-11 14:30:10] [connect] Successful connection Jan 11 14:30:10 music go-librespot[26125]: time="2026-01-11T14:30:10-05:00" level=debug msg="connected to ap-gew1.spotify.com:443" Jan 11 14:30:10 music volumio[26109]: info: Loading plugin "upnp_browser"... Jan 11 14:30:10 music sudo[26157]: pam_unix(sudo:session): session closed for user root Jan 11 14:30:10 music go-librespot[26125]: time="2026-01-11T14:30:10-05:00" level=debug msg="completed keyexchange" Jan 11 14:30:10 music go-librespot[26125]: time="2026-01-11T14:30:10-05:00" level=debug msg="completed challenge" Jan 11 14:30:10 music go-librespot[26125]: time="2026-01-11T14:30:10-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:30:11 music go-librespot[26125]: time="2026-01-11T14:30:11-05:00" level=debug msg="connected to ap-gew4.spotify.com:80" Jan 11 14:30:11 music go-librespot[26125]: time="2026-01-11T14:30:11-05:00" level=debug msg="completed keyexchange" Jan 11 14:30:11 music go-librespot[26125]: time="2026-01-11T14:30:11-05:00" level=debug msg="completed challenge" Jan 11 14:30:11 music go-librespot[26125]: time="2026-01-11T14:30:11-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:30:11 music go-librespot[26125]: time="2026-01-11T14:30:11-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:30:11 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 11 14:30:11 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 11 14:30:12 music volumio[26109]: info: Starting UPNP Browser Jan 11 14:30:12 music volumio[26109]: info: Loading plugin "alarm-clock"... Jan 11 14:30:12 music volumio[26109]: info: Loading plugin "airplay_emulation"... Jan 11 14:30:12 music volumio[26109]: info: Starting Shairport Sync Jan 11 14:30:12 music volumio[26109]: info: Loading plugin "last_100"... Jan 11 14:30:12 music volumio[26109]: info: Loading plugin "webradio"... Jan 11 14:30:12 music volumio[26109]: info: Loading plugin "i2s_dacs"... Jan 11 14:30:12 music volumio[26109]: info: I2S DAC not set, start Auto-detection Jan 11 14:30:12 music volumio[26109]: info: Loading plugin "volumiodiscovery"... Jan 11 14:30:12 music volumio[26109]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jan 11 14:30:12 music volumio[26109]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 11 14:30:12 music volumio[26109]: *** WARNING *** For more information see Jan 11 14:30:12 music volumio[26109]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jan 11 14:30:12 music volumio[26109]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 11 14:30:12 music volumio[26109]: *** WARNING *** For more information see Jan 11 14:30:12 music node[26109]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jan 11 14:30:12 music volumio[26109]: info: Applying required configuration parameters for plugin volumiodiscovery Jan 11 14:30:12 music node[26109]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 11 14:30:12 music node[26109]: *** WARNING *** For more information see Jan 11 14:30:12 music node[26109]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jan 11 14:30:12 music node[26109]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 11 14:30:12 music node[26109]: *** WARNING *** For more information see Jan 11 14:30:12 music volumio[26109]: info: Discovery: Started advertising with name: music Jan 11 14:30:12 music volumio[26109]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 11 14:30:12 music volumio[26109]: info: Loading plugin "spop"... Jan 11 14:30:13 music volumio[26109]: info: Loading plugin "outputs"... Jan 11 14:30:13 music volumio[26109]: info: Loading plugin "albumart"... Jan 11 14:30:13 music volumio[26109]: info: Plugin example_plugin is not enabled Jan 11 14:30:13 music volumio[26109]: info: Loading plugin "inputs"... Jan 11 14:30:13 music volumio[26109]: info: Loading plugin "updater_comm"... Jan 11 14:30:13 music volumio[26109]: info: Plugin mpdemulation is not enabled Jan 11 14:30:13 music volumio[26109]: info: Loading plugin "rest_api"... Jan 11 14:30:13 music volumio[26109]: info: Loading plugin "websocket"... Jan 11 14:30:13 music volumio[26109]: info: Starting Socket.io Server version 1.7.4 Jan 11 14:30:13 music volumio[26109]: info: Loading i18n strings for locale en Jan 11 14:30:13 music volumio[26109]: Updating browse sources language Jan 11 14:30:13 music volumio[26109]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 11 14:30:13 music volumio[26109]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 11 14:30:13 music volumio[26109]: info: CoreCommandRouter::initPlayerControls Jan 11 14:30:13 music volumio[26109]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:30:13 music volumio[26109]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:30:13 music volumio[26109]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:30:13 music volumio[26109]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:30:13 music volumio[26109]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:30:13 music volumio[26109]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:30:13 music volumio[26109]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:30:13 music volumio[26109]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:30:13 music volumio[26109]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 11 14:30:13 music volumio[26109]: Express server listening on port 3000 Jan 11 14:30:13 music volumio[26109]: [Metrics] WebUI: 6s 575.42ms Jan 11 14:30:13 music volumio[26109]: info: CoreStateMachine::resetVolumioState Jan 11 14:30:13 music volumio[26109]: info: CoreStateMachine::getcurrentVolume Jan 11 14:30:13 music volumio[26109]: info: CoreCommandRouter::volumioRetrievevolume Jan 11 14:30:13 music volumio[26109]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 11 14:30:14 music volumio[26109]: info: Volumio Network Manager: Network status updated: 1 Jan 11 14:30:14 music volumio-remote-updater[22000]: [2026-01-11 14:30:14] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1768159810 101 Jan 11 14:30:14 music volumio[26182]: Forking 3 albumart workers Jan 11 14:30:14 music volumio[26109]: 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 11 14:30:14 music volumio[26109]: info: VolumeController:: Volume=86 Mute =false Jan 11 14:30:14 music volumio[26109]: info: CoreStateMachine::pushState Jan 11 14:30:14 music volumio[26109]: info: CorePlayQueue::getTrack 0 Jan 11 14:30:14 music volumio[26109]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 11 14:30:14 music volumio[26109]: info: CoreCommandRouter::volumioPushState Jan 11 14:30:14 music volumio[26109]: info: CoreStateMachine::updateTrackBlock Jan 11 14:30:14 music volumio[26109]: info: CorePlayQueue::getTrackBlock Jan 11 14:30:14 music volumio[26109]: info: CoreCommandRouter::volumioRetrievevolume Jan 11 14:30:14 music volumio[26109]: info: Reloading queue from file Jan 11 14:30:14 music volumio[26109]: info: CoreStateMachine::setRepeat null single undefined Jan 11 14:30:14 music volumio[26109]: info: CoreStateMachine::pushState Jan 11 14:30:14 music volumio[26109]: info: CorePlayQueue::getTrack 0 Jan 11 14:30:14 music volumio[26109]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 11 14:30:14 music volumio[26109]: info: CoreCommandRouter::volumioPushState Jan 11 14:30:14 music volumio[26109]: info: CoreStateMachine::setRandom null Jan 11 14:30:14 music volumio[26109]: info: CoreStateMachine::pushState Jan 11 14:30:14 music volumio[26109]: info: CorePlayQueue::getTrack 0 Jan 11 14:30:14 music volumio[26109]: info: CoreCommandRouter::volumioPushState Jan 11 14:30:14 music volumio[26109]: info: Setting Device type: Raspberry PI Jan 11 14:30:14 music volumio[26109]: info: VolumeController:: Volume=86 Mute =false Jan 11 14:30:14 music volumio[26109]: info: CoreStateMachine::pushState Jan 11 14:30:14 music volumio[26109]: info: CorePlayQueue::getTrack 0 Jan 11 14:30:14 music volumio[26109]: info: CoreCommandRouter::volumioPushState Jan 11 14:30:14 music volumio[26109]: info: Completed loading Core Plugins Jan 11 14:30:14 music volumio[26109]: info: Preparing to generate the ALSA configuration file Jan 11 14:30:14 music volumio[26109]: info: Discovery: adding 4a29b7a7-c637-4926-a2bd-fb4e2f55145e Jan 11 14:30:14 music volumio[26109]: info: Discovery: Found device music Jan 11 14:30:14 music volumio[26109]: info: CoreCommandRouter::volumioGetState Jan 11 14:30:14 music volumio[26109]: info: CorePlayQueue::getTrack 0 Jan 11 14:30:14 music volumio[26109]: info: Discovery: this is already registered, 4a29b7a7-c637-4926-a2bd-fb4e2f55145e Jan 11 14:30:14 music volumio[26109]: info: Discovery: Found device music Jan 11 14:30:14 music volumio[26109]: info: CoreCommandRouter::volumioGetState Jan 11 14:30:14 music volumio[26109]: info: CorePlayQueue::getTrack 0 Jan 11 14:30:14 music volumio[26109]: info: Asound.conf file unchanged, so no further update is needed Jan 11 14:30:14 music volumio[26109]: info: Output device has changed, restarting MPD Jan 11 14:30:14 music volumio[26109]: info: Output device has changed, restarting Shairport Sync Jan 11 14:30:14 music volumio[26109]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:30:14 music volumio[26109]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 11 14:30:14 music sudo[26238]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 11 14:30:14 music sudo[26238]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:30:14 music sudo[26238]: pam_unix(sudo:session): session closed for user root Jan 11 14:30:14 music sudo[26239]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 11 14:30:14 music sudo[26239]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:30:14 music volumio[26109]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 11 14:30:14 music volumio[26109]: info: ___________ START PLUGINS ___________ Jan 11 14:30:14 music volumio[26109]: info: ControllerMpd::onStart: Initializing MPD Jan 11 14:30:14 music volumio[26109]: info: Creating MPD Configuration file Jan 11 14:30:14 music systemd[1]: Stopping mpd.service - Music Player Daemon... Jan 11 14:30:14 music sudo[26247]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 11 14:30:14 music sudo[26247]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:30:14 music sudo[26247]: pam_unix(sudo:session): session closed for user root Jan 11 14:30:14 music volumio[26109]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 11 14:30:14 music volumio[26109]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 11 14:30:14 music systemd[1]: mpd.service: Deactivated successfully. Jan 11 14:30:14 music volumio[26109]: info: [1768159814652] CoreMusicLibrary::Adding element Media Servers Jan 11 14:30:14 music volumio[26109]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 11 14:30:14 music systemd[1]: Stopped mpd.service - Music Player Daemon. Jan 11 14:30:14 music systemd[1]: mpd.service: Consumed 4.219s CPU time. Jan 11 14:30:14 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Jan 11 14:30:14 music systemd[1]: mpd.socket: Deactivated successfully. Jan 11 14:30:14 music systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jan 11 14:30:14 music systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jan 11 14:30:14 music sudo[26250]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 11 14:30:14 music sudo[26250]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:30:14 music volumio[26109]: info: UPNP Browser: Client initialized successfully Jan 11 14:30:14 music volumio[26109]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:30:14 music volumio[26109]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 11 14:30:14 music systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jan 11 14:30:14 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 11 14:30:14 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 11 14:30:14 music systemd[1]: Starting mpd.service - Music Player Daemon... Jan 11 14:30:14 music go-librespot[26257]: go-librespot daemon starting... Jan 11 14:30:14 music volumio[26109]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 11 14:30:14 music volumio[26109]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:30:14 music volumio[26109]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 11 14:30:14 music systemd[1]: mpd.service: Deactivated successfully. Jan 11 14:30:14 music systemd[1]: Stopped mpd.service - Music Player Daemon. Jan 11 14:30:14 music systemd[1]: mpd.socket: Deactivated successfully. Jan 11 14:30:14 music systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jan 11 14:30:14 music systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jan 11 14:30:14 music go-librespot[26259]: time="2026-01-11T14:30:14-05:00" level=info msg="running go-librespot 0.6.2" Jan 11 14:30:14 music go-librespot[26259]: time="2026-01-11T14:30:14-05:00" level=debug msg="app state loaded" Jan 11 14:30:14 music systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jan 11 14:30:14 music volumio[26109]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 11 14:30:14 music volumio[26109]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 11 14:30:14 music volumio[26109]: info: [1768159814875] CoreMusicLibrary::Adding element Last_100 Jan 11 14:30:14 music volumio[26109]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 11 14:30:14 music systemd[1]: Starting mpd.service - Music Player Daemon... Jan 11 14:30:14 music go-librespot[26259]: time="2026-01-11T14:30:14-05:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 11 14:30:14 music volumio[26109]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 11 14:30:14 music volumio[26109]: info: [1768159814949] CoreMusicLibrary::Adding element Webradio Jan 11 14:30:14 music volumio[26109]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 11 14:30:14 music volumio[26109]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 11 14:30:14 music volumio[26109]: info: Initializing BBC Radios Jan 11 14:30:15 music volumio[26109]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 11 14:30:15 music volumio[26109]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 11 14:30:15 music volumio[26109]: info: Creating Spotify config file Jan 11 14:30:15 music volumio[26109]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:30:15 music sudo[26270]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jan 11 14:30:15 music sudo[26270]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Jan 11 14:30:15 music sudo[26270]: pam_unix(sudo:session): session closed for user root Jan 11 14:30:15 music go-librespot[26259]: time="2026-01-11T14:30:15-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 11 14:30:15 music go-librespot[26259]: time="2026-01-11T14:30:15-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 11 14:30:15 music go-librespot[26259]: time="2026-01-11T14:30:15-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 11 14:30:15 music go-librespot[26259]: time="2026-01-11T14:30:15-05:00" level=info msg="zeroconf server listening on port 42201" Jan 11 14:30:15 music volumio[26109]: info: Volumio Calling Home Jan 11 14:30:15 music go-librespot[26259]: time="2026-01-11T14:30:15-05:00" level=debug msg="obtained new client token: AAAw4KKmbUxcG49sbjuJ0zdLIYp0xTmndIVcd9skEIpvDUpTdox30wccpqlm4c5Qz9TY6s0nM/dB4GeESeXzgJDUIZ/5qdjd0eYvEcERMOw6m117HM6eJQfEBmLcOdyXWXsyBSy7J0N6TKjdvFSfxpomGuz+b9x36pwFoU9LO2Hh7jcSSaBCOnjBeWfG7KnTks4xtnaTiWFAldLJEItl9LsSVQ4kgW4O+8XWrMfB9gyaU1LX6dFYHGs=" Jan 11 14:30:15 music go-librespot[26259]: time="2026-01-11T14:30:15-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Jan 11 14:30:15 music go-librespot[26259]: time="2026-01-11T14:30:15-05:00" level=debug msg="completed keyexchange" Jan 11 14:30:15 music go-librespot[26259]: time="2026-01-11T14:30:15-05:00" level=debug msg="completed challenge" Jan 11 14:30:15 music go-librespot[26259]: time="2026-01-11T14:30:15-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:30:16 music volumio[26198]: Starting albumart workers Jan 11 14:30:16 music volumio[26109]: info: MPD Permissions set Jan 11 14:30:16 music volumio[26109]: info: MPD Permissions set Jan 11 14:30:16 music volumio[26200]: Starting albumart workers Jan 11 14:30:16 music volumio[26109]: info: Volumio called home Jan 11 14:30:16 music volumio[26109]: info: Spotify config file written Jan 11 14:30:16 music volumio[26109]: info: CoreCommandRouter::volumioGetState Jan 11 14:30:16 music volumio[26109]: info: CorePlayQueue::getTrack 0 Jan 11 14:30:16 music sudo[26293]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jan 11 14:30:16 music sudo[26293]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:30:16 music volumio[26199]: Starting albumart workers Jan 11 14:30:16 music volumio[26109]: 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 11 14:30:16 music volumio[26109]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:30:16 music volumio[26109]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:30:16 music volumio[26109]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:30:16 music volumio[26109]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:30:16 music go-librespot[26259]: time="2026-01-11T14:30:16-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Jan 11 14:30:16 music volumio[26109]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:30:16 music volumio[26109]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:30:16 music volumio[26109]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:30:16 music volumio[26109]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:30:16 music systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Jan 11 14:30:16 music systemd[1]: go-librespot-daemon.service: Killing process 26263 (go-librespot) with signal SIGKILL. Jan 11 14:30:16 music systemd[1]: go-librespot-daemon.service: Deactivated successfully. Jan 11 14:30:16 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 11 14:30:16 music volumio[26109]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 11 14:30:16 music volumio[26109]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:30:16 music volumio[26109]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:30:16 music volumio[26109]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:30:16 music volumio[26109]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:30:16 music volumio[26109]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:30:16 music volumio[26109]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:30:16 music volumio[26109]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:30:16 music volumio[26109]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:30:16 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 11 14:30:16 music volumio[26109]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:30:16 music sudo[26293]: pam_unix(sudo:session): session closed for user root Jan 11 14:30:16 music go-librespot[26300]: go-librespot daemon starting... Jan 11 14:30:16 music go-librespot[26302]: time="2026-01-11T14:30:16-05:00" level=info msg="running go-librespot 0.6.2" Jan 11 14:30:16 music go-librespot[26302]: time="2026-01-11T14:30:16-05:00" level=debug msg="app state loaded" Jan 11 14:30:16 music volumio[26109]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 11 14:30:16 music volumio[26109]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:30:16 music volumio[26109]: info: No need to fix Spotify hosts Jan 11 14:30:16 music go-librespot[26302]: time="2026-01-11T14:30:16-05:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 11 14:30:17 music go-librespot[26302]: time="2026-01-11T14:30:17-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew4.spotify.com:80]" Jan 11 14:30:17 music go-librespot[26302]: time="2026-01-11T14:30:17-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 11 14:30:17 music go-librespot[26302]: time="2026-01-11T14:30:17-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 11 14:30:17 music go-librespot[26302]: time="2026-01-11T14:30:17-05:00" level=info msg="zeroconf server listening on port 42835" Jan 11 14:30:17 music volumio[26109]: info: Listing playlists Jan 11 14:30:17 music volumio[26109]: info: Listing playlists Jan 11 14:30:17 music go-librespot[26302]: time="2026-01-11T14:30:17-05:00" level=debug msg="obtained new client token: AAANXY28JoXsRy+0TMPMGoCTCm9/eTqwS/luDrcUUiM5tQjJcTzHprLoF8AhDTD55uCUJTg/XCn17Fyc+GHqoMrjAatDv3fFA/eHgB7afOZj/mKZvvkkXgw/A6Xc8ZKtBeg5nNrYn5AqxhTSy10GG5L52jv697GIN0cZ5z/bhsGYVEOT3DxFw67ueRHhOLLwEbM7shYVsq8r0ufQ4A/sYeQY53YZZOl6Txxg1grZs3PreqLetj7JWJM=" Jan 11 14:30:17 music go-librespot[26302]: time="2026-01-11T14:30:17-05:00" level=warning msg="failed to connect to AP ap-gue1.spotify.com:4070, retrying with a different AP" error="dial tcp 34.158.255.62:4070: connect: connection refused" Jan 11 14:30:17 music volumio[26109]: info: Starting Shairport Sync Jan 11 14:30:17 music volumio[26109]: info: Starting Shairport Sync Jan 11 14:30:17 music volumio[26109]: info: Starting Shairport Sync Jan 11 14:30:17 music go-librespot[26302]: time="2026-01-11T14:30:17-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Jan 11 14:30:17 music sudo[26319]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 11 14:30:17 music volumio[26109]: info: An error occurred while refreshing Spotify Token Error: Bad Request Jan 11 14:30:17 music sudo[26323]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 11 14:30:17 music sudo[26323]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:30:17 music go-librespot[26302]: time="2026-01-11T14:30:17-05:00" level=debug msg="completed keyexchange" Jan 11 14:30:17 music go-librespot[26302]: time="2026-01-11T14:30:17-05:00" level=debug msg="completed challenge" Jan 11 14:30:17 music sudo[26319]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:30:17 music systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jan 11 14:30:17 music sudo[26322]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 11 14:30:17 music systemd[1]: shairport-sync.service: Deactivated successfully. Jan 11 14:30:17 music systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 11 14:30:17 music systemd[1]: shairport-sync.service: Consumed 1.724s CPU time. Jan 11 14:30:17 music sudo[26322]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:30:17 music go-librespot[26302]: time="2026-01-11T14:30:17-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:30:17 music systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 11 14:30:17 music sudo[26323]: pam_unix(sudo:session): session closed for user root Jan 11 14:30:17 music systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jan 11 14:30:17 music systemd[1]: shairport-sync.service: Deactivated successfully. Jan 11 14:30:17 music systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 11 14:30:17 music systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 11 14:30:17 music sudo[26322]: pam_unix(sudo:session): session closed for user root Jan 11 14:30:17 music sudo[26319]: pam_unix(sudo:session): session closed for user root Jan 11 14:30:17 music volumio[26109]: info: Shairport-Sync Started Jan 11 14:30:17 music volumio[26109]: Error adding Membership: Error: addMembership EINVAL Jan 11 14:30:17 music volumio[26109]: info: Shairport-Sync Started Jan 11 14:30:17 music volumio[26109]: info: Shairport-Sync Started Jan 11 14:30:17 music volumio[26109]: info: CoreCommandRouter::volumioGetState Jan 11 14:30:17 music volumio[26109]: info: CorePlayQueue::getTrack 0 Jan 11 14:30:18 music go-librespot[26302]: time="2026-01-11T14:30:18-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Jan 11 14:30:18 music go-librespot[26302]: time="2026-01-11T14:30:18-05:00" level=debug msg="completed keyexchange" Jan 11 14:30:18 music go-librespot[26302]: time="2026-01-11T14:30:18-05:00" level=debug msg="completed challenge" Jan 11 14:30:18 music go-librespot[26302]: time="2026-01-11T14:30:18-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:30:18 music go-librespot[26302]: time="2026-01-11T14:30:18-05: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 11 14:30:19 music go-librespot[26302]: time="2026-01-11T14:30:19-05:00" level=debug msg="connected to ap-gae2.spotify.com:443" Jan 11 14:30:19 music mpd[26288]: 2026-01-11T14:30:19 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jan 11 14:30:19 music systemd[1]: Started mpd.service - Music Player Daemon. Jan 11 14:30:19 music sudo[26250]: pam_unix(sudo:session): session closed for user root Jan 11 14:30:19 music sudo[26239]: pam_unix(sudo:session): session closed for user root Jan 11 14:30:19 music volumio[26109]: info: Completed starting Core Plugins Jan 11 14:30:19 music volumio[26109]: info: ------------------------------------------- Jan 11 14:30:19 music volumio[26109]: info: ----- MyVolumio plugins startup ---- Jan 11 14:30:19 music volumio[26109]: info: ------------------------------------------- Jan 11 14:30:19 music volumio[26109]: info: [MyVolumio PluginManager] Fetching plans data.... Jan 11 14:30:19 music volumio[26109]: error: MPD error: The expression evaluated to a falsy value: Jan 11 14:30:19 music volumio[26109]: assert.ok(self.idling) Jan 11 14:30:19 music volumio[26109]: error: The expression evaluated to a falsy value: Jan 11 14:30:19 music volumio[26109]: assert.ok(self.idling) Jan 11 14:30:19 music volumio[26109]: error: updateQueue error: null Jan 11 14:30:19 music volumio[26109]: info: MPD running with PID26288 Jan 11 14:30:19 music volumio[26109]: ,establishing connection Jan 11 14:30:19 music volumio[26109]: error: updateQueue error: null Jan 11 14:30:19 music go-librespot[26302]: time="2026-01-11T14:30:19-05:00" level=debug msg="completed keyexchange" Jan 11 14:30:19 music go-librespot[26302]: time="2026-01-11T14:30:19-05:00" level=debug msg="completed challenge" Jan 11 14:30:19 music go-librespot[26302]: time="2026-01-11T14:30:19-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:30:20 music sudo[26381]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 11 14:30:20 music sudo[26381]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:30:20 music sudo[26383]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 11 14:30:20 music sudo[26383]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:30:20 music sudo[26381]: pam_unix(sudo:session): session closed for user root Jan 11 14:30:20 music sudo[26383]: pam_unix(sudo:session): session closed for user root Jan 11 14:30:20 music sudo[26385]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Jan 11 14:30:20 music sudo[26385]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:30:20 music sudo[26385]: pam_unix(sudo:session): session closed for user root Jan 11 14:30:20 music volumio[26109]: info: Upmpdcli Daemon Started Jan 11 14:30:20 music go-librespot[26302]: time="2026-01-11T14:30:20-05:00" level=debug msg="connected to ap-gew4.spotify.com:80" Jan 11 14:30:20 music volumio[26109]: info: go-librespot daemon successfully initialized Jan 11 14:30:20 music go-librespot[26302]: time="2026-01-11T14:30:20-05:00" level=debug msg="completed keyexchange" Jan 11 14:30:20 music go-librespot[26302]: time="2026-01-11T14:30:20-05:00" level=debug msg="completed challenge" Jan 11 14:30:20 music go-librespot[26302]: time="2026-01-11T14:30:20-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:30:21 music go-librespot[26302]: time="2026-01-11T14:30:21-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Jan 11 14:30:21 music go-librespot[26302]: time="2026-01-11T14:30:21-05:00" level=debug msg="completed keyexchange" Jan 11 14:30:21 music go-librespot[26302]: time="2026-01-11T14:30:21-05:00" level=debug msg="completed challenge" Jan 11 14:30:21 music go-librespot[26302]: time="2026-01-11T14:30:21-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:30:21 music go-librespot[26302]: time="2026-01-11T14:30:21-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Jan 11 14:30:21 music go-librespot[26302]: time="2026-01-11T14:30:21-05:00" level=debug msg="completed keyexchange" Jan 11 14:30:21 music go-librespot[26302]: time="2026-01-11T14:30:21-05:00" level=debug msg="completed challenge" Jan 11 14:30:22 music go-librespot[26302]: time="2026-01-11T14:30:22-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:30:22 music go-librespot[26302]: time="2026-01-11T14:30:22-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:30:22 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 11 14:30:22 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 11 14:30:22 music sudo[26390]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Jan 11 14:30:22 music sudo[26390]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:30:22 music sudo[26392]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Jan 11 14:30:22 music sudo[26392]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:30:22 music systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Jan 11 14:30:22 music systemd[1]: mpd_monitor.service: Deactivated successfully. Jan 11 14:30:22 music systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Jan 11 14:30:22 music systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Jan 11 14:30:22 music sudo[26390]: pam_unix(sudo:session): session closed for user root Jan 11 14:30:22 music sudo[26392]: pam_unix(sudo:session): session closed for user root Jan 11 14:30:22 music mpd_monitor.sh[26395]: MPD Monitor Service: Starting MPD Monitor Service Jan 11 14:30:22 music volumio[26109]: info: Successfully started MPD Monitor Jan 11 14:30:22 music volumio[26109]: info: Successfully started MPD Monitor Jan 11 14:30:23 music volumio[26109]: info: Initializing connection to go-librespot Websocket Jan 11 14:30:23 music volumio[26109]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 11 14:30:24 music volumio[26109]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Jan 11 14:30:24 music volumio[26109]: info: CoreCommandRouter::volumioGetState Jan 11 14:30:24 music volumio[26109]: info: CorePlayQueue::getTrack 0 Jan 11 14:30:25 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Jan 11 14:30:25 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 11 14:30:25 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 11 14:30:25 music go-librespot[26399]: go-librespot daemon starting... Jan 11 14:30:25 music go-librespot[26400]: time="2026-01-11T14:30:25-05:00" level=info msg="running go-librespot 0.6.2" Jan 11 14:30:25 music go-librespot[26400]: time="2026-01-11T14:30:25-05:00" level=debug msg="app state loaded" Jan 11 14:30:25 music go-librespot[26400]: time="2026-01-11T14:30:25-05:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 11 14:30:25 music go-librespot[26400]: time="2026-01-11T14:30:25-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 11 14:30:25 music go-librespot[26400]: time="2026-01-11T14:30:25-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 11 14:30:25 music go-librespot[26400]: time="2026-01-11T14:30:25-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 11 14:30:25 music go-librespot[26400]: time="2026-01-11T14:30:25-05:00" level=info msg="zeroconf server listening on port 40887" Jan 11 14:30:25 music go-librespot[26400]: time="2026-01-11T14:30:25-05:00" level=debug msg="obtained new client token: AADFeODunu+8FdDZzh2tmLUU02Q+2m9wECZunoRgiZze9pxnZaS1v0nIKhMfKp5zWoKOv/ojG7BSMLKwXeCkhfbxfSJJKVjOlz6ZrxiR+2LLOkQPdRMRELkEt03YJwF8SsYBu+L4bpmD87XR5zF1x+uTziOdKnchR0jStyCldEnfULvoef1Fty1dKei879GC0+Wawh+q6rZDHhbVd0egz5dSx5bOWkOKeIE+aF94bY9q7pSc/05Abh0=" Jan 11 14:30:25 music go-librespot[26400]: time="2026-01-11T14:30:25-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Jan 11 14:30:25 music go-librespot[26400]: time="2026-01-11T14:30:25-05:00" level=debug msg="completed keyexchange" Jan 11 14:30:25 music go-librespot[26400]: time="2026-01-11T14:30:25-05:00" level=debug msg="completed challenge" Jan 11 14:30:25 music go-librespot[26400]: time="2026-01-11T14:30:25-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:30:26 music go-librespot[26400]: time="2026-01-11T14:30:26-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Jan 11 14:30:26 music go-librespot[26400]: time="2026-01-11T14:30:26-05:00" level=debug msg="completed keyexchange" Jan 11 14:30:26 music go-librespot[26400]: time="2026-01-11T14:30:26-05:00" level=debug msg="completed challenge" Jan 11 14:30:26 music volumio[26109]: info: Initializing connection to go-librespot Websocket Jan 11 14:30:26 music go-librespot[26400]: time="2026-01-11T14:30:26-05:00" level=debug msg="new websocket client" Jan 11 14:30:26 music volumio[26109]: info: Connection to go-librespot Websocket established Jan 11 14:30:26 music go-librespot[26400]: time="2026-01-11T14:30:26-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:30:27 music go-librespot[26400]: time="2026-01-11T14:30:27-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Jan 11 14:30:27 music go-librespot[26400]: time="2026-01-11T14:30:27-05:00" level=debug msg="completed keyexchange" Jan 11 14:30:27 music go-librespot[26400]: time="2026-01-11T14:30:27-05:00" level=debug msg="completed challenge" Jan 11 14:30:27 music go-librespot[26400]: time="2026-01-11T14:30:27-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:30:27 music volumio[26109]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Jan 11 14:30:27 music volumio[26109]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Jan 11 14:30:27 music volumio[26109]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Jan 11 14:30:27 music volumio[26109]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Jan 11 14:30:27 music volumio[26109]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Jan 11 14:30:27 music volumio[26109]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Jan 11 14:30:27 music volumio[26109]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Jan 11 14:30:27 music volumio[26109]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Jan 11 14:30:27 music volumio[26109]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Jan 11 14:30:27 music volumio[26109]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Jan 11 14:30:27 music volumio[26109]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Jan 11 14:30:27 music volumio[26109]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Jan 11 14:30:27 music volumio[26109]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Jan 11 14:30:27 music volumio[26109]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Jan 11 14:30:27 music volumio[26109]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Jan 11 14:30:27 music volumio[26109]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Jan 11 14:30:27 music volumio[26109]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Jan 11 14:30:27 music volumio[26109]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Jan 11 14:30:27 music volumio[26109]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Jan 11 14:30:27 music volumio[26109]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Jan 11 14:30:27 music volumio[26109]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Jan 11 14:30:27 music volumio[26109]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Jan 11 14:30:27 music volumio[26109]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Jan 11 14:30:27 music volumio[26109]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Jan 11 14:30:27 music volumio[26109]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Jan 11 14:30:27 music volumio[26109]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Jan 11 14:30:27 music volumio[26109]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Jan 11 14:30:27 music volumio[26109]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Jan 11 14:30:27 music volumio[26109]: info: Adding plugin bluetooth to MyMusic Plugins Jan 11 14:30:27 music volumio[26109]: info: Adding plugin multiroom to MyMusic Plugins Jan 11 14:30:27 music volumio[26109]: info: Adding plugin metavolumio to MyMusic Plugins Jan 11 14:30:27 music volumio[26109]: info: Adding plugin cd_controller to MyMusic Plugins Jan 11 14:30:27 music volumio[26109]: info: Adding plugin qobuzconnect to MyMusic Plugins Jan 11 14:30:27 music volumio[26109]: info: Adding plugin smart_inputs to MyMusic Plugins Jan 11 14:30:27 music volumio[26109]: info: Adding plugin tidalconnect to MyMusic Plugins Jan 11 14:30:27 music volumio[26109]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Jan 11 14:30:27 music go-librespot[26400]: time="2026-01-11T14:30:27-05:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 11 14:30:28 music go-librespot[26400]: time="2026-01-11T14:30:28-05:00" level=debug msg="completed keyexchange" Jan 11 14:30:28 music go-librespot[26400]: time="2026-01-11T14:30:28-05:00" level=debug msg="completed challenge" Jan 11 14:30:28 music go-librespot[26400]: time="2026-01-11T14:30:28-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:30:28 music volumio[26109]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Jan 11 14:30:28 music volumio[26109]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Jan 11 14:30:28 music volumio[26109]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 11 14:30:28 music volumio[26109]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 11 14:30:28 music volumio[26109]: info: Starting MyVolumio Remote Streaming Endpoints Jan 11 14:30:28 music volumio[26109]: info: MyVolumio login type: Token Jan 11 14:30:28 music volumio[26109]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Jan 11 14:30:28 music volumio[26109]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Jan 11 14:30:28 music go-librespot[26400]: time="2026-01-11T14:30:28-05:00" level=debug msg="connected to ap-gew1.spotify.com:443" Jan 11 14:30:29 music go-librespot[26400]: time="2026-01-11T14:30:29-05:00" level=debug msg="completed keyexchange" Jan 11 14:30:29 music go-librespot[26400]: time="2026-01-11T14:30:29-05:00" level=debug msg="completed challenge" Jan 11 14:30:29 music go-librespot[26400]: time="2026-01-11T14:30:29-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:30:29 music volumio[26109]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Jan 11 14:30:29 music volumio[26109]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Jan 11 14:30:29 music volumio[26109]: info: Streaming services startup Jan 11 14:30:29 music volumio[26109]: info: Starting Streaming Daemon Jan 11 14:30:29 music sudo[26411]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Jan 11 14:30:29 music sudo[26411]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:30:29 music volumio[26109]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Jan 11 14:30:29 music sudo[26411]: pam_unix(sudo:session): session closed for user root Jan 11 14:30:29 music go-librespot[26400]: time="2026-01-11T14:30:29-05:00" level=debug msg="connected to ap-gew4.spotify.com:80" Jan 11 14:30:29 music volumio[26109]: info: Getting Spotify volume Jan 11 14:30:29 music volumio[26109]: error: Cannot start Volumio Streaming Daemon Jan 11 14:30:29 music volumio[26109]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Jan 11 14:30:29 music volumio[26109]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Jan 11 14:30:29 music volumio[26109]: 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 11 14:30:30 music go-librespot[26400]: time="2026-01-11T14:30:30-05:00" level=debug msg="completed keyexchange" Jan 11 14:30:30 music go-librespot[26400]: time="2026-01-11T14:30:30-05:00" level=debug msg="completed challenge" Jan 11 14:30:30 music go-librespot[26400]: time="2026-01-11T14:30:30-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:30:30 music go-librespot[26400]: time="2026-01-11T14:30:30-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:30:30 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 11 14:30:30 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 11 14:30:30 music volumio[26109]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 11 14:30:30 music volumio[26109]: Error: socket hang up Jan 11 14:30:30 music volumio[26109]: at connResetException (node:internal/errors:720:14) Jan 11 14:30:30 music volumio[26109]: at Socket.socketOnEnd (node:_http_client:519:23) Jan 11 14:30:30 music volumio[26109]: at Socket.emit (node:events:526:35) Jan 11 14:30:30 music volumio[26109]: at endReadableNT (node:internal/streams/readable:1376:12) Jan 11 14:30:30 music volumio[26109]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { Jan 11 14:30:30 music volumio[26109]: code: 'ECONNRESET', Jan 11 14:30:30 music volumio[26109]: response: undefined Jan 11 14:30:30 music volumio[26109]: } Jan 11 14:30:30 music volumio[26109]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 11 14:30:30 music sudo[26445]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-01-11 14:29' Jan 11 14:30:30 music sudo[26445]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) PRETTY_NAME="Raspbian GNU/Linux 12 (bookworm)" NAME="Raspbian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="cfdc872d40b979cca36352a7333c940c38dc64b5" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="6cbc2303e10f00c3a01cb7f02c6d12448bd32c62" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri Dec 5 20:42:14 UTC 2025" VOLUMIO_VERSION="4.073" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="67fdc5f60f00b7a328ccd8c4ad441086"