Nov 05 10:35:01 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 90. Nov 05 10:35:01 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Nov 05 10:35:01 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Nov 05 10:35:01 volumio go-librespot[10207]: go-librespot daemon starting... Nov 05 10:35:01 volumio go-librespot[10208]: time="2025-11-05T10:35:01Z" level=info msg="running go-librespot 0.4.0" Nov 05 10:35:01 volumio go-librespot[10208]: time="2025-11-05T10:35:01Z" level=debug msg="app state loaded" Nov 05 10:35:01 volumio go-librespot[10208]: time="2025-11-05T10:35:01Z" level=info msg="api server listening on 127.0.0.1:9879" Nov 05 10:35:01 volumio go-librespot[10208]: time="2025-11-05T10:35:01Z" 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]" Nov 05 10:35:01 volumio go-librespot[10208]: time="2025-11-05T10:35:01Z" 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]" Nov 05 10:35:01 volumio go-librespot[10208]: time="2025-11-05T10:35:01Z" 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]" Nov 05 10:35:01 volumio go-librespot[10208]: time="2025-11-05T10:35:01Z" level=info msg="zeroconf server listening on port 33247" Nov 05 10:35:01 volumio go-librespot[10208]: time="2025-11-05T10:35:01Z" level=debug msg="obtained new client token: AAALmd4l7JPJCPHYdI51hi7OHC84ivpk4i1RCWaiD2uM42bTSUXERCIW39nS/bm+Mh4DKZV7ldWUX299keQ0iqynsyldAmtI6k5j3LUn49E/qgAsPf7zKl0xn4PzDkbUuK0vUvksXLU6lKYZxaBdo7koB+mYtpdTWZzMWOzFMXd3cYkGp9e5i/7ohhRPbrLOK2Yd2TmKHdInbfdZicCs2NUQwJdqL5RO4ej9uZMi0FnSaE0h5HJ3BO0=" Nov 05 10:35:01 volumio go-librespot[10208]: time="2025-11-05T10:35:01Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Nov 05 10:35:01 volumio go-librespot[10208]: time="2025-11-05T10:35:01Z" level=debug msg="completed keyexchange" Nov 05 10:35:01 volumio go-librespot[10208]: time="2025-11-05T10:35:01Z" level=debug msg="completed challenge" Nov 05 10:35:01 volumio go-librespot[10208]: time="2025-11-05T10:35:01Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Nov 05 10:35:01 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 05 10:35:01 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 05 10:35:01 volumio volumio[9419]: info: Initializing connection to go-librespot Websocket Nov 05 10:35:01 volumio volumio[9419]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 05 10:35:04 volumio volumio[9419]: info: CoreCommandRouter::volumioGetState Nov 05 10:35:04 volumio volumio[9419]: info: CorePlayQueue::getTrack 0 Nov 05 10:35:04 volumio volumio[9419]: info: Listing playlists Nov 05 10:35:04 volumio volumio[9419]: info: Listing playlists Nov 05 10:35:04 volumio volumio[9419]: info: Initializing connection to go-librespot Websocket Nov 05 10:35:04 volumio volumio[9419]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 05 10:35:05 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 91. Nov 05 10:35:05 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Nov 05 10:35:05 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Nov 05 10:35:05 volumio go-librespot[10231]: go-librespot daemon starting... Nov 05 10:35:05 volumio go-librespot[10232]: time="2025-11-05T10:35:05Z" level=info msg="running go-librespot 0.4.0" Nov 05 10:35:05 volumio go-librespot[10232]: time="2025-11-05T10:35:05Z" level=debug msg="app state loaded" Nov 05 10:35:05 volumio go-librespot[10232]: time="2025-11-05T10:35:05Z" level=info msg="api server listening on 127.0.0.1:9879" Nov 05 10:35:05 volumio go-librespot[10232]: time="2025-11-05T10:35: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-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Nov 05 10:35:05 volumio go-librespot[10232]: time="2025-11-05T10:35:05Z" 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]" Nov 05 10:35:05 volumio go-librespot[10232]: time="2025-11-05T10:35:05Z" 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]" Nov 05 10:35:05 volumio go-librespot[10232]: time="2025-11-05T10:35:05Z" level=info msg="zeroconf server listening on port 35415" Nov 05 10:35:05 volumio go-librespot[10232]: time="2025-11-05T10:35:05Z" level=debug msg="obtained new client token: AADlJ+ScUSUK593phKFl3uo2nNQGInErqRK+saPBA9PD8zAXhDRfUpoeGRz7CgTj8LZQV+geRX3tHAzF6bs3zrzkTzADZVOP0r6w9mRXSljrxnbI7b2v+EXbpLdVVaDUkJkL/XB0U1nPdgchjWK05Tex5k0GWRS+JqfhaVhOhWorAn4pbFANqGnHt8A5vGfQmhw7TFavkZpTZSHRqCOv+uguDa+xHVQjWhS8SodV5/foF3e0+oYf" Nov 05 10:35:05 volumio go-librespot[10232]: time="2025-11-05T10:35:05Z" 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" Nov 05 10:35:05 volumio go-librespot[10232]: time="2025-11-05T10:35:05Z" level=debug msg="connected to ap-gew1.spotify.com:443" Nov 05 10:35:05 volumio go-librespot[10232]: time="2025-11-05T10:35:05Z" level=debug msg="completed keyexchange" Nov 05 10:35:05 volumio go-librespot[10232]: time="2025-11-05T10:35:05Z" level=debug msg="completed challenge" Nov 05 10:35:05 volumio go-librespot[10232]: time="2025-11-05T10:35:05Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Nov 05 10:35:05 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 05 10:35:05 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 05 10:35:07 volumio volumio[9419]: info: Initializing connection to go-librespot Websocket Nov 05 10:35:07 volumio volumio[9419]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 05 10:35:08 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 92. Nov 05 10:35:08 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Nov 05 10:35:08 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Nov 05 10:35:08 volumio go-librespot[10239]: go-librespot daemon starting... Nov 05 10:35:08 volumio go-librespot[10240]: time="2025-11-05T10:35:08Z" level=info msg="running go-librespot 0.4.0" Nov 05 10:35:08 volumio go-librespot[10240]: time="2025-11-05T10:35:08Z" level=debug msg="app state loaded" Nov 05 10:35:08 volumio go-librespot[10240]: time="2025-11-05T10:35:08Z" level=info msg="api server listening on 127.0.0.1:9879" Nov 05 10:35:08 volumio go-librespot[10240]: time="2025-11-05T10:35:08Z" 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]" Nov 05 10:35:08 volumio go-librespot[10240]: time="2025-11-05T10:35:08Z" 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]" Nov 05 10:35:08 volumio go-librespot[10240]: time="2025-11-05T10:35:08Z" 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]" Nov 05 10:35:08 volumio go-librespot[10240]: time="2025-11-05T10:35:08Z" level=info msg="zeroconf server listening on port 42639" Nov 05 10:35:08 volumio go-librespot[10240]: time="2025-11-05T10:35:08Z" level=debug msg="obtained new client token: AADdvJeubP5Lux1elny3BXxE2zg1gAJgGnPONhrUElqD1BiVb9RRRsDXGKjQ2suQ5dIbBUbN0NpeYu7ReBrn8IhAoZ+f1mvpkiFtj2u21CbastFWoOYL1iHGjNiQOnVBg5U5E5Ta8TY2GDXlIt/kHCK/IL9NJPrBLJOiJND+z/Z7MCUaifadV2Zenk4utaQ6PAriqXQBdZI++MQiZRawkC0RVePNCKPqwtIhDHAWOM10qz6fJImXOVo=" Nov 05 10:35:08 volumio go-librespot[10240]: time="2025-11-05T10:35:08Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Nov 05 10:35:08 volumio go-librespot[10240]: time="2025-11-05T10:35:08Z" level=debug msg="completed keyexchange" Nov 05 10:35:08 volumio go-librespot[10240]: time="2025-11-05T10:35:08Z" level=debug msg="completed challenge" Nov 05 10:35:08 volumio go-librespot[10240]: time="2025-11-05T10:35:08Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Nov 05 10:35:08 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 05 10:35:08 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 05 10:35:10 volumio volumio[9419]: info: Initializing connection to go-librespot Websocket Nov 05 10:35:10 volumio volumio[9419]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 05 10:35:12 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 93. Nov 05 10:35:12 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Nov 05 10:35:12 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Nov 05 10:35:12 volumio go-librespot[10247]: go-librespot daemon starting... Nov 05 10:35:12 volumio go-librespot[10248]: time="2025-11-05T10:35:12Z" level=info msg="running go-librespot 0.4.0" Nov 05 10:35:12 volumio go-librespot[10248]: time="2025-11-05T10:35:12Z" level=debug msg="app state loaded" Nov 05 10:35:12 volumio go-librespot[10248]: time="2025-11-05T10:35:12Z" level=info msg="api server listening on 127.0.0.1:9879" Nov 05 10:35:12 volumio go-librespot[10248]: time="2025-11-05T10:35: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-gae2.spotify.com:80]" Nov 05 10:35:12 volumio go-librespot[10248]: time="2025-11-05T10:35:12Z" 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]" Nov 05 10:35:12 volumio go-librespot[10248]: time="2025-11-05T10:35:12Z" 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]" Nov 05 10:35:12 volumio go-librespot[10248]: time="2025-11-05T10:35:12Z" level=info msg="zeroconf server listening on port 36165" Nov 05 10:35:12 volumio go-librespot[10248]: time="2025-11-05T10:35:12Z" level=debug msg="obtained new client token: AADZ++eSiSIvVxcAe8Iidk5XWHeJq/LZRXq0uR8tlp6B4mvboDSuxsR/sxVV1y1JEyPnoRCNAnQfli7AM7Klio9eaTzTPlcFncmnBCcRxPmZ2fPetgFlmmW13XUSqOv1kBr1BhTszNGl5pfASS7ch1tOIcbaSkKU+kjj1K4rmb5id64Ksa3sJAXRiVzvUVSSBwb6nOITSfidKkqaMM9HFbC+iTcuDAHvcsSbaVOrEGQXN9SVKuyX" Nov 05 10:35:12 volumio go-librespot[10248]: time="2025-11-05T10:35:12Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Nov 05 10:35:12 volumio go-librespot[10248]: time="2025-11-05T10:35:12Z" level=debug msg="completed keyexchange" Nov 05 10:35:12 volumio go-librespot[10248]: time="2025-11-05T10:35:12Z" level=debug msg="completed challenge" Nov 05 10:35:12 volumio go-librespot[10248]: time="2025-11-05T10:35:12Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Nov 05 10:35:12 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 05 10:35:12 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 05 10:35:13 volumio volumio[9419]: info: Initializing connection to go-librespot Websocket Nov 05 10:35:13 volumio volumio[9419]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 05 10:35:14 volumio volumio[9419]: info: CoreCommandRouter::volumioGetState Nov 05 10:35:14 volumio volumio[9419]: info: CorePlayQueue::getTrack 0 Nov 05 10:35:15 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 94. Nov 05 10:35:15 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Nov 05 10:35:15 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Nov 05 10:35:15 volumio go-librespot[10269]: go-librespot daemon starting... Nov 05 10:35:15 volumio go-librespot[10270]: time="2025-11-05T10:35:15Z" level=info msg="running go-librespot 0.4.0" Nov 05 10:35:15 volumio go-librespot[10270]: time="2025-11-05T10:35:15Z" level=debug msg="app state loaded" Nov 05 10:35:15 volumio go-librespot[10270]: time="2025-11-05T10:35:15Z" level=info msg="api server listening on 127.0.0.1:9879" Nov 05 10:35:15 volumio go-librespot[10270]: time="2025-11-05T10:35: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-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Nov 05 10:35:15 volumio go-librespot[10270]: time="2025-11-05T10:35:15Z" 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]" Nov 05 10:35:15 volumio go-librespot[10270]: time="2025-11-05T10:35:15Z" 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]" Nov 05 10:35:15 volumio go-librespot[10270]: time="2025-11-05T10:35:15Z" level=info msg="zeroconf server listening on port 43477" Nov 05 10:35:15 volumio go-librespot[10270]: time="2025-11-05T10:35:15Z" level=debug msg="obtained new client token: AACGLdG4VhtGapbDg30g1MiDixc6aWdrtCsffxkmdcLBqbnVZNrY1SBQptdIXBM6DsSqBXTKg2U5uAx+Tt4edJ0qKL0VyuxORHB7DMZ09VJyviQbcfj+H77SMiE0ramhlmxaB4QVCT/ikh8Gq/vNII2RgvgWcb8g3j1EzkbcJNZOLHsrcnmUXuSjjMfFAXSXf92JchPmMhewScXI8KK9VKwHvBo2kVSkBQS5Z34LpT+HTJ1HIq1Fzpw=" Nov 05 10:35:15 volumio go-librespot[10270]: time="2025-11-05T10:35:15Z" 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" Nov 05 10:35:15 volumio go-librespot[10270]: time="2025-11-05T10:35:15Z" level=debug msg="connected to ap-gew1.spotify.com:443" Nov 05 10:35:15 volumio go-librespot[10270]: time="2025-11-05T10:35:15Z" level=debug msg="completed keyexchange" Nov 05 10:35:15 volumio go-librespot[10270]: time="2025-11-05T10:35:15Z" level=debug msg="completed challenge" Nov 05 10:35:15 volumio go-librespot[10270]: time="2025-11-05T10:35:15Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Nov 05 10:35:15 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 05 10:35:15 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 05 10:35:16 volumio volumio[9419]: info: Initializing connection to go-librespot Websocket Nov 05 10:35:16 volumio volumio[9419]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 05 10:35:19 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 95. Nov 05 10:35:19 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Nov 05 10:35:19 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Nov 05 10:35:19 volumio go-librespot[10280]: go-librespot daemon starting... Nov 05 10:35:19 volumio go-librespot[10281]: time="2025-11-05T10:35:19Z" level=info msg="running go-librespot 0.4.0" Nov 05 10:35:19 volumio go-librespot[10281]: time="2025-11-05T10:35:19Z" level=debug msg="app state loaded" Nov 05 10:35:19 volumio go-librespot[10281]: time="2025-11-05T10:35:19Z" level=info msg="api server listening on 127.0.0.1:9879" Nov 05 10:35:19 volumio go-librespot[10281]: time="2025-11-05T10:35: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-gew4.spotify.com:80]" Nov 05 10:35:19 volumio go-librespot[10281]: time="2025-11-05T10:35:19Z" 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]" Nov 05 10:35:19 volumio go-librespot[10281]: time="2025-11-05T10:35:19Z" 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]" Nov 05 10:35:19 volumio go-librespot[10281]: time="2025-11-05T10:35:19Z" level=info msg="zeroconf server listening on port 35813" Nov 05 10:35:19 volumio go-librespot[10281]: time="2025-11-05T10:35:19Z" level=debug msg="obtained new client token: AAAX6wUhbLO9E8DeWDs65wJtGmHYlXzFpaAMcu0byXCPe2szWLEvyfpYgEmEtL1dHUGWdYABEWnoFYTYqIw6T/AGnqek5k4d0SJJSkUxMCJe3gQ50jOOIJK36tj3JWX8JEnlNMEL8Sbb2u5ZNf6Em5PZbErASKJilKWjQoEC4I1oLrdqIMWo+X+mqehrKeBZLwMq7omUsukr2sCdMgKYJyScdJfFlG1JNKDZgtgJ9pI3cEJzHw+J" Nov 05 10:35:19 volumio go-librespot[10281]: time="2025-11-05T10:35:19Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Nov 05 10:35:19 volumio go-librespot[10281]: time="2025-11-05T10:35:19Z" level=debug msg="completed keyexchange" Nov 05 10:35:19 volumio go-librespot[10281]: time="2025-11-05T10:35:19Z" level=debug msg="completed challenge" Nov 05 10:35:19 volumio go-librespot[10281]: time="2025-11-05T10:35:19Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Nov 05 10:35:19 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 05 10:35:19 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 05 10:35:19 volumio volumio[9419]: info: Initializing connection to go-librespot Websocket Nov 05 10:35:19 volumio volumio[9419]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 05 10:35:22 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 96. Nov 05 10:35:22 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Nov 05 10:35:22 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Nov 05 10:35:22 volumio go-librespot[10289]: go-librespot daemon starting... Nov 05 10:35:22 volumio go-librespot[10290]: time="2025-11-05T10:35:22Z" level=info msg="running go-librespot 0.4.0" Nov 05 10:35:22 volumio go-librespot[10290]: time="2025-11-05T10:35:22Z" level=debug msg="app state loaded" Nov 05 10:35:22 volumio go-librespot[10290]: time="2025-11-05T10:35:22Z" level=info msg="api server listening on 127.0.0.1:9879" Nov 05 10:35:22 volumio go-librespot[10290]: time="2025-11-05T10:35: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]" Nov 05 10:35:22 volumio go-librespot[10290]: time="2025-11-05T10:35: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]" Nov 05 10:35:22 volumio go-librespot[10290]: time="2025-11-05T10:35: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]" Nov 05 10:35:22 volumio go-librespot[10290]: time="2025-11-05T10:35:22Z" level=info msg="zeroconf server listening on port 36493" Nov 05 10:35:22 volumio volumio[9419]: info: Initializing connection to go-librespot Websocket Nov 05 10:35:22 volumio go-librespot[10290]: time="2025-11-05T10:35:22Z" level=debug msg="new websocket client" Nov 05 10:35:22 volumio volumio[9419]: info: Connection to go-librespot Websocket established Nov 05 10:35:24 volumio volumio[9419]: info: CoreCommandRouter::volumioGetState Nov 05 10:35:24 volumio volumio[9419]: info: CorePlayQueue::getTrack 0 Nov 05 10:35:24 volumio volumio[9419]: info: Listing playlists Nov 05 10:35:24 volumio volumio[9419]: info: Listing playlists Nov 05 10:35:25 volumio go-librespot[10290]: time="2025-11-05T10:35:25Z" level=debug msg="obtained new client token: AADzXNcgOhgJEc0bebiO583EEVmQxe+vJWhBM5C/miyNzBsFo8Hp8FFG+9xMS9opgRptTydNyiEaLg3MPBbY8lVpxrQM2gbIQ8+VsXBJm6a2BwifmG/EzJQPMTyx0NznKpXet9/2n8RVduldFVavDU4HXD1fN7+651qASu/vD5gFmi1sUjF1+7AjdOOa4cenaCKZSRNhQx71jIU6az15urZ8/4sfQ07syfXlrbWu2xV9lY9uibNFEWo=" Nov 05 10:35:25 volumio go-librespot[10290]: time="2025-11-05T10:35:25Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Nov 05 10:35:25 volumio go-librespot[10290]: time="2025-11-05T10:35:25Z" level=debug msg="completed keyexchange" Nov 05 10:35:25 volumio go-librespot[10290]: time="2025-11-05T10:35:25Z" level=debug msg="completed challenge" Nov 05 10:35:25 volumio go-librespot[10290]: time="2025-11-05T10:35:25Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Nov 05 10:35:25 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 05 10:35:25 volumio volumio[9419]: info: Connection to go-librespot Websocket closed Nov 05 10:35:25 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 05 10:35:25 volumio volumio[9419]: info: Getting Spotify volume Nov 05 10:35:25 volumio volumio[9419]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Nov 05 10:35:25 volumio volumio[9419]: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 05 10:35:25 volumio volumio[9419]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Nov 05 10:35:25 volumio volumio[9419]: errno: -111, Nov 05 10:35:25 volumio volumio[9419]: code: 'ECONNREFUSED', Nov 05 10:35:25 volumio volumio[9419]: syscall: 'connect', Nov 05 10:35:25 volumio volumio[9419]: address: '127.0.0.1', Nov 05 10:35:25 volumio volumio[9419]: port: 9879, Nov 05 10:35:25 volumio volumio[9419]: response: undefined Nov 05 10:35:25 volumio volumio[9419]: } Nov 05 10:35:25 volumio volumio[9419]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Nov 05 10:35:26 volumio sudo[10325]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-11-05 10:34' Nov 05 10:35:26 volumio sudo[10325]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 05 10:35:26 volumio sudo[10325]: pam_unix(sudo:session): session closed for user root Nov 05 10:35:26 volumio volumio-remote-updater[874]: [2025-11-05 10:35:26] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Nov 05 10:35:26 volumio volumio-remote-updater[874]: [2025-11-05 10:35:26] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Nov 05 10:35:26 volumio systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Nov 05 10:35:26 volumio systemd[1]: volumio.service: Failed with result 'exit-code'. Nov 05 10:35:26 volumio systemd[1]: volumio.service: Consumed 8.785s CPU time. Nov 05 10:35:26 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Nov 05 10:35:26 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Nov 05 10:35:26 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 7698. Nov 05 10:35:26 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Nov 05 10:35:26 volumio systemd[1]: Stopped volumio.service - Volumio Backend Module. Nov 05 10:35:26 volumio systemd[1]: volumio.service: Consumed 8.785s CPU time. Nov 05 10:35:26 volumio systemd[1]: Started volumio.service - Volumio Backend Module. Nov 05 10:35:26 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Nov 05 10:35:26 volumio volumio[10351]: info: ------------------------------------------- Nov 05 10:35:26 volumio volumio[10351]: info: ----- Volumio3 ---- Nov 05 10:35:26 volumio volumio[10351]: info: ------------------------------------------- Nov 05 10:35:26 volumio volumio[10351]: info: ----- System startup ---- Nov 05 10:35:26 volumio volumio[10351]: info: ------------------------------------------- Nov 05 10:35:27 volumio volumio[10351]: info: MYVOLUMIO Environment detected Nov 05 10:35:27 volumio volumio[10351]: info: Plugin folders cleanup Nov 05 10:35:27 volumio volumio[10351]: info: Scanning into folder /volumio/app/plugins/ Nov 05 10:35:27 volumio volumio[10351]: info: Scanning category audio_interface Nov 05 10:35:27 volumio volumio[10351]: info: Scanning category miscellanea Nov 05 10:35:27 volumio volumio[10351]: info: Scanning category music_service Nov 05 10:35:27 volumio volumio[10351]: info: Scanning category plugins.json Nov 05 10:35:27 volumio volumio[10351]: info: Scanning category system_controller Nov 05 10:35:27 volumio volumio[10351]: info: Scanning category user_interface Nov 05 10:35:27 volumio volumio[10351]: info: Scanning into folder /data/plugins/ Nov 05 10:35:27 volumio volumio[10351]: info: Scanning category music_service Nov 05 10:35:27 volumio volumio[10351]: info: Scanning category user_interface Nov 05 10:35:27 volumio volumio[10351]: info: Plugin folders cleanup completed Nov 05 10:35:27 volumio volumio[10351]: info: ------------------------------------------- Nov 05 10:35:27 volumio volumio[10351]: info: ----- Core plugins startup ---- Nov 05 10:35:27 volumio volumio[10351]: info: ------------------------------------------- Nov 05 10:35:27 volumio volumio[10351]: info: Loading plugins from folder /volumio/app/plugins/ Nov 05 10:35:27 volumio volumio[10351]: info: Adding plugin upnp to MyMusic Plugins Nov 05 10:35:27 volumio volumio[10351]: info: Adding plugin airplay_emulation to MyMusic Plugins Nov 05 10:35:27 volumio volumio[10351]: info: Adding plugin upnp_browser to MyMusic Plugins Nov 05 10:35:27 volumio volumio[10351]: info: Loading plugins from folder /data/plugins/ Nov 05 10:35:27 volumio volumio[10351]: info: Loading plugin "system"... Nov 05 10:35:27 volumio volumio[10351]: info: Loading plugin "appearance"... Nov 05 10:35:27 volumio volumio[10351]: info: Loading plugin "network"... Nov 05 10:35:27 volumio volumio[10351]: info: Refreshing Cached IP Addresses Nov 05 10:35:27 volumio sudo[10379]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Nov 05 10:35:27 volumio sudo[10379]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 05 10:35:27 volumio sudo[10379]: pam_unix(sudo:session): session closed for user root Nov 05 10:35:27 volumio sudo[10381]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Nov 05 10:35:27 volumio sudo[10381]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 05 10:35:27 volumio volumio[10351]: info: Loading plugin "services"... Nov 05 10:35:27 volumio volumio[10351]: info: Loading plugin "alsa_controller"... Nov 05 10:35:27 volumio sudo[10381]: pam_unix(sudo:session): session closed for user root Nov 05 10:35:27 volumio volumio[10351]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Nov 05 10:35:27 volumio volumio[10351]: info: Loading plugin "wizard"... Nov 05 10:35:27 volumio volumio[10351]: info: Loading plugin "networkfs"... Nov 05 10:35:27 volumio volumio[10351]: info: Cannot mount NAS NAS at system boot, trial number 1 ,retrying in 5 seconds Nov 05 10:35:27 volumio volumio[10351]: info: Starting Udev Watcher for removable devices Nov 05 10:35:27 volumio volumio[10351]: info: Ignoring mount for partition: boot Nov 05 10:35:27 volumio volumio[10351]: info: Ignoring mount for partition: volumio Nov 05 10:35:27 volumio volumio[10351]: info: Ignoring mount for partition: volumio_data Nov 05 10:35:27 volumio volumio[10351]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Nov 05 10:35:27 volumio volumio[10351]: info: Loading plugin "volumio_command_line_client"... Nov 05 10:35:27 volumio volumio[10351]: info: Loading plugin "upnp"... Nov 05 10:35:27 volumio volumio[10351]: info: [1762338927313] Starting Upmpd Daemon Nov 05 10:35:27 volumio volumio[10351]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Nov 05 10:35:27 volumio volumio[10351]: info: Loading plugin "my_music"... Nov 05 10:35:27 volumio volumio[10351]: info: Loading plugin "mpd"... Nov 05 10:35:27 volumio volumio[10351]: info: Loading plugin "upnp_browser"... Nov 05 10:35:27 volumio volumio[10351]: info: Loading plugin "alarm-clock"... Nov 05 10:35:27 volumio volumio[10351]: info: Loading plugin "airplay_emulation"... Nov 05 10:35:27 volumio volumio[10351]: info: Starting Shairport Sync Nov 05 10:35:27 volumio volumio[10351]: info: Loading plugin "last_100"... Nov 05 10:35:27 volumio volumio[10351]: info: Loading plugin "webradio"... Nov 05 10:35:27 volumio volumio[10351]: info: Loading plugin "i2s_dacs"... Nov 05 10:35:27 volumio volumio[10351]: info: I2S DAC not set, start Auto-detection Nov 05 10:35:27 volumio volumio[10351]: info: Loading plugin "volumiodiscovery"... Nov 05 10:35:27 volumio volumio[10351]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Nov 05 10:35:27 volumio volumio[10351]: *** WARNING *** Please fix your application to use the native API of Avahi! Nov 05 10:35:27 volumio volumio[10351]: *** WARNING *** For more information see Nov 05 10:35:27 volumio volumio[10351]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Nov 05 10:35:27 volumio volumio[10351]: *** WARNING *** Please fix your application to use the native API of Avahi! Nov 05 10:35:27 volumio volumio[10351]: *** WARNING *** For more information see Nov 05 10:35:27 volumio node[10351]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Nov 05 10:35:27 volumio node[10351]: *** WARNING *** Please fix your application to use the native API of Avahi! Nov 05 10:35:27 volumio node[10351]: *** WARNING *** For more information see Nov 05 10:35:27 volumio node[10351]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Nov 05 10:35:27 volumio node[10351]: *** WARNING *** Please fix your application to use the native API of Avahi! Nov 05 10:35:27 volumio node[10351]: *** WARNING *** For more information see Nov 05 10:35:27 volumio volumio[10351]: info: Applying required configuration parameters for plugin volumiodiscovery Nov 05 10:35:27 volumio volumio[10351]: info: Discovery: Started advertising with name: Volumio Nov 05 10:35:27 volumio volumio[10351]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Nov 05 10:35:27 volumio volumio[10351]: info: Loading plugin "spop"... Nov 05 10:35:27 volumio volumio[10351]: info: Loading plugin "ytcr"... Nov 05 10:35:28 volumio volumio[10351]: info: Loading plugin "outputs"... Nov 05 10:35:28 volumio volumio[10351]: info: Loading plugin "albumart"... Nov 05 10:35:28 volumio volumio[10351]: info: Plugin example_plugin is not enabled Nov 05 10:35:28 volumio volumio[10351]: info: Loading plugin "inputs"... Nov 05 10:35:28 volumio volumio[10351]: info: Loading plugin "updater_comm"... Nov 05 10:35:28 volumio volumio[10351]: info: Plugin mpdemulation is not enabled Nov 05 10:35:28 volumio volumio[10351]: info: Loading plugin "rest_api"... Nov 05 10:35:28 volumio volumio[10351]: info: Loading plugin "websocket"... Nov 05 10:35:28 volumio volumio[10351]: info: Starting Socket.io Server version 1.7.4 Nov 05 10:35:28 volumio volumio[10351]: info: Loading plugin "Systeminfo"... Nov 05 10:35:28 volumio volumio[10351]: info: Loading i18n strings for locale en Nov 05 10:35:28 volumio volumio[10351]: Updating browse sources language Nov 05 10:35:28 volumio volumio[10351]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 05 10:35:28 volumio volumio[10411]: Forking 3 albumart workers Nov 05 10:35:28 volumio volumio[10351]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Nov 05 10:35:28 volumio volumio[10351]: info: CoreCommandRouter::initPlayerControls Nov 05 10:35:28 volumio volumio[10351]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 05 10:35:28 volumio volumio[10351]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 05 10:35:28 volumio volumio[10351]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 05 10:35:28 volumio volumio[10351]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 05 10:35:28 volumio volumio[10351]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 05 10:35:28 volumio volumio[10351]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 05 10:35:28 volumio volumio[10351]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 05 10:35:28 volumio volumio[10351]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 05 10:35:28 volumio volumio[10351]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Nov 05 10:35:28 volumio volumio[10351]: Express server listening on port 3000 Nov 05 10:35:28 volumio volumio[10351]: [Metrics] WebUI: 1s 946.98ms Nov 05 10:35:28 volumio volumio[10351]: info: CoreStateMachine::resetVolumioState Nov 05 10:35:28 volumio volumio[10351]: info: CoreStateMachine::getcurrentVolume Nov 05 10:35:28 volumio volumio[10351]: info: CoreCommandRouter::volumioRetrievevolume Nov 05 10:35:28 volumio volumio[10351]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 05 10:35:28 volumio volumio[10351]: info: Cannot read play queue from file Nov 05 10:35:28 volumio volumio[10351]: info: Volumio Network Manager: Network status updated: 1 Nov 05 10:35:28 volumio volumio[10351]: info: VolumeController:: Volume=33 Mute =false Nov 05 10:35:28 volumio volumio[10351]: info: CoreStateMachine::pushState Nov 05 10:35:28 volumio volumio[10351]: info: CorePlayQueue::getTrack 0 Nov 05 10:35:28 volumio volumio[10351]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 05 10:35:28 volumio volumio[10351]: info: CoreCommandRouter::volumioPushState Nov 05 10:35:28 volumio volumio[10351]: info: CoreStateMachine::updateTrackBlock Nov 05 10:35:28 volumio volumio[10351]: info: CorePlayQueue::getTrackBlock Nov 05 10:35:28 volumio volumio[10351]: info: CoreCommandRouter::volumioRetrievevolume Nov 05 10:35:28 volumio volumio[10351]: info: CoreStateMachine::setRepeat null single undefined Nov 05 10:35:28 volumio volumio[10351]: info: CoreStateMachine::pushState Nov 05 10:35:28 volumio volumio[10351]: info: CorePlayQueue::getTrack 0 Nov 05 10:35:28 volumio volumio[10351]: info: CoreCommandRouter::volumioPushState Nov 05 10:35:28 volumio volumio[10351]: info: CoreStateMachine::setRandom null Nov 05 10:35:28 volumio volumio[10351]: info: CoreStateMachine::pushState Nov 05 10:35:28 volumio volumio[10351]: info: CorePlayQueue::getTrack 0 Nov 05 10:35:28 volumio volumio[10351]: info: CoreCommandRouter::volumioPushState Nov 05 10:35:28 volumio volumio[10351]: info: Setting Device type: Raspberry PI Nov 05 10:35:28 volumio volumio[10351]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Nov 05 10:35:28 volumio volumio[10351]: info: USB Boot Capable - System SBC Revision found in cpuinfo: b04170 Nov 05 10:35:28 volumio volumio[10351]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Nov 05 10:35:28 volumio volumio[10351]: info: VolumeController:: Volume=33 Mute =false Nov 05 10:35:28 volumio volumio[10351]: info: CoreStateMachine::pushState Nov 05 10:35:28 volumio volumio[10351]: info: CorePlayQueue::getTrack 0 Nov 05 10:35:28 volumio volumio[10351]: info: CoreCommandRouter::volumioPushState Nov 05 10:35:28 volumio volumio[10351]: info: Completed loading Core Plugins Nov 05 10:35:28 volumio volumio[10351]: info: Preparing to generate the ALSA configuration file Nov 05 10:35:28 volumio volumio[10351]: info: Discovery: adding 70853f74-8210-4683-a3fa-e1217517bd40 Nov 05 10:35:28 volumio volumio[10351]: info: Discovery: Found device Volumio Nov 05 10:35:28 volumio volumio[10351]: info: CoreCommandRouter::volumioGetState Nov 05 10:35:28 volumio volumio[10351]: info: CorePlayQueue::getTrack 0 Nov 05 10:35:28 volumio volumio[10351]: info: Asound.conf file unchanged, so no further update is needed Nov 05 10:35:28 volumio volumio[10351]: info: Output device has changed, restarting MPD Nov 05 10:35:28 volumio sudo[10468]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Nov 05 10:35:28 volumio volumio[10351]: info: Output device has changed, restarting Shairport Sync Nov 05 10:35:28 volumio volumio[10351]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 05 10:35:28 volumio volumio[10351]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 05 10:35:28 volumio sudo[10468]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 05 10:35:28 volumio sudo[10468]: pam_unix(sudo:session): session closed for user root Nov 05 10:35:28 volumio volumio[10351]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Nov 05 10:35:28 volumio volumio[10351]: info: ___________ START PLUGINS ___________ Nov 05 10:35:28 volumio volumio[10351]: info: ControllerMpd::onStart: Initializing MPD Nov 05 10:35:28 volumio volumio[10351]: info: Creating MPD Configuration file Nov 05 10:35:28 volumio sudo[10470]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Nov 05 10:35:28 volumio sudo[10470]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 05 10:35:28 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 97. Nov 05 10:35:28 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Nov 05 10:35:28 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Nov 05 10:35:28 volumio go-librespot[10478]: go-librespot daemon starting... Nov 05 10:35:28 volumio volumio[10351]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Nov 05 10:35:28 volumio volumio[10351]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Nov 05 10:35:28 volumio volumio[10351]: info: [1762338928970] CoreMusicLibrary::Adding element Media Servers Nov 05 10:35:28 volumio volumio[10351]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 05 10:35:28 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Nov 05 10:35:28 volumio go-librespot[10482]: time="2025-11-05T10:35:28Z" level=info msg="running go-librespot 0.4.0" Nov 05 10:35:28 volumio go-librespot[10482]: time="2025-11-05T10:35:28Z" level=debug msg="app state loaded" Nov 05 10:35:28 volumio go-librespot[10482]: time="2025-11-05T10:35:28Z" level=info msg="api server listening on 127.0.0.1:9879" Nov 05 10:35:28 volumio sudo[10481]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Nov 05 10:35:28 volumio volumio[10351]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 05 10:35:28 volumio volumio[10351]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 05 10:35:28 volumio sudo[10481]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 05 10:35:28 volumio sudo[10479]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Nov 05 10:35:28 volumio systemd[1]: mpd.service: Deactivated successfully. Nov 05 10:35:28 volumio sudo[10479]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 05 10:35:28 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Nov 05 10:35:28 volumio systemd[1]: mpd.socket: Deactivated successfully. Nov 05 10:35:28 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Nov 05 10:35:28 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Nov 05 10:35:29 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Nov 05 10:35:29 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Nov 05 10:35:29 volumio sudo[10479]: pam_unix(sudo:session): session closed for user root Nov 05 10:35:29 volumio volumio[10351]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Nov 05 10:35:29 volumio volumio[10351]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 05 10:35:29 volumio volumio[10351]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 05 10:35:29 volumio systemd[1]: mpd.service: Deactivated successfully. Nov 05 10:35:29 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Nov 05 10:35:29 volumio systemd[1]: mpd.socket: Deactivated successfully. Nov 05 10:35:29 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Nov 05 10:35:29 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Nov 05 10:35:29 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Nov 05 10:35:29 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Nov 05 10:35:29 volumio volumio[10351]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Nov 05 10:35:29 volumio volumio[10351]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Nov 05 10:35:29 volumio volumio[10351]: info: [1762338929071] CoreMusicLibrary::Adding element Last_100 Nov 05 10:35:29 volumio volumio[10351]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 05 10:35:29 volumio volumio[10351]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Nov 05 10:35:29 volumio volumio[10351]: info: [1762338929071] CoreMusicLibrary::Adding element Webradio Nov 05 10:35:29 volumio volumio[10351]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 05 10:35:29 volumio volumio[10351]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Nov 05 10:35:29 volumio volumio[10351]: info: Initializing BBC Radios Nov 05 10:35:29 volumio go-librespot[10482]: time="2025-11-05T10:35: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-gae2.spotify.com:80]" Nov 05 10:35:29 volumio go-librespot[10482]: time="2025-11-05T10:35:29Z" 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]" Nov 05 10:35:29 volumio go-librespot[10482]: time="2025-11-05T10:35:29Z" 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]" Nov 05 10:35:29 volumio go-librespot[10482]: time="2025-11-05T10:35:29Z" level=info msg="zeroconf server listening on port 35427" Nov 05 10:35:29 volumio volumio[10351]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Nov 05 10:35:29 volumio volumio[10351]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 05 10:35:29 volumio sudo[10497]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Nov 05 10:35:29 volumio sudo[10497]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Nov 05 10:35:29 volumio sudo[10497]: pam_unix(sudo:session): session closed for user root Nov 05 10:35:29 volumio volumio[10351]: info: Creating Spotify config file Nov 05 10:35:29 volumio volumio[10351]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 05 10:35:29 volumio go-librespot[10482]: time="2025-11-05T10:35:29Z" level=debug msg="obtained new client token: AACyKonHQjOWa+HDeLck0FAVu6CZe0iXCsg07sxK+1uk6fdH2wRDS5eCGVlihhGEl7irGry/v9dvmjwBiIFVYIBWKYIzZVF2qeugbscpFvEAsr1zI0MQeh2+6skYfNAxj8qP8nIAQTkAsYhPnkn7lN+i4VslGNricp4mnze6y2zwD8sl5+k8yKEE9e9Hg8FcAjYmPlK8wUP72YU8lNx3q0705x7+wc9xgzD1AIxpDfwCT0qOSp9w" Nov 05 10:35:29 volumio go-librespot[10482]: time="2025-11-05T10:35:29Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Nov 05 10:35:29 volumio volumio[10351]: info: Volumio Calling Home Nov 05 10:35:29 volumio volumio[10423]: Starting albumart workers Nov 05 10:35:29 volumio go-librespot[10482]: time="2025-11-05T10:35:29Z" level=debug msg="completed keyexchange" Nov 05 10:35:29 volumio go-librespot[10482]: time="2025-11-05T10:35:29Z" level=debug msg="completed challenge" Nov 05 10:35:29 volumio volumio[10422]: Starting albumart workers Nov 05 10:35:29 volumio volumio[10421]: Starting albumart workers Nov 05 10:35:29 volumio go-librespot[10482]: time="2025-11-05T10:35:29Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Nov 05 10:35:29 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 05 10:35:29 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 05 10:35:29 volumio volumio[10351]: info: Discovery: this is already registered, 70853f74-8210-4683-a3fa-e1217517bd40 Nov 05 10:35:29 volumio volumio[10351]: info: Discovery: Found device Volumio Nov 05 10:35:29 volumio volumio[10351]: info: CoreCommandRouter::volumioGetState Nov 05 10:35:29 volumio volumio[10351]: info: CorePlayQueue::getTrack 0 Nov 05 10:35:29 volumio volumio[10351]: info: MPD Permissions set Nov 05 10:35:29 volumio volumio[10351]: info: MPD Permissions set Nov 05 10:35:29 volumio volumio[10351]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 1 Nov 05 10:35:29 volumio volumio[10351]: info: Volumio called home Nov 05 10:35:29 volumio volumio[10351]: info: Spotify config file written Nov 05 10:35:29 volumio sudo[10523]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Nov 05 10:35:29 volumio sudo[10523]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 05 10:35:29 volumio volumio[10351]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 05 10:35:29 volumio volumio[10351]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 05 10:35:29 volumio volumio[10351]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 05 10:35:29 volumio volumio[10351]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 05 10:35:29 volumio volumio[10351]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 05 10:35:29 volumio volumio[10351]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 05 10:35:29 volumio volumio[10351]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 05 10:35:29 volumio volumio[10351]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 05 10:35:29 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Nov 05 10:35:29 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Nov 05 10:35:29 volumio go-librespot[10530]: go-librespot daemon starting... Nov 05 10:35:29 volumio volumio[10351]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 05 10:35:29 volumio volumio[10351]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 05 10:35:29 volumio volumio[10351]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 05 10:35:29 volumio sudo[10523]: pam_unix(sudo:session): session closed for user root Nov 05 10:35:29 volumio volumio[10351]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 05 10:35:29 volumio volumio[10351]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 05 10:35:29 volumio go-librespot[10531]: time="2025-11-05T10:35:29Z" level=info msg="running go-librespot 0.4.0" Nov 05 10:35:29 volumio volumio[10351]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 05 10:35:29 volumio volumio[10351]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 05 10:35:29 volumio volumio[10351]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 05 10:35:29 volumio volumio[10351]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 05 10:35:29 volumio volumio[10351]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 05 10:35:29 volumio go-librespot[10531]: time="2025-11-05T10:35:29Z" level=debug msg="app state loaded" Nov 05 10:35:29 volumio go-librespot[10531]: time="2025-11-05T10:35:29Z" level=info msg="api server listening on 127.0.0.1:9879" Nov 05 10:35:29 volumio volumio[10351]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 05 10:35:29 volumio volumio[10351]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 05 10:35:29 volumio volumio[10351]: info: No need to fix Spotify hosts Nov 05 10:35:29 volumio go-librespot[10531]: time="2025-11-05T10:35: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-gae2.spotify.com:80]" Nov 05 10:35:29 volumio volumio[10351]: info: Starting Shairport Sync Nov 05 10:35:29 volumio go-librespot[10531]: time="2025-11-05T10:35:29Z" 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]" Nov 05 10:35:29 volumio go-librespot[10531]: time="2025-11-05T10:35:29Z" 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]" Nov 05 10:35:29 volumio mpd[10518]: 2025-11-05T10:35:29 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Nov 05 10:35:29 volumio systemd[1]: Started mpd.service - Music Player Daemon. Nov 05 10:35:29 volumio volumio[10351]: info: Starting Shairport Sync Nov 05 10:35:29 volumio go-librespot[10531]: time="2025-11-05T10:35:29Z" level=info msg="zeroconf server listening on port 42951" Nov 05 10:35:29 volumio volumio[10351]: info: Starting Shairport Sync Nov 05 10:35:29 volumio sudo[10564]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Nov 05 10:35:29 volumio sudo[10564]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 05 10:35:29 volumio sudo[10470]: pam_unix(sudo:session): session closed for user root Nov 05 10:35:29 volumio sudo[10481]: pam_unix(sudo:session): session closed for user root Nov 05 10:35:29 volumio sudo[10569]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Nov 05 10:35:29 volumio sudo[10569]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 05 10:35:29 volumio sudo[10568]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Nov 05 10:35:29 volumio sudo[10568]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 05 10:35:29 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Nov 05 10:35:29 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Nov 05 10:35:29 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Nov 05 10:35:29 volumio systemd[1]: shairport-sync.service: Consumed 1.626s CPU time. Nov 05 10:35:29 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Nov 05 10:35:29 volumio sudo[10564]: pam_unix(sudo:session): session closed for user root Nov 05 10:35:29 volumio sudo[10568]: pam_unix(sudo:session): session closed for user root Nov 05 10:35:29 volumio sudo[10569]: pam_unix(sudo:session): session closed for user root Nov 05 10:35:29 volumio volumio[10351]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Nov 05 10:35:29 volumio volumio[10351]: SPOTIFY: BQA65kAwPC0SCeKsrfwcxxiTpob9sJv5F9F2LCXRO-m2MJofBzjphv_bceI0gxMoLhmQyRqop8go0IdaA8e8mICZTl22wbbTYIZTUPPPKsLWkZkk3NMBUKEv-5fEgUzgnUK84OGEHwsuIUh2OlcxyLZsK54TFkFtUD2CkRy2Klwo1e3cj0Zx0vJZeMRJQxQ9AgW2GdU-3e40cJ6J8qo4ldlWaOcm50Y3Qmg-VIlbrv34pHUn4PA5YsSYq0cLbpwzPYMizYteka5Qi00lHUJ_BmQgSPDtq0v5pVfu_-J4DmJXsPLxEjIggPkD Nov 05 10:35:29 volumio volumio[10351]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Nov 05 10:35:29 volumio volumio[10351]: info: New Spotify access token = BQA65kAwPC0SCeKsrfwcxxiTpob9sJv5F9F2LCXRO-m2MJofBzjphv_bceI0gxMoLhmQyRqop8go0IdaA8e8mICZTl22wbbTYIZTUPPPKsLWkZkk3NMBUKEv-5fEgUzgnUK84OGEHwsuIUh2OlcxyLZsK54TFkFtUD2CkRy2Klwo1e3cj0Zx0vJZeMRJQxQ9AgW2GdU-3e40cJ6J8qo4ldlWaOcm50Y3Qmg-VIlbrv34pHUn4PA5YsSYq0cLbpwzPYMizYteka5Qi00lHUJ_BmQgSPDtq0v5pVfu_-J4DmJXsPLxEjIggPkD Nov 05 10:35:29 volumio volumio[10351]: info: Spotify credentials grant success - running version from March 24, 2019 Nov 05 10:35:29 volumio go-librespot[10531]: time="2025-11-05T10:35:29Z" level=debug msg="obtained new client token: AABaJ6SyQ8jNxa66gUEJ1hz3AfU8KsuxTqm3kSHv7yMV50+VUcOQopeko4Wyd5tk3b1HaQUJeq/btt7FOLqmreukZAJD6U/NFh3TVC8bgYzG2E6ZkDQZvcq4l9MahQAo4Hm2G1kDMSz328lyWun36PiihLYoYfaSVqJdiUfEFN8xuvH6KD3Ip3BbTVIlNBiGDMJBJtBaW1RzdmYGj5NGUYXOgEtwYvCXiaQyAYE9hXzarD592139r/8=" Nov 05 10:35:29 volumio volumio[10351]: error: MPD error: The expression evaluated to a falsy value: Nov 05 10:35:29 volumio volumio[10351]: assert.ok(self.idling) Nov 05 10:35:29 volumio volumio[10351]: error: The expression evaluated to a falsy value: Nov 05 10:35:29 volumio volumio[10351]: assert.ok(self.idling) Nov 05 10:35:29 volumio volumio[10351]: info: Shairport-Sync Started Nov 05 10:35:29 volumio volumio[10351]: Error adding Membership: Error: addMembership EINVAL Nov 05 10:35:29 volumio volumio[10351]: info: Shairport-Sync Started Nov 05 10:35:29 volumio volumio[10351]: info: Shairport-Sync Started Nov 05 10:35:29 volumio volumio[10351]: info: MPD running with PID10518 Nov 05 10:35:29 volumio volumio[10351]: ,establishing connection Nov 05 10:35:29 volumio volumio[10351]: error: updateQueue error: null Nov 05 10:35:29 volumio volumio[10351]: info: CoreCommandRouter::volumioGetState Nov 05 10:35:29 volumio volumio[10351]: info: CorePlayQueue::getTrack 0 Nov 05 10:35:29 volumio go-librespot[10531]: time="2025-11-05T10:35:29Z" 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" Nov 05 10:35:29 volumio volumio[10351]: error: updateQueue error: null Nov 05 10:35:29 volumio go-librespot[10531]: time="2025-11-05T10:35:29Z" level=debug msg="connected to ap-gew1.spotify.com:443" Nov 05 10:35:29 volumio go-librespot[10531]: time="2025-11-05T10:35:29Z" level=debug msg="completed keyexchange" Nov 05 10:35:29 volumio go-librespot[10531]: time="2025-11-05T10:35:29Z" level=debug msg="completed challenge" Nov 05 10:35:29 volumio go-librespot[10531]: time="2025-11-05T10:35:29Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Nov 05 10:35:29 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 05 10:35:29 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 05 10:35:29 volumio volumio[10351]: 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"} Nov 05 10:35:29 volumio volumio[10351]: info: Spotify Successfully logged in Nov 05 10:35:29 volumio volumio[10351]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Nov 05 10:35:29 volumio volumio[10351]: info: [1762338929958] CoreMusicLibrary::Adding element Spotify Nov 05 10:35:29 volumio volumio[10351]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 05 10:35:29 volumio volumio[10351]: Cannot find translation for source Spotify Nov 05 10:35:30 volumio volumio[10351]: info: [yt-cast-receiver] DIAL server listening on port 8098 Nov 05 10:35:30 volumio volumio[10351]: info: CoreCommandRouter::volumioRetrievevolume Nov 05 10:35:30 volumio volumio[10351]: info: VolumeController:: Volume=33 Mute =false Nov 05 10:35:30 volumio volumio[10351]: info: CoreCommandRouter::volumioGetState Nov 05 10:35:30 volumio volumio[10351]: info: CorePlayQueue::getTrack 0 Nov 05 10:35:30 volumio volumio[10351]: info: CoreStateMachine::pushState Nov 05 10:35:30 volumio volumio[10351]: info: CorePlayQueue::getTrack 0 Nov 05 10:35:30 volumio volumio[10351]: info: CoreCommandRouter::volumioPushState Nov 05 10:35:30 volumio volumio[10351]: info: Completed starting Core Plugins Nov 05 10:35:30 volumio volumio[10351]: info: ------------------------------------------- Nov 05 10:35:30 volumio volumio[10351]: info: ----- MyVolumio plugins startup ---- Nov 05 10:35:30 volumio volumio[10351]: info: ------------------------------------------- Nov 05 10:35:30 volumio volumio[10351]: info: [MyVolumio PluginManager] Fetching plans data.... Nov 05 10:35:31 volumio volumio-remote-updater[874]: [2025-11-05 10:35:31] [connect] Successful connection Nov 05 10:35:31 volumio volumio-remote-updater[874]: [2025-11-05 10:35:31] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1762338931 101 Nov 05 10:35:31 volumio volumio[10351]: 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 Nov 05 10:35:32 volumio volumio[10351]: info: Cannot mount NAS NAS at system boot, trial number 2 ,retrying in 5 seconds Nov 05 10:35:32 volumio volumio[10351]: info: go-librespot daemon successfully initialized Nov 05 10:35:32 volumio sudo[10593]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Nov 05 10:35:32 volumio sudo[10593]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 05 10:35:32 volumio sudo[10595]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Nov 05 10:35:32 volumio sudo[10595]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 05 10:35:32 volumio systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Nov 05 10:35:32 volumio systemd[1]: mpd_monitor.service: Deactivated successfully. Nov 05 10:35:32 volumio systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Nov 05 10:35:32 volumio systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Nov 05 10:35:32 volumio sudo[10593]: pam_unix(sudo:session): session closed for user root Nov 05 10:35:32 volumio mpd_monitor.sh[10598]: MPD Monitor Service: Starting MPD Monitor Service Nov 05 10:35:32 volumio sudo[10595]: pam_unix(sudo:session): session closed for user root Nov 05 10:35:32 volumio volumio[10351]: info: Successfully started MPD Monitor Nov 05 10:35:32 volumio volumio[10351]: info: Successfully started MPD Monitor Nov 05 10:35:33 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 98. Nov 05 10:35:33 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Nov 05 10:35:33 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Nov 05 10:35:33 volumio go-librespot[10603]: go-librespot daemon starting... Nov 05 10:35:33 volumio go-librespot[10604]: time="2025-11-05T10:35:33Z" level=info msg="running go-librespot 0.4.0" Nov 05 10:35:33 volumio go-librespot[10604]: time="2025-11-05T10:35:33Z" level=debug msg="app state loaded" Nov 05 10:35:33 volumio go-librespot[10604]: time="2025-11-05T10:35:33Z" level=info msg="api server listening on 127.0.0.1:9879" Nov 05 10:35:33 volumio go-librespot[10604]: time="2025-11-05T10:35:33Z" 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]" Nov 05 10:35:33 volumio go-librespot[10604]: time="2025-11-05T10:35:33Z" 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]" Nov 05 10:35:33 volumio go-librespot[10604]: time="2025-11-05T10:35:33Z" 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]" Nov 05 10:35:33 volumio go-librespot[10604]: time="2025-11-05T10:35:33Z" level=info msg="zeroconf server listening on port 39569" Nov 05 10:35:33 volumio go-librespot[10604]: time="2025-11-05T10:35:33Z" level=debug msg="obtained new client token: AABY8H6WAFf1YoUSdCDC1cGjkI7XO6VkBnZKyokUOXYM0oQghathi0RcMSJ0DzHPF4r7y/4a5dz0OIQeanKfUM++PEmTOJHlWoBoVMezkxLtK3bYHas/fz+NeAkUhhcPOsHekV9O1SuLwWC4foxt6yStDZEcFZZMze5evrcVJ7ODpAsHhc73qxB6vNaqeZj/93fZzfSCJPD7ph12sPQXSO+m8F/F0CT0HBv2RsPLJoUVsSiekdqD" Nov 05 10:35:33 volumio go-librespot[10604]: time="2025-11-05T10:35:33Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Nov 05 10:35:33 volumio go-librespot[10604]: time="2025-11-05T10:35:33Z" level=debug msg="completed keyexchange" Nov 05 10:35:33 volumio go-librespot[10604]: time="2025-11-05T10:35:33Z" level=debug msg="completed challenge" Nov 05 10:35:33 volumio go-librespot[10604]: time="2025-11-05T10:35:33Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Nov 05 10:35:33 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 05 10:35:33 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 05 10:35:34 volumio volumio[10351]: info: CoreCommandRouter::volumioGetState Nov 05 10:35:34 volumio volumio[10351]: info: CorePlayQueue::getTrack 0 Nov 05 10:35:34 volumio volumio[10351]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Nov 05 10:35:35 volumio volumio[10351]: info: Initializing connection to go-librespot Websocket Nov 05 10:35:35 volumio volumio[10351]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 05 10:35:36 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 99. Nov 05 10:35:36 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Nov 05 10:35:36 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Nov 05 10:35:36 volumio go-librespot[10611]: go-librespot daemon starting... Nov 05 10:35:36 volumio go-librespot[10612]: time="2025-11-05T10:35:36Z" level=info msg="running go-librespot 0.4.0" Nov 05 10:35:36 volumio go-librespot[10612]: time="2025-11-05T10:35:36Z" level=debug msg="app state loaded" Nov 05 10:35:36 volumio go-librespot[10612]: time="2025-11-05T10:35:36Z" level=info msg="api server listening on 127.0.0.1:9879" Nov 05 10:35:36 volumio go-librespot[10612]: time="2025-11-05T10:35: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]" Nov 05 10:35:36 volumio go-librespot[10612]: time="2025-11-05T10:35: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]" Nov 05 10:35:36 volumio go-librespot[10612]: time="2025-11-05T10:35: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]" Nov 05 10:35:36 volumio go-librespot[10612]: time="2025-11-05T10:35:36Z" level=info msg="zeroconf server listening on port 42049" Nov 05 10:35:36 volumio go-librespot[10612]: time="2025-11-05T10:35:36Z" level=debug msg="obtained new client token: AAB2JQDMqF2YFxhUjdpK03zo8Zvs+CmzzqJvy/mhBVuNePnC1ChKz0kINHLDKVk3K8g0nryGfPAnEwwGLll6q2YY4Vgi+xIQzzDIBG4gxtklTzP2VTd0APCOA+w8Sw26eWTbVTcvDsshRro+wt6wKra91fi8i81eUotkQlvamxSrzt/RaQOhOYiAiF5ireq6741aIkqD+G8e8IiGcaOYxEDhJmYNM6OXmh4piebh2Q1710EziADCFcY=" Nov 05 10:35:36 volumio go-librespot[10612]: time="2025-11-05T10:35:36Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Nov 05 10:35:36 volumio go-librespot[10612]: time="2025-11-05T10:35:36Z" level=debug msg="completed keyexchange" Nov 05 10:35:36 volumio go-librespot[10612]: time="2025-11-05T10:35:36Z" level=debug msg="completed challenge" Nov 05 10:35:36 volumio go-librespot[10612]: time="2025-11-05T10:35:36Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Nov 05 10:35:36 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 05 10:35:36 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 05 10:35:37 volumio volumio[10351]: info: Cannot mount NAS NAS at system boot, trial number 3 ,retrying in 5 seconds Nov 05 10:35:37 volumio sudo[10634]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Nov 05 10:35:37 volumio sudo[10634]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 05 10:35:37 volumio sudo[10636]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Nov 05 10:35:37 volumio sudo[10636]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 05 10:35:37 volumio sudo[10634]: pam_unix(sudo:session): session closed for user root Nov 05 10:35:37 volumio sudo[10636]: pam_unix(sudo:session): session closed for user root Nov 05 10:35:37 volumio sudo[10640]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Nov 05 10:35:37 volumio sudo[10640]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 05 10:35:37 volumio sudo[10640]: pam_unix(sudo:session): session closed for user root Nov 05 10:35:37 volumio volumio[10351]: info: Upmpdcli Daemon Started Nov 05 10:35:38 volumio volumio[10351]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Nov 05 10:35:38 volumio volumio[10351]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Nov 05 10:35:38 volumio volumio[10351]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Nov 05 10:35:38 volumio volumio[10351]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Nov 05 10:35:38 volumio volumio[10351]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Nov 05 10:35:38 volumio volumio[10351]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Nov 05 10:35:38 volumio volumio[10351]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Nov 05 10:35:38 volumio volumio[10351]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Nov 05 10:35:38 volumio volumio[10351]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Nov 05 10:35:38 volumio volumio[10351]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Nov 05 10:35:38 volumio volumio[10351]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Nov 05 10:35:38 volumio volumio[10351]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Nov 05 10:35:38 volumio volumio[10351]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Nov 05 10:35:38 volumio volumio[10351]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Nov 05 10:35:38 volumio volumio[10351]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Nov 05 10:35:38 volumio volumio[10351]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Nov 05 10:35:38 volumio volumio[10351]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Nov 05 10:35:38 volumio volumio[10351]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Nov 05 10:35:38 volumio volumio[10351]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Nov 05 10:35:38 volumio volumio[10351]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Nov 05 10:35:38 volumio volumio[10351]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Nov 05 10:35:38 volumio volumio[10351]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Nov 05 10:35:38 volumio volumio[10351]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Nov 05 10:35:38 volumio volumio[10351]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Nov 05 10:35:38 volumio volumio[10351]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Nov 05 10:35:38 volumio volumio[10351]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Nov 05 10:35:38 volumio volumio[10351]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Nov 05 10:35:38 volumio volumio[10351]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Nov 05 10:35:38 volumio volumio[10351]: info: Adding plugin bluetooth to MyMusic Plugins Nov 05 10:35:38 volumio volumio[10351]: info: Adding plugin multiroom to MyMusic Plugins Nov 05 10:35:38 volumio volumio[10351]: info: Adding plugin metavolumio to MyMusic Plugins Nov 05 10:35:38 volumio volumio[10351]: info: Adding plugin cd_controller to MyMusic Plugins Nov 05 10:35:38 volumio volumio[10351]: info: Adding plugin qobuzconnect to MyMusic Plugins Nov 05 10:35:38 volumio volumio[10351]: info: Adding plugin smart_inputs to MyMusic Plugins Nov 05 10:35:38 volumio volumio[10351]: info: Adding plugin tidalconnect to MyMusic Plugins Nov 05 10:35:38 volumio volumio[10351]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Nov 05 10:35:38 volumio volumio[10351]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Nov 05 10:35:38 volumio volumio[10351]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Nov 05 10:35:38 volumio volumio[10351]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 05 10:35:38 volumio volumio[10351]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 05 10:35:38 volumio volumio[10351]: info: Starting MyVolumio Remote Streaming Endpoints Nov 05 10:35:38 volumio volumio[10351]: info: MyVolumio login type: Token Nov 05 10:35:38 volumio volumio[10351]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Nov 05 10:35:38 volumio volumio[10351]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Nov 05 10:35:38 volumio volumio[10351]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Nov 05 10:35:38 volumio volumio[10351]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Nov 05 10:35:38 volumio volumio[10351]: info: Streaming services startup Nov 05 10:35:38 volumio volumio[10351]: info: Starting Streaming Daemon Nov 05 10:35:38 volumio sudo[10643]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Nov 05 10:35:38 volumio sudo[10643]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 05 10:35:38 volumio volumio[10351]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Nov 05 10:35:38 volumio sudo[10643]: pam_unix(sudo:session): session closed for user root Nov 05 10:35:38 volumio volumio[10351]: info: Initializing connection to go-librespot Websocket Nov 05 10:35:38 volumio volumio[10351]: error: Cannot start Volumio Streaming Daemon Nov 05 10:35:38 volumio volumio[10351]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Nov 05 10:35:38 volumio volumio[10351]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Nov 05 10:35:38 volumio volumio[10351]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 05 10:35:39 volumio volumio[10351]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Nov 05 10:35:39 volumio volumio[10351]: info: MyVolumio token set successfully Nov 05 10:35:39 volumio volumio[10351]: info: MYVOLUMIO: Adding device Nov 05 10:35:39 volumio volumio[10351]: info: MYVOLUMIO: Evaluating Server Nov 05 10:35:39 volumio volumio[10351]: info: MyVolumio status changed Nov 05 10:35:39 volumio volumio[10351]: info: Streaming services startup Nov 05 10:35:39 volumio volumio[10351]: info: Starting Streaming Daemon Nov 05 10:35:39 volumio volumio[10351]: info: Removing browser output: myVolumio user plan is not superstar Nov 05 10:35:39 volumio volumio[10351]: info: Removing audio output: Nov 05 10:35:39 volumio volumio[10351]: info: Stoppping Tunnel 1 Nov 05 10:35:39 volumio sudo[10669]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Nov 05 10:35:39 volumio sudo[10671]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service Nov 05 10:35:39 volumio sudo[10671]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 05 10:35:39 volumio sudo[10669]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 05 10:35:39 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 100. Nov 05 10:35:39 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Nov 05 10:35:39 volumio sudo[10669]: pam_unix(sudo:session): session closed for user root Nov 05 10:35:39 volumio volumio[10351]: error: Cannot start Volumio Streaming Daemon Nov 05 10:35:39 volumio volumio[10351]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Nov 05 10:35:39 volumio volumio[10351]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Nov 05 10:35:39 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Nov 05 10:35:39 volumio go-librespot[10674]: go-librespot daemon starting... Nov 05 10:35: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. Nov 05 10:35: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. Nov 05 10:35: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. Nov 05 10:35: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. Nov 05 10:35:39 volumio go-librespot[10675]: time="2025-11-05T10:35:39Z" level=info msg="running go-librespot 0.4.0" Nov 05 10:35:39 volumio go-librespot[10675]: time="2025-11-05T10:35:39Z" level=debug msg="app state loaded" Nov 05 10:35:39 volumio go-librespot[10675]: time="2025-11-05T10:35:39Z" level=info msg="api server listening on 127.0.0.1:9879" Nov 05 10:35: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. Nov 05 10:35: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. Nov 05 10:35: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. Nov 05 10:35: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. Nov 05 10:35:39 volumio sudo[10671]: pam_unix(sudo:session): session closed for user root Nov 05 10:35:39 volumio volumio[10351]: info: Remote SSH Stopped Nov 05 10:35:40 volumio go-librespot[10675]: time="2025-11-05T10:35:40Z" 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]" Nov 05 10:35:40 volumio go-librespot[10675]: time="2025-11-05T10:35:40Z" 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]" Nov 05 10:35:40 volumio go-librespot[10675]: time="2025-11-05T10:35:40Z" 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]" Nov 05 10:35:40 volumio go-librespot[10675]: time="2025-11-05T10:35:40Z" level=info msg="zeroconf server listening on port 45415" Nov 05 10:35:40 volumio go-librespot[10675]: time="2025-11-05T10:35:40Z" level=debug msg="obtained new client token: AADCeK+JUDtPy32uBnlo4hKwjNJZgjWiIGkDUT1jmak/a/kVKgSSFXlvmYn/2dF1PcH7RgWKcvZH4b7vQzokJvP2lyRi3OOL4yF9IjtZRH6R66msRUwQq3FDauUiZnCZfwadgNv7bDlRiIib1LESyyOnsL+zNp3LmBcEGtmg6Y8p+ZwxqLmbWD3oV0ipOYufNZ5wkWOgD23UkMrT5E4QDcMDbvX8PGYHrmjMV/JKoOEQ98+eJR5s" Nov 05 10:35:40 volumio go-librespot[10675]: time="2025-11-05T10:35:40Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Nov 05 10:35:40 volumio go-librespot[10675]: time="2025-11-05T10:35:40Z" level=debug msg="completed keyexchange" Nov 05 10:35:40 volumio go-librespot[10675]: time="2025-11-05T10:35:40Z" level=debug msg="completed challenge" Nov 05 10:35:40 volumio volumio[10351]: info: Setting Geolocation for MyVolumio to eu3 Nov 05 10:35:40 volumio volumio[10351]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 05 10:35:40 volumio volumio[10351]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 05 10:35:40 volumio volumio[10351]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 05 10:35:40 volumio go-librespot[10675]: time="2025-11-05T10:35:40Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Nov 05 10:35:40 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 05 10:35:40 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 05 10:35:41 volumio volumio[10351]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Nov 05 10:35:41 volumio volumio[10351]: info: Updating MyVolumio device info Nov 05 10:35:41 volumio volumio[10351]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 05 10:35:41 volumio volumio[10351]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 05 10:35:41 volumio volumio[10351]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 05 10:35:41 volumio volumio[10351]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Nov 05 10:35:41 volumio volumio[10351]: info: Initializing connection to go-librespot Websocket Nov 05 10:35:41 volumio volumio[10351]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 05 10:35:42 volumio volumio[10351]: info: Cannot mount NAS NAS at system boot, trial number 4 ,retrying in 5 seconds Nov 05 10:35:43 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 101. Nov 05 10:35:43 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Nov 05 10:35:43 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Nov 05 10:35:43 volumio go-librespot[10682]: go-librespot daemon starting... Nov 05 10:35:43 volumio go-librespot[10683]: time="2025-11-05T10:35:43Z" level=info msg="running go-librespot 0.4.0" Nov 05 10:35:43 volumio go-librespot[10683]: time="2025-11-05T10:35:43Z" level=debug msg="app state loaded" Nov 05 10:35:43 volumio go-librespot[10683]: time="2025-11-05T10:35:43Z" level=info msg="api server listening on 127.0.0.1:9879" Nov 05 10:35:43 volumio go-librespot[10683]: time="2025-11-05T10:35:43Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Nov 05 10:35:43 volumio go-librespot[10683]: time="2025-11-05T10:35:43Z" 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]" Nov 05 10:35:43 volumio go-librespot[10683]: time="2025-11-05T10:35:43Z" 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]" Nov 05 10:35:43 volumio go-librespot[10683]: time="2025-11-05T10:35:43Z" level=info msg="zeroconf server listening on port 39173" Nov 05 10:35:43 volumio go-librespot[10683]: time="2025-11-05T10:35:43Z" level=debug msg="obtained new client token: AADfyEumIIEEqZlVJnaWDlPWcBMGZ5JHXQ2PuyxCUNRj/JTTudFiYpRNZ/ELbPy5hNctgl2yz+IrEQE3X9IwPDX7KfrsbpmpC4wQjXxNTAh5/fAsM9r52JI72ZDudMBiGcBTxsaycw8bDiKtkUa36pJ6q233WXK9M68q1KF/5KBxE1nWnbXiQAa8bPOMi3wA7goUOY/Yn0kat/XOGHGFWa3u3I1htu2r7WZgedNW5h2ojkBrZlJUadI=" Nov 05 10:35:43 volumio go-librespot[10683]: time="2025-11-05T10:35:43Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Nov 05 10:35:43 volumio go-librespot[10683]: time="2025-11-05T10:35:43Z" level=debug msg="completed keyexchange" Nov 05 10:35:43 volumio go-librespot[10683]: time="2025-11-05T10:35:43Z" level=debug msg="completed challenge" Nov 05 10:35:43 volumio go-librespot[10683]: time="2025-11-05T10:35:43Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Nov 05 10:35:43 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 05 10:35:43 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 05 10:35:44 volumio volumio[10351]: info: CoreCommandRouter::volumioGetState Nov 05 10:35:44 volumio volumio[10351]: info: CorePlayQueue::getTrack 0 Nov 05 10:35:44 volumio volumio[10351]: info: Listing playlists Nov 05 10:35:44 volumio volumio[10351]: info: Listing playlists Nov 05 10:35:44 volumio volumio[10351]: info: Initializing connection to go-librespot Websocket Nov 05 10:35:44 volumio volumio[10351]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 05 10:35:45 volumio volumio[10351]: info: MYVOLUMIO: Adding device Nov 05 10:35:45 volumio volumio[10351]: info: MYVOLUMIO: Evaluating Server Nov 05 10:35:45 volumio volumio[10351]: info: Setting Geolocation for MyVolumio to eu3 Nov 05 10:35:45 volumio volumio[10351]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 05 10:35:45 volumio volumio[10351]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 05 10:35:45 volumio volumio[10351]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 05 10:35:45 volumio volumio[10351]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Nov 05 10:35:46 volumio volumio[10351]: info: Updating MyVolumio device info Nov 05 10:35:46 volumio volumio[10351]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 05 10:35:46 volumio volumio[10351]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 05 10:35:46 volumio volumio[10351]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 05 10:35:46 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 102. Nov 05 10:35:46 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Nov 05 10:35:46 volumio volumio[10351]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Nov 05 10:35:46 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Nov 05 10:35:46 volumio go-librespot[10706]: go-librespot daemon starting... Nov 05 10:35:46 volumio go-librespot[10707]: time="2025-11-05T10:35:46Z" level=info msg="running go-librespot 0.4.0" Nov 05 10:35:46 volumio go-librespot[10707]: time="2025-11-05T10:35:46Z" level=debug msg="app state loaded" Nov 05 10:35:46 volumio go-librespot[10707]: time="2025-11-05T10:35:46Z" level=info msg="api server listening on 127.0.0.1:9879" Nov 05 10:35:46 volumio go-librespot[10707]: time="2025-11-05T10:35: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]" Nov 05 10:35:46 volumio go-librespot[10707]: time="2025-11-05T10:35: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]" Nov 05 10:35:46 volumio go-librespot[10707]: time="2025-11-05T10:35: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]" Nov 05 10:35:46 volumio go-librespot[10707]: time="2025-11-05T10:35:46Z" level=info msg="zeroconf server listening on port 37699" Nov 05 10:35:46 volumio go-librespot[10707]: time="2025-11-05T10:35:46Z" level=debug msg="obtained new client token: AAAyD3v/p/rn6oNb2qhRK1xysXw31Yo4rbfqw1y2lfD/k5mU2Iag3gE0D5H/uIdHiYqwYdsLTbR7A7diRa+RNIcxxfaP1yuZWZukSG/PkNdxbKELLy+xiZYisSyW7Wj7eQq241TLKizq/yfxUA5FnrcIDG98vNfCRmudwBQGWq3KSHH72WVBcxh3ULZfARfRVzADdVoHatT9rkFaE+PMOC6WhH0SINqeoU707l0oSUMV3bssepDNnPE=" Nov 05 10:35:46 volumio go-librespot[10707]: time="2025-11-05T10:35:46Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Nov 05 10:35:47 volumio go-librespot[10707]: time="2025-11-05T10:35:47Z" level=debug msg="completed keyexchange" Nov 05 10:35:47 volumio go-librespot[10707]: time="2025-11-05T10:35:47Z" level=debug msg="completed challenge" Nov 05 10:35:47 volumio go-librespot[10707]: time="2025-11-05T10:35:47Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Nov 05 10:35:47 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 05 10:35:47 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 05 10:35:47 volumio volumio[10351]: info: Cannot mount NAS at system boot, trial number 4 ,stopping Nov 05 10:35:47 volumio volumio[10351]: info: Initializing connection to go-librespot Websocket Nov 05 10:35:47 volumio volumio[10351]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 05 10:35:50 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 103. Nov 05 10:35:50 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Nov 05 10:35:50 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Nov 05 10:35:50 volumio go-librespot[10728]: go-librespot daemon starting... Nov 05 10:35:50 volumio go-librespot[10729]: time="2025-11-05T10:35:50Z" level=info msg="running go-librespot 0.4.0" Nov 05 10:35:50 volumio go-librespot[10729]: time="2025-11-05T10:35:50Z" level=debug msg="app state loaded" Nov 05 10:35:50 volumio go-librespot[10729]: time="2025-11-05T10:35:50Z" level=info msg="api server listening on 127.0.0.1:9879" Nov 05 10:35:50 volumio go-librespot[10729]: time="2025-11-05T10:35:50Z" 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]" Nov 05 10:35:50 volumio go-librespot[10729]: time="2025-11-05T10:35:50Z" 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]" Nov 05 10:35:50 volumio go-librespot[10729]: time="2025-11-05T10:35:50Z" 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]" Nov 05 10:35:50 volumio go-librespot[10729]: time="2025-11-05T10:35:50Z" level=info msg="zeroconf server listening on port 34869" Nov 05 10:35:50 volumio go-librespot[10729]: time="2025-11-05T10:35:50Z" level=debug msg="obtained new client token: AABqxdMu3wrKdbwnlf4rnPB22utxDc2mnyJ/BwRXiGVv1eTd7BZ0/oJf9Px17dsS2WTSujVrpFmdCq9rXdidjk4D4susKTJZDzEVgb+OXv1Sxst5l+3Q/cAKxm1vJATE/vln22kZOIv6JBwxm0LbywIxdbv+4yPmZCBmOnyQzWSnx+0//nulS9HRdxo8I8IMZP3Cb9ZErQo7pstQlye1D5ceEF9RoDaNAFTPeenY2FKzgBsTmG7urbk=" Nov 05 10:35:50 volumio go-librespot[10729]: time="2025-11-05T10:35:50Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Nov 05 10:35:50 volumio go-librespot[10729]: time="2025-11-05T10:35:50Z" level=debug msg="completed keyexchange" Nov 05 10:35:50 volumio go-librespot[10729]: time="2025-11-05T10:35:50Z" level=debug msg="completed challenge" Nov 05 10:35:50 volumio go-librespot[10729]: time="2025-11-05T10:35:50Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Nov 05 10:35:50 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 05 10:35:50 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 05 10:35:50 volumio volumio[10351]: info: Initializing connection to go-librespot Websocket Nov 05 10:35:50 volumio volumio[10351]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 05 10:35:53 volumio volumio[10351]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Nov 05 10:35:53 volumio volumio[10351]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Nov 05 10:35:53 volumio volumio[10351]: info: CoreCommandRouter::volumioGetState Nov 05 10:35:53 volumio volumio[10351]: info: CorePlayQueue::getTrack 0 Nov 05 10:35:53 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 104. Nov 05 10:35:53 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Nov 05 10:35:53 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Nov 05 10:35:53 volumio go-librespot[10739]: go-librespot daemon starting... Nov 05 10:35:53 volumio go-librespot[10740]: time="2025-11-05T10:35:53Z" level=info msg="running go-librespot 0.4.0" Nov 05 10:35:53 volumio go-librespot[10740]: time="2025-11-05T10:35:53Z" level=debug msg="app state loaded" Nov 05 10:35:53 volumio go-librespot[10740]: time="2025-11-05T10:35:53Z" level=info msg="api server listening on 127.0.0.1:9879" Nov 05 10:35:53 volumio go-librespot[10740]: time="2025-11-05T10:35: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]" Nov 05 10:35:53 volumio go-librespot[10740]: time="2025-11-05T10:35: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]" Nov 05 10:35:53 volumio go-librespot[10740]: time="2025-11-05T10:35: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]" Nov 05 10:35:53 volumio go-librespot[10740]: time="2025-11-05T10:35:53Z" level=info msg="zeroconf server listening on port 36097" Nov 05 10:35:53 volumio volumio[10351]: info: Initializing connection to go-librespot Websocket Nov 05 10:35:53 volumio go-librespot[10740]: time="2025-11-05T10:35:53Z" level=debug msg="new websocket client" Nov 05 10:35:53 volumio volumio[10351]: info: Connection to go-librespot Websocket established Nov 05 10:35:53 volumio go-librespot[10740]: time="2025-11-05T10:35:53Z" level=debug msg="obtained new client token: AACti391qNfvn7QwD15zSu51KY7D9a+JVLBAyfaT1I9TM5mFq15pbsBkvZaZkCDlkkNDKbHttyI1XkxpPiO2CaXqjNQYGvg4kVfZrkNTR8X3S4VvzdmVDnu6NLOQzapyi+HErpHAfN74Lgp2prjdZBkhKOjcyjpPlZIBZlTWoI+8qvM82x9qoGdEGRVfLgTyOm5ZIkZWF76Y22jC8+0vCr7j0c24eCzLWaLGeLzaL7HP8Zz81pLK97A=" Nov 05 10:35:53 volumio go-librespot[10740]: time="2025-11-05T10:35:53Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Nov 05 10:35:54 volumio go-librespot[10740]: time="2025-11-05T10:35:54Z" level=debug msg="completed keyexchange" Nov 05 10:35:54 volumio go-librespot[10740]: time="2025-11-05T10:35:54Z" level=debug msg="completed challenge" Nov 05 10:35:54 volumio go-librespot[10740]: time="2025-11-05T10:35:54Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Nov 05 10:35:54 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 05 10:35:54 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 05 10:35:54 volumio volumio[10351]: info: Connection to go-librespot Websocket closed Nov 05 10:35:54 volumio volumio[10351]: info: CoreCommandRouter::volumioGetState Nov 05 10:35:54 volumio volumio[10351]: info: CorePlayQueue::getTrack 0 Nov 05 10:35:56 volumio volumio[10351]: info: Getting Spotify volume Nov 05 10:35:56 volumio volumio[10351]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Nov 05 10:35:56 volumio volumio[10351]: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 05 10:35:56 volumio volumio[10351]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Nov 05 10:35:56 volumio volumio[10351]: errno: -111, Nov 05 10:35:56 volumio volumio[10351]: code: 'ECONNREFUSED', Nov 05 10:35:56 volumio volumio[10351]: syscall: 'connect', Nov 05 10:35:56 volumio volumio[10351]: address: '127.0.0.1', Nov 05 10:35:56 volumio volumio[10351]: port: 9879, Nov 05 10:35:56 volumio volumio[10351]: response: undefined Nov 05 10:35:56 volumio volumio[10351]: } Nov 05 10:35:56 volumio volumio[10351]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Nov 05 10:35:57 volumio sudo[10761]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-11-05 10:34' Nov 05 10:35:57 volumio sudo[10761]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 05 10:35:57 volumio sudo[10761]: pam_unix(sudo:session): session closed for user root Nov 05 10:35:57 volumio volumio-remote-updater[874]: [2025-11-05 10:35:57] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Nov 05 10:35:57 volumio volumio-remote-updater[874]: [2025-11-05 10:35:57] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Nov 05 10:35:57 volumio systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Nov 05 10:35:57 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 105. Nov 05 10:35:57 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Nov 05 10:35:57 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Nov 05 10:35:57 volumio go-librespot[10771]: go-librespot daemon starting... Nov 05 10:35:57 volumio systemd[1]: volumio.service: Failed with result 'exit-code'. Nov 05 10:35:57 volumio systemd[1]: volumio.service: Consumed 8.169s CPU time. Nov 05 10:35:57 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Nov 05 10:35:57 volumio go-librespot[10775]: time="2025-11-05T10:35:57Z" level=info msg="running go-librespot 0.4.0" Nov 05 10:35:57 volumio go-librespot[10775]: time="2025-11-05T10:35:57Z" level=debug msg="app state loaded" Nov 05 10:35:57 volumio go-librespot[10775]: time="2025-11-05T10:35:57Z" level=info msg="api server listening on 127.0.0.1:9879" Nov 05 10:35:57 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Nov 05 10:35:57 volumio go-librespot[10775]: time="2025-11-05T10:35:57Z" 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]" Nov 05 10:35:57 volumio go-librespot[10775]: time="2025-11-05T10:35:57Z" 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]" Nov 05 10:35:57 volumio go-librespot[10775]: time="2025-11-05T10:35:57Z" 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]" Nov 05 10:35:57 volumio go-librespot[10775]: time="2025-11-05T10:35:57Z" level=info msg="zeroconf server listening on port 34427" Nov 05 10:35:57 volumio go-librespot[10775]: time="2025-11-05T10:35:57Z" level=debug msg="obtained new client token: AACssHG/xrRYD1qhqwZFlclMFCbXDGEw9bFZOuYushFgdvXNPmLwRYFQIq60oa02R9BvGC5niOlOIbssfwfctWN8ik+JggDXeGSIeXVL2xaGX8caVO3KvsBiVCOD557IMvDwVfCmAuVEt5XMM6ZOGjPSYIFEFrOK3XqDf0t70QhGXXs9125nBqZSFP1+zi6jgOl8eyM0RICoKd0ThN+eRxS5ftEGOnd6jRd1VrqN4dxAmgOmT8smUBI=" Nov 05 10:35:57 volumio go-librespot[10775]: time="2025-11-05T10:35:57Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Nov 05 10:35:57 volumio go-librespot[10775]: time="2025-11-05T10:35:57Z" level=debug msg="completed keyexchange" Nov 05 10:35:57 volumio go-librespot[10775]: time="2025-11-05T10:35:57Z" level=debug msg="completed challenge" Nov 05 10:35:57 volumio go-librespot[10775]: time="2025-11-05T10:35:57Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Nov 05 10:35:57 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 7699. Nov 05 10:35:57 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Nov 05 10:35:57 volumio systemd[1]: Stopped volumio.service - Volumio Backend Module. Nov 05 10:35:57 volumio systemd[1]: volumio.service: Consumed 8.169s CPU time. Nov 05 10:35:57 volumio systemd[1]: Started volumio.service - Volumio Backend Module. Nov 05 10:35:57 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 05 10:35:57 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 05 10:35:57 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Nov 05 10:35:57 volumio volumio[10789]: info: ------------------------------------------- Nov 05 10:35:57 volumio volumio[10789]: info: ----- Volumio3 ---- Nov 05 10:35:57 volumio volumio[10789]: info: ------------------------------------------- Nov 05 10:35:57 volumio volumio[10789]: info: ----- System startup ---- Nov 05 10:35:57 volumio volumio[10789]: info: ------------------------------------------- Nov 05 10:35:58 volumio volumio[10789]: info: MYVOLUMIO Environment detected Nov 05 10:35:58 volumio volumio[10789]: info: Plugin folders cleanup Nov 05 10:35:58 volumio volumio[10789]: info: Scanning into folder /volumio/app/plugins/ Nov 05 10:35:58 volumio volumio[10789]: info: Scanning category audio_interface Nov 05 10:35:58 volumio volumio[10789]: info: Scanning category miscellanea Nov 05 10:35:58 volumio volumio[10789]: info: Scanning category music_service Nov 05 10:35:58 volumio volumio[10789]: info: Scanning category plugins.json Nov 05 10:35:58 volumio volumio[10789]: info: Scanning category system_controller Nov 05 10:35:58 volumio volumio[10789]: info: Scanning category user_interface Nov 05 10:35:58 volumio volumio[10789]: info: Scanning into folder /data/plugins/ Nov 05 10:35:58 volumio volumio[10789]: info: Scanning category music_service Nov 05 10:35:58 volumio volumio[10789]: info: Scanning category user_interface Nov 05 10:35:58 volumio volumio[10789]: info: Plugin folders cleanup completed Nov 05 10:35:58 volumio volumio[10789]: info: ------------------------------------------- Nov 05 10:35:58 volumio volumio[10789]: info: ----- Core plugins startup ---- Nov 05 10:35:58 volumio volumio[10789]: info: ------------------------------------------- Nov 05 10:35:58 volumio volumio[10789]: info: Loading plugins from folder /volumio/app/plugins/ Nov 05 10:35:58 volumio volumio[10789]: info: Adding plugin upnp to MyMusic Plugins Nov 05 10:35:58 volumio volumio[10789]: info: Adding plugin airplay_emulation to MyMusic Plugins Nov 05 10:35:58 volumio volumio[10789]: info: Adding plugin upnp_browser to MyMusic Plugins Nov 05 10:35:58 volumio volumio[10789]: info: Loading plugins from folder /data/plugins/ Nov 05 10:35:58 volumio volumio[10789]: info: Loading plugin "system"... Nov 05 10:35:58 volumio volumio[10789]: info: Loading plugin "appearance"... Nov 05 10:35:58 volumio volumio[10789]: info: Loading plugin "network"... Nov 05 10:35:58 volumio volumio[10789]: info: Refreshing Cached IP Addresses Nov 05 10:35:58 volumio sudo[10817]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Nov 05 10:35:58 volumio sudo[10817]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 05 10:35:58 volumio sudo[10817]: pam_unix(sudo:session): session closed for user root Nov 05 10:35:58 volumio sudo[10819]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Nov 05 10:35:58 volumio sudo[10819]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 05 10:35:58 volumio volumio[10789]: info: Loading plugin "services"... Nov 05 10:35:58 volumio sudo[10819]: pam_unix(sudo:session): session closed for user root Nov 05 10:35:58 volumio volumio[10789]: info: Loading plugin "alsa_controller"... Nov 05 10:35:58 volumio volumio[10789]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Nov 05 10:35:58 volumio volumio[10789]: info: Loading plugin "wizard"... Nov 05 10:35:58 volumio volumio[10789]: info: Loading plugin "networkfs"... Nov 05 10:35:58 volumio volumio[10789]: info: Cannot mount NAS NAS at system boot, trial number 1 ,retrying in 5 seconds Nov 05 10:35:58 volumio volumio[10789]: info: Starting Udev Watcher for removable devices Nov 05 10:35:58 volumio volumio[10789]: info: Ignoring mount for partition: boot Nov 05 10:35:58 volumio volumio[10789]: info: Ignoring mount for partition: volumio Nov 05 10:35:58 volumio volumio[10789]: info: Ignoring mount for partition: volumio_data Nov 05 10:35:58 volumio volumio[10789]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Nov 05 10:35:58 volumio volumio[10789]: info: Loading plugin "volumio_command_line_client"... Nov 05 10:35:58 volumio volumio[10789]: info: Loading plugin "upnp"... Nov 05 10:35:58 volumio volumio[10789]: info: [1762338958278] Starting Upmpd Daemon Nov 05 10:35:58 volumio volumio[10789]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Nov 05 10:35:58 volumio volumio[10789]: info: Loading plugin "my_music"... Nov 05 10:35:58 volumio volumio[10789]: info: Loading plugin "mpd"... Nov 05 10:35:58 volumio volumio[10789]: info: Loading plugin "upnp_browser"... Nov 05 10:35:58 volumio volumio[10789]: info: Loading plugin "alarm-clock"... Nov 05 10:35:58 volumio volumio[10789]: info: Loading plugin "airplay_emulation"... Nov 05 10:35:58 volumio volumio[10789]: info: Starting Shairport Sync Nov 05 10:35:58 volumio volumio[10789]: info: Loading plugin "last_100"... Nov 05 10:35:58 volumio volumio[10789]: info: Loading plugin "webradio"... Nov 05 10:35:58 volumio volumio[10789]: info: Loading plugin "i2s_dacs"... Nov 05 10:35:58 volumio volumio[10789]: info: I2S DAC not set, start Auto-detection Nov 05 10:35:58 volumio volumio[10789]: info: Loading plugin "volumiodiscovery"... Nov 05 10:35:58 volumio volumio[10789]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Nov 05 10:35:58 volumio node[10789]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Nov 05 10:35:58 volumio volumio[10789]: *** WARNING *** Please fix your application to use the native API of Avahi! Nov 05 10:35:58 volumio node[10789]: *** WARNING *** Please fix your application to use the native API of Avahi! Nov 05 10:35:58 volumio volumio[10789]: *** WARNING *** For more information see Nov 05 10:35:58 volumio node[10789]: *** WARNING *** For more information see Nov 05 10:35:58 volumio volumio[10789]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Nov 05 10:35:58 volumio node[10789]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Nov 05 10:35:58 volumio volumio[10789]: *** WARNING *** Please fix your application to use the native API of Avahi! Nov 05 10:35:58 volumio node[10789]: *** WARNING *** Please fix your application to use the native API of Avahi! Nov 05 10:35:58 volumio volumio[10789]: *** WARNING *** For more information see Nov 05 10:35:58 volumio node[10789]: *** WARNING *** For more information see Nov 05 10:35:58 volumio volumio[10789]: info: Applying required configuration parameters for plugin volumiodiscovery Nov 05 10:35:58 volumio volumio[10789]: info: Discovery: Started advertising with name: Volumio Nov 05 10:35:58 volumio volumio[10789]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Nov 05 10:35:58 volumio volumio[10789]: info: Loading plugin "spop"... Nov 05 10:35:58 volumio volumio[10789]: info: Loading plugin "ytcr"... Nov 05 10:35:59 volumio volumio[10789]: info: Loading plugin "outputs"... Nov 05 10:35:59 volumio volumio[10789]: info: Loading plugin "albumart"... Nov 05 10:35:59 volumio volumio[10789]: info: Plugin example_plugin is not enabled Nov 05 10:35:59 volumio volumio[10789]: info: Loading plugin "inputs"... Nov 05 10:35:59 volumio volumio[10789]: info: Loading plugin "updater_comm"... Nov 05 10:35:59 volumio volumio[10789]: info: Plugin mpdemulation is not enabled Nov 05 10:35:59 volumio volumio[10789]: info: Loading plugin "rest_api"... Nov 05 10:35:59 volumio volumio[10789]: info: Loading plugin "websocket"... Nov 05 10:35:59 volumio volumio[10789]: info: Starting Socket.io Server version 1.7.4 Nov 05 10:35:59 volumio volumio[10789]: info: Loading plugin "Systeminfo"... Nov 05 10:35:59 volumio volumio[10789]: info: Loading i18n strings for locale en Nov 05 10:35:59 volumio volumio[10789]: Updating browse sources language Nov 05 10:35:59 volumio volumio[10789]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 05 10:35:59 volumio volumio[10849]: Forking 3 albumart workers Nov 05 10:35:59 volumio volumio[10789]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Nov 05 10:35:59 volumio volumio[10789]: info: CoreCommandRouter::initPlayerControls Nov 05 10:35:59 volumio volumio[10789]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 05 10:35:59 volumio volumio[10789]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 05 10:35:59 volumio volumio[10789]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 05 10:35:59 volumio volumio[10789]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 05 10:35:59 volumio volumio[10789]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 05 10:35:59 volumio volumio[10789]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 05 10:35:59 volumio volumio[10789]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 05 10:35:59 volumio volumio[10789]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 05 10:35:59 volumio volumio[10789]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Nov 05 10:35:59 volumio volumio[10789]: Express server listening on port 3000 Nov 05 10:35:59 volumio volumio[10789]: [Metrics] WebUI: 1s 954.65ms Nov 05 10:35:59 volumio volumio[10789]: info: CoreStateMachine::resetVolumioState Nov 05 10:35:59 volumio volumio[10789]: info: CoreStateMachine::getcurrentVolume Nov 05 10:35:59 volumio volumio[10789]: info: CoreCommandRouter::volumioRetrievevolume Nov 05 10:35:59 volumio volumio[10789]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 05 10:35:59 volumio volumio[10789]: info: Cannot read play queue from file Nov 05 10:35:59 volumio volumio[10789]: info: Volumio Network Manager: Network status updated: 1 Nov 05 10:35:59 volumio volumio[10789]: info: VolumeController:: Volume=33 Mute =false Nov 05 10:35:59 volumio volumio[10789]: info: CoreStateMachine::pushState Nov 05 10:35:59 volumio volumio[10789]: info: CorePlayQueue::getTrack 0 Nov 05 10:35:59 volumio volumio[10789]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 05 10:35:59 volumio volumio[10789]: info: CoreCommandRouter::volumioPushState Nov 05 10:35:59 volumio volumio[10789]: info: CoreStateMachine::updateTrackBlock Nov 05 10:35:59 volumio volumio[10789]: info: CorePlayQueue::getTrackBlock Nov 05 10:35:59 volumio volumio[10789]: info: CoreCommandRouter::volumioRetrievevolume Nov 05 10:35:59 volumio volumio[10789]: info: CoreStateMachine::setRepeat null single undefined Nov 05 10:35:59 volumio volumio[10789]: info: CoreStateMachine::pushState Nov 05 10:35:59 volumio volumio[10789]: info: CorePlayQueue::getTrack 0 Nov 05 10:35:59 volumio volumio[10789]: info: CoreCommandRouter::volumioPushState Nov 05 10:35:59 volumio volumio[10789]: info: CoreStateMachine::setRandom null Nov 05 10:35:59 volumio volumio[10789]: info: CoreStateMachine::pushState Nov 05 10:35:59 volumio volumio[10789]: info: CorePlayQueue::getTrack 0 Nov 05 10:35:59 volumio volumio[10789]: info: CoreCommandRouter::volumioPushState Nov 05 10:35:59 volumio volumio[10789]: info: Setting Device type: Raspberry PI Nov 05 10:35:59 volumio volumio[10789]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Nov 05 10:35:59 volumio volumio[10789]: info: USB Boot Capable - System SBC Revision found in cpuinfo: b04170 Nov 05 10:35:59 volumio volumio[10789]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Nov 05 10:35:59 volumio volumio[10789]: info: VolumeController:: Volume=33 Mute =false Nov 05 10:35:59 volumio volumio[10789]: info: CoreStateMachine::pushState Nov 05 10:35:59 volumio volumio[10789]: info: CorePlayQueue::getTrack 0 Nov 05 10:35:59 volumio volumio[10789]: info: CoreCommandRouter::volumioPushState Nov 05 10:35:59 volumio volumio[10789]: info: Discovery: adding 70853f74-8210-4683-a3fa-e1217517bd40 Nov 05 10:35:59 volumio volumio[10789]: info: Discovery: Found device Volumio Nov 05 10:35:59 volumio volumio[10789]: info: CoreCommandRouter::volumioGetState Nov 05 10:35:59 volumio volumio[10789]: info: CorePlayQueue::getTrack 0 Nov 05 10:35:59 volumio volumio[10789]: info: Completed loading Core Plugins Nov 05 10:35:59 volumio volumio[10789]: info: Preparing to generate the ALSA configuration file Nov 05 10:35:59 volumio volumio[10789]: info: Discovery: this is already registered, 70853f74-8210-4683-a3fa-e1217517bd40 Nov 05 10:35:59 volumio volumio[10789]: info: Discovery: Found device Volumio Nov 05 10:35:59 volumio volumio[10789]: info: CoreCommandRouter::volumioGetState Nov 05 10:35:59 volumio volumio[10789]: info: CorePlayQueue::getTrack 0 Nov 05 10:35:59 volumio volumio[10789]: info: Asound.conf file unchanged, so no further update is needed Nov 05 10:35:59 volumio volumio[10789]: info: Output device has changed, restarting MPD Nov 05 10:35:59 volumio volumio[10789]: info: Output device has changed, restarting Shairport Sync Nov 05 10:35:59 volumio volumio[10789]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 05 10:35:59 volumio volumio[10789]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 05 10:35:59 volumio sudo[10905]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Nov 05 10:35:59 volumio sudo[10907]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Nov 05 10:35:59 volumio sudo[10907]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 05 10:35:59 volumio sudo[10905]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 05 10:35:59 volumio volumio[10789]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Nov 05 10:35:59 volumio volumio[10789]: info: ___________ START PLUGINS ___________ Nov 05 10:35:59 volumio sudo[10905]: pam_unix(sudo:session): session closed for user root Nov 05 10:35:59 volumio volumio[10789]: info: ControllerMpd::onStart: Initializing MPD Nov 05 10:35:59 volumio volumio[10789]: info: Creating MPD Configuration file Nov 05 10:36:00 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Nov 05 10:36:00 volumio volumio[10789]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Nov 05 10:36:00 volumio volumio[10789]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Nov 05 10:36:00 volumio volumio[10789]: info: [1762338960019] CoreMusicLibrary::Adding element Media Servers Nov 05 10:36:00 volumio volumio[10789]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 05 10:36:00 volumio sudo[10917]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Nov 05 10:36:00 volumio sudo[10917]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 05 10:36:00 volumio systemd[1]: mpd.service: Deactivated successfully. Nov 05 10:36:00 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Nov 05 10:36:00 volumio systemd[1]: mpd.socket: Deactivated successfully. Nov 05 10:36:00 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Nov 05 10:36:00 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Nov 05 10:36:00 volumio volumio[10789]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 05 10:36:00 volumio volumio[10789]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 05 10:36:00 volumio sudo[10915]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Nov 05 10:36:00 volumio sudo[10915]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 05 10:36:00 volumio sudo[10915]: pam_unix(sudo:session): session closed for user root Nov 05 10:36:00 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Nov 05 10:36:00 volumio volumio[10789]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Nov 05 10:36:00 volumio volumio[10789]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 05 10:36:00 volumio volumio[10789]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 05 10:36:00 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Nov 05 10:36:00 volumio systemd[1]: mpd.service: Deactivated successfully. Nov 05 10:36:00 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Nov 05 10:36:00 volumio systemd[1]: mpd.socket: Deactivated successfully. Nov 05 10:36:00 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Nov 05 10:36:00 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Nov 05 10:36:00 volumio volumio[10789]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Nov 05 10:36:00 volumio volumio[10789]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Nov 05 10:36:00 volumio volumio[10789]: info: [1762338960080] CoreMusicLibrary::Adding element Last_100 Nov 05 10:36:00 volumio volumio[10789]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 05 10:36:00 volumio volumio[10789]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Nov 05 10:36:00 volumio volumio[10789]: info: [1762338960081] CoreMusicLibrary::Adding element Webradio Nov 05 10:36:00 volumio volumio[10789]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 05 10:36:00 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Nov 05 10:36:00 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Nov 05 10:36:00 volumio volumio[10789]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Nov 05 10:36:00 volumio volumio[10789]: info: Initializing BBC Radios Nov 05 10:36:00 volumio volumio[10861]: Starting albumart workers Nov 05 10:36:00 volumio sudo[10931]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Nov 05 10:36:00 volumio sudo[10931]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Nov 05 10:36:00 volumio sudo[10931]: pam_unix(sudo:session): session closed for user root Nov 05 10:36:00 volumio volumio[10860]: Starting albumart workers Nov 05 10:36:00 volumio volumio[10789]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Nov 05 10:36:00 volumio volumio[10789]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 05 10:36:00 volumio volumio[10789]: info: Creating Spotify config file Nov 05 10:36:00 volumio volumio[10789]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 05 10:36:00 volumio volumio[10859]: Starting albumart workers Nov 05 10:36:00 volumio volumio[10789]: info: Volumio Calling Home Nov 05 10:36:00 volumio volumio[10789]: info: MPD Permissions set Nov 05 10:36:00 volumio volumio[10789]: info: MPD Permissions set Nov 05 10:36:00 volumio volumio[10789]: info: Spotify config file written Nov 05 10:36:00 volumio sudo[10970]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Nov 05 10:36:00 volumio sudo[10970]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 05 10:36:00 volumio volumio[10789]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 1 Nov 05 10:36:00 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 106. Nov 05 10:36:00 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Nov 05 10:36:00 volumio volumio[10789]: info: Volumio called home Nov 05 10:36:00 volumio volumio[10789]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 05 10:36:00 volumio volumio[10789]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 05 10:36:00 volumio volumio[10789]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 05 10:36:00 volumio volumio[10789]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 05 10:36:00 volumio volumio[10789]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 05 10:36:00 volumio volumio[10789]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 05 10:36:00 volumio volumio[10789]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 05 10:36:00 volumio volumio[10789]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 05 10:36:00 volumio volumio[10789]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 05 10:36:00 volumio volumio[10789]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 05 10:36:00 volumio volumio[10789]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 05 10:36:00 volumio volumio[10789]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 05 10:36:00 volumio volumio[10789]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 05 10:36:00 volumio volumio[10789]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 05 10:36:00 volumio volumio[10789]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 05 10:36:00 volumio volumio[10789]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 05 10:36:00 volumio volumio[10789]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 05 10:36:00 volumio volumio[10789]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 05 10:36:00 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Nov 05 10:36:00 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Nov 05 10:36:00 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Nov 05 10:36:00 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Nov 05 10:36:00 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Nov 05 10:36:00 volumio sudo[10970]: pam_unix(sudo:session): session closed for user root Nov 05 10:36:00 volumio volumio[10789]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 05 10:36:00 volumio volumio[10789]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 05 10:36:00 volumio go-librespot[10980]: go-librespot daemon starting... Nov 05 10:36:00 volumio volumio[10789]: info: No need to fix Spotify hosts Nov 05 10:36:00 volumio go-librespot[10984]: time="2025-11-05T10:36:00Z" level=info msg="running go-librespot 0.4.0" Nov 05 10:36:00 volumio go-librespot[10984]: time="2025-11-05T10:36:00Z" level=debug msg="app state loaded" Nov 05 10:36:00 volumio go-librespot[10984]: time="2025-11-05T10:36:00Z" level=info msg="api server listening on 127.0.0.1:9879" Nov 05 10:36:00 volumio volumio[10789]: info: Starting Shairport Sync Nov 05 10:36:00 volumio volumio[10789]: info: Starting Shairport Sync Nov 05 10:36:00 volumio volumio[10789]: info: Starting Shairport Sync Nov 05 10:36:00 volumio sudo[10991]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Nov 05 10:36:00 volumio sudo[10991]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 05 10:36:00 volumio sudo[10995]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Nov 05 10:36:00 volumio sudo[10995]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 05 10:36:00 volumio sudo[10993]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Nov 05 10:36:00 volumio sudo[10993]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 05 10:36:00 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Nov 05 10:36:00 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Nov 05 10:36:00 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Nov 05 10:36:00 volumio systemd[1]: shairport-sync.service: Consumed 1.538s CPU time. Nov 05 10:36:00 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Nov 05 10:36:00 volumio sudo[10995]: pam_unix(sudo:session): session closed for user root Nov 05 10:36:00 volumio sudo[10991]: pam_unix(sudo:session): session closed for user root Nov 05 10:36:00 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Nov 05 10:36:00 volumio mpd[10941]: 2025-11-05T10:36:00 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Nov 05 10:36:00 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Nov 05 10:36:00 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Nov 05 10:36:00 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Nov 05 10:36:00 volumio systemd[1]: Started mpd.service - Music Player Daemon. Nov 05 10:36:00 volumio sudo[10993]: pam_unix(sudo:session): session closed for user root Nov 05 10:36:00 volumio sudo[10907]: pam_unix(sudo:session): session closed for user root Nov 05 10:36:00 volumio sudo[10917]: pam_unix(sudo:session): session closed for user root Nov 05 10:36:00 volumio go-librespot[10984]: time="2025-11-05T10:36: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-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Nov 05 10:36:00 volumio go-librespot[10984]: time="2025-11-05T10:36:00Z" 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]" Nov 05 10:36:00 volumio go-librespot[10984]: time="2025-11-05T10:36:00Z" 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]" Nov 05 10:36:00 volumio go-librespot[10984]: time="2025-11-05T10:36:00Z" level=info msg="zeroconf server listening on port 44527" Nov 05 10:36:00 volumio volumio[10789]: info: Shairport-Sync Started Nov 05 10:36:00 volumio volumio[10789]: Error adding Membership: Error: addMembership EINVAL Nov 05 10:36:00 volumio volumio[10789]: info: Shairport-Sync Started Nov 05 10:36:00 volumio volumio[10789]: info: Shairport-Sync Started Nov 05 10:36:00 volumio volumio[10789]: error: MPD error: The expression evaluated to a falsy value: Nov 05 10:36:00 volumio volumio[10789]: assert.ok(self.idling) Nov 05 10:36:00 volumio volumio[10789]: error: The expression evaluated to a falsy value: Nov 05 10:36:00 volumio volumio[10789]: assert.ok(self.idling) Nov 05 10:36:00 volumio volumio[10789]: info: CoreCommandRouter::volumioGetState Nov 05 10:36:00 volumio volumio[10789]: info: CorePlayQueue::getTrack 0 Nov 05 10:36:00 volumio volumio[10789]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Nov 05 10:36:00 volumio volumio[10789]: SPOTIFY: BQCtEUjbhr-jPDhkxQa7HGT0oBqrMGo2IcFJiAL4Z5-ZiLtDQsfR3UyBxp6aOA_6lDOmUjja7J7NuA8mNQ_kNgPxdNayJERVQ-GAoGmrFX-b3UV9HJfc6dobViTnc0j5JGizM801vCqS6PU0CE-7wEr4-SfRyF-LLdS0PsJxWMSsoIxmG_UG6V66oHr8YgI-LwfyNGLMGevM7CroN5UqFx83dq0Ox4OxHZc8wIB97NyMo4CKKEuNehMPPwbz6aE3R6zgQDCMVGQKboDVnlr8X2eIA7WMXJlzNl_XstMu-7WsopJN-EPfq350 Nov 05 10:36:00 volumio volumio[10789]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Nov 05 10:36:00 volumio volumio[10789]: info: New Spotify access token = BQCtEUjbhr-jPDhkxQa7HGT0oBqrMGo2IcFJiAL4Z5-ZiLtDQsfR3UyBxp6aOA_6lDOmUjja7J7NuA8mNQ_kNgPxdNayJERVQ-GAoGmrFX-b3UV9HJfc6dobViTnc0j5JGizM801vCqS6PU0CE-7wEr4-SfRyF-LLdS0PsJxWMSsoIxmG_UG6V66oHr8YgI-LwfyNGLMGevM7CroN5UqFx83dq0Ox4OxHZc8wIB97NyMo4CKKEuNehMPPwbz6aE3R6zgQDCMVGQKboDVnlr8X2eIA7WMXJlzNl_XstMu-7WsopJN-EPfq350 Nov 05 10:36:00 volumio volumio[10789]: info: Spotify credentials grant success - running version from March 24, 2019 Nov 05 10:36:00 volumio volumio[10789]: error: updateQueue error: null Nov 05 10:36:00 volumio volumio[10789]: info: MPD running with PID10941 Nov 05 10:36:00 volumio volumio[10789]: ,establishing connection Nov 05 10:36:00 volumio go-librespot[10984]: time="2025-11-05T10:36:00Z" level=debug msg="obtained new client token: AAB6VM3/AqfsmGNizW1rCd+3RGmzLELVm0TvHS7ckxaTKqc5jryYvPWbz+3QPRvzhQmFcLHPgFYqJsSY6KWkxz2q1VVAz93TdWcyQX7AKvFefW0o+89fcdlkwsAxJeL/apS4cpnCsggWAbGTE8HkEyk96YzJSSnBaG6yjydxTfVeILyFXV+k4ZYt3Xy9/Z9ybHNEGv0vNcQYT2HxL8PPGtavaZFbQfT5iVX6snyObjKOsG2TdJuGMTI=" Nov 05 10:36:00 volumio volumio[10789]: error: updateQueue error: null Nov 05 10:36:00 volumio go-librespot[10984]: time="2025-11-05T10:36:00Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Nov 05 10:36:00 volumio go-librespot[10984]: time="2025-11-05T10:36:00Z" level=debug msg="completed keyexchange" Nov 05 10:36:00 volumio go-librespot[10984]: time="2025-11-05T10:36:00Z" level=debug msg="completed challenge" Nov 05 10:36:00 volumio go-librespot[10984]: time="2025-11-05T10:36:00Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Nov 05 10:36:00 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 05 10:36:00 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 05 10:36:00 volumio volumio[10789]: 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"} Nov 05 10:36:00 volumio volumio[10789]: info: Spotify Successfully logged in Nov 05 10:36:00 volumio volumio[10789]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Nov 05 10:36:00 volumio volumio[10789]: info: [1762338960897] CoreMusicLibrary::Adding element Spotify Nov 05 10:36:00 volumio volumio[10789]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 05 10:36:00 volumio volumio[10789]: Cannot find translation for source Spotify Nov 05 10:36:01 volumio volumio[10789]: info: [yt-cast-receiver] DIAL server listening on port 8098 Nov 05 10:36:01 volumio volumio[10789]: info: CoreCommandRouter::volumioRetrievevolume Nov 05 10:36:01 volumio volumio[10789]: info: VolumeController:: Volume=33 Mute =false Nov 05 10:36:01 volumio volumio[10789]: info: CoreCommandRouter::volumioGetState Nov 05 10:36:01 volumio volumio[10789]: info: CorePlayQueue::getTrack 0 Nov 05 10:36:01 volumio volumio[10789]: info: CoreStateMachine::pushState Nov 05 10:36:01 volumio volumio[10789]: info: CorePlayQueue::getTrack 0 Nov 05 10:36:01 volumio volumio[10789]: info: CoreCommandRouter::volumioPushState Nov 05 10:36:01 volumio volumio[10789]: info: Completed starting Core Plugins Nov 05 10:36:01 volumio volumio[10789]: info: ------------------------------------------- Nov 05 10:36:01 volumio volumio[10789]: info: ----- MyVolumio plugins startup ---- Nov 05 10:36:01 volumio volumio[10789]: info: ------------------------------------------- Nov 05 10:36:01 volumio volumio[10789]: info: [MyVolumio PluginManager] Fetching plans data.... Nov 05 10:36:02 volumio volumio-remote-updater[874]: [2025-11-05 10:36:02] [connect] Successful connection Nov 05 10:36:02 volumio volumio-remote-updater[874]: [2025-11-05 10:36:02] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1762338962 101 Nov 05 10:36:02 volumio volumio[10789]: 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 Nov 05 10:36:03 volumio volumio[10789]: info: Cannot mount NAS NAS at system boot, trial number 2 ,retrying in 5 seconds Nov 05 10:36:03 volumio volumio[10789]: info: go-librespot daemon successfully initialized Nov 05 10:36:03 volumio sudo[11024]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Nov 05 10:36:03 volumio sudo[11024]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 05 10:36:03 volumio sudo[11026]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Nov 05 10:36:03 volumio sudo[11026]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 05 10:36:03 volumio systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Nov 05 10:36:03 volumio systemd[1]: mpd_monitor.service: Deactivated successfully. Nov 05 10:36:03 volumio systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Nov 05 10:36:03 volumio systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Nov 05 10:36:03 volumio mpd_monitor.sh[11029]: MPD Monitor Service: Starting MPD Monitor Service Nov 05 10:36:03 volumio sudo[11026]: pam_unix(sudo:session): session closed for user root Nov 05 10:36:03 volumio sudo[11024]: pam_unix(sudo:session): session closed for user root Nov 05 10:36:03 volumio volumio[10789]: info: Successfully started MPD Monitor Nov 05 10:36:03 volumio volumio[10789]: info: Successfully started MPD Monitor Nov 05 10:36:04 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Nov 05 10:36:04 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Nov 05 10:36:04 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Nov 05 10:36:04 volumio go-librespot[11033]: go-librespot daemon starting... Nov 05 10:36:04 volumio go-librespot[11034]: time="2025-11-05T10:36:04Z" level=info msg="running go-librespot 0.4.0" Nov 05 10:36:04 volumio go-librespot[11034]: time="2025-11-05T10:36:04Z" level=debug msg="app state loaded" Nov 05 10:36:04 volumio go-librespot[11034]: time="2025-11-05T10:36:04Z" level=info msg="api server listening on 127.0.0.1:9879" Nov 05 10:36:04 volumio go-librespot[11034]: time="2025-11-05T10:36:04Z" 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]" Nov 05 10:36:04 volumio go-librespot[11034]: time="2025-11-05T10:36:04Z" 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]" Nov 05 10:36:04 volumio go-librespot[11034]: time="2025-11-05T10:36:04Z" 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]" Nov 05 10:36:04 volumio go-librespot[11034]: time="2025-11-05T10:36:04Z" level=info msg="zeroconf server listening on port 43253" Nov 05 10:36:04 volumio go-librespot[11034]: time="2025-11-05T10:36:04Z" level=debug msg="obtained new client token: AAB8ITjJjhqGEeVCPJn8EEtIenotdcnx1TW55nlFqrpm5Ij0Tgwq4OPoUxT5SbXvlX8Ftfzjhq94MCwG/4Tk0NfygxOXHUKi2CmDBPJWN1hMNymtGv3XuhuXs562T9azmqeVn65NHJ8EbDfEKv8XuGpZQuccqSeYhKi5HaejBwcEWYxQbUsYtZiC8rQWuahuusuz0qwMV5Dj8vGlvYbixDeGrVayo9iyyDjY+16VnqTLJW+0z7f+" Nov 05 10:36:04 volumio volumio[10789]: info: CoreCommandRouter::volumioGetState Nov 05 10:36:04 volumio volumio[10789]: info: CorePlayQueue::getTrack 0 Nov 05 10:36:04 volumio volumio[10789]: info: Listing playlists Nov 05 10:36:04 volumio volumio[10789]: info: Listing playlists Nov 05 10:36:04 volumio go-librespot[11034]: time="2025-11-05T10:36:04Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Nov 05 10:36:04 volumio go-librespot[11034]: time="2025-11-05T10:36:04Z" level=debug msg="completed keyexchange" Nov 05 10:36:04 volumio go-librespot[11034]: time="2025-11-05T10:36:04Z" level=debug msg="completed challenge" Nov 05 10:36:04 volumio go-librespot[11034]: time="2025-11-05T10:36:04Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Nov 05 10:36:04 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 05 10:36:04 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 05 10:36:05 volumio volumio[10789]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Nov 05 10:36:06 volumio volumio[10789]: info: Initializing connection to go-librespot Websocket Nov 05 10:36:06 volumio volumio[10789]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 05 10:36:07 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Nov 05 10:36:07 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Nov 05 10:36:07 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Nov 05 10:36:07 volumio go-librespot[11043]: go-librespot daemon starting... Nov 05 10:36:07 volumio go-librespot[11044]: time="2025-11-05T10:36:07Z" level=info msg="running go-librespot 0.4.0" Nov 05 10:36:07 volumio go-librespot[11044]: time="2025-11-05T10:36:07Z" level=debug msg="app state loaded" Nov 05 10:36:07 volumio go-librespot[11044]: time="2025-11-05T10:36:07Z" level=info msg="api server listening on 127.0.0.1:9879" Nov 05 10:36:07 volumio go-librespot[11044]: time="2025-11-05T10:36:07Z" 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]" Nov 05 10:36:07 volumio go-librespot[11044]: time="2025-11-05T10:36:07Z" 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]" Nov 05 10:36:07 volumio go-librespot[11044]: time="2025-11-05T10:36:07Z" 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]" Nov 05 10:36:07 volumio go-librespot[11044]: time="2025-11-05T10:36:07Z" level=info msg="zeroconf server listening on port 43793" Nov 05 10:36:07 volumio go-librespot[11044]: time="2025-11-05T10:36:07Z" level=debug msg="obtained new client token: AABli14TaOLUGhb4Oi20iLtSTdeTV1Zmyvw0YEEmxUZ3AcJNFmE5f24Rkos/27U5ZkT1tQXIS1FW5FOw9yJFTijeu9bXX0U2Cnyln11a3xSrlx97gjwUz04PmMjViD0I47iN5uIs8KddsiA/jiMARrZhyk6sbTLz6H0BGmcs7Dx2IDe9f+A1+sKdlSCjkbgUjA8+e4nKllZHEpacaOwMxyFc+rhKa0XHSQThLIRHBTO9SzBOR33gweM=" Nov 05 10:36:07 volumio go-librespot[11044]: time="2025-11-05T10:36:07Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Nov 05 10:36:07 volumio go-librespot[11044]: time="2025-11-05T10:36:07Z" level=debug msg="completed keyexchange" Nov 05 10:36:07 volumio go-librespot[11044]: time="2025-11-05T10:36:07Z" level=debug msg="completed challenge" Nov 05 10:36:07 volumio go-librespot[11044]: time="2025-11-05T10:36:07Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Nov 05 10:36:07 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 05 10:36:07 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 05 10:36:08 volumio volumio[10789]: info: Cannot mount NAS NAS at system boot, trial number 3 ,retrying in 5 seconds Nov 05 10:36:08 volumio sudo[11066]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Nov 05 10:36:08 volumio sudo[11066]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 05 10:36:08 volumio sudo[11068]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Nov 05 10:36:08 volumio sudo[11068]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 05 10:36:08 volumio sudo[11066]: pam_unix(sudo:session): session closed for user root Nov 05 10:36:08 volumio sudo[11068]: pam_unix(sudo:session): session closed for user root Nov 05 10:36:08 volumio sudo[11072]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Nov 05 10:36:08 volumio sudo[11072]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 05 10:36:08 volumio sudo[11072]: pam_unix(sudo:session): session closed for user root Nov 05 10:36:08 volumio volumio[10789]: info: Upmpdcli Daemon Started Nov 05 10:36:09 volumio volumio[10789]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Nov 05 10:36:09 volumio volumio[10789]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Nov 05 10:36:09 volumio volumio[10789]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Nov 05 10:36:09 volumio volumio[10789]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Nov 05 10:36:09 volumio volumio[10789]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Nov 05 10:36:09 volumio volumio[10789]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Nov 05 10:36:09 volumio volumio[10789]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Nov 05 10:36:09 volumio volumio[10789]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Nov 05 10:36:09 volumio volumio[10789]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Nov 05 10:36:09 volumio volumio[10789]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Nov 05 10:36:09 volumio volumio[10789]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Nov 05 10:36:09 volumio volumio[10789]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Nov 05 10:36:09 volumio volumio[10789]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Nov 05 10:36:09 volumio volumio[10789]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Nov 05 10:36:09 volumio volumio[10789]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Nov 05 10:36:09 volumio volumio[10789]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Nov 05 10:36:09 volumio volumio[10789]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Nov 05 10:36:09 volumio volumio[10789]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Nov 05 10:36:09 volumio volumio[10789]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Nov 05 10:36:09 volumio volumio[10789]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Nov 05 10:36:09 volumio volumio[10789]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Nov 05 10:36:09 volumio volumio[10789]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Nov 05 10:36:09 volumio volumio[10789]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Nov 05 10:36:09 volumio volumio[10789]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Nov 05 10:36:09 volumio volumio[10789]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Nov 05 10:36:09 volumio volumio[10789]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Nov 05 10:36:09 volumio volumio[10789]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Nov 05 10:36:09 volumio volumio[10789]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Nov 05 10:36:09 volumio volumio[10789]: info: Adding plugin bluetooth to MyMusic Plugins Nov 05 10:36:09 volumio volumio[10789]: info: Adding plugin multiroom to MyMusic Plugins Nov 05 10:36:09 volumio volumio[10789]: info: Adding plugin metavolumio to MyMusic Plugins Nov 05 10:36:09 volumio volumio[10789]: info: Adding plugin cd_controller to MyMusic Plugins Nov 05 10:36:09 volumio volumio[10789]: info: Adding plugin qobuzconnect to MyMusic Plugins Nov 05 10:36:09 volumio volumio[10789]: info: Adding plugin smart_inputs to MyMusic Plugins Nov 05 10:36:09 volumio volumio[10789]: info: Adding plugin tidalconnect to MyMusic Plugins Nov 05 10:36:09 volumio volumio[10789]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Nov 05 10:36:09 volumio volumio[10789]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Nov 05 10:36:09 volumio volumio[10789]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Nov 05 10:36:09 volumio volumio[10789]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 05 10:36:09 volumio volumio[10789]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 05 10:36:09 volumio volumio[10789]: info: Starting MyVolumio Remote Streaming Endpoints Nov 05 10:36:09 volumio volumio[10789]: info: MyVolumio login type: Token Nov 05 10:36:09 volumio volumio[10789]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Nov 05 10:36:09 volumio volumio[10789]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Nov 05 10:36:09 volumio volumio[10789]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Nov 05 10:36:09 volumio volumio[10789]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Nov 05 10:36:09 volumio volumio[10789]: info: Streaming services startup Nov 05 10:36:09 volumio volumio[10789]: info: Starting Streaming Daemon Nov 05 10:36:09 volumio sudo[11075]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Nov 05 10:36:09 volumio sudo[11075]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 05 10:36:09 volumio sudo[11075]: pam_unix(sudo:session): session closed for user root Nov 05 10:36:09 volumio volumio[10789]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Nov 05 10:36:09 volumio volumio[10789]: info: Initializing connection to go-librespot Websocket Nov 05 10:36:09 volumio volumio[10789]: error: Cannot start Volumio Streaming Daemon Nov 05 10:36:09 volumio volumio[10789]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Nov 05 10:36:09 volumio volumio[10789]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Nov 05 10:36:09 volumio volumio[10789]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 05 10:36:10 volumio volumio[10789]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Nov 05 10:36:10 volumio volumio[10789]: info: MyVolumio token set successfully Nov 05 10:36:10 volumio volumio[10789]: info: MYVOLUMIO: Adding device Nov 05 10:36:10 volumio volumio[10789]: info: MYVOLUMIO: Evaluating Server Nov 05 10:36:10 volumio volumio[10789]: info: MyVolumio status changed Nov 05 10:36:10 volumio volumio[10789]: info: Streaming services startup Nov 05 10:36:10 volumio volumio[10789]: info: Starting Streaming Daemon Nov 05 10:36:10 volumio volumio[10789]: info: Removing browser output: myVolumio user plan is not superstar Nov 05 10:36:10 volumio volumio[10789]: info: Removing audio output: Nov 05 10:36:10 volumio volumio[10789]: info: Stoppping Tunnel 1 Nov 05 10:36:10 volumio sudo[11100]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Nov 05 10:36:10 volumio sudo[11100]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 05 10:36:10 volumio sudo[11102]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service Nov 05 10:36:10 volumio sudo[11102]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 05 10:36:10 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Nov 05 10:36:10 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Nov 05 10:36:10 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Nov 05 10:36:10 volumio go-librespot[11105]: go-librespot daemon starting... Nov 05 10:36:10 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. Nov 05 10:36:10 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. Nov 05 10:36:10 volumio go-librespot[11106]: time="2025-11-05T10:36:10Z" level=info msg="running go-librespot 0.4.0" Nov 05 10:36:10 volumio go-librespot[11106]: time="2025-11-05T10:36:10Z" level=debug msg="app state loaded" Nov 05 10:36:10 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. Nov 05 10:36:10 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. Nov 05 10:36:10 volumio go-librespot[11106]: time="2025-11-05T10:36:10Z" level=info msg="api server listening on 127.0.0.1:9879" Nov 05 10:36:10 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. Nov 05 10:36:10 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. Nov 05 10:36:10 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. Nov 05 10:36:10 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. Nov 05 10:36:10 volumio sudo[11102]: pam_unix(sudo:session): session closed for user root Nov 05 10:36:10 volumio sudo[11100]: pam_unix(sudo:session): session closed for user root Nov 05 10:36:10 volumio volumio[10789]: info: Remote SSH Stopped Nov 05 10:36:10 volumio volumio[10789]: error: Cannot start Volumio Streaming Daemon Nov 05 10:36:10 volumio volumio[10789]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Nov 05 10:36:10 volumio volumio[10789]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Nov 05 10:36:10 volumio go-librespot[11106]: time="2025-11-05T10:36:10Z" 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]" Nov 05 10:36:10 volumio go-librespot[11106]: time="2025-11-05T10:36:10Z" 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]" Nov 05 10:36:10 volumio go-librespot[11106]: time="2025-11-05T10:36:10Z" 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]" Nov 05 10:36:10 volumio go-librespot[11106]: time="2025-11-05T10:36:10Z" level=info msg="zeroconf server listening on port 41761" Nov 05 10:36:11 volumio go-librespot[11106]: time="2025-11-05T10:36:11Z" level=debug msg="obtained new client token: AABc2Q38lm/jtgHr28Y4jouVSGITBKPkZJsmQQppkqKd3wptexE5Fy9ThfpAMvee3mzew4kCvAARyz0XmjbRMtG35XHMtg8ktBRtrvVAS0XuIPHAAlRDp+eyC+z+MGpSNuoyitzPJVirukY6lGbFp4v1jQblYqnD7aC5Q4uOl5BLiK797LODsx6o1dx1AmPkqwea9hJ2eDETfNRqiMxLBE3GFVNWBfF1aEe6C3cZaKs5gfYlTr2R" Nov 05 10:36:11 volumio go-librespot[11106]: time="2025-11-05T10:36:11Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Nov 05 10:36:11 volumio go-librespot[11106]: time="2025-11-05T10:36:11Z" level=debug msg="completed keyexchange" Nov 05 10:36:11 volumio go-librespot[11106]: time="2025-11-05T10:36:11Z" level=debug msg="completed challenge" Nov 05 10:36:11 volumio volumio[10789]: info: Setting Geolocation for MyVolumio to eu3 Nov 05 10:36:11 volumio volumio[10789]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 05 10:36:11 volumio volumio[10789]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 05 10:36:11 volumio volumio[10789]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 05 10:36:11 volumio go-librespot[11106]: time="2025-11-05T10:36:11Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Nov 05 10:36:11 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 05 10:36:11 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 05 10:36:11 volumio volumio[10789]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Nov 05 10:36:12 volumio volumio[10789]: info: Updating MyVolumio device info Nov 05 10:36:12 volumio volumio[10789]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 05 10:36:12 volumio volumio[10789]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 05 10:36:12 volumio volumio[10789]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 05 10:36:12 volumio volumio[10789]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Nov 05 10:36:12 volumio volumio[10789]: info: Initializing connection to go-librespot Websocket Nov 05 10:36:12 volumio volumio[10789]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 05 10:36:13 volumio volumio[10789]: info: Cannot mount NAS NAS at system boot, trial number 4 ,retrying in 5 seconds Nov 05 10:36:14 volumio volumio[10789]: info: CoreCommandRouter::volumioGetState Nov 05 10:36:14 volumio volumio[10789]: info: CorePlayQueue::getTrack 0 Nov 05 10:36:14 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 4. Nov 05 10:36:14 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Nov 05 10:36:14 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Nov 05 10:36:14 volumio go-librespot[11114]: go-librespot daemon starting... Nov 05 10:36:14 volumio go-librespot[11115]: time="2025-11-05T10:36:14Z" level=info msg="running go-librespot 0.4.0" Nov 05 10:36:14 volumio go-librespot[11115]: time="2025-11-05T10:36:14Z" level=debug msg="app state loaded" Nov 05 10:36:14 volumio go-librespot[11115]: time="2025-11-05T10:36:14Z" level=info msg="api server listening on 127.0.0.1:9879" Nov 05 10:36:14 volumio go-librespot[11115]: time="2025-11-05T10:36:14Z" 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]" Nov 05 10:36:14 volumio go-librespot[11115]: time="2025-11-05T10:36:14Z" 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]" Nov 05 10:36:14 volumio go-librespot[11115]: time="2025-11-05T10:36:14Z" 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]" Nov 05 10:36:14 volumio go-librespot[11115]: time="2025-11-05T10:36:14Z" level=info msg="zeroconf server listening on port 34971" Nov 05 10:36:14 volumio go-librespot[11115]: time="2025-11-05T10:36:14Z" level=debug msg="obtained new client token: AACtaAiJmyoigyMd3qeH8PU74hkr5l9jeTCm4F26Ml8Mgi5w8DYIAIX7UVXCdGnODAUqB3Y1hIbKu2LxUdFWtz4VuBN2ufOLAnsIzgdhBZTMpYqRxhEc5Xawt7Nw1cnYK02N3qMdkByGTumMGMaMI5Qp6/3Ulp/LtRxnrFYvrDeY74SP2vZvkmaiBw4xCWC25gMmc0Bnmw3oQArH1/Ho+VgHfjyX8UApBInppRs5gkv00FoFXOtHQLg=" Nov 05 10:36:14 volumio go-librespot[11115]: time="2025-11-05T10:36:14Z" level=warning msg="failed to connect to AP ap-gew1.spotify.com:4070, retrying with a different AP" error="dial tcp 104.199.65.9:4070: connect: connection refused" Nov 05 10:36:14 volumio go-librespot[11115]: time="2025-11-05T10:36:14Z" level=debug msg="connected to ap-gew1.spotify.com:443" Nov 05 10:36:14 volumio go-librespot[11115]: time="2025-11-05T10:36:14Z" level=debug msg="completed keyexchange" Nov 05 10:36:14 volumio go-librespot[11115]: time="2025-11-05T10:36:14Z" level=debug msg="completed challenge" Nov 05 10:36:14 volumio go-librespot[11115]: time="2025-11-05T10:36:14Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Nov 05 10:36:14 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 05 10:36:14 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 05 10:36:15 volumio volumio[10789]: info: MYVOLUMIO: Adding device Nov 05 10:36:15 volumio volumio[10789]: info: MYVOLUMIO: Evaluating Server Nov 05 10:36:15 volumio volumio[10789]: info: Setting Geolocation for MyVolumio to eu3 Nov 05 10:36:15 volumio volumio[10789]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 05 10:36:15 volumio volumio[10789]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 05 10:36:15 volumio volumio[10789]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 05 10:36:15 volumio volumio[10789]: info: Initializing connection to go-librespot Websocket Nov 05 10:36:15 volumio volumio[10789]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 05 10:36:16 volumio volumio[10789]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Nov 05 10:36:16 volumio volumio[10789]: info: Updating MyVolumio device info Nov 05 10:36:16 volumio volumio[10789]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 05 10:36:16 volumio volumio[10789]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 05 10:36:16 volumio volumio[10789]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 05 10:36:17 volumio volumio[10789]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Nov 05 10:36:17 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 5. Nov 05 10:36:17 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Nov 05 10:36:17 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Nov 05 10:36:17 volumio go-librespot[11137]: go-librespot daemon starting... Nov 05 10:36:17 volumio go-librespot[11138]: time="2025-11-05T10:36:17Z" level=info msg="running go-librespot 0.4.0" Nov 05 10:36:17 volumio go-librespot[11138]: time="2025-11-05T10:36:17Z" level=debug msg="app state loaded" Nov 05 10:36:17 volumio go-librespot[11138]: time="2025-11-05T10:36:17Z" level=info msg="api server listening on 127.0.0.1:9879" Nov 05 10:36:17 volumio go-librespot[11138]: time="2025-11-05T10:36:17Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Nov 05 10:36:17 volumio go-librespot[11138]: time="2025-11-05T10:36:17Z" 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]" Nov 05 10:36:17 volumio go-librespot[11138]: time="2025-11-05T10:36:17Z" 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]" Nov 05 10:36:17 volumio go-librespot[11138]: time="2025-11-05T10:36:17Z" level=info msg="zeroconf server listening on port 43723" Nov 05 10:36:17 volumio go-librespot[11138]: time="2025-11-05T10:36:17Z" level=debug msg="obtained new client token: AAB8wjpBIc12/zfVK5Y37yzbysqFPBKxeVUg2BTrPMeVkQ+rTkQdDd5NWOuEgKIn9peWOHpnTQNuPA1WHGnphYYHFsjyB6aR0CBJAOjV+VntvAyRQkHeVOZpFJ9gFI6aWwD2C3KE6VrwcEHtZ4QTZoZ0GomaRCBOkpnQ9o9dB+Eanzhdu1+OftfH+UvwQYAFSVGISfulE/cYgCkK2OLbjj9U8qsCBq/CMj1UGNiDxKSaDuoDMHklry0=" Nov 05 10:36:17 volumio go-librespot[11138]: time="2025-11-05T10:36:17Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Nov 05 10:36:18 volumio go-librespot[11138]: time="2025-11-05T10:36:18Z" level=debug msg="completed keyexchange" Nov 05 10:36:18 volumio go-librespot[11138]: time="2025-11-05T10:36:18Z" level=debug msg="completed challenge" Nov 05 10:36:18 volumio go-librespot[11138]: time="2025-11-05T10:36:18Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Nov 05 10:36:18 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 05 10:36:18 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 05 10:36:18 volumio volumio[10789]: info: Cannot mount NAS at system boot, trial number 4 ,stopping Nov 05 10:36:18 volumio volumio[10789]: info: Initializing connection to go-librespot Websocket Nov 05 10:36:18 volumio volumio[10789]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 05 10:36:21 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6. Nov 05 10:36:21 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Nov 05 10:36:21 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Nov 05 10:36:21 volumio go-librespot[11159]: go-librespot daemon starting... Nov 05 10:36:21 volumio go-librespot[11160]: time="2025-11-05T10:36:21Z" level=info msg="running go-librespot 0.4.0" Nov 05 10:36:21 volumio go-librespot[11160]: time="2025-11-05T10:36:21Z" level=debug msg="app state loaded" Nov 05 10:36:21 volumio go-librespot[11160]: time="2025-11-05T10:36:21Z" level=info msg="api server listening on 127.0.0.1:9879" Nov 05 10:36:21 volumio go-librespot[11160]: time="2025-11-05T10:36:21Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Nov 05 10:36:21 volumio go-librespot[11160]: time="2025-11-05T10:36:21Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Nov 05 10:36:21 volumio go-librespot[11160]: time="2025-11-05T10:36:21Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Nov 05 10:36:21 volumio go-librespot[11160]: time="2025-11-05T10:36:21Z" level=info msg="zeroconf server listening on port 41619" Nov 05 10:36:21 volumio volumio[10789]: info: Initializing connection to go-librespot Websocket Nov 05 10:36:21 volumio go-librespot[11160]: time="2025-11-05T10:36:21Z" level=debug msg="new websocket client" Nov 05 10:36:21 volumio volumio[10789]: info: Connection to go-librespot Websocket established Nov 05 10:36:24 volumio volumio[10789]: info: CoreCommandRouter::volumioGetState Nov 05 10:36:24 volumio volumio[10789]: info: CorePlayQueue::getTrack 0 Nov 05 10:36:24 volumio volumio[10789]: info: Listing playlists Nov 05 10:36:24 volumio volumio[10789]: info: Listing playlists Nov 05 10:36:24 volumio volumio[10789]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Nov 05 10:36:24 volumio volumio[10789]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Nov 05 10:36:24 volumio volumio[10789]: info: CoreCommandRouter::volumioGetState Nov 05 10:36:24 volumio volumio[10789]: info: CorePlayQueue::getTrack 0 Nov 05 10:36:24 volumio volumio[10789]: info: Getting Spotify volume Nov 05 10:36:24 volumio volumio[10789]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 4 Nov 05 10:36:24 volumio volumio[10789]: info: CoreCommandRouter::volumioGetState Nov 05 10:36:24 volumio volumio[10789]: info: CorePlayQueue::getTrack 0 Nov 05 10:36:24 volumio volumio[10789]: SPOTIFY: RECEIVED VOLUMIO VOLUME 33 Nov 05 10:36:24 volumio volumio[10789]: SPOTIFY: SPOTIFY VOLUME undefined Nov 05 10:36:24 volumio volumio[10789]: SPOTIFY: VOLUMIO VOLUME 33 Nov 05 10:36:24 volumio volumio[10789]: info: Aligning Spotify Volume to Volumio Volume Nov 05 10:36:24 volumio volumio[10789]: info: CoreCommandRouter::volumioGetState Nov 05 10:36:24 volumio volumio[10789]: info: CorePlayQueue::getTrack 0 Nov 05 10:36:24 volumio volumio[10789]: info: Setting Spotify Volume from Volumio: 33 Nov 05 10:36:26 volumio go-librespot[11160]: time="2025-11-05T10:36:26Z" level=fatal msg="failed running with username and spotify token" error="failed obtaining client token: invalid status code from clienttoken: 503" Nov 05 10:36:26 volumio volumio[10789]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Nov 05 10:36:26 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 05 10:36:26 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 05 10:36:26 volumio volumio[10789]: Error: socket hang up Nov 05 10:36:26 volumio volumio[10789]: at connResetException (node:internal/errors:720:14) Nov 05 10:36:26 volumio volumio[10789]: at Socket.socketOnEnd (node:_http_client:519:23) Nov 05 10:36:26 volumio volumio[10789]: at Socket.emit (node:events:526:35) Nov 05 10:36:26 volumio volumio[10789]: at endReadableNT (node:internal/streams/readable:1376:12) Nov 05 10:36:26 volumio volumio[10789]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { Nov 05 10:36:26 volumio volumio[10789]: code: 'ECONNRESET', Nov 05 10:36:26 volumio volumio[10789]: response: undefined Nov 05 10:36:26 volumio volumio[10789]: } Nov 05 10:36:26 volumio volumio[10789]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Nov 05 10:36:26 volumio sudo[11185]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-11-05 10:35' Nov 05 10:36:26 volumio sudo[11185]: 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"