Feb 26 20:36:05 loe ntpd[1017]: CLOCK: time stepped by 1352690.927350 Feb 26 20:36:05 loe ntpd[1017]: CLOCK: time changed from 2026-02-11 to 2026-02-26 Feb 26 20:36:05 loe ntpd[1017]: INIT: MRU 13107 entries, 13 hash bits, 32768 bytes Feb 26 20:36:07 loe sudo[1488]: pam_unix(sudo:session): session closed for user root Feb 26 20:36:08 loe volumio[1224]: verbose: New Socket.io Connection to 192.168.178.245 from 192.168.178.147 UA: Mozilla/5.0 (Linux; Android 16; SM-A566B Build/BP2A.250605.031.A3; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/145.0.7632.79 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 1 Feb 26 20:36:08 loe volumio[1224]: info: VolumeController:: Volume=50 Mute =false Feb 26 20:36:08 loe volumio[1224]: info: CoreStateMachine::pushState Feb 26 20:36:08 loe volumio[1224]: info: CorePlayQueue::getTrack 0 Feb 26 20:36:08 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 26 20:36:08 loe volumio[1224]: info: CoreCommandRouter::volumioPushState Feb 26 20:36:08 loe volumio[1224]: info: CoreStateMachine::updateTrackBlock Feb 26 20:36:08 loe volumio[1224]: info: CorePlayQueue::getTrackBlock Feb 26 20:36:08 loe volumio[1224]: info: CoreCommandRouter::volumioRetrievevolume Feb 26 20:36:08 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 26 20:36:08 loe volumio[1224]: info: Reloading queue from file Feb 26 20:36:09 loe volumio[1224]: info: CoreStateMachine::setRepeat false single undefined Feb 26 20:36:09 loe volumio[1224]: info: CoreStateMachine::pushState Feb 26 20:36:09 loe volumio[1224]: info: CorePlayQueue::getTrack 0 Feb 26 20:36:09 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 26 20:36:09 loe volumio[1224]: info: CoreCommandRouter::volumioPushState Feb 26 20:36:09 loe volumio[1224]: info: CoreStateMachine::setRandom null Feb 26 20:36:09 loe volumio[1224]: info: CoreStateMachine::pushState Feb 26 20:36:09 loe volumio[1224]: info: CorePlayQueue::getTrack 0 Feb 26 20:36:09 loe volumio[1224]: info: CoreCommandRouter::volumioPushState Feb 26 20:36:09 loe volumio[1224]: verbose: New Socket.io Connection to 192.168.178.245 from 192.168.178.147 UA: Mozilla/5.0 (Linux; Android 16; SM-A566B Build/BP2A.250605.031.A3; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/145.0.7632.79 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 2 Feb 26 20:36:09 loe volumio[1224]: info: VolumeController:: Volume=50 Mute =false Feb 26 20:36:09 loe volumio[1224]: info: CoreStateMachine::pushState Feb 26 20:36:09 loe volumio[1224]: info: CorePlayQueue::getTrack 0 Feb 26 20:36:09 loe volumio[1224]: info: CoreCommandRouter::volumioPushState Feb 26 20:36:09 loe volumio[1224]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Feb 26 20:36:09 loe volumio[1224]: info: USB Boot Capable - System SBC Revision found in cpuinfo: b03114 Feb 26 20:36:09 loe volumio[1224]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Feb 26 20:36:09 loe volumio[1224]: verbose: New Socket.io Connection to 192.168.178.245 from 192.168.178.147 UA: Mozilla/5.0 (Linux; Android 16; SM-A566B Build/BP2A.250605.031.A3; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/145.0.7632.79 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 3 Feb 26 20:36:09 loe volumio[1224]: info: Setting Device type: Raspberry PI Feb 26 20:36:09 loe volumio[1224]: info: Completed loading Core Plugins Feb 26 20:36:09 loe volumio[1224]: info: Preparing to generate the ALSA configuration file Feb 26 20:36:09 loe volumio[1224]: info: Discovery: A device disappeared from network Feb 26 20:36:09 loe volumio[1224]: info: Discovery: adding 07fbb113-343c-4b34-af49-444dc3d8fb26 Feb 26 20:36:09 loe volumio[1224]: info: Discovery: Found device Loe Feb 26 20:36:09 loe volumio[1224]: info: CoreCommandRouter::volumioGetState Feb 26 20:36:09 loe volumio[1224]: info: CorePlayQueue::getTrack 0 Feb 26 20:36:09 loe volumio[1224]: info: Discovery: this is already registered, 07fbb113-343c-4b34-af49-444dc3d8fb26 Feb 26 20:36:09 loe volumio[1224]: info: Discovery: Found device Loe Feb 26 20:36:09 loe volumio[1224]: info: CoreCommandRouter::volumioGetState Feb 26 20:36:09 loe volumio[1224]: info: CorePlayQueue::getTrack 0 Feb 26 20:36:09 loe volumio[1224]: info: Discovery: A device disappeared from network Feb 26 20:36:09 loe volumio[1224]: info: Discovery: Device loe disappeared from network Feb 26 20:36:09 loe volumio[1224]: info: Asound.conf file unchanged, so no further update is needed Feb 26 20:36:09 loe volumio[1224]: info: Output device has changed, restarting MPD Feb 26 20:36:09 loe volumio[1224]: info: Output device has changed, restarting Shairport Sync Feb 26 20:36:09 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 26 20:36:09 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 26 20:36:09 loe sudo[1530]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Feb 26 20:36:09 loe sudo[1530]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 26 20:36:09 loe sudo[1530]: pam_unix(sudo:session): session closed for user root Feb 26 20:36:10 loe volumio[1487]: Starting albumart workers Feb 26 20:36:10 loe sudo[1533]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Feb 26 20:36:10 loe sudo[1533]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 26 20:36:10 loe volumio[1224]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Feb 26 20:36:10 loe volumio[1224]: info: ___________ START PLUGINS ___________ Feb 26 20:36:10 loe volumio[1224]: info: ControllerMpd::onStart: Initializing MPD Feb 26 20:36:10 loe volumio[1224]: info: Creating MPD Configuration file Feb 26 20:36:10 loe sudo[1553]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumio5-onboarding.service Feb 26 20:36:10 loe sudo[1553]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 26 20:36:10 loe systemd[1]: Starting dpkg-db-backup.service - Daily dpkg database backup service... Feb 26 20:36:10 loe systemd[1]: Started ntpsec-rotate-stats.service - Rotate ntpd stats. Feb 26 20:36:10 loe systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Feb 26 20:36:10 loe systemd[1]: Starting mpd.service - Music Player Daemon... Feb 26 20:36:10 loe systemd[1]: ntpsec-rotate-stats.service: Deactivated successfully. Feb 26 20:36:10 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 26 20:36:10 loe volumio[1224]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Feb 26 20:36:10 loe volumio[1224]: info: [1772134570381] CoreMusicLibrary::Adding element Media Servers Feb 26 20:36:10 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 26 20:36:10 loe systemd[1]: dpkg-db-backup.service: Deactivated successfully. Feb 26 20:36:10 loe systemd[1]: Finished dpkg-db-backup.service - Daily dpkg database backup service. Feb 26 20:36:10 loe sudo[1556]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Feb 26 20:36:10 loe sudo[1556]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 26 20:36:10 loe sudo[1556]: pam_unix(sudo:session): session closed for user root Feb 26 20:36:10 loe volumio[1224]: info: UPNP Browser: Client initialized successfully Feb 26 20:36:10 loe volumio[1483]: Starting albumart workers Feb 26 20:36:10 loe sudo[1568]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Feb 26 20:36:10 loe sudo[1568]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 26 20:36:10 loe sudo[1567]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Feb 26 20:36:10 loe sudo[1567]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Feb 26 20:36:10 loe sudo[1574]: /bin/chown: cannot access '/var/log/mpd.log': No such file or directory Feb 26 20:36:10 loe sudo[1567]: pam_unix(sudo:session): session closed for user root Feb 26 20:36:10 loe systemd[1]: Started volumio5-onboarding.service - Volumio5 Onboarding Server. Feb 26 20:36:10 loe sudo[1553]: pam_unix(sudo:session): session closed for user root Feb 26 20:36:10 loe volumio[1485]: Starting albumart workers Feb 26 20:36:10 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 26 20:36:10 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 26 20:36:10 loe systemd[1]: mpd.service: Deactivated successfully. Feb 26 20:36:10 loe systemd[1]: Stopped mpd.service - Music Player Daemon. Feb 26 20:36:10 loe systemd[1]: mpd.socket: Deactivated successfully. Feb 26 20:36:10 loe systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Feb 26 20:36:10 loe systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Feb 26 20:36:10 loe systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Feb 26 20:36:10 loe systemd[1]: Starting mpd.service - Music Player Daemon... Feb 26 20:36:11 loe volumio5-onboarding[1573]: time=2026-02-26T20:36:11.001+01:00 level=INFO msg="running volumio5-device-gateway" version=30d1950e+CHANGES buildDate=2026-01-29T13:10:08Z Feb 26 20:36:11 loe volumio[1224]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Feb 26 20:36:11 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 26 20:36:11 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 26 20:36:11 loe sudo[1588]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Feb 26 20:36:11 loe sudo[1588]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Feb 26 20:36:11 loe sudo[1596]: /bin/chown: cannot access '/var/log/mpd.log': No such file or directory Feb 26 20:36:11 loe sudo[1588]: pam_unix(sudo:session): session closed for user root Feb 26 20:36:11 loe volumio[1224]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Feb 26 20:36:11 loe volumio[1224]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Feb 26 20:36:11 loe volumio[1224]: info: [1772134571073] CoreMusicLibrary::Adding element Last_100 Feb 26 20:36:11 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 26 20:36:11 loe volumio[1224]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Feb 26 20:36:11 loe volumio[1224]: info: [1772134571075] CoreMusicLibrary::Adding element Webradio Feb 26 20:36:11 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 26 20:36:11 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Feb 26 20:36:11 loe volumio[1224]: info: Initializing BBC Radios Feb 26 20:36:11 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Feb 26 20:36:11 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 26 20:36:11 loe volumio[1224]: info: Creating Spotify config file Feb 26 20:36:11 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 26 20:36:12 loe volumio[1224]: info: Volumio Calling Home Feb 26 20:36:12 loe volumio-remote-updater[729]: [2026-02-26 20:36:12] [connect] Successful connection Feb 26 20:36:13 loe systemd[1]: systemd-fsckd.service: Deactivated successfully. Feb 26 20:36:14 loe sudo[1634]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Feb 26 20:36:14 loe sudo[1634]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 26 20:36:14 loe sudo[1634]: pam_unix(sudo:session): session closed for user root Feb 26 20:36:14 loe sudo[1637]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Feb 26 20:36:14 loe sudo[1637]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 26 20:36:14 loe sudo[1637]: pam_unix(sudo:session): session closed for user root Feb 26 20:36:14 loe volumio[1224]: info: MPD Permissions set Feb 26 20:36:14 loe volumio[1224]: info: MPD Permissions set Feb 26 20:36:14 loe volumio[1224]: 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: 4 Feb 26 20:36:14 loe volumio[1224]: info: Volumio called home Feb 26 20:36:14 loe volumio[1224]: info: Spotify config file written Feb 26 20:36:15 loe volumio[1224]: info: Discovery: adding 07fbb113-343c-4b34-af49-444dc3d8fb26 Feb 26 20:36:15 loe volumio[1224]: info: Discovery: Found device Loe Feb 26 20:36:15 loe volumio[1224]: info: CoreCommandRouter::volumioGetState Feb 26 20:36:15 loe volumio[1224]: info: CorePlayQueue::getTrack 0 Feb 26 20:36:15 loe sudo[1647]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Feb 26 20:36:15 loe sudo[1647]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 26 20:36:15 loe volumio[1224]: 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: 4 Feb 26 20:36:15 loe volumio[1224]: info: Received Get System Info Feb 26 20:36:15 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Feb 26 20:36:15 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Feb 26 20:36:15 loe volumio[1224]: info: Discovery: Getting this device information Feb 26 20:36:15 loe volumio[1224]: info: CoreCommandRouter::volumioGetState Feb 26 20:36:15 loe volumio[1224]: info: CorePlayQueue::getTrack 0 Feb 26 20:36:15 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 26 20:36:15 loe volumio5-onboarding[1573]: time=2026-02-26T20:36:15.159+01:00 level=INFO msg="system info for 143af29c3c483d56419c3a5083f31115" deviceName=Loe deviceVariant=volumio deviceModel= softwareVersion=4.096 Feb 26 20:36:15 loe 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. Feb 26 20:36:15 loe 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. Feb 26 20:36:15 loe systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 26 20:36:15 loe sudo[1647]: pam_unix(sudo:session): session closed for user root Feb 26 20:36:15 loe go-librespot[1649]: go-librespot daemon starting... Feb 26 20:36:15 loe mpd[1597]: 2026-02-26T20:36:15 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Feb 26 20:36:15 loe systemd[1]: Started mpd.service - Music Player Daemon. Feb 26 20:36:15 loe sudo[1568]: pam_unix(sudo:session): session closed for user root Feb 26 20:36:15 loe sudo[1533]: pam_unix(sudo:session): session closed for user root Feb 26 20:36:15 loe volumio-remote-updater[729]: [2026-02-26 20:36:15] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1772134572 101 Feb 26 20:36:15 loe volumio[1224]: 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: 5 Feb 26 20:36:15 loe go-librespot[1650]: time="2026-02-26T20:36:15+01:00" level=info msg="running go-librespot 0.4.0" Feb 26 20:36:15 loe go-librespot[1650]: time="2026-02-26T20:36:15+01:00" level=debug msg="app state loaded" Feb 26 20:36:15 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 26 20:36:15 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 26 20:36:15 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 26 20:36:15 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 26 20:36:15 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 26 20:36:15 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 26 20:36:15 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 26 20:36:15 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 26 20:36:15 loe go-librespot[1650]: time="2026-02-26T20:36:15+01:00" level=info msg="api server listening on 127.0.0.1:9879" Feb 26 20:36:15 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 26 20:36:15 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 26 20:36:15 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 26 20:36:15 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 26 20:36:15 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 26 20:36:15 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 26 20:36:15 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 26 20:36:15 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 26 20:36:15 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 26 20:36:15 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 26 20:36:15 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 26 20:36:15 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 26 20:36:15 loe volumio[1224]: info: No need to fix Spotify hosts Feb 26 20:36:15 loe systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 2. Feb 26 20:36:15 loe systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Feb 26 20:36:15 loe volumio[1224]: info: Received Get System Info Feb 26 20:36:15 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Feb 26 20:36:15 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Feb 26 20:36:15 loe volumio[1224]: info: Discovery: Getting this device information Feb 26 20:36:15 loe volumio[1224]: info: CoreCommandRouter::volumioGetState Feb 26 20:36:15 loe volumio[1224]: info: CorePlayQueue::getTrack 0 Feb 26 20:36:15 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 26 20:36:15 loe go-librespot[1650]: time="2026-02-26T20:36:15+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Feb 26 20:36:15 loe go-librespot[1650]: time="2026-02-26T20:36:15+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Feb 26 20:36:15 loe go-librespot[1650]: time="2026-02-26T20:36:15+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Feb 26 20:36:15 loe go-librespot[1650]: time="2026-02-26T20:36:15+01:00" level=info msg="zeroconf server listening on port 36803" Feb 26 20:36:16 loe systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Feb 26 20:36:16 loe systemd[1]: systemd-hostnamed.service: Deactivated successfully. Feb 26 20:36:16 loe upmpdcli[1669]: :3:../libupnpp/upnpplib.cxx:273::LibUPnP: Using IPV4 192.168.178.245 port 49152 IPV6 port 49152 Feb 26 20:36:16 loe upmpdcli[1669]: :3:../src/mediaserver/cdplugins/plgwithslave.cxx:238::PlgWithSlave: starting streaming proxy on port 49149 Feb 26 20:36:16 loe upmpdcli[1684]: writing RSA key Feb 26 20:36:16 loe volumio[1224]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 6 Feb 26 20:36:16 loe volumio[1224]: info: Completed starting Core Plugins Feb 26 20:36:16 loe volumio[1224]: info: ------------------------------------------- Feb 26 20:36:16 loe volumio[1224]: info: ----- MyVolumio plugins startup ---- Feb 26 20:36:16 loe volumio[1224]: info: ------------------------------------------- Feb 26 20:36:16 loe volumio[1224]: info: [MyVolumio PluginManager] Fetching plans data.... Feb 26 20:36:16 loe volumio[1224]: info: Discovery: this is already registered, 07fbb113-343c-4b34-af49-444dc3d8fb26 Feb 26 20:36:16 loe volumio[1224]: info: Discovery: Found device Loe Feb 26 20:36:16 loe volumio[1224]: info: CoreCommandRouter::volumioGetState Feb 26 20:36:16 loe volumio[1224]: info: CorePlayQueue::getTrack 0 Feb 26 20:36:16 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Feb 26 20:36:16 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Feb 26 20:36:16 loe volumio5-onboarding[1573]: time=2026-02-26T20:36:16.474+01:00 level=INFO msg="enabling local network discovery" Feb 26 20:36:16 loe volumio5-onboarding[1573]: time=2026-02-26T20:36:16.509+01:00 level=INFO msg="bootstrapping state" hasInternet=true Feb 26 20:36:16 loe volumio[1224]: verbose: New Socket.io Connection to 192.168.178.245 from 192.168.178.147 UA: Mozilla/5.0 (Linux; Android 16; SM-A566B Build/BP2A.250605.031.A3; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/145.0.7632.79 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 7 Feb 26 20:36:16 loe volumio[1224]: info: Received Get System Info Feb 26 20:36:16 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Feb 26 20:36:16 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Feb 26 20:36:16 loe volumio[1224]: info: Discovery: Getting this device information Feb 26 20:36:16 loe volumio[1224]: info: CoreCommandRouter::volumioGetState Feb 26 20:36:16 loe volumio[1224]: info: CorePlayQueue::getTrack 0 Feb 26 20:36:16 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 26 20:36:17 loe volumio[1224]: error: MPD error: The expression evaluated to a falsy value: Feb 26 20:36:17 loe volumio[1224]: assert.ok(self.idling) Feb 26 20:36:17 loe volumio[1224]: error: The expression evaluated to a falsy value: Feb 26 20:36:17 loe volumio[1224]: assert.ok(self.idling) Feb 26 20:36:17 loe volumio[1224]: info: MPD running with PID1597 Feb 26 20:36:17 loe volumio[1224]: ,establishing connection Feb 26 20:36:17 loe volumio[1224]: info: Starting Shairport Sync Feb 26 20:36:17 loe volumio[1224]: info: Starting Shairport Sync Feb 26 20:36:17 loe volumio[1224]: info: Starting Shairport Sync Feb 26 20:36:17 loe sudo[1695]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Feb 26 20:36:17 loe sudo[1695]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 26 20:36:17 loe volumio[1224]: info: An error occurred while refreshing Spotify Token Error: Bad Request Feb 26 20:36:17 loe sudo[1697]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Feb 26 20:36:17 loe sudo[1697]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 26 20:36:17 loe sudo[1699]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Feb 26 20:36:17 loe sudo[1699]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 26 20:36:17 loe sudo[1701]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Feb 26 20:36:17 loe systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Feb 26 20:36:17 loe volumio-remote-updater[729]: Test mode disabled Feb 26 20:36:17 loe volumio-remote-updater[729]: Alpha mode disabled Feb 26 20:36:17 loe volumio-remote-updater[729]: Alpha legacy test mode disabled Feb 26 20:36:17 loe systemd[1]: shairport-sync.service: Deactivated successfully. Feb 26 20:36:17 loe systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Feb 26 20:36:17 loe systemd[1]: shairport-sync.service: Consumed 1.684s CPU time. Feb 26 20:36:17 loe sudo[1701]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 26 20:36:17 loe volumio[1224]: error: updateQueue error: null Feb 26 20:36:17 loe volumio[1224]: verbose: New Socket.io Connection to 192.168.178.245 from 192.168.178.147 UA: Mozilla/5.0 (Linux; Android 16; SM-A566B Build/BP2A.250605.031.A3; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/145.0.7632.79 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 8 Feb 26 20:36:17 loe systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Feb 26 20:36:17 loe sudo[1699]: pam_unix(sudo:session): session closed for user root Feb 26 20:36:17 loe volumio[1224]: info: Update Ready: {"changeLogLink":"","description":"You're already on the latest version","title":"No Updates Available","updateavailable":false} Feb 26 20:36:17 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache Feb 26 20:36:17 loe sudo[1697]: pam_unix(sudo:session): session closed for user root Feb 26 20:36:17 loe sudo[1695]: pam_unix(sudo:session): session closed for user root Feb 26 20:36:17 loe systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Feb 26 20:36:17 loe systemd[1]: shairport-sync.service: Deactivated successfully. Feb 26 20:36:17 loe systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Feb 26 20:36:17 loe systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Feb 26 20:36:17 loe volumio[1224]: error: updateQueue error: null Feb 26 20:36:17 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Feb 26 20:36:17 loe sudo[1701]: pam_unix(sudo:session): session closed for user root Feb 26 20:36:17 loe volumio[1224]: info: Upmpdcli Daemon Started Feb 26 20:36:17 loe volumio[1224]: info: Shairport-Sync Started Feb 26 20:36:17 loe volumio[1224]: Error adding Membership: Error: addMembership EINVAL Feb 26 20:36:17 loe volumio[1224]: info: Shairport-Sync Started Feb 26 20:36:17 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Feb 26 20:36:17 loe volumio[1224]: info: Shairport-Sync Started Feb 26 20:36:17 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Feb 26 20:36:17 loe volumio[1224]: info: CoreCommandRouter::volumioGetState Feb 26 20:36:17 loe volumio[1224]: info: CorePlayQueue::getTrack 0 Feb 26 20:36:17 loe volumio[1224]: info: Received Get System Info Feb 26 20:36:17 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Feb 26 20:36:17 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Feb 26 20:36:17 loe volumio[1224]: info: Discovery: Getting this device information Feb 26 20:36:17 loe volumio[1224]: info: CoreCommandRouter::volumioGetState Feb 26 20:36:17 loe volumio[1224]: info: CorePlayQueue::getTrack 0 Feb 26 20:36:17 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 26 20:36:17 loe volumio[1224]: info: CoreCommandRouter::volumioGetState Feb 26 20:36:17 loe volumio[1224]: info: CorePlayQueue::getTrack 0 Feb 26 20:36:17 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Feb 26 20:36:17 loe volumio[1224]: info: CoreCommandRouter::volumioGetVisibleSources Feb 26 20:36:17 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 26 20:36:17 loe volumio[1224]: info: CoreCommandRouter::volumioGetState Feb 26 20:36:17 loe volumio[1224]: info: CorePlayQueue::getTrack 0 Feb 26 20:36:17 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Feb 26 20:36:17 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Feb 26 20:36:17 loe volumio[1224]: info: Received Get System Info Feb 26 20:36:17 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Feb 26 20:36:17 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Feb 26 20:36:17 loe volumio[1224]: info: Discovery: Getting this device information Feb 26 20:36:17 loe volumio[1224]: info: CoreCommandRouter::volumioGetState Feb 26 20:36:17 loe volumio[1224]: info: CorePlayQueue::getTrack 0 Feb 26 20:36:17 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 26 20:36:17 loe volumio[1224]: info: CoreCommandRouter::volumioGetState Feb 26 20:36:17 loe volumio[1224]: info: CorePlayQueue::getTrack 0 Feb 26 20:36:17 loe volumio[1224]: info: Listing playlists Feb 26 20:36:17 loe volumio[1224]: info: CoreCommandRouter::volumioGetQueue Feb 26 20:36:17 loe volumio[1224]: info: CoreStateMachine::getQueue Feb 26 20:36:17 loe volumio[1224]: info: CorePlayQueue::getQueue Feb 26 20:36:19 loe volumio[1224]: info: go-librespot daemon successfully initialized Feb 26 20:36:20 loe go-librespot[1650]: time="2026-02-26T20:36:20+01:00" level=fatal msg="failed running with username and spotify token" error="failed obtaining client token: invalid status code from clienttoken: 503" Feb 26 20:36:20 loe systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 26 20:36:20 loe systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 26 20:36:21 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Feb 26 20:36:21 loe volumio[1224]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Feb 26 20:36:22 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Feb 26 20:36:22 loe volumio[1224]: info: Initializing connection to go-librespot Websocket Feb 26 20:36:22 loe volumio[1224]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 26 20:36:23 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Feb 26 20:36:23 loe systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Feb 26 20:36:23 loe systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 26 20:36:24 loe systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 26 20:36:24 loe go-librespot[1739]: go-librespot daemon starting... Feb 26 20:36:24 loe go-librespot[1740]: time="2026-02-26T20:36:24+01:00" level=info msg="running go-librespot 0.4.0" Feb 26 20:36:24 loe go-librespot[1740]: time="2026-02-26T20:36:24+01:00" level=debug msg="app state loaded" Feb 26 20:36:24 loe go-librespot[1740]: time="2026-02-26T20:36:24+01:00" level=info msg="api server listening on 127.0.0.1:9879" Feb 26 20:36:24 loe go-librespot[1740]: time="2026-02-26T20:36:24+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Feb 26 20:36:24 loe go-librespot[1740]: time="2026-02-26T20:36:24+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Feb 26 20:36:24 loe go-librespot[1740]: time="2026-02-26T20:36:24+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Feb 26 20:36:24 loe go-librespot[1740]: time="2026-02-26T20:36:24+01:00" level=info msg="zeroconf server listening on port 34089" Feb 26 20:36:24 loe go-librespot[1740]: time="2026-02-26T20:36:24+01:00" level=debug msg="obtained new client token: AADCpnTVcyUDo41lddUL5RqFRmaWPWRZxyI0yaCJw9/U6m2TZVO5Lp7FtFxLVBPJlu7qEB6Hu4RUR+lz/OLzeS61WLk6JG1UOde4Gp9xWPr+L9VGb8aYmheBOWVN5IaYWFYyYyQGviBancYH4TOzskpBgguoItnXcqsSpLrl0mEOJyhp4PW0lkS7/8U13AZne/aasxNLFFxLkFLJQaYNH3NnCHuoawcIebKE1AWQ+YqWeUJq+4PM2uHh7g==" Feb 26 20:36:24 loe go-librespot[1740]: time="2026-02-26T20:36:24+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Feb 26 20:36:24 loe volumio[1224]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Feb 26 20:36:24 loe volumio[1224]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Feb 26 20:36:24 loe volumio[1224]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Feb 26 20:36:24 loe volumio[1224]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Feb 26 20:36:24 loe volumio[1224]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Feb 26 20:36:24 loe volumio[1224]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Feb 26 20:36:24 loe volumio[1224]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Feb 26 20:36:24 loe volumio[1224]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Feb 26 20:36:24 loe volumio[1224]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Feb 26 20:36:24 loe volumio[1224]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Feb 26 20:36:24 loe volumio[1224]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Feb 26 20:36:24 loe volumio[1224]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Feb 26 20:36:24 loe volumio[1224]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Feb 26 20:36:24 loe volumio[1224]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Feb 26 20:36:24 loe volumio[1224]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Feb 26 20:36:24 loe volumio[1224]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Feb 26 20:36:24 loe volumio[1224]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Feb 26 20:36:24 loe volumio[1224]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Feb 26 20:36:24 loe volumio[1224]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Feb 26 20:36:24 loe volumio[1224]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Feb 26 20:36:24 loe volumio[1224]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Feb 26 20:36:24 loe volumio[1224]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Feb 26 20:36:24 loe volumio[1224]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Feb 26 20:36:24 loe volumio[1224]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Feb 26 20:36:24 loe volumio[1224]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Feb 26 20:36:24 loe volumio[1224]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Feb 26 20:36:24 loe volumio[1224]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Feb 26 20:36:24 loe volumio[1224]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Feb 26 20:36:24 loe volumio[1224]: info: Adding plugin bluetooth to MyMusic Plugins Feb 26 20:36:24 loe volumio[1224]: info: Adding plugin multiroom to MyMusic Plugins Feb 26 20:36:24 loe volumio[1224]: info: Adding plugin metavolumio to MyMusic Plugins Feb 26 20:36:24 loe volumio[1224]: info: Adding plugin cd_controller to MyMusic Plugins Feb 26 20:36:24 loe volumio[1224]: info: Adding plugin qobuzconnect to MyMusic Plugins Feb 26 20:36:24 loe volumio[1224]: info: Adding plugin smart_inputs to MyMusic Plugins Feb 26 20:36:24 loe volumio[1224]: info: Adding plugin tidalconnect to MyMusic Plugins Feb 26 20:36:24 loe volumio[1224]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Feb 26 20:36:25 loe go-librespot[1740]: time="2026-02-26T20:36:25+01:00" level=debug msg="completed keyexchange" Feb 26 20:36:25 loe go-librespot[1740]: time="2026-02-26T20:36:25+01:00" level=debug msg="completed challenge" Feb 26 20:36:25 loe go-librespot[1740]: time="2026-02-26T20:36:25+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Feb 26 20:36:25 loe systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 26 20:36:25 loe systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 26 20:36:28 loe volumio[1224]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Feb 26 20:36:28 loe volumio[1224]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Feb 26 20:36:28 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 26 20:36:28 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 26 20:36:28 loe volumio[1224]: info: Starting MyVolumio Remote Streaming Endpoints Feb 26 20:36:28 loe volumio[1224]: info: MyVolumio login type: Token Feb 26 20:36:28 loe systemd[1]: Starting setdatetime-helper.service - Time Synchronization Helper Service... Feb 26 20:36:28 loe volumio[1224]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Feb 26 20:36:28 loe volumio[1224]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Feb 26 20:36:28 loe systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Feb 26 20:36:28 loe systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 26 20:36:28 loe systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 26 20:36:28 loe go-librespot[1759]: go-librespot daemon starting... Feb 26 20:36:28 loe go-librespot[1760]: time="2026-02-26T20:36:28+01:00" level=info msg="running go-librespot 0.4.0" Feb 26 20:36:28 loe go-librespot[1760]: time="2026-02-26T20:36:28+01:00" level=debug msg="app state loaded" Feb 26 20:36:28 loe go-librespot[1760]: time="2026-02-26T20:36:28+01:00" level=info msg="api server listening on 127.0.0.1:9879" Feb 26 20:36:28 loe go-librespot[1760]: time="2026-02-26T20:36:28+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Feb 26 20:36:28 loe go-librespot[1760]: time="2026-02-26T20:36:28+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Feb 26 20:36:28 loe go-librespot[1760]: time="2026-02-26T20:36:28+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Feb 26 20:36:28 loe go-librespot[1760]: time="2026-02-26T20:36:28+01:00" level=info msg="zeroconf server listening on port 41649" Feb 26 20:36:28 loe go-librespot[1760]: time="2026-02-26T20:36:28+01:00" level=debug msg="obtained new client token: AACdA+gKIwDiNJRO+QF8MCtVeZvV3KXYf9zC9Ciy6+VWqv07g8sbEjMS8Bk+azV72xI5K4v3BsH8vq43gbYteepHHdrWsO3hLRvu/0aJLyPkSW/QrJOuM4PGUU3M41xSNucWMXMRPQQV3PFllCHgJ9oft8vbO+2E/NnugoHUVEx0ECVKUejL2QBd/c5X4mmeQXUoY77pzwAzp3IwhBvMfzbjZM446BFCEy6sND9HRFvER7euv/lFoAyTNA==" Feb 26 20:36:28 loe go-librespot[1760]: time="2026-02-26T20:36:28+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Feb 26 20:36:28 loe go-librespot[1760]: time="2026-02-26T20:36:28+01:00" level=debug msg="completed keyexchange" Feb 26 20:36:28 loe go-librespot[1760]: time="2026-02-26T20:36:28+01:00" level=debug msg="completed challenge" Feb 26 20:36:28 loe go-librespot[1760]: time="2026-02-26T20:36:28+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Feb 26 20:36:28 loe systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 26 20:36:28 loe systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 26 20:36:29 loe systemd[1]: setdatetime-helper.service: Deactivated successfully. Feb 26 20:36:29 loe systemd[1]: Finished setdatetime-helper.service - Time Synchronization Helper Service. Feb 26 20:36:31 loe volumio[1224]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Feb 26 20:36:31 loe volumio[1224]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Feb 26 20:36:31 loe volumio[1224]: info: Streaming services startup Feb 26 20:36:31 loe volumio[1224]: info: Starting Streaming Daemon Feb 26 20:36:31 loe volumio[1224]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Feb 26 20:36:31 loe volumio[1224]: info: Initializing connection to go-librespot Websocket Feb 26 20:36:31 loe sudo[1796]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Feb 26 20:36:31 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Feb 26 20:36:31 loe volumio[1224]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 26 20:36:31 loe sudo[1796]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 26 20:36:31 loe sudo[1796]: pam_unix(sudo:session): session closed for user root Feb 26 20:36:31 loe volumio[1224]: error: Cannot start Volumio Streaming Daemon Feb 26 20:36:31 loe volumio[1224]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Feb 26 20:36:31 loe volumio[1224]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Feb 26 20:36:31 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Feb 26 20:36:32 loe volumio[1224]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Feb 26 20:36:32 loe systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Feb 26 20:36:32 loe systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 26 20:36:32 loe systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 26 20:36:32 loe go-librespot[1801]: go-librespot daemon starting... Feb 26 20:36:32 loe go-librespot[1802]: time="2026-02-26T20:36:32+01:00" level=info msg="running go-librespot 0.4.0" Feb 26 20:36:32 loe go-librespot[1802]: time="2026-02-26T20:36:32+01:00" level=debug msg="app state loaded" Feb 26 20:36:32 loe go-librespot[1802]: time="2026-02-26T20:36:32+01:00" level=info msg="api server listening on 127.0.0.1:9879" Feb 26 20:36:32 loe go-librespot[1802]: time="2026-02-26T20:36:32+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Feb 26 20:36:32 loe go-librespot[1802]: time="2026-02-26T20:36:32+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Feb 26 20:36:32 loe go-librespot[1802]: time="2026-02-26T20:36:32+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Feb 26 20:36:32 loe go-librespot[1802]: time="2026-02-26T20:36:32+01:00" level=info msg="zeroconf server listening on port 40793" Feb 26 20:36:32 loe go-librespot[1802]: time="2026-02-26T20:36:32+01:00" level=debug msg="obtained new client token: AABVenBJNjPvYQDhm5BcqCO6ZHoJLEUJbrRJZZJK/TsidNrX+76N3DG13tVcNq3tGAhqDXvXsq1hJ5FEbO7Mcq2UzDPn/qYnYKgDP9s6DY/6ptnQ1QXGGlByKzNYzLi6nv8Iw1n9GUQdbifJB6vKH9UFLwBD7n+QYWsiNqDicVlFb/l0rtG2VXl5D8zZtyaDVGjtkCxaVcIG20mT9BdaoMYT7hArLQTKzthF7vfj7UeViO8zCpU2hSBqzg==" Feb 26 20:36:32 loe volumio[1224]: info: MyVolumio token set successfully Feb 26 20:36:32 loe volumio[1224]: info: MYVOLUMIO: Adding device Feb 26 20:36:32 loe volumio[1224]: info: MYVOLUMIO: Evaluating Server Feb 26 20:36:32 loe go-librespot[1802]: time="2026-02-26T20:36:32+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Feb 26 20:36:32 loe go-librespot[1802]: time="2026-02-26T20:36:32+01:00" level=debug msg="completed keyexchange" Feb 26 20:36:32 loe go-librespot[1802]: time="2026-02-26T20:36:32+01:00" level=debug msg="completed challenge" Feb 26 20:36:32 loe go-librespot[1802]: time="2026-02-26T20:36:32+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Feb 26 20:36:32 loe systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 26 20:36:32 loe systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 26 20:36:33 loe volumio[1224]: info: MyVolumio Plan changed: premium Feb 26 20:36:33 loe volumio[1224]: info: [MyVolumio PluginManager] Subscribed plan changed to premium Feb 26 20:36:33 loe volumio[1224]: info: Removing browser output: myVolumio user plan is not superstar Feb 26 20:36:33 loe volumio[1224]: info: Removing audio output: Feb 26 20:36:33 loe volumio[1224]: info: MYVOLUMIO: Adding device Feb 26 20:36:33 loe volumio[1224]: info: MYVOLUMIO: Evaluating Server Feb 26 20:36:33 loe volumio[1224]: info: Remote config written successfully Feb 26 20:36:33 loe volumio[1224]: info: Starting Tunnel 1 Feb 26 20:36:33 loe volumio[1224]: info: Starting Tunnel Connection Checker Feb 26 20:36:33 loe volumio[1224]: info: Completed starting MyVolumio Plugin Feb 26 20:36:34 loe volumio[1224]: info: MYVolumio Device enabled Feb 26 20:36:34 loe volumio[1224]: info: [MyVolumio PluginManager] Device activated, enabling myvolumio plugins... Feb 26 20:36:34 loe volumio[1224]: info: MyVolumio status changed Feb 26 20:36:34 loe volumio[1224]: info: Streaming services startup Feb 26 20:36:34 loe volumio[1224]: info: Starting Streaming Daemon Feb 26 20:36:34 loe sudo[1848]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Feb 26 20:36:34 loe sudo[1848]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 26 20:36:34 loe volumio[1224]: info: Setting Geolocation for MyVolumio to eu8 Feb 26 20:36:34 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 26 20:36:34 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 26 20:36:34 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 26 20:36:34 loe sudo[1848]: pam_unix(sudo:session): session closed for user root Feb 26 20:36:34 loe volumio[1224]: error: Cannot start Volumio Streaming Daemon Feb 26 20:36:34 loe volumio[1224]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Feb 26 20:36:34 loe volumio[1224]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Feb 26 20:36:34 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getHwuuid Feb 26 20:36:34 loe volumio[1224]: info: [MyVolumio PluginManager] Loading plugin "bluetooth"... Feb 26 20:36:35 loe volumio[1224]: ------------------------------------ BT MESSAGE: [FUNC] onVolumioStart Feb 26 20:36:35 loe volumio[1224]: info: [MyVolumio PluginManager] Loading plugin "multiroom"... Feb 26 20:36:35 loe systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 4. Feb 26 20:36:35 loe systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 26 20:36:35 loe systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 26 20:36:35 loe go-librespot[1852]: go-librespot daemon starting... Feb 26 20:36:36 loe go-librespot[1853]: time="2026-02-26T20:36:36+01:00" level=info msg="running go-librespot 0.4.0" Feb 26 20:36:36 loe go-librespot[1853]: time="2026-02-26T20:36:36+01:00" level=debug msg="app state loaded" Feb 26 20:36:36 loe go-librespot[1853]: time="2026-02-26T20:36:36+01:00" level=info msg="api server listening on 127.0.0.1:9879" Feb 26 20:36:36 loe go-librespot[1853]: time="2026-02-26T20:36:36+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Feb 26 20:36:36 loe go-librespot[1853]: time="2026-02-26T20:36:36+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Feb 26 20:36:36 loe go-librespot[1853]: time="2026-02-26T20:36:36+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Feb 26 20:36:36 loe go-librespot[1853]: time="2026-02-26T20:36:36+01:00" level=info msg="zeroconf server listening on port 46493" Feb 26 20:36:36 loe go-librespot[1853]: time="2026-02-26T20:36:36+01:00" level=debug msg="obtained new client token: AADBIeolAxNeFDyvFbhXIpkBazP3FbpQSGBeaLR4Z4JiERNU7g5614O6q4oh31+K9d0Q4dIcq8zs30DS7MWhwy5XCjqQmuLeYL3LXW8Umal9jA3ZUdU1ie2ULk200R+pxCpnxQYiaVodVUTu3qf1T1sOswwzb1AFvNMOwKmCY/tD0QI9ASGSfDN3rq8eDBko/tDoj9zGE76QCXJA9HjGg51Nw0+LvZvG0Bt9RqafAbN56ClmPXIlMVuszg==" Feb 26 20:36:36 loe go-librespot[1853]: time="2026-02-26T20:36:36+01:00" level=warning msg="failed to connect to AP ap-gew4.spotify.com:4070, retrying with a different AP" error="dial tcp 34.158.1.133:4070: connect: connection refused" Feb 26 20:36:36 loe go-librespot[1853]: time="2026-02-26T20:36:36+01:00" level=debug msg="connected to ap-gew4.spotify.com:443" Feb 26 20:36:36 loe go-librespot[1853]: time="2026-02-26T20:36:36+01:00" level=debug msg="completed keyexchange" Feb 26 20:36:36 loe go-librespot[1853]: time="2026-02-26T20:36:36+01:00" level=debug msg="completed challenge" Feb 26 20:36:36 loe go-librespot[1853]: time="2026-02-26T20:36:36+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Feb 26 20:36:36 loe systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 26 20:36:36 loe systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 26 20:36:38 loe volumio[1224]: info: [MyVolumio PluginManager] Applying required configuration parameters for plugin multiroom Feb 26 20:36:39 loe sudo[1862]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/rm -rf /tmp/multiroom Feb 26 20:36:39 loe sudo[1862]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 26 20:36:39 loe sudo[1862]: pam_unix(sudo:session): session closed for user root Feb 26 20:36:39 loe volumio[1224]: info: MRS: MultiRoom plugin initialized Feb 26 20:36:39 loe volumio[1224]: info: MRS: STOPPING SNAPCLIENT Feb 26 20:36:39 loe volumio[1224]: info: MRS: Snap server stop Feb 26 20:36:39 loe volumio[1224]: info: MRS: STOPPING volumioStreaming Feb 26 20:36:39 loe sudo[1880]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop volumioSnapserver Feb 26 20:36:39 loe sudo[1880]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 26 20:36:39 loe sudo[1881]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop volumioSnapclient Feb 26 20:36:39 loe sudo[1881]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 26 20:36:39 loe sudo[1883]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop volumioStreaming Feb 26 20:36:39 loe volumio[1224]: info: [MyVolumio PluginManager] Loading plugin "metavolumio"... Feb 26 20:36:39 loe sudo[1883]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 26 20:36:39 loe sudo[1886]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/rm -f /tmp/hls/* Feb 26 20:36:39 loe sudo[1886]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 26 20:36:39 loe volumio[1224]: info: [MyVolumio PluginManager] Loading plugin "manifestui"... Feb 26 20:36:39 loe sudo[1880]: pam_unix(sudo:session): session closed for user root Feb 26 20:36:39 loe volumio[1224]: info: [MyVolumio PluginManager] Loading plugin "cd_controller"... Feb 26 20:36:39 loe sudo[1881]: pam_unix(sudo:session): session closed for user root Feb 26 20:36:39 loe sudo[1886]: pam_unix(sudo:session): session closed for user root Feb 26 20:36:39 loe systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 5. Feb 26 20:36:39 loe systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 26 20:36:39 loe volumio[1224]: info: [MyVolumio PluginManager] Loading plugin "smart_inputs"... Feb 26 20:36:39 loe volumio[1224]: info: [MyVolumio PluginManager] Loading plugin "hi_res_audio"... Feb 26 20:36:39 loe volumio[1224]: info: [MyVolumio PluginManager] Applying required configuration parameters for plugin hi_res_audio Feb 26 20:36:39 loe volumio[1224]: info: [MyVolumio PluginManager] Loading plugin "tidal"... Feb 26 20:36:39 loe systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 26 20:36:39 loe go-librespot[1890]: go-librespot daemon starting... Feb 26 20:36:39 loe sudo[1883]: pam_unix(sudo:session): session closed for user root Feb 26 20:36:39 loe go-librespot[1891]: time="2026-02-26T20:36:39+01:00" level=info msg="running go-librespot 0.4.0" Feb 26 20:36:39 loe go-librespot[1891]: time="2026-02-26T20:36:39+01:00" level=debug msg="app state loaded" Feb 26 20:36:39 loe go-librespot[1891]: time="2026-02-26T20:36:39+01:00" level=info msg="api server listening on 127.0.0.1:9879" Feb 26 20:36:39 loe volumio[1224]: info: [MyVolumio PluginManager] Loading plugin "qobuz"... Feb 26 20:36:39 loe volumio[1224]: info: [MyVolumio PluginManager] Loading plugin "tidalconnect"... Feb 26 20:36:40 loe volumio[1224]: info: [MyVolumio PluginManager] Loading plugin "qobuzconnect"... Feb 26 20:36:40 loe go-librespot[1891]: time="2026-02-26T20:36:40+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Feb 26 20:36:40 loe go-librespot[1891]: time="2026-02-26T20:36:40+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Feb 26 20:36:40 loe go-librespot[1891]: time="2026-02-26T20:36:40+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Feb 26 20:36:40 loe go-librespot[1891]: time="2026-02-26T20:36:40+01:00" level=info msg="zeroconf server listening on port 45089" Feb 26 20:36:40 loe volumio[1224]: info: Preparing to generate the ALSA configuration file Feb 26 20:36:40 loe go-librespot[1891]: time="2026-02-26T20:36:40+01:00" level=debug msg="obtained new client token: AADqe0jJ5uGEBG6g50ugUxHFEacic0DRHmRPULlfplYXYH0DYjTri3dunNHVBLpk64mVa/LBU5HhKDIZ+EhqK1USpMWuhDGviw8YNbftC2vWEuVF/xkXGxZduQOWS5hB5k9hAfex1r+Ia8Zu6cTuBhyXgqN8WEzPoi+cxKT/wfi3j+6EByeqCEnyvZ7InifldIAMoiS3ZA2k25vhNFzym3Zja66ICYu2XPLi7yxvhokZ04MIf+ez/Qs=" Feb 26 20:36:40 loe go-librespot[1891]: time="2026-02-26T20:36:40+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Feb 26 20:36:40 loe go-librespot[1891]: time="2026-02-26T20:36:40+01:00" level=debug msg="completed keyexchange" Feb 26 20:36:40 loe go-librespot[1891]: time="2026-02-26T20:36:40+01:00" level=debug msg="completed challenge" Feb 26 20:36:40 loe volumio[1224]: info: Initializing connection to go-librespot Websocket Feb 26 20:36:40 loe volumio[1224]: info: Updating MyVolumio device info Feb 26 20:36:40 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 26 20:36:40 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 26 20:36:40 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 26 20:36:40 loe go-librespot[1891]: time="2026-02-26T20:36:40+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Feb 26 20:36:40 loe systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 26 20:36:40 loe systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 26 20:36:40 loe volumio[1224]: info: The plugin multiroom has an ALSA contribution file volumioMultiRoomServer.postMultiRoom.1000.conf Feb 26 20:36:40 loe volumio[1224]: info: Reading ALSA contributions from plugins. Feb 26 20:36:40 loe volumio[1224]: info: Successfully Added MyVolumio device Feb 26 20:36:40 loe volumio[1224]: info: Setting Geolocation for MyVolumio to eu8 Feb 26 20:36:40 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 26 20:36:40 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 26 20:36:40 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 26 20:36:40 loe volumio[1224]: info: MRS: Removed streaming files Feb 26 20:36:40 loe volumio[1224]: info: MRS: volumioStreaming STOPPED Feb 26 20:36:40 loe volumio[1224]: info: MRS: SNAPSERVER STOPPED Feb 26 20:36:40 loe volumio[1224]: info: MRS: SNAPCLIENT STOPPED Feb 26 20:36:40 loe volumio[1224]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 26 20:36:40 loe sudo[1920]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart sshtunnel.service Feb 26 20:36:40 loe sudo[1920]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 26 20:36:41 loe volumio[1224]: info: Asound.conf file written Feb 26 20:36:41 loe sudo[1924]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mv /home/volumio/.asoundrc /etc/asound.conf Feb 26 20:36:41 loe sudo[1924]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 26 20:36:41 loe systemd[1]: Starting e2scrub_all.service - Online ext4 Metadata Check for All Filesystems... Feb 26 20:36:41 loe 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. Feb 26 20:36:41 loe 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. Feb 26 20:36:41 loe systemd[1]: e2scrub_all.service: Deactivated successfully. Feb 26 20:36:41 loe sudo[1924]: pam_unix(sudo:session): session closed for user root Feb 26 20:36:41 loe systemd[1]: Finished e2scrub_all.service - Online ext4 Metadata Check for All Filesystems. Feb 26 20:36:41 loe systemd[1]: Started sshtunnel.service - MyVolumio SSH Tunnel. Feb 26 20:36:41 loe sudo[1920]: pam_unix(sudo:session): session closed for user root Feb 26 20:36:41 loe autossh[1930]: port set to 0, monitoring disabled Feb 26 20:36:41 loe autossh[1930]: starting ssh (count 1) Feb 26 20:36:41 loe autossh[1930]: ssh child pid is 1934 Feb 26 20:36:41 loe volumio[1224]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:0 use case configuration -2 Feb 26 20:36:41 loe volumio[1224]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:1 use case configuration -2 Feb 26 20:36:41 loe volumio[1224]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:2 use case configuration -2 Feb 26 20:36:41 loe volumio[1224]: No state is present for card vc4hdmi0 Feb 26 20:36:41 loe volumio[1224]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:2 use case configuration -2 Feb 26 20:36:41 loe volumio[1224]: Found hardware: "vc4-hdmi" "" "" "" "" Feb 26 20:36:41 loe volumio[1224]: Hardware is initialized using a generic method Feb 26 20:36:41 loe volumio[1224]: No state is present for card vc4hdmi0 Feb 26 20:36:41 loe volumio[1224]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:3 use case configuration -2 Feb 26 20:36:41 loe volumio[1224]: No state is present for card vc4hdmi1 Feb 26 20:36:41 loe volumio[1224]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:3 use case configuration -2 Feb 26 20:36:41 loe volumio[1224]: Found hardware: "vc4-hdmi" "" "" "" "" Feb 26 20:36:41 loe volumio[1224]: Hardware is initialized using a generic method Feb 26 20:36:41 loe volumio[1224]: No state is present for card vc4hdmi1 Feb 26 20:36:41 loe volumio[1224]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:4 use case configuration -2 Feb 26 20:36:41 loe volumio[1224]: info: Output device has changed, restarting MPD Feb 26 20:36:41 loe volumio[1224]: info: Output device has changed, restarting Shairport Sync Feb 26 20:36:41 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 26 20:36:41 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 26 20:36:41 loe sudo[1936]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Feb 26 20:36:41 loe sudo[1936]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 26 20:36:41 loe sudo[1938]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Feb 26 20:36:41 loe volumio[1224]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Feb 26 20:36:41 loe volumio[1224]: info: MRS: Audio Device Changed, rebuilding Multiroom Configuration Feb 26 20:36:41 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 26 20:36:41 loe volumiossh-tunnel[1934]: Warning: Permanently added '[eu8.myvolumio.org]:2222' (RSA) to the list of known hosts. Feb 26 20:36:41 loe sudo[1936]: pam_unix(sudo:session): session closed for user root Feb 26 20:36:41 loe sudo[1938]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 26 20:36:41 loe volumio[1224]: info: [MyVolumio PluginManager] Starting plugin audio_interface.bluetooth Feb 26 20:36:41 loe volumio[1224]: ------------------------------------ BT MESSAGE: [FUNC] onStart Feb 26 20:36:41 loe volumio[1224]: ------------------------------------ BT MESSAGE: Starting Volumio Bluetooth Service Feb 26 20:36:41 loe volumio[1224]: ------------------------------------ BT MESSAGE: Boot config /etc/bluetooth/volumio.conf: cache mode = tmp Feb 26 20:36:41 loe systemd[1]: Stopping mpd.service - Music Player Daemon... Feb 26 20:36:41 loe upmpdcli[1669]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Feb 26 20:36:41 loe volumio[1224]: ------------------------------------ BT MESSAGE: [metaCache] Created directory: /tmp/bluetooth-cache/ Feb 26 20:36:41 loe volumio[1224]: ------------------------------------ BT MESSAGE: [metaCache] Directory exists and is ready. Feb 26 20:36:41 loe volumio[1224]: info: [MyVolumio PluginManager] Starting plugin audio_interface.multiroom Feb 26 20:36:41 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , pushMultiRoomStatus Feb 26 20:36:41 loe volumio[1224]: info: MRS: Pushing multiroomSync output for this device Feb 26 20:36:41 loe volumio[1224]: info: MRS: Pushing multiroomSync output Feb 26 20:36:41 loe volumio[1224]: info: Adding audio output: Feb 26 20:36:41 loe volumio[1224]: info: Adding audio output: Feb 26 20:36:41 loe bluetoothd[863]: Path / reserved for Adv Monitor app :1.21 Feb 26 20:36:41 loe volumio[1224]: info: MRS: Audio Device Changed, rebuilding Multiroom Configuration Feb 26 20:36:41 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 26 20:36:41 loe volumio[1224]: info: [MyVolumio PluginManager] Starting plugin miscellanea.metavolumio Feb 26 20:36:41 loe systemd[1]: mpd.service: Deactivated successfully. Feb 26 20:36:41 loe systemd[1]: Stopped mpd.service - Music Player Daemon. Feb 26 20:36:41 loe systemd[1]: mpd.service: Consumed 3.075s CPU time. Feb 26 20:36:41 loe volumio[1224]: info: Adding METAVOLUMIO REST API Endpoints Feb 26 20:36:41 loe volumio[1224]: info: Adding metavolumio REST Endpoint for plugin: miscellanea/metavolumio Feb 26 20:36:41 loe volumio[1224]: info: Adding getSimilarArtists REST Endpoint for plugin: miscellanea/metavolumio Feb 26 20:36:41 loe volumio[1224]: info: Adding getSimilarAlbums REST Endpoint for plugin: miscellanea/metavolumio Feb 26 20:36:41 loe volumio[1224]: info: Adding getSimilarTracks REST Endpoint for plugin: miscellanea/metavolumio Feb 26 20:36:41 loe systemd[1]: mpd.socket: Deactivated successfully. Feb 26 20:36:41 loe systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Feb 26 20:36:41 loe systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Feb 26 20:36:41 loe bluetoothd[863]: Adv Monitor app :1.21 disconnected from D-Bus Feb 26 20:36:41 loe volumio[1224]: info: [MyVolumio PluginManager] Starting plugin miscellanea.manifestui Feb 26 20:36:41 loe volumio[1224]: info: [MyVolumio PluginManager] Starting plugin music_service.cd_controller Feb 26 20:36:41 loe volumio[1224]: info: Preparing CD Folders Feb 26 20:36:41 loe volumio[1224]: info: Adding CD REST API Endpoints Feb 26 20:36:41 loe volumio[1224]: info: Adding cdPostRip REST Endpoint for plugin: music_service/cd_controller Feb 26 20:36:41 loe volumio[1224]: info: Starting UDEV Watcher for CD Feb 26 20:36:41 loe volumio[1224]: info: Detecting CD presence with UDEV Feb 26 20:36:41 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: networkfs , getUdevDevices Feb 26 20:36:41 loe systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Feb 26 20:36:41 loe systemd[1]: Starting mpd.service - Music Player Daemon... Feb 26 20:36:41 loe sudo[1953]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Feb 26 20:36:41 loe sudo[1953]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Feb 26 20:36:41 loe sudo[1953]: pam_unix(sudo:session): session closed for user root Feb 26 20:36:43 loe mpd[1955]: 2026-02-26T20:36:43 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Feb 26 20:36:43 loe systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6. Feb 26 20:36:43 loe systemd[1]: Started mpd.service - Music Player Daemon. Feb 26 20:36:43 loe systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 26 20:36:43 loe sudo[1938]: pam_unix(sudo:session): session closed for user root Feb 26 20:36:43 loe systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 26 20:36:43 loe go-librespot[1961]: go-librespot daemon starting... Feb 26 20:36:43 loe go-librespot[1962]: time="2026-02-26T20:36:43+01:00" level=info msg="running go-librespot 0.4.0" Feb 26 20:36:43 loe go-librespot[1962]: time="2026-02-26T20:36:43+01:00" level=debug msg="app state loaded" Feb 26 20:36:43 loe go-librespot[1962]: time="2026-02-26T20:36:43+01:00" level=info msg="api server listening on 127.0.0.1:9879" Feb 26 20:36:43 loe upmpdcli[1669]: :3:../src/mpdcli.cxx:148::MPDCli::startEventLoop: already started Feb 26 20:36:43 loe go-librespot[1962]: time="2026-02-26T20:36:43+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Feb 26 20:36:43 loe go-librespot[1962]: time="2026-02-26T20:36:43+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Feb 26 20:36:43 loe go-librespot[1962]: time="2026-02-26T20:36:43+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Feb 26 20:36:43 loe go-librespot[1962]: time="2026-02-26T20:36:43+01:00" level=info msg="zeroconf server listening on port 45293" Feb 26 20:36:43 loe go-librespot[1962]: time="2026-02-26T20:36:43+01:00" level=debug msg="obtained new client token: AAB4pjCQVaVDPmNP6/AN5R08YovAdO8RKMUhLi63ARhLZ+BoFl4QAQRZuyTk4x5qPkjireSUh1+XgyeC8Q1hbujc0/DB1fKszDArvTULMedXCBtYGeFTUL0VX2wAtyWOmfGamk/UUnmLY3CD0PhNp7ZywMmizrboCbqnBfgBjfqOKlsizsdM4LmqZrxikQXANlto+Sitdf15wwZ9vUqapmtYEcXNVnpFLvlA4hMTqKQWMCeIBOVizRtQ5g==" Feb 26 20:36:43 loe go-librespot[1962]: time="2026-02-26T20:36:43+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Feb 26 20:36:43 loe go-librespot[1962]: time="2026-02-26T20:36:43+01:00" level=debug msg="completed keyexchange" Feb 26 20:36:43 loe go-librespot[1962]: time="2026-02-26T20:36:43+01:00" level=debug msg="completed challenge" Feb 26 20:36:43 loe go-librespot[1962]: time="2026-02-26T20:36:43+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Feb 26 20:36:43 loe systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 26 20:36:43 loe systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 26 20:36:47 loe volumio[1224]: warn: [cd-plugin] cdspeedctl: device or media not ready Feb 26 20:36:47 loe volumio[1224]: info: [MyVolumio PluginManager] Starting plugin music_service.smart_inputs Feb 26 20:36:47 loe volumio[1224]: info: Adding inputs REST Endpoints Feb 26 20:36:47 loe volumio[1224]: info: Adding scanAudioInputs REST Endpoint for plugin: music_service/smart_inputs Feb 26 20:36:47 loe volumio[1224]: info: Scanning Audio Inputs Feb 26 20:36:47 loe systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 7. Feb 26 20:36:47 loe systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 26 20:36:47 loe volumio[1224]: info: Checking against Known Cards name Feb 26 20:36:47 loe volumio[1224]: info: Adding Server instance for streaming Feb 26 20:36:47 loe volumio[1224]: info: [MyVolumio PluginManager] Starting plugin music_service.hi_res_audio Feb 26 20:36:47 loe systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 26 20:36:47 loe go-librespot[1972]: go-librespot daemon starting... Feb 26 20:36:47 loe volumio[1224]: info: Adding HIGHRESAUDIO REST API Endpoints Feb 26 20:36:47 loe volumio[1224]: info: Adding saveAccountData_hi_res_audio REST Endpoint for plugin: music_service/hi_res_audio Feb 26 20:36:47 loe volumio[1224]: info: [MyVolumio PluginManager] Starting plugin music_service.tidal Feb 26 20:36:47 loe volumio[1224]: info: Refreshing TIDAL token Feb 26 20:36:47 loe volumio[1224]: info: [MyVolumio PluginManager] Starting plugin music_service.qobuz Feb 26 20:36:47 loe go-librespot[1973]: time="2026-02-26T20:36:47+01:00" level=info msg="running go-librespot 0.4.0" Feb 26 20:36:47 loe go-librespot[1973]: time="2026-02-26T20:36:47+01:00" level=debug msg="app state loaded" Feb 26 20:36:47 loe go-librespot[1973]: time="2026-02-26T20:36:47+01:00" level=info msg="api server listening on 127.0.0.1:9879" Feb 26 20:36:47 loe volumio[1224]: info: [MyVolumio PluginManager] Starting plugin music_service.tidalconnect Feb 26 20:36:47 loe volumio[1224]: info: [MyVolumio PluginManager] Starting plugin music_service.qobuzconnect Feb 26 20:36:47 loe volumio[1224]: info: Adding qc_getconfig REST Endpoint for plugin: music_service/qobuzconnect Feb 26 20:36:47 loe sudo[1980]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service Feb 26 20:36:47 loe volumio[1224]: info: QobuzConnect: Starting Qobuz Connect socket and service Feb 26 20:36:47 loe sudo[1980]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 26 20:36:47 loe go-librespot[1973]: time="2026-02-26T20:36:47+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Feb 26 20:36:47 loe go-librespot[1973]: time="2026-02-26T20:36:47+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Feb 26 20:36:47 loe go-librespot[1973]: time="2026-02-26T20:36:47+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Feb 26 20:36:47 loe volumio[1224]: info: QobuzConnect: Opened /tmp/qbz-connect.socket socket, listening for connections Feb 26 20:36:47 loe volumio[1224]: info: Stopping AccessToken refresher cron for QOBUZ Feb 26 20:36:47 loe go-librespot[1973]: time="2026-02-26T20:36:47+01:00" level=info msg="zeroconf server listening on port 45759" Feb 26 20:36:47 loe sudo[1989]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl reset-failed qobuz-connect.service Feb 26 20:36:47 loe sudo[1989]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 26 20:36:47 loe sudo[1980]: pam_unix(sudo:session): session closed for user root Feb 26 20:36:47 loe go-librespot[1973]: time="2026-02-26T20:36:47+01:00" level=debug msg="obtained new client token: AABE5f8tojPFdx4nBcxT8XHU02qxA1kFFONXiw+nriHfZnC/9fApvi/So1yCdv0mTHk1/eR2QQruyLb/vyR50LhX3fADArsLhOuNmMnWBf3B5mvd+ma0sgCxQesZoQRRoCSK2AB+7y7v2fVb3i2/nNOx2l1dMNVPkiYDKmIF8jxjJAZ2Pi8li2Ua0GndBZioLTFcfiKNLWVUoG6m/wNrkF6qT40OPmKfLodI3Fc0NGdAANdSot/YOoeEtA==" Feb 26 20:36:47 loe sudo[1989]: pam_unix(sudo:session): session closed for user root Feb 26 20:36:47 loe sudo[1992]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart qobuz-connect.service Feb 26 20:36:47 loe sudo[1992]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 26 20:36:47 loe go-librespot[1973]: time="2026-02-26T20:36:47+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Feb 26 20:36:47 loe go-librespot[1973]: time="2026-02-26T20:36:47+01:00" level=debug msg="completed keyexchange" Feb 26 20:36:47 loe go-librespot[1973]: time="2026-02-26T20:36:47+01:00" level=debug msg="completed challenge" Feb 26 20:36:47 loe go-librespot[1973]: time="2026-02-26T20:36:47+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Feb 26 20:36:47 loe systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 26 20:36:47 loe systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 26 20:36:47 loe volumio[1224]: info: AccessToken refresher cron started for QOBUZ Feb 26 20:36:47 loe volumio[1224]: info: Adding QOBUZ REST API Endpoints Feb 26 20:36:47 loe volumio[1224]: info: Updating MyVolumio device info Feb 26 20:36:47 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 26 20:36:47 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 26 20:36:47 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 26 20:36:47 loe systemd[1]: Started qobuz-connect.service - Volumio Qobuz Connect Service. Feb 26 20:36:47 loe sudo[1992]: pam_unix(sudo:session): session closed for user root Feb 26 20:36:48 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Feb 26 20:36:48 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 26 20:36:48 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Feb 26 20:36:48 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Feb 26 20:36:48 loe volumio[1224]: info: Initializing connection to go-librespot Websocket Feb 26 20:36:48 loe volumio[1224]: info: MRS: Getting audio outputs on start Feb 26 20:36:48 loe volumio[1224]: info: MRS: Requesting all other devices output Feb 26 20:36:48 loe volumio[1224]: info: Successfully Updated MyVolumio device Feb 26 20:36:48 loe volumio[1224]: info: Successfully Added MyVolumio device Feb 26 20:36:48 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Feb 26 20:36:48 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Feb 26 20:36:48 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Feb 26 20:36:48 loe volumio[1224]: ------------------------------------ BT MESSAGE: Bluetooth adapter powered on Feb 26 20:36:48 loe volumio[1224]: info: MPD Permissions set Feb 26 20:36:48 loe volumio[1224]: info: Remote SSH Started Feb 26 20:36:48 loe sudo[1999]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumiobt.service Feb 26 20:36:48 loe sudo[1999]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 26 20:36:48 loe systemd[1]: Started volumiobt.service - Volumio Bluetooth Module. Feb 26 20:36:48 loe sudo[1999]: pam_unix(sudo:session): session closed for user root Feb 26 20:36:48 loe volumiobt[2002]: INFO [BTSTART] Ensuring Bluetooth directory exists... Feb 26 20:36:48 loe sudo[2003]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/mkdir -p /var/lib/bluetooth Feb 26 20:36:48 loe sudo[2003]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 26 20:36:48 loe sudo[2003]: pam_unix(sudo:session): session closed for user root Feb 26 20:36:48 loe sudo[2005]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod -R 777 /var/lib/bluetooth Feb 26 20:36:48 loe sudo[2005]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 26 20:36:48 loe sudo[2005]: pam_unix(sudo:session): session closed for user root Feb 26 20:36:48 loe volumiobt[2007]: INFO [BTSTART] Powering on Bluetooth if needed... Feb 26 20:36:48 loe bluetoothd[863]: Path / reserved for Adv Monitor app :1.23 Feb 26 20:36:48 loe bluetoothd[863]: Adv Monitor app :1.23 disconnected from D-Bus Feb 26 20:36:48 loe volumiobt[2010]: INFO [BTSTART] Making Bluetooth discoverable and pairable... Feb 26 20:36:48 loe volumiobt[2011]: [176B blob data] Feb 26 20:36:48 loe volumiobt[2011]: [157B blob data] Feb 26 20:36:48 loe volumiobt[2011]: [157B blob data] Feb 26 20:36:48 loe volumiobt[2011]: [157B blob data] Feb 26 20:36:48 loe volumiobt[2011]: [113B blob data] Feb 26 20:36:48 loe volumiobt[2011]: [bluetoothctl]> discoverable on Feb 26 20:36:48 loe volumiobt[2011]: Warning: setting discoverable while discoverable-timeout not set(0) is not recommended Feb 26 20:36:48 loe volumiobt[2011]: [bluetoothctl]> pairable on Feb 26 20:36:48 loe bluetoothd[863]: Path / reserved for Adv Monitor app :1.24 Feb 26 20:36:48 loe bluetoothd[863]: Adv Monitor app :1.24 disconnected from D-Bus Feb 26 20:36:48 loe volumiobt[2011]: [bluetoothctl]> Feb 26 20:36:48 loe volumiobt[2012]: INFO [BTSTART] Registering Bluetooth agent... Feb 26 20:36:48 loe volumiobt[2013]: [NEW] Media /org/bluez/hci0 Feb 26 20:36:48 loe volumiobt[2013]: SupportedUUIDs: 0000110a-0000-1000-8000-00805f9b34fb Feb 26 20:36:48 loe volumiobt[2013]: SupportedUUIDs: 0000110b-0000-1000-8000-00805f9b34fb Feb 26 20:36:48 loe volumiobt[2013]: SupportedUUIDs: 0000FDF0-0000-1000-8000-00805f9b34fb Feb 26 20:36:48 loe bluetoothd[863]: Adv Monitor app :1.25 disconnected from D-Bus Feb 26 20:36:48 loe volumiobt[2014]: No agent is registered Feb 26 20:36:48 loe volumiobt[2014]: [NEW] Media /org/bluez/hci0 Feb 26 20:36:48 loe volumiobt[2014]: SupportedUUIDs: 0000110a-0000-1000-8000-00805f9b34fb Feb 26 20:36:48 loe volumiobt[2014]: SupportedUUIDs: 0000110b-0000-1000-8000-00805f9b34fb Feb 26 20:36:48 loe volumiobt[2014]: SupportedUUIDs: 0000FDF0-0000-1000-8000-00805f9b34fb Feb 26 20:36:48 loe bluetoothd[863]: Adv Monitor app :1.26 disconnected from D-Bus Feb 26 20:36:48 loe volumiobt[2015]: INFO [BTSTART] Agent registered successfully. Feb 26 20:36:48 loe volumiobt[2016]: INFO [BTSTART] Starting A2DP agent (a2dp-agent)... Feb 26 20:36:49 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 26 20:36:49 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 26 20:36:49 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam Feb 26 20:36:49 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam Feb 26 20:36:49 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Feb 26 20:36:49 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Feb 26 20:36:49 loe volumio[1224]: info: CoreCommandRouter::volumioGetBrowseSources Feb 26 20:36:49 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Feb 26 20:36:49 loe volumio-remote-updater[729]: Test mode disabled Feb 26 20:36:49 loe volumio-remote-updater[729]: Alpha mode disabled Feb 26 20:36:49 loe volumio-remote-updater[729]: Alpha legacy test mode disabled Feb 26 20:36:49 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateEnabled Feb 26 20:36:49 loe volumio[1224]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 26 20:36:49 loe volumiobt[2017]: INFO:a2dp-agent:Connecting to system bus. Feb 26 20:36:49 loe volumiobt[2017]: INFO:a2dp-agent:Found Bluetooth adapter at: /org/bluez/hci0 Feb 26 20:36:49 loe volumiobt[2017]: INFO:a2dp-agent:Enabling infinite discovery on adapter. Feb 26 20:36:49 loe volumiobt[2017]: INFO:a2dp-agent:Registering agent. Feb 26 20:36:49 loe volumiobt[2017]: INFO:a2dp-agent:Searching for MediaPlayer1 interface... Feb 26 20:36:49 loe volumiobt[2017]: WARNING:a2dp-agent:No active MediaPlayer1 found. Metadata updates won't work. Feb 26 20:36:49 loe volumio[1224]: info: Executing endpoint qc_getconfig Feb 26 20:36:49 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: qobuzconnect , onGetConfig Feb 26 20:36:49 loe volumio[1224]: ------------------------------------ BT MESSAGE: volumiobt.service started successfully Feb 26 20:36:49 loe qobuz-connect[1994]: 20260226 20:36:49.969 [1994.1994] INFO SampleApp: Started connection to /tmp/qbz-connect.socket UNIX socket Feb 26 20:36:49 loe volumio[1224]: info: CoreCommandRouter::volumioStop Feb 26 20:36:50 loe volumio[1224]: info: CoreStateMachine::stop Feb 26 20:36:50 loe volumio[1224]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 26 20:36:50 loe volumio[1224]: ------------------------------------ BT MESSAGE: [FUNC] dbusStart Feb 26 20:36:50 loe volumio[1224]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 26 20:36:50 loe qobuz-connect[1994]: 20260226 20:36:50.068 [1994.1994] INFO VolumeManager: [0x1833408]: Setting new playback volume: 75 Feb 26 20:36:50 loe qobuz-connect[1994]: 20260226 20:36:50.068 [1994.1994] INFO VolumeManager: [0x1833408]: Setting new mute state: 0 Feb 26 20:36:50 loe qobuz-connect[1994]: 20260226 20:36:50.068 [1994.1994] INFO QobuzConnect: [0x1833dd8]: Client initialized! Feb 26 20:36:50 loe qobuz-connect[1994]: 20260226 20:36:50.068 [1994.1994] INFO SampleApp: Starting Avahi advertising, name: Loe, service name: _qobuz-connect._tcp Feb 26 20:36:50 loe qobuz-connect[1994]: 20260226 20:36:50.091 [1994.1994] INFO LocalConfigManager: [0x1832ce8]: Starting Local Configuration server Feb 26 20:36:50 loe qobuz-connect[1994]: 20260226 20:36:50.091 [1994.1994] INFO SampleApp: Starting Local configuration server Feb 26 20:36:50 loe qobuz-connect[1994]: 20260226 20:36:50.091 [1994.1994] INFO SampleApp: Connected to UNIX socket client 0x181d818 Feb 26 20:36:50 loe qobuz-connect[1994]: 20260226 20:36:50.119 [1994.1994] INFO SampleApp: Playback volume changed: 75 Feb 26 20:36:50 loe volumio[1224]: info: Successfully Updated MyVolumio device Feb 26 20:36:50 loe volumio[1224]: info: Update Ready: {"changeLogLink":"","description":"You're already on the latest version","title":"No Updates Available","updateavailable":false} Feb 26 20:36:50 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache Feb 26 20:36:50 loe volumio[1224]: info: QobuzConnect: Qobuz Connect socket /tmp/qbz-connect.socket connected to client [object Object] Feb 26 20:36:50 loe volumio[1224]: info: QobuzConnect: QOBUZ Connect daemon connected Feb 26 20:36:50 loe volumio[1224]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 9 Feb 26 20:36:50 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 26 20:36:50 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 26 20:36:50 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 26 20:36:50 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 26 20:36:50 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 26 20:36:50 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 26 20:36:50 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 26 20:36:50 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 26 20:36:50 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 26 20:36:50 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 26 20:36:50 loe volumio[1224]: error: Hi Res Audio Failed Login: [object Object] Feb 26 20:36:50 loe volumio[1224]: info: Access Token successfully retrieved Feb 26 20:36:50 loe volumio[1224]: error: updateQueue error: null Feb 26 20:36:50 loe volumio[1224]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 10 Feb 26 20:36:50 loe volumio[1224]: info: CoreCommandRouter::volumioGetState Feb 26 20:36:50 loe systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 8. Feb 26 20:36:50 loe systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 26 20:36:50 loe volumio[1224]: info: TidalConnect service stoped! Feb 26 20:36:51 loe systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 26 20:36:51 loe go-librespot[2045]: go-librespot daemon starting... Feb 26 20:36:51 loe go-librespot[2050]: time="2026-02-26T20:36:51+01:00" level=info msg="running go-librespot 0.4.0" Feb 26 20:36:51 loe go-librespot[2050]: time="2026-02-26T20:36:51+01:00" level=debug msg="app state loaded" Feb 26 20:36:51 loe go-librespot[2050]: time="2026-02-26T20:36:51+01:00" level=info msg="api server listening on 127.0.0.1:9879" Feb 26 20:36:51 loe volumio[1224]: info: Starting Shairport Sync Feb 26 20:36:51 loe go-librespot[2050]: time="2026-02-26T20:36:51+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Feb 26 20:36:51 loe go-librespot[2050]: time="2026-02-26T20:36:51+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Feb 26 20:36:51 loe go-librespot[2050]: time="2026-02-26T20:36:51+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Feb 26 20:36:51 loe go-librespot[2050]: time="2026-02-26T20:36:51+01:00" level=info msg="zeroconf server listening on port 44307" Feb 26 20:36:51 loe sudo[2059]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Feb 26 20:36:51 loe sudo[2059]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 26 20:36:51 loe go-librespot[2050]: time="2026-02-26T20:36:51+01:00" level=debug msg="obtained new client token: AACDN1pVDd8CKSOkY/434mjpBfEvmf7ir5+ioQOb+atRCUQeTliuikhQM4DpqALxifmAQJprhAzk0D5eG18oGkfaTbjD6aR2sdpVq42mrqGnVcWFgNF+PlsLnX5ws9ziAeRdmfgW4Ty95rZa6ATKOX2QNj5/jF1KmU00xuq0sb+/VmtZqJgWzqltrajTS5/izfshVlRIercCXzT4m/AoWhHJ6fLZE5kTeRX7b9s2i+2boCtctKJoYXS+kg==" Feb 26 20:36:51 loe systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Feb 26 20:36:51 loe systemd[1]: shairport-sync.service: Deactivated successfully. Feb 26 20:36:51 loe systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Feb 26 20:36:51 loe systemd[1]: shairport-sync.service: Consumed 1.540s CPU time. Feb 26 20:36:51 loe go-librespot[2050]: time="2026-02-26T20:36:51+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Feb 26 20:36:51 loe go-librespot[2050]: time="2026-02-26T20:36:51+01:00" level=debug msg="completed keyexchange" Feb 26 20:36:51 loe go-librespot[2050]: time="2026-02-26T20:36:51+01:00" level=debug msg="completed challenge" Feb 26 20:36:51 loe systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Feb 26 20:36:51 loe sudo[2059]: pam_unix(sudo:session): session closed for user root Feb 26 20:36:51 loe volumio[1224]: info: MRS: Found cast device: Chromecast-84d0dcfc86c31e08fb7722859cd1fe00 Feb 26 20:36:51 loe volumio[1224]: info: Adding audio output: Feb 26 20:36:51 loe go-librespot[2050]: time="2026-02-26T20:36:51+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Feb 26 20:36:51 loe systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 26 20:36:51 loe systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 26 20:36:51 loe volumio[1224]: info: Shairport-Sync Started Feb 26 20:36:51 loe volumio[1224]: info: Adding tc_getconfig REST Endpoint for plugin: music_service/tidalconnect Feb 26 20:36:51 loe volumio[1224]: info: Adding tc_connect REST Endpoint for plugin: music_service/tidalconnect Feb 26 20:36:51 loe volumio[1224]: info: Successfully retrieved User Session From TIDAL Feb 26 20:36:51 loe volumio[1224]: info: CoreCommandRouter::volumioGetState Feb 26 20:36:51 loe sudo[2081]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start vtcs.service Feb 26 20:36:51 loe sudo[2081]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 26 20:36:52 loe volumio[1224]: info: Successfully retrieved User Subscription From TIDAL Feb 26 20:36:52 loe volumio[1224]: info: Adding TIDAL to Browse Sources Feb 26 20:36:52 loe volumio[1224]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Feb 26 20:36:52 loe volumio[1224]: info: [1772134612013] CoreMusicLibrary::Adding element TIDAL Feb 26 20:36:52 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 26 20:36:52 loe volumio[1224]: Cannot find translation for source TIDAL Feb 26 20:36:52 loe volumio[1224]: info: Adding TIDAL REST API Endpoints Feb 26 20:36:52 loe volumio[1224]: info: CoreCommandRouter::volumioGetState Feb 26 20:36:52 loe systemd[1]: Started vtcs.service - Volumio Tidal Connect Service. Feb 26 20:36:52 loe sudo[2081]: pam_unix(sudo:session): session closed for user root Feb 26 20:36:52 loe volumio[1224]: error: Cannot update RT Device info: Error: Reference.set failed: First argument contains undefined in property 'user_devices.mjORZRjMx8YIlyGajvB2CXSYA5r2.143af29c3c483d56419c3a5083f31115.state.status' Feb 26 20:36:52 loe volumio[1224]: info: Initializing connection to go-librespot Websocket Feb 26 20:36:52 loe volumio[1224]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 26 20:36:52 loe volumio[1224]: info: Executing endpoint tc_getconfig Feb 26 20:36:52 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: tidalconnect , onGetConfig Feb 26 20:36:52 loe vtcs[2084]: STARTING TidalConnect services, version: 1.6.1 Feb 26 20:36:52 loe vtcs[2084]: STARTED TidalConnect services. Feb 26 20:36:52 loe volumio[1224]: info: Executing endpoint tc_connect Feb 26 20:36:52 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: tidalconnect , onConnect Feb 26 20:36:52 loe volumio[1224]: info: Connecting to TidalConnect Feb 26 20:36:52 loe volumio[1224]: info: CoreCommandRouter::servicePushState Feb 26 20:36:52 loe volumio[1224]: info: CoreStateMachine::pushState Feb 26 20:36:52 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 26 20:36:52 loe volumio[1224]: info: CoreCommandRouter::volumioPushState Feb 26 20:36:52 loe volumio[1224]: info: MRS: Pushing multiroomSync output update for this device Feb 26 20:36:52 loe volumio[1224]: info: MRS: Pushing multiroomSync output Feb 26 20:36:52 loe volumio[1224]: info: CoreCommandRouter::volumioGetState Feb 26 20:36:52 loe volumio[1224]: info: CorePlayQueue::getTrack 0 Feb 26 20:36:52 loe volumio[1224]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current tidal Received tidalconnect Feb 26 20:36:52 loe volumio[1224]: info: CoreCommandRouter::servicePushState Feb 26 20:36:52 loe volumio[1224]: info: CoreStateMachine::pushState Feb 26 20:36:52 loe volumio[1224]: info: CoreCommandRouter::volumioPushState Feb 26 20:36:52 loe volumio[1224]: info: MRS: Pushing multiroomSync output update for this device Feb 26 20:36:52 loe volumio[1224]: info: MRS: Pushing multiroomSync output Feb 26 20:36:52 loe volumio[1224]: info: CoreCommandRouter::volumioGetState Feb 26 20:36:52 loe volumio[1224]: info: CorePlayQueue::getTrack 0 Feb 26 20:36:52 loe volumio[1224]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current tidal Received tidalconnect Feb 26 20:36:53 loe volumio[1224]: error: Cannot update RT Device info: Error: Reference.set failed: First argument contains undefined in property 'user_devices.mjORZRjMx8YIlyGajvB2CXSYA5r2.143af29c3c483d56419c3a5083f31115.state.status' Feb 26 20:36:54 loe systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 9. Feb 26 20:36:54 loe systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 26 20:36:54 loe systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 26 20:36:54 loe go-librespot[2100]: go-librespot daemon starting... Feb 26 20:36:54 loe go-librespot[2101]: time="2026-02-26T20:36:54+01:00" level=info msg="running go-librespot 0.4.0" Feb 26 20:36:54 loe go-librespot[2101]: time="2026-02-26T20:36:54+01:00" level=debug msg="app state loaded" Feb 26 20:36:54 loe go-librespot[2101]: time="2026-02-26T20:36:54+01:00" level=info msg="api server listening on 127.0.0.1:9879" Feb 26 20:36:55 loe go-librespot[2101]: time="2026-02-26T20:36:55+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Feb 26 20:36:55 loe go-librespot[2101]: time="2026-02-26T20:36:55+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Feb 26 20:36:55 loe go-librespot[2101]: time="2026-02-26T20:36:55+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Feb 26 20:36:55 loe go-librespot[2101]: time="2026-02-26T20:36:55+01:00" level=info msg="zeroconf server listening on port 36957" Feb 26 20:36:55 loe go-librespot[2101]: time="2026-02-26T20:36:55+01:00" level=debug msg="obtained new client token: AADSmIFniWQHC9c4rQ2Qir/wG4gRz8MjWQet/m7+C1654k8zFOv25ldOEYw4kAsmvCqWgSp55GDHWvYE8cel0wCOHcCKVVnAMR0m4OZaBKusYuuiOInG4giaEwmJEdELHDfNFgTxr5k3YRA+lYBEQQikYMKQAA8ueGh1ycXUKcXKj/KETrfJHS2blvvA7opy5fmf5EnyJmmaN9z39N+LstAYltMWXcCra5ksJyRdhAMqtNhk6qOdjgyDAg==" Feb 26 20:36:55 loe volumio[1224]: info: TidalConnect service started! Feb 26 20:36:55 loe volumio[1224]: [Metrics] CommandRouter: 58s 422.64ms Feb 26 20:36:55 loe volumio[1224]: info: CoreCommandRouter::volumiosetStartupVolume Feb 26 20:36:55 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 26 20:36:55 loe volumio[1224]: info: VolumeController:: Setting startup Volume 5 Feb 26 20:36:55 loe go-librespot[2101]: time="2026-02-26T20:36:55+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Feb 26 20:36:55 loe volumio[1224]: info: VolumeController::SetAlsaVolume5 Feb 26 20:36:55 loe go-librespot[2101]: time="2026-02-26T20:36:55+01:00" level=debug msg="completed keyexchange" Feb 26 20:36:55 loe go-librespot[2101]: time="2026-02-26T20:36:55+01:00" level=debug msg="completed challenge" Feb 26 20:36:55 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 26 20:36:55 loe go-librespot[2101]: time="2026-02-26T20:36:55+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Feb 26 20:36:55 loe systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 26 20:36:55 loe systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 26 20:36:55 loe volumio[1224]: info: CoreCommandRouter::Close All Modals sent Feb 26 20:36:55 loe volumio[1224]: info: CoreCommandRouter::Close All Modals sent Feb 26 20:36:55 loe volumio[1224]: info: CoreStateMachine::pushState Feb 26 20:36:55 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 26 20:36:55 loe volumio[1224]: info: CoreCommandRouter::volumioPushState Feb 26 20:36:55 loe volumio[1224]: info: MRS: Pushing multiroomSync output update for this device Feb 26 20:36:55 loe volumio[1224]: info: MRS: Pushing multiroomSync output Feb 26 20:36:55 loe volumio[1224]: info: CoreCommandRouter::volumioGetState Feb 26 20:36:55 loe volumio[1224]: info: Initializing connection to go-librespot Websocket Feb 26 20:36:55 loe volumio[1224]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 26 20:36:56 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable Feb 26 20:36:56 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Feb 26 20:36:56 loe volumio[1224]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect Feb 26 20:36:58 loe systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 10. Feb 26 20:36:58 loe systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 26 20:36:58 loe volumio[1224]: info: Initializing connection to go-librespot Websocket Feb 26 20:36:58 loe volumio[1224]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 26 20:36:58 loe systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 26 20:36:58 loe go-librespot[2111]: go-librespot daemon starting... Feb 26 20:36:58 loe go-librespot[2112]: time="2026-02-26T20:36:58+01:00" level=info msg="running go-librespot 0.4.0" Feb 26 20:36:58 loe go-librespot[2112]: time="2026-02-26T20:36:58+01:00" level=debug msg="app state loaded" Feb 26 20:36:58 loe go-librespot[2112]: time="2026-02-26T20:36:58+01:00" level=info msg="api server listening on 127.0.0.1:9879" Feb 26 20:36:59 loe go-librespot[2112]: time="2026-02-26T20:36:59+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Feb 26 20:36:59 loe go-librespot[2112]: time="2026-02-26T20:36:59+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Feb 26 20:36:59 loe go-librespot[2112]: time="2026-02-26T20:36:59+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Feb 26 20:36:59 loe go-librespot[2112]: time="2026-02-26T20:36:59+01:00" level=info msg="zeroconf server listening on port 33069" Feb 26 20:36:59 loe go-librespot[2112]: time="2026-02-26T20:36:59+01:00" level=debug msg="obtained new client token: AADXDZx4mDkoDdwHyQRknpb32k5DWt7ZP4A8DV4NRxlm5VV+64MmQB+yO/5a3s7iqros8kolzsPZ6F3YONhBkGExcgz/OWqDl6ec22qvbZuTHbLovrOwPA+LE9/OAAYgRwLXEQfL0LJNSpvWZLUge5CzS8QoVYz+v2mRUqJFe1TnltC9tR2cxXgw7tPAonIsXHaNnW3N3mQvLQRvRep2BUA5eXlH/CwBspaSrVgVHQSZXc2GB11LokY=" Feb 26 20:36:59 loe go-librespot[2112]: time="2026-02-26T20:36:59+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Feb 26 20:36:59 loe go-librespot[2112]: time="2026-02-26T20:36:59+01:00" level=debug msg="completed keyexchange" Feb 26 20:36:59 loe go-librespot[2112]: time="2026-02-26T20:36:59+01:00" level=debug msg="completed challenge" Feb 26 20:36:59 loe go-librespot[2112]: time="2026-02-26T20:36:59+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Feb 26 20:36:59 loe systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 26 20:36:59 loe systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 26 20:37:01 loe volumio[1224]: info: Initializing connection to go-librespot Websocket Feb 26 20:37:01 loe volumio[1224]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 26 20:37:02 loe systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 11. Feb 26 20:37:02 loe systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 26 20:37:02 loe volumio[1224]: info: BOOT COMPLETED Feb 26 20:37:02 loe systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 26 20:37:02 loe go-librespot[2134]: go-librespot daemon starting... Feb 26 20:37:02 loe go-librespot[2135]: time="2026-02-26T20:37:02+01:00" level=info msg="running go-librespot 0.4.0" Feb 26 20:37:02 loe go-librespot[2135]: time="2026-02-26T20:37:02+01:00" level=debug msg="app state loaded" Feb 26 20:37:02 loe go-librespot[2135]: time="2026-02-26T20:37:02+01:00" level=info msg="api server listening on 127.0.0.1:9879" Feb 26 20:37:02 loe go-librespot[2135]: time="2026-02-26T20:37:02+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Feb 26 20:37:02 loe go-librespot[2135]: time="2026-02-26T20:37:02+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Feb 26 20:37:02 loe go-librespot[2135]: time="2026-02-26T20:37:02+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Feb 26 20:37:02 loe go-librespot[2135]: time="2026-02-26T20:37:02+01:00" level=info msg="zeroconf server listening on port 33391" Feb 26 20:37:02 loe go-librespot[2135]: time="2026-02-26T20:37:02+01:00" level=debug msg="obtained new client token: AACz/O8EJs314rm0V5z9Bw4YPvTcEtO71jRejHTWvSKR31nFR5Y1MAjGHS7rMyyo1w8mysQPBpHwTN30cLa0N6EsecbFnJG2iCXB2HxKH8rxeqGKk70AeGP7E8AcXAyThK5KXFsFtXZ4vauiG9SbkivMLBHjpoVO7XUp1T77GSL1F3MFiKqAymvVIggt0AzPv3aAHtKvwSgsMtxwjTa4Ae/FVg0q8Rfc2PENTddQTOxTIuf47UqGpATnlA==" Feb 26 20:37:02 loe go-librespot[2135]: time="2026-02-26T20:37:02+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Feb 26 20:37:02 loe go-librespot[2135]: time="2026-02-26T20:37:02+01:00" level=debug msg="completed keyexchange" Feb 26 20:37:03 loe go-librespot[2135]: time="2026-02-26T20:37:03+01:00" level=debug msg="completed challenge" Feb 26 20:37:03 loe go-librespot[2135]: time="2026-02-26T20:37:03+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Feb 26 20:37:03 loe systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 26 20:37:03 loe systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 26 20:37:04 loe volumio[1224]: info: Initializing connection to go-librespot Websocket Feb 26 20:37:04 loe volumio[1224]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 26 20:37:06 loe systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 12. Feb 26 20:37:06 loe systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 26 20:37:06 loe systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 26 20:37:06 loe go-librespot[2142]: go-librespot daemon starting... Feb 26 20:37:06 loe go-librespot[2143]: time="2026-02-26T20:37:06+01:00" level=info msg="running go-librespot 0.4.0" Feb 26 20:37:06 loe go-librespot[2143]: time="2026-02-26T20:37:06+01:00" level=debug msg="app state loaded" Feb 26 20:37:06 loe go-librespot[2143]: time="2026-02-26T20:37:06+01:00" level=info msg="api server listening on 127.0.0.1:9879" Feb 26 20:37:06 loe go-librespot[2143]: time="2026-02-26T20:37:06+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Feb 26 20:37:06 loe go-librespot[2143]: time="2026-02-26T20:37:06+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Feb 26 20:37:06 loe go-librespot[2143]: time="2026-02-26T20:37:06+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Feb 26 20:37:06 loe go-librespot[2143]: time="2026-02-26T20:37:06+01:00" level=info msg="zeroconf server listening on port 37485" Feb 26 20:37:06 loe go-librespot[2143]: time="2026-02-26T20:37:06+01:00" level=debug msg="obtained new client token: AACDcZSX9x7pQ6TS4kvPgQUQnxh3GIbyUydcwLoKv5usGbXm2hFQ711PqniFBZ842dhAN3eQxdQ9FXl5uf0Rjhxrp+cpsCtU1RlOuf03f1OE9ft+cVlFWB+hCtt2MaDGR6CA3AUg58MLBJWKn1yR+Dtdvvf4f1x+uOrqcqwSlPRi/SuSBo+aTHK/GfeL1I2PoXbWXmbYVh4FJ6Z7Jm1aXTKo0mZ755zmmFJolHaWREG3Xia2YrE0wR8yxw==" Feb 26 20:37:06 loe go-librespot[2143]: time="2026-02-26T20:37:06+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Feb 26 20:37:06 loe go-librespot[2143]: time="2026-02-26T20:37:06+01:00" level=debug msg="completed keyexchange" Feb 26 20:37:06 loe go-librespot[2143]: time="2026-02-26T20:37:06+01:00" level=debug msg="completed challenge" Feb 26 20:37:06 loe go-librespot[2143]: time="2026-02-26T20:37:06+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Feb 26 20:37:06 loe systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 26 20:37:06 loe systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 26 20:37:07 loe volumio[1224]: info: Initializing connection to go-librespot Websocket Feb 26 20:37:07 loe volumio[1224]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 26 20:37:10 loe systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 13. Feb 26 20:37:10 loe systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 26 20:37:10 loe systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 26 20:37:10 loe go-librespot[2150]: go-librespot daemon starting... Feb 26 20:37:10 loe go-librespot[2151]: time="2026-02-26T20:37:10+01:00" level=info msg="running go-librespot 0.4.0" Feb 26 20:37:10 loe go-librespot[2151]: time="2026-02-26T20:37:10+01:00" level=debug msg="app state loaded" Feb 26 20:37:10 loe go-librespot[2151]: time="2026-02-26T20:37:10+01:00" level=info msg="api server listening on 127.0.0.1:9879" Feb 26 20:37:10 loe go-librespot[2151]: time="2026-02-26T20:37:10+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Feb 26 20:37:10 loe go-librespot[2151]: time="2026-02-26T20:37:10+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Feb 26 20:37:10 loe go-librespot[2151]: time="2026-02-26T20:37:10+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Feb 26 20:37:10 loe go-librespot[2151]: time="2026-02-26T20:37:10+01:00" level=info msg="zeroconf server listening on port 41919" Feb 26 20:37:10 loe go-librespot[2151]: time="2026-02-26T20:37:10+01:00" level=debug msg="obtained new client token: AAALkmOX5BHxMo5YmLx7wzenazMp9rxc8e5j274GlXEbYfz5OkqvlHKYhLgwQC6ayI9R97jgE9yR8I+bwxuSbvQb5K5GMfEkyxtqxf7do4OERohHAtQhPnrnUBK7TlqH/BIzC8C/73AMQEytB4w1200SPId549DTsy9ncnko1wBN2Y8rC4dKIvgBxKHiZrnA0xJp4iBmhPFTUCmixCMN7DaK2tpBiqpY2GfOzj2yVk1V0v4EUrqh6Og2Tw==" Feb 26 20:37:10 loe go-librespot[2151]: time="2026-02-26T20:37:10+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Feb 26 20:37:10 loe go-librespot[2151]: time="2026-02-26T20:37:10+01:00" level=debug msg="completed keyexchange" Feb 26 20:37:10 loe go-librespot[2151]: time="2026-02-26T20:37:10+01:00" level=debug msg="completed challenge" Feb 26 20:37:10 loe go-librespot[2151]: time="2026-02-26T20:37:10+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Feb 26 20:37:10 loe systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 26 20:37:10 loe systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 26 20:37:10 loe volumio[1224]: info: Initializing connection to go-librespot Websocket Feb 26 20:37:10 loe volumio[1224]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 26 20:37:13 loe volumio[1224]: info: Initializing connection to go-librespot Websocket Feb 26 20:37:13 loe systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 14. Feb 26 20:37:13 loe systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 26 20:37:13 loe volumio[1224]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 26 20:37:13 loe systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 26 20:37:13 loe go-librespot[2172]: go-librespot daemon starting... Feb 26 20:37:13 loe go-librespot[2173]: time="2026-02-26T20:37:13+01:00" level=info msg="running go-librespot 0.4.0" Feb 26 20:37:13 loe go-librespot[2173]: time="2026-02-26T20:37:13+01:00" level=debug msg="app state loaded" Feb 26 20:37:13 loe go-librespot[2173]: time="2026-02-26T20:37:13+01:00" level=info msg="api server listening on 127.0.0.1:9879" Feb 26 20:37:14 loe go-librespot[2173]: time="2026-02-26T20:37:14+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Feb 26 20:37:14 loe go-librespot[2173]: time="2026-02-26T20:37:14+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Feb 26 20:37:14 loe go-librespot[2173]: time="2026-02-26T20:37:14+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Feb 26 20:37:14 loe go-librespot[2173]: time="2026-02-26T20:37:14+01:00" level=info msg="zeroconf server listening on port 46803" Feb 26 20:37:14 loe go-librespot[2173]: time="2026-02-26T20:37:14+01:00" level=debug msg="obtained new client token: AADfXk1w5srvPcdxuL5n+DFESKWlsJpVo8z18g1LwVcMXNw/5G8GBqTVp1r+TXUgKRcUb1HFkKSScxru6+uZnCrm6gYcMyx9eEm75fOKREAXVdzd9Qp7ZNgG3LayHmdeSlBiXb3uXfBJ7T5liXw77vMFoPsqMINal/tl4jVS0hlc9liQjms84MYvo6zIxcBNMBqzaLGnap9orIINIKYBmEuMSFyXZw0pXefPZvK5g2LmHX8QxjKHt8bSMg==" Feb 26 20:37:14 loe go-librespot[2173]: time="2026-02-26T20:37:14+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Feb 26 20:37:14 loe go-librespot[2173]: time="2026-02-26T20:37:14+01:00" level=debug msg="completed keyexchange" Feb 26 20:37:14 loe go-librespot[2173]: time="2026-02-26T20:37:14+01:00" level=debug msg="completed challenge" Feb 26 20:37:14 loe go-librespot[2173]: time="2026-02-26T20:37:14+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Feb 26 20:37:14 loe systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 26 20:37:14 loe systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 26 20:37:16 loe volumio[1224]: info: Initializing connection to go-librespot Websocket Feb 26 20:37:16 loe volumio[1224]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 26 20:37:17 loe systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 15. Feb 26 20:37:17 loe systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 26 20:37:17 loe systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 26 20:37:17 loe go-librespot[2181]: go-librespot daemon starting... Feb 26 20:37:17 loe go-librespot[2182]: time="2026-02-26T20:37:17+01:00" level=info msg="running go-librespot 0.4.0" Feb 26 20:37:17 loe go-librespot[2182]: time="2026-02-26T20:37:17+01:00" level=debug msg="app state loaded" Feb 26 20:37:17 loe go-librespot[2182]: time="2026-02-26T20:37:17+01:00" level=info msg="api server listening on 127.0.0.1:9879" Feb 26 20:37:18 loe go-librespot[2182]: time="2026-02-26T20:37:18+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Feb 26 20:37:18 loe go-librespot[2182]: time="2026-02-26T20:37:18+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Feb 26 20:37:18 loe go-librespot[2182]: time="2026-02-26T20:37:18+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Feb 26 20:37:18 loe go-librespot[2182]: time="2026-02-26T20:37:18+01:00" level=info msg="zeroconf server listening on port 42649" Feb 26 20:37:18 loe go-librespot[2182]: time="2026-02-26T20:37:18+01:00" level=debug msg="obtained new client token: AACOeFK1Mg3CrTND4pJZ/F6AtCTaW8zAo4v3lFM5BvBdTy068AT1b2JfHB44RpXMxYa+KBIC5HR/+2uJulh6xYgZ2tpIxTbTRDZ4pULYqegK82em2YnAuIBlW+hnE6+wsmDxi1XeLkkOh+bIjg9K58vBERL/oyv3EhgKzoXCsZcYaoSjXQ+40lmOs+QpUsPQITKQgW4r7oJSme2ZtGxfq5fYA/YfwXwQmYqzWXuNSfXK8btvrfsLcAs=" Feb 26 20:37:18 loe go-librespot[2182]: time="2026-02-26T20:37:18+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Feb 26 20:37:18 loe go-librespot[2182]: time="2026-02-26T20:37:18+01:00" level=debug msg="completed keyexchange" Feb 26 20:37:18 loe go-librespot[2182]: time="2026-02-26T20:37:18+01:00" level=debug msg="completed challenge" Feb 26 20:37:18 loe go-librespot[2182]: time="2026-02-26T20:37:18+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Feb 26 20:37:18 loe systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 26 20:37:18 loe systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 26 20:37:19 loe volumio[1224]: info: Initializing connection to go-librespot Websocket Feb 26 20:37:19 loe volumio[1224]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 26 20:37:21 loe systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 16. Feb 26 20:37:21 loe systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 26 20:37:21 loe systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 26 20:37:21 loe go-librespot[2204]: go-librespot daemon starting... Feb 26 20:37:21 loe go-librespot[2205]: time="2026-02-26T20:37:21+01:00" level=info msg="running go-librespot 0.4.0" Feb 26 20:37:21 loe go-librespot[2205]: time="2026-02-26T20:37:21+01:00" level=debug msg="app state loaded" Feb 26 20:37:21 loe go-librespot[2205]: time="2026-02-26T20:37:21+01:00" level=info msg="api server listening on 127.0.0.1:9879" Feb 26 20:37:21 loe go-librespot[2205]: time="2026-02-26T20:37:21+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Feb 26 20:37:21 loe go-librespot[2205]: time="2026-02-26T20:37:21+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Feb 26 20:37:21 loe go-librespot[2205]: time="2026-02-26T20:37:21+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Feb 26 20:37:21 loe go-librespot[2205]: time="2026-02-26T20:37:21+01:00" level=info msg="zeroconf server listening on port 35483" Feb 26 20:37:21 loe go-librespot[2205]: time="2026-02-26T20:37:21+01:00" level=debug msg="obtained new client token: AAA3KT6S5NCB0Wb2G4LhpAxWJAnurU8ztYsTfKNTIS9K/gSGlIV3FgqzgAKlPQnTRDYST6Gtb30E3VeZNq0uV60fQd5TGdLMtQNUEfCgaCRFVxigRK2+U3IDc6FTRWWXCc/9TRT8RyDNVsKK8Ncf/J0tC2mqYnBPCc1m2v3YAvXCdOvaWQzOUiyVzzmjXGR2nWYNKpOd98qbyKcnXtplMg7XNGamUeZxKeABrMCt0nP/hVU14DHtSLGrOw==" Feb 26 20:37:21 loe go-librespot[2205]: time="2026-02-26T20:37:21+01:00" level=warning msg="failed to connect to AP ap-gew4.spotify.com:4070, retrying with a different AP" error="dial tcp 34.158.1.133:4070: connect: connection refused" Feb 26 20:37:21 loe go-librespot[2205]: time="2026-02-26T20:37:21+01:00" level=debug msg="connected to ap-gew4.spotify.com:443" Feb 26 20:37:22 loe go-librespot[2205]: time="2026-02-26T20:37:22+01:00" level=debug msg="completed keyexchange" Feb 26 20:37:22 loe go-librespot[2205]: time="2026-02-26T20:37:22+01:00" level=debug msg="completed challenge" Feb 26 20:37:22 loe go-librespot[2205]: time="2026-02-26T20:37:22+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Feb 26 20:37:22 loe systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 26 20:37:22 loe systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 26 20:37:22 loe volumio[1224]: info: Initializing connection to go-librespot Websocket Feb 26 20:37:22 loe volumio[1224]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 26 20:37:25 loe systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 17. Feb 26 20:37:25 loe systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 26 20:37:25 loe systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 26 20:37:25 loe go-librespot[2212]: go-librespot daemon starting... Feb 26 20:37:25 loe go-librespot[2213]: time="2026-02-26T20:37:25+01:00" level=info msg="running go-librespot 0.4.0" Feb 26 20:37:25 loe go-librespot[2213]: time="2026-02-26T20:37:25+01:00" level=debug msg="app state loaded" Feb 26 20:37:25 loe go-librespot[2213]: time="2026-02-26T20:37:25+01:00" level=info msg="api server listening on 127.0.0.1:9879" Feb 26 20:37:25 loe go-librespot[2213]: time="2026-02-26T20:37:25+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Feb 26 20:37:25 loe go-librespot[2213]: time="2026-02-26T20:37:25+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Feb 26 20:37:25 loe go-librespot[2213]: time="2026-02-26T20:37:25+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Feb 26 20:37:25 loe go-librespot[2213]: time="2026-02-26T20:37:25+01:00" level=info msg="zeroconf server listening on port 38439" Feb 26 20:37:25 loe go-librespot[2213]: time="2026-02-26T20:37:25+01:00" level=debug msg="obtained new client token: AADdgPoYEatf1JqQKCY6sE1jtXWth6KzXh/RvDlddAYsILmtjs/I+oMdzmlG8bLVMdNRIO4ZN9V8rpMYeJ24qRWrdoQe61l1v4350dAzxRlfvdKa7joUgpFIylR0+ugcPtuNrPNBP/LNhGuFIxCevvaVr9RdOD3mQ9ALcZMu0sPJDwRl0A3JyYGlTuCQPnp6Gp/nKh2N+0M+u5v12wG07CfS3eGj/TRCPZJsS1jaVnh+IIvWiP3yggzITw==" Feb 26 20:37:25 loe go-librespot[2213]: time="2026-02-26T20:37:25+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Feb 26 20:37:25 loe go-librespot[2213]: time="2026-02-26T20:37:25+01:00" level=debug msg="completed keyexchange" Feb 26 20:37:25 loe go-librespot[2213]: time="2026-02-26T20:37:25+01:00" level=debug msg="completed challenge" Feb 26 20:37:25 loe go-librespot[2213]: time="2026-02-26T20:37:25+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Feb 26 20:37:25 loe systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 26 20:37:25 loe systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 26 20:37:25 loe volumio[1224]: info: Initializing connection to go-librespot Websocket Feb 26 20:37:25 loe volumio[1224]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 26 20:37:28 loe systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 18. Feb 26 20:37:28 loe systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 26 20:37:28 loe volumio[1224]: info: Initializing connection to go-librespot Websocket Feb 26 20:37:28 loe volumio[1224]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 26 20:37:29 loe systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 26 20:37:29 loe go-librespot[2220]: go-librespot daemon starting... Feb 26 20:37:29 loe go-librespot[2221]: time="2026-02-26T20:37:29+01:00" level=info msg="running go-librespot 0.4.0" Feb 26 20:37:29 loe go-librespot[2221]: time="2026-02-26T20:37:29+01:00" level=debug msg="app state loaded" Feb 26 20:37:29 loe go-librespot[2221]: time="2026-02-26T20:37:29+01:00" level=info msg="api server listening on 127.0.0.1:9879" Feb 26 20:37:29 loe go-librespot[2221]: time="2026-02-26T20:37:29+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Feb 26 20:37:29 loe go-librespot[2221]: time="2026-02-26T20:37:29+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Feb 26 20:37:29 loe go-librespot[2221]: time="2026-02-26T20:37:29+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Feb 26 20:37:29 loe go-librespot[2221]: time="2026-02-26T20:37:29+01:00" level=info msg="zeroconf server listening on port 42267" Feb 26 20:37:29 loe go-librespot[2221]: time="2026-02-26T20:37:29+01:00" level=debug msg="obtained new client token: AAC1pfwqKucXQON+pN5YR1sEfMIqOmXcoZWaF/n2SyMhVYiO8O4Me+BR4eM4PaR3VVS9aENuQeHMAya1+/YUwPL8j8VaAocD/SHc1yNTlC/oSHKJHMBbndObqSii731PiKFrqZLJBTYWr9kxtx04P3VCx0vcKGG5lT5dWN9Nf5PqcvBJfZubjP1S6UP8tdjZPUGl9u1ZZAIb8hufyi45FdNA0r79vI4+tr7CZ/9mZlHMpiSTQgA9vtC/6A==" Feb 26 20:37:29 loe go-librespot[2221]: time="2026-02-26T20:37:29+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Feb 26 20:37:29 loe go-librespot[2221]: time="2026-02-26T20:37:29+01:00" level=debug msg="completed keyexchange" Feb 26 20:37:29 loe go-librespot[2221]: time="2026-02-26T20:37:29+01:00" level=debug msg="completed challenge" Feb 26 20:37:29 loe go-librespot[2221]: time="2026-02-26T20:37:29+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Feb 26 20:37:29 loe systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 26 20:37:29 loe systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 26 20:37:31 loe volumio[1224]: info: Initializing connection to go-librespot Websocket Feb 26 20:37:31 loe volumio[1224]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 26 20:37:32 loe systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 19. Feb 26 20:37:32 loe systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 26 20:37:33 loe systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 26 20:37:33 loe go-librespot[2242]: go-librespot daemon starting... Feb 26 20:37:33 loe go-librespot[2243]: time="2026-02-26T20:37:33+01:00" level=info msg="running go-librespot 0.4.0" Feb 26 20:37:33 loe go-librespot[2243]: time="2026-02-26T20:37:33+01:00" level=debug msg="app state loaded" Feb 26 20:37:33 loe go-librespot[2243]: time="2026-02-26T20:37:33+01:00" level=info msg="api server listening on 127.0.0.1:9879" Feb 26 20:37:33 loe go-librespot[2243]: time="2026-02-26T20:37:33+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Feb 26 20:37:33 loe go-librespot[2243]: time="2026-02-26T20:37:33+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Feb 26 20:37:33 loe go-librespot[2243]: time="2026-02-26T20:37:33+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Feb 26 20:37:33 loe go-librespot[2243]: time="2026-02-26T20:37:33+01:00" level=info msg="zeroconf server listening on port 43359" Feb 26 20:37:33 loe go-librespot[2243]: time="2026-02-26T20:37:33+01:00" level=debug msg="obtained new client token: AACyvspotDI1N6DLcv37g/qSr5OBCKPSJp3lgtXhvNkIeL2eqrnbBuYw3+YRx9REptMdYNGNpsUVIOvxhtsh9hiMiEzjaEKGIca6/FnI6AJ4MDVOpYHkFaw2IaZSTCVeB/F1fa6c9Uyi02WkqqTBcdA7ctIjoAVyCN1ate/VSS4vG5CU8B6y06NFNOjysz0/XU4otGhNbcCisyTPy2K1L9BlOGJBoW4IA6knOwh/pXxeazb4rWSdDsJx2w==" Feb 26 20:37:33 loe go-librespot[2243]: time="2026-02-26T20:37:33+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Feb 26 20:37:33 loe go-librespot[2243]: time="2026-02-26T20:37:33+01:00" level=debug msg="completed keyexchange" Feb 26 20:37:33 loe go-librespot[2243]: time="2026-02-26T20:37:33+01:00" level=debug msg="completed challenge" Feb 26 20:37:33 loe go-librespot[2243]: time="2026-02-26T20:37:33+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Feb 26 20:37:33 loe systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 26 20:37:33 loe systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 26 20:37:34 loe volumio[1224]: info: Initializing connection to go-librespot Websocket Feb 26 20:37:34 loe volumio[1224]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 26 20:37:36 loe systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 20. Feb 26 20:37:36 loe systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 26 20:37:36 loe systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 26 20:37:36 loe go-librespot[2250]: go-librespot daemon starting... Feb 26 20:37:37 loe go-librespot[2251]: time="2026-02-26T20:37:37+01:00" level=info msg="running go-librespot 0.4.0" Feb 26 20:37:37 loe go-librespot[2251]: time="2026-02-26T20:37:37+01:00" level=debug msg="app state loaded" Feb 26 20:37:37 loe go-librespot[2251]: time="2026-02-26T20:37:37+01:00" level=info msg="api server listening on 127.0.0.1:9879" Feb 26 20:37:37 loe go-librespot[2251]: time="2026-02-26T20:37:37+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Feb 26 20:37:37 loe go-librespot[2251]: time="2026-02-26T20:37:37+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Feb 26 20:37:37 loe go-librespot[2251]: time="2026-02-26T20:37:37+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Feb 26 20:37:37 loe go-librespot[2251]: time="2026-02-26T20:37:37+01:00" level=info msg="zeroconf server listening on port 41339" Feb 26 20:37:37 loe go-librespot[2251]: time="2026-02-26T20:37:37+01:00" level=debug msg="obtained new client token: AAAL/Gv/u2dqULTqyooUlO/KvGv7ypgy5a98DJ1YsJakrLeBw2RCebLthb4btcf8S2/De2vxC5ZBqNbt03vFXVH8cAt3jkrY6LMN9maqTksx6MlGJkiAUuSMdb8ttnSCVUHl/j048w/L6EjK5u9QVArmii8tO07Ab+UCWkT66tS4P1nkJa+471SiSpiIfU2L0R0UScP0hHB7BeHkVwKZSV80HPXEuitzbeoky+P4GkNjlqqug6RyjqmW5A==" Feb 26 20:37:37 loe go-librespot[2251]: time="2026-02-26T20:37:37+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Feb 26 20:37:37 loe go-librespot[2251]: time="2026-02-26T20:37:37+01:00" level=debug msg="completed keyexchange" Feb 26 20:37:37 loe go-librespot[2251]: time="2026-02-26T20:37:37+01:00" level=debug msg="completed challenge" Feb 26 20:37:37 loe go-librespot[2251]: time="2026-02-26T20:37:37+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Feb 26 20:37:37 loe systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 26 20:37:37 loe systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 26 20:37:37 loe volumio[1224]: info: Initializing connection to go-librespot Websocket Feb 26 20:37:37 loe volumio[1224]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 26 20:37:40 loe systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 21. Feb 26 20:37:40 loe systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 26 20:37:40 loe systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 26 20:37:40 loe go-librespot[2258]: go-librespot daemon starting... Feb 26 20:37:40 loe go-librespot[2259]: time="2026-02-26T20:37:40+01:00" level=info msg="running go-librespot 0.4.0" Feb 26 20:37:40 loe go-librespot[2259]: time="2026-02-26T20:37:40+01:00" level=debug msg="app state loaded" Feb 26 20:37:40 loe go-librespot[2259]: time="2026-02-26T20:37:40+01:00" level=info msg="api server listening on 127.0.0.1:9879" Feb 26 20:37:41 loe volumio[1224]: info: Initializing connection to go-librespot Websocket Feb 26 20:37:41 loe go-librespot[2259]: time="2026-02-26T20:37:41+01:00" level=debug msg="new websocket client" Feb 26 20:37:41 loe volumio[1224]: info: Connection to go-librespot Websocket established Feb 26 20:37:41 loe go-librespot[2259]: time="2026-02-26T20:37:41+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Feb 26 20:37:41 loe go-librespot[2259]: time="2026-02-26T20:37:41+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Feb 26 20:37:41 loe go-librespot[2259]: time="2026-02-26T20:37:41+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Feb 26 20:37:41 loe go-librespot[2259]: time="2026-02-26T20:37:41+01:00" level=info msg="zeroconf server listening on port 41941" Feb 26 20:37:41 loe go-librespot[2259]: time="2026-02-26T20:37:41+01:00" level=debug msg="obtained new client token: AADaUpz18S64jhUMM1anO2ByjTWsPRsVnIGrhInEA3XfulNgT+OLT29hPsXsWmKRlFBB6bef3WGw62DLIYKjOMQmJDmBl5RWTmRidPb22O3BKP5b2DuxyXTVnD0hsfGrus3Db9XMgJDfeiuYQ7rusAp9WinJ5no5X9fHyi2PVNXLKPTouapvdM3ThRW4jFUmOFSzWvy3euT0UFQTs3i9VA6RZ6nP3SfuR3wx775VJkbzsq+gBQKFhwQ=" Feb 26 20:37:41 loe go-librespot[2259]: time="2026-02-26T20:37:41+01:00" level=warning msg="failed to connect to AP ap-gew4.spotify.com:4070, retrying with a different AP" error="dial tcp 34.158.1.133:4070: connect: connection refused" Feb 26 20:37:41 loe go-librespot[2259]: time="2026-02-26T20:37:41+01:00" level=debug msg="connected to ap-gew4.spotify.com:443" Feb 26 20:37:41 loe go-librespot[2259]: time="2026-02-26T20:37:41+01:00" level=debug msg="completed keyexchange" Feb 26 20:37:41 loe go-librespot[2259]: time="2026-02-26T20:37:41+01:00" level=debug msg="completed challenge" Feb 26 20:37:41 loe go-librespot[2259]: time="2026-02-26T20:37:41+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Feb 26 20:37:41 loe systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 26 20:37:41 loe systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 26 20:37:41 loe volumio[1224]: info: Connection to go-librespot Websocket closed Feb 26 20:37:44 loe volumio[1224]: info: Getting Spotify volume Feb 26 20:37:44 loe volumio[1224]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 26 20:37:44 loe volumio[1224]: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 26 20:37:44 loe volumio[1224]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Feb 26 20:37:44 loe volumio[1224]: errno: -111, Feb 26 20:37:44 loe volumio[1224]: code: 'ECONNREFUSED', Feb 26 20:37:44 loe volumio[1224]: syscall: 'connect', Feb 26 20:37:44 loe volumio[1224]: address: '127.0.0.1', Feb 26 20:37:44 loe volumio[1224]: port: 9879, Feb 26 20:37:44 loe volumio[1224]: response: undefined Feb 26 20:37:44 loe volumio[1224]: } Feb 26 20:37:44 loe volumio[1224]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 26 20:37:44 loe systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 22. Feb 26 20:37:44 loe systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 26 20:37:44 loe systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 26 20:37:44 loe go-librespot[2292]: go-librespot daemon starting... Feb 26 20:37:44 loe go-librespot[2293]: time="2026-02-26T20:37:44+01:00" level=info msg="running go-librespot 0.4.0" Feb 26 20:37:44 loe go-librespot[2293]: time="2026-02-26T20:37:44+01:00" level=debug msg="app state loaded" Feb 26 20:37:44 loe go-librespot[2293]: time="2026-02-26T20:37:44+01:00" level=info msg="api server listening on 127.0.0.1:9879" Feb 26 20:37:44 loe go-librespot[2293]: time="2026-02-26T20:37:44+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Feb 26 20:37:44 loe go-librespot[2293]: time="2026-02-26T20:37:44+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Feb 26 20:37:44 loe go-librespot[2293]: time="2026-02-26T20:37:44+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Feb 26 20:37:44 loe go-librespot[2293]: time="2026-02-26T20:37:44+01:00" level=info msg="zeroconf server listening on port 43159" Feb 26 20:37:44 loe go-librespot[2293]: time="2026-02-26T20:37:44+01:00" level=debug msg="obtained new client token: AAAtx4y1314SrJqAV2q9wY572oWMjRlMRlUim3H+A8r2e26T613qc/COZIE6x0AMQHSBaVtW74+6Y16hVx3oP51j0JalISXka3Dtp9z8YJqoOkbdAbuE/5gu7bpS+Tn98CPoPrv6AVohin2/xxme95N+EavARyNuDnFx3VApte/70vd7Mu5xDDdxzwJTwoJz8lr6MyC1/SQuWYWwVVLl3vXPav7BOFFKshYisHMS3dl1xIxVtT4cPTQJeQ==" Feb 26 20:37:45 loe go-librespot[2293]: time="2026-02-26T20:37:45+01:00" level=warning msg="failed to connect to AP ap-gew4.spotify.com:4070, retrying with a different AP" error="dial tcp 34.158.1.133:4070: connect: connection refused" Feb 26 20:37:45 loe go-librespot[2293]: time="2026-02-26T20:37:45+01:00" level=debug msg="connected to ap-gew4.spotify.com:443" Feb 26 20:37:45 loe go-librespot[2293]: time="2026-02-26T20:37:45+01:00" level=debug msg="completed keyexchange" Feb 26 20:37:45 loe go-librespot[2293]: time="2026-02-26T20:37:45+01:00" level=debug msg="completed challenge" Feb 26 20:37:45 loe go-librespot[2293]: time="2026-02-26T20:37:45+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Feb 26 20:37:45 loe systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 26 20:37:45 loe systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 26 20:37:47 loe sudo[2303]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-02-26 20:36' Feb 26 20:37:47 loe sudo[2303]: 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="a78d359cf1dc63ac74e9d151015afd30d31a709a" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="c1ffe93b2136013fc1b5903a4ed7e3f34e0a7bec" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Thu Feb 5 14:07:07 UTC 2026" VOLUMIO_VERSION="4.096" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="5e37060f9823263a753eb5e84030104f"