Oct 23 19:59:00 volumio go-librespot[2833]: time="2025-10-23T19:59:00+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Oct 23 19:59:00 volumio go-librespot[2833]: time="2025-10-23T19:59:00+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 23 19:59:00 volumio go-librespot[2833]: time="2025-10-23T19:59:00+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 23 19:59:00 volumio go-librespot[2833]: time="2025-10-23T19:59:00+01:00" level=info msg="zeroconf server listening on port 40193" Oct 23 19:59:00 volumio go-librespot[2833]: time="2025-10-23T19:59:00+01:00" level=debug msg="obtained new client token: AADUPtmOBximo06zYgYeYk+5nwP3pZ33A6n2P6xY6AcXwUkK6UkMom2b9/Vydkc9LB/SC3EyQLNENP/RaadJdEHcROliubulk21XOal+dJhUaKsKgniO45iaCy6QAJ7kDXio0U0ubMNjdjMh7rmjRiVXiczFQ0tn/b8KQXyUh9SmYPs9rJMu4vq87nDjwBFj+9uRy6Sqlj2j0S2SyltFXrZ1mF5qm10AmzuheQugpr2uXBETPQkb" Oct 23 19:59:00 volumio go-librespot[2833]: time="2025-10-23T19:59:00+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 23 19:59:00 volumio go-librespot[2833]: time="2025-10-23T19:59:00+01:00" level=debug msg="completed keyexchange" Oct 23 19:59:00 volumio go-librespot[2833]: time="2025-10-23T19:59:00+01:00" level=debug msg="completed challenge" Oct 23 19:59:00 volumio go-librespot[2833]: time="2025-10-23T19:59:00+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 23 19:59:00 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 23 19:59:00 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 23 19:59:01 volumio volumio[2497]: info: MYVOLUMIO: Adding device Oct 23 19:59:01 volumio volumio[2497]: info: MYVOLUMIO: Evaluating Server Oct 23 19:59:01 volumio volumio[2497]: info: Initializing connection to go-librespot Websocket Oct 23 19:59:01 volumio volumio[2497]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 23 19:59:02 volumio volumio[2497]: info: Setting Geolocation for MyVolumio to eu3 Oct 23 19:59:02 volumio volumio[2497]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 23 19:59:02 volumio volumio[2497]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 23 19:59:02 volumio volumio[2497]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 23 19:59:02 volumio volumio[2497]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Oct 23 19:59:02 volumio volumio[2497]: info: Cannot mount NAS at system boot, trial number 4 ,stopping Oct 23 19:59:03 volumio volumio[2497]: info: Updating MyVolumio device info Oct 23 19:59:03 volumio volumio[2497]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 23 19:59:03 volumio volumio[2497]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 23 19:59:03 volumio volumio[2497]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 23 19:59:03 volumio volumio[2497]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Oct 23 19:59:03 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 392. Oct 23 19:59:03 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 23 19:59:03 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 23 19:59:03 volumio go-librespot[2869]: go-librespot daemon starting... Oct 23 19:59:03 volumio go-librespot[2870]: time="2025-10-23T19:59:03+01:00" level=info msg="running go-librespot 0.4.0" Oct 23 19:59:03 volumio go-librespot[2870]: time="2025-10-23T19:59:03+01:00" level=debug msg="app state loaded" Oct 23 19:59:03 volumio go-librespot[2870]: time="2025-10-23T19:59:03+01:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 23 19:59:03 volumio go-librespot[2870]: time="2025-10-23T19:59:03+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Oct 23 19:59:03 volumio go-librespot[2870]: time="2025-10-23T19:59:03+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 23 19:59:03 volumio go-librespot[2870]: time="2025-10-23T19:59:03+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 23 19:59:03 volumio go-librespot[2870]: time="2025-10-23T19:59:03+01:00" level=info msg="zeroconf server listening on port 45649" Oct 23 19:59:03 volumio go-librespot[2870]: time="2025-10-23T19:59:03+01:00" level=debug msg="obtained new client token: AADZitjPHQS+1X3iYGWUgU9k124OJNQe8kUnyRQ8qWkXrINB3GNsiMGiDV0kQgcYHx9MmtM6uRAzRznEPrlW+9dqmWW98PsVQuBcholY25dY1FeJszJthjulM15btlT7HRDIRPI5yEujWLTM0wHpZsYthTG6wvHwdvWLMp72XTPLlfA9ArZZE8hQAvRD6bR9udw5LNIQ7NzapuMOPrNddBic5CfJcWYAbI/pZF/8iJHCwYVfQtDiSBU=" Oct 23 19:59:03 volumio go-librespot[2870]: time="2025-10-23T19:59:03+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 23 19:59:03 volumio go-librespot[2870]: time="2025-10-23T19:59:03+01:00" level=debug msg="completed keyexchange" Oct 23 19:59:03 volumio go-librespot[2870]: time="2025-10-23T19:59:03+01:00" level=debug msg="completed challenge" Oct 23 19:59:03 volumio go-librespot[2870]: time="2025-10-23T19:59:03+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 23 19:59:03 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 23 19:59:03 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 23 19:59:04 volumio volumio[2497]: info: Initializing connection to go-librespot Websocket Oct 23 19:59:04 volumio volumio[2497]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 23 19:59:06 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 393. Oct 23 19:59:06 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 23 19:59:06 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 23 19:59:06 volumio go-librespot[2877]: go-librespot daemon starting... Oct 23 19:59:06 volumio go-librespot[2878]: time="2025-10-23T19:59:06+01:00" level=info msg="running go-librespot 0.4.0" Oct 23 19:59:06 volumio go-librespot[2878]: time="2025-10-23T19:59:06+01:00" level=debug msg="app state loaded" Oct 23 19:59:06 volumio go-librespot[2878]: time="2025-10-23T19:59:06+01:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 23 19:59:07 volumio go-librespot[2878]: time="2025-10-23T19:59:07+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Oct 23 19:59:07 volumio go-librespot[2878]: time="2025-10-23T19:59:07+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 23 19:59:07 volumio go-librespot[2878]: time="2025-10-23T19:59:07+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 23 19:59:07 volumio go-librespot[2878]: time="2025-10-23T19:59:07+01:00" level=info msg="zeroconf server listening on port 41087" Oct 23 19:59:07 volumio go-librespot[2878]: time="2025-10-23T19:59:07+01:00" level=debug msg="obtained new client token: AABE/xsTrlkIxK/SjBvyx+YwMk7CVWvvCJ3nN8/h2dsF9UjnJ8EUVtIcsAz2ORjoLj7JbXo+UejZkRU/HleSKVk8QmBeY07zDHkGArIZJDuhNPLxJDrhZtX3pSvhU9OPXStPe7wIlrfKmiY3meddE625om3wSNpJ1HLCIaDQjqPeTnX7NC/dasqA8DGLrwScLch2c8smp9AK/Yf8CIzS83/DASlCQfljU3RT8taYHXbaPQwSqMsU" Oct 23 19:59:07 volumio go-librespot[2878]: time="2025-10-23T19:59:07+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 23 19:59:07 volumio go-librespot[2878]: time="2025-10-23T19:59:07+01:00" level=debug msg="completed keyexchange" Oct 23 19:59:07 volumio go-librespot[2878]: time="2025-10-23T19:59:07+01:00" level=debug msg="completed challenge" Oct 23 19:59:07 volumio go-librespot[2878]: time="2025-10-23T19:59:07+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 23 19:59:07 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 23 19:59:07 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 23 19:59:07 volumio volumio[2497]: info: Initializing connection to go-librespot Websocket Oct 23 19:59:07 volumio volumio[2497]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 23 19:59:10 volumio volumio[2497]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Oct 23 19:59:10 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 394. Oct 23 19:59:10 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 23 19:59:10 volumio volumio[2497]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Oct 23 19:59:10 volumio volumio[2497]: info: CoreCommandRouter::volumioGetState Oct 23 19:59:10 volumio volumio[2497]: info: CorePlayQueue::getTrack 0 Oct 23 19:59:10 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 23 19:59:10 volumio go-librespot[2888]: go-librespot daemon starting... Oct 23 19:59:10 volumio go-librespot[2889]: time="2025-10-23T19:59:10+01:00" level=info msg="running go-librespot 0.4.0" Oct 23 19:59:10 volumio go-librespot[2889]: time="2025-10-23T19:59:10+01:00" level=debug msg="app state loaded" Oct 23 19:59:10 volumio go-librespot[2889]: time="2025-10-23T19:59:10+01:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 23 19:59:10 volumio go-librespot[2889]: time="2025-10-23T19:59:10+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Oct 23 19:59:10 volumio go-librespot[2889]: time="2025-10-23T19:59:10+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 23 19:59:10 volumio go-librespot[2889]: time="2025-10-23T19:59:10+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 23 19:59:10 volumio go-librespot[2889]: time="2025-10-23T19:59:10+01:00" level=info msg="zeroconf server listening on port 42305" Oct 23 19:59:10 volumio go-librespot[2889]: time="2025-10-23T19:59:10+01:00" level=debug msg="obtained new client token: AADX+MGmPKx1H0ugaShrF/XNTcvVt7oACRWvYJomwECFBUgiWt+IFDz14158mK8FAPqDUGCHdD0RfATOsE6bpqA8IVQx/6Cgt9FqidYerwpP/iObBzmK8tU5kn7MILqE28hG3tnJdflnz3pY9bkbwpcgf6x6A0KZIiWjU1XD7iz2NELQmBrt5OP9gq/5KWjqL9MVYxGaQQxHLVMuAeSjoaQ5BZrz3901gEafCG6/qEe2AGLLRER2O5c=" Oct 23 19:59:10 volumio go-librespot[2889]: time="2025-10-23T19:59:10+01:00" level=warning msg="failed to connect to AP ap-gew1.spotify.com:4070, retrying with a different AP" error="dial tcp 104.199.65.9:4070: connect: connection refused" Oct 23 19:59:10 volumio go-librespot[2889]: time="2025-10-23T19:59:10+01:00" level=debug msg="connected to ap-gew1.spotify.com:443" Oct 23 19:59:10 volumio volumio[2497]: info: Initializing connection to go-librespot Websocket Oct 23 19:59:10 volumio go-librespot[2889]: time="2025-10-23T19:59:10+01:00" level=debug msg="new websocket client" Oct 23 19:59:10 volumio volumio[2497]: info: Connection to go-librespot Websocket established Oct 23 19:59:11 volumio go-librespot[2889]: time="2025-10-23T19:59:11+01:00" level=debug msg="completed keyexchange" Oct 23 19:59:11 volumio go-librespot[2889]: time="2025-10-23T19:59:11+01:00" level=debug msg="completed challenge" Oct 23 19:59:11 volumio go-librespot[2889]: time="2025-10-23T19:59:11+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 23 19:59:11 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 23 19:59:11 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 23 19:59:11 volumio volumio[2497]: info: Connection to go-librespot Websocket closed Oct 23 19:59:13 volumio volumio[2497]: info: Getting Spotify volume Oct 23 19:59:13 volumio volumio[2497]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 23 19:59:13 volumio volumio[2497]: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 23 19:59:13 volumio volumio[2497]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Oct 23 19:59:13 volumio volumio[2497]: errno: -111, Oct 23 19:59:13 volumio volumio[2497]: code: 'ECONNREFUSED', Oct 23 19:59:13 volumio volumio[2497]: syscall: 'connect', Oct 23 19:59:13 volumio volumio[2497]: address: '127.0.0.1', Oct 23 19:59:13 volumio volumio[2497]: port: 9879, Oct 23 19:59:13 volumio volumio[2497]: response: undefined Oct 23 19:59:13 volumio volumio[2497]: } Oct 23 19:59:13 volumio volumio[2497]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 23 19:59:13 volumio sudo[2925]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-10-23 19:58' Oct 23 19:59:13 volumio sudo[2925]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 23 19:59:13 volumio sudo[2925]: pam_unix(sudo:session): session closed for user root Oct 23 19:59:13 volumio volumio-remote-updater[896]: [2025-10-23 18:59:13] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Oct 23 19:59:13 volumio volumio-remote-updater[896]: [2025-10-23 18:59:13] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Oct 23 19:59:13 volumio systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Oct 23 19:59:13 volumio systemd[1]: volumio.service: Failed with result 'exit-code'. Oct 23 19:59:13 volumio systemd[1]: volumio.service: Consumed 13.070s CPU time. Oct 23 19:59:13 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Oct 23 19:59:13 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Oct 23 19:59:14 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 3562. Oct 23 19:59:14 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Oct 23 19:59:14 volumio systemd[1]: Stopped volumio.service - Volumio Backend Module. Oct 23 19:59:14 volumio systemd[1]: volumio.service: Consumed 13.070s CPU time. Oct 23 19:59:14 volumio systemd[1]: Started volumio.service - Volumio Backend Module. Oct 23 19:59:14 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Oct 23 19:59:14 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 395. Oct 23 19:59:14 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 23 19:59:14 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 23 19:59:14 volumio go-librespot[2952]: go-librespot daemon starting... Oct 23 19:59:14 volumio go-librespot[2953]: time="2025-10-23T19:59:14+01:00" level=info msg="running go-librespot 0.4.0" Oct 23 19:59:14 volumio go-librespot[2953]: time="2025-10-23T19:59:14+01:00" level=debug msg="app state loaded" Oct 23 19:59:14 volumio go-librespot[2953]: time="2025-10-23T19:59:14+01:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 23 19:59:14 volumio volumio[2937]: info: ------------------------------------------- Oct 23 19:59:14 volumio volumio[2937]: info: ----- Volumio3 ---- Oct 23 19:59:14 volumio volumio[2937]: info: ------------------------------------------- Oct 23 19:59:14 volumio volumio[2937]: info: ----- System startup ---- Oct 23 19:59:14 volumio volumio[2937]: info: ------------------------------------------- Oct 23 19:59:14 volumio go-librespot[2953]: time="2025-10-23T19:59:14+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Oct 23 19:59:14 volumio go-librespot[2953]: time="2025-10-23T19:59:14+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 23 19:59:14 volumio go-librespot[2953]: time="2025-10-23T19:59:14+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 23 19:59:14 volumio go-librespot[2953]: time="2025-10-23T19:59:14+01:00" level=info msg="zeroconf server listening on port 40361" Oct 23 19:59:14 volumio go-librespot[2953]: time="2025-10-23T19:59:14+01:00" level=debug msg="obtained new client token: AACAqjNLbTcx5lKapD9Qxi9smIeiUmWvn/5g2EXCeh0Epe74YvaVrcejWnSqEVWGiYx3iB2RF5w27e9uIlz4DOcH8/i3o8WXHFRfwVw1QC9acHNSvAZ4OatLShBVVuxVoREZ4JD3N2GXR7BzRT5Yx8dG6kbs4ufi4rhwPgzKFVXKOwUEK5PNbXRp4PTzJJgXfPstLM4dAp5FocaYNFHqV3je+VgBQZEntHEIJi/6t+N4jlxH8VM9A74=" Oct 23 19:59:14 volumio go-librespot[2953]: time="2025-10-23T19:59:14+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 23 19:59:14 volumio volumio[2937]: info: MYVOLUMIO Environment detected Oct 23 19:59:14 volumio go-librespot[2953]: time="2025-10-23T19:59:14+01:00" level=debug msg="completed keyexchange" Oct 23 19:59:14 volumio go-librespot[2953]: time="2025-10-23T19:59:14+01:00" level=debug msg="completed challenge" Oct 23 19:59:14 volumio volumio[2937]: info: Plugin folders cleanup Oct 23 19:59:14 volumio volumio[2937]: info: Scanning into folder /volumio/app/plugins/ Oct 23 19:59:14 volumio volumio[2937]: info: Scanning category audio_interface Oct 23 19:59:14 volumio volumio[2937]: info: Scanning category miscellanea Oct 23 19:59:14 volumio volumio[2937]: info: Scanning category music_service Oct 23 19:59:14 volumio volumio[2937]: info: Scanning category plugins.json Oct 23 19:59:14 volumio volumio[2937]: info: Scanning category system_controller Oct 23 19:59:14 volumio volumio[2937]: info: Scanning category user_interface Oct 23 19:59:14 volumio volumio[2937]: info: Scanning into folder /data/plugins/ Oct 23 19:59:14 volumio volumio[2937]: info: Scanning category music_service Oct 23 19:59:14 volumio volumio[2937]: info: Scanning category user_interface Oct 23 19:59:14 volumio volumio[2937]: info: Plugin folders cleanup completed Oct 23 19:59:14 volumio volumio[2937]: info: ------------------------------------------- Oct 23 19:59:14 volumio volumio[2937]: info: ----- Core plugins startup ---- Oct 23 19:59:14 volumio volumio[2937]: info: ------------------------------------------- Oct 23 19:59:14 volumio volumio[2937]: info: Loading plugins from folder /volumio/app/plugins/ Oct 23 19:59:14 volumio volumio[2937]: info: Adding plugin upnp to MyMusic Plugins Oct 23 19:59:14 volumio volumio[2937]: info: Adding plugin airplay_emulation to MyMusic Plugins Oct 23 19:59:14 volumio volumio[2937]: info: Adding plugin upnp_browser to MyMusic Plugins Oct 23 19:59:14 volumio volumio[2937]: info: Loading plugins from folder /data/plugins/ Oct 23 19:59:14 volumio volumio[2937]: info: Loading plugin "system"... Oct 23 19:59:15 volumio volumio[2937]: info: Loading plugin "appearance"... Oct 23 19:59:15 volumio go-librespot[2953]: time="2025-10-23T19:59:15+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 23 19:59:15 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 23 19:59:15 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 23 19:59:15 volumio volumio[2937]: info: Loading plugin "network"... Oct 23 19:59:15 volumio volumio[2937]: info: Refreshing Cached IP Addresses Oct 23 19:59:15 volumio sudo[2974]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 23 19:59:15 volumio sudo[2974]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 23 19:59:15 volumio sudo[2976]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 23 19:59:15 volumio sudo[2976]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 23 19:59:15 volumio volumio[2937]: info: Loading plugin "services"... Oct 23 19:59:15 volumio sudo[2976]: pam_unix(sudo:session): session closed for user root Oct 23 19:59:15 volumio sudo[2974]: pam_unix(sudo:session): session closed for user root Oct 23 19:59:15 volumio volumio[2937]: info: Loading plugin "alsa_controller"... Oct 23 19:59:15 volumio sudo[2983]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Oct 23 19:59:15 volumio sudo[2983]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 23 19:59:15 volumio volumio[2937]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 23 19:59:15 volumio volumio[2937]: info: Loading plugin "wizard"... Oct 23 19:59:15 volumio volumio[2937]: info: Loading plugin "networkfs"... Oct 23 19:59:15 volumio volumio[2937]: info: Cannot mount NAS NAS at system boot, trial number 1 ,retrying in 5 seconds Oct 23 19:59:15 volumio volumio[2937]: info: Starting Udev Watcher for removable devices Oct 23 19:59:15 volumio volumio[2937]: info: Ignoring mount for partition: boot Oct 23 19:59:15 volumio volumio[2937]: info: Ignoring mount for partition: volumio Oct 23 19:59:15 volumio volumio[2937]: info: Ignoring mount for partition: volumio_data Oct 23 19:59:15 volumio volumio[2937]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 23 19:59:15 volumio volumio[2937]: info: Loading plugin "volumio_command_line_client"... Oct 23 19:59:15 volumio volumio[2937]: info: Loading plugin "upnp"... Oct 23 19:59:15 volumio volumio[2937]: info: [1761245955359] Starting Upmpd Daemon Oct 23 19:59:15 volumio volumio[2937]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 23 19:59:15 volumio volumio[2937]: info: Loading plugin "my_music"... Oct 23 19:59:15 volumio volumio[2937]: info: Loading plugin "mpd"... Oct 23 19:59:15 volumio volumio[2937]: info: Loading plugin "upnp_browser"... Oct 23 19:59:15 volumio volumio[2937]: info: Loading plugin "alarm-clock"... Oct 23 19:59:15 volumio volumio[2937]: info: Loading plugin "airplay_emulation"... Oct 23 19:59:15 volumio volumio[2937]: info: Starting Shairport Sync Oct 23 19:59:15 volumio volumio[2937]: info: Loading plugin "last_100"... Oct 23 19:59:15 volumio volumio[2937]: info: Loading plugin "webradio"... Oct 23 19:59:15 volumio volumio[2937]: info: Loading plugin "i2s_dacs"... Oct 23 19:59:15 volumio volumio[2937]: info: I2S DAC not set, start Auto-detection Oct 23 19:59:15 volumio volumio[2937]: info: Loading plugin "volumiodiscovery"... Oct 23 19:59:15 volumio volumio[2937]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Oct 23 19:59:15 volumio volumio[2937]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 23 19:59:15 volumio volumio[2937]: *** WARNING *** For more information see Oct 23 19:59:15 volumio volumio[2937]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Oct 23 19:59:15 volumio node[2937]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Oct 23 19:59:15 volumio volumio[2937]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 23 19:59:15 volumio volumio[2937]: *** WARNING *** For more information see Oct 23 19:59:15 volumio node[2937]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 23 19:59:15 volumio node[2937]: *** WARNING *** For more information see Oct 23 19:59:15 volumio node[2937]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Oct 23 19:59:15 volumio node[2937]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 23 19:59:15 volumio node[2937]: *** WARNING *** For more information see Oct 23 19:59:15 volumio volumio[2937]: info: Applying required configuration parameters for plugin volumiodiscovery Oct 23 19:59:15 volumio volumio[2937]: info: Discovery: Started advertising with name: Volumio Oct 23 19:59:16 volumio volumio[2937]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 23 19:59:16 volumio volumio[2937]: info: Loading plugin "spop"... Oct 23 19:59:16 volumio volumio[2937]: info: Loading plugin "ytcr"... Oct 23 19:59:17 volumio volumio[2937]: info: Loading plugin "outputs"... Oct 23 19:59:17 volumio volumio[2937]: info: Loading plugin "albumart"... Oct 23 19:59:17 volumio volumio[2937]: info: Plugin example_plugin is not enabled Oct 23 19:59:17 volumio volumio[2937]: info: Loading plugin "inputs"... Oct 23 19:59:17 volumio volumio[2937]: info: Loading plugin "updater_comm"... Oct 23 19:59:17 volumio volumio[2937]: info: Plugin mpdemulation is not enabled Oct 23 19:59:17 volumio volumio[2937]: info: Loading plugin "rest_api"... Oct 23 19:59:17 volumio volumio[2937]: info: Loading plugin "websocket"... Oct 23 19:59:17 volumio volumio[2937]: info: Starting Socket.io Server version 1.7.4 Oct 23 19:59:17 volumio volumio[2937]: info: Loading plugin "Systeminfo"... Oct 23 19:59:17 volumio volumio[2937]: info: Loading i18n strings for locale en Oct 23 19:59:17 volumio volumio[3009]: Forking 3 albumart workers Oct 23 19:59:17 volumio volumio[2937]: Updating browse sources language Oct 23 19:59:17 volumio volumio[2937]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 23 19:59:17 volumio volumio[2937]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 23 19:59:17 volumio volumio[2937]: info: CoreCommandRouter::initPlayerControls Oct 23 19:59:17 volumio volumio[2937]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 23 19:59:17 volumio volumio[2937]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 23 19:59:17 volumio volumio[2937]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 23 19:59:17 volumio volumio[2937]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 23 19:59:17 volumio volumio[2937]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 23 19:59:17 volumio volumio[2937]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 23 19:59:17 volumio volumio[2937]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 23 19:59:17 volumio volumio[2937]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 23 19:59:17 volumio volumio[2937]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 23 19:59:17 volumio volumio[2937]: Express server listening on port 3000 Oct 23 19:59:17 volumio volumio[2937]: [Metrics] WebUI: 2s 989.84ms Oct 23 19:59:17 volumio volumio[2937]: info: CoreStateMachine::resetVolumioState Oct 23 19:59:17 volumio volumio[2937]: info: CoreStateMachine::getcurrentVolume Oct 23 19:59:17 volumio volumio[2937]: info: CoreCommandRouter::volumioRetrievevolume Oct 23 19:59:17 volumio volumio[2937]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 23 19:59:17 volumio volumio[2937]: info: Cannot read play queue from file Oct 23 19:59:17 volumio volumio[2937]: info: Volumio Network Manager: Network status updated: 1 Oct 23 19:59:17 volumio volumio[2937]: info: VolumeController:: Volume=51 Mute =false Oct 23 19:59:17 volumio volumio[2937]: info: CoreStateMachine::pushState Oct 23 19:59:17 volumio volumio[2937]: info: CorePlayQueue::getTrack 0 Oct 23 19:59:17 volumio volumio[2937]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 23 19:59:17 volumio volumio[2937]: info: CoreCommandRouter::volumioPushState Oct 23 19:59:17 volumio volumio[2937]: info: CoreStateMachine::updateTrackBlock Oct 23 19:59:17 volumio volumio[2937]: info: CorePlayQueue::getTrackBlock Oct 23 19:59:17 volumio volumio[2937]: info: CoreCommandRouter::volumioRetrievevolume Oct 23 19:59:17 volumio volumio[2937]: info: CoreStateMachine::setRepeat null single undefined Oct 23 19:59:17 volumio volumio[2937]: info: CoreStateMachine::pushState Oct 23 19:59:17 volumio volumio[2937]: info: CorePlayQueue::getTrack 0 Oct 23 19:59:17 volumio volumio[2937]: info: CoreCommandRouter::volumioPushState Oct 23 19:59:17 volumio volumio[2937]: info: CoreStateMachine::setRandom null Oct 23 19:59:17 volumio volumio[2937]: info: CoreStateMachine::pushState Oct 23 19:59:17 volumio volumio[2937]: info: CorePlayQueue::getTrack 0 Oct 23 19:59:17 volumio volumio[2937]: info: CoreCommandRouter::volumioPushState Oct 23 19:59:17 volumio volumio[2937]: info: Setting Device type: Raspberry PI Oct 23 19:59:17 volumio volumio[2937]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Oct 23 19:59:17 volumio volumio[2937]: info: USB Boot Capable - System SBC Revision found in cpuinfo: b04170 Oct 23 19:59:17 volumio volumio[2937]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Oct 23 19:59:17 volumio volumio[2937]: info: Completed loading Core Plugins Oct 23 19:59:17 volumio volumio[2937]: info: Preparing to generate the ALSA configuration file Oct 23 19:59:17 volumio volumio[2937]: info: VolumeController:: Volume=51 Mute =false Oct 23 19:59:17 volumio volumio[2937]: info: CoreStateMachine::pushState Oct 23 19:59:17 volumio volumio[2937]: info: CorePlayQueue::getTrack 0 Oct 23 19:59:17 volumio volumio[2937]: info: CoreCommandRouter::volumioPushState Oct 23 19:59:17 volumio volumio[2937]: info: Discovery: adding 70853f74-8210-4683-a3fa-e1217517bd40 Oct 23 19:59:17 volumio volumio[2937]: info: Discovery: Found device Volumio Oct 23 19:59:17 volumio volumio[2937]: info: CoreCommandRouter::volumioGetState Oct 23 19:59:17 volumio volumio[2937]: info: CorePlayQueue::getTrack 0 Oct 23 19:59:17 volumio volumio[2937]: info: Discovery: this is already registered, 70853f74-8210-4683-a3fa-e1217517bd40 Oct 23 19:59:17 volumio volumio[2937]: info: Discovery: Found device Volumio Oct 23 19:59:17 volumio volumio[2937]: info: CoreCommandRouter::volumioGetState Oct 23 19:59:17 volumio volumio[2937]: info: CorePlayQueue::getTrack 0 Oct 23 19:59:17 volumio volumio[2937]: info: Asound.conf file unchanged, so no further update is needed Oct 23 19:59:17 volumio volumio[2937]: info: Output device has changed, restarting MPD Oct 23 19:59:17 volumio volumio[2937]: info: Output device has changed, restarting Shairport Sync Oct 23 19:59:17 volumio volumio[2937]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 23 19:59:17 volumio volumio[2937]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 23 19:59:17 volumio sudo[3065]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 23 19:59:17 volumio sudo[3065]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 23 19:59:17 volumio sudo[3065]: pam_unix(sudo:session): session closed for user root Oct 23 19:59:17 volumio sudo[3067]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 23 19:59:17 volumio sudo[3067]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 23 19:59:17 volumio volumio[2937]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 23 19:59:17 volumio volumio[2937]: info: ___________ START PLUGINS ___________ Oct 23 19:59:17 volumio volumio[2937]: info: ControllerMpd::onStart: Initializing MPD Oct 23 19:59:17 volumio volumio[2937]: info: Creating MPD Configuration file Oct 23 19:59:17 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Oct 23 19:59:17 volumio volumio[2937]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 23 19:59:17 volumio volumio[2937]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 23 19:59:17 volumio volumio[2937]: info: [1761245957866] CoreMusicLibrary::Adding element Media Servers Oct 23 19:59:17 volumio volumio[2937]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 23 19:59:17 volumio volumio[2937]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 23 19:59:17 volumio volumio[2937]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 23 19:59:17 volumio sudo[3077]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 23 19:59:17 volumio sudo[3077]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 23 19:59:17 volumio volumio[2937]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 23 19:59:17 volumio systemd[1]: mpd.service: Deactivated successfully. Oct 23 19:59:17 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Oct 23 19:59:17 volumio volumio[2937]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 23 19:59:17 volumio volumio[2937]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 23 19:59:17 volumio systemd[1]: mpd.socket: Deactivated successfully. Oct 23 19:59:17 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Oct 23 19:59:17 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Oct 23 19:59:17 volumio sudo[2983]: pam_unix(sudo:session): session closed for user root Oct 23 19:59:17 volumio sudo[3075]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 23 19:59:17 volumio sudo[3075]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 23 19:59:17 volumio sudo[3075]: pam_unix(sudo:session): session closed for user root Oct 23 19:59:17 volumio volumio[2937]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 23 19:59:17 volumio volumio[2937]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 23 19:59:17 volumio volumio[2937]: info: [1761245957913] CoreMusicLibrary::Adding element Last_100 Oct 23 19:59:17 volumio volumio[2937]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 23 19:59:17 volumio volumio[2937]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 23 19:59:17 volumio volumio[2937]: info: [1761245957914] CoreMusicLibrary::Adding element Webradio Oct 23 19:59:17 volumio volumio[2937]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 23 19:59:17 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Oct 23 19:59:17 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Oct 23 19:59:17 volumio volumio[2937]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 23 19:59:17 volumio volumio[2937]: info: Initializing BBC Radios Oct 23 19:59:17 volumio systemd[1]: mpd.service: Deactivated successfully. Oct 23 19:59:17 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Oct 23 19:59:17 volumio systemd[1]: mpd.socket: Deactivated successfully. Oct 23 19:59:17 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Oct 23 19:59:17 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Oct 23 19:59:17 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Oct 23 19:59:17 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Oct 23 19:59:17 volumio volumio[3021]: Starting albumart workers Oct 23 19:59:18 volumio volumio[2937]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 23 19:59:18 volumio volumio[2937]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 23 19:59:18 volumio volumio[2937]: info: Creating Spotify config file Oct 23 19:59:18 volumio volumio[2937]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 23 19:59:18 volumio sudo[3094]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Oct 23 19:59:18 volumio sudo[3094]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Oct 23 19:59:18 volumio sudo[3094]: pam_unix(sudo:session): session closed for user root Oct 23 19:59:18 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 396. Oct 23 19:59:18 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 23 19:59:18 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 23 19:59:18 volumio go-librespot[3106]: go-librespot daemon starting... Oct 23 19:59:18 volumio go-librespot[3107]: time="2025-10-23T19:59:18+01:00" level=info msg="running go-librespot 0.4.0" Oct 23 19:59:18 volumio volumio[3020]: Starting albumart workers Oct 23 19:59:18 volumio volumio[3019]: Starting albumart workers Oct 23 19:59:18 volumio go-librespot[3107]: time="2025-10-23T19:59:18+01:00" level=info msg="zeroconf server listening on port 45603" Oct 23 19:59:18 volumio volumio[2937]: info: Volumio Calling Home Oct 23 19:59:18 volumio volumio[2937]: info: MPD Permissions set Oct 23 19:59:18 volumio volumio[2937]: info: MPD Permissions set Oct 23 19:59:18 volumio volumio[2937]: info: Spotify config file written Oct 23 19:59:18 volumio sudo[3137]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Oct 23 19:59:18 volumio sudo[3137]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 23 19:59:18 volumio volumio[2937]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 1 Oct 23 19:59:18 volumio volumio[2937]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 23 19:59:18 volumio volumio[2937]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 23 19:59:18 volumio volumio[2937]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 23 19:59:18 volumio volumio[2937]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 23 19:59:18 volumio volumio[2937]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 23 19:59:18 volumio volumio[2937]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 23 19:59:18 volumio volumio[2937]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 23 19:59:18 volumio volumio[2937]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 23 19:59:18 volumio volumio[2937]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 23 19:59:18 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Oct 23 19:59:18 volumio volumio[2937]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 23 19:59:18 volumio volumio[2937]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 23 19:59:18 volumio volumio[2937]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 23 19:59:18 volumio volumio[2937]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 23 19:59:18 volumio volumio[2937]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 23 19:59:18 volumio volumio[2937]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 23 19:59:18 volumio volumio[2937]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 23 19:59:18 volumio volumio[2937]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 23 19:59:18 volumio volumio[2937]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 23 19:59:18 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Oct 23 19:59:18 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 23 19:59:18 volumio volumio[2937]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 23 19:59:18 volumio volumio[2937]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 23 19:59:18 volumio volumio[2937]: info: No need to fix Spotify hosts Oct 23 19:59:18 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 23 19:59:18 volumio go-librespot[3146]: go-librespot daemon starting... Oct 23 19:59:18 volumio sudo[3137]: pam_unix(sudo:session): session closed for user root Oct 23 19:59:18 volumio volumio[2937]: info: Volumio called home Oct 23 19:59:18 volumio volumio[2937]: info: Starting Shairport Sync Oct 23 19:59:18 volumio volumio[2937]: info: Starting Shairport Sync Oct 23 19:59:18 volumio go-librespot[3150]: time="2025-10-23T19:59:18+01:00" level=info msg="running go-librespot 0.4.0" Oct 23 19:59:18 volumio go-librespot[3150]: time="2025-10-23T19:59:18+01:00" level=debug msg="app state loaded" Oct 23 19:59:18 volumio go-librespot[3150]: time="2025-10-23T19:59:18+01:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 23 19:59:18 volumio volumio[2937]: info: Starting Shairport Sync Oct 23 19:59:18 volumio sudo[3156]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 23 19:59:18 volumio sudo[3156]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 23 19:59:18 volumio sudo[3158]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 23 19:59:18 volumio sudo[3158]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 23 19:59:18 volumio sudo[3162]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 23 19:59:18 volumio sudo[3162]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 23 19:59:18 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Oct 23 19:59:18 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Oct 23 19:59:18 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Oct 23 19:59:18 volumio systemd[1]: shairport-sync.service: Consumed 1.548s CPU time. Oct 23 19:59:18 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Oct 23 19:59:18 volumio sudo[3162]: pam_unix(sudo:session): session closed for user root Oct 23 19:59:18 volumio sudo[3156]: pam_unix(sudo:session): session closed for user root Oct 23 19:59:18 volumio sudo[3158]: pam_unix(sudo:session): session closed for user root Oct 23 19:59:18 volumio volumio[2937]: info: Shairport-Sync Started Oct 23 19:59:18 volumio volumio[2937]: Error adding Membership: Error: addMembership EINVAL Oct 23 19:59:18 volumio volumio[2937]: info: Shairport-Sync Started Oct 23 19:59:18 volumio volumio[2937]: info: Shairport-Sync Started Oct 23 19:59:18 volumio go-librespot[3150]: time="2025-10-23T19:59:18+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Oct 23 19:59:18 volumio go-librespot[3150]: time="2025-10-23T19:59:18+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Oct 23 19:59:18 volumio go-librespot[3150]: time="2025-10-23T19:59:18+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Oct 23 19:59:18 volumio volumio[2937]: info: CoreCommandRouter::volumioGetState Oct 23 19:59:18 volumio volumio[2937]: info: CorePlayQueue::getTrack 0 Oct 23 19:59:18 volumio go-librespot[3150]: time="2025-10-23T19:59:18+01:00" level=info msg="zeroconf server listening on port 37581" Oct 23 19:59:18 volumio volumio[2937]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Oct 23 19:59:18 volumio volumio[2937]: SPOTIFY: BQBxgCZi9cPKU1BYZfBOFXDnPlPgIQkuNsTOUbSCfBvtOmAivM3T7U-C8uyhAur_YzJmZ-J8CS8WoXMJtgHoEyZLn3sP0JfIw1EUQkTOZKQzqI4b_LMJ2ykV9XfHzwtrmxQCLmQokW0ZSVAp0YfuOb7tVVkHJi8_QDKe2v2SOLuD236dyvOZtOJn8_mD6cEvCkJ9aMoyWhm85w1DzN8ClrXbQlWhrc4LjNLUHCJt2XRy5eVVQoETB3LN1Ekck51YgAjiKHDV1jxbkNft8vGWStXOTWm-Jl8waUHspDg3HkqwksT9BOI Oct 23 19:59:18 volumio volumio[2937]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Oct 23 19:59:18 volumio volumio[2937]: info: New Spotify access token = BQBxgCZi9cPKU1BYZfBOFXDnPlPgIQkuNsTOUbSCfBvtOmAivM3T7U-C8uyhAur_YzJmZ-J8CS8WoXMJtgHoEyZLn3sP0JfIw1EUQkTOZKQzqI4b_LMJ2ykV9XfHzwtrmxQCLmQokW0ZSVAp0YfuOb7tVVkHJi8_QDKe2v2SOLuD236dyvOZtOJn8_mD6cEvCkJ9aMoyWhm85w1DzN8ClrXbQlWhrc4LjNLUHCJt2XRy5eVVQoETB3LN1Ekck51YgAjiKHDV1jxbkNft8vGWStXOTWm-Jl8waUHspDg3HkqwksT9BOI Oct 23 19:59:18 volumio volumio[2937]: info: Spotify credentials grant success - running version from March 24, 2019 Oct 23 19:59:18 volumio go-librespot[3150]: time="2025-10-23T19:59:18+01:00" level=debug msg="obtained new client token: AAAfdwaP0utWFz0aaOtF70CALNF56WNvA8QtRE97JjyEnxlq+vSV58h0hm+j8lgI7YPHRqSjXUANJVnjzhjlu0Byp0PaZjzSh9wBtXYF9fMl2KDLmZhJxMItI2qb3y27Tq2hqcWuMXo3hF3QsjA0hRTS7WffYdHtKSR/teA3lsT0njR42Z2dIEzRSbWnb2MPq9Av9XzPZcRGyfPV8W5ZJPYGtpMLrK/VD7uwRzK16DSx4ZufsOZC+v8=" Oct 23 19:59:18 volumio mpd[3108]: 2025-10-23T19:59:18 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Oct 23 19:59:18 volumio systemd[1]: Started mpd.service - Music Player Daemon. Oct 23 19:59:18 volumio sudo[3067]: pam_unix(sudo:session): session closed for user root Oct 23 19:59:18 volumio sudo[3077]: pam_unix(sudo:session): session closed for user root Oct 23 19:59:18 volumio go-librespot[3150]: time="2025-10-23T19:59:18+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 23 19:59:18 volumio go-librespot[3150]: time="2025-10-23T19:59:18+01:00" level=debug msg="completed keyexchange" Oct 23 19:59:18 volumio go-librespot[3150]: time="2025-10-23T19:59:18+01:00" level=debug msg="completed challenge" Oct 23 19:59:18 volumio volumio[2937]: error: MPD error: The expression evaluated to a falsy value: Oct 23 19:59:18 volumio volumio[2937]: assert.ok(self.idling) Oct 23 19:59:18 volumio volumio[2937]: error: The expression evaluated to a falsy value: Oct 23 19:59:18 volumio volumio[2937]: assert.ok(self.idling) Oct 23 19:59:18 volumio volumio[2937]: error: updateQueue error: null Oct 23 19:59:18 volumio volumio[2937]: info: MPD running with PID3108 Oct 23 19:59:18 volumio volumio[2937]: ,establishing connection Oct 23 19:59:18 volumio volumio[2937]: error: updateQueue error: null Oct 23 19:59:18 volumio volumio[2937]: SPOTIFY: User informations: {"country":"DE","display_name":"lapman","email":"ylm19961214@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/31hyzsop5elyyfayaiyk5tmkxmky"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/31hyzsop5elyyfayaiyk5tmkxmky","id":"31hyzsop5elyyfayaiyk5tmkxmky","images":[],"product":"free","type":"user","uri":"spotify:user:31hyzsop5elyyfayaiyk5tmkxmky"} Oct 23 19:59:18 volumio volumio[2937]: info: Spotify Successfully logged in Oct 23 19:59:18 volumio volumio[2937]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 23 19:59:18 volumio volumio[2937]: info: [1761245958903] CoreMusicLibrary::Adding element Spotify Oct 23 19:59:18 volumio volumio[2937]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 23 19:59:18 volumio volumio[2937]: Cannot find translation for source Spotify Oct 23 19:59:18 volumio go-librespot[3150]: time="2025-10-23T19:59:18+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 23 19:59:18 volumio volumio-remote-updater[896]: [2025-10-23 18:59:18] [connect] Successful connection Oct 23 19:59:18 volumio volumio-remote-updater[896]: [2025-10-23 18:59:18] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1761245958 101 Oct 23 19:59:18 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 23 19:59:18 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 23 19:59:18 volumio volumio[2937]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 3 Transport: websocket Total Clients: 2 Oct 23 19:59:19 volumio volumio[2937]: info: [yt-cast-receiver] DIAL server listening on port 8098 Oct 23 19:59:19 volumio volumio[2937]: info: CoreCommandRouter::volumioRetrievevolume Oct 23 19:59:19 volumio volumio[2937]: info: VolumeController:: Volume=51 Mute =false Oct 23 19:59:19 volumio volumio[2937]: info: CoreCommandRouter::volumioGetState Oct 23 19:59:19 volumio volumio[2937]: info: CorePlayQueue::getTrack 0 Oct 23 19:59:19 volumio volumio[2937]: info: CoreStateMachine::pushState Oct 23 19:59:19 volumio volumio[2937]: info: CorePlayQueue::getTrack 0 Oct 23 19:59:19 volumio volumio[2937]: info: CoreCommandRouter::volumioPushState Oct 23 19:59:19 volumio volumio[2937]: info: Completed starting Core Plugins Oct 23 19:59:19 volumio volumio[2937]: info: ------------------------------------------- Oct 23 19:59:19 volumio volumio[2937]: info: ----- MyVolumio plugins startup ---- Oct 23 19:59:19 volumio volumio[2937]: info: ------------------------------------------- Oct 23 19:59:19 volumio volumio[2937]: info: [MyVolumio PluginManager] Fetching plans data.... Oct 23 19:59:20 volumio volumio[2937]: info: Cannot mount NAS NAS at system boot, trial number 2 ,retrying in 5 seconds Oct 23 19:59:21 volumio volumio[2937]: info: go-librespot daemon successfully initialized Oct 23 19:59:21 volumio sudo[3188]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Oct 23 19:59:21 volumio sudo[3188]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 23 19:59:21 volumio sudo[3190]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Oct 23 19:59:21 volumio sudo[3190]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 23 19:59:21 volumio systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Oct 23 19:59:21 volumio systemd[1]: mpd_monitor.service: Deactivated successfully. Oct 23 19:59:21 volumio systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Oct 23 19:59:21 volumio systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Oct 23 19:59:21 volumio sudo[3190]: pam_unix(sudo:session): session closed for user root Oct 23 19:59:21 volumio sudo[3188]: pam_unix(sudo:session): session closed for user root Oct 23 19:59:21 volumio mpd_monitor.sh[3193]: MPD Monitor Service: Starting MPD Monitor Service Oct 23 19:59:21 volumio volumio[2937]: info: Successfully started MPD Monitor Oct 23 19:59:21 volumio volumio[2937]: info: Successfully started MPD Monitor Oct 23 19:59:22 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Oct 23 19:59:22 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 23 19:59:22 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 23 19:59:22 volumio go-librespot[3197]: go-librespot daemon starting... Oct 23 19:59:22 volumio go-librespot[3198]: time="2025-10-23T19:59:22+01:00" level=info msg="running go-librespot 0.4.0" Oct 23 19:59:22 volumio go-librespot[3198]: time="2025-10-23T19:59:22+01:00" level=debug msg="app state loaded" Oct 23 19:59:22 volumio go-librespot[3198]: time="2025-10-23T19:59:22+01:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 23 19:59:22 volumio go-librespot[3198]: time="2025-10-23T19:59:22+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Oct 23 19:59:22 volumio go-librespot[3198]: time="2025-10-23T19:59:22+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 23 19:59:22 volumio go-librespot[3198]: time="2025-10-23T19:59:22+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 23 19:59:22 volumio go-librespot[3198]: time="2025-10-23T19:59:22+01:00" level=info msg="zeroconf server listening on port 33113" Oct 23 19:59:22 volumio go-librespot[3198]: time="2025-10-23T19:59:22+01:00" level=debug msg="obtained new client token: AADe84CPWcHSJujhbSh7lt9vas5MPpsBRQs1DS4fTuctmb0AYCMfDx5fK92rHk26H526/KI4CKwfuZjU9/if/6b+N0SygQalkcjFeL3/mVN1u3+ZxlhsTj0nERVs1sLkoWuBHdghsfORVG07Lc450VKefFGL4u+EumZAVC/4qPld9oj9/9M2aBN4aOKCktlNEnJXN7rmPJmgw3AVeiQ2uA62PngsblBDpxj5cZK3MiHxaQC3orVOSLo=" Oct 23 19:59:22 volumio go-librespot[3198]: time="2025-10-23T19:59:22+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 23 19:59:22 volumio go-librespot[3198]: time="2025-10-23T19:59:22+01:00" level=debug msg="completed keyexchange" Oct 23 19:59:22 volumio go-librespot[3198]: time="2025-10-23T19:59:22+01:00" level=debug msg="completed challenge" Oct 23 19:59:22 volumio go-librespot[3198]: time="2025-10-23T19:59:22+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 23 19:59:22 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 23 19:59:22 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 23 19:59:23 volumio volumio[2937]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Oct 23 19:59:24 volumio volumio[2937]: info: Initializing connection to go-librespot Websocket Oct 23 19:59:24 volumio volumio[2937]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 23 19:59:25 volumio volumio[2937]: info: Cannot mount NAS NAS at system boot, trial number 3 ,retrying in 5 seconds Oct 23 19:59:25 volumio sudo[3221]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 23 19:59:25 volumio sudo[3221]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 23 19:59:25 volumio sudo[3221]: pam_unix(sudo:session): session closed for user root Oct 23 19:59:25 volumio sudo[3223]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 23 19:59:25 volumio sudo[3223]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 23 19:59:25 volumio sudo[3223]: pam_unix(sudo:session): session closed for user root Oct 23 19:59:25 volumio sudo[3226]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Oct 23 19:59:25 volumio sudo[3226]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 23 19:59:25 volumio sudo[3226]: pam_unix(sudo:session): session closed for user root Oct 23 19:59:25 volumio volumio[2937]: info: Upmpdcli Daemon Started Oct 23 19:59:25 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Oct 23 19:59:25 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 23 19:59:25 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 23 19:59:25 volumio go-librespot[3229]: go-librespot daemon starting... Oct 23 19:59:25 volumio go-librespot[3230]: time="2025-10-23T19:59:25+01:00" level=info msg="running go-librespot 0.4.0" Oct 23 19:59:25 volumio go-librespot[3230]: time="2025-10-23T19:59:25+01:00" level=debug msg="app state loaded" Oct 23 19:59:25 volumio go-librespot[3230]: time="2025-10-23T19:59:25+01:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 23 19:59:25 volumio go-librespot[3230]: time="2025-10-23T19:59:25+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Oct 23 19:59:25 volumio go-librespot[3230]: time="2025-10-23T19:59:25+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 23 19:59:25 volumio go-librespot[3230]: time="2025-10-23T19:59:25+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 23 19:59:25 volumio go-librespot[3230]: time="2025-10-23T19:59:25+01:00" level=info msg="zeroconf server listening on port 44269" Oct 23 19:59:25 volumio go-librespot[3230]: time="2025-10-23T19:59:25+01:00" level=debug msg="obtained new client token: AABLLJfFxl0qLP4WUfznLowkYnHrKxlLM7/d38RndYeenpEAFxuleaVXPz9Ny0+AWI2hsWaZWnVcEvKCDHKaFS6l66vBVVgO6gqmFH+HeEKd9VUzi7oplr7uedguUBi48YzR0yzUTbh4n3FZ9Lwh562/WF9HnFdVE0c4fsuXfjYKwauVEd7aXalLmesoZ5JL067uURWh5SbFKMOTM7ZZJOn7/kXeoBhk+YKgRfQDXARfvw51CHtOzbc=" Oct 23 19:59:25 volumio go-librespot[3230]: time="2025-10-23T19:59:25+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 23 19:59:25 volumio go-librespot[3230]: time="2025-10-23T19:59:25+01:00" level=debug msg="completed keyexchange" Oct 23 19:59:25 volumio go-librespot[3230]: time="2025-10-23T19:59:25+01:00" level=debug msg="completed challenge" Oct 23 19:59:26 volumio go-librespot[3230]: time="2025-10-23T19:59:26+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 23 19:59:26 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 23 19:59:26 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 23 19:59:27 volumio volumio[2937]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Oct 23 19:59:27 volumio volumio[2937]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Oct 23 19:59:27 volumio volumio[2937]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Oct 23 19:59:27 volumio volumio[2937]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Oct 23 19:59:27 volumio volumio[2937]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Oct 23 19:59:27 volumio volumio[2937]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Oct 23 19:59:27 volumio volumio[2937]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Oct 23 19:59:27 volumio volumio[2937]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Oct 23 19:59:27 volumio volumio[2937]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Oct 23 19:59:27 volumio volumio[2937]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Oct 23 19:59:27 volumio volumio[2937]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Oct 23 19:59:27 volumio volumio[2937]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Oct 23 19:59:27 volumio volumio[2937]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Oct 23 19:59:27 volumio volumio[2937]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Oct 23 19:59:27 volumio volumio[2937]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Oct 23 19:59:27 volumio volumio[2937]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Oct 23 19:59:27 volumio volumio[2937]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Oct 23 19:59:27 volumio volumio[2937]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Oct 23 19:59:27 volumio volumio[2937]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Oct 23 19:59:27 volumio volumio[2937]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Oct 23 19:59:27 volumio volumio[2937]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Oct 23 19:59:27 volumio volumio[2937]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Oct 23 19:59:27 volumio volumio[2937]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Oct 23 19:59:27 volumio volumio[2937]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Oct 23 19:59:27 volumio volumio[2937]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Oct 23 19:59:27 volumio volumio[2937]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Oct 23 19:59:27 volumio volumio[2937]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Oct 23 19:59:27 volumio volumio[2937]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Oct 23 19:59:27 volumio volumio[2937]: info: Adding plugin bluetooth to MyMusic Plugins Oct 23 19:59:27 volumio volumio[2937]: info: Adding plugin multiroom to MyMusic Plugins Oct 23 19:59:27 volumio volumio[2937]: info: Adding plugin metavolumio to MyMusic Plugins Oct 23 19:59:27 volumio volumio[2937]: info: Adding plugin cd_controller to MyMusic Plugins Oct 23 19:59:27 volumio volumio[2937]: info: Adding plugin qobuzconnect to MyMusic Plugins Oct 23 19:59:27 volumio volumio[2937]: info: Adding plugin smart_inputs to MyMusic Plugins Oct 23 19:59:27 volumio volumio[2937]: info: Adding plugin tidalconnect to MyMusic Plugins Oct 23 19:59:27 volumio volumio[2937]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Oct 23 19:59:27 volumio volumio[2937]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Oct 23 19:59:27 volumio volumio[2937]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Oct 23 19:59:27 volumio volumio[2937]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 23 19:59:27 volumio volumio[2937]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 23 19:59:27 volumio volumio[2937]: info: Starting MyVolumio Remote Streaming Endpoints Oct 23 19:59:27 volumio volumio[2937]: info: MyVolumio login type: Token Oct 23 19:59:27 volumio volumio[2937]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Oct 23 19:59:27 volumio volumio[2937]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Oct 23 19:59:28 volumio volumio[2937]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Oct 23 19:59:28 volumio volumio[2937]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Oct 23 19:59:28 volumio volumio[2937]: info: Streaming services startup Oct 23 19:59:28 volumio volumio[2937]: info: Starting Streaming Daemon Oct 23 19:59:28 volumio sudo[3241]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Oct 23 19:59:28 volumio sudo[3241]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 23 19:59:28 volumio volumio[2937]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Oct 23 19:59:28 volumio sudo[3241]: pam_unix(sudo:session): session closed for user root Oct 23 19:59:28 volumio volumio[2937]: info: Initializing connection to go-librespot Websocket Oct 23 19:59:28 volumio volumio[2937]: error: Cannot start Volumio Streaming Daemon Oct 23 19:59:28 volumio volumio[2937]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Oct 23 19:59:28 volumio volumio[2937]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Oct 23 19:59:28 volumio volumio[2937]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 23 19:59:28 volumio volumio[2937]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Oct 23 19:59:29 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Oct 23 19:59:29 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 23 19:59:29 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 23 19:59:29 volumio go-librespot[3247]: go-librespot daemon starting... Oct 23 19:59:29 volumio go-librespot[3248]: time="2025-10-23T19:59:29+01:00" level=info msg="running go-librespot 0.4.0" Oct 23 19:59:29 volumio go-librespot[3248]: time="2025-10-23T19:59:29+01:00" level=debug msg="app state loaded" Oct 23 19:59:29 volumio go-librespot[3248]: time="2025-10-23T19:59:29+01:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 23 19:59:29 volumio volumio[2937]: info: MyVolumio token set successfully Oct 23 19:59:29 volumio volumio[2937]: info: MYVOLUMIO: Adding device Oct 23 19:59:29 volumio volumio[2937]: info: MYVOLUMIO: Evaluating Server Oct 23 19:59:29 volumio go-librespot[3248]: time="2025-10-23T19:59:29+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Oct 23 19:59:29 volumio go-librespot[3248]: time="2025-10-23T19:59:29+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 23 19:59:29 volumio go-librespot[3248]: time="2025-10-23T19:59:29+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 23 19:59:29 volumio go-librespot[3248]: time="2025-10-23T19:59:29+01:00" level=info msg="zeroconf server listening on port 41597" Oct 23 19:59:29 volumio go-librespot[3248]: time="2025-10-23T19:59:29+01:00" level=debug msg="obtained new client token: AAAwjgzcyB0ticnzVCS7pBBrhT3p1e13fsnepiPZGW5EddVyjhtx+47tHUxeqtLkHv6uAGJKEVPr5EiB3Ih8C5o9CB85esxeQ2Q+bM/eTjWAAU0HLcidnwVk28mh4Eh+PQad0MUVF6r8dgxhFUgtE36iKtSX9zRV9sXG86pKiDUtrQY9BE207Dc4q+zL7LDf8dWNG1nS7t8GPdcfmGlW+PpCor6nSSVBOXicPCCnvr6KeMW5kjIb3IA=" Oct 23 19:59:29 volumio go-librespot[3248]: time="2025-10-23T19:59:29+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 23 19:59:29 volumio volumio[2937]: info: MyVolumio status changed Oct 23 19:59:29 volumio volumio[2937]: info: Streaming services startup Oct 23 19:59:29 volumio volumio[2937]: info: Starting Streaming Daemon Oct 23 19:59:29 volumio volumio[2937]: info: Removing browser output: myVolumio user plan is not superstar Oct 23 19:59:29 volumio volumio[2937]: info: Removing audio output: Oct 23 19:59:29 volumio volumio[2937]: info: Stoppping Tunnel 1 Oct 23 19:59:29 volumio sudo[3273]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Oct 23 19:59:29 volumio sudo[3273]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 23 19:59:29 volumio go-librespot[3248]: time="2025-10-23T19:59:29+01:00" level=debug msg="completed keyexchange" Oct 23 19:59:29 volumio go-librespot[3248]: time="2025-10-23T19:59:29+01:00" level=debug msg="completed challenge" Oct 23 19:59:29 volumio sudo[3275]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service Oct 23 19:59:29 volumio sudo[3275]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 23 19:59:29 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Oct 23 19:59:29 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Oct 23 19:59:29 volumio sudo[3273]: pam_unix(sudo:session): session closed for user root Oct 23 19:59:29 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Oct 23 19:59:29 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Oct 23 19:59:29 volumio volumio[2937]: error: Cannot start Volumio Streaming Daemon Oct 23 19:59:29 volumio volumio[2937]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Oct 23 19:59:29 volumio volumio[2937]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Oct 23 19:59:29 volumio go-librespot[3248]: time="2025-10-23T19:59:29+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 23 19:59:29 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Oct 23 19:59:29 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Oct 23 19:59:29 volumio sudo[3275]: pam_unix(sudo:session): session closed for user root Oct 23 19:59:29 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 23 19:59:29 volumio volumio[2937]: info: Remote SSH Stopped Oct 23 19:59:29 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 23 19:59:29 volumio volumio[2937]: info: Setting Geolocation for MyVolumio to eu3 Oct 23 19:59:29 volumio volumio[2937]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 23 19:59:29 volumio volumio[2937]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 23 19:59:29 volumio volumio[2937]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 23 19:59:29 volumio volumio[2937]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Oct 23 19:59:30 volumio volumio[2937]: info: Cannot mount NAS NAS at system boot, trial number 4 ,retrying in 5 seconds Oct 23 19:59:30 volumio volumio[2937]: info: Updating MyVolumio device info Oct 23 19:59:30 volumio volumio[2937]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 23 19:59:30 volumio volumio[2937]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 23 19:59:30 volumio volumio[2937]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 23 19:59:30 volumio volumio[2937]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Oct 23 19:59:31 volumio volumio[2937]: info: Initializing connection to go-librespot Websocket Oct 23 19:59:31 volumio volumio[2937]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 23 19:59:32 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 4. Oct 23 19:59:32 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 23 19:59:32 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 23 19:59:32 volumio go-librespot[3278]: go-librespot daemon starting... Oct 23 19:59:32 volumio go-librespot[3279]: time="2025-10-23T19:59:32+01:00" level=info msg="running go-librespot 0.4.0" Oct 23 19:59:32 volumio go-librespot[3279]: time="2025-10-23T19:59:32+01:00" level=debug msg="app state loaded" Oct 23 19:59:32 volumio go-librespot[3279]: time="2025-10-23T19:59:32+01:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 23 19:59:32 volumio go-librespot[3279]: time="2025-10-23T19:59:32+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Oct 23 19:59:32 volumio go-librespot[3279]: time="2025-10-23T19:59:32+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Oct 23 19:59:32 volumio go-librespot[3279]: time="2025-10-23T19:59:32+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Oct 23 19:59:32 volumio go-librespot[3279]: time="2025-10-23T19:59:32+01:00" level=info msg="zeroconf server listening on port 35275" Oct 23 19:59:32 volumio go-librespot[3279]: time="2025-10-23T19:59:32+01:00" level=debug msg="obtained new client token: AAArnuSdjXy5hLkWa9/n72UjDNjCfOAlOClacYj1jCUeXnUKkuQsuZrmhIftTneTodWTycwoFbO8IPa6f37djBw8ZyGR12VdH3sEgOlQwnjwk5x/vhWXdtGBiOD6bp2YFpCcNi5EPfTsNubUkHCKhlddyoCaH5Hbrh5m3IglXv2jp4V+m+UMK5ZN+hJrrrYyxEmb12uTbFFoQ57wWX4pNvpaApC4lHsFEjYPSYyIJEaSd8FU1tRLNFQ=" Oct 23 19:59:32 volumio go-librespot[3279]: time="2025-10-23T19:59:32+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 23 19:59:32 volumio go-librespot[3279]: time="2025-10-23T19:59:32+01:00" level=debug msg="completed keyexchange" Oct 23 19:59:32 volumio go-librespot[3279]: time="2025-10-23T19:59:32+01:00" level=debug msg="completed challenge" Oct 23 19:59:32 volumio go-librespot[3279]: time="2025-10-23T19:59:32+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 23 19:59:32 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 23 19:59:32 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 23 19:59:33 volumio volumio[2937]: info: MYVOLUMIO: Adding device Oct 23 19:59:33 volumio volumio[2937]: info: MYVOLUMIO: Evaluating Server Oct 23 19:59:34 volumio volumio[2937]: info: Initializing connection to go-librespot Websocket Oct 23 19:59:34 volumio volumio[2937]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 23 19:59:34 volumio volumio[2937]: info: Setting Geolocation for MyVolumio to eu3 Oct 23 19:59:34 volumio volumio[2937]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 23 19:59:34 volumio volumio[2937]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 23 19:59:34 volumio volumio[2937]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 23 19:59:34 volumio volumio[2937]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Oct 23 19:59:35 volumio volumio[2937]: info: Cannot mount NAS at system boot, trial number 4 ,stopping Oct 23 19:59:35 volumio volumio[2937]: info: Updating MyVolumio device info Oct 23 19:59:35 volumio volumio[2937]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 23 19:59:35 volumio volumio[2937]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 23 19:59:35 volumio volumio[2937]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 23 19:59:35 volumio volumio[2937]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Oct 23 19:59:36 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 5. Oct 23 19:59:36 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 23 19:59:36 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 23 19:59:36 volumio go-librespot[3315]: go-librespot daemon starting... Oct 23 19:59:36 volumio go-librespot[3316]: time="2025-10-23T19:59:36+01:00" level=info msg="running go-librespot 0.4.0" Oct 23 19:59:36 volumio go-librespot[3316]: time="2025-10-23T19:59:36+01:00" level=debug msg="app state loaded" Oct 23 19:59:36 volumio go-librespot[3316]: time="2025-10-23T19:59:36+01:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 23 19:59:36 volumio go-librespot[3316]: time="2025-10-23T19:59:36+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Oct 23 19:59:36 volumio go-librespot[3316]: time="2025-10-23T19:59:36+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 23 19:59:36 volumio go-librespot[3316]: time="2025-10-23T19:59:36+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 23 19:59:36 volumio go-librespot[3316]: time="2025-10-23T19:59:36+01:00" level=info msg="zeroconf server listening on port 34673" Oct 23 19:59:36 volumio go-librespot[3316]: time="2025-10-23T19:59:36+01:00" level=debug msg="obtained new client token: AACPOz/NUpDZzOgGD/Z3OsDTK3+EUlDMJRsvYKuFFMRwOWhwxRr3FPSAxdbuppvWYpMxKJVAWCNPvcqoIomouQf74e0RT8PFQd2Y0DcMjYAmtNMnD6ZxQTN2dspXu1bWvEbYVJLXUXPl9dvvdxMP35FhHAP9CIYcTby4k4yC2LxW0M6bjMPHi5Yf39YomEjFkLe1JgvMB+I5o3dnRQYHxo7k7wreqCjVPSSbcCmQNyUznADuDBJjNTw=" Oct 23 19:59:36 volumio go-librespot[3316]: time="2025-10-23T19:59:36+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 23 19:59:36 volumio go-librespot[3316]: time="2025-10-23T19:59:36+01:00" level=debug msg="completed keyexchange" Oct 23 19:59:36 volumio go-librespot[3316]: time="2025-10-23T19:59:36+01:00" level=debug msg="completed challenge" Oct 23 19:59:36 volumio go-librespot[3316]: time="2025-10-23T19:59:36+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 23 19:59:36 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 23 19:59:36 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 23 19:59:37 volumio volumio[2937]: info: Initializing connection to go-librespot Websocket Oct 23 19:59:37 volumio volumio[2937]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 23 19:59:39 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6. Oct 23 19:59:39 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 23 19:59:39 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 23 19:59:39 volumio go-librespot[3324]: go-librespot daemon starting... Oct 23 19:59:39 volumio go-librespot[3325]: time="2025-10-23T19:59:39+01:00" level=info msg="running go-librespot 0.4.0" Oct 23 19:59:39 volumio go-librespot[3325]: time="2025-10-23T19:59:39+01:00" level=debug msg="app state loaded" Oct 23 19:59:39 volumio go-librespot[3325]: time="2025-10-23T19:59:39+01:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 23 19:59:39 volumio go-librespot[3325]: time="2025-10-23T19:59:39+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Oct 23 19:59:39 volumio go-librespot[3325]: time="2025-10-23T19:59:39+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Oct 23 19:59:39 volumio go-librespot[3325]: time="2025-10-23T19:59:39+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Oct 23 19:59:39 volumio go-librespot[3325]: time="2025-10-23T19:59:39+01:00" level=info msg="zeroconf server listening on port 46597" Oct 23 19:59:39 volumio go-librespot[3325]: time="2025-10-23T19:59:39+01:00" level=debug msg="obtained new client token: AABV+ARtZAVNmHePyYJWBqvBwJo24MJUhllaEpgri6j5msuW1dfNYzYZLXcGAdizwAPvFoNmG4yqArxUQL/3Wg5Z+or8hV5y120TwYLQnZAqQJ4z/rbWediQhfvCNaoGfS9HYdWUh4un2TAUpmYrTigtELT+4vaQjlqnFsw765B1VJ63Sy10UNsb5JqHCAPtT+O0Kz9xpHLhTxDgdIwQ5GO1WS2Uner8o7YtRCZvPkg3CVQgBxo0KMw=" Oct 23 19:59:39 volumio go-librespot[3325]: time="2025-10-23T19:59:39+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 23 19:59:39 volumio go-librespot[3325]: time="2025-10-23T19:59:39+01:00" level=debug msg="completed keyexchange" Oct 23 19:59:39 volumio go-librespot[3325]: time="2025-10-23T19:59:39+01:00" level=debug msg="completed challenge" Oct 23 19:59:39 volumio go-librespot[3325]: time="2025-10-23T19:59:39+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 23 19:59:39 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 23 19:59:39 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 23 19:59:40 volumio volumio[2937]: info: Initializing connection to go-librespot Websocket Oct 23 19:59:40 volumio volumio[2937]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 23 19:59:42 volumio volumio[2937]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Oct 23 19:59:42 volumio volumio[2937]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Oct 23 19:59:42 volumio volumio[2937]: info: CoreCommandRouter::volumioGetState Oct 23 19:59:42 volumio volumio[2937]: info: CorePlayQueue::getTrack 0 Oct 23 19:59:43 volumio volumio[2937]: info: Initializing connection to go-librespot Websocket Oct 23 19:59:43 volumio volumio[2937]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 23 19:59:43 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 7. Oct 23 19:59:43 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 23 19:59:43 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 23 19:59:43 volumio go-librespot[3335]: go-librespot daemon starting... Oct 23 19:59:43 volumio go-librespot[3336]: time="2025-10-23T19:59:43+01:00" level=info msg="running go-librespot 0.4.0" Oct 23 19:59:43 volumio go-librespot[3336]: time="2025-10-23T19:59:43+01:00" level=debug msg="app state loaded" Oct 23 19:59:43 volumio go-librespot[3336]: time="2025-10-23T19:59:43+01:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 23 19:59:43 volumio go-librespot[3336]: time="2025-10-23T19:59:43+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Oct 23 19:59:43 volumio go-librespot[3336]: time="2025-10-23T19:59:43+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 23 19:59:43 volumio go-librespot[3336]: time="2025-10-23T19:59:43+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 23 19:59:43 volumio go-librespot[3336]: time="2025-10-23T19:59:43+01:00" level=info msg="zeroconf server listening on port 33787" Oct 23 19:59:43 volumio go-librespot[3336]: time="2025-10-23T19:59:43+01:00" level=debug msg="obtained new client token: AABMs32VANeRgyNWyhLJldjLsr9bMSKzj+GDdfJ64fY0TFKCXX0OGGUbBIYsCg1pQql0+FZSbSY/KJ0/9OjGOwLhfwtchiyYkI8x49H3i+LJmJlx1YN+9UG6kcM/sK91bMsueP+PuWk0gvALoz5D18ULwxqDrWV3yiIwiSK9RDTNDctwGxCUgA8gMNjfFBc7+J+RGaqJd1PVyKC5urQbBeDJ7D31HllnaXPnT8N3dcKfTn/E/BiK4bo=" Oct 23 19:59:43 volumio go-librespot[3336]: time="2025-10-23T19:59:43+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 23 19:59:43 volumio go-librespot[3336]: time="2025-10-23T19:59:43+01:00" level=debug msg="completed keyexchange" Oct 23 19:59:43 volumio go-librespot[3336]: time="2025-10-23T19:59:43+01:00" level=debug msg="completed challenge" Oct 23 19:59:43 volumio go-librespot[3336]: time="2025-10-23T19:59:43+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 23 19:59:43 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 23 19:59:43 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 23 19:59:46 volumio volumio[2937]: info: Initializing connection to go-librespot Websocket Oct 23 19:59:46 volumio volumio[2937]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 23 19:59:46 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 8. Oct 23 19:59:46 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 23 19:59:46 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 23 19:59:46 volumio go-librespot[3357]: go-librespot daemon starting... Oct 23 19:59:46 volumio go-librespot[3358]: time="2025-10-23T19:59:46+01:00" level=info msg="running go-librespot 0.4.0" Oct 23 19:59:46 volumio go-librespot[3358]: time="2025-10-23T19:59:46+01:00" level=debug msg="app state loaded" Oct 23 19:59:46 volumio go-librespot[3358]: time="2025-10-23T19:59:46+01:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 23 19:59:46 volumio go-librespot[3358]: time="2025-10-23T19:59:46+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Oct 23 19:59:46 volumio go-librespot[3358]: time="2025-10-23T19:59:46+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 23 19:59:46 volumio go-librespot[3358]: time="2025-10-23T19:59:46+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 23 19:59:46 volumio go-librespot[3358]: time="2025-10-23T19:59:46+01:00" level=info msg="zeroconf server listening on port 35365" Oct 23 19:59:46 volumio go-librespot[3358]: time="2025-10-23T19:59:46+01:00" level=debug msg="obtained new client token: AABMy7/U4knLMB4xuSOifDfEi6N4rawAr9Mj9fDKCmcAEkIqFQnUxq1+oK+frXIkzQ/e7EZfbuVtMvxU65D1p10D8ysKRFPH1UntYyb880/Mr1X9jvBUunxJyoFkOo54fnLscsxVAmt16uG3SSHYptyC2gg3fKBQBAHS5aLXOQdYtWxod1NovJbRY50tBLXvvYOrZbFKIomyNjaRTLQeFD99ZqVIMPqGGld4cFhMk4j9bloU6pCZx2U=" Oct 23 19:59:46 volumio go-librespot[3358]: time="2025-10-23T19:59:46+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 23 19:59:46 volumio go-librespot[3358]: time="2025-10-23T19:59:46+01:00" level=debug msg="completed keyexchange" Oct 23 19:59:46 volumio go-librespot[3358]: time="2025-10-23T19:59:46+01:00" level=debug msg="completed challenge" Oct 23 19:59:46 volumio go-librespot[3358]: time="2025-10-23T19:59:46+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 23 19:59:46 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 23 19:59:46 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 23 19:59:47 volumio volumio[2937]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 23 19:59:47 volumio volumio[2937]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 23 19:59:47 volumio volumio[2937]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam Oct 23 19:59:47 volumio volumio[2937]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Oct 23 19:59:47 volumio volumio[2937]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Oct 23 19:59:47 volumio volumio[2937]: info: CoreCommandRouter::volumioGetBrowseSources Oct 23 19:59:47 volumio volumio[2937]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 23 19:59:48 volumio volumio[2937]: error: MyVolumio Plugin failed to authenticate in a timely fashion Oct 23 19:59:48 volumio volumio[2937]: info: Completed starting MyVolumio Plugin Oct 23 19:59:48 volumio volumio[2937]: [Metrics] CommandRouter: 33s 310.93ms Oct 23 19:59:48 volumio volumio[2937]: info: CoreCommandRouter::volumiosetStartupVolume Oct 23 19:59:48 volumio volumio[2937]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 23 19:59:48 volumio volumio[2937]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 23 19:59:48 volumio volumio[2937]: info: CoreCommandRouter::Close All Modals sent Oct 23 19:59:48 volumio volumio[2937]: info: CoreCommandRouter::Close All Modals sent Oct 23 19:59:48 volumio volumio[2937]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 23 19:59:48 volumio volumio[2937]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 23 19:59:48 volumio volumio[2937]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Oct 23 19:59:48 volumio volumio-remote-updater[896]: Test mode disabled Oct 23 19:59:48 volumio volumio-remote-updater[896]: Alpha mode disabled Oct 23 19:59:48 volumio volumio-remote-updater[896]: Alpha legacy test mode disabled Oct 23 19:59:48 volumio volumio[2937]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateEnabled Oct 23 19:59:48 volumio volumio[2937]: info: Update Ready: {"changeLogLink":"","description":"You're already on the latest version","title":"No Updates Available","updateavailable":false} Oct 23 19:59:48 volumio volumio[2937]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache Oct 23 19:59:49 volumio volumio[2937]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable Oct 23 19:59:49 volumio volumio[2937]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Oct 23 19:59:49 volumio volumio[2937]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect Oct 23 19:59:49 volumio volumio[2937]: info: Initializing connection to go-librespot Websocket Oct 23 19:59:49 volumio volumio[2937]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 23 19:59:50 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 9. Oct 23 19:59:50 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 23 19:59:50 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 23 19:59:50 volumio go-librespot[3375]: go-librespot daemon starting... Oct 23 19:59:50 volumio go-librespot[3376]: time="2025-10-23T19:59:50+01:00" level=info msg="running go-librespot 0.4.0" Oct 23 19:59:50 volumio go-librespot[3376]: time="2025-10-23T19:59:50+01:00" level=debug msg="app state loaded" Oct 23 19:59:50 volumio go-librespot[3376]: time="2025-10-23T19:59:50+01:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 23 19:59:50 volumio go-librespot[3376]: time="2025-10-23T19:59:50+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Oct 23 19:59:50 volumio go-librespot[3376]: time="2025-10-23T19:59:50+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 23 19:59:50 volumio go-librespot[3376]: time="2025-10-23T19:59:50+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 23 19:59:50 volumio go-librespot[3376]: time="2025-10-23T19:59:50+01:00" level=info msg="zeroconf server listening on port 46391" Oct 23 19:59:50 volumio go-librespot[3376]: time="2025-10-23T19:59:50+01:00" level=debug msg="obtained new client token: AACcIOhQUTj85gtbp75b27D/I5ZKKsvZQ+vHnGpsqRTmhjAjj0JOefgZuPG0IQjQbS0wmc4CcWXyI/4PfRi8kd7ZCPQvoBHj/N6Dum4zwMgsP1xOXG4cOMIem0CIXLST/pNtDD6ChEjAomkJC98v8+QTxwmLSdCoT7720ToT8X+Lo0Ersj7VtiKI4sgMs2e2Lq8OS50nAUkWMO68QxncX+d7acl2/RnUnD39N22c9ez++w4JAtnZeFs=" Oct 23 19:59:50 volumio go-librespot[3376]: time="2025-10-23T19:59:50+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 23 19:59:50 volumio go-librespot[3376]: time="2025-10-23T19:59:50+01:00" level=debug msg="completed keyexchange" Oct 23 19:59:50 volumio go-librespot[3376]: time="2025-10-23T19:59:50+01:00" level=debug msg="completed challenge" Oct 23 19:59:50 volumio go-librespot[3376]: time="2025-10-23T19:59:50+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 23 19:59:50 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 23 19:59:50 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 23 19:59:52 volumio volumio[2937]: info: Initializing connection to go-librespot Websocket Oct 23 19:59:52 volumio volumio[2937]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 23 19:59:53 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 10. Oct 23 19:59:53 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 23 19:59:53 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 23 19:59:53 volumio go-librespot[3383]: go-librespot daemon starting... Oct 23 19:59:53 volumio go-librespot[3384]: time="2025-10-23T19:59:53+01:00" level=info msg="running go-librespot 0.4.0" Oct 23 19:59:53 volumio go-librespot[3384]: time="2025-10-23T19:59:53+01:00" level=debug msg="app state loaded" Oct 23 19:59:53 volumio go-librespot[3384]: time="2025-10-23T19:59:53+01:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 23 19:59:53 volumio go-librespot[3384]: time="2025-10-23T19:59:53+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Oct 23 19:59:53 volumio go-librespot[3384]: time="2025-10-23T19:59:53+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 23 19:59:53 volumio go-librespot[3384]: time="2025-10-23T19:59:53+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 23 19:59:53 volumio go-librespot[3384]: time="2025-10-23T19:59:53+01:00" level=info msg="zeroconf server listening on port 44121" Oct 23 19:59:53 volumio go-librespot[3384]: time="2025-10-23T19:59:53+01:00" level=debug msg="obtained new client token: AADO67Bozd7vnhJVAMScFGomXxS584TACfwDaBa3X4zqys0MiHU8LromIZyVnpFvcyo5e29cHQjrbglPoJ0MbXljnMg7iRj+OBpHzkidhQfP6MQif9cLVsuhqBuM6Q4JW/d5pYszWhKLZgdPNGJ5VhYlDrrrVLQzcp4Ueouv2Reh+qLtkMt6Y9UmbfJzPG7PWxkCjgm7s1R8jjboX4kZbH695//1NG1T3B0/+bX82WMcuNYB9fdzDkw=" Oct 23 19:59:53 volumio go-librespot[3384]: time="2025-10-23T19:59:53+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 23 19:59:53 volumio go-librespot[3384]: time="2025-10-23T19:59:53+01:00" level=debug msg="completed keyexchange" Oct 23 19:59:53 volumio go-librespot[3384]: time="2025-10-23T19:59:53+01:00" level=debug msg="completed challenge" Oct 23 19:59:53 volumio go-librespot[3384]: time="2025-10-23T19:59:53+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 23 19:59:53 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 23 19:59:53 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 23 19:59:55 volumio volumio[2937]: info: BOOT COMPLETED Oct 23 19:59:55 volumio volumio[2937]: info: Initializing connection to go-librespot Websocket Oct 23 19:59:55 volumio volumio[2937]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 23 19:59:56 volumio nmbd[1166]: [2025/10/23 19:59:56.371201, 0] ../../source3/libsmb/nmblib.c:923(send_udp) Oct 23 19:59:56 volumio nmbd[1166]: Packet send failed to 127.0.0.1(137) ERRNO=Network is unreachable Oct 23 19:59:56 volumio nmbd[1166]: [2025/10/23 19:59:56.371784, 0] ../../source3/nmbd/nmbd_packets.c:180(send_netbios_packet) Oct 23 19:59:56 volumio nmbd[1166]: send_netbios_packet: send_packet() to IP 127.0.0.1 port 137 failed Oct 23 19:59:56 volumio nmbd[1166]: [2025/10/23 19:59:56.371924, 0] ../../source3/libsmb/nmblib.c:923(send_udp) Oct 23 19:59:56 volumio nmbd[1166]: Packet send failed to 127.0.0.1(137) ERRNO=Network is unreachable Oct 23 19:59:56 volumio nmbd[1166]: [2025/10/23 19:59:56.371957, 0] ../../source3/nmbd/nmbd_packets.c:180(send_netbios_packet) Oct 23 19:59:56 volumio nmbd[1166]: send_netbios_packet: send_packet() to IP 127.0.0.1 port 137 failed Oct 23 19:59:56 volumio nmbd[1166]: [2025/10/23 19:59:56.371982, 0] ../../source3/libsmb/nmblib.c:923(send_udp) Oct 23 19:59:56 volumio nmbd[1166]: Packet send failed to 127.0.0.1(137) ERRNO=Network is unreachable Oct 23 19:59:56 volumio nmbd[1166]: [2025/10/23 19:59:56.372002, 0] ../../source3/nmbd/nmbd_packets.c:180(send_netbios_packet) Oct 23 19:59:56 volumio nmbd[1166]: send_netbios_packet: send_packet() to IP 127.0.0.1 port 137 failed Oct 23 19:59:56 volumio nmbd[1166]: [2025/10/23 19:59:56.372024, 0] ../../source3/libsmb/nmblib.c:923(send_udp) Oct 23 19:59:56 volumio nmbd[1166]: Packet send failed to 127.0.0.1(137) ERRNO=Network is unreachable Oct 23 19:59:56 volumio nmbd[1166]: [2025/10/23 19:59:56.372043, 0] ../../source3/nmbd/nmbd_packets.c:180(send_netbios_packet) Oct 23 19:59:56 volumio nmbd[1166]: send_netbios_packet: send_packet() to IP 127.0.0.1 port 137 failed Oct 23 19:59:56 volumio nmbd[1166]: [2025/10/23 19:59:56.372072, 0] ../../source3/libsmb/nmblib.c:923(send_udp) Oct 23 19:59:56 volumio nmbd[1166]: Packet send failed to 127.0.0.1(137) ERRNO=Network is unreachable Oct 23 19:59:56 volumio nmbd[1166]: [2025/10/23 19:59:56.372091, 0] ../../source3/nmbd/nmbd_packets.c:180(send_netbios_packet) Oct 23 19:59:56 volumio nmbd[1166]: send_netbios_packet: send_packet() to IP 127.0.0.1 port 137 failed Oct 23 19:59:56 volumio nmbd[1166]: [2025/10/23 19:59:56.374160, 0] ../../source3/libsmb/nmblib.c:923(send_udp) Oct 23 19:59:56 volumio nmbd[1166]: Packet send failed to 192.168.1.255(138) ERRNO=Network is unreachable Oct 23 19:59:57 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 11. Oct 23 19:59:57 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 23 19:59:57 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 23 19:59:57 volumio go-librespot[3406]: go-librespot daemon starting... Oct 23 19:59:57 volumio go-librespot[3407]: time="2025-10-23T19:59:57+01:00" level=info msg="running go-librespot 0.4.0" Oct 23 19:59:57 volumio go-librespot[3407]: time="2025-10-23T19:59:57+01:00" level=debug msg="app state loaded" Oct 23 19:59:57 volumio go-librespot[3407]: time="2025-10-23T19:59:57+01:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 23 19:59:57 volumio go-librespot[3407]: time="2025-10-23T19:59:57+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Oct 23 19:59:57 volumio go-librespot[3407]: time="2025-10-23T19:59:57+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 23 19:59:57 volumio go-librespot[3407]: time="2025-10-23T19:59:57+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 23 19:59:57 volumio go-librespot[3407]: time="2025-10-23T19:59:57+01:00" level=info msg="zeroconf server listening on port 41851" Oct 23 19:59:57 volumio go-librespot[3407]: time="2025-10-23T19:59:57+01:00" level=debug msg="obtained new client token: AACrOJrAUJ58hpl6D6aQrOEy+DyRFCzLWKl5kOWhejZAmjbIFtetsndSKJqzo0YqaX4mzvcv1a7hKG/KIMmG4SfiX4waWq4akwFpS2f/gMRhmZgY5VO5dI/GYOUeK7YALCI294k0LykXgDHhtnf8r1f73LcRgpGDsDc+BYaowyoRBHd8XLdQ1GQHwH+KtOAcACJWHeJVl8vIVkBwSXWGquz1WQTCnZtDmoHHgduxbQIlOVzgfKToEF8=" Oct 23 19:59:57 volumio go-librespot[3407]: time="2025-10-23T19:59:57+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 23 19:59:57 volumio go-librespot[3407]: time="2025-10-23T19:59:57+01:00" level=debug msg="completed keyexchange" Oct 23 19:59:57 volumio go-librespot[3407]: time="2025-10-23T19:59:57+01:00" level=debug msg="completed challenge" Oct 23 19:59:57 volumio go-librespot[3407]: time="2025-10-23T19:59:57+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 23 19:59:57 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 23 19:59:57 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 23 19:59:58 volumio volumio[2937]: info: Initializing connection to go-librespot Websocket Oct 23 19:59:58 volumio volumio[2937]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 23 20:00:00 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 12. Oct 23 20:00:00 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 23 20:00:00 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 23 20:00:00 volumio go-librespot[3415]: go-librespot daemon starting... Oct 23 20:00:00 volumio go-librespot[3416]: time="2025-10-23T20:00:00+01:00" level=info msg="running go-librespot 0.4.0" Oct 23 20:00:00 volumio go-librespot[3416]: time="2025-10-23T20:00:00+01:00" level=debug msg="app state loaded" Oct 23 20:00:00 volumio go-librespot[3416]: time="2025-10-23T20:00:00+01:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 23 20:00:00 volumio go-librespot[3416]: time="2025-10-23T20:00:00+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Oct 23 20:00:00 volumio go-librespot[3416]: time="2025-10-23T20:00:00+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 23 20:00:00 volumio go-librespot[3416]: time="2025-10-23T20:00:00+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 23 20:00:00 volumio go-librespot[3416]: time="2025-10-23T20:00:00+01:00" level=info msg="zeroconf server listening on port 45737" Oct 23 20:00:00 volumio go-librespot[3416]: time="2025-10-23T20:00:00+01:00" level=debug msg="obtained new client token: AAB4sTCdrYTvgRwhikQRoyASWQj1Doc7RGqGAi7tc9Wvwwxnn4++m6e1Qh0jZwkJZem1q6bqudR/VDRPSk16PRAbP2XlRepuikk+6864+JXzwr2QwLnOKJDl0hgIJjFK+7d8KSxydr06YY+Vzlv/jUNR1ENzeySKFJ1onv3zrijXFZPOLvbKTrkIQwnti6UrsVvO5E3Hd8tF6M4UkymN+E4xbR8uRPHyRQ5e3wyJnVeuKi2eGa0qxqY=" Oct 23 20:00:00 volumio go-librespot[3416]: time="2025-10-23T20:00:00+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 23 20:00:00 volumio go-librespot[3416]: time="2025-10-23T20:00:00+01:00" level=debug msg="completed keyexchange" Oct 23 20:00:00 volumio go-librespot[3416]: time="2025-10-23T20:00:00+01:00" level=debug msg="completed challenge" Oct 23 20:00:00 volumio go-librespot[3416]: time="2025-10-23T20:00:00+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 23 20:00:00 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 23 20:00:00 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 23 20:00:01 volumio volumio[2937]: info: Initializing connection to go-librespot Websocket Oct 23 20:00:01 volumio volumio[2937]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 23 20:00:04 volumio volumio[2937]: info: Initializing connection to go-librespot Websocket Oct 23 20:00:04 volumio volumio[2937]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 23 20:00:04 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 13. Oct 23 20:00:04 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 23 20:00:04 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 23 20:00:04 volumio go-librespot[3426]: go-librespot daemon starting... Oct 23 20:00:04 volumio go-librespot[3427]: time="2025-10-23T20:00:04+01:00" level=info msg="running go-librespot 0.4.0" Oct 23 20:00:04 volumio go-librespot[3427]: time="2025-10-23T20:00:04+01:00" level=debug msg="app state loaded" Oct 23 20:00:04 volumio go-librespot[3427]: time="2025-10-23T20:00:04+01:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 23 20:00:04 volumio go-librespot[3427]: time="2025-10-23T20:00:04+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Oct 23 20:00:04 volumio go-librespot[3427]: time="2025-10-23T20:00:04+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 23 20:00:04 volumio go-librespot[3427]: time="2025-10-23T20:00:04+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 23 20:00:04 volumio go-librespot[3427]: time="2025-10-23T20:00:04+01:00" level=info msg="zeroconf server listening on port 39115" Oct 23 20:00:04 volumio go-librespot[3427]: time="2025-10-23T20:00:04+01:00" level=debug msg="obtained new client token: AADakY9AbgG5YMueyHKM1ITLU1A1kLosHMoMsWwfhOhj/hUL9L2zKwIKxrcMMmJCKzbVZ/2erv088KZu+GAqOmY+WsY68J9iDUuoKnvsfBYDKvBL3xc4vlGF86RBKQsYVXU2BuPIOSqPl01ic52RHiYYmhHzBWJc3q0FqGokZGgMuDqVuXrKpk9oPwKy8MgGl5RKUl8JaftcXzVDoClZKJM0I/tfeb9JyU6hTU9rsWRdcHNx69PD184=" Oct 23 20:00:04 volumio go-librespot[3427]: time="2025-10-23T20:00:04+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 23 20:00:04 volumio go-librespot[3427]: time="2025-10-23T20:00:04+01:00" level=debug msg="completed keyexchange" Oct 23 20:00:04 volumio go-librespot[3427]: time="2025-10-23T20:00:04+01:00" level=debug msg="completed challenge" Oct 23 20:00:04 volumio go-librespot[3427]: time="2025-10-23T20:00:04+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 23 20:00:04 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 23 20:00:04 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 23 20:00:07 volumio volumio[2937]: info: Initializing connection to go-librespot Websocket Oct 23 20:00:07 volumio volumio[2937]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 23 20:00:07 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 14. Oct 23 20:00:07 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 23 20:00:07 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 23 20:00:07 volumio go-librespot[3448]: go-librespot daemon starting... Oct 23 20:00:07 volumio go-librespot[3449]: time="2025-10-23T20:00:07+01:00" level=info msg="running go-librespot 0.4.0" Oct 23 20:00:07 volumio go-librespot[3449]: time="2025-10-23T20:00:07+01:00" level=debug msg="app state loaded" Oct 23 20:00:07 volumio go-librespot[3449]: time="2025-10-23T20:00:07+01:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 23 20:00:07 volumio go-librespot[3449]: time="2025-10-23T20:00:07+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Oct 23 20:00:07 volumio go-librespot[3449]: time="2025-10-23T20:00:07+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Oct 23 20:00:07 volumio go-librespot[3449]: time="2025-10-23T20:00:07+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Oct 23 20:00:07 volumio go-librespot[3449]: time="2025-10-23T20:00:07+01:00" level=info msg="zeroconf server listening on port 35339" Oct 23 20:00:07 volumio go-librespot[3449]: time="2025-10-23T20:00:07+01:00" level=debug msg="obtained new client token: AAA/BuIlkfgi4crk4KJf+K3UyNXcWdpXNoX0qLhBTBlJSEGXRtfY9r4hGKMkAt781MfsTXOoA5oHAur1d54bv7FXyBCTCXLDD8okeXrswazmYw2e/wu/hy4qGIgr8CQmGLIj3KRM7mGoh7su00hMSnBa0Gmmc5Y9izU0mqaK9EYvHA8XYlddfzyYOXTtDJJSbmNeSsE/wNgnTPSXTOCtKIVoz27HPSerf9r5IiWi/wiok5UUkb8hkZQ=" Oct 23 20:00:07 volumio go-librespot[3449]: time="2025-10-23T20:00:07+01:00" level=warning msg="failed to connect to AP ap-gew1.spotify.com:4070, retrying with a different AP" error="dial tcp 104.199.65.9:4070: connect: connection refused" Oct 23 20:00:07 volumio go-librespot[3449]: time="2025-10-23T20:00:07+01:00" level=debug msg="connected to ap-gew1.spotify.com:443" Oct 23 20:00:07 volumio go-librespot[3449]: time="2025-10-23T20:00:07+01:00" level=debug msg="completed keyexchange" Oct 23 20:00:07 volumio go-librespot[3449]: time="2025-10-23T20:00:07+01:00" level=debug msg="completed challenge" Oct 23 20:00:08 volumio go-librespot[3449]: time="2025-10-23T20:00:08+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 23 20:00:08 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 23 20:00:08 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 23 20:00:10 volumio volumio[2937]: info: Initializing connection to go-librespot Websocket Oct 23 20:00:10 volumio volumio[2937]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 23 20:00:11 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 15. Oct 23 20:00:11 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 23 20:00:11 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 23 20:00:11 volumio go-librespot[3456]: go-librespot daemon starting... Oct 23 20:00:11 volumio go-librespot[3457]: time="2025-10-23T20:00:11+01:00" level=info msg="running go-librespot 0.4.0" Oct 23 20:00:11 volumio go-librespot[3457]: time="2025-10-23T20:00:11+01:00" level=debug msg="app state loaded" Oct 23 20:00:11 volumio go-librespot[3457]: time="2025-10-23T20:00:11+01:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 23 20:00:11 volumio go-librespot[3457]: time="2025-10-23T20:00:11+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Oct 23 20:00:11 volumio go-librespot[3457]: time="2025-10-23T20:00:11+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 23 20:00:11 volumio go-librespot[3457]: time="2025-10-23T20:00:11+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 23 20:00:11 volumio go-librespot[3457]: time="2025-10-23T20:00:11+01:00" level=info msg="zeroconf server listening on port 40015" Oct 23 20:00:11 volumio go-librespot[3457]: time="2025-10-23T20:00:11+01:00" level=debug msg="obtained new client token: AABZJEwGc/x7xCXhnm9bM+f0ywZl0EicOlaoBKgGzUEIOUvsBpiWjqBnIkT1s+iSDXq0/XNlmiYk9XXYsl30OV8RXsPVFg1aFcaj40UOPshvwf4iHCAFjnivOiq9Smk6oPThyqcenqaFxLiSGXWwCs3oq6kH4PFWdd9Qrp1ywZOjLRfNT37dLZvTjaGJmSpcaakbCT5I21ROowKkwfo0CtSvQjjnKooKqEx7Ur1RwYvoAkojawh83yc=" Oct 23 20:00:11 volumio go-librespot[3457]: time="2025-10-23T20:00:11+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 23 20:00:11 volumio go-librespot[3457]: time="2025-10-23T20:00:11+01:00" level=debug msg="completed keyexchange" Oct 23 20:00:11 volumio go-librespot[3457]: time="2025-10-23T20:00:11+01:00" level=debug msg="completed challenge" Oct 23 20:00:11 volumio go-librespot[3457]: time="2025-10-23T20:00:11+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 23 20:00:11 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 23 20:00:11 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 23 20:00:13 volumio volumio[2937]: info: Initializing connection to go-librespot Websocket Oct 23 20:00:13 volumio volumio[2937]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 23 20:00:14 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 16. Oct 23 20:00:14 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 23 20:00:14 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 23 20:00:14 volumio go-librespot[3464]: go-librespot daemon starting... Oct 23 20:00:14 volumio go-librespot[3465]: time="2025-10-23T20:00:14+01:00" level=info msg="running go-librespot 0.4.0" Oct 23 20:00:14 volumio go-librespot[3465]: time="2025-10-23T20:00:14+01:00" level=debug msg="app state loaded" Oct 23 20:00:14 volumio go-librespot[3465]: time="2025-10-23T20:00:14+01:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 23 20:00:14 volumio go-librespot[3465]: time="2025-10-23T20:00:14+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Oct 23 20:00:14 volumio go-librespot[3465]: time="2025-10-23T20:00:14+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 23 20:00:14 volumio go-librespot[3465]: time="2025-10-23T20:00:14+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 23 20:00:14 volumio go-librespot[3465]: time="2025-10-23T20:00:14+01:00" level=info msg="zeroconf server listening on port 40635" Oct 23 20:00:14 volumio go-librespot[3465]: time="2025-10-23T20:00:14+01:00" level=debug msg="obtained new client token: AABriGYSRPjv9H5Z5m3QUy9Xoux3AUPfT8IkhTCIQd35rTq7pQ4XNaq/cGQNllbEg2g0uQ/NdkOqsHrHY7hP7QpX5g1Wp2j5PtK8+oSMHtTDLPE4kizG7IkO0XDD+35hTvElvZVehrY15pLiq6m4uFlq4n7kW3zwSdSmvvEsSsJIr4XpHoe6CTmf/GnaIawaNXauErXqSiSrR9t9HiapWo5AXGDKxXMJ0XLi7O60iFStkbTPLf2uYgw=" Oct 23 20:00:14 volumio go-librespot[3465]: time="2025-10-23T20:00:14+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 23 20:00:14 volumio go-librespot[3465]: time="2025-10-23T20:00:14+01:00" level=debug msg="completed keyexchange" Oct 23 20:00:14 volumio go-librespot[3465]: time="2025-10-23T20:00:14+01:00" level=debug msg="completed challenge" Oct 23 20:00:14 volumio go-librespot[3465]: time="2025-10-23T20:00:14+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 23 20:00:14 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 23 20:00:14 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 23 20:00:16 volumio volumio[2937]: info: Initializing connection to go-librespot Websocket Oct 23 20:00:16 volumio volumio[2937]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 23 20:00:18 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 17. Oct 23 20:00:18 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 23 20:00:18 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 23 20:00:18 volumio go-librespot[3487]: go-librespot daemon starting... Oct 23 20:00:18 volumio go-librespot[3488]: time="2025-10-23T20:00:18+01:00" level=info msg="running go-librespot 0.4.0" Oct 23 20:00:18 volumio go-librespot[3488]: time="2025-10-23T20:00:18+01:00" level=debug msg="app state loaded" Oct 23 20:00:18 volumio go-librespot[3488]: time="2025-10-23T20:00:18+01:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 23 20:00:18 volumio go-librespot[3488]: time="2025-10-23T20:00:18+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Oct 23 20:00:18 volumio go-librespot[3488]: time="2025-10-23T20:00:18+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 23 20:00:18 volumio go-librespot[3488]: time="2025-10-23T20:00:18+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 23 20:00:18 volumio go-librespot[3488]: time="2025-10-23T20:00:18+01:00" level=info msg="zeroconf server listening on port 38203" Oct 23 20:00:18 volumio go-librespot[3488]: time="2025-10-23T20:00:18+01:00" level=debug msg="obtained new client token: AADxxMQE5le7GdY4uPRAOVkj1ze6Y1fNI2qiR2ie4Pnf5+JjUVu+nkx+vpYQGarXAFnCTq67fV+YXD2LRBvlR6GMQ8OdEQmO7+ZHLzt3eKrMhdI5izq3lfn+XvkFmJ8VIYHY+Pm7LrKai0gw0KKq45mKFRoQMEQIjhwuW/3oVMs5HUCNc4WOI8ldGYkeNVBf8LmyVJzXhGvjXM1ZPh5SMSzcxLKroBcwhAUTfvVfSWjp/3kLw2HvMSM=" Oct 23 20:00:18 volumio go-librespot[3488]: time="2025-10-23T20:00:18+01:00" level=warning msg="failed to connect to AP ap-gew1.spotify.com:4070, retrying with a different AP" error="dial tcp 104.199.65.9:4070: connect: connection refused" Oct 23 20:00:18 volumio go-librespot[3488]: time="2025-10-23T20:00:18+01:00" level=debug msg="connected to ap-gew1.spotify.com:443" Oct 23 20:00:18 volumio go-librespot[3488]: time="2025-10-23T20:00:18+01:00" level=debug msg="completed keyexchange" Oct 23 20:00:18 volumio go-librespot[3488]: time="2025-10-23T20:00:18+01:00" level=debug msg="completed challenge" Oct 23 20:00:18 volumio go-librespot[3488]: time="2025-10-23T20:00:18+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 23 20:00:18 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 23 20:00:18 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 23 20:00:19 volumio volumio[2937]: info: Initializing connection to go-librespot Websocket Oct 23 20:00:19 volumio volumio[2937]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 23 20:00:21 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 18. Oct 23 20:00:21 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 23 20:00:21 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 23 20:00:21 volumio go-librespot[3495]: go-librespot daemon starting... Oct 23 20:00:21 volumio go-librespot[3496]: time="2025-10-23T20:00:21+01:00" level=info msg="running go-librespot 0.4.0" Oct 23 20:00:21 volumio go-librespot[3496]: time="2025-10-23T20:00:21+01:00" level=debug msg="app state loaded" Oct 23 20:00:21 volumio go-librespot[3496]: time="2025-10-23T20:00:21+01:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 23 20:00:21 volumio go-librespot[3496]: time="2025-10-23T20:00:21+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Oct 23 20:00:21 volumio go-librespot[3496]: time="2025-10-23T20:00:21+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 23 20:00:21 volumio go-librespot[3496]: time="2025-10-23T20:00:21+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 23 20:00:21 volumio go-librespot[3496]: time="2025-10-23T20:00:21+01:00" level=info msg="zeroconf server listening on port 45901" Oct 23 20:00:21 volumio go-librespot[3496]: time="2025-10-23T20:00:21+01:00" level=debug msg="obtained new client token: AAAuoar/qjNOh1Wjs2+xNdlbFGhHqRi5mwA7kgVJJzxsM0HFp2FhuVKkFC/vlmvRgNAYA409bwoBP+jpo1gumQsKqIbJ+MwW1ViwmA/PYVzlYeX3i4EnJJRB2hyXfpvPQKfX0gnKL/eekVBVg9jRYvJutQW5i8ByK7Z704qJcLeRAUiX8hIw4X/9vr1RPDgwLABfWh5gzHmpFCPWLun4Tx5IciaXV6T/74kwCzX7RtnLN/cVEAddnqU=" Oct 23 20:00:21 volumio go-librespot[3496]: time="2025-10-23T20:00:21+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 23 20:00:21 volumio go-librespot[3496]: time="2025-10-23T20:00:21+01:00" level=debug msg="completed keyexchange" Oct 23 20:00:21 volumio go-librespot[3496]: time="2025-10-23T20:00:21+01:00" level=debug msg="completed challenge" Oct 23 20:00:22 volumio go-librespot[3496]: time="2025-10-23T20:00:22+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 23 20:00:22 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 23 20:00:22 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 23 20:00:22 volumio volumio[2937]: info: Initializing connection to go-librespot Websocket Oct 23 20:00:22 volumio volumio[2937]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 23 20:00:25 volumio volumio[2937]: info: Initializing connection to go-librespot Websocket Oct 23 20:00:25 volumio volumio[2937]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 23 20:00:25 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 19. Oct 23 20:00:25 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 23 20:00:25 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 23 20:00:25 volumio go-librespot[3506]: go-librespot daemon starting... Oct 23 20:00:25 volumio go-librespot[3507]: time="2025-10-23T20:00:25+01:00" level=info msg="running go-librespot 0.4.0" Oct 23 20:00:25 volumio go-librespot[3507]: time="2025-10-23T20:00:25+01:00" level=debug msg="app state loaded" Oct 23 20:00:25 volumio go-librespot[3507]: time="2025-10-23T20:00:25+01:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 23 20:00:25 volumio go-librespot[3507]: time="2025-10-23T20:00:25+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Oct 23 20:00:25 volumio go-librespot[3507]: time="2025-10-23T20:00:25+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 23 20:00:25 volumio go-librespot[3507]: time="2025-10-23T20:00:25+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 23 20:00:25 volumio go-librespot[3507]: time="2025-10-23T20:00:25+01:00" level=info msg="zeroconf server listening on port 37573" Oct 23 20:00:25 volumio go-librespot[3507]: time="2025-10-23T20:00:25+01:00" level=debug msg="obtained new client token: AABByyytuq8/Jcfpi9d9Q8jw4j8welWW/z7khq/fCweTBSQAjtrFh/3muYdJkORn1LkwXOXF0IWf0Q8TFMI26emWEu6GQnHqR8YBH1/8e1zSnMZjD0C/eF1wk8cPZbe/lrWH3NUL9g5rc4iCQvAuQuznaheyTP/lq+DBrL/5u+321t8o4fB+g6TbStAAsyFjttE5nuq9kcRg5a0NOxrFsY7mZjFrwIjp9Gcz+V4vXZG87SNdSJ2hPMQ=" Oct 23 20:00:25 volumio go-librespot[3507]: time="2025-10-23T20:00:25+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 23 20:00:25 volumio go-librespot[3507]: time="2025-10-23T20:00:25+01:00" level=debug msg="completed keyexchange" Oct 23 20:00:25 volumio go-librespot[3507]: time="2025-10-23T20:00:25+01:00" level=debug msg="completed challenge" Oct 23 20:00:25 volumio go-librespot[3507]: time="2025-10-23T20:00:25+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 23 20:00:25 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 23 20:00:25 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 23 20:00:28 volumio volumio[2937]: info: Initializing connection to go-librespot Websocket Oct 23 20:00:28 volumio volumio[2937]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 23 20:00:28 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 20. Oct 23 20:00:28 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 23 20:00:28 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 23 20:00:28 volumio go-librespot[3529]: go-librespot daemon starting... Oct 23 20:00:28 volumio go-librespot[3530]: time="2025-10-23T20:00:28+01:00" level=info msg="running go-librespot 0.4.0" Oct 23 20:00:28 volumio go-librespot[3530]: time="2025-10-23T20:00:28+01:00" level=debug msg="app state loaded" Oct 23 20:00:28 volumio go-librespot[3530]: time="2025-10-23T20:00:28+01:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 23 20:00:28 volumio go-librespot[3530]: time="2025-10-23T20:00:28+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Oct 23 20:00:28 volumio go-librespot[3530]: time="2025-10-23T20:00:28+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Oct 23 20:00:28 volumio go-librespot[3530]: time="2025-10-23T20:00:28+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Oct 23 20:00:28 volumio go-librespot[3530]: time="2025-10-23T20:00:28+01:00" level=info msg="zeroconf server listening on port 36721" Oct 23 20:00:28 volumio go-librespot[3530]: time="2025-10-23T20:00:28+01:00" level=debug msg="obtained new client token: AACxq9maj/mPdMoaRIA6EXcMQ+9uqz1ok/HvG/6xFJCVxonTN/e/qRnGXWPctTzKkJ305pWj3oXZjh35TdQO2ESMJIfSy8Yd+dvYiotjLSvuqL4+1MKwilkYFsAOervikspLRAqU1Ni0KFzKa867jR5ZohA3HIPyz0GDdBorq5ZfR2yWfH6Ic5kpLzsVOue6mBNic64hiP2ztRFK0Hsqqi307ODRCPecPyhvL5EJWFCSOZZ5Drbldlo=" Oct 23 20:00:28 volumio go-librespot[3530]: time="2025-10-23T20:00:28+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 23 20:00:28 volumio go-librespot[3530]: time="2025-10-23T20:00:28+01:00" level=debug msg="completed keyexchange" Oct 23 20:00:28 volumio go-librespot[3530]: time="2025-10-23T20:00:28+01:00" level=debug msg="completed challenge" Oct 23 20:00:28 volumio go-librespot[3530]: time="2025-10-23T20:00:28+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 23 20:00:28 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 23 20:00:28 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 23 20:00:31 volumio volumio[2937]: info: Initializing connection to go-librespot Websocket Oct 23 20:00:31 volumio volumio[2937]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 23 20:00:32 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 21. Oct 23 20:00:32 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 23 20:00:32 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 23 20:00:32 volumio go-librespot[3537]: go-librespot daemon starting... Oct 23 20:00:32 volumio go-librespot[3538]: time="2025-10-23T20:00:32+01:00" level=info msg="running go-librespot 0.4.0" Oct 23 20:00:32 volumio go-librespot[3538]: time="2025-10-23T20:00:32+01:00" level=debug msg="app state loaded" Oct 23 20:00:32 volumio go-librespot[3538]: time="2025-10-23T20:00:32+01:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 23 20:00:32 volumio go-librespot[3538]: time="2025-10-23T20:00:32+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Oct 23 20:00:32 volumio go-librespot[3538]: time="2025-10-23T20:00:32+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 23 20:00:32 volumio go-librespot[3538]: time="2025-10-23T20:00:32+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 23 20:00:32 volumio go-librespot[3538]: time="2025-10-23T20:00:32+01:00" level=info msg="zeroconf server listening on port 36213" Oct 23 20:00:32 volumio go-librespot[3538]: time="2025-10-23T20:00:32+01:00" level=debug msg="obtained new client token: AACi67JwYOKGYJlzi3JLND1SjDzWHLLTb7mQJkWU8EQUv7WKZ66fnwx3i8D7ABg8t//TqGog8n29ILNhoQFA4kOVdmQewj1E05MRd0t07buzJcN6b1+vM5saJjwMxq/T9qYJGMBjygfCspM3t4ccu5cXhf2q9Q8DCKlh/OqHAwivadnmKSXwWBQqofA7L+OHHYOINQS+YMQzXVxgPn6jK9/ftewUWRsUXoXJz3V/NHeH2mvQQhOcvm0=" Oct 23 20:00:32 volumio go-librespot[3538]: time="2025-10-23T20:00:32+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 23 20:00:32 volumio go-librespot[3538]: time="2025-10-23T20:00:32+01:00" level=debug msg="completed keyexchange" Oct 23 20:00:32 volumio go-librespot[3538]: time="2025-10-23T20:00:32+01:00" level=debug msg="completed challenge" Oct 23 20:00:32 volumio go-librespot[3538]: time="2025-10-23T20:00:32+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 23 20:00:32 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 23 20:00:32 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 23 20:00:34 volumio volumio[2937]: info: Initializing connection to go-librespot Websocket Oct 23 20:00:34 volumio volumio[2937]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 23 20:00:35 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 22. Oct 23 20:00:35 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 23 20:00:35 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 23 20:00:35 volumio go-librespot[3559]: go-librespot daemon starting... Oct 23 20:00:35 volumio go-librespot[3560]: time="2025-10-23T20:00:35+01:00" level=info msg="running go-librespot 0.4.0" Oct 23 20:00:35 volumio go-librespot[3560]: time="2025-10-23T20:00:35+01:00" level=debug msg="app state loaded" Oct 23 20:00:35 volumio go-librespot[3560]: time="2025-10-23T20:00:35+01:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 23 20:00:35 volumio go-librespot[3560]: time="2025-10-23T20:00:35+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Oct 23 20:00:35 volumio go-librespot[3560]: time="2025-10-23T20:00:35+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 23 20:00:35 volumio go-librespot[3560]: time="2025-10-23T20:00:35+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 23 20:00:35 volumio go-librespot[3560]: time="2025-10-23T20:00:35+01:00" level=info msg="zeroconf server listening on port 44565" Oct 23 20:00:35 volumio go-librespot[3560]: time="2025-10-23T20:00:35+01:00" level=debug msg="obtained new client token: AAAGFr7Ot5Wsm9A0V9eWXL3G+wCOTBFrxWH1aw/rsK/vkqpmCMuqqIMRwPR54+YgdyAA8gb49aPoycNa+gR+bgyEb2vLXjwBzOYtvWJuPkZOSCSFQI1HQLnMVc9wn8m8S2HHOMbAw2htAgeP7v2NzkEtLLuOwJc1hJotdfvgZnC3vnwMjX2wgRjuR4qoKJe8Rftqp6+4Pg3KsZgTS4fwCtbYBY8z0eF8qQWW4xW0ygQ9DBerZs48dZA=" Oct 23 20:00:35 volumio go-librespot[3560]: time="2025-10-23T20:00:35+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 23 20:00:35 volumio go-librespot[3560]: time="2025-10-23T20:00:35+01:00" level=debug msg="completed keyexchange" Oct 23 20:00:35 volumio go-librespot[3560]: time="2025-10-23T20:00:35+01:00" level=debug msg="completed challenge" Oct 23 20:00:35 volumio go-librespot[3560]: time="2025-10-23T20:00:35+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 23 20:00:35 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 23 20:00:35 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 23 20:00:37 volumio volumio[2937]: info: Initializing connection to go-librespot Websocket Oct 23 20:00:37 volumio volumio[2937]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 23 20:00:39 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 23. Oct 23 20:00:39 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 23 20:00:39 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 23 20:00:39 volumio go-librespot[3569]: go-librespot daemon starting... Oct 23 20:00:39 volumio go-librespot[3570]: time="2025-10-23T20:00:39+01:00" level=info msg="running go-librespot 0.4.0" Oct 23 20:00:39 volumio go-librespot[3570]: time="2025-10-23T20:00:39+01:00" level=debug msg="app state loaded" Oct 23 20:00:39 volumio go-librespot[3570]: time="2025-10-23T20:00:39+01:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 23 20:00:40 volumio volumio[2937]: info: Initializing connection to go-librespot Websocket Oct 23 20:00:40 volumio go-librespot[3570]: time="2025-10-23T20:00:40+01:00" level=debug msg="new websocket client" Oct 23 20:00:40 volumio volumio[2937]: info: Connection to go-librespot Websocket established Oct 23 20:00:43 volumio volumio[2937]: info: Getting Spotify volume Oct 23 20:00:43 volumio volumio[2937]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 4 Oct 23 20:00:43 volumio volumio[2937]: info: CoreCommandRouter::volumioGetState Oct 23 20:00:43 volumio volumio[2937]: info: CorePlayQueue::getTrack 0 Oct 23 20:00:43 volumio volumio[2937]: SPOTIFY: RECEIVED VOLUMIO VOLUME 51 Oct 23 20:00:43 volumio volumio[2937]: SPOTIFY: SPOTIFY VOLUME undefined Oct 23 20:00:43 volumio volumio[2937]: SPOTIFY: VOLUMIO VOLUME 51 Oct 23 20:00:43 volumio volumio[2937]: info: Aligning Spotify Volume to Volumio Volume Oct 23 20:00:43 volumio volumio[2937]: info: CoreCommandRouter::volumioGetState Oct 23 20:00:43 volumio volumio[2937]: info: CorePlayQueue::getTrack 0 Oct 23 20:00:43 volumio volumio[2937]: info: Setting Spotify Volume from Volumio: 51 Oct 23 20:00:44 volumio go-librespot[3570]: time="2025-10-23T20:00:44+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Oct 23 20:00:44 volumio go-librespot[3570]: time="2025-10-23T20:00:44+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 23 20:00:44 volumio go-librespot[3570]: time="2025-10-23T20:00:44+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 23 20:00:44 volumio go-librespot[3570]: time="2025-10-23T20:00:44+01:00" level=info msg="zeroconf server listening on port 35841" Oct 23 20:00:44 volumio go-librespot[3570]: time="2025-10-23T20:00:44+01:00" level=debug msg="obtained new client token: AACaxmAlDHE41GG+mCc9KDtO7MKLVULiSSHrq2zLFLMd9ZgluUaCXqIJ/6in2Mx0+svJll4/RBzzUS3RDscTLraczzvpT3XZvQ3Vs7h7X86xSkMbhulSxCUO7AdXwEBTt8aoKGQxnAxzJYpQ7fcrBo2niWMOUmyGJb9cSb8XRHiXw01t+3q9ablIzT+NhCzMM4Bp/zi2dim5F1yjTDroaomPjHNq/+hrVmAlS7GVgoq7bo3Q+Izypno=" Oct 23 20:00:44 volumio go-librespot[3570]: time="2025-10-23T20:00:44+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 23 20:00:44 volumio go-librespot[3570]: time="2025-10-23T20:00:44+01:00" level=debug msg="completed keyexchange" Oct 23 20:00:44 volumio go-librespot[3570]: time="2025-10-23T20:00:44+01:00" level=debug msg="completed challenge" Oct 23 20:00:44 volumio volumio[2937]: SPOTIFY: SETTING SPOTIFY VOLUME 51 Oct 23 20:00:44 volumio volumio[2937]: info: Sending Spotify command with payload to local API: /player/volume Oct 23 20:00:44 volumio go-librespot[3570]: time="2025-10-23T20:00:44+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 23 20:00:44 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 23 20:00:44 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 23 20:00:44 volumio volumio[2937]: error: Failed to send command to Spotify local API: /player/volume: Error: socket hang up Oct 23 20:00:44 volumio volumio[2937]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 23 20:00:44 volumio volumio[2937]: Error: socket hang up Oct 23 20:00:44 volumio volumio[2937]: at connResetException (node:internal/errors:720:14) Oct 23 20:00:44 volumio volumio[2937]: at Socket.socketOnEnd (node:_http_client:519:23) Oct 23 20:00:44 volumio volumio[2937]: at Socket.emit (node:events:526:35) Oct 23 20:00:44 volumio volumio[2937]: at endReadableNT (node:internal/streams/readable:1376:12) Oct 23 20:00:44 volumio volumio[2937]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { Oct 23 20:00:44 volumio volumio[2937]: code: 'ECONNRESET', Oct 23 20:00:44 volumio volumio[2937]: response: undefined Oct 23 20:00:44 volumio volumio[2937]: } Oct 23 20:00:44 volumio volumio[2937]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 23 20:00:44 volumio sudo[3594]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-10-23 19:59' Oct 23 20:00:44 volumio sudo[3594]: 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"