Aug 28 11:05:00 loftvolumio volumio[1338]: info: MYVOLUMIO Environment detected Aug 28 11:05:00 loftvolumio volumio[1338]: info: Plugin folders cleanup Aug 28 11:05:00 loftvolumio volumio[1338]: info: Scanning into folder /volumio/app/plugins/ Aug 28 11:05:00 loftvolumio volumio[1338]: info: Scanning category audio_interface Aug 28 11:05:00 loftvolumio volumio[1338]: info: Scanning category miscellanea Aug 28 11:05:00 loftvolumio volumio[1338]: info: Scanning category music_service Aug 28 11:05:00 loftvolumio volumio[1338]: info: Scanning category plugins.json Aug 28 11:05:00 loftvolumio volumio[1338]: info: Scanning category system_controller Aug 28 11:05:00 loftvolumio volumio[1338]: info: Scanning category user_interface Aug 28 11:05:00 loftvolumio volumio[1338]: info: Scanning into folder /data/plugins/ Aug 28 11:05:00 loftvolumio volumio[1338]: info: Scanning category music_service Aug 28 11:05:00 loftvolumio volumio[1338]: info: Plugin folders cleanup completed Aug 28 11:05:00 loftvolumio volumio[1338]: info: ------------------------------------------- Aug 28 11:05:00 loftvolumio volumio[1338]: info: ----- Core plugins startup ---- Aug 28 11:05:00 loftvolumio volumio[1338]: info: ------------------------------------------- Aug 28 11:05:00 loftvolumio volumio[1338]: info: Loading plugins from folder /volumio/app/plugins/ Aug 28 11:05:00 loftvolumio volumio[1338]: info: Adding plugin upnp to MyMusic Plugins Aug 28 11:05:00 loftvolumio volumio[1338]: info: Adding plugin airplay_emulation to MyMusic Plugins Aug 28 11:05:00 loftvolumio volumio[1338]: info: Adding plugin upnp_browser to MyMusic Plugins Aug 28 11:05:00 loftvolumio volumio[1338]: info: Loading plugins from folder /data/plugins/ Aug 28 11:05:00 loftvolumio volumio[1338]: info: Loading plugin "system"... Aug 28 11:05:00 loftvolumio volumio[1338]: info: Loading plugin "appearance"... Aug 28 11:05:03 loftvolumio volumio[1338]: info: Loading plugin "network"... Aug 28 11:05:03 loftvolumio volumio[1338]: info: Refreshing Cached IP Addresses Aug 28 11:05:03 loftvolumio volumio[1338]: info: Loading plugin "services"... Aug 28 11:05:03 loftvolumio volumio[1338]: info: Loading plugin "volumio5onboarding"... Aug 28 11:05:03 loftvolumio sudo[1389]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Aug 28 11:05:03 loftvolumio sudo[1389]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 11:05:03 loftvolumio sudo[1389]: pam_unix(sudo:session): session closed for user root Aug 28 11:05:03 loftvolumio volumio[1338]: info: Loading plugin "alsa_controller"... Aug 28 11:05:03 loftvolumio sudo[1390]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Aug 28 11:05:03 loftvolumio sudo[1390]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 11:05:03 loftvolumio sudo[1401]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Aug 28 11:05:03 loftvolumio sudo[1401]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 11:05:03 loftvolumio sudo[1390]: pam_unix(sudo:session): session closed for user root Aug 28 11:05:03 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 28 11:05:03 loftvolumio volumio[1338]: info: Loading plugin "wizard"... Aug 28 11:05:03 loftvolumio volumio[1338]: info: Loading plugin "networkfs"... Aug 28 11:05:03 loftvolumio volumio[1338]: info: Starting Udev Watcher for removable devices Aug 28 11:05:04 loftvolumio sudo[1419]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=cory,password=qweQWE123!@#,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //192.168.0.3/media/music /mnt/NAS/NAS Aug 28 11:05:04 loftvolumio sudo[1419]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 11:05:04 loftvolumio volumio[1338]: info: Ignoring mount for partition: boot Aug 28 11:05:04 loftvolumio volumio[1338]: info: Ignoring mount for partition: volumio Aug 28 11:05:04 loftvolumio volumio[1338]: info: Ignoring mount for partition: volumio_data Aug 28 11:05:04 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Aug 28 11:05:04 loftvolumio volumio[1338]: info: Loading plugin "volumio_command_line_client"... Aug 28 11:05:04 loftvolumio volumio[1338]: info: Loading plugin "upnp"... Aug 28 11:05:04 loftvolumio volumio[1338]: info: [1787936704166] Starting Upmpd Daemon Aug 28 11:05:04 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Aug 28 11:05:04 loftvolumio volumio[1338]: info: Loading plugin "my_music"... Aug 28 11:05:04 loftvolumio volumio[1338]: info: Loading plugin "mpd"... Aug 28 11:05:04 loftvolumio kernel: netfs: FS-Cache loaded Aug 28 11:05:04 loftvolumio volumio-remote-updater[791]: [2026-08-28 11:05:04] [connect] Successful connection Aug 28 11:05:04 loftvolumio nmbd[1130]: [2026/08/28 11:05:04.376725, 0] ../../source3/nmbd/nmbd_namequery.c:109(query_name_response) Aug 28 11:05:04 loftvolumio nmbd[1130]: query_name_response: Multiple (2) responses received for a query on subnet 192.168.0.196 for name WORKGROUP<1d>. Aug 28 11:05:04 loftvolumio nmbd[1130]: This response was from IP 192.168.0.3, reporting an IP address of 192.168.0.3. Aug 28 11:05:04 loftvolumio kernel: Key type cifs.spnego registered Aug 28 11:05:04 loftvolumio kernel: Key type cifs.idmap registered Aug 28 11:05:04 loftvolumio kernel: CIFS: No dialect specified on mount. Default has changed to a more secure dialect, SMB2.1 or later (e.g. SMB3.1.1), from CIFS (SMB1). To use the less secure SMB1 dialect to access old servers which do not support SMB3.1.1 (or even SMB3 or SMB2.1) specify vers=1.0 on mount. Aug 28 11:05:04 loftvolumio kernel: CIFS: Attempting to mount //192.168.0.3/media/music Aug 28 11:05:05 loftvolumio sudo[1419]: pam_unix(sudo:session): session closed for user root Aug 28 11:05:05 loftvolumio volumio[1338]: info: Loading plugin "upnp_browser"... Aug 28 11:05:06 loftvolumio systemd[1]: systemd-fsckd.service: Deactivated successfully. Aug 28 11:05:06 loftvolumio sudo[1401]: pam_unix(sudo:session): session closed for user root Aug 28 11:05:07 loftvolumio volumio[1338]: info: Starting UPNP Browser Aug 28 11:05:07 loftvolumio volumio[1338]: info: Loading plugin "alarm-clock"... Aug 28 11:05:07 loftvolumio volumio[1338]: info: Loading plugin "airplay_emulation"... Aug 28 11:05:07 loftvolumio volumio[1338]: info: Starting Shairport Sync Aug 28 11:05:07 loftvolumio volumio[1338]: info: Loading plugin "last_100"... Aug 28 11:05:08 loftvolumio volumio[1338]: info: Loading plugin "webradio"... Aug 28 11:05:08 loftvolumio volumio[1338]: info: Loading plugin "i2s_dacs"... Aug 28 11:05:08 loftvolumio volumio[1338]: info: Loading plugin "volumiodiscovery"... Aug 28 11:05:08 loftvolumio volumio[1338]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Aug 28 11:05:08 loftvolumio volumio[1338]: *** WARNING *** Please fix your application to use the native API of Avahi! Aug 28 11:05:08 loftvolumio volumio[1338]: *** WARNING *** For more information see Aug 28 11:05:08 loftvolumio volumio[1338]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Aug 28 11:05:08 loftvolumio volumio[1338]: *** WARNING *** Please fix your application to use the native API of Avahi! Aug 28 11:05:08 loftvolumio node[1338]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Aug 28 11:05:08 loftvolumio volumio[1338]: *** WARNING *** For more information see Aug 28 11:05:08 loftvolumio node[1338]: *** WARNING *** Please fix your application to use the native API of Avahi! Aug 28 11:05:08 loftvolumio node[1338]: *** WARNING *** For more information see Aug 28 11:05:08 loftvolumio node[1338]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Aug 28 11:05:08 loftvolumio node[1338]: *** WARNING *** Please fix your application to use the native API of Avahi! Aug 28 11:05:08 loftvolumio node[1338]: *** WARNING *** For more information see Aug 28 11:05:08 loftvolumio volumio[1338]: info: Applying required configuration parameters for plugin volumiodiscovery Aug 28 11:05:08 loftvolumio volumio[1338]: info: Discovery: Started advertising with name: LoftVolumio Aug 28 11:05:08 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Aug 28 11:05:08 loftvolumio volumio[1338]: info: Loading plugin "spop"... Aug 28 11:05:12 loftvolumio systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 2. Aug 28 11:05:12 loftvolumio volumio[1338]: info: Loading plugin "youtube2"... Aug 28 11:05:12 loftvolumio systemd[1]: Starting setdatetime-helper.service - Time Synchronization Helper Service... Aug 28 11:05:12 loftvolumio systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Aug 28 11:05:12 loftvolumio systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Aug 28 11:05:12 loftvolumio systemd[1]: systemd-hostnamed.service: Deactivated successfully. Aug 28 11:05:12 loftvolumio upmpdcli[1462]: Could not open config: /tmp/upmpdcli.conf Aug 28 11:05:12 loftvolumio systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Aug 28 11:05:12 loftvolumio systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Aug 28 11:05:15 loftvolumio volumio[1338]: info: Loading plugin "ytmusic"... Aug 28 11:05:16 loftvolumio systemd[1]: setdatetime-helper.service: Deactivated successfully. Aug 28 11:05:16 loftvolumio systemd[1]: Finished setdatetime-helper.service - Time Synchronization Helper Service. Aug 28 11:05:16 loftvolumio systemd[1]: setdatetime-helper.service: Consumed 1.727s CPU time. Aug 28 11:05:16 loftvolumio volumio[1338]: info: Loading plugin "outputs"... Aug 28 11:05:16 loftvolumio volumio[1338]: info: Loading plugin "albumart"... Aug 28 11:05:16 loftvolumio volumio[1338]: info: Plugin example_plugin is not enabled Aug 28 11:05:16 loftvolumio volumio[1338]: info: Loading plugin "inputs"... Aug 28 11:05:16 loftvolumio volumio[1338]: info: Loading plugin "updater_comm"... Aug 28 11:05:16 loftvolumio volumio[1338]: info: Plugin mpdemulation is not enabled Aug 28 11:05:16 loftvolumio volumio[1338]: info: Loading plugin "rest_api"... Aug 28 11:05:16 loftvolumio volumio[1338]: info: Loading plugin "websocket"... Aug 28 11:05:16 loftvolumio volumio[1338]: info: Starting Socket.io Server version 1.7.4 Aug 28 11:05:16 loftvolumio volumio[1338]: info: Loading i18n strings for locale en Aug 28 11:05:16 loftvolumio volumio[1338]: Updating browse sources language Aug 28 11:05:16 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 28 11:05:17 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 28 11:05:17 loftvolumio volumio[1338]: info: CoreCommandRouter::initPlayerControls Aug 28 11:05:17 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 11:05:17 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 11:05:17 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 11:05:17 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 11:05:17 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 11:05:17 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 11:05:17 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 11:05:17 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 11:05:17 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 28 11:05:17 loftvolumio volumio[1338]: Express server listening on port 3000 Aug 28 11:05:17 loftvolumio volumio[1338]: [Metrics] WebUI: 20s 240.21ms Aug 28 11:05:17 loftvolumio volumio[1338]: info: CoreStateMachine::resetVolumioState Aug 28 11:05:17 loftvolumio volumio[1338]: info: CoreStateMachine::getcurrentVolume Aug 28 11:05:17 loftvolumio volumio[1338]: info: CoreCommandRouter::volumioRetrievevolume Aug 28 11:05:17 loftvolumio volumio[1338]: info: CoreStateMachine::pushState Aug 28 11:05:17 loftvolumio volumio[1338]: info: CorePlayQueue::getTrack 0 Aug 28 11:05:17 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 28 11:05:17 loftvolumio volumio[1338]: info: CoreCommandRouter::volumioPushState Aug 28 11:05:17 loftvolumio sudo[1519]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Aug 28 11:05:17 loftvolumio sudo[1519]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 11:05:17 loftvolumio sudo[1519]: pam_unix(sudo:session): session closed for user root Aug 28 11:05:17 loftvolumio volumio[1338]: info: Volumio Network Manager: Network status updated: 1 Aug 28 11:05:17 loftvolumio sudo[1520]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Aug 28 11:05:17 loftvolumio sudo[1520]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 11:05:17 loftvolumio sudo[1520]: pam_unix(sudo:session): session closed for user root Aug 28 11:05:18 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 11:05:18 loftvolumio volumio[1338]: info: Reloading queue from file Aug 28 11:05:18 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 28 11:05:18 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 28 11:05:18 loftvolumio volumio[1338]: info: Discovery: Getting this device information Aug 28 11:05:18 loftvolumio volumio[1338]: info: CoreCommandRouter::volumioGetState Aug 28 11:05:18 loftvolumio volumio[1338]: info: CorePlayQueue::getTrack 0 Aug 28 11:05:18 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 28 11:05:18 loftvolumio volumio[1338]: info: CoreStateMachine::setRepeat null single undefined Aug 28 11:05:18 loftvolumio volumio[1338]: info: CoreStateMachine::pushState Aug 28 11:05:18 loftvolumio volumio[1338]: info: CorePlayQueue::getTrack 0 Aug 28 11:05:18 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 28 11:05:18 loftvolumio volumio[1338]: info: CoreCommandRouter::volumioPushState Aug 28 11:05:18 loftvolumio volumio[1338]: info: CoreStateMachine::setRandom null Aug 28 11:05:18 loftvolumio volumio[1338]: info: CoreStateMachine::pushState Aug 28 11:05:18 loftvolumio volumio[1338]: info: CorePlayQueue::getTrack 0 Aug 28 11:05:18 loftvolumio volumio[1338]: info: CoreCommandRouter::volumioPushState Aug 28 11:05:18 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 28 11:05:18 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 28 11:05:18 loftvolumio volumio[1338]: info: Discovery: Getting this device information Aug 28 11:05:18 loftvolumio volumio[1338]: info: CoreCommandRouter::volumioGetState Aug 28 11:05:18 loftvolumio volumio[1338]: info: CorePlayQueue::getTrack 0 Aug 28 11:05:18 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 28 11:05:18 loftvolumio volumio[1338]: info: Setting Device type: Raspberry PI Aug 28 11:05:18 loftvolumio volumio[1338]: info: Completed loading Core Plugins Aug 28 11:05:18 loftvolumio volumio[1338]: info: Preparing to generate the ALSA configuration file Aug 28 11:05:18 loftvolumio volumio[1338]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Aug 28 11:05:18 loftvolumio volumio[1338]: info: USB Boot Capable - System SBC Revision found in cpuinfo: c03114 Aug 28 11:05:18 loftvolumio volumio[1338]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Aug 28 11:05:18 loftvolumio volumio[1338]: verbose: New Socket.io Connection to 192.168.0.196:3000 from 192.168.0.3 UA: Dart/3.12 (dart:io) Engine version: 3 Transport: websocket Total Clients: 1 Aug 28 11:05:18 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Aug 28 11:05:18 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Aug 28 11:05:18 loftvolumio sudo[1533]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Aug 28 11:05:18 loftvolumio sudo[1533]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 11:05:18 loftvolumio volumio[1338]: info: Asound.conf file unchanged, so no further update is needed Aug 28 11:05:18 loftvolumio volumio[1338]: info: Output device has changed, restarting MPD Aug 28 11:05:18 loftvolumio volumio[1338]: info: Output device has changed, restarting Shairport Sync Aug 28 11:05:18 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 11:05:18 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 11:05:18 loftvolumio sudo[1536]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Aug 28 11:05:18 loftvolumio sudo[1536]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 11:05:18 loftvolumio volumio[1338]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Aug 28 11:05:18 loftvolumio volumio[1338]: info: ___________ START PLUGINS ___________ Aug 28 11:05:18 loftvolumio sudo[1536]: pam_unix(sudo:session): session closed for user root Aug 28 11:05:18 loftvolumio volumio[1338]: info: ControllerMpd::onStart: Initializing MPD Aug 28 11:05:18 loftvolumio volumio[1338]: info: Creating MPD Configuration file Aug 28 11:05:18 loftvolumio sudo[1538]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Aug 28 11:05:19 loftvolumio sudo[1538]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 11:05:19 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 28 11:05:19 loftvolumio volumio[1338]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 28 11:05:19 loftvolumio volumio[1338]: info: [1787936719029] CoreMusicLibrary::Adding element Media Servers Aug 28 11:05:19 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 28 11:05:19 loftvolumio sudo[1547]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Aug 28 11:05:19 loftvolumio sudo[1547]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 11:05:19 loftvolumio volumio[1338]: info: UPNP Browser: Client initialized successfully Aug 28 11:05:19 loftvolumio volumio[1504]: Forking 3 albumart workers Aug 28 11:05:19 loftvolumio sudo[1545]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumio5-onboarding.service Aug 28 11:05:19 loftvolumio sudo[1545]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 11:05:19 loftvolumio sudo[1547]: pam_unix(sudo:session): session closed for user root Aug 28 11:05:19 loftvolumio sudo[1550]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Aug 28 11:05:19 loftvolumio sudo[1550]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 11:05:19 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 11:05:19 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 11:05:19 loftvolumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Aug 28 11:05:19 loftvolumio systemd[1]: Starting mpd.service - Music Player Daemon... Aug 28 11:05:19 loftvolumio volumio-remote-updater[791]: [2026-08-28 11:05:19] [connect] Successful connection Aug 28 11:05:19 loftvolumio systemd[1]: Started volumio5-onboarding.service - Volumio5 Onboarding Server. Aug 28 11:05:19 loftvolumio systemd[1]: mpd.service: Deactivated successfully. Aug 28 11:05:19 loftvolumio systemd[1]: Stopped mpd.service - Music Player Daemon. Aug 28 11:05:19 loftvolumio systemd[1]: mpd.socket: Deactivated successfully. Aug 28 11:05:19 loftvolumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Aug 28 11:05:19 loftvolumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Aug 28 11:05:19 loftvolumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Aug 28 11:05:19 loftvolumio systemd[1]: Starting mpd.service - Music Player Daemon... Aug 28 11:05:19 loftvolumio sudo[1545]: pam_unix(sudo:session): session closed for user root Aug 28 11:05:19 loftvolumio volumio[1338]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Aug 28 11:05:19 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 11:05:19 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 11:05:19 loftvolumio sudo[1573]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Aug 28 11:05:19 loftvolumio sudo[1573]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Aug 28 11:05:19 loftvolumio sudo[1595]: /bin/chown: cannot access '/var/log/mpd.log': No such file or directory Aug 28 11:05:19 loftvolumio sudo[1573]: pam_unix(sudo:session): session closed for user root Aug 28 11:05:20 loftvolumio volumio[1338]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Aug 28 11:05:20 loftvolumio volumio[1338]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 28 11:05:20 loftvolumio volumio[1338]: info: [1787936720232] CoreMusicLibrary::Adding element Last_100 Aug 28 11:05:20 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 28 11:05:20 loftvolumio volumio[1338]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 28 11:05:20 loftvolumio volumio[1338]: info: [1787936720263] CoreMusicLibrary::Adding element Webradio Aug 28 11:05:20 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 28 11:05:20 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 28 11:05:20 loftvolumio volumio[1338]: info: Initializing BBC Radios Aug 28 11:05:20 loftvolumio volumio5-onboarding[1571]: time=2026-08-28T11:05:20.652-06:00 level=INFO msg="running volumio5-device-gateway" version=6370e0a8+CHANGES buildDate=2026-03-06T16:29:42Z Aug 28 11:05:21 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 28 11:05:21 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 11:05:21 loftvolumio volumio[1338]: info: Creating Spotify config file Aug 28 11:05:21 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 11:05:26 loftvolumio volumio[1338]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 28 11:05:26 loftvolumio volumio[1338]: info: [1787936726184] CoreMusicLibrary::Adding element YouTube2 Aug 28 11:05:26 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 28 11:05:26 loftvolumio volumio[1338]: Cannot find translation for source YouTube2 Aug 28 11:05:26 loftvolumio volumio[1338]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 28 11:05:26 loftvolumio volumio[1338]: info: [1787936726438] CoreMusicLibrary::Adding element YouTube Music Aug 28 11:05:26 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 28 11:05:26 loftvolumio volumio[1338]: Cannot find translation for source YouTube2 Aug 28 11:05:26 loftvolumio volumio[1338]: Cannot find translation for source YouTube Music Aug 28 11:05:26 loftvolumio volumio[1338]: info: Volumio Calling Home Aug 28 11:05:27 loftvolumio systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 3. Aug 28 11:05:27 loftvolumio systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Aug 28 11:05:28 loftvolumio systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Aug 28 11:05:28 loftvolumio sudo[1533]: pam_unix(sudo:session): session closed for user root Aug 28 11:05:28 loftvolumio volumio[1338]: verbose: New Socket.io Connection to 192.168.0.196:3000 from 192.168.0.3 UA: Dart/3.12 (dart:io) Engine version: 3 Transport: websocket Total Clients: 1 Aug 28 11:05:28 loftvolumio volumio[1338]: info: Discovery: adding 3f80afad-d60a-4440-b6b7-bb0379a32a1e Aug 28 11:05:28 loftvolumio volumio[1338]: info: Discovery: Found device LoftVolumio Aug 28 11:05:28 loftvolumio volumio[1338]: info: CoreCommandRouter::volumioGetState Aug 28 11:05:28 loftvolumio volumio[1338]: info: CorePlayQueue::getTrack 0 Aug 28 11:05:28 loftvolumio volumio[1338]: info: Discovery: this is already registered, 3f80afad-d60a-4440-b6b7-bb0379a32a1e Aug 28 11:05:28 loftvolumio volumio[1338]: info: Discovery: Found device LoftVolumio Aug 28 11:05:28 loftvolumio volumio[1338]: info: CoreCommandRouter::volumioGetState Aug 28 11:05:29 loftvolumio volumio[1338]: info: CorePlayQueue::getTrack 0 Aug 28 11:05:29 loftvolumio mpd[1597]: 2026-08-28T11:05:29 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Aug 28 11:05:29 loftvolumio systemd[1]: Starting e2scrub_all.service - Online ext4 Metadata Check for All Filesystems... Aug 28 11:05:29 loftvolumio systemd[1]: e2scrub_all.service: Deactivated successfully. Aug 28 11:05:29 loftvolumio systemd[1]: Finished e2scrub_all.service - Online ext4 Metadata Check for All Filesystems. Aug 28 11:05:29 loftvolumio systemd[1]: Started mpd.service - Music Player Daemon. Aug 28 11:05:29 loftvolumio sudo[1550]: pam_unix(sudo:session): session closed for user root Aug 28 11:05:29 loftvolumio volumio[1338]: info: MPD Permissions set Aug 28 11:05:29 loftvolumio sudo[1538]: pam_unix(sudo:session): session closed for user root Aug 28 11:05:29 loftvolumio volumio[1338]: info: MPD Permissions set Aug 28 11:05:29 loftvolumio volumio[1338]: info: Upmpdcli Daemon Started Aug 28 11:05:30 loftvolumio volumio[1338]: info: Completed starting Core Plugins Aug 28 11:05:30 loftvolumio volumio[1338]: info: ------------------------------------------- Aug 28 11:05:30 loftvolumio volumio[1338]: info: ----- MyVolumio plugins startup ---- Aug 28 11:05:30 loftvolumio volumio[1338]: info: ------------------------------------------- Aug 28 11:05:30 loftvolumio volumio[1338]: info: [MyVolumio PluginManager] Fetching plans data.... Aug 28 11:05:30 loftvolumio volumio[1338]: info: Spotify config file written Aug 28 11:05:30 loftvolumio sudo[1656]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Aug 28 11:05:30 loftvolumio sudo[1656]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 11:05:30 loftvolumio volumio[1557]: Starting albumart workers Aug 28 11:05:30 loftvolumio volumio5-onboarding[1571]: failed to create app: failed to initialize host: failed to create socket connection: could not connect to socket.io server: read tcp 127.0.0.1:57610->127.0.0.1:3000: i/o timeout Aug 28 11:05:30 loftvolumio systemd[1]: volumio5-onboarding.service: Main process exited, code=exited, status=1/FAILURE Aug 28 11:05:30 loftvolumio systemd[1]: volumio5-onboarding.service: Failed with result 'exit-code'. Aug 28 11:05:30 loftvolumio systemd[1]: /lib/systemd/system/go-librespot-daemon.service:9: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Aug 28 11:05:30 loftvolumio systemd[1]: /lib/systemd/system/go-librespot-daemon.service:10: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Aug 28 11:05:30 loftvolumio systemd[1]: volumio5-onboarding.service: Scheduled restart job, restart counter is at 1. Aug 28 11:05:30 loftvolumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 28 11:05:30 loftvolumio systemd[1]: Stopped volumio5-onboarding.service - Volumio5 Onboarding Server. Aug 28 11:05:30 loftvolumio go-librespot[1658]: go-librespot daemon starting... Aug 28 11:05:30 loftvolumio systemd[1]: Started volumio5-onboarding.service - Volumio5 Onboarding Server. Aug 28 11:05:30 loftvolumio volumio5-onboarding[1660]: time=2026-08-28T11:05:30.948-06:00 level=INFO msg="running volumio5-device-gateway" version=6370e0a8+CHANGES buildDate=2026-03-06T16:29:42Z Aug 28 11:05:31 loftvolumio sudo[1656]: pam_unix(sudo:session): session closed for user root Aug 28 11:05:31 loftvolumio volumio[1558]: Starting albumart workers Aug 28 11:05:31 loftvolumio go-librespot[1659]: time="2026-08-28T11:05:31-06:00" level=info msg="running go-librespot 0.7.1" Aug 28 11:05:31 loftvolumio go-librespot[1659]: time="2026-08-28T11:05:31-06:00" level=debug msg="app state loaded" Aug 28 11:05:31 loftvolumio go-librespot[1659]: time="2026-08-28T11:05:31-06:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 28 11:05:32 loftvolumio volumio[1553]: Starting albumart workers Aug 28 11:05:32 loftvolumio go-librespot[1659]: time="2026-08-28T11:05:32-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Aug 28 11:05:32 loftvolumio go-librespot[1659]: time="2026-08-28T11:05:32-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Aug 28 11:05:32 loftvolumio go-librespot[1659]: time="2026-08-28T11:05:32-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Aug 28 11:05:32 loftvolumio go-librespot[1659]: time="2026-08-28T11:05:32-06:00" level=info msg="zeroconf server listening on port 34439" Aug 28 11:05:32 loftvolumio go-librespot[1659]: time="2026-08-28T11:05:32-06:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 28 11:05:32 loftvolumio volumio[1338]: info: Volumio called home Aug 28 11:05:32 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 11:05:32 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 11:05:32 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 11:05:32 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 11:05:32 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 11:05:32 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 11:05:32 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 11:05:32 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 11:05:32 loftvolumio go-librespot[1659]: time="2026-08-28T11:05:32-06:00" level=debug msg="obtained new client token: AAHb5XFPWQJeyEqCl/WWuOj74sg79XtzqtLwyj0vrz/2i9oize4WrhfAyx9yT7UuXa+bb1/xsHKfKmK2iezLdVpEvi1rSYNMkFy1HHNr+LcmScJiVu/SN0zoWNGg9fTEYWStAg77/LRtkKxtUqXoRgkJX1MQwuTUy9w2ERiRMtjouMnW+FHBIQQy8oFFlOHgFMSiTTOeaUs2hW4aiQB8t/Y9dvu5h9CWrN+wlgOSuDxh8x4xypuApRDo" Aug 28 11:05:32 loftvolumio go-librespot[1659]: time="2026-08-28T11:05:32-06:00" level=warning msg="failed to connect to AP ap-guc3.spotify.com:4070, retrying with a different AP" error="dial tcp 104.154.127.247:4070: connect: connection refused" Aug 28 11:05:33 loftvolumio go-librespot[1659]: time="2026-08-28T11:05:33-06:00" level=debug msg="connected to ap-guc3.spotify.com:443" Aug 28 11:05:33 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 11:05:33 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 11:05:33 loftvolumio go-librespot[1659]: time="2026-08-28T11:05:33-06:00" level=debug msg="completed keyexchange" Aug 28 11:05:33 loftvolumio go-librespot[1659]: time="2026-08-28T11:05:33-06:00" level=debug msg="completed challenge" Aug 28 11:05:33 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 11:05:33 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 11:05:33 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 11:05:33 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 11:05:33 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 11:05:33 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 11:05:33 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 11:05:33 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 11:05:33 loftvolumio go-librespot[1659]: time="2026-08-28T11:05:33-06:00" level=info msg="authenticated AP" username="4q*********************3m" Aug 28 11:05:33 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 11:05:33 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 11:05:33 loftvolumio go-librespot[1659]: time="2026-08-28T11:05:33-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 28 11:05:33 loftvolumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 28 11:05:33 loftvolumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 28 11:05:33 loftvolumio volumio[1338]: info: No need to fix Spotify hosts Aug 28 11:05:34 loftvolumio volumio-remote-updater[791]: [2026-08-28 11:05:34] [connect] Successful connection Aug 28 11:05:36 loftvolumio volumio[1338]: error: MPD error: The expression evaluated to a falsy value: Aug 28 11:05:36 loftvolumio volumio[1338]: assert.ok(self.idling) Aug 28 11:05:36 loftvolumio volumio[1338]: error: The expression evaluated to a falsy value: Aug 28 11:05:36 loftvolumio volumio[1338]: assert.ok(self.idling) Aug 28 11:05:36 loftvolumio volumio[1338]: info: MPD running with PID1597 Aug 28 11:05:36 loftvolumio volumio[1338]: ,establishing connection Aug 28 11:05:36 loftvolumio volumio[1338]: error: updateQueue error: null Aug 28 11:05:36 loftvolumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Aug 28 11:05:36 loftvolumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 28 11:05:36 loftvolumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 28 11:05:36 loftvolumio go-librespot[1705]: go-librespot daemon starting... Aug 28 11:05:36 loftvolumio volumio[1338]: verbose: New Socket.io Connection to 192.168.0.196:3000 from 192.168.0.3 UA: Dart/3.12 (dart:io) Engine version: 3 Transport: websocket Total Clients: 2 Aug 28 11:05:36 loftvolumio go-librespot[1706]: time="2026-08-28T11:05:36-06:00" level=info msg="running go-librespot 0.7.1" Aug 28 11:05:36 loftvolumio go-librespot[1706]: time="2026-08-28T11:05:36-06:00" level=debug msg="app state loaded" Aug 28 11:05:36 loftvolumio go-librespot[1706]: time="2026-08-28T11:05:36-06:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 28 11:05:37 loftvolumio volumio[1338]: info: New Spotify access tokenBQCv0XPoLb... Aug 28 11:05:37 loftvolumio volumio[1338]: info: Spotify credentials grant success - running version from March 24, 2019 Aug 28 11:05:37 loftvolumio go-librespot[1706]: time="2026-08-28T11:05:37-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Aug 28 11:05:37 loftvolumio go-librespot[1706]: time="2026-08-28T11:05:37-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Aug 28 11:05:37 loftvolumio go-librespot[1706]: time="2026-08-28T11:05:37-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Aug 28 11:05:37 loftvolumio go-librespot[1706]: time="2026-08-28T11:05:37-06:00" level=info msg="zeroconf server listening on port 36527" Aug 28 11:05:37 loftvolumio go-librespot[1706]: time="2026-08-28T11:05:37-06:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 28 11:05:37 loftvolumio volumio[1338]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Aug 28 11:05:37 loftvolumio volumio[1338]: info: Starting Shairport Sync Aug 28 11:05:37 loftvolumio go-librespot[1706]: time="2026-08-28T11:05:37-06:00" level=debug msg="obtained new client token: AAFWbmhIv9jwlZBYwL7K7xD343MhlIEldyppF5LxxIRkx8S6VZswK3cvgMyRcGio7CfknlNIGcl2ifrlEUgYhhk9urY+zie4JIQmBZ9Jq13L1o7UTGbmw3o1z9wbR/p4LFJNLSTc/dvd+VOEWb0v7fBIM+1sBhAWQEdWx9spiwYvwGNGCOUYNECeQd/tyn/4DeZQUxuS4FbFtk4eUaxk5mq0VuZYQ3R+zWJWrKSR2o/hE6XE08FGAD+r" Aug 28 11:05:37 loftvolumio volumio[1338]: info: Starting Shairport Sync Aug 28 11:05:37 loftvolumio go-librespot[1706]: time="2026-08-28T11:05:37-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Aug 28 11:05:37 loftvolumio volumio[1338]: info: Starting Shairport Sync Aug 28 11:05:37 loftvolumio go-librespot[1706]: time="2026-08-28T11:05:37-06:00" level=debug msg="completed keyexchange" Aug 28 11:05:37 loftvolumio go-librespot[1706]: time="2026-08-28T11:05:37-06:00" level=debug msg="completed challenge" Aug 28 11:05:37 loftvolumio volumio[1338]: error: updateQueue error: null Aug 28 11:05:37 loftvolumio go-librespot[1706]: time="2026-08-28T11:05:37-06:00" level=info msg="authenticated AP" username="4q*********************3m" Aug 28 11:05:37 loftvolumio volumio[1338]: 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 Aug 28 11:05:37 loftvolumio sudo[1730]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Aug 28 11:05:37 loftvolumio sudo[1730]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 11:05:37 loftvolumio sudo[1735]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Aug 28 11:05:37 loftvolumio sudo[1735]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 11:05:38 loftvolumio go-librespot[1706]: time="2026-08-28T11:05:38-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 28 11:05:38 loftvolumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 28 11:05:38 loftvolumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 28 11:05:38 loftvolumio sudo[1732]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Aug 28 11:05:38 loftvolumio sudo[1732]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 11:05:38 loftvolumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Aug 28 11:05:38 loftvolumio systemd[1]: shairport-sync.service: Deactivated successfully. Aug 28 11:05:38 loftvolumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 28 11:05:38 loftvolumio systemd[1]: shairport-sync.service: Consumed 2.484s CPU time. Aug 28 11:05:38 loftvolumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 28 11:05:38 loftvolumio sudo[1735]: pam_unix(sudo:session): session closed for user root Aug 28 11:05:38 loftvolumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Aug 28 11:05:38 loftvolumio systemd[1]: shairport-sync.service: Deactivated successfully. Aug 28 11:05:38 loftvolumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 28 11:05:38 loftvolumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 28 11:05:38 loftvolumio sudo[1730]: pam_unix(sudo:session): session closed for user root Aug 28 11:05:38 loftvolumio volumio[1338]: 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 Aug 28 11:05:38 loftvolumio volumio[1338]: info: Received Get System Info Aug 28 11:05:38 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 28 11:05:38 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 28 11:05:38 loftvolumio volumio[1338]: info: Discovery: Getting this device information Aug 28 11:05:38 loftvolumio volumio[1338]: info: CoreCommandRouter::volumioGetState Aug 28 11:05:38 loftvolumio volumio[1338]: info: CorePlayQueue::getTrack 0 Aug 28 11:05:38 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 28 11:05:38 loftvolumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Aug 28 11:05:38 loftvolumio systemd[1]: shairport-sync.service: Deactivated successfully. Aug 28 11:05:38 loftvolumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 28 11:05:38 loftvolumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 28 11:05:38 loftvolumio volumio5-onboarding[1660]: time=2026-08-28T11:05:38.538-06:00 level=INFO msg="system info for b86d764e6e99cc7f04f383af8e0e9913" deviceName=LoftVolumio deviceVariant=volumio deviceModel= softwareVersion=4.119 Aug 28 11:05:38 loftvolumio sudo[1732]: pam_unix(sudo:session): session closed for user root Aug 28 11:05:38 loftvolumio volumio5-onboarding[1660]: time=2026-08-28T11:05:38.587-06:00 level=INFO msg="bootstrapping state" hasInternet=true Aug 28 11:05:38 loftvolumio volumio[1338]: verbose: New Socket.io Connection to 192.168.0.196:3000 from 192.168.0.3 UA: Dart/3.12 (dart:io) Engine version: 3 Transport: websocket Total Clients: 5 Aug 28 11:05:38 loftvolumio volumio[1338]: info: Received Get System Info Aug 28 11:05:38 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 28 11:05:38 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 28 11:05:38 loftvolumio volumio[1338]: info: Discovery: Getting this device information Aug 28 11:05:38 loftvolumio volumio[1338]: info: CoreCommandRouter::volumioGetState Aug 28 11:05:38 loftvolumio volumio[1338]: info: CorePlayQueue::getTrack 0 Aug 28 11:05:38 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 28 11:05:38 loftvolumio volumio-remote-updater[791]: [2026-08-28 11:05:38] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1787936734 101 Aug 28 11:05:38 loftvolumio volumio[1338]: 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: 6 Aug 28 11:05:39 loftvolumio volumio[1338]: info: Shairport-Sync Started Aug 28 11:05:39 loftvolumio volumio[1338]: Error adding Membership: Error: addMembership EINVAL Aug 28 11:05:39 loftvolumio volumio[1338]: info: Shairport-Sync Started Aug 28 11:05:39 loftvolumio volumio[1338]: info: Shairport-Sync Started Aug 28 11:05:39 loftvolumio volumio-remote-updater[791]: Test mode disabled Aug 28 11:05:39 loftvolumio volumio-remote-updater[791]: Alpha mode disabled Aug 28 11:05:39 loftvolumio volumio-remote-updater[791]: Alpha legacy test mode disabled Aug 28 11:05:39 loftvolumio volumio[1338]: verbose: New Socket.io Connection to 192.168.0.196:3000 from 192.168.0.3 UA: Dart/3.12 (dart:io) Engine version: 3 Transport: websocket Total Clients: 7 Aug 28 11:05:39 loftvolumio volumio[1338]: info: go-librespot daemon successfully initialized Aug 28 11:05:40 loftvolumio volumio[1338]: info: Update Ready: {"changeLogLink":"","description":"You're already on the latest version","title":"No Updates Available","updateavailable":false} Aug 28 11:05:40 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache Aug 28 11:05:40 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 28 11:05:40 loftvolumio volumio5-onboarding[1660]: time=2026-08-28T11:05:40.332-06:00 level=WARN msg="could not read OAuth data for music provider" component=volumio provider=tidal error="could not open plugin config file for \"tidal\": open /data/configuration/music_service/tidal/config.json: no such file or directory" Aug 28 11:05:40 loftvolumio volumio5-onboarding[1660]: time=2026-08-28T11:05:40.334-06:00 level=WARN msg="could not read OAuth data for music provider" component=volumio provider=qobuz error="could not open plugin config file for \"qobuz\": open /data/configuration/music_service/qobuz/config.json: no such file or directory" Aug 28 11:05:40 loftvolumio volumio5-onboarding[1660]: time=2026-08-28T11:05:40.334-06:00 level=WARN msg="could not read username/password data for music provider" component=volumio provider=hi_res_audio error="could not open plugin config file for \"hi_res_audio\": open /data/configuration/music_service/hi_res_audio/config.json: no such file or directory" Aug 28 11:05:40 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 28 11:05:40 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 28 11:05:40 loftvolumio volumio[1338]: info: Discovery: Getting this device information Aug 28 11:05:40 loftvolumio volumio[1338]: info: CoreCommandRouter::volumioGetState Aug 28 11:05:40 loftvolumio volumio[1338]: info: CorePlayQueue::getTrack 0 Aug 28 11:05:40 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 28 11:05:40 loftvolumio volumio[1338]: SPOTIFY: User informations: {"account_id":"KQx9qCP8Sq","country":"CA","display_name":"Caius","email":"huber.cory@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/4qb7av2r51psbptxhf722bn3m"},"followers":{"href":null,"total":1},"href":"https://api.spotify.com/v1/users/4qb7av2r51psbptxhf722bn3m","id":"4qb7av2r51psbptxhf722bn3m","images":[],"product":"premium","type":"user","uri":"spotify:user:4qb7av2r51psbptxhf722bn3m"} Aug 28 11:05:40 loftvolumio volumio[1338]: info: Spotify Successfully logged in Aug 28 11:05:40 loftvolumio volumio[1338]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 28 11:05:40 loftvolumio volumio[1338]: info: [1787936740495] CoreMusicLibrary::Adding element Spotify Aug 28 11:05:40 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 28 11:05:40 loftvolumio volumio[1338]: Cannot find translation for source YouTube2 Aug 28 11:05:40 loftvolumio volumio[1338]: Cannot find translation for source YouTube Music Aug 28 11:05:40 loftvolumio volumio[1338]: Cannot find translation for source Spotify Aug 28 11:05:40 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 28 11:05:40 loftvolumio volumio[1338]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Aug 28 11:05:40 loftvolumio volumio[1338]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Aug 28 11:05:40 loftvolumio volumio[1338]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Aug 28 11:05:40 loftvolumio volumio[1338]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Aug 28 11:05:40 loftvolumio volumio[1338]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Aug 28 11:05:40 loftvolumio volumio[1338]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Aug 28 11:05:40 loftvolumio volumio[1338]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Aug 28 11:05:40 loftvolumio volumio[1338]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Aug 28 11:05:40 loftvolumio volumio[1338]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Aug 28 11:05:40 loftvolumio volumio[1338]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Aug 28 11:05:40 loftvolumio volumio[1338]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Aug 28 11:05:40 loftvolumio volumio[1338]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Aug 28 11:05:40 loftvolumio volumio[1338]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Aug 28 11:05:40 loftvolumio volumio[1338]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Aug 28 11:05:40 loftvolumio volumio[1338]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Aug 28 11:05:40 loftvolumio volumio[1338]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Aug 28 11:05:40 loftvolumio volumio[1338]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Aug 28 11:05:40 loftvolumio volumio[1338]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Aug 28 11:05:40 loftvolumio volumio[1338]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Aug 28 11:05:40 loftvolumio volumio[1338]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Aug 28 11:05:40 loftvolumio volumio[1338]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Aug 28 11:05:40 loftvolumio volumio[1338]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Aug 28 11:05:40 loftvolumio volumio[1338]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Aug 28 11:05:40 loftvolumio volumio[1338]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Aug 28 11:05:40 loftvolumio volumio[1338]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Aug 28 11:05:40 loftvolumio volumio[1338]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Aug 28 11:05:40 loftvolumio volumio[1338]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Aug 28 11:05:40 loftvolumio volumio[1338]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Aug 28 11:05:41 loftvolumio volumio[1338]: info: Adding plugin bluetooth to MyMusic Plugins Aug 28 11:05:41 loftvolumio volumio[1338]: info: Adding plugin multiroom to MyMusic Plugins Aug 28 11:05:41 loftvolumio volumio[1338]: info: Adding plugin metavolumio to MyMusic Plugins Aug 28 11:05:41 loftvolumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Aug 28 11:05:41 loftvolumio volumio[1338]: info: Adding plugin cd_controller to MyMusic Plugins Aug 28 11:05:41 loftvolumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 28 11:05:41 loftvolumio volumio[1338]: info: Adding plugin qobuzconnect to MyMusic Plugins Aug 28 11:05:41 loftvolumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 28 11:05:41 loftvolumio go-librespot[1781]: go-librespot daemon starting... Aug 28 11:05:41 loftvolumio volumio[1338]: info: Adding plugin smart_inputs to MyMusic Plugins Aug 28 11:05:41 loftvolumio go-librespot[1782]: time="2026-08-28T11:05:41-06:00" level=info msg="running go-librespot 0.7.1" Aug 28 11:05:41 loftvolumio go-librespot[1782]: time="2026-08-28T11:05:41-06:00" level=debug msg="app state loaded" Aug 28 11:05:41 loftvolumio volumio[1338]: info: Adding plugin tidalconnect to MyMusic Plugins Aug 28 11:05:41 loftvolumio volumio[1338]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Aug 28 11:05:41 loftvolumio go-librespot[1782]: time="2026-08-28T11:05:41-06:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 28 11:05:41 loftvolumio go-librespot[1782]: time="2026-08-28T11:05:41-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Aug 28 11:05:41 loftvolumio go-librespot[1782]: time="2026-08-28T11:05:41-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Aug 28 11:05:41 loftvolumio go-librespot[1782]: time="2026-08-28T11:05:41-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Aug 28 11:05:41 loftvolumio go-librespot[1782]: time="2026-08-28T11:05:41-06:00" level=info msg="zeroconf server listening on port 33381" Aug 28 11:05:41 loftvolumio go-librespot[1782]: time="2026-08-28T11:05:41-06:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 28 11:05:42 loftvolumio go-librespot[1782]: time="2026-08-28T11:05:42-06:00" level=debug msg="obtained new client token: AAEaRDcI0GCC7f+hp1eQvXnbCfHZ6QvFxcc6zHjBJpggT4VYG2MKnn0EhTF3j8vyKJtteusSg3/9MWsvcBf1qf4FSKCxlLmT6mWxmre+cy6x51HsQU3vfxht85fq5SO5mFWyHt0QsUqLVkqP4JApUIEr6tTubY+GAnAkGRdwmhkKcwNv1v9QNwoYNAzsfHwS6sPPSboH93seWYRN6AFTxwOWte7jv8oy7roFkGWaYfWwVP/oES9/bw==" Aug 28 11:05:42 loftvolumio go-librespot[1782]: time="2026-08-28T11:05:42-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Aug 28 11:05:42 loftvolumio go-librespot[1782]: time="2026-08-28T11:05:42-06:00" level=debug msg="completed keyexchange" Aug 28 11:05:42 loftvolumio go-librespot[1782]: time="2026-08-28T11:05:42-06:00" level=debug msg="completed challenge" Aug 28 11:05:42 loftvolumio go-librespot[1782]: time="2026-08-28T11:05:42-06:00" level=info msg="authenticated AP" username="4q*********************3m" Aug 28 11:05:42 loftvolumio go-librespot[1782]: time="2026-08-28T11:05:42-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 28 11:05:42 loftvolumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 28 11:05:42 loftvolumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 28 11:05:45 loftvolumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Aug 28 11:05:45 loftvolumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 28 11:05:45 loftvolumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 28 11:05:45 loftvolumio go-librespot[1803]: go-librespot daemon starting... Aug 28 11:05:45 loftvolumio go-librespot[1805]: time="2026-08-28T11:05:45-06:00" level=info msg="running go-librespot 0.7.1" Aug 28 11:05:45 loftvolumio go-librespot[1805]: time="2026-08-28T11:05:45-06:00" level=debug msg="app state loaded" Aug 28 11:05:45 loftvolumio go-librespot[1805]: time="2026-08-28T11:05:45-06:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 28 11:05:46 loftvolumio go-librespot[1805]: time="2026-08-28T11:05:46-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Aug 28 11:05:46 loftvolumio go-librespot[1805]: time="2026-08-28T11:05:46-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Aug 28 11:05:46 loftvolumio go-librespot[1805]: time="2026-08-28T11:05:46-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Aug 28 11:05:46 loftvolumio go-librespot[1805]: time="2026-08-28T11:05:46-06:00" level=info msg="zeroconf server listening on port 36959" Aug 28 11:05:46 loftvolumio go-librespot[1805]: time="2026-08-28T11:05:46-06:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 28 11:05:46 loftvolumio go-librespot[1805]: time="2026-08-28T11:05:46-06:00" level=debug msg="obtained new client token: AAH1s1X9zpcRiBFQ7wih7bSbWYnlajfj/uUPQVz1Q0WGU2PuYC/F9/0+BQ8+uI9D16Ihcs3YfRKMMt1uReWgaHfhrPVuIhuA4ehbsnSpY8hzscl6hEVmixXWgcx4NB4E1fgKHwOtrq2R9+YmYV94yba4uW/DNxMLdOkh4z2nr1YQNLbGTIPcWJaUX3tFjS1ACsASG8Wfx8Wpied7zAPmJ/9Nqn25s2dBBbQZwMClv4RjlFkG09haoqeC" Aug 28 11:05:46 loftvolumio go-librespot[1805]: time="2026-08-28T11:05:46-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Aug 28 11:05:46 loftvolumio go-librespot[1805]: time="2026-08-28T11:05:46-06:00" level=debug msg="completed keyexchange" Aug 28 11:05:46 loftvolumio go-librespot[1805]: time="2026-08-28T11:05:46-06:00" level=debug msg="completed challenge" Aug 28 11:05:46 loftvolumio go-librespot[1805]: time="2026-08-28T11:05:46-06:00" level=info msg="authenticated AP" username="4q*********************3m" Aug 28 11:05:47 loftvolumio go-librespot[1805]: time="2026-08-28T11:05:47-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 28 11:05:47 loftvolumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 28 11:05:47 loftvolumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 28 11:05:50 loftvolumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 4. Aug 28 11:05:50 loftvolumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 28 11:05:50 loftvolumio go-librespot[1816]: go-librespot daemon starting... Aug 28 11:05:50 loftvolumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 28 11:05:50 loftvolumio go-librespot[1817]: time="2026-08-28T11:05:50-06:00" level=info msg="running go-librespot 0.7.1" Aug 28 11:05:50 loftvolumio go-librespot[1817]: time="2026-08-28T11:05:50-06:00" level=debug msg="app state loaded" Aug 28 11:05:50 loftvolumio go-librespot[1817]: time="2026-08-28T11:05:50-06:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 28 11:05:51 loftvolumio go-librespot[1817]: time="2026-08-28T11:05:51-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Aug 28 11:05:51 loftvolumio go-librespot[1817]: time="2026-08-28T11:05:51-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Aug 28 11:05:51 loftvolumio go-librespot[1817]: time="2026-08-28T11:05:51-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Aug 28 11:05:51 loftvolumio go-librespot[1817]: time="2026-08-28T11:05:51-06:00" level=info msg="zeroconf server listening on port 32953" Aug 28 11:05:51 loftvolumio go-librespot[1817]: time="2026-08-28T11:05:51-06:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 28 11:05:51 loftvolumio go-librespot[1817]: time="2026-08-28T11:05:51-06:00" level=debug msg="obtained new client token: AAEuXsqB/4R3yDRDlhYiVPLljzNm7kbfAoox+y0ptjrVHnMBI2LQzasj7M2MG7FDRcrNe+CRXm4IqhEpj2M2ixslRB8n//5N2pNKhQooWkLU5l5PaSEhGUwBqe0x/5aYpf4n4/iA0KTwjRN9N6qLBrjzfXxjEsaLYn2PYFQq4t2wCTWgrvzIf0IIoVedtt/wZI/0Ep3FlQaM70lD/ncO2k4LnQHG2QS5ibkv8sH27lMhsqZAJrxNulRJ" Aug 28 11:05:51 loftvolumio go-librespot[1817]: time="2026-08-28T11:05:51-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Aug 28 11:05:51 loftvolumio go-librespot[1817]: time="2026-08-28T11:05:51-06:00" level=debug msg="completed keyexchange" Aug 28 11:05:51 loftvolumio go-librespot[1817]: time="2026-08-28T11:05:51-06:00" level=debug msg="completed challenge" Aug 28 11:05:51 loftvolumio go-librespot[1817]: time="2026-08-28T11:05:51-06:00" level=info msg="authenticated AP" username="4q*********************3m" Aug 28 11:05:51 loftvolumio go-librespot[1817]: time="2026-08-28T11:05:51-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 28 11:05:51 loftvolumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 28 11:05:51 loftvolumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 28 11:05:53 loftvolumio volumio[1338]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Aug 28 11:05:53 loftvolumio volumio[1338]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Aug 28 11:05:53 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 11:05:53 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 11:05:53 loftvolumio volumio[1338]: info: Starting MyVolumio Remote Streaming Endpoints Aug 28 11:05:53 loftvolumio volumio[1338]: info: MyVolumio login type: Token Aug 28 11:05:53 loftvolumio volumio[1338]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Aug 28 11:05:53 loftvolumio volumio[1338]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Aug 28 11:05:54 loftvolumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 5. Aug 28 11:05:54 loftvolumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 28 11:05:54 loftvolumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 28 11:05:55 loftvolumio go-librespot[1826]: go-librespot daemon starting... Aug 28 11:05:55 loftvolumio go-librespot[1827]: time="2026-08-28T11:05:55-06:00" level=info msg="running go-librespot 0.7.1" Aug 28 11:05:55 loftvolumio go-librespot[1827]: time="2026-08-28T11:05:55-06:00" level=debug msg="app state loaded" Aug 28 11:05:55 loftvolumio go-librespot[1827]: time="2026-08-28T11:05:55-06:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 28 11:05:55 loftvolumio go-librespot[1827]: time="2026-08-28T11:05:55-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Aug 28 11:05:55 loftvolumio go-librespot[1827]: time="2026-08-28T11:05:55-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Aug 28 11:05:55 loftvolumio go-librespot[1827]: time="2026-08-28T11:05:55-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Aug 28 11:05:55 loftvolumio go-librespot[1827]: time="2026-08-28T11:05:55-06:00" level=info msg="zeroconf server listening on port 37861" Aug 28 11:05:55 loftvolumio go-librespot[1827]: time="2026-08-28T11:05:55-06:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 28 11:05:55 loftvolumio go-librespot[1827]: time="2026-08-28T11:05:55-06:00" level=debug msg="obtained new client token: AAHb7h94K4oFkHAAgPkNhr7PBu3KQSMzW1roSgeodQEQtA/Nw6UEA4yJ4VAIQOy8+XcFdRLcwUsajGs7S6aOOMlGIafdCn13iTYPw661hEXvXkccy3VR7HIeowB5TPVlINOqcefj+n/m55WNZYac2T0F4DbslSysfTDg3wDrQfItuM+ZzIlcxPPKgeS6O5yxC/JftRzlHgrvfmYIoaDRvelrIsXpETggkSlHdQpRfMy8yHzOTqfYr9Hc" Aug 28 11:05:56 loftvolumio go-librespot[1827]: time="2026-08-28T11:05:56-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Aug 28 11:05:56 loftvolumio go-librespot[1827]: time="2026-08-28T11:05:56-06:00" level=debug msg="completed keyexchange" Aug 28 11:05:56 loftvolumio go-librespot[1827]: time="2026-08-28T11:05:56-06:00" level=debug msg="completed challenge" Aug 28 11:05:56 loftvolumio go-librespot[1827]: time="2026-08-28T11:05:56-06:00" level=info msg="authenticated AP" username="4q*********************3m" Aug 28 11:05:56 loftvolumio go-librespot[1827]: time="2026-08-28T11:05:56-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 28 11:05:56 loftvolumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 28 11:05:56 loftvolumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 28 11:05:59 loftvolumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6. Aug 28 11:05:59 loftvolumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 28 11:05:59 loftvolumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 28 11:05:59 loftvolumio go-librespot[1850]: go-librespot daemon starting... Aug 28 11:05:59 loftvolumio go-librespot[1851]: time="2026-08-28T11:05:59-06:00" level=info msg="running go-librespot 0.7.1" Aug 28 11:05:59 loftvolumio go-librespot[1851]: time="2026-08-28T11:05:59-06:00" level=debug msg="app state loaded" Aug 28 11:05:59 loftvolumio go-librespot[1851]: time="2026-08-28T11:05:59-06:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 28 11:06:00 loftvolumio go-librespot[1851]: time="2026-08-28T11:06:00-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Aug 28 11:06:00 loftvolumio go-librespot[1851]: time="2026-08-28T11:06:00-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Aug 28 11:06:00 loftvolumio go-librespot[1851]: time="2026-08-28T11:06:00-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Aug 28 11:06:00 loftvolumio go-librespot[1851]: time="2026-08-28T11:06:00-06:00" level=info msg="zeroconf server listening on port 33949" Aug 28 11:06:00 loftvolumio go-librespot[1851]: time="2026-08-28T11:06:00-06:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 28 11:06:00 loftvolumio go-librespot[1851]: time="2026-08-28T11:06:00-06:00" level=debug msg="obtained new client token: AAHmC4JHPFDwojAdXRHxQ5pr7iaICZyfV4Z+mpwEtjLUD2er/IltF/YtbupIU0F/3pFZ16I4Q8DxGftlVp6P7hcRVXHVXNbAAVQDcK5oEaF9pupzKNTY0UV+1sBB3rlkuxR3ObAPiy/TgsJCizZnM1w/kSHBPl7oSK+SGQ6V+yKvkP+5xb5NVDsmhtfMH0aPK9ddRY4OHBzU9/zLtk37Gidezwp6S74sFrkzK4K0bnAJ9CUiuHjchf2t" Aug 28 11:06:00 loftvolumio go-librespot[1851]: time="2026-08-28T11:06:00-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Aug 28 11:06:00 loftvolumio go-librespot[1851]: time="2026-08-28T11:06:00-06:00" level=debug msg="completed keyexchange" Aug 28 11:06:00 loftvolumio go-librespot[1851]: time="2026-08-28T11:06:00-06:00" level=debug msg="completed challenge" Aug 28 11:06:01 loftvolumio go-librespot[1851]: time="2026-08-28T11:06:01-06:00" level=info msg="authenticated AP" username="4q*********************3m" Aug 28 11:06:01 loftvolumio go-librespot[1851]: time="2026-08-28T11:06:01-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 28 11:06:01 loftvolumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 28 11:06:01 loftvolumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 28 11:06:04 loftvolumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 7. Aug 28 11:06:04 loftvolumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 28 11:06:04 loftvolumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 28 11:06:04 loftvolumio go-librespot[1860]: go-librespot daemon starting... Aug 28 11:06:04 loftvolumio go-librespot[1861]: time="2026-08-28T11:06:04-06:00" level=info msg="running go-librespot 0.7.1" Aug 28 11:06:04 loftvolumio go-librespot[1861]: time="2026-08-28T11:06:04-06:00" level=debug msg="app state loaded" Aug 28 11:06:04 loftvolumio go-librespot[1861]: time="2026-08-28T11:06:04-06:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 28 11:06:04 loftvolumio volumio[1338]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Aug 28 11:06:04 loftvolumio volumio[1338]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Aug 28 11:06:04 loftvolumio volumio[1338]: info: Streaming services startup Aug 28 11:06:04 loftvolumio volumio[1338]: info: Starting Streaming Daemon Aug 28 11:06:05 loftvolumio go-librespot[1861]: time="2026-08-28T11:06:05-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Aug 28 11:06:05 loftvolumio go-librespot[1861]: time="2026-08-28T11:06:05-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Aug 28 11:06:05 loftvolumio go-librespot[1861]: time="2026-08-28T11:06:05-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Aug 28 11:06:05 loftvolumio go-librespot[1861]: time="2026-08-28T11:06:05-06:00" level=info msg="zeroconf server listening on port 41079" Aug 28 11:06:05 loftvolumio sudo[1870]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Aug 28 11:06:05 loftvolumio volumio[1338]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Aug 28 11:06:05 loftvolumio sudo[1870]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 11:06:05 loftvolumio go-librespot[1861]: time="2026-08-28T11:06:05-06:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 28 11:06:05 loftvolumio go-librespot[1861]: time="2026-08-28T11:06:05-06:00" level=debug msg="obtained new client token: AAFBAs+Koko8hHXxw7Hp+TtsCmcWhEBlgTYdlCI9x9wJT8sPAPIQAk4pgbz2hn9Qb6wlhfYkd+IjqGQxx00hwb+Wl0FDknMYED5O1mozQ/s5LRdWEExF4Eo/QeD3zVT6T/nFlFkqo6dMrnqE+AVk1gVtI4H3CyRb4HgWemyMgSJuNqvMDWbHSsd2KptXuak50L0xO9P3XbE5jV9VNYCk53bZaS/DVEz2szwQ43id942Jn7yQFhWD3957" Aug 28 11:06:05 loftvolumio upmpdcli[1877]: writing RSA key Aug 28 11:06:05 loftvolumio go-librespot[1861]: time="2026-08-28T11:06:05-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Aug 28 11:06:05 loftvolumio sudo[1870]: pam_unix(sudo:session): session closed for user root Aug 28 11:06:05 loftvolumio volumio[1338]: info: Initializing connection to go-librespot Websocket Aug 28 11:06:05 loftvolumio go-librespot[1861]: time="2026-08-28T11:06:05-06:00" level=debug msg="completed keyexchange" Aug 28 11:06:05 loftvolumio go-librespot[1861]: time="2026-08-28T11:06:05-06:00" level=debug msg="completed challenge" Aug 28 11:06:06 loftvolumio go-librespot[1861]: time="2026-08-28T11:06:06-06:00" level=info msg="authenticated AP" username="4q*********************3m" Aug 28 11:06:06 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 28 11:06:06 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 11:06:06 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Aug 28 11:06:06 loftvolumio go-librespot[1861]: time="2026-08-28T11:06:06-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 28 11:06:06 loftvolumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 28 11:06:06 loftvolumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 28 11:06:06 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 28 11:06:06 loftvolumio volumio[1338]: Upnp client error: Error: This socket has been ended by the other party Aug 28 11:06:06 loftvolumio volumio[1338]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Aug 28 11:06:09 loftvolumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 8. Aug 28 11:06:09 loftvolumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 28 11:06:09 loftvolumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 28 11:06:09 loftvolumio go-librespot[1900]: go-librespot daemon starting... Aug 28 11:06:09 loftvolumio go-librespot[1901]: time="2026-08-28T11:06:09-06:00" level=info msg="running go-librespot 0.7.1" Aug 28 11:06:09 loftvolumio go-librespot[1901]: time="2026-08-28T11:06:09-06:00" level=debug msg="app state loaded" Aug 28 11:06:09 loftvolumio go-librespot[1901]: time="2026-08-28T11:06:09-06:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 28 11:06:10 loftvolumio go-librespot[1901]: time="2026-08-28T11:06:10-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Aug 28 11:06:10 loftvolumio go-librespot[1901]: time="2026-08-28T11:06:10-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Aug 28 11:06:10 loftvolumio go-librespot[1901]: time="2026-08-28T11:06:10-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Aug 28 11:06:10 loftvolumio go-librespot[1901]: time="2026-08-28T11:06:10-06:00" level=info msg="zeroconf server listening on port 35977" Aug 28 11:06:10 loftvolumio go-librespot[1901]: time="2026-08-28T11:06:10-06:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 28 11:06:10 loftvolumio go-librespot[1901]: time="2026-08-28T11:06:10-06:00" level=debug msg="obtained new client token: AAHTWZeK5ILHFPoIl5Qd2aauHpCcX5usk6g0mxqPqkMp4KXCi7bTwhAILH/0QHy7j0G7SP7MGJDc6o7KsIwf1EwHDq6TrRfvKLc+/mCycU7adt5vBeXjh1dbv7+rF5gSoXwoeuikSOS4CuvGtYZ9AWI3Z93V/weIEElKE+RGSQbbyYhq5Dv577JoB1eQrnXTPzx3sXckqcDnXA3PnaVk4Do7PcUWNvBW/xyE+CIuN1OL7i7EwXj1YZba" Aug 28 11:06:10 loftvolumio go-librespot[1901]: time="2026-08-28T11:06:10-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Aug 28 11:06:10 loftvolumio volumio[1338]: info: CoreCommandRouter::volumioGetState Aug 28 11:06:10 loftvolumio volumio[1338]: info: CorePlayQueue::getTrack 0 Aug 28 11:06:10 loftvolumio go-librespot[1901]: time="2026-08-28T11:06:10-06:00" level=debug msg="completed keyexchange" Aug 28 11:06:10 loftvolumio go-librespot[1901]: time="2026-08-28T11:06:10-06:00" level=debug msg="completed challenge" Aug 28 11:06:10 loftvolumio volumio[1338]: error: Cannot start Volumio Streaming Daemon Aug 28 11:06:10 loftvolumio volumio[1338]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Aug 28 11:06:10 loftvolumio volumio[1338]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Aug 28 11:06:10 loftvolumio go-librespot[1901]: time="2026-08-28T11:06:10-06:00" level=info msg="authenticated AP" username="4q*********************3m" Aug 28 11:06:10 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Aug 28 11:06:10 loftvolumio volumio[1338]: info: Received Get System Info Aug 28 11:06:10 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 28 11:06:10 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 28 11:06:10 loftvolumio volumio[1338]: info: Discovery: Getting this device information Aug 28 11:06:10 loftvolumio volumio[1338]: info: CoreCommandRouter::volumioGetState Aug 28 11:06:10 loftvolumio volumio[1338]: info: CorePlayQueue::getTrack 0 Aug 28 11:06:10 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 28 11:06:11 loftvolumio go-librespot[1901]: time="2026-08-28T11:06:11-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 28 11:06:11 loftvolumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 28 11:06:11 loftvolumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 28 11:06:13 loftvolumio volumio[1338]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 28 11:06:13 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 11:06:13 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 11:06:13 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam Aug 28 11:06:13 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam Aug 28 11:06:13 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Aug 28 11:06:13 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Aug 28 11:06:13 loftvolumio volumio[1338]: info: CoreCommandRouter::volumioGetBrowseSources Aug 28 11:06:13 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 28 11:06:13 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Aug 28 11:06:13 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Aug 28 11:06:13 loftvolumio volumio5-onboarding[1660]: time=2026-08-28T11:06:13.913-06:00 level=INFO msg="enabling local network discovery" Aug 28 11:06:13 loftvolumio volumio5-onboarding[1660]: time=2026-08-28T11:06:13.970-06:00 level=INFO msg="enabling BLE discovery" Aug 28 11:06:14 loftvolumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 9. Aug 28 11:06:14 loftvolumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 28 11:06:14 loftvolumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 28 11:06:14 loftvolumio go-librespot[1914]: go-librespot daemon starting... Aug 28 11:06:14 loftvolumio go-librespot[1915]: time="2026-08-28T11:06:14-06:00" level=info msg="running go-librespot 0.7.1" Aug 28 11:06:14 loftvolumio go-librespot[1915]: time="2026-08-28T11:06:14-06:00" level=debug msg="app state loaded" Aug 28 11:06:14 loftvolumio go-librespot[1915]: time="2026-08-28T11:06:14-06:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 28 11:06:14 loftvolumio go-librespot[1915]: time="2026-08-28T11:06:14-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Aug 28 11:06:14 loftvolumio go-librespot[1915]: time="2026-08-28T11:06:14-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Aug 28 11:06:14 loftvolumio go-librespot[1915]: time="2026-08-28T11:06:14-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Aug 28 11:06:14 loftvolumio go-librespot[1915]: time="2026-08-28T11:06:14-06:00" level=info msg="zeroconf server listening on port 43537" Aug 28 11:06:14 loftvolumio volumio[1338]: verbose: New Socket.io Connection to 192.168.0.196:3000 from 192.168.0.203 UA: Dart/3.12 (dart:io) Engine version: 3 Transport: websocket Total Clients: 8 Aug 28 11:06:14 loftvolumio go-librespot[1915]: time="2026-08-28T11:06:14-06:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 28 11:06:14 loftvolumio volumio5-onboarding[1660]: time=2026-08-28T11:06:14.987-06:00 level=INFO msg="service successfully established" component=discovery/localnet Aug 28 11:06:15 loftvolumio go-librespot[1915]: time="2026-08-28T11:06:15-06:00" level=debug msg="obtained new client token: AAH6jZgNF4GE1tWDQKlXipARJ39UVONwTdN76v2FXKQseM1wqt0lM0q2YpJ4mz3xsamFjEYfls6lnngTpCWKjfHcm69/vUxNLldDo/fibUOUn7ZeeeDo6Bir2jLnJI68aXnb6FwNT7gopzQ2Jt7e13moQFBiZCUwHX14N4uRLVtNQZOfqr1w1MKt+oTxf/pUsOWtzcpOhpkd1HtNx9nb298Ck5BwggjreQP5PQES6CYK1Y+hpnH22A==" Aug 28 11:06:15 loftvolumio volumio[1338]: error: MyVolumio Custom Token format not valid, refreshing it Aug 28 11:06:15 loftvolumio go-librespot[1915]: time="2026-08-28T11:06:15-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Aug 28 11:06:15 loftvolumio go-librespot[1915]: time="2026-08-28T11:06:15-06:00" level=debug msg="completed keyexchange" Aug 28 11:06:15 loftvolumio go-librespot[1915]: time="2026-08-28T11:06:15-06:00" level=debug msg="completed challenge" Aug 28 11:06:15 loftvolumio go-librespot[1915]: time="2026-08-28T11:06:15-06:00" level=info msg="authenticated AP" username="4q*********************3m" Aug 28 11:06:15 loftvolumio go-librespot[1915]: time="2026-08-28T11:06:15-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 28 11:06:15 loftvolumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 28 11:06:15 loftvolumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 28 11:06:15 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 28 11:06:15 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 28 11:06:15 loftvolumio volumio[1338]: info: Discovery: Getting this device information Aug 28 11:06:15 loftvolumio volumio[1338]: info: CoreCommandRouter::volumioGetState Aug 28 11:06:15 loftvolumio volumio[1338]: info: CorePlayQueue::getTrack 0 Aug 28 11:06:15 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 28 11:06:16 loftvolumio volumio-remote-updater[791]: Test mode disabled Aug 28 11:06:16 loftvolumio volumio-remote-updater[791]: Alpha mode disabled Aug 28 11:06:16 loftvolumio volumio-remote-updater[791]: Alpha legacy test mode disabled Aug 28 11:06:16 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateEnabled Aug 28 11:06:16 loftvolumio volumio[1338]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 9 Aug 28 11:06:16 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 28 11:06:16 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 28 11:06:16 loftvolumio volumio[1338]: info: Discovery: Getting this device information Aug 28 11:06:16 loftvolumio volumio[1338]: info: CoreCommandRouter::volumioGetState Aug 28 11:06:16 loftvolumio volumio[1338]: info: CorePlayQueue::getTrack 0 Aug 28 11:06:16 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 28 11:06:16 loftvolumio volumio[1338]: verbose: New Socket.io Connection to 192.168.0.196:3000 from 192.168.0.203 UA: Dart/3.12 (dart:io) Engine version: 3 Transport: websocket Total Clients: 10 Aug 28 11:06:16 loftvolumio volumio[1338]: info: Update Ready: {"changeLogLink":"","description":"You're already on the latest version","title":"No Updates Available","updateavailable":false} Aug 28 11:06:16 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache Aug 28 11:06:16 loftvolumio volumio[1338]: info: Initializing connection to go-librespot Websocket Aug 28 11:06:16 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 28 11:06:16 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 28 11:06:16 loftvolumio volumio[1338]: info: Discovery: Getting this device information Aug 28 11:06:16 loftvolumio volumio[1338]: info: CoreCommandRouter::volumioGetState Aug 28 11:06:16 loftvolumio volumio[1338]: info: CorePlayQueue::getTrack 0 Aug 28 11:06:16 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 28 11:06:17 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 28 11:06:17 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 28 11:06:17 loftvolumio volumio[1338]: info: Discovery: Getting this device information Aug 28 11:06:17 loftvolumio volumio[1338]: info: CoreCommandRouter::volumioGetState Aug 28 11:06:17 loftvolumio volumio[1338]: info: CorePlayQueue::getTrack 0 Aug 28 11:06:17 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 28 11:06:17 loftvolumio volumio[1338]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 28 11:06:17 loftvolumio volumio[1338]: verbose: New Socket.io Connection to 192.168.0.196:3000 from 192.168.0.203 UA: Dart/3.12 (dart:io) Engine version: 3 Transport: websocket Total Clients: 11 Aug 28 11:06:17 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Aug 28 11:06:17 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Aug 28 11:06:17 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 28 11:06:17 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 28 11:06:17 loftvolumio volumio[1338]: info: Discovery: Getting this device information Aug 28 11:06:17 loftvolumio volumio[1338]: info: CoreCommandRouter::volumioGetState Aug 28 11:06:17 loftvolumio volumio[1338]: info: CorePlayQueue::getTrack 0 Aug 28 11:06:17 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 28 11:06:17 loftvolumio volumio[1338]: info: CoreCommandRouter::volumioGetState Aug 28 11:06:17 loftvolumio volumio[1338]: info: CorePlayQueue::getTrack 0 Aug 28 11:06:17 loftvolumio volumio[1338]: info: MyVolumio login type: Token Aug 28 11:06:18 loftvolumio volumio[1338]: verbose: New Socket.io Connection to 192.168.0.196:3000 from 192.168.0.203 UA: Dart/3.12 (dart:io) Engine version: 3 Transport: websocket Total Clients: 11 Aug 28 11:06:18 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Aug 28 11:06:18 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Aug 28 11:06:18 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 28 11:06:18 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 28 11:06:18 loftvolumio volumio[1338]: info: Discovery: Getting this device information Aug 28 11:06:18 loftvolumio volumio[1338]: info: CoreCommandRouter::volumioGetState Aug 28 11:06:18 loftvolumio volumio[1338]: info: CorePlayQueue::getTrack 0 Aug 28 11:06:18 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 28 11:06:18 loftvolumio volumio5-onboarding[1660]: time=2026-08-28T11:06:18.431-06:00 level=INFO msg="established new WebSocket connection" component=conn/ws remoteAddr=192.168.0.203:48634 Aug 28 11:06:18 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Aug 28 11:06:18 loftvolumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 10. Aug 28 11:06:18 loftvolumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 28 11:06:18 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: appearance , getAvailableLanguages Aug 28 11:06:18 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: system , getCurrentTimezone Aug 28 11:06:18 loftvolumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 28 11:06:18 loftvolumio go-librespot[1939]: go-librespot daemon starting... Aug 28 11:06:18 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: network , getInfoNetwork Aug 28 11:06:18 loftvolumio go-librespot[1940]: time="2026-08-28T11:06:18-06:00" level=info msg="running go-librespot 0.7.1" Aug 28 11:06:18 loftvolumio go-librespot[1940]: time="2026-08-28T11:06:18-06:00" level=debug msg="app state loaded" Aug 28 11:06:19 loftvolumio go-librespot[1940]: time="2026-08-28T11:06:19-06:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 28 11:06:19 loftvolumio sudo[1942]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ethtool eth0 Aug 28 11:06:19 loftvolumio sudo[1942]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 11:06:19 loftvolumio sudo[1942]: pam_unix(sudo:session): session closed for user root Aug 28 11:06:19 loftvolumio sudo[1965]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwconfig wlan0 Aug 28 11:06:19 loftvolumio sudo[1965]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 11:06:19 loftvolumio sudo[1965]: pam_unix(sudo:session): session closed for user root Aug 28 11:06:19 loftvolumio sudo[1954]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwconfig wlan0 Aug 28 11:06:19 loftvolumio sudo[1954]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 11:06:19 loftvolumio sudo[1973]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Aug 28 11:06:19 loftvolumio sudo[1974]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Aug 28 11:06:19 loftvolumio sudo[1974]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 11:06:19 loftvolumio sudo[1973]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 11:06:19 loftvolumio sudo[1974]: pam_unix(sudo:session): session closed for user root Aug 28 11:06:19 loftvolumio sudo[1973]: pam_unix(sudo:session): session closed for user root Aug 28 11:06:19 loftvolumio sudo[1954]: pam_unix(sudo:session): session closed for user root Aug 28 11:06:19 loftvolumio go-librespot[1940]: time="2026-08-28T11:06:19-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Aug 28 11:06:19 loftvolumio go-librespot[1940]: time="2026-08-28T11:06:19-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Aug 28 11:06:19 loftvolumio go-librespot[1940]: time="2026-08-28T11:06:19-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Aug 28 11:06:19 loftvolumio go-librespot[1940]: time="2026-08-28T11:06:19-06:00" level=info msg="zeroconf server listening on port 40101" Aug 28 11:06:19 loftvolumio go-librespot[1940]: time="2026-08-28T11:06:19-06:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 28 11:06:19 loftvolumio sudo[1960]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwconfig wlan0 Aug 28 11:06:19 loftvolumio sudo[1960]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 11:06:19 loftvolumio sudo[1960]: pam_unix(sudo:session): session closed for user root Aug 28 11:06:19 loftvolumio go-librespot[1940]: time="2026-08-28T11:06:19-06:00" level=debug msg="obtained new client token: AAH8vBmAE+ffWbS5WNj0XF4zqKNMzB52eLKKdHzl926P3qhAmFbfRSAhsJNB2mwBHU2jmIm4GBX9SCAgD0aPKa6eq8ZFr4xC62hGpzkcme0fRYxgQUy8JaZ6dZge3s1/VtBNvnrZyqwS//7YEORIKVeBKP8L3WVt7waL3QML8kgOUSmVCCs2ZYU42iDe8TvOsac4lsSKcz3zdDjBA3TdPELnkH1gyaw5n1zJQoGS2PfJPENv9pyd02f+" Aug 28 11:06:19 loftvolumio go-librespot[1940]: time="2026-08-28T11:06:19-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Aug 28 11:06:19 loftvolumio go-librespot[1940]: time="2026-08-28T11:06:19-06:00" level=debug msg="completed keyexchange" Aug 28 11:06:19 loftvolumio go-librespot[1940]: time="2026-08-28T11:06:19-06:00" level=debug msg="completed challenge" Aug 28 11:06:19 loftvolumio volumio[1338]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Aug 28 11:06:19 loftvolumio go-librespot[1940]: time="2026-08-28T11:06:19-06:00" level=info msg="authenticated AP" username="4q*********************3m" Aug 28 11:06:20 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Aug 28 11:06:20 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Aug 28 11:06:20 loftvolumio go-librespot[1940]: time="2026-08-28T11:06:20-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 28 11:06:20 loftvolumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 28 11:06:20 loftvolumio volumio[1338]: info: Initializing connection to go-librespot Websocket Aug 28 11:06:20 loftvolumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 28 11:06:20 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 28 11:06:20 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 28 11:06:20 loftvolumio volumio[1338]: info: Discovery: Getting this device information Aug 28 11:06:20 loftvolumio volumio[1338]: info: CoreCommandRouter::volumioGetState Aug 28 11:06:20 loftvolumio volumio[1338]: info: CorePlayQueue::getTrack 0 Aug 28 11:06:20 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 28 11:06:20 loftvolumio volumio[1338]: info: CoreCommandRouter::volumioGetState Aug 28 11:06:20 loftvolumio volumio[1338]: info: CorePlayQueue::getTrack 0 Aug 28 11:06:20 loftvolumio volumio[1338]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 28 11:06:20 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Aug 28 11:06:20 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Aug 28 11:06:20 loftvolumio volumio5-onboarding[1660]: time=2026-08-28T11:06:20.499-06:00 level=INFO msg="check connectivity" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.203:48634 @ 0x2452420" latency=-1.46947979s timeout=10s Aug 28 11:06:20 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Aug 28 11:06:20 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Aug 28 11:06:20 loftvolumio volumio5-onboarding[1660]: time=2026-08-28T11:06:20.567-06:00 level=INFO msg="navigate to next page" component=server type=REQUEST_TYPE_CONTINUE_NAVIGATION peer="192.168.0.203:48634 @ 0x2452420" latency=-1.470547879s timeout=10s from=APP_PAGE_ROOT to=APP_PAGE_LEGACY_DEVICE Aug 28 11:06:20 loftvolumio volumio[1338]: info: MyVolumio token set successfully Aug 28 11:06:20 loftvolumio volumio[1338]: info: MYVOLUMIO: Adding device Aug 28 11:06:20 loftvolumio volumio[1338]: info: MYVOLUMIO: Evaluating Server Aug 28 11:06:20 loftvolumio volumio5-onboarding[1660]: time=2026-08-28T11:06:20.989-06:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.203:48634 @ 0x2452420" latency=-1.46947979s timeout=10s endpoint=http://pushupdates.volumio.org duration=485.27628ms Aug 28 11:06:21 loftvolumio volumio5-onboarding[1660]: time=2026-08-28T11:06:21.197-06:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.203:48634 @ 0x2452420" latency=-1.46947979s timeout=10s endpoint=https://securetoken.googleapis.com duration=695.147166ms Aug 28 11:06:21 loftvolumio volumio5-onboarding[1660]: time=2026-08-28T11:06:21.237-06:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.203:48634 @ 0x2452420" latency=-1.46947979s timeout=10s endpoint=https://radio-directory.firebaseapp.com duration=737.266619ms Aug 28 11:06:21 loftvolumio volumio5-onboarding[1660]: time=2026-08-28T11:06:21.307-06:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.203:48634 @ 0x2452420" latency=-1.46947979s timeout=10s endpoint=http://plugins.volumio.org duration=800.324736ms Aug 28 11:06:21 loftvolumio volumio5-onboarding[1660]: time=2026-08-28T11:06:21.349-06:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.203:48634 @ 0x2452420" latency=-1.46947979s timeout=10s endpoint=https://www.googleapis.com duration=849.185716ms Aug 28 11:06:21 loftvolumio volumio5-onboarding[1660]: time=2026-08-28T11:06:21.370-06:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.203:48634 @ 0x2452420" latency=-1.46947979s timeout=10s endpoint=https://myvolumio.firebaseio.com duration=869.196925ms Aug 28 11:06:21 loftvolumio volumio5-onboarding[1660]: time=2026-08-28T11:06:21.537-06:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.203:48634 @ 0x2452420" latency=-1.46947979s timeout=10s endpoint=https://google.com duration=1.030423106s Aug 28 11:06:21 loftvolumio volumio5-onboarding[1660]: time=2026-08-28T11:06:21.557-06:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.203:48634 @ 0x2452420" latency=-1.46947979s timeout=10s endpoint=http://cddb.volumio.org duration=1.054753866s Aug 28 11:06:21 loftvolumio volumio5-onboarding[1660]: time=2026-08-28T11:06:21.922-06:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.203:48634 @ 0x2452420" latency=-1.46947979s timeout=10s endpoint=https://functions.volumio.cloud duration=1.4199654s Aug 28 11:06:21 loftvolumio volumio5-onboarding[1660]: time=2026-08-28T11:06:21.926-06:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.203:48634 @ 0x2452420" latency=-1.46947979s timeout=10s endpoint=https://functions.volumio.cloud duration=1.422948389s Aug 28 11:06:22 loftvolumio volumio5-onboarding[1660]: time=2026-08-28T11:06:22.016-06:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.203:48634 @ 0x2452420" latency=-1.46947979s timeout=10s endpoint=https://oauth-performer.dfs.volumio.org duration=1.512865202s Aug 28 11:06:22 loftvolumio volumio5-onboarding[1660]: time=2026-08-28T11:06:22.065-06:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.203:48634 @ 0x2452420" latency=-1.46947979s timeout=10s endpoint=https://database.volumio.cloud duration=1.557567169s Aug 28 11:06:22 loftvolumio volumio5-onboarding[1660]: time=2026-08-28T11:06:22.208-06:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.203:48634 @ 0x2452420" latency=-1.46947979s timeout=10s endpoint=https://browsing-performer.dfs.volumio.org duration=1.707439651s Aug 28 11:06:22 loftvolumio volumio[1338]: info: MyVolumio status changed Aug 28 11:06:22 loftvolumio volumio[1338]: info: Streaming services startup Aug 28 11:06:22 loftvolumio volumio[1338]: info: Starting Streaming Daemon Aug 28 11:06:22 loftvolumio volumio[1338]: info: Removing browser output: myVolumio user plan is not superstar Aug 28 11:06:22 loftvolumio volumio[1338]: info: Removing audio output: Aug 28 11:06:22 loftvolumio volumio[1338]: info: Stoppping Tunnel 1 Aug 28 11:06:22 loftvolumio sudo[2014]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Aug 28 11:06:22 loftvolumio sudo[2014]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 11:06:22 loftvolumio sudo[2016]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service Aug 28 11:06:22 loftvolumio sudo[2016]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 11:06:22 loftvolumio volumio[1338]: info: Setting Geolocation for MyVolumio to us3 Aug 28 11:06:22 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 11:06:22 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 11:06:22 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 11:06:22 loftvolumio sudo[2014]: pam_unix(sudo:session): session closed for user root Aug 28 11:06:23 loftvolumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Aug 28 11:06:23 loftvolumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Aug 28 11:06:23 loftvolumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Aug 28 11:06:23 loftvolumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Aug 28 11:06:23 loftvolumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Aug 28 11:06:23 loftvolumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Aug 28 11:06:23 loftvolumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Aug 28 11:06:23 loftvolumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Aug 28 11:06:23 loftvolumio sudo[2016]: pam_unix(sudo:session): session closed for user root Aug 28 11:06:23 loftvolumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 11. Aug 28 11:06:23 loftvolumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 28 11:06:23 loftvolumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 28 11:06:23 loftvolumio go-librespot[2019]: go-librespot daemon starting... Aug 28 11:06:23 loftvolumio volumio[1338]: error: Cannot start Volumio Streaming Daemon Aug 28 11:06:23 loftvolumio volumio[1338]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Aug 28 11:06:23 loftvolumio volumio[1338]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Aug 28 11:06:23 loftvolumio volumio[1338]: info: Initializing connection to go-librespot Websocket Aug 28 11:06:23 loftvolumio go-librespot[2020]: time="2026-08-28T11:06:23-06:00" level=info msg="running go-librespot 0.7.1" Aug 28 11:06:23 loftvolumio go-librespot[2020]: time="2026-08-28T11:06:23-06:00" level=debug msg="app state loaded" Aug 28 11:06:23 loftvolumio volumio[1338]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Aug 28 11:06:23 loftvolumio volumio[1338]: info: Remote SSH Stopped Aug 28 11:06:23 loftvolumio go-librespot[2020]: time="2026-08-28T11:06:23-06:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 28 11:06:23 loftvolumio volumio[1338]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 28 11:06:23 loftvolumio volumio[1338]: info: Updating MyVolumio device info Aug 28 11:06:23 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 11:06:23 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 11:06:23 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 11:06:24 loftvolumio go-librespot[2020]: time="2026-08-28T11:06:24-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Aug 28 11:06:24 loftvolumio go-librespot[2020]: time="2026-08-28T11:06:24-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Aug 28 11:06:24 loftvolumio go-librespot[2020]: time="2026-08-28T11:06:24-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Aug 28 11:06:24 loftvolumio go-librespot[2020]: time="2026-08-28T11:06:24-06:00" level=info msg="zeroconf server listening on port 42253" Aug 28 11:06:24 loftvolumio go-librespot[2020]: time="2026-08-28T11:06:24-06:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 28 11:06:24 loftvolumio go-librespot[2020]: time="2026-08-28T11:06:24-06:00" level=debug msg="obtained new client token: AAHzhUO2r8vhqs0FQ9eb976rcwIWI0UuTMTnWJWYCKUntr/iKwtcM6cahQg2aHdU2VhlThnx7vqm4NZkGqlVMKgDbGb2ZiRkldDYNYgqHFwP1OBy0KFPOcveqceCcuefNTaN98+IFh+PACSI/KwMdPe94BoGlwwyASNaABTjduPiglBVc99KNPfLETkqCiw9DtV5qPETyR9EKpsRs7Uodbjq/dxVWF8t65hhp3aNCOEo8JsnqGupMJbq" Aug 28 11:06:24 loftvolumio go-librespot[2020]: time="2026-08-28T11:06:24-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Aug 28 11:06:24 loftvolumio go-librespot[2020]: time="2026-08-28T11:06:24-06:00" level=debug msg="completed keyexchange" Aug 28 11:06:24 loftvolumio go-librespot[2020]: time="2026-08-28T11:06:24-06:00" level=debug msg="completed challenge" Aug 28 11:06:24 loftvolumio go-librespot[2020]: time="2026-08-28T11:06:24-06:00" level=info msg="authenticated AP" username="4q*********************3m" Aug 28 11:06:24 loftvolumio go-librespot[2020]: time="2026-08-28T11:06:24-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 28 11:06:24 loftvolumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 28 11:06:24 loftvolumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 28 11:06:24 loftvolumio sudo[2030]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Aug 28 11:06:24 loftvolumio sudo[2030]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 11:06:24 loftvolumio sudo[2030]: pam_unix(sudo:session): session closed for user root Aug 28 11:06:24 loftvolumio volumio[1338]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Aug 28 11:06:24 loftvolumio sudo[2032]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Aug 28 11:06:25 loftvolumio sudo[2032]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 11:06:25 loftvolumio sudo[2032]: pam_unix(sudo:session): session closed for user root Aug 28 11:06:25 loftvolumio volumio[1338]: verbose: New Socket.io Connection to 192.168.0.196 from 192.168.0.203 UA: Mozilla/5.0 (Linux; Android 17; Pixel 8 Build/CP2A.260805.005; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/151.0.7922.199 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 10 Aug 28 11:06:25 loftvolumio volumio[1338]: error: MyVolumio Plugin failed to authenticate in a timely fashion Aug 28 11:06:25 loftvolumio volumio[1338]: info: Completed starting MyVolumio Plugin Aug 28 11:06:25 loftvolumio volumio[1338]: [Metrics] CommandRouter: 86s 475.43ms Aug 28 11:06:25 loftvolumio volumio[1338]: info: CoreCommandRouter::volumiosetStartupVolume Aug 28 11:06:25 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 11:06:25 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 11:06:25 loftvolumio volumio[1338]: info: CoreCommandRouter::Close All Modals sent Aug 28 11:06:25 loftvolumio volumio[1338]: info: CoreCommandRouter::Close All Modals sent Aug 28 11:06:26 loftvolumio sudo[2038]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Aug 28 11:06:26 loftvolumio sudo[2038]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 11:06:26 loftvolumio sudo[2040]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Aug 28 11:06:26 loftvolumio sudo[2040]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 11:06:26 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable Aug 28 11:06:26 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Aug 28 11:06:26 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect Aug 28 11:06:26 loftvolumio sudo[2038]: pam_unix(sudo:session): session closed for user root Aug 28 11:06:26 loftvolumio sudo[2040]: pam_unix(sudo:session): session closed for user root Aug 28 11:06:26 loftvolumio volumio[1338]: verbose: New Socket.io Connection to 192.168.0.196 from 192.168.0.203 UA: Mozilla/5.0 (Linux; Android 17; Pixel 8 Build/CP2A.260805.005; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/151.0.7922.199 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 11 Aug 28 11:06:26 loftvolumio volumio[1338]: info: Initializing connection to go-librespot Websocket Aug 28 11:06:26 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Aug 28 11:06:26 loftvolumio volumio[1338]: info: CoreCommandRouter::volumioGetVisibleSources Aug 28 11:06:26 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 28 11:06:27 loftvolumio volumio[1338]: info: CoreCommandRouter::volumioGetState Aug 28 11:06:27 loftvolumio volumio[1338]: info: CorePlayQueue::getTrack 0 Aug 28 11:06:27 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Aug 28 11:06:27 loftvolumio volumio[1338]: info: CoreCommandRouter::volumioGetQueue Aug 28 11:06:27 loftvolumio volumio[1338]: info: CoreStateMachine::getQueue Aug 28 11:06:27 loftvolumio volumio[1338]: info: CorePlayQueue::getQueue Aug 28 11:06:27 loftvolumio volumio[1338]: info: Listing playlists Aug 28 11:06:27 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Aug 28 11:06:27 loftvolumio volumio[1338]: info: Received Get System Info Aug 28 11:06:27 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 28 11:06:27 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 28 11:06:27 loftvolumio volumio[1338]: info: Discovery: Getting this device information Aug 28 11:06:27 loftvolumio volumio[1338]: info: CoreCommandRouter::volumioGetState Aug 28 11:06:27 loftvolumio volumio[1338]: info: CorePlayQueue::getTrack 0 Aug 28 11:06:27 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 28 11:06:27 loftvolumio volumio[1338]: info: CoreCommandRouter::volumioGetState Aug 28 11:06:27 loftvolumio volumio[1338]: info: CorePlayQueue::getTrack 0 Aug 28 11:06:27 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Aug 28 11:06:27 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Aug 28 11:06:27 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Aug 28 11:06:27 loftvolumio volumio[1338]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 28 11:06:27 loftvolumio volumio[1338]: info: MYVOLUMIO: Adding device Aug 28 11:06:27 loftvolumio volumio[1338]: info: MYVOLUMIO: Evaluating Server Aug 28 11:06:27 loftvolumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 12. Aug 28 11:06:27 loftvolumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 28 11:06:28 loftvolumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 28 11:06:28 loftvolumio go-librespot[2058]: go-librespot daemon starting... Aug 28 11:06:28 loftvolumio go-librespot[2062]: time="2026-08-28T11:06:28-06:00" level=info msg="running go-librespot 0.7.1" Aug 28 11:06:28 loftvolumio go-librespot[2062]: time="2026-08-28T11:06:28-06:00" level=debug msg="app state loaded" Aug 28 11:06:28 loftvolumio go-librespot[2062]: time="2026-08-28T11:06:28-06:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 28 11:06:28 loftvolumio go-librespot[2062]: time="2026-08-28T11:06:28-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Aug 28 11:06:28 loftvolumio go-librespot[2062]: time="2026-08-28T11:06:28-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Aug 28 11:06:28 loftvolumio go-librespot[2062]: time="2026-08-28T11:06:28-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Aug 28 11:06:28 loftvolumio go-librespot[2062]: time="2026-08-28T11:06:28-06:00" level=info msg="zeroconf server listening on port 39207" Aug 28 11:06:28 loftvolumio go-librespot[2062]: time="2026-08-28T11:06:28-06:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 28 11:06:28 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 28 11:06:28 loftvolumio volumio[1338]: info: Received Get System Info Aug 28 11:06:28 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 28 11:06:28 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 28 11:06:28 loftvolumio volumio[1338]: info: Discovery: Getting this device information Aug 28 11:06:28 loftvolumio volumio[1338]: info: CoreCommandRouter::volumioGetState Aug 28 11:06:28 loftvolumio volumio[1338]: info: CorePlayQueue::getTrack 0 Aug 28 11:06:28 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 28 11:06:28 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 28 11:06:28 loftvolumio volumio[1338]: info: Received Get System Info Aug 28 11:06:28 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 28 11:06:28 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 28 11:06:28 loftvolumio volumio[1338]: info: Discovery: Getting this device information Aug 28 11:06:28 loftvolumio volumio[1338]: info: CoreCommandRouter::volumioGetState Aug 28 11:06:28 loftvolumio volumio[1338]: info: CorePlayQueue::getTrack 0 Aug 28 11:06:28 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 28 11:06:28 loftvolumio go-librespot[2062]: time="2026-08-28T11:06:28-06:00" level=debug msg="obtained new client token: AAEM46/CRuQTGZJNVHr0BbtlXdZrwZyH4GEKUlccP6GcNMpaz5DBxrUG5DZvpYVPfGe2ytk3tGoDeFMIxhIS+uHJXNzhN+jIxEQM9UR3cXSe4erqbr3nd/Foo8zj16yTeySjZ6/KzT3L7TERtfAE41N0pgw+rp+EpEhHd2TBxXX7t5J6GbLNcsoBwUu7IKJsaKVRlt1abT9/I3dEuybcO8dqF7phr2AhKyPiGwpahLhG6ukfh7crc/w+" Aug 28 11:06:28 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Aug 28 11:06:28 loftvolumio go-librespot[2062]: time="2026-08-28T11:06:28-06:00" level=warning msg="failed to connect to AP ap-guc3.spotify.com:4070, retrying with a different AP" error="dial tcp 104.154.127.247:4070: connect: connection refused" Aug 28 11:06:29 loftvolumio volumio[1338]: info: Setting Geolocation for MyVolumio to us3 Aug 28 11:06:29 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 11:06:29 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 11:06:29 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 11:06:29 loftvolumio go-librespot[2062]: time="2026-08-28T11:06:29-06:00" level=debug msg="connected to ap-guc3.spotify.com:443" Aug 28 11:06:29 loftvolumio go-librespot[2062]: time="2026-08-28T11:06:29-06:00" level=debug msg="completed keyexchange" Aug 28 11:06:29 loftvolumio go-librespot[2062]: time="2026-08-28T11:06:29-06:00" level=debug msg="completed challenge" Aug 28 11:06:29 loftvolumio go-librespot[2062]: time="2026-08-28T11:06:29-06:00" level=info msg="authenticated AP" username="4q*********************3m" Aug 28 11:06:29 loftvolumio volumio[1338]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Aug 28 11:06:29 loftvolumio go-librespot[2062]: time="2026-08-28T11:06:29-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 28 11:06:29 loftvolumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 28 11:06:29 loftvolumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 28 11:06:30 loftvolumio volumio[1338]: info: Updating MyVolumio device info Aug 28 11:06:30 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 11:06:30 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 11:06:30 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 11:06:30 loftvolumio volumio[1338]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Aug 28 11:06:30 loftvolumio volumio[1338]: info: Initializing connection to go-librespot Websocket Aug 28 11:06:30 loftvolumio volumio[1338]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 28 11:06:32 loftvolumio volumio[1338]: info: BOOT COMPLETED Aug 28 11:06:32 loftvolumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 13. Aug 28 11:06:32 loftvolumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 28 11:06:32 loftvolumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 28 11:06:32 loftvolumio go-librespot[2086]: go-librespot daemon starting... Aug 28 11:06:32 loftvolumio go-librespot[2087]: time="2026-08-28T11:06:32-06:00" level=info msg="running go-librespot 0.7.1" Aug 28 11:06:32 loftvolumio go-librespot[2087]: time="2026-08-28T11:06:32-06:00" level=debug msg="app state loaded" Aug 28 11:06:32 loftvolumio go-librespot[2087]: time="2026-08-28T11:06:32-06:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 28 11:06:33 loftvolumio volumio[1338]: info: Initializing connection to go-librespot Websocket Aug 28 11:06:33 loftvolumio go-librespot[2087]: time="2026-08-28T11:06:33-06:00" level=debug msg="new websocket client" Aug 28 11:06:33 loftvolumio volumio[1338]: info: Connection to go-librespot Websocket established Aug 28 11:06:33 loftvolumio volumio5-onboarding[1660]: time=2026-08-28T11:06:33.354-06:00 level=INFO msg="navigate to next page" component=server type=REQUEST_TYPE_CONTINUE_NAVIGATION peer="192.168.0.203:48634 @ 0x2452420" latency=-1.472401796s timeout=10s from=APP_PAGE_ROOT to=APP_PAGE_LEGACY_DEVICE Aug 28 11:06:33 loftvolumio go-librespot[2087]: time="2026-08-28T11:06:33-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Aug 28 11:06:33 loftvolumio go-librespot[2087]: time="2026-08-28T11:06:33-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Aug 28 11:06:33 loftvolumio go-librespot[2087]: time="2026-08-28T11:06:33-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Aug 28 11:06:33 loftvolumio volumio5-onboarding[1660]: time=2026-08-28T11:06:33.373-06:00 level=INFO msg="check connectivity" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.203:48634 @ 0x2452420" latency=-1.47315939s timeout=10s Aug 28 11:06:33 loftvolumio go-librespot[2087]: time="2026-08-28T11:06:33-06:00" level=info msg="zeroconf server listening on port 39383" Aug 28 11:06:33 loftvolumio volumio5-onboarding[1660]: time=2026-08-28T11:06:33.385-06:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.203:48634 @ 0x2452420" latency=-1.47315939s timeout=10s endpoint=https://radio-directory.firebaseapp.com duration=12.104383ms Aug 28 11:06:33 loftvolumio go-librespot[2087]: time="2026-08-28T11:06:33-06:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 28 11:06:33 loftvolumio volumio5-onboarding[1660]: time=2026-08-28T11:06:33.447-06:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.203:48634 @ 0x2452420" latency=-1.47315939s timeout=10s endpoint=https://myvolumio.firebaseio.com duration=72.782371ms Aug 28 11:06:33 loftvolumio volumio5-onboarding[1660]: time=2026-08-28T11:06:33.448-06:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.203:48634 @ 0x2452420" latency=-1.47315939s timeout=10s endpoint=https://securetoken.googleapis.com duration=74.570743ms Aug 28 11:06:33 loftvolumio volumio5-onboarding[1660]: time=2026-08-28T11:06:33.449-06:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.203:48634 @ 0x2452420" latency=-1.47315939s timeout=10s endpoint=https://google.com duration=75.897526ms Aug 28 11:06:33 loftvolumio volumio5-onboarding[1660]: time=2026-08-28T11:06:33.460-06:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.203:48634 @ 0x2452420" latency=-1.47315939s timeout=10s endpoint=https://database.volumio.cloud duration=84.190335ms Aug 28 11:06:33 loftvolumio volumio5-onboarding[1660]: time=2026-08-28T11:06:33.464-06:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.203:48634 @ 0x2452420" latency=-1.47315939s timeout=10s endpoint=https://functions.volumio.cloud duration=88.31135ms Aug 28 11:06:33 loftvolumio volumio5-onboarding[1660]: time=2026-08-28T11:06:33.464-06:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.203:48634 @ 0x2452420" latency=-1.47315939s timeout=10s endpoint=https://functions.volumio.cloud duration=90.072926ms Aug 28 11:06:33 loftvolumio volumio5-onboarding[1660]: time=2026-08-28T11:06:33.490-06:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.203:48634 @ 0x2452420" latency=-1.47315939s timeout=10s endpoint=https://browsing-performer.dfs.volumio.org duration=115.444162ms Aug 28 11:06:33 loftvolumio volumio5-onboarding[1660]: time=2026-08-28T11:06:33.499-06:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.203:48634 @ 0x2452420" latency=-1.47315939s timeout=10s endpoint=https://www.googleapis.com duration=125.811969ms Aug 28 11:06:33 loftvolumio volumio5-onboarding[1660]: time=2026-08-28T11:06:33.519-06:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.203:48634 @ 0x2452420" latency=-1.47315939s timeout=10s endpoint=https://oauth-performer.dfs.volumio.org duration=144.29792ms Aug 28 11:06:33 loftvolumio volumio5-onboarding[1660]: time=2026-08-28T11:06:33.533-06:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.203:48634 @ 0x2452420" latency=-1.47315939s timeout=10s endpoint=http://pushupdates.volumio.org duration=157.350091ms Aug 28 11:06:33 loftvolumio volumio5-onboarding[1660]: time=2026-08-28T11:06:33.555-06:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.203:48634 @ 0x2452420" latency=-1.47315939s timeout=10s endpoint=http://plugins.volumio.org duration=179.519488ms Aug 28 11:06:33 loftvolumio go-librespot[2087]: time="2026-08-28T11:06:33-06:00" level=debug msg="obtained new client token: AAE91BZqkjkBT0l2obM0gF1GdjuJqxhTcs+PtF4pExtsaXKG0SufMr9ixLhBxVMpgyCPr8Fw2zwyaQvk2+M5/8qE3QUw552HcNr948EInQb95/D4UG0+WGb61nTbKseC2UFwTIHIUMkXsSDE+3bMXMv2Ai2/Iz6LP4vFNnxhXsoU4AiHCKk/yjCnOdhiGRRGpmqE+8OstSYEfpJdh6hlbv1vNOhhoFtqfSw4N2IKalC3mLfiUgh9OWgM" Aug 28 11:06:33 loftvolumio volumio5-onboarding[1660]: time=2026-08-28T11:06:33.608-06:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.203:48634 @ 0x2452420" latency=-1.47315939s timeout=10s endpoint=http://cddb.volumio.org duration=233.229061ms Aug 28 11:06:33 loftvolumio go-librespot[2087]: time="2026-08-28T11:06:33-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Aug 28 11:06:33 loftvolumio go-librespot[2087]: time="2026-08-28T11:06:33-06:00" level=debug msg="completed keyexchange" Aug 28 11:06:33 loftvolumio go-librespot[2087]: time="2026-08-28T11:06:33-06:00" level=debug msg="completed challenge" Aug 28 11:06:33 loftvolumio go-librespot[2087]: time="2026-08-28T11:06:33-06:00" level=info msg="authenticated AP" username="4q*********************3m" Aug 28 11:06:34 loftvolumio go-librespot[2087]: time="2026-08-28T11:06:34-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 28 11:06:34 loftvolumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 28 11:06:34 loftvolumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 28 11:06:34 loftvolumio volumio[1338]: info: Connection to go-librespot Websocket closed Aug 28 11:06:34 loftvolumio sudo[2098]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Aug 28 11:06:34 loftvolumio sudo[2098]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 11:06:34 loftvolumio sudo[2099]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Aug 28 11:06:34 loftvolumio sudo[2099]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 11:06:34 loftvolumio sudo[2098]: pam_unix(sudo:session): session closed for user root Aug 28 11:06:34 loftvolumio sudo[2099]: pam_unix(sudo:session): session closed for user root Aug 28 11:06:34 loftvolumio volumio[1338]: verbose: New Socket.io Connection to 192.168.0.196 from 192.168.0.203 UA: Mozilla/5.0 (Linux; Android 17; Pixel 8 Build/CP2A.260805.005; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/151.0.7922.199 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 11 Aug 28 11:06:35 loftvolumio sudo[2103]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Aug 28 11:06:35 loftvolumio sudo[2103]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 11:06:35 loftvolumio sudo[2103]: pam_unix(sudo:session): session closed for user root Aug 28 11:06:35 loftvolumio sudo[2105]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Aug 28 11:06:35 loftvolumio sudo[2105]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 11:06:35 loftvolumio sudo[2105]: pam_unix(sudo:session): session closed for user root Aug 28 11:06:35 loftvolumio volumio[1338]: verbose: New Socket.io Connection to 192.168.0.196 from 192.168.0.203 UA: Mozilla/5.0 (Linux; Android 17; Pixel 8 Build/CP2A.260805.005; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/151.0.7922.199 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 11 Aug 28 11:06:35 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Aug 28 11:06:35 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Aug 28 11:06:35 loftvolumio volumio[1338]: info: CoreCommandRouter::volumioGetVisibleSources Aug 28 11:06:35 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 28 11:06:35 loftvolumio volumio[1338]: info: CoreCommandRouter::volumioGetState Aug 28 11:06:35 loftvolumio volumio[1338]: info: CorePlayQueue::getTrack 0 Aug 28 11:06:35 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Aug 28 11:06:35 loftvolumio volumio[1338]: info: CoreCommandRouter::volumioGetQueue Aug 28 11:06:35 loftvolumio volumio[1338]: info: CoreStateMachine::getQueue Aug 28 11:06:35 loftvolumio volumio[1338]: info: CorePlayQueue::getQueue Aug 28 11:06:35 loftvolumio volumio[1338]: info: Listing playlists Aug 28 11:06:35 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Aug 28 11:06:35 loftvolumio volumio[1338]: info: Received Get System Info Aug 28 11:06:35 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 28 11:06:35 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 28 11:06:35 loftvolumio volumio[1338]: info: Discovery: Getting this device information Aug 28 11:06:35 loftvolumio volumio[1338]: info: CoreCommandRouter::volumioGetState Aug 28 11:06:36 loftvolumio volumio[1338]: info: CorePlayQueue::getTrack 0 Aug 28 11:06:36 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 28 11:06:36 loftvolumio volumio[1338]: info: CoreCommandRouter::volumioGetState Aug 28 11:06:36 loftvolumio volumio[1338]: info: CorePlayQueue::getTrack 0 Aug 28 11:06:36 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Aug 28 11:06:36 loftvolumio volumio[1338]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Aug 28 11:06:36 loftvolumio volumio[1338]: info: Getting Spotify volume Aug 28 11:06:36 loftvolumio volumio[1338]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 28 11:06:36 loftvolumio volumio[1338]: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 28 11:06:36 loftvolumio volumio[1338]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Aug 28 11:06:36 loftvolumio volumio[1338]: errno: -111, Aug 28 11:06:36 loftvolumio volumio[1338]: code: 'ECONNREFUSED', Aug 28 11:06:36 loftvolumio volumio[1338]: syscall: 'connect', Aug 28 11:06:36 loftvolumio volumio[1338]: address: '127.0.0.1', Aug 28 11:06:36 loftvolumio volumio[1338]: port: 9879, Aug 28 11:06:36 loftvolumio volumio[1338]: response: undefined Aug 28 11:06:36 loftvolumio volumio[1338]: } Aug 28 11:06:36 loftvolumio volumio[1338]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 28 11:06:37 loftvolumio bluealsa[968]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_70_B9_73_C8_9D_FE, ...) Aug 28 11:06:37 loftvolumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 14. Aug 28 11:06:37 loftvolumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 28 11:06:37 loftvolumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 28 11:06:37 loftvolumio go-librespot[2120]: go-librespot daemon starting... Aug 28 11:06:37 loftvolumio go-librespot[2121]: time="2026-08-28T11:06:37-06:00" level=info msg="running go-librespot 0.7.1" Aug 28 11:06:37 loftvolumio go-librespot[2121]: time="2026-08-28T11:06:37-06:00" level=debug msg="app state loaded" Aug 28 11:06:37 loftvolumio go-librespot[2121]: time="2026-08-28T11:06:37-06:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 28 11:06:37 loftvolumio go-librespot[2121]: time="2026-08-28T11:06:37-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Aug 28 11:06:37 loftvolumio go-librespot[2121]: time="2026-08-28T11:06:37-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Aug 28 11:06:37 loftvolumio go-librespot[2121]: time="2026-08-28T11:06:37-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Aug 28 11:06:37 loftvolumio go-librespot[2121]: time="2026-08-28T11:06:37-06:00" level=info msg="zeroconf server listening on port 35831" Aug 28 11:06:37 loftvolumio go-librespot[2121]: time="2026-08-28T11:06:37-06:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 28 11:06:38 loftvolumio go-librespot[2121]: time="2026-08-28T11:06:37-06:00" level=debug msg="obtained new client token: AAGAjygpPE7B/wyQG3zcpOXZQyH0Wp2VbURzjrFebPfS4aPDD13gwgK1Eo9/tF7lG0LLior/6XviVRxzmTwndVTW08vC2VH4m6MLTtLMLhmnz+Z2IyCnBRBkizaCZQZLGdNf6LhC1OTUGmqGuIijLp52CkuLbzF791e/tJKfljvXTnYvJy+vicZwB5VzVe5FgW4MSLXfLabLC8KaB/9d82C6L6M1hxy/TiIJkiE9VGO82NGeqcO3o17K" Aug 28 11:06:38 loftvolumio go-librespot[2121]: time="2026-08-28T11:06:38-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Aug 28 11:06:38 loftvolumio go-librespot[2121]: time="2026-08-28T11:06:38-06:00" level=debug msg="completed keyexchange" Aug 28 11:06:38 loftvolumio go-librespot[2121]: time="2026-08-28T11:06:38-06:00" level=debug msg="completed challenge" Aug 28 11:06:38 loftvolumio go-librespot[2121]: time="2026-08-28T11:06:38-06:00" level=info msg="authenticated AP" username="4q*********************3m" Aug 28 11:06:38 loftvolumio go-librespot[2121]: time="2026-08-28T11:06:38-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 28 11:06:38 loftvolumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 28 11:06:38 loftvolumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 28 11:06:39 loftvolumio volumio5-onboarding[1660]: time=2026-08-28T11:06:39.879-06:00 level=INFO msg="new address was allocated" component=ble/conn old=1 new=2 Aug 28 11:06:40 loftvolumio dbus-daemon[779]: [system] Rejected send message, 0 matched rules; type="error", sender=":1.17" (uid=0 pid=1660 comm="/usr/bin/volumio5-onboarding") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.3" (uid=0 pid=806 comm="/usr/libexec/bluetooth/bluetoothd --noplugin=sap,b") Aug 28 11:06:41 loftvolumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 15. Aug 28 11:06:41 loftvolumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 28 11:06:41 loftvolumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 28 11:06:41 loftvolumio go-librespot[2145]: go-librespot daemon starting... Aug 28 11:06:41 loftvolumio go-librespot[2146]: time="2026-08-28T11:06:41-06:00" level=info msg="running go-librespot 0.7.1" Aug 28 11:06:41 loftvolumio go-librespot[2146]: time="2026-08-28T11:06:41-06:00" level=debug msg="app state loaded" Aug 28 11:06:41 loftvolumio go-librespot[2146]: time="2026-08-28T11:06:41-06:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 28 11:06:42 loftvolumio go-librespot[2146]: time="2026-08-28T11:06:42-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Aug 28 11:06:42 loftvolumio go-librespot[2146]: time="2026-08-28T11:06:42-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Aug 28 11:06:42 loftvolumio go-librespot[2146]: time="2026-08-28T11:06:42-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Aug 28 11:06:42 loftvolumio go-librespot[2146]: time="2026-08-28T11:06:42-06:00" level=info msg="zeroconf server listening on port 35159" Aug 28 11:06:42 loftvolumio go-librespot[2146]: time="2026-08-28T11:06:42-06:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 28 11:06:42 loftvolumio go-librespot[2146]: time="2026-08-28T11:06:42-06:00" level=debug msg="obtained new client token: AAGBD+wmB4SSdA6zQ9cno+gsgzeWzmmEFsGTlEWWqcStf72qQZI5qlQ7mmb/Ezdtlj1zi3z5scQKYPlYz64IJ5EGkG7TBW/oAeDpqXU4NlFO0zUOyceNuwpqt5u1K04tXK064uR3QgIQ0t3tKC7MEAG4hJq101IPhKYgyWHN8uX8E1A9hvdOYso/39oxxuTfsJ3HaVyZDUO69reve1Z1PqCBOhOaQ49iu1nWSdwJRFR5OLdM0dEHesuR" Aug 28 11:06:42 loftvolumio go-librespot[2146]: time="2026-08-28T11:06:42-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Aug 28 11:06:42 loftvolumio go-librespot[2146]: time="2026-08-28T11:06:42-06:00" level=debug msg="completed keyexchange" Aug 28 11:06:42 loftvolumio go-librespot[2146]: time="2026-08-28T11:06:42-06:00" level=debug msg="completed challenge" Aug 28 11:06:42 loftvolumio go-librespot[2146]: time="2026-08-28T11:06:42-06:00" level=info msg="authenticated AP" username="4q*********************3m" Aug 28 11:06:43 loftvolumio go-librespot[2146]: time="2026-08-28T11:06:43-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 28 11:06:43 loftvolumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 28 11:06:43 loftvolumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 28 11:06:44 loftvolumio sudo[2159]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-08-28 11:05' Aug 28 11:06:44 loftvolumio sudo[2159]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) PRETTY_NAME="Raspbian GNU/Linux 12 (bookworm)" NAME="Raspbian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="18952480e8d8c63f22208e9007a0f47a9563eae6" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="0e58f1861fa88e02087981b8d91f7511f0e7011b" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue Mar 24 17:20:52 UTC 2026" VOLUMIO_VERSION="4.119" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="d0c2fd9dbc5e70e58c32413c12353563"