Oct 15 19:36:02 volumio ntpd[903]: CLOCK: time stepped by 14342027.196676 Oct 15 19:36:02 volumio ntpd[903]: CLOCK: time changed from 2026-05-02 to 2026-10-15 Oct 15 19:36:02 volumio ntpd[903]: INIT: MRU 13107 entries, 13 hash bits, 32768 bytes Oct 15 19:36:02 volumio systemd[1]: Starting dpkg-db-backup.service - Daily dpkg database backup service... Oct 15 19:36:02 volumio systemd[1]: Starting e2scrub_all.service - Online ext4 Metadata Check for All Filesystems... Oct 15 19:36:02 volumio systemd[1]: Started ntpsec-rotate-stats.service - Rotate ntpd stats. Oct 15 19:36:02 volumio systemd[1]: e2scrub_all.service: Deactivated successfully. Oct 15 19:36:02 volumio systemd[1]: Finished e2scrub_all.service - Online ext4 Metadata Check for All Filesystems. Oct 15 19:36:02 volumio systemd[1]: ntpsec-rotate-stats.service: Deactivated successfully. Oct 15 19:36:02 volumio systemd[1]: dpkg-db-backup.service: Deactivated successfully. Oct 15 19:36:02 volumio systemd[1]: Finished dpkg-db-backup.service - Daily dpkg database backup service. Oct 15 19:36:03 volumio volumio[1265]: info: Loading plugin "network"... Oct 15 19:36:03 volumio volumio[1265]: info: Refreshing Cached IP Addresses Oct 15 19:36:03 volumio sudo[1336]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 15 19:36:03 volumio sudo[1336]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 15 19:36:03 volumio sudo[1336]: pam_unix(sudo:session): session closed for user root Oct 15 19:36:03 volumio sudo[1335]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 15 19:36:03 volumio sudo[1335]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 15 19:36:03 volumio volumio[1265]: info: Loading plugin "services"... Oct 15 19:36:03 volumio volumio[1265]: info: Loading plugin "volumio5onboarding"... Oct 15 19:36:03 volumio volumio[1265]: info: Loading plugin "alsa_controller"... Oct 15 19:36:03 volumio sudo[1335]: pam_unix(sudo:session): session closed for user root Oct 15 19:36:03 volumio sudo[1344]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Oct 15 19:36:03 volumio sudo[1344]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 15 19:36:03 volumio volumio[1265]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 15 19:36:03 volumio volumio[1265]: info: Loading plugin "wizard"... Oct 15 19:36:03 volumio volumio[1265]: info: Loading plugin "networkfs"... Oct 15 19:36:04 volumio volumio[1265]: info: Starting Udev Watcher for removable devices Oct 15 19:36:04 volumio sudo[1365]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=admin,password=nVng30$97sCnt,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //bunker.local/music/_collection /mnt/NAS/bunker Oct 15 19:36:04 volumio volumio[1265]: info: Ignoring mount for partition: boot Oct 15 19:36:04 volumio volumio[1265]: info: Ignoring mount for partition: volumio Oct 15 19:36:04 volumio volumio[1265]: info: Ignoring mount for partition: volumio_data Oct 15 19:36:04 volumio volumio[1265]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 15 19:36:04 volumio volumio[1265]: info: Loading plugin "volumio_command_line_client"... Oct 15 19:36:04 volumio sudo[1365]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 15 19:36:04 volumio volumio[1265]: info: Loading plugin "upnp"... Oct 15 19:36:04 volumio volumio[1265]: info: [1792085764222] Starting Upmpd Daemon Oct 15 19:36:04 volumio volumio[1265]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 15 19:36:04 volumio volumio[1265]: info: Loading plugin "my_music"... Oct 15 19:36:04 volumio volumio[1265]: info: Loading plugin "mpd"... Oct 15 19:36:04 volumio sudo[1344]: pam_unix(sudo:session): session closed for user root Oct 15 19:36:04 volumio kernel: netfs: FS-Cache loaded Oct 15 19:36:04 volumio kernel: Key type cifs.spnego registered Oct 15 19:36:04 volumio kernel: Key type cifs.idmap registered Oct 15 19:36:04 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. Oct 15 19:36:04 volumio kernel: CIFS: Attempting to mount //bunker.local/music/_collection Oct 15 19:36:05 volumio sudo[1365]: pam_unix(sudo:session): session closed for user root Oct 15 19:36:05 volumio volumio[1265]: info: Loading plugin "upnp_browser"... Oct 15 19:36:07 volumio volumio[1265]: info: Starting UPNP Browser Oct 15 19:36:07 volumio volumio[1265]: info: Loading plugin "alarm-clock"... Oct 15 19:36:07 volumio volumio[1265]: info: Loading plugin "airplay_emulation"... Oct 15 19:36:07 volumio volumio[1265]: info: Starting Shairport Sync Oct 15 19:36:07 volumio volumio[1265]: info: Loading plugin "last_100"... Oct 15 19:36:07 volumio volumio[1265]: info: Loading plugin "webradio"... Oct 15 19:36:07 volumio volumio[1265]: info: Loading plugin "i2s_dacs"... Oct 15 19:36:07 volumio volumio[1265]: info: Loading plugin "volumiodiscovery"... Oct 15 19:36:07 volumio volumio[1265]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Oct 15 19:36:07 volumio volumio[1265]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 15 19:36:07 volumio node[1265]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Oct 15 19:36:07 volumio volumio[1265]: *** WARNING *** For more information see Oct 15 19:36:07 volumio volumio[1265]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Oct 15 19:36:07 volumio volumio[1265]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 15 19:36:07 volumio volumio[1265]: *** WARNING *** For more information see Oct 15 19:36:07 volumio node[1265]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 15 19:36:07 volumio node[1265]: *** WARNING *** For more information see Oct 15 19:36:07 volumio node[1265]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Oct 15 19:36:07 volumio node[1265]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 15 19:36:07 volumio node[1265]: *** WARNING *** For more information see Oct 15 19:36:07 volumio volumio[1265]: info: Applying required configuration parameters for plugin volumiodiscovery Oct 15 19:36:07 volumio volumio[1265]: info: Discovery: Started advertising with name: Volumio Oct 15 19:36:07 volumio volumio[1265]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 15 19:36:07 volumio volumio[1265]: info: Loading plugin "spop"... Oct 15 19:36:11 volumio volumio[1265]: info: Loading plugin "outputs"... Oct 15 19:36:11 volumio volumio[1265]: info: Loading plugin "albumart"... Oct 15 19:36:11 volumio volumio[1265]: info: Plugin example_plugin is not enabled Oct 15 19:36:11 volumio volumio[1265]: info: Loading plugin "inputs"... Oct 15 19:36:11 volumio volumio[1265]: info: Loading plugin "updater_comm"... Oct 15 19:36:11 volumio volumio[1265]: info: Plugin mpdemulation is not enabled Oct 15 19:36:11 volumio volumio[1265]: info: Loading plugin "rest_api"... Oct 15 19:36:11 volumio volumio[1265]: info: Loading plugin "websocket"... Oct 15 19:36:11 volumio volumio[1265]: info: Starting Socket.io Server version 1.7.4 Oct 15 19:36:11 volumio volumio[1265]: info: Loading plugin "volusonic"... Oct 15 19:36:12 volumio volumio[1405]: Forking 3 albumart workers Oct 15 19:36:12 volumio systemd[1]: systemd-fsckd.service: Deactivated successfully. Oct 15 19:36:13 volumio volumio-remote-updater[717]: [2026-10-15 19:36:13] [connect] Successful connection Oct 15 19:36:17 volumio systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 2. Oct 15 19:36:17 volumio systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Oct 15 19:36:17 volumio systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Oct 15 19:36:17 volumio upmpdcli[1459]: Could not open config: /tmp/upmpdcli.conf Oct 15 19:36:17 volumio systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Oct 15 19:36:17 volumio systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Oct 15 19:36:18 volumio systemd[1]: systemd-hostnamed.service: Deactivated successfully. Oct 15 19:36:21 volumio volumio[1265]: info: Applying required configuration parameters for plugin volusonic Oct 15 19:36:21 volumio volumio[1417]: Starting albumart workers Oct 15 19:36:21 volumio volumio[1265]: info: Loading i18n strings for locale en Oct 15 19:36:22 volumio volumio[1265]: Updating browse sources language Oct 15 19:36:22 volumio volumio[1265]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 15 19:36:22 volumio volumio[1415]: Starting albumart workers Oct 15 19:36:22 volumio volumio[1416]: Starting albumart workers Oct 15 19:36:23 volumio volumio[1265]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 15 19:36:23 volumio volumio[1265]: info: CoreCommandRouter::initPlayerControls Oct 15 19:36:23 volumio volumio[1265]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 15 19:36:23 volumio volumio[1265]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 15 19:36:23 volumio volumio[1265]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 15 19:36:23 volumio volumio[1265]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 15 19:36:23 volumio volumio[1265]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 15 19:36:23 volumio volumio[1265]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 15 19:36:23 volumio volumio[1265]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 15 19:36:23 volumio volumio[1265]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 15 19:36:23 volumio volumio[1265]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 15 19:36:23 volumio volumio[1265]: Express server listening on port 3000 Oct 15 19:36:23 volumio volumio[1265]: [Metrics] WebUI: 26s 82.18ms Oct 15 19:36:23 volumio volumio[1265]: info: CoreStateMachine::resetVolumioState Oct 15 19:36:23 volumio volumio[1265]: info: CoreStateMachine::getcurrentVolume Oct 15 19:36:23 volumio volumio[1265]: info: CoreCommandRouter::volumioRetrievevolume Oct 15 19:36:24 volumio sudo[1473]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 15 19:36:24 volumio sudo[1473]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 15 19:36:24 volumio sudo[1473]: pam_unix(sudo:session): session closed for user root Oct 15 19:36:24 volumio sudo[1475]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 15 19:36:24 volumio sudo[1475]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 15 19:36:24 volumio sudo[1475]: pam_unix(sudo:session): session closed for user root Oct 15 19:36:24 volumio volumio[1265]: info: Volumio Network Manager: Network status updated: 1 Oct 15 19:36:25 volumio volumio[1265]: info: CoreStateMachine::pushState Oct 15 19:36:25 volumio volumio[1265]: info: CorePlayQueue::getTrack 0 Oct 15 19:36:25 volumio volumio[1265]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 15 19:36:25 volumio volumio[1265]: info: CoreCommandRouter::volumioPushState Oct 15 19:36:25 volumio volumio[1265]: info: CoreStateMachine::updateTrackBlock Oct 15 19:36:25 volumio volumio[1265]: info: CorePlayQueue::getTrackBlock Oct 15 19:36:25 volumio volumio[1265]: info: CoreCommandRouter::volumioRetrievevolume Oct 15 19:36:26 volumio volumio[1265]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 15 19:36:26 volumio volumio[1265]: info: Reloading queue from file Oct 15 19:36:26 volumio volumio[1265]: info: CoreStateMachine::setRepeat null single undefined Oct 15 19:36:26 volumio volumio[1265]: info: CoreStateMachine::pushState Oct 15 19:36:26 volumio volumio[1265]: info: CorePlayQueue::getTrack 0 Oct 15 19:36:26 volumio volumio[1265]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 15 19:36:26 volumio volumio[1265]: info: CoreCommandRouter::volumioPushState Oct 15 19:36:26 volumio volumio[1265]: info: CoreStateMachine::setRandom null Oct 15 19:36:26 volumio volumio[1265]: info: CoreStateMachine::pushState Oct 15 19:36:26 volumio volumio[1265]: info: CorePlayQueue::getTrack 0 Oct 15 19:36:26 volumio volumio[1265]: info: CoreCommandRouter::volumioPushState Oct 15 19:36:26 volumio volumio[1265]: info: Setting Device type: Raspberry PI Oct 15 19:36:26 volumio volumio[1265]: info: Completed loading Core Plugins Oct 15 19:36:26 volumio volumio[1265]: info: Preparing to generate the ALSA configuration file Oct 15 19:36:26 volumio volumio[1265]: info: CoreStateMachine::pushState Oct 15 19:36:26 volumio volumio[1265]: info: CorePlayQueue::getTrack 0 Oct 15 19:36:26 volumio volumio[1265]: info: CoreCommandRouter::volumioPushState Oct 15 19:36:26 volumio volumio[1265]: info: The plugin alsa_controller has an ALSA contribution file softvolume.postVolume.conf Oct 15 19:36:26 volumio volumio[1265]: info: Reading ALSA contributions from plugins. Oct 15 19:36:26 volumio volumio[1265]: info: Discovery: adding 57bd9636-0bd4-489a-9bb6-b7b8c45bbf04 Oct 15 19:36:26 volumio volumio[1265]: info: Discovery: Found device Volumio Oct 15 19:36:26 volumio volumio[1265]: info: CoreCommandRouter::volumioGetState Oct 15 19:36:26 volumio volumio[1265]: info: CorePlayQueue::getTrack 0 Oct 15 19:36:27 volumio volumio[1265]: info: Discovery: this is already registered, 57bd9636-0bd4-489a-9bb6-b7b8c45bbf04 Oct 15 19:36:27 volumio volumio[1265]: info: Discovery: Found device Volumio Oct 15 19:36:27 volumio volumio[1265]: info: CoreCommandRouter::volumioGetState Oct 15 19:36:27 volumio volumio[1265]: info: CorePlayQueue::getTrack 0 Oct 15 19:36:27 volumio sudo[1514]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Oct 15 19:36:27 volumio sudo[1514]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 15 19:36:27 volumio systemd[1]: Starting setdatetime-helper.service - Time Synchronization Helper Service... Oct 15 19:36:27 volumio volumio[1265]: info: Asound.conf file unchanged, so no further update is needed Oct 15 19:36:27 volumio volumio[1265]: info: Output device has changed, restarting MPD Oct 15 19:36:27 volumio volumio[1265]: info: Output device has changed, restarting Shairport Sync Oct 15 19:36:27 volumio volumio[1265]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 15 19:36:27 volumio volumio[1265]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 15 19:36:27 volumio sudo[1536]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 15 19:36:27 volumio sudo[1545]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 15 19:36:27 volumio sudo[1536]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 15 19:36:27 volumio sudo[1536]: pam_unix(sudo:session): session closed for user root Oct 15 19:36:27 volumio sudo[1545]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 15 19:36:27 volumio volumio[1265]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 15 19:36:27 volumio volumio[1265]: info: ___________ START PLUGINS ___________ Oct 15 19:36:28 volumio volumio[1265]: info: ControllerMpd::onStart: Initializing MPD Oct 15 19:36:28 volumio volumio[1265]: info: Creating MPD Configuration file Oct 15 19:36:28 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Oct 15 19:36:28 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Oct 15 19:36:28 volumio sudo[1556]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumio5-onboarding.service Oct 15 19:36:28 volumio sudo[1556]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 15 19:36:28 volumio sudo[1559]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 15 19:36:28 volumio sudo[1559]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 15 19:36:28 volumio sudo[1559]: pam_unix(sudo:session): session closed for user root Oct 15 19:36:28 volumio volumio[1265]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 15 19:36:28 volumio volumio[1265]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 15 19:36:28 volumio volumio[1265]: info: [1792085788285] CoreMusicLibrary::Adding element Media Servers Oct 15 19:36:28 volumio volumio[1265]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 15 19:36:28 volumio systemd[1]: Started volumio5-onboarding.service - Volumio5 Onboarding Server. Oct 15 19:36:28 volumio sudo[1556]: pam_unix(sudo:session): session closed for user root Oct 15 19:36:28 volumio sudo[1558]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Oct 15 19:36:28 volumio sudo[1558]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Oct 15 19:36:28 volumio sudo[1565]: /bin/chown: cannot access '/var/log/mpd.log': No such file or directory Oct 15 19:36:28 volumio sudo[1558]: pam_unix(sudo:session): session closed for user root Oct 15 19:36:28 volumio sudo[1564]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 15 19:36:28 volumio sudo[1564]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 15 19:36:28 volumio volumio[1265]: info: UPNP Browser: Client initialized successfully Oct 15 19:36:28 volumio volumio[1265]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 15 19:36:28 volumio volumio[1265]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 15 19:36:28 volumio systemd[1]: mpd.service: Deactivated successfully. Oct 15 19:36:28 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Oct 15 19:36:28 volumio volumio-remote-updater[717]: [2026-10-15 19:36:28] [connect] Successful connection Oct 15 19:36:28 volumio systemd[1]: mpd.socket: Deactivated successfully. Oct 15 19:36:28 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Oct 15 19:36:28 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Oct 15 19:36:28 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Oct 15 19:36:28 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Oct 15 19:36:29 volumio sudo[1578]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Oct 15 19:36:29 volumio sudo[1578]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Oct 15 19:36:29 volumio volumio[1265]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 15 19:36:29 volumio sudo[1579]: /bin/chown: cannot access '/var/log/mpd.log': No such file or directory Oct 15 19:36:29 volumio sudo[1578]: pam_unix(sudo:session): session closed for user root Oct 15 19:36:29 volumio volumio[1265]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 15 19:36:29 volumio volumio[1265]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 15 19:36:29 volumio volumio5-onboarding[1562]: time=2026-10-15T19:36:29.153+02:00 level=INFO msg="running volumio5-device-gateway" version=6370e0a8+CHANGES buildDate=2026-03-06T16:29:42Z Oct 15 19:36:29 volumio volumio[1265]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 15 19:36:29 volumio volumio[1265]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 15 19:36:29 volumio volumio[1265]: info: [1792085789462] CoreMusicLibrary::Adding element Last_100 Oct 15 19:36:29 volumio volumio[1265]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 15 19:36:29 volumio volumio[1265]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 15 19:36:29 volumio volumio[1265]: info: [1792085789467] CoreMusicLibrary::Adding element Webradio Oct 15 19:36:29 volumio volumio[1265]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 15 19:36:29 volumio volumio[1265]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 15 19:36:29 volumio volumio[1265]: info: Initializing BBC Radios Oct 15 19:36:29 volumio systemd[1]: setdatetime-helper.service: Deactivated successfully. Oct 15 19:36:29 volumio systemd[1]: Finished setdatetime-helper.service - Time Synchronization Helper Service. Oct 15 19:36:29 volumio systemd[1]: setdatetime-helper.service: Consumed 1.125s CPU time. Oct 15 19:36:30 volumio volumio[1265]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 15 19:36:30 volumio volumio[1265]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 15 19:36:30 volumio volumio[1265]: info: Creating Spotify config file Oct 15 19:36:30 volumio volumio[1265]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 15 19:36:32 volumio systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 3. Oct 15 19:36:32 volumio systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Oct 15 19:36:32 volumio systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Oct 15 19:36:32 volumio sudo[1514]: pam_unix(sudo:session): session closed for user root Oct 15 19:36:33 volumio volumio[1265]: info: Loading i18n strings for locale en Oct 15 19:36:33 volumio volumio[1265]: Updating browse sources language Oct 15 19:36:33 volumio volumio[1265]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 15 19:36:33 volumio volumio[1265]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 15 19:36:33 volumio volumio[1265]: info: [1792085793231] CoreMusicLibrary::Adding element Volusonic Oct 15 19:36:33 volumio volumio[1265]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 15 19:36:33 volumio volumio[1265]: Cannot find translation for source Volusonic Oct 15 19:36:33 volumio volumio[1265]: info: Volumio Calling Home Oct 15 19:36:35 volumio volumio[1265]: info: MPD Permissions set Oct 15 19:36:35 volumio volumio[1265]: info: MPD Permissions set Oct 15 19:36:35 volumio volumio[1265]: info: Upmpdcli Daemon Started Oct 15 19:36:36 volumio volumio[1265]: info: Spotify config file written Oct 15 19:36:36 volumio sudo[1644]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Oct 15 19:36:36 volumio sudo[1644]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 15 19:36:36 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. Oct 15 19:36:36 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. Oct 15 19:36:36 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 15 19:36:36 volumio go-librespot[1646]: go-librespot daemon starting... Oct 15 19:36:36 volumio sudo[1644]: pam_unix(sudo:session): session closed for user root Oct 15 19:36:37 volumio mpd[1584]: 2026-10-15T19:36:37 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Oct 15 19:36:37 volumio go-librespot[1647]: time="2026-10-15T19:36:37+02:00" level=info msg="running go-librespot 0.7.1" Oct 15 19:36:37 volumio go-librespot[1647]: time="2026-10-15T19:36:37+02:00" level=debug msg="app state loaded" Oct 15 19:36:37 volumio go-librespot[1647]: time="2026-10-15T19:36:37+02:00" level=debug msg="stored credentials not found" Oct 15 19:36:37 volumio go-librespot[1647]: time="2026-10-15T19:36:37+02:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 15 19:36:37 volumio systemd[1]: Started mpd.service - Music Player Daemon. Oct 15 19:36:37 volumio sudo[1564]: pam_unix(sudo:session): session closed for user root Oct 15 19:36:37 volumio sudo[1545]: pam_unix(sudo:session): session closed for user root Oct 15 19:36:38 volumio volumio[1265]: 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: 1 Oct 15 19:36:38 volumio volumio[1265]: info: Volumio called home Oct 15 19:36:38 volumio volumio[1265]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 15 19:36:38 volumio volumio[1265]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 15 19:36:38 volumio volumio[1265]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 15 19:36:38 volumio volumio[1265]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 15 19:36:38 volumio volumio[1265]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 15 19:36:38 volumio volumio[1265]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 15 19:36:38 volumio volumio[1265]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 15 19:36:38 volumio volumio[1265]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 15 19:36:38 volumio go-librespot[1647]: time="2026-10-15T19:36:38+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Oct 15 19:36:38 volumio go-librespot[1647]: time="2026-10-15T19:36:38+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 15 19:36:38 volumio go-librespot[1647]: time="2026-10-15T19:36:38+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 15 19:36:38 volumio volumio[1265]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 15 19:36:38 volumio go-librespot[1647]: time="2026-10-15T19:36:38+02:00" level=info msg="zeroconf server listening on port 35601" Oct 15 19:36:38 volumio go-librespot[1647]: time="2026-10-15T19:36:38+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Oct 15 19:36:38 volumio volumio[1265]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 15 19:36:38 volumio volumio[1265]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 15 19:36:38 volumio volumio[1265]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 15 19:36:38 volumio volumio[1265]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 15 19:36:38 volumio volumio[1265]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 15 19:36:38 volumio volumio[1265]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 15 19:36:38 volumio volumio[1265]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 15 19:36:38 volumio volumio[1265]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 15 19:36:38 volumio volumio[1265]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 15 19:36:38 volumio volumio[1265]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 15 19:36:38 volumio volumio[1265]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 15 19:36:38 volumio volumio[1265]: info: No need to fix Spotify hosts Oct 15 19:36:39 volumio volumio[1265]: 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: 1 Oct 15 19:36:39 volumio volumio[1265]: info: Received Get System Info Oct 15 19:36:39 volumio volumio[1265]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 15 19:36:39 volumio volumio[1265]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 15 19:36:39 volumio volumio[1265]: info: Discovery: Getting this device information Oct 15 19:36:39 volumio volumio[1265]: info: CoreCommandRouter::volumioGetState Oct 15 19:36:39 volumio volumio[1265]: info: CorePlayQueue::getTrack 0 Oct 15 19:36:39 volumio volumio[1265]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 15 19:36:39 volumio volumio5-onboarding[1562]: time=2026-10-15T19:36:39.105+02:00 level=INFO msg="system info for dcdf8ce376176a059293946f5ca17709" deviceName=Volumio deviceVariant=volumio deviceModel= softwareVersion=4.119 Oct 15 19:36:39 volumio volumio5-onboarding[1562]: time=2026-10-15T19:36:39.121+02:00 level=INFO msg="bootstrapping state" hasInternet=true Oct 15 19:36:39 volumio volumio[1265]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Oct 15 19:36:39 volumio volumio[1265]: info: Completed starting Core Plugins Oct 15 19:36:39 volumio volumio[1265]: info: ------------------------------------------- Oct 15 19:36:39 volumio volumio[1265]: info: ----- MyVolumio plugins startup ---- Oct 15 19:36:39 volumio volumio[1265]: info: ------------------------------------------- Oct 15 19:36:39 volumio volumio[1265]: info: [MyVolumio PluginManager] Fetching plans data.... Oct 15 19:36:40 volumio volumio[1265]: info: Received Get System Info Oct 15 19:36:40 volumio volumio[1265]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 15 19:36:40 volumio volumio[1265]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 15 19:36:40 volumio volumio[1265]: info: Discovery: Getting this device information Oct 15 19:36:40 volumio volumio[1265]: info: CoreCommandRouter::volumioGetState Oct 15 19:36:40 volumio volumio[1265]: info: CorePlayQueue::getTrack 0 Oct 15 19:36:40 volumio volumio[1265]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 15 19:36:40 volumio volumio[1265]: info: An error occurred while refreshing Spotify Token Error: Bad Request Oct 15 19:36:40 volumio volumio[1265]: error: MPD error: The expression evaluated to a falsy value: Oct 15 19:36:40 volumio volumio[1265]: assert.ok(self.idling) Oct 15 19:36:40 volumio volumio[1265]: error: The expression evaluated to a falsy value: Oct 15 19:36:40 volumio volumio[1265]: assert.ok(self.idling) Oct 15 19:36:40 volumio volumio[1265]: info: MPD running with PID1584 Oct 15 19:36:40 volumio volumio[1265]: ,establishing connection Oct 15 19:36:40 volumio volumio[1265]: info: Starting Shairport Sync Oct 15 19:36:41 volumio volumio[1265]: info: Starting Shairport Sync Oct 15 19:36:41 volumio volumio[1265]: info: Starting Shairport Sync Oct 15 19:36:41 volumio volumio[1265]: error: updateQueue error: null Oct 15 19:36:41 volumio sudo[1676]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 15 19:36:41 volumio sudo[1676]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 15 19:36:41 volumio sudo[1674]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 15 19:36:41 volumio sudo[1674]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 15 19:36:41 volumio sudo[1678]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 15 19:36:41 volumio sudo[1678]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 15 19:36:41 volumio volumio[1265]: error: updateQueue error: null Oct 15 19:36:41 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Oct 15 19:36:41 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Oct 15 19:36:41 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Oct 15 19:36:41 volumio systemd[1]: shairport-sync.service: Consumed 2.010s CPU time. Oct 15 19:36:41 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Oct 15 19:36:41 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Oct 15 19:36:41 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Oct 15 19:36:41 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Oct 15 19:36:41 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Oct 15 19:36:41 volumio sudo[1678]: pam_unix(sudo:session): session closed for user root Oct 15 19:36:41 volumio sudo[1676]: pam_unix(sudo:session): session closed for user root Oct 15 19:36:41 volumio sudo[1674]: pam_unix(sudo:session): session closed for user root Oct 15 19:36:41 volumio volumio[1265]: info: Shairport-Sync Started Oct 15 19:36:41 volumio volumio[1265]: Error adding Membership: Error: addMembership EINVAL Oct 15 19:36:41 volumio volumio[1265]: info: Shairport-Sync Started Oct 15 19:36:41 volumio volumio[1265]: info: Shairport-Sync Started Oct 15 19:36:41 volumio volumio[1265]: info: CoreCommandRouter::volumioGetState Oct 15 19:36:41 volumio volumio[1265]: info: CorePlayQueue::getTrack 0 Oct 15 19:36:42 volumio volumio[1265]: info: go-librespot daemon successfully initialized Oct 15 19:36:43 volumio volumio-remote-updater[717]: [2026-10-15 19:36:43] [connect] Successful connection Oct 15 19:36:43 volumio volumio-remote-updater[717]: [2026-10-15 19:36:43] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1792085803 101 Oct 15 19:36:43 volumio volumio[1265]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 3 Transport: websocket Total Clients: 3 Oct 15 19:36:45 volumio volumio[1265]: info: Initializing connection to go-librespot Websocket Oct 15 19:36:46 volumio go-librespot[1647]: time="2026-10-15T19:36:46+02:00" level=debug msg="new websocket client" Oct 15 19:36:46 volumio volumio[1265]: info: Connection to go-librespot Websocket established Oct 15 19:36:46 volumio volumio[1265]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Oct 15 19:36:51 volumio volumio[1265]: info: Getting Spotify volume Oct 15 19:36:57 volumio upmpdcli[1737]: writing RSA key Oct 15 19:37:03 volumio volumio[1265]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 15 19:37:04 volumio volumio[1265]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 15 19:37:04 volumio volumio[1265]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Oct 15 19:37:04 volumio volumio[1265]: error: MyVolumio Plugin failed to start in a timely fashion Oct 15 19:37:04 volumio volumio[1265]: [Metrics] CommandRouter: 64s 890.98ms Oct 15 19:37:04 volumio volumio[1265]: info: CoreCommandRouter::volumiosetStartupVolume Oct 15 19:37:04 volumio volumio[1265]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 15 19:37:04 volumio volumio[1265]: info: VolumeController:: Setting startup Volume 85 Oct 15 19:37:04 volumio volumio[1265]: info: VolumeController::SetAlsaVolume85 Oct 15 19:37:04 volumio volumio[1265]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 15 19:37:04 volumio volumio[1265]: info: CoreCommandRouter::Close All Modals sent Oct 15 19:37:04 volumio volumio[1265]: info: CoreCommandRouter::Close All Modals sent Oct 15 19:37:04 volumio volumio[1265]: info: CoreStateMachine::pushState Oct 15 19:37:04 volumio volumio[1265]: info: CorePlayQueue::getTrack 0 Oct 15 19:37:04 volumio volumio[1265]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 15 19:37:04 volumio volumio[1265]: info: CoreCommandRouter::volumioPushState Oct 15 19:37:09 volumio volumio5-onboarding[1562]: failed to bootstrap state: failed to check for software update: could not check for updates: context deadline exceeded Oct 15 19:37:09 volumio systemd[1]: volumio5-onboarding.service: Main process exited, code=exited, status=1/FAILURE Oct 15 19:37:09 volumio systemd[1]: volumio5-onboarding.service: Failed with result 'exit-code'. Oct 15 19:37:09 volumio systemd[1]: volumio5-onboarding.service: Scheduled restart job, restart counter is at 1. Oct 15 19:37:09 volumio systemd[1]: Stopped volumio5-onboarding.service - Volumio5 Onboarding Server. Oct 15 19:37:09 volumio systemd[1]: Started volumio5-onboarding.service - Volumio5 Onboarding Server. Oct 15 19:37:09 volumio volumio5-onboarding[1771]: time=2026-10-15T19:37:09.491+02:00 level=INFO msg="running volumio5-device-gateway" version=6370e0a8+CHANGES buildDate=2026-03-06T16:29:42Z Oct 15 19:37:11 volumio volumio[1265]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 4 Oct 15 19:37:11 volumio volumio[1265]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable Oct 15 19:37:11 volumio volumio[1265]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Oct 15 19:37:11 volumio volumio[1265]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect Oct 15 19:37:11 volumio volumio[1265]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 15 19:37:11 volumio volumio[1265]: Error [ERR_INTERNAL_ASSERTION]: This is caused by either a bug in Node.js or incorrect usage of Node.js internals. Oct 15 19:37:11 volumio volumio[1265]: Please open an issue with this stack trace at https://github.com/nodejs/node/issues Oct 15 19:37:11 volumio volumio[1265]: at new NodeError (node:internal/errors:405:5) Oct 15 19:37:11 volumio volumio[1265]: at assert (node:internal/assert:14:11) Oct 15 19:37:11 volumio volumio[1265]: at internalConnectMultiple (node:net:1118:3) Oct 15 19:37:11 volumio volumio[1265]: at Timeout.internalConnectMultipleTimeout (node:net:1687:3) Oct 15 19:37:11 volumio volumio[1265]: at listOnTimeout (node:internal/timers:575:11) Oct 15 19:37:11 volumio volumio[1265]: at process.processTimers (node:internal/timers:514:7) { Oct 15 19:37:11 volumio volumio[1265]: code: 'ERR_INTERNAL_ASSERTION' Oct 15 19:37:11 volumio volumio[1265]: } Oct 15 19:37:11 volumio volumio[1265]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 15 19:37:18 volumio sudo[1812]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-10-15 19:36' Oct 15 19:37:18 volumio sudo[1812]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) PRETTY_NAME="Raspbian GNU/Linux 12 (bookworm)" NAME="Raspbian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="18952480e8d8c63f22208e9007a0f47a9563eae6" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="0e58f1861fa88e02087981b8d91f7511f0e7011b" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue Mar 24 17:20:52 UTC 2026" VOLUMIO_VERSION="4.119" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="d0c2fd9dbc5e70e58c32413c12353563"