-- Logs begin at Thu 2019-02-14 05:12:00 EST, end at Sat 2024-10-19 15:44:10 EDT. -- Oct 19 15:43:28 up kernel: hub 1-0:1.0: 1 port detected Oct 19 15:43:28 up kernel: dwc_otg: FIQ enabled Oct 19 15:43:28 up kernel: dwc_otg: NAK holdoff enabled Oct 19 15:43:28 up kernel: dwc_otg: FIQ split-transaction FSM enabled Oct 19 15:43:28 up kernel: Module dwc_common_port init Oct 19 15:43:28 up kernel: usbcore: registered new interface driver usb-storage Oct 19 15:43:28 up kernel: mousedev: PS/2 mouse device common for all mice Oct 19 15:43:28 up kernel: sdhci: Secure Digital Host Controller Interface driver Oct 19 15:43:28 up kernel: sdhci: Copyright(c) Pierre Ossman Oct 19 15:43:28 up kernel: sdhci-pltfm: SDHCI platform and OF driver helper Oct 19 15:43:28 up kernel: ledtrig-cpu: registered to indicate activity on CPUs Oct 19 15:43:28 up kernel: hid: raw HID events driver (C) Jiri Kosina Oct 19 15:43:28 up kernel: usbcore: registered new interface driver usbhid Oct 19 15:43:28 up kernel: usbhid: USB HID core driver Oct 19 15:43:28 up kernel: Initializing XFRM netlink socket Oct 19 15:43:28 up kernel: NET: Registered PF_PACKET protocol family Oct 19 15:43:28 up kernel: Key type dns_resolver registered Oct 19 15:43:28 up kernel: Registering SWP/SWPB emulation handler Oct 19 15:43:28 up kernel: registered taskstats version 1 Oct 19 15:43:28 up kernel: Loading compiled-in X.509 certificates Oct 19 15:43:28 up kernel: Key type .fscrypt registered Oct 19 15:43:28 up kernel: Key type fscrypt-provisioning registered Oct 19 15:43:28 up kernel: uart-pl011 3f201000.serial: cts_event_workaround enabled Oct 19 15:43:28 up kernel: 3f201000.serial: ttyAMA1 at MMIO 0x3f201000 (irq = 114, base_baud = 0) is a PL011 rev2 Oct 19 15:43:28 up kernel: serial serial0: tty port ttyAMA1 registered Oct 19 15:43:28 up kernel: bcm2835-wdt bcm2835-wdt: Broadcom BCM2835 watchdog timer Oct 19 15:43:28 up kernel: bcm2835-power bcm2835-power: Broadcom BCM2835 power domains driver Oct 19 15:43:28 up kernel: mmc-bcm2835 3f300000.mmcnr: mmc_debug:0 mmc_debug2:0 Oct 19 15:43:28 up kernel: mmc-bcm2835 3f300000.mmcnr: DMA channel allocated Oct 19 15:43:28 up kernel: sdhost: log_buf @ a2cc0378 (f4107000) Oct 19 15:43:28 up kernel: mmc0: sdhost-bcm2835 loaded - DMA enabled (>1) Oct 19 15:43:28 up kernel: of_cfs_init Oct 19 15:43:28 up kernel: of_cfs_init: OK Oct 19 15:43:28 up kernel: Freeing unused kernel image (initmem) memory: 1024K Oct 19 15:43:28 up kernel: Indeed it is in host mode hprt0 = 00021501 Oct 19 15:43:28 up kernel: mmc0: host does not support reading read-only switch, assuming write-enable Oct 19 15:43:28 up kernel: mmc0: new high speed SDHC card at address e624 Oct 19 15:43:28 up kernel: mmcblk0: mmc0:e624 SC16G 14.8 GiB Oct 19 15:43:28 up kernel: mmcblk0: p1 p2 p3 Oct 19 15:43:28 up kernel: mmcblk0: mmc0:e624 SC16G 14.8 GiB (quirks 0x00004000) Oct 19 15:43:28 up kernel: mmc1: new high speed SDIO card at address 0001 Oct 19 15:43:28 up kernel: Run /init as init process Oct 19 15:43:28 up kernel: with arguments: Oct 19 15:43:28 up kernel: /init Oct 19 15:43:28 up kernel: splash Oct 19 15:43:28 up kernel: nodebug Oct 19 15:43:28 up kernel: with environment: Oct 19 15:43:28 up kernel: HOME=/ Oct 19 15:43:28 up kernel: TERM=linux Oct 19 15:43:28 up kernel: imgpart=UUID=0c3a77ec-ae84-4f1b-8028-c61cc251ffe5 Oct 19 15:43:28 up kernel: imgfile=/volumio_current.sqsh Oct 19 15:43:28 up kernel: bootpart=UUID=41CA-9A8B Oct 19 15:43:28 up kernel: datapart=UUID=0324d53a-d066-482b-b659-eb98af2b49e7 Oct 19 15:43:28 up kernel: uuidconfig=cmdline.txt Oct 19 15:43:28 up kernel: pcie_aspm=off Oct 19 15:43:28 up kernel: pci=pcie_bus_safe Oct 19 15:43:28 up kernel: bootdelay=7 Oct 19 15:43:28 up kernel: use_kmsg=no Oct 19 15:43:28 up kernel: usb 1-1: new high-speed USB device number 2 using dwc_otg Oct 19 15:43:28 up kernel: Indeed it is in host mode hprt0 = 00001101 Oct 19 15:43:28 up kernel: usb 1-1: New USB device found, idVendor=0424, idProduct=9514, bcdDevice= 2.00 Oct 19 15:43:28 up kernel: usb 1-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0 Oct 19 15:43:28 up kernel: hub 1-1:1.0: USB hub found Oct 19 15:43:28 up kernel: hub 1-1:1.0: 5 ports detected Oct 19 15:43:28 up kernel: usb 1-1.1: new high-speed USB device number 3 using dwc_otg Oct 19 15:43:28 up kernel: usb 1-1.1: New USB device found, idVendor=0424, idProduct=ec00, bcdDevice= 2.00 Oct 19 15:43:28 up kernel: usb 1-1.1: New USB device strings: Mfr=0, Product=0, SerialNumber=0 Oct 19 15:43:28 up kernel: smsc95xx v2.0.0 Oct 19 15:43:28 up kernel: SMSC LAN8700 usb-001:003:01: attached PHY driver (mii_bus:phy_addr=usb-001:003:01, irq=199) Oct 19 15:43:28 up kernel: smsc95xx 1-1.1:1.0 eth0: register 'smsc95xx' at usb-3f980000.usb-1.1, smsc95xx USB 2.0 Ethernet, b8:27:eb:31:38:01 Oct 19 15:43:28 up kernel: fuse: init (API version 7.37) Oct 19 15:43:28 up kernel: squashfs: version 4.0 (2009/01/31) Phillip Lougher Oct 19 15:43:28 up kernel: usbcore: registered new interface driver uas Oct 19 15:43:28 up kernel: FAT-fs (mmcblk0p1): Volume was not properly unmounted. Some data may be corrupt. Please run fsck. Oct 19 15:43:28 up kernel: EXT4-fs (mmcblk0p2): recovery complete Oct 19 15:43:28 up kernel: EXT4-fs (mmcblk0p2): mounted filesystem with ordered data mode. Quota mode: none. Oct 19 15:43:28 up kernel: loop0: detected capacity change from 0 to 983416 Oct 19 15:43:28 up kernel: EXT4-fs (mmcblk0p3): recovery complete Oct 19 15:43:28 up kernel: EXT4-fs (mmcblk0p3): mounted filesystem with ordered data mode. Quota mode: none. Oct 19 15:43:28 up systemd[1]: System time before build time, advancing clock. Oct 19 15:43:28 up kernel: NET: Registered PF_INET6 protocol family Oct 19 15:43:28 up kernel: Segment Routing with IPv6 Oct 19 15:43:28 up kernel: In-situ OAM (IOAM) with IPv6 Oct 19 15:43:28 up 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) Oct 19 15:43:28 up systemd[1]: Detected architecture arm. Oct 19 15:43:28 up systemd[1]: Set hostname to . Oct 19 15:43:28 up 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. Oct 19 15:43:28 up systemd[1]: Created slice User and Session Slice. Oct 19 15:43:28 up systemd[1]: Listening on udev Kernel Socket. Oct 19 15:43:28 up systemd[1]: Listening on RPCbind Server Activation Socket. Oct 19 15:43:28 up systemd[1]: Reached target Slices. Oct 19 15:43:28 up systemd[1]: Set up automount Arbitrary Executable File Formats File System Automount Point. Oct 19 15:43:28 up systemd[1]: Created slice system-getty.slice. Oct 19 15:43:28 up kernel: i2c_dev: i2c /dev entries driver Oct 19 15:43:28 up systemd-journald[325]: Journal started Oct 19 15:43:28 up systemd-journald[325]: Runtime journal (/run/log/journal/d5012141e8efab18115b4334669e938a) is 7.5M, max 30.0M, 22.5M free. Oct 19 15:43:28 up systemd-modules-load[319]: Inserted module 'i2c_dev' Oct 19 15:43:28 up systemd[1]: Started Load/Save Random Seed. Oct 19 15:43:28 up fake-hwclock[326]: Sat Oct 19 19:43:28 UTC 2024 Oct 19 15:43:28 up systemd[1]: Started Apply Kernel Variables. Oct 19 15:43:28 up systemd[1]: dynamicswap.service: Succeeded. Oct 19 15:43:28 up systemd[1]: Started Create System Users. Oct 19 15:43:28 up systemd[1]: Starting Create Static Device Nodes in /dev... Oct 19 15:43:28 up systemd[1]: Started udev Coldplug all Devices. Oct 19 15:43:28 up systemd[1]: Starting Helper to synchronize boot up for ifupdown... Oct 19 15:43:28 up systemd[1]: Started Helper to synchronize boot up for ifupdown. Oct 19 15:43:28 up systemd[1]: Started Create Static Device Nodes in /dev. Oct 19 15:43:28 up systemd[1]: Starting udev Kernel Device Manager... Oct 19 15:43:28 up systemd[1]: Reached target Local File Systems (Pre). Oct 19 15:43:28 up systemd[1]: Mounting /var/spool/cups... Oct 19 15:43:28 up systemd[1]: var-log.mount: Directory /var/log to mount over is not empty, mounting anyway. Oct 19 15:43:28 up systemd[1]: Mounting /var/log... Oct 19 15:43:28 up systemd[1]: tmp.mount: Directory /tmp to mount over is not empty, mounting anyway. Oct 19 15:43:28 up systemd[1]: Mounting /tmp... Oct 19 15:43:28 up systemd[1]: Mounted /var/spool/cups. Oct 19 15:43:28 up systemd[1]: Mounting /var/spool/cups/tmp... Oct 19 15:43:28 up systemd[1]: Mounted /var/log. Oct 19 15:43:28 up systemd[1]: Mounted /tmp. Oct 19 15:43:28 up systemd[1]: Mounted /var/spool/cups/tmp. Oct 19 15:43:28 up systemd[1]: Starting Flush Journal to Persistent Storage... Oct 19 15:43:28 up systemd-udevd[349]: Network interface NamePolicy= disabled on kernel command line, ignoring. Oct 19 15:43:28 up systemd[1]: Started udev Kernel Device Manager. Oct 19 15:43:28 up systemd-journald[325]: Runtime journal (/run/log/journal/d5012141e8efab18115b4334669e938a) is 7.5M, max 30.0M, 22.5M free. Oct 19 15:43:28 up systemd[1]: Starting Show Plymouth Boot Screen... Oct 19 15:43:28 up systemd[1]: Started Flush Journal to Persistent Storage. Oct 19 15:43:28 up systemd[1]: plymouth-start.service: Succeeded. Oct 19 15:43:28 up systemd[1]: Started Show Plymouth Boot Screen. Oct 19 15:43:28 up systemd[1]: Started Forward Password Requests to Plymouth Directory Watch. Oct 19 15:43:28 up systemd[1]: Condition check resulted in Dispatch Password Requests to Console Directory Watch being skipped. Oct 19 15:43:28 up systemd[1]: Reached target Paths. Oct 19 15:43:28 up systemd[1]: Reached target Local Encrypted Volumes. Oct 19 15:43:28 up kernel: vc_sm_cma: module is from the staging directory, the quality is unknown, you have been warned. Oct 19 15:43:28 up kernel: mc: Linux media interface: v0.10 Oct 19 15:43:28 up kernel: bcm2835_vc_sm_cma_probe: Videocore shared memory driver Oct 19 15:43:28 up kernel: [vc_sm_connected_init]: start Oct 19 15:43:28 up kernel: [vc_sm_connected_init]: installed successfully Oct 19 15:43:29 up kernel: rpi-gpiomem 3f200000.gpiomem: window base 0x3f200000 size 0x00001000 Oct 19 15:43:29 up kernel: rpi-gpiomem 3f200000.gpiomem: initialised 1 regions as /dev/gpiomem Oct 19 15:43:29 up kernel: videodev: Linux video capture interface: v2.00 Oct 19 15:43:29 up kernel: bcm2835_mmal_vchiq: module is from the staging directory, the quality is unknown, you have been warned. Oct 19 15:43:29 up kernel: bcm2835_mmal_vchiq: module is from the staging directory, the quality is unknown, you have been warned. Oct 19 15:43:29 up kernel: bcm2835_mmal_vchiq: module is from the staging directory, the quality is unknown, you have been warned. Oct 19 15:43:29 up kernel: bcm2835_isp: module is from the staging directory, the quality is unknown, you have been warned. Oct 19 15:43:29 up kernel: bcm2835-isp bcm2835-isp: Device node output[0] registered as /dev/video13 Oct 19 15:43:29 up kernel: bcm2835-isp bcm2835-isp: Device node capture[0] registered as /dev/video14 Oct 19 15:43:29 up kernel: bcm2835-isp bcm2835-isp: Device node capture[1] registered as /dev/video15 Oct 19 15:43:29 up kernel: bcm2835-isp bcm2835-isp: Device node stats[2] registered as /dev/video16 Oct 19 15:43:29 up kernel: bcm2835-isp bcm2835-isp: Register output node 0 with media controller Oct 19 15:43:29 up kernel: bcm2835-isp bcm2835-isp: Register capture node 1 with media controller Oct 19 15:43:29 up kernel: bcm2835-isp bcm2835-isp: Register capture node 2 with media controller Oct 19 15:43:29 up kernel: bcm2835-isp bcm2835-isp: Register capture node 3 with media controller Oct 19 15:43:29 up kernel: bcm2835-isp bcm2835-isp: Device node output[0] registered as /dev/video20 Oct 19 15:43:29 up kernel: bcm2835-isp bcm2835-isp: Device node capture[0] registered as /dev/video21 Oct 19 15:43:29 up kernel: bcm2835-isp bcm2835-isp: Device node capture[1] registered as /dev/video22 Oct 19 15:43:29 up kernel: bcm2835-isp bcm2835-isp: Device node stats[2] registered as /dev/video23 Oct 19 15:43:29 up kernel: bcm2835-isp bcm2835-isp: Register output node 0 with media controller Oct 19 15:43:29 up kernel: bcm2835-isp bcm2835-isp: Register capture node 1 with media controller Oct 19 15:43:29 up kernel: bcm2835-isp bcm2835-isp: Register capture node 2 with media controller Oct 19 15:43:29 up kernel: bcm2835-isp bcm2835-isp: Register capture node 3 with media controller Oct 19 15:43:29 up kernel: bcm2835-isp bcm2835-isp: Loaded V4L2 bcm2835-isp Oct 19 15:43:29 up kernel: bcm2835_v4l2: module is from the staging directory, the quality is unknown, you have been warned. Oct 19 15:43:29 up kernel: bcm2835_codec: module is from the staging directory, the quality is unknown, you have been warned. Oct 19 15:43:29 up kernel: bcm2835-codec bcm2835-codec: Device registered as /dev/video10 Oct 19 15:43:29 up kernel: bcm2835-codec bcm2835-codec: Loaded V4L2 decode Oct 19 15:43:29 up kernel: snd_bcm2835: module is from the staging directory, the quality is unknown, you have been warned. Oct 19 15:43:29 up kernel: snd_bcm2835: unknown parameter 'enable_compat_alsa' ignored Oct 19 15:43:29 up kernel: bcm2835-codec bcm2835-codec: Device registered as /dev/video11 Oct 19 15:43:29 up kernel: bcm2835-codec bcm2835-codec: Loaded V4L2 encode Oct 19 15:43:29 up kernel: bcm2835-codec bcm2835-codec: Device registered as /dev/video12 Oct 19 15:43:29 up kernel: bcm2835-codec bcm2835-codec: Loaded V4L2 isp Oct 19 15:43:29 up kernel: bcm2835-codec bcm2835-codec: Device registered as /dev/video18 Oct 19 15:43:29 up kernel: bcm2835-codec bcm2835-codec: Loaded V4L2 image_fx Oct 19 15:43:29 up kernel: bcm2835-codec bcm2835-codec: Device registered as /dev/video31 Oct 19 15:43:29 up kernel: bcm2835-codec bcm2835-codec: Loaded V4L2 encode_image Oct 19 15:43:29 up kernel: bcm2835_audio bcm2835_audio: card created with 4 channels Oct 19 15:43:29 up systemd[1]: Found device /dev/disk/by-uuid/41CA-9A8B. Oct 19 15:43:29 up kernel: bcm2835_audio bcm2835_audio: card created with 4 channels Oct 19 15:43:29 up systemd-udevd[368]: Using default interface naming scheme 'v240'. Oct 19 15:43:29 up kernel: Bluetooth: Core ver 2.22 Oct 19 15:43:29 up kernel: NET: Registered PF_BLUETOOTH protocol family Oct 19 15:43:29 up kernel: Bluetooth: HCI device and connection manager initialized Oct 19 15:43:29 up kernel: Bluetooth: HCI socket layer initialized Oct 19 15:43:29 up kernel: Bluetooth: L2CAP socket layer initialized Oct 19 15:43:29 up kernel: Bluetooth: SCO socket layer initialized Oct 19 15:43:30 up systemd-udevd[368]: link_config: autonegotiation is unset or enabled, the speed and duplex are not writable. Oct 19 15:43:30 up kernel: Bluetooth: HCI UART driver ver 2.3 Oct 19 15:43:30 up kernel: Bluetooth: HCI UART protocol H4 registered Oct 19 15:43:30 up kernel: Bluetooth: HCI UART protocol Three-wire (H5) registered Oct 19 15:43:30 up kernel: Bluetooth: HCI UART protocol Broadcom registered Oct 19 15:43:30 up kernel: hci_uart_bcm serial0-0: supply vbat not found, using dummy regulator Oct 19 15:43:30 up kernel: hci_uart_bcm serial0-0: supply vddio not found, using dummy regulator Oct 19 15:43:30 up systemd-udevd[360]: link_config: autonegotiation is unset or enabled, the speed and duplex are not writable. Oct 19 15:43:30 up kernel: uart-pl011 3f201000.serial: no DMA platform data Oct 19 15:43:30 up kernel: cfg80211: Loading compiled-in X.509 certificates for regulatory database Oct 19 15:43:30 up kernel: Bluetooth: hci0: BCM: chip id 94 Oct 19 15:43:30 up kernel: Bluetooth: hci0: BCM: features 0x2e Oct 19 15:43:30 up kernel: Bluetooth: hci0: BCM43430A1 Oct 19 15:43:30 up kernel: Bluetooth: hci0: BCM43430A1 (001.002.009) build 0000 Oct 19 15:43:30 up kernel: Bluetooth: hci0: BCM43430A1 'brcm/BCM43430A1.hcd' Patch Oct 19 15:43:30 up kernel: cfg80211: Loaded X.509 cert 'benh@debian.org: 577e021cb980e0e820821ba7b54b4961b8b4fadf' Oct 19 15:43:30 up kernel: cfg80211: Loaded X.509 cert 'romain.perier@gmail.com: 3abbc6ec146e09d1b6016ab9d6cf71dd233f0328' Oct 19 15:43:30 up kernel: cfg80211: Loaded X.509 cert 'sforshee: 00b28ddf47aef9cea7' Oct 19 15:43:31 up kernel: brcmfmac: F1 signature read @0x18000000=0x1541a9a6 Oct 19 15:43:31 up kernel: brcmfmac: brcmf_fw_alloc_request: using brcm/brcmfmac43430-sdio for chip BCM43430/1 Oct 19 15:43:31 up kernel: usbcore: registered new interface driver brcmfmac Oct 19 15:43:31 up kernel: wm8804 1-003b: revision E Oct 19 15:43:31 up kernel: brcmfmac: brcmf_c_preinit_dcmds: Firmware: BCM43430/1 wl0: Jul 19 2021 03:24:18 version 7.45.98 (TOB) (56df937 CY) FWID 01-8e14b897 Oct 19 15:43:31 up systemd-udevd[355]: Using default interface naming scheme 'v240'. Oct 19 15:43:31 up systemd-udevd[355]: link_config: autonegotiation is unset or enabled, the speed and duplex are not writable. Oct 19 15:43:31 up kernel: Bluetooth: hci0: BCM: features 0x2e Oct 19 15:43:31 up kernel: Bluetooth: hci0: BCM43438A1 37.4MHz Raspberry Pi 3-0141 Oct 19 15:43:31 up kernel: Bluetooth: hci0: BCM43430A1 (001.002.009) build 0508 Oct 19 15:43:31 up systemd[1]: Created slice system-bthelper.slice. Oct 19 15:43:31 up systemd[1]: Condition check resulted in Set Up Additional Binary Formats being skipped. Oct 19 15:43:31 up systemd[1]: Condition check resulted in Rebuild Hardware Database being skipped. Oct 19 15:43:31 up systemd[1]: Condition check resulted in Huge Pages File System being skipped. Oct 19 15:43:31 up systemd[1]: Starting Show Plymouth Boot Screen... Oct 19 15:43:31 up systemd[1]: Listening on Load/Save RF Kill Switch Status /dev/rfkill Watch. Oct 19 15:43:31 up systemd[1]: Starting File System Check on /dev/disk/by-uuid/41CA-9A8B... Oct 19 15:43:31 up systemd[1]: Found device SMSC9512/9514 Fast Ethernet Adapter. Oct 19 15:43:31 up systemd[1]: plymouth-start.service: Succeeded. Oct 19 15:43:31 up systemd[1]: Started Show Plymouth Boot Screen. Oct 19 15:43:32 up systemd[1]: Started File System Check Daemon to report status. Oct 19 15:43:32 up systemd[1]: Condition check resulted in Dispatch Password Requests to Console Directory Watch being skipped. Oct 19 15:43:32 up systemd[1]: Starting Load/Save RF Kill Switch Status... Oct 19 15:43:32 up systemd[1]: Started Load/Save RF Kill Switch Status. Oct 19 15:43:32 up systemd[1]: Found device /sys/subsystem/net/devices/wlan0. Oct 19 15:43:32 up systemd-fsck[523]: fsck.fat 4.1 (2017-01-24) Oct 19 15:43:32 up systemd-fsck[523]: 0x41: Dirty bit is set. Fs was not properly unmounted and some data may be corrupt. Oct 19 15:43:32 up systemd-fsck[523]: Automatically removing dirty bit. Oct 19 15:43:32 up systemd-fsck[523]: Performing changes. Oct 19 15:43:32 up systemd-fsck[523]: /dev/mmcblk0p1: 369 files, 134161/184582 clusters Oct 19 15:43:32 up systemd[1]: Started File System Check on /dev/disk/by-uuid/41CA-9A8B. Oct 19 15:43:32 up systemd[1]: Mounting /boot... Oct 19 15:43:32 up systemd[1]: Mounted /boot. Oct 19 15:43:32 up systemd[1]: Reached target Local File Systems. Oct 19 15:43:32 up systemd[1]: Starting Create Volatile Files and Directories... Oct 19 15:43:32 up systemd[1]: Starting Preprocess NFS configuration... Oct 19 15:43:32 up systemd[1]: Condition check resulted in Commit a transient machine-id on disk being skipped. Oct 19 15:43:32 up systemd[1]: Starting Tell Plymouth To Write Out Runtime Data... Oct 19 15:43:32 up systemd[1]: Starting Raise network interfaces... Oct 19 15:43:32 up systemd[1]: Started ifup for wlan0. Oct 19 15:43:32 up systemd[1]: Started ifup for eth0. Oct 19 15:43:32 up systemd[1]: nfs-config.service: Succeeded. Oct 19 15:43:32 up systemd[1]: Started Preprocess NFS configuration. Oct 19 15:43:32 up systemd[1]: Condition check resulted in RPC security service for NFS client and server being skipped. Oct 19 15:43:32 up systemd[1]: Condition check resulted in RPC security service for NFS server being skipped. Oct 19 15:43:32 up systemd[1]: Reached target NFS client services. Oct 19 15:43:32 up systemd[1]: Received SIGRTMIN+20 from PID 211 (plymouthd). Oct 19 15:43:32 up systemd[1]: plymouth-read-write.service: Succeeded. Oct 19 15:43:32 up systemd[1]: Started Tell Plymouth To Write Out Runtime Data. Oct 19 15:43:32 up systemd[1]: Started Create Volatile Files and Directories. Oct 19 15:43:32 up systemd[1]: Starting RPC bind portmap service... Oct 19 15:43:32 up systemd[1]: Starting Update UTMP about System Boot/Shutdown... Oct 19 15:43:32 up systemd[1]: Condition check resulted in Network Time Synchronization being skipped. Oct 19 15:43:32 up systemd[1]: Started Entropy daemon using the HAVEGE algorithm. Oct 19 15:43:32 up systemd[1]: Started Update UTMP about System Boot/Shutdown. Oct 19 15:43:32 up systemd[1]: Reached target System Initialization. Oct 19 15:43:32 up kernel: brcmfmac: brcmf_cfg80211_set_power_mgmt: power save disabled Oct 19 15:43:32 up systemd[1]: Listening on triggerhappy.socket. Oct 19 15:43:32 up systemd[1]: Listening on D-Bus System Message Bus Socket. Oct 19 15:43:32 up systemd[1]: apt-daily.timer: Not using persistent file timestamp Tue 2024-10-22 23:15:38 EDT as it is in the future. Oct 19 15:43:32 up systemd[1]: Started Daily apt download activities. Oct 19 15:43:32 up systemd[1]: apt-daily-upgrade.timer: Not using persistent file timestamp Tue 2024-10-22 06:38:43 EDT as it is in the future. Oct 19 15:43:32 up systemd[1]: Started Daily apt upgrade and clean activities. Oct 19 15:43:33 up systemd[1]: Listening on Avahi mDNS/DNS-SD Stack Activation Socket. Oct 19 15:43:33 up systemd[1]: Reached target Sockets. Oct 19 15:43:33 up systemd[1]: Reached target Basic System. Oct 19 15:43:33 up kernel: 8021q: 802.1Q VLAN Support v1.8 Oct 19 15:43:33 up systemd[1]: Started Manage Sound Card State (restore and store). Oct 19 15:43:33 up systemd[1]: Started UPnP Renderer front-end to MPD. Oct 19 15:43:33 up systemd[1]: Condition check resulted in getty on tty2-tty6 if dbus and logind are not available being skipped. Oct 19 15:43:33 up alsactl[617]: alsactl 1.1.8 daemon started Oct 19 15:43:33 up systemd[1]: Started volumio-remote-updater.service. Oct 19 15:43:33 up systemd[1]: Starting Wireless Services... Oct 19 15:43:33 up systemd[1]: Started Volumio Log Rotation Service. Oct 19 15:43:33 up systemd[1]: Condition check resulted in Copy user wpa_supplicant.conf being skipped. Oct 19 15:43:33 up systemd[1]: Starting dhcpcd on all interfaces... Oct 19 15:43:33 up systemd[1]: Started D-Bus System Message Bus. Oct 19 15:43:33 up systemd[1]: Starting WPA supplicant... Oct 19 15:43:33 up systemd[1]: Starting triggerhappy global hotkey daemon... Oct 19 15:43:33 up systemd[1]: Starting Save/Restore Sound Card State... Oct 19 15:43:33 up systemd[1]: Started Volumio Iptables Module. Oct 19 15:43:33 up systemd[1]: Starting Avahi mDNS/DNS-SD Stack... Oct 19 15:43:33 up dhcpcd[639]: Not running dhcpcd because /etc/network/interfaces Oct 19 15:43:33 up dhcpcd[639]: defines some interfaces that will use a Oct 19 15:43:33 up dhcpcd[639]: DHCP client or static address Oct 19 15:43:33 up systemd[1]: Condition check resulted in Volumio SSH enabler being skipped. Oct 19 15:43:33 up systemd[1]: Starting Configure Bluetooth Modems connected by UART... Oct 19 15:43:33 up systemd[1]: Starting Login Service... Oct 19 15:43:33 up systemd[1]: Started Daily Cleanup of Temporary Directories. Oct 19 15:43:33 up systemd[1]: Reached target Timers. Oct 19 15:43:33 up systemd[1]: Started RPC bind portmap service. Oct 19 15:43:33 up systemd[1]: dhcpcd.service: Control process exited, code=exited, status=6/NOTCONFIGURED Oct 19 15:43:33 up systemd[1]: dhcpcd.service: Failed with result 'exit-code'. Oct 19 15:43:33 up systemd[1]: Failed to start dhcpcd on all interfaces. Oct 19 15:43:33 up thd[643]: Unable to parse trigger line: Oct 19 15:43:33 up thd[643]: Unable to parse trigger line: KEY_MIN_INTERESTING 1 /usr/local/bin/volumio volume toggle Oct 19 15:43:33 up thd[643]: Unable to parse trigger line: Oct 19 15:43:33 up thd[643]: Unable to parse trigger line: Oct 19 15:43:33 up thd[643]: Found socket passed from systemd Oct 19 15:43:33 up sh[538]: wlan0=wlan0 Oct 19 15:43:33 up systemd[1]: Started triggerhappy global hotkey daemon. Oct 19 15:43:33 up systemd[1]: Started Save/Restore Sound Card State. Oct 19 15:43:33 up systemd[1]: Reached target Sound Card. Oct 19 15:43:33 up systemd[1]: Reached target Remote File Systems (Pre). Oct 19 15:43:33 up systemd[1]: Reached target Remote File Systems. Oct 19 15:43:33 up systemd[1]: Starting LSB: Load kernel modules needed to enable cpufreq scaling... Oct 19 15:43:33 up systemd[1]: Reached target RPC Port Mapper. Oct 19 15:43:33 up systemd-logind[651]: New seat seat0. Oct 19 15:43:33 up sh[540]: eth0: waiting for carrier Oct 19 15:43:33 up dhcpcd[584]: eth0: waiting for carrier Oct 19 15:43:33 up kernel: smsc95xx 1-1.1:1.0 eth0: hardware isn't capable of remote wakeup Oct 19 15:43:33 up kernel: smsc95xx 1-1.1:1.0 eth0: Link is Up - 100Mbps/Full - flow control off Oct 19 15:43:33 up sh[540]: eth0: carrier acquired Oct 19 15:43:33 up dhcpcd[584]: eth0: carrier acquired Oct 19 15:43:33 up kernel: hwmon hwmon1: Undervoltage detected! Oct 19 15:43:33 up avahi-daemon[649]: Found user 'avahi' (UID 110) and group 'avahi' (GID 113). Oct 19 15:43:33 up avahi-daemon[649]: Successfully dropped root privileges. Oct 19 15:43:33 up avahi-daemon[649]: avahi-daemon 0.7 starting up. Oct 19 15:43:33 up sh[540]: DUID 00:01:00:01:2e:31:51:db:b8:27:eb:31:38:01 Oct 19 15:43:33 up sh[540]: eth0: IAID eb:31:38:01 Oct 19 15:43:33 up dhcpcd[584]: DUID 00:01:00:01:2e:31:51:db:b8:27:eb:31:38:01 Oct 19 15:43:33 up sh[540]: eth0: adding address fe80::135:5ef8:493a:b7d5 Oct 19 15:43:33 up sh[540]: ipv6_addaddr1: Permission denied Oct 19 15:43:33 up dhcpcd[584]: eth0: IAID eb:31:38:01 Oct 19 15:43:33 up dhcpcd[584]: eth0: adding address fe80::135:5ef8:493a:b7d5 Oct 19 15:43:33 up dhcpcd[584]: ipv6_addaddr1: Permission denied Oct 19 15:43:34 up sh[540]: eth0: soliciting an IPv6 router Oct 19 15:43:34 up dhcpcd[584]: eth0: soliciting an IPv6 router Oct 19 15:43:34 up dbus-daemon[640]: [system] Successfully activated service 'org.freedesktop.systemd1' Oct 19 15:43:34 up avahi-daemon[649]: Successfully called chroot(). Oct 19 15:43:34 up avahi-daemon[649]: Successfully dropped remaining capabilities. Oct 19 15:43:34 up systemd[1]: Started Login Service. Oct 19 15:43:34 up systemd[1]: hciuart.service: Succeeded. Oct 19 15:43:34 up systemd[1]: Started Configure Bluetooth Modems connected by UART. Oct 19 15:43:34 up wpa_supplicant[642]: Successfully initialized wpa_supplicant Oct 19 15:43:34 up avahi-daemon[649]: Loading service file /services/volumio.service. Oct 19 15:43:34 up avahi-daemon[649]: Network interface enumeration completed. Oct 19 15:43:34 up avahi-daemon[649]: Server startup complete. Host name is up.local. Local service cookie is 646283819. Oct 19 15:43:34 up avahi-daemon[649]: Service "up" (/services/volumio.service) successfully established. Oct 19 15:43:34 up systemd[1]: Started Raise network interfaces. Oct 19 15:43:34 up systemd[1]: Started Avahi mDNS/DNS-SD Stack. Oct 19 15:43:34 up systemd[1]: Started WPA supplicant. Oct 19 15:43:34 up systemd[1]: Reached target Network. Oct 19 15:43:34 up systemd[1]: Starting Permit User Sessions... Oct 19 15:43:34 up systemd[1]: Starting Network Time Service... Oct 19 15:43:34 up sh[540]: eth0: rebinding lease of 192.168.0.168 Oct 19 15:43:34 up dhcpcd[584]: eth0: rebinding lease of 192.168.0.168 Oct 19 15:43:34 up systemd[1]: Condition check resulted in fast remote file copy program daemon being skipped. Oct 19 15:43:34 up systemd[1]: Reached target Network is Online. Oct 19 15:43:34 up systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Oct 19 15:43:34 up systemd[1]: Starting LSB: Brings up/down network automatically... Oct 19 15:43:34 up systemd[1]: Starting Samba NMB Daemon... Oct 19 15:43:34 up systemd[1]: Starting /etc/rc.local Compatibility... Oct 19 15:43:34 up systemd[1]: Starting Raspberry Pi bluetooth helper... Oct 19 15:43:34 up dhcpcd[584]: eth0: probing address 192.168.0.168/24 Oct 19 15:43:34 up sh[540]: eth0: probing address 192.168.0.168/24 Oct 19 15:43:35 up volumio-remote-updater[629]: Error: No active session Oct 19 15:43:35 up volumio-remote-updater[629]: [2024-10-19 15:43:35] [info] asio async_connect error: system:111 (Connection refused) Oct 19 15:43:35 up volumio-remote-updater[629]: [2024-10-19 15:43:35] [info] Error getting remote endpoint: system:107 (Transport endpoint is not connected) Oct 19 15:43:35 up volumio-remote-updater[629]: [2024-10-19 15:43:35] [error] handle_connect error: Underlying Transport Error Oct 19 15:43:35 up systemd[1]: Started /etc/rc.local Compatibility. Oct 19 15:43:35 up systemd[1]: Started Permit User Sessions. Oct 19 15:43:35 up systemd[1]: Starting Hold until boot process finishes up... Oct 19 15:43:35 up systemd[1]: Starting Terminate Plymouth Boot Screen... Oct 19 15:43:35 up volumio[628]: Could not open config: /tmp/upmpdcli.conf Oct 19 15:43:35 up systemd[1]: iptables.service: Succeeded. Oct 19 15:43:35 up systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Oct 19 15:43:35 up systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Oct 19 15:43:35 up bthelper[738]: Raspberry Pi BDADDR already set Oct 19 15:43:35 up systemd[1]: Received SIGRTMIN+21 from PID 211 (plymouthd). Oct 19 15:43:35 up systemd[1]: Started Raspberry Pi bluetooth helper. Oct 19 15:43:35 up ntpd[730]: ntpd 4.2.8p12@1.3728-o (1): Starting Oct 19 15:43:35 up ntpd[730]: Command line: /usr/sbin/ntpd -p /var/run/ntpd.pid -g -u 103:103 Oct 19 15:43:35 up systemd[1]: Starting Bluetooth service... Oct 19 15:43:35 up systemd[1]: Started Network Time Service. Oct 19 15:43:35 up systemd[1]: Received SIGRTMIN+21 from PID 211 (plymouthd). Oct 19 15:43:35 up systemd[1]: plymouth-quit-wait.service: Succeeded. Oct 19 15:43:35 up systemd[1]: Started Hold until boot process finishes up. Oct 19 15:43:35 up systemd[1]: plymouth-quit.service: Succeeded. Oct 19 15:43:35 up systemd[1]: Started Terminate Plymouth Boot Screen. Oct 19 15:43:35 up systemd[1]: Started Getty on tty1. Oct 19 15:43:35 up systemd[1]: Reached target Login Prompts. Oct 19 15:43:35 up ifplugd(eth0)[794]: ifplugd 0.28 initializing. Oct 19 15:43:35 up ifplugd(eth0)[794]: Using interface eth0/B8:27:EB:31:38:01 with driver (version: 6.1.69-v7+) Oct 19 15:43:35 up ntpd[773]: proto: precision = 1.458 usec (-19) Oct 19 15:43:35 up ifplugd(eth0)[794]: Using detection mode: SIOCETHTOOL Oct 19 15:43:35 up ifplugd(eth0)[794]: Initialization complete, link beat detected. Oct 19 15:43:35 up ntpd[773]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): good hash signature Oct 19 15:43:35 up ntpd[773]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): loaded, expire=2024-12-28T00:00:00Z last=2017-01-01T00:00:00Z ofs=37 Oct 19 15:43:35 up ntpd[773]: Listen and drop on 0 v6wildcard [::]:123 Oct 19 15:43:35 up ntpd[773]: Listen and drop on 1 v4wildcard 0.0.0.0:123 Oct 19 15:43:35 up ntpd[773]: Listen normally on 2 lo 127.0.0.1:123 Oct 19 15:43:35 up ntpd[773]: Listening on routing socket on fd #19 for interface updates Oct 19 15:43:35 up ntpd[773]: kernel reports TIME_ERROR: 0x41: Clock Unsynchronized Oct 19 15:43:35 up ntpd[773]: kernel reports TIME_ERROR: 0x41: Clock Unsynchronized Oct 19 15:43:35 up ifplugd(eth0)[794]: Executing '/etc/ifplugd/ifplugd.action eth0 up'. Oct 19 15:43:35 up loadcpufreq[694]: Loading cpufreq kernel modules...done (none). Oct 19 15:43:35 up systemd[1]: Started LSB: Load kernel modules needed to enable cpufreq scaling. Oct 19 15:43:35 up systemd[1]: Starting LSB: set CPUFreq kernel parameters... Oct 19 15:43:35 up bluetoothd[769]: Bluetooth daemon 5.50 Oct 19 15:43:35 up ifplugd(eth0)[794]: client: ifup: waiting for lock on /run/network/ifstate.eth0 Oct 19 15:43:35 up bluetoothd[769]: Unknown key AutoConnectTimeout for group General in /etc/bluetooth/main.conf Oct 19 15:43:35 up systemd[1]: Started Bluetooth service. Oct 19 15:43:35 up systemd[1]: Reached target Bluetooth. Oct 19 15:43:35 up bluetoothd[769]: Starting SDP server Oct 19 15:43:35 up bluetoothd[769]: Excluding (cli) sap Oct 19 15:43:36 up kernel: Bluetooth: BNEP (Ethernet Emulation) ver 1.3 Oct 19 15:43:36 up kernel: Bluetooth: BNEP filters: protocol multicast Oct 19 15:43:36 up kernel: Bluetooth: BNEP socket layer initialized Oct 19 15:43:36 up bluetoothd[769]: Bluetooth management interface 1.22 initialized Oct 19 15:43:36 up dbus-daemon[640]: [system] Activating via systemd: service name='org.freedesktop.hostname1' unit='dbus-org.freedesktop.hostname1.service' requested by ':1.5' (uid=0 pid=769 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap ") Oct 19 15:43:36 up kernel: Bluetooth: MGMT ver 1.22 Oct 19 15:43:36 up cpufrequtils[804]: CPUFreq Utilities: Setting ondemand CPUFreq governor...CPU0...CPU1...CPU2...CPU3...done. Oct 19 15:43:36 up bluetoothd[769]: Failed to set privacy: Rejected (0x0b) Oct 19 15:43:36 up haveged[593]: haveged: ver: 1.9.1; arch: generic; vend: ; build: (gcc 8.2.0 CTV); collect: 128K Oct 19 15:43:36 up haveged[593]: haveged: cpu: (VC); data: 16K (D); inst: 16K (D); idx: 11/40; sz: 14768/63488 Oct 19 15:43:36 up haveged[593]: haveged: tot tests(BA8): A:1/1 B:1/1 continuous tests(B): last entropy estimate 8.00074 Oct 19 15:43:36 up haveged[593]: haveged: fills: 0, generated: 0 Oct 19 15:43:36 up systemd[1]: Started LSB: set CPUFreq kernel parameters. Oct 19 15:43:36 up systemd[1]: Starting Hostname Service... Oct 19 15:43:36 up ntpd[773]: error resolving pool 0.debian.pool.ntp.org: System error (-11) Oct 19 15:43:36 up dbus-daemon[640]: [system] Successfully activated service 'org.freedesktop.hostname1' Oct 19 15:43:36 up systemd[1]: Started Hostname Service. Oct 19 15:43:36 up nmbd[742]: [2024/10/19 15:43:36.799856, 0] ../source3/nmbd/asyncdns.c:158(start_async_dns) Oct 19 15:43:36 up nmbd[742]: started asyncdns process 827 Oct 19 15:43:36 up nmbd[742]: [2024/10/19 15:43:36.803252, 0] ../lib/util/become_daemon.c:149(daemon_status) Oct 19 15:43:36 up nmbd[742]: daemon_status: STATUS=daemon 'nmbd' : No local IPv4 non-loopback interfaces available, waiting for interface ... Oct 19 15:43:36 up nmbd[742]: [2024/10/19 15:43:36.803484, 0] ../source3/nmbd/nmbd_subnetdb.c:254(create_subnets) Oct 19 15:43:36 up nmbd[742]: NOTE: NetBIOS name resolution is not supported for Internet Protocol Version 6 (IPv6). Oct 19 15:43:37 up systemd[1]: systemd-rfkill.service: Succeeded. Oct 19 15:43:37 up wireless.js[636]: Cleaning previous... Oct 19 15:43:37 up sudo[835]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ip addr flush dev wlan0 Oct 19 15:43:37 up sudo[835]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 19 15:43:37 up sudo[835]: pam_unix(sudo:session): session closed for user root Oct 19 15:43:37 up sudo[837]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 down Oct 19 15:43:37 up sudo[837]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 19 15:43:37 up ntpd[773]: error resolving pool 1.debian.pool.ntp.org: System error (-11) Oct 19 15:43:38 up sudo[837]: pam_unix(sudo:session): session closed for user root Oct 19 15:43:38 up wireless.js[636]: Stopped aP Oct 19 15:43:38 up sudo[844]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 up Oct 19 15:43:38 up sudo[844]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 19 15:43:38 up kernel: brcmfmac: brcmf_cfg80211_set_power_mgmt: power save disabled Oct 19 15:43:38 up sudo[844]: pam_unix(sudo:session): session closed for user root Oct 19 15:43:38 up sudo[846]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iw reg get Oct 19 15:43:38 up sudo[846]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 19 15:43:38 up sudo[846]: pam_unix(sudo:session): session closed for user root Oct 19 15:43:38 up sudo[853]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 up Oct 19 15:43:38 up sudo[853]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 19 15:43:38 up sudo[853]: pam_unix(sudo:session): session closed for user root Oct 19 15:43:38 up sudo[855]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iw wlan0 scan Oct 19 15:43:38 up sudo[855]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 19 15:43:38 up ntpd[773]: error resolving pool 2.debian.pool.ntp.org: System error (-11) Oct 19 15:43:38 up sudo[855]: pam_unix(sudo:session): session closed for user root Oct 19 15:43:38 up wireless.js[636]: SETTING APPROPRIATE REG DOMAIN: US Oct 19 15:43:38 up sudo[860]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 up Oct 19 15:43:38 up sudo[860]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 19 15:43:38 up sudo[860]: pam_unix(sudo:session): session closed for user root Oct 19 15:43:38 up sudo[862]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iw reg set US Oct 19 15:43:38 up sudo[862]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 19 15:43:38 up sudo[862]: pam_unix(sudo:session): session closed for user root Oct 19 15:43:38 up wireless.js[636]: SUCCESSFULLY SET NEW REGDOMAIN: US Oct 19 15:43:38 up sudo[869]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ip addr flush dev wlan0 Oct 19 15:43:38 up sudo[869]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 19 15:43:38 up sudo[869]: pam_unix(sudo:session): session closed for user root Oct 19 15:43:39 up sudo[871]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 down Oct 19 15:43:39 up sudo[871]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 19 15:43:39 up sh[540]: eth0: leased 192.168.0.168 for infinity Oct 19 15:43:39 up dhcpcd[584]: eth0: leased 192.168.0.168 for infinity Oct 19 15:43:39 up ntpd[773]: error resolving pool 3.debian.pool.ntp.org: System error (-11) Oct 19 15:43:39 up sh[540]: eth0: adding route to 192.168.0.0/24 Oct 19 15:43:39 up sh[540]: eth0: adding default route via 192.168.0.1 Oct 19 15:43:39 up dhcpcd[584]: eth0: adding route to 192.168.0.0/24 Oct 19 15:43:39 up dhcpcd[584]: eth0: adding default route via 192.168.0.1 Oct 19 15:43:39 up avahi-daemon[649]: Joining mDNS multicast group on interface eth0.IPv4 with address 192.168.0.168. Oct 19 15:43:39 up avahi-daemon[649]: New relevant interface eth0.IPv4 for mDNS. Oct 19 15:43:39 up avahi-daemon[649]: Registering new address record for 192.168.0.168 on eth0.IPv4. Oct 19 15:43:39 up sudo[871]: pam_unix(sudo:session): session closed for user root Oct 19 15:43:39 up avahi-daemon[649]: Joining mDNS multicast group on interface wlan0.IPv4 with address 192.168.211.1. Oct 19 15:43:39 up avahi-daemon[649]: New relevant interface wlan0.IPv4 for mDNS. Oct 19 15:43:39 up avahi-daemon[649]: Registering new address record for 192.168.211.1 on wlan0.IPv4. Oct 19 15:43:39 up kernel: brcmfmac: brcmf_cfg80211_set_power_mgmt: power save disabled Oct 19 15:43:39 up sh[540]: forked to background, child pid 898 Oct 19 15:43:39 up dhcpcd[584]: forked to background, child pid 898 Oct 19 15:43:39 up systemd[1]: Starting Advanced IEEE 802.11 AP and IEEE 802.1X/WPA/WPA2/EAP Authenticator... Oct 19 15:43:39 up systemd[1]: Starting dnsmasq - A lightweight DHCP and caching DNS server... Oct 19 15:43:39 up dnsmasq[901]: dnsmasq: syntax check OK. Oct 19 15:43:39 up hostapd[897]: Configuration file: /etc/hostapd/hostapd.conf Oct 19 15:43:39 up hostapd[897]: wlan0: Could not connect to kernel driver Oct 19 15:43:39 up hostapd[897]: Using interface wlan0 with hwaddr b8:27:eb:64:6d:54 and ssid "Volumio-1F31B" Oct 19 15:43:39 up ifplugd(eth0)[794]: client: ifup: interface eth0 already configured Oct 19 15:43:39 up sh[540]: eth0=eth0 Oct 19 15:43:39 up dnsmasq[930]: started, version 2.80 cachesize 150 Oct 19 15:43:39 up dnsmasq[930]: compile time options: IPv6 GNU-getopt DBus i18n IDN DHCP DHCPv6 no-Lua TFTP conntrack ipset auth DNSSEC loop-detect inotify dumpfile Oct 19 15:43:39 up dnsmasq-dhcp[930]: DHCP, IP range 192.168.211.100 -- 192.168.211.200, lease time 1d Oct 19 15:43:39 up dnsmasq[930]: reading /etc/resolv.conf Oct 19 15:43:39 up dnsmasq[930]: using nameserver 192.168.0.1#53 Oct 19 15:43:39 up dnsmasq[930]: using nameserver 208.67.222.222#53 Oct 19 15:43:39 up dnsmasq[930]: using nameserver 208.67.220.220#53 Oct 19 15:43:39 up dnsmasq[930]: read /etc/hosts - 1 addresses Oct 19 15:43:39 up hostapd[897]: wlan0: interface state UNINITIALIZED->ENABLED Oct 19 15:43:39 up hostapd[897]: wlan0: AP-ENABLED Oct 19 15:43:39 up systemd[1]: Started Advanced IEEE 802.11 AP and IEEE 802.1X/WPA/WPA2/EAP Authenticator. Oct 19 15:43:39 up ifplugd(eth0)[794]: Program executed successfully. Oct 19 15:43:40 up ifplugd[732]: Network Interface Plugging Daemon...start eth0...done. Oct 19 15:43:40 up systemd[1]: Started LSB: Brings up/down network automatically. Oct 19 15:43:40 up volumio-remote-updater[629]: [2024-10-19 15:43:40] [info] asio async_connect error: system:111 (Connection refused) Oct 19 15:43:40 up volumio-remote-updater[629]: [2024-10-19 15:43:40] [info] Error getting remote endpoint: system:107 (Transport endpoint is not connected) Oct 19 15:43:40 up volumio-remote-updater[629]: [2024-10-19 15:43:40] [error] handle_connect error: Underlying Transport Error Oct 19 15:43:40 up iwconfig[936]: Error for wireless request "Set Power Management" (8B2C) : Oct 19 15:43:40 up iwconfig[936]: SET failed on device wlan0 ; Invalid argument. Oct 19 15:43:40 up systemd[1]: wireless.service: Succeeded. Oct 19 15:43:40 up systemd[1]: Started Wireless Services. Oct 19 15:43:40 up systemd[1]: Started Volumio Backend Module. Oct 19 15:43:40 up systemd[1]: Started Volumio Cpu Tweaker. Oct 19 15:43:40 up systemd[1]: Started dnsmasq - A lightweight DHCP and caching DNS server. Oct 19 15:43:40 up systemd[1]: Reached target Host and Network Name Lookups. Oct 19 15:43:40 up volumio-cpu-tweak[940]: Setting RT Priority for mpd Oct 19 15:43:40 up volumio-cpu-tweak[940]: pid 35's current scheduling policy: SCHED_OTHER Oct 19 15:43:40 up volumio-cpu-tweak[940]: pid 35's current scheduling priority: 0 Oct 19 15:43:40 up volumio-cpu-tweak[940]: Setting MPD Affinity Oct 19 15:43:40 up volumio-cpu-tweak[940]: pid 3's current affinity mask: f Oct 19 15:43:40 up volumio-cpu-tweak[940]: /bin/volumio_cpu_tweak: line 27: warning: command substitution: ignored null byte in input Oct 19 15:43:40 up volumio-cpu-tweak[940]: VOLUMIO CPU TWEAK: Setting CPU Governor: performance Oct 19 15:43:40 up systemd[1]: volumio_cpu_tweak.service: Succeeded. Oct 19 15:43:40 up bthelper[738]: Changing power off succeeded Oct 19 15:43:40 up bthelper[738]: [CHG] Controller B8:27:EB:9B:92:AB Powered: no Oct 19 15:43:40 up bthelper[738]: [CHG] Controller B8:27:EB:9B:92:AB Discovering: no Oct 19 15:43:40 up bthelper[738]: [CHG] Controller B8:27:EB:9B:92:AB Class: 0x00000000 Oct 19 15:43:40 up bthelper[738]: [CHG] Controller B8:27:EB:9B:92:AB Class: 0x0000041c Oct 19 15:43:40 up bthelper[738]: Changing power on succeeded Oct 19 15:43:40 up bthelper[738]: [CHG] Controller B8:27:EB:9B:92:AB Powered: yes Oct 19 15:43:41 up ntpd[773]: Listen normally on 3 eth0 192.168.0.168:123 Oct 19 15:43:41 up ntpd[773]: Listen normally on 4 wlan0 192.168.211.1:123 Oct 19 15:43:41 up ntpd[773]: new interface(s) found: waking up resolver Oct 19 15:43:41 up systemd[1]: Started Samba NMB Daemon. Oct 19 15:43:41 up nmbd[742]: [2024/10/19 15:43:41.817815, 0] ../lib/util/become_daemon.c:138(daemon_ready) Oct 19 15:43:41 up nmbd[742]: daemon_ready: STATUS=daemon 'nmbd' finished starting up and ready to serve connections Oct 19 15:43:41 up systemd[1]: Starting Samba Winbind Daemon... Oct 19 15:43:42 up winbindd[963]: [2024/10/19 15:43:42.550892, 0] ../source3/winbindd/winbindd_cache.c:3160(initialize_winbindd_cache) Oct 19 15:43:42 up winbindd[963]: initialize_winbindd_cache: clearing cache and re-creating with version number 2 Oct 19 15:43:42 up winbindd[963]: [2024/10/19 15:43:42.600747, 0] ../lib/util/become_daemon.c:138(daemon_ready) Oct 19 15:43:42 up systemd[1]: Started Samba Winbind Daemon. Oct 19 15:43:42 up winbindd[963]: daemon_ready: STATUS=daemon 'winbindd' finished starting up and ready to serve connections Oct 19 15:43:42 up systemd[1]: Starting Samba SMB Daemon... Oct 19 15:43:43 up winbindd[963]: [2024/10/19 15:43:43.398676, 0] ../source3/winbindd/wb_lookupsids.c:659(wb_lookupsids_recv) Oct 19 15:43:43 up winbindd[963]: res_names->count = 3, expected 4 Oct 19 15:43:43 up smbd[968]: [2024/10/19 15:43:43.452080, 0] ../lib/util/become_daemon.c:138(daemon_ready) Oct 19 15:43:43 up smbd[968]: daemon_ready: STATUS=daemon 'smbd' finished starting up and ready to serve connections Oct 19 15:43:43 up systemd[1]: Started Samba SMB Daemon. Oct 19 15:43:43 up systemd[1]: Reached target Multi-User System. Oct 19 15:43:43 up systemd[1]: Reached target Graphical Interface. Oct 19 15:43:43 up systemd[1]: Starting Update UTMP about System Runlevel Changes... Oct 19 15:43:43 up systemd[1]: systemd-update-utmp-runlevel.service: Succeeded. Oct 19 15:43:43 up systemd[1]: Started Update UTMP about System Runlevel Changes. Oct 19 15:43:43 up systemd[1]: Startup finished in 15.571s (kernel) + 18.519s (userspace) = 34.090s. Oct 19 15:43:45 up volumio[939]: info: ------------------------------------------- Oct 19 15:43:45 up volumio[939]: info: ----- Volumio3 ---- Oct 19 15:43:45 up volumio[939]: info: ------------------------------------------- Oct 19 15:43:45 up volumio[939]: info: ----- System startup ---- Oct 19 15:43:45 up volumio[939]: info: ------------------------------------------- Oct 19 15:43:47 up volumio[939]: info: MYVOLUMIO Environment detected Oct 19 15:43:47 up volumio-remote-updater[629]: [2024-10-19 15:43:47] [connect] Successful connection Oct 19 15:43:47 up volumio[939]: info: Plugin folders cleanup Oct 19 15:43:47 up volumio[939]: info: Scanning into folder /volumio/app/plugins/ Oct 19 15:43:47 up volumio[939]: info: Scanning category audio_interface Oct 19 15:43:47 up volumio[939]: info: Scanning category miscellanea Oct 19 15:43:47 up volumio[939]: info: Scanning category music_service Oct 19 15:43:47 up volumio[939]: info: Scanning category plugins.json Oct 19 15:43:47 up volumio[939]: info: Scanning category system_controller Oct 19 15:43:47 up volumio[939]: info: Scanning category user_interface Oct 19 15:43:47 up volumio[939]: info: Scanning into folder /data/plugins/ Oct 19 15:43:47 up volumio[939]: info: Scanning category music_service Oct 19 15:43:47 up volumio[939]: info: Plugin folders cleanup completed Oct 19 15:43:47 up volumio[939]: info: ------------------------------------------- Oct 19 15:43:47 up volumio[939]: info: ----- Core plugins startup ---- Oct 19 15:43:47 up volumio[939]: info: ------------------------------------------- Oct 19 15:43:47 up volumio[939]: info: Loading plugins from folder /volumio/app/plugins/ Oct 19 15:43:47 up volumio[939]: info: Adding plugin upnp to MyMusic Plugins Oct 19 15:43:47 up volumio[939]: info: Adding plugin airplay_emulation to MyMusic Plugins Oct 19 15:43:47 up volumio[939]: info: Adding plugin upnp_browser to MyMusic Plugins Oct 19 15:43:47 up volumio[939]: info: Loading plugins from folder /data/plugins/ Oct 19 15:43:47 up volumio[939]: info: Loading plugin "system"... Oct 19 15:43:47 up volumio[939]: info: Loading plugin "appearance"... Oct 19 15:43:50 up volumio[939]: info: Loading plugin "network"... Oct 19 15:43:50 up volumio[939]: info: Refreshing Cached IP Addresses Oct 19 15:43:50 up sudo[991]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 19 15:43:50 up sudo[991]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 19 15:43:50 up sudo[991]: pam_unix(sudo:session): session closed for user root Oct 19 15:43:50 up sudo[993]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 19 15:43:50 up volumio[939]: info: Loading plugin "services"... Oct 19 15:43:50 up sudo[993]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 19 15:43:50 up volumio[939]: info: Loading plugin "alsa_controller"... Oct 19 15:43:50 up sudo[993]: pam_unix(sudo:session): session closed for user root Oct 19 15:43:50 up sudo[996]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Oct 19 15:43:50 up sudo[996]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 19 15:43:50 up volumio[939]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 19 15:43:50 up volumio[939]: info: Loading plugin "wizard"... Oct 19 15:43:50 up volumio[939]: info: Loading plugin "networkfs"... Oct 19 15:43:50 up volumio[939]: info: Starting Udev Watcher for removable devices Oct 19 15:43:50 up sudo[1002]: 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.0.146/NVMe /mnt/NAS/NVMe Oct 19 15:43:50 up sudo[1002]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 19 15:43:50 up volumio[939]: info: Ignoring mount for partition: boot Oct 19 15:43:50 up volumio[939]: info: Ignoring mount for partition: volumio Oct 19 15:43:50 up volumio[939]: info: Ignoring mount for partition: volumio_data Oct 19 15:43:50 up volumio[939]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 19 15:43:50 up volumio[939]: info: Loading plugin "volumio_command_line_client"... Oct 19 15:43:50 up volumio[939]: info: Loading plugin "upnp"... Oct 19 15:43:50 up volumio[939]: info: [1729367030746] Starting Upmpd Daemon Oct 19 15:43:50 up volumio[939]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 19 15:43:50 up volumio[939]: info: Loading plugin "my_music"... Oct 19 15:43:50 up volumio[939]: info: Loading plugin "mpd"... Oct 19 15:43:50 up kernel: Key type cifs.spnego registered Oct 19 15:43:50 up kernel: Key type cifs.idmap registered Oct 19 15:43:50 up kernel: CIFS: No dialect specified on mount. Default has changed to a more secure dialect, SMB2.1 or later (e.g. SMB3.1.1), from CIFS (SMB1). To use the less secure SMB1 dialect to access old servers which do not support SMB3.1.1 (or even SMB3 or SMB2.1) specify vers=1.0 on mount. Oct 19 15:43:50 up kernel: CIFS: Attempting to mount \\192.168.0.146\NVMe Oct 19 15:43:51 up sudo[996]: pam_unix(sudo:session): session closed for user root Oct 19 15:43:51 up volumio[939]: info: Loading plugin "upnp_browser"... Oct 19 15:43:51 up volumio[939]: info: Loading plugin "alarm-clock"... Oct 19 15:43:52 up volumio[939]: info: Loading plugin "airplay_emulation"... Oct 19 15:43:52 up volumio[939]: info: Starting Shairport Sync Oct 19 15:43:52 up volumio[939]: info: Loading plugin "last_100"... Oct 19 15:43:52 up volumio[939]: info: Loading plugin "webradio"... Oct 19 15:43:52 up volumio[939]: info: Loading plugin "i2s_dacs"... Oct 19 15:43:52 up volumio[939]: info: Loading plugin "volumiodiscovery"... Oct 19 15:43:52 up volumio[939]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Oct 19 15:43:52 up volumio[939]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 19 15:43:52 up volumio[939]: *** WARNING *** For more information see Oct 19 15:43:52 up node[939]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Oct 19 15:43:52 up volumio[939]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Oct 19 15:43:52 up volumio[939]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 19 15:43:52 up volumio[939]: *** WARNING *** For more information see Oct 19 15:43:52 up node[939]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 19 15:43:52 up node[939]: *** WARNING *** For more information see Oct 19 15:43:52 up node[939]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Oct 19 15:43:52 up node[939]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 19 15:43:52 up node[939]: *** WARNING *** For more information see Oct 19 15:43:52 up volumio[939]: info: Applying required configuration parameters for plugin volumiodiscovery Oct 19 15:43:52 up volumio[939]: info: Discovery: Started advertising with name: up Oct 19 15:43:52 up volumio[939]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 19 15:43:52 up volumio[939]: info: Loading plugin "spop"... Oct 19 15:43:55 up volumio[939]: info: Loading plugin "outputs"... Oct 19 15:43:55 up volumio[939]: info: Loading plugin "albumart"... Oct 19 15:43:55 up volumio[939]: info: Plugin example_plugin is not enabled Oct 19 15:43:55 up volumio[939]: info: Loading plugin "inputs"... Oct 19 15:43:55 up volumio[939]: info: Loading plugin "updater_comm"... Oct 19 15:43:55 up volumio[939]: info: Plugin mpdemulation is not enabled Oct 19 15:43:55 up volumio[939]: info: Loading plugin "rest_api"... Oct 19 15:43:55 up volumio[939]: info: Loading plugin "websocket"... Oct 19 15:43:55 up volumio[939]: info: Starting Socket.io Server version 2.3.0 Oct 19 15:43:55 up volumio[939]: info: Loading i18n strings for locale en Oct 19 15:43:55 up volumio[939]: Updating browse sources language Oct 19 15:43:55 up volumio[939]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 19 15:43:55 up volumio[939]: Forking 3 albumart workers Oct 19 15:43:56 up volumio[939]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 19 15:43:56 up volumio[939]: info: CoreCommandRouter::initPlayerControls Oct 19 15:43:56 up volumio[939]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 19 15:43:56 up volumio[939]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 19 15:43:56 up volumio[939]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 19 15:43:56 up volumio[939]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 19 15:43:56 up volumio[939]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 19 15:43:56 up volumio[939]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 19 15:43:56 up volumio[939]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 19 15:43:56 up volumio[939]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 19 15:43:56 up volumio[939]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 19 15:43:56 up volumio[939]: Express server listening on port 3000 Oct 19 15:43:56 up volumio[939]: [Metrics] WebUI: 12s 518.64ms Oct 19 15:43:56 up volumio[939]: info: CoreStateMachine::resetVolumioState Oct 19 15:43:56 up volumio[939]: info: CoreStateMachine::getcurrentVolume Oct 19 15:43:56 up volumio[939]: info: CoreCommandRouter::volumioRetrievevolume Oct 19 15:43:56 up volumio[939]: info: CoreStateMachine::pushState Oct 19 15:43:56 up volumio[939]: info: CorePlayQueue::getTrack 0 Oct 19 15:43:56 up volumio[939]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 19 15:43:56 up volumio[939]: info: CoreCommandRouter::volumioPushState Oct 19 15:43:56 up volumio[939]: verbose: New Socket.io Connection to 192.168.0.168:3000 from 192.168.0.137 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 1 Oct 19 15:43:56 up volumio[939]: verbose: New Socket.io Connection to 192.168.0.168:3000 from 192.168.0.132 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Oct 19 15:43:56 up volumio[939]: verbose: New Socket.io Connection to 192.168.0.168:3000 from 192.168.0.226 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Oct 19 15:43:56 up volumio[939]: verbose: New Socket.io Connection to 192.168.0.168:3000 from 192.168.0.137 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 4 Oct 19 15:43:56 up volumio[939]: verbose: New Socket.io Connection to 192.168.0.168:3000 from 192.168.0.132 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 5 Oct 19 15:43:56 up volumio[939]: verbose: New Socket.io Connection to 192.168.0.168:3000 from 192.168.0.226 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 6 Oct 19 15:43:56 up volumio[939]: info: Reloading queue from file Oct 19 15:43:56 up volumio[939]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 19 15:43:57 up volumio[939]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , initSocket Oct 19 15:43:57 up volumio[939]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , initSocket Oct 19 15:43:57 up volumio[939]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , initSocket Oct 19 15:43:57 up volumio[939]: info: CoreStateMachine::setRepeat null single undefined Oct 19 15:43:57 up volumio[939]: info: CoreStateMachine::pushState Oct 19 15:43:57 up volumio[939]: info: CorePlayQueue::getTrack 0 Oct 19 15:43:57 up volumio[939]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 19 15:43:57 up volumio[939]: info: CoreCommandRouter::volumioPushState Oct 19 15:43:57 up volumio[939]: info: CoreStateMachine::setRandom null Oct 19 15:43:57 up volumio[939]: info: CoreStateMachine::pushState Oct 19 15:43:57 up volumio[939]: info: CorePlayQueue::getTrack 0 Oct 19 15:43:57 up volumio[939]: info: CoreCommandRouter::volumioPushState Oct 19 15:43:57 up volumio[939]: info: Setting Device type: Raspberry PI Oct 19 15:43:57 up sudo[1002]: pam_unix(sudo:session): session closed for user root Oct 19 15:43:57 up kernel: CIFS: VFS: Error connecting to socket. Aborting operation. Oct 19 15:43:57 up kernel: CIFS: VFS: cifs_mount failed w/return code = -113 Oct 19 15:43:57 up volumio[939]: info: CoreCommandRouter::volumioGetState Oct 19 15:43:57 up volumio[939]: info: CorePlayQueue::getTrack 0 Oct 19 15:43:57 up volumio[939]: info: CoreCommandRouter::volumioGetState Oct 19 15:43:57 up volumio[939]: info: CorePlayQueue::getTrack 0 Oct 19 15:43:57 up volumio[939]: info: CoreCommandRouter::volumioGetState Oct 19 15:43:57 up volumio[939]: info: CorePlayQueue::getTrack 0 Oct 19 15:43:57 up volumio[939]: info: Cannot mount NAS NVMe at system boot, trial number 1 ,retrying in 5 seconds Oct 19 15:43:57 up volumio[939]: info: Completed loading Core Plugins Oct 19 15:43:57 up volumio[939]: info: Preparing to generate the ALSA configuration file Oct 19 15:43:57 up volumio[939]: info: Discovery: adding 57c9ace6-3374-4a5f-8508-c9c42a04b97b Oct 19 15:43:57 up volumio[939]: info: Discovery: Found device pi4 Oct 19 15:43:57 up volumio[939]: Starting albumart workers Oct 19 15:43:57 up volumio[939]: info: Discovery: Connecting to remote: 192.168.0.137 Oct 19 15:43:57 up volumio[939]: info: Discovery: adding 39bc0ce9-e4cd-4c78-89f1-19854d452264 Oct 19 15:43:57 up volumio[939]: info: Discovery: Found device Garage Oct 19 15:43:57 up volumio[939]: Starting albumart workers Oct 19 15:43:57 up volumio[939]: info: Discovery: Connecting to remote: 192.168.0.134 Oct 19 15:43:57 up volumio[939]: Starting albumart workers Oct 19 15:43:57 up volumio[939]: info: Asound.conf file written Oct 19 15:43:57 up sudo[1059]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mv /home/volumio/.asoundrc /etc/asound.conf Oct 19 15:43:57 up sudo[1059]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 19 15:43:57 up sudo[1059]: pam_unix(sudo:session): session closed for user root Oct 19 15:43:57 up volumio[939]: info: Output device has changed, restarting MPD Oct 19 15:43:58 up volumio[939]: info: Output device has changed, restarting Shairport Sync Oct 19 15:43:58 up volumio[939]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 19 15:43:58 up volumio[939]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 19 15:43:58 up sudo[1064]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 19 15:43:58 up sudo[1064]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 19 15:43:58 up sudo[1064]: pam_unix(sudo:session): session closed for user root Oct 19 15:43:58 up sudo[1066]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 19 15:43:58 up sudo[1066]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 19 15:43:58 up volumio[939]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 19 15:43:58 up volumio[939]: info: ___________ START PLUGINS ___________ Oct 19 15:43:58 up volumio[939]: info: ControllerMpd::onStart: Initializing MPD Oct 19 15:43:58 up volumio[939]: info: Creating MPD Configuration file Oct 19 15:43:58 up systemd[1]: Listening on mpd.socket. Oct 19 15:43:58 up systemd[1]: Starting Music Player Daemon... Oct 19 15:43:58 up sudo[1075]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 19 15:43:58 up volumio[939]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 19 15:43:58 up sudo[1075]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 19 15:43:58 up volumio[939]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 19 15:43:58 up volumio[939]: info: [1729367038438] CoreMusicLibrary::Adding element Media Servers Oct 19 15:43:58 up volumio[939]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 19 15:43:58 up sudo[1075]: pam_unix(sudo:session): session closed for user root Oct 19 15:43:58 up volumio[939]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 19 15:43:58 up volumio[939]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 19 15:43:58 up sudo[1077]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 19 15:43:58 up sudo[1077]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 19 15:43:58 up sudo[1074]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Oct 19 15:43:58 up sudo[1074]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 19 15:43:58 up sudo[1074]: /bin/chown: cannot access '/var/log/mpd.log': No such file or directory Oct 19 15:43:58 up sudo[1074]: pam_unix(sudo:session): session closed for user root Oct 19 15:43:58 up volumio[939]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 19 15:43:58 up volumio[939]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 19 15:43:58 up volumio[939]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 19 15:43:58 up systemd[1]: mpd.service: Main process exited, code=killed, status=15/TERM Oct 19 15:43:58 up systemd[1]: mpd.service: Succeeded. Oct 19 15:43:58 up systemd[1]: Stopped Music Player Daemon. Oct 19 15:43:58 up systemd[1]: Starting Music Player Daemon... Oct 19 15:43:58 up volumio[939]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 19 15:43:58 up volumio[939]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 19 15:43:58 up volumio[939]: info: [1729367038867] CoreMusicLibrary::Adding element Last_100 Oct 19 15:43:58 up volumio[939]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 19 15:43:58 up volumio[939]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 19 15:43:58 up volumio[939]: info: [1729367038887] CoreMusicLibrary::Adding element Webradio Oct 19 15:43:58 up volumio[939]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 19 15:43:58 up volumio[939]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 19 15:43:58 up volumio[939]: info: Initializing BBC Radios Oct 19 15:43:59 up sudo[1088]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Oct 19 15:43:59 up sudo[1088]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 19 15:43:59 up sudo[1088]: /bin/chown: cannot access '/var/log/mpd.log': No such file or directory Oct 19 15:43:59 up sudo[1088]: pam_unix(sudo:session): session closed for user root Oct 19 15:43:59 up volumio[939]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 19 15:43:59 up volumio[939]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 19 15:43:59 up volumio[939]: info: Creating Spotify config file Oct 19 15:43:59 up volumio[939]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 19 15:43:59 up volumio[939]: info: Volumio Calling Home Oct 19 15:43:59 up volumio[939]: info: Discovery: Connected to remote: 192.168.0.137 Oct 19 15:43:59 up volumio[939]: info: Discovery: adding 6ee29b10-db3e-41fd-b692-dddd483ca35a Oct 19 15:43:59 up volumio[939]: info: Discovery: Found device up Oct 19 15:43:59 up volumio[939]: info: CoreCommandRouter::volumioGetState Oct 19 15:43:59 up volumio[939]: info: CorePlayQueue::getTrack 0 Oct 19 15:43:59 up volumio[939]: info: Discovery: this is already registered, 6ee29b10-db3e-41fd-b692-dddd483ca35a Oct 19 15:43:59 up volumio[939]: info: Discovery: Found device up Oct 19 15:43:59 up volumio[939]: info: CoreCommandRouter::volumioGetState Oct 19 15:43:59 up volumio[939]: info: CorePlayQueue::getTrack 0 Oct 19 15:43:59 up volumio[939]: info: Discovery: adding f0fbcee6-d599-4f74-bac3-7bee34109ab8 Oct 19 15:43:59 up volumio[939]: info: Discovery: Found device down Oct 19 15:43:59 up volumio[939]: info: Discovery: Connecting to remote: 192.168.0.226 Oct 19 15:43:59 up volumio[939]: info: MPD Permissions set Oct 19 15:43:59 up volumio[939]: info: MPD Permissions set Oct 19 15:43:59 up volumio[939]: info: Volumio called home Oct 19 15:43:59 up volumio[939]: info: Spotify config file written Oct 19 15:44:00 up volumio[939]: info: Discovery: Connected to remote: 192.168.0.226 Oct 19 15:44:00 up sudo[1129]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Oct 19 15:44:00 up sudo[1129]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 19 15:44:00 up volumio[939]: info: Discovery: Connected to remote: 192.168.0.134 Oct 19 15:44:00 up systemd[1]: Started go-librespot Daemon. Oct 19 15:44:00 up go-librespot[1131]: Librespot-go daemon starting... Oct 19 15:44:00 up sudo[1129]: pam_unix(sudo:session): session closed for user root Oct 19 15:44:00 up volumio[939]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Oct 19 15:44:00 up volumio[939]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 19 15:44:00 up volumio[939]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 19 15:44:00 up volumio[939]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 19 15:44:00 up volumio[939]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 19 15:44:00 up volumio[939]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 19 15:44:00 up volumio[939]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 19 15:44:00 up volumio[939]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 19 15:44:00 up volumio[939]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 19 15:44:00 up volumio[939]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 19 15:44:00 up volumio[939]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 19 15:44:00 up volumio[939]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 19 15:44:00 up volumio[939]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 19 15:44:00 up volumio[939]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 19 15:44:00 up volumio[939]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 19 15:44:00 up volumio[939]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 19 15:44:00 up volumio[939]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 19 15:44:00 up volumio[939]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 19 15:44:00 up volumio[939]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 19 15:44:00 up volumio[939]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 19 15:44:00 up volumio[939]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 19 15:44:00 up volumio[939]: info: No need to fix Spotify hosts Oct 19 15:44:00 up volumio[939]: info: Starting Shairport Sync Oct 19 15:44:00 up sudo[1148]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 19 15:44:00 up sudo[1148]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 19 15:44:00 up volumio[939]: info: Starting Shairport Sync Oct 19 15:44:00 up sudo[1148]: pam_unix(sudo:session): session closed for user root Oct 19 15:44:00 up sudo[1150]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 19 15:44:00 up sudo[1150]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 19 15:44:00 up volumio[939]: info: Starting Shairport Sync Oct 19 15:44:00 up sudo[1150]: pam_unix(sudo:session): session closed for user root Oct 19 15:44:00 up sudo[1153]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 19 15:44:00 up sudo[1153]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 19 15:44:00 up go-librespot[1131]: time="2024-10-19T15:44:00-04:00" level=info msg="generated new device id: f0583f5b4e894525505602013c5c45fbaf7f3e01" Oct 19 15:44:00 up sudo[1155]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 19 15:44:01 up sudo[1155]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 19 15:44:01 up sudo[1159]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 19 15:44:01 up sudo[1159]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 19 15:44:01 up systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Oct 19 15:44:01 up systemd[1]: shairport-sync.service: Succeeded. Oct 19 15:44:01 up systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Oct 19 15:44:01 up volumio[939]: info: CoreCommandRouter::volumioGetState Oct 19 15:44:01 up volumio[939]: info: CorePlayQueue::getTrack 0 Oct 19 15:44:01 up systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Oct 19 15:44:01 up sudo[1153]: pam_unix(sudo:session): session closed for user root Oct 19 15:44:01 up volumio[939]: info: Shairport-Sync Started Oct 19 15:44:01 up volumio[939]: Error adding Membership: Error: addMembership EINVAL Oct 19 15:44:01 up sudo[1155]: pam_unix(sudo:session): session closed for user root Oct 19 15:44:01 up systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Oct 19 15:44:01 up systemd[1]: shairport-sync.service: Main process exited, code=killed, status=15/TERM Oct 19 15:44:01 up systemd[1]: shairport-sync.service: Succeeded. Oct 19 15:44:01 up systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Oct 19 15:44:01 up sudo[1164]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Oct 19 15:44:01 up sudo[1164]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 19 15:44:01 up systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Oct 19 15:44:01 up sudo[1159]: pam_unix(sudo:session): session closed for user root Oct 19 15:44:01 up volumio[939]: info: Shairport-Sync Started Oct 19 15:44:01 up volumio[939]: info: Shairport-Sync Started Oct 19 15:44:01 up systemd[1]: Started UPnP Renderer front-end to MPD. Oct 19 15:44:01 up sudo[1164]: pam_unix(sudo:session): session closed for user root Oct 19 15:44:01 up volumio[939]: info: Upmpdcli Daemon Started Oct 19 15:44:01 up go-librespot[1131]: time="2024-10-19T15:44:01-04:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Oct 19 15:44:01 up go-librespot[1131]: time="2024-10-19T15:44:01-04:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Oct 19 15:44:01 up go-librespot[1131]: time="2024-10-19T15:44:01-04:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Oct 19 15:44:01 up go-librespot[1131]: time="2024-10-19T15:44:01-04:00" level=debug msg="zeroconf server listening on port 44529" Oct 19 15:44:02 up systemd[1]: systemd-fsckd.service: Succeeded. Oct 19 15:44:02 up sudo[1173]: 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.0.146/NVMe /mnt/NAS/NVMe Oct 19 15:44:02 up sudo[1173]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 19 15:44:02 up kernel: CIFS: Attempting to mount \\192.168.0.146\NVMe Oct 19 15:44:02 up volumio-remote-updater[629]: [2024-10-19 15:44:02] [connect] Successful connection Oct 19 15:44:02 up volumio-remote-updater[629]: [2024-10-19 15:44:02] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1729367042 101 Oct 19 15:44:02 up volumio[939]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 4 Transport: websocket Total Clients: 8 Oct 19 15:44:03 up volumio[939]: info: go-librespot daemon successfully initialized Oct 19 15:44:03 up mpd[1093]: Oct 19 15:44 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Oct 19 15:44:04 up systemd[1]: Started Music Player Daemon. Oct 19 15:44:04 up sudo[1066]: pam_unix(sudo:session): session closed for user root Oct 19 15:44:04 up volumio[939]: Upnp client error: Error: This socket has been ended by the other party Oct 19 15:44:04 up sudo[1077]: pam_unix(sudo:session): session closed for user root Oct 19 15:44:04 up volumio[939]: info: Completed starting Core Plugins Oct 19 15:44:04 up volumio[939]: info: ------------------------------------------- Oct 19 15:44:04 up volumio[939]: info: ----- MyVolumio plugins startup ---- Oct 19 15:44:04 up volumio[939]: info: ------------------------------------------- Oct 19 15:44:04 up volumio[939]: info: [MyVolumio PluginManager] Fetching plans data.... Oct 19 15:44:04 up volumio[939]: error: MPD error: The expression evaluated to a falsy value: Oct 19 15:44:04 up volumio[939]: assert.ok(self.idling) Oct 19 15:44:04 up volumio[939]: error: The expression evaluated to a falsy value: Oct 19 15:44:04 up volumio[939]: assert.ok(self.idling) Oct 19 15:44:04 up volumio[939]: info: MPD running with PID1093 Oct 19 15:44:04 up volumio[939]: ,establishing connection Oct 19 15:44:04 up volumio[939]: error: MPD error: The expression evaluated to a falsy value: Oct 19 15:44:04 up volumio[939]: assert.ok(self.idling) Oct 19 15:44:04 up volumio[939]: error: The expression evaluated to a falsy value: Oct 19 15:44:04 up volumio[939]: assert.ok(self.idling) Oct 19 15:44:04 up volumio[939]: error: updateQueue error: null Oct 19 15:44:05 up kernel: hwmon hwmon1: Voltage normalised Oct 19 15:44:05 up volumio[1168]: Generating RSA private key, 4096 bit long modulus (2 primes) Oct 19 15:44:06 up go-librespot[1131]: time="2024-10-19T15:44:06-04:00" level=debug msg="obtained new client token: AAA0B0J22b9eK+i73+cLqD1PNAzy9LYz51FKjysmL5SN9cQ7/LuPXU6nu6q9aMmbCmxpFb54pkH3JMQ8qknil8AvB7X+BH2DnGtet6bu+F4jU8n+DK6OkFfl6Q2wGnkpV27Hwc4ioiyFIa3TrO1Tz+x1lZ28GMqOwmDEtaQpoYRQ+Q1lCYQoFhyQa8CNSK1O00RSqwVm8FB2FIaRXWqOMyoLbKH6OQd/aZppljR8dJi0dcEk2OVL3sDETnA+Ag==" Oct 19 15:44:06 up go-librespot[1131]: time="2024-10-19T15:44:06-04:00" level=info msg="connected to ap-gue1.spotify.com:4070" Oct 19 15:44:06 up go-librespot[1131]: time="2024-10-19T15:44:06-04:00" level=debug msg="completed keyexchange" Oct 19 15:44:06 up systemd[1]: systemd-hostnamed.service: Succeeded. Oct 19 15:44:06 up volumio[939]: info: Initializing connection to go-librespot Websocket Oct 19 15:44:06 up go-librespot[1131]: time="2024-10-19T15:44:06-04:00" level=debug msg="new websocket client" Oct 19 15:44:06 up volumio[939]: info: Connection to go-librespot Websocket established Oct 19 15:44:07 up go-librespot[1131]: time="2024-10-19T15:44:07-04:00" level=debug msg="completed challenge" Oct 19 15:44:07 up go-librespot[1131]: time="2024-10-19T15:44:07-04:00" level=debug msg="authenticated as 7ef8glzrxj8irqjidryw8kanh" Oct 19 15:44:07 up go-librespot[1131]: time="2024-10-19T15:44:07-04:00" level=debug msg="authenticated as 7ef8glzrxj8irqjidryw8kanh" Oct 19 15:44:07 up go-librespot[1131]: time="2024-10-19T15:44:07-04:00" level=debug msg="dealer connection opened" Oct 19 15:44:07 up go-librespot[1131]: time="2024-10-19T15:44:07-04:00" level=info msg="accepted zeroconf user 7ef8glzrxj8irqjidryw8kanh from MSI-I5" Oct 19 15:44:07 up go-librespot[1131]: time="2024-10-19T15:44:07-04:00" level=debug msg="received connection id: ZGRmZmY0ZGEtY2QwOS00ZjY4LWJlOTUtMzY5MTg1NDg0ODA2K2RlYWxlcit0Y3A6Ly8wYWNiZjg5NC5pcC5ndWUxLnNwb3RpZnkubmV0OjU3MDArNDUxNkYxQTdCOEQ1OEE0RkY0ODIzM0I5NzY3NzJFMjIxOTM4MTMyREJGRDUwRjg5MDQ0RDk4NzI3QUU2N0VENg==" Oct 19 15:44:07 up go-librespot[1131]: time="2024-10-19T15:44:07-04:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Oct 19 15:44:07 up go-librespot[1131]: time="2024-10-19T15:44:07-04:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Oct 19 15:44:07 up go-librespot[1131]: time="2024-10-19T15:44:07-04:00" level=debug msg="put connect state because NEW_DEVICE" Oct 19 15:44:07 up go-librespot[1131]: time="2024-10-19T15:44:07-04:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Oct 19 15:44:07 up go-librespot[1131]: time="2024-10-19T15:44:07-04:00" level=debug msg="autoplay enabled: false" Oct 19 15:44:07 up go-librespot[1131]: time="2024-10-19T15:44:07-04:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Oct 19 15:44:07 up go-librespot[1131]: time="2024-10-19T15:44:07-04:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 505" Oct 19 15:44:08 up go-librespot[1131]: time="2024-10-19T15:44:08-04:00" level=debug msg="handling transfer player command from 0191e3f3b11c5f8ffb945d6b3aa9c47a85707311" Oct 19 15:44:08 up go-librespot[1131]: time="2024-10-19T15:44:08-04:00" level=debug msg="resolved context of track" uri="spotify:station:album:3ywVzrwMQ3Kq43N9zBdBQm" Oct 19 15:44:08 up go-librespot[1131]: time="2024-10-19T15:44:08-04:00" level=trace msg="fetched new page 0 with 50 items (list: 50)" uri="spotify:station:album:3ywVzrwMQ3Kq43N9zBdBQm" Oct 19 15:44:08 up go-librespot[1131]: time="2024-10-19T15:44:08-04:00" level=debug msg="loading track (paused: false, position: -294011520ms)" uri="spotify:track:1S4igP7OpCUIEC5l75DssU" Oct 19 15:44:08 up go-librespot[1131]: time="2024-10-19T15:44:08-04:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 19 15:44:08 up go-librespot[1131]: time="2024-10-19T15:44:08-04:00" level=trace msg="emitting websocket event: will_play" Oct 19 15:44:08 up volumio[939]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:1S4igP7OpCUIEC5l75DssU","play_origin":""}} Oct 19 15:44:08 up go-librespot[1131]: time="2024-10-19T15:44:08-04:00" level=debug msg="selected format OGG_VORBIS_320 (648dc337405473777b3e2a2e87792e6214744624)" uri="spotify:track:1S4igP7OpCUIEC5l75DssU" Oct 19 15:44:08 up go-librespot[1131]: time="2024-10-19T15:44:08-04:00" level=debug msg="requested aes key for file 648dc337405473777b3e2a2e87792e6214744624, gid: 1S4igP7OpCUIEC5l75DssU" Oct 19 15:44:08 up sudo[1173]: pam_unix(sudo:session): session closed for user root Oct 19 15:44:08 up kernel: CIFS: VFS: Error connecting to socket. Aborting operation. Oct 19 15:44:08 up kernel: CIFS: VFS: cifs_mount failed w/return code = -113 Oct 19 15:44:08 up volumio[939]: info: Cannot mount NAS NVMe at system boot, trial number 2 ,retrying in 5 seconds Oct 19 15:44:08 up go-librespot[1131]: time="2024-10-19T15:44:08-04:00" level=debug msg="fetched first chunk of 15, total size is 7814704 bytes" uri="spotify:track:1S4igP7OpCUIEC5l75DssU" Oct 19 15:44:08 up go-librespot[1131]: time="2024-10-19T15:44:08-04:00" level=trace msg="seek to 0ms (diff: 0ms, samples: 0, bytes: 0)" uri="spotify:track:1S4igP7OpCUIEC5l75DssU" Oct 19 15:44:08 up go-librespot[1131]: time="2024-10-19T15:44:08-04:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 5102 us, period size = 225 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 98 frames" Oct 19 15:44:08 up go-librespot[1131]: time="2024-10-19T15:44:08-04:00" level=debug msg="created new output device" Oct 19 15:44:08 up go-librespot[1131]: time="2024-10-19T15:44:08-04:00" level=info msg="loaded track \"Biological Speculation\" (paused: false, position: -294011520ms, duration: 185610ms, prefetched: false)" uri="spotify:track:1S4igP7OpCUIEC5l75DssU" Oct 19 15:44:09 up go-librespot[1131]: time="2024-10-19T15:44:09-04:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 19 15:44:09 up go-librespot[1131]: time="2024-10-19T15:44:09-04:00" level=trace msg="scheduling prefetch in 155s" Oct 19 15:44:09 up go-librespot[1131]: time="2024-10-19T15:44:09-04:00" level=trace msg="emitting websocket event: metadata" Oct 19 15:44:09 up go-librespot[1131]: time="2024-10-19T15:44:09-04:00" level=trace msg="emitting websocket event: active" Oct 19 15:44:09 up go-librespot[1131]: time="2024-10-19T15:44:09-04:00" level=debug msg="sending successful reply for dealer request" Oct 19 15:44:09 up volumio[939]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:1S4igP7OpCUIEC5l75DssU","name":"Biological Speculation","artist_names":["Funkadelic"],"album_name":"America Eats Its Young","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02e3c251129b0fa401b6f165ed","position":-294011520,"duration":185610,"release_date":"year:1972 month:5 day:22","track_number":10,"disc_number":1}} Oct 19 15:44:09 up volumio[939]: SPOTIFY: received: {"type":"active","data":null} Oct 19 15:44:09 up volumio[939]: info: Aligning Spotify Volume to Volumio Volume Oct 19 15:44:09 up volumio[939]: info: CoreCommandRouter::volumioGetState Oct 19 15:44:09 up volumio[939]: info: CorePlayQueue::getTrack 0 Oct 19 15:44:09 up go-librespot[1131]: time="2024-10-19T15:44:09-04:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Oct 19 15:44:09 up go-librespot[1131]: time="2024-10-19T15:44:09-04:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 241" Oct 19 15:44:09 up go-librespot[1131]: time="2024-10-19T15:44:09-04:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Oct 19 15:44:09 up go-librespot[1131]: time="2024-10-19T15:44:09-04:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 19 15:44:09 up go-librespot[1131]: time="2024-10-19T15:44:09-04:00" level=trace msg="emitting websocket event: playing" Oct 19 15:44:09 up volumio[939]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:1S4igP7OpCUIEC5l75DssU","play_origin":""}} Oct 19 15:44:09 up volumio[939]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 19 15:44:09 up volumio[939]: TypeError: Cannot read property 'service' of undefined Oct 19 15:44:09 up volumio[939]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:337:50) Oct 19 15:44:09 up volumio[939]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:263:18) Oct 19 15:44:09 up volumio[939]: at WebSocket.message (/data/plugins/music_service/spop/index.js:190:14) Oct 19 15:44:09 up volumio[939]: at WebSocket.emit (events.js:315:20) Oct 19 15:44:09 up volumio[939]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20) Oct 19 15:44:09 up volumio[939]: at Receiver.emit (events.js:315:20) Oct 19 15:44:09 up volumio[939]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) Oct 19 15:44:09 up volumio[939]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) Oct 19 15:44:09 up volumio[939]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) Oct 19 15:44:09 up volumio[939]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) Oct 19 15:44:09 up volumio[939]: at writeOrBuffer (internal/streams/writable.js:358:12) Oct 19 15:44:09 up volumio[939]: at Receiver.Writable.write (internal/streams/writable.js:303:10) Oct 19 15:44:09 up volumio[939]: at Socket.socketOnData (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1355:35) Oct 19 15:44:09 up volumio[939]: at Socket.emit (events.js:315:20) Oct 19 15:44:09 up volumio[939]: at addChunk (internal/streams/readable.js:309:12) Oct 19 15:44:09 up volumio[939]: at readableAddChunk (internal/streams/readable.js:284:9) Oct 19 15:44:09 up kernel: hwmon hwmon1: Undervoltage detected! Oct 19 15:44:09 up volumio[939]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 19 15:44:09 up go-librespot[1131]: time="2024-10-19T15:44:09-04:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1371" Oct 19 15:44:09 up go-librespot[1131]: time="2024-10-19T15:44:09-04:00" level=debug msg="fetched chunk 1/14, size: 524288" uri="spotify:track:1S4igP7OpCUIEC5l75DssU" Oct 19 15:44:09 up go-librespot[1131]: time="2024-10-19T15:44:09-04:00" level=debug msg="fetched chunk 2/14, size: 524288" uri="spotify:track:1S4igP7OpCUIEC5l75DssU" Oct 19 15:44:09 up go-librespot[1131]: time="2024-10-19T15:44:09-04:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Oct 19 15:44:09 up go-librespot[1131]: time="2024-10-19T15:44:09-04:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1137" Oct 19 15:44:09 up go-librespot[1131]: time="2024-10-19T15:44:09-04:00" level=debug msg="fetched chunk 3/14, size: 524288" uri="spotify:track:1S4igP7OpCUIEC5l75DssU" Oct 19 15:44:10 up sudo[1210]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-10-19 15:43 Oct 19 15:44:10 up sudo[1210]: pam_unix(sudo:session): session opened for user root by (uid=0) 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="bba9e3185e150dd0995f9a49355b34fc6218d5a2" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="8aa57e3ae5b742ea1069404608336a9884ccfb4e" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue 17 Sep 2024 05:01:09 PM CEST" VOLUMIO_VERSION="3.757" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="e0a6dc7e914e3fb93cbf2123f2f73eac"