Aug 30 16:31:21 lapa ntpd[926]: CLOCK: time stepped by 13727400.503460 Aug 30 16:31:21 lapa ntpd[926]: CLOCK: time changed from 2026-03-24 to 2026-08-30 Aug 30 16:31:21 lapa ntpd[926]: INIT: MRU 13107 entries, 13 hash bits, 32768 bytes Aug 30 16:31:21 lapa volumio[1124]: info: Plugin folders cleanup Aug 30 16:31:21 lapa volumio[1124]: info: Scanning into folder /volumio/app/plugins/ Aug 30 16:31:21 lapa volumio[1124]: info: Scanning category audio_interface Aug 30 16:31:21 lapa volumio[1124]: info: Scanning category miscellanea Aug 30 16:31:21 lapa volumio[1124]: info: Scanning category music_service Aug 30 16:31:21 lapa volumio[1124]: info: Scanning category plugins.json Aug 30 16:31:21 lapa volumio[1124]: info: Scanning category system_controller Aug 30 16:31:21 lapa volumio[1124]: info: Scanning category user_interface Aug 30 16:31:21 lapa volumio[1124]: info: Scanning into folder /data/plugins/ Aug 30 16:31:21 lapa volumio[1124]: info: Scanning category music_service Aug 30 16:31:21 lapa volumio[1124]: info: Plugin folders cleanup completed Aug 30 16:31:21 lapa volumio[1124]: info: ------------------------------------------- Aug 30 16:31:21 lapa volumio[1124]: info: ----- Core plugins startup ---- Aug 30 16:31:21 lapa volumio[1124]: info: ------------------------------------------- Aug 30 16:31:21 lapa volumio[1124]: info: Loading plugins from folder /volumio/app/plugins/ Aug 30 16:31:21 lapa volumio[1124]: info: Adding plugin upnp to MyMusic Plugins Aug 30 16:31:21 lapa volumio[1124]: info: Adding plugin airplay_emulation to MyMusic Plugins Aug 30 16:31:21 lapa volumio[1124]: info: Adding plugin upnp_browser to MyMusic Plugins Aug 30 16:31:21 lapa volumio[1124]: info: Loading plugins from folder /data/plugins/ Aug 30 16:31:21 lapa volumio[1124]: info: Loading plugin "system"... Aug 30 16:31:21 lapa volumio[1124]: info: Loading plugin "appearance"... Aug 30 16:31:21 lapa systemd[1]: Starting dpkg-db-backup.service - Daily dpkg database backup service... Aug 30 16:31:21 lapa systemd[1]: Starting e2scrub_all.service - Online ext4 Metadata Check for All Filesystems... Aug 30 16:31:21 lapa systemd[1]: Started ntpsec-rotate-stats.service - Rotate ntpd stats. Aug 30 16:31:21 lapa systemd[1]: e2scrub_all.service: Deactivated successfully. Aug 30 16:31:21 lapa systemd[1]: Finished e2scrub_all.service - Online ext4 Metadata Check for All Filesystems. Aug 30 16:31:21 lapa systemd[1]: ntpsec-rotate-stats.service: Deactivated successfully. Aug 30 16:31:21 lapa systemd[1]: dpkg-db-backup.service: Deactivated successfully. Aug 30 16:31:21 lapa systemd[1]: Finished dpkg-db-backup.service - Daily dpkg database backup service. Aug 30 16:31:24 lapa volumio[1124]: info: Loading plugin "network"... Aug 30 16:31:24 lapa volumio[1124]: info: Refreshing Cached IP Addresses Aug 30 16:31:24 lapa volumio[1124]: info: Loading plugin "services"... Aug 30 16:31:24 lapa volumio[1124]: info: Loading plugin "volumio5onboarding"... Aug 30 16:31:24 lapa systemd[1]: systemd-fsckd.service: Deactivated successfully. Aug 30 16:31:24 lapa sudo[1275]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Aug 30 16:31:24 lapa sudo[1286]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Aug 30 16:31:24 lapa sudo[1286]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 16:31:24 lapa sudo[1275]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 16:31:24 lapa sudo[1277]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Aug 30 16:31:24 lapa sudo[1277]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 16:31:24 lapa volumio[1124]: info: Loading plugin "alsa_controller"... Aug 30 16:31:24 lapa sudo[1275]: pam_unix(sudo:session): session closed for user root Aug 30 16:31:24 lapa sudo[1277]: pam_unix(sudo:session): session closed for user root Aug 30 16:31:24 lapa volumio[1124]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 30 16:31:24 lapa volumio[1124]: info: Loading plugin "wizard"... Aug 30 16:31:24 lapa volumio[1124]: info: Loading plugin "networkfs"... Aug 30 16:31:24 lapa volumio[1124]: info: Starting Udev Watcher for removable devices Aug 30 16:31:24 lapa sudo[1309]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=Jr,password=jr,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //192.168.1.2/Music /mnt/NAS/Yollanda Aug 30 16:31:24 lapa volumio[1124]: info: Ignoring mount for partition: boot Aug 30 16:31:24 lapa volumio[1124]: info: Ignoring mount for partition: volumio Aug 30 16:31:24 lapa volumio[1124]: info: Ignoring mount for partition: volumio_data Aug 30 16:31:24 lapa volumio[1124]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Aug 30 16:31:24 lapa volumio[1124]: info: Loading plugin "volumio_command_line_client"... Aug 30 16:31:24 lapa sudo[1309]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 16:31:24 lapa volumio[1124]: info: Plugin upnp is not enabled Aug 30 16:31:24 lapa volumio[1124]: info: Loading plugin "my_music"... Aug 30 16:31:24 lapa volumio[1124]: info: Loading plugin "mpd"... Aug 30 16:31:24 lapa kernel: netfs: FS-Cache loaded Aug 30 16:31:24 lapa kernel: Key type cifs.spnego registered Aug 30 16:31:24 lapa kernel: Key type cifs.idmap registered Aug 30 16:31:24 lapa 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 30 16:31:24 lapa kernel: CIFS: Attempting to mount //192.168.1.2/Music Aug 30 16:31:25 lapa volumio[1124]: info: Loading plugin "upnp_browser"... Aug 30 16:31:25 lapa sudo[1309]: pam_unix(sudo:session): session closed for user root Aug 30 16:31:26 lapa wpa_supplicant[1085]: RRM: Ignoring radio measurement request: Not RRM network Aug 30 16:31:27 lapa sudo[1286]: pam_unix(sudo:session): session closed for user root Aug 30 16:31:27 lapa systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 2. Aug 30 16:31:27 lapa systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Aug 30 16:31:27 lapa volumio[1124]: info: Starting UPNP Browser Aug 30 16:31:27 lapa systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Aug 30 16:31:27 lapa volumio[1124]: info: Loading plugin "alarm-clock"... Aug 30 16:31:28 lapa upmpdcli[1346]: Could not open config: /tmp/upmpdcli.conf Aug 30 16:31:28 lapa systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Aug 30 16:31:28 lapa systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Aug 30 16:31:28 lapa volumio[1124]: info: Loading plugin "airplay_emulation"... Aug 30 16:31:28 lapa volumio[1124]: info: Starting Shairport Sync Aug 30 16:31:28 lapa volumio[1124]: info: Loading plugin "last_100"... Aug 30 16:31:28 lapa volumio[1124]: info: Loading plugin "webradio"... Aug 30 16:31:28 lapa volumio[1124]: info: Loading plugin "i2s_dacs"... Aug 30 16:31:28 lapa volumio[1124]: info: I2S DAC not set, start Auto-detection Aug 30 16:31:28 lapa volumio[1124]: info: Loading plugin "volumiodiscovery"... Aug 30 16:31:28 lapa systemd[1]: systemd-hostnamed.service: Deactivated successfully. Aug 30 16:31:28 lapa volumio[1124]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Aug 30 16:31:28 lapa node[1124]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Aug 30 16:31:28 lapa volumio[1124]: *** WARNING *** Please fix your application to use the native API of Avahi! Aug 30 16:31:28 lapa node[1124]: *** WARNING *** Please fix your application to use the native API of Avahi! Aug 30 16:31:28 lapa volumio[1124]: *** WARNING *** For more information see Aug 30 16:31:28 lapa node[1124]: *** WARNING *** For more information see Aug 30 16:31:28 lapa volumio[1124]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Aug 30 16:31:28 lapa node[1124]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Aug 30 16:31:28 lapa volumio[1124]: *** WARNING *** Please fix your application to use the native API of Avahi! Aug 30 16:31:28 lapa node[1124]: *** WARNING *** Please fix your application to use the native API of Avahi! Aug 30 16:31:28 lapa volumio[1124]: *** WARNING *** For more information see Aug 30 16:31:28 lapa node[1124]: *** WARNING *** For more information see Aug 30 16:31:28 lapa volumio[1124]: info: Applying required configuration parameters for plugin volumiodiscovery Aug 30 16:31:28 lapa volumio[1124]: info: Discovery: Started advertising with name: LAPA Aug 30 16:31:28 lapa volumio[1124]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Aug 30 16:31:28 lapa volumio[1124]: info: Loading plugin "spop"... Aug 30 16:31:31 lapa volumio[1124]: info: Loading plugin "outputs"... Aug 30 16:31:31 lapa volumio[1124]: info: Loading plugin "albumart"... Aug 30 16:31:31 lapa volumio[1124]: info: Plugin example_plugin is not enabled Aug 30 16:31:31 lapa volumio[1124]: info: Loading plugin "inputs"... Aug 30 16:31:31 lapa volumio[1124]: info: Loading plugin "updater_comm"... Aug 30 16:31:31 lapa volumio[1124]: info: Plugin mpdemulation is not enabled Aug 30 16:31:31 lapa volumio[1124]: info: Loading plugin "rest_api"... Aug 30 16:31:31 lapa volumio[1124]: info: Loading plugin "websocket"... Aug 30 16:31:31 lapa volumio[1124]: info: Starting Socket.io Server version 1.7.4 Aug 30 16:31:31 lapa volumio[1124]: info: Loading i18n strings for locale en Aug 30 16:31:31 lapa volumio[1124]: Updating browse sources language Aug 30 16:31:31 lapa volumio[1124]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 30 16:31:32 lapa volumio[1124]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 30 16:31:32 lapa volumio[1124]: info: CoreCommandRouter::initPlayerControls Aug 30 16:31:32 lapa volumio[1124]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 16:31:32 lapa volumio[1124]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 16:31:32 lapa volumio[1124]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 16:31:32 lapa volumio[1124]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 16:31:32 lapa volumio[1124]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 16:31:32 lapa volumio[1124]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 16:31:32 lapa volumio[1124]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 16:31:32 lapa volumio[1124]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 16:31:32 lapa volumio[1124]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 30 16:31:32 lapa volumio[1124]: Express server listening on port 3000 Aug 30 16:31:32 lapa volumio[1124]: [Metrics] WebUI: 13s 887.77ms Aug 30 16:31:32 lapa volumio[1124]: info: CoreStateMachine::resetVolumioState Aug 30 16:31:32 lapa volumio[1124]: info: CoreStateMachine::getcurrentVolume Aug 30 16:31:32 lapa volumio[1124]: info: CoreCommandRouter::volumioRetrievevolume Aug 30 16:31:32 lapa volumio[1124]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 30 16:31:32 lapa volumio[1124]: info: Volumio Network Manager: Network status updated: 2 Aug 30 16:31:32 lapa volumio[1124]: info: VolumeController:: Volume=86 Mute =false Aug 30 16:31:32 lapa volumio[1124]: info: CoreStateMachine::pushState Aug 30 16:31:32 lapa volumio[1124]: info: CorePlayQueue::getTrack 0 Aug 30 16:31:32 lapa volumio[1124]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 30 16:31:32 lapa volumio[1124]: info: CoreCommandRouter::volumioPushState Aug 30 16:31:32 lapa volumio[1124]: info: CoreStateMachine::updateTrackBlock Aug 30 16:31:32 lapa volumio[1124]: info: CorePlayQueue::getTrackBlock Aug 30 16:31:32 lapa volumio[1124]: info: CoreCommandRouter::volumioRetrievevolume Aug 30 16:31:32 lapa volumio[1124]: info: Reloading queue from file Aug 30 16:31:32 lapa volumio[1124]: info: Setting Device type: Raspberry PI Aug 30 16:31:32 lapa volumio[1124]: info: CoreStateMachine::setRepeat null single undefined Aug 30 16:31:32 lapa volumio[1124]: info: CoreStateMachine::pushState Aug 30 16:31:32 lapa volumio[1124]: info: CorePlayQueue::getTrack 0 Aug 30 16:31:32 lapa volumio[1124]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 30 16:31:32 lapa volumio[1124]: info: CoreCommandRouter::volumioPushState Aug 30 16:31:32 lapa volumio[1124]: info: CoreStateMachine::setRandom null Aug 30 16:31:32 lapa volumio[1124]: info: CoreStateMachine::pushState Aug 30 16:31:32 lapa volumio[1124]: info: CorePlayQueue::getTrack 0 Aug 30 16:31:32 lapa volumio[1124]: info: CoreCommandRouter::volumioPushState Aug 30 16:31:33 lapa volumio[1124]: info: Discovery: adding 20bf9b46-74f2-480c-b5a8-922bff2fe4bb Aug 30 16:31:33 lapa volumio[1124]: info: Discovery: Found device LAPA Aug 30 16:31:33 lapa volumio[1124]: info: CoreCommandRouter::volumioGetState Aug 30 16:31:33 lapa volumio[1124]: info: CorePlayQueue::getTrack 0 Aug 30 16:31:33 lapa volumio[1124]: info: Discovery: this is already registered, 20bf9b46-74f2-480c-b5a8-922bff2fe4bb Aug 30 16:31:33 lapa volumio[1124]: info: Discovery: Found device LAPA Aug 30 16:31:33 lapa volumio[1124]: info: CoreCommandRouter::volumioGetState Aug 30 16:31:33 lapa volumio[1124]: info: CorePlayQueue::getTrack 0 Aug 30 16:31:33 lapa volumio[1124]: info: VolumeController:: Volume=86 Mute =false Aug 30 16:31:33 lapa volumio[1124]: info: CoreStateMachine::pushState Aug 30 16:31:33 lapa volumio[1124]: info: CorePlayQueue::getTrack 0 Aug 30 16:31:33 lapa volumio[1124]: info: CoreCommandRouter::volumioPushState Aug 30 16:31:33 lapa volumio[1124]: info: Completed loading Core Plugins Aug 30 16:31:33 lapa volumio[1124]: info: Preparing to generate the ALSA configuration file Aug 30 16:31:33 lapa volumio[1124]: info: Asound.conf file written Aug 30 16:31:33 lapa sudo[1380]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mv /home/volumio/.asoundrc /etc/asound.conf Aug 30 16:31:33 lapa sudo[1380]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 16:31:33 lapa sudo[1380]: pam_unix(sudo:session): session closed for user root Aug 30 16:31:33 lapa volumio[1124]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:0 use case configuration -2 Aug 30 16:31:33 lapa volumio[1124]: No state is present for card b1 Aug 30 16:31:33 lapa volumio[1124]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:0 use case configuration -2 Aug 30 16:31:33 lapa volumio[1124]: /usr/share/alsa/init/bcm2835:14: control element not found Aug 30 16:31:33 lapa volumio[1124]: No state is present for card b1 Aug 30 16:31:33 lapa volumio[1124]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:1 use case configuration -2 Aug 30 16:31:33 lapa volumio[1124]: No state is present for card Headphones Aug 30 16:31:33 lapa volumio[1124]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:1 use case configuration -2 Aug 30 16:31:33 lapa volumio[1124]: /usr/share/alsa/init/bcm2835:20: control element not found Aug 30 16:31:33 lapa volumio[1124]: No state is present for card Headphones Aug 30 16:31:33 lapa volumio[1124]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:2 use case configuration -2 Aug 30 16:31:33 lapa volumio[1124]: No state is present for card vc4hdmi Aug 30 16:31:33 lapa volumio[1124]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:2 use case configuration -2 Aug 30 16:31:33 lapa volumio[1124]: Found hardware: "vc4-hdmi" "" "" "" "" Aug 30 16:31:33 lapa volumio[1124]: Hardware is initialized using a generic method Aug 30 16:31:33 lapa volumio[1124]: No state is present for card vc4hdmi Aug 30 16:31:33 lapa volumio[1124]: info: Output device has changed, restarting MPD Aug 30 16:31:33 lapa volumio[1124]: info: Output device has changed, restarting Shairport Sync Aug 30 16:31:33 lapa volumio[1124]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 16:31:33 lapa volumio[1124]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 30 16:31:33 lapa volumio[1352]: Forking 3 albumart workers Aug 30 16:31:33 lapa sudo[1386]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Aug 30 16:31:33 lapa sudo[1386]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 16:31:33 lapa sudo[1386]: pam_unix(sudo:session): session closed for user root Aug 30 16:31:33 lapa sudo[1388]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Aug 30 16:31:33 lapa sudo[1388]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 16:31:33 lapa volumio[1124]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Aug 30 16:31:33 lapa volumio[1124]: info: ___________ START PLUGINS ___________ Aug 30 16:31:33 lapa volumio[1124]: info: ControllerMpd::onStart: Initializing MPD Aug 30 16:31:33 lapa volumio[1124]: info: Creating MPD Configuration file Aug 30 16:31:34 lapa systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Aug 30 16:31:34 lapa systemd[1]: Starting mpd.service - Music Player Daemon... Aug 30 16:31:34 lapa volumio[1124]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 30 16:31:34 lapa volumio[1124]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 30 16:31:34 lapa volumio[1124]: info: [1788100294147] CoreMusicLibrary::Adding element Media Servers Aug 30 16:31:34 lapa volumio[1124]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 30 16:31:34 lapa sudo[1400]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumio5-onboarding.service Aug 30 16:31:34 lapa sudo[1400]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 16:31:34 lapa volumio[1124]: info: UPNP Browser: Client initialized successfully Aug 30 16:31:34 lapa sudo[1415]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Aug 30 16:31:34 lapa sudo[1415]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Aug 30 16:31:34 lapa sudo[1432]: /bin/chown: cannot access '/var/log/mpd.log': No such file or directory Aug 30 16:31:34 lapa sudo[1415]: pam_unix(sudo:session): session closed for user root Aug 30 16:31:34 lapa sudo[1414]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Aug 30 16:31:34 lapa sudo[1414]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 16:31:34 lapa sudo[1420]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Aug 30 16:31:34 lapa sudo[1420]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 16:31:34 lapa sudo[1414]: pam_unix(sudo:session): session closed for user root Aug 30 16:31:34 lapa volumio[1124]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 16:31:34 lapa volumio[1124]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 30 16:31:34 lapa systemd[1]: Started volumio5-onboarding.service - Volumio5 Onboarding Server. Aug 30 16:31:34 lapa volumio-remote-updater[651]: [2026-08-30 16:31:34] [connect] Successful connection Aug 30 16:31:34 lapa sudo[1400]: pam_unix(sudo:session): session closed for user root Aug 30 16:31:34 lapa volumio[1124]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Aug 30 16:31:34 lapa volumio[1124]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 16:31:34 lapa volumio[1124]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 30 16:31:34 lapa systemd[1]: mpd.service: Deactivated successfully. Aug 30 16:31:34 lapa systemd[1]: Stopped mpd.service - Music Player Daemon. Aug 30 16:31:34 lapa systemd[1]: mpd.socket: Deactivated successfully. Aug 30 16:31:34 lapa systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Aug 30 16:31:34 lapa systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Aug 30 16:31:34 lapa systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Aug 30 16:31:34 lapa systemd[1]: Starting mpd.service - Music Player Daemon... Aug 30 16:31:35 lapa sudo[1460]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Aug 30 16:31:35 lapa sudo[1460]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Aug 30 16:31:35 lapa sudo[1465]: /bin/chown: cannot access '/var/log/mpd.log': No such file or directory Aug 30 16:31:35 lapa sudo[1460]: pam_unix(sudo:session): session closed for user root Aug 30 16:31:35 lapa volumio[1124]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Aug 30 16:31:35 lapa volumio[1124]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 30 16:31:35 lapa volumio[1124]: info: [1788100295198] CoreMusicLibrary::Adding element Last_100 Aug 30 16:31:35 lapa volumio[1124]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 30 16:31:35 lapa volumio[1124]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 30 16:31:35 lapa volumio[1124]: info: [1788100295202] CoreMusicLibrary::Adding element Webradio Aug 30 16:31:35 lapa volumio[1124]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 30 16:31:35 lapa volumio5-onboarding[1441]: time=2026-08-30T16:31:35.256+02:00 level=INFO msg="running volumio5-device-gateway" version=6370e0a8+CHANGES buildDate=2026-03-06T16:29:42Z Aug 30 16:31:35 lapa volumio[1124]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 30 16:31:35 lapa volumio[1124]: info: Initializing BBC Radios Aug 30 16:31:35 lapa volumio[1124]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 30 16:31:35 lapa volumio[1124]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 30 16:31:36 lapa volumio[1124]: info: Creating Spotify config file Aug 30 16:31:36 lapa volumio[1124]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 16:31:37 lapa wpa_supplicant[1085]: RRM: Ignoring radio measurement request: Not RRM network Aug 30 16:31:37 lapa systemd[1]: Starting setdatetime-helper.service - Time Synchronization Helper Service... Aug 30 16:31:40 lapa volumio[1124]: info: Volumio Calling Home Aug 30 16:31:43 lapa systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 3. Aug 30 16:31:43 lapa systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Aug 30 16:31:43 lapa systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Aug 30 16:31:43 lapa mpd[1466]: 2026-08-30T16:31:43 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Aug 30 16:31:43 lapa upmpdcli[1509]: Could not open config: /tmp/upmpdcli.conf Aug 30 16:31:43 lapa systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Aug 30 16:31:43 lapa systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Aug 30 16:31:43 lapa systemd[1]: Started mpd.service - Music Player Daemon. Aug 30 16:31:43 lapa sudo[1388]: pam_unix(sudo:session): session closed for user root Aug 30 16:31:43 lapa sudo[1420]: pam_unix(sudo:session): session closed for user root Aug 30 16:31:43 lapa volumio[1124]: info: MPD Permissions set Aug 30 16:31:44 lapa volumio[1124]: info: Completed starting Core Plugins Aug 30 16:31:44 lapa volumio[1124]: info: ------------------------------------------- Aug 30 16:31:44 lapa volumio[1124]: info: ----- MyVolumio plugins startup ---- Aug 30 16:31:44 lapa volumio[1124]: info: ------------------------------------------- Aug 30 16:31:44 lapa volumio[1124]: info: [MyVolumio PluginManager] Fetching plans data.... Aug 30 16:31:44 lapa volumio[1124]: info: MPD Permissions set Aug 30 16:31:44 lapa volumio[1124]: info: Volumio called home Aug 30 16:31:44 lapa volumio[1124]: info: Spotify config file written Aug 30 16:31:44 lapa sudo[1516]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Aug 30 16:31:44 lapa sudo[1516]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 16:31:44 lapa 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 30 16:31:44 lapa 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 30 16:31:44 lapa systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 30 16:31:44 lapa go-librespot[1518]: go-librespot daemon starting... Aug 30 16:31:44 lapa sudo[1516]: pam_unix(sudo:session): session closed for user root Aug 30 16:31:45 lapa volumio5-onboarding[1441]: 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:60794->127.0.0.1:3000: i/o timeout Aug 30 16:31:45 lapa systemd[1]: volumio5-onboarding.service: Main process exited, code=exited, status=1/FAILURE Aug 30 16:31:45 lapa systemd[1]: volumio5-onboarding.service: Failed with result 'exit-code'. Aug 30 16:31:45 lapa systemd[1]: volumio5-onboarding.service: Scheduled restart job, restart counter is at 1. Aug 30 16:31:45 lapa systemd[1]: Stopped volumio5-onboarding.service - Volumio5 Onboarding Server. Aug 30 16:31:45 lapa systemd[1]: Started volumio5-onboarding.service - Volumio5 Onboarding Server. Aug 30 16:31:45 lapa systemd[1]: setdatetime-helper.service: Deactivated successfully. Aug 30 16:31:45 lapa systemd[1]: Finished setdatetime-helper.service - Time Synchronization Helper Service. Aug 30 16:31:45 lapa systemd[1]: setdatetime-helper.service: Consumed 1.153s CPU time. Aug 30 16:31:45 lapa volumio5-onboarding[1533]: time=2026-08-30T16:31:45.534+02:00 level=INFO msg="running volumio5-device-gateway" version=6370e0a8+CHANGES buildDate=2026-03-06T16:29:42Z Aug 30 16:31:45 lapa volumio[1397]: Starting albumart workers Aug 30 16:31:45 lapa go-librespot[1519]: time="2026-08-30T16:31:45+02:00" level=info msg="running go-librespot 0.7.1" Aug 30 16:31:45 lapa go-librespot[1519]: time="2026-08-30T16:31:45+02:00" level=debug msg="app state loaded" Aug 30 16:31:45 lapa go-librespot[1519]: time="2026-08-30T16:31:45+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 30 16:31:45 lapa volumio[1396]: Starting albumart workers Aug 30 16:31:46 lapa volumio[1124]: error: MPD error: The expression evaluated to a falsy value: Aug 30 16:31:46 lapa volumio[1124]: assert.ok(self.idling) Aug 30 16:31:46 lapa volumio[1124]: error: The expression evaluated to a falsy value: Aug 30 16:31:46 lapa volumio[1124]: assert.ok(self.idling) Aug 30 16:31:46 lapa go-librespot[1519]: time="2026-08-30T16:31:46+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Aug 30 16:31:46 lapa go-librespot[1519]: time="2026-08-30T16:31:46+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Aug 30 16:31:46 lapa go-librespot[1519]: time="2026-08-30T16:31:46+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Aug 30 16:31:46 lapa go-librespot[1519]: time="2026-08-30T16:31:46+02:00" level=info msg="zeroconf server listening on port 37811" Aug 30 16:31:46 lapa go-librespot[1519]: time="2026-08-30T16:31:46+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 30 16:31:46 lapa volumio[1124]: info: MPD running with PID1466 Aug 30 16:31:46 lapa volumio[1124]: ,establishing connection Aug 30 16:31:46 lapa volumio[1124]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 16:31:46 lapa volumio[1124]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 16:31:46 lapa volumio[1124]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 16:31:46 lapa volumio[1124]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 16:31:46 lapa volumio[1124]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 16:31:46 lapa volumio[1124]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 16:31:46 lapa volumio[1124]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 16:31:46 lapa volumio[1124]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 16:31:46 lapa go-librespot[1519]: time="2026-08-30T16:31:46+02:00" level=debug msg="obtained new client token: AAHjW/+GWV4fj0q/K/aQJ3HbOcpkcAXqn3CHvL4vWpUdvVpEFBmZHAPp0SsgQRUV5GMUB/y1elm7JpQPmmUboijzKrW3VZ8UGeEgtgXTFR429ErFc+S8EajhK3tWMz08z5of4Wglou9lbvZbS7U7iaA68sCVG9jntLFhOR/Zl1CCqaqJihhDc9c7Kv0AuWTihywLJHlqOOezqPEit8QvxIs1rCUYpOAm3uPSEC6gR4QrvLVJa12FO0A3cw==" Aug 30 16:31:46 lapa volumio[1124]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 30 16:31:46 lapa volumio[1124]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 16:31:46 lapa volumio[1124]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 16:31:46 lapa volumio[1124]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 16:31:46 lapa volumio[1124]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 16:31:46 lapa volumio[1124]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 16:31:46 lapa volumio[1124]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 16:31:46 lapa volumio[1124]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 16:31:46 lapa volumio[1124]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 16:31:46 lapa go-librespot[1519]: time="2026-08-30T16:31:46+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 30 16:31:46 lapa volumio[1124]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 16:31:47 lapa volumio[1395]: Starting albumart workers Aug 30 16:31:47 lapa volumio[1124]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 30 16:31:47 lapa volumio[1124]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 16:31:47 lapa volumio[1124]: info: No need to fix Spotify hosts Aug 30 16:31:47 lapa go-librespot[1519]: time="2026-08-30T16:31:47+02:00" level=debug msg="completed keyexchange" Aug 30 16:31:47 lapa go-librespot[1519]: time="2026-08-30T16:31:47+02:00" level=debug msg="completed challenge" Aug 30 16:31:47 lapa go-librespot[1519]: time="2026-08-30T16:31:47+02:00" level=info msg="authenticated AP" username="ha********ts" Aug 30 16:31:47 lapa volumio[1124]: error: updateQueue error: null Aug 30 16:31:47 lapa go-librespot[1519]: time="2026-08-30T16:31:47+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 30 16:31:47 lapa systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 30 16:31:47 lapa systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 30 16:31:48 lapa volumio[1124]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 1 Aug 30 16:31:49 lapa volumio-remote-updater[651]: [2026-08-30 16:31:49] [connect] Successful connection Aug 30 16:31:49 lapa volumio[1124]: 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: 2 Aug 30 16:31:50 lapa volumio[1124]: info: New Spotify access tokenBQDD3S3EzB... Aug 30 16:31:50 lapa volumio[1124]: info: Spotify credentials grant success - running version from March 24, 2019 Aug 30 16:31:50 lapa volumio[1124]: error: updateQueue error: null Aug 30 16:31:50 lapa volumio[1124]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Aug 30 16:31:50 lapa systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Aug 30 16:31:50 lapa systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 30 16:31:50 lapa systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 30 16:31:50 lapa go-librespot[1582]: go-librespot daemon starting... Aug 30 16:31:51 lapa go-librespot[1583]: time="2026-08-30T16:31:51+02:00" level=info msg="running go-librespot 0.7.1" Aug 30 16:31:51 lapa go-librespot[1583]: time="2026-08-30T16:31:51+02:00" level=debug msg="app state loaded" Aug 30 16:31:51 lapa go-librespot[1583]: time="2026-08-30T16:31:51+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 30 16:31:51 lapa go-librespot[1583]: time="2026-08-30T16:31:51+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Aug 30 16:31:51 lapa go-librespot[1583]: time="2026-08-30T16:31:51+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Aug 30 16:31:51 lapa go-librespot[1583]: time="2026-08-30T16:31:51+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Aug 30 16:31:51 lapa go-librespot[1583]: time="2026-08-30T16:31:51+02:00" level=info msg="zeroconf server listening on port 38207" Aug 30 16:31:51 lapa go-librespot[1583]: time="2026-08-30T16:31:51+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 30 16:31:51 lapa go-librespot[1583]: time="2026-08-30T16:31:51+02:00" level=debug msg="obtained new client token: AAHZL1TAB4dUwuPojsKDg7ly+HpArlblsRU8OZb7+Shs+0crWAihJiwKF/+Hy9EqVQQP9J0bTyShKBbjxiqIoEPe43sYR6/6861VqzDk5jfpWTNKH64pnUqUJEJITaVtuAsK9mQJQjWyEqVeBCMgPNaLlwQsq+9BkFIcP8ycObtC9k/UXyejR4dW0x5vX/VXrKT0PmSB9ThxHK/xpem3HiiGXwI0BjzFMphQ5Ghk5m6ylKQNSQUd28+DJw==" Aug 30 16:31:52 lapa go-librespot[1583]: time="2026-08-30T16:31:52+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 30 16:31:52 lapa go-librespot[1583]: time="2026-08-30T16:31:52+02:00" level=debug msg="completed keyexchange" Aug 30 16:31:52 lapa go-librespot[1583]: time="2026-08-30T16:31:52+02:00" level=debug msg="completed challenge" Aug 30 16:31:52 lapa go-librespot[1583]: time="2026-08-30T16:31:52+02:00" level=info msg="authenticated AP" username="ha********ts" Aug 30 16:31:52 lapa volumio[1124]: 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: 2 Aug 30 16:31:52 lapa volumio[1124]: info: Received Get System Info Aug 30 16:31:52 lapa volumio[1124]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 30 16:31:52 lapa volumio[1124]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 30 16:31:52 lapa volumio[1124]: info: Discovery: Getting this device information Aug 30 16:31:52 lapa volumio[1124]: info: CoreCommandRouter::volumioGetState Aug 30 16:31:52 lapa volumio[1124]: info: CorePlayQueue::getTrack 0 Aug 30 16:31:52 lapa volumio[1124]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 30 16:31:52 lapa volumio5-onboarding[1533]: time=2026-08-30T16:31:52.643+02:00 level=INFO msg="system info for bca75da8751ab4c8204b8894c0cad3d9" deviceName=LAPA deviceVariant=volumio deviceModel= softwareVersion=4.119 Aug 30 16:31:52 lapa volumio[1124]: info: go-librespot daemon successfully initialized Aug 30 16:31:52 lapa volumio[1124]: info: Starting Shairport Sync Aug 30 16:31:52 lapa volumio5-onboarding[1533]: time=2026-08-30T16:31:52.717+02:00 level=INFO msg="bootstrapping state" hasInternet=true Aug 30 16:31:52 lapa volumio[1124]: info: Starting Shairport Sync Aug 30 16:31:52 lapa go-librespot[1583]: time="2026-08-30T16:31:52+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 30 16:31:52 lapa volumio[1124]: info: Starting Shairport Sync Aug 30 16:31:52 lapa systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 30 16:31:52 lapa systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 30 16:31:52 lapa sudo[1599]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Aug 30 16:31:52 lapa sudo[1599]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 16:31:53 lapa sudo[1604]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Aug 30 16:31:53 lapa sudo[1604]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 16:31:53 lapa systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Aug 30 16:31:53 lapa systemd[1]: shairport-sync.service: Deactivated successfully. Aug 30 16:31:53 lapa systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 30 16:31:53 lapa systemd[1]: shairport-sync.service: Consumed 1.462s CPU time. Aug 30 16:31:53 lapa sudo[1603]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Aug 30 16:31:53 lapa sudo[1603]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 16:31:53 lapa systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 30 16:31:53 lapa systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Aug 30 16:31:53 lapa sudo[1599]: pam_unix(sudo:session): session closed for user root Aug 30 16:31:53 lapa systemd[1]: shairport-sync.service: Deactivated successfully. Aug 30 16:31:53 lapa systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 30 16:31:53 lapa systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 30 16:31:53 lapa sudo[1603]: pam_unix(sudo:session): session closed for user root Aug 30 16:31:53 lapa sudo[1604]: pam_unix(sudo:session): session closed for user root Aug 30 16:31:53 lapa volumio-remote-updater[651]: [2026-08-30 16:31:53] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1788100309 101 Aug 30 16:31:53 lapa volumio[1124]: 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: 3 Aug 30 16:31:54 lapa volumio[1124]: info: Received Get System Info Aug 30 16:31:54 lapa volumio[1124]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 30 16:31:54 lapa volumio[1124]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 30 16:31:54 lapa volumio[1124]: info: Discovery: Getting this device information Aug 30 16:31:54 lapa volumio[1124]: info: CoreCommandRouter::volumioGetState Aug 30 16:31:54 lapa volumio[1124]: info: CorePlayQueue::getTrack 0 Aug 30 16:31:54 lapa volumio[1124]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 30 16:31:54 lapa volumio[1124]: info: Shairport-Sync Started Aug 30 16:31:54 lapa volumio[1124]: Error adding Membership: Error: addMembership EINVAL Aug 30 16:31:54 lapa volumio[1124]: info: Shairport-Sync Started Aug 30 16:31:54 lapa volumio[1124]: info: Shairport-Sync Started Aug 30 16:31:54 lapa volumio-remote-updater[651]: Test mode disabled Aug 30 16:31:54 lapa volumio-remote-updater[651]: Alpha mode disabled Aug 30 16:31:54 lapa volumio-remote-updater[651]: Alpha legacy test mode disabled Aug 30 16:31:55 lapa volumio[1124]: Cannot compose Albumart path Aug 30 16:31:55 lapa systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Aug 30 16:31:55 lapa systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 30 16:31:56 lapa systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 30 16:31:56 lapa go-librespot[1651]: go-librespot daemon starting... Aug 30 16:31:56 lapa go-librespot[1652]: time="2026-08-30T16:31:56+02:00" level=info msg="running go-librespot 0.7.1" Aug 30 16:31:56 lapa go-librespot[1652]: time="2026-08-30T16:31:56+02:00" level=debug msg="app state loaded" Aug 30 16:31:56 lapa go-librespot[1652]: time="2026-08-30T16:31:56+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 30 16:31:56 lapa go-librespot[1652]: time="2026-08-30T16:31:56+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Aug 30 16:31:56 lapa go-librespot[1652]: time="2026-08-30T16:31:56+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Aug 30 16:31:56 lapa go-librespot[1652]: time="2026-08-30T16:31:56+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Aug 30 16:31:56 lapa go-librespot[1652]: time="2026-08-30T16:31:56+02:00" level=info msg="zeroconf server listening on port 40747" Aug 30 16:31:56 lapa go-librespot[1652]: time="2026-08-30T16:31:56+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 30 16:31:56 lapa go-librespot[1652]: time="2026-08-30T16:31:56+02:00" level=debug msg="obtained new client token: AAEME7w/TxVVE3ibvsuKP2oSkG1FnD5qOoehU4GZFLl22HuHmMxHl009JG7U7iXJBehClTFUnyimaJsDJq8WP2SaGDmakcVWWd7LqRQvSo7xOvKwSwNQW9YiJaGNT6XfyHP8rb7sOv+YK7J5B8JqB/3a9Par5nmfDtYWUx2rwFhvhEqm2c1iYGtzZ27Xtj/eVRpHjeNhZgjLTL8VdG6pzAiNJ/KMnPCbCNTfyd34ZFoZoxIHl/uqZx5Rcw==" Aug 30 16:31:57 lapa go-librespot[1652]: time="2026-08-30T16:31:57+02:00" level=warning msg="failed to connect to AP ap-gew1.spotify.com:4070, retrying with a different AP" error="dial tcp 104.199.65.9:4070: connect: connection refused" Aug 30 16:31:57 lapa volumio[1124]: Cannot compose Albumart path Aug 30 16:31:57 lapa go-librespot[1652]: time="2026-08-30T16:31:57+02:00" level=debug msg="connected to ap-gew1.spotify.com:443" Aug 30 16:31:57 lapa go-librespot[1652]: time="2026-08-30T16:31:57+02:00" level=debug msg="completed keyexchange" Aug 30 16:31:57 lapa go-librespot[1652]: time="2026-08-30T16:31:57+02:00" level=debug msg="completed challenge" Aug 30 16:31:57 lapa go-librespot[1652]: time="2026-08-30T16:31:57+02:00" level=info msg="authenticated AP" username="ha********ts" Aug 30 16:31:57 lapa go-librespot[1652]: time="2026-08-30T16:31:57+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 30 16:31:57 lapa systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 30 16:31:57 lapa systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 30 16:31:58 lapa systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 4. Aug 30 16:31:58 lapa systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Aug 30 16:31:58 lapa systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Aug 30 16:31:58 lapa upmpdcli[1661]: Could not open config: /tmp/upmpdcli.conf Aug 30 16:31:58 lapa systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Aug 30 16:31:58 lapa systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Aug 30 16:31:58 lapa volumio[1124]: info: Initializing connection to go-librespot Websocket Aug 30 16:31:59 lapa volumio[1124]: info: Update Ready: {"changeLogLink":"","description":"You're already on the latest version","title":"No Updates Available","updateavailable":false} Aug 30 16:31:59 lapa volumio[1124]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache Aug 30 16:31:59 lapa volumio[1124]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 30 16:31:59 lapa volumio[1124]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 30 16:31:59 lapa volumio[1124]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 30 16:31:59 lapa volumio[1124]: info: CoreCommandRouter::volumioGetState Aug 30 16:31:59 lapa volumio[1124]: info: CorePlayQueue::getTrack 0 Aug 30 16:31:59 lapa volumio[1124]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 30 16:31:59 lapa volumio[1124]: info: Received Get System Info Aug 30 16:31:59 lapa volumio[1124]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 30 16:31:59 lapa volumio[1124]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 30 16:31:59 lapa volumio[1124]: info: Discovery: Getting this device information Aug 30 16:31:59 lapa volumio[1124]: info: CoreCommandRouter::volumioGetState Aug 30 16:31:59 lapa volumio[1124]: info: CorePlayQueue::getTrack 0 Aug 30 16:31:59 lapa volumio[1124]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 30 16:31:59 lapa volumio[1124]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Aug 30 16:31:59 lapa volumio[1124]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Aug 30 16:31:59 lapa volumio5-onboarding[1533]: time=2026-08-30T16:31:59.243+02:00 level=INFO msg="enabling local network discovery" Aug 30 16:31:59 lapa volumio5-onboarding[1533]: time=2026-08-30T16:31:59.272+02:00 level=INFO msg="enabling BLE discovery" Aug 30 16:31:59 lapa volumio[1124]: SPOTIFY: User informations: {"account_id":"bshiW4IVwH","country":"ZA","display_name":"hannes.roets","email":"hannes.roets@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/hannes.roets"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/hannes.roets","id":"hannes.roets","images":[],"product":"premium","type":"user","uri":"spotify:user:hannes.roets"} Aug 30 16:31:59 lapa volumio[1124]: info: Spotify Successfully logged in Aug 30 16:31:59 lapa volumio[1124]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 30 16:31:59 lapa volumio[1124]: info: [1788100319829] CoreMusicLibrary::Adding element Spotify Aug 30 16:31:59 lapa volumio[1124]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 30 16:31:59 lapa volumio[1124]: Cannot find translation for source Spotify Aug 30 16:32:00 lapa volumio[1124]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Aug 30 16:32:00 lapa volumio[1124]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Aug 30 16:32:00 lapa volumio[1124]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Aug 30 16:32:00 lapa volumio[1124]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Aug 30 16:32:00 lapa volumio[1124]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Aug 30 16:32:00 lapa volumio[1124]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Aug 30 16:32:00 lapa volumio[1124]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Aug 30 16:32:00 lapa volumio[1124]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Aug 30 16:32:00 lapa volumio[1124]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Aug 30 16:32:00 lapa volumio[1124]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Aug 30 16:32:00 lapa volumio[1124]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Aug 30 16:32:00 lapa volumio[1124]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Aug 30 16:32:00 lapa volumio[1124]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Aug 30 16:32:00 lapa volumio[1124]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Aug 30 16:32:00 lapa volumio[1124]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Aug 30 16:32:00 lapa volumio[1124]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Aug 30 16:32:00 lapa volumio[1124]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Aug 30 16:32:00 lapa volumio[1124]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Aug 30 16:32:00 lapa volumio[1124]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Aug 30 16:32:00 lapa volumio[1124]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Aug 30 16:32:00 lapa volumio[1124]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Aug 30 16:32:00 lapa volumio[1124]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Aug 30 16:32:00 lapa volumio[1124]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Aug 30 16:32:00 lapa volumio[1124]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Aug 30 16:32:00 lapa volumio[1124]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Aug 30 16:32:00 lapa volumio[1124]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Aug 30 16:32:00 lapa volumio[1124]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Aug 30 16:32:00 lapa volumio[1124]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Aug 30 16:32:00 lapa volumio[1124]: info: Adding plugin bluetooth to MyMusic Plugins Aug 30 16:32:00 lapa volumio[1124]: info: Adding plugin multiroom to MyMusic Plugins Aug 30 16:32:00 lapa volumio[1124]: info: Adding plugin metavolumio to MyMusic Plugins Aug 30 16:32:00 lapa volumio[1124]: info: Adding plugin cd_controller to MyMusic Plugins Aug 30 16:32:00 lapa volumio[1124]: info: Adding plugin qobuzconnect to MyMusic Plugins Aug 30 16:32:00 lapa volumio[1124]: info: Adding plugin smart_inputs to MyMusic Plugins Aug 30 16:32:00 lapa volumio[1124]: info: Adding plugin tidalconnect to MyMusic Plugins Aug 30 16:32:00 lapa volumio[1124]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Aug 30 16:32:00 lapa volumio5-onboarding[1533]: time=2026-08-30T16:32:00.195+02:00 level=INFO msg="service successfully established" component=discovery/localnet Aug 30 16:32:01 lapa systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Aug 30 16:32:01 lapa systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 30 16:32:01 lapa systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 30 16:32:01 lapa go-librespot[1665]: go-librespot daemon starting... Aug 30 16:32:01 lapa go-librespot[1666]: time="2026-08-30T16:32:01+02:00" level=info msg="running go-librespot 0.7.1" Aug 30 16:32:01 lapa go-librespot[1666]: time="2026-08-30T16:32:01+02:00" level=debug msg="app state loaded" Aug 30 16:32:01 lapa go-librespot[1666]: time="2026-08-30T16:32:01+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 30 16:32:01 lapa go-librespot[1666]: time="2026-08-30T16:32:01+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Aug 30 16:32:01 lapa go-librespot[1666]: time="2026-08-30T16:32:01+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Aug 30 16:32:01 lapa go-librespot[1666]: time="2026-08-30T16:32:01+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Aug 30 16:32:01 lapa go-librespot[1666]: time="2026-08-30T16:32:01+02:00" level=info msg="zeroconf server listening on port 35241" Aug 30 16:32:01 lapa go-librespot[1666]: time="2026-08-30T16:32:01+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 30 16:32:02 lapa go-librespot[1666]: time="2026-08-30T16:32:02+02:00" level=debug msg="obtained new client token: AAEBbU7v7DOM4C+UITU88Xzrb+AEOFjkRENsp0ZCMikKed2KMJCXUBcgoLTVFlUH457LOHg3T7bxen0hympyMXmFm/B8RXbFsnPIVrYslX/4FLj64OXf1/vlOQHMatlW7mH7lOsaMUAea18ukLFG1GAh5HR5xCmUpIoRFsVfEuB4tV6J7mpYMDOFYP3/fVl+cloRIeWvlT6VfhiI9N+S3xNFT1OIxCHRl9jo51qv5IS8YKScdlRqU5GcgQ==" Aug 30 16:32:02 lapa go-librespot[1666]: time="2026-08-30T16:32:02+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 30 16:32:03 lapa go-librespot[1666]: time="2026-08-30T16:32:03+02:00" level=debug msg="completed keyexchange" Aug 30 16:32:03 lapa go-librespot[1666]: time="2026-08-30T16:32:03+02:00" level=debug msg="completed challenge" Aug 30 16:32:03 lapa go-librespot[1666]: time="2026-08-30T16:32:03+02:00" level=info msg="authenticated AP" username="ha********ts" Aug 30 16:32:03 lapa go-librespot[1666]: time="2026-08-30T16:32:03+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 30 16:32:03 lapa systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 30 16:32:03 lapa systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 30 16:32:06 lapa systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 4. Aug 30 16:32:06 lapa systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 30 16:32:06 lapa systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 30 16:32:06 lapa go-librespot[1689]: go-librespot daemon starting... Aug 30 16:32:06 lapa go-librespot[1690]: time="2026-08-30T16:32:06+02:00" level=info msg="running go-librespot 0.7.1" Aug 30 16:32:06 lapa go-librespot[1690]: time="2026-08-30T16:32:06+02:00" level=debug msg="app state loaded" Aug 30 16:32:06 lapa volumio[1124]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Aug 30 16:32:06 lapa go-librespot[1690]: time="2026-08-30T16:32:06+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 30 16:32:06 lapa volumio[1124]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Aug 30 16:32:06 lapa volumio[1124]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 30 16:32:06 lapa volumio[1124]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 30 16:32:06 lapa volumio[1124]: info: Starting MyVolumio Remote Streaming Endpoints Aug 30 16:32:07 lapa volumio[1124]: info: MyVolumio login type: Token Aug 30 16:32:07 lapa go-librespot[1690]: time="2026-08-30T16:32:07+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Aug 30 16:32:07 lapa go-librespot[1690]: time="2026-08-30T16:32:07+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Aug 30 16:32:07 lapa go-librespot[1690]: time="2026-08-30T16:32:07+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Aug 30 16:32:07 lapa go-librespot[1690]: time="2026-08-30T16:32:07+02:00" level=info msg="zeroconf server listening on port 46119" Aug 30 16:32:07 lapa go-librespot[1690]: time="2026-08-30T16:32:07+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 30 16:32:07 lapa volumio[1124]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Aug 30 16:32:07 lapa volumio[1124]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Aug 30 16:32:07 lapa wpa_supplicant[1085]: RRM: Ignoring radio measurement request: Not RRM network Aug 30 16:32:08 lapa go-librespot[1690]: time="2026-08-30T16:32:08+02:00" level=debug msg="obtained new client token: AAFFgbDNs8xh5nKYSO/Hf9F6oo+sawc5mADLZa35iR9yto6tvWmSWXliYG9T1ietezomG48rAl63y4WfLHBuFjy77JRXgMx3Vd97ECiEirfh5mUKaw/IjTkJYDAJycn44ZzN84WHlAhbUZE7f2dscZJI/b8Ui3cDRzyLToKilSzNB5mYg8F6j9dYoyP/aHaa0RCWkWXbPG6lmAY0W+qsut11r39xNRHlDmoTAPkGTUS7WBi9fu5iVje7Xg==" Aug 30 16:32:08 lapa go-librespot[1690]: time="2026-08-30T16:32:08+02:00" level=warning msg="failed to connect to AP ap-gew1.spotify.com:4070, retrying with a different AP" error="dial tcp 104.199.65.9:4070: connect: connection refused" Aug 30 16:32:08 lapa go-librespot[1690]: time="2026-08-30T16:32:08+02:00" level=debug msg="connected to ap-gew1.spotify.com:443" Aug 30 16:32:09 lapa go-librespot[1690]: time="2026-08-30T16:32:09+02:00" level=debug msg="completed keyexchange" Aug 30 16:32:09 lapa go-librespot[1690]: time="2026-08-30T16:32:09+02:00" level=debug msg="completed challenge" Aug 30 16:32:09 lapa go-librespot[1690]: time="2026-08-30T16:32:09+02:00" level=info msg="authenticated AP" username="ha********ts" Aug 30 16:32:09 lapa go-librespot[1690]: time="2026-08-30T16:32:09+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 30 16:32:09 lapa systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 30 16:32:09 lapa systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 30 16:32:12 lapa systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 5. Aug 30 16:32:12 lapa systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 30 16:32:12 lapa systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 30 16:32:12 lapa go-librespot[1699]: go-librespot daemon starting... Aug 30 16:32:12 lapa go-librespot[1700]: time="2026-08-30T16:32:12+02:00" level=info msg="running go-librespot 0.7.1" Aug 30 16:32:12 lapa go-librespot[1700]: time="2026-08-30T16:32:12+02:00" level=debug msg="app state loaded" Aug 30 16:32:12 lapa go-librespot[1700]: time="2026-08-30T16:32:12+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 30 16:32:13 lapa volumio[1124]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Aug 30 16:32:13 lapa volumio[1124]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Aug 30 16:32:13 lapa volumio[1124]: info: Streaming services startup Aug 30 16:32:13 lapa volumio[1124]: info: Starting Streaming Daemon Aug 30 16:32:13 lapa go-librespot[1700]: time="2026-08-30T16:32:13+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Aug 30 16:32:13 lapa go-librespot[1700]: time="2026-08-30T16:32:13+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Aug 30 16:32:13 lapa go-librespot[1700]: time="2026-08-30T16:32:13+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Aug 30 16:32:13 lapa go-librespot[1700]: time="2026-08-30T16:32:13+02:00" level=info msg="zeroconf server listening on port 41619" Aug 30 16:32:13 lapa go-librespot[1700]: time="2026-08-30T16:32:13+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 30 16:32:13 lapa systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 5. Aug 30 16:32:13 lapa systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Aug 30 16:32:13 lapa volumio[1124]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Aug 30 16:32:13 lapa sudo[1711]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Aug 30 16:32:13 lapa sudo[1711]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 16:32:13 lapa systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Aug 30 16:32:13 lapa upmpdcli[1715]: Could not open config: /tmp/upmpdcli.conf Aug 30 16:32:13 lapa systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Aug 30 16:32:13 lapa systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Aug 30 16:32:13 lapa volumio[1124]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 30 16:32:13 lapa volumio[1124]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 30 16:32:13 lapa volumio[1124]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Aug 30 16:32:13 lapa volumio[1124]: info: Initializing connection to go-librespot Websocket Aug 30 16:32:13 lapa sudo[1711]: pam_unix(sudo:session): session closed for user root Aug 30 16:32:14 lapa volumio[1124]: error: An error occurred while listing Spotify featured playlists Error: Client network socket disconnected before secure TLS connection was established Aug 30 16:32:14 lapa volumio[1124]: info: An error occurred while getting Spotify ROOT Discover Folders: Aug 30 16:32:14 lapa go-librespot[1700]: time="2026-08-30T16:32:14+02:00" level=debug msg="obtained new client token: AAEhG5QAiGThipcb0Xm36iEmUV4RlX9Irsdyp39gs0iSqh859RuoCCZnonHfykJEdUFKYRzx/RQ55BIsF6+Algt7WVIl61KpHGhMnaqhr9LqteQApMDBRCCM7al8+b2h/AbVC1FIMHCRKdjFDFBeg0I+Re+D+fd0Gw5HItyb8O1o/N5KpH062L/VcYT3PhArWDdhcZviBguwpW5XJr1+hBKS73ImwBrCnXE1ADV0CWRtG4X4u0ulm3v+nA==" Aug 30 16:32:14 lapa volumio[1124]: error: An error occurred while listing Spotify new albums Error: Client network socket disconnected before secure TLS connection was established Aug 30 16:32:14 lapa volumio[1124]: error: An error occurred while listing Spotify categories Error: Client network socket disconnected before secure TLS connection was established Aug 30 16:32:14 lapa go-librespot[1700]: time="2026-08-30T16:32:14+02:00" level=debug msg="new websocket client" Aug 30 16:32:14 lapa volumio[1124]: error: Cannot start Volumio Streaming Daemon Aug 30 16:32:14 lapa volumio[1124]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Aug 30 16:32:14 lapa volumio[1124]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Aug 30 16:32:14 lapa volumio[1124]: info: Connection to go-librespot Websocket established Aug 30 16:32:14 lapa go-librespot[1700]: time="2026-08-30T16:32:14+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 30 16:32:14 lapa go-librespot[1700]: time="2026-08-30T16:32:14+02:00" level=debug msg="completed keyexchange" Aug 30 16:32:14 lapa go-librespot[1700]: time="2026-08-30T16:32:14+02:00" level=debug msg="completed challenge" Aug 30 16:32:14 lapa go-librespot[1700]: time="2026-08-30T16:32:14+02:00" level=info msg="authenticated AP" username="ha********ts" Aug 30 16:32:15 lapa go-librespot[1700]: time="2026-08-30T16:32:15+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 30 16:32:15 lapa systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 30 16:32:15 lapa systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 30 16:32:15 lapa volumio[1124]: info: Connection to go-librespot Websocket closed Aug 30 16:32:15 lapa volumio[1124]: error: MyVolumio Custom Token format not valid, refreshing it Aug 30 16:32:16 lapa volumio[1124]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateEnabled Aug 30 16:32:16 lapa volumio-remote-updater[651]: Test mode disabled Aug 30 16:32:16 lapa volumio-remote-updater[651]: Alpha mode disabled Aug 30 16:32:16 lapa volumio-remote-updater[651]: Alpha legacy test mode disabled Aug 30 16:32:17 lapa volumio[1124]: info: Update Ready: {"changeLogLink":"","description":"You're already on the latest version","title":"No Updates Available","updateavailable":false} Aug 30 16:32:17 lapa volumio[1124]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache Aug 30 16:32:17 lapa volumio[1124]: info: Getting Spotify volume Aug 30 16:32:17 lapa volumio[1124]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 30 16:32:17 lapa volumio[1124]: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 30 16:32:17 lapa volumio[1124]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Aug 30 16:32:17 lapa volumio[1124]: errno: -111, Aug 30 16:32:17 lapa volumio[1124]: code: 'ECONNREFUSED', Aug 30 16:32:17 lapa volumio[1124]: syscall: 'connect', Aug 30 16:32:17 lapa volumio[1124]: address: '127.0.0.1', Aug 30 16:32:17 lapa volumio[1124]: port: 9879, Aug 30 16:32:17 lapa volumio[1124]: response: undefined Aug 30 16:32:17 lapa volumio[1124]: } Aug 30 16:32:17 lapa volumio[1124]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 30 16:32:18 lapa systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6. Aug 30 16:32:18 lapa systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 30 16:32:18 lapa systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 30 16:32:18 lapa go-librespot[1746]: go-librespot daemon starting... Aug 30 16:32:18 lapa go-librespot[1747]: time="2026-08-30T16:32:18+02:00" level=info msg="running go-librespot 0.7.1" Aug 30 16:32:18 lapa go-librespot[1747]: time="2026-08-30T16:32:18+02:00" level=debug msg="app state loaded" Aug 30 16:32:18 lapa go-librespot[1747]: time="2026-08-30T16:32:18+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 30 16:32:19 lapa go-librespot[1747]: time="2026-08-30T16:32:19+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Aug 30 16:32:19 lapa go-librespot[1747]: time="2026-08-30T16:32:19+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Aug 30 16:32:19 lapa go-librespot[1747]: time="2026-08-30T16:32:19+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Aug 30 16:32:19 lapa go-librespot[1747]: time="2026-08-30T16:32:19+02:00" level=info msg="zeroconf server listening on port 37781" Aug 30 16:32:19 lapa go-librespot[1747]: time="2026-08-30T16:32:19+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 30 16:32:19 lapa go-librespot[1747]: time="2026-08-30T16:32:19+02:00" level=debug msg="obtained new client token: AAFXuEaRNMNc0CfT9R4YPn+oK7JJMFx5IjF0N4rn3Ip1JFjNVIebX904+XtbQulMhCjeRyEAmEp8nQ8NFWCnxpT4ToXy2fEfHLEWjQ2mRt6j7HLRCvtj6y/vsIIRpQS3U7F7LJB0K7uVCsWzi8f9eLL44khlGBs6M2vOzUXCuj/XZuQr6h+g8f/F0WC8pbrMWqbZnGN40lNmgs0fdPP/BvVSb/n29qQJgu/hzlmJLHaFAt36EU8A+1VA4g==" Aug 30 16:32:20 lapa go-librespot[1747]: time="2026-08-30T16:32:20+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 30 16:32:20 lapa go-librespot[1747]: time="2026-08-30T16:32:20+02:00" level=debug msg="completed keyexchange" Aug 30 16:32:20 lapa go-librespot[1747]: time="2026-08-30T16:32:20+02:00" level=debug msg="completed challenge" Aug 30 16:32:20 lapa go-librespot[1747]: time="2026-08-30T16:32:20+02:00" level=info msg="authenticated AP" username="ha********ts" Aug 30 16:32:21 lapa go-librespot[1747]: time="2026-08-30T16:32:21+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 30 16:32:21 lapa systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 30 16:32:21 lapa systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 30 16:32:24 lapa systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 7. Aug 30 16:32:24 lapa systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 30 16:32:24 lapa systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 30 16:32:24 lapa go-librespot[1759]: go-librespot daemon starting... Aug 30 16:32:24 lapa go-librespot[1761]: time="2026-08-30T16:32:24+02:00" level=info msg="running go-librespot 0.7.1" Aug 30 16:32:24 lapa go-librespot[1761]: time="2026-08-30T16:32:24+02:00" level=debug msg="app state loaded" Aug 30 16:32:24 lapa sudo[1760]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-08-30 16:31' Aug 30 16:32:24 lapa go-librespot[1761]: time="2026-08-30T16:32:24+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 30 16:32:24 lapa sudo[1760]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 16:32:25 lapa go-librespot[1761]: time="2026-08-30T16:32:25+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Aug 30 16:32:25 lapa go-librespot[1761]: time="2026-08-30T16:32:25+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Aug 30 16:32:25 lapa go-librespot[1761]: time="2026-08-30T16:32:25+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Aug 30 16:32:25 lapa go-librespot[1761]: time="2026-08-30T16:32:25+02:00" level=info msg="zeroconf server listening on port 33283" Aug 30 16:32:25 lapa go-librespot[1761]: time="2026-08-30T16:32:25+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" 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"