Oct 30 21:59:02 volumio go-librespot[13196]: time="2025-10-30T21:59:02Z" 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 30 21:59:02 volumio volumio[12884]: error: Failed to send command to Spotify local API: /player/volume: Error: socket hang up Oct 30 21:59:02 volumio volumio[12884]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 30 21:59:02 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 30 21:59:02 volumio volumio[12884]: Error: socket hang up Oct 30 21:59:02 volumio volumio[12884]: at connResetException (node:internal/errors:720:14) Oct 30 21:59:02 volumio volumio[12884]: at Socket.socketOnEnd (node:_http_client:519:23) Oct 30 21:59:02 volumio volumio[12884]: at Socket.emit (node:events:526:35) Oct 30 21:59:02 volumio volumio[12884]: at endReadableNT (node:internal/streams/readable:1376:12) Oct 30 21:59:02 volumio volumio[12884]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { Oct 30 21:59:02 volumio volumio[12884]: code: 'ECONNRESET', Oct 30 21:59:02 volumio volumio[12884]: response: undefined Oct 30 21:59:02 volumio volumio[12884]: } Oct 30 21:59:02 volumio volumio[12884]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 30 21:59:02 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 30 21:59:02 volumio sudo[14280]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-10-30 21:58' Oct 30 21:59:02 volumio sudo[14280]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 30 21:59:02 volumio sudo[14280]: pam_unix(sudo:session): session closed for user root Oct 30 21:59:02 volumio volumio-remote-updater[874]: [2025-10-30 21:59:02] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Oct 30 21:59:02 volumio volumio-remote-updater[874]: [2025-10-30 21:59:02] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Oct 30 21:59:02 volumio systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Oct 30 21:59:02 volumio systemd[1]: volumio.service: Failed with result 'exit-code'. Oct 30 21:59:02 volumio systemd[1]: volumio.service: Consumed 8.806s CPU time. Oct 30 21:59:02 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Oct 30 21:59:02 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Oct 30 21:59:02 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 3333. Oct 30 21:59:02 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Oct 30 21:59:02 volumio systemd[1]: Stopped volumio.service - Volumio Backend Module. Oct 30 21:59:02 volumio systemd[1]: volumio.service: Consumed 8.806s CPU time. Oct 30 21:59:02 volumio systemd[1]: Started volumio.service - Volumio Backend Module. Oct 30 21:59:02 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Oct 30 21:59:02 volumio volumio[14327]: info: ------------------------------------------- Oct 30 21:59:02 volumio volumio[14327]: info: ----- Volumio3 ---- Oct 30 21:59:02 volumio volumio[14327]: info: ------------------------------------------- Oct 30 21:59:02 volumio volumio[14327]: info: ----- System startup ---- Oct 30 21:59:02 volumio volumio[14327]: info: ------------------------------------------- Oct 30 21:59:03 volumio volumio[14327]: info: MYVOLUMIO Environment detected Oct 30 21:59:03 volumio volumio[14327]: info: Plugin folders cleanup Oct 30 21:59:03 volumio volumio[14327]: info: Scanning into folder /volumio/app/plugins/ Oct 30 21:59:03 volumio volumio[14327]: info: Scanning category audio_interface Oct 30 21:59:03 volumio volumio[14327]: info: Scanning category miscellanea Oct 30 21:59:03 volumio volumio[14327]: info: Scanning category music_service Oct 30 21:59:03 volumio volumio[14327]: info: Scanning category plugins.json Oct 30 21:59:03 volumio volumio[14327]: info: Scanning category system_controller Oct 30 21:59:03 volumio volumio[14327]: info: Scanning category user_interface Oct 30 21:59:03 volumio volumio[14327]: info: Scanning into folder /data/plugins/ Oct 30 21:59:03 volumio volumio[14327]: info: Scanning category music_service Oct 30 21:59:03 volumio volumio[14327]: info: Scanning category user_interface Oct 30 21:59:03 volumio volumio[14327]: info: Plugin folders cleanup completed Oct 30 21:59:03 volumio volumio[14327]: info: ------------------------------------------- Oct 30 21:59:03 volumio volumio[14327]: info: ----- Core plugins startup ---- Oct 30 21:59:03 volumio volumio[14327]: info: ------------------------------------------- Oct 30 21:59:03 volumio volumio[14327]: info: Loading plugins from folder /volumio/app/plugins/ Oct 30 21:59:03 volumio volumio[14327]: info: Adding plugin upnp to MyMusic Plugins Oct 30 21:59:03 volumio volumio[14327]: info: Adding plugin airplay_emulation to MyMusic Plugins Oct 30 21:59:03 volumio volumio[14327]: info: Adding plugin upnp_browser to MyMusic Plugins Oct 30 21:59:03 volumio volumio[14327]: info: Loading plugins from folder /data/plugins/ Oct 30 21:59:03 volumio volumio[14327]: info: Loading plugin "system"... Oct 30 21:59:03 volumio volumio[14327]: info: Loading plugin "appearance"... Oct 30 21:59:03 volumio volumio[14327]: info: Loading plugin "network"... Oct 30 21:59:03 volumio volumio[14327]: info: Refreshing Cached IP Addresses Oct 30 21:59:03 volumio sudo[14352]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 30 21:59:03 volumio sudo[14352]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 30 21:59:03 volumio volumio[14327]: info: Loading plugin "services"... Oct 30 21:59:03 volumio sudo[14352]: pam_unix(sudo:session): session closed for user root Oct 30 21:59:03 volumio volumio[14327]: info: Loading plugin "alsa_controller"... Oct 30 21:59:03 volumio sudo[14354]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 30 21:59:03 volumio sudo[14354]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 30 21:59:03 volumio sudo[14354]: pam_unix(sudo:session): session closed for user root Oct 30 21:59:03 volumio volumio[14327]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 30 21:59:03 volumio volumio[14327]: info: Loading plugin "wizard"... Oct 30 21:59:03 volumio volumio[14327]: info: Loading plugin "networkfs"... Oct 30 21:59:03 volumio volumio[14327]: info: Cannot mount NAS NAS at system boot, trial number 1 ,retrying in 5 seconds Oct 30 21:59:03 volumio volumio[14327]: info: Starting Udev Watcher for removable devices Oct 30 21:59:03 volumio volumio[14327]: info: Ignoring mount for partition: boot Oct 30 21:59:03 volumio volumio[14327]: info: Ignoring mount for partition: volumio Oct 30 21:59:03 volumio volumio[14327]: info: Ignoring mount for partition: volumio_data Oct 30 21:59:03 volumio volumio[14327]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 30 21:59:03 volumio volumio[14327]: info: Loading plugin "volumio_command_line_client"... Oct 30 21:59:03 volumio volumio[14327]: info: Loading plugin "upnp"... Oct 30 21:59:03 volumio volumio[14327]: info: [1761861543319] Starting Upmpd Daemon Oct 30 21:59:03 volumio volumio[14327]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 30 21:59:03 volumio volumio[14327]: info: Loading plugin "my_music"... Oct 30 21:59:03 volumio volumio[14327]: info: Loading plugin "mpd"... Oct 30 21:59:03 volumio volumio[14327]: info: Loading plugin "upnp_browser"... Oct 30 21:59:03 volumio volumio[14327]: info: Loading plugin "alarm-clock"... Oct 30 21:59:03 volumio volumio[14327]: info: Loading plugin "airplay_emulation"... Oct 30 21:59:03 volumio volumio[14327]: info: Starting Shairport Sync Oct 30 21:59:03 volumio volumio[14327]: info: Loading plugin "last_100"... Oct 30 21:59:03 volumio volumio[14327]: info: Loading plugin "webradio"... Oct 30 21:59:03 volumio volumio[14327]: info: Loading plugin "i2s_dacs"... Oct 30 21:59:03 volumio volumio[14327]: info: I2S DAC not set, start Auto-detection Oct 30 21:59:03 volumio volumio[14327]: info: Loading plugin "volumiodiscovery"... Oct 30 21:59:03 volumio volumio[14327]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Oct 30 21:59:03 volumio volumio[14327]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 30 21:59:03 volumio volumio[14327]: *** WARNING *** For more information see Oct 30 21:59:03 volumio volumio[14327]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Oct 30 21:59:03 volumio volumio[14327]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 30 21:59:03 volumio volumio[14327]: *** WARNING *** For more information see Oct 30 21:59:03 volumio node[14327]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Oct 30 21:59:03 volumio node[14327]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 30 21:59:03 volumio node[14327]: *** WARNING *** For more information see Oct 30 21:59:03 volumio node[14327]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Oct 30 21:59:03 volumio node[14327]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 30 21:59:03 volumio node[14327]: *** WARNING *** For more information see Oct 30 21:59:03 volumio volumio[14327]: info: Applying required configuration parameters for plugin volumiodiscovery Oct 30 21:59:03 volumio volumio[14327]: info: Discovery: Started advertising with name: Volumio Oct 30 21:59:03 volumio volumio[14327]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 30 21:59:03 volumio volumio[14327]: info: Loading plugin "spop"... Oct 30 21:59:03 volumio volumio[14327]: info: Loading plugin "ytcr"... Oct 30 21:59:04 volumio volumio[14327]: info: Loading plugin "outputs"... Oct 30 21:59:04 volumio volumio[14327]: info: Loading plugin "albumart"... Oct 30 21:59:04 volumio volumio[14327]: info: Plugin example_plugin is not enabled Oct 30 21:59:04 volumio volumio[14327]: info: Loading plugin "inputs"... Oct 30 21:59:04 volumio volumio[14327]: info: Loading plugin "updater_comm"... Oct 30 21:59:04 volumio volumio[14327]: info: Plugin mpdemulation is not enabled Oct 30 21:59:04 volumio volumio[14327]: info: Loading plugin "rest_api"... Oct 30 21:59:04 volumio volumio[14327]: info: Loading plugin "websocket"... Oct 30 21:59:04 volumio volumio[14327]: info: Starting Socket.io Server version 1.7.4 Oct 30 21:59:04 volumio volumio[14327]: info: Loading plugin "Systeminfo"... Oct 30 21:59:04 volumio volumio[14327]: info: Loading i18n strings for locale en Oct 30 21:59:04 volumio volumio[14327]: Updating browse sources language Oct 30 21:59:04 volumio volumio[14327]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 30 21:59:04 volumio volumio[14384]: Forking 3 albumart workers Oct 30 21:59:04 volumio volumio[14327]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 30 21:59:04 volumio volumio[14327]: info: CoreCommandRouter::initPlayerControls Oct 30 21:59:04 volumio volumio[14327]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 21:59:04 volumio volumio[14327]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 21:59:04 volumio volumio[14327]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 21:59:04 volumio volumio[14327]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 21:59:04 volumio volumio[14327]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 21:59:04 volumio volumio[14327]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 21:59:04 volumio volumio[14327]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 21:59:04 volumio volumio[14327]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 21:59:04 volumio volumio[14327]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 30 21:59:04 volumio volumio[14327]: Express server listening on port 3000 Oct 30 21:59:04 volumio volumio[14327]: [Metrics] WebUI: 1s 955.13ms Oct 30 21:59:04 volumio volumio[14327]: info: CoreStateMachine::resetVolumioState Oct 30 21:59:04 volumio volumio[14327]: info: CoreStateMachine::getcurrentVolume Oct 30 21:59:04 volumio volumio[14327]: info: CoreCommandRouter::volumioRetrievevolume Oct 30 21:59:04 volumio volumio[14327]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 30 21:59:04 volumio volumio[14327]: info: Cannot read play queue from file Oct 30 21:59:04 volumio volumio[14327]: info: Volumio Network Manager: Network status updated: 1 Oct 30 21:59:04 volumio volumio[14327]: info: VolumeController:: Volume=33 Mute =false Oct 30 21:59:04 volumio volumio[14327]: info: CoreStateMachine::pushState Oct 30 21:59:04 volumio volumio[14327]: info: CorePlayQueue::getTrack 0 Oct 30 21:59:04 volumio volumio[14327]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 30 21:59:04 volumio volumio[14327]: info: CoreCommandRouter::volumioPushState Oct 30 21:59:04 volumio volumio[14327]: info: CoreStateMachine::updateTrackBlock Oct 30 21:59:04 volumio volumio[14327]: info: CorePlayQueue::getTrackBlock Oct 30 21:59:04 volumio volumio[14327]: info: CoreCommandRouter::volumioRetrievevolume Oct 30 21:59:04 volumio volumio[14327]: info: CoreStateMachine::setRepeat null single undefined Oct 30 21:59:04 volumio volumio[14327]: info: CoreStateMachine::pushState Oct 30 21:59:04 volumio volumio[14327]: info: CorePlayQueue::getTrack 0 Oct 30 21:59:04 volumio volumio[14327]: info: CoreCommandRouter::volumioPushState Oct 30 21:59:04 volumio volumio[14327]: info: CoreStateMachine::setRandom null Oct 30 21:59:04 volumio volumio[14327]: info: CoreStateMachine::pushState Oct 30 21:59:04 volumio volumio[14327]: info: CorePlayQueue::getTrack 0 Oct 30 21:59:04 volumio volumio[14327]: info: CoreCommandRouter::volumioPushState Oct 30 21:59:04 volumio volumio[14327]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Oct 30 21:59:04 volumio volumio[14327]: info: USB Boot Capable - System SBC Revision found in cpuinfo: b04170 Oct 30 21:59:04 volumio volumio[14327]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Oct 30 21:59:04 volumio volumio[14327]: info: VolumeController:: Volume=33 Mute =false Oct 30 21:59:04 volumio volumio[14327]: info: CoreStateMachine::pushState Oct 30 21:59:04 volumio volumio[14327]: info: CorePlayQueue::getTrack 0 Oct 30 21:59:04 volumio volumio[14327]: info: CoreCommandRouter::volumioPushState Oct 30 21:59:04 volumio volumio[14327]: info: Setting Device type: Raspberry PI Oct 30 21:59:04 volumio volumio[14327]: info: Completed loading Core Plugins Oct 30 21:59:04 volumio volumio[14327]: info: Preparing to generate the ALSA configuration file Oct 30 21:59:04 volumio volumio[14327]: info: Discovery: adding 70853f74-8210-4683-a3fa-e1217517bd40 Oct 30 21:59:04 volumio volumio[14327]: info: Discovery: Found device Volumio Oct 30 21:59:04 volumio volumio[14327]: info: CoreCommandRouter::volumioGetState Oct 30 21:59:04 volumio volumio[14327]: info: CorePlayQueue::getTrack 0 Oct 30 21:59:04 volumio volumio[14327]: info: Discovery: this is already registered, 70853f74-8210-4683-a3fa-e1217517bd40 Oct 30 21:59:04 volumio volumio[14327]: info: Discovery: Found device Volumio Oct 30 21:59:04 volumio volumio[14327]: info: CoreCommandRouter::volumioGetState Oct 30 21:59:04 volumio volumio[14327]: info: CorePlayQueue::getTrack 0 Oct 30 21:59:04 volumio volumio[14327]: info: Asound.conf file unchanged, so no further update is needed Oct 30 21:59:04 volumio volumio[14327]: info: Output device has changed, restarting MPD Oct 30 21:59:04 volumio sudo[14440]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 30 21:59:04 volumio volumio[14327]: info: Output device has changed, restarting Shairport Sync Oct 30 21:59:04 volumio volumio[14327]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 21:59:04 volumio volumio[14327]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 30 21:59:04 volumio sudo[14440]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 30 21:59:04 volumio sudo[14440]: pam_unix(sudo:session): session closed for user root Oct 30 21:59:04 volumio volumio[14327]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 30 21:59:04 volumio volumio[14327]: info: ___________ START PLUGINS ___________ Oct 30 21:59:04 volumio volumio[14327]: info: ControllerMpd::onStart: Initializing MPD Oct 30 21:59:04 volumio volumio[14327]: info: Creating MPD Configuration file Oct 30 21:59:04 volumio sudo[14442]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 30 21:59:04 volumio sudo[14442]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 30 21:59:04 volumio volumio[14327]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 30 21:59:04 volumio volumio[14327]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 30 21:59:04 volumio volumio[14327]: info: [1761861544996] CoreMusicLibrary::Adding element Media Servers Oct 30 21:59:04 volumio volumio[14327]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 30 21:59:05 volumio sudo[14452]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 30 21:59:05 volumio sudo[14452]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 30 21:59:05 volumio sudo[14450]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 30 21:59:05 volumio sudo[14450]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 30 21:59:05 volumio volumio[14327]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 21:59:05 volumio volumio[14327]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 30 21:59:05 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Oct 30 21:59:05 volumio sudo[14450]: pam_unix(sudo:session): session closed for user root Oct 30 21:59:05 volumio systemd[1]: mpd.service: Deactivated successfully. Oct 30 21:59:05 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Oct 30 21:59:05 volumio systemd[1]: mpd.socket: Deactivated successfully. Oct 30 21:59:05 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Oct 30 21:59:05 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Oct 30 21:59:05 volumio volumio[14327]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 30 21:59:05 volumio volumio[14327]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 21:59:05 volumio volumio[14327]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 30 21:59:05 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Oct 30 21:59:05 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Oct 30 21:59:05 volumio volumio[14327]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 30 21:59:05 volumio volumio[14327]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 30 21:59:05 volumio volumio[14327]: info: [1761861545087] CoreMusicLibrary::Adding element Last_100 Oct 30 21:59:05 volumio volumio[14327]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 30 21:59:05 volumio volumio[14327]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 30 21:59:05 volumio volumio[14327]: info: [1761861545087] CoreMusicLibrary::Adding element Webradio Oct 30 21:59:05 volumio volumio[14327]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 30 21:59:05 volumio volumio[14327]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 30 21:59:05 volumio volumio[14327]: info: Initializing BBC Radios Oct 30 21:59:05 volumio sudo[14464]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Oct 30 21:59:05 volumio sudo[14464]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Oct 30 21:59:05 volumio sudo[14464]: pam_unix(sudo:session): session closed for user root Oct 30 21:59:05 volumio volumio[14327]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 30 21:59:05 volumio volumio[14327]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 30 21:59:05 volumio volumio[14327]: info: Creating Spotify config file Oct 30 21:59:05 volumio volumio[14327]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 21:59:05 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 88. Oct 30 21:59:05 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 30 21:59:05 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 30 21:59:05 volumio go-librespot[14480]: go-librespot daemon starting... Oct 30 21:59:05 volumio go-librespot[14481]: time="2025-10-30T21:59:05Z" level=info msg="running go-librespot 0.4.0" Oct 30 21:59:05 volumio volumio[14396]: Starting albumart workers Oct 30 21:59:05 volumio volumio[14395]: Starting albumart workers Oct 30 21:59:05 volumio volumio[14394]: Starting albumart workers Oct 30 21:59:05 volumio go-librespot[14481]: time="2025-10-30T21:59:05Z" level=info msg="zeroconf server listening on port 42015" Oct 30 21:59:05 volumio volumio[14327]: info: Volumio Calling Home Oct 30 21:59:05 volumio volumio[14327]: info: MPD Permissions set Oct 30 21:59:05 volumio volumio[14327]: info: MPD Permissions set Oct 30 21:59:05 volumio volumio[14327]: info: Spotify config file written Oct 30 21:59:05 volumio sudo[14501]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Oct 30 21:59:05 volumio sudo[14501]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 30 21:59:05 volumio volumio[14327]: 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 30 21:59:05 volumio volumio[14327]: info: Volumio called home Oct 30 21:59:05 volumio volumio[14327]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 21:59:05 volumio volumio[14327]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 21:59:05 volumio volumio[14327]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 21:59:05 volumio volumio[14327]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 21:59:05 volumio volumio[14327]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 21:59:05 volumio volumio[14327]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 21:59:05 volumio volumio[14327]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 21:59:05 volumio volumio[14327]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 21:59:05 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Oct 30 21:59:05 volumio systemd[1]: go-librespot-daemon.service: Killing process 14483 (go-librespot) with signal SIGKILL. Oct 30 21:59:05 volumio volumio[14327]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 30 21:59:05 volumio volumio[14327]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 21:59:05 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Oct 30 21:59:05 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 30 21:59:05 volumio volumio[14327]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 21:59:05 volumio volumio[14327]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 21:59:05 volumio volumio[14327]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 21:59:05 volumio volumio[14327]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 21:59:05 volumio volumio[14327]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 21:59:05 volumio volumio[14327]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 21:59:05 volumio volumio[14327]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 21:59:05 volumio volumio[14327]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 21:59:05 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 30 21:59:05 volumio go-librespot[14517]: go-librespot daemon starting... Oct 30 21:59:05 volumio sudo[14501]: pam_unix(sudo:session): session closed for user root Oct 30 21:59:05 volumio go-librespot[14523]: time="2025-10-30T21:59:05Z" level=info msg="running go-librespot 0.4.0" Oct 30 21:59:05 volumio go-librespot[14523]: time="2025-10-30T21:59:05Z" level=debug msg="app state loaded" Oct 30 21:59:05 volumio go-librespot[14523]: time="2025-10-30T21:59:05Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 30 21:59:05 volumio volumio[14327]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 30 21:59:05 volumio volumio[14327]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 21:59:05 volumio volumio[14327]: info: No need to fix Spotify hosts Oct 30 21:59:05 volumio mpd[14474]: decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Oct 30 21:59:05 volumio mpd[14474]: output: No 'audio_output' defined in config file Oct 30 21:59:05 volumio mpd[14474]: couldn't open play stream: Unknown error 524 Oct 30 21:59:05 volumio mpd[14474]: sndio_output: Error opening default sndio device Oct 30 21:59:05 volumio mpd[14474]: output: Successfully detected a alsa audio device Oct 30 21:59:05 volumio mpd[14474]: zeroconf: No global port, disabling zeroconf Oct 30 21:59:05 volumio systemd[1]: Started mpd.service - Music Player Daemon. Oct 30 21:59:05 volumio sudo[14452]: pam_unix(sudo:session): session closed for user root Oct 30 21:59:05 volumio sudo[14442]: pam_unix(sudo:session): session closed for user root Oct 30 21:59:05 volumio volumio[14327]: info: Starting Shairport Sync Oct 30 21:59:05 volumio volumio[14327]: info: Starting Shairport Sync Oct 30 21:59:05 volumio volumio[14327]: info: Starting Shairport Sync Oct 30 21:59:05 volumio sudo[14536]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 30 21:59:05 volumio sudo[14536]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 30 21:59:05 volumio sudo[14535]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 30 21:59:05 volumio sudo[14535]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 30 21:59:05 volumio sudo[14539]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 30 21:59:05 volumio sudo[14539]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 30 21:59:05 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Oct 30 21:59:05 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Oct 30 21:59:05 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Oct 30 21:59:05 volumio systemd[1]: shairport-sync.service: Consumed 1.879s CPU time. Oct 30 21:59:05 volumio volumio[14327]: error: MPD error: The expression evaluated to a falsy value: Oct 30 21:59:05 volumio volumio[14327]: assert.ok(self.idling) Oct 30 21:59:05 volumio volumio[14327]: error: The expression evaluated to a falsy value: Oct 30 21:59:05 volumio volumio[14327]: assert.ok(self.idling) Oct 30 21:59:05 volumio volumio[14327]: info: MPD running with PID14474 Oct 30 21:59:05 volumio volumio[14327]: ,establishing connection Oct 30 21:59:05 volumio volumio[14327]: error: MPD error: The expression evaluated to a falsy value: Oct 30 21:59:05 volumio volumio[14327]: assert.ok(self.idling) Oct 30 21:59:05 volumio volumio[14327]: error: The expression evaluated to a falsy value: Oct 30 21:59:05 volumio volumio[14327]: assert.ok(self.idling) Oct 30 21:59:05 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Oct 30 21:59:05 volumio go-librespot[14523]: time="2025-10-30T21:59:05Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Oct 30 21:59:05 volumio go-librespot[14523]: time="2025-10-30T21:59:05Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 30 21:59:05 volumio go-librespot[14523]: time="2025-10-30T21:59:05Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 30 21:59:05 volumio go-librespot[14523]: time="2025-10-30T21:59:05Z" level=info msg="zeroconf server listening on port 35195" Oct 30 21:59:05 volumio sudo[14536]: pam_unix(sudo:session): session closed for user root Oct 30 21:59:05 volumio sudo[14535]: pam_unix(sudo:session): session closed for user root Oct 30 21:59:05 volumio sudo[14539]: pam_unix(sudo:session): session closed for user root Oct 30 21:59:05 volumio volumio[14327]: info: CoreCommandRouter::volumioGetState Oct 30 21:59:05 volumio volumio[14327]: info: CorePlayQueue::getTrack 0 Oct 30 21:59:05 volumio volumio[14327]: info: Shairport-Sync Started Oct 30 21:59:05 volumio volumio[14327]: Error adding Membership: Error: addMembership EINVAL Oct 30 21:59:05 volumio volumio[14327]: error: updateQueue error: null Oct 30 21:59:05 volumio volumio[14327]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Oct 30 21:59:05 volumio volumio[14327]: SPOTIFY: BQDsQBj9fO8df5t5mQeDv2tQvInW3Yd5cG9c2WdWhoyoQezlZX2LTUUNgQ9XRS6G_BORo2hS3-IR3M0SJURLTowCllgJDcnVmdt2wev7jWl_XX-6THn1pHR3RFchTju6X72cdolaSOCleAaCUWrhElsG38wZFgZrHCmIsyH7mFfCdVFSfbGOgto_sC8jWu48x6Fm1FdbJdpPLCYVAolADxXUr6R8Wh-aBachtL-L6K6aobE4dZzpPz9Exa0Dxkb3MeU98WCDYhpKzu9GohdrmobqVc4vC7H8o44zMq929MM8YZV7PR8 Oct 30 21:59:05 volumio volumio[14327]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Oct 30 21:59:05 volumio volumio[14327]: info: New Spotify access token = BQDsQBj9fO8df5t5mQeDv2tQvInW3Yd5cG9c2WdWhoyoQezlZX2LTUUNgQ9XRS6G_BORo2hS3-IR3M0SJURLTowCllgJDcnVmdt2wev7jWl_XX-6THn1pHR3RFchTju6X72cdolaSOCleAaCUWrhElsG38wZFgZrHCmIsyH7mFfCdVFSfbGOgto_sC8jWu48x6Fm1FdbJdpPLCYVAolADxXUr6R8Wh-aBachtL-L6K6aobE4dZzpPz9Exa0Dxkb3MeU98WCDYhpKzu9GohdrmobqVc4vC7H8o44zMq929MM8YZV7PR8 Oct 30 21:59:05 volumio volumio[14327]: info: Spotify credentials grant success - running version from March 24, 2019 Oct 30 21:59:05 volumio volumio[14327]: info: Shairport-Sync Started Oct 30 21:59:05 volumio volumio[14327]: info: Shairport-Sync Started Oct 30 21:59:05 volumio go-librespot[14523]: time="2025-10-30T21:59:05Z" level=debug msg="obtained new client token: AAAwPR6ECl+blcfCEbs/wz6zYfYJIYHbWNstAQMywtL06Ipf3xzOx3M40EwM5hJ42QTXBSlhM7nPZ+Ab7yAZ5j9JjC/7Qxr1Z2i3hWfcOkOJCQVUvaVXlrYmBbLJB2MhjdGAswY+6Sr9SLwzpP7xhXABIkas5lv3InBKXjjdu6Q6rn6V++P8Z+HZUq55Kk89unoZRI3juHsLPhDIJZUzBC5aL/aD7Q8bkRVAmJ5A9RkweRCOgKvMPjk=" Oct 30 21:59:05 volumio go-librespot[14523]: time="2025-10-30T21:59:05Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 30 21:59:05 volumio go-librespot[14523]: time="2025-10-30T21:59:05Z" level=debug msg="completed keyexchange" Oct 30 21:59:05 volumio go-librespot[14523]: time="2025-10-30T21:59:05Z" level=debug msg="completed challenge" Oct 30 21:59:05 volumio go-librespot[14523]: time="2025-10-30T21:59:05Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 30 21:59:05 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 30 21:59:05 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 30 21:59:05 volumio volumio[14327]: 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 30 21:59:05 volumio volumio[14327]: info: Spotify Successfully logged in Oct 30 21:59:05 volumio volumio[14327]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 30 21:59:05 volumio volumio[14327]: info: [1761861545967] CoreMusicLibrary::Adding element Spotify Oct 30 21:59:05 volumio volumio[14327]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 30 21:59:05 volumio volumio[14327]: Cannot find translation for source Spotify Oct 30 21:59:06 volumio volumio[14327]: info: [yt-cast-receiver] DIAL server listening on port 8098 Oct 30 21:59:06 volumio volumio[14327]: info: CoreCommandRouter::volumioRetrievevolume Oct 30 21:59:06 volumio volumio[14327]: info: VolumeController:: Volume=33 Mute =false Oct 30 21:59:06 volumio volumio[14327]: info: CoreCommandRouter::volumioGetState Oct 30 21:59:06 volumio volumio[14327]: info: CorePlayQueue::getTrack 0 Oct 30 21:59:06 volumio volumio[14327]: info: CoreStateMachine::pushState Oct 30 21:59:06 volumio volumio[14327]: info: CorePlayQueue::getTrack 0 Oct 30 21:59:06 volumio volumio[14327]: info: CoreCommandRouter::volumioPushState Oct 30 21:59:06 volumio volumio[14327]: info: Completed starting Core Plugins Oct 30 21:59:06 volumio volumio[14327]: info: ------------------------------------------- Oct 30 21:59:06 volumio volumio[14327]: info: ----- MyVolumio plugins startup ---- Oct 30 21:59:06 volumio volumio[14327]: info: ------------------------------------------- Oct 30 21:59:06 volumio volumio[14327]: info: [MyVolumio PluginManager] Fetching plans data.... Oct 30 21:59:07 volumio volumio-remote-updater[874]: [2025-10-30 21:59:07] [connect] Successful connection Oct 30 21:59:07 volumio volumio-remote-updater[874]: [2025-10-30 21:59:07] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1761861547 101 Oct 30 21:59:07 volumio volumio[14327]: 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 30 21:59:08 volumio volumio[14327]: info: Cannot mount NAS NAS at system boot, trial number 2 ,retrying in 5 seconds Oct 30 21:59:08 volumio volumio[14327]: info: go-librespot daemon successfully initialized Oct 30 21:59:08 volumio sudo[14563]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Oct 30 21:59:08 volumio sudo[14563]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 30 21:59:08 volumio systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Oct 30 21:59:08 volumio systemd[1]: mpd_monitor.service: Deactivated successfully. Oct 30 21:59:08 volumio systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Oct 30 21:59:08 volumio sudo[14567]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Oct 30 21:59:08 volumio sudo[14567]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 30 21:59:08 volumio systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Oct 30 21:59:08 volumio mpd_monitor.sh[14565]: MPD Monitor Service: Starting MPD Monitor Service Oct 30 21:59:08 volumio sudo[14563]: pam_unix(sudo:session): session closed for user root Oct 30 21:59:08 volumio volumio[14327]: info: Successfully started MPD Monitor Oct 30 21:59:08 volumio mpd[14474]: mixer: Failed to read mixer for "default detected output": no such mixer control: PCM Oct 30 21:59:08 volumio systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Oct 30 21:59:08 volumio systemd[1]: mpd_monitor.service: Deactivated successfully. Oct 30 21:59:08 volumio systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Oct 30 21:59:08 volumio systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Oct 30 21:59:08 volumio sudo[14567]: pam_unix(sudo:session): session closed for user root Oct 30 21:59:08 volumio mpd_monitor.sh[14572]: MPD Monitor Service: Starting MPD Monitor Service Oct 30 21:59:08 volumio volumio[14327]: info: Successfully started MPD Monitor Oct 30 21:59:09 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Oct 30 21:59:09 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 30 21:59:09 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 30 21:59:09 volumio go-librespot[14576]: go-librespot daemon starting... Oct 30 21:59:09 volumio go-librespot[14577]: time="2025-10-30T21:59:09Z" level=info msg="running go-librespot 0.4.0" Oct 30 21:59:09 volumio go-librespot[14577]: time="2025-10-30T21:59:09Z" level=debug msg="app state loaded" Oct 30 21:59:09 volumio go-librespot[14577]: time="2025-10-30T21:59:09Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 30 21:59:09 volumio go-librespot[14577]: time="2025-10-30T21:59:09Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Oct 30 21:59:09 volumio go-librespot[14577]: time="2025-10-30T21:59:09Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 30 21:59:09 volumio go-librespot[14577]: time="2025-10-30T21:59:09Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 30 21:59:09 volumio go-librespot[14577]: time="2025-10-30T21:59:09Z" level=info msg="zeroconf server listening on port 45875" Oct 30 21:59:09 volumio go-librespot[14577]: time="2025-10-30T21:59:09Z" level=debug msg="obtained new client token: AAA0V2mbL4OlZhXjBbIYxNhg25JLgqu/tMrfnjZ3ipnsx7roSfBx5jjbXlVD0/WjKDzVpj1dc3qA25Vk9S552qfsH0xHZTNF0t43Xb8zFjfsk1sMndCP+qcL1TPCjnbYhPGdhrfkj1WaCyLshIXoPcbHUXdUJydQbjJ+f+Vc5zi8tteYscKgds2Edz2QSFYDIiKzAP8vmrOPwS/s+F291DVL6QqucVfgPW+rBHAzYU8ShI4gIJe5" Oct 30 21:59:09 volumio go-librespot[14577]: time="2025-10-30T21:59:09Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 30 21:59:09 volumio go-librespot[14577]: time="2025-10-30T21:59:09Z" level=debug msg="completed keyexchange" Oct 30 21:59:09 volumio go-librespot[14577]: time="2025-10-30T21:59:09Z" level=debug msg="completed challenge" Oct 30 21:59:09 volumio go-librespot[14577]: time="2025-10-30T21:59:09Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 30 21:59:09 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 30 21:59:09 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 30 21:59:10 volumio mpd[14474]: exception: No database Oct 30 21:59:10 volumio mpd[14474]: exception: No database Oct 30 21:59:10 volumio mpd[14474]: exception: No database Oct 30 21:59:10 volumio volumio[14327]: error: Failed LSINFO: Error: [50@0] {lsinfo} No database Oct 30 21:59:11 volumio volumio[14327]: info: Initializing connection to go-librespot Websocket Oct 30 21:59:11 volumio volumio[14327]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 30 21:59:12 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Oct 30 21:59:12 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 30 21:59:12 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 30 21:59:12 volumio go-librespot[14585]: go-librespot daemon starting... Oct 30 21:59:12 volumio go-librespot[14586]: time="2025-10-30T21:59:12Z" level=info msg="running go-librespot 0.4.0" Oct 30 21:59:12 volumio go-librespot[14586]: time="2025-10-30T21:59:12Z" level=debug msg="app state loaded" Oct 30 21:59:12 volumio go-librespot[14586]: time="2025-10-30T21:59:12Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 30 21:59:12 volumio go-librespot[14586]: time="2025-10-30T21:59:12Z" 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 30 21:59:12 volumio go-librespot[14586]: time="2025-10-30T21:59:12Z" 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 30 21:59:12 volumio go-librespot[14586]: time="2025-10-30T21:59:12Z" 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 30 21:59:12 volumio go-librespot[14586]: time="2025-10-30T21:59:12Z" level=info msg="zeroconf server listening on port 44337" Oct 30 21:59:12 volumio go-librespot[14586]: time="2025-10-30T21:59:12Z" level=debug msg="obtained new client token: AAAhFx4ZgocEukC30P19EFVegQIEdCvxO85Ga5RK464ARMrdczmKzHqviWEvJeipsF9vhV1XgVhicPBeUoAa5NTNRosbA+gbqyulf/kZHOYjrvX7IslGEk1pFcnrAAtsjihqb3uGm3RDVgXxXq+XXS5IsktZ4BOGZJnQm8GI8tU48trJO55rH/nAKz2D8Z5rGQMA4fzCenxO12eTKdKCex9JiS0zufsqkC/G9R5vUFcHP9xGx6xgiwQ=" Oct 30 21:59:12 volumio go-librespot[14586]: time="2025-10-30T21:59:12Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 30 21:59:12 volumio go-librespot[14586]: time="2025-10-30T21:59:12Z" level=debug msg="completed keyexchange" Oct 30 21:59:12 volumio go-librespot[14586]: time="2025-10-30T21:59:12Z" level=debug msg="completed challenge" Oct 30 21:59:12 volumio go-librespot[14586]: time="2025-10-30T21:59:12Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 30 21:59:12 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 30 21:59:12 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 30 21:59:13 volumio volumio[14327]: info: Cannot mount NAS NAS at system boot, trial number 3 ,retrying in 5 seconds Oct 30 21:59:13 volumio sudo[14608]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 30 21:59:13 volumio sudo[14608]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 30 21:59:13 volumio sudo[14610]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 30 21:59:13 volumio sudo[14610]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 30 21:59:13 volumio sudo[14608]: pam_unix(sudo:session): session closed for user root Oct 30 21:59:13 volumio sudo[14610]: pam_unix(sudo:session): session closed for user root Oct 30 21:59:13 volumio sudo[14614]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Oct 30 21:59:13 volumio sudo[14614]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 30 21:59:13 volumio sudo[14614]: pam_unix(sudo:session): session closed for user root Oct 30 21:59:13 volumio volumio[14327]: info: Upmpdcli Daemon Started Oct 30 21:59:14 volumio volumio[14327]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Oct 30 21:59:14 volumio volumio[14327]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Oct 30 21:59:14 volumio volumio[14327]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Oct 30 21:59:14 volumio volumio[14327]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Oct 30 21:59:14 volumio volumio[14327]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Oct 30 21:59:14 volumio volumio[14327]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Oct 30 21:59:14 volumio volumio[14327]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Oct 30 21:59:14 volumio volumio[14327]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Oct 30 21:59:14 volumio volumio[14327]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Oct 30 21:59:14 volumio volumio[14327]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Oct 30 21:59:14 volumio volumio[14327]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Oct 30 21:59:14 volumio volumio[14327]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Oct 30 21:59:14 volumio volumio[14327]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Oct 30 21:59:14 volumio volumio[14327]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Oct 30 21:59:14 volumio volumio[14327]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Oct 30 21:59:14 volumio volumio[14327]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Oct 30 21:59:14 volumio volumio[14327]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Oct 30 21:59:14 volumio volumio[14327]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Oct 30 21:59:14 volumio volumio[14327]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Oct 30 21:59:14 volumio volumio[14327]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Oct 30 21:59:14 volumio volumio[14327]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Oct 30 21:59:14 volumio volumio[14327]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Oct 30 21:59:14 volumio volumio[14327]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Oct 30 21:59:14 volumio volumio[14327]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Oct 30 21:59:14 volumio volumio[14327]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Oct 30 21:59:14 volumio volumio[14327]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Oct 30 21:59:14 volumio volumio[14327]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Oct 30 21:59:14 volumio volumio[14327]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Oct 30 21:59:14 volumio volumio[14327]: info: Adding plugin bluetooth to MyMusic Plugins Oct 30 21:59:14 volumio volumio[14327]: info: Adding plugin multiroom to MyMusic Plugins Oct 30 21:59:14 volumio volumio[14327]: info: Adding plugin metavolumio to MyMusic Plugins Oct 30 21:59:14 volumio volumio[14327]: info: Adding plugin cd_controller to MyMusic Plugins Oct 30 21:59:14 volumio volumio[14327]: info: Adding plugin qobuzconnect to MyMusic Plugins Oct 30 21:59:14 volumio volumio[14327]: info: Adding plugin smart_inputs to MyMusic Plugins Oct 30 21:59:14 volumio volumio[14327]: info: Adding plugin tidalconnect to MyMusic Plugins Oct 30 21:59:14 volumio volumio[14327]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Oct 30 21:59:14 volumio volumio[14327]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Oct 30 21:59:14 volumio volumio[14327]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Oct 30 21:59:14 volumio volumio[14327]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 30 21:59:14 volumio volumio[14327]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 30 21:59:14 volumio volumio[14327]: info: Starting MyVolumio Remote Streaming Endpoints Oct 30 21:59:14 volumio volumio[14327]: info: MyVolumio login type: Token Oct 30 21:59:14 volumio volumio[14327]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Oct 30 21:59:14 volumio volumio[14327]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Oct 30 21:59:14 volumio volumio[14327]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Oct 30 21:59:14 volumio volumio[14327]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Oct 30 21:59:14 volumio volumio[14327]: info: Streaming services startup Oct 30 21:59:14 volumio volumio[14327]: info: Starting Streaming Daemon Oct 30 21:59:14 volumio sudo[14617]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Oct 30 21:59:14 volumio sudo[14617]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 30 21:59:14 volumio volumio[14327]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Oct 30 21:59:14 volumio sudo[14617]: pam_unix(sudo:session): session closed for user root Oct 30 21:59:14 volumio volumio[14327]: info: Initializing connection to go-librespot Websocket Oct 30 21:59:14 volumio volumio[14327]: error: Cannot start Volumio Streaming Daemon Oct 30 21:59:14 volumio volumio[14327]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Oct 30 21:59:14 volumio volumio[14327]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Oct 30 21:59:14 volumio volumio[14327]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 30 21:59:15 volumio volumio[14327]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Oct 30 21:59:15 volumio volumio[14327]: info: MyVolumio token set successfully Oct 30 21:59:15 volumio volumio[14327]: info: MYVOLUMIO: Adding device Oct 30 21:59:15 volumio volumio[14327]: info: MYVOLUMIO: Evaluating Server Oct 30 21:59:15 volumio volumio[14327]: info: MyVolumio status changed Oct 30 21:59:15 volumio volumio[14327]: info: Streaming services startup Oct 30 21:59:15 volumio volumio[14327]: info: Starting Streaming Daemon Oct 30 21:59:15 volumio volumio[14327]: info: Removing browser output: myVolumio user plan is not superstar Oct 30 21:59:15 volumio volumio[14327]: info: Removing audio output: Oct 30 21:59:15 volumio volumio[14327]: info: Stoppping Tunnel 1 Oct 30 21:59:15 volumio sudo[14644]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service Oct 30 21:59:15 volumio sudo[14644]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 30 21:59:15 volumio sudo[14642]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Oct 30 21:59:15 volumio sudo[14642]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 30 21:59:15 volumio sudo[14642]: pam_unix(sudo:session): session closed for user root Oct 30 21:59:15 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 30 21:59:15 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 30 21:59:15 volumio volumio[14327]: error: Cannot start Volumio Streaming Daemon Oct 30 21:59:15 volumio volumio[14327]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Oct 30 21:59:15 volumio volumio[14327]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Oct 30 21:59:15 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 30 21:59:15 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 30 21:59:15 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 30 21:59:15 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 30 21:59:15 volumio sudo[14644]: pam_unix(sudo:session): session closed for user root Oct 30 21:59:15 volumio volumio[14327]: info: Remote SSH Stopped Oct 30 21:59:16 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Oct 30 21:59:16 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 30 21:59:16 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 30 21:59:16 volumio go-librespot[14647]: go-librespot daemon starting... Oct 30 21:59:16 volumio go-librespot[14648]: time="2025-10-30T21:59:16Z" level=info msg="running go-librespot 0.4.0" Oct 30 21:59:16 volumio go-librespot[14648]: time="2025-10-30T21:59:16Z" level=debug msg="app state loaded" Oct 30 21:59:16 volumio go-librespot[14648]: time="2025-10-30T21:59:16Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 30 21:59:16 volumio volumio[14327]: info: Setting Geolocation for MyVolumio to eu3 Oct 30 21:59:16 volumio volumio[14327]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 30 21:59:16 volumio volumio[14327]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 30 21:59:16 volumio volumio[14327]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 30 21:59:16 volumio go-librespot[14648]: time="2025-10-30T21:59:16Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Oct 30 21:59:16 volumio go-librespot[14648]: time="2025-10-30T21:59:16Z" 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 30 21:59:16 volumio go-librespot[14648]: time="2025-10-30T21:59:16Z" 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 30 21:59:16 volumio go-librespot[14648]: time="2025-10-30T21:59:16Z" level=info msg="zeroconf server listening on port 46545" Oct 30 21:59:16 volumio go-librespot[14648]: time="2025-10-30T21:59:16Z" level=debug msg="obtained new client token: AADd0ay2LpLyzURxBOSQwAv81JKwWm9iX3FQdtc6KDENex2UfBia9EN2bma0F5Y7Kj0Clm4E+YMFZNjcRaayx3pVJV8zL8LJWiRbVqZUUtvQhL6YK296NXAeRUJAb9j0IhI15wK56Ds6Tqr7Cxlu4lM0aVYTGmjEZO+MtjgZFybOEZlxfYJBZqtZ8KYop8x6Jto8G9/Pj6hFt5h1EQJ9mY9p2MJBxU6CUHHDAlTbspbPXTTZPBN2" Oct 30 21:59:16 volumio go-librespot[14648]: time="2025-10-30T21:59:16Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 30 21:59:16 volumio go-librespot[14648]: time="2025-10-30T21:59:16Z" level=debug msg="completed keyexchange" Oct 30 21:59:16 volumio go-librespot[14648]: time="2025-10-30T21:59:16Z" level=debug msg="completed challenge" Oct 30 21:59:16 volumio go-librespot[14648]: time="2025-10-30T21:59:16Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 30 21:59:16 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 30 21:59:16 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 30 21:59:16 volumio volumio[14327]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Oct 30 21:59:17 volumio volumio[14327]: info: Updating MyVolumio device info Oct 30 21:59:17 volumio volumio[14327]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 30 21:59:17 volumio volumio[14327]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 30 21:59:17 volumio volumio[14327]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 30 21:59:17 volumio volumio[14327]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Oct 30 21:59:17 volumio volumio[14327]: info: Initializing connection to go-librespot Websocket Oct 30 21:59:17 volumio volumio[14327]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 30 21:59:18 volumio volumio[14327]: info: Cannot mount NAS NAS at system boot, trial number 4 ,retrying in 5 seconds Oct 30 21:59:19 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 4. Oct 30 21:59:19 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 30 21:59:19 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 30 21:59:19 volumio go-librespot[14656]: go-librespot daemon starting... Oct 30 21:59:19 volumio go-librespot[14657]: time="2025-10-30T21:59:19Z" level=info msg="running go-librespot 0.4.0" Oct 30 21:59:19 volumio go-librespot[14657]: time="2025-10-30T21:59:19Z" level=debug msg="app state loaded" Oct 30 21:59:19 volumio go-librespot[14657]: time="2025-10-30T21:59:19Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 30 21:59:19 volumio go-librespot[14657]: time="2025-10-30T21:59:19Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Oct 30 21:59:19 volumio go-librespot[14657]: time="2025-10-30T21:59:19Z" 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 30 21:59:19 volumio go-librespot[14657]: time="2025-10-30T21:59:19Z" 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 30 21:59:19 volumio go-librespot[14657]: time="2025-10-30T21:59:19Z" level=info msg="zeroconf server listening on port 44575" Oct 30 21:59:19 volumio go-librespot[14657]: time="2025-10-30T21:59:19Z" level=debug msg="obtained new client token: AACtyxjlQX02XFMIeAukgGhFAR4mtcqy+rXFw9pjWOFZAcAUgYhdNSakSfRE0R+OaaZr2bc/h5uuSIgM4DXHLPQKd7NG6xB8dyzGnWajk6iJvXdrDEy80PLiSMDlxcWtfhDVigo1d7abe/MdpW5uh/O1OLJFGWqfWRBQ+UXzqkgMpuHMUhZIKA2yy5aLdgNgIic8d3w+0AydGhB9ciZ3rFh8n59fvn4oiMOH5u4WpJKsR7gH2zTJTPA=" Oct 30 21:59:19 volumio go-librespot[14657]: time="2025-10-30T21:59:19Z" 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 30 21:59:19 volumio go-librespot[14657]: time="2025-10-30T21:59:19Z" level=debug msg="connected to ap-gew1.spotify.com:443" Oct 30 21:59:19 volumio go-librespot[14657]: time="2025-10-30T21:59:19Z" level=debug msg="completed keyexchange" Oct 30 21:59:19 volumio go-librespot[14657]: time="2025-10-30T21:59:19Z" level=debug msg="completed challenge" Oct 30 21:59:19 volumio go-librespot[14657]: time="2025-10-30T21:59:19Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 30 21:59:19 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 30 21:59:19 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 30 21:59:20 volumio volumio[14327]: info: MYVOLUMIO: Adding device Oct 30 21:59:20 volumio volumio[14327]: info: MYVOLUMIO: Evaluating Server Oct 30 21:59:20 volumio volumio[14327]: info: Initializing connection to go-librespot Websocket Oct 30 21:59:20 volumio volumio[14327]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 30 21:59:21 volumio volumio[14327]: info: Setting Geolocation for MyVolumio to eu3 Oct 30 21:59:21 volumio volumio[14327]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 30 21:59:21 volumio volumio[14327]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 30 21:59:21 volumio volumio[14327]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 30 21:59:21 volumio volumio[14327]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Oct 30 21:59:22 volumio volumio[14327]: info: Updating MyVolumio device info Oct 30 21:59:22 volumio volumio[14327]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 30 21:59:22 volumio volumio[14327]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 30 21:59:22 volumio volumio[14327]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 30 21:59:22 volumio volumio[14327]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Oct 30 21:59:23 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 5. Oct 30 21:59:23 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 30 21:59:23 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 30 21:59:23 volumio go-librespot[14679]: go-librespot daemon starting... Oct 30 21:59:23 volumio go-librespot[14680]: time="2025-10-30T21:59:23Z" level=info msg="running go-librespot 0.4.0" Oct 30 21:59:23 volumio go-librespot[14680]: time="2025-10-30T21:59:23Z" level=debug msg="app state loaded" Oct 30 21:59:23 volumio go-librespot[14680]: time="2025-10-30T21:59:23Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 30 21:59:23 volumio go-librespot[14680]: time="2025-10-30T21:59:23Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Oct 30 21:59:23 volumio go-librespot[14680]: time="2025-10-30T21:59:23Z" 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 30 21:59:23 volumio go-librespot[14680]: time="2025-10-30T21:59:23Z" 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 30 21:59:23 volumio go-librespot[14680]: time="2025-10-30T21:59:23Z" level=info msg="zeroconf server listening on port 43373" Oct 30 21:59:23 volumio go-librespot[14680]: time="2025-10-30T21:59:23Z" level=debug msg="obtained new client token: AADD1zjID9ZPUbuLAKnaBN8idunHJh4eylAkrJ5fq1b1uvLmXFqB0CtJuLqmF8+l99rBMmI4qXcfY6ElNmQwzDXchPKNsSh6DEAURlpDzj08fVIVO/0dHGWWSqHNiRPCpXbAKhAey9BOIBMRDAbDupbgqKTnKsSIkOAlNyNpsquNfeuYBBWWUuaQISemFFLs1PypKR3pE2T4rmzkdJd6X+MJoYNoPgHAgnUATCuZdJAK7EWhRVwZ" Oct 30 21:59:23 volumio go-librespot[14680]: time="2025-10-30T21:59:23Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 30 21:59:23 volumio go-librespot[14680]: time="2025-10-30T21:59:23Z" level=debug msg="completed keyexchange" Oct 30 21:59:23 volumio go-librespot[14680]: time="2025-10-30T21:59:23Z" level=debug msg="completed challenge" Oct 30 21:59:23 volumio go-librespot[14680]: time="2025-10-30T21:59:23Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 30 21:59:23 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 30 21:59:23 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 30 21:59:23 volumio volumio[14327]: info: Cannot mount NAS at system boot, trial number 4 ,stopping Oct 30 21:59:23 volumio volumio[14327]: info: Initializing connection to go-librespot Websocket Oct 30 21:59:23 volumio volumio[14327]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 30 21:59:26 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6. Oct 30 21:59:26 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 30 21:59:26 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 30 21:59:26 volumio go-librespot[14701]: go-librespot daemon starting... Oct 30 21:59:26 volumio go-librespot[14702]: time="2025-10-30T21:59:26Z" level=info msg="running go-librespot 0.4.0" Oct 30 21:59:26 volumio go-librespot[14702]: time="2025-10-30T21:59:26Z" level=debug msg="app state loaded" Oct 30 21:59:26 volumio go-librespot[14702]: time="2025-10-30T21:59:26Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 30 21:59:26 volumio go-librespot[14702]: time="2025-10-30T21:59:26Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Oct 30 21:59:26 volumio go-librespot[14702]: time="2025-10-30T21:59:26Z" 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 30 21:59:26 volumio go-librespot[14702]: time="2025-10-30T21:59:26Z" 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 30 21:59:26 volumio go-librespot[14702]: time="2025-10-30T21:59:26Z" level=info msg="zeroconf server listening on port 40559" Oct 30 21:59:26 volumio go-librespot[14702]: time="2025-10-30T21:59:26Z" level=debug msg="obtained new client token: AADudDF8rOStpX3v+VgBOn0GDFqe+zZbbIpKb/N7C/1dioA29IdCP6coyZAgjLTtqMPbY7HrqZBFdW7wKld+YDVaeIA+0A0M+VUmzQIJfkqD7aaGNJcu8Vzt1D5Q0SkPO4e7Kpi6uY8ZIE31EFS709JmDZbrpbpaGfcau5z/QvBA8svwgBTuNMR9J4HcfCt9wCf1lsGO0qrk5g6CcGdK5n7KWgVrIwxDuBX/HQZy/AN409LXjobxPDU=" Oct 30 21:59:26 volumio go-librespot[14702]: time="2025-10-30T21:59:26Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 30 21:59:26 volumio go-librespot[14702]: time="2025-10-30T21:59:26Z" level=debug msg="completed keyexchange" Oct 30 21:59:26 volumio go-librespot[14702]: time="2025-10-30T21:59:26Z" level=debug msg="completed challenge" Oct 30 21:59:26 volumio go-librespot[14702]: time="2025-10-30T21:59:26Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 30 21:59:26 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 30 21:59:26 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 30 21:59:26 volumio volumio[14327]: info: Initializing connection to go-librespot Websocket Oct 30 21:59:26 volumio volumio[14327]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 30 21:59:29 volumio volumio[14327]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Oct 30 21:59:29 volumio volumio[14327]: 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 30 21:59:29 volumio volumio[14327]: info: CoreCommandRouter::volumioGetState Oct 30 21:59:29 volumio volumio[14327]: info: CorePlayQueue::getTrack 0 Oct 30 21:59:29 volumio volumio[14327]: info: Initializing connection to go-librespot Websocket Oct 30 21:59:29 volumio volumio[14327]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 30 21:59:30 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 7. Oct 30 21:59:30 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 30 21:59:30 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 30 21:59:30 volumio go-librespot[14712]: go-librespot daemon starting... Oct 30 21:59:30 volumio go-librespot[14713]: time="2025-10-30T21:59:30Z" level=info msg="running go-librespot 0.4.0" Oct 30 21:59:30 volumio go-librespot[14713]: time="2025-10-30T21:59:30Z" level=debug msg="app state loaded" Oct 30 21:59:30 volumio go-librespot[14713]: time="2025-10-30T21:59:30Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 30 21:59:30 volumio go-librespot[14713]: time="2025-10-30T21:59:30Z" 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 30 21:59:30 volumio go-librespot[14713]: time="2025-10-30T21:59:30Z" 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 30 21:59:30 volumio go-librespot[14713]: time="2025-10-30T21:59:30Z" 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 30 21:59:30 volumio go-librespot[14713]: time="2025-10-30T21:59:30Z" level=info msg="zeroconf server listening on port 37689" Oct 30 21:59:30 volumio go-librespot[14713]: time="2025-10-30T21:59:30Z" level=debug msg="obtained new client token: AAByNEZrdM5n3IKqdQ6VlAtYTwGFpjGcxLcH45QscEI6N93GQEcFnS4JzqSYNs3UOBeiCrV16Fr/qErkfSm7WreOGhGxp8d1GfgqA2D2M6ATAAWioPWwPr4u7vBvqFBHk/0L26Md5EfOObUUAJCopgu0DQBxAMHXQorHgeY14aPBj70IKlydz0LVoT2yQ09Yas4DRN/8eucJbRBvTt5UhYqFFUo5uXzrR9UFmou01Sovwjpsn6+j" Oct 30 21:59:30 volumio go-librespot[14713]: time="2025-10-30T21:59:30Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 30 21:59:30 volumio go-librespot[14713]: time="2025-10-30T21:59:30Z" level=debug msg="completed keyexchange" Oct 30 21:59:30 volumio go-librespot[14713]: time="2025-10-30T21:59:30Z" level=debug msg="completed challenge" Oct 30 21:59:30 volumio go-librespot[14713]: time="2025-10-30T21:59:30Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 30 21:59:30 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 30 21:59:30 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 30 21:59:32 volumio volumio[14327]: info: Initializing connection to go-librespot Websocket Oct 30 21:59:32 volumio volumio[14327]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 30 21:59:33 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 8. Oct 30 21:59:33 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 30 21:59:33 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 30 21:59:33 volumio go-librespot[14734]: go-librespot daemon starting... Oct 30 21:59:33 volumio go-librespot[14735]: time="2025-10-30T21:59:33Z" level=info msg="running go-librespot 0.4.0" Oct 30 21:59:33 volumio go-librespot[14735]: time="2025-10-30T21:59:33Z" level=debug msg="app state loaded" Oct 30 21:59:33 volumio go-librespot[14735]: time="2025-10-30T21:59:33Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 30 21:59:33 volumio go-librespot[14735]: time="2025-10-30T21:59:33Z" 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 30 21:59:33 volumio go-librespot[14735]: time="2025-10-30T21:59:33Z" 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 30 21:59:33 volumio go-librespot[14735]: time="2025-10-30T21:59:33Z" 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 30 21:59:33 volumio go-librespot[14735]: time="2025-10-30T21:59:33Z" level=info msg="zeroconf server listening on port 42313" Oct 30 21:59:33 volumio go-librespot[14735]: time="2025-10-30T21:59:33Z" level=debug msg="obtained new client token: AADR1caMOEiRx6ETZH+wch9EQ9UCiHKZsX2TnG5IpOhTwQAF1ZnU0/DY1fGv2vEFlBU7p6+UP3UByfFhkF06z6aMPX8HQopil6dMj/gkNsi3rqElfBDhljhG4mpHyoFUhuu8TbaG9TTPyuTfIZJ4UBL0YDVP9PjoVwy6MPR/lOqZuWAG9ZzsjW/CufcgiUuDEnxm79ES0LZ0GFGyE3x7Q9m8UMnPCXH7i8aKfuTqG2WOlvCEITA7Y6A=" Oct 30 21:59:33 volumio go-librespot[14735]: time="2025-10-30T21:59:33Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 30 21:59:33 volumio go-librespot[14735]: time="2025-10-30T21:59:33Z" level=debug msg="completed keyexchange" Oct 30 21:59:33 volumio go-librespot[14735]: time="2025-10-30T21:59:33Z" level=debug msg="completed challenge" Oct 30 21:59:33 volumio go-librespot[14735]: time="2025-10-30T21:59:33Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 30 21:59:33 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 30 21:59:33 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 30 21:59:34 volumio volumio[14327]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 21:59:34 volumio volumio[14327]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 21:59:34 volumio volumio[14327]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam Oct 30 21:59:34 volumio volumio[14327]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Oct 30 21:59:34 volumio volumio[14327]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Oct 30 21:59:34 volumio volumio[14327]: info: CoreCommandRouter::volumioGetBrowseSources Oct 30 21:59:34 volumio volumio[14327]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 30 21:59:34 volumio volumio[14327]: error: MyVolumio Plugin failed to authenticate in a timely fashion Oct 30 21:59:34 volumio volumio[14327]: info: Completed starting MyVolumio Plugin Oct 30 21:59:34 volumio volumio[14327]: [Metrics] CommandRouter: 31s 906.98ms Oct 30 21:59:34 volumio volumio[14327]: info: CoreCommandRouter::volumiosetStartupVolume Oct 30 21:59:34 volumio volumio[14327]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 21:59:34 volumio volumio[14327]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 30 21:59:34 volumio volumio[14327]: info: CoreCommandRouter::Close All Modals sent Oct 30 21:59:34 volumio volumio[14327]: info: CoreCommandRouter::Close All Modals sent Oct 30 21:59:35 volumio volumio[14327]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 30 21:59:35 volumio volumio[14327]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 30 21:59:35 volumio volumio[14327]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Oct 30 21:59:35 volumio volumio-remote-updater[874]: Test mode disabled Oct 30 21:59:35 volumio volumio-remote-updater[874]: Alpha mode disabled Oct 30 21:59:35 volumio volumio-remote-updater[874]: Alpha legacy test mode disabled Oct 30 21:59:35 volumio volumio[14327]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateEnabled Oct 30 21:59:35 volumio volumio[14327]: info: Update Ready: {"changeLogLink":"","description":"You're already on the latest version","title":"No Updates Available","updateavailable":false} Oct 30 21:59:35 volumio volumio[14327]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache Oct 30 21:59:35 volumio volumio[14327]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable Oct 30 21:59:35 volumio volumio[14327]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Oct 30 21:59:35 volumio volumio[14327]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect Oct 30 21:59:35 volumio volumio[14327]: info: Initializing connection to go-librespot Websocket Oct 30 21:59:35 volumio volumio[14327]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 30 21:59:37 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 9. Oct 30 21:59:37 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 30 21:59:37 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 30 21:59:37 volumio go-librespot[14751]: go-librespot daemon starting... Oct 30 21:59:37 volumio go-librespot[14752]: time="2025-10-30T21:59:37Z" level=info msg="running go-librespot 0.4.0" Oct 30 21:59:37 volumio go-librespot[14752]: time="2025-10-30T21:59:37Z" level=debug msg="app state loaded" Oct 30 21:59:37 volumio go-librespot[14752]: time="2025-10-30T21:59:37Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 30 21:59:37 volumio go-librespot[14752]: time="2025-10-30T21:59:37Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Oct 30 21:59:37 volumio go-librespot[14752]: time="2025-10-30T21:59:37Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 30 21:59:37 volumio go-librespot[14752]: time="2025-10-30T21:59:37Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 30 21:59:37 volumio go-librespot[14752]: time="2025-10-30T21:59:37Z" level=info msg="zeroconf server listening on port 43663" Oct 30 21:59:37 volumio go-librespot[14752]: time="2025-10-30T21:59:37Z" level=debug msg="obtained new client token: AADrOED6awNY/WP0bm8eCyItwMQ5lIHadNf8Lmtzx5Fj4HJTi5I/TZMt++IQxaon76BknMQCGCq7ThuQ3FMffqwDcQ+VBn5Si0B48BKVvmTIecCvqfgCWqrjXGKfkrA1woRuwdkku/B2IrFgpM4cQhHO1+gb4p96+lJYlxIINMB52KIq+O0X6uqDkd+V2xEYAwKdG23aE+yq0jrt/TqqDYu1IcDZCAEXqbVgGRfByPr4zTVgWrNO" Oct 30 21:59:37 volumio go-librespot[14752]: time="2025-10-30T21:59:37Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 30 21:59:37 volumio go-librespot[14752]: time="2025-10-30T21:59:37Z" level=debug msg="completed keyexchange" Oct 30 21:59:37 volumio go-librespot[14752]: time="2025-10-30T21:59:37Z" level=debug msg="completed challenge" Oct 30 21:59:37 volumio go-librespot[14752]: time="2025-10-30T21:59:37Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 30 21:59:37 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 30 21:59:37 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 30 21:59:38 volumio volumio[14327]: info: Initializing connection to go-librespot Websocket Oct 30 21:59:38 volumio volumio[14327]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 30 21:59:40 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 10. Oct 30 21:59:40 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 30 21:59:40 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 30 21:59:40 volumio go-librespot[14760]: go-librespot daemon starting... Oct 30 21:59:40 volumio go-librespot[14761]: time="2025-10-30T21:59:40Z" level=info msg="running go-librespot 0.4.0" Oct 30 21:59:40 volumio go-librespot[14761]: time="2025-10-30T21:59:40Z" level=debug msg="app state loaded" Oct 30 21:59:40 volumio go-librespot[14761]: time="2025-10-30T21:59:40Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 30 21:59:40 volumio go-librespot[14761]: time="2025-10-30T21:59:40Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Oct 30 21:59:40 volumio go-librespot[14761]: time="2025-10-30T21:59:40Z" 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 30 21:59:40 volumio go-librespot[14761]: time="2025-10-30T21:59:40Z" 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 30 21:59:40 volumio go-librespot[14761]: time="2025-10-30T21:59:40Z" level=info msg="zeroconf server listening on port 37137" Oct 30 21:59:40 volumio go-librespot[14761]: time="2025-10-30T21:59:40Z" level=debug msg="obtained new client token: AADbbOzVIiJcYRfIRFP2bF5PqMJNuoGukKD4lVfMA0Rv6I3Ea0K2u+c6URIJ67LAF+ZUckBC858JLhiuzgVBEoOz51+gT4YhceLaQLtxbACNAui7TaasKr/A8VSdi5d8KiEIAcQdzQVenb2I1jcFSloSsfzKQN1kUWXfmfKRYDa5YGSBNHeFxaBFkeBcdKCrzaaoGH2V+4X9hnZoZA5fzTbzwMLFs0PamR2mKNGN6C+5HTHweomSabA=" Oct 30 21:59:40 volumio go-librespot[14761]: time="2025-10-30T21:59:40Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 30 21:59:40 volumio go-librespot[14761]: time="2025-10-30T21:59:40Z" level=debug msg="completed keyexchange" Oct 30 21:59:40 volumio go-librespot[14761]: time="2025-10-30T21:59:40Z" level=debug msg="completed challenge" Oct 30 21:59:40 volumio go-librespot[14761]: time="2025-10-30T21:59:40Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 30 21:59:40 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 30 21:59:40 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 30 21:59:41 volumio volumio[14327]: info: BOOT COMPLETED Oct 30 21:59:41 volumio volumio[14327]: info: Initializing connection to go-librespot Websocket Oct 30 21:59:41 volumio volumio[14327]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 30 21:59:44 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 11. Oct 30 21:59:44 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 30 21:59:44 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 30 21:59:44 volumio go-librespot[14782]: go-librespot daemon starting... Oct 30 21:59:44 volumio go-librespot[14783]: time="2025-10-30T21:59:44Z" level=info msg="running go-librespot 0.4.0" Oct 30 21:59:44 volumio go-librespot[14783]: time="2025-10-30T21:59:44Z" level=debug msg="app state loaded" Oct 30 21:59:44 volumio go-librespot[14783]: time="2025-10-30T21:59:44Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 30 21:59:44 volumio go-librespot[14783]: time="2025-10-30T21:59:44Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Oct 30 21:59:44 volumio go-librespot[14783]: time="2025-10-30T21:59:44Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 30 21:59:44 volumio go-librespot[14783]: time="2025-10-30T21:59:44Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 30 21:59:44 volumio go-librespot[14783]: time="2025-10-30T21:59:44Z" level=info msg="zeroconf server listening on port 37183" Oct 30 21:59:44 volumio go-librespot[14783]: time="2025-10-30T21:59:44Z" level=debug msg="obtained new client token: AAD/swUcck8zWq3ZAEkSMZhp18lFgVaro1vo9ShwXjJoewdER8KX8YQ1/2Ex3w4/L7w7+aQQa+lZ58YSBvaXcMJJXDp4rXtMvTeDh9kb4Va6eioIMa6MfRFqP0epuddFg7uDwPYhPlBa0fZg0WuXteOG/yA1OUxv4xCd30sh20PoQinT1heGw8LqfjP+Zl6Du+TU0fCNUeIJ1UkkclPPKxDAONRwNwqPwVmtI/gZIkQ82vRySg+W" Oct 30 21:59:44 volumio go-librespot[14783]: time="2025-10-30T21:59:44Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 30 21:59:44 volumio go-librespot[14783]: time="2025-10-30T21:59:44Z" level=debug msg="completed keyexchange" Oct 30 21:59:44 volumio go-librespot[14783]: time="2025-10-30T21:59:44Z" level=debug msg="completed challenge" Oct 30 21:59:44 volumio go-librespot[14783]: time="2025-10-30T21:59:44Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 30 21:59:44 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 30 21:59:44 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 30 21:59:44 volumio volumio[14327]: info: Initializing connection to go-librespot Websocket Oct 30 21:59:44 volumio volumio[14327]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 30 21:59:47 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 12. Oct 30 21:59:47 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 30 21:59:47 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 30 21:59:47 volumio go-librespot[14790]: go-librespot daemon starting... Oct 30 21:59:47 volumio go-librespot[14791]: time="2025-10-30T21:59:47Z" level=info msg="running go-librespot 0.4.0" Oct 30 21:59:47 volumio go-librespot[14791]: time="2025-10-30T21:59:47Z" level=debug msg="app state loaded" Oct 30 21:59:47 volumio go-librespot[14791]: time="2025-10-30T21:59:47Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 30 21:59:47 volumio go-librespot[14791]: time="2025-10-30T21:59:47Z" 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 30 21:59:47 volumio go-librespot[14791]: time="2025-10-30T21:59:47Z" 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 30 21:59:47 volumio go-librespot[14791]: time="2025-10-30T21:59:47Z" 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 30 21:59:47 volumio go-librespot[14791]: time="2025-10-30T21:59:47Z" level=info msg="zeroconf server listening on port 36835" Oct 30 21:59:47 volumio go-librespot[14791]: time="2025-10-30T21:59:47Z" level=debug msg="obtained new client token: AACT7GUOchDvIyzrl1dCPm2tdJfYhYT4QV9w0ckolTJJtSBb7MmTkH/ypQBzQrYDZw3y6C00EmBx7IPa1OABHZFsKBj8qnRY7nmf53WujE7uJBoXb2j6pFXVI7fplEEsqA8CSJvF5GMYOHyJT0eMuaplRB+h2NFAdVYgF2rjUvexLJioiUg32HG2AlBLhEaFuLpN+Gais7OQY2nIeMzM6tIui77x6zrsxJZQruB1PXHuCdjWxpL1jdc=" Oct 30 21:59:47 volumio go-librespot[14791]: time="2025-10-30T21:59:47Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 30 21:59:47 volumio go-librespot[14791]: time="2025-10-30T21:59:47Z" level=debug msg="completed keyexchange" Oct 30 21:59:47 volumio go-librespot[14791]: time="2025-10-30T21:59:47Z" level=debug msg="completed challenge" Oct 30 21:59:47 volumio go-librespot[14791]: time="2025-10-30T21:59:47Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 30 21:59:47 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 30 21:59:47 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 30 21:59:47 volumio volumio[14327]: info: Initializing connection to go-librespot Websocket Oct 30 21:59:47 volumio volumio[14327]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 30 21:59:50 volumio volumio[14327]: info: Initializing connection to go-librespot Websocket Oct 30 21:59:50 volumio volumio[14327]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 30 21:59:51 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 13. Oct 30 21:59:51 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 30 21:59:51 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 30 21:59:51 volumio go-librespot[14801]: go-librespot daemon starting... Oct 30 21:59:51 volumio go-librespot[14802]: time="2025-10-30T21:59:51Z" level=info msg="running go-librespot 0.4.0" Oct 30 21:59:51 volumio go-librespot[14802]: time="2025-10-30T21:59:51Z" level=debug msg="app state loaded" Oct 30 21:59:51 volumio go-librespot[14802]: time="2025-10-30T21:59:51Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 30 21:59:51 volumio go-librespot[14802]: time="2025-10-30T21:59:51Z" 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 30 21:59:51 volumio go-librespot[14802]: time="2025-10-30T21:59:51Z" 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 30 21:59:51 volumio go-librespot[14802]: time="2025-10-30T21:59:51Z" 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 30 21:59:51 volumio go-librespot[14802]: time="2025-10-30T21:59:51Z" level=info msg="zeroconf server listening on port 44609" Oct 30 21:59:51 volumio go-librespot[14802]: time="2025-10-30T21:59:51Z" level=debug msg="obtained new client token: AADTPqSPdBny3sBjwQR5ughvzhIl5o+NzxrAIlKYDy/9hgj2eQW4yEuFNJw8y/YMzJYwXMdUKRxuMJShOkBDCUrOQL3T3O19KTg0lvXQPQOakXe/x+zrm4YAWwn8LrVopF5H5hXRsvIGnXuaAhk88XbbeXQIu+affgM3siBRbFazZ2BDoo+wVYNQNe3vncfhwcvzIIRan8NrWxz5JTI9RJvvpEuxEeYS/8fHVU5PodvL6gJ0Dmvz" Oct 30 21:59:51 volumio go-librespot[14802]: time="2025-10-30T21:59:51Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 30 21:59:51 volumio go-librespot[14802]: time="2025-10-30T21:59:51Z" level=debug msg="completed keyexchange" Oct 30 21:59:51 volumio go-librespot[14802]: time="2025-10-30T21:59:51Z" level=debug msg="completed challenge" Oct 30 21:59:51 volumio go-librespot[14802]: time="2025-10-30T21:59:51Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 30 21:59:51 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 30 21:59:51 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 30 21:59:53 volumio volumio[14327]: info: Initializing connection to go-librespot Websocket Oct 30 21:59:53 volumio volumio[14327]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 30 21:59:54 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 14. Oct 30 21:59:54 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 30 21:59:54 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 30 21:59:54 volumio go-librespot[14823]: go-librespot daemon starting... Oct 30 21:59:54 volumio go-librespot[14824]: time="2025-10-30T21:59:54Z" level=info msg="running go-librespot 0.4.0" Oct 30 21:59:54 volumio go-librespot[14824]: time="2025-10-30T21:59:54Z" level=debug msg="app state loaded" Oct 30 21:59:54 volumio go-librespot[14824]: time="2025-10-30T21:59:54Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 30 21:59:54 volumio go-librespot[14824]: time="2025-10-30T21:59:54Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Oct 30 21:59:54 volumio go-librespot[14824]: time="2025-10-30T21:59:54Z" 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 30 21:59:54 volumio go-librespot[14824]: time="2025-10-30T21:59:54Z" 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 30 21:59:54 volumio go-librespot[14824]: time="2025-10-30T21:59:54Z" level=info msg="zeroconf server listening on port 45701" Oct 30 21:59:54 volumio go-librespot[14824]: time="2025-10-30T21:59:54Z" level=debug msg="obtained new client token: AABjkcLYhYxKGt8EUPwESDe81gMqOBoFDHHTGQBOhFxiRDH5Bu8/QWXjP/ky/zxfmL4t3qSZfUQ1bUGwcZmvOQqvGWgAsosxd9tq6+f0RQynA++eTocVSC9VNowpq7+PNZ+BWkSlbFJJ/pgVS6j1g4bDDjc6Ibcc2aFoUvXdtbP0jw/9wkEhC8CDrTAJfRdJS8tag+eAutzjQZ8FTbhupfAsdV0/QrYfi+XyGrwfOWFIfs9awEYCz3k=" Oct 30 21:59:54 volumio go-librespot[14824]: time="2025-10-30T21:59:54Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 30 21:59:54 volumio go-librespot[14824]: time="2025-10-30T21:59:54Z" level=debug msg="completed keyexchange" Oct 30 21:59:54 volumio go-librespot[14824]: time="2025-10-30T21:59:54Z" level=debug msg="completed challenge" Oct 30 21:59:54 volumio go-librespot[14824]: time="2025-10-30T21:59:54Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 30 21:59:54 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 30 21:59:54 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 30 21:59:56 volumio volumio[14327]: info: Initializing connection to go-librespot Websocket Oct 30 21:59:56 volumio volumio[14327]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 30 21:59:58 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 15. Oct 30 21:59:58 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 30 21:59:58 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 30 21:59:58 volumio go-librespot[14831]: go-librespot daemon starting... Oct 30 21:59:58 volumio go-librespot[14832]: time="2025-10-30T21:59:58Z" level=info msg="running go-librespot 0.4.0" Oct 30 21:59:58 volumio go-librespot[14832]: time="2025-10-30T21:59:58Z" level=debug msg="app state loaded" Oct 30 21:59:58 volumio go-librespot[14832]: time="2025-10-30T21:59:58Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 30 21:59:58 volumio go-librespot[14832]: time="2025-10-30T21:59:58Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Oct 30 21:59:58 volumio go-librespot[14832]: time="2025-10-30T21:59:58Z" 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 30 21:59:58 volumio go-librespot[14832]: time="2025-10-30T21:59:58Z" 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 30 21:59:58 volumio go-librespot[14832]: time="2025-10-30T21:59:58Z" level=info msg="zeroconf server listening on port 40707" Oct 30 21:59:58 volumio go-librespot[14832]: time="2025-10-30T21:59:58Z" level=debug msg="obtained new client token: AABECB+4NdkTKHggpXNdxofoaQams5tngYioFtVKSzwlF3nnhmVOhfLNyqZpCsItQWjohJ28oz5vLhD2TPU1EOMcxmW+720hQKDZJQf0vBrb+j1j5pcwsK+V7N8qhOBHga7AWcTpb3KJ0OaYlv0d31GGVwthN0c2PHFdYL7pUHnljJzddEFPjfBPlFpzMgt5Expt7s8wk7mFoF3R68T8dLcFWhCoSScs8IT4X3CTNNHgsD2IT/Sz" Oct 30 21:59:58 volumio go-librespot[14832]: time="2025-10-30T21:59:58Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 30 21:59:58 volumio go-librespot[14832]: time="2025-10-30T21:59:58Z" level=debug msg="completed keyexchange" Oct 30 21:59:58 volumio go-librespot[14832]: time="2025-10-30T21:59:58Z" level=debug msg="completed challenge" Oct 30 21:59:58 volumio go-librespot[14832]: time="2025-10-30T21:59:58Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 30 21:59:58 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 30 21:59:58 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 30 21:59:59 volumio volumio[14327]: info: Initializing connection to go-librespot Websocket Oct 30 21:59:59 volumio volumio[14327]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 30 22:00:01 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 16. Oct 30 22:00:01 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 30 22:00:01 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 30 22:00:01 volumio go-librespot[14840]: go-librespot daemon starting... Oct 30 22:00:01 volumio go-librespot[14841]: time="2025-10-30T22:00:01Z" level=info msg="running go-librespot 0.4.0" Oct 30 22:00:01 volumio go-librespot[14841]: time="2025-10-30T22:00:01Z" level=debug msg="app state loaded" Oct 30 22:00:01 volumio go-librespot[14841]: time="2025-10-30T22:00:01Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 30 22:00:01 volumio go-librespot[14841]: time="2025-10-30T22:00:01Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Oct 30 22:00:01 volumio go-librespot[14841]: time="2025-10-30T22:00:01Z" 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 30 22:00:01 volumio go-librespot[14841]: time="2025-10-30T22:00:01Z" 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 30 22:00:01 volumio go-librespot[14841]: time="2025-10-30T22:00:01Z" level=info msg="zeroconf server listening on port 46213" Oct 30 22:00:01 volumio go-librespot[14841]: time="2025-10-30T22:00:01Z" level=debug msg="obtained new client token: AAA9+k8Cs4WbtQFQtVgmtH16XgTEzBwxWAHmjGBLKOqpM28Me1jGhY5+2AqKEYd/3g16pwPuslzVMstLH8K+96jNCcqA17KZO2aradtLHHBMjeF1UiuV5hyZljqh042XONk5ppXCMJdRm2QmJs4jaGqU+J49brOwzXiIKF2jwuSsK0IDPB4yAy1lzz9ZaZkSbXtQb8qQTpTGhHfk+jL4EjNU68C0RZY7LYpcUtHFMFnb6vhtAVZliao=" Oct 30 22:00:01 volumio go-librespot[14841]: time="2025-10-30T22:00:01Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 30 22:00:01 volumio go-librespot[14841]: time="2025-10-30T22:00:01Z" level=debug msg="completed keyexchange" Oct 30 22:00:01 volumio go-librespot[14841]: time="2025-10-30T22:00:01Z" level=debug msg="completed challenge" Oct 30 22:00:01 volumio go-librespot[14841]: time="2025-10-30T22:00:01Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 30 22:00:01 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 30 22:00:01 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 30 22:00:02 volumio volumio[14327]: info: Initializing connection to go-librespot Websocket Oct 30 22:00:02 volumio volumio[14327]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 30 22:00:05 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 17. Oct 30 22:00:05 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 30 22:00:05 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 30 22:00:05 volumio go-librespot[14862]: go-librespot daemon starting... Oct 30 22:00:05 volumio go-librespot[14863]: time="2025-10-30T22:00:05Z" level=info msg="running go-librespot 0.4.0" Oct 30 22:00:05 volumio go-librespot[14863]: time="2025-10-30T22:00:05Z" level=debug msg="app state loaded" Oct 30 22:00:05 volumio go-librespot[14863]: time="2025-10-30T22:00:05Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 30 22:00:05 volumio go-librespot[14863]: time="2025-10-30T22:00:05Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Oct 30 22:00:05 volumio go-librespot[14863]: time="2025-10-30T22:00:05Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 30 22:00:05 volumio go-librespot[14863]: time="2025-10-30T22:00:05Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 30 22:00:05 volumio go-librespot[14863]: time="2025-10-30T22:00:05Z" level=info msg="zeroconf server listening on port 40247" Oct 30 22:00:05 volumio go-librespot[14863]: time="2025-10-30T22:00:05Z" level=debug msg="obtained new client token: AABfaG/VYV68MflyGdacXtI5jmEHxT3mmoVBJ/Vk5llQZ5eL7iqz8U3WVOgFbL5uSmsWhx15PjYidePY3cOR7gOxsWBeXzsaThkk/yf87Ft9FICUhRu0+4qoSDzQfa+P5ExsoRa/nHCV1Ak2dwHukBtANmOnc4xJwm5UH8GaZ+UmSHlJ4WiStUO9SwfRFYY9xNVBcVuRisvui0EcNg1Jkq1Hyx2v2BCCdyWXoF7A3cNhDGE5/QCB" Oct 30 22:00:05 volumio go-librespot[14863]: time="2025-10-30T22:00:05Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 30 22:00:05 volumio go-librespot[14863]: time="2025-10-30T22:00:05Z" level=debug msg="completed keyexchange" Oct 30 22:00:05 volumio go-librespot[14863]: time="2025-10-30T22:00:05Z" level=debug msg="completed challenge" Oct 30 22:00:05 volumio go-librespot[14863]: time="2025-10-30T22:00:05Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 30 22:00:05 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 30 22:00:05 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 30 22:00:05 volumio volumio[14327]: info: Initializing connection to go-librespot Websocket Oct 30 22:00:05 volumio volumio[14327]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 30 22:00:08 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 18. Oct 30 22:00:08 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 30 22:00:08 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 30 22:00:08 volumio go-librespot[14870]: go-librespot daemon starting... Oct 30 22:00:08 volumio go-librespot[14871]: time="2025-10-30T22:00:08Z" level=info msg="running go-librespot 0.4.0" Oct 30 22:00:08 volumio go-librespot[14871]: time="2025-10-30T22:00:08Z" level=debug msg="app state loaded" Oct 30 22:00:08 volumio go-librespot[14871]: time="2025-10-30T22:00:08Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 30 22:00:08 volumio go-librespot[14871]: time="2025-10-30T22:00:08Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Oct 30 22:00:08 volumio go-librespot[14871]: time="2025-10-30T22:00:08Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Oct 30 22:00:08 volumio go-librespot[14871]: time="2025-10-30T22:00:08Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Oct 30 22:00:08 volumio go-librespot[14871]: time="2025-10-30T22:00:08Z" level=info msg="zeroconf server listening on port 35049" Oct 30 22:00:08 volumio go-librespot[14871]: time="2025-10-30T22:00:08Z" level=debug msg="obtained new client token: AAAAV2IIRvX0oO8SMuR81PKTF23rV/R1vjE2lDYM7dI2nSiQoxA0ZmLNPqihh07KK9mcH4G8N6PYH/At/dN7O0/mASBFgW7NkAoH6/XHmeuIJ89m35XXlZ2ocygeDEbSBEk5UMVZ5SOLQbHz+UFycKqwPVDzyhxo5SMVonG/0fria/vdgxjPRDy6/XyflgrUFteZYA+By8oPXqIDf+mmoN1tGwhXpdYCD3t9V40/rFlm7LWojF9PrWE=" Oct 30 22:00:08 volumio go-librespot[14871]: time="2025-10-30T22:00:08Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 30 22:00:08 volumio go-librespot[14871]: time="2025-10-30T22:00:08Z" level=debug msg="completed keyexchange" Oct 30 22:00:08 volumio go-librespot[14871]: time="2025-10-30T22:00:08Z" level=debug msg="completed challenge" Oct 30 22:00:08 volumio go-librespot[14871]: time="2025-10-30T22:00:08Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 30 22:00:08 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 30 22:00:08 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 30 22:00:08 volumio volumio[14327]: info: Initializing connection to go-librespot Websocket Oct 30 22:00:08 volumio volumio[14327]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 30 22:00:11 volumio volumio[14327]: info: Initializing connection to go-librespot Websocket Oct 30 22:00:11 volumio volumio[14327]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 30 22:00:12 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 19. Oct 30 22:00:12 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 30 22:00:12 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 30 22:00:12 volumio go-librespot[14881]: go-librespot daemon starting... Oct 30 22:00:12 volumio go-librespot[14882]: time="2025-10-30T22:00:12Z" level=info msg="running go-librespot 0.4.0" Oct 30 22:00:12 volumio go-librespot[14882]: time="2025-10-30T22:00:12Z" level=debug msg="app state loaded" Oct 30 22:00:12 volumio go-librespot[14882]: time="2025-10-30T22:00:12Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 30 22:00:12 volumio go-librespot[14882]: time="2025-10-30T22:00:12Z" 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 30 22:00:12 volumio go-librespot[14882]: time="2025-10-30T22:00:12Z" 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 30 22:00:12 volumio go-librespot[14882]: time="2025-10-30T22:00:12Z" 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 30 22:00:12 volumio go-librespot[14882]: time="2025-10-30T22:00:12Z" level=info msg="zeroconf server listening on port 44149" Oct 30 22:00:12 volumio go-librespot[14882]: time="2025-10-30T22:00:12Z" level=debug msg="obtained new client token: AAB2amsrAQNE6tqKiuNobYwEx9sF4U3cpdJ1EB81/0uY/phlJMjSwpnZO6ZcIU0vnTcm14/E4MDP4x7xzOZQSENYwmyr3ycGqzp42PIbuZ+hqTWdnv90zU/ibafSNq2r/TFCCGGG4CDNZzTUwktHk/DKNzZhHAKMBmtOwUEfJv776J2nGYxG97b55INrM6mECcqaEt5ZeVKCx1JNYB6i4JmIq2z4C1jMwCurjUAXpOF67Py5OBQg" Oct 30 22:00:12 volumio go-librespot[14882]: time="2025-10-30T22:00:12Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 30 22:00:12 volumio go-librespot[14882]: time="2025-10-30T22:00:12Z" level=debug msg="completed keyexchange" Oct 30 22:00:12 volumio go-librespot[14882]: time="2025-10-30T22:00:12Z" level=debug msg="completed challenge" Oct 30 22:00:12 volumio go-librespot[14882]: time="2025-10-30T22:00:12Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 30 22:00:12 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 30 22:00:12 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 30 22:00:14 volumio volumio[14327]: info: Initializing connection to go-librespot Websocket Oct 30 22:00:14 volumio volumio[14327]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 30 22:00:15 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 20. Oct 30 22:00:15 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 30 22:00:15 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 30 22:00:15 volumio go-librespot[14905]: go-librespot daemon starting... Oct 30 22:00:15 volumio go-librespot[14906]: time="2025-10-30T22:00:15Z" level=info msg="running go-librespot 0.4.0" Oct 30 22:00:15 volumio go-librespot[14906]: time="2025-10-30T22:00:15Z" level=debug msg="app state loaded" Oct 30 22:00:15 volumio go-librespot[14906]: time="2025-10-30T22:00:15Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 30 22:00:15 volumio go-librespot[14906]: time="2025-10-30T22:00:15Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Oct 30 22:00:15 volumio go-librespot[14906]: time="2025-10-30T22:00:15Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Oct 30 22:00:15 volumio go-librespot[14906]: time="2025-10-30T22:00:15Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Oct 30 22:00:15 volumio go-librespot[14906]: time="2025-10-30T22:00:15Z" level=info msg="zeroconf server listening on port 43159" Oct 30 22:00:15 volumio go-librespot[14906]: time="2025-10-30T22:00:15Z" level=debug msg="obtained new client token: AABZxSlLq/Y4iag3ewqWdZFDiTp2rFBrIpSvV+jTEQ6p/ZVxYKBjGvAcrpCusEePNnHzBBc91LUE3qt+AhUMM2tIR77XJPue/B8Oyhip2WnN1WHY7tpvf7f6/Vmf5cuhZQ0N26ULc8usJvZiQuQifYVIHCHFxSz6oKX2t7bUb8iRr+/JdpyOFLOw4EUxtBFMOuJMSZi3wLqbQOFndlxy7JUiwWy5/pARFH4xzrKnaZRjuKpYVTBSWY0=" Oct 30 22:00:15 volumio go-librespot[14906]: time="2025-10-30T22:00:15Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 30 22:00:15 volumio go-librespot[14906]: time="2025-10-30T22:00:15Z" level=debug msg="completed keyexchange" Oct 30 22:00:15 volumio go-librespot[14906]: time="2025-10-30T22:00:15Z" level=debug msg="completed challenge" Oct 30 22:00:15 volumio go-librespot[14906]: time="2025-10-30T22:00:15Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 30 22:00:15 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 30 22:00:15 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 30 22:00:17 volumio volumio[14327]: info: Initializing connection to go-librespot Websocket Oct 30 22:00:17 volumio volumio[14327]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 30 22:00:19 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 21. Oct 30 22:00:19 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 30 22:00:19 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 30 22:00:19 volumio go-librespot[14913]: go-librespot daemon starting... Oct 30 22:00:19 volumio go-librespot[14914]: time="2025-10-30T22:00:19Z" level=info msg="running go-librespot 0.4.0" Oct 30 22:00:19 volumio go-librespot[14914]: time="2025-10-30T22:00:19Z" level=debug msg="app state loaded" Oct 30 22:00:19 volumio go-librespot[14914]: time="2025-10-30T22:00:19Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 30 22:00:19 volumio go-librespot[14914]: time="2025-10-30T22:00:19Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Oct 30 22:00:19 volumio go-librespot[14914]: time="2025-10-30T22:00:19Z" 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 30 22:00:19 volumio go-librespot[14914]: time="2025-10-30T22:00:19Z" 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 30 22:00:19 volumio go-librespot[14914]: time="2025-10-30T22:00:19Z" level=info msg="zeroconf server listening on port 34181" Oct 30 22:00:19 volumio go-librespot[14914]: time="2025-10-30T22:00:19Z" level=debug msg="obtained new client token: AADayWaFv5UDyZ/i6CFi7f7k9w2LcIlttoaLM4oVVAwwE94snISAMg67etRBPvHjLUQX8FOUNGmU08Nv1TPGxm2ADQYQWeX+c3KEuRp2yjzI/Cay5Wp9IZYSS14OXj4Z5U472rtTr0jdj3eg5GJHGvuTR/u3B39dqJE5fZeAP2EHvrkr6QkNYUXjb5TdGVPihi4NOTefpXaaq259hLLlIYIT2opWnxl+9OOFcXdZ3afo5DmUxzn9" Oct 30 22:00:19 volumio go-librespot[14914]: time="2025-10-30T22:00:19Z" 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 30 22:00:19 volumio go-librespot[14914]: time="2025-10-30T22:00:19Z" level=debug msg="connected to ap-gew1.spotify.com:443" Oct 30 22:00:19 volumio go-librespot[14914]: time="2025-10-30T22:00:19Z" level=debug msg="completed keyexchange" Oct 30 22:00:19 volumio go-librespot[14914]: time="2025-10-30T22:00:19Z" level=debug msg="completed challenge" Oct 30 22:00:19 volumio go-librespot[14914]: time="2025-10-30T22:00:19Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 30 22:00:19 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 30 22:00:19 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 30 22:00:20 volumio volumio[14327]: info: Initializing connection to go-librespot Websocket Oct 30 22:00:20 volumio volumio[14327]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 30 22:00:22 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 22. Oct 30 22:00:22 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 30 22:00:22 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 30 22:00:22 volumio go-librespot[14922]: go-librespot daemon starting... Oct 30 22:00:22 volumio go-librespot[14923]: time="2025-10-30T22:00:22Z" level=info msg="running go-librespot 0.4.0" Oct 30 22:00:22 volumio go-librespot[14923]: time="2025-10-30T22:00:22Z" level=debug msg="app state loaded" Oct 30 22:00:22 volumio go-librespot[14923]: time="2025-10-30T22:00:22Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 30 22:00:22 volumio go-librespot[14923]: time="2025-10-30T22:00:22Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Oct 30 22:00:22 volumio go-librespot[14923]: time="2025-10-30T22:00:22Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 30 22:00:22 volumio go-librespot[14923]: time="2025-10-30T22:00:22Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 30 22:00:22 volumio go-librespot[14923]: time="2025-10-30T22:00:22Z" level=info msg="zeroconf server listening on port 42357" Oct 30 22:00:22 volumio go-librespot[14923]: time="2025-10-30T22:00:22Z" level=debug msg="obtained new client token: AAAZBFPOfsfcsVaInUwZMTnZy/1N09QCUu45q+j5rekJ1L4MLZYCSmNAQ09cSWBC7cuimJaX4btUOqcHmxJwGIaJOlL8TdtxG3s2+UvmCdv5dJm8rEG0f8QITYikyDRq6+MkJfV84be+verJW5Dhk25wzX6mi2fVK7A7zMytJInpaGyEC/IuWyeZMuL6xOoOLj7zGQjpqzR6DI3uDTWFPnAReXP7k/qgsliqXvzO0NtYHVKeaxjxJtg=" Oct 30 22:00:22 volumio go-librespot[14923]: time="2025-10-30T22:00:22Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 30 22:00:22 volumio go-librespot[14923]: time="2025-10-30T22:00:22Z" level=debug msg="completed keyexchange" Oct 30 22:00:22 volumio go-librespot[14923]: time="2025-10-30T22:00:22Z" level=debug msg="completed challenge" Oct 30 22:00:22 volumio go-librespot[14923]: time="2025-10-30T22:00:22Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 30 22:00:22 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 30 22:00:22 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 30 22:00:23 volumio volumio[14327]: info: Initializing connection to go-librespot Websocket Oct 30 22:00:23 volumio volumio[14327]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 30 22:00:26 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 23. Oct 30 22:00:26 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 30 22:00:26 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 30 22:00:26 volumio go-librespot[14945]: go-librespot daemon starting... Oct 30 22:00:26 volumio go-librespot[14946]: time="2025-10-30T22:00:26Z" level=info msg="running go-librespot 0.4.0" Oct 30 22:00:26 volumio go-librespot[14946]: time="2025-10-30T22:00:26Z" level=debug msg="app state loaded" Oct 30 22:00:26 volumio go-librespot[14946]: time="2025-10-30T22:00:26Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 30 22:00:26 volumio go-librespot[14946]: time="2025-10-30T22:00:26Z" 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 30 22:00:26 volumio go-librespot[14946]: time="2025-10-30T22:00:26Z" 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 30 22:00:26 volumio go-librespot[14946]: time="2025-10-30T22:00:26Z" 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 30 22:00:26 volumio go-librespot[14946]: time="2025-10-30T22:00:26Z" level=info msg="zeroconf server listening on port 40571" Oct 30 22:00:26 volumio go-librespot[14946]: time="2025-10-30T22:00:26Z" level=debug msg="obtained new client token: AACFmFaXXRES/UjSocRTV58RloMUoVTvKEp44kOFKEyEZ6COEYLAHxL0A4+yQ2ZYA0awJ3RJxZfR/8Cs9tGAxsxxdTsBsxTKi2M2y0brLn1QCxLPbm28sz+wFkjjGJl/pOn8MCHUvPXndO503b4eeY4Z3jUR+lhVyr9BauyQaof1gbF5fWW7PK8pNo96rlDFHqeTNfA5LK/kEEDEqyY2+PGmyB70e68QBt+H1wrCIr+CebkrXPVE" Oct 30 22:00:26 volumio go-librespot[14946]: time="2025-10-30T22:00:26Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 30 22:00:26 volumio go-librespot[14946]: time="2025-10-30T22:00:26Z" level=debug msg="completed keyexchange" Oct 30 22:00:26 volumio go-librespot[14946]: time="2025-10-30T22:00:26Z" level=debug msg="completed challenge" Oct 30 22:00:26 volumio go-librespot[14946]: time="2025-10-30T22:00:26Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 30 22:00:26 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 30 22:00:26 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 30 22:00:26 volumio volumio[14327]: info: Initializing connection to go-librespot Websocket Oct 30 22:00:26 volumio volumio[14327]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 30 22:00:29 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 24. Oct 30 22:00:29 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 30 22:00:29 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 30 22:00:29 volumio go-librespot[14956]: go-librespot daemon starting... Oct 30 22:00:29 volumio go-librespot[14957]: time="2025-10-30T22:00:29Z" level=info msg="running go-librespot 0.4.0" Oct 30 22:00:29 volumio go-librespot[14957]: time="2025-10-30T22:00:29Z" level=debug msg="app state loaded" Oct 30 22:00:29 volumio go-librespot[14957]: time="2025-10-30T22:00:29Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 30 22:00:29 volumio go-librespot[14957]: time="2025-10-30T22:00:29Z" 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 30 22:00:29 volumio go-librespot[14957]: time="2025-10-30T22:00:29Z" 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 30 22:00:29 volumio go-librespot[14957]: time="2025-10-30T22:00:29Z" 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 30 22:00:29 volumio go-librespot[14957]: time="2025-10-30T22:00:29Z" level=info msg="zeroconf server listening on port 40027" Oct 30 22:00:29 volumio go-librespot[14957]: time="2025-10-30T22:00:29Z" level=debug msg="obtained new client token: AAC/Eit5E++oznU6H0yYAAmaRv1SRU6zbqBkCGUcu7ul4TTYeXosy6HWHZ6F/jJDu0n+1FADjCdDUeMXVqrMU4bits+fqA8PGnhy7CF8ZUWri7RvoKQJ/55R++eqPQy1RqnUpeqnfqy+O5PHeTm9yBW0kjWzsakcujnyAAgit9DScZKbNNSpmowOxDGo00G+lNaGmLBoO7Gcy7BpjxJnyu4JBS6ccDpq7Q3x4JE0kmiCeeNbpqKsmhU=" Oct 30 22:00:29 volumio go-librespot[14957]: time="2025-10-30T22:00:29Z" 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 30 22:00:29 volumio go-librespot[14957]: time="2025-10-30T22:00:29Z" level=debug msg="connected to ap-gew1.spotify.com:443" Oct 30 22:00:29 volumio go-librespot[14957]: time="2025-10-30T22:00:29Z" level=debug msg="completed keyexchange" Oct 30 22:00:29 volumio go-librespot[14957]: time="2025-10-30T22:00:29Z" level=debug msg="completed challenge" Oct 30 22:00:29 volumio go-librespot[14957]: time="2025-10-30T22:00:29Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 30 22:00:29 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 30 22:00:29 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 30 22:00:29 volumio volumio[14327]: info: Initializing connection to go-librespot Websocket Oct 30 22:00:29 volumio volumio[14327]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 30 22:00:32 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 25. Oct 30 22:00:32 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 30 22:00:32 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 30 22:00:32 volumio go-librespot[14964]: go-librespot daemon starting... Oct 30 22:00:32 volumio go-librespot[14965]: time="2025-10-30T22:00:32Z" level=info msg="running go-librespot 0.4.0" Oct 30 22:00:32 volumio go-librespot[14965]: time="2025-10-30T22:00:32Z" level=debug msg="app state loaded" Oct 30 22:00:32 volumio go-librespot[14965]: time="2025-10-30T22:00:32Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 30 22:00:32 volumio volumio[14327]: info: Initializing connection to go-librespot Websocket Oct 30 22:00:32 volumio go-librespot[14965]: time="2025-10-30T22:00: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 30 22:00:32 volumio go-librespot[14965]: time="2025-10-30T22:00: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 30 22:00:32 volumio go-librespot[14965]: time="2025-10-30T22:00: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 30 22:00:32 volumio go-librespot[14965]: time="2025-10-30T22:00:32Z" level=debug msg="new websocket client" Oct 30 22:00:32 volumio volumio[14327]: info: Connection to go-librespot Websocket established Oct 30 22:00:32 volumio go-librespot[14965]: time="2025-10-30T22:00:32Z" level=info msg="zeroconf server listening on port 34493" Oct 30 22:00:32 volumio go-librespot[14965]: time="2025-10-30T22:00:32Z" level=debug msg="obtained new client token: AABVMGsX/ezRvpyIoqS879ABZgb39VNgMAMjoPRGxCZj7rVgnqU6KJsGiV67v0dzNTOHy4HTk2wbdW0jG+mqQS2tZI9Q0QDHawK/fyDfRyfXch04jxCIJ6zkjAf0mQVlP/AhBUUZNOAq8+KolqTStkdBYQmTn2pIJhack0sqTyZ6mqDgBVxyQ89unYueXEubTLlMqML34zmlpeEq5V2pXlpRVtc7HGfYjlYfVj/1euU8eEjmPjsLjsc=" Oct 30 22:00:32 volumio go-librespot[14965]: time="2025-10-30T22:00:32Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 30 22:00:32 volumio go-librespot[14965]: time="2025-10-30T22:00:32Z" level=debug msg="completed keyexchange" Oct 30 22:00:32 volumio go-librespot[14965]: time="2025-10-30T22:00:32Z" level=debug msg="completed challenge" Oct 30 22:00:33 volumio go-librespot[14965]: time="2025-10-30T22:00:33Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 30 22:00:33 volumio volumio[14327]: info: Connection to go-librespot Websocket closed Oct 30 22:00:33 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 30 22:00:33 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 30 22:00:35 volumio volumio[14327]: info: Getting Spotify volume Oct 30 22:00:35 volumio volumio[14327]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 30 22:00:35 volumio volumio[14327]: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 30 22:00:35 volumio volumio[14327]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Oct 30 22:00:35 volumio volumio[14327]: errno: -111, Oct 30 22:00:35 volumio volumio[14327]: code: 'ECONNREFUSED', Oct 30 22:00:35 volumio volumio[14327]: syscall: 'connect', Oct 30 22:00:35 volumio volumio[14327]: address: '127.0.0.1', Oct 30 22:00:35 volumio volumio[14327]: port: 9879, Oct 30 22:00:35 volumio volumio[14327]: response: undefined Oct 30 22:00:35 volumio volumio[14327]: } Oct 30 22:00:35 volumio volumio[14327]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 30 22:00:36 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 26. Oct 30 22:00:36 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 30 22:00:36 volumio sudo[15001]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-10-30 21:59' Oct 30 22:00:36 volumio sudo[15001]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 30 22:00:36 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 30 22:00:36 volumio go-librespot[14998]: go-librespot daemon starting... Oct 30 22:00:36 volumio go-librespot[15003]: time="2025-10-30T22:00:36Z" level=info msg="running go-librespot 0.4.0" Oct 30 22:00:36 volumio go-librespot[15003]: time="2025-10-30T22:00:36Z" level=debug msg="app state loaded" Oct 30 22:00:36 volumio go-librespot[15003]: time="2025-10-30T22:00:36Z" level=info msg="api server listening on 127.0.0.1:9879" 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"