-- Logs begin at Thu 2019-02-14 11:11:59 CET, end at Wed 2024-02-21 09:23:27 CET. -- Feb 21 09:22:49 volumitest kernel: usb 1-1.1.2: New USB device found, idVendor=1235, idProduct=8205, bcdDevice= 4.1c Feb 21 09:22:49 volumitest kernel: usb 1-1.1.2: New USB device strings: Mfr=1, Product=3, SerialNumber=0 Feb 21 09:22:49 volumitest kernel: usb 1-1.1.2: Product: Scarlett Solo USB Feb 21 09:22:49 volumitest kernel: usb 1-1.1.2: Manufacturer: Focusrite Feb 21 09:22:49 volumitest initramfs: Checking for USB updates Feb 21 09:22:49 volumitest initramfs: No USB device detected (when incorrect, try adding 'bootdelay=5' to your boot cmdline) Feb 21 09:22:49 volumitest kernel: loop0: detected capacity change from 0 to 1004000 Feb 21 09:22:49 volumitest kernel: FAT-fs (mmcblk0p1): Volume was not properly unmounted. Some data may be corrupt. Please run fsck. Feb 21 09:22:49 volumitest kernel: FAT-fs (mmcblk0p1): Volume was not properly unmounted. Some data may be corrupt. Please run fsck. Feb 21 09:22:49 volumitest kernel: EXT4-fs (mmcblk0p3): recovery complete Feb 21 09:22:49 volumitest kernel: EXT4-fs (mmcblk0p3): mounted filesystem with ordered data mode. Quota mode: none. Feb 21 09:22:49 volumitest initramfs: With Option: Feb 21 09:22:49 volumitest initramfs: VOLUMIO_VERSION="3.616" Feb 21 09:22:49 volumitest initramfs: Finish initramfs, continue booting Volumio Feb 21 09:22:49 volumitest systemd[1]: System time before build time, advancing clock. Feb 21 09:22:49 volumitest kernel: NET: Registered PF_INET6 protocol family Feb 21 09:22:49 volumitest kernel: Segment Routing with IPv6 Feb 21 09:22:49 volumitest kernel: In-situ OAM (IOAM) with IPv6 Feb 21 09:22:49 volumitest systemd[1]: systemd 241 running in system mode. (+PAM +AUDIT +SELINUX +IMA +APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD -IDN2 +IDN -PCRE2 default-hierarchy=hybrid) Feb 21 09:22:49 volumitest systemd[1]: Detected architecture arm. Feb 21 09:22:49 volumitest systemd[1]: Set hostname to . Feb 21 09:22:49 volumitest systemd[1]: /lib/systemd/system/winbind.service:8: PIDFile= references path below legacy directory /var/run/, updating /var/run/samba/winbindd.pid → /run/samba/winbindd.pid; please update the unit file accordingly. Feb 21 09:22:49 volumitest systemd[1]: Listening on udev Kernel Socket. Feb 21 09:22:49 volumitest systemd[1]: Listening on Journal Audit Socket. Feb 21 09:22:49 volumitest systemd[1]: Created slice system-systemd\x2dfsck.slice. Feb 21 09:22:49 volumitest systemd[1]: Listening on Journal Socket (/dev/log). Feb 21 09:22:49 volumitest systemd[1]: Listening on udev Control Socket. Feb 21 09:22:49 volumitest systemd[1]: Started Forward Password Requests to Wall Directory Watch. Feb 21 09:22:49 volumitest systemd-journald[194]: Journal started Feb 21 09:22:49 volumitest systemd-journald[194]: Runtime journal (/run/log/journal/ba41094955353179f46b1ad365cba63d) is 7.5M, max 30.0M, 22.5M free. Feb 21 09:22:49 volumitest fake-hwclock[192]: Wed Feb 21 08:22:49 UTC 2024 Feb 21 09:22:49 volumitest systemd-modules-load[199]: Inserted module 'i2c_dev' Feb 21 09:22:49 volumitest kernel: i2c_dev: i2c /dev entries driver Feb 21 09:22:49 volumitest systemd[1]: Started Restore / save the current clock. Feb 21 09:22:49 volumitest systemd[1]: Mounted POSIX Message Queue File System. Feb 21 09:22:49 volumitest systemd[1]: Started Load Kernel Modules. Feb 21 09:22:49 volumitest systemd[1]: Mounted RPC Pipe File System. Feb 21 09:22:49 volumitest systemd[1]: Condition check resulted in FUSE Control File System being skipped. Feb 21 09:22:49 volumitest systemd[1]: Starting Apply Kernel Variables... Feb 21 09:22:49 volumitest systemd[1]: Mounting Kernel Configuration File System... Feb 21 09:22:49 volumitest systemd[1]: Started Load/Save Random Seed. Feb 21 09:22:49 volumitest systemd[1]: Mounted Kernel Configuration File System. Feb 21 09:22:49 volumitest systemd[1]: Started Apply Kernel Variables. Feb 21 09:22:49 volumitest systemd[1]: Started Create System Users. Feb 21 09:22:49 volumitest systemd[1]: Starting Create Static Device Nodes in /dev... Feb 21 09:22:49 volumitest systemd[1]: dynamicswap.service: Succeeded. Feb 21 09:22:49 volumitest systemd[1]: Started udev Coldplug all Devices. Feb 21 09:22:49 volumitest systemd[1]: Starting Helper to synchronize boot up for ifupdown... Feb 21 09:22:49 volumitest systemd[1]: Started Helper to synchronize boot up for ifupdown. Feb 21 09:22:49 volumitest systemd[1]: Started Create Static Device Nodes in /dev. Feb 21 09:22:49 volumitest systemd[1]: Reached target Local File Systems (Pre). Feb 21 09:22:49 volumitest systemd[1]: var-log.mount: Directory /var/log to mount over is not empty, mounting anyway. Feb 21 09:22:49 volumitest systemd[1]: Mounting /var/log... Feb 21 09:22:49 volumitest systemd[1]: tmp.mount: Directory /tmp to mount over is not empty, mounting anyway. Feb 21 09:22:49 volumitest systemd[1]: Mounting /tmp... Feb 21 09:22:49 volumitest systemd[1]: Mounting /var/spool/cups... Feb 21 09:22:49 volumitest systemd[1]: Starting udev Kernel Device Manager... Feb 21 09:22:49 volumitest systemd[1]: Mounted /var/log. Feb 21 09:22:49 volumitest systemd[1]: Mounted /tmp. Feb 21 09:22:49 volumitest systemd[1]: Mounted /var/spool/cups. Feb 21 09:22:49 volumitest systemd[1]: Mounting /var/spool/cups/tmp... Feb 21 09:22:49 volumitest systemd[1]: Starting Flush Journal to Persistent Storage... Feb 21 09:22:49 volumitest systemd[1]: Mounted /var/spool/cups/tmp. Feb 21 09:22:49 volumitest systemd-udevd[226]: Network interface NamePolicy= disabled on kernel command line, ignoring. Feb 21 09:22:49 volumitest systemd-journald[194]: Runtime journal (/run/log/journal/ba41094955353179f46b1ad365cba63d) is 7.5M, max 30.0M, 22.5M free. Feb 21 09:22:49 volumitest systemd[1]: Started Flush Journal to Persistent Storage. Feb 21 09:22:49 volumitest systemd[1]: Started udev Kernel Device Manager. Feb 21 09:22:49 volumitest systemd[1]: Starting Show Plymouth Boot Screen... Feb 21 09:22:49 volumitest systemd[1]: Received SIGRTMIN+20 from PID 240 (plymouthd). Feb 21 09:22:49 volumitest systemd[1]: Started Show Plymouth Boot Screen. Feb 21 09:22:49 volumitest systemd[1]: Condition check resulted in Dispatch Password Requests to Console Directory Watch being skipped. Feb 21 09:22:49 volumitest systemd[1]: Reached target Local Encrypted Volumes. Feb 21 09:22:49 volumitest systemd[1]: Reached target Paths. Feb 21 09:22:49 volumitest systemd[1]: Started Forward Password Requests to Plymouth Directory Watch. Feb 21 09:22:49 volumitest kernel: vc_sm_cma: module is from the staging directory, the quality is unknown, you have been warned. Feb 21 09:22:49 volumitest kernel: bcm2835_vc_sm_cma_probe: Videocore shared memory driver Feb 21 09:22:49 volumitest kernel: [vc_sm_connected_init]: start Feb 21 09:22:49 volumitest kernel: [vc_sm_connected_init]: installed successfully Feb 21 09:22:49 volumitest kernel: rpi-gpiomem 3f200000.gpiomem: window base 0x3f200000 size 0x00001000 Feb 21 09:22:49 volumitest kernel: rpi-gpiomem 3f200000.gpiomem: initialised 1 regions as /dev/gpiomem Feb 21 09:22:50 volumitest kernel: mc: Linux media interface: v0.10 Feb 21 09:22:50 volumitest kernel: videodev: Linux video capture interface: v2.00 Feb 21 09:22:50 volumitest kernel: Bluetooth: Core ver 2.22 Feb 21 09:22:50 volumitest kernel: NET: Registered PF_BLUETOOTH protocol family Feb 21 09:22:50 volumitest kernel: Bluetooth: HCI device and connection manager initialized Feb 21 09:22:50 volumitest kernel: Bluetooth: HCI socket layer initialized Feb 21 09:22:50 volumitest kernel: Bluetooth: L2CAP socket layer initialized Feb 21 09:22:50 volumitest kernel: Bluetooth: SCO socket layer initialized Feb 21 09:22:50 volumitest kernel: snd_bcm2835: module is from the staging directory, the quality is unknown, you have been warned. Feb 21 09:22:50 volumitest kernel: snd_bcm2835: unknown parameter 'enable_compat_alsa' ignored Feb 21 09:22:50 volumitest kernel: bcm2835_mmal_vchiq: module is from the staging directory, the quality is unknown, you have been warned. Feb 21 09:22:50 volumitest kernel: bcm2835_mmal_vchiq: module is from the staging directory, the quality is unknown, you have been warned. Feb 21 09:22:50 volumitest kernel: Bluetooth: HCI UART driver ver 2.3 Feb 21 09:22:50 volumitest kernel: Bluetooth: HCI UART protocol H4 registered Feb 21 09:22:50 volumitest kernel: Bluetooth: HCI UART protocol Three-wire (H5) registered Feb 21 09:22:50 volumitest kernel: Bluetooth: HCI UART protocol Broadcom registered Feb 21 09:22:50 volumitest kernel: hci_uart_bcm serial0-0: supply vbat not found, using dummy regulator Feb 21 09:22:50 volumitest kernel: hci_uart_bcm serial0-0: supply vddio not found, using dummy regulator Feb 21 09:22:50 volumitest kernel: bcm2835_mmal_vchiq: module is from the staging directory, the quality is unknown, you have been warned. Feb 21 09:22:50 volumitest kernel: bcm2835_v4l2: module is from the staging directory, the quality is unknown, you have been warned. Feb 21 09:22:50 volumitest kernel: bcm2835_audio bcm2835_audio: card created with 4 channels Feb 21 09:22:50 volumitest kernel: bcm2835_isp: module is from the staging directory, the quality is unknown, you have been warned. Feb 21 09:22:50 volumitest kernel: bcm2835_audio bcm2835_audio: card created with 4 channels Feb 21 09:22:50 volumitest kernel: bcm2835-isp bcm2835-isp: Device node output[0] registered as /dev/video13 Feb 21 09:22:50 volumitest kernel: bcm2835-isp bcm2835-isp: Device node capture[0] registered as /dev/video14 Feb 21 09:22:50 volumitest kernel: bcm2835-isp bcm2835-isp: Device node capture[1] registered as /dev/video15 Feb 21 09:22:50 volumitest kernel: bcm2835-isp bcm2835-isp: Device node stats[2] registered as /dev/video16 Feb 21 09:22:50 volumitest kernel: bcm2835-isp bcm2835-isp: Register output node 0 with media controller Feb 21 09:22:50 volumitest kernel: bcm2835-isp bcm2835-isp: Register capture node 1 with media controller Feb 21 09:22:50 volumitest kernel: bcm2835-isp bcm2835-isp: Register capture node 2 with media controller Feb 21 09:22:50 volumitest kernel: bcm2835-isp bcm2835-isp: Register capture node 3 with media controller Feb 21 09:22:50 volumitest kernel: bcm2835-isp bcm2835-isp: Device node output[0] registered as /dev/video20 Feb 21 09:22:50 volumitest kernel: bcm2835-isp bcm2835-isp: Device node capture[0] registered as /dev/video21 Feb 21 09:22:50 volumitest kernel: bcm2835-isp bcm2835-isp: Device node capture[1] registered as /dev/video22 Feb 21 09:22:50 volumitest kernel: bcm2835-isp bcm2835-isp: Device node stats[2] registered as /dev/video23 Feb 21 09:22:50 volumitest kernel: bcm2835-isp bcm2835-isp: Register output node 0 with media controller Feb 21 09:22:50 volumitest kernel: bcm2835-isp bcm2835-isp: Register capture node 1 with media controller Feb 21 09:22:50 volumitest kernel: bcm2835-isp bcm2835-isp: Register capture node 2 with media controller Feb 21 09:22:50 volumitest kernel: bcm2835-isp bcm2835-isp: Register capture node 3 with media controller Feb 21 09:22:50 volumitest kernel: bcm2835-isp bcm2835-isp: Loaded V4L2 bcm2835-isp Feb 21 09:22:50 volumitest kernel: uart-pl011 3f201000.serial: no DMA platform data Feb 21 09:22:50 volumitest systemd[1]: Found device /dev/mmcblk0p1. Feb 21 09:22:50 volumitest kernel: cfg80211: Loading compiled-in X.509 certificates for regulatory database Feb 21 09:22:50 volumitest kernel: bcm2835_codec: module is from the staging directory, the quality is unknown, you have been warned. Feb 21 09:22:50 volumitest kernel: cfg80211: Loaded X.509 cert 'benh@debian.org: 577e021cb980e0e820821ba7b54b4961b8b4fadf' Feb 21 09:22:50 volumitest kernel: cfg80211: Loaded X.509 cert 'romain.perier@gmail.com: 3abbc6ec146e09d1b6016ab9d6cf71dd233f0328' Feb 21 09:22:50 volumitest kernel: cfg80211: Loaded X.509 cert 'sforshee: 00b28ddf47aef9cea7' Feb 21 09:22:50 volumitest kernel: bcm2835-codec bcm2835-codec: Device registered as /dev/video10 Feb 21 09:22:50 volumitest kernel: bcm2835-codec bcm2835-codec: Loaded V4L2 decode Feb 21 09:22:50 volumitest kernel: bcm2835-codec bcm2835-codec: Device registered as /dev/video11 Feb 21 09:22:50 volumitest kernel: bcm2835-codec bcm2835-codec: Loaded V4L2 encode Feb 21 09:22:50 volumitest kernel: Bluetooth: hci0: BCM: chip id 107 Feb 21 09:22:51 volumitest kernel: Bluetooth: hci0: BCM: features 0x2f Feb 21 09:22:51 volumitest kernel: bcm2835-codec bcm2835-codec: Device registered as /dev/video12 Feb 21 09:22:51 volumitest kernel: bcm2835-codec bcm2835-codec: Loaded V4L2 isp Feb 21 09:22:51 volumitest kernel: Bluetooth: hci0: BCM4345C0 Feb 21 09:22:51 volumitest kernel: Bluetooth: hci0: BCM4345C0 (003.001.025) build 0000 Feb 21 09:22:51 volumitest kernel: Bluetooth: hci0: BCM4345C0 'brcm/BCM4345C0.hcd' Patch Feb 21 09:22:51 volumitest kernel: bcm2835-codec bcm2835-codec: Device registered as /dev/video18 Feb 21 09:22:51 volumitest kernel: bcm2835-codec bcm2835-codec: Loaded V4L2 image_fx Feb 21 09:22:51 volumitest kernel: bcm2835-codec bcm2835-codec: Device registered as /dev/video31 Feb 21 09:22:51 volumitest kernel: bcm2835-codec bcm2835-codec: Loaded V4L2 encode_image Feb 21 09:22:51 volumitest systemd-udevd[235]: Using default interface naming scheme 'v240'. Feb 21 09:22:51 volumitest systemd-udevd[235]: link_config: autonegotiation is unset or enabled, the speed and duplex are not writable. Feb 21 09:22:51 volumitest systemd[1]: Starting File System Check on /dev/mmcblk0p1... Feb 21 09:22:51 volumitest systemd[1]: Started File System Check Daemon to report status. Feb 21 09:22:51 volumitest kernel: brcmfmac: F1 signature read @0x18000000=0x15264345 Feb 21 09:22:51 volumitest kernel: brcmfmac: brcmf_fw_alloc_request: using brcm/brcmfmac43455-sdio for chip BCM4345/6 Feb 21 09:22:51 volumitest kernel: usbcore: registered new interface driver brcmfmac Feb 21 09:22:51 volumitest systemd-udevd[236]: link_config: autonegotiation is unset or enabled, the speed and duplex are not writable. Feb 21 09:22:51 volumitest systemd-fsck[313]: fsck.fat 4.1 (2017-01-24) Feb 21 09:22:51 volumitest systemd-fsck[313]: 0x25: Dirty bit is set. Fs was not properly unmounted and some data may be corrupt. Feb 21 09:22:51 volumitest systemd-fsck[313]: Automatically removing dirty bit. Feb 21 09:22:51 volumitest systemd-fsck[313]: Performing changes. Feb 21 09:22:51 volumitest systemd-fsck[313]: /dev/mmcblk0p1: 364 files, 33346/46774 clusters Feb 21 09:22:51 volumitest systemd[1]: Started File System Check on /dev/mmcblk0p1. Feb 21 09:22:51 volumitest kernel: brcmfmac: brcmf_c_preinit_dcmds: Firmware: BCM4345/6 wl0: Nov 1 2021 00:37:25 version 7.45.241 (1a2f2fa CY) FWID 01-703fd60 Feb 21 09:22:51 volumitest kernel: Bluetooth: hci0: BCM: features 0x2f Feb 21 09:22:51 volumitest kernel: Bluetooth: hci0: BCM43455 37.4MHz Raspberry Pi 3+ Feb 21 09:22:51 volumitest kernel: Bluetooth: hci0: BCM4345C0 (003.001.025) build 0342 Feb 21 09:22:51 volumitest kernel: Bluetooth: hci0: BCM: Using default device address (43:45:c0:00:1f:ac) Feb 21 09:22:52 volumitest kernel: usbcore: registered new interface driver snd-usb-audio Feb 21 09:22:52 volumitest systemd-udevd[237]: Using default interface naming scheme 'v240'. Feb 21 09:22:52 volumitest systemd-udevd[237]: link_config: autonegotiation is unset or enabled, the speed and duplex are not writable. Feb 21 09:22:53 volumitest systemd-udevd[238]: Process '/usr/sbin/alsactl -E HOME=/run/alsa restore 5' failed with exit code 99. Feb 21 09:22:53 volumitest systemd-udevd[239]: Process '/usr/sbin/alsactl -E HOME=/run/alsa restore 0' failed with exit code 17. Feb 21 09:22:53 volumitest systemd-udevd[236]: Process '/bin/bash -c '/usr/local/bin/volumio scanaudioinputs'' failed with exit code 7. Feb 21 09:22:53 volumitest systemd-udevd[229]: Process '/bin/bash -c '/usr/local/bin/volumio usbattach'' failed with exit code 7. Feb 21 09:22:53 volumitest systemd[1]: Condition check resulted in 7800 being skipped. Feb 21 09:22:53 volumitest systemd[1]: Condition check resulted in /sys/subsystem/net/devices/wlan0 being skipped. Feb 21 09:22:53 volumitest systemd[1]: Created slice system-bthelper.slice. Feb 21 09:22:53 volumitest systemd[1]: Condition check resulted in Set Up Additional Binary Formats being skipped. Feb 21 09:22:53 volumitest systemd[1]: Condition check resulted in Dispatch Password Requests to Console Directory Watch being skipped. Feb 21 09:22:53 volumitest systemd[1]: Condition check resulted in Huge Pages File System being skipped. Feb 21 09:22:53 volumitest systemd[1]: Condition check resulted in FUSE Control File System being skipped. Feb 21 09:22:53 volumitest systemd[1]: Condition check resulted in Rebuild Hardware Database being skipped. Feb 21 09:22:53 volumitest systemd[1]: Listening on Load/Save RF Kill Switch Status /dev/rfkill Watch. Feb 21 09:22:54 volumitest systemd[1]: Mounting /boot... Feb 21 09:22:54 volumitest systemd[1]: Starting Load/Save RF Kill Switch Status... Feb 21 09:22:54 volumitest systemd[1]: Mounted /boot. Feb 21 09:22:54 volumitest systemd[1]: Reached target Local File Systems. Feb 21 09:22:54 volumitest systemd[1]: Condition check resulted in Commit a transient machine-id on disk being skipped. Feb 21 09:22:54 volumitest systemd[1]: Starting Create Volatile Files and Directories... Feb 21 09:22:54 volumitest systemd[1]: Started ifup for eth0. Feb 21 09:22:54 volumitest systemd[1]: Starting Tell Plymouth To Write Out Runtime Data... Feb 21 09:22:54 volumitest systemd[1]: Starting Preprocess NFS configuration... Feb 21 09:22:54 volumitest systemd[1]: Starting Raise network interfaces... Feb 21 09:22:54 volumitest systemd[1]: Started ifup for wlan0. Feb 21 09:22:54 volumitest systemd[1]: Started Load/Save RF Kill Switch Status. Feb 21 09:22:54 volumitest systemd[1]: Received SIGRTMIN+20 from PID 240 (plymouthd). Feb 21 09:22:54 volumitest systemd[1]: plymouth-read-write.service: Succeeded. Feb 21 09:22:54 volumitest systemd[1]: Started Tell Plymouth To Write Out Runtime Data. Feb 21 09:22:54 volumitest systemd[1]: nfs-config.service: Succeeded. Feb 21 09:22:54 volumitest systemd[1]: Started Preprocess NFS configuration. Feb 21 09:22:54 volumitest systemd[1]: Condition check resulted in RPC security service for NFS client and server being skipped. Feb 21 09:22:54 volumitest systemd[1]: Condition check resulted in RPC security service for NFS server being skipped. Feb 21 09:22:54 volumitest systemd[1]: Reached target NFS client services. Feb 21 09:22:54 volumitest systemd[1]: Started Create Volatile Files and Directories. Feb 21 09:22:54 volumitest systemd[1]: Condition check resulted in Network Time Synchronization being skipped. Feb 21 09:22:54 volumitest systemd[1]: Starting Update UTMP about System Boot/Shutdown... Feb 21 09:22:54 volumitest systemd[1]: Starting RPC bind portmap service... Feb 21 09:22:54 volumitest systemd[1]: Started Entropy daemon using the HAVEGE algorithm. Feb 21 09:22:54 volumitest kernel: brcmfmac: brcmf_cfg80211_set_power_mgmt: power save disabled Feb 21 09:22:54 volumitest systemd[1]: Started RPC bind portmap service. Feb 21 09:22:54 volumitest systemd[1]: Reached target Remote File Systems (Pre). Feb 21 09:22:54 volumitest systemd[1]: Reached target Remote File Systems. Feb 21 09:22:54 volumitest systemd[1]: Reached target RPC Port Mapper. Feb 21 09:22:54 volumitest systemd[1]: Started Update UTMP about System Boot/Shutdown. Feb 21 09:22:54 volumitest systemd[1]: Reached target System Initialization. Feb 21 09:22:54 volumitest systemd[1]: Started Volumio Splash. Feb 21 09:22:54 volumitest kernel: 8021q: 802.1Q VLAN Support v1.8 Feb 21 09:22:54 volumitest systemd[1]: apt-daily.timer: Not using persistent file timestamp Fri 2024-11-01 11:47:06 CET as it is in the future. Feb 21 09:22:54 volumitest systemd[1]: Started Daily apt download activities. Feb 21 09:22:54 volumitest systemd[455]: volumiosplash.service: Failed to execute command: No such file or directory Feb 21 09:22:54 volumitest systemd[455]: volumiosplash.service: Failed at step EXEC spawning /bin/volumiosplash.sh: No such file or directory Feb 21 09:22:54 volumitest systemd[1]: Listening on triggerhappy.socket. Feb 21 09:22:54 volumitest systemd[1]: Started Daily Cleanup of Temporary Directories. Feb 21 09:22:54 volumitest systemd[1]: Listening on D-Bus System Message Bus Socket. Feb 21 09:22:54 volumitest systemd[1]: Listening on Avahi mDNS/DNS-SD Stack Activation Socket. Feb 21 09:22:54 volumitest systemd[1]: Reached target Sockets. Feb 21 09:22:54 volumitest systemd[1]: Reached target Basic System. Feb 21 09:22:54 volumitest systemd[1]: Starting triggerhappy global hotkey daemon... Feb 21 09:22:54 volumitest systemd[1]: Condition check resulted in getty on tty2-tty6 if dbus and logind are not available being skipped. Feb 21 09:22:54 volumitest systemd[1]: Started Volumio Iptables Module. Feb 21 09:22:54 volumitest systemd[1]: Starting Login Service... Feb 21 09:22:54 volumitest systemd[1]: Starting LSB: Load kernel modules needed to enable cpufreq scaling... Feb 21 09:22:54 volumitest systemd[1]: Condition check resulted in Copy user wpa_supplicant.conf being skipped. Feb 21 09:22:54 volumitest thd[466]: Unable to parse trigger line: Feb 21 09:22:54 volumitest thd[466]: Unable to parse trigger line: KEY_MIN_INTERESTING 1 /usr/local/bin/volumio volume toggle Feb 21 09:22:54 volumitest thd[466]: Unable to parse trigger line: Feb 21 09:22:54 volumitest thd[466]: Found socket passed from systemd Feb 21 09:22:54 volumitest systemd[1]: Starting dhcpcd on all interfaces... Feb 21 09:22:54 volumitest systemd[1]: Starting Wireless Services... Feb 21 09:22:54 volumitest systemd[1]: Starting Configure Bluetooth Modems connected by UART... Feb 21 09:22:54 volumitest systemd[1]: Started UPnP Renderer front-end to MPD. Feb 21 09:22:54 volumitest systemd[1]: Started volumio-remote-updater.service. Feb 21 09:22:54 volumitest systemd[1]: Started D-Bus System Message Bus. Feb 21 09:22:54 volumitest dhcpcd[480]: Not running dhcpcd because /etc/network/interfaces Feb 21 09:22:54 volumitest dhcpcd[480]: defines some interfaces that will use a Feb 21 09:22:54 volumitest dhcpcd[480]: DHCP client or static address Feb 21 09:22:54 volumitest systemd[1]: Starting WPA supplicant... Feb 21 09:22:54 volumitest systemd[1]: Condition check resulted in Volumio SSH enabler being skipped. Feb 21 09:22:54 volumitest systemd[1]: Starting Avahi mDNS/DNS-SD Stack... Feb 21 09:22:54 volumitest systemd[1]: apt-daily-upgrade.timer: Not using persistent file timestamp Fri 2024-11-01 06:34:06 CET as it is in the future. Feb 21 09:22:54 volumitest systemd[1]: Started Daily apt upgrade and clean activities. Feb 21 09:22:54 volumitest systemd[1]: Reached target Timers. Feb 21 09:22:54 volumitest systemd[1]: Started Manage Sound Card State (restore and store). Feb 21 09:22:54 volumitest alsactl[495]: alsactl 1.1.8 daemon started Feb 21 09:22:54 volumitest systemd[1]: Starting Save/Restore Sound Card State... Feb 21 09:22:54 volumitest systemd[1]: Started Volumio Log Rotation Service. Feb 21 09:22:54 volumitest systemd[1]: Started triggerhappy global hotkey daemon. Feb 21 09:22:54 volumitest systemd[1]: volumiosplash.service: Main process exited, code=exited, status=203/EXEC Feb 21 09:22:54 volumitest systemd[1]: volumiosplash.service: Failed with result 'exit-code'. Feb 21 09:22:54 volumitest systemd[1]: dhcpcd.service: Control process exited, code=exited, status=6/NOTCONFIGURED Feb 21 09:22:54 volumitest systemd[1]: dhcpcd.service: Failed with result 'exit-code'. Feb 21 09:22:54 volumitest systemd[1]: Failed to start dhcpcd on all interfaces. Feb 21 09:22:54 volumitest systemd-logind[469]: New seat seat0. Feb 21 09:22:55 volumitest systemd[1]: Started Save/Restore Sound Card State. Feb 21 09:22:55 volumitest systemd[1]: Reached target Sound Card. Feb 21 09:22:55 volumitest sh[383]: wlan0=wlan0 Feb 21 09:22:55 volumitest avahi-daemon[494]: Found user 'avahi' (UID 110) and group 'avahi' (GID 113). Feb 21 09:22:55 volumitest avahi-daemon[494]: Successfully dropped root privileges. Feb 21 09:22:55 volumitest avahi-daemon[494]: avahi-daemon 0.7 starting up. Feb 21 09:22:55 volumitest systemd[1]: hciuart.service: Succeeded. Feb 21 09:22:55 volumitest systemd[1]: Started Configure Bluetooth Modems connected by UART. Feb 21 09:22:55 volumitest sh[376]: eth0: waiting for carrier Feb 21 09:22:55 volumitest kernel: lan78xx 1-1.1.1:1.0 eth0: Link is Down Feb 21 09:22:55 volumitest kernel: 8021q: adding VLAN 0 to HW filter on device eth0 Feb 21 09:22:55 volumitest dhcpcd[427]: eth0: waiting for carrier Feb 21 09:22:55 volumitest systemd[1]: Starting Raspberry Pi bluetooth helper... Feb 21 09:22:55 volumitest volumio-remote-updater[485]: Error: No active session Feb 21 09:22:55 volumitest volumio-remote-updater[485]: [2024-02-21 09:22:55] [info] asio async_connect error: system:111 (Connection refused) Feb 21 09:22:55 volumitest volumio-remote-updater[485]: [2024-02-21 09:22:55] [info] Error getting remote endpoint: system:107 (Transport endpoint is not connected) Feb 21 09:22:55 volumitest volumio-remote-updater[485]: [2024-02-21 09:22:55] [error] handle_connect error: Underlying Transport Error Feb 21 09:22:55 volumitest bthelper[564]: Raspberry Pi BDADDR already set Feb 21 09:22:55 volumitest volumio[484]: Could not open config: /tmp/upmpdcli.conf Feb 21 09:22:55 volumitest systemd[1]: Started Login Service. Feb 21 09:22:55 volumitest avahi-daemon[494]: Successfully called chroot(). Feb 21 09:22:55 volumitest avahi-daemon[494]: Successfully dropped remaining capabilities. Feb 21 09:22:55 volumitest systemd[1]: Started Raise network interfaces. Feb 21 09:22:55 volumitest wpa_supplicant[493]: Successfully initialized wpa_supplicant Feb 21 09:22:55 volumitest systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Feb 21 09:22:55 volumitest avahi-daemon[494]: Loading service file /services/volumio.service. Feb 21 09:22:55 volumitest systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Feb 21 09:22:55 volumitest avahi-daemon[494]: Network interface enumeration completed. Feb 21 09:22:55 volumitest avahi-daemon[494]: Server startup complete. Host name is volumitest.local. Local service cookie is 1916050279. Feb 21 09:22:55 volumitest avahi-daemon[494]: Service "VolumiTest" (/services/volumio.service) successfully established. Feb 21 09:22:55 volumitest systemd[1]: Started Raspberry Pi bluetooth helper. Feb 21 09:22:55 volumitest systemd[1]: Started Avahi mDNS/DNS-SD Stack. Feb 21 09:22:55 volumitest systemd[1]: Started WPA supplicant. Feb 21 09:22:56 volumitest systemd[1]: Starting Bluetooth service... Feb 21 09:22:56 volumitest systemd[1]: Reached target Network. Feb 21 09:22:56 volumitest systemd[1]: Starting Network Time Service... Feb 21 09:22:56 volumitest systemd[1]: Starting Permit User Sessions... Feb 21 09:22:56 volumitest systemd[1]: Reached target Network is Online. Feb 21 09:22:56 volumitest systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Feb 21 09:22:56 volumitest loadcpufreq[476]: Loading cpufreq kernel modules...done (none). Feb 21 09:22:56 volumitest systemd[1]: Starting Samba NMB Daemon... Feb 21 09:22:56 volumitest systemd[1]: Starting LSB: Brings up/down network automatically... Feb 21 09:22:56 volumitest systemd[1]: Starting /etc/rc.local Compatibility... Feb 21 09:22:56 volumitest systemd[1]: Condition check resulted in fast remote file copy program daemon being skipped. Feb 21 09:22:56 volumitest systemd[1]: Started LSB: Load kernel modules needed to enable cpufreq scaling. Feb 21 09:22:56 volumitest systemd[1]: Started Permit User Sessions. Feb 21 09:22:56 volumitest systemd[1]: Started /etc/rc.local Compatibility. Feb 21 09:22:56 volumitest systemd[1]: Starting Terminate Plymouth Boot Screen... Feb 21 09:22:56 volumitest systemd[1]: Starting Hold until boot process finishes up... Feb 21 09:22:56 volumitest systemd[1]: Starting LSB: set CPUFreq kernel parameters... Feb 21 09:22:56 volumitest systemd[1]: plymouth-quit.service: Succeeded. Feb 21 09:22:56 volumitest systemd[1]: Started Terminate Plymouth Boot Screen. Feb 21 09:22:56 volumitest systemd[1]: plymouth-start.service: Succeeded. Feb 21 09:22:56 volumitest systemd[1]: plymouth-quit-wait.service: Succeeded. Feb 21 09:22:56 volumitest systemd[1]: Started Hold until boot process finishes up. Feb 21 09:22:56 volumitest systemd[1]: Received SIGRTMIN+21 from PID 240 (n/a). Feb 21 09:22:56 volumitest systemd[1]: Received SIGRTMIN+21 from PID 240 (n/a). Feb 21 09:22:56 volumitest bluetoothd[602]: Bluetooth daemon 5.50 Feb 21 09:22:56 volumitest bluetoothd[602]: Unknown key AutoConnectTimeout for group General in /etc/bluetooth/main.conf Feb 21 09:22:56 volumitest bluetoothd[602]: Starting SDP server Feb 21 09:22:56 volumitest bluetoothd[602]: Excluding (cli) sap Feb 21 09:22:56 volumitest systemd[1]: Started Bluetooth service. Feb 21 09:22:56 volumitest ifplugd(eth0)[638]: ifplugd 0.28 initializing. Feb 21 09:22:56 volumitest ifplugd(eth0)[638]: Using interface eth0/B8:27:EB:44:39:42 with driver (version: 6.1.69-v7+) Feb 21 09:22:56 volumitest systemd[1]: Reached target Bluetooth. Feb 21 09:22:56 volumitest ifplugd(eth0)[638]: Using detection mode: SIOCETHTOOL Feb 21 09:22:56 volumitest ifplugd(eth0)[638]: Initialization complete, link beat not detected. Feb 21 09:22:56 volumitest ntpd[608]: ntpd 4.2.8p12@1.3728-o (1): Starting Feb 21 09:22:56 volumitest ntpd[608]: Command line: /usr/sbin/ntpd -p /var/run/ntpd.pid -g -u 103:103 Feb 21 09:22:56 volumitest systemd[1]: Started Getty on tty1. Feb 21 09:22:56 volumitest systemd[1]: Reached target Login Prompts. Feb 21 09:22:56 volumitest kernel: Bluetooth: BNEP (Ethernet Emulation) ver 1.3 Feb 21 09:22:56 volumitest kernel: Bluetooth: BNEP filters: protocol multicast Feb 21 09:22:56 volumitest kernel: Bluetooth: BNEP socket layer initialized Feb 21 09:22:56 volumitest ntpd[642]: proto: precision = 1.458 usec (-19) Feb 21 09:22:56 volumitest bluetoothd[602]: Bluetooth management interface 1.22 initialized Feb 21 09:22:56 volumitest kernel: Bluetooth: MGMT ver 1.22 Feb 21 09:22:56 volumitest dbus-daemon[486]: [system] Activating via systemd: service name='org.freedesktop.hostname1' unit='dbus-org.freedesktop.hostname1.service' requested by ':1.4' (uid=0 pid=602 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap ") Feb 21 09:22:56 volumitest ifplugd[612]: Network Interface Plugging Daemon...start eth0...done. Feb 21 09:22:56 volumitest systemd[1]: Started Network Time Service. Feb 21 09:22:56 volumitest systemd[1]: Started LSB: Brings up/down network automatically. Feb 21 09:22:56 volumitest ntpd[642]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): good hash signature Feb 21 09:22:56 volumitest ntpd[642]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): loaded, expire=2024-06-28T00:00:00Z last=2017-01-01T00:00:00Z ofs=37 Feb 21 09:22:56 volumitest ntpd[642]: Listen and drop on 0 v6wildcard [::]:123 Feb 21 09:22:56 volumitest ntpd[642]: Listen and drop on 1 v4wildcard 0.0.0.0:123 Feb 21 09:22:56 volumitest ntpd[642]: Listen normally on 2 lo 127.0.0.1:123 Feb 21 09:22:56 volumitest ntpd[642]: Listening on routing socket on fd #19 for interface updates Feb 21 09:22:56 volumitest ntpd[642]: kernel reports TIME_ERROR: 0x41: Clock Unsynchronized Feb 21 09:22:56 volumitest ntpd[642]: kernel reports TIME_ERROR: 0x41: Clock Unsynchronized Feb 21 09:22:56 volumitest systemd[1]: iptables.service: Succeeded. Feb 21 09:22:56 volumitest bluetoothd[602]: Failed to set privacy: Rejected (0x0b) Feb 21 09:22:57 volumitest cpufrequtils[625]: CPUFreq Utilities: Setting ondemand CPUFreq governor...CPU0...CPU1...CPU2...CPU3...done. Feb 21 09:22:57 volumitest systemd[1]: Started LSB: set CPUFreq kernel parameters. Feb 21 09:22:57 volumitest systemd[1]: Starting Hostname Service... Feb 21 09:22:57 volumitest haveged[442]: haveged: ver: 1.9.1; arch: generic; vend: ; build: (gcc 8.2.0 CTV); collect: 128K Feb 21 09:22:57 volumitest haveged[442]: haveged: cpu: (VC); data: 16K (D); inst: 16K (D); idx: 11/40; sz: 14768/63488 Feb 21 09:22:57 volumitest haveged[442]: haveged: tot tests(BA8): A:1/1 B:1/1 continuous tests(B): last entropy estimate 7.99646 Feb 21 09:22:57 volumitest haveged[442]: haveged: fills: 0, generated: 0 Feb 21 09:22:57 volumitest dbus-daemon[486]: [system] Successfully activated service 'org.freedesktop.hostname1' Feb 21 09:22:57 volumitest systemd[1]: Started Hostname Service. Feb 21 09:22:57 volumitest nmbd[618]: [2024/02/21 09:22:57.754606, 0] ../source3/nmbd/asyncdns.c:158(start_async_dns) Feb 21 09:22:57 volumitest nmbd[618]: started asyncdns process 663 Feb 21 09:22:57 volumitest nmbd[618]: [2024/02/21 09:22:57.756657, 0] ../lib/util/become_daemon.c:149(daemon_status) Feb 21 09:22:57 volumitest nmbd[618]: daemon_status: STATUS=daemon 'nmbd' : No local IPv4 non-loopback interfaces available, waiting for interface ... Feb 21 09:22:57 volumitest nmbd[618]: [2024/02/21 09:22:57.756838, 0] ../source3/nmbd/nmbd_subnetdb.c:254(create_subnets) Feb 21 09:22:57 volumitest nmbd[618]: NOTE: NetBIOS name resolution is not supported for Internet Protocol Version 6 (IPv6). Feb 21 09:22:57 volumitest ntpd[642]: error resolving pool 0.debian.pool.ntp.org: System error (-11) Feb 21 09:22:58 volumitest wireless.js[481]: Cleaning previous... Feb 21 09:22:58 volumitest sudo[671]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ip addr flush dev wlan0 Feb 21 09:22:58 volumitest sudo[671]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 21 09:22:58 volumitest sudo[671]: pam_unix(sudo:session): session closed for user root Feb 21 09:22:58 volumitest sudo[673]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 down Feb 21 09:22:58 volumitest sudo[673]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 21 09:22:58 volumitest ntpd[642]: error resolving pool 1.debian.pool.ntp.org: System error (-11) Feb 21 09:22:58 volumitest sudo[673]: pam_unix(sudo:session): session closed for user root Feb 21 09:22:59 volumitest wireless.js[481]: Stopped aP Feb 21 09:22:59 volumitest sudo[680]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 up Feb 21 09:22:59 volumitest sudo[680]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 21 09:22:59 volumitest kernel: brcmfmac: brcmf_cfg80211_set_power_mgmt: power save disabled Feb 21 09:22:59 volumitest sudo[680]: pam_unix(sudo:session): session closed for user root Feb 21 09:22:59 volumitest sudo[682]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iw reg get Feb 21 09:22:59 volumitest sudo[682]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 21 09:22:59 volumitest sudo[682]: pam_unix(sudo:session): session closed for user root Feb 21 09:22:59 volumitest sudo[689]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 up Feb 21 09:22:59 volumitest sudo[689]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 21 09:22:59 volumitest systemd[1]: systemd-rfkill.service: Succeeded. Feb 21 09:22:59 volumitest sudo[689]: pam_unix(sudo:session): session closed for user root Feb 21 09:22:59 volumitest sudo[691]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iw wlan0 scan Feb 21 09:22:59 volumitest sudo[691]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 21 09:22:59 volumitest ntpd[642]: error resolving pool 2.debian.pool.ntp.org: System error (-11) Feb 21 09:23:00 volumitest volumio-remote-updater[485]: [2024-02-21 09:23:00] [info] asio async_connect error: system:111 (Connection refused) Feb 21 09:23:00 volumitest volumio-remote-updater[485]: [2024-02-21 09:23:00] [info] Error getting remote endpoint: system:107 (Transport endpoint is not connected) Feb 21 09:23:00 volumitest volumio-remote-updater[485]: [2024-02-21 09:23:00] [error] handle_connect error: Underlying Transport Error Feb 21 09:23:00 volumitest ntpd[642]: error resolving pool 3.debian.pool.ntp.org: System error (-11) Feb 21 09:23:00 volumitest bthelper[564]: Changing power off succeeded Feb 21 09:23:01 volumitest bthelper[564]: [CHG] Controller B8:27:EB:EE:93:E8 Class: 0x0000041c Feb 21 09:23:01 volumitest bthelper[564]: Changing power on succeeded Feb 21 09:23:01 volumitest sudo[691]: pam_unix(sudo:session): session closed for user root Feb 21 09:23:01 volumitest wireless.js[481]: SETTING APPROPRIATE REG DOMAIN: DE Feb 21 09:23:01 volumitest sudo[703]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 up Feb 21 09:23:01 volumitest sudo[703]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 21 09:23:01 volumitest wireless.js[481]: SUCCESSFULLY SET NEW REGDOMAIN: DE Feb 21 09:23:01 volumitest wireless.js[481]: Start wireless flow Feb 21 09:23:01 volumitest wireless.js[481]: Stopped hotspot (if there).. Feb 21 09:23:01 volumitest sudo[703]: pam_unix(sudo:session): session closed for user root Feb 21 09:23:01 volumitest sudo[705]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iw reg set DE Feb 21 09:23:01 volumitest sudo[705]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 21 09:23:01 volumitest sudo[705]: pam_unix(sudo:session): session closed for user root Feb 21 09:23:01 volumitest sudo[710]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ip addr flush dev wlan0 Feb 21 09:23:01 volumitest sudo[710]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 21 09:23:01 volumitest sudo[710]: pam_unix(sudo:session): session closed for user root Feb 21 09:23:01 volumitest sudo[712]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 down Feb 21 09:23:01 volumitest sudo[712]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 21 09:23:02 volumitest sudo[712]: pam_unix(sudo:session): session closed for user root Feb 21 09:23:02 volumitest wireless.js[481]: DHCP IP Feb 21 09:23:02 volumitest wireless.js[481]: Start ap Feb 21 09:23:02 volumitest wpa_supplicant[714]: Successfully initialized wpa_supplicant Feb 21 09:23:02 volumitest sudo[715]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/dhcpcd Feb 21 09:23:02 volumitest sudo[715]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 21 09:23:02 volumitest kernel: brcmfmac: brcmf_cfg80211_set_power_mgmt: power save disabled Feb 21 09:23:02 volumitest dhcpcd[716]: dev: loaded udev Feb 21 09:23:02 volumitest dhcpcd-run-hooks[734]: wlan0: starting wpa_supplicant Feb 21 09:23:02 volumitest dhcpcd-run-hooks[739]: wlan0: failed to start wpa_supplicant Feb 21 09:23:02 volumitest dhcpcd-run-hooks[740]: wlan0: Successfully initialized wpa_supplicant nl80211: kernel reports: Match already configured nl80211: kernel reports: Match already configured nl80211: kernel reports: Match already configured nl80211: kernel reports: Match already configured nl80211: kernel reports: Match already configured nl80211: kernel reports: Match already configured nl80211: kernel reports: Match already configured nl80211: kernel reports: Match already configured nl80211: kernel reports: Match already configured nl80211: kernel reports: Match already configured nl80211: kernel reports: Match already configured nl80211: kernel reports: Match already configured nl80211: kernel reports: Match already configured nl80211: kernel reports: Match already configured nl80211: kernel reports: Match already configured nl80211: kernel reports: Match already configured nl80211: kernel reports: Match already configured nl80211: kernel reports: Match already configured nl80211: kernel reports: Match already configured nl80211: kernel reports: Ma Feb 21 09:23:02 volumitest dhcpcd[716]: wlan0: connected to Access Point `' Feb 21 09:23:02 volumitest dhcpcd[716]: no interfaces have a carrier Feb 21 09:23:02 volumitest dhcpcd[716]: forked to background, child pid 750 Feb 21 09:23:02 volumitest dhcpcd[750]: eth0: waiting for carrier Feb 21 09:23:02 volumitest dhcpcd[750]: wlan0: waiting for carrier Feb 21 09:23:02 volumitest sudo[715]: pam_unix(sudo:session): session closed for user root Feb 21 09:23:03 volumitest wireless.js[481]: trying... Feb 21 09:23:03 volumitest sudo[752]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Feb 21 09:23:03 volumitest sudo[752]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 21 09:23:03 volumitest sudo[752]: pam_unix(sudo:session): session closed for user root Feb 21 09:23:04 volumitest wireless.js[481]: trying... Feb 21 09:23:04 volumitest sudo[755]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Feb 21 09:23:04 volumitest sudo[755]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 21 09:23:04 volumitest sudo[755]: pam_unix(sudo:session): session closed for user root Feb 21 09:23:05 volumitest wpa_supplicant[738]: wlan0: Trying to associate with SSID 'vajfaj5G' Feb 21 09:23:05 volumitest wireless.js[481]: trying... Feb 21 09:23:05 volumitest sudo[758]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Feb 21 09:23:05 volumitest sudo[758]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 21 09:23:05 volumitest sudo[758]: pam_unix(sudo:session): session closed for user root Feb 21 09:23:06 volumitest wireless.js[481]: trying... Feb 21 09:23:06 volumitest sudo[761]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Feb 21 09:23:06 volumitest sudo[761]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 21 09:23:06 volumitest sudo[761]: pam_unix(sudo:session): session closed for user root Feb 21 09:23:07 volumitest wireless.js[481]: trying... Feb 21 09:23:07 volumitest sudo[764]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Feb 21 09:23:07 volumitest sudo[764]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 21 09:23:07 volumitest sudo[764]: pam_unix(sudo:session): session closed for user root Feb 21 09:23:07 volumitest dhcpcd[750]: wlan0: carrier acquired Feb 21 09:23:07 volumitest dhcpcd[750]: wlan0: connected to Access Point `vajfaj5G' Feb 21 09:23:07 volumitest wpa_supplicant[738]: wlan0: Associated with 1c:61:b4:2a:1f:22 Feb 21 09:23:07 volumitest wpa_supplicant[738]: wlan0: CTRL-EVENT-CONNECTED - Connection to 1c:61:b4:2a:1f:22 completed [id=0 id_str=] Feb 21 09:23:07 volumitest wpa_supplicant[738]: wlan0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0 Feb 21 09:23:07 volumitest wpa_supplicant[738]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=COUNTRY_IE type=COUNTRY alpha2=DE Feb 21 09:23:07 volumitest dhcpcd[750]: DUID 00:01:00:01:2d:5e:65:3a:b8:27:eb:11:6c:17 Feb 21 09:23:07 volumitest dhcpcd[750]: wlan0: IAID eb:11:6c:17 Feb 21 09:23:07 volumitest dhcpcd[750]: wlan0: adding address fe80::631c:5b4b:2ebe:a9b8 Feb 21 09:23:07 volumitest dhcpcd[750]: ipv6_addaddr1: Permission denied Feb 21 09:23:07 volumitest dhcpcd[750]: wlan0: carrier lost Feb 21 09:23:07 volumitest dhcpcd[750]: wlan0: carrier acquired Feb 21 09:23:07 volumitest dhcpcd[750]: wlan0: IAID eb:11:6c:17 Feb 21 09:23:07 volumitest dhcpcd[750]: wlan0: soliciting an IPv6 router Feb 21 09:23:08 volumitest volumio-remote-updater[485]: [2024-02-21 09:23:08] [info] asio async_connect error: system:111 (Connection refused) Feb 21 09:23:08 volumitest volumio-remote-updater[485]: [2024-02-21 09:23:08] [info] Error getting remote endpoint: system:107 (Transport endpoint is not connected) Feb 21 09:23:08 volumitest volumio-remote-updater[485]: [2024-02-21 09:23:08] [error] handle_connect error: Underlying Transport Error Feb 21 09:23:08 volumitest dhcpcd[750]: wlan0: rebinding lease of 192.168.1.6 Feb 21 09:23:08 volumitest dhcpcd[750]: wlan0: probing address 192.168.1.6/24 Feb 21 09:23:08 volumitest wireless.js[481]: trying... Feb 21 09:23:08 volumitest sudo[779]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Feb 21 09:23:08 volumitest sudo[779]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 21 09:23:08 volumitest sudo[779]: pam_unix(sudo:session): session closed for user root Feb 21 09:23:09 volumitest wireless.js[481]: trying... Feb 21 09:23:09 volumitest sudo[782]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Feb 21 09:23:09 volumitest sudo[782]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 21 09:23:09 volumitest sudo[782]: pam_unix(sudo:session): session closed for user root Feb 21 09:23:10 volumitest wireless.js[481]: trying... Feb 21 09:23:10 volumitest sudo[785]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Feb 21 09:23:10 volumitest sudo[785]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 21 09:23:10 volumitest sudo[785]: pam_unix(sudo:session): session closed for user root Feb 21 09:23:11 volumitest wireless.js[481]: trying... Feb 21 09:23:11 volumitest sudo[788]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Feb 21 09:23:11 volumitest sudo[788]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 21 09:23:11 volumitest sudo[788]: pam_unix(sudo:session): session closed for user root Feb 21 09:23:12 volumitest wireless.js[481]: trying... Feb 21 09:23:12 volumitest sudo[791]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Feb 21 09:23:12 volumitest sudo[791]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 21 09:23:12 volumitest sudo[791]: pam_unix(sudo:session): session closed for user root Feb 21 09:23:13 volumitest wireless.js[481]: trying... Feb 21 09:23:13 volumitest sudo[794]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Feb 21 09:23:13 volumitest sudo[794]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 21 09:23:13 volumitest sudo[794]: pam_unix(sudo:session): session closed for user root Feb 21 09:23:13 volumitest dhcpcd[750]: wlan0: leased 192.168.1.6 for 86400 seconds Feb 21 09:23:13 volumitest avahi-daemon[494]: Joining mDNS multicast group on interface wlan0.IPv4 with address 192.168.1.6. Feb 21 09:23:13 volumitest avahi-daemon[494]: New relevant interface wlan0.IPv4 for mDNS. Feb 21 09:23:13 volumitest dhcpcd[750]: wlan0: adding route to 192.168.1.0/24 Feb 21 09:23:13 volumitest avahi-daemon[494]: Registering new address record for 192.168.1.6 on wlan0.IPv4. Feb 21 09:23:13 volumitest dhcpcd[750]: wlan0: adding default route via 192.168.1.1 Feb 21 09:23:14 volumitest wireless.js[481]: trying... Feb 21 09:23:14 volumitest sudo[818]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Feb 21 09:23:14 volumitest sudo[818]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 21 09:23:14 volumitest sudo[818]: pam_unix(sudo:session): session closed for user root Feb 21 09:23:14 volumitest wireless.js[481]: Connected to: ----vajfaj5G Feb 21 09:23:14 volumitest wireless.js[481]: ---- Feb 21 09:23:14 volumitest sudo[821]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Feb 21 09:23:14 volumitest sudo[821]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 21 09:23:14 volumitest sudo[821]: pam_unix(sudo:session): session closed for user root Feb 21 09:23:14 volumitest wireless.js[481]: ... joined AP, wlan0 IPv4 is 192.168.1.6, ipV6 is undefined Feb 21 09:23:14 volumitest wireless.js[481]: It's done! AP Feb 21 09:23:14 volumitest systemd[1]: Started Wireless Services. Feb 21 09:23:14 volumitest systemd[1]: Started Volumio Backend Module. Feb 21 09:23:14 volumitest kernel: brcmfmac: brcmf_cfg80211_set_power_mgmt: power save disabled Feb 21 09:23:14 volumitest systemd[1]: Started Volumio Cpu Tweaker. Feb 21 09:23:14 volumitest volumio-cpu-tweak[827]: Setting RT Priority for mpd Feb 21 09:23:14 volumitest volumio-cpu-tweak[827]: pid 35's current scheduling policy: SCHED_OTHER Feb 21 09:23:14 volumitest volumio-cpu-tweak[827]: pid 35's current scheduling priority: 0 Feb 21 09:23:14 volumitest volumio-cpu-tweak[827]: Setting MPD Affinity Feb 21 09:23:14 volumitest volumio-cpu-tweak[827]: pid 3's current affinity mask: f Feb 21 09:23:14 volumitest volumio-cpu-tweak[827]: /bin/volumio_cpu_tweak: line 27: warning: command substitution: ignored null byte in input Feb 21 09:23:14 volumitest volumio-cpu-tweak[827]: VOLUMIO CPU TWEAK: Setting CPU Governor: performance Feb 21 09:23:14 volumitest ntpd[642]: Listen normally on 3 wlan0 192.168.1.6:123 Feb 21 09:23:14 volumitest ntpd[642]: new interface(s) found: waking up resolver Feb 21 09:23:14 volumitest systemd[1]: volumio_cpu_tweak.service: Succeeded. Feb 21 09:23:17 volumitest volumio[826]: info: ------------------------------------------- Feb 21 09:23:17 volumitest volumio[826]: info: ----- Volumio3 ---- Feb 21 09:23:17 volumitest volumio[826]: info: ------------------------------------------- Feb 21 09:23:17 volumitest volumio[826]: info: ----- System startup ---- Feb 21 09:23:17 volumitest volumio[826]: info: ------------------------------------------- Feb 21 09:23:17 volumitest nmbd[618]: [2024/02/21 09:23:17.764010, 0] ../lib/util/become_daemon.c:138(daemon_ready) Feb 21 09:23:17 volumitest nmbd[618]: daemon_ready: STATUS=daemon 'nmbd' finished starting up and ready to serve connections Feb 21 09:23:17 volumitest systemd[1]: Started Samba NMB Daemon. Feb 21 09:23:17 volumitest systemd[1]: Starting Samba Winbind Daemon... Feb 21 09:23:18 volumitest volumio-remote-updater[485]: [2024-02-21 09:23:18] [connect] Successful connection Feb 21 09:23:18 volumitest winbindd[851]: [2024/02/21 09:23:18.167163, 0] ../source3/winbindd/winbindd_cache.c:3160(initialize_winbindd_cache) Feb 21 09:23:18 volumitest winbindd[851]: initialize_winbindd_cache: clearing cache and re-creating with version number 2 Feb 21 09:23:18 volumitest systemd[1]: Started Samba Winbind Daemon. Feb 21 09:23:18 volumitest winbindd[851]: [2024/02/21 09:23:18.230714, 0] ../lib/util/become_daemon.c:138(daemon_ready) Feb 21 09:23:18 volumitest winbindd[851]: daemon_ready: STATUS=daemon 'winbindd' finished starting up and ready to serve connections Feb 21 09:23:18 volumitest systemd[1]: Starting Samba SMB Daemon... Feb 21 09:23:18 volumitest volumio[826]: info: MYVOLUMIO Environment detected Feb 21 09:23:18 volumitest volumio[826]: info: Plugin folders cleanup Feb 21 09:23:18 volumitest volumio[826]: info: Scanning into folder /volumio/app/plugins/ Feb 21 09:23:18 volumitest volumio[826]: info: Scanning category audio_interface Feb 21 09:23:18 volumitest volumio[826]: info: Scanning category miscellanea Feb 21 09:23:18 volumitest volumio[826]: info: Scanning category music_service Feb 21 09:23:18 volumitest volumio[826]: info: Scanning category plugins.json Feb 21 09:23:18 volumitest volumio[826]: info: Scanning category system_controller Feb 21 09:23:18 volumitest volumio[826]: info: Scanning category user_interface Feb 21 09:23:18 volumitest volumio[826]: info: Scanning into folder /data/plugins/ Feb 21 09:23:18 volumitest volumio[826]: info: Scanning category music_service Feb 21 09:23:18 volumitest volumio[826]: info: Plugin folders cleanup completed Feb 21 09:23:18 volumitest volumio[826]: info: ------------------------------------------- Feb 21 09:23:18 volumitest volumio[826]: info: ----- Core plugins startup ---- Feb 21 09:23:18 volumitest volumio[826]: info: ------------------------------------------- Feb 21 09:23:18 volumitest volumio[826]: info: Loading plugins from folder /volumio/app/plugins/ Feb 21 09:23:18 volumitest volumio[826]: info: Adding plugin upnp to MyMusic Plugins Feb 21 09:23:18 volumitest volumio[826]: info: Adding plugin airplay_emulation to MyMusic Plugins Feb 21 09:23:18 volumitest volumio[826]: info: Adding plugin upnp_browser to MyMusic Plugins Feb 21 09:23:18 volumitest volumio[826]: info: Loading plugins from folder /data/plugins/ Feb 21 09:23:18 volumitest volumio[826]: info: Loading plugin "system"... Feb 21 09:23:18 volumitest volumio[826]: info: Loading plugin "appearance"... Feb 21 09:23:18 volumitest winbindd[851]: [2024/02/21 09:23:18.754763, 0] ../source3/winbindd/wb_lookupsids.c:659(wb_lookupsids_recv) Feb 21 09:23:18 volumitest winbindd[851]: res_names->count = 3, expected 4 Feb 21 09:23:18 volumitest smbd[856]: [2024/02/21 09:23:18.780086, 0] ../lib/util/become_daemon.c:138(daemon_ready) Feb 21 09:23:18 volumitest systemd[1]: Started Samba SMB Daemon. Feb 21 09:23:18 volumitest smbd[856]: daemon_ready: STATUS=daemon 'smbd' finished starting up and ready to serve connections Feb 21 09:23:18 volumitest systemd[1]: Reached target Multi-User System. Feb 21 09:23:18 volumitest systemd[1]: Reached target Graphical Interface. Feb 21 09:23:18 volumitest systemd[1]: Starting Update UTMP about System Runlevel Changes... Feb 21 09:23:18 volumitest systemd[1]: systemd-update-utmp-runlevel.service: Succeeded. Feb 21 09:23:18 volumitest systemd[1]: Started Update UTMP about System Runlevel Changes. Feb 21 09:23:18 volumitest systemd[1]: Startup finished in 10.137s (kernel) + 31.809s (userspace) = 41.946s. Feb 21 09:23:20 volumitest volumio[826]: info: Loading plugin "network"... Feb 21 09:23:20 volumitest volumio[826]: info: Refreshing Cached IP Addresses Feb 21 09:23:20 volumitest sudo[868]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Feb 21 09:23:20 volumitest sudo[868]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 21 09:23:20 volumitest volumio[826]: info: Loading plugin "services"... Feb 21 09:23:20 volumitest sudo[870]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Feb 21 09:23:20 volumitest sudo[868]: pam_unix(sudo:session): session closed for user root Feb 21 09:23:20 volumitest sudo[870]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 21 09:23:20 volumitest sudo[870]: pam_unix(sudo:session): session closed for user root Feb 21 09:23:20 volumitest volumio[826]: info: Loading plugin "alsa_controller"... Feb 21 09:23:20 volumitest sudo[873]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Feb 21 09:23:20 volumitest sudo[873]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 21 09:23:20 volumitest volumio[826]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Feb 21 09:23:20 volumitest volumio[826]: info: Loading plugin "wizard"... Feb 21 09:23:20 volumitest volumio[826]: info: Loading plugin "networkfs"... Feb 21 09:23:20 volumitest volumio[826]: info: Starting Udev Watcher for removable devices Feb 21 09:23:20 volumitest sudo[879]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o guest,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //192.168.1.169/homelab/Music /mnt/NAS/homecloud Feb 21 09:23:20 volumitest sudo[879]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 21 09:23:20 volumitest volumio[826]: info: Ignoring mount for partition: boot Feb 21 09:23:20 volumitest volumio[826]: info: Ignoring mount for partition: volumio Feb 21 09:23:20 volumitest volumio[826]: info: Ignoring mount for partition: volumio_data Feb 21 09:23:20 volumitest volumio[826]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Feb 21 09:23:20 volumitest volumio[826]: info: Loading plugin "volumio_command_line_client"... Feb 21 09:23:20 volumitest volumio[826]: info: Loading plugin "upnp"... Feb 21 09:23:20 volumitest volumio[826]: info: [1708503800349] Starting Upmpd Daemon Feb 21 09:23:20 volumitest volumio[826]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Feb 21 09:23:20 volumitest volumio[826]: info: Loading plugin "my_music"... Feb 21 09:23:20 volumitest volumio[826]: info: Loading plugin "mpd"... Feb 21 09:23:20 volumitest kernel: Key type cifs.spnego registered Feb 21 09:23:20 volumitest kernel: Key type cifs.idmap registered Feb 21 09:23:20 volumitest 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 21 09:23:20 volumitest kernel: CIFS: Attempting to mount \\192.168.1.169\homelab Feb 21 09:23:20 volumitest sudo[879]: pam_unix(sudo:session): session closed for user root Feb 21 09:23:20 volumitest kernel: CIFS: VFS: Error connecting to socket. Aborting operation. Feb 21 09:23:20 volumitest kernel: CIFS: VFS: cifs_mount failed w/return code = -113 Feb 21 09:23:20 volumitest volumio[826]: info: Loading plugin "upnp_browser"... Feb 21 09:23:21 volumitest volumio[826]: info: Loading plugin "alarm-clock"... Feb 21 09:23:21 volumitest volumio[826]: info: Loading plugin "airplay_emulation"... Feb 21 09:23:21 volumitest volumio[826]: info: Starting Shairport Sync Feb 21 09:23:21 volumitest volumio[826]: info: Loading plugin "last_100"... Feb 21 09:23:21 volumitest volumio[826]: info: Loading plugin "webradio"... Feb 21 09:23:21 volumitest volumio[826]: info: Loading plugin "i2s_dacs"... Feb 21 09:23:21 volumitest volumio[826]: info: I2S DAC not set, start Auto-detection Feb 21 09:23:21 volumitest volumio[826]: info: Loading plugin "volumiodiscovery"... Feb 21 09:23:21 volumitest volumio[826]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Feb 21 09:23:21 volumitest volumio[826]: *** WARNING *** Please fix your application to use the native API of Avahi! Feb 21 09:23:21 volumitest volumio[826]: *** WARNING *** For more information see Feb 21 09:23:21 volumitest node[826]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Feb 21 09:23:21 volumitest volumio[826]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Feb 21 09:23:21 volumitest volumio[826]: *** WARNING *** Please fix your application to use the native API of Avahi! Feb 21 09:23:21 volumitest volumio[826]: *** WARNING *** For more information see Feb 21 09:23:21 volumitest node[826]: *** WARNING *** Please fix your application to use the native API of Avahi! Feb 21 09:23:21 volumitest node[826]: *** WARNING *** For more information see Feb 21 09:23:21 volumitest node[826]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Feb 21 09:23:21 volumitest node[826]: *** WARNING *** Please fix your application to use the native API of Avahi! Feb 21 09:23:21 volumitest node[826]: *** WARNING *** For more information see Feb 21 09:23:21 volumitest volumio[826]: info: Applying required configuration parameters for plugin volumiodiscovery Feb 21 09:23:21 volumitest volumio[826]: info: Discovery: Started advertising with name: VolumiTest Feb 21 09:23:21 volumitest volumio[826]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Feb 21 09:23:21 volumitest volumio[826]: info: Loading plugin "spop"... Feb 21 09:23:21 volumitest systemd[1]: systemd-fsckd.service: Succeeded. Feb 21 09:23:23 volumitest volumio[826]: info: Loading plugin "outputs"... Feb 21 09:23:23 volumitest volumio[826]: info: Loading plugin "albumart"... Feb 21 09:23:23 volumitest volumio[826]: info: Plugin example_plugin is not enabled Feb 21 09:23:23 volumitest volumio[826]: info: Loading plugin "inputs"... Feb 21 09:23:23 volumitest volumio[826]: info: Loading plugin "updater_comm"... Feb 21 09:23:23 volumitest volumio[826]: info: Plugin mpdemulation is not enabled Feb 21 09:23:23 volumitest volumio[826]: info: Loading plugin "rest_api"... Feb 21 09:23:23 volumitest volumio[826]: info: Loading plugin "websocket"... Feb 21 09:23:23 volumitest volumio[826]: info: Loading i18n strings for locale sk Feb 21 09:23:23 volumitest volumio[826]: Updating browse sources language Feb 21 09:23:23 volumitest volumio[826]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 21 09:23:23 volumitest volumio[826]: Forking 3 albumart workers Feb 21 09:23:23 volumitest sudo[873]: pam_unix(sudo:session): session closed for user root Feb 21 09:23:23 volumitest volumio[826]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 21 09:23:23 volumitest volumio[826]: info: CoreCommandRouter::initPlayerControls Feb 21 09:23:23 volumitest volumio[826]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 21 09:23:23 volumitest volumio[826]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 21 09:23:23 volumitest volumio[826]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 21 09:23:23 volumitest volumio[826]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 21 09:23:23 volumitest volumio[826]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 21 09:23:23 volumitest volumio[826]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 21 09:23:23 volumitest volumio[826]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 21 09:23:23 volumitest volumio[826]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 21 09:23:23 volumitest volumio[826]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 21 09:23:23 volumitest volumio[826]: Express server listening on port 3000 Feb 21 09:23:23 volumitest volumio[826]: [Metrics] WebUI: 7s 683.47ms Feb 21 09:23:24 volumitest volumio[826]: info: CoreStateMachine::resetVolumioState Feb 21 09:23:24 volumitest volumio[826]: info: CoreStateMachine::getcurrentVolume Feb 21 09:23:24 volumitest volumio[826]: info: CoreCommandRouter::volumioRetrievevolume Feb 21 09:23:24 volumitest volumio[826]: info: CoreStateMachine::pushState Feb 21 09:23:24 volumitest volumio[826]: info: CorePlayQueue::getTrack 0 Feb 21 09:23:24 volumitest volumio[826]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 21 09:23:24 volumitest volumio[826]: info: CoreCommandRouter::volumioPushState Feb 21 09:23:24 volumitest volumio[826]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 21 09:23:24 volumitest volumio[826]: info: Cannot mount NAS homecloud at system boot, trial number 1 ,retrying in 5 seconds Feb 21 09:23:24 volumitest volumio[826]: verbose: New Socket.io Connection to 192.168.1.6:3000 from 192.168.1.11 UA: node-XMLHttpRequest Total Clients: 1 Feb 21 09:23:24 volumitest volumio[826]: info: Reloading queue from file Feb 21 09:23:24 volumitest volumio[826]: info: CoreStateMachine::setRepeat null single undefined Feb 21 09:23:24 volumitest volumio[826]: info: CoreStateMachine::pushState Feb 21 09:23:24 volumitest volumio[826]: info: CorePlayQueue::getTrack 0 Feb 21 09:23:24 volumitest volumio[826]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 21 09:23:24 volumitest volumio[826]: info: CoreCommandRouter::volumioPushState Feb 21 09:23:24 volumitest volumio[826]: info: CoreStateMachine::setRandom null Feb 21 09:23:24 volumitest volumio[826]: info: CoreStateMachine::pushState Feb 21 09:23:24 volumitest volumio[826]: info: CorePlayQueue::getTrack 0 Feb 21 09:23:24 volumitest volumio[826]: info: CoreCommandRouter::volumioPushState Feb 21 09:23:24 volumitest volumio[826]: info: Setting Device type: Raspberry PI Feb 21 09:23:24 volumitest volumio[826]: info: Completed loading Core Plugins Feb 21 09:23:24 volumitest volumio[826]: info: Preparing to generate the ALSA configuration file Feb 21 09:23:24 volumitest volumio[826]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , initSocket Feb 21 09:23:24 volumitest volumio[826]: info: Discovery: adding a7119ebb-a202-4575-b48c-d5a5e94d4c69 Feb 21 09:23:24 volumitest volumio[826]: info: Discovery: Found device Volumio Feb 21 09:23:24 volumitest volumio[826]: info: Discovery: Connecting to remote: 192.168.1.11 Feb 21 09:23:24 volumitest volumio[826]: info: Discovery: adding f769a889-a088-4603-bddc-027e3eeeac6f Feb 21 09:23:24 volumitest volumio[826]: info: Discovery: Found device VolumiTest Feb 21 09:23:24 volumitest volumio[826]: info: CoreCommandRouter::volumioGetState Feb 21 09:23:24 volumitest volumio[826]: info: CorePlayQueue::getTrack 0 Feb 21 09:23:24 volumitest volumio[826]: info: Asound.conf file unchanged, so no further update is needed Feb 21 09:23:24 volumitest volumio[826]: info: Output device has changed, restarting MPD Feb 21 09:23:24 volumitest volumio[826]: info: Output device has changed, restarting Shairport Sync Feb 21 09:23:24 volumitest volumio[826]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 21 09:23:24 volumitest volumio[826]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 21 09:23:24 volumitest sudo[933]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Feb 21 09:23:24 volumitest sudo[933]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 21 09:23:24 volumitest sudo[934]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Feb 21 09:23:24 volumitest sudo[933]: pam_unix(sudo:session): session closed for user root Feb 21 09:23:24 volumitest sudo[934]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 21 09:23:24 volumitest volumio[826]: Starting albumart workers Feb 21 09:23:24 volumitest volumio[826]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Feb 21 09:23:24 volumitest volumio[826]: info: ___________ START PLUGINS ___________ Feb 21 09:23:24 volumitest volumio[826]: info: ControllerMpd::onStart: Initializing MPD Feb 21 09:23:24 volumitest volumio[826]: info: Creating MPD Configuration file Feb 21 09:23:24 volumitest volumio[826]: Starting albumart workers Feb 21 09:23:24 volumitest volumio[826]: Starting albumart workers Feb 21 09:23:24 volumitest volumio[826]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 21 09:23:24 volumitest volumio[826]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Feb 21 09:23:24 volumitest volumio[826]: info: [1708503804739] CoreMusicLibrary::Adding element Mediálne servery Feb 21 09:23:24 volumitest volumio[826]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 21 09:23:24 volumitest sudo[942]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Feb 21 09:23:24 volumitest sudo[942]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 21 09:23:24 volumitest sudo[942]: pam_unix(sudo:session): session closed for user root Feb 21 09:23:24 volumitest systemd[1]: Listening on mpd.socket. Feb 21 09:23:24 volumitest sudo[944]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Feb 21 09:23:24 volumitest systemd[1]: Starting Music Player Daemon... Feb 21 09:23:24 volumitest sudo[944]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 21 09:23:24 volumitest volumio[826]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 21 09:23:24 volumitest volumio[826]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 21 09:23:24 volumitest systemd[1]: mpd.service: Control process exited, code=killed, status=15/TERM Feb 21 09:23:24 volumitest systemd[1]: mpd.service: Succeeded. Feb 21 09:23:24 volumitest systemd[1]: Stopped Music Player Daemon. Feb 21 09:23:24 volumitest systemd[1]: Starting Music Player Daemon... Feb 21 09:23:24 volumitest volumio[826]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Feb 21 09:23:24 volumitest volumio[826]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 21 09:23:24 volumitest volumio[826]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 21 09:23:24 volumitest sudo[951]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Feb 21 09:23:24 volumitest sudo[951]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 21 09:23:24 volumitest sudo[951]: /bin/chown: cannot access '/var/log/mpd.log': No such file or directory Feb 21 09:23:24 volumitest sudo[951]: pam_unix(sudo:session): session closed for user root Feb 21 09:23:25 volumitest volumio[826]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Feb 21 09:23:25 volumitest volumio[826]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Feb 21 09:23:25 volumitest volumio[826]: info: [1708503805010] CoreMusicLibrary::Adding element Last_100 Feb 21 09:23:25 volumitest volumio[826]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 21 09:23:25 volumitest volumio[826]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Feb 21 09:23:25 volumitest volumio[826]: info: [1708503805014] CoreMusicLibrary::Adding element Webradio Feb 21 09:23:25 volumitest volumio[826]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 21 09:23:25 volumitest volumio[826]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Feb 21 09:23:25 volumitest volumio[826]: info: Creating Spotify config file Feb 21 09:23:25 volumitest volumio[826]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 21 09:23:25 volumitest volumio[826]: info: Volumio Calling Home Feb 21 09:23:25 volumitest volumio[826]: info: CoreCommandRouter::volumioGetState Feb 21 09:23:25 volumitest volumio[826]: info: CorePlayQueue::getTrack 0 Feb 21 09:23:25 volumitest volumio[826]: info: MPD Permissions set Feb 21 09:23:25 volumitest volumio[826]: info: MPD Permissions set Feb 21 09:23:25 volumitest sh[376]: timed out Feb 21 09:23:25 volumitest dhcpcd[427]: timed out Feb 21 09:23:25 volumitest sh[376]: dhcpcd exited Feb 21 09:23:25 volumitest dhcpcd[427]: dhcpcd exited Feb 21 09:23:25 volumitest sh[376]: ifup: failed to bring up eth0 Feb 21 09:23:25 volumitest systemd[1]: ifup@eth0.service: Main process exited, code=exited, status=1/FAILURE Feb 21 09:23:25 volumitest systemd[1]: ifup@eth0.service: Failed with result 'exit-code'. Feb 21 09:23:25 volumitest volumio[826]: info: Spotify config file written Feb 21 09:23:25 volumitest volumio[826]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 2 Feb 21 09:23:25 volumitest volumio[826]: info: Volumio called home Feb 21 09:23:25 volumitest volumio[826]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 21 09:23:25 volumitest volumio[826]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 21 09:23:25 volumitest volumio[826]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 21 09:23:25 volumitest volumio[826]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 21 09:23:25 volumitest volumio[826]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 21 09:23:25 volumitest volumio[826]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 21 09:23:25 volumitest volumio[826]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 21 09:23:25 volumitest volumio[826]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 21 09:23:25 volumitest sudo[970]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Feb 21 09:23:25 volumitest sudo[970]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 21 09:23:25 volumitest volumio[826]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 21 09:23:25 volumitest volumio[826]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 21 09:23:25 volumitest volumio[826]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 21 09:23:25 volumitest volumio[826]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 21 09:23:25 volumitest volumio[826]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 21 09:23:25 volumitest volumio[826]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 21 09:23:25 volumitest volumio[826]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 21 09:23:25 volumitest volumio[826]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 21 09:23:25 volumitest volumio[826]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 21 09:23:25 volumitest volumio[826]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 21 09:23:25 volumitest volumio[826]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 21 09:23:25 volumitest volumio[826]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 21 09:23:25 volumitest systemd[1]: Started go-librespot Daemon. Feb 21 09:23:25 volumitest go-librespot[980]: Librespot-go daemon starting... Feb 21 09:23:25 volumitest sudo[970]: pam_unix(sudo:session): session closed for user root Feb 21 09:23:25 volumitest volumio[826]: info: Discovery: Connected to remote: 192.168.1.11 Feb 21 09:23:25 volumitest volumio[826]: info: Starting Shairport Sync Feb 21 09:23:25 volumitest volumio[826]: info: Starting Shairport Sync Feb 21 09:23:25 volumitest volumio[826]: info: Starting Shairport Sync Feb 21 09:23:25 volumitest sudo[1004]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Feb 21 09:23:25 volumitest sudo[1004]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 21 09:23:25 volumitest sudo[1006]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Feb 21 09:23:25 volumitest sudo[1006]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 21 09:23:25 volumitest systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Feb 21 09:23:25 volumitest systemd[1]: shairport-sync.service: Succeeded. Feb 21 09:23:25 volumitest systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Feb 21 09:23:25 volumitest sudo[1010]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Feb 21 09:23:25 volumitest sudo[1010]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 21 09:23:26 volumitest systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Feb 21 09:23:26 volumitest sudo[1010]: pam_unix(sudo:session): session closed for user root Feb 21 09:23:26 volumitest sudo[1004]: pam_unix(sudo:session): session closed for user root Feb 21 09:23:26 volumitest sudo[1006]: pam_unix(sudo:session): session closed for user root Feb 21 09:23:26 volumitest volumio[826]: info: CoreCommandRouter::volumioGetState Feb 21 09:23:26 volumitest volumio[826]: info: CorePlayQueue::getTrack 0 Feb 21 09:23:26 volumitest volumio[826]: info: Shairport-Sync Started Feb 21 09:23:26 volumitest volumio[826]: Error adding Membership: Error: addMembership EINVAL Feb 21 09:23:26 volumitest volumio[826]: info: Shairport-Sync Started Feb 21 09:23:26 volumitest volumio[826]: info: Shairport-Sync Started Feb 21 09:23:26 volumitest volumio[826]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Feb 21 09:23:26 volumitest volumio[826]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Feb 21 09:23:26 volumitest volumio[826]: info: Discovery: Getting this device information Feb 21 09:23:26 volumitest volumio[826]: info: CoreCommandRouter::volumioGetState Feb 21 09:23:26 volumitest volumio[826]: info: CorePlayQueue::getTrack 0 Feb 21 09:23:26 volumitest volumio[826]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 21 09:23:26 volumitest volumio[826]: verbose: New Socket.io Connection to 192.168.1.6:3000 from 192.168.1.203 UA: Dart/3.5 (dart:io) Total Clients: 3 Feb 21 09:23:26 volumitest volumio[826]: info: CoreCommandRouter::volumioGetState Feb 21 09:23:26 volumitest volumio[826]: info: CorePlayQueue::getTrack 0 Feb 21 09:23:26 volumitest go-librespot[980]: time="2024-02-21T09:23:26+01:00" level=info msg="generated new device id: 9709c3a1524344de291831690b365af7a6b572e1" Feb 21 09:23:26 volumitest volumio[826]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Feb 21 09:23:26 volumitest volumio[826]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Feb 21 09:23:26 volumitest volumio[826]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 21 09:23:26 volumitest volumio[826]: Error: certificate is not yet valid Feb 21 09:23:26 volumitest volumio[826]: at TLSSocket.onConnectSecure (_tls_wrap.js:1497:34) Feb 21 09:23:26 volumitest volumio[826]: at TLSSocket.emit (events.js:315:20) Feb 21 09:23:26 volumitest volumio[826]: at TLSSocket._finishInit (_tls_wrap.js:932:8) Feb 21 09:23:26 volumitest volumio[826]: at TLSWrap.ssl.onhandshakedone (_tls_wrap.js:706:12) { Feb 21 09:23:26 volumitest volumio[826]: code: 'CERT_NOT_YET_VALID' Feb 21 09:23:26 volumitest volumio[826]: } Feb 21 09:23:26 volumitest volumio[826]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 21 09:23:27 volumitest go-librespot[980]: time="2024-02-21T09:23:27+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Feb 21 09:23:27 volumitest go-librespot[980]: time="2024-02-21T09:23:27+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Feb 21 09:23:27 volumitest go-librespot[980]: time="2024-02-21T09:23:27+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Feb 21 09:23:27 volumitest go-librespot[980]: time="2024-02-21T09:23:27+01:00" level=debug msg="zeroconf server listening on port 39917" Feb 21 09:23:27 volumitest sudo[1026]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-02-21 09:22 Feb 21 09:23:27 volumitest sudo[1026]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 21 09:23:27 volumitest systemd[1]: systemd-hostnamed.service: Succeeded. PRETTY_NAME="Raspbian GNU/Linux 10 (buster)" NAME="Raspbian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster 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="9552505bba4239c163ac9ee7b0b87a56e0dd0574" VOLUMIO_FE_VERSION="614d7b13ffdcb0cc5a6072e7d06f59d52e323e71" VOLUMIO_FE3_VERSION="570aaed971c1346d45d1172dc445b086b258c6d1" VOLUMIO_BE_VERSION="3d3fc502273a5c173ba19f72c1a952bdb2bdd3b0" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue 13 Feb 2024 06:28:23 PM CET" VOLUMIO_VERSION="3.616" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="b343c71baf05cbc21bf1a530c8e51fc1"