Dec 30 04:17:00 music go-librespot[13196]: time="2025-12-30T04:17:00-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Dec 30 04:17:00 music go-librespot[13196]: time="2025-12-30T04:17:00-05:00" level=debug msg="completed keyexchange" Dec 30 04:17:00 music go-librespot[13196]: time="2025-12-30T04:17:00-05:00" level=debug msg="completed challenge" Dec 30 04:17:00 music go-librespot[13196]: time="2025-12-30T04:17:00-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 30 04:17:00 music go-librespot[13196]: time="2025-12-30T04:17:00-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Dec 30 04:17:00 music go-librespot[13196]: time="2025-12-30T04:17:00-05:00" level=debug msg="completed keyexchange" Dec 30 04:17:00 music go-librespot[13196]: time="2025-12-30T04:17:00-05:00" level=debug msg="completed challenge" Dec 30 04:17:01 music go-librespot[13196]: time="2025-12-30T04:17:01-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 30 04:17:01 music mpd[13182]: 2025-12-30T04:17:01 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Dec 30 04:17:01 music systemd[1]: Started mpd.service - Music Player Daemon. Dec 30 04:17:01 music mpd_monitor.sh[12933]: MPD Monitor Service: MPD restarted due to no mpc output. Dec 30 04:17:01 music sudo[13139]: pam_unix(sudo:session): session closed for user root Dec 30 04:17:01 music sudo[13150]: pam_unix(sudo:session): session closed for user root Dec 30 04:17:01 music volumio[13009]: info: Completed starting Core Plugins Dec 30 04:17:01 music volumio[13009]: info: ------------------------------------------- Dec 30 04:17:01 music volumio[13009]: info: ----- MyVolumio plugins startup ---- Dec 30 04:17:01 music volumio[13009]: info: ------------------------------------------- Dec 30 04:17:01 music volumio[13009]: info: [MyVolumio PluginManager] Fetching plans data.... Dec 30 04:17:01 music volumio[13009]: error: MPD error: The expression evaluated to a falsy value: Dec 30 04:17:01 music volumio[13009]: assert.ok(self.idling) Dec 30 04:17:01 music volumio[13009]: error: The expression evaluated to a falsy value: Dec 30 04:17:01 music volumio[13009]: assert.ok(self.idling) Dec 30 04:17:01 music volumio[13009]: error: updateQueue error: null Dec 30 04:17:01 music volumio[13009]: info: MPD running with PID13182 Dec 30 04:17:01 music volumio[13009]: ,establishing connection Dec 30 04:17:01 music volumio[13009]: error: updateQueue error: null Dec 30 04:17:01 music go-librespot[13196]: time="2025-12-30T04:17:01-05:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 04:17:01 music go-librespot[13196]: time="2025-12-30T04:17:01-05:00" level=debug msg="completed keyexchange" Dec 30 04:17:01 music go-librespot[13196]: time="2025-12-30T04:17:01-05:00" level=debug msg="completed challenge" Dec 30 04:17:01 music go-librespot[13196]: time="2025-12-30T04:17:01-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 30 04:17:01 music sudo[13274]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 30 04:17:01 music sudo[13274]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 04:17:01 music sudo[13276]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 30 04:17:01 music sudo[13276]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 04:17:01 music sudo[13274]: pam_unix(sudo:session): session closed for user root Dec 30 04:17:01 music sudo[13276]: pam_unix(sudo:session): session closed for user root Dec 30 04:17:01 music sudo[13278]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Dec 30 04:17:01 music sudo[13278]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 04:17:01 music sudo[13278]: pam_unix(sudo:session): session closed for user root Dec 30 04:17:01 music volumio[13009]: info: Upmpdcli Daemon Started Dec 30 04:17:02 music volumio[13009]: info: go-librespot daemon successfully initialized Dec 30 04:17:02 music go-librespot[13196]: time="2025-12-30T04:17:02-05:00" level=debug msg="connected to ap-gae2.spotify.com:443" Dec 30 04:17:02 music go-librespot[13196]: time="2025-12-30T04:17:02-05:00" level=debug msg="completed keyexchange" Dec 30 04:17:02 music go-librespot[13196]: time="2025-12-30T04:17:02-05:00" level=debug msg="completed challenge" Dec 30 04:17:02 music go-librespot[13196]: time="2025-12-30T04:17:02-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 30 04:17:03 music go-librespot[13196]: time="2025-12-30T04:17:03-05:00" level=debug msg="connected to ap-gew4.spotify.com:80" Dec 30 04:17:03 music go-librespot[13196]: time="2025-12-30T04:17:03-05:00" level=debug msg="completed keyexchange" Dec 30 04:17:03 music go-librespot[13196]: time="2025-12-30T04:17:03-05:00" level=debug msg="completed challenge" Dec 30 04:17:03 music go-librespot[13196]: time="2025-12-30T04:17:03-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 30 04:17:03 music go-librespot[13196]: time="2025-12-30T04:17:03-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Dec 30 04:17:03 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 04:17:03 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 04:17:04 music sudo[13283]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 30 04:17:04 music sudo[13283]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 04:17:04 music sudo[13285]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 30 04:17:04 music sudo[13285]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 04:17:04 music systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Dec 30 04:17:04 music systemd[1]: mpd_monitor.service: Deactivated successfully. Dec 30 04:17:04 music systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Dec 30 04:17:04 music systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Dec 30 04:17:04 music sudo[13283]: pam_unix(sudo:session): session closed for user root Dec 30 04:17:04 music mpd_monitor.sh[13288]: MPD Monitor Service: Starting MPD Monitor Service Dec 30 04:17:04 music sudo[13285]: pam_unix(sudo:session): session closed for user root Dec 30 04:17:04 music volumio[13009]: info: Successfully started MPD Monitor Dec 30 04:17:04 music volumio[13009]: info: Successfully started MPD Monitor Dec 30 04:17:05 music volumio[13009]: info: Initializing connection to go-librespot Websocket Dec 30 04:17:05 music volumio[13009]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 30 04:17:06 music volumio[13009]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Dec 30 04:17:06 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Dec 30 04:17:06 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 04:17:06 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 04:17:06 music go-librespot[13293]: go-librespot daemon starting... Dec 30 04:17:06 music go-librespot[13294]: time="2025-12-30T04:17:06-05:00" level=info msg="running go-librespot 0.6.2" Dec 30 04:17:06 music go-librespot[13294]: time="2025-12-30T04:17:06-05:00" level=debug msg="app state loaded" Dec 30 04:17:06 music go-librespot[13294]: time="2025-12-30T04:17:06-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 04:17:07 music go-librespot[13294]: time="2025-12-30T04:17: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-gae2.spotify.com:443 ap-gew1.spotify.com:80]" Dec 30 04:17:07 music go-librespot[13294]: time="2025-12-30T04:17:07-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]" Dec 30 04:17:07 music go-librespot[13294]: time="2025-12-30T04:17:07-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]" Dec 30 04:17:07 music go-librespot[13294]: time="2025-12-30T04:17:07-05:00" level=info msg="zeroconf server listening on port 39297" Dec 30 04:17:07 music go-librespot[13294]: time="2025-12-30T04:17:07-05:00" level=debug msg="obtained new client token: AADJ2XhnT/bEWL23inS1lSvUAMZ2+6HF2ZUhqbNE05atBlUX94875WV5feY/2nxzQG2VDFxAKw9UN3YMP3BtSc+yHLRINS6Jv55KfTG7zq/TWMpYpcVudw5/ijs7rxM5Ye35r8jDdBEf37X2qJ8vsjXH2JIPLMCMRg+CjeXXyIF97zfnW4emN/nkIxbMBB6S4hb56jJnj7PXoURk1GQjeODUmfNobhm3Y+snABgsI+p9bnx07HrhTRkU" Dec 30 04:17:07 music go-librespot[13294]: time="2025-12-30T04:17:07-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 30 04:17:07 music go-librespot[13294]: time="2025-12-30T04:17:07-05:00" level=debug msg="completed keyexchange" Dec 30 04:17:07 music go-librespot[13294]: time="2025-12-30T04:17:07-05:00" level=debug msg="completed challenge" Dec 30 04:17:07 music go-librespot[13294]: time="2025-12-30T04:17:07-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 30 04:17:08 music go-librespot[13294]: time="2025-12-30T04:17:08-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Dec 30 04:17:08 music go-librespot[13294]: time="2025-12-30T04:17:08-05:00" level=debug msg="completed keyexchange" Dec 30 04:17:08 music go-librespot[13294]: time="2025-12-30T04:17:08-05:00" level=debug msg="completed challenge" Dec 30 04:17:08 music go-librespot[13294]: time="2025-12-30T04:17:08-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 30 04:17:08 music volumio[13009]: info: Initializing connection to go-librespot Websocket Dec 30 04:17:08 music go-librespot[13294]: time="2025-12-30T04:17:08-05:00" level=debug msg="new websocket client" Dec 30 04:17:08 music volumio[13009]: info: Connection to go-librespot Websocket established Dec 30 04:17:08 music go-librespot[13294]: time="2025-12-30T04:17:08-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Dec 30 04:17:08 music go-librespot[13294]: time="2025-12-30T04:17:08-05:00" level=debug msg="completed keyexchange" Dec 30 04:17:08 music go-librespot[13294]: time="2025-12-30T04:17:08-05:00" level=debug msg="completed challenge" Dec 30 04:17:08 music go-librespot[13294]: time="2025-12-30T04:17:08-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 30 04:17:09 music go-librespot[13294]: time="2025-12-30T04:17:09-05:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 04:17:09 music volumio[13009]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Dec 30 04:17:09 music volumio[13009]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Dec 30 04:17:09 music volumio[13009]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Dec 30 04:17:09 music volumio[13009]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Dec 30 04:17:09 music volumio[13009]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Dec 30 04:17:09 music volumio[13009]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Dec 30 04:17:09 music volumio[13009]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Dec 30 04:17:09 music volumio[13009]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Dec 30 04:17:09 music volumio[13009]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Dec 30 04:17:09 music volumio[13009]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Dec 30 04:17:09 music volumio[13009]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Dec 30 04:17:09 music volumio[13009]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Dec 30 04:17:09 music volumio[13009]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Dec 30 04:17:09 music volumio[13009]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Dec 30 04:17:09 music go-librespot[13294]: time="2025-12-30T04:17:09-05:00" level=debug msg="completed keyexchange" Dec 30 04:17:09 music volumio[13009]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Dec 30 04:17:09 music go-librespot[13294]: time="2025-12-30T04:17:09-05:00" level=debug msg="completed challenge" Dec 30 04:17:09 music volumio[13009]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Dec 30 04:17:09 music volumio[13009]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Dec 30 04:17:09 music volumio[13009]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Dec 30 04:17:09 music volumio[13009]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Dec 30 04:17:09 music volumio[13009]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Dec 30 04:17:09 music volumio[13009]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Dec 30 04:17:09 music volumio[13009]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Dec 30 04:17:09 music volumio[13009]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Dec 30 04:17:09 music volumio[13009]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Dec 30 04:17:09 music volumio[13009]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Dec 30 04:17:09 music volumio[13009]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Dec 30 04:17:09 music volumio[13009]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Dec 30 04:17:09 music volumio[13009]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Dec 30 04:17:09 music volumio[13009]: info: Adding plugin bluetooth to MyMusic Plugins Dec 30 04:17:09 music volumio[13009]: info: Adding plugin multiroom to MyMusic Plugins Dec 30 04:17:09 music volumio[13009]: info: Adding plugin metavolumio to MyMusic Plugins Dec 30 04:17:09 music volumio[13009]: info: Adding plugin cd_controller to MyMusic Plugins Dec 30 04:17:09 music volumio[13009]: info: Adding plugin qobuzconnect to MyMusic Plugins Dec 30 04:17:09 music volumio[13009]: info: Adding plugin smart_inputs to MyMusic Plugins Dec 30 04:17:09 music volumio[13009]: info: Adding plugin tidalconnect to MyMusic Plugins Dec 30 04:17:09 music volumio[13009]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Dec 30 04:17:09 music go-librespot[13294]: time="2025-12-30T04:17:09-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 30 04:17:10 music go-librespot[13294]: time="2025-12-30T04:17:10-05:00" level=debug msg="connected to ap-gae2.spotify.com:443" Dec 30 04:17:10 music go-librespot[13294]: time="2025-12-30T04:17:10-05:00" level=debug msg="completed keyexchange" Dec 30 04:17:10 music go-librespot[13294]: time="2025-12-30T04:17:10-05:00" level=debug msg="completed challenge" Dec 30 04:17:10 music volumio[13009]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Dec 30 04:17:10 music volumio[13009]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Dec 30 04:17:10 music volumio[13009]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 04:17:10 music volumio[13009]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 04:17:10 music volumio[13009]: info: Starting MyVolumio Remote Streaming Endpoints Dec 30 04:17:10 music volumio[13009]: info: MyVolumio login type: Token Dec 30 04:17:10 music volumio[13009]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Dec 30 04:17:10 music volumio[13009]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Dec 30 04:17:10 music go-librespot[13294]: time="2025-12-30T04:17:10-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 30 04:17:11 music go-librespot[13294]: time="2025-12-30T04:17:11-05:00" level=debug msg="connected to ap-gew1.spotify.com:80" Dec 30 04:17:11 music go-librespot[13294]: time="2025-12-30T04:17:11-05:00" level=debug msg="completed keyexchange" Dec 30 04:17:11 music go-librespot[13294]: time="2025-12-30T04:17:11-05:00" level=debug msg="completed challenge" Dec 30 04:17:11 music go-librespot[13294]: time="2025-12-30T04:17:11-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 30 04:17:11 music go-librespot[13294]: time="2025-12-30T04:17: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 " Dec 30 04:17:11 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 04:17:11 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 04:17:11 music volumio[13009]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Dec 30 04:17:11 music volumio[13009]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Dec 30 04:17:11 music volumio[13009]: info: Streaming services startup Dec 30 04:17:11 music volumio[13009]: info: Starting Streaming Daemon Dec 30 04:17:11 music sudo[13304]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Dec 30 04:17:11 music sudo[13304]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 04:17:11 music volumio[13009]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Dec 30 04:17:11 music sudo[13304]: pam_unix(sudo:session): session closed for user root Dec 30 04:17:11 music volumio[13009]: info: Getting Spotify volume Dec 30 04:17:11 music volumio[13009]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 30 04:17:11 music volumio[13009]: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 30 04:17:11 music volumio[13009]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Dec 30 04:17:11 music volumio[13009]: errno: -111, Dec 30 04:17:11 music volumio[13009]: code: 'ECONNREFUSED', Dec 30 04:17:11 music volumio[13009]: syscall: 'connect', Dec 30 04:17:11 music volumio[13009]: address: '127.0.0.1', Dec 30 04:17:11 music volumio[13009]: port: 9879, Dec 30 04:17:11 music volumio[13009]: response: undefined Dec 30 04:17:11 music volumio[13009]: } Dec 30 04:17:11 music volumio[13009]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 30 04:17:12 music sudo[13338]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-30 04:16' Dec 30 04:17:12 music sudo[13338]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 04:17:12 music sudo[13338]: pam_unix(sudo:session): session closed for user root Dec 30 04:17:13 music volumio-remote-updater[735]: [2025-12-30 09:17:13] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Dec 30 04:17:13 music volumio-remote-updater[735]: [2025-12-30 09:17:13] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Dec 30 04:17:13 music systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Dec 30 04:17:13 music systemd[1]: volumio.service: Failed with result 'exit-code'. Dec 30 04:17:13 music systemd[1]: volumio.service: Consumed 26.426s CPU time. Dec 30 04:17:13 music systemd[1]: Started dynamicswap.service - dynamicswap service. Dec 30 04:17:13 music systemd[1]: dynamicswap.service: Deactivated successfully. Dec 30 04:17:13 music systemd[1]: volumio.service: Scheduled restart job, restart counter is at 8373. Dec 30 04:17:13 music systemd[1]: Started dynamicswap.service - dynamicswap service. Dec 30 04:17:13 music systemd[1]: Stopped volumio.service - Volumio Backend Module. Dec 30 04:17:13 music systemd[1]: volumio.service: Consumed 26.426s CPU time. Dec 30 04:17:13 music systemd[1]: Started volumio.service - Volumio Backend Module. Dec 30 04:17:13 music systemd[1]: dynamicswap.service: Deactivated successfully. Dec 30 04:17:14 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Dec 30 04:17:14 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 04:17:14 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 04:17:14 music go-librespot[13368]: go-librespot daemon starting... Dec 30 04:17:14 music go-librespot[13369]: time="2025-12-30T04:17:14-05:00" level=info msg="running go-librespot 0.6.2" Dec 30 04:17:14 music go-librespot[13369]: time="2025-12-30T04:17:14-05:00" level=debug msg="app state loaded" Dec 30 04:17:14 music go-librespot[13369]: time="2025-12-30T04:17:14-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 04:17:15 music go-librespot[13369]: time="2025-12-30T04:17:15-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew4.spotify.com:80]" Dec 30 04:17:15 music go-librespot[13369]: time="2025-12-30T04:17:15-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]" Dec 30 04:17:15 music go-librespot[13369]: time="2025-12-30T04:17:15-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]" Dec 30 04:17:15 music go-librespot[13369]: time="2025-12-30T04:17:15-05:00" level=info msg="zeroconf server listening on port 46415" Dec 30 04:17:15 music go-librespot[13369]: time="2025-12-30T04:17:15-05:00" level=debug msg="obtained new client token: AACYoRbu6nw0YhTd7VOexbFSs2GmCjPbfhDKWDubA0cGvDHGFAi6eKCQMXysDGZbJ2Cln+TmkUnlJSkbZ8CaITtA+5vAtnmEodqSQc5QolavawGQ6d6ggYAKaPJYRneBPiyveJlOg3dzz5F7mZrpsEBJFwssuhTSWoYQ37n71Hk7H9nRYMLnZtWgjniXaQnPXd5s69+2JV7YcEzGvnVtnw4A1K4UtOVV3DQyZJp11PPRO0UbKMkqOQ==" Dec 30 04:17:15 music go-librespot[13369]: time="2025-12-30T04:17:15-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 30 04:17:15 music go-librespot[13369]: time="2025-12-30T04:17:15-05:00" level=debug msg="completed keyexchange" Dec 30 04:17:15 music go-librespot[13369]: time="2025-12-30T04:17:15-05:00" level=debug msg="completed challenge" Dec 30 04:17:15 music go-librespot[13369]: time="2025-12-30T04:17:15-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 30 04:17:15 music volumio[13353]: info: ------------------------------------------- Dec 30 04:17:15 music volumio[13353]: info: ----- Volumio3 ---- Dec 30 04:17:15 music volumio[13353]: info: ------------------------------------------- Dec 30 04:17:15 music volumio[13353]: info: ----- System startup ---- Dec 30 04:17:15 music volumio[13353]: info: ------------------------------------------- Dec 30 04:17:15 music go-librespot[13369]: time="2025-12-30T04:17:15-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Dec 30 04:17:16 music go-librespot[13369]: time="2025-12-30T04:17:16-05:00" level=debug msg="completed keyexchange" Dec 30 04:17:16 music go-librespot[13369]: time="2025-12-30T04:17:16-05:00" level=debug msg="completed challenge" Dec 30 04:17:16 music go-librespot[13369]: time="2025-12-30T04:17:16-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 30 04:17:16 music volumio[13353]: info: MYVOLUMIO Environment detected Dec 30 04:17:16 music volumio[13353]: info: Plugin folders cleanup Dec 30 04:17:16 music volumio[13353]: info: Scanning into folder /volumio/app/plugins/ Dec 30 04:17:16 music volumio[13353]: info: Scanning category audio_interface Dec 30 04:17:16 music volumio[13353]: info: Scanning category miscellanea Dec 30 04:17:16 music volumio[13353]: info: Scanning category music_service Dec 30 04:17:16 music volumio[13353]: info: Scanning category plugins.json Dec 30 04:17:16 music volumio[13353]: info: Scanning category system_controller Dec 30 04:17:16 music volumio[13353]: info: Scanning category user_interface Dec 30 04:17:16 music volumio[13353]: info: Scanning into folder /data/plugins/ Dec 30 04:17:16 music volumio[13353]: info: Scanning category music_service Dec 30 04:17:16 music volumio[13353]: info: Plugin folders cleanup completed Dec 30 04:17:16 music volumio[13353]: info: ------------------------------------------- Dec 30 04:17:16 music volumio[13353]: info: ----- Core plugins startup ---- Dec 30 04:17:16 music volumio[13353]: info: ------------------------------------------- Dec 30 04:17:16 music volumio[13353]: info: Loading plugins from folder /volumio/app/plugins/ Dec 30 04:17:16 music volumio[13353]: info: Adding plugin upnp to MyMusic Plugins Dec 30 04:17:16 music volumio[13353]: info: Adding plugin airplay_emulation to MyMusic Plugins Dec 30 04:17:16 music volumio[13353]: info: Adding plugin upnp_browser to MyMusic Plugins Dec 30 04:17:16 music volumio[13353]: info: Loading plugins from folder /data/plugins/ Dec 30 04:17:16 music volumio[13353]: info: Loading plugin "system"... Dec 30 04:17:16 music volumio[13353]: info: Loading plugin "appearance"... Dec 30 04:17:16 music go-librespot[13369]: time="2025-12-30T04:17:16-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Dec 30 04:17:16 music go-librespot[13369]: time="2025-12-30T04:17:16-05:00" level=debug msg="completed keyexchange" Dec 30 04:17:16 music go-librespot[13369]: time="2025-12-30T04:17:16-05:00" level=debug msg="completed challenge" Dec 30 04:17:16 music go-librespot[13369]: time="2025-12-30T04:17:16-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 30 04:17:17 music go-librespot[13369]: time="2025-12-30T04:17:17-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" Dec 30 04:17:17 music volumio[13353]: info: Loading plugin "network"... Dec 30 04:17:17 music volumio[13353]: info: Refreshing Cached IP Addresses Dec 30 04:17:17 music sudo[13391]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 30 04:17:17 music sudo[13391]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 04:17:17 music go-librespot[13369]: time="2025-12-30T04:17:17-05:00" level=debug msg="connected to ap-gae2.spotify.com:443" Dec 30 04:17:17 music sudo[13393]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 30 04:17:17 music sudo[13393]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 04:17:17 music volumio[13353]: info: Loading plugin "services"... Dec 30 04:17:17 music volumio[13353]: info: Loading plugin "alsa_controller"... Dec 30 04:17:17 music sudo[13393]: pam_unix(sudo:session): session closed for user root Dec 30 04:17:17 music sudo[13391]: pam_unix(sudo:session): session closed for user root Dec 30 04:17:17 music sudo[13405]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Dec 30 04:17:17 music sudo[13405]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 04:17:17 music volumio[13353]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 30 04:17:17 music volumio[13353]: info: Loading plugin "wizard"... Dec 30 04:17:17 music volumio[13353]: info: Loading plugin "networkfs"... Dec 30 04:17:17 music volumio[13353]: info: Starting Udev Watcher for removable devices Dec 30 04:17:17 music volumio[13353]: info: Ignoring mount for partition: boot Dec 30 04:17:17 music volumio[13353]: info: Ignoring mount for partition: volumio Dec 30 04:17:17 music volumio[13353]: info: Ignoring mount for partition: volumio_data Dec 30 04:17:17 music volumio[13353]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 30 04:17:17 music volumio[13353]: info: Loading plugin "volumio_command_line_client"... Dec 30 04:17:17 music volumio[13353]: info: Loading plugin "upnp"... Dec 30 04:17:17 music volumio[13353]: info: [1767086237797] Starting Upmpd Daemon Dec 30 04:17:17 music volumio[13353]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 30 04:17:17 music volumio[13353]: info: Loading plugin "my_music"... Dec 30 04:17:17 music volumio[13353]: info: Loading plugin "mpd"... Dec 30 04:17:17 music go-librespot[13369]: time="2025-12-30T04:17:17-05:00" level=debug msg="completed keyexchange" Dec 30 04:17:17 music go-librespot[13369]: time="2025-12-30T04:17:17-05:00" level=debug msg="completed challenge" Dec 30 04:17:18 music go-librespot[13369]: time="2025-12-30T04:17:18-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 30 04:17:18 music volumio[13353]: info: Loading plugin "upnp_browser"... Dec 30 04:17:18 music sudo[13405]: pam_unix(sudo:session): session closed for user root Dec 30 04:17:18 music volumio-remote-updater[735]: [2025-12-30 09:17:18] [connect] Successful connection Dec 30 04:17:18 music go-librespot[13369]: time="2025-12-30T04:17:18-05:00" level=debug msg="connected to ap-gew4.spotify.com:80" Dec 30 04:17:18 music go-librespot[13369]: time="2025-12-30T04:17:18-05:00" level=debug msg="completed keyexchange" Dec 30 04:17:18 music go-librespot[13369]: time="2025-12-30T04:17:18-05:00" level=debug msg="completed challenge" Dec 30 04:17:19 music go-librespot[13369]: time="2025-12-30T04:17:19-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 30 04:17:19 music go-librespot[13369]: time="2025-12-30T04:17:19-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 30 04:17:19 music go-librespot[13369]: time="2025-12-30T04:17:19-05:00" level=debug msg="completed keyexchange" Dec 30 04:17:19 music go-librespot[13369]: time="2025-12-30T04:17:19-05:00" level=debug msg="completed challenge" Dec 30 04:17:19 music go-librespot[13369]: time="2025-12-30T04:17:19-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 30 04:17:19 music go-librespot[13369]: time="2025-12-30T04:17: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 " Dec 30 04:17:19 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 04:17:19 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 04:17:19 music volumio[13353]: info: Starting UPNP Browser Dec 30 04:17:19 music volumio[13353]: info: Loading plugin "alarm-clock"... Dec 30 04:17:19 music volumio[13353]: info: Loading plugin "airplay_emulation"... Dec 30 04:17:19 music volumio[13353]: info: Starting Shairport Sync Dec 30 04:17:19 music volumio[13353]: info: Loading plugin "last_100"... Dec 30 04:17:19 music volumio[13353]: info: Loading plugin "webradio"... Dec 30 04:17:20 music volumio[13353]: info: Loading plugin "i2s_dacs"... Dec 30 04:17:20 music volumio[13353]: info: I2S DAC not set, start Auto-detection Dec 30 04:17:20 music volumio[13353]: info: Loading plugin "volumiodiscovery"... Dec 30 04:17:20 music volumio[13353]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 30 04:17:20 music volumio[13353]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 30 04:17:20 music volumio[13353]: *** WARNING *** For more information see Dec 30 04:17:20 music volumio[13353]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 30 04:17:20 music volumio[13353]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 30 04:17:20 music volumio[13353]: *** WARNING *** For more information see Dec 30 04:17:20 music node[13353]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 30 04:17:20 music node[13353]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 30 04:17:20 music node[13353]: *** WARNING *** For more information see Dec 30 04:17:20 music node[13353]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 30 04:17:20 music node[13353]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 30 04:17:20 music node[13353]: *** WARNING *** For more information see Dec 30 04:17:20 music volumio[13353]: info: Applying required configuration parameters for plugin volumiodiscovery Dec 30 04:17:20 music volumio[13353]: info: Discovery: Started advertising with name: music Dec 30 04:17:20 music volumio[13353]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 30 04:17:20 music volumio[13353]: info: Loading plugin "spop"... Dec 30 04:17:21 music volumio[13353]: info: Loading plugin "outputs"... Dec 30 04:17:21 music volumio[13353]: info: Loading plugin "albumart"... Dec 30 04:17:21 music volumio[13353]: info: Plugin example_plugin is not enabled Dec 30 04:17:21 music volumio[13353]: info: Loading plugin "inputs"... Dec 30 04:17:21 music volumio[13353]: info: Loading plugin "updater_comm"... Dec 30 04:17:21 music volumio[13353]: info: Plugin mpdemulation is not enabled Dec 30 04:17:21 music volumio[13353]: info: Loading plugin "rest_api"... Dec 30 04:17:21 music volumio[13353]: info: Loading plugin "websocket"... Dec 30 04:17:21 music volumio[13353]: info: Starting Socket.io Server version 1.7.4 Dec 30 04:17:21 music volumio[13353]: info: Loading i18n strings for locale en Dec 30 04:17:21 music volumio[13353]: Updating browse sources language Dec 30 04:17:21 music volumio[13353]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 04:17:21 music volumio[13353]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 30 04:17:21 music volumio[13353]: info: CoreCommandRouter::initPlayerControls Dec 30 04:17:21 music volumio[13353]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:17:21 music volumio[13353]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:17:21 music volumio[13353]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:17:21 music volumio[13353]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:17:21 music volumio[13353]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:17:21 music volumio[13353]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:17:21 music volumio[13353]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:17:21 music volumio[13353]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:17:21 music volumio[13353]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 30 04:17:21 music volumio[13353]: Express server listening on port 3000 Dec 30 04:17:21 music volumio[13353]: [Metrics] WebUI: 6s 596.22ms Dec 30 04:17:21 music volumio[13353]: info: CoreStateMachine::resetVolumioState Dec 30 04:17:21 music volumio[13353]: info: CoreStateMachine::getcurrentVolume Dec 30 04:17:21 music volumio[13353]: info: CoreCommandRouter::volumioRetrievevolume Dec 30 04:17:21 music volumio[13353]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 04:17:21 music volumio[13353]: info: Volumio Network Manager: Network status updated: 1 Dec 30 04:17:21 music volumio-remote-updater[735]: [2025-12-30 09:17:21] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1767086238 101 Dec 30 04:17:21 music volumio[13426]: Forking 3 albumart workers Dec 30 04:17:21 music volumio[13353]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 3 Transport: websocket Total Clients: 1 Dec 30 04:17:21 music volumio[13353]: info: VolumeController:: Volume=86 Mute =false Dec 30 04:17:21 music volumio[13353]: info: CoreStateMachine::pushState Dec 30 04:17:21 music volumio[13353]: info: CorePlayQueue::getTrack 0 Dec 30 04:17:21 music volumio[13353]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 30 04:17:21 music volumio[13353]: info: CoreCommandRouter::volumioPushState Dec 30 04:17:21 music volumio[13353]: info: CoreStateMachine::updateTrackBlock Dec 30 04:17:21 music volumio[13353]: info: CorePlayQueue::getTrackBlock Dec 30 04:17:21 music volumio[13353]: info: CoreCommandRouter::volumioRetrievevolume Dec 30 04:17:21 music volumio[13353]: info: Reloading queue from file Dec 30 04:17:21 music volumio[13353]: info: CoreStateMachine::setRepeat null single undefined Dec 30 04:17:21 music volumio[13353]: info: CoreStateMachine::pushState Dec 30 04:17:21 music volumio[13353]: info: CorePlayQueue::getTrack 0 Dec 30 04:17:21 music volumio[13353]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 30 04:17:21 music volumio[13353]: info: CoreCommandRouter::volumioPushState Dec 30 04:17:21 music volumio[13353]: info: CoreStateMachine::setRandom null Dec 30 04:17:21 music volumio[13353]: info: CoreStateMachine::pushState Dec 30 04:17:21 music volumio[13353]: info: CorePlayQueue::getTrack 0 Dec 30 04:17:21 music volumio[13353]: info: CoreCommandRouter::volumioPushState Dec 30 04:17:21 music volumio[13353]: info: Setting Device type: Raspberry PI Dec 30 04:17:22 music volumio[13353]: info: VolumeController:: Volume=86 Mute =false Dec 30 04:17:22 music volumio[13353]: info: CoreStateMachine::pushState Dec 30 04:17:22 music volumio[13353]: info: CorePlayQueue::getTrack 0 Dec 30 04:17:22 music volumio[13353]: info: CoreCommandRouter::volumioPushState Dec 30 04:17:22 music volumio[13353]: info: Completed loading Core Plugins Dec 30 04:17:22 music volumio[13353]: info: Preparing to generate the ALSA configuration file Dec 30 04:17:22 music volumio[13353]: info: Discovery: adding 4a29b7a7-c637-4926-a2bd-fb4e2f55145e Dec 30 04:17:22 music volumio[13353]: info: Discovery: Found device music Dec 30 04:17:22 music volumio[13353]: info: CoreCommandRouter::volumioGetState Dec 30 04:17:22 music volumio[13353]: info: CorePlayQueue::getTrack 0 Dec 30 04:17:22 music volumio[13353]: info: Discovery: this is already registered, 4a29b7a7-c637-4926-a2bd-fb4e2f55145e Dec 30 04:17:22 music volumio[13353]: info: Discovery: Found device music Dec 30 04:17:22 music volumio[13353]: info: CoreCommandRouter::volumioGetState Dec 30 04:17:22 music volumio[13353]: info: CorePlayQueue::getTrack 0 Dec 30 04:17:22 music volumio[13353]: info: Asound.conf file unchanged, so no further update is needed Dec 30 04:17:22 music volumio[13353]: info: Output device has changed, restarting MPD Dec 30 04:17:22 music volumio[13353]: info: Output device has changed, restarting Shairport Sync Dec 30 04:17:22 music volumio[13353]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:17:22 music volumio[13353]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 04:17:22 music sudo[13481]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 30 04:17:22 music sudo[13481]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 04:17:22 music sudo[13481]: pam_unix(sudo:session): session closed for user root Dec 30 04:17:22 music sudo[13483]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 30 04:17:22 music sudo[13483]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 04:17:22 music volumio[13353]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 30 04:17:22 music volumio[13353]: info: ___________ START PLUGINS ___________ Dec 30 04:17:22 music volumio[13353]: info: ControllerMpd::onStart: Initializing MPD Dec 30 04:17:22 music volumio[13353]: info: Creating MPD Configuration file Dec 30 04:17:22 music systemd[1]: Stopping mpd.service - Music Player Daemon... Dec 30 04:17:22 music volumio[13353]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 30 04:17:22 music volumio[13353]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 04:17:22 music volumio[13353]: info: [1767086242341] CoreMusicLibrary::Adding element Media Servers Dec 30 04:17:22 music volumio[13353]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 04:17:22 music sudo[13491]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 30 04:17:22 music sudo[13491]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 04:17:22 music sudo[13491]: pam_unix(sudo:session): session closed for user root Dec 30 04:17:22 music volumio[13353]: info: UPNP Browser: Client initialized successfully Dec 30 04:17:22 music sudo[13493]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 30 04:17:22 music sudo[13493]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 04:17:22 music systemd[1]: mpd.service: Deactivated successfully. Dec 30 04:17:22 music systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 30 04:17:22 music systemd[1]: mpd.service: Consumed 4.175s CPU time. Dec 30 04:17:22 music systemd[1]: mpd.socket: Deactivated successfully. Dec 30 04:17:22 music systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 30 04:17:22 music systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 30 04:17:22 music volumio[13353]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:17:22 music volumio[13353]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 04:17:22 music volumio[13353]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 30 04:17:22 music volumio[13353]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:17:22 music volumio[13353]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 04:17:22 music systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 30 04:17:22 music systemd[1]: Starting mpd.service - Music Player Daemon... Dec 30 04:17:22 music volumio[13353]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 30 04:17:22 music volumio[13353]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 04:17:22 music volumio[13353]: info: [1767086242537] CoreMusicLibrary::Adding element Last_100 Dec 30 04:17:22 music volumio[13353]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 04:17:22 music volumio[13353]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 04:17:22 music volumio[13353]: info: [1767086242552] CoreMusicLibrary::Adding element Webradio Dec 30 04:17:22 music volumio[13353]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 04:17:22 music systemd[1]: mpd.service: Deactivated successfully. Dec 30 04:17:22 music systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 30 04:17:22 music systemd[1]: mpd.socket: Deactivated successfully. Dec 30 04:17:22 music systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 30 04:17:22 music systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 30 04:17:22 music volumio[13353]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 30 04:17:22 music volumio[13353]: info: Initializing BBC Radios Dec 30 04:17:22 music systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 30 04:17:22 music systemd[1]: Starting mpd.service - Music Player Daemon... Dec 30 04:17:22 music volumio[13353]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 30 04:17:22 music volumio[13353]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 04:17:22 music volumio[13353]: info: Creating Spotify config file Dec 30 04:17:22 music volumio[13353]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:17:22 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Dec 30 04:17:22 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 04:17:22 music sudo[13510]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 30 04:17:22 music sudo[13510]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 30 04:17:22 music sudo[13510]: pam_unix(sudo:session): session closed for user root Dec 30 04:17:22 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 04:17:22 music go-librespot[13521]: go-librespot daemon starting... Dec 30 04:17:22 music go-librespot[13523]: time="2025-12-30T04:17:22-05:00" level=info msg="running go-librespot 0.6.2" Dec 30 04:17:23 music volumio[13353]: info: Volumio Calling Home Dec 30 04:17:23 music go-librespot[13523]: time="2025-12-30T04:17:23-05:00" level=info msg="zeroconf server listening on port 46273" Dec 30 04:17:23 music volumio[13443]: Starting albumart workers Dec 30 04:17:23 music volumio[13353]: info: MPD Permissions set Dec 30 04:17:23 music volumio[13353]: info: MPD Permissions set Dec 30 04:17:23 music volumio[13353]: info: Volumio called home Dec 30 04:17:23 music volumio[13353]: info: Spotify config file written Dec 30 04:17:24 music sudo[13537]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 30 04:17:24 music sudo[13537]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 04:17:24 music systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Dec 30 04:17:24 music systemd[1]: go-librespot-daemon.service: Deactivated successfully. Dec 30 04:17:24 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 04:17:24 music volumio[13444]: Starting albumart workers Dec 30 04:17:24 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 04:17:24 music go-librespot[13539]: go-librespot daemon starting... Dec 30 04:17:24 music sudo[13537]: pam_unix(sudo:session): session closed for user root Dec 30 04:17:24 music volumio[13353]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Dec 30 04:17:24 music go-librespot[13540]: time="2025-12-30T04:17:24-05:00" level=info msg="running go-librespot 0.6.2" Dec 30 04:17:24 music go-librespot[13540]: time="2025-12-30T04:17:24-05:00" level=debug msg="app state loaded" Dec 30 04:17:24 music volumio[13353]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:17:24 music volumio[13353]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:17:24 music volumio[13353]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:17:24 music volumio[13353]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:17:24 music volumio[13442]: Starting albumart workers Dec 30 04:17:24 music volumio[13353]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:17:24 music volumio[13353]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:17:24 music volumio[13353]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:17:24 music volumio[13353]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:17:24 music go-librespot[13540]: time="2025-12-30T04:17:24-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 04:17:24 music volumio[13353]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 04:17:24 music volumio[13353]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:17:24 music volumio[13353]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:17:24 music volumio[13353]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:17:24 music volumio[13353]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:17:24 music volumio[13353]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:17:24 music volumio[13353]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:17:24 music volumio[13353]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:17:24 music volumio[13353]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:17:24 music volumio[13353]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:17:24 music volumio[13353]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 04:17:24 music volumio[13353]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:17:24 music volumio[13353]: info: No need to fix Spotify hosts Dec 30 04:17:24 music go-librespot[13540]: time="2025-12-30T04:17:24-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]" Dec 30 04:17:24 music go-librespot[13540]: time="2025-12-30T04:17:24-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]" Dec 30 04:17:24 music go-librespot[13540]: time="2025-12-30T04:17:24-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]" Dec 30 04:17:24 music go-librespot[13540]: time="2025-12-30T04:17:24-05:00" level=info msg="zeroconf server listening on port 42151" Dec 30 04:17:24 music go-librespot[13540]: time="2025-12-30T04:17:24-05:00" level=debug msg="obtained new client token: AAAM8Y6lco29F/yyzWkOoXZj0iXe4mVCGngojAFjM9I08E6e5muWCmZALjVTmw2/SMB3vqCWOi/fsIROCmPiVUsrerry8a3gr7FMIrsCH6x74ioFQSUCeEoLS4GUbnNzOBT/eBRfQ8KrC/bD6NJva5jQmDinsZpeC5Jjs4fVMyCz6GuwGcsOpPpgTYwWGUvZ6hxNAmFHLqMk0/1sOoRn6SxbF1ZGqG815MYGsvLbPc2a9B6hyqC71Dxa" Dec 30 04:17:24 music go-librespot[13540]: time="2025-12-30T04:17:24-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 30 04:17:25 music go-librespot[13540]: time="2025-12-30T04:17:25-05:00" level=debug msg="completed keyexchange" Dec 30 04:17:25 music go-librespot[13540]: time="2025-12-30T04:17:25-05:00" level=debug msg="completed challenge" Dec 30 04:17:25 music volumio[13353]: info: Starting Shairport Sync Dec 30 04:17:25 music volumio[13353]: info: Starting Shairport Sync Dec 30 04:17:25 music go-librespot[13540]: time="2025-12-30T04:17:25-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 30 04:17:25 music volumio[13353]: info: Starting Shairport Sync Dec 30 04:17:25 music sudo[13568]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 30 04:17:25 music sudo[13568]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 04:17:25 music sudo[13570]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 30 04:17:25 music sudo[13570]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 04:17:25 music volumio[13353]: info: An error occurred while refreshing Spotify Token Error: Bad Request Dec 30 04:17:25 music systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 30 04:17:25 music sudo[13573]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 30 04:17:25 music systemd[1]: shairport-sync.service: Deactivated successfully. Dec 30 04:17:25 music systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 30 04:17:25 music systemd[1]: shairport-sync.service: Consumed 1.869s CPU time. Dec 30 04:17:25 music sudo[13573]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 04:17:25 music systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 30 04:17:25 music sudo[13568]: pam_unix(sudo:session): session closed for user root Dec 30 04:17:25 music sudo[13570]: pam_unix(sudo:session): session closed for user root Dec 30 04:17:25 music systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 30 04:17:25 music systemd[1]: shairport-sync.service: Deactivated successfully. Dec 30 04:17:25 music systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 30 04:17:25 music systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 30 04:17:25 music sudo[13573]: pam_unix(sudo:session): session closed for user root Dec 30 04:17:25 music volumio[13353]: info: Shairport-Sync Started Dec 30 04:17:25 music volumio[13353]: Error adding Membership: Error: addMembership EINVAL Dec 30 04:17:25 music volumio[13353]: info: Shairport-Sync Started Dec 30 04:17:25 music volumio[13353]: info: Shairport-Sync Started Dec 30 04:17:25 music volumio[13353]: info: CoreCommandRouter::volumioGetState Dec 30 04:17:25 music volumio[13353]: info: CorePlayQueue::getTrack 0 Dec 30 04:17:25 music go-librespot[13540]: time="2025-12-30T04:17:25-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Dec 30 04:17:25 music go-librespot[13540]: time="2025-12-30T04:17:25-05:00" level=debug msg="completed keyexchange" Dec 30 04:17:25 music go-librespot[13540]: time="2025-12-30T04:17:25-05:00" level=debug msg="completed challenge" Dec 30 04:17:25 music go-librespot[13540]: time="2025-12-30T04:17:25-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 30 04:17:26 music go-librespot[13540]: time="2025-12-30T04:17:26-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Dec 30 04:17:26 music go-librespot[13540]: time="2025-12-30T04:17:26-05:00" level=debug msg="completed keyexchange" Dec 30 04:17:26 music go-librespot[13540]: time="2025-12-30T04:17:26-05:00" level=debug msg="completed challenge" Dec 30 04:17:26 music go-librespot[13540]: time="2025-12-30T04:17:26-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 30 04:17:26 music mpd[13524]: 2025-12-30T04:17:26 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Dec 30 04:17:26 music systemd[1]: Started mpd.service - Music Player Daemon. Dec 30 04:17:26 music sudo[13493]: pam_unix(sudo:session): session closed for user root Dec 30 04:17:26 music sudo[13483]: pam_unix(sudo:session): session closed for user root Dec 30 04:17:27 music volumio[13353]: info: Completed starting Core Plugins Dec 30 04:17:27 music volumio[13353]: info: ------------------------------------------- Dec 30 04:17:27 music volumio[13353]: info: ----- MyVolumio plugins startup ---- Dec 30 04:17:27 music volumio[13353]: info: ------------------------------------------- Dec 30 04:17:27 music volumio[13353]: info: [MyVolumio PluginManager] Fetching plans data.... Dec 30 04:17:27 music volumio[13353]: error: MPD error: The expression evaluated to a falsy value: Dec 30 04:17:27 music volumio[13353]: assert.ok(self.idling) Dec 30 04:17:27 music volumio[13353]: error: The expression evaluated to a falsy value: Dec 30 04:17:27 music volumio[13353]: assert.ok(self.idling) Dec 30 04:17:27 music volumio[13353]: error: updateQueue error: null Dec 30 04:17:27 music go-librespot[13540]: time="2025-12-30T04:17:27-05:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 04:17:27 music volumio[13353]: info: MPD running with PID13524 Dec 30 04:17:27 music volumio[13353]: ,establishing connection Dec 30 04:17:27 music volumio[13353]: error: updateQueue error: null Dec 30 04:17:27 music go-librespot[13540]: time="2025-12-30T04:17:27-05:00" level=debug msg="completed keyexchange" Dec 30 04:17:27 music go-librespot[13540]: time="2025-12-30T04:17:27-05:00" level=debug msg="completed challenge" Dec 30 04:17:27 music go-librespot[13540]: time="2025-12-30T04:17:27-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 30 04:17:27 music sudo[13627]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 30 04:17:27 music sudo[13627]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 04:17:27 music sudo[13629]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 30 04:17:27 music sudo[13629]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 04:17:27 music sudo[13627]: pam_unix(sudo:session): session closed for user root Dec 30 04:17:27 music sudo[13629]: pam_unix(sudo:session): session closed for user root Dec 30 04:17:27 music sudo[13632]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Dec 30 04:17:27 music sudo[13632]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 04:17:27 music sudo[13632]: pam_unix(sudo:session): session closed for user root Dec 30 04:17:27 music volumio[13353]: info: go-librespot daemon successfully initialized Dec 30 04:17:27 music volumio[13353]: info: Upmpdcli Daemon Started Dec 30 04:17:27 music go-librespot[13540]: time="2025-12-30T04:17:27-05:00" level=debug msg="connected to ap-gae2.spotify.com:443" Dec 30 04:17:28 music go-librespot[13540]: time="2025-12-30T04:17:28-05:00" level=debug msg="completed keyexchange" Dec 30 04:17:28 music go-librespot[13540]: time="2025-12-30T04:17:28-05:00" level=debug msg="completed challenge" Dec 30 04:17:28 music go-librespot[13540]: time="2025-12-30T04:17:28-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 30 04:17:29 music go-librespot[13540]: time="2025-12-30T04:17:29-05:00" level=debug msg="connected to ap-gew4.spotify.com:80" Dec 30 04:17:29 music go-librespot[13540]: time="2025-12-30T04:17:29-05:00" level=debug msg="completed keyexchange" Dec 30 04:17:29 music go-librespot[13540]: time="2025-12-30T04:17:29-05:00" level=debug msg="completed challenge" Dec 30 04:17:29 music go-librespot[13540]: time="2025-12-30T04:17:29-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 30 04:17:29 music go-librespot[13540]: time="2025-12-30T04:17:29-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 " Dec 30 04:17:29 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 04:17:29 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 04:17:30 music sudo[13636]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 30 04:17:30 music sudo[13636]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 04:17:30 music sudo[13638]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 30 04:17:30 music sudo[13638]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 04:17:30 music systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Dec 30 04:17:30 music systemd[1]: mpd_monitor.service: Deactivated successfully. Dec 30 04:17:30 music systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Dec 30 04:17:30 music systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Dec 30 04:17:30 music sudo[13638]: pam_unix(sudo:session): session closed for user root Dec 30 04:17:30 music sudo[13636]: pam_unix(sudo:session): session closed for user root Dec 30 04:17:30 music volumio[13353]: info: Successfully started MPD Monitor Dec 30 04:17:30 music mpd_monitor.sh[13641]: MPD Monitor Service: Starting MPD Monitor Service Dec 30 04:17:30 music volumio[13353]: info: Successfully started MPD Monitor Dec 30 04:17:30 music volumio[13353]: info: Initializing connection to go-librespot Websocket Dec 30 04:17:30 music volumio[13353]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 30 04:17:32 music volumio[13353]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Dec 30 04:17:32 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Dec 30 04:17:32 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 04:17:32 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 04:17:32 music go-librespot[13645]: go-librespot daemon starting... Dec 30 04:17:32 music go-librespot[13646]: time="2025-12-30T04:17:32-05:00" level=info msg="running go-librespot 0.6.2" Dec 30 04:17:32 music go-librespot[13646]: time="2025-12-30T04:17:32-05:00" level=debug msg="app state loaded" Dec 30 04:17:32 music go-librespot[13646]: time="2025-12-30T04:17:32-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 04:17:32 music go-librespot[13646]: time="2025-12-30T04:17:32-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]" Dec 30 04:17:32 music go-librespot[13646]: time="2025-12-30T04:17:32-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]" Dec 30 04:17:32 music go-librespot[13646]: time="2025-12-30T04:17:32-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]" Dec 30 04:17:32 music go-librespot[13646]: time="2025-12-30T04:17:32-05:00" level=info msg="zeroconf server listening on port 45569" Dec 30 04:17:32 music go-librespot[13646]: time="2025-12-30T04:17:32-05:00" level=debug msg="obtained new client token: AAAnU17Nwwt7lPyUBBXIlneEehutH9Yjgn1EO7YBlih1djFtCQXlcwrdAfi9yudGVmccbl0veA4pPjH/YRZSqStscFa3lZ6GLktpQ0KOqaBErlO4WUF5dZ2e02srVpktSoV3j3u66gmSQcZavwjPqPF4wk+2I8M8Gj4iPe+5Ecp1smvEr6Cwxw51efBIt5kj5vk2hooBf32MbizRCvO+b1M4Fs8r8Wl0ijfaKm4aAv91b9ZBoKLxAonq" Dec 30 04:17:32 music go-librespot[13646]: time="2025-12-30T04:17:32-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 30 04:17:33 music go-librespot[13646]: time="2025-12-30T04:17:33-05:00" level=debug msg="completed keyexchange" Dec 30 04:17:33 music go-librespot[13646]: time="2025-12-30T04:17:33-05:00" level=debug msg="completed challenge" Dec 30 04:17:33 music go-librespot[13646]: time="2025-12-30T04:17:33-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 30 04:17:33 music go-librespot[13646]: time="2025-12-30T04:17:33-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Dec 30 04:17:33 music go-librespot[13646]: time="2025-12-30T04:17:33-05:00" level=debug msg="completed keyexchange" Dec 30 04:17:33 music go-librespot[13646]: time="2025-12-30T04:17:33-05:00" level=debug msg="completed challenge" Dec 30 04:17:33 music go-librespot[13646]: time="2025-12-30T04:17:33-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 30 04:17:33 music volumio[13353]: info: Initializing connection to go-librespot Websocket Dec 30 04:17:33 music go-librespot[13646]: time="2025-12-30T04:17:33-05:00" level=debug msg="new websocket client" Dec 30 04:17:33 music volumio[13353]: info: Connection to go-librespot Websocket established Dec 30 04:17:34 music go-librespot[13646]: time="2025-12-30T04:17:34-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Dec 30 04:17:34 music go-librespot[13646]: time="2025-12-30T04:17:34-05:00" level=debug msg="completed keyexchange" Dec 30 04:17:34 music go-librespot[13646]: time="2025-12-30T04:17:34-05:00" level=debug msg="completed challenge" Dec 30 04:17:34 music go-librespot[13646]: time="2025-12-30T04:17:34-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 30 04:17:35 music go-librespot[13646]: time="2025-12-30T04:17:35-05:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Dec 30 04:17:35 music volumio[13353]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Dec 30 04:17:35 music volumio[13353]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Dec 30 04:17:35 music volumio[13353]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Dec 30 04:17:35 music volumio[13353]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Dec 30 04:17:35 music volumio[13353]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Dec 30 04:17:35 music volumio[13353]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Dec 30 04:17:35 music volumio[13353]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Dec 30 04:17:35 music volumio[13353]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Dec 30 04:17:35 music volumio[13353]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Dec 30 04:17:35 music volumio[13353]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Dec 30 04:17:35 music volumio[13353]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Dec 30 04:17:35 music volumio[13353]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Dec 30 04:17:35 music volumio[13353]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Dec 30 04:17:35 music volumio[13353]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Dec 30 04:17:35 music volumio[13353]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Dec 30 04:17:35 music volumio[13353]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Dec 30 04:17:35 music volumio[13353]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Dec 30 04:17:35 music volumio[13353]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Dec 30 04:17:35 music volumio[13353]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Dec 30 04:17:35 music volumio[13353]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Dec 30 04:17:35 music volumio[13353]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Dec 30 04:17:35 music volumio[13353]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Dec 30 04:17:35 music volumio[13353]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Dec 30 04:17:35 music volumio[13353]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Dec 30 04:17:35 music volumio[13353]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Dec 30 04:17:35 music volumio[13353]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Dec 30 04:17:35 music volumio[13353]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Dec 30 04:17:35 music volumio[13353]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Dec 30 04:17:35 music volumio[13353]: info: Adding plugin bluetooth to MyMusic Plugins Dec 30 04:17:35 music volumio[13353]: info: Adding plugin multiroom to MyMusic Plugins Dec 30 04:17:35 music volumio[13353]: info: Adding plugin metavolumio to MyMusic Plugins Dec 30 04:17:35 music volumio[13353]: info: Adding plugin cd_controller to MyMusic Plugins Dec 30 04:17:35 music volumio[13353]: info: Adding plugin qobuzconnect to MyMusic Plugins Dec 30 04:17:35 music volumio[13353]: info: Adding plugin smart_inputs to MyMusic Plugins Dec 30 04:17:35 music volumio[13353]: info: Adding plugin tidalconnect to MyMusic Plugins Dec 30 04:17:35 music volumio[13353]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Dec 30 04:17:35 music go-librespot[13646]: time="2025-12-30T04:17:35-05:00" level=debug msg="completed keyexchange" Dec 30 04:17:35 music go-librespot[13646]: time="2025-12-30T04:17:35-05:00" level=debug msg="completed challenge" Dec 30 04:17:35 music go-librespot[13646]: time="2025-12-30T04:17:35-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 30 04:17:36 music go-librespot[13646]: time="2025-12-30T04:17:36-05:00" level=debug msg="connected to ap-gew1.spotify.com:443" Dec 30 04:17:36 music go-librespot[13646]: time="2025-12-30T04:17:36-05:00" level=debug msg="completed keyexchange" Dec 30 04:17:36 music go-librespot[13646]: time="2025-12-30T04:17:36-05:00" level=debug msg="completed challenge" Dec 30 04:17:36 music volumio[13353]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Dec 30 04:17:36 music volumio[13353]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Dec 30 04:17:36 music volumio[13353]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 04:17:36 music volumio[13353]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 04:17:36 music go-librespot[13646]: time="2025-12-30T04:17:36-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 30 04:17:36 music volumio[13353]: info: Starting MyVolumio Remote Streaming Endpoints Dec 30 04:17:36 music volumio[13353]: info: MyVolumio login type: Token Dec 30 04:17:36 music volumio[13353]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Dec 30 04:17:36 music volumio[13353]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Dec 30 04:17:37 music go-librespot[13646]: time="2025-12-30T04:17:37-05:00" level=debug msg="connected to ap-gew4.spotify.com:80" Dec 30 04:17:37 music go-librespot[13646]: time="2025-12-30T04:17:37-05:00" level=debug msg="completed keyexchange" Dec 30 04:17:37 music go-librespot[13646]: time="2025-12-30T04:17:37-05:00" level=debug msg="completed challenge" Dec 30 04:17:37 music go-librespot[13646]: time="2025-12-30T04:17:37-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 30 04:17:37 music go-librespot[13646]: time="2025-12-30T04:17:37-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 " Dec 30 04:17:37 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 04:17:37 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 04:17:37 music volumio[13353]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Dec 30 04:17:37 music volumio[13353]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Dec 30 04:17:37 music volumio[13353]: info: Streaming services startup Dec 30 04:17:37 music volumio[13353]: info: Starting Streaming Daemon Dec 30 04:17:37 music sudo[13656]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Dec 30 04:17:37 music sudo[13656]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 04:17:37 music volumio[13353]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Dec 30 04:17:37 music sudo[13656]: pam_unix(sudo:session): session closed for user root Dec 30 04:17:37 music volumio[13353]: info: Getting Spotify volume Dec 30 04:17:37 music volumio[13353]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 30 04:17:37 music volumio[13353]: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 30 04:17:37 music volumio[13353]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Dec 30 04:17:37 music volumio[13353]: errno: -111, Dec 30 04:17:37 music volumio[13353]: code: 'ECONNREFUSED', Dec 30 04:17:37 music volumio[13353]: syscall: 'connect', Dec 30 04:17:37 music volumio[13353]: address: '127.0.0.1', Dec 30 04:17:37 music volumio[13353]: port: 9879, Dec 30 04:17:37 music volumio[13353]: response: undefined Dec 30 04:17:37 music volumio[13353]: } Dec 30 04:17:37 music volumio[13353]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 30 04:17:38 music sudo[13690]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-30 04:16' Dec 30 04:17:38 music sudo[13690]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 04:17:38 music sudo[13690]: pam_unix(sudo:session): session closed for user root Dec 30 04:17:38 music volumio-remote-updater[735]: [2025-12-30 09:17:38] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Dec 30 04:17:38 music volumio-remote-updater[735]: [2025-12-30 09:17:38] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Dec 30 04:17:38 music systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Dec 30 04:17:38 music systemd[1]: volumio.service: Failed with result 'exit-code'. Dec 30 04:17:38 music systemd[1]: volumio.service: Consumed 26.416s CPU time. Dec 30 04:17:38 music systemd[1]: Started dynamicswap.service - dynamicswap service. Dec 30 04:17:38 music systemd[1]: dynamicswap.service: Deactivated successfully. Dec 30 04:17:38 music systemd[1]: volumio.service: Scheduled restart job, restart counter is at 8374. Dec 30 04:17:38 music systemd[1]: Started dynamicswap.service - dynamicswap service. Dec 30 04:17:38 music systemd[1]: Stopped volumio.service - Volumio Backend Module. Dec 30 04:17:38 music systemd[1]: volumio.service: Consumed 26.416s CPU time. Dec 30 04:17:38 music systemd[1]: Started volumio.service - Volumio Backend Module. Dec 30 04:17:38 music systemd[1]: dynamicswap.service: Deactivated successfully. Dec 30 04:17:40 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Dec 30 04:17:40 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 04:17:40 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 04:17:40 music go-librespot[13717]: go-librespot daemon starting... Dec 30 04:17:40 music go-librespot[13718]: time="2025-12-30T04:17:40-05:00" level=info msg="running go-librespot 0.6.2" Dec 30 04:17:40 music go-librespot[13718]: time="2025-12-30T04:17:40-05:00" level=debug msg="app state loaded" Dec 30 04:17:40 music go-librespot[13718]: time="2025-12-30T04:17:40-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 04:17:40 music go-librespot[13718]: time="2025-12-30T04:17:40-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]" Dec 30 04:17:40 music go-librespot[13718]: time="2025-12-30T04:17:40-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]" Dec 30 04:17:40 music go-librespot[13718]: time="2025-12-30T04:17:40-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]" Dec 30 04:17:40 music go-librespot[13718]: time="2025-12-30T04:17:40-05:00" level=info msg="zeroconf server listening on port 39263" Dec 30 04:17:40 music volumio[13702]: info: ------------------------------------------- Dec 30 04:17:40 music volumio[13702]: info: ----- Volumio3 ---- Dec 30 04:17:40 music volumio[13702]: info: ------------------------------------------- Dec 30 04:17:40 music volumio[13702]: info: ----- System startup ---- Dec 30 04:17:40 music volumio[13702]: info: ------------------------------------------- Dec 30 04:17:40 music go-librespot[13718]: time="2025-12-30T04:17:40-05:00" level=debug msg="obtained new client token: AADP5+7VX2pYK4tpvID+bfOgVCX5xwnn6FP0G9uIBy5YrFJ8VgplryGQ+FwUVnGm3mlegzcHCIHs4Y95DKF0PSOCCwcc4LiPDI0NE0UgZhRwlUEqatoAcOgPFKDe+P8Lvzp79c2pqJmvo4Hrd3Pewf4H5QgZq3oamkuNFA7DL/sb42x/K+gxEaJ9aFIBMV3U3QduyXE8WF7WiF89jt3KLp/LiMTLTeeKeNVJPfGhs363ybvDYCmO97yG" Dec 30 04:17:40 music go-librespot[13718]: time="2025-12-30T04:17:40-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 30 04:17:41 music go-librespot[13718]: time="2025-12-30T04:17:41-05:00" level=debug msg="completed keyexchange" Dec 30 04:17:41 music go-librespot[13718]: time="2025-12-30T04:17:41-05:00" level=debug msg="completed challenge" Dec 30 04:17:41 music go-librespot[13718]: time="2025-12-30T04:17:41-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 30 04:17:41 music go-librespot[13718]: time="2025-12-30T04:17:41-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Dec 30 04:17:41 music volumio[13702]: info: MYVOLUMIO Environment detected Dec 30 04:17:41 music go-librespot[13718]: time="2025-12-30T04:17:41-05:00" level=debug msg="completed keyexchange" Dec 30 04:17:41 music go-librespot[13718]: time="2025-12-30T04:17:41-05:00" level=debug msg="completed challenge" Dec 30 04:17:41 music volumio[13702]: info: Plugin folders cleanup Dec 30 04:17:41 music volumio[13702]: info: Scanning into folder /volumio/app/plugins/ Dec 30 04:17:41 music volumio[13702]: info: Scanning category audio_interface Dec 30 04:17:41 music volumio[13702]: info: Scanning category miscellanea Dec 30 04:17:41 music volumio[13702]: info: Scanning category music_service Dec 30 04:17:41 music volumio[13702]: info: Scanning category plugins.json Dec 30 04:17:41 music volumio[13702]: info: Scanning category system_controller Dec 30 04:17:41 music volumio[13702]: info: Scanning category user_interface Dec 30 04:17:41 music volumio[13702]: info: Scanning into folder /data/plugins/ Dec 30 04:17:41 music volumio[13702]: info: Scanning category music_service Dec 30 04:17:41 music volumio[13702]: info: Plugin folders cleanup completed Dec 30 04:17:41 music volumio[13702]: info: ------------------------------------------- Dec 30 04:17:41 music volumio[13702]: info: ----- Core plugins startup ---- Dec 30 04:17:41 music volumio[13702]: info: ------------------------------------------- Dec 30 04:17:41 music volumio[13702]: info: Loading plugins from folder /volumio/app/plugins/ Dec 30 04:17:41 music volumio[13702]: info: Adding plugin upnp to MyMusic Plugins Dec 30 04:17:41 music volumio[13702]: info: Adding plugin airplay_emulation to MyMusic Plugins Dec 30 04:17:41 music volumio[13702]: info: Adding plugin upnp_browser to MyMusic Plugins Dec 30 04:17:41 music go-librespot[13718]: time="2025-12-30T04:17:41-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 30 04:17:41 music volumio[13702]: info: Loading plugins from folder /data/plugins/ Dec 30 04:17:41 music volumio[13702]: info: Loading plugin "system"... Dec 30 04:17:41 music volumio[13702]: info: Loading plugin "appearance"... Dec 30 04:17:42 music go-librespot[13718]: time="2025-12-30T04:17:42-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Dec 30 04:17:42 music go-librespot[13718]: time="2025-12-30T04:17:42-05:00" level=debug msg="completed keyexchange" Dec 30 04:17:42 music go-librespot[13718]: time="2025-12-30T04:17:42-05:00" level=debug msg="completed challenge" Dec 30 04:17:42 music go-librespot[13718]: time="2025-12-30T04:17:42-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 30 04:17:42 music volumio[13702]: info: Loading plugin "network"... Dec 30 04:17:42 music volumio[13702]: info: Refreshing Cached IP Addresses Dec 30 04:17:42 music sudo[13740]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 30 04:17:42 music sudo[13740]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 04:17:42 music sudo[13742]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 30 04:17:42 music sudo[13742]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 04:17:42 music sudo[13742]: pam_unix(sudo:session): session closed for user root Dec 30 04:17:42 music sudo[13740]: pam_unix(sudo:session): session closed for user root Dec 30 04:17:42 music volumio[13702]: info: Loading plugin "services"... Dec 30 04:17:42 music volumio[13702]: info: Loading plugin "alsa_controller"... Dec 30 04:17:43 music sudo[13751]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Dec 30 04:17:43 music sudo[13751]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 04:17:43 music go-librespot[13718]: time="2025-12-30T04:17:43-05:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 04:17:43 music volumio[13702]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 30 04:17:43 music volumio[13702]: info: Loading plugin "wizard"... Dec 30 04:17:43 music go-librespot[13718]: time="2025-12-30T04:17:43-05:00" level=debug msg="completed keyexchange" Dec 30 04:17:43 music go-librespot[13718]: time="2025-12-30T04:17:43-05:00" level=debug msg="completed challenge" Dec 30 04:17:43 music volumio[13702]: info: Loading plugin "networkfs"... Dec 30 04:17:43 music volumio[13702]: info: Starting Udev Watcher for removable devices Dec 30 04:17:43 music go-librespot[13718]: time="2025-12-30T04:17:43-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 30 04:17:43 music volumio[13702]: info: Ignoring mount for partition: boot Dec 30 04:17:43 music volumio[13702]: info: Ignoring mount for partition: volumio Dec 30 04:17:43 music volumio[13702]: info: Ignoring mount for partition: volumio_data Dec 30 04:17:43 music volumio[13702]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 30 04:17:43 music volumio[13702]: info: Loading plugin "volumio_command_line_client"... Dec 30 04:17:43 music volumio[13702]: info: Loading plugin "upnp"... Dec 30 04:17:43 music volumio[13702]: info: [1767086263165] Starting Upmpd Daemon Dec 30 04:17:43 music volumio[13702]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 30 04:17:43 music volumio[13702]: info: Loading plugin "my_music"... Dec 30 04:17:43 music volumio[13702]: info: Loading plugin "mpd"... Dec 30 04:17:43 music volumio[13702]: info: Loading plugin "upnp_browser"... Dec 30 04:17:43 music sudo[13751]: pam_unix(sudo:session): session closed for user root Dec 30 04:17:43 music volumio-remote-updater[735]: [2025-12-30 09:17:43] [connect] Successful connection Dec 30 04:17:43 music go-librespot[13718]: time="2025-12-30T04:17:43-05:00" level=debug msg="connected to ap-gae2.spotify.com:443" Dec 30 04:17:44 music go-librespot[13718]: time="2025-12-30T04:17:44-05:00" level=debug msg="completed keyexchange" Dec 30 04:17:44 music go-librespot[13718]: time="2025-12-30T04:17:44-05:00" level=debug msg="completed challenge" Dec 30 04:17:44 music go-librespot[13718]: time="2025-12-30T04:17:44-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 30 04:17:44 music go-librespot[13718]: time="2025-12-30T04:17:44-05:00" level=debug msg="connected to ap-gew4.spotify.com:80" Dec 30 04:17:45 music volumio[13702]: info: Starting UPNP Browser Dec 30 04:17:45 music volumio[13702]: info: Loading plugin "alarm-clock"... Dec 30 04:17:45 music go-librespot[13718]: time="2025-12-30T04:17:45-05:00" level=debug msg="completed keyexchange" Dec 30 04:17:45 music go-librespot[13718]: time="2025-12-30T04:17:45-05:00" level=debug msg="completed challenge" Dec 30 04:17:45 music volumio[13702]: info: Loading plugin "airplay_emulation"... Dec 30 04:17:45 music volumio[13702]: info: Starting Shairport Sync Dec 30 04:17:45 music go-librespot[13718]: time="2025-12-30T04:17:45-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 30 04:17:45 music go-librespot[13718]: time="2025-12-30T04:17:45-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 " Dec 30 04:17:45 music volumio[13702]: info: Loading plugin "last_100"... Dec 30 04:17:45 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 04:17:45 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 04:17:45 music volumio[13702]: info: Loading plugin "webradio"... Dec 30 04:17:45 music volumio[13702]: info: Loading plugin "i2s_dacs"... Dec 30 04:17:45 music volumio[13702]: info: I2S DAC not set, start Auto-detection Dec 30 04:17:45 music volumio[13702]: info: Loading plugin "volumiodiscovery"... Dec 30 04:17:45 music volumio[13702]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 30 04:17:45 music volumio[13702]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 30 04:17:45 music volumio[13702]: *** WARNING *** For more information see Dec 30 04:17:45 music volumio[13702]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 30 04:17:45 music volumio[13702]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 30 04:17:45 music volumio[13702]: *** WARNING *** For more information see Dec 30 04:17:45 music node[13702]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 30 04:17:45 music node[13702]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 30 04:17:45 music node[13702]: *** WARNING *** For more information see Dec 30 04:17:45 music node[13702]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 30 04:17:45 music node[13702]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 30 04:17:45 music node[13702]: *** WARNING *** For more information see Dec 30 04:17:45 music volumio[13702]: info: Applying required configuration parameters for plugin volumiodiscovery Dec 30 04:17:45 music volumio[13702]: info: Discovery: Started advertising with name: music Dec 30 04:17:45 music volumio[13702]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 30 04:17:45 music volumio[13702]: info: Loading plugin "spop"... Dec 30 04:17:46 music volumio[13702]: info: Loading plugin "outputs"... Dec 30 04:17:46 music volumio[13702]: info: Loading plugin "albumart"... Dec 30 04:17:46 music volumio[13702]: info: Plugin example_plugin is not enabled Dec 30 04:17:46 music volumio[13702]: info: Loading plugin "inputs"... Dec 30 04:17:46 music volumio[13702]: info: Loading plugin "updater_comm"... Dec 30 04:17:46 music volumio[13702]: info: Plugin mpdemulation is not enabled Dec 30 04:17:46 music volumio[13702]: info: Loading plugin "rest_api"... Dec 30 04:17:46 music volumio[13702]: info: Loading plugin "websocket"... Dec 30 04:17:46 music volumio[13702]: info: Starting Socket.io Server version 1.7.4 Dec 30 04:17:46 music volumio[13702]: info: Loading i18n strings for locale en Dec 30 04:17:46 music volumio[13702]: Updating browse sources language Dec 30 04:17:46 music volumio[13702]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 04:17:46 music volumio[13702]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 30 04:17:46 music volumio[13702]: info: CoreCommandRouter::initPlayerControls Dec 30 04:17:46 music volumio[13702]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:17:46 music volumio[13702]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:17:46 music volumio[13702]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:17:46 music volumio[13702]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:17:46 music volumio[13702]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:17:46 music volumio[13702]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:17:46 music volumio[13702]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:17:46 music volumio[13702]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:17:46 music volumio[13702]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 30 04:17:46 music volumio[13702]: Express server listening on port 3000 Dec 30 04:17:46 music volumio[13702]: [Metrics] WebUI: 6s 616.61ms Dec 30 04:17:46 music volumio[13702]: info: CoreStateMachine::resetVolumioState Dec 30 04:17:46 music volumio[13702]: info: CoreStateMachine::getcurrentVolume Dec 30 04:17:46 music volumio[13702]: info: CoreCommandRouter::volumioRetrievevolume Dec 30 04:17:47 music volumio[13702]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 04:17:47 music volumio[13702]: info: Volumio Network Manager: Network status updated: 1 Dec 30 04:17:47 music volumio-remote-updater[735]: [2025-12-30 09:17:47] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1767086263 101 Dec 30 04:17:47 music volumio[13702]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 3 Transport: websocket Total Clients: 1 Dec 30 04:17:47 music volumio[13776]: Forking 3 albumart workers Dec 30 04:17:47 music volumio[13702]: info: VolumeController:: Volume=86 Mute =false Dec 30 04:17:47 music volumio[13702]: info: CoreStateMachine::pushState Dec 30 04:17:47 music volumio[13702]: info: CorePlayQueue::getTrack 0 Dec 30 04:17:47 music volumio[13702]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 30 04:17:47 music volumio[13702]: info: CoreCommandRouter::volumioPushState Dec 30 04:17:47 music volumio[13702]: info: CoreStateMachine::updateTrackBlock Dec 30 04:17:47 music volumio[13702]: info: CorePlayQueue::getTrackBlock Dec 30 04:17:47 music volumio[13702]: info: CoreCommandRouter::volumioRetrievevolume Dec 30 04:17:47 music volumio[13702]: info: Reloading queue from file Dec 30 04:17:47 music volumio[13702]: info: CoreStateMachine::setRepeat null single undefined Dec 30 04:17:47 music volumio[13702]: info: CoreStateMachine::pushState Dec 30 04:17:47 music volumio[13702]: info: CorePlayQueue::getTrack 0 Dec 30 04:17:47 music volumio[13702]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 30 04:17:47 music volumio[13702]: info: CoreCommandRouter::volumioPushState Dec 30 04:17:47 music volumio[13702]: info: CoreStateMachine::setRandom null Dec 30 04:17:47 music volumio[13702]: info: CoreStateMachine::pushState Dec 30 04:17:47 music volumio[13702]: info: CorePlayQueue::getTrack 0 Dec 30 04:17:47 music volumio[13702]: info: CoreCommandRouter::volumioPushState Dec 30 04:17:47 music volumio[13702]: info: Setting Device type: Raspberry PI Dec 30 04:17:47 music volumio[13702]: info: VolumeController:: Volume=86 Mute =false Dec 30 04:17:47 music volumio[13702]: info: CoreStateMachine::pushState Dec 30 04:17:47 music volumio[13702]: info: CorePlayQueue::getTrack 0 Dec 30 04:17:47 music volumio[13702]: info: CoreCommandRouter::volumioPushState Dec 30 04:17:47 music volumio[13702]: info: Completed loading Core Plugins Dec 30 04:17:47 music volumio[13702]: info: Preparing to generate the ALSA configuration file Dec 30 04:17:47 music volumio[13702]: info: Discovery: adding 4a29b7a7-c637-4926-a2bd-fb4e2f55145e Dec 30 04:17:47 music volumio[13702]: info: Discovery: Found device music Dec 30 04:17:47 music volumio[13702]: info: CoreCommandRouter::volumioGetState Dec 30 04:17:47 music volumio[13702]: info: CorePlayQueue::getTrack 0 Dec 30 04:17:47 music volumio[13702]: info: Discovery: this is already registered, 4a29b7a7-c637-4926-a2bd-fb4e2f55145e Dec 30 04:17:47 music volumio[13702]: info: Discovery: Found device music Dec 30 04:17:47 music volumio[13702]: info: CoreCommandRouter::volumioGetState Dec 30 04:17:47 music volumio[13702]: info: CorePlayQueue::getTrack 0 Dec 30 04:17:47 music volumio[13702]: info: Asound.conf file unchanged, so no further update is needed Dec 30 04:17:47 music volumio[13702]: info: Output device has changed, restarting MPD Dec 30 04:17:47 music volumio[13702]: info: Output device has changed, restarting Shairport Sync Dec 30 04:17:47 music volumio[13702]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:17:47 music volumio[13702]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 04:17:47 music sudo[13831]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 30 04:17:47 music sudo[13831]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 04:17:47 music sudo[13831]: pam_unix(sudo:session): session closed for user root Dec 30 04:17:47 music sudo[13833]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 30 04:17:47 music sudo[13833]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 04:17:47 music volumio[13702]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 30 04:17:47 music volumio[13702]: info: ___________ START PLUGINS ___________ Dec 30 04:17:47 music volumio[13702]: info: ControllerMpd::onStart: Initializing MPD Dec 30 04:17:47 music volumio[13702]: info: Creating MPD Configuration file Dec 30 04:17:47 music systemd[1]: Stopping mpd.service - Music Player Daemon... Dec 30 04:17:47 music volumio[13702]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 30 04:17:47 music volumio[13702]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 04:17:47 music volumio[13702]: info: [1767086267618] CoreMusicLibrary::Adding element Media Servers Dec 30 04:17:47 music volumio[13702]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 04:17:47 music sudo[13841]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 30 04:17:47 music sudo[13841]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 04:17:47 music sudo[13843]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 30 04:17:47 music sudo[13841]: pam_unix(sudo:session): session closed for user root Dec 30 04:17:47 music sudo[13843]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 04:17:47 music volumio[13702]: info: UPNP Browser: Client initialized successfully Dec 30 04:17:47 music systemd[1]: mpd.service: Deactivated successfully. Dec 30 04:17:47 music systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 30 04:17:47 music systemd[1]: mpd.service: Consumed 4.186s CPU time. Dec 30 04:17:47 music systemd[1]: mpd.socket: Deactivated successfully. Dec 30 04:17:47 music systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 30 04:17:47 music systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 30 04:17:47 music volumio[13702]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:17:47 music volumio[13702]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 04:17:47 music volumio[13702]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 30 04:17:47 music volumio[13702]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:17:47 music volumio[13702]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 04:17:47 music systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 30 04:17:47 music systemd[1]: Starting mpd.service - Music Player Daemon... Dec 30 04:17:47 music systemd[1]: mpd.service: Deactivated successfully. Dec 30 04:17:47 music systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 30 04:17:47 music volumio[13702]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 30 04:17:47 music systemd[1]: mpd.socket: Deactivated successfully. Dec 30 04:17:47 music systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 30 04:17:47 music systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 30 04:17:47 music volumio[13702]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 04:17:47 music volumio[13702]: info: [1767086267865] CoreMusicLibrary::Adding element Last_100 Dec 30 04:17:47 music volumio[13702]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 04:17:47 music systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 30 04:17:47 music volumio[13702]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 04:17:47 music volumio[13702]: info: [1767086267873] CoreMusicLibrary::Adding element Webradio Dec 30 04:17:47 music volumio[13702]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 04:17:47 music systemd[1]: Starting mpd.service - Music Player Daemon... Dec 30 04:17:47 music volumio[13702]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 30 04:17:47 music volumio[13702]: info: Initializing BBC Radios Dec 30 04:17:48 music volumio[13702]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 30 04:17:48 music volumio[13702]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 04:17:48 music volumio[13702]: info: Creating Spotify config file Dec 30 04:17:48 music volumio[13702]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:17:48 music sudo[13857]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 30 04:17:48 music sudo[13857]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 30 04:17:48 music sudo[13857]: pam_unix(sudo:session): session closed for user root Dec 30 04:17:48 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Dec 30 04:17:48 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 04:17:48 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 04:17:48 music go-librespot[13873]: go-librespot daemon starting... Dec 30 04:17:48 music go-librespot[13874]: time="2025-12-30T04:17:48-05:00" level=info msg="running go-librespot 0.6.2" Dec 30 04:17:48 music volumio[13702]: info: Volumio Calling Home Dec 30 04:17:48 music go-librespot[13874]: time="2025-12-30T04:17:48-05:00" level=info msg="zeroconf server listening on port 39369" Dec 30 04:17:49 music volumio[13793]: Starting albumart workers Dec 30 04:17:49 music volumio[13702]: info: MPD Permissions set Dec 30 04:17:49 music volumio[13702]: info: MPD Permissions set Dec 30 04:17:49 music volumio[13702]: info: Spotify config file written Dec 30 04:17:49 music sudo[13887]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 30 04:17:49 music volumio[13795]: Starting albumart workers Dec 30 04:17:49 music sudo[13887]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 04:17:49 music volumio[13702]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Dec 30 04:17:49 music volumio[13702]: info: Volumio called home Dec 30 04:17:49 music volumio[13702]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:17:49 music volumio[13702]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:17:49 music volumio[13702]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:17:49 music volumio[13702]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:17:49 music volumio[13702]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:17:49 music volumio[13702]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:17:49 music systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Dec 30 04:17:49 music systemd[1]: go-librespot-daemon.service: Killing process 13880 (go-librespot) with signal SIGKILL. Dec 30 04:17:49 music volumio[13702]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:17:49 music systemd[1]: go-librespot-daemon.service: Deactivated successfully. Dec 30 04:17:49 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 04:17:49 music volumio[13702]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:17:49 music volumio[13702]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 04:17:49 music volumio[13702]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:17:49 music volumio[13702]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:17:49 music volumio[13702]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:17:49 music volumio[13702]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:17:49 music volumio[13702]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:17:49 music volumio[13702]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:17:49 music volumio[13702]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:17:49 music volumio[13702]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:17:49 music volumio[13702]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:17:49 music volumio[13792]: Starting albumart workers Dec 30 04:17:49 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 04:17:49 music go-librespot[13891]: go-librespot daemon starting... Dec 30 04:17:49 music volumio[13702]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 04:17:49 music volumio[13702]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:17:49 music volumio[13702]: info: No need to fix Spotify hosts Dec 30 04:17:49 music sudo[13887]: pam_unix(sudo:session): session closed for user root Dec 30 04:17:49 music go-librespot[13900]: time="2025-12-30T04:17:49-05:00" level=info msg="running go-librespot 0.6.2" Dec 30 04:17:49 music go-librespot[13900]: time="2025-12-30T04:17:49-05:00" level=debug msg="app state loaded" Dec 30 04:17:49 music go-librespot[13900]: time="2025-12-30T04:17:49-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 04:17:50 music go-librespot[13900]: time="2025-12-30T04:17:50-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]" Dec 30 04:17:50 music go-librespot[13900]: time="2025-12-30T04:17:50-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]" Dec 30 04:17:50 music go-librespot[13900]: time="2025-12-30T04:17:50-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]" Dec 30 04:17:50 music volumio[13702]: info: An error occurred while refreshing Spotify Token Error: Bad Request Dec 30 04:17:50 music go-librespot[13900]: time="2025-12-30T04:17:50-05:00" level=info msg="zeroconf server listening on port 35755" Dec 30 04:17:50 music volumio[13702]: info: Starting Shairport Sync Dec 30 04:17:50 music volumio[13702]: info: Starting Shairport Sync Dec 30 04:17:50 music volumio[13702]: info: Starting Shairport Sync Dec 30 04:17:50 music sudo[13918]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 30 04:17:50 music sudo[13918]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 04:17:50 music sudo[13920]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 30 04:17:50 music sudo[13920]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 04:17:50 music go-librespot[13900]: time="2025-12-30T04:17:50-05:00" level=debug msg="obtained new client token: AAA04uKePc7UISGIRnRYbpOYAVfdvCQaZ/0NpA4G55XdRKr4adDn9JjB8VpW2vByrm+xLQBfwSWsQQfRUo2WSrinmqT75i89gPp1Y7x+alJTM2qsgJ1wniPq8t/CFAdDsRxkv04MrFja/Rt3hFb43wq7W2n7Hu6hFDejWZi7CDh0M1oSEj2i3Fx8rFU2qPZP7UMzPLMaMlwO7C35AneMvvqhGBMFmLyAkrM3wmMFucLJj1Ikq97tq0yE" Dec 30 04:17:50 music systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 30 04:17:50 music systemd[1]: shairport-sync.service: Deactivated successfully. Dec 30 04:17:50 music systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 30 04:17:50 music systemd[1]: shairport-sync.service: Consumed 1.879s CPU time. Dec 30 04:17:50 music go-librespot[13900]: time="2025-12-30T04:17:50-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 30 04:17:50 music systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 30 04:17:50 music go-librespot[13900]: time="2025-12-30T04:17:50-05:00" level=debug msg="completed keyexchange" Dec 30 04:17:50 music go-librespot[13900]: time="2025-12-30T04:17:50-05:00" level=debug msg="completed challenge" Dec 30 04:17:50 music systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 30 04:17:50 music sudo[13918]: pam_unix(sudo:session): session closed for user root Dec 30 04:17:50 music systemd[1]: shairport-sync.service: Deactivated successfully. Dec 30 04:17:50 music systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 30 04:17:50 music go-librespot[13900]: time="2025-12-30T04:17:50-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 30 04:17:50 music systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 30 04:17:50 music sudo[13920]: pam_unix(sudo:session): session closed for user root Dec 30 04:17:50 music sudo[13924]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 30 04:17:50 music sudo[13924]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 04:17:50 music systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 30 04:17:50 music systemd[1]: shairport-sync.service: Deactivated successfully. Dec 30 04:17:50 music systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 30 04:17:50 music volumio[13702]: info: Shairport-Sync Started Dec 30 04:17:50 music volumio[13702]: Error adding Membership: Error: addMembership EINVAL Dec 30 04:17:50 music volumio[13702]: info: Shairport-Sync Started Dec 30 04:17:50 music systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 30 04:17:50 music sudo[13924]: pam_unix(sudo:session): session closed for user root Dec 30 04:17:50 music volumio[13702]: info: Shairport-Sync Started Dec 30 04:17:50 music volumio[13702]: info: CoreCommandRouter::volumioGetState Dec 30 04:17:50 music volumio[13702]: info: CorePlayQueue::getTrack 0 Dec 30 04:17:51 music go-librespot[13900]: time="2025-12-30T04:17:51-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Dec 30 04:17:51 music go-librespot[13900]: time="2025-12-30T04:17:51-05:00" level=debug msg="completed keyexchange" Dec 30 04:17:51 music go-librespot[13900]: time="2025-12-30T04:17:51-05:00" level=debug msg="completed challenge" Dec 30 04:17:51 music go-librespot[13900]: time="2025-12-30T04:17:51-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 30 04:17:51 music go-librespot[13900]: time="2025-12-30T04:17:51-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Dec 30 04:17:51 music go-librespot[13900]: time="2025-12-30T04:17:51-05:00" level=debug msg="completed keyexchange" Dec 30 04:17:51 music go-librespot[13900]: time="2025-12-30T04:17:51-05:00" level=debug msg="completed challenge" Dec 30 04:17:51 music go-librespot[13900]: time="2025-12-30T04:17:51-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 30 04:17:52 music mpd[13872]: 2025-12-30T04:17:52 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Dec 30 04:17:52 music systemd[1]: Started mpd.service - Music Player Daemon. Dec 30 04:17:52 music sudo[13843]: pam_unix(sudo:session): session closed for user root Dec 30 04:17:52 music sudo[13833]: pam_unix(sudo:session): session closed for user root Dec 30 04:17:52 music volumio[13702]: info: Completed starting Core Plugins Dec 30 04:17:52 music volumio[13702]: info: ------------------------------------------- Dec 30 04:17:52 music volumio[13702]: info: ----- MyVolumio plugins startup ---- Dec 30 04:17:52 music volumio[13702]: info: ------------------------------------------- Dec 30 04:17:52 music volumio[13702]: info: [MyVolumio PluginManager] Fetching plans data.... Dec 30 04:17:52 music volumio[13702]: error: MPD error: The expression evaluated to a falsy value: Dec 30 04:17:52 music volumio[13702]: assert.ok(self.idling) Dec 30 04:17:52 music volumio[13702]: error: The expression evaluated to a falsy value: Dec 30 04:17:52 music volumio[13702]: assert.ok(self.idling) Dec 30 04:17:52 music volumio[13702]: error: updateQueue error: null Dec 30 04:17:52 music volumio[13702]: info: MPD running with PID13872 Dec 30 04:17:52 music volumio[13702]: ,establishing connection Dec 30 04:17:52 music volumio[13702]: error: updateQueue error: null Dec 30 04:17:52 music go-librespot[13900]: time="2025-12-30T04:17:52-05:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Dec 30 04:17:52 music go-librespot[13900]: time="2025-12-30T04:17:52-05:00" level=debug msg="completed keyexchange" Dec 30 04:17:52 music go-librespot[13900]: time="2025-12-30T04:17:52-05:00" level=debug msg="completed challenge" Dec 30 04:17:53 music go-librespot[13900]: time="2025-12-30T04:17:53-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 30 04:17:53 music sudo[13989]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 30 04:17:53 music sudo[13989]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 04:17:53 music volumio[13702]: info: go-librespot daemon successfully initialized Dec 30 04:17:53 music sudo[13991]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 30 04:17:53 music sudo[13991]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 04:17:53 music sudo[13989]: pam_unix(sudo:session): session closed for user root Dec 30 04:17:53 music sudo[13991]: pam_unix(sudo:session): session closed for user root Dec 30 04:17:53 music sudo[13994]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Dec 30 04:17:53 music sudo[13994]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 04:17:53 music sudo[13994]: pam_unix(sudo:session): session closed for user root Dec 30 04:17:53 music volumio[13702]: info: Upmpdcli Daemon Started Dec 30 04:17:53 music go-librespot[13900]: time="2025-12-30T04:17:53-05:00" level=debug msg="connected to ap-gew1.spotify.com:443" Dec 30 04:17:53 music go-librespot[13900]: time="2025-12-30T04:17:53-05:00" level=debug msg="completed keyexchange" Dec 30 04:17:53 music go-librespot[13900]: time="2025-12-30T04:17:53-05:00" level=debug msg="completed challenge" Dec 30 04:17:53 music go-librespot[13900]: time="2025-12-30T04:17:53-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 30 04:17:54 music go-librespot[13900]: time="2025-12-30T04:17:54-05:00" level=debug msg="connected to ap-gew4.spotify.com:80" Dec 30 04:17:54 music go-librespot[13900]: time="2025-12-30T04:17:54-05:00" level=debug msg="completed keyexchange" Dec 30 04:17:54 music go-librespot[13900]: time="2025-12-30T04:17:54-05:00" level=debug msg="completed challenge" Dec 30 04:17:54 music go-librespot[13900]: time="2025-12-30T04:17:54-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 30 04:17:54 music go-librespot[13900]: time="2025-12-30T04:17:54-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 " Dec 30 04:17:54 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 04:17:54 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 04:17:55 music sudo[13998]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 30 04:17:55 music sudo[13998]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 04:17:55 music sudo[14000]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 30 04:17:55 music sudo[14000]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 04:17:55 music systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Dec 30 04:17:55 music systemd[1]: mpd_monitor.service: Deactivated successfully. Dec 30 04:17:55 music systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Dec 30 04:17:55 music systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Dec 30 04:17:55 music sudo[13998]: pam_unix(sudo:session): session closed for user root Dec 30 04:17:55 music sudo[14000]: pam_unix(sudo:session): session closed for user root Dec 30 04:17:55 music mpd_monitor.sh[14003]: MPD Monitor Service: Starting MPD Monitor Service Dec 30 04:17:55 music volumio[13702]: info: Successfully started MPD Monitor Dec 30 04:17:55 music volumio[13702]: info: Successfully started MPD Monitor Dec 30 04:17:56 music volumio[13702]: info: Initializing connection to go-librespot Websocket Dec 30 04:17:56 music volumio[13702]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 30 04:17:57 music volumio[13702]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Dec 30 04:17:57 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Dec 30 04:17:57 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 04:17:57 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 04:17:57 music go-librespot[14007]: go-librespot daemon starting... Dec 30 04:17:57 music go-librespot[14008]: time="2025-12-30T04:17:57-05:00" level=info msg="running go-librespot 0.6.2" Dec 30 04:17:57 music go-librespot[14008]: time="2025-12-30T04:17:57-05:00" level=debug msg="app state loaded" Dec 30 04:17:57 music go-librespot[14008]: time="2025-12-30T04:17:57-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 04:17:58 music go-librespot[14008]: time="2025-12-30T04:17:58-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]" Dec 30 04:17:58 music go-librespot[14008]: time="2025-12-30T04:17:58-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]" Dec 30 04:17:58 music go-librespot[14008]: time="2025-12-30T04:17:58-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]" Dec 30 04:17:58 music go-librespot[14008]: time="2025-12-30T04:17:58-05:00" level=info msg="zeroconf server listening on port 38577" Dec 30 04:17:58 music go-librespot[14008]: time="2025-12-30T04:17:58-05:00" level=debug msg="obtained new client token: AABt9t78LOim0+ooRDJQ4XKLBtit7FFEZlAiezoW5LwfeiaFRzFjeXwQZRhFWtL1XmLlWg94hVBoNBVzWBE1DLdG7h7mo0yUyOcqVPP+tuuTuuk/A1IRYv/6TRWwZ45IKdp4CfGeHUG+uyg3rQQfBFhR8qtqEZoR1QS2NLwN2eeSjbIIAkWeF4UcbyfzifCj+tElSyNOFJcLFd+R1BP3TL+IkD4ocKxYZbpgDBXxhxoex8g9hgBZZmba" Dec 30 04:17:58 music go-librespot[14008]: time="2025-12-30T04:17:58-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 30 04:17:58 music go-librespot[14008]: time="2025-12-30T04:17:58-05:00" level=debug msg="completed keyexchange" Dec 30 04:17:58 music go-librespot[14008]: time="2025-12-30T04:17:58-05:00" level=debug msg="completed challenge" Dec 30 04:17:58 music go-librespot[14008]: time="2025-12-30T04:17:58-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 30 04:17:59 music go-librespot[14008]: time="2025-12-30T04:17:59-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" Dec 30 04:17:59 music go-librespot[14008]: time="2025-12-30T04:17:59-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Dec 30 04:17:59 music go-librespot[14008]: time="2025-12-30T04:17:59-05:00" level=debug msg="completed keyexchange" Dec 30 04:17:59 music go-librespot[14008]: time="2025-12-30T04:17:59-05:00" level=debug msg="completed challenge" Dec 30 04:17:59 music volumio[13702]: info: Initializing connection to go-librespot Websocket Dec 30 04:17:59 music go-librespot[14008]: time="2025-12-30T04:17:59-05:00" level=debug msg="new websocket client" Dec 30 04:17:59 music volumio[13702]: info: Connection to go-librespot Websocket established Dec 30 04:17:59 music go-librespot[14008]: time="2025-12-30T04:17:59-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 30 04:17:59 music go-librespot[14008]: time="2025-12-30T04:17:59-05:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 04:17:59 music go-librespot[14008]: time="2025-12-30T04:17:59-05:00" level=debug msg="completed keyexchange" Dec 30 04:17:59 music go-librespot[14008]: time="2025-12-30T04:17:59-05:00" level=debug msg="completed challenge" Dec 30 04:17:59 music go-librespot[14008]: time="2025-12-30T04:17:59-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 30 04:18:00 music go-librespot[14008]: time="2025-12-30T04:18:00-05:00" level=debug msg="connected to ap-gew1.spotify.com:443" Dec 30 04:18:00 music volumio[13702]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Dec 30 04:18:00 music volumio[13702]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Dec 30 04:18:00 music volumio[13702]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Dec 30 04:18:00 music volumio[13702]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Dec 30 04:18:00 music volumio[13702]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Dec 30 04:18:00 music volumio[13702]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Dec 30 04:18:00 music volumio[13702]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Dec 30 04:18:00 music volumio[13702]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Dec 30 04:18:00 music volumio[13702]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Dec 30 04:18:00 music volumio[13702]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Dec 30 04:18:00 music volumio[13702]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Dec 30 04:18:00 music volumio[13702]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Dec 30 04:18:00 music volumio[13702]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Dec 30 04:18:00 music volumio[13702]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Dec 30 04:18:00 music volumio[13702]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Dec 30 04:18:00 music volumio[13702]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Dec 30 04:18:00 music volumio[13702]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Dec 30 04:18:00 music volumio[13702]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Dec 30 04:18:00 music volumio[13702]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Dec 30 04:18:00 music volumio[13702]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Dec 30 04:18:00 music volumio[13702]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Dec 30 04:18:00 music volumio[13702]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Dec 30 04:18:00 music volumio[13702]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Dec 30 04:18:00 music volumio[13702]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Dec 30 04:18:00 music volumio[13702]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Dec 30 04:18:00 music volumio[13702]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Dec 30 04:18:00 music volumio[13702]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Dec 30 04:18:00 music volumio[13702]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Dec 30 04:18:00 music volumio[13702]: info: Adding plugin bluetooth to MyMusic Plugins Dec 30 04:18:00 music volumio[13702]: info: Adding plugin multiroom to MyMusic Plugins Dec 30 04:18:00 music volumio[13702]: info: Adding plugin metavolumio to MyMusic Plugins Dec 30 04:18:00 music volumio[13702]: info: Adding plugin cd_controller to MyMusic Plugins Dec 30 04:18:00 music volumio[13702]: info: Adding plugin qobuzconnect to MyMusic Plugins Dec 30 04:18:00 music volumio[13702]: info: Adding plugin smart_inputs to MyMusic Plugins Dec 30 04:18:00 music volumio[13702]: info: Adding plugin tidalconnect to MyMusic Plugins Dec 30 04:18:00 music volumio[13702]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Dec 30 04:18:00 music go-librespot[14008]: time="2025-12-30T04:18:00-05:00" level=debug msg="completed keyexchange" Dec 30 04:18:00 music go-librespot[14008]: time="2025-12-30T04:18:00-05:00" level=debug msg="completed challenge" Dec 30 04:18:01 music go-librespot[14008]: time="2025-12-30T04:18:01-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 30 04:18:01 music go-librespot[14008]: time="2025-12-30T04:18:01-05:00" level=debug msg="connected to ap-gew4.spotify.com:80" Dec 30 04:18:01 music volumio[13702]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Dec 30 04:18:01 music volumio[13702]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Dec 30 04:18:01 music volumio[13702]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 04:18:01 music volumio[13702]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 04:18:01 music volumio[13702]: info: Starting MyVolumio Remote Streaming Endpoints Dec 30 04:18:01 music volumio[13702]: info: MyVolumio login type: Token Dec 30 04:18:01 music volumio[13702]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Dec 30 04:18:01 music volumio[13702]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Dec 30 04:18:01 music go-librespot[14008]: time="2025-12-30T04:18:01-05:00" level=debug msg="completed keyexchange" Dec 30 04:18:01 music go-librespot[14008]: time="2025-12-30T04:18:01-05:00" level=debug msg="completed challenge" Dec 30 04:18:01 music go-librespot[14008]: time="2025-12-30T04:18:01-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 30 04:18:02 music go-librespot[14008]: time="2025-12-30T04:18:02-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 30 04:18:02 music volumio[13702]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Dec 30 04:18:02 music volumio[13702]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Dec 30 04:18:02 music volumio[13702]: info: Streaming services startup Dec 30 04:18:02 music volumio[13702]: info: Starting Streaming Daemon Dec 30 04:18:02 music sudo[14018]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Dec 30 04:18:02 music sudo[14018]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 04:18:02 music volumio[13702]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Dec 30 04:18:02 music sudo[14018]: pam_unix(sudo:session): session closed for user root Dec 30 04:18:02 music volumio[13702]: info: Getting Spotify volume Dec 30 04:18:02 music volumio[13702]: error: Cannot start Volumio Streaming Daemon Dec 30 04:18:02 music volumio[13702]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Dec 30 04:18:02 music volumio[13702]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Dec 30 04:18:02 music volumio[13702]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Dec 30 04:18:02 music volumio[13702]: info: CoreCommandRouter::volumioGetState Dec 30 04:18:02 music volumio[13702]: info: CorePlayQueue::getTrack 0 Dec 30 04:18:03 music volumio[13702]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Dec 30 04:18:03 music volumio[13702]: SPOTIFY: SPOTIFY VOLUME undefined Dec 30 04:18:03 music volumio[13702]: SPOTIFY: VOLUMIO VOLUME 86 Dec 30 04:18:03 music volumio[13702]: info: Aligning Spotify Volume to Volumio Volume Dec 30 04:18:03 music volumio[13702]: info: CoreCommandRouter::volumioGetState Dec 30 04:18:03 music volumio[13702]: info: CorePlayQueue::getTrack 0 Dec 30 04:18:03 music volumio[13702]: info: Setting Spotify Volume from Volumio: 86 Dec 30 04:18:03 music volumio[13702]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Dec 30 04:18:03 music volumio[13702]: info: MyVolumio token set successfully Dec 30 04:18:03 music volumio[13702]: info: MYVOLUMIO: Adding device Dec 30 04:18:03 music volumio[13702]: info: MYVOLUMIO: Evaluating Server Dec 30 04:18:03 music volumio[13702]: info: MyVolumio status changed Dec 30 04:18:03 music volumio[13702]: info: Streaming services startup Dec 30 04:18:03 music volumio[13702]: info: Starting Streaming Daemon Dec 30 04:18:03 music volumio[13702]: info: Removing browser output: myVolumio user plan is not superstar Dec 30 04:18:03 music volumio[13702]: info: Removing audio output: Dec 30 04:18:03 music volumio[13702]: info: Stoppping Tunnel 1 Dec 30 04:18:03 music sudo[14060]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Dec 30 04:18:03 music sudo[14060]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 04:18:03 music sudo[14062]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service Dec 30 04:18:03 music sudo[14062]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 04:18:04 music systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Dec 30 04:18:04 music systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Dec 30 04:18:04 music sudo[14060]: pam_unix(sudo:session): session closed for user root Dec 30 04:18:04 music volumio[13702]: error: Cannot start Volumio Streaming Daemon Dec 30 04:18:04 music volumio[13702]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Dec 30 04:18:04 music volumio[13702]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Dec 30 04:18:04 music systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Dec 30 04:18:04 music systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Dec 30 04:18:04 music systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Dec 30 04:18:04 music systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Dec 30 04:18:04 music sudo[14062]: pam_unix(sudo:session): session closed for user root Dec 30 04:18:04 music volumio[13702]: info: Remote SSH Stopped Dec 30 04:18:04 music go-librespot[14008]: time="2025-12-30T04:18:04-05:00" level=debug msg="completed keyexchange" Dec 30 04:18:04 music go-librespot[14008]: time="2025-12-30T04:18:04-05:00" level=debug msg="completed challenge" Dec 30 04:18:04 music go-librespot[14008]: time="2025-12-30T04:18:04-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 30 04:18:04 music go-librespot[14008]: time="2025-12-30T04:18:04-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Dec 30 04:18:04 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 04:18:04 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 04:18:04 music volumio[13702]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 30 04:18:04 music volumio[13702]: Error: socket hang up Dec 30 04:18:04 music volumio[13702]: at connResetException (node:internal/errors:720:14) Dec 30 04:18:04 music volumio[13702]: at Socket.socketOnEnd (node:_http_client:519:23) Dec 30 04:18:04 music volumio[13702]: at Socket.emit (node:events:526:35) Dec 30 04:18:04 music volumio[13702]: at endReadableNT (node:internal/streams/readable:1376:12) Dec 30 04:18:04 music volumio[13702]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { Dec 30 04:18:04 music volumio[13702]: code: 'ECONNRESET', Dec 30 04:18:04 music volumio[13702]: response: undefined Dec 30 04:18:04 music volumio[13702]: } Dec 30 04:18:04 music volumio[13702]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 30 04:18:05 music sudo[14079]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-30 04:17' Dec 30 04:18:05 music sudo[14079]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 04:18:05 music sudo[14079]: pam_unix(sudo:session): session closed for user root Dec 30 04:18:05 music volumio-remote-updater[735]: [2025-12-30 09:18:05] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Dec 30 04:18:05 music volumio-remote-updater[735]: [2025-12-30 09:18:05] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Dec 30 04:18:05 music systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Dec 30 04:18:05 music systemd[1]: volumio.service: Failed with result 'exit-code'. Dec 30 04:18:05 music systemd[1]: volumio.service: Consumed 27.671s CPU time. Dec 30 04:18:06 music systemd[1]: Started dynamicswap.service - dynamicswap service. Dec 30 04:18:06 music systemd[1]: dynamicswap.service: Deactivated successfully. Dec 30 04:18:06 music systemd[1]: volumio.service: Scheduled restart job, restart counter is at 8375. Dec 30 04:18:06 music systemd[1]: Started dynamicswap.service - dynamicswap service. Dec 30 04:18:06 music systemd[1]: Stopped volumio.service - Volumio Backend Module. Dec 30 04:18:06 music systemd[1]: volumio.service: Consumed 27.671s CPU time. Dec 30 04:18:06 music systemd[1]: Started volumio.service - Volumio Backend Module. Dec 30 04:18:06 music systemd[1]: dynamicswap.service: Deactivated successfully. Dec 30 04:18:07 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Dec 30 04:18:07 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 04:18:07 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 04:18:07 music go-librespot[14110]: go-librespot daemon starting... Dec 30 04:18:07 music go-librespot[14111]: time="2025-12-30T04:18:07-05:00" level=info msg="running go-librespot 0.6.2" Dec 30 04:18:07 music go-librespot[14111]: time="2025-12-30T04:18:07-05:00" level=debug msg="app state loaded" Dec 30 04:18:07 music go-librespot[14111]: time="2025-12-30T04:18:07-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 04:18:07 music go-librespot[14111]: time="2025-12-30T04:18: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]" Dec 30 04:18:07 music go-librespot[14111]: time="2025-12-30T04:18: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]" Dec 30 04:18:07 music go-librespot[14111]: time="2025-12-30T04:18: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]" Dec 30 04:18:07 music go-librespot[14111]: time="2025-12-30T04:18:07-05:00" level=info msg="zeroconf server listening on port 39941" Dec 30 04:18:07 music go-librespot[14111]: time="2025-12-30T04:18:07-05:00" level=debug msg="obtained new client token: AADcinWDPELOOmtMBXipsyO80osgznZD4tiPYGmtn05j4O/wxOYH+PO+MkOTMPTxYC923XAjWpiI+SIwtDNvNZZRE84oSJBfl58hzIIXsR/2giHgbxHEXD3sf+OErvQjBahS+iuf2fKz9rpl2NXAXeFgpP2gnXWEwKyOCT/2CB6eY2+1srwB61zbjehYswqLWvWj59XSvLKPCTIQdfy+oW/vyrZnh6QB5MsrFic0LedEBxf3l6YyHs17" Dec 30 04:18:08 music go-librespot[14111]: time="2025-12-30T04:18:08-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 30 04:18:08 music go-librespot[14111]: time="2025-12-30T04:18:08-05:00" level=debug msg="completed keyexchange" Dec 30 04:18:08 music go-librespot[14111]: time="2025-12-30T04:18:08-05:00" level=debug msg="completed challenge" Dec 30 04:18:08 music volumio[14095]: info: ------------------------------------------- Dec 30 04:18:08 music go-librespot[14111]: time="2025-12-30T04:18:08-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 30 04:18:08 music volumio[14095]: info: ----- Volumio3 ---- Dec 30 04:18:08 music volumio[14095]: info: ------------------------------------------- Dec 30 04:18:08 music volumio[14095]: info: ----- System startup ---- Dec 30 04:18:08 music volumio[14095]: info: ------------------------------------------- Dec 30 04:18:08 music go-librespot[14111]: time="2025-12-30T04:18:08-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Dec 30 04:18:08 music go-librespot[14111]: time="2025-12-30T04:18:08-05:00" level=debug msg="completed keyexchange" Dec 30 04:18:08 music go-librespot[14111]: time="2025-12-30T04:18:08-05:00" level=debug msg="completed challenge" Dec 30 04:18:08 music go-librespot[14111]: time="2025-12-30T04:18:08-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 30 04:18:08 music volumio[14095]: info: MYVOLUMIO Environment detected Dec 30 04:18:08 music volumio[14095]: info: Plugin folders cleanup Dec 30 04:18:08 music volumio[14095]: info: Scanning into folder /volumio/app/plugins/ Dec 30 04:18:08 music volumio[14095]: info: Scanning category audio_interface Dec 30 04:18:08 music volumio[14095]: info: Scanning category miscellanea Dec 30 04:18:08 music volumio[14095]: info: Scanning category music_service Dec 30 04:18:08 music volumio[14095]: info: Scanning category plugins.json Dec 30 04:18:08 music volumio[14095]: info: Scanning category system_controller Dec 30 04:18:09 music volumio[14095]: info: Scanning category user_interface Dec 30 04:18:09 music volumio[14095]: info: Scanning into folder /data/plugins/ Dec 30 04:18:09 music volumio[14095]: info: Scanning category music_service Dec 30 04:18:09 music volumio[14095]: info: Plugin folders cleanup completed Dec 30 04:18:09 music volumio[14095]: info: ------------------------------------------- Dec 30 04:18:09 music volumio[14095]: info: ----- Core plugins startup ---- Dec 30 04:18:09 music volumio[14095]: info: ------------------------------------------- Dec 30 04:18:09 music volumio[14095]: info: Loading plugins from folder /volumio/app/plugins/ Dec 30 04:18:09 music volumio[14095]: info: Adding plugin upnp to MyMusic Plugins Dec 30 04:18:09 music volumio[14095]: info: Adding plugin airplay_emulation to MyMusic Plugins Dec 30 04:18:09 music volumio[14095]: info: Adding plugin upnp_browser to MyMusic Plugins Dec 30 04:18:09 music volumio[14095]: info: Loading plugins from folder /data/plugins/ Dec 30 04:18:09 music volumio[14095]: info: Loading plugin "system"... Dec 30 04:18:09 music volumio[14095]: info: Loading plugin "appearance"... Dec 30 04:18:09 music go-librespot[14111]: time="2025-12-30T04:18:09-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Dec 30 04:18:09 music go-librespot[14111]: time="2025-12-30T04:18:09-05:00" level=debug msg="completed keyexchange" Dec 30 04:18:09 music go-librespot[14111]: time="2025-12-30T04:18:09-05:00" level=debug msg="completed challenge" Dec 30 04:18:09 music go-librespot[14111]: time="2025-12-30T04:18:09-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 30 04:18:10 music go-librespot[14111]: time="2025-12-30T04:18:10-05:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 04:18:10 music go-librespot[14111]: time="2025-12-30T04:18:10-05:00" level=debug msg="completed keyexchange" Dec 30 04:18:10 music go-librespot[14111]: time="2025-12-30T04:18:10-05:00" level=debug msg="completed challenge" Dec 30 04:18:10 music volumio[14095]: info: Loading plugin "network"... Dec 30 04:18:10 music volumio[14095]: info: Refreshing Cached IP Addresses Dec 30 04:18:10 music go-librespot[14111]: time="2025-12-30T04:18:10-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 30 04:18:10 music sudo[14134]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 30 04:18:10 music sudo[14134]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 04:18:10 music sudo[14134]: pam_unix(sudo:session): session closed for user root Dec 30 04:18:10 music sudo[14136]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 30 04:18:10 music sudo[14136]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 04:18:10 music volumio[14095]: info: Loading plugin "services"... Dec 30 04:18:10 music sudo[14136]: pam_unix(sudo:session): session closed for user root Dec 30 04:18:10 music volumio[14095]: info: Loading plugin "alsa_controller"... Dec 30 04:18:10 music sudo[14144]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Dec 30 04:18:10 music sudo[14144]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 04:18:10 music volumio[14095]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 30 04:18:10 music volumio[14095]: info: Loading plugin "wizard"... Dec 30 04:18:10 music volumio[14095]: info: Loading plugin "networkfs"... Dec 30 04:18:10 music volumio[14095]: info: Starting Udev Watcher for removable devices Dec 30 04:18:10 music volumio[14095]: info: Ignoring mount for partition: boot Dec 30 04:18:10 music volumio[14095]: info: Ignoring mount for partition: volumio Dec 30 04:18:10 music volumio[14095]: info: Ignoring mount for partition: volumio_data Dec 30 04:18:10 music volumio[14095]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 30 04:18:10 music volumio[14095]: info: Loading plugin "volumio_command_line_client"... Dec 30 04:18:10 music volumio[14095]: info: Loading plugin "upnp"... Dec 30 04:18:10 music volumio[14095]: info: [1767086290377] Starting Upmpd Daemon Dec 30 04:18:10 music volumio[14095]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 30 04:18:10 music volumio[14095]: info: Loading plugin "my_music"... Dec 30 04:18:10 music volumio[14095]: info: Loading plugin "mpd"... Dec 30 04:18:10 music volumio[14095]: info: Loading plugin "upnp_browser"... Dec 30 04:18:10 music go-librespot[14111]: time="2025-12-30T04:18:10-05:00" level=debug msg="connected to ap-gew1.spotify.com:443" Dec 30 04:18:10 music sudo[14144]: pam_unix(sudo:session): session closed for user root Dec 30 04:18:10 music volumio-remote-updater[735]: [2025-12-30 09:18:10] [connect] Successful connection Dec 30 04:18:11 music go-librespot[14111]: time="2025-12-30T04:18:11-05:00" level=debug msg="completed keyexchange" Dec 30 04:18:11 music go-librespot[14111]: time="2025-12-30T04:18:11-05:00" level=debug msg="completed challenge" Dec 30 04:18:11 music go-librespot[14111]: time="2025-12-30T04:18:11-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 30 04:18:11 music go-librespot[14111]: time="2025-12-30T04:18:11-05:00" level=debug msg="connected to ap-gew4.spotify.com:80" Dec 30 04:18:11 music go-librespot[14111]: time="2025-12-30T04:18:11-05:00" level=debug msg="completed keyexchange" Dec 30 04:18:11 music go-librespot[14111]: time="2025-12-30T04:18:11-05:00" level=debug msg="completed challenge" Dec 30 04:18:11 music go-librespot[14111]: time="2025-12-30T04:18:11-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 30 04:18:11 music go-librespot[14111]: time="2025-12-30T04:18: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 " Dec 30 04:18:11 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 04:18:11 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 04:18:12 music volumio[14095]: info: Starting UPNP Browser Dec 30 04:18:12 music volumio[14095]: info: Loading plugin "alarm-clock"... Dec 30 04:18:12 music volumio[14095]: info: Loading plugin "airplay_emulation"... Dec 30 04:18:12 music volumio[14095]: info: Starting Shairport Sync Dec 30 04:18:12 music volumio[14095]: info: Loading plugin "last_100"... Dec 30 04:18:12 music volumio[14095]: info: Loading plugin "webradio"... Dec 30 04:18:12 music volumio[14095]: info: Loading plugin "i2s_dacs"... Dec 30 04:18:12 music volumio[14095]: info: I2S DAC not set, start Auto-detection Dec 30 04:18:12 music volumio[14095]: info: Loading plugin "volumiodiscovery"... Dec 30 04:18:12 music volumio[14095]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 30 04:18:12 music volumio[14095]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 30 04:18:12 music volumio[14095]: *** WARNING *** For more information see Dec 30 04:18:12 music volumio[14095]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 30 04:18:12 music volumio[14095]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 30 04:18:12 music volumio[14095]: *** WARNING *** For more information see Dec 30 04:18:12 music node[14095]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 30 04:18:12 music node[14095]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 30 04:18:12 music node[14095]: *** WARNING *** For more information see Dec 30 04:18:12 music node[14095]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 30 04:18:12 music node[14095]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 30 04:18:12 music node[14095]: *** WARNING *** For more information see Dec 30 04:18:12 music volumio[14095]: info: Applying required configuration parameters for plugin volumiodiscovery Dec 30 04:18:12 music volumio[14095]: info: Discovery: Started advertising with name: music Dec 30 04:18:12 music volumio[14095]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 30 04:18:12 music volumio[14095]: info: Loading plugin "spop"... Dec 30 04:18:13 music volumio[14095]: info: Loading plugin "outputs"... Dec 30 04:18:13 music volumio[14095]: info: Loading plugin "albumart"... Dec 30 04:18:13 music volumio[14095]: info: Plugin example_plugin is not enabled Dec 30 04:18:13 music volumio[14095]: info: Loading plugin "inputs"... Dec 30 04:18:13 music volumio[14095]: info: Loading plugin "updater_comm"... Dec 30 04:18:13 music volumio[14095]: info: Plugin mpdemulation is not enabled Dec 30 04:18:13 music volumio[14095]: info: Loading plugin "rest_api"... Dec 30 04:18:13 music volumio[14095]: info: Loading plugin "websocket"... Dec 30 04:18:13 music volumio[14095]: info: Starting Socket.io Server version 1.7.4 Dec 30 04:18:14 music volumio[14095]: info: Loading i18n strings for locale en Dec 30 04:18:14 music volumio[14095]: Updating browse sources language Dec 30 04:18:14 music volumio[14095]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 04:18:14 music volumio[14095]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 30 04:18:14 music volumio[14095]: info: CoreCommandRouter::initPlayerControls Dec 30 04:18:14 music volumio[14095]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:18:14 music volumio[14095]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:18:14 music volumio[14095]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:18:14 music volumio[14095]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:18:14 music volumio[14095]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:18:14 music volumio[14095]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:18:14 music volumio[14095]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:18:14 music volumio[14095]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:18:14 music volumio[14095]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 30 04:18:14 music volumio[14095]: Express server listening on port 3000 Dec 30 04:18:14 music volumio[14095]: [Metrics] WebUI: 6s 609.30ms Dec 30 04:18:14 music volumio[14095]: info: CoreStateMachine::resetVolumioState Dec 30 04:18:14 music volumio[14095]: info: CoreStateMachine::getcurrentVolume Dec 30 04:18:14 music volumio[14095]: info: CoreCommandRouter::volumioRetrievevolume Dec 30 04:18:14 music volumio[14095]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 04:18:14 music volumio[14095]: info: Volumio Network Manager: Network status updated: 1 Dec 30 04:18:14 music volumio[14170]: Forking 3 albumart workers Dec 30 04:18:14 music volumio-remote-updater[735]: [2025-12-30 09:18:14] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1767086290 101 Dec 30 04:18:14 music volumio[14095]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 3 Transport: websocket Total Clients: 1 Dec 30 04:18:14 music volumio[14095]: info: VolumeController:: Volume=86 Mute =false Dec 30 04:18:14 music volumio[14095]: info: CoreStateMachine::pushState Dec 30 04:18:14 music volumio[14095]: info: CorePlayQueue::getTrack 0 Dec 30 04:18:14 music volumio[14095]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 30 04:18:14 music volumio[14095]: info: CoreCommandRouter::volumioPushState Dec 30 04:18:14 music volumio[14095]: info: CoreStateMachine::updateTrackBlock Dec 30 04:18:14 music volumio[14095]: info: CorePlayQueue::getTrackBlock Dec 30 04:18:14 music volumio[14095]: info: CoreCommandRouter::volumioRetrievevolume Dec 30 04:18:14 music volumio[14095]: info: Reloading queue from file Dec 30 04:18:14 music volumio[14095]: info: CoreStateMachine::setRepeat null single undefined Dec 30 04:18:14 music volumio[14095]: info: CoreStateMachine::pushState Dec 30 04:18:14 music volumio[14095]: info: CorePlayQueue::getTrack 0 Dec 30 04:18:14 music volumio[14095]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 30 04:18:14 music volumio[14095]: info: CoreCommandRouter::volumioPushState Dec 30 04:18:14 music volumio[14095]: info: CoreStateMachine::setRandom null Dec 30 04:18:14 music volumio[14095]: info: CoreStateMachine::pushState Dec 30 04:18:14 music volumio[14095]: info: CorePlayQueue::getTrack 0 Dec 30 04:18:14 music volumio[14095]: info: CoreCommandRouter::volumioPushState Dec 30 04:18:14 music volumio[14095]: info: Setting Device type: Raspberry PI Dec 30 04:18:14 music volumio[14095]: info: VolumeController:: Volume=86 Mute =false Dec 30 04:18:14 music volumio[14095]: info: CoreStateMachine::pushState Dec 30 04:18:14 music volumio[14095]: info: CorePlayQueue::getTrack 0 Dec 30 04:18:14 music volumio[14095]: info: CoreCommandRouter::volumioPushState Dec 30 04:18:14 music volumio[14095]: info: Discovery: adding 4a29b7a7-c637-4926-a2bd-fb4e2f55145e Dec 30 04:18:14 music volumio[14095]: info: Discovery: Found device music Dec 30 04:18:14 music volumio[14095]: info: CoreCommandRouter::volumioGetState Dec 30 04:18:14 music volumio[14095]: info: CorePlayQueue::getTrack 0 Dec 30 04:18:14 music volumio[14095]: info: Discovery: this is already registered, 4a29b7a7-c637-4926-a2bd-fb4e2f55145e Dec 30 04:18:14 music volumio[14095]: info: Discovery: Found device music Dec 30 04:18:14 music volumio[14095]: info: CoreCommandRouter::volumioGetState Dec 30 04:18:14 music volumio[14095]: info: CorePlayQueue::getTrack 0 Dec 30 04:18:14 music volumio[14095]: info: Completed loading Core Plugins Dec 30 04:18:14 music volumio[14095]: info: Preparing to generate the ALSA configuration file Dec 30 04:18:14 music volumio[14095]: info: Asound.conf file unchanged, so no further update is needed Dec 30 04:18:14 music volumio[14095]: info: Output device has changed, restarting MPD Dec 30 04:18:14 music volumio[14095]: info: Output device has changed, restarting Shairport Sync Dec 30 04:18:14 music volumio[14095]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:18:14 music volumio[14095]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 04:18:14 music sudo[14225]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 30 04:18:14 music sudo[14225]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 04:18:14 music volumio[14095]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 30 04:18:14 music volumio[14095]: info: ___________ START PLUGINS ___________ Dec 30 04:18:14 music volumio[14095]: info: ControllerMpd::onStart: Initializing MPD Dec 30 04:18:14 music volumio[14095]: info: Creating MPD Configuration file Dec 30 04:18:14 music sudo[14227]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 30 04:18:14 music sudo[14227]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 04:18:14 music sudo[14225]: pam_unix(sudo:session): session closed for user root Dec 30 04:18:14 music volumio[14095]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 30 04:18:14 music volumio[14095]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 04:18:14 music volumio[14095]: info: [1767086294845] CoreMusicLibrary::Adding element Media Servers Dec 30 04:18:14 music volumio[14095]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 04:18:14 music sudo[14234]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 30 04:18:14 music volumio[14095]: info: UPNP Browser: Client initialized successfully Dec 30 04:18:14 music sudo[14234]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 04:18:14 music sudo[14237]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 30 04:18:14 music sudo[14237]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 04:18:14 music sudo[14234]: pam_unix(sudo:session): session closed for user root Dec 30 04:18:14 music systemd[1]: Stopping mpd.service - Music Player Daemon... Dec 30 04:18:14 music volumio[14095]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:18:14 music volumio[14095]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 04:18:14 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Dec 30 04:18:15 music volumio[14095]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 30 04:18:15 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 04:18:15 music volumio[14095]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:18:15 music volumio[14095]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 04:18:15 music volumio[14095]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 30 04:18:15 music volumio[14095]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 04:18:15 music volumio[14095]: info: [1767086295057] CoreMusicLibrary::Adding element Last_100 Dec 30 04:18:15 music volumio[14095]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 04:18:15 music volumio[14095]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 04:18:15 music volumio[14095]: info: [1767086295075] CoreMusicLibrary::Adding element Webradio Dec 30 04:18:15 music volumio[14095]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 04:18:15 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 04:18:15 music go-librespot[14244]: go-librespot daemon starting... Dec 30 04:18:15 music systemd[1]: mpd.service: Deactivated successfully. Dec 30 04:18:15 music systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 30 04:18:15 music systemd[1]: mpd.service: Consumed 4.235s CPU time. Dec 30 04:18:15 music systemd[1]: mpd.socket: Deactivated successfully. Dec 30 04:18:15 music systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 30 04:18:15 music systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 30 04:18:15 music volumio[14095]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 30 04:18:15 music systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 30 04:18:15 music volumio[14095]: info: Initializing BBC Radios Dec 30 04:18:15 music systemd[1]: Starting mpd.service - Music Player Daemon... Dec 30 04:18:15 music go-librespot[14249]: time="2025-12-30T04:18:15-05:00" level=info msg="running go-librespot 0.6.2" Dec 30 04:18:15 music go-librespot[14249]: time="2025-12-30T04:18:15-05:00" level=debug msg="app state loaded" Dec 30 04:18:15 music go-librespot[14249]: time="2025-12-30T04:18:15-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 04:18:15 music volumio[14095]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 30 04:18:15 music volumio[14095]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 04:18:15 music volumio[14095]: info: Creating Spotify config file Dec 30 04:18:15 music volumio[14095]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:18:15 music sudo[14256]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 30 04:18:15 music sudo[14256]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 30 04:18:15 music sudo[14256]: pam_unix(sudo:session): session closed for user root Dec 30 04:18:15 music go-librespot[14249]: time="2025-12-30T04:18:15-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew1.spotify.com:80]" Dec 30 04:18:15 music go-librespot[14249]: time="2025-12-30T04:18:15-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]" Dec 30 04:18:15 music go-librespot[14249]: time="2025-12-30T04:18:15-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]" Dec 30 04:18:15 music go-librespot[14249]: time="2025-12-30T04:18:15-05:00" level=info msg="zeroconf server listening on port 36285" Dec 30 04:18:15 music go-librespot[14249]: time="2025-12-30T04:18:15-05:00" level=debug msg="obtained new client token: AAC2BSt7+kwMthlS8sL1FZ/Gl5i+Theps34sWA+duHNqoTsqHBbxU+u8Y15GYPL4W8IfO6AoZ3BfW8NtrxzVIqR6lQLuoRmZFpHnffclzGj0PwG7emhZ5t5BBedXpoJE6U1kQ+g7J/Gm4kgFzisQtKmFcB2Y3SERSLf61MNvmfAYs3dJNFGIz6ZMsHJ5L41olJMLS6EcRN0Kb7IVhZzzjikj9DbMha5HHWBd8J5xZD+ONjTCs2dQ91H+" Dec 30 04:18:15 music go-librespot[14249]: time="2025-12-30T04:18:15-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 30 04:18:15 music go-librespot[14249]: time="2025-12-30T04:18:15-05:00" level=debug msg="completed keyexchange" Dec 30 04:18:15 music go-librespot[14249]: time="2025-12-30T04:18:15-05:00" level=debug msg="completed challenge" Dec 30 04:18:15 music go-librespot[14249]: time="2025-12-30T04:18:15-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 30 04:18:16 music volumio[14095]: info: Volumio Calling Home Dec 30 04:18:16 music volumio[14188]: Starting albumart workers Dec 30 04:18:16 music volumio[14186]: Starting albumart workers Dec 30 04:18:16 music volumio[14187]: Starting albumart workers Dec 30 04:18:16 music go-librespot[14249]: time="2025-12-30T04:18:16-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Dec 30 04:18:16 music go-librespot[14249]: time="2025-12-30T04:18:16-05:00" level=debug msg="completed keyexchange" Dec 30 04:18:16 music go-librespot[14249]: time="2025-12-30T04:18:16-05:00" level=debug msg="completed challenge" Dec 30 04:18:16 music go-librespot[14249]: time="2025-12-30T04:18:16-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 30 04:18:16 music volumio[14095]: info: MPD Permissions set Dec 30 04:18:16 music volumio[14095]: info: MPD Permissions set Dec 30 04:18:16 music volumio[14095]: info: Volumio called home Dec 30 04:18:16 music volumio[14095]: info: Spotify config file written Dec 30 04:18:16 music sudo[14281]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 30 04:18:16 music sudo[14281]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 04:18:17 music systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Dec 30 04:18:17 music systemd[1]: go-librespot-daemon.service: Deactivated successfully. Dec 30 04:18:17 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 04:18:17 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 04:18:17 music go-librespot[14283]: go-librespot daemon starting... Dec 30 04:18:17 music sudo[14281]: pam_unix(sudo:session): session closed for user root Dec 30 04:18:17 music go-librespot[14284]: time="2025-12-30T04:18:17-05:00" level=info msg="running go-librespot 0.6.2" Dec 30 04:18:17 music go-librespot[14284]: time="2025-12-30T04:18:17-05:00" level=debug msg="app state loaded" Dec 30 04:18:17 music go-librespot[14284]: time="2025-12-30T04:18:17-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 04:18:17 music volumio[14095]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Dec 30 04:18:17 music volumio[14095]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:18:17 music volumio[14095]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:18:17 music volumio[14095]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:18:17 music volumio[14095]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:18:17 music volumio[14095]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:18:17 music volumio[14095]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:18:17 music volumio[14095]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:18:17 music volumio[14095]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:18:17 music volumio[14095]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 04:18:17 music volumio[14095]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:18:17 music volumio[14095]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:18:17 music volumio[14095]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:18:17 music volumio[14095]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:18:17 music volumio[14095]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:18:17 music volumio[14095]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:18:17 music volumio[14095]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:18:17 music go-librespot[14284]: time="2025-12-30T04:18:17-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew1.spotify.com:80]" Dec 30 04:18:17 music go-librespot[14284]: time="2025-12-30T04:18:17-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]" Dec 30 04:18:17 music go-librespot[14284]: time="2025-12-30T04:18:17-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]" Dec 30 04:18:17 music volumio[14095]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:18:17 music volumio[14095]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:18:17 music go-librespot[14284]: time="2025-12-30T04:18:17-05:00" level=info msg="zeroconf server listening on port 46055" Dec 30 04:18:17 music volumio[14095]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 04:18:17 music volumio[14095]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:18:17 music volumio[14095]: info: No need to fix Spotify hosts Dec 30 04:18:17 music go-librespot[14284]: time="2025-12-30T04:18:17-05:00" level=debug msg="obtained new client token: AACcEuZ4IysJ3MhbxSr2eMtuzdlLfSNMr+51QH0uhYOyLJBstr946uxE3a3fDYOr2bWUIhAARCKsFaNF4lDs6FOn2/yZ/J+yinY4z/ZexbFxyDi3IWSGRSXESvhbwqROJzlhOf2DkK+OW2LG3WURe+s9ctcMxsrnhK7hvajPbjdNm2Kd5BFqf/K0mzZA0H2ve6FmsMmA4sRKW5UTgI9JVe4E1FX68NU/IAXCuClA3SXQeYhKqzTaqA6h" Dec 30 04:18:17 music go-librespot[14284]: time="2025-12-30T04:18:17-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 30 04:18:17 music volumio[14095]: info: An error occurred while refreshing Spotify Token Error: Bad Request Dec 30 04:18:17 music volumio[14095]: info: Starting Shairport Sync Dec 30 04:18:17 music volumio[14095]: info: Starting Shairport Sync Dec 30 04:18:17 music go-librespot[14284]: time="2025-12-30T04:18:17-05:00" level=debug msg="completed keyexchange" Dec 30 04:18:17 music go-librespot[14284]: time="2025-12-30T04:18:17-05:00" level=debug msg="completed challenge" Dec 30 04:18:17 music sudo[14316]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 30 04:18:17 music sudo[14316]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 04:18:17 music volumio[14095]: info: Starting Shairport Sync Dec 30 04:18:17 music sudo[14319]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 30 04:18:17 music sudo[14319]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 04:18:17 music go-librespot[14284]: time="2025-12-30T04:18:17-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 30 04:18:17 music systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 30 04:18:17 music sudo[14321]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 30 04:18:17 music systemd[1]: shairport-sync.service: Deactivated successfully. Dec 30 04:18:17 music systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 30 04:18:17 music systemd[1]: shairport-sync.service: Consumed 1.866s CPU time. Dec 30 04:18:17 music sudo[14321]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 04:18:18 music systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 30 04:18:18 music sudo[14316]: pam_unix(sudo:session): session closed for user root Dec 30 04:18:18 music systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 30 04:18:18 music systemd[1]: shairport-sync.service: Deactivated successfully. Dec 30 04:18:18 music systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 30 04:18:18 music systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 30 04:18:18 music sudo[14319]: pam_unix(sudo:session): session closed for user root Dec 30 04:18:18 music sudo[14321]: pam_unix(sudo:session): session closed for user root Dec 30 04:18:18 music volumio[14095]: info: Shairport-Sync Started Dec 30 04:18:18 music volumio[14095]: Error adding Membership: Error: addMembership EINVAL Dec 30 04:18:18 music volumio[14095]: info: Shairport-Sync Started Dec 30 04:18:18 music volumio[14095]: info: Shairport-Sync Started Dec 30 04:18:18 music volumio[14095]: info: CoreCommandRouter::volumioGetState Dec 30 04:18:18 music volumio[14095]: info: CorePlayQueue::getTrack 0 Dec 30 04:18:18 music go-librespot[14284]: time="2025-12-30T04:18:18-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Dec 30 04:18:18 music go-librespot[14284]: time="2025-12-30T04:18:18-05:00" level=debug msg="completed keyexchange" Dec 30 04:18:18 music go-librespot[14284]: time="2025-12-30T04:18:18-05:00" level=debug msg="completed challenge" Dec 30 04:18:18 music go-librespot[14284]: time="2025-12-30T04:18:18-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 30 04:18:19 music go-librespot[14284]: time="2025-12-30T04:18:19-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Dec 30 04:18:19 music go-librespot[14284]: time="2025-12-30T04:18:19-05:00" level=debug msg="completed keyexchange" Dec 30 04:18:19 music go-librespot[14284]: time="2025-12-30T04:18:19-05:00" level=debug msg="completed challenge" Dec 30 04:18:19 music go-librespot[14284]: time="2025-12-30T04:18:19-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 30 04:18:19 music mpd[14274]: 2025-12-30T04:18:19 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Dec 30 04:18:19 music systemd[1]: Started mpd.service - Music Player Daemon. Dec 30 04:18:19 music sudo[14227]: pam_unix(sudo:session): session closed for user root Dec 30 04:18:19 music sudo[14237]: pam_unix(sudo:session): session closed for user root Dec 30 04:18:19 music volumio[14095]: info: Completed starting Core Plugins Dec 30 04:18:19 music volumio[14095]: info: ------------------------------------------- Dec 30 04:18:19 music volumio[14095]: info: ----- MyVolumio plugins startup ---- Dec 30 04:18:19 music volumio[14095]: info: ------------------------------------------- Dec 30 04:18:19 music volumio[14095]: info: [MyVolumio PluginManager] Fetching plans data.... Dec 30 04:18:19 music volumio[14095]: error: MPD error: The expression evaluated to a falsy value: Dec 30 04:18:19 music volumio[14095]: assert.ok(self.idling) Dec 30 04:18:19 music volumio[14095]: error: The expression evaluated to a falsy value: Dec 30 04:18:19 music volumio[14095]: assert.ok(self.idling) Dec 30 04:18:19 music volumio[14095]: info: MPD running with PID14274 Dec 30 04:18:19 music volumio[14095]: ,establishing connection Dec 30 04:18:19 music volumio[14095]: error: updateQueue error: null Dec 30 04:18:19 music volumio[14095]: error: updateQueue error: null Dec 30 04:18:19 music go-librespot[14284]: time="2025-12-30T04:18:19-05:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 04:18:19 music go-librespot[14284]: time="2025-12-30T04:18:19-05:00" level=debug msg="completed keyexchange" Dec 30 04:18:19 music go-librespot[14284]: time="2025-12-30T04:18:19-05:00" level=debug msg="completed challenge" Dec 30 04:18:19 music go-librespot[14284]: time="2025-12-30T04:18:19-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 30 04:18:20 music sudo[14367]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 30 04:18:20 music sudo[14367]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 04:18:20 music sudo[14369]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 30 04:18:20 music sudo[14369]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 04:18:20 music sudo[14367]: pam_unix(sudo:session): session closed for user root Dec 30 04:18:20 music sudo[14369]: pam_unix(sudo:session): session closed for user root Dec 30 04:18:20 music sudo[14371]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Dec 30 04:18:20 music sudo[14371]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 04:18:20 music sudo[14371]: pam_unix(sudo:session): session closed for user root Dec 30 04:18:20 music volumio[14095]: info: Upmpdcli Daemon Started Dec 30 04:18:20 music go-librespot[14284]: time="2025-12-30T04:18:20-05:00" level=debug msg="connected to ap-gae2.spotify.com:443" Dec 30 04:18:20 music volumio[14095]: info: go-librespot daemon successfully initialized Dec 30 04:18:20 music go-librespot[14284]: time="2025-12-30T04:18:20-05:00" level=debug msg="completed keyexchange" Dec 30 04:18:20 music go-librespot[14284]: time="2025-12-30T04:18:20-05:00" level=debug msg="completed challenge" Dec 30 04:18:21 music go-librespot[14284]: time="2025-12-30T04:18:21-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 30 04:18:21 music go-librespot[14284]: time="2025-12-30T04:18:21-05:00" level=debug msg="connected to ap-gew1.spotify.com:80" Dec 30 04:18:21 music go-librespot[14284]: time="2025-12-30T04:18:21-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: EOF" Dec 30 04:18:21 music go-librespot[14284]: time="2025-12-30T04:18:21-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: EOF" Dec 30 04:18:21 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 04:18:21 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 04:18:22 music sudo[14376]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 30 04:18:22 music sudo[14376]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 04:18:22 music sudo[14378]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 30 04:18:22 music sudo[14378]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 04:18:22 music systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Dec 30 04:18:22 music systemd[1]: mpd_monitor.service: Deactivated successfully. Dec 30 04:18:22 music systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Dec 30 04:18:22 music systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Dec 30 04:18:22 music mpd_monitor.sh[14381]: MPD Monitor Service: Starting MPD Monitor Service Dec 30 04:18:22 music sudo[14376]: pam_unix(sudo:session): session closed for user root Dec 30 04:18:22 music volumio[14095]: info: Successfully started MPD Monitor Dec 30 04:18:22 music systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Dec 30 04:18:22 music systemd[1]: mpd_monitor.service: Deactivated successfully. Dec 30 04:18:22 music systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Dec 30 04:18:22 music systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Dec 30 04:18:22 music sudo[14378]: pam_unix(sudo:session): session closed for user root Dec 30 04:18:22 music mpd_monitor.sh[14384]: MPD Monitor Service: Starting MPD Monitor Service Dec 30 04:18:22 music volumio[14095]: info: Successfully started MPD Monitor Dec 30 04:18:23 music volumio[14095]: info: Initializing connection to go-librespot Websocket Dec 30 04:18:23 music volumio[14095]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 30 04:18:24 music volumio[14095]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Dec 30 04:18:25 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Dec 30 04:18:25 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 04:18:25 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 04:18:25 music go-librespot[14388]: go-librespot daemon starting... Dec 30 04:18:25 music go-librespot[14389]: time="2025-12-30T04:18:25-05:00" level=info msg="running go-librespot 0.6.2" Dec 30 04:18:25 music go-librespot[14389]: time="2025-12-30T04:18:25-05:00" level=debug msg="app state loaded" Dec 30 04:18:25 music go-librespot[14389]: time="2025-12-30T04:18:25-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 04:18:25 music go-librespot[14389]: time="2025-12-30T04:18:25-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew1.spotify.com:80]" Dec 30 04:18:25 music go-librespot[14389]: time="2025-12-30T04:18:25-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]" Dec 30 04:18:25 music go-librespot[14389]: time="2025-12-30T04:18:25-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]" Dec 30 04:18:25 music go-librespot[14389]: time="2025-12-30T04:18:25-05:00" level=info msg="zeroconf server listening on port 43183" Dec 30 04:18:25 music go-librespot[14389]: time="2025-12-30T04:18:25-05:00" level=debug msg="obtained new client token: AAAX7DzQdmzX4RvDLPzslPW43mmnUWC8c3EDC45cZRQ8Tv6L8mc7Tj34oOrKLd7q2FPvVVE2yBK+f/hZr9i7129pA2b/tWGDdsFSwTe1yC/4OZJ4cpppqgI+UX60m21DMlJRgcDC+mfQ1HHBDX2I/NXAoJhLhpnyPh8KizZNp+Uoby68l1qB2EwsztElv0nwYvKkG/bySgz8/oFxkd0WfDfxDVs0Y0UXn9ut/IdFPlHD4G+D7zOaYE0f" Dec 30 04:18:25 music go-librespot[14389]: time="2025-12-30T04:18:25-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 30 04:18:25 music go-librespot[14389]: time="2025-12-30T04:18:25-05:00" level=debug msg="completed keyexchange" Dec 30 04:18:25 music go-librespot[14389]: time="2025-12-30T04:18:25-05:00" level=debug msg="completed challenge" Dec 30 04:18:25 music go-librespot[14389]: time="2025-12-30T04:18:25-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 30 04:18:26 music go-librespot[14389]: time="2025-12-30T04:18:26-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" Dec 30 04:18:26 music go-librespot[14389]: time="2025-12-30T04:18:26-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Dec 30 04:18:26 music go-librespot[14389]: time="2025-12-30T04:18:26-05:00" level=debug msg="completed keyexchange" Dec 30 04:18:26 music go-librespot[14389]: time="2025-12-30T04:18:26-05:00" level=debug msg="completed challenge" Dec 30 04:18:26 music go-librespot[14389]: time="2025-12-30T04:18:26-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 30 04:18:26 music volumio[14095]: info: Initializing connection to go-librespot Websocket Dec 30 04:18:26 music go-librespot[14389]: time="2025-12-30T04:18:26-05:00" level=debug msg="new websocket client" Dec 30 04:18:26 music volumio[14095]: info: Connection to go-librespot Websocket established Dec 30 04:18:27 music go-librespot[14389]: time="2025-12-30T04:18:27-05:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 04:18:27 music go-librespot[14389]: time="2025-12-30T04:18:27-05:00" level=debug msg="completed keyexchange" Dec 30 04:18:27 music go-librespot[14389]: time="2025-12-30T04:18:27-05:00" level=debug msg="completed challenge" Dec 30 04:18:27 music go-librespot[14389]: time="2025-12-30T04:18:27-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 30 04:18:27 music go-librespot[14389]: time="2025-12-30T04:18:27-05:00" level=debug msg="connected to ap-gae2.spotify.com:443" Dec 30 04:18:27 music volumio[14095]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Dec 30 04:18:27 music volumio[14095]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Dec 30 04:18:27 music volumio[14095]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Dec 30 04:18:27 music volumio[14095]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Dec 30 04:18:27 music volumio[14095]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Dec 30 04:18:27 music volumio[14095]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Dec 30 04:18:27 music volumio[14095]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Dec 30 04:18:27 music volumio[14095]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Dec 30 04:18:27 music volumio[14095]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Dec 30 04:18:27 music volumio[14095]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Dec 30 04:18:27 music volumio[14095]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Dec 30 04:18:27 music volumio[14095]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Dec 30 04:18:27 music volumio[14095]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Dec 30 04:18:27 music volumio[14095]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Dec 30 04:18:27 music volumio[14095]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Dec 30 04:18:27 music volumio[14095]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Dec 30 04:18:27 music volumio[14095]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Dec 30 04:18:27 music volumio[14095]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Dec 30 04:18:27 music volumio[14095]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Dec 30 04:18:27 music volumio[14095]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Dec 30 04:18:27 music volumio[14095]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Dec 30 04:18:27 music volumio[14095]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Dec 30 04:18:27 music volumio[14095]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Dec 30 04:18:27 music volumio[14095]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Dec 30 04:18:27 music volumio[14095]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Dec 30 04:18:27 music volumio[14095]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Dec 30 04:18:27 music volumio[14095]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Dec 30 04:18:27 music volumio[14095]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Dec 30 04:18:27 music volumio[14095]: info: Adding plugin bluetooth to MyMusic Plugins Dec 30 04:18:27 music volumio[14095]: info: Adding plugin multiroom to MyMusic Plugins Dec 30 04:18:27 music volumio[14095]: info: Adding plugin metavolumio to MyMusic Plugins Dec 30 04:18:27 music volumio[14095]: info: Adding plugin cd_controller to MyMusic Plugins Dec 30 04:18:27 music volumio[14095]: info: Adding plugin qobuzconnect to MyMusic Plugins Dec 30 04:18:27 music volumio[14095]: info: Adding plugin smart_inputs to MyMusic Plugins Dec 30 04:18:27 music volumio[14095]: info: Adding plugin tidalconnect to MyMusic Plugins Dec 30 04:18:27 music volumio[14095]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Dec 30 04:18:28 music go-librespot[14389]: time="2025-12-30T04:18:28-05:00" level=debug msg="completed keyexchange" Dec 30 04:18:28 music go-librespot[14389]: time="2025-12-30T04:18:28-05:00" level=debug msg="completed challenge" Dec 30 04:18:28 music go-librespot[14389]: time="2025-12-30T04:18:28-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 30 04:18:28 music go-librespot[14389]: time="2025-12-30T04:18:28-05:00" level=debug msg="connected to ap-gew1.spotify.com:80" Dec 30 04:18:29 music volumio[14095]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Dec 30 04:18:29 music volumio[14095]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Dec 30 04:18:29 music volumio[14095]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 04:18:29 music volumio[14095]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 04:18:29 music volumio[14095]: info: Starting MyVolumio Remote Streaming Endpoints Dec 30 04:18:29 music go-librespot[14389]: time="2025-12-30T04:18:29-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: EOF" Dec 30 04:18:29 music volumio[14095]: info: MyVolumio login type: Token Dec 30 04:18:29 music volumio[14095]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Dec 30 04:18:29 music volumio[14095]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Dec 30 04:18:29 music go-librespot[14389]: time="2025-12-30T04:18:29-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 30 04:18:29 music go-librespot[14389]: time="2025-12-30T04:18:29-05:00" level=debug msg="completed keyexchange" Dec 30 04:18:29 music go-librespot[14389]: time="2025-12-30T04:18:29-05:00" level=debug msg="completed challenge" Dec 30 04:18:29 music go-librespot[14389]: time="2025-12-30T04:18:29-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 30 04:18:29 music go-librespot[14389]: time="2025-12-30T04:18:29-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 " Dec 30 04:18:29 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 04:18:29 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 04:18:30 music volumio[14095]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Dec 30 04:18:30 music volumio[14095]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Dec 30 04:18:30 music volumio[14095]: info: Streaming services startup Dec 30 04:18:30 music volumio[14095]: info: Starting Streaming Daemon Dec 30 04:18:30 music sudo[14400]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Dec 30 04:18:30 music sudo[14400]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 04:18:30 music volumio[14095]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Dec 30 04:18:30 music sudo[14400]: pam_unix(sudo:session): session closed for user root Dec 30 04:18:30 music volumio[14095]: info: Getting Spotify volume Dec 30 04:18:30 music volumio[14095]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 30 04:18:30 music volumio[14095]: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 30 04:18:30 music volumio[14095]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Dec 30 04:18:30 music volumio[14095]: errno: -111, Dec 30 04:18:30 music volumio[14095]: code: 'ECONNREFUSED', Dec 30 04:18:30 music volumio[14095]: syscall: 'connect', Dec 30 04:18:30 music volumio[14095]: address: '127.0.0.1', Dec 30 04:18:30 music volumio[14095]: port: 9879, Dec 30 04:18:30 music volumio[14095]: response: undefined Dec 30 04:18:30 music volumio[14095]: } Dec 30 04:18:30 music volumio[14095]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 30 04:18:30 music sudo[14435]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-30 04:17' Dec 30 04:18:30 music sudo[14435]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 04:18:31 music sudo[14435]: pam_unix(sudo:session): session closed for user root Dec 30 04:18:32 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Dec 30 04:18:32 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 04:18:32 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 04:18:32 music go-librespot[14444]: go-librespot daemon starting... Dec 30 04:18:32 music go-librespot[14445]: time="2025-12-30T04:18:32-05:00" level=info msg="running go-librespot 0.6.2" Dec 30 04:18:32 music go-librespot[14445]: time="2025-12-30T04:18:32-05:00" level=debug msg="app state loaded" Dec 30 04:18:32 music go-librespot[14445]: time="2025-12-30T04:18:32-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 04:18:33 music volumio-remote-updater[735]: [2025-12-30 09:18:33] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Dec 30 04:18:33 music volumio-remote-updater[735]: [2025-12-30 09:18:33] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Dec 30 04:18:33 music systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Dec 30 04:18:33 music systemd[1]: volumio.service: Failed with result 'exit-code'. Dec 30 04:18:33 music systemd[1]: volumio.service: Consumed 26.481s CPU time. Dec 30 04:18:33 music systemd[1]: Started dynamicswap.service - dynamicswap service. Dec 30 04:18:33 music systemd[1]: dynamicswap.service: Deactivated successfully. Dec 30 04:18:33 music go-librespot[14445]: time="2025-12-30T04:18:33-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]" Dec 30 04:18:33 music go-librespot[14445]: time="2025-12-30T04:18:33-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]" Dec 30 04:18:33 music go-librespot[14445]: time="2025-12-30T04:18:33-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]" Dec 30 04:18:33 music go-librespot[14445]: time="2025-12-30T04:18:33-05:00" level=info msg="zeroconf server listening on port 32891" Dec 30 04:18:33 music systemd[1]: volumio.service: Scheduled restart job, restart counter is at 8376. Dec 30 04:18:33 music go-librespot[14445]: time="2025-12-30T04:18:33-05:00" level=debug msg="obtained new client token: AAAKDp/1YUurS8pUEahRE5szVo/CKNLWCbAURdRooEprIcvyVCR/k7luH/IJLYepagoyYwnqxpfxfm/TMdTqWbdSN7xWSkh3STH8HQcA+mjE+oawIzFVtOJcPDY0ST6S0h2xKU1GlyeneZzgo2NjEfWRv6tBaYBpiAoMQzCOqWloPPsjX+GVMV8ZzxXEA30DIJWCQ6BVijRUgBd2NRAon/Xzh81oMDR6YE+X9aymUcJ5g1NYGXD/x5u2" Dec 30 04:18:33 music systemd[1]: Started dynamicswap.service - dynamicswap service. Dec 30 04:18:33 music systemd[1]: Stopped volumio.service - Volumio Backend Module. Dec 30 04:18:33 music systemd[1]: volumio.service: Consumed 26.481s CPU time. Dec 30 04:18:33 music systemd[1]: Started volumio.service - Volumio Backend Module. Dec 30 04:18:33 music systemd[1]: dynamicswap.service: Deactivated successfully. Dec 30 04:18:33 music go-librespot[14445]: time="2025-12-30T04:18:33-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 30 04:18:33 music go-librespot[14445]: time="2025-12-30T04:18:33-05:00" level=debug msg="completed keyexchange" Dec 30 04:18:33 music go-librespot[14445]: time="2025-12-30T04:18:33-05:00" level=debug msg="completed challenge" Dec 30 04:18:33 music go-librespot[14445]: time="2025-12-30T04:18:33-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 30 04:18:34 music go-librespot[14445]: time="2025-12-30T04:18:34-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Dec 30 04:18:34 music go-librespot[14445]: time="2025-12-30T04:18:34-05:00" level=debug msg="completed keyexchange" Dec 30 04:18:34 music go-librespot[14445]: time="2025-12-30T04:18:34-05:00" level=debug msg="completed challenge" Dec 30 04:18:34 music go-librespot[14445]: time="2025-12-30T04:18:34-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 30 04:18:34 music go-librespot[14445]: time="2025-12-30T04:18:34-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Dec 30 04:18:34 music go-librespot[14445]: time="2025-12-30T04:18:34-05:00" level=debug msg="completed keyexchange" Dec 30 04:18:34 music go-librespot[14445]: time="2025-12-30T04:18:34-05:00" level=debug msg="completed challenge" Dec 30 04:18:34 music go-librespot[14445]: time="2025-12-30T04:18:34-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 30 04:18:35 music volumio[14462]: info: ------------------------------------------- Dec 30 04:18:35 music volumio[14462]: info: ----- Volumio3 ---- Dec 30 04:18:35 music volumio[14462]: info: ------------------------------------------- Dec 30 04:18:35 music volumio[14462]: info: ----- System startup ---- Dec 30 04:18:35 music volumio[14462]: info: ------------------------------------------- Dec 30 04:18:35 music go-librespot[14445]: time="2025-12-30T04:18:35-05:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 04:18:35 music go-librespot[14445]: time="2025-12-30T04:18:35-05:00" level=debug msg="completed keyexchange" Dec 30 04:18:35 music go-librespot[14445]: time="2025-12-30T04:18:35-05:00" level=debug msg="completed challenge" Dec 30 04:18:35 music go-librespot[14445]: time="2025-12-30T04:18:35-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 30 04:18:36 music volumio[14462]: info: MYVOLUMIO Environment detected Dec 30 04:18:36 music volumio[14462]: info: Plugin folders cleanup Dec 30 04:18:36 music volumio[14462]: info: Scanning into folder /volumio/app/plugins/ Dec 30 04:18:36 music volumio[14462]: info: Scanning category audio_interface Dec 30 04:18:36 music volumio[14462]: info: Scanning category miscellanea Dec 30 04:18:36 music volumio[14462]: info: Scanning category music_service Dec 30 04:18:36 music volumio[14462]: info: Scanning category plugins.json Dec 30 04:18:36 music volumio[14462]: info: Scanning category system_controller Dec 30 04:18:36 music volumio[14462]: info: Scanning category user_interface Dec 30 04:18:36 music volumio[14462]: info: Scanning into folder /data/plugins/ Dec 30 04:18:36 music volumio[14462]: info: Scanning category music_service Dec 30 04:18:36 music volumio[14462]: info: Plugin folders cleanup completed Dec 30 04:18:36 music volumio[14462]: info: ------------------------------------------- Dec 30 04:18:36 music volumio[14462]: info: ----- Core plugins startup ---- Dec 30 04:18:36 music volumio[14462]: info: ------------------------------------------- Dec 30 04:18:36 music volumio[14462]: info: Loading plugins from folder /volumio/app/plugins/ Dec 30 04:18:36 music volumio[14462]: info: Adding plugin upnp to MyMusic Plugins Dec 30 04:18:36 music volumio[14462]: info: Adding plugin airplay_emulation to MyMusic Plugins Dec 30 04:18:36 music volumio[14462]: info: Adding plugin upnp_browser to MyMusic Plugins Dec 30 04:18:36 music volumio[14462]: info: Loading plugins from folder /data/plugins/ Dec 30 04:18:36 music volumio[14462]: info: Loading plugin "system"... Dec 30 04:18:36 music volumio[14462]: info: Loading plugin "appearance"... Dec 30 04:18:36 music go-librespot[14445]: time="2025-12-30T04:18:36-05:00" level=debug msg="connected to ap-gae2.spotify.com:443" Dec 30 04:18:36 music go-librespot[14445]: time="2025-12-30T04:18:36-05:00" level=debug msg="completed keyexchange" Dec 30 04:18:36 music go-librespot[14445]: time="2025-12-30T04:18:36-05:00" level=debug msg="completed challenge" Dec 30 04:18:37 music go-librespot[14445]: time="2025-12-30T04:18:37-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 30 04:18:37 music volumio[14462]: info: Loading plugin "network"... Dec 30 04:18:37 music volumio[14462]: info: Refreshing Cached IP Addresses Dec 30 04:18:37 music sudo[14490]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 30 04:18:37 music sudo[14490]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 04:18:37 music sudo[14490]: pam_unix(sudo:session): session closed for user root Dec 30 04:18:37 music sudo[14492]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 30 04:18:37 music sudo[14492]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 04:18:37 music volumio[14462]: info: Loading plugin "services"... Dec 30 04:18:37 music sudo[14492]: pam_unix(sudo:session): session closed for user root Dec 30 04:18:37 music volumio[14462]: info: Loading plugin "alsa_controller"... Dec 30 04:18:37 music sudo[14500]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Dec 30 04:18:37 music sudo[14500]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 04:18:37 music volumio[14462]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 30 04:18:37 music volumio[14462]: info: Loading plugin "wizard"... Dec 30 04:18:37 music volumio[14462]: info: Loading plugin "networkfs"... Dec 30 04:18:37 music volumio[14462]: info: Starting Udev Watcher for removable devices Dec 30 04:18:37 music volumio[14462]: info: Ignoring mount for partition: boot Dec 30 04:18:37 music volumio[14462]: info: Ignoring mount for partition: volumio Dec 30 04:18:37 music volumio[14462]: info: Ignoring mount for partition: volumio_data Dec 30 04:18:37 music volumio[14462]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 30 04:18:37 music volumio[14462]: info: Loading plugin "volumio_command_line_client"... Dec 30 04:18:37 music volumio[14462]: info: Loading plugin "upnp"... Dec 30 04:18:37 music volumio[14462]: info: [1767086317651] Starting Upmpd Daemon Dec 30 04:18:37 music volumio[14462]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 30 04:18:37 music volumio[14462]: info: Loading plugin "my_music"... Dec 30 04:18:37 music volumio[14462]: info: Loading plugin "mpd"... Dec 30 04:18:37 music go-librespot[14445]: time="2025-12-30T04:18:37-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" Dec 30 04:18:37 music go-librespot[14445]: time="2025-12-30T04:18:37-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" Dec 30 04:18:37 music go-librespot[14445]: time="2025-12-30T04:18:37-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" Dec 30 04:18:37 music go-librespot[14445]: time="2025-12-30T04:18:37-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Dec 30 04:18:37 music go-librespot[14445]: time="2025-12-30T04:18:37-05:00" level=debug msg="completed keyexchange" Dec 30 04:18:37 music go-librespot[14445]: time="2025-12-30T04:18:37-05:00" level=debug msg="completed challenge" Dec 30 04:18:37 music go-librespot[14445]: time="2025-12-30T04:18:37-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 30 04:18:37 music go-librespot[14445]: time="2025-12-30T04:18:37-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 " Dec 30 04:18:38 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 04:18:38 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 04:18:38 music volumio-remote-updater[735]: [2025-12-30 09:18:38] [connect] Successful connection Dec 30 04:18:38 music volumio[14462]: info: Loading plugin "upnp_browser"... Dec 30 04:18:38 music sudo[14500]: pam_unix(sudo:session): session closed for user root Dec 30 04:18:39 music volumio[14462]: info: Starting UPNP Browser Dec 30 04:18:39 music volumio[14462]: info: Loading plugin "alarm-clock"... Dec 30 04:18:39 music volumio[14462]: info: Loading plugin "airplay_emulation"... Dec 30 04:18:39 music volumio[14462]: info: Starting Shairport Sync Dec 30 04:18:39 music volumio[14462]: info: Loading plugin "last_100"... Dec 30 04:18:39 music volumio[14462]: info: Loading plugin "webradio"... Dec 30 04:18:39 music volumio[14462]: info: Loading plugin "i2s_dacs"... Dec 30 04:18:39 music volumio[14462]: info: I2S DAC not set, start Auto-detection Dec 30 04:18:39 music volumio[14462]: info: Loading plugin "volumiodiscovery"... Dec 30 04:18:39 music volumio[14462]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 30 04:18:39 music volumio[14462]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 30 04:18:39 music volumio[14462]: *** WARNING *** For more information see Dec 30 04:18:39 music volumio[14462]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 30 04:18:39 music volumio[14462]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 30 04:18:39 music volumio[14462]: *** WARNING *** For more information see Dec 30 04:18:39 music node[14462]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 30 04:18:39 music node[14462]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 30 04:18:39 music node[14462]: *** WARNING *** For more information see Dec 30 04:18:39 music node[14462]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 30 04:18:39 music node[14462]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 30 04:18:39 music node[14462]: *** WARNING *** For more information see Dec 30 04:18:39 music volumio[14462]: info: Applying required configuration parameters for plugin volumiodiscovery Dec 30 04:18:39 music volumio[14462]: info: Discovery: Started advertising with name: music Dec 30 04:18:39 music volumio[14462]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 30 04:18:39 music volumio[14462]: info: Loading plugin "spop"... Dec 30 04:18:41 music volumio[14462]: info: Loading plugin "outputs"... Dec 30 04:18:41 music volumio[14462]: info: Loading plugin "albumart"... Dec 30 04:18:41 music volumio[14462]: info: Plugin example_plugin is not enabled Dec 30 04:18:41 music volumio[14462]: info: Loading plugin "inputs"... Dec 30 04:18:41 music volumio[14462]: info: Loading plugin "updater_comm"... Dec 30 04:18:41 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Dec 30 04:18:41 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 04:18:41 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 04:18:41 music go-librespot[14534]: go-librespot daemon starting... Dec 30 04:18:41 music volumio[14462]: info: Plugin mpdemulation is not enabled Dec 30 04:18:41 music volumio[14462]: info: Loading plugin "rest_api"... Dec 30 04:18:41 music go-librespot[14536]: time="2025-12-30T04:18:41-05:00" level=info msg="running go-librespot 0.6.2" Dec 30 04:18:41 music go-librespot[14536]: time="2025-12-30T04:18:41-05:00" level=debug msg="app state loaded" Dec 30 04:18:41 music volumio[14462]: info: Loading plugin "websocket"... Dec 30 04:18:41 music volumio[14462]: info: Starting Socket.io Server version 1.7.4 Dec 30 04:18:41 music go-librespot[14536]: time="2025-12-30T04:18:41-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 04:18:41 music volumio[14462]: info: Loading i18n strings for locale en Dec 30 04:18:41 music volumio[14462]: Updating browse sources language Dec 30 04:18:41 music volumio[14462]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 04:18:41 music volumio[14462]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 30 04:18:41 music volumio[14462]: info: CoreCommandRouter::initPlayerControls Dec 30 04:18:41 music volumio[14462]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:18:41 music volumio[14462]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:18:41 music volumio[14462]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:18:41 music volumio[14462]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:18:41 music volumio[14462]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:18:41 music volumio[14462]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:18:41 music volumio[14462]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:18:41 music volumio[14462]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:18:41 music volumio[14462]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 30 04:18:41 music volumio[14462]: Express server listening on port 3000 Dec 30 04:18:41 music volumio[14462]: [Metrics] WebUI: 6s 585.27ms Dec 30 04:18:41 music volumio[14462]: info: CoreStateMachine::resetVolumioState Dec 30 04:18:41 music volumio[14462]: info: CoreStateMachine::getcurrentVolume Dec 30 04:18:41 music volumio[14462]: info: CoreCommandRouter::volumioRetrievevolume Dec 30 04:18:41 music volumio[14462]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 04:18:41 music volumio[14462]: info: Volumio Network Manager: Network status updated: 1 Dec 30 04:18:41 music go-librespot[14536]: time="2025-12-30T04:18:41-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]" Dec 30 04:18:41 music go-librespot[14536]: time="2025-12-30T04:18:41-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]" Dec 30 04:18:41 music go-librespot[14536]: time="2025-12-30T04:18:41-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]" Dec 30 04:18:41 music go-librespot[14536]: time="2025-12-30T04:18:41-05:00" level=info msg="zeroconf server listening on port 38321" Dec 30 04:18:41 music volumio[14525]: Forking 3 albumart workers Dec 30 04:18:41 music volumio-remote-updater[735]: [2025-12-30 09:18:41] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1767086318 101 Dec 30 04:18:41 music volumio[14462]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 3 Transport: websocket Total Clients: 1 Dec 30 04:18:41 music volumio[14462]: info: VolumeController:: Volume=86 Mute =false Dec 30 04:18:41 music volumio[14462]: info: CoreStateMachine::pushState Dec 30 04:18:41 music volumio[14462]: info: CorePlayQueue::getTrack 0 Dec 30 04:18:41 music volumio[14462]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 30 04:18:41 music volumio[14462]: info: CoreCommandRouter::volumioPushState Dec 30 04:18:41 music volumio[14462]: info: CoreStateMachine::updateTrackBlock Dec 30 04:18:41 music volumio[14462]: info: CorePlayQueue::getTrackBlock Dec 30 04:18:41 music volumio[14462]: info: CoreCommandRouter::volumioRetrievevolume Dec 30 04:18:41 music go-librespot[14536]: time="2025-12-30T04:18:41-05:00" level=debug msg="obtained new client token: AABtAAugvIL8G3rqeetL1WrW/liNSc41WefSrcxLRZ35ZFOXXwEP5efUASubC4rn+bSqQ5Zrd2I456Q5GUQoFX1i5+d0K5ITipJz/1BekQkoA8Yn5Jy98N18BhxMThKUlNEj0/NKTyg7IyuxaKtdsl4sW3SYg/AgPvsxIa/BKphyLIVs0T4er+4D0/InVB1OG3QBYuo5Fk+1BvJkRmK0ECPqk4ILNEE4SR7QVV4/NJpzq/5K80cZxBjD" Dec 30 04:18:41 music volumio[14462]: info: Reloading queue from file Dec 30 04:18:41 music go-librespot[14536]: time="2025-12-30T04:18:41-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 30 04:18:41 music volumio[14462]: info: CoreStateMachine::setRepeat null single undefined Dec 30 04:18:41 music volumio[14462]: info: CoreStateMachine::pushState Dec 30 04:18:41 music volumio[14462]: info: CorePlayQueue::getTrack 0 Dec 30 04:18:41 music volumio[14462]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 30 04:18:41 music volumio[14462]: info: CoreCommandRouter::volumioPushState Dec 30 04:18:41 music volumio[14462]: info: CoreStateMachine::setRandom null Dec 30 04:18:41 music volumio[14462]: info: CoreStateMachine::pushState Dec 30 04:18:41 music volumio[14462]: info: CorePlayQueue::getTrack 0 Dec 30 04:18:41 music volumio[14462]: info: CoreCommandRouter::volumioPushState Dec 30 04:18:41 music go-librespot[14536]: time="2025-12-30T04:18:41-05:00" level=debug msg="completed keyexchange" Dec 30 04:18:41 music go-librespot[14536]: time="2025-12-30T04:18:41-05:00" level=debug msg="completed challenge" Dec 30 04:18:41 music volumio[14462]: info: Setting Device type: Raspberry PI Dec 30 04:18:41 music go-librespot[14536]: time="2025-12-30T04:18:41-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 30 04:18:41 music volumio[14462]: info: VolumeController:: Volume=86 Mute =false Dec 30 04:18:41 music volumio[14462]: info: CoreStateMachine::pushState Dec 30 04:18:41 music volumio[14462]: info: CorePlayQueue::getTrack 0 Dec 30 04:18:41 music volumio[14462]: info: CoreCommandRouter::volumioPushState Dec 30 04:18:42 music volumio[14462]: info: Completed loading Core Plugins Dec 30 04:18:42 music volumio[14462]: info: Preparing to generate the ALSA configuration file Dec 30 04:18:42 music volumio[14462]: info: Discovery: adding 4a29b7a7-c637-4926-a2bd-fb4e2f55145e Dec 30 04:18:42 music volumio[14462]: info: Discovery: Found device music Dec 30 04:18:42 music volumio[14462]: info: CoreCommandRouter::volumioGetState Dec 30 04:18:42 music volumio[14462]: info: CorePlayQueue::getTrack 0 Dec 30 04:18:42 music volumio[14462]: info: Discovery: this is already registered, 4a29b7a7-c637-4926-a2bd-fb4e2f55145e Dec 30 04:18:42 music volumio[14462]: info: Discovery: Found device music Dec 30 04:18:42 music volumio[14462]: info: CoreCommandRouter::volumioGetState Dec 30 04:18:42 music volumio[14462]: info: CorePlayQueue::getTrack 0 Dec 30 04:18:42 music volumio[14462]: info: Asound.conf file unchanged, so no further update is needed Dec 30 04:18:42 music volumio[14462]: info: Output device has changed, restarting MPD Dec 30 04:18:42 music volumio[14462]: info: Output device has changed, restarting Shairport Sync Dec 30 04:18:42 music volumio[14462]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:18:42 music volumio[14462]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 04:18:42 music sudo[14591]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 30 04:18:42 music sudo[14591]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 04:18:42 music volumio[14462]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 30 04:18:42 music sudo[14592]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 30 04:18:42 music volumio[14462]: info: ___________ START PLUGINS ___________ Dec 30 04:18:42 music sudo[14591]: pam_unix(sudo:session): session closed for user root Dec 30 04:18:42 music sudo[14592]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 04:18:42 music volumio[14462]: info: ControllerMpd::onStart: Initializing MPD Dec 30 04:18:42 music volumio[14462]: info: Creating MPD Configuration file Dec 30 04:18:42 music volumio[14462]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 30 04:18:42 music volumio[14462]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 04:18:42 music volumio[14462]: info: [1767086322204] CoreMusicLibrary::Adding element Media Servers Dec 30 04:18:42 music volumio[14462]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 04:18:42 music sudo[14600]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 30 04:18:42 music sudo[14600]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 04:18:42 music volumio[14462]: info: UPNP Browser: Client initialized successfully Dec 30 04:18:42 music sudo[14600]: pam_unix(sudo:session): session closed for user root Dec 30 04:18:42 music systemd[1]: Stopping mpd.service - Music Player Daemon... Dec 30 04:18:42 music volumio[14462]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:18:42 music volumio[14462]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 04:18:42 music sudo[14602]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 30 04:18:42 music sudo[14602]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 04:18:42 music volumio[14462]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 30 04:18:42 music volumio[14462]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:18:42 music volumio[14462]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 04:18:42 music systemd[1]: mpd.service: Deactivated successfully. Dec 30 04:18:42 music systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 30 04:18:42 music systemd[1]: mpd.service: Consumed 4.262s CPU time. Dec 30 04:18:42 music systemd[1]: mpd.socket: Deactivated successfully. Dec 30 04:18:42 music systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 30 04:18:42 music systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 30 04:18:42 music volumio[14462]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 30 04:18:42 music volumio[14462]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 04:18:42 music volumio[14462]: info: [1767086322382] CoreMusicLibrary::Adding element Last_100 Dec 30 04:18:42 music volumio[14462]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 04:18:42 music volumio[14462]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 04:18:42 music volumio[14462]: info: [1767086322386] CoreMusicLibrary::Adding element Webradio Dec 30 04:18:42 music volumio[14462]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 04:18:42 music volumio[14462]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 30 04:18:42 music volumio[14462]: info: Initializing BBC Radios Dec 30 04:18:42 music systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 30 04:18:42 music systemd[1]: Starting mpd.service - Music Player Daemon... Dec 30 04:18:42 music systemd[1]: mpd.service: Deactivated successfully. Dec 30 04:18:42 music systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 30 04:18:42 music systemd[1]: mpd.socket: Deactivated successfully. Dec 30 04:18:42 music systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 30 04:18:42 music systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 30 04:18:42 music systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 30 04:18:42 music systemd[1]: Starting mpd.service - Music Player Daemon... Dec 30 04:18:42 music go-librespot[14536]: time="2025-12-30T04:18:42-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Dec 30 04:18:42 music volumio[14462]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 30 04:18:42 music volumio[14462]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 04:18:42 music volumio[14462]: info: Creating Spotify config file Dec 30 04:18:42 music volumio[14462]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:18:42 music go-librespot[14536]: time="2025-12-30T04:18:42-05:00" level=debug msg="completed keyexchange" Dec 30 04:18:42 music go-librespot[14536]: time="2025-12-30T04:18:42-05:00" level=debug msg="completed challenge" Dec 30 04:18:42 music go-librespot[14536]: time="2025-12-30T04:18:42-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 30 04:18:42 music sudo[14628]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 30 04:18:42 music sudo[14628]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 30 04:18:42 music sudo[14628]: pam_unix(sudo:session): session closed for user root Dec 30 04:18:43 music volumio[14462]: info: Volumio Calling Home Dec 30 04:18:43 music go-librespot[14536]: time="2025-12-30T04:18:43-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Dec 30 04:18:43 music volumio[14553]: Starting albumart workers Dec 30 04:18:43 music volumio[14551]: Starting albumart workers Dec 30 04:18:43 music volumio[14552]: Starting albumart workers Dec 30 04:18:44 music volumio[14462]: info: MPD Permissions set Dec 30 04:18:44 music volumio[14462]: info: MPD Permissions set Dec 30 04:18:44 music volumio[14462]: info: Volumio called home Dec 30 04:18:44 music volumio[14462]: info: Spotify config file written Dec 30 04:18:44 music volumio[14462]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Dec 30 04:18:44 music volumio[14462]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:18:44 music volumio[14462]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:18:44 music volumio[14462]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:18:44 music volumio[14462]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:18:44 music volumio[14462]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:18:44 music volumio[14462]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:18:44 music volumio[14462]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:18:44 music volumio[14462]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:18:44 music sudo[14638]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 30 04:18:44 music sudo[14638]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 04:18:44 music volumio[14462]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 04:18:44 music volumio[14462]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:18:44 music volumio[14462]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:18:44 music volumio[14462]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:18:44 music volumio[14462]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:18:44 music volumio[14462]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:18:44 music volumio[14462]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:18:44 music volumio[14462]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:18:44 music volumio[14462]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:18:44 music volumio[14462]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:18:44 music systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Dec 30 04:18:44 music systemd[1]: go-librespot-daemon.service: Deactivated successfully. Dec 30 04:18:44 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 04:18:44 music volumio[14462]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 04:18:44 music volumio[14462]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 04:18:44 music volumio[14462]: info: No need to fix Spotify hosts Dec 30 04:18:44 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 04:18:44 music go-librespot[14650]: go-librespot daemon starting... Dec 30 04:18:44 music sudo[14638]: pam_unix(sudo:session): session closed for user root Dec 30 04:18:44 music go-librespot[14652]: time="2025-12-30T04:18:44-05:00" level=info msg="running go-librespot 0.6.2" Dec 30 04:18:44 music go-librespot[14652]: time="2025-12-30T04:18:44-05:00" level=debug msg="app state loaded" Dec 30 04:18:44 music go-librespot[14652]: time="2025-12-30T04:18:44-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 04:18:44 music volumio[14462]: info: Starting Shairport Sync Dec 30 04:18:44 music go-librespot[14652]: time="2025-12-30T04:18: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]" Dec 30 04:18:44 music go-librespot[14652]: time="2025-12-30T04:18: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]" Dec 30 04:18:44 music go-librespot[14652]: time="2025-12-30T04:18: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]" Dec 30 04:18:44 music volumio[14462]: info: Starting Shairport Sync Dec 30 04:18:44 music go-librespot[14652]: time="2025-12-30T04:18:44-05:00" level=info msg="zeroconf server listening on port 40353" Dec 30 04:18:44 music volumio[14462]: info: Starting Shairport Sync Dec 30 04:18:44 music sudo[14676]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 30 04:18:44 music volumio[14462]: info: An error occurred while refreshing Spotify Token Error: Bad Request Dec 30 04:18:44 music sudo[14676]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 04:18:45 music sudo[14674]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 30 04:18:45 music sudo[14674]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 04:18:45 music sudo[14678]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 30 04:18:45 music sudo[14678]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 04:18:45 music go-librespot[14652]: time="2025-12-30T04:18:45-05:00" level=debug msg="obtained new client token: AADj4XfkibiVdMxt77z5uBDQF27BkiM+woesmq1VIhjxGHXvFuvZFcg1xSA3t/67stB1BSz+cOKNLWVTAxLQJsIg4p0WtxoruAx2CD+Y0Nqt8GQ2Y5o3t6GJjOxVK9Tmb0TS/BFPxogen+hyi5zbzg0sOTOlEoU/mRdSYKqiTrmXvvPJw/sIX626kYCf3wv+hkT8kbZL/KuDCGQPa6OX/ofGZZqjLMjTEBhlqSeuG37dz75H0lNxqw==" Dec 30 04:18:45 music systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 30 04:18:45 music systemd[1]: shairport-sync.service: Deactivated successfully. Dec 30 04:18:45 music systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 30 04:18:45 music systemd[1]: shairport-sync.service: Consumed 1.878s CPU time. Dec 30 04:18:45 music go-librespot[14652]: time="2025-12-30T04:18:45-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" Dec 30 04:18:45 music systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 30 04:18:45 music sudo[14678]: pam_unix(sudo:session): session closed for user root Dec 30 04:18:45 music go-librespot[14652]: time="2025-12-30T04:18:45-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Dec 30 04:18:45 music sudo[14676]: pam_unix(sudo:session): session closed for user root Dec 30 04:18:45 music sudo[14674]: pam_unix(sudo:session): session closed for user root Dec 30 04:18:45 music go-librespot[14652]: time="2025-12-30T04:18:45-05:00" level=debug msg="completed keyexchange" Dec 30 04:18:45 music go-librespot[14652]: time="2025-12-30T04:18:45-05:00" level=debug msg="completed challenge" Dec 30 04:18:45 music volumio[14462]: info: Shairport-Sync Started Dec 30 04:18:45 music volumio[14462]: Error adding Membership: Error: addMembership EINVAL Dec 30 04:18:45 music volumio[14462]: info: Shairport-Sync Started Dec 30 04:18:45 music volumio[14462]: info: Shairport-Sync Started Dec 30 04:18:45 music volumio[14462]: info: CoreCommandRouter::volumioGetState Dec 30 04:18:45 music volumio[14462]: info: CorePlayQueue::getTrack 0 Dec 30 04:18:45 music go-librespot[14652]: time="2025-12-30T04:18:45-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 30 04:18:45 music go-librespot[14652]: time="2025-12-30T04:18:45-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Dec 30 04:18:45 music go-librespot[14652]: time="2025-12-30T04:18:45-05:00" level=debug msg="completed keyexchange" Dec 30 04:18:45 music go-librespot[14652]: time="2025-12-30T04:18:45-05:00" level=debug msg="completed challenge" Dec 30 04:18:46 music go-librespot[14652]: time="2025-12-30T04:18:46-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 30 04:18:46 music go-librespot[14652]: time="2025-12-30T04:18:46-05:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 04:18:46 music go-librespot[14652]: time="2025-12-30T04:18:46-05:00" level=debug msg="completed keyexchange" Dec 30 04:18:46 music go-librespot[14652]: time="2025-12-30T04:18:46-05:00" level=debug msg="completed challenge" Dec 30 04:18:46 music go-librespot[14652]: time="2025-12-30T04:18:46-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 30 04:18:46 music mpd[14633]: 2025-12-30T04:18:46 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Dec 30 04:18:46 music systemd[1]: Started mpd.service - Music Player Daemon. Dec 30 04:18:46 music sudo[14602]: pam_unix(sudo:session): session closed for user root Dec 30 04:18:46 music sudo[14592]: pam_unix(sudo:session): session closed for user root Dec 30 04:18:46 music volumio[14462]: info: Completed starting Core Plugins Dec 30 04:18:46 music volumio[14462]: info: ------------------------------------------- Dec 30 04:18:46 music volumio[14462]: info: ----- MyVolumio plugins startup ---- Dec 30 04:18:46 music volumio[14462]: info: ------------------------------------------- Dec 30 04:18:46 music volumio[14462]: info: [MyVolumio PluginManager] Fetching plans data.... Dec 30 04:18:46 music systemd[1]: Starting setdatetime-helper.service - Time Synchronization Helper Service... Dec 30 04:18:47 music volumio[14462]: error: MPD error: The expression evaluated to a falsy value: Dec 30 04:18:47 music volumio[14462]: assert.ok(self.idling) Dec 30 04:18:47 music volumio[14462]: error: The expression evaluated to a falsy value: Dec 30 04:18:47 music volumio[14462]: assert.ok(self.idling) Dec 30 04:18:47 music volumio[14462]: error: updateQueue error: null Dec 30 04:18:47 music volumio[14462]: info: MPD running with PID14633 Dec 30 04:18:47 music volumio[14462]: ,establishing connection Dec 30 04:18:47 music volumio[14462]: error: updateQueue error: null Dec 30 04:18:47 music go-librespot[14652]: time="2025-12-30T04:18:47-05:00" level=debug msg="connected to ap-gae2.spotify.com:443" Dec 30 04:18:47 music sudo[14744]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 30 04:18:47 music sudo[14744]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 04:18:47 music sudo[14746]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 30 04:18:47 music sudo[14746]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 04:18:47 music sudo[14744]: pam_unix(sudo:session): session closed for user root Dec 30 04:18:47 music sudo[14746]: pam_unix(sudo:session): session closed for user root Dec 30 04:18:47 music sudo[14749]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Dec 30 04:18:47 music sudo[14749]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 04:18:47 music sudo[14749]: pam_unix(sudo:session): session closed for user root Dec 30 04:18:47 music volumio[14462]: info: Upmpdcli Daemon Started Dec 30 04:18:47 music volumio[14462]: info: go-librespot daemon successfully initialized Dec 30 04:18:48 music systemd[1]: setdatetime-helper.service: Deactivated successfully. Dec 30 04:18:48 music systemd[1]: Finished setdatetime-helper.service - Time Synchronization Helper Service. Dec 30 04:18:48 music go-librespot[14652]: time="2025-12-30T04:18:48-05:00" level=debug msg="completed keyexchange" Dec 30 04:18:48 music go-librespot[14652]: time="2025-12-30T04:18:48-05:00" level=debug msg="completed challenge" Dec 30 04:18:48 music go-librespot[14652]: time="2025-12-30T04:18:48-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 30 04:18:49 music go-librespot[14652]: time="2025-12-30T04:18:49-05:00" level=debug msg="connected to ap-gew1.spotify.com:80" Dec 30 04:18:49 music go-librespot[14652]: time="2025-12-30T04:18:49-05:00" level=debug msg="completed keyexchange" Dec 30 04:18:49 music go-librespot[14652]: time="2025-12-30T04:18:49-05:00" level=debug msg="completed challenge" Dec 30 04:18:49 music go-librespot[14652]: time="2025-12-30T04:18:49-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 30 04:18:49 music sudo[14759]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 30 04:18:49 music sudo[14759]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 04:18:49 music sudo[14761]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 30 04:18:49 music sudo[14761]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 04:18:49 music systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Dec 30 04:18:49 music systemd[1]: mpd_monitor.service: Deactivated successfully. Dec 30 04:18:49 music systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Dec 30 04:18:49 music go-librespot[14652]: time="2025-12-30T04:18:49-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" Dec 30 04:18:50 music go-librespot[14652]: time="2025-12-30T04:18:50-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Dec 30 04:18:50 music systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Dec 30 04:18:50 music mpd_monitor.sh[14764]: MPD Monitor Service: Starting MPD Monitor Service Dec 30 04:18:50 music sudo[14759]: pam_unix(sudo:session): session closed for user root Dec 30 04:18:50 music volumio[14462]: info: Successfully started MPD Monitor Dec 30 04:18:50 music systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Dec 30 04:18:50 music systemd[1]: mpd_monitor.service: Deactivated successfully. Dec 30 04:18:50 music systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Dec 30 04:18:50 music systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Dec 30 04:18:50 music sudo[14761]: pam_unix(sudo:session): session closed for user root Dec 30 04:18:50 music mpd_monitor.sh[14769]: MPD Monitor Service: Starting MPD Monitor Service Dec 30 04:18:50 music volumio[14462]: info: Successfully started MPD Monitor Dec 30 04:18:50 music go-librespot[14652]: time="2025-12-30T04:18:50-05:00" level=debug msg="completed keyexchange" Dec 30 04:18:50 music go-librespot[14652]: time="2025-12-30T04:18:50-05:00" level=debug msg="completed challenge" Dec 30 04:18:50 music go-librespot[14652]: time="2025-12-30T04:18:50-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 30 04:18:50 music go-librespot[14652]: time="2025-12-30T04:18:50-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 " Dec 30 04:18:50 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 04:18:50 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 04:18:50 music volumio[14462]: info: Initializing connection to go-librespot Websocket Dec 30 04:18:50 music volumio[14462]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 30 04:18:51 music volumio[14462]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Dec 30 04:18:53 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Dec 30 04:18:53 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 04:18:53 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 04:18:53 music go-librespot[14774]: go-librespot daemon starting... Dec 30 04:18:53 music go-librespot[14775]: time="2025-12-30T04:18:53-05:00" level=info msg="running go-librespot 0.6.2" Dec 30 04:18:53 music go-librespot[14775]: time="2025-12-30T04:18:53-05:00" level=debug msg="app state loaded" Dec 30 04:18:53 music go-librespot[14775]: time="2025-12-30T04:18:53-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 04:18:53 music go-librespot[14775]: time="2025-12-30T04:18:53-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]" Dec 30 04:18:53 music go-librespot[14775]: time="2025-12-30T04:18:53-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]" Dec 30 04:18:53 music go-librespot[14775]: time="2025-12-30T04:18:53-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]" Dec 30 04:18:53 music go-librespot[14775]: time="2025-12-30T04:18:53-05:00" level=info msg="zeroconf server listening on port 34193" Dec 30 04:18:53 music go-librespot[14775]: time="2025-12-30T04:18:53-05:00" level=debug msg="obtained new client token: AABhkqLlC9NnJCF7h3Ywq1UI1Yjt4avUHjwWsl3ZTnkeX8Cwrp+jmkm33gdc6X/76XpgmAOCWhYq2XZUh+UtUcAQOo7g8D0Y2WBRMJ6IXQGFsvvDoTRUea7Huyas10zMF/4WWWTDZGTBqayzWqyNZkoOLsrtcb8Y2L1Xeh35Rcq5qpRSdaYmEPN535HUVOpFt/NU+RNGKEeCBGNs22m4xH1KA2N8IRwdLdNACkrEGDvs+V9VIdNhD3h3" Dec 30 04:18:53 music volumio[14462]: info: Initializing connection to go-librespot Websocket Dec 30 04:18:53 music go-librespot[14775]: time="2025-12-30T04:18:53-05:00" level=debug msg="new websocket client" Dec 30 04:18:53 music volumio[14462]: info: Connection to go-librespot Websocket established Dec 30 04:18:53 music go-librespot[14775]: time="2025-12-30T04:18:53-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" Dec 30 04:18:53 music go-librespot[14775]: time="2025-12-30T04:18:53-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Dec 30 04:18:54 music go-librespot[14775]: time="2025-12-30T04:18:54-05:00" level=debug msg="completed keyexchange" Dec 30 04:18:54 music go-librespot[14775]: time="2025-12-30T04:18:54-05:00" level=debug msg="completed challenge" Dec 30 04:18:54 music go-librespot[14775]: time="2025-12-30T04:18:54-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 30 04:18:54 music go-librespot[14775]: time="2025-12-30T04:18:54-05:00" level=warning msg="failed to connect to AP ap-gue1.spotify.com:80, retrying with a different AP" error="dial tcp 34.158.255.62:80: connect: connection refused" Dec 30 04:18:54 music go-librespot[14775]: time="2025-12-30T04:18:54-05:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 04:18:54 music go-librespot[14775]: time="2025-12-30T04:18:54-05:00" level=debug msg="completed keyexchange" Dec 30 04:18:54 music go-librespot[14775]: time="2025-12-30T04:18:54-05:00" level=debug msg="completed challenge" Dec 30 04:18:54 music go-librespot[14775]: time="2025-12-30T04:18:54-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 30 04:18:55 music volumio[14462]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Dec 30 04:18:55 music volumio[14462]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Dec 30 04:18:55 music volumio[14462]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Dec 30 04:18:55 music volumio[14462]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Dec 30 04:18:55 music volumio[14462]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Dec 30 04:18:55 music volumio[14462]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Dec 30 04:18:55 music volumio[14462]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Dec 30 04:18:55 music volumio[14462]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Dec 30 04:18:55 music volumio[14462]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Dec 30 04:18:55 music volumio[14462]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Dec 30 04:18:55 music volumio[14462]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Dec 30 04:18:55 music volumio[14462]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Dec 30 04:18:55 music volumio[14462]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Dec 30 04:18:55 music volumio[14462]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Dec 30 04:18:55 music volumio[14462]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Dec 30 04:18:55 music volumio[14462]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Dec 30 04:18:55 music volumio[14462]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Dec 30 04:18:55 music volumio[14462]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Dec 30 04:18:55 music volumio[14462]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Dec 30 04:18:55 music volumio[14462]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Dec 30 04:18:55 music volumio[14462]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Dec 30 04:18:55 music volumio[14462]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Dec 30 04:18:55 music volumio[14462]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Dec 30 04:18:55 music volumio[14462]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Dec 30 04:18:55 music volumio[14462]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Dec 30 04:18:55 music volumio[14462]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Dec 30 04:18:55 music volumio[14462]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Dec 30 04:18:55 music volumio[14462]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Dec 30 04:18:55 music volumio[14462]: info: Adding plugin bluetooth to MyMusic Plugins Dec 30 04:18:55 music volumio[14462]: info: Adding plugin multiroom to MyMusic Plugins Dec 30 04:18:55 music volumio[14462]: info: Adding plugin metavolumio to MyMusic Plugins Dec 30 04:18:55 music volumio[14462]: info: Adding plugin cd_controller to MyMusic Plugins Dec 30 04:18:55 music volumio[14462]: info: Adding plugin qobuzconnect to MyMusic Plugins Dec 30 04:18:55 music volumio[14462]: info: Adding plugin smart_inputs to MyMusic Plugins Dec 30 04:18:55 music volumio[14462]: info: Adding plugin tidalconnect to MyMusic Plugins Dec 30 04:18:55 music volumio[14462]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Dec 30 04:18:55 music go-librespot[14775]: time="2025-12-30T04:18:55-05:00" level=debug msg="connected to ap-gae2.spotify.com:443" Dec 30 04:18:56 music go-librespot[14775]: time="2025-12-30T04:18:56-05:00" level=debug msg="completed keyexchange" Dec 30 04:18:56 music go-librespot[14775]: time="2025-12-30T04:18:56-05:00" level=debug msg="completed challenge" Dec 30 04:18:56 music volumio[14462]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Dec 30 04:18:56 music volumio[14462]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Dec 30 04:18:56 music volumio[14462]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 04:18:56 music volumio[14462]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 04:18:56 music volumio[14462]: info: Starting MyVolumio Remote Streaming Endpoints Dec 30 04:18:56 music volumio[14462]: info: MyVolumio login type: Token Dec 30 04:18:56 music go-librespot[14775]: time="2025-12-30T04:18:56-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 30 04:18:56 music volumio[14462]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Dec 30 04:18:56 music volumio[14462]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Dec 30 04:18:56 music go-librespot[14775]: time="2025-12-30T04:18:56-05:00" level=debug msg="connected to ap-gew1.spotify.com:80" Dec 30 04:18:57 music go-librespot[14775]: time="2025-12-30T04:18:57-05:00" level=debug msg="completed keyexchange" Dec 30 04:18:57 music go-librespot[14775]: time="2025-12-30T04:18:57-05:00" level=debug msg="completed challenge" Dec 30 04:18:57 music go-librespot[14775]: time="2025-12-30T04:18:57-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 30 04:18:57 music volumio[14462]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Dec 30 04:18:57 music volumio[14462]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Dec 30 04:18:57 music volumio[14462]: info: Streaming services startup Dec 30 04:18:57 music volumio[14462]: info: Starting Streaming Daemon Dec 30 04:18:57 music sudo[14786]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Dec 30 04:18:57 music sudo[14786]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 04:18:57 music volumio[14462]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Dec 30 04:18:57 music sudo[14786]: pam_unix(sudo:session): session closed for user root Dec 30 04:18:57 music volumio[14462]: info: Getting Spotify volume Dec 30 04:18:57 music volumio[14462]: error: Cannot start Volumio Streaming Daemon Dec 30 04:18:57 music volumio[14462]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Dec 30 04:18:57 music volumio[14462]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Dec 30 04:18:57 music volumio[14462]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Dec 30 04:18:57 music volumio[14462]: info: CoreCommandRouter::volumioGetState Dec 30 04:18:57 music volumio[14462]: info: CorePlayQueue::getTrack 0 Dec 30 04:18:57 music volumio[14462]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Dec 30 04:18:57 music volumio[14462]: SPOTIFY: SPOTIFY VOLUME undefined Dec 30 04:18:57 music volumio[14462]: SPOTIFY: VOLUMIO VOLUME 86 Dec 30 04:18:57 music volumio[14462]: info: Aligning Spotify Volume to Volumio Volume Dec 30 04:18:57 music volumio[14462]: info: CoreCommandRouter::volumioGetState Dec 30 04:18:57 music volumio[14462]: info: CorePlayQueue::getTrack 0 Dec 30 04:18:57 music volumio[14462]: info: Setting Spotify Volume from Volumio: 86 Dec 30 04:18:57 music go-librespot[14775]: time="2025-12-30T04:18:57-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 30 04:18:57 music go-librespot[14775]: time="2025-12-30T04:18:57-05:00" level=debug msg="completed keyexchange" Dec 30 04:18:57 music go-librespot[14775]: time="2025-12-30T04:18:57-05:00" level=debug msg="completed challenge" Dec 30 04:18:57 music volumio[14462]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Dec 30 04:18:57 music go-librespot[14775]: time="2025-12-30T04:18:57-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 30 04:18:58 music go-librespot[14775]: time="2025-12-30T04:18:58-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Dec 30 04:18:58 music go-librespot[14775]: time="2025-12-30T04:18:58-05:00" level=debug msg="completed keyexchange" Dec 30 04:18:58 music go-librespot[14775]: time="2025-12-30T04:18:58-05:00" level=debug msg="completed challenge" Dec 30 04:18:58 music volumio[14462]: info: MyVolumio token set successfully Dec 30 04:18:58 music volumio[14462]: info: MYVOLUMIO: Adding device Dec 30 04:18:58 music volumio[14462]: info: MYVOLUMIO: Evaluating Server Dec 30 04:18:58 music go-librespot[14775]: time="2025-12-30T04:18:58-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 30 04:18:58 music go-librespot[14775]: time="2025-12-30T04:18:58-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 " Dec 30 04:18:58 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 04:18:58 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 04:18:58 music volumio[14462]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 30 04:18:58 music volumio[14462]: Error: socket hang up Dec 30 04:18:58 music volumio[14462]: at connResetException (node:internal/errors:720:14) Dec 30 04:18:58 music volumio[14462]: at Socket.socketOnEnd (node:_http_client:519:23) Dec 30 04:18:58 music volumio[14462]: at Socket.emit (node:events:526:35) Dec 30 04:18:58 music volumio[14462]: at endReadableNT (node:internal/streams/readable:1376:12) Dec 30 04:18:58 music volumio[14462]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { Dec 30 04:18:58 music volumio[14462]: code: 'ECONNRESET', Dec 30 04:18:58 music volumio[14462]: response: undefined Dec 30 04:18:58 music volumio[14462]: } Dec 30 04:18:58 music volumio[14462]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 30 04:18:59 music sudo[14822]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-30 04:17' Dec 30 04:18:59 music sudo[14822]: 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"