Jan 25 08:31:00 music sudo[30407]: pam_unix(sudo:session): session closed for user root Jan 25 08:31:00 music volumio[30195]: info: Shairport-Sync Started Jan 25 08:31:00 music volumio[30195]: Error adding Membership: Error: addMembership EINVAL Jan 25 08:31:00 music volumio[30195]: info: Shairport-Sync Started Jan 25 08:31:00 music volumio[30195]: info: Shairport-Sync Started Jan 25 08:31:00 music go-librespot[30387]: time="2026-01-25T08:31:00-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Jan 25 08:31:00 music go-librespot[30387]: time="2026-01-25T08:31:00-05:00" level=debug msg="completed keyexchange" Jan 25 08:31:00 music go-librespot[30387]: time="2026-01-25T08:31:00-05:00" level=debug msg="completed challenge" Jan 25 08:31:00 music go-librespot[30387]: time="2026-01-25T08:31:00-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 25 08:31:00 music go-librespot[30387]: time="2026-01-25T08:31:00-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Jan 25 08:31:01 music go-librespot[30387]: time="2026-01-25T08:31:01-05:00" level=debug msg="completed keyexchange" Jan 25 08:31:01 music go-librespot[30387]: time="2026-01-25T08:31:01-05:00" level=debug msg="completed challenge" Jan 25 08:31:01 music go-librespot[30387]: time="2026-01-25T08:31:01-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 25 08:31:01 music go-librespot[30387]: time="2026-01-25T08:31:01-05:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 25 08:31:01 music go-librespot[30387]: time="2026-01-25T08:31:01-05:00" level=debug msg="completed keyexchange" Jan 25 08:31:01 music go-librespot[30387]: time="2026-01-25T08:31:01-05:00" level=debug msg="completed challenge" Jan 25 08:31:01 music mpd[30363]: 2026-01-25T08:31:01 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jan 25 08:31:01 music go-librespot[30387]: time="2026-01-25T08:31:01-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 25 08:31:01 music systemd[1]: Started mpd.service - Music Player Daemon. Jan 25 08:31:01 music sudo[30324]: pam_unix(sudo:session): session closed for user root Jan 25 08:31:01 music sudo[30334]: pam_unix(sudo:session): session closed for user root Jan 25 08:31:01 music volumio[30195]: info: Completed starting Core Plugins Jan 25 08:31:01 music volumio[30195]: info: ------------------------------------------- Jan 25 08:31:01 music volumio[30195]: info: ----- MyVolumio plugins startup ---- Jan 25 08:31:01 music volumio[30195]: info: ------------------------------------------- Jan 25 08:31:01 music volumio[30195]: info: [MyVolumio PluginManager] Fetching plans data.... Jan 25 08:31:01 music volumio[30195]: error: MPD error: The expression evaluated to a falsy value: Jan 25 08:31:01 music volumio[30195]: assert.ok(self.idling) Jan 25 08:31:01 music volumio[30195]: error: The expression evaluated to a falsy value: Jan 25 08:31:01 music volumio[30195]: assert.ok(self.idling) Jan 25 08:31:01 music volumio[30195]: info: MPD running with PID30363 Jan 25 08:31:01 music volumio[30195]: ,establishing connection Jan 25 08:31:01 music volumio[30195]: error: updateQueue error: null Jan 25 08:31:01 music volumio[30195]: error: updateQueue error: null Jan 25 08:31:02 music volumio[30195]: info: go-librespot daemon successfully initialized Jan 25 08:31:02 music go-librespot[30387]: time="2026-01-25T08:31:02-05:00" level=debug msg="connected to ap-gae2.spotify.com:443" Jan 25 08:31:02 music sudo[30465]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 25 08:31:02 music sudo[30465]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 08:31:02 music sudo[30467]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 25 08:31:02 music sudo[30467]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 08:31:02 music sudo[30467]: pam_unix(sudo:session): session closed for user root Jan 25 08:31:02 music sudo[30465]: pam_unix(sudo:session): session closed for user root Jan 25 08:31:02 music sudo[30469]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Jan 25 08:31:02 music sudo[30469]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 08:31:02 music sudo[30469]: pam_unix(sudo:session): session closed for user root Jan 25 08:31:02 music volumio[30195]: info: Upmpdcli Daemon Started Jan 25 08:31:02 music go-librespot[30387]: time="2026-01-25T08:31:02-05:00" level=debug msg="completed keyexchange" Jan 25 08:31:02 music go-librespot[30387]: time="2026-01-25T08:31:02-05:00" level=debug msg="completed challenge" Jan 25 08:31:02 music go-librespot[30387]: time="2026-01-25T08:31:02-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 25 08:31:03 music go-librespot[30387]: time="2026-01-25T08:31:03-05:00" level=debug msg="connected to ap-gew1.spotify.com:80" Jan 25 08:31:03 music go-librespot[30387]: time="2026-01-25T08:31:03-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: read tcp 192.168.3.63:33940->104.199.65.9:80: read: connection reset by peer" Jan 25 08:31:03 music go-librespot[30387]: time="2026-01-25T08:31:03-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: read tcp 192.168.3.63:33940->104.199.65.9:80: read: connection reset by peer" Jan 25 08:31:03 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 25 08:31:03 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 25 08:31:04 music sudo[30474]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Jan 25 08:31:04 music sudo[30474]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 08:31:04 music sudo[30476]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Jan 25 08:31:04 music sudo[30476]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 08:31:04 music systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Jan 25 08:31:04 music systemd[1]: mpd_monitor.service: Deactivated successfully. Jan 25 08:31:04 music systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Jan 25 08:31:04 music systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Jan 25 08:31:04 music sudo[30474]: pam_unix(sudo:session): session closed for user root Jan 25 08:31:05 music volumio[30195]: info: Successfully started MPD Monitor Jan 25 08:31:05 music mpd_monitor.sh[30479]: MPD Monitor Service: Starting MPD Monitor Service Jan 25 08:31:05 music sudo[30476]: pam_unix(sudo:session): session closed for user root Jan 25 08:31:05 music volumio[30195]: info: Successfully started MPD Monitor Jan 25 08:31:05 music volumio[30195]: info: Initializing connection to go-librespot Websocket Jan 25 08:31:05 music volumio[30195]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 25 08:31:06 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Jan 25 08:31:06 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 25 08:31:06 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 25 08:31:06 music volumio[30195]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Jan 25 08:31:06 music go-librespot[30484]: go-librespot daemon starting... Jan 25 08:31:06 music go-librespot[30485]: time="2026-01-25T08:31:06-05:00" level=info msg="running go-librespot 0.6.2" Jan 25 08:31:06 music go-librespot[30485]: time="2026-01-25T08:31:06-05:00" level=debug msg="app state loaded" Jan 25 08:31:06 music go-librespot[30485]: time="2026-01-25T08:31:06-05:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 25 08:31:07 music go-librespot[30485]: time="2026-01-25T08:31: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 25 08:31:07 music go-librespot[30485]: time="2026-01-25T08:31: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 25 08:31:07 music go-librespot[30485]: time="2026-01-25T08:31: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 25 08:31:07 music go-librespot[30485]: time="2026-01-25T08:31:07-05:00" level=info msg="zeroconf server listening on port 41241" Jan 25 08:31:07 music go-librespot[30485]: time="2026-01-25T08:31:07-05:00" level=debug msg="obtained new client token: AABvt7ddHAzJ5BwtLjv62g5utP9Oayjq6oH9RnJq3CTGF7sjdf5l8u9vthXrgeJs8Pwh0dL6g/Yeh6WXQgXoG7JDw+I++BogATfUA3RVI2MK1MnbpivKJ53rWGcXeAvQpFVrz4gLfXXrAECyphWxnfLw7ZKnXOJUZ/aGtd9lZKXX6Dk7X574Fn7pMA2zfgC8XJ3kZMMgeiV6v4dXg7aM3DGjxaIlf+13MVM0rKGXfYHikPa0KzFKTA8=" Jan 25 08:31:07 music go-librespot[30485]: time="2026-01-25T08:31:07-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Jan 25 08:31:07 music go-librespot[30485]: time="2026-01-25T08:31:07-05:00" level=debug msg="completed keyexchange" Jan 25 08:31:07 music go-librespot[30485]: time="2026-01-25T08:31:07-05:00" level=debug msg="completed challenge" Jan 25 08:31:07 music go-librespot[30485]: time="2026-01-25T08:31:07-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 25 08:31:08 music go-librespot[30485]: time="2026-01-25T08:31:08-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Jan 25 08:31:08 music go-librespot[30485]: time="2026-01-25T08:31:08-05:00" level=debug msg="completed keyexchange" Jan 25 08:31:08 music go-librespot[30485]: time="2026-01-25T08:31:08-05:00" level=debug msg="completed challenge" Jan 25 08:31:08 music go-librespot[30485]: time="2026-01-25T08:31:08-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 25 08:31:08 music volumio[30195]: info: Initializing connection to go-librespot Websocket Jan 25 08:31:08 music go-librespot[30485]: time="2026-01-25T08:31:08-05:00" level=debug msg="new websocket client" Jan 25 08:31:08 music volumio[30195]: info: Connection to go-librespot Websocket established Jan 25 08:31:08 music volumio[30195]: info: CoreCommandRouter::volumioGetState Jan 25 08:31:08 music volumio[30195]: info: CorePlayQueue::getTrack 0 Jan 25 08:31:08 music go-librespot[30485]: time="2026-01-25T08:31:08-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Jan 25 08:31:08 music go-librespot[30485]: time="2026-01-25T08:31:08-05:00" level=debug msg="completed keyexchange" Jan 25 08:31:08 music go-librespot[30485]: time="2026-01-25T08:31:08-05:00" level=debug msg="completed challenge" Jan 25 08:31:08 music go-librespot[30485]: time="2026-01-25T08:31:08-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 25 08:31:09 music go-librespot[30485]: time="2026-01-25T08:31:09-05:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 25 08:31:09 music go-librespot[30485]: time="2026-01-25T08:31:09-05:00" level=debug msg="completed keyexchange" Jan 25 08:31:09 music go-librespot[30485]: time="2026-01-25T08:31:09-05:00" level=debug msg="completed challenge" Jan 25 08:31:09 music go-librespot[30485]: time="2026-01-25T08:31:09-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 25 08:31:10 music volumio[30195]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Jan 25 08:31:10 music volumio[30195]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Jan 25 08:31:10 music volumio[30195]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Jan 25 08:31:10 music volumio[30195]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Jan 25 08:31:10 music volumio[30195]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Jan 25 08:31:10 music volumio[30195]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Jan 25 08:31:10 music volumio[30195]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Jan 25 08:31:10 music volumio[30195]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Jan 25 08:31:10 music volumio[30195]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Jan 25 08:31:10 music volumio[30195]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Jan 25 08:31:10 music volumio[30195]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Jan 25 08:31:10 music volumio[30195]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Jan 25 08:31:10 music volumio[30195]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Jan 25 08:31:10 music volumio[30195]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Jan 25 08:31:10 music volumio[30195]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Jan 25 08:31:10 music volumio[30195]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Jan 25 08:31:10 music volumio[30195]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Jan 25 08:31:10 music volumio[30195]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Jan 25 08:31:10 music volumio[30195]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Jan 25 08:31:10 music volumio[30195]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Jan 25 08:31:10 music volumio[30195]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Jan 25 08:31:10 music volumio[30195]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Jan 25 08:31:10 music volumio[30195]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Jan 25 08:31:10 music volumio[30195]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Jan 25 08:31:10 music volumio[30195]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Jan 25 08:31:10 music volumio[30195]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Jan 25 08:31:10 music volumio[30195]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Jan 25 08:31:10 music volumio[30195]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Jan 25 08:31:10 music volumio[30195]: info: Adding plugin bluetooth to MyMusic Plugins Jan 25 08:31:10 music volumio[30195]: info: Adding plugin multiroom to MyMusic Plugins Jan 25 08:31:10 music volumio[30195]: info: Adding plugin metavolumio to MyMusic Plugins Jan 25 08:31:10 music volumio[30195]: info: Adding plugin cd_controller to MyMusic Plugins Jan 25 08:31:10 music volumio[30195]: info: Adding plugin qobuzconnect to MyMusic Plugins Jan 25 08:31:10 music volumio[30195]: info: Adding plugin smart_inputs to MyMusic Plugins Jan 25 08:31:10 music volumio[30195]: info: Adding plugin tidalconnect to MyMusic Plugins Jan 25 08:31:10 music volumio[30195]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Jan 25 08:31:10 music go-librespot[30485]: time="2026-01-25T08:31:10-05:00" level=debug msg="connected to ap-gew1.spotify.com:443" Jan 25 08:31:10 music go-librespot[30485]: time="2026-01-25T08:31:10-05:00" level=debug msg="completed keyexchange" Jan 25 08:31:10 music go-librespot[30485]: time="2026-01-25T08:31:10-05:00" level=debug msg="completed challenge" Jan 25 08:31:10 music go-librespot[30485]: time="2026-01-25T08:31:10-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 25 08:31:11 music go-librespot[30485]: time="2026-01-25T08:31:11-05:00" level=warning msg="failed to connect to AP ap-gew4.spotify.com:80, retrying with a different AP" error="dial tcp 34.158.1.133:80: connect: connection refused" Jan 25 08:31:11 music volumio[30195]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Jan 25 08:31:11 music volumio[30195]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Jan 25 08:31:11 music volumio[30195]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 25 08:31:11 music volumio[30195]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 25 08:31:11 music volumio[30195]: info: Starting MyVolumio Remote Streaming Endpoints Jan 25 08:31:11 music volumio[30195]: info: MyVolumio login type: Token Jan 25 08:31:11 music go-librespot[30485]: time="2026-01-25T08:31:11-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 25 08:31:11 music volumio[30195]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Jan 25 08:31:11 music volumio[30195]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Jan 25 08:31:11 music go-librespot[30485]: time="2026-01-25T08:31:11-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Jan 25 08:31:11 music go-librespot[30485]: time="2026-01-25T08:31:11-05:00" level=debug msg="completed keyexchange" Jan 25 08:31:11 music go-librespot[30485]: time="2026-01-25T08:31:11-05:00" level=debug msg="completed challenge" Jan 25 08:31:11 music go-librespot[30485]: time="2026-01-25T08:31:11-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 25 08:31:11 music go-librespot[30485]: time="2026-01-25T08:31: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 25 08:31:11 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 25 08:31:11 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 25 08:31:12 music volumio[30195]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Jan 25 08:31:12 music volumio[30195]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Jan 25 08:31:12 music volumio[30195]: info: Streaming services startup Jan 25 08:31:12 music volumio[30195]: info: Starting Streaming Daemon Jan 25 08:31:12 music sudo[30495]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Jan 25 08:31:12 music sudo[30495]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 08:31:12 music volumio[30195]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Jan 25 08:31:12 music sudo[30495]: pam_unix(sudo:session): session closed for user root Jan 25 08:31:12 music volumio[30195]: info: Getting Spotify volume Jan 25 08:31:12 music volumio[30195]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 25 08:31:12 music volumio[30195]: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 25 08:31:12 music volumio[30195]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Jan 25 08:31:12 music volumio[30195]: errno: -111, Jan 25 08:31:12 music volumio[30195]: code: 'ECONNREFUSED', Jan 25 08:31:12 music volumio[30195]: syscall: 'connect', Jan 25 08:31:12 music volumio[30195]: address: '127.0.0.1', Jan 25 08:31:12 music volumio[30195]: port: 9879, Jan 25 08:31:12 music volumio[30195]: response: undefined Jan 25 08:31:12 music volumio[30195]: } Jan 25 08:31:12 music volumio[30195]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 25 08:31:13 music sudo[30530]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-01-25 08:30' Jan 25 08:31:13 music sudo[30530]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 08:31:13 music sudo[30530]: pam_unix(sudo:session): session closed for user root Jan 25 08:31:14 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Jan 25 08:31:14 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 25 08:31:14 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 25 08:31:14 music go-librespot[30538]: go-librespot daemon starting... Jan 25 08:31:14 music go-librespot[30539]: time="2026-01-25T08:31:14-05:00" level=info msg="running go-librespot 0.6.2" Jan 25 08:31:14 music go-librespot[30539]: time="2026-01-25T08:31:14-05:00" level=debug msg="app state loaded" Jan 25 08:31:14 music go-librespot[30539]: time="2026-01-25T08:31:14-05:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 25 08:31:14 music go-librespot[30539]: time="2026-01-25T08:31:14-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 25 08:31:14 music go-librespot[30539]: time="2026-01-25T08:31:14-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 25 08:31:14 music go-librespot[30539]: time="2026-01-25T08:31:14-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 25 08:31:14 music go-librespot[30539]: time="2026-01-25T08:31:14-05:00" level=info msg="zeroconf server listening on port 40315" Jan 25 08:31:15 music volumio-remote-updater[1248]: [2026-01-25 08:31:15] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Jan 25 08:31:15 music volumio-remote-updater[1248]: [2026-01-25 08:31:15] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Jan 25 08:31:15 music systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Jan 25 08:31:15 music systemd[1]: volumio.service: Failed with result 'exit-code'. Jan 25 08:31:15 music systemd[1]: volumio.service: Consumed 26.414s CPU time. Jan 25 08:31:15 music go-librespot[30539]: time="2026-01-25T08:31:15-05:00" level=debug msg="obtained new client token: AADHNzRpm4Sh30rcZwhJ32ooW/rnlhj+3t580WUFvi8/Qn+03WMClialgln0hCup6eptjheFNCGKwLL3TvPmVbwGbbM5s/sjkuQD1ljmy/3UmTpx5PnBsvQIMWMt7xyvU8H4VfA0KyxOLT9oB2eYwhSZ/YhrZ4PEZZl+QLUdabXGpBdQTAKFzCItgxPQhNIYAgg5eRBGft3a4lBWMbNtHvTl9WB7kaG7jkewEzbkE/zi6IpVixP0" Jan 25 08:31:15 music systemd[1]: Started dynamicswap.service - dynamicswap service. Jan 25 08:31:15 music go-librespot[30539]: time="2026-01-25T08:31:15-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Jan 25 08:31:15 music systemd[1]: dynamicswap.service: Deactivated successfully. Jan 25 08:31:15 music go-librespot[30539]: time="2026-01-25T08:31:15-05:00" level=debug msg="completed keyexchange" Jan 25 08:31:15 music go-librespot[30539]: time="2026-01-25T08:31:15-05:00" level=debug msg="completed challenge" Jan 25 08:31:15 music go-librespot[30539]: time="2026-01-25T08:31:15-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 25 08:31:15 music systemd[1]: volumio.service: Scheduled restart job, restart counter is at 27509. Jan 25 08:31:15 music systemd[1]: Started dynamicswap.service - dynamicswap service. Jan 25 08:31:15 music systemd[1]: Stopped volumio.service - Volumio Backend Module. Jan 25 08:31:15 music systemd[1]: volumio.service: Consumed 26.414s CPU time. Jan 25 08:31:15 music systemd[1]: Started volumio.service - Volumio Backend Module. Jan 25 08:31:15 music systemd[1]: dynamicswap.service: Deactivated successfully. Jan 25 08:31:15 music go-librespot[30539]: time="2026-01-25T08:31:15-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Jan 25 08:31:15 music go-librespot[30539]: time="2026-01-25T08:31:15-05:00" level=debug msg="completed keyexchange" Jan 25 08:31:15 music go-librespot[30539]: time="2026-01-25T08:31:15-05:00" level=debug msg="completed challenge" Jan 25 08:31:16 music go-librespot[30539]: time="2026-01-25T08:31:16-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 25 08:31:16 music go-librespot[30539]: time="2026-01-25T08:31:16-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Jan 25 08:31:16 music go-librespot[30539]: time="2026-01-25T08:31:16-05:00" level=debug msg="completed keyexchange" Jan 25 08:31:16 music go-librespot[30539]: time="2026-01-25T08:31:16-05:00" level=debug msg="completed challenge" Jan 25 08:31:16 music go-librespot[30539]: time="2026-01-25T08:31:16-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 25 08:31:17 music go-librespot[30539]: time="2026-01-25T08:31:17-05:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 25 08:31:17 music go-librespot[30539]: time="2026-01-25T08:31:17-05:00" level=debug msg="completed keyexchange" Jan 25 08:31:17 music go-librespot[30539]: time="2026-01-25T08:31:17-05:00" level=debug msg="completed challenge" Jan 25 08:31:17 music go-librespot[30539]: time="2026-01-25T08:31:17-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 25 08:31:17 music volumio[30561]: info: ------------------------------------------- Jan 25 08:31:17 music volumio[30561]: info: ----- Volumio3 ---- Jan 25 08:31:17 music volumio[30561]: info: ------------------------------------------- Jan 25 08:31:17 music volumio[30561]: info: ----- System startup ---- Jan 25 08:31:17 music volumio[30561]: info: ------------------------------------------- Jan 25 08:31:18 music go-librespot[30539]: time="2026-01-25T08:31:18-05:00" level=debug msg="connected to ap-gew1.spotify.com:443" Jan 25 08:31:18 music volumio[30561]: info: MYVOLUMIO Environment detected Jan 25 08:31:18 music volumio[30561]: info: Plugin folders cleanup Jan 25 08:31:18 music volumio[30561]: info: Scanning into folder /volumio/app/plugins/ Jan 25 08:31:18 music volumio[30561]: info: Scanning category audio_interface Jan 25 08:31:18 music volumio[30561]: info: Scanning category miscellanea Jan 25 08:31:18 music go-librespot[30539]: time="2026-01-25T08:31:18-05:00" level=debug msg="completed keyexchange" Jan 25 08:31:18 music go-librespot[30539]: time="2026-01-25T08:31:18-05:00" level=debug msg="completed challenge" Jan 25 08:31:18 music volumio[30561]: info: Scanning category music_service Jan 25 08:31:18 music volumio[30561]: info: Scanning category plugins.json Jan 25 08:31:18 music volumio[30561]: info: Scanning category system_controller Jan 25 08:31:18 music volumio[30561]: info: Scanning category user_interface Jan 25 08:31:18 music volumio[30561]: info: Scanning into folder /data/plugins/ Jan 25 08:31:18 music volumio[30561]: info: Scanning category music_service Jan 25 08:31:18 music volumio[30561]: info: Plugin folders cleanup completed Jan 25 08:31:18 music volumio[30561]: info: ------------------------------------------- Jan 25 08:31:18 music volumio[30561]: info: ----- Core plugins startup ---- Jan 25 08:31:18 music volumio[30561]: info: ------------------------------------------- Jan 25 08:31:18 music volumio[30561]: info: Loading plugins from folder /volumio/app/plugins/ Jan 25 08:31:18 music volumio[30561]: info: Adding plugin upnp to MyMusic Plugins Jan 25 08:31:18 music volumio[30561]: info: Adding plugin airplay_emulation to MyMusic Plugins Jan 25 08:31:18 music volumio[30561]: info: Adding plugin upnp_browser to MyMusic Plugins Jan 25 08:31:18 music volumio[30561]: info: Loading plugins from folder /data/plugins/ Jan 25 08:31:18 music volumio[30561]: info: Loading plugin "system"... Jan 25 08:31:18 music volumio[30561]: info: Loading plugin "appearance"... Jan 25 08:31:18 music go-librespot[30539]: time="2026-01-25T08:31:18-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 25 08:31:19 music go-librespot[30539]: time="2026-01-25T08:31:19-05:00" level=debug msg="connected to ap-gew4.spotify.com:80" Jan 25 08:31:19 music go-librespot[30539]: time="2026-01-25T08:31:19-05:00" level=debug msg="completed keyexchange" Jan 25 08:31:19 music go-librespot[30539]: time="2026-01-25T08:31:19-05:00" level=debug msg="completed challenge" Jan 25 08:31:19 music go-librespot[30539]: time="2026-01-25T08:31:19-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 25 08:31:19 music go-librespot[30539]: time="2026-01-25T08:31:19-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 25 08:31:19 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 25 08:31:19 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 25 08:31:19 music volumio[30561]: info: Loading plugin "network"... Jan 25 08:31:19 music volumio[30561]: info: Refreshing Cached IP Addresses Jan 25 08:31:19 music sudo[30589]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 25 08:31:19 music sudo[30589]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 08:31:19 music sudo[30591]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 25 08:31:19 music sudo[30591]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 08:31:19 music sudo[30589]: pam_unix(sudo:session): session closed for user root Jan 25 08:31:19 music sudo[30591]: pam_unix(sudo:session): session closed for user root Jan 25 08:31:19 music volumio[30561]: info: Loading plugin "services"... Jan 25 08:31:19 music volumio[30561]: info: Loading plugin "alsa_controller"... Jan 25 08:31:19 music sudo[30600]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Jan 25 08:31:19 music sudo[30600]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 08:31:19 music volumio[30561]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 25 08:31:19 music volumio[30561]: info: Loading plugin "wizard"... Jan 25 08:31:19 music volumio[30561]: info: Loading plugin "networkfs"... Jan 25 08:31:19 music volumio[30561]: info: Starting Udev Watcher for removable devices Jan 25 08:31:19 music volumio[30561]: info: Ignoring mount for partition: boot Jan 25 08:31:19 music volumio[30561]: info: Ignoring mount for partition: volumio Jan 25 08:31:19 music volumio[30561]: info: Ignoring mount for partition: volumio_data Jan 25 08:31:19 music volumio[30561]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 25 08:31:19 music volumio[30561]: info: Loading plugin "volumio_command_line_client"... Jan 25 08:31:19 music volumio[30561]: info: Loading plugin "upnp"... Jan 25 08:31:19 music volumio[30561]: info: [1769347879683] Starting Upmpd Daemon Jan 25 08:31:19 music volumio[30561]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 25 08:31:19 music volumio[30561]: info: Loading plugin "my_music"... Jan 25 08:31:19 music volumio[30561]: info: Loading plugin "mpd"... Jan 25 08:31:20 music volumio-remote-updater[1248]: [2026-01-25 08:31:20] [connect] Successful connection Jan 25 08:31:20 music volumio[30561]: info: Loading plugin "upnp_browser"... Jan 25 08:31:20 music sudo[30600]: pam_unix(sudo:session): session closed for user root Jan 25 08:31:21 music volumio[30561]: info: Starting UPNP Browser Jan 25 08:31:21 music volumio[30561]: info: Loading plugin "alarm-clock"... Jan 25 08:31:21 music volumio[30561]: info: Loading plugin "airplay_emulation"... Jan 25 08:31:21 music volumio[30561]: info: Starting Shairport Sync Jan 25 08:31:21 music volumio[30561]: info: Loading plugin "last_100"... Jan 25 08:31:21 music volumio[30561]: info: Loading plugin "webradio"... Jan 25 08:31:21 music volumio[30561]: info: Loading plugin "i2s_dacs"... Jan 25 08:31:21 music volumio[30561]: info: I2S DAC not set, start Auto-detection Jan 25 08:31:21 music volumio[30561]: info: Loading plugin "volumiodiscovery"... Jan 25 08:31:21 music volumio[30561]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jan 25 08:31:21 music volumio[30561]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 25 08:31:21 music volumio[30561]: *** WARNING *** For more information see Jan 25 08:31:21 music volumio[30561]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jan 25 08:31:21 music volumio[30561]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 25 08:31:21 music volumio[30561]: *** WARNING *** For more information see Jan 25 08:31:21 music node[30561]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jan 25 08:31:21 music node[30561]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 25 08:31:21 music node[30561]: *** WARNING *** For more information see Jan 25 08:31:21 music node[30561]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jan 25 08:31:21 music node[30561]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 25 08:31:21 music node[30561]: *** WARNING *** For more information see Jan 25 08:31:21 music volumio[30561]: info: Applying required configuration parameters for plugin volumiodiscovery Jan 25 08:31:21 music volumio[30561]: info: Discovery: Started advertising with name: music Jan 25 08:31:22 music volumio[30561]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 25 08:31:22 music volumio[30561]: info: Loading plugin "spop"... Jan 25 08:31:22 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Jan 25 08:31:22 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 25 08:31:22 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 25 08:31:22 music go-librespot[30624]: go-librespot daemon starting... Jan 25 08:31:22 music go-librespot[30625]: time="2026-01-25T08:31:22-05:00" level=info msg="running go-librespot 0.6.2" Jan 25 08:31:22 music go-librespot[30625]: time="2026-01-25T08:31:22-05:00" level=debug msg="app state loaded" Jan 25 08:31:22 music go-librespot[30625]: time="2026-01-25T08:31:22-05:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 25 08:31:23 music go-librespot[30625]: time="2026-01-25T08:31:23-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 25 08:31:23 music go-librespot[30625]: time="2026-01-25T08:31:23-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 25 08:31:23 music go-librespot[30625]: time="2026-01-25T08:31:23-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 25 08:31:23 music go-librespot[30625]: time="2026-01-25T08:31:23-05:00" level=info msg="zeroconf server listening on port 46225" Jan 25 08:31:23 music volumio[30561]: info: Loading plugin "outputs"... Jan 25 08:31:23 music volumio[30561]: info: Loading plugin "albumart"... Jan 25 08:31:23 music volumio[30561]: info: Plugin example_plugin is not enabled Jan 25 08:31:23 music volumio[30561]: info: Loading plugin "inputs"... Jan 25 08:31:23 music volumio[30561]: info: Loading plugin "updater_comm"... Jan 25 08:31:23 music go-librespot[30625]: time="2026-01-25T08:31:23-05:00" level=debug msg="obtained new client token: AAAYXbggLAxGbW1BPcsYIof2gS7UIgf54otZqujn+8zMePJEW4p3BFPUdLQjbvr9C/57JzYFf5flezgYWVl5ehbh/V6m6in1ahclRbUhS6CZYH9fksHaaBq1Gt8wcYDVkg4zZUt8qmJnWd/McvAjIuI36vJawMtc0cghwT6+pZ5txS8+V1JeujJQ4/oiL8fB73r/dHjT+p7fSjkaDjHR/FaleOiXSklrrcnmxuxfhEjolzDuz3Z5" Jan 25 08:31:23 music go-librespot[30625]: time="2026-01-25T08:31:23-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Jan 25 08:31:23 music volumio[30561]: info: Plugin mpdemulation is not enabled Jan 25 08:31:23 music volumio[30561]: info: Loading plugin "rest_api"... Jan 25 08:31:23 music volumio[30561]: info: Loading plugin "websocket"... Jan 25 08:31:23 music volumio[30561]: info: Starting Socket.io Server version 1.7.4 Jan 25 08:31:23 music volumio[30561]: info: Loading i18n strings for locale en Jan 25 08:31:23 music volumio[30561]: Updating browse sources language Jan 25 08:31:23 music go-librespot[30625]: time="2026-01-25T08:31:23-05:00" level=debug msg="completed keyexchange" Jan 25 08:31:23 music go-librespot[30625]: time="2026-01-25T08:31:23-05:00" level=debug msg="completed challenge" Jan 25 08:31:23 music volumio[30561]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 25 08:31:23 music go-librespot[30625]: time="2026-01-25T08:31:23-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 25 08:31:23 music volumio[30561]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 25 08:31:23 music volumio[30561]: info: CoreCommandRouter::initPlayerControls Jan 25 08:31:23 music volumio[30561]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:31:23 music volumio[30561]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:31:23 music volumio[30561]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:31:23 music volumio[30561]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:31:23 music volumio[30561]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:31:23 music volumio[30561]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:31:23 music volumio[30561]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:31:23 music volumio[30561]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:31:23 music volumio[30561]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 25 08:31:23 music volumio[30561]: Express server listening on port 3000 Jan 25 08:31:23 music volumio[30561]: [Metrics] WebUI: 6s 637.06ms Jan 25 08:31:23 music volumio[30561]: info: CoreStateMachine::resetVolumioState Jan 25 08:31:23 music volumio[30561]: info: CoreStateMachine::getcurrentVolume Jan 25 08:31:23 music volumio[30561]: info: CoreCommandRouter::volumioRetrievevolume Jan 25 08:31:23 music volumio[30561]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 25 08:31:23 music volumio[30561]: info: Volumio Network Manager: Network status updated: 1 Jan 25 08:31:23 music volumio[30561]: info: VolumeController:: Volume=86 Mute =false Jan 25 08:31:23 music volumio[30561]: info: CoreStateMachine::pushState Jan 25 08:31:23 music volumio[30561]: info: CorePlayQueue::getTrack 0 Jan 25 08:31:23 music volumio[30561]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 25 08:31:23 music volumio[30561]: info: CoreCommandRouter::volumioPushState Jan 25 08:31:23 music volumio[30561]: info: CoreStateMachine::updateTrackBlock Jan 25 08:31:23 music volumio[30561]: info: CorePlayQueue::getTrackBlock Jan 25 08:31:23 music volumio[30561]: info: CoreCommandRouter::volumioRetrievevolume Jan 25 08:31:23 music volumio[30634]: Forking 3 albumart workers Jan 25 08:31:23 music volumio[30561]: info: CoreCommandRouter::volumioGetState Jan 25 08:31:23 music volumio[30561]: info: CorePlayQueue::getTrack 0 Jan 25 08:31:23 music volumio-remote-updater[1248]: [2026-01-25 08:31:23] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1769347880 101 Jan 25 08:31:23 music volumio[30561]: 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 25 08:31:23 music volumio[30561]: info: Reloading queue from file Jan 25 08:31:23 music volumio[30561]: info: Setting Device type: Raspberry PI Jan 25 08:31:23 music volumio[30561]: info: CoreStateMachine::setRepeat null single undefined Jan 25 08:31:23 music volumio[30561]: info: CoreStateMachine::pushState Jan 25 08:31:23 music volumio[30561]: info: CorePlayQueue::getTrack 0 Jan 25 08:31:23 music volumio[30561]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 25 08:31:23 music volumio[30561]: info: CoreCommandRouter::volumioPushState Jan 25 08:31:23 music volumio[30561]: info: CoreStateMachine::setRandom null Jan 25 08:31:23 music volumio[30561]: info: CoreStateMachine::pushState Jan 25 08:31:23 music volumio[30561]: info: CorePlayQueue::getTrack 0 Jan 25 08:31:23 music volumio[30561]: info: CoreCommandRouter::volumioPushState Jan 25 08:31:23 music volumio[30561]: info: Listing playlists Jan 25 08:31:23 music volumio[30561]: info: Listing playlists Jan 25 08:31:23 music go-librespot[30625]: time="2026-01-25T08:31:23-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Jan 25 08:31:24 music volumio[30561]: info: VolumeController:: Volume=86 Mute =false Jan 25 08:31:24 music volumio[30561]: info: CoreStateMachine::pushState Jan 25 08:31:24 music volumio[30561]: info: CorePlayQueue::getTrack 0 Jan 25 08:31:24 music volumio[30561]: info: CoreCommandRouter::volumioPushState Jan 25 08:31:24 music volumio[30561]: info: Discovery: adding 4a29b7a7-c637-4926-a2bd-fb4e2f55145e Jan 25 08:31:24 music volumio[30561]: info: Discovery: Found device music Jan 25 08:31:24 music volumio[30561]: info: CoreCommandRouter::volumioGetState Jan 25 08:31:24 music volumio[30561]: info: CorePlayQueue::getTrack 0 Jan 25 08:31:24 music go-librespot[30625]: time="2026-01-25T08:31:24-05:00" level=debug msg="completed keyexchange" Jan 25 08:31:24 music go-librespot[30625]: time="2026-01-25T08:31:24-05:00" level=debug msg="completed challenge" Jan 25 08:31:24 music volumio[30561]: info: Discovery: this is already registered, 4a29b7a7-c637-4926-a2bd-fb4e2f55145e Jan 25 08:31:24 music volumio[30561]: info: Discovery: Found device music Jan 25 08:31:24 music volumio[30561]: info: CoreCommandRouter::volumioGetState Jan 25 08:31:24 music volumio[30561]: info: CorePlayQueue::getTrack 0 Jan 25 08:31:24 music volumio[30561]: info: Completed loading Core Plugins Jan 25 08:31:24 music volumio[30561]: info: Preparing to generate the ALSA configuration file Jan 25 08:31:24 music volumio[30561]: info: Asound.conf file unchanged, so no further update is needed Jan 25 08:31:24 music volumio[30561]: info: Output device has changed, restarting MPD Jan 25 08:31:24 music go-librespot[30625]: time="2026-01-25T08:31:24-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 25 08:31:24 music volumio[30561]: info: Output device has changed, restarting Shairport Sync Jan 25 08:31:24 music volumio[30561]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:31:24 music volumio[30561]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 25 08:31:24 music volumio[30561]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 25 08:31:24 music sudo[30689]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 25 08:31:24 music volumio[30561]: info: ___________ START PLUGINS ___________ Jan 25 08:31:24 music sudo[30689]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 08:31:24 music sudo[30692]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 25 08:31:24 music volumio[30561]: info: ControllerMpd::onStart: Initializing MPD Jan 25 08:31:24 music volumio[30561]: info: Creating MPD Configuration file Jan 25 08:31:24 music sudo[30689]: pam_unix(sudo:session): session closed for user root Jan 25 08:31:24 music sudo[30692]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 08:31:24 music volumio[30561]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 25 08:31:24 music volumio[30561]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 25 08:31:24 music volumio[30561]: info: [1769347884232] CoreMusicLibrary::Adding element Media Servers Jan 25 08:31:24 music volumio[30561]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 25 08:31:24 music volumio[30561]: info: UPNP Browser: Client initialized successfully Jan 25 08:31:24 music sudo[30699]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 25 08:31:24 music sudo[30699]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 08:31:24 music sudo[30701]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 25 08:31:24 music sudo[30699]: pam_unix(sudo:session): session closed for user root Jan 25 08:31:24 music systemd[1]: Stopping mpd.service - Music Player Daemon... Jan 25 08:31:24 music sudo[30701]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 08:31:24 music volumio[30561]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:31:24 music volumio[30561]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 25 08:31:24 music systemd[1]: mpd.service: Deactivated successfully. Jan 25 08:31:24 music systemd[1]: Stopped mpd.service - Music Player Daemon. Jan 25 08:31:24 music systemd[1]: mpd.service: Consumed 4.084s CPU time. Jan 25 08:31:24 music systemd[1]: mpd.socket: Deactivated successfully. Jan 25 08:31:24 music systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jan 25 08:31:24 music systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jan 25 08:31:24 music volumio[30561]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 25 08:31:24 music volumio[30561]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:31:24 music volumio[30561]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 25 08:31:24 music volumio[30561]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 25 08:31:24 music volumio[30561]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 25 08:31:24 music volumio[30561]: info: [1769347884439] CoreMusicLibrary::Adding element Last_100 Jan 25 08:31:24 music volumio[30561]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 25 08:31:24 music volumio[30561]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 25 08:31:24 music volumio[30561]: info: [1769347884445] CoreMusicLibrary::Adding element Webradio Jan 25 08:31:24 music volumio[30561]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 25 08:31:24 music volumio[30561]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 25 08:31:24 music volumio[30561]: info: Initializing BBC Radios Jan 25 08:31:24 music systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jan 25 08:31:24 music systemd[1]: Starting mpd.service - Music Player Daemon... Jan 25 08:31:24 music systemd[1]: mpd.service: Deactivated successfully. Jan 25 08:31:24 music systemd[1]: Stopped mpd.service - Music Player Daemon. Jan 25 08:31:24 music systemd[1]: mpd.socket: Deactivated successfully. Jan 25 08:31:24 music systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jan 25 08:31:24 music systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jan 25 08:31:24 music systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jan 25 08:31:24 music systemd[1]: Starting mpd.service - Music Player Daemon... Jan 25 08:31:24 music volumio[30561]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 25 08:31:24 music volumio[30561]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 25 08:31:24 music volumio[30561]: info: Creating Spotify config file Jan 25 08:31:24 music volumio[30561]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:31:24 music go-librespot[30625]: time="2026-01-25T08:31:24-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Jan 25 08:31:24 music sudo[30723]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jan 25 08:31:24 music sudo[30723]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Jan 25 08:31:24 music sudo[30723]: pam_unix(sudo:session): session closed for user root Jan 25 08:31:24 music go-librespot[30625]: time="2026-01-25T08:31:24-05:00" level=debug msg="completed keyexchange" Jan 25 08:31:24 music go-librespot[30625]: time="2026-01-25T08:31:24-05:00" level=debug msg="completed challenge" Jan 25 08:31:24 music go-librespot[30625]: time="2026-01-25T08:31:24-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 25 08:31:25 music volumio[30561]: info: Volumio Calling Home Jan 25 08:31:25 music volumio[30561]: info: MPD Permissions set Jan 25 08:31:25 music volumio[30561]: info: MPD Permissions set Jan 25 08:31:25 music volumio[30561]: info: Spotify config file written Jan 25 08:31:25 music volumio[30561]: 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 25 08:31:25 music volumio[30561]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:31:25 music volumio[30561]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:31:25 music volumio[30561]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:31:25 music volumio[30561]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:31:25 music volumio[30561]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:31:25 music volumio[30561]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:31:25 music volumio[30561]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:31:25 music volumio[30561]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:31:25 music sudo[30737]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jan 25 08:31:25 music sudo[30737]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 08:31:25 music volumio[30561]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 25 08:31:25 music volumio[30561]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:31:25 music go-librespot[30625]: time="2026-01-25T08:31:25-05:00" level=warning msg="failed to connect to AP ap-gae2.spotify.com:4070, retrying with a different AP" error="dial tcp 104.199.241.202:4070: connect: connection refused" Jan 25 08:31:25 music volumio[30561]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:31:25 music volumio[30561]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:31:25 music volumio[30561]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:31:25 music volumio[30561]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:31:25 music volumio[30561]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:31:25 music volumio[30561]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:31:25 music volumio[30561]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:31:25 music volumio[30561]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:31:25 music systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Jan 25 08:31:25 music systemd[1]: go-librespot-daemon.service: Killing process 30628 (go-librespot) with signal SIGKILL. Jan 25 08:31:25 music systemd[1]: go-librespot-daemon.service: Deactivated successfully. Jan 25 08:31:25 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 25 08:31:25 music volumio[30561]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 25 08:31:25 music volumio[30561]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:31:25 music volumio[30561]: info: No need to fix Spotify hosts Jan 25 08:31:25 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 25 08:31:25 music go-librespot[30749]: go-librespot daemon starting... Jan 25 08:31:25 music sudo[30737]: pam_unix(sudo:session): session closed for user root Jan 25 08:31:25 music go-librespot[30750]: time="2026-01-25T08:31:25-05:00" level=info msg="running go-librespot 0.6.2" Jan 25 08:31:25 music go-librespot[30750]: time="2026-01-25T08:31:25-05:00" level=debug msg="app state loaded" Jan 25 08:31:25 music go-librespot[30750]: time="2026-01-25T08:31:25-05:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 25 08:31:25 music volumio[30651]: Starting albumart workers Jan 25 08:31:26 music volumio[30653]: Starting albumart workers Jan 25 08:31:26 music volumio[30561]: info: Volumio called home Jan 25 08:31:26 music volumio[30652]: Starting albumart workers Jan 25 08:31:26 music volumio[30561]: info: Starting Shairport Sync Jan 25 08:31:26 music volumio[30561]: info: Starting Shairport Sync Jan 25 08:31:26 music volumio[30561]: info: Starting Shairport Sync Jan 25 08:31:26 music sudo[30760]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 25 08:31:26 music sudo[30760]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 08:31:26 music sudo[30765]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 25 08:31:26 music sudo[30765]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 08:31:26 music systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jan 25 08:31:26 music systemd[1]: shairport-sync.service: Deactivated successfully. Jan 25 08:31:26 music systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 25 08:31:26 music systemd[1]: shairport-sync.service: Consumed 1.850s CPU time. Jan 25 08:31:26 music go-librespot[30750]: time="2026-01-25T08:31: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-gew4.spotify.com:80]" Jan 25 08:31:26 music go-librespot[30750]: time="2026-01-25T08:31:26-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 25 08:31:26 music go-librespot[30750]: time="2026-01-25T08:31:26-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 25 08:31:26 music go-librespot[30750]: time="2026-01-25T08:31:26-05:00" level=info msg="zeroconf server listening on port 44435" Jan 25 08:31:26 music sudo[30762]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 25 08:31:26 music sudo[30762]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 08:31:26 music systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 25 08:31:26 music sudo[30760]: pam_unix(sudo:session): session closed for user root Jan 25 08:31:26 music systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jan 25 08:31:26 music systemd[1]: shairport-sync.service: Deactivated successfully. Jan 25 08:31:26 music systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 25 08:31:26 music go-librespot[30750]: time="2026-01-25T08:31:26-05:00" level=debug msg="obtained new client token: AAB26AKDQUIJNhyfBc5PhALw2sKCiRTDqAWbGf9i30q9lBPfP/UY4u0fsxjySJhM0glvOsYXCCQw3fl9g12MjTX1nkV4WjiyUItdkiOVPXeNCSA+Q5aNU2EUjzODC84HD9mvKZL6m+ocOYL8knfu9XwmV3QpfPPINBwAj5A59OJ9SHc4QN5DmciFcPXqy2UEaz/+sjrsGpFRRcJbdcygkqUYo7RX1KnAicXCIWrzggJ0s2aKKw0rVCI=" Jan 25 08:31:26 music systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 25 08:31:26 music sudo[30765]: pam_unix(sudo:session): session closed for user root Jan 25 08:31:26 music sudo[30762]: pam_unix(sudo:session): session closed for user root Jan 25 08:31:26 music go-librespot[30750]: time="2026-01-25T08:31:26-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Jan 25 08:31:26 music volumio[30561]: info: An error occurred while refreshing Spotify Token Error: Bad Request Jan 25 08:31:26 music go-librespot[30750]: time="2026-01-25T08:31:26-05:00" level=debug msg="completed keyexchange" Jan 25 08:31:26 music go-librespot[30750]: time="2026-01-25T08:31:26-05:00" level=debug msg="completed challenge" Jan 25 08:31:26 music go-librespot[30750]: time="2026-01-25T08:31:26-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 25 08:31:26 music volumio[30561]: info: Shairport-Sync Started Jan 25 08:31:26 music volumio[30561]: Error adding Membership: Error: addMembership EINVAL Jan 25 08:31:26 music volumio[30561]: info: Shairport-Sync Started Jan 25 08:31:26 music volumio[30561]: info: Shairport-Sync Started Jan 25 08:31:26 music volumio[30561]: info: CoreCommandRouter::volumioGetState Jan 25 08:31:26 music volumio[30561]: info: CorePlayQueue::getTrack 0 Jan 25 08:31:27 music go-librespot[30750]: time="2026-01-25T08:31:27-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Jan 25 08:31:27 music go-librespot[30750]: time="2026-01-25T08:31:27-05:00" level=debug msg="completed keyexchange" Jan 25 08:31:27 music go-librespot[30750]: time="2026-01-25T08:31:27-05:00" level=debug msg="completed challenge" Jan 25 08:31:27 music go-librespot[30750]: time="2026-01-25T08:31:27-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 25 08:31:28 music go-librespot[30750]: time="2026-01-25T08:31:28-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Jan 25 08:31:28 music go-librespot[30750]: time="2026-01-25T08:31:28-05:00" level=debug msg="completed keyexchange" Jan 25 08:31:28 music go-librespot[30750]: time="2026-01-25T08:31:28-05:00" level=debug msg="completed challenge" Jan 25 08:31:28 music go-librespot[30750]: time="2026-01-25T08:31:28-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 25 08:31:28 music volumio[30561]: info: CoreCommandRouter::volumioGetState Jan 25 08:31:28 music volumio[30561]: info: CorePlayQueue::getTrack 0 Jan 25 08:31:28 music go-librespot[30750]: time="2026-01-25T08:31:28-05:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 25 08:31:28 music go-librespot[30750]: time="2026-01-25T08:31:28-05:00" level=debug msg="completed keyexchange" Jan 25 08:31:28 music go-librespot[30750]: time="2026-01-25T08:31:28-05:00" level=debug msg="completed challenge" Jan 25 08:31:28 music go-librespot[30750]: time="2026-01-25T08:31:28-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 25 08:31:29 music mpd[30730]: 2026-01-25T08:31:28 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jan 25 08:31:29 music systemd[1]: Started mpd.service - Music Player Daemon. Jan 25 08:31:29 music sudo[30692]: pam_unix(sudo:session): session closed for user root Jan 25 08:31:29 music sudo[30701]: pam_unix(sudo:session): session closed for user root Jan 25 08:31:29 music volumio[30561]: info: Completed starting Core Plugins Jan 25 08:31:29 music volumio[30561]: info: ------------------------------------------- Jan 25 08:31:29 music volumio[30561]: info: ----- MyVolumio plugins startup ---- Jan 25 08:31:29 music volumio[30561]: info: ------------------------------------------- Jan 25 08:31:29 music volumio[30561]: info: [MyVolumio PluginManager] Fetching plans data.... Jan 25 08:31:29 music volumio[30561]: error: MPD error: The expression evaluated to a falsy value: Jan 25 08:31:29 music volumio[30561]: assert.ok(self.idling) Jan 25 08:31:29 music volumio[30561]: error: The expression evaluated to a falsy value: Jan 25 08:31:29 music volumio[30561]: assert.ok(self.idling) Jan 25 08:31:29 music volumio[30561]: info: go-librespot daemon successfully initialized Jan 25 08:31:29 music volumio[30561]: info: MPD running with PID30730 Jan 25 08:31:29 music volumio[30561]: ,establishing connection Jan 25 08:31:29 music volumio[30561]: error: updateQueue error: null Jan 25 08:31:29 music volumio[30561]: error: updateQueue error: null Jan 25 08:31:29 music go-librespot[30750]: time="2026-01-25T08:31:29-05:00" level=debug msg="connected to ap-gae2.spotify.com:443" Jan 25 08:31:29 music sudo[30823]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 25 08:31:29 music sudo[30823]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 08:31:29 music sudo[30825]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 25 08:31:29 music sudo[30823]: pam_unix(sudo:session): session closed for user root Jan 25 08:31:29 music sudo[30825]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 08:31:29 music sudo[30825]: pam_unix(sudo:session): session closed for user root Jan 25 08:31:29 music sudo[30827]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Jan 25 08:31:29 music sudo[30827]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 08:31:29 music go-librespot[30750]: time="2026-01-25T08:31:29-05:00" level=debug msg="completed keyexchange" Jan 25 08:31:29 music go-librespot[30750]: time="2026-01-25T08:31:29-05:00" level=debug msg="completed challenge" Jan 25 08:31:29 music sudo[30827]: pam_unix(sudo:session): session closed for user root Jan 25 08:31:29 music volumio[30561]: info: Upmpdcli Daemon Started Jan 25 08:31:29 music go-librespot[30750]: time="2026-01-25T08:31:29-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 25 08:31:30 music go-librespot[30750]: time="2026-01-25T08:31:30-05:00" level=warning msg="failed to connect to AP ap-gew4.spotify.com:80, retrying with a different AP" error="dial tcp 34.158.1.133:80: connect: connection refused" Jan 25 08:31:30 music go-librespot[30750]: time="2026-01-25T08:31:30-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 25 08:31:30 music go-librespot[30750]: time="2026-01-25T08:31:30-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Jan 25 08:31:30 music go-librespot[30750]: time="2026-01-25T08:31:30-05:00" level=debug msg="completed keyexchange" Jan 25 08:31:30 music go-librespot[30750]: time="2026-01-25T08:31:30-05:00" level=debug msg="completed challenge" Jan 25 08:31:30 music go-librespot[30750]: time="2026-01-25T08:31:30-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 25 08:31:30 music go-librespot[30750]: time="2026-01-25T08:31: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 25 08:31:30 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 25 08:31:30 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 25 08:31:32 music sudo[30832]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Jan 25 08:31:32 music sudo[30832]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 08:31:32 music sudo[30834]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Jan 25 08:31:32 music sudo[30834]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 08:31:32 music systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Jan 25 08:31:32 music systemd[1]: mpd_monitor.service: Deactivated successfully. Jan 25 08:31:32 music systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Jan 25 08:31:32 music volumio[30561]: info: Initializing connection to go-librespot Websocket Jan 25 08:31:32 music volumio[30561]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 25 08:31:32 music systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Jan 25 08:31:32 music sudo[30832]: pam_unix(sudo:session): session closed for user root Jan 25 08:31:32 music mpd_monitor.sh[30837]: MPD Monitor Service: Starting MPD Monitor Service Jan 25 08:31:32 music sudo[30834]: pam_unix(sudo:session): session closed for user root Jan 25 08:31:32 music volumio[30561]: info: Successfully started MPD Monitor Jan 25 08:31:32 music volumio[30561]: info: Successfully started MPD Monitor Jan 25 08:31:34 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Jan 25 08:31:34 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 25 08:31:34 music volumio[30561]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Jan 25 08:31:34 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 25 08:31:34 music go-librespot[30842]: go-librespot daemon starting... Jan 25 08:31:34 music go-librespot[30843]: time="2026-01-25T08:31:34-05:00" level=info msg="running go-librespot 0.6.2" Jan 25 08:31:34 music go-librespot[30843]: time="2026-01-25T08:31:34-05:00" level=debug msg="app state loaded" Jan 25 08:31:34 music go-librespot[30843]: time="2026-01-25T08:31:34-05:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 25 08:31:34 music go-librespot[30843]: time="2026-01-25T08:31: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 25 08:31:34 music go-librespot[30843]: time="2026-01-25T08:31: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 25 08:31:34 music go-librespot[30843]: time="2026-01-25T08:31: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 25 08:31:34 music go-librespot[30843]: time="2026-01-25T08:31:34-05:00" level=info msg="zeroconf server listening on port 43311" Jan 25 08:31:34 music go-librespot[30843]: time="2026-01-25T08:31:34-05:00" level=debug msg="obtained new client token: AAAQ9R4wvIe1dugwQ/FddvZCFVbwljwLkFrmhXTXXBTWxBjU5XP09OFIcPfOZ2A6egybB8jIGneTj8hg65E0NOTZaCP5K+1WcPKHxMgsf18kBDHrXkE0F1ingLy9naWoUKtDgS869odWHwGS0E4QuNr2OigHagug979uF8sxuTmz3rrMyIYp7Q0CD4qyN5qrIWKvrBeO1R411GllA3kE9Djr62bn2azp040k04Zupp4tLPhe3ukMTew=" Jan 25 08:31:34 music go-librespot[30843]: time="2026-01-25T08:31:34-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 25 08:31:34 music go-librespot[30843]: time="2026-01-25T08:31:34-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Jan 25 08:31:34 music go-librespot[30843]: time="2026-01-25T08:31:34-05:00" level=debug msg="completed keyexchange" Jan 25 08:31:34 music go-librespot[30843]: time="2026-01-25T08:31:34-05:00" level=debug msg="completed challenge" Jan 25 08:31:34 music go-librespot[30843]: time="2026-01-25T08:31:34-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 25 08:31:35 music volumio[30561]: info: Initializing connection to go-librespot Websocket Jan 25 08:31:35 music go-librespot[30843]: time="2026-01-25T08:31:35-05:00" level=debug msg="new websocket client" Jan 25 08:31:35 music volumio[30561]: info: Connection to go-librespot Websocket established Jan 25 08:31:35 music go-librespot[30843]: time="2026-01-25T08:31:35-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Jan 25 08:31:35 music go-librespot[30843]: time="2026-01-25T08:31:35-05:00" level=debug msg="completed keyexchange" Jan 25 08:31:35 music go-librespot[30843]: time="2026-01-25T08:31:35-05:00" level=debug msg="completed challenge" Jan 25 08:31:35 music go-librespot[30843]: time="2026-01-25T08:31:35-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 25 08:31:36 music go-librespot[30843]: time="2026-01-25T08:31:36-05:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 25 08:31:36 music go-librespot[30843]: time="2026-01-25T08:31:36-05:00" level=debug msg="completed keyexchange" Jan 25 08:31:36 music go-librespot[30843]: time="2026-01-25T08:31:36-05:00" level=debug msg="completed challenge" Jan 25 08:31:36 music go-librespot[30843]: time="2026-01-25T08:31:36-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 25 08:31:36 music go-librespot[30843]: time="2026-01-25T08:31:36-05:00" level=warning msg="failed to connect to AP ap-gae2.spotify.com:443, retrying with a different AP" error="dial tcp 104.199.241.202:443: connect: connection refused" Jan 25 08:31:37 music go-librespot[30843]: time="2026-01-25T08:31:37-05:00" level=debug msg="connected to ap-gew4.spotify.com:80" Jan 25 08:31:37 music go-librespot[30843]: time="2026-01-25T08:31:37-05:00" level=debug msg="completed keyexchange" Jan 25 08:31:37 music go-librespot[30843]: time="2026-01-25T08:31:37-05:00" level=debug msg="completed challenge" Jan 25 08:31:37 music volumio[30561]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Jan 25 08:31:37 music volumio[30561]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Jan 25 08:31:37 music volumio[30561]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Jan 25 08:31:37 music volumio[30561]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Jan 25 08:31:37 music volumio[30561]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Jan 25 08:31:37 music volumio[30561]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Jan 25 08:31:37 music volumio[30561]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Jan 25 08:31:37 music volumio[30561]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Jan 25 08:31:37 music volumio[30561]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Jan 25 08:31:37 music volumio[30561]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Jan 25 08:31:37 music volumio[30561]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Jan 25 08:31:37 music volumio[30561]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Jan 25 08:31:37 music volumio[30561]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Jan 25 08:31:37 music volumio[30561]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Jan 25 08:31:37 music volumio[30561]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Jan 25 08:31:37 music volumio[30561]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Jan 25 08:31:37 music volumio[30561]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Jan 25 08:31:37 music volumio[30561]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Jan 25 08:31:37 music volumio[30561]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Jan 25 08:31:37 music volumio[30561]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Jan 25 08:31:37 music volumio[30561]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Jan 25 08:31:37 music volumio[30561]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Jan 25 08:31:37 music volumio[30561]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Jan 25 08:31:37 music volumio[30561]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Jan 25 08:31:37 music volumio[30561]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Jan 25 08:31:37 music volumio[30561]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Jan 25 08:31:37 music volumio[30561]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Jan 25 08:31:37 music volumio[30561]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Jan 25 08:31:37 music volumio[30561]: info: Adding plugin bluetooth to MyMusic Plugins Jan 25 08:31:37 music volumio[30561]: info: Adding plugin multiroom to MyMusic Plugins Jan 25 08:31:37 music volumio[30561]: info: Adding plugin metavolumio to MyMusic Plugins Jan 25 08:31:37 music volumio[30561]: info: Adding plugin cd_controller to MyMusic Plugins Jan 25 08:31:37 music volumio[30561]: info: Adding plugin qobuzconnect to MyMusic Plugins Jan 25 08:31:37 music volumio[30561]: info: Adding plugin smart_inputs to MyMusic Plugins Jan 25 08:31:37 music volumio[30561]: info: Adding plugin tidalconnect to MyMusic Plugins Jan 25 08:31:37 music volumio[30561]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Jan 25 08:31:37 music go-librespot[30843]: time="2026-01-25T08:31:37-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 25 08:31:37 music go-librespot[30843]: time="2026-01-25T08:31:37-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Jan 25 08:31:37 music go-librespot[30843]: time="2026-01-25T08:31:37-05:00" level=debug msg="completed keyexchange" Jan 25 08:31:37 music go-librespot[30843]: time="2026-01-25T08:31:37-05:00" level=debug msg="completed challenge" Jan 25 08:31:37 music go-librespot[30843]: time="2026-01-25T08:31:37-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 25 08:31:38 music volumio[30561]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Jan 25 08:31:38 music volumio[30561]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Jan 25 08:31:38 music volumio[30561]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 25 08:31:38 music volumio[30561]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 25 08:31:38 music volumio[30561]: info: Starting MyVolumio Remote Streaming Endpoints Jan 25 08:31:38 music volumio[30561]: info: MyVolumio login type: Token Jan 25 08:31:38 music volumio[30561]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Jan 25 08:31:38 music volumio[30561]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Jan 25 08:31:38 music go-librespot[30843]: time="2026-01-25T08:31:38-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Jan 25 08:31:38 music go-librespot[30843]: time="2026-01-25T08:31:38-05:00" level=debug msg="completed keyexchange" Jan 25 08:31:38 music go-librespot[30843]: time="2026-01-25T08:31:38-05:00" level=debug msg="completed challenge" Jan 25 08:31:38 music go-librespot[30843]: time="2026-01-25T08:31:38-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 25 08:31:38 music go-librespot[30843]: time="2026-01-25T08:31: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 25 08:31:38 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 25 08:31:38 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 25 08:31:39 music volumio[30561]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Jan 25 08:31:39 music volumio[30561]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Jan 25 08:31:39 music volumio[30561]: info: Streaming services startup Jan 25 08:31:39 music volumio[30561]: info: Starting Streaming Daemon Jan 25 08:31:39 music sudo[30853]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Jan 25 08:31:39 music sudo[30853]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 08:31:39 music volumio[30561]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Jan 25 08:31:39 music sudo[30853]: pam_unix(sudo:session): session closed for user root Jan 25 08:31:39 music volumio[30561]: info: Getting Spotify volume Jan 25 08:31:39 music volumio[30561]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 25 08:31:39 music volumio[30561]: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 25 08:31:39 music volumio[30561]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Jan 25 08:31:39 music volumio[30561]: errno: -111, Jan 25 08:31:39 music volumio[30561]: code: 'ECONNREFUSED', Jan 25 08:31:39 music volumio[30561]: syscall: 'connect', Jan 25 08:31:39 music volumio[30561]: address: '127.0.0.1', Jan 25 08:31:39 music volumio[30561]: port: 9879, Jan 25 08:31:39 music volumio[30561]: response: undefined Jan 25 08:31:39 music volumio[30561]: } Jan 25 08:31:39 music volumio[30561]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 25 08:31:40 music sudo[30887]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-01-25 08:30' Jan 25 08:31:40 music sudo[30887]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 08:31:40 music sudo[30887]: pam_unix(sudo:session): session closed for user root Jan 25 08:31:40 music volumio-remote-updater[1248]: [2026-01-25 08:31:40] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Jan 25 08:31:40 music volumio-remote-updater[1248]: [2026-01-25 08:31:40] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Jan 25 08:31:40 music systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Jan 25 08:31:40 music systemd[1]: volumio.service: Failed with result 'exit-code'. Jan 25 08:31:40 music systemd[1]: volumio.service: Consumed 26.479s CPU time. Jan 25 08:31:40 music systemd[1]: Started dynamicswap.service - dynamicswap service. Jan 25 08:31:40 music systemd[1]: dynamicswap.service: Deactivated successfully. Jan 25 08:31:40 music systemd[1]: volumio.service: Scheduled restart job, restart counter is at 27510. Jan 25 08:31:40 music systemd[1]: Started dynamicswap.service - dynamicswap service. Jan 25 08:31:40 music systemd[1]: Stopped volumio.service - Volumio Backend Module. Jan 25 08:31:40 music systemd[1]: volumio.service: Consumed 26.479s CPU time. Jan 25 08:31:40 music systemd[1]: Started volumio.service - Volumio Backend Module. Jan 25 08:31:40 music systemd[1]: dynamicswap.service: Deactivated successfully. Jan 25 08:31:41 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Jan 25 08:31:41 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 25 08:31:41 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 25 08:31:41 music go-librespot[30914]: go-librespot daemon starting... Jan 25 08:31:41 music go-librespot[30915]: time="2026-01-25T08:31:41-05:00" level=info msg="running go-librespot 0.6.2" Jan 25 08:31:41 music go-librespot[30915]: time="2026-01-25T08:31:41-05:00" level=debug msg="app state loaded" Jan 25 08:31:41 music go-librespot[30915]: time="2026-01-25T08:31:41-05:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 25 08:31:42 music go-librespot[30915]: time="2026-01-25T08:31: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-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 25 08:31:42 music go-librespot[30915]: time="2026-01-25T08:31:42-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 25 08:31:42 music go-librespot[30915]: time="2026-01-25T08:31:42-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 25 08:31:42 music go-librespot[30915]: time="2026-01-25T08:31:42-05:00" level=info msg="zeroconf server listening on port 39937" Jan 25 08:31:42 music go-librespot[30915]: time="2026-01-25T08:31:42-05:00" level=debug msg="obtained new client token: AAAj+tpaj6Ia+p+xtVjT46BgEnj+eawKE0Ggs/nX3zoOAJKgBXOBy1fLhydVmb+5N6I3wJH0jNdsFN2AR49jnyJ15qLuFJtNgt6oYYawOS4pH2nE2+1231n61eBY0g7F9qZgi/E/vfMr6V8BYO6efOLxfbCDxziMfeVbiE3ynavc4uhQNqjTnpWgI3F9SEynGb3ireBqGZ9BltPv6T8Wl9M+cSxpBIrpdzsBkfpGGUUeHqdoFHhbggM=" Jan 25 08:31:42 music go-librespot[30915]: time="2026-01-25T08:31:42-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Jan 25 08:31:42 music go-librespot[30915]: time="2026-01-25T08:31:42-05:00" level=debug msg="completed keyexchange" Jan 25 08:31:42 music go-librespot[30915]: time="2026-01-25T08:31:42-05:00" level=debug msg="completed challenge" Jan 25 08:31:42 music go-librespot[30915]: time="2026-01-25T08:31:42-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 25 08:31:42 music volumio[30899]: info: ------------------------------------------- Jan 25 08:31:42 music volumio[30899]: info: ----- Volumio3 ---- Jan 25 08:31:42 music volumio[30899]: info: ------------------------------------------- Jan 25 08:31:42 music volumio[30899]: info: ----- System startup ---- Jan 25 08:31:42 music volumio[30899]: info: ------------------------------------------- Jan 25 08:31:43 music go-librespot[30915]: time="2026-01-25T08:31:43-05:00" level=warning msg="failed to connect to AP ap-gue1.spotify.com:443, retrying with a different AP" error="dial tcp 34.158.255.62:443: connect: connection refused" Jan 25 08:31:43 music go-librespot[30915]: time="2026-01-25T08:31:43-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Jan 25 08:31:43 music go-librespot[30915]: time="2026-01-25T08:31:43-05:00" level=debug msg="completed keyexchange" Jan 25 08:31:43 music go-librespot[30915]: time="2026-01-25T08:31:43-05:00" level=debug msg="completed challenge" Jan 25 08:31:43 music go-librespot[30915]: time="2026-01-25T08:31:43-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 25 08:31:43 music volumio[30899]: info: MYVOLUMIO Environment detected Jan 25 08:31:43 music volumio[30899]: info: Plugin folders cleanup Jan 25 08:31:43 music volumio[30899]: info: Scanning into folder /volumio/app/plugins/ Jan 25 08:31:43 music volumio[30899]: info: Scanning category audio_interface Jan 25 08:31:43 music volumio[30899]: info: Scanning category miscellanea Jan 25 08:31:43 music volumio[30899]: info: Scanning category music_service Jan 25 08:31:43 music volumio[30899]: info: Scanning category plugins.json Jan 25 08:31:43 music volumio[30899]: info: Scanning category system_controller Jan 25 08:31:43 music volumio[30899]: info: Scanning category user_interface Jan 25 08:31:43 music volumio[30899]: info: Scanning into folder /data/plugins/ Jan 25 08:31:43 music volumio[30899]: info: Scanning category music_service Jan 25 08:31:43 music volumio[30899]: info: Plugin folders cleanup completed Jan 25 08:31:43 music volumio[30899]: info: ------------------------------------------- Jan 25 08:31:43 music volumio[30899]: info: ----- Core plugins startup ---- Jan 25 08:31:43 music volumio[30899]: info: ------------------------------------------- Jan 25 08:31:43 music volumio[30899]: info: Loading plugins from folder /volumio/app/plugins/ Jan 25 08:31:43 music volumio[30899]: info: Adding plugin upnp to MyMusic Plugins Jan 25 08:31:43 music volumio[30899]: info: Adding plugin airplay_emulation to MyMusic Plugins Jan 25 08:31:43 music volumio[30899]: info: Adding plugin upnp_browser to MyMusic Plugins Jan 25 08:31:43 music volumio[30899]: info: Loading plugins from folder /data/plugins/ Jan 25 08:31:43 music volumio[30899]: info: Loading plugin "system"... Jan 25 08:31:43 music volumio[30899]: info: Loading plugin "appearance"... Jan 25 08:31:44 music go-librespot[30915]: time="2026-01-25T08:31:44-05:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 25 08:31:44 music go-librespot[30915]: time="2026-01-25T08:31:44-05:00" level=debug msg="completed keyexchange" Jan 25 08:31:44 music go-librespot[30915]: time="2026-01-25T08:31:44-05:00" level=debug msg="completed challenge" Jan 25 08:31:44 music go-librespot[30915]: time="2026-01-25T08:31:44-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 25 08:31:44 music volumio[30899]: info: Loading plugin "network"... Jan 25 08:31:44 music volumio[30899]: info: Refreshing Cached IP Addresses Jan 25 08:31:44 music sudo[30938]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 25 08:31:44 music sudo[30938]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 08:31:44 music sudo[30940]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 25 08:31:44 music sudo[30940]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 08:31:44 music sudo[30938]: pam_unix(sudo:session): session closed for user root Jan 25 08:31:44 music volumio[30899]: info: Loading plugin "services"... Jan 25 08:31:44 music volumio[30899]: info: Loading plugin "alsa_controller"... Jan 25 08:31:44 music sudo[30940]: pam_unix(sudo:session): session closed for user root Jan 25 08:31:44 music sudo[30948]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Jan 25 08:31:44 music sudo[30948]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 08:31:45 music volumio[30899]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 25 08:31:45 music volumio[30899]: info: Loading plugin "wizard"... Jan 25 08:31:45 music volumio[30899]: info: Loading plugin "networkfs"... Jan 25 08:31:45 music volumio[30899]: info: Starting Udev Watcher for removable devices Jan 25 08:31:45 music volumio[30899]: info: Ignoring mount for partition: boot Jan 25 08:31:45 music volumio[30899]: info: Ignoring mount for partition: volumio Jan 25 08:31:45 music volumio[30899]: info: Ignoring mount for partition: volumio_data Jan 25 08:31:45 music volumio[30899]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 25 08:31:45 music volumio[30899]: info: Loading plugin "volumio_command_line_client"... Jan 25 08:31:45 music volumio[30899]: info: Loading plugin "upnp"... Jan 25 08:31:45 music volumio[30899]: info: [1769347905109] Starting Upmpd Daemon Jan 25 08:31:45 music volumio[30899]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 25 08:31:45 music volumio[30899]: info: Loading plugin "my_music"... Jan 25 08:31:45 music volumio[30899]: info: Loading plugin "mpd"... Jan 25 08:31:45 music go-librespot[30915]: time="2026-01-25T08:31:45-05:00" level=debug msg="connected to ap-gew1.spotify.com:443" Jan 25 08:31:45 music go-librespot[30915]: time="2026-01-25T08:31:45-05:00" level=debug msg="completed keyexchange" Jan 25 08:31:45 music go-librespot[30915]: time="2026-01-25T08:31:45-05:00" level=debug msg="completed challenge" Jan 25 08:31:45 music go-librespot[30915]: time="2026-01-25T08:31:45-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 25 08:31:45 music volumio[30899]: info: Loading plugin "upnp_browser"... Jan 25 08:31:45 music sudo[30948]: pam_unix(sudo:session): session closed for user root Jan 25 08:31:45 music volumio-remote-updater[1248]: [2026-01-25 08:31:45] [connect] Successful connection Jan 25 08:31:46 music go-librespot[30915]: time="2026-01-25T08:31:46-05:00" level=debug msg="connected to ap-gew4.spotify.com:80" Jan 25 08:31:46 music go-librespot[30915]: time="2026-01-25T08:31:46-05:00" level=debug msg="completed keyexchange" Jan 25 08:31:46 music go-librespot[30915]: time="2026-01-25T08:31:46-05:00" level=debug msg="completed challenge" Jan 25 08:31:46 music go-librespot[30915]: time="2026-01-25T08:31:46-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 25 08:31:46 music go-librespot[30915]: time="2026-01-25T08:31:46-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Jan 25 08:31:46 music go-librespot[30915]: time="2026-01-25T08:31:46-05:00" level=debug msg="completed keyexchange" Jan 25 08:31:46 music go-librespot[30915]: time="2026-01-25T08:31:46-05:00" level=debug msg="completed challenge" Jan 25 08:31:46 music go-librespot[30915]: time="2026-01-25T08:31:46-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 25 08:31:46 music go-librespot[30915]: time="2026-01-25T08:31: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 25 08:31:46 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 25 08:31:46 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 25 08:31:47 music volumio[30899]: info: Starting UPNP Browser Jan 25 08:31:47 music volumio[30899]: info: Loading plugin "alarm-clock"... Jan 25 08:31:47 music volumio[30899]: info: Loading plugin "airplay_emulation"... Jan 25 08:31:47 music volumio[30899]: info: Starting Shairport Sync Jan 25 08:31:47 music volumio[30899]: info: Loading plugin "last_100"... Jan 25 08:31:47 music volumio[30899]: info: Loading plugin "webradio"... Jan 25 08:31:47 music volumio[30899]: info: Loading plugin "i2s_dacs"... Jan 25 08:31:47 music volumio[30899]: info: I2S DAC not set, start Auto-detection Jan 25 08:31:47 music volumio[30899]: info: Loading plugin "volumiodiscovery"... Jan 25 08:31:47 music volumio[30899]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jan 25 08:31:47 music volumio[30899]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 25 08:31:47 music volumio[30899]: *** WARNING *** For more information see Jan 25 08:31:47 music volumio[30899]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jan 25 08:31:47 music volumio[30899]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 25 08:31:47 music volumio[30899]: *** WARNING *** For more information see Jan 25 08:31:47 music node[30899]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jan 25 08:31:47 music node[30899]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 25 08:31:47 music node[30899]: *** WARNING *** For more information see Jan 25 08:31:47 music node[30899]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jan 25 08:31:47 music node[30899]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 25 08:31:47 music node[30899]: *** WARNING *** For more information see Jan 25 08:31:47 music volumio[30899]: info: Applying required configuration parameters for plugin volumiodiscovery Jan 25 08:31:47 music volumio[30899]: info: Discovery: Started advertising with name: music Jan 25 08:31:47 music volumio[30899]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 25 08:31:47 music volumio[30899]: info: Loading plugin "spop"... Jan 25 08:31:48 music volumio[30899]: info: Loading plugin "outputs"... Jan 25 08:31:48 music volumio[30899]: info: Loading plugin "albumart"... Jan 25 08:31:48 music volumio[30899]: info: Plugin example_plugin is not enabled Jan 25 08:31:48 music volumio[30899]: info: Loading plugin "inputs"... Jan 25 08:31:48 music volumio[30899]: info: Loading plugin "updater_comm"... Jan 25 08:31:48 music volumio[30899]: info: Plugin mpdemulation is not enabled Jan 25 08:31:48 music volumio[30899]: info: Loading plugin "rest_api"... Jan 25 08:31:48 music volumio[30899]: info: Loading plugin "websocket"... Jan 25 08:31:48 music volumio[30899]: info: Starting Socket.io Server version 1.7.4 Jan 25 08:31:48 music volumio[30899]: info: Loading i18n strings for locale en Jan 25 08:31:48 music volumio[30899]: Updating browse sources language Jan 25 08:31:48 music volumio[30899]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 25 08:31:48 music volumio[30899]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 25 08:31:48 music volumio[30899]: info: CoreCommandRouter::initPlayerControls Jan 25 08:31:48 music volumio[30899]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:31:48 music volumio[30899]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:31:48 music volumio[30899]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:31:48 music volumio[30899]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:31:48 music volumio[30899]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:31:48 music volumio[30899]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:31:48 music volumio[30899]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:31:48 music volumio[30899]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:31:48 music volumio[30899]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 25 08:31:48 music volumio[30899]: Express server listening on port 3000 Jan 25 08:31:48 music volumio[30899]: [Metrics] WebUI: 6s 598.23ms Jan 25 08:31:48 music volumio[30899]: info: CoreStateMachine::resetVolumioState Jan 25 08:31:48 music volumio[30899]: info: CoreStateMachine::getcurrentVolume Jan 25 08:31:48 music volumio[30899]: info: CoreCommandRouter::volumioRetrievevolume Jan 25 08:31:48 music volumio[30899]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 25 08:31:48 music volumio[30899]: info: Volumio Network Manager: Network status updated: 1 Jan 25 08:31:49 music volumio-remote-updater[1248]: [2026-01-25 08:31:49] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1769347905 101 Jan 25 08:31:49 music volumio[30899]: 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 25 08:31:49 music volumio[30899]: info: VolumeController:: Volume=86 Mute =false Jan 25 08:31:49 music volumio[30899]: info: CoreStateMachine::pushState Jan 25 08:31:49 music volumio[30899]: info: CorePlayQueue::getTrack 0 Jan 25 08:31:49 music volumio[30899]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 25 08:31:49 music volumio[30899]: info: CoreCommandRouter::volumioPushState Jan 25 08:31:49 music volumio[30973]: Forking 3 albumart workers Jan 25 08:31:49 music volumio[30899]: info: CoreStateMachine::updateTrackBlock Jan 25 08:31:49 music volumio[30899]: info: CorePlayQueue::getTrackBlock Jan 25 08:31:49 music volumio[30899]: info: CoreCommandRouter::volumioRetrievevolume Jan 25 08:31:49 music volumio[30899]: info: Reloading queue from file Jan 25 08:31:49 music volumio[30899]: info: CoreCommandRouter::volumioGetState Jan 25 08:31:49 music volumio[30899]: info: CorePlayQueue::getTrack 0 Jan 25 08:31:49 music volumio[30899]: info: CoreStateMachine::setRepeat null single undefined Jan 25 08:31:49 music volumio[30899]: info: CoreStateMachine::pushState Jan 25 08:31:49 music volumio[30899]: info: CorePlayQueue::getTrack 0 Jan 25 08:31:49 music volumio[30899]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 25 08:31:49 music volumio[30899]: info: CoreCommandRouter::volumioPushState Jan 25 08:31:49 music volumio[30899]: info: CoreStateMachine::setRandom null Jan 25 08:31:49 music volumio[30899]: info: CoreStateMachine::pushState Jan 25 08:31:49 music volumio[30899]: info: CorePlayQueue::getTrack 0 Jan 25 08:31:49 music volumio[30899]: info: CoreCommandRouter::volumioPushState Jan 25 08:31:49 music volumio[30899]: info: Setting Device type: Raspberry PI Jan 25 08:31:49 music volumio[30899]: info: Listing playlists Jan 25 08:31:49 music volumio[30899]: info: Listing playlists Jan 25 08:31:49 music volumio[30899]: info: VolumeController:: Volume=86 Mute =false Jan 25 08:31:49 music volumio[30899]: info: CoreStateMachine::pushState Jan 25 08:31:49 music volumio[30899]: info: CorePlayQueue::getTrack 0 Jan 25 08:31:49 music volumio[30899]: info: CoreCommandRouter::volumioPushState Jan 25 08:31:49 music volumio[30899]: info: Completed loading Core Plugins Jan 25 08:31:49 music volumio[30899]: info: Preparing to generate the ALSA configuration file Jan 25 08:31:49 music volumio[30899]: info: Discovery: adding 4a29b7a7-c637-4926-a2bd-fb4e2f55145e Jan 25 08:31:49 music volumio[30899]: info: Discovery: Found device music Jan 25 08:31:49 music volumio[30899]: info: CoreCommandRouter::volumioGetState Jan 25 08:31:49 music volumio[30899]: info: CorePlayQueue::getTrack 0 Jan 25 08:31:49 music volumio[30899]: info: Discovery: this is already registered, 4a29b7a7-c637-4926-a2bd-fb4e2f55145e Jan 25 08:31:49 music volumio[30899]: info: Discovery: Found device music Jan 25 08:31:49 music volumio[30899]: info: CoreCommandRouter::volumioGetState Jan 25 08:31:49 music volumio[30899]: info: CorePlayQueue::getTrack 0 Jan 25 08:31:49 music volumio[30899]: info: Asound.conf file unchanged, so no further update is needed Jan 25 08:31:49 music volumio[30899]: info: Output device has changed, restarting MPD Jan 25 08:31:49 music volumio[30899]: info: Output device has changed, restarting Shairport Sync Jan 25 08:31:49 music volumio[30899]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:31:49 music volumio[30899]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 25 08:31:49 music sudo[31030]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 25 08:31:49 music sudo[31029]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 25 08:31:49 music volumio[30899]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 25 08:31:49 music sudo[31030]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 08:31:49 music volumio[30899]: info: ___________ START PLUGINS ___________ Jan 25 08:31:49 music sudo[31029]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 08:31:49 music volumio[30899]: info: ControllerMpd::onStart: Initializing MPD Jan 25 08:31:49 music volumio[30899]: info: Creating MPD Configuration file Jan 25 08:31:49 music sudo[31029]: pam_unix(sudo:session): session closed for user root Jan 25 08:31:49 music volumio[30899]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 25 08:31:49 music volumio[30899]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 25 08:31:49 music volumio[30899]: info: [1769347909584] CoreMusicLibrary::Adding element Media Servers Jan 25 08:31:49 music volumio[30899]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 25 08:31:49 music volumio[30899]: info: UPNP Browser: Client initialized successfully Jan 25 08:31:49 music systemd[1]: Stopping mpd.service - Music Player Daemon... Jan 25 08:31:49 music sudo[31039]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 25 08:31:49 music sudo[31039]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 08:31:49 music sudo[31040]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 25 08:31:49 music sudo[31040]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 08:31:49 music volumio[30899]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:31:49 music volumio[30899]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 25 08:31:49 music systemd[1]: mpd.service: Deactivated successfully. Jan 25 08:31:49 music systemd[1]: Stopped mpd.service - Music Player Daemon. Jan 25 08:31:49 music systemd[1]: mpd.service: Consumed 4.105s CPU time. Jan 25 08:31:49 music systemd[1]: mpd.socket: Deactivated successfully. Jan 25 08:31:49 music sudo[31039]: pam_unix(sudo:session): session closed for user root Jan 25 08:31:49 music systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jan 25 08:31:49 music systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jan 25 08:31:49 music volumio[30899]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 25 08:31:49 music volumio[30899]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:31:49 music volumio[30899]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 25 08:31:49 music volumio[30899]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 25 08:31:49 music volumio[30899]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 25 08:31:49 music volumio[30899]: info: [1769347909758] CoreMusicLibrary::Adding element Last_100 Jan 25 08:31:49 music volumio[30899]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 25 08:31:49 music systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jan 25 08:31:49 music volumio[30899]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 25 08:31:49 music volumio[30899]: info: [1769347909766] CoreMusicLibrary::Adding element Webradio Jan 25 08:31:49 music volumio[30899]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 25 08:31:49 music systemd[1]: Starting mpd.service - Music Player Daemon... Jan 25 08:31:49 music volumio[30899]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 25 08:31:49 music volumio[30899]: info: Initializing BBC Radios Jan 25 08:31:49 music systemd[1]: mpd.service: Deactivated successfully. Jan 25 08:31:49 music systemd[1]: Stopped mpd.service - Music Player Daemon. Jan 25 08:31:49 music systemd[1]: mpd.socket: Deactivated successfully. Jan 25 08:31:49 music systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jan 25 08:31:49 music systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jan 25 08:31:49 music systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jan 25 08:31:49 music systemd[1]: Starting mpd.service - Music Player Daemon... Jan 25 08:31:49 music volumio[30899]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 25 08:31:49 music volumio[30899]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 25 08:31:49 music volumio[30899]: info: Creating Spotify config file Jan 25 08:31:49 music volumio[30899]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:31:50 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Jan 25 08:31:50 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 25 08:31:50 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 25 08:31:50 music go-librespot[31068]: go-librespot daemon starting... Jan 25 08:31:50 music sudo[31062]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jan 25 08:31:50 music sudo[31062]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Jan 25 08:31:50 music sudo[31062]: pam_unix(sudo:session): session closed for user root Jan 25 08:31:50 music go-librespot[31069]: time="2026-01-25T08:31:50-05:00" level=info msg="running go-librespot 0.6.2" Jan 25 08:31:50 music volumio[30899]: info: Volumio Calling Home Jan 25 08:31:50 music go-librespot[31069]: time="2026-01-25T08:31:50-05:00" level=info msg="zeroconf server listening on port 46413" Jan 25 08:31:51 music volumio[30992]: Starting albumart workers Jan 25 08:31:51 music volumio[30991]: Starting albumart workers Jan 25 08:31:51 music volumio[30899]: info: MPD Permissions set Jan 25 08:31:51 music volumio[30899]: info: MPD Permissions set Jan 25 08:31:51 music volumio[30899]: info: Volumio called home Jan 25 08:31:51 music volumio[30899]: info: Spotify config file written Jan 25 08:31:51 music volumio[30899]: 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 25 08:31:51 music volumio[30899]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:31:51 music volumio[30899]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:31:51 music volumio[30899]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:31:51 music volumio[30899]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:31:51 music volumio[30899]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:31:51 music volumio[30899]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:31:51 music volumio[30899]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:31:51 music sudo[31084]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jan 25 08:31:51 music sudo[31084]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 08:31:51 music volumio[30899]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:31:51 music volumio[30899]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 25 08:31:51 music volumio[30899]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:31:51 music volumio[30899]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:31:51 music volumio[30899]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:31:51 music volumio[30899]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:31:51 music volumio[30899]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:31:51 music volumio[30899]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:31:51 music volumio[30899]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:31:51 music volumio[30899]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:31:51 music volumio[30899]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:31:51 music volumio[30990]: Starting albumart workers Jan 25 08:31:51 music volumio[30899]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 25 08:31:51 music volumio[30899]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:31:51 music systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Jan 25 08:31:51 music volumio[30899]: info: No need to fix Spotify hosts Jan 25 08:31:51 music systemd[1]: go-librespot-daemon.service: Killing process 31075 (go-librespot) with signal SIGKILL. Jan 25 08:31:51 music systemd[1]: go-librespot-daemon.service: Deactivated successfully. Jan 25 08:31:51 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 25 08:31:51 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 25 08:31:51 music go-librespot[31096]: go-librespot daemon starting... Jan 25 08:31:51 music sudo[31084]: pam_unix(sudo:session): session closed for user root Jan 25 08:31:51 music go-librespot[31097]: time="2026-01-25T08:31:51-05:00" level=info msg="running go-librespot 0.6.2" Jan 25 08:31:51 music go-librespot[31097]: time="2026-01-25T08:31:51-05:00" level=debug msg="app state loaded" Jan 25 08:31:51 music go-librespot[31097]: time="2026-01-25T08:31:51-05:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 25 08:31:52 music go-librespot[31097]: time="2026-01-25T08:31:52-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 25 08:31:52 music go-librespot[31097]: time="2026-01-25T08:31:52-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 25 08:31:52 music go-librespot[31097]: time="2026-01-25T08:31:52-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 25 08:31:52 music go-librespot[31097]: time="2026-01-25T08:31:52-05:00" level=info msg="zeroconf server listening on port 44061" Jan 25 08:31:52 music go-librespot[31097]: time="2026-01-25T08:31:52-05:00" level=debug msg="obtained new client token: AAC0JQwlFTmfC1IJDjPtkEQs8O5mx15peZBKYbrILfWGFC0pGNac9pIhnPRXE/uhp3AodpWz1RzaijAK4besEDkzoLOSr9mHN0XlvYZ9UhZSYnS1xmNurJ4B1RUHyXQXplXv7dKh41ap+ISHCDt+/CSTRZVWAU+A6M2sT59LBgWnVeEW+NJF5qhFp4G+KfMzyG4CThAgtGME4y/xiyON5P1zV9omEbaGmjqdKoi+JUJv5rqdCqc9Qu8=" Jan 25 08:31:52 music volumio[30899]: info: Starting Shairport Sync Jan 25 08:31:52 music volumio[30899]: info: Starting Shairport Sync Jan 25 08:31:52 music volumio[30899]: info: Starting Shairport Sync Jan 25 08:31:52 music go-librespot[31097]: time="2026-01-25T08:31:52-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Jan 25 08:31:52 music sudo[31124]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 25 08:31:52 music sudo[31124]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 08:31:52 music sudo[31127]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 25 08:31:52 music sudo[31127]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 08:31:52 music volumio[30899]: info: An error occurred while refreshing Spotify Token Error: Bad Request Jan 25 08:31:52 music sudo[31128]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 25 08:31:52 music sudo[31128]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 08:31:52 music go-librespot[31097]: time="2026-01-25T08:31:52-05:00" level=debug msg="completed keyexchange" Jan 25 08:31:52 music go-librespot[31097]: time="2026-01-25T08:31:52-05:00" level=debug msg="completed challenge" Jan 25 08:31:52 music volumio[30899]: info: CoreCommandRouter::volumioGetState Jan 25 08:31:52 music volumio[30899]: info: CorePlayQueue::getTrack 0 Jan 25 08:31:52 music go-librespot[31097]: time="2026-01-25T08:31:52-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 25 08:31:52 music systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jan 25 08:31:52 music systemd[1]: shairport-sync.service: Deactivated successfully. Jan 25 08:31:52 music systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 25 08:31:52 music systemd[1]: shairport-sync.service: Consumed 1.760s CPU time. Jan 25 08:31:52 music systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 25 08:31:52 music sudo[31128]: pam_unix(sudo:session): session closed for user root Jan 25 08:31:52 music sudo[31127]: pam_unix(sudo:session): session closed for user root Jan 25 08:31:52 music sudo[31124]: pam_unix(sudo:session): session closed for user root Jan 25 08:31:52 music volumio[30899]: info: Shairport-Sync Started Jan 25 08:31:52 music volumio[30899]: Error adding Membership: Error: addMembership EINVAL Jan 25 08:31:52 music volumio[30899]: info: Shairport-Sync Started Jan 25 08:31:52 music volumio[30899]: info: Shairport-Sync Started Jan 25 08:31:53 music go-librespot[31097]: time="2026-01-25T08:31:53-05:00" level=warning msg="failed to connect to AP ap-gue1.spotify.com:443, retrying with a different AP" error="dial tcp 34.158.255.62:443: connect: connection refused" Jan 25 08:31:53 music go-librespot[31097]: time="2026-01-25T08:31:53-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Jan 25 08:31:53 music go-librespot[31097]: time="2026-01-25T08:31:53-05:00" level=debug msg="completed keyexchange" Jan 25 08:31:53 music go-librespot[31097]: time="2026-01-25T08:31:53-05:00" level=debug msg="completed challenge" Jan 25 08:31:53 music go-librespot[31097]: time="2026-01-25T08:31:53-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 25 08:31:54 music go-librespot[31097]: time="2026-01-25T08:31:54-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 25 08:31:54 music go-librespot[31097]: time="2026-01-25T08:31:54-05:00" level=debug msg="connected to ap-gae2.spotify.com:443" Jan 25 08:31:54 music mpd[31076]: 2026-01-25T08:31:54 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jan 25 08:31:54 music systemd[1]: Started mpd.service - Music Player Daemon. Jan 25 08:31:54 music sudo[31030]: pam_unix(sudo:session): session closed for user root Jan 25 08:31:54 music sudo[31040]: pam_unix(sudo:session): session closed for user root Jan 25 08:31:54 music volumio[30899]: info: Completed starting Core Plugins Jan 25 08:31:54 music volumio[30899]: info: ------------------------------------------- Jan 25 08:31:54 music volumio[30899]: info: ----- MyVolumio plugins startup ---- Jan 25 08:31:54 music volumio[30899]: info: ------------------------------------------- Jan 25 08:31:54 music volumio[30899]: info: [MyVolumio PluginManager] Fetching plans data.... Jan 25 08:31:54 music volumio[30899]: error: MPD error: The expression evaluated to a falsy value: Jan 25 08:31:54 music volumio[30899]: assert.ok(self.idling) Jan 25 08:31:54 music volumio[30899]: error: The expression evaluated to a falsy value: Jan 25 08:31:54 music volumio[30899]: assert.ok(self.idling) Jan 25 08:31:54 music volumio[30899]: error: updateQueue error: null Jan 25 08:31:54 music volumio[30899]: info: MPD running with PID31076 Jan 25 08:31:54 music volumio[30899]: ,establishing connection Jan 25 08:31:54 music volumio[30899]: error: updateQueue error: null Jan 25 08:31:54 music go-librespot[31097]: time="2026-01-25T08:31:54-05:00" level=debug msg="completed keyexchange" Jan 25 08:31:54 music go-librespot[31097]: time="2026-01-25T08:31:54-05:00" level=debug msg="completed challenge" Jan 25 08:31:54 music go-librespot[31097]: time="2026-01-25T08:31:54-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 25 08:31:55 music sudo[31173]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 25 08:31:55 music sudo[31173]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 08:31:55 music sudo[31173]: pam_unix(sudo:session): session closed for user root Jan 25 08:31:55 music sudo[31175]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 25 08:31:55 music sudo[31175]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 08:31:55 music sudo[31175]: pam_unix(sudo:session): session closed for user root Jan 25 08:31:55 music sudo[31179]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Jan 25 08:31:55 music sudo[31179]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 08:31:55 music sudo[31179]: pam_unix(sudo:session): session closed for user root Jan 25 08:31:55 music volumio[30899]: info: Upmpdcli Daemon Started Jan 25 08:31:55 music go-librespot[31097]: time="2026-01-25T08:31:55-05:00" level=debug msg="connected to ap-gew1.spotify.com:80" Jan 25 08:31:55 music volumio[30899]: info: go-librespot daemon successfully initialized Jan 25 08:31:55 music go-librespot[31097]: time="2026-01-25T08:31:55-05:00" level=debug msg="completed keyexchange" Jan 25 08:31:55 music go-librespot[31097]: time="2026-01-25T08:31:55-05:00" level=debug msg="completed challenge" Jan 25 08:31:55 music go-librespot[31097]: time="2026-01-25T08:31:55-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 25 08:31:56 music go-librespot[31097]: time="2026-01-25T08:31:56-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Jan 25 08:31:56 music go-librespot[31097]: time="2026-01-25T08:31:56-05:00" level=debug msg="completed keyexchange" Jan 25 08:31:56 music go-librespot[31097]: time="2026-01-25T08:31:56-05:00" level=debug msg="completed challenge" Jan 25 08:31:56 music go-librespot[31097]: time="2026-01-25T08:31:56-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 25 08:31:56 music go-librespot[31097]: time="2026-01-25T08:31:56-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Jan 25 08:31:57 music go-librespot[31097]: time="2026-01-25T08:31:57-05:00" level=debug msg="completed keyexchange" Jan 25 08:31:57 music go-librespot[31097]: time="2026-01-25T08:31:57-05:00" level=debug msg="completed challenge" Jan 25 08:31:57 music go-librespot[31097]: time="2026-01-25T08:31:57-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 25 08:31:57 music go-librespot[31097]: time="2026-01-25T08:31:57-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 25 08:31:57 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 25 08:31:57 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 25 08:31:57 music sudo[31183]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Jan 25 08:31:57 music sudo[31183]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 08:31:57 music sudo[31185]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Jan 25 08:31:57 music sudo[31185]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 08:31:57 music systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Jan 25 08:31:57 music systemd[1]: mpd_monitor.service: Deactivated successfully. Jan 25 08:31:57 music systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Jan 25 08:31:57 music systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Jan 25 08:31:57 music sudo[31183]: pam_unix(sudo:session): session closed for user root Jan 25 08:31:57 music sudo[31185]: pam_unix(sudo:session): session closed for user root Jan 25 08:31:57 music mpd_monitor.sh[31188]: MPD Monitor Service: Starting MPD Monitor Service Jan 25 08:31:57 music volumio[30899]: info: Successfully started MPD Monitor Jan 25 08:31:57 music volumio[30899]: info: Successfully started MPD Monitor Jan 25 08:31:58 music volumio[30899]: info: Initializing connection to go-librespot Websocket Jan 25 08:31:58 music volumio[30899]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 25 08:31:58 music volumio[30899]: info: CoreCommandRouter::volumioGetState Jan 25 08:31:58 music volumio[30899]: info: CorePlayQueue::getTrack 0 Jan 25 08:31:59 music volumio[30899]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Jan 25 08:32:00 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Jan 25 08:32:00 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 25 08:32:00 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 25 08:32:00 music go-librespot[31192]: go-librespot daemon starting... Jan 25 08:32:00 music go-librespot[31193]: time="2026-01-25T08:32:00-05:00" level=info msg="running go-librespot 0.6.2" Jan 25 08:32:00 music go-librespot[31193]: time="2026-01-25T08:32:00-05:00" level=debug msg="app state loaded" Jan 25 08:32:00 music go-librespot[31193]: time="2026-01-25T08:32:00-05:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 25 08:32:00 music go-librespot[31193]: time="2026-01-25T08:32: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-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 25 08:32:00 music go-librespot[31193]: time="2026-01-25T08:32:00-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 25 08:32:00 music go-librespot[31193]: time="2026-01-25T08:32:00-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 25 08:32:00 music go-librespot[31193]: time="2026-01-25T08:32:00-05:00" level=info msg="zeroconf server listening on port 37225" Jan 25 08:32:00 music go-librespot[31193]: time="2026-01-25T08:32:00-05:00" level=debug msg="obtained new client token: AAAh9OWNSiF2+DGHsBi2kci5CHOWP2+q/qCgsxg7NRo5V/WWGTXKOMTKVx1OsN2CzHntbiTHrII+JIQ0YV6jl//7U/yTcTlGzKAowAF08hZpztYOUAMWkslEEN4zCuC6YWjtc99VRSBAg2vv6aB/1/p2TL7KWBNpL4QjaoPKVr2TPlEnBAoL7WwBPTY2h3lQ9GoXxSWl9E2cG3dhowO1KoFbVa94+kpAlob0eN792ZsU5xJfIJ3btBA=" Jan 25 08:32:00 music go-librespot[31193]: time="2026-01-25T08:32:00-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Jan 25 08:32:00 music go-librespot[31193]: time="2026-01-25T08:32:00-05:00" level=debug msg="completed keyexchange" Jan 25 08:32:00 music go-librespot[31193]: time="2026-01-25T08:32:00-05:00" level=debug msg="completed challenge" Jan 25 08:32:01 music go-librespot[31193]: time="2026-01-25T08:32:01-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 25 08:32:01 music volumio[30899]: info: Initializing connection to go-librespot Websocket Jan 25 08:32:01 music go-librespot[31193]: time="2026-01-25T08:32:01-05:00" level=debug msg="new websocket client" Jan 25 08:32:01 music volumio[30899]: info: Connection to go-librespot Websocket established Jan 25 08:32:01 music go-librespot[31193]: time="2026-01-25T08:32:01-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Jan 25 08:32:01 music go-librespot[31193]: time="2026-01-25T08:32:01-05:00" level=debug msg="completed keyexchange" Jan 25 08:32:01 music go-librespot[31193]: time="2026-01-25T08:32:01-05:00" level=debug msg="completed challenge" Jan 25 08:32:01 music go-librespot[31193]: time="2026-01-25T08:32:01-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 25 08:32:02 music go-librespot[31193]: time="2026-01-25T08:32:02-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Jan 25 08:32:02 music go-librespot[31193]: time="2026-01-25T08:32:02-05:00" level=debug msg="completed keyexchange" Jan 25 08:32:02 music go-librespot[31193]: time="2026-01-25T08:32:02-05:00" level=debug msg="completed challenge" Jan 25 08:32:02 music go-librespot[31193]: time="2026-01-25T08:32:02-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 25 08:32:02 music volumio[30899]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Jan 25 08:32:02 music volumio[30899]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Jan 25 08:32:02 music volumio[30899]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Jan 25 08:32:02 music volumio[30899]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Jan 25 08:32:02 music volumio[30899]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Jan 25 08:32:02 music volumio[30899]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Jan 25 08:32:02 music volumio[30899]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Jan 25 08:32:02 music volumio[30899]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Jan 25 08:32:02 music volumio[30899]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Jan 25 08:32:02 music volumio[30899]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Jan 25 08:32:02 music volumio[30899]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Jan 25 08:32:02 music volumio[30899]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Jan 25 08:32:02 music volumio[30899]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Jan 25 08:32:02 music volumio[30899]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Jan 25 08:32:02 music volumio[30899]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Jan 25 08:32:02 music volumio[30899]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Jan 25 08:32:02 music volumio[30899]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Jan 25 08:32:02 music volumio[30899]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Jan 25 08:32:02 music volumio[30899]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Jan 25 08:32:02 music volumio[30899]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Jan 25 08:32:02 music volumio[30899]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Jan 25 08:32:02 music volumio[30899]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Jan 25 08:32:02 music volumio[30899]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Jan 25 08:32:02 music volumio[30899]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Jan 25 08:32:02 music volumio[30899]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Jan 25 08:32:02 music volumio[30899]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Jan 25 08:32:02 music volumio[30899]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Jan 25 08:32:02 music volumio[30899]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Jan 25 08:32:02 music volumio[30899]: info: Adding plugin bluetooth to MyMusic Plugins Jan 25 08:32:02 music volumio[30899]: info: Adding plugin multiroom to MyMusic Plugins Jan 25 08:32:02 music volumio[30899]: info: Adding plugin metavolumio to MyMusic Plugins Jan 25 08:32:02 music volumio[30899]: info: Adding plugin cd_controller to MyMusic Plugins Jan 25 08:32:02 music volumio[30899]: info: Adding plugin qobuzconnect to MyMusic Plugins Jan 25 08:32:02 music volumio[30899]: info: Adding plugin smart_inputs to MyMusic Plugins Jan 25 08:32:02 music volumio[30899]: info: Adding plugin tidalconnect to MyMusic Plugins Jan 25 08:32:02 music volumio[30899]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Jan 25 08:32:03 music go-librespot[31193]: time="2026-01-25T08:32:03-05:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 25 08:32:03 music go-librespot[31193]: time="2026-01-25T08:32:03-05:00" level=debug msg="completed keyexchange" Jan 25 08:32:03 music go-librespot[31193]: time="2026-01-25T08:32:03-05:00" level=debug msg="completed challenge" Jan 25 08:32:03 music go-librespot[31193]: time="2026-01-25T08:32:03-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 25 08:32:03 music volumio[30899]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Jan 25 08:32:03 music volumio[30899]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Jan 25 08:32:03 music volumio[30899]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 25 08:32:03 music volumio[30899]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 25 08:32:03 music volumio[30899]: info: Starting MyVolumio Remote Streaming Endpoints Jan 25 08:32:03 music volumio[30899]: info: MyVolumio login type: Token Jan 25 08:32:03 music volumio[30899]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Jan 25 08:32:03 music volumio[30899]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Jan 25 08:32:04 music go-librespot[31193]: time="2026-01-25T08:32:04-05:00" level=debug msg="connected to ap-gew1.spotify.com:443" Jan 25 08:32:04 music go-librespot[31193]: time="2026-01-25T08:32:04-05:00" level=debug msg="completed keyexchange" Jan 25 08:32:04 music go-librespot[31193]: time="2026-01-25T08:32:04-05:00" level=debug msg="completed challenge" Jan 25 08:32:04 music go-librespot[31193]: time="2026-01-25T08:32:04-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 25 08:32:04 music volumio[30899]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Jan 25 08:32:04 music volumio[30899]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Jan 25 08:32:04 music volumio[30899]: info: Streaming services startup Jan 25 08:32:04 music volumio[30899]: info: Starting Streaming Daemon Jan 25 08:32:04 music sudo[31203]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Jan 25 08:32:04 music sudo[31203]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 08:32:04 music volumio[30899]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Jan 25 08:32:04 music sudo[31203]: pam_unix(sudo:session): session closed for user root Jan 25 08:32:04 music volumio[30899]: info: Getting Spotify volume Jan 25 08:32:04 music volumio[30899]: error: Cannot start Volumio Streaming Daemon Jan 25 08:32:04 music volumio[30899]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Jan 25 08:32:04 music volumio[30899]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Jan 25 08:32:04 music volumio[30899]: 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 25 08:32:04 music volumio[30899]: info: CoreCommandRouter::volumioGetState Jan 25 08:32:04 music volumio[30899]: info: CorePlayQueue::getTrack 0 Jan 25 08:32:05 music volumio[30899]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Jan 25 08:32:05 music volumio[30899]: SPOTIFY: SPOTIFY VOLUME undefined Jan 25 08:32:05 music volumio[30899]: SPOTIFY: VOLUMIO VOLUME 86 Jan 25 08:32:05 music volumio[30899]: info: Aligning Spotify Volume to Volumio Volume Jan 25 08:32:05 music volumio[30899]: info: CoreCommandRouter::volumioGetState Jan 25 08:32:05 music volumio[30899]: info: CorePlayQueue::getTrack 0 Jan 25 08:32:05 music volumio[30899]: info: Setting Spotify Volume from Volumio: 86 Jan 25 08:32:05 music go-librespot[31193]: time="2026-01-25T08:32:05-05:00" level=debug msg="connected to ap-gew4.spotify.com:80" Jan 25 08:32:05 music go-librespot[31193]: time="2026-01-25T08:32:05-05:00" level=debug msg="completed keyexchange" Jan 25 08:32:05 music go-librespot[31193]: time="2026-01-25T08:32:05-05:00" level=debug msg="completed challenge" Jan 25 08:32:05 music volumio[30899]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Jan 25 08:32:05 music go-librespot[31193]: time="2026-01-25T08:32:05-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 25 08:32:05 music go-librespot[31193]: time="2026-01-25T08:32:05-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 25 08:32:05 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 25 08:32:05 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 25 08:32:05 music volumio[30899]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 25 08:32:05 music volumio[30899]: Error: socket hang up Jan 25 08:32:05 music volumio[30899]: at connResetException (node:internal/errors:720:14) Jan 25 08:32:05 music volumio[30899]: at Socket.socketOnEnd (node:_http_client:519:23) Jan 25 08:32:05 music volumio[30899]: at Socket.emit (node:events:526:35) Jan 25 08:32:05 music volumio[30899]: at endReadableNT (node:internal/streams/readable:1376:12) Jan 25 08:32:05 music volumio[30899]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { Jan 25 08:32:05 music volumio[30899]: code: 'ECONNRESET', Jan 25 08:32:05 music volumio[30899]: response: undefined Jan 25 08:32:05 music volumio[30899]: } Jan 25 08:32:05 music volumio[30899]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 25 08:32:06 music sudo[31238]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-01-25 08:31' Jan 25 08:32:06 music sudo[31238]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 08:32:06 music sudo[31238]: pam_unix(sudo:session): session closed for user root Jan 25 08:32:07 music volumio-remote-updater[1248]: [2026-01-25 08:32:07] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Jan 25 08:32:07 music volumio-remote-updater[1248]: [2026-01-25 08:32:07] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Jan 25 08:32:07 music systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Jan 25 08:32:07 music systemd[1]: volumio.service: Failed with result 'exit-code'. Jan 25 08:32:07 music systemd[1]: volumio.service: Consumed 27.068s CPU time. Jan 25 08:32:07 music systemd[1]: Started dynamicswap.service - dynamicswap service. Jan 25 08:32:07 music systemd[1]: dynamicswap.service: Deactivated successfully. Jan 25 08:32:07 music systemd[1]: volumio.service: Scheduled restart job, restart counter is at 27511. Jan 25 08:32:07 music systemd[1]: Started dynamicswap.service - dynamicswap service. Jan 25 08:32:07 music systemd[1]: Stopped volumio.service - Volumio Backend Module. Jan 25 08:32:07 music systemd[1]: volumio.service: Consumed 27.068s CPU time. Jan 25 08:32:07 music systemd[1]: Started volumio.service - Volumio Backend Module. Jan 25 08:32:07 music systemd[1]: dynamicswap.service: Deactivated successfully. Jan 25 08:32:08 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Jan 25 08:32:08 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 25 08:32:08 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 25 08:32:08 music go-librespot[31268]: go-librespot daemon starting... Jan 25 08:32:08 music go-librespot[31269]: time="2026-01-25T08:32:08-05:00" level=info msg="running go-librespot 0.6.2" Jan 25 08:32:08 music go-librespot[31269]: time="2026-01-25T08:32:08-05:00" level=debug msg="app state loaded" Jan 25 08:32:08 music go-librespot[31269]: time="2026-01-25T08:32:08-05:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 25 08:32:08 music go-librespot[31269]: time="2026-01-25T08:32: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 25 08:32:08 music go-librespot[31269]: time="2026-01-25T08:32: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 25 08:32:08 music go-librespot[31269]: time="2026-01-25T08:32: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 25 08:32:08 music go-librespot[31269]: time="2026-01-25T08:32:08-05:00" level=info msg="zeroconf server listening on port 41311" Jan 25 08:32:09 music go-librespot[31269]: time="2026-01-25T08:32:09-05:00" level=debug msg="obtained new client token: AADwddwjBMeqS7RYWwfgjMUZhoqXgHM2+E71UdFFlSEg97VU/ZTE1pWluKnsp+UXDw/5jKsILURaxFuZZVAEk+cdE7cLxssvlAnkPT7u9GbfixI2EGnCf9jlJUOZVkc7pyc699qD18ffHICHR28LR3yB72IJ0Sz9JnzLAty7vfULS7W2gXiQe2e83YUC8nKfH+oWdl3qv3BlgfMpHUX45sXTe6gR9qwjB8QaCrLJrUNCwj6MNtje" Jan 25 08:32:09 music go-librespot[31269]: time="2026-01-25T08:32:09-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Jan 25 08:32:09 music go-librespot[31269]: time="2026-01-25T08:32:09-05:00" level=debug msg="completed keyexchange" Jan 25 08:32:09 music go-librespot[31269]: time="2026-01-25T08:32:09-05:00" level=debug msg="completed challenge" Jan 25 08:32:09 music volumio[31253]: info: ------------------------------------------- Jan 25 08:32:09 music volumio[31253]: info: ----- Volumio3 ---- Jan 25 08:32:09 music volumio[31253]: info: ------------------------------------------- Jan 25 08:32:09 music volumio[31253]: info: ----- System startup ---- Jan 25 08:32:09 music volumio[31253]: info: ------------------------------------------- Jan 25 08:32:09 music go-librespot[31269]: time="2026-01-25T08:32:09-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 25 08:32:09 music go-librespot[31269]: time="2026-01-25T08:32:09-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Jan 25 08:32:09 music go-librespot[31269]: time="2026-01-25T08:32:09-05:00" level=debug msg="completed keyexchange" Jan 25 08:32:09 music go-librespot[31269]: time="2026-01-25T08:32:09-05:00" level=debug msg="completed challenge" Jan 25 08:32:10 music go-librespot[31269]: time="2026-01-25T08:32:10-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 25 08:32:10 music volumio[31253]: info: MYVOLUMIO Environment detected Jan 25 08:32:10 music volumio[31253]: info: Plugin folders cleanup Jan 25 08:32:10 music volumio[31253]: info: Scanning into folder /volumio/app/plugins/ Jan 25 08:32:10 music volumio[31253]: info: Scanning category audio_interface Jan 25 08:32:10 music volumio[31253]: info: Scanning category miscellanea Jan 25 08:32:10 music volumio[31253]: info: Scanning category music_service Jan 25 08:32:10 music volumio[31253]: info: Scanning category plugins.json Jan 25 08:32:10 music volumio[31253]: info: Scanning category system_controller Jan 25 08:32:10 music volumio[31253]: info: Scanning category user_interface Jan 25 08:32:10 music volumio[31253]: info: Scanning into folder /data/plugins/ Jan 25 08:32:10 music volumio[31253]: info: Scanning category music_service Jan 25 08:32:10 music volumio[31253]: info: Plugin folders cleanup completed Jan 25 08:32:10 music volumio[31253]: info: ------------------------------------------- Jan 25 08:32:10 music volumio[31253]: info: ----- Core plugins startup ---- Jan 25 08:32:10 music volumio[31253]: info: ------------------------------------------- Jan 25 08:32:10 music volumio[31253]: info: Loading plugins from folder /volumio/app/plugins/ Jan 25 08:32:10 music volumio[31253]: info: Adding plugin upnp to MyMusic Plugins Jan 25 08:32:10 music volumio[31253]: info: Adding plugin airplay_emulation to MyMusic Plugins Jan 25 08:32:10 music volumio[31253]: info: Adding plugin upnp_browser to MyMusic Plugins Jan 25 08:32:10 music volumio[31253]: info: Loading plugins from folder /data/plugins/ Jan 25 08:32:10 music volumio[31253]: info: Loading plugin "system"... Jan 25 08:32:10 music volumio[31253]: info: Loading plugin "appearance"... Jan 25 08:32:10 music go-librespot[31269]: time="2026-01-25T08:32:10-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Jan 25 08:32:10 music go-librespot[31269]: time="2026-01-25T08:32:10-05:00" level=debug msg="completed keyexchange" Jan 25 08:32:10 music go-librespot[31269]: time="2026-01-25T08:32:10-05:00" level=debug msg="completed challenge" Jan 25 08:32:10 music go-librespot[31269]: time="2026-01-25T08:32:10-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 25 08:32:11 music volumio[31253]: info: Loading plugin "network"... Jan 25 08:32:11 music go-librespot[31269]: time="2026-01-25T08:32:11-05:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 25 08:32:11 music volumio[31253]: info: Refreshing Cached IP Addresses Jan 25 08:32:11 music sudo[31292]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 25 08:32:11 music sudo[31292]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 08:32:11 music sudo[31292]: pam_unix(sudo:session): session closed for user root Jan 25 08:32:11 music sudo[31294]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 25 08:32:11 music sudo[31294]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 08:32:11 music volumio[31253]: info: Loading plugin "services"... Jan 25 08:32:11 music sudo[31294]: pam_unix(sudo:session): session closed for user root Jan 25 08:32:11 music volumio[31253]: info: Loading plugin "alsa_controller"... Jan 25 08:32:11 music go-librespot[31269]: time="2026-01-25T08:32:11-05:00" level=debug msg="completed keyexchange" Jan 25 08:32:11 music go-librespot[31269]: time="2026-01-25T08:32:11-05:00" level=debug msg="completed challenge" Jan 25 08:32:11 music sudo[31302]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Jan 25 08:32:11 music sudo[31302]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 08:32:11 music go-librespot[31269]: time="2026-01-25T08:32:11-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 25 08:32:11 music volumio[31253]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 25 08:32:11 music volumio[31253]: info: Loading plugin "wizard"... Jan 25 08:32:11 music volumio[31253]: info: Loading plugin "networkfs"... Jan 25 08:32:11 music volumio[31253]: info: Starting Udev Watcher for removable devices Jan 25 08:32:11 music volumio[31253]: info: Ignoring mount for partition: boot Jan 25 08:32:11 music volumio[31253]: info: Ignoring mount for partition: volumio Jan 25 08:32:11 music volumio[31253]: info: Ignoring mount for partition: volumio_data Jan 25 08:32:11 music volumio[31253]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 25 08:32:11 music volumio[31253]: info: Loading plugin "volumio_command_line_client"... Jan 25 08:32:11 music volumio[31253]: info: Loading plugin "upnp"... Jan 25 08:32:11 music volumio[31253]: info: [1769347931565] Starting Upmpd Daemon Jan 25 08:32:11 music volumio[31253]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 25 08:32:11 music volumio[31253]: info: Loading plugin "my_music"... Jan 25 08:32:11 music volumio[31253]: info: Loading plugin "mpd"... Jan 25 08:32:11 music volumio[31253]: info: Loading plugin "upnp_browser"... Jan 25 08:32:11 music sudo[31302]: pam_unix(sudo:session): session closed for user root Jan 25 08:32:12 music volumio-remote-updater[1248]: [2026-01-25 08:32:12] [connect] Successful connection Jan 25 08:32:12 music go-librespot[31269]: time="2026-01-25T08:32:12-05:00" level=debug msg="connected to ap-gae2.spotify.com:443" Jan 25 08:32:12 music go-librespot[31269]: time="2026-01-25T08:32:12-05:00" level=debug msg="completed keyexchange" Jan 25 08:32:12 music go-librespot[31269]: time="2026-01-25T08:32:12-05:00" level=debug msg="completed challenge" Jan 25 08:32:12 music go-librespot[31269]: time="2026-01-25T08:32:12-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 25 08:32:13 music go-librespot[31269]: time="2026-01-25T08:32:13-05:00" level=debug msg="connected to ap-gew4.spotify.com:80" Jan 25 08:32:13 music go-librespot[31269]: time="2026-01-25T08:32:13-05:00" level=debug msg="completed keyexchange" Jan 25 08:32:13 music go-librespot[31269]: time="2026-01-25T08:32:13-05:00" level=debug msg="completed challenge" Jan 25 08:32:13 music go-librespot[31269]: time="2026-01-25T08:32:13-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 25 08:32:13 music go-librespot[31269]: time="2026-01-25T08:32: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 25 08:32:13 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 25 08:32:13 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 25 08:32:13 music volumio[31253]: info: Starting UPNP Browser Jan 25 08:32:13 music volumio[31253]: info: Loading plugin "alarm-clock"... Jan 25 08:32:13 music volumio[31253]: info: Loading plugin "airplay_emulation"... Jan 25 08:32:13 music volumio[31253]: info: Starting Shairport Sync Jan 25 08:32:13 music volumio[31253]: info: Loading plugin "last_100"... Jan 25 08:32:13 music volumio[31253]: info: Loading plugin "webradio"... Jan 25 08:32:13 music volumio[31253]: info: Loading plugin "i2s_dacs"... Jan 25 08:32:13 music volumio[31253]: info: I2S DAC not set, start Auto-detection Jan 25 08:32:13 music volumio[31253]: info: Loading plugin "volumiodiscovery"... Jan 25 08:32:13 music volumio[31253]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jan 25 08:32:13 music volumio[31253]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 25 08:32:13 music volumio[31253]: *** WARNING *** For more information see Jan 25 08:32:13 music volumio[31253]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jan 25 08:32:13 music volumio[31253]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 25 08:32:13 music volumio[31253]: *** WARNING *** For more information see Jan 25 08:32:13 music node[31253]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jan 25 08:32:13 music node[31253]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 25 08:32:13 music node[31253]: *** WARNING *** For more information see Jan 25 08:32:13 music node[31253]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jan 25 08:32:13 music node[31253]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 25 08:32:13 music node[31253]: *** WARNING *** For more information see Jan 25 08:32:13 music volumio[31253]: info: Applying required configuration parameters for plugin volumiodiscovery Jan 25 08:32:13 music volumio[31253]: info: Discovery: Started advertising with name: music Jan 25 08:32:13 music volumio[31253]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 25 08:32:13 music volumio[31253]: info: Loading plugin "spop"... Jan 25 08:32:14 music volumio[31253]: info: Loading plugin "outputs"... Jan 25 08:32:14 music volumio[31253]: info: Loading plugin "albumart"... Jan 25 08:32:14 music volumio[31253]: info: Plugin example_plugin is not enabled Jan 25 08:32:14 music volumio[31253]: info: Loading plugin "inputs"... Jan 25 08:32:14 music volumio[31253]: info: Loading plugin "updater_comm"... Jan 25 08:32:15 music volumio[31253]: info: Plugin mpdemulation is not enabled Jan 25 08:32:15 music volumio[31253]: info: Loading plugin "rest_api"... Jan 25 08:32:15 music volumio[31253]: info: Loading plugin "websocket"... Jan 25 08:32:15 music volumio[31253]: info: Starting Socket.io Server version 1.7.4 Jan 25 08:32:15 music volumio[31253]: info: Loading i18n strings for locale en Jan 25 08:32:15 music volumio[31253]: Updating browse sources language Jan 25 08:32:15 music volumio[31253]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 25 08:32:15 music volumio[31253]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 25 08:32:15 music volumio[31253]: info: CoreCommandRouter::initPlayerControls Jan 25 08:32:15 music volumio[31253]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:32:15 music volumio[31253]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:32:15 music volumio[31253]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:32:15 music volumio[31253]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:32:15 music volumio[31253]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:32:15 music volumio[31253]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:32:15 music volumio[31253]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:32:15 music volumio[31253]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:32:15 music volumio[31253]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 25 08:32:15 music volumio[31253]: Express server listening on port 3000 Jan 25 08:32:15 music volumio[31253]: [Metrics] WebUI: 6s 592.16ms Jan 25 08:32:15 music volumio[31253]: info: CoreStateMachine::resetVolumioState Jan 25 08:32:15 music volumio[31253]: info: CoreStateMachine::getcurrentVolume Jan 25 08:32:15 music volumio[31253]: info: CoreCommandRouter::volumioRetrievevolume Jan 25 08:32:15 music volumio[31253]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 25 08:32:15 music volumio[31253]: info: Volumio Network Manager: Network status updated: 1 Jan 25 08:32:15 music volumio-remote-updater[1248]: [2026-01-25 08:32:15] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1769347932 101 Jan 25 08:32:15 music volumio[31327]: Forking 3 albumart workers Jan 25 08:32:15 music volumio[31253]: 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 25 08:32:15 music volumio[31253]: info: VolumeController:: Volume=86 Mute =false Jan 25 08:32:15 music volumio[31253]: info: CoreStateMachine::pushState Jan 25 08:32:15 music volumio[31253]: info: CorePlayQueue::getTrack 0 Jan 25 08:32:15 music volumio[31253]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 25 08:32:15 music volumio[31253]: info: CoreCommandRouter::volumioPushState Jan 25 08:32:15 music volumio[31253]: info: CoreStateMachine::updateTrackBlock Jan 25 08:32:15 music volumio[31253]: info: CorePlayQueue::getTrackBlock Jan 25 08:32:15 music volumio[31253]: info: CoreCommandRouter::volumioRetrievevolume Jan 25 08:32:15 music volumio[31253]: info: Reloading queue from file Jan 25 08:32:15 music volumio[31253]: info: CoreStateMachine::setRepeat null single undefined Jan 25 08:32:15 music volumio[31253]: info: CoreStateMachine::pushState Jan 25 08:32:15 music volumio[31253]: info: CorePlayQueue::getTrack 0 Jan 25 08:32:15 music volumio[31253]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 25 08:32:15 music volumio[31253]: info: CoreCommandRouter::volumioPushState Jan 25 08:32:15 music volumio[31253]: info: CoreStateMachine::setRandom null Jan 25 08:32:15 music volumio[31253]: info: CoreStateMachine::pushState Jan 25 08:32:15 music volumio[31253]: info: CorePlayQueue::getTrack 0 Jan 25 08:32:15 music volumio[31253]: info: CoreCommandRouter::volumioPushState Jan 25 08:32:15 music volumio[31253]: info: Setting Device type: Raspberry PI Jan 25 08:32:15 music volumio[31253]: info: VolumeController:: Volume=86 Mute =false Jan 25 08:32:15 music volumio[31253]: info: CoreStateMachine::pushState Jan 25 08:32:15 music volumio[31253]: info: CorePlayQueue::getTrack 0 Jan 25 08:32:15 music volumio[31253]: info: CoreCommandRouter::volumioPushState Jan 25 08:32:15 music volumio[31253]: info: Completed loading Core Plugins Jan 25 08:32:15 music volumio[31253]: info: Preparing to generate the ALSA configuration file Jan 25 08:32:15 music volumio[31253]: info: Discovery: adding 4a29b7a7-c637-4926-a2bd-fb4e2f55145e Jan 25 08:32:15 music volumio[31253]: info: Discovery: Found device music Jan 25 08:32:15 music volumio[31253]: info: CoreCommandRouter::volumioGetState Jan 25 08:32:15 music volumio[31253]: info: CorePlayQueue::getTrack 0 Jan 25 08:32:15 music volumio[31253]: info: Discovery: this is already registered, 4a29b7a7-c637-4926-a2bd-fb4e2f55145e Jan 25 08:32:15 music volumio[31253]: info: Discovery: Found device music Jan 25 08:32:15 music volumio[31253]: info: CoreCommandRouter::volumioGetState Jan 25 08:32:15 music volumio[31253]: info: CorePlayQueue::getTrack 0 Jan 25 08:32:15 music volumio[31253]: info: Asound.conf file unchanged, so no further update is needed Jan 25 08:32:15 music volumio[31253]: info: Output device has changed, restarting MPD Jan 25 08:32:15 music volumio[31253]: info: Output device has changed, restarting Shairport Sync Jan 25 08:32:15 music volumio[31253]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:32:15 music volumio[31253]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 25 08:32:15 music sudo[31383]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 25 08:32:15 music sudo[31383]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 08:32:15 music sudo[31383]: pam_unix(sudo:session): session closed for user root Jan 25 08:32:15 music sudo[31384]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 25 08:32:15 music sudo[31384]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 08:32:15 music volumio[31253]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 25 08:32:15 music volumio[31253]: info: ___________ START PLUGINS ___________ Jan 25 08:32:16 music volumio[31253]: info: ControllerMpd::onStart: Initializing MPD Jan 25 08:32:16 music volumio[31253]: info: Creating MPD Configuration file Jan 25 08:32:16 music systemd[1]: Stopping mpd.service - Music Player Daemon... Jan 25 08:32:16 music volumio[31253]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 25 08:32:16 music volumio[31253]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 25 08:32:16 music volumio[31253]: info: [1769347936048] CoreMusicLibrary::Adding element Media Servers Jan 25 08:32:16 music volumio[31253]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 25 08:32:16 music volumio[31253]: info: UPNP Browser: Client initialized successfully Jan 25 08:32:16 music sudo[31393]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 25 08:32:16 music volumio[31253]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:32:16 music volumio[31253]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 25 08:32:16 music sudo[31394]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 25 08:32:16 music sudo[31394]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 08:32:16 music sudo[31393]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 08:32:16 music systemd[1]: mpd.service: Deactivated successfully. Jan 25 08:32:16 music systemd[1]: Stopped mpd.service - Music Player Daemon. Jan 25 08:32:16 music systemd[1]: mpd.service: Consumed 4.182s CPU time. Jan 25 08:32:16 music sudo[31393]: pam_unix(sudo:session): session closed for user root Jan 25 08:32:16 music systemd[1]: mpd.socket: Deactivated successfully. Jan 25 08:32:16 music systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jan 25 08:32:16 music systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jan 25 08:32:16 music volumio[31253]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 25 08:32:16 music volumio[31253]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:32:16 music volumio[31253]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 25 08:32:16 music systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jan 25 08:32:16 music systemd[1]: Starting mpd.service - Music Player Daemon... Jan 25 08:32:16 music volumio[31253]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 25 08:32:16 music volumio[31253]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 25 08:32:16 music volumio[31253]: info: [1769347936214] CoreMusicLibrary::Adding element Last_100 Jan 25 08:32:16 music volumio[31253]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 25 08:32:16 music volumio[31253]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 25 08:32:16 music volumio[31253]: info: [1769347936230] CoreMusicLibrary::Adding element Webradio Jan 25 08:32:16 music volumio[31253]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 25 08:32:16 music systemd[1]: mpd.service: Deactivated successfully. Jan 25 08:32:16 music systemd[1]: Stopped mpd.service - Music Player Daemon. Jan 25 08:32:16 music systemd[1]: mpd.socket: Deactivated successfully. Jan 25 08:32:16 music volumio[31253]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 25 08:32:16 music systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jan 25 08:32:16 music systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jan 25 08:32:16 music volumio[31253]: info: Initializing BBC Radios Jan 25 08:32:16 music systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jan 25 08:32:16 music systemd[1]: Starting mpd.service - Music Player Daemon... Jan 25 08:32:16 music volumio[31253]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 25 08:32:16 music volumio[31253]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 25 08:32:16 music volumio[31253]: info: Creating Spotify config file Jan 25 08:32:16 music volumio[31253]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:32:16 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Jan 25 08:32:16 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 25 08:32:16 music sudo[31409]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jan 25 08:32:16 music sudo[31409]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Jan 25 08:32:16 music sudo[31409]: pam_unix(sudo:session): session closed for user root Jan 25 08:32:16 music go-librespot[31422]: go-librespot daemon starting... Jan 25 08:32:16 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 25 08:32:16 music go-librespot[31424]: time="2026-01-25T08:32:16-05:00" level=info msg="running go-librespot 0.6.2" Jan 25 08:32:17 music go-librespot[31424]: time="2026-01-25T08:32:17-05:00" level=info msg="zeroconf server listening on port 37401" Jan 25 08:32:17 music volumio[31253]: info: Volumio Calling Home Jan 25 08:32:17 music volumio[31345]: Starting albumart workers Jan 25 08:32:17 music volumio[31344]: Starting albumart workers Jan 25 08:32:17 music volumio[31343]: Starting albumart workers Jan 25 08:32:17 music volumio[31253]: info: MPD Permissions set Jan 25 08:32:17 music volumio[31253]: info: MPD Permissions set Jan 25 08:32:17 music volumio[31253]: info: Spotify config file written Jan 25 08:32:17 music volumio[31253]: 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 25 08:32:17 music sudo[31440]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jan 25 08:32:17 music sudo[31440]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 08:32:17 music volumio[31253]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:32:17 music volumio[31253]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:32:17 music volumio[31253]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:32:17 music volumio[31253]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:32:17 music volumio[31253]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:32:17 music volumio[31253]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:32:17 music volumio[31253]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:32:17 music volumio[31253]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:32:17 music systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Jan 25 08:32:17 music systemd[1]: go-librespot-daemon.service: Deactivated successfully. Jan 25 08:32:17 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 25 08:32:18 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 25 08:32:18 music go-librespot[31443]: go-librespot daemon starting... Jan 25 08:32:18 music sudo[31440]: pam_unix(sudo:session): session closed for user root Jan 25 08:32:18 music volumio[31253]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 25 08:32:18 music go-librespot[31448]: time="2026-01-25T08:32:18-05:00" level=info msg="running go-librespot 0.6.2" Jan 25 08:32:18 music go-librespot[31448]: time="2026-01-25T08:32:18-05:00" level=debug msg="app state loaded" Jan 25 08:32:18 music volumio[31253]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:32:18 music volumio[31253]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:32:18 music volumio[31253]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:32:18 music volumio[31253]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:32:18 music volumio[31253]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:32:18 music volumio[31253]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:32:18 music volumio[31253]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:32:18 music volumio[31253]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:32:18 music volumio[31253]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:32:18 music go-librespot[31448]: time="2026-01-25T08:32:18-05:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 25 08:32:18 music volumio[31253]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 25 08:32:18 music volumio[31253]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:32:18 music volumio[31253]: info: No need to fix Spotify hosts Jan 25 08:32:18 music volumio[31253]: info: Volumio called home Jan 25 08:32:18 music go-librespot[31448]: time="2026-01-25T08:32:18-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 25 08:32:18 music go-librespot[31448]: time="2026-01-25T08:32:18-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 25 08:32:18 music go-librespot[31448]: time="2026-01-25T08:32:18-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 25 08:32:18 music go-librespot[31448]: time="2026-01-25T08:32:18-05:00" level=info msg="zeroconf server listening on port 46485" Jan 25 08:32:18 music go-librespot[31448]: time="2026-01-25T08:32:18-05:00" level=debug msg="obtained new client token: AACMiLiktpwww97I1RXbNZDZlL31v899P/iLaxyuntBfRIhgNZC5J8u3tMS8nvW9pjjuxaBfr6fpjrAwQY9pynUlx7Pf9nrQ9yvzyDl2qvWhgrBZcJJrRWXLGwjTsOrejuMZzP3AJsTdcicKOxd8Qlsbv59VYczwDgEmhKMBBMV0trF1o8EtssO+h716ClWZK/fPMfnbFYHHJpdtjjmYDKccG14JZlgOHlfx9ZcpgKs2yv7gLV53u8s=" Jan 25 08:32:18 music go-librespot[31448]: time="2026-01-25T08:32:18-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Jan 25 08:32:18 music volumio[31253]: info: Starting Shairport Sync Jan 25 08:32:18 music volumio[31253]: info: Starting Shairport Sync Jan 25 08:32:18 music volumio[31253]: info: Starting Shairport Sync Jan 25 08:32:18 music go-librespot[31448]: time="2026-01-25T08:32:18-05:00" level=debug msg="completed keyexchange" Jan 25 08:32:18 music go-librespot[31448]: time="2026-01-25T08:32:18-05:00" level=debug msg="completed challenge" Jan 25 08:32:18 music sudo[31481]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 25 08:32:19 music sudo[31481]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 08:32:19 music sudo[31483]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 25 08:32:19 music sudo[31483]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 08:32:19 music sudo[31485]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 25 08:32:19 music sudo[31485]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 08:32:19 music go-librespot[31448]: time="2026-01-25T08:32:19-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 25 08:32:19 music volumio[31253]: info: An error occurred while refreshing Spotify Token Error: Bad Request Jan 25 08:32:19 music systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jan 25 08:32:19 music systemd[1]: shairport-sync.service: Deactivated successfully. Jan 25 08:32:19 music systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 25 08:32:19 music systemd[1]: shairport-sync.service: Consumed 1.876s CPU time. Jan 25 08:32:19 music systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 25 08:32:19 music sudo[31481]: pam_unix(sudo:session): session closed for user root Jan 25 08:32:19 music sudo[31485]: pam_unix(sudo:session): session closed for user root Jan 25 08:32:19 music sudo[31483]: pam_unix(sudo:session): session closed for user root Jan 25 08:32:19 music volumio[31253]: info: CoreCommandRouter::volumioGetState Jan 25 08:32:19 music volumio[31253]: info: CorePlayQueue::getTrack 0 Jan 25 08:32:19 music volumio[31253]: info: Shairport-Sync Started Jan 25 08:32:19 music volumio[31253]: Error adding Membership: Error: addMembership EINVAL Jan 25 08:32:19 music volumio[31253]: info: Shairport-Sync Started Jan 25 08:32:19 music volumio[31253]: info: Shairport-Sync Started Jan 25 08:32:19 music volumio[31253]: info: Listing playlists Jan 25 08:32:19 music volumio[31253]: info: Listing playlists Jan 25 08:32:19 music volumio[31253]: info: CoreCommandRouter::volumioGetState Jan 25 08:32:19 music volumio[31253]: info: CorePlayQueue::getTrack 0 Jan 25 08:32:19 music go-librespot[31448]: time="2026-01-25T08:32:19-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Jan 25 08:32:19 music go-librespot[31448]: time="2026-01-25T08:32:19-05:00" level=debug msg="completed keyexchange" Jan 25 08:32:19 music go-librespot[31448]: time="2026-01-25T08:32:19-05:00" level=debug msg="completed challenge" Jan 25 08:32:19 music go-librespot[31448]: time="2026-01-25T08:32:19-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 25 08:32:20 music go-librespot[31448]: time="2026-01-25T08:32:20-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Jan 25 08:32:20 music go-librespot[31448]: time="2026-01-25T08:32:20-05:00" level=debug msg="completed keyexchange" Jan 25 08:32:20 music go-librespot[31448]: time="2026-01-25T08:32:20-05:00" level=debug msg="completed challenge" Jan 25 08:32:20 music go-librespot[31448]: time="2026-01-25T08:32:20-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 25 08:32:20 music mpd[31430]: 2026-01-25T08:32:20 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jan 25 08:32:20 music systemd[1]: Started mpd.service - Music Player Daemon. Jan 25 08:32:20 music sudo[31394]: pam_unix(sudo:session): session closed for user root Jan 25 08:32:20 music sudo[31384]: pam_unix(sudo:session): session closed for user root Jan 25 08:32:20 music volumio[31253]: info: Completed starting Core Plugins Jan 25 08:32:20 music volumio[31253]: info: ------------------------------------------- Jan 25 08:32:20 music volumio[31253]: info: ----- MyVolumio plugins startup ---- Jan 25 08:32:20 music volumio[31253]: info: ------------------------------------------- Jan 25 08:32:20 music volumio[31253]: info: [MyVolumio PluginManager] Fetching plans data.... Jan 25 08:32:20 music volumio[31253]: error: MPD error: The expression evaluated to a falsy value: Jan 25 08:32:20 music volumio[31253]: assert.ok(self.idling) Jan 25 08:32:20 music volumio[31253]: error: The expression evaluated to a falsy value: Jan 25 08:32:20 music volumio[31253]: assert.ok(self.idling) Jan 25 08:32:20 music volumio[31253]: error: updateQueue error: null Jan 25 08:32:20 music volumio[31253]: info: MPD running with PID31430 Jan 25 08:32:20 music volumio[31253]: ,establishing connection Jan 25 08:32:20 music volumio[31253]: error: updateQueue error: null Jan 25 08:32:21 music go-librespot[31448]: time="2026-01-25T08:32:21-05:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 25 08:32:21 music go-librespot[31448]: time="2026-01-25T08:32:21-05:00" level=debug msg="completed keyexchange" Jan 25 08:32:21 music go-librespot[31448]: time="2026-01-25T08:32:21-05:00" level=debug msg="completed challenge" Jan 25 08:32:21 music sudo[31525]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 25 08:32:21 music sudo[31525]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 08:32:21 music sudo[31527]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 25 08:32:21 music sudo[31527]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 08:32:21 music sudo[31525]: pam_unix(sudo:session): session closed for user root Jan 25 08:32:21 music go-librespot[31448]: time="2026-01-25T08:32:21-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 25 08:32:21 music sudo[31527]: pam_unix(sudo:session): session closed for user root Jan 25 08:32:21 music sudo[31529]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Jan 25 08:32:21 music sudo[31529]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 08:32:21 music sudo[31529]: pam_unix(sudo:session): session closed for user root Jan 25 08:32:21 music volumio[31253]: info: Upmpdcli Daemon Started Jan 25 08:32:21 music volumio[31253]: info: go-librespot daemon successfully initialized Jan 25 08:32:22 music go-librespot[31448]: time="2026-01-25T08:32:22-05:00" level=debug msg="connected to ap-gew1.spotify.com:443" Jan 25 08:32:22 music go-librespot[31448]: time="2026-01-25T08:32:22-05:00" level=debug msg="completed keyexchange" Jan 25 08:32:22 music go-librespot[31448]: time="2026-01-25T08:32:22-05:00" level=debug msg="completed challenge" Jan 25 08:32:22 music go-librespot[31448]: time="2026-01-25T08:32:22-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 25 08:32:23 music go-librespot[31448]: time="2026-01-25T08:32:23-05:00" level=debug msg="connected to ap-gew4.spotify.com:80" Jan 25 08:32:23 music go-librespot[31448]: time="2026-01-25T08:32:23-05:00" level=debug msg="completed keyexchange" Jan 25 08:32:23 music go-librespot[31448]: time="2026-01-25T08:32:23-05:00" level=debug msg="completed challenge" Jan 25 08:32:23 music go-librespot[31448]: time="2026-01-25T08:32:23-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 25 08:32:23 music go-librespot[31448]: time="2026-01-25T08:32:23-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 25 08:32:23 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 25 08:32:23 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 25 08:32:23 music sudo[31534]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Jan 25 08:32:23 music sudo[31534]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 08:32:23 music sudo[31536]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Jan 25 08:32:23 music sudo[31536]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 08:32:23 music systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Jan 25 08:32:23 music systemd[1]: mpd_monitor.service: Deactivated successfully. Jan 25 08:32:23 music systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Jan 25 08:32:23 music systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Jan 25 08:32:23 music sudo[31534]: pam_unix(sudo:session): session closed for user root Jan 25 08:32:23 music mpd_monitor.sh[31539]: MPD Monitor Service: Starting MPD Monitor Service Jan 25 08:32:23 music sudo[31536]: pam_unix(sudo:session): session closed for user root Jan 25 08:32:23 music volumio[31253]: info: Successfully started MPD Monitor Jan 25 08:32:24 music volumio[31253]: info: Successfully started MPD Monitor Jan 25 08:32:24 music volumio[31253]: info: Initializing connection to go-librespot Websocket Jan 25 08:32:24 music volumio[31253]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 25 08:32:25 music volumio[31253]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Jan 25 08:32:26 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Jan 25 08:32:26 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 25 08:32:26 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 25 08:32:26 music go-librespot[31543]: go-librespot daemon starting... Jan 25 08:32:26 music go-librespot[31544]: time="2026-01-25T08:32:26-05:00" level=info msg="running go-librespot 0.6.2" Jan 25 08:32:26 music go-librespot[31544]: time="2026-01-25T08:32:26-05:00" level=debug msg="app state loaded" Jan 25 08:32:26 music go-librespot[31544]: time="2026-01-25T08:32:26-05:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 25 08:32:26 music go-librespot[31544]: time="2026-01-25T08:32: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 25 08:32:26 music go-librespot[31544]: time="2026-01-25T08:32: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 25 08:32:26 music go-librespot[31544]: time="2026-01-25T08:32: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 25 08:32:26 music go-librespot[31544]: time="2026-01-25T08:32:26-05:00" level=info msg="zeroconf server listening on port 35737" Jan 25 08:32:27 music go-librespot[31544]: time="2026-01-25T08:32:27-05:00" level=debug msg="obtained new client token: AADMwkBgc7HMHonKJpk2ARPCZocXsO01Z/ez7ytZqn5QyI1bVvOC6Hh5v5npbwTaNQ7qaBNqLJVsS+PoklBkUzly91dVnRdHz1McLqXlf8UkJM4cPTD2YjscF9TWduT3UNqJrDQxMv/mBCrBr+TLZEQVAQ2iZSVgvDpVzHyFwyRi7DVOz4qn7SRk2DoQGsRusu/4TNIOEu8GAm8GTlWsz//kyCdu9mNl+0HBJCGOl0VDE6EvnP9p" Jan 25 08:32:27 music go-librespot[31544]: time="2026-01-25T08:32:27-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Jan 25 08:32:27 music go-librespot[31544]: time="2026-01-25T08:32:27-05:00" level=debug msg="completed keyexchange" Jan 25 08:32:27 music go-librespot[31544]: time="2026-01-25T08:32:27-05:00" level=debug msg="completed challenge" Jan 25 08:32:27 music go-librespot[31544]: time="2026-01-25T08:32:27-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 25 08:32:27 music volumio[31253]: info: Initializing connection to go-librespot Websocket Jan 25 08:32:27 music go-librespot[31544]: time="2026-01-25T08:32:27-05:00" level=debug msg="new websocket client" Jan 25 08:32:27 music volumio[31253]: info: Connection to go-librespot Websocket established Jan 25 08:32:27 music go-librespot[31544]: time="2026-01-25T08:32:27-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Jan 25 08:32:27 music go-librespot[31544]: time="2026-01-25T08:32:27-05:00" level=debug msg="completed keyexchange" Jan 25 08:32:27 music go-librespot[31544]: time="2026-01-25T08:32:27-05:00" level=debug msg="completed challenge" Jan 25 08:32:28 music go-librespot[31544]: time="2026-01-25T08:32:28-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 25 08:32:28 music volumio[31253]: info: CoreCommandRouter::volumioGetState Jan 25 08:32:28 music volumio[31253]: info: CorePlayQueue::getTrack 0 Jan 25 08:32:28 music go-librespot[31544]: time="2026-01-25T08:32:28-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Jan 25 08:32:28 music go-librespot[31544]: time="2026-01-25T08:32:28-05:00" level=debug msg="completed keyexchange" Jan 25 08:32:28 music go-librespot[31544]: time="2026-01-25T08:32:28-05:00" level=debug msg="completed challenge" Jan 25 08:32:28 music go-librespot[31544]: time="2026-01-25T08:32:28-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 25 08:32:29 music volumio[31253]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Jan 25 08:32:29 music volumio[31253]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Jan 25 08:32:29 music volumio[31253]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Jan 25 08:32:29 music volumio[31253]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Jan 25 08:32:29 music volumio[31253]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Jan 25 08:32:29 music volumio[31253]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Jan 25 08:32:29 music volumio[31253]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Jan 25 08:32:29 music volumio[31253]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Jan 25 08:32:29 music volumio[31253]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Jan 25 08:32:29 music volumio[31253]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Jan 25 08:32:29 music volumio[31253]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Jan 25 08:32:29 music volumio[31253]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Jan 25 08:32:29 music volumio[31253]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Jan 25 08:32:29 music volumio[31253]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Jan 25 08:32:29 music volumio[31253]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Jan 25 08:32:29 music volumio[31253]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Jan 25 08:32:29 music volumio[31253]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Jan 25 08:32:29 music volumio[31253]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Jan 25 08:32:29 music volumio[31253]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Jan 25 08:32:29 music volumio[31253]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Jan 25 08:32:29 music volumio[31253]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Jan 25 08:32:29 music volumio[31253]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Jan 25 08:32:29 music volumio[31253]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Jan 25 08:32:29 music volumio[31253]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Jan 25 08:32:29 music volumio[31253]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Jan 25 08:32:29 music volumio[31253]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Jan 25 08:32:29 music volumio[31253]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Jan 25 08:32:29 music volumio[31253]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Jan 25 08:32:29 music volumio[31253]: info: Adding plugin bluetooth to MyMusic Plugins Jan 25 08:32:29 music volumio[31253]: info: Adding plugin multiroom to MyMusic Plugins Jan 25 08:32:29 music volumio[31253]: info: Adding plugin metavolumio to MyMusic Plugins Jan 25 08:32:29 music volumio[31253]: info: Adding plugin cd_controller to MyMusic Plugins Jan 25 08:32:29 music volumio[31253]: info: Adding plugin qobuzconnect to MyMusic Plugins Jan 25 08:32:29 music volumio[31253]: info: Adding plugin smart_inputs to MyMusic Plugins Jan 25 08:32:29 music volumio[31253]: info: Adding plugin tidalconnect to MyMusic Plugins Jan 25 08:32:29 music volumio[31253]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Jan 25 08:32:29 music go-librespot[31544]: time="2026-01-25T08:32:29-05:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 25 08:32:29 music go-librespot[31544]: time="2026-01-25T08:32:29-05:00" level=debug msg="completed keyexchange" Jan 25 08:32:29 music go-librespot[31544]: time="2026-01-25T08:32:29-05:00" level=debug msg="completed challenge" Jan 25 08:32:29 music go-librespot[31544]: time="2026-01-25T08:32:29-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 25 08:32:30 music volumio[31253]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Jan 25 08:32:30 music volumio[31253]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Jan 25 08:32:30 music volumio[31253]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 25 08:32:30 music volumio[31253]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 25 08:32:30 music volumio[31253]: info: Starting MyVolumio Remote Streaming Endpoints Jan 25 08:32:30 music volumio[31253]: info: MyVolumio login type: Token Jan 25 08:32:30 music volumio[31253]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Jan 25 08:32:30 music volumio[31253]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Jan 25 08:32:30 music go-librespot[31544]: time="2026-01-25T08:32:30-05:00" level=debug msg="connected to ap-gae2.spotify.com:443" Jan 25 08:32:30 music go-librespot[31544]: time="2026-01-25T08:32:30-05:00" level=debug msg="completed keyexchange" Jan 25 08:32:30 music go-librespot[31544]: time="2026-01-25T08:32:30-05:00" level=debug msg="completed challenge" Jan 25 08:32:30 music go-librespot[31544]: time="2026-01-25T08:32:30-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 25 08:32:31 music volumio[31253]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Jan 25 08:32:31 music volumio[31253]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Jan 25 08:32:31 music volumio[31253]: info: Streaming services startup Jan 25 08:32:31 music volumio[31253]: info: Starting Streaming Daemon Jan 25 08:32:31 music sudo[31554]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Jan 25 08:32:31 music sudo[31554]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 08:32:31 music volumio[31253]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Jan 25 08:32:31 music sudo[31554]: pam_unix(sudo:session): session closed for user root Jan 25 08:32:31 music volumio[31253]: info: Getting Spotify volume Jan 25 08:32:31 music volumio[31253]: error: Cannot start Volumio Streaming Daemon Jan 25 08:32:31 music volumio[31253]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Jan 25 08:32:31 music volumio[31253]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Jan 25 08:32:31 music volumio[31253]: 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 25 08:32:31 music go-librespot[31544]: time="2026-01-25T08:32:31-05:00" level=debug msg="connected to ap-gew1.spotify.com:80" Jan 25 08:32:31 music go-librespot[31544]: time="2026-01-25T08:32:31-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: read tcp 192.168.3.63:38174->104.199.65.9:80: read: connection reset by peer" Jan 25 08:32:31 music go-librespot[31544]: time="2026-01-25T08:32:31-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: read tcp 192.168.3.63:38174->104.199.65.9:80: read: connection reset by peer" Jan 25 08:32:31 music volumio[31253]: info: CoreCommandRouter::volumioGetState Jan 25 08:32:31 music volumio[31253]: info: CorePlayQueue::getTrack 0 Jan 25 08:32:31 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 25 08:32:31 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 25 08:32:31 music volumio[31253]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 25 08:32:31 music volumio[31253]: Error: socket hang up Jan 25 08:32:31 music volumio[31253]: at connResetException (node:internal/errors:720:14) Jan 25 08:32:31 music volumio[31253]: at Socket.socketOnEnd (node:_http_client:519:23) Jan 25 08:32:31 music volumio[31253]: at Socket.emit (node:events:526:35) Jan 25 08:32:31 music volumio[31253]: at endReadableNT (node:internal/streams/readable:1376:12) Jan 25 08:32:31 music volumio[31253]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { Jan 25 08:32:31 music volumio[31253]: code: 'ECONNRESET', Jan 25 08:32:31 music volumio[31253]: response: undefined Jan 25 08:32:31 music volumio[31253]: } Jan 25 08:32:31 music volumio[31253]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 25 08:32:32 music sudo[31588]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-01-25 08:31' Jan 25 08:32:32 music sudo[31588]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 08:32:32 music sudo[31588]: pam_unix(sudo:session): session closed for user root Jan 25 08:32:32 music volumio-remote-updater[1248]: [2026-01-25 08:32:32] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Jan 25 08:32:32 music volumio-remote-updater[1248]: [2026-01-25 08:32:32] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Jan 25 08:32:32 music systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Jan 25 08:32:32 music systemd[1]: volumio.service: Failed with result 'exit-code'. Jan 25 08:32:32 music systemd[1]: volumio.service: Consumed 26.589s CPU time. Jan 25 08:32:32 music systemd[1]: Started dynamicswap.service - dynamicswap service. Jan 25 08:32:32 music systemd[1]: dynamicswap.service: Deactivated successfully. Jan 25 08:32:32 music systemd[1]: volumio.service: Scheduled restart job, restart counter is at 27512. Jan 25 08:32:32 music systemd[1]: Started dynamicswap.service - dynamicswap service. Jan 25 08:32:32 music systemd[1]: Stopped volumio.service - Volumio Backend Module. Jan 25 08:32:32 music systemd[1]: volumio.service: Consumed 26.589s CPU time. Jan 25 08:32:32 music systemd[1]: Started volumio.service - Volumio Backend Module. Jan 25 08:32:32 music systemd[1]: dynamicswap.service: Deactivated successfully. Jan 25 08:32:34 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Jan 25 08:32:34 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 25 08:32:34 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 25 08:32:34 music go-librespot[31615]: go-librespot daemon starting... Jan 25 08:32:34 music go-librespot[31616]: time="2026-01-25T08:32:34-05:00" level=info msg="running go-librespot 0.6.2" Jan 25 08:32:34 music go-librespot[31616]: time="2026-01-25T08:32:34-05:00" level=debug msg="app state loaded" Jan 25 08:32:34 music go-librespot[31616]: time="2026-01-25T08:32:34-05:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 25 08:32:34 music volumio[31600]: info: ------------------------------------------- Jan 25 08:32:34 music volumio[31600]: info: ----- Volumio3 ---- Jan 25 08:32:34 music volumio[31600]: info: ------------------------------------------- Jan 25 08:32:34 music volumio[31600]: info: ----- System startup ---- Jan 25 08:32:34 music volumio[31600]: info: ------------------------------------------- Jan 25 08:32:34 music go-librespot[31616]: time="2026-01-25T08:32: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-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 25 08:32:34 music go-librespot[31616]: time="2026-01-25T08:32:34-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 25 08:32:34 music go-librespot[31616]: time="2026-01-25T08:32:34-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 25 08:32:35 music go-librespot[31616]: time="2026-01-25T08:32:35-05:00" level=info msg="zeroconf server listening on port 46421" Jan 25 08:32:35 music go-librespot[31616]: time="2026-01-25T08:32:35-05:00" level=debug msg="obtained new client token: AAAfZ4Q9FPXoUxIby+mOmE/HL38KLdP5IQFnHrZh+YKaTzb2DN/JXR1HJ5wLlvYmmMz0r4FSBMX+Zb/R30YK8VzlWRVdLCFqKLRNncNxOrmQG0DGGejGeM/94jGJXLig/9rOw851Bz/bdcqJZrQqYWDPebwI65c/fGw9kaOfWdKCaHzB82REFDO74eAn88M6eRGgexj6M8PZwogfej/Nefy+UFwMMWhvrPvCAa3/IqkFNs8Iebh/" Jan 25 08:32:35 music go-librespot[31616]: time="2026-01-25T08:32:35-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Jan 25 08:32:35 music go-librespot[31616]: time="2026-01-25T08:32:35-05:00" level=debug msg="completed keyexchange" Jan 25 08:32:35 music go-librespot[31616]: time="2026-01-25T08:32:35-05:00" level=debug msg="completed challenge" Jan 25 08:32:35 music go-librespot[31616]: time="2026-01-25T08:32:35-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 25 08:32:35 music volumio[31600]: info: MYVOLUMIO Environment detected Jan 25 08:32:35 music volumio[31600]: info: Plugin folders cleanup Jan 25 08:32:35 music volumio[31600]: info: Scanning into folder /volumio/app/plugins/ Jan 25 08:32:35 music volumio[31600]: info: Scanning category audio_interface Jan 25 08:32:35 music volumio[31600]: info: Scanning category miscellanea Jan 25 08:32:35 music volumio[31600]: info: Scanning category music_service Jan 25 08:32:35 music volumio[31600]: info: Scanning category plugins.json Jan 25 08:32:35 music volumio[31600]: info: Scanning category system_controller Jan 25 08:32:35 music volumio[31600]: info: Scanning category user_interface Jan 25 08:32:35 music volumio[31600]: info: Scanning into folder /data/plugins/ Jan 25 08:32:35 music volumio[31600]: info: Scanning category music_service Jan 25 08:32:35 music volumio[31600]: info: Plugin folders cleanup completed Jan 25 08:32:35 music volumio[31600]: info: ------------------------------------------- Jan 25 08:32:35 music volumio[31600]: info: ----- Core plugins startup ---- Jan 25 08:32:35 music volumio[31600]: info: ------------------------------------------- Jan 25 08:32:35 music volumio[31600]: info: Loading plugins from folder /volumio/app/plugins/ Jan 25 08:32:35 music volumio[31600]: info: Adding plugin upnp to MyMusic Plugins Jan 25 08:32:35 music volumio[31600]: info: Adding plugin airplay_emulation to MyMusic Plugins Jan 25 08:32:35 music volumio[31600]: info: Adding plugin upnp_browser to MyMusic Plugins Jan 25 08:32:35 music volumio[31600]: info: Loading plugins from folder /data/plugins/ Jan 25 08:32:35 music volumio[31600]: info: Loading plugin "system"... Jan 25 08:32:35 music volumio[31600]: info: Loading plugin "appearance"... Jan 25 08:32:35 music go-librespot[31616]: time="2026-01-25T08:32:35-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Jan 25 08:32:36 music go-librespot[31616]: time="2026-01-25T08:32:36-05:00" level=debug msg="completed keyexchange" Jan 25 08:32:36 music go-librespot[31616]: time="2026-01-25T08:32:36-05:00" level=debug msg="completed challenge" Jan 25 08:32:36 music go-librespot[31616]: time="2026-01-25T08:32:36-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 25 08:32:36 music go-librespot[31616]: time="2026-01-25T08:32:36-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Jan 25 08:32:36 music go-librespot[31616]: time="2026-01-25T08:32:36-05:00" level=debug msg="completed keyexchange" Jan 25 08:32:36 music go-librespot[31616]: time="2026-01-25T08:32:36-05:00" level=debug msg="completed challenge" Jan 25 08:32:36 music go-librespot[31616]: time="2026-01-25T08:32:36-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 25 08:32:36 music volumio[31600]: info: Loading plugin "network"... Jan 25 08:32:36 music volumio[31600]: info: Refreshing Cached IP Addresses Jan 25 08:32:36 music sudo[31638]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 25 08:32:36 music sudo[31638]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 08:32:36 music sudo[31638]: pam_unix(sudo:session): session closed for user root Jan 25 08:32:36 music sudo[31640]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 25 08:32:36 music sudo[31640]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 08:32:36 music volumio[31600]: info: Loading plugin "services"... Jan 25 08:32:36 music volumio[31600]: info: Loading plugin "alsa_controller"... Jan 25 08:32:37 music sudo[31640]: pam_unix(sudo:session): session closed for user root Jan 25 08:32:37 music sudo[31648]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Jan 25 08:32:37 music sudo[31648]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 08:32:37 music volumio[31600]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 25 08:32:37 music volumio[31600]: info: Loading plugin "wizard"... Jan 25 08:32:37 music volumio[31600]: info: Loading plugin "networkfs"... Jan 25 08:32:37 music volumio[31600]: info: Starting Udev Watcher for removable devices Jan 25 08:32:37 music volumio[31600]: info: Ignoring mount for partition: boot Jan 25 08:32:37 music volumio[31600]: info: Ignoring mount for partition: volumio Jan 25 08:32:37 music volumio[31600]: info: Ignoring mount for partition: volumio_data Jan 25 08:32:37 music volumio[31600]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 25 08:32:37 music volumio[31600]: info: Loading plugin "volumio_command_line_client"... Jan 25 08:32:37 music volumio[31600]: info: Loading plugin "upnp"... Jan 25 08:32:37 music volumio[31600]: info: [1769347957165] Starting Upmpd Daemon Jan 25 08:32:37 music volumio[31600]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 25 08:32:37 music volumio[31600]: info: Loading plugin "my_music"... Jan 25 08:32:37 music volumio[31600]: info: Loading plugin "mpd"... Jan 25 08:32:37 music go-librespot[31616]: time="2026-01-25T08:32:37-05:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 25 08:32:37 music volumio-remote-updater[1248]: [2026-01-25 08:32:37] [connect] Successful connection Jan 25 08:32:37 music volumio[31600]: info: Loading plugin "upnp_browser"... Jan 25 08:32:37 music sudo[31648]: pam_unix(sudo:session): session closed for user root Jan 25 08:32:37 music go-librespot[31616]: time="2026-01-25T08:32:37-05:00" level=debug msg="completed keyexchange" Jan 25 08:32:37 music go-librespot[31616]: time="2026-01-25T08:32:37-05:00" level=debug msg="completed challenge" Jan 25 08:32:37 music go-librespot[31616]: time="2026-01-25T08:32:37-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 25 08:32:38 music go-librespot[31616]: time="2026-01-25T08:32:38-05:00" level=debug msg="connected to ap-gew1.spotify.com:443" Jan 25 08:32:38 music go-librespot[31616]: time="2026-01-25T08:32:38-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: read tcp 192.168.3.63:37222->104.199.65.9:443: read: connection reset by peer" Jan 25 08:32:39 music volumio[31600]: info: Starting UPNP Browser Jan 25 08:32:39 music volumio[31600]: info: Loading plugin "alarm-clock"... Jan 25 08:32:39 music go-librespot[31616]: time="2026-01-25T08:32:39-05:00" level=debug msg="connected to ap-gew4.spotify.com:80" Jan 25 08:32:39 music volumio[31600]: info: Loading plugin "airplay_emulation"... Jan 25 08:32:39 music volumio[31600]: info: Starting Shairport Sync Jan 25 08:32:39 music volumio[31600]: info: Loading plugin "last_100"... Jan 25 08:32:39 music volumio[31600]: info: Loading plugin "webradio"... Jan 25 08:32:39 music go-librespot[31616]: time="2026-01-25T08:32:39-05:00" level=debug msg="completed keyexchange" Jan 25 08:32:39 music go-librespot[31616]: time="2026-01-25T08:32:39-05:00" level=debug msg="completed challenge" Jan 25 08:32:39 music volumio[31600]: info: Loading plugin "i2s_dacs"... Jan 25 08:32:39 music volumio[31600]: info: I2S DAC not set, start Auto-detection Jan 25 08:32:39 music volumio[31600]: info: Loading plugin "volumiodiscovery"... Jan 25 08:32:39 music go-librespot[31616]: time="2026-01-25T08:32:39-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 25 08:32:39 music go-librespot[31616]: time="2026-01-25T08:32:39-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 25 08:32:39 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 25 08:32:39 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 25 08:32:39 music volumio[31600]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jan 25 08:32:39 music volumio[31600]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 25 08:32:39 music volumio[31600]: *** WARNING *** For more information see Jan 25 08:32:39 music volumio[31600]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jan 25 08:32:39 music volumio[31600]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 25 08:32:39 music volumio[31600]: *** WARNING *** For more information see Jan 25 08:32:39 music node[31600]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jan 25 08:32:39 music node[31600]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 25 08:32:39 music node[31600]: *** WARNING *** For more information see Jan 25 08:32:39 music node[31600]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jan 25 08:32:39 music node[31600]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 25 08:32:39 music node[31600]: *** WARNING *** For more information see Jan 25 08:32:39 music volumio[31600]: info: Applying required configuration parameters for plugin volumiodiscovery Jan 25 08:32:39 music volumio[31600]: info: Discovery: Started advertising with name: music Jan 25 08:32:39 music volumio[31600]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 25 08:32:39 music volumio[31600]: info: Loading plugin "spop"... Jan 25 08:32:40 music volumio[31600]: info: Loading plugin "outputs"... Jan 25 08:32:40 music volumio[31600]: info: Loading plugin "albumart"... Jan 25 08:32:40 music volumio[31600]: info: Plugin example_plugin is not enabled Jan 25 08:32:40 music volumio[31600]: info: Loading plugin "inputs"... Jan 25 08:32:40 music volumio[31600]: info: Loading plugin "updater_comm"... Jan 25 08:32:40 music volumio[31600]: info: Plugin mpdemulation is not enabled Jan 25 08:32:40 music volumio[31600]: info: Loading plugin "rest_api"... Jan 25 08:32:40 music volumio[31600]: info: Loading plugin "websocket"... Jan 25 08:32:40 music volumio[31600]: info: Starting Socket.io Server version 1.7.4 Jan 25 08:32:40 music volumio[31600]: info: Loading i18n strings for locale en Jan 25 08:32:40 music volumio[31600]: Updating browse sources language Jan 25 08:32:40 music volumio[31600]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 25 08:32:40 music volumio[31600]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 25 08:32:40 music volumio[31600]: info: CoreCommandRouter::initPlayerControls Jan 25 08:32:40 music volumio[31600]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:32:40 music volumio[31600]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:32:40 music volumio[31600]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:32:40 music volumio[31600]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:32:40 music volumio[31600]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:32:40 music volumio[31600]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:32:40 music volumio[31600]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:32:40 music volumio[31600]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:32:40 music volumio[31600]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 25 08:32:40 music volumio[31600]: Express server listening on port 3000 Jan 25 08:32:40 music volumio[31600]: [Metrics] WebUI: 6s 609.83ms Jan 25 08:32:40 music volumio[31600]: info: CoreStateMachine::resetVolumioState Jan 25 08:32:40 music volumio[31600]: info: CoreStateMachine::getcurrentVolume Jan 25 08:32:40 music volumio[31600]: info: CoreCommandRouter::volumioRetrievevolume Jan 25 08:32:40 music volumio[31600]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 25 08:32:41 music volumio[31600]: info: Volumio Network Manager: Network status updated: 1 Jan 25 08:32:41 music volumio-remote-updater[1248]: [2026-01-25 08:32:41] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1769347957 101 Jan 25 08:32:41 music volumio[31600]: 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 25 08:32:41 music volumio[31600]: info: VolumeController:: Volume=86 Mute =false Jan 25 08:32:41 music volumio[31600]: info: CoreStateMachine::pushState Jan 25 08:32:41 music volumio[31600]: info: CorePlayQueue::getTrack 0 Jan 25 08:32:41 music volumio[31600]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 25 08:32:41 music volumio[31600]: info: CoreCommandRouter::volumioPushState Jan 25 08:32:41 music volumio[31673]: Forking 3 albumart workers Jan 25 08:32:41 music volumio[31600]: info: CoreStateMachine::updateTrackBlock Jan 25 08:32:41 music volumio[31600]: info: CorePlayQueue::getTrackBlock Jan 25 08:32:41 music volumio[31600]: info: CoreCommandRouter::volumioRetrievevolume Jan 25 08:32:41 music volumio[31600]: info: Reloading queue from file Jan 25 08:32:41 music volumio[31600]: info: CoreCommandRouter::volumioGetState Jan 25 08:32:41 music volumio[31600]: info: CorePlayQueue::getTrack 0 Jan 25 08:32:41 music volumio[31600]: info: CoreStateMachine::setRepeat null single undefined Jan 25 08:32:41 music volumio[31600]: info: CoreStateMachine::pushState Jan 25 08:32:41 music volumio[31600]: info: CorePlayQueue::getTrack 0 Jan 25 08:32:41 music volumio[31600]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 25 08:32:41 music volumio[31600]: info: CoreCommandRouter::volumioPushState Jan 25 08:32:41 music volumio[31600]: info: CoreStateMachine::setRandom null Jan 25 08:32:41 music volumio[31600]: info: CoreStateMachine::pushState Jan 25 08:32:41 music volumio[31600]: info: CorePlayQueue::getTrack 0 Jan 25 08:32:41 music volumio[31600]: info: CoreCommandRouter::volumioPushState Jan 25 08:32:41 music volumio[31600]: info: Setting Device type: Raspberry PI Jan 25 08:32:41 music volumio[31600]: info: Listing playlists Jan 25 08:32:41 music volumio[31600]: info: Listing playlists Jan 25 08:32:41 music volumio[31600]: info: VolumeController:: Volume=86 Mute =false Jan 25 08:32:41 music volumio[31600]: info: CoreStateMachine::pushState Jan 25 08:32:41 music volumio[31600]: info: CorePlayQueue::getTrack 0 Jan 25 08:32:41 music volumio[31600]: info: CoreCommandRouter::volumioPushState Jan 25 08:32:41 music volumio[31600]: info: Discovery: adding 4a29b7a7-c637-4926-a2bd-fb4e2f55145e Jan 25 08:32:41 music volumio[31600]: info: Discovery: Found device music Jan 25 08:32:41 music volumio[31600]: info: CoreCommandRouter::volumioGetState Jan 25 08:32:41 music volumio[31600]: info: CorePlayQueue::getTrack 0 Jan 25 08:32:41 music volumio[31600]: info: Discovery: this is already registered, 4a29b7a7-c637-4926-a2bd-fb4e2f55145e Jan 25 08:32:41 music volumio[31600]: info: Discovery: Found device music Jan 25 08:32:41 music volumio[31600]: info: CoreCommandRouter::volumioGetState Jan 25 08:32:41 music volumio[31600]: info: CorePlayQueue::getTrack 0 Jan 25 08:32:41 music volumio[31600]: info: Completed loading Core Plugins Jan 25 08:32:41 music volumio[31600]: info: Preparing to generate the ALSA configuration file Jan 25 08:32:41 music volumio[31600]: info: Asound.conf file unchanged, so no further update is needed Jan 25 08:32:41 music volumio[31600]: info: Output device has changed, restarting MPD Jan 25 08:32:41 music volumio[31600]: info: Output device has changed, restarting Shairport Sync Jan 25 08:32:41 music volumio[31600]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:32:41 music volumio[31600]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 25 08:32:41 music sudo[31729]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 25 08:32:41 music sudo[31729]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 08:32:41 music sudo[31729]: pam_unix(sudo:session): session closed for user root Jan 25 08:32:41 music sudo[31730]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 25 08:32:41 music sudo[31730]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 08:32:41 music volumio[31600]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 25 08:32:41 music volumio[31600]: info: ___________ START PLUGINS ___________ Jan 25 08:32:41 music volumio[31600]: info: ControllerMpd::onStart: Initializing MPD Jan 25 08:32:41 music volumio[31600]: info: Creating MPD Configuration file Jan 25 08:32:41 music systemd[1]: Stopping mpd.service - Music Player Daemon... Jan 25 08:32:41 music volumio[31600]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 25 08:32:41 music volumio[31600]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 25 08:32:41 music volumio[31600]: info: [1769347961696] CoreMusicLibrary::Adding element Media Servers Jan 25 08:32:41 music volumio[31600]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 25 08:32:41 music volumio[31600]: info: UPNP Browser: Client initialized successfully Jan 25 08:32:41 music sudo[31738]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 25 08:32:41 music sudo[31738]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 08:32:41 music sudo[31738]: pam_unix(sudo:session): session closed for user root Jan 25 08:32:41 music systemd[1]: mpd.service: Deactivated successfully. Jan 25 08:32:41 music sudo[31740]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 25 08:32:41 music systemd[1]: Stopped mpd.service - Music Player Daemon. Jan 25 08:32:41 music sudo[31740]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 08:32:41 music systemd[1]: mpd.service: Consumed 4.183s CPU time. Jan 25 08:32:41 music systemd[1]: mpd.socket: Deactivated successfully. Jan 25 08:32:41 music systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jan 25 08:32:41 music systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jan 25 08:32:41 music volumio[31600]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:32:41 music volumio[31600]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 25 08:32:41 music systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jan 25 08:32:41 music systemd[1]: Starting mpd.service - Music Player Daemon... Jan 25 08:32:41 music volumio[31600]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 25 08:32:41 music volumio[31600]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:32:41 music volumio[31600]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 25 08:32:41 music systemd[1]: mpd.service: Deactivated successfully. Jan 25 08:32:41 music systemd[1]: Stopped mpd.service - Music Player Daemon. Jan 25 08:32:41 music systemd[1]: mpd.socket: Deactivated successfully. Jan 25 08:32:41 music systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jan 25 08:32:41 music systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jan 25 08:32:41 music systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jan 25 08:32:41 music systemd[1]: Starting mpd.service - Music Player Daemon... Jan 25 08:32:41 music volumio[31600]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 25 08:32:41 music volumio[31600]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 25 08:32:41 music volumio[31600]: info: [1769347961949] CoreMusicLibrary::Adding element Last_100 Jan 25 08:32:41 music volumio[31600]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 25 08:32:41 music volumio[31600]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 25 08:32:41 music volumio[31600]: info: [1769347961956] CoreMusicLibrary::Adding element Webradio Jan 25 08:32:41 music volumio[31600]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 25 08:32:41 music volumio[31600]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 25 08:32:41 music volumio[31600]: info: Initializing BBC Radios Jan 25 08:32:42 music volumio[31600]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 25 08:32:42 music volumio[31600]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 25 08:32:42 music volumio[31600]: info: Creating Spotify config file Jan 25 08:32:42 music volumio[31600]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:32:42 music sudo[31754]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jan 25 08:32:42 music sudo[31754]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Jan 25 08:32:42 music sudo[31754]: pam_unix(sudo:session): session closed for user root Jan 25 08:32:42 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Jan 25 08:32:42 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 25 08:32:42 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 25 08:32:42 music go-librespot[31770]: go-librespot daemon starting... Jan 25 08:32:42 music go-librespot[31771]: time="2026-01-25T08:32:42-05:00" level=info msg="running go-librespot 0.6.2" Jan 25 08:32:42 music volumio[31600]: info: Volumio Calling Home Jan 25 08:32:43 music go-librespot[31771]: time="2026-01-25T08:32:43-05:00" level=info msg="zeroconf server listening on port 37245" Jan 25 08:32:43 music volumio[31691]: Starting albumart workers Jan 25 08:32:43 music volumio[31692]: Starting albumart workers Jan 25 08:32:43 music volumio[31600]: info: MPD Permissions set Jan 25 08:32:43 music volumio[31600]: info: MPD Permissions set Jan 25 08:32:43 music volumio[31690]: Starting albumart workers Jan 25 08:32:43 music volumio[31600]: info: Volumio called home Jan 25 08:32:43 music volumio[31600]: info: Spotify config file written Jan 25 08:32:43 music volumio[31600]: 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 25 08:32:43 music volumio[31600]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:32:43 music volumio[31600]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:32:43 music volumio[31600]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:32:43 music volumio[31600]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:32:43 music volumio[31600]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:32:43 music volumio[31600]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:32:43 music sudo[31786]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jan 25 08:32:43 music sudo[31786]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 08:32:43 music volumio[31600]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:32:43 music volumio[31600]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:32:43 music volumio[31600]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 25 08:32:43 music volumio[31600]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:32:43 music volumio[31600]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:32:43 music volumio[31600]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:32:43 music volumio[31600]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:32:43 music volumio[31600]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:32:43 music volumio[31600]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:32:43 music volumio[31600]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:32:43 music volumio[31600]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:32:43 music volumio[31600]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:32:43 music volumio[31600]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 25 08:32:43 music volumio[31600]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 08:32:43 music volumio[31600]: info: No need to fix Spotify hosts Jan 25 08:32:43 music systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Jan 25 08:32:43 music systemd[1]: go-librespot-daemon.service: Killing process 31781 (go-librespot) with signal SIGKILL. Jan 25 08:32:43 music systemd[1]: go-librespot-daemon.service: Deactivated successfully. Jan 25 08:32:43 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 25 08:32:43 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 25 08:32:43 music go-librespot[31798]: go-librespot daemon starting... Jan 25 08:32:43 music sudo[31786]: pam_unix(sudo:session): session closed for user root Jan 25 08:32:43 music go-librespot[31799]: time="2026-01-25T08:32:43-05:00" level=info msg="running go-librespot 0.6.2" Jan 25 08:32:43 music go-librespot[31799]: time="2026-01-25T08:32:43-05:00" level=debug msg="app state loaded" Jan 25 08:32:43 music go-librespot[31799]: time="2026-01-25T08:32:43-05:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 25 08:32:44 music go-librespot[31799]: time="2026-01-25T08:32:44-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 25 08:32:44 music go-librespot[31799]: time="2026-01-25T08:32:44-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 25 08:32:44 music go-librespot[31799]: time="2026-01-25T08:32:44-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 25 08:32:44 music go-librespot[31799]: time="2026-01-25T08:32:44-05:00" level=info msg="zeroconf server listening on port 43127" Jan 25 08:32:44 music volumio[31600]: info: Starting Shairport Sync Jan 25 08:32:44 music volumio[31600]: info: Starting Shairport Sync Jan 25 08:32:44 music volumio[31600]: info: Starting Shairport Sync Jan 25 08:32:44 music sudo[31818]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 25 08:32:44 music sudo[31818]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 08:32:44 music sudo[31820]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 25 08:32:44 music sudo[31820]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 08:32:44 music volumio[31600]: info: An error occurred while refreshing Spotify Token Error: Bad Request Jan 25 08:32:44 music systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jan 25 08:32:44 music systemd[1]: shairport-sync.service: Deactivated successfully. Jan 25 08:32:44 music sudo[31824]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 25 08:32:44 music sudo[31824]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 08:32:44 music systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 25 08:32:44 music go-librespot[31799]: time="2026-01-25T08:32:44-05:00" level=debug msg="obtained new client token: AAC92vKRCTlcQYAaXxIaOYl/oh/xk3tWMSMywnyGROHXWKRZ3YvT+KpKDJhFXwpO8Dt6BIpGE6KzuZeOEq5gh5sf/bOIgjU4EI1AQQoW+Q18w21YeY7wbLbIELBFPC/CWqY0jIgIgtBxe0vPtnYnYSxdWFou/D03nLBp9h5Hzw8SzMriN8nLOSfDFz0aE0fVW9OF5wc6HywMOlzgvh9YywJf0nRD29Wl0IR1bY9dMILmQatA5WuOSNM=" Jan 25 08:32:44 music systemd[1]: shairport-sync.service: Consumed 1.889s CPU time. Jan 25 08:32:44 music systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 25 08:32:44 music go-librespot[31799]: time="2026-01-25T08:32:44-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Jan 25 08:32:44 music sudo[31818]: pam_unix(sudo:session): session closed for user root Jan 25 08:32:44 music systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jan 25 08:32:44 music systemd[1]: shairport-sync.service: Deactivated successfully. Jan 25 08:32:44 music systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 25 08:32:44 music systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 25 08:32:44 music go-librespot[31799]: time="2026-01-25T08:32:44-05:00" level=debug msg="completed keyexchange" Jan 25 08:32:44 music go-librespot[31799]: time="2026-01-25T08:32:44-05:00" level=debug msg="completed challenge" Jan 25 08:32:44 music sudo[31820]: pam_unix(sudo:session): session closed for user root Jan 25 08:32:44 music sudo[31824]: pam_unix(sudo:session): session closed for user root Jan 25 08:32:44 music go-librespot[31799]: time="2026-01-25T08:32:44-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 25 08:32:44 music volumio[31600]: info: Shairport-Sync Started Jan 25 08:32:44 music volumio[31600]: Error adding Membership: Error: addMembership EINVAL Jan 25 08:32:44 music volumio[31600]: info: Shairport-Sync Started Jan 25 08:32:44 music volumio[31600]: info: Shairport-Sync Started Jan 25 08:32:44 music volumio[31600]: info: CoreCommandRouter::volumioGetState Jan 25 08:32:44 music volumio[31600]: info: CorePlayQueue::getTrack 0 Jan 25 08:32:45 music go-librespot[31799]: time="2026-01-25T08:32:45-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Jan 25 08:32:45 music go-librespot[31799]: time="2026-01-25T08:32:45-05:00" level=debug msg="completed keyexchange" Jan 25 08:32:45 music go-librespot[31799]: time="2026-01-25T08:32:45-05:00" level=debug msg="completed challenge" Jan 25 08:32:45 music go-librespot[31799]: time="2026-01-25T08:32:45-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 25 08:32:46 music go-librespot[31799]: time="2026-01-25T08:32:46-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Jan 25 08:32:46 music go-librespot[31799]: time="2026-01-25T08:32:46-05:00" level=debug msg="completed keyexchange" Jan 25 08:32:46 music go-librespot[31799]: time="2026-01-25T08:32:46-05:00" level=debug msg="completed challenge" Jan 25 08:32:46 music go-librespot[31799]: time="2026-01-25T08:32:46-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 25 08:32:46 music mpd[31769]: 2026-01-25T08:32:46 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jan 25 08:32:46 music systemd[1]: Started mpd.service - Music Player Daemon. Jan 25 08:32:46 music sudo[31730]: pam_unix(sudo:session): session closed for user root Jan 25 08:32:46 music sudo[31740]: pam_unix(sudo:session): session closed for user root Jan 25 08:32:46 music volumio[31600]: info: Completed starting Core Plugins Jan 25 08:32:46 music volumio[31600]: info: ------------------------------------------- Jan 25 08:32:46 music volumio[31600]: info: ----- MyVolumio plugins startup ---- Jan 25 08:32:46 music volumio[31600]: info: ------------------------------------------- Jan 25 08:32:46 music volumio[31600]: info: [MyVolumio PluginManager] Fetching plans data.... Jan 25 08:32:46 music volumio[31600]: error: MPD error: The expression evaluated to a falsy value: Jan 25 08:32:46 music volumio[31600]: assert.ok(self.idling) Jan 25 08:32:46 music volumio[31600]: error: The expression evaluated to a falsy value: Jan 25 08:32:46 music volumio[31600]: assert.ok(self.idling) Jan 25 08:32:46 music volumio[31600]: info: MPD running with PID31769 Jan 25 08:32:46 music volumio[31600]: ,establishing connection Jan 25 08:32:46 music volumio[31600]: error: updateQueue error: null Jan 25 08:32:46 music volumio[31600]: error: updateQueue error: null Jan 25 08:32:46 music go-librespot[31799]: time="2026-01-25T08:32:46-05:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 25 08:32:46 music go-librespot[31799]: time="2026-01-25T08:32:46-05:00" level=debug msg="completed keyexchange" Jan 25 08:32:46 music go-librespot[31799]: time="2026-01-25T08:32:46-05:00" level=debug msg="completed challenge" Jan 25 08:32:46 music go-librespot[31799]: time="2026-01-25T08:32:46-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 25 08:32:47 music sudo[31874]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 25 08:32:47 music sudo[31874]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 08:32:47 music sudo[31874]: pam_unix(sudo:session): session closed for user root Jan 25 08:32:47 music sudo[31876]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 25 08:32:47 music sudo[31876]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 08:32:47 music sudo[31876]: pam_unix(sudo:session): session closed for user root Jan 25 08:32:47 music sudo[31879]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Jan 25 08:32:47 music sudo[31879]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 08:32:47 music sudo[31879]: pam_unix(sudo:session): session closed for user root Jan 25 08:32:47 music volumio[31600]: info: Upmpdcli Daemon Started Jan 25 08:32:47 music volumio[31600]: info: go-librespot daemon successfully initialized Jan 25 08:32:47 music go-librespot[31799]: time="2026-01-25T08:32:47-05:00" level=debug msg="connected to ap-gae2.spotify.com:443" Jan 25 08:32:47 music go-librespot[31799]: time="2026-01-25T08:32:47-05:00" level=debug msg="completed keyexchange" Jan 25 08:32:47 music go-librespot[31799]: time="2026-01-25T08:32:47-05:00" level=debug msg="completed challenge" Jan 25 08:32:48 music go-librespot[31799]: time="2026-01-25T08:32:48-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 25 08:32:48 music volumio[31600]: info: CoreCommandRouter::volumioGetState Jan 25 08:32:48 music volumio[31600]: info: CorePlayQueue::getTrack 0 Jan 25 08:32:48 music go-librespot[31799]: time="2026-01-25T08:32:48-05:00" level=debug msg="connected to ap-gew1.spotify.com:80" Jan 25 08:32:48 music go-librespot[31799]: time="2026-01-25T08:32:48-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: read tcp 192.168.3.63:54388->104.199.65.9:80: read: connection reset by peer" Jan 25 08:32:48 music go-librespot[31799]: time="2026-01-25T08:32:48-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: read tcp 192.168.3.63:54388->104.199.65.9:80: read: connection reset by peer" Jan 25 08:32:48 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 25 08:32:48 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 25 08:32:49 music sudo[31883]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Jan 25 08:32:49 music sudo[31883]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 08:32:49 music sudo[31885]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Jan 25 08:32:49 music sudo[31885]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 08:32:49 music systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Jan 25 08:32:49 music systemd[1]: mpd_monitor.service: Deactivated successfully. Jan 25 08:32:49 music systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Jan 25 08:32:49 music systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Jan 25 08:32:49 music sudo[31883]: pam_unix(sudo:session): session closed for user root Jan 25 08:32:49 music sudo[31885]: pam_unix(sudo:session): session closed for user root Jan 25 08:32:49 music mpd_monitor.sh[31888]: MPD Monitor Service: Starting MPD Monitor Service Jan 25 08:32:49 music volumio[31600]: info: Successfully started MPD Monitor Jan 25 08:32:49 music volumio[31600]: info: Successfully started MPD Monitor Jan 25 08:32:50 music volumio[31600]: info: Initializing connection to go-librespot Websocket Jan 25 08:32:50 music volumio[31600]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 25 08:32:51 music volumio[31600]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Jan 25 08:32:52 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Jan 25 08:32:52 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 25 08:32:52 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 25 08:32:52 music go-librespot[31892]: go-librespot daemon starting... Jan 25 08:32:52 music go-librespot[31893]: time="2026-01-25T08:32:52-05:00" level=info msg="running go-librespot 0.6.2" Jan 25 08:32:52 music go-librespot[31893]: time="2026-01-25T08:32:52-05:00" level=debug msg="app state loaded" Jan 25 08:32:52 music go-librespot[31893]: time="2026-01-25T08:32:52-05:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 25 08:32:52 music go-librespot[31893]: time="2026-01-25T08:32:52-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 25 08:32:52 music go-librespot[31893]: time="2026-01-25T08:32:52-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 25 08:32:52 music go-librespot[31893]: time="2026-01-25T08:32:52-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 25 08:32:52 music go-librespot[31893]: time="2026-01-25T08:32:52-05:00" level=info msg="zeroconf server listening on port 45425" Jan 25 08:32:52 music go-librespot[31893]: time="2026-01-25T08:32:52-05:00" level=debug msg="obtained new client token: AADJ/b/Yq49C9A88WE4B59+7uhArc8eQMKM+uemSSrV93hMjd0nvPm6S8MqQrtlt7fI3zzTDpXEue3tVhMeRN0atGo6lGvly+1U8WVpO317CNHXXuRZHYo6rjU+gIq9p9lJpcxLsh76YwCS9L5V4lSF5rzQ7BioU13zGQuE4Gfepz9sH6ie/a/cIdd5YnKsLupqxHcfWOg3rz6cukl4lvUGK69LfDoAnobDGhzzBL8zVFMigwFrNB48=" Jan 25 08:32:52 music go-librespot[31893]: time="2026-01-25T08:32:52-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Jan 25 08:32:52 music go-librespot[31893]: time="2026-01-25T08:32:52-05:00" level=debug msg="completed keyexchange" Jan 25 08:32:52 music go-librespot[31893]: time="2026-01-25T08:32:52-05:00" level=debug msg="completed challenge" Jan 25 08:32:52 music go-librespot[31893]: time="2026-01-25T08:32:52-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 25 08:32:53 music volumio[31600]: info: Initializing connection to go-librespot Websocket Jan 25 08:32:53 music go-librespot[31893]: time="2026-01-25T08:32:53-05:00" level=debug msg="new websocket client" Jan 25 08:32:53 music volumio[31600]: info: Connection to go-librespot Websocket established Jan 25 08:32:53 music go-librespot[31893]: time="2026-01-25T08:32:53-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Jan 25 08:32:53 music go-librespot[31893]: time="2026-01-25T08:32:53-05:00" level=debug msg="completed keyexchange" Jan 25 08:32:53 music go-librespot[31893]: time="2026-01-25T08:32:53-05:00" level=debug msg="completed challenge" Jan 25 08:32:53 music go-librespot[31893]: time="2026-01-25T08:32:53-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 25 08:32:54 music go-librespot[31893]: time="2026-01-25T08:32:54-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Jan 25 08:32:54 music go-librespot[31893]: time="2026-01-25T08:32:54-05:00" level=debug msg="completed keyexchange" Jan 25 08:32:54 music go-librespot[31893]: time="2026-01-25T08:32:54-05:00" level=debug msg="completed challenge" Jan 25 08:32:54 music go-librespot[31893]: time="2026-01-25T08:32:54-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 25 08:32:54 music volumio[31600]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Jan 25 08:32:54 music volumio[31600]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Jan 25 08:32:54 music volumio[31600]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Jan 25 08:32:54 music volumio[31600]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Jan 25 08:32:54 music volumio[31600]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Jan 25 08:32:54 music volumio[31600]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Jan 25 08:32:54 music volumio[31600]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Jan 25 08:32:54 music volumio[31600]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Jan 25 08:32:54 music volumio[31600]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Jan 25 08:32:54 music volumio[31600]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Jan 25 08:32:54 music volumio[31600]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Jan 25 08:32:54 music volumio[31600]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Jan 25 08:32:54 music volumio[31600]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Jan 25 08:32:54 music volumio[31600]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Jan 25 08:32:54 music volumio[31600]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Jan 25 08:32:54 music volumio[31600]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Jan 25 08:32:54 music volumio[31600]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Jan 25 08:32:54 music volumio[31600]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Jan 25 08:32:54 music volumio[31600]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Jan 25 08:32:54 music volumio[31600]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Jan 25 08:32:54 music volumio[31600]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Jan 25 08:32:54 music volumio[31600]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Jan 25 08:32:54 music volumio[31600]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Jan 25 08:32:54 music volumio[31600]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Jan 25 08:32:54 music volumio[31600]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Jan 25 08:32:54 music volumio[31600]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Jan 25 08:32:54 music volumio[31600]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Jan 25 08:32:54 music volumio[31600]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Jan 25 08:32:54 music volumio[31600]: info: Adding plugin bluetooth to MyMusic Plugins Jan 25 08:32:54 music volumio[31600]: info: Adding plugin multiroom to MyMusic Plugins Jan 25 08:32:54 music volumio[31600]: info: Adding plugin metavolumio to MyMusic Plugins Jan 25 08:32:54 music volumio[31600]: info: Adding plugin cd_controller to MyMusic Plugins Jan 25 08:32:54 music volumio[31600]: info: Adding plugin qobuzconnect to MyMusic Plugins Jan 25 08:32:54 music volumio[31600]: info: Adding plugin smart_inputs to MyMusic Plugins Jan 25 08:32:54 music volumio[31600]: info: Adding plugin tidalconnect to MyMusic Plugins Jan 25 08:32:54 music volumio[31600]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Jan 25 08:32:54 music go-librespot[31893]: time="2026-01-25T08:32:54-05:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 25 08:32:54 music go-librespot[31893]: time="2026-01-25T08:32:54-05:00" level=debug msg="completed keyexchange" Jan 25 08:32:54 music go-librespot[31893]: time="2026-01-25T08:32:54-05:00" level=debug msg="completed challenge" Jan 25 08:32:54 music go-librespot[31893]: time="2026-01-25T08:32:54-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 25 08:32:55 music go-librespot[31893]: time="2026-01-25T08:32:55-05:00" level=debug msg="connected to ap-gew1.spotify.com:443" Jan 25 08:32:55 music go-librespot[31893]: time="2026-01-25T08:32:55-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: EOF" Jan 25 08:32:55 music volumio[31600]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Jan 25 08:32:55 music volumio[31600]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Jan 25 08:32:55 music volumio[31600]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 25 08:32:55 music volumio[31600]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 25 08:32:55 music volumio[31600]: info: Starting MyVolumio Remote Streaming Endpoints Jan 25 08:32:55 music volumio[31600]: info: MyVolumio login type: Token Jan 25 08:32:55 music volumio[31600]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Jan 25 08:32:55 music volumio[31600]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Jan 25 08:32:56 music go-librespot[31893]: time="2026-01-25T08:32:56-05:00" level=debug msg="connected to ap-gew4.spotify.com:80" Jan 25 08:32:56 music go-librespot[31893]: time="2026-01-25T08:32:56-05:00" level=debug msg="completed keyexchange" Jan 25 08:32:56 music go-librespot[31893]: time="2026-01-25T08:32:56-05:00" level=debug msg="completed challenge" Jan 25 08:32:56 music go-librespot[31893]: time="2026-01-25T08:32:56-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 25 08:32:56 music go-librespot[31893]: time="2026-01-25T08:32: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 25 08:32:56 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 25 08:32:56 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 25 08:32:56 music volumio[31600]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Jan 25 08:32:56 music volumio[31600]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Jan 25 08:32:56 music volumio[31600]: info: Streaming services startup Jan 25 08:32:56 music volumio[31600]: info: Starting Streaming Daemon Jan 25 08:32:56 music sudo[31904]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Jan 25 08:32:56 music sudo[31904]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 08:32:56 music volumio[31600]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Jan 25 08:32:56 music sudo[31904]: pam_unix(sudo:session): session closed for user root Jan 25 08:32:56 music volumio[31600]: info: Getting Spotify volume Jan 25 08:32:56 music volumio[31600]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 25 08:32:56 music volumio[31600]: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 25 08:32:56 music volumio[31600]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Jan 25 08:32:56 music volumio[31600]: errno: -111, Jan 25 08:32:56 music volumio[31600]: code: 'ECONNREFUSED', Jan 25 08:32:56 music volumio[31600]: syscall: 'connect', Jan 25 08:32:56 music volumio[31600]: address: '127.0.0.1', Jan 25 08:32:56 music volumio[31600]: port: 9879, Jan 25 08:32:56 music volumio[31600]: response: undefined Jan 25 08:32:56 music volumio[31600]: } Jan 25 08:32:56 music volumio[31600]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 25 08:32:57 music sudo[31939]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-01-25 08:31' Jan 25 08:32:57 music sudo[31939]: 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"