Apr 10 19:35:16 volumio systemd[1]: Starting smbd.service - Samba SMB Daemon... Apr 10 19:35:16 volumio systemd[1]: setdatetime-helper.service: Deactivated successfully. Apr 10 19:35:16 volumio systemd[1]: Finished setdatetime-helper.service - Time Synchronization Helper Service. Apr 10 19:35:16 volumio systemd[1]: setdatetime-helper.service: Consumed 1.222s CPU time. Apr 10 19:35:16 volumio systemd[1]: Starting dpkg-db-backup.service - Daily dpkg database backup service... Apr 10 19:35:16 volumio systemd[1]: Started ntpsec-rotate-stats.service - Rotate ntpd stats. Apr 10 19:35:16 volumio systemd[1]: ntpsec-rotate-stats.service: Deactivated successfully. Apr 10 19:35:16 volumio systemd[1]: dpkg-db-backup.service: Deactivated successfully. Apr 10 19:35:16 volumio systemd[1]: Finished dpkg-db-backup.service - Daily dpkg database backup service. Apr 10 19:35:16 volumio ntpd[912]: IO: Listen normally on 3 eth0 192.168.2.115:123 Apr 10 19:35:16 volumio ntpd[912]: IO: new interface(s) found: waking up resolver Apr 10 19:35:16 volumio ntpd[912]: DNS: dns_check: processing 3.debian.pool.ntp.org, 8, 101 Apr 10 19:35:16 volumio ntpd[912]: DNS: Pool taking: 85.215.166.214 Apr 10 19:35:16 volumio ntpd[912]: DNS: Pool taking: 46.38.233.159 Apr 10 19:35:16 volumio ntpd[912]: DNS: Pool taking: 141.144.246.224 Apr 10 19:35:16 volumio ntpd[912]: DNS: Pool taking: 178.63.67.56 Apr 10 19:35:16 volumio ntpd[912]: DNS: dns_take_status: 3.debian.pool.ntp.org=>good, 8 Apr 10 19:35:16 volumio sudo[1151]: pam_unix(sudo:session): session closed for user root Apr 10 19:35:16 volumio wireless.js[726]: WIRELESS.JS - INFO: Cleaning previous... Apr 10 19:35:16 volumio systemd[1]: systemd-rfkill.service: Deactivated successfully. Apr 10 19:35:16 volumio sudo[1181]: root : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 up Apr 10 19:35:16 volumio sudo[1181]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Apr 10 19:35:16 volumio kernel: brcmfmac: brcmf_cfg80211_set_power_mgmt: power save disabled Apr 10 19:35:16 volumio sudo[1181]: pam_unix(sudo:session): session closed for user root Apr 10 19:35:16 volumio wireless.js[726]: WIRELESS.JS - INFO: InterfaceValidator: READY - wlan0 is ready for operations Apr 10 19:35:16 volumio wireless.js[726]: WIRELESS.JS - INFO: InterfaceValidator: wlan0 became ready after 26ms Apr 10 19:35:16 volumio wireless.js[726]: WIRELESS.JS - INFO: ensureInterfaceReady: Interface ready (MAC: b8:27:eb:b5:23:d6) Apr 10 19:35:16 volumio dhcpcd[824]: eth0: leased 192.168.2.115 for 864000 seconds Apr 10 19:35:16 volumio dhcpcd[824]: eth0: adding route to 192.168.2.0/24 Apr 10 19:35:16 volumio dhcpcd[824]: eth0: adding default route via 192.168.2.1 Apr 10 19:35:16 volumio smbd[1175]: [2026/04/10 19:35:16.733184, 0] ../../source3/smbd/server.c:1741(main) Apr 10 19:35:16 volumio smbd[1175]: smbd version 4.17.8-Raspbian started. Apr 10 19:35:16 volumio smbd[1175]: Copyright Andrew Tridgell and the Samba Team 1992-2022 Apr 10 19:35:16 volumio winbindd[1131]: [2026/04/10 19:35:16.755035, 0] ../../source3/winbindd/winbindd_idmap.c:372(wb_parent_idmap_setup_lookupname_done) Apr 10 19:35:16 volumio winbindd[1131]: wb_parent_idmap_setup_lookupname_done: Lookup domain name 'VOLUMIO' failed 'NT_STATUS_IO_TIMEOUT' Apr 10 19:35:16 volumio sudo[1194]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iw reg get Apr 10 19:35:16 volumio sudo[1194]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 10 19:35:16 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Apr 10 19:35:16 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Apr 10 19:35:16 volumio systemd[1]: welcome.service: Deactivated successfully. Apr 10 19:35:16 volumio systemd[1]: Stopped welcome.service - Show a welcome message on console. Apr 10 19:35:16 volumio systemd[1]: Stopping welcome.service - Show a welcome message on console... Apr 10 19:35:16 volumio sudo[1194]: pam_unix(sudo:session): session closed for user root Apr 10 19:35:16 volumio systemd[1]: Starting welcome.service - Show a welcome message on console... Apr 10 19:35:16 volumio systemd[1]: Started smbd.service - Samba SMB Daemon. Apr 10 19:35:16 volumio ntpd[912]: DNS: dns_probe: 2.debian.pool.ntp.org, cast_flags:8, flags:101 Apr 10 19:35:16 volumio ntpd[912]: DNS: dns_check: processing 2.debian.pool.ntp.org, 8, 101 Apr 10 19:35:16 volumio ntpd[912]: DNS: Pool skipping: 139.162.152.20 Apr 10 19:35:16 volumio ntpd[912]: DNS: Pool skipping: 82.165.178.31 Apr 10 19:35:16 volumio ntpd[912]: DNS: Pool skipping: 46.38.241.235 Apr 10 19:35:16 volumio ntpd[912]: DNS: Pool skipping: 129.250.35.250 Apr 10 19:35:16 volumio ntpd[912]: DNS: Pool skipping: 2003:a:87f:c37c::8 Apr 10 19:35:16 volumio ntpd[912]: DNS: Pool skipping: 2a02:8106:21:9400::6 Apr 10 19:35:16 volumio ntpd[912]: DNS: Pool skipping: 2a01:4f8:10b:1c50::2 Apr 10 19:35:16 volumio ntpd[912]: DNS: Pool skipping: 2a01:7e01::f03c:94ff:fee2:9ce0 Apr 10 19:35:16 volumio ntpd[912]: DNS: dns_take_status: 2.debian.pool.ntp.org=>good, 8 Apr 10 19:35:16 volumio welcome[1217]: Resolved ip:[1] 192.168.2.115 Apr 10 19:35:16 volumio systemd[1]: Finished welcome.service - Show a welcome message on console. Apr 10 19:35:16 volumio sudo[1233]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iw wlan0 scan Apr 10 19:35:16 volumio sudo[1233]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 10 19:35:16 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Apr 10 19:35:17 volumio sudo[1233]: pam_unix(sudo:session): session closed for user root Apr 10 19:35:17 volumio wireless.js[726]: WIRELESS.JS - INFO: SETTING APPROPRIATE REG DOMAIN: DE Apr 10 19:35:17 volumio sudo[1245]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iw reg set DE Apr 10 19:35:17 volumio sudo[1245]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 10 19:35:17 volumio sudo[1245]: pam_unix(sudo:session): session closed for user root Apr 10 19:35:17 volumio wireless.js[726]: WIRELESS.JS - INFO: SUCCESSFULLY SET NEW REGDOMAIN: DE Apr 10 19:35:17 volumio wireless.js[726]: WIRELESS.JS - INFO: netconfigured file not found, starting hotspot Apr 10 19:35:17 volumio wireless.js[726]: WIRELESS.JS - INFO: Single Network Mode: Ethernet active, maintaining WiFi scan capability Apr 10 19:35:17 volumio wireless.js[726]: WIRELESS.JS - INFO: SNM: Maintaining wlan0 UP without IP (scan mode) Apr 10 19:35:17 volumio wireless.js[726]: WIRELESS.JS - INFO: SNM: Users can configure WiFi via WebUI while ethernet is active Apr 10 19:35:17 volumio ntpd[912]: DNS: dns_probe: 1.debian.pool.ntp.org, cast_flags:8, flags:101 Apr 10 19:35:17 volumio ntpd[912]: DNS: dns_check: processing 1.debian.pool.ntp.org, 8, 101 Apr 10 19:35:17 volumio ntpd[912]: DNS: Pool taking: 5.45.97.204 Apr 10 19:35:17 volumio ntpd[912]: DNS: Pool taking: 185.16.60.96 Apr 10 19:35:17 volumio ntpd[912]: DNS: Pool taking: 158.180.28.150 Apr 10 19:35:17 volumio ntpd[912]: DNS: Pool taking: 176.9.8.206 Apr 10 19:35:17 volumio ntpd[912]: DNS: dns_take_status: 1.debian.pool.ntp.org=>good, 8 Apr 10 19:35:17 volumio sudo[1256]: root : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 up Apr 10 19:35:17 volumio sudo[1256]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Apr 10 19:35:17 volumio sudo[1256]: pam_unix(sudo:session): session closed for user root Apr 10 19:35:17 volumio sudo[1259]: root : PWD=/ ; USER=root ; COMMAND=/sbin/ip addr flush dev wlan0 Apr 10 19:35:17 volumio sudo[1259]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Apr 10 19:35:18 volumio sudo[1259]: pam_unix(sudo:session): session closed for user root Apr 10 19:35:18 volumio wpa_supplicant[1262]: Successfully initialized wpa_supplicant Apr 10 19:35:18 volumio winbindd[1154]: [2026/04/10 19:35:18.201796, 0] ../../source3/winbindd/winbindd_dual.c:162(child_write_response) Apr 10 19:35:18 volumio winbindd[1154]: Could not write result Apr 10 19:35:18 volumio wireless.js[726]: WIRELESS.JS - INFO: SNM: Transition to scan mode completed in 2867746787ms Apr 10 19:35:18 volumio wireless.js[726]: WIRELESS.JS - INFO: SNM: wlan0 is UP without IP, scan capable Apr 10 19:35:18 volumio wireless.js[726]: Failed to connect to non-global ctrl_ifname: wlan0 error: No such file or directory Apr 10 19:35:18 volumio ntpd[912]: DNS: dns_probe: 0.debian.pool.ntp.org, cast_flags:8, flags:101 Apr 10 19:35:18 volumio ntpd[912]: DNS: dns_check: processing 0.debian.pool.ntp.org, 8, 101 Apr 10 19:35:18 volumio ntpd[912]: DNS: Pool taking: 195.201.107.151 Apr 10 19:35:18 volumio ntpd[912]: DNS: Pool taking: 85.121.52.237 Apr 10 19:35:18 volumio ntpd[912]: DNS: Pool taking: 116.203.218.109 Apr 10 19:35:18 volumio ntpd[912]: DNS: Pool taking: 144.76.76.107 Apr 10 19:35:18 volumio ntpd[912]: DNS: dns_take_status: 0.debian.pool.ntp.org=>good, 8 Apr 10 19:35:18 volumio wireless.js[726]: WIRELESS.JS - INFO: Notified systemd about wireless ready Apr 10 19:35:18 volumio kernel: brcmfmac: brcmf_cfg80211_set_power_mgmt: power save disabled Apr 10 19:35:18 volumio systemd[1]: Started wireless.service - Wireless Services. Apr 10 19:35:18 volumio systemd[1]: Started volumio.service - Volumio Backend Module. Apr 10 19:35:19 volumio systemd[1]: Starting plymouth-quit.service - Terminate Plymouth Boot Screen... Apr 10 19:35:19 volumio systemd[1]: Started volumio_cpu_tweak.service - Volumio Cpu Tweaker. Apr 10 19:35:19 volumio systemd[1]: Received SIGRTMIN+21 from PID 310 (plymouthd). Apr 10 19:35:19 volumio systemd[1]: Finished plymouth-quit.service - Terminate Plymouth Boot Screen. Apr 10 19:35:19 volumio systemd[1]: Received SIGRTMIN+21 from PID 310 (n/a). Apr 10 19:35:19 volumio systemd[1]: Finished plymouth-quit-wait.service - Hold until boot process finishes up. Apr 10 19:35:19 volumio systemd[1]: Started getty@tty1.service - Getty on tty1. Apr 10 19:35:19 volumio systemd[1]: Reached target getty.target - Login Prompts. Apr 10 19:35:19 volumio systemd[1]: Reached target multi-user.target - Multi-User System. Apr 10 19:35:19 volumio systemd[1]: Reached target graphical.target - Graphical Interface. Apr 10 19:35:19 volumio systemd[1]: Starting systemd-update-utmp-runlevel.service - Record Runlevel Change in UTMP... Apr 10 19:35:19 volumio volumio-cpu-tweak[1288]: Setting RT Priority for mpd Apr 10 19:35:19 volumio volumio-cpu-tweak[1304]: pid 35's current scheduling policy: SCHED_OTHER Apr 10 19:35:19 volumio volumio-cpu-tweak[1304]: pid 35's current scheduling priority: 0 Apr 10 19:35:19 volumio volumio-cpu-tweak[1288]: Setting MPD Affinity Apr 10 19:35:19 volumio volumio-cpu-tweak[1305]: pid 3's current affinity mask: f Apr 10 19:35:19 volumio volumio-cpu-tweak[1288]: /bin/volumio_cpu_tweak: line 27: warning: command substitution: ignored null byte in input Apr 10 19:35:19 volumio volumio-cpu-tweak[1288]: VOLUMIO CPU TWEAK: Setting CPU Governor: performance Apr 10 19:35:19 volumio systemd[1]: systemd-update-utmp-runlevel.service: Deactivated successfully. Apr 10 19:35:19 volumio systemd[1]: Finished systemd-update-utmp-runlevel.service - Record Runlevel Change in UTMP. Apr 10 19:35:19 volumio systemd[1]: Startup finished in 15.408s (kernel) + 14.407s (userspace) = 29.815s. Apr 10 19:35:19 volumio systemd[1]: volumio_cpu_tweak.service: Deactivated successfully. Apr 10 19:35:22 volumio ntpd[912]: CLOCK: time stepped by 0.349214 Apr 10 19:35:22 volumio ntpd[912]: INIT: MRU 13107 entries, 13 hash bits, 32768 bytes Apr 10 19:35:23 volumio volumio-remote-updater[723]: [2026-04-10 19:35:23] [connect] Successful connection Apr 10 19:35:24 volumio volumio[1286]: info: ------------------------------------------- Apr 10 19:35:24 volumio volumio[1286]: info: ----- Volumio3 ---- Apr 10 19:35:24 volumio volumio[1286]: info: ------------------------------------------- Apr 10 19:35:24 volumio volumio[1286]: info: ----- System startup ---- Apr 10 19:35:24 volumio volumio[1286]: info: ------------------------------------------- Apr 10 19:35:25 volumio volumio[1286]: info: MYVOLUMIO Environment detected Apr 10 19:35:26 volumio volumio[1286]: info: Plugin folders cleanup Apr 10 19:35:26 volumio volumio[1286]: info: Scanning into folder /volumio/app/plugins/ Apr 10 19:35:26 volumio volumio[1286]: info: Scanning category audio_interface Apr 10 19:35:26 volumio volumio[1286]: info: Scanning category miscellanea Apr 10 19:35:26 volumio volumio[1286]: info: Scanning category music_service Apr 10 19:35:26 volumio volumio[1286]: info: Scanning category plugins.json Apr 10 19:35:26 volumio volumio[1286]: info: Scanning category system_controller Apr 10 19:35:26 volumio volumio[1286]: info: Scanning category user_interface Apr 10 19:35:26 volumio volumio[1286]: info: Scanning into folder /data/plugins/ Apr 10 19:35:26 volumio volumio[1286]: info: Scanning category music_service Apr 10 19:35:26 volumio volumio[1286]: info: Plugin folders cleanup completed Apr 10 19:35:26 volumio volumio[1286]: info: ------------------------------------------- Apr 10 19:35:26 volumio volumio[1286]: info: ----- Core plugins startup ---- Apr 10 19:35:26 volumio volumio[1286]: info: ------------------------------------------- Apr 10 19:35:26 volumio volumio[1286]: info: Loading plugins from folder /volumio/app/plugins/ Apr 10 19:35:26 volumio volumio[1286]: info: Adding plugin upnp to MyMusic Plugins Apr 10 19:35:26 volumio volumio[1286]: info: Adding plugin airplay_emulation to MyMusic Plugins Apr 10 19:35:26 volumio volumio[1286]: info: Adding plugin upnp_browser to MyMusic Plugins Apr 10 19:35:26 volumio volumio[1286]: info: Loading plugins from folder /data/plugins/ Apr 10 19:35:26 volumio volumio[1286]: info: Loading plugin "system"... Apr 10 19:35:26 volumio volumio[1286]: info: Loading plugin "appearance"... Apr 10 19:35:26 volumio systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 1. Apr 10 19:35:26 volumio systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Apr 10 19:35:26 volumio systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Apr 10 19:35:26 volumio upmpdcli[1321]: Could not open config: /tmp/upmpdcli.conf Apr 10 19:35:26 volumio systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Apr 10 19:35:26 volumio systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Apr 10 19:35:28 volumio volumio[1286]: info: Loading plugin "network"... Apr 10 19:35:28 volumio volumio[1286]: info: Refreshing Cached IP Addresses Apr 10 19:35:28 volumio sudo[1323]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Apr 10 19:35:28 volumio sudo[1323]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 10 19:35:28 volumio sudo[1323]: pam_unix(sudo:session): session closed for user root Apr 10 19:35:28 volumio volumio[1286]: info: Loading plugin "services"... Apr 10 19:35:28 volumio volumio[1286]: info: Loading plugin "volumio5onboarding"... Apr 10 19:35:28 volumio sudo[1333]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Apr 10 19:35:28 volumio sudo[1333]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 10 19:35:28 volumio volumio[1286]: info: Loading plugin "alsa_controller"... Apr 10 19:35:28 volumio sudo[1325]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Apr 10 19:35:28 volumio sudo[1325]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 10 19:35:28 volumio sudo[1325]: pam_unix(sudo:session): session closed for user root Apr 10 19:35:28 volumio volumio[1286]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Apr 10 19:35:28 volumio volumio[1286]: info: Loading plugin "wizard"... Apr 10 19:35:28 volumio volumio[1286]: info: Loading plugin "networkfs"... Apr 10 19:35:28 volumio volumio[1286]: info: Starting Udev Watcher for removable devices Apr 10 19:35:29 volumio sudo[1354]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=michael,password=vangelis,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //bunker.local/music/_collection /mnt/NAS/Bunker-Collection Apr 10 19:35:29 volumio sudo[1354]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 10 19:35:29 volumio volumio[1286]: info: Ignoring mount for partition: boot Apr 10 19:35:29 volumio volumio[1286]: info: Ignoring mount for partition: volumio Apr 10 19:35:29 volumio volumio[1286]: info: Ignoring mount for partition: volumio_data Apr 10 19:35:29 volumio volumio[1286]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Apr 10 19:35:29 volumio volumio[1286]: info: Loading plugin "volumio_command_line_client"... Apr 10 19:35:29 volumio volumio[1286]: info: Loading plugin "upnp"... Apr 10 19:35:29 volumio volumio[1286]: info: [1775842529113] Starting Upmpd Daemon Apr 10 19:35:29 volumio volumio[1286]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Apr 10 19:35:29 volumio volumio[1286]: info: Loading plugin "my_music"... Apr 10 19:35:29 volumio volumio[1286]: info: Loading plugin "mpd"... Apr 10 19:35:29 volumio sudo[1333]: pam_unix(sudo:session): session closed for user root Apr 10 19:35:29 volumio kernel: netfs: FS-Cache loaded Apr 10 19:35:29 volumio kernel: Key type cifs.spnego registered Apr 10 19:35:29 volumio kernel: Key type cifs.idmap registered Apr 10 19:35:29 volumio 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. Apr 10 19:35:29 volumio kernel: CIFS: Attempting to mount //bunker.local/music/_collection Apr 10 19:35:30 volumio sudo[1354]: pam_unix(sudo:session): session closed for user root Apr 10 19:35:30 volumio volumio[1286]: info: Loading plugin "upnp_browser"... Apr 10 19:35:32 volumio volumio[1286]: info: Starting UPNP Browser Apr 10 19:35:32 volumio volumio[1286]: info: Loading plugin "alarm-clock"... Apr 10 19:35:33 volumio volumio[1286]: info: Loading plugin "airplay_emulation"... Apr 10 19:35:33 volumio volumio[1286]: info: Starting Shairport Sync Apr 10 19:35:33 volumio volumio[1286]: info: Loading plugin "last_100"... Apr 10 19:35:33 volumio volumio[1286]: info: Loading plugin "webradio"... Apr 10 19:35:33 volumio volumio[1286]: info: Loading plugin "i2s_dacs"... Apr 10 19:35:33 volumio volumio[1286]: info: Loading plugin "volumiodiscovery"... Apr 10 19:35:33 volumio volumio[1286]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Apr 10 19:35:33 volumio node[1286]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Apr 10 19:35:33 volumio volumio[1286]: *** WARNING *** Please fix your application to use the native API of Avahi! Apr 10 19:35:33 volumio node[1286]: *** WARNING *** Please fix your application to use the native API of Avahi! Apr 10 19:35:33 volumio volumio[1286]: *** WARNING *** For more information see Apr 10 19:35:33 volumio node[1286]: *** WARNING *** For more information see Apr 10 19:35:33 volumio volumio[1286]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Apr 10 19:35:33 volumio node[1286]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Apr 10 19:35:33 volumio volumio[1286]: *** WARNING *** Please fix your application to use the native API of Avahi! Apr 10 19:35:33 volumio node[1286]: *** WARNING *** Please fix your application to use the native API of Avahi! Apr 10 19:35:33 volumio volumio[1286]: *** WARNING *** For more information see Apr 10 19:35:33 volumio node[1286]: *** WARNING *** For more information see Apr 10 19:35:33 volumio volumio[1286]: info: Applying required configuration parameters for plugin volumiodiscovery Apr 10 19:35:33 volumio volumio[1286]: info: Discovery: Started advertising with name: Volumio Apr 10 19:35:33 volumio volumio[1286]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Apr 10 19:35:33 volumio volumio[1286]: info: Loading plugin "spop"... Apr 10 19:35:36 volumio volumio[1286]: info: Loading plugin "outputs"... Apr 10 19:35:36 volumio volumio[1286]: info: Loading plugin "albumart"... Apr 10 19:35:36 volumio volumio[1286]: info: Plugin example_plugin is not enabled Apr 10 19:35:36 volumio volumio[1286]: info: Loading plugin "inputs"... Apr 10 19:35:36 volumio volumio[1286]: info: Loading plugin "updater_comm"... Apr 10 19:35:36 volumio volumio[1286]: info: Plugin mpdemulation is not enabled Apr 10 19:35:36 volumio volumio[1286]: info: Loading plugin "rest_api"... Apr 10 19:35:36 volumio volumio[1286]: info: Loading plugin "websocket"... Apr 10 19:35:37 volumio volumio[1286]: info: Starting Socket.io Server version 1.7.4 Apr 10 19:35:37 volumio volumio[1286]: info: Loading i18n strings for locale de Apr 10 19:35:37 volumio volumio[1286]: Updating browse sources language Apr 10 19:35:37 volumio volumio[1286]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 10 19:35:37 volumio volumio[1286]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Apr 10 19:35:37 volumio volumio[1286]: info: CoreCommandRouter::initPlayerControls Apr 10 19:35:37 volumio volumio[1286]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 10 19:35:37 volumio volumio[1286]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 10 19:35:37 volumio volumio[1286]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 10 19:35:37 volumio volumio[1286]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 10 19:35:37 volumio volumio[1286]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 10 19:35:37 volumio volumio[1286]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 10 19:35:37 volumio volumio[1286]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 10 19:35:37 volumio volumio[1286]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 10 19:35:37 volumio volumio[1286]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Apr 10 19:35:37 volumio volumio[1286]: Express server listening on port 3000 Apr 10 19:35:37 volumio volumio[1286]: [Metrics] WebUI: 14s 648.64ms Apr 10 19:35:37 volumio volumio[1286]: info: CoreStateMachine::resetVolumioState Apr 10 19:35:37 volumio volumio[1286]: info: CoreStateMachine::getcurrentVolume Apr 10 19:35:37 volumio volumio[1286]: info: CoreCommandRouter::volumioRetrievevolume Apr 10 19:35:37 volumio volumio[1286]: info: Volumio Network Manager: Network status updated: 1 Apr 10 19:35:37 volumio volumio[1286]: verbose: New Socket.io Connection to 192.168.2.115 from 192.168.2.47 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/145.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 1 Apr 10 19:35:37 volumio volumio[1286]: info: CoreStateMachine::pushState Apr 10 19:35:37 volumio volumio[1286]: info: CorePlayQueue::getTrack 0 Apr 10 19:35:37 volumio volumio[1286]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 10 19:35:37 volumio volumio[1286]: info: CoreCommandRouter::volumioPushState Apr 10 19:35:37 volumio volumio[1286]: info: CoreStateMachine::updateTrackBlock Apr 10 19:35:37 volumio volumio[1286]: info: CorePlayQueue::getTrackBlock Apr 10 19:35:37 volumio volumio[1286]: info: CoreCommandRouter::volumioRetrievevolume Apr 10 19:35:37 volumio volumio[1286]: verbose: New Socket.io Connection to 192.168.2.115 from 192.168.2.47 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/145.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 2 Apr 10 19:35:37 volumio volumio[1286]: info: Reloading queue from file Apr 10 19:35:37 volumio volumio[1286]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 10 19:35:37 volumio volumio[1286]: verbose: New Socket.io Connection to 192.168.2.115 from 192.168.2.47 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/145.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 3 Apr 10 19:35:37 volumio volumio[1286]: info: CoreStateMachine::setRepeat null single undefined Apr 10 19:35:37 volumio volumio[1286]: info: CoreStateMachine::pushState Apr 10 19:35:37 volumio volumio[1286]: info: CorePlayQueue::getTrack 0 Apr 10 19:35:37 volumio volumio[1286]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 10 19:35:37 volumio volumio[1286]: info: CoreCommandRouter::volumioPushState Apr 10 19:35:37 volumio volumio[1286]: info: CoreStateMachine::setRandom null Apr 10 19:35:37 volumio volumio[1286]: info: CoreStateMachine::pushState Apr 10 19:35:37 volumio volumio[1286]: info: CorePlayQueue::getTrack 0 Apr 10 19:35:37 volumio volumio[1286]: info: CoreCommandRouter::volumioPushState Apr 10 19:35:37 volumio volumio[1286]: info: Setting Device type: Raspberry PI Apr 10 19:35:37 volumio volumio[1286]: info: Completed loading Core Plugins Apr 10 19:35:37 volumio volumio[1286]: info: Preparing to generate the ALSA configuration file Apr 10 19:35:37 volumio volumio[1286]: info: CoreStateMachine::pushState Apr 10 19:35:37 volumio volumio[1286]: info: CorePlayQueue::getTrack 0 Apr 10 19:35:37 volumio volumio[1286]: info: CoreCommandRouter::volumioPushState Apr 10 19:35:37 volumio volumio[1286]: info: The plugin alsa_controller has an ALSA contribution file softvolume.postVolume.conf Apr 10 19:35:37 volumio volumio[1286]: info: Reading ALSA contributions from plugins. Apr 10 19:35:38 volumio volumio[1286]: info: Discovery: adding 820776be-9728-4e69-a911-fd0aa19751c6 Apr 10 19:35:38 volumio volumio[1286]: info: Discovery: Found device Volumio Apr 10 19:35:38 volumio volumio[1286]: info: CoreCommandRouter::volumioGetState Apr 10 19:35:38 volumio volumio[1286]: info: CorePlayQueue::getTrack 0 Apr 10 19:35:38 volumio volumio[1286]: info: Discovery: this is already registered, 820776be-9728-4e69-a911-fd0aa19751c6 Apr 10 19:35:38 volumio volumio[1286]: info: Discovery: Found device Volumio Apr 10 19:35:38 volumio volumio[1286]: info: CoreCommandRouter::volumioGetState Apr 10 19:35:38 volumio volumio[1286]: info: CorePlayQueue::getTrack 0 Apr 10 19:35:38 volumio volumio[1286]: info: Asound.conf file unchanged, so no further update is needed Apr 10 19:35:38 volumio volumio[1286]: info: Output device has changed, restarting MPD Apr 10 19:35:38 volumio volumio[1286]: info: Output device has changed, restarting Shairport Sync Apr 10 19:35:38 volumio volumio[1286]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 10 19:35:38 volumio volumio[1286]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 10 19:35:38 volumio sudo[1431]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Apr 10 19:35:38 volumio sudo[1429]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Apr 10 19:35:38 volumio sudo[1429]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 10 19:35:38 volumio sudo[1431]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 10 19:35:38 volumio volumio[1286]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Apr 10 19:35:38 volumio volumio[1286]: info: ___________ START PLUGINS ___________ Apr 10 19:35:38 volumio sudo[1429]: pam_unix(sudo:session): session closed for user root Apr 10 19:35:38 volumio volumio[1286]: info: ControllerMpd::onStart: Initializing MPD Apr 10 19:35:38 volumio volumio[1286]: info: Creating MPD Configuration file Apr 10 19:35:38 volumio volumio[1286]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Apr 10 19:35:38 volumio volumio[1286]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Apr 10 19:35:38 volumio volumio[1286]: info: [1775842538318] CoreMusicLibrary::Adding element Medienserver Apr 10 19:35:38 volumio sudo[1439]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumio5-onboarding.service Apr 10 19:35:38 volumio sudo[1444]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Apr 10 19:35:38 volumio sudo[1444]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 10 19:35:38 volumio volumio[1286]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 10 19:35:38 volumio sudo[1439]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 10 19:35:38 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Apr 10 19:35:38 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Apr 10 19:35:38 volumio systemd[1]: systemd-fsckd.service: Deactivated successfully. Apr 10 19:35:38 volumio sudo[1441]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Apr 10 19:35:38 volumio sudo[1441]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 10 19:35:38 volumio volumio[1286]: info: UPNP Browser: Client initialized successfully Apr 10 19:35:38 volumio systemd[1]: mpd.service: Deactivated successfully. Apr 10 19:35:38 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Apr 10 19:35:38 volumio systemd[1]: mpd.socket: Deactivated successfully. Apr 10 19:35:38 volumio sudo[1441]: pam_unix(sudo:session): session closed for user root Apr 10 19:35:38 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Apr 10 19:35:38 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Apr 10 19:35:38 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Apr 10 19:35:38 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Apr 10 19:35:38 volumio volumio-remote-updater[723]: [2026-04-10 19:35:38] [connect] Successful connection Apr 10 19:35:38 volumio systemd[1]: Started volumio5-onboarding.service - Volumio5 Onboarding Server. Apr 10 19:35:38 volumio sudo[1439]: pam_unix(sudo:session): session closed for user root Apr 10 19:35:38 volumio volumio[1286]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 10 19:35:38 volumio volumio[1286]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 10 19:35:38 volumio volumio[1286]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Apr 10 19:35:38 volumio volumio[1286]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 10 19:35:38 volumio volumio[1286]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 10 19:35:38 volumio sudo[1450]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Apr 10 19:35:38 volumio sudo[1450]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Apr 10 19:35:38 volumio sudo[1469]: /bin/chown: cannot access '/var/log/mpd.log': No such file or directory Apr 10 19:35:38 volumio sudo[1450]: pam_unix(sudo:session): session closed for user root Apr 10 19:35:38 volumio volumio[1286]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Apr 10 19:35:38 volumio volumio[1286]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Apr 10 19:35:38 volumio volumio[1286]: info: [1775842538850] CoreMusicLibrary::Adding element Last_100 Apr 10 19:35:38 volumio volumio[1286]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 10 19:35:38 volumio volumio[1286]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Apr 10 19:35:38 volumio volumio[1286]: info: [1775842538874] CoreMusicLibrary::Adding element Webradio Apr 10 19:35:38 volumio volumio[1286]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 10 19:35:38 volumio volumio[1286]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Apr 10 19:35:38 volumio volumio[1286]: info: Initializing BBC Radios Apr 10 19:35:39 volumio volumio[1393]: Forking 3 albumart workers Apr 10 19:35:39 volumio volumio5-onboarding[1451]: time=2026-04-10T19:35:39.229+02:00 level=INFO msg="running volumio5-device-gateway" version=30d1950e+CHANGES buildDate=2026-01-29T13:10:08Z Apr 10 19:35:39 volumio volumio[1286]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Apr 10 19:35:39 volumio volumio[1286]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 10 19:35:39 volumio volumio[1286]: info: Creating Spotify config file Apr 10 19:35:39 volumio volumio[1286]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 10 19:35:39 volumio volumio[1286]: info: Volumio Calling Home Apr 10 19:35:41 volumio systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 2. Apr 10 19:35:41 volumio systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Apr 10 19:35:42 volumio systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Apr 10 19:35:42 volumio upmpdcli[1530]: Could not open config: /tmp/upmpdcli.conf Apr 10 19:35:42 volumio systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Apr 10 19:35:42 volumio systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Apr 10 19:35:43 volumio systemd[1]: systemd-hostnamed.service: Deactivated successfully. Apr 10 19:35:45 volumio sudo[1537]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Apr 10 19:35:45 volumio sudo[1537]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 10 19:35:45 volumio sudo[1537]: pam_unix(sudo:session): session closed for user root Apr 10 19:35:45 volumio sudo[1536]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Apr 10 19:35:46 volumio sudo[1536]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 10 19:35:46 volumio sudo[1536]: pam_unix(sudo:session): session closed for user root Apr 10 19:35:46 volumio mpd[1474]: 2026-04-10T19:35:46 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Apr 10 19:35:46 volumio volumio[1286]: info: MPD Permissions set Apr 10 19:35:46 volumio volumio[1286]: info: MPD Permissions set Apr 10 19:35:47 volumio systemd[1]: Started mpd.service - Music Player Daemon. Apr 10 19:35:47 volumio sudo[1431]: pam_unix(sudo:session): session closed for user root Apr 10 19:35:47 volumio sudo[1444]: pam_unix(sudo:session): session closed for user root Apr 10 19:35:47 volumio volumio[1286]: info: Volumio called home Apr 10 19:35:47 volumio volumio[1286]: info: Spotify config file written Apr 10 19:35:47 volumio sudo[1546]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Apr 10 19:35:47 volumio sudo[1546]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 10 19:35:47 volumio 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. Apr 10 19:35:47 volumio 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. Apr 10 19:35:47 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Apr 10 19:35:47 volumio go-librespot[1548]: go-librespot daemon starting... Apr 10 19:35:47 volumio sudo[1546]: pam_unix(sudo:session): session closed for user root Apr 10 19:35:48 volumio volumio[1498]: Starting albumart workers Apr 10 19:35:48 volumio go-librespot[1549]: time="2026-04-10T19:35:48+02:00" level=info msg="running go-librespot 0.6.2" Apr 10 19:35:48 volumio go-librespot[1549]: time="2026-04-10T19:35:48+02:00" level=debug msg="app state loaded" Apr 10 19:35:48 volumio go-librespot[1549]: time="2026-04-10T19:35:48+02:00" level=debug msg="stored credentials not found" Apr 10 19:35:48 volumio go-librespot[1549]: time="2026-04-10T19:35:48+02:00" level=info msg="api server listening on 127.0.0.1:9879" Apr 10 19:35:49 volumio go-librespot[1549]: time="2026-04-10T19:35:49+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Apr 10 19:35:49 volumio go-librespot[1549]: time="2026-04-10T19:35:49+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Apr 10 19:35:49 volumio go-librespot[1549]: time="2026-04-10T19:35:49+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Apr 10 19:35:49 volumio go-librespot[1549]: time="2026-04-10T19:35:49+02:00" level=info msg="zeroconf server listening on port 43795" Apr 10 19:35:49 volumio volumio[1286]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 4 Apr 10 19:35:49 volumio volumio[1286]: info: Completed starting Core Plugins Apr 10 19:35:49 volumio volumio[1286]: info: ------------------------------------------- Apr 10 19:35:49 volumio volumio[1286]: info: ----- MyVolumio plugins startup ---- Apr 10 19:35:49 volumio volumio[1286]: info: ------------------------------------------- Apr 10 19:35:49 volumio volumio[1286]: info: [MyVolumio PluginManager] Fetching plans data.... Apr 10 19:35:49 volumio volumio[1286]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 10 19:35:49 volumio volumio[1286]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 10 19:35:49 volumio volumio[1286]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 10 19:35:49 volumio volumio[1286]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 10 19:35:49 volumio volumio[1286]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 10 19:35:49 volumio volumio[1286]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 10 19:35:49 volumio volumio[1286]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 10 19:35:49 volumio volumio[1286]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 10 19:35:49 volumio volumio[1286]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 10 19:35:49 volumio volumio[1286]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 10 19:35:49 volumio volumio[1286]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 10 19:35:49 volumio volumio[1286]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 10 19:35:49 volumio volumio[1286]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 10 19:35:49 volumio volumio[1286]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 10 19:35:49 volumio volumio[1286]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 10 19:35:49 volumio volumio[1286]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 10 19:35:49 volumio volumio[1286]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 10 19:35:49 volumio volumio[1286]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 10 19:35:50 volumio volumio[1286]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 10 19:35:50 volumio volumio[1286]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 10 19:35:50 volumio volumio[1286]: info: No need to fix Spotify hosts Apr 10 19:35:50 volumio volumio[1507]: Starting albumart workers Apr 10 19:35:50 volumio volumio[1286]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 4 Apr 10 19:35:51 volumio volumio[1497]: Starting albumart workers Apr 10 19:35:51 volumio volumio[1286]: info: Received Get System Info Apr 10 19:35:51 volumio volumio[1286]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 10 19:35:51 volumio volumio[1286]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 10 19:35:51 volumio volumio[1286]: info: Discovery: Getting this device information Apr 10 19:35:51 volumio volumio[1286]: info: CoreCommandRouter::volumioGetState Apr 10 19:35:51 volumio volumio[1286]: info: CorePlayQueue::getTrack 0 Apr 10 19:35:51 volumio volumio[1286]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 10 19:35:51 volumio volumio5-onboarding[1451]: time=2026-04-10T19:35:51.121+02:00 level=INFO msg="system info for dcdf8ce376176a059293946f5ca17709" deviceName=Volumio deviceVariant=volumio deviceModel= softwareVersion=4.096 Apr 10 19:35:51 volumio volumio[1286]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 5 Apr 10 19:35:51 volumio volumio[1286]: info: Received Get System Info Apr 10 19:35:51 volumio volumio[1286]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 10 19:35:51 volumio volumio[1286]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 10 19:35:51 volumio volumio[1286]: info: Discovery: Getting this device information Apr 10 19:35:51 volumio volumio[1286]: info: CoreCommandRouter::volumioGetState Apr 10 19:35:51 volumio volumio[1286]: info: CorePlayQueue::getTrack 0 Apr 10 19:35:51 volumio volumio[1286]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 10 19:35:52 volumio volumio[1286]: error: MPD error: The expression evaluated to a falsy value: Apr 10 19:35:52 volumio volumio[1286]: assert.ok(self.idling) Apr 10 19:35:52 volumio volumio[1286]: error: The expression evaluated to a falsy value: Apr 10 19:35:52 volumio volumio[1286]: assert.ok(self.idling) Apr 10 19:35:52 volumio volumio[1286]: info: MPD running with PID1474 Apr 10 19:35:52 volumio volumio[1286]: ,establishing connection Apr 10 19:35:52 volumio volumio[1286]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Apr 10 19:35:52 volumio volumio[1286]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Apr 10 19:35:52 volumio volumio5-onboarding[1451]: time=2026-04-10T19:35:52.567+02:00 level=INFO msg="enabling local network discovery" Apr 10 19:35:52 volumio volumio[1286]: error: updateQueue error: null Apr 10 19:35:52 volumio volumio5-onboarding[1451]: time=2026-04-10T19:35:52.611+02:00 level=INFO msg="bootstrapping state" hasInternet=true Apr 10 19:35:52 volumio volumio[1286]: info: Starting Shairport Sync Apr 10 19:35:52 volumio volumio[1286]: info: Starting Shairport Sync Apr 10 19:35:52 volumio sudo[1596]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Apr 10 19:35:52 volumio sudo[1596]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 10 19:35:52 volumio volumio[1286]: info: Starting Shairport Sync Apr 10 19:35:52 volumio volumio[1286]: error: updateQueue error: null Apr 10 19:35:52 volumio sudo[1600]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Apr 10 19:35:52 volumio sudo[1600]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 10 19:35:52 volumio volumio[1286]: info: Received Get System Info Apr 10 19:35:52 volumio volumio[1286]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 10 19:35:52 volumio volumio[1286]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 10 19:35:52 volumio volumio[1286]: info: Discovery: Getting this device information Apr 10 19:35:52 volumio volumio[1286]: info: CoreCommandRouter::volumioGetState Apr 10 19:35:52 volumio volumio[1286]: info: CorePlayQueue::getTrack 0 Apr 10 19:35:52 volumio volumio[1286]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 10 19:35:52 volumio systemd[1]: Starting e2scrub_all.service - Online ext4 Metadata Check for All Filesystems... Apr 10 19:35:52 volumio systemd[1]: Starting setdatetime-helper.service - Time Synchronization Helper Service... Apr 10 19:35:53 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Apr 10 19:35:53 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Apr 10 19:35:53 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Apr 10 19:35:53 volumio systemd[1]: shairport-sync.service: Consumed 1.939s CPU time. Apr 10 19:35:53 volumio systemd[1]: e2scrub_all.service: Deactivated successfully. Apr 10 19:35:53 volumio systemd[1]: Finished e2scrub_all.service - Online ext4 Metadata Check for All Filesystems. Apr 10 19:35:53 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Apr 10 19:35:53 volumio sudo[1601]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Apr 10 19:35:53 volumio sudo[1596]: pam_unix(sudo:session): session closed for user root Apr 10 19:35:53 volumio sudo[1603]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Apr 10 19:35:53 volumio sudo[1603]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 10 19:35:53 volumio sudo[1601]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 10 19:35:53 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Apr 10 19:35:53 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Apr 10 19:35:53 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Apr 10 19:35:53 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Apr 10 19:35:53 volumio volumio-remote-updater[723]: [2026-04-10 19:35:53] [connect] Successful connection Apr 10 19:35:53 volumio sudo[1603]: pam_unix(sudo:session): session closed for user root Apr 10 19:35:53 volumio sudo[1600]: pam_unix(sudo:session): session closed for user root Apr 10 19:35:53 volumio volumio[1286]: info: Shairport-Sync Started Apr 10 19:35:53 volumio volumio[1286]: Error adding Membership: Error: addMembership EINVAL Apr 10 19:35:53 volumio volumio[1286]: info: Shairport-Sync Started Apr 10 19:35:53 volumio volumio[1286]: info: Shairport-Sync Started Apr 10 19:35:54 volumio volumio-remote-updater[723]: [2026-04-10 19:35:54] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1775842553 101 Apr 10 19:35:54 volumio volumio[1286]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 3 Transport: websocket Total Clients: 6 Apr 10 19:35:54 volumio volumio[1286]: info: go-librespot daemon successfully initialized Apr 10 19:35:54 volumio volumio[1286]: info: CoreCommandRouter::volumioGetState Apr 10 19:35:54 volumio volumio[1286]: info: CorePlayQueue::getTrack 0 Apr 10 19:35:55 volumio systemd[1]: setdatetime-helper.service: Deactivated successfully. Apr 10 19:35:55 volumio systemd[1]: Finished setdatetime-helper.service - Time Synchronization Helper Service. Apr 10 19:35:55 volumio systemd[1]: setdatetime-helper.service: Consumed 1.424s CPU time. Apr 10 19:35:57 volumio systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 3. Apr 10 19:35:57 volumio systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Apr 10 19:35:57 volumio volumio[1286]: info: Initializing connection to go-librespot Websocket Apr 10 19:35:57 volumio systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Apr 10 19:35:57 volumio sudo[1601]: pam_unix(sudo:session): session closed for user root Apr 10 19:35:57 volumio volumio[1286]: info: Upmpdcli Daemon Started Apr 10 19:35:57 volumio go-librespot[1549]: time="2026-04-10T19:35:57+02:00" level=debug msg="new websocket client" Apr 10 19:35:57 volumio volumio[1286]: info: Connection to go-librespot Websocket established Apr 10 19:35:57 volumio volumio[1286]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Apr 10 19:36:01 volumio volumio[1286]: info: Getting Spotify volume Apr 10 19:36:07 volumio go-librespot[1549]: time="2026-04-10T19:36:07+02:00" level=debug msg="obtained new client token: AAAdQ8GA8ylmVhgHk0r/nGqmuxYcuTXZd2BMYL8AY6mM6c6AUs27oWp3aA5TKXM/xDPW3iH4p9WgwcbuD76R6klYTNcN5+krc+xgNWCPbJ6ZKNa5dOdLxLFXVHk47CuKac8wpH+XsfxmNrk8kT4qcdnDOrFj8Gc5voMPNG5P30XuloJvR/VIvdNwV3u+6CkprJ5ewlcviMmyD7l33CapVUdnMbXxRMdJH1fPFHoCKcKadUyFy6fSupaGvew=" Apr 10 19:36:07 volumio go-librespot[1549]: time="2026-04-10T19:36:07+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Apr 10 19:36:07 volumio go-librespot[1549]: time="2026-04-10T19:36:07+02:00" level=debug msg="completed keyexchange" Apr 10 19:36:07 volumio go-librespot[1549]: time="2026-04-10T19:36:07+02:00" level=debug msg="completed challenge" Apr 10 19:36:07 volumio go-librespot[1549]: time="2026-04-10T19:36:07+02:00" level=info msg="authenticated AP" username="br****78" Apr 10 19:36:08 volumio go-librespot[1549]: time="2026-04-10T19:36:08+02:00" level=info msg="authenticated Login5" username="br****78" Apr 10 19:36:08 volumio go-librespot[1549]: time="2026-04-10T19:36:08+02:00" level=info msg="accepted zeroconf from iPad" username="br****78" Apr 10 19:36:08 volumio go-librespot[1549]: time="2026-04-10T19:36:08+02:00" level=debug msg="dealer connection opened" Apr 10 19:36:08 volumio go-librespot[1549]: time="2026-04-10T19:36:08+02:00" level=trace msg="starting accesspoint recv loop" Apr 10 19:36:08 volumio go-librespot[1549]: time="2026-04-10T19:36:08+02:00" level=trace msg="starting dealer recv loop" Apr 10 19:36:08 volumio go-librespot[1549]: time="2026-04-10T19:36:08+02:00" level=trace msg="received accesspoint ping" Apr 10 19:36:08 volumio go-librespot[1549]: time="2026-04-10T19:36:08+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Apr 10 19:36:08 volumio go-librespot[1549]: time="2026-04-10T19:36:08+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Apr 10 19:36:08 volumio go-librespot[1549]: time="2026-04-10T19:36:08+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Apr 10 19:36:08 volumio go-librespot[1549]: time="2026-04-10T19:36:08+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Apr 10 19:36:08 volumio go-librespot[1549]: time="2026-04-10T19:36:08+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Apr 10 19:36:08 volumio go-librespot[1549]: time="2026-04-10T19:36:08+02:00" level=debug msg="received connection id: MDg5MjdhNTYtMDRk...NUU4MkNFNkQ1RQ==" Apr 10 19:36:08 volumio go-librespot[1549]: time="2026-04-10T19:36:08+02:00" level=trace msg="received accesspoint pong ack" Apr 10 19:36:08 volumio go-librespot[1549]: time="2026-04-10T19:36:08+02:00" level=debug msg="put connect state because NEW_DEVICE" Apr 10 19:36:08 volumio go-librespot[1549]: time="2026-04-10T19:36:08+02:00" level=debug msg="handling transfer player command from dfb057953b940f8135e810f0d2559f0fb834541a" Apr 10 19:36:08 volumio go-librespot[1549]: time="2026-04-10T19:36:08+02:00" level=debug msg="resolved context of track" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:08 volumio go-librespot[1549]: time="2026-04-10T19:36:08+02:00" level=trace msg="loading context page from artistplaycontext/v1/page/spotify/album/5R9jQdWKo4HUsqHJFofAy2/km" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:08 volumio go-librespot[1549]: time="2026-04-10T19:36:08+02:00" level=trace msg="fetched new page from (has next: false)" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:08 volumio go-librespot[1549]: time="2026-04-10T19:36:08+02:00" level=trace msg="fetched new page 0 with 2 items (list: 2)" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:08 volumio go-librespot[1549]: time="2026-04-10T19:36:08+02:00" level=trace msg="loading context page from artistplaycontext/v1/page/spotify/album/3BtzAsMFsTiqHC4LKgclG0/km" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:08 volumio go-librespot[1549]: time="2026-04-10T19:36:08+02:00" level=trace msg="fetched new page from (has next: false)" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:08 volumio go-librespot[1549]: time="2026-04-10T19:36:08+02:00" level=trace msg="fetched new page 1 with 25 items (list: 27)" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:08 volumio go-librespot[1549]: time="2026-04-10T19:36:08+02:00" level=trace msg="loading context page from artistplaycontext/v1/page/spotify/album/55S3ZotBiszLOXNEE7tx7Q/km" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:08 volumio go-librespot[1549]: time="2026-04-10T19:36:08+02:00" level=trace msg="fetched new page from (has next: false)" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:08 volumio go-librespot[1549]: time="2026-04-10T19:36:08+02:00" level=trace msg="fetched new page 2 with 20 items (list: 47)" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:08 volumio go-librespot[1549]: time="2026-04-10T19:36:08+02:00" level=trace msg="loading context page from artistplaycontext/v1/page/spotify/album/7hDh7xY2NJsrpMUIQFjcXE/km" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:08 volumio go-librespot[1549]: time="2026-04-10T19:36:08+02:00" level=trace msg="fetched new page from (has next: false)" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:08 volumio go-librespot[1549]: time="2026-04-10T19:36:08+02:00" level=trace msg="fetched new page 3 with 10 items (list: 57)" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:08 volumio go-librespot[1549]: time="2026-04-10T19:36:08+02:00" level=trace msg="loading context page from artistplaycontext/v1/page/spotify/album/5X9OQxBHtSIxlti9g5Xzav/km" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:08 volumio go-librespot[1549]: time="2026-04-10T19:36:08+02:00" level=trace msg="fetched new page from (has next: false)" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:08 volumio go-librespot[1549]: time="2026-04-10T19:36:08+02:00" level=trace msg="fetched new page 4 with 8 items (list: 65)" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:08 volumio go-librespot[1549]: time="2026-04-10T19:36:08+02:00" level=trace msg="loading context page from artistplaycontext/v1/page/spotify/album/4G35yvOQ1JcH3taN5NpENN/km" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:08 volumio go-librespot[1549]: time="2026-04-10T19:36:08+02:00" level=trace msg="fetched new page from (has next: false)" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:08 volumio go-librespot[1549]: time="2026-04-10T19:36:08+02:00" level=trace msg="fetched new page 5 with 10 items (list: 75)" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:08 volumio go-librespot[1549]: time="2026-04-10T19:36:08+02:00" level=trace msg="loading context page from artistplaycontext/v1/page/spotify/album/4Rj1WnHjEumhaypD0PWioc/km" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:08 volumio go-librespot[1549]: time="2026-04-10T19:36:08+02:00" level=trace msg="fetched new page from (has next: false)" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:08 volumio go-librespot[1549]: time="2026-04-10T19:36:08+02:00" level=trace msg="fetched new page 6 with 10 items (list: 85)" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:08 volumio go-librespot[1549]: time="2026-04-10T19:36:08+02:00" level=trace msg="loading context page from artistplaycontext/v1/page/spotify/album/09jvItaMhKfumQ22B7pKE7/km" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:08 volumio go-librespot[1549]: time="2026-04-10T19:36:08+02:00" level=trace msg="fetched new page from (has next: false)" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:08 volumio go-librespot[1549]: time="2026-04-10T19:36:08+02:00" level=trace msg="fetched new page 7 with 1 items (list: 86)" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:08 volumio go-librespot[1549]: time="2026-04-10T19:36:08+02:00" level=trace msg="loading context page from artistplaycontext/v1/page/spotify/album/5FZAI4Bw3S575e1pL0Qhbs/km" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:08 volumio go-librespot[1549]: time="2026-04-10T19:36:08+02:00" level=trace msg="fetched new page from (has next: false)" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:08 volumio go-librespot[1549]: time="2026-04-10T19:36:08+02:00" level=trace msg="fetched new page 8 with 23 items (list: 109)" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:08 volumio go-librespot[1549]: time="2026-04-10T19:36:08+02:00" level=trace msg="loading context page from artistplaycontext/v1/page/spotify/album/0n9y9P04G9FeefRnWW8dGL/km" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:08 volumio go-librespot[1549]: time="2026-04-10T19:36:08+02:00" level=trace msg="fetched new page from (has next: false)" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:08 volumio go-librespot[1549]: time="2026-04-10T19:36:08+02:00" level=trace msg="fetched new page 9 with 1 items (list: 110)" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:08 volumio go-librespot[1549]: time="2026-04-10T19:36:08+02:00" level=trace msg="loading context page from artistplaycontext/v1/page/spotify/album/4K8xMOlFWwjd0SN2VppJjY/km" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:08 volumio go-librespot[1549]: time="2026-04-10T19:36:08+02:00" level=trace msg="fetched new page from (has next: false)" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:08 volumio go-librespot[1549]: time="2026-04-10T19:36:08+02:00" level=trace msg="fetched new page 10 with 15 items (list: 125)" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:08 volumio go-librespot[1549]: time="2026-04-10T19:36:08+02:00" level=trace msg="loading context page from artistplaycontext/v1/page/spotify/album/5iPvfzK3uHaSvdytvcw1xd/km" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:08 volumio go-librespot[1549]: time="2026-04-10T19:36:08+02:00" level=trace msg="fetched new page from (has next: false)" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:08 volumio go-librespot[1549]: time="2026-04-10T19:36:08+02:00" level=trace msg="fetched new page 11 with 9 items (list: 134)" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:08 volumio go-librespot[1549]: time="2026-04-10T19:36:08+02:00" level=trace msg="loading context page from artistplaycontext/v1/page/spotify/album/5aRjfoDIJ4OU0G0bvi2B0l/km" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:08 volumio go-librespot[1549]: time="2026-04-10T19:36:08+02:00" level=trace msg="fetched new page from (has next: false)" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:08 volumio go-librespot[1549]: time="2026-04-10T19:36:08+02:00" level=trace msg="fetched new page 12 with 1 items (list: 135)" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:08 volumio go-librespot[1549]: time="2026-04-10T19:36:08+02:00" level=trace msg="loading context page from artistplaycontext/v1/page/spotify/album/17a562KMG0dw7XUS95TKoz/km" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:08 volumio go-librespot[1549]: time="2026-04-10T19:36:08+02:00" level=trace msg="fetched new page from (has next: false)" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:08 volumio go-librespot[1549]: time="2026-04-10T19:36:08+02:00" level=trace msg="fetched new page 13 with 1 items (list: 136)" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:08 volumio go-librespot[1549]: time="2026-04-10T19:36:08+02:00" level=trace msg="loading context page from artistplaycontext/v1/page/spotify/album/2jgk5KzppwRPmcNANCs0h6/km" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:08 volumio go-librespot[1549]: time="2026-04-10T19:36:08+02:00" level=trace msg="fetched new page from (has next: false)" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:08 volumio go-librespot[1549]: time="2026-04-10T19:36:08+02:00" level=trace msg="fetched new page 14 with 1 items (list: 137)" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:08 volumio go-librespot[1549]: time="2026-04-10T19:36:08+02:00" level=trace msg="loading context page from artistplaycontext/v1/page/spotify/album/2cxiElVXlef4bPUWgzIWxh/km" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:09 volumio go-librespot[1549]: time="2026-04-10T19:36:09+02:00" level=trace msg="fetched new page from (has next: false)" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:09 volumio go-librespot[1549]: time="2026-04-10T19:36:09+02:00" level=trace msg="fetched new page 15 with 20 items (list: 157)" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:09 volumio go-librespot[1549]: time="2026-04-10T19:36:09+02:00" level=trace msg="loading context page from artistplaycontext/v1/page/spotify/album/1sgFOVl6DyEFUG9HnonlWk/km" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:09 volumio go-librespot[1549]: time="2026-04-10T19:36:09+02:00" level=trace msg="fetched new page from (has next: false)" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:09 volumio go-librespot[1549]: time="2026-04-10T19:36:09+02:00" level=trace msg="fetched new page 16 with 1 items (list: 158)" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:09 volumio go-librespot[1549]: time="2026-04-10T19:36:09+02:00" level=trace msg="loading context page from artistplaycontext/v1/page/spotify/album/2HpL8U4L5ibYXhfiBQmbPo/km" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:09 volumio go-librespot[1549]: time="2026-04-10T19:36:09+02:00" level=trace msg="fetched new page from (has next: false)" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:09 volumio go-librespot[1549]: time="2026-04-10T19:36:09+02:00" level=trace msg="fetched new page 17 with 1 items (list: 159)" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:09 volumio go-librespot[1549]: time="2026-04-10T19:36:09+02:00" level=trace msg="loading context page from artistplaycontext/v1/page/spotify/album/6BUR55MxmZe3j3iCPK7m0M/km" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:09 volumio go-librespot[1549]: time="2026-04-10T19:36:09+02:00" level=trace msg="fetched new page from (has next: false)" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:09 volumio go-librespot[1549]: time="2026-04-10T19:36:09+02:00" level=trace msg="fetched new page 18 with 9 items (list: 168)" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:09 volumio go-librespot[1549]: time="2026-04-10T19:36:09+02:00" level=trace msg="loading context page from artistplaycontext/v1/page/spotify/album/1woIhjMC2Q2SiSBQ9Nu2q6/km" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:09 volumio go-librespot[1549]: time="2026-04-10T19:36:09+02:00" level=trace msg="fetched new page from (has next: false)" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:09 volumio go-librespot[1549]: time="2026-04-10T19:36:09+02:00" level=trace msg="fetched new page 19 with 9 items (list: 177)" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:09 volumio go-librespot[1549]: time="2026-04-10T19:36:09+02:00" level=trace msg="loading context page from artistplaycontext/v1/page/spotify/album/0XGXlCdUv0ow06y6Il1vDM/km" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:09 volumio go-librespot[1549]: time="2026-04-10T19:36:09+02:00" level=trace msg="fetched new page from (has next: false)" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:09 volumio go-librespot[1549]: time="2026-04-10T19:36:09+02:00" level=trace msg="fetched new page 20 with 1 items (list: 178)" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:09 volumio go-librespot[1549]: time="2026-04-10T19:36:09+02:00" level=trace msg="loading context page from artistplaycontext/v1/page/spotify/album/7fYmMwPXen4CHYKU9AMuz2/km" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:09 volumio go-librespot[1549]: time="2026-04-10T19:36:09+02:00" level=trace msg="fetched new page from (has next: false)" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:09 volumio go-librespot[1549]: time="2026-04-10T19:36:09+02:00" level=trace msg="fetched new page 21 with 1 items (list: 179)" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:09 volumio go-librespot[1549]: time="2026-04-10T19:36:09+02:00" level=trace msg="loading context page from artistplaycontext/v1/page/spotify/album/2M9yVWQJKZlCszDcPSkNAy/km" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:09 volumio go-librespot[1549]: time="2026-04-10T19:36:09+02:00" level=trace msg="fetched new page from (has next: false)" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:09 volumio go-librespot[1549]: time="2026-04-10T19:36:09+02:00" level=trace msg="fetched new page 22 with 1 items (list: 180)" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:09 volumio go-librespot[1549]: time="2026-04-10T19:36:09+02:00" level=trace msg="loading context page from artistplaycontext/v1/page/spotify/album/3sM4v7DzXYUQYKPRr6xBKu/km" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:09 volumio go-librespot[1549]: time="2026-04-10T19:36:09+02:00" level=trace msg="fetched new page from (has next: false)" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:09 volumio go-librespot[1549]: time="2026-04-10T19:36:09+02:00" level=trace msg="fetched new page 23 with 1 items (list: 181)" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:09 volumio go-librespot[1549]: time="2026-04-10T19:36:09+02:00" level=trace msg="loading context page from artistplaycontext/v1/page/spotify/album/4MwNp8SXDYGo2SzBZZTZx0/km" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:09 volumio go-librespot[1549]: time="2026-04-10T19:36:09+02:00" level=trace msg="fetched new page from (has next: false)" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:09 volumio go-librespot[1549]: time="2026-04-10T19:36:09+02:00" level=trace msg="fetched new page 24 with 21 items (list: 202)" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:09 volumio go-librespot[1549]: time="2026-04-10T19:36:09+02:00" level=trace msg="loading context page from artistplaycontext/v1/page/spotify/album/0AaY55M8IZ0iCpsZPdmVqN/km" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:09 volumio go-librespot[1549]: time="2026-04-10T19:36:09+02:00" level=trace msg="fetched new page from (has next: false)" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:09 volumio go-librespot[1549]: time="2026-04-10T19:36:09+02:00" level=trace msg="fetched new page 25 with 9 items (list: 211)" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:09 volumio go-librespot[1549]: time="2026-04-10T19:36:09+02:00" level=trace msg="loading context page from artistplaycontext/v1/page/spotify/album/0TKLgkR9wInodtqGxdAJAt/km" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:09 volumio go-librespot[1549]: time="2026-04-10T19:36:09+02:00" level=trace msg="fetched new page from (has next: false)" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:09 volumio go-librespot[1549]: time="2026-04-10T19:36:09+02:00" level=trace msg="fetched new page 26 with 9 items (list: 220)" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:09 volumio go-librespot[1549]: time="2026-04-10T19:36:09+02:00" level=trace msg="loading context page from artistplaycontext/v1/page/spotify/album/2dTdFFi4YZ5NYPlZ2bmd24/km" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:09 volumio go-librespot[1549]: time="2026-04-10T19:36:09+02:00" level=trace msg="fetched new page from (has next: false)" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:09 volumio go-librespot[1549]: time="2026-04-10T19:36:09+02:00" level=trace msg="fetched new page 27 with 21 items (list: 241)" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:09 volumio go-librespot[1549]: time="2026-04-10T19:36:09+02:00" level=trace msg="loading context page from artistplaycontext/v1/page/spotify/album/5eHKGlhGIGEEQLnRVNxGq8/km" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:09 volumio go-librespot[1549]: time="2026-04-10T19:36:09+02:00" level=trace msg="fetched new page from (has next: false)" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:09 volumio go-librespot[1549]: time="2026-04-10T19:36:09+02:00" level=trace msg="fetched new page 28 with 10 items (list: 251)" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:09 volumio go-librespot[1549]: time="2026-04-10T19:36:09+02:00" level=trace msg="loading context page from artistplaycontext/v1/page/spotify/album/10tlf97SKfqkzzj5y7xjqI/km" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:09 volumio go-librespot[1549]: time="2026-04-10T19:36:09+02:00" level=trace msg="fetched new page from (has next: false)" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:09 volumio go-librespot[1549]: time="2026-04-10T19:36:09+02:00" level=trace msg="fetched new page 29 with 3 items (list: 254)" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:09 volumio go-librespot[1549]: time="2026-04-10T19:36:09+02:00" level=trace msg="loading context page from artistplaycontext/v1/page/spotify/album/7rtK5FNmJchfUDXNEA7Qty/km" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:09 volumio go-librespot[1549]: time="2026-04-10T19:36:09+02:00" level=trace msg="fetched new page from (has next: false)" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:09 volumio go-librespot[1549]: time="2026-04-10T19:36:09+02:00" level=trace msg="fetched new page 30 with 13 items (list: 267)" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:09 volumio go-librespot[1549]: time="2026-04-10T19:36:09+02:00" level=trace msg="fetched new page 31 with 18 items (list: 285)" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:09 volumio go-librespot[1549]: time="2026-04-10T19:36:09+02:00" level=trace msg="fetched new page 32 with 9 items (list: 294)" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:09 volumio go-librespot[1549]: time="2026-04-10T19:36:09+02:00" level=trace msg="loading context page from artistplaycontext/v1/page/spotify/album/5ct8FoqpHiSZXxZ6mdD01f/km" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:09 volumio go-librespot[1549]: time="2026-04-10T19:36:09+02:00" level=trace msg="fetched new page from (has next: false)" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:09 volumio go-librespot[1549]: time="2026-04-10T19:36:09+02:00" level=trace msg="fetched new page 33 with 17 items (list: 311)" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:09 volumio go-librespot[1549]: time="2026-04-10T19:36:09+02:00" level=trace msg="loading context page from artistplaycontext/v1/page/spotify/album/0CZma5f5OAjlMYqOP8DZt7/km" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:09 volumio go-librespot[1549]: time="2026-04-10T19:36:09+02:00" level=trace msg="fetched new page from (has next: false)" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:09 volumio go-librespot[1549]: time="2026-04-10T19:36:09+02:00" level=trace msg="fetched new page 34 with 8 items (list: 319)" uri="spotify:artist:1JdeDdujDbS6ZeSlkXqx3a" Apr 10 19:36:09 volumio go-librespot[1549]: time="2026-04-10T19:36:09+02:00" level=debug msg="loading track (paused: true, position: 353126ms)" uri="spotify:track:5lemzoYLaoDdbbEwSZHvHD" Apr 10 19:36:09 volumio go-librespot[1549]: time="2026-04-10T19:36:09+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 10 19:36:09 volumio go-librespot[1549]: time="2026-04-10T19:36:09+02:00" level=trace msg="emitting websocket event: will_play" Apr 10 19:36:09 volumio go-librespot[1549]: time="2026-04-10T19:36:09+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 411" Apr 10 19:36:09 volumio go-librespot[1549]: time="2026-04-10T19:36:09+02:00" level=debug msg="selected format OGG_VORBIS_320 (9965cc9e0f2a7eeb74ad21320258c784aa209b08)" uri="spotify:track:5lemzoYLaoDdbbEwSZHvHD" Apr 10 19:36:09 volumio go-librespot[1549]: time="2026-04-10T19:36:09+02:00" level=debug msg="requested aes key for file 9965cc9e0f2a7eeb74ad21320258c784aa209b08, gid: 5lemzoYLaoDdbbEwSZHvHD" Apr 10 19:36:09 volumio go-librespot[1549]: time="2026-04-10T19:36:09+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1678" Apr 10 19:36:09 volumio volumio[1286]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Apr 10 19:36:09 volumio volumio[1286]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 10 19:36:09 volumio volumio[1286]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Apr 10 19:36:09 volumio go-librespot[1549]: time="2026-04-10T19:36:09+02:00" level=trace msg="found 2 cdn urls" uri="spotify:track:5lemzoYLaoDdbbEwSZHvHD" Apr 10 19:36:10 volumio go-librespot[1549]: time="2026-04-10T19:36:10+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1292" Apr 10 19:36:10 volumio volumio[1286]: error: MyVolumio Plugin failed to start in a timely fashion Apr 10 19:36:10 volumio volumio[1286]: [Metrics] CommandRouter: 46s 67.70ms Apr 10 19:36:10 volumio go-librespot[1549]: time="2026-04-10T19:36:10+02:00" level=debug msg="fetched first chunk of 29, total size is 15163141 bytes" uri="spotify:track:5lemzoYLaoDdbbEwSZHvHD" Apr 10 19:36:10 volumio volumio[1286]: info: CoreCommandRouter::volumiosetStartupVolume Apr 10 19:36:10 volumio volumio[1286]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 10 19:36:10 volumio volumio[1286]: info: VolumeController:: Setting startup Volume 80 Apr 10 19:36:10 volumio volumio[1286]: info: VolumeController::SetAlsaVolume80 Apr 10 19:36:10 volumio volumio[1286]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 10 19:36:10 volumio volumio[1286]: info: CoreCommandRouter::Close All Modals sent Apr 10 19:36:10 volumio volumio[1286]: info: CoreCommandRouter::Close All Modals sent Apr 10 19:36:10 volumio volumio[1286]: info: CoreStateMachine::pushState Apr 10 19:36:10 volumio volumio[1286]: info: CorePlayQueue::getTrack 0 Apr 10 19:36:10 volumio volumio[1286]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 10 19:36:10 volumio volumio[1286]: info: CoreCommandRouter::volumioPushState Apr 10 19:36:10 volumio go-librespot[1549]: time="2026-04-10T19:36:10+02:00" level=debug msg="fetched chunk 1/28, size: 524288" uri="spotify:track:5lemzoYLaoDdbbEwSZHvHD" Apr 10 19:36:10 volumio volumio[1286]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 10 19:36:10 volumio go-librespot[1549]: time="2026-04-10T19:36:10+02:00" level=debug msg="fetched chunk 2/28, size: 524288" uri="spotify:track:5lemzoYLaoDdbbEwSZHvHD" Apr 10 19:36:10 volumio go-librespot[1549]: time="2026-04-10T19:36:10+02:00" level=debug msg="fetched chunk 26/28, size: 524288" uri="spotify:track:5lemzoYLaoDdbbEwSZHvHD" Apr 10 19:36:10 volumio go-librespot[1549]: time="2026-04-10T19:36:10+02:00" level=debug msg="fetched chunk 25/28, size: 524288" uri="spotify:track:5lemzoYLaoDdbbEwSZHvHD" Apr 10 19:36:10 volumio volumio[1286]: Error [ERR_INTERNAL_ASSERTION]: This is caused by either a bug in Node.js or incorrect usage of Node.js internals. Apr 10 19:36:10 volumio volumio[1286]: Please open an issue with this stack trace at https://github.com/nodejs/node/issues Apr 10 19:36:10 volumio volumio[1286]: at new NodeError (node:internal/errors:405:5) Apr 10 19:36:10 volumio volumio[1286]: at assert (node:internal/assert:14:11) Apr 10 19:36:10 volumio volumio[1286]: at internalConnectMultiple (node:net:1118:3) Apr 10 19:36:10 volumio volumio[1286]: at Timeout.internalConnectMultipleTimeout (node:net:1687:3) Apr 10 19:36:10 volumio volumio[1286]: at listOnTimeout (node:internal/timers:575:11) Apr 10 19:36:10 volumio volumio[1286]: at process.processTimers (node:internal/timers:514:7) { Apr 10 19:36:10 volumio volumio[1286]: code: 'ERR_INTERNAL_ASSERTION' Apr 10 19:36:10 volumio volumio[1286]: } Apr 10 19:36:10 volumio volumio[1286]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 10 19:36:10 volumio go-librespot[1549]: time="2026-04-10T19:36:10+02:00" level=debug msg="fetched chunk 3/28, size: 524288" uri="spotify:track:5lemzoYLaoDdbbEwSZHvHD" Apr 10 19:36:10 volumio go-librespot[1549]: time="2026-04-10T19:36:10+02:00" level=debug msg="fetched chunk 24/28, size: 524288" uri="spotify:track:5lemzoYLaoDdbbEwSZHvHD" Apr 10 19:36:10 volumio go-librespot[1549]: time="2026-04-10T19:36:10+02:00" level=trace msg="seek to 353126ms (diff: 372ms, samples: 15572856, bytes: 12751381)" uri="spotify:track:5lemzoYLaoDdbbEwSZHvHD" Apr 10 19:36:10 volumio go-librespot[1549]: time="2026-04-10T19:36:10+02:00" level=debug msg="created new output device" Apr 10 19:36:10 volumio go-librespot[1549]: time="2026-04-10T19:36:10+02:00" level=info msg="loaded track \"Never-Ending Road (Amhrán Duit) - Nights from the Alhambra Live\" (paused: true, position: 353126ms, duration: 388214ms, prefetched: false)" uri="spotify:track:5lemzoYLaoDdbbEwSZHvHD" Apr 10 19:36:10 volumio go-librespot[1549]: time="2026-04-10T19:36:10+02:00" level=debug msg="fetched chunk 27/28, size: 524288" uri="spotify:track:5lemzoYLaoDdbbEwSZHvHD" Apr 10 19:36:10 volumio go-librespot[1549]: time="2026-04-10T19:36:10+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 10 19:36:10 volumio go-librespot[1549]: time="2026-04-10T19:36:10+02:00" level=trace msg="emitting websocket event: metadata" Apr 10 19:36:11 volumio go-librespot[1549]: time="2026-04-10T19:36:10+02:00" level=trace msg="emitting websocket event: active" Apr 10 19:36:11 volumio go-librespot[1549]: time="2026-04-10T19:36:10+02:00" level=debug msg="sending successful reply for dealer request" Apr 10 19:36:11 volumio go-librespot[1549]: time="2026-04-10T19:36:11+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Apr 10 19:36:11 volumio go-librespot[1549]: time="2026-04-10T19:36:11+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Apr 10 19:36:11 volumio go-librespot[1549]: time="2026-04-10T19:36:11+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Apr 10 19:36:11 volumio go-librespot[1549]: time="2026-04-10T19:36:11+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 10 19:36:11 volumio go-librespot[1549]: time="2026-04-10T19:36:11+02:00" level=trace msg="emitting websocket event: paused" Apr 10 19:36:15 volumio go-librespot[1549]: time="2026-04-10T19:36:15+02:00" level=debug msg="handling play player command from dfb057953b940f8135e810f0d2559f0fb834541a" Apr 10 19:36:15 volumio go-librespot[1549]: time="2026-04-10T19:36:15+02:00" level=debug msg="resolved context of track" uri="spotify:album:1JRHNXI5FJiWVkUqIe2Ref" Apr 10 19:36:15 volumio go-librespot[1549]: time="2026-04-10T19:36:15+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:album:1JRHNXI5FJiWVkUqIe2Ref" Apr 10 19:36:15 volumio go-librespot[1549]: time="2026-04-10T19:36:15+02:00" level=debug msg="loading track (paused: false, position: 1ms)" uri="spotify:track:0KhBTCqbjWRcIOkc5me83L" Apr 10 19:36:15 volumio go-librespot[1549]: time="2026-04-10T19:36:15+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 10 19:36:15 volumio go-librespot[1549]: time="2026-04-10T19:36:15+02:00" level=trace msg="emitting websocket event: will_play" Apr 10 19:36:15 volumio go-librespot[1549]: time="2026-04-10T19:36:15+02:00" level=debug msg="selected format OGG_VORBIS_320 (9447350172c7d993d62f0115bf3664e1b9ee96aa)" uri="spotify:track:0KhBTCqbjWRcIOkc5me83L" Apr 10 19:36:15 volumio go-librespot[1549]: time="2026-04-10T19:36:15+02:00" level=debug msg="requested aes key for file 9447350172c7d993d62f0115bf3664e1b9ee96aa, gid: 0KhBTCqbjWRcIOkc5me83L" Apr 10 19:36:15 volumio go-librespot[1549]: time="2026-04-10T19:36:15+02:00" level=trace msg="found 2 cdn urls" uri="spotify:track:0KhBTCqbjWRcIOkc5me83L" Apr 10 19:36:15 volumio go-librespot[1549]: time="2026-04-10T19:36:15+02:00" level=debug msg="fetched first chunk of 23, total size is 11716059 bytes" uri="spotify:track:0KhBTCqbjWRcIOkc5me83L" Apr 10 19:36:15 volumio go-librespot[1549]: time="2026-04-10T19:36:15+02:00" level=trace msg="seek to 1ms (diff: 1ms, samples: 44, bytes: 0)" uri="spotify:track:0KhBTCqbjWRcIOkc5me83L" Apr 10 19:36:15 volumio go-librespot[1549]: time="2026-04-10T19:36:15+02:00" level=warning msg="failed handling dealer request" error="failed loading current track (load context): failed setting stream for spotify:track:0KhBTCqbjWRcIOkc5me83L: ALSA error at snd_pcm_open: Device or resource busy" Apr 10 19:36:16 volumio go-librespot[1549]: time="2026-04-10T19:36:16+02:00" level=debug msg="fetched chunk 2/22, size: 524288" uri="spotify:track:0KhBTCqbjWRcIOkc5me83L" Apr 10 19:36:16 volumio go-librespot[1549]: time="2026-04-10T19:36:16+02:00" level=debug msg="fetched chunk 1/22, size: 524288" uri="spotify:track:0KhBTCqbjWRcIOkc5me83L" Apr 10 19:36:16 volumio go-librespot[1549]: time="2026-04-10T19:36:16+02:00" level=debug msg="fetched chunk 3/22, size: 524288" uri="spotify:track:0KhBTCqbjWRcIOkc5me83L" Apr 10 19:36:16 volumio sudo[1736]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-04-10 19:35' Apr 10 19:36:16 volumio sudo[1736]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) PRETTY_NAME="Raspbian GNU/Linux 12 (bookworm)" NAME="Raspbian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="a78d359cf1dc63ac74e9d151015afd30d31a709a" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="c1ffe93b2136013fc1b5903a4ed7e3f34e0a7bec" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Thu Feb 5 14:07:07 UTC 2026" VOLUMIO_VERSION="4.096" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="5e37060f9823263a753eb5e84030104f"