Oct 25 20:02:00 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 518. Oct 25 20:02:00 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 25 20:02:00 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 25 20:02:00 volumio go-librespot[14027]: go-librespot daemon starting... Oct 25 20:02:00 volumio go-librespot[14028]: time="2025-10-25T20:02:00+01:00" level=info msg="running go-librespot 0.4.0" Oct 25 20:02:00 volumio go-librespot[14028]: time="2025-10-25T20:02:00+01:00" level=debug msg="app state loaded" Oct 25 20:02:00 volumio go-librespot[14028]: time="2025-10-25T20:02:00+01:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 25 20:02:00 volumio go-librespot[14028]: time="2025-10-25T20:02:00+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Oct 25 20:02:00 volumio go-librespot[14028]: time="2025-10-25T20:02:00+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 25 20:02:00 volumio go-librespot[14028]: time="2025-10-25T20:02:00+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 25 20:02:00 volumio go-librespot[14028]: time="2025-10-25T20:02:00+01:00" level=info msg="zeroconf server listening on port 36073" Oct 25 20:02:00 volumio go-librespot[14028]: time="2025-10-25T20:02:00+01:00" level=debug msg="obtained new client token: AAAWxNZHM2toHMYIZBrdMaGbEaP+RpH5tm+jk2ejuUIF9rne+/C2AyMpvtNuoUT/9qw8hYCgqBGe6xXYJT5yrm+moUBnsUdViHMl4oBYCRcsiNJgAgpWSoyYAG6EH6s9NTZzQopTPOvlaKxN/9QWYDg1TmtwBzcmLIMVCfE8M4Z5o8PBMz7elldiZsE+oJyU4piD7S1qPVFZaF/2RIfSYdNgJ4VIjkkJFhuRCw65C9PlloBjBZVAeTQ=" Oct 25 20:02:00 volumio go-librespot[14028]: time="2025-10-25T20:02:00+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 25 20:02:00 volumio go-librespot[14028]: time="2025-10-25T20:02:00+01:00" level=debug msg="completed keyexchange" Oct 25 20:02:00 volumio go-librespot[14028]: time="2025-10-25T20:02:00+01:00" level=debug msg="completed challenge" Oct 25 20:02:00 volumio go-librespot[14028]: time="2025-10-25T20:02: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 25 20:02:00 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 25 20:02:00 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 25 20:02:00 volumio volumio[13967]: info: Loading plugin "outputs"... Oct 25 20:02:00 volumio volumio[13967]: info: Loading plugin "albumart"... Oct 25 20:02:00 volumio volumio[13967]: info: Plugin example_plugin is not enabled Oct 25 20:02:00 volumio volumio[13967]: info: Loading plugin "inputs"... Oct 25 20:02:00 volumio volumio[13967]: info: Loading plugin "updater_comm"... Oct 25 20:02:00 volumio volumio[13967]: info: Plugin mpdemulation is not enabled Oct 25 20:02:00 volumio volumio[13967]: info: Loading plugin "rest_api"... Oct 25 20:02:00 volumio volumio[13967]: info: Loading plugin "websocket"... Oct 25 20:02:00 volumio volumio[13967]: info: Starting Socket.io Server version 1.7.4 Oct 25 20:02:00 volumio volumio[13967]: info: Loading plugin "Systeminfo"... Oct 25 20:02:00 volumio volumio[13967]: info: Loading i18n strings for locale en Oct 25 20:02:00 volumio volumio[13967]: Updating browse sources language Oct 25 20:02:00 volumio volumio[13967]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 25 20:02:01 volumio volumio[14035]: Forking 3 albumart workers Oct 25 20:02:01 volumio volumio[13967]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 25 20:02:01 volumio volumio[13967]: info: CoreCommandRouter::initPlayerControls Oct 25 20:02:01 volumio volumio[13967]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 25 20:02:01 volumio volumio[13967]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 25 20:02:01 volumio volumio[13967]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 25 20:02:01 volumio volumio[13967]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 25 20:02:01 volumio volumio[13967]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 25 20:02:01 volumio volumio[13967]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 25 20:02:01 volumio volumio[13967]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 25 20:02:01 volumio volumio[13967]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 25 20:02:01 volumio volumio[13967]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 25 20:02:01 volumio volumio[13967]: Express server listening on port 3000 Oct 25 20:02:01 volumio volumio[13967]: [Metrics] WebUI: 2s 957.40ms Oct 25 20:02:01 volumio volumio[13967]: info: CoreStateMachine::resetVolumioState Oct 25 20:02:01 volumio volumio[13967]: info: CoreStateMachine::getcurrentVolume Oct 25 20:02:01 volumio volumio[13967]: info: CoreCommandRouter::volumioRetrievevolume Oct 25 20:02:01 volumio volumio[13967]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 25 20:02:01 volumio volumio[13967]: info: Cannot read play queue from file Oct 25 20:02:01 volumio volumio[13967]: info: Volumio Network Manager: Network status updated: 1 Oct 25 20:02:01 volumio volumio[13967]: info: VolumeController:: Volume=33 Mute =false Oct 25 20:02:01 volumio volumio[13967]: info: CoreStateMachine::pushState Oct 25 20:02:01 volumio volumio[13967]: info: CorePlayQueue::getTrack 0 Oct 25 20:02:01 volumio volumio[13967]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 25 20:02:01 volumio volumio[13967]: info: CoreCommandRouter::volumioPushState Oct 25 20:02:01 volumio volumio[13967]: info: CoreStateMachine::updateTrackBlock Oct 25 20:02:01 volumio volumio[13967]: info: CorePlayQueue::getTrackBlock Oct 25 20:02:01 volumio volumio[13967]: info: CoreCommandRouter::volumioRetrievevolume Oct 25 20:02:01 volumio volumio[13967]: info: CoreStateMachine::setRepeat null single undefined Oct 25 20:02:01 volumio volumio[13967]: info: CoreStateMachine::pushState Oct 25 20:02:01 volumio volumio[13967]: info: CorePlayQueue::getTrack 0 Oct 25 20:02:01 volumio volumio[13967]: info: CoreCommandRouter::volumioPushState Oct 25 20:02:01 volumio volumio[13967]: info: CoreStateMachine::setRandom null Oct 25 20:02:01 volumio volumio[13967]: info: CoreStateMachine::pushState Oct 25 20:02:01 volumio volumio[13967]: info: CorePlayQueue::getTrack 0 Oct 25 20:02:01 volumio volumio[13967]: info: CoreCommandRouter::volumioPushState Oct 25 20:02:01 volumio volumio[13967]: info: Setting Device type: Raspberry PI Oct 25 20:02:01 volumio volumio[13967]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Oct 25 20:02:01 volumio volumio[13967]: info: USB Boot Capable - System SBC Revision found in cpuinfo: b04170 Oct 25 20:02:01 volumio volumio[13967]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Oct 25 20:02:01 volumio volumio[13967]: info: VolumeController:: Volume=33 Mute =false Oct 25 20:02:01 volumio volumio[13967]: info: CoreStateMachine::pushState Oct 25 20:02:01 volumio volumio[13967]: info: CorePlayQueue::getTrack 0 Oct 25 20:02:01 volumio volumio[13967]: info: CoreCommandRouter::volumioPushState Oct 25 20:02:01 volumio volumio[13967]: info: Discovery: adding 70853f74-8210-4683-a3fa-e1217517bd40 Oct 25 20:02:01 volumio volumio[13967]: info: Discovery: Found device Volumio Oct 25 20:02:01 volumio volumio[13967]: info: CoreCommandRouter::volumioGetState Oct 25 20:02:01 volumio volumio[13967]: info: CorePlayQueue::getTrack 0 Oct 25 20:02:01 volumio volumio[13967]: info: Discovery: this is already registered, 70853f74-8210-4683-a3fa-e1217517bd40 Oct 25 20:02:01 volumio volumio[13967]: info: Discovery: Found device Volumio Oct 25 20:02:01 volumio volumio[13967]: info: CoreCommandRouter::volumioGetState Oct 25 20:02:01 volumio volumio[13967]: info: CorePlayQueue::getTrack 0 Oct 25 20:02:01 volumio volumio[13967]: info: Completed loading Core Plugins Oct 25 20:02:01 volumio volumio[13967]: info: Preparing to generate the ALSA configuration file Oct 25 20:02:01 volumio volumio[13967]: info: Asound.conf file unchanged, so no further update is needed Oct 25 20:02:01 volumio volumio[13967]: info: Output device has changed, restarting MPD Oct 25 20:02:01 volumio volumio[13967]: info: Output device has changed, restarting Shairport Sync Oct 25 20:02:01 volumio volumio[13967]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 25 20:02:01 volumio volumio[13967]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 25 20:02:01 volumio volumio[13967]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 25 20:02:01 volumio sudo[14091]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 25 20:02:01 volumio sudo[14091]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 25 20:02:01 volumio volumio[13967]: info: ___________ START PLUGINS ___________ Oct 25 20:02:01 volumio sudo[14093]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 25 20:02:01 volumio sudo[14093]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 25 20:02:01 volumio sudo[14091]: pam_unix(sudo:session): session closed for user root Oct 25 20:02:01 volumio volumio[13967]: info: ControllerMpd::onStart: Initializing MPD Oct 25 20:02:01 volumio volumio[13967]: info: Creating MPD Configuration file Oct 25 20:02:01 volumio volumio[13967]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 25 20:02:01 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Oct 25 20:02:01 volumio volumio[13967]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 25 20:02:01 volumio volumio[13967]: info: [1761418921306] CoreMusicLibrary::Adding element Media Servers Oct 25 20:02:01 volumio volumio[13967]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 25 20:02:01 volumio sudo[14103]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 25 20:02:01 volumio sudo[14103]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 25 20:02:01 volumio volumio[13967]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 25 20:02:01 volumio volumio[13967]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 25 20:02:01 volumio volumio[13967]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 25 20:02:01 volumio volumio[13967]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 25 20:02:01 volumio volumio[13967]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 25 20:02:01 volumio systemd[1]: mpd.service: Deactivated successfully. Oct 25 20:02:01 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Oct 25 20:02:01 volumio systemd[1]: mpd.socket: Deactivated successfully. Oct 25 20:02:01 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Oct 25 20:02:01 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Oct 25 20:02:01 volumio sudo[14102]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 25 20:02:01 volumio sudo[14102]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 25 20:02:01 volumio volumio[13967]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 25 20:02:01 volumio volumio[13967]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 25 20:02:01 volumio volumio[13967]: info: [1761418921350] CoreMusicLibrary::Adding element Last_100 Oct 25 20:02:01 volumio volumio[13967]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 25 20:02:01 volumio volumio[13967]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 25 20:02:01 volumio volumio[13967]: info: [1761418921354] CoreMusicLibrary::Adding element Webradio Oct 25 20:02:01 volumio volumio[13967]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 25 20:02:01 volumio sudo[14102]: pam_unix(sudo:session): session closed for user root Oct 25 20:02:01 volumio volumio[13967]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 25 20:02:01 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Oct 25 20:02:01 volumio volumio[13967]: info: Initializing BBC Radios Oct 25 20:02:01 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Oct 25 20:02:01 volumio systemd[1]: mpd.service: Deactivated successfully. Oct 25 20:02:01 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Oct 25 20:02:01 volumio systemd[1]: mpd.socket: Deactivated successfully. Oct 25 20:02:01 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Oct 25 20:02:01 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Oct 25 20:02:01 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Oct 25 20:02:01 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Oct 25 20:02:01 volumio volumio[13967]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 25 20:02:01 volumio volumio[13967]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 25 20:02:01 volumio volumio[13967]: info: Creating Spotify config file Oct 25 20:02:01 volumio volumio[13967]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 25 20:02:01 volumio sudo[14125]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Oct 25 20:02:01 volumio sudo[14125]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Oct 25 20:02:01 volumio sudo[14125]: pam_unix(sudo:session): session closed for user root Oct 25 20:02:01 volumio volumio[14047]: Starting albumart workers Oct 25 20:02:01 volumio volumio[14046]: Starting albumart workers Oct 25 20:02:01 volumio volumio[13967]: info: Volumio Calling Home Oct 25 20:02:01 volumio volumio[14045]: Starting albumart workers Oct 25 20:02:01 volumio volumio[13967]: info: MPD Permissions set Oct 25 20:02:01 volumio volumio[13967]: info: MPD Permissions set Oct 25 20:02:01 volumio volumio[13967]: info: Volumio called home Oct 25 20:02:01 volumio volumio[13967]: info: Spotify config file written Oct 25 20:02:01 volumio sudo[14141]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Oct 25 20:02:01 volumio sudo[14141]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 25 20:02:01 volumio volumio[13967]: 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 25 20:02:01 volumio volumio[13967]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 25 20:02:01 volumio volumio[13967]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 25 20:02:01 volumio volumio[13967]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 25 20:02:01 volumio volumio[13967]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 25 20:02:01 volumio volumio[13967]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 25 20:02:01 volumio volumio[13967]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 25 20:02:01 volumio volumio[13967]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 25 20:02:01 volumio volumio[13967]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 25 20:02:01 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 25 20:02:01 volumio volumio[13967]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 25 20:02:01 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 25 20:02:01 volumio volumio[13967]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 25 20:02:01 volumio go-librespot[14148]: go-librespot daemon starting... Oct 25 20:02:01 volumio volumio[13967]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 25 20:02:01 volumio volumio[13967]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 25 20:02:01 volumio volumio[13967]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 25 20:02:01 volumio volumio[13967]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 25 20:02:01 volumio volumio[13967]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 25 20:02:01 volumio volumio[13967]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 25 20:02:01 volumio volumio[13967]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 25 20:02:01 volumio volumio[13967]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 25 20:02:01 volumio sudo[14141]: pam_unix(sudo:session): session closed for user root Oct 25 20:02:01 volumio go-librespot[14157]: time="2025-10-25T20:02:01+01:00" level=info msg="running go-librespot 0.4.0" Oct 25 20:02:01 volumio go-librespot[14157]: time="2025-10-25T20:02:01+01:00" level=debug msg="app state loaded" Oct 25 20:02:01 volumio go-librespot[14157]: time="2025-10-25T20:02:01+01:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 25 20:02:01 volumio volumio[13967]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 25 20:02:01 volumio volumio[13967]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 25 20:02:01 volumio volumio[13967]: info: No need to fix Spotify hosts Oct 25 20:02:02 volumio volumio[13967]: info: Starting Shairport Sync Oct 25 20:02:02 volumio volumio[13967]: info: Starting Shairport Sync Oct 25 20:02:02 volumio go-librespot[14157]: time="2025-10-25T20:02:02+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 25 20:02:02 volumio volumio[13967]: info: Starting Shairport Sync Oct 25 20:02:02 volumio go-librespot[14157]: time="2025-10-25T20:02:02+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 25 20:02:02 volumio go-librespot[14157]: time="2025-10-25T20:02:02+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 25 20:02:02 volumio sudo[14176]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 25 20:02:02 volumio sudo[14176]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 25 20:02:02 volumio go-librespot[14157]: time="2025-10-25T20:02:02+01:00" level=info msg="zeroconf server listening on port 42079" Oct 25 20:02:02 volumio sudo[14178]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 25 20:02:02 volumio sudo[14178]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 25 20:02:02 volumio sudo[14182]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 25 20:02:02 volumio sudo[14182]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 25 20:02:02 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Oct 25 20:02:02 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Oct 25 20:02:02 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Oct 25 20:02:02 volumio systemd[1]: shairport-sync.service: Consumed 1.530s CPU time. Oct 25 20:02:02 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Oct 25 20:02:02 volumio sudo[14176]: pam_unix(sudo:session): session closed for user root Oct 25 20:02:02 volumio sudo[14178]: pam_unix(sudo:session): session closed for user root Oct 25 20:02:02 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Oct 25 20:02:02 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Oct 25 20:02:02 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Oct 25 20:02:02 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Oct 25 20:02:02 volumio sudo[14182]: pam_unix(sudo:session): session closed for user root Oct 25 20:02:02 volumio go-librespot[14157]: time="2025-10-25T20:02:02+01:00" level=debug msg="obtained new client token: AACSOhiOB1DJpuQbuS7yBJjlLOyeVna4XkDLnQoywVc4XRXHQQNK3dVsgIbfTZrKP+959WsvancxuBAc9s8e9HVI59MuNudL5z3dKiiJNDsXBp+16aYj6WUN48uNvHhKKdJg/00b5Ag9Jn+73/nKa5ZRYO5oxS8TrOVxN0lQ6rL4tN7pajfgn/QzZ9szS0Ns3pnk23Ab+F8ozZh02QXdkDAPK7d9VDUiELk+6t463QZMde8ThagF" Oct 25 20:02:02 volumio volumio[13967]: info: Shairport-Sync Started Oct 25 20:02:02 volumio volumio[13967]: Error adding Membership: Error: addMembership EINVAL Oct 25 20:02:02 volumio volumio[13967]: info: Shairport-Sync Started Oct 25 20:02:02 volumio volumio[13967]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Oct 25 20:02:02 volumio volumio[13967]: SPOTIFY: BQB9ZK0ORwnYhOAM3suLvrOYGBkWIuUjJpT0FHlznRW7fOA0GadmJwfSZNxVNWvU6Ga9-1I8uL-yVaXXJ3nf4x5pOfTJu87joqvxZgK9LZFU2T0Ar1p6FvK_W8wkof939ldIJBvm7YOBCvzOReibsvBctaf3B3XcCbH8ZAqONe_revEExwpkm-WuYZOZ-kP1THeNvk6lC6nRWJvkcoiVM4IEHf8ni5x9PYaMJnNdRDEFSSYsBmhtm7v7DgaYFvY0YmXzLWiqf_2J2dCFChu8A7b6ysB2cQzDh0Bht-M9FRKuZWK_StA Oct 25 20:02:02 volumio volumio[13967]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Oct 25 20:02:02 volumio volumio[13967]: info: New Spotify access token = BQB9ZK0ORwnYhOAM3suLvrOYGBkWIuUjJpT0FHlznRW7fOA0GadmJwfSZNxVNWvU6Ga9-1I8uL-yVaXXJ3nf4x5pOfTJu87joqvxZgK9LZFU2T0Ar1p6FvK_W8wkof939ldIJBvm7YOBCvzOReibsvBctaf3B3XcCbH8ZAqONe_revEExwpkm-WuYZOZ-kP1THeNvk6lC6nRWJvkcoiVM4IEHf8ni5x9PYaMJnNdRDEFSSYsBmhtm7v7DgaYFvY0YmXzLWiqf_2J2dCFChu8A7b6ysB2cQzDh0Bht-M9FRKuZWK_StA Oct 25 20:02:02 volumio volumio[13967]: info: Spotify credentials grant success - running version from March 24, 2019 Oct 25 20:02:02 volumio go-librespot[14157]: time="2025-10-25T20:02:02+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 25 20:02:02 volumio volumio[13967]: info: Shairport-Sync Started Oct 25 20:02:02 volumio volumio[13967]: info: CoreCommandRouter::volumioGetState Oct 25 20:02:02 volumio volumio[13967]: info: CorePlayQueue::getTrack 0 Oct 25 20:02:02 volumio go-librespot[14157]: time="2025-10-25T20:02:02+01:00" level=debug msg="completed keyexchange" Oct 25 20:02:02 volumio go-librespot[14157]: time="2025-10-25T20:02:02+01:00" level=debug msg="completed challenge" Oct 25 20:02:02 volumio go-librespot[14157]: time="2025-10-25T20:02:02+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 25 20:02:02 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 25 20:02:02 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 25 20:02:02 volumio volumio[13967]: 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 25 20:02:02 volumio volumio[13967]: info: Spotify Successfully logged in Oct 25 20:02:02 volumio volumio[13967]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 25 20:02:02 volumio volumio[13967]: info: [1761418922268] CoreMusicLibrary::Adding element Spotify Oct 25 20:02:02 volumio volumio[13967]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 25 20:02:02 volumio volumio[13967]: Cannot find translation for source Spotify Oct 25 20:02:02 volumio mpd[14132]: 2025-10-25T20:02:02 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Oct 25 20:02:02 volumio systemd[1]: Started mpd.service - Music Player Daemon. Oct 25 20:02:02 volumio sudo[14103]: pam_unix(sudo:session): session closed for user root Oct 25 20:02:02 volumio sudo[14093]: pam_unix(sudo:session): session closed for user root Oct 25 20:02:02 volumio volumio[13967]: error: MPD error: The expression evaluated to a falsy value: Oct 25 20:02:02 volumio volumio[13967]: assert.ok(self.idling) Oct 25 20:02:02 volumio volumio[13967]: error: The expression evaluated to a falsy value: Oct 25 20:02:02 volumio volumio[13967]: assert.ok(self.idling) Oct 25 20:02:02 volumio volumio[13967]: info: MPD running with PID14132 Oct 25 20:02:02 volumio volumio[13967]: ,establishing connection Oct 25 20:02:02 volumio volumio[13967]: error: updateQueue error: null Oct 25 20:02:02 volumio volumio[13967]: error: updateQueue error: null Oct 25 20:02:02 volumio volumio-remote-updater[896]: [2025-10-25 19:02:02] [connect] Successful connection Oct 25 20:02:02 volumio volumio-remote-updater[896]: [2025-10-25 19:02:02] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1761418922 101 Oct 25 20:02:02 volumio volumio[13967]: 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 25 20:02:02 volumio volumio[13967]: info: [yt-cast-receiver] DIAL server listening on port 8098 Oct 25 20:02:02 volumio volumio[13967]: info: CoreCommandRouter::volumioRetrievevolume Oct 25 20:02:02 volumio volumio[13967]: info: VolumeController:: Volume=33 Mute =false Oct 25 20:02:02 volumio volumio[13967]: info: CoreCommandRouter::volumioGetState Oct 25 20:02:02 volumio volumio[13967]: info: CorePlayQueue::getTrack 0 Oct 25 20:02:02 volumio volumio[13967]: info: CoreStateMachine::pushState Oct 25 20:02:02 volumio volumio[13967]: info: CorePlayQueue::getTrack 0 Oct 25 20:02:02 volumio volumio[13967]: info: CoreCommandRouter::volumioPushState Oct 25 20:02:02 volumio volumio[13967]: info: Completed starting Core Plugins Oct 25 20:02:02 volumio volumio[13967]: info: ------------------------------------------- Oct 25 20:02:02 volumio volumio[13967]: info: ----- MyVolumio plugins startup ---- Oct 25 20:02:02 volumio volumio[13967]: info: ------------------------------------------- Oct 25 20:02:02 volumio volumio[13967]: info: [MyVolumio PluginManager] Fetching plans data.... Oct 25 20:02:03 volumio volumio[13967]: info: Cannot mount NAS NAS at system boot, trial number 2 ,retrying in 5 seconds Oct 25 20:02:05 volumio volumio[13967]: info: go-librespot daemon successfully initialized Oct 25 20:02:05 volumio sudo[14210]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Oct 25 20:02:05 volumio sudo[14210]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 25 20:02:05 volumio sudo[14213]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Oct 25 20:02:05 volumio sudo[14213]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 25 20:02:05 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 519. Oct 25 20:02:05 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 25 20:02:05 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 25 20:02:05 volumio go-librespot[14215]: go-librespot daemon starting... Oct 25 20:02:05 volumio go-librespot[14216]: time="2025-10-25T20:02:05+01:00" level=info msg="running go-librespot 0.4.0" Oct 25 20:02:05 volumio go-librespot[14216]: time="2025-10-25T20:02:05+01:00" level=debug msg="app state loaded" Oct 25 20:02:05 volumio systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Oct 25 20:02:05 volumio go-librespot[14216]: time="2025-10-25T20:02:05+01:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 25 20:02:05 volumio systemd[1]: mpd_monitor.service: Deactivated successfully. Oct 25 20:02:05 volumio systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Oct 25 20:02:05 volumio systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Oct 25 20:02:05 volumio mpd_monitor.sh[14222]: MPD Monitor Service: Starting MPD Monitor Service Oct 25 20:02:05 volumio sudo[14210]: pam_unix(sudo:session): session closed for user root Oct 25 20:02:05 volumio sudo[14213]: pam_unix(sudo:session): session closed for user root Oct 25 20:02:05 volumio volumio[13967]: info: Successfully started MPD Monitor Oct 25 20:02:05 volumio volumio[13967]: info: Successfully started MPD Monitor Oct 25 20:02:05 volumio go-librespot[14216]: time="2025-10-25T20:02:05+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 25 20:02:05 volumio go-librespot[14216]: time="2025-10-25T20:02:05+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 25 20:02:05 volumio go-librespot[14216]: time="2025-10-25T20:02:05+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 25 20:02:05 volumio go-librespot[14216]: time="2025-10-25T20:02:05+01:00" level=info msg="zeroconf server listening on port 34735" Oct 25 20:02:05 volumio go-librespot[14216]: time="2025-10-25T20:02:05+01:00" level=debug msg="obtained new client token: AAAEVH7P9wBddtQjCuaqxpxn9rB6iOYXrDbQVGgyUprimMn1vuGgS4YF+MJZo1AX0OyNv3CdXMg6LbpuvriqESZNHEJSmRNTdUnPqggdf7/GECn/x1Xsa9CdCZch4Z/BodXr4DyfbToYA2pRpxvFDS5jSY8JLAGa+5WsN7eOIZss+MaJmI6BYYL8OnFNEk8gUnWBN2qJnj1uGgvIMcM8NvpTib0EiEJKYcW1cs00joVOaIuZJ5ogoX0=" Oct 25 20:02:05 volumio go-librespot[14216]: time="2025-10-25T20:02:05+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 25 20:02:05 volumio go-librespot[14216]: time="2025-10-25T20:02:05+01:00" level=debug msg="completed keyexchange" Oct 25 20:02:05 volumio go-librespot[14216]: time="2025-10-25T20:02:05+01:00" level=debug msg="completed challenge" Oct 25 20:02:05 volumio go-librespot[14216]: time="2025-10-25T20:02:05+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 25 20:02:05 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 25 20:02:05 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 25 20:02:07 volumio volumio[13967]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Oct 25 20:02:08 volumio volumio[13967]: info: Initializing connection to go-librespot Websocket Oct 25 20:02:08 volumio volumio[13967]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 25 20:02:08 volumio volumio[13967]: info: Cannot mount NAS NAS at system boot, trial number 3 ,retrying in 5 seconds Oct 25 20:02:08 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 520. Oct 25 20:02:08 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 25 20:02:08 volumio sudo[14243]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 25 20:02:08 volumio sudo[14243]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 25 20:02:08 volumio sudo[14243]: pam_unix(sudo:session): session closed for user root Oct 25 20:02:08 volumio sudo[14245]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 25 20:02:08 volumio sudo[14245]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 25 20:02:08 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 25 20:02:08 volumio sudo[14245]: pam_unix(sudo:session): session closed for user root Oct 25 20:02:08 volumio sudo[14248]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Oct 25 20:02:08 volumio go-librespot[14241]: go-librespot daemon starting... Oct 25 20:02:08 volumio sudo[14248]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 25 20:02:08 volumio go-librespot[14250]: time="2025-10-25T20:02:08+01:00" level=info msg="running go-librespot 0.4.0" Oct 25 20:02:08 volumio go-librespot[14250]: time="2025-10-25T20:02:08+01:00" level=debug msg="app state loaded" Oct 25 20:02:08 volumio go-librespot[14250]: time="2025-10-25T20:02:08+01:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 25 20:02:08 volumio sudo[14248]: pam_unix(sudo:session): session closed for user root Oct 25 20:02:08 volumio volumio[13967]: info: Upmpdcli Daemon Started Oct 25 20:02:08 volumio go-librespot[14250]: time="2025-10-25T20:02: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 25 20:02:08 volumio go-librespot[14250]: time="2025-10-25T20:02: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 25 20:02:08 volumio go-librespot[14250]: time="2025-10-25T20:02: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 25 20:02:08 volumio go-librespot[14250]: time="2025-10-25T20:02:08+01:00" level=info msg="zeroconf server listening on port 45245" Oct 25 20:02:09 volumio go-librespot[14250]: time="2025-10-25T20:02:09+01:00" level=debug msg="obtained new client token: AABdZITiGgZCviWTvKEbANB9ftyGQT6IKHzacBXU+NqGnGvGozfKqEq4/yKOeGTKjLz3EjUYTPaNzxtECA47Vhyh6YHwXxhUcBk71y9lSpLtnGi5g2ZEVlpkdBUUtCTLq+S45XZon1lM6JW7PmRTJEaUqPAywt2WilLQ46mEBeH1u5MkSwcZKuOEhQmZtZrZoxxpEXVn+398nEo/xpiPvOMEl+uIAtqrtIT/UBT3eFjPXj1KI80q" Oct 25 20:02:09 volumio go-librespot[14250]: time="2025-10-25T20:02:09+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 25 20:02:09 volumio go-librespot[14250]: time="2025-10-25T20:02:09+01:00" level=debug msg="completed keyexchange" Oct 25 20:02:09 volumio go-librespot[14250]: time="2025-10-25T20:02:09+01:00" level=debug msg="completed challenge" Oct 25 20:02:09 volumio go-librespot[14250]: time="2025-10-25T20:02:09+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 25 20:02:09 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 25 20:02:09 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 25 20:02:10 volumio volumio[13967]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Oct 25 20:02:10 volumio volumio[13967]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Oct 25 20:02:10 volumio volumio[13967]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Oct 25 20:02:10 volumio volumio[13967]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Oct 25 20:02:10 volumio volumio[13967]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Oct 25 20:02:10 volumio volumio[13967]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Oct 25 20:02:10 volumio volumio[13967]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Oct 25 20:02:10 volumio volumio[13967]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Oct 25 20:02:10 volumio volumio[13967]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Oct 25 20:02:10 volumio volumio[13967]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Oct 25 20:02:10 volumio volumio[13967]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Oct 25 20:02:10 volumio volumio[13967]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Oct 25 20:02:10 volumio volumio[13967]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Oct 25 20:02:10 volumio volumio[13967]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Oct 25 20:02:10 volumio volumio[13967]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Oct 25 20:02:10 volumio volumio[13967]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Oct 25 20:02:10 volumio volumio[13967]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Oct 25 20:02:10 volumio volumio[13967]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Oct 25 20:02:10 volumio volumio[13967]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Oct 25 20:02:10 volumio volumio[13967]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Oct 25 20:02:10 volumio volumio[13967]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Oct 25 20:02:10 volumio volumio[13967]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Oct 25 20:02:10 volumio volumio[13967]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Oct 25 20:02:10 volumio volumio[13967]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Oct 25 20:02:10 volumio volumio[13967]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Oct 25 20:02:10 volumio volumio[13967]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Oct 25 20:02:10 volumio volumio[13967]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Oct 25 20:02:10 volumio volumio[13967]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Oct 25 20:02:10 volumio volumio[13967]: info: Adding plugin bluetooth to MyMusic Plugins Oct 25 20:02:10 volumio volumio[13967]: info: Adding plugin multiroom to MyMusic Plugins Oct 25 20:02:10 volumio volumio[13967]: info: Adding plugin metavolumio to MyMusic Plugins Oct 25 20:02:10 volumio volumio[13967]: info: Adding plugin cd_controller to MyMusic Plugins Oct 25 20:02:10 volumio volumio[13967]: info: Adding plugin qobuzconnect to MyMusic Plugins Oct 25 20:02:10 volumio volumio[13967]: info: Adding plugin smart_inputs to MyMusic Plugins Oct 25 20:02:10 volumio volumio[13967]: info: Adding plugin tidalconnect to MyMusic Plugins Oct 25 20:02:10 volumio volumio[13967]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Oct 25 20:02:11 volumio volumio[13967]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Oct 25 20:02:11 volumio volumio[13967]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Oct 25 20:02:11 volumio volumio[13967]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 25 20:02:11 volumio volumio[13967]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 25 20:02:11 volumio volumio[13967]: info: Starting MyVolumio Remote Streaming Endpoints Oct 25 20:02:11 volumio volumio[13967]: info: MyVolumio login type: Token Oct 25 20:02:11 volumio volumio[13967]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Oct 25 20:02:11 volumio volumio[13967]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Oct 25 20:02:11 volumio volumio[13967]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Oct 25 20:02:11 volumio volumio[13967]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Oct 25 20:02:11 volumio volumio[13967]: info: Streaming services startup Oct 25 20:02:11 volumio volumio[13967]: info: Starting Streaming Daemon Oct 25 20:02:11 volumio sudo[14259]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Oct 25 20:02:11 volumio sudo[14259]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 25 20:02:11 volumio volumio[13967]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Oct 25 20:02:11 volumio sudo[14259]: pam_unix(sudo:session): session closed for user root Oct 25 20:02:11 volumio volumio[13967]: info: Initializing connection to go-librespot Websocket Oct 25 20:02:11 volumio volumio[13967]: error: Cannot start Volumio Streaming Daemon Oct 25 20:02:11 volumio volumio[13967]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Oct 25 20:02:11 volumio volumio[13967]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Oct 25 20:02:11 volumio volumio[13967]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 25 20:02:11 volumio volumio[13967]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Oct 25 20:02:12 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 521. Oct 25 20:02:12 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 25 20:02:12 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 25 20:02:12 volumio go-librespot[14265]: go-librespot daemon starting... Oct 25 20:02:12 volumio go-librespot[14266]: time="2025-10-25T20:02:12+01:00" level=info msg="running go-librespot 0.4.0" Oct 25 20:02:12 volumio go-librespot[14266]: time="2025-10-25T20:02:12+01:00" level=debug msg="app state loaded" Oct 25 20:02:12 volumio go-librespot[14266]: time="2025-10-25T20:02:12+01:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 25 20:02:12 volumio go-librespot[14266]: time="2025-10-25T20:02:12+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 25 20:02:12 volumio go-librespot[14266]: time="2025-10-25T20:02:12+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 25 20:02:12 volumio go-librespot[14266]: time="2025-10-25T20:02:12+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 25 20:02:12 volumio go-librespot[14266]: time="2025-10-25T20:02:12+01:00" level=info msg="zeroconf server listening on port 46631" Oct 25 20:02:12 volumio volumio[13967]: info: MyVolumio token set successfully Oct 25 20:02:12 volumio volumio[13967]: info: MYVOLUMIO: Adding device Oct 25 20:02:12 volumio volumio[13967]: info: MYVOLUMIO: Evaluating Server Oct 25 20:02:12 volumio go-librespot[14266]: time="2025-10-25T20:02:12+01:00" level=debug msg="obtained new client token: AADP3LPHgIzjOSDX30EosPuq9wMdBIK0Rt9j7xqloPIa75ughPfLJnrk1BPSeeazuwEIyNzf3xXtdTT08cVD9UeuOmKwscb9RaK4TUvx745acCnfPqvhYOWYHoKShX24nhKGOxSaJwHAHAAqUQ2J+NJ6UsNpuyP/TOZOyqIVkdsqBfvMa5NYCpwolVx07VZ77g/3jnhyixNYXd18w/aXqUu47de47SsaO39U5YP8pohzdgSf9mkZ5pU=" Oct 25 20:02:12 volumio go-librespot[14266]: time="2025-10-25T20:02:12+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 25 20:02:12 volumio go-librespot[14266]: time="2025-10-25T20:02:12+01:00" level=debug msg="completed keyexchange" Oct 25 20:02:12 volumio go-librespot[14266]: time="2025-10-25T20:02:12+01:00" level=debug msg="completed challenge" Oct 25 20:02:12 volumio go-librespot[14266]: time="2025-10-25T20:02:12+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 25 20:02:12 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 25 20:02:12 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 25 20:02:12 volumio volumio[13967]: info: MyVolumio status changed Oct 25 20:02:12 volumio volumio[13967]: info: Streaming services startup Oct 25 20:02:12 volumio volumio[13967]: info: Starting Streaming Daemon Oct 25 20:02:12 volumio volumio[13967]: info: Removing browser output: myVolumio user plan is not superstar Oct 25 20:02:12 volumio volumio[13967]: info: Removing audio output: Oct 25 20:02:12 volumio volumio[13967]: info: Stoppping Tunnel 1 Oct 25 20:02:12 volumio sudo[14291]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Oct 25 20:02:12 volumio sudo[14291]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 25 20:02:12 volumio sudo[14293]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service Oct 25 20:02:12 volumio sudo[14293]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 25 20:02:12 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 25 20:02:12 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 25 20:02:12 volumio sudo[14291]: pam_unix(sudo:session): session closed for user root Oct 25 20:02:12 volumio volumio[13967]: error: Cannot start Volumio Streaming Daemon Oct 25 20:02:12 volumio volumio[13967]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Oct 25 20:02:12 volumio volumio[13967]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Oct 25 20:02:12 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 25 20:02:12 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 25 20:02:12 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 25 20:02:12 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 25 20:02:12 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 25 20:02:12 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 25 20:02:12 volumio sudo[14293]: pam_unix(sudo:session): session closed for user root Oct 25 20:02:12 volumio volumio[13967]: info: Remote SSH Stopped Oct 25 20:02:12 volumio volumio[13967]: info: Setting Geolocation for MyVolumio to eu3 Oct 25 20:02:12 volumio volumio[13967]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 25 20:02:12 volumio volumio[13967]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 25 20:02:12 volumio volumio[13967]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 25 20:02:13 volumio volumio[13967]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Oct 25 20:02:13 volumio volumio[13967]: info: Cannot mount NAS NAS at system boot, trial number 4 ,retrying in 5 seconds Oct 25 20:02:13 volumio volumio[13967]: info: Updating MyVolumio device info Oct 25 20:02:13 volumio volumio[13967]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 25 20:02:13 volumio volumio[13967]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 25 20:02:13 volumio volumio[13967]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 25 20:02:14 volumio volumio[13967]: info: Initializing connection to go-librespot Websocket Oct 25 20:02:14 volumio volumio[13967]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 25 20:02:14 volumio volumio[13967]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Oct 25 20:02:15 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 522. Oct 25 20:02:15 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 25 20:02:15 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 25 20:02:15 volumio go-librespot[14296]: go-librespot daemon starting... Oct 25 20:02:15 volumio go-librespot[14297]: time="2025-10-25T20:02:15+01:00" level=info msg="running go-librespot 0.4.0" Oct 25 20:02:15 volumio go-librespot[14297]: time="2025-10-25T20:02:15+01:00" level=debug msg="app state loaded" Oct 25 20:02:15 volumio go-librespot[14297]: time="2025-10-25T20:02:15+01:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 25 20:02:15 volumio go-librespot[14297]: time="2025-10-25T20:02:15+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 25 20:02:15 volumio go-librespot[14297]: time="2025-10-25T20:02:15+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 25 20:02:15 volumio go-librespot[14297]: time="2025-10-25T20:02:15+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 25 20:02:15 volumio go-librespot[14297]: time="2025-10-25T20:02:15+01:00" level=info msg="zeroconf server listening on port 45151" Oct 25 20:02:15 volumio go-librespot[14297]: time="2025-10-25T20:02:15+01:00" level=debug msg="obtained new client token: AADIhyT4aE5fLp6KSwoUvj3LON3RhR7SeTqLxD0XyOAH90/TVbvI4NrQnNZKKK34qqCo5UeKtO5/2Cf1B6I6vs4kKPjfKDB/i8Vyk3Lb+Zqpb8q0/AroPcTfKJmTI81E5XKRdbg0/yuBhsbZWJ5PNBUzFucjw0qUBBEn6pvaCm7KZiztDw4TWM/nflFINxJDW0ayi8FBd/67QbvLJHO/26uKeYjfB/oFkEA4w7dG1JAHa0CfYBJ+gCA=" Oct 25 20:02:15 volumio go-librespot[14297]: time="2025-10-25T20:02:15+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 25 20:02:15 volumio go-librespot[14297]: time="2025-10-25T20:02:15+01:00" level=debug msg="completed keyexchange" Oct 25 20:02:15 volumio go-librespot[14297]: time="2025-10-25T20:02:15+01:00" level=debug msg="completed challenge" Oct 25 20:02:15 volumio go-librespot[14297]: time="2025-10-25T20:02:15+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 25 20:02:15 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 25 20:02:15 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 25 20:02:17 volumio volumio[13967]: info: MYVOLUMIO: Adding device Oct 25 20:02:17 volumio volumio[13967]: info: MYVOLUMIO: Evaluating Server Oct 25 20:02:17 volumio volumio[13967]: info: Setting Geolocation for MyVolumio to eu3 Oct 25 20:02:17 volumio volumio[13967]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 25 20:02:17 volumio volumio[13967]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 25 20:02:17 volumio volumio[13967]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 25 20:02:17 volumio volumio[13967]: info: Initializing connection to go-librespot Websocket Oct 25 20:02:17 volumio volumio[13967]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 25 20:02:17 volumio volumio[13967]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Oct 25 20:02:18 volumio volumio[13967]: info: Updating MyVolumio device info Oct 25 20:02:18 volumio volumio[13967]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 25 20:02:18 volumio volumio[13967]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 25 20:02:18 volumio volumio[13967]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 25 20:02:18 volumio volumio[13967]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Oct 25 20:02:18 volumio volumio[13967]: info: Cannot mount NAS at system boot, trial number 4 ,stopping Oct 25 20:02:19 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 523. Oct 25 20:02:19 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 25 20:02:19 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 25 20:02:19 volumio go-librespot[14334]: go-librespot daemon starting... Oct 25 20:02:19 volumio go-librespot[14335]: time="2025-10-25T20:02:19+01:00" level=info msg="running go-librespot 0.4.0" Oct 25 20:02:19 volumio go-librespot[14335]: time="2025-10-25T20:02:19+01:00" level=debug msg="app state loaded" Oct 25 20:02:19 volumio go-librespot[14335]: time="2025-10-25T20:02:19+01:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 25 20:02:19 volumio go-librespot[14335]: time="2025-10-25T20:02:19+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 25 20:02:19 volumio go-librespot[14335]: time="2025-10-25T20:02:19+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 25 20:02:19 volumio go-librespot[14335]: time="2025-10-25T20:02:19+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 25 20:02:19 volumio go-librespot[14335]: time="2025-10-25T20:02:19+01:00" level=info msg="zeroconf server listening on port 45881" Oct 25 20:02:19 volumio go-librespot[14335]: time="2025-10-25T20:02:19+01:00" level=debug msg="obtained new client token: AADLrt3n2FKihqdsFkayz6PtppH/xZ5rg5BmLgb0KIX73TNc0QFIRltw4BTgpT2uQD2/XSpcuzeqhfzh2gGHLFo/ryjrjF/432nfkG7PfFEW2eSo3TN1vJ+ia04/rxJYQLQDKXzU/5GPegq5Qr3QBAwENOMueycxX78ZnIWeP8/RzkQHcsejkaUNBrU4fVWtPjYpzBKgXNu++gBfqgP5DBfU2sd0DtJTbgCIB1LWDkeyI4BTkwkjuy4=" Oct 25 20:02:19 volumio go-librespot[14335]: time="2025-10-25T20:02:19+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 25 20:02:19 volumio go-librespot[14335]: time="2025-10-25T20:02:19+01:00" level=debug msg="completed keyexchange" Oct 25 20:02:19 volumio go-librespot[14335]: time="2025-10-25T20:02:19+01:00" level=debug msg="completed challenge" Oct 25 20:02:19 volumio go-librespot[14335]: time="2025-10-25T20:02:19+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 25 20:02:19 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 25 20:02:19 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 25 20:02:20 volumio volumio[13967]: info: Initializing connection to go-librespot Websocket Oct 25 20:02:20 volumio volumio[13967]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 25 20:02:22 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 524. Oct 25 20:02:22 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 25 20:02:22 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 25 20:02:22 volumio go-librespot[14342]: go-librespot daemon starting... Oct 25 20:02:22 volumio go-librespot[14343]: time="2025-10-25T20:02:22+01:00" level=info msg="running go-librespot 0.4.0" Oct 25 20:02:22 volumio go-librespot[14343]: time="2025-10-25T20:02:22+01:00" level=debug msg="app state loaded" Oct 25 20:02:22 volumio go-librespot[14343]: time="2025-10-25T20:02:22+01:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 25 20:02:22 volumio go-librespot[14343]: time="2025-10-25T20:02:22+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Oct 25 20:02:22 volumio go-librespot[14343]: time="2025-10-25T20:02:22+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 25 20:02:22 volumio go-librespot[14343]: time="2025-10-25T20:02:22+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 25 20:02:22 volumio go-librespot[14343]: time="2025-10-25T20:02:22+01:00" level=info msg="zeroconf server listening on port 46177" Oct 25 20:02:22 volumio go-librespot[14343]: time="2025-10-25T20:02:22+01:00" level=debug msg="obtained new client token: AADEW4myBKKLCi6JZgIF67YYbJjJhe50aJsgtPQQnKnV8iKjwAsnqshtvtxovSkUAvFG6kGwxypSEFKvrT1KF6wRZ29Di7OOLVolevU7dRXebf44wGkvVV/EM+foGBidKIdDn0hKJpxPWZ8tRV9QuDm7w8ecgmnEh8sxa+xmkk554tBf3vRpyF0l1zQ8ZfHf1eyec3McBnawdKik0pnhslDYC8RUz4jR0Jln4F/dWpSvbU5XeBcVbxs=" Oct 25 20:02:22 volumio go-librespot[14343]: time="2025-10-25T20:02:22+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 25 20:02:22 volumio go-librespot[14343]: time="2025-10-25T20:02:22+01:00" level=debug msg="completed keyexchange" Oct 25 20:02:22 volumio go-librespot[14343]: time="2025-10-25T20:02:22+01:00" level=debug msg="completed challenge" Oct 25 20:02:22 volumio go-librespot[14343]: time="2025-10-25T20:02:22+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 25 20:02:22 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 25 20:02:22 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 25 20:02:23 volumio volumio[13967]: info: Initializing connection to go-librespot Websocket Oct 25 20:02:23 volumio volumio[13967]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 25 20:02:26 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 525. Oct 25 20:02:26 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 25 20:02:26 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 25 20:02:26 volumio go-librespot[14353]: go-librespot daemon starting... Oct 25 20:02:26 volumio go-librespot[14354]: time="2025-10-25T20:02:26+01:00" level=info msg="running go-librespot 0.4.0" Oct 25 20:02:26 volumio go-librespot[14354]: time="2025-10-25T20:02:26+01:00" level=debug msg="app state loaded" Oct 25 20:02:26 volumio go-librespot[14354]: time="2025-10-25T20:02:26+01:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 25 20:02:26 volumio volumio[13967]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Oct 25 20:02:26 volumio volumio[13967]: 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 25 20:02:26 volumio volumio[13967]: info: CoreCommandRouter::volumioGetState Oct 25 20:02:26 volumio volumio[13967]: info: CorePlayQueue::getTrack 0 Oct 25 20:02:26 volumio go-librespot[14354]: time="2025-10-25T20:02:26+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 25 20:02:26 volumio go-librespot[14354]: time="2025-10-25T20:02:26+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 25 20:02:26 volumio go-librespot[14354]: time="2025-10-25T20:02:26+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 25 20:02:26 volumio go-librespot[14354]: time="2025-10-25T20:02:26+01:00" level=info msg="zeroconf server listening on port 33687" Oct 25 20:02:26 volumio go-librespot[14354]: time="2025-10-25T20:02:26+01:00" level=debug msg="obtained new client token: AADLLMyCtjHLeTxHpkyK4+HixdHaqw64kD1itlmiYhkFGT3Iw9OWPEdxre122LeaXIRW68tSvl99RSgbk7dyPNuN8yIvojSjWB4nlr2MXd03Jm3wQrKoAwiQc75q/vPA7pgYtAJeSTYrKeXIdntMgNnhLyb9E1pPRDR+6VXmOYTY79b6WJH8VtAUIjOZ1YVh9k8ZIXDymM8wwS2R6TIWABiwWnNbyoqebU86DvYmY8xDWRiEyqO8nfo=" Oct 25 20:02:26 volumio go-librespot[14354]: time="2025-10-25T20:02:26+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 25 20:02:26 volumio go-librespot[14354]: time="2025-10-25T20:02:26+01:00" level=debug msg="completed keyexchange" Oct 25 20:02:26 volumio go-librespot[14354]: time="2025-10-25T20:02:26+01:00" level=debug msg="completed challenge" Oct 25 20:02:26 volumio go-librespot[14354]: time="2025-10-25T20:02:26+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 25 20:02:26 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 25 20:02:26 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 25 20:02:26 volumio volumio[13967]: info: Initializing connection to go-librespot Websocket Oct 25 20:02:26 volumio volumio[13967]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 25 20:02:29 volumio volumio[13967]: info: Initializing connection to go-librespot Websocket Oct 25 20:02:29 volumio volumio[13967]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 25 20:02:29 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 526. Oct 25 20:02:29 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 25 20:02:29 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 25 20:02:29 volumio go-librespot[14375]: go-librespot daemon starting... Oct 25 20:02:29 volumio go-librespot[14376]: time="2025-10-25T20:02:29+01:00" level=info msg="running go-librespot 0.4.0" Oct 25 20:02:29 volumio go-librespot[14376]: time="2025-10-25T20:02:29+01:00" level=debug msg="app state loaded" Oct 25 20:02:29 volumio go-librespot[14376]: time="2025-10-25T20:02:29+01:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 25 20:02:29 volumio go-librespot[14376]: time="2025-10-25T20:02:29+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Oct 25 20:02:29 volumio go-librespot[14376]: time="2025-10-25T20:02:29+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 25 20:02:29 volumio go-librespot[14376]: time="2025-10-25T20:02:29+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 25 20:02:29 volumio go-librespot[14376]: time="2025-10-25T20:02:29+01:00" level=info msg="zeroconf server listening on port 45025" Oct 25 20:02:29 volumio go-librespot[14376]: time="2025-10-25T20:02:29+01:00" level=debug msg="obtained new client token: AABoCVVIHQXjkHYbiBHiV9+4ya84UBHIhPabSvulmDWjtxYyedU6JQdi/DpdiFv9FPDRlbEeZEQY6ldcru7q2UGK+AoKv5d7tgHWgpcuF7lctatJLkMKaKXLJEHuFl4fyox6sSH8KOIdG9S43a+3zj8CE+kuCNo+Sn4YfC6P/hUGlK1wMSlmGalyuB51/Rg2xIryDTRmRwaeN8SCKyRaPjsyjZVygi9zmN1lYWorEdC9xZufYHiGRwk=" Oct 25 20:02:29 volumio go-librespot[14376]: time="2025-10-25T20:02:29+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 25 20:02:29 volumio go-librespot[14376]: time="2025-10-25T20:02:29+01:00" level=debug msg="completed keyexchange" Oct 25 20:02:29 volumio go-librespot[14376]: time="2025-10-25T20:02:29+01:00" level=debug msg="completed challenge" Oct 25 20:02:29 volumio go-librespot[14376]: time="2025-10-25T20:02: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 25 20:02:29 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 25 20:02:29 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 25 20:02:31 volumio volumio[13967]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 25 20:02:31 volumio volumio[13967]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 25 20:02:31 volumio volumio[13967]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam Oct 25 20:02:31 volumio volumio[13967]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Oct 25 20:02:31 volumio volumio[13967]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Oct 25 20:02:31 volumio volumio[13967]: info: CoreCommandRouter::volumioGetBrowseSources Oct 25 20:02:31 volumio volumio[13967]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 25 20:02:31 volumio volumio[13967]: error: MyVolumio Plugin failed to authenticate in a timely fashion Oct 25 20:02:31 volumio volumio[13967]: info: Completed starting MyVolumio Plugin Oct 25 20:02:31 volumio volumio[13967]: [Metrics] CommandRouter: 33s 303.24ms Oct 25 20:02:31 volumio volumio[13967]: info: CoreCommandRouter::volumiosetStartupVolume Oct 25 20:02:31 volumio volumio[13967]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 25 20:02:31 volumio volumio[13967]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 25 20:02:31 volumio volumio[13967]: info: CoreCommandRouter::Close All Modals sent Oct 25 20:02:31 volumio volumio[13967]: info: CoreCommandRouter::Close All Modals sent Oct 25 20:02:31 volumio volumio[13967]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 25 20:02:31 volumio volumio[13967]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 25 20:02:31 volumio volumio[13967]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Oct 25 20:02:31 volumio volumio-remote-updater[896]: Test mode disabled Oct 25 20:02:31 volumio volumio-remote-updater[896]: Alpha mode disabled Oct 25 20:02:31 volumio volumio-remote-updater[896]: Alpha legacy test mode disabled Oct 25 20:02:31 volumio volumio[13967]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateEnabled Oct 25 20:02:31 volumio volumio[13967]: info: Update Ready: {"changeLogLink":"","description":"You're already on the latest version","title":"No Updates Available","updateavailable":false} Oct 25 20:02:31 volumio volumio[13967]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache Oct 25 20:02:32 volumio volumio[13967]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable Oct 25 20:02:32 volumio volumio[13967]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Oct 25 20:02:32 volumio volumio[13967]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect Oct 25 20:02:32 volumio volumio[13967]: info: Initializing connection to go-librespot Websocket Oct 25 20:02:32 volumio volumio[13967]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 25 20:02:33 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 527. Oct 25 20:02:33 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 25 20:02:33 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 25 20:02:33 volumio go-librespot[14392]: go-librespot daemon starting... Oct 25 20:02:33 volumio go-librespot[14393]: time="2025-10-25T20:02:33+01:00" level=info msg="running go-librespot 0.4.0" Oct 25 20:02:33 volumio go-librespot[14393]: time="2025-10-25T20:02:33+01:00" level=debug msg="app state loaded" Oct 25 20:02:33 volumio go-librespot[14393]: time="2025-10-25T20:02:33+01:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 25 20:02:33 volumio go-librespot[14393]: time="2025-10-25T20:02: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 25 20:02:33 volumio go-librespot[14393]: time="2025-10-25T20:02: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 25 20:02:33 volumio go-librespot[14393]: time="2025-10-25T20:02: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 25 20:02:33 volumio go-librespot[14393]: time="2025-10-25T20:02:33+01:00" level=info msg="zeroconf server listening on port 41309" Oct 25 20:02:33 volumio go-librespot[14393]: time="2025-10-25T20:02:33+01:00" level=debug msg="obtained new client token: AAA5YclN0hhBZM8IcpCCD81VHjEUGCBlrPaRWr939gJF+zm7xj4/L64HiVhUBrf7GMMaS+HPGx8nPI0x3gaw0eu0v6SpdiS5OL2M0RJdnGG7x2Nte3iCPg2Vm1Z/ouZ/DtTxDqt50togUO9YdLpsqg0c9nkZtCcheP/oFLoJgUqVZ5v8Cgle38t0rfESASKyXCO/1/v+HGQcYelF0jPshBFGPa7feY2pWtLIfPFNzTN81ncKr0EH8OA=" Oct 25 20:02:33 volumio go-librespot[14393]: time="2025-10-25T20:02:33+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 25 20:02:33 volumio go-librespot[14393]: time="2025-10-25T20:02:33+01:00" level=debug msg="completed keyexchange" Oct 25 20:02:33 volumio go-librespot[14393]: time="2025-10-25T20:02:33+01:00" level=debug msg="completed challenge" Oct 25 20:02:33 volumio go-librespot[14393]: time="2025-10-25T20:02: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 25 20:02:33 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 25 20:02:33 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 25 20:02:35 volumio volumio[13967]: info: Initializing connection to go-librespot Websocket Oct 25 20:02:35 volumio volumio[13967]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 25 20:02:36 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 528. Oct 25 20:02:36 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 25 20:02:36 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 25 20:02:36 volumio go-librespot[14400]: go-librespot daemon starting... Oct 25 20:02:36 volumio go-librespot[14401]: time="2025-10-25T20:02:36+01:00" level=info msg="running go-librespot 0.4.0" Oct 25 20:02:36 volumio go-librespot[14401]: time="2025-10-25T20:02:36+01:00" level=debug msg="app state loaded" Oct 25 20:02:36 volumio go-librespot[14401]: time="2025-10-25T20:02:36+01:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 25 20:02:36 volumio go-librespot[14401]: time="2025-10-25T20:02: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-gae2.spotify.com:80]" Oct 25 20:02:36 volumio go-librespot[14401]: time="2025-10-25T20:02:36+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 25 20:02:36 volumio go-librespot[14401]: time="2025-10-25T20:02:36+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 25 20:02:36 volumio go-librespot[14401]: time="2025-10-25T20:02:36+01:00" level=info msg="zeroconf server listening on port 42365" Oct 25 20:02:36 volumio go-librespot[14401]: time="2025-10-25T20:02:36+01:00" level=debug msg="obtained new client token: AADGmAljstX0VXZYFs3QuUI8Bb2vVkmYmGklLisy4fcuN7ShoX3k2TNd2wwzl66UQ39mlu0MW28pEHiiSIIp3r6G6Ovp8carYG7Fg6IXv7IvjIBW2A2eEsLw5WFfA0sTIgmcTeDMBSz6bHBev22qAw2MLv4l6FGR5GfK7TWq8E0HRPapykR+322FVq1GaZkeTZJEnm+endcRvmPXpqyrCybbe1P/wOLoeubliEzEawFrQ0bu0n9loFE=" Oct 25 20:02:36 volumio go-librespot[14401]: time="2025-10-25T20:02:36+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 25 20:02:36 volumio go-librespot[14401]: time="2025-10-25T20:02:36+01:00" level=debug msg="completed keyexchange" Oct 25 20:02:36 volumio go-librespot[14401]: time="2025-10-25T20:02:36+01:00" level=debug msg="completed challenge" Oct 25 20:02:36 volumio go-librespot[14401]: time="2025-10-25T20:02: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 25 20:02:36 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 25 20:02:36 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 25 20:02:38 volumio volumio[13967]: info: BOOT COMPLETED Oct 25 20:02:38 volumio volumio[13967]: info: Initializing connection to go-librespot Websocket Oct 25 20:02:38 volumio volumio[13967]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 25 20:02:40 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 529. Oct 25 20:02:40 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 25 20:02:40 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 25 20:02:40 volumio go-librespot[14423]: go-librespot daemon starting... Oct 25 20:02:40 volumio go-librespot[14424]: time="2025-10-25T20:02:40+01:00" level=info msg="running go-librespot 0.4.0" Oct 25 20:02:40 volumio go-librespot[14424]: time="2025-10-25T20:02:40+01:00" level=debug msg="app state loaded" Oct 25 20:02:40 volumio go-librespot[14424]: time="2025-10-25T20:02:40+01:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 25 20:02:40 volumio go-librespot[14424]: time="2025-10-25T20:02: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-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Oct 25 20:02:40 volumio go-librespot[14424]: time="2025-10-25T20:02:40+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 25 20:02:40 volumio go-librespot[14424]: time="2025-10-25T20:02:40+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 25 20:02:40 volumio go-librespot[14424]: time="2025-10-25T20:02:40+01:00" level=info msg="zeroconf server listening on port 42435" Oct 25 20:02:40 volumio go-librespot[14424]: time="2025-10-25T20:02:40+01:00" level=debug msg="obtained new client token: AAA76u1HgKV5WmgNh5CuUten45M7r+HQxuGq6aEqj8tahyZroY0yPtStuLhESBvGjZG39XJE99aAvDAVCxGdSIwMSKmfPUpjIxGJ1qrO0gcpgCAtupPtD7xLp9j1ilPoGfOESMKB8uKlhmlytLMKFmVvYwbFCWczhJh/GFy39TqnITqMpv45yPdh4/cSh98j0h4qQn2p/jgsGBkGIrW8SNokFmLfJilI/Czym8E4+x0Ph6mLZhMBbOw=" Oct 25 20:02:40 volumio go-librespot[14424]: time="2025-10-25T20:02:40+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 25 20:02:40 volumio go-librespot[14424]: time="2025-10-25T20:02:40+01:00" level=debug msg="completed keyexchange" Oct 25 20:02:40 volumio go-librespot[14424]: time="2025-10-25T20:02:40+01:00" level=debug msg="completed challenge" Oct 25 20:02:40 volumio go-librespot[14424]: time="2025-10-25T20:02: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: BadCredentials " Oct 25 20:02:40 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 25 20:02:40 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 25 20:02:41 volumio volumio[13967]: info: Initializing connection to go-librespot Websocket Oct 25 20:02:41 volumio volumio[13967]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 25 20:02:43 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 530. Oct 25 20:02:43 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 25 20:02:43 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 25 20:02:43 volumio go-librespot[14431]: go-librespot daemon starting... Oct 25 20:02:43 volumio go-librespot[14432]: time="2025-10-25T20:02:43+01:00" level=info msg="running go-librespot 0.4.0" Oct 25 20:02:43 volumio go-librespot[14432]: time="2025-10-25T20:02:43+01:00" level=debug msg="app state loaded" Oct 25 20:02:43 volumio go-librespot[14432]: time="2025-10-25T20:02:43+01:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 25 20:02:43 volumio go-librespot[14432]: time="2025-10-25T20:02:43+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Oct 25 20:02:43 volumio go-librespot[14432]: time="2025-10-25T20:02:43+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 25 20:02:43 volumio go-librespot[14432]: time="2025-10-25T20:02:43+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 25 20:02:43 volumio go-librespot[14432]: time="2025-10-25T20:02:43+01:00" level=info msg="zeroconf server listening on port 37001" Oct 25 20:02:43 volumio go-librespot[14432]: time="2025-10-25T20:02:43+01:00" level=debug msg="obtained new client token: AAB2RlabYnc0Z1+rnVru5JAmYvSsMcoEoUIHyKKMUShSJ3WCJawqg46gF4SYAFSi5kObkQRsuV96+Z57TvRFyWNjR89cNX4kBOh7AxN/4tp+a2AfO2tG62wjyOslDz9vMXsMnXB0YmXFVXySkHpsZmiRtNYzAofEU9R+v/C5SDb9V1iud0DxuZQ8uKFtZvHToU9KqRXoY/2NvBCFukoENgRXr68zt9sSeo/Yty1qL8fIZZNJy+rAp7Q=" Oct 25 20:02:43 volumio go-librespot[14432]: time="2025-10-25T20:02:43+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 25 20:02:43 volumio go-librespot[14432]: time="2025-10-25T20:02:43+01:00" level=debug msg="completed keyexchange" Oct 25 20:02:43 volumio go-librespot[14432]: time="2025-10-25T20:02:43+01:00" level=debug msg="completed challenge" Oct 25 20:02:43 volumio go-librespot[14432]: time="2025-10-25T20:02: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 25 20:02:43 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 25 20:02:43 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 25 20:02:44 volumio volumio[13967]: info: Initializing connection to go-librespot Websocket Oct 25 20:02:44 volumio volumio[13967]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 25 20:02:47 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 531. Oct 25 20:02:47 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 25 20:02:47 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 25 20:02:47 volumio go-librespot[14442]: go-librespot daemon starting... Oct 25 20:02:47 volumio go-librespot[14443]: time="2025-10-25T20:02:47+01:00" level=info msg="running go-librespot 0.4.0" Oct 25 20:02:47 volumio go-librespot[14443]: time="2025-10-25T20:02:47+01:00" level=debug msg="app state loaded" Oct 25 20:02:47 volumio go-librespot[14443]: time="2025-10-25T20:02:47+01:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 25 20:02:47 volumio go-librespot[14443]: time="2025-10-25T20:02: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-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Oct 25 20:02:47 volumio go-librespot[14443]: time="2025-10-25T20:02:47+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 25 20:02:47 volumio go-librespot[14443]: time="2025-10-25T20:02:47+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 25 20:02:47 volumio go-librespot[14443]: time="2025-10-25T20:02:47+01:00" level=info msg="zeroconf server listening on port 38333" Oct 25 20:02:47 volumio go-librespot[14443]: time="2025-10-25T20:02:47+01:00" level=debug msg="obtained new client token: AAC8zYDgZGWCsAa0i3AMA/7XacstBn4BQVsXftLhXsUI8aZrzj/TzlhKdBRs3PzNHiqMdaBvteUJz0IE9jA5ogDnlRVi08F32FsIVHJjqYvbQ/fujACRTpNMHOkND6z7yFH92/htiAEYF+WKMmEOnsHUQZGudUOQIhKHnC7LReAH8yV1ojPcvyOLBpMZ5OS1aofhkOc7GhXr5L0b6IiY/m9lvP/RF7XOfQV5Pdj3uDxuLVeDORSpZiU=" Oct 25 20:02:47 volumio go-librespot[14443]: time="2025-10-25T20:02:47+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 25 20:02:47 volumio go-librespot[14443]: time="2025-10-25T20:02:47+01:00" level=debug msg="completed keyexchange" Oct 25 20:02:47 volumio go-librespot[14443]: time="2025-10-25T20:02:47+01:00" level=debug msg="completed challenge" Oct 25 20:02:47 volumio go-librespot[14443]: time="2025-10-25T20:02: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 25 20:02:47 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 25 20:02:47 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 25 20:02:47 volumio volumio[13967]: info: Initializing connection to go-librespot Websocket Oct 25 20:02:47 volumio volumio[13967]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 25 20:02:50 volumio volumio[13967]: info: Initializing connection to go-librespot Websocket Oct 25 20:02:50 volumio volumio[13967]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 25 20:02:50 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 532. Oct 25 20:02:50 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 25 20:02:50 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 25 20:02:50 volumio go-librespot[14464]: go-librespot daemon starting... Oct 25 20:02:50 volumio go-librespot[14465]: time="2025-10-25T20:02:50+01:00" level=info msg="running go-librespot 0.4.0" Oct 25 20:02:50 volumio go-librespot[14465]: time="2025-10-25T20:02:50+01:00" level=debug msg="app state loaded" Oct 25 20:02:50 volumio go-librespot[14465]: time="2025-10-25T20:02:50+01:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 25 20:02:50 volumio go-librespot[14465]: time="2025-10-25T20:02: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-gew4.spotify.com:80]" Oct 25 20:02:50 volumio go-librespot[14465]: time="2025-10-25T20:02:50+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 25 20:02:50 volumio go-librespot[14465]: time="2025-10-25T20:02:50+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 25 20:02:50 volumio go-librespot[14465]: time="2025-10-25T20:02:50+01:00" level=info msg="zeroconf server listening on port 46157" Oct 25 20:02:50 volumio go-librespot[14465]: time="2025-10-25T20:02:50+01:00" level=debug msg="obtained new client token: AABK/BpPRNDcibLmMr0qcNToABu87GlCYCkP6IqMEwS42D8XpbJXWpIK/EwEj6gHSdbnhvWujvZvQXh0zWNRBpy9e/fQxNnBQ9g4/3X30gXrvozmNQ79FwjSJxoDWtsls3+LoZIAShaMldEEhvpxFe1oA5LTHyYy0HGcOot1HaYiLJ9zE80JL9PsdxrWvPOQQ4P5bEHPB4aEPaG0nu68sGtvhQK/J7U8R9TyBhYQ8c7Qkg3RxDjVRIU=" Oct 25 20:02:50 volumio go-librespot[14465]: time="2025-10-25T20:02:50+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 25 20:02:50 volumio go-librespot[14465]: time="2025-10-25T20:02:50+01:00" level=debug msg="completed keyexchange" Oct 25 20:02:50 volumio go-librespot[14465]: time="2025-10-25T20:02:50+01:00" level=debug msg="completed challenge" Oct 25 20:02:50 volumio go-librespot[14465]: time="2025-10-25T20:02: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 25 20:02:50 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 25 20:02:50 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 25 20:02:53 volumio volumio[13967]: info: Initializing connection to go-librespot Websocket Oct 25 20:02:53 volumio volumio[13967]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 25 20:02:53 volumio systemd[1]: Starting setdatetime-helper.service - Time Synchronization Helper Service... Oct 25 20:02:53 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 533. Oct 25 20:02:53 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 25 20:02:53 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 25 20:02:53 volumio go-librespot[14484]: go-librespot daemon starting... Oct 25 20:02:53 volumio go-librespot[14485]: time="2025-10-25T20:02:53+01:00" level=info msg="running go-librespot 0.4.0" Oct 25 20:02:53 volumio go-librespot[14485]: time="2025-10-25T20:02:53+01:00" level=debug msg="app state loaded" Oct 25 20:02:53 volumio go-librespot[14485]: time="2025-10-25T20:02:53+01:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 25 20:02:54 volumio go-librespot[14485]: time="2025-10-25T20:02: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 25 20:02:54 volumio go-librespot[14485]: time="2025-10-25T20:02: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 25 20:02:54 volumio go-librespot[14485]: time="2025-10-25T20:02: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 25 20:02:54 volumio go-librespot[14485]: time="2025-10-25T20:02:54+01:00" level=info msg="zeroconf server listening on port 37191" Oct 25 20:02:54 volumio go-librespot[14485]: time="2025-10-25T20:02:54+01:00" level=debug msg="obtained new client token: AADezyxUBjyqcOVp4L7HqLsa5e6P1uv3dy/VyuMQKUxux1Ivzvn+DtqOz6FUKxvTwK0vsxXHP82eJftQzoUK+m15dltfHsQeM0knGICMI7J8YOclta/k8xkn4zJJPKQ0YUV5GE2us3esK1Oakva+VLtKdZzpA3P+HXinMBwEoGPhB0X3WOweeEobB53OS5LcQ2x4vJvzxY0yC1Bm2Wb279c1BpXbeR6cdU2AEQu5aIOQw4kah0Dt" Oct 25 20:02:54 volumio go-librespot[14485]: time="2025-10-25T20:02:54+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 25 20:02:54 volumio go-librespot[14485]: time="2025-10-25T20:02:54+01:00" level=debug msg="completed keyexchange" Oct 25 20:02:54 volumio go-librespot[14485]: time="2025-10-25T20:02:54+01:00" level=debug msg="completed challenge" Oct 25 20:02:54 volumio go-librespot[14485]: time="2025-10-25T20:02: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 25 20:02:54 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 25 20:02:54 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 25 20:02:54 volumio systemd[1]: setdatetime-helper.service: Deactivated successfully. Oct 25 20:02:54 volumio systemd[1]: Finished setdatetime-helper.service - Time Synchronization Helper Service. Oct 25 20:02:56 volumio volumio[13967]: info: Initializing connection to go-librespot Websocket Oct 25 20:02:56 volumio volumio[13967]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 25 20:02:57 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 534. Oct 25 20:02:57 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 25 20:02:57 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 25 20:02:57 volumio go-librespot[14506]: go-librespot daemon starting... Oct 25 20:02:57 volumio go-librespot[14507]: time="2025-10-25T20:02:57+01:00" level=info msg="running go-librespot 0.4.0" Oct 25 20:02:57 volumio go-librespot[14507]: time="2025-10-25T20:02:57+01:00" level=debug msg="app state loaded" Oct 25 20:02:57 volumio go-librespot[14507]: time="2025-10-25T20:02:57+01:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 25 20:02:57 volumio go-librespot[14507]: time="2025-10-25T20:02: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 25 20:02:57 volumio go-librespot[14507]: time="2025-10-25T20:02: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 25 20:02:57 volumio go-librespot[14507]: time="2025-10-25T20:02: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 25 20:02:57 volumio go-librespot[14507]: time="2025-10-25T20:02:57+01:00" level=info msg="zeroconf server listening on port 45603" Oct 25 20:02:57 volumio go-librespot[14507]: time="2025-10-25T20:02:57+01:00" level=debug msg="obtained new client token: AADyf70j1mCsN2vkGm+JiGCN5Gpypm3LaWgXtmZNdTFf9XAnF9djdrqGIXEFeNmOz1R9DkLwjQh2MTnH75MYYkv2FQj80kPR56gGv42sljLe5QX7ykU4+aaPeqqyGBc5QoIJgtJbP/fmC/qWazsJF+nidGvR7i/p7nbMvHsAyNZH3INW6uy57LeLDD3Z8yg9AZdVMJRL03L3Cg+qUsb6ptYuHflicoYjmGwY//HTRUw98gK/5iqhm30=" Oct 25 20:02:57 volumio go-librespot[14507]: time="2025-10-25T20:02:57+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 25 20:02:57 volumio go-librespot[14507]: time="2025-10-25T20:02:57+01:00" level=debug msg="completed keyexchange" Oct 25 20:02:57 volumio go-librespot[14507]: time="2025-10-25T20:02:57+01:00" level=debug msg="completed challenge" Oct 25 20:02:57 volumio go-librespot[14507]: time="2025-10-25T20:02: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 25 20:02:57 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 25 20:02:57 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 25 20:02:59 volumio volumio[13967]: info: Initializing connection to go-librespot Websocket Oct 25 20:02:59 volumio volumio[13967]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 25 20:03:00 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 535. Oct 25 20:03:00 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 25 20:03:00 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 25 20:03:00 volumio go-librespot[14528]: go-librespot daemon starting... Oct 25 20:03:00 volumio go-librespot[14529]: time="2025-10-25T20:03:00+01:00" level=info msg="running go-librespot 0.4.0" Oct 25 20:03:00 volumio go-librespot[14529]: time="2025-10-25T20:03:00+01:00" level=debug msg="app state loaded" Oct 25 20:03:00 volumio go-librespot[14529]: time="2025-10-25T20:03:00+01:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 25 20:03:01 volumio go-librespot[14529]: time="2025-10-25T20:03:01+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 25 20:03:01 volumio go-librespot[14529]: time="2025-10-25T20:03:01+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 25 20:03:01 volumio go-librespot[14529]: time="2025-10-25T20:03:01+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 25 20:03:01 volumio go-librespot[14529]: time="2025-10-25T20:03:01+01:00" level=info msg="zeroconf server listening on port 38017" Oct 25 20:03:01 volumio go-librespot[14529]: time="2025-10-25T20:03:01+01:00" level=debug msg="obtained new client token: AACXaG6ljJBR/K/dqz+sqSBSn0Ju6XqTQi/iAHrKdTShp6eC1CMTmwf6kEQZ3qYKJNe6k15ijVpso0q3mVYl6NjREzRHZK3GtkAdi8lGaP99Wlr+AxUD3cYtUAcDp6xtBK9NXcf6Imn5x1gcuycZT4tJMQ5Ho4sZ3/cljeEHOHrG/TJE1G7raxYZE0z8Mp2QAdOxqgTjQ7a6HiFAkczKo5ZV1FnYkips8Od9pzNXIGVKUCcmHFnG" Oct 25 20:03:01 volumio go-librespot[14529]: time="2025-10-25T20:03:01+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 25 20:03:01 volumio go-librespot[14529]: time="2025-10-25T20:03:01+01:00" level=debug msg="completed keyexchange" Oct 25 20:03:01 volumio go-librespot[14529]: time="2025-10-25T20:03:01+01:00" level=debug msg="completed challenge" Oct 25 20:03:01 volumio go-librespot[14529]: time="2025-10-25T20:03:01+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 25 20:03:01 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 25 20:03:01 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 25 20:03:02 volumio volumio[13967]: info: Initializing connection to go-librespot Websocket Oct 25 20:03:02 volumio volumio[13967]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 25 20:03:04 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 536. Oct 25 20:03:04 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 25 20:03:04 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 25 20:03:04 volumio go-librespot[14536]: go-librespot daemon starting... Oct 25 20:03:04 volumio go-librespot[14537]: time="2025-10-25T20:03:04+01:00" level=info msg="running go-librespot 0.4.0" Oct 25 20:03:04 volumio go-librespot[14537]: time="2025-10-25T20:03:04+01:00" level=debug msg="app state loaded" Oct 25 20:03:04 volumio go-librespot[14537]: time="2025-10-25T20:03:04+01:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 25 20:03:04 volumio go-librespot[14537]: time="2025-10-25T20:03: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 25 20:03:04 volumio go-librespot[14537]: time="2025-10-25T20:03: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 25 20:03:04 volumio go-librespot[14537]: time="2025-10-25T20:03: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 25 20:03:04 volumio go-librespot[14537]: time="2025-10-25T20:03:04+01:00" level=info msg="zeroconf server listening on port 45097" Oct 25 20:03:04 volumio go-librespot[14537]: time="2025-10-25T20:03:04+01:00" level=debug msg="obtained new client token: AABTCUHvUKIsAbykq0FbX3UDUhtiRx8CQg/PSLpRlGn45THy72qL90+ecf8hGWlS2VhTDnZuGMO8YZOmPnbVVvO142IWktZHLot3h9ypaxLtUtqEMSY78qYMmLa6EPsce0QeB1ZIxvBVu8CIPqZw7rtq9qVdhcMBBxBCnwoyIq84CGYLE3R31s9ApFChqLdFWb5CnUhbjcILw/ZxX2DU8F4TBtU+nDp52CuizM8DzKvcVbjkOz0/QsU=" Oct 25 20:03:04 volumio go-librespot[14537]: time="2025-10-25T20:03:04+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 25 20:03:04 volumio go-librespot[14537]: time="2025-10-25T20:03:04+01:00" level=debug msg="completed keyexchange" Oct 25 20:03:04 volumio go-librespot[14537]: time="2025-10-25T20:03:04+01:00" level=debug msg="completed challenge" Oct 25 20:03:04 volumio go-librespot[14537]: time="2025-10-25T20:03: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 25 20:03:04 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 25 20:03:04 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 25 20:03:05 volumio volumio[13967]: info: Initializing connection to go-librespot Websocket Oct 25 20:03:05 volumio volumio[13967]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 25 20:03:07 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 537. Oct 25 20:03:07 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 25 20:03:07 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 25 20:03:07 volumio go-librespot[14547]: go-librespot daemon starting... Oct 25 20:03:07 volumio go-librespot[14548]: time="2025-10-25T20:03:07+01:00" level=info msg="running go-librespot 0.4.0" Oct 25 20:03:07 volumio go-librespot[14548]: time="2025-10-25T20:03:07+01:00" level=debug msg="app state loaded" Oct 25 20:03:07 volumio go-librespot[14548]: time="2025-10-25T20:03:07+01:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 25 20:03:08 volumio go-librespot[14548]: time="2025-10-25T20:03: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-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Oct 25 20:03:08 volumio go-librespot[14548]: time="2025-10-25T20:03:08+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 25 20:03:08 volumio go-librespot[14548]: time="2025-10-25T20:03:08+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 25 20:03:08 volumio go-librespot[14548]: time="2025-10-25T20:03:08+01:00" level=info msg="zeroconf server listening on port 42813" Oct 25 20:03:08 volumio go-librespot[14548]: time="2025-10-25T20:03:08+01:00" level=debug msg="obtained new client token: AAC0ecejn3NAgYglwui9yrdUw+um+Ge93WKoSBStykBX9ps3Ty4ZoowtP6BK5h0XljpKYtGNp0KsxNW5Exxrulz3JZYndWYP5U33/X55GGrrXpySW0DT0dIrkZdkXenld+q2zcALF57XMXNiW4H82Qiy52/dNnfooNLmkrzUE4flvHQUSphhnd2ekudfPtPHSbTJ6CufYl/t6VmFAP7yBIACC+4hGVUm5fYXQm0bmIvVeiv3FeZG" Oct 25 20:03:08 volumio go-librespot[14548]: time="2025-10-25T20:03:08+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 25 20:03:08 volumio go-librespot[14548]: time="2025-10-25T20:03:08+01:00" level=debug msg="connected to ap-gew1.spotify.com:443" Oct 25 20:03:08 volumio go-librespot[14548]: time="2025-10-25T20:03:08+01:00" level=debug msg="completed keyexchange" Oct 25 20:03:08 volumio go-librespot[14548]: time="2025-10-25T20:03:08+01:00" level=debug msg="completed challenge" Oct 25 20:03:08 volumio go-librespot[14548]: time="2025-10-25T20:03: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 25 20:03:08 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 25 20:03:08 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 25 20:03:08 volumio volumio[13967]: info: Initializing connection to go-librespot Websocket Oct 25 20:03:08 volumio volumio[13967]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 25 20:03:11 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 538. Oct 25 20:03:11 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 25 20:03:11 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 25 20:03:11 volumio go-librespot[14569]: go-librespot daemon starting... Oct 25 20:03:11 volumio go-librespot[14570]: time="2025-10-25T20:03:11+01:00" level=info msg="running go-librespot 0.4.0" Oct 25 20:03:11 volumio go-librespot[14570]: time="2025-10-25T20:03:11+01:00" level=debug msg="app state loaded" Oct 25 20:03:11 volumio go-librespot[14570]: time="2025-10-25T20:03:11+01:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 25 20:03:11 volumio go-librespot[14570]: time="2025-10-25T20:03:11+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Oct 25 20:03:11 volumio go-librespot[14570]: time="2025-10-25T20:03:11+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 25 20:03:11 volumio go-librespot[14570]: time="2025-10-25T20:03:11+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 25 20:03:11 volumio go-librespot[14570]: time="2025-10-25T20:03:11+01:00" level=info msg="zeroconf server listening on port 37429" Oct 25 20:03:11 volumio volumio[13967]: info: Initializing connection to go-librespot Websocket Oct 25 20:03:11 volumio go-librespot[14570]: time="2025-10-25T20:03:11+01:00" level=debug msg="new websocket client" Oct 25 20:03:11 volumio volumio[13967]: info: Connection to go-librespot Websocket established Oct 25 20:03:11 volumio go-librespot[14570]: time="2025-10-25T20:03:11+01:00" level=debug msg="obtained new client token: AAATupYZVSqtrMwQRSLbWCdPgSLcnn8j6wJDRKwOWPR4t9XCQbIzPoMJF63ncfRxQDGagln0xs9AII3VnQDtw8iEEt7OXIZdF1iIF4SL3Zb46iN0Hm0CLxfe2JjMiKhB44pY0brKtb0bBk33ZiGX2I9UQwk6Iy9EXHZnzPg276w4035baKnM+Z+elehdlRHz/3lYfIb6RIykqMbLWSkWSwMeRDJfxWE8tYlI3Q5FsGpEGZdCviTnOb4=" Oct 25 20:03:11 volumio go-librespot[14570]: time="2025-10-25T20:03:11+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 25 20:03:11 volumio go-librespot[14570]: time="2025-10-25T20:03:11+01:00" level=debug msg="completed keyexchange" Oct 25 20:03:11 volumio go-librespot[14570]: time="2025-10-25T20:03:11+01:00" level=debug msg="completed challenge" Oct 25 20:03:11 volumio go-librespot[14570]: time="2025-10-25T20:03: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 25 20:03:11 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 25 20:03:11 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 25 20:03:11 volumio volumio[13967]: info: Connection to go-librespot Websocket closed Oct 25 20:03:14 volumio volumio[13967]: info: Getting Spotify volume Oct 25 20:03:14 volumio volumio[13967]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 25 20:03:14 volumio volumio[13967]: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 25 20:03:14 volumio volumio[13967]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Oct 25 20:03:14 volumio volumio[13967]: errno: -111, Oct 25 20:03:14 volumio volumio[13967]: code: 'ECONNREFUSED', Oct 25 20:03:14 volumio volumio[13967]: syscall: 'connect', Oct 25 20:03:14 volumio volumio[13967]: address: '127.0.0.1', Oct 25 20:03:14 volumio volumio[13967]: port: 9879, Oct 25 20:03:14 volumio volumio[13967]: response: undefined Oct 25 20:03:14 volumio volumio[13967]: } Oct 25 20:03:14 volumio volumio[13967]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 25 20:03:14 volumio sudo[14592]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-10-25 20:02' Oct 25 20:03:14 volumio sudo[14592]: 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"