Aug 28 09:02:00 volumio4 dbus-daemon[774]: [system] Activating via systemd: service name='org.freedesktop.hostname1' unit='dbus-org.freedesktop.hostname1.service' requested by ':1.2' (uid=0 pid=773 comm="/usr/libexec/bluetooth/bluetoothd --noplugin=sap,b") Aug 28 09:02:00 volumio4 bluetoothd[773]: Bluetooth management interface 1.23 initialized Aug 28 09:02:00 volumio4 bluetoothd[773]: Battery Provider Manager created Aug 28 09:02:00 volumio4 kernel: Bluetooth: BNEP (Ethernet Emulation) ver 1.3 Aug 28 09:02:00 volumio4 kernel: Bluetooth: BNEP filters: protocol multicast Aug 28 09:02:00 volumio4 kernel: Bluetooth: BNEP socket layer initialized Aug 28 09:02:00 volumio4 kernel: Bluetooth: MGMT ver 1.23 Aug 28 09:02:00 volumio4 cpufrequtils[929]: CPUFreq Utilities: Setting ondemand CPUFreq governor...CPU0...CPU1...CPU2...CPU3...done. Aug 28 09:02:00 volumio4 kernel: NET: Registered PF_ALG protocol family Aug 28 09:02:00 volumio4 systemd[1]: Starting wpa_supplicant.service - WPA supplicant... Aug 28 09:02:00 volumio4 systemd[1]: Started cpufrequtils.service - LSB: set CPUFreq kernel parameters. Aug 28 09:02:00 volumio4 systemd[1]: Started bluetooth.service - Bluetooth service. Aug 28 09:02:00 volumio4 systemd[1]: Started systemd-logind.service - User Login Management. Aug 28 09:02:00 volumio4 systemd[1]: Started avahi-daemon.service - Avahi mDNS/DNS-SD Stack. Aug 28 09:02:00 volumio4 systemd[1]: iptables.service: Deactivated successfully. Aug 28 09:02:00 volumio4 systemd[1]: Starting bluealsa.service - BlueALSA service... Aug 28 09:02:00 volumio4 systemd[1]: Starting systemd-hostnamed.service - Hostname Service... Aug 28 09:02:00 volumio4 kernel: cryptd: max_cpu_qlen set to 1000 Aug 28 09:02:00 volumio4 dbus-daemon[774]: [system] Successfully activated service 'org.freedesktop.hostname1' Aug 28 09:02:00 volumio4 systemd[1]: Started systemd-hostnamed.service - Hostname Service. Aug 28 09:02:00 volumio4 rpi-eeprom-update[778]: Skipping automatic bootloader upgrade. current 1765221822 >= min 1746717695 Aug 28 09:02:00 volumio4 systemd[1]: Started wpa_supplicant.service - WPA supplicant. Aug 28 09:02:00 volumio4 wpa_supplicant[957]: Successfully initialized wpa_supplicant Aug 28 09:02:00 volumio4 systemd[1]: Reached target network.target - Network. Aug 28 09:02:00 volumio4 systemd[1]: Reached target network-online.target - Network is Online. Aug 28 09:02:00 volumio4 systemd[1]: Starting ifplugd.service - LSB: Brings up/down network automatically... Aug 28 09:02:00 volumio4 systemd[1]: Starting nmbd.service - Samba NMB Daemon... Aug 28 09:02:00 volumio4 bluetoothd[773]: profiles/audio/bap.c:bap_adapter_probe() BAP requires ISO Socket which is not enabled Aug 28 09:02:00 volumio4 bluetoothd[773]: bap: Operation not supported (95) Aug 28 09:02:00 volumio4 systemd[1]: Starting ntpsec.service - Network Time Service... Aug 28 09:02:00 volumio4 systemd[1]: Starting rc-local.service - /etc/rc.local Compatibility... Aug 28 09:02:00 volumio4 systemd[1]: Starting rpc-statd-notify.service - Notify NFS peers of a restart... Aug 28 09:02:00 volumio4 systemd[1]: Starting samba-ad-dc.service - Samba AD Daemon... Aug 28 09:02:00 volumio4 bluetoothd[773]: Adv Monitor Manager created with supported features:0x00000000, enabled features:0x00000000, max number of supported monitors:32, max number of supported patterns:16 Aug 28 09:02:00 volumio4 sm-notify[997]: Version 2.6.2 starting Aug 28 09:02:00 volumio4 systemd[1]: Starting setdatetime-helper.service - Time Synchronization Helper Service... Aug 28 09:02:00 volumio4 systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 28 09:02:00 volumio4 systemd[1]: Starting ssh.service - OpenBSD Secure Shell server... Aug 28 09:02:00 volumio4 systemd[1]: Starting systemd-user-sessions.service - Permit User Sessions... Aug 28 09:02:00 volumio4 systemd[1]: Started volumio-ipchange.service - Volumio IP Change Monitor. Aug 28 09:02:00 volumio4 systemd[1]: Starting welcome.service - Show a welcome message on console... Aug 28 09:02:00 volumio4 systemd[1]: Started rc-local.service - /etc/rc.local Compatibility. Aug 28 09:02:00 volumio4 systemd[1]: Started rpc-statd-notify.service - Notify NFS peers of a restart. Aug 28 09:02:00 volumio4 systemd[1]: Finished systemd-user-sessions.service - Permit User Sessions. Aug 28 09:02:00 volumio4 ntpd[1001]: INIT: ntpd ntpsec-1.2.2: Starting Aug 28 09:02:00 volumio4 ntpd[1001]: INIT: Command line: /usr/sbin/ntpd -p /run/ntpd.pid -c /etc/ntpsec/ntp.conf -g -N -u ntpsec:ntpsec Aug 28 09:02:00 volumio4 ntp-systemd-wrapper[1001]: 2026-08-28T09:02:00 ntpd[1001]: INIT: ntpd ntpsec-1.2.2: Starting Aug 28 09:02:00 volumio4 ntp-systemd-wrapper[1001]: 2026-08-28T09:02:00 ntpd[1001]: INIT: Command line: /usr/sbin/ntpd -p /run/ntpd.pid -c /etc/ntpsec/ntp.conf -g -N -u ntpsec:ntpsec Aug 28 09:02:00 volumio4 welcome[1012]: Resolved ip:[0] Aug 28 09:02:00 volumio4 ifplugd(eth0)[1032]: ifplugd 0.28 initializing. Aug 28 09:02:00 volumio4 systemd[1]: Starting plymouth-quit-wait.service - Hold until boot process finishes up... Aug 28 09:02:00 volumio4 ifplugd(eth0)[1032]: Using interface eth0/D8:3A:DD:65:57:1A with driver (version: 6.12.74-v7l+) Aug 28 09:02:00 volumio4 ifplugd(eth0)[1032]: Using detection mode: SIOCETHTOOL Aug 28 09:02:00 volumio4 ifplugd(eth0)[1032]: Initialization complete, link beat not detected. Aug 28 09:02:00 volumio4 systemd[1]: Started ntpsec.service - Network Time Service. Aug 28 09:02:00 volumio4 ntpd[1021]: INIT: precision = 1.037 usec (-20) Aug 28 09:02:00 volumio4 ntpd[1021]: INIT: successfully locked into RAM Aug 28 09:02:00 volumio4 ntpd[1021]: CONFIG: readconfig: parsing file: /etc/ntpsec/ntp.conf Aug 28 09:02:00 volumio4 ntpd[1021]: CONFIG: restrict nopeer ignored Aug 28 09:02:00 volumio4 ifplugd[986]: Network Interface Plugging Daemon...start eth0...done. Aug 28 09:02:00 volumio4 systemd[1]: Started ifplugd.service - LSB: Brings up/down network automatically. Aug 28 09:02:00 volumio4 ntpd[1021]: CLOCK: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): good hash signature Aug 28 09:02:00 volumio4 ntpd[1021]: CLOCK: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): loaded, expire=2026-06-28T00:00Z last=2017-01-01T00:00Z ofs=37 Aug 28 09:02:00 volumio4 ntpd[1021]: CLOCK: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): expired less than 62 days ago Aug 28 09:02:00 volumio4 ntpd[1021]: INIT: Using SO_TIMESTAMPNS(ns) Aug 28 09:02:00 volumio4 ntpd[1021]: IO: Listen and drop on 0 v6wildcard [::]:123 Aug 28 09:02:00 volumio4 ntpd[1021]: IO: Listen and drop on 1 v4wildcard 0.0.0.0:123 Aug 28 09:02:00 volumio4 ntpd[1021]: IO: Listen normally on 2 lo 127.0.0.1:123 Aug 28 09:02:00 volumio4 ntpd[1021]: IO: Listening on routing socket on fd #19 for interface updates Aug 28 09:02:00 volumio4 ntpd[1021]: INIT: This system has a 32-bit time_t. Aug 28 09:02:00 volumio4 ntpd[1021]: INIT: This ntpd will fail on 2038-01-19T03:14:07Z. Aug 28 09:02:00 volumio4 ntpd[1021]: INIT: MRU 13107 entries, 13 hash bits, 32768 bytes Aug 28 09:02:00 volumio4 ntpd[1021]: INIT: Built with OpenSSL 3.0.9 30 May 2023, 30000090 Aug 28 09:02:00 volumio4 ntpd[1021]: INIT: Running with OpenSSL 3.0.19 27 Jan 2026, 30000130 Aug 28 09:02:00 volumio4 ntpd[1021]: NTSc: Using system default root certificates. Aug 28 09:02:00 volumio4 rpi-eeprom-update[778]: BOOTLOADER: up to date Aug 28 09:02:00 volumio4 rpi-eeprom-update[778]: CURRENT: Mon Dec 8 19:23:42 UTC 2025 (1765221822) Aug 28 09:02:00 volumio4 rpi-eeprom-update[778]: LATEST: Fri Jan 9 16:12:13 UTC 2026 (1767975133) Aug 28 09:02:00 volumio4 rpi-eeprom-update[778]: RELEASE: default (/usr/lib/firmware/raspberrypi/bootloader-2711/default) Aug 28 09:02:00 volumio4 rpi-eeprom-update[778]: Use raspi-config to change the release. Aug 28 09:02:00 volumio4 rpi-eeprom-update[778]: VL805_FW: Using bootloader EEPROM Aug 28 09:02:00 volumio4 rpi-eeprom-update[778]: VL805: up to date Aug 28 09:02:00 volumio4 rpi-eeprom-update[778]: CURRENT: 000138c0 Aug 28 09:02:00 volumio4 rpi-eeprom-update[778]: LATEST: 000138c0 Aug 28 09:02:00 volumio4 systemd[1]: Finished rpi-eeprom-update.service - Check for Raspberry Pi EEPROM updates. Aug 28 09:02:00 volumio4 systemd[1]: Finished welcome.service - Show a welcome message on console. Aug 28 09:02:00 volumio4 avahi-daemon[769]: Server startup complete. Host name is volumio4.local. Local service cookie is 857552722. Aug 28 09:02:00 volumio4 sshd[1056]: Server listening on 0.0.0.0 port 22. Aug 28 09:02:00 volumio4 sshd[1056]: Server listening on :: port 22. Aug 28 09:02:00 volumio4 systemd[1]: Started ssh.service - OpenBSD Secure Shell server. Aug 28 09:02:01 volumio4 ntpd[1021]: statistics directory /var/log/ntpsec/ does not exist or is unwriteable, error No such file or directory Aug 28 09:02:01 volumio4 bluealsa[970]: ../src/storage.c:90: Initializing persistent storage: /var/lib/bluealsa Aug 28 09:02:01 volumio4 bluealsa[970]: main.c:663: Starting main dispatching loop Aug 28 09:02:01 volumio4 bluealsa[970]: main.c:118: Acquired D-Bus service name: org.bluealsa Aug 28 09:02:01 volumio4 systemd[1]: Started bluealsa.service - BlueALSA service. Aug 28 09:02:01 volumio4 bluealsa[970]: bluealsa-dbus.c:358: Registering BlueALSA D-Bus manager: /org/bluealsa Aug 28 09:02:01 volumio4 systemd[1]: Reached target bluetooth.target - Bluetooth Support. Aug 28 09:02:01 volumio4 bluealsa[970]: bluez.c:153: Registering media application: /org/bluez/hci0 Aug 28 09:02:01 volumio4 bluealsa[970]: bluez.c:743: Exporting media endpoint object: /org/bluez/hci0/A2DP/SBC/source/1 Aug 28 09:02:01 volumio4 bluealsa[970]: bluez.c:743: Exporting media endpoint object: /org/bluez/hci0/A2DP/SBC/source/2 Aug 28 09:02:01 volumio4 bluealsa[970]: bluez.c:743: Exporting media endpoint object: /org/bluez/hci0/A2DP/SBC/sink/1 Aug 28 09:02:01 volumio4 bluealsa[970]: bluez.c:743: Exporting media endpoint object: /org/bluez/hci0/A2DP/SBC/sink/2 Aug 28 09:02:01 volumio4 bluetoothd[773]: Endpoint registered: sender=:1.6 path=/org/bluez/hci0/A2DP/SBC/sink/1 Aug 28 09:02:01 volumio4 bluetoothd[773]: Endpoint registered: sender=:1.6 path=/org/bluez/hci0/A2DP/SBC/sink/2 Aug 28 09:02:01 volumio4 bluetoothd[773]: Endpoint registered: sender=:1.6 path=/org/bluez/hci0/A2DP/SBC/source/1 Aug 28 09:02:01 volumio4 bluetoothd[773]: Endpoint registered: sender=:1.6 path=/org/bluez/hci0/A2DP/SBC/source/2 Aug 28 09:02:01 volumio4 avahi-daemon[769]: Service "Volumio4" (/services/volumio.service) successfully established. Aug 28 09:02:02 volumio4 ntpd[1021]: DNS: dns_probe: 0.debian.pool.ntp.org, cast_flags:8, flags:101 Aug 28 09:02:02 volumio4 systemd[1]: samba-ad-dc.service: Skipped due to 'exec-condition'. Aug 28 09:02:02 volumio4 systemd[1]: Condition check resulted in samba-ad-dc.service - Samba AD Daemon being skipped. Aug 28 09:02:02 volumio4 ntpd[1021]: DNS: dns_check: processing 0.debian.pool.ntp.org, 8, 101 Aug 28 09:02:02 volumio4 ntpd[1021]: DNS: dns_check: DNS error: -11, System error Aug 28 09:02:02 volumio4 ntpd[1021]: DNS: dns_take_status: 0.debian.pool.ntp.org=>error, 12 Aug 28 09:02:02 volumio4 nmbd[1095]: [2026/08/28 09:02:02.536626, 0] ../../source3/nmbd/nmbd.c:901(main) Aug 28 09:02:02 volumio4 nmbd[1095]: nmbd version 4.17.8-Raspbian started. Aug 28 09:02:02 volumio4 nmbd[1095]: Copyright Andrew Tridgell and the Samba Team 1992-2022 Aug 28 09:02:02 volumio4 nmbd[1095]: [2026/08/28 09:02:02.541382, 0] ../../source3/nmbd/asyncdns.c:158(start_async_dns) Aug 28 09:02:02 volumio4 nmbd[1095]: started asyncdns process 1100 Aug 28 09:02:02 volumio4 nmbd[1095]: [2026/08/28 09:02:02.542483, 0] ../../lib/util/become_daemon.c:150(daemon_status) Aug 28 09:02:02 volumio4 nmbd[1095]: daemon_status: daemon 'nmbd' : No local IPv4 non-loopback interfaces available, waiting for interface ... Aug 28 09:02:02 volumio4 nmbd[1095]: [2026/08/28 09:02:02.542575, 0] ../../source3/nmbd/nmbd_subnetdb.c:252(create_subnets) Aug 28 09:02:02 volumio4 nmbd[1095]: NOTE: NetBIOS name resolution is not supported for Internet Protocol Version 6 (IPv6). Aug 28 09:02:03 volumio4 wireless.js[785]: WIRELESS.JS - INFO: Single Network Mode enabled (default) - only one network device can be active at a time between ethernet and wireless Aug 28 09:02:03 volumio4 ntpd[1021]: DNS: dns_probe: 1.debian.pool.ntp.org, cast_flags:8, flags:101 Aug 28 09:02:03 volumio4 ntpd[1021]: DNS: dns_check: processing 1.debian.pool.ntp.org, 8, 101 Aug 28 09:02:03 volumio4 ntpd[1021]: DNS: dns_check: DNS error: -11, System error Aug 28 09:02:03 volumio4 ntpd[1021]: DNS: dns_take_status: 1.debian.pool.ntp.org=>error, 12 Aug 28 09:02:03 volumio4 wireless.js[785]: WIRELESS.JS - INFO: Wireless.js initializing wireless flow Aug 28 09:02:03 volumio4 sudo[1117]: root : PWD=/ ; USER=root ; COMMAND=/sbin/ip addr flush dev wlan0 Aug 28 09:02:03 volumio4 sudo[1117]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Aug 28 09:02:03 volumio4 sudo[1117]: pam_unix(sudo:session): session closed for user root Aug 28 09:02:03 volumio4 sudo[1119]: root : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 down Aug 28 09:02:03 volumio4 sudo[1119]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Aug 28 09:02:03 volumio4 systemd[1]: systemd-rfkill.service: Deactivated successfully. Aug 28 09:02:03 volumio4 sudo[1119]: pam_unix(sudo:session): session closed for user root Aug 28 09:02:03 volumio4 wireless.js[785]: WIRELESS.JS - INFO: Cleaning previous... Aug 28 09:02:04 volumio4 sudo[1128]: root : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 up Aug 28 09:02:04 volumio4 sudo[1128]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Aug 28 09:02:04 volumio4 kernel: brcmfmac: brcmf_cfg80211_set_power_mgmt: power save disabled Aug 28 09:02:04 volumio4 sudo[1128]: pam_unix(sudo:session): session closed for user root Aug 28 09:02:04 volumio4 wireless.js[785]: WIRELESS.JS - INFO: InterfaceValidator: READY - wlan0 is ready for operations Aug 28 09:02:04 volumio4 wireless.js[785]: WIRELESS.JS - INFO: InterfaceValidator: wlan0 became ready after 3ms Aug 28 09:02:04 volumio4 wireless.js[785]: WIRELESS.JS - INFO: ensureInterfaceReady: Interface ready (MAC: d8:3a:dd:65:57:1d) Aug 28 09:02:04 volumio4 ntpd[1021]: DNS: dns_probe: 2.debian.pool.ntp.org, cast_flags:8, flags:101 Aug 28 09:02:04 volumio4 ntpd[1021]: DNS: dns_check: processing 2.debian.pool.ntp.org, 8, 101 Aug 28 09:02:04 volumio4 ntpd[1021]: DNS: dns_check: DNS error: -11, System error Aug 28 09:02:04 volumio4 ntpd[1021]: DNS: dns_take_status: 2.debian.pool.ntp.org=>error, 12 Aug 28 09:02:04 volumio4 sudo[1136]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iw reg get Aug 28 09:02:04 volumio4 sudo[1136]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 09:02:04 volumio4 sudo[1136]: pam_unix(sudo:session): session closed for user root Aug 28 09:02:04 volumio4 sudo[1144]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iw wlan0 scan Aug 28 09:02:04 volumio4 sudo[1144]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 09:02:04 volumio4 volumio-remote-updater[784]: [2026-08-28 09:02:04] [info] asio async_connect error: asio.system:111 (Connection refused) Aug 28 09:02:04 volumio4 volumio-remote-updater[784]: [2026-08-28 09:02:04] [info] Error getting remote endpoint: asio.system:107 (Transport endpoint is not connected) Aug 28 09:02:04 volumio4 volumio-remote-updater[784]: [2026-08-28 09:02:04] [error] handle_connect error: Connection refused Aug 28 09:02:05 volumio4 ntpd[1021]: DNS: dns_probe: 3.debian.pool.ntp.org, cast_flags:8, flags:101 Aug 28 09:02:05 volumio4 ntpd[1021]: DNS: dns_check: processing 3.debian.pool.ntp.org, 8, 101 Aug 28 09:02:05 volumio4 ntpd[1021]: DNS: dns_check: DNS error: -11, System error Aug 28 09:02:05 volumio4 ntpd[1021]: DNS: dns_take_status: 3.debian.pool.ntp.org=>error, 12 Aug 28 09:02:07 volumio4 sudo[1144]: pam_unix(sudo:session): session closed for user root Aug 28 09:02:07 volumio4 wireless.js[785]: WIRELESS.JS - INFO: SETTING APPROPRIATE REG DOMAIN: US Aug 28 09:02:07 volumio4 sudo[1169]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iw reg set US Aug 28 09:02:07 volumio4 sudo[1169]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 09:02:07 volumio4 sudo[1169]: pam_unix(sudo:session): session closed for user root Aug 28 09:02:07 volumio4 wireless.js[785]: WIRELESS.JS - INFO: SUCCESSFULLY SET NEW REGDOMAIN: US Aug 28 09:02:07 volumio4 wireless.js[785]: WIRELESS.JS - INFO: Start wireless flow Aug 28 09:02:07 volumio4 wireless.js[785]: WIRELESS.JS - INFO: Stopped hotspot (if there).. Aug 28 09:02:07 volumio4 sudo[1177]: root : PWD=/ ; USER=root ; COMMAND=/sbin/ip addr flush dev wlan0 Aug 28 09:02:07 volumio4 sudo[1177]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Aug 28 09:02:07 volumio4 sudo[1177]: pam_unix(sudo:session): session closed for user root Aug 28 09:02:07 volumio4 sudo[1179]: root : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 down Aug 28 09:02:07 volumio4 sudo[1179]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Aug 28 09:02:07 volumio4 sudo[1179]: pam_unix(sudo:session): session closed for user root Aug 28 09:02:07 volumio4 wireless.js[785]: WIRELESS.JS - INFO: InterfaceValidator: READY - wlan0 is ready for operations Aug 28 09:02:07 volumio4 wireless.js[785]: WIRELESS.JS - INFO: STAGE 1: wlan0 validated and ready (MAC: d8:3a:dd:65:57:1d, USB: false) Aug 28 09:02:07 volumio4 bash[1006]: setdatetime-helper: all HTTPS Date fallbacks failed Aug 28 09:02:07 volumio4 systemd[1]: setdatetime-helper.service: Deactivated successfully. Aug 28 09:02:07 volumio4 systemd[1]: Finished setdatetime-helper.service - Time Synchronization Helper Service. Aug 28 09:02:07 volumio4 wpa_supplicant[1186]: Successfully initialized wpa_supplicant Aug 28 09:02:07 volumio4 kernel: brcmfmac: brcmf_cfg80211_set_power_mgmt: power save disabled Aug 28 09:02:08 volumio4 wpa_supplicant[1186]: nl80211: kernel reports: Registration to specific type not supported Aug 28 09:02:08 volumio4 sudo[1192]: root : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 up Aug 28 09:02:08 volumio4 sudo[1192]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Aug 28 09:02:08 volumio4 sudo[1192]: pam_unix(sudo:session): session closed for user root Aug 28 09:02:09 volumio4 wireless.js[785]: WIRELESS.JS - INFO: DHCP IP fallback Aug 28 09:02:09 volumio4 wireless.js[785]: WIRELESS.JS - INFO: STAGE 2: Starting event-driven WPA state monitor Aug 28 09:02:09 volumio4 wireless.js[785]: WIRELESS.JS - INFO: WpaStateMachine: Starting state monitor for wlan0 Aug 28 09:02:09 volumio4 wireless.js[785]: WIRELESS.JS - INFO: WpaStateMachine: State transition: NULL -> SCANNING (duration: 0ms) Aug 28 09:02:10 volumio4 wpa_supplicant[1189]: wlan0: Trying to associate with 04:42:1a:d9:d2:04 (SSID='Giggleswick_5G' freq=5220 MHz) Aug 28 09:02:11 volumio4 wpa_supplicant[1189]: wlan0: Associated with 04:42:1a:d9:d2:04 Aug 28 09:02:11 volumio4 wpa_supplicant[1189]: wlan0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0 Aug 28 09:02:11 volumio4 wpa_supplicant[1189]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=COUNTRY_IE type=COUNTRY alpha2=US Aug 28 09:02:11 volumio4 wpa_supplicant[1189]: wlan0: WPA: Key negotiation completed with 04:42:1a:d9:d2:04 [PTK=CCMP GTK=CCMP] Aug 28 09:02:11 volumio4 wpa_supplicant[1189]: wlan0: CTRL-EVENT-CONNECTED - Connection to 04:42:1a:d9:d2:04 completed [id=0 id_str=] Aug 28 09:02:11 volumio4 dhcpcd[814]: wlan0: carrier acquired Aug 28 09:02:11 volumio4 dhcpcd[814]: wlan0: connected to Access Point: Giggleswick_5G Aug 28 09:02:11 volumio4 dhcpcd[814]: wlan0: IAID dd:65:57:1d Aug 28 09:02:11 volumio4 dhcpcd[814]: wlan0: adding address fe80::98e0:1cac:24ce:1e66 Aug 28 09:02:11 volumio4 dhcpcd[814]: ipv6_addaddr1: Permission denied Aug 28 09:02:11 volumio4 wireless.js[785]: WIRELESS.JS - INFO: WpaStateMachine: State transition: SCANNING -> COMPLETED (duration: 1526ms) Aug 28 09:02:11 volumio4 wireless.js[785]: WIRELESS.JS - INFO: WpaStateMachine: COMPLETED - connection successful Aug 28 09:02:11 volumio4 wireless.js[785]: WIRELESS.JS - INFO: STAGE 2: Connection successful - Connected to 04:42:1a:d9:d2:04 Aug 28 09:02:11 volumio4 wireless.js[785]: WIRELESS.JS - INFO: Onboard WiFi adapter detected, using standard dhcpcd flow Aug 28 09:02:12 volumio4 dhcpcd[814]: wlan0: soliciting an IPv6 router Aug 28 09:02:12 volumio4 volumio-remote-updater[784]: [2026-08-28 09:02:12] [info] asio async_connect error: asio.system:111 (Connection refused) Aug 28 09:02:12 volumio4 volumio-remote-updater[784]: [2026-08-28 09:02:12] [info] Error getting remote endpoint: asio.system:107 (Transport endpoint is not connected) Aug 28 09:02:12 volumio4 volumio-remote-updater[784]: [2026-08-28 09:02:12] [error] handle_connect error: Connection refused Aug 28 09:02:12 volumio4 sudo[1217]: root : PWD=/ ; USER=root ; COMMAND=/sbin/dhcpcd wlan0 Aug 28 09:02:12 volumio4 sudo[1217]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Aug 28 09:02:12 volumio4 dhcpcd[814]: control command: /sbin/dhcpcd wlan0 Aug 28 09:02:12 volumio4 dhcpcd[814]: control_free: No such file or directory Aug 28 09:02:12 volumio4 sudo[1217]: pam_unix(sudo:session): session closed for user root Aug 28 09:02:12 volumio4 dhcpcd[814]: wlan0: rebinding lease of 192.168.1.146 Aug 28 09:02:13 volumio4 dhcpcd[814]: wlan0: probing address 192.168.1.146/24 Aug 28 09:02:14 volumio4 wireless.js[785]: WIRELESS.JS - INFO: Start ap Aug 28 09:02:14 volumio4 wireless.js[785]: WIRELESS.JS - INFO: Notified systemd about wireless ready Aug 28 09:02:14 volumio4 kernel: brcmfmac: brcmf_cfg80211_set_power_mgmt: power save disabled Aug 28 09:02:14 volumio4 systemd[1]: Started wireless.service - Wireless Services. Aug 28 09:02:14 volumio4 systemd[1]: Started volumio.service - Volumio Backend Module. Aug 28 09:02:14 volumio4 systemd[1]: Starting plymouth-quit.service - Terminate Plymouth Boot Screen... Aug 28 09:02:14 volumio4 systemd[1]: Started volumio_cpu_tweak.service - Volumio Cpu Tweaker. Aug 28 09:02:14 volumio4 systemd[1]: Received SIGRTMIN+21 from PID 331 (plymouthd). Aug 28 09:02:14 volumio4 systemd[1]: Received SIGRTMIN+21 from PID 331 (plymouthd). Aug 28 09:02:14 volumio4 volumio-cpu-tweak[1229]: Setting RT Priority for mpd Aug 28 09:02:14 volumio4 systemd[1]: Finished plymouth-quit-wait.service - Hold until boot process finishes up. Aug 28 09:02:14 volumio4 systemd[1]: Finished plymouth-quit.service - Terminate Plymouth Boot Screen. Aug 28 09:02:14 volumio4 volumio-cpu-tweak[1243]: pid 35's current scheduling policy: SCHED_OTHER Aug 28 09:02:14 volumio4 volumio-cpu-tweak[1243]: pid 35's current scheduling priority: 0 Aug 28 09:02:14 volumio4 volumio-cpu-tweak[1229]: Setting MPD Affinity Aug 28 09:02:14 volumio4 volumio-cpu-tweak[1244]: pid 3's current affinity mask: f Aug 28 09:02:14 volumio4 volumio-cpu-tweak[1229]: /bin/volumio_cpu_tweak: line 27: warning: command substitution: ignored null byte in input Aug 28 09:02:14 volumio4 volumio-cpu-tweak[1229]: VOLUMIO CPU TWEAK: Setting CPU Governor: performance Aug 28 09:02:14 volumio4 systemd[1]: Started getty@tty1.service - Getty on tty1. Aug 28 09:02:14 volumio4 systemd[1]: Reached target getty.target - Login Prompts. Aug 28 09:02:14 volumio4 systemd[1]: volumio_cpu_tweak.service: Deactivated successfully. Aug 28 09:02:15 volumio4 systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 1. Aug 28 09:02:15 volumio4 systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Aug 28 09:02:15 volumio4 systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Aug 28 09:02:15 volumio4 upmpdcli[1249]: Could not open config: /tmp/upmpdcli.conf Aug 28 09:02:15 volumio4 systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Aug 28 09:02:15 volumio4 systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Aug 28 09:02:15 volumio4 wireless.js[785]: WIRELESS.JS - INFO: trying... Aug 28 09:02:15 volumio4 sudo[1261]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Aug 28 09:02:15 volumio4 sudo[1261]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 09:02:15 volumio4 sudo[1261]: pam_unix(sudo:session): session closed for user root Aug 28 09:02:15 volumio4 sudo[1264]: root : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Aug 28 09:02:15 volumio4 sudo[1264]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Aug 28 09:02:15 volumio4 sudo[1264]: pam_unix(sudo:session): session closed for user root Aug 28 09:02:15 volumio4 wireless.js[785]: WIRELESS.JS - INFO: ... wlan0 IPv4 is undefined, ipV6 is undefined Aug 28 09:02:16 volumio4 wireless.js[785]: WIRELESS.JS - INFO: trying... Aug 28 09:02:16 volumio4 sudo[1275]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Aug 28 09:02:16 volumio4 sudo[1275]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 09:02:16 volumio4 sudo[1275]: pam_unix(sudo:session): session closed for user root Aug 28 09:02:16 volumio4 sudo[1280]: root : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Aug 28 09:02:16 volumio4 sudo[1280]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Aug 28 09:02:16 volumio4 sudo[1280]: pam_unix(sudo:session): session closed for user root Aug 28 09:02:16 volumio4 wireless.js[785]: WIRELESS.JS - INFO: ... wlan0 IPv4 is undefined, ipV6 is undefined Aug 28 09:02:17 volumio4 volumio[1227]: info: ------------------------------------------- Aug 28 09:02:17 volumio4 volumio[1227]: info: ----- Volumio3 ---- Aug 28 09:02:17 volumio4 volumio[1227]: info: ------------------------------------------- Aug 28 09:02:17 volumio4 volumio[1227]: info: ----- System startup ---- Aug 28 09:02:17 volumio4 volumio[1227]: info: ------------------------------------------- Aug 28 09:02:17 volumio4 wireless.js[785]: WIRELESS.JS - INFO: WARNING: dhcpcd running but no IP assigned yet Aug 28 09:02:17 volumio4 wireless.js[785]: WIRELESS.JS - INFO: trying... Aug 28 09:02:17 volumio4 sudo[1302]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Aug 28 09:02:17 volumio4 sudo[1302]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 09:02:17 volumio4 sudo[1302]: pam_unix(sudo:session): session closed for user root Aug 28 09:02:17 volumio4 sudo[1305]: root : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Aug 28 09:02:17 volumio4 sudo[1305]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Aug 28 09:02:17 volumio4 sudo[1305]: pam_unix(sudo:session): session closed for user root Aug 28 09:02:17 volumio4 wireless.js[785]: WIRELESS.JS - INFO: ... wlan0 IPv4 is undefined, ipV6 is undefined Aug 28 09:02:17 volumio4 dhcpcd[814]: wlan0: leased 192.168.1.146 for 86400 seconds Aug 28 09:02:17 volumio4 dhcpcd[814]: wlan0: adding route to 192.168.1.0/24 Aug 28 09:02:17 volumio4 avahi-daemon[769]: Joining mDNS multicast group on interface wlan0.IPv4 with address 192.168.1.146. Aug 28 09:02:17 volumio4 avahi-daemon[769]: New relevant interface wlan0.IPv4 for mDNS. Aug 28 09:02:17 volumio4 avahi-daemon[769]: Registering new address record for 192.168.1.146 on wlan0.IPv4. Aug 28 09:02:17 volumio4 dhcpcd[814]: wlan0: adding default route via 192.168.1.1 Aug 28 09:02:18 volumio4 systemd[1]: welcome.service: Deactivated successfully. Aug 28 09:02:18 volumio4 systemd[1]: Stopped welcome.service - Show a welcome message on console. Aug 28 09:02:18 volumio4 systemd[1]: Stopping welcome.service - Show a welcome message on console... Aug 28 09:02:18 volumio4 volumio[1227]: info: MYVOLUMIO Environment detected Aug 28 09:02:18 volumio4 systemd[1]: Starting welcome.service - Show a welcome message on console... Aug 28 09:02:18 volumio4 welcome[1321]: Resolved ip:[1] 192.168.1.146 Aug 28 09:02:18 volumio4 systemd[1]: Finished welcome.service - Show a welcome message on console. Aug 28 09:02:18 volumio4 systemd[1]: Reached target ip-changed@wlan0.target - IP Address changed on wlan0. Aug 28 09:02:18 volumio4 systemd[1]: Started nmbd.service - Samba NMB Daemon. Aug 28 09:02:18 volumio4 volumio[1227]: info: Plugin folders cleanup Aug 28 09:02:18 volumio4 volumio[1227]: info: Scanning into folder /volumio/app/plugins/ Aug 28 09:02:18 volumio4 volumio[1227]: info: Scanning category audio_interface Aug 28 09:02:18 volumio4 systemd[1]: Starting winbind.service - Samba Winbind Daemon... Aug 28 09:02:18 volumio4 volumio[1227]: info: Scanning category miscellanea Aug 28 09:02:18 volumio4 volumio[1227]: info: Scanning category music_service Aug 28 09:02:18 volumio4 volumio[1227]: info: Scanning category plugins.json Aug 28 09:02:18 volumio4 volumio[1227]: info: Scanning category system_controller Aug 28 09:02:18 volumio4 volumio[1227]: info: Scanning category user_interface Aug 28 09:02:18 volumio4 volumio[1227]: info: Scanning into folder /data/plugins/ Aug 28 09:02:18 volumio4 volumio[1227]: info: Scanning category music_service Aug 28 09:02:18 volumio4 volumio[1227]: info: Scanning category user_interface Aug 28 09:02:18 volumio4 volumio[1227]: info: Plugin folders cleanup completed Aug 28 09:02:18 volumio4 volumio[1227]: info: ------------------------------------------- Aug 28 09:02:18 volumio4 volumio[1227]: info: ----- Core plugins startup ---- Aug 28 09:02:18 volumio4 volumio[1227]: info: ------------------------------------------- Aug 28 09:02:18 volumio4 volumio[1227]: info: Loading plugins from folder /volumio/app/plugins/ Aug 28 09:02:18 volumio4 volumio[1227]: info: Adding plugin upnp to MyMusic Plugins Aug 28 09:02:18 volumio4 volumio[1227]: info: Adding plugin airplay_emulation to MyMusic Plugins Aug 28 09:02:18 volumio4 volumio[1227]: info: Adding plugin upnp_browser to MyMusic Plugins Aug 28 09:02:18 volumio4 volumio[1227]: info: Loading plugins from folder /data/plugins/ Aug 28 09:02:18 volumio4 volumio[1227]: info: Loading plugin "system"... Aug 28 09:02:18 volumio4 volumio[1227]: info: Loading plugin "appearance"... Aug 28 09:02:18 volumio4 wireless.js[785]: WIRELESS.JS - INFO: trying... Aug 28 09:02:18 volumio4 winbindd[1338]: [2026/08/28 09:02:18.586786, 0] ../../source3/winbindd/winbindd.c:1440(main) Aug 28 09:02:18 volumio4 winbindd[1338]: winbindd version 4.17.8-Raspbian started. Aug 28 09:02:18 volumio4 winbindd[1338]: Copyright Andrew Tridgell and the Samba Team 1992-2022 Aug 28 09:02:18 volumio4 winbindd[1338]: [2026/08/28 09:02:18.600980, 0] ../../source3/winbindd/winbindd_cache.c:3116(initialize_winbindd_cache) Aug 28 09:02:18 volumio4 winbindd[1338]: initialize_winbindd_cache: clearing cache and re-creating with version number 2 Aug 28 09:02:18 volumio4 systemd[1]: Started winbind.service - Samba Winbind Daemon. Aug 28 09:02:18 volumio4 systemd[1]: Starting smbd.service - Samba SMB Daemon... Aug 28 09:02:18 volumio4 sudo[1356]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Aug 28 09:02:18 volumio4 sudo[1356]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 09:02:18 volumio4 sudo[1356]: pam_unix(sudo:session): session closed for user root Aug 28 09:02:18 volumio4 sudo[1360]: root : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Aug 28 09:02:18 volumio4 sudo[1360]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Aug 28 09:02:18 volumio4 sudo[1360]: pam_unix(sudo:session): session closed for user root Aug 28 09:02:18 volumio4 wireless.js[785]: WIRELESS.JS - INFO: ... wlan0 IPv4 is 192.168.1.146, ipV6 is undefined Aug 28 09:02:18 volumio4 wireless.js[785]: WIRELESS.JS - INFO: Connected to SSID: Giggleswick_5G Aug 28 09:02:18 volumio4 wireless.js[785]: WIRELESS.JS - INFO: It's done! AP Aug 28 09:02:18 volumio4 wireless.js[785]: WIRELESS.JS - INFO: Restarting avahi-daemon... Aug 28 09:02:18 volumio4 sudo[1366]: root : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart avahi-daemon Aug 28 09:02:18 volumio4 sudo[1366]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Aug 28 09:02:18 volumio4 systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Aug 28 09:02:18 volumio4 systemd[1]: shairport-sync.service: Deactivated successfully. Aug 28 09:02:18 volumio4 systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 28 09:02:18 volumio4 systemd[1]: shairport-sync.service: Consumed 1.593s CPU time. Aug 28 09:02:18 volumio4 avahi-daemon[769]: Got SIGTERM, quitting. Aug 28 09:02:18 volumio4 avahi-daemon[769]: Leaving mDNS multicast group on interface wlan0.IPv4 with address 192.168.1.146. Aug 28 09:02:18 volumio4 avahi-daemon[769]: Leaving mDNS multicast group on interface lo.IPv4 with address 127.0.0.1. Aug 28 09:02:18 volumio4 systemd[1]: Stopping avahi-daemon.service - Avahi mDNS/DNS-SD Stack... Aug 28 09:02:18 volumio4 avahi-daemon[769]: avahi-daemon 0.8 exiting. Aug 28 09:02:18 volumio4 systemd[1]: avahi-daemon.service: Deactivated successfully. Aug 28 09:02:18 volumio4 systemd[1]: Stopped avahi-daemon.service - Avahi mDNS/DNS-SD Stack. Aug 28 09:02:18 volumio4 systemd[1]: Starting avahi-daemon.service - Avahi mDNS/DNS-SD Stack... Aug 28 09:02:18 volumio4 avahi-daemon[1379]: Process 769 died: No such process; trying to remove PID file. (/run/avahi-daemon//pid) Aug 28 09:02:18 volumio4 avahi-daemon[1379]: Found user 'avahi' (UID 103) and group 'avahi' (GID 109). Aug 28 09:02:18 volumio4 avahi-daemon[1379]: Successfully dropped root privileges. Aug 28 09:02:18 volumio4 avahi-daemon[1379]: avahi-daemon 0.8 starting up. Aug 28 09:02:19 volumio4 avahi-daemon[1379]: Successfully called chroot(). Aug 28 09:02:19 volumio4 avahi-daemon[1379]: Successfully dropped remaining capabilities. Aug 28 09:02:19 volumio4 systemd[1]: Started avahi-daemon.service - Avahi mDNS/DNS-SD Stack. Aug 28 09:02:19 volumio4 avahi-daemon[1379]: Loading service file /services/volumio.service. Aug 28 09:02:19 volumio4 avahi-daemon[1379]: Joining mDNS multicast group on interface wlan0.IPv4 with address 192.168.1.146. Aug 28 09:02:19 volumio4 avahi-daemon[1379]: New relevant interface wlan0.IPv4 for mDNS. Aug 28 09:02:19 volumio4 avahi-daemon[1379]: Joining mDNS multicast group on interface lo.IPv4 with address 127.0.0.1. Aug 28 09:02:19 volumio4 systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 28 09:02:19 volumio4 avahi-daemon[1379]: New relevant interface lo.IPv4 for mDNS. Aug 28 09:02:19 volumio4 avahi-daemon[1379]: Network interface enumeration completed. Aug 28 09:02:19 volumio4 avahi-daemon[1379]: Registering new address record for 192.168.1.146 on wlan0.IPv4. Aug 28 09:02:19 volumio4 avahi-daemon[1379]: Registering new address record for 127.0.0.1 on lo.IPv4. Aug 28 09:02:19 volumio4 sudo[1366]: pam_unix(sudo:session): session closed for user root Aug 28 09:02:19 volumio4 ntpd[1021]: IO: Listen normally on 3 wlan0 192.168.1.146:123 Aug 28 09:02:19 volumio4 ntpd[1021]: IO: new interface(s) found: waking up resolver Aug 28 09:02:19 volumio4 ntpd[1021]: DNS: dns_probe: 3.debian.pool.ntp.org, cast_flags:8, flags:101 Aug 28 09:02:19 volumio4 smbd[1378]: [2026/08/28 09:02:19.179173, 0] ../../source3/smbd/server.c:1741(main) Aug 28 09:02:19 volumio4 smbd[1378]: smbd version 4.17.8-Raspbian started. Aug 28 09:02:19 volumio4 smbd[1378]: Copyright Andrew Tridgell and the Samba Team 1992-2022 Aug 28 09:02:19 volumio4 wireless.js[785]: WIRELESS.JS - INFO: Notified systemd about wireless ready Aug 28 09:02:19 volumio4 avahi-daemon[1379]: Server startup complete. Host name is volumio4.local. Local service cookie is 3070660084. Aug 28 09:02:20 volumio4 avahi-daemon[1379]: Service "Volumio4" (/services/volumio.service) successfully established. Aug 28 09:02:20 volumio4 systemd[1]: Started smbd.service - Samba SMB Daemon. Aug 28 09:02:20 volumio4 systemd[1]: Reached target multi-user.target - Multi-User System. Aug 28 09:02:20 volumio4 systemd[1]: Reached target graphical.target - Graphical Interface. Aug 28 09:02:20 volumio4 systemd[1]: Starting systemd-update-utmp-runlevel.service - Record Runlevel Change in UTMP... Aug 28 09:02:20 volumio4 systemd[1]: systemd-update-utmp-runlevel.service: Deactivated successfully. Aug 28 09:02:20 volumio4 systemd[1]: Finished systemd-update-utmp-runlevel.service - Record Runlevel Change in UTMP. Aug 28 09:02:20 volumio4 systemd[1]: Startup finished in 13.494s (kernel) + 24.996s (userspace) = 38.490s. Aug 28 09:02:21 volumio4 volumio[1227]: info: Loading plugin "network"... Aug 28 09:02:21 volumio4 volumio[1227]: info: Refreshing Cached IP Addresses Aug 28 09:02:21 volumio4 sudo[1413]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Aug 28 09:02:21 volumio4 sudo[1413]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 09:02:21 volumio4 sudo[1413]: pam_unix(sudo:session): session closed for user root Aug 28 09:02:21 volumio4 volumio[1227]: info: Loading plugin "services"... Aug 28 09:02:21 volumio4 volumio[1227]: info: Loading plugin "volumio5onboarding"... Aug 28 09:02:21 volumio4 sudo[1415]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Aug 28 09:02:21 volumio4 sudo[1415]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 09:02:21 volumio4 sudo[1423]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Aug 28 09:02:21 volumio4 sudo[1415]: pam_unix(sudo:session): session closed for user root Aug 28 09:02:21 volumio4 sudo[1423]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 09:02:21 volumio4 volumio[1227]: info: Loading plugin "alsa_controller"... Aug 28 09:02:21 volumio4 volumio[1227]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 28 09:02:21 volumio4 volumio[1227]: info: Loading plugin "wizard"... Aug 28 09:02:21 volumio4 volumio[1227]: info: Loading plugin "networkfs"... Aug 28 09:02:21 volumio4 volumio[1227]: info: Starting Udev Watcher for removable devices Aug 28 09:02:21 volumio4 sudo[1448]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=admin,password=j0ul3y2a!,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft,vers=3.11 //192.168.1.10/Gunginr_Music /mnt/NAS/Gungnir Aug 28 09:02:21 volumio4 sudo[1448]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 09:02:21 volumio4 volumio[1227]: info: Ignoring mount for partition: boot Aug 28 09:02:21 volumio4 volumio[1227]: info: Ignoring mount for partition: volumio Aug 28 09:02:21 volumio4 volumio[1227]: info: Ignoring mount for partition: volumio_data Aug 28 09:02:21 volumio4 volumio[1227]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Aug 28 09:02:21 volumio4 volumio[1227]: info: Loading plugin "volumio_command_line_client"... Aug 28 09:02:21 volumio4 sudo[1449]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=admin,password=j0ul3y2a!,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft,vers=3.11 '//192.168.1.10/Jimmy/iTunes Media/Music' /mnt/NAS/Jimmy Aug 28 09:02:21 volumio4 volumio[1227]: info: Loading plugin "upnp"... Aug 28 09:02:21 volumio4 sudo[1449]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 09:02:21 volumio4 volumio[1227]: info: [1787922141649] Starting Upmpd Daemon Aug 28 09:02:21 volumio4 volumio[1227]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Aug 28 09:02:21 volumio4 volumio[1227]: info: Loading plugin "my_music"... Aug 28 09:02:21 volumio4 volumio[1227]: info: Loading plugin "mpd"... Aug 28 09:02:21 volumio4 kernel: netfs: FS-Cache loaded Aug 28 09:02:21 volumio4 kernel: Key type cifs.spnego registered Aug 28 09:02:21 volumio4 kernel: Key type cifs.idmap registered Aug 28 09:02:21 volumio4 kernel: CIFS: Attempting to mount //192.168.1.10/Jimmy/iTunes Media/Music Aug 28 09:02:22 volumio4 volumio[1227]: info: Loading plugin "upnp_browser"... Aug 28 09:02:22 volumio4 volumio-remote-updater[784]: [2026-08-28 09:02:22] [connect] Successful connection Aug 28 09:02:22 volumio4 sudo[1449]: pam_unix(sudo:session): session closed for user root Aug 28 09:02:22 volumio4 kernel: CIFS: Attempting to mount //192.168.1.10/Gunginr_Music Aug 28 09:02:23 volumio4 sudo[1448]: pam_unix(sudo:session): session closed for user root Aug 28 09:02:23 volumio4 volumio[1227]: info: Starting UPNP Browser Aug 28 09:02:23 volumio4 volumio[1227]: info: Loading plugin "alarm-clock"... Aug 28 09:02:23 volumio4 volumio[1227]: info: Loading plugin "airplay_emulation"... Aug 28 09:02:23 volumio4 volumio[1227]: info: Starting Shairport Sync Aug 28 09:02:23 volumio4 volumio[1227]: info: Loading plugin "last_100"... Aug 28 09:02:23 volumio4 volumio[1227]: info: Loading plugin "webradio"... Aug 28 09:02:23 volumio4 volumio[1227]: info: Loading plugin "i2s_dacs"... Aug 28 09:02:23 volumio4 volumio[1227]: info: I2S DAC not set, start Auto-detection Aug 28 09:02:23 volumio4 volumio[1227]: info: Loading plugin "volumiodiscovery"... Aug 28 09:02:23 volumio4 volumio[1227]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Aug 28 09:02:23 volumio4 node[1227]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Aug 28 09:02:23 volumio4 volumio[1227]: *** WARNING *** Please fix your application to use the native API of Avahi! Aug 28 09:02:23 volumio4 node[1227]: *** WARNING *** Please fix your application to use the native API of Avahi! Aug 28 09:02:23 volumio4 volumio[1227]: *** WARNING *** For more information see Aug 28 09:02:23 volumio4 node[1227]: *** WARNING *** For more information see Aug 28 09:02:23 volumio4 volumio[1227]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Aug 28 09:02:23 volumio4 node[1227]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Aug 28 09:02:23 volumio4 volumio[1227]: *** WARNING *** Please fix your application to use the native API of Avahi! Aug 28 09:02:23 volumio4 node[1227]: *** WARNING *** Please fix your application to use the native API of Avahi! Aug 28 09:02:23 volumio4 volumio[1227]: *** WARNING *** For more information see Aug 28 09:02:23 volumio4 node[1227]: *** WARNING *** For more information see Aug 28 09:02:23 volumio4 volumio[1227]: info: Applying required configuration parameters for plugin volumiodiscovery Aug 28 09:02:23 volumio4 volumio[1227]: info: Discovery: Started advertising with name: Volumio4 Aug 28 09:02:23 volumio4 volumio[1227]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Aug 28 09:02:23 volumio4 volumio[1227]: info: Plugin spotify-connect is not enabled Aug 28 09:02:23 volumio4 volumio[1227]: info: Loading plugin "outputs"... Aug 28 09:02:23 volumio4 volumio[1227]: info: Loading plugin "albumart"... Aug 28 09:02:23 volumio4 volumio[1227]: info: Plugin example_plugin is not enabled Aug 28 09:02:23 volumio4 volumio[1227]: info: Loading plugin "inputs"... Aug 28 09:02:23 volumio4 volumio[1227]: info: Loading plugin "updater_comm"... Aug 28 09:02:23 volumio4 volumio[1227]: info: Plugin mpdemulation is not enabled Aug 28 09:02:23 volumio4 volumio[1227]: info: Loading plugin "rest_api"... Aug 28 09:02:24 volumio4 volumio[1227]: info: Loading plugin "websocket"... Aug 28 09:02:24 volumio4 volumio[1227]: info: Starting Socket.io Server version 1.7.4 Aug 28 09:02:24 volumio4 volumio[1227]: info: Loading plugin "soloist_connect"... Aug 28 09:02:24 volumio4 volumio[1227]: info: Loading plugin "upc_search"... Aug 28 09:02:24 volumio4 volumio[1493]: Forking 3 albumart workers Aug 28 09:02:24 volumio4 ntpd[1021]: DNS: dns_check: processing 3.debian.pool.ntp.org, 8, 101 Aug 28 09:02:24 volumio4 ntpd[1021]: DNS: Pool taking: 198.12.95.197 Aug 28 09:02:24 volumio4 ntpd[1021]: DNS: Pool taking: 74.6.168.73 Aug 28 09:02:24 volumio4 ntpd[1021]: DNS: Pool taking: 172.233.155.39 Aug 28 09:02:24 volumio4 ntpd[1021]: DNS: Pool taking: 23.186.168.125 Aug 28 09:02:24 volumio4 ntpd[1021]: DNS: dns_take_status: 3.debian.pool.ntp.org=>good, 8 Aug 28 09:02:25 volumio4 ntpd[1021]: DNS: dns_probe: 2.debian.pool.ntp.org, cast_flags:8, flags:101 Aug 28 09:02:25 volumio4 sudo[1423]: pam_unix(sudo:session): session closed for user root Aug 28 09:02:25 volumio4 sshd[1401]: Accepted password for volumio from 192.168.1.170 port 52231 ssh2 Aug 28 09:02:25 volumio4 sshd[1401]: pam_unix(sshd:session): session opened for user volumio(uid=1000) by (uid=0) Aug 28 09:02:25 volumio4 systemd[1]: Created slice user-1000.slice - User Slice of UID 1000. Aug 28 09:02:25 volumio4 systemd[1]: Starting user-runtime-dir@1000.service - User Runtime Directory /run/user/1000... Aug 28 09:02:25 volumio4 systemd-logind[779]: New session 1 of user volumio. Aug 28 09:02:25 volumio4 systemd[1]: Finished user-runtime-dir@1000.service - User Runtime Directory /run/user/1000. Aug 28 09:02:25 volumio4 systemd[1]: Starting user@1000.service - User Manager for UID 1000... Aug 28 09:02:25 volumio4 (systemd)[1535]: pam_unix(systemd-user:session): session opened for user volumio(uid=1000) by (uid=0) Aug 28 09:02:26 volumio4 systemd[1535]: Queued start job for default target default.target. Aug 28 09:02:26 volumio4 systemd[1535]: Created slice app.slice - User Application Slice. Aug 28 09:02:26 volumio4 systemd[1535]: Reached target paths.target - Paths. Aug 28 09:02:26 volumio4 systemd[1535]: Reached target timers.target - Timers. Aug 28 09:02:26 volumio4 systemd[1535]: Listening on dirmngr.socket - GnuPG network certificate management daemon. Aug 28 09:02:26 volumio4 systemd[1535]: Listening on gpg-agent-browser.socket - GnuPG cryptographic agent and passphrase cache (access for web browsers). Aug 28 09:02:26 volumio4 systemd[1535]: Listening on gpg-agent-extra.socket - GnuPG cryptographic agent and passphrase cache (restricted). Aug 28 09:02:26 volumio4 systemd[1535]: Listening on gpg-agent-ssh.socket - GnuPG cryptographic agent (ssh-agent emulation). Aug 28 09:02:26 volumio4 systemd[1535]: Listening on gpg-agent.socket - GnuPG cryptographic agent and passphrase cache. Aug 28 09:02:26 volumio4 systemd[1535]: Reached target sockets.target - Sockets. Aug 28 09:02:26 volumio4 systemd[1535]: Reached target basic.target - Basic System. Aug 28 09:02:26 volumio4 systemd[1]: Started user@1000.service - User Manager for UID 1000. Aug 28 09:02:26 volumio4 systemd[1535]: Started mpris-proxy.service - Bluetooth mpris proxy. Aug 28 09:02:26 volumio4 systemd[1535]: Reached target default.target - Main User Target. Aug 28 09:02:26 volumio4 systemd[1535]: Startup finished in 701ms. Aug 28 09:02:26 volumio4 systemd[1]: Started session-1.scope - Session 1 of User volumio. Aug 28 09:02:26 volumio4 systemd[1535]: mpris-proxy.service: Main process exited, code=exited, status=1/FAILURE Aug 28 09:02:26 volumio4 mpris-proxy[1550]: Can't get on session bus Aug 28 09:02:26 volumio4 systemd[1535]: mpris-proxy.service: Failed with result 'exit-code'. Aug 28 09:02:26 volumio4 volumio[1505]: Starting albumart workers Aug 28 09:02:26 volumio4 volumio[1227]: info: Applying required configuration parameters for plugin upc_search Aug 28 09:02:26 volumio4 sshd[1401]: pam_env(sshd:session): deprecated reading of user environment enabled Aug 28 09:02:26 volumio4 volumio[1227]: info: Loading i18n strings for locale en Aug 28 09:02:26 volumio4 volumio[1227]: Updating browse sources language Aug 28 09:02:26 volumio4 volumio[1227]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 28 09:02:26 volumio4 volumio[1227]: debug: API:emitFavourites Aug 28 09:02:27 volumio4 volumio[1227]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 28 09:02:27 volumio4 volumio[1227]: info: CoreCommandRouter::initPlayerControls Aug 28 09:02:27 volumio4 volumio[1227]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 09:02:27 volumio4 volumio[1227]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 09:02:27 volumio4 volumio[1227]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 09:02:27 volumio4 volumio[1227]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 09:02:27 volumio4 volumio[1227]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 09:02:27 volumio4 volumio[1227]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 09:02:27 volumio4 volumio[1227]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 09:02:27 volumio4 volumio[1227]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 09:02:27 volumio4 volumio[1227]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 28 09:02:27 volumio4 volumio[1227]: Express server listening on port 3000 Aug 28 09:02:27 volumio4 volumio[1227]: [Metrics] WebUI: 11s 113.41ms Aug 28 09:02:27 volumio4 volumio[1227]: info: CoreStateMachine::resetVolumioState Aug 28 09:02:27 volumio4 volumio[1227]: info: CoreStateMachine::getcurrentVolume Aug 28 09:02:27 volumio4 volumio[1227]: info: CoreCommandRouter::volumioRetrievevolume Aug 28 09:02:27 volumio4 volumio[1227]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 09:02:27 volumio4 volumio[1227]: info: Volumio Network Manager: Network status updated: 2 Aug 28 09:02:27 volumio4 volumio[1227]: verbose: New Socket.io Connection to 192.168.1.146:3000 from 192.168.1.17 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 1 Aug 28 09:02:27 volumio4 systemd[1]: systemd-fsckd.service: Deactivated successfully. Aug 28 09:02:28 volumio4 volumio[1227]: verbose: New Socket.io Connection to 192.168.1.146 from 192.168.1.170 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/151.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 2 Aug 28 09:02:28 volumio4 volumio[1227]: info: Reloading queue from file Aug 28 09:02:28 volumio4 volumio[1227]: verbose: New Socket.io Connection to 192.168.1.146 from 192.168.1.170 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/151.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 3 Aug 28 09:02:28 volumio4 volumio[1227]: info: CoreStateMachine::setRepeat false single undefined Aug 28 09:02:28 volumio4 volumio[1227]: info: CoreStateMachine::pushState Aug 28 09:02:28 volumio4 volumio[1227]: debug: CoreStateMachine::getState Aug 28 09:02:28 volumio4 volumio[1227]: info: CorePlayQueue::getTrack 0 Aug 28 09:02:28 volumio4 volumio[1227]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 28 09:02:28 volumio4 volumio[1227]: info: CoreCommandRouter::volumioPushState Aug 28 09:02:28 volumio4 volumio[1227]: debug: API:pushState Aug 28 09:02:28 volumio4 volumio[1227]: debug: No callbacks for volumioPushState Aug 28 09:02:28 volumio4 volumio[1227]: info: CoreStateMachine::setRandom false Aug 28 09:02:28 volumio4 volumio[1227]: info: CoreStateMachine::pushState Aug 28 09:02:28 volumio4 volumio[1227]: debug: CoreStateMachine::getState Aug 28 09:02:28 volumio4 volumio[1227]: info: CorePlayQueue::getTrack 0 Aug 28 09:02:28 volumio4 volumio[1227]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 28 09:02:28 volumio4 volumio[1227]: info: CoreCommandRouter::volumioPushState Aug 28 09:02:28 volumio4 volumio[1227]: debug: API:pushState Aug 28 09:02:28 volumio4 volumio[1227]: debug: No callbacks for volumioPushState Aug 28 09:02:28 volumio4 volumio[1504]: Starting albumart workers Aug 28 09:02:28 volumio4 volumio[1227]: verbose: New Socket.io Connection to 192.168.1.146 from 192.168.1.170 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/151.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 4 Aug 28 09:02:28 volumio4 volumio[1227]: verbose: New Socket.io Connection to 192.168.1.146 from 192.168.1.170 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/151.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 5 Aug 28 09:02:28 volumio4 volumio[1227]: info: VolumeController:: Volume=50 Mute =false Aug 28 09:02:28 volumio4 volumio[1227]: debug: No callbacks for volumioupdatevolume Aug 28 09:02:28 volumio4 volumio[1227]: info: CoreStateMachine::pushState Aug 28 09:02:28 volumio4 volumio[1227]: debug: CoreStateMachine::getState Aug 28 09:02:28 volumio4 volumio[1227]: info: CorePlayQueue::getTrack 0 Aug 28 09:02:28 volumio4 volumio[1227]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 28 09:02:28 volumio4 volumio[1227]: info: CoreCommandRouter::volumioPushState Aug 28 09:02:28 volumio4 volumio[1227]: debug: API:pushState Aug 28 09:02:28 volumio4 volumio[1227]: debug: No callbacks for volumioPushState Aug 28 09:02:28 volumio4 volumio[1227]: info: CoreStateMachine::updateTrackBlock Aug 28 09:02:28 volumio4 volumio[1227]: info: CorePlayQueue::getTrackBlock Aug 28 09:02:28 volumio4 volumio[1227]: info: CoreCommandRouter::volumioRetrievevolume Aug 28 09:02:28 volumio4 volumio[1227]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Aug 28 09:02:28 volumio4 volumio[1227]: info: USB Boot Capable - System SBC Revision found in cpuinfo: c03115 Aug 28 09:02:28 volumio4 volumio[1227]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Aug 28 09:02:28 volumio4 volumio[1227]: info: Setting Device type: Raspberry PI Aug 28 09:02:28 volumio4 dhcpcd[685]: timed out Aug 28 09:02:28 volumio4 sh[674]: timed out Aug 28 09:02:28 volumio4 volumio[1227]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Aug 28 09:02:28 volumio4 dhcpcd[685]: dhcpcd exited Aug 28 09:02:28 volumio4 sh[674]: dhcpcd exited Aug 28 09:02:28 volumio4 volumio[1227]: verbose: New Socket.io Connection to 192.168.1.146 from 192.168.1.170 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/151.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 6 Aug 28 09:02:28 volumio4 volumio[1227]: info: VolumeController:: Volume=50 Mute =false Aug 28 09:02:28 volumio4 volumio[1227]: debug: No callbacks for volumioupdatevolume Aug 28 09:02:28 volumio4 volumio[1227]: info: CoreStateMachine::pushState Aug 28 09:02:28 volumio4 volumio[1227]: debug: CoreStateMachine::getState Aug 28 09:02:28 volumio4 volumio[1227]: info: CorePlayQueue::getTrack 0 Aug 28 09:02:28 volumio4 volumio[1227]: info: CoreCommandRouter::volumioPushState Aug 28 09:02:28 volumio4 volumio[1227]: debug: API:pushState Aug 28 09:02:28 volumio4 sh[637]: ifup: failed to bring up eth0 Aug 28 09:02:28 volumio4 systemd[1]: ifup@eth0.service: Main process exited, code=exited, status=1/FAILURE Aug 28 09:02:28 volumio4 systemd[1]: ifup@eth0.service: Failed with result 'exit-code'. Aug 28 09:02:28 volumio4 volumio[1227]: debug: No callbacks for volumioPushState Aug 28 09:02:28 volumio4 volumio[1227]: info: CoreCommandRouter::volumioGetVisibleSources Aug 28 09:02:28 volumio4 volumio[1227]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 28 09:02:28 volumio4 volumio[1227]: info: CoreCommandRouter::volumioGetState Aug 28 09:02:28 volumio4 volumio[1227]: debug: CoreStateMachine::getState Aug 28 09:02:28 volumio4 volumio[1227]: info: CorePlayQueue::getTrack 0 Aug 28 09:02:28 volumio4 volumio[1227]: info: CoreCommandRouter::volumioGetState Aug 28 09:02:28 volumio4 volumio[1227]: debug: CoreStateMachine::getState Aug 28 09:02:28 volumio4 volumio[1227]: info: CorePlayQueue::getTrack 0 Aug 28 09:02:28 volumio4 volumio[1227]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Aug 28 09:02:28 volumio4 volumio[1227]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Aug 28 09:02:28 volumio4 volumio[1227]: info: Received Get System Info Aug 28 09:02:28 volumio4 volumio[1227]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 28 09:02:28 volumio4 volumio[1227]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 28 09:02:29 volumio4 volumio[1227]: info: Discovery: Getting this device information Aug 28 09:02:29 volumio4 volumio[1227]: info: CoreCommandRouter::volumioGetState Aug 28 09:02:29 volumio4 volumio[1227]: debug: CoreStateMachine::getState Aug 28 09:02:29 volumio4 volumio[1227]: info: CorePlayQueue::getTrack 0 Aug 28 09:02:29 volumio4 volumio[1227]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 28 09:02:29 volumio4 volumio[1227]: info: CoreCommandRouter::volumioGetState Aug 28 09:02:29 volumio4 volumio[1227]: debug: CoreStateMachine::getState Aug 28 09:02:29 volumio4 volumio[1227]: info: CorePlayQueue::getTrack 0 Aug 28 09:02:29 volumio4 volumio[1227]: info: Listing playlists Aug 28 09:02:29 volumio4 volumio[1227]: verbose: New Socket.io Connection to 192.168.1.146:3000 from 192.168.1.17 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Aug 28 09:02:29 volumio4 volumio[1503]: Starting albumart workers Aug 28 09:02:29 volumio4 volumio[1227]: info: Completed loading Core Plugins Aug 28 09:02:29 volumio4 volumio[1227]: info: Preparing to generate the ALSA configuration file Aug 28 09:02:29 volumio4 volumio[1227]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , initSocket Aug 28 09:02:29 volumio4 volumio[1227]: info: Asound.conf file unchanged, so no further update is needed Aug 28 09:02:29 volumio4 volumio[1227]: info: Output device has changed, restarting MPD Aug 28 09:02:29 volumio4 sudo[1599]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Aug 28 09:02:29 volumio4 sudo[1599]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 09:02:29 volumio4 volumio[1227]: info: Output device has changed, restarting Shairport Sync Aug 28 09:02:29 volumio4 volumio[1227]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 09:02:29 volumio4 volumio[1227]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 09:02:29 volumio4 sudo[1599]: pam_unix(sudo:session): session closed for user root Aug 28 09:02:30 volumio4 sudo[1603]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Aug 28 09:02:30 volumio4 volumio[1227]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Aug 28 09:02:30 volumio4 volumio[1227]: info: ___________ START PLUGINS ___________ Aug 28 09:02:30 volumio4 sudo[1603]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 09:02:30 volumio4 volumio[1227]: info: ControllerMpd::onStart: Initializing MPD Aug 28 09:02:30 volumio4 volumio[1227]: info: Creating MPD Configuration file Aug 28 09:02:30 volumio4 sudo[1611]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Aug 28 09:02:30 volumio4 sudo[1611]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 09:02:30 volumio4 ntpd[1021]: DNS: dns_check: processing 2.debian.pool.ntp.org, 8, 101 Aug 28 09:02:30 volumio4 ntpd[1021]: DNS: Pool taking: 198.23.133.146 Aug 28 09:02:30 volumio4 ntpd[1021]: DNS: Pool taking: 45.63.54.13 Aug 28 09:02:30 volumio4 ntpd[1021]: DNS: Pool taking: 51.81.226.229 Aug 28 09:02:30 volumio4 ntpd[1021]: DNS: Pool taking: 144.86.176.12 Aug 28 09:02:30 volumio4 ntpd[1021]: DNS: Pool taking: 2606:8fc0::9 Aug 28 09:02:30 volumio4 ntpd[1021]: DNS: Pool taking: 2607:f1c0:f054:5e00::2 Aug 28 09:02:30 volumio4 ntpd[1021]: DNS: Pool taking: 2603:c020:0:8369:607:e532:d534:7109 Aug 28 09:02:30 volumio4 ntpd[1021]: DNS: Pool taking: 2602:fb95:16::123 Aug 28 09:02:30 volumio4 ntpd[1021]: DNS: dns_take_status: 2.debian.pool.ntp.org=>good, 8 Aug 28 09:02:30 volumio4 sudo[1608]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumio5-onboarding.service Aug 28 09:02:30 volumio4 sudo[1608]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 09:02:30 volumio4 volumio[1227]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 28 09:02:30 volumio4 volumio[1227]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 28 09:02:30 volumio4 volumio[1227]: info: [1787922150219] CoreMusicLibrary::Adding element Media Servers Aug 28 09:02:30 volumio4 volumio[1227]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 28 09:02:30 volumio4 volumio[1227]: debug: API:emitFavourites Aug 28 09:02:30 volumio4 sudo[1611]: pam_unix(sudo:session): session closed for user root Aug 28 09:02:30 volumio4 sudo[1615]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Aug 28 09:02:30 volumio4 sudo[1615]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 09:02:30 volumio4 volumio[1227]: info: UPNP Browser: Client initialized successfully Aug 28 09:02:30 volumio4 systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Aug 28 09:02:30 volumio4 systemd[1]: Starting mpd.service - Music Player Daemon... Aug 28 09:02:30 volumio4 volumio[1227]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 09:02:30 volumio4 volumio[1227]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 09:02:30 volumio4 systemd[1]: Started volumio5-onboarding.service - Volumio5 Onboarding Server. Aug 28 09:02:30 volumio4 systemd[1]: mpd.service: Deactivated successfully. Aug 28 09:02:30 volumio4 systemd[1]: Stopped mpd.service - Music Player Daemon. Aug 28 09:02:30 volumio4 systemd[1]: mpd.socket: Deactivated successfully. Aug 28 09:02:30 volumio4 sudo[1608]: pam_unix(sudo:session): session closed for user root Aug 28 09:02:30 volumio4 systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Aug 28 09:02:30 volumio4 systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Aug 28 09:02:30 volumio4 systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Aug 28 09:02:30 volumio4 systemd[1]: Starting mpd.service - Music Player Daemon... Aug 28 09:02:30 volumio4 systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 2. Aug 28 09:02:30 volumio4 systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Aug 28 09:02:30 volumio4 systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Aug 28 09:02:30 volumio4 sudo[1627]: volumio : TTY=pts/0 ; PWD=/home/volumio ; USER=root ; COMMAND=/bin/journalctl -f Aug 28 09:02:30 volumio4 sudo[1627]: pam_unix(sudo:session): session opened for user root(uid=0) by volumio(uid=1000) Aug 28 09:02:30 volumio4 volumio[1227]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Aug 28 09:02:30 volumio4 volumio[1227]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 09:02:30 volumio4 volumio[1227]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 09:02:30 volumio4 upmpdcli[1626]: Could not open config: /tmp/upmpdcli.conf Aug 28 09:02:30 volumio4 systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Aug 28 09:02:30 volumio4 systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Aug 28 09:02:30 volumio4 volumio[1227]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Aug 28 09:02:30 volumio4 volumio[1227]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 28 09:02:30 volumio4 volumio[1227]: info: [1787922150538] CoreMusicLibrary::Adding element Last_100 Aug 28 09:02:30 volumio4 volumio[1227]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 28 09:02:30 volumio4 volumio[1227]: debug: API:emitFavourites Aug 28 09:02:30 volumio4 volumio[1227]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 28 09:02:30 volumio4 volumio[1227]: info: [1787922150562] CoreMusicLibrary::Adding element Webradio Aug 28 09:02:30 volumio4 volumio[1227]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 28 09:02:30 volumio4 volumio[1227]: debug: API:emitFavourites Aug 28 09:02:30 volumio4 volumio[1227]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 28 09:02:30 volumio4 systemd[1]: systemd-hostnamed.service: Deactivated successfully. Aug 28 09:02:30 volumio4 volumio[1227]: info: Initializing BBC Radios Aug 28 09:02:30 volumio4 volumio[1227]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 28 09:02:30 volumio4 volumio[1227]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 09:02:31 volumio4 ntpd[1021]: DNS: dns_probe: 1.debian.pool.ntp.org, cast_flags:8, flags:101 Aug 28 09:02:31 volumio4 sudo[1625]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Aug 28 09:02:31 volumio4 sudo[1625]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Aug 28 09:02:31 volumio4 sudo[1664]: /bin/chown: cannot access '/var/log/mpd.log': No such file or directory Aug 28 09:02:31 volumio4 sudo[1625]: pam_unix(sudo:session): session closed for user root Aug 28 09:03:02 volumio4 ntpd[1021]: CLOCK: time stepped by 31.213585 Aug 28 09:03:02 volumio4 ntpd[1021]: INIT: MRU 13107 entries, 13 hash bits, 32768 bytes Aug 28 09:03:02 volumio4 volumio5-onboarding[1621]: time=2026-08-28T09:03:02.455-04:00 level=INFO msg="running volumio5-device-gateway" version=6370e0a8+CHANGES buildDate=2026-03-06T16:29:42Z Aug 28 09:03:02 volumio4 volumio[1227]: info: Adding user_interface/upc_search REST Endpoint for plugin: user_interface/upc_search Aug 28 09:03:02 volumio4 volumio[1227]: info: Volumio Calling Home Aug 28 09:03:04 volumio4 sudo[1686]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Aug 28 09:03:04 volumio4 sudo[1686]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 09:03:04 volumio4 sudo[1686]: pam_unix(sudo:session): session closed for user root Aug 28 09:03:04 volumio4 sudo[1689]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Aug 28 09:03:04 volumio4 sudo[1689]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 09:03:04 volumio4 sudo[1689]: pam_unix(sudo:session): session closed for user root Aug 28 09:03:04 volumio4 volumio[1227]: info: CoreCommandRouter::volumioGetState Aug 28 09:03:04 volumio4 volumio[1227]: debug: CoreStateMachine::getState Aug 28 09:03:04 volumio4 volumio[1227]: info: CorePlayQueue::getTrack 0 Aug 28 09:03:04 volumio4 volumio[1227]: info: CoreCommandRouter::executeOnPlugin: peppy_screensaver , soloistMeteringWanted Aug 28 09:03:04 volumio4 volumio[1227]: info: SoloistConnect: writeEnvFile cache_location="disk" cache_size_mb=1024 ceiling=945 -> ramMb=0 CACHE_SIZE=1024 Aug 28 09:03:04 volumio4 volumio[1227]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 09:03:04 volumio4 volumio[1227]: info: MPD Permissions set Aug 28 09:03:04 volumio4 volumio[1227]: info: MPD Permissions set Aug 28 09:03:04 volumio4 sudo[1692]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/systemctl restart soloist.service Aug 28 09:03:04 volumio4 sudo[1692]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 09:03:04 volumio4 volumio[1227]: 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: 8 Aug 28 09:03:04 volumio4 volumio[1227]: 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: 8 Aug 28 09:03:04 volumio4 systemd[1]: Starting soloist.service - Spotify Soloist daemon (Volumio 4 ALSA)... Aug 28 09:03:04 volumio4 volumio[1227]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 09:03:04 volumio4 sudo[1692]: pam_unix(sudo:session): session closed for user root Aug 28 09:03:04 volumio4 volumio[1227]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 09:03:04 volumio4 volumio[1227]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 09:03:04 volumio4 volumio[1227]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 09:03:04 volumio4 volumio[1227]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 09:03:04 volumio4 volumio[1227]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 09:03:04 volumio4 volumio[1227]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 09:03:04 volumio4 volumio[1227]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 09:03:04 volumio4 systemd[1]: Started soloist.service - Spotify Soloist daemon (Volumio 4 ALSA). Aug 28 09:03:04 volumio4 volumio[1227]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 09:03:05 volumio4 volumio[1227]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 09:03:05 volumio4 volumio[1227]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 09:03:05 volumio4 volumio[1227]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 09:03:05 volumio4 volumio[1227]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 09:03:05 volumio4 volumio[1227]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 09:03:05 volumio4 volumio[1227]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 09:03:05 volumio4 volumio[1227]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 09:03:05 volumio4 volumio[1227]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 09:03:05 volumio4 volumio[1227]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 09:03:05 volumio4 volumio[1227]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 09:03:05 volumio4 volumio[1227]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 09:03:05 volumio4 launch-soloist.sh[1705]: SoloistConnect: userspace=armhf device=plug:volumio tlength_cap=500ms external_volume=true trim=0dB diag=1 uname=armv7l Aug 28 09:03:05 volumio4 volumio[1227]: info: Received Get System Info Aug 28 09:03:05 volumio4 volumio[1227]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 28 09:03:05 volumio4 volumio[1227]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 28 09:03:05 volumio4 volumio[1227]: info: Discovery: Getting this device information Aug 28 09:03:05 volumio4 volumio[1227]: info: CoreCommandRouter::volumioGetState Aug 28 09:03:05 volumio4 volumio[1227]: debug: CoreStateMachine::getState Aug 28 09:03:05 volumio4 volumio[1227]: info: CorePlayQueue::getTrack 0 Aug 28 09:03:05 volumio4 volumio[1227]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 28 09:03:05 volumio4 volumio5-onboarding[1621]: time=2026-08-28T09:03:05.207-04:00 level=INFO msg="system info for 6205d0344b89bd5d1a7773681fe5c1c7" deviceName=Volumio4 deviceVariant=volumio deviceModel= softwareVersion=4.119 Aug 28 09:03:05 volumio4 volumio[1227]: info: SoloistConnect: soloist daemon started Aug 28 09:03:05 volumio4 volumio[1227]: info: SoloistConnect: connecting to ws://127.0.0.1:9878 Aug 28 09:03:05 volumio4 volumio5-onboarding[1621]: time=2026-08-28T09:03:05.230-04:00 level=INFO msg="bootstrapping state" hasInternet=true Aug 28 09:03:05 volumio4 volumio[1227]: info: Received Get System Info Aug 28 09:03:05 volumio4 volumio[1227]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 28 09:03:05 volumio4 volumio[1227]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 28 09:03:05 volumio4 volumio[1227]: info: Discovery: Getting this device information Aug 28 09:03:05 volumio4 volumio[1227]: info: CoreCommandRouter::volumioGetState Aug 28 09:03:05 volumio4 volumio[1227]: debug: CoreStateMachine::getState Aug 28 09:03:05 volumio4 volumio[1227]: info: CorePlayQueue::getTrack 0 Aug 28 09:03:05 volumio4 volumio[1227]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 28 09:03:05 volumio4 volumio[1227]: debug: API:emitFavourites Aug 28 09:03:05 volumio4 volumio[1227]: info: Starting Shairport Sync Aug 28 09:03:05 volumio4 sudo[1728]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Aug 28 09:03:05 volumio4 sudo[1728]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 09:03:05 volumio4 volumio[1227]: info: Starting Shairport Sync Aug 28 09:03:05 volumio4 volumio[1227]: info: Starting Shairport Sync Aug 28 09:03:05 volumio4 sudo[1733]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Aug 28 09:03:05 volumio4 sudo[1731]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Aug 28 09:03:05 volumio4 sudo[1733]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 09:03:05 volumio4 systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Aug 28 09:03:05 volumio4 systemd[1]: shairport-sync.service: Deactivated successfully. Aug 28 09:03:05 volumio4 systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 28 09:03:05 volumio4 systemd[1]: shairport-sync.service: Consumed 1.053s CPU time. Aug 28 09:03:05 volumio4 sudo[1731]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 09:03:05 volumio4 systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 28 09:03:05 volumio4 sudo[1728]: pam_unix(sudo:session): session closed for user root Aug 28 09:03:05 volumio4 systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Aug 28 09:03:05 volumio4 systemd[1]: shairport-sync.service: Deactivated successfully. Aug 28 09:03:05 volumio4 systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 28 09:03:05 volumio4 systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 28 09:03:05 volumio4 volumio[1227]: info: Shairport-Sync Started Aug 28 09:03:05 volumio4 volumio[1227]: Error adding Membership: Error: addMembership EINVAL Aug 28 09:03:05 volumio4 sudo[1733]: pam_unix(sudo:session): session closed for user root Aug 28 09:03:05 volumio4 systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Aug 28 09:03:05 volumio4 sudo[1738]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Aug 28 09:03:05 volumio4 sudo[1738]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 09:03:05 volumio4 systemd[1]: shairport-sync.service: Deactivated successfully. Aug 28 09:03:05 volumio4 systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 28 09:03:05 volumio4 systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 28 09:03:05 volumio4 sudo[1731]: pam_unix(sudo:session): session closed for user root Aug 28 09:03:05 volumio4 volumio[1227]: info: Shairport-Sync Started Aug 28 09:03:05 volumio4 volumio[1227]: info: Shairport-Sync Started Aug 28 09:03:05 volumio4 launch-soloist.sh[1705]: SoloistConnect: interpreter=/data/soloist/sysroot/usr/lib/ld-linux-armhf.so.3 Aug 28 09:03:05 volumio4 launch-soloist.sh[1705]: 2026-08-28 09:03:05.760: soloist 1.3.7.495 build 1787767311 (20260826) (gb24005ef46) (linux/arm) Aug 28 09:03:05 volumio4 launch-soloist.sh[1705]: 2026-08-28 09:03:05.761: client expires in 88 days Aug 28 09:03:05 volumio4 launch-soloist.sh[1705]: 2026-08-28 09:03:05.999: api: websocket server listening on 127.0.0.1:9878 Aug 28 09:03:05 volumio4 launch-soloist.sh[1705]: 2026-08-28 09:03:05.999: ready, device_name=Volumio4 device_id=47dba5c8-06b7-469e-bf5a-536b5767a5dc Aug 28 09:03:06 volumio4 launch-soloist.sh[1705]: 2026-08-28 09:03:06.018: restoring session Aug 28 09:03:06 volumio4 launch-soloist.sh[1705]: 2026-08-28 09:03:06.019: running Aug 28 09:03:07 volumio4 ntpd[1021]: DNS: dns_check: processing 1.debian.pool.ntp.org, 8, 101 Aug 28 09:03:07 volumio4 ntpd[1021]: DNS: Pool taking: 159.203.82.102 Aug 28 09:03:07 volumio4 ntpd[1021]: DNS: Pool taking: 69.89.207.199 Aug 28 09:03:07 volumio4 ntpd[1021]: DNS: Pool taking: 66.118.228.14 Aug 28 09:03:07 volumio4 ntpd[1021]: DNS: Pool taking: 216.66.48.42 Aug 28 09:03:07 volumio4 ntpd[1021]: DNS: dns_take_status: 1.debian.pool.ntp.org=>good, 8 Aug 28 09:03:08 volumio4 ntpd[1021]: DNS: dns_probe: 0.debian.pool.ntp.org, cast_flags:8, flags:101 Aug 28 09:03:08 volumio4 volumio-remote-updater[784]: [2026-08-28 09:03:08] [connect] Successful connection Aug 28 09:03:08 volumio4 volumio-remote-updater[784]: [2026-08-28 09:03:08] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1787922188 101 Aug 28 09:03:08 volumio4 volumio[1227]: 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: 9 Aug 28 09:03:08 volumio4 volumio[1227]: info: Volumio called home Aug 28 09:03:10 volumio4 volumio[1227]: info: Discovery: adding 9e349fd9-e43e-47bf-849d-5c8c89426e06 Aug 28 09:03:10 volumio4 volumio[1227]: info: Discovery: Found device Volumio4 Aug 28 09:03:10 volumio4 volumio[1227]: info: CoreCommandRouter::volumioGetState Aug 28 09:03:10 volumio4 volumio[1227]: debug: CoreStateMachine::getState Aug 28 09:03:10 volumio4 volumio[1227]: info: CorePlayQueue::getTrack 0 Aug 28 09:03:10 volumio4 volumio[1227]: debug: API:pushMultiroomDevices Aug 28 09:03:10 volumio4 volumio[1227]: info: Discovery: this is already registered, 9e349fd9-e43e-47bf-849d-5c8c89426e06 Aug 28 09:03:10 volumio4 volumio[1227]: info: Discovery: Found device Volumio4 Aug 28 09:03:10 volumio4 volumio[1227]: info: CoreCommandRouter::volumioGetState Aug 28 09:03:10 volumio4 volumio[1227]: debug: CoreStateMachine::getState Aug 28 09:03:10 volumio4 volumio[1227]: info: CorePlayQueue::getTrack 0 Aug 28 09:03:10 volumio4 volumio[1227]: debug: API:pushMultiroomDevices Aug 28 09:03:10 volumio4 volumio[1227]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 10 Aug 28 09:03:10 volumio4 volumio[1227]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 11 Aug 28 09:03:10 volumio4 volumio[1227]: info: SoloistConnect: connecting to ws://127.0.0.1:9878 Aug 28 09:03:10 volumio4 volumio[1227]: info: SoloistConnect: WebSocket connected Aug 28 09:03:10 volumio4 volumio[1227]: info: CoreCommandRouter::volumioRemoveToBrowseSourcesSpotify Queue Aug 28 09:03:10 volumio4 volumio[1227]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 28 09:03:10 volumio4 volumio[1227]: debug: API:emitFavourites Aug 28 09:03:10 volumio4 volumio[1227]: info: SoloistConnect: ws event {"type":"auth_state","logged_in":false,"is_active":false,"device_name":"Volumio4"} Aug 28 09:03:10 volumio4 volumio[1227]: info: SoloistConnect: hold yield: is_active=false hold=2000ms Aug 28 09:03:10 volumio4 volumio[1227]: info: SoloistConnect: ws event {"type":"error","message":"command requires authentication"} Aug 28 09:03:11 volumio4 mpd[1665]: 2026-08-28T09:03:11 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Aug 28 09:03:13 volumio4 systemd[1]: Started mpd.service - Music Player Daemon. Aug 28 09:03:13 volumio4 sudo[1615]: pam_unix(sudo:session): session closed for user root Aug 28 09:03:13 volumio4 sudo[1603]: pam_unix(sudo:session): session closed for user root Aug 28 09:03:13 volumio4 volumio[1227]: debug: API:printToastMessage Aug 28 09:03:13 volumio4 volumio[1227]: info: Completed starting Core Plugins Aug 28 09:03:13 volumio4 volumio[1227]: info: ------------------------------------------- Aug 28 09:03:13 volumio4 volumio[1227]: info: ----- MyVolumio plugins startup ---- Aug 28 09:03:13 volumio4 volumio[1227]: info: ------------------------------------------- Aug 28 09:03:13 volumio4 volumio[1227]: info: [MyVolumio PluginManager] Fetching plans data.... Aug 28 09:03:13 volumio4 volumio[1227]: error: MPD error: The expression evaluated to a falsy value: Aug 28 09:03:13 volumio4 volumio[1227]: assert.ok(self.idling) Aug 28 09:03:13 volumio4 volumio[1227]: error: The expression evaluated to a falsy value: Aug 28 09:03:13 volumio4 volumio[1227]: assert.ok(self.idling) Aug 28 09:03:13 volumio4 volumio[1227]: error: updateQueue error: null Aug 28 09:03:13 volumio4 volumio[1227]: info: MPD running with PID1665 Aug 28 09:03:13 volumio4 volumio[1227]: ,establishing connection Aug 28 09:03:13 volumio4 volumio[1227]: error: updateQueue error: null Aug 28 09:03:14 volumio4 ntpd[1021]: DNS: dns_check: processing 0.debian.pool.ntp.org, 8, 101 Aug 28 09:03:14 volumio4 ntpd[1021]: DNS: Pool taking: 172.234.25.10 Aug 28 09:03:14 volumio4 ntpd[1021]: DNS: Pool taking: 142.248.192.33 Aug 28 09:03:14 volumio4 ntpd[1021]: DNS: Pool taking: 170.187.142.180 Aug 28 09:03:14 volumio4 ntpd[1021]: DNS: Pool taking: 162.254.225.152 Aug 28 09:03:14 volumio4 ntpd[1021]: DNS: dns_take_status: 0.debian.pool.ntp.org=>good, 8 Aug 28 09:03:15 volumio4 systemd[1]: Starting setdatetime-helper.service - Time Synchronization Helper Service... Aug 28 09:03:16 volumio4 launch-soloist.sh[1705]: 2026-08-28 09:03:16.691: login failed: make sure --api-key is valid Aug 28 09:03:16 volumio4 systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 3. Aug 28 09:03:16 volumio4 systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Aug 28 09:03:16 volumio4 systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Aug 28 09:03:16 volumio4 sudo[1738]: pam_unix(sudo:session): session closed for user root Aug 28 09:03:16 volumio4 volumio[1227]: info: Upmpdcli Daemon Started Aug 28 09:03:20 volumio4 volumio[1227]: info: Discovery: adding 2f584d33-8bd3-4ac2-ac36-eb8013e138da Aug 28 09:03:20 volumio4 volumio[1227]: info: Discovery: Found device volumiold Aug 28 09:03:20 volumio4 volumio[1227]: info: Discovery: Connecting to remote: 192.168.1.17 Aug 28 09:03:20 volumio4 volumio[1227]: info: Discovery: Connected to remote: 192.168.1.17 Aug 28 09:03:20 volumio4 volumio[1227]: debug: API:pushMultiroomDevices Aug 28 09:03:20 volumio4 volumio[1227]: info: CoreCommandRouter::volumioGetState Aug 28 09:03:20 volumio4 volumio[1227]: debug: CoreStateMachine::getState Aug 28 09:03:20 volumio4 volumio[1227]: info: CorePlayQueue::getTrack 0 Aug 28 09:03:20 volumio4 volumio[1227]: debug: API:pushMultiroomDevices Aug 28 09:03:21 volumio4 volumio[1227]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Aug 28 09:03:32 volumio4 volumio[1227]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 28 09:03:32 volumio4 volumio[1227]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 09:03:32 volumio4 volumio[1227]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Aug 28 09:03:33 volumio4 volumio[1227]: error: MyVolumio Plugin failed to start in a timely fashion Aug 28 09:03:33 volumio4 volumio[1227]: [Metrics] CommandRouter: 45s 485.91ms Aug 28 09:03:33 volumio4 volumio[1227]: info: CoreCommandRouter::volumiosetStartupVolume Aug 28 09:03:33 volumio4 volumio[1227]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 09:03:33 volumio4 volumio[1227]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 09:03:33 volumio4 volumio[1227]: info: CoreCommandRouter::Close All Modals sent Aug 28 09:03:33 volumio4 volumio[1227]: debug: API:emitFavourites Aug 28 09:03:33 volumio4 volumio[1227]: info: CoreCommandRouter::Close All Modals sent Aug 28 09:03:33 volumio4 volumio[1227]: debug: API:emitFavourites Aug 28 09:03:35 volumio4 volumio5-onboarding[1621]: failed to bootstrap state: failed to check for software update: could not check for updates: context deadline exceeded Aug 28 09:03:35 volumio4 systemd[1]: volumio5-onboarding.service: Main process exited, code=exited, status=1/FAILURE Aug 28 09:03:35 volumio4 systemd[1]: volumio5-onboarding.service: Failed with result 'exit-code'. Aug 28 09:03:35 volumio4 volumio[1227]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable Aug 28 09:03:35 volumio4 systemd[1]: volumio5-onboarding.service: Scheduled restart job, restart counter is at 1. Aug 28 09:03:35 volumio4 systemd[1]: Stopped volumio5-onboarding.service - Volumio5 Onboarding Server. Aug 28 09:03:35 volumio4 volumio[1227]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Aug 28 09:03:35 volumio4 systemd[1]: Started volumio5-onboarding.service - Volumio5 Onboarding Server. Aug 28 09:03:35 volumio4 volumio[1227]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect Aug 28 09:03:35 volumio4 volumio5-onboarding[1858]: time=2026-08-28T09:03:35.547-04:00 level=INFO msg="running volumio5-device-gateway" version=6370e0a8+CHANGES buildDate=2026-03-06T16:29:42Z Aug 28 09:03:36 volumio4 volumio[1227]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 28 09:03:36 volumio4 volumio[1227]: Error [ERR_INTERNAL_ASSERTION]: This is caused by either a bug in Node.js or incorrect usage of Node.js internals. Aug 28 09:03:36 volumio4 volumio[1227]: Please open an issue with this stack trace at https://github.com/nodejs/node/issues Aug 28 09:03:36 volumio4 volumio[1227]: at new NodeError (node:internal/errors:405:5) Aug 28 09:03:36 volumio4 volumio[1227]: at assert (node:internal/assert:14:11) Aug 28 09:03:36 volumio4 volumio[1227]: at internalConnectMultiple (node:net:1118:3) Aug 28 09:03:36 volumio4 volumio[1227]: at Timeout.internalConnectMultipleTimeout (node:net:1687:3) Aug 28 09:03:36 volumio4 volumio[1227]: at listOnTimeout (node:internal/timers:575:11) Aug 28 09:03:36 volumio4 volumio[1227]: at process.processTimers (node:internal/timers:514:7) { Aug 28 09:03:36 volumio4 volumio[1227]: code: 'ERR_INTERNAL_ASSERTION' Aug 28 09:03:36 volumio4 volumio[1227]: } Aug 28 09:03:36 volumio4 volumio[1227]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 28 09:03:38 volumio4 sudo[1883]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-08-28 09:02' Aug 28 09:03:38 volumio4 sudo[1883]: 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"