Oct 29 06:34:00 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 168. Oct 29 06:34:00 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 29 06:34:00 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 29 06:34:00 volumio go-librespot[24802]: go-librespot daemon starting... Oct 29 06:34:00 volumio go-librespot[24803]: time="2025-10-29T06:34:00Z" level=info msg="running go-librespot 0.4.0" Oct 29 06:34:00 volumio go-librespot[24803]: time="2025-10-29T06:34:00Z" level=debug msg="app state loaded" Oct 29 06:34:00 volumio go-librespot[24803]: time="2025-10-29T06:34:00Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 29 06:34:00 volumio go-librespot[24803]: time="2025-10-29T06:34:00Z" 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 29 06:34:00 volumio go-librespot[24803]: time="2025-10-29T06:34:00Z" 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 29 06:34:00 volumio go-librespot[24803]: time="2025-10-29T06:34:00Z" 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 29 06:34:00 volumio go-librespot[24803]: time="2025-10-29T06:34:00Z" level=info msg="zeroconf server listening on port 34819" Oct 29 06:34:00 volumio go-librespot[24803]: time="2025-10-29T06:34:00Z" level=debug msg="obtained new client token: AAAeVNyc9hYJW5aDswqFPARnVEAVL7NirFu+xW3StCI3YAXJnl/JHMUlg9AUVXuWEtQSvc4ujSiCOi393piWaibMZdHBocG06QTXVB9z6w8Gmc/n7soggjqnJqUv7suTHNJEFLDMaxeva20j9X6JXoPmZvzncflgo4JBET7mExP7ctq/0RrKyAC74K63YznXytQR4sXveBXCxsg7Ic5UmpQ2UDImd8nt4fFH8ehn+9WBCp2BlwaS/2c=" Oct 29 06:34:00 volumio go-librespot[24803]: time="2025-10-29T06:34:00Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 29 06:34:00 volumio go-librespot[24803]: time="2025-10-29T06:34:00Z" level=debug msg="completed keyexchange" Oct 29 06:34:00 volumio go-librespot[24803]: time="2025-10-29T06:34:00Z" level=debug msg="completed challenge" Oct 29 06:34:00 volumio go-librespot[24803]: time="2025-10-29T06:34:00Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 29 06:34:00 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 29 06:34:00 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 29 06:34:01 volumio volumio[24098]: info: Initializing connection to go-librespot Websocket Oct 29 06:34:01 volumio volumio[24098]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 29 06:34:01 volumio kernel: nfs: server 192.168.1.3 not responding, timed out Oct 29 06:34:04 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 169. Oct 29 06:34:04 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 29 06:34:04 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 29 06:34:04 volumio go-librespot[24824]: go-librespot daemon starting... Oct 29 06:34:04 volumio go-librespot[24825]: time="2025-10-29T06:34:04Z" level=info msg="running go-librespot 0.4.0" Oct 29 06:34:04 volumio go-librespot[24825]: time="2025-10-29T06:34:04Z" level=debug msg="app state loaded" Oct 29 06:34:04 volumio go-librespot[24825]: time="2025-10-29T06:34:04Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 29 06:34:04 volumio volumio[24098]: info: Initializing connection to go-librespot Websocket Oct 29 06:34:04 volumio volumio[24098]: info: Connection to go-librespot Websocket established Oct 29 06:34:04 volumio go-librespot[24825]: time="2025-10-29T06:34:04Z" level=debug msg="new websocket client" Oct 29 06:34:04 volumio go-librespot[24825]: time="2025-10-29T06:34:04Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Oct 29 06:34:04 volumio go-librespot[24825]: time="2025-10-29T06:34:04Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 29 06:34:04 volumio go-librespot[24825]: time="2025-10-29T06:34:04Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 29 06:34:04 volumio go-librespot[24825]: time="2025-10-29T06:34:04Z" level=info msg="zeroconf server listening on port 39255" Oct 29 06:34:04 volumio go-librespot[24825]: time="2025-10-29T06:34:04Z" level=debug msg="obtained new client token: AAD76roPBIO5IH1EG/MhYYRPWuFcJ2IOjVDSrFw7yfbbviQMnewaQ+z8O6btnMopg9kigeThgWafFYlXNXw9/SIECqjGJO7yzPnYcGGbhbjkBOPSrIUSBUG0AfvtQl/3+BZs0hYmsNIdRcTlEXa1/4tFTXcb/SFwwqvQrgsUcF4bNSvR9kPPa9REjaHgfnAwKb0hHLvYSYxt0GYCWDbqYq33MlbQkCiOOKjqdhyV+OSST1KRgD10" Oct 29 06:34:04 volumio go-librespot[24825]: time="2025-10-29T06:34:04Z" 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 29 06:34:04 volumio go-librespot[24825]: time="2025-10-29T06:34:04Z" level=debug msg="connected to ap-gew1.spotify.com:443" Oct 29 06:34:04 volumio go-librespot[24825]: time="2025-10-29T06:34:04Z" level=debug msg="completed keyexchange" Oct 29 06:34:04 volumio go-librespot[24825]: time="2025-10-29T06:34:04Z" level=debug msg="completed challenge" Oct 29 06:34:04 volumio go-librespot[24825]: time="2025-10-29T06:34:04Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 29 06:34:04 volumio volumio[24098]: info: Connection to go-librespot Websocket closed Oct 29 06:34:04 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 29 06:34:04 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 29 06:34:07 volumio volumio[24098]: info: Getting Spotify volume Oct 29 06:34:07 volumio volumio[24098]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 29 06:34:07 volumio volumio[24098]: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 29 06:34:07 volumio volumio[24098]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Oct 29 06:34:07 volumio volumio[24098]: errno: -111, Oct 29 06:34:07 volumio volumio[24098]: code: 'ECONNREFUSED', Oct 29 06:34:07 volumio volumio[24098]: syscall: 'connect', Oct 29 06:34:07 volumio volumio[24098]: address: '127.0.0.1', Oct 29 06:34:07 volumio volumio[24098]: port: 9879, Oct 29 06:34:07 volumio volumio[24098]: response: undefined Oct 29 06:34:07 volumio volumio[24098]: } Oct 29 06:34:07 volumio volumio[24098]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 29 06:34:07 volumio sudo[24846]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-10-29 06:33' Oct 29 06:34:07 volumio sudo[24846]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 29 06:34:07 volumio sudo[24846]: pam_unix(sudo:session): session closed for user root Oct 29 06:34:07 volumio volumio-remote-updater[874]: [2025-10-29 06:34:07] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Oct 29 06:34:07 volumio volumio-remote-updater[874]: [2025-10-29 06:34:07] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Oct 29 06:34:07 volumio systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Oct 29 06:34:07 volumio systemd[1]: volumio.service: Failed with result 'exit-code'. Oct 29 06:34:07 volumio systemd[1]: volumio.service: Consumed 8.363s CPU time. Oct 29 06:34:07 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Oct 29 06:34:07 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Oct 29 06:34:07 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 170. Oct 29 06:34:07 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 2024. Oct 29 06:34:07 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Oct 29 06:34:07 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 29 06:34:07 volumio systemd[1]: Stopped volumio.service - Volumio Backend Module. Oct 29 06:34:07 volumio systemd[1]: volumio.service: Consumed 8.363s CPU time. Oct 29 06:34:07 volumio systemd[1]: Started volumio.service - Volumio Backend Module. Oct 29 06:34:07 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 29 06:34:07 volumio go-librespot[24873]: go-librespot daemon starting... Oct 29 06:34:07 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Oct 29 06:34:07 volumio go-librespot[24874]: time="2025-10-29T06:34:07Z" level=info msg="running go-librespot 0.4.0" Oct 29 06:34:07 volumio go-librespot[24874]: time="2025-10-29T06:34:07Z" level=debug msg="app state loaded" Oct 29 06:34:07 volumio go-librespot[24874]: time="2025-10-29T06:34:07Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 29 06:34:07 volumio go-librespot[24874]: time="2025-10-29T06:34:07Z" 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 29 06:34:07 volumio go-librespot[24874]: time="2025-10-29T06:34:07Z" 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 29 06:34:07 volumio go-librespot[24874]: time="2025-10-29T06:34:07Z" 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 29 06:34:07 volumio go-librespot[24874]: time="2025-10-29T06:34:07Z" level=info msg="zeroconf server listening on port 34693" Oct 29 06:34:07 volumio go-librespot[24874]: time="2025-10-29T06:34:07Z" level=debug msg="obtained new client token: AAB3r+uhTGvYFeSdVysPD79c90jG1ex3KNPNnHcxeZAVCkG+KL9Vi4IsmB6RgBbCFPF4UqqdGW0dClg+fQuXmmZPq3xbzLM2zCGWn8QqXcBvOzSqFOo8w0ndksphidYcURV6yzzYaTrc1m8qHRyYV2VYuX5r1nVoJLGKOwhYTGJNaqyuOsLTjVs2zJnQIV3xSGb3rJ0myUIu/I6+S1YkY6un6jxFhViYS38lmDVZ2ZId8tWkjGcMigM=" Oct 29 06:34:07 volumio go-librespot[24874]: time="2025-10-29T06:34:07Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 29 06:34:07 volumio go-librespot[24874]: time="2025-10-29T06:34:07Z" level=debug msg="completed keyexchange" Oct 29 06:34:07 volumio go-librespot[24874]: time="2025-10-29T06:34:07Z" level=debug msg="completed challenge" Oct 29 06:34:07 volumio go-librespot[24874]: time="2025-10-29T06:34:07Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 29 06:34:07 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 29 06:34:07 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 29 06:34:07 volumio volumio[24870]: info: ------------------------------------------- Oct 29 06:34:07 volumio volumio[24870]: info: ----- Volumio3 ---- Oct 29 06:34:07 volumio volumio[24870]: info: ------------------------------------------- Oct 29 06:34:07 volumio volumio[24870]: info: ----- System startup ---- Oct 29 06:34:07 volumio volumio[24870]: info: ------------------------------------------- Oct 29 06:34:08 volumio volumio[24870]: info: MYVOLUMIO Environment detected Oct 29 06:34:08 volumio volumio[24870]: info: Plugin folders cleanup Oct 29 06:34:08 volumio volumio[24870]: info: Scanning into folder /volumio/app/plugins/ Oct 29 06:34:08 volumio volumio[24870]: info: Scanning category audio_interface Oct 29 06:34:08 volumio volumio[24870]: info: Scanning category miscellanea Oct 29 06:34:08 volumio volumio[24870]: info: Scanning category music_service Oct 29 06:34:08 volumio volumio[24870]: info: Scanning category plugins.json Oct 29 06:34:08 volumio volumio[24870]: info: Scanning category system_controller Oct 29 06:34:08 volumio volumio[24870]: info: Scanning category user_interface Oct 29 06:34:08 volumio volumio[24870]: info: Scanning into folder /data/plugins/ Oct 29 06:34:08 volumio volumio[24870]: info: Scanning category music_service Oct 29 06:34:08 volumio volumio[24870]: info: Scanning category user_interface Oct 29 06:34:08 volumio volumio[24870]: info: Plugin folders cleanup completed Oct 29 06:34:08 volumio volumio[24870]: info: ------------------------------------------- Oct 29 06:34:08 volumio volumio[24870]: info: ----- Core plugins startup ---- Oct 29 06:34:08 volumio volumio[24870]: info: ------------------------------------------- Oct 29 06:34:08 volumio volumio[24870]: info: Loading plugins from folder /volumio/app/plugins/ Oct 29 06:34:08 volumio volumio[24870]: info: Adding plugin upnp to MyMusic Plugins Oct 29 06:34:08 volumio volumio[24870]: info: Adding plugin airplay_emulation to MyMusic Plugins Oct 29 06:34:08 volumio volumio[24870]: info: Adding plugin upnp_browser to MyMusic Plugins Oct 29 06:34:08 volumio volumio[24870]: info: Loading plugins from folder /data/plugins/ Oct 29 06:34:08 volumio volumio[24870]: info: Loading plugin "system"... Oct 29 06:34:08 volumio volumio[24870]: info: Loading plugin "appearance"... Oct 29 06:34:08 volumio volumio[24870]: info: Loading plugin "network"... Oct 29 06:34:08 volumio volumio[24870]: info: Refreshing Cached IP Addresses Oct 29 06:34:08 volumio sudo[24903]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 29 06:34:08 volumio sudo[24903]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 29 06:34:08 volumio sudo[24903]: pam_unix(sudo:session): session closed for user root Oct 29 06:34:08 volumio volumio[24870]: info: Loading plugin "services"... Oct 29 06:34:08 volumio sudo[24905]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 29 06:34:08 volumio sudo[24905]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 29 06:34:08 volumio volumio[24870]: info: Loading plugin "alsa_controller"... Oct 29 06:34:08 volumio sudo[24905]: pam_unix(sudo:session): session closed for user root Oct 29 06:34:08 volumio volumio[24870]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 29 06:34:08 volumio volumio[24870]: info: Loading plugin "wizard"... Oct 29 06:34:08 volumio volumio[24870]: info: Loading plugin "networkfs"... Oct 29 06:34:08 volumio volumio[24870]: info: Cannot mount NAS NAS at system boot, trial number 1 ,retrying in 5 seconds Oct 29 06:34:08 volumio volumio[24870]: info: Starting Udev Watcher for removable devices Oct 29 06:34:08 volumio volumio[24870]: info: Ignoring mount for partition: boot Oct 29 06:34:08 volumio volumio[24870]: info: Ignoring mount for partition: volumio Oct 29 06:34:08 volumio volumio[24870]: info: Ignoring mount for partition: volumio_data Oct 29 06:34:08 volumio volumio[24870]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 29 06:34:08 volumio volumio[24870]: info: Loading plugin "volumio_command_line_client"... Oct 29 06:34:08 volumio volumio[24870]: info: Loading plugin "upnp"... Oct 29 06:34:08 volumio volumio[24870]: info: [1761719648321] Starting Upmpd Daemon Oct 29 06:34:08 volumio volumio[24870]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 29 06:34:08 volumio volumio[24870]: info: Loading plugin "my_music"... Oct 29 06:34:08 volumio volumio[24870]: info: Loading plugin "mpd"... Oct 29 06:34:08 volumio volumio[24870]: info: Loading plugin "upnp_browser"... Oct 29 06:34:08 volumio volumio[24870]: info: Loading plugin "alarm-clock"... Oct 29 06:34:08 volumio volumio[24870]: info: Loading plugin "airplay_emulation"... Oct 29 06:34:08 volumio volumio[24870]: info: Starting Shairport Sync Oct 29 06:34:08 volumio volumio[24870]: info: Loading plugin "last_100"... Oct 29 06:34:08 volumio volumio[24870]: info: Loading plugin "webradio"... Oct 29 06:34:08 volumio volumio[24870]: info: Loading plugin "i2s_dacs"... Oct 29 06:34:08 volumio volumio[24870]: info: I2S DAC not set, start Auto-detection Oct 29 06:34:08 volumio volumio[24870]: info: Loading plugin "volumiodiscovery"... Oct 29 06:34:08 volumio volumio[24870]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Oct 29 06:34:08 volumio volumio[24870]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 29 06:34:08 volumio volumio[24870]: *** WARNING *** For more information see Oct 29 06:34:08 volumio volumio[24870]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Oct 29 06:34:08 volumio volumio[24870]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 29 06:34:08 volumio volumio[24870]: *** WARNING *** For more information see Oct 29 06:34:08 volumio node[24870]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Oct 29 06:34:08 volumio node[24870]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 29 06:34:08 volumio node[24870]: *** WARNING *** For more information see Oct 29 06:34:08 volumio node[24870]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Oct 29 06:34:08 volumio node[24870]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 29 06:34:08 volumio node[24870]: *** WARNING *** For more information see Oct 29 06:34:08 volumio volumio[24870]: info: Applying required configuration parameters for plugin volumiodiscovery Oct 29 06:34:08 volumio volumio[24870]: info: Discovery: Started advertising with name: Volumio Oct 29 06:34:08 volumio volumio[24870]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 29 06:34:08 volumio volumio[24870]: info: Loading plugin "spop"... Oct 29 06:34:08 volumio volumio[24870]: info: Loading plugin "ytcr"... Oct 29 06:34:09 volumio volumio[24870]: info: Loading plugin "outputs"... Oct 29 06:34:09 volumio volumio[24870]: info: Loading plugin "albumart"... Oct 29 06:34:09 volumio volumio[24870]: info: Plugin example_plugin is not enabled Oct 29 06:34:09 volumio volumio[24870]: info: Loading plugin "inputs"... Oct 29 06:34:09 volumio volumio[24870]: info: Loading plugin "updater_comm"... Oct 29 06:34:09 volumio volumio[24870]: info: Plugin mpdemulation is not enabled Oct 29 06:34:09 volumio volumio[24870]: info: Loading plugin "rest_api"... Oct 29 06:34:09 volumio volumio[24870]: info: Loading plugin "websocket"... Oct 29 06:34:09 volumio volumio[24870]: info: Starting Socket.io Server version 1.7.4 Oct 29 06:34:09 volumio volumio[24870]: info: Loading plugin "Systeminfo"... Oct 29 06:34:09 volumio volumio[24870]: info: Loading i18n strings for locale en Oct 29 06:34:09 volumio volumio[24870]: Updating browse sources language Oct 29 06:34:09 volumio volumio[24870]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 29 06:34:09 volumio volumio[24935]: Forking 3 albumart workers Oct 29 06:34:09 volumio volumio[24870]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 29 06:34:09 volumio volumio[24870]: info: CoreCommandRouter::initPlayerControls Oct 29 06:34:09 volumio volumio[24870]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 29 06:34:09 volumio volumio[24870]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 29 06:34:09 volumio volumio[24870]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 29 06:34:09 volumio volumio[24870]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 29 06:34:09 volumio volumio[24870]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 29 06:34:09 volumio volumio[24870]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 29 06:34:09 volumio volumio[24870]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 29 06:34:09 volumio volumio[24870]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 29 06:34:09 volumio volumio[24870]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 29 06:34:09 volumio volumio[24870]: Express server listening on port 3000 Oct 29 06:34:09 volumio volumio[24870]: [Metrics] WebUI: 1s 948.51ms Oct 29 06:34:09 volumio volumio[24870]: info: CoreStateMachine::resetVolumioState Oct 29 06:34:09 volumio volumio[24870]: info: CoreStateMachine::getcurrentVolume Oct 29 06:34:09 volumio volumio[24870]: info: CoreCommandRouter::volumioRetrievevolume Oct 29 06:34:09 volumio volumio[24870]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 29 06:34:09 volumio volumio[24870]: info: Cannot read play queue from file Oct 29 06:34:09 volumio volumio[24870]: info: Volumio Network Manager: Network status updated: 1 Oct 29 06:34:09 volumio volumio[24870]: info: VolumeController:: Volume=33 Mute =false Oct 29 06:34:09 volumio volumio[24870]: info: CoreStateMachine::pushState Oct 29 06:34:09 volumio volumio[24870]: info: CorePlayQueue::getTrack 0 Oct 29 06:34:09 volumio volumio[24870]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 29 06:34:09 volumio volumio[24870]: info: CoreCommandRouter::volumioPushState Oct 29 06:34:09 volumio volumio[24870]: info: CoreStateMachine::updateTrackBlock Oct 29 06:34:09 volumio volumio[24870]: info: CorePlayQueue::getTrackBlock Oct 29 06:34:09 volumio volumio[24870]: info: CoreCommandRouter::volumioRetrievevolume Oct 29 06:34:09 volumio volumio[24870]: info: CoreStateMachine::setRepeat null single undefined Oct 29 06:34:09 volumio volumio[24870]: info: CoreStateMachine::pushState Oct 29 06:34:09 volumio volumio[24870]: info: CorePlayQueue::getTrack 0 Oct 29 06:34:09 volumio volumio[24870]: info: CoreCommandRouter::volumioPushState Oct 29 06:34:09 volumio volumio[24870]: info: CoreStateMachine::setRandom null Oct 29 06:34:09 volumio volumio[24870]: info: CoreStateMachine::pushState Oct 29 06:34:09 volumio volumio[24870]: info: CorePlayQueue::getTrack 0 Oct 29 06:34:09 volumio volumio[24870]: info: CoreCommandRouter::volumioPushState Oct 29 06:34:09 volumio volumio[24870]: info: Setting Device type: Raspberry PI Oct 29 06:34:09 volumio volumio[24870]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Oct 29 06:34:09 volumio volumio[24870]: info: USB Boot Capable - System SBC Revision found in cpuinfo: b04170 Oct 29 06:34:09 volumio volumio[24870]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Oct 29 06:34:09 volumio volumio[24870]: info: VolumeController:: Volume=33 Mute =false Oct 29 06:34:09 volumio volumio[24870]: info: CoreStateMachine::pushState Oct 29 06:34:09 volumio volumio[24870]: info: CorePlayQueue::getTrack 0 Oct 29 06:34:09 volumio volumio[24870]: info: CoreCommandRouter::volumioPushState Oct 29 06:34:09 volumio volumio[24870]: info: Discovery: adding 70853f74-8210-4683-a3fa-e1217517bd40 Oct 29 06:34:09 volumio volumio[24870]: info: Discovery: Found device Volumio Oct 29 06:34:09 volumio volumio[24870]: info: CoreCommandRouter::volumioGetState Oct 29 06:34:09 volumio volumio[24870]: info: CorePlayQueue::getTrack 0 Oct 29 06:34:09 volumio volumio[24870]: info: Completed loading Core Plugins Oct 29 06:34:09 volumio volumio[24870]: info: Preparing to generate the ALSA configuration file Oct 29 06:34:09 volumio volumio[24870]: info: Discovery: this is already registered, 70853f74-8210-4683-a3fa-e1217517bd40 Oct 29 06:34:09 volumio volumio[24870]: info: Discovery: Found device Volumio Oct 29 06:34:09 volumio volumio[24870]: info: CoreCommandRouter::volumioGetState Oct 29 06:34:09 volumio volumio[24870]: info: CorePlayQueue::getTrack 0 Oct 29 06:34:09 volumio volumio[24870]: info: Asound.conf file unchanged, so no further update is needed Oct 29 06:34:09 volumio volumio[24870]: info: Output device has changed, restarting MPD Oct 29 06:34:09 volumio sudo[24992]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 29 06:34:09 volumio sudo[24992]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 29 06:34:09 volumio volumio[24870]: info: Output device has changed, restarting Shairport Sync Oct 29 06:34:09 volumio volumio[24870]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 29 06:34:09 volumio volumio[24870]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 29 06:34:09 volumio sudo[24992]: pam_unix(sudo:session): session closed for user root Oct 29 06:34:10 volumio volumio[24870]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 29 06:34:10 volumio volumio[24870]: info: ___________ START PLUGINS ___________ Oct 29 06:34:10 volumio volumio[24870]: info: ControllerMpd::onStart: Initializing MPD Oct 29 06:34:10 volumio volumio[24870]: info: Creating MPD Configuration file Oct 29 06:34:10 volumio sudo[24994]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 29 06:34:10 volumio sudo[24994]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 29 06:34:10 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Oct 29 06:34:10 volumio volumio[24870]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 29 06:34:10 volumio volumio[24870]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 29 06:34:10 volumio volumio[24870]: info: [1761719650039] CoreMusicLibrary::Adding element Media Servers Oct 29 06:34:10 volumio volumio[24870]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 29 06:34:10 volumio sudo[25002]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 29 06:34:10 volumio sudo[25004]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 29 06:34:10 volumio sudo[25002]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 29 06:34:10 volumio sudo[25004]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 29 06:34:10 volumio sudo[25002]: pam_unix(sudo:session): session closed for user root Oct 29 06:34:10 volumio systemd[1]: mpd.service: Deactivated successfully. Oct 29 06:34:10 volumio volumio[24870]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 29 06:34:10 volumio volumio[24870]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 29 06:34:10 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Oct 29 06:34:10 volumio systemd[1]: mpd.socket: Deactivated successfully. Oct 29 06:34:10 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Oct 29 06:34:10 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Oct 29 06:34:10 volumio volumio[24870]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 29 06:34:10 volumio volumio[24870]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 29 06:34:10 volumio volumio[24870]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 29 06:34:10 volumio volumio[24870]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 29 06:34:10 volumio volumio[24870]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 29 06:34:10 volumio volumio[24870]: info: [1761719650079] CoreMusicLibrary::Adding element Last_100 Oct 29 06:34:10 volumio volumio[24870]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 29 06:34:10 volumio volumio[24870]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 29 06:34:10 volumio volumio[24870]: info: [1761719650080] CoreMusicLibrary::Adding element Webradio Oct 29 06:34:10 volumio volumio[24870]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 29 06:34:10 volumio volumio[24870]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 29 06:34:10 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Oct 29 06:34:10 volumio volumio[24870]: info: Initializing BBC Radios Oct 29 06:34:10 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Oct 29 06:34:10 volumio systemd[1]: mpd.service: Deactivated successfully. Oct 29 06:34:10 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Oct 29 06:34:10 volumio systemd[1]: mpd.socket: Deactivated successfully. Oct 29 06:34:10 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Oct 29 06:34:10 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Oct 29 06:34:10 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Oct 29 06:34:10 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Oct 29 06:34:10 volumio volumio[24870]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 29 06:34:10 volumio volumio[24870]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 29 06:34:10 volumio volumio[24947]: Starting albumart workers Oct 29 06:34:10 volumio sudo[25031]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Oct 29 06:34:10 volumio sudo[25031]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Oct 29 06:34:10 volumio volumio[24870]: info: Creating Spotify config file Oct 29 06:34:10 volumio volumio[24870]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 29 06:34:10 volumio sudo[25031]: pam_unix(sudo:session): session closed for user root Oct 29 06:34:10 volumio volumio[24946]: Starting albumart workers Oct 29 06:34:10 volumio volumio[24870]: info: Volumio Calling Home Oct 29 06:34:10 volumio volumio[24945]: Starting albumart workers Oct 29 06:34:10 volumio volumio[24870]: info: MPD Permissions set Oct 29 06:34:10 volumio volumio[24870]: info: MPD Permissions set Oct 29 06:34:10 volumio volumio[24870]: 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 29 06:34:10 volumio volumio[24870]: info: Volumio called home Oct 29 06:34:10 volumio volumio[24870]: info: Spotify config file written Oct 29 06:34:10 volumio volumio[24870]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 29 06:34:10 volumio volumio[24870]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 29 06:34:10 volumio volumio[24870]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 29 06:34:10 volumio volumio[24870]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 29 06:34:10 volumio volumio[24870]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 29 06:34:10 volumio volumio[24870]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 29 06:34:10 volumio volumio[24870]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 29 06:34:10 volumio volumio[24870]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 29 06:34:10 volumio sudo[25050]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Oct 29 06:34:10 volumio sudo[25050]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 29 06:34:10 volumio volumio[24870]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 29 06:34:10 volumio volumio[24870]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 29 06:34:10 volumio volumio[24870]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 29 06:34:10 volumio volumio[24870]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 29 06:34:10 volumio volumio[24870]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 29 06:34:10 volumio volumio[24870]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 29 06:34:10 volumio volumio[24870]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 29 06:34:10 volumio volumio[24870]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 29 06:34:10 volumio volumio[24870]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 29 06:34:10 volumio volumio[24870]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 29 06:34:10 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 29 06:34:10 volumio volumio[24870]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 29 06:34:10 volumio volumio[24870]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 29 06:34:10 volumio volumio[24870]: info: No need to fix Spotify hosts Oct 29 06:34:10 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 29 06:34:10 volumio go-librespot[25058]: go-librespot daemon starting... Oct 29 06:34:10 volumio go-librespot[25063]: time="2025-10-29T06:34:10Z" level=info msg="running go-librespot 0.4.0" Oct 29 06:34:10 volumio sudo[25050]: pam_unix(sudo:session): session closed for user root Oct 29 06:34:10 volumio go-librespot[25063]: time="2025-10-29T06:34:10Z" level=debug msg="app state loaded" Oct 29 06:34:10 volumio go-librespot[25063]: time="2025-10-29T06:34:10Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 29 06:34:10 volumio volumio[24870]: info: Starting Shairport Sync Oct 29 06:34:10 volumio volumio[24870]: info: Starting Shairport Sync Oct 29 06:34:10 volumio volumio[24870]: info: Starting Shairport Sync Oct 29 06:34:10 volumio sudo[25076]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 29 06:34:10 volumio sudo[25078]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 29 06:34:10 volumio sudo[25076]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 29 06:34:10 volumio sudo[25080]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 29 06:34:10 volumio sudo[25080]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 29 06:34:10 volumio sudo[25078]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 29 06:34:10 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Oct 29 06:34:10 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Oct 29 06:34:10 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Oct 29 06:34:10 volumio systemd[1]: shairport-sync.service: Consumed 1.587s CPU time. Oct 29 06:34:10 volumio volumio[24870]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Oct 29 06:34:10 volumio volumio[24870]: SPOTIFY: BQCd1bIHjSNceCW2qJtbJCEgx1BV1VFUryaD1HFTH5RqcCVDk0AkgyhaGmWhdTI8bP6zBo6xk421Vmc3K-tWcEMeHDCju_ztg3rH3TjWtpte4Vkkw9OnNXNAKRijUgHIpph6bIri48Zmj_9kNDarT2zdpPp04DaNBuWClLoW78v2xw2ZRwxK5jfNpOb0SloIwpiKZG2A01mHHKDqd08HbdiK3lpkQZ63SIK7bzi9efnfBt0CfuIksvkWH1zqnsZmEWOu9HY4BpnZbd3cDlJqtHtbs809sCCIgyttsSGH9bfC8TLqxCs Oct 29 06:34:10 volumio volumio[24870]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Oct 29 06:34:10 volumio volumio[24870]: info: New Spotify access token = BQCd1bIHjSNceCW2qJtbJCEgx1BV1VFUryaD1HFTH5RqcCVDk0AkgyhaGmWhdTI8bP6zBo6xk421Vmc3K-tWcEMeHDCju_ztg3rH3TjWtpte4Vkkw9OnNXNAKRijUgHIpph6bIri48Zmj_9kNDarT2zdpPp04DaNBuWClLoW78v2xw2ZRwxK5jfNpOb0SloIwpiKZG2A01mHHKDqd08HbdiK3lpkQZ63SIK7bzi9efnfBt0CfuIksvkWH1zqnsZmEWOu9HY4BpnZbd3cDlJqtHtbs809sCCIgyttsSGH9bfC8TLqxCs Oct 29 06:34:10 volumio volumio[24870]: info: Spotify credentials grant success - running version from March 24, 2019 Oct 29 06:34:10 volumio volumio[24870]: info: CoreCommandRouter::volumioGetState Oct 29 06:34:10 volumio volumio[24870]: info: CorePlayQueue::getTrack 0 Oct 29 06:34:10 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Oct 29 06:34:10 volumio sudo[25078]: pam_unix(sudo:session): session closed for user root Oct 29 06:34:10 volumio sudo[25076]: pam_unix(sudo:session): session closed for user root Oct 29 06:34:10 volumio sudo[25080]: pam_unix(sudo:session): session closed for user root Oct 29 06:34:10 volumio go-librespot[25063]: time="2025-10-29T06:34:10Z" 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 29 06:34:10 volumio go-librespot[25063]: time="2025-10-29T06:34:10Z" 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 29 06:34:10 volumio go-librespot[25063]: time="2025-10-29T06:34:10Z" 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 29 06:34:10 volumio go-librespot[25063]: time="2025-10-29T06:34:10Z" level=info msg="zeroconf server listening on port 37801" Oct 29 06:34:10 volumio volumio[24870]: info: Shairport-Sync Started Oct 29 06:34:10 volumio volumio[24870]: Error adding Membership: Error: addMembership EINVAL Oct 29 06:34:10 volumio volumio[24870]: info: Shairport-Sync Started Oct 29 06:34:10 volumio volumio[24870]: info: Shairport-Sync Started Oct 29 06:34:10 volumio mpd[25033]: 2025-10-29T06:34:10 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Oct 29 06:34:10 volumio systemd[1]: Started mpd.service - Music Player Daemon. Oct 29 06:34:10 volumio sudo[24994]: pam_unix(sudo:session): session closed for user root Oct 29 06:34:10 volumio sudo[25004]: pam_unix(sudo:session): session closed for user root Oct 29 06:34:10 volumio go-librespot[25063]: time="2025-10-29T06:34:10Z" level=debug msg="obtained new client token: AADTLydO+Wv2GjSsPjhkRSb14DG4pkeUSMROgNE8YpP8jER6hll/06U5Q6Ar2vLSiG/WehJemwW+/UosRlEGPg7huZDUuGv6oCpqj9cP2zCsbst5jeu/+eKT/dopmV8uwo+6Hj9UFVFS8wtXKGMqjAj4zN9ozR+5KH93mfegvkC1yJyDt1KK7ZC5eUTaWij6G4pfIImD1Qd5KLlVnFhib4GmEp5Q0X6tppGgh52rwe6XkeM1wTHPlZ4=" Oct 29 06:34:10 volumio volumio[24870]: error: MPD error: The expression evaluated to a falsy value: Oct 29 06:34:10 volumio volumio[24870]: assert.ok(self.idling) Oct 29 06:34:10 volumio volumio[24870]: error: The expression evaluated to a falsy value: Oct 29 06:34:10 volumio volumio[24870]: assert.ok(self.idling) Oct 29 06:34:10 volumio volumio[24870]: info: MPD running with PID25033 Oct 29 06:34:10 volumio volumio[24870]: ,establishing connection Oct 29 06:34:10 volumio volumio[24870]: error: updateQueue error: null Oct 29 06:34:10 volumio volumio[24870]: error: updateQueue error: null Oct 29 06:34:10 volumio go-librespot[25063]: time="2025-10-29T06:34:10Z" 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 29 06:34:10 volumio go-librespot[25063]: time="2025-10-29T06:34:10Z" level=debug msg="connected to ap-gew1.spotify.com:443" Oct 29 06:34:10 volumio volumio[24870]: 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 29 06:34:10 volumio volumio[24870]: info: Spotify Successfully logged in Oct 29 06:34:10 volumio volumio[24870]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 29 06:34:10 volumio volumio[24870]: info: [1761719650849] CoreMusicLibrary::Adding element Spotify Oct 29 06:34:10 volumio volumio[24870]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 29 06:34:10 volumio volumio[24870]: Cannot find translation for source Spotify Oct 29 06:34:10 volumio go-librespot[25063]: time="2025-10-29T06:34:10Z" level=debug msg="completed keyexchange" Oct 29 06:34:10 volumio go-librespot[25063]: time="2025-10-29T06:34:10Z" level=debug msg="completed challenge" Oct 29 06:34:10 volumio go-librespot[25063]: time="2025-10-29T06:34:10Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 29 06:34:10 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 29 06:34:10 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 29 06:34:11 volumio volumio[24870]: info: [yt-cast-receiver] DIAL server listening on port 8098 Oct 29 06:34:11 volumio volumio[24870]: info: CoreCommandRouter::volumioRetrievevolume Oct 29 06:34:11 volumio volumio[24870]: info: VolumeController:: Volume=33 Mute =false Oct 29 06:34:11 volumio volumio[24870]: info: CoreCommandRouter::volumioGetState Oct 29 06:34:11 volumio volumio[24870]: info: CorePlayQueue::getTrack 0 Oct 29 06:34:11 volumio volumio[24870]: info: CoreStateMachine::pushState Oct 29 06:34:11 volumio volumio[24870]: info: CorePlayQueue::getTrack 0 Oct 29 06:34:11 volumio volumio[24870]: info: CoreCommandRouter::volumioPushState Oct 29 06:34:11 volumio volumio[24870]: info: Completed starting Core Plugins Oct 29 06:34:11 volumio volumio[24870]: info: ------------------------------------------- Oct 29 06:34:11 volumio volumio[24870]: info: ----- MyVolumio plugins startup ---- Oct 29 06:34:11 volumio volumio[24870]: info: ------------------------------------------- Oct 29 06:34:11 volumio volumio[24870]: info: [MyVolumio PluginManager] Fetching plans data.... Oct 29 06:34:12 volumio volumio-remote-updater[874]: [2025-10-29 06:34:12] [connect] Successful connection Oct 29 06:34:12 volumio volumio-remote-updater[874]: [2025-10-29 06:34:12] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1761719652 101 Oct 29 06:34:12 volumio volumio[24870]: 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 29 06:34:13 volumio volumio[24870]: info: Cannot mount NAS NAS at system boot, trial number 2 ,retrying in 5 seconds Oct 29 06:34:13 volumio volumio[24870]: info: go-librespot daemon successfully initialized Oct 29 06:34:13 volumio sudo[25109]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Oct 29 06:34:13 volumio sudo[25109]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 29 06:34:13 volumio sudo[25111]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Oct 29 06:34:13 volumio sudo[25111]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 29 06:34:13 volumio systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Oct 29 06:34:13 volumio systemd[1]: mpd_monitor.service: Deactivated successfully. Oct 29 06:34:13 volumio systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Oct 29 06:34:13 volumio systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Oct 29 06:34:13 volumio sudo[25109]: pam_unix(sudo:session): session closed for user root Oct 29 06:34:13 volumio mpd_monitor.sh[25114]: MPD Monitor Service: Starting MPD Monitor Service Oct 29 06:34:13 volumio sudo[25111]: pam_unix(sudo:session): session closed for user root Oct 29 06:34:13 volumio volumio[24870]: info: Successfully started MPD Monitor Oct 29 06:34:13 volumio volumio[24870]: info: Successfully started MPD Monitor Oct 29 06:34:14 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 171. Oct 29 06:34:14 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 29 06:34:14 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 29 06:34:14 volumio go-librespot[25118]: go-librespot daemon starting... Oct 29 06:34:14 volumio go-librespot[25119]: time="2025-10-29T06:34:14Z" level=info msg="running go-librespot 0.4.0" Oct 29 06:34:14 volumio go-librespot[25119]: time="2025-10-29T06:34:14Z" level=debug msg="app state loaded" Oct 29 06:34:14 volumio go-librespot[25119]: time="2025-10-29T06:34:14Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 29 06:34:14 volumio go-librespot[25119]: time="2025-10-29T06:34:14Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Oct 29 06:34:14 volumio go-librespot[25119]: time="2025-10-29T06:34:14Z" 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 29 06:34:14 volumio go-librespot[25119]: time="2025-10-29T06:34:14Z" 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 29 06:34:14 volumio go-librespot[25119]: time="2025-10-29T06:34:14Z" level=info msg="zeroconf server listening on port 39677" Oct 29 06:34:14 volumio go-librespot[25119]: time="2025-10-29T06:34:14Z" level=debug msg="obtained new client token: AABkWETnrB1F9c9ixt6VL6RGyf+PDhtmm20Z3PhkXHVquKAyA2yVw6vbg+RVgZAWcfLMJhRb8/FL3D9PIJAtusMGmd101laLKzoxajZuf2e2LYqpzFNwl/KKDxOi254Tee9yxpi4hNwtxMp4EN/4+xCSIrDpPhjicqPIyGeH84Q29vEEPLyGEu3oekeQvdPLfqh9gJ6tlPJQ5D3yF8WBsUNYNvxtL3tLNugTagE5k50VQO0COIa6" Oct 29 06:34:14 volumio go-librespot[25119]: time="2025-10-29T06:34:14Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 29 06:34:14 volumio go-librespot[25119]: time="2025-10-29T06:34:14Z" level=debug msg="completed keyexchange" Oct 29 06:34:14 volumio go-librespot[25119]: time="2025-10-29T06:34:14Z" level=debug msg="completed challenge" Oct 29 06:34:14 volumio go-librespot[25119]: time="2025-10-29T06:34:14Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 29 06:34:14 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 29 06:34:14 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 29 06:34:15 volumio volumio[24870]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Oct 29 06:34:16 volumio volumio[24870]: info: Initializing connection to go-librespot Websocket Oct 29 06:34:16 volumio volumio[24870]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 29 06:34:16 volumio kernel: nfs: server 192.168.1.3 not responding, timed out Oct 29 06:34:17 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 172. Oct 29 06:34:17 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 29 06:34:17 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 29 06:34:17 volumio go-librespot[25126]: go-librespot daemon starting... Oct 29 06:34:17 volumio go-librespot[25127]: time="2025-10-29T06:34:17Z" level=info msg="running go-librespot 0.4.0" Oct 29 06:34:17 volumio go-librespot[25127]: time="2025-10-29T06:34:17Z" level=debug msg="app state loaded" Oct 29 06:34:17 volumio go-librespot[25127]: time="2025-10-29T06:34:17Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 29 06:34:17 volumio go-librespot[25127]: time="2025-10-29T06:34:17Z" 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 29 06:34:17 volumio go-librespot[25127]: time="2025-10-29T06:34:17Z" 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 29 06:34:17 volumio go-librespot[25127]: time="2025-10-29T06:34:17Z" 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 29 06:34:17 volumio go-librespot[25127]: time="2025-10-29T06:34:17Z" level=info msg="zeroconf server listening on port 44669" Oct 29 06:34:17 volumio go-librespot[25127]: time="2025-10-29T06:34:17Z" level=debug msg="obtained new client token: AAAtjMhn9zEShP5+os0cqNt9wQoAdXPWcvMaFu4Vu2LuRB4saO0ke0kOxZpS0FUTPzzqyL6cuoYgBj5OmiJQlofVeMKWd+xl7nEcyvBunC7vqYHISMJIAB5sSFCMiLN2+P2iRclR1F+D8tyurIV834Sm1z2hRY8OUEmtZJeQVu5GcVn42rQpGr6e+TMbpyJbxpzfL4YeIn3QqG7HINlLUxp227RRU/mt0MNcmRZbHyudn7C5+QMcFhQ=" Oct 29 06:34:17 volumio go-librespot[25127]: time="2025-10-29T06:34:17Z" 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 29 06:34:17 volumio go-librespot[25127]: time="2025-10-29T06:34:17Z" level=debug msg="connected to ap-gew1.spotify.com:443" Oct 29 06:34:17 volumio go-librespot[25127]: time="2025-10-29T06:34:17Z" level=debug msg="completed keyexchange" Oct 29 06:34:17 volumio go-librespot[25127]: time="2025-10-29T06:34:17Z" level=debug msg="completed challenge" Oct 29 06:34:17 volumio go-librespot[25127]: time="2025-10-29T06:34:17Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 29 06:34:17 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 29 06:34:17 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 29 06:34:18 volumio volumio[24870]: info: Cannot mount NAS NAS at system boot, trial number 3 ,retrying in 5 seconds Oct 29 06:34:18 volumio sudo[25149]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 29 06:34:18 volumio sudo[25149]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 29 06:34:18 volumio sudo[25151]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 29 06:34:18 volumio sudo[25151]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 29 06:34:18 volumio sudo[25149]: pam_unix(sudo:session): session closed for user root Oct 29 06:34:18 volumio sudo[25151]: pam_unix(sudo:session): session closed for user root Oct 29 06:34:18 volumio sudo[25155]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Oct 29 06:34:18 volumio sudo[25155]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 29 06:34:18 volumio sudo[25155]: pam_unix(sudo:session): session closed for user root Oct 29 06:34:18 volumio volumio[24870]: info: Upmpdcli Daemon Started Oct 29 06:34:19 volumio volumio[24870]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Oct 29 06:34:19 volumio volumio[24870]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Oct 29 06:34:19 volumio volumio[24870]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Oct 29 06:34:19 volumio volumio[24870]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Oct 29 06:34:19 volumio volumio[24870]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Oct 29 06:34:19 volumio volumio[24870]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Oct 29 06:34:19 volumio volumio[24870]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Oct 29 06:34:19 volumio volumio[24870]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Oct 29 06:34:19 volumio volumio[24870]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Oct 29 06:34:19 volumio volumio[24870]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Oct 29 06:34:19 volumio volumio[24870]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Oct 29 06:34:19 volumio volumio[24870]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Oct 29 06:34:19 volumio volumio[24870]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Oct 29 06:34:19 volumio volumio[24870]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Oct 29 06:34:19 volumio volumio[24870]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Oct 29 06:34:19 volumio volumio[24870]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Oct 29 06:34:19 volumio volumio[24870]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Oct 29 06:34:19 volumio volumio[24870]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Oct 29 06:34:19 volumio volumio[24870]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Oct 29 06:34:19 volumio volumio[24870]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Oct 29 06:34:19 volumio volumio[24870]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Oct 29 06:34:19 volumio volumio[24870]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Oct 29 06:34:19 volumio volumio[24870]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Oct 29 06:34:19 volumio volumio[24870]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Oct 29 06:34:19 volumio volumio[24870]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Oct 29 06:34:19 volumio volumio[24870]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Oct 29 06:34:19 volumio volumio[24870]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Oct 29 06:34:19 volumio volumio[24870]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Oct 29 06:34:19 volumio volumio[24870]: info: Adding plugin bluetooth to MyMusic Plugins Oct 29 06:34:19 volumio volumio[24870]: info: Adding plugin multiroom to MyMusic Plugins Oct 29 06:34:19 volumio volumio[24870]: info: Adding plugin metavolumio to MyMusic Plugins Oct 29 06:34:19 volumio volumio[24870]: info: Adding plugin cd_controller to MyMusic Plugins Oct 29 06:34:19 volumio volumio[24870]: info: Adding plugin qobuzconnect to MyMusic Plugins Oct 29 06:34:19 volumio volumio[24870]: info: Adding plugin smart_inputs to MyMusic Plugins Oct 29 06:34:19 volumio volumio[24870]: info: Adding plugin tidalconnect to MyMusic Plugins Oct 29 06:34:19 volumio volumio[24870]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Oct 29 06:34:19 volumio volumio[24870]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Oct 29 06:34:19 volumio volumio[24870]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Oct 29 06:34:19 volumio volumio[24870]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 29 06:34:19 volumio volumio[24870]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 29 06:34:19 volumio volumio[24870]: info: Starting MyVolumio Remote Streaming Endpoints Oct 29 06:34:19 volumio volumio[24870]: info: MyVolumio login type: Token Oct 29 06:34:19 volumio volumio[24870]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Oct 29 06:34:19 volumio volumio[24870]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Oct 29 06:34:19 volumio volumio[24870]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Oct 29 06:34:19 volumio volumio[24870]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Oct 29 06:34:19 volumio volumio[24870]: info: Streaming services startup Oct 29 06:34:19 volumio volumio[24870]: info: Starting Streaming Daemon Oct 29 06:34:19 volumio sudo[25158]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Oct 29 06:34:19 volumio sudo[25158]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 29 06:34:19 volumio volumio[24870]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Oct 29 06:34:19 volumio sudo[25158]: pam_unix(sudo:session): session closed for user root Oct 29 06:34:19 volumio volumio[24870]: info: Initializing connection to go-librespot Websocket Oct 29 06:34:19 volumio volumio[24870]: error: Cannot start Volumio Streaming Daemon Oct 29 06:34:19 volumio volumio[24870]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Oct 29 06:34:19 volumio volumio[24870]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Oct 29 06:34:19 volumio volumio[24870]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 29 06:34:20 volumio volumio[24870]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Oct 29 06:34:20 volumio volumio[24870]: info: MyVolumio token set successfully Oct 29 06:34:20 volumio volumio[24870]: info: MYVOLUMIO: Adding device Oct 29 06:34:20 volumio volumio[24870]: info: MYVOLUMIO: Evaluating Server Oct 29 06:34:20 volumio volumio[24870]: info: MyVolumio status changed Oct 29 06:34:20 volumio volumio[24870]: info: Streaming services startup Oct 29 06:34:20 volumio volumio[24870]: info: Starting Streaming Daemon Oct 29 06:34:20 volumio volumio[24870]: info: Removing browser output: myVolumio user plan is not superstar Oct 29 06:34:20 volumio volumio[24870]: info: Removing audio output: Oct 29 06:34:20 volumio volumio[24870]: info: Stoppping Tunnel 1 Oct 29 06:34:20 volumio sudo[25183]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Oct 29 06:34:20 volumio sudo[25183]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 29 06:34:20 volumio sudo[25185]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service Oct 29 06:34:20 volumio sudo[25185]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 29 06:34:20 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 173. Oct 29 06:34:20 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 29 06:34:20 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 29 06:34:20 volumio go-librespot[25188]: go-librespot daemon starting... Oct 29 06:34:20 volumio sudo[25183]: pam_unix(sudo:session): session closed for user root Oct 29 06:34:20 volumio volumio[24870]: error: Cannot start Volumio Streaming Daemon Oct 29 06:34:20 volumio volumio[24870]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Oct 29 06:34:20 volumio volumio[24870]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Oct 29 06:34:20 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 29 06:34:20 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 29 06:34:20 volumio go-librespot[25189]: time="2025-10-29T06:34:20Z" level=info msg="running go-librespot 0.4.0" Oct 29 06:34:20 volumio go-librespot[25189]: time="2025-10-29T06:34:20Z" level=debug msg="app state loaded" Oct 29 06:34:20 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 29 06:34:20 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 29 06:34:20 volumio go-librespot[25189]: time="2025-10-29T06:34:20Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 29 06:34:20 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 29 06:34:20 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 29 06:34:20 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 29 06:34:20 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 29 06:34:20 volumio sudo[25185]: pam_unix(sudo:session): session closed for user root Oct 29 06:34:20 volumio volumio[24870]: info: Remote SSH Stopped Oct 29 06:34:20 volumio go-librespot[25189]: time="2025-10-29T06:34:20Z" 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 29 06:34:20 volumio go-librespot[25189]: time="2025-10-29T06:34:20Z" 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 29 06:34:20 volumio go-librespot[25189]: time="2025-10-29T06:34:20Z" 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 29 06:34:20 volumio go-librespot[25189]: time="2025-10-29T06:34:20Z" level=info msg="zeroconf server listening on port 39319" Oct 29 06:34:21 volumio go-librespot[25189]: time="2025-10-29T06:34:21Z" level=debug msg="obtained new client token: AACoR2ik++0MDhLAwm5nRXDonUrd/GfQwTfAvfsKoO45BBzwSwbhrdR8SFV+0jAXxDyqiv8nih4Uve3LKxInVYj7sCJNphqvdE/zLnP1N7PSzoTEB2SrAM9qJxze+EMU0hsSMDWytvTbrRWGEoAJMI8P6WypIQiif3sBK/5pCXWc7YoeNLNhECajWw4ewtoFyMYQq6A5RKuUQK0Yij+0SXklONrNiWLMd2176Uut3KXSFBsyV8nA" Oct 29 06:34:21 volumio go-librespot[25189]: time="2025-10-29T06:34:21Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 29 06:34:21 volumio go-librespot[25189]: time="2025-10-29T06:34:21Z" level=debug msg="completed keyexchange" Oct 29 06:34:21 volumio go-librespot[25189]: time="2025-10-29T06:34:21Z" level=debug msg="completed challenge" Oct 29 06:34:21 volumio go-librespot[25189]: time="2025-10-29T06:34:21Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 29 06:34:21 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 29 06:34:21 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 29 06:34:22 volumio volumio[24870]: info: Setting Geolocation for MyVolumio to eu3 Oct 29 06:34:22 volumio volumio[24870]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 29 06:34:22 volumio volumio[24870]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 29 06:34:22 volumio volumio[24870]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 29 06:34:22 volumio volumio[24870]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Oct 29 06:34:22 volumio volumio[24870]: info: Initializing connection to go-librespot Websocket Oct 29 06:34:22 volumio volumio[24870]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 29 06:34:23 volumio volumio[24870]: info: Updating MyVolumio device info Oct 29 06:34:23 volumio volumio[24870]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 29 06:34:23 volumio volumio[24870]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 29 06:34:23 volumio volumio[24870]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 29 06:34:23 volumio volumio[24870]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Oct 29 06:34:23 volumio volumio[24870]: info: Cannot mount NAS NAS at system boot, trial number 4 ,retrying in 5 seconds Oct 29 06:34:24 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 174. Oct 29 06:34:24 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 29 06:34:24 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 29 06:34:24 volumio go-librespot[25197]: go-librespot daemon starting... Oct 29 06:34:24 volumio go-librespot[25198]: time="2025-10-29T06:34:24Z" level=info msg="running go-librespot 0.4.0" Oct 29 06:34:24 volumio go-librespot[25198]: time="2025-10-29T06:34:24Z" level=debug msg="app state loaded" Oct 29 06:34:24 volumio go-librespot[25198]: time="2025-10-29T06:34:24Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 29 06:34:24 volumio go-librespot[25198]: time="2025-10-29T06:34:24Z" 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 29 06:34:24 volumio go-librespot[25198]: time="2025-10-29T06:34:24Z" 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 29 06:34:24 volumio go-librespot[25198]: time="2025-10-29T06:34:24Z" 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 29 06:34:24 volumio go-librespot[25198]: time="2025-10-29T06:34:24Z" level=info msg="zeroconf server listening on port 36009" Oct 29 06:34:24 volumio go-librespot[25198]: time="2025-10-29T06:34:24Z" level=debug msg="obtained new client token: AAB6G/fJ9hM6upfxEpPkKg9MyW/ZUQt9lFYKEdKprJoXoyGBIvu+WzpxH1sGz46YaqLskn1r/5JPm4OqETTDPCuQeufkO3an8nQO0l47ApC1sNWnArVSsf8/HdVIbI6owen24zOeGxsSc9z+AFC617V2RmYattDWLv9bGYfxaBOGLNc4PX2PpVJ3E70FAmexjVmQnJ/wqogkjq2eZo/W6fv9pjYlug1fbGE/gVJHJ1S7qV3J7griiEQ=" Oct 29 06:34:24 volumio go-librespot[25198]: time="2025-10-29T06:34:24Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 29 06:34:24 volumio go-librespot[25198]: time="2025-10-29T06:34:24Z" level=debug msg="completed keyexchange" Oct 29 06:34:24 volumio go-librespot[25198]: time="2025-10-29T06:34:24Z" level=debug msg="completed challenge" Oct 29 06:34:24 volumio go-librespot[25198]: time="2025-10-29T06:34:24Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 29 06:34:24 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 29 06:34:24 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 29 06:34:25 volumio volumio[24870]: info: Initializing connection to go-librespot Websocket Oct 29 06:34:25 volumio volumio[24870]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 29 06:34:26 volumio kernel: nfs: server 192.168.1.3 not responding, timed out Oct 29 06:34:26 volumio volumio[24870]: info: MYVOLUMIO: Adding device Oct 29 06:34:26 volumio volumio[24870]: info: MYVOLUMIO: Evaluating Server Oct 29 06:34:26 volumio volumio[24870]: info: Setting Geolocation for MyVolumio to eu3 Oct 29 06:34:26 volumio volumio[24870]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 29 06:34:26 volumio volumio[24870]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 29 06:34:26 volumio volumio[24870]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 29 06:34:26 volumio volumio[24870]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Oct 29 06:34:27 volumio volumio[24870]: info: Updating MyVolumio device info Oct 29 06:34:27 volumio volumio[24870]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 29 06:34:27 volumio volumio[24870]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 29 06:34:27 volumio volumio[24870]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 29 06:34:27 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 175. Oct 29 06:34:27 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 29 06:34:27 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 29 06:34:27 volumio go-librespot[25222]: go-librespot daemon starting... Oct 29 06:34:27 volumio go-librespot[25223]: time="2025-10-29T06:34:27Z" level=info msg="running go-librespot 0.4.0" Oct 29 06:34:27 volumio go-librespot[25223]: time="2025-10-29T06:34:27Z" level=debug msg="app state loaded" Oct 29 06:34:27 volumio go-librespot[25223]: time="2025-10-29T06:34:27Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 29 06:34:27 volumio go-librespot[25223]: time="2025-10-29T06:34:27Z" 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 29 06:34:27 volumio go-librespot[25223]: time="2025-10-29T06:34:27Z" 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 29 06:34:27 volumio go-librespot[25223]: time="2025-10-29T06:34:27Z" 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 29 06:34:27 volumio go-librespot[25223]: time="2025-10-29T06:34:27Z" level=info msg="zeroconf server listening on port 40055" Oct 29 06:34:27 volumio go-librespot[25223]: time="2025-10-29T06:34:27Z" level=debug msg="obtained new client token: AADD09MjfI5uLWEwGSdHY3JL4QQlTuRFLSj7lctup4NEJTK8rxAxHIKQh8n4cbTWTHW1NcSoTvFGsPCvvTVQvTCzNPpSNbzJgPciLy3F6aPsXD4xZVgbEpEbFljn2QBWxE8c57BFzHQIc1k9UWZKPY22D+dFAZ5EZOf52epf2XN7djV730tpnchet9FJVxCHF3/zPBpL8NVWWGSheL4Jo97v0Vk6YOsFZl2oKVShC3ODKWpG60VG1RQ=" Oct 29 06:34:27 volumio go-librespot[25223]: time="2025-10-29T06:34:27Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 29 06:34:27 volumio volumio[24870]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Oct 29 06:34:27 volumio go-librespot[25223]: time="2025-10-29T06:34:27Z" level=debug msg="completed keyexchange" Oct 29 06:34:27 volumio go-librespot[25223]: time="2025-10-29T06:34:27Z" level=debug msg="completed challenge" Oct 29 06:34:28 volumio go-librespot[25223]: time="2025-10-29T06:34:28Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 29 06:34:28 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 29 06:34:28 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 29 06:34:28 volumio volumio[24870]: info: Cannot mount NAS at system boot, trial number 4 ,stopping Oct 29 06:34:28 volumio volumio[24870]: info: Initializing connection to go-librespot Websocket Oct 29 06:34:28 volumio volumio[24870]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 29 06:34:31 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 176. Oct 29 06:34:31 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 29 06:34:31 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 29 06:34:31 volumio go-librespot[25245]: go-librespot daemon starting... Oct 29 06:34:31 volumio go-librespot[25246]: time="2025-10-29T06:34:31Z" level=info msg="running go-librespot 0.4.0" Oct 29 06:34:31 volumio go-librespot[25246]: time="2025-10-29T06:34:31Z" level=debug msg="app state loaded" Oct 29 06:34:31 volumio go-librespot[25246]: time="2025-10-29T06:34:31Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 29 06:34:31 volumio go-librespot[25246]: time="2025-10-29T06:34:31Z" 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 29 06:34:31 volumio go-librespot[25246]: time="2025-10-29T06:34:31Z" 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 29 06:34:31 volumio go-librespot[25246]: time="2025-10-29T06:34:31Z" 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 29 06:34:31 volumio go-librespot[25246]: time="2025-10-29T06:34:31Z" level=info msg="zeroconf server listening on port 34523" Oct 29 06:34:31 volumio go-librespot[25246]: time="2025-10-29T06:34:31Z" level=debug msg="obtained new client token: AAAbRw27SDrP6f8TwbCS72y0jDPtx/PAYMdcY4aUynUynhhCJeQBfeV8OM+Xux9y/3n8NyRQvBPndKYVQ5ohm4ST5ZTDDcEiR52vSsANipZV3pXBSjI6d9k0hBy61xUgsBscUD3pFbwLgIBKmmmm0YkL+ext9yFMUYTQ24h67WNXBInBR+4hsGw+jrXFIgJlFiLmGJjc8hW2lSEiOj8CUjqncaHAHQg83fekqKGulVUTvra+0KMkAU8=" Oct 29 06:34:31 volumio go-librespot[25246]: time="2025-10-29T06:34:31Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 29 06:34:31 volumio go-librespot[25246]: time="2025-10-29T06:34:31Z" level=debug msg="completed keyexchange" Oct 29 06:34:31 volumio go-librespot[25246]: time="2025-10-29T06:34:31Z" level=debug msg="completed challenge" Oct 29 06:34:31 volumio go-librespot[25246]: time="2025-10-29T06:34:31Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 29 06:34:31 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 29 06:34:31 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 29 06:34:31 volumio volumio[24870]: info: Initializing connection to go-librespot Websocket Oct 29 06:34:31 volumio volumio[24870]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 29 06:34:34 volumio volumio[24870]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Oct 29 06:34:34 volumio volumio[24870]: 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 29 06:34:34 volumio volumio[24870]: info: CoreCommandRouter::volumioGetState Oct 29 06:34:34 volumio volumio[24870]: info: CorePlayQueue::getTrack 0 Oct 29 06:34:34 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 177. Oct 29 06:34:34 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 29 06:34:34 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 29 06:34:34 volumio go-librespot[25256]: go-librespot daemon starting... Oct 29 06:34:34 volumio go-librespot[25257]: time="2025-10-29T06:34:34Z" level=info msg="running go-librespot 0.4.0" Oct 29 06:34:34 volumio go-librespot[25257]: time="2025-10-29T06:34:34Z" level=debug msg="app state loaded" Oct 29 06:34:34 volumio go-librespot[25257]: time="2025-10-29T06:34:34Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 29 06:34:34 volumio go-librespot[25257]: time="2025-10-29T06:34:34Z" 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 29 06:34:34 volumio go-librespot[25257]: time="2025-10-29T06:34:34Z" 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 29 06:34:34 volumio go-librespot[25257]: time="2025-10-29T06:34:34Z" 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 29 06:34:34 volumio go-librespot[25257]: time="2025-10-29T06:34:34Z" level=info msg="zeroconf server listening on port 37397" Oct 29 06:34:34 volumio volumio[24870]: info: Initializing connection to go-librespot Websocket Oct 29 06:34:34 volumio go-librespot[25257]: time="2025-10-29T06:34:34Z" level=debug msg="new websocket client" Oct 29 06:34:34 volumio volumio[24870]: info: Connection to go-librespot Websocket established Oct 29 06:34:34 volumio go-librespot[25257]: time="2025-10-29T06:34:34Z" level=debug msg="obtained new client token: AADOSmICiPgsCcx+1IM5fTHYFie3l6G5beFMqfupCuozFziZKz0kX1Nu+kQLyET0FibFkk1MuQMWKWR4XwOqVbCBKsHov1DODoL2p/5PupaESCeAb5aFccpdCDH65Y/OPD7xNVA7UuuBUMiRM0zHQveKXysGj3wkmRfkaLoXvcbnZ7G3KZPjYQ4AohzF57C4gwA3ArhLRUZy5b1fr2qedT+JPZL4WszNVK0EU05P54FiobhihcUgtXo=" Oct 29 06:34:34 volumio go-librespot[25257]: time="2025-10-29T06:34:34Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 29 06:34:35 volumio go-librespot[25257]: time="2025-10-29T06:34:35Z" level=debug msg="completed keyexchange" Oct 29 06:34:35 volumio go-librespot[25257]: time="2025-10-29T06:34:35Z" level=debug msg="completed challenge" Oct 29 06:34:35 volumio go-librespot[25257]: time="2025-10-29T06:34:35Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 29 06:34:35 volumio volumio[24870]: info: Connection to go-librespot Websocket closed Oct 29 06:34:35 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 29 06:34:35 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 29 06:34:37 volumio volumio[24870]: info: Getting Spotify volume Oct 29 06:34:37 volumio volumio[24870]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 29 06:34:37 volumio volumio[24870]: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 29 06:34:37 volumio volumio[24870]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Oct 29 06:34:37 volumio volumio[24870]: errno: -111, Oct 29 06:34:37 volumio volumio[24870]: code: 'ECONNREFUSED', Oct 29 06:34:37 volumio volumio[24870]: syscall: 'connect', Oct 29 06:34:37 volumio volumio[24870]: address: '127.0.0.1', Oct 29 06:34:37 volumio volumio[24870]: port: 9879, Oct 29 06:34:37 volumio volumio[24870]: response: undefined Oct 29 06:34:37 volumio volumio[24870]: } Oct 29 06:34:37 volumio volumio[24870]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 29 06:34:38 volumio sudo[25278]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-10-29 06:33' Oct 29 06:34:38 volumio sudo[25278]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 29 06:34:38 volumio sudo[25278]: pam_unix(sudo:session): session closed for user root Oct 29 06:34:38 volumio volumio-remote-updater[874]: [2025-10-29 06:34:38] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Oct 29 06:34:38 volumio volumio-remote-updater[874]: [2025-10-29 06:34:38] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Oct 29 06:34:38 volumio systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Oct 29 06:34:38 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 178. Oct 29 06:34:38 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 29 06:34:38 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 29 06:34:38 volumio go-librespot[25289]: go-librespot daemon starting... Oct 29 06:34:38 volumio systemd[1]: volumio.service: Failed with result 'exit-code'. Oct 29 06:34:38 volumio systemd[1]: volumio.service: Consumed 7.506s CPU time. Oct 29 06:34:38 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Oct 29 06:34:38 volumio go-librespot[25290]: time="2025-10-29T06:34:38Z" level=info msg="running go-librespot 0.4.0" Oct 29 06:34:38 volumio go-librespot[25290]: time="2025-10-29T06:34:38Z" level=debug msg="app state loaded" Oct 29 06:34:38 volumio go-librespot[25290]: time="2025-10-29T06:34:38Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 29 06:34:38 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Oct 29 06:34:38 volumio go-librespot[25290]: time="2025-10-29T06:34:38Z" 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 29 06:34:38 volumio go-librespot[25290]: time="2025-10-29T06:34:38Z" 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 29 06:34:38 volumio go-librespot[25290]: time="2025-10-29T06:34:38Z" 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 29 06:34:38 volumio go-librespot[25290]: time="2025-10-29T06:34:38Z" level=info msg="zeroconf server listening on port 36447" Oct 29 06:34:38 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 2025. Oct 29 06:34:38 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Oct 29 06:34:38 volumio systemd[1]: Stopped volumio.service - Volumio Backend Module. Oct 29 06:34:38 volumio systemd[1]: volumio.service: Consumed 7.506s CPU time. Oct 29 06:34:38 volumio systemd[1]: Started volumio.service - Volumio Backend Module. Oct 29 06:34:38 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Oct 29 06:34:38 volumio go-librespot[25290]: time="2025-10-29T06:34:38Z" level=debug msg="obtained new client token: AABHqaJVUwF3/smUmkNbgMM7zfaDtIreNdiYAD1YR+vdnBt05hsNqk8CDEb+mEN1e47sKpLjhrmRzB9OHBjAX+VfCDiHXbDrgCMAjVJNTgvo3WBLChudD1372N6VHSlhfUC7OGRAWWL6iRXC+fl14z5KhEPJvipkBgC1uKFVuBFSRKZLVd1tS3GugFOoJ5hPZw+giNepGkjZxtUdWueZ5nj+z1297kTWYvpPSKA1IOYv0ULSyRNfmpQ=" Oct 29 06:34:38 volumio go-librespot[25290]: time="2025-10-29T06:34:38Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 29 06:34:38 volumio go-librespot[25290]: time="2025-10-29T06:34:38Z" level=debug msg="completed keyexchange" Oct 29 06:34:38 volumio go-librespot[25290]: time="2025-10-29T06:34:38Z" level=debug msg="completed challenge" Oct 29 06:34:38 volumio go-librespot[25290]: time="2025-10-29T06:34:38Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 29 06:34:38 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 29 06:34:38 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 29 06:34:38 volumio volumio[25304]: info: ------------------------------------------- Oct 29 06:34:38 volumio volumio[25304]: info: ----- Volumio3 ---- Oct 29 06:34:38 volumio volumio[25304]: info: ------------------------------------------- Oct 29 06:34:38 volumio volumio[25304]: info: ----- System startup ---- Oct 29 06:34:38 volumio volumio[25304]: info: ------------------------------------------- Oct 29 06:34:38 volumio volumio[25304]: info: MYVOLUMIO Environment detected Oct 29 06:34:38 volumio volumio[25304]: info: Plugin folders cleanup Oct 29 06:34:38 volumio volumio[25304]: info: Scanning into folder /volumio/app/plugins/ Oct 29 06:34:38 volumio volumio[25304]: info: Scanning category audio_interface Oct 29 06:34:38 volumio volumio[25304]: info: Scanning category miscellanea Oct 29 06:34:38 volumio volumio[25304]: info: Scanning category music_service Oct 29 06:34:38 volumio volumio[25304]: info: Scanning category plugins.json Oct 29 06:34:38 volumio volumio[25304]: info: Scanning category system_controller Oct 29 06:34:38 volumio volumio[25304]: info: Scanning category user_interface Oct 29 06:34:38 volumio volumio[25304]: info: Scanning into folder /data/plugins/ Oct 29 06:34:38 volumio volumio[25304]: info: Scanning category music_service Oct 29 06:34:38 volumio volumio[25304]: info: Scanning category user_interface Oct 29 06:34:38 volumio volumio[25304]: info: Plugin folders cleanup completed Oct 29 06:34:38 volumio volumio[25304]: info: ------------------------------------------- Oct 29 06:34:38 volumio volumio[25304]: info: ----- Core plugins startup ---- Oct 29 06:34:38 volumio volumio[25304]: info: ------------------------------------------- Oct 29 06:34:38 volumio volumio[25304]: info: Loading plugins from folder /volumio/app/plugins/ Oct 29 06:34:38 volumio volumio[25304]: info: Adding plugin upnp to MyMusic Plugins Oct 29 06:34:38 volumio volumio[25304]: info: Adding plugin airplay_emulation to MyMusic Plugins Oct 29 06:34:38 volumio volumio[25304]: info: Adding plugin upnp_browser to MyMusic Plugins Oct 29 06:34:38 volumio volumio[25304]: info: Loading plugins from folder /data/plugins/ Oct 29 06:34:38 volumio volumio[25304]: info: Loading plugin "system"... Oct 29 06:34:38 volumio volumio[25304]: info: Loading plugin "appearance"... Oct 29 06:34:39 volumio volumio[25304]: info: Loading plugin "network"... Oct 29 06:34:39 volumio volumio[25304]: info: Refreshing Cached IP Addresses Oct 29 06:34:39 volumio sudo[25332]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 29 06:34:39 volumio sudo[25332]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 29 06:34:39 volumio volumio[25304]: info: Loading plugin "services"... Oct 29 06:34:39 volumio sudo[25332]: pam_unix(sudo:session): session closed for user root Oct 29 06:34:39 volumio volumio[25304]: info: Loading plugin "alsa_controller"... Oct 29 06:34:39 volumio sudo[25334]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 29 06:34:39 volumio sudo[25334]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 29 06:34:39 volumio sudo[25334]: pam_unix(sudo:session): session closed for user root Oct 29 06:34:39 volumio volumio[25304]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 29 06:34:39 volumio volumio[25304]: info: Loading plugin "wizard"... Oct 29 06:34:39 volumio volumio[25304]: info: Loading plugin "networkfs"... Oct 29 06:34:39 volumio volumio[25304]: info: Cannot mount NAS NAS at system boot, trial number 1 ,retrying in 5 seconds Oct 29 06:34:39 volumio volumio[25304]: info: Starting Udev Watcher for removable devices Oct 29 06:34:39 volumio volumio[25304]: info: Ignoring mount for partition: boot Oct 29 06:34:39 volumio volumio[25304]: info: Ignoring mount for partition: volumio Oct 29 06:34:39 volumio volumio[25304]: info: Ignoring mount for partition: volumio_data Oct 29 06:34:39 volumio volumio[25304]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 29 06:34:39 volumio volumio[25304]: info: Loading plugin "volumio_command_line_client"... Oct 29 06:34:39 volumio volumio[25304]: info: Loading plugin "upnp"... Oct 29 06:34:39 volumio volumio[25304]: info: [1761719679060] Starting Upmpd Daemon Oct 29 06:34:39 volumio volumio[25304]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 29 06:34:39 volumio volumio[25304]: info: Loading plugin "my_music"... Oct 29 06:34:39 volumio volumio[25304]: info: Loading plugin "mpd"... Oct 29 06:34:39 volumio volumio[25304]: info: Loading plugin "upnp_browser"... Oct 29 06:34:39 volumio volumio[25304]: info: Loading plugin "alarm-clock"... Oct 29 06:34:39 volumio volumio[25304]: info: Loading plugin "airplay_emulation"... Oct 29 06:34:39 volumio volumio[25304]: info: Starting Shairport Sync Oct 29 06:34:39 volumio volumio[25304]: info: Loading plugin "last_100"... Oct 29 06:34:39 volumio volumio[25304]: info: Loading plugin "webradio"... Oct 29 06:34:39 volumio volumio[25304]: info: Loading plugin "i2s_dacs"... Oct 29 06:34:39 volumio volumio[25304]: info: I2S DAC not set, start Auto-detection Oct 29 06:34:39 volumio volumio[25304]: info: Loading plugin "volumiodiscovery"... Oct 29 06:34:39 volumio volumio[25304]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Oct 29 06:34:39 volumio volumio[25304]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 29 06:34:39 volumio volumio[25304]: *** WARNING *** For more information see Oct 29 06:34:39 volumio volumio[25304]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Oct 29 06:34:39 volumio volumio[25304]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 29 06:34:39 volumio volumio[25304]: *** WARNING *** For more information see Oct 29 06:34:39 volumio node[25304]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Oct 29 06:34:39 volumio node[25304]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 29 06:34:39 volumio node[25304]: *** WARNING *** For more information see Oct 29 06:34:39 volumio node[25304]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Oct 29 06:34:39 volumio node[25304]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 29 06:34:39 volumio node[25304]: *** WARNING *** For more information see Oct 29 06:34:39 volumio volumio[25304]: info: Applying required configuration parameters for plugin volumiodiscovery Oct 29 06:34:39 volumio volumio[25304]: info: Discovery: Started advertising with name: Volumio Oct 29 06:34:39 volumio volumio[25304]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 29 06:34:39 volumio volumio[25304]: info: Loading plugin "spop"... Oct 29 06:34:39 volumio volumio[25304]: info: Loading plugin "ytcr"... Oct 29 06:34:40 volumio volumio[25304]: info: Loading plugin "outputs"... Oct 29 06:34:40 volumio volumio[25304]: info: Loading plugin "albumart"... Oct 29 06:34:40 volumio volumio[25304]: info: Plugin example_plugin is not enabled Oct 29 06:34:40 volumio volumio[25304]: info: Loading plugin "inputs"... Oct 29 06:34:40 volumio volumio[25304]: info: Loading plugin "updater_comm"... Oct 29 06:34:40 volumio volumio[25304]: info: Plugin mpdemulation is not enabled Oct 29 06:34:40 volumio volumio[25304]: info: Loading plugin "rest_api"... Oct 29 06:34:40 volumio volumio[25304]: info: Loading plugin "websocket"... Oct 29 06:34:40 volumio volumio[25304]: info: Starting Socket.io Server version 1.7.4 Oct 29 06:34:40 volumio volumio[25304]: info: Loading plugin "Systeminfo"... Oct 29 06:34:40 volumio volumio[25304]: info: Loading i18n strings for locale en Oct 29 06:34:40 volumio volumio[25304]: Updating browse sources language Oct 29 06:34:40 volumio volumio[25304]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 29 06:34:40 volumio volumio[25364]: Forking 3 albumart workers Oct 29 06:34:40 volumio volumio[25304]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 29 06:34:40 volumio volumio[25304]: info: CoreCommandRouter::initPlayerControls Oct 29 06:34:40 volumio volumio[25304]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 29 06:34:40 volumio volumio[25304]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 29 06:34:40 volumio volumio[25304]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 29 06:34:40 volumio volumio[25304]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 29 06:34:40 volumio volumio[25304]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 29 06:34:40 volumio volumio[25304]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 29 06:34:40 volumio volumio[25304]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 29 06:34:40 volumio volumio[25304]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 29 06:34:40 volumio volumio[25304]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 29 06:34:40 volumio volumio[25304]: Express server listening on port 3000 Oct 29 06:34:40 volumio volumio[25304]: [Metrics] WebUI: 1s 937.51ms Oct 29 06:34:40 volumio volumio[25304]: info: CoreStateMachine::resetVolumioState Oct 29 06:34:40 volumio volumio[25304]: info: CoreStateMachine::getcurrentVolume Oct 29 06:34:40 volumio volumio[25304]: info: CoreCommandRouter::volumioRetrievevolume Oct 29 06:34:40 volumio volumio[25304]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 29 06:34:40 volumio volumio[25304]: info: Cannot read play queue from file Oct 29 06:34:40 volumio volumio[25304]: info: Volumio Network Manager: Network status updated: 1 Oct 29 06:34:40 volumio volumio[25304]: info: VolumeController:: Volume=33 Mute =false Oct 29 06:34:40 volumio volumio[25304]: info: CoreStateMachine::pushState Oct 29 06:34:40 volumio volumio[25304]: info: CorePlayQueue::getTrack 0 Oct 29 06:34:40 volumio volumio[25304]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 29 06:34:40 volumio volumio[25304]: info: CoreCommandRouter::volumioPushState Oct 29 06:34:40 volumio volumio[25304]: info: CoreStateMachine::updateTrackBlock Oct 29 06:34:40 volumio volumio[25304]: info: CorePlayQueue::getTrackBlock Oct 29 06:34:40 volumio volumio[25304]: info: CoreCommandRouter::volumioRetrievevolume Oct 29 06:34:40 volumio volumio[25304]: info: CoreStateMachine::setRepeat null single undefined Oct 29 06:34:40 volumio volumio[25304]: info: CoreStateMachine::pushState Oct 29 06:34:40 volumio volumio[25304]: info: CorePlayQueue::getTrack 0 Oct 29 06:34:40 volumio volumio[25304]: info: CoreCommandRouter::volumioPushState Oct 29 06:34:40 volumio volumio[25304]: info: CoreStateMachine::setRandom null Oct 29 06:34:40 volumio volumio[25304]: info: CoreStateMachine::pushState Oct 29 06:34:40 volumio volumio[25304]: info: CorePlayQueue::getTrack 0 Oct 29 06:34:40 volumio volumio[25304]: info: CoreCommandRouter::volumioPushState Oct 29 06:34:40 volumio volumio[25304]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Oct 29 06:34:40 volumio volumio[25304]: info: USB Boot Capable - System SBC Revision found in cpuinfo: b04170 Oct 29 06:34:40 volumio volumio[25304]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Oct 29 06:34:40 volumio volumio[25304]: info: VolumeController:: Volume=33 Mute =false Oct 29 06:34:40 volumio volumio[25304]: info: CoreStateMachine::pushState Oct 29 06:34:40 volumio volumio[25304]: info: CorePlayQueue::getTrack 0 Oct 29 06:34:40 volumio volumio[25304]: info: CoreCommandRouter::volumioPushState Oct 29 06:34:40 volumio volumio[25304]: info: Discovery: adding 70853f74-8210-4683-a3fa-e1217517bd40 Oct 29 06:34:40 volumio volumio[25304]: info: Discovery: Found device Volumio Oct 29 06:34:40 volumio volumio[25304]: info: CoreCommandRouter::volumioGetState Oct 29 06:34:40 volumio volumio[25304]: info: CorePlayQueue::getTrack 0 Oct 29 06:34:40 volumio volumio[25304]: info: Discovery: this is already registered, 70853f74-8210-4683-a3fa-e1217517bd40 Oct 29 06:34:40 volumio volumio[25304]: info: Discovery: Found device Volumio Oct 29 06:34:40 volumio volumio[25304]: info: CoreCommandRouter::volumioGetState Oct 29 06:34:40 volumio volumio[25304]: info: CorePlayQueue::getTrack 0 Oct 29 06:34:40 volumio volumio[25304]: info: Setting Device type: Raspberry PI Oct 29 06:34:40 volumio volumio[25304]: info: Completed loading Core Plugins Oct 29 06:34:40 volumio volumio[25304]: info: Preparing to generate the ALSA configuration file Oct 29 06:34:40 volumio volumio[25304]: info: Asound.conf file unchanged, so no further update is needed Oct 29 06:34:40 volumio volumio[25304]: info: Output device has changed, restarting MPD Oct 29 06:34:40 volumio volumio[25304]: info: Output device has changed, restarting Shairport Sync Oct 29 06:34:40 volumio volumio[25304]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 29 06:34:40 volumio volumio[25304]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 29 06:34:40 volumio sudo[25421]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 29 06:34:40 volumio sudo[25421]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 29 06:34:40 volumio sudo[25423]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 29 06:34:40 volumio sudo[25423]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 29 06:34:40 volumio sudo[25421]: pam_unix(sudo:session): session closed for user root Oct 29 06:34:40 volumio volumio[25304]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 29 06:34:40 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Oct 29 06:34:40 volumio volumio[25304]: info: ___________ START PLUGINS ___________ Oct 29 06:34:40 volumio volumio[25304]: info: ControllerMpd::onStart: Initializing MPD Oct 29 06:34:40 volumio volumio[25304]: info: Creating MPD Configuration file Oct 29 06:34:40 volumio systemd[1]: mpd.service: Deactivated successfully. Oct 29 06:34:40 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Oct 29 06:34:40 volumio systemd[1]: mpd.socket: Deactivated successfully. Oct 29 06:34:40 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Oct 29 06:34:40 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Oct 29 06:34:40 volumio volumio[25304]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 29 06:34:40 volumio volumio[25304]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 29 06:34:40 volumio volumio[25304]: info: [1761719680747] CoreMusicLibrary::Adding element Media Servers Oct 29 06:34:40 volumio volumio[25304]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 29 06:34:40 volumio sudo[25433]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 29 06:34:40 volumio sudo[25433]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 29 06:34:40 volumio volumio[25304]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 29 06:34:40 volumio volumio[25304]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 29 06:34:40 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Oct 29 06:34:40 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Oct 29 06:34:40 volumio sudo[25431]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 29 06:34:40 volumio sudo[25431]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 29 06:34:40 volumio systemd[1]: mpd.service: Deactivated successfully. Oct 29 06:34:40 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Oct 29 06:34:40 volumio volumio[25304]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 29 06:34:40 volumio volumio[25304]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 29 06:34:40 volumio volumio[25304]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 29 06:34:40 volumio systemd[1]: mpd.socket: Deactivated successfully. Oct 29 06:34:40 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Oct 29 06:34:40 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Oct 29 06:34:40 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Oct 29 06:34:40 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Oct 29 06:34:40 volumio volumio[25304]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 29 06:34:40 volumio volumio[25304]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 29 06:34:40 volumio volumio[25304]: info: [1761719680807] CoreMusicLibrary::Adding element Last_100 Oct 29 06:34:40 volumio volumio[25304]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 29 06:34:40 volumio volumio[25304]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 29 06:34:40 volumio volumio[25304]: info: [1761719680808] CoreMusicLibrary::Adding element Webradio Oct 29 06:34:40 volumio volumio[25304]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 29 06:34:40 volumio volumio[25304]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 29 06:34:40 volumio sudo[25431]: pam_unix(sudo:session): session closed for user root Oct 29 06:34:40 volumio volumio[25304]: info: Initializing BBC Radios Oct 29 06:34:40 volumio sudo[25447]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Oct 29 06:34:40 volumio sudo[25447]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Oct 29 06:34:40 volumio sudo[25447]: pam_unix(sudo:session): session closed for user root Oct 29 06:34:40 volumio volumio[25304]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 29 06:34:40 volumio volumio[25304]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 29 06:34:40 volumio volumio[25304]: info: Creating Spotify config file Oct 29 06:34:40 volumio volumio[25304]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 29 06:34:40 volumio volumio[25375]: Starting albumart workers Oct 29 06:34:40 volumio volumio[25376]: Starting albumart workers Oct 29 06:34:41 volumio volumio[25374]: Starting albumart workers Oct 29 06:34:41 volumio volumio[25304]: info: Volumio Calling Home Oct 29 06:34:41 volumio volumio[25304]: info: MPD Permissions set Oct 29 06:34:41 volumio volumio[25304]: info: MPD Permissions set Oct 29 06:34:41 volumio volumio[25304]: 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 29 06:34:41 volumio volumio[25304]: info: Volumio called home Oct 29 06:34:41 volumio volumio[25304]: info: Spotify config file written Oct 29 06:34:41 volumio volumio[25304]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 29 06:34:41 volumio volumio[25304]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 29 06:34:41 volumio volumio[25304]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 29 06:34:41 volumio volumio[25304]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 29 06:34:41 volumio volumio[25304]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 29 06:34:41 volumio volumio[25304]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 29 06:34:41 volumio volumio[25304]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 29 06:34:41 volumio volumio[25304]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 29 06:34:41 volumio volumio[25304]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 29 06:34:41 volumio volumio[25304]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 29 06:34:41 volumio sudo[25474]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Oct 29 06:34:41 volumio sudo[25474]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 29 06:34:41 volumio volumio[25304]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 29 06:34:41 volumio volumio[25304]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 29 06:34:41 volumio volumio[25304]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 29 06:34:41 volumio volumio[25304]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 29 06:34:41 volumio volumio[25304]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 29 06:34:41 volumio volumio[25304]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 29 06:34:41 volumio volumio[25304]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 29 06:34:41 volumio volumio[25304]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 29 06:34:41 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 29 06:34:41 volumio volumio[25304]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 29 06:34:41 volumio volumio[25304]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 29 06:34:41 volumio volumio[25304]: info: No need to fix Spotify hosts Oct 29 06:34:41 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 29 06:34:41 volumio go-librespot[25484]: go-librespot daemon starting... Oct 29 06:34:41 volumio go-librespot[25498]: time="2025-10-29T06:34:41Z" level=info msg="running go-librespot 0.4.0" Oct 29 06:34:41 volumio sudo[25474]: pam_unix(sudo:session): session closed for user root Oct 29 06:34:41 volumio go-librespot[25498]: time="2025-10-29T06:34:41Z" level=debug msg="app state loaded" Oct 29 06:34:41 volumio go-librespot[25498]: time="2025-10-29T06:34:41Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 29 06:34:41 volumio mpd[25458]: 2025-10-29T06:34:41 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Oct 29 06:34:41 volumio systemd[1]: Started mpd.service - Music Player Daemon. Oct 29 06:34:41 volumio sudo[25423]: pam_unix(sudo:session): session closed for user root Oct 29 06:34:41 volumio sudo[25433]: pam_unix(sudo:session): session closed for user root Oct 29 06:34:41 volumio volumio[25304]: info: Starting Shairport Sync Oct 29 06:34:41 volumio volumio[25304]: info: Starting Shairport Sync Oct 29 06:34:41 volumio sudo[25510]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 29 06:34:41 volumio sudo[25510]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 29 06:34:41 volumio volumio[25304]: info: Starting Shairport Sync Oct 29 06:34:41 volumio sudo[25513]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 29 06:34:41 volumio sudo[25513]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 29 06:34:41 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Oct 29 06:34:41 volumio sudo[25516]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 29 06:34:41 volumio sudo[25516]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 29 06:34:41 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Oct 29 06:34:41 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Oct 29 06:34:41 volumio systemd[1]: shairport-sync.service: Consumed 1.516s CPU time. Oct 29 06:34:41 volumio go-librespot[25498]: time="2025-10-29T06:34:41Z" 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 29 06:34:41 volumio go-librespot[25498]: time="2025-10-29T06:34:41Z" 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 29 06:34:41 volumio go-librespot[25498]: time="2025-10-29T06:34:41Z" 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 29 06:34:41 volumio go-librespot[25498]: time="2025-10-29T06:34:41Z" level=info msg="zeroconf server listening on port 44905" Oct 29 06:34:41 volumio volumio[25304]: error: MPD error: The expression evaluated to a falsy value: Oct 29 06:34:41 volumio volumio[25304]: assert.ok(self.idling) Oct 29 06:34:41 volumio volumio[25304]: error: The expression evaluated to a falsy value: Oct 29 06:34:41 volumio volumio[25304]: assert.ok(self.idling) Oct 29 06:34:41 volumio volumio[25304]: info: MPD running with PID25458 Oct 29 06:34:41 volumio volumio[25304]: ,establishing connection Oct 29 06:34:41 volumio volumio[25304]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Oct 29 06:34:41 volumio volumio[25304]: SPOTIFY: BQBU8CBLdiwu8gd3e9XgzkJWeAvvZMj-pUZjIWqBxYpYQFeCbnI9r6vjvECipIUpxP3alpcLxDtvAGf0qzc9fS9_RNXuLFGSDk10rf0N0lBo6W_e4TBoZvMONePQCtyFLVaRSNKzUyy5ww0ryBo7tQ123IMXLSl0bNAY5N9RRE43SoioWEpvsz0_Q17Dnx4kwvRsCg13R3a6Oi265hAzP6VH93lsqLuAQeze4M6BskWDrqs0ChcxKAYcJoB0cVe3nxB7_FDlnrUqikJPjtjnSr0OAy52WTXB1cZc9ENQcKNuSVt_0No Oct 29 06:34:41 volumio volumio[25304]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Oct 29 06:34:41 volumio volumio[25304]: info: New Spotify access token = BQBU8CBLdiwu8gd3e9XgzkJWeAvvZMj-pUZjIWqBxYpYQFeCbnI9r6vjvECipIUpxP3alpcLxDtvAGf0qzc9fS9_RNXuLFGSDk10rf0N0lBo6W_e4TBoZvMONePQCtyFLVaRSNKzUyy5ww0ryBo7tQ123IMXLSl0bNAY5N9RRE43SoioWEpvsz0_Q17Dnx4kwvRsCg13R3a6Oi265hAzP6VH93lsqLuAQeze4M6BskWDrqs0ChcxKAYcJoB0cVe3nxB7_FDlnrUqikJPjtjnSr0OAy52WTXB1cZc9ENQcKNuSVt_0No Oct 29 06:34:41 volumio volumio[25304]: info: Spotify credentials grant success - running version from March 24, 2019 Oct 29 06:34:41 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Oct 29 06:34:41 volumio sudo[25510]: pam_unix(sudo:session): session closed for user root Oct 29 06:34:41 volumio volumio[25304]: error: updateQueue error: null Oct 29 06:34:41 volumio volumio[25304]: error: updateQueue error: null Oct 29 06:34:41 volumio volumio[25304]: info: CoreCommandRouter::volumioGetState Oct 29 06:34:41 volumio volumio[25304]: info: CorePlayQueue::getTrack 0 Oct 29 06:34:41 volumio volumio[25304]: info: Shairport-Sync Started Oct 29 06:34:41 volumio volumio[25304]: Error adding Membership: Error: addMembership EINVAL Oct 29 06:34:41 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Oct 29 06:34:41 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Oct 29 06:34:41 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Oct 29 06:34:41 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Oct 29 06:34:41 volumio sudo[25516]: pam_unix(sudo:session): session closed for user root Oct 29 06:34:41 volumio sudo[25513]: pam_unix(sudo:session): session closed for user root Oct 29 06:34:41 volumio volumio[25304]: info: Shairport-Sync Started Oct 29 06:34:41 volumio volumio[25304]: info: Shairport-Sync Started Oct 29 06:34:41 volumio go-librespot[25498]: time="2025-10-29T06:34:41Z" level=debug msg="obtained new client token: AAAU8Qx5eKMGK0RwQYarXlhb+ThnrxK73eJMJjxUt1j22dpekzIVIXB0XlPdp5nzdS1h9dRBljBPe01sEne+ja06K9Qvlf5OjUt5GzAsv84Kyb8uvE3UdyziR9XfEKccELqRtqOA8hvcPwUZpVHnT3eN0ESCpaNVXk0wdvO5W34K5aG8nxx6Ignx0wDGqz3gueFWYeQqlskxzOAoZSQMMfHdpSb2fLCEoJfbeRjVN15Byroj4tW2hWc=" Oct 29 06:34:41 volumio go-librespot[25498]: time="2025-10-29T06:34:41Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 29 06:34:41 volumio go-librespot[25498]: time="2025-10-29T06:34:41Z" level=debug msg="completed keyexchange" Oct 29 06:34:41 volumio go-librespot[25498]: time="2025-10-29T06:34:41Z" level=debug msg="completed challenge" Oct 29 06:34:41 volumio go-librespot[25498]: time="2025-10-29T06:34:41Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 29 06:34:41 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 29 06:34:41 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 29 06:34:41 volumio volumio[25304]: 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 29 06:34:41 volumio volumio[25304]: info: Spotify Successfully logged in Oct 29 06:34:41 volumio volumio[25304]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 29 06:34:41 volumio volumio[25304]: info: [1761719681641] CoreMusicLibrary::Adding element Spotify Oct 29 06:34:41 volumio volumio[25304]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 29 06:34:41 volumio volumio[25304]: Cannot find translation for source Spotify Oct 29 06:34:41 volumio volumio[25304]: info: [yt-cast-receiver] DIAL server listening on port 8098 Oct 29 06:34:41 volumio volumio[25304]: info: CoreCommandRouter::volumioRetrievevolume Oct 29 06:34:41 volumio volumio[25304]: info: VolumeController:: Volume=33 Mute =false Oct 29 06:34:41 volumio volumio[25304]: info: CoreCommandRouter::volumioGetState Oct 29 06:34:41 volumio volumio[25304]: info: CorePlayQueue::getTrack 0 Oct 29 06:34:41 volumio volumio[25304]: info: CoreStateMachine::pushState Oct 29 06:34:41 volumio volumio[25304]: info: CorePlayQueue::getTrack 0 Oct 29 06:34:41 volumio volumio[25304]: info: CoreCommandRouter::volumioPushState Oct 29 06:34:42 volumio volumio[25304]: info: Completed starting Core Plugins Oct 29 06:34:42 volumio volumio[25304]: info: ------------------------------------------- Oct 29 06:34:42 volumio volumio[25304]: info: ----- MyVolumio plugins startup ---- Oct 29 06:34:42 volumio volumio[25304]: info: ------------------------------------------- Oct 29 06:34:42 volumio volumio[25304]: info: [MyVolumio PluginManager] Fetching plans data.... Oct 29 06:34:43 volumio volumio-remote-updater[874]: [2025-10-29 06:34:43] [connect] Successful connection Oct 29 06:34:43 volumio volumio-remote-updater[874]: [2025-10-29 06:34:43] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1761719683 101 Oct 29 06:34:43 volumio volumio[25304]: 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 29 06:34:44 volumio volumio[25304]: info: Cannot mount NAS NAS at system boot, trial number 2 ,retrying in 5 seconds Oct 29 06:34:44 volumio volumio[25304]: info: go-librespot daemon successfully initialized Oct 29 06:34:44 volumio sudo[25538]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Oct 29 06:34:44 volumio sudo[25538]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 29 06:34:44 volumio sudo[25541]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Oct 29 06:34:44 volumio sudo[25541]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 29 06:34:44 volumio systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Oct 29 06:34:44 volumio systemd[1]: mpd_monitor.service: Deactivated successfully. Oct 29 06:34:44 volumio systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Oct 29 06:34:44 volumio systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Oct 29 06:34:44 volumio sudo[25538]: pam_unix(sudo:session): session closed for user root Oct 29 06:34:44 volumio mpd_monitor.sh[25543]: MPD Monitor Service: Starting MPD Monitor Service Oct 29 06:34:44 volumio volumio[25304]: info: Successfully started MPD Monitor Oct 29 06:34:44 volumio sudo[25541]: pam_unix(sudo:session): session closed for user root Oct 29 06:34:44 volumio volumio[25304]: info: Successfully started MPD Monitor Oct 29 06:34:44 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 179. Oct 29 06:34:44 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 29 06:34:44 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 29 06:34:44 volumio go-librespot[25547]: go-librespot daemon starting... Oct 29 06:34:44 volumio go-librespot[25548]: time="2025-10-29T06:34:44Z" level=info msg="running go-librespot 0.4.0" Oct 29 06:34:44 volumio go-librespot[25548]: time="2025-10-29T06:34:44Z" level=debug msg="app state loaded" Oct 29 06:34:44 volumio go-librespot[25548]: time="2025-10-29T06:34:44Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 29 06:34:44 volumio go-librespot[25548]: time="2025-10-29T06:34: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-gew4.spotify.com:80]" Oct 29 06:34:44 volumio go-librespot[25548]: time="2025-10-29T06:34:44Z" 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 29 06:34:44 volumio go-librespot[25548]: time="2025-10-29T06:34:44Z" 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 29 06:34:44 volumio go-librespot[25548]: time="2025-10-29T06:34:44Z" level=info msg="zeroconf server listening on port 44623" Oct 29 06:34:44 volumio go-librespot[25548]: time="2025-10-29T06:34:44Z" level=debug msg="obtained new client token: AACuTJfK+sBZrhiltahFDzXTi9gy7rQUl/65Q0ulfd6EmlmWzOXr3WN55FARjYakRffB3BWoFtEpA9mWkMLb2Gf/I+IkSzXXlddLVG+SaDcQhnR2pu6xC2eimdTAnmRqOrYqifEuBWfmWcg9ma9eBFZtMpfzfPAdK0QGgoaJHb/KWeynjTefxTvYiSPIAfiUtiMS/GWnw01OZ0dOVWGxALYYHY2rQ6MjoOfVriLtHH1l/BHg47OsFZY=" Oct 29 06:34:44 volumio go-librespot[25548]: time="2025-10-29T06:34:44Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 29 06:34:44 volumio go-librespot[25548]: time="2025-10-29T06:34:44Z" level=debug msg="completed keyexchange" Oct 29 06:34:44 volumio go-librespot[25548]: time="2025-10-29T06:34:44Z" level=debug msg="completed challenge" Oct 29 06:34:45 volumio go-librespot[25548]: time="2025-10-29T06:34:45Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 29 06:34:45 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 29 06:34:45 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 29 06:34:46 volumio volumio[25304]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Oct 29 06:34:47 volumio volumio[25304]: info: Initializing connection to go-librespot Websocket Oct 29 06:34:47 volumio volumio[25304]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 29 06:34:48 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 180. Oct 29 06:34:48 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 29 06:34:48 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 29 06:34:48 volumio go-librespot[25556]: go-librespot daemon starting... Oct 29 06:34:48 volumio go-librespot[25557]: time="2025-10-29T06:34:48Z" level=info msg="running go-librespot 0.4.0" Oct 29 06:34:48 volumio go-librespot[25557]: time="2025-10-29T06:34:48Z" level=debug msg="app state loaded" Oct 29 06:34:48 volumio go-librespot[25557]: time="2025-10-29T06:34:48Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 29 06:34:48 volumio go-librespot[25557]: time="2025-10-29T06:34:48Z" 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 29 06:34:48 volumio go-librespot[25557]: time="2025-10-29T06:34:48Z" 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 29 06:34:48 volumio go-librespot[25557]: time="2025-10-29T06:34:48Z" 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 29 06:34:48 volumio go-librespot[25557]: time="2025-10-29T06:34:48Z" level=info msg="zeroconf server listening on port 43111" Oct 29 06:34:48 volumio go-librespot[25557]: time="2025-10-29T06:34:48Z" level=debug msg="obtained new client token: AABwzAEbW8sfE4rpP7DjYBHUnfCsMJhsaGo48tq1st3VQ+9vyC/2r7aMVOzf4RF7Nb7B+XTmZekfSya4dUjL5ORU+3R/3tS2Aw3iIxHg7HkoNXU3ENELemLygjwyKVeCy99D9hQKoiZqKGX1tGB+25HG2SlHcKJWwbayU4p9xifeGO3EOALSnzXsXl6o2WhcZlcYozYFFU+smgw6RaIui17PMLIhey1f3naMGhT8bJakQulnuhRe9wM=" Oct 29 06:34:48 volumio go-librespot[25557]: time="2025-10-29T06:34:48Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 29 06:34:48 volumio go-librespot[25557]: time="2025-10-29T06:34:48Z" level=debug msg="completed keyexchange" Oct 29 06:34:48 volumio go-librespot[25557]: time="2025-10-29T06:34:48Z" level=debug msg="completed challenge" Oct 29 06:34:48 volumio go-librespot[25557]: time="2025-10-29T06:34:48Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 29 06:34:48 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 29 06:34:48 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 29 06:34:49 volumio volumio[25304]: info: Cannot mount NAS NAS at system boot, trial number 3 ,retrying in 5 seconds Oct 29 06:34:49 volumio sudo[25579]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 29 06:34:49 volumio sudo[25579]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 29 06:34:49 volumio sudo[25581]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 29 06:34:49 volumio sudo[25581]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 29 06:34:49 volumio sudo[25579]: pam_unix(sudo:session): session closed for user root Oct 29 06:34:49 volumio sudo[25581]: pam_unix(sudo:session): session closed for user root Oct 29 06:34:49 volumio sudo[25585]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Oct 29 06:34:49 volumio sudo[25585]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 29 06:34:49 volumio sudo[25585]: pam_unix(sudo:session): session closed for user root Oct 29 06:34:49 volumio volumio[25304]: info: Upmpdcli Daemon Started Oct 29 06:34:50 volumio volumio[25304]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Oct 29 06:34:50 volumio volumio[25304]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Oct 29 06:34:50 volumio volumio[25304]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Oct 29 06:34:50 volumio volumio[25304]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Oct 29 06:34:50 volumio volumio[25304]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Oct 29 06:34:50 volumio volumio[25304]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Oct 29 06:34:50 volumio volumio[25304]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Oct 29 06:34:50 volumio volumio[25304]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Oct 29 06:34:50 volumio volumio[25304]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Oct 29 06:34:50 volumio volumio[25304]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Oct 29 06:34:50 volumio volumio[25304]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Oct 29 06:34:50 volumio volumio[25304]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Oct 29 06:34:50 volumio volumio[25304]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Oct 29 06:34:50 volumio volumio[25304]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Oct 29 06:34:50 volumio volumio[25304]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Oct 29 06:34:50 volumio volumio[25304]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Oct 29 06:34:50 volumio volumio[25304]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Oct 29 06:34:50 volumio volumio[25304]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Oct 29 06:34:50 volumio volumio[25304]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Oct 29 06:34:50 volumio volumio[25304]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Oct 29 06:34:50 volumio volumio[25304]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Oct 29 06:34:50 volumio volumio[25304]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Oct 29 06:34:50 volumio volumio[25304]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Oct 29 06:34:50 volumio volumio[25304]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Oct 29 06:34:50 volumio volumio[25304]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Oct 29 06:34:50 volumio volumio[25304]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Oct 29 06:34:50 volumio volumio[25304]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Oct 29 06:34:50 volumio volumio[25304]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Oct 29 06:34:50 volumio volumio[25304]: info: Adding plugin bluetooth to MyMusic Plugins Oct 29 06:34:50 volumio volumio[25304]: info: Adding plugin multiroom to MyMusic Plugins Oct 29 06:34:50 volumio volumio[25304]: info: Adding plugin metavolumio to MyMusic Plugins Oct 29 06:34:50 volumio volumio[25304]: info: Adding plugin cd_controller to MyMusic Plugins Oct 29 06:34:50 volumio volumio[25304]: info: Adding plugin qobuzconnect to MyMusic Plugins Oct 29 06:34:50 volumio volumio[25304]: info: Adding plugin smart_inputs to MyMusic Plugins Oct 29 06:34:50 volumio volumio[25304]: info: Adding plugin tidalconnect to MyMusic Plugins Oct 29 06:34:50 volumio volumio[25304]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Oct 29 06:34:50 volumio volumio[25304]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Oct 29 06:34:50 volumio volumio[25304]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Oct 29 06:34:50 volumio volumio[25304]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 29 06:34:50 volumio volumio[25304]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 29 06:34:50 volumio volumio[25304]: info: Starting MyVolumio Remote Streaming Endpoints Oct 29 06:34:50 volumio volumio[25304]: info: MyVolumio login type: Token Oct 29 06:34:50 volumio volumio[25304]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Oct 29 06:34:50 volumio volumio[25304]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Oct 29 06:34:50 volumio volumio[25304]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Oct 29 06:34:50 volumio volumio[25304]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Oct 29 06:34:50 volumio volumio[25304]: info: Streaming services startup Oct 29 06:34:50 volumio volumio[25304]: info: Starting Streaming Daemon Oct 29 06:34:50 volumio sudo[25588]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Oct 29 06:34:50 volumio sudo[25588]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 29 06:34:50 volumio volumio[25304]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Oct 29 06:34:50 volumio sudo[25588]: pam_unix(sudo:session): session closed for user root Oct 29 06:34:50 volumio volumio[25304]: info: Initializing connection to go-librespot Websocket Oct 29 06:34:50 volumio volumio[25304]: error: Cannot start Volumio Streaming Daemon Oct 29 06:34:50 volumio volumio[25304]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Oct 29 06:34:50 volumio volumio[25304]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Oct 29 06:34:50 volumio volumio[25304]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 29 06:34:51 volumio volumio[25304]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Oct 29 06:34:51 volumio kernel: nfs: server 192.168.1.3 not responding, timed out Oct 29 06:34:51 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 181. Oct 29 06:34:51 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 29 06:34:51 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 29 06:34:51 volumio go-librespot[25596]: go-librespot daemon starting... Oct 29 06:34:51 volumio go-librespot[25597]: time="2025-10-29T06:34:51Z" level=info msg="running go-librespot 0.4.0" Oct 29 06:34:51 volumio go-librespot[25597]: time="2025-10-29T06:34:51Z" level=debug msg="app state loaded" Oct 29 06:34:51 volumio go-librespot[25597]: time="2025-10-29T06:34:51Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 29 06:34:51 volumio go-librespot[25597]: time="2025-10-29T06:34:51Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Oct 29 06:34:51 volumio go-librespot[25597]: time="2025-10-29T06:34:51Z" 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 29 06:34:51 volumio go-librespot[25597]: time="2025-10-29T06:34:51Z" 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 29 06:34:51 volumio go-librespot[25597]: time="2025-10-29T06:34:51Z" level=info msg="zeroconf server listening on port 32993" Oct 29 06:34:51 volumio go-librespot[25597]: time="2025-10-29T06:34:51Z" level=debug msg="obtained new client token: AAA7IO55HDrifZP7CNdr/f2vYlIO5QjEG8BqDsvsIztVJLZsjoi2bAidUtXPWKW5OfjUxVCDts1dh0PQyftG57UJGDgkIQtSONGUOp0+MDCI3YLSncJbOTgk79Qv46gi+00OwuVtk8gTdVpyoN3FIDuNbA61vCfvxq+nqyVxM6w2JPtOVJ5RoelKjddiyGcv0U0OyDjt7rGC0Bfm2F716EqBZRfJV9FkEkz5yfiU6MwpU1ccXfWFkfU=" Oct 29 06:34:51 volumio go-librespot[25597]: time="2025-10-29T06:34:51Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 29 06:34:52 volumio go-librespot[25597]: time="2025-10-29T06:34:52Z" level=debug msg="completed keyexchange" Oct 29 06:34:52 volumio go-librespot[25597]: time="2025-10-29T06:34:52Z" level=debug msg="completed challenge" Oct 29 06:34:52 volumio go-librespot[25597]: time="2025-10-29T06:34:52Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 29 06:34:52 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 29 06:34:52 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 29 06:34:52 volumio volumio[25304]: info: MyVolumio token set successfully Oct 29 06:34:52 volumio volumio[25304]: info: MYVOLUMIO: Adding device Oct 29 06:34:52 volumio volumio[25304]: info: MYVOLUMIO: Evaluating Server Oct 29 06:34:52 volumio volumio[25304]: info: MyVolumio status changed Oct 29 06:34:52 volumio volumio[25304]: info: Streaming services startup Oct 29 06:34:52 volumio volumio[25304]: info: Starting Streaming Daemon Oct 29 06:34:52 volumio volumio[25304]: info: Removing browser output: myVolumio user plan is not superstar Oct 29 06:34:52 volumio volumio[25304]: info: Removing audio output: Oct 29 06:34:52 volumio volumio[25304]: info: Stoppping Tunnel 1 Oct 29 06:34:52 volumio sudo[25620]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Oct 29 06:34:52 volumio sudo[25620]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 29 06:34:52 volumio sudo[25622]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service Oct 29 06:34:52 volumio sudo[25622]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 29 06:34:52 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 29 06:34:52 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 29 06:34:52 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 29 06:34:52 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 29 06:34:52 volumio sudo[25620]: pam_unix(sudo:session): session closed for user root Oct 29 06:34:52 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 29 06:34:52 volumio volumio[25304]: error: Cannot start Volumio Streaming Daemon Oct 29 06:34:52 volumio volumio[25304]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Oct 29 06:34:52 volumio volumio[25304]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Oct 29 06:34:52 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 29 06:34:52 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 29 06:34:52 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 29 06:34:52 volumio sudo[25622]: pam_unix(sudo:session): session closed for user root Oct 29 06:34:52 volumio volumio[25304]: info: Remote SSH Stopped Oct 29 06:34:53 volumio volumio[25304]: info: Initializing connection to go-librespot Websocket Oct 29 06:34:53 volumio volumio[25304]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 29 06:34:53 volumio volumio[25304]: info: Setting Geolocation for MyVolumio to eu3 Oct 29 06:34:53 volumio volumio[25304]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 29 06:34:53 volumio volumio[25304]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 29 06:34:53 volumio volumio[25304]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 29 06:34:53 volumio volumio[25304]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Oct 29 06:34:54 volumio volumio[25304]: info: Cannot mount NAS NAS at system boot, trial number 4 ,retrying in 5 seconds Oct 29 06:34:54 volumio kernel: nfs: server 192.168.1.3 not responding, timed out Oct 29 06:34:54 volumio volumio[25304]: info: Updating MyVolumio device info Oct 29 06:34:54 volumio volumio[25304]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 29 06:34:54 volumio volumio[25304]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 29 06:34:54 volumio volumio[25304]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 29 06:34:55 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 182. Oct 29 06:34:55 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 29 06:34:55 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 29 06:34:55 volumio go-librespot[25625]: go-librespot daemon starting... Oct 29 06:34:55 volumio go-librespot[25626]: time="2025-10-29T06:34:55Z" level=info msg="running go-librespot 0.4.0" Oct 29 06:34:55 volumio go-librespot[25626]: time="2025-10-29T06:34:55Z" level=debug msg="app state loaded" Oct 29 06:34:55 volumio go-librespot[25626]: time="2025-10-29T06:34:55Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 29 06:34:55 volumio volumio[25304]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Oct 29 06:34:55 volumio go-librespot[25626]: time="2025-10-29T06:34:55Z" 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 29 06:34:55 volumio go-librespot[25626]: time="2025-10-29T06:34:55Z" 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 29 06:34:55 volumio go-librespot[25626]: time="2025-10-29T06:34:55Z" 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 29 06:34:55 volumio go-librespot[25626]: time="2025-10-29T06:34:55Z" level=info msg="zeroconf server listening on port 39111" Oct 29 06:34:55 volumio go-librespot[25626]: time="2025-10-29T06:34:55Z" level=debug msg="obtained new client token: AAAMaABP6FOLTFPQK+AN7IG14P4evWqcT23BYMVTaA05LAjIqXdl+GiXNuPMzGyLq6G662CC543dc8q1AyyyDhl0mTFjAm7Wx6U5H7qly9yEoWNsPoRgpzm6DZG6ltziy5kzLPHFfv6+GiD7MSxmdWjMXCKJ5Aiw1GsveFgusWstyG/eDymqitI0WvIeFFE6Eat2vZcmirHpgZSt2mKIm2KQVfTlFX11JOd1iGtz/KGqTwGypUQL4M0=" Oct 29 06:34:55 volumio go-librespot[25626]: time="2025-10-29T06:34:55Z" 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 29 06:34:55 volumio go-librespot[25626]: time="2025-10-29T06:34:55Z" level=debug msg="connected to ap-gew1.spotify.com:443" Oct 29 06:34:55 volumio go-librespot[25626]: time="2025-10-29T06:34:55Z" level=debug msg="completed keyexchange" Oct 29 06:34:55 volumio go-librespot[25626]: time="2025-10-29T06:34:55Z" level=debug msg="completed challenge" Oct 29 06:34:55 volumio go-librespot[25626]: time="2025-10-29T06:34:55Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 29 06:34:55 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 29 06:34:55 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 29 06:34:56 volumio volumio[25304]: info: Initializing connection to go-librespot Websocket Oct 29 06:34:56 volumio volumio[25304]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 29 06:34:57 volumio volumio[25304]: info: MYVOLUMIO: Adding device Oct 29 06:34:57 volumio volumio[25304]: info: MYVOLUMIO: Evaluating Server Oct 29 06:34:58 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 183. Oct 29 06:34:58 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 29 06:34:58 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 29 06:34:58 volumio go-librespot[25649]: go-librespot daemon starting... Oct 29 06:34:58 volumio go-librespot[25650]: time="2025-10-29T06:34:58Z" level=info msg="running go-librespot 0.4.0" Oct 29 06:34:58 volumio go-librespot[25650]: time="2025-10-29T06:34:58Z" level=debug msg="app state loaded" Oct 29 06:34:58 volumio go-librespot[25650]: time="2025-10-29T06:34:58Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 29 06:34:58 volumio go-librespot[25650]: time="2025-10-29T06:34: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-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Oct 29 06:34:58 volumio go-librespot[25650]: time="2025-10-29T06:34:58Z" 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 29 06:34:58 volumio go-librespot[25650]: time="2025-10-29T06:34:58Z" 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 29 06:34:58 volumio go-librespot[25650]: time="2025-10-29T06:34:58Z" level=info msg="zeroconf server listening on port 39933" Oct 29 06:34:58 volumio go-librespot[25650]: time="2025-10-29T06:34:58Z" level=debug msg="obtained new client token: AAAX5FwF+ydRUX13aaj5oAnMv+fQY61Guz2610/GYaxKI/LgccuCYtZzxIFwIYO/TFNO/Doy3RyAQeH5Z0V4IHEAh5GHpBfjkHp8RoGKbRa5vIgPRcZYdR3hdrJvfZG5jsNmvfkB5R5pagAyOD58NWyPgGbZJkpHu4J1yFlhcaFTHoorqUzO0BD9g6U8wYm15+ObKur++nmnFrGs5YmVPHphNUpoVZ+z2M77qDiLCgZnhr2s6+OXj+g=" Oct 29 06:34:58 volumio go-librespot[25650]: time="2025-10-29T06:34:58Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 29 06:34:58 volumio go-librespot[25650]: time="2025-10-29T06:34:58Z" level=debug msg="completed keyexchange" Oct 29 06:34:58 volumio go-librespot[25650]: time="2025-10-29T06:34:58Z" level=debug msg="completed challenge" Oct 29 06:34:59 volumio go-librespot[25650]: time="2025-10-29T06:34:59Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 29 06:34:59 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 29 06:34:59 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 29 06:34:59 volumio volumio[25304]: info: Cannot mount NAS at system boot, trial number 4 ,stopping Oct 29 06:34:59 volumio volumio[25304]: info: Setting Geolocation for MyVolumio to eu3 Oct 29 06:34:59 volumio volumio[25304]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 29 06:34:59 volumio volumio[25304]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 29 06:34:59 volumio volumio[25304]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 29 06:34:59 volumio volumio[25304]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Oct 29 06:34:59 volumio volumio[25304]: info: Initializing connection to go-librespot Websocket Oct 29 06:34:59 volumio volumio[25304]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 29 06:34:59 volumio kernel: nfs: server 192.168.1.3 not responding, timed out Oct 29 06:35:00 volumio volumio[25304]: info: Updating MyVolumio device info Oct 29 06:35:00 volumio volumio[25304]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 29 06:35:00 volumio volumio[25304]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 29 06:35:00 volumio volumio[25304]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 29 06:35:00 volumio volumio[25304]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Oct 29 06:35:02 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 184. Oct 29 06:35:02 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 29 06:35:02 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 29 06:35:02 volumio go-librespot[25671]: go-librespot daemon starting... Oct 29 06:35:02 volumio go-librespot[25672]: time="2025-10-29T06:35:02Z" level=info msg="running go-librespot 0.4.0" Oct 29 06:35:02 volumio go-librespot[25672]: time="2025-10-29T06:35:02Z" level=debug msg="app state loaded" Oct 29 06:35:02 volumio go-librespot[25672]: time="2025-10-29T06:35:02Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 29 06:35:02 volumio go-librespot[25672]: time="2025-10-29T06:35:02Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Oct 29 06:35:02 volumio go-librespot[25672]: time="2025-10-29T06:35:02Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Oct 29 06:35:02 volumio go-librespot[25672]: time="2025-10-29T06:35:02Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Oct 29 06:35:02 volumio go-librespot[25672]: time="2025-10-29T06:35:02Z" level=info msg="zeroconf server listening on port 46413" Oct 29 06:35:02 volumio go-librespot[25672]: time="2025-10-29T06:35:02Z" level=debug msg="obtained new client token: AAD45P9dLOwhKP0GxZpHuY9tP/X32QQK10TF4EtDSdVBXzFJ4yrXVjAg6YOicqyFHgJ61SCjd3ThyBWAZhorZpbnyDe81op1yYTWzBfwlD6GDTBLy9TBv3yR7NmHIUUJpuIuTO2BOAPjJapapJkLmqoQFD1ICdugMe9F3rvPFqmwuvadpVMsA09Y+9ULCFCiJUBhnOuYNeWO7RypQ1kO4r8M806Gdc7DimySmkBp4RYyId/0mxJjGDk=" Oct 29 06:35:02 volumio go-librespot[25672]: time="2025-10-29T06:35:02Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 29 06:35:02 volumio go-librespot[25672]: time="2025-10-29T06:35:02Z" level=debug msg="completed keyexchange" Oct 29 06:35:02 volumio go-librespot[25672]: time="2025-10-29T06:35:02Z" level=debug msg="completed challenge" Oct 29 06:35:02 volumio go-librespot[25672]: time="2025-10-29T06:35:02Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 29 06:35:02 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 29 06:35:02 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 29 06:35:02 volumio volumio[25304]: info: Initializing connection to go-librespot Websocket Oct 29 06:35:02 volumio volumio[25304]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 29 06:35:05 volumio volumio[25304]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Oct 29 06:35:05 volumio volumio[25304]: 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 29 06:35:05 volumio volumio[25304]: info: CoreCommandRouter::volumioGetState Oct 29 06:35:05 volumio volumio[25304]: info: CorePlayQueue::getTrack 0 Oct 29 06:35:05 volumio volumio[25304]: info: Initializing connection to go-librespot Websocket Oct 29 06:35:05 volumio volumio[25304]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 29 06:35:05 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 185. Oct 29 06:35:05 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 29 06:35:05 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 29 06:35:05 volumio go-librespot[25682]: go-librespot daemon starting... Oct 29 06:35:05 volumio go-librespot[25683]: time="2025-10-29T06:35:05Z" level=info msg="running go-librespot 0.4.0" Oct 29 06:35:05 volumio go-librespot[25683]: time="2025-10-29T06:35:05Z" level=debug msg="app state loaded" Oct 29 06:35:05 volumio go-librespot[25683]: time="2025-10-29T06:35:05Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 29 06:35:05 volumio go-librespot[25683]: time="2025-10-29T06:35: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 29 06:35:05 volumio go-librespot[25683]: time="2025-10-29T06:35: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 29 06:35:05 volumio go-librespot[25683]: time="2025-10-29T06:35: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 29 06:35:05 volumio go-librespot[25683]: time="2025-10-29T06:35:05Z" level=info msg="zeroconf server listening on port 33155" Oct 29 06:35:05 volumio go-librespot[25683]: time="2025-10-29T06:35:05Z" level=debug msg="obtained new client token: AABfxx+0bTIjjgSwnP0zGZSLJc7z3QQwbJABf6GvUARM24qcXdGe9MLP2iTVt4imJULGq0sekMVZ8nDpJm08opQm69zFf1X3zUlNXp4m9Yi3Dn+opBzh8w1EO+67YDOH7fO9st6Vtkor38rYh4BDaLQmcstbe1xDALxRg9ubxEN9qth0wLCw/AElFUk3ontX797Q9CrkaoYHbk61Dt6F5U9998lMMuO7pXZAMV0pL1bwVRXiVOeJoaM=" Oct 29 06:35:06 volumio go-librespot[25683]: time="2025-10-29T06:35:06Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 29 06:35:06 volumio go-librespot[25683]: time="2025-10-29T06:35:06Z" level=debug msg="completed keyexchange" Oct 29 06:35:06 volumio go-librespot[25683]: time="2025-10-29T06:35:06Z" level=debug msg="completed challenge" Oct 29 06:35:06 volumio go-librespot[25683]: time="2025-10-29T06:35:06Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 29 06:35:06 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 29 06:35:06 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 29 06:35:08 volumio volumio[25304]: info: Initializing connection to go-librespot Websocket Oct 29 06:35:08 volumio volumio[25304]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 29 06:35:09 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 186. Oct 29 06:35:09 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 29 06:35:09 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 29 06:35:09 volumio go-librespot[25704]: go-librespot daemon starting... Oct 29 06:35:09 volumio go-librespot[25705]: time="2025-10-29T06:35:09Z" level=info msg="running go-librespot 0.4.0" Oct 29 06:35:09 volumio go-librespot[25705]: time="2025-10-29T06:35:09Z" level=debug msg="app state loaded" Oct 29 06:35:09 volumio go-librespot[25705]: time="2025-10-29T06:35:09Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 29 06:35:09 volumio go-librespot[25705]: time="2025-10-29T06:35: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-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Oct 29 06:35:09 volumio go-librespot[25705]: time="2025-10-29T06:35:09Z" 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 29 06:35:09 volumio go-librespot[25705]: time="2025-10-29T06:35:09Z" 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 29 06:35:09 volumio go-librespot[25705]: time="2025-10-29T06:35:09Z" level=info msg="zeroconf server listening on port 38735" Oct 29 06:35:09 volumio go-librespot[25705]: time="2025-10-29T06:35:09Z" level=debug msg="obtained new client token: AADjPXRkWL6un1AO9sj6cVhkvkuHGvLuLS8/UqjVOlPyAZHIvmze2XJTBoh/SCQBuGeG3qMFZeZR1d4nqsRmXgIYa9eUga8JXOweNZQkiOpt/vFVfyeQiOEuzCK7oCi9+Aew0stErSJdoZM0MstS7ctVkg03iauy8Dnh5jjyW/u+8dCxDSa53/6RVlolV9Uddy7ZssdYvAyb+anB2datJVvbO8UMglXN+B22rGTERSTSx/aA2z9KB90=" Oct 29 06:35:09 volumio go-librespot[25705]: time="2025-10-29T06:35:09Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 29 06:35:09 volumio go-librespot[25705]: time="2025-10-29T06:35:09Z" level=debug msg="completed keyexchange" Oct 29 06:35:09 volumio go-librespot[25705]: time="2025-10-29T06:35:09Z" level=debug msg="completed challenge" Oct 29 06:35:09 volumio go-librespot[25705]: time="2025-10-29T06:35: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 29 06:35:09 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 29 06:35:09 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 29 06:35:10 volumio volumio[25304]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 29 06:35:10 volumio volumio[25304]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 29 06:35:10 volumio volumio[25304]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam Oct 29 06:35:10 volumio volumio[25304]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Oct 29 06:35:10 volumio volumio[25304]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Oct 29 06:35:10 volumio volumio[25304]: info: CoreCommandRouter::volumioGetBrowseSources Oct 29 06:35:10 volumio volumio[25304]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 29 06:35:10 volumio volumio[25304]: error: MyVolumio Plugin failed to authenticate in a timely fashion Oct 29 06:35:10 volumio volumio[25304]: info: Completed starting MyVolumio Plugin Oct 29 06:35:10 volumio volumio[25304]: [Metrics] CommandRouter: 31s 908.97ms Oct 29 06:35:10 volumio volumio[25304]: info: CoreCommandRouter::volumiosetStartupVolume Oct 29 06:35:10 volumio volumio[25304]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 29 06:35:10 volumio volumio[25304]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 29 06:35:10 volumio volumio[25304]: info: CoreCommandRouter::Close All Modals sent Oct 29 06:35:10 volumio volumio[25304]: info: CoreCommandRouter::Close All Modals sent Oct 29 06:35:11 volumio volumio[25304]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 29 06:35:11 volumio volumio[25304]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 29 06:35:11 volumio volumio[25304]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Oct 29 06:35:11 volumio volumio-remote-updater[874]: Test mode disabled Oct 29 06:35:11 volumio volumio-remote-updater[874]: Alpha mode disabled Oct 29 06:35:11 volumio volumio-remote-updater[874]: Alpha legacy test mode disabled Oct 29 06:35:11 volumio volumio[25304]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateEnabled Oct 29 06:35:11 volumio volumio[25304]: info: Update Ready: {"changeLogLink":"","description":"You're already on the latest version","title":"No Updates Available","updateavailable":false} Oct 29 06:35:11 volumio volumio[25304]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache Oct 29 06:35:11 volumio volumio[25304]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable Oct 29 06:35:11 volumio volumio[25304]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Oct 29 06:35:11 volumio volumio[25304]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect Oct 29 06:35:11 volumio volumio[25304]: info: Initializing connection to go-librespot Websocket Oct 29 06:35:11 volumio volumio[25304]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 29 06:35:12 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 187. Oct 29 06:35:12 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 29 06:35:12 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 29 06:35:12 volumio go-librespot[25722]: go-librespot daemon starting... Oct 29 06:35:12 volumio go-librespot[25723]: time="2025-10-29T06:35:12Z" level=info msg="running go-librespot 0.4.0" Oct 29 06:35:12 volumio go-librespot[25723]: time="2025-10-29T06:35:12Z" level=debug msg="app state loaded" Oct 29 06:35:12 volumio go-librespot[25723]: time="2025-10-29T06:35:12Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 29 06:35:12 volumio go-librespot[25723]: time="2025-10-29T06:35: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-gae2.spotify.com:80]" Oct 29 06:35:12 volumio go-librespot[25723]: time="2025-10-29T06:35:12Z" 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 29 06:35:12 volumio go-librespot[25723]: time="2025-10-29T06:35:12Z" 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 29 06:35:12 volumio go-librespot[25723]: time="2025-10-29T06:35:12Z" level=info msg="zeroconf server listening on port 45949" Oct 29 06:35:12 volumio go-librespot[25723]: time="2025-10-29T06:35:12Z" level=debug msg="obtained new client token: AABvQpHkZExg5MCt9TqeGYwXCpwv981fuhIvOSDoQZXsSVumOwmBFI7NCTFUp+MkTdKurVWeIBLiVW+FYZrEmvKzlpk3MBSswavwafCcjIAnaaNKrqdwy1ic1WE0hkSORbTg4lXpJnYaLryDYUDby6cYLSW8OU6u3uPwhVQzQ/WDM9lNdlDmmFv44JRMcZDA5GPBEjEcwxbK6kS8V+F/T4SQJb3pNoqlb8xkaTO8SvULSCrbpkg/mW0=" Oct 29 06:35:12 volumio go-librespot[25723]: time="2025-10-29T06:35:12Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 29 06:35:13 volumio go-librespot[25723]: time="2025-10-29T06:35:13Z" level=debug msg="completed keyexchange" Oct 29 06:35:13 volumio go-librespot[25723]: time="2025-10-29T06:35:13Z" level=debug msg="completed challenge" Oct 29 06:35:13 volumio go-librespot[25723]: time="2025-10-29T06:35:13Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 29 06:35:13 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 29 06:35:13 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 29 06:35:14 volumio volumio[25304]: info: Initializing connection to go-librespot Websocket Oct 29 06:35:14 volumio volumio[25304]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 29 06:35:15 volumio kernel: nfs: server 192.168.1.3 not responding, timed out Oct 29 06:35:16 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 188. Oct 29 06:35:16 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 29 06:35:16 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 29 06:35:16 volumio go-librespot[25730]: go-librespot daemon starting... Oct 29 06:35:16 volumio go-librespot[25731]: time="2025-10-29T06:35:16Z" level=info msg="running go-librespot 0.4.0" Oct 29 06:35:16 volumio go-librespot[25731]: time="2025-10-29T06:35:16Z" level=debug msg="app state loaded" Oct 29 06:35:16 volumio go-librespot[25731]: time="2025-10-29T06:35:16Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 29 06:35:16 volumio go-librespot[25731]: time="2025-10-29T06:35:16Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Oct 29 06:35:16 volumio go-librespot[25731]: time="2025-10-29T06:35:16Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 29 06:35:16 volumio go-librespot[25731]: time="2025-10-29T06:35:16Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 29 06:35:16 volumio go-librespot[25731]: time="2025-10-29T06:35:16Z" level=info msg="zeroconf server listening on port 41279" Oct 29 06:35:16 volumio go-librespot[25731]: time="2025-10-29T06:35:16Z" level=debug msg="obtained new client token: AAAW79dYuGsn9sf0fzExqftEjtHPdNZ+Re5lF1mZwFRMfePt5AHzvqdLhgsLyvGiOAGxXp5bx3E545FAfv52DCtlhC1r6fYQWj9MjykW0sYL8Me21JssKcsbOb/P4uDcJu9H1HJ05BtX/sfPNLBFPhSd6ptkjYqh2KwlaZ1NfahA/WcjjKnm0kT531GbUFe+eBhlpt694O1P6zP25QKDB01FaPpAUfVZTGjSku6cigwegWHEwP31Uhg=" Oct 29 06:35:16 volumio go-librespot[25731]: time="2025-10-29T06:35:16Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 29 06:35:16 volumio go-librespot[25731]: time="2025-10-29T06:35:16Z" level=debug msg="completed keyexchange" Oct 29 06:35:16 volumio go-librespot[25731]: time="2025-10-29T06:35:16Z" level=debug msg="completed challenge" Oct 29 06:35:16 volumio go-librespot[25731]: time="2025-10-29T06:35: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 29 06:35:16 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 29 06:35:16 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 29 06:35:17 volumio volumio[25304]: info: BOOT COMPLETED Oct 29 06:35:17 volumio volumio[25304]: info: Initializing connection to go-librespot Websocket Oct 29 06:35:17 volumio volumio[25304]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 29 06:35:19 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 189. Oct 29 06:35:19 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 29 06:35:19 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 29 06:35:19 volumio go-librespot[25753]: go-librespot daemon starting... Oct 29 06:35:19 volumio go-librespot[25754]: time="2025-10-29T06:35:19Z" level=info msg="running go-librespot 0.4.0" Oct 29 06:35:19 volumio go-librespot[25754]: time="2025-10-29T06:35:19Z" level=debug msg="app state loaded" Oct 29 06:35:19 volumio go-librespot[25754]: time="2025-10-29T06:35:19Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 29 06:35:19 volumio go-librespot[25754]: time="2025-10-29T06:35: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 29 06:35:19 volumio go-librespot[25754]: time="2025-10-29T06:35: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 29 06:35:19 volumio go-librespot[25754]: time="2025-10-29T06:35: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 29 06:35:19 volumio go-librespot[25754]: time="2025-10-29T06:35:19Z" level=info msg="zeroconf server listening on port 46597" Oct 29 06:35:19 volumio go-librespot[25754]: time="2025-10-29T06:35:19Z" level=debug msg="obtained new client token: AAA7I7yhGC0Rh+NBj2/H8Lrw/1b7LXjymL0Hi4JIPmR/vKNN7E9rXZPAakYo2LmF1F+wD6jcLO2xDqX6bHn+0PTgtnjSAPHelaV+MLUY3mm3m9E+1DgU6poAJ/Batr5vkjuErWwekfY07iVF3yrlyvr0IlaXOQUl77ieYPnJMWw3SXcynBmxhYPKf7qCP2OnHAxij/I3oBqDonE+6Ra1YFHOqc+6HO90DkPqKEQtsft8ylKz2HROFvU=" Oct 29 06:35:19 volumio go-librespot[25754]: time="2025-10-29T06:35:19Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 29 06:35:20 volumio go-librespot[25754]: time="2025-10-29T06:35:20Z" level=debug msg="completed keyexchange" Oct 29 06:35:20 volumio go-librespot[25754]: time="2025-10-29T06:35:20Z" level=debug msg="completed challenge" Oct 29 06:35:20 volumio go-librespot[25754]: time="2025-10-29T06:35:20Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 29 06:35:20 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 29 06:35:20 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 29 06:35:20 volumio volumio[25304]: info: Initializing connection to go-librespot Websocket Oct 29 06:35:20 volumio volumio[25304]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 29 06:35:23 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 190. Oct 29 06:35:23 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 29 06:35:23 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 29 06:35:23 volumio go-librespot[25761]: go-librespot daemon starting... Oct 29 06:35:23 volumio go-librespot[25762]: time="2025-10-29T06:35:23Z" level=info msg="running go-librespot 0.4.0" Oct 29 06:35:23 volumio go-librespot[25762]: time="2025-10-29T06:35:23Z" level=debug msg="app state loaded" Oct 29 06:35:23 volumio go-librespot[25762]: time="2025-10-29T06:35:23Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 29 06:35:23 volumio go-librespot[25762]: time="2025-10-29T06:35: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-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Oct 29 06:35:23 volumio go-librespot[25762]: time="2025-10-29T06:35:23Z" 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 29 06:35:23 volumio go-librespot[25762]: time="2025-10-29T06:35:23Z" 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 29 06:35:23 volumio go-librespot[25762]: time="2025-10-29T06:35:23Z" level=info msg="zeroconf server listening on port 44063" Oct 29 06:35:23 volumio volumio[25304]: info: Initializing connection to go-librespot Websocket Oct 29 06:35:23 volumio volumio[25304]: info: Connection to go-librespot Websocket established Oct 29 06:35:23 volumio go-librespot[25762]: time="2025-10-29T06:35:23Z" level=debug msg="new websocket client" Oct 29 06:35:26 volumio volumio[25304]: info: Getting Spotify volume Oct 29 06:35:26 volumio volumio[25304]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 4 Oct 29 06:35:26 volumio volumio[25304]: info: CoreCommandRouter::volumioGetState Oct 29 06:35:26 volumio volumio[25304]: info: CorePlayQueue::getTrack 0 Oct 29 06:35:26 volumio volumio[25304]: SPOTIFY: RECEIVED VOLUMIO VOLUME 33 Oct 29 06:35:26 volumio volumio[25304]: SPOTIFY: SPOTIFY VOLUME undefined Oct 29 06:35:26 volumio volumio[25304]: SPOTIFY: VOLUMIO VOLUME 33 Oct 29 06:35:26 volumio volumio[25304]: info: Aligning Spotify Volume to Volumio Volume Oct 29 06:35:26 volumio volumio[25304]: info: CoreCommandRouter::volumioGetState Oct 29 06:35:26 volumio volumio[25304]: info: CorePlayQueue::getTrack 0 Oct 29 06:35:26 volumio volumio[25304]: info: Setting Spotify Volume from Volumio: 33 Oct 29 06:35:27 volumio go-librespot[25762]: time="2025-10-29T06:35:27Z" level=debug msg="obtained new client token: AABJhuZsODP1UEshW9VqeiResBpKSuC8hTlYZyQcqFOXTSyX8+xj6e+47Ub6wFHP69055wUTkLvOVwHOCCeNu7a8jGmYQDEOcAdmZ59y+6ooAyqRwfDZYS7lRjxV42twiGVMyPdr31UOf7lWgvlOMdHC6hI0s2cqKGTgokU5qPl3hL25o3LobhgDxPa0k2Qfxp3NWQgXW4Ll8QdvcEUyoQUptTym+MbgisNIKG0un+Trj6KMaPuhaJ4=" Oct 29 06:35:27 volumio go-librespot[25762]: time="2025-10-29T06:35:27Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 29 06:35:27 volumio go-librespot[25762]: time="2025-10-29T06:35:27Z" level=debug msg="completed keyexchange" Oct 29 06:35:27 volumio go-librespot[25762]: time="2025-10-29T06:35:27Z" level=debug msg="completed challenge" Oct 29 06:35:27 volumio go-librespot[25762]: time="2025-10-29T06:35:27Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 29 06:35:27 volumio volumio[25304]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 29 06:35:27 volumio volumio[25304]: Error: socket hang up Oct 29 06:35:27 volumio volumio[25304]: at connResetException (node:internal/errors:720:14) Oct 29 06:35:27 volumio volumio[25304]: at Socket.socketOnEnd (node:_http_client:519:23) Oct 29 06:35:27 volumio volumio[25304]: at Socket.emit (node:events:526:35) Oct 29 06:35:27 volumio volumio[25304]: at endReadableNT (node:internal/streams/readable:1376:12) Oct 29 06:35:27 volumio volumio[25304]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { Oct 29 06:35:27 volumio volumio[25304]: code: 'ECONNRESET', Oct 29 06:35:27 volumio volumio[25304]: response: undefined Oct 29 06:35:27 volumio volumio[25304]: } Oct 29 06:35:27 volumio volumio[25304]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 29 06:35:27 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 29 06:35:27 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 29 06:35:27 volumio sudo[25786]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-10-29 06:34' Oct 29 06:35:27 volumio sudo[25786]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 29 06:35:27 volumio sudo[25786]: pam_unix(sudo:session): session closed for user root Oct 29 06:35:27 volumio volumio-remote-updater[874]: [2025-10-29 06:35:27] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Oct 29 06:35:27 volumio volumio-remote-updater[874]: [2025-10-29 06:35:27] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Oct 29 06:35:27 volumio systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Oct 29 06:35:27 volumio systemd[1]: volumio.service: Failed with result 'exit-code'. Oct 29 06:35:27 volumio systemd[1]: volumio.service: Consumed 7.711s CPU time. Oct 29 06:35:27 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Oct 29 06:35:27 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Oct 29 06:35:28 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 2026. Oct 29 06:35:28 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Oct 29 06:35:28 volumio systemd[1]: Stopped volumio.service - Volumio Backend Module. Oct 29 06:35:28 volumio systemd[1]: volumio.service: Consumed 7.711s CPU time. Oct 29 06:35:28 volumio systemd[1]: Started volumio.service - Volumio Backend Module. Oct 29 06:35:28 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Oct 29 06:35:28 volumio volumio[25809]: info: ------------------------------------------- Oct 29 06:35:28 volumio volumio[25809]: info: ----- Volumio3 ---- Oct 29 06:35:28 volumio volumio[25809]: info: ------------------------------------------- Oct 29 06:35:28 volumio volumio[25809]: info: ----- System startup ---- Oct 29 06:35:28 volumio volumio[25809]: info: ------------------------------------------- Oct 29 06:35:28 volumio volumio[25809]: info: MYVOLUMIO Environment detected Oct 29 06:35:28 volumio volumio[25809]: info: Plugin folders cleanup Oct 29 06:35:28 volumio volumio[25809]: info: Scanning into folder /volumio/app/plugins/ Oct 29 06:35:28 volumio volumio[25809]: info: Scanning category audio_interface Oct 29 06:35:28 volumio volumio[25809]: info: Scanning category miscellanea Oct 29 06:35:28 volumio volumio[25809]: info: Scanning category music_service Oct 29 06:35:28 volumio volumio[25809]: info: Scanning category plugins.json Oct 29 06:35:28 volumio volumio[25809]: info: Scanning category system_controller Oct 29 06:35:28 volumio volumio[25809]: info: Scanning category user_interface Oct 29 06:35:28 volumio volumio[25809]: info: Scanning into folder /data/plugins/ Oct 29 06:35:28 volumio volumio[25809]: info: Scanning category music_service Oct 29 06:35:28 volumio volumio[25809]: info: Scanning category user_interface Oct 29 06:35:28 volumio volumio[25809]: info: Plugin folders cleanup completed Oct 29 06:35:28 volumio volumio[25809]: info: ------------------------------------------- Oct 29 06:35:28 volumio volumio[25809]: info: ----- Core plugins startup ---- Oct 29 06:35:28 volumio volumio[25809]: info: ------------------------------------------- Oct 29 06:35:28 volumio volumio[25809]: info: Loading plugins from folder /volumio/app/plugins/ Oct 29 06:35:28 volumio volumio[25809]: info: Adding plugin upnp to MyMusic Plugins Oct 29 06:35:28 volumio volumio[25809]: info: Adding plugin airplay_emulation to MyMusic Plugins Oct 29 06:35:28 volumio volumio[25809]: info: Adding plugin upnp_browser to MyMusic Plugins Oct 29 06:35:28 volumio volumio[25809]: info: Loading plugins from folder /data/plugins/ Oct 29 06:35:28 volumio volumio[25809]: info: Loading plugin "system"... Oct 29 06:35:28 volumio volumio[25809]: info: Loading plugin "appearance"... Oct 29 06:35:28 volumio volumio[25809]: info: Loading plugin "network"... Oct 29 06:35:28 volumio volumio[25809]: info: Refreshing Cached IP Addresses Oct 29 06:35:28 volumio sudo[25834]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 29 06:35:28 volumio sudo[25834]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 29 06:35:28 volumio sudo[25834]: pam_unix(sudo:session): session closed for user root Oct 29 06:35:28 volumio volumio[25809]: info: Loading plugin "services"... Oct 29 06:35:28 volumio volumio[25809]: info: Loading plugin "alsa_controller"... Oct 29 06:35:28 volumio sudo[25836]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 29 06:35:28 volumio sudo[25836]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 29 06:35:28 volumio sudo[25836]: pam_unix(sudo:session): session closed for user root Oct 29 06:35:28 volumio volumio[25809]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 29 06:35:28 volumio volumio[25809]: info: Loading plugin "wizard"... Oct 29 06:35:28 volumio volumio[25809]: info: Loading plugin "networkfs"... Oct 29 06:35:28 volumio volumio[25809]: info: Cannot mount NAS NAS at system boot, trial number 1 ,retrying in 5 seconds Oct 29 06:35:28 volumio volumio[25809]: info: Starting Udev Watcher for removable devices Oct 29 06:35:28 volumio volumio[25809]: info: Ignoring mount for partition: boot Oct 29 06:35:28 volumio volumio[25809]: info: Ignoring mount for partition: volumio Oct 29 06:35:28 volumio volumio[25809]: info: Ignoring mount for partition: volumio_data Oct 29 06:35:28 volumio volumio[25809]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 29 06:35:28 volumio volumio[25809]: info: Loading plugin "volumio_command_line_client"... Oct 29 06:35:28 volumio volumio[25809]: info: Loading plugin "upnp"... Oct 29 06:35:28 volumio volumio[25809]: info: [1761719728829] Starting Upmpd Daemon Oct 29 06:35:28 volumio volumio[25809]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 29 06:35:28 volumio volumio[25809]: info: Loading plugin "my_music"... Oct 29 06:35:28 volumio volumio[25809]: info: Loading plugin "mpd"... Oct 29 06:35:28 volumio volumio[25809]: info: Loading plugin "upnp_browser"... Oct 29 06:35:29 volumio volumio[25809]: info: Loading plugin "alarm-clock"... Oct 29 06:35:29 volumio volumio[25809]: info: Loading plugin "airplay_emulation"... Oct 29 06:35:29 volumio volumio[25809]: info: Starting Shairport Sync Oct 29 06:35:29 volumio volumio[25809]: info: Loading plugin "last_100"... Oct 29 06:35:29 volumio volumio[25809]: info: Loading plugin "webradio"... Oct 29 06:35:29 volumio volumio[25809]: info: Loading plugin "i2s_dacs"... Oct 29 06:35:29 volumio volumio[25809]: info: I2S DAC not set, start Auto-detection Oct 29 06:35:29 volumio volumio[25809]: info: Loading plugin "volumiodiscovery"... Oct 29 06:35:29 volumio volumio[25809]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Oct 29 06:35:29 volumio volumio[25809]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 29 06:35:29 volumio volumio[25809]: *** WARNING *** For more information see Oct 29 06:35:29 volumio volumio[25809]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Oct 29 06:35:29 volumio volumio[25809]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 29 06:35:29 volumio volumio[25809]: *** WARNING *** For more information see Oct 29 06:35:29 volumio node[25809]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Oct 29 06:35:29 volumio node[25809]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 29 06:35:29 volumio node[25809]: *** WARNING *** For more information see Oct 29 06:35:29 volumio node[25809]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Oct 29 06:35:29 volumio node[25809]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 29 06:35:29 volumio node[25809]: *** WARNING *** For more information see Oct 29 06:35:29 volumio volumio[25809]: info: Applying required configuration parameters for plugin volumiodiscovery Oct 29 06:35:29 volumio volumio[25809]: info: Discovery: Started advertising with name: Volumio Oct 29 06:35:29 volumio volumio[25809]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 29 06:35:29 volumio volumio[25809]: info: Loading plugin "spop"... Oct 29 06:35:29 volumio volumio[25809]: info: Loading plugin "ytcr"... Oct 29 06:35:30 volumio volumio[25809]: info: Loading plugin "outputs"... Oct 29 06:35:30 volumio volumio[25809]: info: Loading plugin "albumart"... Oct 29 06:35:30 volumio volumio[25809]: info: Plugin example_plugin is not enabled Oct 29 06:35:30 volumio volumio[25809]: info: Loading plugin "inputs"... Oct 29 06:35:30 volumio volumio[25809]: info: Loading plugin "updater_comm"... Oct 29 06:35:30 volumio volumio[25809]: info: Plugin mpdemulation is not enabled Oct 29 06:35:30 volumio volumio[25809]: info: Loading plugin "rest_api"... Oct 29 06:35:30 volumio volumio[25809]: info: Loading plugin "websocket"... Oct 29 06:35:30 volumio volumio[25809]: info: Starting Socket.io Server version 1.7.4 Oct 29 06:35:30 volumio volumio[25809]: info: Loading plugin "Systeminfo"... Oct 29 06:35:30 volumio volumio[25809]: info: Loading i18n strings for locale en Oct 29 06:35:30 volumio volumio[25809]: Updating browse sources language Oct 29 06:35:30 volumio volumio[25809]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 29 06:35:30 volumio volumio[25866]: Forking 3 albumart workers Oct 29 06:35:30 volumio volumio[25809]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 29 06:35:30 volumio volumio[25809]: info: CoreCommandRouter::initPlayerControls Oct 29 06:35:30 volumio volumio[25809]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 29 06:35:30 volumio volumio[25809]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 29 06:35:30 volumio volumio[25809]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 29 06:35:30 volumio volumio[25809]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 29 06:35:30 volumio volumio[25809]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 29 06:35:30 volumio volumio[25809]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 29 06:35:30 volumio volumio[25809]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 29 06:35:30 volumio volumio[25809]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 29 06:35:30 volumio volumio[25809]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 29 06:35:30 volumio volumio[25809]: Express server listening on port 3000 Oct 29 06:35:30 volumio volumio[25809]: [Metrics] WebUI: 1s 963.40ms Oct 29 06:35:30 volumio volumio[25809]: info: CoreStateMachine::resetVolumioState Oct 29 06:35:30 volumio volumio[25809]: info: CoreStateMachine::getcurrentVolume Oct 29 06:35:30 volumio volumio[25809]: info: CoreCommandRouter::volumioRetrievevolume Oct 29 06:35:30 volumio volumio[25809]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 29 06:35:30 volumio volumio[25809]: info: Cannot read play queue from file Oct 29 06:35:30 volumio volumio[25809]: info: Volumio Network Manager: Network status updated: 1 Oct 29 06:35:30 volumio volumio[25809]: info: VolumeController:: Volume=33 Mute =false Oct 29 06:35:30 volumio volumio[25809]: info: CoreStateMachine::pushState Oct 29 06:35:30 volumio volumio[25809]: info: CorePlayQueue::getTrack 0 Oct 29 06:35:30 volumio volumio[25809]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 29 06:35:30 volumio volumio[25809]: info: CoreCommandRouter::volumioPushState Oct 29 06:35:30 volumio volumio[25809]: info: CoreStateMachine::updateTrackBlock Oct 29 06:35:30 volumio volumio[25809]: info: CorePlayQueue::getTrackBlock Oct 29 06:35:30 volumio volumio[25809]: info: CoreCommandRouter::volumioRetrievevolume Oct 29 06:35:30 volumio volumio[25809]: info: CoreStateMachine::setRepeat null single undefined Oct 29 06:35:30 volumio volumio[25809]: info: CoreStateMachine::pushState Oct 29 06:35:30 volumio volumio[25809]: info: CorePlayQueue::getTrack 0 Oct 29 06:35:30 volumio volumio[25809]: info: CoreCommandRouter::volumioPushState Oct 29 06:35:30 volumio volumio[25809]: info: CoreStateMachine::setRandom null Oct 29 06:35:30 volumio volumio[25809]: info: CoreStateMachine::pushState Oct 29 06:35:30 volumio volumio[25809]: info: CorePlayQueue::getTrack 0 Oct 29 06:35:30 volumio volumio[25809]: info: CoreCommandRouter::volumioPushState Oct 29 06:35:30 volumio volumio[25809]: info: Setting Device type: Raspberry PI Oct 29 06:35:30 volumio volumio[25809]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Oct 29 06:35:30 volumio volumio[25809]: info: USB Boot Capable - System SBC Revision found in cpuinfo: b04170 Oct 29 06:35:30 volumio volumio[25809]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Oct 29 06:35:30 volumio volumio[25809]: info: Discovery: adding 70853f74-8210-4683-a3fa-e1217517bd40 Oct 29 06:35:30 volumio volumio[25809]: info: Discovery: Found device Volumio Oct 29 06:35:30 volumio volumio[25809]: info: CoreCommandRouter::volumioGetState Oct 29 06:35:30 volumio volumio[25809]: info: CorePlayQueue::getTrack 0 Oct 29 06:35:30 volumio volumio[25809]: info: VolumeController:: Volume=33 Mute =false Oct 29 06:35:30 volumio volumio[25809]: info: CoreStateMachine::pushState Oct 29 06:35:30 volumio volumio[25809]: info: CorePlayQueue::getTrack 0 Oct 29 06:35:30 volumio volumio[25809]: info: CoreCommandRouter::volumioPushState Oct 29 06:35:30 volumio volumio[25809]: info: Completed loading Core Plugins Oct 29 06:35:30 volumio volumio[25809]: info: Preparing to generate the ALSA configuration file Oct 29 06:35:30 volumio volumio[25809]: info: Discovery: this is already registered, 70853f74-8210-4683-a3fa-e1217517bd40 Oct 29 06:35:30 volumio volumio[25809]: info: Discovery: Found device Volumio Oct 29 06:35:30 volumio volumio[25809]: info: CoreCommandRouter::volumioGetState Oct 29 06:35:30 volumio volumio[25809]: info: CorePlayQueue::getTrack 0 Oct 29 06:35:30 volumio volumio[25809]: info: Asound.conf file unchanged, so no further update is needed Oct 29 06:35:30 volumio volumio[25809]: info: Output device has changed, restarting MPD Oct 29 06:35:30 volumio volumio[25809]: info: Output device has changed, restarting Shairport Sync Oct 29 06:35:30 volumio volumio[25809]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 29 06:35:30 volumio volumio[25809]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 29 06:35:30 volumio volumio[25809]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 29 06:35:30 volumio volumio[25809]: info: ___________ START PLUGINS ___________ Oct 29 06:35:30 volumio volumio[25809]: info: ControllerMpd::onStart: Initializing MPD Oct 29 06:35:30 volumio volumio[25809]: info: Creating MPD Configuration file Oct 29 06:35:30 volumio sudo[25924]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 29 06:35:30 volumio sudo[25924]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 29 06:35:30 volumio sudo[25924]: pam_unix(sudo:session): session closed for user root Oct 29 06:35:30 volumio sudo[25928]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 29 06:35:30 volumio sudo[25928]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 29 06:35:30 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 191. Oct 29 06:35:30 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 29 06:35:30 volumio volumio[25809]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 29 06:35:30 volumio volumio[25809]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 29 06:35:30 volumio volumio[25809]: info: [1761719730442] CoreMusicLibrary::Adding element Media Servers Oct 29 06:35:30 volumio volumio[25809]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 29 06:35:30 volumio sudo[25936]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 29 06:35:30 volumio sudo[25936]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 29 06:35:30 volumio volumio[25809]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 29 06:35:30 volumio volumio[25809]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 29 06:35:30 volumio sudo[25934]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 29 06:35:30 volumio sudo[25934]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 29 06:35:30 volumio volumio[25809]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 29 06:35:30 volumio volumio[25809]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 29 06:35:30 volumio volumio[25809]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 29 06:35:30 volumio sudo[25934]: pam_unix(sudo:session): session closed for user root Oct 29 06:35:30 volumio volumio[25809]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 29 06:35:30 volumio volumio[25809]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 29 06:35:30 volumio volumio[25809]: info: [1761719730473] CoreMusicLibrary::Adding element Last_100 Oct 29 06:35:30 volumio volumio[25809]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 29 06:35:30 volumio volumio[25809]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 29 06:35:30 volumio volumio[25809]: info: [1761719730474] CoreMusicLibrary::Adding element Webradio Oct 29 06:35:30 volumio volumio[25809]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 29 06:35:30 volumio volumio[25809]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 29 06:35:30 volumio volumio[25809]: info: Initializing BBC Radios Oct 29 06:35:30 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 29 06:35:30 volumio go-librespot[25937]: go-librespot daemon starting... Oct 29 06:35:30 volumio go-librespot[25949]: time="2025-10-29T06:35:30Z" level=info msg="running go-librespot 0.4.0" Oct 29 06:35:30 volumio go-librespot[25949]: time="2025-10-29T06:35:30Z" level=debug msg="app state loaded" Oct 29 06:35:30 volumio go-librespot[25949]: time="2025-10-29T06:35:30Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 29 06:35:30 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Oct 29 06:35:30 volumio systemd[1]: mpd.service: Deactivated successfully. Oct 29 06:35:30 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Oct 29 06:35:30 volumio systemd[1]: mpd.socket: Deactivated successfully. Oct 29 06:35:30 volumio kernel: nfs: server 192.168.1.3 not responding, timed out Oct 29 06:35:30 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Oct 29 06:35:30 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Oct 29 06:35:30 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Oct 29 06:35:30 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Oct 29 06:35:30 volumio volumio[25809]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 29 06:35:30 volumio volumio[25809]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 29 06:35:30 volumio volumio[25809]: info: Creating Spotify config file Oct 29 06:35:30 volumio volumio[25809]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 29 06:35:30 volumio sudo[25965]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Oct 29 06:35:30 volumio sudo[25965]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Oct 29 06:35:30 volumio sudo[25965]: pam_unix(sudo:session): session closed for user root Oct 29 06:35:30 volumio go-librespot[25949]: time="2025-10-29T06:35:30Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Oct 29 06:35:30 volumio go-librespot[25949]: time="2025-10-29T06:35:30Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 29 06:35:30 volumio go-librespot[25949]: time="2025-10-29T06:35:30Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 29 06:35:30 volumio go-librespot[25949]: time="2025-10-29T06:35:30Z" level=info msg="zeroconf server listening on port 41481" Oct 29 06:35:30 volumio volumio[25809]: info: Volumio Calling Home Oct 29 06:35:30 volumio go-librespot[25949]: time="2025-10-29T06:35:30Z" level=debug msg="obtained new client token: AACq7fs1jxmcxlxzGM9ykYiht9+Z0Wak2+qudFretduXHM3QKVU9xl18BIQrnX0ex3mdQHuZ1l/xuz2Gcx/ZZ+RlYKq3jC5Jh+yQZykMIk2785ayu8qgN4vz/O+8UeaHbdfFHqHnSZM3i278QZVl+53AOHU9ZzbDkCmFzCH0AHQpsJZHgUz5Rae9cSg3hIVrQLkTrt+fR0YJ8M+UxnflA0jOGIdlPUi9w/ebNLSMPbXI08A3zZituUM=" Oct 29 06:35:30 volumio go-librespot[25949]: time="2025-10-29T06:35:30Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 29 06:35:30 volumio go-librespot[25949]: time="2025-10-29T06:35:30Z" level=debug msg="completed keyexchange" Oct 29 06:35:30 volumio go-librespot[25949]: time="2025-10-29T06:35:30Z" level=debug msg="completed challenge" Oct 29 06:35:30 volumio volumio[25809]: info: MPD Permissions set Oct 29 06:35:30 volumio volumio[25809]: info: MPD Permissions set Oct 29 06:35:30 volumio go-librespot[25949]: time="2025-10-29T06:35: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 29 06:35:30 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 29 06:35:30 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 29 06:35:30 volumio volumio[25809]: 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 29 06:35:30 volumio volumio[25809]: info: Volumio called home Oct 29 06:35:30 volumio volumio[25809]: info: Spotify config file written Oct 29 06:35:30 volumio volumio[25809]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 29 06:35:30 volumio volumio[25809]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 29 06:35:30 volumio volumio[25809]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 29 06:35:30 volumio volumio[25809]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 29 06:35:30 volumio volumio[25809]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 29 06:35:30 volumio volumio[25809]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 29 06:35:30 volumio volumio[25809]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 29 06:35:30 volumio volumio[25809]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 29 06:35:30 volumio sudo[25977]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Oct 29 06:35:30 volumio sudo[25977]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 29 06:35:30 volumio volumio[25876]: Starting albumart workers Oct 29 06:35:30 volumio volumio[25809]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 29 06:35:30 volumio volumio[25809]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 29 06:35:30 volumio volumio[25877]: Starting albumart workers Oct 29 06:35:30 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 29 06:35:30 volumio volumio[25809]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 29 06:35:30 volumio volumio[25809]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 29 06:35:30 volumio volumio[25809]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 29 06:35:30 volumio volumio[25809]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 29 06:35:30 volumio volumio[25809]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 29 06:35:30 volumio volumio[25809]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 29 06:35:30 volumio volumio[25809]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 29 06:35:30 volumio volumio[25809]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 29 06:35:30 volumio volumio[25809]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 29 06:35:30 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 29 06:35:30 volumio volumio[25809]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 29 06:35:30 volumio volumio[25809]: info: No need to fix Spotify hosts Oct 29 06:35:30 volumio go-librespot[25984]: go-librespot daemon starting... Oct 29 06:35:30 volumio sudo[25977]: pam_unix(sudo:session): session closed for user root Oct 29 06:35:30 volumio go-librespot[25990]: time="2025-10-29T06:35:30Z" level=info msg="running go-librespot 0.4.0" Oct 29 06:35:30 volumio go-librespot[25990]: time="2025-10-29T06:35:30Z" level=debug msg="app state loaded" Oct 29 06:35:30 volumio go-librespot[25990]: time="2025-10-29T06:35:30Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 29 06:35:31 volumio volumio[25878]: Starting albumart workers Oct 29 06:35:31 volumio volumio[25809]: info: Starting Shairport Sync Oct 29 06:35:31 volumio volumio[25809]: info: Starting Shairport Sync Oct 29 06:35:31 volumio volumio[25809]: info: Starting Shairport Sync Oct 29 06:35:31 volumio volumio[25809]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Oct 29 06:35:31 volumio volumio[25809]: SPOTIFY: BQCCXJ1N5JEGCk-gYO7oVBQTRS2wf5-1MtzW1HolTf9dWAYjvtX-bEtfm_73pTaftmy7ImokHMiMrUC9Dh3qEL5BZWrBrLubH73yqtvwjZL_dOzrywIbvumADjHepSL_hnb3Siz5tWDvo9r70TFn6GhaCT59K9GcLxaf5Q5512US_KIh5JB6l7DFx8zYNbmAFUMwqKk9pe4nDWIV3Ea7h32GzivZp1Zo1fLvQbQ8qN0LRw3ZSifU86u3m4EUYdcZO8DVJRjFIs1DZJfqtBT7vaa3JfMhcL9bfCyY0hP-0KwEp5rISGY Oct 29 06:35:31 volumio volumio[25809]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Oct 29 06:35:31 volumio volumio[25809]: info: New Spotify access token = BQCCXJ1N5JEGCk-gYO7oVBQTRS2wf5-1MtzW1HolTf9dWAYjvtX-bEtfm_73pTaftmy7ImokHMiMrUC9Dh3qEL5BZWrBrLubH73yqtvwjZL_dOzrywIbvumADjHepSL_hnb3Siz5tWDvo9r70TFn6GhaCT59K9GcLxaf5Q5512US_KIh5JB6l7DFx8zYNbmAFUMwqKk9pe4nDWIV3Ea7h32GzivZp1Zo1fLvQbQ8qN0LRw3ZSifU86u3m4EUYdcZO8DVJRjFIs1DZJfqtBT7vaa3JfMhcL9bfCyY0hP-0KwEp5rISGY Oct 29 06:35:31 volumio volumio[25809]: info: Spotify credentials grant success - running version from March 24, 2019 Oct 29 06:35:31 volumio sudo[26000]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 29 06:35:31 volumio sudo[26000]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 29 06:35:31 volumio sudo[26001]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 29 06:35:31 volumio sudo[26001]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 29 06:35:31 volumio sudo[26003]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 29 06:35:31 volumio sudo[26003]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 29 06:35:31 volumio go-librespot[25990]: time="2025-10-29T06:35:31Z" 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 29 06:35:31 volumio go-librespot[25990]: time="2025-10-29T06:35:31Z" 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 29 06:35:31 volumio go-librespot[25990]: time="2025-10-29T06:35:31Z" 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 29 06:35:31 volumio go-librespot[25990]: time="2025-10-29T06:35:31Z" level=info msg="zeroconf server listening on port 45447" Oct 29 06:35:31 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Oct 29 06:35:31 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Oct 29 06:35:31 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Oct 29 06:35:31 volumio systemd[1]: shairport-sync.service: Consumed 1.561s CPU time. Oct 29 06:35:31 volumio volumio[25809]: info: CoreCommandRouter::volumioGetState Oct 29 06:35:31 volumio volumio[25809]: info: CorePlayQueue::getTrack 0 Oct 29 06:35:31 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Oct 29 06:35:31 volumio sudo[26000]: pam_unix(sudo:session): session closed for user root Oct 29 06:35:31 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Oct 29 06:35:31 volumio mpd[25972]: 2025-10-29T06:35:31 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Oct 29 06:35:31 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Oct 29 06:35:31 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Oct 29 06:35:31 volumio go-librespot[25990]: time="2025-10-29T06:35:31Z" level=debug msg="obtained new client token: AAALY4dlO9oLzTwHbnt4ZbmBG3C+bahnDQePqfyUDxEupuAMAgXWlrzZ11WnoO/ITWsTGfaZ2fydF7nXuTHhq0wbY2dljEtAPUWw0esznVcIjJTqp7opFgcgxZpf6hxda3bmew/kUdZJsUMdDOYWWGgHWtQtpwwcpLfe7kw6uJVxbYORy/X6HGL5OT96/6gFDioBLPB5/Kfp7Bwbph453bzYSqXH5xg7Y8xQH6S977xSmB01k8ow" Oct 29 06:35:31 volumio systemd[1]: Started mpd.service - Music Player Daemon. Oct 29 06:35:31 volumio sudo[25936]: pam_unix(sudo:session): session closed for user root Oct 29 06:35:31 volumio volumio[25809]: info: Shairport-Sync Started Oct 29 06:35:31 volumio volumio[25809]: Error adding Membership: Error: addMembership EINVAL Oct 29 06:35:31 volumio sudo[25928]: pam_unix(sudo:session): session closed for user root Oct 29 06:35:31 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Oct 29 06:35:31 volumio sudo[26003]: pam_unix(sudo:session): session closed for user root Oct 29 06:35:31 volumio go-librespot[25990]: time="2025-10-29T06:35:31Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 29 06:35:31 volumio sudo[26001]: pam_unix(sudo:session): session closed for user root Oct 29 06:35:31 volumio volumio[25809]: info: Shairport-Sync Started Oct 29 06:35:31 volumio go-librespot[25990]: time="2025-10-29T06:35:31Z" level=debug msg="completed keyexchange" Oct 29 06:35:31 volumio go-librespot[25990]: time="2025-10-29T06:35:31Z" level=debug msg="completed challenge" Oct 29 06:35:31 volumio go-librespot[25990]: time="2025-10-29T06:35:31Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 29 06:35:31 volumio volumio[25809]: error: MPD error: The expression evaluated to a falsy value: Oct 29 06:35:31 volumio volumio[25809]: assert.ok(self.idling) Oct 29 06:35:31 volumio volumio[25809]: error: The expression evaluated to a falsy value: Oct 29 06:35:31 volumio volumio[25809]: assert.ok(self.idling) Oct 29 06:35:31 volumio volumio[25809]: info: MPD running with PID25972 Oct 29 06:35:31 volumio volumio[25809]: ,establishing connection Oct 29 06:35:31 volumio volumio[25809]: info: Shairport-Sync Started Oct 29 06:35:31 volumio volumio[25809]: error: MPD error: The expression evaluated to a falsy value: Oct 29 06:35:31 volumio volumio[25809]: assert.ok(self.idling) Oct 29 06:35:31 volumio volumio[25809]: error: The expression evaluated to a falsy value: Oct 29 06:35:31 volumio volumio[25809]: assert.ok(self.idling) Oct 29 06:35:31 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 29 06:35:31 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 29 06:35:31 volumio volumio[25809]: error: updateQueue error: null Oct 29 06:35:31 volumio volumio[25809]: 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 29 06:35:31 volumio volumio[25809]: info: Spotify Successfully logged in Oct 29 06:35:31 volumio volumio[25809]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 29 06:35:31 volumio volumio[25809]: info: [1761719731308] CoreMusicLibrary::Adding element Spotify Oct 29 06:35:31 volumio volumio[25809]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 29 06:35:31 volumio volumio[25809]: Cannot find translation for source Spotify Oct 29 06:35:31 volumio volumio[25809]: info: [yt-cast-receiver] DIAL server listening on port 8098 Oct 29 06:35:31 volumio volumio[25809]: info: CoreCommandRouter::volumioRetrievevolume Oct 29 06:35:31 volumio volumio[25809]: info: VolumeController:: Volume=33 Mute =false Oct 29 06:35:31 volumio volumio[25809]: info: CoreCommandRouter::volumioGetState Oct 29 06:35:31 volumio volumio[25809]: info: CorePlayQueue::getTrack 0 Oct 29 06:35:31 volumio volumio[25809]: info: CoreStateMachine::pushState Oct 29 06:35:31 volumio volumio[25809]: info: CorePlayQueue::getTrack 0 Oct 29 06:35:31 volumio volumio[25809]: info: CoreCommandRouter::volumioPushState Oct 29 06:35:31 volumio volumio[25809]: info: Completed starting Core Plugins Oct 29 06:35:31 volumio volumio[25809]: info: ------------------------------------------- Oct 29 06:35:31 volumio volumio[25809]: info: ----- MyVolumio plugins startup ---- Oct 29 06:35:31 volumio volumio[25809]: info: ------------------------------------------- Oct 29 06:35:31 volumio volumio[25809]: info: [MyVolumio PluginManager] Fetching plans data.... Oct 29 06:35:32 volumio volumio-remote-updater[874]: [2025-10-29 06:35:32] [connect] Successful connection Oct 29 06:35:32 volumio volumio-remote-updater[874]: [2025-10-29 06:35:32] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1761719732 101 Oct 29 06:35:32 volumio volumio[25809]: 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 29 06:35:33 volumio volumio[25809]: info: Cannot mount NAS NAS at system boot, trial number 2 ,retrying in 5 seconds Oct 29 06:35:34 volumio volumio[25809]: info: go-librespot daemon successfully initialized Oct 29 06:35:34 volumio systemd[1]: Starting setdatetime-helper.service - Time Synchronization Helper Service... Oct 29 06:35:34 volumio sudo[26071]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Oct 29 06:35:34 volumio sudo[26071]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 29 06:35:34 volumio systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Oct 29 06:35:34 volumio systemd[1]: mpd_monitor.service: Deactivated successfully. Oct 29 06:35:34 volumio systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Oct 29 06:35:34 volumio systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Oct 29 06:35:34 volumio mpd_monitor.sh[26073]: MPD Monitor Service: Starting MPD Monitor Service Oct 29 06:35:34 volumio sudo[26071]: pam_unix(sudo:session): session closed for user root Oct 29 06:35:34 volumio volumio[25809]: info: Successfully started MPD Monitor Oct 29 06:35:34 volumio sudo[26078]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Oct 29 06:35:34 volumio sudo[26078]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 29 06:35:34 volumio systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Oct 29 06:35:34 volumio systemd[1]: mpd_monitor.service: Deactivated successfully. Oct 29 06:35:34 volumio systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Oct 29 06:35:34 volumio systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Oct 29 06:35:34 volumio mpd_monitor.sh[26081]: MPD Monitor Service: Starting MPD Monitor Service Oct 29 06:35:34 volumio sudo[26078]: pam_unix(sudo:session): session closed for user root Oct 29 06:35:34 volumio volumio[25809]: info: Successfully started MPD Monitor Oct 29 06:35:34 volumio systemd[1]: setdatetime-helper.service: Deactivated successfully. Oct 29 06:35:34 volumio systemd[1]: Finished setdatetime-helper.service - Time Synchronization Helper Service. Oct 29 06:35:34 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 192. Oct 29 06:35:34 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 29 06:35:34 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 29 06:35:34 volumio go-librespot[26089]: go-librespot daemon starting... Oct 29 06:35:34 volumio go-librespot[26090]: time="2025-10-29T06:35:34Z" level=info msg="running go-librespot 0.4.0" Oct 29 06:35:34 volumio go-librespot[26090]: time="2025-10-29T06:35:34Z" level=debug msg="app state loaded" Oct 29 06:35:34 volumio go-librespot[26090]: time="2025-10-29T06:35:34Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 29 06:35:34 volumio go-librespot[26090]: time="2025-10-29T06:35:34Z" 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 29 06:35:34 volumio go-librespot[26090]: time="2025-10-29T06:35:34Z" 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 29 06:35:34 volumio go-librespot[26090]: time="2025-10-29T06:35:34Z" 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 29 06:35:34 volumio go-librespot[26090]: time="2025-10-29T06:35:34Z" level=info msg="zeroconf server listening on port 36207" Oct 29 06:35:34 volumio go-librespot[26090]: time="2025-10-29T06:35:34Z" level=debug msg="obtained new client token: AAALvinsuOEC1TlMtM7TvpcvHUEnA02C6AcKvoQVa+wMqiBxx+Mi/qWHLxSA0SRF2srS/6oqF1NZ9ioUgEBmXn2oz8vJY3pF/bs2BQZzuoPE8pKls25XIJdvcNM9Oy57ayBp/H+UCQ3iy8jxkaLiV+L6dU2lqIFfdrLEjltFCVfNP3GU0E9hcsKKahGjf+EANne6zwzQNafFWKIJt/KVPR6ORU/WkY3mOSy7N86D6g7OngmkMcSu/RM=" Oct 29 06:35:34 volumio go-librespot[26090]: time="2025-10-29T06:35:34Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 29 06:35:34 volumio go-librespot[26090]: time="2025-10-29T06:35:34Z" level=debug msg="completed keyexchange" Oct 29 06:35:34 volumio go-librespot[26090]: time="2025-10-29T06:35:34Z" level=debug msg="completed challenge" Oct 29 06:35:34 volumio go-librespot[26090]: time="2025-10-29T06:35:34Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 29 06:35:34 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 29 06:35:34 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 29 06:35:36 volumio volumio[25809]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Oct 29 06:35:37 volumio volumio[25809]: info: Initializing connection to go-librespot Websocket Oct 29 06:35:37 volumio volumio[25809]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 29 06:35:37 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 193. Oct 29 06:35:37 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 29 06:35:37 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 29 06:35:37 volumio go-librespot[26097]: go-librespot daemon starting... Oct 29 06:35:37 volumio go-librespot[26098]: time="2025-10-29T06:35:37Z" level=info msg="running go-librespot 0.4.0" Oct 29 06:35:37 volumio go-librespot[26098]: time="2025-10-29T06:35:37Z" level=debug msg="app state loaded" Oct 29 06:35:37 volumio go-librespot[26098]: time="2025-10-29T06:35:37Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 29 06:35:37 volumio go-librespot[26098]: time="2025-10-29T06:35:37Z" 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 29 06:35:37 volumio go-librespot[26098]: time="2025-10-29T06:35:37Z" 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 29 06:35:37 volumio go-librespot[26098]: time="2025-10-29T06:35:37Z" 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 29 06:35:37 volumio go-librespot[26098]: time="2025-10-29T06:35:37Z" level=info msg="zeroconf server listening on port 34073" Oct 29 06:35:37 volumio go-librespot[26098]: time="2025-10-29T06:35:37Z" level=debug msg="obtained new client token: AABsxn4qESCrIo+5kvZdrDjR6kPp+WJxCJ0dG6Xj47eDcElZonghqeY9LMViD83nEMEOMsgXGeYwxVM1hUqqPcqxw4v93fQmppyg7BjnVcJFMZTHUhdgSA7QB0IE4Th4FZfW43JQXQK+GUlLlMtfYr7XHMQjrcv9Fk6HJjmz4eDG8LQ5LmT4/vUhnGgC1Sm6mg745tbKmI2CAko3P5LPiuTlAD49ZTg2M+rGFKqY9EGuVL4Oot40GpU=" Oct 29 06:35:37 volumio go-librespot[26098]: time="2025-10-29T06:35:37Z" 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 29 06:35:37 volumio go-librespot[26098]: time="2025-10-29T06:35:37Z" level=debug msg="connected to ap-gew1.spotify.com:443" Oct 29 06:35:38 volumio go-librespot[26098]: time="2025-10-29T06:35:38Z" level=debug msg="completed keyexchange" Oct 29 06:35:38 volumio go-librespot[26098]: time="2025-10-29T06:35:38Z" level=debug msg="completed challenge" Oct 29 06:35:38 volumio go-librespot[26098]: time="2025-10-29T06:35:38Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 29 06:35:38 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 29 06:35:38 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 29 06:35:38 volumio volumio[25809]: info: Cannot mount NAS NAS at system boot, trial number 3 ,retrying in 5 seconds Oct 29 06:35:38 volumio sudo[26120]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 29 06:35:38 volumio sudo[26120]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 29 06:35:38 volumio sudo[26122]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 29 06:35:38 volumio sudo[26122]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 29 06:35:38 volumio sudo[26122]: pam_unix(sudo:session): session closed for user root Oct 29 06:35:38 volumio sudo[26120]: pam_unix(sudo:session): session closed for user root Oct 29 06:35:38 volumio sudo[26126]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Oct 29 06:35:38 volumio sudo[26126]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 29 06:35:38 volumio sudo[26126]: pam_unix(sudo:session): session closed for user root Oct 29 06:35:38 volumio volumio[25809]: info: Upmpdcli Daemon Started Oct 29 06:35:39 volumio volumio[25809]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Oct 29 06:35:39 volumio volumio[25809]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Oct 29 06:35:39 volumio volumio[25809]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Oct 29 06:35:39 volumio volumio[25809]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Oct 29 06:35:39 volumio volumio[25809]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Oct 29 06:35:39 volumio volumio[25809]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Oct 29 06:35:39 volumio volumio[25809]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Oct 29 06:35:39 volumio volumio[25809]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Oct 29 06:35:39 volumio volumio[25809]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Oct 29 06:35:39 volumio volumio[25809]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Oct 29 06:35:39 volumio volumio[25809]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Oct 29 06:35:39 volumio volumio[25809]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Oct 29 06:35:39 volumio volumio[25809]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Oct 29 06:35:39 volumio volumio[25809]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Oct 29 06:35:39 volumio volumio[25809]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Oct 29 06:35:39 volumio volumio[25809]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Oct 29 06:35:39 volumio volumio[25809]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Oct 29 06:35:39 volumio volumio[25809]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Oct 29 06:35:39 volumio volumio[25809]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Oct 29 06:35:39 volumio volumio[25809]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Oct 29 06:35:39 volumio volumio[25809]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Oct 29 06:35:39 volumio volumio[25809]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Oct 29 06:35:39 volumio volumio[25809]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Oct 29 06:35:39 volumio volumio[25809]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Oct 29 06:35:39 volumio volumio[25809]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Oct 29 06:35:39 volumio volumio[25809]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Oct 29 06:35:39 volumio volumio[25809]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Oct 29 06:35:39 volumio volumio[25809]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Oct 29 06:35:39 volumio volumio[25809]: info: Adding plugin bluetooth to MyMusic Plugins Oct 29 06:35:39 volumio volumio[25809]: info: Adding plugin multiroom to MyMusic Plugins Oct 29 06:35:39 volumio volumio[25809]: info: Adding plugin metavolumio to MyMusic Plugins Oct 29 06:35:39 volumio volumio[25809]: info: Adding plugin cd_controller to MyMusic Plugins Oct 29 06:35:39 volumio volumio[25809]: info: Adding plugin qobuzconnect to MyMusic Plugins Oct 29 06:35:39 volumio volumio[25809]: info: Adding plugin smart_inputs to MyMusic Plugins Oct 29 06:35:39 volumio volumio[25809]: info: Adding plugin tidalconnect to MyMusic Plugins Oct 29 06:35:39 volumio volumio[25809]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Oct 29 06:35:39 volumio volumio[25809]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Oct 29 06:35:39 volumio volumio[25809]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Oct 29 06:35:39 volumio volumio[25809]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 29 06:35:39 volumio volumio[25809]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 29 06:35:39 volumio volumio[25809]: info: Starting MyVolumio Remote Streaming Endpoints Oct 29 06:35:39 volumio volumio[25809]: info: MyVolumio login type: Token Oct 29 06:35:39 volumio volumio[25809]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Oct 29 06:35:39 volumio volumio[25809]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Oct 29 06:35:40 volumio volumio[25809]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Oct 29 06:35:40 volumio volumio[25809]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Oct 29 06:35:40 volumio volumio[25809]: info: Streaming services startup Oct 29 06:35:40 volumio volumio[25809]: info: Starting Streaming Daemon Oct 29 06:35:40 volumio sudo[26129]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Oct 29 06:35:40 volumio sudo[26129]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 29 06:35:40 volumio volumio[25809]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Oct 29 06:35:40 volumio sudo[26129]: pam_unix(sudo:session): session closed for user root Oct 29 06:35:40 volumio volumio[25809]: info: Initializing connection to go-librespot Websocket Oct 29 06:35:40 volumio volumio[25809]: error: Cannot start Volumio Streaming Daemon Oct 29 06:35:40 volumio volumio[25809]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Oct 29 06:35:40 volumio volumio[25809]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Oct 29 06:35:40 volumio volumio[25809]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 29 06:35:40 volumio kernel: nfs: server 192.168.1.3 not responding, timed out Oct 29 06:35:40 volumio volumio[25809]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Oct 29 06:35:40 volumio volumio[25809]: info: MyVolumio token set successfully Oct 29 06:35:40 volumio volumio[25809]: info: MYVOLUMIO: Adding device Oct 29 06:35:40 volumio volumio[25809]: info: MYVOLUMIO: Evaluating Server Oct 29 06:35:41 volumio volumio[25809]: info: MyVolumio status changed Oct 29 06:35:41 volumio volumio[25809]: info: Streaming services startup Oct 29 06:35:41 volumio volumio[25809]: info: Starting Streaming Daemon Oct 29 06:35:41 volumio volumio[25809]: info: Removing browser output: myVolumio user plan is not superstar Oct 29 06:35:41 volumio volumio[25809]: info: Removing audio output: Oct 29 06:35:41 volumio volumio[25809]: info: Stoppping Tunnel 1 Oct 29 06:35:41 volumio sudo[26155]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service Oct 29 06:35:41 volumio sudo[26155]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 29 06:35:41 volumio sudo[26153]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Oct 29 06:35:41 volumio sudo[26153]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 29 06:35:41 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 194. Oct 29 06:35:41 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 29 06:35:41 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 29 06:35:41 volumio go-librespot[26158]: go-librespot daemon starting... Oct 29 06:35:41 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 29 06:35:41 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 29 06:35:41 volumio sudo[26153]: pam_unix(sudo:session): session closed for user root Oct 29 06:35:41 volumio volumio[25809]: error: Cannot start Volumio Streaming Daemon Oct 29 06:35:41 volumio volumio[25809]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Oct 29 06:35:41 volumio volumio[25809]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Oct 29 06:35:41 volumio go-librespot[26159]: time="2025-10-29T06:35:41Z" level=info msg="running go-librespot 0.4.0" Oct 29 06:35:41 volumio go-librespot[26159]: time="2025-10-29T06:35:41Z" level=debug msg="app state loaded" Oct 29 06:35:41 volumio go-librespot[26159]: time="2025-10-29T06:35:41Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 29 06:35:41 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 29 06:35:41 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 29 06:35:41 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 29 06:35:41 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 29 06:35:41 volumio sudo[26155]: pam_unix(sudo:session): session closed for user root Oct 29 06:35:41 volumio volumio[25809]: info: Remote SSH Stopped Oct 29 06:35:41 volumio go-librespot[26159]: time="2025-10-29T06:35:41Z" 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 29 06:35:41 volumio go-librespot[26159]: time="2025-10-29T06:35:41Z" 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 29 06:35:41 volumio go-librespot[26159]: time="2025-10-29T06:35:41Z" 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 29 06:35:41 volumio go-librespot[26159]: time="2025-10-29T06:35:41Z" level=info msg="zeroconf server listening on port 44447" Oct 29 06:35:41 volumio go-librespot[26159]: time="2025-10-29T06:35:41Z" level=debug msg="obtained new client token: AABvJo+Vtbd+8XLAQVX8jGyBLbY9W1aG7lGcnI/YnbPXE539cL5J4nSc8ie6LZu4YRzv4vqBDAwcqONNgW6IvRtKEZWQOs8vgWr0K9NnBVV2eSUMtUlWfVFcun5IdoqZZucej1WVS7JgGdxUibsdIyl/9+3dgqn/fIBfwr70L04iQwZ20b40eBjJv+fGh4aOYWKaQtqK8F4HvamVrxJububUxaZmmuXtXHSsjG1fozMBTaSuKnpVX3g=" Oct 29 06:35:41 volumio go-librespot[26159]: time="2025-10-29T06:35:41Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 29 06:35:41 volumio go-librespot[26159]: time="2025-10-29T06:35:41Z" level=debug msg="completed keyexchange" Oct 29 06:35:41 volumio go-librespot[26159]: time="2025-10-29T06:35:41Z" level=debug msg="completed challenge" Oct 29 06:35:41 volumio volumio[25809]: info: Setting Geolocation for MyVolumio to eu3 Oct 29 06:35:41 volumio volumio[25809]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 29 06:35:41 volumio volumio[25809]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 29 06:35:41 volumio volumio[25809]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 29 06:35:41 volumio go-librespot[26159]: time="2025-10-29T06:35:41Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 29 06:35:41 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 29 06:35:41 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 29 06:35:41 volumio volumio[25809]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Oct 29 06:35:42 volumio volumio[25809]: info: Updating MyVolumio device info Oct 29 06:35:42 volumio volumio[25809]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 29 06:35:42 volumio volumio[25809]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 29 06:35:42 volumio volumio[25809]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 29 06:35:42 volumio volumio[25809]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Oct 29 06:35:43 volumio volumio[25809]: info: Initializing connection to go-librespot Websocket Oct 29 06:35:43 volumio volumio[25809]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 29 06:35:43 volumio volumio[25809]: info: Cannot mount NAS NAS at system boot, trial number 4 ,retrying in 5 seconds Oct 29 06:35:44 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 195. Oct 29 06:35:44 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 29 06:35:44 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 29 06:35:44 volumio go-librespot[26167]: go-librespot daemon starting... Oct 29 06:35:44 volumio go-librespot[26168]: time="2025-10-29T06:35:44Z" level=info msg="running go-librespot 0.4.0" Oct 29 06:35:44 volumio go-librespot[26168]: time="2025-10-29T06:35:44Z" level=debug msg="app state loaded" Oct 29 06:35:44 volumio go-librespot[26168]: time="2025-10-29T06:35:44Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 29 06:35:44 volumio go-librespot[26168]: time="2025-10-29T06:35: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 29 06:35:44 volumio go-librespot[26168]: time="2025-10-29T06:35: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 29 06:35:44 volumio go-librespot[26168]: time="2025-10-29T06:35: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 29 06:35:44 volumio go-librespot[26168]: time="2025-10-29T06:35:44Z" level=info msg="zeroconf server listening on port 45235" Oct 29 06:35:44 volumio go-librespot[26168]: time="2025-10-29T06:35:44Z" level=debug msg="obtained new client token: AABsIAYTpW92MLjRIpCJkczfL+HhRIrafP3aPwKc0/75BRrDK7us0yf5798QBJDyDpIY0AetG+/FUWNo/RTD1Pumrzt9o6CRhKNlX0kgGKNwQz8COOZgEoASmgwQE/cM5xJMSLsLsSAFY4AemCLR61MjlJeAT2ksDWvCbOD/DkHpdXMhlYLU0fLgt3lUh8YqMMoj+cEpl19zS3MDJ8bxzUiB6v4LzJbiUA8d2WkcqUYp0ygLTNEObVs=" Oct 29 06:35:44 volumio go-librespot[26168]: time="2025-10-29T06:35:44Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 29 06:35:44 volumio go-librespot[26168]: time="2025-10-29T06:35:44Z" level=debug msg="completed keyexchange" Oct 29 06:35:44 volumio go-librespot[26168]: time="2025-10-29T06:35:44Z" level=debug msg="completed challenge" Oct 29 06:35:44 volumio go-librespot[26168]: time="2025-10-29T06:35: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 29 06:35:44 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 29 06:35:44 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 29 06:35:45 volumio volumio[25809]: info: MYVOLUMIO: Adding device Oct 29 06:35:45 volumio volumio[25809]: info: MYVOLUMIO: Evaluating Server Oct 29 06:35:46 volumio volumio[25809]: info: Setting Geolocation for MyVolumio to eu3 Oct 29 06:35:46 volumio volumio[25809]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 29 06:35:46 volumio volumio[25809]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 29 06:35:46 volumio volumio[25809]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 29 06:35:46 volumio volumio[25809]: info: Initializing connection to go-librespot Websocket Oct 29 06:35:46 volumio volumio[25809]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 29 06:35:46 volumio volumio[25809]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Oct 29 06:35:47 volumio volumio[25809]: info: Updating MyVolumio device info Oct 29 06:35:47 volumio volumio[25809]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 29 06:35:47 volumio volumio[25809]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 29 06:35:47 volumio volumio[25809]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 29 06:35:47 volumio volumio[25809]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Oct 29 06:35:48 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 196. Oct 29 06:35:48 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 29 06:35:48 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 29 06:35:48 volumio go-librespot[26190]: go-librespot daemon starting... Oct 29 06:35:48 volumio go-librespot[26191]: time="2025-10-29T06:35:48Z" level=info msg="running go-librespot 0.4.0" Oct 29 06:35:48 volumio go-librespot[26191]: time="2025-10-29T06:35:48Z" level=debug msg="app state loaded" Oct 29 06:35:48 volumio go-librespot[26191]: time="2025-10-29T06:35:48Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 29 06:35:48 volumio go-librespot[26191]: time="2025-10-29T06:35:48Z" 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 29 06:35:48 volumio go-librespot[26191]: time="2025-10-29T06:35:48Z" 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 29 06:35:48 volumio go-librespot[26191]: time="2025-10-29T06:35:48Z" 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 29 06:35:48 volumio go-librespot[26191]: time="2025-10-29T06:35:48Z" level=info msg="zeroconf server listening on port 45955" Oct 29 06:35:48 volumio go-librespot[26191]: time="2025-10-29T06:35:48Z" level=debug msg="obtained new client token: AABXuD5pqZvvascwWPf9RvUjFrM2P93wkiLXhV4sR8FA1opoMzr3LbV8nTT83BTGwFgCA3/Jm7fRxqKclgPPnjv4TjaculbB2IgIr/6lrrFJWvlLdF4X5uZ539WoNHfPrUffrX4ESJFWiOuZS5UaSu2tKD+2SAr2mHuC20tx6CCLoRo47Mful152JHvQBlsJ9zaoc9Oivhyw/wc5Ng9JtBsb2TlTcTr0rIVWa893TpQkH7XM3f/5" Oct 29 06:35:48 volumio go-librespot[26191]: time="2025-10-29T06:35:48Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 29 06:35:48 volumio go-librespot[26191]: time="2025-10-29T06:35:48Z" level=debug msg="completed keyexchange" Oct 29 06:35:48 volumio go-librespot[26191]: time="2025-10-29T06:35:48Z" level=debug msg="completed challenge" Oct 29 06:35:48 volumio go-librespot[26191]: time="2025-10-29T06:35:48Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 29 06:35:48 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 29 06:35:48 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 29 06:35:48 volumio volumio[25809]: info: Cannot mount NAS at system boot, trial number 4 ,stopping Oct 29 06:35:49 volumio volumio[25809]: info: Initializing connection to go-librespot Websocket Oct 29 06:35:49 volumio volumio[25809]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 29 06:35:51 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 197. Oct 29 06:35:51 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 29 06:35:51 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 29 06:35:51 volumio go-librespot[26213]: go-librespot daemon starting... Oct 29 06:35:51 volumio go-librespot[26214]: time="2025-10-29T06:35:51Z" level=info msg="running go-librespot 0.4.0" Oct 29 06:35:51 volumio go-librespot[26214]: time="2025-10-29T06:35:51Z" level=debug msg="app state loaded" Oct 29 06:35:51 volumio go-librespot[26214]: time="2025-10-29T06:35:51Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 29 06:35:51 volumio go-librespot[26214]: time="2025-10-29T06:35: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 29 06:35:51 volumio go-librespot[26214]: time="2025-10-29T06:35: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 29 06:35:51 volumio go-librespot[26214]: time="2025-10-29T06:35: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 29 06:35:51 volumio go-librespot[26214]: time="2025-10-29T06:35:51Z" level=info msg="zeroconf server listening on port 41805" Oct 29 06:35:51 volumio go-librespot[26214]: time="2025-10-29T06:35:51Z" level=debug msg="obtained new client token: AAAsgUQMq0Li8mASmpOD4BTnQLkj2X8IaU9V9n/YNNUgtGiyWDwksfPi6RrDxu2ANImfx4UBz4A037B2P+C1A8IUG/j2SRhh1GWUAhkJHyu4UsZ4e1SOaNUx6NHXyX75ZjjUfHNRXh/xBG4vZLOJSaMucMHbRyHgiVtLkxjDHhz3mknV8L3dQ/Hl3YWNMFLenHyICoFFfCdOZHpyDBxbVdjCsFS1WRmhGOvH+h7lty4X9hF0w5z/Mtg=" Oct 29 06:35:51 volumio go-librespot[26214]: time="2025-10-29T06:35:51Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 29 06:35:51 volumio go-librespot[26214]: time="2025-10-29T06:35:51Z" level=debug msg="completed keyexchange" Oct 29 06:35:51 volumio go-librespot[26214]: time="2025-10-29T06:35:51Z" level=debug msg="completed challenge" Oct 29 06:35:51 volumio go-librespot[26214]: time="2025-10-29T06:35: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 29 06:35:51 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 29 06:35:51 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 29 06:35:52 volumio volumio[25809]: info: Initializing connection to go-librespot Websocket Oct 29 06:35:52 volumio volumio[25809]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 29 06:35:54 volumio volumio[25809]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Oct 29 06:35:54 volumio volumio[25809]: 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 29 06:35:55 volumio volumio[25809]: info: CoreCommandRouter::volumioGetState Oct 29 06:35:55 volumio volumio[25809]: info: CorePlayQueue::getTrack 0 Oct 29 06:35:55 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 198. Oct 29 06:35:55 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 29 06:35:55 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 29 06:35:55 volumio go-librespot[26224]: go-librespot daemon starting... Oct 29 06:35:55 volumio go-librespot[26225]: time="2025-10-29T06:35:55Z" level=info msg="running go-librespot 0.4.0" Oct 29 06:35:55 volumio go-librespot[26225]: time="2025-10-29T06:35:55Z" level=debug msg="app state loaded" Oct 29 06:35:55 volumio go-librespot[26225]: time="2025-10-29T06:35:55Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 29 06:35:55 volumio go-librespot[26225]: time="2025-10-29T06:35:55Z" 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 29 06:35:55 volumio go-librespot[26225]: time="2025-10-29T06:35:55Z" 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 29 06:35:55 volumio go-librespot[26225]: time="2025-10-29T06:35:55Z" 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 29 06:35:55 volumio go-librespot[26225]: time="2025-10-29T06:35:55Z" level=info msg="zeroconf server listening on port 45613" Oct 29 06:35:55 volumio volumio[25809]: info: Initializing connection to go-librespot Websocket Oct 29 06:35:55 volumio volumio[25809]: info: Connection to go-librespot Websocket established Oct 29 06:35:55 volumio go-librespot[26225]: time="2025-10-29T06:35:55Z" level=debug msg="new websocket client" Oct 29 06:35:55 volumio go-librespot[26225]: time="2025-10-29T06:35:55Z" level=debug msg="obtained new client token: AABTFOFJvhU4uS6hIyymwynsuVGLe50iASWHZ9v1DNT9A+q3hfXNdlPZRoiD65JV5H2qe8UZq2uosFK0fGxQrB/APIbKCF6KIPm2THHSiFuMnTYAE2ZauokmlKrs2kjDomZgCYFpT4mQuy1ZLjvzV+psAW2PByV14cFAyOhy+YwZlnvja+k5gfwvFaRvI/qpbjzJjZTtywhAwPEHs+Sc8pY9nW9MX2Ri4wJ3b2iaSPjxlUerHWMN" Oct 29 06:35:55 volumio go-librespot[26225]: time="2025-10-29T06:35:55Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 29 06:35:55 volumio go-librespot[26225]: time="2025-10-29T06:35:55Z" level=debug msg="completed keyexchange" Oct 29 06:35:55 volumio go-librespot[26225]: time="2025-10-29T06:35:55Z" level=debug msg="completed challenge" Oct 29 06:35:55 volumio go-librespot[26225]: time="2025-10-29T06:35:55Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 29 06:35:55 volumio volumio[25809]: info: Connection to go-librespot Websocket closed Oct 29 06:35:55 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 29 06:35:55 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 29 06:35:56 volumio kernel: nfs: server 192.168.1.3 not responding, timed out Oct 29 06:35:58 volumio volumio[25809]: info: Getting Spotify volume Oct 29 06:35:58 volumio volumio[25809]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 29 06:35:58 volumio volumio[25809]: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 29 06:35:58 volumio volumio[25809]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Oct 29 06:35:58 volumio volumio[25809]: errno: -111, Oct 29 06:35:58 volumio volumio[25809]: code: 'ECONNREFUSED', Oct 29 06:35:58 volumio volumio[25809]: syscall: 'connect', Oct 29 06:35:58 volumio volumio[25809]: address: '127.0.0.1', Oct 29 06:35:58 volumio volumio[25809]: port: 9879, Oct 29 06:35:58 volumio volumio[25809]: response: undefined Oct 29 06:35:58 volumio volumio[25809]: } Oct 29 06:35:58 volumio volumio[25809]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 29 06:35:58 volumio sudo[26246]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-10-29 06:34' Oct 29 06:35:58 volumio sudo[26246]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) PRETTY_NAME="Raspbian GNU/Linux 12 (bookworm)" NAME="Raspbian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="c22b72a8acb34a699a626adb0a09a6b88ee7233a" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="40400d6a6fa57cf20e36499e510876b3654e9c4e" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Sat Oct 4 16:40:08 UTC 2025" VOLUMIO_VERSION="4.061" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="7f8ace80645f85765fa10c72d1769d04"