Oct 27 19:47:00 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 27 19:47:00 volumio go-librespot[30520]: go-librespot daemon starting... Oct 27 19:47:00 volumio sudo[30518]: pam_unix(sudo:session): session closed for user root Oct 27 19:47:00 volumio volumio[30236]: info: Upmpdcli Daemon Started Oct 27 19:47:00 volumio go-librespot[30521]: time="2025-10-27T19:47:00Z" level=info msg="running go-librespot 0.4.0" Oct 27 19:47:00 volumio go-librespot[30521]: time="2025-10-27T19:47:00Z" level=debug msg="app state loaded" Oct 27 19:47:00 volumio go-librespot[30521]: time="2025-10-27T19:47:00Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 27 19:47:00 volumio go-librespot[30521]: time="2025-10-27T19:47:00Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Oct 27 19:47:00 volumio go-librespot[30521]: time="2025-10-27T19:47:00Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 27 19:47:00 volumio go-librespot[30521]: time="2025-10-27T19:47:00Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 27 19:47:00 volumio go-librespot[30521]: time="2025-10-27T19:47:00Z" level=info msg="zeroconf server listening on port 43505" Oct 27 19:47:00 volumio go-librespot[30521]: time="2025-10-27T19:47:00Z" level=debug msg="obtained new client token: AAAOuROQygzVDPznWvNiLKq1PnIWXmJRmshcZfw1+tsjmd+2kI2jeYALpECHZjLjpYyTfJWSwzVruVEAdcbsSdSBqbBTy3yOX9sUoen1AEzbqo4y3owRcq/TFaMT9bt5DxkrkK7Y8gPnNbHV5RLJ2NyZGEEPUAeVwQ5ZnrkdPSXEz5BqhfKmGobBdz+pemwXYYw6jzXZAZUszMkOnP3tIhoZWEzJo4MTL602UN7z5bmrKSmCAw7O" Oct 27 19:47:00 volumio go-librespot[30521]: time="2025-10-27T19:47:00Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 27 19:47:00 volumio go-librespot[30521]: time="2025-10-27T19:47:00Z" level=debug msg="completed keyexchange" Oct 27 19:47:00 volumio go-librespot[30521]: time="2025-10-27T19:47:00Z" level=debug msg="completed challenge" Oct 27 19:47:00 volumio go-librespot[30521]: time="2025-10-27T19:47:00Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 27 19:47:00 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 27 19:47:00 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 27 19:47:01 volumio volumio[30236]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Oct 27 19:47:01 volumio volumio[30236]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Oct 27 19:47:01 volumio volumio[30236]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Oct 27 19:47:01 volumio volumio[30236]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Oct 27 19:47:01 volumio volumio[30236]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Oct 27 19:47:01 volumio volumio[30236]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Oct 27 19:47:01 volumio volumio[30236]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Oct 27 19:47:01 volumio volumio[30236]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Oct 27 19:47:01 volumio volumio[30236]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Oct 27 19:47:01 volumio volumio[30236]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Oct 27 19:47:01 volumio volumio[30236]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Oct 27 19:47:01 volumio volumio[30236]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Oct 27 19:47:01 volumio volumio[30236]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Oct 27 19:47:01 volumio volumio[30236]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Oct 27 19:47:01 volumio volumio[30236]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Oct 27 19:47:01 volumio volumio[30236]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Oct 27 19:47:01 volumio volumio[30236]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Oct 27 19:47:01 volumio volumio[30236]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Oct 27 19:47:01 volumio volumio[30236]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Oct 27 19:47:01 volumio volumio[30236]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Oct 27 19:47:01 volumio volumio[30236]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Oct 27 19:47:01 volumio volumio[30236]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Oct 27 19:47:01 volumio volumio[30236]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Oct 27 19:47:01 volumio volumio[30236]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Oct 27 19:47:01 volumio volumio[30236]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Oct 27 19:47:01 volumio volumio[30236]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Oct 27 19:47:01 volumio volumio[30236]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Oct 27 19:47:01 volumio volumio[30236]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Oct 27 19:47:01 volumio volumio[30236]: info: Adding plugin bluetooth to MyMusic Plugins Oct 27 19:47:01 volumio volumio[30236]: info: Adding plugin multiroom to MyMusic Plugins Oct 27 19:47:01 volumio volumio[30236]: info: Adding plugin metavolumio to MyMusic Plugins Oct 27 19:47:01 volumio volumio[30236]: info: Adding plugin cd_controller to MyMusic Plugins Oct 27 19:47:01 volumio volumio[30236]: info: Adding plugin qobuzconnect to MyMusic Plugins Oct 27 19:47:01 volumio volumio[30236]: info: Adding plugin smart_inputs to MyMusic Plugins Oct 27 19:47:01 volumio volumio[30236]: info: Adding plugin tidalconnect to MyMusic Plugins Oct 27 19:47:01 volumio volumio[30236]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Oct 27 19:47:02 volumio volumio[30236]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Oct 27 19:47:02 volumio volumio[30236]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Oct 27 19:47:02 volumio volumio[30236]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 27 19:47:02 volumio volumio[30236]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 27 19:47:02 volumio volumio[30236]: info: Starting MyVolumio Remote Streaming Endpoints Oct 27 19:47:02 volumio volumio[30236]: info: MyVolumio login type: Token Oct 27 19:47:02 volumio volumio[30236]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Oct 27 19:47:02 volumio volumio[30236]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Oct 27 19:47:02 volumio volumio[30236]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Oct 27 19:47:02 volumio volumio[30236]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Oct 27 19:47:02 volumio volumio[30236]: info: Streaming services startup Oct 27 19:47:02 volumio volumio[30236]: info: Starting Streaming Daemon Oct 27 19:47:02 volumio sudo[30529]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Oct 27 19:47:02 volumio sudo[30529]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 27 19:47:02 volumio volumio[30236]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Oct 27 19:47:02 volumio sudo[30529]: pam_unix(sudo:session): session closed for user root Oct 27 19:47:02 volumio volumio[30236]: info: Initializing connection to go-librespot Websocket Oct 27 19:47:02 volumio volumio[30236]: error: Cannot start Volumio Streaming Daemon Oct 27 19:47:02 volumio volumio[30236]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Oct 27 19:47:02 volumio volumio[30236]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Oct 27 19:47:02 volumio volumio[30236]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 27 19:47:02 volumio volumio[30236]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Oct 27 19:47:03 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1253. Oct 27 19:47:03 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 27 19:47:03 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 27 19:47:03 volumio go-librespot[30536]: go-librespot daemon starting... Oct 27 19:47:03 volumio go-librespot[30537]: time="2025-10-27T19:47:03Z" level=info msg="running go-librespot 0.4.0" Oct 27 19:47:03 volumio go-librespot[30537]: time="2025-10-27T19:47:03Z" level=debug msg="app state loaded" Oct 27 19:47:03 volumio go-librespot[30537]: time="2025-10-27T19:47:03Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 27 19:47:03 volumio go-librespot[30537]: time="2025-10-27T19:47:03Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Oct 27 19:47:03 volumio go-librespot[30537]: time="2025-10-27T19:47:03Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 27 19:47:03 volumio go-librespot[30537]: time="2025-10-27T19:47:03Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 27 19:47:03 volumio go-librespot[30537]: time="2025-10-27T19:47:03Z" level=info msg="zeroconf server listening on port 41487" Oct 27 19:47:03 volumio go-librespot[30537]: time="2025-10-27T19:47:03Z" level=debug msg="obtained new client token: AAB7Wiy3tB3v8wA6o9otgN0OmYKk1sz3RwWGYeQ4yeHZwDHVed+q5Xf/EXmuXhmhwdjg+vDuqOBi9s19ssafU8g0CQ1Mlua7TJkEOW4Lra3GoDvYr9NB+3AwNX94xpidGx+eoSMBPw4FlLOlkE9wOIeccK24IYBeOwsifVeX9C3WvvnGhll5xNwiNnCGtjQnXoETlaZBuVUrQ3KxVNkJc0m46qKqEG2JzQ6tuSaio2k4Kb9UpJp/MP8=" Oct 27 19:47:03 volumio go-librespot[30537]: time="2025-10-27T19:47:03Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 27 19:47:03 volumio go-librespot[30537]: time="2025-10-27T19:47:03Z" level=debug msg="completed keyexchange" Oct 27 19:47:03 volumio go-librespot[30537]: time="2025-10-27T19:47:03Z" level=debug msg="completed challenge" Oct 27 19:47:03 volumio go-librespot[30537]: time="2025-10-27T19:47:03Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 27 19:47:03 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 27 19:47:03 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 27 19:47:03 volumio volumio[30236]: info: MyVolumio token set successfully Oct 27 19:47:03 volumio volumio[30236]: info: MYVOLUMIO: Adding device Oct 27 19:47:03 volumio volumio[30236]: info: MYVOLUMIO: Evaluating Server Oct 27 19:47:04 volumio volumio[30236]: info: MyVolumio status changed Oct 27 19:47:04 volumio volumio[30236]: info: Streaming services startup Oct 27 19:47:04 volumio volumio[30236]: info: Starting Streaming Daemon Oct 27 19:47:04 volumio volumio[30236]: info: Removing browser output: myVolumio user plan is not superstar Oct 27 19:47:04 volumio volumio[30236]: info: Removing audio output: Oct 27 19:47:04 volumio volumio[30236]: info: Stoppping Tunnel 1 Oct 27 19:47:04 volumio sudo[30562]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Oct 27 19:47:04 volumio sudo[30562]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 27 19:47:04 volumio sudo[30564]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service Oct 27 19:47:04 volumio sudo[30564]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 27 19:47:04 volumio 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. Oct 27 19:47:04 volumio 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. Oct 27 19:47:04 volumio sudo[30562]: pam_unix(sudo:session): session closed for user root Oct 27 19:47:04 volumio volumio[30236]: error: Cannot start Volumio Streaming Daemon Oct 27 19:47:04 volumio volumio[30236]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Oct 27 19:47:04 volumio volumio[30236]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Oct 27 19:47:04 volumio 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. Oct 27 19:47:04 volumio 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. Oct 27 19:47:04 volumio 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. Oct 27 19:47:04 volumio 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. Oct 27 19:47:04 volumio sudo[30564]: pam_unix(sudo:session): session closed for user root Oct 27 19:47:04 volumio volumio[30236]: info: Remote SSH Stopped Oct 27 19:47:04 volumio volumio[30236]: info: Setting Geolocation for MyVolumio to eu3 Oct 27 19:47:04 volumio volumio[30236]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 27 19:47:04 volumio volumio[30236]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 27 19:47:04 volumio volumio[30236]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 27 19:47:04 volumio volumio[30236]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Oct 27 19:47:04 volumio volumio[30236]: info: Cannot mount NAS NAS at system boot, trial number 4 ,retrying in 5 seconds Oct 27 19:47:05 volumio volumio[30236]: info: Updating MyVolumio device info Oct 27 19:47:05 volumio volumio[30236]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 27 19:47:05 volumio volumio[30236]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 27 19:47:05 volumio volumio[30236]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 27 19:47:05 volumio volumio[30236]: info: Initializing connection to go-librespot Websocket Oct 27 19:47:05 volumio volumio[30236]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 27 19:47:06 volumio volumio[30236]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Oct 27 19:47:07 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1254. Oct 27 19:47:07 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 27 19:47:07 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 27 19:47:07 volumio go-librespot[30567]: go-librespot daemon starting... Oct 27 19:47:07 volumio go-librespot[30568]: time="2025-10-27T19:47:07Z" level=info msg="running go-librespot 0.4.0" Oct 27 19:47:07 volumio go-librespot[30568]: time="2025-10-27T19:47:07Z" level=debug msg="app state loaded" Oct 27 19:47:07 volumio go-librespot[30568]: time="2025-10-27T19:47:07Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 27 19:47:07 volumio go-librespot[30568]: time="2025-10-27T19:47:07Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Oct 27 19:47:07 volumio go-librespot[30568]: time="2025-10-27T19:47:07Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 27 19:47:07 volumio go-librespot[30568]: time="2025-10-27T19:47:07Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 27 19:47:07 volumio go-librespot[30568]: time="2025-10-27T19:47:07Z" level=info msg="zeroconf server listening on port 37931" Oct 27 19:47:07 volumio go-librespot[30568]: time="2025-10-27T19:47:07Z" level=debug msg="obtained new client token: AAChPshysDVSj4C3HsWNydBT01qLaRRaDoRRTl1ekx8RWFL0X1nEPByLk0+78ab/EV4dzL7+0MnDLiNgOULXg2QiooLE9ZlklPEKhqEx8xxw8vBNE+QTbMz8+9CUtxynuqNlhrj0U5RoxtukbDJv/jokGqs4HZip1pRHvGPdHR3KPvoHx/MiYXlRrH1vKj8hEVvxKyKaCmr4kxFRsr9gC1QQowXcABxwXaYRh/04nf5ewhfXWUh0" Oct 27 19:47:07 volumio go-librespot[30568]: time="2025-10-27T19:47:07Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 27 19:47:07 volumio go-librespot[30568]: time="2025-10-27T19:47:07Z" level=debug msg="completed keyexchange" Oct 27 19:47:07 volumio go-librespot[30568]: time="2025-10-27T19:47:07Z" level=debug msg="completed challenge" Oct 27 19:47:07 volumio go-librespot[30568]: time="2025-10-27T19:47:07Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 27 19:47:07 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 27 19:47:07 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 27 19:47:08 volumio volumio[30236]: info: Initializing connection to go-librespot Websocket Oct 27 19:47:08 volumio volumio[30236]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 27 19:47:08 volumio volumio[30236]: info: MYVOLUMIO: Adding device Oct 27 19:47:08 volumio volumio[30236]: info: MYVOLUMIO: Evaluating Server Oct 27 19:47:09 volumio volumio[30236]: info: Setting Geolocation for MyVolumio to eu3 Oct 27 19:47:09 volumio volumio[30236]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 27 19:47:09 volumio volumio[30236]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 27 19:47:09 volumio volumio[30236]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 27 19:47:09 volumio volumio[30236]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Oct 27 19:47:09 volumio volumio[30236]: info: Cannot mount NAS at system boot, trial number 4 ,stopping Oct 27 19:47:10 volumio volumio[30236]: info: Updating MyVolumio device info Oct 27 19:47:10 volumio volumio[30236]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 27 19:47:10 volumio volumio[30236]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 27 19:47:10 volumio volumio[30236]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 27 19:47:10 volumio volumio[30236]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Oct 27 19:47:10 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1255. Oct 27 19:47:10 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 27 19:47:10 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 27 19:47:10 volumio go-librespot[30604]: go-librespot daemon starting... Oct 27 19:47:10 volumio go-librespot[30605]: time="2025-10-27T19:47:10Z" level=info msg="running go-librespot 0.4.0" Oct 27 19:47:10 volumio go-librespot[30605]: time="2025-10-27T19:47:10Z" level=debug msg="app state loaded" Oct 27 19:47:10 volumio go-librespot[30605]: time="2025-10-27T19:47:10Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 27 19:47:10 volumio go-librespot[30605]: time="2025-10-27T19:47:10Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Oct 27 19:47:10 volumio go-librespot[30605]: time="2025-10-27T19:47:10Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 27 19:47:10 volumio go-librespot[30605]: time="2025-10-27T19:47:10Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 27 19:47:10 volumio go-librespot[30605]: time="2025-10-27T19:47:10Z" level=info msg="zeroconf server listening on port 43565" Oct 27 19:47:10 volumio go-librespot[30605]: time="2025-10-27T19:47:10Z" level=debug msg="obtained new client token: AACl+dbj0kZAy2tgh45Xif77d688Rm64Vl8ZRhMyVLkdhEE3h40Lx8Q7L3eDW589X3Nu6IfCu/fpl6Rj3LNykhF1ir3o6jHuQTzegegczmKdXBFNSswkcVxRtGGdIRBE8UtjHl6R7EhX4cHNUCS9texY1fa6slWztCXJw0nMVDIYCYjbcxlevxvhIdjOcw3irF1+6pfnx0KM2QWH8MoMxQjAdX+Jb4BYv1unP9dmSmSMskqtOfoBnjU=" Oct 27 19:47:10 volumio go-librespot[30605]: time="2025-10-27T19:47:10Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 27 19:47:10 volumio go-librespot[30605]: time="2025-10-27T19:47:10Z" level=debug msg="completed keyexchange" Oct 27 19:47:10 volumio go-librespot[30605]: time="2025-10-27T19:47:10Z" level=debug msg="completed challenge" Oct 27 19:47:10 volumio go-librespot[30605]: time="2025-10-27T19:47:10Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 27 19:47:10 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 27 19:47:10 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 27 19:47:11 volumio volumio[30236]: info: Initializing connection to go-librespot Websocket Oct 27 19:47:11 volumio volumio[30236]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 27 19:47:14 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1256. Oct 27 19:47:14 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 27 19:47:14 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 27 19:47:14 volumio go-librespot[30613]: go-librespot daemon starting... Oct 27 19:47:14 volumio go-librespot[30614]: time="2025-10-27T19:47:14Z" level=info msg="running go-librespot 0.4.0" Oct 27 19:47:14 volumio go-librespot[30614]: time="2025-10-27T19:47:14Z" level=debug msg="app state loaded" Oct 27 19:47:14 volumio go-librespot[30614]: time="2025-10-27T19:47:14Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 27 19:47:14 volumio go-librespot[30614]: time="2025-10-27T19:47:14Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Oct 27 19:47:14 volumio go-librespot[30614]: time="2025-10-27T19:47:14Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 27 19:47:14 volumio go-librespot[30614]: time="2025-10-27T19:47:14Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 27 19:47:14 volumio go-librespot[30614]: time="2025-10-27T19:47:14Z" level=info msg="zeroconf server listening on port 39221" Oct 27 19:47:14 volumio go-librespot[30614]: time="2025-10-27T19:47:14Z" level=debug msg="obtained new client token: AAAtSkkiiBp44fPYVubUt8IfsumvRBUXJTDcsfYH61TY3HhzQngmSFNO/WKGGguv3f9O3f3IlfXbCm9MLQ+hdC1UFKJS48wTeHicdu/10vVg0kcphOFaqQm3O9q7eZ4S8euJ8A7n5F3v0ozdtx8zg9xrdPIq+R6hEC7N5zo4Ap7Go+rF533dGlbfwJbSYemkuMtEvboN6nH3pzx5ydkim0gQQII3D2rmG+OCujFqkGb2lC+cLF7u" Oct 27 19:47:14 volumio go-librespot[30614]: time="2025-10-27T19:47:14Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 27 19:47:14 volumio go-librespot[30614]: time="2025-10-27T19:47:14Z" level=debug msg="completed keyexchange" Oct 27 19:47:14 volumio go-librespot[30614]: time="2025-10-27T19:47:14Z" level=debug msg="completed challenge" Oct 27 19:47:14 volumio go-librespot[30614]: time="2025-10-27T19:47:14Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Oct 27 19:47:14 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 27 19:47:14 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 27 19:47:14 volumio volumio[30236]: info: Initializing connection to go-librespot Websocket Oct 27 19:47:14 volumio volumio[30236]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 27 19:47:17 volumio volumio[30236]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Oct 27 19:47:17 volumio volumio[30236]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Oct 27 19:47:17 volumio volumio[30236]: info: CoreCommandRouter::volumioGetState Oct 27 19:47:17 volumio volumio[30236]: info: CorePlayQueue::getTrack 0 Oct 27 19:47:17 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1257. Oct 27 19:47:17 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 27 19:47:17 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 27 19:47:17 volumio go-librespot[30624]: go-librespot daemon starting... Oct 27 19:47:17 volumio go-librespot[30625]: time="2025-10-27T19:47:17Z" level=info msg="running go-librespot 0.4.0" Oct 27 19:47:17 volumio go-librespot[30625]: time="2025-10-27T19:47:17Z" level=debug msg="app state loaded" Oct 27 19:47:17 volumio volumio[30236]: info: Initializing connection to go-librespot Websocket Oct 27 19:47:17 volumio go-librespot[30625]: time="2025-10-27T19:47:17Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 27 19:47:17 volumio go-librespot[30625]: time="2025-10-27T19:47:17Z" level=debug msg="new websocket client" Oct 27 19:47:17 volumio volumio[30236]: info: Connection to go-librespot Websocket established Oct 27 19:47:17 volumio go-librespot[30625]: time="2025-10-27T19:47:17Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Oct 27 19:47:17 volumio go-librespot[30625]: time="2025-10-27T19:47:17Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Oct 27 19:47:17 volumio go-librespot[30625]: time="2025-10-27T19:47:17Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Oct 27 19:47:17 volumio go-librespot[30625]: time="2025-10-27T19:47:17Z" level=info msg="zeroconf server listening on port 43565" Oct 27 19:47:17 volumio go-librespot[30625]: time="2025-10-27T19:47:17Z" level=debug msg="obtained new client token: AAA2KA7lDXK+OkkaHw+XbhiAnMTejNbMay7HhzTBvcZHXZFEnRI6Tdu7BuNRd7zYKTvhhXAzCy/hbWt+lqf7v4AgZL/MGOzoeBbQSxGwEZ9shzLKz6VMgk3Bj0zVtCQdKe2ViXDRGGC5iyb4HJFXWUUC5IiYf7soQpmiqFjix9R8zHLjuewfFIfv4DjremCPZ8IT0QI3MIXjLzpcwbOfdpi62bT8StQcvGDSqm16V8kDrJQGJ+1Snc4=" Oct 27 19:47:17 volumio go-librespot[30625]: time="2025-10-27T19:47:17Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 27 19:47:17 volumio go-librespot[30625]: time="2025-10-27T19:47:17Z" level=debug msg="completed keyexchange" Oct 27 19:47:17 volumio go-librespot[30625]: time="2025-10-27T19:47:17Z" level=debug msg="completed challenge" Oct 27 19:47:17 volumio go-librespot[30625]: time="2025-10-27T19:47:17Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 27 19:47:17 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 27 19:47:17 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 27 19:47:17 volumio volumio[30236]: info: Connection to go-librespot Websocket closed Oct 27 19:47:20 volumio volumio[30236]: info: Getting Spotify volume Oct 27 19:47:20 volumio volumio[30236]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 27 19:47:20 volumio volumio[30236]: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 27 19:47:20 volumio volumio[30236]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Oct 27 19:47:20 volumio volumio[30236]: errno: -111, Oct 27 19:47:20 volumio volumio[30236]: code: 'ECONNREFUSED', Oct 27 19:47:20 volumio volumio[30236]: syscall: 'connect', Oct 27 19:47:20 volumio volumio[30236]: address: '127.0.0.1', Oct 27 19:47:20 volumio volumio[30236]: port: 9879, Oct 27 19:47:20 volumio volumio[30236]: response: undefined Oct 27 19:47:20 volumio volumio[30236]: } Oct 27 19:47:20 volumio volumio[30236]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 27 19:47:20 volumio sudo[30660]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-10-27 19:46' Oct 27 19:47:20 volumio sudo[30660]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 27 19:47:20 volumio sudo[30660]: pam_unix(sudo:session): session closed for user root Oct 27 19:47:20 volumio volumio-remote-updater[874]: [2025-10-27 19:47:20] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Oct 27 19:47:20 volumio volumio-remote-updater[874]: [2025-10-27 19:47:20] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Oct 27 19:47:20 volumio systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Oct 27 19:47:20 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1258. Oct 27 19:47:20 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 27 19:47:20 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 27 19:47:20 volumio go-librespot[30665]: go-librespot daemon starting... Oct 27 19:47:20 volumio systemd[1]: volumio.service: Failed with result 'exit-code'. Oct 27 19:47:20 volumio systemd[1]: volumio.service: Consumed 11.236s CPU time. Oct 27 19:47:20 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Oct 27 19:47:20 volumio go-librespot[30667]: time="2025-10-27T19:47:20Z" level=info msg="running go-librespot 0.4.0" Oct 27 19:47:20 volumio go-librespot[30667]: time="2025-10-27T19:47:20Z" level=debug msg="app state loaded" Oct 27 19:47:20 volumio go-librespot[30667]: time="2025-10-27T19:47:20Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 27 19:47:20 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Oct 27 19:47:21 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 1018. Oct 27 19:47:21 volumio go-librespot[30667]: time="2025-10-27T19:47:21Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Oct 27 19:47:21 volumio go-librespot[30667]: time="2025-10-27T19:47:21Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Oct 27 19:47:21 volumio go-librespot[30667]: time="2025-10-27T19:47:21Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Oct 27 19:47:21 volumio go-librespot[30667]: time="2025-10-27T19:47:21Z" level=info msg="zeroconf server listening on port 42501" Oct 27 19:47:21 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Oct 27 19:47:21 volumio systemd[1]: Stopped volumio.service - Volumio Backend Module. Oct 27 19:47:21 volumio systemd[1]: volumio.service: Consumed 11.236s CPU time. Oct 27 19:47:21 volumio systemd[1]: Started volumio.service - Volumio Backend Module. Oct 27 19:47:21 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Oct 27 19:47:21 volumio go-librespot[30667]: time="2025-10-27T19:47:21Z" level=debug msg="obtained new client token: AAAklDbzWOuxYclaTsxjeQyNyks5811UfFYwJxeLxn5GMwlanKUx7W5mBYLPWqt96/xLcX9zEdp9Un7s/U+71uOfscDhnmYiH2ySnhSOKmlybdIKgual7gM+p9O7EYLj4wZmQ7p+GY+U03UjxKghjQLRTQH0kqyaQeNmlFeFDH4E8tCRNPtey4XLKvUfHk+N5Yo6xqs+ecttOralE+uk0dhbjhi8YSr+B2UyDiYdKPsHNF3qOtl0" Oct 27 19:47:21 volumio go-librespot[30667]: time="2025-10-27T19:47:21Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 27 19:47:21 volumio go-librespot[30667]: time="2025-10-27T19:47:21Z" level=debug msg="completed keyexchange" Oct 27 19:47:21 volumio go-librespot[30667]: time="2025-10-27T19:47:21Z" level=debug msg="completed challenge" Oct 27 19:47:21 volumio go-librespot[30667]: time="2025-10-27T19:47:21Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 27 19:47:21 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 27 19:47:21 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 27 19:47:21 volumio volumio[30681]: info: ------------------------------------------- Oct 27 19:47:21 volumio volumio[30681]: info: ----- Volumio3 ---- Oct 27 19:47:21 volumio volumio[30681]: info: ------------------------------------------- Oct 27 19:47:21 volumio volumio[30681]: info: ----- System startup ---- Oct 27 19:47:21 volumio volumio[30681]: info: ------------------------------------------- Oct 27 19:47:21 volumio volumio[30681]: info: MYVOLUMIO Environment detected Oct 27 19:47:21 volumio volumio[30681]: info: Plugin folders cleanup Oct 27 19:47:21 volumio volumio[30681]: info: Scanning into folder /volumio/app/plugins/ Oct 27 19:47:21 volumio volumio[30681]: info: Scanning category audio_interface Oct 27 19:47:21 volumio volumio[30681]: info: Scanning category miscellanea Oct 27 19:47:21 volumio volumio[30681]: info: Scanning category music_service Oct 27 19:47:21 volumio volumio[30681]: info: Scanning category plugins.json Oct 27 19:47:21 volumio volumio[30681]: info: Scanning category system_controller Oct 27 19:47:21 volumio volumio[30681]: info: Scanning category user_interface Oct 27 19:47:21 volumio volumio[30681]: info: Scanning into folder /data/plugins/ Oct 27 19:47:21 volumio volumio[30681]: info: Scanning category music_service Oct 27 19:47:21 volumio volumio[30681]: info: Scanning category user_interface Oct 27 19:47:21 volumio volumio[30681]: info: Plugin folders cleanup completed Oct 27 19:47:21 volumio volumio[30681]: info: ------------------------------------------- Oct 27 19:47:21 volumio volumio[30681]: info: ----- Core plugins startup ---- Oct 27 19:47:21 volumio volumio[30681]: info: ------------------------------------------- Oct 27 19:47:21 volumio volumio[30681]: info: Loading plugins from folder /volumio/app/plugins/ Oct 27 19:47:21 volumio volumio[30681]: info: Adding plugin upnp to MyMusic Plugins Oct 27 19:47:21 volumio volumio[30681]: info: Adding plugin airplay_emulation to MyMusic Plugins Oct 27 19:47:21 volumio volumio[30681]: info: Adding plugin upnp_browser to MyMusic Plugins Oct 27 19:47:21 volumio volumio[30681]: info: Loading plugins from folder /data/plugins/ Oct 27 19:47:21 volumio volumio[30681]: info: Loading plugin "system"... Oct 27 19:47:21 volumio volumio[30681]: info: Loading plugin "appearance"... Oct 27 19:47:22 volumio volumio[30681]: info: Loading plugin "network"... Oct 27 19:47:22 volumio volumio[30681]: info: Refreshing Cached IP Addresses Oct 27 19:47:22 volumio sudo[30709]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 27 19:47:22 volumio sudo[30709]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 27 19:47:22 volumio sudo[30711]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 27 19:47:22 volumio sudo[30711]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 27 19:47:22 volumio sudo[30709]: pam_unix(sudo:session): session closed for user root Oct 27 19:47:22 volumio volumio[30681]: info: Loading plugin "services"... Oct 27 19:47:22 volumio sudo[30711]: pam_unix(sudo:session): session closed for user root Oct 27 19:47:22 volumio volumio[30681]: info: Loading plugin "alsa_controller"... Oct 27 19:47:22 volumio volumio[30681]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 27 19:47:22 volumio volumio[30681]: info: Loading plugin "wizard"... Oct 27 19:47:22 volumio volumio[30681]: info: Loading plugin "networkfs"... Oct 27 19:47:22 volumio volumio[30681]: info: Cannot mount NAS NAS at system boot, trial number 1 ,retrying in 5 seconds Oct 27 19:47:22 volumio volumio[30681]: info: Starting Udev Watcher for removable devices Oct 27 19:47:22 volumio volumio[30681]: info: Ignoring mount for partition: boot Oct 27 19:47:22 volumio volumio[30681]: info: Ignoring mount for partition: volumio Oct 27 19:47:22 volumio volumio[30681]: info: Ignoring mount for partition: volumio_data Oct 27 19:47:22 volumio volumio[30681]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 27 19:47:22 volumio volumio[30681]: info: Loading plugin "volumio_command_line_client"... Oct 27 19:47:22 volumio volumio[30681]: info: Loading plugin "upnp"... Oct 27 19:47:22 volumio volumio[30681]: info: [1761594442201] Starting Upmpd Daemon Oct 27 19:47:22 volumio volumio[30681]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 27 19:47:22 volumio volumio[30681]: info: Loading plugin "my_music"... Oct 27 19:47:22 volumio volumio[30681]: info: Loading plugin "mpd"... Oct 27 19:47:22 volumio volumio[30681]: info: Loading plugin "upnp_browser"... Oct 27 19:47:22 volumio volumio[30681]: info: Loading plugin "alarm-clock"... Oct 27 19:47:22 volumio volumio[30681]: info: Loading plugin "airplay_emulation"... Oct 27 19:47:22 volumio volumio[30681]: info: Starting Shairport Sync Oct 27 19:47:22 volumio volumio[30681]: info: Loading plugin "last_100"... Oct 27 19:47:22 volumio volumio[30681]: info: Loading plugin "webradio"... Oct 27 19:47:22 volumio volumio[30681]: info: Loading plugin "i2s_dacs"... Oct 27 19:47:22 volumio volumio[30681]: info: I2S DAC not set, start Auto-detection Oct 27 19:47:22 volumio volumio[30681]: info: Loading plugin "volumiodiscovery"... Oct 27 19:47:22 volumio volumio[30681]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Oct 27 19:47:22 volumio node[30681]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Oct 27 19:47:22 volumio volumio[30681]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 27 19:47:22 volumio node[30681]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 27 19:47:22 volumio volumio[30681]: *** WARNING *** For more information see Oct 27 19:47:22 volumio node[30681]: *** WARNING *** For more information see Oct 27 19:47:22 volumio volumio[30681]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Oct 27 19:47:22 volumio node[30681]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Oct 27 19:47:22 volumio volumio[30681]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 27 19:47:22 volumio node[30681]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 27 19:47:22 volumio volumio[30681]: *** WARNING *** For more information see Oct 27 19:47:22 volumio node[30681]: *** WARNING *** For more information see Oct 27 19:47:22 volumio volumio[30681]: info: Applying required configuration parameters for plugin volumiodiscovery Oct 27 19:47:22 volumio volumio[30681]: info: Discovery: Started advertising with name: Volumio Oct 27 19:47:22 volumio volumio[30681]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 27 19:47:22 volumio volumio[30681]: info: Loading plugin "spop"... Oct 27 19:47:23 volumio volumio[30681]: info: Loading plugin "ytcr"... Oct 27 19:47:24 volumio volumio[30681]: info: Loading plugin "outputs"... Oct 27 19:47:24 volumio volumio[30681]: info: Loading plugin "albumart"... Oct 27 19:47:24 volumio volumio[30681]: info: Plugin example_plugin is not enabled Oct 27 19:47:24 volumio volumio[30681]: info: Loading plugin "inputs"... Oct 27 19:47:24 volumio volumio[30681]: info: Loading plugin "updater_comm"... Oct 27 19:47:24 volumio volumio[30681]: info: Plugin mpdemulation is not enabled Oct 27 19:47:24 volumio volumio[30681]: info: Loading plugin "rest_api"... Oct 27 19:47:24 volumio volumio[30681]: info: Loading plugin "websocket"... Oct 27 19:47:24 volumio volumio[30681]: info: Starting Socket.io Server version 1.7.4 Oct 27 19:47:24 volumio volumio[30681]: info: Loading plugin "Systeminfo"... Oct 27 19:47:24 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1259. Oct 27 19:47:24 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 27 19:47:24 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 27 19:47:24 volumio go-librespot[30751]: go-librespot daemon starting... Oct 27 19:47:24 volumio go-librespot[30752]: time="2025-10-27T19:47:24Z" level=info msg="running go-librespot 0.4.0" Oct 27 19:47:24 volumio go-librespot[30752]: time="2025-10-27T19:47:24Z" level=debug msg="app state loaded" Oct 27 19:47:24 volumio go-librespot[30752]: time="2025-10-27T19:47:24Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 27 19:47:24 volumio volumio[30681]: info: Loading i18n strings for locale en Oct 27 19:47:24 volumio volumio[30681]: Updating browse sources language Oct 27 19:47:24 volumio volumio[30681]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 27 19:47:24 volumio volumio[30741]: Forking 3 albumart workers Oct 27 19:47:24 volumio volumio[30681]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 27 19:47:24 volumio volumio[30681]: info: CoreCommandRouter::initPlayerControls Oct 27 19:47:24 volumio volumio[30681]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 27 19:47:24 volumio volumio[30681]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 27 19:47:24 volumio volumio[30681]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 27 19:47:24 volumio volumio[30681]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 27 19:47:24 volumio volumio[30681]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 27 19:47:24 volumio volumio[30681]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 27 19:47:24 volumio volumio[30681]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 27 19:47:24 volumio volumio[30681]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 27 19:47:24 volumio volumio[30681]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 27 19:47:24 volumio volumio[30681]: Express server listening on port 3000 Oct 27 19:47:24 volumio volumio[30681]: [Metrics] WebUI: 2s 944.61ms Oct 27 19:47:24 volumio volumio[30681]: info: CoreStateMachine::resetVolumioState Oct 27 19:47:24 volumio volumio[30681]: info: CoreStateMachine::getcurrentVolume Oct 27 19:47:24 volumio volumio[30681]: info: CoreCommandRouter::volumioRetrievevolume Oct 27 19:47:24 volumio volumio[30681]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 27 19:47:24 volumio go-librespot[30752]: time="2025-10-27T19:47:24Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Oct 27 19:47:24 volumio go-librespot[30752]: time="2025-10-27T19:47:24Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 27 19:47:24 volumio go-librespot[30752]: time="2025-10-27T19:47:24Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 27 19:47:24 volumio volumio[30681]: info: Cannot read play queue from file Oct 27 19:47:24 volumio go-librespot[30752]: time="2025-10-27T19:47:24Z" level=info msg="zeroconf server listening on port 45345" Oct 27 19:47:24 volumio volumio[30681]: info: Volumio Network Manager: Network status updated: 1 Oct 27 19:47:24 volumio go-librespot[30752]: time="2025-10-27T19:47:24Z" level=debug msg="obtained new client token: AADv0KYU8spjcehpzrxsRIrEZomQjyj40eJW/xChdy31Fgy3Pl55iZeUMTS9gM6ug8rJdRIqmcEioKdYdZ1mQ+GSOWm0E+qM3tNHGR13BKNBnOxPh+LjI6dn13rnmJtG0nSH1nIweqDHfF9q/6F0h4gsGnGobnoEU6L3hIiG5m1gDyDKqdKZQsGAKUBxwSmG2ugnXDPON8Lzh2gwEmBrWkSYPiSt2pYIYdiRFycQHvgMM+ehITZ9R8g=" Oct 27 19:47:24 volumio volumio[30681]: info: VolumeController:: Volume=33 Mute =false Oct 27 19:47:24 volumio volumio[30681]: info: CoreStateMachine::pushState Oct 27 19:47:24 volumio volumio[30681]: info: CorePlayQueue::getTrack 0 Oct 27 19:47:24 volumio volumio[30681]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 27 19:47:24 volumio go-librespot[30752]: time="2025-10-27T19:47:24Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 27 19:47:24 volumio volumio[30681]: info: CoreCommandRouter::volumioPushState Oct 27 19:47:24 volumio volumio[30681]: info: CoreStateMachine::updateTrackBlock Oct 27 19:47:24 volumio volumio[30681]: info: CorePlayQueue::getTrackBlock Oct 27 19:47:24 volumio volumio[30681]: info: CoreCommandRouter::volumioRetrievevolume Oct 27 19:47:24 volumio volumio[30681]: info: CoreStateMachine::setRepeat null single undefined Oct 27 19:47:24 volumio volumio[30681]: info: CoreStateMachine::pushState Oct 27 19:47:24 volumio volumio[30681]: info: CorePlayQueue::getTrack 0 Oct 27 19:47:24 volumio volumio[30681]: info: CoreCommandRouter::volumioPushState Oct 27 19:47:24 volumio volumio[30681]: info: CoreStateMachine::setRandom null Oct 27 19:47:24 volumio go-librespot[30752]: time="2025-10-27T19:47:24Z" level=debug msg="completed keyexchange" Oct 27 19:47:24 volumio volumio[30681]: info: CoreStateMachine::pushState Oct 27 19:47:24 volumio go-librespot[30752]: time="2025-10-27T19:47:24Z" level=debug msg="completed challenge" Oct 27 19:47:24 volumio volumio[30681]: info: CorePlayQueue::getTrack 0 Oct 27 19:47:24 volumio volumio[30681]: info: CoreCommandRouter::volumioPushState Oct 27 19:47:24 volumio volumio[30681]: info: Setting Device type: Raspberry PI Oct 27 19:47:24 volumio volumio[30681]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Oct 27 19:47:24 volumio volumio[30681]: info: USB Boot Capable - System SBC Revision found in cpuinfo: b04170 Oct 27 19:47:24 volumio volumio[30681]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Oct 27 19:47:24 volumio go-librespot[30752]: time="2025-10-27T19:47:24Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 27 19:47:24 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 27 19:47:24 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 27 19:47:24 volumio volumio[30681]: info: Completed loading Core Plugins Oct 27 19:47:24 volumio volumio[30681]: info: Preparing to generate the ALSA configuration file Oct 27 19:47:24 volumio volumio[30681]: info: Discovery: adding 70853f74-8210-4683-a3fa-e1217517bd40 Oct 27 19:47:24 volumio volumio[30681]: info: Discovery: Found device Volumio Oct 27 19:47:24 volumio volumio[30681]: info: CoreCommandRouter::volumioGetState Oct 27 19:47:24 volumio volumio[30681]: info: CorePlayQueue::getTrack 0 Oct 27 19:47:24 volumio volumio[30681]: info: VolumeController:: Volume=33 Mute =false Oct 27 19:47:24 volumio volumio[30681]: info: CoreStateMachine::pushState Oct 27 19:47:24 volumio volumio[30681]: info: CorePlayQueue::getTrack 0 Oct 27 19:47:24 volumio volumio[30681]: info: CoreCommandRouter::volumioPushState Oct 27 19:47:24 volumio volumio[30681]: info: Discovery: this is already registered, 70853f74-8210-4683-a3fa-e1217517bd40 Oct 27 19:47:24 volumio volumio[30681]: info: Discovery: Found device Volumio Oct 27 19:47:24 volumio volumio[30681]: info: CoreCommandRouter::volumioGetState Oct 27 19:47:24 volumio volumio[30681]: info: CorePlayQueue::getTrack 0 Oct 27 19:47:24 volumio volumio[30681]: info: Asound.conf file unchanged, so no further update is needed Oct 27 19:47:24 volumio volumio[30681]: info: Output device has changed, restarting MPD Oct 27 19:47:24 volumio volumio[30681]: info: Output device has changed, restarting Shairport Sync Oct 27 19:47:24 volumio volumio[30681]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 27 19:47:24 volumio volumio[30681]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 27 19:47:24 volumio sudo[30807]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 27 19:47:24 volumio sudo[30807]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 27 19:47:24 volumio sudo[30809]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 27 19:47:24 volumio sudo[30809]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 27 19:47:24 volumio sudo[30807]: pam_unix(sudo:session): session closed for user root Oct 27 19:47:24 volumio volumio[30681]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 27 19:47:24 volumio volumio[30681]: info: ___________ START PLUGINS ___________ Oct 27 19:47:24 volumio volumio[30681]: info: ControllerMpd::onStart: Initializing MPD Oct 27 19:47:24 volumio volumio[30681]: info: Creating MPD Configuration file Oct 27 19:47:24 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Oct 27 19:47:24 volumio volumio[30681]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 27 19:47:24 volumio volumio[30681]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 27 19:47:24 volumio volumio[30681]: info: [1761594444760] CoreMusicLibrary::Adding element Media Servers Oct 27 19:47:24 volumio volumio[30681]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 27 19:47:24 volumio sudo[30817]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 27 19:47:24 volumio sudo[30817]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 27 19:47:24 volumio sudo[30817]: pam_unix(sudo:session): session closed for user root Oct 27 19:47:24 volumio systemd[1]: mpd.service: Deactivated successfully. Oct 27 19:47:24 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Oct 27 19:47:24 volumio systemd[1]: mpd.socket: Deactivated successfully. Oct 27 19:47:24 volumio volumio[30681]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 27 19:47:24 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Oct 27 19:47:24 volumio sudo[30819]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 27 19:47:24 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Oct 27 19:47:24 volumio sudo[30819]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 27 19:47:24 volumio volumio[30681]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 27 19:47:24 volumio volumio[30681]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 27 19:47:24 volumio volumio[30681]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 27 19:47:24 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Oct 27 19:47:24 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Oct 27 19:47:24 volumio volumio[30681]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 27 19:47:24 volumio systemd[1]: mpd.service: Deactivated successfully. Oct 27 19:47:24 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Oct 27 19:47:24 volumio volumio[30760]: Starting albumart workers Oct 27 19:47:24 volumio systemd[1]: mpd.socket: Deactivated successfully. Oct 27 19:47:24 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Oct 27 19:47:24 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Oct 27 19:47:24 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Oct 27 19:47:24 volumio volumio[30681]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 27 19:47:24 volumio volumio[30681]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 27 19:47:24 volumio volumio[30681]: info: [1761594444837] CoreMusicLibrary::Adding element Last_100 Oct 27 19:47:24 volumio volumio[30681]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 27 19:47:24 volumio volumio[30681]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 27 19:47:24 volumio volumio[30681]: info: [1761594444838] CoreMusicLibrary::Adding element Webradio Oct 27 19:47:24 volumio volumio[30681]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 27 19:47:24 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Oct 27 19:47:24 volumio volumio[30681]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 27 19:47:24 volumio volumio[30681]: info: Initializing BBC Radios Oct 27 19:47:24 volumio volumio[30758]: Starting albumart workers Oct 27 19:47:24 volumio volumio[30681]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 27 19:47:24 volumio volumio[30681]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 27 19:47:24 volumio volumio[30681]: info: Creating Spotify config file Oct 27 19:47:24 volumio volumio[30681]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 27 19:47:24 volumio sudo[30833]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Oct 27 19:47:24 volumio sudo[30833]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Oct 27 19:47:24 volumio sudo[30833]: pam_unix(sudo:session): session closed for user root Oct 27 19:47:25 volumio volumio[30759]: Starting albumart workers Oct 27 19:47:25 volumio volumio[30681]: info: Volumio Calling Home Oct 27 19:47:25 volumio volumio[30681]: info: MPD Permissions set Oct 27 19:47:25 volumio volumio[30681]: info: MPD Permissions set Oct 27 19:47:25 volumio volumio[30681]: info: Volumio called home Oct 27 19:47:25 volumio volumio[30681]: info: Spotify config file written Oct 27 19:47:25 volumio volumio[30681]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 1 Oct 27 19:47:25 volumio sudo[30865]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Oct 27 19:47:25 volumio sudo[30865]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 27 19:47:25 volumio volumio[30681]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 27 19:47:25 volumio volumio[30681]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 27 19:47:25 volumio volumio[30681]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 27 19:47:25 volumio volumio[30681]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 27 19:47:25 volumio volumio[30681]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 27 19:47:25 volumio volumio[30681]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 27 19:47:25 volumio volumio[30681]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 27 19:47:25 volumio volumio[30681]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 27 19:47:25 volumio volumio[30681]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 27 19:47:25 volumio volumio[30681]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 27 19:47:25 volumio volumio[30681]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 27 19:47:25 volumio volumio[30681]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 27 19:47:25 volumio volumio[30681]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 27 19:47:25 volumio volumio[30681]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 27 19:47:25 volumio volumio[30681]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 27 19:47:25 volumio volumio[30681]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 27 19:47:25 volumio volumio[30681]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 27 19:47:25 volumio volumio[30681]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 27 19:47:25 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 27 19:47:25 volumio volumio[30681]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 27 19:47:25 volumio volumio[30681]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 27 19:47:25 volumio volumio[30681]: info: No need to fix Spotify hosts Oct 27 19:47:25 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 27 19:47:25 volumio go-librespot[30880]: go-librespot daemon starting... Oct 27 19:47:25 volumio sudo[30865]: pam_unix(sudo:session): session closed for user root Oct 27 19:47:25 volumio volumio[30681]: info: Starting Shairport Sync Oct 27 19:47:25 volumio volumio[30681]: info: Starting Shairport Sync Oct 27 19:47:25 volumio go-librespot[30884]: time="2025-10-27T19:47:25Z" level=info msg="running go-librespot 0.4.0" Oct 27 19:47:25 volumio go-librespot[30884]: time="2025-10-27T19:47:25Z" level=debug msg="app state loaded" Oct 27 19:47:25 volumio go-librespot[30884]: time="2025-10-27T19:47:25Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 27 19:47:25 volumio volumio[30681]: info: Starting Shairport Sync Oct 27 19:47:25 volumio sudo[30891]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 27 19:47:25 volumio sudo[30891]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 27 19:47:25 volumio sudo[30893]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 27 19:47:25 volumio sudo[30893]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 27 19:47:25 volumio sudo[30896]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 27 19:47:25 volumio sudo[30896]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 27 19:47:25 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Oct 27 19:47:25 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Oct 27 19:47:25 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Oct 27 19:47:25 volumio systemd[1]: shairport-sync.service: Consumed 1.571s CPU time. Oct 27 19:47:25 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Oct 27 19:47:25 volumio sudo[30893]: pam_unix(sudo:session): session closed for user root Oct 27 19:47:25 volumio sudo[30896]: pam_unix(sudo:session): session closed for user root Oct 27 19:47:25 volumio sudo[30891]: pam_unix(sudo:session): session closed for user root Oct 27 19:47:25 volumio go-librespot[30884]: time="2025-10-27T19:47:25Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Oct 27 19:47:25 volumio go-librespot[30884]: time="2025-10-27T19:47:25Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Oct 27 19:47:25 volumio go-librespot[30884]: time="2025-10-27T19:47:25Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Oct 27 19:47:25 volumio go-librespot[30884]: time="2025-10-27T19:47:25Z" level=info msg="zeroconf server listening on port 34513" Oct 27 19:47:25 volumio volumio[30681]: info: Shairport-Sync Started Oct 27 19:47:25 volumio volumio[30681]: Error adding Membership: Error: addMembership EINVAL Oct 27 19:47:25 volumio volumio[30681]: info: Shairport-Sync Started Oct 27 19:47:25 volumio volumio[30681]: info: Shairport-Sync Started Oct 27 19:47:25 volumio volumio[30681]: info: CoreCommandRouter::volumioGetState Oct 27 19:47:25 volumio volumio[30681]: info: CorePlayQueue::getTrack 0 Oct 27 19:47:25 volumio volumio[30681]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Oct 27 19:47:25 volumio volumio[30681]: SPOTIFY: BQD-JsuTcfvM7SDYw3eLHtFNc-RF-u6QlvR20A2AMYdz4d9hMUujUBPM1kcUPWv3g8VSaWzeqrZOTBo9U_jhTXJMNdR5MDO9-qvpnbgsYqhB4uh2jBaGQu_oQGanZ_e4XcrB99TwRnsne-bigGqNrM7RIut3730DhJZjuwZ8D33LVDYTFMYC7CyK2ri3VLap6G3zJO2tqQqwKJIGqMKsrRjNFstjMyxapF16oqMACo_lZ_AcRt6PSjHGIy6df2FwnUZgdu5Q2sjrnArQctn3g3WvGlF1uJ4LRy19abAqhT0bpRXZkxQ Oct 27 19:47:25 volumio volumio[30681]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Oct 27 19:47:25 volumio volumio[30681]: info: New Spotify access token = BQD-JsuTcfvM7SDYw3eLHtFNc-RF-u6QlvR20A2AMYdz4d9hMUujUBPM1kcUPWv3g8VSaWzeqrZOTBo9U_jhTXJMNdR5MDO9-qvpnbgsYqhB4uh2jBaGQu_oQGanZ_e4XcrB99TwRnsne-bigGqNrM7RIut3730DhJZjuwZ8D33LVDYTFMYC7CyK2ri3VLap6G3zJO2tqQqwKJIGqMKsrRjNFstjMyxapF16oqMACo_lZ_AcRt6PSjHGIy6df2FwnUZgdu5Q2sjrnArQctn3g3WvGlF1uJ4LRy19abAqhT0bpRXZkxQ Oct 27 19:47:25 volumio volumio[30681]: info: Spotify credentials grant success - running version from March 24, 2019 Oct 27 19:47:25 volumio go-librespot[30884]: time="2025-10-27T19:47:25Z" level=debug msg="obtained new client token: AADfZsx8kP+r2iX5jqlrxG/0zo7VoqYOvVxTaqoakfU8wMJEEudE/2zaiH7HMEXKCSYX64ppD5URtQIjtCP+GzykbYDGXt7J+d2Cee6BC5LADgvdQ5qO9Q/hGmgTTp5CQsDno4ZhQi/VUOWcn5P6SRHUOEttvgRtRzGZsrz0GZDXjZbkBTGVOcjZDEORbHZXSJyS8/wHMakL4deLlIHnT0sWzSI2n03S8Rml0JIn0M87HmNagwqmYEU=" Oct 27 19:47:25 volumio go-librespot[30884]: time="2025-10-27T19:47:25Z" level=warning msg="failed to connect to AP ap-gew1.spotify.com:4070, retrying with a different AP" error="dial tcp 104.199.65.9:4070: connect: connection refused" Oct 27 19:47:25 volumio go-librespot[30884]: time="2025-10-27T19:47:25Z" level=warning msg="failed to connect to AP ap-gew1.spotify.com:443, retrying with a different AP" error="dial tcp 104.199.65.9:443: connect: connection refused" Oct 27 19:47:25 volumio go-librespot[30884]: time="2025-10-27T19:47:25Z" level=debug msg="connected to ap-gew1.spotify.com:80" Oct 27 19:47:25 volumio go-librespot[30884]: time="2025-10-27T19:47:25Z" level=debug msg="completed keyexchange" Oct 27 19:47:25 volumio go-librespot[30884]: time="2025-10-27T19:47:25Z" level=debug msg="completed challenge" Oct 27 19:47:25 volumio volumio[30681]: SPOTIFY: User informations: {"country":"DE","display_name":"lapman","email":"ylm19961214@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/31hyzsop5elyyfayaiyk5tmkxmky"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/31hyzsop5elyyfayaiyk5tmkxmky","id":"31hyzsop5elyyfayaiyk5tmkxmky","images":[],"product":"free","type":"user","uri":"spotify:user:31hyzsop5elyyfayaiyk5tmkxmky"} Oct 27 19:47:25 volumio volumio[30681]: info: Spotify Successfully logged in Oct 27 19:47:25 volumio volumio[30681]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 27 19:47:25 volumio volumio[30681]: info: [1761594445666] CoreMusicLibrary::Adding element Spotify Oct 27 19:47:25 volumio volumio[30681]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 27 19:47:25 volumio volumio[30681]: Cannot find translation for source Spotify Oct 27 19:47:25 volumio go-librespot[30884]: time="2025-10-27T19:47:25Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 27 19:47:25 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 27 19:47:25 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 27 19:47:25 volumio mpd[30848]: 2025-10-27T19:47:25 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Oct 27 19:47:25 volumio systemd[1]: Started mpd.service - Music Player Daemon. Oct 27 19:47:25 volumio sudo[30809]: pam_unix(sudo:session): session closed for user root Oct 27 19:47:25 volumio sudo[30819]: pam_unix(sudo:session): session closed for user root Oct 27 19:47:25 volumio volumio[30681]: error: MPD error: The expression evaluated to a falsy value: Oct 27 19:47:25 volumio volumio[30681]: assert.ok(self.idling) Oct 27 19:47:25 volumio volumio[30681]: error: The expression evaluated to a falsy value: Oct 27 19:47:25 volumio volumio[30681]: assert.ok(self.idling) Oct 27 19:47:25 volumio volumio[30681]: info: MPD running with PID30848 Oct 27 19:47:25 volumio volumio[30681]: ,establishing connection Oct 27 19:47:25 volumio volumio[30681]: error: updateQueue error: null Oct 27 19:47:25 volumio volumio[30681]: error: updateQueue error: null Oct 27 19:47:25 volumio volumio-remote-updater[874]: [2025-10-27 19:47:25] [connect] Successful connection Oct 27 19:47:25 volumio volumio[30681]: info: [yt-cast-receiver] DIAL server listening on port 8098 Oct 27 19:47:25 volumio volumio[30681]: info: CoreCommandRouter::volumioRetrievevolume Oct 27 19:47:25 volumio volumio-remote-updater[874]: [2025-10-27 19:47:25] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1761594445 101 Oct 27 19:47:25 volumio volumio[30681]: 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: 2 Oct 27 19:47:25 volumio volumio[30681]: info: VolumeController:: Volume=33 Mute =false Oct 27 19:47:25 volumio volumio[30681]: info: CoreCommandRouter::volumioGetState Oct 27 19:47:25 volumio volumio[30681]: info: CorePlayQueue::getTrack 0 Oct 27 19:47:25 volumio volumio[30681]: info: CoreStateMachine::pushState Oct 27 19:47:25 volumio volumio[30681]: info: CorePlayQueue::getTrack 0 Oct 27 19:47:25 volumio volumio[30681]: info: CoreCommandRouter::volumioPushState Oct 27 19:47:26 volumio volumio[30681]: info: Completed starting Core Plugins Oct 27 19:47:26 volumio volumio[30681]: info: ------------------------------------------- Oct 27 19:47:26 volumio volumio[30681]: info: ----- MyVolumio plugins startup ---- Oct 27 19:47:26 volumio volumio[30681]: info: ------------------------------------------- Oct 27 19:47:26 volumio volumio[30681]: info: [MyVolumio PluginManager] Fetching plans data.... Oct 27 19:47:27 volumio volumio[30681]: info: Cannot mount NAS NAS at system boot, trial number 2 ,retrying in 5 seconds Oct 27 19:47:28 volumio volumio[30681]: info: go-librespot daemon successfully initialized Oct 27 19:47:28 volumio sudo[30923]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Oct 27 19:47:28 volumio sudo[30923]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 27 19:47:28 volumio sudo[30925]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Oct 27 19:47:28 volumio sudo[30925]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 27 19:47:28 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1260. Oct 27 19:47:28 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 27 19:47:28 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 27 19:47:28 volumio go-librespot[30928]: go-librespot daemon starting... Oct 27 19:47:28 volumio systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Oct 27 19:47:28 volumio systemd[1]: mpd_monitor.service: Deactivated successfully. Oct 27 19:47:28 volumio systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Oct 27 19:47:28 volumio systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Oct 27 19:47:28 volumio go-librespot[30929]: time="2025-10-27T19:47:28Z" level=info msg="running go-librespot 0.4.0" Oct 27 19:47:28 volumio go-librespot[30929]: time="2025-10-27T19:47:28Z" level=debug msg="app state loaded" Oct 27 19:47:28 volumio go-librespot[30929]: time="2025-10-27T19:47:28Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 27 19:47:28 volumio mpd_monitor.sh[30935]: MPD Monitor Service: Starting MPD Monitor Service Oct 27 19:47:28 volumio sudo[30925]: pam_unix(sudo:session): session closed for user root Oct 27 19:47:28 volumio sudo[30923]: pam_unix(sudo:session): session closed for user root Oct 27 19:47:28 volumio volumio[30681]: info: Successfully started MPD Monitor Oct 27 19:47:28 volumio volumio[30681]: info: Successfully started MPD Monitor Oct 27 19:47:28 volumio go-librespot[30929]: time="2025-10-27T19:47:28Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Oct 27 19:47:28 volumio go-librespot[30929]: time="2025-10-27T19:47:28Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 27 19:47:28 volumio go-librespot[30929]: time="2025-10-27T19:47:28Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 27 19:47:28 volumio go-librespot[30929]: time="2025-10-27T19:47:28Z" level=info msg="zeroconf server listening on port 38415" Oct 27 19:47:28 volumio go-librespot[30929]: time="2025-10-27T19:47:28Z" level=debug msg="obtained new client token: AABJNaA05OCKp59EW/5rwaLBRGYEZuDSTqq/yyKgR0nMCisUzQ2T9p/H6LvT8mZrtNLW51bfDJ0L6dcIMWHfiihAKu+/eQyCut4F/Zpd1uTZRHRC8IuCwyfS7I5U0br5k6fvMpMyfuAjI5267mu/F47TebGyPMA+tJdFtGtYestXFHfKyfcI3dCDP/L0kINzp12CVqbS4bw5d1+Z3UboYPYAtEledEvBpMK7bTF4aRz11AH9nsm2zw8=" Oct 27 19:47:29 volumio go-librespot[30929]: time="2025-10-27T19:47:29Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 27 19:47:29 volumio go-librespot[30929]: time="2025-10-27T19:47:29Z" level=debug msg="completed keyexchange" Oct 27 19:47:29 volumio go-librespot[30929]: time="2025-10-27T19:47:29Z" level=debug msg="completed challenge" Oct 27 19:47:29 volumio go-librespot[30929]: time="2025-10-27T19:47:29Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 27 19:47:29 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 27 19:47:29 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 27 19:47:30 volumio volumio[30681]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Oct 27 19:47:31 volumio volumio[30681]: info: Initializing connection to go-librespot Websocket Oct 27 19:47:31 volumio volumio[30681]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 27 19:47:32 volumio volumio[30681]: info: Cannot mount NAS NAS at system boot, trial number 3 ,retrying in 5 seconds Oct 27 19:47:32 volumio sudo[30956]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 27 19:47:32 volumio sudo[30956]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 27 19:47:32 volumio sudo[30958]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 27 19:47:32 volumio sudo[30958]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 27 19:47:32 volumio sudo[30956]: pam_unix(sudo:session): session closed for user root Oct 27 19:47:32 volumio sudo[30958]: pam_unix(sudo:session): session closed for user root Oct 27 19:47:32 volumio sudo[30961]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Oct 27 19:47:32 volumio sudo[30961]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 27 19:47:32 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1261. Oct 27 19:47:32 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 27 19:47:32 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 27 19:47:32 volumio go-librespot[30964]: go-librespot daemon starting... Oct 27 19:47:32 volumio sudo[30961]: pam_unix(sudo:session): session closed for user root Oct 27 19:47:32 volumio go-librespot[30965]: time="2025-10-27T19:47:32Z" level=info msg="running go-librespot 0.4.0" Oct 27 19:47:32 volumio go-librespot[30965]: time="2025-10-27T19:47:32Z" level=debug msg="app state loaded" Oct 27 19:47:32 volumio volumio[30681]: info: Upmpdcli Daemon Started Oct 27 19:47:32 volumio go-librespot[30965]: time="2025-10-27T19:47:32Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 27 19:47:32 volumio go-librespot[30965]: time="2025-10-27T19:47:32Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Oct 27 19:47:32 volumio go-librespot[30965]: time="2025-10-27T19:47:32Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 27 19:47:32 volumio go-librespot[30965]: time="2025-10-27T19:47:32Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 27 19:47:32 volumio go-librespot[30965]: time="2025-10-27T19:47:32Z" level=info msg="zeroconf server listening on port 34705" Oct 27 19:47:32 volumio go-librespot[30965]: time="2025-10-27T19:47:32Z" level=debug msg="obtained new client token: AADragXLz+HaosFsDXRc68QPH5+GztJAWf4wrXCLq5vwEBhS/qCyD+ZbkEOX1Y142ZXsAfTZX07Vge69F/q9oUrm6OUMNdJjESHGqkfbkjCXvwNqZjEIVdouV9gvzFZGiPzrEwaRyVo2v+cz5xqJVKgrHfDFjieeSkw/Jka6ldKBbj8Wa+s0HUAt6i2bC6fQcIsFXQklfJXo7sHKNv3f8drv5ymYTEY3WVROwDN4S/5q7w77L5Tq6m0=" Oct 27 19:47:32 volumio go-librespot[30965]: time="2025-10-27T19:47:32Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 27 19:47:32 volumio go-librespot[30965]: time="2025-10-27T19:47:32Z" level=debug msg="completed keyexchange" Oct 27 19:47:32 volumio go-librespot[30965]: time="2025-10-27T19:47:32Z" level=debug msg="completed challenge" Oct 27 19:47:32 volumio go-librespot[30965]: time="2025-10-27T19:47:32Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 27 19:47:32 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 27 19:47:32 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 27 19:47:34 volumio volumio[30681]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Oct 27 19:47:34 volumio volumio[30681]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Oct 27 19:47:34 volumio volumio[30681]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Oct 27 19:47:34 volumio volumio[30681]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Oct 27 19:47:34 volumio volumio[30681]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Oct 27 19:47:34 volumio volumio[30681]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Oct 27 19:47:34 volumio volumio[30681]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Oct 27 19:47:34 volumio volumio[30681]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Oct 27 19:47:34 volumio volumio[30681]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Oct 27 19:47:34 volumio volumio[30681]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Oct 27 19:47:34 volumio volumio[30681]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Oct 27 19:47:34 volumio volumio[30681]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Oct 27 19:47:34 volumio volumio[30681]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Oct 27 19:47:34 volumio volumio[30681]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Oct 27 19:47:34 volumio volumio[30681]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Oct 27 19:47:34 volumio volumio[30681]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Oct 27 19:47:34 volumio volumio[30681]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Oct 27 19:47:34 volumio volumio[30681]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Oct 27 19:47:34 volumio volumio[30681]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Oct 27 19:47:34 volumio volumio[30681]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Oct 27 19:47:34 volumio volumio[30681]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Oct 27 19:47:34 volumio volumio[30681]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Oct 27 19:47:34 volumio volumio[30681]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Oct 27 19:47:34 volumio volumio[30681]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Oct 27 19:47:34 volumio volumio[30681]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Oct 27 19:47:34 volumio volumio[30681]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Oct 27 19:47:34 volumio volumio[30681]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Oct 27 19:47:34 volumio volumio[30681]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Oct 27 19:47:34 volumio volumio[30681]: info: Adding plugin bluetooth to MyMusic Plugins Oct 27 19:47:34 volumio volumio[30681]: info: Adding plugin multiroom to MyMusic Plugins Oct 27 19:47:34 volumio volumio[30681]: info: Adding plugin metavolumio to MyMusic Plugins Oct 27 19:47:34 volumio volumio[30681]: info: Adding plugin cd_controller to MyMusic Plugins Oct 27 19:47:34 volumio volumio[30681]: info: Adding plugin qobuzconnect to MyMusic Plugins Oct 27 19:47:34 volumio volumio[30681]: info: Adding plugin smart_inputs to MyMusic Plugins Oct 27 19:47:34 volumio volumio[30681]: info: Adding plugin tidalconnect to MyMusic Plugins Oct 27 19:47:34 volumio volumio[30681]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Oct 27 19:47:34 volumio volumio[30681]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Oct 27 19:47:34 volumio volumio[30681]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Oct 27 19:47:34 volumio volumio[30681]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 27 19:47:34 volumio volumio[30681]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 27 19:47:34 volumio volumio[30681]: info: Starting MyVolumio Remote Streaming Endpoints Oct 27 19:47:34 volumio volumio[30681]: info: MyVolumio login type: Token Oct 27 19:47:34 volumio volumio[30681]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Oct 27 19:47:34 volumio volumio[30681]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Oct 27 19:47:34 volumio volumio[30681]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Oct 27 19:47:34 volumio volumio[30681]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Oct 27 19:47:34 volumio volumio[30681]: info: Streaming services startup Oct 27 19:47:34 volumio volumio[30681]: info: Starting Streaming Daemon Oct 27 19:47:34 volumio sudo[30973]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Oct 27 19:47:34 volumio sudo[30973]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 27 19:47:34 volumio volumio[30681]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Oct 27 19:47:34 volumio sudo[30973]: pam_unix(sudo:session): session closed for user root Oct 27 19:47:34 volumio volumio[30681]: info: Initializing connection to go-librespot Websocket Oct 27 19:47:34 volumio volumio[30681]: error: Cannot start Volumio Streaming Daemon Oct 27 19:47:34 volumio volumio[30681]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Oct 27 19:47:34 volumio volumio[30681]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Oct 27 19:47:34 volumio volumio[30681]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 27 19:47:35 volumio volumio[30681]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Oct 27 19:47:35 volumio volumio[30681]: info: MyVolumio token set successfully Oct 27 19:47:35 volumio volumio[30681]: info: MYVOLUMIO: Adding device Oct 27 19:47:35 volumio volumio[30681]: info: MYVOLUMIO: Evaluating Server Oct 27 19:47:35 volumio volumio[30681]: info: MyVolumio status changed Oct 27 19:47:35 volumio volumio[30681]: info: Streaming services startup Oct 27 19:47:35 volumio volumio[30681]: info: Starting Streaming Daemon Oct 27 19:47:35 volumio volumio[30681]: info: Removing browser output: myVolumio user plan is not superstar Oct 27 19:47:35 volumio volumio[30681]: info: Removing audio output: Oct 27 19:47:35 volumio volumio[30681]: info: Stoppping Tunnel 1 Oct 27 19:47:35 volumio sudo[30997]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Oct 27 19:47:35 volumio sudo[30997]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 27 19:47:35 volumio sudo[30999]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service Oct 27 19:47:35 volumio sudo[30999]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 27 19:47:35 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1262. Oct 27 19:47:35 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 27 19:47:35 volumio sudo[30997]: pam_unix(sudo:session): session closed for user root Oct 27 19:47:35 volumio volumio[30681]: error: Cannot start Volumio Streaming Daemon Oct 27 19:47:35 volumio volumio[30681]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Oct 27 19:47:35 volumio volumio[30681]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Oct 27 19:47:35 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 27 19:47:35 volumio go-librespot[31002]: go-librespot daemon starting... Oct 27 19:47:35 volumio 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. Oct 27 19:47:35 volumio 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. Oct 27 19:47:35 volumio 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. Oct 27 19:47:35 volumio 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. Oct 27 19:47:35 volumio go-librespot[31003]: time="2025-10-27T19:47:35Z" level=info msg="running go-librespot 0.4.0" Oct 27 19:47:35 volumio go-librespot[31003]: time="2025-10-27T19:47:35Z" level=debug msg="app state loaded" Oct 27 19:47:35 volumio 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. Oct 27 19:47:35 volumio 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. Oct 27 19:47:35 volumio go-librespot[31003]: time="2025-10-27T19:47:35Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 27 19:47:35 volumio 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. Oct 27 19:47:35 volumio 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. Oct 27 19:47:35 volumio sudo[30999]: pam_unix(sudo:session): session closed for user root Oct 27 19:47:35 volumio volumio[30681]: info: Remote SSH Stopped Oct 27 19:47:35 volumio go-librespot[31003]: time="2025-10-27T19:47:35Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Oct 27 19:47:35 volumio go-librespot[31003]: time="2025-10-27T19:47:35Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 27 19:47:35 volumio go-librespot[31003]: time="2025-10-27T19:47:35Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 27 19:47:35 volumio go-librespot[31003]: time="2025-10-27T19:47:35Z" level=info msg="zeroconf server listening on port 44347" Oct 27 19:47:35 volumio go-librespot[31003]: time="2025-10-27T19:47:35Z" level=debug msg="obtained new client token: AACqdgqUufqm5t5TJttXSDErpS59xA5aZmOnqXOV6aNclXA7RS2eFHoqc31siNOiksgXmSg30IXE4775nW2yLQH15eorSbfBsbFb0Tq1/zMW/Us8djCNp3YzshSHHrwgVULd3Ky9Ie6cxATMGAcdtL6ULAyeMIPHZrnQO08t7LppRnBkCMSoCspps/qf/4o/HVmBJ6/pI2u89EeVf9aE0wb7xDu8O1/wDBkmaCiH5ebw0FywYE1Cgog=" Oct 27 19:47:35 volumio go-librespot[31003]: time="2025-10-27T19:47:35Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 27 19:47:36 volumio volumio[30681]: info: Setting Geolocation for MyVolumio to eu3 Oct 27 19:47:36 volumio volumio[30681]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 27 19:47:36 volumio volumio[30681]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 27 19:47:36 volumio volumio[30681]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 27 19:47:36 volumio go-librespot[31003]: time="2025-10-27T19:47:36Z" level=debug msg="completed keyexchange" Oct 27 19:47:36 volumio go-librespot[31003]: time="2025-10-27T19:47:36Z" level=debug msg="completed challenge" Oct 27 19:47:36 volumio go-librespot[31003]: time="2025-10-27T19:47:36Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 27 19:47:36 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 27 19:47:36 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 27 19:47:36 volumio volumio[30681]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Oct 27 19:47:37 volumio volumio[30681]: info: Updating MyVolumio device info Oct 27 19:47:37 volumio volumio[30681]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 27 19:47:37 volumio volumio[30681]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 27 19:47:37 volumio volumio[30681]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 27 19:47:37 volumio volumio[30681]: info: Cannot mount NAS NAS at system boot, trial number 4 ,retrying in 5 seconds Oct 27 19:47:37 volumio volumio[30681]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Oct 27 19:47:37 volumio volumio[30681]: info: Initializing connection to go-librespot Websocket Oct 27 19:47:37 volumio volumio[30681]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 27 19:47:39 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1263. Oct 27 19:47:39 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 27 19:47:39 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 27 19:47:39 volumio go-librespot[31010]: go-librespot daemon starting... Oct 27 19:47:39 volumio go-librespot[31011]: time="2025-10-27T19:47:39Z" level=info msg="running go-librespot 0.4.0" Oct 27 19:47:39 volumio go-librespot[31011]: time="2025-10-27T19:47:39Z" level=debug msg="app state loaded" Oct 27 19:47:39 volumio go-librespot[31011]: time="2025-10-27T19:47:39Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 27 19:47:39 volumio go-librespot[31011]: time="2025-10-27T19:47:39Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Oct 27 19:47:39 volumio go-librespot[31011]: time="2025-10-27T19:47:39Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 27 19:47:39 volumio go-librespot[31011]: time="2025-10-27T19:47:39Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 27 19:47:39 volumio go-librespot[31011]: time="2025-10-27T19:47:39Z" level=info msg="zeroconf server listening on port 33463" Oct 27 19:47:39 volumio go-librespot[31011]: time="2025-10-27T19:47:39Z" level=debug msg="obtained new client token: AADyonytri9Lnxlr/Qp+noSZ/ZvZ6fd8daSBmOokKWDdiQJyLVssTjnawMgQMHgnae1CeSD+mrVLnsKZFxIF05azFW1S2vFnfvk2ncXYJw/Tk9HgtKHZlDHg7UkY66e8LtraGpLUFDeShLBZ71gHdfR3KDieco3NWcqt+IouvadbSrme1arF1RawEaXdQi4ZklPiF7RFBLzGaMn9y/BGt1aIUMnz2+Ba8s+5pzutt1jDx+UQNwGzQGA=" Oct 27 19:47:39 volumio go-librespot[31011]: time="2025-10-27T19:47:39Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 27 19:47:39 volumio go-librespot[31011]: time="2025-10-27T19:47:39Z" level=debug msg="completed keyexchange" Oct 27 19:47:39 volumio go-librespot[31011]: time="2025-10-27T19:47:39Z" level=debug msg="completed challenge" Oct 27 19:47:39 volumio go-librespot[31011]: time="2025-10-27T19:47:39Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 27 19:47:39 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 27 19:47:39 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 27 19:47:40 volumio volumio[30681]: info: MYVOLUMIO: Adding device Oct 27 19:47:40 volumio volumio[30681]: info: MYVOLUMIO: Evaluating Server Oct 27 19:47:40 volumio volumio[30681]: info: Setting Geolocation for MyVolumio to eu3 Oct 27 19:47:40 volumio volumio[30681]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 27 19:47:40 volumio volumio[30681]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 27 19:47:40 volumio volumio[30681]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 27 19:47:40 volumio volumio[30681]: info: Initializing connection to go-librespot Websocket Oct 27 19:47:40 volumio volumio[30681]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 27 19:47:41 volumio volumio[30681]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Oct 27 19:47:41 volumio volumio[30681]: info: Updating MyVolumio device info Oct 27 19:47:41 volumio volumio[30681]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 27 19:47:41 volumio volumio[30681]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 27 19:47:41 volumio volumio[30681]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 27 19:47:42 volumio volumio[30681]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Oct 27 19:47:42 volumio volumio[30681]: info: Cannot mount NAS at system boot, trial number 4 ,stopping Oct 27 19:47:42 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1264. Oct 27 19:47:42 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 27 19:47:42 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 27 19:47:42 volumio go-librespot[31047]: go-librespot daemon starting... Oct 27 19:47:42 volumio go-librespot[31048]: time="2025-10-27T19:47:42Z" level=info msg="running go-librespot 0.4.0" Oct 27 19:47:42 volumio go-librespot[31048]: time="2025-10-27T19:47:42Z" level=debug msg="app state loaded" Oct 27 19:47:42 volumio go-librespot[31048]: time="2025-10-27T19:47:42Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 27 19:47:42 volumio go-librespot[31048]: time="2025-10-27T19:47:42Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Oct 27 19:47:42 volumio go-librespot[31048]: time="2025-10-27T19:47:42Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 27 19:47:42 volumio go-librespot[31048]: time="2025-10-27T19:47:42Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 27 19:47:42 volumio go-librespot[31048]: time="2025-10-27T19:47:42Z" level=info msg="zeroconf server listening on port 43321" Oct 27 19:47:42 volumio go-librespot[31048]: time="2025-10-27T19:47:42Z" level=debug msg="obtained new client token: AABWAsL7ZTSO74Z7cqlcCYubnoSi6mApFGB0aBjab2AkGPSF8dF5nNv2bk3Lz4n2d/Vpcw4d4P3GK/VsBHMb6nwEk0uDrAINzM1lF3Vfx7qO873gUIMcuADnx0ed/GO13b0tB3KvhCueCx8p5ubB+RWZARodmdcZsfxkdtMiiBvASHCVN64QmZhG2Xj+i6LiRA9zBjvNZI16HWm3pA9oOX3y1h4VMQRSx02ld/ACCWfwof5p3sHQ/Jk=" Oct 27 19:47:43 volumio go-librespot[31048]: time="2025-10-27T19:47:43Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 27 19:47:43 volumio go-librespot[31048]: time="2025-10-27T19:47:43Z" level=debug msg="completed keyexchange" Oct 27 19:47:43 volumio go-librespot[31048]: time="2025-10-27T19:47:43Z" level=debug msg="completed challenge" Oct 27 19:47:43 volumio go-librespot[31048]: time="2025-10-27T19:47:43Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 27 19:47:43 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 27 19:47:43 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 27 19:47:43 volumio volumio[30681]: info: Initializing connection to go-librespot Websocket Oct 27 19:47:43 volumio volumio[30681]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 27 19:47:46 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1265. Oct 27 19:47:46 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 27 19:47:46 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 27 19:47:46 volumio go-librespot[31055]: go-librespot daemon starting... Oct 27 19:47:46 volumio go-librespot[31056]: time="2025-10-27T19:47:46Z" level=info msg="running go-librespot 0.4.0" Oct 27 19:47:46 volumio go-librespot[31056]: time="2025-10-27T19:47:46Z" level=debug msg="app state loaded" Oct 27 19:47:46 volumio go-librespot[31056]: time="2025-10-27T19:47:46Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 27 19:47:46 volumio go-librespot[31056]: time="2025-10-27T19:47:46Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Oct 27 19:47:46 volumio go-librespot[31056]: time="2025-10-27T19:47:46Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 27 19:47:46 volumio go-librespot[31056]: time="2025-10-27T19:47:46Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 27 19:47:46 volumio go-librespot[31056]: time="2025-10-27T19:47:46Z" level=info msg="zeroconf server listening on port 41381" Oct 27 19:47:46 volumio go-librespot[31056]: time="2025-10-27T19:47:46Z" level=debug msg="obtained new client token: AACgnrxdQpqnbSlkcwbf0LC7LxV3lvf+XjeewuG01/kpjhPI+suXoDsB74E3fTlSQgD4/b6hVr407NujcHxrwIKQfz+Mk0yU+VdTSL6+72QX/Y9IhIQVNqnJ6Qq4oIfzoNpC6kxhSUepO5/CQrJGAUZb6nh533W7WtWZf7u2oybXajRmv/Swc4cbdX6tpwzKzPjukj19aii6N1ymbBDK2LpcZJIOqfed908GiW7sMIAPL4E0h9KQk1A=" Oct 27 19:47:46 volumio go-librespot[31056]: time="2025-10-27T19:47:46Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 27 19:47:46 volumio go-librespot[31056]: time="2025-10-27T19:47:46Z" level=debug msg="completed keyexchange" Oct 27 19:47:46 volumio go-librespot[31056]: time="2025-10-27T19:47:46Z" level=debug msg="completed challenge" Oct 27 19:47:46 volumio go-librespot[31056]: time="2025-10-27T19:47:46Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 27 19:47:46 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 27 19:47:46 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 27 19:47:46 volumio volumio[30681]: info: Initializing connection to go-librespot Websocket Oct 27 19:47:46 volumio volumio[30681]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 27 19:47:49 volumio volumio[30681]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Oct 27 19:47:49 volumio volumio[30681]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Oct 27 19:47:49 volumio volumio[30681]: info: CoreCommandRouter::volumioGetState Oct 27 19:47:49 volumio volumio[30681]: info: CorePlayQueue::getTrack 0 Oct 27 19:47:49 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1266. Oct 27 19:47:49 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 27 19:47:49 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 27 19:47:49 volumio go-librespot[31066]: go-librespot daemon starting... Oct 27 19:47:49 volumio volumio[30681]: info: Initializing connection to go-librespot Websocket Oct 27 19:47:49 volumio volumio[30681]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 27 19:47:49 volumio go-librespot[31067]: time="2025-10-27T19:47:49Z" level=info msg="running go-librespot 0.4.0" Oct 27 19:47:49 volumio go-librespot[31067]: time="2025-10-27T19:47:49Z" level=debug msg="app state loaded" Oct 27 19:47:49 volumio go-librespot[31067]: time="2025-10-27T19:47:49Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 27 19:47:49 volumio go-librespot[31067]: time="2025-10-27T19:47:49Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Oct 27 19:47:49 volumio go-librespot[31067]: time="2025-10-27T19:47:49Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 27 19:47:49 volumio go-librespot[31067]: time="2025-10-27T19:47:49Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 27 19:47:49 volumio go-librespot[31067]: time="2025-10-27T19:47:49Z" level=info msg="zeroconf server listening on port 39299" Oct 27 19:47:49 volumio go-librespot[31067]: time="2025-10-27T19:47:49Z" level=debug msg="obtained new client token: AABb+fW7bdzEjEudWypNdHsPL1Ute7NjQUYS4/zaJdEFx+K1JGi0UoFtc5F6rRgH2OSAe70/mJ/ait9CM5fEuBE17uXftxDJMwWvweuUurvodAfFvapJPKVMOdS8KdXUUoc027+hCbRFKr3RTTxh69zJ3Ff0vHr8qxunmsaE0IKKzBKwZFbr3Rd6yzRfmy+30UOtRcPR78tKnUr2naMnWHfJM/01wW2n1yo1a6OCdEo11jgY8IFU9k4=" Oct 27 19:47:49 volumio go-librespot[31067]: time="2025-10-27T19:47:49Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 27 19:47:50 volumio go-librespot[31067]: time="2025-10-27T19:47:50Z" level=debug msg="completed keyexchange" Oct 27 19:47:50 volumio go-librespot[31067]: time="2025-10-27T19:47:50Z" level=debug msg="completed challenge" Oct 27 19:47:50 volumio go-librespot[31067]: time="2025-10-27T19:47:50Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 27 19:47:50 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 27 19:47:50 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 27 19:47:52 volumio volumio[30681]: info: Initializing connection to go-librespot Websocket Oct 27 19:47:52 volumio volumio[30681]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 27 19:47:53 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1267. Oct 27 19:47:53 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 27 19:47:53 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 27 19:47:53 volumio go-librespot[31089]: go-librespot daemon starting... Oct 27 19:47:53 volumio go-librespot[31090]: time="2025-10-27T19:47:53Z" level=info msg="running go-librespot 0.4.0" Oct 27 19:47:53 volumio go-librespot[31090]: time="2025-10-27T19:47:53Z" level=debug msg="app state loaded" Oct 27 19:47:53 volumio go-librespot[31090]: time="2025-10-27T19:47:53Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 27 19:47:53 volumio go-librespot[31090]: time="2025-10-27T19:47:53Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Oct 27 19:47:53 volumio go-librespot[31090]: time="2025-10-27T19:47:53Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 27 19:47:53 volumio go-librespot[31090]: time="2025-10-27T19:47:53Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 27 19:47:53 volumio go-librespot[31090]: time="2025-10-27T19:47:53Z" level=info msg="zeroconf server listening on port 44605" Oct 27 19:47:53 volumio go-librespot[31090]: time="2025-10-27T19:47:53Z" level=debug msg="obtained new client token: AAAm4ok3JnnbGtnIIZD9F3OxFJiXkATSyaQ8AFKr5lfCJ/Qe3bnF0FYustj5Np2LTR2qQo7XrEHLfm0Bi/qFyN1aPpxqyeD0KSvGvqpjEsq+3yoTqBkOAllaEqZeaa2ZUa6aaeHChxxo+qmQ68laYtJ5EDH81ztE5uMGutb9o2txtkY4oWKhxJJxy20gBut+w628/NPZugmXK7hFF6wsanTDGQMew+IJEYySyZbb3eplD+G8xn3JXdE=" Oct 27 19:47:53 volumio go-librespot[31090]: time="2025-10-27T19:47:53Z" level=warning msg="failed to connect to AP ap-gew1.spotify.com:4070, retrying with a different AP" error="dial tcp 104.199.65.9:4070: connect: connection refused" Oct 27 19:47:53 volumio go-librespot[31090]: time="2025-10-27T19:47:53Z" level=debug msg="connected to ap-gew1.spotify.com:443" Oct 27 19:47:53 volumio go-librespot[31090]: time="2025-10-27T19:47:53Z" level=debug msg="completed keyexchange" Oct 27 19:47:53 volumio go-librespot[31090]: time="2025-10-27T19:47:53Z" level=debug msg="completed challenge" Oct 27 19:47:53 volumio go-librespot[31090]: time="2025-10-27T19:47:53Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 27 19:47:53 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 27 19:47:53 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 27 19:47:54 volumio volumio[30681]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 27 19:47:54 volumio volumio[30681]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 27 19:47:54 volumio volumio[30681]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam Oct 27 19:47:54 volumio volumio[30681]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Oct 27 19:47:54 volumio volumio[30681]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Oct 27 19:47:54 volumio volumio[30681]: info: CoreCommandRouter::volumioGetBrowseSources Oct 27 19:47:54 volumio volumio[30681]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 27 19:47:54 volumio volumio[30681]: error: MyVolumio Plugin failed to authenticate in a timely fashion Oct 27 19:47:54 volumio volumio[30681]: info: Completed starting MyVolumio Plugin Oct 27 19:47:54 volumio volumio[30681]: [Metrics] CommandRouter: 33s 160.05ms Oct 27 19:47:54 volumio volumio[30681]: info: CoreCommandRouter::volumiosetStartupVolume Oct 27 19:47:54 volumio volumio[30681]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 27 19:47:54 volumio volumio[30681]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 27 19:47:54 volumio volumio[30681]: info: CoreCommandRouter::Close All Modals sent Oct 27 19:47:54 volumio volumio[30681]: info: CoreCommandRouter::Close All Modals sent Oct 27 19:47:55 volumio volumio[30681]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 27 19:47:55 volumio volumio[30681]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 27 19:47:55 volumio volumio[30681]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Oct 27 19:47:55 volumio volumio-remote-updater[874]: Test mode disabled Oct 27 19:47:55 volumio volumio-remote-updater[874]: Alpha mode disabled Oct 27 19:47:55 volumio volumio-remote-updater[874]: Alpha legacy test mode disabled Oct 27 19:47:55 volumio volumio[30681]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateEnabled Oct 27 19:47:55 volumio volumio[30681]: info: Update Ready: {"changeLogLink":"","description":"You're already on the latest version","title":"No Updates Available","updateavailable":false} Oct 27 19:47:55 volumio volumio[30681]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache Oct 27 19:47:55 volumio volumio[30681]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable Oct 27 19:47:55 volumio volumio[30681]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Oct 27 19:47:55 volumio volumio[30681]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect Oct 27 19:47:55 volumio volumio[30681]: info: Initializing connection to go-librespot Websocket Oct 27 19:47:55 volumio volumio[30681]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 27 19:47:56 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1268. Oct 27 19:47:56 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 27 19:47:56 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 27 19:47:56 volumio go-librespot[31106]: go-librespot daemon starting... Oct 27 19:47:56 volumio go-librespot[31107]: time="2025-10-27T19:47:56Z" level=info msg="running go-librespot 0.4.0" Oct 27 19:47:56 volumio go-librespot[31107]: time="2025-10-27T19:47:56Z" level=debug msg="app state loaded" Oct 27 19:47:56 volumio go-librespot[31107]: time="2025-10-27T19:47:56Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 27 19:47:56 volumio go-librespot[31107]: time="2025-10-27T19:47:56Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Oct 27 19:47:56 volumio go-librespot[31107]: time="2025-10-27T19:47:56Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 27 19:47:56 volumio go-librespot[31107]: time="2025-10-27T19:47:56Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 27 19:47:56 volumio go-librespot[31107]: time="2025-10-27T19:47:56Z" level=info msg="zeroconf server listening on port 33983" Oct 27 19:47:56 volumio go-librespot[31107]: time="2025-10-27T19:47:56Z" level=debug msg="obtained new client token: AAClFSdeY00lLf0xEIeIxr9T6wsFXOUQh4yuoe/n4oUMWwzzU2NEWOaDBGqMiO+yiPRhd3tMhkAm0Pwo01zjApXFuTccyzC6tfA0DTgOFwpvwa1k+5zbLdCq76uq2oc14SdZDkilO3YaMqOtG3Ulg/2E/CYH9ZQAOSx9jVzazfYyAhR0WzKBXW7ckMLuNxvGTWag2ynkWtv1hd/SDyqtQT72uO/B7rxk+MnNmLl9dDYCTJ789KizHME=" Oct 27 19:47:56 volumio go-librespot[31107]: time="2025-10-27T19:47:56Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 27 19:47:57 volumio go-librespot[31107]: time="2025-10-27T19:47:57Z" level=debug msg="completed keyexchange" Oct 27 19:47:57 volumio go-librespot[31107]: time="2025-10-27T19:47:57Z" level=debug msg="completed challenge" Oct 27 19:47:57 volumio go-librespot[31107]: time="2025-10-27T19:47:57Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 27 19:47:57 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 27 19:47:57 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 27 19:47:58 volumio volumio[30681]: info: Initializing connection to go-librespot Websocket Oct 27 19:47:58 volumio volumio[30681]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 27 19:48:00 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1269. Oct 27 19:48:00 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 27 19:48:00 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 27 19:48:00 volumio go-librespot[31115]: go-librespot daemon starting... Oct 27 19:48:00 volumio go-librespot[31116]: time="2025-10-27T19:48:00Z" level=info msg="running go-librespot 0.4.0" Oct 27 19:48:00 volumio go-librespot[31116]: time="2025-10-27T19:48:00Z" level=debug msg="app state loaded" Oct 27 19:48:00 volumio go-librespot[31116]: time="2025-10-27T19:48:00Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 27 19:48:00 volumio go-librespot[31116]: time="2025-10-27T19:48:00Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Oct 27 19:48:00 volumio go-librespot[31116]: time="2025-10-27T19:48:00Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Oct 27 19:48:00 volumio go-librespot[31116]: time="2025-10-27T19:48:00Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Oct 27 19:48:00 volumio go-librespot[31116]: time="2025-10-27T19:48:00Z" level=info msg="zeroconf server listening on port 38173" Oct 27 19:48:00 volumio go-librespot[31116]: time="2025-10-27T19:48:00Z" level=debug msg="obtained new client token: AAAEN4V0hVHzlO52RZCrUmSW1Kc5iMirl9PHmHMn6pW84IFLYuCYo8GANMAcXieP846WAeiUbZUj2uI0Fud17v3wGU+RhK7SaMRl8h31y01tNmoyDeLtFM/IVKY8LQLXVoSjEtMKcHIcn9Q0OkvL/AM1vTI5TeSrI3Ji+NXNdS7HQxvxJ89WO8gaYuklj58Jm+dRE2CvoiSNO0mWIqI7Zc9XXsj4U1dYqWkWeLCrv9t92U97P/FskQs=" Oct 27 19:48:00 volumio go-librespot[31116]: time="2025-10-27T19:48:00Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 27 19:48:00 volumio go-librespot[31116]: time="2025-10-27T19:48:00Z" level=debug msg="completed keyexchange" Oct 27 19:48:00 volumio go-librespot[31116]: time="2025-10-27T19:48:00Z" level=debug msg="completed challenge" Oct 27 19:48:00 volumio go-librespot[31116]: time="2025-10-27T19:48:00Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 27 19:48:00 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 27 19:48:00 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 27 19:48:01 volumio volumio[30681]: info: BOOT COMPLETED Oct 27 19:48:01 volumio volumio[30681]: info: Initializing connection to go-librespot Websocket Oct 27 19:48:01 volumio volumio[30681]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 27 19:48:03 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1270. Oct 27 19:48:03 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 27 19:48:03 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 27 19:48:03 volumio go-librespot[31137]: go-librespot daemon starting... Oct 27 19:48:03 volumio go-librespot[31138]: time="2025-10-27T19:48:03Z" level=info msg="running go-librespot 0.4.0" Oct 27 19:48:03 volumio go-librespot[31138]: time="2025-10-27T19:48:03Z" level=debug msg="app state loaded" Oct 27 19:48:03 volumio go-librespot[31138]: time="2025-10-27T19:48:03Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 27 19:48:03 volumio go-librespot[31138]: time="2025-10-27T19:48:03Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Oct 27 19:48:03 volumio go-librespot[31138]: time="2025-10-27T19:48:03Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Oct 27 19:48:03 volumio go-librespot[31138]: time="2025-10-27T19:48:03Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Oct 27 19:48:03 volumio go-librespot[31138]: time="2025-10-27T19:48:03Z" level=info msg="zeroconf server listening on port 34593" Oct 27 19:48:03 volumio go-librespot[31138]: time="2025-10-27T19:48:03Z" level=debug msg="obtained new client token: AAAmajWdi4As7+Fc6DsNTmBsiFSvWOYr2/MrBD6gil5e7XB8wlXSE2lmL5LOVHbXteGNI1ppJwYnCQJjXVQCOJBE7r3kecUf1aLyKWbJvhM1EFJ2voNgBMlJ9l+NzR9uuQnvE0bx1F4E3wcPvemP4ju1FEu2/j5AD2W8/OPl4RmaFeBpQriK4kP/Xde8+uHGEV5AsaDJFWFXzN1aoaQPWVpCm1vYPcU8v6PL+S48aoUYAL0ecqBJGE4=" Oct 27 19:48:03 volumio go-librespot[31138]: time="2025-10-27T19:48:03Z" level=warning msg="failed to connect to AP ap-gew1.spotify.com:4070, retrying with a different AP" error="dial tcp 104.199.65.9:4070: connect: connection refused" Oct 27 19:48:04 volumio go-librespot[31138]: time="2025-10-27T19:48:04Z" level=debug msg="connected to ap-gew1.spotify.com:443" Oct 27 19:48:04 volumio go-librespot[31138]: time="2025-10-27T19:48:04Z" level=debug msg="completed keyexchange" Oct 27 19:48:04 volumio go-librespot[31138]: time="2025-10-27T19:48:04Z" level=debug msg="completed challenge" Oct 27 19:48:04 volumio go-librespot[31138]: time="2025-10-27T19:48:04Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 27 19:48:04 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 27 19:48:04 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 27 19:48:04 volumio volumio[30681]: info: Initializing connection to go-librespot Websocket Oct 27 19:48:04 volumio volumio[30681]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 27 19:48:07 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1271. Oct 27 19:48:07 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 27 19:48:07 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 27 19:48:07 volumio go-librespot[31145]: go-librespot daemon starting... Oct 27 19:48:07 volumio go-librespot[31146]: time="2025-10-27T19:48:07Z" level=info msg="running go-librespot 0.4.0" Oct 27 19:48:07 volumio go-librespot[31146]: time="2025-10-27T19:48:07Z" level=debug msg="app state loaded" Oct 27 19:48:07 volumio go-librespot[31146]: time="2025-10-27T19:48:07Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 27 19:48:07 volumio go-librespot[31146]: time="2025-10-27T19:48:07Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Oct 27 19:48:07 volumio go-librespot[31146]: time="2025-10-27T19:48:07Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 27 19:48:07 volumio go-librespot[31146]: time="2025-10-27T19:48:07Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 27 19:48:07 volumio go-librespot[31146]: time="2025-10-27T19:48:07Z" level=info msg="zeroconf server listening on port 45755" Oct 27 19:48:07 volumio go-librespot[31146]: time="2025-10-27T19:48:07Z" level=debug msg="obtained new client token: AAArYFgnUEVK/1jcL0eui3ZXOc/mRrT74JpsrC3jwXc9TVA2urYnGNGr51EvZa+ETEPKjYFoTsplK20/tww8ZpTb0qjxbmhVRuD9GzQ/ZQavBJoLG9N01J2hIzQLCY0ETWGrncV9IKpsoBT2rg/YCo2W8M5yFuwHP92y+lxaqVBiD8RB9IFPcs3e2++Xv6Yx2SAzqMiMd8CVCgDwyRBO6g/3veRCciLoHygssSBPgUY2CvzrLyrjNIM=" Oct 27 19:48:07 volumio go-librespot[31146]: time="2025-10-27T19:48:07Z" level=warning msg="failed to connect to AP ap-gew1.spotify.com:4070, retrying with a different AP" error="dial tcp 104.199.65.9:4070: connect: connection refused" Oct 27 19:48:07 volumio go-librespot[31146]: time="2025-10-27T19:48:07Z" level=debug msg="connected to ap-gew1.spotify.com:443" Oct 27 19:48:07 volumio go-librespot[31146]: time="2025-10-27T19:48:07Z" level=debug msg="completed keyexchange" Oct 27 19:48:07 volumio go-librespot[31146]: time="2025-10-27T19:48:07Z" level=debug msg="completed challenge" Oct 27 19:48:07 volumio go-librespot[31146]: time="2025-10-27T19:48:07Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 27 19:48:07 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 27 19:48:07 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 27 19:48:07 volumio volumio[30681]: info: Initializing connection to go-librespot Websocket Oct 27 19:48:07 volumio volumio[30681]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 27 19:48:10 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1272. Oct 27 19:48:10 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 27 19:48:10 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 27 19:48:10 volumio go-librespot[31156]: go-librespot daemon starting... Oct 27 19:48:10 volumio volumio[30681]: info: Initializing connection to go-librespot Websocket Oct 27 19:48:10 volumio volumio[30681]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 27 19:48:10 volumio go-librespot[31157]: time="2025-10-27T19:48:10Z" level=info msg="running go-librespot 0.4.0" Oct 27 19:48:10 volumio go-librespot[31157]: time="2025-10-27T19:48:10Z" level=debug msg="app state loaded" Oct 27 19:48:10 volumio go-librespot[31157]: time="2025-10-27T19:48:10Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 27 19:48:10 volumio go-librespot[31157]: time="2025-10-27T19:48:10Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Oct 27 19:48:10 volumio go-librespot[31157]: time="2025-10-27T19:48:10Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 27 19:48:10 volumio go-librespot[31157]: time="2025-10-27T19:48:10Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 27 19:48:10 volumio go-librespot[31157]: time="2025-10-27T19:48:10Z" level=info msg="zeroconf server listening on port 36695" Oct 27 19:48:10 volumio go-librespot[31157]: time="2025-10-27T19:48:10Z" level=debug msg="obtained new client token: AAD0ScmS3qZH/S0F1UUn+G7ke7ewb5AelxTDVbSZZdTxmQsubboJw+7rJuhlVqDR9GS+/KKL9Sr4ZS1mazTwL9vk39wGO+8gGsDLS9CjTELBEAswp+gvFod43NucQJM9n/aFqd2J+B05FU7VvWxoiU3feMfzYi65kI9H6NHydqMtAS9y+ZGi7OPN5lqPkiLeS+EtBqDqO+cz7eZ76i+NXr2YBaP2tkaUysQDpmkQcHsh05TXe/BKt5I=" Oct 27 19:48:11 volumio go-librespot[31157]: time="2025-10-27T19:48:11Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 27 19:48:11 volumio go-librespot[31157]: time="2025-10-27T19:48:11Z" level=debug msg="completed keyexchange" Oct 27 19:48:11 volumio go-librespot[31157]: time="2025-10-27T19:48:11Z" level=debug msg="completed challenge" Oct 27 19:48:11 volumio go-librespot[31157]: time="2025-10-27T19:48:11Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 27 19:48:11 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 27 19:48:11 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 27 19:48:13 volumio volumio[30681]: info: Initializing connection to go-librespot Websocket Oct 27 19:48:13 volumio volumio[30681]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 27 19:48:14 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1273. Oct 27 19:48:14 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 27 19:48:14 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 27 19:48:14 volumio go-librespot[31178]: go-librespot daemon starting... Oct 27 19:48:14 volumio go-librespot[31179]: time="2025-10-27T19:48:14Z" level=info msg="running go-librespot 0.4.0" Oct 27 19:48:14 volumio go-librespot[31179]: time="2025-10-27T19:48:14Z" level=debug msg="app state loaded" Oct 27 19:48:14 volumio go-librespot[31179]: time="2025-10-27T19:48:14Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 27 19:48:14 volumio go-librespot[31179]: time="2025-10-27T19:48:14Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Oct 27 19:48:14 volumio go-librespot[31179]: time="2025-10-27T19:48:14Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 27 19:48:14 volumio go-librespot[31179]: time="2025-10-27T19:48:14Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 27 19:48:14 volumio go-librespot[31179]: time="2025-10-27T19:48:14Z" level=info msg="zeroconf server listening on port 34645" Oct 27 19:48:14 volumio go-librespot[31179]: time="2025-10-27T19:48:14Z" level=debug msg="obtained new client token: AADGjSP/j3jkOn0QWT2DKjQjxPYXZSUWoyj/k6huM5/5QIRAaeDRxMihpgx6hnMEjS6WBW21BkHa3rhQxTmFdi3WBsp8IiZfKP0oem6jq6802D2qSy9z+Cop9ZLtYUvlnilZptEibbQdeFSTZSXZhHZy7euB6yIzEwmmDXJ8N56jZme7CsE/j6RmGLxdT48zrtn4O5qlGffnQEFedQT6RQuAy1jFmgayBmQkn+kI4C1CeX0k4MT+/2E=" Oct 27 19:48:14 volumio go-librespot[31179]: time="2025-10-27T19:48:14Z" level=warning msg="failed to connect to AP ap-gew1.spotify.com:4070, retrying with a different AP" error="dial tcp 104.199.65.9:4070: connect: connection refused" Oct 27 19:48:14 volumio go-librespot[31179]: time="2025-10-27T19:48:14Z" level=debug msg="connected to ap-gew1.spotify.com:443" Oct 27 19:48:14 volumio go-librespot[31179]: time="2025-10-27T19:48:14Z" level=debug msg="completed keyexchange" Oct 27 19:48:14 volumio go-librespot[31179]: time="2025-10-27T19:48:14Z" level=debug msg="completed challenge" Oct 27 19:48:14 volumio go-librespot[31179]: time="2025-10-27T19:48:14Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 27 19:48:14 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 27 19:48:14 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 27 19:48:16 volumio volumio[30681]: info: Initializing connection to go-librespot Websocket Oct 27 19:48:16 volumio volumio[30681]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 27 19:48:17 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1274. Oct 27 19:48:17 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 27 19:48:17 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 27 19:48:17 volumio go-librespot[31187]: go-librespot daemon starting... Oct 27 19:48:17 volumio go-librespot[31188]: time="2025-10-27T19:48:17Z" level=info msg="running go-librespot 0.4.0" Oct 27 19:48:17 volumio go-librespot[31188]: time="2025-10-27T19:48:17Z" level=debug msg="app state loaded" Oct 27 19:48:17 volumio go-librespot[31188]: time="2025-10-27T19:48:17Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 27 19:48:17 volumio go-librespot[31188]: time="2025-10-27T19:48:17Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Oct 27 19:48:17 volumio go-librespot[31188]: time="2025-10-27T19:48:17Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 27 19:48:17 volumio go-librespot[31188]: time="2025-10-27T19:48:17Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 27 19:48:17 volumio go-librespot[31188]: time="2025-10-27T19:48:17Z" level=info msg="zeroconf server listening on port 34059" Oct 27 19:48:17 volumio go-librespot[31188]: time="2025-10-27T19:48:17Z" level=debug msg="obtained new client token: AAD4jWq7vhGQ/RkyF5Opy9dynzcWXK5/AXrteLg/g86J2jyLTx5jgtBVlOynEhPeEngOfWnGB4JtTqK2ld2IKZx6WqXw0lrQHuD48D+rSwqlwLUHsSq8oro2HQDQZop+zHuqf5j75L0CyjNf3SEp/VVFwYHhXGqwr5VsSM0aJ6G38zulvFvuytD5hAAMreKFIvWH903kuaGQ6M+C3sBzQQ/RybzN+1XRxclv/FAnvVW78vKLLuF+QFM=" Oct 27 19:48:17 volumio go-librespot[31188]: time="2025-10-27T19:48:17Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 27 19:48:18 volumio go-librespot[31188]: time="2025-10-27T19:48:18Z" level=debug msg="completed keyexchange" Oct 27 19:48:18 volumio go-librespot[31188]: time="2025-10-27T19:48:18Z" level=debug msg="completed challenge" Oct 27 19:48:18 volumio go-librespot[31188]: time="2025-10-27T19:48:18Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 27 19:48:18 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 27 19:48:18 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 27 19:48:19 volumio volumio[30681]: info: Initializing connection to go-librespot Websocket Oct 27 19:48:19 volumio volumio[30681]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 27 19:48:21 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1275. Oct 27 19:48:21 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 27 19:48:21 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 27 19:48:21 volumio go-librespot[31195]: go-librespot daemon starting... Oct 27 19:48:21 volumio go-librespot[31196]: time="2025-10-27T19:48:21Z" level=info msg="running go-librespot 0.4.0" Oct 27 19:48:21 volumio go-librespot[31196]: time="2025-10-27T19:48:21Z" level=debug msg="app state loaded" Oct 27 19:48:21 volumio go-librespot[31196]: time="2025-10-27T19:48:21Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 27 19:48:21 volumio go-librespot[31196]: time="2025-10-27T19:48:21Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Oct 27 19:48:21 volumio go-librespot[31196]: time="2025-10-27T19:48:21Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 27 19:48:21 volumio go-librespot[31196]: time="2025-10-27T19:48:21Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 27 19:48:21 volumio go-librespot[31196]: time="2025-10-27T19:48:21Z" level=info msg="zeroconf server listening on port 42351" Oct 27 19:48:21 volumio go-librespot[31196]: time="2025-10-27T19:48:21Z" level=debug msg="obtained new client token: AACxSaq7VCQwj7De1H/k5l7TvjprurAuacpq18rWE4D9c90k3Y3mYHsbDF9PrKSZYYV9VEEDrcsQW2P/GbH6v4FjMjCkPBRZwVo8h3mF2YRB36GSS4j+JzVYg0sCi6u10Gk0beyGOOwUtBLsdvVRVy3K0iRVQ+uDxNG/taYSoSDCh2ZCi4m30zMb78ybJUxZqJArh4eV8baaybwihkWbzIxG+RSbVOZYZmCLRqToYQFm13Bv2+WDC58=" Oct 27 19:48:21 volumio go-librespot[31196]: time="2025-10-27T19:48:21Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 27 19:48:21 volumio go-librespot[31196]: time="2025-10-27T19:48:21Z" level=debug msg="completed keyexchange" Oct 27 19:48:21 volumio go-librespot[31196]: time="2025-10-27T19:48:21Z" level=debug msg="completed challenge" Oct 27 19:48:21 volumio go-librespot[31196]: time="2025-10-27T19:48:21Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 27 19:48:21 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 27 19:48:21 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 27 19:48:22 volumio volumio[30681]: info: Initializing connection to go-librespot Websocket Oct 27 19:48:22 volumio volumio[30681]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 27 19:48:24 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1276. Oct 27 19:48:24 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 27 19:48:24 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 27 19:48:24 volumio go-librespot[31217]: go-librespot daemon starting... Oct 27 19:48:24 volumio go-librespot[31218]: time="2025-10-27T19:48:24Z" level=info msg="running go-librespot 0.4.0" Oct 27 19:48:24 volumio go-librespot[31218]: time="2025-10-27T19:48:24Z" level=debug msg="app state loaded" Oct 27 19:48:24 volumio go-librespot[31218]: time="2025-10-27T19:48:24Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 27 19:48:24 volumio go-librespot[31218]: time="2025-10-27T19:48:24Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Oct 27 19:48:24 volumio go-librespot[31218]: time="2025-10-27T19:48:24Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 27 19:48:24 volumio go-librespot[31218]: time="2025-10-27T19:48:24Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 27 19:48:24 volumio go-librespot[31218]: time="2025-10-27T19:48:24Z" level=info msg="zeroconf server listening on port 35845" Oct 27 19:48:24 volumio go-librespot[31218]: time="2025-10-27T19:48:24Z" level=debug msg="obtained new client token: AACGUw7+sTdfd16ay2ncvWQcksJXsdsmY9ovEtyjfXSp1Q/cLvYt6jMnhOABtVWsWtcez3YHO7vsLmCn0u8UFui8+P3ZwVH6AjdXCPyLJzSMG0q6RmV4U/S6Xi8u8ggWLdxWyIVUB5szu77SzPxANNnNW8o+8tKllhQrAGQQMNhTkr8qm0xdfwNKcoROUSxDm5Dd8IoB0zMuV6ETKw6q9kQikqUMO3YIh5HawX/NcnKWTh7zYOi8GBM=" Oct 27 19:48:25 volumio go-librespot[31218]: time="2025-10-27T19:48:25Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 27 19:48:25 volumio go-librespot[31218]: time="2025-10-27T19:48:25Z" level=debug msg="completed keyexchange" Oct 27 19:48:25 volumio go-librespot[31218]: time="2025-10-27T19:48:25Z" level=debug msg="completed challenge" Oct 27 19:48:25 volumio go-librespot[31218]: time="2025-10-27T19:48:25Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 27 19:48:25 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 27 19:48:25 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 27 19:48:25 volumio volumio[30681]: info: Initializing connection to go-librespot Websocket Oct 27 19:48:25 volumio volumio[30681]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 27 19:48:28 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1277. Oct 27 19:48:28 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 27 19:48:28 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 27 19:48:28 volumio go-librespot[31225]: go-librespot daemon starting... Oct 27 19:48:28 volumio go-librespot[31226]: time="2025-10-27T19:48:28Z" level=info msg="running go-librespot 0.4.0" Oct 27 19:48:28 volumio go-librespot[31226]: time="2025-10-27T19:48:28Z" level=debug msg="app state loaded" Oct 27 19:48:28 volumio go-librespot[31226]: time="2025-10-27T19:48:28Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 27 19:48:28 volumio go-librespot[31226]: time="2025-10-27T19:48:28Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Oct 27 19:48:28 volumio go-librespot[31226]: time="2025-10-27T19:48:28Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Oct 27 19:48:28 volumio go-librespot[31226]: time="2025-10-27T19:48:28Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Oct 27 19:48:28 volumio go-librespot[31226]: time="2025-10-27T19:48:28Z" level=info msg="zeroconf server listening on port 45559" Oct 27 19:48:28 volumio go-librespot[31226]: time="2025-10-27T19:48:28Z" level=debug msg="obtained new client token: AAAtc8wfz+JUpCzLcTURMPzBDSoKInhxUVnqA/fGiJdZMK8x5xxz+Q91T2FaJHpa3U09KqTnOzkBaXhX784WQ8HFi/BxZMpInULsR6sFVxeyT4Dlvuw2ByOjXBgnTaMMP8bj2MLtuHwEbUud8D2PFupdul2lKk4F4aUxFwCmV1rEVy9uBXNuX2AcE/aBR94vZ8qfYfvc0wpkwGpnimiObza0dWyXBwTGlhfVlyyGqJFzsk0OQ8ALygc=" Oct 27 19:48:28 volumio go-librespot[31226]: time="2025-10-27T19:48:28Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 27 19:48:28 volumio go-librespot[31226]: time="2025-10-27T19:48:28Z" level=debug msg="completed keyexchange" Oct 27 19:48:28 volumio go-librespot[31226]: time="2025-10-27T19:48:28Z" level=debug msg="completed challenge" Oct 27 19:48:28 volumio go-librespot[31226]: time="2025-10-27T19:48:28Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 27 19:48:28 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 27 19:48:28 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 27 19:48:28 volumio volumio[30681]: info: Initializing connection to go-librespot Websocket Oct 27 19:48:28 volumio volumio[30681]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 27 19:48:31 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1278. Oct 27 19:48:31 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 27 19:48:31 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 27 19:48:31 volumio go-librespot[31236]: go-librespot daemon starting... Oct 27 19:48:31 volumio go-librespot[31237]: time="2025-10-27T19:48:31Z" level=info msg="running go-librespot 0.4.0" Oct 27 19:48:31 volumio go-librespot[31237]: time="2025-10-27T19:48:31Z" level=debug msg="app state loaded" Oct 27 19:48:31 volumio go-librespot[31237]: time="2025-10-27T19:48:31Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 27 19:48:31 volumio volumio[30681]: info: Initializing connection to go-librespot Websocket Oct 27 19:48:31 volumio go-librespot[31237]: time="2025-10-27T19:48:31Z" level=debug msg="new websocket client" Oct 27 19:48:31 volumio volumio[30681]: info: Connection to go-librespot Websocket established Oct 27 19:48:31 volumio go-librespot[31237]: time="2025-10-27T19:48:31Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Oct 27 19:48:31 volumio go-librespot[31237]: time="2025-10-27T19:48:31Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 27 19:48:31 volumio go-librespot[31237]: time="2025-10-27T19:48:31Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 27 19:48:31 volumio go-librespot[31237]: time="2025-10-27T19:48:31Z" level=info msg="zeroconf server listening on port 43691" Oct 27 19:48:31 volumio go-librespot[31237]: time="2025-10-27T19:48:31Z" level=debug msg="obtained new client token: AABh04X2ic0JTe7cm0ul/KD5+m38I/XOsDlfTSrXzoXyZz/gW7+Lv1dSy4BeXe2oAoBzCjJ4TSdd8XVlNI9IFEg7TyHSIa4Zcd/AjX9TSa1Pzvk0A00Np2QsDijbQCgW/AEKZxRsh43z/fRTQt/yRzk2rQwTybllIW9NtmXBXcROm0eb3Hb60ZN99RC9ozfKz9hydkkZFQFzjr7ahzvfQu+QNjekjxLlGPX2r/Cb28oE/tHvhwHJkic=" Oct 27 19:48:32 volumio go-librespot[31237]: time="2025-10-27T19:48:32Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 27 19:48:32 volumio go-librespot[31237]: time="2025-10-27T19:48:32Z" level=debug msg="completed keyexchange" Oct 27 19:48:32 volumio go-librespot[31237]: time="2025-10-27T19:48:32Z" level=debug msg="completed challenge" Oct 27 19:48:32 volumio go-librespot[31237]: time="2025-10-27T19:48:32Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 27 19:48:32 volumio volumio[30681]: info: Connection to go-librespot Websocket closed Oct 27 19:48:32 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 27 19:48:32 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 27 19:48:34 volumio volumio[30681]: info: Getting Spotify volume Oct 27 19:48:34 volumio volumio[30681]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 27 19:48:34 volumio volumio[30681]: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 27 19:48:34 volumio volumio[30681]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Oct 27 19:48:34 volumio volumio[30681]: errno: -111, Oct 27 19:48:34 volumio volumio[30681]: code: 'ECONNREFUSED', Oct 27 19:48:34 volumio volumio[30681]: syscall: 'connect', Oct 27 19:48:34 volumio volumio[30681]: address: '127.0.0.1', Oct 27 19:48:34 volumio volumio[30681]: port: 9879, Oct 27 19:48:34 volumio volumio[30681]: response: undefined Oct 27 19:48:34 volumio volumio[30681]: } Oct 27 19:48:34 volumio volumio[30681]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 27 19:48:35 volumio sudo[31272]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-10-27 19:47' Oct 27 19:48:35 volumio sudo[31272]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 27 19:48:35 volumio sudo[31272]: pam_unix(sudo:session): session closed for user root Oct 27 19:48:35 volumio volumio-remote-updater[874]: [2025-10-27 19:48:35] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Oct 27 19:48:35 volumio volumio-remote-updater[874]: [2025-10-27 19:48:35] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Oct 27 19:48:35 volumio systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Oct 27 19:48:35 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1279. Oct 27 19:48:35 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 27 19:48:35 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 27 19:48:35 volumio go-librespot[31277]: go-librespot daemon starting... Oct 27 19:48:35 volumio systemd[1]: volumio.service: Failed with result 'exit-code'. Oct 27 19:48:35 volumio systemd[1]: volumio.service: Consumed 11.433s CPU time. Oct 27 19:48:35 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Oct 27 19:48:35 volumio go-librespot[31278]: time="2025-10-27T19:48:35Z" level=info msg="running go-librespot 0.4.0" Oct 27 19:48:35 volumio go-librespot[31278]: time="2025-10-27T19:48:35Z" level=debug msg="app state loaded" Oct 27 19:48:35 volumio go-librespot[31278]: time="2025-10-27T19:48:35Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 27 19:48:35 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Oct 27 19:48:35 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 1019. Oct 27 19:48:35 volumio go-librespot[31278]: time="2025-10-27T19:48:35Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Oct 27 19:48:35 volumio go-librespot[31278]: time="2025-10-27T19:48:35Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 27 19:48:35 volumio go-librespot[31278]: time="2025-10-27T19:48:35Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 27 19:48:35 volumio go-librespot[31278]: time="2025-10-27T19:48:35Z" level=info msg="zeroconf server listening on port 44001" Oct 27 19:48:35 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Oct 27 19:48:35 volumio systemd[1]: Stopped volumio.service - Volumio Backend Module. Oct 27 19:48:35 volumio systemd[1]: volumio.service: Consumed 11.433s CPU time. Oct 27 19:48:35 volumio systemd[1]: Started volumio.service - Volumio Backend Module. Oct 27 19:48:35 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Oct 27 19:48:35 volumio go-librespot[31278]: time="2025-10-27T19:48:35Z" level=debug msg="obtained new client token: AAC1RUyfnFOOa4jyefnDY3olqmUOq0Ela4r8etjiADrZxrFnNr0hDH3mzDnagkotf7hqcsNUUCwGGzqTXRw94csU+4q1OJwYNbd71EP67enFRpD9B12GVGQzgDlB2bNeCGSWvMxkS9WhNA5odu+qZ99YVuu0wnE5dopFLRSoGaXZ7Vc2UJ+CIX5kVvT7IvFpNwh0sOenulcHa5Xe68lTE8oQmhGDwpIBy1xbitzB9/3PWeia7028jZo=" Oct 27 19:48:35 volumio go-librespot[31278]: time="2025-10-27T19:48:35Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 27 19:48:35 volumio go-librespot[31278]: time="2025-10-27T19:48:35Z" level=debug msg="completed keyexchange" Oct 27 19:48:35 volumio go-librespot[31278]: time="2025-10-27T19:48:35Z" level=debug msg="completed challenge" Oct 27 19:48:35 volumio go-librespot[31278]: time="2025-10-27T19:48:35Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 27 19:48:35 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 27 19:48:35 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 27 19:48:35 volumio volumio[31292]: info: ------------------------------------------- Oct 27 19:48:35 volumio volumio[31292]: info: ----- Volumio3 ---- Oct 27 19:48:35 volumio volumio[31292]: info: ------------------------------------------- Oct 27 19:48:35 volumio volumio[31292]: info: ----- System startup ---- Oct 27 19:48:35 volumio volumio[31292]: info: ------------------------------------------- Oct 27 19:48:36 volumio volumio[31292]: info: MYVOLUMIO Environment detected Oct 27 19:48:36 volumio volumio[31292]: info: Plugin folders cleanup Oct 27 19:48:36 volumio volumio[31292]: info: Scanning into folder /volumio/app/plugins/ Oct 27 19:48:36 volumio volumio[31292]: info: Scanning category audio_interface Oct 27 19:48:36 volumio volumio[31292]: info: Scanning category miscellanea Oct 27 19:48:36 volumio volumio[31292]: info: Scanning category music_service Oct 27 19:48:36 volumio volumio[31292]: info: Scanning category plugins.json Oct 27 19:48:36 volumio volumio[31292]: info: Scanning category system_controller Oct 27 19:48:36 volumio volumio[31292]: info: Scanning category user_interface Oct 27 19:48:36 volumio volumio[31292]: info: Scanning into folder /data/plugins/ Oct 27 19:48:36 volumio volumio[31292]: info: Scanning category music_service Oct 27 19:48:36 volumio volumio[31292]: info: Scanning category user_interface Oct 27 19:48:36 volumio volumio[31292]: info: Plugin folders cleanup completed Oct 27 19:48:36 volumio volumio[31292]: info: ------------------------------------------- Oct 27 19:48:36 volumio volumio[31292]: info: ----- Core plugins startup ---- Oct 27 19:48:36 volumio volumio[31292]: info: ------------------------------------------- Oct 27 19:48:36 volumio volumio[31292]: info: Loading plugins from folder /volumio/app/plugins/ Oct 27 19:48:36 volumio volumio[31292]: info: Adding plugin upnp to MyMusic Plugins Oct 27 19:48:36 volumio volumio[31292]: info: Adding plugin airplay_emulation to MyMusic Plugins Oct 27 19:48:36 volumio volumio[31292]: info: Adding plugin upnp_browser to MyMusic Plugins Oct 27 19:48:36 volumio volumio[31292]: info: Loading plugins from folder /data/plugins/ Oct 27 19:48:36 volumio volumio[31292]: info: Loading plugin "system"... Oct 27 19:48:36 volumio volumio[31292]: info: Loading plugin "appearance"... Oct 27 19:48:36 volumio volumio[31292]: info: Loading plugin "network"... Oct 27 19:48:36 volumio volumio[31292]: info: Refreshing Cached IP Addresses Oct 27 19:48:36 volumio sudo[31320]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 27 19:48:36 volumio sudo[31320]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 27 19:48:36 volumio sudo[31322]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 27 19:48:36 volumio sudo[31322]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 27 19:48:36 volumio volumio[31292]: info: Loading plugin "services"... Oct 27 19:48:36 volumio sudo[31322]: pam_unix(sudo:session): session closed for user root Oct 27 19:48:36 volumio sudo[31320]: pam_unix(sudo:session): session closed for user root Oct 27 19:48:36 volumio volumio[31292]: info: Loading plugin "alsa_controller"... Oct 27 19:48:36 volumio volumio[31292]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 27 19:48:36 volumio volumio[31292]: info: Loading plugin "wizard"... Oct 27 19:48:36 volumio volumio[31292]: info: Loading plugin "networkfs"... Oct 27 19:48:36 volumio volumio[31292]: info: Cannot mount NAS NAS at system boot, trial number 1 ,retrying in 5 seconds Oct 27 19:48:36 volumio volumio[31292]: info: Starting Udev Watcher for removable devices Oct 27 19:48:36 volumio volumio[31292]: info: Ignoring mount for partition: boot Oct 27 19:48:36 volumio volumio[31292]: info: Ignoring mount for partition: volumio Oct 27 19:48:36 volumio volumio[31292]: info: Ignoring mount for partition: volumio_data Oct 27 19:48:36 volumio volumio[31292]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 27 19:48:36 volumio volumio[31292]: info: Loading plugin "volumio_command_line_client"... Oct 27 19:48:36 volumio volumio[31292]: info: Loading plugin "upnp"... Oct 27 19:48:36 volumio volumio[31292]: info: [1761594516450] Starting Upmpd Daemon Oct 27 19:48:36 volumio volumio[31292]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 27 19:48:36 volumio volumio[31292]: info: Loading plugin "my_music"... Oct 27 19:48:36 volumio volumio[31292]: info: Loading plugin "mpd"... Oct 27 19:48:36 volumio volumio[31292]: info: Loading plugin "upnp_browser"... Oct 27 19:48:36 volumio volumio[31292]: info: Loading plugin "alarm-clock"... Oct 27 19:48:37 volumio volumio[31292]: info: Loading plugin "airplay_emulation"... Oct 27 19:48:37 volumio volumio[31292]: info: Starting Shairport Sync Oct 27 19:48:37 volumio volumio[31292]: info: Loading plugin "last_100"... Oct 27 19:48:37 volumio volumio[31292]: info: Loading plugin "webradio"... Oct 27 19:48:37 volumio volumio[31292]: info: Loading plugin "i2s_dacs"... Oct 27 19:48:37 volumio volumio[31292]: info: I2S DAC not set, start Auto-detection Oct 27 19:48:37 volumio volumio[31292]: info: Loading plugin "volumiodiscovery"... Oct 27 19:48:37 volumio volumio[31292]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Oct 27 19:48:37 volumio volumio[31292]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 27 19:48:37 volumio volumio[31292]: *** WARNING *** For more information see Oct 27 19:48:37 volumio volumio[31292]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Oct 27 19:48:37 volumio volumio[31292]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 27 19:48:37 volumio volumio[31292]: *** WARNING *** For more information see Oct 27 19:48:37 volumio volumio[31292]: info: Applying required configuration parameters for plugin volumiodiscovery Oct 27 19:48:37 volumio node[31292]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Oct 27 19:48:37 volumio node[31292]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 27 19:48:37 volumio node[31292]: *** WARNING *** For more information see Oct 27 19:48:37 volumio node[31292]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Oct 27 19:48:37 volumio node[31292]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 27 19:48:37 volumio volumio[31292]: info: Discovery: Started advertising with name: Volumio Oct 27 19:48:37 volumio node[31292]: *** WARNING *** For more information see Oct 27 19:48:37 volumio volumio[31292]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 27 19:48:37 volumio volumio[31292]: info: Loading plugin "spop"... Oct 27 19:48:37 volumio volumio[31292]: info: Loading plugin "ytcr"... Oct 27 19:48:38 volumio volumio[31292]: info: Loading plugin "outputs"... Oct 27 19:48:38 volumio volumio[31292]: info: Loading plugin "albumart"... Oct 27 19:48:38 volumio volumio[31292]: info: Plugin example_plugin is not enabled Oct 27 19:48:38 volumio volumio[31292]: info: Loading plugin "inputs"... Oct 27 19:48:38 volumio volumio[31292]: info: Loading plugin "updater_comm"... Oct 27 19:48:38 volumio volumio[31292]: info: Plugin mpdemulation is not enabled Oct 27 19:48:38 volumio volumio[31292]: info: Loading plugin "rest_api"... Oct 27 19:48:38 volumio volumio[31292]: info: Loading plugin "websocket"... Oct 27 19:48:38 volumio volumio[31292]: info: Starting Socket.io Server version 1.7.4 Oct 27 19:48:38 volumio volumio[31292]: info: Loading plugin "Systeminfo"... Oct 27 19:48:38 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1280. Oct 27 19:48:38 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 27 19:48:38 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 27 19:48:38 volumio go-librespot[31363]: go-librespot daemon starting... Oct 27 19:48:38 volumio go-librespot[31364]: time="2025-10-27T19:48:38Z" level=info msg="running go-librespot 0.4.0" Oct 27 19:48:38 volumio go-librespot[31364]: time="2025-10-27T19:48:38Z" level=debug msg="app state loaded" Oct 27 19:48:38 volumio go-librespot[31364]: time="2025-10-27T19:48:38Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 27 19:48:38 volumio volumio[31292]: info: Loading i18n strings for locale en Oct 27 19:48:38 volumio volumio[31292]: Updating browse sources language Oct 27 19:48:38 volumio volumio[31292]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 27 19:48:38 volumio volumio[31353]: Forking 3 albumart workers Oct 27 19:48:38 volumio volumio[31292]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 27 19:48:38 volumio volumio[31292]: info: CoreCommandRouter::initPlayerControls Oct 27 19:48:38 volumio volumio[31292]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 27 19:48:38 volumio volumio[31292]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 27 19:48:38 volumio volumio[31292]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 27 19:48:38 volumio volumio[31292]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 27 19:48:38 volumio volumio[31292]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 27 19:48:38 volumio volumio[31292]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 27 19:48:38 volumio volumio[31292]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 27 19:48:38 volumio volumio[31292]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 27 19:48:38 volumio volumio[31292]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 27 19:48:38 volumio volumio[31292]: Express server listening on port 3000 Oct 27 19:48:38 volumio volumio[31292]: [Metrics] WebUI: 2s 956.18ms Oct 27 19:48:38 volumio volumio[31292]: info: CoreStateMachine::resetVolumioState Oct 27 19:48:38 volumio volumio[31292]: info: CoreStateMachine::getcurrentVolume Oct 27 19:48:38 volumio volumio[31292]: info: CoreCommandRouter::volumioRetrievevolume Oct 27 19:48:38 volumio go-librespot[31364]: time="2025-10-27T19:48:38Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Oct 27 19:48:38 volumio go-librespot[31364]: time="2025-10-27T19:48:38Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Oct 27 19:48:38 volumio go-librespot[31364]: time="2025-10-27T19:48:38Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Oct 27 19:48:38 volumio volumio[31292]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 27 19:48:38 volumio go-librespot[31364]: time="2025-10-27T19:48:38Z" level=info msg="zeroconf server listening on port 44389" Oct 27 19:48:38 volumio volumio[31292]: info: Cannot read play queue from file Oct 27 19:48:38 volumio volumio[31292]: info: Volumio Network Manager: Network status updated: 1 Oct 27 19:48:38 volumio go-librespot[31364]: time="2025-10-27T19:48:38Z" level=debug msg="obtained new client token: AADwJuCZAdDwjn8NhpBC0RpITuT6CSC0H1l6KtpEU6R0rhoivf3DeEYpRxBzvMY0soUJxXVOfJJxubpn+1f8E9u+RrKk3rl9I+0Vf5JUxU6ruEixjsm+O2iaro6CdzEjtms1Hq7yEOPkq9D5YQ4KjBq+Emk39hAa4njLXkXhojpYUi50+dRWlh3L0qEtxo8H0GYuNEJ3jnNMfhnXsNDdv696ww4eNEI/OTbl5n9H3CzUXSlGu5iyiuU=" Oct 27 19:48:38 volumio go-librespot[31364]: time="2025-10-27T19:48:38Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 27 19:48:38 volumio volumio[31292]: info: CoreStateMachine::setRepeat null single undefined Oct 27 19:48:38 volumio volumio[31292]: info: CoreStateMachine::pushState Oct 27 19:48:38 volumio volumio[31292]: info: CorePlayQueue::getTrack 0 Oct 27 19:48:38 volumio volumio[31292]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 27 19:48:38 volumio volumio[31292]: info: CoreCommandRouter::volumioPushState Oct 27 19:48:38 volumio volumio[31292]: info: CoreStateMachine::setRandom null Oct 27 19:48:38 volumio volumio[31292]: info: CoreStateMachine::pushState Oct 27 19:48:38 volumio volumio[31292]: info: CorePlayQueue::getTrack 0 Oct 27 19:48:38 volumio volumio[31292]: info: CoreCommandRouter::volumioPushState Oct 27 19:48:38 volumio volumio[31292]: info: Setting Device type: Raspberry PI Oct 27 19:48:38 volumio volumio[31292]: info: VolumeController:: Volume=33 Mute =false Oct 27 19:48:38 volumio go-librespot[31364]: time="2025-10-27T19:48:38Z" level=debug msg="completed keyexchange" Oct 27 19:48:38 volumio go-librespot[31364]: time="2025-10-27T19:48:38Z" level=debug msg="completed challenge" Oct 27 19:48:38 volumio volumio[31292]: info: CoreStateMachine::pushState Oct 27 19:48:38 volumio volumio[31292]: info: CorePlayQueue::getTrack 0 Oct 27 19:48:38 volumio volumio[31292]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 27 19:48:38 volumio volumio[31292]: info: CoreCommandRouter::volumioPushState Oct 27 19:48:38 volumio volumio[31292]: info: CoreStateMachine::updateTrackBlock Oct 27 19:48:38 volumio volumio[31292]: info: CorePlayQueue::getTrackBlock Oct 27 19:48:38 volumio volumio[31292]: info: CoreCommandRouter::volumioRetrievevolume Oct 27 19:48:38 volumio volumio[31292]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Oct 27 19:48:38 volumio volumio[31292]: info: USB Boot Capable - System SBC Revision found in cpuinfo: b04170 Oct 27 19:48:38 volumio volumio[31292]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Oct 27 19:48:38 volumio go-librespot[31364]: time="2025-10-27T19:48:38Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 27 19:48:38 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 27 19:48:38 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 27 19:48:38 volumio volumio[31292]: info: VolumeController:: Volume=33 Mute =false Oct 27 19:48:38 volumio volumio[31292]: info: CoreStateMachine::pushState Oct 27 19:48:38 volumio volumio[31292]: info: CorePlayQueue::getTrack 0 Oct 27 19:48:38 volumio volumio[31292]: info: CoreCommandRouter::volumioPushState Oct 27 19:48:38 volumio volumio[31292]: info: Completed loading Core Plugins Oct 27 19:48:38 volumio volumio[31292]: info: Preparing to generate the ALSA configuration file Oct 27 19:48:38 volumio volumio[31292]: info: Discovery: adding 70853f74-8210-4683-a3fa-e1217517bd40 Oct 27 19:48:38 volumio volumio[31292]: info: Discovery: Found device Volumio Oct 27 19:48:38 volumio volumio[31292]: info: CoreCommandRouter::volumioGetState Oct 27 19:48:38 volumio volumio[31292]: info: CorePlayQueue::getTrack 0 Oct 27 19:48:38 volumio volumio[31292]: info: Asound.conf file unchanged, so no further update is needed Oct 27 19:48:38 volumio volumio[31292]: info: Output device has changed, restarting MPD Oct 27 19:48:38 volumio volumio[31292]: info: Output device has changed, restarting Shairport Sync Oct 27 19:48:38 volumio volumio[31292]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 27 19:48:38 volumio volumio[31292]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 27 19:48:38 volumio sudo[31419]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 27 19:48:38 volumio volumio[31292]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 27 19:48:38 volumio sudo[31419]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 27 19:48:38 volumio volumio[31292]: info: ___________ START PLUGINS ___________ Oct 27 19:48:38 volumio sudo[31421]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 27 19:48:38 volumio sudo[31421]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 27 19:48:38 volumio sudo[31419]: pam_unix(sudo:session): session closed for user root Oct 27 19:48:38 volumio volumio[31292]: info: ControllerMpd::onStart: Initializing MPD Oct 27 19:48:38 volumio volumio[31292]: info: Creating MPD Configuration file Oct 27 19:48:38 volumio volumio[31292]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 27 19:48:38 volumio volumio[31292]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 27 19:48:38 volumio volumio[31292]: info: [1761594518958] CoreMusicLibrary::Adding element Media Servers Oct 27 19:48:38 volumio volumio[31292]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 27 19:48:38 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Oct 27 19:48:38 volumio sudo[31429]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 27 19:48:38 volumio volumio[31292]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 27 19:48:38 volumio volumio[31292]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 27 19:48:38 volumio sudo[31429]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 27 19:48:38 volumio volumio[31292]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 27 19:48:38 volumio volumio[31292]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 27 19:48:38 volumio volumio[31292]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 27 19:48:38 volumio sudo[31429]: pam_unix(sudo:session): session closed for user root Oct 27 19:48:38 volumio sudo[31431]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 27 19:48:38 volumio sudo[31431]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 27 19:48:38 volumio systemd[1]: mpd.service: Deactivated successfully. Oct 27 19:48:38 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Oct 27 19:48:38 volumio systemd[1]: mpd.socket: Deactivated successfully. Oct 27 19:48:38 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Oct 27 19:48:38 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Oct 27 19:48:38 volumio volumio[31292]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 27 19:48:38 volumio volumio[31292]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 27 19:48:38 volumio volumio[31292]: info: [1761594518995] CoreMusicLibrary::Adding element Last_100 Oct 27 19:48:38 volumio volumio[31292]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 27 19:48:38 volumio volumio[31292]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 27 19:48:38 volumio volumio[31292]: info: [1761594518996] CoreMusicLibrary::Adding element Webradio Oct 27 19:48:38 volumio volumio[31292]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 27 19:48:39 volumio volumio[31292]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 27 19:48:39 volumio volumio[31292]: info: Initializing BBC Radios Oct 27 19:48:39 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Oct 27 19:48:39 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Oct 27 19:48:39 volumio systemd[1]: mpd.service: Deactivated successfully. Oct 27 19:48:39 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Oct 27 19:48:39 volumio systemd[1]: mpd.socket: Deactivated successfully. Oct 27 19:48:39 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Oct 27 19:48:39 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Oct 27 19:48:39 volumio volumio[31292]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 27 19:48:39 volumio volumio[31292]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 27 19:48:39 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Oct 27 19:48:39 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Oct 27 19:48:39 volumio volumio[31292]: info: Creating Spotify config file Oct 27 19:48:39 volumio volumio[31292]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 27 19:48:39 volumio sudo[31458]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Oct 27 19:48:39 volumio sudo[31458]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Oct 27 19:48:39 volumio sudo[31458]: pam_unix(sudo:session): session closed for user root Oct 27 19:48:39 volumio volumio[31370]: Starting albumart workers Oct 27 19:48:39 volumio volumio[31371]: Starting albumart workers Oct 27 19:48:39 volumio volumio[31372]: Starting albumart workers Oct 27 19:48:39 volumio volumio[31292]: info: Volumio Calling Home Oct 27 19:48:39 volumio volumio[31292]: info: Discovery: this is already registered, 70853f74-8210-4683-a3fa-e1217517bd40 Oct 27 19:48:39 volumio volumio[31292]: info: Discovery: Found device Volumio Oct 27 19:48:39 volumio volumio[31292]: info: CoreCommandRouter::volumioGetState Oct 27 19:48:39 volumio volumio[31292]: info: CorePlayQueue::getTrack 0 Oct 27 19:48:39 volumio volumio[31292]: info: MPD Permissions set Oct 27 19:48:39 volumio volumio[31292]: info: MPD Permissions set Oct 27 19:48:39 volumio volumio[31292]: info: Volumio called home Oct 27 19:48:39 volumio volumio[31292]: info: Spotify config file written Oct 27 19:48:39 volumio volumio[31292]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 1 Oct 27 19:48:39 volumio volumio[31292]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 27 19:48:39 volumio volumio[31292]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 27 19:48:39 volumio volumio[31292]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 27 19:48:39 volumio volumio[31292]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 27 19:48:39 volumio volumio[31292]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 27 19:48:39 volumio volumio[31292]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 27 19:48:39 volumio volumio[31292]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 27 19:48:39 volumio volumio[31292]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 27 19:48:39 volumio sudo[31465]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Oct 27 19:48:39 volumio sudo[31465]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 27 19:48:39 volumio volumio[31292]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 27 19:48:39 volumio volumio[31292]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 27 19:48:39 volumio volumio[31292]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 27 19:48:39 volumio volumio[31292]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 27 19:48:39 volumio volumio[31292]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 27 19:48:39 volumio volumio[31292]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 27 19:48:39 volumio volumio[31292]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 27 19:48:39 volumio volumio[31292]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 27 19:48:39 volumio volumio[31292]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 27 19:48:39 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 27 19:48:39 volumio volumio[31292]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 27 19:48:39 volumio volumio[31292]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 27 19:48:39 volumio volumio[31292]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 27 19:48:39 volumio volumio[31292]: info: No need to fix Spotify hosts Oct 27 19:48:39 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 27 19:48:39 volumio go-librespot[31480]: go-librespot daemon starting... Oct 27 19:48:39 volumio sudo[31465]: pam_unix(sudo:session): session closed for user root Oct 27 19:48:39 volumio go-librespot[31490]: time="2025-10-27T19:48:39Z" level=info msg="running go-librespot 0.4.0" Oct 27 19:48:39 volumio go-librespot[31490]: time="2025-10-27T19:48:39Z" level=debug msg="app state loaded" Oct 27 19:48:39 volumio go-librespot[31490]: time="2025-10-27T19:48:39Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 27 19:48:39 volumio volumio[31292]: info: Starting Shairport Sync Oct 27 19:48:39 volumio volumio[31292]: info: Starting Shairport Sync Oct 27 19:48:39 volumio volumio[31292]: info: Starting Shairport Sync Oct 27 19:48:39 volumio sudo[31504]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 27 19:48:39 volumio sudo[31504]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 27 19:48:39 volumio go-librespot[31490]: time="2025-10-27T19:48:39Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Oct 27 19:48:39 volumio go-librespot[31490]: time="2025-10-27T19:48:39Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 27 19:48:39 volumio go-librespot[31490]: time="2025-10-27T19:48:39Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 27 19:48:39 volumio go-librespot[31490]: time="2025-10-27T19:48:39Z" level=info msg="zeroconf server listening on port 46777" Oct 27 19:48:39 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Oct 27 19:48:39 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Oct 27 19:48:39 volumio sudo[31506]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 27 19:48:39 volumio sudo[31509]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 27 19:48:39 volumio sudo[31506]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 27 19:48:39 volumio sudo[31509]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 27 19:48:39 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Oct 27 19:48:39 volumio systemd[1]: shairport-sync.service: Consumed 1.606s CPU time. Oct 27 19:48:39 volumio volumio[31292]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Oct 27 19:48:39 volumio volumio[31292]: SPOTIFY: BQBn-COfj_4HeMvv9QkmG_0l31LTROvqxM0B2ySOX7sHndu8dWePGupFwcblg7mI6Flnf2zKHEQC7jWhtU6MU6KnXaJakWqiaUdJ70Am1ORBec8OEMNBm0kTdQw5cuRMADsYhjSSVSOx25hPUPXi6YTQ-zeJb-LRvdMtjNxkoE9vmfrMHcqsoKwkj9dqsV9IgG-a9C-fqfv3wnm_XRE7L1iRNhZrVJo6oYneqemUT-Wfo4mKcbmi3rQEqvDmNnQWcw1GNLbFjDVMCxjTIeS27DIGY80zG2Z8odtgQWsXqC3ZvWP3HjU Oct 27 19:48:39 volumio volumio[31292]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Oct 27 19:48:39 volumio volumio[31292]: info: New Spotify access token = BQBn-COfj_4HeMvv9QkmG_0l31LTROvqxM0B2ySOX7sHndu8dWePGupFwcblg7mI6Flnf2zKHEQC7jWhtU6MU6KnXaJakWqiaUdJ70Am1ORBec8OEMNBm0kTdQw5cuRMADsYhjSSVSOx25hPUPXi6YTQ-zeJb-LRvdMtjNxkoE9vmfrMHcqsoKwkj9dqsV9IgG-a9C-fqfv3wnm_XRE7L1iRNhZrVJo6oYneqemUT-Wfo4mKcbmi3rQEqvDmNnQWcw1GNLbFjDVMCxjTIeS27DIGY80zG2Z8odtgQWsXqC3ZvWP3HjU Oct 27 19:48:39 volumio volumio[31292]: info: Spotify credentials grant success - running version from March 24, 2019 Oct 27 19:48:39 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Oct 27 19:48:39 volumio sudo[31504]: pam_unix(sudo:session): session closed for user root Oct 27 19:48:39 volumio volumio[31292]: info: Shairport-Sync Started Oct 27 19:48:39 volumio volumio[31292]: Error adding Membership: Error: addMembership EINVAL Oct 27 19:48:39 volumio volumio[31292]: info: CoreCommandRouter::volumioGetState Oct 27 19:48:39 volumio volumio[31292]: info: CorePlayQueue::getTrack 0 Oct 27 19:48:39 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Oct 27 19:48:39 volumio go-librespot[31490]: time="2025-10-27T19:48:39Z" level=debug msg="obtained new client token: AABR1GMPl7EQIHrN7sQEQq4CwH3MLzHe/L9C7Iy3+AIpEc4s9SveHQOvauwrfOJIwmx9lRV1gTLuCJTOpbnmDi0U9YQGx0evDeEj+tg2qP/xLEBL7ZVbK6vJf/lo0qV0Ggu+SDNpySiRS4pQrIFApeMoGZXqde5Z8rFl8xc/PjuPwxEvwWnTt+U/l42vwdQqeHogURyUso6eVltU96iGfCtn3SVHutHpPQsKNfCUt8IcHcojTHxZFyw=" Oct 27 19:48:39 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Oct 27 19:48:39 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Oct 27 19:48:39 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Oct 27 19:48:39 volumio sudo[31509]: pam_unix(sudo:session): session closed for user root Oct 27 19:48:39 volumio sudo[31506]: pam_unix(sudo:session): session closed for user root Oct 27 19:48:39 volumio volumio[31292]: info: Shairport-Sync Started Oct 27 19:48:39 volumio volumio[31292]: info: Shairport-Sync Started Oct 27 19:48:39 volumio go-librespot[31490]: time="2025-10-27T19:48:39Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 27 19:48:39 volumio go-librespot[31490]: time="2025-10-27T19:48:39Z" level=debug msg="completed keyexchange" Oct 27 19:48:39 volumio go-librespot[31490]: time="2025-10-27T19:48:39Z" level=debug msg="completed challenge" Oct 27 19:48:39 volumio volumio[31292]: SPOTIFY: User informations: {"country":"DE","display_name":"lapman","email":"ylm19961214@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/31hyzsop5elyyfayaiyk5tmkxmky"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/31hyzsop5elyyfayaiyk5tmkxmky","id":"31hyzsop5elyyfayaiyk5tmkxmky","images":[],"product":"free","type":"user","uri":"spotify:user:31hyzsop5elyyfayaiyk5tmkxmky"} Oct 27 19:48:39 volumio volumio[31292]: info: Spotify Successfully logged in Oct 27 19:48:39 volumio volumio[31292]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 27 19:48:39 volumio volumio[31292]: info: [1761594519846] CoreMusicLibrary::Adding element Spotify Oct 27 19:48:39 volumio volumio[31292]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 27 19:48:39 volumio volumio[31292]: Cannot find translation for source Spotify Oct 27 19:48:39 volumio go-librespot[31490]: time="2025-10-27T19:48:39Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 27 19:48:39 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 27 19:48:39 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 27 19:48:39 volumio mpd[31460]: 2025-10-27T19:48:39 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Oct 27 19:48:39 volumio systemd[1]: Started mpd.service - Music Player Daemon. Oct 27 19:48:39 volumio sudo[31431]: pam_unix(sudo:session): session closed for user root Oct 27 19:48:39 volumio sudo[31421]: pam_unix(sudo:session): session closed for user root Oct 27 19:48:39 volumio volumio[31292]: error: MPD error: The expression evaluated to a falsy value: Oct 27 19:48:39 volumio volumio[31292]: assert.ok(self.idling) Oct 27 19:48:39 volumio volumio[31292]: error: The expression evaluated to a falsy value: Oct 27 19:48:39 volumio volumio[31292]: assert.ok(self.idling) Oct 27 19:48:39 volumio volumio[31292]: error: updateQueue error: null Oct 27 19:48:40 volumio volumio[31292]: info: MPD running with PID31460 Oct 27 19:48:40 volumio volumio[31292]: ,establishing connection Oct 27 19:48:40 volumio volumio[31292]: error: updateQueue error: null Oct 27 19:48:40 volumio volumio-remote-updater[874]: [2025-10-27 19:48:40] [connect] Successful connection Oct 27 19:48:40 volumio volumio-remote-updater[874]: [2025-10-27 19:48:40] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1761594520 101 Oct 27 19:48:40 volumio volumio[31292]: 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: 2 Oct 27 19:48:41 volumio volumio[31292]: info: Cannot mount NAS NAS at system boot, trial number 2 ,retrying in 5 seconds Oct 27 19:48:42 volumio volumio[31292]: info: go-librespot daemon successfully initialized Oct 27 19:48:42 volumio sudo[31535]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Oct 27 19:48:42 volumio sudo[31535]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 27 19:48:42 volumio sudo[31537]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Oct 27 19:48:42 volumio sudo[31537]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 27 19:48:42 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1281. Oct 27 19:48:42 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 27 19:48:43 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 27 19:48:43 volumio go-librespot[31540]: go-librespot daemon starting... Oct 27 19:48:43 volumio systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Oct 27 19:48:43 volumio systemd[1]: mpd_monitor.service: Deactivated successfully. Oct 27 19:48:43 volumio systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Oct 27 19:48:43 volumio systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Oct 27 19:48:43 volumio go-librespot[31541]: time="2025-10-27T19:48:43Z" level=info msg="running go-librespot 0.4.0" Oct 27 19:48:43 volumio go-librespot[31541]: time="2025-10-27T19:48:43Z" level=debug msg="app state loaded" Oct 27 19:48:43 volumio go-librespot[31541]: time="2025-10-27T19:48:43Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 27 19:48:43 volumio mpd_monitor.sh[31547]: MPD Monitor Service: Starting MPD Monitor Service Oct 27 19:48:43 volumio sudo[31537]: pam_unix(sudo:session): session closed for user root Oct 27 19:48:43 volumio sudo[31535]: pam_unix(sudo:session): session closed for user root Oct 27 19:48:43 volumio volumio[31292]: info: Successfully started MPD Monitor Oct 27 19:48:43 volumio volumio[31292]: info: Successfully started MPD Monitor Oct 27 19:48:43 volumio go-librespot[31541]: time="2025-10-27T19:48:43Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Oct 27 19:48:43 volumio go-librespot[31541]: time="2025-10-27T19:48:43Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 27 19:48:43 volumio go-librespot[31541]: time="2025-10-27T19:48:43Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 27 19:48:43 volumio go-librespot[31541]: time="2025-10-27T19:48:43Z" level=info msg="zeroconf server listening on port 41907" Oct 27 19:48:43 volumio go-librespot[31541]: time="2025-10-27T19:48:43Z" level=debug msg="obtained new client token: AABI1zZk+EdJcD6svBA7NxzMBuuFYNu0qy0i+a4ML+4Q1G4JseyfqErK5YTCuujJaK2P+8WEIWpmNkb6owAsfcAGVEHxkokI4L6/H6Q/qvJno+jPqL/Sre1eRjbVdbAx4VvCbL17QgirFYLn7JROCwCdDuIs9p8EEkOBesdVHYdKOIsAQvUGbZNLWuB/t1LH0Pq82Q+trrwnn1poDYqQNH7jr8gbOK9kOBAQdjYM4vti34IkG0Le" Oct 27 19:48:43 volumio go-librespot[31541]: time="2025-10-27T19:48:43Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 27 19:48:43 volumio go-librespot[31541]: time="2025-10-27T19:48:43Z" level=debug msg="completed keyexchange" Oct 27 19:48:43 volumio go-librespot[31541]: time="2025-10-27T19:48:43Z" level=debug msg="completed challenge" Oct 27 19:48:43 volumio go-librespot[31541]: time="2025-10-27T19:48:43Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 27 19:48:43 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 27 19:48:43 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 27 19:48:44 volumio volumio[31292]: info: [yt-cast-receiver] DIAL server listening on port 8098 Oct 27 19:48:44 volumio volumio[31292]: info: CoreCommandRouter::volumioRetrievevolume Oct 27 19:48:44 volumio volumio[31292]: info: VolumeController:: Volume=33 Mute =false Oct 27 19:48:44 volumio volumio[31292]: info: CoreCommandRouter::volumioGetState Oct 27 19:48:44 volumio volumio[31292]: info: CorePlayQueue::getTrack 0 Oct 27 19:48:44 volumio volumio[31292]: info: CoreStateMachine::pushState Oct 27 19:48:44 volumio volumio[31292]: info: CorePlayQueue::getTrack 0 Oct 27 19:48:44 volumio volumio[31292]: info: CoreCommandRouter::volumioPushState Oct 27 19:48:44 volumio volumio[31292]: info: Completed starting Core Plugins Oct 27 19:48:44 volumio volumio[31292]: info: ------------------------------------------- Oct 27 19:48:44 volumio volumio[31292]: info: ----- MyVolumio plugins startup ---- Oct 27 19:48:44 volumio volumio[31292]: info: ------------------------------------------- Oct 27 19:48:44 volumio volumio[31292]: info: [MyVolumio PluginManager] Fetching plans data.... Oct 27 19:48:44 volumio volumio[31292]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Oct 27 19:48:45 volumio volumio[31292]: info: Initializing connection to go-librespot Websocket Oct 27 19:48:45 volumio volumio[31292]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 27 19:48:46 volumio volumio[31292]: info: Cannot mount NAS NAS at system boot, trial number 3 ,retrying in 5 seconds Oct 27 19:48:46 volumio sudo[31570]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 27 19:48:46 volumio sudo[31570]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 27 19:48:46 volumio sudo[31570]: pam_unix(sudo:session): session closed for user root Oct 27 19:48:46 volumio sudo[31572]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 27 19:48:46 volumio sudo[31572]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 27 19:48:46 volumio sudo[31572]: pam_unix(sudo:session): session closed for user root Oct 27 19:48:46 volumio sudo[31576]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Oct 27 19:48:46 volumio sudo[31576]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 27 19:48:46 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1282. Oct 27 19:48:46 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 27 19:48:46 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 27 19:48:46 volumio go-librespot[31579]: go-librespot daemon starting... Oct 27 19:48:46 volumio sudo[31576]: pam_unix(sudo:session): session closed for user root Oct 27 19:48:46 volumio volumio[31292]: info: Upmpdcli Daemon Started Oct 27 19:48:46 volumio go-librespot[31580]: time="2025-10-27T19:48:46Z" level=info msg="running go-librespot 0.4.0" Oct 27 19:48:46 volumio go-librespot[31580]: time="2025-10-27T19:48:46Z" level=debug msg="app state loaded" Oct 27 19:48:46 volumio go-librespot[31580]: time="2025-10-27T19:48:46Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 27 19:48:46 volumio go-librespot[31580]: time="2025-10-27T19:48:46Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Oct 27 19:48:46 volumio go-librespot[31580]: time="2025-10-27T19:48:46Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 27 19:48:46 volumio go-librespot[31580]: time="2025-10-27T19:48:46Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 27 19:48:46 volumio go-librespot[31580]: time="2025-10-27T19:48:46Z" level=info msg="zeroconf server listening on port 45195" Oct 27 19:48:46 volumio go-librespot[31580]: time="2025-10-27T19:48:46Z" level=debug msg="obtained new client token: AAC+P1jGpJROu3VJC9UkR4WCL8kRspom60ewHw36/V6vxx7GHFbWXjUvrByVCWOSNaFjgF3UN+LWSK4R+hSJLU4lGIBEiG91GNmmPPh34/1WYII/s5qJzeyKu6hCsj4DtXbKOpUa2h72AaAuTyil01zHIHMdWBGLljfeGabqbD14oPVbGrQEC3rvkJC/VYTrZRAmyJERi8Vp5bY9hqCykBXXTv65svaQvPWcHjjgsM6qn19XADMBQbk=" Oct 27 19:48:46 volumio go-librespot[31580]: time="2025-10-27T19:48:46Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 27 19:48:46 volumio go-librespot[31580]: time="2025-10-27T19:48:46Z" level=debug msg="completed keyexchange" Oct 27 19:48:46 volumio go-librespot[31580]: time="2025-10-27T19:48:46Z" level=debug msg="completed challenge" Oct 27 19:48:46 volumio go-librespot[31580]: time="2025-10-27T19:48:46Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 27 19:48:46 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 27 19:48:46 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 27 19:48:48 volumio volumio[31292]: info: Initializing connection to go-librespot Websocket Oct 27 19:48:48 volumio volumio[31292]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 27 19:48:50 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1283. Oct 27 19:48:50 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 27 19:48:50 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 27 19:48:50 volumio go-librespot[31588]: go-librespot daemon starting... Oct 27 19:48:50 volumio go-librespot[31589]: time="2025-10-27T19:48:50Z" level=info msg="running go-librespot 0.4.0" Oct 27 19:48:50 volumio go-librespot[31589]: time="2025-10-27T19:48:50Z" level=debug msg="app state loaded" Oct 27 19:48:50 volumio go-librespot[31589]: time="2025-10-27T19:48:50Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 27 19:48:50 volumio go-librespot[31589]: time="2025-10-27T19:48:50Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Oct 27 19:48:50 volumio go-librespot[31589]: time="2025-10-27T19:48:50Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 27 19:48:50 volumio go-librespot[31589]: time="2025-10-27T19:48:50Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 27 19:48:50 volumio go-librespot[31589]: time="2025-10-27T19:48:50Z" level=info msg="zeroconf server listening on port 34231" Oct 27 19:48:50 volumio go-librespot[31589]: time="2025-10-27T19:48:50Z" level=debug msg="obtained new client token: AABB9KYAEhppoVXniJT7OpsS3fv4f9RA3D8SMx2LG7Nmk5GuohN7FrMw6irQMo+VXLsTOZwYrEN/QQ20iiTRQaaAXZPSKE38WwJ+9vSIy2OMvF3Q176S1OY270zJ3pFvqxoE+xSO76H+VU3XiSrqTGNsBY1ZONAN1DYfYtBKo1LudJ8h8Sv4ts2fBrJ6fPkM3HZXRWRssoUed/Ad+hol9BOEyFxKWO/gnB85144+IsffJwlMF2DE" Oct 27 19:48:50 volumio go-librespot[31589]: time="2025-10-27T19:48:50Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 27 19:48:50 volumio go-librespot[31589]: time="2025-10-27T19:48:50Z" level=debug msg="completed keyexchange" Oct 27 19:48:50 volumio go-librespot[31589]: time="2025-10-27T19:48:50Z" level=debug msg="completed challenge" Oct 27 19:48:50 volumio go-librespot[31589]: time="2025-10-27T19:48:50Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 27 19:48:50 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 27 19:48:50 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 27 19:48:51 volumio volumio[31292]: info: Cannot mount NAS NAS at system boot, trial number 4 ,retrying in 5 seconds Oct 27 19:48:51 volumio volumio[31292]: info: Initializing connection to go-librespot Websocket Oct 27 19:48:51 volumio volumio[31292]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 27 19:48:52 volumio volumio[31292]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Oct 27 19:48:52 volumio volumio[31292]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Oct 27 19:48:52 volumio volumio[31292]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Oct 27 19:48:52 volumio volumio[31292]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Oct 27 19:48:52 volumio volumio[31292]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Oct 27 19:48:52 volumio volumio[31292]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Oct 27 19:48:52 volumio volumio[31292]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Oct 27 19:48:52 volumio volumio[31292]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Oct 27 19:48:52 volumio volumio[31292]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Oct 27 19:48:52 volumio volumio[31292]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Oct 27 19:48:52 volumio volumio[31292]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Oct 27 19:48:52 volumio volumio[31292]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Oct 27 19:48:52 volumio volumio[31292]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Oct 27 19:48:52 volumio volumio[31292]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Oct 27 19:48:52 volumio volumio[31292]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Oct 27 19:48:52 volumio volumio[31292]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Oct 27 19:48:52 volumio volumio[31292]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Oct 27 19:48:52 volumio volumio[31292]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Oct 27 19:48:52 volumio volumio[31292]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Oct 27 19:48:52 volumio volumio[31292]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Oct 27 19:48:52 volumio volumio[31292]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Oct 27 19:48:52 volumio volumio[31292]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Oct 27 19:48:52 volumio volumio[31292]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Oct 27 19:48:52 volumio volumio[31292]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Oct 27 19:48:52 volumio volumio[31292]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Oct 27 19:48:52 volumio volumio[31292]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Oct 27 19:48:52 volumio volumio[31292]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Oct 27 19:48:52 volumio volumio[31292]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Oct 27 19:48:52 volumio volumio[31292]: info: Adding plugin bluetooth to MyMusic Plugins Oct 27 19:48:52 volumio volumio[31292]: info: Adding plugin multiroom to MyMusic Plugins Oct 27 19:48:52 volumio volumio[31292]: info: Adding plugin metavolumio to MyMusic Plugins Oct 27 19:48:52 volumio volumio[31292]: info: Adding plugin cd_controller to MyMusic Plugins Oct 27 19:48:52 volumio volumio[31292]: info: Adding plugin qobuzconnect to MyMusic Plugins Oct 27 19:48:52 volumio volumio[31292]: info: Adding plugin smart_inputs to MyMusic Plugins Oct 27 19:48:52 volumio volumio[31292]: info: Adding plugin tidalconnect to MyMusic Plugins Oct 27 19:48:52 volumio volumio[31292]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Oct 27 19:48:52 volumio volumio[31292]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Oct 27 19:48:52 volumio volumio[31292]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Oct 27 19:48:52 volumio volumio[31292]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 27 19:48:52 volumio volumio[31292]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 27 19:48:52 volumio volumio[31292]: info: Starting MyVolumio Remote Streaming Endpoints Oct 27 19:48:52 volumio volumio[31292]: info: MyVolumio login type: Token Oct 27 19:48:52 volumio volumio[31292]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Oct 27 19:48:52 volumio volumio[31292]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Oct 27 19:48:53 volumio volumio[31292]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Oct 27 19:48:53 volumio volumio[31292]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Oct 27 19:48:53 volumio volumio[31292]: info: Streaming services startup Oct 27 19:48:53 volumio volumio[31292]: info: Starting Streaming Daemon Oct 27 19:48:53 volumio sudo[31597]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Oct 27 19:48:53 volumio sudo[31597]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 27 19:48:53 volumio volumio[31292]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Oct 27 19:48:53 volumio sudo[31597]: pam_unix(sudo:session): session closed for user root Oct 27 19:48:53 volumio volumio[31292]: error: Cannot start Volumio Streaming Daemon Oct 27 19:48:53 volumio volumio[31292]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Oct 27 19:48:53 volumio volumio[31292]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Oct 27 19:48:53 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1284. Oct 27 19:48:53 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 27 19:48:53 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 27 19:48:53 volumio go-librespot[31604]: go-librespot daemon starting... Oct 27 19:48:53 volumio go-librespot[31605]: time="2025-10-27T19:48:53Z" level=info msg="running go-librespot 0.4.0" Oct 27 19:48:53 volumio go-librespot[31605]: time="2025-10-27T19:48:53Z" level=debug msg="app state loaded" Oct 27 19:48:53 volumio go-librespot[31605]: time="2025-10-27T19:48:53Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 27 19:48:53 volumio volumio[31292]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Oct 27 19:48:54 volumio volumio[31292]: info: MyVolumio token set successfully Oct 27 19:48:54 volumio volumio[31292]: info: MYVOLUMIO: Adding device Oct 27 19:48:54 volumio volumio[31292]: info: MYVOLUMIO: Evaluating Server Oct 27 19:48:54 volumio volumio[31292]: info: MyVolumio status changed Oct 27 19:48:54 volumio volumio[31292]: info: Streaming services startup Oct 27 19:48:54 volumio volumio[31292]: info: Starting Streaming Daemon Oct 27 19:48:54 volumio volumio[31292]: info: Removing browser output: myVolumio user plan is not superstar Oct 27 19:48:54 volumio volumio[31292]: info: Removing audio output: Oct 27 19:48:54 volumio volumio[31292]: info: Stoppping Tunnel 1 Oct 27 19:48:54 volumio sudo[31630]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Oct 27 19:48:54 volumio sudo[31630]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 27 19:48:54 volumio sudo[31632]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service Oct 27 19:48:54 volumio sudo[31632]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 27 19:48:54 volumio sudo[31630]: pam_unix(sudo:session): session closed for user root Oct 27 19:48:54 volumio volumio[31292]: error: Cannot start Volumio Streaming Daemon Oct 27 19:48:54 volumio volumio[31292]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Oct 27 19:48:54 volumio volumio[31292]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Oct 27 19:48:54 volumio 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. Oct 27 19:48:54 volumio 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. Oct 27 19:48:54 volumio 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. Oct 27 19:48:54 volumio 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. Oct 27 19:48:54 volumio 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. Oct 27 19:48:54 volumio 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. Oct 27 19:48:54 volumio 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. Oct 27 19:48:54 volumio 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. Oct 27 19:48:54 volumio sudo[31632]: pam_unix(sudo:session): session closed for user root Oct 27 19:48:54 volumio volumio[31292]: info: Remote SSH Stopped Oct 27 19:48:54 volumio volumio[31292]: info: Setting Geolocation for MyVolumio to eu3 Oct 27 19:48:54 volumio volumio[31292]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 27 19:48:54 volumio volumio[31292]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 27 19:48:54 volumio volumio[31292]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 27 19:48:54 volumio volumio[31292]: info: Initializing connection to go-librespot Websocket Oct 27 19:48:54 volumio go-librespot[31605]: time="2025-10-27T19:48:54Z" level=debug msg="new websocket client" Oct 27 19:48:54 volumio volumio[31292]: info: Connection to go-librespot Websocket established Oct 27 19:48:54 volumio volumio[31292]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Oct 27 19:48:55 volumio volumio[31292]: info: Updating MyVolumio device info Oct 27 19:48:55 volumio volumio[31292]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 27 19:48:55 volumio volumio[31292]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 27 19:48:55 volumio volumio[31292]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 27 19:48:55 volumio volumio[31292]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Oct 27 19:48:56 volumio volumio[31292]: info: Cannot mount NAS at system boot, trial number 4 ,stopping Oct 27 19:48:57 volumio volumio[31292]: info: Getting Spotify volume Oct 27 19:48:57 volumio volumio[31292]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Oct 27 19:48:57 volumio volumio[31292]: info: CoreCommandRouter::volumioGetState Oct 27 19:48:57 volumio volumio[31292]: info: CorePlayQueue::getTrack 0 Oct 27 19:48:57 volumio volumio[31292]: SPOTIFY: RECEIVED VOLUMIO VOLUME 33 Oct 27 19:48:57 volumio volumio[31292]: SPOTIFY: SPOTIFY VOLUME undefined Oct 27 19:48:57 volumio volumio[31292]: SPOTIFY: VOLUMIO VOLUME 33 Oct 27 19:48:57 volumio volumio[31292]: info: Aligning Spotify Volume to Volumio Volume Oct 27 19:48:57 volumio volumio[31292]: info: CoreCommandRouter::volumioGetState Oct 27 19:48:57 volumio volumio[31292]: info: CorePlayQueue::getTrack 0 Oct 27 19:48:57 volumio volumio[31292]: info: Setting Spotify Volume from Volumio: 33 Oct 27 19:48:58 volumio go-librespot[31605]: time="2025-10-27T19:48:58Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Oct 27 19:48:58 volumio go-librespot[31605]: time="2025-10-27T19:48:58Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Oct 27 19:48:58 volumio go-librespot[31605]: time="2025-10-27T19:48:58Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Oct 27 19:48:58 volumio go-librespot[31605]: time="2025-10-27T19:48:58Z" level=info msg="zeroconf server listening on port 39169" Oct 27 19:48:58 volumio go-librespot[31605]: time="2025-10-27T19:48:58Z" level=debug msg="obtained new client token: AABITQeyh7BmpAUFBVru3SEbuPODDWcnRP1kXpkX5dmwUp5P2QGCGJ/sBNQF3N9huDPK4FxjyReU2dpVgAggXNUl0YrEXD2LQzMZRvdLauBGbyFBtEETaQ9prGO4st9cWFGxQfAmel3SqmmbyfN5dty2Vyg+UZo1wV8RuKm7yKkXvQalMRLl7/a3Ss98l/wEEzUi7DwTx34RifCyY0LQRCI5h9n881QpRi09ubjqLhuuYKAHyFhq42A=" Oct 27 19:48:58 volumio go-librespot[31605]: time="2025-10-27T19:48:58Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 27 19:48:58 volumio volumio[31292]: info: MYVOLUMIO: Adding device Oct 27 19:48:58 volumio volumio[31292]: info: MYVOLUMIO: Evaluating Server Oct 27 19:48:58 volumio go-librespot[31605]: time="2025-10-27T19:48:58Z" level=debug msg="completed keyexchange" Oct 27 19:48:58 volumio go-librespot[31605]: time="2025-10-27T19:48:58Z" level=debug msg="completed challenge" Oct 27 19:48:58 volumio go-librespot[31605]: time="2025-10-27T19:48:58Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 27 19:48:58 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 27 19:48:58 volumio volumio[31292]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 27 19:48:58 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 27 19:48:58 volumio volumio[31292]: Error: socket hang up Oct 27 19:48:58 volumio volumio[31292]: at connResetException (node:internal/errors:720:14) Oct 27 19:48:58 volumio volumio[31292]: at Socket.socketOnEnd (node:_http_client:519:23) Oct 27 19:48:58 volumio volumio[31292]: at Socket.emit (node:events:526:35) Oct 27 19:48:58 volumio volumio[31292]: at endReadableNT (node:internal/streams/readable:1376:12) Oct 27 19:48:58 volumio volumio[31292]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { Oct 27 19:48:58 volumio volumio[31292]: code: 'ECONNRESET', Oct 27 19:48:58 volumio volumio[31292]: response: undefined Oct 27 19:48:58 volumio volumio[31292]: } Oct 27 19:48:58 volumio volumio[31292]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 27 19:48:59 volumio sudo[31665]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-10-27 19:47' Oct 27 19:48:59 volumio sudo[31665]: 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="c22b72a8acb34a699a626adb0a09a6b88ee7233a" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="40400d6a6fa57cf20e36499e510876b3654e9c4e" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Sat Oct 4 16:40:08 UTC 2025" VOLUMIO_VERSION="4.061" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="7f8ace80645f85765fa10c72d1769d04"