Nov 05 06:15:00 volumio volumio[2864]: info: Loading plugin "network"... Nov 05 06:15:00 volumio volumio[2864]: info: Refreshing Cached IP Addresses Nov 05 06:15:00 volumio sudo[2895]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Nov 05 06:15:00 volumio sudo[2895]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 05 06:15:00 volumio sudo[2895]: pam_unix(sudo:session): session closed for user root Nov 05 06:15:00 volumio volumio[2864]: info: Loading plugin "services"... Nov 05 06:15:00 volumio sudo[2897]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Nov 05 06:15:00 volumio sudo[2897]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 05 06:15:00 volumio volumio[2864]: info: Loading plugin "alsa_controller"... Nov 05 06:15:00 volumio sudo[2897]: pam_unix(sudo:session): session closed for user root Nov 05 06:15:00 volumio volumio[2864]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Nov 05 06:15:00 volumio volumio[2864]: info: Loading plugin "wizard"... Nov 05 06:15:00 volumio volumio[2864]: info: Loading plugin "networkfs"... Nov 05 06:15:00 volumio volumio[2864]: info: Cannot mount NAS NAS at system boot, trial number 1 ,retrying in 5 seconds Nov 05 06:15:00 volumio volumio[2864]: info: Starting Udev Watcher for removable devices Nov 05 06:15:00 volumio volumio[2864]: info: Ignoring mount for partition: boot Nov 05 06:15:00 volumio volumio[2864]: info: Ignoring mount for partition: volumio Nov 05 06:15:00 volumio volumio[2864]: info: Ignoring mount for partition: volumio_data Nov 05 06:15:00 volumio volumio[2864]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Nov 05 06:15:00 volumio volumio[2864]: info: Loading plugin "volumio_command_line_client"... Nov 05 06:15:00 volumio volumio[2864]: info: Loading plugin "upnp"... Nov 05 06:15:00 volumio volumio[2864]: info: [1762323300057] Starting Upmpd Daemon Nov 05 06:15:00 volumio volumio[2864]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Nov 05 06:15:00 volumio volumio[2864]: info: Loading plugin "my_music"... Nov 05 06:15:00 volumio volumio[2864]: info: Loading plugin "mpd"... Nov 05 06:15:00 volumio volumio[2864]: info: Loading plugin "upnp_browser"... Nov 05 06:15:00 volumio volumio[2864]: info: Loading plugin "alarm-clock"... Nov 05 06:15:00 volumio volumio[2864]: info: Loading plugin "airplay_emulation"... Nov 05 06:15:00 volumio volumio[2864]: info: Starting Shairport Sync Nov 05 06:15:00 volumio volumio[2864]: info: Loading plugin "last_100"... Nov 05 06:15:00 volumio volumio[2864]: info: Loading plugin "webradio"... Nov 05 06:15:00 volumio volumio[2864]: info: Loading plugin "i2s_dacs"... Nov 05 06:15:00 volumio volumio[2864]: info: I2S DAC not set, start Auto-detection Nov 05 06:15:00 volumio volumio[2864]: info: Loading plugin "volumiodiscovery"... Nov 05 06:15:00 volumio volumio[2864]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Nov 05 06:15:00 volumio node[2864]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Nov 05 06:15:00 volumio volumio[2864]: *** WARNING *** Please fix your application to use the native API of Avahi! Nov 05 06:15:00 volumio node[2864]: *** WARNING *** Please fix your application to use the native API of Avahi! Nov 05 06:15:00 volumio volumio[2864]: *** WARNING *** For more information see Nov 05 06:15:00 volumio node[2864]: *** WARNING *** For more information see Nov 05 06:15:00 volumio volumio[2864]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Nov 05 06:15:00 volumio node[2864]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Nov 05 06:15:00 volumio volumio[2864]: *** WARNING *** Please fix your application to use the native API of Avahi! Nov 05 06:15:00 volumio node[2864]: *** WARNING *** Please fix your application to use the native API of Avahi! Nov 05 06:15:00 volumio volumio[2864]: *** WARNING *** For more information see Nov 05 06:15:00 volumio node[2864]: *** WARNING *** For more information see Nov 05 06:15:00 volumio volumio[2864]: info: Applying required configuration parameters for plugin volumiodiscovery Nov 05 06:15:00 volumio volumio[2864]: info: Discovery: Started advertising with name: Volumio Nov 05 06:15:00 volumio volumio[2864]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Nov 05 06:15:00 volumio volumio[2864]: info: Loading plugin "spop"... Nov 05 06:15:00 volumio volumio[2864]: info: Loading plugin "ytcr"... Nov 05 06:15:01 volumio volumio[2864]: info: Loading plugin "outputs"... Nov 05 06:15:01 volumio volumio[2864]: info: Loading plugin "albumart"... Nov 05 06:15:01 volumio volumio[2864]: info: Plugin example_plugin is not enabled Nov 05 06:15:01 volumio volumio[2864]: info: Loading plugin "inputs"... Nov 05 06:15:01 volumio volumio[2864]: info: Loading plugin "updater_comm"... Nov 05 06:15:01 volumio volumio[2864]: info: Plugin mpdemulation is not enabled Nov 05 06:15:01 volumio volumio[2864]: info: Loading plugin "rest_api"... Nov 05 06:15:01 volumio volumio[2864]: info: Loading plugin "websocket"... Nov 05 06:15:01 volumio volumio[2864]: info: Starting Socket.io Server version 1.7.4 Nov 05 06:15:01 volumio volumio[2864]: info: Loading plugin "Systeminfo"... Nov 05 06:15:01 volumio volumio[2864]: info: Loading i18n strings for locale en Nov 05 06:15:01 volumio volumio[2864]: Updating browse sources language Nov 05 06:15:01 volumio volumio[2864]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 05 06:15:01 volumio volumio[2927]: Forking 3 albumart workers Nov 05 06:15:01 volumio volumio[2864]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Nov 05 06:15:01 volumio volumio[2864]: info: CoreCommandRouter::initPlayerControls Nov 05 06:15:01 volumio volumio[2864]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 05 06:15:01 volumio volumio[2864]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 05 06:15:01 volumio volumio[2864]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 05 06:15:01 volumio volumio[2864]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 05 06:15:01 volumio volumio[2864]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 05 06:15:01 volumio volumio[2864]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 05 06:15:01 volumio volumio[2864]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 05 06:15:01 volumio volumio[2864]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 05 06:15:01 volumio volumio[2864]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Nov 05 06:15:01 volumio volumio[2864]: Express server listening on port 3000 Nov 05 06:15:01 volumio volumio[2864]: [Metrics] WebUI: 1s 966.80ms Nov 05 06:15:01 volumio volumio[2864]: info: CoreStateMachine::resetVolumioState Nov 05 06:15:01 volumio volumio[2864]: info: CoreStateMachine::getcurrentVolume Nov 05 06:15:01 volumio volumio[2864]: info: CoreCommandRouter::volumioRetrievevolume Nov 05 06:15:01 volumio volumio[2864]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 05 06:15:01 volumio volumio[2864]: info: Cannot read play queue from file Nov 05 06:15:01 volumio volumio[2864]: info: Volumio Network Manager: Network status updated: 1 Nov 05 06:15:01 volumio volumio[2864]: info: VolumeController:: Volume=33 Mute =false Nov 05 06:15:01 volumio volumio[2864]: info: CoreStateMachine::pushState Nov 05 06:15:01 volumio volumio[2864]: info: CorePlayQueue::getTrack 0 Nov 05 06:15:01 volumio volumio[2864]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 05 06:15:01 volumio volumio[2864]: info: CoreCommandRouter::volumioPushState Nov 05 06:15:01 volumio volumio[2864]: info: CoreStateMachine::updateTrackBlock Nov 05 06:15:01 volumio volumio[2864]: info: CorePlayQueue::getTrackBlock Nov 05 06:15:01 volumio volumio[2864]: info: CoreCommandRouter::volumioRetrievevolume Nov 05 06:15:01 volumio volumio[2864]: info: CoreStateMachine::setRepeat null single undefined Nov 05 06:15:01 volumio volumio[2864]: info: CoreStateMachine::pushState Nov 05 06:15:01 volumio volumio[2864]: info: CorePlayQueue::getTrack 0 Nov 05 06:15:01 volumio volumio[2864]: info: CoreCommandRouter::volumioPushState Nov 05 06:15:01 volumio volumio[2864]: info: CoreStateMachine::setRandom null Nov 05 06:15:01 volumio volumio[2864]: info: CoreStateMachine::pushState Nov 05 06:15:01 volumio volumio[2864]: info: CorePlayQueue::getTrack 0 Nov 05 06:15:01 volumio volumio[2864]: info: CoreCommandRouter::volumioPushState Nov 05 06:15:01 volumio volumio[2864]: info: Setting Device type: Raspberry PI Nov 05 06:15:01 volumio volumio[2864]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Nov 05 06:15:01 volumio volumio[2864]: info: USB Boot Capable - System SBC Revision found in cpuinfo: b04170 Nov 05 06:15:01 volumio volumio[2864]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Nov 05 06:15:01 volumio volumio[2864]: info: VolumeController:: Volume=33 Mute =false Nov 05 06:15:01 volumio volumio[2864]: info: CoreStateMachine::pushState Nov 05 06:15:01 volumio volumio[2864]: info: CorePlayQueue::getTrack 0 Nov 05 06:15:01 volumio volumio[2864]: info: CoreCommandRouter::volumioPushState Nov 05 06:15:01 volumio volumio[2864]: info: Discovery: adding 70853f74-8210-4683-a3fa-e1217517bd40 Nov 05 06:15:01 volumio volumio[2864]: info: Discovery: Found device Volumio Nov 05 06:15:01 volumio volumio[2864]: info: CoreCommandRouter::volumioGetState Nov 05 06:15:01 volumio volumio[2864]: info: CorePlayQueue::getTrack 0 Nov 05 06:15:01 volumio volumio[2864]: info: Discovery: this is already registered, 70853f74-8210-4683-a3fa-e1217517bd40 Nov 05 06:15:01 volumio volumio[2864]: info: Discovery: Found device Volumio Nov 05 06:15:01 volumio volumio[2864]: info: CoreCommandRouter::volumioGetState Nov 05 06:15:01 volumio volumio[2864]: info: CorePlayQueue::getTrack 0 Nov 05 06:15:01 volumio volumio[2864]: info: Completed loading Core Plugins Nov 05 06:15:01 volumio volumio[2864]: info: Preparing to generate the ALSA configuration file Nov 05 06:15:01 volumio volumio[2864]: info: Asound.conf file unchanged, so no further update is needed Nov 05 06:15:01 volumio volumio[2864]: info: Output device has changed, restarting MPD Nov 05 06:15:01 volumio volumio[2864]: info: Output device has changed, restarting Shairport Sync Nov 05 06:15:01 volumio volumio[2864]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 05 06:15:01 volumio volumio[2864]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 05 06:15:01 volumio sudo[2985]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Nov 05 06:15:01 volumio sudo[2985]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 05 06:15:01 volumio sudo[2985]: pam_unix(sudo:session): session closed for user root Nov 05 06:15:01 volumio sudo[2986]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Nov 05 06:15:01 volumio sudo[2986]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 05 06:15:01 volumio volumio[2864]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Nov 05 06:15:01 volumio volumio[2864]: info: ___________ START PLUGINS ___________ Nov 05 06:15:01 volumio volumio[2864]: info: ControllerMpd::onStart: Initializing MPD Nov 05 06:15:01 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Nov 05 06:15:01 volumio volumio[2864]: info: Creating MPD Configuration file Nov 05 06:15:01 volumio sudo[2994]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Nov 05 06:15:01 volumio volumio[2864]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Nov 05 06:15:01 volumio volumio[2864]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Nov 05 06:15:01 volumio volumio[2864]: info: [1762323301761] CoreMusicLibrary::Adding element Media Servers Nov 05 06:15:01 volumio volumio[2864]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 05 06:15:01 volumio sudo[2994]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 05 06:15:01 volumio systemd[1]: mpd.service: Deactivated successfully. Nov 05 06:15:01 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Nov 05 06:15:01 volumio systemd[1]: mpd.socket: Deactivated successfully. Nov 05 06:15:01 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Nov 05 06:15:01 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Nov 05 06:15:01 volumio sudo[2994]: pam_unix(sudo:session): session closed for user root Nov 05 06:15:01 volumio volumio[2864]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 05 06:15:01 volumio volumio[2864]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 05 06:15:01 volumio sudo[2996]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Nov 05 06:15:01 volumio sudo[2996]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 05 06:15:01 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Nov 05 06:15:01 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Nov 05 06:15:01 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 88. Nov 05 06:15:01 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Nov 05 06:15:01 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Nov 05 06:15:01 volumio go-librespot[3005]: go-librespot daemon starting... Nov 05 06:15:01 volumio volumio[2864]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Nov 05 06:15:01 volumio volumio[2864]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 05 06:15:01 volumio volumio[2864]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 05 06:15:01 volumio go-librespot[3006]: time="2025-11-05T06:15:01Z" level=info msg="running go-librespot 0.4.0" Nov 05 06:15:01 volumio go-librespot[3006]: time="2025-11-05T06:15:01Z" level=debug msg="app state loaded" Nov 05 06:15:01 volumio go-librespot[3006]: time="2025-11-05T06:15:01Z" level=info msg="api server listening on 127.0.0.1:9879" Nov 05 06:15:01 volumio volumio[2864]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Nov 05 06:15:01 volumio volumio[2864]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Nov 05 06:15:01 volumio volumio[2864]: info: [1762323301810] CoreMusicLibrary::Adding element Last_100 Nov 05 06:15:01 volumio volumio[2864]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 05 06:15:01 volumio volumio[2864]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Nov 05 06:15:01 volumio volumio[2864]: info: [1762323301813] CoreMusicLibrary::Adding element Webradio Nov 05 06:15:01 volumio volumio[2864]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 05 06:15:01 volumio systemd[1]: mpd.service: Deactivated successfully. Nov 05 06:15:01 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Nov 05 06:15:01 volumio systemd[1]: mpd.socket: Deactivated successfully. Nov 05 06:15:01 volumio volumio[2864]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Nov 05 06:15:01 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Nov 05 06:15:01 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Nov 05 06:15:01 volumio volumio[2864]: info: Initializing BBC Radios Nov 05 06:15:01 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Nov 05 06:15:01 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Nov 05 06:15:01 volumio sudo[3019]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Nov 05 06:15:01 volumio sudo[3019]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Nov 05 06:15:01 volumio volumio[2864]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Nov 05 06:15:01 volumio volumio[2864]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 05 06:15:01 volumio sudo[3019]: pam_unix(sudo:session): session closed for user root Nov 05 06:15:01 volumio volumio[2864]: info: Creating Spotify config file Nov 05 06:15:01 volumio volumio[2864]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 05 06:15:01 volumio go-librespot[3006]: time="2025-11-05T06:15:01Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Nov 05 06:15:01 volumio go-librespot[3006]: time="2025-11-05T06:15:01Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Nov 05 06:15:01 volumio go-librespot[3006]: time="2025-11-05T06:15:01Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Nov 05 06:15:01 volumio go-librespot[3006]: time="2025-11-05T06:15:01Z" level=info msg="zeroconf server listening on port 39991" Nov 05 06:15:01 volumio volumio[2938]: Starting albumart workers Nov 05 06:15:01 volumio volumio[2864]: info: Volumio Calling Home Nov 05 06:15:02 volumio go-librespot[3006]: time="2025-11-05T06:15:02Z" level=debug msg="obtained new client token: AABISJjqyWMu8LpS9M4Qpx/fTFtjMHMOoLQ0tqlIABmndabGwjZam5MTt3bni+nQoDM5Ky93lJ5VS7l7T8UEg8NI6oCe7AlFSKtquiRaAzPy8qmuc+IXADFIUdnydMkHmXhxZYY4lT3DvQTUW6ky/bpt+NSUVNkO4vcpFMa52niUTtqNK4XDGjOR9C57417Jg0i7+zYY5MiREfN67zA8GOyjUnK2exdTMdJD7saw0jfvDwlaGeL4cUc=" Nov 05 06:15:02 volumio go-librespot[3006]: time="2025-11-05T06:15:02Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Nov 05 06:15:02 volumio go-librespot[3006]: time="2025-11-05T06:15:02Z" level=debug msg="completed keyexchange" Nov 05 06:15:02 volumio go-librespot[3006]: time="2025-11-05T06:15:02Z" level=debug msg="completed challenge" Nov 05 06:15:02 volumio volumio[2937]: Starting albumart workers Nov 05 06:15:02 volumio volumio[2939]: Starting albumart workers Nov 05 06:15:02 volumio volumio[2864]: info: MPD Permissions set Nov 05 06:15:02 volumio volumio[2864]: info: MPD Permissions set Nov 05 06:15:02 volumio go-librespot[3006]: time="2025-11-05T06:15:02Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Nov 05 06:15:02 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 05 06:15:02 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 05 06:15:02 volumio volumio[2864]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 1 Nov 05 06:15:02 volumio volumio[2864]: info: Volumio called home Nov 05 06:15:02 volumio volumio[2864]: info: Spotify config file written Nov 05 06:15:02 volumio volumio[2864]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 05 06:15:02 volumio volumio[2864]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 05 06:15:02 volumio volumio[2864]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 05 06:15:02 volumio volumio[2864]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 05 06:15:02 volumio volumio[2864]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 05 06:15:02 volumio volumio[2864]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 05 06:15:02 volumio volumio[2864]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 05 06:15:02 volumio volumio[2864]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 05 06:15:02 volumio sudo[3038]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Nov 05 06:15:02 volumio sudo[3038]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 05 06:15:02 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Nov 05 06:15:02 volumio volumio[2864]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 05 06:15:02 volumio volumio[2864]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 05 06:15:02 volumio volumio[2864]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 05 06:15:02 volumio volumio[2864]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 05 06:15:02 volumio volumio[2864]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 05 06:15:02 volumio volumio[2864]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 05 06:15:02 volumio volumio[2864]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 05 06:15:02 volumio volumio[2864]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 05 06:15:02 volumio volumio[2864]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 05 06:15:02 volumio volumio[2864]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 05 06:15:02 volumio volumio[2864]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 05 06:15:02 volumio volumio[2864]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 05 06:15:02 volumio volumio[2864]: info: No need to fix Spotify hosts Nov 05 06:15:02 volumio go-librespot[3045]: go-librespot daemon starting... Nov 05 06:15:02 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Nov 05 06:15:02 volumio sudo[3038]: pam_unix(sudo:session): session closed for user root Nov 05 06:15:02 volumio go-librespot[3052]: time="2025-11-05T06:15:02Z" level=info msg="running go-librespot 0.4.0" Nov 05 06:15:02 volumio go-librespot[3052]: time="2025-11-05T06:15:02Z" level=debug msg="app state loaded" Nov 05 06:15:02 volumio go-librespot[3052]: time="2025-11-05T06:15:02Z" level=info msg="api server listening on 127.0.0.1:9879" Nov 05 06:15:02 volumio volumio[2864]: info: Starting Shairport Sync Nov 05 06:15:02 volumio volumio[2864]: info: Starting Shairport Sync Nov 05 06:15:02 volumio volumio[2864]: info: Starting Shairport Sync Nov 05 06:15:02 volumio go-librespot[3052]: time="2025-11-05T06:15:02Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Nov 05 06:15:02 volumio go-librespot[3052]: time="2025-11-05T06:15:02Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Nov 05 06:15:02 volumio go-librespot[3052]: time="2025-11-05T06:15:02Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Nov 05 06:15:02 volumio go-librespot[3052]: time="2025-11-05T06:15:02Z" level=info msg="zeroconf server listening on port 33681" Nov 05 06:15:02 volumio sudo[3061]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Nov 05 06:15:02 volumio sudo[3061]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 05 06:15:02 volumio sudo[3068]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Nov 05 06:15:02 volumio sudo[3068]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 05 06:15:02 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Nov 05 06:15:02 volumio sudo[3070]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Nov 05 06:15:02 volumio sudo[3070]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 05 06:15:02 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Nov 05 06:15:02 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Nov 05 06:15:02 volumio systemd[1]: shairport-sync.service: Consumed 1.970s CPU time. Nov 05 06:15:02 volumio volumio[2864]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Nov 05 06:15:02 volumio volumio[2864]: SPOTIFY: BQB-t2hyRF8PlNvnWQFILSEtxrFalvpOQubmNST5rpcQYid3QgPXYKEA9wedGXbsUVS_bAvOpRAKaAmUY8V4XzXt5jVHG7EIIFcIolSH8aeuDZ8EjkDXnB5OnpRLO_Oy1HRSzvCT8aBG-oXjY-KjfvCQSOOkLHL4o_f7GAWlzBsakWJBTX8Va8c8fsmyMm72SkLdMbbLEhun8J-1UKrbefkhtPj_k9MA0j06tdyShRX1RTJaZcN8jQ8aIISgsfaUNJNSsEKuZUOLS4pQtOAA1Y0s_VIyjb7kzCl4A_FAa1Pkqb8Me3yae7ia Nov 05 06:15:02 volumio volumio[2864]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Nov 05 06:15:02 volumio volumio[2864]: info: New Spotify access token = BQB-t2hyRF8PlNvnWQFILSEtxrFalvpOQubmNST5rpcQYid3QgPXYKEA9wedGXbsUVS_bAvOpRAKaAmUY8V4XzXt5jVHG7EIIFcIolSH8aeuDZ8EjkDXnB5OnpRLO_Oy1HRSzvCT8aBG-oXjY-KjfvCQSOOkLHL4o_f7GAWlzBsakWJBTX8Va8c8fsmyMm72SkLdMbbLEhun8J-1UKrbefkhtPj_k9MA0j06tdyShRX1RTJaZcN8jQ8aIISgsfaUNJNSsEKuZUOLS4pQtOAA1Y0s_VIyjb7kzCl4A_FAa1Pkqb8Me3yae7ia Nov 05 06:15:02 volumio volumio[2864]: info: Spotify credentials grant success - running version from March 24, 2019 Nov 05 06:15:02 volumio mpd[3033]: 2025-11-05T06:15:02 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Nov 05 06:15:02 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Nov 05 06:15:02 volumio go-librespot[3052]: time="2025-11-05T06:15:02Z" level=debug msg="obtained new client token: AABqtWnkWK7xNTBXZLogReLSvpb7S8Fn+N/er7zMP8M6do3UmcSRxJHGdVcAqadLVon7feV7G0JVJ7bNZ92Drl/TKQdvjxUGuSW3MOwxRGAtPxEhkSaKGZusVxkkPcC1BH6p1UooUhYGzC7Ui/UKEiMA0H2V59J0wDAcUY0BviHpvwkSQhMhZ4pgx04GXxmmGj5kohKCqaG5GuZ7/09Sa4eOh/v6m4BEqfIXIrEQXt6hz/iR88DYQ7o=" Nov 05 06:15:02 volumio systemd[1]: Started mpd.service - Music Player Daemon. Nov 05 06:15:02 volumio sudo[2986]: pam_unix(sudo:session): session closed for user root Nov 05 06:15:02 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Nov 05 06:15:02 volumio sudo[3061]: pam_unix(sudo:session): session closed for user root Nov 05 06:15:02 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Nov 05 06:15:02 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Nov 05 06:15:02 volumio sudo[2996]: pam_unix(sudo:session): session closed for user root Nov 05 06:15:02 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Nov 05 06:15:02 volumio go-librespot[3052]: time="2025-11-05T06:15:02Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Nov 05 06:15:02 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Nov 05 06:15:02 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Nov 05 06:15:02 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Nov 05 06:15:02 volumio volumio[2864]: info: CoreCommandRouter::volumioGetState Nov 05 06:15:02 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Nov 05 06:15:02 volumio volumio[2864]: info: CorePlayQueue::getTrack 0 Nov 05 06:15:02 volumio sudo[3068]: pam_unix(sudo:session): session closed for user root Nov 05 06:15:02 volumio sudo[3070]: pam_unix(sudo:session): session closed for user root Nov 05 06:15:02 volumio go-librespot[3052]: time="2025-11-05T06:15:02Z" level=debug msg="completed keyexchange" Nov 05 06:15:02 volumio go-librespot[3052]: time="2025-11-05T06:15:02Z" level=debug msg="completed challenge" Nov 05 06:15:02 volumio volumio[2864]: info: Shairport-Sync Started Nov 05 06:15:02 volumio volumio[2864]: Error adding Membership: Error: addMembership EINVAL Nov 05 06:15:02 volumio volumio[2864]: info: Shairport-Sync Started Nov 05 06:15:02 volumio volumio[2864]: info: Shairport-Sync Started Nov 05 06:15:02 volumio go-librespot[3052]: time="2025-11-05T06:15:02Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Nov 05 06:15:02 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 05 06:15:02 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 05 06:15:02 volumio volumio[2864]: error: MPD error: The expression evaluated to a falsy value: Nov 05 06:15:02 volumio volumio[2864]: assert.ok(self.idling) Nov 05 06:15:02 volumio volumio[2864]: error: The expression evaluated to a falsy value: Nov 05 06:15:02 volumio volumio[2864]: assert.ok(self.idling) Nov 05 06:15:02 volumio volumio[2864]: error: updateQueue error: null Nov 05 06:15:02 volumio volumio[2864]: info: MPD running with PID3033 Nov 05 06:15:02 volumio volumio[2864]: ,establishing connection Nov 05 06:15:02 volumio volumio[2864]: error: updateQueue error: null Nov 05 06:15:02 volumio volumio[2864]: info: CoreCommandRouter::volumioGetState Nov 05 06:15:02 volumio volumio[2864]: info: CorePlayQueue::getTrack 0 Nov 05 06:15:02 volumio volumio[2864]: SPOTIFY: User informations: {"country":"DE","display_name":"lapman","email":"ylm19961214@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/31hyzsop5elyyfayaiyk5tmkxmky"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/31hyzsop5elyyfayaiyk5tmkxmky","id":"31hyzsop5elyyfayaiyk5tmkxmky","images":[],"product":"free","type":"user","uri":"spotify:user:31hyzsop5elyyfayaiyk5tmkxmky"} Nov 05 06:15:02 volumio volumio[2864]: info: Spotify Successfully logged in Nov 05 06:15:02 volumio volumio[2864]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Nov 05 06:15:02 volumio volumio[2864]: info: [1762323302734] CoreMusicLibrary::Adding element Spotify Nov 05 06:15:02 volumio volumio[2864]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 05 06:15:02 volumio volumio[2864]: Cannot find translation for source Spotify Nov 05 06:15:02 volumio volumio[2864]: info: [yt-cast-receiver] DIAL server listening on port 8098 Nov 05 06:15:02 volumio volumio[2864]: info: CoreCommandRouter::volumioRetrievevolume Nov 05 06:15:02 volumio volumio[2864]: info: VolumeController:: Volume=33 Mute =false Nov 05 06:15:02 volumio volumio[2864]: info: CoreCommandRouter::volumioGetState Nov 05 06:15:02 volumio volumio[2864]: info: CorePlayQueue::getTrack 0 Nov 05 06:15:02 volumio volumio[2864]: info: CoreStateMachine::pushState Nov 05 06:15:02 volumio volumio[2864]: info: CorePlayQueue::getTrack 0 Nov 05 06:15:02 volumio volumio[2864]: info: CoreCommandRouter::volumioPushState Nov 05 06:15:03 volumio volumio[2864]: info: Completed starting Core Plugins Nov 05 06:15:03 volumio volumio[2864]: info: ------------------------------------------- Nov 05 06:15:03 volumio volumio[2864]: info: ----- MyVolumio plugins startup ---- Nov 05 06:15:03 volumio volumio[2864]: info: ------------------------------------------- Nov 05 06:15:03 volumio volumio[2864]: info: [MyVolumio PluginManager] Fetching plans data.... Nov 05 06:15:04 volumio volumio-remote-updater[874]: [2025-11-05 06:15:04] [connect] Successful connection Nov 05 06:15:04 volumio volumio-remote-updater[874]: [2025-11-05 06:15:04] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1762323304 101 Nov 05 06:15:04 volumio volumio[2864]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 3 Transport: websocket Total Clients: 2 Nov 05 06:15:05 volumio volumio[2864]: info: Cannot mount NAS NAS at system boot, trial number 2 ,retrying in 5 seconds Nov 05 06:15:05 volumio volumio[2864]: info: go-librespot daemon successfully initialized Nov 05 06:15:05 volumio sudo[3123]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Nov 05 06:15:05 volumio sudo[3123]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 05 06:15:05 volumio systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Nov 05 06:15:05 volumio systemd[1]: mpd_monitor.service: Deactivated successfully. Nov 05 06:15:05 volumio systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Nov 05 06:15:05 volumio sudo[3127]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Nov 05 06:15:05 volumio sudo[3127]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 05 06:15:05 volumio systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Nov 05 06:15:05 volumio sudo[3123]: pam_unix(sudo:session): session closed for user root Nov 05 06:15:05 volumio mpd_monitor.sh[3126]: MPD Monitor Service: Starting MPD Monitor Service Nov 05 06:15:05 volumio volumio[2864]: info: Successfully started MPD Monitor Nov 05 06:15:05 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 89. Nov 05 06:15:05 volumio kernel: nfs: server 192.168.1.3 not responding, timed out Nov 05 06:15:05 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Nov 05 06:15:05 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Nov 05 06:15:05 volumio systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Nov 05 06:15:05 volumio systemd[1]: mpd_monitor.service: Deactivated successfully. Nov 05 06:15:05 volumio go-librespot[3133]: go-librespot daemon starting... Nov 05 06:15:05 volumio systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Nov 05 06:15:05 volumio systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Nov 05 06:15:05 volumio sudo[3127]: pam_unix(sudo:session): session closed for user root Nov 05 06:15:05 volumio mpd_monitor.sh[3140]: MPD Monitor Service: Starting MPD Monitor Service Nov 05 06:15:05 volumio go-librespot[3134]: time="2025-11-05T06:15:05Z" level=info msg="running go-librespot 0.4.0" Nov 05 06:15:05 volumio volumio[2864]: info: Successfully started MPD Monitor Nov 05 06:15:05 volumio go-librespot[3134]: time="2025-11-05T06:15:05Z" level=debug msg="app state loaded" Nov 05 06:15:05 volumio go-librespot[3134]: time="2025-11-05T06:15:05Z" level=info msg="api server listening on 127.0.0.1:9879" Nov 05 06:15:05 volumio go-librespot[3134]: time="2025-11-05T06:15:05Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Nov 05 06:15:05 volumio go-librespot[3134]: time="2025-11-05T06:15:05Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Nov 05 06:15:05 volumio go-librespot[3134]: time="2025-11-05T06:15:05Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Nov 05 06:15:05 volumio go-librespot[3134]: time="2025-11-05T06:15:05Z" level=info msg="zeroconf server listening on port 38147" Nov 05 06:15:05 volumio go-librespot[3134]: time="2025-11-05T06:15:05Z" level=debug msg="obtained new client token: AADsaNmaK+9JYoz09jnQTFCiMoNghnDeT4M6DuJJCkvSMzyHmwl1PpzIp35bJLZ3xyLBI4NulaXTzbZcitDSLOGum48QlMuxYnXTOsHEL+c+TdZhf7ncQUTKu5/W9k/YbDcfppvhxesTOwzrWahe3deexoMIUztaermdJTevASRTPY4lA0KWrjcq2cR2oZLo41gNI3q2hYKu0PSd9chVvZZ1eUiv/5Jc4iGpsPckgLseap7pnUZtrV4=" Nov 05 06:15:05 volumio go-librespot[3134]: time="2025-11-05T06:15:05Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Nov 05 06:15:05 volumio go-librespot[3134]: time="2025-11-05T06:15:05Z" level=debug msg="completed keyexchange" Nov 05 06:15:05 volumio go-librespot[3134]: time="2025-11-05T06:15:05Z" level=debug msg="completed challenge" Nov 05 06:15:05 volumio go-librespot[3134]: time="2025-11-05T06:15:05Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Nov 05 06:15:05 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 05 06:15:05 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 05 06:15:07 volumio volumio[2864]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Nov 05 06:15:08 volumio volumio[2864]: info: Initializing connection to go-librespot Websocket Nov 05 06:15:08 volumio volumio[2864]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 05 06:15:09 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 90. Nov 05 06:15:09 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Nov 05 06:15:09 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Nov 05 06:15:09 volumio go-librespot[3145]: go-librespot daemon starting... Nov 05 06:15:09 volumio go-librespot[3146]: time="2025-11-05T06:15:09Z" level=info msg="running go-librespot 0.4.0" Nov 05 06:15:09 volumio go-librespot[3146]: time="2025-11-05T06:15:09Z" level=debug msg="app state loaded" Nov 05 06:15:09 volumio go-librespot[3146]: time="2025-11-05T06:15:09Z" level=info msg="api server listening on 127.0.0.1:9879" Nov 05 06:15:09 volumio go-librespot[3146]: time="2025-11-05T06:15:09Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Nov 05 06:15:09 volumio go-librespot[3146]: time="2025-11-05T06:15:09Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Nov 05 06:15:09 volumio go-librespot[3146]: time="2025-11-05T06:15:09Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Nov 05 06:15:09 volumio go-librespot[3146]: time="2025-11-05T06:15:09Z" level=info msg="zeroconf server listening on port 39949" Nov 05 06:15:09 volumio go-librespot[3146]: time="2025-11-05T06:15:09Z" level=debug msg="obtained new client token: AADK4UjsmWvlVuOkzH0oaxqKWfXHrxsOOJv1c1FyA3NL+9jLz5gCFweSewWyPL+Ts0iyNRWF5t+WnwzYNIp/4uT6cfplyNNQhRDAJGy3mIY7iZvkUdTHr/IG0cWZW7YTgfu81lxQhmEiGK01FUQ8GUPlkuBW4Tfl8IJiODBAaBhgR+eSyltDJ9nrrGrBCOH2QkyhzllVFVegeeevdLHMrzNLc2TTvcCmPyZmf6B9Ly0XU+pNIios" Nov 05 06:15:09 volumio go-librespot[3146]: time="2025-11-05T06:15:09Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Nov 05 06:15:09 volumio go-librespot[3146]: time="2025-11-05T06:15:09Z" level=debug msg="completed keyexchange" Nov 05 06:15:09 volumio go-librespot[3146]: time="2025-11-05T06:15:09Z" level=debug msg="completed challenge" Nov 05 06:15:09 volumio go-librespot[3146]: time="2025-11-05T06:15:09Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Nov 05 06:15:09 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 05 06:15:09 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 05 06:15:10 volumio volumio[2864]: info: Cannot mount NAS NAS at system boot, trial number 3 ,retrying in 5 seconds Nov 05 06:15:10 volumio sudo[3169]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Nov 05 06:15:10 volumio sudo[3169]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 05 06:15:10 volumio sudo[3171]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Nov 05 06:15:10 volumio sudo[3169]: pam_unix(sudo:session): session closed for user root Nov 05 06:15:10 volumio sudo[3171]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 05 06:15:10 volumio sudo[3171]: pam_unix(sudo:session): session closed for user root Nov 05 06:15:10 volumio sudo[3175]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Nov 05 06:15:10 volumio sudo[3175]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 05 06:15:10 volumio sudo[3175]: pam_unix(sudo:session): session closed for user root Nov 05 06:15:10 volumio volumio[2864]: info: Upmpdcli Daemon Started Nov 05 06:15:11 volumio volumio[2864]: info: Initializing connection to go-librespot Websocket Nov 05 06:15:11 volumio volumio[2864]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 05 06:15:11 volumio volumio[2864]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Nov 05 06:15:11 volumio volumio[2864]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Nov 05 06:15:11 volumio volumio[2864]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Nov 05 06:15:11 volumio volumio[2864]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Nov 05 06:15:11 volumio volumio[2864]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Nov 05 06:15:11 volumio volumio[2864]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Nov 05 06:15:11 volumio volumio[2864]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Nov 05 06:15:11 volumio volumio[2864]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Nov 05 06:15:11 volumio volumio[2864]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Nov 05 06:15:11 volumio volumio[2864]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Nov 05 06:15:11 volumio volumio[2864]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Nov 05 06:15:11 volumio volumio[2864]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Nov 05 06:15:11 volumio volumio[2864]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Nov 05 06:15:11 volumio volumio[2864]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Nov 05 06:15:11 volumio volumio[2864]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Nov 05 06:15:11 volumio volumio[2864]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Nov 05 06:15:11 volumio volumio[2864]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Nov 05 06:15:11 volumio volumio[2864]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Nov 05 06:15:11 volumio volumio[2864]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Nov 05 06:15:11 volumio volumio[2864]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Nov 05 06:15:11 volumio volumio[2864]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Nov 05 06:15:11 volumio volumio[2864]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Nov 05 06:15:11 volumio volumio[2864]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Nov 05 06:15:11 volumio volumio[2864]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Nov 05 06:15:11 volumio volumio[2864]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Nov 05 06:15:11 volumio volumio[2864]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Nov 05 06:15:11 volumio volumio[2864]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Nov 05 06:15:11 volumio volumio[2864]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Nov 05 06:15:11 volumio volumio[2864]: info: Adding plugin bluetooth to MyMusic Plugins Nov 05 06:15:11 volumio volumio[2864]: info: Adding plugin multiroom to MyMusic Plugins Nov 05 06:15:11 volumio volumio[2864]: info: Adding plugin metavolumio to MyMusic Plugins Nov 05 06:15:11 volumio volumio[2864]: info: Adding plugin cd_controller to MyMusic Plugins Nov 05 06:15:11 volumio volumio[2864]: info: Adding plugin qobuzconnect to MyMusic Plugins Nov 05 06:15:11 volumio volumio[2864]: info: Adding plugin smart_inputs to MyMusic Plugins Nov 05 06:15:11 volumio volumio[2864]: info: Adding plugin tidalconnect to MyMusic Plugins Nov 05 06:15:11 volumio volumio[2864]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Nov 05 06:15:11 volumio volumio[2864]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Nov 05 06:15:11 volumio volumio[2864]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Nov 05 06:15:11 volumio volumio[2864]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 05 06:15:11 volumio volumio[2864]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 05 06:15:11 volumio volumio[2864]: info: Starting MyVolumio Remote Streaming Endpoints Nov 05 06:15:11 volumio volumio[2864]: info: MyVolumio login type: Token Nov 05 06:15:11 volumio volumio[2864]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Nov 05 06:15:11 volumio volumio[2864]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Nov 05 06:15:11 volumio volumio[2864]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Nov 05 06:15:11 volumio volumio[2864]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Nov 05 06:15:11 volumio volumio[2864]: info: Streaming services startup Nov 05 06:15:11 volumio volumio[2864]: info: Starting Streaming Daemon Nov 05 06:15:11 volumio sudo[3178]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Nov 05 06:15:11 volumio sudo[3178]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 05 06:15:11 volumio volumio[2864]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Nov 05 06:15:11 volumio sudo[3178]: pam_unix(sudo:session): session closed for user root Nov 05 06:15:11 volumio volumio[2864]: error: Cannot start Volumio Streaming Daemon Nov 05 06:15:11 volumio volumio[2864]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Nov 05 06:15:11 volumio volumio[2864]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Nov 05 06:15:12 volumio volumio[2864]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Nov 05 06:15:12 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 91. Nov 05 06:15:12 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Nov 05 06:15:12 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Nov 05 06:15:12 volumio go-librespot[3185]: go-librespot daemon starting... Nov 05 06:15:12 volumio go-librespot[3186]: time="2025-11-05T06:15:12Z" level=info msg="running go-librespot 0.4.0" Nov 05 06:15:12 volumio go-librespot[3186]: time="2025-11-05T06:15:12Z" level=debug msg="app state loaded" Nov 05 06:15:12 volumio go-librespot[3186]: time="2025-11-05T06:15:12Z" level=info msg="api server listening on 127.0.0.1:9879" Nov 05 06:15:12 volumio volumio[2864]: info: CoreCommandRouter::volumioGetState Nov 05 06:15:12 volumio volumio[2864]: info: CorePlayQueue::getTrack 0 Nov 05 06:15:12 volumio volumio[2864]: info: Listing playlists Nov 05 06:15:12 volumio volumio[2864]: info: Listing playlists Nov 05 06:15:12 volumio go-librespot[3186]: time="2025-11-05T06:15:12Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Nov 05 06:15:12 volumio go-librespot[3186]: time="2025-11-05T06:15:12Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Nov 05 06:15:12 volumio go-librespot[3186]: time="2025-11-05T06:15:12Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Nov 05 06:15:12 volumio go-librespot[3186]: time="2025-11-05T06:15:12Z" level=info msg="zeroconf server listening on port 34681" Nov 05 06:15:12 volumio go-librespot[3186]: time="2025-11-05T06:15:12Z" level=debug msg="obtained new client token: AADe8QU/mz45eKUU1GVFD+lWd6WKkRzsZ2lMNynvSqAn5fC/PABhu9spOcjoHnsLQVBHOPJcmu0LeGX0+QqxlzoegFn0LdopeR26TWDMiLpJSUaX3mMF7UDshEk4uNLBspEwUv6c5io8jJMMT1PsqzVITrVoswuqBM9S+MxoluF51vAytLTEOcZSyhvkrgjvcNSAUTV2or838XOE4kKMAEmiOpR+k5SkMMDB0SZqt3/Vpu2dvZSNToU=" Nov 05 06:15:12 volumio volumio[2864]: info: MyVolumio token set successfully Nov 05 06:15:12 volumio volumio[2864]: info: MYVOLUMIO: Adding device Nov 05 06:15:12 volumio volumio[2864]: info: MYVOLUMIO: Evaluating Server Nov 05 06:15:12 volumio go-librespot[3186]: time="2025-11-05T06:15:12Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Nov 05 06:15:12 volumio go-librespot[3186]: time="2025-11-05T06:15:12Z" level=debug msg="completed keyexchange" Nov 05 06:15:12 volumio go-librespot[3186]: time="2025-11-05T06:15:12Z" level=debug msg="completed challenge" Nov 05 06:15:12 volumio go-librespot[3186]: time="2025-11-05T06:15:12Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Nov 05 06:15:12 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 05 06:15:12 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 05 06:15:12 volumio volumio[2864]: info: MyVolumio status changed Nov 05 06:15:12 volumio volumio[2864]: info: Streaming services startup Nov 05 06:15:12 volumio volumio[2864]: info: Starting Streaming Daemon Nov 05 06:15:12 volumio volumio[2864]: info: Removing browser output: myVolumio user plan is not superstar Nov 05 06:15:12 volumio volumio[2864]: info: Removing audio output: Nov 05 06:15:12 volumio volumio[2864]: info: Stoppping Tunnel 1 Nov 05 06:15:12 volumio sudo[3211]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Nov 05 06:15:12 volumio sudo[3211]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 05 06:15:12 volumio sudo[3211]: pam_unix(sudo:session): session closed for user root Nov 05 06:15:12 volumio sudo[3213]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service Nov 05 06:15:12 volumio volumio[2864]: error: Cannot start Volumio Streaming Daemon Nov 05 06:15:12 volumio volumio[2864]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Nov 05 06:15:12 volumio volumio[2864]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Nov 05 06:15:12 volumio sudo[3213]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Nov 05 06:15: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. Nov 05 06:15: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. Nov 05 06:15: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. Nov 05 06:15: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. Nov 05 06:15: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. Nov 05 06:15: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. Nov 05 06:15: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. Nov 05 06:15: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. Nov 05 06:15:12 volumio sudo[3213]: pam_unix(sudo:session): session closed for user root Nov 05 06:15:12 volumio volumio[2864]: info: Remote SSH Stopped Nov 05 06:15:13 volumio volumio[2864]: info: Setting Geolocation for MyVolumio to eu3 Nov 05 06:15:13 volumio volumio[2864]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 05 06:15:13 volumio volumio[2864]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 05 06:15:13 volumio volumio[2864]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 05 06:15:13 volumio volumio[2864]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Nov 05 06:15:14 volumio kernel: nfs: server 192.168.1.3 not responding, timed out Nov 05 06:15:14 volumio volumio[2864]: info: Updating MyVolumio device info Nov 05 06:15:14 volumio volumio[2864]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 05 06:15:14 volumio volumio[2864]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 05 06:15:14 volumio volumio[2864]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 05 06:15:14 volumio volumio[2864]: info: Initializing connection to go-librespot Websocket Nov 05 06:15:14 volumio volumio[2864]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 05 06:15:14 volumio volumio[2864]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Nov 05 06:15:15 volumio volumio[2864]: info: Cannot mount NAS NAS at system boot, trial number 4 ,retrying in 5 seconds Nov 05 06:15:16 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 92. Nov 05 06:15:16 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Nov 05 06:15:16 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Nov 05 06:15:16 volumio go-librespot[3216]: go-librespot daemon starting... Nov 05 06:15:16 volumio go-librespot[3217]: time="2025-11-05T06:15:16Z" level=info msg="running go-librespot 0.4.0" Nov 05 06:15:16 volumio go-librespot[3217]: time="2025-11-05T06:15:16Z" level=debug msg="app state loaded" Nov 05 06:15:16 volumio go-librespot[3217]: time="2025-11-05T06:15:16Z" level=info msg="api server listening on 127.0.0.1:9879" Nov 05 06:15:16 volumio go-librespot[3217]: time="2025-11-05T06:15:16Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Nov 05 06:15:16 volumio go-librespot[3217]: time="2025-11-05T06:15:16Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Nov 05 06:15:16 volumio go-librespot[3217]: time="2025-11-05T06:15:16Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Nov 05 06:15:16 volumio go-librespot[3217]: time="2025-11-05T06:15:16Z" level=info msg="zeroconf server listening on port 45413" Nov 05 06:15:16 volumio go-librespot[3217]: time="2025-11-05T06:15:16Z" level=debug msg="obtained new client token: AAD5+UVTNdtpxlDWecyYJiZ52GWaNN+p7lm4kJ5FNtFiBxHp10pO8HmmfebZYT0lqUuDvl0MHlNbruyqFzE9VXWQSP8Y9bYHc5QGCzpKQCIRWv/I2v3Cc2cskScjnFvwv7MipsXmmGzMRqHZt+WnDtXnwrZkPVx0xXoIlENrtN37M3MyuwfAQdsaFlT0Q4giOqyTpmdjYBfjYbUtoylf+gRtaYgZcUsKeppJv7gl0rfvsTkyWpeQ" Nov 05 06:15:16 volumio go-librespot[3217]: time="2025-11-05T06:15:16Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Nov 05 06:15:16 volumio go-librespot[3217]: time="2025-11-05T06:15:16Z" level=debug msg="completed keyexchange" Nov 05 06:15:16 volumio go-librespot[3217]: time="2025-11-05T06:15:16Z" level=debug msg="completed challenge" Nov 05 06:15:16 volumio go-librespot[3217]: time="2025-11-05T06:15:16Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Nov 05 06:15:16 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 05 06:15:16 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 05 06:15:17 volumio volumio[2864]: info: Initializing connection to go-librespot Websocket Nov 05 06:15:17 volumio volumio[2864]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 05 06:15:17 volumio volumio[2864]: info: MYVOLUMIO: Adding device Nov 05 06:15:17 volumio volumio[2864]: info: MYVOLUMIO: Evaluating Server Nov 05 06:15:18 volumio volumio[2864]: info: Setting Geolocation for MyVolumio to eu3 Nov 05 06:15:18 volumio volumio[2864]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 05 06:15:18 volumio volumio[2864]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 05 06:15:18 volumio volumio[2864]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 05 06:15:18 volumio volumio[2864]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Nov 05 06:15:19 volumio volumio[2864]: info: Updating MyVolumio device info Nov 05 06:15:19 volumio volumio[2864]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 05 06:15:19 volumio volumio[2864]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 05 06:15:19 volumio volumio[2864]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 05 06:15:19 volumio volumio[2864]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Nov 05 06:15:19 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 93. Nov 05 06:15:19 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Nov 05 06:15:19 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Nov 05 06:15:19 volumio go-librespot[3239]: go-librespot daemon starting... Nov 05 06:15:19 volumio go-librespot[3241]: time="2025-11-05T06:15:19Z" level=info msg="running go-librespot 0.4.0" Nov 05 06:15:19 volumio go-librespot[3241]: time="2025-11-05T06:15:19Z" level=debug msg="app state loaded" Nov 05 06:15:19 volumio go-librespot[3241]: time="2025-11-05T06:15:19Z" level=info msg="api server listening on 127.0.0.1:9879" Nov 05 06:15:19 volumio go-librespot[3241]: time="2025-11-05T06:15:19Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Nov 05 06:15:19 volumio go-librespot[3241]: time="2025-11-05T06:15:19Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Nov 05 06:15:19 volumio go-librespot[3241]: time="2025-11-05T06:15:19Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Nov 05 06:15:19 volumio go-librespot[3241]: time="2025-11-05T06:15:19Z" level=info msg="zeroconf server listening on port 35639" Nov 05 06:15:19 volumio go-librespot[3241]: time="2025-11-05T06:15:19Z" level=debug msg="obtained new client token: AACuLavOfCKOtF/T0sWKre7EEPWKhsvUtdHiztkFUR9gRJx7whmf+Xv7M3w7RPg7x4/oTbQ4Xm2OnCzRMJKylYN8dWnGGd2VtvemuzrYA09QMhaE3Dr2BhiZkvOfpx72hezlY9Glt5GgEeOAuzUYhZlMX7N5UUtnDJCHiLIkAY/O0hjxnO474tpyaAA7o7QUPil8nhJmevWtmnLGmQJMzBXI/FOOrKw8X4xZIq44DTaVJuR3DIZouYs=" Nov 05 06:15:19 volumio go-librespot[3241]: time="2025-11-05T06:15:19Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Nov 05 06:15:19 volumio go-librespot[3241]: time="2025-11-05T06:15:19Z" level=debug msg="completed keyexchange" Nov 05 06:15:19 volumio go-librespot[3241]: time="2025-11-05T06:15:19Z" level=debug msg="completed challenge" Nov 05 06:15:19 volumio go-librespot[3241]: time="2025-11-05T06:15:19Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Nov 05 06:15:19 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 05 06:15:19 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 05 06:15:20 volumio volumio[2864]: info: Cannot mount NAS at system boot, trial number 4 ,stopping Nov 05 06:15:20 volumio volumio[2864]: info: Initializing connection to go-librespot Websocket Nov 05 06:15:20 volumio volumio[2864]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 05 06:15:22 volumio volumio[2864]: info: CoreCommandRouter::volumioGetState Nov 05 06:15:22 volumio volumio[2864]: info: CorePlayQueue::getTrack 0 Nov 05 06:15:23 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 94. Nov 05 06:15:23 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Nov 05 06:15:23 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Nov 05 06:15:23 volumio go-librespot[3262]: go-librespot daemon starting... Nov 05 06:15:23 volumio go-librespot[3263]: time="2025-11-05T06:15:23Z" level=info msg="running go-librespot 0.4.0" Nov 05 06:15:23 volumio go-librespot[3263]: time="2025-11-05T06:15:23Z" level=debug msg="app state loaded" Nov 05 06:15:23 volumio go-librespot[3263]: time="2025-11-05T06:15:23Z" level=info msg="api server listening on 127.0.0.1:9879" Nov 05 06:15:23 volumio go-librespot[3263]: time="2025-11-05T06:15:23Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Nov 05 06:15:23 volumio go-librespot[3263]: time="2025-11-05T06:15:23Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Nov 05 06:15:23 volumio go-librespot[3263]: time="2025-11-05T06:15:23Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Nov 05 06:15:23 volumio go-librespot[3263]: time="2025-11-05T06:15:23Z" level=info msg="zeroconf server listening on port 38125" Nov 05 06:15:23 volumio go-librespot[3263]: time="2025-11-05T06:15:23Z" level=debug msg="obtained new client token: AACw6+wr+QPKMT11vp3WRR2nmBlAHgh7s+hh88jG1bkpPV8gAqrfJ6adyYF0IQj5zKd2Acb3EyVtdi5kgz9dMMFWuq/qP68cjduSFd9MMU/TnFfMQkUaIM7TjGOPcijob/LxAwfkJ2lLkWLCtNNzZaTAeNADMT4LWNo/E+Z5C8LPaOuzSYr/bk+zKsXDRBUigPbM4nVx49tFeLnAUmpYbKKM7rRQDgLwnz++2wyoj+SX0SBzM+1z" Nov 05 06:15:23 volumio go-librespot[3263]: time="2025-11-05T06:15:23Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Nov 05 06:15:23 volumio go-librespot[3263]: time="2025-11-05T06:15:23Z" level=debug msg="completed keyexchange" Nov 05 06:15:23 volumio go-librespot[3263]: time="2025-11-05T06:15:23Z" level=debug msg="completed challenge" Nov 05 06:15:23 volumio go-librespot[3263]: time="2025-11-05T06:15:23Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Nov 05 06:15:23 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 05 06:15:23 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 05 06:15:23 volumio volumio[2864]: info: Initializing connection to go-librespot Websocket Nov 05 06:15:23 volumio volumio[2864]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 05 06:15:26 volumio volumio[2864]: info: Initializing connection to go-librespot Websocket Nov 05 06:15:26 volumio volumio[2864]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 05 06:15:26 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 95. Nov 05 06:15:26 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Nov 05 06:15:26 volumio volumio[2864]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Nov 05 06:15:26 volumio volumio[2864]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Nov 05 06:15:26 volumio volumio[2864]: info: CoreCommandRouter::volumioGetState Nov 05 06:15:26 volumio volumio[2864]: info: CorePlayQueue::getTrack 0 Nov 05 06:15:26 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Nov 05 06:15:26 volumio go-librespot[3273]: go-librespot daemon starting... Nov 05 06:15:26 volumio go-librespot[3274]: time="2025-11-05T06:15:26Z" level=info msg="running go-librespot 0.4.0" Nov 05 06:15:26 volumio go-librespot[3274]: time="2025-11-05T06:15:26Z" level=debug msg="app state loaded" Nov 05 06:15:26 volumio go-librespot[3274]: time="2025-11-05T06:15:26Z" level=info msg="api server listening on 127.0.0.1:9879" Nov 05 06:15:26 volumio go-librespot[3274]: time="2025-11-05T06:15:26Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Nov 05 06:15:26 volumio go-librespot[3274]: time="2025-11-05T06:15:26Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Nov 05 06:15:26 volumio go-librespot[3274]: time="2025-11-05T06:15:26Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Nov 05 06:15:26 volumio go-librespot[3274]: time="2025-11-05T06:15:26Z" level=info msg="zeroconf server listening on port 43669" Nov 05 06:15:26 volumio go-librespot[3274]: time="2025-11-05T06:15:26Z" level=debug msg="obtained new client token: AADAVcffaRrMoMVrfg91OFamwDdfT9Sf2eHbTwTCxiJVZ8z8J0ojZcNJNo/WHnW5TjxN2HP7KlV4Z8f71UKY9JBQddltPmyTusOICgBfndkVLISON7sM2gJvzqN53Z1GZaYRJ2aJuIlmESxX5AEO9YNtmBFCRQnMojrODMJPBbIMTU9KiWjVPjpvUfXQAo+A+N0FXI8pir25BOjtIjz78PFE9r37gxyKOTapaaYngTF84JR2aVUNm2k=" Nov 05 06:15:26 volumio go-librespot[3274]: time="2025-11-05T06:15:26Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Nov 05 06:15:26 volumio go-librespot[3274]: time="2025-11-05T06:15:26Z" level=debug msg="completed keyexchange" Nov 05 06:15:26 volumio go-librespot[3274]: time="2025-11-05T06:15:26Z" level=debug msg="completed challenge" Nov 05 06:15:26 volumio go-librespot[3274]: time="2025-11-05T06:15:26Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Nov 05 06:15:26 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 05 06:15:26 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 05 06:15:27 volumio kernel: nfs: server 192.168.1.3 not responding, timed out Nov 05 06:15:29 volumio volumio[2864]: info: Initializing connection to go-librespot Websocket Nov 05 06:15:29 volumio volumio[2864]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 05 06:15:30 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 96. Nov 05 06:15:30 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Nov 05 06:15:30 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Nov 05 06:15:30 volumio go-librespot[3281]: go-librespot daemon starting... Nov 05 06:15:30 volumio go-librespot[3285]: time="2025-11-05T06:15:30Z" level=info msg="running go-librespot 0.4.0" Nov 05 06:15:30 volumio go-librespot[3285]: time="2025-11-05T06:15:30Z" level=debug msg="app state loaded" Nov 05 06:15:30 volumio go-librespot[3285]: time="2025-11-05T06:15:30Z" level=info msg="api server listening on 127.0.0.1:9879" Nov 05 06:15:30 volumio go-librespot[3285]: time="2025-11-05T06:15:30Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Nov 05 06:15:30 volumio go-librespot[3285]: time="2025-11-05T06:15:30Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Nov 05 06:15:30 volumio go-librespot[3285]: time="2025-11-05T06:15:30Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Nov 05 06:15:30 volumio go-librespot[3285]: time="2025-11-05T06:15:30Z" level=info msg="zeroconf server listening on port 43739" Nov 05 06:15:30 volumio go-librespot[3285]: time="2025-11-05T06:15:30Z" level=debug msg="obtained new client token: AAD/07NlcpAjieS13oi1zAhBnHeouVfdHjYBoiMmr7sPDV8B2TfqnYLzJG5nSmwzyY4uOt+mhI2+10T6xD4qutgCtCGPJg33+ZhL7OvnJGaHcNxfaM5npNT2Q3H1RpyI0hY8sVFPmcsMb+IgDq2SX+H3EeTi4yrsje3CA7go6EDeJse95zr6piXrp7xj91/i9bU4Z3meaR9zsw8/HRqCeIzaI9bWgicT9IGTHqKnFcFg626cDH4S" Nov 05 06:15:30 volumio go-librespot[3285]: time="2025-11-05T06:15:30Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Nov 05 06:15:30 volumio go-librespot[3285]: time="2025-11-05T06:15:30Z" level=debug msg="completed keyexchange" Nov 05 06:15:30 volumio go-librespot[3285]: time="2025-11-05T06:15:30Z" level=debug msg="completed challenge" Nov 05 06:15:30 volumio go-librespot[3285]: time="2025-11-05T06:15:30Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Nov 05 06:15:30 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 05 06:15:30 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 05 06:15:31 volumio volumio[2864]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 05 06:15:31 volumio volumio[2864]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 05 06:15:31 volumio volumio[2864]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam Nov 05 06:15:31 volumio volumio[2864]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Nov 05 06:15:31 volumio volumio[2864]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Nov 05 06:15:31 volumio volumio[2864]: info: CoreCommandRouter::volumioGetBrowseSources Nov 05 06:15:31 volumio volumio[2864]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Nov 05 06:15:31 volumio volumio[2864]: error: MyVolumio Plugin failed to authenticate in a timely fashion Nov 05 06:15:31 volumio volumio[2864]: info: Completed starting MyVolumio Plugin Nov 05 06:15:31 volumio volumio[2864]: [Metrics] CommandRouter: 32s 58.48ms Nov 05 06:15:31 volumio volumio[2864]: info: CoreCommandRouter::volumiosetStartupVolume Nov 05 06:15:31 volumio volumio[2864]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 05 06:15:31 volumio volumio[2864]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 05 06:15:31 volumio volumio[2864]: info: CoreCommandRouter::Close All Modals sent Nov 05 06:15:31 volumio volumio[2864]: info: CoreCommandRouter::Close All Modals sent Nov 05 06:15:31 volumio volumio[2864]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Nov 05 06:15:31 volumio volumio[2864]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 05 06:15:31 volumio volumio[2864]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Nov 05 06:15:32 volumio volumio-remote-updater[874]: Test mode disabled Nov 05 06:15:32 volumio volumio-remote-updater[874]: Alpha mode disabled Nov 05 06:15:32 volumio volumio-remote-updater[874]: Alpha legacy test mode disabled Nov 05 06:15:32 volumio volumio[2864]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateEnabled Nov 05 06:15:32 volumio volumio[2864]: info: Update Ready: {"changeLogLink":"","description":"You're already on the latest version","title":"No Updates Available","updateavailable":false} Nov 05 06:15:32 volumio volumio[2864]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache Nov 05 06:15:32 volumio volumio[2864]: info: Initializing connection to go-librespot Websocket Nov 05 06:15:32 volumio volumio[2864]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 05 06:15:32 volumio volumio[2864]: info: CoreCommandRouter::volumioGetState Nov 05 06:15:32 volumio volumio[2864]: info: CorePlayQueue::getTrack 0 Nov 05 06:15:32 volumio volumio[2864]: info: Listing playlists Nov 05 06:15:32 volumio volumio[2864]: info: Listing playlists Nov 05 06:15:32 volumio volumio[2864]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable Nov 05 06:15:32 volumio volumio[2864]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Nov 05 06:15:32 volumio volumio[2864]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect Nov 05 06:15:33 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 97. Nov 05 06:15:33 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Nov 05 06:15:33 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Nov 05 06:15:33 volumio go-librespot[3312]: go-librespot daemon starting... Nov 05 06:15:33 volumio go-librespot[3313]: time="2025-11-05T06:15:33Z" level=info msg="running go-librespot 0.4.0" Nov 05 06:15:33 volumio go-librespot[3313]: time="2025-11-05T06:15:33Z" level=debug msg="app state loaded" Nov 05 06:15:33 volumio go-librespot[3313]: time="2025-11-05T06:15:33Z" level=info msg="api server listening on 127.0.0.1:9879" Nov 05 06:15:33 volumio go-librespot[3313]: time="2025-11-05T06:15:33Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Nov 05 06:15:33 volumio go-librespot[3313]: time="2025-11-05T06:15:33Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Nov 05 06:15:33 volumio go-librespot[3313]: time="2025-11-05T06:15:33Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Nov 05 06:15:33 volumio go-librespot[3313]: time="2025-11-05T06:15:33Z" level=info msg="zeroconf server listening on port 37523" Nov 05 06:15:33 volumio go-librespot[3313]: time="2025-11-05T06:15:33Z" level=debug msg="obtained new client token: AABg3KtmF0+J3LcSG0mRoceUiZxJ3DPB2OKrhEYv5xQulpEQtBJR/4LgAJESHjwTgHm+i6vKF1lY6o6zHMh/0vaw4Nmeo5agVXrno6m8JHUf6uZe+ItPofg4qGo55Qn8jceC2gqfDQ4hE0m7Z7y0nniPB06ZAqMZCET4WjQX8h7HTwFX4MFPw/6fJav+y03fBIZ/NBDEFYpQWrQcmpnFBm9W0RsiqhucCyEwP4yJofeDOk4IVWLGy1I=" Nov 05 06:15:33 volumio go-librespot[3313]: time="2025-11-05T06:15:33Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Nov 05 06:15:33 volumio go-librespot[3313]: time="2025-11-05T06:15:33Z" level=debug msg="completed keyexchange" Nov 05 06:15:33 volumio go-librespot[3313]: time="2025-11-05T06:15:33Z" level=debug msg="completed challenge" Nov 05 06:15:33 volumio go-librespot[3313]: time="2025-11-05T06:15:33Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Nov 05 06:15:33 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 05 06:15:33 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 05 06:15:35 volumio volumio[2864]: info: Initializing connection to go-librespot Websocket Nov 05 06:15:35 volumio volumio[2864]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 05 06:15:37 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 98. Nov 05 06:15:37 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Nov 05 06:15:37 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Nov 05 06:15:37 volumio go-librespot[3320]: go-librespot daemon starting... Nov 05 06:15:37 volumio go-librespot[3321]: time="2025-11-05T06:15:37Z" level=info msg="running go-librespot 0.4.0" Nov 05 06:15:37 volumio go-librespot[3321]: time="2025-11-05T06:15:37Z" level=debug msg="app state loaded" Nov 05 06:15:37 volumio go-librespot[3321]: time="2025-11-05T06:15:37Z" level=info msg="api server listening on 127.0.0.1:9879" Nov 05 06:15:37 volumio go-librespot[3321]: time="2025-11-05T06:15:37Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Nov 05 06:15:37 volumio go-librespot[3321]: time="2025-11-05T06:15:37Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Nov 05 06:15:37 volumio go-librespot[3321]: time="2025-11-05T06:15:37Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Nov 05 06:15:37 volumio go-librespot[3321]: time="2025-11-05T06:15:37Z" level=info msg="zeroconf server listening on port 41865" Nov 05 06:15:37 volumio go-librespot[3321]: time="2025-11-05T06:15:37Z" level=debug msg="obtained new client token: AADlH1xSyIFCz3DHxvG6m2mKUBs51Al7LXlcNXbacq0Pzt2mc/+Pj9W49SOo+8XwHP8YVN9T0kUw3Ov9GLB86bUEvaQ4Xc9vOFYw/AMb3PI/NgYek4SAZxN4GFnpR9xMZYRb6VYTT6XTRx6KU+wBFUK0oBC+NbiHwqF8a34RLab06FiSGUt9z8ad1Af1OgG7JuU8lY5cdu/OWjKbipKahnyDO6KGFOtBjYisx/Os+Aa3apdbUTNk" Nov 05 06:15:37 volumio go-librespot[3321]: time="2025-11-05T06:15:37Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Nov 05 06:15:37 volumio go-librespot[3321]: time="2025-11-05T06:15:37Z" level=debug msg="completed keyexchange" Nov 05 06:15:37 volumio go-librespot[3321]: time="2025-11-05T06:15:37Z" level=debug msg="completed challenge" Nov 05 06:15:37 volumio go-librespot[3321]: time="2025-11-05T06:15:37Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Nov 05 06:15:37 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 05 06:15:37 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 05 06:15:38 volumio volumio[2864]: info: Initializing connection to go-librespot Websocket Nov 05 06:15:38 volumio volumio[2864]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 05 06:15:38 volumio volumio[2864]: info: BOOT COMPLETED Nov 05 06:15:40 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 99. Nov 05 06:15:40 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Nov 05 06:15:40 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Nov 05 06:15:40 volumio go-librespot[3343]: go-librespot daemon starting... Nov 05 06:15:40 volumio go-librespot[3344]: time="2025-11-05T06:15:40Z" level=info msg="running go-librespot 0.4.0" Nov 05 06:15:40 volumio go-librespot[3344]: time="2025-11-05T06:15:40Z" level=debug msg="app state loaded" Nov 05 06:15:40 volumio go-librespot[3344]: time="2025-11-05T06:15:40Z" level=info msg="api server listening on 127.0.0.1:9879" Nov 05 06:15:40 volumio go-librespot[3344]: time="2025-11-05T06:15:40Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Nov 05 06:15:40 volumio go-librespot[3344]: time="2025-11-05T06:15:40Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Nov 05 06:15:40 volumio go-librespot[3344]: time="2025-11-05T06:15:40Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Nov 05 06:15:40 volumio go-librespot[3344]: time="2025-11-05T06:15:40Z" level=info msg="zeroconf server listening on port 44629" Nov 05 06:15:40 volumio go-librespot[3344]: time="2025-11-05T06:15:40Z" level=debug msg="obtained new client token: AAD7VeLskU9aeS1QpufOl1+Xapv8of47g/r8TyvqklwlZDRO/S7o+L5OIaHBrIvS0+NFs8SzbDu6t6xwhEtBVMA2747PwIsHA/U2zeCJ3aJ06LiwDTHykSqO4RBuEK3wdVF/6Nt8COXfIBtK1thIqoOQy+r5NQ+XClyIpfkmdWql1VlZmxlFFAmjEJVKnFid/F/cKR4WNorCTxV3gyiuMttWQ+otkJpT6eseMdHApVc+y4Nw4Ip8yYc=" Nov 05 06:15:40 volumio go-librespot[3344]: time="2025-11-05T06:15:40Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Nov 05 06:15:40 volumio go-librespot[3344]: time="2025-11-05T06:15:40Z" level=debug msg="completed keyexchange" Nov 05 06:15:40 volumio go-librespot[3344]: time="2025-11-05T06:15:40Z" level=debug msg="completed challenge" Nov 05 06:15:40 volumio go-librespot[3344]: time="2025-11-05T06:15:40Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Nov 05 06:15:40 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 05 06:15:40 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 05 06:15:41 volumio volumio[2864]: info: Initializing connection to go-librespot Websocket Nov 05 06:15:41 volumio volumio[2864]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 05 06:15:42 volumio volumio[2864]: info: CoreCommandRouter::volumioGetState Nov 05 06:15:42 volumio volumio[2864]: info: CorePlayQueue::getTrack 0 Nov 05 06:15:44 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 100. Nov 05 06:15:44 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Nov 05 06:15:44 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Nov 05 06:15:44 volumio go-librespot[3353]: go-librespot daemon starting... Nov 05 06:15:44 volumio go-librespot[3354]: time="2025-11-05T06:15:44Z" level=info msg="running go-librespot 0.4.0" Nov 05 06:15:44 volumio go-librespot[3354]: time="2025-11-05T06:15:44Z" level=debug msg="app state loaded" Nov 05 06:15:44 volumio go-librespot[3354]: time="2025-11-05T06:15:44Z" level=info msg="api server listening on 127.0.0.1:9879" Nov 05 06:15:44 volumio go-librespot[3354]: time="2025-11-05T06:15:44Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Nov 05 06:15:44 volumio go-librespot[3354]: time="2025-11-05T06:15:44Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Nov 05 06:15:44 volumio go-librespot[3354]: time="2025-11-05T06:15:44Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Nov 05 06:15:44 volumio go-librespot[3354]: time="2025-11-05T06:15:44Z" level=info msg="zeroconf server listening on port 37269" Nov 05 06:15:44 volumio go-librespot[3354]: time="2025-11-05T06:15:44Z" level=debug msg="obtained new client token: AAByAUKgxkWRmFD9TDrFKG9xy0kgSNqvAQPOUWFcFoq2Pjs7N9SA8LsAUhPmRPqwqsJQLf4xDGZskNL3ysuVFMmkQETUfc/NPU8tm7fFytuMUZuQ+Xei/nKw4hzPG3LM9O7I7uCJ+jO72WRvTcwGzuHPoPdt13WQVuaDcnsu0MZ2equh+XF91PW3I5U3UECdrlilLb35zT3ct8/s3eJlqe4paM421ItH9cuivUAV0QtyV6LQ9Q/L" Nov 05 06:15:44 volumio go-librespot[3354]: time="2025-11-05T06:15:44Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Nov 05 06:15:44 volumio go-librespot[3354]: time="2025-11-05T06:15:44Z" level=debug msg="completed keyexchange" Nov 05 06:15:44 volumio go-librespot[3354]: time="2025-11-05T06:15:44Z" level=debug msg="completed challenge" Nov 05 06:15:44 volumio go-librespot[3354]: time="2025-11-05T06:15:44Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Nov 05 06:15:44 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 05 06:15:44 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 05 06:15:44 volumio volumio[2864]: info: Initializing connection to go-librespot Websocket Nov 05 06:15:44 volumio volumio[2864]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 05 06:15:47 volumio volumio[2864]: info: Initializing connection to go-librespot Websocket Nov 05 06:15:47 volumio volumio[2864]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 05 06:15:47 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 101. Nov 05 06:15:47 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Nov 05 06:15:47 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Nov 05 06:15:47 volumio go-librespot[3364]: go-librespot daemon starting... Nov 05 06:15:47 volumio go-librespot[3365]: time="2025-11-05T06:15:47Z" level=info msg="running go-librespot 0.4.0" Nov 05 06:15:47 volumio go-librespot[3365]: time="2025-11-05T06:15:47Z" level=debug msg="app state loaded" Nov 05 06:15:47 volumio go-librespot[3365]: time="2025-11-05T06:15:47Z" level=info msg="api server listening on 127.0.0.1:9879" Nov 05 06:15:47 volumio go-librespot[3365]: time="2025-11-05T06:15:47Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Nov 05 06:15:47 volumio go-librespot[3365]: time="2025-11-05T06:15:47Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Nov 05 06:15:47 volumio go-librespot[3365]: time="2025-11-05T06:15:47Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Nov 05 06:15:47 volumio go-librespot[3365]: time="2025-11-05T06:15:47Z" level=info msg="zeroconf server listening on port 41793" Nov 05 06:15:47 volumio go-librespot[3365]: time="2025-11-05T06:15:47Z" level=debug msg="obtained new client token: AACDjNHrHtvLc3/I3IBNE9bRASh8B2iMe8iwiw9ieM6fAQqXpQ2hpCqXMYpe0SgjhJsuWvSirlBZg+PzRgzuEJDmIsVXmx25MqcCS1jBZRuvDZPsPIsEAQ60I6l9UZStrYyvuAWQ+P5G275eouzSNAGxlj7+i6OSN64L6wtZWsZDTRkoujeCTLMd0NmR4Cuxj8yHKjWQBHdekMHFZ/HW0EedlsuNhAbKZnf0mXvoRDjCn8daSjJuLqE=" Nov 05 06:15:47 volumio go-librespot[3365]: time="2025-11-05T06:15:47Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Nov 05 06:15:47 volumio go-librespot[3365]: time="2025-11-05T06:15:47Z" level=debug msg="completed keyexchange" Nov 05 06:15:47 volumio go-librespot[3365]: time="2025-11-05T06:15:47Z" level=debug msg="completed challenge" Nov 05 06:15:47 volumio go-librespot[3365]: time="2025-11-05T06:15:47Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Nov 05 06:15:47 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 05 06:15:47 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 05 06:15:50 volumio volumio[2864]: info: Initializing connection to go-librespot Websocket Nov 05 06:15:50 volumio volumio[2864]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 05 06:15:51 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 102. Nov 05 06:15:51 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Nov 05 06:15:51 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Nov 05 06:15:51 volumio go-librespot[3389]: go-librespot daemon starting... Nov 05 06:15:51 volumio go-librespot[3390]: time="2025-11-05T06:15:51Z" level=info msg="running go-librespot 0.4.0" Nov 05 06:15:51 volumio go-librespot[3390]: time="2025-11-05T06:15:51Z" level=debug msg="app state loaded" Nov 05 06:15:51 volumio go-librespot[3390]: time="2025-11-05T06:15:51Z" level=info msg="api server listening on 127.0.0.1:9879" Nov 05 06:15:51 volumio go-librespot[3390]: time="2025-11-05T06:15:51Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Nov 05 06:15:51 volumio go-librespot[3390]: time="2025-11-05T06:15:51Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Nov 05 06:15:51 volumio go-librespot[3390]: time="2025-11-05T06:15:51Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Nov 05 06:15:51 volumio go-librespot[3390]: time="2025-11-05T06:15:51Z" level=info msg="zeroconf server listening on port 40131" Nov 05 06:15:51 volumio go-librespot[3390]: time="2025-11-05T06:15:51Z" level=debug msg="obtained new client token: AABeJqusgX3ktPkxP26ZpuyKWkukd4lqSbzvURatSC/0mB4yvZtTE0Ne1jbiT/K+FAJk4XgGS1Q2Ha0Mq1McRsYTNZF+NvFOqXnF0Dzm5dlClQO0d/qOvLfkA9sYMEqh3wCRVv65LI1xTlLGMv94hXSi9cT02JaX3o9JRIaDsLTrXtl2QJU6yPx+61K+vvx5d1pqKXW/OCYroDofkOJTy6T6IRHaCDuxrrG6oCdoK/WgziakWjfH" Nov 05 06:15:51 volumio go-librespot[3390]: time="2025-11-05T06:15:51Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Nov 05 06:15:51 volumio go-librespot[3390]: time="2025-11-05T06:15:51Z" level=debug msg="completed keyexchange" Nov 05 06:15:51 volumio go-librespot[3390]: time="2025-11-05T06:15:51Z" level=debug msg="completed challenge" Nov 05 06:15:51 volumio go-librespot[3390]: time="2025-11-05T06:15:51Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Nov 05 06:15:51 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 05 06:15:51 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 05 06:15:52 volumio volumio[2864]: info: CoreCommandRouter::volumioGetState Nov 05 06:15:52 volumio volumio[2864]: info: CorePlayQueue::getTrack 0 Nov 05 06:15:52 volumio volumio[2864]: info: Listing playlists Nov 05 06:15:52 volumio volumio[2864]: info: Listing playlists Nov 05 06:15:53 volumio volumio[2864]: info: Initializing connection to go-librespot Websocket Nov 05 06:15:53 volumio volumio[2864]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 05 06:15:54 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 103. Nov 05 06:15:54 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Nov 05 06:15:54 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Nov 05 06:15:54 volumio go-librespot[3397]: go-librespot daemon starting... Nov 05 06:15:54 volumio go-librespot[3398]: time="2025-11-05T06:15:54Z" level=info msg="running go-librespot 0.4.0" Nov 05 06:15:54 volumio go-librespot[3398]: time="2025-11-05T06:15:54Z" level=debug msg="app state loaded" Nov 05 06:15:54 volumio go-librespot[3398]: time="2025-11-05T06:15:54Z" level=info msg="api server listening on 127.0.0.1:9879" Nov 05 06:15:54 volumio go-librespot[3398]: time="2025-11-05T06:15:54Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Nov 05 06:15:54 volumio go-librespot[3398]: time="2025-11-05T06:15:54Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Nov 05 06:15:54 volumio go-librespot[3398]: time="2025-11-05T06:15:54Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Nov 05 06:15:54 volumio go-librespot[3398]: time="2025-11-05T06:15:54Z" level=info msg="zeroconf server listening on port 37421" Nov 05 06:15:54 volumio go-librespot[3398]: time="2025-11-05T06:15:54Z" level=debug msg="obtained new client token: AACeQVju0Iv8nugrRWUye3XJWo3Sg2PAiPW/bcmAPCyfDGaN17GUVVuK1QAwjouzsRlGAqnQXJw4FQLXYNHKw3qugUeddWs32q1DfU8bG8HhvRLBKy8g+x8yWyaM0zEM5Vbg5gWuP0Id3G9rixX7frIw5wqEWq/uunMpYJ3+Ywt5hnyo8JO+tIyDLUPK6sbrCamfX6hORK+Cu33CTAN5U3okcK12N3DF4S3+p/1LaunbnQiMcjXlvNY=" Nov 05 06:15:54 volumio go-librespot[3398]: time="2025-11-05T06:15:54Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Nov 05 06:15:54 volumio go-librespot[3398]: time="2025-11-05T06:15:54Z" level=debug msg="completed keyexchange" Nov 05 06:15:54 volumio go-librespot[3398]: time="2025-11-05T06:15:54Z" level=debug msg="completed challenge" Nov 05 06:15:54 volumio go-librespot[3398]: time="2025-11-05T06:15:54Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Nov 05 06:15:54 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 05 06:15:54 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 05 06:15:56 volumio volumio[2864]: info: Initializing connection to go-librespot Websocket Nov 05 06:15:56 volumio volumio[2864]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 05 06:15:58 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 104. Nov 05 06:15:58 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Nov 05 06:15:58 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Nov 05 06:15:58 volumio go-librespot[3405]: go-librespot daemon starting... Nov 05 06:15:58 volumio go-librespot[3406]: time="2025-11-05T06:15:58Z" level=info msg="running go-librespot 0.4.0" Nov 05 06:15:58 volumio go-librespot[3406]: time="2025-11-05T06:15:58Z" level=debug msg="app state loaded" Nov 05 06:15:58 volumio go-librespot[3406]: time="2025-11-05T06:15:58Z" level=info msg="api server listening on 127.0.0.1:9879" Nov 05 06:15:58 volumio go-librespot[3406]: time="2025-11-05T06:15:58Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Nov 05 06:15:58 volumio go-librespot[3406]: time="2025-11-05T06:15:58Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Nov 05 06:15:58 volumio go-librespot[3406]: time="2025-11-05T06:15:58Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Nov 05 06:15:58 volumio go-librespot[3406]: time="2025-11-05T06:15:58Z" level=info msg="zeroconf server listening on port 32859" Nov 05 06:15:58 volumio go-librespot[3406]: time="2025-11-05T06:15:58Z" level=debug msg="obtained new client token: AADyUjmxNTymyn47AKPtsOhNLlB4+Jec5V9jpjcjCO/jMcWUE6b0P/BslOvzlaf5M7NuKxY1m7kUK8TiHOvOMM1/PQ0Hk2k9ZVGviKIX2O5CTXSt6S1CXVtM0bB10xuTJ7q+iYJVtt2baTDkLx1dF3a0PfaNgnPPdeb28YGWaHTj1g5Hys2LqNPmH6lCzfeuaz0opnBbP626Ru38Gu3UVdojO8d71cT83gGEPnF0FLFBl9qAsxi1" Nov 05 06:15:58 volumio go-librespot[3406]: time="2025-11-05T06:15:58Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Nov 05 06:15:58 volumio go-librespot[3406]: time="2025-11-05T06:15:58Z" level=debug msg="completed keyexchange" Nov 05 06:15:58 volumio go-librespot[3406]: time="2025-11-05T06:15:58Z" level=debug msg="completed challenge" Nov 05 06:15:58 volumio go-librespot[3406]: time="2025-11-05T06:15:58Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Nov 05 06:15:58 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 05 06:15:58 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 05 06:15:59 volumio volumio[2864]: info: Initializing connection to go-librespot Websocket Nov 05 06:15:59 volumio volumio[2864]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 05 06:16:01 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 105. Nov 05 06:16:01 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Nov 05 06:16:01 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Nov 05 06:16:01 volumio go-librespot[3427]: go-librespot daemon starting... Nov 05 06:16:01 volumio go-librespot[3428]: time="2025-11-05T06:16:01Z" level=info msg="running go-librespot 0.4.0" Nov 05 06:16:01 volumio go-librespot[3428]: time="2025-11-05T06:16:01Z" level=debug msg="app state loaded" Nov 05 06:16:01 volumio go-librespot[3428]: time="2025-11-05T06:16:01Z" level=info msg="api server listening on 127.0.0.1:9879" Nov 05 06:16:01 volumio go-librespot[3428]: time="2025-11-05T06:16:01Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Nov 05 06:16:01 volumio go-librespot[3428]: time="2025-11-05T06:16:01Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Nov 05 06:16:01 volumio go-librespot[3428]: time="2025-11-05T06:16:01Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Nov 05 06:16:01 volumio go-librespot[3428]: time="2025-11-05T06:16:01Z" level=info msg="zeroconf server listening on port 45475" Nov 05 06:16:01 volumio go-librespot[3428]: time="2025-11-05T06:16:01Z" level=debug msg="obtained new client token: AAAhTNE4oeH7mJtCkqHFcescN7CnffqGD9jOk6926OfdZDkz6G3UjLI/le8o+1o2xW3yQN/yaA81PEJDNuNAFfPR4aaLTon5I0IqbzFLX2HymdUFcKko8sBDaviTwmLCxTyBtscH0m/cB5kH6xDgkTjv8gaSwcUPOrnU8BIuBjy4musWQH72SbIbxZ6KFXG+hF0c/zBFArMiu5ps0JIyL7fbx1bVdZJso4PIH8Lc2jnGHw9sDkybBP0=" Nov 05 06:16:01 volumio go-librespot[3428]: time="2025-11-05T06:16:01Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Nov 05 06:16:01 volumio go-librespot[3428]: time="2025-11-05T06:16:01Z" level=debug msg="completed keyexchange" Nov 05 06:16:01 volumio go-librespot[3428]: time="2025-11-05T06:16:01Z" level=debug msg="completed challenge" Nov 05 06:16:01 volumio go-librespot[3428]: time="2025-11-05T06:16:01Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Nov 05 06:16:01 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 05 06:16:01 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 05 06:16:02 volumio volumio[2864]: info: Initializing connection to go-librespot Websocket Nov 05 06:16:02 volumio volumio[2864]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 05 06:16:02 volumio volumio[2864]: info: CoreCommandRouter::volumioGetState Nov 05 06:16:02 volumio volumio[2864]: info: CorePlayQueue::getTrack 0 Nov 05 06:16:05 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 106. Nov 05 06:16:05 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Nov 05 06:16:05 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Nov 05 06:16:05 volumio go-librespot[3435]: go-librespot daemon starting... Nov 05 06:16:05 volumio go-librespot[3436]: time="2025-11-05T06:16:05Z" level=info msg="running go-librespot 0.4.0" Nov 05 06:16:05 volumio go-librespot[3436]: time="2025-11-05T06:16:05Z" level=debug msg="app state loaded" Nov 05 06:16:05 volumio go-librespot[3436]: time="2025-11-05T06:16:05Z" level=info msg="api server listening on 127.0.0.1:9879" Nov 05 06:16:05 volumio go-librespot[3436]: time="2025-11-05T06:16:05Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Nov 05 06:16:05 volumio go-librespot[3436]: time="2025-11-05T06:16:05Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Nov 05 06:16:05 volumio go-librespot[3436]: time="2025-11-05T06:16:05Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Nov 05 06:16:05 volumio go-librespot[3436]: time="2025-11-05T06:16:05Z" level=info msg="zeroconf server listening on port 43913" Nov 05 06:16:05 volumio go-librespot[3436]: time="2025-11-05T06:16:05Z" level=debug msg="obtained new client token: AAA1Yc4mkW2ItAvROqya0h17Wf1mFc+hLkSsCWhyUVSGbwkqcWB1hx972qQAKgVf6nslKaQvRNvOn80Sus414dZD6wV8dOkei6I+XKKi/tzvhED4/gG67N3e80CJbamnhIwiv0j+kMhx6ikpk+jxVyYVGIytvbH9TU5KuL/gkMavi8OBxitVT+Fyomyig3PL+mbwa5UmmDfPxDog1opHWELYvrbfn4BYGsFxG4fcURiAxOl4JfBk" Nov 05 06:16:05 volumio go-librespot[3436]: time="2025-11-05T06:16:05Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Nov 05 06:16:05 volumio go-librespot[3436]: time="2025-11-05T06:16:05Z" level=debug msg="completed keyexchange" Nov 05 06:16:05 volumio go-librespot[3436]: time="2025-11-05T06:16:05Z" level=debug msg="completed challenge" Nov 05 06:16:05 volumio go-librespot[3436]: time="2025-11-05T06:16:05Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Nov 05 06:16:05 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 05 06:16:05 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 05 06:16:05 volumio volumio[2864]: info: Initializing connection to go-librespot Websocket Nov 05 06:16:05 volumio volumio[2864]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 05 06:16:08 volumio volumio[2864]: info: Initializing connection to go-librespot Websocket Nov 05 06:16:08 volumio volumio[2864]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 05 06:16:08 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 107. Nov 05 06:16:08 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Nov 05 06:16:08 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Nov 05 06:16:08 volumio go-librespot[3446]: go-librespot daemon starting... Nov 05 06:16:08 volumio go-librespot[3447]: time="2025-11-05T06:16:08Z" level=info msg="running go-librespot 0.4.0" Nov 05 06:16:08 volumio go-librespot[3447]: time="2025-11-05T06:16:08Z" level=debug msg="app state loaded" Nov 05 06:16:08 volumio go-librespot[3447]: time="2025-11-05T06:16:08Z" level=info msg="api server listening on 127.0.0.1:9879" Nov 05 06:16:08 volumio go-librespot[3447]: time="2025-11-05T06:16:08Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Nov 05 06:16:08 volumio go-librespot[3447]: time="2025-11-05T06:16:08Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Nov 05 06:16:08 volumio go-librespot[3447]: time="2025-11-05T06:16:08Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Nov 05 06:16:08 volumio go-librespot[3447]: time="2025-11-05T06:16:08Z" level=info msg="zeroconf server listening on port 44377" Nov 05 06:16:08 volumio go-librespot[3447]: time="2025-11-05T06:16:08Z" level=debug msg="obtained new client token: AACTuMKxG96WqIeLjSfaDNTs47x+AbDXViys1lcSg64P0gAIkDJdpejwsiVnWilsaajm97EWPNJB0r/HWeadm7bHPSZ14WwGuQ+OK/vClv9LnItdmOwV3RAi4dSW2i45prYWa9qwH7Ty16MhjlpNzUnpD3SZvrfmbEkU/Gao/aOtV2CYAaHTTvwKq+xbOMShWul0q7m2VmDlmdXMPsouunWIlMpKzkf+Z2TT6TNGsdWP+8FcYkXOmsg=" Nov 05 06:16:08 volumio go-librespot[3447]: time="2025-11-05T06:16:08Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Nov 05 06:16:08 volumio go-librespot[3447]: time="2025-11-05T06:16:08Z" level=debug msg="completed keyexchange" Nov 05 06:16:08 volumio go-librespot[3447]: time="2025-11-05T06:16:08Z" level=debug msg="completed challenge" Nov 05 06:16:08 volumio go-librespot[3447]: time="2025-11-05T06:16:08Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Nov 05 06:16:08 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 05 06:16:08 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 05 06:16:10 volumio kernel: nfs: server 192.168.1.3 not responding, timed out Nov 05 06:16:11 volumio volumio[2864]: info: Initializing connection to go-librespot Websocket Nov 05 06:16:11 volumio volumio[2864]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 05 06:16:12 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 108. Nov 05 06:16:12 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Nov 05 06:16:12 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Nov 05 06:16:12 volumio go-librespot[3468]: go-librespot daemon starting... Nov 05 06:16:12 volumio go-librespot[3469]: time="2025-11-05T06:16:12Z" level=info msg="running go-librespot 0.4.0" Nov 05 06:16:12 volumio go-librespot[3469]: time="2025-11-05T06:16:12Z" level=debug msg="app state loaded" Nov 05 06:16:12 volumio go-librespot[3469]: time="2025-11-05T06:16:12Z" level=info msg="api server listening on 127.0.0.1:9879" Nov 05 06:16:12 volumio go-librespot[3469]: time="2025-11-05T06:16:12Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Nov 05 06:16:12 volumio go-librespot[3469]: time="2025-11-05T06:16:12Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Nov 05 06:16:12 volumio go-librespot[3469]: time="2025-11-05T06:16:12Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Nov 05 06:16:12 volumio go-librespot[3469]: time="2025-11-05T06:16:12Z" level=info msg="zeroconf server listening on port 39515" Nov 05 06:16:12 volumio go-librespot[3469]: time="2025-11-05T06:16:12Z" level=debug msg="obtained new client token: AAA+r5yrYXKQcPr2VUX4E3PbR/n1/TETw0y1RIro4OrkvexKv+Tm1/qoiJNAuB/0b7UL/V0UVfM9HxF/SepD1nydhx30iBMK0+4j3tvP05gJHlDzREbLjmzCjINnz87cYNCTRIl+DfRyk8Z51rGj9pF6yIUIgjPl67sQcO17O3wzz5IBibDk+xp9Ri8LzZHUvbpa2qL1wmgGHajROR5rGFfQeupTC7ufOeX68UrlafENux3O3SjQ" Nov 05 06:16:12 volumio go-librespot[3469]: time="2025-11-05T06:16:12Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Nov 05 06:16:12 volumio go-librespot[3469]: time="2025-11-05T06:16:12Z" level=debug msg="completed keyexchange" Nov 05 06:16:12 volumio go-librespot[3469]: time="2025-11-05T06:16:12Z" level=debug msg="completed challenge" Nov 05 06:16:12 volumio go-librespot[3469]: time="2025-11-05T06:16:12Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Nov 05 06:16:12 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 05 06:16:12 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 05 06:16:12 volumio volumio[2864]: info: CoreCommandRouter::volumioGetState Nov 05 06:16:12 volumio volumio[2864]: info: CorePlayQueue::getTrack 0 Nov 05 06:16:12 volumio volumio[2864]: info: Listing playlists Nov 05 06:16:12 volumio volumio[2864]: info: Listing playlists Nov 05 06:16:14 volumio volumio[2864]: info: Initializing connection to go-librespot Websocket Nov 05 06:16:14 volumio volumio[2864]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 05 06:16:14 volumio kernel: nfs: server 192.168.1.3 not responding, timed out Nov 05 06:16:15 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 109. Nov 05 06:16:15 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Nov 05 06:16:15 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Nov 05 06:16:15 volumio go-librespot[3476]: go-librespot daemon starting... Nov 05 06:16:15 volumio go-librespot[3477]: time="2025-11-05T06:16:15Z" level=info msg="running go-librespot 0.4.0" Nov 05 06:16:15 volumio go-librespot[3477]: time="2025-11-05T06:16:15Z" level=debug msg="app state loaded" Nov 05 06:16:15 volumio go-librespot[3477]: time="2025-11-05T06:16:15Z" level=info msg="api server listening on 127.0.0.1:9879" Nov 05 06:16:15 volumio go-librespot[3477]: time="2025-11-05T06:16:15Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Nov 05 06:16:15 volumio go-librespot[3477]: time="2025-11-05T06:16:15Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Nov 05 06:16:15 volumio go-librespot[3477]: time="2025-11-05T06:16:15Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Nov 05 06:16:15 volumio go-librespot[3477]: time="2025-11-05T06:16:15Z" level=info msg="zeroconf server listening on port 34095" Nov 05 06:16:15 volumio go-librespot[3477]: time="2025-11-05T06:16:15Z" level=debug msg="obtained new client token: AACgE6OlJ5POKMkN2WExmFwGsQpV0tYpxLGw//p4+hvQg4uDDqkfF+yQxNu0XPihzThugmx6DCtMRhXICxnxkzGpt8rTwgjTKep/0gf5RuiV71Pp+fMO44GVnI+VTh18v3wesg3Zs72i31MwrBYZ9BcWXuUWxrv4O29NRs6V3KtX8zw2lv0f8t0kUYwXtW/VLmTJMogrwf8j0DNxHDQOLQ/KCcc5HJ8DpY2zx/oFtiARAqw/1k/U5kM=" Nov 05 06:16:15 volumio go-librespot[3477]: time="2025-11-05T06:16:15Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Nov 05 06:16:15 volumio go-librespot[3477]: time="2025-11-05T06:16:15Z" level=debug msg="completed keyexchange" Nov 05 06:16:15 volumio go-librespot[3477]: time="2025-11-05T06:16:15Z" level=debug msg="completed challenge" Nov 05 06:16:15 volumio go-librespot[3477]: time="2025-11-05T06:16:15Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Nov 05 06:16:15 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 05 06:16:15 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 05 06:16:17 volumio volumio[2864]: info: Initializing connection to go-librespot Websocket Nov 05 06:16:17 volumio volumio[2864]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 05 06:16:19 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 110. Nov 05 06:16:19 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Nov 05 06:16:19 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Nov 05 06:16:19 volumio go-librespot[3484]: go-librespot daemon starting... Nov 05 06:16:19 volumio go-librespot[3485]: time="2025-11-05T06:16:19Z" level=info msg="running go-librespot 0.4.0" Nov 05 06:16:19 volumio go-librespot[3485]: time="2025-11-05T06:16:19Z" level=debug msg="app state loaded" Nov 05 06:16:19 volumio go-librespot[3485]: time="2025-11-05T06:16:19Z" level=info msg="api server listening on 127.0.0.1:9879" Nov 05 06:16:19 volumio go-librespot[3485]: time="2025-11-05T06:16:19Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Nov 05 06:16:19 volumio go-librespot[3485]: time="2025-11-05T06:16:19Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Nov 05 06:16:19 volumio go-librespot[3485]: time="2025-11-05T06:16:19Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Nov 05 06:16:19 volumio go-librespot[3485]: time="2025-11-05T06:16:19Z" level=info msg="zeroconf server listening on port 46125" Nov 05 06:16:19 volumio go-librespot[3485]: time="2025-11-05T06:16:19Z" level=debug msg="obtained new client token: AADnEojg98w8gqZY/tKzT6pSB0vykDHk755dYuGdLGkfw4V2aSKUGY0FH6OX5l2ZEYQH6uJPapjmrIrc9/IZqMl8gG0/jfQzHF3IFMgPSPXpzYeiKtGmRe92pqhtzdYvXnH+PeT+Qm7nrhvj7GmMLfeuKSUZR+CvTa3Ad43iNLLy0gVWFZxQApF+MuWp6h4KWPzoW1M0RLgUxxwlwFPsdXaMU5PyKE5sgRhhYOMtCODMfTDqoyNM" Nov 05 06:16:19 volumio go-librespot[3485]: time="2025-11-05T06:16:19Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Nov 05 06:16:19 volumio go-librespot[3485]: time="2025-11-05T06:16:19Z" level=debug msg="completed keyexchange" Nov 05 06:16:19 volumio go-librespot[3485]: time="2025-11-05T06:16:19Z" level=debug msg="completed challenge" Nov 05 06:16:19 volumio go-librespot[3485]: time="2025-11-05T06:16:19Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Nov 05 06:16:19 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 05 06:16:19 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 05 06:16:20 volumio volumio[2864]: info: Initializing connection to go-librespot Websocket Nov 05 06:16:20 volumio volumio[2864]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 05 06:16:22 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 111. Nov 05 06:16:22 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Nov 05 06:16:22 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Nov 05 06:16:22 volumio go-librespot[3508]: go-librespot daemon starting... Nov 05 06:16:22 volumio go-librespot[3509]: time="2025-11-05T06:16:22Z" level=info msg="running go-librespot 0.4.0" Nov 05 06:16:22 volumio go-librespot[3509]: time="2025-11-05T06:16:22Z" level=debug msg="app state loaded" Nov 05 06:16:22 volumio go-librespot[3509]: time="2025-11-05T06:16:22Z" level=info msg="api server listening on 127.0.0.1:9879" Nov 05 06:16:22 volumio volumio[2864]: info: CoreCommandRouter::volumioGetState Nov 05 06:16:22 volumio volumio[2864]: info: CorePlayQueue::getTrack 0 Nov 05 06:16:22 volumio go-librespot[3509]: time="2025-11-05T06:16:22Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Nov 05 06:16:22 volumio go-librespot[3509]: time="2025-11-05T06:16:22Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Nov 05 06:16:22 volumio go-librespot[3509]: time="2025-11-05T06:16:22Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Nov 05 06:16:22 volumio go-librespot[3509]: time="2025-11-05T06:16:22Z" level=info msg="zeroconf server listening on port 34515" Nov 05 06:16:22 volumio go-librespot[3509]: time="2025-11-05T06:16:22Z" level=debug msg="obtained new client token: AAD5KXiRRS9xaj005fT54m56Ope3/oQKbvvK+1Zu7+NYOZ+l1BBYjmf7Ftkz4s68Wi5Xj9uLLWuJHjqHVgX3A9zlUGkRIl0vDAUCUDuD3hfMV1dBZYV0N3mmOfLgxz7rvILkbgyX/rDX2vwgvin3hd3o6QKAZLgZrZraJKCS3ArgKkpTpj2OR4DJKU/kjzDnQGJh07Wt1MqjQfDIZrgLHPeKJVhGcuwA1TsezIWEhOa9WI42/yd0xAc=" Nov 05 06:16:22 volumio go-librespot[3509]: time="2025-11-05T06:16:22Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Nov 05 06:16:22 volumio go-librespot[3509]: time="2025-11-05T06:16:22Z" level=debug msg="completed keyexchange" Nov 05 06:16:22 volumio go-librespot[3509]: time="2025-11-05T06:16:22Z" level=debug msg="completed challenge" Nov 05 06:16:22 volumio go-librespot[3509]: time="2025-11-05T06:16:22Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Nov 05 06:16:22 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 05 06:16:22 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 05 06:16:23 volumio volumio[2864]: info: Initializing connection to go-librespot Websocket Nov 05 06:16:23 volumio volumio[2864]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 05 06:16:26 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 112. Nov 05 06:16:26 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Nov 05 06:16:26 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Nov 05 06:16:26 volumio go-librespot[3519]: go-librespot daemon starting... Nov 05 06:16:26 volumio go-librespot[3520]: time="2025-11-05T06:16:26Z" level=info msg="running go-librespot 0.4.0" Nov 05 06:16:26 volumio go-librespot[3520]: time="2025-11-05T06:16:26Z" level=debug msg="app state loaded" Nov 05 06:16:26 volumio go-librespot[3520]: time="2025-11-05T06:16:26Z" level=info msg="api server listening on 127.0.0.1:9879" Nov 05 06:16:26 volumio go-librespot[3520]: time="2025-11-05T06:16:26Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Nov 05 06:16:26 volumio go-librespot[3520]: time="2025-11-05T06:16:26Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Nov 05 06:16:26 volumio go-librespot[3520]: time="2025-11-05T06:16:26Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Nov 05 06:16:26 volumio go-librespot[3520]: time="2025-11-05T06:16:26Z" level=info msg="zeroconf server listening on port 35643" Nov 05 06:16:26 volumio go-librespot[3520]: time="2025-11-05T06:16:26Z" level=debug msg="obtained new client token: AACGFv5Rj3eIAXuOvg2w7YgIwp5E1cqiLdCHrUOddzzVHS/iMYkfRwlwZMq8ia6CO42tv4vXbzYGIWPRxeom1qH6536coGuqc26aKGjED7slQJSc5nfHosTbNSKzE47gVtx9LG82pe9jkFEmsJacgeL3N7uv0FvQhzUwpQ/b93/PeH7ykgqYIyBpPIT5SjdzDUx4kbzw45O/x8Z0lBrSUj8/UKhGSynzBenn0QBQvNnOiGONDVXL" Nov 05 06:16:26 volumio go-librespot[3520]: time="2025-11-05T06:16:26Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Nov 05 06:16:26 volumio volumio[2864]: info: Initializing connection to go-librespot Websocket Nov 05 06:16:26 volumio go-librespot[3520]: time="2025-11-05T06:16:26Z" level=debug msg="new websocket client" Nov 05 06:16:26 volumio volumio[2864]: info: Connection to go-librespot Websocket established Nov 05 06:16:26 volumio go-librespot[3520]: time="2025-11-05T06:16:26Z" level=debug msg="completed keyexchange" Nov 05 06:16:26 volumio go-librespot[3520]: time="2025-11-05T06:16:26Z" level=debug msg="completed challenge" Nov 05 06:16:26 volumio go-librespot[3520]: time="2025-11-05T06:16:26Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Nov 05 06:16:26 volumio volumio[2864]: info: Connection to go-librespot Websocket closed Nov 05 06:16:26 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 05 06:16:26 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 05 06:16:29 volumio volumio[2864]: info: Getting Spotify volume Nov 05 06:16:29 volumio volumio[2864]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Nov 05 06:16:29 volumio volumio[2864]: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 05 06:16:29 volumio volumio[2864]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Nov 05 06:16:29 volumio volumio[2864]: errno: -111, Nov 05 06:16:29 volumio volumio[2864]: code: 'ECONNREFUSED', Nov 05 06:16:29 volumio volumio[2864]: syscall: 'connect', Nov 05 06:16:29 volumio volumio[2864]: address: '127.0.0.1', Nov 05 06:16:29 volumio volumio[2864]: port: 9879, Nov 05 06:16:29 volumio volumio[2864]: response: undefined Nov 05 06:16:29 volumio volumio[2864]: } Nov 05 06:16:29 volumio volumio[2864]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Nov 05 06:16:29 volumio sudo[3541]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-11-05 06:15' Nov 05 06:16:29 volumio sudo[3541]: 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"