Aug 27 19:24:03 volumio systemd[1]: setdatetime-helper.service: Deactivated successfully. Aug 27 19:24:03 volumio systemd[1]: Finished setdatetime-helper.service - Time Synchronization Helper Service. Aug 27 19:24:03 volumio systemd[1]: setdatetime-helper.service: Consumed 1.516s CPU time. Aug 27 19:24:03 volumio ifplugd(eth0)[986]: Program executed successfully. Aug 27 19:24:03 volumio ifplugd[932]: Network Interface Plugging Daemon...start eth0...done. Aug 27 19:24:03 volumio systemd[1]: Starting dpkg-db-backup.service - Daily dpkg database backup service... Aug 27 19:24:03 volumio systemd[1]: Started ntpsec-rotate-stats.service - Rotate ntpd stats. Aug 27 19:24:03 volumio welcome[1099]: Resolved ip:[1] 192.168.2.101 Aug 27 19:24:03 volumio sudo[1083]: pam_unix(sudo:session): session closed for user root Aug 27 19:24:03 volumio winbindd[1073]: [2026/08/27 19:24:03.211436, 0] ../../source3/winbindd/winbindd.c:1440(main) Aug 27 19:24:03 volumio winbindd[1073]: winbindd version 4.17.8-Raspbian started. Aug 27 19:24:03 volumio winbindd[1073]: Copyright Andrew Tridgell and the Samba Team 1992-2022 Aug 27 19:24:03 volumio wireless.js[704]: WIRELESS.JS - INFO: Cleaning previous... Aug 27 19:24:03 volumio systemd[1]: Started ifplugd.service - LSB: Brings up/down network automatically. Aug 27 19:24:03 volumio systemd[1]: ntpsec-rotate-stats.service: Deactivated successfully. Aug 27 19:24:03 volumio systemd[1]: Finished welcome.service - Show a welcome message on console. Aug 27 19:24:03 volumio wireless.js[704]: WIRELESS.JS - INFO: Wireless Networking DISABLED, not starting wireless flow Aug 27 19:24:03 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Aug 27 19:24:03 volumio winbindd[1073]: [2026/08/27 19:24:03.256915, 0] ../../source3/winbindd/winbindd_cache.c:3116(initialize_winbindd_cache) Aug 27 19:24:03 volumio winbindd[1073]: initialize_winbindd_cache: clearing cache and re-creating with version number 2 Aug 27 19:24:03 volumio ntpd[984]: DNS: dns_probe: 3.debian.pool.ntp.org, cast_flags:8, flags:101 Aug 27 19:24:03 volumio ntpd[984]: DNS: dns_check: processing 3.debian.pool.ntp.org, 8, 101 Aug 27 19:24:03 volumio ntpd[984]: DNS: Pool taking: 178.215.228.24 Aug 27 19:24:03 volumio ntpd[984]: DNS: Pool taking: 91.212.242.21 Aug 27 19:24:03 volumio ntpd[984]: DNS: Pool taking: 156.17.245.123 Aug 27 19:24:03 volumio ntpd[984]: DNS: Pool skipping: 162.159.200.1 Aug 27 19:24:03 volumio ntpd[984]: DNS: dns_take_status: 3.debian.pool.ntp.org=>good, 8 Aug 27 19:24:03 volumio systemd[1]: Started winbind.service - Samba Winbind Daemon. Aug 27 19:24:03 volumio systemd[1]: Starting smbd.service - Samba SMB Daemon... Aug 27 19:24:03 volumio wireless.js[704]: WIRELESS.JS - INFO: Notified systemd about wireless ready Aug 27 19:24:03 volumio systemd[1]: dpkg-db-backup.service: Deactivated successfully. Aug 27 19:24:03 volumio systemd[1]: Finished dpkg-db-backup.service - Daily dpkg database backup service. Aug 27 19:24:03 volumio systemd[1]: Started wireless.service - Wireless Services. Aug 27 19:24:03 volumio systemd[1]: Started volumio.service - Volumio Backend Module. Aug 27 19:24:03 volumio systemd[1]: Starting plymouth-quit.service - Terminate Plymouth Boot Screen... Aug 27 19:24:03 volumio systemd[1]: Started volumio_cpu_tweak.service - Volumio Cpu Tweaker. Aug 27 19:24:03 volumio systemd[1]: Finished plymouth-quit-wait.service - Hold until boot process finishes up. Aug 27 19:24:03 volumio systemd[1]: Finished plymouth-quit.service - Terminate Plymouth Boot Screen. Aug 27 19:24:03 volumio systemd[1]: Received SIGRTMIN+21 from PID 304 (n/a). Aug 27 19:24:03 volumio systemd[1]: Received SIGRTMIN+21 from PID 304 (n/a). Aug 27 19:24:03 volumio systemd[1]: Started getty@tty1.service - Getty on tty1. Aug 27 19:24:03 volumio systemd[1]: Reached target getty.target - Login Prompts. Aug 27 19:24:03 volumio volumio-cpu-tweak[1162]: Setting RT Priority for mpd Aug 27 19:24:03 volumio volumio-cpu-tweak[1177]: pid 35's current scheduling policy: SCHED_OTHER Aug 27 19:24:03 volumio volumio-cpu-tweak[1177]: pid 35's current scheduling priority: 0 Aug 27 19:24:03 volumio volumio-cpu-tweak[1162]: Setting MPD Affinity Aug 27 19:24:03 volumio volumio-cpu-tweak[1179]: pid 3's current affinity mask: f Aug 27 19:24:03 volumio volumio-cpu-tweak[1162]: /bin/volumio_cpu_tweak: line 27: warning: command substitution: ignored null byte in input Aug 27 19:24:03 volumio volumio-cpu-tweak[1162]: VOLUMIO CPU TWEAK: Setting CPU Governor: performance Aug 27 19:24:03 volumio systemd[1]: volumio_cpu_tweak.service: Deactivated successfully. Aug 27 19:24:04 volumio smbd[1193]: [2026/08/27 19:24:04.187537, 0] ../../source3/smbd/server.c:1741(main) Aug 27 19:24:04 volumio smbd[1193]: smbd version 4.17.8-Raspbian started. Aug 27 19:24:04 volumio smbd[1193]: Copyright Andrew Tridgell and the Samba Team 1992-2022 Aug 27 19:24:04 volumio ntpd[984]: IO: Listen normally on 3 eth0 192.168.2.101:123 Aug 27 19:24:04 volumio ntpd[984]: IO: new interface(s) found: waking up resolver Aug 27 19:24:04 volumio ntpd[984]: DNS: dns_probe: 3.debian.pool.ntp.org, cast_flags:8, flags:101 Aug 27 19:24:04 volumio ntpd[984]: DNS: dns_check: processing 3.debian.pool.ntp.org, 8, 101 Aug 27 19:24:04 volumio ntpd[984]: DNS: Pool skipping: 178.215.228.24 Aug 27 19:24:04 volumio ntpd[984]: DNS: Pool skipping: 91.212.242.21 Aug 27 19:24:04 volumio ntpd[984]: DNS: Pool skipping: 156.17.245.123 Aug 27 19:24:04 volumio ntpd[984]: DNS: Pool skipping: 162.159.200.1 Aug 27 19:24:04 volumio ntpd[984]: DNS: dns_take_status: 3.debian.pool.ntp.org=>good, 8 Aug 27 19:24:05 volumio ntpd[984]: DNS: dns_probe: 2.debian.pool.ntp.org, cast_flags:8, flags:101 Aug 27 19:24:05 volumio ntpd[984]: DNS: dns_check: processing 2.debian.pool.ntp.org, 8, 101 Aug 27 19:24:05 volumio ntpd[984]: DNS: Pool skipping: 193.70.94.182 Aug 27 19:24:05 volumio ntpd[984]: DNS: Pool skipping: 213.222.217.11 Aug 27 19:24:05 volumio ntpd[984]: DNS: Pool skipping: 162.159.200.1 Aug 27 19:24:05 volumio ntpd[984]: DNS: Pool skipping: 51.38.131.245 Aug 27 19:24:05 volumio ntpd[984]: DNS: Pool skipping: 2a12:bec4:1da0:3e::123 Aug 27 19:24:05 volumio ntpd[984]: DNS: Pool skipping: 2a05:9404::15e Aug 27 19:24:05 volumio ntpd[984]: DNS: Pool skipping: 2a05:5502:12:11::123 Aug 27 19:24:05 volumio ntpd[984]: DNS: Pool skipping: 2a03:7580:1:217::11 Aug 27 19:24:05 volumio ntpd[984]: DNS: dns_take_status: 2.debian.pool.ntp.org=>good, 8 Aug 27 19:24:05 volumio systemd[1]: Started smbd.service - Samba SMB Daemon. Aug 27 19:24:05 volumio systemd[1]: Reached target multi-user.target - Multi-User System. Aug 27 19:24:05 volumio systemd[1]: Reached target graphical.target - Graphical Interface. Aug 27 19:24:05 volumio systemd[1]: Starting systemd-update-utmp-runlevel.service - Record Runlevel Change in UTMP... Aug 27 19:24:05 volumio systemd[1]: systemd-update-utmp-runlevel.service: Deactivated successfully. Aug 27 19:24:05 volumio systemd[1]: Finished systemd-update-utmp-runlevel.service - Record Runlevel Change in UTMP. Aug 27 19:24:05 volumio systemd[1]: Startup finished in 15.735s (kernel) + 15.266s (userspace) = 31.001s. Aug 27 19:24:06 volumio ntpd[984]: DNS: dns_probe: 1.debian.pool.ntp.org, cast_flags:8, flags:101 Aug 27 19:24:06 volumio ntpd[984]: DNS: dns_check: processing 1.debian.pool.ntp.org, 8, 101 Aug 27 19:24:06 volumio ntpd[984]: DNS: Pool skipping: 193.70.94.182 Aug 27 19:24:06 volumio ntpd[984]: DNS: Pool taking: 91.222.192.254 Aug 27 19:24:06 volumio ntpd[984]: DNS: Pool taking: 94.154.96.7 Aug 27 19:24:06 volumio ntpd[984]: DNS: Pool taking: 213.222.217.10 Aug 27 19:24:06 volumio ntpd[984]: DNS: dns_take_status: 1.debian.pool.ntp.org=>good, 8 Aug 27 19:24:07 volumio ntpd[984]: DNS: dns_probe: 0.debian.pool.ntp.org, cast_flags:8, flags:101 Aug 27 19:24:07 volumio ntpd[984]: DNS: dns_check: processing 0.debian.pool.ntp.org, 8, 101 Aug 27 19:24:07 volumio ntpd[984]: DNS: Pool taking: 91.212.242.20 Aug 27 19:24:07 volumio ntpd[984]: DNS: Pool skipping: 156.17.245.123 Aug 27 19:24:07 volumio ntpd[984]: DNS: Pool taking: 89.174.70.2 Aug 27 19:24:07 volumio ntpd[984]: DNS: Pool taking: 89.250.197.242 Aug 27 19:24:07 volumio ntpd[984]: DNS: dns_take_status: 0.debian.pool.ntp.org=>good, 8 Aug 27 19:24:09 volumio volumio[1160]: info: ------------------------------------------- Aug 27 19:24:09 volumio volumio[1160]: info: ----- Volumio3 ---- Aug 27 19:24:09 volumio volumio[1160]: info: ------------------------------------------- Aug 27 19:24:09 volumio volumio[1160]: info: ----- System startup ---- Aug 27 19:24:09 volumio volumio[1160]: info: ------------------------------------------- Aug 27 19:24:09 volumio volumio-remote-updater[702]: [2026-08-27 19:24:09] [connect] Successful connection Aug 27 19:24:11 volumio volumio[1160]: info: MYVOLUMIO Environment detected Aug 27 19:24:11 volumio volumio[1160]: info: Plugin folders cleanup Aug 27 19:24:11 volumio volumio[1160]: info: Scanning into folder /volumio/app/plugins/ Aug 27 19:24:11 volumio volumio[1160]: info: Scanning category audio_interface Aug 27 19:24:11 volumio volumio[1160]: info: Scanning category miscellanea Aug 27 19:24:11 volumio volumio[1160]: info: Scanning category music_service Aug 27 19:24:11 volumio volumio[1160]: info: Scanning category plugins.json Aug 27 19:24:11 volumio volumio[1160]: info: Scanning category system_controller Aug 27 19:24:11 volumio volumio[1160]: info: Scanning category user_interface Aug 27 19:24:11 volumio volumio[1160]: info: Scanning into folder /data/plugins/ Aug 27 19:24:11 volumio volumio[1160]: info: Scanning category audio_interface Aug 27 19:24:11 volumio volumio[1160]: info: Scanning category music_service Aug 27 19:24:11 volumio volumio[1160]: info: Plugin folders cleanup completed Aug 27 19:24:11 volumio volumio[1160]: info: ------------------------------------------- Aug 27 19:24:11 volumio volumio[1160]: info: ----- Core plugins startup ---- Aug 27 19:24:11 volumio volumio[1160]: info: ------------------------------------------- Aug 27 19:24:11 volumio volumio[1160]: info: Loading plugins from folder /volumio/app/plugins/ Aug 27 19:24:11 volumio volumio[1160]: info: Adding plugin upnp to MyMusic Plugins Aug 27 19:24:11 volumio volumio[1160]: info: Adding plugin airplay_emulation to MyMusic Plugins Aug 27 19:24:11 volumio volumio[1160]: info: Adding plugin upnp_browser to MyMusic Plugins Aug 27 19:24:11 volumio volumio[1160]: info: Loading plugins from folder /data/plugins/ Aug 27 19:24:11 volumio volumio[1160]: info: Loading plugin "system"... Aug 27 19:24:11 volumio volumio[1160]: info: Loading plugin "appearance"... Aug 27 19:24:12 volumio ntpd[984]: CLOCK: time stepped by 0.483719 Aug 27 19:24:12 volumio ntpd[984]: INIT: MRU 13107 entries, 13 hash bits, 32768 bytes Aug 27 19:24:12 volumio systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 1. Aug 27 19:24:12 volumio systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Aug 27 19:24:13 volumio systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Aug 27 19:24:13 volumio upmpdcli[1220]: Could not open config: /tmp/upmpdcli.conf Aug 27 19:24:13 volumio systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Aug 27 19:24:13 volumio systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Aug 27 19:24:13 volumio volumio[1160]: info: Loading plugin "network"... Aug 27 19:24:13 volumio volumio[1160]: info: Refreshing Cached IP Addresses Aug 27 19:24:13 volumio volumio[1160]: info: Loading plugin "services"... Aug 27 19:24:13 volumio sudo[1224]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Aug 27 19:24:13 volumio sudo[1224]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 27 19:24:13 volumio volumio[1160]: info: Loading plugin "volumio5onboarding"... Aug 27 19:24:13 volumio sudo[1224]: pam_unix(sudo:session): session closed for user root Aug 27 19:24:13 volumio volumio[1160]: info: Loading plugin "alsa_controller"... Aug 27 19:24:13 volumio sudo[1222]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Aug 27 19:24:13 volumio sudo[1222]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 27 19:24:14 volumio sudo[1222]: pam_unix(sudo:session): session closed for user root Aug 27 19:24:14 volumio volumio[1160]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 27 19:24:14 volumio volumio[1160]: info: Loading plugin "wizard"... Aug 27 19:24:14 volumio volumio[1160]: info: Loading plugin "networkfs"... Aug 27 19:24:14 volumio volumio[1160]: info: Starting Udev Watcher for removable devices Aug 27 19:24:14 volumio sudo[1253]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=Volumio,password=VolPass123$,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //192.168.2.100/Dysk/Pobrane/Muzyka/muzyka /mnt/NAS/Muzyka Aug 27 19:24:14 volumio sudo[1253]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 27 19:24:14 volumio volumio[1160]: info: Ignoring mount for partition: boot Aug 27 19:24:14 volumio volumio[1160]: info: Ignoring mount for partition: volumio Aug 27 19:24:14 volumio volumio[1160]: info: Ignoring mount for partition: volumio_data Aug 27 19:24:14 volumio volumio[1160]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Aug 27 19:24:14 volumio volumio[1160]: info: Loading plugin "volumio_command_line_client"... Aug 27 19:24:14 volumio sudo[1255]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=Volumio,password=VolPass123$,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft '//192.168.2.100/Dysk/Pobrane/Muzyka/muzyka jazz' /mnt/NAS/Muzyka_Jazz Aug 27 19:24:14 volumio sudo[1255]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 27 19:24:14 volumio volumio[1160]: info: Loading plugin "upnp"... Aug 27 19:24:14 volumio volumio[1160]: info: [1787851454552] Starting Upmpd Daemon Aug 27 19:24:14 volumio volumio[1160]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Aug 27 19:24:14 volumio volumio[1160]: info: Loading plugin "my_music"... Aug 27 19:24:14 volumio volumio[1160]: info: Loading plugin "mpd"... Aug 27 19:24:14 volumio kernel: netfs: FS-Cache loaded Aug 27 19:24:14 volumio kernel: Key type cifs.spnego registered Aug 27 19:24:14 volumio kernel: Key type cifs.idmap registered Aug 27 19:24:14 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. Aug 27 19:24:14 volumio kernel: CIFS: Attempting to mount //192.168.2.100/Dysk/Pobrane/Muzyka/muzyka jazz Aug 27 19:24:15 volumio volumio[1160]: info: Loading plugin "upnp_browser"... Aug 27 19:24:16 volumio kernel: CIFS: VFS: Autodisabling the use of server inode numbers on new server Aug 27 19:24:16 volumio kernel: CIFS: VFS: The server doesn't seem to support them properly or the files might be on different servers (DFS) Aug 27 19:24:16 volumio kernel: CIFS: VFS: Hardlinks will not be recognized on this mount. Consider mounting with the "noserverino" option to silence this message. Aug 27 19:24:16 volumio kernel: CIFS: Attempting to mount //192.168.2.100/Dysk/Pobrane/Muzyka/muzyka Aug 27 19:24:16 volumio sudo[1255]: pam_unix(sudo:session): session closed for user root Aug 27 19:24:17 volumio kernel: CIFS: VFS: Autodisabling the use of server inode numbers on new server Aug 27 19:24:17 volumio kernel: CIFS: VFS: The server doesn't seem to support them properly or the files might be on different servers (DFS) Aug 27 19:24:17 volumio kernel: CIFS: VFS: Hardlinks will not be recognized on this mount. Consider mounting with the "noserverino" option to silence this message. Aug 27 19:24:17 volumio sudo[1253]: pam_unix(sudo:session): session closed for user root Aug 27 19:24:18 volumio volumio[1160]: info: Starting UPNP Browser Aug 27 19:24:18 volumio volumio[1160]: info: Loading plugin "alarm-clock"... Aug 27 19:24:18 volumio volumio[1160]: info: Loading plugin "airplay_emulation"... Aug 27 19:24:18 volumio volumio[1160]: info: Starting Shairport Sync Aug 27 19:24:18 volumio volumio[1160]: info: Loading plugin "last_100"... Aug 27 19:24:18 volumio volumio[1160]: info: Loading plugin "webradio"... Aug 27 19:24:18 volumio volumio[1160]: info: Loading plugin "i2s_dacs"... Aug 27 19:24:18 volumio volumio[1160]: info: I2S DAC not set, start Auto-detection Aug 27 19:24:18 volumio volumio[1160]: info: Loading plugin "volumiodiscovery"... Aug 27 19:24:19 volumio volumio[1160]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Aug 27 19:24:19 volumio volumio[1160]: *** WARNING *** Please fix your application to use the native API of Avahi! Aug 27 19:24:19 volumio volumio[1160]: *** WARNING *** For more information see Aug 27 19:24:19 volumio volumio[1160]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Aug 27 19:24:19 volumio volumio[1160]: *** WARNING *** Please fix your application to use the native API of Avahi! Aug 27 19:24:19 volumio volumio[1160]: *** WARNING *** For more information see Aug 27 19:24:19 volumio node[1160]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Aug 27 19:24:19 volumio node[1160]: *** WARNING *** Please fix your application to use the native API of Avahi! Aug 27 19:24:19 volumio node[1160]: *** WARNING *** For more information see Aug 27 19:24:19 volumio node[1160]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Aug 27 19:24:19 volumio node[1160]: *** WARNING *** Please fix your application to use the native API of Avahi! Aug 27 19:24:19 volumio node[1160]: *** WARNING *** For more information see Aug 27 19:24:19 volumio volumio[1160]: info: Applying required configuration parameters for plugin volumiodiscovery Aug 27 19:24:19 volumio volumio[1160]: info: Discovery: Started advertising with name: Volumio Aug 27 19:24:19 volumio volumio[1160]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Aug 27 19:24:19 volumio volumio[1160]: info: Loading plugin "spop"... Aug 27 19:24:21 volumio volumio[1160]: info: Loading plugin "outputs"... Aug 27 19:24:21 volumio volumio[1160]: info: Loading plugin "albumart"... Aug 27 19:24:21 volumio volumio[1160]: info: Plugin example_plugin is not enabled Aug 27 19:24:21 volumio volumio[1160]: info: Loading plugin "inputs"... Aug 27 19:24:21 volumio volumio[1160]: info: Loading plugin "updater_comm"... Aug 27 19:24:22 volumio volumio[1160]: info: Plugin mpdemulation is not enabled Aug 27 19:24:22 volumio volumio[1160]: info: Loading plugin "rest_api"... Aug 27 19:24:22 volumio volumio[1160]: info: Loading plugin "websocket"... Aug 27 19:24:22 volumio volumio[1160]: info: Starting Socket.io Server version 1.7.4 Aug 27 19:24:22 volumio volumio[1160]: info: Loading plugin "fusiondsp"... Aug 27 19:24:23 volumio volumio[1306]: Forking 3 albumart workers Aug 27 19:24:24 volumio volumio[1160]: info: Applying required configuration parameters for plugin fusiondsp Aug 27 19:24:24 volumio systemd[1]: systemd-fsckd.service: Deactivated successfully. Aug 27 19:24:25 volumio volumio-remote-updater[702]: [2026-08-27 19:24:25] [connect] Successful connection Aug 27 19:24:26 volumio volumio[1160]: info: Loading i18n strings for locale pl Aug 27 19:24:26 volumio volumio[1160]: Updating browse sources language Aug 27 19:24:26 volumio volumio[1160]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 27 19:24:27 volumio volumio[1160]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 27 19:24:27 volumio volumio[1160]: info: CoreCommandRouter::initPlayerControls Aug 27 19:24:27 volumio volumio[1160]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 19:24:27 volumio volumio[1160]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 19:24:27 volumio volumio[1160]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 19:24:27 volumio volumio[1160]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 19:24:27 volumio volumio[1160]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 19:24:27 volumio volumio[1160]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 19:24:27 volumio volumio[1160]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 19:24:27 volumio volumio[1160]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 19:24:27 volumio volumio[1160]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 27 19:24:28 volumio volumio[1160]: Express server listening on port 3000 Aug 27 19:24:28 volumio volumio[1160]: [Metrics] WebUI: 19s 281.61ms Aug 27 19:24:28 volumio volumio[1160]: info: CoreStateMachine::resetVolumioState Aug 27 19:24:28 volumio volumio[1160]: info: CoreStateMachine::getcurrentVolume Aug 27 19:24:28 volumio volumio[1160]: info: CoreCommandRouter::volumioRetrievevolume Aug 27 19:24:28 volumio systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 2. Aug 27 19:24:28 volumio systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Aug 27 19:24:28 volumio volumio[1160]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 27 19:24:28 volumio systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Aug 27 19:24:28 volumio upmpdcli[1363]: Could not open config: /tmp/upmpdcli.conf Aug 27 19:24:28 volumio systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Aug 27 19:24:28 volumio systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Aug 27 19:24:28 volumio systemd[1]: systemd-hostnamed.service: Deactivated successfully. Aug 27 19:24:28 volumio sudo[1369]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Aug 27 19:24:28 volumio sudo[1369]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 27 19:24:28 volumio sudo[1369]: pam_unix(sudo:session): session closed for user root Aug 27 19:24:28 volumio sudo[1371]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Aug 27 19:24:28 volumio sudo[1371]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 27 19:24:28 volumio sudo[1371]: pam_unix(sudo:session): session closed for user root Aug 27 19:24:29 volumio volumio[1160]: info: Volumio Network Manager: Network status updated: 1 Aug 27 19:24:29 volumio volumio-remote-updater[702]: [2026-08-27 19:24:29] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1787851465 101 Aug 27 19:24:30 volumio volumio[1160]: 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 27 19:24:30 volumio volumio[1160]: info: VolumeController:: Volume=8 Mute =false Aug 27 19:24:30 volumio volumio[1160]: info: CoreStateMachine::pushState Aug 27 19:24:30 volumio volumio[1160]: info: CorePlayQueue::getTrack 0 Aug 27 19:24:30 volumio volumio[1160]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 27 19:24:30 volumio volumio[1160]: info: CoreCommandRouter::volumioPushState Aug 27 19:24:30 volumio volumio[1160]: info: CoreStateMachine::updateTrackBlock Aug 27 19:24:30 volumio volumio[1160]: info: CorePlayQueue::getTrackBlock Aug 27 19:24:30 volumio volumio[1160]: info: CoreCommandRouter::volumioRetrievevolume Aug 27 19:24:30 volumio volumio[1160]: info: Reloading queue from file Aug 27 19:24:30 volumio volumio[1160]: info: Setting Device type: Raspberry PI Aug 27 19:24:30 volumio volumio[1160]: info: CoreStateMachine::setRepeat null single undefined Aug 27 19:24:30 volumio volumio[1160]: info: CoreStateMachine::pushState Aug 27 19:24:30 volumio volumio[1160]: info: CorePlayQueue::getTrack 0 Aug 27 19:24:30 volumio volumio[1160]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 27 19:24:30 volumio volumio[1160]: info: CoreCommandRouter::volumioPushState Aug 27 19:24:30 volumio volumio[1160]: info: CoreStateMachine::setRandom null Aug 27 19:24:30 volumio volumio[1160]: info: CoreStateMachine::pushState Aug 27 19:24:30 volumio volumio[1160]: info: CorePlayQueue::getTrack 0 Aug 27 19:24:30 volumio volumio[1160]: info: CoreCommandRouter::volumioPushState Aug 27 19:24:31 volumio volumio[1160]: info: Discovery: adding bfa3d19f-3b65-4b6b-9c76-4d08f58ab72b Aug 27 19:24:31 volumio volumio[1160]: info: Discovery: Found device Volumio Aug 27 19:24:31 volumio volumio[1160]: info: CoreCommandRouter::volumioGetState Aug 27 19:24:31 volumio volumio[1160]: info: CorePlayQueue::getTrack 0 Aug 27 19:24:31 volumio volumio[1160]: info: Discovery: this is already registered, bfa3d19f-3b65-4b6b-9c76-4d08f58ab72b Aug 27 19:24:31 volumio volumio[1160]: info: Discovery: Found device Volumio Aug 27 19:24:31 volumio volumio[1160]: info: CoreCommandRouter::volumioGetState Aug 27 19:24:31 volumio volumio[1160]: info: CorePlayQueue::getTrack 0 Aug 27 19:24:31 volumio sudo[1387]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Aug 27 19:24:31 volumio sudo[1387]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 27 19:24:31 volumio volumio[1160]: info: VolumeController:: Volume=8 Mute =false Aug 27 19:24:31 volumio volumio[1160]: info: CoreStateMachine::pushState Aug 27 19:24:31 volumio volumio[1160]: info: CorePlayQueue::getTrack 0 Aug 27 19:24:31 volumio volumio[1160]: info: CoreCommandRouter::volumioPushState Aug 27 19:24:31 volumio volumio[1160]: info: Completed loading Core Plugins Aug 27 19:24:31 volumio volumio[1160]: info: Preparing to generate the ALSA configuration file Aug 27 19:24:31 volumio volumio[1317]: Starting albumart workers Aug 27 19:24:31 volumio volumio[1160]: info: The plugin fusiondsp has an ALSA contribution file volumioDsp.postDsp.10.conf Aug 27 19:24:31 volumio volumio[1160]: info: Reading ALSA contributions from plugins. Aug 27 19:24:31 volumio volumio[1160]: info: Asound.conf file unchanged, so no further update is needed Aug 27 19:24:31 volumio volumio[1160]: info: Output device has changed, restarting MPD Aug 27 19:24:32 volumio volumio[1160]: info: Output device has changed, restarting Shairport Sync Aug 27 19:24:32 volumio volumio[1160]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 19:24:32 volumio volumio[1160]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 27 19:24:32 volumio sudo[1390]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Aug 27 19:24:32 volumio sudo[1390]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 27 19:24:32 volumio sudo[1390]: pam_unix(sudo:session): session closed for user root Aug 27 19:24:32 volumio sudo[1392]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Aug 27 19:24:32 volumio sudo[1392]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 27 19:24:32 volumio volumio[1160]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Aug 27 19:24:32 volumio volumio[1160]: info: ___________ START PLUGINS ___________ Aug 27 19:24:32 volumio volumio[1160]: info: ControllerMpd::onStart: Initializing MPD Aug 27 19:24:32 volumio volumio[1160]: info: Creating MPD Configuration file Aug 27 19:24:32 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Aug 27 19:24:32 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Aug 27 19:24:32 volumio volumio[1160]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 27 19:24:32 volumio volumio[1160]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 27 19:24:32 volumio volumio[1160]: info: [1787851472743] CoreMusicLibrary::Adding element Serwery Mediów Aug 27 19:24:32 volumio volumio[1160]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 27 19:24:32 volumio sudo[1401]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumio5-onboarding.service Aug 27 19:24:32 volumio sudo[1401]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 27 19:24:32 volumio sudo[1402]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Aug 27 19:24:32 volumio sudo[1402]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Aug 27 19:24:32 volumio sudo[1408]: /bin/chown: cannot access '/var/log/mpd.log': No such file or directory Aug 27 19:24:32 volumio sudo[1402]: pam_unix(sudo:session): session closed for user root Aug 27 19:24:32 volumio sudo[1404]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Aug 27 19:24:32 volumio sudo[1404]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 27 19:24:32 volumio volumio[1160]: info: UPNP Browser: Client initialized successfully Aug 27 19:24:33 volumio sudo[1404]: pam_unix(sudo:session): session closed for user root Aug 27 19:24:33 volumio systemd[1]: Started volumio5-onboarding.service - Volumio5 Onboarding Server. Aug 27 19:24:33 volumio sudo[1401]: pam_unix(sudo:session): session closed for user root Aug 27 19:24:33 volumio sudo[1407]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Aug 27 19:24:33 volumio sudo[1407]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 27 19:24:33 volumio volumio[1160]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 19:24:33 volumio volumio[1160]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 27 19:24:33 volumio systemd[1]: mpd.service: Deactivated successfully. Aug 27 19:24:33 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Aug 27 19:24:33 volumio systemd[1]: mpd.socket: Deactivated successfully. Aug 27 19:24:33 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Aug 27 19:24:33 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Aug 27 19:24:33 volumio volumio[1160]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Aug 27 19:24:33 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Aug 27 19:24:33 volumio volumio[1160]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 19:24:33 volumio volumio[1160]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 27 19:24:33 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Aug 27 19:24:33 volumio volumio[1160]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Aug 27 19:24:33 volumio volumio[1160]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 27 19:24:33 volumio volumio[1160]: info: [1787851473683] CoreMusicLibrary::Adding element Last_100 Aug 27 19:24:33 volumio volumio[1160]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 27 19:24:33 volumio volumio[1160]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 27 19:24:33 volumio volumio[1160]: info: [1787851473733] CoreMusicLibrary::Adding element Webradio Aug 27 19:24:33 volumio volumio[1160]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 27 19:24:33 volumio volumio[1318]: Starting albumart workers Aug 27 19:24:33 volumio volumio[1160]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 27 19:24:33 volumio sudo[1424]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Aug 27 19:24:33 volumio sudo[1424]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Aug 27 19:24:33 volumio sudo[1429]: /bin/chown: cannot access '/var/log/mpd.log': No such file or directory Aug 27 19:24:33 volumio sudo[1424]: pam_unix(sudo:session): session closed for user root Aug 27 19:24:33 volumio volumio5-onboarding[1411]: time=2026-08-27T19:24:33.900+02:00 level=INFO msg="running volumio5-device-gateway" version=10ca7e93+CHANGES buildDate=2026-03-06T14:30:20Z Aug 27 19:24:33 volumio volumio[1160]: info: Initializing BBC Radios Aug 27 19:24:34 volumio volumio[1160]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 27 19:24:34 volumio volumio[1160]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 27 19:24:34 volumio volumio[1160]: info: Creating Spotify config file Aug 27 19:24:34 volumio volumio[1160]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 19:24:35 volumio volumio[1316]: Starting albumart workers Aug 27 19:24:38 volumio volumio[1160]: info: FusionDsp - CamillaDSP binary found. Aug 27 19:24:38 volumio volumio[1160]: info: Loading i18n strings for locale pl Aug 27 19:24:38 volumio volumio[1160]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , updateALSAConfigFile Aug 27 19:24:38 volumio volumio[1160]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 19:24:38 volumio volumio[1160]: info: FusionDsp - mixtype--------------------- Hardware Aug 27 19:24:38 volumio volumio[1160]: info: Volumio Calling Home Aug 27 19:24:39 volumio volumio[1160]: info: Preparing to generate the ALSA configuration file Aug 27 19:24:39 volumio systemd[1]: Starting setdatetime-helper.service - Time Synchronization Helper Service... Aug 27 19:24:41 volumio volumio[1160]: info: The plugin fusiondsp has an ALSA contribution file volumioDsp.postDsp.10.conf Aug 27 19:24:41 volumio volumio[1160]: info: Reading ALSA contributions from plugins. Aug 27 19:24:41 volumio mpd[1430]: 2026-08-27T19:24:41 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Aug 27 19:24:42 volumio volumio[1160]: info: MPD Permissions set Aug 27 19:24:42 volumio volumio[1160]: info: MPD Permissions set Aug 27 19:24:42 volumio volumio[1160]: 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 27 19:24:42 volumio volumio[1160]: info: Volumio called home Aug 27 19:24:42 volumio volumio[1160]: info: Spotify config file written Aug 27 19:24:42 volumio systemd[1]: setdatetime-helper.service: Deactivated successfully. Aug 27 19:24:42 volumio systemd[1]: Finished setdatetime-helper.service - Time Synchronization Helper Service. Aug 27 19:24:42 volumio systemd[1]: setdatetime-helper.service: Consumed 1.071s CPU time. Aug 27 19:24:42 volumio sudo[1511]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Aug 27 19:24:42 volumio sudo[1511]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 27 19:24:42 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. Aug 27 19:24:42 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. Aug 27 19:24:42 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 27 19:24:42 volumio go-librespot[1513]: go-librespot daemon starting... Aug 27 19:24:42 volumio systemd[1]: Started mpd.service - Music Player Daemon. Aug 27 19:24:42 volumio sudo[1407]: pam_unix(sudo:session): session closed for user root Aug 27 19:24:42 volumio sudo[1392]: pam_unix(sudo:session): session closed for user root Aug 27 19:24:42 volumio sudo[1511]: pam_unix(sudo:session): session closed for user root Aug 27 19:24:43 volumio systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 3. Aug 27 19:24:43 volumio systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Aug 27 19:24:43 volumio systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Aug 27 19:24:43 volumio sudo[1387]: pam_unix(sudo:session): session closed for user root Aug 27 19:24:43 volumio go-librespot[1516]: time="2026-08-27T19:24:43+02:00" level=info msg="running go-librespot 0.7.1" Aug 27 19:24:43 volumio go-librespot[1516]: time="2026-08-27T19:24:43+02:00" level=debug msg="app state loaded" Aug 27 19:24:43 volumio go-librespot[1516]: time="2026-08-27T19:24:43+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 27 19:24:44 volumio volumio[1160]: 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 27 19:24:44 volumio volumio[1160]: info: Received Get System Info Aug 27 19:24:44 volumio volumio[1160]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 27 19:24:44 volumio volumio[1160]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 27 19:24:44 volumio volumio[1160]: info: Discovery: Getting this device information Aug 27 19:24:44 volumio volumio[1160]: info: CoreCommandRouter::volumioGetState Aug 27 19:24:44 volumio volumio[1160]: info: CorePlayQueue::getTrack 0 Aug 27 19:24:44 volumio volumio[1160]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 27 19:24:44 volumio go-librespot[1516]: time="2026-08-27T19:24:44+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-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Aug 27 19:24:44 volumio go-librespot[1516]: time="2026-08-27T19:24:44+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Aug 27 19:24:44 volumio go-librespot[1516]: time="2026-08-27T19:24:44+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Aug 27 19:24:44 volumio go-librespot[1516]: time="2026-08-27T19:24:44+02:00" level=info msg="zeroconf server listening on port 44009" Aug 27 19:24:44 volumio go-librespot[1516]: time="2026-08-27T19:24:44+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 27 19:24:44 volumio volumio5-onboarding[1411]: time=2026-08-27T19:24:44.315+02:00 level=INFO msg="system info for 5bc45c9736dcfbee457186f989f20019" deviceName=Volumio deviceVariant=volumio deviceModel= softwareVersion=4.103 Aug 27 19:24:44 volumio volumio5-onboarding[1411]: time=2026-08-27T19:24:44.345+02:00 level=INFO msg="bootstrapping state" hasInternet=true Aug 27 19:24:44 volumio volumio[1160]: 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 27 19:24:44 volumio volumio[1160]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 19:24:44 volumio volumio[1160]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 19:24:44 volumio volumio[1160]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 19:24:44 volumio volumio[1160]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 19:24:44 volumio volumio[1160]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 19:24:44 volumio volumio[1160]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 19:24:44 volumio volumio[1160]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 19:24:44 volumio volumio[1160]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 19:24:44 volumio volumio[1160]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 27 19:24:44 volumio volumio[1160]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 19:24:44 volumio volumio[1160]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 19:24:44 volumio volumio[1160]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 19:24:44 volumio volumio[1160]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 19:24:44 volumio volumio[1160]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 19:24:44 volumio volumio[1160]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 19:24:44 volumio volumio[1160]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 19:24:44 volumio volumio[1160]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 19:24:44 volumio volumio[1160]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 19:24:44 volumio volumio[1160]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 27 19:24:44 volumio volumio[1160]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 19:24:44 volumio volumio[1160]: info: No need to fix Spotify hosts Aug 27 19:24:45 volumio volumio[1160]: info: Received Get System Info Aug 27 19:24:45 volumio volumio[1160]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 27 19:24:45 volumio volumio[1160]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 27 19:24:45 volumio volumio[1160]: info: Discovery: Getting this device information Aug 27 19:24:45 volumio volumio[1160]: info: CoreCommandRouter::volumioGetState Aug 27 19:24:45 volumio volumio[1160]: info: CorePlayQueue::getTrack 0 Aug 27 19:24:45 volumio volumio[1160]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 27 19:24:45 volumio volumio[1160]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 4 Aug 27 19:24:46 volumio volumio[1160]: info: Upmpdcli Daemon Started Aug 27 19:24:46 volumio volumio[1160]: info: Completed starting Core Plugins Aug 27 19:24:46 volumio volumio[1160]: info: ------------------------------------------- Aug 27 19:24:46 volumio volumio[1160]: info: ----- MyVolumio plugins startup ---- Aug 27 19:24:46 volumio volumio[1160]: info: ------------------------------------------- Aug 27 19:24:46 volumio volumio[1160]: info: [MyVolumio PluginManager] Fetching plans data.... Aug 27 19:24:46 volumio volumio-remote-updater[702]: Test mode disabled Aug 27 19:24:46 volumio volumio-remote-updater[702]: Alpha mode disabled Aug 27 19:24:46 volumio volumio-remote-updater[702]: Alpha legacy test mode disabled Aug 27 19:24:46 volumio volumio[1160]: info: An error occurred while refreshing Spotify Token Error: Bad Request Aug 27 19:24:47 volumio volumio[1160]: error: MPD error: The expression evaluated to a falsy value: Aug 27 19:24:47 volumio volumio[1160]: assert.ok(self.idling) Aug 27 19:24:47 volumio volumio[1160]: error: The expression evaluated to a falsy value: Aug 27 19:24:47 volumio volumio[1160]: assert.ok(self.idling) Aug 27 19:24:47 volumio volumio[1160]: info: MPD running with PID1430 Aug 27 19:24:47 volumio volumio[1160]: ,establishing connection Aug 27 19:24:47 volumio volumio[1160]: info: Starting Shairport Sync Aug 27 19:24:47 volumio volumio[1160]: info: Starting Shairport Sync Aug 27 19:24:47 volumio volumio[1160]: info: Starting Shairport Sync Aug 27 19:24:47 volumio volumio[1160]: error: updateQueue error: null Aug 27 19:24:47 volumio sudo[1570]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Aug 27 19:24:47 volumio sudo[1572]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Aug 27 19:24:47 volumio sudo[1570]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 27 19:24:47 volumio sudo[1572]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 27 19:24:47 volumio sudo[1568]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Aug 27 19:24:47 volumio volumio[1160]: info: Update Ready: {"changeLogLink":"http://volumio.org","description":"

