Aug 28 05:30:00 volumio-4 systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 3. Aug 28 05:30:00 volumio-4 systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Aug 28 05:30:01 volumio-4 systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Aug 28 05:30:01 volumio-4 upmpdcli[1501]: Could not open config: /tmp/upmpdcli.conf Aug 28 05:30:01 volumio-4 systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Aug 28 05:30:01 volumio-4 systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Aug 28 05:30:02 volumio-4 volumio[1433]: Starting albumart workers Aug 28 05:30:02 volumio-4 volumio[1432]: Starting albumart workers Aug 28 05:30:02 volumio-4 volumio[1434]: Starting albumart workers Aug 28 05:30:03 volumio-4 volumio[1200]: info: Loading i18n strings for locale en Aug 28 05:30:03 volumio-4 volumio[1200]: Updating browse sources language Aug 28 05:30:03 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 28 05:30:04 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 28 05:30:04 volumio-4 volumio[1200]: info: CoreCommandRouter::initPlayerControls Aug 28 05:30:04 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 05:30:04 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 05:30:04 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 05:30:04 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 05:30:04 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 05:30:04 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 05:30:04 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 05:30:04 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 05:30:04 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 28 05:30:05 volumio-4 volumio[1200]: Express server listening on port 3000 Aug 28 05:30:05 volumio-4 volumio[1200]: [Metrics] WebUI: 30s 801.47ms Aug 28 05:30:05 volumio-4 volumio[1200]: info: CoreStateMachine::resetVolumioState Aug 28 05:30:05 volumio-4 volumio[1200]: info: CoreStateMachine::getcurrentVolume Aug 28 05:30:05 volumio-4 volumio[1200]: info: CoreCommandRouter::volumioRetrievevolume Aug 28 05:30:05 volumio-4 sudo[1508]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Aug 28 05:30:05 volumio-4 sudo[1509]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Aug 28 05:30:05 volumio-4 sudo[1508]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 05:30:05 volumio-4 sudo[1509]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 05:30:05 volumio-4 sudo[1508]: pam_unix(sudo:session): session closed for user root Aug 28 05:30:05 volumio-4 sudo[1509]: pam_unix(sudo:session): session closed for user root Aug 28 05:30:05 volumio-4 volumio[1200]: info: Volumio Network Manager: Network status updated: 2 Aug 28 05:30:07 volumio-4 volumio-remote-updater[740]: [2026-08-28 05:30:07] [connect] Successful connection Aug 28 05:30:07 volumio-4 volumio[1200]: info: VolumeController:: Volume=25 Mute =false Aug 28 05:30:07 volumio-4 volumio[1200]: info: CoreStateMachine::pushState Aug 28 05:30:07 volumio-4 volumio[1200]: info: CorePlayQueue::getTrack 0 Aug 28 05:30:07 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 28 05:30:07 volumio-4 volumio[1200]: info: CoreCommandRouter::volumioPushState Aug 28 05:30:07 volumio-4 volumio[1200]: info: CoreStateMachine::updateTrackBlock Aug 28 05:30:07 volumio-4 volumio[1200]: info: CorePlayQueue::getTrackBlock Aug 28 05:30:07 volumio-4 volumio[1200]: info: CoreCommandRouter::volumioRetrievevolume Aug 28 05:30:07 volumio-4 volumio[1200]: verbose: New Socket.io Connection to 192.168.1.207 from 192.168.1.85 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:154.0) Gecko/20100101 Firefox/154.0 Engine version: 3 Transport: polling Total Clients: 1 Aug 28 05:30:08 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 05:30:08 volumio-4 volumio[1200]: info: Reloading queue from file Aug 28 05:30:08 volumio-4 volumio[1200]: verbose: New Socket.io Connection to 192.168.1.207 from 192.168.1.85 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:154.0) Gecko/20100101 Firefox/154.0 Engine version: 3 Transport: polling Total Clients: 2 Aug 28 05:30:08 volumio-4 volumio[1200]: info: CoreStateMachine::setRepeat null single undefined Aug 28 05:30:08 volumio-4 volumio[1200]: info: CoreStateMachine::pushState Aug 28 05:30:08 volumio-4 volumio[1200]: info: CorePlayQueue::getTrack 0 Aug 28 05:30:08 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 28 05:30:08 volumio-4 volumio[1200]: info: CoreCommandRouter::volumioPushState Aug 28 05:30:08 volumio-4 volumio[1200]: info: CoreStateMachine::setRandom null Aug 28 05:30:08 volumio-4 volumio[1200]: info: CoreStateMachine::pushState Aug 28 05:30:08 volumio-4 volumio[1200]: info: CorePlayQueue::getTrack 0 Aug 28 05:30:08 volumio-4 volumio[1200]: info: CoreCommandRouter::volumioPushState Aug 28 05:30:08 volumio-4 volumio[1200]: info: Setting Device type: Raspberry PI Aug 28 05:30:08 volumio-4 volumio[1200]: verbose: New Socket.io Connection to 192.168.1.207 from 192.168.1.85 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:154.0) Gecko/20100101 Firefox/154.0 Engine version: 3 Transport: polling Total Clients: 3 Aug 28 05:30:08 volumio-4 volumio[1200]: verbose: New Socket.io Connection to 192.168.1.207 from 192.168.1.85 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:154.0) Gecko/20100101 Firefox/154.0 Engine version: 3 Transport: polling Total Clients: 4 Aug 28 05:30:08 volumio-4 volumio[1200]: info: Completed loading Core Plugins Aug 28 05:30:08 volumio-4 volumio[1200]: info: Preparing to generate the ALSA configuration file Aug 28 05:30:08 volumio-4 volumio[1200]: info: VolumeController:: Volume=25 Mute =false Aug 28 05:30:08 volumio-4 volumio[1200]: info: CoreStateMachine::pushState Aug 28 05:30:08 volumio-4 volumio[1200]: info: CorePlayQueue::getTrack 0 Aug 28 05:30:08 volumio-4 volumio[1200]: info: CoreCommandRouter::volumioPushState Aug 28 05:30:09 volumio-4 volumio[1200]: info: The plugin fusiondsp has an ALSA contribution file volumioDsp.postDsp.10.conf Aug 28 05:30:09 volumio-4 volumio[1200]: info: Reading ALSA contributions from plugins. Aug 28 05:30:09 volumio-4 volumio[1200]: verbose: New Socket.io Connection to 192.168.1.207 from 192.168.1.85 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:154.0) Gecko/20100101 Firefox/154.0 Engine version: 3 Transport: polling Total Clients: 5 Aug 28 05:30:09 volumio-4 volumio[1200]: info: Discovery: adding 8d3917a7-1ea7-4dfa-b54f-ec5c360f8532 Aug 28 05:30:09 volumio-4 volumio[1200]: info: Discovery: Found device Volumio 4 Aug 28 05:30:09 volumio-4 volumio[1200]: info: CoreCommandRouter::volumioGetState Aug 28 05:30:09 volumio-4 volumio[1200]: info: CorePlayQueue::getTrack 0 Aug 28 05:30:09 volumio-4 sudo[1545]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Aug 28 05:30:09 volumio-4 sudo[1545]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 05:30:09 volumio-4 volumio[1200]: info: CoreCommandRouter::volumioGetState Aug 28 05:30:09 volumio-4 volumio[1200]: info: CorePlayQueue::getTrack 0 Aug 28 05:30:09 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Aug 28 05:30:09 volumio-4 volumio[1200]: info: CoreCommandRouter::volumioGetVisibleSources Aug 28 05:30:09 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 28 05:30:09 volumio-4 volumio[1200]: info: Listing playlists Aug 28 05:30:09 volumio-4 volumio[1200]: info: CoreCommandRouter::volumioGetQueue Aug 28 05:30:09 volumio-4 volumio[1200]: info: CoreStateMachine::getQueue Aug 28 05:30:09 volumio-4 volumio[1200]: info: CorePlayQueue::getQueue Aug 28 05:30:09 volumio-4 volumio[1200]: verbose: New Socket.io Connection to 192.168.1.207 from 192.168.1.85 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:154.0) Gecko/20100101 Firefox/154.0 Engine version: 3 Transport: polling Total Clients: 6 Aug 28 05:30:10 volumio-4 volumio[1200]: info: Discovery: this is already registered, 8d3917a7-1ea7-4dfa-b54f-ec5c360f8532 Aug 28 05:30:10 volumio-4 volumio[1200]: info: Discovery: Found device Volumio 4 Aug 28 05:30:10 volumio-4 volumio[1200]: info: CoreCommandRouter::volumioGetState Aug 28 05:30:10 volumio-4 volumio[1200]: info: CorePlayQueue::getTrack 0 Aug 28 05:30:10 volumio-4 volumio[1200]: verbose: New Socket.io Connection to 192.168.1.207 from 192.168.1.85 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:154.0) Gecko/20100101 Firefox/154.0 Engine version: 3 Transport: polling Total Clients: 7 Aug 28 05:30:10 volumio-4 volumio-remote-updater[740]: [2026-08-28 05:30:10] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1787913007 101 Aug 28 05:30:10 volumio-4 volumio[1200]: 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: 8 Aug 28 05:30:10 volumio-4 volumio[1200]: info: Asound.conf file written Aug 28 05:30:10 volumio-4 sudo[1565]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mv /home/volumio/.asoundrc /etc/asound.conf Aug 28 05:30:11 volumio-4 sudo[1565]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 05:30:11 volumio-4 sudo[1565]: pam_unix(sudo:session): session closed for user root Aug 28 05:30:11 volumio-4 volumio[1200]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:0 use case configuration -2 Aug 28 05:30:11 volumio-4 volumio[1200]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:1 use case configuration -2 Aug 28 05:30:11 volumio-4 volumio[1200]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:2 use case configuration -2 Aug 28 05:30:11 volumio-4 volumio[1200]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:3 use case configuration -2 Aug 28 05:30:11 volumio-4 volumio[1200]: info: Output device has changed, restarting MPD Aug 28 05:30:11 volumio-4 volumio[1200]: info: Output device has changed, restarting Shairport Sync Aug 28 05:30:11 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 05:30:11 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 05:30:11 volumio-4 sudo[1571]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Aug 28 05:30:11 volumio-4 sudo[1571]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 05:30:11 volumio-4 sudo[1573]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Aug 28 05:30:11 volumio-4 sudo[1573]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 05:30:11 volumio-4 sudo[1571]: pam_unix(sudo:session): session closed for user root Aug 28 05:30:11 volumio-4 volumio[1200]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Aug 28 05:30:11 volumio-4 volumio[1200]: info: ___________ START PLUGINS ___________ Aug 28 05:30:11 volumio-4 volumio[1200]: info: ControllerMpd::onStart: Initializing MPD Aug 28 05:30:11 volumio-4 volumio[1200]: info: Creating MPD Configuration file Aug 28 05:30:11 volumio-4 systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Aug 28 05:30:11 volumio-4 systemd[1]: Starting mpd.service - Music Player Daemon... Aug 28 05:30:11 volumio-4 sudo[1582]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumio5-onboarding.service Aug 28 05:30:11 volumio-4 sudo[1584]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Aug 28 05:30:11 volumio-4 sudo[1584]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 05:30:11 volumio-4 sudo[1582]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 05:30:11 volumio-4 sudo[1584]: pam_unix(sudo:session): session closed for user root Aug 28 05:30:12 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 28 05:30:12 volumio-4 sudo[1585]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Aug 28 05:30:12 volumio-4 sudo[1585]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Aug 28 05:30:12 volumio-4 volumio[1200]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 28 05:30:12 volumio-4 volumio[1200]: info: [1787913012040] CoreMusicLibrary::Adding element Media Servers Aug 28 05:30:12 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 28 05:30:12 volumio-4 sudo[1590]: /bin/chown: cannot access '/var/log/mpd.log': No such file or directory Aug 28 05:30:12 volumio-4 sudo[1585]: pam_unix(sudo:session): session closed for user root Aug 28 05:30:12 volumio-4 systemd[1]: Started volumio5-onboarding.service - Volumio5 Onboarding Server. Aug 28 05:30:12 volumio-4 sudo[1589]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Aug 28 05:30:12 volumio-4 sudo[1589]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 05:30:12 volumio-4 volumio[1200]: info: UPNP Browser: Client initialized successfully Aug 28 05:30:12 volumio-4 sudo[1582]: pam_unix(sudo:session): session closed for user root Aug 28 05:30:12 volumio-4 systemd[1]: mpd.service: Deactivated successfully. Aug 28 05:30:12 volumio-4 systemd[1]: Stopped mpd.service - Music Player Daemon. Aug 28 05:30:12 volumio-4 systemd[1]: mpd.socket: Deactivated successfully. Aug 28 05:30:12 volumio-4 systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Aug 28 05:30:12 volumio-4 systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Aug 28 05:30:12 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 05:30:12 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 05:30:12 volumio-4 systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Aug 28 05:30:12 volumio-4 systemd[1]: Starting mpd.service - Music Player Daemon... Aug 28 05:30:12 volumio-4 volumio[1200]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Aug 28 05:30:12 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 05:30:12 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 05:30:12 volumio-4 sudo[1603]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Aug 28 05:30:12 volumio-4 sudo[1603]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Aug 28 05:30:12 volumio-4 sudo[1610]: /bin/chown: cannot access '/var/log/mpd.log': No such file or directory Aug 28 05:30:12 volumio-4 sudo[1603]: pam_unix(sudo:session): session closed for user root Aug 28 05:30:12 volumio-4 volumio[1200]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Aug 28 05:30:12 volumio-4 volumio[1200]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 28 05:30:12 volumio-4 volumio[1200]: info: [1787913012904] CoreMusicLibrary::Adding element Last_100 Aug 28 05:30:12 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 28 05:30:12 volumio-4 volumio5-onboarding[1592]: time=2026-08-28T05:30:12.904-05:00 level=INFO msg="running volumio5-device-gateway" version=6370e0a8+CHANGES buildDate=2026-03-06T16:29:42Z Aug 28 05:30:12 volumio-4 volumio[1200]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 28 05:30:12 volumio-4 volumio[1200]: info: [1787913012909] CoreMusicLibrary::Adding element Webradio Aug 28 05:30:12 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 28 05:30:13 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 28 05:30:13 volumio-4 volumio[1200]: info: Initializing BBC Radios Aug 28 05:30:13 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 28 05:30:13 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 05:30:13 volumio-4 volumio[1200]: info: Creating Spotify config file Aug 28 05:30:13 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 05:30:16 volumio-4 systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 4. Aug 28 05:30:16 volumio-4 systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Aug 28 05:30:16 volumio-4 systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Aug 28 05:30:16 volumio-4 sudo[1545]: pam_unix(sudo:session): session closed for user root Aug 28 05:30:17 volumio-4 volumio[1200]: info: FusionDsp - CamillaDSP binary found. Aug 28 05:30:17 volumio-4 volumio[1200]: info: Loading i18n strings for locale en Aug 28 05:30:17 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , updateALSAConfigFile Aug 28 05:30:17 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 05:30:17 volumio-4 volumio[1200]: info: FusionDsp - mixtype--------------------- Hardware Aug 28 05:30:17 volumio-4 volumio[1200]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 28 05:30:17 volumio-4 volumio[1200]: info: [1787913017812] CoreMusicLibrary::Adding element Mother Earth Radio Aug 28 05:30:17 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 28 05:30:17 volumio-4 volumio[1200]: Cannot find translation for source Mother Earth Radio Aug 28 05:30:17 volumio-4 volumio[1200]: info: [MER] Plugin started (SSE mode) Aug 28 05:30:18 volumio-4 volumio[1200]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 28 05:30:18 volumio-4 volumio[1200]: info: [1787913018056] CoreMusicLibrary::Adding element Radio Paradise Aug 28 05:30:18 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 28 05:30:18 volumio-4 volumio[1200]: Cannot find translation for source Mother Earth Radio Aug 28 05:30:18 volumio-4 volumio[1200]: Cannot find translation for source Radio Paradise Aug 28 05:30:18 volumio-4 volumio[1200]: info: Volumio Calling Home Aug 28 05:30:18 volumio-4 volumio[1200]: info: Preparing to generate the ALSA configuration file Aug 28 05:30:21 volumio-4 volumio[1200]: info: The plugin fusiondsp has an ALSA contribution file volumioDsp.postDsp.10.conf Aug 28 05:30:21 volumio-4 volumio[1200]: info: Reading ALSA contributions from plugins. Aug 28 05:30:21 volumio-4 volumio[1200]: info: MPD Permissions set Aug 28 05:30:21 volumio-4 volumio[1200]: info: MPD Permissions set Aug 28 05:30:21 volumio-4 volumio[1200]: info: Upmpdcli Daemon Started Aug 28 05:30:21 volumio-4 volumio[1200]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 9 Aug 28 05:30:21 volumio-4 volumio[1200]: info: Volumio called home Aug 28 05:30:21 volumio-4 volumio[1200]: info: Spotify config file written Aug 28 05:30:22 volumio-4 sudo[1658]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Aug 28 05:30:22 volumio-4 sudo[1658]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 05:30:22 volumio-4 mpd[1611]: 2026-08-28T05:30:22 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Aug 28 05:30:22 volumio-4 systemd[1]: /lib/systemd/system/go-librespot-daemon.service:9: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Aug 28 05:30:22 volumio-4 systemd[1]: /lib/systemd/system/go-librespot-daemon.service:10: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Aug 28 05:30:22 volumio-4 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 28 05:30:22 volumio-4 go-librespot[1660]: go-librespot daemon starting... Aug 28 05:30:22 volumio-4 sudo[1658]: pam_unix(sudo:session): session closed for user root Aug 28 05:30:22 volumio-4 systemd[1]: Started mpd.service - Music Player Daemon. Aug 28 05:30:22 volumio-4 sudo[1589]: pam_unix(sudo:session): session closed for user root Aug 28 05:30:22 volumio-4 sudo[1573]: pam_unix(sudo:session): session closed for user root Aug 28 05:30:22 volumio-4 volumio[1200]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 9 Aug 28 05:30:23 volumio-4 volumio[1200]: info: Received Get System Info Aug 28 05:30:23 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 28 05:30:23 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 28 05:30:23 volumio-4 volumio[1200]: info: Discovery: Getting this device information Aug 28 05:30:23 volumio-4 volumio[1200]: info: CoreCommandRouter::volumioGetState Aug 28 05:30:23 volumio-4 volumio[1200]: info: CorePlayQueue::getTrack 0 Aug 28 05:30:23 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 28 05:30:23 volumio-4 volumio5-onboarding[1592]: time=2026-08-28T05:30:23.041-05:00 level=INFO msg="system info for c779468a483b39ef6ab3705a4e983170" deviceName="Volumio 4" deviceVariant=volumio deviceModel= softwareVersion=4.119 Aug 28 05:30:23 volumio-4 volumio5-onboarding[1592]: time=2026-08-28T05:30:23.055-05:00 level=INFO msg="bootstrapping state" hasInternet=true Aug 28 05:30:23 volumio-4 volumio[1200]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 10 Aug 28 05:30:23 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 05:30:23 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 05:30:23 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 05:30:23 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 05:30:23 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 05:30:23 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 05:30:23 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 05:30:23 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 05:30:23 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 05:30:23 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 05:30:23 volumio-4 go-librespot[1661]: time="2026-08-28T05:30:23-05:00" level=info msg="running go-librespot 0.7.1" Aug 28 05:30:23 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 05:30:23 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 05:30:23 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 05:30:23 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 05:30:23 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 05:30:23 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 05:30:23 volumio-4 go-librespot[1661]: time="2026-08-28T05:30:23-05:00" level=debug msg="app state loaded" Aug 28 05:30:23 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 05:30:23 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 05:30:23 volumio-4 go-librespot[1661]: time="2026-08-28T05:30:23-05:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 28 05:30:23 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 05:30:23 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 05:30:23 volumio-4 volumio[1200]: info: No need to fix Spotify hosts Aug 28 05:30:23 volumio-4 go-librespot[1661]: time="2026-08-28T05:30:23-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew1.spotify.com:80]" Aug 28 05:30:23 volumio-4 go-librespot[1661]: time="2026-08-28T05:30:23-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Aug 28 05:30:23 volumio-4 go-librespot[1661]: time="2026-08-28T05:30:23-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Aug 28 05:30:23 volumio-4 go-librespot[1661]: time="2026-08-28T05:30:23-05:00" level=info msg="zeroconf server listening on port 40267" Aug 28 05:30:23 volumio-4 go-librespot[1661]: time="2026-08-28T05:30:23-05:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 28 05:30:24 volumio-4 go-librespot[1661]: time="2026-08-28T05:30:24-05:00" level=debug msg="obtained new client token: AAFdU4SKd9/8ZBphbQG+QXWzOCmpHTwJJy6hpbVH96UFn37pScWLuSdbAX1qqz+iq/kYWMIyqObcl5lPeuOP58KmnJPg/20ezCfoX5DsG+uR5knVTAHdLHor6ed1UwvJlZ4BsKMUcQWDhX52nmQ284N8s1vnyfYU5zzzi886b+sEvCVj5a9jfN4zcoWGdEnWQWKxpdqYNDvH4ERt/P+X3HDkK4SE/YbHeNPwePUrXAQg0kVPAPxSkA==" Aug 28 05:30:24 volumio-4 volumio[1200]: info: Received Get System Info Aug 28 05:30:24 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 28 05:30:24 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 28 05:30:24 volumio-4 volumio[1200]: info: Discovery: Getting this device information Aug 28 05:30:24 volumio-4 volumio[1200]: info: CoreCommandRouter::volumioGetState Aug 28 05:30:24 volumio-4 volumio[1200]: info: CorePlayQueue::getTrack 0 Aug 28 05:30:24 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 28 05:30:24 volumio-4 go-librespot[1661]: time="2026-08-28T05:30:24-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Aug 28 05:30:24 volumio-4 go-librespot[1661]: time="2026-08-28T05:30:24-05:00" level=debug msg="completed keyexchange" Aug 28 05:30:24 volumio-4 go-librespot[1661]: time="2026-08-28T05:30:24-05:00" level=debug msg="completed challenge" Aug 28 05:30:24 volumio-4 go-librespot[1661]: time="2026-08-28T05:30:24-05:00" level=info msg="authenticated AP" username="31************************pi" Aug 28 05:30:24 volumio-4 go-librespot[1661]: time="2026-08-28T05:30:24-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 28 05:30:24 volumio-4 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 28 05:30:24 volumio-4 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 28 05:30:24 volumio-4 volumio[1200]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 11 Aug 28 05:30:25 volumio-4 volumio[1200]: info: Completed starting Core Plugins Aug 28 05:30:25 volumio-4 volumio[1200]: info: ------------------------------------------- Aug 28 05:30:25 volumio-4 volumio[1200]: info: ----- MyVolumio plugins startup ---- Aug 28 05:30:25 volumio-4 volumio[1200]: info: ------------------------------------------- Aug 28 05:30:25 volumio-4 volumio[1200]: info: [MyVolumio PluginManager] Fetching plans data.... Aug 28 05:30:25 volumio-4 volumio-remote-updater[740]: Test mode disabled Aug 28 05:30:25 volumio-4 volumio-remote-updater[740]: Alpha mode disabled Aug 28 05:30:25 volumio-4 volumio-remote-updater[740]: Alpha legacy test mode disabled Aug 28 05:30:25 volumio-4 volumio[1200]: info: New Spotify access tokenBQDpBTyuR3... Aug 28 05:30:25 volumio-4 volumio[1200]: info: Spotify credentials grant success - running version from March 24, 2019 Aug 28 05:30:27 volumio-4 volumio[1200]: error: MPD error: The expression evaluated to a falsy value: Aug 28 05:30:27 volumio-4 volumio[1200]: assert.ok(self.idling) Aug 28 05:30:27 volumio-4 volumio[1200]: error: The expression evaluated to a falsy value: Aug 28 05:30:27 volumio-4 volumio[1200]: assert.ok(self.idling) Aug 28 05:30:27 volumio-4 volumio[1200]: info: Update Ready: {"changeLogLink":"","description":"You're already on the latest version","title":"No Updates Available","updateavailable":false} Aug 28 05:30:27 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache Aug 28 05:30:27 volumio-4 volumio[1200]: info: MPD running with PID1611 Aug 28 05:30:27 volumio-4 volumio[1200]: ,establishing connection Aug 28 05:30:27 volumio-4 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Aug 28 05:30:27 volumio-4 systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 28 05:30:27 volumio-4 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 28 05:30:27 volumio-4 go-librespot[1695]: go-librespot daemon starting... Aug 28 05:30:27 volumio-4 volumio[1200]: info: FusionDsp - If filter freq >samplerate/2 then disable it Aug 28 05:30:27 volumio-4 go-librespot[1696]: time="2026-08-28T05:30:27-05:00" level=info msg="running go-librespot 0.7.1" Aug 28 05:30:27 volumio-4 go-librespot[1696]: time="2026-08-28T05:30:27-05:00" level=debug msg="app state loaded" Aug 28 05:30:27 volumio-4 go-librespot[1696]: time="2026-08-28T05:30:27-05:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 28 05:30:27 volumio-4 volumio[1200]: info: FusionDsp - Crossfeed selected : linkwitz Aug 28 05:30:28 volumio-4 go-librespot[1696]: time="2026-08-28T05:30:28-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew4.spotify.com:80]" Aug 28 05:30:28 volumio-4 go-librespot[1696]: time="2026-08-28T05:30:28-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Aug 28 05:30:28 volumio-4 go-librespot[1696]: time="2026-08-28T05:30:28-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Aug 28 05:30:28 volumio-4 go-librespot[1696]: time="2026-08-28T05:30:28-05:00" level=info msg="zeroconf server listening on port 35641" Aug 28 05:30:28 volumio-4 go-librespot[1696]: time="2026-08-28T05:30:28-05:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 28 05:30:28 volumio-4 go-librespot[1696]: time="2026-08-28T05:30:28-05:00" level=debug msg="obtained new client token: AAHfvX91nPkEXG0Xl1IvBuI3xHnvLAzGKtYO+QNLfoOYDnr5fByZRo412kyg29rkyUymlfBFDePwE3uohe02iO0SVMyEy1JrdF9AuRfiQJmDUAe8464M9CKjXBXhPjKJUH4wxJmlqBhsz64hBmIs83cNyEdcylsW08t4fET2WKxFGxELExVQ717J20xdjFiC+VLDx0mM+nPfJyQ/BBY1GUi34O04f5Wk5tVuKST2pr3+OigGhXAAvw==" Aug 28 05:30:28 volumio-4 volumio[1200]: info: camilladsp service started and running in background, instance 1 Aug 28 05:30:28 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 05:30:28 volumio-4 go-librespot[1696]: time="2026-08-28T05:30:28-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Aug 28 05:30:28 volumio-4 go-librespot[1696]: time="2026-08-28T05:30:28-05:00" level=debug msg="completed keyexchange" Aug 28 05:30:28 volumio-4 go-librespot[1696]: time="2026-08-28T05:30:28-05:00" level=debug msg="completed challenge" Aug 28 05:30:28 volumio-4 go-librespot[1696]: time="2026-08-28T05:30:28-05:00" level=info msg="authenticated AP" username="31************************pi" Aug 28 05:30:28 volumio-4 volumio[1200]: info: FusionDsp - AAAAAAAAAAAAAA-> 22050 44100 48000 88200 96000 176400 192000 384000 <-AAAAAAAAAAAAA Aug 28 05:30:28 volumio-4 go-librespot[1696]: time="2026-08-28T05:30:28-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 28 05:30:28 volumio-4 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 28 05:30:28 volumio-4 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 28 05:30:28 volumio-4 sudo[1713]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start fusiondsp.service Aug 28 05:30:28 volumio-4 sudo[1713]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 05:30:28 volumio-4 volumio[1200]: info: FusionDsp loaded Aug 28 05:30:28 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 28 05:30:28 volumio-4 volumio[1200]: info: FusionDsp - --[object Object] Aug 28 05:30:28 volumio-4 volumio[1200]: error: FusionDsp - Socket connection not established Aug 28 05:30:28 volumio-4 volumio[1200]: info: FusionDsp - Reporting Fusion DSP Enabled Aug 28 05:30:28 volumio-4 volumio[1200]: info: Adding Signal Path Element [object Object] Aug 28 05:30:28 volumio-4 volumio[1200]: info: Adding fusiondspeq DSP Signal Path Element Aug 28 05:30:28 volumio-4 volumio[1200]: info: FusionDsp - ---- installed callbackRead (debounced 200ms) Aug 28 05:30:28 volumio-4 volumio[1200]: info: FusionDsp - PEQ graph server listening on port 10015 Aug 28 05:30:28 volumio-4 volumio[1200]: info: Starting Shairport Sync Aug 28 05:30:28 volumio-4 systemd[1]: Starting fusiondsp.service - FusionDsp Daemon... Aug 28 05:30:28 volumio-4 volumio[1200]: info: Starting Shairport Sync Aug 28 05:30:28 volumio-4 sudo[1719]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Aug 28 05:30:28 volumio-4 sudo[1719]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 05:30:28 volumio-4 volumio[1200]: info: Starting Shairport Sync Aug 28 05:30:29 volumio-4 sudo[1717]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Aug 28 05:30:29 volumio-4 sudo[1717]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 05:30:29 volumio-4 volumio[1200]: error: updateQueue error: null Aug 28 05:30:29 volumio-4 systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Aug 28 05:30:29 volumio-4 systemd[1]: shairport-sync.service: Deactivated successfully. Aug 28 05:30:29 volumio-4 systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 28 05:30:29 volumio-4 systemd[1]: shairport-sync.service: Consumed 1.597s CPU time. Aug 28 05:30:29 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 28 05:30:29 volumio-4 systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 28 05:30:29 volumio-4 sudo[1722]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Aug 28 05:30:29 volumio-4 sudo[1719]: pam_unix(sudo:session): session closed for user root Aug 28 05:30:29 volumio-4 systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Aug 28 05:30:29 volumio-4 systemd[1]: shairport-sync.service: Deactivated successfully. Aug 28 05:30:29 volumio-4 systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 28 05:30:29 volumio-4 sudo[1722]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 05:30:29 volumio-4 volumio[1200]: info: go-librespot daemon successfully initialized Aug 28 05:30:29 volumio-4 systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 28 05:30:29 volumio-4 sudo[1717]: pam_unix(sudo:session): session closed for user root Aug 28 05:30:29 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 28 05:30:29 volumio-4 systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Aug 28 05:30:29 volumio-4 systemd[1]: shairport-sync.service: Deactivated successfully. Aug 28 05:30:29 volumio-4 systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 28 05:30:29 volumio-4 volumio[1200]: error: FusionDsp - Reload WebSocket error: [object Object] Aug 28 05:30:29 volumio-4 systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 28 05:30:29 volumio-4 sudo[1722]: pam_unix(sudo:session): session closed for user root Aug 28 05:30:29 volumio-4 volumio[1200]: info: Shairport-Sync Started Aug 28 05:30:29 volumio-4 volumio[1200]: Error adding Membership: Error: addMembership EINVAL Aug 28 05:30:29 volumio-4 volumio[1200]: info: Asound.conf file unchanged, so no further update is needed Aug 28 05:30:29 volumio-4 volumio[1200]: info: Output device has changed, restarting MPD Aug 28 05:30:29 volumio-4 volumio[1200]: info: Output device has changed, restarting Shairport Sync Aug 28 05:30:29 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 05:30:29 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 05:30:29 volumio-4 sudo[1758]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Aug 28 05:30:29 volumio-4 sudo[1758]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 05:30:30 volumio-4 volumio[1200]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Aug 28 05:30:30 volumio-4 sudo[1759]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Aug 28 05:30:30 volumio-4 sudo[1759]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 05:30:30 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 28 05:30:30 volumio-4 systemd[1]: Stopping mpd.service - Music Player Daemon... Aug 28 05:30:30 volumio-4 sudo[1759]: pam_unix(sudo:session): session closed for user root Aug 28 05:30:30 volumio-4 volumio[1200]: error: updateQueue error: null Aug 28 05:30:30 volumio-4 systemd[1]: mpd.service: Deactivated successfully. Aug 28 05:30:30 volumio-4 systemd[1]: Stopped mpd.service - Music Player Daemon. Aug 28 05:30:30 volumio-4 systemd[1]: mpd.service: Consumed 6.852s CPU time. Aug 28 05:30:30 volumio-4 systemd[1]: mpd.socket: Deactivated successfully. Aug 28 05:30:30 volumio-4 systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Aug 28 05:30:30 volumio-4 systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Aug 28 05:30:30 volumio-4 systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Aug 28 05:30:30 volumio-4 systemd[1]: Starting mpd.service - Music Player Daemon... Aug 28 05:30:31 volumio-4 volumio[1200]: info: Shairport-Sync Started Aug 28 05:30:31 volumio-4 volumio[1200]: info: Shairport-Sync Started Aug 28 05:30:31 volumio-4 volumio[1200]: error: MPD error: Error: write EPIPE Aug 28 05:30:31 volumio-4 volumio[1200]: error: write EPIPE {"code":"EPIPE","errno":-32,"syscall":"write"} Aug 28 05:30:31 volumio-4 volumio[1200]: info: Received Get System Info Aug 28 05:30:31 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 28 05:30:31 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 28 05:30:31 volumio-4 volumio[1200]: info: Discovery: Getting this device information Aug 28 05:30:31 volumio-4 volumio[1200]: info: CoreCommandRouter::volumioGetState Aug 28 05:30:31 volumio-4 sudo[1771]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Aug 28 05:30:31 volumio-4 sudo[1771]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Aug 28 05:30:31 volumio-4 volumio[1200]: info: CorePlayQueue::getTrack 0 Aug 28 05:30:31 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 28 05:30:31 volumio-4 sudo[1771]: pam_unix(sudo:session): session closed for user root Aug 28 05:30:31 volumio-4 volumio[1200]: info: MPD Permissions set Aug 28 05:30:31 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Aug 28 05:30:31 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Aug 28 05:30:31 volumio-4 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Aug 28 05:30:31 volumio-4 systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 28 05:30:31 volumio-4 volumio5-onboarding[1592]: time=2026-08-28T05:30:31.756-05:00 level=INFO msg="enabling local network discovery" Aug 28 05:30:31 volumio-4 volumio5-onboarding[1592]: time=2026-08-28T05:30:31.798-05:00 level=INFO msg="enabling BLE discovery" Aug 28 05:30:31 volumio-4 go-librespot[1784]: go-librespot daemon starting... Aug 28 05:30:31 volumio-4 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 28 05:30:31 volumio-4 go-librespot[1787]: time="2026-08-28T05:30:31-05:00" level=info msg="running go-librespot 0.7.1" Aug 28 05:30:31 volumio-4 go-librespot[1787]: time="2026-08-28T05:30:31-05:00" level=debug msg="app state loaded" Aug 28 05:30:31 volumio-4 go-librespot[1787]: time="2026-08-28T05:30:31-05:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 28 05:30:32 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 05:30:32 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 05:30:32 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 05:30:32 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 05:30:32 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 05:30:32 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 05:30:32 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 05:30:32 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 05:30:32 volumio-4 go-librespot[1787]: time="2026-08-28T05:30:32-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Aug 28 05:30:32 volumio-4 go-librespot[1787]: time="2026-08-28T05:30:32-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Aug 28 05:30:32 volumio-4 go-librespot[1787]: time="2026-08-28T05:30:32-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Aug 28 05:30:32 volumio-4 go-librespot[1787]: time="2026-08-28T05:30:32-05:00" level=info msg="zeroconf server listening on port 33427" Aug 28 05:30:32 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 05:30:32 volumio-4 go-librespot[1787]: time="2026-08-28T05:30:32-05:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 28 05:30:32 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 05:30:32 volumio-4 volumio[1200]: info: Initializing connection to go-librespot Websocket Aug 28 05:30:32 volumio-4 go-librespot[1787]: time="2026-08-28T05:30:32-05:00" level=debug msg="obtained new client token: AAFnBvUa1XifiZT4akttY2rDnIVTtREWpXJTqy4+dVzzQEGA42DOPi71SzPJqPQYNm98i7TgmVslFc6Nn8+OwquqK7xAn0IoNfV20n6KaTxwiDU2hKXUA9hoFyx0VEjcLVMGJmMPILRJ3rJhhfrKdAV7v55U1MVdcyRRGVq0KRp67tNc9nibME9A0wz41onMOepmW1IdKLI/yHuwCS/Nc6D8SA9vcyHvjm4FkTUveG1KwrqZMzhNGgxV" Aug 28 05:30:32 volumio-4 go-librespot[1787]: time="2026-08-28T05:30:32-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Aug 28 05:30:32 volumio-4 volumio5-onboarding[1592]: time=2026-08-28T05:30:32.733-05:00 level=INFO msg="service successfully established" component=discovery/localnet Aug 28 05:30:32 volumio-4 volumio[1200]: info: CoreCommandRouter::volumioGetState Aug 28 05:30:32 volumio-4 volumio[1200]: info: CorePlayQueue::getTrack 0 Aug 28 05:30:32 volumio-4 go-librespot[1787]: time="2026-08-28T05:30:32-05:00" level=debug msg="completed keyexchange" Aug 28 05:30:32 volumio-4 go-librespot[1787]: time="2026-08-28T05:30:32-05:00" level=debug msg="completed challenge" Aug 28 05:30:32 volumio-4 go-librespot[1787]: time="2026-08-28T05:30:32-05:00" level=info msg="authenticated AP" username="31************************pi" Aug 28 05:30:32 volumio-4 volumio[1200]: SPOTIFY: User informations: {"account_id":"k0HhQsSNzD","country":"US","display_name":"Jeff S.","email":"jeffcell2158@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/315ufuseiivdu357uehxglyckipi"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/315ufuseiivdu357uehxglyckipi","id":"315ufuseiivdu357uehxglyckipi","images":[{"height":300,"url":"https://i.scdn.co/image/ab6775700000ee850e50d44ef386b2b753bf780c","width":300},{"height":64,"url":"https://i.scdn.co/image/ab67757000003b820e50d44ef386b2b753bf780c","width":64}],"product":"premium","type":"user","uri":"spotify:user:315ufuseiivdu357uehxglyckipi"} Aug 28 05:30:32 volumio-4 volumio[1200]: info: Spotify Successfully logged in Aug 28 05:30:32 volumio-4 volumio[1200]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 28 05:30:32 volumio-4 volumio[1200]: info: [1787913032982] CoreMusicLibrary::Adding element Spotify Aug 28 05:30:32 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 28 05:30:32 volumio-4 volumio[1200]: Cannot find translation for source Mother Earth Radio Aug 28 05:30:32 volumio-4 volumio[1200]: Cannot find translation for source Radio Paradise Aug 28 05:30:32 volumio-4 volumio[1200]: Cannot find translation for source Spotify Aug 28 05:30:33 volumio-4 go-librespot[1787]: time="2026-08-28T05:30:33-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 28 05:30:33 volumio-4 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 28 05:30:33 volumio-4 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 28 05:30:33 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 28 05:30:33 volumio-4 volumio[1200]: info: Systeminfo: --[object Object] Aug 28 05:30:33 volumio-4 volumio[1200]: info: Systeminfo web UI listening on port 12334 Aug 28 05:30:33 volumio-4 volumio[1200]: info: Starting Shairport Sync Aug 28 05:30:33 volumio-4 volumio[1200]: info: Error connecting to go-librespot Websocket: Error: socket hang up Aug 28 05:30:33 volumio-4 systemd[1]: Started fusiondsp.service - FusionDsp Daemon. Aug 28 05:30:33 volumio-4 sudo[1713]: pam_unix(sudo:session): session closed for user root Aug 28 05:30:34 volumio-4 sudo[1803]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Aug 28 05:30:34 volumio-4 sudo[1803]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 05:30:34 volumio-4 systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Aug 28 05:30:34 volumio-4 systemd[1]: shairport-sync.service: Deactivated successfully. Aug 28 05:30:34 volumio-4 systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 28 05:30:34 volumio-4 systemd[1]: shairport-sync.service: Consumed 1.394s CPU time. Aug 28 05:30:34 volumio-4 systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 28 05:30:34 volumio-4 sudo[1803]: pam_unix(sudo:session): session closed for user root Aug 28 05:30:35 volumio-4 mpd[1783]: 2026-08-28T05:30:35 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Aug 28 05:30:35 volumio-4 volumio[1200]: info: Shairport-Sync Started Aug 28 05:30:35 volumio-4 systemd[1]: Started mpd.service - Music Player Daemon. Aug 28 05:30:35 volumio-4 volumio[1200]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Aug 28 05:30:35 volumio-4 volumio[1200]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Aug 28 05:30:35 volumio-4 volumio[1200]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Aug 28 05:30:35 volumio-4 volumio[1200]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Aug 28 05:30:35 volumio-4 volumio[1200]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Aug 28 05:30:35 volumio-4 volumio[1200]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Aug 28 05:30:35 volumio-4 volumio[1200]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Aug 28 05:30:35 volumio-4 volumio[1200]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Aug 28 05:30:35 volumio-4 volumio[1200]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Aug 28 05:30:35 volumio-4 volumio[1200]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Aug 28 05:30:35 volumio-4 volumio[1200]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Aug 28 05:30:36 volumio-4 sudo[1758]: pam_unix(sudo:session): session closed for user root Aug 28 05:30:36 volumio-4 volumio[1200]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Aug 28 05:30:36 volumio-4 volumio[1200]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Aug 28 05:30:36 volumio-4 volumio[1200]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Aug 28 05:30:36 volumio-4 volumio[1200]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Aug 28 05:30:36 volumio-4 volumio[1200]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Aug 28 05:30:36 volumio-4 volumio[1200]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Aug 28 05:30:36 volumio-4 volumio[1200]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Aug 28 05:30:36 volumio-4 volumio[1200]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Aug 28 05:30:36 volumio-4 volumio[1200]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Aug 28 05:30:36 volumio-4 volumio[1200]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Aug 28 05:30:36 volumio-4 volumio[1200]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Aug 28 05:30:36 volumio-4 volumio[1200]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Aug 28 05:30:36 volumio-4 volumio[1200]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Aug 28 05:30:36 volumio-4 volumio[1200]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Aug 28 05:30:36 volumio-4 volumio[1200]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Aug 28 05:30:36 volumio-4 volumio[1200]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Aug 28 05:30:36 volumio-4 volumio[1200]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Aug 28 05:30:36 volumio-4 volumio[1200]: info: Adding plugin bluetooth to MyMusic Plugins Aug 28 05:30:36 volumio-4 volumio[1200]: info: Adding plugin multiroom to MyMusic Plugins Aug 28 05:30:36 volumio-4 volumio[1200]: info: Adding plugin metavolumio to MyMusic Plugins Aug 28 05:30:36 volumio-4 volumio[1200]: info: Adding plugin cd_controller to MyMusic Plugins Aug 28 05:30:36 volumio-4 volumio[1200]: info: Adding plugin qobuzconnect to MyMusic Plugins Aug 28 05:30:36 volumio-4 volumio[1200]: info: Adding plugin smart_inputs to MyMusic Plugins Aug 28 05:30:36 volumio-4 volumio[1200]: info: Adding plugin tidalconnect to MyMusic Plugins Aug 28 05:30:36 volumio-4 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Aug 28 05:30:36 volumio-4 systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 28 05:30:36 volumio-4 volumio[1200]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Aug 28 05:30:36 volumio-4 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 28 05:30:36 volumio-4 go-librespot[1824]: go-librespot daemon starting... Aug 28 05:30:36 volumio-4 go-librespot[1825]: time="2026-08-28T05:30:36-05:00" level=info msg="running go-librespot 0.7.1" Aug 28 05:30:36 volumio-4 go-librespot[1825]: time="2026-08-28T05:30:36-05:00" level=debug msg="app state loaded" Aug 28 05:30:36 volumio-4 go-librespot[1825]: time="2026-08-28T05:30:36-05:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 28 05:30:36 volumio-4 go-librespot[1825]: time="2026-08-28T05:30:36-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew1.spotify.com:80]" Aug 28 05:30:36 volumio-4 go-librespot[1825]: time="2026-08-28T05:30:36-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Aug 28 05:30:36 volumio-4 go-librespot[1825]: time="2026-08-28T05:30:36-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Aug 28 05:30:36 volumio-4 go-librespot[1825]: time="2026-08-28T05:30:36-05:00" level=info msg="zeroconf server listening on port 35295" Aug 28 05:30:36 volumio-4 go-librespot[1825]: time="2026-08-28T05:30:36-05:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 28 05:30:37 volumio-4 go-librespot[1825]: time="2026-08-28T05:30:37-05:00" level=debug msg="obtained new client token: AAGIFvP8/+aph8l6Ceyf1MBU0S/BZYQpn2PO9VNpftV7ViGBYfR8BeCeoDpG2nMctQ/miJ+Pf/n3/bNv88gvAfLSt0dQQ7zxZaI7ySlK5sQ+GQI+6OgJ9JjjVybpf2FM6q8KoPh1ztDK6yxt6OPnEku6b4ARRTb7x0Z3Rnu+na9pF4Lp5yPvf+NIXKQnn2px+6nmjs4xH2ZAoWpOhQ9KxbASfMUzUu8/uaPRBq3gN9XZGPGF9DqKsQ==" Aug 28 05:30:37 volumio-4 go-librespot[1825]: time="2026-08-28T05:30:37-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Aug 28 05:30:37 volumio-4 go-librespot[1825]: time="2026-08-28T05:30:37-05:00" level=debug msg="completed keyexchange" Aug 28 05:30:37 volumio-4 go-librespot[1825]: time="2026-08-28T05:30:37-05:00" level=debug msg="completed challenge" Aug 28 05:30:37 volumio-4 go-librespot[1825]: time="2026-08-28T05:30:37-05:00" level=info msg="authenticated AP" username="31************************pi" Aug 28 05:30:37 volumio-4 go-librespot[1825]: time="2026-08-28T05:30:37-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 28 05:30:37 volumio-4 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 28 05:30:37 volumio-4 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 28 05:30:40 volumio-4 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 4. Aug 28 05:30:40 volumio-4 systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 28 05:30:40 volumio-4 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 28 05:30:40 volumio-4 go-librespot[1836]: go-librespot daemon starting... Aug 28 05:30:40 volumio-4 go-librespot[1837]: time="2026-08-28T05:30:40-05:00" level=info msg="running go-librespot 0.7.1" Aug 28 05:30:40 volumio-4 go-librespot[1837]: time="2026-08-28T05:30:40-05:00" level=debug msg="app state loaded" Aug 28 05:30:40 volumio-4 go-librespot[1837]: time="2026-08-28T05:30:40-05:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 28 05:30:41 volumio-4 go-librespot[1837]: time="2026-08-28T05:30:41-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew4.spotify.com:80]" Aug 28 05:30:41 volumio-4 go-librespot[1837]: time="2026-08-28T05:30:41-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Aug 28 05:30:41 volumio-4 go-librespot[1837]: time="2026-08-28T05:30:41-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Aug 28 05:30:41 volumio-4 go-librespot[1837]: time="2026-08-28T05:30:41-05:00" level=info msg="zeroconf server listening on port 40545" Aug 28 05:30:41 volumio-4 go-librespot[1837]: time="2026-08-28T05:30:41-05:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 28 05:30:41 volumio-4 go-librespot[1837]: time="2026-08-28T05:30:41-05:00" level=debug msg="obtained new client token: AAGtfbJm631AwSYcovYCVnlMseLvH2iDsWsEG5tPPrLQorcLh6ThqQnsstmIs/F9OtzZIkKNlW0Ad1fKhCDqWAVLgbubeE9kk8r8Ye1XyCvEz5rJ+Bz6u0miED6pNwDuo+ehPieGdZXrjvVxO2Voy7kcgbMSgHHwiZEseDGqgaDBjoXNuuSk73oj8ygG7A20W5OWNwlS3WoqAwnk7Ir3VbIOT4A2G6NNlO9V9AboftI5O7DSLv0l0c26" Aug 28 05:30:41 volumio-4 go-librespot[1837]: time="2026-08-28T05:30:41-05:00" level=warning msg="failed to connect to AP ap-gue1.spotify.com:4070, retrying with a different AP" error="dial tcp 34.158.255.62:4070: connect: connection refused" Aug 28 05:30:41 volumio-4 go-librespot[1837]: time="2026-08-28T05:30:41-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Aug 28 05:30:41 volumio-4 go-librespot[1837]: time="2026-08-28T05:30:41-05:00" level=debug msg="completed keyexchange" Aug 28 05:30:41 volumio-4 go-librespot[1837]: time="2026-08-28T05:30:41-05:00" level=debug msg="completed challenge" Aug 28 05:30:41 volumio-4 go-librespot[1837]: time="2026-08-28T05:30:41-05:00" level=info msg="authenticated AP" username="31************************pi" Aug 28 05:30:41 volumio-4 go-librespot[1837]: time="2026-08-28T05:30:41-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 28 05:30:41 volumio-4 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 28 05:30:41 volumio-4 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 28 05:30:44 volumio-4 volumio[1200]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Aug 28 05:30:44 volumio-4 volumio[1200]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Aug 28 05:30:44 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 05:30:44 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 05:30:44 volumio-4 volumio[1200]: info: Starting MyVolumio Remote Streaming Endpoints Aug 28 05:30:44 volumio-4 volumio[1200]: info: MyVolumio login type: Token Aug 28 05:30:44 volumio-4 volumio[1200]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Aug 28 05:30:44 volumio-4 volumio[1200]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Aug 28 05:30:44 volumio-4 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 5. Aug 28 05:30:45 volumio-4 systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 28 05:30:45 volumio-4 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 28 05:30:45 volumio-4 go-librespot[1860]: go-librespot daemon starting... Aug 28 05:30:45 volumio-4 go-librespot[1861]: time="2026-08-28T05:30:45-05:00" level=info msg="running go-librespot 0.7.1" Aug 28 05:30:45 volumio-4 go-librespot[1861]: time="2026-08-28T05:30:45-05:00" level=debug msg="app state loaded" Aug 28 05:30:45 volumio-4 go-librespot[1861]: time="2026-08-28T05:30:45-05:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 28 05:30:45 volumio-4 go-librespot[1861]: time="2026-08-28T05:30:45-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Aug 28 05:30:45 volumio-4 go-librespot[1861]: time="2026-08-28T05:30:45-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Aug 28 05:30:45 volumio-4 go-librespot[1861]: time="2026-08-28T05:30:45-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Aug 28 05:30:45 volumio-4 go-librespot[1861]: time="2026-08-28T05:30:45-05:00" level=info msg="zeroconf server listening on port 42173" Aug 28 05:30:45 volumio-4 go-librespot[1861]: time="2026-08-28T05:30:45-05:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 28 05:30:45 volumio-4 go-librespot[1861]: time="2026-08-28T05:30:45-05:00" level=debug msg="obtained new client token: AAEi7F1l2zp7miFM1kEzLOIzrR3Xj2jrMkH/EH96MYUvGVh3/XW05vTxD6vxcWiBR2I8qK8yB/yVYnuWYDu7jCezPVc2fsdL1xZnFIDOKC6R8YSeUCGYxqDlLJK+4Vmu0Vvr0aeWNYA1/GYzFYUiaPo20A4fy8BjUrGrKGnRbuwW5LWMD74MP/4DPrMFZS381C2ubUOGO2uQ82mR7kHglB4ffVJ9/0Yry54vj+pFMY5cmITGyXximj9h" Aug 28 05:30:45 volumio-4 go-librespot[1861]: time="2026-08-28T05:30:45-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Aug 28 05:30:45 volumio-4 go-librespot[1861]: time="2026-08-28T05:30:45-05:00" level=debug msg="completed keyexchange" Aug 28 05:30:45 volumio-4 go-librespot[1861]: time="2026-08-28T05:30:45-05:00" level=debug msg="completed challenge" Aug 28 05:30:46 volumio-4 go-librespot[1861]: time="2026-08-28T05:30:46-05:00" level=info msg="authenticated AP" username="31************************pi" Aug 28 05:30:46 volumio-4 go-librespot[1861]: time="2026-08-28T05:30:46-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 28 05:30:46 volumio-4 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 28 05:30:46 volumio-4 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 28 05:30:49 volumio-4 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6. Aug 28 05:30:49 volumio-4 systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 28 05:30:49 volumio-4 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 28 05:30:49 volumio-4 go-librespot[1870]: go-librespot daemon starting... Aug 28 05:30:49 volumio-4 go-librespot[1871]: time="2026-08-28T05:30:49-05:00" level=info msg="running go-librespot 0.7.1" Aug 28 05:30:49 volumio-4 go-librespot[1871]: time="2026-08-28T05:30:49-05:00" level=debug msg="app state loaded" Aug 28 05:30:49 volumio-4 go-librespot[1871]: time="2026-08-28T05:30:49-05:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 28 05:30:49 volumio-4 go-librespot[1871]: time="2026-08-28T05:30:49-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Aug 28 05:30:49 volumio-4 go-librespot[1871]: time="2026-08-28T05:30:49-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Aug 28 05:30:49 volumio-4 go-librespot[1871]: time="2026-08-28T05:30:49-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Aug 28 05:30:49 volumio-4 go-librespot[1871]: time="2026-08-28T05:30:49-05:00" level=info msg="zeroconf server listening on port 36687" Aug 28 05:30:49 volumio-4 go-librespot[1871]: time="2026-08-28T05:30:49-05:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 28 05:30:50 volumio-4 go-librespot[1871]: time="2026-08-28T05:30:50-05:00" level=debug msg="obtained new client token: AAHxGPBekdezrI0uYXaQXRjg6S1lpGLxB8YgVt5tzRv3qkohmHAimN31kr+Q/f3pPARRhaayFpbq0XPmsv/E8UpICb7fRTA4Y5FGwRFws7EO+B+6PXRFV/qXhmwPUegqyaUrzORhPzn55uiPJaE0RGIdiILE5npCAr/AcDERbvARZ0y54i08+OIbXmKeYjCevOuJNMEViGGdQmc89u5YswMG4q7YOapOux85EhGKVU0wl18SR5sJAP0h" Aug 28 05:30:50 volumio-4 go-librespot[1871]: time="2026-08-28T05:30:50-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Aug 28 05:30:50 volumio-4 go-librespot[1871]: time="2026-08-28T05:30:50-05:00" level=debug msg="completed keyexchange" Aug 28 05:30:50 volumio-4 go-librespot[1871]: time="2026-08-28T05:30:50-05:00" level=debug msg="completed challenge" Aug 28 05:30:50 volumio-4 go-librespot[1871]: time="2026-08-28T05:30:50-05:00" level=info msg="authenticated AP" username="31************************pi" Aug 28 05:30:50 volumio-4 go-librespot[1871]: time="2026-08-28T05:30:50-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 28 05:30:50 volumio-4 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 28 05:30:50 volumio-4 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 28 05:30:51 volumio-4 volumio[1200]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Aug 28 05:30:51 volumio-4 volumio[1200]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Aug 28 05:30:51 volumio-4 volumio[1200]: info: Streaming services startup Aug 28 05:30:51 volumio-4 volumio[1200]: info: Starting Streaming Daemon Aug 28 05:30:51 volumio-4 volumio[1200]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Aug 28 05:30:51 volumio-4 sudo[1892]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Aug 28 05:30:51 volumio-4 sudo[1892]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 05:30:52 volumio-4 sudo[1892]: pam_unix(sudo:session): session closed for user root Aug 28 05:30:52 volumio-4 volumio[1200]: info: Initializing connection to go-librespot Websocket Aug 28 05:30:52 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 28 05:30:52 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 05:30:52 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Aug 28 05:30:52 volumio-4 volumio[1200]: error: Cannot start Volumio Streaming Daemon Aug 28 05:30:52 volumio-4 volumio[1200]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Aug 28 05:30:52 volumio-4 volumio[1200]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Aug 28 05:30:52 volumio-4 volumio[1200]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 28 05:30:53 volumio-4 volumio[1200]: error: updateQueue error: null Aug 28 05:30:53 volumio-4 volumio[1200]: error: MyVolumio Custom Token format not valid, refreshing it Aug 28 05:30:53 volumio-4 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 7. Aug 28 05:30:53 volumio-4 systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 28 05:30:53 volumio-4 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 28 05:30:53 volumio-4 go-librespot[1905]: go-librespot daemon starting... Aug 28 05:30:53 volumio-4 go-librespot[1906]: time="2026-08-28T05:30:53-05:00" level=info msg="running go-librespot 0.7.1" Aug 28 05:30:53 volumio-4 go-librespot[1906]: time="2026-08-28T05:30:53-05:00" level=debug msg="app state loaded" Aug 28 05:30:53 volumio-4 go-librespot[1906]: time="2026-08-28T05:30:53-05:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 28 05:30:54 volumio-4 go-librespot[1906]: time="2026-08-28T05:30:54-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew1.spotify.com:80]" Aug 28 05:30:54 volumio-4 go-librespot[1906]: time="2026-08-28T05:30:54-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Aug 28 05:30:54 volumio-4 go-librespot[1906]: time="2026-08-28T05:30:54-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Aug 28 05:30:54 volumio-4 go-librespot[1906]: time="2026-08-28T05:30:54-05:00" level=info msg="zeroconf server listening on port 38133" Aug 28 05:30:54 volumio-4 go-librespot[1906]: time="2026-08-28T05:30:54-05:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 28 05:30:54 volumio-4 go-librespot[1906]: time="2026-08-28T05:30:54-05:00" level=debug msg="obtained new client token: AAGuRjpxX6bmU1ItjTFMX2onvpHGj620lGEj2Bx8q7LBhcYi/iYlDdezqz8aaAK8wYXZSXgwEGMqgbJCGNVJliXHxrwzo6+cfG2NKbrbRdk8g/zc6HtegkBRob0n0DdFwy3gRLT4nhCv/6MGrXifxu+KGOKu68LiaLX43/LOIxij0+lKbx3p2nC2htJScpZuEBNOF/xzEj9mPZQkBC5wTlOP8NrWX0rKckXlQGTKbaooJKzXN5cOVA==" Aug 28 05:30:54 volumio-4 go-librespot[1906]: time="2026-08-28T05:30:54-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Aug 28 05:30:54 volumio-4 go-librespot[1906]: time="2026-08-28T05:30:54-05:00" level=debug msg="completed keyexchange" Aug 28 05:30:54 volumio-4 go-librespot[1906]: time="2026-08-28T05:30:54-05:00" level=debug msg="completed challenge" Aug 28 05:30:54 volumio-4 go-librespot[1906]: time="2026-08-28T05:30:54-05:00" level=info msg="authenticated AP" username="31************************pi" Aug 28 05:30:54 volumio-4 go-librespot[1906]: time="2026-08-28T05:30:54-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 28 05:30:54 volumio-4 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 28 05:30:54 volumio-4 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 28 05:30:54 volumio-4 volumio-remote-updater[740]: Test mode disabled Aug 28 05:30:54 volumio-4 volumio-remote-updater[740]: Alpha mode disabled Aug 28 05:30:54 volumio-4 volumio-remote-updater[740]: Alpha legacy test mode disabled Aug 28 05:30:54 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateEnabled Aug 28 05:30:55 volumio-4 volumio[1200]: info: Update Ready: {"changeLogLink":"","description":"You're already on the latest version","title":"No Updates Available","updateavailable":false} Aug 28 05:30:55 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache Aug 28 05:30:55 volumio-4 volumio[1200]: info: Initializing connection to go-librespot Websocket Aug 28 05:30:56 volumio-4 volumio[1200]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 28 05:30:56 volumio-4 volumio[1200]: info: MyVolumio login type: Token Aug 28 05:30:56 volumio-4 volumio[1200]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Aug 28 05:30:57 volumio-4 volumio[1200]: info: MyVolumio token set successfully Aug 28 05:30:57 volumio-4 volumio[1200]: info: MYVOLUMIO: Adding device Aug 28 05:30:57 volumio-4 volumio[1200]: info: MYVOLUMIO: Evaluating Server Aug 28 05:30:57 volumio-4 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 8. Aug 28 05:30:57 volumio-4 systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 28 05:30:57 volumio-4 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 28 05:30:57 volumio-4 go-librespot[1925]: go-librespot daemon starting... Aug 28 05:30:57 volumio-4 go-librespot[1927]: time="2026-08-28T05:30:57-05:00" level=info msg="running go-librespot 0.7.1" Aug 28 05:30:57 volumio-4 go-librespot[1927]: time="2026-08-28T05:30:57-05:00" level=debug msg="app state loaded" Aug 28 05:30:57 volumio-4 go-librespot[1927]: time="2026-08-28T05:30:57-05:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 28 05:30:58 volumio-4 go-librespot[1927]: time="2026-08-28T05:30:58-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew4.spotify.com:80]" Aug 28 05:30:58 volumio-4 go-librespot[1927]: time="2026-08-28T05:30:58-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Aug 28 05:30:58 volumio-4 go-librespot[1927]: time="2026-08-28T05:30:58-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Aug 28 05:30:58 volumio-4 go-librespot[1927]: time="2026-08-28T05:30:58-05:00" level=info msg="zeroconf server listening on port 39179" Aug 28 05:30:58 volumio-4 go-librespot[1927]: time="2026-08-28T05:30:58-05:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 28 05:30:58 volumio-4 go-librespot[1927]: time="2026-08-28T05:30:58-05:00" level=debug msg="obtained new client token: AAHXD1WXtpb/VStTCichnVIQENixbhe9L7i16o8clBO0JcpYkB3VYvU6F34gcSypXC2JBfz7mJngWygSu1S3uPjHOfzCVLf/1z7H+fTqPwiwl4b5fnZi2juPtpAMOIu+isc4ykZOAle/4YZ6/x0jsZraN624XQDrGPEl8Aq6w0u4d0oNxqtvrRRv6XfQAFvJaMrxqyXItfwyI/Zf9thZAWsDEzSYJUd9uhYYtMLGguhOFYNFB4m55y6i" Aug 28 05:30:59 volumio-4 go-librespot[1927]: time="2026-08-28T05:30:59-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Aug 28 05:30:59 volumio-4 go-librespot[1927]: time="2026-08-28T05:30:59-05:00" level=debug msg="completed keyexchange" Aug 28 05:30:59 volumio-4 go-librespot[1927]: time="2026-08-28T05:30:59-05:00" level=debug msg="completed challenge" Aug 28 05:30:59 volumio-4 go-librespot[1927]: time="2026-08-28T05:30:59-05:00" level=info msg="authenticated AP" username="31************************pi" Aug 28 05:30:59 volumio-4 volumio[1200]: info: Initializing connection to go-librespot Websocket Aug 28 05:30:59 volumio-4 go-librespot[1927]: time="2026-08-28T05:30:59-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 28 05:30:59 volumio-4 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 28 05:30:59 volumio-4 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 28 05:30:59 volumio-4 volumio[1200]: info: MyVolumio Plan changed: premium Aug 28 05:30:59 volumio-4 volumio[1200]: info: [MyVolumio PluginManager] Subscribed plan changed to premium Aug 28 05:30:59 volumio-4 volumio[1200]: info: Removing browser output: myVolumio user plan is not superstar Aug 28 05:30:59 volumio-4 volumio[1200]: info: Removing audio output: Aug 28 05:30:59 volumio-4 volumio[1200]: info: MYVOLUMIO: Adding device Aug 28 05:30:59 volumio-4 volumio[1200]: info: MYVOLUMIO: Evaluating Server Aug 28 05:30:59 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Aug 28 05:31:01 volumio-4 volumio[1200]: info: Setting Geolocation for MyVolumio to us4 Aug 28 05:31:01 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 05:31:01 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 05:31:01 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 05:31:01 volumio-4 volumio[1200]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 28 05:31:01 volumio-4 volumio[1200]: info: Remote config written successfully Aug 28 05:31:01 volumio-4 volumio[1200]: info: Starting Tunnel 1 Aug 28 05:31:01 volumio-4 volumio[1200]: info: Starting Tunnel Connection Checker Aug 28 05:31:01 volumio-4 volumio[1200]: info: Completed starting MyVolumio Plugin Aug 28 05:31:01 volumio-4 volumio[1200]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 12 Aug 28 05:31:01 volumio-4 volumio[1200]: info: MYVolumio Device enabled Aug 28 05:31:01 volumio-4 volumio[1200]: info: [MyVolumio PluginManager] Device activated, enabling myvolumio plugins... Aug 28 05:31:01 volumio-4 volumio[1200]: info: MyVolumio status changed Aug 28 05:31:01 volumio-4 volumio[1200]: info: Streaming services startup Aug 28 05:31:01 volumio-4 volumio[1200]: info: Starting Streaming Daemon Aug 28 05:31:02 volumio-4 sudo[1971]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Aug 28 05:31:02 volumio-4 sudo[1971]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 05:31:02 volumio-4 sudo[1971]: pam_unix(sudo:session): session closed for user root Aug 28 05:31:02 volumio-4 volumio[1200]: info: Setting Geolocation for MyVolumio to us1 Aug 28 05:31:02 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 05:31:02 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 05:31:02 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 05:31:02 volumio-4 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 9. Aug 28 05:31:02 volumio-4 systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 28 05:31:02 volumio-4 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 28 05:31:02 volumio-4 go-librespot[1987]: go-librespot daemon starting... Aug 28 05:31:02 volumio-4 go-librespot[1988]: time="2026-08-28T05:31:02-05:00" level=info msg="running go-librespot 0.7.1" Aug 28 05:31:02 volumio-4 go-librespot[1988]: time="2026-08-28T05:31:02-05:00" level=debug msg="app state loaded" Aug 28 05:31:02 volumio-4 go-librespot[1988]: time="2026-08-28T05:31:02-05:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 28 05:31:03 volumio-4 go-librespot[1988]: time="2026-08-28T05:31:03-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew1.spotify.com:80]" Aug 28 05:31:03 volumio-4 go-librespot[1988]: time="2026-08-28T05:31:03-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Aug 28 05:31:03 volumio-4 go-librespot[1988]: time="2026-08-28T05:31:03-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Aug 28 05:31:03 volumio-4 volumio[1200]: info: Successfully Added MyVolumio device Aug 28 05:31:03 volumio-4 go-librespot[1988]: time="2026-08-28T05:31:03-05:00" level=info msg="zeroconf server listening on port 35461" Aug 28 05:31:03 volumio-4 volumio[1200]: error: Cannot start Volumio Streaming Daemon Aug 28 05:31:03 volumio-4 volumio[1200]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Aug 28 05:31:03 volumio-4 volumio[1200]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Aug 28 05:31:03 volumio-4 go-librespot[1988]: time="2026-08-28T05:31:03-05:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 28 05:31:03 volumio-4 volumio[1200]: info: Updating MyVolumio device info Aug 28 05:31:03 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 05:31:03 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 05:31:03 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 05:31:03 volumio-4 go-librespot[1988]: time="2026-08-28T05:31:03-05:00" level=debug msg="obtained new client token: AAGAHw5Dtem+SbD52JlyluOQFjSZggy8x+rz4nJUOm13TPTgOr+w062wIyhmML408lr0CTSvcdgmt2ZVPfPUjnkz5wXx7qozxycUXnF/yhqasxsrxVmbuiYZmodGtBygAc7E+zvqsCkCQ76SBdZszSyl8IBMZmB0fhRjtOhCxrklzKD2hNYRgWb9RPpyBbgZib9chkm/dYC1BG9I5dk20/XahQ7vTQtcNQsQ2uU4pn6RWxm+c//iuaz9" Aug 28 05:31:03 volumio-4 go-librespot[1988]: time="2026-08-28T05:31:03-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Aug 28 05:31:03 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getHwuuid Aug 28 05:31:03 volumio-4 go-librespot[1988]: time="2026-08-28T05:31:03-05:00" level=debug msg="completed keyexchange" Aug 28 05:31:03 volumio-4 go-librespot[1988]: time="2026-08-28T05:31:03-05:00" level=debug msg="completed challenge" Aug 28 05:31:03 volumio-4 volumio[1200]: error: [MyVolumio PluginManager] Cache data is invalid! Aug 28 05:31:03 volumio-4 go-librespot[1988]: time="2026-08-28T05:31:03-05:00" level=info msg="authenticated AP" username="31************************pi" Aug 28 05:31:03 volumio-4 volumio[1200]: info: Successfully Added MyVolumio device Aug 28 05:31:03 volumio-4 volumio[1200]: info: Updating MyVolumio device info Aug 28 05:31:03 volumio-4 go-librespot[1988]: time="2026-08-28T05:31:03-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 28 05:31:03 volumio-4 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 28 05:31:03 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 05:31:03 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 05:31:03 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 05:31:03 volumio-4 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 28 05:31:03 volumio-4 volumio[1200]: info: Successfully Updated MyVolumio device Aug 28 05:31:04 volumio-4 volumio[1200]: info: Successfully Updated MyVolumio device Aug 28 05:31:04 volumio-4 volumio[1200]: info: [MyVolumio PluginManager] Loading plugin "bluetooth"... Aug 28 05:31:06 volumio-4 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 10. Aug 28 05:31:06 volumio-4 systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 28 05:31:06 volumio-4 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 28 05:31:06 volumio-4 go-librespot[1999]: go-librespot daemon starting... Aug 28 05:31:06 volumio-4 go-librespot[2000]: time="2026-08-28T05:31:06-05:00" level=info msg="running go-librespot 0.7.1" Aug 28 05:31:06 volumio-4 go-librespot[2000]: time="2026-08-28T05:31:06-05:00" level=debug msg="app state loaded" Aug 28 05:31:07 volumio-4 go-librespot[2000]: time="2026-08-28T05:31:07-05:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 28 05:31:07 volumio-4 go-librespot[2000]: time="2026-08-28T05:31:07-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew4.spotify.com:80]" Aug 28 05:31:07 volumio-4 go-librespot[2000]: time="2026-08-28T05:31:07-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Aug 28 05:31:07 volumio-4 go-librespot[2000]: time="2026-08-28T05:31:07-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Aug 28 05:31:07 volumio-4 go-librespot[2000]: time="2026-08-28T05:31:07-05:00" level=info msg="zeroconf server listening on port 41403" Aug 28 05:31:07 volumio-4 go-librespot[2000]: time="2026-08-28T05:31:07-05:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 28 05:31:07 volumio-4 go-librespot[2000]: time="2026-08-28T05:31:07-05:00" level=debug msg="obtained new client token: AAHtw1nqIjEhtTrX8g5njZvYCQDZVUv7CMyYe7WVj2O9OpqyQA4bqOk4hesz+Y5xFfusTHhyKU8diC0FB2+woc1ovlw1hOIIOw4HL0TL5h059DPf0EVyK2deLAI4j9E8vAt48sG7mLcarDELgRdMAvwdMzJa+Tb9XPcvz00j5fG6bvNEGXSQTLKnB+vnvnjThHkQyaw19/uLOFjTQQLlxzEJ9aG52+9n04sXzkAAS8e9fai9fE/Y9Gmw" Aug 28 05:31:07 volumio-4 go-librespot[2000]: time="2026-08-28T05:31:07-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Aug 28 05:31:07 volumio-4 go-librespot[2000]: time="2026-08-28T05:31:07-05:00" level=debug msg="completed keyexchange" Aug 28 05:31:07 volumio-4 go-librespot[2000]: time="2026-08-28T05:31:07-05:00" level=debug msg="completed challenge" Aug 28 05:31:07 volumio-4 go-librespot[2000]: time="2026-08-28T05:31:07-05:00" level=info msg="authenticated AP" username="31************************pi" Aug 28 05:31:07 volumio-4 go-librespot[2000]: time="2026-08-28T05:31:07-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 28 05:31:08 volumio-4 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 28 05:31:08 volumio-4 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 28 05:31:08 volumio-4 volumio[1200]: info: [MyVolumio PluginManager] Applying required configuration parameters for plugin bluetooth Aug 28 05:31:08 volumio-4 volumio[1200]: info: [MyVolumio PluginManager] Applying required configuration parameters for plugin bluetooth Aug 28 05:31:08 volumio-4 volumio[1200]: ------------------------------------ BT MESSAGE: [FUNC] onVolumioStart Aug 28 05:31:08 volumio-4 volumio[1200]: info: [MyVolumio PluginManager] Loading plugin "multiroom"... Aug 28 05:31:11 volumio-4 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 11. Aug 28 05:31:11 volumio-4 systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 28 05:31:11 volumio-4 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 28 05:31:11 volumio-4 go-librespot[2009]: go-librespot daemon starting... Aug 28 05:31:11 volumio-4 go-librespot[2010]: time="2026-08-28T05:31:11-05:00" level=info msg="running go-librespot 0.7.1" Aug 28 05:31:11 volumio-4 go-librespot[2010]: time="2026-08-28T05:31:11-05:00" level=debug msg="app state loaded" Aug 28 05:31:11 volumio-4 go-librespot[2010]: time="2026-08-28T05:31:11-05:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 28 05:31:12 volumio-4 go-librespot[2010]: time="2026-08-28T05:31:12-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Aug 28 05:31:12 volumio-4 go-librespot[2010]: time="2026-08-28T05:31:12-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Aug 28 05:31:12 volumio-4 go-librespot[2010]: time="2026-08-28T05:31:12-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Aug 28 05:31:12 volumio-4 go-librespot[2010]: time="2026-08-28T05:31:12-05:00" level=info msg="zeroconf server listening on port 40853" Aug 28 05:31:12 volumio-4 go-librespot[2010]: time="2026-08-28T05:31:12-05:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 28 05:31:12 volumio-4 go-librespot[2010]: time="2026-08-28T05:31:12-05:00" level=debug msg="obtained new client token: AAFXsN4iWTHC3egAbL6cyR1F8NywRS8NJSeWjJAJQHd3+F0TtCTSGSLXz6iiJ/gasnG2N12mdF22yVKJmlfN2RVYKAO7aNK4hgWjG3Zimb5lyQjyf8b5TZkKtrayrzoxhr2aWZ/xW7+9yhQwz5ZkqUu0KMVUHEd2OBE6CDm5A4BJ+jeL8NWefCSNllTTzuUI5wG/QMydNzSbRXSqBhkse7t4fd1p89/0Bfcqgcct8OruPXAfa5BBHg==" Aug 28 05:31:12 volumio-4 go-librespot[2010]: time="2026-08-28T05:31:12-05:00" level=warning msg="failed to connect to AP ap-gue1.spotify.com:4070, retrying with a different AP" error="dial tcp 34.158.255.62:4070: connect: connection refused" Aug 28 05:31:12 volumio-4 go-librespot[2010]: time="2026-08-28T05:31:12-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Aug 28 05:31:12 volumio-4 go-librespot[2010]: time="2026-08-28T05:31:12-05:00" level=debug msg="completed keyexchange" Aug 28 05:31:12 volumio-4 go-librespot[2010]: time="2026-08-28T05:31:12-05:00" level=debug msg="completed challenge" Aug 28 05:31:12 volumio-4 go-librespot[2010]: time="2026-08-28T05:31:12-05:00" level=info msg="authenticated AP" username="31************************pi" Aug 28 05:31:12 volumio-4 go-librespot[2010]: time="2026-08-28T05:31:12-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 28 05:31:12 volumio-4 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 28 05:31:12 volumio-4 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 28 05:31:15 volumio-4 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 12. Aug 28 05:31:15 volumio-4 systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 28 05:31:15 volumio-4 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 28 05:31:15 volumio-4 go-librespot[2033]: go-librespot daemon starting... Aug 28 05:31:15 volumio-4 go-librespot[2034]: time="2026-08-28T05:31:15-05:00" level=info msg="running go-librespot 0.7.1" Aug 28 05:31:15 volumio-4 go-librespot[2034]: time="2026-08-28T05:31:15-05:00" level=debug msg="app state loaded" Aug 28 05:31:15 volumio-4 go-librespot[2034]: time="2026-08-28T05:31:15-05:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 28 05:31:16 volumio-4 go-librespot[2034]: time="2026-08-28T05:31:16-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Aug 28 05:31:16 volumio-4 go-librespot[2034]: time="2026-08-28T05:31:16-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Aug 28 05:31:16 volumio-4 go-librespot[2034]: time="2026-08-28T05:31:16-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Aug 28 05:31:16 volumio-4 go-librespot[2034]: time="2026-08-28T05:31:16-05:00" level=info msg="zeroconf server listening on port 34653" Aug 28 05:31:16 volumio-4 go-librespot[2034]: time="2026-08-28T05:31:16-05:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 28 05:31:16 volumio-4 go-librespot[2034]: time="2026-08-28T05:31:16-05:00" level=debug msg="obtained new client token: AAHuOYnKzP1Dex5bxTkjZw1oee6/r8S4Duw8MUVZWkmD8zO8fux4IVThlzZLd3dITD9qIWl9TWWJejGTFUqVuBfvw1P/9VgT+kYXfIoH0UVTIyilRT6MUuuEvdxPRefIX2cfob9WnqdtGYmb2chmlTLUNyVxWmzxqPvlVS1O1ORM9LspUwr4KQVKGaJRKRW26eutuxjzH2Gr5a01QYSfo/eW3Puydc4hqkkX0fxZC+daWLqn/5P08IxK" Aug 28 05:31:16 volumio-4 go-librespot[2034]: time="2026-08-28T05:31:16-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Aug 28 05:31:16 volumio-4 go-librespot[2034]: time="2026-08-28T05:31:16-05:00" level=debug msg="completed keyexchange" Aug 28 05:31:16 volumio-4 go-librespot[2034]: time="2026-08-28T05:31:16-05:00" level=debug msg="completed challenge" Aug 28 05:31:17 volumio-4 go-librespot[2034]: time="2026-08-28T05:31:17-05:00" level=info msg="authenticated AP" username="31************************pi" Aug 28 05:31:17 volumio-4 go-librespot[2034]: time="2026-08-28T05:31:17-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 28 05:31:17 volumio-4 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 28 05:31:17 volumio-4 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 28 05:31:20 volumio-4 upmpdcli[2043]: writing RSA key Aug 28 05:31:20 volumio-4 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 13. Aug 28 05:31:20 volumio-4 systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 28 05:31:20 volumio-4 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 28 05:31:20 volumio-4 go-librespot[2046]: go-librespot daemon starting... Aug 28 05:31:20 volumio-4 volumio[1200]: info: [MyVolumio PluginManager] Applying required configuration parameters for plugin multiroom Aug 28 05:31:20 volumio-4 go-librespot[2047]: time="2026-08-28T05:31:20-05:00" level=info msg="running go-librespot 0.7.1" Aug 28 05:31:20 volumio-4 go-librespot[2047]: time="2026-08-28T05:31:20-05:00" level=debug msg="app state loaded" Aug 28 05:31:20 volumio-4 go-librespot[2047]: time="2026-08-28T05:31:20-05:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 28 05:31:20 volumio-4 sudo[2057]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/rm -rf /tmp/multiroom Aug 28 05:31:20 volumio-4 sudo[2057]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 05:31:20 volumio-4 sudo[2057]: pam_unix(sudo:session): session closed for user root Aug 28 05:31:21 volumio-4 go-librespot[2047]: time="2026-08-28T05:31:21-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew4.spotify.com:80]" Aug 28 05:31:21 volumio-4 go-librespot[2047]: time="2026-08-28T05:31:21-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Aug 28 05:31:21 volumio-4 go-librespot[2047]: time="2026-08-28T05:31:21-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Aug 28 05:31:21 volumio-4 go-librespot[2047]: time="2026-08-28T05:31:21-05:00" level=info msg="zeroconf server listening on port 46087" Aug 28 05:31:21 volumio-4 go-librespot[2047]: time="2026-08-28T05:31:21-05:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 28 05:31:21 volumio-4 volumio[1200]: info: MRS: MultiRoom plugin initialized Aug 28 05:31:21 volumio-4 go-librespot[2047]: time="2026-08-28T05:31:21-05:00" level=debug msg="obtained new client token: AAE8j9NKK8HnpfO0GmSiv1npQ91IpDYDnwByxHCb6TuQVQ8zpkQZPOYlTauZMRxwZcXFPSULUSg0Ia0JbxrH0E6mlJ/C0aLTuEDYDNYi8XxgqskeDWsvb9UUDt3Vh9z9zGIp0e3QykU062yPAcXXvnP5HIP7ABrUOByyCoRAmRKwADrI44H4T4pBHgWJ74OSO1zK7rxxOGAg+RPVRq96rbAjF2/YgjIrBF24PV254hbgx1ssp+iCDA==" Aug 28 05:31:21 volumio-4 go-librespot[2047]: time="2026-08-28T05:31:21-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Aug 28 05:31:21 volumio-4 volumio[1200]: info: MRS: STOPPING SNAPCLIENT Aug 28 05:31:21 volumio-4 go-librespot[2047]: time="2026-08-28T05:31:21-05:00" level=debug msg="completed keyexchange" Aug 28 05:31:21 volumio-4 go-librespot[2047]: time="2026-08-28T05:31:21-05:00" level=debug msg="completed challenge" Aug 28 05:31:21 volumio-4 go-librespot[2047]: time="2026-08-28T05:31:21-05:00" level=info msg="authenticated AP" username="31************************pi" Aug 28 05:31:21 volumio-4 volumio[1200]: info: MRS: Snap server stop Aug 28 05:31:21 volumio-4 volumio[1200]: info: MRS: STOPPING volumioStreaming Aug 28 05:31:21 volumio-4 sudo[2080]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop volumioSnapclient Aug 28 05:31:21 volumio-4 sudo[2080]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 05:31:21 volumio-4 go-librespot[2047]: time="2026-08-28T05:31:21-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 28 05:31:21 volumio-4 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 28 05:31:21 volumio-4 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 28 05:31:21 volumio-4 sudo[2082]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop volumioSnapserver Aug 28 05:31:21 volumio-4 volumio[1200]: info: [MyVolumio PluginManager] Loading plugin "metavolumio"... Aug 28 05:31:21 volumio-4 sudo[2086]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop volumioStreaming Aug 28 05:31:21 volumio-4 sudo[2086]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 05:31:21 volumio-4 sudo[2082]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 05:31:21 volumio-4 sudo[2080]: pam_unix(sudo:session): session closed for user root Aug 28 05:31:21 volumio-4 sudo[2089]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/rm -f /tmp/hls/* Aug 28 05:31:21 volumio-4 sudo[2082]: pam_unix(sudo:session): session closed for user root Aug 28 05:31:21 volumio-4 sudo[2089]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 05:31:22 volumio-4 volumio[1200]: info: [MyVolumio PluginManager] Loading plugin "manifestui"... Aug 28 05:31:22 volumio-4 sudo[2089]: pam_unix(sudo:session): session closed for user root Aug 28 05:31:22 volumio-4 sudo[2086]: pam_unix(sudo:session): session closed for user root Aug 28 05:31:22 volumio-4 volumio[1200]: info: [MyVolumio PluginManager] Loading plugin "cd_controller"... Aug 28 05:31:22 volumio-4 volumio[1200]: info: [MyVolumio PluginManager] Loading plugin "smart_inputs"... Aug 28 05:31:22 volumio-4 volumio[1200]: info: [MyVolumio PluginManager] Loading plugin "hi_res_audio"... Aug 28 05:31:22 volumio-4 volumio[1200]: info: [MyVolumio PluginManager] Applying required configuration parameters for plugin hi_res_audio Aug 28 05:31:22 volumio-4 volumio[1200]: info: [MyVolumio PluginManager] Loading plugin "tidal"... Aug 28 05:31:22 volumio-4 volumio[1200]: info: [MyVolumio PluginManager] Loading plugin "qobuz"... Aug 28 05:31:22 volumio-4 volumio[1200]: info: [MyVolumio PluginManager] Loading plugin "tidalconnect"... Aug 28 05:31:22 volumio-4 volumio[1200]: info: [MyVolumio PluginManager] Loading plugin "qobuzconnect"... Aug 28 05:31:22 volumio-4 volumio[1200]: info: Preparing to generate the ALSA configuration file Aug 28 05:31:23 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 05:31:23 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 05:31:23 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam Aug 28 05:31:23 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam Aug 28 05:31:23 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Aug 28 05:31:23 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Aug 28 05:31:23 volumio-4 volumio[1200]: info: CoreCommandRouter::volumioGetBrowseSources Aug 28 05:31:23 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 28 05:31:23 volumio-4 volumio[1200]: info: Initializing connection to go-librespot Websocket Aug 28 05:31:23 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getHwuuid Aug 28 05:31:23 volumio-4 volumio[1200]: info: The plugin multiroom has an ALSA contribution file volumioMultiRoomServer.postMultiRoom.1000.conf Aug 28 05:31:23 volumio-4 volumio[1200]: info: The plugin fusiondsp has an ALSA contribution file volumioDsp.postDsp.10.conf Aug 28 05:31:23 volumio-4 volumio[1200]: info: Reading ALSA contributions from plugins. Aug 28 05:31:23 volumio-4 volumio[1200]: info: CoreCommandRouter::volumioGetState Aug 28 05:31:23 volumio-4 volumio[1200]: info: CorePlayQueue::getTrack 0 Aug 28 05:31:24 volumio-4 volumio[1200]: info: MRS: Removed streaming files Aug 28 05:31:24 volumio-4 volumio[1200]: info: MRS: volumioStreaming STOPPED Aug 28 05:31:24 volumio-4 volumio[1200]: info: MRS: SNAPSERVER STOPPED Aug 28 05:31:24 volumio-4 volumio[1200]: info: MRS: SNAPCLIENT STOPPED Aug 28 05:31:24 volumio-4 volumio[1200]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 28 05:31:24 volumio-4 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 14. Aug 28 05:31:24 volumio-4 systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 28 05:31:24 volumio-4 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 28 05:31:24 volumio-4 go-librespot[2114]: go-librespot daemon starting... Aug 28 05:31:24 volumio-4 go-librespot[2115]: time="2026-08-28T05:31:24-05:00" level=info msg="running go-librespot 0.7.1" Aug 28 05:31:24 volumio-4 go-librespot[2115]: time="2026-08-28T05:31:24-05:00" level=debug msg="app state loaded" Aug 28 05:31:24 volumio-4 go-librespot[2115]: time="2026-08-28T05:31:24-05:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 28 05:31:25 volumio-4 sudo[2124]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart sshtunnel.service Aug 28 05:31:25 volumio-4 sudo[2124]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 05:31:25 volumio-4 go-librespot[2115]: time="2026-08-28T05:31:25-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Aug 28 05:31:25 volumio-4 go-librespot[2115]: time="2026-08-28T05:31:25-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Aug 28 05:31:25 volumio-4 go-librespot[2115]: time="2026-08-28T05:31:25-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Aug 28 05:31:25 volumio-4 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. Aug 28 05:31:25 volumio-4 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. Aug 28 05:31:25 volumio-4 go-librespot[2115]: time="2026-08-28T05:31:25-05:00" level=info msg="zeroconf server listening on port 40527" Aug 28 05:31:25 volumio-4 go-librespot[2115]: time="2026-08-28T05:31:25-05:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 28 05:31:25 volumio-4 systemd[1]: Started sshtunnel.service - MyVolumio SSH Tunnel. Aug 28 05:31:25 volumio-4 volumio[1200]: info: Asound.conf file written Aug 28 05:31:25 volumio-4 sudo[2124]: pam_unix(sudo:session): session closed for user root Aug 28 05:31:25 volumio-4 autossh[2128]: port set to 0, monitoring disabled Aug 28 05:31:25 volumio-4 autossh[2128]: starting ssh (count 1) Aug 28 05:31:25 volumio-4 autossh[2128]: ssh child pid is 2134 Aug 28 05:31:25 volumio-4 go-librespot[2115]: time="2026-08-28T05:31:25-05:00" level=debug msg="obtained new client token: AAHsk5kdQShjmY3VL1Un5SCm0pMnFweexU8/slDOJa1hrG4u9s8g/0FRYzh3ByzqwoEcqB/9OXNysSi6DQkQ+HmC0aKptgbHYdy6MOKhC7vg1QbLPbclFyF10YWAk0B+s0Y9m94N58mNPRgv/XtBo0oTxbb3T1CE5aJvS6g6opEDDJAAf1bk4BYGxTytMZfZvBVLTTdTNZ/FBtzXfU6X5USp0DWsTdcIeaEvL6rYyoyHqTtCVv/EXnk0" Aug 28 05:31:25 volumio-4 go-librespot[2115]: time="2026-08-28T05:31:25-05:00" level=warning msg="failed to connect to AP ap-gue1.spotify.com:4070, retrying with a different AP" error="dial tcp 34.158.255.62:4070: connect: connection refused" Aug 28 05:31:25 volumio-4 go-librespot[2115]: time="2026-08-28T05:31:25-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Aug 28 05:31:25 volumio-4 go-librespot[2115]: time="2026-08-28T05:31:25-05:00" level=debug msg="completed keyexchange" Aug 28 05:31:25 volumio-4 go-librespot[2115]: time="2026-08-28T05:31:25-05:00" level=debug msg="completed challenge" Aug 28 05:31:25 volumio-4 sudo[2133]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mv /home/volumio/.asoundrc /etc/asound.conf Aug 28 05:31:25 volumio-4 sudo[2133]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 05:31:25 volumio-4 go-librespot[2115]: time="2026-08-28T05:31:25-05:00" level=info msg="authenticated AP" username="31************************pi" Aug 28 05:31:25 volumio-4 sudo[2133]: pam_unix(sudo:session): session closed for user root Aug 28 05:31:25 volumio-4 volumiossh-tunnel[2134]: Warning: Permanently added '[us1.myvolumio.org]:2222' (RSA) to the list of known hosts. Aug 28 05:31:25 volumio-4 go-librespot[2115]: time="2026-08-28T05:31:25-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 28 05:31:25 volumio-4 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 28 05:31:25 volumio-4 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 28 05:31:26 volumio-4 volumio[1200]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:0 use case configuration -2 Aug 28 05:31:26 volumio-4 volumio[1200]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:1 use case configuration -2 Aug 28 05:31:26 volumio-4 volumio[1200]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:2 use case configuration -2 Aug 28 05:31:26 volumio-4 volumio[1200]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:3 use case configuration -2 Aug 28 05:31:26 volumio-4 volumio[1200]: info: Output device has changed, restarting MPD Aug 28 05:31:26 volumio-4 sudo[2140]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Aug 28 05:31:26 volumio-4 sudo[2140]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 05:31:26 volumio-4 sudo[2140]: pam_unix(sudo:session): session closed for user root Aug 28 05:31:26 volumio-4 volumio[1200]: info: Output device has changed, restarting Shairport Sync Aug 28 05:31:26 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 05:31:26 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 05:31:26 volumio-4 sudo[2143]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Aug 28 05:31:26 volumio-4 sudo[2143]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 05:31:26 volumio-4 volumio[1200]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Aug 28 05:31:26 volumio-4 volumio[1200]: info: MRS: Audio Device Changed, rebuilding Multiroom Configuration Aug 28 05:31:26 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 05:31:26 volumio-4 systemd[1]: Stopping mpd.service - Music Player Daemon... Aug 28 05:31:26 volumio-4 volumio[1200]: info: [MyVolumio PluginManager] Starting plugin audio_interface.bluetooth Aug 28 05:31:26 volumio-4 systemd[1]: mpd.service: Deactivated successfully. Aug 28 05:31:26 volumio-4 systemd[1]: Stopped mpd.service - Music Player Daemon. Aug 28 05:31:26 volumio-4 systemd[1]: mpd.service: Consumed 4.350s CPU time. Aug 28 05:31:26 volumio-4 systemd[1]: mpd.socket: Deactivated successfully. Aug 28 05:31:26 volumio-4 volumio[1200]: ------------------------------------ BT MESSAGE: [FUNC] onStart Aug 28 05:31:26 volumio-4 volumio[1200]: ------------------------------------ BT MESSAGE: Starting Volumio Bluetooth Service Aug 28 05:31:26 volumio-4 systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Aug 28 05:31:26 volumio-4 systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Aug 28 05:31:26 volumio-4 volumio[1200]: ------------------------------------ BT MESSAGE: Boot config /etc/bluetooth/volumio.conf: cache mode = tmp Aug 28 05:31:26 volumio-4 volumio[1200]: ------------------------------------ BT MESSAGE: [metaCache] Created directory: /tmp/bluetooth-cache/ Aug 28 05:31:26 volumio-4 systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Aug 28 05:31:26 volumio-4 volumio[1200]: ------------------------------------ BT MESSAGE: [metaCache] Directory exists and is ready. Aug 28 05:31:26 volumio-4 systemd[1]: Starting mpd.service - Music Player Daemon... Aug 28 05:31:26 volumio-4 volumio[1200]: info: [MyVolumio PluginManager] Starting plugin audio_interface.multiroom Aug 28 05:31:26 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , pushMultiRoomStatus Aug 28 05:31:26 volumio-4 volumio[1200]: info: MRS: Pushing multiroomSync output for this device Aug 28 05:31:26 volumio-4 volumio[1200]: info: MRS: Pushing multiroomSync output Aug 28 05:31:27 volumio-4 volumio[1200]: info: Adding audio output: Aug 28 05:31:27 volumio-4 volumio[1200]: info: Adding audio output: Aug 28 05:31:27 volumio-4 sudo[2152]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Aug 28 05:31:27 volumio-4 sudo[2152]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Aug 28 05:31:27 volumio-4 sudo[2152]: pam_unix(sudo:session): session closed for user root Aug 28 05:31:27 volumio-4 bluetoothd[957]: Path / reserved for Adv Monitor app :1.41 Aug 28 05:31:27 volumio-4 volumio[1200]: info: MRS: Audio Device Changed, rebuilding Multiroom Configuration Aug 28 05:31:27 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 05:31:27 volumio-4 bluetoothd[957]: Adv Monitor app :1.41 disconnected from D-Bus Aug 28 05:31:27 volumio-4 volumio[1200]: info: [MyVolumio PluginManager] Starting plugin miscellanea.metavolumio Aug 28 05:31:27 volumio-4 volumio[1200]: info: Adding METAVOLUMIO REST API Endpoints Aug 28 05:31:27 volumio-4 volumio[1200]: info: Adding metavolumio REST Endpoint for plugin: miscellanea/metavolumio Aug 28 05:31:27 volumio-4 volumio[1200]: info: Adding getSimilarArtists REST Endpoint for plugin: miscellanea/metavolumio Aug 28 05:31:27 volumio-4 volumio[1200]: info: Adding getSimilarAlbums REST Endpoint for plugin: miscellanea/metavolumio Aug 28 05:31:27 volumio-4 volumio[1200]: info: Adding getSimilarTracks REST Endpoint for plugin: miscellanea/metavolumio Aug 28 05:31:27 volumio-4 volumio[1200]: info: [MyVolumio PluginManager] Starting plugin miscellanea.manifestui Aug 28 05:31:27 volumio-4 volumio[1200]: info: [MyVolumio PluginManager] Starting plugin music_service.cd_controller Aug 28 05:31:27 volumio-4 volumio[1200]: info: Preparing CD Folders Aug 28 05:31:27 volumio-4 volumio[1200]: info: Adding CD REST API Endpoints Aug 28 05:31:27 volumio-4 volumio[1200]: info: Adding cdPostRip REST Endpoint for plugin: music_service/cd_controller Aug 28 05:31:27 volumio-4 volumio[1200]: info: Starting UDEV Watcher for CD Aug 28 05:31:27 volumio-4 volumio[1200]: info: Detecting CD presence with UDEV Aug 28 05:31:27 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: networkfs , getUdevDevices Aug 28 05:31:28 volumio-4 volumio[1200]: info: [cd-plugin] Set CD speed to 1X Aug 28 05:31:28 volumio-4 volumio[1200]: info: [MyVolumio PluginManager] Starting plugin music_service.smart_inputs Aug 28 05:31:28 volumio-4 volumio[1200]: info: Adding inputs REST Endpoints Aug 28 05:31:28 volumio-4 volumio[1200]: info: Adding scanAudioInputs REST Endpoint for plugin: music_service/smart_inputs Aug 28 05:31:28 volumio-4 volumio[1200]: info: Scanning Audio Inputs Aug 28 05:31:28 volumio-4 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 15. Aug 28 05:31:28 volumio-4 systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 28 05:31:29 volumio-4 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 28 05:31:29 volumio-4 go-librespot[2165]: go-librespot daemon starting... Aug 28 05:31:29 volumio-4 volumio[1200]: info: Checking against Known Cards name Aug 28 05:31:29 volumio-4 volumio[1200]: info: Adding Server instance for streaming Aug 28 05:31:29 volumio-4 volumio[1200]: info: [MyVolumio PluginManager] Starting plugin music_service.hi_res_audio Aug 28 05:31:29 volumio-4 go-librespot[2167]: time="2026-08-28T05:31:29-05:00" level=info msg="running go-librespot 0.7.1" Aug 28 05:31:29 volumio-4 go-librespot[2167]: time="2026-08-28T05:31:29-05:00" level=debug msg="app state loaded" Aug 28 05:31:29 volumio-4 go-librespot[2167]: time="2026-08-28T05:31:29-05:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 28 05:31:29 volumio-4 volumio[1200]: error: Hi Res Audio Failed Login: Missing Login Data Aug 28 05:31:29 volumio-4 volumio[1200]: info: Adding HIGHRESAUDIO REST API Endpoints Aug 28 05:31:29 volumio-4 volumio[1200]: info: Adding saveAccountData_hi_res_audio REST Endpoint for plugin: music_service/hi_res_audio Aug 28 05:31:29 volumio-4 volumio[1200]: info: [MyVolumio PluginManager] Starting plugin music_service.tidal Aug 28 05:31:29 volumio-4 volumio[1200]: info: [MyVolumio PluginManager] Starting plugin music_service.qobuz Aug 28 05:31:29 volumio-4 volumio[1200]: info: [MyVolumio PluginManager] Starting plugin music_service.tidalconnect Aug 28 05:31:29 volumio-4 volumio[1200]: info: [MyVolumio PluginManager] Plugin tidalconnect disabled by user. Not starting Aug 28 05:31:29 volumio-4 volumio[1200]: info: [MyVolumio PluginManager] Starting plugin music_service.qobuzconnect Aug 28 05:31:29 volumio-4 volumio[1200]: info: [MyVolumio PluginManager] Plugin qobuzconnect disabled by user. Not starting Aug 28 05:31:29 volumio-4 volumio[1200]: info: Adding TIDAL REST API Endpoints Aug 28 05:31:29 volumio-4 volumio[1200]: info: Stopping AccessToken refresher cron for QOBUZ Aug 28 05:31:29 volumio-4 go-librespot[2167]: time="2026-08-28T05:31:29-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Aug 28 05:31:29 volumio-4 go-librespot[2167]: time="2026-08-28T05:31:29-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Aug 28 05:31:29 volumio-4 go-librespot[2167]: time="2026-08-28T05:31:29-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Aug 28 05:31:29 volumio-4 go-librespot[2167]: time="2026-08-28T05:31:29-05:00" level=info msg="zeroconf server listening on port 35403" Aug 28 05:31:29 volumio-4 go-librespot[2167]: time="2026-08-28T05:31:29-05:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 28 05:31:29 volumio-4 volumio[1200]: info: AccessToken refresher cron started for QOBUZ Aug 28 05:31:29 volumio-4 volumio[1200]: info: Adding QOBUZ REST API Endpoints Aug 28 05:31:29 volumio-4 volumio[1200]: info: Initializing connection to go-librespot Websocket Aug 28 05:31:29 volumio-4 go-librespot[2167]: time="2026-08-28T05:31:29-05:00" level=debug msg="obtained new client token: AAGksRdub6KsR8uaIzTJpHaQD2l760qh0sEQWfEMrNpkGjOW0KpYXaog4wxbWliASf5E66yzlL2v9KxAVU46a/RL/+sbE40ej494zRubdfg7AuyBci6FutuYhk8ECiP/TLqcPBmwtWTLuyEZyAjP858CSHfvMhqO/ZJI/atAZ4Bh/qLSwx42+dPlGTmoI+eAmixsa6iXWjvpsp7E5gRdCgdPHalCJSsBwu4yZjDCMVuX9dbQg0o2zeet" Aug 28 05:31:30 volumio-4 go-librespot[2167]: time="2026-08-28T05:31:30-05:00" level=warning msg="failed to connect to AP ap-gue1.spotify.com:4070, retrying with a different AP" error="dial tcp 34.158.255.62:4070: connect: connection refused" Aug 28 05:31:30 volumio-4 go-librespot[2167]: time="2026-08-28T05:31:30-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Aug 28 05:31:30 volumio-4 go-librespot[2167]: time="2026-08-28T05:31:30-05:00" level=debug msg="completed keyexchange" Aug 28 05:31:30 volumio-4 go-librespot[2167]: time="2026-08-28T05:31:30-05:00" level=debug msg="completed challenge" Aug 28 05:31:30 volumio-4 go-librespot[2167]: time="2026-08-28T05:31:30-05:00" level=info msg="authenticated AP" username="31************************pi" Aug 28 05:31:30 volumio-4 go-librespot[2167]: time="2026-08-28T05:31:30-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 28 05:31:30 volumio-4 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 28 05:31:30 volumio-4 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 28 05:31:30 volumio-4 volumio[1200]: ------------------------------------ BT MESSAGE: Bluetooth adapter powered on Aug 28 05:31:30 volumio-4 volumio[1200]: info: MPD Permissions set Aug 28 05:31:30 volumio-4 volumio[1200]: info: Remote SSH Started Aug 28 05:31:31 volumio-4 sudo[2178]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumiobt.service Aug 28 05:31:31 volumio-4 mpd[2156]: 2026-08-28T05:31:31 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Aug 28 05:31:31 volumio-4 sudo[2178]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 05:31:31 volumio-4 systemd[1]: Started volumiobt.service - Volumio Bluetooth Module. Aug 28 05:31:31 volumio-4 systemd[1]: Started mpd.service - Music Player Daemon. Aug 28 05:31:31 volumio-4 sudo[2143]: pam_unix(sudo:session): session closed for user root Aug 28 05:31:31 volumio-4 volumiobt[2183]: INFO [BTSTART] Ensuring Bluetooth directory exists... Aug 28 05:31:31 volumio-4 sudo[2178]: pam_unix(sudo:session): session closed for user root Aug 28 05:31:31 volumio-4 sudo[2184]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/mkdir -p /var/lib/bluetooth Aug 28 05:31:31 volumio-4 sudo[2184]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 05:31:31 volumio-4 sudo[2184]: pam_unix(sudo:session): session closed for user root Aug 28 05:31:31 volumio-4 sudo[2186]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod -R 777 /var/lib/bluetooth Aug 28 05:31:31 volumio-4 sudo[2186]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 05:31:31 volumio-4 sudo[2186]: pam_unix(sudo:session): session closed for user root Aug 28 05:31:31 volumio-4 volumiobt[2188]: INFO [BTSTART] Powering on Bluetooth if needed... Aug 28 05:31:31 volumio-4 bluetoothd[957]: Path / reserved for Adv Monitor app :1.44 Aug 28 05:31:31 volumio-4 bluetoothd[957]: Adv Monitor app :1.44 disconnected from D-Bus Aug 28 05:31:31 volumio-4 volumiobt[2191]: INFO [BTSTART] Making Bluetooth discoverable and pairable... Aug 28 05:31:31 volumio-4 volumiobt[2192]: [176B blob data] Aug 28 05:31:31 volumio-4 volumiobt[2192]: [157B blob data] Aug 28 05:31:31 volumio-4 volumiobt[2192]: [157B blob data] Aug 28 05:31:31 volumio-4 volumiobt[2192]: [157B blob data] Aug 28 05:31:31 volumio-4 volumiobt[2192]: [113B blob data] Aug 28 05:31:31 volumio-4 volumiobt[2192]: [bluetoothctl]> discoverable on Aug 28 05:31:31 volumio-4 volumiobt[2192]: Warning: setting discoverable while discoverable-timeout not set(0) is not recommended Aug 28 05:31:31 volumio-4 volumiobt[2192]: [bluetoothctl]> pairable on Aug 28 05:31:31 volumio-4 bluetoothd[957]: Path / reserved for Adv Monitor app :1.45 Aug 28 05:31:31 volumio-4 bluetoothd[957]: Adv Monitor app :1.45 disconnected from D-Bus Aug 28 05:31:31 volumio-4 volumiobt[2192]: [bluetoothctl]> Aug 28 05:31:31 volumio-4 volumiobt[2193]: INFO [BTSTART] Registering Bluetooth agent... Aug 28 05:31:32 volumio-4 volumiobt[2194]: [NEW] Media /org/bluez/hci0 Aug 28 05:31:32 volumio-4 volumiobt[2194]: SupportedUUIDs: 0000110a-0000-1000-8000-00805f9b34fb Aug 28 05:31:32 volumio-4 volumiobt[2194]: SupportedUUIDs: 0000110b-0000-1000-8000-00805f9b34fb Aug 28 05:31:32 volumio-4 volumiobt[2194]: SupportedUUIDs: 0000FDF0-0000-1000-8000-00805f9b34fb Aug 28 05:31:32 volumio-4 bluetoothd[957]: Adv Monitor app :1.46 disconnected from D-Bus Aug 28 05:31:32 volumio-4 volumiobt[2195]: No agent is registered Aug 28 05:31:32 volumio-4 volumiobt[2195]: [NEW] Media /org/bluez/hci0 Aug 28 05:31:32 volumio-4 volumiobt[2195]: SupportedUUIDs: 0000110a-0000-1000-8000-00805f9b34fb Aug 28 05:31:32 volumio-4 volumiobt[2195]: SupportedUUIDs: 0000110b-0000-1000-8000-00805f9b34fb Aug 28 05:31:32 volumio-4 volumiobt[2195]: SupportedUUIDs: 0000FDF0-0000-1000-8000-00805f9b34fb Aug 28 05:31:32 volumio-4 bluetoothd[957]: Adv Monitor app :1.47 disconnected from D-Bus Aug 28 05:31:32 volumio-4 volumiobt[2196]: INFO [BTSTART] Agent registered successfully. Aug 28 05:31:32 volumio-4 volumiobt[2197]: INFO [BTSTART] Starting A2DP agent (a2dp-agent)... Aug 28 05:31:33 volumio-4 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 16. Aug 28 05:31:33 volumio-4 systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 28 05:31:33 volumio-4 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 28 05:31:33 volumio-4 go-librespot[2206]: go-librespot daemon starting... Aug 28 05:31:33 volumio-4 go-librespot[2208]: time="2026-08-28T05:31:33-05:00" level=info msg="running go-librespot 0.7.1" Aug 28 05:31:33 volumio-4 go-librespot[2208]: time="2026-08-28T05:31:33-05:00" level=debug msg="app state loaded" Aug 28 05:31:33 volumio-4 go-librespot[2208]: time="2026-08-28T05:31:33-05:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 28 05:31:33 volumio-4 volumiobt[2198]: 2026-08-28 05:31:33 a2dp-agent [INFO] Connecting to system D-Bus Aug 28 05:31:33 volumio-4 volumiobt[2198]: 2026-08-28 05:31:33 a2dp-agent [INFO] Connected to system D-Bus Aug 28 05:31:33 volumio-4 volumiobt[2198]: 2026-08-28 05:31:33 bluezutils [INFO] Found adapter at: /org/bluez/hci0 Aug 28 05:31:33 volumio-4 volumiobt[2198]: 2026-08-28 05:31:33 a2dp-agent [INFO] Found Bluetooth adapter: /org/bluez/hci0 Aug 28 05:31:33 volumio-4 volumiobt[2198]: 2026-08-28 05:31:33 a2dp-agent [INFO] Set DiscoverableTimeout to infinite Aug 28 05:31:33 volumio-4 volumiobt[2198]: 2026-08-28 05:31:33 a2dp-agent [INFO] Enabled Discoverable mode Aug 28 05:31:33 volumio-4 volumiobt[2198]: 2026-08-28 05:31:33 a2dp-agent [INFO] Agent registered at /local/a2dpagent Aug 28 05:31:33 volumio-4 volumiobt[2198]: 2026-08-28 05:31:33 a2dp-agent [INFO] Agent set as default Aug 28 05:31:33 volumio-4 volumiobt[2198]: 2026-08-28 05:31:33 a2dp-agent [INFO] A2DP agent running, waiting for connections... Aug 28 05:31:34 volumio-4 volumio[1200]: info: MRS: Getting audio outputs on start Aug 28 05:31:34 volumio-4 volumio[1200]: info: MRS: Requesting all other devices output Aug 28 05:31:34 volumio-4 go-librespot[2208]: time="2026-08-28T05:31:34-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew4.spotify.com:80]" Aug 28 05:31:34 volumio-4 go-librespot[2208]: time="2026-08-28T05:31:34-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Aug 28 05:31:34 volumio-4 go-librespot[2208]: time="2026-08-28T05:31:34-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Aug 28 05:31:34 volumio-4 volumio[1200]: error: MyVolumio Plugins failed to start in a timely fashion Aug 28 05:31:34 volumio-4 go-librespot[2208]: time="2026-08-28T05:31:34-05:00" level=info msg="zeroconf server listening on port 33083" Aug 28 05:31:34 volumio-4 volumio[1200]: error: Plugin audio_interface bluetooth failed to complete 'onStart' in a timely fashion Aug 28 05:31:34 volumio-4 volumio[1200]: error: Plugin audio_interface multiroom failed to complete 'onStart' in a timely fashion Aug 28 05:31:34 volumio-4 volumio[1200]: error: Plugin music_service tidalconnect failed to complete 'onStart' in a timely fashion Aug 28 05:31:34 volumio-4 go-librespot[2208]: time="2026-08-28T05:31:34-05:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 28 05:31:34 volumio-4 volumio[1200]: error: Plugin music_service qobuzconnect failed to complete 'onStart' in a timely fashion Aug 28 05:31:34 volumio-4 volumio[1200]: [Metrics] CommandRouter: 119s 101.31ms Aug 28 05:31:34 volumio-4 volumio[1200]: info: CoreCommandRouter::volumiosetStartupVolume Aug 28 05:31:34 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 05:31:34 volumio-4 volumio[1200]: info: VolumeController:: Setting startup Volume 10 Aug 28 05:31:34 volumio-4 volumio[1200]: info: VolumeController::SetAlsaVolume10 Aug 28 05:31:34 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 05:31:34 volumio-4 volumio[1200]: info: CoreCommandRouter::Close All Modals sent Aug 28 05:31:34 volumio-4 go-librespot[2208]: time="2026-08-28T05:31:34-05:00" level=debug msg="obtained new client token: AAFsLL6jC59GsxOEJhWq5R2p39KL53YrSzKu3LucZ7jUSmWo36o9ANmslG1k8VEeVKZ3SxyO8axBCRaxu//rM0FeNxnAuzScnhWB2RKiGc+1dl5COqjyo1NyOEaB6WlGItFTKMJy2buHeHG+HtSIeHVi30ZRuDfvH8Z+BmlCJuf6uaLMQkz4aatywNdVAicn7PPWr9h1ZxXq3K+GWdP6lTKc1DczXMYoRLQ/mf1OGy6JqAxTNQCaMngN" Aug 28 05:31:34 volumio-4 go-librespot[2208]: time="2026-08-28T05:31:34-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Aug 28 05:31:34 volumio-4 volumio[1200]: info: CoreCommandRouter::Close All Modals sent Aug 28 05:31:34 volumio-4 volumio[1200]: info: CoreStateMachine::pushState Aug 28 05:31:34 volumio-4 volumio[1200]: info: CorePlayQueue::getTrack 0 Aug 28 05:31:34 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 28 05:31:34 volumio-4 volumio[1200]: info: CoreCommandRouter::volumioPushState Aug 28 05:31:34 volumio-4 go-librespot[2208]: time="2026-08-28T05:31:34-05:00" level=debug msg="completed keyexchange" Aug 28 05:31:34 volumio-4 go-librespot[2208]: time="2026-08-28T05:31:34-05:00" level=debug msg="completed challenge" Aug 28 05:31:34 volumio-4 go-librespot[2208]: time="2026-08-28T05:31:34-05:00" level=info msg="authenticated AP" username="31************************pi" Aug 28 05:31:34 volumio-4 volumio[1200]: info: MRS: Pushing multiroomSync output update for this device Aug 28 05:31:34 volumio-4 volumio[1200]: info: MRS: Pushing multiroomSync output Aug 28 05:31:34 volumio-4 go-librespot[2208]: time="2026-08-28T05:31:34-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 28 05:31:34 volumio-4 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 28 05:31:34 volumio-4 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 28 05:31:35 volumio-4 volumio[1200]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 28 05:31:35 volumio-4 volumio[1200]: ------------------------------------ BT MESSAGE: volumiobt.service started successfully Aug 28 05:31:35 volumio-4 volumio[1200]: ------------------------------------ BT MESSAGE: [FUNC] dbusStart Aug 28 05:31:35 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable Aug 28 05:31:35 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Aug 28 05:31:35 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect Aug 28 05:31:35 volumio-4 volumio[1200]: info: FusionDsp - ---- read samplerate, raw: 44100,S32_LE,2,32 Aug 28 05:31:35 volumio-4 volumio[1200]: info: FusionDsp - ---- read samplerate from file: 44100 Aug 28 05:31:35 volumio-4 volumio[1200]: info: camilladsp stopping service pid 1706... Aug 28 05:31:36 volumio-4 volumio[1200]: grep: /proc/1706/cmdline: binary file matches Aug 28 05:31:36 volumio-4 volumio[1200]: grep: /proc/1706/cmdline: binary file matches Aug 28 05:31:36 volumio-4 volumio[1200]: grep: /proc/1706/cmdline: binary file matches Aug 28 05:31:36 volumio-4 volumio[1200]: info: camilladsp service terminated, instance 1 Aug 28 05:31:36 volumio-4 volumio[1200]: info: FusionDsp - If filter freq >samplerate/2 then disable it Aug 28 05:31:36 volumio-4 volumio[1200]: info: FusionDsp - Crossfeed selected : linkwitz Aug 28 05:31:36 volumio-4 volumio[1200]: info: camilladsp service started and running in background, instance 1 Aug 28 05:31:36 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 05:31:36 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 05:31:36 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 05:31:36 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 05:31:36 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 05:31:36 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 05:31:36 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 05:31:36 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 05:31:36 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 05:31:36 volumio-4 volumio[1200]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 05:31:37 volumio-4 volumio[1200]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Aug 28 05:31:37 volumio-4 volumio[1200]: info: camilladsp respawn in 100 ms (attempt 1/10) Aug 28 05:31:37 volumio-4 volumio[1200]: error: updateQueue error: null Aug 28 05:31:37 volumio-4 volumio[1200]: info: MRS: Found cast device: Pendant-57da2e32fa13224143807328a6adb06f Aug 28 05:31:37 volumio-4 volumio[1200]: info: Adding audio output: Aug 28 05:31:37 volumio-4 volumio[1200]: info: Starting Shairport Sync Aug 28 05:31:37 volumio-4 volumio[1200]: info: MRS: Found cast device: Pendant-5d51b6981df1ea312b13d27fb6ed5aa7 Aug 28 05:31:37 volumio-4 volumio[1200]: info: Adding audio output: Aug 28 05:31:37 volumio-4 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 17. Aug 28 05:31:37 volumio-4 systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 28 05:31:37 volumio-4 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 28 05:31:37 volumio-4 go-librespot[2261]: go-librespot daemon starting... Aug 28 05:31:37 volumio-4 sudo[2260]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Aug 28 05:31:37 volumio-4 sudo[2260]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 05:31:37 volumio-4 go-librespot[2262]: time="2026-08-28T05:31:37-05:00" level=info msg="running go-librespot 0.7.1" Aug 28 05:31:37 volumio-4 go-librespot[2262]: time="2026-08-28T05:31:37-05:00" level=debug msg="app state loaded" Aug 28 05:31:37 volumio-4 go-librespot[2262]: time="2026-08-28T05:31:37-05:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 28 05:31:38 volumio-4 systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Aug 28 05:31:38 volumio-4 systemd[1]: shairport-sync.service: Deactivated successfully. Aug 28 05:31:38 volumio-4 systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 28 05:31:38 volumio-4 systemd[1]: shairport-sync.service: Consumed 1.735s CPU time. Aug 28 05:31:38 volumio-4 systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 28 05:31:38 volumio-4 sudo[2260]: pam_unix(sudo:session): session closed for user root Aug 28 05:31:38 volumio-4 volumio[1200]: info: MRS: Found cast device: Pendant-d967c90a7fcffc21a985b503fc496f85 Aug 28 05:31:38 volumio-4 volumio[1200]: info: Adding audio output: Aug 28 05:31:38 volumio-4 volumio[1200]: info: MRS: Found cast device: Pendant-c072909152d3e71d586335856757bfd7 Aug 28 05:31:38 volumio-4 volumio[1200]: info: Adding audio output: Aug 28 05:31:38 volumio-4 go-librespot[2262]: time="2026-08-28T05:31:38-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Aug 28 05:31:38 volumio-4 go-librespot[2262]: time="2026-08-28T05:31:38-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Aug 28 05:31:38 volumio-4 go-librespot[2262]: time="2026-08-28T05:31:38-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Aug 28 05:31:38 volumio-4 go-librespot[2262]: time="2026-08-28T05:31:38-05:00" level=info msg="zeroconf server listening on port 43993" Aug 28 05:31:38 volumio-4 go-librespot[2262]: time="2026-08-28T05:31:38-05:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 28 05:31:38 volumio-4 volumio[1200]: info: Shairport-Sync Started Aug 28 05:31:38 volumio-4 volumio[1200]: info: CoreCommandRouter::volumioGetState Aug 28 05:31:38 volumio-4 volumio[1200]: info: CorePlayQueue::getTrack 0 Aug 28 05:31:38 volumio-4 volumio[1200]: info: Initializing connection to go-librespot Websocket Aug 28 05:31:38 volumio-4 go-librespot[2262]: time="2026-08-28T05:31:38-05:00" level=debug msg="new websocket client" Aug 28 05:31:38 volumio-4 volumio[1200]: info: Connection to go-librespot Websocket established Aug 28 05:31:38 volumio-4 go-librespot[2262]: time="2026-08-28T05:31:38-05:00" level=debug msg="obtained new client token: AAGIJurrc8O6HJ8F0J3qnbCrUrmhlr2OvxGIfBHDVtIvmKPYyNosHI6/9CBstm3D1/aYjnB0DWRw9k4qti5kGbsy7qeKuM/ZSep8IwN8y5LbXkfFruCdYQumQyM85nT/u2T5BRgq/2oc4ccGslAVZy7k9GaK/D7E592lNzyGxR9iBiraNNzO0dbU3WMIjmLFeA/q3h2SYBCmX3d06md+lFGn88G6jIqpc8VmANFQi95Wex2mq+iXAsxY" Aug 28 05:31:38 volumio-4 go-librespot[2262]: time="2026-08-28T05:31:38-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Aug 28 05:31:38 volumio-4 go-librespot[2262]: time="2026-08-28T05:31:38-05:00" level=debug msg="completed keyexchange" Aug 28 05:31:38 volumio-4 go-librespot[2262]: time="2026-08-28T05:31:38-05:00" level=debug msg="completed challenge" Aug 28 05:31:38 volumio-4 go-librespot[2262]: time="2026-08-28T05:31:38-05:00" level=info msg="authenticated AP" username="31************************pi" Aug 28 05:31:39 volumio-4 go-librespot[2262]: time="2026-08-28T05:31:39-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 28 05:31:39 volumio-4 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 28 05:31:39 volumio-4 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 28 05:31:39 volumio-4 volumio[1200]: info: Connection to go-librespot Websocket closed Aug 28 05:31:41 volumio-4 volumio[1200]: info: camilladsp respawn in 200 ms (attempt 2/10) Aug 28 05:31:41 volumio-4 volumio[1200]: info: BOOT COMPLETED Aug 28 05:31:41 volumio-4 volumio[1200]: info: Getting Spotify volume Aug 28 05:31:41 volumio-4 volumio[1200]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 28 05:31:41 volumio-4 volumio[1200]: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 28 05:31:41 volumio-4 volumio[1200]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Aug 28 05:31:41 volumio-4 volumio[1200]: errno: -111, Aug 28 05:31:41 volumio-4 volumio[1200]: code: 'ECONNREFUSED', Aug 28 05:31:41 volumio-4 volumio[1200]: syscall: 'connect', Aug 28 05:31:41 volumio-4 volumio[1200]: address: '127.0.0.1', Aug 28 05:31:41 volumio-4 volumio[1200]: port: 9879, Aug 28 05:31:41 volumio-4 volumio[1200]: response: undefined Aug 28 05:31:41 volumio-4 volumio[1200]: } Aug 28 05:31:41 volumio-4 volumio[1200]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 28 05:31:42 volumio-4 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 18. Aug 28 05:31:42 volumio-4 systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 28 05:31:42 volumio-4 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 28 05:31:42 volumio-4 go-librespot[2297]: go-librespot daemon starting... Aug 28 05:31:42 volumio-4 go-librespot[2303]: time="2026-08-28T05:31:42-05:00" level=info msg="running go-librespot 0.7.1" Aug 28 05:31:42 volumio-4 go-librespot[2303]: time="2026-08-28T05:31:42-05:00" level=debug msg="app state loaded" Aug 28 05:31:42 volumio-4 go-librespot[2303]: time="2026-08-28T05:31:42-05:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 28 05:31:42 volumio-4 go-librespot[2303]: time="2026-08-28T05:31:42-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Aug 28 05:31:42 volumio-4 go-librespot[2303]: time="2026-08-28T05:31:42-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Aug 28 05:31:42 volumio-4 go-librespot[2303]: time="2026-08-28T05:31:42-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Aug 28 05:31:42 volumio-4 go-librespot[2303]: time="2026-08-28T05:31:42-05:00" level=info msg="zeroconf server listening on port 43943" Aug 28 05:31:42 volumio-4 go-librespot[2303]: time="2026-08-28T05:31:42-05:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 28 05:31:43 volumio-4 go-librespot[2303]: time="2026-08-28T05:31:43-05:00" level=debug msg="obtained new client token: AAGTFb2yQUYfOYUWluVY9pYHCXqN4pvRwyMV90gVxU++63UFQh8xCIpLKH+GjkOGFBq2m+n8beMobpXJGKUVHb8zB1HjJF68ku1PG4lxjmQ2DfE/s9lVFEi0ZTWZrsos6fbVV2BwlT3Qw6dG7RlBe0sTdzcfSGoZj7TD6fkwZB7PebYY4LQyO3IedJe3lP1diAeiyMUdacmQnoch3TMl/vn85w1LKoi5C7pH0VT/yZpXZgh2qv04TA==" Aug 28 05:31:43 volumio-4 go-librespot[2303]: time="2026-08-28T05:31:43-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Aug 28 05:31:43 volumio-4 go-librespot[2303]: time="2026-08-28T05:31:43-05:00" level=debug msg="completed keyexchange" Aug 28 05:31:43 volumio-4 go-librespot[2303]: time="2026-08-28T05:31:43-05:00" level=debug msg="completed challenge" Aug 28 05:31:43 volumio-4 go-librespot[2303]: time="2026-08-28T05:31:43-05:00" level=info msg="authenticated AP" username="31************************pi" Aug 28 05:31:43 volumio-4 go-librespot[2303]: time="2026-08-28T05:31:43-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 28 05:31:43 volumio-4 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 28 05:31:43 volumio-4 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 28 05:31:46 volumio-4 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 19. Aug 28 05:31:46 volumio-4 systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 28 05:31:46 volumio-4 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 28 05:31:46 volumio-4 go-librespot[2327]: go-librespot daemon starting... Aug 28 05:31:47 volumio-4 go-librespot[2328]: time="2026-08-28T05:31:47-05:00" level=info msg="running go-librespot 0.7.1" Aug 28 05:31:47 volumio-4 go-librespot[2328]: time="2026-08-28T05:31:47-05:00" level=debug msg="app state loaded" Aug 28 05:31:47 volumio-4 go-librespot[2328]: time="2026-08-28T05:31:47-05:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 28 05:31:47 volumio-4 go-librespot[2328]: time="2026-08-28T05:31:47-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Aug 28 05:31:47 volumio-4 go-librespot[2328]: time="2026-08-28T05:31:47-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Aug 28 05:31:47 volumio-4 go-librespot[2328]: time="2026-08-28T05:31:47-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Aug 28 05:31:47 volumio-4 go-librespot[2328]: time="2026-08-28T05:31:47-05:00" level=info msg="zeroconf server listening on port 43123" Aug 28 05:31:47 volumio-4 go-librespot[2328]: time="2026-08-28T05:31:47-05:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 28 05:31:47 volumio-4 go-librespot[2328]: time="2026-08-28T05:31:47-05:00" level=debug msg="obtained new client token: AAFHaB+fCjJVaKJXv0XZp0R0683TDih4W5jpaqlhYYA0/EJd/HCbOufs3cVhvXH1i8MuOVby/aIV+bx6cey752XrVxTPUJFq1EyxolCQGXFf4cqbRxvLIhGliBZqkFixw8aS/cpkK9cy8Qg5epjhUaI9rsOkfqP3FKeRfXVrYrGht8Ia0iUPjh3jgG1WuoqqxFA64G6pgu2OF8zX5eLFigghFDSgqDgnWerGeqcE9qiYpwg38MfKN5pG" Aug 28 05:31:47 volumio-4 go-librespot[2328]: time="2026-08-28T05:31:47-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Aug 28 05:31:47 volumio-4 go-librespot[2328]: time="2026-08-28T05:31:47-05:00" level=debug msg="completed keyexchange" Aug 28 05:31:47 volumio-4 go-librespot[2328]: time="2026-08-28T05:31:47-05:00" level=debug msg="completed challenge" Aug 28 05:31:47 volumio-4 go-librespot[2328]: time="2026-08-28T05:31:47-05:00" level=info msg="authenticated AP" username="31************************pi" Aug 28 05:31:48 volumio-4 go-librespot[2328]: time="2026-08-28T05:31:48-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 28 05:31:48 volumio-4 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 28 05:31:48 volumio-4 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 28 05:31:48 volumio-4 sudo[2340]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-08-28 05:30' Aug 28 05:31:48 volumio-4 sudo[2340]: 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="18952480e8d8c63f22208e9007a0f47a9563eae6" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="0e58f1861fa88e02087981b8d91f7511f0e7011b" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue Mar 24 17:20:52 UTC 2026" VOLUMIO_VERSION="4.119" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="d0c2fd9dbc5e70e58c32413c12353563"