Oct 24 04:20:00 volumio sudo[13236]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 24 04:20:00 volumio sudo[13236]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 24 04:20:00 volumio sudo[13236]: pam_unix(sudo:session): session closed for user root Oct 24 04:20:00 volumio volumio[13098]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:20:00 volumio volumio[13098]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 24 04:20:00 volumio sudo[13238]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 24 04:20:00 volumio sudo[13238]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 24 04:20:00 volumio systemd[1]: mpd.service: Deactivated successfully. Oct 24 04:20:00 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Oct 24 04:20:00 volumio systemd[1]: mpd.socket: Deactivated successfully. Oct 24 04:20:00 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Oct 24 04:20:00 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Oct 24 04:20:00 volumio volumio[13098]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 24 04:20:00 volumio volumio[13098]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:20:00 volumio volumio[13098]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 24 04:20:00 volumio volumio[13098]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 24 04:20:00 volumio volumio[13098]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 24 04:20:00 volumio volumio[13098]: info: [1761276000049] CoreMusicLibrary::Adding element Last_100 Oct 24 04:20:00 volumio volumio[13098]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 24 04:20:00 volumio volumio[13098]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 24 04:20:00 volumio volumio[13098]: info: [1761276000050] CoreMusicLibrary::Adding element Webradio Oct 24 04:20:00 volumio volumio[13098]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 24 04:20:00 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Oct 24 04:20:00 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Oct 24 04:20:00 volumio volumio[13098]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 24 04:20:00 volumio volumio[13098]: info: Initializing BBC Radios Oct 24 04:20:00 volumio systemd[1]: mpd.service: Deactivated successfully. Oct 24 04:20:00 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Oct 24 04:20:00 volumio systemd[1]: mpd.socket: Deactivated successfully. Oct 24 04:20:00 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Oct 24 04:20:00 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Oct 24 04:20:00 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Oct 24 04:20:00 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Oct 24 04:20:00 volumio volumio[13181]: Starting albumart workers Oct 24 04:20:00 volumio volumio[13182]: Starting albumart workers Oct 24 04:20:00 volumio volumio[13098]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 24 04:20:00 volumio volumio[13098]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 24 04:20:00 volumio volumio[13098]: info: Creating Spotify config file Oct 24 04:20:00 volumio volumio[13098]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:20:00 volumio sudo[13258]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Oct 24 04:20:00 volumio sudo[13258]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Oct 24 04:20:00 volumio sudo[13258]: pam_unix(sudo:session): session closed for user root Oct 24 04:20:00 volumio volumio[13180]: Starting albumart workers Oct 24 04:20:00 volumio volumio[13098]: info: Volumio Calling Home Oct 24 04:20:00 volumio volumio[13098]: info: MPD Permissions set Oct 24 04:20:00 volumio volumio[13098]: info: MPD Permissions set Oct 24 04:20:00 volumio volumio[13098]: info: Spotify config file written Oct 24 04:20:00 volumio sudo[13285]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Oct 24 04:20:00 volumio sudo[13285]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 24 04:20:00 volumio volumio[13098]: 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 24 04:20:00 volumio volumio[13098]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:20:00 volumio volumio[13098]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:20:00 volumio volumio[13098]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:20:00 volumio volumio[13098]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:20:00 volumio volumio[13098]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:20:00 volumio volumio[13098]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:20:00 volumio volumio[13098]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:20:00 volumio volumio[13098]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:20:00 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 24 04:20:00 volumio volumio[13098]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 24 04:20:00 volumio volumio[13098]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:20:00 volumio volumio[13098]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:20:00 volumio volumio[13098]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:20:00 volumio volumio[13098]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:20:00 volumio volumio[13098]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:20:00 volumio volumio[13098]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:20:00 volumio volumio[13098]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:20:00 volumio volumio[13098]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:20:00 volumio volumio[13098]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:20:00 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 24 04:20:00 volumio go-librespot[13289]: go-librespot daemon starting... Oct 24 04:20:00 volumio sudo[13285]: pam_unix(sudo:session): session closed for user root Oct 24 04:20:00 volumio volumio[13098]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 24 04:20:00 volumio volumio[13098]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:20:00 volumio volumio[13098]: info: No need to fix Spotify hosts Oct 24 04:20:00 volumio go-librespot[13298]: time="2025-10-24T04:20:00+01:00" level=info msg="running go-librespot 0.4.0" Oct 24 04:20:00 volumio go-librespot[13298]: time="2025-10-24T04:20:00+01:00" level=debug msg="app state loaded" Oct 24 04:20:00 volumio go-librespot[13298]: time="2025-10-24T04:20:00+01:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 24 04:20:00 volumio volumio[13098]: info: Volumio called home Oct 24 04:20:00 volumio volumio[13098]: info: Starting Shairport Sync Oct 24 04:20:00 volumio volumio[13098]: info: Starting Shairport Sync Oct 24 04:20:00 volumio volumio[13098]: info: Starting Shairport Sync Oct 24 04:20:00 volumio sudo[13313]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 24 04:20:00 volumio sudo[13313]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 24 04:20:00 volumio sudo[13315]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 24 04:20:00 volumio sudo[13315]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 24 04:20:00 volumio sudo[13318]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 24 04:20:00 volumio sudo[13318]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 24 04:20:00 volumio go-librespot[13298]: time="2025-10-24T04:20: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-gew4.spotify.com:80]" Oct 24 04:20:00 volumio go-librespot[13298]: time="2025-10-24T04:20:00+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 24 04:20:00 volumio go-librespot[13298]: time="2025-10-24T04:20:00+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 24 04:20:00 volumio go-librespot[13298]: time="2025-10-24T04:20:00+01:00" level=info msg="zeroconf server listening on port 42415" Oct 24 04:20:00 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Oct 24 04:20:00 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Oct 24 04:20:00 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Oct 24 04:20:00 volumio systemd[1]: shairport-sync.service: Consumed 1.548s CPU time. Oct 24 04:20:00 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Oct 24 04:20:00 volumio sudo[13313]: pam_unix(sudo:session): session closed for user root Oct 24 04:20:00 volumio sudo[13315]: pam_unix(sudo:session): session closed for user root Oct 24 04:20:00 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Oct 24 04:20:00 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Oct 24 04:20:00 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Oct 24 04:20:00 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Oct 24 04:20:00 volumio go-librespot[13298]: time="2025-10-24T04:20:00+01:00" level=debug msg="obtained new client token: AAAqXTnM7FEO5CA3ecBVM+7K5R0feY8JNBDQlqdlUB7Gl78rzqI3itjUO4SebVyBlMWXF79Gz+B/jKNXiAO0iZb1N7CTb5bO41hIDSSlqn3NEln1LGGyqETGNxbu1L9kNlK1bYhdYTVPOPJPGKq8C77kmfljhHpy9JzXAIHWDGB7bJdfrURpNzmPtuDY9NCPACnedBRetYA4AcyKjs3cnQd8YHFvFzOzjuceXdImQG8UgPA+0wfzA/E=" Oct 24 04:20:00 volumio volumio[13098]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Oct 24 04:20:00 volumio volumio[13098]: SPOTIFY: BQBV3d6Wcp7vomEtMPQYnFFxWK9MbdcSy3oQySqYHXREty_NcpkYFOJb8rmxhPZ98FY5Irc4Wjx5NacrlNZFjs0mKfptMNtth3-lTS5hlQGY0ctfZ2t9YiwsHRYd0RTHQ0G7ygGy4XHZJWxFFBEu0w_AqTRVMZGMlqa5VktvwZRCAmayM6kbiF9bs3jzmxddE-C48NDHVX9W7gHLHlJmy3b-1DH_-m8YsVlOphLfGcVZSXzVZA-LrnGThq2b8mNX99hIHonqf6m9097nTDe3l6xdyceObMut0fa8yRiHLUbywAXaV1o Oct 24 04:20:00 volumio volumio[13098]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Oct 24 04:20:00 volumio volumio[13098]: info: New Spotify access token = BQBV3d6Wcp7vomEtMPQYnFFxWK9MbdcSy3oQySqYHXREty_NcpkYFOJb8rmxhPZ98FY5Irc4Wjx5NacrlNZFjs0mKfptMNtth3-lTS5hlQGY0ctfZ2t9YiwsHRYd0RTHQ0G7ygGy4XHZJWxFFBEu0w_AqTRVMZGMlqa5VktvwZRCAmayM6kbiF9bs3jzmxddE-C48NDHVX9W7gHLHlJmy3b-1DH_-m8YsVlOphLfGcVZSXzVZA-LrnGThq2b8mNX99hIHonqf6m9097nTDe3l6xdyceObMut0fa8yRiHLUbywAXaV1o Oct 24 04:20:00 volumio volumio[13098]: info: Spotify credentials grant success - running version from March 24, 2019 Oct 24 04:20:00 volumio sudo[13318]: pam_unix(sudo:session): session closed for user root Oct 24 04:20:00 volumio go-librespot[13298]: time="2025-10-24T04:20:00+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 24 04:20:00 volumio volumio[13098]: info: Shairport-Sync Started Oct 24 04:20:00 volumio volumio[13098]: Error adding Membership: Error: addMembership EINVAL Oct 24 04:20:00 volumio volumio[13098]: info: Shairport-Sync Started Oct 24 04:20:00 volumio volumio[13098]: info: Shairport-Sync Started Oct 24 04:20:00 volumio volumio[13098]: info: CoreCommandRouter::volumioGetState Oct 24 04:20:00 volumio volumio[13098]: info: CorePlayQueue::getTrack 0 Oct 24 04:20:00 volumio go-librespot[13298]: time="2025-10-24T04:20:00+01:00" level=debug msg="completed keyexchange" Oct 24 04:20:00 volumio go-librespot[13298]: time="2025-10-24T04:20:00+01:00" level=debug msg="completed challenge" Oct 24 04:20:00 volumio go-librespot[13298]: time="2025-10-24T04:20: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 24 04:20:00 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 24 04:20:00 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 24 04:20:00 volumio volumio[13098]: 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 24 04:20:00 volumio volumio[13098]: info: Spotify Successfully logged in Oct 24 04:20:00 volumio volumio[13098]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 24 04:20:00 volumio volumio[13098]: info: [1761276000879] CoreMusicLibrary::Adding element Spotify Oct 24 04:20:00 volumio volumio[13098]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 24 04:20:00 volumio volumio[13098]: Cannot find translation for source Spotify Oct 24 04:20:00 volumio mpd[13267]: 2025-10-24T04:20:00 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Oct 24 04:20:00 volumio systemd[1]: Started mpd.service - Music Player Daemon. Oct 24 04:20:00 volumio sudo[13228]: pam_unix(sudo:session): session closed for user root Oct 24 04:20:00 volumio sudo[13238]: pam_unix(sudo:session): session closed for user root Oct 24 04:20:00 volumio volumio[13098]: error: updateQueue error: null Oct 24 04:20:00 volumio volumio[13098]: error: updateQueue error: null Oct 24 04:20:01 volumio volumio[13098]: info: MPD running with PID13267 Oct 24 04:20:01 volumio volumio[13098]: ,establishing connection Oct 24 04:20:01 volumio volumio[13098]: error: updateQueue error: null Oct 24 04:20:01 volumio volumio-remote-updater[896]: [2025-10-24 03:20:01] [connect] Successful connection Oct 24 04:20:01 volumio volumio-remote-updater[896]: [2025-10-24 03:20:01] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1761276001 101 Oct 24 04:20:01 volumio volumio[13098]: 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 24 04:20:01 volumio volumio[13098]: info: [yt-cast-receiver] DIAL server listening on port 8098 Oct 24 04:20:01 volumio volumio[13098]: info: CoreCommandRouter::volumioRetrievevolume Oct 24 04:20:01 volumio volumio[13098]: info: VolumeController:: Volume=51 Mute =false Oct 24 04:20:01 volumio volumio[13098]: info: CoreCommandRouter::volumioGetState Oct 24 04:20:01 volumio volumio[13098]: info: CorePlayQueue::getTrack 0 Oct 24 04:20:01 volumio volumio[13098]: info: CoreStateMachine::pushState Oct 24 04:20:01 volumio volumio[13098]: info: CorePlayQueue::getTrack 0 Oct 24 04:20:01 volumio volumio[13098]: info: CoreCommandRouter::volumioPushState Oct 24 04:20:01 volumio volumio[13098]: info: Completed starting Core Plugins Oct 24 04:20:01 volumio volumio[13098]: info: ------------------------------------------- Oct 24 04:20:01 volumio volumio[13098]: info: ----- MyVolumio plugins startup ---- Oct 24 04:20:01 volumio volumio[13098]: info: ------------------------------------------- Oct 24 04:20:01 volumio volumio[13098]: info: [MyVolumio PluginManager] Fetching plans data.... Oct 24 04:20:02 volumio volumio[13098]: info: Cannot mount NAS NAS at system boot, trial number 2 ,retrying in 5 seconds Oct 24 04:20:03 volumio kernel: nfs: server 192.168.1.3 not responding, timed out Oct 24 04:20:03 volumio volumio[13098]: info: go-librespot daemon successfully initialized Oct 24 04:20:03 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1186. Oct 24 04:20:03 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 24 04:20:03 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 24 04:20:03 volumio go-librespot[13356]: go-librespot daemon starting... Oct 24 04:20:03 volumio go-librespot[13357]: time="2025-10-24T04:20:03+01:00" level=info msg="running go-librespot 0.4.0" Oct 24 04:20:03 volumio go-librespot[13357]: time="2025-10-24T04:20:03+01:00" level=debug msg="app state loaded" Oct 24 04:20:03 volumio go-librespot[13357]: time="2025-10-24T04:20:03+01:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 24 04:20:03 volumio sudo[13364]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Oct 24 04:20:03 volumio sudo[13364]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 24 04:20:04 volumio sudo[13366]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Oct 24 04:20:04 volumio sudo[13366]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 24 04:20:04 volumio systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Oct 24 04:20:04 volumio systemd[1]: mpd_monitor.service: Deactivated successfully. Oct 24 04:20:04 volumio systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Oct 24 04:20:04 volumio sudo[13364]: pam_unix(sudo:session): session closed for user root Oct 24 04:20:04 volumio systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Oct 24 04:20:04 volumio mpd_monitor.sh[13370]: MPD Monitor Service: Starting MPD Monitor Service Oct 24 04:20:04 volumio sudo[13366]: pam_unix(sudo:session): session closed for user root Oct 24 04:20:04 volumio volumio[13098]: info: Successfully started MPD Monitor Oct 24 04:20:04 volumio volumio[13098]: info: Successfully started MPD Monitor Oct 24 04:20:04 volumio go-librespot[13357]: time="2025-10-24T04:20: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-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Oct 24 04:20:04 volumio go-librespot[13357]: time="2025-10-24T04:20:04+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 24 04:20:04 volumio go-librespot[13357]: time="2025-10-24T04:20:04+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 24 04:20:04 volumio go-librespot[13357]: time="2025-10-24T04:20:04+01:00" level=info msg="zeroconf server listening on port 37619" Oct 24 04:20:04 volumio go-librespot[13357]: time="2025-10-24T04:20:04+01:00" level=debug msg="obtained new client token: AAB/i/E5bt7SSTZsw1MnfMnS5/D4XfFkNmflb8U0BAWHlK2q257C8vTct3V5xCEjpTHnt/8kLDGcgIgpu0YkQS1MQItk1vnTTPtQzmkiV2Opk4Jcb9CSOvK8ip7U1a5bqkZjq4z17Ysndknr5VpXyYUIEOcSHWZ9znD4hiDvLmRqCPxw78lDMIABqvrHNShdp9XbOQgm+83li02GurZJefjMIfFlEH823QFOMv3v2YfxozYRooSq" Oct 24 04:20:04 volumio go-librespot[13357]: time="2025-10-24T04:20:04+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 24 04:20:04 volumio go-librespot[13357]: time="2025-10-24T04:20:04+01:00" level=debug msg="completed keyexchange" Oct 24 04:20:04 volumio go-librespot[13357]: time="2025-10-24T04:20:04+01:00" level=debug msg="completed challenge" Oct 24 04:20:04 volumio go-librespot[13357]: time="2025-10-24T04:20: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 24 04:20:04 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 24 04:20:04 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 24 04:20:05 volumio volumio[13098]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Oct 24 04:20:06 volumio volumio[13098]: info: Initializing connection to go-librespot Websocket Oct 24 04:20:06 volumio volumio[13098]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 24 04:20:07 volumio volumio[13098]: info: Cannot mount NAS NAS at system boot, trial number 3 ,retrying in 5 seconds Oct 24 04:20:07 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1187. Oct 24 04:20:07 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 24 04:20:07 volumio sudo[13390]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 24 04:20:07 volumio sudo[13390]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 24 04:20:07 volumio sudo[13390]: pam_unix(sudo:session): session closed for user root Oct 24 04:20:07 volumio sudo[13393]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 24 04:20:07 volumio sudo[13393]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 24 04:20:07 volumio sudo[13393]: pam_unix(sudo:session): session closed for user root Oct 24 04:20:07 volumio sudo[13396]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Oct 24 04:20:07 volumio sudo[13396]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 24 04:20:07 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 24 04:20:07 volumio go-librespot[13391]: go-librespot daemon starting... Oct 24 04:20:07 volumio go-librespot[13399]: time="2025-10-24T04:20:07+01:00" level=info msg="running go-librespot 0.4.0" Oct 24 04:20:07 volumio go-librespot[13399]: time="2025-10-24T04:20:07+01:00" level=debug msg="app state loaded" Oct 24 04:20:07 volumio go-librespot[13399]: time="2025-10-24T04:20:07+01:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 24 04:20:07 volumio sudo[13396]: pam_unix(sudo:session): session closed for user root Oct 24 04:20:07 volumio volumio[13098]: info: Upmpdcli Daemon Started Oct 24 04:20:07 volumio go-librespot[13399]: time="2025-10-24T04:20: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 24 04:20:07 volumio go-librespot[13399]: time="2025-10-24T04:20: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 24 04:20:07 volumio go-librespot[13399]: time="2025-10-24T04:20: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 24 04:20:07 volumio go-librespot[13399]: time="2025-10-24T04:20:07+01:00" level=info msg="zeroconf server listening on port 40233" Oct 24 04:20:07 volumio go-librespot[13399]: time="2025-10-24T04:20:07+01:00" level=debug msg="obtained new client token: AADHRn0kcjjRtKEj14i+k58ib+0LhoBRLHj+ZnEJBnUlyJkDQz0yQvfB0TaPfD6bnq+gkjt+wpZtQPHOhih+BhtSzS/USFrkahQxqwwgYgY1eICBQ8mrqnxnLdbbRJSKB1QMVhQ6IOGEjDw5hHvPhI3Oc6ggQ/F4rHtJQjZq5G00zBU6sObqrC46cH9TjNWEW2diR7UBxj6YbALm2OBsTH8mXT6M06L9XpjyCzzlYTu4lq83hbzRGXM=" Oct 24 04:20:07 volumio go-librespot[13399]: time="2025-10-24T04:20:07+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 24 04:20:07 volumio go-librespot[13399]: time="2025-10-24T04:20:07+01:00" level=debug msg="completed keyexchange" Oct 24 04:20:07 volumio go-librespot[13399]: time="2025-10-24T04:20:07+01:00" level=debug msg="completed challenge" Oct 24 04:20:07 volumio go-librespot[13399]: time="2025-10-24T04:20: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 24 04:20:07 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 24 04:20:07 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 24 04:20:09 volumio volumio[13098]: info: Initializing connection to go-librespot Websocket Oct 24 04:20:09 volumio volumio[13098]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 24 04:20:09 volumio volumio[13098]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Oct 24 04:20:09 volumio volumio[13098]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Oct 24 04:20:09 volumio volumio[13098]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Oct 24 04:20:09 volumio volumio[13098]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Oct 24 04:20:09 volumio volumio[13098]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Oct 24 04:20:09 volumio volumio[13098]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Oct 24 04:20:09 volumio volumio[13098]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Oct 24 04:20:09 volumio volumio[13098]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Oct 24 04:20:09 volumio volumio[13098]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Oct 24 04:20:09 volumio volumio[13098]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Oct 24 04:20:09 volumio volumio[13098]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Oct 24 04:20:09 volumio volumio[13098]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Oct 24 04:20:09 volumio volumio[13098]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Oct 24 04:20:09 volumio volumio[13098]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Oct 24 04:20:09 volumio volumio[13098]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Oct 24 04:20:09 volumio volumio[13098]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Oct 24 04:20:09 volumio volumio[13098]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Oct 24 04:20:09 volumio volumio[13098]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Oct 24 04:20:09 volumio volumio[13098]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Oct 24 04:20:09 volumio volumio[13098]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Oct 24 04:20:09 volumio volumio[13098]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Oct 24 04:20:09 volumio volumio[13098]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Oct 24 04:20:09 volumio volumio[13098]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Oct 24 04:20:09 volumio volumio[13098]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Oct 24 04:20:09 volumio volumio[13098]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Oct 24 04:20:09 volumio volumio[13098]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Oct 24 04:20:09 volumio volumio[13098]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Oct 24 04:20:09 volumio volumio[13098]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Oct 24 04:20:09 volumio volumio[13098]: info: Adding plugin bluetooth to MyMusic Plugins Oct 24 04:20:09 volumio volumio[13098]: info: Adding plugin multiroom to MyMusic Plugins Oct 24 04:20:09 volumio volumio[13098]: info: Adding plugin metavolumio to MyMusic Plugins Oct 24 04:20:09 volumio volumio[13098]: info: Adding plugin cd_controller to MyMusic Plugins Oct 24 04:20:09 volumio volumio[13098]: info: Adding plugin qobuzconnect to MyMusic Plugins Oct 24 04:20:09 volumio volumio[13098]: info: Adding plugin smart_inputs to MyMusic Plugins Oct 24 04:20:09 volumio volumio[13098]: info: Adding plugin tidalconnect to MyMusic Plugins Oct 24 04:20:09 volumio volumio[13098]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Oct 24 04:20:09 volumio volumio[13098]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Oct 24 04:20:09 volumio volumio[13098]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Oct 24 04:20:09 volumio volumio[13098]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 24 04:20:09 volumio volumio[13098]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 24 04:20:09 volumio volumio[13098]: info: Starting MyVolumio Remote Streaming Endpoints Oct 24 04:20:09 volumio volumio[13098]: info: MyVolumio login type: Token Oct 24 04:20:10 volumio volumio[13098]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Oct 24 04:20:10 volumio volumio[13098]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Oct 24 04:20:10 volumio volumio[13098]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Oct 24 04:20:10 volumio volumio[13098]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Oct 24 04:20:10 volumio volumio[13098]: info: Streaming services startup Oct 24 04:20:10 volumio volumio[13098]: info: Starting Streaming Daemon Oct 24 04:20:10 volumio sudo[13407]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Oct 24 04:20:10 volumio sudo[13407]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 24 04:20:10 volumio volumio[13098]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Oct 24 04:20:10 volumio sudo[13407]: pam_unix(sudo:session): session closed for user root Oct 24 04:20:10 volumio volumio[13098]: error: Cannot start Volumio Streaming Daemon Oct 24 04:20:10 volumio volumio[13098]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Oct 24 04:20:10 volumio volumio[13098]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Oct 24 04:20:10 volumio volumio[13098]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Oct 24 04:20:10 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1188. Oct 24 04:20:10 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 24 04:20:10 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 24 04:20:10 volumio go-librespot[13414]: go-librespot daemon starting... Oct 24 04:20:10 volumio go-librespot[13415]: time="2025-10-24T04:20:10+01:00" level=info msg="running go-librespot 0.4.0" Oct 24 04:20:10 volumio go-librespot[13415]: time="2025-10-24T04:20:10+01:00" level=debug msg="app state loaded" Oct 24 04:20:10 volumio go-librespot[13415]: time="2025-10-24T04:20:10+01:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 24 04:20:10 volumio volumio[13098]: info: MyVolumio token set successfully Oct 24 04:20:10 volumio volumio[13098]: info: MYVOLUMIO: Adding device Oct 24 04:20:10 volumio volumio[13098]: info: MYVOLUMIO: Evaluating Server Oct 24 04:20:11 volumio go-librespot[13415]: time="2025-10-24T04:20: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-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Oct 24 04:20:11 volumio go-librespot[13415]: time="2025-10-24T04:20:11+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 24 04:20:11 volumio go-librespot[13415]: time="2025-10-24T04:20:11+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 24 04:20:11 volumio go-librespot[13415]: time="2025-10-24T04:20:11+01:00" level=info msg="zeroconf server listening on port 37925" Oct 24 04:20:11 volumio volumio[13098]: info: MyVolumio status changed Oct 24 04:20:11 volumio volumio[13098]: info: Streaming services startup Oct 24 04:20:11 volumio volumio[13098]: info: Starting Streaming Daemon Oct 24 04:20:11 volumio volumio[13098]: info: Removing browser output: myVolumio user plan is not superstar Oct 24 04:20:11 volumio volumio[13098]: info: Removing audio output: Oct 24 04:20:11 volumio volumio[13098]: info: Stoppping Tunnel 1 Oct 24 04:20:11 volumio go-librespot[13415]: time="2025-10-24T04:20:11+01:00" level=debug msg="obtained new client token: AABgVromm78iBslm9OTkiwtiqZAp3AFnaqcPP9UO/2FTVBwkHCQE79QS+TZaCFpipj+X8g83pwwzv1QDLkpGa1ea2dsnqIM43UmHVbJyShAt3c27htJt30smXUyd4CxwOqy/CuO8mecONywAyAilk4nfbrBZQqKZ4VGoH0hiUydG8P8JFQS5ka2Kg2gVtz/exx2mrnKbWiUThKe8fkXlUyMOuPmyH4iiC9wmm6X7XjgYmq+9acYj" Oct 24 04:20:11 volumio sudo[13441]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Oct 24 04:20:11 volumio sudo[13441]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 24 04:20:11 volumio sudo[13443]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service Oct 24 04:20:11 volumio sudo[13443]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 24 04:20:11 volumio sudo[13441]: pam_unix(sudo:session): session closed for user root Oct 24 04:20:11 volumio volumio[13098]: error: Cannot start Volumio Streaming Daemon Oct 24 04:20:11 volumio volumio[13098]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Oct 24 04:20:11 volumio volumio[13098]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Oct 24 04:20:11 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 24 04:20:11 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 24 04:20:11 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 24 04:20:11 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 24 04:20:11 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 24 04:20:11 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 24 04:20:11 volumio go-librespot[13415]: time="2025-10-24T04:20:11+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 24 04:20:11 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 24 04:20:11 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 24 04:20:11 volumio sudo[13443]: pam_unix(sudo:session): session closed for user root Oct 24 04:20:11 volumio volumio[13098]: info: Remote SSH Stopped Oct 24 04:20:11 volumio go-librespot[13415]: time="2025-10-24T04:20:11+01:00" level=debug msg="completed keyexchange" Oct 24 04:20:11 volumio go-librespot[13415]: time="2025-10-24T04:20:11+01:00" level=debug msg="completed challenge" Oct 24 04:20:11 volumio go-librespot[13415]: time="2025-10-24T04:20: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 24 04:20:11 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 24 04:20:11 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 24 04:20:11 volumio volumio[13098]: info: Setting Geolocation for MyVolumio to eu3 Oct 24 04:20:11 volumio volumio[13098]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 24 04:20:11 volumio volumio[13098]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 24 04:20:11 volumio volumio[13098]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 24 04:20:12 volumio volumio[13098]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Oct 24 04:20:12 volumio volumio[13098]: info: Cannot mount NAS NAS at system boot, trial number 4 ,retrying in 5 seconds Oct 24 04:20:12 volumio volumio[13098]: info: Updating MyVolumio device info Oct 24 04:20:12 volumio volumio[13098]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 24 04:20:12 volumio volumio[13098]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 24 04:20:12 volumio volumio[13098]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 24 04:20:12 volumio volumio[13098]: info: Initializing connection to go-librespot Websocket Oct 24 04:20:12 volumio volumio[13098]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 24 04:20:12 volumio volumio[13098]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Oct 24 04:20:14 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1189. Oct 24 04:20:14 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 24 04:20:14 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 24 04:20:14 volumio go-librespot[13446]: go-librespot daemon starting... Oct 24 04:20:14 volumio go-librespot[13447]: time="2025-10-24T04:20:14+01:00" level=info msg="running go-librespot 0.4.0" Oct 24 04:20:14 volumio go-librespot[13447]: time="2025-10-24T04:20:14+01:00" level=debug msg="app state loaded" Oct 24 04:20:14 volumio go-librespot[13447]: time="2025-10-24T04:20:14+01:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 24 04:20:14 volumio go-librespot[13447]: time="2025-10-24T04:20: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-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Oct 24 04:20:14 volumio go-librespot[13447]: time="2025-10-24T04:20:14+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 24 04:20:14 volumio go-librespot[13447]: time="2025-10-24T04:20:14+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 24 04:20:14 volumio go-librespot[13447]: time="2025-10-24T04:20:14+01:00" level=info msg="zeroconf server listening on port 38125" Oct 24 04:20:14 volumio go-librespot[13447]: time="2025-10-24T04:20:14+01:00" level=debug msg="obtained new client token: AABRBJW3LnpM9FPdKDtrI6SSQTkGka/n4vkk9ntgCL6XTUI1A9kOWjJdLofzcyKeJpygWIvvw/9IbnAWprbleemKTDJDXkbSN4CnMk7P9C1xiBeLlFZH38CRwatKg2Eak8TDHttpda7Ahy2LKvE8RyetwfW1U5xPD3YVoqXtS7gKYeb1cx87TpD6jwBIvuWMGmSvA8DGWi6g1BTrpVqzFu2lEkTdWiNXH6r1QUCdVNven4oSue+Cu4o=" Oct 24 04:20:14 volumio go-librespot[13447]: time="2025-10-24T04:20:14+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 24 04:20:14 volumio go-librespot[13447]: time="2025-10-24T04:20:14+01:00" level=debug msg="completed keyexchange" Oct 24 04:20:14 volumio go-librespot[13447]: time="2025-10-24T04:20:14+01:00" level=debug msg="completed challenge" Oct 24 04:20:14 volumio go-librespot[13447]: time="2025-10-24T04:20: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 24 04:20:14 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 24 04:20:14 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 24 04:20:15 volumio volumio[13098]: info: Initializing connection to go-librespot Websocket Oct 24 04:20:15 volumio volumio[13098]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 24 04:20:16 volumio volumio[13098]: info: MYVOLUMIO: Adding device Oct 24 04:20:16 volumio volumio[13098]: info: MYVOLUMIO: Evaluating Server Oct 24 04:20:16 volumio volumio[13098]: info: Setting Geolocation for MyVolumio to eu3 Oct 24 04:20:16 volumio volumio[13098]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 24 04:20:16 volumio volumio[13098]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 24 04:20:16 volumio volumio[13098]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 24 04:20:16 volumio volumio[13098]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Oct 24 04:20:17 volumio volumio[13098]: info: Cannot mount NAS at system boot, trial number 4 ,stopping Oct 24 04:20:17 volumio volumio[13098]: info: Updating MyVolumio device info Oct 24 04:20:17 volumio volumio[13098]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 24 04:20:17 volumio volumio[13098]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 24 04:20:17 volumio volumio[13098]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 24 04:20:17 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1190. Oct 24 04:20:17 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 24 04:20:17 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 24 04:20:17 volumio go-librespot[13483]: go-librespot daemon starting... Oct 24 04:20:17 volumio go-librespot[13484]: time="2025-10-24T04:20:17+01:00" level=info msg="running go-librespot 0.4.0" Oct 24 04:20:17 volumio go-librespot[13484]: time="2025-10-24T04:20:17+01:00" level=debug msg="app state loaded" Oct 24 04:20:17 volumio go-librespot[13484]: time="2025-10-24T04:20:17+01:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 24 04:20:18 volumio go-librespot[13484]: time="2025-10-24T04:20: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 24 04:20:18 volumio go-librespot[13484]: time="2025-10-24T04:20: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 24 04:20:18 volumio go-librespot[13484]: time="2025-10-24T04:20: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 24 04:20:18 volumio go-librespot[13484]: time="2025-10-24T04:20:18+01:00" level=info msg="zeroconf server listening on port 44505" Oct 24 04:20:18 volumio go-librespot[13484]: time="2025-10-24T04:20:18+01:00" level=debug msg="obtained new client token: AAA3JOIQV4hBh2Bq/KAAD+WaSMwxv4/EYPMBTaLXNePEmlKrK9uxp4kN1sqCA2feoTECIe6ngfDBWukWqVSI06eFUbKiNTzi1sLKZNwyjTxmtFZBg10Xc5TCY0/VWudcKrmCaPb7a8KoUSJvUZNc5Xi9MwdTma9vTRvY0wOW+YKp2VNm6jcXYuhscUnXmvJNmQQzJOUyar/9Jrie1oVEkHRYI/lDEJhgO1fwfYXWDGhDxZopIP9a" Oct 24 04:20:18 volumio go-librespot[13484]: time="2025-10-24T04:20:18+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 24 04:20:18 volumio go-librespot[13484]: time="2025-10-24T04:20:18+01:00" level=debug msg="completed keyexchange" Oct 24 04:20:18 volumio go-librespot[13484]: time="2025-10-24T04:20:18+01:00" level=debug msg="completed challenge" Oct 24 04:20:18 volumio go-librespot[13484]: time="2025-10-24T04:20: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 24 04:20:18 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 24 04:20:18 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 24 04:20:18 volumio volumio[13098]: info: Initializing connection to go-librespot Websocket Oct 24 04:20:18 volumio volumio[13098]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 24 04:20:18 volumio volumio[13098]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Oct 24 04:20:18 volumio kernel: nfs: server 192.168.1.3 not responding, timed out Oct 24 04:20:21 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1191. Oct 24 04:20:21 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 24 04:20:21 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 24 04:20:21 volumio go-librespot[13491]: go-librespot daemon starting... Oct 24 04:20:21 volumio go-librespot[13492]: time="2025-10-24T04:20:21+01:00" level=info msg="running go-librespot 0.4.0" Oct 24 04:20:21 volumio go-librespot[13492]: time="2025-10-24T04:20:21+01:00" level=debug msg="app state loaded" Oct 24 04:20:21 volumio go-librespot[13492]: time="2025-10-24T04:20:21+01:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 24 04:20:21 volumio go-librespot[13492]: time="2025-10-24T04:20: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 24 04:20:21 volumio go-librespot[13492]: time="2025-10-24T04:20: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 24 04:20:21 volumio go-librespot[13492]: time="2025-10-24T04:20: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 24 04:20:21 volumio go-librespot[13492]: time="2025-10-24T04:20:21+01:00" level=info msg="zeroconf server listening on port 43659" Oct 24 04:20:21 volumio volumio[13098]: info: Initializing connection to go-librespot Websocket Oct 24 04:20:21 volumio go-librespot[13492]: time="2025-10-24T04:20:21+01:00" level=debug msg="new websocket client" Oct 24 04:20:21 volumio volumio[13098]: info: Connection to go-librespot Websocket established Oct 24 04:20:21 volumio go-librespot[13492]: time="2025-10-24T04:20:21+01:00" level=debug msg="obtained new client token: AAA3rnyghuLZqILeG2PncHTrDdH8CiuBWjlfsMsrPhaAqs73pPrPjd4q2hZ7CSF8DfdMZMCLIUMYPWUIDOPK04GaT8FzcfH09X+khBdPK29idcSePZFMokI7ldgzOdiiDjG90I2vRwhAcTxIw+kNdtb+Znq/uA2uilaq2tFYVCh0HnqKJNXrir81gr4+X72+JRJK/V/AHiMVwu9ZZsc22EG6Q6wpJVDqsnpmhx/esLChWCLAjdrVqqU=" Oct 24 04:20:21 volumio go-librespot[13492]: time="2025-10-24T04:20:21+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 24 04:20:21 volumio go-librespot[13492]: time="2025-10-24T04:20:21+01:00" level=debug msg="completed keyexchange" Oct 24 04:20:21 volumio go-librespot[13492]: time="2025-10-24T04:20:21+01:00" level=debug msg="completed challenge" Oct 24 04:20:21 volumio go-librespot[13492]: time="2025-10-24T04:20:21+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 24 04:20:21 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 24 04:20:21 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 24 04:20:21 volumio volumio[13098]: info: Connection to go-librespot Websocket closed Oct 24 04:20:24 volumio volumio[13098]: info: Getting Spotify volume Oct 24 04:20:24 volumio volumio[13098]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 24 04:20:24 volumio volumio[13098]: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 24 04:20:24 volumio volumio[13098]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Oct 24 04:20:24 volumio volumio[13098]: errno: -111, Oct 24 04:20:24 volumio volumio[13098]: code: 'ECONNREFUSED', Oct 24 04:20:24 volumio volumio[13098]: syscall: 'connect', Oct 24 04:20:24 volumio volumio[13098]: address: '127.0.0.1', Oct 24 04:20:24 volumio volumio[13098]: port: 9879, Oct 24 04:20:24 volumio volumio[13098]: response: undefined Oct 24 04:20:24 volumio volumio[13098]: } Oct 24 04:20:24 volumio volumio[13098]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 24 04:20:24 volumio sudo[13516]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-10-24 04:19' Oct 24 04:20:24 volumio sudo[13516]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 24 04:20:24 volumio sudo[13516]: pam_unix(sudo:session): session closed for user root Oct 24 04:20:24 volumio volumio-remote-updater[896]: [2025-10-24 03:20:24] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Oct 24 04:20:24 volumio volumio-remote-updater[896]: [2025-10-24 03:20:24] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Oct 24 04:20:24 volumio systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Oct 24 04:20:24 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1192. Oct 24 04:20:24 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 24 04:20:24 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 24 04:20:24 volumio systemd[1]: volumio.service: Failed with result 'exit-code'. Oct 24 04:20:24 volumio systemd[1]: volumio.service: Consumed 11.280s CPU time. Oct 24 04:20:24 volumio go-librespot[13521]: go-librespot daemon starting... Oct 24 04:20:24 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Oct 24 04:20:24 volumio go-librespot[13522]: time="2025-10-24T04:20:24+01:00" level=info msg="running go-librespot 0.4.0" Oct 24 04:20:24 volumio go-librespot[13522]: time="2025-10-24T04:20:24+01:00" level=debug msg="app state loaded" Oct 24 04:20:24 volumio go-librespot[13522]: time="2025-10-24T04:20:24+01:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 24 04:20:24 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Oct 24 04:20:25 volumio go-librespot[13522]: time="2025-10-24T04:20: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-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Oct 24 04:20:25 volumio go-librespot[13522]: time="2025-10-24T04:20:25+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 24 04:20:25 volumio go-librespot[13522]: time="2025-10-24T04:20:25+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 24 04:20:25 volumio go-librespot[13522]: time="2025-10-24T04:20:25+01:00" level=info msg="zeroconf server listening on port 41765" Oct 24 04:20:25 volumio go-librespot[13522]: time="2025-10-24T04:20:25+01:00" level=debug msg="obtained new client token: AADoF58Gn6WMNCY6gOr3Vu2rzNM0jycwbT2KDDxCfk7GJchAhPBeaE84Pj3pEQcbqVFpn23REwzng5wpc7iYtzndXVp0kAe/de0OyVT1lF/LbPzNMUeeg19v4tMu567L+eZkYz/q/MNJQpsQEmlofnetw32TIXcccX59Eugt5x7cdak9f1PYI3h6wfjcOupeuSS6D4D10i7inFjGx7ZCqVof+l/efhFqwlDwlPJ3ViBuu4xxlFLx" Oct 24 04:20:25 volumio go-librespot[13522]: time="2025-10-24T04:20:25+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 24 04:20:25 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 4096. Oct 24 04:20:25 volumio go-librespot[13522]: time="2025-10-24T04:20:25+01:00" level=debug msg="completed keyexchange" Oct 24 04:20:25 volumio go-librespot[13522]: time="2025-10-24T04:20:25+01:00" level=debug msg="completed challenge" Oct 24 04:20:25 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Oct 24 04:20:25 volumio systemd[1]: Stopped volumio.service - Volumio Backend Module. Oct 24 04:20:25 volumio systemd[1]: volumio.service: Consumed 11.280s CPU time. Oct 24 04:20:25 volumio systemd[1]: Started volumio.service - Volumio Backend Module. Oct 24 04:20:25 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Oct 24 04:20:25 volumio go-librespot[13522]: time="2025-10-24T04:20: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 24 04:20:25 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 24 04:20:25 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 24 04:20:25 volumio volumio[13536]: info: ------------------------------------------- Oct 24 04:20:25 volumio volumio[13536]: info: ----- Volumio3 ---- Oct 24 04:20:25 volumio volumio[13536]: info: ------------------------------------------- Oct 24 04:20:25 volumio volumio[13536]: info: ----- System startup ---- Oct 24 04:20:25 volumio volumio[13536]: info: ------------------------------------------- Oct 24 04:20:25 volumio kernel: nfs: server 192.168.1.3 not responding, timed out Oct 24 04:20:25 volumio volumio[13536]: info: MYVOLUMIO Environment detected Oct 24 04:20:25 volumio volumio[13536]: info: Plugin folders cleanup Oct 24 04:20:25 volumio volumio[13536]: info: Scanning into folder /volumio/app/plugins/ Oct 24 04:20:25 volumio volumio[13536]: info: Scanning category audio_interface Oct 24 04:20:25 volumio volumio[13536]: info: Scanning category miscellanea Oct 24 04:20:25 volumio volumio[13536]: info: Scanning category music_service Oct 24 04:20:25 volumio volumio[13536]: info: Scanning category plugins.json Oct 24 04:20:25 volumio volumio[13536]: info: Scanning category system_controller Oct 24 04:20:25 volumio volumio[13536]: info: Scanning category user_interface Oct 24 04:20:25 volumio volumio[13536]: info: Scanning into folder /data/plugins/ Oct 24 04:20:25 volumio volumio[13536]: info: Scanning category music_service Oct 24 04:20:25 volumio volumio[13536]: info: Scanning category user_interface Oct 24 04:20:25 volumio volumio[13536]: info: Plugin folders cleanup completed Oct 24 04:20:25 volumio volumio[13536]: info: ------------------------------------------- Oct 24 04:20:25 volumio volumio[13536]: info: ----- Core plugins startup ---- Oct 24 04:20:25 volumio volumio[13536]: info: ------------------------------------------- Oct 24 04:20:25 volumio volumio[13536]: info: Loading plugins from folder /volumio/app/plugins/ Oct 24 04:20:25 volumio volumio[13536]: info: Adding plugin upnp to MyMusic Plugins Oct 24 04:20:25 volumio volumio[13536]: info: Adding plugin airplay_emulation to MyMusic Plugins Oct 24 04:20:25 volumio volumio[13536]: info: Adding plugin upnp_browser to MyMusic Plugins Oct 24 04:20:25 volumio volumio[13536]: info: Loading plugins from folder /data/plugins/ Oct 24 04:20:25 volumio volumio[13536]: info: Loading plugin "system"... Oct 24 04:20:26 volumio volumio[13536]: info: Loading plugin "appearance"... Oct 24 04:20:26 volumio volumio[13536]: info: Loading plugin "network"... Oct 24 04:20:26 volumio volumio[13536]: info: Refreshing Cached IP Addresses Oct 24 04:20:26 volumio sudo[13564]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 24 04:20:26 volumio sudo[13564]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 24 04:20:26 volumio sudo[13566]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 24 04:20:26 volumio sudo[13564]: pam_unix(sudo:session): session closed for user root Oct 24 04:20:26 volumio sudo[13566]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 24 04:20:26 volumio sudo[13566]: pam_unix(sudo:session): session closed for user root Oct 24 04:20:26 volumio volumio[13536]: info: Loading plugin "services"... Oct 24 04:20:26 volumio volumio[13536]: info: Loading plugin "alsa_controller"... Oct 24 04:20:26 volumio sudo[13570]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Oct 24 04:20:26 volumio sudo[13570]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 24 04:20:26 volumio volumio[13536]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 24 04:20:26 volumio volumio[13536]: info: Loading plugin "wizard"... Oct 24 04:20:26 volumio volumio[13536]: info: Loading plugin "networkfs"... Oct 24 04:20:26 volumio volumio[13536]: info: Cannot mount NAS NAS at system boot, trial number 1 ,retrying in 5 seconds Oct 24 04:20:26 volumio volumio[13536]: info: Starting Udev Watcher for removable devices Oct 24 04:20:26 volumio volumio[13536]: info: Ignoring mount for partition: boot Oct 24 04:20:26 volumio volumio[13536]: info: Ignoring mount for partition: volumio Oct 24 04:20:26 volumio volumio[13536]: info: Ignoring mount for partition: volumio_data Oct 24 04:20:26 volumio volumio[13536]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 24 04:20:26 volumio volumio[13536]: info: Loading plugin "volumio_command_line_client"... Oct 24 04:20:26 volumio volumio[13536]: info: Loading plugin "upnp"... Oct 24 04:20:26 volumio volumio[13536]: info: [1761276026355] Starting Upmpd Daemon Oct 24 04:20:26 volumio volumio[13536]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 24 04:20:26 volumio volumio[13536]: info: Loading plugin "my_music"... Oct 24 04:20:26 volumio volumio[13536]: info: Loading plugin "mpd"... Oct 24 04:20:26 volumio volumio[13536]: info: Loading plugin "upnp_browser"... Oct 24 04:20:26 volumio volumio[13536]: info: Loading plugin "alarm-clock"... Oct 24 04:20:26 volumio volumio[13536]: info: Loading plugin "airplay_emulation"... Oct 24 04:20:26 volumio volumio[13536]: info: Starting Shairport Sync Oct 24 04:20:26 volumio volumio[13536]: info: Loading plugin "last_100"... Oct 24 04:20:26 volumio volumio[13536]: info: Loading plugin "webradio"... Oct 24 04:20:26 volumio volumio[13536]: info: Loading plugin "i2s_dacs"... Oct 24 04:20:26 volumio volumio[13536]: info: I2S DAC not set, start Auto-detection Oct 24 04:20:26 volumio volumio[13536]: info: Loading plugin "volumiodiscovery"... Oct 24 04:20:26 volumio volumio[13536]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Oct 24 04:20:26 volumio volumio[13536]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 24 04:20:26 volumio volumio[13536]: *** WARNING *** For more information see Oct 24 04:20:26 volumio volumio[13536]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Oct 24 04:20:26 volumio volumio[13536]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 24 04:20:26 volumio volumio[13536]: *** WARNING *** For more information see Oct 24 04:20:26 volumio node[13536]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Oct 24 04:20:26 volumio node[13536]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 24 04:20:26 volumio node[13536]: *** WARNING *** For more information see Oct 24 04:20:26 volumio node[13536]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Oct 24 04:20:26 volumio node[13536]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 24 04:20:26 volumio node[13536]: *** WARNING *** For more information see Oct 24 04:20:26 volumio volumio[13536]: info: Applying required configuration parameters for plugin volumiodiscovery Oct 24 04:20:26 volumio volumio[13536]: info: Discovery: Started advertising with name: Volumio Oct 24 04:20:27 volumio volumio[13536]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 24 04:20:27 volumio volumio[13536]: info: Loading plugin "spop"... Oct 24 04:20:27 volumio volumio[13536]: info: Loading plugin "ytcr"... Oct 24 04:20:28 volumio volumio[13536]: info: Loading plugin "outputs"... Oct 24 04:20:28 volumio volumio[13536]: info: Loading plugin "albumart"... Oct 24 04:20:28 volumio volumio[13536]: info: Plugin example_plugin is not enabled Oct 24 04:20:28 volumio volumio[13536]: info: Loading plugin "inputs"... Oct 24 04:20:28 volumio volumio[13536]: info: Loading plugin "updater_comm"... Oct 24 04:20:28 volumio volumio[13536]: info: Plugin mpdemulation is not enabled Oct 24 04:20:28 volumio volumio[13536]: info: Loading plugin "rest_api"... Oct 24 04:20:28 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1193. Oct 24 04:20:28 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 24 04:20:28 volumio volumio[13536]: info: Loading plugin "websocket"... Oct 24 04:20:28 volumio volumio[13536]: info: Starting Socket.io Server version 1.7.4 Oct 24 04:20:28 volumio volumio[13536]: info: Loading plugin "Systeminfo"... Oct 24 04:20:28 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 24 04:20:28 volumio go-librespot[13610]: go-librespot daemon starting... Oct 24 04:20:28 volumio go-librespot[13611]: time="2025-10-24T04:20:28+01:00" level=info msg="running go-librespot 0.4.0" Oct 24 04:20:28 volumio go-librespot[13611]: time="2025-10-24T04:20:28+01:00" level=debug msg="app state loaded" Oct 24 04:20:28 volumio go-librespot[13611]: time="2025-10-24T04:20:28+01:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 24 04:20:28 volumio volumio[13536]: info: Loading i18n strings for locale en Oct 24 04:20:28 volumio volumio[13536]: Updating browse sources language Oct 24 04:20:28 volumio volumio[13536]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 24 04:20:28 volumio volumio[13600]: Forking 3 albumart workers Oct 24 04:20:28 volumio volumio[13536]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 24 04:20:28 volumio volumio[13536]: info: CoreCommandRouter::initPlayerControls Oct 24 04:20:28 volumio volumio[13536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:20:28 volumio volumio[13536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:20:28 volumio volumio[13536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:20:28 volumio volumio[13536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:20:28 volumio volumio[13536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:20:28 volumio volumio[13536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:20:28 volumio volumio[13536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:20:28 volumio volumio[13536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:20:28 volumio volumio[13536]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 24 04:20:28 volumio volumio[13536]: Express server listening on port 3000 Oct 24 04:20:28 volumio volumio[13536]: [Metrics] WebUI: 2s 963.25ms Oct 24 04:20:28 volumio volumio[13536]: info: CoreStateMachine::resetVolumioState Oct 24 04:20:28 volumio volumio[13536]: info: CoreStateMachine::getcurrentVolume Oct 24 04:20:28 volumio volumio[13536]: info: CoreCommandRouter::volumioRetrievevolume Oct 24 04:20:28 volumio go-librespot[13611]: time="2025-10-24T04:20: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-gae2.spotify.com:80]" Oct 24 04:20:28 volumio go-librespot[13611]: time="2025-10-24T04:20:28+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 24 04:20:28 volumio go-librespot[13611]: time="2025-10-24T04:20:28+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 24 04:20:28 volumio go-librespot[13611]: time="2025-10-24T04:20:28+01:00" level=info msg="zeroconf server listening on port 36969" Oct 24 04:20:28 volumio volumio[13536]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 24 04:20:28 volumio volumio[13536]: info: Cannot read play queue from file Oct 24 04:20:28 volumio volumio[13536]: info: Volumio Network Manager: Network status updated: 1 Oct 24 04:20:28 volumio go-librespot[13611]: time="2025-10-24T04:20:28+01:00" level=debug msg="obtained new client token: AADGCgHEde+KXs7maqv1nvJPIQMwriI8B1FvTpL677X9bz0xhQzucqIOLqQut/GOAf0OLKSC/2/C/gUt4uN9L+eBiU0sszxKZa4k3VInxhj/kHaW5yVRqwQi61pdZ4nsjpUoq5NEOqBZ+5dI0hR/6J9bYEDLOQHkR9fB+yJPCgL5vCG3J2zs3+V91shcAlPzS1LsNNcnknk6k/VFHEQhoIhxtoZQk9WcCL4CG1PtIMg20eS4mUMseDo=" Oct 24 04:20:28 volumio go-librespot[13611]: time="2025-10-24T04:20:28+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 24 04:20:28 volumio volumio[13536]: info: CoreStateMachine::setRepeat null single undefined Oct 24 04:20:28 volumio volumio[13536]: info: CoreStateMachine::pushState Oct 24 04:20:28 volumio volumio[13536]: info: CorePlayQueue::getTrack 0 Oct 24 04:20:28 volumio volumio[13536]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 24 04:20:28 volumio volumio[13536]: info: CoreCommandRouter::volumioPushState Oct 24 04:20:28 volumio volumio[13536]: info: CoreStateMachine::setRandom null Oct 24 04:20:28 volumio volumio[13536]: info: CoreStateMachine::pushState Oct 24 04:20:28 volumio volumio[13536]: info: CorePlayQueue::getTrack 0 Oct 24 04:20:28 volumio volumio[13536]: info: CoreCommandRouter::volumioPushState Oct 24 04:20:28 volumio go-librespot[13611]: time="2025-10-24T04:20:28+01:00" level=debug msg="connected to ap-gew1.spotify.com:443" Oct 24 04:20:28 volumio volumio[13536]: info: Setting Device type: Raspberry PI Oct 24 04:20:28 volumio volumio[13536]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Oct 24 04:20:28 volumio volumio[13536]: info: USB Boot Capable - System SBC Revision found in cpuinfo: b04170 Oct 24 04:20:28 volumio volumio[13536]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Oct 24 04:20:28 volumio volumio[13536]: info: VolumeController:: Volume=51 Mute =false Oct 24 04:20:28 volumio volumio[13536]: info: CoreStateMachine::pushState Oct 24 04:20:28 volumio volumio[13536]: info: CorePlayQueue::getTrack 0 Oct 24 04:20:28 volumio volumio[13536]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 24 04:20:28 volumio volumio[13536]: info: CoreCommandRouter::volumioPushState Oct 24 04:20:28 volumio volumio[13536]: info: CoreStateMachine::updateTrackBlock Oct 24 04:20:28 volumio volumio[13536]: info: CorePlayQueue::getTrackBlock Oct 24 04:20:28 volumio volumio[13536]: info: CoreCommandRouter::volumioRetrievevolume Oct 24 04:20:28 volumio go-librespot[13611]: time="2025-10-24T04:20:28+01:00" level=debug msg="completed keyexchange" Oct 24 04:20:28 volumio go-librespot[13611]: time="2025-10-24T04:20:28+01:00" level=debug msg="completed challenge" Oct 24 04:20:28 volumio go-librespot[13611]: time="2025-10-24T04:20: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 24 04:20:28 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 24 04:20:28 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 24 04:20:28 volumio volumio[13536]: info: Completed loading Core Plugins Oct 24 04:20:28 volumio volumio[13536]: info: Preparing to generate the ALSA configuration file Oct 24 04:20:28 volumio volumio[13536]: info: Discovery: adding 70853f74-8210-4683-a3fa-e1217517bd40 Oct 24 04:20:28 volumio volumio[13536]: info: Discovery: Found device Volumio Oct 24 04:20:28 volumio volumio[13536]: info: CoreCommandRouter::volumioGetState Oct 24 04:20:28 volumio volumio[13536]: info: CorePlayQueue::getTrack 0 Oct 24 04:20:28 volumio volumio[13536]: info: VolumeController:: Volume=51 Mute =false Oct 24 04:20:28 volumio volumio[13536]: info: CoreStateMachine::pushState Oct 24 04:20:28 volumio volumio[13536]: info: CorePlayQueue::getTrack 0 Oct 24 04:20:28 volumio volumio[13536]: info: CoreCommandRouter::volumioPushState Oct 24 04:20:28 volumio volumio[13536]: info: Asound.conf file unchanged, so no further update is needed Oct 24 04:20:28 volumio volumio[13536]: info: Output device has changed, restarting MPD Oct 24 04:20:28 volumio volumio[13536]: info: Output device has changed, restarting Shairport Sync Oct 24 04:20:28 volumio volumio[13536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:20:28 volumio volumio[13536]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 24 04:20:28 volumio sudo[13664]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 24 04:20:28 volumio sudo[13664]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 24 04:20:28 volumio sudo[13664]: pam_unix(sudo:session): session closed for user root Oct 24 04:20:28 volumio volumio[13536]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 24 04:20:28 volumio sudo[13666]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 24 04:20:28 volumio volumio[13536]: info: ___________ START PLUGINS ___________ Oct 24 04:20:28 volumio sudo[13666]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 24 04:20:28 volumio volumio[13536]: info: ControllerMpd::onStart: Initializing MPD Oct 24 04:20:28 volumio volumio[13536]: info: Creating MPD Configuration file Oct 24 04:20:28 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Oct 24 04:20:28 volumio volumio[13536]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 24 04:20:28 volumio volumio[13536]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 24 04:20:28 volumio volumio[13536]: info: [1761276028893] CoreMusicLibrary::Adding element Media Servers Oct 24 04:20:28 volumio volumio[13536]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 24 04:20:28 volumio sudo[13675]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 24 04:20:28 volumio sudo[13675]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 24 04:20:28 volumio sudo[13675]: pam_unix(sudo:session): session closed for user root Oct 24 04:20:28 volumio sudo[13570]: pam_unix(sudo:session): session closed for user root Oct 24 04:20:28 volumio sudo[13676]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 24 04:20:28 volumio sudo[13676]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 24 04:20:28 volumio systemd[1]: mpd.service: Deactivated successfully. Oct 24 04:20:28 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Oct 24 04:20:28 volumio systemd[1]: mpd.socket: Deactivated successfully. Oct 24 04:20:28 volumio volumio[13536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:20:28 volumio volumio[13536]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 24 04:20:28 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Oct 24 04:20:28 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Oct 24 04:20:28 volumio volumio[13536]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 24 04:20:28 volumio volumio[13536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:20:28 volumio volumio[13536]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 24 04:20:28 volumio volumio[13536]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 24 04:20:28 volumio volumio[13536]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 24 04:20:28 volumio volumio[13536]: info: [1761276028945] CoreMusicLibrary::Adding element Last_100 Oct 24 04:20:28 volumio volumio[13536]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 24 04:20:28 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Oct 24 04:20:28 volumio volumio[13536]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 24 04:20:28 volumio volumio[13536]: info: [1761276028946] CoreMusicLibrary::Adding element Webradio Oct 24 04:20:28 volumio volumio[13536]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 24 04:20:28 volumio volumio[13536]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 24 04:20:28 volumio volumio[13536]: info: Initializing BBC Radios Oct 24 04:20:28 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Oct 24 04:20:28 volumio systemd[1]: mpd.service: Deactivated successfully. Oct 24 04:20:28 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Oct 24 04:20:28 volumio systemd[1]: mpd.socket: Deactivated successfully. Oct 24 04:20:28 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Oct 24 04:20:28 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Oct 24 04:20:28 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Oct 24 04:20:28 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Oct 24 04:20:29 volumio volumio[13536]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 24 04:20:29 volumio volumio[13536]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 24 04:20:29 volumio volumio[13536]: info: Creating Spotify config file Oct 24 04:20:29 volumio volumio[13536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:20:29 volumio sudo[13700]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Oct 24 04:20:29 volumio sudo[13700]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Oct 24 04:20:29 volumio sudo[13700]: pam_unix(sudo:session): session closed for user root Oct 24 04:20:29 volumio volumio[13617]: Starting albumart workers Oct 24 04:20:29 volumio volumio[13618]: Starting albumart workers Oct 24 04:20:29 volumio volumio[13620]: Starting albumart workers Oct 24 04:20:29 volumio volumio[13536]: info: Volumio Calling Home Oct 24 04:20:29 volumio volumio[13536]: info: Discovery: this is already registered, 70853f74-8210-4683-a3fa-e1217517bd40 Oct 24 04:20:29 volumio volumio[13536]: info: Discovery: Found device Volumio Oct 24 04:20:29 volumio volumio[13536]: info: CoreCommandRouter::volumioGetState Oct 24 04:20:29 volumio volumio[13536]: info: CorePlayQueue::getTrack 0 Oct 24 04:20:29 volumio volumio[13536]: info: MPD Permissions set Oct 24 04:20:29 volumio volumio[13536]: info: MPD Permissions set Oct 24 04:20:29 volumio volumio[13536]: info: Volumio called home Oct 24 04:20:29 volumio volumio[13536]: info: Spotify config file written Oct 24 04:20:29 volumio volumio[13536]: 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 24 04:20:29 volumio volumio[13536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:20:29 volumio volumio[13536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:20:29 volumio volumio[13536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:20:29 volumio volumio[13536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:20:29 volumio volumio[13536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:20:29 volumio volumio[13536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:20:29 volumio volumio[13536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:20:29 volumio volumio[13536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:20:29 volumio sudo[13716]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Oct 24 04:20:29 volumio sudo[13716]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 24 04:20:29 volumio volumio[13536]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 24 04:20:29 volumio volumio[13536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:20:29 volumio volumio[13536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:20:29 volumio volumio[13536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:20:29 volumio volumio[13536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:20:29 volumio volumio[13536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:20:29 volumio volumio[13536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:20:29 volumio volumio[13536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:20:29 volumio volumio[13536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:20:29 volumio volumio[13536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:20:29 volumio volumio[13536]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 24 04:20:29 volumio volumio[13536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:20:29 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 24 04:20:29 volumio volumio[13536]: info: No need to fix Spotify hosts Oct 24 04:20:29 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 24 04:20:29 volumio go-librespot[13728]: go-librespot daemon starting... Oct 24 04:20:29 volumio sudo[13716]: pam_unix(sudo:session): session closed for user root Oct 24 04:20:29 volumio go-librespot[13735]: time="2025-10-24T04:20:29+01:00" level=info msg="running go-librespot 0.4.0" Oct 24 04:20:29 volumio go-librespot[13735]: time="2025-10-24T04:20:29+01:00" level=debug msg="app state loaded" Oct 24 04:20:29 volumio go-librespot[13735]: time="2025-10-24T04:20:29+01:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 24 04:20:29 volumio volumio[13536]: info: Starting Shairport Sync Oct 24 04:20:29 volumio volumio[13536]: info: Starting Shairport Sync Oct 24 04:20:29 volumio volumio[13536]: info: Starting Shairport Sync Oct 24 04:20:29 volumio sudo[13749]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 24 04:20:29 volumio sudo[13749]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 24 04:20:29 volumio go-librespot[13735]: time="2025-10-24T04:20: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-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Oct 24 04:20:29 volumio go-librespot[13735]: time="2025-10-24T04:20:29+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 24 04:20:29 volumio go-librespot[13735]: time="2025-10-24T04:20:29+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 24 04:20:29 volumio sudo[13751]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 24 04:20:29 volumio go-librespot[13735]: time="2025-10-24T04:20:29+01:00" level=info msg="zeroconf server listening on port 33105" Oct 24 04:20:29 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Oct 24 04:20:29 volumio sudo[13751]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 24 04:20:29 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Oct 24 04:20:29 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Oct 24 04:20:29 volumio systemd[1]: shairport-sync.service: Consumed 1.559s CPU time. Oct 24 04:20:29 volumio volumio[13536]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Oct 24 04:20:29 volumio volumio[13536]: SPOTIFY: BQATpnMEzHJv7EdAcv6uFd0gAKVUZ-kMl4oTQklUENT_2q0K1nu__zA_OTfdsI_nExRc5iu77enNlv_2cpy8QbLYp5UIOJ5hyggVkKUsOdz_Sqjg8eDr4TNpPQxIbpuwmSJ8umUO72rAXsVlaLrTtX54xXxoCKlFmlID-3Pz2-ZmwKtE9PixVVZfsF4H0nIH1Kf62Xq3_4bL8WYFd2twPrMY5SI5i6xl1oplJ3q4zSoXfbhqTfODkBQ4fVq_Gdc63viBc2o8Qx6c51xSzMWMtl66GHXuBphj4a1NRoJROGQrJIn3B08 Oct 24 04:20:29 volumio volumio[13536]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Oct 24 04:20:29 volumio volumio[13536]: info: New Spotify access token = BQATpnMEzHJv7EdAcv6uFd0gAKVUZ-kMl4oTQklUENT_2q0K1nu__zA_OTfdsI_nExRc5iu77enNlv_2cpy8QbLYp5UIOJ5hyggVkKUsOdz_Sqjg8eDr4TNpPQxIbpuwmSJ8umUO72rAXsVlaLrTtX54xXxoCKlFmlID-3Pz2-ZmwKtE9PixVVZfsF4H0nIH1Kf62Xq3_4bL8WYFd2twPrMY5SI5i6xl1oplJ3q4zSoXfbhqTfODkBQ4fVq_Gdc63viBc2o8Qx6c51xSzMWMtl66GHXuBphj4a1NRoJROGQrJIn3B08 Oct 24 04:20:29 volumio volumio[13536]: info: Spotify credentials grant success - running version from March 24, 2019 Oct 24 04:20:29 volumio sudo[13754]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 24 04:20:29 volumio sudo[13754]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 24 04:20:29 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Oct 24 04:20:29 volumio sudo[13749]: pam_unix(sudo:session): session closed for user root Oct 24 04:20:29 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Oct 24 04:20:29 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Oct 24 04:20:29 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Oct 24 04:20:29 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Oct 24 04:20:29 volumio sudo[13754]: pam_unix(sudo:session): session closed for user root Oct 24 04:20:29 volumio sudo[13751]: pam_unix(sudo:session): session closed for user root Oct 24 04:20:29 volumio go-librespot[13735]: time="2025-10-24T04:20:29+01:00" level=debug msg="obtained new client token: AADbu06wzebHE2CNM9jGuw5bjv//FZtzU1R/QB+ssEATaYxCn7t4YuMa6NSCCsFPLlX8GgMeM8W/ZzDv/auoI6kcBvdWMOi7HGxLEntQxgjN/x0WlkQniT1VccCawAXRb172XoVr9FEjsP5lX6ZBu2W0y470gOz5VncXMTmODPWVdW53hrYSFBqic6pAuks1BarKP3lBywyJKIHovmpO5Ofblr13NQn9cR0Wm1CH4IUyueOixpKCfLk=" Oct 24 04:20:29 volumio volumio[13536]: info: Shairport-Sync Started Oct 24 04:20:29 volumio volumio[13536]: Error adding Membership: Error: addMembership EINVAL Oct 24 04:20:29 volumio volumio[13536]: info: Shairport-Sync Started Oct 24 04:20:29 volumio volumio[13536]: info: Shairport-Sync Started Oct 24 04:20:29 volumio go-librespot[13735]: time="2025-10-24T04:20:29+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 24 04:20:29 volumio volumio[13536]: info: CoreCommandRouter::volumioGetState Oct 24 04:20:29 volumio volumio[13536]: info: CorePlayQueue::getTrack 0 Oct 24 04:20:29 volumio go-librespot[13735]: time="2025-10-24T04:20:29+01:00" level=debug msg="connected to ap-gew1.spotify.com:443" Oct 24 04:20:29 volumio go-librespot[13735]: time="2025-10-24T04:20:29+01:00" level=debug msg="completed keyexchange" Oct 24 04:20:29 volumio go-librespot[13735]: time="2025-10-24T04:20:29+01:00" level=debug msg="completed challenge" Oct 24 04:20:29 volumio volumio[13536]: 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 24 04:20:29 volumio volumio[13536]: info: Spotify Successfully logged in Oct 24 04:20:29 volumio volumio[13536]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 24 04:20:29 volumio volumio[13536]: info: [1761276029806] CoreMusicLibrary::Adding element Spotify Oct 24 04:20:29 volumio volumio[13536]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 24 04:20:29 volumio volumio[13536]: Cannot find translation for source Spotify Oct 24 04:20:29 volumio go-librespot[13735]: time="2025-10-24T04:20: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 24 04:20:29 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 24 04:20:29 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 24 04:20:29 volumio volumio-remote-updater[896]: [2025-10-24 03:20:29] [connect] Successful connection Oct 24 04:20:29 volumio volumio-remote-updater[896]: [2025-10-24 03:20:29] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1761276029 101 Oct 24 04:20:29 volumio volumio[13536]: 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 24 04:20:29 volumio mpd[13705]: 2025-10-24T04:20:29 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Oct 24 04:20:29 volumio systemd[1]: Started mpd.service - Music Player Daemon. Oct 24 04:20:29 volumio sudo[13666]: pam_unix(sudo:session): session closed for user root Oct 24 04:20:29 volumio sudo[13676]: pam_unix(sudo:session): session closed for user root Oct 24 04:20:29 volumio volumio[13536]: error: MPD error: The expression evaluated to a falsy value: Oct 24 04:20:29 volumio volumio[13536]: assert.ok(self.idling) Oct 24 04:20:29 volumio volumio[13536]: error: The expression evaluated to a falsy value: Oct 24 04:20:29 volumio volumio[13536]: assert.ok(self.idling) Oct 24 04:20:29 volumio volumio[13536]: info: MPD running with PID13705 Oct 24 04:20:29 volumio volumio[13536]: ,establishing connection Oct 24 04:20:29 volumio volumio[13536]: error: updateQueue error: null Oct 24 04:20:29 volumio volumio[13536]: error: updateQueue error: null Oct 24 04:20:30 volumio volumio[13536]: info: [yt-cast-receiver] DIAL server listening on port 8098 Oct 24 04:20:30 volumio volumio[13536]: info: CoreCommandRouter::volumioRetrievevolume Oct 24 04:20:30 volumio volumio[13536]: info: VolumeController:: Volume=51 Mute =false Oct 24 04:20:30 volumio volumio[13536]: info: CoreCommandRouter::volumioGetState Oct 24 04:20:30 volumio volumio[13536]: info: CorePlayQueue::getTrack 0 Oct 24 04:20:30 volumio volumio[13536]: info: CoreStateMachine::pushState Oct 24 04:20:30 volumio volumio[13536]: info: CorePlayQueue::getTrack 0 Oct 24 04:20:30 volumio volumio[13536]: info: CoreCommandRouter::volumioPushState Oct 24 04:20:30 volumio volumio[13536]: info: Completed starting Core Plugins Oct 24 04:20:30 volumio volumio[13536]: info: ------------------------------------------- Oct 24 04:20:30 volumio volumio[13536]: info: ----- MyVolumio plugins startup ---- Oct 24 04:20:30 volumio volumio[13536]: info: ------------------------------------------- Oct 24 04:20:30 volumio volumio[13536]: info: [MyVolumio PluginManager] Fetching plans data.... Oct 24 04:20:31 volumio volumio[13536]: info: Cannot mount NAS NAS at system boot, trial number 2 ,retrying in 5 seconds Oct 24 04:20:32 volumio volumio[13536]: info: go-librespot daemon successfully initialized Oct 24 04:20:32 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1194. Oct 24 04:20:32 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 24 04:20:32 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 24 04:20:32 volumio go-librespot[13788]: go-librespot daemon starting... Oct 24 04:20:32 volumio go-librespot[13789]: time="2025-10-24T04:20:32+01:00" level=info msg="running go-librespot 0.4.0" Oct 24 04:20:32 volumio go-librespot[13789]: time="2025-10-24T04:20:32+01:00" level=debug msg="app state loaded" Oct 24 04:20:32 volumio go-librespot[13789]: time="2025-10-24T04:20:32+01:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 24 04:20:32 volumio sudo[13796]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Oct 24 04:20:32 volumio sudo[13796]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 24 04:20:32 volumio sudo[13798]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Oct 24 04:20:32 volumio sudo[13798]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 24 04:20:32 volumio systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Oct 24 04:20:32 volumio systemd[1]: mpd_monitor.service: Deactivated successfully. Oct 24 04:20:32 volumio systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Oct 24 04:20:33 volumio systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Oct 24 04:20:33 volumio sudo[13796]: pam_unix(sudo:session): session closed for user root Oct 24 04:20:33 volumio mpd_monitor.sh[13801]: MPD Monitor Service: Starting MPD Monitor Service Oct 24 04:20:33 volumio sudo[13798]: pam_unix(sudo:session): session closed for user root Oct 24 04:20:33 volumio volumio[13536]: info: Successfully started MPD Monitor Oct 24 04:20:33 volumio volumio[13536]: info: Successfully started MPD Monitor Oct 24 04:20:33 volumio go-librespot[13789]: time="2025-10-24T04:20:33+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 24 04:20:33 volumio go-librespot[13789]: time="2025-10-24T04:20:33+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 24 04:20:33 volumio go-librespot[13789]: time="2025-10-24T04:20:33+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 24 04:20:33 volumio go-librespot[13789]: time="2025-10-24T04:20:33+01:00" level=info msg="zeroconf server listening on port 45493" Oct 24 04:20:33 volumio go-librespot[13789]: time="2025-10-24T04:20:33+01:00" level=debug msg="obtained new client token: AACYbC1jvyCljEd6Z3bsdm+1GNPsHaZWvuz45Gs5WsSXTsIdReLv8+hBd9TD3+ViZ6jZoBpjF1rKATxz24fLJHzgW5Pv3CEyMVemKuZ/3dseVmodihJqMuoYmDc6IqVjpb/PgcIyYie9uaSmApzYXehlg1D0Q23jxNfdXQBHVjBrhjmtrzsMZ8XwFMvRoD51rsyduekYlMDHjRTSlsu8fRV2WdL5/pulcck3Lkqzsx8SJ6Po8lI7" Oct 24 04:20:33 volumio go-librespot[13789]: time="2025-10-24T04:20:33+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 24 04:20:33 volumio go-librespot[13789]: time="2025-10-24T04:20:33+01:00" level=debug msg="completed keyexchange" Oct 24 04:20:33 volumio go-librespot[13789]: time="2025-10-24T04:20:33+01:00" level=debug msg="completed challenge" Oct 24 04:20:33 volumio go-librespot[13789]: time="2025-10-24T04:20:33+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 24 04:20:33 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 24 04:20:33 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 24 04:20:34 volumio kernel: nfs: server 192.168.1.3 not responding, timed out Oct 24 04:20:34 volumio volumio[13536]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Oct 24 04:20:35 volumio volumio[13536]: info: Initializing connection to go-librespot Websocket Oct 24 04:20:35 volumio volumio[13536]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 24 04:20:36 volumio volumio[13536]: info: Cannot mount NAS NAS at system boot, trial number 3 ,retrying in 5 seconds Oct 24 04:20:36 volumio sudo[13822]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 24 04:20:36 volumio sudo[13822]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 24 04:20:36 volumio sudo[13822]: pam_unix(sudo:session): session closed for user root Oct 24 04:20:36 volumio sudo[13824]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 24 04:20:36 volumio sudo[13824]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 24 04:20:36 volumio sudo[13824]: pam_unix(sudo:session): session closed for user root Oct 24 04:20:36 volumio sudo[13827]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Oct 24 04:20:36 volumio sudo[13827]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 24 04:20:36 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1195. Oct 24 04:20:36 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 24 04:20:36 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 24 04:20:36 volumio go-librespot[13830]: go-librespot daemon starting... Oct 24 04:20:36 volumio sudo[13827]: pam_unix(sudo:session): session closed for user root Oct 24 04:20:36 volumio volumio[13536]: info: Upmpdcli Daemon Started Oct 24 04:20:36 volumio go-librespot[13831]: time="2025-10-24T04:20:36+01:00" level=info msg="running go-librespot 0.4.0" Oct 24 04:20:36 volumio go-librespot[13831]: time="2025-10-24T04:20:36+01:00" level=debug msg="app state loaded" Oct 24 04:20:36 volumio go-librespot[13831]: time="2025-10-24T04:20:36+01:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 24 04:20:36 volumio go-librespot[13831]: time="2025-10-24T04:20: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-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Oct 24 04:20:36 volumio go-librespot[13831]: time="2025-10-24T04:20:36+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 24 04:20:36 volumio go-librespot[13831]: time="2025-10-24T04:20:36+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 24 04:20:36 volumio go-librespot[13831]: time="2025-10-24T04:20:36+01:00" level=info msg="zeroconf server listening on port 42233" Oct 24 04:20:36 volumio go-librespot[13831]: time="2025-10-24T04:20:36+01:00" level=debug msg="obtained new client token: AADPpyNCwa6iCKojIQlaRr58CfPUiR8hb9utJ1sHUJDJQgWEhaqWqoAPf8XnKWco1HO5AViK4PEMQqi25RvOuR1eVqbXGB0rnqNi1HsQpOErPhUQlxHvzBxpj1NCszhvzXMuic3kzg8DacbRrB8fV+bZYhk+uMy5Kvhse0nQjyNBOzFPk8ZqzIWONM2yTdJidpXQoYhRpE8WwO/3pK9ZdwudbyNgmQf6j5tTctUcuqozb7fjppwAOT4=" Oct 24 04:20:36 volumio go-librespot[13831]: time="2025-10-24T04:20:36+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 24 04:20:36 volumio go-librespot[13831]: time="2025-10-24T04:20:36+01:00" level=debug msg="completed keyexchange" Oct 24 04:20:36 volumio go-librespot[13831]: time="2025-10-24T04:20:36+01:00" level=debug msg="completed challenge" Oct 24 04:20:36 volumio go-librespot[13831]: time="2025-10-24T04:20: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 24 04:20:36 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 24 04:20:36 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 24 04:20:38 volumio volumio[13536]: info: Initializing connection to go-librespot Websocket Oct 24 04:20:38 volumio volumio[13536]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 24 04:20:38 volumio volumio[13536]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Oct 24 04:20:38 volumio volumio[13536]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Oct 24 04:20:38 volumio volumio[13536]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Oct 24 04:20:38 volumio volumio[13536]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Oct 24 04:20:38 volumio volumio[13536]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Oct 24 04:20:38 volumio volumio[13536]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Oct 24 04:20:38 volumio volumio[13536]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Oct 24 04:20:38 volumio volumio[13536]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Oct 24 04:20:38 volumio volumio[13536]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Oct 24 04:20:38 volumio volumio[13536]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Oct 24 04:20:38 volumio volumio[13536]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Oct 24 04:20:38 volumio volumio[13536]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Oct 24 04:20:38 volumio volumio[13536]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Oct 24 04:20:38 volumio volumio[13536]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Oct 24 04:20:38 volumio volumio[13536]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Oct 24 04:20:38 volumio volumio[13536]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Oct 24 04:20:38 volumio volumio[13536]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Oct 24 04:20:38 volumio volumio[13536]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Oct 24 04:20:38 volumio volumio[13536]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Oct 24 04:20:38 volumio volumio[13536]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Oct 24 04:20:38 volumio volumio[13536]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Oct 24 04:20:38 volumio volumio[13536]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Oct 24 04:20:38 volumio volumio[13536]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Oct 24 04:20:38 volumio volumio[13536]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Oct 24 04:20:38 volumio volumio[13536]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Oct 24 04:20:38 volumio volumio[13536]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Oct 24 04:20:38 volumio volumio[13536]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Oct 24 04:20:38 volumio volumio[13536]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Oct 24 04:20:38 volumio volumio[13536]: info: Adding plugin bluetooth to MyMusic Plugins Oct 24 04:20:38 volumio volumio[13536]: info: Adding plugin multiroom to MyMusic Plugins Oct 24 04:20:38 volumio volumio[13536]: info: Adding plugin metavolumio to MyMusic Plugins Oct 24 04:20:38 volumio volumio[13536]: info: Adding plugin cd_controller to MyMusic Plugins Oct 24 04:20:38 volumio volumio[13536]: info: Adding plugin qobuzconnect to MyMusic Plugins Oct 24 04:20:38 volumio volumio[13536]: info: Adding plugin smart_inputs to MyMusic Plugins Oct 24 04:20:38 volumio volumio[13536]: info: Adding plugin tidalconnect to MyMusic Plugins Oct 24 04:20:38 volumio volumio[13536]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Oct 24 04:20:38 volumio volumio[13536]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Oct 24 04:20:38 volumio volumio[13536]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Oct 24 04:20:38 volumio volumio[13536]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 24 04:20:38 volumio volumio[13536]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 24 04:20:38 volumio volumio[13536]: info: Starting MyVolumio Remote Streaming Endpoints Oct 24 04:20:38 volumio volumio[13536]: info: MyVolumio login type: Token Oct 24 04:20:38 volumio volumio[13536]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Oct 24 04:20:38 volumio volumio[13536]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Oct 24 04:20:39 volumio volumio[13536]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Oct 24 04:20:39 volumio volumio[13536]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Oct 24 04:20:39 volumio volumio[13536]: info: Streaming services startup Oct 24 04:20:39 volumio volumio[13536]: info: Starting Streaming Daemon Oct 24 04:20:39 volumio sudo[13841]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Oct 24 04:20:39 volumio sudo[13841]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 24 04:20:39 volumio volumio[13536]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Oct 24 04:20:39 volumio sudo[13841]: pam_unix(sudo:session): session closed for user root Oct 24 04:20:39 volumio volumio[13536]: error: Cannot start Volumio Streaming Daemon Oct 24 04:20:39 volumio volumio[13536]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Oct 24 04:20:39 volumio volumio[13536]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Oct 24 04:20:39 volumio volumio[13536]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Oct 24 04:20:39 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1196. Oct 24 04:20:39 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 24 04:20:39 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 24 04:20:39 volumio go-librespot[13848]: go-librespot daemon starting... Oct 24 04:20:39 volumio go-librespot[13849]: time="2025-10-24T04:20:39+01:00" level=info msg="running go-librespot 0.4.0" Oct 24 04:20:39 volumio go-librespot[13849]: time="2025-10-24T04:20:39+01:00" level=debug msg="app state loaded" Oct 24 04:20:39 volumio go-librespot[13849]: time="2025-10-24T04:20:39+01:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 24 04:20:40 volumio go-librespot[13849]: time="2025-10-24T04:20:40+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 24 04:20:40 volumio go-librespot[13849]: time="2025-10-24T04:20:40+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 24 04:20:40 volumio go-librespot[13849]: time="2025-10-24T04:20:40+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 24 04:20:40 volumio go-librespot[13849]: time="2025-10-24T04:20:40+01:00" level=info msg="zeroconf server listening on port 41437" Oct 24 04:20:40 volumio volumio[13536]: info: MyVolumio token set successfully Oct 24 04:20:40 volumio volumio[13536]: info: MYVOLUMIO: Adding device Oct 24 04:20:40 volumio volumio[13536]: info: MYVOLUMIO: Evaluating Server Oct 24 04:20:40 volumio go-librespot[13849]: time="2025-10-24T04:20:40+01:00" level=debug msg="obtained new client token: AADrTXqJpBX9is+yqF7xoKNp4As2B1LmOjOdm2tOnW6Hw4fT0y9XjANiE6NdQnoscjSJ7l1CWLxkV4/qnqoExXAbyzyjgwynVwQazJQpHg8M9qnzsefKzaFnPE8E20FVYM4dkVi0kTgR1gPNRANqobV5DDz5TlzsE5ORbIqgfcNlKzftltsTm/xHPHZj8JBf2JoxZB//l+ji7EPxr4bPPjnfhknyEuglJW7bfjyLa66FTHmYcjZ+" Oct 24 04:20:40 volumio go-librespot[13849]: time="2025-10-24T04:20:40+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 24 04:20:40 volumio go-librespot[13849]: time="2025-10-24T04:20:40+01:00" level=debug msg="completed keyexchange" Oct 24 04:20:40 volumio go-librespot[13849]: time="2025-10-24T04:20:40+01:00" level=debug msg="completed challenge" Oct 24 04:20:40 volumio go-librespot[13849]: time="2025-10-24T04:20:40+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 24 04:20:40 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 24 04:20:40 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 24 04:20:40 volumio volumio[13536]: info: MyVolumio status changed Oct 24 04:20:40 volumio volumio[13536]: info: Streaming services startup Oct 24 04:20:40 volumio volumio[13536]: info: Starting Streaming Daemon Oct 24 04:20:40 volumio volumio[13536]: info: Removing browser output: myVolumio user plan is not superstar Oct 24 04:20:40 volumio volumio[13536]: info: Removing audio output: Oct 24 04:20:40 volumio volumio[13536]: info: Stoppping Tunnel 1 Oct 24 04:20:40 volumio sudo[13874]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Oct 24 04:20:40 volumio sudo[13874]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 24 04:20:40 volumio sudo[13876]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service Oct 24 04:20:40 volumio sudo[13876]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 24 04:20:40 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 24 04:20:40 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 24 04:20:40 volumio sudo[13874]: pam_unix(sudo:session): session closed for user root Oct 24 04:20:40 volumio volumio[13536]: error: Cannot start Volumio Streaming Daemon Oct 24 04:20:40 volumio volumio[13536]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Oct 24 04:20:40 volumio volumio[13536]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Oct 24 04:20:40 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 24 04:20:40 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 24 04:20:40 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 24 04:20:40 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 24 04:20:40 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 24 04:20:40 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 24 04:20:40 volumio sudo[13876]: pam_unix(sudo:session): session closed for user root Oct 24 04:20:40 volumio volumio[13536]: info: Remote SSH Stopped Oct 24 04:20:40 volumio volumio[13536]: info: Setting Geolocation for MyVolumio to eu3 Oct 24 04:20:40 volumio volumio[13536]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 24 04:20:40 volumio volumio[13536]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 24 04:20:40 volumio volumio[13536]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 24 04:20:41 volumio volumio[13536]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Oct 24 04:20:41 volumio volumio[13536]: info: Cannot mount NAS NAS at system boot, trial number 4 ,retrying in 5 seconds Oct 24 04:20:41 volumio volumio[13536]: info: Initializing connection to go-librespot Websocket Oct 24 04:20:41 volumio volumio[13536]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 24 04:20:41 volumio volumio[13536]: info: Updating MyVolumio device info Oct 24 04:20:41 volumio volumio[13536]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 24 04:20:41 volumio volumio[13536]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 24 04:20:41 volumio volumio[13536]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 24 04:20:41 volumio volumio[13536]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Oct 24 04:20:43 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1197. Oct 24 04:20:43 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 24 04:20:43 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 24 04:20:43 volumio go-librespot[13879]: go-librespot daemon starting... Oct 24 04:20:43 volumio go-librespot[13880]: time="2025-10-24T04:20:43+01:00" level=info msg="running go-librespot 0.4.0" Oct 24 04:20:43 volumio go-librespot[13880]: time="2025-10-24T04:20:43+01:00" level=debug msg="app state loaded" Oct 24 04:20:43 volumio go-librespot[13880]: time="2025-10-24T04:20:43+01:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 24 04:20:43 volumio go-librespot[13880]: time="2025-10-24T04:20: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-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Oct 24 04:20:43 volumio go-librespot[13880]: time="2025-10-24T04:20:43+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 24 04:20:43 volumio go-librespot[13880]: time="2025-10-24T04:20:43+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 24 04:20:43 volumio go-librespot[13880]: time="2025-10-24T04:20:43+01:00" level=info msg="zeroconf server listening on port 38873" Oct 24 04:20:43 volumio go-librespot[13880]: time="2025-10-24T04:20:43+01:00" level=debug msg="obtained new client token: AAB91knIpCMXOxzs7y3x4TzT42bLkjVuy9ezNngC1bUNKXFKOz1kUYwbL9H1g5VxtGBpCtxlv+KHz2QHW4Db3CbfcncWZioLkngkBLNPsQOYmVjJ3OiTmOt5JJ3La3E3ukPRR92Pg6zywspIwZS0djanHeru+4i52C3SjXV+6TCIrmsTd2sqP0DXaQ/LbcUQJJPdFL/Fi9w1v26OxecDMQBPd/nL8kbz9vcgMSlltYbBAkZX5gAYLfc=" Oct 24 04:20:43 volumio go-librespot[13880]: time="2025-10-24T04:20:43+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 24 04:20:43 volumio go-librespot[13880]: time="2025-10-24T04:20:43+01:00" level=debug msg="completed keyexchange" Oct 24 04:20:43 volumio go-librespot[13880]: time="2025-10-24T04:20:43+01:00" level=debug msg="completed challenge" Oct 24 04:20:43 volumio go-librespot[13880]: time="2025-10-24T04:20: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 24 04:20:43 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 24 04:20:43 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 24 04:20:44 volumio volumio[13536]: info: Initializing connection to go-librespot Websocket Oct 24 04:20:44 volumio volumio[13536]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 24 04:20:45 volumio volumio[13536]: info: MYVOLUMIO: Adding device Oct 24 04:20:45 volumio volumio[13536]: info: MYVOLUMIO: Evaluating Server Oct 24 04:20:45 volumio volumio[13536]: info: Setting Geolocation for MyVolumio to eu3 Oct 24 04:20:45 volumio volumio[13536]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 24 04:20:45 volumio volumio[13536]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 24 04:20:45 volumio volumio[13536]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 24 04:20:45 volumio volumio[13536]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Oct 24 04:20:46 volumio kernel: nfs: server 192.168.1.3 not responding, timed out Oct 24 04:20:46 volumio volumio[13536]: info: Cannot mount NAS at system boot, trial number 4 ,stopping Oct 24 04:20:46 volumio volumio[13536]: info: Updating MyVolumio device info Oct 24 04:20:46 volumio volumio[13536]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 24 04:20:46 volumio volumio[13536]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 24 04:20:46 volumio volumio[13536]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 24 04:20:46 volumio volumio[13536]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Oct 24 04:20:46 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1198. Oct 24 04:20:46 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 24 04:20:46 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 24 04:20:46 volumio go-librespot[13917]: go-librespot daemon starting... Oct 24 04:20:46 volumio go-librespot[13918]: time="2025-10-24T04:20:46+01:00" level=info msg="running go-librespot 0.4.0" Oct 24 04:20:46 volumio go-librespot[13918]: time="2025-10-24T04:20:46+01:00" level=debug msg="app state loaded" Oct 24 04:20:46 volumio go-librespot[13918]: time="2025-10-24T04:20:46+01:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 24 04:20:47 volumio go-librespot[13918]: time="2025-10-24T04:20:47+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 24 04:20:47 volumio go-librespot[13918]: time="2025-10-24T04:20:47+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 24 04:20:47 volumio go-librespot[13918]: time="2025-10-24T04:20:47+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 24 04:20:47 volumio go-librespot[13918]: time="2025-10-24T04:20:47+01:00" level=info msg="zeroconf server listening on port 41673" Oct 24 04:20:47 volumio go-librespot[13918]: time="2025-10-24T04:20:47+01:00" level=debug msg="obtained new client token: AACUVOHgcYnaWc91AW5wWI8nzO+6TzBuVfmpNQ2hNDvJ2Giry13dEf/GDEnMcGR9aMdFBmJ4qtNycgPs6VXrn37KUheeukQ5yPlMo5AxQfWqUScbBRzn6XoquBBUPBUAT6sz8LWj0mPmxxym1YEHpmhpvMBcnO4j8fnRtl7IVhoc5w7Bb9YkYKUJqKpbNuJ6eQ8XmwlFAeWVHkpju9NJ48O45pYTrIY/c9YVUxHlOZswNBSbsKQP" Oct 24 04:20:47 volumio go-librespot[13918]: time="2025-10-24T04:20:47+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 24 04:20:47 volumio go-librespot[13918]: time="2025-10-24T04:20:47+01:00" level=debug msg="completed keyexchange" Oct 24 04:20:47 volumio go-librespot[13918]: time="2025-10-24T04:20:47+01:00" level=debug msg="completed challenge" Oct 24 04:20:47 volumio go-librespot[13918]: time="2025-10-24T04:20:47+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 24 04:20:47 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 24 04:20:47 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 24 04:20:47 volumio volumio[13536]: info: Initializing connection to go-librespot Websocket Oct 24 04:20:47 volumio volumio[13536]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 24 04:20:50 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1199. Oct 24 04:20:50 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 24 04:20:50 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 24 04:20:50 volumio go-librespot[13925]: go-librespot daemon starting... Oct 24 04:20:50 volumio systemd[1]: Starting setdatetime-helper.service - Time Synchronization Helper Service... Oct 24 04:20:50 volumio go-librespot[13926]: time="2025-10-24T04:20:50+01:00" level=info msg="running go-librespot 0.4.0" Oct 24 04:20:50 volumio go-librespot[13926]: time="2025-10-24T04:20:50+01:00" level=debug msg="app state loaded" Oct 24 04:20:50 volumio go-librespot[13926]: time="2025-10-24T04:20:50+01:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 24 04:20:50 volumio volumio[13536]: info: Initializing connection to go-librespot Websocket Oct 24 04:20:50 volumio go-librespot[13926]: time="2025-10-24T04:20: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 24 04:20:50 volumio go-librespot[13926]: time="2025-10-24T04:20: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 24 04:20:50 volumio go-librespot[13926]: time="2025-10-24T04:20: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 24 04:20:50 volumio go-librespot[13926]: time="2025-10-24T04:20:50+01:00" level=debug msg="new websocket client" Oct 24 04:20:50 volumio volumio[13536]: info: Connection to go-librespot Websocket established Oct 24 04:20:50 volumio go-librespot[13926]: time="2025-10-24T04:20:50+01:00" level=info msg="zeroconf server listening on port 45599" Oct 24 04:20:50 volumio go-librespot[13926]: time="2025-10-24T04:20:50+01:00" level=debug msg="obtained new client token: AACC1vhPzNGB623aufKXrvzSxRuFkTD0FTFPVK01laQecnD2Al2fSXbC0qHN4q0izTiAZHvDav1/xr4yCf0z10HFkyUVpzY0SL/e8kFyf95kHkb23+jCAz+3WSLEEHPO/vR0VQHCRdvbajbBumrYePWVw56Xkj5Mv3oTH7OQa5EsffqLBbz1UtRLuKP28XPKGzP5dNHPPIeZfD8SxOaY0N8GWNzu8P1o2Zz7veq2RjXhWRYWKGuo/Zk=" Oct 24 04:20:50 volumio go-librespot[13926]: time="2025-10-24T04:20:50+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 24 04:20:50 volumio go-librespot[13926]: time="2025-10-24T04:20:50+01:00" level=debug msg="completed keyexchange" Oct 24 04:20:50 volumio go-librespot[13926]: time="2025-10-24T04:20:50+01:00" level=debug msg="completed challenge" Oct 24 04:20:50 volumio go-librespot[13926]: time="2025-10-24T04:20: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 24 04:20:50 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 24 04:20:50 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 24 04:20:50 volumio volumio[13536]: info: Connection to go-librespot Websocket closed Oct 24 04:20:50 volumio systemd[1]: setdatetime-helper.service: Deactivated successfully. Oct 24 04:20:50 volumio systemd[1]: Finished setdatetime-helper.service - Time Synchronization Helper Service. Oct 24 04:20:53 volumio volumio[13536]: info: Getting Spotify volume Oct 24 04:20:53 volumio volumio[13536]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 24 04:20:53 volumio volumio[13536]: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 24 04:20:53 volumio volumio[13536]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Oct 24 04:20:53 volumio volumio[13536]: errno: -111, Oct 24 04:20:53 volumio volumio[13536]: code: 'ECONNREFUSED', Oct 24 04:20:53 volumio volumio[13536]: syscall: 'connect', Oct 24 04:20:53 volumio volumio[13536]: address: '127.0.0.1', Oct 24 04:20:53 volumio volumio[13536]: port: 9879, Oct 24 04:20:53 volumio volumio[13536]: response: undefined Oct 24 04:20:53 volumio volumio[13536]: } Oct 24 04:20:53 volumio volumio[13536]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 24 04:20:53 volumio sudo[13975]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-10-24 04:19' Oct 24 04:20:53 volumio sudo[13975]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 24 04:20:53 volumio sudo[13975]: pam_unix(sudo:session): session closed for user root Oct 24 04:20:53 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1200. Oct 24 04:20:53 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 24 04:20:53 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 24 04:20:53 volumio go-librespot[13980]: go-librespot daemon starting... Oct 24 04:20:53 volumio volumio-remote-updater[896]: [2025-10-24 03:20:53] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Oct 24 04:20:53 volumio volumio-remote-updater[896]: [2025-10-24 03:20:53] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Oct 24 04:20:53 volumio systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Oct 24 04:20:53 volumio go-librespot[13981]: time="2025-10-24T04:20:53+01:00" level=info msg="running go-librespot 0.4.0" Oct 24 04:20:53 volumio go-librespot[13981]: time="2025-10-24T04:20:53+01:00" level=debug msg="app state loaded" Oct 24 04:20:53 volumio go-librespot[13981]: time="2025-10-24T04:20:53+01:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 24 04:20:53 volumio systemd[1]: volumio.service: Failed with result 'exit-code'. Oct 24 04:20:53 volumio systemd[1]: volumio.service: Consumed 11.426s CPU time. Oct 24 04:20:53 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Oct 24 04:20:53 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Oct 24 04:20:54 volumio go-librespot[13981]: time="2025-10-24T04:20:54+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 24 04:20:54 volumio go-librespot[13981]: time="2025-10-24T04:20:54+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 24 04:20:54 volumio go-librespot[13981]: time="2025-10-24T04:20:54+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 24 04:20:54 volumio go-librespot[13981]: time="2025-10-24T04:20:54+01:00" level=info msg="zeroconf server listening on port 34193" Oct 24 04:20:54 volumio go-librespot[13981]: time="2025-10-24T04:20:54+01:00" level=debug msg="obtained new client token: AADiNBy9XRgOhPFLzMDU5vyfH35vEyq2GVr7A7tlg5Sc9JTubjYQ6WJZ9x7ja5qNidkNTgC6sGgU3ZbxfUDHwZggD7SV8Nr3E0P914J/724Akq9dKLOC2H/FhCz8UhIy4jYKSqlScEIyiKOQLMsRKtYIjY1kAf4nnNIuI4uUJhtKUcaL6DzhVHe5TQ3U0JnvFcM1QPIXn/ooVglNvlvPGKnbdFwdP+Ejrs4zqhfxn0EAQ9tVJzeg" Oct 24 04:20:54 volumio go-librespot[13981]: time="2025-10-24T04:20:54+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 24 04:20:54 volumio go-librespot[13981]: time="2025-10-24T04:20:54+01:00" level=debug msg="completed keyexchange" Oct 24 04:20:54 volumio go-librespot[13981]: time="2025-10-24T04:20:54+01:00" level=debug msg="completed challenge" Oct 24 04:20:54 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 4097. Oct 24 04:20:54 volumio go-librespot[13981]: time="2025-10-24T04:20:54+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 24 04:20:54 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Oct 24 04:20:54 volumio systemd[1]: Stopped volumio.service - Volumio Backend Module. Oct 24 04:20:54 volumio systemd[1]: volumio.service: Consumed 11.426s CPU time. Oct 24 04:20:54 volumio systemd[1]: Started volumio.service - Volumio Backend Module. Oct 24 04:20:54 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 24 04:20:54 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 24 04:20:54 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Oct 24 04:20:54 volumio volumio[13998]: info: ------------------------------------------- Oct 24 04:20:54 volumio volumio[13998]: info: ----- Volumio3 ---- Oct 24 04:20:54 volumio volumio[13998]: info: ------------------------------------------- Oct 24 04:20:54 volumio volumio[13998]: info: ----- System startup ---- Oct 24 04:20:54 volumio volumio[13998]: info: ------------------------------------------- Oct 24 04:20:54 volumio volumio[13998]: info: MYVOLUMIO Environment detected Oct 24 04:20:54 volumio volumio[13998]: info: Plugin folders cleanup Oct 24 04:20:54 volumio volumio[13998]: info: Scanning into folder /volumio/app/plugins/ Oct 24 04:20:54 volumio volumio[13998]: info: Scanning category audio_interface Oct 24 04:20:54 volumio volumio[13998]: info: Scanning category miscellanea Oct 24 04:20:54 volumio volumio[13998]: info: Scanning category music_service Oct 24 04:20:54 volumio volumio[13998]: info: Scanning category plugins.json Oct 24 04:20:54 volumio volumio[13998]: info: Scanning category system_controller Oct 24 04:20:54 volumio volumio[13998]: info: Scanning category user_interface Oct 24 04:20:54 volumio volumio[13998]: info: Scanning into folder /data/plugins/ Oct 24 04:20:54 volumio volumio[13998]: info: Scanning category music_service Oct 24 04:20:54 volumio volumio[13998]: info: Scanning category user_interface Oct 24 04:20:54 volumio volumio[13998]: info: Plugin folders cleanup completed Oct 24 04:20:54 volumio volumio[13998]: info: ------------------------------------------- Oct 24 04:20:54 volumio volumio[13998]: info: ----- Core plugins startup ---- Oct 24 04:20:54 volumio volumio[13998]: info: ------------------------------------------- Oct 24 04:20:54 volumio volumio[13998]: info: Loading plugins from folder /volumio/app/plugins/ Oct 24 04:20:54 volumio volumio[13998]: info: Adding plugin upnp to MyMusic Plugins Oct 24 04:20:54 volumio volumio[13998]: info: Adding plugin airplay_emulation to MyMusic Plugins Oct 24 04:20:54 volumio volumio[13998]: info: Adding plugin upnp_browser to MyMusic Plugins Oct 24 04:20:55 volumio volumio[13998]: info: Loading plugins from folder /data/plugins/ Oct 24 04:20:55 volumio volumio[13998]: info: Loading plugin "system"... Oct 24 04:20:55 volumio volumio[13998]: info: Loading plugin "appearance"... Oct 24 04:20:55 volumio volumio[13998]: info: Loading plugin "network"... Oct 24 04:20:55 volumio volumio[13998]: info: Refreshing Cached IP Addresses Oct 24 04:20:55 volumio sudo[14026]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 24 04:20:55 volumio sudo[14026]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 24 04:20:55 volumio sudo[14028]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 24 04:20:55 volumio sudo[14028]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 24 04:20:55 volumio sudo[14026]: pam_unix(sudo:session): session closed for user root Oct 24 04:20:55 volumio sudo[14028]: pam_unix(sudo:session): session closed for user root Oct 24 04:20:55 volumio volumio[13998]: info: Loading plugin "services"... Oct 24 04:20:55 volumio volumio[13998]: info: Loading plugin "alsa_controller"... Oct 24 04:20:55 volumio sudo[14039]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Oct 24 04:20:55 volumio sudo[14039]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 24 04:20:55 volumio volumio[13998]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 24 04:20:55 volumio volumio[13998]: info: Loading plugin "wizard"... Oct 24 04:20:55 volumio volumio[13998]: info: Loading plugin "networkfs"... Oct 24 04:20:55 volumio volumio[13998]: info: Cannot mount NAS NAS at system boot, trial number 1 ,retrying in 5 seconds Oct 24 04:20:55 volumio volumio[13998]: info: Starting Udev Watcher for removable devices Oct 24 04:20:55 volumio volumio[13998]: info: Ignoring mount for partition: boot Oct 24 04:20:55 volumio volumio[13998]: info: Ignoring mount for partition: volumio Oct 24 04:20:55 volumio volumio[13998]: info: Ignoring mount for partition: volumio_data Oct 24 04:20:55 volumio volumio[13998]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 24 04:20:55 volumio volumio[13998]: info: Loading plugin "volumio_command_line_client"... Oct 24 04:20:55 volumio volumio[13998]: info: Loading plugin "upnp"... Oct 24 04:20:55 volumio volumio[13998]: info: [1761276055365] Starting Upmpd Daemon Oct 24 04:20:55 volumio volumio[13998]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 24 04:20:55 volumio volumio[13998]: info: Loading plugin "my_music"... Oct 24 04:20:55 volumio volumio[13998]: info: Loading plugin "mpd"... Oct 24 04:20:55 volumio volumio[13998]: info: Loading plugin "upnp_browser"... Oct 24 04:20:55 volumio volumio[13998]: info: Loading plugin "alarm-clock"... Oct 24 04:20:55 volumio volumio[13998]: info: Loading plugin "airplay_emulation"... Oct 24 04:20:55 volumio volumio[13998]: info: Starting Shairport Sync Oct 24 04:20:55 volumio volumio[13998]: info: Loading plugin "last_100"... Oct 24 04:20:55 volumio volumio[13998]: info: Loading plugin "webradio"... Oct 24 04:20:55 volumio volumio[13998]: info: Loading plugin "i2s_dacs"... Oct 24 04:20:55 volumio volumio[13998]: info: I2S DAC not set, start Auto-detection Oct 24 04:20:55 volumio volumio[13998]: info: Loading plugin "volumiodiscovery"... Oct 24 04:20:56 volumio volumio[13998]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Oct 24 04:20:56 volumio volumio[13998]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 24 04:20:56 volumio volumio[13998]: *** WARNING *** For more information see Oct 24 04:20:56 volumio volumio[13998]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Oct 24 04:20:56 volumio volumio[13998]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 24 04:20:56 volumio node[13998]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Oct 24 04:20:56 volumio volumio[13998]: *** WARNING *** For more information see Oct 24 04:20:56 volumio node[13998]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 24 04:20:56 volumio node[13998]: *** WARNING *** For more information see Oct 24 04:20:56 volumio node[13998]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Oct 24 04:20:56 volumio node[13998]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 24 04:20:56 volumio node[13998]: *** WARNING *** For more information see Oct 24 04:20:56 volumio volumio[13998]: info: Applying required configuration parameters for plugin volumiodiscovery Oct 24 04:20:56 volumio volumio[13998]: info: Discovery: Started advertising with name: Volumio Oct 24 04:20:56 volumio volumio[13998]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 24 04:20:56 volumio volumio[13998]: info: Loading plugin "spop"... Oct 24 04:20:56 volumio volumio[13998]: info: Loading plugin "ytcr"... Oct 24 04:20:57 volumio volumio[13998]: info: Loading plugin "outputs"... Oct 24 04:20:57 volumio volumio[13998]: info: Loading plugin "albumart"... Oct 24 04:20:57 volumio volumio[13998]: info: Plugin example_plugin is not enabled Oct 24 04:20:57 volumio volumio[13998]: info: Loading plugin "inputs"... Oct 24 04:20:57 volumio volumio[13998]: info: Loading plugin "updater_comm"... Oct 24 04:20:57 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1201. Oct 24 04:20:57 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 24 04:20:57 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 24 04:20:57 volumio go-librespot[14070]: go-librespot daemon starting... Oct 24 04:20:57 volumio volumio[13998]: info: Plugin mpdemulation is not enabled Oct 24 04:20:57 volumio volumio[13998]: info: Loading plugin "rest_api"... Oct 24 04:20:57 volumio volumio[13998]: info: Loading plugin "websocket"... Oct 24 04:20:57 volumio go-librespot[14071]: time="2025-10-24T04:20:57+01:00" level=info msg="running go-librespot 0.4.0" Oct 24 04:20:57 volumio go-librespot[14071]: time="2025-10-24T04:20:57+01:00" level=debug msg="app state loaded" Oct 24 04:20:57 volumio go-librespot[14071]: time="2025-10-24T04:20:57+01:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 24 04:20:57 volumio volumio[13998]: info: Starting Socket.io Server version 1.7.4 Oct 24 04:20:57 volumio volumio[13998]: info: Loading plugin "Systeminfo"... Oct 24 04:20:57 volumio go-librespot[14071]: time="2025-10-24T04:20: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-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Oct 24 04:20:57 volumio go-librespot[14071]: time="2025-10-24T04:20:57+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 24 04:20:57 volumio go-librespot[14071]: time="2025-10-24T04:20:57+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 24 04:20:57 volumio go-librespot[14071]: time="2025-10-24T04:20:57+01:00" level=info msg="zeroconf server listening on port 38113" Oct 24 04:20:57 volumio volumio[14061]: Forking 3 albumart workers Oct 24 04:20:57 volumio volumio[13998]: info: Loading i18n strings for locale en Oct 24 04:20:57 volumio volumio[13998]: Updating browse sources language Oct 24 04:20:57 volumio volumio[13998]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 24 04:20:57 volumio go-librespot[14071]: time="2025-10-24T04:20:57+01:00" level=debug msg="obtained new client token: AABcE0iGCyhjyC7zZP4mzwn1Uno7Sv3a0OWj30DyoIbKKSxfUShKjEQutqs4mD0bGOx2QBb8bmv9a/24o9buQ+DV/TlxCwyb5j3qOyoSiQ1aMB6WyDYURA/HJHhdkTZPj7NGK8+yn0LHQdyV6yJBTaRMMYg4UkmLK0oIx7T9LJmEPUwrw1xGRcyYm1jml77kVMwbZ84kzyRTM/zypvdtWUEYvdh/6AxM2+BoJ2YBZlKS8LwkKfVsOII=" Oct 24 04:20:57 volumio volumio[13998]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 24 04:20:57 volumio volumio[13998]: info: CoreCommandRouter::initPlayerControls Oct 24 04:20:57 volumio volumio[13998]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:20:57 volumio volumio[13998]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:20:57 volumio volumio[13998]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:20:57 volumio volumio[13998]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:20:57 volumio volumio[13998]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:20:57 volumio volumio[13998]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:20:57 volumio volumio[13998]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:20:57 volumio volumio[13998]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:20:57 volumio volumio[13998]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 24 04:20:57 volumio volumio[13998]: Express server listening on port 3000 Oct 24 04:20:57 volumio volumio[13998]: [Metrics] WebUI: 3s 34.70ms Oct 24 04:20:57 volumio volumio[13998]: info: CoreStateMachine::resetVolumioState Oct 24 04:20:57 volumio volumio[13998]: info: CoreStateMachine::getcurrentVolume Oct 24 04:20:57 volumio volumio[13998]: info: CoreCommandRouter::volumioRetrievevolume Oct 24 04:20:57 volumio go-librespot[14071]: time="2025-10-24T04:20:57+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 24 04:20:57 volumio volumio[13998]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 24 04:20:57 volumio volumio[13998]: info: Cannot read play queue from file Oct 24 04:20:57 volumio go-librespot[14071]: time="2025-10-24T04:20:57+01:00" level=debug msg="completed keyexchange" Oct 24 04:20:57 volumio go-librespot[14071]: time="2025-10-24T04:20:57+01:00" level=debug msg="completed challenge" Oct 24 04:20:57 volumio volumio[13998]: info: Volumio Network Manager: Network status updated: 1 Oct 24 04:20:57 volumio go-librespot[14071]: time="2025-10-24T04:20: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 24 04:20:57 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 24 04:20:57 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 24 04:20:57 volumio volumio[13998]: info: VolumeController:: Volume=51 Mute =false Oct 24 04:20:57 volumio volumio[13998]: info: CoreStateMachine::pushState Oct 24 04:20:57 volumio volumio[13998]: info: CorePlayQueue::getTrack 0 Oct 24 04:20:57 volumio volumio[13998]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 24 04:20:57 volumio volumio[13998]: info: CoreCommandRouter::volumioPushState Oct 24 04:20:57 volumio volumio[13998]: info: CoreStateMachine::updateTrackBlock Oct 24 04:20:57 volumio volumio[13998]: info: CorePlayQueue::getTrackBlock Oct 24 04:20:57 volumio volumio[13998]: info: CoreCommandRouter::volumioRetrievevolume Oct 24 04:20:57 volumio volumio[13998]: info: CoreStateMachine::setRepeat null single undefined Oct 24 04:20:57 volumio volumio[13998]: info: CoreStateMachine::pushState Oct 24 04:20:57 volumio volumio[13998]: info: CorePlayQueue::getTrack 0 Oct 24 04:20:57 volumio volumio[13998]: info: CoreCommandRouter::volumioPushState Oct 24 04:20:57 volumio volumio[13998]: info: CoreStateMachine::setRandom null Oct 24 04:20:57 volumio volumio[13998]: info: CoreStateMachine::pushState Oct 24 04:20:57 volumio volumio[13998]: info: CorePlayQueue::getTrack 0 Oct 24 04:20:57 volumio volumio[13998]: info: CoreCommandRouter::volumioPushState Oct 24 04:20:57 volumio volumio[13998]: info: Setting Device type: Raspberry PI Oct 24 04:20:57 volumio volumio[13998]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Oct 24 04:20:57 volumio volumio[13998]: info: USB Boot Capable - System SBC Revision found in cpuinfo: b04170 Oct 24 04:20:57 volumio volumio[13998]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Oct 24 04:20:57 volumio sudo[14039]: pam_unix(sudo:session): session closed for user root Oct 24 04:20:57 volumio volumio[13998]: info: Discovery: adding 70853f74-8210-4683-a3fa-e1217517bd40 Oct 24 04:20:57 volumio volumio[13998]: info: Discovery: Found device Volumio Oct 24 04:20:57 volumio volumio[13998]: info: CoreCommandRouter::volumioGetState Oct 24 04:20:57 volumio volumio[13998]: info: CorePlayQueue::getTrack 0 Oct 24 04:20:57 volumio volumio[13998]: info: VolumeController:: Volume=51 Mute =false Oct 24 04:20:57 volumio volumio[13998]: info: CoreStateMachine::pushState Oct 24 04:20:57 volumio volumio[13998]: info: CorePlayQueue::getTrack 0 Oct 24 04:20:57 volumio volumio[13998]: info: CoreCommandRouter::volumioPushState Oct 24 04:20:57 volumio volumio[13998]: info: Discovery: this is already registered, 70853f74-8210-4683-a3fa-e1217517bd40 Oct 24 04:20:57 volumio volumio[13998]: info: Discovery: Found device Volumio Oct 24 04:20:57 volumio volumio[13998]: info: CoreCommandRouter::volumioGetState Oct 24 04:20:57 volumio volumio[13998]: info: CorePlayQueue::getTrack 0 Oct 24 04:20:57 volumio volumio[13998]: info: Completed loading Core Plugins Oct 24 04:20:57 volumio volumio[13998]: info: Preparing to generate the ALSA configuration file Oct 24 04:20:57 volumio volumio[14079]: Starting albumart workers Oct 24 04:20:57 volumio volumio[13998]: info: Asound.conf file unchanged, so no further update is needed Oct 24 04:20:57 volumio volumio[13998]: info: Output device has changed, restarting MPD Oct 24 04:20:57 volumio volumio[13998]: info: Output device has changed, restarting Shairport Sync Oct 24 04:20:57 volumio volumio[13998]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:20:57 volumio volumio[13998]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 24 04:20:57 volumio sudo[14126]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 24 04:20:57 volumio sudo[14126]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 24 04:20:57 volumio sudo[14127]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 24 04:20:57 volumio sudo[14127]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 24 04:20:57 volumio sudo[14127]: pam_unix(sudo:session): session closed for user root Oct 24 04:20:57 volumio volumio[13998]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 24 04:20:57 volumio volumio[13998]: info: ___________ START PLUGINS ___________ Oct 24 04:20:58 volumio volumio[13998]: info: ControllerMpd::onStart: Initializing MPD Oct 24 04:20:58 volumio volumio[13998]: info: Creating MPD Configuration file Oct 24 04:20:58 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Oct 24 04:20:58 volumio volumio[13998]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 24 04:20:58 volumio volumio[13998]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 24 04:20:58 volumio volumio[13998]: info: [1761276058035] CoreMusicLibrary::Adding element Media Servers Oct 24 04:20:58 volumio volumio[13998]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 24 04:20:58 volumio volumio[13998]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:20:58 volumio volumio[13998]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 24 04:20:58 volumio systemd[1]: mpd.service: Deactivated successfully. Oct 24 04:20:58 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Oct 24 04:20:58 volumio sudo[14135]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 24 04:20:58 volumio sudo[14135]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 24 04:20:58 volumio systemd[1]: mpd.socket: Deactivated successfully. Oct 24 04:20:58 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Oct 24 04:20:58 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Oct 24 04:20:58 volumio sudo[14135]: pam_unix(sudo:session): session closed for user root Oct 24 04:20:58 volumio sudo[14137]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 24 04:20:58 volumio sudo[14137]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 24 04:20:58 volumio volumio[13998]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 24 04:20:58 volumio volumio[13998]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:20:58 volumio volumio[13998]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 24 04:20:58 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Oct 24 04:20:58 volumio volumio[13998]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 24 04:20:58 volumio volumio[13998]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 24 04:20:58 volumio volumio[13998]: info: [1761276058077] CoreMusicLibrary::Adding element Last_100 Oct 24 04:20:58 volumio volumio[13998]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 24 04:20:58 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Oct 24 04:20:58 volumio volumio[13998]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 24 04:20:58 volumio volumio[13998]: info: [1761276058081] CoreMusicLibrary::Adding element Webradio Oct 24 04:20:58 volumio volumio[13998]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 24 04:20:58 volumio volumio[13998]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 24 04:20:58 volumio systemd[1]: mpd.service: Deactivated successfully. Oct 24 04:20:58 volumio volumio[13998]: info: Initializing BBC Radios Oct 24 04:20:58 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Oct 24 04:20:58 volumio systemd[1]: mpd.socket: Deactivated successfully. Oct 24 04:20:58 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Oct 24 04:20:58 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Oct 24 04:20:58 volumio volumio[14080]: Starting albumart workers Oct 24 04:20:58 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Oct 24 04:20:58 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Oct 24 04:20:58 volumio volumio[13998]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 24 04:20:58 volumio volumio[13998]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 24 04:20:58 volumio volumio[14081]: Starting albumart workers Oct 24 04:20:58 volumio volumio[13998]: info: Creating Spotify config file Oct 24 04:20:58 volumio volumio[13998]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:20:58 volumio sudo[14156]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Oct 24 04:20:58 volumio sudo[14156]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Oct 24 04:20:58 volumio sudo[14156]: pam_unix(sudo:session): session closed for user root Oct 24 04:20:58 volumio volumio[13998]: info: Volumio Calling Home Oct 24 04:20:58 volumio volumio[13998]: info: MPD Permissions set Oct 24 04:20:58 volumio volumio[13998]: info: MPD Permissions set Oct 24 04:20:58 volumio volumio[13998]: info: Spotify config file written Oct 24 04:20:58 volumio sudo[14189]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Oct 24 04:20:58 volumio sudo[14189]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 24 04:20:58 volumio volumio[13998]: 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 24 04:20:58 volumio volumio[13998]: info: Volumio called home Oct 24 04:20:58 volumio volumio[13998]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:20:58 volumio volumio[13998]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:20:58 volumio volumio[13998]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:20:58 volumio volumio[13998]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:20:58 volumio volumio[13998]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:20:58 volumio volumio[13998]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:20:58 volumio volumio[13998]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:20:58 volumio volumio[13998]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:20:58 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 24 04:20:58 volumio volumio[13998]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 24 04:20:58 volumio volumio[13998]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:20:58 volumio volumio[13998]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:20:58 volumio volumio[13998]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:20:58 volumio volumio[13998]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:20:58 volumio volumio[13998]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:20:58 volumio volumio[13998]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:20:58 volumio volumio[13998]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:20:58 volumio volumio[13998]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:20:58 volumio volumio[13998]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:20:58 volumio volumio[13998]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 24 04:20:58 volumio volumio[13998]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:20:58 volumio volumio[13998]: info: No need to fix Spotify hosts Oct 24 04:20:58 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 24 04:20:58 volumio go-librespot[14193]: go-librespot daemon starting... Oct 24 04:20:58 volumio sudo[14189]: pam_unix(sudo:session): session closed for user root Oct 24 04:20:58 volumio go-librespot[14202]: time="2025-10-24T04:20:58+01:00" level=info msg="running go-librespot 0.4.0" Oct 24 04:20:58 volumio go-librespot[14202]: time="2025-10-24T04:20:58+01:00" level=debug msg="app state loaded" Oct 24 04:20:58 volumio go-librespot[14202]: time="2025-10-24T04:20:58+01:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 24 04:20:58 volumio volumio[13998]: info: Starting Shairport Sync Oct 24 04:20:58 volumio volumio[13998]: info: Starting Shairport Sync Oct 24 04:20:58 volumio volumio[13998]: info: Starting Shairport Sync Oct 24 04:20:58 volumio sudo[14210]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 24 04:20:58 volumio sudo[14210]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 24 04:20:58 volumio sudo[14212]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 24 04:20:58 volumio sudo[14212]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 24 04:20:58 volumio sudo[14215]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 24 04:20:58 volumio sudo[14215]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 24 04:20:58 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Oct 24 04:20:58 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Oct 24 04:20:58 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Oct 24 04:20:58 volumio systemd[1]: shairport-sync.service: Consumed 1.564s CPU time. Oct 24 04:20:58 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Oct 24 04:20:58 volumio kernel: nfs: server 192.168.1.3 not responding, timed out Oct 24 04:20:58 volumio sudo[14210]: pam_unix(sudo:session): session closed for user root Oct 24 04:20:58 volumio sudo[14215]: pam_unix(sudo:session): session closed for user root Oct 24 04:20:58 volumio go-librespot[14202]: time="2025-10-24T04:20:58+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 24 04:20:58 volumio go-librespot[14202]: time="2025-10-24T04:20:58+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 24 04:20:58 volumio go-librespot[14202]: time="2025-10-24T04:20:58+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 24 04:20:58 volumio go-librespot[14202]: time="2025-10-24T04:20:58+01:00" level=info msg="zeroconf server listening on port 43727" Oct 24 04:20:58 volumio sudo[14212]: pam_unix(sudo:session): session closed for user root Oct 24 04:20:58 volumio volumio[13998]: info: Shairport-Sync Started Oct 24 04:20:58 volumio volumio[13998]: Error adding Membership: Error: addMembership EINVAL Oct 24 04:20:58 volumio volumio[13998]: info: Shairport-Sync Started Oct 24 04:20:58 volumio volumio[13998]: info: Shairport-Sync Started Oct 24 04:20:58 volumio volumio[13998]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Oct 24 04:20:58 volumio volumio[13998]: SPOTIFY: BQD5y6Vzu45CbNaqQI1008ab1B5eWA25b3bNDv1cEYAIGraKfaelHTtt0Y04whHmJ0N4PVk5kC3Efl0kLkREJ5A5hzK7EwUA0wMDaa_AKJgCL_jNNoN3T5qAHpS3QIA-TOL-0vKRc6c1KrviqGBsZs_MwWfcaur0EexaAEPF6_xBHbxN8sIq9Y_QoDSn36wXaOT-VyRWLQKqGtPJT9vJoGSJrQhCVsRiwWd2NeXijTh5YphB_QhRdXs1QKprb5iysZSBE6L2q-Auz6Fpis-LkK_ZOEZ7EUk6d5FWgEk3EBnB6tr7yP8 Oct 24 04:20:58 volumio volumio[13998]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Oct 24 04:20:58 volumio volumio[13998]: info: New Spotify access token = BQD5y6Vzu45CbNaqQI1008ab1B5eWA25b3bNDv1cEYAIGraKfaelHTtt0Y04whHmJ0N4PVk5kC3Efl0kLkREJ5A5hzK7EwUA0wMDaa_AKJgCL_jNNoN3T5qAHpS3QIA-TOL-0vKRc6c1KrviqGBsZs_MwWfcaur0EexaAEPF6_xBHbxN8sIq9Y_QoDSn36wXaOT-VyRWLQKqGtPJT9vJoGSJrQhCVsRiwWd2NeXijTh5YphB_QhRdXs1QKprb5iysZSBE6L2q-Auz6Fpis-LkK_ZOEZ7EUk6d5FWgEk3EBnB6tr7yP8 Oct 24 04:20:58 volumio volumio[13998]: info: Spotify credentials grant success - running version from March 24, 2019 Oct 24 04:20:58 volumio go-librespot[14202]: time="2025-10-24T04:20:58+01:00" level=debug msg="obtained new client token: AAAT664s4STCw9UIBvXC0dJ6rMWJc924Xe9ScYGkhXYFPuGcvvoZ7ZwjS7s01btDj+QDiWNFuPMDGq47hP/HPy7kEGy3+3jO71krCpJ0dkJuiuc5CVSzR6F7KS176mNiKq2lbCK1xtUnLgNW9/3DbfNT4XhJmAvCUwWqE6/Tq6Fs6ROOzMo0uyeDN+D6vm4E9/eAHpxR5zuJrksHx68/vSXJDY+u3o5WKXUbjvjYBYQydR8W7eI/4PE=" Oct 24 04:20:58 volumio volumio[13998]: info: CoreCommandRouter::volumioGetState Oct 24 04:20:58 volumio volumio[13998]: info: CorePlayQueue::getTrack 0 Oct 24 04:20:58 volumio go-librespot[14202]: time="2025-10-24T04:20:58+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 24 04:20:58 volumio go-librespot[14202]: time="2025-10-24T04:20:58+01:00" level=debug msg="completed keyexchange" Oct 24 04:20:58 volumio go-librespot[14202]: time="2025-10-24T04:20:58+01:00" level=debug msg="completed challenge" Oct 24 04:20:58 volumio go-librespot[14202]: time="2025-10-24T04:20:58+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 24 04:20:58 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 24 04:20:58 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 24 04:20:58 volumio volumio[13998]: 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 24 04:20:58 volumio volumio[13998]: info: Spotify Successfully logged in Oct 24 04:20:58 volumio volumio[13998]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 24 04:20:58 volumio volumio[13998]: info: [1761276058840] CoreMusicLibrary::Adding element Spotify Oct 24 04:20:58 volumio volumio[13998]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 24 04:20:58 volumio volumio[13998]: Cannot find translation for source Spotify Oct 24 04:20:58 volumio volumio-remote-updater[896]: [2025-10-24 03:20:58] [connect] Successful connection Oct 24 04:20:58 volumio volumio-remote-updater[896]: [2025-10-24 03:20:58] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1761276058 101 Oct 24 04:20:58 volumio volumio[13998]: 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 24 04:20:58 volumio mpd[14166]: 2025-10-24T04:20:58 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Oct 24 04:20:58 volumio systemd[1]: Started mpd.service - Music Player Daemon. Oct 24 04:20:58 volumio sudo[14126]: pam_unix(sudo:session): session closed for user root Oct 24 04:20:58 volumio sudo[14137]: pam_unix(sudo:session): session closed for user root Oct 24 04:20:59 volumio volumio[13998]: error: MPD error: The expression evaluated to a falsy value: Oct 24 04:20:59 volumio volumio[13998]: assert.ok(self.idling) Oct 24 04:20:59 volumio volumio[13998]: error: The expression evaluated to a falsy value: Oct 24 04:20:59 volumio volumio[13998]: assert.ok(self.idling) Oct 24 04:20:59 volumio volumio[13998]: error: updateQueue error: null Oct 24 04:20:59 volumio volumio[13998]: info: MPD running with PID14166 Oct 24 04:20:59 volumio volumio[13998]: ,establishing connection Oct 24 04:20:59 volumio volumio[13998]: error: updateQueue error: null Oct 24 04:20:59 volumio volumio[13998]: info: [yt-cast-receiver] DIAL server listening on port 8098 Oct 24 04:20:59 volumio volumio[13998]: info: CoreCommandRouter::volumioRetrievevolume Oct 24 04:20:59 volumio volumio[13998]: info: VolumeController:: Volume=51 Mute =false Oct 24 04:20:59 volumio volumio[13998]: info: CoreCommandRouter::volumioGetState Oct 24 04:20:59 volumio volumio[13998]: info: CorePlayQueue::getTrack 0 Oct 24 04:20:59 volumio volumio[13998]: info: CoreStateMachine::pushState Oct 24 04:20:59 volumio volumio[13998]: info: CorePlayQueue::getTrack 0 Oct 24 04:20:59 volumio volumio[13998]: info: CoreCommandRouter::volumioPushState Oct 24 04:20:59 volumio volumio[13998]: info: Completed starting Core Plugins Oct 24 04:20:59 volumio volumio[13998]: info: ------------------------------------------- Oct 24 04:20:59 volumio volumio[13998]: info: ----- MyVolumio plugins startup ---- Oct 24 04:20:59 volumio volumio[13998]: info: ------------------------------------------- Oct 24 04:20:59 volumio volumio[13998]: info: [MyVolumio PluginManager] Fetching plans data.... Oct 24 04:21:00 volumio volumio[13998]: info: Cannot mount NAS NAS at system boot, trial number 2 ,retrying in 5 seconds Oct 24 04:21:01 volumio volumio[13998]: info: go-librespot daemon successfully initialized Oct 24 04:21:01 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1202. Oct 24 04:21:01 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 24 04:21:01 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 24 04:21:01 volumio go-librespot[14239]: go-librespot daemon starting... Oct 24 04:21:01 volumio go-librespot[14240]: time="2025-10-24T04:21:01+01:00" level=info msg="running go-librespot 0.4.0" Oct 24 04:21:01 volumio go-librespot[14240]: time="2025-10-24T04:21:01+01:00" level=debug msg="app state loaded" Oct 24 04:21:01 volumio go-librespot[14240]: time="2025-10-24T04:21:01+01:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 24 04:21:01 volumio sudo[14247]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Oct 24 04:21:01 volumio sudo[14247]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 24 04:21:01 volumio sudo[14249]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Oct 24 04:21:01 volumio sudo[14249]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 24 04:21:02 volumio systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Oct 24 04:21:02 volumio systemd[1]: mpd_monitor.service: Deactivated successfully. Oct 24 04:21:02 volumio systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Oct 24 04:21:02 volumio systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Oct 24 04:21:02 volumio sudo[14249]: pam_unix(sudo:session): session closed for user root Oct 24 04:21:02 volumio mpd_monitor.sh[14252]: MPD Monitor Service: Starting MPD Monitor Service Oct 24 04:21:02 volumio sudo[14247]: pam_unix(sudo:session): session closed for user root Oct 24 04:21:02 volumio volumio[13998]: info: Successfully started MPD Monitor Oct 24 04:21:02 volumio volumio[13998]: info: Successfully started MPD Monitor Oct 24 04:21:04 volumio volumio[13998]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Oct 24 04:21:04 volumio volumio[13998]: info: Initializing connection to go-librespot Websocket Oct 24 04:21:04 volumio go-librespot[14240]: time="2025-10-24T04:21:04+01:00" level=debug msg="new websocket client" Oct 24 04:21:04 volumio volumio[13998]: info: Connection to go-librespot Websocket established Oct 24 04:21:05 volumio volumio[13998]: info: Cannot mount NAS NAS at system boot, trial number 3 ,retrying in 5 seconds Oct 24 04:21:05 volumio sudo[14271]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 24 04:21:05 volumio sudo[14271]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 24 04:21:05 volumio sudo[14273]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 24 04:21:05 volumio sudo[14273]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 24 04:21:05 volumio sudo[14271]: pam_unix(sudo:session): session closed for user root Oct 24 04:21:05 volumio sudo[14273]: pam_unix(sudo:session): session closed for user root Oct 24 04:21:05 volumio sudo[14277]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Oct 24 04:21:05 volumio sudo[14277]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 24 04:21:05 volumio sudo[14277]: pam_unix(sudo:session): session closed for user root Oct 24 04:21:05 volumio volumio[13998]: info: Upmpdcli Daemon Started Oct 24 04:21:07 volumio volumio[13998]: info: Getting Spotify volume Oct 24 04:21:07 volumio volumio[13998]: 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 24 04:21:07 volumio volumio[13998]: info: CoreCommandRouter::volumioGetState Oct 24 04:21:07 volumio volumio[13998]: info: CorePlayQueue::getTrack 0 Oct 24 04:21:07 volumio volumio[13998]: SPOTIFY: RECEIVED VOLUMIO VOLUME 51 Oct 24 04:21:07 volumio volumio[13998]: SPOTIFY: SPOTIFY VOLUME undefined Oct 24 04:21:07 volumio volumio[13998]: SPOTIFY: VOLUMIO VOLUME 51 Oct 24 04:21:07 volumio volumio[13998]: info: Aligning Spotify Volume to Volumio Volume Oct 24 04:21:07 volumio volumio[13998]: info: CoreCommandRouter::volumioGetState Oct 24 04:21:07 volumio volumio[13998]: info: CorePlayQueue::getTrack 0 Oct 24 04:21:07 volumio volumio[13998]: info: Setting Spotify Volume from Volumio: 51 Oct 24 04:21:07 volumio volumio[13998]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Oct 24 04:21:07 volumio volumio[13998]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Oct 24 04:21:07 volumio volumio[13998]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Oct 24 04:21:07 volumio volumio[13998]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Oct 24 04:21:07 volumio volumio[13998]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Oct 24 04:21:07 volumio volumio[13998]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Oct 24 04:21:07 volumio volumio[13998]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Oct 24 04:21:07 volumio volumio[13998]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Oct 24 04:21:07 volumio volumio[13998]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Oct 24 04:21:07 volumio volumio[13998]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Oct 24 04:21:07 volumio volumio[13998]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Oct 24 04:21:07 volumio volumio[13998]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Oct 24 04:21:07 volumio volumio[13998]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Oct 24 04:21:07 volumio volumio[13998]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Oct 24 04:21:07 volumio volumio[13998]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Oct 24 04:21:07 volumio volumio[13998]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Oct 24 04:21:07 volumio volumio[13998]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Oct 24 04:21:07 volumio volumio[13998]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Oct 24 04:21:07 volumio volumio[13998]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Oct 24 04:21:07 volumio volumio[13998]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Oct 24 04:21:07 volumio volumio[13998]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Oct 24 04:21:07 volumio volumio[13998]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Oct 24 04:21:07 volumio volumio[13998]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Oct 24 04:21:07 volumio volumio[13998]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Oct 24 04:21:07 volumio volumio[13998]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Oct 24 04:21:07 volumio volumio[13998]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Oct 24 04:21:07 volumio volumio[13998]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Oct 24 04:21:07 volumio volumio[13998]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Oct 24 04:21:07 volumio volumio[13998]: info: Adding plugin bluetooth to MyMusic Plugins Oct 24 04:21:07 volumio volumio[13998]: info: Adding plugin multiroom to MyMusic Plugins Oct 24 04:21:07 volumio volumio[13998]: info: Adding plugin metavolumio to MyMusic Plugins Oct 24 04:21:07 volumio volumio[13998]: info: Adding plugin cd_controller to MyMusic Plugins Oct 24 04:21:07 volumio volumio[13998]: info: Adding plugin qobuzconnect to MyMusic Plugins Oct 24 04:21:07 volumio volumio[13998]: info: Adding plugin smart_inputs to MyMusic Plugins Oct 24 04:21:07 volumio volumio[13998]: info: Adding plugin tidalconnect to MyMusic Plugins Oct 24 04:21:07 volumio volumio[13998]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Oct 24 04:21:08 volumio go-librespot[14240]: time="2025-10-24T04:21:08+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 24 04:21:08 volumio go-librespot[14240]: time="2025-10-24T04:21:08+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 24 04:21:08 volumio go-librespot[14240]: time="2025-10-24T04:21:08+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 24 04:21:08 volumio go-librespot[14240]: time="2025-10-24T04:21:08+01:00" level=info msg="zeroconf server listening on port 35473" Oct 24 04:21:08 volumio go-librespot[14240]: time="2025-10-24T04:21:08+01:00" level=debug msg="obtained new client token: AAAeKSoviNkVyM4fee7z3hHvytc7MtJEwWTny5EKrPSg8febNzkCL0hjohYkxtP0Z2yf5GUGZBS3rG2BIAghpZwGVBzm/AVwi5/4OVaUEYJJ1yMgjTZUzrk8OtBv/7V7jsHa9M8ou2XghvIzOLCbQ4MRcS1xgtyOFETnmk9E5WLiZf4x9God0JfO4kvKibY7+Ym74DCv1x2BAqA9pDae3HHc6PScXVnxxeYEEE8Yag+um4jfmbcD" Oct 24 04:21:08 volumio go-librespot[14240]: time="2025-10-24T04:21:08+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 24 04:21:08 volumio go-librespot[14240]: time="2025-10-24T04:21:08+01:00" level=debug msg="completed keyexchange" Oct 24 04:21:08 volumio go-librespot[14240]: time="2025-10-24T04:21:08+01:00" level=debug msg="completed challenge" Oct 24 04:21:08 volumio go-librespot[14240]: time="2025-10-24T04:21: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 24 04:21:08 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 24 04:21:08 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 24 04:21:08 volumio volumio[13998]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Oct 24 04:21:08 volumio volumio[13998]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Oct 24 04:21:08 volumio volumio[13998]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 24 04:21:08 volumio volumio[13998]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 24 04:21:08 volumio volumio[13998]: info: Starting MyVolumio Remote Streaming Endpoints Oct 24 04:21:08 volumio volumio[13998]: info: MyVolumio login type: Token Oct 24 04:21:08 volumio volumio[13998]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Oct 24 04:21:08 volumio volumio[13998]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Oct 24 04:21:08 volumio volumio[13998]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Oct 24 04:21:08 volumio volumio[13998]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Oct 24 04:21:08 volumio volumio[13998]: info: Streaming services startup Oct 24 04:21:08 volumio volumio[13998]: info: Starting Streaming Daemon Oct 24 04:21:08 volumio sudo[14282]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Oct 24 04:21:08 volumio sudo[14282]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 24 04:21:08 volumio volumio[13998]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Oct 24 04:21:08 volumio sudo[14282]: pam_unix(sudo:session): session closed for user root Oct 24 04:21:08 volumio volumio[13998]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 24 04:21:08 volumio volumio[13998]: Error: socket hang up Oct 24 04:21:08 volumio volumio[13998]: at connResetException (node:internal/errors:720:14) Oct 24 04:21:08 volumio volumio[13998]: at Socket.socketOnEnd (node:_http_client:519:23) Oct 24 04:21:08 volumio volumio[13998]: at Socket.emit (node:events:526:35) Oct 24 04:21:08 volumio volumio[13998]: at endReadableNT (node:internal/streams/readable:1376:12) Oct 24 04:21:08 volumio volumio[13998]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { Oct 24 04:21:08 volumio volumio[13998]: code: 'ECONNRESET', Oct 24 04:21:08 volumio volumio[13998]: response: undefined Oct 24 04:21:08 volumio volumio[13998]: } Oct 24 04:21:08 volumio volumio[13998]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 24 04:21:08 volumio sudo[14302]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-10-24 04:20' Oct 24 04:21:08 volumio sudo[14302]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 24 04:21:08 volumio sudo[14302]: pam_unix(sudo:session): session closed for user root Oct 24 04:21:09 volumio volumio-remote-updater[896]: [2025-10-24 03:21:09] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Oct 24 04:21:09 volumio volumio-remote-updater[896]: [2025-10-24 03:21:09] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Oct 24 04:21:09 volumio systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Oct 24 04:21:09 volumio systemd[1]: volumio.service: Failed with result 'exit-code'. Oct 24 04:21:09 volumio systemd[1]: volumio.service: Consumed 10.009s CPU time. Oct 24 04:21:09 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Oct 24 04:21:09 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Oct 24 04:21:09 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 4098. Oct 24 04:21:09 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Oct 24 04:21:09 volumio systemd[1]: Stopped volumio.service - Volumio Backend Module. Oct 24 04:21:09 volumio systemd[1]: volumio.service: Consumed 10.009s CPU time. Oct 24 04:21:09 volumio systemd[1]: Started volumio.service - Volumio Backend Module. Oct 24 04:21:09 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Oct 24 04:21:09 volumio volumio[14321]: info: ------------------------------------------- Oct 24 04:21:09 volumio volumio[14321]: info: ----- Volumio3 ---- Oct 24 04:21:09 volumio volumio[14321]: info: ------------------------------------------- Oct 24 04:21:09 volumio volumio[14321]: info: ----- System startup ---- Oct 24 04:21:09 volumio volumio[14321]: info: ------------------------------------------- Oct 24 04:21:10 volumio volumio[14321]: info: MYVOLUMIO Environment detected Oct 24 04:21:10 volumio volumio[14321]: info: Plugin folders cleanup Oct 24 04:21:10 volumio volumio[14321]: info: Scanning into folder /volumio/app/plugins/ Oct 24 04:21:10 volumio volumio[14321]: info: Scanning category audio_interface Oct 24 04:21:10 volumio volumio[14321]: info: Scanning category miscellanea Oct 24 04:21:10 volumio volumio[14321]: info: Scanning category music_service Oct 24 04:21:10 volumio volumio[14321]: info: Scanning category plugins.json Oct 24 04:21:10 volumio volumio[14321]: info: Scanning category system_controller Oct 24 04:21:10 volumio volumio[14321]: info: Scanning category user_interface Oct 24 04:21:10 volumio volumio[14321]: info: Scanning into folder /data/plugins/ Oct 24 04:21:10 volumio volumio[14321]: info: Scanning category music_service Oct 24 04:21:10 volumio volumio[14321]: info: Scanning category user_interface Oct 24 04:21:10 volumio volumio[14321]: info: Plugin folders cleanup completed Oct 24 04:21:10 volumio volumio[14321]: info: ------------------------------------------- Oct 24 04:21:10 volumio volumio[14321]: info: ----- Core plugins startup ---- Oct 24 04:21:10 volumio volumio[14321]: info: ------------------------------------------- Oct 24 04:21:10 volumio volumio[14321]: info: Loading plugins from folder /volumio/app/plugins/ Oct 24 04:21:10 volumio volumio[14321]: info: Adding plugin upnp to MyMusic Plugins Oct 24 04:21:10 volumio volumio[14321]: info: Adding plugin airplay_emulation to MyMusic Plugins Oct 24 04:21:10 volumio volumio[14321]: info: Adding plugin upnp_browser to MyMusic Plugins Oct 24 04:21:10 volumio volumio[14321]: info: Loading plugins from folder /data/plugins/ Oct 24 04:21:10 volumio volumio[14321]: info: Loading plugin "system"... Oct 24 04:21:10 volumio volumio[14321]: info: Loading plugin "appearance"... Oct 24 04:21:10 volumio kernel: nfs: server 192.168.1.3 not responding, timed out Oct 24 04:21:10 volumio volumio[14321]: info: Loading plugin "network"... Oct 24 04:21:10 volumio volumio[14321]: info: Refreshing Cached IP Addresses Oct 24 04:21:10 volumio sudo[14349]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 24 04:21:10 volumio sudo[14349]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 24 04:21:10 volumio sudo[14351]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 24 04:21:10 volumio sudo[14351]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 24 04:21:10 volumio sudo[14349]: pam_unix(sudo:session): session closed for user root Oct 24 04:21:10 volumio volumio[14321]: info: Loading plugin "services"... Oct 24 04:21:10 volumio sudo[14351]: pam_unix(sudo:session): session closed for user root Oct 24 04:21:10 volumio volumio[14321]: info: Loading plugin "alsa_controller"... Oct 24 04:21:10 volumio sudo[14355]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Oct 24 04:21:10 volumio sudo[14355]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 24 04:21:10 volumio volumio[14321]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 24 04:21:10 volumio volumio[14321]: info: Loading plugin "wizard"... Oct 24 04:21:10 volumio volumio[14321]: info: Loading plugin "networkfs"... Oct 24 04:21:10 volumio volumio[14321]: info: Cannot mount NAS NAS at system boot, trial number 1 ,retrying in 5 seconds Oct 24 04:21:10 volumio volumio[14321]: info: Starting Udev Watcher for removable devices Oct 24 04:21:10 volumio volumio[14321]: info: Ignoring mount for partition: boot Oct 24 04:21:10 volumio volumio[14321]: info: Ignoring mount for partition: volumio Oct 24 04:21:10 volumio volumio[14321]: info: Ignoring mount for partition: volumio_data Oct 24 04:21:10 volumio volumio[14321]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 24 04:21:10 volumio volumio[14321]: info: Loading plugin "volumio_command_line_client"... Oct 24 04:21:10 volumio volumio[14321]: info: Loading plugin "upnp"... Oct 24 04:21:10 volumio volumio[14321]: info: [1761276070618] Starting Upmpd Daemon Oct 24 04:21:10 volumio volumio[14321]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 24 04:21:10 volumio volumio[14321]: info: Loading plugin "my_music"... Oct 24 04:21:10 volumio volumio[14321]: info: Loading plugin "mpd"... Oct 24 04:21:10 volumio volumio[14321]: info: Loading plugin "upnp_browser"... Oct 24 04:21:11 volumio volumio[14321]: info: Loading plugin "alarm-clock"... Oct 24 04:21:11 volumio volumio[14321]: info: Loading plugin "airplay_emulation"... Oct 24 04:21:11 volumio volumio[14321]: info: Starting Shairport Sync Oct 24 04:21:11 volumio volumio[14321]: info: Loading plugin "last_100"... Oct 24 04:21:11 volumio volumio[14321]: info: Loading plugin "webradio"... Oct 24 04:21:11 volumio volumio[14321]: info: Loading plugin "i2s_dacs"... Oct 24 04:21:11 volumio volumio[14321]: info: I2S DAC not set, start Auto-detection Oct 24 04:21:11 volumio volumio[14321]: info: Loading plugin "volumiodiscovery"... Oct 24 04:21:11 volumio volumio[14321]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Oct 24 04:21:11 volumio volumio[14321]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 24 04:21:11 volumio volumio[14321]: *** WARNING *** For more information see Oct 24 04:21:11 volumio volumio[14321]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Oct 24 04:21:11 volumio volumio[14321]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 24 04:21:11 volumio volumio[14321]: *** WARNING *** For more information see Oct 24 04:21:11 volumio node[14321]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Oct 24 04:21:11 volumio node[14321]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 24 04:21:11 volumio node[14321]: *** WARNING *** For more information see Oct 24 04:21:11 volumio node[14321]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Oct 24 04:21:11 volumio node[14321]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 24 04:21:11 volumio node[14321]: *** WARNING *** For more information see Oct 24 04:21:11 volumio volumio[14321]: info: Applying required configuration parameters for plugin volumiodiscovery Oct 24 04:21:11 volumio volumio[14321]: info: Discovery: Started advertising with name: Volumio Oct 24 04:21:11 volumio volumio[14321]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 24 04:21:11 volumio volumio[14321]: info: Loading plugin "spop"... Oct 24 04:21:11 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1203. Oct 24 04:21:11 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 24 04:21:11 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 24 04:21:11 volumio go-librespot[14384]: go-librespot daemon starting... Oct 24 04:21:11 volumio go-librespot[14385]: time="2025-10-24T04:21:11+01:00" level=info msg="running go-librespot 0.4.0" Oct 24 04:21:11 volumio go-librespot[14385]: time="2025-10-24T04:21:11+01:00" level=debug msg="app state loaded" Oct 24 04:21:11 volumio go-librespot[14385]: time="2025-10-24T04:21:11+01:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 24 04:21:11 volumio volumio[14321]: info: Loading plugin "ytcr"... Oct 24 04:21:11 volumio go-librespot[14385]: time="2025-10-24T04:21: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-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Oct 24 04:21:11 volumio go-librespot[14385]: time="2025-10-24T04:21:11+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 24 04:21:11 volumio go-librespot[14385]: time="2025-10-24T04:21:11+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 24 04:21:11 volumio go-librespot[14385]: time="2025-10-24T04:21:11+01:00" level=info msg="zeroconf server listening on port 42219" Oct 24 04:21:11 volumio go-librespot[14385]: time="2025-10-24T04:21:11+01:00" level=debug msg="obtained new client token: AADMfp0DoNptpm1ZrJ2YpCvgbZnzDP3b+QCkn6WhZfZC91Md5NBtoe0NF0VOJcma2OR/dQF/WNYIGO9/zJ/3XxOrhSm48NpCTpxlLxcmQqGweRjRvPIabumNoEZeely1fc/DmSVDTZV5k6GxkejWYiuEuhEcnt3z8bQw64lfnPsFBjtc1Ir6icUz58d6wesOCus/1m000HoEPKnvNttzsZ4ZdOF6/o/E6GZLX9eoc4sKcWbW4Z5L1Ns=" Oct 24 04:21:11 volumio go-librespot[14385]: time="2025-10-24T04:21:11+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 24 04:21:11 volumio go-librespot[14385]: time="2025-10-24T04:21:11+01:00" level=debug msg="completed keyexchange" Oct 24 04:21:11 volumio go-librespot[14385]: time="2025-10-24T04:21:11+01:00" level=debug msg="completed challenge" Oct 24 04:21:11 volumio go-librespot[14385]: time="2025-10-24T04:21: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 24 04:21:11 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 24 04:21:11 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 24 04:21:12 volumio volumio[14321]: info: Loading plugin "outputs"... Oct 24 04:21:12 volumio volumio[14321]: info: Loading plugin "albumart"... Oct 24 04:21:12 volumio volumio[14321]: info: Plugin example_plugin is not enabled Oct 24 04:21:12 volumio volumio[14321]: info: Loading plugin "inputs"... Oct 24 04:21:12 volumio volumio[14321]: info: Loading plugin "updater_comm"... Oct 24 04:21:12 volumio volumio[14321]: info: Plugin mpdemulation is not enabled Oct 24 04:21:12 volumio volumio[14321]: info: Loading plugin "rest_api"... Oct 24 04:21:12 volumio volumio[14321]: info: Loading plugin "websocket"... Oct 24 04:21:12 volumio volumio[14321]: info: Starting Socket.io Server version 1.7.4 Oct 24 04:21:12 volumio volumio[14321]: info: Loading plugin "Systeminfo"... Oct 24 04:21:12 volumio volumio[14321]: info: Loading i18n strings for locale en Oct 24 04:21:12 volumio volumio[14321]: Updating browse sources language Oct 24 04:21:12 volumio volumio[14321]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 24 04:21:12 volumio volumio[14393]: Forking 3 albumart workers Oct 24 04:21:12 volumio volumio[14321]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 24 04:21:12 volumio volumio[14321]: info: CoreCommandRouter::initPlayerControls Oct 24 04:21:12 volumio volumio[14321]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:21:12 volumio volumio[14321]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:21:12 volumio volumio[14321]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:21:12 volumio volumio[14321]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:21:12 volumio volumio[14321]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:21:12 volumio volumio[14321]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:21:12 volumio volumio[14321]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:21:12 volumio volumio[14321]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:21:12 volumio volumio[14321]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 24 04:21:12 volumio volumio[14321]: Express server listening on port 3000 Oct 24 04:21:12 volumio volumio[14321]: [Metrics] WebUI: 3s 9.42ms Oct 24 04:21:12 volumio volumio[14321]: info: CoreStateMachine::resetVolumioState Oct 24 04:21:12 volumio volumio[14321]: info: CoreStateMachine::getcurrentVolume Oct 24 04:21:12 volumio volumio[14321]: info: CoreCommandRouter::volumioRetrievevolume Oct 24 04:21:12 volumio volumio[14321]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 24 04:21:12 volumio volumio[14321]: info: Cannot read play queue from file Oct 24 04:21:12 volumio volumio[14321]: info: Volumio Network Manager: Network status updated: 1 Oct 24 04:21:12 volumio volumio[14321]: info: VolumeController:: Volume=51 Mute =false Oct 24 04:21:12 volumio volumio[14321]: info: CoreStateMachine::pushState Oct 24 04:21:12 volumio volumio[14321]: info: CorePlayQueue::getTrack 0 Oct 24 04:21:12 volumio volumio[14321]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 24 04:21:12 volumio volumio[14321]: info: CoreCommandRouter::volumioPushState Oct 24 04:21:12 volumio volumio[14321]: info: CoreStateMachine::updateTrackBlock Oct 24 04:21:12 volumio volumio[14321]: info: CorePlayQueue::getTrackBlock Oct 24 04:21:12 volumio volumio[14321]: info: CoreCommandRouter::volumioRetrievevolume Oct 24 04:21:12 volumio volumio[14321]: info: CoreStateMachine::setRepeat null single undefined Oct 24 04:21:12 volumio volumio[14321]: info: CoreStateMachine::pushState Oct 24 04:21:12 volumio volumio[14321]: info: CorePlayQueue::getTrack 0 Oct 24 04:21:12 volumio volumio[14321]: info: CoreCommandRouter::volumioPushState Oct 24 04:21:12 volumio volumio[14321]: info: CoreStateMachine::setRandom null Oct 24 04:21:12 volumio volumio[14321]: info: CoreStateMachine::pushState Oct 24 04:21:12 volumio volumio[14321]: info: CorePlayQueue::getTrack 0 Oct 24 04:21:12 volumio volumio[14321]: info: CoreCommandRouter::volumioPushState Oct 24 04:21:13 volumio volumio[14321]: info: Setting Device type: Raspberry PI Oct 24 04:21:13 volumio volumio[14321]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Oct 24 04:21:13 volumio volumio[14321]: info: USB Boot Capable - System SBC Revision found in cpuinfo: b04170 Oct 24 04:21:13 volumio volumio[14321]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Oct 24 04:21:13 volumio volumio[14321]: info: VolumeController:: Volume=51 Mute =false Oct 24 04:21:13 volumio volumio[14321]: info: CoreStateMachine::pushState Oct 24 04:21:13 volumio volumio[14321]: info: CorePlayQueue::getTrack 0 Oct 24 04:21:13 volumio volumio[14321]: info: CoreCommandRouter::volumioPushState Oct 24 04:21:13 volumio volumio[14321]: info: Completed loading Core Plugins Oct 24 04:21:13 volumio volumio[14321]: info: Preparing to generate the ALSA configuration file Oct 24 04:21:13 volumio volumio[14321]: info: Discovery: adding 70853f74-8210-4683-a3fa-e1217517bd40 Oct 24 04:21:13 volumio volumio[14321]: info: Discovery: Found device Volumio Oct 24 04:21:13 volumio volumio[14321]: info: CoreCommandRouter::volumioGetState Oct 24 04:21:13 volumio volumio[14321]: info: CorePlayQueue::getTrack 0 Oct 24 04:21:13 volumio volumio[14321]: info: Discovery: this is already registered, 70853f74-8210-4683-a3fa-e1217517bd40 Oct 24 04:21:13 volumio volumio[14321]: info: Discovery: Found device Volumio Oct 24 04:21:13 volumio volumio[14321]: info: CoreCommandRouter::volumioGetState Oct 24 04:21:13 volumio volumio[14321]: info: CorePlayQueue::getTrack 0 Oct 24 04:21:13 volumio volumio[14321]: info: Asound.conf file unchanged, so no further update is needed Oct 24 04:21:13 volumio volumio[14321]: info: Output device has changed, restarting MPD Oct 24 04:21:13 volumio volumio[14321]: info: Output device has changed, restarting Shairport Sync Oct 24 04:21:13 volumio volumio[14321]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:21:13 volumio volumio[14321]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 24 04:21:13 volumio sudo[14449]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 24 04:21:13 volumio sudo[14449]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 24 04:21:13 volumio volumio[14321]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 24 04:21:13 volumio sudo[14449]: pam_unix(sudo:session): session closed for user root Oct 24 04:21:13 volumio volumio[14321]: info: ___________ START PLUGINS ___________ Oct 24 04:21:13 volumio sudo[14452]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 24 04:21:13 volumio sudo[14452]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 24 04:21:13 volumio volumio[14321]: info: ControllerMpd::onStart: Initializing MPD Oct 24 04:21:13 volumio volumio[14321]: info: Creating MPD Configuration file Oct 24 04:21:13 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Oct 24 04:21:13 volumio volumio[14321]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 24 04:21:13 volumio volumio[14321]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 24 04:21:13 volumio volumio[14321]: info: [1761276073150] CoreMusicLibrary::Adding element Media Servers Oct 24 04:21:13 volumio volumio[14321]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 24 04:21:13 volumio sudo[14355]: pam_unix(sudo:session): session closed for user root Oct 24 04:21:13 volumio volumio[14321]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:21:13 volumio volumio[14321]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 24 04:21:13 volumio sudo[14459]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 24 04:21:13 volumio sudo[14459]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 24 04:21:13 volumio sudo[14459]: pam_unix(sudo:session): session closed for user root Oct 24 04:21:13 volumio systemd[1]: mpd.service: Deactivated successfully. Oct 24 04:21:13 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Oct 24 04:21:13 volumio systemd[1]: mpd.socket: Deactivated successfully. Oct 24 04:21:13 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Oct 24 04:21:13 volumio sudo[14461]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 24 04:21:13 volumio sudo[14461]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 24 04:21:13 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Oct 24 04:21:13 volumio volumio[14321]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 24 04:21:13 volumio volumio[14321]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:21:13 volumio volumio[14321]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 24 04:21:13 volumio volumio[14321]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 24 04:21:13 volumio volumio[14321]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 24 04:21:13 volumio volumio[14321]: info: [1761276073200] CoreMusicLibrary::Adding element Last_100 Oct 24 04:21:13 volumio volumio[14321]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 24 04:21:13 volumio volumio[14321]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 24 04:21:13 volumio volumio[14321]: info: [1761276073202] CoreMusicLibrary::Adding element Webradio Oct 24 04:21:13 volumio volumio[14321]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 24 04:21:13 volumio volumio[14321]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 24 04:21:13 volumio volumio[14321]: info: Initializing BBC Radios Oct 24 04:21:13 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Oct 24 04:21:13 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Oct 24 04:21:13 volumio systemd[1]: mpd.service: Deactivated successfully. Oct 24 04:21:13 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Oct 24 04:21:13 volumio systemd[1]: mpd.socket: Deactivated successfully. Oct 24 04:21:13 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Oct 24 04:21:13 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Oct 24 04:21:13 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Oct 24 04:21:13 volumio volumio[14321]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 24 04:21:13 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Oct 24 04:21:13 volumio volumio[14321]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 24 04:21:13 volumio volumio[14321]: info: Creating Spotify config file Oct 24 04:21:13 volumio volumio[14321]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:21:13 volumio sudo[14488]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Oct 24 04:21:13 volumio sudo[14488]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Oct 24 04:21:13 volumio sudo[14488]: pam_unix(sudo:session): session closed for user root Oct 24 04:21:13 volumio volumio[14405]: Starting albumart workers Oct 24 04:21:13 volumio volumio[14404]: Starting albumart workers Oct 24 04:21:13 volumio volumio[14321]: info: Volumio Calling Home Oct 24 04:21:13 volumio volumio[14403]: Starting albumart workers Oct 24 04:21:13 volumio volumio[14321]: info: MPD Permissions set Oct 24 04:21:13 volumio volumio[14321]: info: MPD Permissions set Oct 24 04:21:13 volumio volumio[14321]: info: Volumio called home Oct 24 04:21:13 volumio volumio[14321]: info: Spotify config file written Oct 24 04:21:13 volumio sudo[14502]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Oct 24 04:21:13 volumio sudo[14502]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 24 04:21:13 volumio volumio[14321]: 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 24 04:21:13 volumio volumio[14321]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:21:13 volumio volumio[14321]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:21:13 volumio volumio[14321]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:21:13 volumio volumio[14321]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:21:13 volumio volumio[14321]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:21:13 volumio volumio[14321]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:21:13 volumio volumio[14321]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:21:13 volumio volumio[14321]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:21:13 volumio volumio[14321]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 24 04:21:13 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 24 04:21:13 volumio volumio[14321]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:21:13 volumio volumio[14321]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:21:13 volumio volumio[14321]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:21:13 volumio volumio[14321]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:21:13 volumio volumio[14321]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:21:13 volumio volumio[14321]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:21:13 volumio volumio[14321]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:21:13 volumio volumio[14321]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:21:13 volumio volumio[14321]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:21:13 volumio volumio[14321]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 24 04:21:13 volumio volumio[14321]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 04:21:13 volumio volumio[14321]: info: No need to fix Spotify hosts Oct 24 04:21:13 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 24 04:21:13 volumio go-librespot[14509]: go-librespot daemon starting... Oct 24 04:21:13 volumio sudo[14502]: pam_unix(sudo:session): session closed for user root Oct 24 04:21:13 volumio go-librespot[14521]: time="2025-10-24T04:21:13+01:00" level=info msg="running go-librespot 0.4.0" Oct 24 04:21:13 volumio go-librespot[14521]: time="2025-10-24T04:21:13+01:00" level=debug msg="app state loaded" Oct 24 04:21:13 volumio go-librespot[14521]: time="2025-10-24T04:21:13+01:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 24 04:21:13 volumio volumio[14321]: info: Starting Shairport Sync Oct 24 04:21:13 volumio volumio[14321]: info: Starting Shairport Sync Oct 24 04:21:13 volumio volumio[14321]: info: Starting Shairport Sync Oct 24 04:21:13 volumio sudo[14534]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 24 04:21:13 volumio sudo[14534]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 24 04:21:13 volumio sudo[14537]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 24 04:21:13 volumio sudo[14537]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 24 04:21:13 volumio sudo[14539]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 24 04:21:13 volumio sudo[14539]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 24 04:21:13 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Oct 24 04:21:13 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Oct 24 04:21:13 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Oct 24 04:21:13 volumio systemd[1]: shairport-sync.service: Consumed 1.552s CPU time. Oct 24 04:21:13 volumio go-librespot[14521]: time="2025-10-24T04:21:13+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 24 04:21:13 volumio go-librespot[14521]: time="2025-10-24T04:21:13+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 24 04:21:13 volumio go-librespot[14521]: time="2025-10-24T04:21:13+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 24 04:21:13 volumio go-librespot[14521]: time="2025-10-24T04:21:13+01:00" level=info msg="zeroconf server listening on port 43957" Oct 24 04:21:13 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Oct 24 04:21:13 volumio sudo[14534]: pam_unix(sudo:session): session closed for user root Oct 24 04:21:13 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Oct 24 04:21:13 volumio sudo[14537]: pam_unix(sudo:session): session closed for user root Oct 24 04:21:13 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Oct 24 04:21:13 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Oct 24 04:21:13 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Oct 24 04:21:13 volumio sudo[14539]: pam_unix(sudo:session): session closed for user root Oct 24 04:21:13 volumio volumio[14321]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Oct 24 04:21:13 volumio volumio[14321]: SPOTIFY: BQCJdNU7NqZ-udmQacSC_Xm3xqAZodpANSQXQJV8rBTPk1lCV0iPZ0g1iyHSIbSR9LBuhlyRMzHigXBFQpxB2HJYOQQ1gElDpdnYwHAw8-65Ogq1boAxipOybx1cPZEoGp3SyeYhAyShMsv6z3NmOTQQs2B5vft4tSYfsn3AoCoW8dhxXTUdjoz3CsF70MlSqi0RrzmJGOHaazBwGgcZlpFPRjjUd4BzPVzpLPyLWmsDkSVUb7V7dcUpjOHmCQmY16YCwigPwrKg1jM-lL_XVYD3AQQHBiArW-jtJMJobKbRBCl-n68 Oct 24 04:21:13 volumio volumio[14321]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Oct 24 04:21:13 volumio volumio[14321]: info: New Spotify access token = BQCJdNU7NqZ-udmQacSC_Xm3xqAZodpANSQXQJV8rBTPk1lCV0iPZ0g1iyHSIbSR9LBuhlyRMzHigXBFQpxB2HJYOQQ1gElDpdnYwHAw8-65Ogq1boAxipOybx1cPZEoGp3SyeYhAyShMsv6z3NmOTQQs2B5vft4tSYfsn3AoCoW8dhxXTUdjoz3CsF70MlSqi0RrzmJGOHaazBwGgcZlpFPRjjUd4BzPVzpLPyLWmsDkSVUb7V7dcUpjOHmCQmY16YCwigPwrKg1jM-lL_XVYD3AQQHBiArW-jtJMJobKbRBCl-n68 Oct 24 04:21:13 volumio volumio[14321]: info: Spotify credentials grant success - running version from March 24, 2019 Oct 24 04:21:13 volumio volumio[14321]: info: Shairport-Sync Started Oct 24 04:21:13 volumio go-librespot[14521]: time="2025-10-24T04:21:13+01:00" level=debug msg="obtained new client token: AABfL4OqjX8kEJxMfn12u4hIQy+cjpAZEarVMwWzCxDd73vwNlR2izxCWUAypl+pXqppPCZyqg16O2ltRtZoPcL3Vt7LCNblIjagJeTcSsW0hFxro05eUGsBBauan0c5hEleM0yC8sZceG/48foOQrPEqEVdsHqtKBIsCVdcQfCZbr3fpDCy8TSuvkAl48atouYe+rccXAcPJwVJJ38ktLqOvgtS7SMTi4DtlYhZhU/HYej/hQ4D1HE=" Oct 24 04:21:13 volumio volumio[14321]: Error adding Membership: Error: addMembership EINVAL Oct 24 04:21:13 volumio volumio[14321]: info: Shairport-Sync Started Oct 24 04:21:13 volumio volumio[14321]: info: Shairport-Sync Started Oct 24 04:21:14 volumio volumio[14321]: info: CoreCommandRouter::volumioGetState Oct 24 04:21:14 volumio volumio[14321]: info: CorePlayQueue::getTrack 0 Oct 24 04:21:14 volumio go-librespot[14521]: time="2025-10-24T04:21:14+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 24 04:21:14 volumio go-librespot[14521]: time="2025-10-24T04:21:14+01:00" level=debug msg="completed keyexchange" Oct 24 04:21:14 volumio go-librespot[14521]: time="2025-10-24T04:21:14+01:00" level=debug msg="completed challenge" Oct 24 04:21:14 volumio go-librespot[14521]: time="2025-10-24T04:21: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 24 04:21:14 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 24 04:21:14 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 24 04:21:14 volumio volumio-remote-updater[896]: [2025-10-24 03:21:14] [connect] Successful connection Oct 24 04:21:14 volumio volumio-remote-updater[896]: [2025-10-24 03:21:14] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1761276074 101 Oct 24 04:21:14 volumio volumio[14321]: 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 24 04:21:14 volumio volumio[14321]: 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 24 04:21:14 volumio volumio[14321]: info: Spotify Successfully logged in Oct 24 04:21:14 volumio volumio[14321]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 24 04:21:14 volumio volumio[14321]: info: [1761276074139] CoreMusicLibrary::Adding element Spotify Oct 24 04:21:14 volumio volumio[14321]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 24 04:21:14 volumio volumio[14321]: Cannot find translation for source Spotify Oct 24 04:21:14 volumio mpd[14490]: 2025-10-24T04:21:14 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Oct 24 04:21:14 volumio systemd[1]: Started mpd.service - Music Player Daemon. Oct 24 04:21:14 volumio sudo[14452]: pam_unix(sudo:session): session closed for user root Oct 24 04:21:14 volumio sudo[14461]: pam_unix(sudo:session): session closed for user root Oct 24 04:21:14 volumio volumio[14321]: error: MPD error: The expression evaluated to a falsy value: Oct 24 04:21:14 volumio volumio[14321]: assert.ok(self.idling) Oct 24 04:21:14 volumio volumio[14321]: error: The expression evaluated to a falsy value: Oct 24 04:21:14 volumio volumio[14321]: assert.ok(self.idling) Oct 24 04:21:14 volumio volumio[14321]: info: MPD running with PID14490 Oct 24 04:21:14 volumio volumio[14321]: ,establishing connection Oct 24 04:21:14 volumio volumio[14321]: error: updateQueue error: null Oct 24 04:21:14 volumio volumio[14321]: error: updateQueue error: null Oct 24 04:21:14 volumio volumio[14321]: info: [yt-cast-receiver] DIAL server listening on port 8098 Oct 24 04:21:14 volumio volumio[14321]: info: CoreCommandRouter::volumioRetrievevolume Oct 24 04:21:14 volumio volumio[14321]: info: VolumeController:: Volume=51 Mute =false Oct 24 04:21:14 volumio volumio[14321]: info: CoreCommandRouter::volumioGetState Oct 24 04:21:14 volumio volumio[14321]: info: CorePlayQueue::getTrack 0 Oct 24 04:21:14 volumio volumio[14321]: info: CoreStateMachine::pushState Oct 24 04:21:14 volumio volumio[14321]: info: CorePlayQueue::getTrack 0 Oct 24 04:21:14 volumio volumio[14321]: info: CoreCommandRouter::volumioPushState Oct 24 04:21:14 volumio volumio[14321]: info: Completed starting Core Plugins Oct 24 04:21:14 volumio volumio[14321]: info: ------------------------------------------- Oct 24 04:21:14 volumio volumio[14321]: info: ----- MyVolumio plugins startup ---- Oct 24 04:21:14 volumio volumio[14321]: info: ------------------------------------------- Oct 24 04:21:14 volumio volumio[14321]: info: [MyVolumio PluginManager] Fetching plans data.... Oct 24 04:21:15 volumio volumio[14321]: info: Cannot mount NAS NAS at system boot, trial number 2 ,retrying in 5 seconds Oct 24 04:21:16 volumio volumio[14321]: info: go-librespot daemon successfully initialized Oct 24 04:21:17 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1204. Oct 24 04:21:17 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 24 04:21:17 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 24 04:21:17 volumio go-librespot[14566]: go-librespot daemon starting... Oct 24 04:21:17 volumio go-librespot[14567]: time="2025-10-24T04:21:17+01:00" level=info msg="running go-librespot 0.4.0" Oct 24 04:21:17 volumio go-librespot[14567]: time="2025-10-24T04:21:17+01:00" level=debug msg="app state loaded" Oct 24 04:21:17 volumio go-librespot[14567]: time="2025-10-24T04:21:17+01:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 24 04:21:17 volumio sudo[14574]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Oct 24 04:21:17 volumio sudo[14574]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 24 04:21:17 volumio systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Oct 24 04:21:17 volumio sudo[14577]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Oct 24 04:21:17 volumio systemd[1]: mpd_monitor.service: Deactivated successfully. Oct 24 04:21:17 volumio sudo[14577]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 24 04:21:17 volumio systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Oct 24 04:21:17 volumio systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Oct 24 04:21:17 volumio sudo[14574]: pam_unix(sudo:session): session closed for user root Oct 24 04:21:17 volumio mpd_monitor.sh[14579]: MPD Monitor Service: Starting MPD Monitor Service Oct 24 04:21:17 volumio volumio[14321]: info: Successfully started MPD Monitor Oct 24 04:21:17 volumio systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Oct 24 04:21:17 volumio systemd[1]: mpd_monitor.service: Deactivated successfully. Oct 24 04:21:17 volumio systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Oct 24 04:21:17 volumio systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Oct 24 04:21:17 volumio sudo[14577]: pam_unix(sudo:session): session closed for user root Oct 24 04:21:17 volumio mpd_monitor.sh[14582]: MPD Monitor Service: Starting MPD Monitor Service Oct 24 04:21:17 volumio volumio[14321]: info: Successfully started MPD Monitor Oct 24 04:21:17 volumio go-librespot[14567]: time="2025-10-24T04:21:17+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 24 04:21:17 volumio go-librespot[14567]: time="2025-10-24T04:21:17+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 24 04:21:17 volumio go-librespot[14567]: time="2025-10-24T04:21:17+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 24 04:21:17 volumio go-librespot[14567]: time="2025-10-24T04:21:17+01:00" level=info msg="zeroconf server listening on port 35175" Oct 24 04:21:17 volumio go-librespot[14567]: time="2025-10-24T04:21:17+01:00" level=debug msg="obtained new client token: AABCBSmRiFFnuqMd9kyLo8qRth4Cbt3uXnsniJ/a7/cpI6SLOnU56zi2vOH3pylPKRkklN3kKimbgz6pv/nEfW3H7um/U409MGENfArAWPBuMu7LALplYGUvjaXfgMQ+Pjxwuznwc6+JKKJfoyHOdJRJl/1kl5CahEIsElV4xN6d2zdyS3sGSLM5hVSarObsIIcbUkfOaHLzd5gMW+2R5DewScN6+aXAsbzxAy/B+MEBb9ZARM+T/wg=" Oct 24 04:21:17 volumio go-librespot[14567]: time="2025-10-24T04:21:17+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 24 04:21:17 volumio go-librespot[14567]: time="2025-10-24T04:21:17+01:00" level=debug msg="completed keyexchange" Oct 24 04:21:17 volumio go-librespot[14567]: time="2025-10-24T04:21:17+01:00" level=debug msg="completed challenge" Oct 24 04:21:17 volumio go-librespot[14567]: time="2025-10-24T04:21:17+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 24 04:21:17 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 24 04:21:17 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 24 04:21:19 volumio volumio[14321]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Oct 24 04:21:19 volumio volumio[14321]: info: Initializing connection to go-librespot Websocket Oct 24 04:21:19 volumio volumio[14321]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 24 04:21:19 volumio kernel: nfs: server 192.168.1.3 not responding, timed out Oct 24 04:21:20 volumio volumio[14321]: info: Cannot mount NAS NAS at system boot, trial number 3 ,retrying in 5 seconds Oct 24 04:21:20 volumio sudo[14602]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 24 04:21:20 volumio sudo[14602]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 24 04:21:20 volumio sudo[14602]: pam_unix(sudo:session): session closed for user root Oct 24 04:21:20 volumio sudo[14604]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 24 04:21:20 volumio sudo[14604]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 24 04:21:20 volumio sudo[14604]: pam_unix(sudo:session): session closed for user root Oct 24 04:21:20 volumio sudo[14608]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Oct 24 04:21:20 volumio sudo[14608]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 24 04:21:20 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1205. Oct 24 04:21:20 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 24 04:21:20 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 24 04:21:20 volumio go-librespot[14610]: go-librespot daemon starting... Oct 24 04:21:20 volumio sudo[14608]: pam_unix(sudo:session): session closed for user root Oct 24 04:21:20 volumio volumio[14321]: info: Upmpdcli Daemon Started Oct 24 04:21:20 volumio go-librespot[14611]: time="2025-10-24T04:21:20+01:00" level=info msg="running go-librespot 0.4.0" Oct 24 04:21:20 volumio go-librespot[14611]: time="2025-10-24T04:21:20+01:00" level=debug msg="app state loaded" Oct 24 04:21:20 volumio go-librespot[14611]: time="2025-10-24T04:21:20+01:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 24 04:21:20 volumio go-librespot[14611]: time="2025-10-24T04:21:20+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 24 04:21:20 volumio go-librespot[14611]: time="2025-10-24T04:21:20+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 24 04:21:20 volumio go-librespot[14611]: time="2025-10-24T04:21:20+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 24 04:21:20 volumio go-librespot[14611]: time="2025-10-24T04:21:20+01:00" level=info msg="zeroconf server listening on port 38087" Oct 24 04:21:20 volumio go-librespot[14611]: time="2025-10-24T04:21:20+01:00" level=debug msg="obtained new client token: AAAXRAZQyo2jjgdzRDuW9tWu4NaSpfRjPGzat6FDasVYNJUFNZemGGVSSmVYpbVf8iUbzzyLEkf6eIr+37OHeAFUzbK7sstf3nncq9KGzY26izpqhRLROEtCjECIsuqFajr2Vp3IISN3Ar1acKlXSVs9cwmDl0IBTmqCySezSx8Gmjwja6E5j69tjExHAy2UZV3zbgfTdMFYvuHHMRHnWtqO/NIAlOUWQUlYy9zS0gRLPLQz+lOL3Fg=" Oct 24 04:21:20 volumio go-librespot[14611]: time="2025-10-24T04:21:20+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 24 04:21:20 volumio go-librespot[14611]: time="2025-10-24T04:21:20+01:00" level=debug msg="completed keyexchange" Oct 24 04:21:20 volumio go-librespot[14611]: time="2025-10-24T04:21:20+01:00" level=debug msg="completed challenge" Oct 24 04:21:20 volumio go-librespot[14611]: time="2025-10-24T04:21:20+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 24 04:21:20 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 24 04:21:20 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 24 04:21:22 volumio volumio[14321]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Oct 24 04:21:22 volumio volumio[14321]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Oct 24 04:21:22 volumio volumio[14321]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Oct 24 04:21:22 volumio volumio[14321]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Oct 24 04:21:22 volumio volumio[14321]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Oct 24 04:21:22 volumio volumio[14321]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Oct 24 04:21:22 volumio volumio[14321]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Oct 24 04:21:22 volumio volumio[14321]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Oct 24 04:21:22 volumio volumio[14321]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Oct 24 04:21:22 volumio volumio[14321]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Oct 24 04:21:22 volumio volumio[14321]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Oct 24 04:21:22 volumio volumio[14321]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Oct 24 04:21:22 volumio volumio[14321]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Oct 24 04:21:22 volumio volumio[14321]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Oct 24 04:21:22 volumio volumio[14321]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Oct 24 04:21:22 volumio volumio[14321]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Oct 24 04:21:22 volumio volumio[14321]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Oct 24 04:21:22 volumio volumio[14321]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Oct 24 04:21:22 volumio volumio[14321]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Oct 24 04:21:22 volumio volumio[14321]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Oct 24 04:21:22 volumio volumio[14321]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Oct 24 04:21:22 volumio volumio[14321]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Oct 24 04:21:22 volumio volumio[14321]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Oct 24 04:21:22 volumio volumio[14321]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Oct 24 04:21:22 volumio volumio[14321]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Oct 24 04:21:22 volumio volumio[14321]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Oct 24 04:21:22 volumio volumio[14321]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Oct 24 04:21:22 volumio volumio[14321]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Oct 24 04:21:22 volumio volumio[14321]: info: Adding plugin bluetooth to MyMusic Plugins Oct 24 04:21:22 volumio volumio[14321]: info: Adding plugin multiroom to MyMusic Plugins Oct 24 04:21:22 volumio volumio[14321]: info: Adding plugin metavolumio to MyMusic Plugins Oct 24 04:21:22 volumio volumio[14321]: info: Adding plugin cd_controller to MyMusic Plugins Oct 24 04:21:22 volumio volumio[14321]: info: Adding plugin qobuzconnect to MyMusic Plugins Oct 24 04:21:22 volumio volumio[14321]: info: Adding plugin smart_inputs to MyMusic Plugins Oct 24 04:21:22 volumio volumio[14321]: info: Adding plugin tidalconnect to MyMusic Plugins Oct 24 04:21:22 volumio volumio[14321]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Oct 24 04:21:22 volumio volumio[14321]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Oct 24 04:21:22 volumio volumio[14321]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Oct 24 04:21:22 volumio volumio[14321]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 24 04:21:22 volumio volumio[14321]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 24 04:21:23 volumio volumio[14321]: info: Starting MyVolumio Remote Streaming Endpoints Oct 24 04:21:23 volumio volumio[14321]: info: MyVolumio login type: Token Oct 24 04:21:23 volumio volumio[14321]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Oct 24 04:21:23 volumio volumio[14321]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Oct 24 04:21:23 volumio volumio[14321]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Oct 24 04:21:23 volumio volumio[14321]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Oct 24 04:21:23 volumio volumio[14321]: info: Streaming services startup Oct 24 04:21:23 volumio volumio[14321]: info: Starting Streaming Daemon Oct 24 04:21:23 volumio sudo[14619]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Oct 24 04:21:23 volumio sudo[14619]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 24 04:21:23 volumio volumio[14321]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Oct 24 04:21:23 volumio sudo[14619]: pam_unix(sudo:session): session closed for user root Oct 24 04:21:23 volumio volumio[14321]: info: Initializing connection to go-librespot Websocket Oct 24 04:21:23 volumio volumio[14321]: error: Cannot start Volumio Streaming Daemon Oct 24 04:21:23 volumio volumio[14321]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Oct 24 04:21:23 volumio volumio[14321]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Oct 24 04:21:23 volumio volumio[14321]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 24 04:21:23 volumio volumio[14321]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Oct 24 04:21:24 volumio volumio[14321]: info: MyVolumio token set successfully Oct 24 04:21:24 volumio volumio[14321]: info: MYVOLUMIO: Adding device Oct 24 04:21:24 volumio volumio[14321]: info: MYVOLUMIO: Evaluating Server Oct 24 04:21:24 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1206. Oct 24 04:21:24 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 24 04:21:24 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 24 04:21:24 volumio go-librespot[14627]: go-librespot daemon starting... Oct 24 04:21:24 volumio go-librespot[14628]: time="2025-10-24T04:21:24+01:00" level=info msg="running go-librespot 0.4.0" Oct 24 04:21:24 volumio go-librespot[14628]: time="2025-10-24T04:21:24+01:00" level=debug msg="app state loaded" Oct 24 04:21:24 volumio go-librespot[14628]: time="2025-10-24T04:21:24+01:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 24 04:21:24 volumio volumio[14321]: info: MyVolumio status changed Oct 24 04:21:24 volumio volumio[14321]: info: Streaming services startup Oct 24 04:21:24 volumio volumio[14321]: info: Starting Streaming Daemon Oct 24 04:21:24 volumio volumio[14321]: info: Removing browser output: myVolumio user plan is not superstar Oct 24 04:21:24 volumio volumio[14321]: info: Removing audio output: Oct 24 04:21:24 volumio volumio[14321]: info: Stoppping Tunnel 1 Oct 24 04:21:24 volumio sudo[14650]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Oct 24 04:21:24 volumio sudo[14650]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 24 04:21:24 volumio sudo[14653]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service Oct 24 04:21:24 volumio sudo[14653]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 24 04:21:24 volumio sudo[14650]: pam_unix(sudo:session): session closed for user root Oct 24 04:21:24 volumio volumio[14321]: error: Cannot start Volumio Streaming Daemon Oct 24 04:21:24 volumio volumio[14321]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Oct 24 04:21:24 volumio volumio[14321]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Oct 24 04:21:24 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 24 04:21:24 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 24 04:21:24 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 24 04:21:24 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 24 04:21:24 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 24 04:21:24 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 24 04:21:24 volumio sudo[14653]: pam_unix(sudo:session): session closed for user root Oct 24 04:21:24 volumio volumio[14321]: info: Remote SSH Stopped Oct 24 04:21:24 volumio go-librespot[14628]: time="2025-10-24T04:21:24+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 24 04:21:24 volumio go-librespot[14628]: time="2025-10-24T04:21:24+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 24 04:21:24 volumio go-librespot[14628]: time="2025-10-24T04:21:24+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 24 04:21:24 volumio go-librespot[14628]: time="2025-10-24T04:21:24+01:00" level=info msg="zeroconf server listening on port 40705" Oct 24 04:21:24 volumio go-librespot[14628]: time="2025-10-24T04:21:24+01:00" level=debug msg="obtained new client token: AADKC2ioi8BPgWt2WmT9GNNYQU490We/BlwpKBbr1UwPPQR+9a5E/zVVdEw0kjSYA2b979UHArTVzT8hnxopP9XzP8ys2PUH9ANx1j+CJEkxQUWpI1CERfslBPezS+5YTZChQEkdxkDxfpjGXkcCmb4oIO2iBSOiG3vqpjz1jTDWviA7WKegeHfX4rfFYLxG8u26RRWSr4Wjn/42Y03lEaAtMC+G56BFecRdigujvRjpPFJex+ajkZA=" Oct 24 04:21:24 volumio go-librespot[14628]: time="2025-10-24T04:21:24+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 24 04:21:24 volumio go-librespot[14628]: time="2025-10-24T04:21:24+01:00" level=debug msg="completed keyexchange" Oct 24 04:21:24 volumio go-librespot[14628]: time="2025-10-24T04:21:24+01:00" level=debug msg="completed challenge" Oct 24 04:21:24 volumio go-librespot[14628]: time="2025-10-24T04:21:24+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 24 04:21:24 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 24 04:21:24 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 24 04:21:24 volumio volumio[14321]: info: Setting Geolocation for MyVolumio to eu3 Oct 24 04:21:24 volumio volumio[14321]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 24 04:21:24 volumio volumio[14321]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 24 04:21:24 volumio volumio[14321]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 24 04:21:25 volumio volumio[14321]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Oct 24 04:21:25 volumio volumio[14321]: info: Updating MyVolumio device info Oct 24 04:21:25 volumio volumio[14321]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 24 04:21:25 volumio volumio[14321]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 24 04:21:25 volumio volumio[14321]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 24 04:21:25 volumio volumio[14321]: info: Cannot mount NAS NAS at system boot, trial number 4 ,retrying in 5 seconds Oct 24 04:21:25 volumio volumio[14321]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Oct 24 04:21:26 volumio volumio[14321]: info: Initializing connection to go-librespot Websocket Oct 24 04:21:26 volumio volumio[14321]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 24 04:21:27 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1207. Oct 24 04:21:27 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 24 04:21:27 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 24 04:21:27 volumio go-librespot[14657]: go-librespot daemon starting... Oct 24 04:21:27 volumio go-librespot[14658]: time="2025-10-24T04:21:27+01:00" level=info msg="running go-librespot 0.4.0" Oct 24 04:21:27 volumio go-librespot[14658]: time="2025-10-24T04:21:27+01:00" level=debug msg="app state loaded" Oct 24 04:21:27 volumio go-librespot[14658]: time="2025-10-24T04:21:27+01:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 24 04:21:27 volumio go-librespot[14658]: time="2025-10-24T04:21:27+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 24 04:21:27 volumio go-librespot[14658]: time="2025-10-24T04:21:27+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 24 04:21:27 volumio go-librespot[14658]: time="2025-10-24T04:21:27+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 24 04:21:27 volumio go-librespot[14658]: time="2025-10-24T04:21:27+01:00" level=info msg="zeroconf server listening on port 42433" Oct 24 04:21:27 volumio go-librespot[14658]: time="2025-10-24T04:21:27+01:00" level=debug msg="obtained new client token: AADYOKYLE/UuzFDBWnnaVmnxbg8D+XSEsP123RVpBluQW0dGNiGa/v2a1+CdYvbP/dJqYvq2M5cm1SLeE8oP0Ivr06n8b3Qyl0SGAzkkh0+5wAlWzo1PyYK8qnDrt1EYDUT5zGNR+IP5335ZJrIqd6HxXy0vu9xx3ASaLMdcTjG8KmWzx6u5VGUbamwRTYOPbYEWb5aJCAVdaJpU1wid8P6OMZoTiLCFOI6P2Zdg1fPKI3mt2Zuhc1A=" Oct 24 04:21:27 volumio go-librespot[14658]: time="2025-10-24T04:21:27+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 24 04:21:27 volumio go-librespot[14658]: time="2025-10-24T04:21:27+01:00" level=debug msg="completed keyexchange" Oct 24 04:21:27 volumio go-librespot[14658]: time="2025-10-24T04:21:27+01:00" level=debug msg="completed challenge" Oct 24 04:21:27 volumio go-librespot[14658]: time="2025-10-24T04:21:27+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 24 04:21:27 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 24 04:21:27 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 24 04:21:29 volumio volumio[14321]: info: Initializing connection to go-librespot Websocket Oct 24 04:21:29 volumio volumio[14321]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 24 04:21:29 volumio volumio[14321]: info: MYVOLUMIO: Adding device Oct 24 04:21:29 volumio volumio[14321]: info: MYVOLUMIO: Evaluating Server Oct 24 04:21:29 volumio volumio[14321]: info: Setting Geolocation for MyVolumio to eu3 Oct 24 04:21:29 volumio volumio[14321]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 24 04:21:29 volumio volumio[14321]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 24 04:21:29 volumio volumio[14321]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 24 04:21:30 volumio volumio[14321]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Oct 24 04:21:30 volumio volumio[14321]: info: Cannot mount NAS at system boot, trial number 4 ,stopping Oct 24 04:21:30 volumio kernel: nfs: server 192.168.1.3 not responding, timed out Oct 24 04:21:30 volumio volumio[14321]: info: Updating MyVolumio device info Oct 24 04:21:30 volumio volumio[14321]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 24 04:21:30 volumio volumio[14321]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 24 04:21:30 volumio volumio[14321]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 24 04:21:31 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1208. Oct 24 04:21:31 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 24 04:21:31 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 24 04:21:31 volumio go-librespot[14695]: go-librespot daemon starting... Oct 24 04:21:31 volumio volumio[14321]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Oct 24 04:21:31 volumio go-librespot[14696]: time="2025-10-24T04:21:31+01:00" level=info msg="running go-librespot 0.4.0" Oct 24 04:21:31 volumio go-librespot[14696]: time="2025-10-24T04:21:31+01:00" level=debug msg="app state loaded" Oct 24 04:21:31 volumio go-librespot[14696]: time="2025-10-24T04:21:31+01:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 24 04:21:31 volumio go-librespot[14696]: time="2025-10-24T04:21:31+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 24 04:21:31 volumio go-librespot[14696]: time="2025-10-24T04:21:31+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 24 04:21:31 volumio go-librespot[14696]: time="2025-10-24T04:21:31+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 24 04:21:31 volumio go-librespot[14696]: time="2025-10-24T04:21:31+01:00" level=info msg="zeroconf server listening on port 37601" Oct 24 04:21:31 volumio go-librespot[14696]: time="2025-10-24T04:21:31+01:00" level=debug msg="obtained new client token: AACioV/hNpGA4kIl1bBms3TYo4L21NamDCSjZ1K2BG4Kk8f6L6BNt65T3SwXlFN1FGdL/ahmxl6jOBEuZwW8S079fIgn+nO0CTFnIRP39Dzg1TAKH8O8piF5MYJ3JDz32bWoIjlm4kDa7tVmsSjDXf6n+MX3kfNuWOBdnRD27ePpKTY0gRbty7fEJPfCFfB6HobznHbEjEXZWbIRLf2l6AX01ebI0MZdH85G7dedKZ8d322KUdMm04g=" Oct 24 04:21:31 volumio go-librespot[14696]: time="2025-10-24T04:21:31+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 24 04:21:31 volumio go-librespot[14696]: time="2025-10-24T04:21:31+01:00" level=debug msg="completed keyexchange" Oct 24 04:21:31 volumio go-librespot[14696]: time="2025-10-24T04:21:31+01:00" level=debug msg="completed challenge" Oct 24 04:21:31 volumio go-librespot[14696]: time="2025-10-24T04:21:31+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 24 04:21:31 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 24 04:21:31 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 24 04:21:32 volumio volumio[14321]: info: Initializing connection to go-librespot Websocket Oct 24 04:21:32 volumio volumio[14321]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 24 04:21:34 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1209. Oct 24 04:21:34 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 24 04:21:34 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 24 04:21:34 volumio go-librespot[14703]: go-librespot daemon starting... Oct 24 04:21:34 volumio go-librespot[14704]: time="2025-10-24T04:21:34+01:00" level=info msg="running go-librespot 0.4.0" Oct 24 04:21:34 volumio go-librespot[14704]: time="2025-10-24T04:21:34+01:00" level=debug msg="app state loaded" Oct 24 04:21:34 volumio go-librespot[14704]: time="2025-10-24T04:21:34+01:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 24 04:21:34 volumio go-librespot[14704]: time="2025-10-24T04:21:34+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 24 04:21:34 volumio go-librespot[14704]: time="2025-10-24T04:21:34+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 24 04:21:34 volumio go-librespot[14704]: time="2025-10-24T04:21:34+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 24 04:21:34 volumio go-librespot[14704]: time="2025-10-24T04:21:34+01:00" level=info msg="zeroconf server listening on port 33463" Oct 24 04:21:34 volumio go-librespot[14704]: time="2025-10-24T04:21:34+01:00" level=debug msg="obtained new client token: AADhPyEI0Hm9prF5Fw4AhDcpdmGWHZQ5lz3NpwPrQwcIuXJihA1wQeLzH6bAu6xcarrg2tXvNDLmCx3+UzHp7jbeSO3WGnYVUkdJuauIujY5Unu9tEE9vxGbNVUFJU9IS76K7KscJorqrEVHAaRxnyrjXspulVisa1Bs4heDvw/G2p3GwZIjOHqUn073ZhQnPm3owmsFtowGcTa9p0PiAbKVZJCfNE5hTyW3jt7ENFSfejq2/rkjbKc=" Oct 24 04:21:34 volumio go-librespot[14704]: time="2025-10-24T04:21:34+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 24 04:21:34 volumio go-librespot[14704]: time="2025-10-24T04:21:34+01:00" level=debug msg="completed keyexchange" Oct 24 04:21:34 volumio go-librespot[14704]: time="2025-10-24T04:21:34+01:00" level=debug msg="completed challenge" Oct 24 04:21:34 volumio go-librespot[14704]: time="2025-10-24T04:21:34+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 24 04:21:34 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 24 04:21:34 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 24 04:21:35 volumio volumio[14321]: info: Initializing connection to go-librespot Websocket Oct 24 04:21:35 volumio volumio[14321]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 24 04:21:38 volumio volumio[14321]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Oct 24 04:21:38 volumio volumio[14321]: 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 24 04:21:38 volumio volumio[14321]: info: CoreCommandRouter::volumioGetState Oct 24 04:21:38 volumio volumio[14321]: info: CorePlayQueue::getTrack 0 Oct 24 04:21:38 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1210. Oct 24 04:21:38 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 24 04:21:38 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 24 04:21:38 volumio go-librespot[14714]: go-librespot daemon starting... Oct 24 04:21:38 volumio go-librespot[14715]: time="2025-10-24T04:21:38+01:00" level=info msg="running go-librespot 0.4.0" Oct 24 04:21:38 volumio go-librespot[14715]: time="2025-10-24T04:21:38+01:00" level=debug msg="app state loaded" Oct 24 04:21:38 volumio go-librespot[14715]: time="2025-10-24T04:21:38+01:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 24 04:21:38 volumio go-librespot[14715]: time="2025-10-24T04:21:38+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 24 04:21:38 volumio go-librespot[14715]: time="2025-10-24T04:21:38+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 24 04:21:38 volumio go-librespot[14715]: time="2025-10-24T04:21:38+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 24 04:21:38 volumio go-librespot[14715]: time="2025-10-24T04:21:38+01:00" level=info msg="zeroconf server listening on port 40503" Oct 24 04:21:38 volumio volumio[14321]: info: Initializing connection to go-librespot Websocket Oct 24 04:21:38 volumio go-librespot[14715]: time="2025-10-24T04:21:38+01:00" level=debug msg="new websocket client" Oct 24 04:21:38 volumio volumio[14321]: info: Connection to go-librespot Websocket established Oct 24 04:21:38 volumio go-librespot[14715]: time="2025-10-24T04:21:38+01:00" level=debug msg="obtained new client token: AABW2zkoidcXCkeEjXKT9dA0yldNBeuV977cVtxUEBRqmF2I9fnfvsH4MkUeK4QPg7ZYXE9flEm/TB1s0pSeaZfxFv+3aRTikxLF98mCvDFil88aoQu3jnCctWRqxZvo95Z0cMTq/QRZ2KtP+cNwTsdAirKUOcOzsazzwdUuhPqHhsKPVLAMGtLq/I9bK/6q3kcXXsy+UVgU4x+s4XS3/mervjq5/dGrH8zIDh4Cb8fVJBmRpWrhLiU=" Oct 24 04:21:38 volumio go-librespot[14715]: time="2025-10-24T04:21:38+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 24 04:21:38 volumio go-librespot[14715]: time="2025-10-24T04:21:38+01:00" level=debug msg="completed keyexchange" Oct 24 04:21:38 volumio go-librespot[14715]: time="2025-10-24T04:21:38+01:00" level=debug msg="completed challenge" Oct 24 04:21:38 volumio go-librespot[14715]: time="2025-10-24T04:21:38+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 24 04:21:38 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 24 04:21:38 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 24 04:21:38 volumio volumio[14321]: info: Connection to go-librespot Websocket closed Oct 24 04:21:41 volumio volumio[14321]: info: Getting Spotify volume Oct 24 04:21:41 volumio volumio[14321]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 24 04:21:41 volumio volumio[14321]: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 24 04:21:41 volumio volumio[14321]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Oct 24 04:21:41 volumio volumio[14321]: errno: -111, Oct 24 04:21:41 volumio volumio[14321]: code: 'ECONNREFUSED', Oct 24 04:21:41 volumio volumio[14321]: syscall: 'connect', Oct 24 04:21:41 volumio volumio[14321]: address: '127.0.0.1', Oct 24 04:21:41 volumio volumio[14321]: port: 9879, Oct 24 04:21:41 volumio volumio[14321]: response: undefined Oct 24 04:21:41 volumio volumio[14321]: } Oct 24 04:21:41 volumio volumio[14321]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 24 04:21:41 volumio sudo[14750]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-10-24 04:20' Oct 24 04:21:41 volumio sudo[14750]: 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"