Dec 21 15:39:18 volumio3840x2160 ntpd[1136]: CLOCK: time stepped by 102.267836 Dec 21 15:39:18 volumio3840x2160 ntpd[1136]: INIT: MRU 13107 entries, 13 hash bits, 32768 bytes Dec 21 15:39:18 volumio3840x2160 volumio[1372]: info: MyVolumio Plan changed: premium Dec 21 15:39:18 volumio3840x2160 volumio[1372]: info: [MyVolumio PluginManager] Subscribed plan changed to premium Dec 21 15:39:18 volumio3840x2160 volumio[1372]: info: Removing browser output: myVolumio user plan is not superstar Dec 21 15:39:18 volumio3840x2160 volumio[1372]: info: Removing audio output: Dec 21 15:39:18 volumio3840x2160 volumio[1372]: info: MYVOLUMIO: Adding device Dec 21 15:39:18 volumio3840x2160 volumio[1372]: info: MYVOLUMIO: Evaluating Server Dec 21 15:39:18 volumio3840x2160 volumio[1372]: info: Remote config written successfully Dec 21 15:39:18 volumio3840x2160 volumio[1372]: info: Starting Tunnel 1 Dec 21 15:39:18 volumio3840x2160 volumio[1372]: info: Starting Tunnel Connection Checker Dec 21 15:39:18 volumio3840x2160 volumio[1372]: info: Completed starting MyVolumio Plugin Dec 21 15:39:18 volumio3840x2160 go-librespot[2160]: time="2025-12-21T15:39:18+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Dec 21 15:39:18 volumio3840x2160 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 21 15:39:18 volumio3840x2160 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 21 15:39:18 volumio3840x2160 volumio[1372]: info: MYVolumio Device enabled Dec 21 15:39:18 volumio3840x2160 volumio[1372]: info: [MyVolumio PluginManager] Device activated, enabling myvolumio plugins... Dec 21 15:39:18 volumio3840x2160 volumio[1372]: info: MyVolumio status changed Dec 21 15:39:18 volumio3840x2160 volumio[1372]: info: Streaming services startup Dec 21 15:39:18 volumio3840x2160 volumio[1372]: info: Starting Streaming Daemon Dec 21 15:39:18 volumio3840x2160 volumio[1372]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getHwuuid Dec 21 15:39:18 volumio3840x2160 volumio[1372]: info: [MyVolumio PluginManager] Loading plugin "bluetooth"... Dec 21 15:39:18 volumio3840x2160 sudo[2206]: volumio : unable to resolve host volumio3840x2160: System error Dec 21 15:39:18 volumio3840x2160 sudo[2206]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Dec 21 15:39:18 volumio3840x2160 sudo[2206]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 21 15:39:18 volumio3840x2160 sudo[2206]: pam_unix(sudo:session): session closed for user root Dec 21 15:39:18 volumio3840x2160 volumio[1372]: ------------------------------------ BT MESSAGE: [FUNC] onVolumioStart Dec 21 15:39:18 volumio3840x2160 volumio[1372]: info: [MyVolumio PluginManager] Loading plugin "multiroom"... Dec 21 15:39:18 volumio3840x2160 volumio[1372]: info: [MyVolumio PluginManager] Applying required configuration parameters for plugin multiroom Dec 21 15:39:18 volumio3840x2160 sudo[2211]: volumio : unable to resolve host volumio3840x2160: System error Dec 21 15:39:18 volumio3840x2160 sudo[2211]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/rm -rf /tmp/multiroom Dec 21 15:39:18 volumio3840x2160 sudo[2211]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 21 15:39:18 volumio3840x2160 sudo[2211]: pam_unix(sudo:session): session closed for user root Dec 21 15:39:18 volumio3840x2160 volumio[1372]: sudo: unable to resolve host volumio3840x2160: System error Dec 21 15:39:18 volumio3840x2160 volumio[1372]: info: MRS: MultiRoom plugin initialized Dec 21 15:39:18 volumio3840x2160 volumio[1372]: info: MRS: STOPPING SNAPCLIENT Dec 21 15:39:18 volumio3840x2160 volumio[1372]: info: MRS: Snap server stop Dec 21 15:39:18 volumio3840x2160 volumio[1372]: info: MRS: STOPPING volumioStreaming Dec 21 15:39:18 volumio3840x2160 volumio[1372]: info: [MyVolumio PluginManager] Loading plugin "metavolumio"... Dec 21 15:39:18 volumio3840x2160 volumio[1372]: info: [MyVolumio PluginManager] Loading plugin "manifestui"... Dec 21 15:39:18 volumio3840x2160 volumio[1372]: info: [MyVolumio PluginManager] Loading plugin "cd_controller"... Dec 21 15:39:18 volumio3840x2160 volumio[1372]: info: [MyVolumio PluginManager] Loading plugin "smart_inputs"... Dec 21 15:39:18 volumio3840x2160 volumio[1372]: info: [MyVolumio PluginManager] Loading plugin "hi_res_audio"... Dec 21 15:39:18 volumio3840x2160 sudo[2228]: volumio : unable to resolve host volumio3840x2160: System error Dec 21 15:39:18 volumio3840x2160 sudo[2228]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop volumioSnapclient Dec 21 15:39:18 volumio3840x2160 sudo[2228]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 21 15:39:18 volumio3840x2160 volumio[1372]: info: [MyVolumio PluginManager] Applying required configuration parameters for plugin hi_res_audio Dec 21 15:39:18 volumio3840x2160 sudo[2230]: volumio : unable to resolve host volumio3840x2160: System error Dec 21 15:39:18 volumio3840x2160 sudo[2232]: volumio : unable to resolve host volumio3840x2160: System error Dec 21 15:39:18 volumio3840x2160 volumio[1372]: info: [MyVolumio PluginManager] Loading plugin "tidal"... Dec 21 15:39:18 volumio3840x2160 sudo[2230]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop volumioSnapserver Dec 21 15:39:18 volumio3840x2160 sudo[2232]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop volumioStreaming Dec 21 15:39:18 volumio3840x2160 sudo[2230]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 21 15:39:18 volumio3840x2160 sudo[2232]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 21 15:39:18 volumio3840x2160 sudo[2234]: volumio : unable to resolve host volumio3840x2160: System error Dec 21 15:39:18 volumio3840x2160 volumio[1372]: info: [MyVolumio PluginManager] Loading plugin "qobuz"... Dec 21 15:39:18 volumio3840x2160 sudo[2234]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/rm -f /tmp/hls/* Dec 21 15:39:18 volumio3840x2160 sudo[2234]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 21 15:39:18 volumio3840x2160 sudo[2234]: pam_unix(sudo:session): session closed for user root Dec 21 15:39:18 volumio3840x2160 volumio[1372]: info: [MyVolumio PluginManager] Loading plugin "tidalconnect"... Dec 21 15:39:18 volumio3840x2160 volumio[1372]: info: [MyVolumio PluginManager] Loading plugin "qobuzconnect"... Dec 21 15:39:18 volumio3840x2160 sudo[2228]: pam_unix(sudo:session): session closed for user root Dec 21 15:39:18 volumio3840x2160 volumio[1372]: info: Preparing to generate the ALSA configuration file Dec 21 15:39:18 volumio3840x2160 sudo[2230]: pam_unix(sudo:session): session closed for user root Dec 21 15:39:18 volumio3840x2160 sudo[2232]: pam_unix(sudo:session): session closed for user root Dec 21 15:39:18 volumio3840x2160 volumio[1372]: info: The plugin alsa_controller has an ALSA contribution file softvolume.postVolume.conf Dec 21 15:39:18 volumio3840x2160 volumio[1372]: info: Reading ALSA contributions from plugins. Dec 21 15:39:18 volumio3840x2160 volumio[1372]: info: Setting Geolocation for MyVolumio to eu5 Dec 21 15:39:18 volumio3840x2160 volumio[1372]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 21 15:39:18 volumio3840x2160 volumio[1372]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 21 15:39:18 volumio3840x2160 volumio[1372]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 21 15:39:18 volumio3840x2160 volumio[1372]: info: Setting Geolocation for MyVolumio to eu12 Dec 21 15:39:18 volumio3840x2160 volumio[1372]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 21 15:39:18 volumio3840x2160 volumio[1372]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 21 15:39:18 volumio3840x2160 volumio[1372]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 21 15:39:19 volumio3840x2160 volumio[1372]: info: MRS: Removed streaming files Dec 21 15:39:19 volumio3840x2160 volumio[1372]: info: MRS: volumioStreaming STOPPED Dec 21 15:39:19 volumio3840x2160 volumio[1372]: info: MRS: SNAPSERVER STOPPED Dec 21 15:39:19 volumio3840x2160 volumio[1372]: info: MRS: SNAPCLIENT STOPPED Dec 21 15:39:19 volumio3840x2160 volumio[1372]: error: Cannot start Volumio Streaming Daemon Dec 21 15:39:19 volumio3840x2160 volumio[1372]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Dec 21 15:39:19 volumio3840x2160 volumio[1372]: sudo: unable to resolve host volumio3840x2160: System error Dec 21 15:39:19 volumio3840x2160 volumio[1372]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Dec 21 15:39:19 volumio3840x2160 volumio[1372]: info: Asound.conf file unchanged, so no further update is needed Dec 21 15:39:19 volumio3840x2160 volumio[1372]: info: Output device has changed, restarting MPD Dec 21 15:39:19 volumio3840x2160 volumio[1372]: info: MRS: Audio Device Changed, rebuilding Multiroom Configuration Dec 21 15:39:19 volumio3840x2160 volumio[1372]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 21 15:39:19 volumio3840x2160 volumio[1372]: info: [MyVolumio PluginManager] Starting plugin audio_interface.bluetooth Dec 21 15:39:19 volumio3840x2160 volumio[1372]: info: [MyVolumio PluginManager] Plugin bluetooth disabled by user. Not starting Dec 21 15:39:19 volumio3840x2160 volumio[1372]: info: [MyVolumio PluginManager] Starting plugin audio_interface.multiroom Dec 21 15:39:19 volumio3840x2160 volumio[1372]: info: [MyVolumio PluginManager] Plugin multiroom disabled by user. Not starting Dec 21 15:39:19 volumio3840x2160 volumio[1372]: info: [MyVolumio PluginManager] Starting plugin miscellanea.metavolumio Dec 21 15:39:19 volumio3840x2160 volumio[1372]: info: Adding METAVOLUMIO REST API Endpoints Dec 21 15:39:19 volumio3840x2160 volumio[1372]: info: Adding metavolumio REST Endpoint for plugin: miscellanea/metavolumio Dec 21 15:39:19 volumio3840x2160 volumio[1372]: info: Adding getSimilarArtists REST Endpoint for plugin: miscellanea/metavolumio Dec 21 15:39:19 volumio3840x2160 volumio[1372]: info: Adding getSimilarAlbums REST Endpoint for plugin: miscellanea/metavolumio Dec 21 15:39:19 volumio3840x2160 volumio[1372]: info: Adding getSimilarTracks REST Endpoint for plugin: miscellanea/metavolumio Dec 21 15:39:19 volumio3840x2160 volumio[1372]: info: [MyVolumio PluginManager] Starting plugin miscellanea.manifestui Dec 21 15:39:19 volumio3840x2160 volumio[1372]: info: [MyVolumio PluginManager] Starting plugin music_service.cd_controller Dec 21 15:39:19 volumio3840x2160 volumio[1372]: info: Preparing CD Folders Dec 21 15:39:19 volumio3840x2160 volumio[1372]: info: Adding CD REST API Endpoints Dec 21 15:39:19 volumio3840x2160 volumio[1372]: info: Adding cdPostRip REST Endpoint for plugin: music_service/cd_controller Dec 21 15:39:19 volumio3840x2160 volumio[1372]: info: Starting UDEV Watcher for CD Dec 21 15:39:19 volumio3840x2160 volumio[1372]: info: Detecting CD presence with UDEV Dec 21 15:39:19 volumio3840x2160 volumio[1372]: info: CoreCommandRouter::executeOnPlugin: networkfs , getUdevDevices Dec 21 15:39:19 volumio3840x2160 sudo[2240]: volumio : unable to resolve host volumio3840x2160: System error Dec 21 15:39:19 volumio3840x2160 sudo[2240]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 21 15:39:19 volumio3840x2160 sudo[2240]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 21 15:39:19 volumio3840x2160 sudo[2240]: pam_unix(sudo:session): session closed for user root Dec 21 15:39:19 volumio3840x2160 sudo[2242]: volumio : unable to resolve host volumio3840x2160: System error Dec 21 15:39:19 volumio3840x2160 sudo[2242]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 21 15:39:19 volumio3840x2160 sudo[2242]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 21 15:39:19 volumio3840x2160 systemd[1]: Stopping mpd.service - Music Player Daemon... Dec 21 15:39:19 volumio3840x2160 systemd[1]: mpd.service: Deactivated successfully. Dec 21 15:39:19 volumio3840x2160 systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 21 15:39:19 volumio3840x2160 systemd[1]: mpd.service: Consumed 1.586s CPU time. Dec 21 15:39:19 volumio3840x2160 systemd[1]: mpd.socket: Deactivated successfully. Dec 21 15:39:19 volumio3840x2160 systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 21 15:39:19 volumio3840x2160 systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 21 15:39:19 volumio3840x2160 systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 21 15:39:19 volumio3840x2160 systemd[1]: Starting mpd.service - Music Player Daemon... Dec 21 15:39:19 volumio3840x2160 sudo[2251]: root : unable to resolve host volumio3840x2160: System error Dec 21 15:39:19 volumio3840x2160 sudo[2251]: sudo: unable to resolve host volumio3840x2160: System error Dec 21 15:39:19 volumio3840x2160 sudo[2251]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 21 15:39:19 volumio3840x2160 sudo[2251]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 21 15:39:19 volumio3840x2160 sudo[2251]: pam_unix(sudo:session): session closed for user root Dec 21 15:39:19 volumio3840x2160 mpd[2253]: 2025-12-21T15:39:19 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Dec 21 15:39:19 volumio3840x2160 systemd[1]: Started mpd.service - Music Player Daemon. Dec 21 15:39:19 volumio3840x2160 sudo[2242]: pam_unix(sudo:session): session closed for user root Dec 21 15:39:21 volumio3840x2160 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 4. Dec 21 15:39:21 volumio3840x2160 systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 21 15:39:21 volumio3840x2160 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 21 15:39:21 volumio3840x2160 go-librespot[2256]: go-librespot daemon starting... Dec 21 15:39:21 volumio3840x2160 go-librespot[2257]: time="2025-12-21T15:39:21+01:00" level=info msg="running go-librespot 0.4.0" Dec 21 15:39:21 volumio3840x2160 go-librespot[2257]: time="2025-12-21T15:39:21+01:00" level=debug msg="app state loaded" Dec 21 15:39:21 volumio3840x2160 go-librespot[2257]: time="2025-12-21T15:39:21+01:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 21 15:39:21 volumio3840x2160 go-librespot[2257]: time="2025-12-21T15:39:21+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Dec 21 15:39:21 volumio3840x2160 go-librespot[2257]: time="2025-12-21T15:39:21+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Dec 21 15:39:21 volumio3840x2160 go-librespot[2257]: time="2025-12-21T15:39:21+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Dec 21 15:39:21 volumio3840x2160 go-librespot[2257]: time="2025-12-21T15:39:21+01:00" level=info msg="zeroconf server listening on port 35653" Dec 21 15:39:21 volumio3840x2160 go-librespot[2257]: time="2025-12-21T15:39:21+01:00" level=debug msg="obtained new client token: AADwhsUTelE9rzr15ETdoM7jPc+KzIjHQRQRowS0utk01fJC2PEqNkXcpTQLLVymiVMEISVLw3iu3rRuyrbJeTXyEE3ioH/jh8ZCB8OlosD4dLVRYWa35fO7Dzf9xY3LBDglwNEfi1X7d8OvVBJ1jzvcFEqiYtQm+6QMzMFufixrvlGUn1Ze0ZUA9mZ3tjoCeIIQ6oqdPrOoOzeSSdzy97ooIfsmE9leFq1bI041wsKZzYCTyJGEiuKV1w==" Dec 21 15:39:21 volumio3840x2160 go-librespot[2257]: time="2025-12-21T15:39:21+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Dec 21 15:39:21 volumio3840x2160 go-librespot[2257]: time="2025-12-21T15:39:21+01:00" level=debug msg="completed keyexchange" Dec 21 15:39:21 volumio3840x2160 go-librespot[2257]: time="2025-12-21T15:39:21+01:00" level=debug msg="completed challenge" Dec 21 15:39:21 volumio3840x2160 go-librespot[2257]: time="2025-12-21T15:39:21+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Dec 21 15:39:21 volumio3840x2160 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 21 15:39:21 volumio3840x2160 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 21 15:39:24 volumio3840x2160 volumio[1372]: warn: [cd-plugin] cdspeedctl: device or media not ready Dec 21 15:39:24 volumio3840x2160 volumio[1372]: info: [MyVolumio PluginManager] Starting plugin music_service.smart_inputs Dec 21 15:39:24 volumio3840x2160 volumio[1372]: info: Adding inputs REST Endpoints Dec 21 15:39:24 volumio3840x2160 volumio[1372]: info: Adding scanAudioInputs REST Endpoint for plugin: music_service/smart_inputs Dec 21 15:39:24 volumio3840x2160 volumio[1372]: info: Scanning Audio Inputs Dec 21 15:39:24 volumio3840x2160 volumio[1372]: info: Checking against Known Cards name Dec 21 15:39:24 volumio3840x2160 volumio[1372]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 21 15:39:24 volumio3840x2160 volumio[1372]: info: [1766327964056] CoreMusicLibrary::Adding element HiFiBerry ADC Dec 21 15:39:24 volumio3840x2160 volumio[1372]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 21 15:39:24 volumio3840x2160 volumio[1372]: Cannot find translation for source HiFiBerry ADC Dec 21 15:39:24 volumio3840x2160 volumio[1372]: info: Checking against Known Cards name Dec 21 15:39:24 volumio3840x2160 volumio[1372]: info: Adding Server instance for streaming Dec 21 15:39:24 volumio3840x2160 volumio[1372]: info: [MyVolumio PluginManager] Starting plugin music_service.hi_res_audio Dec 21 15:39:24 volumio3840x2160 volumio[1372]: error: Hi Res Audio Failed Login: Missing Login Data Dec 21 15:39:24 volumio3840x2160 volumio[1372]: info: Adding HIGHRESAUDIO REST API Endpoints Dec 21 15:39:24 volumio3840x2160 volumio[1372]: info: Adding saveAccountData_hi_res_audio REST Endpoint for plugin: music_service/hi_res_audio Dec 21 15:39:24 volumio3840x2160 volumio[1372]: info: [MyVolumio PluginManager] Starting plugin music_service.tidal Dec 21 15:39:24 volumio3840x2160 volumio[1372]: info: Refreshing TIDAL token Dec 21 15:39:24 volumio3840x2160 volumio[1372]: info: [MyVolumio PluginManager] Starting plugin music_service.qobuz Dec 21 15:39:24 volumio3840x2160 volumio[1372]: info: [MyVolumio PluginManager] Starting plugin music_service.tidalconnect Dec 21 15:39:24 volumio3840x2160 volumio[1372]: info: [MyVolumio PluginManager] Starting plugin music_service.qobuzconnect Dec 21 15:39:24 volumio3840x2160 volumio[1372]: info: [MyVolumio PluginManager] Plugin qobuzconnect disabled by user. Not starting Dec 21 15:39:24 volumio3840x2160 volumio[1372]: info: Stopping AccessToken refresher cron for QOBUZ Dec 21 15:39:24 volumio3840x2160 volumio[1372]: info: AccessToken refresher cron started for QOBUZ Dec 21 15:39:24 volumio3840x2160 volumio[1372]: info: Adding QOBUZ REST API Endpoints Dec 21 15:39:24 volumio3840x2160 volumio[1372]: info: Updating MyVolumio device info Dec 21 15:39:24 volumio3840x2160 volumio[1372]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 21 15:39:24 volumio3840x2160 volumio[1372]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 21 15:39:24 volumio3840x2160 volumio[1372]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 21 15:39:24 volumio3840x2160 volumio[1372]: info: Updating MyVolumio device info Dec 21 15:39:24 volumio3840x2160 volumio[1372]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 21 15:39:24 volumio3840x2160 volumio[1372]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 21 15:39:24 volumio3840x2160 volumio[1372]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 21 15:39:24 volumio3840x2160 volumio[1372]: info: Initializing connection to go-librespot Websocket Dec 21 15:39:24 volumio3840x2160 volumio[1372]: info: Successfully Added MyVolumio device Dec 21 15:39:24 volumio3840x2160 volumio[1372]: info: Successfully Added MyVolumio device Dec 21 15:39:24 volumio3840x2160 volumio[1372]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Dec 21 15:39:24 volumio3840x2160 volumio[1372]: info: MPD Permissions set Dec 21 15:39:24 volumio3840x2160 volumio[1372]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 21 15:39:24 volumio3840x2160 volumio[1372]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 21 15:39:24 volumio3840x2160 volumio[1372]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 21 15:39:24 volumio3840x2160 volumio[1372]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 21 15:39:24 volumio3840x2160 volumio[1372]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 21 15:39:24 volumio3840x2160 volumio[1372]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 21 15:39:24 volumio3840x2160 volumio[1372]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 21 15:39:24 volumio3840x2160 volumio[1372]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 21 15:39:24 volumio3840x2160 volumio[1372]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 21 15:39:24 volumio3840x2160 sudo[2270]: volumio : unable to resolve host volumio3840x2160: System error Dec 21 15:39:24 volumio3840x2160 sudo[2270]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service Dec 21 15:39:24 volumio3840x2160 sudo[2270]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 21 15:39:24 volumio3840x2160 volumio[1372]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 21 15:39:24 volumio3840x2160 volumio[1372]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 21 15:39:24 volumio3840x2160 sudo[2270]: pam_unix(sudo:session): session closed for user root Dec 21 15:39:24 volumio3840x2160 volumio[1372]: error: updateQueue error: null Dec 21 15:39:24 volumio3840x2160 sudo[2285]: volumio : unable to resolve host volumio3840x2160: System error Dec 21 15:39:24 volumio3840x2160 sudo[2285]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart sshtunnel.service Dec 21 15:39:24 volumio3840x2160 sudo[2285]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 21 15:39:24 volumio3840x2160 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. Dec 21 15:39:24 volumio3840x2160 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. Dec 21 15:39:24 volumio3840x2160 systemd[1]: Started sshtunnel.service - MyVolumio SSH Tunnel. Dec 21 15:39:24 volumio3840x2160 sudo[2285]: pam_unix(sudo:session): session closed for user root Dec 21 15:39:24 volumio3840x2160 volumio[1372]: info: Remote SSH Started Dec 21 15:39:24 volumio3840x2160 autossh[2288]: port set to 0, monitoring disabled Dec 21 15:39:24 volumio3840x2160 autossh[2288]: starting ssh (count 1) Dec 21 15:39:24 volumio3840x2160 autossh[2288]: ssh child pid is 2291 Dec 21 15:39:24 volumio3840x2160 volumio[1372]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 16 Dec 21 15:39:24 volumio3840x2160 volumio[1372]: info: CoreCommandRouter::volumioGetState Dec 21 15:39:24 volumio3840x2160 volumio[1372]: info: CorePlayQueue::getTrack 0 Dec 21 15:39:24 volumio3840x2160 volumio[1372]: info: Successfully Updated MyVolumio device Dec 21 15:39:24 volumio3840x2160 volumio[1372]: info: Successfully Updated MyVolumio device Dec 21 15:39:24 volumio3840x2160 volumio[1372]: info: Access Token successfully retrieved Dec 21 15:39:24 volumio3840x2160 volumiossh-tunnel[2291]: Warning: Permanently added '[eu12.myvolumio.org]:2222' (ED25519) to the list of known hosts. Dec 21 15:39:24 volumio3840x2160 volumio[1372]: info: Successfully retrieved User Session From TIDAL Dec 21 15:39:24 volumio3840x2160 volumio[1372]: info: Successfully retrieved User Subscription From TIDAL Dec 21 15:39:24 volumio3840x2160 volumio[1372]: info: Adding TIDAL to Browse Sources Dec 21 15:39:24 volumio3840x2160 volumio[1372]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 21 15:39:24 volumio3840x2160 volumio[1372]: info: [1766327964801] CoreMusicLibrary::Adding element TIDAL Dec 21 15:39:24 volumio3840x2160 volumio[1372]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 21 15:39:24 volumio3840x2160 volumio[1372]: Cannot find translation for source HiFiBerry ADC Dec 21 15:39:24 volumio3840x2160 volumio[1372]: Cannot find translation for source TIDAL Dec 21 15:39:24 volumio3840x2160 volumio[1372]: info: Adding TIDAL REST API Endpoints Dec 21 15:39:24 volumio3840x2160 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 5. Dec 21 15:39:24 volumio3840x2160 systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 21 15:39:24 volumio3840x2160 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 21 15:39:24 volumio3840x2160 go-librespot[2306]: go-librespot daemon starting... Dec 21 15:39:24 volumio3840x2160 go-librespot[2307]: time="2025-12-21T15:39:24+01:00" level=info msg="running go-librespot 0.4.0" Dec 21 15:39:24 volumio3840x2160 go-librespot[2307]: time="2025-12-21T15:39:24+01:00" level=debug msg="app state loaded" Dec 21 15:39:24 volumio3840x2160 go-librespot[2307]: time="2025-12-21T15:39:24+01:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 21 15:39:25 volumio3840x2160 go-librespot[2307]: time="2025-12-21T15:39:25+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Dec 21 15:39:25 volumio3840x2160 go-librespot[2307]: time="2025-12-21T15:39:25+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Dec 21 15:39:25 volumio3840x2160 go-librespot[2307]: time="2025-12-21T15:39:25+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Dec 21 15:39:25 volumio3840x2160 go-librespot[2307]: time="2025-12-21T15:39:25+01:00" level=info msg="zeroconf server listening on port 39623" Dec 21 15:39:25 volumio3840x2160 go-librespot[2307]: time="2025-12-21T15:39:25+01:00" level=debug msg="obtained new client token: AACP35rDHQthrw1d0XhdpKG3zPb9UAEBi4ix6WU9N7iQp1+CzPkt4D3pFgvOPZMMDl3bTKZ6K1mXnpmcsbpgYmdInpcQGw7h1kCxt17ctsxHTTZ+3HYsYFCaHakVRxFCbl/spmZKFx1WDvVtJyR1cvXy/kGnBQMCr7mkA4CGZrrqr6Mn936gDqpvL/NfH66JA4rVMZcLIapiC3qOFXFjwBzNR6yYgmzyJsJyv1BNbGBd6eKB99EhAuU=" Dec 21 15:39:25 volumio3840x2160 go-librespot[2307]: time="2025-12-21T15:39:25+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Dec 21 15:39:25 volumio3840x2160 go-librespot[2307]: time="2025-12-21T15:39:25+01:00" level=debug msg="completed keyexchange" Dec 21 15:39:25 volumio3840x2160 go-librespot[2307]: time="2025-12-21T15:39:25+01:00" level=debug msg="completed challenge" Dec 21 15:39:25 volumio3840x2160 go-librespot[2307]: time="2025-12-21T15:39:25+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Dec 21 15:39:25 volumio3840x2160 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 21 15:39:25 volumio3840x2160 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 21 15:39:27 volumio3840x2160 volumio[1372]: info: Initializing connection to go-librespot Websocket Dec 21 15:39:27 volumio3840x2160 volumio[1372]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 21 15:39:27 volumio3840x2160 volumio[1372]: error: Unable to stop TidalConnect service: Dec 21 15:39:27 volumio3840x2160 volumio[1372]: info: TidalConnect service stoped! Dec 21 15:39:27 volumio3840x2160 volumio[1372]: info: Adding tc_getconfig REST Endpoint for plugin: music_service/tidalconnect Dec 21 15:39:27 volumio3840x2160 volumio[1372]: info: Adding tc_connect REST Endpoint for plugin: music_service/tidalconnect Dec 21 15:39:27 volumio3840x2160 sudo[2323]: volumio : unable to resolve host volumio3840x2160: System error Dec 21 15:39:27 volumio3840x2160 sudo[2323]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start vtcs.service Dec 21 15:39:27 volumio3840x2160 sudo[2323]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 21 15:39:27 volumio3840x2160 systemd[1]: Started vtcs.service - Volumio Tidal Connect Service. Dec 21 15:39:27 volumio3840x2160 sudo[2323]: pam_unix(sudo:session): session closed for user root Dec 21 15:39:27 volumio3840x2160 volumio[1372]: info: Executing endpoint tc_getconfig Dec 21 15:39:27 volumio3840x2160 volumio[1372]: info: CoreCommandRouter::executeOnPlugin: tidalconnect , onGetConfig Dec 21 15:39:27 volumio3840x2160 vtcs[2326]: STARTING TidalConnect services, version: 1.5.2.56 Dec 21 15:39:27 volumio3840x2160 vtcs[2326]: STARTED TidalConnect services. Dec 21 15:39:27 volumio3840x2160 volumio[1372]: info: Executing endpoint tc_connect Dec 21 15:39:27 volumio3840x2160 volumio[1372]: info: CoreCommandRouter::executeOnPlugin: tidalconnect , onConnect Dec 21 15:39:27 volumio3840x2160 volumio[1372]: info: Connecting to TidalConnect Dec 21 15:39:27 volumio3840x2160 volumio[1372]: info: CoreCommandRouter::servicePushState Dec 21 15:39:27 volumio3840x2160 volumio[1372]: info: CoreStateMachine::pushState Dec 21 15:39:27 volumio3840x2160 volumio[1372]: info: CorePlayQueue::getTrack 0 Dec 21 15:39:27 volumio3840x2160 volumio[1372]: info: CoreCommandRouter::volumioPushState Dec 21 15:39:27 volumio3840x2160 volumio[1372]: info: CorePlayQueue::getTrack 0 Dec 21 15:39:27 volumio3840x2160 volumio[1372]: verbose: STATE SERVICE {"status":"stop","service":"tidalconnect","title":"","artist":"","album":"","albumart":"/albumart","uri":"","icon":"fa fa-spinner","trackType":"tidal","codec":"","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"","channels":2,"random":false,"repeat":false,"repeatSingle":false} Dec 21 15:39:27 volumio3840x2160 volumio[1372]: verbose: CURRENT POSITION 0 Dec 21 15:39:27 volumio3840x2160 volumio[1372]: info: CoreStateMachine::syncState stateService stop Dec 21 15:39:27 volumio3840x2160 volumio[1372]: info: CoreStateMachine::syncState currentStatus stop Dec 21 15:39:27 volumio3840x2160 volumio[1372]: info: CoreStateMachine::pushState Dec 21 15:39:27 volumio3840x2160 volumio[1372]: info: CorePlayQueue::getTrack 0 Dec 21 15:39:27 volumio3840x2160 volumio[1372]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 21 15:39:27 volumio3840x2160 volumio[1372]: info: CoreCommandRouter::volumioPushState Dec 21 15:39:27 volumio3840x2160 volumio[1372]: info: No code Dec 21 15:39:27 volumio3840x2160 volumio[1372]: info: CoreStateMachine::pushState Dec 21 15:39:27 volumio3840x2160 volumio[1372]: info: CorePlayQueue::getTrack 0 Dec 21 15:39:27 volumio3840x2160 volumio[1372]: info: CoreCommandRouter::volumioPushState Dec 21 15:39:27 volumio3840x2160 volumio[1372]: info: CoreCommandRouter::servicePushState Dec 21 15:39:27 volumio3840x2160 volumio[1372]: info: CoreStateMachine::pushState Dec 21 15:39:27 volumio3840x2160 volumio[1372]: info: CorePlayQueue::getTrack 0 Dec 21 15:39:27 volumio3840x2160 volumio[1372]: info: CoreCommandRouter::volumioPushState Dec 21 15:39:27 volumio3840x2160 volumio[1372]: info: CorePlayQueue::getTrack 0 Dec 21 15:39:27 volumio3840x2160 volumio[1372]: verbose: STATE SERVICE {"status":"stop","service":"tidalconnect","title":"","artist":"","album":"","albumart":"/albumart","uri":"","icon":"fa fa-spinner","trackType":"tidal","codec":"","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"","channels":2,"random":false,"repeat":false,"repeatSingle":false} Dec 21 15:39:27 volumio3840x2160 volumio[1372]: verbose: CURRENT POSITION 0 Dec 21 15:39:27 volumio3840x2160 volumio[1372]: info: CoreStateMachine::syncState stateService stop Dec 21 15:39:27 volumio3840x2160 volumio[1372]: info: CoreStateMachine::syncState currentStatus stop Dec 21 15:39:27 volumio3840x2160 volumio[1372]: info: CoreStateMachine::pushState Dec 21 15:39:27 volumio3840x2160 volumio[1372]: info: CorePlayQueue::getTrack 0 Dec 21 15:39:27 volumio3840x2160 volumio[1372]: info: CoreCommandRouter::volumioPushState Dec 21 15:39:27 volumio3840x2160 volumio[1372]: info: No code Dec 21 15:39:27 volumio3840x2160 volumio[1372]: info: CoreStateMachine::pushState Dec 21 15:39:27 volumio3840x2160 volumio[1372]: info: CorePlayQueue::getTrack 0 Dec 21 15:39:27 volumio3840x2160 volumio[1372]: info: CoreCommandRouter::volumioPushState Dec 21 15:39:27 volumio3840x2160 systemd[1]: systemd-fsckd.service: Deactivated successfully. Dec 21 15:39:28 volumio3840x2160 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6. Dec 21 15:39:28 volumio3840x2160 systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 21 15:39:28 volumio3840x2160 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 21 15:39:28 volumio3840x2160 go-librespot[2342]: go-librespot daemon starting... Dec 21 15:39:28 volumio3840x2160 go-librespot[2343]: time="2025-12-21T15:39:28+01:00" level=info msg="running go-librespot 0.4.0" Dec 21 15:39:28 volumio3840x2160 go-librespot[2343]: time="2025-12-21T15:39:28+01:00" level=debug msg="app state loaded" Dec 21 15:39:28 volumio3840x2160 go-librespot[2343]: time="2025-12-21T15:39:28+01:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 21 15:39:28 volumio3840x2160 go-librespot[2343]: time="2025-12-21T15:39:28+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Dec 21 15:39:28 volumio3840x2160 go-librespot[2343]: time="2025-12-21T15:39:28+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Dec 21 15:39:28 volumio3840x2160 go-librespot[2343]: time="2025-12-21T15:39:28+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Dec 21 15:39:28 volumio3840x2160 go-librespot[2343]: time="2025-12-21T15:39:28+01:00" level=info msg="zeroconf server listening on port 46257" Dec 21 15:39:28 volumio3840x2160 go-librespot[2343]: time="2025-12-21T15:39:28+01:00" level=debug msg="obtained new client token: AADPseMMbXpYOPjrMnoUcT1iFT9QAQZa5nFFEIbTtD1GGtsW+N0u8sCRiHDXv7i8NOyNyeU7lnWF5129jOerKz0OWH9ZBCAuNnk1Y8bK8JOBOTqk3oc0NlhSu97WR8rdURDOAgnwYYlJY95X2aGp2kWqcLw+BCHmjxTs4iv5WzHwDA6o8oa9ePWKPbKb8XHFfIlbLz8TwnYp+nRmg90WG1yeHOp1q7YLaCGqqW/9Mm+SnIS7B7zPjuevlA==" Dec 21 15:39:28 volumio3840x2160 go-librespot[2343]: time="2025-12-21T15:39:28+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Dec 21 15:39:28 volumio3840x2160 go-librespot[2343]: time="2025-12-21T15:39:28+01:00" level=debug msg="completed keyexchange" Dec 21 15:39:28 volumio3840x2160 go-librespot[2343]: time="2025-12-21T15:39:28+01:00" level=debug msg="completed challenge" Dec 21 15:39:28 volumio3840x2160 go-librespot[2343]: time="2025-12-21T15:39:28+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Dec 21 15:39:28 volumio3840x2160 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 21 15:39:28 volumio3840x2160 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 21 15:39:28 volumio3840x2160 systemd[1]: systemd-hostnamed.service: Deactivated successfully. Dec 21 15:39:29 volumio3840x2160 systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 2. Dec 21 15:39:29 volumio3840x2160 systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Dec 21 15:39:29 volumio3840x2160 systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Dec 21 15:39:29 volumio3840x2160 upmpdcli[2353]: Could not open config: /tmp/upmpdcli.conf Dec 21 15:39:29 volumio3840x2160 systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Dec 21 15:39:29 volumio3840x2160 systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Dec 21 15:39:30 volumio3840x2160 volumio[1372]: info: Initializing connection to go-librespot Websocket Dec 21 15:39:30 volumio3840x2160 volumio[1372]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 21 15:39:30 volumio3840x2160 volumio[1372]: error: Unable to start TidalConnect service: Dec 21 15:39:30 volumio3840x2160 volumio[1372]: info: TidalConnect service started! Dec 21 15:39:30 volumio3840x2160 volumio[1372]: [Metrics] CommandRouter: 26s 368.24ms Dec 21 15:39:30 volumio3840x2160 volumio[1372]: info: CoreCommandRouter::volumiosetStartupVolume Dec 21 15:39:30 volumio3840x2160 volumio[1372]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 21 15:39:30 volumio3840x2160 volumio[1372]: info: VolumeController:: Setting startup Volume 35 Dec 21 15:39:30 volumio3840x2160 volumio[1372]: info: VolumeController::SetAlsaVolume35 Dec 21 15:39:30 volumio3840x2160 volumio[1372]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 21 15:39:30 volumio3840x2160 volumio[1372]: info: CoreCommandRouter::Close All Modals sent Dec 21 15:39:30 volumio3840x2160 volumio[1372]: info: CoreCommandRouter::Close All Modals sent Dec 21 15:39:30 volumio3840x2160 volumio[1372]: info: CoreStateMachine::pushState Dec 21 15:39:30 volumio3840x2160 volumio[1372]: info: CorePlayQueue::getTrack 0 Dec 21 15:39:30 volumio3840x2160 volumio[1372]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 21 15:39:30 volumio3840x2160 volumio[1372]: info: CoreCommandRouter::volumioPushState Dec 21 15:39:30 volumio3840x2160 volumio[1372]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Dec 21 15:39:30 volumio3840x2160 volumio[1372]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Dec 21 15:39:30 volumio3840x2160 volumio[1372]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Dec 21 15:39:30 volumio3840x2160 volumio[1372]: info: Received Get System Version Dec 21 15:39:30 volumio3840x2160 volumio[1372]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 21 15:39:30 volumio3840x2160 volumio[1372]: info: Received Get System Info Dec 21 15:39:30 volumio3840x2160 volumio[1372]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 21 15:39:30 volumio3840x2160 volumio[1372]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 21 15:39:30 volumio3840x2160 volumio[1372]: info: Discovery: Getting this device information Dec 21 15:39:30 volumio3840x2160 volumio[1372]: info: CoreCommandRouter::volumioGetState Dec 21 15:39:30 volumio3840x2160 volumio[1372]: info: CorePlayQueue::getTrack 0 Dec 21 15:39:30 volumio3840x2160 volumio[1372]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 21 15:39:31 volumio3840x2160 volumio[1372]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable Dec 21 15:39:31 volumio3840x2160 volumio[1372]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Dec 21 15:39:31 volumio3840x2160 volumio[1372]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect Dec 21 15:39:31 volumio3840x2160 volumio[1372]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Dec 21 15:39:31 volumio3840x2160 volumio[1372]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 17 Dec 21 15:39:31 volumio3840x2160 volumio[1372]: info: CoreCommandRouter::volumioGetState Dec 21 15:39:31 volumio3840x2160 volumio[1372]: info: CorePlayQueue::getTrack 0 Dec 21 15:39:31 volumio3840x2160 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 7. Dec 21 15:39:31 volumio3840x2160 systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 21 15:39:31 volumio3840x2160 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 21 15:39:31 volumio3840x2160 go-librespot[2357]: go-librespot daemon starting... Dec 21 15:39:31 volumio3840x2160 go-librespot[2358]: time="2025-12-21T15:39:31+01:00" level=info msg="running go-librespot 0.4.0" Dec 21 15:39:31 volumio3840x2160 go-librespot[2358]: time="2025-12-21T15:39:31+01:00" level=debug msg="app state loaded" Dec 21 15:39:31 volumio3840x2160 go-librespot[2358]: time="2025-12-21T15:39:31+01:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 21 15:39:32 volumio3840x2160 go-librespot[2358]: time="2025-12-21T15:39:32+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Dec 21 15:39:32 volumio3840x2160 go-librespot[2358]: time="2025-12-21T15:39:32+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Dec 21 15:39:32 volumio3840x2160 go-librespot[2358]: time="2025-12-21T15:39:32+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Dec 21 15:39:32 volumio3840x2160 go-librespot[2358]: time="2025-12-21T15:39:32+01:00" level=info msg="zeroconf server listening on port 35305" Dec 21 15:39:32 volumio3840x2160 go-librespot[2358]: time="2025-12-21T15:39:32+01:00" level=debug msg="obtained new client token: AAD888AIEr06wAijmCMu3peDosn2jugNs10QdgpcJ2/+Fpq6IBkBVt/7Z6/yM6VnlXvvJB5BVtj2IragNPzuF0S+Su82PWg7oAdNuJ3ioB1dYMdICSnUW8gdEoQ212BAsQhef21VGh4S34jNuKIKzXiMIAo2+UGbACpBn/gYgkV0eGKwaReeFNpGPeXaStCaGTg17Cmx6QkW4b/Js9JAWx2asDphyRNYE1qw4ws90O+uMfjPFkwuLdM=" Dec 21 15:39:32 volumio3840x2160 go-librespot[2358]: time="2025-12-21T15:39:32+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Dec 21 15:39:32 volumio3840x2160 go-librespot[2358]: time="2025-12-21T15:39:32+01:00" level=debug msg="completed keyexchange" Dec 21 15:39:32 volumio3840x2160 go-librespot[2358]: time="2025-12-21T15:39:32+01:00" level=debug msg="completed challenge" Dec 21 15:39:32 volumio3840x2160 go-librespot[2358]: time="2025-12-21T15:39:32+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Dec 21 15:39:32 volumio3840x2160 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 21 15:39:32 volumio3840x2160 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 21 15:39:33 volumio3840x2160 volumio[1372]: info: Initializing connection to go-librespot Websocket Dec 21 15:39:33 volumio3840x2160 volumio[1372]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 21 15:39:35 volumio3840x2160 volumio[1372]: info: CoreCommandRouter::volumioGetQueue Dec 21 15:39:35 volumio3840x2160 volumio[1372]: info: CoreStateMachine::getQueue Dec 21 15:39:35 volumio3840x2160 volumio[1372]: info: CorePlayQueue::getQueue Dec 21 15:39:35 volumio3840x2160 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 8. Dec 21 15:39:35 volumio3840x2160 systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 21 15:39:35 volumio3840x2160 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 21 15:39:35 volumio3840x2160 go-librespot[2379]: go-librespot daemon starting... Dec 21 15:39:35 volumio3840x2160 go-librespot[2380]: time="2025-12-21T15:39:35+01:00" level=info msg="running go-librespot 0.4.0" Dec 21 15:39:35 volumio3840x2160 go-librespot[2380]: time="2025-12-21T15:39:35+01:00" level=debug msg="app state loaded" Dec 21 15:39:35 volumio3840x2160 go-librespot[2380]: time="2025-12-21T15:39:35+01:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 21 15:39:35 volumio3840x2160 go-librespot[2380]: time="2025-12-21T15:39:35+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Dec 21 15:39:35 volumio3840x2160 go-librespot[2380]: time="2025-12-21T15:39:35+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Dec 21 15:39:35 volumio3840x2160 go-librespot[2380]: time="2025-12-21T15:39:35+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Dec 21 15:39:35 volumio3840x2160 go-librespot[2380]: time="2025-12-21T15:39:35+01:00" level=info msg="zeroconf server listening on port 35543" Dec 21 15:39:35 volumio3840x2160 go-librespot[2380]: time="2025-12-21T15:39:35+01:00" level=debug msg="obtained new client token: AAAztXXCWZX+5hHESnnAoMfJBfPa+8NlWSiHW4el0+trj3F1gCjuno8PYoEDJ7DRMo85tj9CS+fvoE3gbaWC7nwozVV0qFTCWS1iwD6gr5NA1k4Odho0k6SSpiuBH/SgpdzoYhPEjLDPERfffIXp2mygMrvYJJfG/3Nf1aeW0DrnpGZtVmwTvwmygBTzQR3mTXI8g/+sq+WvUoCo2ZIBRkS4hPv4AcEdSfwTiRMM0Rthxdip+R9Y46Y1TQ==" Dec 21 15:39:35 volumio3840x2160 go-librespot[2380]: time="2025-12-21T15:39:35+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Dec 21 15:39:35 volumio3840x2160 go-librespot[2380]: time="2025-12-21T15:39:35+01:00" level=debug msg="completed keyexchange" Dec 21 15:39:35 volumio3840x2160 go-librespot[2380]: time="2025-12-21T15:39:35+01:00" level=debug msg="completed challenge" Dec 21 15:39:35 volumio3840x2160 go-librespot[2380]: time="2025-12-21T15:39:35+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Dec 21 15:39:35 volumio3840x2160 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 21 15:39:35 volumio3840x2160 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 21 15:39:36 volumio3840x2160 volumio[1372]: info: Initializing connection to go-librespot Websocket Dec 21 15:39:36 volumio3840x2160 volumio[1372]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 21 15:39:36 volumio3840x2160 volumio[1372]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 21 15:39:36 volumio3840x2160 volumio[1372]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 21 15:39:36 volumio3840x2160 volumio[1372]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Dec 21 15:39:36 volumio3840x2160 volumio-remote-updater[1002]: Test mode enabled Dec 21 15:39:36 volumio3840x2160 volumio-remote-updater[1002]: Alpha mode disabled Dec 21 15:39:36 volumio3840x2160 volumio-remote-updater[1002]: Alpha legacy test mode disabled Dec 21 15:39:36 volumio3840x2160 volumio[1372]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateEnabled Dec 21 15:39:36 volumio3840x2160 volumio[1372]: info: Update Ready: {"changeLogLink":"","description":"You're already on the latest version","title":"No Updates Available","updateavailable":false} Dec 21 15:39:36 volumio3840x2160 volumio[1372]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache Dec 21 15:39:36 volumio3840x2160 volumio[1372]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 21 15:39:36 volumio3840x2160 volumio[1372]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 21 15:39:36 volumio3840x2160 volumio[1372]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam Dec 21 15:39:36 volumio3840x2160 volumio[1372]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam Dec 21 15:39:36 volumio3840x2160 volumio[1372]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Dec 21 15:39:36 volumio3840x2160 volumio[1372]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Dec 21 15:39:36 volumio3840x2160 volumio[1372]: info: CoreCommandRouter::volumioGetBrowseSources Dec 21 15:39:36 volumio3840x2160 volumio[1372]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 21 15:39:37 volumio3840x2160 volumio[1372]: info: BOOT COMPLETED Dec 21 15:39:38 volumio3840x2160 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 9. Dec 21 15:39:38 volumio3840x2160 systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 21 15:39:38 volumio3840x2160 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 21 15:39:38 volumio3840x2160 go-librespot[2391]: go-librespot daemon starting... Dec 21 15:39:38 volumio3840x2160 go-librespot[2392]: time="2025-12-21T15:39:38+01:00" level=info msg="running go-librespot 0.4.0" Dec 21 15:39:38 volumio3840x2160 go-librespot[2392]: time="2025-12-21T15:39:38+01:00" level=debug msg="app state loaded" Dec 21 15:39:38 volumio3840x2160 go-librespot[2392]: time="2025-12-21T15:39:38+01:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 21 15:39:38 volumio3840x2160 volumio[1372]: info: Preload queue cleared Dec 21 15:39:38 volumio3840x2160 volumio[1372]: info: CoreCommandRouter::volumioReplaceandPlayItems Dec 21 15:39:38 volumio3840x2160 volumio[1372]: info: CoreStateMachine::ClearQueue Dec 21 15:39:38 volumio3840x2160 volumio[1372]: info: CoreStateMachine::stop Dec 21 15:39:38 volumio3840x2160 volumio[1372]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 21 15:39:38 volumio3840x2160 volumio[1372]: info: CorePlayQueue::clearPlayQueue Dec 21 15:39:38 volumio3840x2160 volumio[1372]: info: CorePlayQueue::saveQueue Dec 21 15:39:38 volumio3840x2160 volumio[1372]: info: CoreCommandRouter::volumioPushQueue Dec 21 15:39:38 volumio3840x2160 volumio[1372]: info: CoreStateMachine::addQueueItems Dec 21 15:39:38 volumio3840x2160 volumio[1372]: info: CorePlayQueue::addQueueItems Dec 21 15:39:38 volumio3840x2160 volumio[1372]: info: Preload queue cleared Dec 21 15:39:38 volumio3840x2160 volumio[1372]: info: Adding Item to queue: music-library/NAS/Music_GP/01 Progresive - Psychadelic - Smooth - Electronic/Clannad/[1984] Legend [Vinyl] Dec 21 15:39:38 volumio3840x2160 volumio[1372]: info: Exploding uri music-library/NAS/Music_GP/01 Progresive - Psychadelic - Smooth - Electronic/Clannad/[1984] Legend [Vinyl] in service mpd Dec 21 15:39:38 volumio3840x2160 volumio[1372]: info: ALBUMART /albumart?cacheid=58&web=Clannad/Legend%20%5BVinyl%5D/extralarge&path=%2Fmnt%2FNAS%2FMusic_GP%2F01%20Progresive%20-%20Psychadelic%20-%20Smooth%20-%20Electronic%2FClannad%2F%5B1984%5D%20Legend%20%5BVinyl%5D%2FA1%20Robin%20(The%20Hooded%20Man).flac&metadata=false Dec 21 15:39:38 volumio3840x2160 volumio[1372]: info: URI /mnt/NAS/Music_GP/01 Progresive - Psychadelic - Smooth - Electronic/Clannad/[1984] Legend [Vinyl]/A1 Robin (The Hooded Man).flac Dec 21 15:39:38 volumio3840x2160 volumio[1372]: info: ALBUMART /albumart?cacheid=58&web=Clannad/Legend%20%5BVinyl%5D/extralarge&path=%2Fmnt%2FNAS%2FMusic_GP%2F01%20Progresive%20-%20Psychadelic%20-%20Smooth%20-%20Electronic%2FClannad%2F%5B1984%5D%20Legend%20%5BVinyl%5D%2FA2%20Now%20Is%20Here.flac&metadata=false Dec 21 15:39:38 volumio3840x2160 volumio[1372]: info: URI /mnt/NAS/Music_GP/01 Progresive - Psychadelic - Smooth - Electronic/Clannad/[1984] Legend [Vinyl]/A2 Now Is Here.flac Dec 21 15:39:38 volumio3840x2160 volumio[1372]: info: ALBUMART /albumart?cacheid=58&web=Clannad/Legend%20%5BVinyl%5D/extralarge&path=%2Fmnt%2FNAS%2FMusic_GP%2F01%20Progresive%20-%20Psychadelic%20-%20Smooth%20-%20Electronic%2FClannad%2F%5B1984%5D%20Legend%20%5BVinyl%5D%2FA3%20Herne.flac&metadata=false Dec 21 15:39:38 volumio3840x2160 volumio[1372]: info: URI /mnt/NAS/Music_GP/01 Progresive - Psychadelic - Smooth - Electronic/Clannad/[1984] Legend [Vinyl]/A3 Herne.flac Dec 21 15:39:38 volumio3840x2160 volumio[1372]: info: ALBUMART /albumart?cacheid=58&web=Clannad/Legend%20%5BVinyl%5D/extralarge&path=%2Fmnt%2FNAS%2FMusic_GP%2F01%20Progresive%20-%20Psychadelic%20-%20Smooth%20-%20Electronic%2FClannad%2F%5B1984%5D%20Legend%20%5BVinyl%5D%2FA4%20Together%20We.flac&metadata=false Dec 21 15:39:38 volumio3840x2160 volumio[1372]: info: URI /mnt/NAS/Music_GP/01 Progresive - Psychadelic - Smooth - Electronic/Clannad/[1984] Legend [Vinyl]/A4 Together We.flac Dec 21 15:39:38 volumio3840x2160 volumio[1372]: info: ALBUMART /albumart?cacheid=58&web=Clannad/Legend%20%5BVinyl%5D/extralarge&path=%2Fmnt%2FNAS%2FMusic_GP%2F01%20Progresive%20-%20Psychadelic%20-%20Smooth%20-%20Electronic%2FClannad%2F%5B1984%5D%20Legend%20%5BVinyl%5D%2FA5%20Darkmere.flac&metadata=false Dec 21 15:39:38 volumio3840x2160 volumio[1372]: info: URI /mnt/NAS/Music_GP/01 Progresive - Psychadelic - Smooth - Electronic/Clannad/[1984] Legend [Vinyl]/A5 Darkmere.flac Dec 21 15:39:38 volumio3840x2160 volumio[1372]: info: ALBUMART /albumart?cacheid=58&web=Clannad/Legend%20%5BVinyl%5D/extralarge&path=%2Fmnt%2FNAS%2FMusic_GP%2F01%20Progresive%20-%20Psychadelic%20-%20Smooth%20-%20Electronic%2FClannad%2F%5B1984%5D%20Legend%20%5BVinyl%5D%2FB1%20Strange%20Land.flac&metadata=false Dec 21 15:39:38 volumio3840x2160 volumio[1372]: info: URI /mnt/NAS/Music_GP/01 Progresive - Psychadelic - Smooth - Electronic/Clannad/[1984] Legend [Vinyl]/B1 Strange Land.flac Dec 21 15:39:38 volumio3840x2160 volumio[1372]: info: ALBUMART /albumart?cacheid=58&web=Clannad/Legend%20%5BVinyl%5D/extralarge&path=%2Fmnt%2FNAS%2FMusic_GP%2F01%20Progresive%20-%20Psychadelic%20-%20Smooth%20-%20Electronic%2FClannad%2F%5B1984%5D%20Legend%20%5BVinyl%5D%2FB2%20Scarlet%20Inside.flac&metadata=false Dec 21 15:39:38 volumio3840x2160 volumio[1372]: info: URI /mnt/NAS/Music_GP/01 Progresive - Psychadelic - Smooth - Electronic/Clannad/[1984] Legend [Vinyl]/B2 Scarlet Inside.flac Dec 21 15:39:38 volumio3840x2160 volumio[1372]: info: ALBUMART /albumart?cacheid=58&web=Clannad/Legend%20%5BVinyl%5D/extralarge&path=%2Fmnt%2FNAS%2FMusic_GP%2F01%20Progresive%20-%20Psychadelic%20-%20Smooth%20-%20Electronic%2FClannad%2F%5B1984%5D%20Legend%20%5BVinyl%5D%2FB3%20Lady%20Marian.flac&metadata=false Dec 21 15:39:38 volumio3840x2160 volumio[1372]: info: URI /mnt/NAS/Music_GP/01 Progresive - Psychadelic - Smooth - Electronic/Clannad/[1984] Legend [Vinyl]/B3 Lady Marian.flac Dec 21 15:39:38 volumio3840x2160 volumio[1372]: info: ALBUMART /albumart?cacheid=58&web=Clannad/Legend%20%5BVinyl%5D/extralarge&path=%2Fmnt%2FNAS%2FMusic_GP%2F01%20Progresive%20-%20Psychadelic%20-%20Smooth%20-%20Electronic%2FClannad%2F%5B1984%5D%20Legend%20%5BVinyl%5D%2FB4%20Battles.flac&metadata=false Dec 21 15:39:38 volumio3840x2160 volumio[1372]: info: URI /mnt/NAS/Music_GP/01 Progresive - Psychadelic - Smooth - Electronic/Clannad/[1984] Legend [Vinyl]/B4 Battles.flac Dec 21 15:39:38 volumio3840x2160 volumio[1372]: info: ALBUMART /albumart?cacheid=58&web=Clannad/Legend%20%5BVinyl%5D/extralarge&path=%2Fmnt%2FNAS%2FMusic_GP%2F01%20Progresive%20-%20Psychadelic%20-%20Smooth%20-%20Electronic%2FClannad%2F%5B1984%5D%20Legend%20%5BVinyl%5D%2FB5%20Ancient%20Forest.flac&metadata=false Dec 21 15:39:38 volumio3840x2160 volumio[1372]: info: URI /mnt/NAS/Music_GP/01 Progresive - Psychadelic - Smooth - Electronic/Clannad/[1984] Legend [Vinyl]/B5 Ancient Forest.flac Dec 21 15:39:38 volumio3840x2160 volumio[1372]: info: CoreCommandRouter::volumioPushQueue Dec 21 15:39:38 volumio3840x2160 volumio[1372]: info: CorePlayQueue::saveQueue Dec 21 15:39:38 volumio3840x2160 volumio[1372]: info: CoreStateMachine::updateTrackBlock Dec 21 15:39:38 volumio3840x2160 volumio[1372]: info: CorePlayQueue::getTrackBlock Dec 21 15:39:38 volumio3840x2160 volumio[1372]: info: CoreCommandRouter::volumioGetState Dec 21 15:39:38 volumio3840x2160 volumio[1372]: info: CorePlayQueue::getTrack 0 Dec 21 15:39:38 volumio3840x2160 volumio[1372]: info: CoreCommandRouter::executeOnPlugin: play , [object Object] Dec 21 15:39:38 volumio3840x2160 volumio[1372]: info: CoreCommandRouter::volumioPlay Dec 21 15:39:38 volumio3840x2160 volumio[1372]: info: CoreStateMachine::play index 0 Dec 21 15:39:38 volumio3840x2160 volumio[1372]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 21 15:39:38 volumio3840x2160 volumio[1372]: info: CoreStateMachine::stop Dec 21 15:39:38 volumio3840x2160 volumio[1372]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 21 15:39:38 volumio3840x2160 volumio[1372]: info: CoreStateMachine::play index undefined Dec 21 15:39:38 volumio3840x2160 volumio[1372]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 21 15:39:38 volumio3840x2160 volumio[1372]: info: CorePlayQueue::getTrack 0 Dec 21 15:39:38 volumio3840x2160 volumio[1372]: info: CoreStateMachine::startPlaybackTimer Dec 21 15:39:38 volumio3840x2160 volumio[1372]: info: CorePlayQueue::getTrack 0 Dec 21 15:39:38 volumio3840x2160 volumio[1372]: verbose: ControllerMpd::clearAddPlayTracks NAS/Music_GP/01 Progresive - Psychadelic - Smooth - Electronic/Clannad/[1984] Legend [Vinyl]/A1 Robin (The Hooded Man).flac Dec 21 15:39:38 volumio3840x2160 volumio[1372]: verbose: ControllerMpd::sendMpdCommand stop Dec 21 15:39:38 volumio3840x2160 volumio[1372]: info: sendMpdCommand stop took 2 milliseconds Dec 21 15:39:38 volumio3840x2160 volumio[1372]: verbose: ControllerMpd::sendMpdCommand clear Dec 21 15:39:38 volumio3840x2160 volumio[1372]: info: Dec 21 15:39:38 volumio3840x2160 volumio[1372]: ---------------------------- MPD announces system playlist update Dec 21 15:39:38 volumio3840x2160 volumio[1372]: info: Ignoring MPD Status Update Dec 21 15:39:38 volumio3840x2160 volumio[1372]: info: sendMpdCommand clear took 0 milliseconds Dec 21 15:39:38 volumio3840x2160 volumio[1372]: verbose: ControllerMpd::sendMpdCommand add "NAS/Music_GP/01 Progresive - Psychadelic - Smooth - Electronic/Clannad/[1984] Legend [Vinyl]/A1 Robin (The Hooded Man).flac" Dec 21 15:39:38 volumio3840x2160 volumio[1372]: error: updateQueue error: null Dec 21 15:39:38 volumio3840x2160 volumio[1372]: info: Dec 21 15:39:38 volumio3840x2160 volumio[1372]: ---------------------------- MPD announces system playlist update Dec 21 15:39:38 volumio3840x2160 volumio[1372]: info: Ignoring MPD Status Update Dec 21 15:39:38 volumio3840x2160 volumio[1372]: info: ------------------------------ 1ms Dec 21 15:39:38 volumio3840x2160 volumio[1372]: info: sendMpdCommand add "NAS/Music_GP/01 Progresive - Psychadelic - Smooth - Electronic/Clannad/[1984] Legend [Vinyl]/A1 Robin (The Hooded Man).flac" took 1 milliseconds Dec 21 15:39:38 volumio3840x2160 volumio[1372]: verbose: ControllerMpd::sendMpdCommand play Dec 21 15:39:38 volumio3840x2160 volumio[1372]: info: ------------------------------ 0ms Dec 21 15:39:38 volumio3840x2160 volumio[1372]: info: sendMpdCommand play took 1 milliseconds Dec 21 15:39:38 volumio3840x2160 volumio[1372]: info: Dec 21 15:39:38 volumio3840x2160 volumio[1372]: ---------------------------- MPD announces state update: player Dec 21 15:39:38 volumio3840x2160 volumio[1372]: info: ControllerMpd::getState Dec 21 15:39:38 volumio3840x2160 volumio[1372]: verbose: ControllerMpd::sendMpdCommand status Dec 21 15:39:38 volumio3840x2160 volumio[1372]: info: sendMpdCommand status took 10 milliseconds Dec 21 15:39:38 volumio3840x2160 volumio[1372]: verbose: ControllerMpd::parseState Dec 21 15:39:38 volumio3840x2160 volumio[1372]: verbose: ControllerMpd::sendMpdCommand playlistinfo Dec 21 15:39:38 volumio3840x2160 volumio[1372]: info: Dec 21 15:39:38 volumio3840x2160 volumio[1372]: ---------------------------- MPD announces state update: player Dec 21 15:39:38 volumio3840x2160 volumio[1372]: info: ControllerMpd::getState Dec 21 15:39:38 volumio3840x2160 volumio[1372]: verbose: ControllerMpd::sendMpdCommand status Dec 21 15:39:38 volumio3840x2160 volumio[1372]: info: sendMpdCommand playlistinfo took 1 milliseconds Dec 21 15:39:38 volumio3840x2160 volumio[1372]: verbose: ControllerMpd::parseTrackInfo Dec 21 15:39:38 volumio3840x2160 volumio[1372]: info: ControllerMpd::pushState Dec 21 15:39:38 volumio3840x2160 volumio[1372]: info: CoreCommandRouter::servicePushState Dec 21 15:39:38 volumio3840x2160 volumio[1372]: info: CorePlayQueue::getTrack 0 Dec 21 15:39:38 volumio3840x2160 volumio[1372]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":170,"samplerate":"96 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"604 Kbps","isStreaming":false,"title":"Robin (The Hooded Man)","artist":"Clannad","album":"Legend [Vinyl]","uri":"NAS/Music_GP/01 Progresive - Psychadelic - Smooth - Electronic/Clannad/[1984] Legend [Vinyl]/A1 Robin (The Hooded Man).flac","trackType":"flac"} Dec 21 15:39:38 volumio3840x2160 volumio[1372]: verbose: CURRENT POSITION 0 Dec 21 15:39:38 volumio3840x2160 volumio[1372]: info: CoreStateMachine::syncState stateService play Dec 21 15:39:38 volumio3840x2160 volumio[1372]: info: CoreStateMachine::syncState currentStatus stop Dec 21 15:39:38 volumio3840x2160 volumio[1372]: info: ------------------------------ 15ms Dec 21 15:39:38 volumio3840x2160 volumio[1372]: info: sendMpdCommand status took 3 milliseconds Dec 21 15:39:38 volumio3840x2160 volumio[1372]: verbose: ControllerMpd::parseState Dec 21 15:39:38 volumio3840x2160 volumio[1372]: verbose: ControllerMpd::sendMpdCommand playlistinfo Dec 21 15:39:38 volumio3840x2160 volumio[1372]: info: sendMpdCommand playlistinfo took 1 milliseconds Dec 21 15:39:38 volumio3840x2160 volumio[1372]: verbose: ControllerMpd::parseTrackInfo Dec 21 15:39:38 volumio3840x2160 volumio[1372]: info: ControllerMpd::pushState Dec 21 15:39:38 volumio3840x2160 volumio[1372]: info: CoreCommandRouter::servicePushState Dec 21 15:39:38 volumio3840x2160 volumio[1372]: info: CorePlayQueue::getTrack 0 Dec 21 15:39:38 volumio3840x2160 volumio[1372]: verbose: STATE SERVICE {"status":"play","position":0,"seek":625,"duration":170,"samplerate":"96 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"341 Kbps","isStreaming":false,"title":"Robin (The Hooded Man)","artist":"Clannad","album":"Legend [Vinyl]","uri":"NAS/Music_GP/01 Progresive - Psychadelic - Smooth - Electronic/Clannad/[1984] Legend [Vinyl]/A1 Robin (The Hooded Man).flac","trackType":"flac"} Dec 21 15:39:38 volumio3840x2160 volumio[1372]: verbose: CURRENT POSITION 0 Dec 21 15:39:38 volumio3840x2160 volumio[1372]: info: CoreStateMachine::syncState stateService play Dec 21 15:39:38 volumio3840x2160 volumio[1372]: info: CoreStateMachine::syncState currentStatus play Dec 21 15:39:38 volumio3840x2160 volumio[1372]: info: Received an update from plugin. extracting info from payload Dec 21 15:39:38 volumio3840x2160 volumio[1372]: info: CoreStateMachine::pushState Dec 21 15:39:38 volumio3840x2160 volumio[1372]: info: CorePlayQueue::getTrack 0 Dec 21 15:39:38 volumio3840x2160 volumio[1372]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 21 15:39:38 volumio3840x2160 volumio[1372]: info: CoreCommandRouter::volumioPushState Dec 21 15:39:39 volumio3840x2160 volumio[1372]: info: CoreStateMachine::pushState Dec 21 15:39:39 volumio3840x2160 volumio[1372]: info: CorePlayQueue::getTrack 0 Dec 21 15:39:39 volumio3840x2160 volumio[1372]: info: CoreCommandRouter::volumioPushState Dec 21 15:39:39 volumio3840x2160 volumio[1372]: info: ------------------------------ 22ms Dec 21 15:39:39 volumio3840x2160 go-librespot[2392]: time="2025-12-21T15:39:39+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Dec 21 15:39:39 volumio3840x2160 go-librespot[2392]: time="2025-12-21T15:39:39+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Dec 21 15:39:39 volumio3840x2160 go-librespot[2392]: time="2025-12-21T15:39:39+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Dec 21 15:39:39 volumio3840x2160 go-librespot[2392]: time="2025-12-21T15:39:39+01:00" level=info msg="zeroconf server listening on port 46451" Dec 21 15:39:39 volumio3840x2160 volumio[1372]: info: Initializing connection to go-librespot Websocket Dec 21 15:39:39 volumio3840x2160 volumio[1372]: info: Connection to go-librespot Websocket established Dec 21 15:39:39 volumio3840x2160 go-librespot[2392]: time="2025-12-21T15:39:39+01:00" level=debug msg="new websocket client" Dec 21 15:39:39 volumio3840x2160 go-librespot[2392]: time="2025-12-21T15:39:39+01:00" level=debug msg="obtained new client token: AACsCe66oTL60GYtTkO3b0HKNoybC05Tsa30nrGf0GmDyrKq0ECsHM2+l5Erhz1XipH0Q02pUTocymsBc2xuBCpqFUnz5svWYDOONY1TaByDf6AV1NURx8vqkQjAJU0GWs2IF3vqe58jmE50zLiwh8bTiFaPBWXiO57tVS0VX0HfOZtMJfzUC9BZBZ18VYlI25NEnm53qCnbR7QyCt+LOF1nxh5aOfGRs2Y4bM3jf6TVnnyXtxhXwZs=" Dec 21 15:39:39 volumio3840x2160 go-librespot[2392]: time="2025-12-21T15:39:39+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Dec 21 15:39:39 volumio3840x2160 go-librespot[2392]: time="2025-12-21T15:39:39+01:00" level=debug msg="completed keyexchange" Dec 21 15:39:39 volumio3840x2160 go-librespot[2392]: time="2025-12-21T15:39:39+01:00" level=debug msg="completed challenge" Dec 21 15:39:39 volumio3840x2160 go-librespot[2392]: time="2025-12-21T15:39:39+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Dec 21 15:39:39 volumio3840x2160 volumio[1372]: info: Connection to go-librespot Websocket closed Dec 21 15:39:39 volumio3840x2160 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 21 15:39:39 volumio3840x2160 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 21 15:39:41 volumio3840x2160 volumio[1372]: info: Executing endpoint metavolumio Dec 21 15:39:41 volumio3840x2160 volumio[1372]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Dec 21 15:39:41 volumio3840x2160 volumio[1372]: info: Executing endpoint metavolumio Dec 21 15:39:41 volumio3840x2160 volumio[1372]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Dec 21 15:39:41 volumio3840x2160 volumio[1372]: info: Executing endpoint metavolumio Dec 21 15:39:41 volumio3840x2160 volumio[1372]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Dec 21 15:39:42 volumio3840x2160 volumio[1372]: info: Getting Spotify volume Dec 21 15:39:42 volumio3840x2160 volumio[1372]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 21 15:39:42 volumio3840x2160 volumio[1372]: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 21 15:39:42 volumio3840x2160 volumio[1372]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Dec 21 15:39:42 volumio3840x2160 volumio[1372]: errno: -111, Dec 21 15:39:42 volumio3840x2160 volumio[1372]: code: 'ECONNREFUSED', Dec 21 15:39:42 volumio3840x2160 volumio[1372]: syscall: 'connect', Dec 21 15:39:42 volumio3840x2160 volumio[1372]: address: '127.0.0.1', Dec 21 15:39:42 volumio3840x2160 volumio[1372]: port: 9879, Dec 21 15:39:42 volumio3840x2160 volumio[1372]: response: undefined Dec 21 15:39:42 volumio3840x2160 volumio[1372]: } Dec 21 15:39:42 volumio3840x2160 volumio[1372]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 21 15:39:42 volumio3840x2160 sudo[2418]: volumio : unable to resolve host volumio3840x2160: System error Dec 21 15:39:42 volumio3840x2160 sudo[2418]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-21 15:38' Dec 21 15:39:42 volumio3840x2160 sudo[2418]: 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="5250573efb99f2852fa27ea7e92def8586093039" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="d9e2b6784b9276d5a676bf564ce7524ad160509b" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri Dec 19 15:53:15 UTC 2025" VOLUMIO_VERSION="4.082" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="47d7740e8c55792fe06a847eb7ad6b29"