Feb 17 09:44:00 volumio-bb kernel: bcm2835_mmal_vchiq: module is from the staging directory, the quality is unknown, you have been warned. Feb 17 09:44:00 volumio-bb kernel: bcm2835_isp: module is from the staging directory, the quality is unknown, you have been warned. Feb 17 09:44:00 volumio-bb kernel: bcm2835_codec: module is from the staging directory, the quality is unknown, you have been warned. Feb 17 09:44:00 volumio-bb kernel: bcm2835-isp bcm2835-isp: Device node output[0] registered as /dev/video13 Feb 17 09:44:00 volumio-bb kernel: bcm2835-isp bcm2835-isp: Device node capture[0] registered as /dev/video14 Feb 17 09:44:00 volumio-bb kernel: bcm2835-isp bcm2835-isp: Device node capture[1] registered as /dev/video15 Feb 17 09:44:00 volumio-bb kernel: bcm2835-isp bcm2835-isp: Device node stats[2] registered as /dev/video16 Feb 17 09:44:00 volumio-bb kernel: bcm2835-isp bcm2835-isp: Register output node 0 with media controller Feb 17 09:44:00 volumio-bb kernel: bcm2835-isp bcm2835-isp: Register capture node 1 with media controller Feb 17 09:44:00 volumio-bb kernel: bcm2835-isp bcm2835-isp: Register capture node 2 with media controller Feb 17 09:44:00 volumio-bb kernel: bcm2835-isp bcm2835-isp: Register capture node 3 with media controller Feb 17 09:44:00 volumio-bb kernel: bcm2835-codec bcm2835-codec: Device registered as /dev/video10 Feb 17 09:44:00 volumio-bb kernel: bcm2835-codec bcm2835-codec: Loaded V4L2 decode Feb 17 09:44:00 volumio-bb kernel: bcm2835-isp bcm2835-isp: Device node output[0] registered as /dev/video20 Feb 17 09:44:00 volumio-bb kernel: bcm2835-isp bcm2835-isp: Device node capture[0] registered as /dev/video21 Feb 17 09:44:00 volumio-bb kernel: bcm2835_v4l2: module is from the staging directory, the quality is unknown, you have been warned. Feb 17 09:44:00 volumio-bb kernel: bcm2835-codec bcm2835-codec: Device registered as /dev/video11 Feb 17 09:44:00 volumio-bb kernel: bcm2835-codec bcm2835-codec: Loaded V4L2 encode Feb 17 09:44:00 volumio-bb kernel: bcm2835-isp bcm2835-isp: Device node capture[1] registered as /dev/video22 Feb 17 09:44:00 volumio-bb kernel: bcm2835-isp bcm2835-isp: Device node stats[2] registered as /dev/video23 Feb 17 09:44:00 volumio-bb kernel: bcm2835-isp bcm2835-isp: Register output node 0 with media controller Feb 17 09:44:00 volumio-bb kernel: bcm2835-isp bcm2835-isp: Register capture node 1 with media controller Feb 17 09:44:00 volumio-bb kernel: bcm2835-isp bcm2835-isp: Register capture node 2 with media controller Feb 17 09:44:00 volumio-bb kernel: bcm2835-isp bcm2835-isp: Register capture node 3 with media controller Feb 17 09:44:00 volumio-bb kernel: bcm2835-isp bcm2835-isp: Loaded V4L2 bcm2835-isp Feb 17 09:44:00 volumio-bb kernel: cfg80211: Loading compiled-in X.509 certificates for regulatory database Feb 17 09:44:00 volumio-bb systemd[1]: dev-hugepages.mount - Huge Pages File System was skipped because of an unmet condition check (ConditionPathExists=/sys/kernel/mm/hugepages). Feb 17 09:44:00 volumio-bb systemd[1]: tmp.mount: Directory /tmp to mount over is not empty, mounting anyway. Feb 17 09:44:00 volumio-bb kernel: Loaded X.509 cert 'benh@debian.org: 577e021cb980e0e820821ba7b54b4961b8b4fadf' Feb 17 09:44:00 volumio-bb kernel: Loaded X.509 cert 'romain.perier@gmail.com: 3abbc6ec146e09d1b6016ab9d6cf71dd233f0328' Feb 17 09:44:00 volumio-bb kernel: Loaded X.509 cert 'sforshee: 00b28ddf47aef9cea7' Feb 17 09:44:00 volumio-bb kernel: Loaded X.509 cert 'wens: 61c038651aabdcf94bd0ac7ff06c7248db18c600' Feb 17 09:44:00 volumio-bb systemd[1]: Mounting tmp.mount - /tmp... Feb 17 09:44:00 volumio-bb systemd[1]: var-log.mount: Directory /var/log to mount over is not empty, mounting anyway. Feb 17 09:44:00 volumio-bb systemd[1]: Mounting var-log.mount - /var/log... Feb 17 09:44:00 volumio-bb systemd[1]: Mounting var-spool-cups.mount - /var/spool/cups... Feb 17 09:44:00 volumio-bb kernel: bcm2835-codec bcm2835-codec: Device registered as /dev/video12 Feb 17 09:44:00 volumio-bb kernel: bcm2835-codec bcm2835-codec: Loaded V4L2 isp Feb 17 09:44:00 volumio-bb systemd[1]: Starting modprobe@dm_mod.service - Load Kernel Module dm_mod... Feb 17 09:44:00 volumio-bb kernel: bcm2835-codec bcm2835-codec: Device registered as /dev/video18 Feb 17 09:44:00 volumio-bb kernel: bcm2835-codec bcm2835-codec: Loaded V4L2 image_fx Feb 17 09:44:00 volumio-bb kernel: usbcore: registered new interface driver snd-usb-audio Feb 17 09:44:00 volumio-bb systemd[1]: Starting modprobe@efi_pstore.service - Load Kernel Module efi_pstore... Feb 17 09:44:00 volumio-bb systemd[1]: Starting modprobe@loop.service - Load Kernel Module loop... Feb 17 09:44:00 volumio-bb systemd[1]: systemd-firstboot.service - First Boot Wizard was skipped because of an unmet condition check (ConditionFirstBoot=yes). Feb 17 09:44:00 volumio-bb systemd[1]: first-boot-complete.target - First Boot Complete was skipped because of an unmet condition check (ConditionFirstBoot=yes). Feb 17 09:44:00 volumio-bb kernel: bcm2835-codec bcm2835-codec: Device registered as /dev/video31 Feb 17 09:44:00 volumio-bb kernel: bcm2835-codec bcm2835-codec: Loaded V4L2 encode_image Feb 17 09:44:00 volumio-bb systemd[1]: Mounted tmp.mount - /tmp. Feb 17 09:44:00 volumio-bb systemd[1]: Mounted var-log.mount - /var/log. Feb 17 09:44:00 volumio-bb systemd[1]: Mounted var-spool-cups.mount - /var/spool/cups. Feb 17 09:44:00 volumio-bb systemd[1]: modprobe@dm_mod.service: Deactivated successfully. Feb 17 09:44:00 volumio-bb systemd[1]: Finished modprobe@dm_mod.service - Load Kernel Module dm_mod. Feb 17 09:44:00 volumio-bb systemd[1]: modprobe@efi_pstore.service: Deactivated successfully. Feb 17 09:44:00 volumio-bb systemd[1]: Finished modprobe@efi_pstore.service - Load Kernel Module efi_pstore. Feb 17 09:44:00 volumio-bb systemd[1]: modprobe@loop.service: Deactivated successfully. Feb 17 09:44:00 volumio-bb systemd[1]: Finished modprobe@loop.service - Load Kernel Module loop. Feb 17 09:44:00 volumio-bb systemd[1]: Found device dev-disk-by\x2duuid-0428\x2dC7E4.device - SanDisk_3.2Gen1 boot. Feb 17 09:44:00 volumio-bb systemd[1]: Mounting var-spool-cups-tmp.mount - /var/spool/cups/tmp... Feb 17 09:44:00 volumio-bb systemd[1]: Starting systemd-fsck@dev-disk-by\x2duuid-0428\x2dC7E4.service - File System Check on /dev/disk/by-uuid/0428-C7E4... Feb 17 09:44:00 volumio-bb systemd[1]: Starting systemd-journal-flush.service - Flush Journal to Persistent Storage... Feb 17 09:44:00 volumio-bb systemd[1]: systemd-pstore.service - Platform Persistent Storage Archival was skipped because of an unmet condition check (ConditionDirectoryNotEmpty=/sys/fs/pstore). Feb 17 09:44:00 volumio-bb systemd[1]: systemd-repart.service - Repartition Root Disk was skipped because no trigger condition checks were met. Feb 17 09:44:00 volumio-bb systemd[1]: Mounted var-spool-cups-tmp.mount - /var/spool/cups/tmp. Feb 17 09:44:00 volumio-bb systemd[1]: Started systemd-fsckd.service - File System Check Daemon to report status. Feb 17 09:44:00 volumio-bb systemd-journald[459]: Runtime Journal (/run/log/journal/5d75154b0edd470a8cb44210694cfe4a) is 3.7M, max 30.0M, 26.2M free. Feb 17 09:44:00 volumio-bb systemd-journald[459]: Received client request to flush runtime journal. Feb 17 09:44:00 volumio-bb systemd[1]: Finished systemd-journal-flush.service - Flush Journal to Persistent Storage. Feb 17 09:44:00 volumio-bb kernel: brcmfmac: F1 signature read @0x18000000=0x15264345 Feb 17 09:44:00 volumio-bb kernel: brcmfmac: brcmf_fw_alloc_request: using brcm/brcmfmac43455-sdio for chip BCM4345/6 Feb 17 09:44:00 volumio-bb kernel: usbcore: registered new interface driver brcmfmac Feb 17 09:44:00 volumio-bb systemd-fsck[642]: fsck.fat 4.2 (2021-01-31) Feb 17 09:44:00 volumio-bb systemd-fsck[642]: /dev/sda1: 509 files, 23716/93500 clusters Feb 17 09:44:00 volumio-bb systemd[1]: Finished systemd-fsck@dev-disk-by\x2duuid-0428\x2dC7E4.service - File System Check on /dev/disk/by-uuid/0428-C7E4. Feb 17 09:44:00 volumio-bb systemd[1]: boot.mount: Directory /boot to mount over is not empty, mounting anyway. Feb 17 09:44:00 volumio-bb systemd[1]: Mounting boot.mount - /boot... Feb 17 09:44:00 volumio-bb systemd[1]: Mounted boot.mount - /boot. Feb 17 09:44:00 volumio-bb systemd[1]: Reached target local-fs.target - Local File Systems. Feb 17 09:44:00 volumio-bb systemd[1]: Started ifup@eth0.service - ifup for eth0. Feb 17 09:44:00 volumio-bb systemd[1]: Starting networking.service - Raise network interfaces... Feb 17 09:44:00 volumio-bb systemd[1]: Starting plymouth-read-write.service - Tell Plymouth To Write Out Runtime Data... Feb 17 09:44:00 volumio-bb systemd[1]: Starting plymouth-rotation.service - Plymouth rotation detection for shutdown/reboot... Feb 17 09:44:00 volumio-bb kernel: Bluetooth: Core ver 2.22 Feb 17 09:44:00 volumio-bb kernel: NET: Registered PF_BLUETOOTH protocol family Feb 17 09:44:00 volumio-bb kernel: Bluetooth: HCI device and connection manager initialized Feb 17 09:44:00 volumio-bb kernel: Bluetooth: HCI socket layer initialized Feb 17 09:44:00 volumio-bb kernel: Bluetooth: L2CAP socket layer initialized Feb 17 09:44:00 volumio-bb kernel: Bluetooth: SCO socket layer initialized Feb 17 09:44:00 volumio-bb systemd[1]: Starting systemd-binfmt.service - Set Up Additional Binary Formats... Feb 17 09:44:00 volumio-bb systemd[1]: systemd-machine-id-commit.service - Commit a transient machine-id on disk was skipped because of an unmet condition check (ConditionPathIsMountPoint=/etc/machine-id). Feb 17 09:44:00 volumio-bb systemd[1]: Starting systemd-tmpfiles-setup.service - Create System Files and Directories... Feb 17 09:44:00 volumio-bb systemd[1]: Received SIGRTMIN+20 from PID 324 (plymouthd). Feb 17 09:44:00 volumio-bb systemd[1]: Finished plymouth-read-write.service - Tell Plymouth To Write Out Runtime Data. Feb 17 09:44:00 volumio-bb systemd[1]: Listening on systemd-rfkill.socket - Load/Save RF Kill Switch Status /dev/rfkill Watch. Feb 17 09:44:00 volumio-bb systemd[1]: proc-sys-fs-binfmt_misc.automount: Got automount request for /proc/sys/fs/binfmt_misc, triggered by 664 (systemd-binfmt) Feb 17 09:44:00 volumio-bb kernel: Bluetooth: HCI UART driver ver 2.3 Feb 17 09:44:00 volumio-bb kernel: Bluetooth: HCI UART protocol H4 registered Feb 17 09:44:00 volumio-bb kernel: Bluetooth: HCI UART protocol Three-wire (H5) registered Feb 17 09:44:00 volumio-bb kernel: hci_uart_bcm serial0-0: supply vbat not found, using dummy regulator Feb 17 09:44:00 volumio-bb kernel: hci_uart_bcm serial0-0: supply vddio not found, using dummy regulator Feb 17 09:44:00 volumio-bb sh[688]: command failed: No such device (-19) Feb 17 09:44:00 volumio-bb ifup[687]: command failed: No such device (-19) Feb 17 09:44:00 volumio-bb systemd[1]: Finished plymouth-rotation.service - Plymouth rotation detection for shutdown/reboot. Feb 17 09:44:00 volumio-bb systemd[1]: Finished systemd-tmpfiles-setup.service - Create System Files and Directories. Feb 17 09:44:00 volumio-bb kernel: Bluetooth: HCI UART protocol Broadcom registered Feb 17 09:44:00 volumio-bb sh[719]: dhcpcd-9.4.1 starting Feb 17 09:44:00 volumio-bb dhcpcd[719]: dhcpcd-9.4.1 starting Feb 17 09:44:00 volumio-bb dhcpcd[726]: DUID 00:01:00:01:30:df:bc:b5:e4:5f:01:05:2d:4a Feb 17 09:44:00 volumio-bb sh[719]: DUID 00:01:00:01:30:df:bc:b5:e4:5f:01:05:2d:4a Feb 17 09:44:00 volumio-bb systemd[1]: Started haveged.service - Entropy Daemon based on the HAVEGE algorithm. Feb 17 09:44:00 volumio-bb systemd[1]: Starting plymouth-start.service - Show Plymouth Boot Screen... Feb 17 09:44:00 volumio-bb systemd[1]: Starting rpcbind.service - RPC bind portmap service... Feb 17 09:44:00 volumio-bb systemd[1]: Starting systemd-update-utmp.service - Record System Boot/Shutdown in UTMP... Feb 17 09:44:00 volumio-bb ifup[738]: command failed: No such device (-19) Feb 17 09:44:00 volumio-bb systemd[1]: Starting systemd-rfkill.service - Load/Save RF Kill Switch Status... Feb 17 09:44:00 volumio-bb systemd[1]: Started plymouth-start.service - Show Plymouth Boot Screen. Feb 17 09:44:00 volumio-bb systemd[1]: systemd-ask-password-console.path - Dispatch Password Requests to Console Directory Watch was skipped because of an unmet condition check (ConditionPathExists=!/run/plymouth/pid). Feb 17 09:44:00 volumio-bb systemd[1]: Started systemd-ask-password-plymouth.path - Forward Password Requests to Plymouth Directory Watch. Feb 17 09:44:00 volumio-bb systemd[1]: Reached target cryptsetup.target - Local Encrypted Volumes. Feb 17 09:44:01 volumio-bb systemd[1]: Reached target paths.target - Path Units. Feb 17 09:44:01 volumio-bb kernel: brcmfmac: brcmf_c_process_txcap_blob: no txcap_blob available (err=-2) Feb 17 09:44:01 volumio-bb kernel: brcmfmac: brcmf_c_preinit_dcmds: Firmware: BCM4345/6 wl0: Aug 29 2023 01:47:08 version 7.45.265 (28bca26 CY) FWID 01-b677b91b Feb 17 09:44:01 volumio-bb systemd[1]: Finished systemd-update-utmp.service - Record System Boot/Shutdown in UTMP. Feb 17 09:44:01 volumio-bb kernel: 8021q: 802.1Q VLAN Support v1.8 Feb 17 09:44:01 volumio-bb systemd[1]: Mounting proc-sys-fs-binfmt_misc.mount - Arbitrary Executable File Formats File System... Feb 17 09:44:01 volumio-bb systemd[1]: Mounting run-rpc_pipefs.mount - RPC Pipe File System... Feb 17 09:44:01 volumio-bb (udev-worker)[484]: hci0: Process '/usr/bin/hciconfig hci0 up' failed with exit code 1. Feb 17 09:44:01 volumio-bb (udev-worker)[510]: Network interface NamePolicy= disabled on kernel command line. Feb 17 09:44:01 volumio-bb systemd[1]: Started systemd-rfkill.service - Load/Save RF Kill Switch Status. Feb 17 09:44:01 volumio-bb systemd[1]: Mounted proc-sys-fs-binfmt_misc.mount - Arbitrary Executable File Formats File System. Feb 17 09:44:01 volumio-bb systemd[1]: Mounted run-rpc_pipefs.mount - RPC Pipe File System. Feb 17 09:44:01 volumio-bb kernel: Bluetooth: hci0: BCM: chip id 107 Feb 17 09:44:01 volumio-bb kernel: Bluetooth: hci0: BCM: features 0x2f Feb 17 09:44:01 volumio-bb kernel: Bluetooth: hci0: BCM4345C0 Feb 17 09:44:01 volumio-bb kernel: Bluetooth: hci0: BCM4345C0 (003.001.025) build 0000 Feb 17 09:44:01 volumio-bb haveged[720]: haveged: command socket is listening at fd 3 Feb 17 09:44:01 volumio-bb kernel: Bluetooth: hci0: BCM4345C0 'brcm/BCM4345C0.raspberrypi,4-model-b.hcd' Patch Feb 17 09:44:01 volumio-bb systemd[1]: Finished systemd-binfmt.service - Set Up Additional Binary Formats. Feb 17 09:44:01 volumio-bb systemd[1]: systemd-ask-password-console.path - Dispatch Password Requests to Console Directory Watch was skipped because of an unmet condition check (ConditionPathExists=!/run/plymouth/pid). Feb 17 09:44:01 volumio-bb systemd[1]: Reached target rpc_pipefs.target. Feb 17 09:44:01 volumio-bb systemd[1]: dev-hugepages.mount - Huge Pages File System was skipped because of an unmet condition check (ConditionPathExists=/sys/kernel/mm/hugepages). Feb 17 09:44:01 volumio-bb systemd[1]: Starting modprobe@dm_mod.service - Load Kernel Module dm_mod... Feb 17 09:44:01 volumio-bb systemd[1]: Starting modprobe@efi_pstore.service - Load Kernel Module efi_pstore... Feb 17 09:44:01 volumio-bb systemd[1]: Starting modprobe@loop.service - Load Kernel Module loop... Feb 17 09:44:01 volumio-bb systemd[1]: rpc-gssd.service - RPC security service for NFS client and server was skipped because of an unmet condition check (ConditionPathExists=/etc/krb5.keytab). Feb 17 09:44:01 volumio-bb systemd[1]: Reached target nfs-client.target - NFS client services. Feb 17 09:44:01 volumio-bb systemd[1]: systemd-firstboot.service - First Boot Wizard was skipped because of an unmet condition check (ConditionFirstBoot=yes). Feb 17 09:44:01 volumio-bb systemd[1]: first-boot-complete.target - First Boot Complete was skipped because of an unmet condition check (ConditionFirstBoot=yes). Feb 17 09:44:01 volumio-bb systemd[1]: systemd-machine-id-commit.service - Commit a transient machine-id on disk was skipped because of an unmet condition check (ConditionPathIsMountPoint=/etc/machine-id). Feb 17 09:44:01 volumio-bb systemd[1]: modprobe@dm_mod.service: Deactivated successfully. Feb 17 09:44:01 volumio-bb systemd[1]: Finished modprobe@dm_mod.service - Load Kernel Module dm_mod. Feb 17 09:44:01 volumio-bb dhcpcd[726]: eth0: waiting for carrier Feb 17 09:44:01 volumio-bb sh[719]: eth0: waiting for carrier Feb 17 09:44:01 volumio-bb systemd[1]: modprobe@efi_pstore.service: Deactivated successfully. Feb 17 09:44:01 volumio-bb systemd[1]: Finished modprobe@efi_pstore.service - Load Kernel Module efi_pstore. Feb 17 09:44:01 volumio-bb kernel: bcmgenet fd580000.ethernet: configuring instance for external RGMII (RX delay) Feb 17 09:44:01 volumio-bb kernel: bcmgenet fd580000.ethernet eth0: Link is Down Feb 17 09:44:01 volumio-bb systemd[1]: modprobe@loop.service: Deactivated successfully. Feb 17 09:44:01 volumio-bb systemd[1]: Finished modprobe@loop.service - Load Kernel Module loop. Feb 17 09:44:01 volumio-bb systemd[1]: Expecting device sys-subsystem-net-devices-wlan0.device - /sys/subsystem/net/devices/wlan0... Feb 17 09:44:01 volumio-bb systemd[1]: systemd-pstore.service - Platform Persistent Storage Archival was skipped because of an unmet condition check (ConditionDirectoryNotEmpty=/sys/fs/pstore). Feb 17 09:44:01 volumio-bb systemd[1]: Reached target sysinit.target - System Initialization. Feb 17 09:44:01 volumio-bb systemd[1]: Started apt-daily.timer - Daily apt download activities. Feb 17 09:44:01 volumio-bb systemd[1]: Started apt-daily-upgrade.timer - Daily apt upgrade and clean activities. Feb 17 09:44:01 volumio-bb systemd[1]: Started dpkg-db-backup.timer - Daily dpkg database backup timer. Feb 17 09:44:01 volumio-bb systemd[1]: Started e2scrub_all.timer - Periodic ext4 Online Metadata Check for All Filesystems. Feb 17 09:44:01 volumio-bb systemd[1]: Started fstrim.timer - Discard unused blocks once a week. Feb 17 09:44:01 volumio-bb systemd[1]: Started man-db.timer - Daily man-db regeneration. Feb 17 09:44:01 volumio-bb systemd[1]: Started ntpsec-rotate-stats.timer - Rotate ntpd stats daily. Feb 17 09:44:01 volumio-bb systemd[1]: Started setdatetime-helper.timer - Volumio Time Sync Watchdog Timer. Feb 17 09:44:01 volumio-bb systemd[1]: Started systemd-tmpfiles-clean.timer - Daily Cleanup of Temporary Directories. Feb 17 09:44:01 volumio-bb systemd[1]: Reached target timers.target - Timer Units. Feb 17 09:44:01 volumio-bb systemd[1]: Listening on avahi-daemon.socket - Avahi mDNS/DNS-SD Stack Activation Socket. Feb 17 09:44:01 volumio-bb systemd[1]: Listening on dbus.socket - D-Bus System Message Bus Socket. Feb 17 09:44:01 volumio-bb systemd[1]: Reached target sockets.target - Socket Units. Feb 17 09:44:01 volumio-bb systemd[1]: systemd-pcrphase-sysinit.service - TPM2 PCR Barrier (Initialization) was skipped because of an unmet condition check (ConditionPathExists=/sys/firmware/efi/efivars/StubPcrKernelImage-4a67b082-0a4c-41cf-b6c7-440b29bb8c4f). Feb 17 09:44:01 volumio-bb systemd[1]: Reached target basic.target - Basic System. Feb 17 09:44:01 volumio-bb systemd[1]: alsa-state.service - Manage Sound Card State (restore and store) was skipped because of an unmet condition check (ConditionPathExists=/etc/alsa/state-daemon.conf). Feb 17 09:44:01 volumio-bb systemd[1]: Starting alsa-restore.service - Save/Restore Sound Card State... Feb 17 09:44:01 volumio-bb systemd[1]: Starting avahi-daemon.service - Avahi mDNS/DNS-SD Stack... Feb 17 09:44:01 volumio-bb systemd[1]: Starting bluetooth.service - Bluetooth service... Feb 17 09:44:01 volumio-bb systemd[1]: Starting dbus.service - D-Bus System Message Bus... Feb 17 09:44:01 volumio-bb systemd[1]: Starting e2scrub_reap.service - Remove Stale Online ext4 Metadata Check Snapshots... Feb 17 09:44:01 volumio-bb systemd[1]: getty-static.service - getty on tty2-tty6 if dbus and logind are not available was skipped because of an unmet condition check (ConditionPathExists=!/usr/bin/dbus-daemon). Feb 17 09:44:01 volumio-bb systemd[1]: Starting glamor-test.service - Check for glamor... Feb 17 09:44:01 volumio-bb systemd[1]: headless_wireless.service - Copy user wpa_supplicant.conf was skipped because of an unmet condition check (ConditionPathExists=/boot/wpa_supplicant.conf). Feb 17 09:44:01 volumio-bb systemd[1]: Started iptables.service - Volumio Iptables Module. Feb 17 09:44:01 volumio-bb systemd[1]: Starting rp1-test.service - Check for RP1 displays for Xorg... Feb 17 09:44:01 volumio-bb systemd[1]: Starting rpi-eeprom-update.service - Check for Raspberry Pi EEPROM updates... Feb 17 09:44:01 volumio-bb systemd[1]: Starting systemd-logind.service - User Login Management... Feb 17 09:44:01 volumio-bb systemd[1]: systemd-repart.service - Repartition Root Disk was skipped because no trigger condition checks were met. Feb 17 09:44:01 volumio-bb systemd[1]: Starting triggerhappy.service - triggerhappy global hotkey daemon... Feb 17 09:44:01 volumio-bb systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Feb 17 09:44:01 volumio-bb systemd[1]: Started volumio-remote-updater.service - Volumio Remote OTA Updater. Feb 17 09:44:01 volumio-bb systemd[1]: Starting volumio_rfkill_unblock.service - Manage nl80211 modules blocking state... Feb 17 09:44:01 volumio-bb systemd[1]: volumiossh.service - Volumio SSH enabler was skipped because of an unmet condition check (ConditionPathExistsGlob=/boot/ssh{,.txt}). Feb 17 09:44:01 volumio-bb systemd[1]: Starting wireless.service - Wireless Services... Feb 17 09:44:01 volumio-bb systemd[1]: Started rpcbind.service - RPC bind portmap service. Feb 17 09:44:01 volumio-bb systemd[1]: e2scrub_reap.service: Deactivated successfully. Feb 17 09:44:01 volumio-bb systemd[1]: Finished e2scrub_reap.service - Remove Stale Online ext4 Metadata Check Snapshots. Feb 17 09:44:01 volumio-bb volumio_rfkill_unblock.sh[814]: Volumio WiFi Soft Blocked check script Feb 17 09:44:01 volumio-bb volumio_rfkill_unblock.sh[814]: Check if rfkill is available Feb 17 09:44:01 volumio-bb avahi-daemon[790]: Found user 'avahi' (UID 103) and group 'avahi' (GID 109). Feb 17 09:44:01 volumio-bb avahi-daemon[790]: Successfully dropped root privileges. Feb 17 09:44:01 volumio-bb avahi-daemon[790]: avahi-daemon 0.8 starting up. Feb 17 09:44:01 volumio-bb systemd[1]: Reached target remote-fs-pre.target - Preparation for Remote File Systems. Feb 17 09:44:01 volumio-bb thd[805]: Unable to parse trigger line: Feb 17 09:44:01 volumio-bb thd[805]: Unable to parse trigger line: Feb 17 09:44:01 volumio-bb volumio_rfkill_unblock.sh[814]: Check if rfkill listed devices are already unblocked Feb 17 09:44:01 volumio-bb systemd[1]: Reached target remote-fs.target - Remote File Systems. Feb 17 09:44:01 volumio-bb systemd[1]: Reached target rpcbind.target - RPC Port Mapper. Feb 17 09:44:01 volumio-bb systemd[1]: Starting loadcpufreq.service - LSB: Load kernel modules needed to enable cpufreq scaling... Feb 17 09:44:01 volumio-bb systemd[1]: systemd-pcrphase.service - TPM2 PCR Barrier (User) was skipped because of an unmet condition check (ConditionPathExists=/sys/firmware/efi/efivars/StubPcrKernelImage-4a67b082-0a4c-41cf-b6c7-440b29bb8c4f). Feb 17 09:44:01 volumio-bb systemd[1]: Started triggerhappy.service - triggerhappy global hotkey daemon. Feb 17 09:44:01 volumio-bb systemd-logind[801]: New seat seat0. Feb 17 09:44:01 volumio-bb systemd-logind[801]: Watching system buttons on /dev/input/event4 (Logitech MX Master) Feb 17 09:44:01 volumio-bb systemd-logind[801]: Watching system buttons on /dev/input/event5 (Logitech MX Keys) Feb 17 09:44:01 volumio-bb systemd-logind[801]: Watching system buttons on /dev/input/event0 (vc4-hdmi-0) Feb 17 09:44:01 volumio-bb systemd-logind[801]: Watching system buttons on /dev/input/event2 (vc4-hdmi-1) Feb 17 09:44:01 volumio-bb systemd[1]: Found device sys-subsystem-net-devices-wlan0.device - /sys/subsystem/net/devices/wlan0. Feb 17 09:44:01 volumio-bb volumio_rfkill_unblock.sh[814]: Wi-Fi is already unblocked. Feb 17 09:44:01 volumio-bb systemd[1]: Finished volumio_rfkill_unblock.service - Manage nl80211 modules blocking state. Feb 17 09:44:01 volumio-bb alsactl[837]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:0 use case configuration -2 Feb 17 09:44:01 volumio-bb alsactl[837]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:1 use case configuration -2 Feb 17 09:44:01 volumio-bb alsactl[837]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:2 use case configuration -2 Feb 17 09:44:01 volumio-bb alsactl[837]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:3 use case configuration -2 Feb 17 09:44:01 volumio-bb systemd[1]: Finished alsa-restore.service - Save/Restore Sound Card State. Feb 17 09:44:01 volumio-bb systemd[1]: Reached target sound.target - Sound Card. Feb 17 09:44:01 volumio-bb systemd[1]: Starting dhcpcd.service - DHCP Client Daemon on all interfaces... Feb 17 09:44:01 volumio-bb systemd[1]: Started ifup@wlan0.service - ifup for wlan0. Feb 17 09:44:01 volumio-bb systemd[1]: Starting th-udev-rebind.service - Late rebind of input devices to triggerhappy... Feb 17 09:44:01 volumio-bb th-udev-rebind.sh[847]: Rebinding /dev/input/event0 to thd using --add... Feb 17 09:44:01 volumio-bb kernel: warning: `iwconfig' uses wireless extensions which will stop working for Wi-Fi 7 hardware; use nl80211 Feb 17 09:44:01 volumio-bb th-udev-rebind.sh[847]: Rebinding /dev/input/event1 to thd using --add... Feb 17 09:44:01 volumio-bb (udev-worker)[491]: pcmC5D0c: Process '/bin/bash -c '/usr/local/bin/volumio scanaudioinputs'' failed with exit code 7. Feb 17 09:44:01 volumio-bb th-udev-rebind.sh[847]: Rebinding /dev/input/event2 to thd using --add... Feb 17 09:44:01 volumio-bb bluetoothd[791]: Bluetooth daemon 5.83 Feb 17 09:44:01 volumio-bb (udev-worker)[501]: pcmC5D0p: Process '/bin/bash -c '/usr/local/bin/volumio usbattach'' failed with exit code 7. Feb 17 09:44:01 volumio-bb th-udev-rebind.sh[847]: Rebinding /dev/input/event3 to thd using --add... Feb 17 09:44:01 volumio-bb th-udev-rebind.sh[847]: Rebinding /dev/input/event4 to thd using --add... Feb 17 09:44:01 volumio-bb th-udev-rebind.sh[847]: Rebinding /dev/input/event5 to thd using --add... Feb 17 09:44:02 volumio-bb kernel: brcmfmac: brcmf_cfg80211_set_power_mgmt: power save disabled Feb 17 09:44:02 volumio-bb dhcpcd[844]: dhcpcd-9.4.1 starting Feb 17 09:44:02 volumio-bb systemd[1]: th-udev-rebind.service: Deactivated successfully. Feb 17 09:44:02 volumio-bb systemd[1]: Finished th-udev-rebind.service - Late rebind of input devices to triggerhappy. Feb 17 09:44:02 volumio-bb kernel: Bluetooth: hci0: BCM: features 0x2f Feb 17 09:44:02 volumio-bb kernel: Bluetooth: hci0: BCM43455 37.4MHz Raspberry Pi 3+-0190 Feb 17 09:44:02 volumio-bb kernel: Bluetooth: hci0: BCM4345C0 (003.001.025) build 0382 Feb 17 09:44:02 volumio-bb volumio-remote-updater[812]: Volumio OTA Client: 1.7.0 Feb 17 09:44:02 volumio-bb volumio-remote-updater[812]: Error: No active session Feb 17 09:44:02 volumio-bb volumio-remote-updater[812]: [2026-02-17 09:44:02] [info] asio async_connect error: asio.system:111 (Connection refused) Feb 17 09:44:02 volumio-bb volumio-remote-updater[812]: [2026-02-17 09:44:02] [info] Error getting remote endpoint: asio.system:107 (Transport endpoint is not connected) Feb 17 09:44:02 volumio-bb volumio-remote-updater[812]: [2026-02-17 09:44:02] [error] handle_connect error: Connection refused Feb 17 09:44:02 volumio-bb haveged[720]: haveged: ver: 1.9.14; arch: generic; vend: ; build: (gcc 10.2.1 CTV); collect: 128K Feb 17 09:44:02 volumio-bb haveged[720]: haveged: cpu: (VC); data: 16K (D); inst: 16K (D); idx: 11/40; sz: 14748/63356 Feb 17 09:44:02 volumio-bb haveged[720]: haveged: tot tests(BA8): A:1/1 B:1/1 continuous tests(B): last entropy estimate 7.9971 Feb 17 09:44:02 volumio-bb haveged[720]: haveged: fills: 0, generated: 0 Feb 17 09:44:02 volumio-bb dhcpcd[904]: dev: loaded udev Feb 17 09:44:02 volumio-bb dhcpcd[904]: DUID 00:01:00:01:30:df:bc:b5:e4:5f:01:05:2d:4a Feb 17 09:44:02 volumio-bb systemd[1]: Finished networking.service - Raise network interfaces. Feb 17 09:44:02 volumio-bb systemd[1]: Started dhcpcd.service - DHCP Client Daemon on all interfaces. Feb 17 09:44:02 volumio-bb systemd[1]: Finished glamor-test.service - Check for glamor. Feb 17 09:44:02 volumio-bb sh[963]: wlan0=wlan0 Feb 17 09:44:02 volumio-bb avahi-daemon[790]: Successfully called chroot(). Feb 17 09:44:02 volumio-bb avahi-daemon[790]: Successfully dropped remaining capabilities. Feb 17 09:44:02 volumio-bb bluetoothd[791]: Starting SDP server Feb 17 09:44:02 volumio-bb upmpdcli[806]: Could not open config: /tmp/upmpdcli.conf Feb 17 09:44:02 volumio-bb bluetoothd[791]: Excluding (cli) sap Feb 17 09:44:02 volumio-bb bluetoothd[791]: Excluding (cli) midi Feb 17 09:44:02 volumio-bb bluetoothd[791]: Excluding (cli) battery Feb 17 09:44:02 volumio-bb dhcpcd[904]: eth0: waiting for carrier Feb 17 09:44:02 volumio-bb dhcpcd[904]: wlan0: waiting for carrier Feb 17 09:44:02 volumio-bb avahi-daemon[790]: Loading service file /services/volumio.service. Feb 17 09:44:02 volumio-bb avahi-daemon[790]: Joining mDNS multicast group on interface lo.IPv4 with address 127.0.0.1. Feb 17 09:44:02 volumio-bb avahi-daemon[790]: New relevant interface lo.IPv4 for mDNS. Feb 17 09:44:02 volumio-bb avahi-daemon[790]: Network interface enumeration completed. Feb 17 09:44:02 volumio-bb avahi-daemon[790]: Registering new address record for 127.0.0.1 on lo.IPv4. Feb 17 09:44:02 volumio-bb systemd[1]: Started dbus.service - D-Bus System Message Bus. Feb 17 09:44:02 volumio-bb systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Feb 17 09:44:02 volumio-bb systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Feb 17 09:44:02 volumio-bb systemd[1]: iptables.service: Deactivated successfully. Feb 17 09:44:02 volumio-bb systemd[1]: Starting wpa_supplicant.service - WPA supplicant... Feb 17 09:44:02 volumio-bb systemd[1]: Finished rp1-test.service - Check for RP1 displays for Xorg. Feb 17 09:44:02 volumio-bb systemd[1]: Started systemd-logind.service - User Login Management. Feb 17 09:44:02 volumio-bb systemd[1]: Started bluetooth.service - Bluetooth service. Feb 17 09:44:02 volumio-bb dbus-daemon[792]: [system] Successfully activated service 'org.freedesktop.systemd1' Feb 17 09:44:02 volumio-bb systemd[1]: Started avahi-daemon.service - Avahi mDNS/DNS-SD Stack. Feb 17 09:44:02 volumio-bb systemd[1]: Starting bluealsa.service - BlueALSA service... Feb 17 09:44:02 volumio-bb kernel: Bluetooth: BNEP (Ethernet Emulation) ver 1.3 Feb 17 09:44:02 volumio-bb kernel: Bluetooth: BNEP filters: protocol multicast Feb 17 09:44:02 volumio-bb kernel: Bluetooth: BNEP socket layer initialized Feb 17 09:44:02 volumio-bb dbus-daemon[792]: [system] Activating via systemd: service name='org.freedesktop.hostname1' unit='dbus-org.freedesktop.hostname1.service' requested by ':1.2' (uid=0 pid=791 comm="/usr/libexec/bluetooth/bluetoothd --noplugin=sap,b") Feb 17 09:44:02 volumio-bb bluetoothd[791]: Bluetooth management interface 1.23 initialized Feb 17 09:44:02 volumio-bb bluetoothd[791]: Battery Provider Manager created Feb 17 09:44:02 volumio-bb kernel: Bluetooth: MGMT ver 1.23 Feb 17 09:44:02 volumio-bb loadcpufreq[833]: Loading cpufreq kernel modules...done (none). Feb 17 09:44:02 volumio-bb kernel: NET: Registered PF_ALG protocol family Feb 17 09:44:02 volumio-bb systemd[1]: Starting systemd-hostnamed.service - Hostname Service... Feb 17 09:44:02 volumio-bb systemd[1]: Started loadcpufreq.service - LSB: Load kernel modules needed to enable cpufreq scaling. Feb 17 09:44:02 volumio-bb systemd[1]: Starting cpufrequtils.service - LSB: set CPUFreq kernel parameters... Feb 17 09:44:02 volumio-bb kernel: cryptd: max_cpu_qlen set to 1000 Feb 17 09:44:02 volumio-bb wpa_supplicant[997]: Successfully initialized wpa_supplicant Feb 17 09:44:02 volumio-bb systemd[1]: Started wpa_supplicant.service - WPA supplicant. Feb 17 09:44:02 volumio-bb systemd[1]: Reached target network.target - Network. Feb 17 09:44:02 volumio-bb systemd[1]: Reached target network-online.target - Network is Online. Feb 17 09:44:02 volumio-bb systemd[1]: Starting ifplugd.service - LSB: Brings up/down network automatically... Feb 17 09:44:02 volumio-bb systemd[1]: Starting nmbd.service - Samba NMB Daemon... Feb 17 09:44:02 volumio-bb systemd[1]: Starting ntpsec.service - Network Time Service... Feb 17 09:44:02 volumio-bb systemd[1]: Starting rc-local.service - /etc/rc.local Compatibility... Feb 17 09:44:02 volumio-bb systemd[1]: Starting rpc-statd-notify.service - Notify NFS peers of a restart... Feb 17 09:44:02 volumio-bb systemd[1]: Starting samba-ad-dc.service - Samba AD Daemon... Feb 17 09:44:02 volumio-bb sm-notify[1047]: Version 2.6.2 starting Feb 17 09:44:02 volumio-bb systemd[1]: Starting setdatetime-helper.service - Time Synchronization Helper Service... Feb 17 09:44:02 volumio-bb cpufrequtils[1016]: CPUFreq Utilities: Setting ondemand CPUFreq governor...CPU0...CPU1...CPU2...CPU3...done. Feb 17 09:44:02 volumio-bb systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Feb 17 09:44:02 volumio-bb dbus-daemon[792]: [system] Successfully activated service 'org.freedesktop.hostname1' Feb 17 09:44:02 volumio-bb bluetoothd[791]: profiles/audio/bap.c:bap_adapter_probe() BAP requires ISO Socket which is not enabled Feb 17 09:44:02 volumio-bb bluetoothd[791]: bap: Operation not supported (95) Feb 17 09:44:02 volumio-bb systemd[1]: Starting ssh.service - OpenBSD Secure Shell server... Feb 17 09:44:02 volumio-bb systemd[1]: Starting systemd-user-sessions.service - Permit User Sessions... Feb 17 09:44:02 volumio-bb systemd[1]: Started volumio-ipchange.service - Volumio IP Change Monitor. Feb 17 09:44:02 volumio-bb bluetoothd[791]: Adv Monitor Manager created with supported features:0x00000000, enabled features:0x00000000, max number of supported monitors:32, max number of supported patterns:16 Feb 17 09:44:02 volumio-bb systemd[1]: Starting welcome.service - Show a welcome message on console... Feb 17 09:44:02 volumio-bb systemd[1]: Started cpufrequtils.service - LSB: set CPUFreq kernel parameters. Feb 17 09:44:02 volumio-bb systemd[1]: Started rc-local.service - /etc/rc.local Compatibility. Feb 17 09:44:02 volumio-bb systemd[1]: Started rpc-statd-notify.service - Notify NFS peers of a restart. Feb 17 09:44:02 volumio-bb systemd[1]: Started systemd-hostnamed.service - Hostname Service. Feb 17 09:44:02 volumio-bb systemd[1]: Finished systemd-user-sessions.service - Permit User Sessions. Feb 17 09:44:02 volumio-bb ntpd[1061]: INIT: ntpd ntpsec-1.2.2: Starting Feb 17 09:44:02 volumio-bb ntpd[1061]: INIT: Command line: /usr/sbin/ntpd -p /run/ntpd.pid -c /etc/ntpsec/ntp.conf -g -N -u ntpsec:ntpsec Feb 17 09:44:02 volumio-bb ntp-systemd-wrapper[1061]: 2026-02-17T09:44:02 ntpd[1061]: INIT: ntpd ntpsec-1.2.2: Starting Feb 17 09:44:02 volumio-bb ntp-systemd-wrapper[1061]: 2026-02-17T09:44:02 ntpd[1061]: INIT: Command line: /usr/sbin/ntpd -p /run/ntpd.pid -c /etc/ntpsec/ntp.conf -g -N -u ntpsec:ntpsec Feb 17 09:44:02 volumio-bb welcome[1066]: Resolved ip:[0] Feb 17 09:44:02 volumio-bb systemd[1]: Starting plymouth-quit-wait.service - Hold until boot process finishes up... Feb 17 09:44:02 volumio-bb systemd[1]: Started ntpsec.service - Network Time Service. Feb 17 09:44:02 volumio-bb ntpd[1083]: INIT: precision = 0.445 usec (-21) Feb 17 09:44:02 volumio-bb ntpd[1083]: INIT: successfully locked into RAM Feb 17 09:44:02 volumio-bb ifplugd(eth0)[1098]: ifplugd 0.28 initializing. Feb 17 09:44:02 volumio-bb ifplugd(eth0)[1098]: Using interface eth0/E4:5F:01:05:2D:4A with driver (version: 6.12.47-v7l+) Feb 17 09:44:02 volumio-bb ifplugd(eth0)[1098]: Using detection mode: SIOCETHTOOL Feb 17 09:44:02 volumio-bb ifplugd(eth0)[1098]: Initialization complete, link beat not detected. Feb 17 09:44:02 volumio-bb ntpd[1083]: CONFIG: readconfig: parsing file: /etc/ntpsec/ntp.conf Feb 17 09:44:02 volumio-bb ntpd[1083]: CONFIG: restrict nopeer ignored Feb 17 09:44:03 volumio-bb ntpd[1083]: CLOCK: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): good hash signature Feb 17 09:44:03 volumio-bb ntpd[1083]: CLOCK: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): loaded, expire=2026-06-28T00:00Z last=2017-01-01T00:00Z ofs=37 Feb 17 09:44:03 volumio-bb ntpd[1083]: INIT: Using SO_TIMESTAMPNS(ns) Feb 17 09:44:03 volumio-bb ntpd[1083]: IO: Listen and drop on 0 v6wildcard [::]:123 Feb 17 09:44:03 volumio-bb ntpd[1083]: IO: Listen and drop on 1 v4wildcard 0.0.0.0:123 Feb 17 09:44:03 volumio-bb ntpd[1083]: IO: Listen normally on 2 lo 127.0.0.1:123 Feb 17 09:44:03 volumio-bb ntpd[1083]: IO: Listening on routing socket on fd #19 for interface updates Feb 17 09:44:03 volumio-bb systemd[1]: Finished welcome.service - Show a welcome message on console. Feb 17 09:44:03 volumio-bb ifplugd[1031]: Network Interface Plugging Daemon...start eth0...done. Feb 17 09:44:03 volumio-bb systemd[1]: Started ifplugd.service - LSB: Brings up/down network automatically. Feb 17 09:44:03 volumio-bb ntpd[1083]: INIT: This system has a 32-bit time_t. Feb 17 09:44:03 volumio-bb ntpd[1083]: INIT: This ntpd will fail on 2038-01-19T03:14:07Z. Feb 17 09:44:03 volumio-bb ntpd[1083]: INIT: MRU 13107 entries, 13 hash bits, 32768 bytes Feb 17 09:44:03 volumio-bb ntpd[1083]: INIT: Built with OpenSSL 3.0.9 30 May 2023, 30000090 Feb 17 09:44:03 volumio-bb ntpd[1083]: INIT: Running with OpenSSL 3.0.18 30 Sep 2025, 30000120 Feb 17 09:44:03 volumio-bb ntpd[1083]: NTSc: Using system default root certificates. Feb 17 09:44:03 volumio-bb sshd[1112]: Server listening on 0.0.0.0 port 22. Feb 17 09:44:03 volumio-bb sshd[1112]: Server listening on :: port 22. Feb 17 09:44:03 volumio-bb systemd[1]: Started ssh.service - OpenBSD Secure Shell server. Feb 17 09:44:03 volumio-bb rpi-eeprom-update[797]: BOOTLOADER: up to date Feb 17 09:44:03 volumio-bb rpi-eeprom-update[797]: CURRENT: Fri Jan 9 16:12:13 UTC 2026 (1767975133) Feb 17 09:44:03 volumio-bb rpi-eeprom-update[797]: LATEST: Mon Dec 8 19:23:42 UTC 2025 (1765221822) Feb 17 09:44:03 volumio-bb rpi-eeprom-update[797]: RELEASE: default (/usr/lib/firmware/raspberrypi/bootloader-2711/default) Feb 17 09:44:03 volumio-bb rpi-eeprom-update[797]: Use raspi-config to change the release. Feb 17 09:44:03 volumio-bb rpi-eeprom-update[797]: VL805_FW: Using bootloader EEPROM Feb 17 09:44:03 volumio-bb rpi-eeprom-update[797]: VL805: up to date Feb 17 09:44:03 volumio-bb rpi-eeprom-update[797]: CURRENT: 000138c0 Feb 17 09:44:03 volumio-bb rpi-eeprom-update[797]: LATEST: 000138c0 Feb 17 09:44:03 volumio-bb systemd[1]: Finished rpi-eeprom-update.service - Check for Raspberry Pi EEPROM updates. Feb 17 09:44:03 volumio-bb avahi-daemon[790]: Server startup complete. Host name is volumio-bb.local. Local service cookie is 2659512206. Feb 17 09:44:03 volumio-bb ntpd[1083]: statistics directory /var/log/ntpsec/ does not exist or is unwriteable, error No such file or directory Feb 17 09:44:03 volumio-bb bluealsa[1009]: ../src/storage.c:90: Initializing persistent storage: /var/lib/bluealsa Feb 17 09:44:03 volumio-bb bluealsa[1009]: main.c:663: Starting main dispatching loop Feb 17 09:44:03 volumio-bb systemd[1]: Started bluealsa.service - BlueALSA service. Feb 17 09:44:03 volumio-bb bluealsa[1009]: main.c:118: Acquired D-Bus service name: org.bluealsa Feb 17 09:44:03 volumio-bb systemd[1]: Reached target bluetooth.target - Bluetooth Support. Feb 17 09:44:03 volumio-bb bluealsa[1009]: bluealsa-dbus.c:358: Registering BlueALSA D-Bus manager: /org/bluealsa Feb 17 09:44:03 volumio-bb bluealsa[1009]: bluez.c:153: Registering media application: /org/bluez/hci0 Feb 17 09:44:03 volumio-bb bluealsa[1009]: bluez.c:743: Exporting media endpoint object: /org/bluez/hci0/A2DP/SBC/source/1 Feb 17 09:44:03 volumio-bb bluealsa[1009]: bluez.c:743: Exporting media endpoint object: /org/bluez/hci0/A2DP/SBC/source/2 Feb 17 09:44:03 volumio-bb bluealsa[1009]: bluez.c:743: Exporting media endpoint object: /org/bluez/hci0/A2DP/SBC/sink/1 Feb 17 09:44:03 volumio-bb bluealsa[1009]: bluez.c:743: Exporting media endpoint object: /org/bluez/hci0/A2DP/SBC/sink/2 Feb 17 09:44:03 volumio-bb dbus-daemon[792]: [system] Activating via systemd: service name='org.freedesktop.UPower' unit='upower.service' requested by ':1.6' (uid=0 pid=1009 comm="/usr/bin/bluealsa -S -p a2dp-source -p a2dp-sink") Feb 17 09:44:03 volumio-bb systemd[1]: Starting upower.service - Daemon for power management... Feb 17 09:44:04 volumio-bb dbus-daemon[792]: [system] Successfully activated service 'org.freedesktop.UPower' Feb 17 09:44:04 volumio-bb systemd[1]: Started upower.service - Daemon for power management. Feb 17 09:44:04 volumio-bb bluetoothd[791]: Endpoint registered: sender=:1.6 path=/org/bluez/hci0/A2DP/SBC/source/1 Feb 17 09:44:04 volumio-bb bluetoothd[791]: Endpoint registered: sender=:1.6 path=/org/bluez/hci0/A2DP/SBC/sink/2 Feb 17 09:44:04 volumio-bb bluetoothd[791]: Endpoint registered: sender=:1.6 path=/org/bluez/hci0/A2DP/SBC/source/2 Feb 17 09:44:04 volumio-bb bluetoothd[791]: Endpoint registered: sender=:1.6 path=/org/bluez/hci0/A2DP/SBC/sink/1 Feb 17 09:44:04 volumio-bb systemd[1]: samba-ad-dc.service: Skipped due to 'exec-condition'. Feb 17 09:44:04 volumio-bb systemd[1]: Condition check resulted in samba-ad-dc.service - Samba AD Daemon being skipped. Feb 17 09:44:04 volumio-bb avahi-daemon[790]: Service "Volumio-bb" (/services/volumio.service) successfully established. Feb 17 09:44:04 volumio-bb ntpd[1083]: DNS: dns_probe: 0.debian.pool.ntp.org, cast_flags:8, flags:101 Feb 17 09:44:04 volumio-bb ntpd[1083]: DNS: dns_check: processing 0.debian.pool.ntp.org, 8, 101 Feb 17 09:44:04 volumio-bb ntpd[1083]: DNS: dns_check: DNS error: -11, System error Feb 17 09:44:04 volumio-bb ntpd[1083]: DNS: dns_take_status: 0.debian.pool.ntp.org=>error, 12 Feb 17 09:44:04 volumio-bb dhcpcd[726]: eth0: carrier acquired Feb 17 09:44:04 volumio-bb sh[719]: eth0: carrier acquired Feb 17 09:44:04 volumio-bb dhcpcd[904]: eth0: carrier acquired Feb 17 09:44:04 volumio-bb kernel: bcmgenet fd580000.ethernet eth0: Link is Up - 1Gbps/Full - flow control off Feb 17 09:44:04 volumio-bb dhcpcd[726]: eth0: IAID 01:05:2d:4a Feb 17 09:44:04 volumio-bb sh[719]: eth0: IAID 01:05:2d:4a Feb 17 09:44:04 volumio-bb dhcpcd[726]: eth0: adding address fe80::202:2f6c:6f79:ffa3 Feb 17 09:44:04 volumio-bb dhcpcd[726]: ipv6_addaddr1: Permission denied Feb 17 09:44:04 volumio-bb sh[719]: eth0: adding address fe80::202:2f6c:6f79:ffa3 Feb 17 09:44:04 volumio-bb sh[719]: ipv6_addaddr1: Permission denied Feb 17 09:44:04 volumio-bb dhcpcd[904]: eth0: IAID 01:05:2d:4a Feb 17 09:44:04 volumio-bb dhcpcd[904]: eth0: adding address fe80::202:2f6c:6f79:ffa3 Feb 17 09:44:04 volumio-bb dhcpcd[904]: ipv6_addaddr1: Permission denied Feb 17 09:44:04 volumio-bb nmbd[1158]: [2026/02/17 09:44:04.796221, 0] ../../source3/nmbd/nmbd.c:901(main) Feb 17 09:44:04 volumio-bb nmbd[1158]: nmbd version 4.17.8-Raspbian started. Feb 17 09:44:04 volumio-bb nmbd[1158]: Copyright Andrew Tridgell and the Samba Team 1992-2022 Feb 17 09:44:04 volumio-bb nmbd[1158]: [2026/02/17 09:44:04.809883, 0] ../../source3/nmbd/asyncdns.c:158(start_async_dns) Feb 17 09:44:04 volumio-bb nmbd[1158]: started asyncdns process 1164 Feb 17 09:44:04 volumio-bb nmbd[1158]: [2026/02/17 09:44:04.814590, 0] ../../lib/util/become_daemon.c:150(daemon_status) Feb 17 09:44:04 volumio-bb nmbd[1158]: daemon_status: daemon 'nmbd' : No local IPv4 non-loopback interfaces available, waiting for interface ... Feb 17 09:44:04 volumio-bb nmbd[1158]: [2026/02/17 09:44:04.814719, 0] ../../source3/nmbd/nmbd_subnetdb.c:252(create_subnets) Feb 17 09:44:04 volumio-bb nmbd[1158]: NOTE: NetBIOS name resolution is not supported for Internet Protocol Version 6 (IPv6). Feb 17 09:44:05 volumio-bb ifplugd(eth0)[1098]: Link beat detected. Feb 17 09:44:05 volumio-bb ifplugd(eth0)[1098]: Executing '/etc/ifplugd/ifplugd.action eth0 up'. Feb 17 09:44:05 volumio-bb dhcpcd[726]: eth0: soliciting an IPv6 router Feb 17 09:44:05 volumio-bb sh[719]: eth0: soliciting an IPv6 router Feb 17 09:44:05 volumio-bb dhcpcd[904]: eth0: soliciting a DHCP lease Feb 17 09:44:05 volumio-bb wireless.js[815]: WIRELESS.JS - INFO: Single Network Mode enabled (default) - only one network device can be active at a time between ethernet and wireless Feb 17 09:44:05 volumio-bb ifplugd(eth0)[1098]: client: ifup: waiting for lock on /run/network/ifstate.eth0 Feb 17 09:44:05 volumio-bb wireless.js[815]: WIRELESS.JS - INFO: === SNM TRANSITION === Feb 17 09:44:05 volumio-bb wireless.js[815]: WIRELESS.JS - INFO: Previous ethernet state: disconnected Feb 17 09:44:05 volumio-bb wireless.js[815]: WIRELESS.JS - INFO: New ethernet state: connected Feb 17 09:44:05 volumio-bb wireless.js[815]: WIRELESS.JS - INFO: Single Network Mode: enabled Feb 17 09:44:05 volumio-bb wireless.js[815]: WIRELESS.JS - INFO: First start: yes Feb 17 09:44:05 volumio-bb wireless.js[815]: WIRELESS.JS - INFO: Action: Switch to ethernet (WiFi scan mode) Feb 17 09:44:05 volumio-bb wireless.js[815]: WIRELESS.JS - INFO: === END TRANSITION === Feb 17 09:44:05 volumio-bb wireless.js[815]: WIRELESS.JS - INFO: Wireless.js initializing wireless flow Feb 17 09:44:05 volumio-bb ntpd[1083]: DNS: dns_probe: 1.debian.pool.ntp.org, cast_flags:8, flags:101 Feb 17 09:44:05 volumio-bb ntpd[1083]: DNS: dns_check: processing 1.debian.pool.ntp.org, 8, 101 Feb 17 09:44:05 volumio-bb ntpd[1083]: DNS: dns_check: DNS error: -11, System error Feb 17 09:44:05 volumio-bb ntpd[1083]: DNS: dns_take_status: 1.debian.pool.ntp.org=>error, 12 Feb 17 09:44:05 volumio-bb dhcpcd[904]: eth0: soliciting an IPv6 router Feb 17 09:44:05 volumio-bb sudo[1188]: root : PWD=/ ; USER=root ; COMMAND=/sbin/ip addr flush dev wlan0 Feb 17 09:44:05 volumio-bb sudo[1188]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Feb 17 09:44:05 volumio-bb sudo[1188]: pam_unix(sudo:session): session closed for user root Feb 17 09:44:05 volumio-bb sudo[1190]: root : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 down Feb 17 09:44:05 volumio-bb sudo[1190]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Feb 17 09:44:05 volumio-bb sh[719]: eth0: soliciting a DHCP lease Feb 17 09:44:05 volumio-bb dhcpcd[726]: eth0: soliciting a DHCP lease Feb 17 09:44:06 volumio-bb systemd[1]: systemd-rfkill.service: Deactivated successfully. Feb 17 09:44:06 volumio-bb sudo[1190]: pam_unix(sudo:session): session closed for user root Feb 17 09:44:06 volumio-bb wireless.js[815]: WIRELESS.JS - INFO: Cleaning previous... Feb 17 09:44:06 volumio-bb sudo[1200]: root : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 up Feb 17 09:44:06 volumio-bb sudo[1200]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Feb 17 09:44:06 volumio-bb kernel: brcmfmac: brcmf_cfg80211_set_power_mgmt: power save disabled Feb 17 09:44:06 volumio-bb sudo[1200]: pam_unix(sudo:session): session closed for user root Feb 17 09:44:06 volumio-bb wireless.js[815]: WIRELESS.JS - INFO: InterfaceValidator: READY - wlan0 is ready for operations Feb 17 09:44:06 volumio-bb wireless.js[815]: WIRELESS.JS - INFO: InterfaceValidator: wlan0 became ready after 4ms Feb 17 09:44:06 volumio-bb wireless.js[815]: WIRELESS.JS - INFO: ensureInterfaceReady: Interface ready (MAC: e4:5f:01:05:2d:4b) Feb 17 09:44:06 volumio-bb sudo[1207]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iw reg get Feb 17 09:44:06 volumio-bb sudo[1207]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 17 09:44:06 volumio-bb sudo[1207]: pam_unix(sudo:session): session closed for user root Feb 17 09:44:06 volumio-bb sudo[1216]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iw wlan0 scan Feb 17 09:44:06 volumio-bb sudo[1216]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 17 09:44:06 volumio-bb ntpd[1083]: DNS: dns_probe: 2.debian.pool.ntp.org, cast_flags:8, flags:101 Feb 17 09:44:06 volumio-bb ntpd[1083]: DNS: dns_check: processing 2.debian.pool.ntp.org, 8, 101 Feb 17 09:44:06 volumio-bb ntpd[1083]: DNS: dns_check: DNS error: -11, System error Feb 17 09:44:06 volumio-bb ntpd[1083]: DNS: dns_take_status: 2.debian.pool.ntp.org=>error, 12 Feb 17 09:44:07 volumio-bb volumio-remote-updater[812]: [2026-02-17 09:44:07] [info] asio async_connect error: asio.system:111 (Connection refused) Feb 17 09:44:07 volumio-bb volumio-remote-updater[812]: [2026-02-17 09:44:07] [info] Error getting remote endpoint: asio.system:107 (Transport endpoint is not connected) Feb 17 09:44:07 volumio-bb volumio-remote-updater[812]: [2026-02-17 09:44:07] [error] handle_connect error: Connection refused Feb 17 09:44:07 volumio-bb ntpd[1083]: DNS: dns_probe: 3.debian.pool.ntp.org, cast_flags:8, flags:101 Feb 17 09:44:07 volumio-bb ntpd[1083]: DNS: dns_check: processing 3.debian.pool.ntp.org, 8, 101 Feb 17 09:44:07 volumio-bb ntpd[1083]: DNS: dns_check: DNS error: -11, System error Feb 17 09:44:07 volumio-bb ntpd[1083]: DNS: dns_take_status: 3.debian.pool.ntp.org=>error, 12 Feb 17 09:44:09 volumio-bb sudo[1216]: pam_unix(sudo:session): session closed for user root Feb 17 09:44:09 volumio-bb wireless.js[815]: WIRELESS.JS - INFO: SETTING APPROPRIATE REG DOMAIN: MT Feb 17 09:44:09 volumio-bb sudo[1242]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iw reg set MT Feb 17 09:44:09 volumio-bb sudo[1242]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 17 09:44:09 volumio-bb sudo[1242]: pam_unix(sudo:session): session closed for user root Feb 17 09:44:09 volumio-bb wireless.js[815]: WIRELESS.JS - INFO: SUCCESSFULLY SET NEW REGDOMAIN: MT Feb 17 09:44:09 volumio-bb wireless.js[815]: WIRELESS.JS - INFO: Single Network Mode: Ethernet active, maintaining WiFi scan capability Feb 17 09:44:09 volumio-bb wireless.js[815]: WIRELESS.JS - INFO: SNM: Maintaining wlan0 UP without IP (scan mode) Feb 17 09:44:09 volumio-bb wireless.js[815]: WIRELESS.JS - INFO: SNM: Users can configure WiFi via WebUI while ethernet is active Feb 17 09:44:09 volumio-bb sudo[1251]: root : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 up Feb 17 09:44:09 volumio-bb sudo[1251]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Feb 17 09:44:09 volumio-bb sudo[1251]: pam_unix(sudo:session): session closed for user root Feb 17 09:44:09 volumio-bb sudo[1254]: root : PWD=/ ; USER=root ; COMMAND=/sbin/ip addr flush dev wlan0 Feb 17 09:44:09 volumio-bb sudo[1254]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Feb 17 09:44:09 volumio-bb sudo[1254]: pam_unix(sudo:session): session closed for user root Feb 17 09:44:09 volumio-bb wpa_supplicant[1257]: Successfully initialized wpa_supplicant Feb 17 09:44:09 volumio-bb bash[1055]: setdatetime-helper: all HTTPS Date fallbacks failed Feb 17 09:44:09 volumio-bb systemd[1]: setdatetime-helper.service: Deactivated successfully. Feb 17 09:44:09 volumio-bb systemd[1]: Finished setdatetime-helper.service - Time Synchronization Helper Service. Feb 17 09:44:09 volumio-bb wpa_supplicant[1257]: nl80211: kernel reports: Registration to specific type not supported Feb 17 09:44:10 volumio-bb wpa_supplicant[1261]: wlan0: CTRL-EVENT-DSCP-POLICY clear_all Feb 17 09:44:10 volumio-bb wireless.js[815]: WIRELESS.JS - INFO: SNM: Transition to scan mode completed in 4712ms Feb 17 09:44:10 volumio-bb wireless.js[815]: WIRELESS.JS - INFO: SNM: wlan0 is UP without IP, scan capable Feb 17 09:44:10 volumio-bb wireless.js[815]: WIRELESS.JS - INFO: Notified systemd about wireless ready Feb 17 09:44:10 volumio-bb kernel: brcmfmac: brcmf_cfg80211_set_power_mgmt: power save disabled Feb 17 09:44:10 volumio-bb systemd[1]: Started wireless.service - Wireless Services. Feb 17 09:44:10 volumio-bb systemd[1]: Started volumio.service - Volumio Backend Module. Feb 17 09:44:10 volumio-bb systemd[1]: Starting plymouth-quit.service - Terminate Plymouth Boot Screen... Feb 17 09:44:10 volumio-bb systemd[1]: Started volumio_cpu_tweak.service - Volumio Cpu Tweaker. Feb 17 09:44:10 volumio-bb systemd[1]: Received SIGRTMIN+21 from PID 324 (plymouthd). Feb 17 09:44:10 volumio-bb volumio-cpu-tweak[1282]: Setting RT Priority for mpd Feb 17 09:44:10 volumio-bb volumio-cpu-tweak[1296]: pid 35's current scheduling policy: SCHED_OTHER Feb 17 09:44:10 volumio-bb volumio-cpu-tweak[1296]: pid 35's current scheduling priority: 0 Feb 17 09:44:10 volumio-bb volumio-cpu-tweak[1282]: Setting MPD Affinity Feb 17 09:44:10 volumio-bb volumio-cpu-tweak[1297]: pid 3's current affinity mask: f Feb 17 09:44:10 volumio-bb volumio-cpu-tweak[1282]: /bin/volumio_cpu_tweak: line 27: warning: command substitution: ignored null byte in input Feb 17 09:44:10 volumio-bb volumio-cpu-tweak[1282]: VOLUMIO CPU TWEAK: Setting CPU Governor: performance Feb 17 09:44:10 volumio-bb systemd[1]: Finished plymouth-quit-wait.service - Hold until boot process finishes up. Feb 17 09:44:10 volumio-bb systemd[1]: Received SIGRTMIN+21 from PID 324 (plymouthd). Feb 17 09:44:10 volumio-bb systemd[1]: Finished plymouth-quit.service - Terminate Plymouth Boot Screen. Feb 17 09:44:10 volumio-bb systemd[1]: Started getty@tty1.service - Getty on tty1. Feb 17 09:44:10 volumio-bb systemd[1]: Reached target getty.target - Login Prompts. Feb 17 09:44:10 volumio-bb systemd[1]: volumio_cpu_tweak.service: Deactivated successfully. Feb 17 09:44:13 volumio-bb volumio[1280]: info: ------------------------------------------- Feb 17 09:44:13 volumio-bb volumio[1280]: info: ----- Volumio3 ---- Feb 17 09:44:13 volumio-bb volumio[1280]: info: ------------------------------------------- Feb 17 09:44:13 volumio-bb volumio[1280]: info: ----- System startup ---- Feb 17 09:44:13 volumio-bb volumio[1280]: info: ------------------------------------------- Feb 17 09:44:14 volumio-bb volumio[1280]: info: MYVOLUMIO Environment detected Feb 17 09:44:14 volumio-bb volumio[1280]: info: Plugin folders cleanup Feb 17 09:44:14 volumio-bb volumio[1280]: info: Scanning into folder /volumio/app/plugins/ Feb 17 09:44:14 volumio-bb volumio[1280]: info: Scanning category audio_interface Feb 17 09:44:14 volumio-bb volumio[1280]: info: Scanning category miscellanea Feb 17 09:44:14 volumio-bb volumio[1280]: info: Scanning category music_service Feb 17 09:44:14 volumio-bb volumio[1280]: info: Scanning category plugins.json Feb 17 09:44:14 volumio-bb volumio[1280]: info: Scanning category system_controller Feb 17 09:44:14 volumio-bb volumio[1280]: info: Scanning category user_interface Feb 17 09:44:14 volumio-bb volumio[1280]: info: Scanning into folder /data/plugins/ Feb 17 09:44:14 volumio-bb volumio[1280]: info: Scanning category music_service Feb 17 09:44:14 volumio-bb volumio[1280]: info: Scanning category user_interface Feb 17 09:44:14 volumio-bb volumio[1280]: info: Plugin folders cleanup completed Feb 17 09:44:14 volumio-bb volumio[1280]: info: ------------------------------------------- Feb 17 09:44:14 volumio-bb volumio[1280]: info: ----- Core plugins startup ---- Feb 17 09:44:14 volumio-bb volumio[1280]: info: ------------------------------------------- Feb 17 09:44:14 volumio-bb volumio[1280]: info: Loading plugins from folder /volumio/app/plugins/ Feb 17 09:44:14 volumio-bb volumio[1280]: info: Adding plugin upnp to MyMusic Plugins Feb 17 09:44:14 volumio-bb volumio[1280]: info: Adding plugin airplay_emulation to MyMusic Plugins Feb 17 09:44:14 volumio-bb volumio[1280]: info: Adding plugin upnp_browser to MyMusic Plugins Feb 17 09:44:14 volumio-bb volumio-remote-updater[812]: [2026-02-17 09:44:14] [connect] Successful connection Feb 17 09:44:14 volumio-bb volumio[1280]: info: Loading plugins from folder /data/plugins/ Feb 17 09:44:14 volumio-bb volumio[1280]: info: Loading plugin "system"... Feb 17 09:44:14 volumio-bb volumio[1280]: info: Loading plugin "appearance"... Feb 17 09:44:16 volumio-bb volumio[1280]: info: Loading plugin "network"... Feb 17 09:44:16 volumio-bb volumio[1280]: info: Refreshing Cached IP Addresses Feb 17 09:44:16 volumio-bb volumio[1280]: info: Loading plugin "services"... Feb 17 09:44:16 volumio-bb sudo[1317]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Feb 17 09:44:16 volumio-bb sudo[1317]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 17 09:44:16 volumio-bb volumio[1280]: info: Loading plugin "volumio5onboarding"... Feb 17 09:44:16 volumio-bb sudo[1316]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Feb 17 09:44:16 volumio-bb sudo[1316]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 17 09:44:16 volumio-bb sudo[1316]: pam_unix(sudo:session): session closed for user root Feb 17 09:44:16 volumio-bb sudo[1317]: pam_unix(sudo:session): session closed for user root Feb 17 09:44:16 volumio-bb volumio[1280]: info: Loading plugin "alsa_controller"... Feb 17 09:44:16 volumio-bb sudo[1328]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Feb 17 09:44:16 volumio-bb sudo[1328]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 17 09:44:16 volumio-bb volumio[1280]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Feb 17 09:44:16 volumio-bb volumio[1280]: info: Loading plugin "wizard"... Feb 17 09:44:16 volumio-bb volumio[1280]: info: Loading plugin "networkfs"... Feb 17 09:44:16 volumio-bb volumio[1280]: info: Starting Udev Watcher for removable devices Feb 17 09:44:16 volumio-bb sudo[1346]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=toniolombardi,password=O0grPinbJhCvqzI66,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //tl-nas1.toniolombardi.com/music /mnt/NAS/tl-nas1 Feb 17 09:44:16 volumio-bb sudo[1346]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 17 09:44:16 volumio-bb sudo[1346]: pam_unix(sudo:session): session closed for user root Feb 17 09:44:16 volumio-bb volumio[1280]: info: Ignoring mount for partition: boot Feb 17 09:44:16 volumio-bb volumio[1280]: info: Ignoring mount for partition: volumio Feb 17 09:44:16 volumio-bb volumio[1280]: info: Ignoring mount for partition: volumio_data Feb 17 09:44:16 volumio-bb volumio[1280]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Feb 17 09:44:16 volumio-bb volumio[1280]: info: Loading plugin "volumio_command_line_client"... Feb 17 09:44:16 volumio-bb volumio[1280]: info: Loading plugin "upnp"... Feb 17 09:44:16 volumio-bb volumio[1280]: info: [1771317856488] Starting Upmpd Daemon Feb 17 09:44:16 volumio-bb volumio[1280]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Feb 17 09:44:16 volumio-bb volumio[1280]: info: Loading plugin "my_music"... Feb 17 09:44:16 volumio-bb volumio[1280]: info: Loading plugin "mpd"... Feb 17 09:44:16 volumio-bb dhcpcd[904]: eth0: offered 192.168.3.102 from 192.168.3.1 Feb 17 09:44:16 volumio-bb dhcpcd[904]: eth0: probing address 192.168.3.102/24 Feb 17 09:44:16 volumio-bb volumio[1280]: info: Loading plugin "upnp_browser"... Feb 17 09:44:17 volumio-bb sh[719]: eth0: offered 192.168.3.102 from 192.168.3.1 Feb 17 09:44:17 volumio-bb dhcpcd[726]: eth0: offered 192.168.3.102 from 192.168.3.1 Feb 17 09:44:17 volumio-bb sh[719]: eth0: probing address 192.168.3.102/24 Feb 17 09:44:17 volumio-bb dhcpcd[726]: eth0: probing address 192.168.3.102/24 Feb 17 09:44:17 volumio-bb systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 1. Feb 17 09:44:17 volumio-bb systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Feb 17 09:44:17 volumio-bb systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Feb 17 09:44:17 volumio-bb upmpdcli[1352]: Could not open config: /tmp/upmpdcli.conf Feb 17 09:44:17 volumio-bb systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Feb 17 09:44:17 volumio-bb systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Feb 17 09:44:18 volumio-bb volumio[1280]: info: Starting UPNP Browser Feb 17 09:44:18 volumio-bb volumio[1280]: info: Loading plugin "alarm-clock"... Feb 17 09:44:18 volumio-bb volumio[1280]: info: Loading plugin "airplay_emulation"... Feb 17 09:44:18 volumio-bb volumio[1280]: info: Starting Shairport Sync Feb 17 09:44:18 volumio-bb volumio[1280]: info: Loading plugin "last_100"... Feb 17 09:44:18 volumio-bb volumio[1280]: info: Loading plugin "webradio"... Feb 17 09:44:18 volumio-bb volumio[1280]: info: Loading plugin "i2s_dacs"... Feb 17 09:44:18 volumio-bb volumio[1280]: info: I2S DAC not set, start Auto-detection Feb 17 09:44:18 volumio-bb volumio[1280]: info: Loading plugin "volumiodiscovery"... Feb 17 09:44:18 volumio-bb volumio[1280]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Feb 17 09:44:18 volumio-bb volumio[1280]: *** WARNING *** Please fix your application to use the native API of Avahi! Feb 17 09:44:18 volumio-bb volumio[1280]: *** WARNING *** For more information see Feb 17 09:44:18 volumio-bb volumio[1280]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Feb 17 09:44:18 volumio-bb volumio[1280]: *** WARNING *** Please fix your application to use the native API of Avahi! Feb 17 09:44:18 volumio-bb volumio[1280]: *** WARNING *** For more information see Feb 17 09:44:18 volumio-bb node[1280]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Feb 17 09:44:18 volumio-bb node[1280]: *** WARNING *** Please fix your application to use the native API of Avahi! Feb 17 09:44:18 volumio-bb node[1280]: *** WARNING *** For more information see Feb 17 09:44:18 volumio-bb node[1280]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Feb 17 09:44:18 volumio-bb node[1280]: *** WARNING *** Please fix your application to use the native API of Avahi! Feb 17 09:44:18 volumio-bb node[1280]: *** WARNING *** For more information see Feb 17 09:44:18 volumio-bb volumio[1280]: info: Applying required configuration parameters for plugin volumiodiscovery Feb 17 09:44:18 volumio-bb volumio[1280]: info: Discovery: Started advertising with name: Volumio-bb Feb 17 09:44:18 volumio-bb volumio[1280]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Feb 17 09:44:18 volumio-bb volumio[1280]: info: Loading plugin "spop"... Feb 17 09:44:18 volumio-bb sudo[1328]: pam_unix(sudo:session): session closed for user root Feb 17 09:44:20 volumio-bb volumio[1280]: info: Loading plugin "now_playing"... Feb 17 09:44:21 volumio-bb dhcpcd[904]: eth0: leased 192.168.3.102 for 86400 seconds Feb 17 09:44:21 volumio-bb avahi-daemon[790]: Joining mDNS multicast group on interface eth0.IPv4 with address 192.168.3.102. Feb 17 09:44:21 volumio-bb avahi-daemon[790]: New relevant interface eth0.IPv4 for mDNS. Feb 17 09:44:21 volumio-bb avahi-daemon[790]: Registering new address record for 192.168.3.102 on eth0.IPv4. Feb 17 09:44:21 volumio-bb dhcpcd[904]: eth0: adding route to 192.168.3.0/24 Feb 17 09:44:21 volumio-bb dhcpcd[904]: eth0: adding default route via 192.168.3.1 Feb 17 09:44:21 volumio-bb systemd[1]: welcome.service: Deactivated successfully. Feb 17 09:44:21 volumio-bb systemd[1]: Stopped welcome.service - Show a welcome message on console. Feb 17 09:44:21 volumio-bb systemd[1]: Stopping welcome.service - Show a welcome message on console... Feb 17 09:44:21 volumio-bb systemd[1]: Starting welcome.service - Show a welcome message on console... Feb 17 09:44:21 volumio-bb systemd[1]: Started nmbd.service - Samba NMB Daemon. Feb 17 09:44:21 volumio-bb welcome[1373]: Resolved ip:[1] 192.168.3.102 Feb 17 09:44:21 volumio-bb systemd[1]: Starting winbind.service - Samba Winbind Daemon... Feb 17 09:44:21 volumio-bb systemd[1]: Finished welcome.service - Show a welcome message on console. Feb 17 09:44:21 volumio-bb systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Feb 17 09:44:22 volumio-bb winbindd[1389]: [2026/02/17 09:44:22.090275, 0] ../../source3/winbindd/winbindd.c:1440(main) Feb 17 09:44:22 volumio-bb winbindd[1389]: winbindd version 4.17.8-Raspbian started. Feb 17 09:44:22 volumio-bb winbindd[1389]: Copyright Andrew Tridgell and the Samba Team 1992-2022 Feb 17 09:44:22 volumio-bb winbindd[1389]: [2026/02/17 09:44:22.106418, 0] ../../source3/winbindd/winbindd_cache.c:3116(initialize_winbindd_cache) Feb 17 09:44:22 volumio-bb winbindd[1389]: initialize_winbindd_cache: clearing cache and re-creating with version number 2 Feb 17 09:44:22 volumio-bb systemd[1]: Started winbind.service - Samba Winbind Daemon. Feb 17 09:44:22 volumio-bb systemd[1]: Starting smbd.service - Samba SMB Daemon... Feb 17 09:44:22 volumio-bb sh[719]: eth0: leased 192.168.3.102 for 86400 seconds Feb 17 09:44:22 volumio-bb dhcpcd[726]: eth0: leased 192.168.3.102 for 86400 seconds Feb 17 09:44:22 volumio-bb dhcpcd[726]: eth0: adding route to 192.168.3.0/24 Feb 17 09:44:22 volumio-bb sh[719]: eth0: adding route to 192.168.3.0/24 Feb 17 09:44:22 volumio-bb sh[719]: eth0: adding default route via 192.168.3.1 Feb 17 09:44:22 volumio-bb dhcpcd[726]: eth0: adding default route via 192.168.3.1 Feb 17 09:44:22 volumio-bb systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Feb 17 09:44:22 volumio-bb systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Feb 17 09:44:22 volumio-bb systemd[1]: welcome.service: Deactivated successfully. Feb 17 09:44:22 volumio-bb systemd[1]: Stopped welcome.service - Show a welcome message on console. Feb 17 09:44:22 volumio-bb systemd[1]: Stopping welcome.service - Show a welcome message on console... Feb 17 09:44:22 volumio-bb smbd[1396]: [2026/02/17 09:44:22.579209, 0] ../../source3/smbd/server.c:1741(main) Feb 17 09:44:22 volumio-bb smbd[1396]: smbd version 4.17.8-Raspbian started. Feb 17 09:44:22 volumio-bb smbd[1396]: Copyright Andrew Tridgell and the Samba Team 1992-2022 Feb 17 09:44:22 volumio-bb systemd[1]: Starting welcome.service - Show a welcome message on console... Feb 17 09:44:22 volumio-bb welcome[1430]: Resolved ip:[1] 192.168.3.102 Feb 17 09:44:22 volumio-bb sh[719]: Failed to try-restart systemd-timesyncd.service: Unit systemd-timesyncd.service not found. Feb 17 09:44:22 volumio-bb sh[719]: forked to background, child pid 725 Feb 17 09:44:22 volumio-bb volumio[1280]: info: Loading plugin "outputs"... Feb 17 09:44:22 volumio-bb systemd[1]: Finished welcome.service - Show a welcome message on console. Feb 17 09:44:22 volumio-bb systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Feb 17 09:44:22 volumio-bb volumio[1280]: info: Loading plugin "albumart"... Feb 17 09:44:22 volumio-bb volumio[1280]: info: Plugin example_plugin is not enabled Feb 17 09:44:22 volumio-bb volumio[1280]: info: Loading plugin "inputs"... Feb 17 09:44:22 volumio-bb volumio[1280]: info: Loading plugin "updater_comm"... Feb 17 09:44:22 volumio-bb sh[1476]: eth0=eth0 Feb 17 09:44:22 volumio-bb ifplugd(eth0)[1098]: client: ifup: interface eth0 already configured Feb 17 09:44:22 volumio-bb ifplugd(eth0)[1098]: Program executed successfully. Feb 17 09:44:23 volumio-bb volumio[1280]: info: Plugin mpdemulation is not enabled Feb 17 09:44:23 volumio-bb volumio[1280]: info: Loading plugin "rest_api"... Feb 17 09:44:23 volumio-bb volumio[1280]: info: Loading plugin "websocket"... Feb 17 09:44:23 volumio-bb volumio[1280]: info: Starting Socket.io Server version 1.7.4 Feb 17 09:44:23 volumio-bb volumio[1280]: info: Plugin peppymeterbasic is not enabled Feb 17 09:44:23 volumio-bb volumio[1280]: info: Loading plugin "peppyspectrum"... Feb 17 09:44:23 volumio-bb volumio[1456]: Forking 3 albumart workers Feb 17 09:44:23 volumio-bb systemd[1]: Started smbd.service - Samba SMB Daemon. Feb 17 09:44:23 volumio-bb systemd[1]: Reached target multi-user.target - Multi-User System. Feb 17 09:44:23 volumio-bb systemd[1]: Reached target graphical.target - Graphical Interface. Feb 17 09:44:23 volumio-bb systemd[1]: Starting systemd-update-utmp-runlevel.service - Record Runlevel Change in UTMP... Feb 17 09:44:23 volumio-bb systemd[1]: systemd-update-utmp-runlevel.service: Deactivated successfully. Feb 17 09:44:23 volumio-bb systemd[1]: Finished systemd-update-utmp-runlevel.service - Record Runlevel Change in UTMP. Feb 17 09:44:23 volumio-bb systemd[1]: Startup finished in 13.534s (kernel) + 26.089s (userspace) = 39.624s. Feb 17 09:44:24 volumio-bb ntpd[1083]: IO: Listen normally on 3 eth0 192.168.3.102:123 Feb 17 09:44:24 volumio-bb ntpd[1083]: IO: new interface(s) found: waking up resolver Feb 17 09:44:24 volumio-bb ntpd[1083]: DNS: dns_probe: 3.debian.pool.ntp.org, cast_flags:8, flags:101 Feb 17 09:44:24 volumio-bb ntpd[1083]: DNS: dns_check: processing 3.debian.pool.ntp.org, 8, 101 Feb 17 09:44:24 volumio-bb ntpd[1083]: DNS: Pool taking: 94.142.246.192 Feb 17 09:44:24 volumio-bb ntpd[1083]: DNS: Pool taking: 89.109.251.23 Feb 17 09:44:24 volumio-bb ntpd[1083]: DNS: Pool taking: 84.27.222.8 Feb 17 09:44:24 volumio-bb ntpd[1083]: DNS: Pool taking: 46.146.231.187 Feb 17 09:44:24 volumio-bb ntpd[1083]: DNS: dns_take_status: 3.debian.pool.ntp.org=>good, 8 Feb 17 09:44:25 volumio-bb ntpd[1083]: DNS: dns_probe: 2.debian.pool.ntp.org, cast_flags:8, flags:101 Feb 17 09:44:25 volumio-bb ntpd[1083]: DNS: dns_check: processing 2.debian.pool.ntp.org, 8, 101 Feb 17 09:44:25 volumio-bb ntpd[1083]: DNS: Pool taking: 195.161.69.241 Feb 17 09:44:25 volumio-bb ntpd[1083]: DNS: Pool taking: 129.152.16.145 Feb 17 09:44:25 volumio-bb ntpd[1083]: DNS: Pool taking: 78.143.220.46 Feb 17 09:44:25 volumio-bb ntpd[1083]: DNS: Pool taking: 162.19.170.154 Feb 17 09:44:25 volumio-bb ntpd[1083]: DNS: Pool taking: 2a01:7e00::f03c:94ff:fe78:a7d1 Feb 17 09:44:25 volumio-bb ntpd[1083]: DNS: Pool taking: 2a14:2d86:0:c::1 Feb 17 09:44:25 volumio-bb ntpd[1083]: DNS: Pool taking: 2003:a:47f:abe4::1 Feb 17 09:44:25 volumio-bb ntpd[1083]: DNS: Pool taking: 2001:9b1:9bd0::aa Feb 17 09:44:25 volumio-bb ntpd[1083]: DNS: dns_take_status: 2.debian.pool.ntp.org=>good, 8 Feb 17 09:44:25 volumio-bb volumio[1280]: info: Plugin touch_display is not enabled Feb 17 09:44:25 volumio-bb volumio[1280]: info: Loading i18n strings for locale en Feb 17 09:44:25 volumio-bb volumio[1280]: Updating browse sources language Feb 17 09:44:25 volumio-bb volumio[1280]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 17 09:44:26 volumio-bb ntpd[1083]: DNS: dns_probe: 1.debian.pool.ntp.org, cast_flags:8, flags:101 Feb 17 09:44:26 volumio-bb ntpd[1083]: DNS: dns_check: processing 1.debian.pool.ntp.org, 8, 101 Feb 17 09:44:26 volumio-bb ntpd[1083]: DNS: Pool taking: 171.25.158.11 Feb 17 09:44:26 volumio-bb ntpd[1083]: DNS: Pool taking: 78.46.56.170 Feb 17 09:44:26 volumio-bb ntpd[1083]: DNS: Pool taking: 46.160.198.122 Feb 17 09:44:26 volumio-bb ntpd[1083]: DNS: Pool taking: 176.58.127.131 Feb 17 09:44:26 volumio-bb ntpd[1083]: DNS: dns_take_status: 1.debian.pool.ntp.org=>good, 8 Feb 17 09:44:26 volumio-bb volumio[1280]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 17 09:44:26 volumio-bb volumio[1280]: info: CoreCommandRouter::initPlayerControls Feb 17 09:44:26 volumio-bb volumio[1280]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 17 09:44:26 volumio-bb volumio[1280]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 17 09:44:26 volumio-bb volumio[1280]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 17 09:44:26 volumio-bb volumio[1280]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 17 09:44:26 volumio-bb volumio[1280]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 17 09:44:26 volumio-bb volumio[1280]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 17 09:44:26 volumio-bb volumio[1280]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 17 09:44:26 volumio-bb volumio[1280]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 17 09:44:26 volumio-bb volumio[1280]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 17 09:44:26 volumio-bb volumio[1280]: Express server listening on port 3000 Feb 17 09:44:26 volumio-bb volumio[1280]: [Metrics] WebUI: 14s 650.58ms Feb 17 09:44:27 volumio-bb volumio[1280]: info: CoreStateMachine::resetVolumioState Feb 17 09:44:27 volumio-bb volumio[1280]: info: CoreStateMachine::getcurrentVolume Feb 17 09:44:27 volumio-bb volumio[1280]: info: CoreCommandRouter::volumioRetrievevolume Feb 17 09:44:27 volumio-bb volumio[1280]: info: CoreStateMachine::pushState Feb 17 09:44:27 volumio-bb volumio[1280]: info: CorePlayQueue::getTrack 0 Feb 17 09:44:27 volumio-bb volumio[1280]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 17 09:44:27 volumio-bb volumio[1280]: info: CoreCommandRouter::volumioPushState Feb 17 09:44:27 volumio-bb volumio[1280]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 17 09:44:27 volumio-bb sudo[1535]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Feb 17 09:44:27 volumio-bb ntpd[1083]: DNS: dns_probe: 0.debian.pool.ntp.org, cast_flags:8, flags:101 Feb 17 09:44:27 volumio-bb sudo[1535]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 17 09:44:27 volumio-bb sudo[1537]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Feb 17 09:44:27 volumio-bb sudo[1537]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 17 09:44:27 volumio-bb sudo[1535]: pam_unix(sudo:session): session closed for user root Feb 17 09:44:27 volumio-bb ntpd[1083]: DNS: dns_check: processing 0.debian.pool.ntp.org, 8, 101 Feb 17 09:44:27 volumio-bb ntpd[1083]: DNS: Pool taking: 194.58.207.20 Feb 17 09:44:27 volumio-bb ntpd[1083]: DNS: Pool taking: 91.236.251.38 Feb 17 09:44:27 volumio-bb ntpd[1083]: DNS: Pool taking: 89.161.47.136 Feb 17 09:44:27 volumio-bb ntpd[1083]: DNS: Pool taking: 212.25.15.128 Feb 17 09:44:27 volumio-bb ntpd[1083]: DNS: dns_take_status: 0.debian.pool.ntp.org=>good, 8 Feb 17 09:44:27 volumio-bb sudo[1537]: pam_unix(sudo:session): session closed for user root Feb 17 09:44:27 volumio-bb volumio[1280]: info: Volumio Network Manager: Network status updated: 0 Feb 17 09:44:27 volumio-bb volumio[1280]: info: Cannot mount NAS tl-nas1 at system boot, trial number 1 ,retrying in 5 seconds Feb 17 09:44:28 volumio-bb volumio[1280]: verbose: New Socket.io Connection to 192.168.3.102 from 192.168.3.187 UA: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/145.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 1 Feb 17 09:44:28 volumio-bb volumio[1280]: info: Reloading queue from file Feb 17 09:44:28 volumio-bb volumio[1280]: verbose: New Socket.io Connection to 192.168.3.102 from 192.168.3.187 UA: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/145.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 2 Feb 17 09:44:28 volumio-bb volumio[1280]: info: Setting Device type: Raspberry PI Feb 17 09:44:28 volumio-bb volumio[1280]: info: CoreStateMachine::setRepeat null single undefined Feb 17 09:44:28 volumio-bb volumio[1280]: info: CoreStateMachine::pushState Feb 17 09:44:28 volumio-bb volumio[1280]: info: CorePlayQueue::getTrack 0 Feb 17 09:44:28 volumio-bb volumio[1280]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 17 09:44:28 volumio-bb volumio[1280]: info: CoreCommandRouter::volumioPushState Feb 17 09:44:28 volumio-bb volumio[1280]: info: CoreStateMachine::setRandom null Feb 17 09:44:28 volumio-bb volumio[1280]: info: CoreStateMachine::pushState Feb 17 09:44:28 volumio-bb volumio[1280]: info: CorePlayQueue::getTrack 0 Feb 17 09:44:28 volumio-bb volumio[1280]: info: CoreCommandRouter::volumioPushState Feb 17 09:44:28 volumio-bb volumio[1280]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Feb 17 09:44:28 volumio-bb volumio[1280]: info: USB Boot Capable - System SBC Revision found in cpuinfo: d03114 Feb 17 09:44:28 volumio-bb volumio[1280]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Feb 17 09:44:28 volumio-bb volumio[1280]: info: Discovery: adding 47cd6388-490c-493b-bfe4-41f068d16d34 Feb 17 09:44:28 volumio-bb volumio[1280]: info: Discovery: Found device Volumio-bb Feb 17 09:44:28 volumio-bb volumio[1280]: info: CoreCommandRouter::volumioGetState Feb 17 09:44:28 volumio-bb volumio[1280]: info: CorePlayQueue::getTrack 0 Feb 17 09:44:28 volumio-bb sudo[1552]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Feb 17 09:44:28 volumio-bb sudo[1552]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 17 09:44:28 volumio-bb volumio[1280]: info: Discovery: this is already registered, 47cd6388-490c-493b-bfe4-41f068d16d34 Feb 17 09:44:28 volumio-bb volumio[1280]: info: Discovery: Found device Volumio-bb Feb 17 09:44:28 volumio-bb volumio[1280]: info: CoreCommandRouter::volumioGetState Feb 17 09:44:28 volumio-bb volumio[1280]: info: CorePlayQueue::getTrack 0 Feb 17 09:44:29 volumio-bb volumio[1280]: info: Completed loading Core Plugins Feb 17 09:44:29 volumio-bb volumio[1280]: info: Preparing to generate the ALSA configuration file Feb 17 09:44:29 volumio-bb volumio[1280]: info: The plugin peppyspectrum has an ALSA contribution file peppy_in.peppy_out.6.conf Feb 17 09:44:29 volumio-bb volumio[1280]: info: Reading ALSA contributions from plugins. Feb 17 09:44:29 volumio-bb volumio[1280]: info: Asound.conf file unchanged, so no further update is needed Feb 17 09:44:29 volumio-bb volumio[1280]: info: Output device has changed, restarting MPD Feb 17 09:44:29 volumio-bb volumio[1280]: info: Output device has changed, restarting Shairport Sync Feb 17 09:44:29 volumio-bb volumio[1280]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 17 09:44:29 volumio-bb volumio[1280]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 17 09:44:29 volumio-bb volumio[1481]: Starting albumart workers Feb 17 09:44:29 volumio-bb sudo[1557]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Feb 17 09:44:29 volumio-bb sudo[1557]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 17 09:44:29 volumio-bb sudo[1555]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Feb 17 09:44:29 volumio-bb sudo[1555]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 17 09:44:29 volumio-bb volumio[1479]: Starting albumart workers Feb 17 09:44:29 volumio-bb volumio[1280]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Feb 17 09:44:29 volumio-bb volumio[1280]: info: ___________ START PLUGINS ___________ Feb 17 09:44:29 volumio-bb sudo[1555]: pam_unix(sudo:session): session closed for user root Feb 17 09:44:29 volumio-bb volumio[1280]: info: ControllerMpd::onStart: Initializing MPD Feb 17 09:44:29 volumio-bb volumio[1280]: info: Creating MPD Configuration file Feb 17 09:44:29 volumio-bb volumio-remote-updater[812]: [2026-02-17 09:44:29] [connect] Successful connection Feb 17 09:44:29 volumio-bb systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Feb 17 09:44:29 volumio-bb systemd[1]: Starting mpd.service - Music Player Daemon... Feb 17 09:44:29 volumio-bb sudo[1565]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumio5-onboarding.service Feb 17 09:44:29 volumio-bb volumio[1280]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 17 09:44:29 volumio-bb sudo[1565]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 17 09:44:29 volumio-bb volumio[1280]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Feb 17 09:44:29 volumio-bb volumio[1280]: info: [1771317869697] CoreMusicLibrary::Adding element Media Servers Feb 17 09:44:29 volumio-bb volumio[1280]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 17 09:44:29 volumio-bb sudo[1569]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Feb 17 09:44:29 volumio-bb volumio[1480]: Starting albumart workers Feb 17 09:44:29 volumio-bb sudo[1569]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Feb 17 09:44:29 volumio-bb sudo[1573]: /bin/chown: cannot access '/var/log/mpd.log': No such file or directory Feb 17 09:44:29 volumio-bb sudo[1569]: pam_unix(sudo:session): session closed for user root Feb 17 09:44:29 volumio-bb sudo[1568]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Feb 17 09:44:29 volumio-bb sudo[1568]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 17 09:44:29 volumio-bb sudo[1568]: pam_unix(sudo:session): session closed for user root Feb 17 09:44:29 volumio-bb volumio[1280]: info: UPNP Browser: Client initialized successfully Feb 17 09:44:29 volumio-bb sudo[1571]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Feb 17 09:44:29 volumio-bb sudo[1571]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 17 09:44:29 volumio-bb systemd[1]: Started volumio5-onboarding.service - Volumio5 Onboarding Server. Feb 17 09:44:29 volumio-bb volumio[1280]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 17 09:44:29 volumio-bb volumio[1280]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 17 09:44:29 volumio-bb sudo[1565]: pam_unix(sudo:session): session closed for user root Feb 17 09:44:30 volumio-bb systemd[1]: mpd.service: Deactivated successfully. Feb 17 09:44:30 volumio-bb systemd[1]: Stopped mpd.service - Music Player Daemon. Feb 17 09:44:30 volumio-bb systemd[1]: mpd.socket: Deactivated successfully. Feb 17 09:44:30 volumio-bb systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Feb 17 09:44:30 volumio-bb systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Feb 17 09:44:30 volumio-bb systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Feb 17 09:44:30 volumio-bb systemd[1]: Starting mpd.service - Music Player Daemon... Feb 17 09:44:30 volumio-bb sudo[1587]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Feb 17 09:44:30 volumio-bb sudo[1587]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Feb 17 09:44:30 volumio-bb sudo[1589]: /bin/chown: cannot access '/var/log/mpd.log': No such file or directory Feb 17 09:44:30 volumio-bb sudo[1587]: pam_unix(sudo:session): session closed for user root Feb 17 09:44:30 volumio-bb volumio5-onboarding[1577]: time=2026-02-17T09:44:30.224+01:00 level=INFO msg="running volumio5-device-gateway" version=30d1950e+CHANGES buildDate=2026-01-29T13:10:08Z Feb 17 09:44:30 volumio-bb volumio[1280]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Feb 17 09:44:30 volumio-bb volumio[1280]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 17 09:44:30 volumio-bb volumio[1280]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 17 09:44:30 volumio-bb volumio[1280]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Feb 17 09:44:30 volumio-bb volumio[1280]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Feb 17 09:44:30 volumio-bb volumio[1280]: info: [1771317870344] CoreMusicLibrary::Adding element Last_100 Feb 17 09:44:30 volumio-bb volumio[1280]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 17 09:44:30 volumio-bb volumio[1280]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Feb 17 09:44:30 volumio-bb volumio[1280]: info: [1771317870366] CoreMusicLibrary::Adding element Webradio Feb 17 09:44:30 volumio-bb volumio[1280]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 17 09:44:30 volumio-bb volumio[1280]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Feb 17 09:44:30 volumio-bb volumio[1280]: info: Initializing BBC Radios Feb 17 09:44:56 volumio-bb ntpd[1083]: CLOCK: time stepped by 26.247610 Feb 17 09:44:56 volumio-bb ntpd[1083]: INIT: MRU 13107 entries, 13 hash bits, 32768 bytes Feb 17 09:44:56 volumio-bb systemd[1]: systemd-fsckd.service: Deactivated successfully. Feb 17 09:44:57 volumio-bb volumio[1280]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Feb 17 09:44:57 volumio-bb volumio[1280]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 17 09:44:57 volumio-bb volumio[1280]: info: Creating Spotify config file Feb 17 09:44:57 volumio-bb volumio[1280]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 17 09:44:58 volumio-bb systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 2. Feb 17 09:44:58 volumio-bb systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Feb 17 09:44:59 volumio-bb systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Feb 17 09:44:59 volumio-bb sudo[1552]: pam_unix(sudo:session): session closed for user root Feb 17 09:44:59 volumio-bb systemd[1]: systemd-hostnamed.service: Deactivated successfully. Feb 17 09:44:59 volumio-bb volumio[1280]: info: [now-playing] ConfigUpdater: config is up to date. Feb 17 09:44:59 volumio-bb volumio[1280]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , updateALSAConfigFile Feb 17 09:44:59 volumio-bb volumio[1280]: info: Volumio Calling Home Feb 17 09:45:00 volumio-bb sudo[1638]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/modprobe snd-aloop index=7 pcm_substreams=1 Feb 17 09:45:00 volumio-bb sudo[1638]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 17 09:45:00 volumio-bb sudo[1638]: pam_unix(sudo:session): session closed for user root Feb 17 09:45:00 volumio-bb mpd[1591]: 2026-02-17T09:45:00 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Feb 17 09:45:00 volumio-bb volumio[1280]: info: Preparing to generate the ALSA configuration file Feb 17 09:45:00 volumio-bb systemd[1]: Started mpd.service - Music Player Daemon. Feb 17 09:45:00 volumio-bb sudo[1571]: pam_unix(sudo:session): session closed for user root Feb 17 09:45:00 volumio-bb sudo[1557]: pam_unix(sudo:session): session closed for user root Feb 17 09:45:00 volumio-bb volumio[1280]: info: [now-playing] App is listening on port 4004. Feb 17 09:45:00 volumio-bb volumio[1280]: warn: [now-playing] MyBackgroundMonitor is now watching /data/INTERNAL/NowPlayingPlugin/My Backgrounds Feb 17 09:45:01 volumio-bb volumio[1280]: info: The plugin peppyspectrum has an ALSA contribution file peppy_in.peppy_out.6.conf Feb 17 09:45:01 volumio-bb volumio[1280]: info: Reading ALSA contributions from plugins. Feb 17 09:45:01 volumio-bb sudo[1654]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=toniolombardi,password=O0grPinbJhCvqzI66,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //tl-nas1.toniolombardi.com/music /mnt/NAS/tl-nas1 Feb 17 09:45:01 volumio-bb sudo[1654]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 17 09:45:01 volumio-bb volumio[1280]: info: snd_dummy loaded Feb 17 09:45:01 volumio-bb volumio[1280]: info: MPD Permissions set Feb 17 09:45:01 volumio-bb volumio[1280]: info: Completed starting Core Plugins Feb 17 09:45:01 volumio-bb volumio[1280]: info: ------------------------------------------- Feb 17 09:45:01 volumio-bb volumio[1280]: info: ----- MyVolumio plugins startup ---- Feb 17 09:45:01 volumio-bb volumio[1280]: info: ------------------------------------------- Feb 17 09:45:01 volumio-bb kernel: netfs: FS-Cache loaded Feb 17 09:45:01 volumio-bb volumio[1280]: info: [MyVolumio PluginManager] Fetching plans data.... Feb 17 09:45:01 volumio-bb volumio[1280]: info: MPD Permissions set Feb 17 09:45:01 volumio-bb volumio[1280]: info: Upmpdcli Daemon Started Feb 17 09:45:01 volumio-bb volumio[1280]: info: Volumio called home Feb 17 09:45:01 volumio-bb volumio[1280]: info: Spotify config file written Feb 17 09:45:01 volumio-bb kernel: Key type cifs.spnego registered Feb 17 09:45:01 volumio-bb kernel: Key type cifs.idmap registered Feb 17 09:45:01 volumio-bb 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. Feb 17 09:45:01 volumio-bb kernel: CIFS: Attempting to mount //tl-nas1.toniolombardi.com/music Feb 17 09:45:01 volumio-bb sudo[1674]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Feb 17 09:45:01 volumio-bb sudo[1674]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 17 09:45:01 volumio-bb 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. Feb 17 09:45:01 volumio-bb 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. Feb 17 09:45:01 volumio-bb systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 17 09:45:01 volumio-bb go-librespot[1691]: go-librespot daemon starting... Feb 17 09:45:01 volumio-bb sudo[1674]: pam_unix(sudo:session): session closed for user root Feb 17 09:45:01 volumio-bb sudo[1654]: pam_unix(sudo:session): session closed for user root Feb 17 09:45:01 volumio-bb volumio[1280]: error: MPD error: The expression evaluated to a falsy value: Feb 17 09:45:01 volumio-bb volumio[1280]: assert.ok(self.idling) Feb 17 09:45:01 volumio-bb volumio[1280]: error: The expression evaluated to a falsy value: Feb 17 09:45:01 volumio-bb volumio[1280]: assert.ok(self.idling) Feb 17 09:45:01 volumio-bb volumio[1280]: 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: 3 Feb 17 09:45:01 volumio-bb go-librespot[1697]: time="2026-02-17T09:45:01+01:00" level=info msg="running go-librespot 0.6.2" Feb 17 09:45:01 volumio-bb go-librespot[1697]: time="2026-02-17T09:45:01+01:00" level=debug msg="app state loaded" Feb 17 09:45:01 volumio-bb volumio[1280]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 17 09:45:01 volumio-bb volumio[1280]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 17 09:45:01 volumio-bb volumio[1280]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 17 09:45:01 volumio-bb volumio[1280]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 17 09:45:01 volumio-bb volumio[1280]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 17 09:45:01 volumio-bb volumio[1280]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 17 09:45:01 volumio-bb volumio[1280]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 17 09:45:01 volumio-bb volumio[1280]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 17 09:45:01 volumio-bb go-librespot[1697]: time="2026-02-17T09:45:01+01:00" level=info msg="api server listening on 127.0.0.1:9879" Feb 17 09:45:01 volumio-bb volumio[1280]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 17 09:45:01 volumio-bb volumio[1280]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 17 09:45:01 volumio-bb volumio[1280]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 17 09:45:01 volumio-bb volumio[1280]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 17 09:45:01 volumio-bb volumio[1280]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 17 09:45:01 volumio-bb volumio[1280]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 17 09:45:01 volumio-bb volumio[1280]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 17 09:45:01 volumio-bb volumio[1280]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 17 09:45:01 volumio-bb volumio[1280]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 17 09:45:01 volumio-bb volumio[1280]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 17 09:45:01 volumio-bb volumio[1280]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 17 09:45:01 volumio-bb volumio[1280]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 17 09:45:01 volumio-bb volumio[1280]: info: No need to fix Spotify hosts Feb 17 09:45:02 volumio-bb volumio[1280]: error: updateQueue error: null Feb 17 09:45:02 volumio-bb volumio[1280]: 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: 3 Feb 17 09:45:02 volumio-bb volumio[1280]: info: Received Get System Info Feb 17 09:45:02 volumio-bb volumio[1280]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Feb 17 09:45:02 volumio-bb volumio[1280]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Feb 17 09:45:02 volumio-bb volumio[1280]: info: Discovery: Getting this device information Feb 17 09:45:02 volumio-bb volumio[1280]: info: CoreCommandRouter::volumioGetState Feb 17 09:45:02 volumio-bb volumio[1280]: info: CorePlayQueue::getTrack 0 Feb 17 09:45:02 volumio-bb volumio[1280]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 17 09:45:02 volumio-bb volumio5-onboarding[1577]: time=2026-02-17T09:45:02.103+01:00 level=INFO msg="system info for 0ad4515d9c277ca45afa2058d79d46ed" deviceName=Volumio-bb deviceVariant=volumio deviceModel= softwareVersion=4.096 Feb 17 09:45:02 volumio-bb go-librespot[1697]: time="2026-02-17T09:45:02+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Feb 17 09:45:02 volumio-bb go-librespot[1697]: time="2026-02-17T09:45:02+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Feb 17 09:45:02 volumio-bb go-librespot[1697]: time="2026-02-17T09:45:02+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Feb 17 09:45:02 volumio-bb go-librespot[1697]: time="2026-02-17T09:45:02+01:00" level=info msg="zeroconf server listening on port 38751" Feb 17 09:45:02 volumio-bb go-librespot[1697]: time="2026-02-17T09:45:02+01:00" level=debug msg="obtained new client token: AAD1DvCBefe5i1l3TauFlGwJTRtYdf7TfaAbtH74CQuGPFyzVwBOAKRZLQfEMDO6fMSwJamahhi9hvj6KBZ8/sxOVINPfCHlWQlZgKu3t6xgJmGfXISxJen6mKx5jaUxBvHzM7nWP29bXx65/Eazai4NsoDqBT+YjuqWGHxXVS8I1FAQWkhbWgrefT/NMp9/UVrXC2bx/ndz9NuU3D5sZ/4E8yCuhjmmklhJoFqxsC9ZDpODRJACE0Qypms=" Feb 17 09:45:02 volumio-bb volumio[1280]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 4 Feb 17 09:45:02 volumio-bb volumio[1280]: info: MPD running with PID1591 Feb 17 09:45:02 volumio-bb volumio[1280]: ,establishing connection Feb 17 09:45:02 volumio-bb go-librespot[1697]: time="2026-02-17T09:45:02+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Feb 17 09:45:02 volumio-bb volumio[1280]: info: Received Get System Info Feb 17 09:45:02 volumio-bb volumio[1280]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Feb 17 09:45:02 volumio-bb volumio[1280]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Feb 17 09:45:02 volumio-bb volumio[1280]: info: Discovery: Getting this device information Feb 17 09:45:02 volumio-bb volumio[1280]: info: CoreCommandRouter::volumioGetState Feb 17 09:45:02 volumio-bb volumio[1280]: info: CorePlayQueue::getTrack 0 Feb 17 09:45:02 volumio-bb volumio[1280]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 17 09:45:02 volumio-bb go-librespot[1697]: time="2026-02-17T09:45:02+01:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: EOF" Feb 17 09:45:02 volumio-bb volumio[1280]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 5 Feb 17 09:45:02 volumio-bb volumio[1280]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Feb 17 09:45:02 volumio-bb volumio[1280]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Feb 17 09:45:03 volumio-bb volumio5-onboarding[1577]: time=2026-02-17T09:45:03.003+01:00 level=INFO msg="enabling local network discovery" Feb 17 09:45:03 volumio-bb volumio5-onboarding[1577]: time=2026-02-17T09:45:03.057+01:00 level=INFO msg="bootstrapping state" hasInternet=true Feb 17 09:45:03 volumio-bb volumio[1280]: info: Volumio Network Manager: Network status updated: 1 Feb 17 09:45:03 volumio-bb go-librespot[1697]: time="2026-02-17T09:45:03+01:00" level=debug msg="connected to ap-gew1.spotify.com:443" Feb 17 09:45:03 volumio-bb volumio[1280]: info: Starting Shairport Sync Feb 17 09:45:03 volumio-bb volumio[1280]: info: Starting Shairport Sync Feb 17 09:45:03 volumio-bb sudo[1736]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Feb 17 09:45:03 volumio-bb sudo[1736]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 17 09:45:03 volumio-bb volumio[1280]: info: Starting Shairport Sync Feb 17 09:45:03 volumio-bb go-librespot[1697]: time="2026-02-17T09:45:03+01:00" level=debug msg="completed keyexchange" Feb 17 09:45:03 volumio-bb go-librespot[1697]: time="2026-02-17T09:45:03+01:00" level=debug msg="completed challenge" Feb 17 09:45:03 volumio-bb volumio[1280]: info: Received Get System Info Feb 17 09:45:03 volumio-bb volumio[1280]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Feb 17 09:45:03 volumio-bb volumio[1280]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Feb 17 09:45:03 volumio-bb volumio[1280]: info: Discovery: Getting this device information Feb 17 09:45:03 volumio-bb volumio[1280]: info: CoreCommandRouter::volumioGetState Feb 17 09:45:03 volumio-bb volumio[1280]: info: CorePlayQueue::getTrack 0 Feb 17 09:45:03 volumio-bb volumio[1280]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 17 09:45:03 volumio-bb go-librespot[1697]: time="2026-02-17T09:45:03+01:00" level=info msg="authenticated AP" username="11*******48" Feb 17 09:45:03 volumio-bb volumio[1280]: error: updateQueue error: null Feb 17 09:45:03 volumio-bb sudo[1738]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Feb 17 09:45:03 volumio-bb sudo[1738]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 17 09:45:03 volumio-bb sudo[1741]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Feb 17 09:45:03 volumio-bb sudo[1741]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 17 09:45:03 volumio-bb volumio[1280]: info: New Spotify access tokenBQDizaSOUW... Feb 17 09:45:03 volumio-bb volumio[1280]: info: Spotify credentials grant success - running version from March 24, 2019 Feb 17 09:45:03 volumio-bb systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Feb 17 09:45:03 volumio-bb systemd[1]: shairport-sync.service: Deactivated successfully. Feb 17 09:45:03 volumio-bb systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Feb 17 09:45:03 volumio-bb systemd[1]: shairport-sync.service: Consumed 1.389s CPU time. Feb 17 09:45:03 volumio-bb systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Feb 17 09:45:03 volumio-bb sudo[1736]: pam_unix(sudo:session): session closed for user root Feb 17 09:45:03 volumio-bb sudo[1738]: pam_unix(sudo:session): session closed for user root Feb 17 09:45:03 volumio-bb systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Feb 17 09:45:03 volumio-bb systemd[1]: shairport-sync.service: Deactivated successfully. Feb 17 09:45:03 volumio-bb systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Feb 17 09:45:03 volumio-bb systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Feb 17 09:45:03 volumio-bb sudo[1741]: pam_unix(sudo:session): session closed for user root Feb 17 09:45:03 volumio-bb go-librespot[1697]: time="2026-02-17T09:45:03+01:00" level=info msg="authenticated Login5" username="11*******48" Feb 17 09:45:03 volumio-bb go-librespot[1697]: time="2026-02-17T09:45:03+01:00" level=debug msg="initializing zeroconf session" username="11*******48" Feb 17 09:45:03 volumio-bb volumio[1280]: info: Asound.conf file unchanged, so no further update is needed Feb 17 09:45:03 volumio-bb volumio[1280]: info: Output device has changed, restarting MPD Feb 17 09:45:03 volumio-bb go-librespot[1697]: time="2026-02-17T09:45:03+01:00" level=debug msg="dealer connection opened" Feb 17 09:45:03 volumio-bb go-librespot[1697]: time="2026-02-17T09:45:03+01:00" level=trace msg="starting accesspoint recv loop" Feb 17 09:45:03 volumio-bb go-librespot[1697]: time="2026-02-17T09:45:03+01:00" level=trace msg="starting dealer recv loop" Feb 17 09:45:03 volumio-bb go-librespot[1697]: time="2026-02-17T09:45:03+01:00" level=trace msg="received accesspoint ping" Feb 17 09:45:03 volumio-bb go-librespot[1697]: time="2026-02-17T09:45:03+01:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Feb 17 09:45:03 volumio-bb go-librespot[1697]: time="2026-02-17T09:45:03+01:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Feb 17 09:45:03 volumio-bb go-librespot[1697]: time="2026-02-17T09:45:03+01:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Feb 17 09:45:03 volumio-bb go-librespot[1697]: time="2026-02-17T09:45:03+01:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Feb 17 09:45:03 volumio-bb go-librespot[1697]: time="2026-02-17T09:45:03+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Feb 17 09:45:03 volumio-bb go-librespot[1697]: time="2026-02-17T09:45:03+01:00" level=debug msg="received connection id: ZjFhYzZhOTgtMjI3...QjRDNDdCODI2Ng==" Feb 17 09:45:03 volumio-bb go-librespot[1697]: time="2026-02-17T09:45:03+01:00" level=trace msg="received accesspoint pong ack" Feb 17 09:45:03 volumio-bb volumio[1280]: info: Output device has changed, restarting Shairport Sync Feb 17 09:45:03 volumio-bb volumio[1280]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 17 09:45:03 volumio-bb volumio[1280]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 17 09:45:03 volumio-bb sudo[1764]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Feb 17 09:45:03 volumio-bb sudo[1764]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 17 09:45:04 volumio-bb sudo[1763]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Feb 17 09:45:04 volumio-bb sudo[1763]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 17 09:45:04 volumio-bb sudo[1764]: pam_unix(sudo:session): session closed for user root Feb 17 09:45:04 volumio-bb volumio[1280]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Feb 17 09:45:04 volumio-bb systemd[1]: Stopping mpd.service - Music Player Daemon... Feb 17 09:45:04 volumio-bb go-librespot[1697]: time="2026-02-17T09:45:04+01:00" level=debug msg="put connect state because NEW_DEVICE" Feb 17 09:45:04 volumio-bb go-librespot[1697]: time="2026-02-17T09:45:04+01:00" level=debug msg="update volume requested to 65535/65535" Feb 17 09:45:04 volumio-bb volumio[1280]: info: Shairport-Sync Started Feb 17 09:45:04 volumio-bb volumio[1280]: Error adding Membership: Error: addMembership EINVAL Feb 17 09:45:04 volumio-bb systemd[1]: mpd.service: Deactivated successfully. Feb 17 09:45:04 volumio-bb systemd[1]: Stopped mpd.service - Music Player Daemon. Feb 17 09:45:04 volumio-bb systemd[1]: mpd.service: Consumed 3.137s CPU time. Feb 17 09:45:04 volumio-bb systemd[1]: mpd.socket: Deactivated successfully. Feb 17 09:45:04 volumio-bb systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Feb 17 09:45:04 volumio-bb systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Feb 17 09:45:04 volumio-bb volumio[1280]: info: Shairport-Sync Started Feb 17 09:45:04 volumio-bb volumio[1280]: info: Shairport-Sync Started Feb 17 09:45:04 volumio-bb volumio[1280]: error: Upnp client error: Error: This socket has been ended by the other party Feb 17 09:45:04 volumio-bb go-librespot[1697]: time="2026-02-17T09:45:04+01:00" level=debug msg="put connect state because VOLUME_CHANGED" Feb 17 09:45:04 volumio-bb go-librespot[1697]: time="2026-02-17T09:45:04+01:00" level=trace msg="emitting websocket event: volume" Feb 17 09:45:04 volumio-bb systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Feb 17 09:45:04 volumio-bb systemd[1]: Starting mpd.service - Music Player Daemon... Feb 17 09:45:04 volumio-bb volumio[1280]: info: MPD Permissions set Feb 17 09:45:04 volumio-bb sudo[1776]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Feb 17 09:45:04 volumio-bb sudo[1776]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Feb 17 09:45:04 volumio-bb sudo[1776]: pam_unix(sudo:session): session closed for user root Feb 17 09:45:04 volumio-bb volumio[1280]: error: Upnp client error: Error: connect ECONNREFUSED 127.0.0.1:6600 Feb 17 09:45:05 volumio-bb volumio[1280]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 17 09:45:05 volumio-bb volumio[1280]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 17 09:45:05 volumio-bb volumio[1280]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 17 09:45:05 volumio-bb volumio[1280]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 17 09:45:05 volumio-bb volumio[1280]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 17 09:45:05 volumio-bb volumio[1280]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 17 09:45:05 volumio-bb volumio[1280]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 17 09:45:05 volumio-bb volumio[1280]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 17 09:45:05 volumio-bb volumio[1280]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 17 09:45:05 volumio-bb volumio[1280]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 17 09:45:05 volumio-bb volumio[1280]: info: CoreCommandRouter::volumioGetState Feb 17 09:45:05 volumio-bb volumio[1280]: info: CorePlayQueue::getTrack 0 Feb 17 09:45:05 volumio-bb volumio[1280]: info: go-librespot daemon successfully initialized Feb 17 09:45:05 volumio-bb volumio[1280]: info: Starting Shairport Sync Feb 17 09:45:05 volumio-bb sudo[1785]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Feb 17 09:45:05 volumio-bb sudo[1785]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 17 09:45:05 volumio-bb systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Feb 17 09:45:05 volumio-bb systemd[1]: shairport-sync.service: Deactivated successfully. Feb 17 09:45:05 volumio-bb systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Feb 17 09:45:05 volumio-bb systemd[1]: shairport-sync.service: Consumed 1.377s CPU time. Feb 17 09:45:05 volumio-bb systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Feb 17 09:45:05 volumio-bb sudo[1785]: pam_unix(sudo:session): session closed for user root Feb 17 09:45:05 volumio-bb volumio[1280]: info: Shairport-Sync Started Feb 17 09:45:05 volumio-bb volumio[1280]: SPOTIFY: User informations: {"country":"MT","display_name":"Tonio Lombardi","email":"toniolombardi@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/11136049648"},"followers":{"href":null,"total":92},"href":"https://api.spotify.com/v1/users/11136049648","id":"11136049648","images":[{"height":300,"url":"https://scontent-arn2-1.xx.fbcdn.net/v/t39.30808-1/533462269_10163854729902366_6987805929629156828_n.jpg?stp=c193.447.1000.1000a_dst-jpg_s320x320_tt6&_nc_cat=101&ccb=1-7&_nc_sid=08baa4&_nc_ohc=pXgp8Ci4CMwQ7kNvwEqxrfA&_nc_oc=Adnq5wSvceErZxlvRiWPljOPDEGHr0O_ywZK60eP7dlZ28ezdmsJZMZCRCv900ZKoClsB4Odj6-PFc9iuGPdg6kR&_nc_zt=24&_nc_ht=scontent-arn2-1.xx&edm=AP4hL3IEAAAA&_nc_gid=BD3bF-IsscEbpyfdl9NEcA&_nc_tpa=Q5bMBQEvUWhxI1wUBbX1yPUm8gdM1GD-_fix8SkQPRtrcG_DglimHkTthjNj_JHjIkpagST-lZq9&oh=00_AfvD7g0UlWb0EhS4HuBrszvcaQZqAVKZrZIP8QM055vzyQ&oe=6999B515","width":300},{"height":64,"url":"https://scontent-arn2-1.xx.fbcdn.net/v/t39.30808-1/533462269_10163854729902366_6987805929629156828_n.jpg?stp=c193.447.1000.1000a_cp0_dst-jpg_s50x50_tt6&_nc_cat=101&ccb=1-7&_nc_sid=28885b&_nc_ohc=pXgp8Ci4CMwQ7kNvwEqxrfA&_nc_oc=Adnq5wSvceErZxlvRiWPljOPDEGHr0O_ywZK60eP7dlZ28ezdmsJZMZCRCv900ZKoClsB4Odj6-PFc9iuGPdg6kR&_nc_zt=24&_nc_ht=scontent-arn2-1.xx&edm=AP4hL3IEAAAA&_nc_gid=BD3bF-IsscEbpyfdl9NEcA&_nc_tpa=Q5bMBQFaiRcvLjkm3teKzxO9d3w0cUYXZXKxLztGi95E_FZuiGGLg-5EnZNB2o1ECa_QaF-nahMR&oh=00_AfvvCyfxL25gjeMVP7kXiVmD0Ho9kHDJ-1KhVrVCsfNVzQ&oe=6999B515","width":64}],"product":"premium","type":"user","uri":"spotify:user:11136049648"} Feb 17 09:45:05 volumio-bb volumio[1280]: info: Spotify Successfully logged in Feb 17 09:45:05 volumio-bb volumio[1280]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Feb 17 09:45:05 volumio-bb volumio[1280]: info: [1771317905991] CoreMusicLibrary::Adding element Spotify Feb 17 09:45:05 volumio-bb volumio[1280]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 17 09:45:06 volumio-bb mpd[1778]: 2026-02-17T09:45:05 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Feb 17 09:45:06 volumio-bb volumio[1280]: Cannot find translation for source Spotify Feb 17 09:45:06 volumio-bb systemd[1]: Started mpd.service - Music Player Daemon. Feb 17 09:45:06 volumio-bb sudo[1763]: pam_unix(sudo:session): session closed for user root Feb 17 09:45:06 volumio-bb volumio[1280]: error: updateQueue error: null Feb 17 09:45:06 volumio-bb volumio[1280]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Feb 17 09:45:08 volumio-bb volumio[1280]: info: Initializing connection to go-librespot Websocket Feb 17 09:45:08 volumio-bb go-librespot[1697]: time="2026-02-17T09:45:08+01:00" level=debug msg="new websocket client" Feb 17 09:45:08 volumio-bb volumio[1280]: info: Connection to go-librespot Websocket established Feb 17 09:45:10 volumio-bb volumio[1280]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Feb 17 09:45:10 volumio-bb volumio[1280]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Feb 17 09:45:10 volumio-bb volumio[1280]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Feb 17 09:45:10 volumio-bb volumio[1280]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Feb 17 09:45:10 volumio-bb volumio[1280]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Feb 17 09:45:10 volumio-bb volumio[1280]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Feb 17 09:45:10 volumio-bb volumio[1280]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Feb 17 09:45:10 volumio-bb volumio[1280]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Feb 17 09:45:10 volumio-bb volumio[1280]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Feb 17 09:45:10 volumio-bb volumio[1280]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Feb 17 09:45:10 volumio-bb volumio[1280]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Feb 17 09:45:10 volumio-bb volumio[1280]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Feb 17 09:45:10 volumio-bb volumio[1280]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Feb 17 09:45:10 volumio-bb volumio[1280]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Feb 17 09:45:10 volumio-bb volumio[1280]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Feb 17 09:45:10 volumio-bb volumio[1280]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Feb 17 09:45:10 volumio-bb volumio[1280]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Feb 17 09:45:10 volumio-bb volumio[1280]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Feb 17 09:45:10 volumio-bb volumio[1280]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Feb 17 09:45:10 volumio-bb volumio[1280]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Feb 17 09:45:10 volumio-bb volumio[1280]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Feb 17 09:45:10 volumio-bb volumio[1280]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Feb 17 09:45:10 volumio-bb volumio[1280]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Feb 17 09:45:10 volumio-bb volumio[1280]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Feb 17 09:45:10 volumio-bb volumio[1280]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Feb 17 09:45:10 volumio-bb volumio[1280]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Feb 17 09:45:10 volumio-bb volumio[1280]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Feb 17 09:45:10 volumio-bb volumio[1280]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Feb 17 09:45:10 volumio-bb volumio[1280]: info: Adding plugin bluetooth to MyMusic Plugins Feb 17 09:45:10 volumio-bb volumio[1280]: info: Adding plugin multiroom to MyMusic Plugins Feb 17 09:45:10 volumio-bb volumio[1280]: info: Adding plugin metavolumio to MyMusic Plugins Feb 17 09:45:10 volumio-bb volumio[1280]: info: Adding plugin cd_controller to MyMusic Plugins Feb 17 09:45:10 volumio-bb volumio[1280]: info: Adding plugin qobuzconnect to MyMusic Plugins Feb 17 09:45:10 volumio-bb volumio[1280]: info: Adding plugin smart_inputs to MyMusic Plugins Feb 17 09:45:10 volumio-bb volumio[1280]: info: Adding plugin tidalconnect to MyMusic Plugins Feb 17 09:45:10 volumio-bb volumio[1280]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Feb 17 09:45:10 volumio-bb volumio-remote-updater[812]: [2026-02-17 09:45:10] [connect] Successful connection Feb 17 09:45:11 volumio-bb go-librespot[1697]: time="2026-02-17T09:45:11+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 3620" Feb 17 09:45:11 volumio-bb go-librespot[1697]: time="2026-02-17T09:45:11+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Feb 17 09:45:15 volumio-bb upmpdcli[1825]: writing RSA key Feb 17 09:45:15 volumio-bb volumio[1280]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Feb 17 09:45:15 volumio-bb volumio[1280]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Feb 17 09:45:15 volumio-bb volumio[1280]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 17 09:45:15 volumio-bb volumio[1280]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 17 09:45:15 volumio-bb volumio[1280]: info: Starting MyVolumio Remote Streaming Endpoints Feb 17 09:45:15 volumio-bb volumio[1280]: info: MyVolumio login type: Token Feb 17 09:45:15 volumio-bb volumio[1280]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Feb 17 09:45:15 volumio-bb volumio[1280]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Feb 17 09:45:15 volumio-bb go-librespot[1697]: time="2026-02-17T09:45:15+01:00" level=debug msg="handling transfer player command from b8c601a63c73a12381e36a02b7d393e6dff250c0" Feb 17 09:45:15 volumio-bb go-librespot[1697]: time="2026-02-17T09:45:15+01:00" level=debug msg="resolved context of track" uri="spotify:album:4EgQs5wnhJqGAfqsuzcQpo" Feb 17 09:45:15 volumio-bb go-librespot[1697]: time="2026-02-17T09:45:15+01:00" level=trace msg="fetched new page 0 with 5 items (list: 5)" uri="spotify:album:4EgQs5wnhJqGAfqsuzcQpo" Feb 17 09:45:15 volumio-bb go-librespot[1697]: time="2026-02-17T09:45:15+01:00" level=debug msg="loading track (paused: false, position: 11ms)" uri="spotify:track:4oBD4rJ7XyssxxuOfC82mg" Feb 17 09:45:16 volumio-bb go-librespot[1697]: time="2026-02-17T09:45:16+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 17 09:45:16 volumio-bb go-librespot[1697]: time="2026-02-17T09:45:16+01:00" level=trace msg="emitting websocket event: will_play" Feb 17 09:45:16 volumio-bb go-librespot[1697]: time="2026-02-17T09:45:16+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 411" Feb 17 09:45:16 volumio-bb go-librespot[1697]: time="2026-02-17T09:45:16+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 3613" Feb 17 09:45:16 volumio-bb go-librespot[1697]: time="2026-02-17T09:45:16+01:00" level=debug msg="selected format OGG_VORBIS_320 (7fd0e662e26cb3b36daad3b3b44550688100bb3d)" uri="spotify:track:4oBD4rJ7XyssxxuOfC82mg" Feb 17 09:45:16 volumio-bb go-librespot[1697]: time="2026-02-17T09:45:16+01:00" level=debug msg="requested aes key for file 7fd0e662e26cb3b36daad3b3b44550688100bb3d, gid: 4oBD4rJ7XyssxxuOfC82mg" Feb 17 09:45:16 volumio-bb systemd[1]: Starting setdatetime-helper.service - Time Synchronization Helper Service... Feb 17 09:45:16 volumio-bb go-librespot[1697]: time="2026-02-17T09:45:16+01:00" level=trace msg="found 3 cdn urls" uri="spotify:track:4oBD4rJ7XyssxxuOfC82mg" Feb 17 09:45:16 volumio-bb go-librespot[1697]: time="2026-02-17T09:45:16+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 2252" Feb 17 09:45:16 volumio-bb go-librespot[1697]: time="2026-02-17T09:45:16+01:00" level=debug msg="fetched first chunk of 15, total size is 7568684 bytes" uri="spotify:track:4oBD4rJ7XyssxxuOfC82mg" Feb 17 09:45:16 volumio-bb go-librespot[1697]: time="2026-02-17T09:45:16+01:00" level=trace msg="seek to 11ms (diff: 11ms, samples: 485, bytes: 0)" uri="spotify:track:4oBD4rJ7XyssxxuOfC82mg" Feb 17 09:45:16 volumio-bb go-librespot[1697]: time="2026-02-17T09:45:16+01:00" level=debug msg="created new output device" Feb 17 09:45:16 volumio-bb go-librespot[1697]: time="2026-02-17T09:45:16+01:00" level=debug msg="fetched chunk 1/14, size: 524288" uri="spotify:track:4oBD4rJ7XyssxxuOfC82mg" Feb 17 09:45:16 volumio-bb go-librespot[1697]: time="2026-02-17T09:45:16+01:00" level=debug msg="fetched chunk 2/14, size: 524288" uri="spotify:track:4oBD4rJ7XyssxxuOfC82mg" Feb 17 09:45:16 volumio-bb go-librespot[1697]: time="2026-02-17T09:45:16+01:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 100000 us, period size = 4410 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 5 frames, PCM format = FLOAT_LE" Feb 17 09:45:16 volumio-bb go-librespot[1697]: time="2026-02-17T09:45:16+01:00" level=debug msg="fetched chunk 3/14, size: 524288" uri="spotify:track:4oBD4rJ7XyssxxuOfC82mg" Feb 17 09:45:16 volumio-bb go-librespot[1697]: time="2026-02-17T09:45:16+01:00" level=info msg="loaded track \"WELCOME TO ECLESIA\" (paused: false, position: 11ms, duration: 183360ms, prefetched: false)" uri="spotify:track:4oBD4rJ7XyssxxuOfC82mg" Feb 17 09:45:17 volumio-bb go-librespot[1697]: time="2026-02-17T09:45:17+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 17 09:45:17 volumio-bb go-librespot[1697]: time="2026-02-17T09:45:17+01:00" level=trace msg="scheduling prefetch in 153s" Feb 17 09:45:17 volumio-bb go-librespot[1697]: time="2026-02-17T09:45:17+01:00" level=trace msg="emitting websocket event: metadata" Feb 17 09:45:17 volumio-bb go-librespot[1697]: time="2026-02-17T09:45:17+01:00" level=trace msg="emitting websocket event: active" Feb 17 09:45:17 volumio-bb go-librespot[1697]: time="2026-02-17T09:45:17+01:00" level=debug msg="sending successful reply for dealer request" Feb 17 09:45:17 volumio-bb go-librespot[1697]: time="2026-02-17T09:45:17+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Feb 17 09:45:17 volumio-bb go-librespot[1697]: time="2026-02-17T09:45:17+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Feb 17 09:45:17 volumio-bb go-librespot[1697]: time="2026-02-17T09:45:17+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Feb 17 09:45:17 volumio-bb go-librespot[1697]: time="2026-02-17T09:45:17+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 17 09:45:17 volumio-bb go-librespot[1697]: time="2026-02-17T09:45:17+01:00" level=trace msg="emitting websocket event: playing" Feb 17 09:45:19 volumio-bb volumio[1280]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Feb 17 09:45:19 volumio-bb volumio[1280]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Feb 17 09:45:19 volumio-bb volumio[1280]: info: Streaming services startup Feb 17 09:45:19 volumio-bb volumio[1280]: info: Starting Streaming Daemon Feb 17 09:45:19 volumio-bb volumio[1280]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Feb 17 09:45:19 volumio-bb sudo[1851]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Feb 17 09:45:19 volumio-bb sudo[1851]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 17 09:45:19 volumio-bb sudo[1851]: pam_unix(sudo:session): session closed for user root Feb 17 09:45:20 volumio-bb volumio[1280]: info: Getting Spotify volume Feb 17 09:45:20 volumio-bb volumio[1280]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:album:4EgQs5wnhJqGAfqsuzcQpo","uri":"spotify:track:4oBD4rJ7XyssxxuOfC82mg","play_origin":"album"}} Feb 17 09:45:20 volumio-bb volumio[1280]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:4oBD4rJ7XyssxxuOfC82mg","name":"WELCOME TO ECLESIA","artist_names":["Naïka"],"album_name":"WELCOME TO ECLESIA","album_cover_url":"https://i.scdn.co/image/ab67616d00001e020fcfea62cef6c159e688452b","position":11,"duration":183360,"release_date":"year:2026 month:2 day:16","track_number":1,"disc_number":1}} Feb 17 09:45:20 volumio-bb volumio[1280]: SPOTIFY: received: {"type":"active","data":null} Feb 17 09:45:20 volumio-bb volumio[1280]: info: Aligning Spotify Volume to Volumio Volume Feb 17 09:45:20 volumio-bb volumio[1280]: info: CoreCommandRouter::volumioGetState Feb 17 09:45:20 volumio-bb volumio[1280]: info: CorePlayQueue::getTrack 0 Feb 17 09:45:20 volumio-bb volumio[1280]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:album:4EgQs5wnhJqGAfqsuzcQpo","uri":"spotify:track:4oBD4rJ7XyssxxuOfC82mg","resume":false,"play_origin":"album"}} Feb 17 09:45:20 volumio-bb volumio[1280]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 17 09:45:20 volumio-bb volumio[1280]: TypeError: Cannot read properties of undefined (reading 'service') Feb 17 09:45:20 volumio-bb volumio[1280]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:346:50) Feb 17 09:45:20 volumio-bb volumio[1280]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:272:18) Feb 17 09:45:20 volumio-bb volumio[1280]: at WebSocket.message (/data/plugins/music_service/spop/index.js:199:14) Feb 17 09:45:20 volumio-bb volumio[1280]: at WebSocket.emit (node:events:514:28) Feb 17 09:45:20 volumio-bb volumio[1280]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20) Feb 17 09:45:20 volumio-bb volumio[1280]: at Receiver.emit (node:events:514:28) Feb 17 09:45:20 volumio-bb volumio[1280]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) Feb 17 09:45:20 volumio-bb volumio[1280]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) Feb 17 09:45:20 volumio-bb volumio[1280]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) Feb 17 09:45:20 volumio-bb volumio[1280]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) Feb 17 09:45:20 volumio-bb volumio[1280]: at writeOrBuffer (node:internal/streams/writable:399:12) Feb 17 09:45:20 volumio-bb volumio[1280]: at _write (node:internal/streams/writable:340:10) Feb 17 09:45:20 volumio-bb volumio[1280]: at Writable.write (node:internal/streams/writable:344:10) Feb 17 09:45:20 volumio-bb volumio[1280]: at Socket.socketOnData (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1355:35) Feb 17 09:45:20 volumio-bb volumio[1280]: at Socket.emit (node:events:514:28) Feb 17 09:45:20 volumio-bb volumio[1280]: at addChunk (node:internal/streams/readable:343:12) Feb 17 09:45:20 volumio-bb volumio[1280]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 17 09:45:23 volumio-bb systemd[1]: setdatetime-helper.service: Deactivated successfully. Feb 17 09:45:23 volumio-bb systemd[1]: Finished setdatetime-helper.service - Time Synchronization Helper Service. Feb 17 09:45:23 volumio-bb sudo[1895]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-02-17 09:44' Feb 17 09:45:23 volumio-bb sudo[1895]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) PRETTY_NAME="Raspbian GNU/Linux 12 (bookworm)" NAME="Raspbian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="a78d359cf1dc63ac74e9d151015afd30d31a709a" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="c1ffe93b2136013fc1b5903a4ed7e3f34e0a7bec" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Thu Feb 5 14:07:07 UTC 2026" VOLUMIO_VERSION="4.096" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="5e37060f9823263a753eb5e84030104f"