Oct 30 04:59:01 volumio volumio[20149]: info: Initializing connection to go-librespot Websocket Oct 30 04:59:01 volumio volumio[20149]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 30 04:59:01 volumio kernel: nfs: server 192.168.1.3 not responding, timed out Oct 30 04:59:02 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 89. Oct 30 04:59:02 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 30 04:59:02 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 30 04:59:02 volumio go-librespot[20814]: go-librespot daemon starting... Oct 30 04:59:02 volumio go-librespot[20815]: time="2025-10-30T04:59:02Z" level=info msg="running go-librespot 0.4.0" Oct 30 04:59:02 volumio go-librespot[20815]: time="2025-10-30T04:59:02Z" level=debug msg="app state loaded" Oct 30 04:59:02 volumio go-librespot[20815]: time="2025-10-30T04:59:02Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 30 04:59:02 volumio go-librespot[20815]: time="2025-10-30T04:59:02Z" 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 30 04:59:02 volumio go-librespot[20815]: time="2025-10-30T04:59:02Z" 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 30 04:59:02 volumio go-librespot[20815]: time="2025-10-30T04:59:02Z" 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 30 04:59:02 volumio go-librespot[20815]: time="2025-10-30T04:59:02Z" level=info msg="zeroconf server listening on port 36307" Oct 30 04:59:02 volumio go-librespot[20815]: time="2025-10-30T04:59:02Z" level=debug msg="obtained new client token: AABxxUyR3yLyzmGb3j24rhnxJgmvVuYjZdmBAhU5w37P8MOj9mUTdpZ2T8N0uU6ZmuTI3M56jqJW6Rwp9NTNW3jVzJInfNnflD4S7/vNZNC27SiDT1GwiZyPYQz5mZMqt6Mu0LGShMg88VpI/bjlesSrByvB/EIRN9IYjcGjKZcPmYbEPnuF3ceM5ubWiVK452Z23LhMx1N2pIY60jCRzDLKWrfc1/ultRaTIJTI6IBPZWOWdhx7" Oct 30 04:59:02 volumio go-librespot[20815]: time="2025-10-30T04:59:02Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 30 04:59:02 volumio go-librespot[20815]: time="2025-10-30T04:59:02Z" level=debug msg="completed keyexchange" Oct 30 04:59:02 volumio go-librespot[20815]: time="2025-10-30T04:59:02Z" level=debug msg="completed challenge" Oct 30 04:59:02 volumio go-librespot[20815]: time="2025-10-30T04:59:02Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 30 04:59:02 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 30 04:59:02 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 30 04:59:04 volumio volumio[20149]: info: Initializing connection to go-librespot Websocket Oct 30 04:59:04 volumio volumio[20149]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 30 04:59:05 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 90. Oct 30 04:59:05 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 30 04:59:05 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 30 04:59:05 volumio go-librespot[20836]: go-librespot daemon starting... Oct 30 04:59:05 volumio go-librespot[20837]: time="2025-10-30T04:59:05Z" level=info msg="running go-librespot 0.4.0" Oct 30 04:59:05 volumio go-librespot[20837]: time="2025-10-30T04:59:05Z" level=debug msg="app state loaded" Oct 30 04:59:05 volumio go-librespot[20837]: time="2025-10-30T04:59:05Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 30 04:59:05 volumio go-librespot[20837]: time="2025-10-30T04:59:05Z" 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 30 04:59:05 volumio go-librespot[20837]: time="2025-10-30T04:59:05Z" 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 30 04:59:05 volumio go-librespot[20837]: time="2025-10-30T04:59:05Z" 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 30 04:59:05 volumio go-librespot[20837]: time="2025-10-30T04:59:05Z" level=info msg="zeroconf server listening on port 46879" Oct 30 04:59:05 volumio go-librespot[20837]: time="2025-10-30T04:59:05Z" level=debug msg="obtained new client token: AAAP6tt+TIMJ3/zgpN1ywAKIx67pw73qGHt9SGKMUkdFXEAcfrwuHmYBpbv7fQ5EH/pyL/d8utIwXpsVjgkIlvPJNJ/CQHk+jRBGxpU58P8H0S/nEXb1Hh74nFRJK/k/Zvk7Fk6HWj7i6L2szw2DreMNep7MSdUpnptSAAJO14iNRbxsDy20lE53ZmtyZnEAtD9EipwSRt/WkvUF2omt4EFIXnA5rBUllSk1wT4lSX+1wk31e2DrAXo=" Oct 30 04:59:05 volumio go-librespot[20837]: time="2025-10-30T04:59:05Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 30 04:59:05 volumio go-librespot[20837]: time="2025-10-30T04:59:05Z" level=debug msg="completed keyexchange" Oct 30 04:59:05 volumio go-librespot[20837]: time="2025-10-30T04:59:05Z" level=debug msg="completed challenge" Oct 30 04:59:05 volumio go-librespot[20837]: time="2025-10-30T04:59:05Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 30 04:59:05 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 30 04:59:05 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 30 04:59:07 volumio volumio[20149]: info: Initializing connection to go-librespot Websocket Oct 30 04:59:07 volumio volumio[20149]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 30 04:59:08 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 91. Oct 30 04:59:08 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 30 04:59:08 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 30 04:59:08 volumio go-librespot[20844]: go-librespot daemon starting... Oct 30 04:59:08 volumio go-librespot[20845]: time="2025-10-30T04:59:08Z" level=info msg="running go-librespot 0.4.0" Oct 30 04:59:08 volumio go-librespot[20845]: time="2025-10-30T04:59:08Z" level=debug msg="app state loaded" Oct 30 04:59:08 volumio go-librespot[20845]: time="2025-10-30T04:59:08Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 30 04:59:08 volumio go-librespot[20845]: time="2025-10-30T04:59:08Z" 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 30 04:59:08 volumio go-librespot[20845]: time="2025-10-30T04:59:08Z" 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 30 04:59:08 volumio go-librespot[20845]: time="2025-10-30T04:59:08Z" 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 30 04:59:08 volumio go-librespot[20845]: time="2025-10-30T04:59:08Z" level=info msg="zeroconf server listening on port 44919" Oct 30 04:59:08 volumio go-librespot[20845]: time="2025-10-30T04:59:08Z" level=debug msg="obtained new client token: AAB6XS+Ni15CbymC3bBaCWoF6locroDwy6qEnLHU7EuQZVYA/Jv+B+8opPfQbd0tA+ehzHlA/2mkybjpuSvi4ZPk7gy9DzJjM39Wyas0x/PIHtFNklVf1XzaQ3dh7Qe1ImQFpKAjPeZqlG0zYe56GgHgSAj009IPFWQ3bbq0FpxZ5BK2JWRfLuPVfGgPfDBgddrhjf5MO6TrMJTMzezwFyrhBOepSVsP5coRlL6CWgNfbaYB3BCeCOk=" Oct 30 04:59:08 volumio go-librespot[20845]: time="2025-10-30T04:59:08Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 30 04:59:08 volumio go-librespot[20845]: time="2025-10-30T04:59:08Z" level=debug msg="completed keyexchange" Oct 30 04:59:08 volumio go-librespot[20845]: time="2025-10-30T04:59:08Z" level=debug msg="completed challenge" Oct 30 04:59:09 volumio go-librespot[20845]: time="2025-10-30T04:59:09Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 30 04:59:09 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 30 04:59:09 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 30 04:59:10 volumio volumio[20149]: info: Initializing connection to go-librespot Websocket Oct 30 04:59:10 volumio volumio[20149]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 30 04:59:12 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 92. Oct 30 04:59:12 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 30 04:59:12 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 30 04:59:12 volumio go-librespot[20852]: go-librespot daemon starting... Oct 30 04:59:12 volumio go-librespot[20853]: time="2025-10-30T04:59:12Z" level=info msg="running go-librespot 0.4.0" Oct 30 04:59:12 volumio go-librespot[20853]: time="2025-10-30T04:59:12Z" level=debug msg="app state loaded" Oct 30 04:59:12 volumio go-librespot[20853]: time="2025-10-30T04:59:12Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 30 04:59:12 volumio go-librespot[20853]: time="2025-10-30T04:59:12Z" 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 30 04:59:12 volumio go-librespot[20853]: time="2025-10-30T04:59:12Z" 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 30 04:59:12 volumio go-librespot[20853]: time="2025-10-30T04:59:12Z" 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 30 04:59:12 volumio go-librespot[20853]: time="2025-10-30T04:59:12Z" level=info msg="zeroconf server listening on port 41955" Oct 30 04:59:12 volumio go-librespot[20853]: time="2025-10-30T04:59:12Z" level=debug msg="obtained new client token: AABxmC97D0mJfEseiVSUeCma7dsADmFj4Dck9zp1y0FEA1H3glbaFYI7NS/AaaR97xQBe9cYGR41gWZn3a9KUe4j5AOaUurl2Fujm5ttRYkLmBtmyDpt6fk0w3WJAlxxH3VvjL3kB+1RyhWLVCrYATuHqQCWM/PvyNG5sGQ610Hewt6KIzmHHdd1eml7m+KU6zH/yLJwxwr0lwaHXDAchHoNbj4lMYnLcO87/XIolcWjoMnP/xgX" Oct 30 04:59:12 volumio go-librespot[20853]: time="2025-10-30T04:59:12Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 30 04:59:12 volumio go-librespot[20853]: time="2025-10-30T04:59:12Z" level=debug msg="completed keyexchange" Oct 30 04:59:12 volumio go-librespot[20853]: time="2025-10-30T04:59:12Z" level=debug msg="completed challenge" Oct 30 04:59:12 volumio go-librespot[20853]: time="2025-10-30T04:59:12Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 30 04:59:12 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 30 04:59:12 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 30 04:59:13 volumio kernel: nfs: server 192.168.1.3 not responding, timed out Oct 30 04:59:13 volumio volumio[20149]: info: Initializing connection to go-librespot Websocket Oct 30 04:59:13 volumio volumio[20149]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 30 04:59:15 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 93. Oct 30 04:59:15 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 30 04:59:15 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 30 04:59:15 volumio go-librespot[20874]: go-librespot daemon starting... Oct 30 04:59:15 volumio go-librespot[20875]: time="2025-10-30T04:59:15Z" level=info msg="running go-librespot 0.4.0" Oct 30 04:59:15 volumio go-librespot[20875]: time="2025-10-30T04:59:15Z" level=debug msg="app state loaded" Oct 30 04:59:15 volumio go-librespot[20875]: time="2025-10-30T04:59:15Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 30 04:59:15 volumio go-librespot[20875]: time="2025-10-30T04:59:15Z" 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 30 04:59:15 volumio go-librespot[20875]: time="2025-10-30T04:59:15Z" 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 30 04:59:15 volumio go-librespot[20875]: time="2025-10-30T04:59:15Z" 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 30 04:59:15 volumio go-librespot[20875]: time="2025-10-30T04:59:15Z" level=info msg="zeroconf server listening on port 45437" Oct 30 04:59:15 volumio go-librespot[20875]: time="2025-10-30T04:59:15Z" level=debug msg="obtained new client token: AACZSCLkZlOUgwixoSAwvzIQAkGeeIligih30FfNLv/I01usViwofQGBKxvBIAaPBsUdB691Hg3LRs1HhS0vF+s7vnKjPhQ3lccHsCDtLvsbOKnh0rAB35NBmajx8oMJPx4Pw4IiY9vzZhsEpHsUdZfayxgGVwPcZs4hSbbUDpIRqvsI2JpsvF4l9ml5ucs1Qr5i6c/Hf++mgGtkzFBU5Cj4aK7JiceRQW00/3SIqsgEkrvoVpPA7hU=" Oct 30 04:59:15 volumio go-librespot[20875]: time="2025-10-30T04:59:15Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 30 04:59:15 volumio go-librespot[20875]: time="2025-10-30T04:59:15Z" level=debug msg="completed keyexchange" Oct 30 04:59:15 volumio go-librespot[20875]: time="2025-10-30T04:59:15Z" level=debug msg="completed challenge" Oct 30 04:59:15 volumio go-librespot[20875]: time="2025-10-30T04:59:15Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 30 04:59:15 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 30 04:59:15 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 30 04:59:16 volumio volumio[20149]: info: Initializing connection to go-librespot Websocket Oct 30 04:59:16 volumio volumio[20149]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 30 04:59:19 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 94. Oct 30 04:59:19 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 30 04:59:19 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 30 04:59:19 volumio go-librespot[20886]: go-librespot daemon starting... Oct 30 04:59:19 volumio go-librespot[20887]: time="2025-10-30T04:59:19Z" level=info msg="running go-librespot 0.4.0" Oct 30 04:59:19 volumio go-librespot[20887]: time="2025-10-30T04:59:19Z" level=debug msg="app state loaded" Oct 30 04:59:19 volumio go-librespot[20887]: time="2025-10-30T04:59:19Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 30 04:59:19 volumio go-librespot[20887]: time="2025-10-30T04:59:19Z" 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 30 04:59:19 volumio go-librespot[20887]: time="2025-10-30T04:59:19Z" 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 30 04:59:19 volumio go-librespot[20887]: time="2025-10-30T04:59:19Z" 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 30 04:59:19 volumio go-librespot[20887]: time="2025-10-30T04:59:19Z" level=info msg="zeroconf server listening on port 38447" Oct 30 04:59:19 volumio go-librespot[20887]: time="2025-10-30T04:59:19Z" level=debug msg="obtained new client token: AACeZX6SQHQ/tnb7NHs9OWBOuuJxjas+Z/FZKfjbhqrqkQQol+Mj3eA5I61XEXrBI2XYO4hfqABq2uldNeojROh4/MDq55ybv14gNv9NoY6UZsY3rqyaCwuKBhIjz3Tp3chItScr6v3+tRIxe0CjwHk5JDvhh2RVD0NasRwN75TwMdrpWZ0HiH/Qs2hX8LNjoF5eM/CrS8I0FDk+ucp2BIb+EjJouFVQV5AwMVtTBct4UJuQAsM2" Oct 30 04:59:19 volumio go-librespot[20887]: time="2025-10-30T04:59:19Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 30 04:59:19 volumio go-librespot[20887]: time="2025-10-30T04:59:19Z" level=debug msg="completed keyexchange" Oct 30 04:59:19 volumio go-librespot[20887]: time="2025-10-30T04:59:19Z" level=debug msg="completed challenge" Oct 30 04:59:19 volumio go-librespot[20887]: time="2025-10-30T04:59:19Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 30 04:59:19 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 30 04:59:19 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 30 04:59:19 volumio volumio[20149]: info: Initializing connection to go-librespot Websocket Oct 30 04:59:19 volumio volumio[20149]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 30 04:59:22 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 95. Oct 30 04:59:22 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 30 04:59:22 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 30 04:59:22 volumio go-librespot[20908]: go-librespot daemon starting... Oct 30 04:59:22 volumio go-librespot[20909]: time="2025-10-30T04:59:22Z" level=info msg="running go-librespot 0.4.0" Oct 30 04:59:22 volumio go-librespot[20909]: time="2025-10-30T04:59:22Z" level=debug msg="app state loaded" Oct 30 04:59:22 volumio go-librespot[20909]: time="2025-10-30T04:59:22Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 30 04:59:22 volumio volumio[20149]: info: Initializing connection to go-librespot Websocket Oct 30 04:59:22 volumio go-librespot[20909]: time="2025-10-30T04:59:22Z" level=debug msg="new websocket client" Oct 30 04:59:22 volumio volumio[20149]: info: Connection to go-librespot Websocket established Oct 30 04:59:22 volumio go-librespot[20909]: time="2025-10-30T04:59:22Z" 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 30 04:59:22 volumio go-librespot[20909]: time="2025-10-30T04:59:22Z" 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 30 04:59:22 volumio go-librespot[20909]: time="2025-10-30T04:59:22Z" 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 30 04:59:22 volumio go-librespot[20909]: time="2025-10-30T04:59:22Z" level=info msg="zeroconf server listening on port 42647" Oct 30 04:59:22 volumio go-librespot[20909]: time="2025-10-30T04:59:22Z" level=debug msg="obtained new client token: AADjkb2s5eRCMnB0OOkkUiWdJAN9rQ9desue5ustlvIwgL1wD4p9AcVeKfegdS/Dg8LGr8wyDEy5iDX76ptmFwFrsY8GsGaWQTGF36OOa85L2VJAvOUg2xcUaqW3gqampiBBL8Q0semE3EwvjJFgy3xdnPo/LpUKsKr1svnENkH9Y6KkddU70tSBV8DO6WriTNVrsAjjjFyrTMe2ZRJXasqE7+MukrRy/WJuAwWzXXzPVt210fzkMic=" Oct 30 04:59:22 volumio go-librespot[20909]: time="2025-10-30T04:59:22Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 30 04:59:22 volumio go-librespot[20909]: time="2025-10-30T04:59:22Z" level=debug msg="completed keyexchange" Oct 30 04:59:22 volumio go-librespot[20909]: time="2025-10-30T04:59:22Z" level=debug msg="completed challenge" Oct 30 04:59:22 volumio go-librespot[20909]: time="2025-10-30T04:59:22Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 30 04:59:22 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 30 04:59:22 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 30 04:59:22 volumio volumio[20149]: info: Connection to go-librespot Websocket closed Oct 30 04:59:25 volumio volumio[20149]: info: Getting Spotify volume Oct 30 04:59:25 volumio volumio[20149]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 30 04:59:25 volumio volumio[20149]: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 30 04:59:25 volumio volumio[20149]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Oct 30 04:59:25 volumio volumio[20149]: errno: -111, Oct 30 04:59:25 volumio volumio[20149]: code: 'ECONNREFUSED', Oct 30 04:59:25 volumio volumio[20149]: syscall: 'connect', Oct 30 04:59:25 volumio volumio[20149]: address: '127.0.0.1', Oct 30 04:59:25 volumio volumio[20149]: port: 9879, Oct 30 04:59:25 volumio volumio[20149]: response: undefined Oct 30 04:59:25 volumio volumio[20149]: } Oct 30 04:59:25 volumio volumio[20149]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 30 04:59:25 volumio sudo[20931]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-10-30 04:58' Oct 30 04:59:25 volumio sudo[20931]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 30 04:59:25 volumio sudo[20931]: pam_unix(sudo:session): session closed for user root Oct 30 04:59:25 volumio volumio-remote-updater[874]: [2025-10-30 04:59:25] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Oct 30 04:59:25 volumio volumio-remote-updater[874]: [2025-10-30 04:59:25] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Oct 30 04:59:25 volumio systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Oct 30 04:59:25 volumio systemd[1]: volumio.service: Failed with result 'exit-code'. Oct 30 04:59:25 volumio systemd[1]: volumio.service: Consumed 7.820s CPU time. Oct 30 04:59:25 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Oct 30 04:59:25 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 96. Oct 30 04:59:25 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 30 04:59:25 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 30 04:59:25 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Oct 30 04:59:25 volumio go-librespot[20940]: go-librespot daemon starting... Oct 30 04:59:25 volumio go-librespot[20943]: time="2025-10-30T04:59:25Z" level=info msg="running go-librespot 0.4.0" Oct 30 04:59:25 volumio go-librespot[20943]: time="2025-10-30T04:59:25Z" level=debug msg="app state loaded" Oct 30 04:59:25 volumio go-librespot[20943]: time="2025-10-30T04:59:25Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 30 04:59:25 volumio go-librespot[20943]: time="2025-10-30T04:59: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 30 04:59:25 volumio go-librespot[20943]: time="2025-10-30T04:59: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 30 04:59:25 volumio go-librespot[20943]: time="2025-10-30T04:59: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 30 04:59:25 volumio go-librespot[20943]: time="2025-10-30T04:59:25Z" level=info msg="zeroconf server listening on port 41173" Oct 30 04:59:25 volumio go-librespot[20943]: time="2025-10-30T04:59:25Z" level=debug msg="obtained new client token: AAC7bgwE04LTtPrmIm+NSS1RnJghRpi0NfR7o9xFiwWxj7IC6nCtNcgJZM0WhF2nxUEQKc867u99M2/sqnMU+VQnPaaoa09eFufPtTR/FahcHMCJGcnIYmVgXP7AGJs2yThcmYPrLGUQhctH+iBEO2AnuhLqA7JPp4Ck4OzB+60Ybp1CovENss/l4+VRJunuyiAJfooQWethtfqAztte7Ia+hH0ZU1UVcxYPGvJ3NFs9YQI1fkuMB5o=" Oct 30 04:59:25 volumio go-librespot[20943]: time="2025-10-30T04:59:25Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 30 04:59:26 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 2745. Oct 30 04:59:26 volumio go-librespot[20943]: time="2025-10-30T04:59:26Z" level=debug msg="completed keyexchange" Oct 30 04:59:26 volumio go-librespot[20943]: time="2025-10-30T04:59:26Z" level=debug msg="completed challenge" Oct 30 04:59:26 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Oct 30 04:59:26 volumio systemd[1]: Stopped volumio.service - Volumio Backend Module. Oct 30 04:59:26 volumio systemd[1]: volumio.service: Consumed 7.820s CPU time. Oct 30 04:59:26 volumio systemd[1]: Started volumio.service - Volumio Backend Module. Oct 30 04:59:26 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Oct 30 04:59:26 volumio go-librespot[20943]: time="2025-10-30T04:59:26Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 30 04:59:26 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 30 04:59:26 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 30 04:59:26 volumio volumio[20954]: info: ------------------------------------------- Oct 30 04:59:26 volumio volumio[20954]: info: ----- Volumio3 ---- Oct 30 04:59:26 volumio volumio[20954]: info: ------------------------------------------- Oct 30 04:59:26 volumio volumio[20954]: info: ----- System startup ---- Oct 30 04:59:26 volumio volumio[20954]: info: ------------------------------------------- Oct 30 04:59:26 volumio volumio[20954]: info: MYVOLUMIO Environment detected Oct 30 04:59:26 volumio volumio[20954]: info: Plugin folders cleanup Oct 30 04:59:26 volumio volumio[20954]: info: Scanning into folder /volumio/app/plugins/ Oct 30 04:59:26 volumio volumio[20954]: info: Scanning category audio_interface Oct 30 04:59:26 volumio volumio[20954]: info: Scanning category miscellanea Oct 30 04:59:26 volumio volumio[20954]: info: Scanning category music_service Oct 30 04:59:26 volumio volumio[20954]: info: Scanning category plugins.json Oct 30 04:59:26 volumio volumio[20954]: info: Scanning category system_controller Oct 30 04:59:26 volumio volumio[20954]: info: Scanning category user_interface Oct 30 04:59:26 volumio volumio[20954]: info: Scanning into folder /data/plugins/ Oct 30 04:59:26 volumio volumio[20954]: info: Scanning category music_service Oct 30 04:59:26 volumio volumio[20954]: info: Scanning category user_interface Oct 30 04:59:26 volumio volumio[20954]: info: Plugin folders cleanup completed Oct 30 04:59:26 volumio volumio[20954]: info: ------------------------------------------- Oct 30 04:59:26 volumio volumio[20954]: info: ----- Core plugins startup ---- Oct 30 04:59:26 volumio volumio[20954]: info: ------------------------------------------- Oct 30 04:59:26 volumio volumio[20954]: info: Loading plugins from folder /volumio/app/plugins/ Oct 30 04:59:26 volumio volumio[20954]: info: Adding plugin upnp to MyMusic Plugins Oct 30 04:59:26 volumio volumio[20954]: info: Adding plugin airplay_emulation to MyMusic Plugins Oct 30 04:59:26 volumio volumio[20954]: info: Adding plugin upnp_browser to MyMusic Plugins Oct 30 04:59:26 volumio volumio[20954]: info: Loading plugins from folder /data/plugins/ Oct 30 04:59:26 volumio volumio[20954]: info: Loading plugin "system"... Oct 30 04:59:26 volumio volumio[20954]: info: Loading plugin "appearance"... Oct 30 04:59:26 volumio volumio[20954]: info: Loading plugin "network"... Oct 30 04:59:26 volumio volumio[20954]: info: Refreshing Cached IP Addresses Oct 30 04:59:26 volumio sudo[20979]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 30 04:59:26 volumio sudo[20979]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 30 04:59:26 volumio sudo[20979]: pam_unix(sudo:session): session closed for user root Oct 30 04:59:26 volumio volumio[20954]: info: Loading plugin "services"... Oct 30 04:59:26 volumio volumio[20954]: info: Loading plugin "alsa_controller"... Oct 30 04:59:26 volumio sudo[20981]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 30 04:59:26 volumio sudo[20981]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 30 04:59:26 volumio sudo[20981]: pam_unix(sudo:session): session closed for user root Oct 30 04:59:26 volumio volumio[20954]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 30 04:59:26 volumio volumio[20954]: info: Loading plugin "wizard"... Oct 30 04:59:26 volumio volumio[20954]: info: Loading plugin "networkfs"... Oct 30 04:59:26 volumio volumio[20954]: info: Cannot mount NAS NAS at system boot, trial number 1 ,retrying in 5 seconds Oct 30 04:59:26 volumio volumio[20954]: info: Starting Udev Watcher for removable devices Oct 30 04:59:26 volumio volumio[20954]: info: Ignoring mount for partition: boot Oct 30 04:59:26 volumio volumio[20954]: info: Ignoring mount for partition: volumio Oct 30 04:59:26 volumio volumio[20954]: info: Ignoring mount for partition: volumio_data Oct 30 04:59:26 volumio volumio[20954]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 30 04:59:26 volumio volumio[20954]: info: Loading plugin "volumio_command_line_client"... Oct 30 04:59:26 volumio volumio[20954]: info: Loading plugin "upnp"... Oct 30 04:59:26 volumio volumio[20954]: info: [1761800366807] Starting Upmpd Daemon Oct 30 04:59:26 volumio volumio[20954]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 30 04:59:26 volumio volumio[20954]: info: Loading plugin "my_music"... Oct 30 04:59:26 volumio volumio[20954]: info: Loading plugin "mpd"... Oct 30 04:59:26 volumio volumio[20954]: info: Loading plugin "upnp_browser"... Oct 30 04:59:27 volumio volumio[20954]: info: Loading plugin "alarm-clock"... Oct 30 04:59:27 volumio volumio[20954]: info: Loading plugin "airplay_emulation"... Oct 30 04:59:27 volumio volumio[20954]: info: Starting Shairport Sync Oct 30 04:59:27 volumio volumio[20954]: info: Loading plugin "last_100"... Oct 30 04:59:27 volumio volumio[20954]: info: Loading plugin "webradio"... Oct 30 04:59:27 volumio volumio[20954]: info: Loading plugin "i2s_dacs"... Oct 30 04:59:27 volumio volumio[20954]: info: I2S DAC not set, start Auto-detection Oct 30 04:59:27 volumio volumio[20954]: info: Loading plugin "volumiodiscovery"... Oct 30 04:59:27 volumio volumio[20954]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Oct 30 04:59:27 volumio volumio[20954]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 30 04:59:27 volumio volumio[20954]: *** WARNING *** For more information see Oct 30 04:59:27 volumio volumio[20954]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Oct 30 04:59:27 volumio volumio[20954]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 30 04:59:27 volumio volumio[20954]: *** WARNING *** For more information see Oct 30 04:59:27 volumio node[20954]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Oct 30 04:59:27 volumio node[20954]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 30 04:59:27 volumio node[20954]: *** WARNING *** For more information see Oct 30 04:59:27 volumio node[20954]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Oct 30 04:59:27 volumio node[20954]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 30 04:59:27 volumio node[20954]: *** WARNING *** For more information see Oct 30 04:59:27 volumio volumio[20954]: info: Applying required configuration parameters for plugin volumiodiscovery Oct 30 04:59:27 volumio volumio[20954]: info: Discovery: Started advertising with name: Volumio Oct 30 04:59:27 volumio volumio[20954]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 30 04:59:27 volumio volumio[20954]: info: Loading plugin "spop"... Oct 30 04:59:27 volumio volumio[20954]: info: Loading plugin "ytcr"... Oct 30 04:59:27 volumio kernel: nfs: server 192.168.1.3 not responding, timed out Oct 30 04:59:28 volumio volumio[20954]: info: Loading plugin "outputs"... Oct 30 04:59:28 volumio volumio[20954]: info: Loading plugin "albumart"... Oct 30 04:59:28 volumio volumio[20954]: info: Plugin example_plugin is not enabled Oct 30 04:59:28 volumio volumio[20954]: info: Loading plugin "inputs"... Oct 30 04:59:28 volumio volumio[20954]: info: Loading plugin "updater_comm"... Oct 30 04:59:28 volumio volumio[20954]: info: Plugin mpdemulation is not enabled Oct 30 04:59:28 volumio volumio[20954]: info: Loading plugin "rest_api"... Oct 30 04:59:28 volumio volumio[20954]: info: Loading plugin "websocket"... Oct 30 04:59:28 volumio volumio[20954]: info: Starting Socket.io Server version 1.7.4 Oct 30 04:59:28 volumio volumio[20954]: info: Loading plugin "Systeminfo"... Oct 30 04:59:28 volumio volumio[20954]: info: Loading i18n strings for locale en Oct 30 04:59:28 volumio volumio[20954]: Updating browse sources language Oct 30 04:59:28 volumio volumio[20954]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 30 04:59:28 volumio volumio[21011]: Forking 3 albumart workers Oct 30 04:59:28 volumio volumio[20954]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 30 04:59:28 volumio volumio[20954]: info: CoreCommandRouter::initPlayerControls Oct 30 04:59:28 volumio volumio[20954]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 04:59:28 volumio volumio[20954]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 04:59:28 volumio volumio[20954]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 04:59:28 volumio volumio[20954]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 04:59:28 volumio volumio[20954]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 04:59:28 volumio volumio[20954]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 04:59:28 volumio volumio[20954]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 04:59:28 volumio volumio[20954]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 04:59:28 volumio volumio[20954]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 30 04:59:28 volumio volumio[20954]: Express server listening on port 3000 Oct 30 04:59:28 volumio volumio[20954]: [Metrics] WebUI: 1s 938.63ms Oct 30 04:59:28 volumio volumio[20954]: info: CoreStateMachine::resetVolumioState Oct 30 04:59:28 volumio volumio[20954]: info: CoreStateMachine::getcurrentVolume Oct 30 04:59:28 volumio volumio[20954]: info: CoreCommandRouter::volumioRetrievevolume Oct 30 04:59:28 volumio volumio[20954]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 30 04:59:28 volumio volumio[20954]: info: Cannot read play queue from file Oct 30 04:59:28 volumio volumio[20954]: info: Volumio Network Manager: Network status updated: 1 Oct 30 04:59:28 volumio volumio[20954]: info: CoreStateMachine::setRepeat null single undefined Oct 30 04:59:28 volumio volumio[20954]: info: CoreStateMachine::pushState Oct 30 04:59:28 volumio volumio[20954]: info: CorePlayQueue::getTrack 0 Oct 30 04:59:28 volumio volumio[20954]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 30 04:59:28 volumio volumio[20954]: info: CoreCommandRouter::volumioPushState Oct 30 04:59:28 volumio volumio[20954]: info: CoreStateMachine::setRandom null Oct 30 04:59:28 volumio volumio[20954]: info: CoreStateMachine::pushState Oct 30 04:59:28 volumio volumio[20954]: info: CorePlayQueue::getTrack 0 Oct 30 04:59:28 volumio volumio[20954]: info: CoreCommandRouter::volumioPushState Oct 30 04:59:28 volumio volumio[20954]: info: Setting Device type: Raspberry PI Oct 30 04:59:28 volumio volumio[20954]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Oct 30 04:59:28 volumio volumio[20954]: info: USB Boot Capable - System SBC Revision found in cpuinfo: b04170 Oct 30 04:59:28 volumio volumio[20954]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Oct 30 04:59:28 volumio volumio[20954]: info: VolumeController:: Volume=33 Mute =false Oct 30 04:59:28 volumio volumio[20954]: info: CoreStateMachine::pushState Oct 30 04:59:28 volumio volumio[20954]: info: CorePlayQueue::getTrack 0 Oct 30 04:59:28 volumio volumio[20954]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 30 04:59:28 volumio volumio[20954]: info: CoreCommandRouter::volumioPushState Oct 30 04:59:28 volumio volumio[20954]: info: CoreStateMachine::updateTrackBlock Oct 30 04:59:28 volumio volumio[20954]: info: CorePlayQueue::getTrackBlock Oct 30 04:59:28 volumio volumio[20954]: info: CoreCommandRouter::volumioRetrievevolume Oct 30 04:59:28 volumio volumio[20954]: info: Completed loading Core Plugins Oct 30 04:59:28 volumio volumio[20954]: info: Preparing to generate the ALSA configuration file Oct 30 04:59:28 volumio volumio[20954]: info: Discovery: adding 70853f74-8210-4683-a3fa-e1217517bd40 Oct 30 04:59:28 volumio volumio[20954]: info: Discovery: Found device Volumio Oct 30 04:59:28 volumio volumio[20954]: info: CoreCommandRouter::volumioGetState Oct 30 04:59:28 volumio volumio[20954]: info: CorePlayQueue::getTrack 0 Oct 30 04:59:28 volumio volumio[20954]: info: VolumeController:: Volume=33 Mute =false Oct 30 04:59:28 volumio volumio[20954]: info: CoreStateMachine::pushState Oct 30 04:59:28 volumio volumio[20954]: info: CorePlayQueue::getTrack 0 Oct 30 04:59:28 volumio volumio[20954]: info: CoreCommandRouter::volumioPushState Oct 30 04:59:28 volumio volumio[20954]: info: Discovery: this is already registered, 70853f74-8210-4683-a3fa-e1217517bd40 Oct 30 04:59:28 volumio volumio[20954]: info: Discovery: Found device Volumio Oct 30 04:59:28 volumio volumio[20954]: info: CoreCommandRouter::volumioGetState Oct 30 04:59:28 volumio volumio[20954]: info: CorePlayQueue::getTrack 0 Oct 30 04:59:28 volumio volumio[20954]: info: Asound.conf file unchanged, so no further update is needed Oct 30 04:59:28 volumio volumio[20954]: info: Output device has changed, restarting MPD Oct 30 04:59:28 volumio volumio[20954]: info: Output device has changed, restarting Shairport Sync Oct 30 04:59:28 volumio volumio[20954]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 04:59:28 volumio volumio[20954]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 30 04:59:28 volumio sudo[21068]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 30 04:59:28 volumio sudo[21068]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 30 04:59:28 volumio sudo[21068]: pam_unix(sudo:session): session closed for user root Oct 30 04:59:28 volumio sudo[21069]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 30 04:59:28 volumio sudo[21069]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 30 04:59:28 volumio volumio[20954]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 30 04:59:28 volumio volumio[20954]: info: ___________ START PLUGINS ___________ Oct 30 04:59:28 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Oct 30 04:59:28 volumio systemd[1]: mpd.service: Deactivated successfully. Oct 30 04:59:28 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Oct 30 04:59:28 volumio systemd[1]: mpd.socket: Deactivated successfully. Oct 30 04:59:28 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Oct 30 04:59:28 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Oct 30 04:59:28 volumio volumio[20954]: info: ControllerMpd::onStart: Initializing MPD Oct 30 04:59:28 volumio volumio[20954]: info: Creating MPD Configuration file Oct 30 04:59:28 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Oct 30 04:59:28 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Oct 30 04:59:28 volumio volumio[20954]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 30 04:59:28 volumio volumio[20954]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 30 04:59:28 volumio volumio[20954]: info: [1761800368535] CoreMusicLibrary::Adding element Media Servers Oct 30 04:59:28 volumio sudo[21079]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 30 04:59:28 volumio volumio[20954]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 30 04:59:28 volumio sudo[21082]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 30 04:59:28 volumio sudo[21082]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 30 04:59:28 volumio sudo[21079]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 30 04:59:28 volumio sudo[21079]: pam_unix(sudo:session): session closed for user root Oct 30 04:59:28 volumio volumio[20954]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 04:59:28 volumio volumio[20954]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 30 04:59:28 volumio volumio[20954]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 30 04:59:28 volumio volumio[20954]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 04:59:28 volumio volumio[20954]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 30 04:59:28 volumio systemd[1]: mpd.service: Deactivated successfully. Oct 30 04:59:28 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Oct 30 04:59:28 volumio systemd[1]: mpd.socket: Deactivated successfully. Oct 30 04:59:28 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Oct 30 04:59:28 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Oct 30 04:59:28 volumio volumio[20954]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 30 04:59:28 volumio volumio[20954]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 30 04:59:28 volumio volumio[20954]: info: [1761800368594] CoreMusicLibrary::Adding element Last_100 Oct 30 04:59:28 volumio volumio[20954]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 30 04:59:28 volumio volumio[20954]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 30 04:59:28 volumio volumio[20954]: info: [1761800368599] CoreMusicLibrary::Adding element Webradio Oct 30 04:59:28 volumio volumio[20954]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 30 04:59:28 volumio volumio[20954]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 30 04:59:28 volumio volumio[20954]: info: Initializing BBC Radios Oct 30 04:59:28 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Oct 30 04:59:28 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Oct 30 04:59:28 volumio volumio[21030]: Starting albumart workers Oct 30 04:59:28 volumio volumio[20954]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 30 04:59:28 volumio volumio[20954]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 30 04:59:28 volumio sudo[21096]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Oct 30 04:59:28 volumio sudo[21096]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Oct 30 04:59:28 volumio volumio[20954]: info: Creating Spotify config file Oct 30 04:59:28 volumio volumio[20954]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 04:59:28 volumio sudo[21096]: pam_unix(sudo:session): session closed for user root Oct 30 04:59:28 volumio volumio[21022]: Starting albumart workers Oct 30 04:59:28 volumio volumio[21021]: Starting albumart workers Oct 30 04:59:28 volumio volumio[20954]: info: Volumio Calling Home Oct 30 04:59:29 volumio volumio[20954]: info: MPD Permissions set Oct 30 04:59:29 volumio volumio[20954]: info: MPD Permissions set Oct 30 04:59:29 volumio volumio[20954]: info: Spotify config file written Oct 30 04:59:29 volumio volumio[20954]: 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 30 04:59:29 volumio sudo[21132]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Oct 30 04:59:29 volumio sudo[21132]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 30 04:59:29 volumio volumio[20954]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 04:59:29 volumio volumio[20954]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 04:59:29 volumio volumio[20954]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 04:59:29 volumio volumio[20954]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 04:59:29 volumio volumio[20954]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 04:59:29 volumio volumio[20954]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 04:59:29 volumio volumio[20954]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 04:59:29 volumio volumio[20954]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 04:59:29 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 30 04:59:29 volumio volumio[20954]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 30 04:59:29 volumio volumio[20954]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 04:59:29 volumio volumio[20954]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 04:59:29 volumio volumio[20954]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 04:59:29 volumio volumio[20954]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 04:59:29 volumio volumio[20954]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 04:59:29 volumio volumio[20954]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 04:59:29 volumio volumio[20954]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 04:59:29 volumio volumio[20954]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 04:59:29 volumio volumio[20954]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 04:59:29 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 30 04:59:29 volumio go-librespot[21137]: go-librespot daemon starting... Oct 30 04:59:29 volumio go-librespot[21145]: time="2025-10-30T04:59:29Z" level=info msg="running go-librespot 0.4.0" Oct 30 04:59:29 volumio go-librespot[21145]: time="2025-10-30T04:59:29Z" level=debug msg="app state loaded" Oct 30 04:59:29 volumio go-librespot[21145]: time="2025-10-30T04:59:29Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 30 04:59:29 volumio volumio[20954]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 30 04:59:29 volumio volumio[20954]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 04:59:29 volumio volumio[20954]: info: No need to fix Spotify hosts Oct 30 04:59:29 volumio sudo[21132]: pam_unix(sudo:session): session closed for user root Oct 30 04:59:29 volumio volumio[20954]: info: Volumio called home Oct 30 04:59:29 volumio volumio[20954]: info: Starting Shairport Sync Oct 30 04:59:29 volumio volumio[20954]: info: Starting Shairport Sync Oct 30 04:59:29 volumio volumio[20954]: info: Starting Shairport Sync Oct 30 04:59:29 volumio sudo[21154]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 30 04:59:29 volumio sudo[21154]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 30 04:59:29 volumio sudo[21152]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 30 04:59:29 volumio sudo[21152]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 30 04:59:29 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Oct 30 04:59:29 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Oct 30 04:59:29 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Oct 30 04:59:29 volumio systemd[1]: shairport-sync.service: Consumed 1.560s CPU time. Oct 30 04:59:29 volumio sudo[21157]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 30 04:59:29 volumio sudo[21157]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 30 04:59:29 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Oct 30 04:59:29 volumio sudo[21154]: pam_unix(sudo:session): session closed for user root Oct 30 04:59:29 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Oct 30 04:59:29 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Oct 30 04:59:29 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Oct 30 04:59:29 volumio go-librespot[21145]: time="2025-10-30T04:59:29Z" 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 30 04:59:29 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Oct 30 04:59:29 volumio go-librespot[21145]: time="2025-10-30T04:59:29Z" 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 30 04:59:29 volumio go-librespot[21145]: time="2025-10-30T04:59:29Z" 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 30 04:59:29 volumio go-librespot[21145]: time="2025-10-30T04:59:29Z" level=info msg="zeroconf server listening on port 40355" Oct 30 04:59:29 volumio sudo[21152]: pam_unix(sudo:session): session closed for user root Oct 30 04:59:29 volumio sudo[21157]: pam_unix(sudo:session): session closed for user root Oct 30 04:59:29 volumio volumio[20954]: info: Shairport-Sync Started Oct 30 04:59:29 volumio volumio[20954]: Error adding Membership: Error: addMembership EINVAL Oct 30 04:59:29 volumio volumio[20954]: info: Shairport-Sync Started Oct 30 04:59:29 volumio volumio[20954]: info: Shairport-Sync Started Oct 30 04:59:29 volumio mpd[21109]: 2025-10-30T04:59:29 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Oct 30 04:59:29 volumio systemd[1]: Started mpd.service - Music Player Daemon. Oct 30 04:59:29 volumio sudo[21082]: pam_unix(sudo:session): session closed for user root Oct 30 04:59:29 volumio sudo[21069]: pam_unix(sudo:session): session closed for user root Oct 30 04:59:29 volumio volumio[20954]: info: CoreCommandRouter::volumioGetState Oct 30 04:59:29 volumio volumio[20954]: info: CorePlayQueue::getTrack 0 Oct 30 04:59:29 volumio go-librespot[21145]: time="2025-10-30T04:59:29Z" level=debug msg="obtained new client token: AAA3Z3S9PTBHdpCUAIV9ct63jnGovyr65xl/r1KfBqGRRi0ESIsCuBB/Olm5fpiMJRzjIJNp5senMtR1xDQoxnHhpzhZzxvHe9w77VldRIWCG/hPyIFbg4Cxp1W8KXKnrcnpuIlp4eQl1B9xfbuz5NByH/51vJOvg9CT44AEm47hPfq9QDfGsEII4uq5swZAC20tVFTei587nAmpr19iNmENb869yRPWMBFuWSaw25zyE8iUJG4X" Oct 30 04:59:29 volumio volumio[20954]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Oct 30 04:59:29 volumio volumio[20954]: SPOTIFY: BQAz-2BTwKlsG642dQ16z9cPo9JGE4UQyRBDcNnWhv4wO1ICrfPoGXG-8COVtb5VadLAJlTyzG7Xxbx0s2wGtuHANMQev8j_ZhxTDcasq5MSXVYpZwQ0zHNpWIFfvb4ltEa8WpCKCj0m9CAcnc7ThWGwVdLfvxyC-AGaybIZ0XSbc79jCcDABjj7oUy1xXOUsA63nMExEdZjOFPo4TxOPbUTGtjbxpKqEn5ol03Zvgo1EEY5Qh2E3AK7VUqz_t8tYh1753cxuVqpptdelGcFSTqu67E5bHW9TjshMTdzOys6-XOTJXA Oct 30 04:59:29 volumio volumio[20954]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Oct 30 04:59:29 volumio volumio[20954]: info: New Spotify access token = BQAz-2BTwKlsG642dQ16z9cPo9JGE4UQyRBDcNnWhv4wO1ICrfPoGXG-8COVtb5VadLAJlTyzG7Xxbx0s2wGtuHANMQev8j_ZhxTDcasq5MSXVYpZwQ0zHNpWIFfvb4ltEa8WpCKCj0m9CAcnc7ThWGwVdLfvxyC-AGaybIZ0XSbc79jCcDABjj7oUy1xXOUsA63nMExEdZjOFPo4TxOPbUTGtjbxpKqEn5ol03Zvgo1EEY5Qh2E3AK7VUqz_t8tYh1753cxuVqpptdelGcFSTqu67E5bHW9TjshMTdzOys6-XOTJXA Oct 30 04:59:29 volumio volumio[20954]: info: Spotify credentials grant success - running version from March 24, 2019 Oct 30 04:59:29 volumio go-librespot[21145]: time="2025-10-30T04:59:29Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 30 04:59:29 volumio volumio[20954]: error: MPD error: The expression evaluated to a falsy value: Oct 30 04:59:29 volumio volumio[20954]: assert.ok(self.idling) Oct 30 04:59:29 volumio volumio[20954]: error: The expression evaluated to a falsy value: Oct 30 04:59:29 volumio volumio[20954]: assert.ok(self.idling) Oct 30 04:59:29 volumio volumio[20954]: info: MPD running with PID21109 Oct 30 04:59:29 volumio volumio[20954]: ,establishing connection Oct 30 04:59:29 volumio volumio[20954]: error: updateQueue error: null Oct 30 04:59:29 volumio volumio[20954]: error: updateQueue error: null Oct 30 04:59:29 volumio go-librespot[21145]: time="2025-10-30T04:59:29Z" level=debug msg="completed keyexchange" Oct 30 04:59:29 volumio go-librespot[21145]: time="2025-10-30T04:59:29Z" level=debug msg="completed challenge" Oct 30 04:59:29 volumio go-librespot[21145]: time="2025-10-30T04:59: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 30 04:59:29 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 30 04:59:29 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 30 04:59:29 volumio volumio[20954]: 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 30 04:59:29 volumio volumio[20954]: info: Spotify Successfully logged in Oct 30 04:59:29 volumio volumio[20954]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 30 04:59:29 volumio volumio[20954]: info: [1761800369386] CoreMusicLibrary::Adding element Spotify Oct 30 04:59:29 volumio volumio[20954]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 30 04:59:29 volumio volumio[20954]: Cannot find translation for source Spotify Oct 30 04:59:29 volumio volumio[20954]: info: [yt-cast-receiver] DIAL server listening on port 8098 Oct 30 04:59:29 volumio volumio[20954]: info: CoreCommandRouter::volumioRetrievevolume Oct 30 04:59:29 volumio volumio[20954]: info: VolumeController:: Volume=33 Mute =false Oct 30 04:59:29 volumio volumio[20954]: info: CoreCommandRouter::volumioGetState Oct 30 04:59:29 volumio volumio[20954]: info: CorePlayQueue::getTrack 0 Oct 30 04:59:29 volumio volumio[20954]: info: CoreStateMachine::pushState Oct 30 04:59:29 volumio volumio[20954]: info: CorePlayQueue::getTrack 0 Oct 30 04:59:29 volumio volumio[20954]: info: CoreCommandRouter::volumioPushState Oct 30 04:59:29 volumio volumio[20954]: info: Completed starting Core Plugins Oct 30 04:59:29 volumio volumio[20954]: info: ------------------------------------------- Oct 30 04:59:29 volumio volumio[20954]: info: ----- MyVolumio plugins startup ---- Oct 30 04:59:29 volumio volumio[20954]: info: ------------------------------------------- Oct 30 04:59:29 volumio volumio[20954]: info: [MyVolumio PluginManager] Fetching plans data.... Oct 30 04:59:30 volumio volumio-remote-updater[874]: [2025-10-30 04:59:30] [connect] Successful connection Oct 30 04:59:30 volumio volumio-remote-updater[874]: [2025-10-30 04:59:30] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1761800370 101 Oct 30 04:59:30 volumio volumio[20954]: 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 30 04:59:31 volumio volumio[20954]: info: Cannot mount NAS NAS at system boot, trial number 2 ,retrying in 5 seconds Oct 30 04:59:32 volumio volumio[20954]: info: go-librespot daemon successfully initialized Oct 30 04:59:32 volumio sudo[21186]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Oct 30 04:59:32 volumio sudo[21186]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 30 04:59:32 volumio sudo[21188]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Oct 30 04:59:32 volumio sudo[21188]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 30 04:59:32 volumio systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Oct 30 04:59:32 volumio systemd[1]: mpd_monitor.service: Deactivated successfully. Oct 30 04:59:32 volumio systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Oct 30 04:59:32 volumio systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Oct 30 04:59:32 volumio mpd_monitor.sh[21191]: MPD Monitor Service: Starting MPD Monitor Service Oct 30 04:59:32 volumio sudo[21186]: pam_unix(sudo:session): session closed for user root Oct 30 04:59:32 volumio sudo[21188]: pam_unix(sudo:session): session closed for user root Oct 30 04:59:32 volumio volumio[20954]: info: Successfully started MPD Monitor Oct 30 04:59:32 volumio volumio[20954]: info: Successfully started MPD Monitor Oct 30 04:59:32 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 97. Oct 30 04:59:32 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 30 04:59:32 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 30 04:59:32 volumio go-librespot[21195]: go-librespot daemon starting... Oct 30 04:59:32 volumio go-librespot[21196]: time="2025-10-30T04:59:32Z" level=info msg="running go-librespot 0.4.0" Oct 30 04:59:32 volumio go-librespot[21196]: time="2025-10-30T04:59:32Z" level=debug msg="app state loaded" Oct 30 04:59:32 volumio go-librespot[21196]: time="2025-10-30T04:59:32Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 30 04:59:32 volumio go-librespot[21196]: time="2025-10-30T04:59: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-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Oct 30 04:59:32 volumio go-librespot[21196]: time="2025-10-30T04:59:32Z" 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 30 04:59:32 volumio go-librespot[21196]: time="2025-10-30T04:59:32Z" 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 30 04:59:32 volumio go-librespot[21196]: time="2025-10-30T04:59:32Z" level=info msg="zeroconf server listening on port 44801" Oct 30 04:59:32 volumio go-librespot[21196]: time="2025-10-30T04:59:32Z" level=debug msg="obtained new client token: AADu+6+/i57NzBBGnxXg4HELVMsNhN5WdrHKmoSyvgbO3fb/ev0mlWunYB4g1MGQ26DhZrfp2dK6kCajAPR6UGjXno/EekquCaH1Li5PvDPD3iSg/H7AuK3dEtvrnGUfP+2RJjG5VOn/XivLvmM6PqNqXMCn4v8COeGvNiPiKe+iyz1ndSfwggOOxwSLFVpf4Hhlx8KVpVLJ6j+3Wyb+11KH3ulyaVtEM8SPaoMAcG31nhqsG0CFpyA=" Oct 30 04:59:32 volumio go-librespot[21196]: time="2025-10-30T04:59:32Z" 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 30 04:59:32 volumio go-librespot[21196]: time="2025-10-30T04:59:32Z" level=debug msg="connected to ap-gew1.spotify.com:443" Oct 30 04:59:32 volumio go-librespot[21196]: time="2025-10-30T04:59:32Z" level=debug msg="completed keyexchange" Oct 30 04:59:32 volumio go-librespot[21196]: time="2025-10-30T04:59:32Z" level=debug msg="completed challenge" Oct 30 04:59:32 volumio go-librespot[21196]: time="2025-10-30T04:59: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 30 04:59:32 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 30 04:59:32 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 30 04:59:34 volumio volumio[20954]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Oct 30 04:59:35 volumio volumio[20954]: info: Initializing connection to go-librespot Websocket Oct 30 04:59:35 volumio volumio[20954]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 30 04:59:36 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 98. Oct 30 04:59:36 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 30 04:59:36 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 30 04:59:36 volumio go-librespot[21203]: go-librespot daemon starting... Oct 30 04:59:36 volumio go-librespot[21204]: time="2025-10-30T04:59:36Z" level=info msg="running go-librespot 0.4.0" Oct 30 04:59:36 volumio go-librespot[21204]: time="2025-10-30T04:59:36Z" level=debug msg="app state loaded" Oct 30 04:59:36 volumio go-librespot[21204]: time="2025-10-30T04:59:36Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 30 04:59:36 volumio go-librespot[21204]: time="2025-10-30T04:59:36Z" 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 30 04:59:36 volumio go-librespot[21204]: time="2025-10-30T04:59:36Z" 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 30 04:59:36 volumio go-librespot[21204]: time="2025-10-30T04:59:36Z" 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 30 04:59:36 volumio go-librespot[21204]: time="2025-10-30T04:59:36Z" level=info msg="zeroconf server listening on port 33263" Oct 30 04:59:36 volumio go-librespot[21204]: time="2025-10-30T04:59:36Z" level=debug msg="obtained new client token: AAAyQ4hVMTw/KBbKkYFC4TYr7DwGtRTCpjEqJSV7SJGveP1rOBiaW67kNxjcg4lgD5rivn1/pxkOddcKfMPofK5G71uR7Nhi87X34FdrJE4UaP1c3p/IHWh57RDOFgt7zLOgfOAW2Y6HR9Qoqxt+JqfLIPPlEvhWKdTlXC5kVR+F+qgKTTaBJgqkwpzrNyECFL9kB2l6v3FJadb2aawob7DLDkMHZh6Nu12eFrSDQOg9NDTbggwc" Oct 30 04:59:36 volumio go-librespot[21204]: time="2025-10-30T04:59:36Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 30 04:59:36 volumio go-librespot[21204]: time="2025-10-30T04:59:36Z" level=debug msg="completed keyexchange" Oct 30 04:59:36 volumio go-librespot[21204]: time="2025-10-30T04:59:36Z" level=debug msg="completed challenge" Oct 30 04:59:36 volumio go-librespot[21204]: time="2025-10-30T04:59: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 30 04:59:36 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 30 04:59:36 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 30 04:59:36 volumio volumio[20954]: info: Cannot mount NAS NAS at system boot, trial number 3 ,retrying in 5 seconds Oct 30 04:59:36 volumio sudo[21227]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 30 04:59:36 volumio sudo[21227]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 30 04:59:36 volumio sudo[21229]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 30 04:59:36 volumio sudo[21229]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 30 04:59:36 volumio sudo[21227]: pam_unix(sudo:session): session closed for user root Oct 30 04:59:36 volumio sudo[21229]: pam_unix(sudo:session): session closed for user root Oct 30 04:59:36 volumio sudo[21233]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Oct 30 04:59:36 volumio sudo[21233]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 30 04:59:36 volumio sudo[21233]: pam_unix(sudo:session): session closed for user root Oct 30 04:59:36 volumio volumio[20954]: info: Upmpdcli Daemon Started Oct 30 04:59:38 volumio volumio[20954]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Oct 30 04:59:38 volumio volumio[20954]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Oct 30 04:59:38 volumio volumio[20954]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Oct 30 04:59:38 volumio volumio[20954]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Oct 30 04:59:38 volumio volumio[20954]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Oct 30 04:59:38 volumio volumio[20954]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Oct 30 04:59:38 volumio volumio[20954]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Oct 30 04:59:38 volumio volumio[20954]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Oct 30 04:59:38 volumio volumio[20954]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Oct 30 04:59:38 volumio volumio[20954]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Oct 30 04:59:38 volumio volumio[20954]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Oct 30 04:59:38 volumio volumio[20954]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Oct 30 04:59:38 volumio volumio[20954]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Oct 30 04:59:38 volumio volumio[20954]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Oct 30 04:59:38 volumio volumio[20954]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Oct 30 04:59:38 volumio volumio[20954]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Oct 30 04:59:38 volumio volumio[20954]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Oct 30 04:59:38 volumio volumio[20954]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Oct 30 04:59:38 volumio volumio[20954]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Oct 30 04:59:38 volumio volumio[20954]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Oct 30 04:59:38 volumio volumio[20954]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Oct 30 04:59:38 volumio volumio[20954]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Oct 30 04:59:38 volumio volumio[20954]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Oct 30 04:59:38 volumio volumio[20954]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Oct 30 04:59:38 volumio volumio[20954]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Oct 30 04:59:38 volumio volumio[20954]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Oct 30 04:59:38 volumio volumio[20954]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Oct 30 04:59:38 volumio volumio[20954]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Oct 30 04:59:38 volumio volumio[20954]: info: Adding plugin bluetooth to MyMusic Plugins Oct 30 04:59:38 volumio volumio[20954]: info: Adding plugin multiroom to MyMusic Plugins Oct 30 04:59:38 volumio volumio[20954]: info: Adding plugin metavolumio to MyMusic Plugins Oct 30 04:59:38 volumio volumio[20954]: info: Adding plugin cd_controller to MyMusic Plugins Oct 30 04:59:38 volumio volumio[20954]: info: Adding plugin qobuzconnect to MyMusic Plugins Oct 30 04:59:38 volumio volumio[20954]: info: Adding plugin smart_inputs to MyMusic Plugins Oct 30 04:59:38 volumio volumio[20954]: info: Adding plugin tidalconnect to MyMusic Plugins Oct 30 04:59:38 volumio volumio[20954]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Oct 30 04:59:38 volumio volumio[20954]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Oct 30 04:59:38 volumio volumio[20954]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Oct 30 04:59:38 volumio volumio[20954]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 30 04:59:38 volumio volumio[20954]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 30 04:59:38 volumio volumio[20954]: info: Starting MyVolumio Remote Streaming Endpoints Oct 30 04:59:38 volumio volumio[20954]: info: MyVolumio login type: Token Oct 30 04:59:38 volumio volumio[20954]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Oct 30 04:59:38 volumio volumio[20954]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Oct 30 04:59:38 volumio volumio[20954]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Oct 30 04:59:38 volumio volumio[20954]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Oct 30 04:59:38 volumio volumio[20954]: info: Streaming services startup Oct 30 04:59:38 volumio volumio[20954]: info: Starting Streaming Daemon Oct 30 04:59:38 volumio sudo[21236]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Oct 30 04:59:38 volumio sudo[21236]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 30 04:59:38 volumio volumio[20954]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Oct 30 04:59:38 volumio sudo[21236]: pam_unix(sudo:session): session closed for user root Oct 30 04:59:38 volumio volumio[20954]: info: Initializing connection to go-librespot Websocket Oct 30 04:59:38 volumio volumio[20954]: error: Cannot start Volumio Streaming Daemon Oct 30 04:59:38 volumio volumio[20954]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Oct 30 04:59:38 volumio volumio[20954]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Oct 30 04:59:38 volumio volumio[20954]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 30 04:59:38 volumio kernel: nfs: server 192.168.1.3 not responding, timed out Oct 30 04:59:38 volumio volumio[20954]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Oct 30 04:59:39 volumio volumio[20954]: info: MyVolumio token set successfully Oct 30 04:59:39 volumio volumio[20954]: info: MYVOLUMIO: Adding device Oct 30 04:59:39 volumio volumio[20954]: info: MYVOLUMIO: Evaluating Server Oct 30 04:59:39 volumio volumio[20954]: info: MyVolumio status changed Oct 30 04:59:39 volumio volumio[20954]: info: Streaming services startup Oct 30 04:59:39 volumio volumio[20954]: info: Starting Streaming Daemon Oct 30 04:59:39 volumio volumio[20954]: info: Removing browser output: myVolumio user plan is not superstar Oct 30 04:59:39 volumio volumio[20954]: info: Removing audio output: Oct 30 04:59:39 volumio volumio[20954]: info: Stoppping Tunnel 1 Oct 30 04:59:39 volumio sudo[21245]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Oct 30 04:59:39 volumio sudo[21245]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 30 04:59:39 volumio sudo[21247]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service Oct 30 04:59:39 volumio sudo[21245]: pam_unix(sudo:session): session closed for user root Oct 30 04:59:39 volumio sudo[21247]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 30 04:59:39 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 30 04:59:39 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 30 04:59:39 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 99. Oct 30 04:59:39 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 30 04:59:39 volumio volumio[20954]: error: Cannot start Volumio Streaming Daemon Oct 30 04:59:39 volumio volumio[20954]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Oct 30 04:59:39 volumio volumio[20954]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Oct 30 04:59:39 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 30 04:59:39 volumio go-librespot[21257]: go-librespot daemon starting... Oct 30 04:59:39 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 30 04:59:39 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 30 04:59:39 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 30 04:59:39 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 30 04:59:39 volumio sudo[21247]: pam_unix(sudo:session): session closed for user root Oct 30 04:59:39 volumio go-librespot[21266]: time="2025-10-30T04:59:39Z" level=info msg="running go-librespot 0.4.0" Oct 30 04:59:39 volumio volumio[20954]: info: Remote SSH Stopped Oct 30 04:59:39 volumio go-librespot[21266]: time="2025-10-30T04:59:39Z" level=debug msg="app state loaded" Oct 30 04:59:39 volumio go-librespot[21266]: time="2025-10-30T04:59:39Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 30 04:59:39 volumio go-librespot[21266]: time="2025-10-30T04:59: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-gew4.spotify.com:80]" Oct 30 04:59:39 volumio go-librespot[21266]: time="2025-10-30T04:59:39Z" 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 30 04:59:39 volumio go-librespot[21266]: time="2025-10-30T04:59:39Z" 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 30 04:59:39 volumio go-librespot[21266]: time="2025-10-30T04:59:39Z" level=info msg="zeroconf server listening on port 32981" Oct 30 04:59:39 volumio go-librespot[21266]: time="2025-10-30T04:59:39Z" level=debug msg="obtained new client token: AABK9g2NMWrA1a7cFcCiVKYo85xtxZlmDsIbl8qX9gG7B9o1z4qf9r/IsAshZXJRQMN9alKJLUUXV3JVJGNssmtLLWLsRYtURQwMIjYdLmo67JIxgR0hWSGJEXZwIm/2hiRWHplzEmwDu1s/walSkyUqsYODROa1SbVyLain2BUCNfoK/0winVC3H2o6X3VWXoH7unq0EaKzIDvS/+JD5gVm/nO9RLBhnnTiC5prtBOJO3U8GAKzmQA=" Oct 30 04:59:39 volumio go-librespot[21266]: time="2025-10-30T04:59:39Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 30 04:59:39 volumio go-librespot[21266]: time="2025-10-30T04:59:39Z" level=debug msg="completed keyexchange" Oct 30 04:59:39 volumio go-librespot[21266]: time="2025-10-30T04:59:39Z" level=debug msg="completed challenge" Oct 30 04:59:39 volumio go-librespot[21266]: time="2025-10-30T04:59: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 30 04:59:39 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 30 04:59:39 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 30 04:59:39 volumio volumio[20954]: info: Setting Geolocation for MyVolumio to eu3 Oct 30 04:59:39 volumio volumio[20954]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 30 04:59:39 volumio volumio[20954]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 30 04:59:39 volumio volumio[20954]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 30 04:59:40 volumio volumio[20954]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Oct 30 04:59:40 volumio volumio[20954]: info: Updating MyVolumio device info Oct 30 04:59:40 volumio volumio[20954]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 30 04:59:40 volumio volumio[20954]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 30 04:59:40 volumio volumio[20954]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 30 04:59:40 volumio volumio[20954]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Oct 30 04:59:41 volumio volumio[20954]: info: Initializing connection to go-librespot Websocket Oct 30 04:59:41 volumio volumio[20954]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 30 04:59:41 volumio volumio[20954]: info: Cannot mount NAS NAS at system boot, trial number 4 ,retrying in 5 seconds Oct 30 04:59:42 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 100. Oct 30 04:59:42 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 30 04:59:42 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 30 04:59:42 volumio go-librespot[21273]: go-librespot daemon starting... Oct 30 04:59:42 volumio go-librespot[21274]: time="2025-10-30T04:59:42Z" level=info msg="running go-librespot 0.4.0" Oct 30 04:59:42 volumio go-librespot[21274]: time="2025-10-30T04:59:42Z" level=debug msg="app state loaded" Oct 30 04:59:42 volumio go-librespot[21274]: time="2025-10-30T04:59:42Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 30 04:59:42 volumio go-librespot[21274]: time="2025-10-30T04:59: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-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Oct 30 04:59:42 volumio go-librespot[21274]: time="2025-10-30T04:59:42Z" 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 30 04:59:42 volumio go-librespot[21274]: time="2025-10-30T04:59:42Z" 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 30 04:59:42 volumio go-librespot[21274]: time="2025-10-30T04:59:42Z" level=info msg="zeroconf server listening on port 45655" Oct 30 04:59:42 volumio go-librespot[21274]: time="2025-10-30T04:59:42Z" level=debug msg="obtained new client token: AACzC4L0sL8TKnn5w8B+Bfjq9EKHkbeJDhG3opHBxgwuKHldx/FLQ2F44o/WB/SwuRP2LZkCC2yTIcNApqzTaP3QO7LmeO1/2iLXqU5BjULRqrdq+8CISg3ZQlQAqj9A8YM6bP6aI647E5kuuymOKP6QOvj+gQ6uzB9LafoU561jLXWMHT/Opwi3R4Wr17wMC+2Ci9m9AxsQTg6vCeLY49AVTfXT8E5a93vWddkibZZ0qIeF52sQ/Wg=" Oct 30 04:59:42 volumio go-librespot[21274]: time="2025-10-30T04:59:42Z" 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 30 04:59:42 volumio go-librespot[21274]: time="2025-10-30T04:59:42Z" level=debug msg="connected to ap-gew1.spotify.com:443" Oct 30 04:59:43 volumio go-librespot[21274]: time="2025-10-30T04:59:43Z" level=debug msg="completed keyexchange" Oct 30 04:59:43 volumio go-librespot[21274]: time="2025-10-30T04:59:43Z" level=debug msg="completed challenge" Oct 30 04:59:43 volumio go-librespot[21274]: time="2025-10-30T04:59: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 30 04:59:43 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 30 04:59:43 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 30 04:59:44 volumio volumio[20954]: info: MYVOLUMIO: Adding device Oct 30 04:59:44 volumio volumio[20954]: info: MYVOLUMIO: Evaluating Server Oct 30 04:59:44 volumio volumio[20954]: info: Initializing connection to go-librespot Websocket Oct 30 04:59:44 volumio volumio[20954]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 30 04:59:44 volumio volumio[20954]: info: Setting Geolocation for MyVolumio to eu3 Oct 30 04:59:44 volumio volumio[20954]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 30 04:59:44 volumio volumio[20954]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 30 04:59:44 volumio volumio[20954]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 30 04:59:44 volumio volumio[20954]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Oct 30 04:59:45 volumio volumio[20954]: info: Updating MyVolumio device info Oct 30 04:59:45 volumio volumio[20954]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 30 04:59:45 volumio volumio[20954]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 30 04:59:45 volumio volumio[20954]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 30 04:59:45 volumio volumio[20954]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Oct 30 04:59:46 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 101. Oct 30 04:59:46 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 30 04:59:46 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 30 04:59:46 volumio go-librespot[21296]: go-librespot daemon starting... Oct 30 04:59:46 volumio go-librespot[21297]: time="2025-10-30T04:59:46Z" level=info msg="running go-librespot 0.4.0" Oct 30 04:59:46 volumio go-librespot[21297]: time="2025-10-30T04:59:46Z" level=debug msg="app state loaded" Oct 30 04:59:46 volumio go-librespot[21297]: time="2025-10-30T04:59:46Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 30 04:59:46 volumio go-librespot[21297]: time="2025-10-30T04:59: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-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Oct 30 04:59:46 volumio go-librespot[21297]: time="2025-10-30T04:59:46Z" 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 30 04:59:46 volumio go-librespot[21297]: time="2025-10-30T04:59:46Z" 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 30 04:59:46 volumio go-librespot[21297]: time="2025-10-30T04:59:46Z" level=info msg="zeroconf server listening on port 46339" Oct 30 04:59:46 volumio go-librespot[21297]: time="2025-10-30T04:59:46Z" level=debug msg="obtained new client token: AACKmtca6RBQrB03QKEosBJBBR9I/zKo8cR7UbM4JfmnYFaphxiVhsp+zJtW7BJ6uoqTlhkPUtoBgRul2kokuig+QA0d6XsCD6vjy2T79vFi7nmQF+kjUFPCaGOzdnDICM2LIWtR6niIZIWwW/x7dBoEk+L4zQm24ssXv1e6oyd/iSsIwt5NYjCDiv2ZINCtAjkLlJPUkCZ+Aa8YaPjZP6SJPP5sxDyAOoLRc1k3xU7v2TvQYuhDyLw=" Oct 30 04:59:46 volumio go-librespot[21297]: time="2025-10-30T04:59:46Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 30 04:59:46 volumio go-librespot[21297]: time="2025-10-30T04:59:46Z" level=debug msg="completed keyexchange" Oct 30 04:59:46 volumio go-librespot[21297]: time="2025-10-30T04:59:46Z" level=debug msg="completed challenge" Oct 30 04:59:46 volumio go-librespot[21297]: time="2025-10-30T04:59: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 30 04:59:46 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 30 04:59:46 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 30 04:59:46 volumio volumio[20954]: info: Cannot mount NAS at system boot, trial number 4 ,stopping Oct 30 04:59:47 volumio volumio[20954]: info: Initializing connection to go-librespot Websocket Oct 30 04:59:47 volumio volumio[20954]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 30 04:59:49 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 102. Oct 30 04:59:49 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 30 04:59:49 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 30 04:59:49 volumio go-librespot[21318]: go-librespot daemon starting... Oct 30 04:59:49 volumio go-librespot[21319]: time="2025-10-30T04:59:49Z" level=info msg="running go-librespot 0.4.0" Oct 30 04:59:49 volumio go-librespot[21319]: time="2025-10-30T04:59:49Z" level=debug msg="app state loaded" Oct 30 04:59:49 volumio go-librespot[21319]: time="2025-10-30T04:59:49Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 30 04:59:49 volumio go-librespot[21319]: time="2025-10-30T04:59:49Z" 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 30 04:59:49 volumio go-librespot[21319]: time="2025-10-30T04:59:49Z" 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 30 04:59:49 volumio go-librespot[21319]: time="2025-10-30T04:59:49Z" 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 30 04:59:49 volumio go-librespot[21319]: time="2025-10-30T04:59:49Z" level=info msg="zeroconf server listening on port 34137" Oct 30 04:59:49 volumio go-librespot[21319]: time="2025-10-30T04:59:49Z" level=debug msg="obtained new client token: AACfpFeSsIw/+5Mhr7XPj+mlXDfJkLLLfZJvOdByZVjiL3JO5TUcBLjreMQ/nLjdvWKQ5YIChGlPrEh/ePAbBB4UMlcL/F2dJ2UKgITa1gQfLzsWTCkXMSph411wqsikSmKfpGKBpwKaYavB794Gg4qH3N89h0TvspOTkrqKIgnN7irPXAP+SjHuY+vm9qbKGNVwQ4IGkdKNGp/g1fJwalgziBZNbwiC8Gxk6AIihSae9/poCjstVlw=" Oct 30 04:59:49 volumio go-librespot[21319]: time="2025-10-30T04:59:49Z" 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 30 04:59:50 volumio go-librespot[21319]: time="2025-10-30T04:59:50Z" level=debug msg="connected to ap-gew1.spotify.com:443" Oct 30 04:59:50 volumio go-librespot[21319]: time="2025-10-30T04:59:50Z" level=debug msg="completed keyexchange" Oct 30 04:59:50 volumio go-librespot[21319]: time="2025-10-30T04:59:50Z" level=debug msg="completed challenge" Oct 30 04:59:50 volumio go-librespot[21319]: time="2025-10-30T04:59: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 30 04:59:50 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 30 04:59:50 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 30 04:59:50 volumio volumio[20954]: info: Initializing connection to go-librespot Websocket Oct 30 04:59:50 volumio volumio[20954]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 30 04:59:53 volumio volumio[20954]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Oct 30 04:59:53 volumio volumio[20954]: 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 30 04:59:53 volumio volumio[20954]: info: CoreCommandRouter::volumioGetState Oct 30 04:59:53 volumio volumio[20954]: info: CorePlayQueue::getTrack 0 Oct 30 04:59:53 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 103. Oct 30 04:59:53 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 30 04:59:53 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 30 04:59:53 volumio go-librespot[21329]: go-librespot daemon starting... Oct 30 04:59:53 volumio go-librespot[21330]: time="2025-10-30T04:59:53Z" level=info msg="running go-librespot 0.4.0" Oct 30 04:59:53 volumio go-librespot[21330]: time="2025-10-30T04:59:53Z" level=debug msg="app state loaded" Oct 30 04:59:53 volumio go-librespot[21330]: time="2025-10-30T04:59:53Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 30 04:59:53 volumio go-librespot[21330]: time="2025-10-30T04:59:53Z" 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 30 04:59:53 volumio go-librespot[21330]: time="2025-10-30T04:59:53Z" 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 30 04:59:53 volumio go-librespot[21330]: time="2025-10-30T04:59:53Z" 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 30 04:59:53 volumio go-librespot[21330]: time="2025-10-30T04:59:53Z" level=info msg="zeroconf server listening on port 39127" Oct 30 04:59:53 volumio volumio[20954]: info: Initializing connection to go-librespot Websocket Oct 30 04:59:53 volumio go-librespot[21330]: time="2025-10-30T04:59:53Z" level=debug msg="obtained new client token: AACb3CcrSYwc5fj/Ni5b8602alFXvn5OQ6OfUtrGH0mRH0L1gSsYTlvEmKh9lSWsbNaXfS6/wL6tMlZcJcI/CfooPB3e5VQj9rDNLyjdKh5o9zUAqvF+VD13lDhKUBhg3Stqtjgu7ItyH5WmVBLmUFRIY9uEH+jFWUkIsPdk4Aon2l33xclbA2jLzzFl8RNlIwXvWPTQpZc4r5sPHPOFddbWJg/fRCPJMvVgncKbeV20s5+Ek8sZM80=" Oct 30 04:59:53 volumio go-librespot[21330]: time="2025-10-30T04:59:53Z" level=debug msg="new websocket client" Oct 30 04:59:53 volumio volumio[20954]: info: Connection to go-librespot Websocket established Oct 30 04:59:53 volumio go-librespot[21330]: time="2025-10-30T04:59:53Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 30 04:59:53 volumio go-librespot[21330]: time="2025-10-30T04:59:53Z" level=debug msg="completed keyexchange" Oct 30 04:59:53 volumio go-librespot[21330]: time="2025-10-30T04:59:53Z" level=debug msg="completed challenge" Oct 30 04:59:53 volumio go-librespot[21330]: time="2025-10-30T04:59: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 30 04:59:53 volumio volumio[20954]: info: Connection to go-librespot Websocket closed Oct 30 04:59:53 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 30 04:59:53 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 30 04:59:54 volumio kernel: nfs: server 192.168.1.3 not responding, timed out Oct 30 04:59:56 volumio volumio[20954]: info: Getting Spotify volume Oct 30 04:59:56 volumio volumio[20954]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 30 04:59:56 volumio volumio[20954]: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 30 04:59:56 volumio volumio[20954]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Oct 30 04:59:56 volumio volumio[20954]: errno: -111, Oct 30 04:59:56 volumio volumio[20954]: code: 'ECONNREFUSED', Oct 30 04:59:56 volumio volumio[20954]: syscall: 'connect', Oct 30 04:59:56 volumio volumio[20954]: address: '127.0.0.1', Oct 30 04:59:56 volumio volumio[20954]: port: 9879, Oct 30 04:59:56 volumio volumio[20954]: response: undefined Oct 30 04:59:56 volumio volumio[20954]: } Oct 30 04:59:56 volumio volumio[20954]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 30 04:59:56 volumio sudo[21353]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-10-30 04:58' Oct 30 04:59:56 volumio sudo[21353]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 30 04:59:56 volumio sudo[21353]: pam_unix(sudo:session): session closed for user root Oct 30 04:59:56 volumio volumio-remote-updater[874]: [2025-10-30 04:59:56] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Oct 30 04:59:56 volumio volumio-remote-updater[874]: [2025-10-30 04:59:56] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Oct 30 04:59:56 volumio systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Oct 30 04:59:56 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 104. Oct 30 04:59:56 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 30 04:59:56 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 30 04:59:56 volumio go-librespot[21362]: go-librespot daemon starting... Oct 30 04:59:56 volumio systemd[1]: volumio.service: Failed with result 'exit-code'. Oct 30 04:59:56 volumio systemd[1]: volumio.service: Consumed 7.531s CPU time. Oct 30 04:59:56 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Oct 30 04:59:56 volumio go-librespot[21371]: time="2025-10-30T04:59:56Z" level=info msg="running go-librespot 0.4.0" Oct 30 04:59:56 volumio go-librespot[21371]: time="2025-10-30T04:59:56Z" level=debug msg="app state loaded" Oct 30 04:59:56 volumio go-librespot[21371]: time="2025-10-30T04:59:56Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 30 04:59:56 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Oct 30 04:59:56 volumio go-librespot[21371]: time="2025-10-30T04:59: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-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Oct 30 04:59:56 volumio go-librespot[21371]: time="2025-10-30T04:59:56Z" 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 30 04:59:56 volumio go-librespot[21371]: time="2025-10-30T04:59:56Z" 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 30 04:59:56 volumio go-librespot[21371]: time="2025-10-30T04:59:56Z" level=info msg="zeroconf server listening on port 39079" Oct 30 04:59:56 volumio go-librespot[21371]: time="2025-10-30T04:59:56Z" level=debug msg="obtained new client token: AABm2Ib8JNHNpQplKldejEmZpOsAKyGMP44eTmlXXE3q7k3wJqpzKAs+jP4HcvhJKs7FynFYZJYdE+WgzguKC7T+aWOVROTDTdSUkRDQ+r4l/0NXyB0dnS7hdyWrthyopmy0dX9g7nl02q8/Ld8ZbY55/jbPYfXQgjde9TbJGjswDTZb1OGjal+0cxgzK2G+M0z7vM9cIhVmgnno2C3yfDx/YTbQpBrkin/8eQtqbPlS9e2rd/PLCeY=" Oct 30 04:59:56 volumio go-librespot[21371]: time="2025-10-30T04:59:56Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 30 04:59:56 volumio go-librespot[21371]: time="2025-10-30T04:59:56Z" level=debug msg="completed keyexchange" Oct 30 04:59:56 volumio go-librespot[21371]: time="2025-10-30T04:59:56Z" level=debug msg="completed challenge" Oct 30 04:59:56 volumio go-librespot[21371]: time="2025-10-30T04:59:56Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 30 04:59:56 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 30 04:59:56 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 30 04:59:56 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 2746. Oct 30 04:59:57 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Oct 30 04:59:57 volumio systemd[1]: Stopped volumio.service - Volumio Backend Module. Oct 30 04:59:57 volumio systemd[1]: volumio.service: Consumed 7.531s CPU time. Oct 30 04:59:57 volumio systemd[1]: Started volumio.service - Volumio Backend Module. Oct 30 04:59:57 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Oct 30 04:59:57 volumio volumio[21385]: info: ------------------------------------------- Oct 30 04:59:57 volumio volumio[21385]: info: ----- Volumio3 ---- Oct 30 04:59:57 volumio volumio[21385]: info: ------------------------------------------- Oct 30 04:59:57 volumio volumio[21385]: info: ----- System startup ---- Oct 30 04:59:57 volumio volumio[21385]: info: ------------------------------------------- Oct 30 04:59:57 volumio volumio[21385]: info: MYVOLUMIO Environment detected Oct 30 04:59:57 volumio volumio[21385]: info: Plugin folders cleanup Oct 30 04:59:57 volumio volumio[21385]: info: Scanning into folder /volumio/app/plugins/ Oct 30 04:59:57 volumio volumio[21385]: info: Scanning category audio_interface Oct 30 04:59:57 volumio volumio[21385]: info: Scanning category miscellanea Oct 30 04:59:57 volumio volumio[21385]: info: Scanning category music_service Oct 30 04:59:57 volumio volumio[21385]: info: Scanning category plugins.json Oct 30 04:59:57 volumio volumio[21385]: info: Scanning category system_controller Oct 30 04:59:57 volumio volumio[21385]: info: Scanning category user_interface Oct 30 04:59:57 volumio volumio[21385]: info: Scanning into folder /data/plugins/ Oct 30 04:59:57 volumio volumio[21385]: info: Scanning category music_service Oct 30 04:59:57 volumio volumio[21385]: info: Scanning category user_interface Oct 30 04:59:57 volumio volumio[21385]: info: Plugin folders cleanup completed Oct 30 04:59:57 volumio volumio[21385]: info: ------------------------------------------- Oct 30 04:59:57 volumio volumio[21385]: info: ----- Core plugins startup ---- Oct 30 04:59:57 volumio volumio[21385]: info: ------------------------------------------- Oct 30 04:59:57 volumio volumio[21385]: info: Loading plugins from folder /volumio/app/plugins/ Oct 30 04:59:57 volumio volumio[21385]: info: Adding plugin upnp to MyMusic Plugins Oct 30 04:59:57 volumio volumio[21385]: info: Adding plugin airplay_emulation to MyMusic Plugins Oct 30 04:59:57 volumio volumio[21385]: info: Adding plugin upnp_browser to MyMusic Plugins Oct 30 04:59:57 volumio volumio[21385]: info: Loading plugins from folder /data/plugins/ Oct 30 04:59:57 volumio volumio[21385]: info: Loading plugin "system"... Oct 30 04:59:57 volumio volumio[21385]: info: Loading plugin "appearance"... Oct 30 04:59:57 volumio volumio[21385]: info: Loading plugin "network"... Oct 30 04:59:57 volumio volumio[21385]: info: Refreshing Cached IP Addresses Oct 30 04:59:57 volumio sudo[21413]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 30 04:59:57 volumio sudo[21413]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 30 04:59:57 volumio sudo[21413]: pam_unix(sudo:session): session closed for user root Oct 30 04:59:57 volumio volumio[21385]: info: Loading plugin "services"... Oct 30 04:59:57 volumio volumio[21385]: info: Loading plugin "alsa_controller"... Oct 30 04:59:57 volumio sudo[21415]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 30 04:59:57 volumio sudo[21415]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 30 04:59:57 volumio sudo[21415]: pam_unix(sudo:session): session closed for user root Oct 30 04:59:57 volumio volumio[21385]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 30 04:59:57 volumio volumio[21385]: info: Loading plugin "wizard"... Oct 30 04:59:57 volumio volumio[21385]: info: Loading plugin "networkfs"... Oct 30 04:59:57 volumio volumio[21385]: info: Cannot mount NAS NAS at system boot, trial number 1 ,retrying in 5 seconds Oct 30 04:59:57 volumio volumio[21385]: info: Starting Udev Watcher for removable devices Oct 30 04:59:57 volumio volumio[21385]: info: Ignoring mount for partition: boot Oct 30 04:59:57 volumio volumio[21385]: info: Ignoring mount for partition: volumio Oct 30 04:59:57 volumio volumio[21385]: info: Ignoring mount for partition: volumio_data Oct 30 04:59:57 volumio volumio[21385]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 30 04:59:57 volumio volumio[21385]: info: Loading plugin "volumio_command_line_client"... Oct 30 04:59:57 volumio volumio[21385]: info: Loading plugin "upnp"... Oct 30 04:59:57 volumio volumio[21385]: info: [1761800397774] Starting Upmpd Daemon Oct 30 04:59:57 volumio volumio[21385]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 30 04:59:57 volumio volumio[21385]: info: Loading plugin "my_music"... Oct 30 04:59:57 volumio volumio[21385]: info: Loading plugin "mpd"... Oct 30 04:59:57 volumio volumio[21385]: info: Loading plugin "upnp_browser"... Oct 30 04:59:58 volumio volumio[21385]: info: Loading plugin "alarm-clock"... Oct 30 04:59:58 volumio volumio[21385]: info: Loading plugin "airplay_emulation"... Oct 30 04:59:58 volumio volumio[21385]: info: Starting Shairport Sync Oct 30 04:59:58 volumio volumio[21385]: info: Loading plugin "last_100"... Oct 30 04:59:58 volumio volumio[21385]: info: Loading plugin "webradio"... Oct 30 04:59:58 volumio volumio[21385]: info: Loading plugin "i2s_dacs"... Oct 30 04:59:58 volumio volumio[21385]: info: I2S DAC not set, start Auto-detection Oct 30 04:59:58 volumio volumio[21385]: info: Loading plugin "volumiodiscovery"... Oct 30 04:59:58 volumio volumio[21385]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Oct 30 04:59:58 volumio volumio[21385]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 30 04:59:58 volumio volumio[21385]: *** WARNING *** For more information see Oct 30 04:59:58 volumio volumio[21385]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Oct 30 04:59:58 volumio volumio[21385]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 30 04:59:58 volumio volumio[21385]: *** WARNING *** For more information see Oct 30 04:59:58 volumio node[21385]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Oct 30 04:59:58 volumio node[21385]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 30 04:59:58 volumio node[21385]: *** WARNING *** For more information see Oct 30 04:59:58 volumio node[21385]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Oct 30 04:59:58 volumio node[21385]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 30 04:59:58 volumio node[21385]: *** WARNING *** For more information see Oct 30 04:59:58 volumio volumio[21385]: info: Applying required configuration parameters for plugin volumiodiscovery Oct 30 04:59:58 volumio volumio[21385]: info: Discovery: Started advertising with name: Volumio Oct 30 04:59:58 volumio volumio[21385]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 30 04:59:58 volumio volumio[21385]: info: Loading plugin "spop"... Oct 30 04:59:58 volumio volumio[21385]: info: Loading plugin "ytcr"... Oct 30 04:59:59 volumio volumio[21385]: info: Loading plugin "outputs"... Oct 30 04:59:59 volumio volumio[21385]: info: Loading plugin "albumart"... Oct 30 04:59:59 volumio volumio[21385]: info: Plugin example_plugin is not enabled Oct 30 04:59:59 volumio volumio[21385]: info: Loading plugin "inputs"... Oct 30 04:59:59 volumio volumio[21385]: info: Loading plugin "updater_comm"... Oct 30 04:59:59 volumio volumio[21385]: info: Plugin mpdemulation is not enabled Oct 30 04:59:59 volumio volumio[21385]: info: Loading plugin "rest_api"... Oct 30 04:59:59 volumio volumio[21385]: info: Loading plugin "websocket"... Oct 30 04:59:59 volumio volumio[21385]: info: Starting Socket.io Server version 1.7.4 Oct 30 04:59:59 volumio volumio[21385]: info: Loading plugin "Systeminfo"... Oct 30 04:59:59 volumio volumio[21385]: info: Loading i18n strings for locale en Oct 30 04:59:59 volumio volumio[21385]: Updating browse sources language Oct 30 04:59:59 volumio volumio[21385]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 30 04:59:59 volumio volumio[21445]: Forking 3 albumart workers Oct 30 04:59:59 volumio volumio[21385]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 30 04:59:59 volumio volumio[21385]: info: CoreCommandRouter::initPlayerControls Oct 30 04:59:59 volumio volumio[21385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 04:59:59 volumio volumio[21385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 04:59:59 volumio volumio[21385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 04:59:59 volumio volumio[21385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 04:59:59 volumio volumio[21385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 04:59:59 volumio volumio[21385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 04:59:59 volumio volumio[21385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 04:59:59 volumio volumio[21385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 04:59:59 volumio volumio[21385]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 30 04:59:59 volumio volumio[21385]: Express server listening on port 3000 Oct 30 04:59:59 volumio volumio[21385]: [Metrics] WebUI: 1s 934.31ms Oct 30 04:59:59 volumio volumio[21385]: info: CoreStateMachine::resetVolumioState Oct 30 04:59:59 volumio volumio[21385]: info: CoreStateMachine::getcurrentVolume Oct 30 04:59:59 volumio volumio[21385]: info: CoreCommandRouter::volumioRetrievevolume Oct 30 04:59:59 volumio volumio[21385]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 30 04:59:59 volumio volumio[21385]: info: Cannot read play queue from file Oct 30 04:59:59 volumio volumio[21385]: info: Volumio Network Manager: Network status updated: 1 Oct 30 04:59:59 volumio volumio[21385]: info: VolumeController:: Volume=33 Mute =false Oct 30 04:59:59 volumio volumio[21385]: info: CoreStateMachine::pushState Oct 30 04:59:59 volumio volumio[21385]: info: CorePlayQueue::getTrack 0 Oct 30 04:59:59 volumio volumio[21385]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 30 04:59:59 volumio volumio[21385]: info: CoreCommandRouter::volumioPushState Oct 30 04:59:59 volumio volumio[21385]: info: CoreStateMachine::updateTrackBlock Oct 30 04:59:59 volumio volumio[21385]: info: CorePlayQueue::getTrackBlock Oct 30 04:59:59 volumio volumio[21385]: info: CoreCommandRouter::volumioRetrievevolume Oct 30 04:59:59 volumio volumio[21385]: info: CoreStateMachine::setRepeat null single undefined Oct 30 04:59:59 volumio volumio[21385]: info: CoreStateMachine::pushState Oct 30 04:59:59 volumio volumio[21385]: info: CorePlayQueue::getTrack 0 Oct 30 04:59:59 volumio volumio[21385]: info: CoreCommandRouter::volumioPushState Oct 30 04:59:59 volumio volumio[21385]: info: CoreStateMachine::setRandom null Oct 30 04:59:59 volumio volumio[21385]: info: CoreStateMachine::pushState Oct 30 04:59:59 volumio volumio[21385]: info: CorePlayQueue::getTrack 0 Oct 30 04:59:59 volumio volumio[21385]: info: CoreCommandRouter::volumioPushState Oct 30 04:59:59 volumio volumio[21385]: info: Setting Device type: Raspberry PI Oct 30 04:59:59 volumio volumio[21385]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Oct 30 04:59:59 volumio volumio[21385]: info: USB Boot Capable - System SBC Revision found in cpuinfo: b04170 Oct 30 04:59:59 volumio volumio[21385]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Oct 30 04:59:59 volumio volumio[21385]: info: VolumeController:: Volume=33 Mute =false Oct 30 04:59:59 volumio volumio[21385]: info: CoreStateMachine::pushState Oct 30 04:59:59 volumio volumio[21385]: info: CorePlayQueue::getTrack 0 Oct 30 04:59:59 volumio volumio[21385]: info: CoreCommandRouter::volumioPushState Oct 30 04:59:59 volumio volumio[21385]: info: Completed loading Core Plugins Oct 30 04:59:59 volumio volumio[21385]: info: Preparing to generate the ALSA configuration file Oct 30 04:59:59 volumio volumio[21385]: info: Discovery: adding 70853f74-8210-4683-a3fa-e1217517bd40 Oct 30 04:59:59 volumio volumio[21385]: info: Discovery: Found device Volumio Oct 30 04:59:59 volumio volumio[21385]: info: CoreCommandRouter::volumioGetState Oct 30 04:59:59 volumio volumio[21385]: info: CorePlayQueue::getTrack 0 Oct 30 04:59:59 volumio volumio[21385]: info: Discovery: this is already registered, 70853f74-8210-4683-a3fa-e1217517bd40 Oct 30 04:59:59 volumio volumio[21385]: info: Discovery: Found device Volumio Oct 30 04:59:59 volumio volumio[21385]: info: CoreCommandRouter::volumioGetState Oct 30 04:59:59 volumio volumio[21385]: info: CorePlayQueue::getTrack 0 Oct 30 04:59:59 volumio volumio[21385]: info: Asound.conf file unchanged, so no further update is needed Oct 30 04:59:59 volumio volumio[21385]: info: Output device has changed, restarting MPD Oct 30 04:59:59 volumio sudo[21502]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 30 04:59:59 volumio sudo[21502]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 30 04:59:59 volumio volumio[21385]: info: Output device has changed, restarting Shairport Sync Oct 30 04:59:59 volumio volumio[21385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 04:59:59 volumio volumio[21385]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 30 04:59:59 volumio sudo[21502]: pam_unix(sudo:session): session closed for user root Oct 30 04:59:59 volumio sudo[21505]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 30 04:59:59 volumio volumio[21385]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 30 04:59:59 volumio volumio[21385]: info: ___________ START PLUGINS ___________ Oct 30 04:59:59 volumio sudo[21505]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 30 04:59:59 volumio volumio[21385]: info: ControllerMpd::onStart: Initializing MPD Oct 30 04:59:59 volumio volumio[21385]: info: Creating MPD Configuration file Oct 30 04:59:59 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Oct 30 04:59:59 volumio volumio[21385]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 30 04:59:59 volumio volumio[21385]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 30 04:59:59 volumio volumio[21385]: info: [1761800399406] CoreMusicLibrary::Adding element Media Servers Oct 30 04:59:59 volumio volumio[21385]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 30 04:59:59 volumio volumio[21385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 04:59:59 volumio volumio[21385]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 30 04:59:59 volumio sudo[21514]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 30 04:59:59 volumio sudo[21514]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 30 04:59:59 volumio sudo[21512]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 30 04:59:59 volumio sudo[21512]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 30 04:59:59 volumio sudo[21512]: pam_unix(sudo:session): session closed for user root Oct 30 04:59:59 volumio systemd[1]: mpd.service: Deactivated successfully. Oct 30 04:59:59 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Oct 30 04:59:59 volumio systemd[1]: mpd.socket: Deactivated successfully. Oct 30 04:59:59 volumio volumio[21385]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 30 04:59:59 volumio volumio[21385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 04:59:59 volumio volumio[21385]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 30 04:59:59 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Oct 30 04:59:59 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Oct 30 04:59:59 volumio volumio[21385]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 30 04:59:59 volumio volumio[21385]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 30 04:59:59 volumio volumio[21385]: info: [1761800399451] CoreMusicLibrary::Adding element Last_100 Oct 30 04:59:59 volumio volumio[21385]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 30 04:59:59 volumio volumio[21385]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 30 04:59:59 volumio volumio[21385]: info: [1761800399452] CoreMusicLibrary::Adding element Webradio Oct 30 04:59:59 volumio volumio[21385]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 30 04:59:59 volumio volumio[21385]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 30 04:59:59 volumio volumio[21385]: info: Initializing BBC Radios Oct 30 04:59:59 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Oct 30 04:59:59 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Oct 30 04:59:59 volumio systemd[1]: mpd.service: Deactivated successfully. Oct 30 04:59:59 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Oct 30 04:59:59 volumio systemd[1]: mpd.socket: Deactivated successfully. Oct 30 04:59:59 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Oct 30 04:59:59 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Oct 30 04:59:59 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Oct 30 04:59:59 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Oct 30 04:59:59 volumio volumio[21385]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 30 04:59:59 volumio volumio[21385]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 30 04:59:59 volumio volumio[21385]: info: Creating Spotify config file Oct 30 04:59:59 volumio volumio[21385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 04:59:59 volumio sudo[21532]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Oct 30 04:59:59 volumio sudo[21532]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Oct 30 04:59:59 volumio sudo[21532]: pam_unix(sudo:session): session closed for user root Oct 30 04:59:59 volumio volumio[21385]: info: Volumio Calling Home Oct 30 04:59:59 volumio volumio[21456]: Starting albumart workers Oct 30 04:59:59 volumio volumio[21385]: info: MPD Permissions set Oct 30 04:59:59 volumio volumio[21385]: info: MPD Permissions set Oct 30 04:59:59 volumio volumio[21457]: Starting albumart workers Oct 30 04:59:59 volumio volumio[21385]: 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 30 04:59:59 volumio volumio[21385]: info: Spotify config file written Oct 30 04:59:59 volumio sudo[21554]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Oct 30 04:59:59 volumio sudo[21554]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 30 04:59:59 volumio volumio[21455]: Starting albumart workers Oct 30 04:59:59 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 30 04:59:59 volumio volumio[21385]: info: Volumio called home Oct 30 04:59:59 volumio volumio[21385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 04:59:59 volumio volumio[21385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 04:59:59 volumio volumio[21385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 04:59:59 volumio volumio[21385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 04:59:59 volumio volumio[21385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 04:59:59 volumio volumio[21385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 04:59:59 volumio volumio[21385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 04:59:59 volumio volumio[21385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 04:59:59 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 30 04:59:59 volumio go-librespot[21556]: go-librespot daemon starting... Oct 30 04:59:59 volumio sudo[21554]: pam_unix(sudo:session): session closed for user root Oct 30 04:59:59 volumio volumio[21385]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 30 04:59:59 volumio volumio[21385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 04:59:59 volumio volumio[21385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 04:59:59 volumio volumio[21385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 04:59:59 volumio volumio[21385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 04:59:59 volumio volumio[21385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 04:59:59 volumio volumio[21385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 04:59:59 volumio volumio[21385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 04:59:59 volumio volumio[21385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 04:59:59 volumio volumio[21385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 04:59:59 volumio volumio[21385]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 30 04:59:59 volumio volumio[21385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 04:59:59 volumio volumio[21385]: info: No need to fix Spotify hosts Oct 30 04:59:59 volumio go-librespot[21562]: time="2025-10-30T04:59:59Z" level=info msg="running go-librespot 0.4.0" Oct 30 04:59:59 volumio go-librespot[21562]: time="2025-10-30T04:59:59Z" level=debug msg="app state loaded" Oct 30 04:59:59 volumio go-librespot[21562]: time="2025-10-30T04:59:59Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 30 05:00:00 volumio mpd[21543]: decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Oct 30 05:00:00 volumio mpd[21543]: output: No 'audio_output' defined in config file Oct 30 05:00:00 volumio mpd[21543]: couldn't open play stream: Unknown error 524 Oct 30 05:00:00 volumio mpd[21543]: sndio_output: Error opening default sndio device Oct 30 05:00:00 volumio mpd[21543]: output: Successfully detected a alsa audio device Oct 30 05:00:00 volumio go-librespot[21562]: time="2025-10-30T05:00: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 30 05:00:00 volumio go-librespot[21562]: time="2025-10-30T05:00: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 30 05:00:00 volumio go-librespot[21562]: time="2025-10-30T05:00: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 30 05:00:00 volumio go-librespot[21562]: time="2025-10-30T05:00:00Z" level=info msg="zeroconf server listening on port 46527" Oct 30 05:00:00 volumio sudo[21514]: pam_unix(sudo:session): session closed for user root Oct 30 05:00:00 volumio systemd[1]: Started mpd.service - Music Player Daemon. Oct 30 05:00:00 volumio mpd[21543]: zeroconf: No global port, disabling zeroconf Oct 30 05:00:00 volumio sudo[21505]: pam_unix(sudo:session): session closed for user root Oct 30 05:00:00 volumio volumio[21385]: info: Starting Shairport Sync Oct 30 05:00:00 volumio volumio[21385]: info: Starting Shairport Sync Oct 30 05:00:00 volumio volumio[21385]: info: Starting Shairport Sync Oct 30 05:00:00 volumio sudo[21591]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 30 05:00:00 volumio sudo[21591]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 30 05:00:00 volumio sudo[21593]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 30 05:00:00 volumio sudo[21593]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 30 05:00:00 volumio go-librespot[21562]: time="2025-10-30T05:00:00Z" level=debug msg="obtained new client token: AACoJt0bL1TMKIt3lAQQwBdaIna5rpGq6mIgUw2SgVfBWiXhsshCNaSdIIxKWcBnSZ273NEWvLiWnfMXkzmvy6iQRb94orM2ZzyMUEx/HRTrAR6qqktDdoHQX3i+HS8uacMH7pmE6tGfOQg5pJW2t9KT3ukpJsvuXhB+Ui1jurHayqH5R+jlCfcHpLqiRVfpllli8WQ7lEPpvYuTO7epqhTPvsyjncfBZ7PE66hr/1yE7wJa7do3" Oct 30 05:00:00 volumio sudo[21597]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 30 05:00:00 volumio sudo[21597]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 30 05:00:00 volumio volumio[21385]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Oct 30 05:00:00 volumio volumio[21385]: SPOTIFY: BQCTam9nZoaqSOICQOtExT5xwFgbxar3AIBHrCHZu27-G5_liZnBEoK6koRThRLpa9QXZ96p7yNm2gX5Xy2UqqxUTRqAThfXz-9Y5FUaRofrfwiIs5iJy7NUQHYzq_Mv3-q_BM6Hl_AI493GjQddKZEImQ9t3NEwmVWRbnPg2lSU1K7kgwzEayhYsIOiqwHCm0uNUF_ivt_KOK3sQp6jOU-iMlP0sghXOUcj0cU9tqzTUyqszi0rJhPJ10SpDFiHHaYtCdkT_CNCurAHSG9RD9RMLhaXYv8pQJcwtSBLLNfOOhiNRfE Oct 30 05:00:00 volumio volumio[21385]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Oct 30 05:00:00 volumio volumio[21385]: info: New Spotify access token = BQCTam9nZoaqSOICQOtExT5xwFgbxar3AIBHrCHZu27-G5_liZnBEoK6koRThRLpa9QXZ96p7yNm2gX5Xy2UqqxUTRqAThfXz-9Y5FUaRofrfwiIs5iJy7NUQHYzq_Mv3-q_BM6Hl_AI493GjQddKZEImQ9t3NEwmVWRbnPg2lSU1K7kgwzEayhYsIOiqwHCm0uNUF_ivt_KOK3sQp6jOU-iMlP0sghXOUcj0cU9tqzTUyqszi0rJhPJ10SpDFiHHaYtCdkT_CNCurAHSG9RD9RMLhaXYv8pQJcwtSBLLNfOOhiNRfE Oct 30 05:00:00 volumio volumio[21385]: info: Spotify credentials grant success - running version from March 24, 2019 Oct 30 05:00:00 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Oct 30 05:00:00 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Oct 30 05:00:00 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Oct 30 05:00:00 volumio systemd[1]: shairport-sync.service: Consumed 1.523s CPU time. Oct 30 05:00:00 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Oct 30 05:00:00 volumio sudo[21591]: pam_unix(sudo:session): session closed for user root Oct 30 05:00:00 volumio sudo[21593]: pam_unix(sudo:session): session closed for user root Oct 30 05:00:00 volumio sudo[21597]: pam_unix(sudo:session): session closed for user root Oct 30 05:00:00 volumio volumio[21385]: error: MPD error: The expression evaluated to a falsy value: Oct 30 05:00:00 volumio volumio[21385]: assert.ok(self.idling) Oct 30 05:00:00 volumio volumio[21385]: error: The expression evaluated to a falsy value: Oct 30 05:00:00 volumio volumio[21385]: assert.ok(self.idling) Oct 30 05:00:00 volumio volumio[21385]: info: MPD running with PID21543 Oct 30 05:00:00 volumio volumio[21385]: ,establishing connection Oct 30 05:00:00 volumio volumio[21385]: error: updateQueue error: null Oct 30 05:00:00 volumio volumio[21385]: info: Shairport-Sync Started Oct 30 05:00:00 volumio volumio[21385]: Error adding Membership: Error: addMembership EINVAL Oct 30 05:00:00 volumio volumio[21385]: info: Shairport-Sync Started Oct 30 05:00:00 volumio volumio[21385]: info: Shairport-Sync Started Oct 30 05:00:00 volumio volumio[21385]: error: updateQueue error: null Oct 30 05:00:00 volumio volumio[21385]: info: CoreCommandRouter::volumioGetState Oct 30 05:00:00 volumio volumio[21385]: info: CorePlayQueue::getTrack 0 Oct 30 05:00:00 volumio go-librespot[21562]: time="2025-10-30T05:00:00Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 30 05:00:00 volumio go-librespot[21562]: time="2025-10-30T05:00:00Z" level=debug msg="completed keyexchange" Oct 30 05:00:00 volumio go-librespot[21562]: time="2025-10-30T05:00:00Z" level=debug msg="completed challenge" Oct 30 05:00:00 volumio go-librespot[21562]: time="2025-10-30T05:00: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 30 05:00:00 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 30 05:00:00 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 30 05:00:00 volumio volumio[21385]: 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 30 05:00:00 volumio volumio[21385]: info: Spotify Successfully logged in Oct 30 05:00:00 volumio volumio[21385]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 30 05:00:00 volumio volumio[21385]: info: [1761800400420] CoreMusicLibrary::Adding element Spotify Oct 30 05:00:00 volumio volumio[21385]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 30 05:00:00 volumio volumio[21385]: Cannot find translation for source Spotify Oct 30 05:00:00 volumio volumio[21385]: info: [yt-cast-receiver] DIAL server listening on port 8098 Oct 30 05:00:00 volumio volumio[21385]: info: CoreCommandRouter::volumioRetrievevolume Oct 30 05:00:00 volumio volumio[21385]: info: VolumeController:: Volume=33 Mute =false Oct 30 05:00:00 volumio volumio[21385]: info: CoreCommandRouter::volumioGetState Oct 30 05:00:00 volumio volumio[21385]: info: CorePlayQueue::getTrack 0 Oct 30 05:00:00 volumio volumio[21385]: info: CoreStateMachine::pushState Oct 30 05:00:00 volumio volumio[21385]: info: CorePlayQueue::getTrack 0 Oct 30 05:00:00 volumio volumio[21385]: info: CoreCommandRouter::volumioPushState Oct 30 05:00:00 volumio volumio[21385]: info: Completed starting Core Plugins Oct 30 05:00:00 volumio volumio[21385]: info: ------------------------------------------- Oct 30 05:00:00 volumio volumio[21385]: info: ----- MyVolumio plugins startup ---- Oct 30 05:00:00 volumio volumio[21385]: info: ------------------------------------------- Oct 30 05:00:00 volumio volumio[21385]: info: [MyVolumio PluginManager] Fetching plans data.... Oct 30 05:00:01 volumio volumio-remote-updater[874]: [2025-10-30 05:00:01] [connect] Successful connection Oct 30 05:00:01 volumio volumio-remote-updater[874]: [2025-10-30 05:00:01] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1761800401 101 Oct 30 05:00:01 volumio volumio[21385]: 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 30 05:00:02 volumio volumio[21385]: info: Cannot mount NAS NAS at system boot, trial number 2 ,retrying in 5 seconds Oct 30 05:00:03 volumio volumio[21385]: info: go-librespot daemon successfully initialized Oct 30 05:00:03 volumio sudo[21618]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Oct 30 05:00:03 volumio sudo[21618]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 30 05:00:03 volumio sudo[21620]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Oct 30 05:00:03 volumio sudo[21620]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 30 05:00:03 volumio systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Oct 30 05:00:03 volumio systemd[1]: mpd_monitor.service: Deactivated successfully. Oct 30 05:00:03 volumio systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Oct 30 05:00:03 volumio systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Oct 30 05:00:03 volumio sudo[21618]: pam_unix(sudo:session): session closed for user root Oct 30 05:00:03 volumio mpd_monitor.sh[21623]: MPD Monitor Service: Starting MPD Monitor Service Oct 30 05:00:03 volumio volumio[21385]: info: Successfully started MPD Monitor Oct 30 05:00:03 volumio sudo[21620]: pam_unix(sudo:session): session closed for user root Oct 30 05:00:03 volumio volumio[21385]: info: Successfully started MPD Monitor Oct 30 05:00:03 volumio mpd[21543]: mixer: Failed to read mixer for "default detected output": no such mixer control: PCM Oct 30 05:00:03 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 105. Oct 30 05:00:03 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 30 05:00:03 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 30 05:00:03 volumio go-librespot[21627]: go-librespot daemon starting... Oct 30 05:00:03 volumio go-librespot[21628]: time="2025-10-30T05:00:03Z" level=info msg="running go-librespot 0.4.0" Oct 30 05:00:03 volumio go-librespot[21628]: time="2025-10-30T05:00:03Z" level=debug msg="app state loaded" Oct 30 05:00:03 volumio go-librespot[21628]: time="2025-10-30T05:00:03Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 30 05:00:03 volumio go-librespot[21628]: time="2025-10-30T05:00: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-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Oct 30 05:00:03 volumio go-librespot[21628]: time="2025-10-30T05:00:03Z" 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 30 05:00:03 volumio go-librespot[21628]: time="2025-10-30T05:00:03Z" 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 30 05:00:03 volumio go-librespot[21628]: time="2025-10-30T05:00:03Z" level=info msg="zeroconf server listening on port 36649" Oct 30 05:00:03 volumio go-librespot[21628]: time="2025-10-30T05:00:03Z" level=debug msg="obtained new client token: AAA1uyYGqMqkzbwzK38AUcB+iKR27XQ07FHxGk+a67OujPUiOeVvhs/WI4atnUFhMs4YSkyulOwKiESQ6r+Qsbj6A3UAFQJD8CGnCgw8ttfMVrgos9TZJLjDob4CXVAwHzOnJPl3dRsX8YS/I80FyFHQ1t0sKYh39CWUaLKn2bYcSqzF7SGNn1XdOgKNz7n7vPljtVHYKSdyWbPrhhlJYLDZcv7veZEMrehUZDrS0sohVlNFYjaHpFo=" Oct 30 05:00:03 volumio go-librespot[21628]: time="2025-10-30T05:00:03Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 30 05:00:03 volumio go-librespot[21628]: time="2025-10-30T05:00:03Z" level=debug msg="completed keyexchange" Oct 30 05:00:03 volumio go-librespot[21628]: time="2025-10-30T05:00:03Z" level=debug msg="completed challenge" Oct 30 05:00:03 volumio go-librespot[21628]: time="2025-10-30T05:00: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 30 05:00:03 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 30 05:00:03 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 30 05:00:05 volumio mpd[21543]: exception: No database Oct 30 05:00:05 volumio mpd[21543]: exception: No database Oct 30 05:00:05 volumio mpd[21543]: exception: No database Oct 30 05:00:05 volumio volumio[21385]: error: Failed LSINFO: Error: [50@0] {lsinfo} No database Oct 30 05:00:06 volumio volumio[21385]: info: Initializing connection to go-librespot Websocket Oct 30 05:00:06 volumio volumio[21385]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 30 05:00:07 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 106. Oct 30 05:00:07 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 30 05:00:07 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 30 05:00:07 volumio go-librespot[21635]: go-librespot daemon starting... Oct 30 05:00:07 volumio go-librespot[21636]: time="2025-10-30T05:00:07Z" level=info msg="running go-librespot 0.4.0" Oct 30 05:00:07 volumio go-librespot[21636]: time="2025-10-30T05:00:07Z" level=debug msg="app state loaded" Oct 30 05:00:07 volumio go-librespot[21636]: time="2025-10-30T05:00:07Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 30 05:00:07 volumio volumio[21385]: info: Cannot mount NAS NAS at system boot, trial number 3 ,retrying in 5 seconds Oct 30 05:00:07 volumio sudo[21657]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 30 05:00:07 volumio sudo[21657]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 30 05:00:07 volumio sudo[21659]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 30 05:00:07 volumio sudo[21659]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 30 05:00:07 volumio sudo[21659]: pam_unix(sudo:session): session closed for user root Oct 30 05:00:07 volumio sudo[21657]: pam_unix(sudo:session): session closed for user root Oct 30 05:00:07 volumio sudo[21662]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Oct 30 05:00:07 volumio sudo[21662]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 30 05:00:07 volumio sudo[21662]: pam_unix(sudo:session): session closed for user root Oct 30 05:00:07 volumio volumio[21385]: info: Upmpdcli Daemon Started Oct 30 05:00:09 volumio volumio[21385]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Oct 30 05:00:09 volumio volumio[21385]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Oct 30 05:00:09 volumio volumio[21385]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Oct 30 05:00:09 volumio volumio[21385]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Oct 30 05:00:09 volumio volumio[21385]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Oct 30 05:00:09 volumio volumio[21385]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Oct 30 05:00:09 volumio volumio[21385]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Oct 30 05:00:09 volumio volumio[21385]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Oct 30 05:00:09 volumio volumio[21385]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Oct 30 05:00:09 volumio volumio[21385]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Oct 30 05:00:09 volumio volumio[21385]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Oct 30 05:00:09 volumio volumio[21385]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Oct 30 05:00:09 volumio volumio[21385]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Oct 30 05:00:09 volumio volumio[21385]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Oct 30 05:00:09 volumio volumio[21385]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Oct 30 05:00:09 volumio volumio[21385]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Oct 30 05:00:09 volumio volumio[21385]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Oct 30 05:00:09 volumio volumio[21385]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Oct 30 05:00:09 volumio volumio[21385]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Oct 30 05:00:09 volumio volumio[21385]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Oct 30 05:00:09 volumio volumio[21385]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Oct 30 05:00:09 volumio volumio[21385]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Oct 30 05:00:09 volumio volumio[21385]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Oct 30 05:00:09 volumio volumio[21385]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Oct 30 05:00:09 volumio volumio[21385]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Oct 30 05:00:09 volumio volumio[21385]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Oct 30 05:00:09 volumio volumio[21385]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Oct 30 05:00:09 volumio volumio[21385]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Oct 30 05:00:09 volumio volumio[21385]: info: Adding plugin bluetooth to MyMusic Plugins Oct 30 05:00:09 volumio volumio[21385]: info: Adding plugin multiroom to MyMusic Plugins Oct 30 05:00:09 volumio volumio[21385]: info: Adding plugin metavolumio to MyMusic Plugins Oct 30 05:00:09 volumio volumio[21385]: info: Adding plugin cd_controller to MyMusic Plugins Oct 30 05:00:09 volumio volumio[21385]: info: Adding plugin qobuzconnect to MyMusic Plugins Oct 30 05:00:09 volumio volumio[21385]: info: Adding plugin smart_inputs to MyMusic Plugins Oct 30 05:00:09 volumio volumio[21385]: info: Adding plugin tidalconnect to MyMusic Plugins Oct 30 05:00:09 volumio volumio[21385]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Oct 30 05:00:09 volumio volumio[21385]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Oct 30 05:00:09 volumio volumio[21385]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Oct 30 05:00:09 volumio volumio[21385]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 30 05:00:09 volumio volumio[21385]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 30 05:00:09 volumio volumio[21385]: info: Starting MyVolumio Remote Streaming Endpoints Oct 30 05:00:09 volumio volumio[21385]: info: MyVolumio login type: Token Oct 30 05:00:09 volumio volumio[21385]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Oct 30 05:00:09 volumio volumio[21385]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Oct 30 05:00:09 volumio kernel: nfs: server 192.168.1.3 not responding, timed out Oct 30 05:00:09 volumio volumio[21385]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Oct 30 05:00:09 volumio volumio[21385]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Oct 30 05:00:09 volumio volumio[21385]: info: Streaming services startup Oct 30 05:00:09 volumio volumio[21385]: info: Starting Streaming Daemon Oct 30 05:00:09 volumio sudo[21666]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Oct 30 05:00:09 volumio sudo[21666]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 30 05:00:09 volumio volumio[21385]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Oct 30 05:00:09 volumio sudo[21666]: pam_unix(sudo:session): session closed for user root Oct 30 05:00:09 volumio volumio[21385]: info: Initializing connection to go-librespot Websocket Oct 30 05:00:09 volumio volumio[21385]: error: Cannot start Volumio Streaming Daemon Oct 30 05:00:09 volumio volumio[21385]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Oct 30 05:00:09 volumio volumio[21385]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Oct 30 05:00:09 volumio go-librespot[21636]: time="2025-10-30T05:00:09Z" level=debug msg="new websocket client" Oct 30 05:00:09 volumio volumio[21385]: info: Connection to go-librespot Websocket established Oct 30 05:00:12 volumio volumio[21385]: info: Getting Spotify volume Oct 30 05:00:12 volumio volumio[21385]: info: Cannot mount NAS NAS at system boot, trial number 4 ,retrying in 5 seconds Oct 30 05:00:14 volumio volumio[21385]: 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 30 05:00:14 volumio volumio[21385]: info: CoreCommandRouter::volumioGetState Oct 30 05:00:14 volumio volumio[21385]: info: CorePlayQueue::getTrack 0 Oct 30 05:00:14 volumio volumio[21385]: SPOTIFY: RECEIVED VOLUMIO VOLUME 33 Oct 30 05:00:14 volumio volumio[21385]: SPOTIFY: SPOTIFY VOLUME undefined Oct 30 05:00:14 volumio volumio[21385]: SPOTIFY: VOLUMIO VOLUME 33 Oct 30 05:00:14 volumio volumio[21385]: info: Aligning Spotify Volume to Volumio Volume Oct 30 05:00:14 volumio volumio[21385]: info: CoreCommandRouter::volumioGetState Oct 30 05:00:14 volumio volumio[21385]: info: CorePlayQueue::getTrack 0 Oct 30 05:00:14 volumio volumio[21385]: info: Setting Spotify Volume from Volumio: 33 Oct 30 05:00:14 volumio go-librespot[21636]: time="2025-10-30T05:00: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 30 05:00:14 volumio go-librespot[21636]: time="2025-10-30T05:00: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 30 05:00:14 volumio go-librespot[21636]: time="2025-10-30T05:00: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 30 05:00:14 volumio go-librespot[21636]: time="2025-10-30T05:00:14Z" level=info msg="zeroconf server listening on port 42003" Oct 30 05:00:14 volumio go-librespot[21636]: time="2025-10-30T05:00:14Z" level=debug msg="obtained new client token: AABMl2v8Dd2ptk5lzNgpcR1V9V9s4PX1pzQHq3T61jSe4zSNBKEJoUt3vpm22TxCCjABFuxbtdBNYhkMput0sFH8QdBU53v1DLVIYcVlCcRqMRLUnPtYJpmSHDvr/RDqL3U3RFQvHsuoDT2rKNLUWBjT4eGIGucZHG2K+5Jo9jJ1yV/7E6Ron4y4/DGv5pCOCTG5Vn0qKE36Vu6vl6bnU5Adl1KsXItl3NOKkqGFao190wGfkp00l4Y=" Oct 30 05:00:14 volumio go-librespot[21636]: time="2025-10-30T05:00:14Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 30 05:00:14 volumio go-librespot[21636]: time="2025-10-30T05:00:14Z" level=debug msg="completed keyexchange" Oct 30 05:00:14 volumio go-librespot[21636]: time="2025-10-30T05:00:14Z" level=debug msg="completed challenge" Oct 30 05:00:14 volumio go-librespot[21636]: time="2025-10-30T05:00: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 30 05:00:14 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 30 05:00:14 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 30 05:00:14 volumio volumio[21385]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 30 05:00:14 volumio volumio[21385]: Error: socket hang up Oct 30 05:00:14 volumio volumio[21385]: at connResetException (node:internal/errors:720:14) Oct 30 05:00:14 volumio volumio[21385]: at Socket.socketOnEnd (node:_http_client:519:23) Oct 30 05:00:14 volumio volumio[21385]: at Socket.emit (node:events:526:35) Oct 30 05:00:14 volumio volumio[21385]: at endReadableNT (node:internal/streams/readable:1376:12) Oct 30 05:00:14 volumio volumio[21385]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { Oct 30 05:00:14 volumio volumio[21385]: code: 'ECONNRESET', Oct 30 05:00:14 volumio volumio[21385]: response: undefined Oct 30 05:00:14 volumio volumio[21385]: } Oct 30 05:00:14 volumio volumio[21385]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 30 05:00:14 volumio sudo[21688]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-10-30 04:59' Oct 30 05:00:14 volumio sudo[21688]: 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"