Aug 30 17:02:29 lapa ntpd[926]: CLOCK: time stepped by 13729268.270873 Aug 30 17:02:29 lapa ntpd[926]: CLOCK: time changed from 2026-03-24 to 2026-08-30 Aug 30 17:02:29 lapa ntpd[926]: INIT: MRU 13107 entries, 13 hash bits, 32768 bytes Aug 30 17:02:30 lapa wpa_supplicant[1081]: RRM: Ignoring radio measurement request: Not RRM network Aug 30 17:02:31 lapa systemd[1]: systemd-fsckd.service: Deactivated successfully. Aug 30 17:02:31 lapa systemd[1]: Starting dpkg-db-backup.service - Daily dpkg database backup service... Aug 30 17:02:31 lapa systemd[1]: Started ntpsec-rotate-stats.service - Rotate ntpd stats. Aug 30 17:02:31 lapa systemd[1]: ntpsec-rotate-stats.service: Deactivated successfully. Aug 30 17:02:32 lapa systemd[1]: dpkg-db-backup.service: Deactivated successfully. Aug 30 17:02:32 lapa systemd[1]: Finished dpkg-db-backup.service - Daily dpkg database backup service. Aug 30 17:02:32 lapa volumio[1123]: info: Loading plugin "network"... Aug 30 17:02:32 lapa volumio[1123]: info: Refreshing Cached IP Addresses Aug 30 17:02:32 lapa volumio[1123]: info: Loading plugin "services"... Aug 30 17:02:32 lapa volumio[1123]: info: Loading plugin "volumio5onboarding"... Aug 30 17:02:32 lapa sudo[1275]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Aug 30 17:02:32 lapa sudo[1275]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 17:02:32 lapa sudo[1275]: pam_unix(sudo:session): session closed for user root Aug 30 17:02:32 lapa sudo[1287]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Aug 30 17:02:32 lapa sudo[1287]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 17:02:32 lapa sudo[1277]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Aug 30 17:02:32 lapa sudo[1277]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 17:02:32 lapa volumio[1123]: info: Loading plugin "alsa_controller"... Aug 30 17:02:32 lapa sudo[1277]: pam_unix(sudo:session): session closed for user root Aug 30 17:02:32 lapa volumio[1123]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 30 17:02:32 lapa volumio[1123]: info: Loading plugin "wizard"... Aug 30 17:02:32 lapa volumio[1123]: info: Loading plugin "networkfs"... Aug 30 17:02:32 lapa volumio[1123]: info: Starting Udev Watcher for removable devices Aug 30 17:02:32 lapa volumio[1123]: info: Ignoring mount for partition: boot Aug 30 17:02:32 lapa volumio[1123]: info: Ignoring mount for partition: volumio Aug 30 17:02:32 lapa volumio[1123]: info: Ignoring mount for partition: volumio_data Aug 30 17:02:32 lapa volumio[1123]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Aug 30 17:02:32 lapa volumio[1123]: info: Loading plugin "volumio_command_line_client"... Aug 30 17:02:33 lapa sudo[1308]: 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 17:02:33 lapa sudo[1308]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 17:02:33 lapa volumio[1123]: info: Plugin upnp is not enabled Aug 30 17:02:33 lapa volumio[1123]: info: Loading plugin "my_music"... Aug 30 17:02:33 lapa volumio[1123]: info: Loading plugin "mpd"... Aug 30 17:02:33 lapa kernel: netfs: FS-Cache loaded Aug 30 17:02:33 lapa kernel: Key type cifs.spnego registered Aug 30 17:02:33 lapa kernel: Key type cifs.idmap registered Aug 30 17:02:33 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 17:02:33 lapa kernel: CIFS: Attempting to mount //192.168.1.2/Music Aug 30 17:02:34 lapa volumio[1123]: info: Loading plugin "upnp_browser"... Aug 30 17:02:34 lapa sudo[1308]: pam_unix(sudo:session): session closed for user root Aug 30 17:02:34 lapa systemd[1]: Starting e2scrub_all.service - Online ext4 Metadata Check for All Filesystems... Aug 30 17:02:34 lapa systemd[1]: e2scrub_all.service: Deactivated successfully. Aug 30 17:02:34 lapa systemd[1]: Finished e2scrub_all.service - Online ext4 Metadata Check for All Filesystems. Aug 30 17:02:35 lapa systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 2. Aug 30 17:02:35 lapa systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Aug 30 17:02:35 lapa systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Aug 30 17:02:35 lapa upmpdcli[1347]: Could not open config: /tmp/upmpdcli.conf Aug 30 17:02:35 lapa systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Aug 30 17:02:35 lapa systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Aug 30 17:02:36 lapa systemd[1]: systemd-hostnamed.service: Deactivated successfully. Aug 30 17:02:36 lapa sudo[1287]: pam_unix(sudo:session): session closed for user root Aug 30 17:02:37 lapa volumio[1123]: info: Starting UPNP Browser Aug 30 17:02:37 lapa volumio[1123]: info: Loading plugin "alarm-clock"... Aug 30 17:02:37 lapa volumio[1123]: info: Loading plugin "airplay_emulation"... Aug 30 17:02:37 lapa volumio[1123]: info: Starting Shairport Sync Aug 30 17:02:37 lapa volumio[1123]: info: Loading plugin "last_100"... Aug 30 17:02:37 lapa volumio[1123]: info: Loading plugin "webradio"... Aug 30 17:02:37 lapa volumio[1123]: info: Loading plugin "i2s_dacs"... Aug 30 17:02:37 lapa volumio[1123]: info: I2S DAC not set, start Auto-detection Aug 30 17:02:37 lapa volumio[1123]: info: Loading plugin "volumiodiscovery"... Aug 30 17:02:37 lapa volumio[1123]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Aug 30 17:02:37 lapa volumio[1123]: *** WARNING *** Please fix your application to use the native API of Avahi! Aug 30 17:02:37 lapa volumio[1123]: *** WARNING *** For more information see Aug 30 17:02:37 lapa volumio[1123]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Aug 30 17:02:37 lapa volumio[1123]: *** WARNING *** Please fix your application to use the native API of Avahi! Aug 30 17:02:37 lapa volumio[1123]: *** WARNING *** For more information see Aug 30 17:02:37 lapa node[1123]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Aug 30 17:02:37 lapa node[1123]: *** WARNING *** Please fix your application to use the native API of Avahi! Aug 30 17:02:37 lapa node[1123]: *** WARNING *** For more information see Aug 30 17:02:37 lapa node[1123]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Aug 30 17:02:37 lapa node[1123]: *** WARNING *** Please fix your application to use the native API of Avahi! Aug 30 17:02:37 lapa node[1123]: *** WARNING *** For more information see Aug 30 17:02:37 lapa volumio[1123]: info: Applying required configuration parameters for plugin volumiodiscovery Aug 30 17:02:37 lapa volumio[1123]: info: Discovery: Started advertising with name: LAPA Aug 30 17:02:37 lapa volumio[1123]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Aug 30 17:02:37 lapa volumio[1123]: info: Loading plugin "spop"... Aug 30 17:02:40 lapa volumio[1123]: info: Loading plugin "outputs"... Aug 30 17:02:40 lapa volumio[1123]: info: Loading plugin "albumart"... Aug 30 17:02:40 lapa volumio[1123]: info: Plugin example_plugin is not enabled Aug 30 17:02:40 lapa volumio[1123]: info: Loading plugin "inputs"... Aug 30 17:02:40 lapa volumio[1123]: info: Loading plugin "updater_comm"... Aug 30 17:02:41 lapa volumio[1123]: info: Plugin mpdemulation is not enabled Aug 30 17:02:41 lapa volumio[1123]: info: Loading plugin "rest_api"... Aug 30 17:02:41 lapa volumio[1123]: info: Loading plugin "websocket"... Aug 30 17:02:41 lapa volumio[1123]: info: Starting Socket.io Server version 1.7.4 Aug 30 17:02:41 lapa volumio[1123]: info: Loading i18n strings for locale en Aug 30 17:02:41 lapa volumio[1123]: Updating browse sources language Aug 30 17:02:41 lapa volumio[1123]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 30 17:02:41 lapa volumio[1123]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 30 17:02:41 lapa volumio[1123]: info: CoreCommandRouter::initPlayerControls Aug 30 17:02:41 lapa volumio[1123]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 17:02:41 lapa volumio[1123]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 17:02:41 lapa volumio[1123]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 17:02:41 lapa volumio[1123]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 17:02:41 lapa volumio[1123]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 17:02:41 lapa volumio[1123]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 17:02:41 lapa volumio[1123]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 17:02:41 lapa volumio[1123]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 17:02:41 lapa volumio[1123]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 30 17:02:41 lapa volumio[1123]: Express server listening on port 3000 Aug 30 17:02:41 lapa volumio[1123]: [Metrics] WebUI: 15s 19.23ms Aug 30 17:02:41 lapa volumio[1123]: info: CoreStateMachine::resetVolumioState Aug 30 17:02:41 lapa volumio[1123]: info: CoreStateMachine::getcurrentVolume Aug 30 17:02:41 lapa volumio[1123]: info: CoreCommandRouter::volumioRetrievevolume Aug 30 17:02:41 lapa volumio[1123]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 30 17:02:41 lapa volumio[1123]: info: Volumio Network Manager: Network status updated: 2 Aug 30 17:02:42 lapa volumio-remote-updater[654]: [2026-08-30 17:02:42] [connect] Successful connection Aug 30 17:02:42 lapa volumio[1123]: info: VolumeController:: Volume=86 Mute =false Aug 30 17:02:42 lapa volumio[1123]: info: CoreStateMachine::pushState Aug 30 17:02:42 lapa volumio[1123]: info: CorePlayQueue::getTrack 0 Aug 30 17:02:42 lapa volumio[1123]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 30 17:02:42 lapa volumio[1123]: info: CoreCommandRouter::volumioPushState Aug 30 17:02:42 lapa volumio[1123]: info: CoreStateMachine::updateTrackBlock Aug 30 17:02:42 lapa volumio[1123]: info: CorePlayQueue::getTrackBlock Aug 30 17:02:42 lapa volumio[1123]: info: CoreCommandRouter::volumioRetrievevolume Aug 30 17:02:42 lapa volumio-remote-updater[654]: [2026-08-30 17:02:42] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1788102162 101 Aug 30 17:02:42 lapa volumio[1123]: 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: 1 Aug 30 17:02:42 lapa volumio[1123]: info: Reloading queue from file Aug 30 17:02:42 lapa volumio[1123]: info: CoreStateMachine::setRepeat null single undefined Aug 30 17:02:42 lapa volumio[1123]: info: CoreStateMachine::pushState Aug 30 17:02:42 lapa volumio[1123]: info: CorePlayQueue::getTrack 0 Aug 30 17:02:42 lapa volumio[1123]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 30 17:02:42 lapa volumio[1123]: info: CoreCommandRouter::volumioPushState Aug 30 17:02:42 lapa volumio[1123]: info: CoreStateMachine::setRandom null Aug 30 17:02:42 lapa volumio[1123]: info: CoreStateMachine::pushState Aug 30 17:02:42 lapa volumio[1123]: info: CorePlayQueue::getTrack 0 Aug 30 17:02:42 lapa volumio[1123]: info: CoreCommandRouter::volumioPushState Aug 30 17:02:42 lapa volumio[1354]: Forking 3 albumart workers Aug 30 17:02:42 lapa volumio[1123]: info: Setting Device type: Raspberry PI Aug 30 17:02:42 lapa volumio[1123]: info: VolumeController:: Volume=86 Mute =false Aug 30 17:02:42 lapa volumio[1123]: info: CoreStateMachine::pushState Aug 30 17:02:42 lapa volumio[1123]: info: CorePlayQueue::getTrack 0 Aug 30 17:02:42 lapa volumio[1123]: info: CoreCommandRouter::volumioPushState Aug 30 17:02:42 lapa volumio[1123]: info: Discovery: adding 20bf9b46-74f2-480c-b5a8-922bff2fe4bb Aug 30 17:02:42 lapa volumio[1123]: info: Discovery: Found device LAPA Aug 30 17:02:42 lapa volumio[1123]: info: CoreCommandRouter::volumioGetState Aug 30 17:02:42 lapa volumio[1123]: info: CorePlayQueue::getTrack 0 Aug 30 17:02:42 lapa volumio[1123]: info: Discovery: this is already registered, 20bf9b46-74f2-480c-b5a8-922bff2fe4bb Aug 30 17:02:42 lapa volumio[1123]: info: Discovery: Found device LAPA Aug 30 17:02:42 lapa volumio[1123]: info: CoreCommandRouter::volumioGetState Aug 30 17:02:42 lapa volumio[1123]: info: CorePlayQueue::getTrack 0 Aug 30 17:02:43 lapa volumio[1123]: info: Completed loading Core Plugins Aug 30 17:02:43 lapa volumio[1123]: info: Preparing to generate the ALSA configuration file Aug 30 17:02:43 lapa volumio[1123]: info: Asound.conf file written Aug 30 17:02:43 lapa sudo[1424]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mv /home/volumio/.asoundrc /etc/asound.conf Aug 30 17:02:43 lapa sudo[1424]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 17:02:43 lapa sudo[1424]: pam_unix(sudo:session): session closed for user root Aug 30 17:02:43 lapa volumio[1123]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:0 use case configuration -2 Aug 30 17:02:43 lapa volumio[1123]: No state is present for card b1 Aug 30 17:02:43 lapa volumio[1123]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:0 use case configuration -2 Aug 30 17:02:43 lapa volumio[1123]: /usr/share/alsa/init/bcm2835:14: control element not found Aug 30 17:02:43 lapa volumio[1123]: No state is present for card b1 Aug 30 17:02:43 lapa volumio[1123]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:1 use case configuration -2 Aug 30 17:02:43 lapa volumio[1123]: No state is present for card Headphones Aug 30 17:02:43 lapa volumio[1123]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:1 use case configuration -2 Aug 30 17:02:43 lapa volumio[1123]: /usr/share/alsa/init/bcm2835:20: control element not found Aug 30 17:02:43 lapa volumio[1123]: No state is present for card Headphones Aug 30 17:02:43 lapa volumio[1123]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:2 use case configuration -2 Aug 30 17:02:43 lapa volumio[1123]: No state is present for card vc4hdmi Aug 30 17:02:43 lapa volumio[1123]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:2 use case configuration -2 Aug 30 17:02:43 lapa volumio[1123]: Found hardware: "vc4-hdmi" "" "" "" "" Aug 30 17:02:43 lapa volumio[1123]: Hardware is initialized using a generic method Aug 30 17:02:43 lapa volumio[1123]: No state is present for card vc4hdmi Aug 30 17:02:43 lapa volumio[1123]: info: Output device has changed, restarting MPD Aug 30 17:02:44 lapa volumio[1123]: info: Output device has changed, restarting Shairport Sync Aug 30 17:02:44 lapa sudo[1433]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Aug 30 17:02:44 lapa volumio[1123]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 17:02:44 lapa volumio[1123]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 30 17:02:44 lapa sudo[1433]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 17:02:44 lapa sudo[1433]: pam_unix(sudo:session): session closed for user root Aug 30 17:02:44 lapa sudo[1435]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Aug 30 17:02:44 lapa sudo[1435]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 17:02:44 lapa volumio[1123]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Aug 30 17:02:44 lapa volumio[1123]: info: ___________ START PLUGINS ___________ Aug 30 17:02:44 lapa systemd[1]: Starting setdatetime-helper.service - Time Synchronization Helper Service... Aug 30 17:02:44 lapa systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Aug 30 17:02:44 lapa systemd[1]: Starting mpd.service - Music Player Daemon... Aug 30 17:02:44 lapa volumio[1123]: info: ControllerMpd::onStart: Initializing MPD Aug 30 17:02:44 lapa volumio[1123]: info: Creating MPD Configuration file Aug 30 17:02:44 lapa sudo[1444]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumio5-onboarding.service Aug 30 17:02:44 lapa sudo[1444]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 17:02:44 lapa sudo[1448]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Aug 30 17:02:44 lapa sudo[1448]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Aug 30 17:02:44 lapa sudo[1464]: /bin/chown: cannot access '/var/log/mpd.log': No such file or directory Aug 30 17:02:44 lapa sudo[1448]: pam_unix(sudo:session): session closed for user root Aug 30 17:02:44 lapa sudo[1465]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Aug 30 17:02:44 lapa sudo[1465]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 17:02:44 lapa volumio[1123]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 30 17:02:44 lapa volumio[1123]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 30 17:02:44 lapa volumio[1123]: info: [1788102164916] CoreMusicLibrary::Adding element Media Servers Aug 30 17:02:44 lapa volumio[1123]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 30 17:02:44 lapa sudo[1461]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Aug 30 17:02:45 lapa systemd[1]: mpd.service: Deactivated successfully. Aug 30 17:02:45 lapa systemd[1]: Stopped mpd.service - Music Player Daemon. Aug 30 17:02:45 lapa systemd[1]: mpd.socket: Deactivated successfully. Aug 30 17:02:45 lapa systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Aug 30 17:02:45 lapa systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Aug 30 17:02:45 lapa systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Aug 30 17:02:45 lapa volumio[1123]: info: UPNP Browser: Client initialized successfully Aug 30 17:02:45 lapa systemd[1]: Starting mpd.service - Music Player Daemon... Aug 30 17:02:45 lapa sudo[1461]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 17:02:45 lapa sudo[1461]: pam_unix(sudo:session): session closed for user root Aug 30 17:02:45 lapa systemd[1]: Started volumio5-onboarding.service - Volumio5 Onboarding Server. Aug 30 17:02:45 lapa sudo[1444]: pam_unix(sudo:session): session closed for user root Aug 30 17:02:45 lapa volumio[1123]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 17:02:45 lapa volumio[1123]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 30 17:02:45 lapa sudo[1469]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Aug 30 17:02:45 lapa sudo[1469]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Aug 30 17:02:45 lapa sudo[1474]: /bin/chown: cannot access '/var/log/mpd.log': No such file or directory Aug 30 17:02:45 lapa sudo[1469]: pam_unix(sudo:session): session closed for user root Aug 30 17:02:45 lapa volumio[1123]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Aug 30 17:02:45 lapa volumio[1123]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 17:02:45 lapa volumio[1123]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 30 17:02:45 lapa volumio[1123]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Aug 30 17:02:45 lapa volumio[1123]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 30 17:02:45 lapa volumio[1123]: info: [1788102165872] CoreMusicLibrary::Adding element Last_100 Aug 30 17:02:45 lapa volumio[1123]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 30 17:02:45 lapa volumio[1123]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 30 17:02:45 lapa volumio[1123]: info: [1788102165883] CoreMusicLibrary::Adding element Webradio Aug 30 17:02:45 lapa volumio[1123]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 30 17:02:45 lapa volumio[1123]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 30 17:02:45 lapa volumio[1123]: info: Initializing BBC Radios Aug 30 17:02:46 lapa volumio5-onboarding[1473]: time=2026-08-30T17:02:46.142+02:00 level=INFO msg="running volumio5-device-gateway" version=6370e0a8+CHANGES buildDate=2026-03-06T16:29:42Z Aug 30 17:02:46 lapa volumio[1123]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 30 17:02:46 lapa volumio[1123]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 30 17:02:46 lapa volumio[1123]: info: Creating Spotify config file Aug 30 17:02:46 lapa volumio[1123]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 17:02:46 lapa systemd[1]: setdatetime-helper.service: Deactivated successfully. Aug 30 17:02:47 lapa systemd[1]: Finished setdatetime-helper.service - Time Synchronization Helper Service. Aug 30 17:02:47 lapa systemd[1]: setdatetime-helper.service: Consumed 1.136s CPU time. Aug 30 17:02:50 lapa volumio[1123]: info: Volumio Calling Home Aug 30 17:02:50 lapa systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 3. Aug 30 17:02:50 lapa systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Aug 30 17:02:50 lapa systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Aug 30 17:02:50 lapa upmpdcli[1516]: Could not open config: /tmp/upmpdcli.conf Aug 30 17:02:50 lapa systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Aug 30 17:02:50 lapa systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Aug 30 17:02:53 lapa volumio[1123]: info: MPD Permissions set Aug 30 17:02:53 lapa volumio[1123]: info: MPD Permissions set Aug 30 17:02:53 lapa volumio[1123]: 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 17:02:53 lapa mpd[1475]: 2026-08-30T17:02:53 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Aug 30 17:02:53 lapa volumio[1123]: info: Spotify config file written Aug 30 17:02:53 lapa volumio[1123]: 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 17:02:53 lapa volumio[1123]: info: Received Get System Info Aug 30 17:02:53 lapa volumio[1123]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 30 17:02:53 lapa volumio[1123]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 30 17:02:53 lapa volumio[1123]: info: Discovery: Getting this device information Aug 30 17:02:53 lapa volumio[1123]: info: CoreCommandRouter::volumioGetState Aug 30 17:02:53 lapa volumio[1123]: info: CorePlayQueue::getTrack 0 Aug 30 17:02:53 lapa volumio[1123]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 30 17:02:53 lapa systemd[1]: Started mpd.service - Music Player Daemon. Aug 30 17:02:53 lapa volumio5-onboarding[1473]: time=2026-08-30T17:02:53.876+02:00 level=INFO msg="system info for bca75da8751ab4c8204b8894c0cad3d9" deviceName=LAPA deviceVariant=volumio deviceModel= softwareVersion=4.119 Aug 30 17:02:53 lapa sudo[1465]: pam_unix(sudo:session): session closed for user root Aug 30 17:02:53 lapa sudo[1435]: pam_unix(sudo:session): session closed for user root Aug 30 17:02:53 lapa volumio5-onboarding[1473]: time=2026-08-30T17:02:53.912+02:00 level=INFO msg="bootstrapping state" hasInternet=true Aug 30 17:02:54 lapa sudo[1535]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Aug 30 17:02:54 lapa sudo[1535]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 17:02:54 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 17:02:54 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 17:02:54 lapa systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 30 17:02:54 lapa sudo[1535]: pam_unix(sudo:session): session closed for user root Aug 30 17:02:54 lapa go-librespot[1539]: go-librespot daemon starting... Aug 30 17:02:54 lapa volumio[1389]: Starting albumart workers Aug 30 17:02:54 lapa volumio[1390]: Starting albumart workers Aug 30 17:02:54 lapa volumio[1123]: 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 30 17:02:55 lapa volumio[1123]: info: Volumio called home Aug 30 17:02:55 lapa volumio[1123]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 17:02:55 lapa volumio[1123]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 17:02:55 lapa volumio[1123]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 17:02:55 lapa volumio[1123]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 17:02:55 lapa volumio[1123]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 17:02:55 lapa volumio[1123]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 17:02:55 lapa volumio[1123]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 17:02:55 lapa volumio[1123]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 17:02:55 lapa go-librespot[1540]: time="2026-08-30T17:02:55+02:00" level=info msg="running go-librespot 0.7.1" Aug 30 17:02:55 lapa go-librespot[1540]: time="2026-08-30T17:02:55+02:00" level=debug msg="app state loaded" Aug 30 17:02:55 lapa go-librespot[1540]: time="2026-08-30T17:02:55+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 30 17:02:55 lapa volumio[1123]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 30 17:02:55 lapa volumio[1123]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 17:02:55 lapa volumio[1123]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 17:02:55 lapa volumio[1123]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 17:02:55 lapa volumio[1123]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 17:02:55 lapa volumio[1123]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 17:02:55 lapa volumio[1123]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 17:02:55 lapa volumio[1123]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 17:02:55 lapa volumio[1123]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 17:02:55 lapa volumio[1123]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 17:02:55 lapa volumio[1123]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 30 17:02:55 lapa volumio[1123]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 17:02:55 lapa volumio[1123]: info: No need to fix Spotify hosts Aug 30 17:02:55 lapa volumio[1123]: info: Received Get System Info Aug 30 17:02:55 lapa volumio[1123]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 30 17:02:55 lapa volumio[1123]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 30 17:02:55 lapa volumio[1123]: info: Discovery: Getting this device information Aug 30 17:02:55 lapa volumio[1123]: info: CoreCommandRouter::volumioGetState Aug 30 17:02:55 lapa volumio[1123]: info: CorePlayQueue::getTrack 0 Aug 30 17:02:55 lapa volumio[1123]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 30 17:02:55 lapa go-librespot[1540]: time="2026-08-30T17:02:55+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 17:02:55 lapa go-librespot[1540]: time="2026-08-30T17:02:55+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 17:02:55 lapa go-librespot[1540]: time="2026-08-30T17:02:55+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 17:02:55 lapa go-librespot[1540]: time="2026-08-30T17:02:55+02:00" level=info msg="zeroconf server listening on port 38789" Aug 30 17:02:55 lapa go-librespot[1540]: time="2026-08-30T17:02:55+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 30 17:02:56 lapa volumio[1384]: Starting albumart workers Aug 30 17:02:57 lapa volumio[1123]: info: Completed starting Core Plugins Aug 30 17:02:57 lapa volumio[1123]: info: ------------------------------------------- Aug 30 17:02:57 lapa volumio[1123]: info: ----- MyVolumio plugins startup ---- Aug 30 17:02:57 lapa volumio[1123]: info: ------------------------------------------- Aug 30 17:02:57 lapa volumio[1123]: info: [MyVolumio PluginManager] Fetching plans data.... Aug 30 17:02:57 lapa volumio-remote-updater[654]: Test mode disabled Aug 30 17:02:57 lapa volumio-remote-updater[654]: Alpha mode disabled Aug 30 17:02:57 lapa volumio-remote-updater[654]: Alpha legacy test mode disabled Aug 30 17:02:57 lapa volumio[1123]: info: New Spotify access tokenBQCjNegyWK... Aug 30 17:02:57 lapa volumio[1123]: info: Spotify credentials grant success - running version from March 24, 2019 Aug 30 17:02:58 lapa volumio[1123]: error: MPD error: The expression evaluated to a falsy value: Aug 30 17:02:58 lapa volumio[1123]: assert.ok(self.idling) Aug 30 17:02:58 lapa volumio[1123]: error: The expression evaluated to a falsy value: Aug 30 17:02:58 lapa volumio[1123]: assert.ok(self.idling) Aug 30 17:02:58 lapa volumio[1123]: info: MPD running with PID1475 Aug 30 17:02:58 lapa volumio[1123]: ,establishing connection Aug 30 17:02:58 lapa volumio[1123]: info: Starting Shairport Sync Aug 30 17:02:58 lapa volumio[1123]: info: Starting Shairport Sync Aug 30 17:02:58 lapa volumio[1123]: info: Starting Shairport Sync Aug 30 17:02:58 lapa volumio[1123]: error: updateQueue error: null Aug 30 17:02:58 lapa volumio[1123]: info: Update Ready: {"changeLogLink":"","description":"You're already on the latest version","title":"No Updates Available","updateavailable":false} Aug 30 17:02:58 lapa volumio[1123]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache Aug 30 17:02:58 lapa sudo[1579]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Aug 30 17:02:58 lapa sudo[1579]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 17:02:58 lapa sudo[1583]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Aug 30 17:02:58 lapa sudo[1583]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 17:02:58 lapa sudo[1581]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Aug 30 17:02:58 lapa sudo[1581]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 17:02:58 lapa systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Aug 30 17:02:58 lapa systemd[1]: shairport-sync.service: Deactivated successfully. Aug 30 17:02:58 lapa systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 30 17:02:58 lapa systemd[1]: shairport-sync.service: Consumed 1.320s CPU time. Aug 30 17:02:58 lapa systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 30 17:02:59 lapa sudo[1583]: pam_unix(sudo:session): session closed for user root Aug 30 17:02:59 lapa systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Aug 30 17:02:59 lapa systemd[1]: shairport-sync.service: Deactivated successfully. Aug 30 17:02:59 lapa systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 30 17:02:59 lapa systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 30 17:02:59 lapa systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Aug 30 17:02:59 lapa sudo[1581]: pam_unix(sudo:session): session closed for user root Aug 30 17:02:59 lapa systemd[1]: shairport-sync.service: Deactivated successfully. Aug 30 17:02:59 lapa systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 30 17:02:59 lapa systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 30 17:02:59 lapa sudo[1579]: pam_unix(sudo:session): session closed for user root Aug 30 17:02:59 lapa volumio[1123]: error: updateQueue error: null Aug 30 17:02:59 lapa volumio[1123]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 30 17:02:59 lapa volumio[1123]: info: Shairport-Sync Started Aug 30 17:02:59 lapa volumio[1123]: Error adding Membership: Error: addMembership EINVAL Aug 30 17:02:59 lapa volumio[1123]: info: Shairport-Sync Started Aug 30 17:02:59 lapa volumio[1123]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 30 17:03:00 lapa volumio[1123]: info: Shairport-Sync Started Aug 30 17:03:00 lapa volumio[1123]: info: go-librespot daemon successfully initialized Aug 30 17:03:00 lapa volumio[1123]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 30 17:03:00 lapa volumio[1123]: info: Received Get System Info Aug 30 17:03:00 lapa volumio[1123]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 30 17:03:00 lapa volumio[1123]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 30 17:03:00 lapa volumio[1123]: info: Discovery: Getting this device information Aug 30 17:03:00 lapa volumio[1123]: info: CoreCommandRouter::volumioGetState Aug 30 17:03:00 lapa volumio[1123]: info: CorePlayQueue::getTrack 0 Aug 30 17:03:00 lapa volumio[1123]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 30 17:03:00 lapa volumio[1123]: info: CoreCommandRouter::volumioGetState Aug 30 17:03:00 lapa volumio[1123]: info: CorePlayQueue::getTrack 0 Aug 30 17:03:00 lapa volumio[1123]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Aug 30 17:03:00 lapa volumio[1123]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Aug 30 17:03:00 lapa volumio5-onboarding[1473]: time=2026-08-30T17:03:00.412+02:00 level=INFO msg="enabling local network discovery" Aug 30 17:03:00 lapa volumio5-onboarding[1473]: time=2026-08-30T17:03:00.444+02:00 level=INFO msg="enabling BLE discovery" Aug 30 17:03:00 lapa wpa_supplicant[1081]: RRM: Ignoring radio measurement request: Not RRM network Aug 30 17:03:00 lapa volumio[1123]: 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 17:03:00 lapa volumio[1123]: info: Spotify Successfully logged in Aug 30 17:03:00 lapa volumio[1123]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 30 17:03:00 lapa volumio[1123]: info: [1788102180916] CoreMusicLibrary::Adding element Spotify Aug 30 17:03:00 lapa volumio[1123]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 30 17:03:00 lapa volumio[1123]: Cannot find translation for source Spotify Aug 30 17:03:01 lapa volumio5-onboarding[1473]: time=2026-08-30T17:03:01.363+02:00 level=INFO msg="service successfully established" component=discovery/localnet Aug 30 17:03:03 lapa volumio[1123]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Aug 30 17:03:06 lapa systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 4. Aug 30 17:03:06 lapa systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Aug 30 17:03:06 lapa volumio[1123]: info: Initializing connection to go-librespot Websocket Aug 30 17:03:06 lapa systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Aug 30 17:03:06 lapa upmpdcli[1641]: Could not open config: /tmp/upmpdcli.conf Aug 30 17:03:06 lapa systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Aug 30 17:03:06 lapa systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Aug 30 17:03:06 lapa volumio[1123]: Cannot compose Albumart path Aug 30 17:03:07 lapa volumio[1123]: Cannot compose Albumart path Aug 30 17:03:08 lapa go-librespot[1540]: time="2026-08-30T17:03:08+02:00" level=debug msg="new websocket client" Aug 30 17:03:08 lapa volumio[1123]: info: Connection to go-librespot Websocket established Aug 30 17:03:10 lapa volumio[1123]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Aug 30 17:03:10 lapa volumio[1123]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Aug 30 17:03:10 lapa volumio[1123]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Aug 30 17:03:10 lapa volumio[1123]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Aug 30 17:03:10 lapa volumio[1123]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Aug 30 17:03:10 lapa volumio[1123]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Aug 30 17:03:10 lapa volumio[1123]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Aug 30 17:03:10 lapa volumio[1123]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Aug 30 17:03:10 lapa volumio[1123]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Aug 30 17:03:10 lapa volumio[1123]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Aug 30 17:03:10 lapa volumio[1123]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Aug 30 17:03:10 lapa volumio[1123]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Aug 30 17:03:10 lapa volumio[1123]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Aug 30 17:03:10 lapa volumio[1123]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Aug 30 17:03:10 lapa volumio[1123]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Aug 30 17:03:10 lapa volumio[1123]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Aug 30 17:03:10 lapa volumio[1123]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Aug 30 17:03:10 lapa volumio[1123]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Aug 30 17:03:10 lapa volumio[1123]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Aug 30 17:03:10 lapa volumio[1123]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Aug 30 17:03:10 lapa volumio[1123]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Aug 30 17:03:10 lapa volumio[1123]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Aug 30 17:03:10 lapa volumio[1123]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Aug 30 17:03:10 lapa volumio[1123]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Aug 30 17:03:10 lapa volumio[1123]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Aug 30 17:03:10 lapa volumio[1123]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Aug 30 17:03:10 lapa volumio[1123]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Aug 30 17:03:10 lapa volumio[1123]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Aug 30 17:03:10 lapa volumio[1123]: info: Adding plugin bluetooth to MyMusic Plugins Aug 30 17:03:10 lapa volumio[1123]: info: Adding plugin multiroom to MyMusic Plugins Aug 30 17:03:10 lapa volumio[1123]: info: Adding plugin metavolumio to MyMusic Plugins Aug 30 17:03:10 lapa volumio[1123]: info: Adding plugin cd_controller to MyMusic Plugins Aug 30 17:03:10 lapa volumio[1123]: info: Adding plugin qobuzconnect to MyMusic Plugins Aug 30 17:03:10 lapa volumio[1123]: info: Adding plugin smart_inputs to MyMusic Plugins Aug 30 17:03:10 lapa volumio[1123]: info: Adding plugin tidalconnect to MyMusic Plugins Aug 30 17:03:10 lapa volumio[1123]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Aug 30 17:03:10 lapa wpa_supplicant[1081]: RRM: Ignoring radio measurement request: Not RRM network Aug 30 17:03:11 lapa go-librespot[1540]: time="2026-08-30T17:03:11+02:00" level=debug msg="obtained new client token: AAFhtX3Pjgr12xPrsnoV0eHSuT5vlS8uD31nPPccGI8RMoZ9xGaWQUUt94lGN3d9qxqTCHi/PC5BBoEs7IJiY5g/s/hSsI+KHYQ/n1r6jhtdSVgX45NDsPvqb0W87Y6/H8E+hLVon1UvNwAihFj5dkGJHeZXx1jubB4FGozJZmk3qNezzjxg1jUQzwfarzmHFAsO+AoDpX6k+rn7tL3l+zsXNxDddRRubQ8sO/bh0VgaUphj5BFMh2A=" Aug 30 17:03:11 lapa go-librespot[1540]: time="2026-08-30T17:03:11+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 30 17:03:11 lapa go-librespot[1540]: time="2026-08-30T17:03:11+02:00" level=debug msg="completed keyexchange" Aug 30 17:03:11 lapa go-librespot[1540]: time="2026-08-30T17:03:11+02:00" level=debug msg="completed challenge" Aug 30 17:03:11 lapa go-librespot[1540]: time="2026-08-30T17:03:11+02:00" level=info msg="authenticated AP" username="31************************ju" Aug 30 17:03:12 lapa go-librespot[1540]: time="2026-08-30T17:03:12+02:00" level=info msg="authenticated Login5" username="31************************ju" Aug 30 17:03:12 lapa go-librespot[1540]: time="2026-08-30T17:03:12+02:00" level=info msg="accepted zeroconf from Yollanda's S25 Ultra" username="31************************ju" Aug 30 17:03:12 lapa go-librespot[1540]: time="2026-08-30T17:03:12+02:00" level=debug msg="dealer connection opened" Aug 30 17:03:12 lapa go-librespot[1540]: time="2026-08-30T17:03:12+02:00" level=trace msg="starting accesspoint recv loop" Aug 30 17:03:12 lapa go-librespot[1540]: time="2026-08-30T17:03:12+02:00" level=trace msg="starting dealer recv loop" Aug 30 17:03:12 lapa go-librespot[1540]: time="2026-08-30T17:03:12+02:00" level=trace msg="received accesspoint ping" Aug 30 17:03:12 lapa go-librespot[1540]: time="2026-08-30T17:03:12+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Aug 30 17:03:12 lapa go-librespot[1540]: time="2026-08-30T17:03:12+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Aug 30 17:03:12 lapa go-librespot[1540]: time="2026-08-30T17:03:12+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Aug 30 17:03:12 lapa go-librespot[1540]: time="2026-08-30T17:03:12+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Aug 30 17:03:12 lapa go-librespot[1540]: time="2026-08-30T17:03:12+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Aug 30 17:03:12 lapa go-librespot[1540]: time="2026-08-30T17:03:12+02:00" level=debug msg="received connection id: OWY4YWQ2MGMtMTE1...OTlGREJCRUFERg==" Aug 30 17:03:12 lapa go-librespot[1540]: time="2026-08-30T17:03:12+02:00" level=trace msg="received accesspoint pong ack" Aug 30 17:03:12 lapa go-librespot[1540]: time="2026-08-30T17:03:12+02:00" level=debug msg="put connect state because NEW_DEVICE" Aug 30 17:03:13 lapa go-librespot[1540]: time="2026-08-30T17:03:13+02:00" level=debug msg="handling transfer player command from 49798ebd8584ce6fe7b9da32cb665a14c60d9e59" Aug 30 17:03:13 lapa go-librespot[1540]: time="2026-08-30T17:03:13+02:00" level=debug msg="resolved context of track" uri="spotify:playlist:37i9dQZF1EQqZgBURAEzWH" Aug 30 17:03:13 lapa go-librespot[1540]: time="2026-08-30T17:03:13+02:00" level=trace msg="fetched new page 0 with 50 items (list: 50)" uri="spotify:playlist:37i9dQZF1EQqZgBURAEzWH" Aug 30 17:03:13 lapa go-librespot[1540]: time="2026-08-30T17:03:13+02:00" level=warning msg="failed seeking to track in context spotify:playlist:37i9dQZF1EQqZgBURAEzWH" error="could not find track" uri="spotify:playlist:37i9dQZF1EQqZgBURAEzWH" Aug 30 17:03:13 lapa go-librespot[1540]: time="2026-08-30T17:03:13+02:00" level=debug msg="loading track (paused: true, position: 11247ms)" uri="spotify:track:6JSVjObIfHHr7UXXDW79Zr" Aug 30 17:03:13 lapa go-librespot[1540]: time="2026-08-30T17:03:13+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 30 17:03:13 lapa go-librespot[1540]: time="2026-08-30T17:03:13+02:00" level=trace msg="emitting websocket event: will_play" Aug 30 17:03:13 lapa go-librespot[1540]: time="2026-08-30T17:03:13+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 432" Aug 30 17:03:14 lapa go-librespot[1540]: time="2026-08-30T17:03:14+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 2149" Aug 30 17:03:14 lapa go-librespot[1540]: time="2026-08-30T17:03:14+02:00" level=debug msg="selected format OGG_VORBIS_320 (1dbfac0af1be269984f786f9858082de6be67441)" uri="spotify:track:6JSVjObIfHHr7UXXDW79Zr" Aug 30 17:03:14 lapa go-librespot[1540]: time="2026-08-30T17:03:14+02:00" level=debug msg="requested aes key for file 1dbfac0af1be269984f786f9858082de6be67441, gid: 6JSVjObIfHHr7UXXDW79Zr" Aug 30 17:03:14 lapa go-librespot[1540]: time="2026-08-30T17:03:14+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 298" Aug 30 17:03:14 lapa go-librespot[1540]: time="2026-08-30T17:03:14+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 432" Aug 30 17:03:14 lapa go-librespot[1540]: time="2026-08-30T17:03:14+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1575" Aug 30 17:03:15 lapa go-librespot[1540]: time="2026-08-30T17:03:15+02:00" level=trace msg="found 2 cdn urls" uri="spotify:track:6JSVjObIfHHr7UXXDW79Zr" Aug 30 17:03:15 lapa volumio[1123]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Aug 30 17:03:15 lapa volumio[1123]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Aug 30 17:03:15 lapa volumio[1123]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 30 17:03:15 lapa volumio[1123]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 30 17:03:15 lapa volumio[1123]: info: Starting MyVolumio Remote Streaming Endpoints Aug 30 17:03:15 lapa volumio[1123]: info: MyVolumio login type: Token Aug 30 17:03:16 lapa volumio[1123]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Aug 30 17:03:16 lapa volumio[1123]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Aug 30 17:03:18 lapa go-librespot[1540]: time="2026-08-30T17:03:18+02:00" level=debug msg="fetched first chunk of 23, total size is 11723270 bytes" uri="spotify:track:6JSVjObIfHHr7UXXDW79Zr" Aug 30 17:03:18 lapa go-librespot[1540]: time="2026-08-30T17:03:18+02:00" level=trace msg="seek to 11247ms (diff: 150ms, samples: 495992, bytes: 385078)" uri="spotify:track:6JSVjObIfHHr7UXXDW79Zr" Aug 30 17:03:18 lapa go-librespot[1540]: time="2026-08-30T17:03:18+02:00" level=debug msg="created new output device" Aug 30 17:03:18 lapa go-librespot[1540]: time="2026-08-30T17:03:18+02:00" level=info msg="loaded track \"The King Is Coming\" (paused: true, position: 11247ms, duration: 286586ms, prefetched: false)" uri="spotify:track:6JSVjObIfHHr7UXXDW79Zr" Aug 30 17:03:18 lapa go-librespot[1540]: time="2026-08-30T17:03:18+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 30 17:03:18 lapa go-librespot[1540]: time="2026-08-30T17:03:18+02:00" level=trace msg="emitting websocket event: metadata" Aug 30 17:03:18 lapa go-librespot[1540]: time="2026-08-30T17:03:18+02:00" level=trace msg="emitting websocket event: active" Aug 30 17:03:18 lapa go-librespot[1540]: time="2026-08-30T17:03:18+02:00" level=debug msg="sending successful reply for dealer request" Aug 30 17:03:18 lapa go-librespot[1540]: time="2026-08-30T17:03:18+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Aug 30 17:03:18 lapa go-librespot[1540]: time="2026-08-30T17:03:18+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Aug 30 17:03:18 lapa go-librespot[1540]: time="2026-08-30T17:03:18+02:00" level=debug msg="skipping dealer message" uri="hm://playlist/v2/playlist/6xvcAWK0RPhFTVWHxqztqp" Aug 30 17:03:18 lapa go-librespot[1540]: time="2026-08-30T17:03:18+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Aug 30 17:03:18 lapa go-librespot[1540]: time="2026-08-30T17:03:18+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Aug 30 17:03:18 lapa go-librespot[1540]: time="2026-08-30T17:03:18+02:00" level=debug msg="fetched chunk 2/22, size: 524288" uri="spotify:track:6JSVjObIfHHr7UXXDW79Zr" Aug 30 17:03:18 lapa go-librespot[1540]: time="2026-08-30T17:03:18+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 30 17:03:18 lapa go-librespot[1540]: time="2026-08-30T17:03:18+02:00" level=trace msg="emitting websocket event: paused" Aug 30 17:03:18 lapa go-librespot[1540]: time="2026-08-30T17:03:18+02:00" level=debug msg="handling resume player command from 49798ebd8584ce6fe7b9da32cb665a14c60d9e59" Aug 30 17:03:18 lapa go-librespot[1540]: time="2026-08-30T17:03:18+02:00" level=trace msg="seek to 11247ms (diff: 150ms, samples: 495992, bytes: 385078)" uri="spotify:track:6JSVjObIfHHr7UXXDW79Zr" Aug 30 17:03:18 lapa go-librespot[1540]: time="2026-08-30T17:03:18+02:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 124988 us, period size = 5512 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 4 frames, PCM format = FLOAT_LE" Aug 30 17:03:18 lapa go-librespot[1540]: time="2026-08-30T17:03:18+02:00" level=debug msg="resume track at 11097ms" Aug 30 17:03:18 lapa go-librespot[1540]: time="2026-08-30T17:03:18+02:00" level=debug msg="fetched chunk 1/22, size: 524288" uri="spotify:track:6JSVjObIfHHr7UXXDW79Zr" Aug 30 17:03:19 lapa go-librespot[1540]: time="2026-08-30T17:03:19+02:00" level=debug msg="fetched chunk 3/22, size: 524288" uri="spotify:track:6JSVjObIfHHr7UXXDW79Zr" Aug 30 17:03:19 lapa go-librespot[1540]: time="2026-08-30T17:03:19+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 30 17:03:19 lapa go-librespot[1540]: time="2026-08-30T17:03:19+02:00" level=trace msg="scheduling prefetch in 245s" Aug 30 17:03:19 lapa go-librespot[1540]: time="2026-08-30T17:03:19+02:00" level=debug msg="sending successful reply for dealer request" Aug 30 17:03:19 lapa go-librespot[1540]: time="2026-08-30T17:03:19+02:00" level=error msg="failed receiving dealer message" error="failed to get reader: received close frame: status = StatusNormalClosure and reason = \"Request disconnect\"" Aug 30 17:03:19 lapa go-librespot[1540]: time="2026-08-30T17:03:19+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 30 17:03:19 lapa go-librespot[1540]: time="2026-08-30T17:03:19+02:00" level=trace msg="emitting websocket event: playing" Aug 30 17:03:19 lapa go-librespot[1540]: time="2026-08-30T17:03:19+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 211" Aug 30 17:03:20 lapa go-librespot[1540]: time="2026-08-30T17:03:20+02:00" level=debug msg="dealer connection opened" Aug 30 17:03:20 lapa go-librespot[1540]: time="2026-08-30T17:03:20+02:00" level=debug msg="re-established dealer connection" Aug 30 17:03:20 lapa go-librespot[1540]: time="2026-08-30T17:03:20+02:00" level=debug msg="received connection id: MjYwNWUyMDktMmU2...RERDRDFEMzdFNw==" Aug 30 17:03:20 lapa go-librespot[1540]: time="2026-08-30T17:03:20+02:00" level=debug msg="put connect state because NEW_DEVICE" Aug 30 17:03:21 lapa systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 5. Aug 30 17:03:21 lapa systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Aug 30 17:03:21 lapa systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Aug 30 17:03:21 lapa go-librespot[1540]: time="2026-08-30T17:03:21+02:00" level=debug msg="update volume requested to 62914/65535" Aug 30 17:03:21 lapa upmpdcli[1657]: Could not open config: /tmp/upmpdcli.conf Aug 30 17:03:21 lapa systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Aug 30 17:03:21 lapa systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Aug 30 17:03:21 lapa go-librespot[1540]: time="2026-08-30T17:03:21+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Aug 30 17:03:21 lapa go-librespot[1540]: time="2026-08-30T17:03:21+02:00" level=trace msg="emitting websocket event: volume" Aug 30 17:03:21 lapa go-librespot[1540]: time="2026-08-30T17:03:21+02:00" level=debug msg="update volume requested to 60292/65535" Aug 30 17:03:21 lapa go-librespot[1540]: time="2026-08-30T17:03:21+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Aug 30 17:03:21 lapa go-librespot[1540]: time="2026-08-30T17:03:21+02:00" level=trace msg="emitting websocket event: volume" Aug 30 17:03:21 lapa go-librespot[1540]: time="2026-08-30T17:03:21+02:00" level=debug msg="update volume requested to 52428/65535" Aug 30 17:03:22 lapa go-librespot[1540]: time="2026-08-30T17:03:22+02:00" level=debug msg="fetched chunk 4/22, size: 524288" uri="spotify:track:6JSVjObIfHHr7UXXDW79Zr" Aug 30 17:03:22 lapa go-librespot[1540]: time="2026-08-30T17:03:22+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Aug 30 17:03:22 lapa go-librespot[1540]: time="2026-08-30T17:03:22+02:00" level=trace msg="emitting websocket event: volume" Aug 30 17:03:23 lapa volumio[1123]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Aug 30 17:03:23 lapa volumio[1123]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Aug 30 17:03:23 lapa volumio[1123]: info: Streaming services startup Aug 30 17:03:23 lapa volumio[1123]: info: Starting Streaming Daemon Aug 30 17:03:23 lapa volumio[1123]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Aug 30 17:03:23 lapa sudo[1660]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Aug 30 17:03:23 lapa sudo[1660]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 17:03:23 lapa sudo[1660]: pam_unix(sudo:session): session closed for user root Aug 30 17:03:24 lapa volumio[1123]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 30 17:03:24 lapa volumio[1123]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 30 17:03:24 lapa volumio[1123]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Aug 30 17:03:24 lapa volumio[1123]: info: Getting Spotify volume Aug 30 17:03:24 lapa volumio[1123]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:playlist:37i9dQZF1EQqZgBURAEzWH","uri":"spotify:track:6JSVjObIfHHr7UXXDW79Zr","play_origin":"media-session"}} Aug 30 17:03:24 lapa volumio[1123]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:6JSVjObIfHHr7UXXDW79Zr","name":"The King Is Coming","artist_names":["Newsboys"],"album_name":"God's Not Dead","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02dd0a598f02b4a196bd9f41b5","position":11247,"duration":286586,"release_date":"year:2011 month:1 day:1","track_number":1,"disc_number":1}} Aug 30 17:03:24 lapa volumio[1123]: SPOTIFY: received: {"type":"active","data":null} Aug 30 17:03:24 lapa volumio[1123]: info: Aligning Spotify Volume to Volumio Volume Aug 30 17:03:24 lapa volumio[1123]: info: CoreCommandRouter::volumioGetState Aug 30 17:03:24 lapa volumio[1123]: info: CorePlayQueue::getTrack 0 Aug 30 17:03:24 lapa volumio[1123]: info: Setting Spotify Volume from Volumio: 86 Aug 30 17:03:24 lapa volumio[1123]: SPOTIFY: received: {"type":"paused","data":{"context_uri":"spotify:playlist:37i9dQZF1EQqZgBURAEzWH","uri":"spotify:track:6JSVjObIfHHr7UXXDW79Zr","play_origin":"media-session"}} Aug 30 17:03:24 lapa volumio[1123]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 30 17:03:24 lapa volumio[1123]: TypeError: Cannot read properties of undefined (reading 'service') Aug 30 17:03:24 lapa volumio[1123]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:346:50) Aug 30 17:03:24 lapa volumio[1123]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:280:18) Aug 30 17:03:24 lapa volumio[1123]: at WebSocket.message (/data/plugins/music_service/spop/index.js:199:14) Aug 30 17:03:24 lapa volumio[1123]: at WebSocket.emit (node:events:514:28) Aug 30 17:03:24 lapa volumio[1123]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20) Aug 30 17:03:24 lapa volumio[1123]: at Receiver.emit (node:events:514:28) Aug 30 17:03:24 lapa volumio[1123]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) Aug 30 17:03:24 lapa volumio[1123]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) Aug 30 17:03:24 lapa volumio[1123]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) Aug 30 17:03:24 lapa volumio[1123]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) Aug 30 17:03:24 lapa volumio[1123]: at writeOrBuffer (node:internal/streams/writable:399:12) Aug 30 17:03:24 lapa volumio[1123]: at _write (node:internal/streams/writable:340:10) Aug 30 17:03:24 lapa volumio[1123]: at Writable.write (node:internal/streams/writable:344:10) Aug 30 17:03:24 lapa volumio[1123]: at Socket.socketOnData (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1355:35) Aug 30 17:03:24 lapa volumio[1123]: at Socket.emit (node:events:514:28) Aug 30 17:03:24 lapa volumio[1123]: at addChunk (node:internal/streams/readable:343:12) Aug 30 17:03:24 lapa volumio[1123]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 30 17:03:25 lapa go-librespot[1540]: time="2026-08-30T17:03:25+02:00" level=debug msg="update volume requested to 49807/65535" Aug 30 17:03:26 lapa go-librespot[1540]: time="2026-08-30T17:03:26+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 211" Aug 30 17:03:26 lapa go-librespot[1540]: time="2026-08-30T17:03:26+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Aug 30 17:03:26 lapa go-librespot[1540]: time="2026-08-30T17:03:26+02:00" level=trace msg="emitting websocket event: volume" Aug 30 17:03:26 lapa go-librespot[1540]: time="2026-08-30T17:03:26+02:00" level=debug msg="update volume requested to 47185/65535" Aug 30 17:03:26 lapa go-librespot[1540]: time="2026-08-30T17:03:26+02:00" level=debug msg="skipping dealer message" uri="hm://playlist/v2/playlist/6xvcAWK0RPhFTVWHxqztqp" Aug 30 17:03:26 lapa go-librespot[1540]: time="2026-08-30T17:03:26+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Aug 30 17:03:26 lapa go-librespot[1540]: time="2026-08-30T17:03:26+02:00" level=trace msg="emitting websocket event: volume" Aug 30 17:03:26 lapa go-librespot[1540]: time="2026-08-30T17:03:26+02:00" level=debug msg="update volume requested to 31457/65535" Aug 30 17:03:26 lapa go-librespot[1540]: time="2026-08-30T17:03:26+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Aug 30 17:03:26 lapa go-librespot[1540]: time="2026-08-30T17:03:26+02:00" level=trace msg="emitting websocket event: volume" Aug 30 17:03:29 lapa go-librespot[1540]: time="2026-08-30T17:03:29+02:00" level=debug msg="update volume requested to 28835/65535" Aug 30 17:03:29 lapa go-librespot[1540]: time="2026-08-30T17:03:29+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Aug 30 17:03:29 lapa go-librespot[1540]: time="2026-08-30T17:03:29+02:00" level=trace msg="emitting websocket event: volume" Aug 30 17:03:29 lapa go-librespot[1540]: time="2026-08-30T17:03:29+02:00" level=debug msg="update volume requested to 26214/65535" Aug 30 17:03:29 lapa go-librespot[1540]: time="2026-08-30T17:03:29+02:00" level=debug msg="update volume requested to 18350/65535" Aug 30 17:03:29 lapa go-librespot[1540]: time="2026-08-30T17:03:29+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Aug 30 17:03:29 lapa go-librespot[1540]: time="2026-08-30T17:03:29+02:00" level=trace msg="emitting websocket event: volume" Aug 30 17:03:30 lapa go-librespot[1540]: time="2026-08-30T17:03:30+02:00" level=debug msg="update volume requested to 13107/65535" Aug 30 17:03:30 lapa go-librespot[1540]: time="2026-08-30T17:03:30+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Aug 30 17:03:30 lapa go-librespot[1540]: time="2026-08-30T17:03:30+02:00" level=trace msg="emitting websocket event: volume" Aug 30 17:03:30 lapa go-librespot[1540]: time="2026-08-30T17:03:30+02:00" level=debug msg="skipping dealer message" uri="hm://playlist/v2/playlist/6xvcAWK0RPhFTVWHxqztqp" Aug 30 17:03:30 lapa go-librespot[1540]: time="2026-08-30T17:03:30+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 211" Aug 30 17:03:32 lapa sudo[1696]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-08-30 17:02' Aug 30 17:03:32 lapa sudo[1696]: 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"