FIXES

  • Fix for missing PWM backlight module
  • Fix for crash loop on Onboarding plugin

NEW ADDITIONS

  • Bump RPi/CM4 kernel to 6.12.74

","title":"Update v4.119","updateavailable":true} Aug 27 19:24:47 volumio sudo[1568]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 27 19:24:47 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Aug 27 19:24:47 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Aug 27 19:24:47 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 27 19:24:47 volumio systemd[1]: shairport-sync.service: Consumed 2.026s CPU time. Aug 27 19:24:47 volumio volumio[1160]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache Aug 27 19:24:47 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 27 19:24:47 volumio sudo[1572]: pam_unix(sudo:session): session closed for user root Aug 27 19:24:47 volumio sudo[1570]: pam_unix(sudo:session): session closed for user root Aug 27 19:24:47 volumio sudo[1568]: pam_unix(sudo:session): session closed for user root Aug 27 19:24:47 volumio volumio[1160]: info: FusionDsp - If filter freq >samplerate/2 then disable it Aug 27 19:24:48 volumio volumio[1160]: info: camilladsp service started and running in background, instance 1 Aug 27 19:24:48 volumio volumio[1160]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 19:24:48 volumio go-librespot[1516]: time="2026-08-27T19:24:48+02:00" level=debug msg="obtained new client token: AAEWPsIqAmrULwPxgqE+VYIxXACxURfSfVBlbH+YgKawu2Qqvtq8SsmzZZnji/0VZa/YoNZPpXMnuOP/amoIuJqUegZ2kpFleackrLV88+zKTp7zNE6jKH56zbppDZakEEEe4ENV/FdJsgNCOXhvk8AUy84eok08g6rnZUYKLNKn6F+OcSU8TWeYK/GAItK91eqoe1V1T0028CG37rKJF4ApJxw8hHU+/d7r0DkjsViVG1AIOpNIVTFD" Aug 27 19:24:48 volumio go-librespot[1516]: time="2026-08-27T19:24:48+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Aug 27 19:24:48 volumio volumio[1160]: info: FusionDsp - AAAAAAAAAAAAAA-> 44100 48000 88200 96000 <-AAAAAAAAAAAAA Aug 27 19:24:48 volumio go-librespot[1516]: time="2026-08-27T19:24:48+02:00" level=debug msg="completed keyexchange" Aug 27 19:24:48 volumio go-librespot[1516]: time="2026-08-27T19:24:48+02:00" level=debug msg="completed challenge" Aug 27 19:24:48 volumio volumio[1160]: info: FusionDsp loaded Aug 27 19:24:48 volumio volumio[1160]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 27 19:24:48 volumio volumio[1160]: info: FusionDsp - --[object Object] Aug 27 19:24:48 volumio volumio[1160]: error: FusionDsp - Socket connection not established Aug 27 19:24:48 volumio volumio[1160]: info: FusionDsp - Reporting Fusion DSP Enabled Aug 27 19:24:48 volumio volumio[1160]: info: Adding Signal Path Element [object Object] Aug 27 19:24:48 volumio volumio[1160]: info: Adding fusiondspeq DSP Signal Path Element Aug 27 19:24:48 volumio volumio[1160]: info: FusionDsp - ---- installed callbackRead (debounced 200ms) Aug 27 19:24:48 volumio volumio[1160]: info: FusionDsp - PEQ graph server listening on port 10015 Aug 27 19:24:48 volumio go-librespot[1516]: time="2026-08-27T19:24:48+02:00" level=info msg="authenticated AP" username="wa*****26" Aug 27 19:24:48 volumio volumio[1160]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 27 19:24:48 volumio sudo[1603]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start fusiondsp.service Aug 27 19:24:48 volumio sudo[1603]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 27 19:24:48 volumio go-librespot[1516]: time="2026-08-27T19:24:48+02:00" level=info msg="authenticated Login5" username="wa*****26" Aug 27 19:24:48 volumio go-librespot[1516]: time="2026-08-27T19:24:48+02:00" level=info msg="accepted zeroconf from Pixel 6a" username="wa*****26" Aug 27 19:24:48 volumio volumio5-onboarding[1411]: time=2026-08-27T19:24:48.739+02:00 level=WARN msg="could not read OAuth data for music provider" component=volumio provider=tidal error="could not open plugin config file for \"tidal\": open /data/configuration/music_service/tidal/config.json: no such file or directory" Aug 27 19:24:48 volumio volumio5-onboarding[1411]: time=2026-08-27T19:24:48.740+02:00 level=WARN msg="could not read OAuth data for music provider" component=volumio provider=qobuz error="could not open plugin config file for \"qobuz\": open /data/configuration/music_service/qobuz/config.json: no such file or directory" Aug 27 19:24:48 volumio volumio5-onboarding[1411]: time=2026-08-27T19:24:48.741+02:00 level=WARN msg="could not read username/password data for music provider" component=volumio provider=hi_res_audio error="could not open plugin config file for \"hi_res_audio\": open /data/configuration/music_service/hi_res_audio/config.json: no such file or directory" Aug 27 19:24:48 volumio go-librespot[1516]: time="2026-08-27T19:24:48+02:00" level=debug msg="dealer connection opened" Aug 27 19:24:48 volumio go-librespot[1516]: time="2026-08-27T19:24:48+02:00" level=trace msg="starting accesspoint recv loop" Aug 27 19:24:48 volumio go-librespot[1516]: time="2026-08-27T19:24:48+02:00" level=trace msg="starting dealer recv loop" Aug 27 19:24:48 volumio go-librespot[1516]: time="2026-08-27T19:24:48+02:00" level=trace msg="received accesspoint ping" Aug 27 19:24:48 volumio go-librespot[1516]: time="2026-08-27T19:24:48+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Aug 27 19:24:48 volumio go-librespot[1516]: time="2026-08-27T19:24:48+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Aug 27 19:24:48 volumio go-librespot[1516]: time="2026-08-27T19:24:48+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Aug 27 19:24:48 volumio go-librespot[1516]: time="2026-08-27T19:24:48+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Aug 27 19:24:48 volumio go-librespot[1516]: time="2026-08-27T19:24:48+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Aug 27 19:24:48 volumio go-librespot[1516]: time="2026-08-27T19:24:48+02:00" level=debug msg="received connection id: YmY2OWMxY2ItYTli...NzBFNDg2QjhBQQ==" Aug 27 19:24:48 volumio go-librespot[1516]: time="2026-08-27T19:24:48+02:00" level=trace msg="received accesspoint pong ack" Aug 27 19:24:48 volumio systemd[1]: Starting fusiondsp.service - FusionDsp Daemon... Aug 27 19:24:48 volumio volumio[1160]: info: Shairport-Sync Started Aug 27 19:24:49 volumio volumio[1160]: Error adding Membership: Error: addMembership EINVAL Aug 27 19:24:49 volumio volumio[1160]: info: Shairport-Sync Started Aug 27 19:24:49 volumio volumio[1160]: info: Shairport-Sync Started Aug 27 19:24:49 volumio go-librespot[1516]: time="2026-08-27T19:24:49+02:00" level=debug msg="put connect state because NEW_DEVICE" Aug 27 19:24:49 volumio volumio[1160]: info: go-librespot daemon successfully initialized Aug 27 19:24:49 volumio volumio[1160]: info: Asound.conf file unchanged, so no further update is needed Aug 27 19:24:49 volumio volumio[1160]: info: Output device has changed, restarting MPD Aug 27 19:24:49 volumio volumio[1160]: info: Output device has changed, restarting Shairport Sync Aug 27 19:24:49 volumio volumio[1160]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 19:24:49 volumio volumio[1160]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 27 19:24:49 volumio go-librespot[1516]: time="2026-08-27T19:24:49+02:00" level=debug msg="handling transfer player command from f7db85937ee572a4fa2a4dbd3bb0afdc50eab3a4" Aug 27 19:24:49 volumio sudo[1609]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Aug 27 19:24:49 volumio sudo[1609]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 27 19:24:49 volumio go-librespot[1516]: time="2026-08-27T19:24:49+02:00" level=debug msg="resolved context of track" uri="spotify:album:30Perjew8HyGkdSmqguYyg" Aug 27 19:24:49 volumio go-librespot[1516]: time="2026-08-27T19:24:49+02:00" level=trace msg="fetched new page 0 with 19 items (list: 19)" uri="spotify:album:30Perjew8HyGkdSmqguYyg" Aug 27 19:24:49 volumio go-librespot[1516]: time="2026-08-27T19:24:49+02:00" level=debug msg="loading track (paused: true, position: 60740ms)" uri="spotify:track:5ITOTuCOy6y4PB55CSZADE" Aug 27 19:24:49 volumio sudo[1611]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Aug 27 19:24:49 volumio sudo[1611]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 27 19:24:49 volumio go-librespot[1516]: time="2026-08-27T19:24:49+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 27 19:24:49 volumio go-librespot[1516]: time="2026-08-27T19:24:49+02:00" level=trace msg="emitting websocket event: will_play" Aug 27 19:24:49 volumio volumio[1160]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Aug 27 19:24:49 volumio volumio[1160]: error: updateQueue error: null Aug 27 19:24:49 volumio volumio[1160]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 27 19:24:49 volumio go-librespot[1516]: time="2026-08-27T19:24:49+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 435" Aug 27 19:24:49 volumio sudo[1609]: pam_unix(sudo:session): session closed for user root Aug 27 19:24:49 volumio go-librespot[1516]: time="2026-08-27T19:24:49+02:00" level=debug msg="selected format OGG_VORBIS_320 (e96adb3d39ea6d448e223b47582686a95c94c13f)" uri="spotify:track:5ITOTuCOy6y4PB55CSZADE" Aug 27 19:24:49 volumio go-librespot[1516]: time="2026-08-27T19:24:49+02:00" level=debug msg="requested aes key for file e96adb3d39ea6d448e223b47582686a95c94c13f, gid: 5ITOTuCOy6y4PB55CSZADE" Aug 27 19:24:49 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Aug 27 19:24:49 volumio volumio[1160]: error: FusionDsp - Reload WebSocket error: [object Object] Aug 27 19:24:49 volumio go-librespot[1516]: time="2026-08-27T19:24:49+02:00" level=trace msg="found 2 cdn urls" uri="spotify:track:5ITOTuCOy6y4PB55CSZADE" Aug 27 19:24:49 volumio volumio[1160]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 27 19:24:49 volumio go-librespot[1516]: time="2026-08-27T19:24:49+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1452" Aug 27 19:24:49 volumio go-librespot[1516]: time="2026-08-27T19:24:49+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 435" Aug 27 19:24:49 volumio volumio[1160]: info: MPD Permissions set Aug 27 19:24:49 volumio go-librespot[1516]: time="2026-08-27T19:24:49+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1228" Aug 27 19:24:49 volumio volumio[1160]: info: Received Get System Info Aug 27 19:24:50 volumio volumio[1160]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 27 19:24:50 volumio volumio[1160]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 27 19:24:50 volumio volumio[1160]: info: Discovery: Getting this device information Aug 27 19:24:50 volumio volumio[1160]: info: CoreCommandRouter::volumioGetState Aug 27 19:24:50 volumio volumio[1160]: info: CorePlayQueue::getTrack 0 Aug 27 19:24:50 volumio volumio[1160]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 27 19:24:50 volumio systemd[1]: mpd.service: Deactivated successfully. Aug 27 19:24:50 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Aug 27 19:24:50 volumio systemd[1]: mpd.service: Consumed 6.547s CPU time. Aug 27 19:24:50 volumio systemd[1]: mpd.socket: Deactivated successfully. Aug 27 19:24:50 volumio volumio[1160]: error: Upnp client error: Error: This socket has been ended by the other party Aug 27 19:24:50 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Aug 27 19:24:50 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Aug 27 19:24:50 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Aug 27 19:24:50 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Aug 27 19:24:50 volumio volumio[1160]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Aug 27 19:24:50 volumio volumio[1160]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Aug 27 19:24:50 volumio volumio5-onboarding[1411]: time=2026-08-27T19:24:50.324+02:00 level=INFO msg="enabling local network discovery" Aug 27 19:24:50 volumio go-librespot[1516]: time="2026-08-27T19:24:50+02:00" level=debug msg="fetched first chunk of 22, total size is 11110656 bytes" uri="spotify:track:5ITOTuCOy6y4PB55CSZADE" Aug 27 19:24:50 volumio volumio5-onboarding[1411]: time=2026-08-27T19:24:50.355+02:00 level=INFO msg="enabling BLE discovery" Aug 27 19:24:50 volumio volumio[1160]: error: Upnp client error: Error: connect ECONNREFUSED 127.0.0.1:6600 Aug 27 19:24:50 volumio volumio[1160]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 19:24:50 volumio volumio[1160]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 19:24:50 volumio volumio[1160]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 19:24:50 volumio volumio[1160]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 19:24:50 volumio volumio[1160]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 19:24:50 volumio volumio[1160]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 19:24:50 volumio volumio[1160]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 19:24:50 volumio volumio[1160]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 19:24:50 volumio sudo[1620]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Aug 27 19:24:50 volumio sudo[1620]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Aug 27 19:24:50 volumio sudo[1620]: pam_unix(sudo:session): session closed for user root Aug 27 19:24:50 volumio volumio[1160]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 27 19:24:50 volumio volumio[1160]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 19:24:50 volumio go-librespot[1516]: time="2026-08-27T19:24:50+02:00" level=debug msg="fetched chunk 1/21, size: 524288" uri="spotify:track:5ITOTuCOy6y4PB55CSZADE" Aug 27 19:24:51 volumio go-librespot[1516]: time="2026-08-27T19:24:51+02:00" level=debug msg="fetched chunk 3/21, size: 524288" uri="spotify:track:5ITOTuCOy6y4PB55CSZADE" Aug 27 19:24:51 volumio volumio[1160]: info: CoreCommandRouter::volumioGetState Aug 27 19:24:51 volumio volumio[1160]: info: CorePlayQueue::getTrack 0 Aug 27 19:24:51 volumio go-librespot[1516]: time="2026-08-27T19:24:51+02:00" level=debug msg="fetched chunk 2/21, size: 524288" uri="spotify:track:5ITOTuCOy6y4PB55CSZADE" Aug 27 19:24:51 volumio volumio5-onboarding[1411]: time=2026-08-27T19:24:51.375+02:00 level=INFO msg="service successfully established" component=discovery/localnet Aug 27 19:24:51 volumio volumio[1160]: info: Starting Shairport Sync Aug 27 19:24:51 volumio go-librespot[1516]: time="2026-08-27T19:24:51+02:00" level=debug msg="fetched chunk 6/21, size: 524288" uri="spotify:track:5ITOTuCOy6y4PB55CSZADE" Aug 27 19:24:51 volumio go-librespot[1516]: time="2026-08-27T19:24:51+02:00" level=debug msg="fetched chunk 8/21, size: 524288" uri="spotify:track:5ITOTuCOy6y4PB55CSZADE" Aug 27 19:24:51 volumio go-librespot[1516]: time="2026-08-27T19:24:51+02:00" level=debug msg="fetched chunk 7/21, size: 524288" uri="spotify:track:5ITOTuCOy6y4PB55CSZADE" Aug 27 19:24:51 volumio go-librespot[1516]: time="2026-08-27T19:24:51+02:00" level=debug msg="fetched chunk 5/21, size: 524288" uri="spotify:track:5ITOTuCOy6y4PB55CSZADE" Aug 27 19:24:51 volumio go-librespot[1516]: time="2026-08-27T19:24:51+02:00" level=trace msg="seek to 60740ms (diff: 129ms, samples: 2678634, bytes: 2639669)" uri="spotify:track:5ITOTuCOy6y4PB55CSZADE" Aug 27 19:24:51 volumio go-librespot[1516]: time="2026-08-27T19:24:51+02:00" level=debug msg="created new output device" Aug 27 19:24:51 volumio go-librespot[1516]: time="2026-08-27T19:24:51+02:00" level=info msg="loaded track \"The Righteous & the Wicked\" (paused: true, position: 60740ms, duration: 248000ms, prefetched: false)" uri="spotify:track:5ITOTuCOy6y4PB55CSZADE" Aug 27 19:24:51 volumio go-librespot[1516]: time="2026-08-27T19:24:51+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 27 19:24:51 volumio go-librespot[1516]: time="2026-08-27T19:24:51+02:00" level=trace msg="emitting websocket event: metadata" Aug 27 19:24:51 volumio go-librespot[1516]: time="2026-08-27T19:24:51+02:00" level=trace msg="emitting websocket event: active" Aug 27 19:24:51 volumio go-librespot[1516]: time="2026-08-27T19:24:51+02:00" level=debug msg="sending successful reply for dealer request" Aug 27 19:24:51 volumio go-librespot[1516]: time="2026-08-27T19:24:51+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Aug 27 19:24:51 volumio go-librespot[1516]: time="2026-08-27T19:24:51+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Aug 27 19:24:51 volumio go-librespot[1516]: time="2026-08-27T19:24:51+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Aug 27 19:24:51 volumio go-librespot[1516]: time="2026-08-27T19:24:51+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Aug 27 19:24:51 volumio sudo[1632]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Aug 27 19:24:51 volumio sudo[1632]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 27 19:24:51 volumio go-librespot[1516]: time="2026-08-27T19:24:51+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 27 19:24:51 volumio go-librespot[1516]: time="2026-08-27T19:24:51+02:00" level=trace msg="emitting websocket event: paused" Aug 27 19:24:51 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Aug 27 19:24:51 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Aug 27 19:24:51 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 27 19:24:51 volumio systemd[1]: shairport-sync.service: Consumed 1.322s CPU time. Aug 27 19:24:52 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 27 19:24:52 volumio sudo[1632]: pam_unix(sudo:session): session closed for user root Aug 27 19:24:52 volumio volumio[1160]: info: Shairport-Sync Started Aug 27 19:24:52 volumio volumio[1160]: info: Initializing connection to go-librespot Websocket Aug 27 19:24:52 volumio go-librespot[1516]: time="2026-08-27T19:24:52+02:00" level=debug msg="handling play player command from f7db85937ee572a4fa2a4dbd3bb0afdc50eab3a4" Aug 27 19:24:52 volumio go-librespot[1516]: time="2026-08-27T19:24:52+02:00" level=debug msg="resolved context of track" uri="spotify:album:67cksuMf5EvK5pu1DwGeFi" Aug 27 19:24:52 volumio go-librespot[1516]: time="2026-08-27T19:24:52+02:00" level=trace msg="fetched new page 0 with 9 items (list: 9)" uri="spotify:album:67cksuMf5EvK5pu1DwGeFi" Aug 27 19:24:52 volumio go-librespot[1516]: time="2026-08-27T19:24:52+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:1PkwRIvAEJhtITAK9BACv4" Aug 27 19:24:52 volumio go-librespot[1516]: time="2026-08-27T19:24:52+02:00" level=debug msg="new websocket client" Aug 27 19:24:52 volumio volumio[1160]: info: Connection to go-librespot Websocket established Aug 27 19:24:52 volumio go-librespot[1516]: time="2026-08-27T19:24:52+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 27 19:24:52 volumio go-librespot[1516]: time="2026-08-27T19:24:52+02:00" level=trace msg="emitting websocket event: will_play" Aug 27 19:24:52 volumio volumio[1160]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:album:67cksuMf5EvK5pu1DwGeFi","uri":"spotify:track:1PkwRIvAEJhtITAK9BACv4","play_origin":"album"}} Aug 27 19:24:52 volumio go-librespot[1516]: time="2026-08-27T19:24:52+02:00" level=debug msg="selected format OGG_VORBIS_320 (357960f39063345cdc441d70759c888fb6950782)" uri="spotify:track:1PkwRIvAEJhtITAK9BACv4" Aug 27 19:24:52 volumio go-librespot[1516]: time="2026-08-27T19:24:52+02:00" level=debug msg="requested aes key for file 357960f39063345cdc441d70759c888fb6950782, gid: 1PkwRIvAEJhtITAK9BACv4" Aug 27 19:24:52 volumio go-librespot[1516]: time="2026-08-27T19:24:52+02:00" level=trace msg="found 2 cdn urls" uri="spotify:track:1PkwRIvAEJhtITAK9BACv4" Aug 27 19:24:52 volumio go-librespot[1516]: time="2026-08-27T19:24:52+02:00" level=debug msg="fetched first chunk of 17, total size is 8394244 bytes" uri="spotify:track:1PkwRIvAEJhtITAK9BACv4" Aug 27 19:24:52 volumio go-librespot[1516]: time="2026-08-27T19:24:52+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 27 19:24:52 volumio go-librespot[1516]: time="2026-08-27T19:24:52+02:00" level=info msg="loaded track \"Illusions\" (paused: false, position: 0ms, duration: 217739ms, prefetched: false)" uri="spotify:track:1PkwRIvAEJhtITAK9BACv4" Aug 27 19:24:52 volumio go-librespot[1516]: time="2026-08-27T19:24:52+02:00" level=debug msg="fetched chunk 1/16, size: 524288" uri="spotify:track:1PkwRIvAEJhtITAK9BACv4" Aug 27 19:24:52 volumio go-librespot[1516]: time="2026-08-27T19:24:52+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 27 19:24:53 volumio kernel: usb 1-1.2: 2:1: cannot get freq at ep 0x1 Aug 27 19:24:53 volumio kernel: usb 1-1.2: 2:1: cannot get freq at ep 0x1 Aug 27 19:24:53 volumio volumio[1160]: info: FusionDsp - ---- read samplerate, raw: 44100,S32_LE,2,32 Aug 27 19:24:53 volumio volumio[1160]: info: FusionDsp - ---- read samplerate from file: 44100 Aug 27 19:24:53 volumio volumio[1160]: info: camilladsp stopping service pid 1598... Aug 27 19:24:53 volumio go-librespot[1516]: time="2026-08-27T19:24:53+02:00" level=debug msg="fetched chunk 2/16, size: 524288" uri="spotify:track:1PkwRIvAEJhtITAK9BACv4" Aug 27 19:24:53 volumio go-librespot[1516]: time="2026-08-27T19:24:53+02:00" level=debug msg="fetched chunk 3/16, size: 524288" uri="spotify:track:1PkwRIvAEJhtITAK9BACv4" Aug 27 19:24:53 volumio go-librespot[1516]: time="2026-08-27T19:24:53+02:00" level=trace msg="scheduling prefetch in 185s" Aug 27 19:24:53 volumio go-librespot[1516]: time="2026-08-27T19:24:53+02:00" level=trace msg="emitting websocket event: metadata" Aug 27 19:24:53 volumio go-librespot[1516]: time="2026-08-27T19:24:53+02:00" level=debug msg="sending successful reply for dealer request" Aug 27 19:24:53 volumio go-librespot[1516]: time="2026-08-27T19:24:53+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 27 19:24:53 volumio go-librespot[1516]: time="2026-08-27T19:24:53+02:00" level=trace msg="emitting websocket event: playing" Aug 27 19:24:53 volumio volumio[1160]: grep: /proc/1598/cmdline: binary file matches Aug 27 19:24:53 volumio volumio[1160]: grep: /proc/1598/cmdline: binary file matches Aug 27 19:24:53 volumio volumio[1160]: info: camilladsp service terminated, instance 1 Aug 27 19:24:53 volumio volumio[1160]: info: FusionDsp - If filter freq >samplerate/2 then disable it Aug 27 19:24:53 volumio volumio[1160]: info: camilladsp service started and running in background, instance 1 Aug 27 19:24:53 volumio volumio[1160]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:1PkwRIvAEJhtITAK9BACv4","name":"Illusions","artist_names":["Ibrahim Maalouf"],"album_name":"Illusions","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02246852a50d37ccdc2121eaf1","position":0,"duration":217739,"release_date":"year:2013 month:11 day:5","track_number":1,"disc_number":1}} Aug 27 19:24:53 volumio volumio[1160]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:album:67cksuMf5EvK5pu1DwGeFi","uri":"spotify:track:1PkwRIvAEJhtITAK9BACv4","resume":false,"play_origin":"album"}} Aug 27 19:24:53 volumio volumio[1160]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 27 19:24:53 volumio volumio[1160]: TypeError: Cannot read properties of undefined (reading 'service') Aug 27 19:24:53 volumio volumio[1160]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:346:50) Aug 27 19:24:53 volumio volumio[1160]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:272:18) Aug 27 19:24:53 volumio volumio[1160]: at WebSocket.message (/data/plugins/music_service/spop/index.js:199:14) Aug 27 19:24:53 volumio volumio[1160]: at WebSocket.emit (node:events:514:28) Aug 27 19:24:53 volumio volumio[1160]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20) Aug 27 19:24:53 volumio volumio[1160]: at Receiver.emit (node:events:514:28) Aug 27 19:24:53 volumio volumio[1160]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) Aug 27 19:24:53 volumio volumio[1160]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) Aug 27 19:24:53 volumio volumio[1160]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) Aug 27 19:24:53 volumio volumio[1160]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) Aug 27 19:24:53 volumio volumio[1160]: at writeOrBuffer (node:internal/streams/writable:399:12) Aug 27 19:24:53 volumio volumio[1160]: at _write (node:internal/streams/writable:340:10) Aug 27 19:24:53 volumio volumio[1160]: at Writable.write (node:internal/streams/writable:344:10) Aug 27 19:24:53 volumio volumio[1160]: at Socket.socketOnData (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1355:35) Aug 27 19:24:53 volumio volumio[1160]: at Socket.emit (node:events:514:28) Aug 27 19:24:53 volumio volumio[1160]: at addChunk (node:internal/streams/readable:343:12) Aug 27 19:24:53 volumio volumio[1160]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 27 19:24:54 volumio systemd[1]: Started fusiondsp.service - FusionDsp Daemon. Aug 27 19:24:54 volumio sudo[1603]: pam_unix(sudo:session): session closed for user root Aug 27 19:24:54 volumio mpd[1630]: 2026-08-27T19:24:54 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Aug 27 19:24:55 volumio systemd[1]: Started mpd.service - Music Player Daemon. Aug 27 19:24:55 volumio sudo[1611]: pam_unix(sudo:session): session closed for user root Aug 27 19:25:00 volumio sudo[1696]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-08-27 19:24' Aug 27 19:25:00 volumio 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="dc61260dec5515dafd2b634881860b4c46c919ff" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="0e58f1861fa88e02087981b8d91f7511f0e7011b" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri Mar 6 16:46:58 UTC 2026" VOLUMIO_VERSION="4.103" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="aa741395b8bfc648ff5d04e312f53d2c"