Oct 31 16:16:00 volumio go-librespot[7289]: time="2025-10-31T16:16:00Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: EOF" Oct 31 16:16:00 volumio volumio[6894]: error: Failed to send command to Spotify local API: /player/volume: Error: socket hang up Oct 31 16:16:00 volumio volumio[6894]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 31 16:16:00 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 31 16:16:00 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 31 16:16:00 volumio volumio[6894]: Error: socket hang up Oct 31 16:16:00 volumio volumio[6894]: at connResetException (node:internal/errors:720:14) Oct 31 16:16:00 volumio volumio[6894]: at Socket.socketOnEnd (node:_http_client:519:23) Oct 31 16:16:00 volumio volumio[6894]: at Socket.emit (node:events:526:35) Oct 31 16:16:00 volumio volumio[6894]: at endReadableNT (node:internal/streams/readable:1376:12) Oct 31 16:16:00 volumio volumio[6894]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { Oct 31 16:16:00 volumio volumio[6894]: code: 'ECONNRESET', Oct 31 16:16:00 volumio volumio[6894]: response: undefined Oct 31 16:16:00 volumio volumio[6894]: } Oct 31 16:16:00 volumio volumio[6894]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 31 16:16:00 volumio sudo[8310]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-10-31 16:15' Oct 31 16:16:00 volumio sudo[8310]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 31 16:16:00 volumio sudo[8310]: pam_unix(sudo:session): session closed for user root Oct 31 16:16:00 volumio systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Oct 31 16:16:00 volumio volumio-remote-updater[874]: [2025-10-31 16:16:00] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Oct 31 16:16:00 volumio volumio-remote-updater[874]: [2025-10-31 16:16:00] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Oct 31 16:16:00 volumio systemd[1]: volumio.service: Failed with result 'exit-code'. Oct 31 16:16:00 volumio systemd[1]: volumio.service: Consumed 8.806s CPU time. Oct 31 16:16:00 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Oct 31 16:16:00 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Oct 31 16:16:01 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 3967. Oct 31 16:16:01 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Oct 31 16:16:01 volumio systemd[1]: Stopped volumio.service - Volumio Backend Module. Oct 31 16:16:01 volumio systemd[1]: volumio.service: Consumed 8.806s CPU time. Oct 31 16:16:01 volumio systemd[1]: Started volumio.service - Volumio Backend Module. Oct 31 16:16:01 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Oct 31 16:16:01 volumio volumio[8361]: info: ------------------------------------------- Oct 31 16:16:01 volumio volumio[8361]: info: ----- Volumio3 ---- Oct 31 16:16:01 volumio volumio[8361]: info: ------------------------------------------- Oct 31 16:16:01 volumio volumio[8361]: info: ----- System startup ---- Oct 31 16:16:01 volumio volumio[8361]: info: ------------------------------------------- Oct 31 16:16:01 volumio volumio[8361]: info: MYVOLUMIO Environment detected Oct 31 16:16:01 volumio volumio[8361]: info: Plugin folders cleanup Oct 31 16:16:01 volumio volumio[8361]: info: Scanning into folder /volumio/app/plugins/ Oct 31 16:16:01 volumio volumio[8361]: info: Scanning category audio_interface Oct 31 16:16:01 volumio volumio[8361]: info: Scanning category miscellanea Oct 31 16:16:01 volumio volumio[8361]: info: Scanning category music_service Oct 31 16:16:01 volumio volumio[8361]: info: Scanning category plugins.json Oct 31 16:16:01 volumio volumio[8361]: info: Scanning category system_controller Oct 31 16:16:01 volumio volumio[8361]: info: Scanning category user_interface Oct 31 16:16:01 volumio volumio[8361]: info: Scanning into folder /data/plugins/ Oct 31 16:16:01 volumio volumio[8361]: info: Scanning category music_service Oct 31 16:16:01 volumio volumio[8361]: info: Scanning category user_interface Oct 31 16:16:01 volumio volumio[8361]: info: Plugin folders cleanup completed Oct 31 16:16:01 volumio volumio[8361]: info: ------------------------------------------- Oct 31 16:16:01 volumio volumio[8361]: info: ----- Core plugins startup ---- Oct 31 16:16:01 volumio volumio[8361]: info: ------------------------------------------- Oct 31 16:16:01 volumio volumio[8361]: info: Loading plugins from folder /volumio/app/plugins/ Oct 31 16:16:01 volumio volumio[8361]: info: Adding plugin upnp to MyMusic Plugins Oct 31 16:16:01 volumio volumio[8361]: info: Adding plugin airplay_emulation to MyMusic Plugins Oct 31 16:16:01 volumio volumio[8361]: info: Adding plugin upnp_browser to MyMusic Plugins Oct 31 16:16:01 volumio volumio[8361]: info: Loading plugins from folder /data/plugins/ Oct 31 16:16:01 volumio volumio[8361]: info: Loading plugin "system"... Oct 31 16:16:01 volumio volumio[8361]: info: Loading plugin "appearance"... Oct 31 16:16:01 volumio volumio[8361]: info: Loading plugin "network"... Oct 31 16:16:01 volumio volumio[8361]: info: Refreshing Cached IP Addresses Oct 31 16:16:01 volumio sudo[8386]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 31 16:16:01 volumio sudo[8386]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 31 16:16:01 volumio sudo[8386]: pam_unix(sudo:session): session closed for user root Oct 31 16:16:01 volumio volumio[8361]: info: Loading plugin "services"... Oct 31 16:16:01 volumio sudo[8388]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 31 16:16:01 volumio sudo[8388]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 31 16:16:01 volumio volumio[8361]: info: Loading plugin "alsa_controller"... Oct 31 16:16:01 volumio sudo[8388]: pam_unix(sudo:session): session closed for user root Oct 31 16:16:01 volumio volumio[8361]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 31 16:16:01 volumio volumio[8361]: info: Loading plugin "wizard"... Oct 31 16:16:01 volumio volumio[8361]: info: Loading plugin "networkfs"... Oct 31 16:16:01 volumio volumio[8361]: info: Cannot mount NAS NAS at system boot, trial number 1 ,retrying in 5 seconds Oct 31 16:16:01 volumio volumio[8361]: info: Starting Udev Watcher for removable devices Oct 31 16:16:01 volumio volumio[8361]: info: Ignoring mount for partition: boot Oct 31 16:16:01 volumio volumio[8361]: info: Ignoring mount for partition: volumio Oct 31 16:16:01 volumio volumio[8361]: info: Ignoring mount for partition: volumio_data Oct 31 16:16:01 volumio volumio[8361]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 31 16:16:01 volumio volumio[8361]: info: Loading plugin "volumio_command_line_client"... Oct 31 16:16:01 volumio volumio[8361]: info: Loading plugin "upnp"... Oct 31 16:16:01 volumio volumio[8361]: info: [1761927361822] Starting Upmpd Daemon Oct 31 16:16:01 volumio volumio[8361]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 31 16:16:01 volumio volumio[8361]: info: Loading plugin "my_music"... Oct 31 16:16:01 volumio volumio[8361]: info: Loading plugin "mpd"... Oct 31 16:16:01 volumio volumio[8361]: info: Loading plugin "upnp_browser"... Oct 31 16:16:02 volumio volumio[8361]: info: Loading plugin "alarm-clock"... Oct 31 16:16:02 volumio volumio[8361]: info: Loading plugin "airplay_emulation"... Oct 31 16:16:02 volumio volumio[8361]: info: Starting Shairport Sync Oct 31 16:16:02 volumio volumio[8361]: info: Loading plugin "last_100"... Oct 31 16:16:02 volumio volumio[8361]: info: Loading plugin "webradio"... Oct 31 16:16:02 volumio volumio[8361]: info: Loading plugin "i2s_dacs"... Oct 31 16:16:02 volumio volumio[8361]: info: I2S DAC not set, start Auto-detection Oct 31 16:16:02 volumio volumio[8361]: info: Loading plugin "volumiodiscovery"... Oct 31 16:16:02 volumio volumio[8361]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Oct 31 16:16:02 volumio node[8361]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Oct 31 16:16:02 volumio volumio[8361]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 31 16:16:02 volumio node[8361]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 31 16:16:02 volumio volumio[8361]: *** WARNING *** For more information see Oct 31 16:16:02 volumio node[8361]: *** WARNING *** For more information see Oct 31 16:16:02 volumio volumio[8361]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Oct 31 16:16:02 volumio node[8361]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Oct 31 16:16:02 volumio volumio[8361]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 31 16:16:02 volumio node[8361]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 31 16:16:02 volumio volumio[8361]: *** WARNING *** For more information see Oct 31 16:16:02 volumio volumio[8361]: info: Applying required configuration parameters for plugin volumiodiscovery Oct 31 16:16:02 volumio volumio[8361]: info: Discovery: Started advertising with name: Volumio Oct 31 16:16:02 volumio node[8361]: *** WARNING *** For more information see Oct 31 16:16:02 volumio volumio[8361]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 31 16:16:02 volumio volumio[8361]: info: Loading plugin "spop"... Oct 31 16:16:02 volumio volumio[8361]: info: Loading plugin "ytcr"... Oct 31 16:16:03 volumio volumio[8361]: info: Loading plugin "outputs"... Oct 31 16:16:03 volumio volumio[8361]: info: Loading plugin "albumart"... Oct 31 16:16:03 volumio volumio[8361]: info: Plugin example_plugin is not enabled Oct 31 16:16:03 volumio volumio[8361]: info: Loading plugin "inputs"... Oct 31 16:16:03 volumio volumio[8361]: info: Loading plugin "updater_comm"... Oct 31 16:16:03 volumio volumio[8361]: info: Plugin mpdemulation is not enabled Oct 31 16:16:03 volumio volumio[8361]: info: Loading plugin "rest_api"... Oct 31 16:16:03 volumio volumio[8361]: info: Loading plugin "websocket"... Oct 31 16:16:03 volumio volumio[8361]: info: Starting Socket.io Server version 1.7.4 Oct 31 16:16:03 volumio volumio[8361]: info: Loading plugin "Systeminfo"... Oct 31 16:16:03 volumio volumio[8361]: info: Loading i18n strings for locale en Oct 31 16:16:03 volumio volumio[8361]: Updating browse sources language Oct 31 16:16:03 volumio volumio[8361]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 31 16:16:03 volumio volumio[8421]: Forking 3 albumart workers Oct 31 16:16:03 volumio volumio[8361]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 31 16:16:03 volumio volumio[8361]: info: CoreCommandRouter::initPlayerControls Oct 31 16:16:03 volumio volumio[8361]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 16:16:03 volumio volumio[8361]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 16:16:03 volumio volumio[8361]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 16:16:03 volumio volumio[8361]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 16:16:03 volumio volumio[8361]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 16:16:03 volumio volumio[8361]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 16:16:03 volumio volumio[8361]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 16:16:03 volumio volumio[8361]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 16:16:03 volumio volumio[8361]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 31 16:16:03 volumio volumio[8361]: Express server listening on port 3000 Oct 31 16:16:03 volumio volumio[8361]: [Metrics] WebUI: 1s 957.66ms Oct 31 16:16:03 volumio volumio[8361]: info: CoreStateMachine::resetVolumioState Oct 31 16:16:03 volumio volumio[8361]: info: CoreStateMachine::getcurrentVolume Oct 31 16:16:03 volumio volumio[8361]: info: CoreCommandRouter::volumioRetrievevolume Oct 31 16:16:03 volumio volumio[8361]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 31 16:16:03 volumio volumio[8361]: info: Cannot read play queue from file Oct 31 16:16:03 volumio volumio[8361]: info: Volumio Network Manager: Network status updated: 1 Oct 31 16:16:03 volumio volumio[8361]: info: VolumeController:: Volume=33 Mute =false Oct 31 16:16:03 volumio volumio[8361]: info: CoreStateMachine::pushState Oct 31 16:16:03 volumio volumio[8361]: info: CorePlayQueue::getTrack 0 Oct 31 16:16:03 volumio volumio[8361]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 31 16:16:03 volumio volumio[8361]: info: CoreCommandRouter::volumioPushState Oct 31 16:16:03 volumio volumio[8361]: info: CoreStateMachine::updateTrackBlock Oct 31 16:16:03 volumio volumio[8361]: info: CorePlayQueue::getTrackBlock Oct 31 16:16:03 volumio volumio[8361]: info: CoreCommandRouter::volumioRetrievevolume Oct 31 16:16:03 volumio volumio[8361]: info: CoreStateMachine::setRepeat null single undefined Oct 31 16:16:03 volumio volumio[8361]: info: CoreStateMachine::pushState Oct 31 16:16:03 volumio volumio[8361]: info: CorePlayQueue::getTrack 0 Oct 31 16:16:03 volumio volumio[8361]: info: CoreCommandRouter::volumioPushState Oct 31 16:16:03 volumio volumio[8361]: info: CoreStateMachine::setRandom null Oct 31 16:16:03 volumio volumio[8361]: info: CoreStateMachine::pushState Oct 31 16:16:03 volumio volumio[8361]: info: CorePlayQueue::getTrack 0 Oct 31 16:16:03 volumio volumio[8361]: info: CoreCommandRouter::volumioPushState Oct 31 16:16:03 volumio volumio[8361]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Oct 31 16:16:03 volumio volumio[8361]: info: USB Boot Capable - System SBC Revision found in cpuinfo: b04170 Oct 31 16:16:03 volumio volumio[8361]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Oct 31 16:16:03 volumio volumio[8361]: info: Setting Device type: Raspberry PI Oct 31 16:16:03 volumio volumio[8361]: info: VolumeController:: Volume=33 Mute =false Oct 31 16:16:03 volumio volumio[8361]: info: CoreStateMachine::pushState Oct 31 16:16:03 volumio volumio[8361]: info: CorePlayQueue::getTrack 0 Oct 31 16:16:03 volumio volumio[8361]: info: CoreCommandRouter::volumioPushState Oct 31 16:16:03 volumio volumio[8361]: info: Completed loading Core Plugins Oct 31 16:16:03 volumio volumio[8361]: info: Preparing to generate the ALSA configuration file Oct 31 16:16:03 volumio volumio[8361]: info: Discovery: adding 70853f74-8210-4683-a3fa-e1217517bd40 Oct 31 16:16:03 volumio volumio[8361]: info: Discovery: Found device Volumio Oct 31 16:16:03 volumio volumio[8361]: info: CoreCommandRouter::volumioGetState Oct 31 16:16:03 volumio volumio[8361]: info: CorePlayQueue::getTrack 0 Oct 31 16:16:03 volumio volumio[8361]: info: Discovery: this is already registered, 70853f74-8210-4683-a3fa-e1217517bd40 Oct 31 16:16:03 volumio volumio[8361]: info: Discovery: Found device Volumio Oct 31 16:16:03 volumio volumio[8361]: info: CoreCommandRouter::volumioGetState Oct 31 16:16:03 volumio volumio[8361]: info: CorePlayQueue::getTrack 0 Oct 31 16:16:03 volumio volumio[8361]: info: Asound.conf file unchanged, so no further update is needed Oct 31 16:16:03 volumio volumio[8361]: info: Output device has changed, restarting MPD Oct 31 16:16:03 volumio volumio[8361]: info: Output device has changed, restarting Shairport Sync Oct 31 16:16:03 volumio volumio[8361]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 16:16:03 volumio volumio[8361]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 31 16:16:03 volumio sudo[8478]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 31 16:16:03 volumio sudo[8478]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 31 16:16:03 volumio sudo[8480]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 31 16:16:03 volumio sudo[8480]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 31 16:16:03 volumio sudo[8478]: pam_unix(sudo:session): session closed for user root Oct 31 16:16:03 volumio volumio[8361]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 31 16:16:03 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 11. Oct 31 16:16:03 volumio volumio[8361]: info: ___________ START PLUGINS ___________ Oct 31 16:16:03 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 31 16:16:03 volumio volumio[8361]: info: ControllerMpd::onStart: Initializing MPD Oct 31 16:16:03 volumio volumio[8361]: info: Creating MPD Configuration file Oct 31 16:16:03 volumio volumio[8361]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 31 16:16:03 volumio volumio[8361]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 31 16:16:03 volumio volumio[8361]: info: [1761927363540] CoreMusicLibrary::Adding element Media Servers Oct 31 16:16:03 volumio volumio[8361]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 31 16:16:03 volumio go-librespot[8487]: go-librespot daemon starting... Oct 31 16:16:03 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 31 16:16:03 volumio volumio[8361]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 16:16:03 volumio volumio[8361]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 31 16:16:03 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Oct 31 16:16:03 volumio sudo[8491]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 31 16:16:03 volumio sudo[8491]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 31 16:16:03 volumio volumio[8361]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 31 16:16:03 volumio volumio[8361]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 16:16:03 volumio volumio[8361]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 31 16:16:03 volumio go-librespot[8492]: time="2025-10-31T16:16:03Z" level=info msg="running go-librespot 0.4.0" Oct 31 16:16:03 volumio go-librespot[8492]: time="2025-10-31T16:16:03Z" level=debug msg="app state loaded" Oct 31 16:16:03 volumio go-librespot[8492]: time="2025-10-31T16:16:03Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 31 16:16:03 volumio sudo[8490]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 31 16:16:03 volumio systemd[1]: mpd.service: Deactivated successfully. Oct 31 16:16:03 volumio sudo[8490]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 31 16:16:03 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Oct 31 16:16:03 volumio systemd[1]: mpd.socket: Deactivated successfully. Oct 31 16:16:03 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Oct 31 16:16:03 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Oct 31 16:16:03 volumio sudo[8490]: pam_unix(sudo:session): session closed for user root Oct 31 16:16:03 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Oct 31 16:16:03 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Oct 31 16:16:03 volumio volumio[8431]: Starting albumart workers Oct 31 16:16:03 volumio volumio[8361]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 31 16:16:03 volumio systemd[1]: mpd.service: Deactivated successfully. Oct 31 16:16:03 volumio volumio[8361]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 31 16:16:03 volumio volumio[8361]: info: [1761927363598] CoreMusicLibrary::Adding element Last_100 Oct 31 16:16:03 volumio volumio[8361]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 31 16:16:03 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Oct 31 16:16:03 volumio systemd[1]: mpd.socket: Deactivated successfully. Oct 31 16:16:03 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Oct 31 16:16:03 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Oct 31 16:16:03 volumio volumio[8361]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 31 16:16:03 volumio volumio[8361]: info: [1761927363601] CoreMusicLibrary::Adding element Webradio Oct 31 16:16:03 volumio volumio[8361]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 31 16:16:03 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Oct 31 16:16:03 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Oct 31 16:16:03 volumio volumio[8361]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 31 16:16:03 volumio volumio[8361]: info: Initializing BBC Radios Oct 31 16:16:03 volumio sudo[8511]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Oct 31 16:16:03 volumio sudo[8511]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Oct 31 16:16:03 volumio volumio[8361]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 31 16:16:03 volumio volumio[8361]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 31 16:16:03 volumio sudo[8511]: pam_unix(sudo:session): session closed for user root Oct 31 16:16:03 volumio volumio[8361]: info: Creating Spotify config file Oct 31 16:16:03 volumio volumio[8361]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 16:16:03 volumio go-librespot[8492]: time="2025-10-31T16:16:03Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Oct 31 16:16:03 volumio go-librespot[8492]: time="2025-10-31T16:16:03Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 31 16:16:03 volumio go-librespot[8492]: time="2025-10-31T16:16:03Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 31 16:16:03 volumio go-librespot[8492]: time="2025-10-31T16:16:03Z" level=info msg="zeroconf server listening on port 38367" Oct 31 16:16:03 volumio volumio[8433]: Starting albumart workers Oct 31 16:16:03 volumio go-librespot[8492]: time="2025-10-31T16:16:03Z" level=debug msg="obtained new client token: AADMYBzwRAMmtqPH8sF7jIv1BmpxR8fWkRIqnsiFGR1aeXWfDpa8nyHXjuXoh5ayegRnTekGkAryrXw0YJ1nRu9GNs09kPab9tfipwPWW0qEO4A8WozLzdhLX71TLstGygsCColFDRnqBS0a5GIx9buwTy6Rh72nUyckUg92IfCbRrwLHa+iFssMa4STzZ+0p4oYGIB3pXtChtl1BFMuo0gv0wgQa0/EFem7oBr1714w9YLsYzZoh7U=" Oct 31 16:16:03 volumio go-librespot[8492]: time="2025-10-31T16:16:03Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 31 16:16:03 volumio go-librespot[8492]: time="2025-10-31T16:16:03Z" level=debug msg="completed keyexchange" Oct 31 16:16:03 volumio go-librespot[8492]: time="2025-10-31T16:16:03Z" level=debug msg="completed challenge" Oct 31 16:16:03 volumio volumio[8361]: info: Volumio Calling Home Oct 31 16:16:03 volumio go-librespot[8492]: time="2025-10-31T16:16:03Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 31 16:16:03 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 31 16:16:03 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 31 16:16:03 volumio volumio[8432]: Starting albumart workers Oct 31 16:16:04 volumio volumio[8361]: info: MPD Permissions set Oct 31 16:16:04 volumio volumio[8361]: info: MPD Permissions set Oct 31 16:16:04 volumio volumio[8361]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 1 Oct 31 16:16:04 volumio volumio[8361]: info: Spotify config file written Oct 31 16:16:04 volumio volumio[8361]: info: Volumio called home Oct 31 16:16:04 volumio volumio[8361]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 16:16:04 volumio volumio[8361]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 16:16:04 volumio volumio[8361]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 16:16:04 volumio volumio[8361]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 16:16:04 volumio volumio[8361]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 16:16:04 volumio volumio[8361]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 16:16:04 volumio volumio[8361]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 16:16:04 volumio volumio[8361]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 16:16:04 volumio sudo[8545]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Oct 31 16:16:04 volumio sudo[8545]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 31 16:16:04 volumio volumio[8361]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 31 16:16:04 volumio volumio[8361]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 16:16:04 volumio volumio[8361]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 16:16:04 volumio volumio[8361]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 16:16:04 volumio volumio[8361]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 16:16:04 volumio volumio[8361]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 16:16:04 volumio volumio[8361]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 16:16:04 volumio volumio[8361]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 16:16:04 volumio volumio[8361]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 16:16:04 volumio volumio[8361]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 16:16:04 volumio volumio[8361]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 31 16:16:04 volumio volumio[8361]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 16:16:04 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 31 16:16:04 volumio volumio[8361]: info: No need to fix Spotify hosts Oct 31 16:16:04 volumio go-librespot[8565]: go-librespot daemon starting... Oct 31 16:16:04 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 31 16:16:04 volumio sudo[8545]: pam_unix(sudo:session): session closed for user root Oct 31 16:16:04 volumio go-librespot[8566]: time="2025-10-31T16:16:04Z" level=info msg="running go-librespot 0.4.0" Oct 31 16:16:04 volumio go-librespot[8566]: time="2025-10-31T16:16:04Z" level=debug msg="app state loaded" Oct 31 16:16:04 volumio go-librespot[8566]: time="2025-10-31T16:16:04Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 31 16:16:04 volumio volumio[8361]: info: Starting Shairport Sync Oct 31 16:16:04 volumio volumio[8361]: info: Starting Shairport Sync Oct 31 16:16:04 volumio volumio[8361]: info: Starting Shairport Sync Oct 31 16:16:04 volumio sudo[8573]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 31 16:16:04 volumio sudo[8573]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 31 16:16:04 volumio sudo[8576]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 31 16:16:04 volumio sudo[8576]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 31 16:16:04 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Oct 31 16:16:04 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Oct 31 16:16:04 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Oct 31 16:16:04 volumio systemd[1]: shairport-sync.service: Consumed 1.859s CPU time. Oct 31 16:16:04 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Oct 31 16:16:04 volumio sudo[8577]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 31 16:16:04 volumio sudo[8577]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 31 16:16:04 volumio sudo[8573]: pam_unix(sudo:session): session closed for user root Oct 31 16:16:04 volumio sudo[8576]: pam_unix(sudo:session): session closed for user root Oct 31 16:16:04 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Oct 31 16:16:04 volumio mpd[8527]: 2025-10-31T16:16:04 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Oct 31 16:16:04 volumio systemd[1]: Started mpd.service - Music Player Daemon. Oct 31 16:16:04 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Oct 31 16:16:04 volumio sudo[8480]: pam_unix(sudo:session): session closed for user root Oct 31 16:16:04 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Oct 31 16:16:04 volumio sudo[8491]: pam_unix(sudo:session): session closed for user root Oct 31 16:16:04 volumio volumio[8361]: info: Shairport-Sync Started Oct 31 16:16:04 volumio volumio[8361]: Error adding Membership: Error: addMembership EINVAL Oct 31 16:16:04 volumio volumio[8361]: info: Shairport-Sync Started Oct 31 16:16:04 volumio volumio[8361]: info: CoreCommandRouter::volumioGetState Oct 31 16:16:04 volumio volumio[8361]: info: CorePlayQueue::getTrack 0 Oct 31 16:16:04 volumio volumio[8361]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Oct 31 16:16:04 volumio volumio[8361]: SPOTIFY: BQDYgWvBrb7aE412l5fG42dw0Fae2_GCVHm97nzHMgAuqfMZ_laBYJQdKkLDZVxXQD2iC-kijkWYaeWtEeBSfQcxi2tP99NyY_ntU4vAHj5pWqmp3aBsNkFf9luQIJ9H50UX-DdwkwkCtD-NE9kMEkTG84ieMFBpcxP4aHhrp9uZDKo_x1JtKQTQFmqC4Qj_4VzkVxqNKSYG_h9TaxJiOWVYc4H7vUhNV3SiSKiCq7LLml3f8qkVrQXBd-AQtnUySQz3WutS7yNuoGMDwY3h-PR7q9tkcHHmLSXlpuumHVolpBT9vyI Oct 31 16:16:04 volumio volumio[8361]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Oct 31 16:16:04 volumio volumio[8361]: info: New Spotify access token = BQDYgWvBrb7aE412l5fG42dw0Fae2_GCVHm97nzHMgAuqfMZ_laBYJQdKkLDZVxXQD2iC-kijkWYaeWtEeBSfQcxi2tP99NyY_ntU4vAHj5pWqmp3aBsNkFf9luQIJ9H50UX-DdwkwkCtD-NE9kMEkTG84ieMFBpcxP4aHhrp9uZDKo_x1JtKQTQFmqC4Qj_4VzkVxqNKSYG_h9TaxJiOWVYc4H7vUhNV3SiSKiCq7LLml3f8qkVrQXBd-AQtnUySQz3WutS7yNuoGMDwY3h-PR7q9tkcHHmLSXlpuumHVolpBT9vyI Oct 31 16:16:04 volumio volumio[8361]: info: Spotify credentials grant success - running version from March 24, 2019 Oct 31 16:16:04 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Oct 31 16:16:04 volumio sudo[8577]: pam_unix(sudo:session): session closed for user root Oct 31 16:16:04 volumio go-librespot[8566]: time="2025-10-31T16:16:04Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Oct 31 16:16:04 volumio go-librespot[8566]: time="2025-10-31T16:16:04Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 31 16:16:04 volumio go-librespot[8566]: time="2025-10-31T16:16:04Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 31 16:16:04 volumio go-librespot[8566]: time="2025-10-31T16:16:04Z" level=info msg="zeroconf server listening on port 44233" Oct 31 16:16:04 volumio volumio[8361]: error: MPD error: The expression evaluated to a falsy value: Oct 31 16:16:04 volumio volumio[8361]: assert.ok(self.idling) Oct 31 16:16:04 volumio volumio[8361]: error: The expression evaluated to a falsy value: Oct 31 16:16:04 volumio volumio[8361]: assert.ok(self.idling) Oct 31 16:16:04 volumio volumio[8361]: info: Shairport-Sync Started Oct 31 16:16:04 volumio volumio[8361]: info: MPD running with PID8527 Oct 31 16:16:04 volumio volumio[8361]: ,establishing connection Oct 31 16:16:04 volumio volumio[8361]: error: updateQueue error: null Oct 31 16:16:04 volumio volumio[8361]: error: updateQueue error: null Oct 31 16:16:04 volumio go-librespot[8566]: time="2025-10-31T16:16:04Z" level=debug msg="obtained new client token: AAA3mUrajl3QEMLZRgABwzj3BkQ49AmqkgytULStyCvY+InPXA4SvsvhnmsRl/srhFJeOvLyI776JcZNBtvB7SCBZXFGvRmjUkcfCW2py8RKz+ty9bpFPVRRD29KQcb6Q0lzd7IaHD49iwEedA2+UTKKvji3bAAyvYAJQ+ZgU8GCYbCD9oH78qp3WbnKbgi3hb5zJoPAw/tg4EUM98EWe9mJ2fv1U/Z4sFsRpiok32Dq0fdEb4YpHLM=" Oct 31 16:16:04 volumio go-librespot[8566]: time="2025-10-31T16:16:04Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 31 16:16:04 volumio go-librespot[8566]: time="2025-10-31T16:16:04Z" level=debug msg="completed keyexchange" Oct 31 16:16:04 volumio go-librespot[8566]: time="2025-10-31T16:16:04Z" level=debug msg="completed challenge" Oct 31 16:16:04 volumio volumio[8361]: SPOTIFY: User informations: {"country":"DE","display_name":"lapman","email":"ylm19961214@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/31hyzsop5elyyfayaiyk5tmkxmky"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/31hyzsop5elyyfayaiyk5tmkxmky","id":"31hyzsop5elyyfayaiyk5tmkxmky","images":[],"product":"free","type":"user","uri":"spotify:user:31hyzsop5elyyfayaiyk5tmkxmky"} Oct 31 16:16:04 volumio volumio[8361]: info: Spotify Successfully logged in Oct 31 16:16:04 volumio volumio[8361]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 31 16:16:04 volumio volumio[8361]: info: [1761927364489] CoreMusicLibrary::Adding element Spotify Oct 31 16:16:04 volumio volumio[8361]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 31 16:16:04 volumio volumio[8361]: Cannot find translation for source Spotify Oct 31 16:16:04 volumio go-librespot[8566]: time="2025-10-31T16:16:04Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 31 16:16:04 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 31 16:16:04 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 31 16:16:04 volumio volumio[8361]: info: [yt-cast-receiver] DIAL server listening on port 8098 Oct 31 16:16:04 volumio volumio[8361]: info: CoreCommandRouter::volumioRetrievevolume Oct 31 16:16:04 volumio volumio[8361]: info: VolumeController:: Volume=33 Mute =false Oct 31 16:16:04 volumio volumio[8361]: info: CoreCommandRouter::volumioGetState Oct 31 16:16:04 volumio volumio[8361]: info: CorePlayQueue::getTrack 0 Oct 31 16:16:04 volumio volumio[8361]: info: CoreStateMachine::pushState Oct 31 16:16:04 volumio volumio[8361]: info: CorePlayQueue::getTrack 0 Oct 31 16:16:04 volumio volumio[8361]: info: CoreCommandRouter::volumioPushState Oct 31 16:16:04 volumio volumio[8361]: info: Completed starting Core Plugins Oct 31 16:16:04 volumio volumio[8361]: info: ------------------------------------------- Oct 31 16:16:04 volumio volumio[8361]: info: ----- MyVolumio plugins startup ---- Oct 31 16:16:04 volumio volumio[8361]: info: ------------------------------------------- Oct 31 16:16:04 volumio volumio[8361]: info: [MyVolumio PluginManager] Fetching plans data.... Oct 31 16:16:05 volumio volumio-remote-updater[874]: [2025-10-31 16:16:05] [connect] Successful connection Oct 31 16:16:05 volumio volumio-remote-updater[874]: [2025-10-31 16:16:05] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1761927365 101 Oct 31 16:16:05 volumio volumio[8361]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 3 Transport: websocket Total Clients: 2 Oct 31 16:16:06 volumio volumio[8361]: info: Cannot mount NAS NAS at system boot, trial number 2 ,retrying in 5 seconds Oct 31 16:16:07 volumio volumio[8361]: info: go-librespot daemon successfully initialized Oct 31 16:16:07 volumio sudo[8621]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Oct 31 16:16:07 volumio sudo[8621]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 31 16:16:07 volumio sudo[8624]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Oct 31 16:16:07 volumio sudo[8624]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 31 16:16:07 volumio systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Oct 31 16:16:07 volumio systemd[1]: mpd_monitor.service: Deactivated successfully. Oct 31 16:16:07 volumio systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Oct 31 16:16:07 volumio systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Oct 31 16:16:07 volumio mpd_monitor.sh[8626]: MPD Monitor Service: Starting MPD Monitor Service Oct 31 16:16:07 volumio sudo[8621]: pam_unix(sudo:session): session closed for user root Oct 31 16:16:07 volumio volumio[8361]: info: Successfully started MPD Monitor Oct 31 16:16:07 volumio sudo[8624]: pam_unix(sudo:session): session closed for user root Oct 31 16:16:07 volumio volumio[8361]: info: Successfully started MPD Monitor Oct 31 16:16:07 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 12. Oct 31 16:16:07 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 31 16:16:07 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 31 16:16:07 volumio go-librespot[8630]: go-librespot daemon starting... Oct 31 16:16:07 volumio go-librespot[8631]: time="2025-10-31T16:16:07Z" level=info msg="running go-librespot 0.4.0" Oct 31 16:16:07 volumio go-librespot[8631]: time="2025-10-31T16:16:07Z" level=debug msg="app state loaded" Oct 31 16:16:07 volumio go-librespot[8631]: time="2025-10-31T16:16:07Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 31 16:16:07 volumio go-librespot[8631]: time="2025-10-31T16:16:07Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Oct 31 16:16:07 volumio go-librespot[8631]: time="2025-10-31T16:16:07Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 31 16:16:07 volumio go-librespot[8631]: time="2025-10-31T16:16:07Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 31 16:16:07 volumio go-librespot[8631]: time="2025-10-31T16:16:07Z" level=info msg="zeroconf server listening on port 45825" Oct 31 16:16:07 volumio go-librespot[8631]: time="2025-10-31T16:16:07Z" level=debug msg="obtained new client token: AAANLBRTsVyR2K8MaR32ThfBbKlOHxlS8EUmX3o5mu4I3rLWXym/gGHwmKM3U8gT7emHkgk55fZF8ThOcVrCq+EDmSouOBxhh4ppe8ftF19Qa6QmkbpSqwpeFnsEFCcrxtn0abqf6utJC5xigfQghrfPu1gi9vipCfnnfNuIVfP8TYCOnhbkI2OmytXeJET+m18hfeks0tnqw4tskwWYFjJwyq3Lq6yzGoFn5ukb1up5erBYJ+4X/9E=" Oct 31 16:16:07 volumio go-librespot[8631]: time="2025-10-31T16:16:07Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 31 16:16:07 volumio go-librespot[8631]: time="2025-10-31T16:16:07Z" level=debug msg="completed keyexchange" Oct 31 16:16:07 volumio go-librespot[8631]: time="2025-10-31T16:16:07Z" level=debug msg="completed challenge" Oct 31 16:16:07 volumio go-librespot[8631]: time="2025-10-31T16:16:07Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 31 16:16:07 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 31 16:16:07 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 31 16:16:09 volumio volumio[8361]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Oct 31 16:16:10 volumio volumio[8361]: info: Initializing connection to go-librespot Websocket Oct 31 16:16:10 volumio volumio[8361]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 31 16:16:11 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 13. Oct 31 16:16:11 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 31 16:16:11 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 31 16:16:11 volumio go-librespot[8638]: go-librespot daemon starting... Oct 31 16:16:11 volumio go-librespot[8639]: time="2025-10-31T16:16:11Z" level=info msg="running go-librespot 0.4.0" Oct 31 16:16:11 volumio go-librespot[8639]: time="2025-10-31T16:16:11Z" level=debug msg="app state loaded" Oct 31 16:16:11 volumio go-librespot[8639]: time="2025-10-31T16:16:11Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 31 16:16:11 volumio go-librespot[8639]: time="2025-10-31T16:16:11Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Oct 31 16:16:11 volumio go-librespot[8639]: time="2025-10-31T16:16:11Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Oct 31 16:16:11 volumio go-librespot[8639]: time="2025-10-31T16:16:11Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Oct 31 16:16:11 volumio go-librespot[8639]: time="2025-10-31T16:16:11Z" level=info msg="zeroconf server listening on port 41279" Oct 31 16:16:11 volumio go-librespot[8639]: time="2025-10-31T16:16:11Z" level=debug msg="obtained new client token: AACMu5Zr2wua8v58WN0cBaQ2+1Qd4DEHvgymMVHPDGtiCGJSBLPMN9RmA3bJAPOTG598wVmshRrfng4tEb6pacul1hEqplOwfcYwOpBry1VR/t3daW9M6KhCIJXbJ2VbpTt10Mz0uYH17emiIhYzFtpkMTRD3Nqs2vgvpcwR43u78mTr/pE9YdLjkGZakEWXg48vZMOaR256qvfNWtGYJDy5vHvoNfzHl+MC7L8ozxGLAa5o2Vjr" Oct 31 16:16:11 volumio go-librespot[8639]: time="2025-10-31T16:16:11Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 31 16:16:11 volumio go-librespot[8639]: time="2025-10-31T16:16:11Z" level=debug msg="completed keyexchange" Oct 31 16:16:11 volumio go-librespot[8639]: time="2025-10-31T16:16:11Z" level=debug msg="completed challenge" Oct 31 16:16:11 volumio go-librespot[8639]: time="2025-10-31T16:16:11Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 31 16:16:11 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 31 16:16:11 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 31 16:16:11 volumio volumio[8361]: info: Cannot mount NAS NAS at system boot, trial number 3 ,retrying in 5 seconds Oct 31 16:16:11 volumio sudo[8661]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 31 16:16:11 volumio sudo[8661]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 31 16:16:11 volumio sudo[8663]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 31 16:16:11 volumio sudo[8663]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 31 16:16:11 volumio sudo[8661]: pam_unix(sudo:session): session closed for user root Oct 31 16:16:11 volumio sudo[8663]: pam_unix(sudo:session): session closed for user root Oct 31 16:16:11 volumio sudo[8667]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Oct 31 16:16:11 volumio sudo[8667]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 31 16:16:11 volumio sudo[8667]: pam_unix(sudo:session): session closed for user root Oct 31 16:16:11 volumio volumio[8361]: info: Upmpdcli Daemon Started Oct 31 16:16:13 volumio volumio[8361]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Oct 31 16:16:13 volumio volumio[8361]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Oct 31 16:16:13 volumio volumio[8361]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Oct 31 16:16:13 volumio volumio[8361]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Oct 31 16:16:13 volumio volumio[8361]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Oct 31 16:16:13 volumio volumio[8361]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Oct 31 16:16:13 volumio volumio[8361]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Oct 31 16:16:13 volumio volumio[8361]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Oct 31 16:16:13 volumio volumio[8361]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Oct 31 16:16:13 volumio volumio[8361]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Oct 31 16:16:13 volumio volumio[8361]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Oct 31 16:16:13 volumio volumio[8361]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Oct 31 16:16:13 volumio volumio[8361]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Oct 31 16:16:13 volumio volumio[8361]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Oct 31 16:16:13 volumio volumio[8361]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Oct 31 16:16:13 volumio volumio[8361]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Oct 31 16:16:13 volumio volumio[8361]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Oct 31 16:16:13 volumio volumio[8361]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Oct 31 16:16:13 volumio volumio[8361]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Oct 31 16:16:13 volumio volumio[8361]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Oct 31 16:16:13 volumio volumio[8361]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Oct 31 16:16:13 volumio volumio[8361]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Oct 31 16:16:13 volumio volumio[8361]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Oct 31 16:16:13 volumio volumio[8361]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Oct 31 16:16:13 volumio volumio[8361]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Oct 31 16:16:13 volumio volumio[8361]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Oct 31 16:16:13 volumio volumio[8361]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Oct 31 16:16:13 volumio volumio[8361]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Oct 31 16:16:13 volumio volumio[8361]: info: Adding plugin bluetooth to MyMusic Plugins Oct 31 16:16:13 volumio volumio[8361]: info: Adding plugin multiroom to MyMusic Plugins Oct 31 16:16:13 volumio volumio[8361]: info: Adding plugin metavolumio to MyMusic Plugins Oct 31 16:16:13 volumio volumio[8361]: info: Adding plugin cd_controller to MyMusic Plugins Oct 31 16:16:13 volumio volumio[8361]: info: Adding plugin qobuzconnect to MyMusic Plugins Oct 31 16:16:13 volumio volumio[8361]: info: Adding plugin smart_inputs to MyMusic Plugins Oct 31 16:16:13 volumio volumio[8361]: info: Adding plugin tidalconnect to MyMusic Plugins Oct 31 16:16:13 volumio volumio[8361]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Oct 31 16:16:13 volumio volumio[8361]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Oct 31 16:16:13 volumio volumio[8361]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Oct 31 16:16:13 volumio volumio[8361]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 31 16:16:13 volumio volumio[8361]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 31 16:16:13 volumio volumio[8361]: info: Starting MyVolumio Remote Streaming Endpoints Oct 31 16:16:13 volumio volumio[8361]: info: MyVolumio login type: Token Oct 31 16:16:13 volumio volumio[8361]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Oct 31 16:16:13 volumio volumio[8361]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Oct 31 16:16:13 volumio volumio[8361]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Oct 31 16:16:13 volumio volumio[8361]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Oct 31 16:16:13 volumio volumio[8361]: info: Streaming services startup Oct 31 16:16:13 volumio volumio[8361]: info: Starting Streaming Daemon Oct 31 16:16:13 volumio sudo[8670]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Oct 31 16:16:13 volumio sudo[8670]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 31 16:16:13 volumio volumio[8361]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Oct 31 16:16:13 volumio sudo[8670]: pam_unix(sudo:session): session closed for user root Oct 31 16:16:13 volumio volumio[8361]: info: Initializing connection to go-librespot Websocket Oct 31 16:16:13 volumio volumio[8361]: error: Cannot start Volumio Streaming Daemon Oct 31 16:16:13 volumio volumio[8361]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Oct 31 16:16:13 volumio volumio[8361]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Oct 31 16:16:13 volumio volumio[8361]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 31 16:16:13 volumio volumio[8361]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Oct 31 16:16:14 volumio volumio[8361]: info: MyVolumio token set successfully Oct 31 16:16:14 volumio volumio[8361]: info: MYVOLUMIO: Adding device Oct 31 16:16:14 volumio volumio[8361]: info: MYVOLUMIO: Evaluating Server Oct 31 16:16:14 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 14. Oct 31 16:16:14 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 31 16:16:14 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 31 16:16:14 volumio go-librespot[8678]: go-librespot daemon starting... Oct 31 16:16:14 volumio go-librespot[8679]: time="2025-10-31T16:16:14Z" level=info msg="running go-librespot 0.4.0" Oct 31 16:16:14 volumio go-librespot[8679]: time="2025-10-31T16:16:14Z" level=debug msg="app state loaded" Oct 31 16:16:14 volumio go-librespot[8679]: time="2025-10-31T16:16:14Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 31 16:16:14 volumio volumio[8361]: info: MyVolumio status changed Oct 31 16:16:14 volumio volumio[8361]: info: Streaming services startup Oct 31 16:16:14 volumio volumio[8361]: info: Starting Streaming Daemon Oct 31 16:16:14 volumio go-librespot[8679]: time="2025-10-31T16:16:14Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Oct 31 16:16:14 volumio go-librespot[8679]: time="2025-10-31T16:16:14Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Oct 31 16:16:14 volumio go-librespot[8679]: time="2025-10-31T16:16:14Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Oct 31 16:16:14 volumio volumio[8361]: info: Removing browser output: myVolumio user plan is not superstar Oct 31 16:16:14 volumio go-librespot[8679]: time="2025-10-31T16:16:14Z" level=info msg="zeroconf server listening on port 45487" Oct 31 16:16:14 volumio volumio[8361]: info: Removing audio output: Oct 31 16:16:14 volumio volumio[8361]: info: Stoppping Tunnel 1 Oct 31 16:16:14 volumio sudo[8702]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Oct 31 16:16:14 volumio sudo[8702]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 31 16:16:14 volumio sudo[8704]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service Oct 31 16:16:14 volumio sudo[8704]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 31 16:16:14 volumio sudo[8702]: pam_unix(sudo:session): session closed for user root Oct 31 16:16:14 volumio volumio[8361]: error: Cannot start Volumio Streaming Daemon Oct 31 16:16:14 volumio volumio[8361]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Oct 31 16:16:14 volumio volumio[8361]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Oct 31 16:16:14 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Oct 31 16:16:14 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Oct 31 16:16:14 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Oct 31 16:16:14 volumio sudo[8704]: pam_unix(sudo:session): session closed for user root Oct 31 16:16:14 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Oct 31 16:16:14 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Oct 31 16:16:14 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Oct 31 16:16:14 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Oct 31 16:16:14 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Oct 31 16:16:14 volumio volumio[8361]: info: Remote SSH Stopped Oct 31 16:16:14 volumio go-librespot[8679]: time="2025-10-31T16:16:14Z" level=debug msg="obtained new client token: AAA+eYEVSdYg7KE8W29iJFXjn8/YYqqrhW/eLvP8/2A0jfmo/Mlw4tn+vhIMQlZbktcQolCBSBevbhhnMS+RjQ7xhu5C/etd16p0mYtd4ysIO+7ABUZzVmGSFmMwjKibU4o7x+N/mUoTHfeh6s3sWnyM0Gg4fVOj8x6uAXsHwnsYxj+Mn4yN2c2GiJWkP3TdPXlEJMIbBUlDeQHACY01jq5I2jxu/r0BJxwmO86ZKha1VwB0Rn15Fkg=" Oct 31 16:16:14 volumio go-librespot[8679]: time="2025-10-31T16:16:14Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 31 16:16:14 volumio go-librespot[8679]: time="2025-10-31T16:16:14Z" level=debug msg="completed keyexchange" Oct 31 16:16:14 volumio go-librespot[8679]: time="2025-10-31T16:16:14Z" level=debug msg="completed challenge" Oct 31 16:16:14 volumio go-librespot[8679]: time="2025-10-31T16:16:14Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 31 16:16:14 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 31 16:16:14 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 31 16:16:14 volumio volumio[8361]: info: Setting Geolocation for MyVolumio to eu3 Oct 31 16:16:14 volumio volumio[8361]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 31 16:16:14 volumio volumio[8361]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 31 16:16:14 volumio volumio[8361]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 31 16:16:15 volumio volumio[8361]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Oct 31 16:16:15 volumio volumio[8361]: info: Updating MyVolumio device info Oct 31 16:16:15 volumio volumio[8361]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 31 16:16:15 volumio volumio[8361]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 31 16:16:15 volumio volumio[8361]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 31 16:16:16 volumio volumio[8361]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Oct 31 16:16:16 volumio volumio[8361]: info: Initializing connection to go-librespot Websocket Oct 31 16:16:16 volumio volumio[8361]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 31 16:16:16 volumio volumio[8361]: info: Cannot mount NAS NAS at system boot, trial number 4 ,retrying in 5 seconds Oct 31 16:16:18 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 15. Oct 31 16:16:18 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 31 16:16:18 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 31 16:16:18 volumio go-librespot[8708]: go-librespot daemon starting... Oct 31 16:16:18 volumio go-librespot[8709]: time="2025-10-31T16:16:18Z" level=info msg="running go-librespot 0.4.0" Oct 31 16:16:18 volumio go-librespot[8709]: time="2025-10-31T16:16:18Z" level=debug msg="app state loaded" Oct 31 16:16:18 volumio go-librespot[8709]: time="2025-10-31T16:16:18Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 31 16:16:18 volumio go-librespot[8709]: time="2025-10-31T16:16:18Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Oct 31 16:16:18 volumio go-librespot[8709]: time="2025-10-31T16:16:18Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 31 16:16:18 volumio go-librespot[8709]: time="2025-10-31T16:16:18Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 31 16:16:18 volumio go-librespot[8709]: time="2025-10-31T16:16:18Z" level=info msg="zeroconf server listening on port 40537" Oct 31 16:16:18 volumio go-librespot[8709]: time="2025-10-31T16:16:18Z" level=debug msg="obtained new client token: AACerFwiR1pe1hLPywNRG4fDFOgL2qGJqgpGUl8dO5dXYGXTPEfbVPkmUvDnqk0pyk2AItL8Ah0S/9iPFdedgegSFe57DwME1o/av2teqGldCKg+eEacl1wf0ItFKk6BESZAxZprlL8cAhFrout01yDUxu9K4OChcRKzcqhKHXsaksLvGhxha2teDpQ545Mp65Eaopsk1wKRySoYxnW8CFCZyjJKfzNFsgZop/cjDoXJyuq7C+S+" Oct 31 16:16:18 volumio go-librespot[8709]: time="2025-10-31T16:16:18Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 31 16:16:18 volumio go-librespot[8709]: time="2025-10-31T16:16:18Z" level=debug msg="completed keyexchange" Oct 31 16:16:18 volumio go-librespot[8709]: time="2025-10-31T16:16:18Z" level=debug msg="completed challenge" Oct 31 16:16:18 volumio go-librespot[8709]: time="2025-10-31T16:16:18Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 31 16:16:18 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 31 16:16:18 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 31 16:16:19 volumio volumio[8361]: info: Initializing connection to go-librespot Websocket Oct 31 16:16:19 volumio volumio[8361]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 31 16:16:19 volumio volumio[8361]: info: MYVOLUMIO: Adding device Oct 31 16:16:19 volumio volumio[8361]: info: MYVOLUMIO: Evaluating Server Oct 31 16:16:19 volumio volumio[8361]: info: Setting Geolocation for MyVolumio to eu3 Oct 31 16:16:19 volumio volumio[8361]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 31 16:16:19 volumio volumio[8361]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 31 16:16:19 volumio volumio[8361]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 31 16:16:20 volumio volumio[8361]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Oct 31 16:16:20 volumio volumio[8361]: info: Updating MyVolumio device info Oct 31 16:16:20 volumio volumio[8361]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 31 16:16:20 volumio volumio[8361]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 31 16:16:20 volumio volumio[8361]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 31 16:16:21 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 16. Oct 31 16:16:21 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 31 16:16:21 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 31 16:16:21 volumio go-librespot[8732]: go-librespot daemon starting... Oct 31 16:16:21 volumio go-librespot[8733]: time="2025-10-31T16:16:21Z" level=info msg="running go-librespot 0.4.0" Oct 31 16:16:21 volumio go-librespot[8733]: time="2025-10-31T16:16:21Z" level=debug msg="app state loaded" Oct 31 16:16:21 volumio go-librespot[8733]: time="2025-10-31T16:16:21Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 31 16:16:21 volumio go-librespot[8733]: time="2025-10-31T16:16:21Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Oct 31 16:16:21 volumio go-librespot[8733]: time="2025-10-31T16:16:21Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 31 16:16:21 volumio go-librespot[8733]: time="2025-10-31T16:16:21Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 31 16:16:21 volumio go-librespot[8733]: time="2025-10-31T16:16:21Z" level=info msg="zeroconf server listening on port 42499" Oct 31 16:16:21 volumio go-librespot[8733]: time="2025-10-31T16:16:21Z" level=debug msg="obtained new client token: AABrV7LQAJEfgC+Bq5wSF9c1kA+jKANEDK2eA7Q87U+qtQkS7ClDjVgCjmm+PXXu3WHBrmeVBxR/RNMiP3T/9Eo3am2+R3dAGGf5D25jM+LC4/Pw1zYrEU7bUuqzQSb+WuXyvHW8nzmvJNhgTOMTOE6CZDuI2Tao+R8m9RXYORv/k5jGfhN+18hgdGwnDGI+JVJJNO4T4EZMVq68YUsEefaa+vuk1xqX1gYaoTtZVxn19kt21sqDBZs=" Oct 31 16:16:21 volumio go-librespot[8733]: time="2025-10-31T16:16:21Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 31 16:16:21 volumio volumio[8361]: info: Cannot mount NAS at system boot, trial number 4 ,stopping Oct 31 16:16:21 volumio go-librespot[8733]: time="2025-10-31T16:16:21Z" level=debug msg="completed keyexchange" Oct 31 16:16:21 volumio go-librespot[8733]: time="2025-10-31T16:16:21Z" level=debug msg="completed challenge" Oct 31 16:16:21 volumio go-librespot[8733]: time="2025-10-31T16:16:21Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 31 16:16:21 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 31 16:16:21 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 31 16:16:21 volumio volumio[8361]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Oct 31 16:16:22 volumio volumio[8361]: info: Initializing connection to go-librespot Websocket Oct 31 16:16:22 volumio volumio[8361]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 31 16:16:25 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 17. Oct 31 16:16:25 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 31 16:16:25 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 31 16:16:25 volumio go-librespot[8754]: go-librespot daemon starting... Oct 31 16:16:25 volumio go-librespot[8755]: time="2025-10-31T16:16:25Z" level=info msg="running go-librespot 0.4.0" Oct 31 16:16:25 volumio go-librespot[8755]: time="2025-10-31T16:16:25Z" level=debug msg="app state loaded" Oct 31 16:16:25 volumio go-librespot[8755]: time="2025-10-31T16:16:25Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 31 16:16:25 volumio go-librespot[8755]: time="2025-10-31T16:16:25Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Oct 31 16:16:25 volumio go-librespot[8755]: time="2025-10-31T16:16:25Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 31 16:16:25 volumio go-librespot[8755]: time="2025-10-31T16:16:25Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 31 16:16:25 volumio go-librespot[8755]: time="2025-10-31T16:16:25Z" level=info msg="zeroconf server listening on port 35085" Oct 31 16:16:25 volumio go-librespot[8755]: time="2025-10-31T16:16:25Z" level=debug msg="obtained new client token: AABo1+UsP1SB7x7UgtJf8cGuZ4sRv4vKwhN1GKmsvQztRbmJZ01Z0UJDnxmDXV0Jdmt0n5Jh6+20tJmivCB8WxSZVeLI8OT+h1zDDites7Q5UN2x/CKwvk45uwoupOnpNl3ePs9uSbA9n8/gfZMIA9EfQYs6gQhSKIANFGb4nUFGL16xPQPuJCXezDe38/q150zmjRJ5Xl8mgoAvLsdGDwtLvwZy8O+NHSsO8ckbXPnNfuWP5478" Oct 31 16:16:25 volumio go-librespot[8755]: time="2025-10-31T16:16:25Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 31 16:16:25 volumio go-librespot[8755]: time="2025-10-31T16:16:25Z" level=debug msg="completed keyexchange" Oct 31 16:16:25 volumio go-librespot[8755]: time="2025-10-31T16:16:25Z" level=debug msg="completed challenge" Oct 31 16:16:25 volumio go-librespot[8755]: time="2025-10-31T16:16:25Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 31 16:16:25 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 31 16:16:25 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 31 16:16:25 volumio volumio[8361]: info: Initializing connection to go-librespot Websocket Oct 31 16:16:25 volumio volumio[8361]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 31 16:16:28 volumio volumio[8361]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Oct 31 16:16:28 volumio volumio[8361]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Oct 31 16:16:28 volumio volumio[8361]: info: CoreCommandRouter::volumioGetState Oct 31 16:16:28 volumio volumio[8361]: info: CorePlayQueue::getTrack 0 Oct 31 16:16:28 volumio volumio[8361]: info: Initializing connection to go-librespot Websocket Oct 31 16:16:28 volumio volumio[8361]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 31 16:16:28 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 18. Oct 31 16:16:28 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 31 16:16:28 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 31 16:16:28 volumio go-librespot[8765]: go-librespot daemon starting... Oct 31 16:16:28 volumio go-librespot[8766]: time="2025-10-31T16:16:28Z" level=info msg="running go-librespot 0.4.0" Oct 31 16:16:28 volumio go-librespot[8766]: time="2025-10-31T16:16:28Z" level=debug msg="app state loaded" Oct 31 16:16:28 volumio go-librespot[8766]: time="2025-10-31T16:16:28Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 31 16:16:28 volumio go-librespot[8766]: time="2025-10-31T16:16:28Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Oct 31 16:16:28 volumio go-librespot[8766]: time="2025-10-31T16:16:28Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 31 16:16:28 volumio go-librespot[8766]: time="2025-10-31T16:16:28Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 31 16:16:28 volumio go-librespot[8766]: time="2025-10-31T16:16:28Z" level=info msg="zeroconf server listening on port 45677" Oct 31 16:16:28 volumio go-librespot[8766]: time="2025-10-31T16:16:28Z" level=debug msg="obtained new client token: AABgpHHDrqj6JFZ+etAmrtlU+er2B82hxCPHXHtOIYFs9R5Zvl3NiBfv1YQJQzzIXkOdpE2ayV8MhrVslxrAwe1WBHTIdDmN5ueH3SveTM1Aq/OEkAIjO0cpdAkbw/zu2w0x0/+ts/fTRaje7PWzM1kNX3K0bQYID8DgpXXdzkquviCtMiIx4uLU5MLlBUFw/mNiaJ0YrGWOaNHa07h56YXqGAcmw+9az3NZmFIGNXDh+7Pkw4P0euA=" Oct 31 16:16:28 volumio go-librespot[8766]: time="2025-10-31T16:16:28Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 31 16:16:28 volumio go-librespot[8766]: time="2025-10-31T16:16:28Z" level=debug msg="completed keyexchange" Oct 31 16:16:28 volumio go-librespot[8766]: time="2025-10-31T16:16:28Z" level=debug msg="completed challenge" Oct 31 16:16:28 volumio go-librespot[8766]: time="2025-10-31T16:16:28Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 31 16:16:28 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 31 16:16:28 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 31 16:16:31 volumio volumio[8361]: info: Initializing connection to go-librespot Websocket Oct 31 16:16:31 volumio volumio[8361]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 31 16:16:32 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 19. Oct 31 16:16:32 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 31 16:16:32 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 31 16:16:32 volumio go-librespot[8787]: go-librespot daemon starting... Oct 31 16:16:32 volumio go-librespot[8788]: time="2025-10-31T16:16:32Z" level=info msg="running go-librespot 0.4.0" Oct 31 16:16:32 volumio go-librespot[8788]: time="2025-10-31T16:16:32Z" level=debug msg="app state loaded" Oct 31 16:16:32 volumio go-librespot[8788]: time="2025-10-31T16:16:32Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 31 16:16:32 volumio go-librespot[8788]: time="2025-10-31T16:16:32Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Oct 31 16:16:32 volumio go-librespot[8788]: time="2025-10-31T16:16:32Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 31 16:16:32 volumio go-librespot[8788]: time="2025-10-31T16:16:32Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 31 16:16:32 volumio go-librespot[8788]: time="2025-10-31T16:16:32Z" level=info msg="zeroconf server listening on port 40933" Oct 31 16:16:32 volumio go-librespot[8788]: time="2025-10-31T16:16:32Z" level=debug msg="obtained new client token: AAA5xCL9C2Tx1yJiT/yhMke3GkAokjLrVV72FOPHNG+QmfKsBpVmkRte90g5MCzVXCo2Bxipo4rDtn/tuQ4D1b1Pmvc3dSWOjNfb4m6n/eDa0SDlTjbKTs1IYX2ikFyhHkiMItlyOv60TsVNqqQVa+J8JaWEM1U8k49fW4pWo+TnR4PkeCCePbflgNndAqmXV8+1S/9QcsmyVBupLfCN16H9wnWrPMreDbabv8t/TTPwGzBrDLBq" Oct 31 16:16:32 volumio go-librespot[8788]: time="2025-10-31T16:16:32Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 31 16:16:32 volumio go-librespot[8788]: time="2025-10-31T16:16:32Z" level=debug msg="completed keyexchange" Oct 31 16:16:32 volumio go-librespot[8788]: time="2025-10-31T16:16:32Z" level=debug msg="completed challenge" Oct 31 16:16:32 volumio go-librespot[8788]: time="2025-10-31T16:16:32Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 31 16:16:32 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 31 16:16:32 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 31 16:16:33 volumio volumio[8361]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 16:16:33 volumio volumio[8361]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 16:16:33 volumio volumio[8361]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam Oct 31 16:16:33 volumio volumio[8361]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Oct 31 16:16:33 volumio volumio[8361]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Oct 31 16:16:33 volumio volumio[8361]: info: CoreCommandRouter::volumioGetBrowseSources Oct 31 16:16:33 volumio volumio[8361]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 31 16:16:33 volumio volumio[8361]: error: MyVolumio Plugin failed to authenticate in a timely fashion Oct 31 16:16:33 volumio volumio[8361]: info: Completed starting MyVolumio Plugin Oct 31 16:16:33 volumio volumio[8361]: [Metrics] CommandRouter: 31s 993.09ms Oct 31 16:16:33 volumio volumio[8361]: info: CoreCommandRouter::volumiosetStartupVolume Oct 31 16:16:33 volumio volumio[8361]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 16:16:33 volumio volumio[8361]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 31 16:16:33 volumio volumio[8361]: info: CoreCommandRouter::Close All Modals sent Oct 31 16:16:33 volumio volumio[8361]: info: CoreCommandRouter::Close All Modals sent Oct 31 16:16:33 volumio volumio[8361]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 31 16:16:33 volumio volumio[8361]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 31 16:16:33 volumio volumio[8361]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Oct 31 16:16:33 volumio volumio-remote-updater[874]: Test mode disabled Oct 31 16:16:33 volumio volumio-remote-updater[874]: Alpha mode disabled Oct 31 16:16:33 volumio volumio-remote-updater[874]: Alpha legacy test mode disabled Oct 31 16:16:34 volumio volumio[8361]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateEnabled Oct 31 16:16:34 volumio volumio[8361]: info: Update Ready: {"changeLogLink":"","description":"You're already on the latest version","title":"No Updates Available","updateavailable":false} Oct 31 16:16:34 volumio volumio[8361]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache Oct 31 16:16:34 volumio volumio[8361]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable Oct 31 16:16:34 volumio volumio[8361]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Oct 31 16:16:34 volumio volumio[8361]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect Oct 31 16:16:34 volumio volumio[8361]: info: Initializing connection to go-librespot Websocket Oct 31 16:16:34 volumio volumio[8361]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 31 16:16:35 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 20. Oct 31 16:16:35 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 31 16:16:35 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 31 16:16:35 volumio go-librespot[8804]: go-librespot daemon starting... Oct 31 16:16:35 volumio go-librespot[8805]: time="2025-10-31T16:16:35Z" level=info msg="running go-librespot 0.4.0" Oct 31 16:16:35 volumio go-librespot[8805]: time="2025-10-31T16:16:35Z" level=debug msg="app state loaded" Oct 31 16:16:35 volumio go-librespot[8805]: time="2025-10-31T16:16:35Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 31 16:16:35 volumio go-librespot[8805]: time="2025-10-31T16:16:35Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Oct 31 16:16:35 volumio go-librespot[8805]: time="2025-10-31T16:16:35Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 31 16:16:35 volumio go-librespot[8805]: time="2025-10-31T16:16:35Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 31 16:16:35 volumio go-librespot[8805]: time="2025-10-31T16:16:35Z" level=info msg="zeroconf server listening on port 43167" Oct 31 16:16:35 volumio go-librespot[8805]: time="2025-10-31T16:16:35Z" level=debug msg="obtained new client token: AAAlAeofIDk6uLd2TJxUTI3OkCyI3bMvna8y9MJqJNf59OgUXMHpK5pq++tbtlMwOI8Ald+7NJ5hQg8ebJJ4EmZQ355mnnjdQzDgE62lkr7uhrwSn8WEhKDF+8nMJMQtQSsvgCywfQqGAQjLZzZV2Znv81mcKVUqfZZnXVAxtKQlzR90GQ0Lu7Gz9IiucOgI87oedBABn/lZhbSRD/37wzN5qRQQmlWLqL+Cu+DlGj7L9RZ99/3cbT8=" Oct 31 16:16:35 volumio go-librespot[8805]: time="2025-10-31T16:16:35Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 31 16:16:35 volumio go-librespot[8805]: time="2025-10-31T16:16:35Z" level=debug msg="completed keyexchange" Oct 31 16:16:35 volumio go-librespot[8805]: time="2025-10-31T16:16:35Z" level=debug msg="completed challenge" Oct 31 16:16:35 volumio go-librespot[8805]: time="2025-10-31T16:16:35Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 31 16:16:35 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 31 16:16:35 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 31 16:16:37 volumio volumio[8361]: info: Initializing connection to go-librespot Websocket Oct 31 16:16:37 volumio volumio[8361]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 31 16:16:39 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 21. Oct 31 16:16:39 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 31 16:16:39 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 31 16:16:39 volumio go-librespot[8812]: go-librespot daemon starting... Oct 31 16:16:39 volumio go-librespot[8813]: time="2025-10-31T16:16:39Z" level=info msg="running go-librespot 0.4.0" Oct 31 16:16:39 volumio go-librespot[8813]: time="2025-10-31T16:16:39Z" level=debug msg="app state loaded" Oct 31 16:16:39 volumio go-librespot[8813]: time="2025-10-31T16:16:39Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 31 16:16:39 volumio go-librespot[8813]: time="2025-10-31T16:16:39Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Oct 31 16:16:39 volumio go-librespot[8813]: time="2025-10-31T16:16:39Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 31 16:16:39 volumio go-librespot[8813]: time="2025-10-31T16:16:39Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 31 16:16:39 volumio go-librespot[8813]: time="2025-10-31T16:16:39Z" level=info msg="zeroconf server listening on port 33947" Oct 31 16:16:39 volumio go-librespot[8813]: time="2025-10-31T16:16:39Z" level=debug msg="obtained new client token: AACTjuMSM2orfyq4BkuN/a1nj4wA1Cflv8WFBf+kuM224LaX/dQtVW88PkBNy6peVxFOnajHUr/06M8jIGq8iUkjESpvz0xfDn1dL8EadA0ij9yZH4ir9c5m/Mdwmt2Z1iW9CEF0mO8riZqXXUxAlKKxCWqFLZsu+qkmDpfo58C+Jf10o8FOAvTnW6DQ1DuX4AL1U1FrVKBRpp0ZKtxV7zvXwFF4j1RzG2NWi4AUncf0mOGGjPAo" Oct 31 16:16:39 volumio go-librespot[8813]: time="2025-10-31T16:16:39Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 31 16:16:39 volumio go-librespot[8813]: time="2025-10-31T16:16:39Z" level=debug msg="completed keyexchange" Oct 31 16:16:39 volumio go-librespot[8813]: time="2025-10-31T16:16:39Z" level=debug msg="completed challenge" Oct 31 16:16:39 volumio go-librespot[8813]: time="2025-10-31T16:16:39Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 31 16:16:39 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 31 16:16:39 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 31 16:16:40 volumio volumio[8361]: info: BOOT COMPLETED Oct 31 16:16:40 volumio volumio[8361]: info: Initializing connection to go-librespot Websocket Oct 31 16:16:40 volumio volumio[8361]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 31 16:16:42 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 22. Oct 31 16:16:42 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 31 16:16:42 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 31 16:16:42 volumio go-librespot[8835]: go-librespot daemon starting... Oct 31 16:16:42 volumio go-librespot[8836]: time="2025-10-31T16:16:42Z" level=info msg="running go-librespot 0.4.0" Oct 31 16:16:42 volumio go-librespot[8836]: time="2025-10-31T16:16:42Z" level=debug msg="app state loaded" Oct 31 16:16:42 volumio go-librespot[8836]: time="2025-10-31T16:16:42Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 31 16:16:42 volumio go-librespot[8836]: time="2025-10-31T16:16:42Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Oct 31 16:16:42 volumio go-librespot[8836]: time="2025-10-31T16:16:42Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Oct 31 16:16:42 volumio go-librespot[8836]: time="2025-10-31T16:16:42Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Oct 31 16:16:42 volumio go-librespot[8836]: time="2025-10-31T16:16:42Z" level=info msg="zeroconf server listening on port 39885" Oct 31 16:16:42 volumio go-librespot[8836]: time="2025-10-31T16:16:42Z" level=debug msg="obtained new client token: AAD05K9WGsPPHiLlgCAVBtqQsOs0SeLJJdT/AZMVEpu/zgVEoL60yc9Qxqr0RW5/9dcDXLFWWQEFF81ll7/tF322ZsjhlrEKVRq9nHEj0qt7K94LmJ9Al5tbWtFVL0roQIGEb10o8qlyD1ELpAkXwFiUHAvAoJqXMsOW6Bf20jdHFzQQHXU9AMq6MPof+xRkdZy+H6FEvinxSb8Q4dZtnXr74ZUlvhCGfQ36Zs+3+qVTaQvJl8Qpg9M=" Oct 31 16:16:42 volumio go-librespot[8836]: time="2025-10-31T16:16:42Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 31 16:16:42 volumio go-librespot[8836]: time="2025-10-31T16:16:42Z" level=debug msg="completed keyexchange" Oct 31 16:16:42 volumio go-librespot[8836]: time="2025-10-31T16:16:42Z" level=debug msg="completed challenge" Oct 31 16:16:42 volumio go-librespot[8836]: time="2025-10-31T16:16:42Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 31 16:16:42 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 31 16:16:42 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 31 16:16:43 volumio volumio[8361]: info: Initializing connection to go-librespot Websocket Oct 31 16:16:43 volumio volumio[8361]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 31 16:16:46 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 23. Oct 31 16:16:46 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 31 16:16:46 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 31 16:16:46 volumio go-librespot[8843]: go-librespot daemon starting... Oct 31 16:16:46 volumio go-librespot[8844]: time="2025-10-31T16:16:46Z" level=info msg="running go-librespot 0.4.0" Oct 31 16:16:46 volumio go-librespot[8844]: time="2025-10-31T16:16:46Z" level=debug msg="app state loaded" Oct 31 16:16:46 volumio go-librespot[8844]: time="2025-10-31T16:16:46Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 31 16:16:46 volumio go-librespot[8844]: time="2025-10-31T16:16:46Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Oct 31 16:16:46 volumio go-librespot[8844]: time="2025-10-31T16:16:46Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Oct 31 16:16:46 volumio go-librespot[8844]: time="2025-10-31T16:16:46Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Oct 31 16:16:46 volumio go-librespot[8844]: time="2025-10-31T16:16:46Z" level=info msg="zeroconf server listening on port 44863" Oct 31 16:16:46 volumio go-librespot[8844]: time="2025-10-31T16:16:46Z" level=debug msg="obtained new client token: AADLsVYE16eup0RbECOyRJi8+htjnlQlyIs9+mBhukL9caHxtJYwp71iR9RdhlBAvYumzsU/Pzo/2qOI2ORjoonJuQ2EtCrYxOzMZjA0xH3rrxhszPnf0oyfszSGQct4Zhqm4xUcmnYcDl8Jt5mcX4A9CJ0yCah64ccfeilqkTRq6ZrgvdRKXWMbKoQNfxfYKSNoM0pavNCgo54uW25pd/6OpkE7jW++xjqBV0+LfbhpHldkp7LS" Oct 31 16:16:46 volumio go-librespot[8844]: time="2025-10-31T16:16:46Z" level=warning msg="failed to connect to AP ap-gew1.spotify.com:4070, retrying with a different AP" error="dial tcp 104.199.65.9:4070: connect: connection refused" Oct 31 16:16:46 volumio go-librespot[8844]: time="2025-10-31T16:16:46Z" level=debug msg="connected to ap-gew1.spotify.com:443" Oct 31 16:16:46 volumio go-librespot[8844]: time="2025-10-31T16:16:46Z" level=debug msg="completed keyexchange" Oct 31 16:16:46 volumio go-librespot[8844]: time="2025-10-31T16:16:46Z" level=debug msg="completed challenge" Oct 31 16:16:46 volumio go-librespot[8844]: time="2025-10-31T16:16:46Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 31 16:16:46 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 31 16:16:46 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 31 16:16:46 volumio volumio[8361]: info: Initializing connection to go-librespot Websocket Oct 31 16:16:46 volumio volumio[8361]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 31 16:16:49 volumio volumio[8361]: info: Initializing connection to go-librespot Websocket Oct 31 16:16:49 volumio volumio[8361]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 31 16:16:49 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 24. Oct 31 16:16:49 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 31 16:16:49 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 31 16:16:49 volumio go-librespot[8854]: go-librespot daemon starting... Oct 31 16:16:49 volumio go-librespot[8855]: time="2025-10-31T16:16:49Z" level=info msg="running go-librespot 0.4.0" Oct 31 16:16:49 volumio go-librespot[8855]: time="2025-10-31T16:16:49Z" level=debug msg="app state loaded" Oct 31 16:16:49 volumio go-librespot[8855]: time="2025-10-31T16:16:49Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 31 16:16:49 volumio go-librespot[8855]: time="2025-10-31T16:16:49Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Oct 31 16:16:49 volumio go-librespot[8855]: time="2025-10-31T16:16:49Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 31 16:16:49 volumio go-librespot[8855]: time="2025-10-31T16:16:49Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 31 16:16:49 volumio go-librespot[8855]: time="2025-10-31T16:16:49Z" level=info msg="zeroconf server listening on port 40897" Oct 31 16:16:49 volumio go-librespot[8855]: time="2025-10-31T16:16:49Z" level=debug msg="obtained new client token: AAA2GOmV7Z55P3CzBnl8YJM2XBCi852iCK0bUWLhFckNqDQbcSB+aRnQVWV3UCOENT/0B6EFHxexyqrqg5zKkpgTYqegyrb5cWKy3qDu70xf+Yya8riUGbm3YKjRwIGn0tqYZR4jvAnpns5HoKphEmSB1BxwOMxxkWrA6/gK+m3XlgNiKm1NsMFEix1d4LyTbEobu0S5ZmSLWKM8FbU0rFDl37XVJHmlg7KiJ2bTE8/yTU3zO2P/14k=" Oct 31 16:16:49 volumio go-librespot[8855]: time="2025-10-31T16:16:49Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 31 16:16:49 volumio go-librespot[8855]: time="2025-10-31T16:16:49Z" level=debug msg="completed keyexchange" Oct 31 16:16:49 volumio go-librespot[8855]: time="2025-10-31T16:16:49Z" level=debug msg="completed challenge" Oct 31 16:16:49 volumio go-librespot[8855]: time="2025-10-31T16:16:49Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 31 16:16:49 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 31 16:16:49 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 31 16:16:52 volumio volumio[8361]: info: Initializing connection to go-librespot Websocket Oct 31 16:16:52 volumio volumio[8361]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 31 16:16:52 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 25. Oct 31 16:16:52 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 31 16:16:52 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 31 16:16:52 volumio go-librespot[8877]: go-librespot daemon starting... Oct 31 16:16:52 volumio go-librespot[8878]: time="2025-10-31T16:16:52Z" level=info msg="running go-librespot 0.4.0" Oct 31 16:16:52 volumio go-librespot[8878]: time="2025-10-31T16:16:52Z" level=debug msg="app state loaded" Oct 31 16:16:52 volumio go-librespot[8878]: time="2025-10-31T16:16:52Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 31 16:16:52 volumio go-librespot[8878]: time="2025-10-31T16:16:52Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Oct 31 16:16:52 volumio go-librespot[8878]: time="2025-10-31T16:16:52Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Oct 31 16:16:52 volumio go-librespot[8878]: time="2025-10-31T16:16:52Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Oct 31 16:16:52 volumio go-librespot[8878]: time="2025-10-31T16:16:52Z" level=info msg="zeroconf server listening on port 39735" Oct 31 16:16:52 volumio go-librespot[8878]: time="2025-10-31T16:16:52Z" level=debug msg="obtained new client token: AAAAVAWLYaPYwsuR1RyMZ1zRzvtsAvNsm2vbgxa71kPX8v4Z2giIfytPbie62pb9hZJ2rbo4mq6rJJmldag3GNj8ovMKJXFL5YODSa6JTT1WIPKMod0IwZuhOR7DY4oLXySs1EMebleWhJ8H6TmRqhb6OjHjXBLMahqZVC1rnI4zqC3oZYcD5ogbRHSi9WEKkK2WU7cFL9aZw9rmcBYUARcw31vlZP0R78f+hdlO97fdxNUcAfYeUs4=" Oct 31 16:16:52 volumio go-librespot[8878]: time="2025-10-31T16:16:52Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 31 16:16:53 volumio go-librespot[8878]: time="2025-10-31T16:16:53Z" level=debug msg="completed keyexchange" Oct 31 16:16:53 volumio go-librespot[8878]: time="2025-10-31T16:16:53Z" level=debug msg="completed challenge" Oct 31 16:16:53 volumio go-librespot[8878]: time="2025-10-31T16:16:53Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 31 16:16:53 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 31 16:16:53 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 31 16:16:55 volumio volumio[8361]: info: Initializing connection to go-librespot Websocket Oct 31 16:16:55 volumio volumio[8361]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 31 16:16:56 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 26. Oct 31 16:16:56 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 31 16:16:56 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 31 16:16:56 volumio go-librespot[8885]: go-librespot daemon starting... Oct 31 16:16:56 volumio go-librespot[8886]: time="2025-10-31T16:16:56Z" level=info msg="running go-librespot 0.4.0" Oct 31 16:16:56 volumio go-librespot[8886]: time="2025-10-31T16:16:56Z" level=debug msg="app state loaded" Oct 31 16:16:56 volumio go-librespot[8886]: time="2025-10-31T16:16:56Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 31 16:16:56 volumio go-librespot[8886]: time="2025-10-31T16:16:56Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Oct 31 16:16:56 volumio go-librespot[8886]: time="2025-10-31T16:16:56Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 31 16:16:56 volumio go-librespot[8886]: time="2025-10-31T16:16:56Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 31 16:16:56 volumio go-librespot[8886]: time="2025-10-31T16:16:56Z" level=info msg="zeroconf server listening on port 35241" Oct 31 16:16:56 volumio go-librespot[8886]: time="2025-10-31T16:16:56Z" level=debug msg="obtained new client token: AAAlEPqa1Mgl6/GOqcMQhmwt8eLhBRHBmFJ2Ey7bJXW8pF/Yk6w4Df9GIBCTmO9Ssgka3u2HiVE/EdubkIVWVgsZV9lIXzjbmrIgpNy+AYLEIetXG3UaU9O7Ve3/eBbJJI+5YT3EGQt/IokQOQrgNelcQ+v7n0242o1ZuCx8U4KojB4u3k+vazWw44DN+YWFYLx3UuYXz81GSW1w61zceQcVx7hfZpkywhKpC9h5aRU7+IwVzRrF9zQ=" Oct 31 16:16:56 volumio go-librespot[8886]: time="2025-10-31T16:16:56Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 31 16:16:56 volumio go-librespot[8886]: time="2025-10-31T16:16:56Z" level=debug msg="completed keyexchange" Oct 31 16:16:56 volumio go-librespot[8886]: time="2025-10-31T16:16:56Z" level=debug msg="completed challenge" Oct 31 16:16:56 volumio go-librespot[8886]: time="2025-10-31T16:16:56Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 31 16:16:56 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 31 16:16:56 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 31 16:16:58 volumio volumio[8361]: info: Initializing connection to go-librespot Websocket Oct 31 16:16:58 volumio volumio[8361]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 31 16:16:59 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 27. Oct 31 16:16:59 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 31 16:16:59 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 31 16:16:59 volumio go-librespot[8893]: go-librespot daemon starting... Oct 31 16:16:59 volumio go-librespot[8894]: time="2025-10-31T16:16:59Z" level=info msg="running go-librespot 0.4.0" Oct 31 16:16:59 volumio go-librespot[8894]: time="2025-10-31T16:16:59Z" level=debug msg="app state loaded" Oct 31 16:16:59 volumio go-librespot[8894]: time="2025-10-31T16:16:59Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 31 16:16:59 volumio go-librespot[8894]: time="2025-10-31T16:16:59Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Oct 31 16:16:59 volumio go-librespot[8894]: time="2025-10-31T16:16:59Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 31 16:16:59 volumio go-librespot[8894]: time="2025-10-31T16:16:59Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 31 16:16:59 volumio go-librespot[8894]: time="2025-10-31T16:16:59Z" level=info msg="zeroconf server listening on port 42759" Oct 31 16:16:59 volumio go-librespot[8894]: time="2025-10-31T16:16:59Z" level=debug msg="obtained new client token: AABIb65teljD9FVxGXF1NGMq9ZVYAC6LFB7JFRsiRnWXrsNuireVIqGcEgcmL04zUB9fxy1K3lSLTYMF4Ru8KXsMdOPWQvtnRSzvNzaKkrKor18hsVf7mT+qUP0TdWEtaeQQejo2RhLk5Z8C4BLzYbGPGG0HR4Lcsqe+yFqD1q9uV8+QSCfOaRPH2Hg7MmnrpztTSdZr3oySPtqKrjFRQCWQ9M+UCMcrKFFAUhUqRscvqbOklWO4Sf8=" Oct 31 16:16:59 volumio go-librespot[8894]: time="2025-10-31T16:16:59Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 31 16:17:00 volumio go-librespot[8894]: time="2025-10-31T16:17:00Z" level=debug msg="completed keyexchange" Oct 31 16:17:00 volumio go-librespot[8894]: time="2025-10-31T16:17:00Z" level=debug msg="completed challenge" Oct 31 16:17:00 volumio go-librespot[8894]: time="2025-10-31T16:17:00Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 31 16:17:00 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 31 16:17:00 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 31 16:17:01 volumio volumio[8361]: info: Initializing connection to go-librespot Websocket Oct 31 16:17:01 volumio volumio[8361]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 31 16:17:03 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 28. Oct 31 16:17:03 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 31 16:17:03 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 31 16:17:03 volumio go-librespot[8916]: go-librespot daemon starting... Oct 31 16:17:03 volumio go-librespot[8917]: time="2025-10-31T16:17:03Z" level=info msg="running go-librespot 0.4.0" Oct 31 16:17:03 volumio go-librespot[8917]: time="2025-10-31T16:17:03Z" level=debug msg="app state loaded" Oct 31 16:17:03 volumio go-librespot[8917]: time="2025-10-31T16:17:03Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 31 16:17:03 volumio go-librespot[8917]: time="2025-10-31T16:17:03Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Oct 31 16:17:03 volumio go-librespot[8917]: time="2025-10-31T16:17:03Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Oct 31 16:17:03 volumio go-librespot[8917]: time="2025-10-31T16:17:03Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Oct 31 16:17:03 volumio go-librespot[8917]: time="2025-10-31T16:17:03Z" level=info msg="zeroconf server listening on port 45283" Oct 31 16:17:03 volumio go-librespot[8917]: time="2025-10-31T16:17:03Z" level=debug msg="obtained new client token: AAACeVG/OcsJDe9kdrZQjWPU9Tv9B/K0RkCqGZHOqHl9kVvjciPIktwv2NQm2uq9fSY0imZIdIUmyMk8RIT7X36VgXCe1soxRGNlWAbmYdqsi/doCSH8wTsS3uBhvwZA8TdrCqTmQ/e1dDspoLFCS3fIxCqR5ec+2Orm/t/Pfv+Vuxty1UMUD68qGVFn5vsM78zL//zhBQ83mmROtBwRJ9+KcH8UC+kKjTQOcTHp0vJXElFXajPysn4=" Oct 31 16:17:03 volumio go-librespot[8917]: time="2025-10-31T16:17:03Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 31 16:17:03 volumio go-librespot[8917]: time="2025-10-31T16:17:03Z" level=debug msg="completed keyexchange" Oct 31 16:17:03 volumio go-librespot[8917]: time="2025-10-31T16:17:03Z" level=debug msg="completed challenge" Oct 31 16:17:03 volumio go-librespot[8917]: time="2025-10-31T16:17:03Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 31 16:17:03 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 31 16:17:03 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 31 16:17:04 volumio volumio[8361]: info: Initializing connection to go-librespot Websocket Oct 31 16:17:04 volumio volumio[8361]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 31 16:17:06 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 29. Oct 31 16:17:06 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 31 16:17:06 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 31 16:17:06 volumio go-librespot[8924]: go-librespot daemon starting... Oct 31 16:17:06 volumio go-librespot[8925]: time="2025-10-31T16:17:06Z" level=info msg="running go-librespot 0.4.0" Oct 31 16:17:06 volumio go-librespot[8925]: time="2025-10-31T16:17:06Z" level=debug msg="app state loaded" Oct 31 16:17:06 volumio go-librespot[8925]: time="2025-10-31T16:17:06Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 31 16:17:06 volumio go-librespot[8925]: time="2025-10-31T16:17:06Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Oct 31 16:17:06 volumio go-librespot[8925]: time="2025-10-31T16:17:06Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 31 16:17:06 volumio go-librespot[8925]: time="2025-10-31T16:17:06Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 31 16:17:06 volumio go-librespot[8925]: time="2025-10-31T16:17:06Z" level=info msg="zeroconf server listening on port 34065" Oct 31 16:17:06 volumio go-librespot[8925]: time="2025-10-31T16:17:06Z" level=debug msg="obtained new client token: AAAZ5uL0znVw3SqnDheMYIpDlaPX28oohr2HGAGENPf7OYOcDija2NiMkYK5FhfEF0sdSi2kocKAOHnOTduUsOxCJ9m2dumK+pcDq404L6+H/QtLx9pgHnOqp0S42TjmseGrsqi+6re4FZRNdxD+CO6EE/hR656dX2HWD9DsELBNvssjXPfCU879oBBBOKcVSYUev08bPZuaJkyipXqiHZEQYE6zz2UW1W9/GaYR1zfKvcQv2XfFObo=" Oct 31 16:17:06 volumio go-librespot[8925]: time="2025-10-31T16:17:06Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 31 16:17:07 volumio go-librespot[8925]: time="2025-10-31T16:17:07Z" level=debug msg="completed keyexchange" Oct 31 16:17:07 volumio go-librespot[8925]: time="2025-10-31T16:17:07Z" level=debug msg="completed challenge" Oct 31 16:17:07 volumio go-librespot[8925]: time="2025-10-31T16:17:07Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 31 16:17:07 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 31 16:17:07 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 31 16:17:07 volumio volumio[8361]: info: Initializing connection to go-librespot Websocket Oct 31 16:17:07 volumio volumio[8361]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 31 16:17:10 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 30. Oct 31 16:17:10 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 31 16:17:10 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 31 16:17:10 volumio go-librespot[8935]: go-librespot daemon starting... Oct 31 16:17:10 volumio go-librespot[8936]: time="2025-10-31T16:17:10Z" level=info msg="running go-librespot 0.4.0" Oct 31 16:17:10 volumio go-librespot[8936]: time="2025-10-31T16:17:10Z" level=debug msg="app state loaded" Oct 31 16:17:10 volumio go-librespot[8936]: time="2025-10-31T16:17:10Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 31 16:17:10 volumio go-librespot[8936]: time="2025-10-31T16:17:10Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Oct 31 16:17:10 volumio go-librespot[8936]: time="2025-10-31T16:17:10Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 31 16:17:10 volumio go-librespot[8936]: time="2025-10-31T16:17:10Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 31 16:17:10 volumio go-librespot[8936]: time="2025-10-31T16:17:10Z" level=info msg="zeroconf server listening on port 39237" Oct 31 16:17:10 volumio volumio[8361]: info: Initializing connection to go-librespot Websocket Oct 31 16:17:10 volumio go-librespot[8936]: time="2025-10-31T16:17:10Z" level=debug msg="new websocket client" Oct 31 16:17:10 volumio volumio[8361]: info: Connection to go-librespot Websocket established Oct 31 16:17:10 volumio go-librespot[8936]: time="2025-10-31T16:17:10Z" level=debug msg="obtained new client token: AAC8RQ3ZPKl3G8E0kkwcbS5P8SRAQJQjD2ob9XCcm/6oXh0jMvUGBax36xGw3JK+ruXqF//VBkekeiCpo1zCAUSzH+/mF4Ymc9tAZrw52UzoGgrcO6tTlVl5tOrj1vOhT3iOK/fTvooQZYOVdaqF4bTVKSBhJ76dSpwOmy05hV8hDdjoBHJcEdfGzVA2npYz6Ck65NCAAM0dsVlIGt5YR8blL69fIw0ovpWLAOCoWnwMyNsds89J9PE=" Oct 31 16:17:10 volumio go-librespot[8936]: time="2025-10-31T16:17:10Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 31 16:17:10 volumio go-librespot[8936]: time="2025-10-31T16:17:10Z" level=debug msg="completed keyexchange" Oct 31 16:17:10 volumio go-librespot[8936]: time="2025-10-31T16:17:10Z" level=debug msg="completed challenge" Oct 31 16:17:10 volumio go-librespot[8936]: time="2025-10-31T16:17:10Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 31 16:17:10 volumio volumio[8361]: info: Connection to go-librespot Websocket closed Oct 31 16:17:10 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 31 16:17:10 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 31 16:17:13 volumio volumio[8361]: info: Getting Spotify volume Oct 31 16:17:13 volumio volumio[8361]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 31 16:17:13 volumio volumio[8361]: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 31 16:17:13 volumio volumio[8361]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Oct 31 16:17:13 volumio volumio[8361]: errno: -111, Oct 31 16:17:13 volumio volumio[8361]: code: 'ECONNREFUSED', Oct 31 16:17:13 volumio volumio[8361]: syscall: 'connect', Oct 31 16:17:13 volumio volumio[8361]: address: '127.0.0.1', Oct 31 16:17:13 volumio volumio[8361]: port: 9879, Oct 31 16:17:13 volumio volumio[8361]: response: undefined Oct 31 16:17:13 volumio volumio[8361]: } Oct 31 16:17:13 volumio volumio[8361]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 31 16:17:13 volumio sudo[8971]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-10-31 16:16' Oct 31 16:17:13 volumio sudo[8971]: 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"