-- Logs begin at Thu 2019-02-14 10:12:00 WET, end at Tue 2024-11-12 22:40:59 WET. -- Nov 12 22:40:27 volumio2 kernel: audit: type=2000 audit(0.030:1): state=initialized audit_enabled=0 res=1 Nov 12 22:40:27 volumio2 kernel: thermal_sys: Registered thermal governor 'step_wise' Nov 12 22:40:27 volumio2 kernel: hw-breakpoint: found 5 (+1 reserved) breakpoint and 4 watchpoint registers. Nov 12 22:40:27 volumio2 kernel: hw-breakpoint: maximum watchpoint size is 8 bytes. Nov 12 22:40:27 volumio2 kernel: Serial: AMBA PL011 UART driver Nov 12 22:40:27 volumio2 kernel: bcm2835-mbox 3f00b880.mailbox: mailbox enabled Nov 12 22:40:27 volumio2 kernel: raspberrypi-firmware soc:firmware: Attached to firmware from 2023-10-17T15:42:39, variant start Nov 12 22:40:27 volumio2 kernel: raspberrypi-firmware soc:firmware: Firmware hash is 30f0c5e4d076da3ab4f341d88e7d505760b93ad7 Nov 12 22:40:27 volumio2 kernel: kprobes: kprobe jump-optimization is enabled. All kprobes are optimized if possible. Nov 12 22:40:27 volumio2 kernel: bcm2835-dma 3f007000.dma: DMA legacy API manager, dmachans=0x1 Nov 12 22:40:27 volumio2 kernel: SCSI subsystem initialized Nov 12 22:40:27 volumio2 kernel: usbcore: registered new interface driver usbfs Nov 12 22:40:27 volumio2 kernel: usbcore: registered new interface driver hub Nov 12 22:40:27 volumio2 kernel: usbcore: registered new device driver usb Nov 12 22:40:27 volumio2 kernel: usb_phy_generic phy: supply vcc not found, using dummy regulator Nov 12 22:40:27 volumio2 kernel: pps_core: LinuxPPS API ver. 1 registered Nov 12 22:40:27 volumio2 kernel: pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti Nov 12 22:40:27 volumio2 kernel: PTP clock support registered Nov 12 22:40:27 volumio2 kernel: clocksource: Switched to clocksource arch_sys_counter Nov 12 22:40:27 volumio2 kernel: VFS: Disk quotas dquot_6.6.0 Nov 12 22:40:27 volumio2 kernel: VFS: Dquot-cache hash table entries: 1024 (order 0, 4096 bytes) Nov 12 22:40:27 volumio2 kernel: FS-Cache: Loaded Nov 12 22:40:27 volumio2 kernel: CacheFiles: Loaded Nov 12 22:40:27 volumio2 kernel: NET: Registered PF_INET protocol family Nov 12 22:40:27 volumio2 kernel: IP idents hash table entries: 16384 (order: 5, 131072 bytes, linear) Nov 12 22:40:27 volumio2 kernel: tcp_listen_portaddr_hash hash table entries: 512 (order: 0, 4096 bytes, linear) Nov 12 22:40:27 volumio2 kernel: Table-perturb hash table entries: 65536 (order: 6, 262144 bytes, linear) Nov 12 22:40:27 volumio2 kernel: TCP established hash table entries: 8192 (order: 3, 32768 bytes, linear) Nov 12 22:40:27 volumio2 kernel: TCP bind hash table entries: 8192 (order: 5, 131072 bytes, linear) Nov 12 22:40:27 volumio2 kernel: TCP: Hash tables configured (established 8192 bind 8192) Nov 12 22:40:27 volumio2 kernel: UDP hash table entries: 512 (order: 2, 16384 bytes, linear) Nov 12 22:40:27 volumio2 kernel: UDP-Lite hash table entries: 512 (order: 2, 16384 bytes, linear) Nov 12 22:40:27 volumio2 kernel: NET: Registered PF_UNIX/PF_LOCAL protocol family Nov 12 22:40:27 volumio2 kernel: RPC: Registered named UNIX socket transport module. Nov 12 22:40:27 volumio2 kernel: RPC: Registered udp transport module. Nov 12 22:40:27 volumio2 kernel: RPC: Registered tcp transport module. Nov 12 22:40:27 volumio2 kernel: RPC: Registered tcp NFSv4.1 backchannel transport module. Nov 12 22:40:27 volumio2 kernel: Trying to unpack rootfs image as initramfs... Nov 12 22:40:27 volumio2 kernel: hw perfevents: enabled with armv7_cortex_a7 PMU driver, 7 counters available Nov 12 22:40:27 volumio2 kernel: Freeing initrd memory: 14316K Nov 12 22:40:27 volumio2 kernel: Initialise system trusted keyrings Nov 12 22:40:27 volumio2 kernel: workingset: timestamp_bits=14 max_order=18 bucket_order=4 Nov 12 22:40:27 volumio2 kernel: zbud: loaded Nov 12 22:40:27 volumio2 kernel: NFS: Registering the id_resolver key type Nov 12 22:40:27 volumio2 kernel: Key type id_resolver registered Nov 12 22:40:27 volumio2 kernel: Key type id_legacy registered Nov 12 22:40:27 volumio2 kernel: nfs4filelayout_init: NFSv4 File Layout Driver Registering... Nov 12 22:40:27 volumio2 kernel: nfs4flexfilelayout_init: NFSv4 Flexfile Layout Driver Registering... Nov 12 22:40:27 volumio2 kernel: Key type asymmetric registered Nov 12 22:40:27 volumio2 kernel: Asymmetric key parser 'x509' registered Nov 12 22:40:27 volumio2 kernel: Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) Nov 12 22:40:27 volumio2 kernel: io scheduler mq-deadline registered Nov 12 22:40:27 volumio2 kernel: io scheduler kyber registered Nov 12 22:40:27 volumio2 kernel: bcm2708_fb soc:fb: FB found 1 display(s) Nov 12 22:40:27 volumio2 kernel: Console: switching to colour frame buffer device 80x30 Nov 12 22:40:27 volumio2 kernel: bcm2708_fb soc:fb: Registered framebuffer for display 0, size 640x480 Nov 12 22:40:27 volumio2 kernel: bcm2835-rng 3f104000.rng: hwrng registered Nov 12 22:40:27 volumio2 kernel: vc-mem: phys_addr:0x00000000 mem_base=0x3ec00000 mem_size:0x40000000(1024 MiB) Nov 12 22:40:27 volumio2 kernel: brd: module loaded Nov 12 22:40:27 volumio2 kernel: loop: module loaded Nov 12 22:40:27 volumio2 kernel: Loading iSCSI transport class v2.0-870. Nov 12 22:40:27 volumio2 kernel: usbcore: registered new interface driver lan78xx Nov 12 22:40:27 volumio2 kernel: usbcore: registered new interface driver smsc95xx Nov 12 22:40:27 volumio2 kernel: dwc_otg: version 3.00a 10-AUG-2012 (platform bus) Nov 12 22:40:27 volumio2 kernel: Core Release: 2.80a Nov 12 22:40:27 volumio2 kernel: Setting default values for core params Nov 12 22:40:27 volumio2 kernel: Finished setting default values for core params Nov 12 22:40:27 volumio2 kernel: Using Buffer DMA mode Nov 12 22:40:27 volumio2 kernel: Periodic Transfer Interrupt Enhancement - disabled Nov 12 22:40:27 volumio2 kernel: Multiprocessor Interrupt Enhancement - disabled Nov 12 22:40:27 volumio2 kernel: OTG VER PARAM: 0, OTG VER FLAG: 0 Nov 12 22:40:27 volumio2 kernel: Dedicated Tx FIFOs mode Nov 12 22:40:27 volumio2 kernel: Nov 12 22:40:27 volumio2 kernel: WARN::dwc_otg_hcd_init:1074: FIQ DMA bounce buffers: virt = b4114000 dma = 0xf4114000 len=9024 Nov 12 22:40:27 volumio2 kernel: FIQ FSM acceleration enabled for : Non-periodic Split Transactions Periodic Split Transactions High-Speed Isochronous Endpoints Interrupt/Control Split Transaction hack enabled Nov 12 22:40:27 volumio2 kernel: dwc_otg: Microframe scheduler enabled Nov 12 22:40:27 volumio2 kernel: Nov 12 22:40:27 volumio2 kernel: WARN::hcd_init_fiq:457: FIQ on core 1 Nov 12 22:40:27 volumio2 kernel: Nov 12 22:40:27 volumio2 kernel: WARN::hcd_init_fiq:458: FIQ ASM at 807cb80c length 36 Nov 12 22:40:27 volumio2 kernel: Nov 12 22:40:27 volumio2 kernel: WARN::hcd_init_fiq:497: MPHI regs_base at b8810000 Nov 12 22:40:27 volumio2 kernel: dwc_otg 3f980000.usb: DWC OTG Controller Nov 12 22:40:27 volumio2 kernel: dwc_otg 3f980000.usb: new USB bus registered, assigned bus number 1 Nov 12 22:40:27 volumio2 kernel: dwc_otg 3f980000.usb: irq 89, io mem 0x00000000 Nov 12 22:40:27 volumio2 kernel: Init: Port Power? op_state=1 Nov 12 22:40:27 volumio2 kernel: Init: Power Port (0) Nov 12 22:40:27 volumio2 kernel: usb usb1: New USB device found, idVendor=1d6b, idProduct=0002, bcdDevice= 6.01 Nov 12 22:40:27 volumio2 kernel: usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1 Nov 12 22:40:27 volumio2 kernel: usb usb1: Product: DWC OTG Controller Nov 12 22:40:27 volumio2 kernel: usb usb1: Manufacturer: Linux 6.1.69-v7+ dwc_otg_hcd Nov 12 22:40:27 volumio2 kernel: usb usb1: SerialNumber: 3f980000.usb Nov 12 22:40:27 volumio2 kernel: hub 1-0:1.0: USB hub found Nov 12 22:40:27 volumio2 kernel: hub 1-0:1.0: 1 port detected Nov 12 22:40:27 volumio2 kernel: dwc_otg: FIQ enabled Nov 12 22:40:27 volumio2 kernel: dwc_otg: NAK holdoff enabled Nov 12 22:40:27 volumio2 kernel: dwc_otg: FIQ split-transaction FSM enabled Nov 12 22:40:27 volumio2 kernel: Module dwc_common_port init Nov 12 22:40:27 volumio2 kernel: usbcore: registered new interface driver usb-storage Nov 12 22:40:27 volumio2 kernel: mousedev: PS/2 mouse device common for all mice Nov 12 22:40:27 volumio2 kernel: sdhci: Secure Digital Host Controller Interface driver Nov 12 22:40:27 volumio2 kernel: sdhci: Copyright(c) Pierre Ossman Nov 12 22:40:27 volumio2 kernel: sdhci-pltfm: SDHCI platform and OF driver helper Nov 12 22:40:27 volumio2 kernel: ledtrig-cpu: registered to indicate activity on CPUs Nov 12 22:40:27 volumio2 kernel: hid: raw HID events driver (C) Jiri Kosina Nov 12 22:40:27 volumio2 kernel: usbcore: registered new interface driver usbhid Nov 12 22:40:27 volumio2 kernel: usbhid: USB HID core driver Nov 12 22:40:27 volumio2 kernel: Initializing XFRM netlink socket Nov 12 22:40:27 volumio2 kernel: NET: Registered PF_PACKET protocol family Nov 12 22:40:27 volumio2 kernel: Key type dns_resolver registered Nov 12 22:40:27 volumio2 kernel: Registering SWP/SWPB emulation handler Nov 12 22:40:27 volumio2 kernel: registered taskstats version 1 Nov 12 22:40:27 volumio2 kernel: Loading compiled-in X.509 certificates Nov 12 22:40:27 volumio2 kernel: Key type .fscrypt registered Nov 12 22:40:27 volumio2 kernel: Key type fscrypt-provisioning registered Nov 12 22:40:27 volumio2 kernel: uart-pl011 3f201000.serial: cts_event_workaround enabled Nov 12 22:40:27 volumio2 kernel: 3f201000.serial: ttyAMA1 at MMIO 0x3f201000 (irq = 114, base_baud = 0) is a PL011 rev2 Nov 12 22:40:27 volumio2 kernel: serial serial0: tty port ttyAMA1 registered Nov 12 22:40:27 volumio2 kernel: bcm2835-wdt bcm2835-wdt: Broadcom BCM2835 watchdog timer Nov 12 22:40:27 volumio2 kernel: bcm2835-power bcm2835-power: Broadcom BCM2835 power domains driver Nov 12 22:40:27 volumio2 kernel: mmc-bcm2835 3f300000.mmcnr: mmc_debug:0 mmc_debug2:0 Nov 12 22:40:27 volumio2 kernel: mmc-bcm2835 3f300000.mmcnr: DMA channel allocated Nov 12 22:40:27 volumio2 kernel: sdhost: log_buf @ 0e9a7a2b (f4113000) Nov 12 22:40:27 volumio2 kernel: mmc0: sdhost-bcm2835 loaded - DMA enabled (>1) Nov 12 22:40:27 volumio2 kernel: of_cfs_init Nov 12 22:40:27 volumio2 kernel: of_cfs_init: OK Nov 12 22:40:27 volumio2 kernel: Freeing unused kernel image (initmem) memory: 1024K Nov 12 22:40:27 volumio2 kernel: Indeed it is in host mode hprt0 = 00021501 Nov 12 22:40:27 volumio2 kernel: mmc0: host does not support reading read-only switch, assuming write-enable Nov 12 22:40:27 volumio2 kernel: mmc0: new high speed SDHC card at address 5048 Nov 12 22:40:27 volumio2 kernel: mmcblk0: mmc0:5048 SD16G 14.4 GiB Nov 12 22:40:27 volumio2 kernel: mmcblk0: p1 p2 p3 Nov 12 22:40:27 volumio2 kernel: mmcblk0: mmc0:5048 SD16G 14.4 GiB Nov 12 22:40:27 volumio2 kernel: mmc1: new high speed SDIO card at address 0001 Nov 12 22:40:27 volumio2 kernel: Run /init as init process Nov 12 22:40:27 volumio2 kernel: with arguments: Nov 12 22:40:27 volumio2 kernel: /init Nov 12 22:40:27 volumio2 kernel: splash Nov 12 22:40:27 volumio2 kernel: nodebug Nov 12 22:40:27 volumio2 kernel: with environment: Nov 12 22:40:27 volumio2 kernel: HOME=/ Nov 12 22:40:27 volumio2 kernel: TERM=linux Nov 12 22:40:27 volumio2 kernel: imgpart=UUID=af3faec2-9654-4fec-8791-d5638a5837ad Nov 12 22:40:27 volumio2 kernel: imgfile=/volumio_current.sqsh Nov 12 22:40:27 volumio2 kernel: bootpart=UUID=2E0A-AE55 Nov 12 22:40:27 volumio2 kernel: datapart=UUID=660717eb-e471-4727-aac1-2c263938c365 Nov 12 22:40:27 volumio2 kernel: uuidconfig=cmdline.txt Nov 12 22:40:27 volumio2 kernel: pcie_aspm=off Nov 12 22:40:27 volumio2 kernel: pci=pcie_bus_safe Nov 12 22:40:27 volumio2 kernel: bootdelay=7 Nov 12 22:40:27 volumio2 kernel: use_kmsg=no Nov 12 22:40:27 volumio2 kernel: usb 1-1: new high-speed USB device number 2 using dwc_otg Nov 12 22:40:27 volumio2 kernel: Indeed it is in host mode hprt0 = 00001101 Nov 12 22:40:27 volumio2 kernel: usb 1-1: New USB device found, idVendor=0424, idProduct=2514, bcdDevice= b.b3 Nov 12 22:40:27 volumio2 kernel: usb 1-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0 Nov 12 22:40:27 volumio2 kernel: hub 1-1:1.0: USB hub found Nov 12 22:40:27 volumio2 kernel: hub 1-1:1.0: 4 ports detected Nov 12 22:40:27 volumio2 kernel: usb 1-1.1: new high-speed USB device number 3 using dwc_otg Nov 12 22:40:27 volumio2 kernel: usb 1-1.1: New USB device found, idVendor=0424, idProduct=2514, bcdDevice= b.b3 Nov 12 22:40:27 volumio2 kernel: usb 1-1.1: New USB device strings: Mfr=0, Product=0, SerialNumber=0 Nov 12 22:40:27 volumio2 kernel: hub 1-1.1:1.0: USB hub found Nov 12 22:40:27 volumio2 kernel: hub 1-1.1:1.0: 3 ports detected Nov 12 22:40:27 volumio2 kernel: fuse: init (API version 7.37) Nov 12 22:40:27 volumio2 kernel: usb 1-1.1.3: new high-speed USB device number 4 using dwc_otg Nov 12 22:40:27 volumio2 kernel: squashfs: version 4.0 (2009/01/31) Phillip Lougher Nov 12 22:40:27 volumio2 kernel: usbcore: registered new interface driver uas Nov 12 22:40:27 volumio2 kernel: usb 1-1.1.3: New USB device found, idVendor=22e8, idProduct=dac4, bcdDevice= 3.26 Nov 12 22:40:27 volumio2 kernel: usb 1-1.1.3: New USB device strings: Mfr=1, Product=2, SerialNumber=3 Nov 12 22:40:27 volumio2 kernel: usb 1-1.1.3: Product: Cambridge AudioDAC100 USB 2 Nov 12 22:40:27 volumio2 kernel: usb 1-1.1.3: Manufacturer: Cambridge Audio Nov 12 22:40:27 volumio2 kernel: usb 1-1.1.3: SerialNumber: 0000 Nov 12 22:40:27 volumio2 kernel: usb 1-1.1.1: new high-speed USB device number 5 using dwc_otg Nov 12 22:40:27 volumio2 kernel: usb 1-1.1.1: New USB device found, idVendor=0424, idProduct=7800, bcdDevice= 3.00 Nov 12 22:40:27 volumio2 kernel: usb 1-1.1.1: New USB device strings: Mfr=0, Product=0, SerialNumber=0 Nov 12 22:40:27 volumio2 kernel: lan78xx 1-1.1.1:1.0 (unnamed net_device) (uninitialized): No External EEPROM. Setting MAC Speed Nov 12 22:40:27 volumio2 kernel: lan78xx 1-1.1.1:1.0 (unnamed net_device) (uninitialized): int urb period 64 Nov 12 22:40:27 volumio2 kernel: FAT-fs (mmcblk0p1): Volume was not properly unmounted. Some data may be corrupt. Please run fsck. Nov 12 22:40:27 volumio2 kernel: EXT4-fs (mmcblk0p2): recovery complete Nov 12 22:40:27 volumio2 kernel: EXT4-fs (mmcblk0p2): mounted filesystem with ordered data mode. Quota mode: none. Nov 12 22:40:27 volumio2 kernel: loop0: detected capacity change from 0 to 983416 Nov 12 22:40:27 volumio2 kernel: EXT4-fs (mmcblk0p3): recovery complete Nov 12 22:40:27 volumio2 kernel: EXT4-fs (mmcblk0p3): mounted filesystem with ordered data mode. Quota mode: none. Nov 12 22:40:27 volumio2 systemd[1]: System time before build time, advancing clock. Nov 12 22:40:27 volumio2 kernel: NET: Registered PF_INET6 protocol family Nov 12 22:40:27 volumio2 kernel: Segment Routing with IPv6 Nov 12 22:40:27 volumio2 kernel: In-situ OAM (IOAM) with IPv6 Nov 12 22:40:27 volumio2 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) Nov 12 22:40:27 volumio2 systemd[1]: Detected architecture arm. Nov 12 22:40:27 volumio2 systemd[1]: Set hostname to . Nov 12 22:40:27 volumio2 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. Nov 12 22:40:27 volumio2 systemd[1]: Created slice system-getty.slice. Nov 12 22:40:27 volumio2 systemd[1]: Listening on Journal Socket. Nov 12 22:40:27 volumio2 systemd[1]: Starting Load Kernel Modules... Nov 12 22:40:27 volumio2 systemd[1]: Starting Create list of required static device nodes for the current kernel... Nov 12 22:40:27 volumio2 systemd[1]: Created slice system-systemd\x2dfsck.slice. Nov 12 22:40:27 volumio2 systemd[1]: Started Forward Password Requests to Wall Directory Watch. Nov 12 22:40:27 volumio2 kernel: i2c_dev: i2c /dev entries driver Nov 12 22:40:27 volumio2 systemd-journald[310]: Journal started Nov 12 22:40:27 volumio2 systemd-journald[310]: Runtime journal (/run/log/journal/4ceeebcde4a5f04b591e77826532825c) is 7.5M, max 30.0M, 22.5M free. Nov 12 22:40:27 volumio2 systemd-modules-load[297]: Inserted module 'i2c_dev' Nov 12 22:40:27 volumio2 fake-hwclock[306]: Tue Nov 12 22:40:27 UTC 2024 Nov 12 22:40:27 volumio2 systemd[1]: Started Load/Save Random Seed. Nov 12 22:40:27 volumio2 systemd[1]: dynamicswap.service: Succeeded. Nov 12 22:40:27 volumio2 systemd[1]: Started Create System Users. Nov 12 22:40:27 volumio2 systemd[1]: Starting Create Static Device Nodes in /dev... Nov 12 22:40:27 volumio2 systemd[1]: Started udev Coldplug all Devices. Nov 12 22:40:27 volumio2 systemd[1]: Starting Helper to synchronize boot up for ifupdown... Nov 12 22:40:27 volumio2 systemd[1]: Started Helper to synchronize boot up for ifupdown. Nov 12 22:40:27 volumio2 systemd[1]: Started Create Static Device Nodes in /dev. Nov 12 22:40:27 volumio2 systemd[1]: Reached target Local File Systems (Pre). Nov 12 22:40:27 volumio2 systemd[1]: Mounting /var/spool/cups... Nov 12 22:40:27 volumio2 systemd[1]: tmp.mount: Directory /tmp to mount over is not empty, mounting anyway. Nov 12 22:40:27 volumio2 systemd[1]: Mounting /tmp... Nov 12 22:40:27 volumio2 systemd[1]: var-log.mount: Directory /var/log to mount over is not empty, mounting anyway. Nov 12 22:40:27 volumio2 systemd[1]: Mounting /var/log... Nov 12 22:40:27 volumio2 systemd[1]: Starting udev Kernel Device Manager... Nov 12 22:40:27 volumio2 systemd[1]: Mounted /var/spool/cups. Nov 12 22:40:27 volumio2 systemd[1]: Mounted /tmp. Nov 12 22:40:27 volumio2 systemd[1]: Mounting /var/spool/cups/tmp... Nov 12 22:40:27 volumio2 systemd[1]: Mounted /var/log. Nov 12 22:40:27 volumio2 systemd[1]: Starting Flush Journal to Persistent Storage... Nov 12 22:40:27 volumio2 systemd[1]: Mounted /var/spool/cups/tmp. Nov 12 22:40:27 volumio2 systemd-udevd[348]: Network interface NamePolicy= disabled on kernel command line, ignoring. Nov 12 22:40:27 volumio2 systemd-journald[310]: Runtime journal (/run/log/journal/4ceeebcde4a5f04b591e77826532825c) is 7.5M, max 30.0M, 22.5M free. Nov 12 22:40:27 volumio2 systemd[1]: Started Flush Journal to Persistent Storage. Nov 12 22:40:27 volumio2 systemd[1]: Started udev Kernel Device Manager. Nov 12 22:40:27 volumio2 systemd[1]: Starting Show Plymouth Boot Screen... Nov 12 22:40:27 volumio2 systemd[1]: plymouth-start.service: Succeeded. Nov 12 22:40:27 volumio2 systemd[1]: Started Show Plymouth Boot Screen. Nov 12 22:40:27 volumio2 systemd[1]: Condition check resulted in Dispatch Password Requests to Console Directory Watch being skipped. Nov 12 22:40:27 volumio2 systemd[1]: Reached target Paths. Nov 12 22:40:27 volumio2 systemd[1]: Reached target Local Encrypted Volumes. Nov 12 22:40:27 volumio2 systemd[1]: Started Forward Password Requests to Plymouth Directory Watch. Nov 12 22:40:27 volumio2 kernel: vc_sm_cma: module is from the staging directory, the quality is unknown, you have been warned. Nov 12 22:40:27 volumio2 kernel: bcm2835_vc_sm_cma_probe: Videocore shared memory driver Nov 12 22:40:27 volumio2 kernel: [vc_sm_connected_init]: start Nov 12 22:40:27 volumio2 kernel: rpi-gpiomem 3f200000.gpiomem: window base 0x3f200000 size 0x00001000 Nov 12 22:40:28 volumio2 kernel: mc: Linux media interface: v0.10 Nov 12 22:40:28 volumio2 kernel: rpi-gpiomem 3f200000.gpiomem: initialised 1 regions as /dev/gpiomem Nov 12 22:40:28 volumio2 kernel: [vc_sm_connected_init]: installed successfully Nov 12 22:40:28 volumio2 kernel: videodev: Linux video capture interface: v2.00 Nov 12 22:40:28 volumio2 kernel: bcm2835_mmal_vchiq: module is from the staging directory, the quality is unknown, you have been warned. Nov 12 22:40:28 volumio2 kernel: bcm2835_isp: module is from the staging directory, the quality is unknown, you have been warned. Nov 12 22:40:28 volumio2 kernel: bcm2835-isp bcm2835-isp: Device node output[0] registered as /dev/video13 Nov 12 22:40:28 volumio2 kernel: bcm2835-isp bcm2835-isp: Device node capture[0] registered as /dev/video14 Nov 12 22:40:28 volumio2 kernel: bcm2835-isp bcm2835-isp: Device node capture[1] registered as /dev/video15 Nov 12 22:40:28 volumio2 kernel: bcm2835-isp bcm2835-isp: Device node stats[2] registered as /dev/video16 Nov 12 22:40:28 volumio2 kernel: bcm2835-isp bcm2835-isp: Register output node 0 with media controller Nov 12 22:40:28 volumio2 kernel: bcm2835-isp bcm2835-isp: Register capture node 1 with media controller Nov 12 22:40:28 volumio2 kernel: bcm2835-isp bcm2835-isp: Register capture node 2 with media controller Nov 12 22:40:28 volumio2 kernel: bcm2835-isp bcm2835-isp: Register capture node 3 with media controller Nov 12 22:40:28 volumio2 kernel: bcm2835-isp bcm2835-isp: Device node output[0] registered as /dev/video20 Nov 12 22:40:28 volumio2 kernel: bcm2835-isp bcm2835-isp: Device node capture[0] registered as /dev/video21 Nov 12 22:40:28 volumio2 kernel: bcm2835-isp bcm2835-isp: Device node capture[1] registered as /dev/video22 Nov 12 22:40:28 volumio2 kernel: bcm2835-isp bcm2835-isp: Device node stats[2] registered as /dev/video23 Nov 12 22:40:28 volumio2 kernel: bcm2835-isp bcm2835-isp: Register output node 0 with media controller Nov 12 22:40:28 volumio2 kernel: bcm2835-isp bcm2835-isp: Register capture node 1 with media controller Nov 12 22:40:28 volumio2 kernel: bcm2835-isp bcm2835-isp: Register capture node 2 with media controller Nov 12 22:40:28 volumio2 kernel: bcm2835-isp bcm2835-isp: Register capture node 3 with media controller Nov 12 22:40:28 volumio2 kernel: bcm2835-isp bcm2835-isp: Loaded V4L2 bcm2835-isp Nov 12 22:40:28 volumio2 kernel: bcm2835_v4l2: module is from the staging directory, the quality is unknown, you have been warned. Nov 12 22:40:28 volumio2 kernel: bcm2835_codec: module is from the staging directory, the quality is unknown, you have been warned. Nov 12 22:40:28 volumio2 kernel: bcm2835-codec bcm2835-codec: Device registered as /dev/video10 Nov 12 22:40:28 volumio2 kernel: bcm2835-codec bcm2835-codec: Loaded V4L2 decode Nov 12 22:40:28 volumio2 systemd[1]: Found device /dev/disk/by-uuid/2E0A-AE55. Nov 12 22:40:28 volumio2 kernel: bcm2835-codec bcm2835-codec: Device registered as /dev/video11 Nov 12 22:40:28 volumio2 kernel: bcm2835-codec bcm2835-codec: Loaded V4L2 encode Nov 12 22:40:28 volumio2 kernel: bcm2835-codec bcm2835-codec: Device registered as /dev/video12 Nov 12 22:40:28 volumio2 kernel: bcm2835-codec bcm2835-codec: Loaded V4L2 isp Nov 12 22:40:28 volumio2 kernel: bcm2835-codec bcm2835-codec: Device registered as /dev/video18 Nov 12 22:40:28 volumio2 kernel: bcm2835-codec bcm2835-codec: Loaded V4L2 image_fx Nov 12 22:40:28 volumio2 kernel: cfg80211: Loading compiled-in X.509 certificates for regulatory database Nov 12 22:40:28 volumio2 kernel: bcm2835-codec bcm2835-codec: Device registered as /dev/video31 Nov 12 22:40:28 volumio2 kernel: bcm2835-codec bcm2835-codec: Loaded V4L2 encode_image Nov 12 22:40:28 volumio2 kernel: cfg80211: Loaded X.509 cert 'benh@debian.org: 577e021cb980e0e820821ba7b54b4961b8b4fadf' Nov 12 22:40:28 volumio2 kernel: cfg80211: Loaded X.509 cert 'romain.perier@gmail.com: 3abbc6ec146e09d1b6016ab9d6cf71dd233f0328' Nov 12 22:40:28 volumio2 kernel: cfg80211: Loaded X.509 cert 'sforshee: 00b28ddf47aef9cea7' Nov 12 22:40:28 volumio2 kernel: snd_bcm2835: module is from the staging directory, the quality is unknown, you have been warned. Nov 12 22:40:28 volumio2 kernel: snd_bcm2835: unknown parameter 'enable_compat_alsa' ignored Nov 12 22:40:29 volumio2 kernel: bcm2835_audio bcm2835_audio: card created with 4 channels Nov 12 22:40:29 volumio2 kernel: bcm2835_audio bcm2835_audio: card created with 4 channels Nov 12 22:40:29 volumio2 systemd[1]: Starting File System Check on /dev/disk/by-uuid/2E0A-AE55... Nov 12 22:40:29 volumio2 systemd-udevd[351]: Using default interface naming scheme 'v240'. Nov 12 22:40:29 volumio2 systemd[1]: Started File System Check Daemon to report status. Nov 12 22:40:29 volumio2 systemd-udevd[351]: link_config: autonegotiation is unset or enabled, the speed and duplex are not writable. Nov 12 22:40:29 volumio2 kernel: brcmfmac: F1 signature read @0x18000000=0x15264345 Nov 12 22:40:29 volumio2 kernel: Bluetooth: Core ver 2.22 Nov 12 22:40:29 volumio2 kernel: NET: Registered PF_BLUETOOTH protocol family Nov 12 22:40:29 volumio2 kernel: Bluetooth: HCI device and connection manager initialized Nov 12 22:40:29 volumio2 kernel: Bluetooth: HCI socket layer initialized Nov 12 22:40:29 volumio2 kernel: Bluetooth: L2CAP socket layer initialized Nov 12 22:40:29 volumio2 kernel: Bluetooth: SCO socket layer initialized Nov 12 22:40:29 volumio2 kernel: brcmfmac: brcmf_fw_alloc_request: using brcm/brcmfmac43455-sdio for chip BCM4345/6 Nov 12 22:40:29 volumio2 kernel: usbcore: registered new interface driver brcmfmac Nov 12 22:40:29 volumio2 kernel: Bluetooth: HCI UART driver ver 2.3 Nov 12 22:40:29 volumio2 kernel: Bluetooth: HCI UART protocol H4 registered Nov 12 22:40:29 volumio2 kernel: Bluetooth: HCI UART protocol Three-wire (H5) registered Nov 12 22:40:29 volumio2 kernel: Bluetooth: HCI UART protocol Broadcom registered Nov 12 22:40:29 volumio2 kernel: hci_uart_bcm serial0-0: supply vbat not found, using dummy regulator Nov 12 22:40:29 volumio2 kernel: hci_uart_bcm serial0-0: supply vddio not found, using dummy regulator Nov 12 22:40:29 volumio2 systemd-fsck[414]: fsck.fat 4.1 (2017-01-24) Nov 12 22:40:29 volumio2 systemd-fsck[414]: 0x25: Dirty bit is set. Fs was not properly unmounted and some data may be corrupt. Nov 12 22:40:29 volumio2 systemd-fsck[414]: Automatically removing dirty bit. Nov 12 22:40:29 volumio2 systemd-fsck[414]: Performing changes. Nov 12 22:40:29 volumio2 systemd-fsck[414]: /dev/mmcblk0p1: 370 files, 33697/46774 clusters Nov 12 22:40:29 volumio2 systemd[1]: Started File System Check on /dev/disk/by-uuid/2E0A-AE55. Nov 12 22:40:29 volumio2 kernel: uart-pl011 3f201000.serial: no DMA platform data Nov 12 22:40:29 volumio2 systemd[1]: Mounting /boot... Nov 12 22:40:29 volumio2 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 Nov 12 22:40:29 volumio2 systemd-udevd[353]: link_config: autonegotiation is unset or enabled, the speed and duplex are not writable. Nov 12 22:40:29 volumio2 systemd[1]: Mounted /boot. Nov 12 22:40:29 volumio2 kernel: Bluetooth: hci0: BCM: chip id 107 Nov 12 22:40:29 volumio2 kernel: Bluetooth: hci0: BCM: features 0x2f Nov 12 22:40:29 volumio2 kernel: Bluetooth: hci0: BCM4345C0 Nov 12 22:40:29 volumio2 kernel: Bluetooth: hci0: BCM4345C0 (003.001.025) build 0000 Nov 12 22:40:29 volumio2 kernel: Bluetooth: hci0: BCM4345C0 'brcm/BCM4345C0.hcd' Patch Nov 12 22:40:30 volumio2 kernel: usbcore: registered new interface driver snd-usb-audio Nov 12 22:40:30 volumio2 systemd-udevd[354]: Using default interface naming scheme 'v240'. Nov 12 22:40:30 volumio2 systemd-udevd[354]: link_config: autonegotiation is unset or enabled, the speed and duplex are not writable. Nov 12 22:40:30 volumio2 kernel: Bluetooth: hci0: BCM: features 0x2f Nov 12 22:40:30 volumio2 kernel: Bluetooth: hci0: BCM43455 37.4MHz Raspberry Pi 3+ Nov 12 22:40:30 volumio2 kernel: Bluetooth: hci0: BCM4345C0 (003.001.025) build 0342 Nov 12 22:40:30 volumio2 kernel: Bluetooth: hci0: BCM: Using default device address (43:45:c0:00:1f:ac) Nov 12 22:40:31 volumio2 systemd-udevd[352]: Process '/bin/bash -c '/usr/local/bin/volumio usbattach'' failed with exit code 7. Nov 12 22:40:31 volumio2 systemd[1]: Condition check resulted in 7800 being skipped. Nov 12 22:40:31 volumio2 systemd[1]: Created slice system-bthelper.slice. Nov 12 22:40:31 volumio2 systemd[1]: Starting Show Plymouth Boot Screen... Nov 12 22:40:31 volumio2 systemd[1]: Condition check resulted in Rebuild Hardware Database being skipped. Nov 12 22:40:31 volumio2 systemd[1]: Condition check resulted in Huge Pages File System being skipped. Nov 12 22:40:31 volumio2 systemd[1]: Condition check resulted in Set Up Additional Binary Formats being skipped. Nov 12 22:40:31 volumio2 systemd[1]: Listening on Load/Save RF Kill Switch Status /dev/rfkill Watch. Nov 12 22:40:31 volumio2 systemd[1]: Reached target Local File Systems. Nov 12 22:40:31 volumio2 systemd[1]: Starting Preprocess NFS configuration... Nov 12 22:40:31 volumio2 systemd[1]: Started ifup for eth0. Nov 12 22:40:31 volumio2 systemd[1]: Starting Raise network interfaces... Nov 12 22:40:31 volumio2 systemd[1]: Condition check resulted in Commit a transient machine-id on disk being skipped. Nov 12 22:40:31 volumio2 systemd[1]: Starting Create Volatile Files and Directories... Nov 12 22:40:31 volumio2 systemd[1]: Starting Tell Plymouth To Write Out Runtime Data... Nov 12 22:40:31 volumio2 systemd[1]: Found device /sys/subsystem/net/devices/wlan0. Nov 12 22:40:31 volumio2 systemd[1]: nfs-config.service: Succeeded. Nov 12 22:40:31 volumio2 systemd[1]: Started Preprocess NFS configuration. Nov 12 22:40:31 volumio2 systemd[1]: plymouth-read-write.service: Succeeded. Nov 12 22:40:31 volumio2 systemd[1]: Started Tell Plymouth To Write Out Runtime Data. Nov 12 22:40:31 volumio2 systemd[1]: plymouth-start.service: Succeeded. Nov 12 22:40:31 volumio2 systemd[1]: Started Show Plymouth Boot Screen. Nov 12 22:40:31 volumio2 systemd[1]: Received SIGRTMIN+20 from PID 195 (plymouthd). Nov 12 22:40:31 volumio2 systemd[1]: Starting Load/Save RF Kill Switch Status... Nov 12 22:40:31 volumio2 systemd[1]: Condition check resulted in Dispatch Password Requests to Console Directory Watch being skipped. Nov 12 22:40:31 volumio2 systemd[1]: Condition check resulted in RPC security service for NFS client and server being skipped. Nov 12 22:40:31 volumio2 systemd[1]: Condition check resulted in RPC security service for NFS server being skipped. Nov 12 22:40:31 volumio2 systemd[1]: Reached target NFS client services. Nov 12 22:40:31 volumio2 systemd[1]: Started ifup for wlan0. Nov 12 22:40:31 volumio2 systemd[1]: Started Create Volatile Files and Directories. Nov 12 22:40:31 volumio2 systemd[1]: Started Entropy daemon using the HAVEGE algorithm. Nov 12 22:40:31 volumio2 systemd[1]: Starting RPC bind portmap service... Nov 12 22:40:31 volumio2 systemd[1]: Starting Update UTMP about System Boot/Shutdown... Nov 12 22:40:31 volumio2 systemd[1]: Condition check resulted in Network Time Synchronization being skipped. Nov 12 22:40:32 volumio2 systemd[1]: Started Load/Save RF Kill Switch Status. Nov 12 22:40:32 volumio2 kernel: 8021q: 802.1Q VLAN Support v1.8 Nov 12 22:40:32 volumio2 systemd[1]: Started RPC bind portmap service. Nov 12 22:40:32 volumio2 systemd[1]: Started Update UTMP about System Boot/Shutdown. Nov 12 22:40:32 volumio2 systemd[1]: Reached target System Initialization. Nov 12 22:40:32 volumio2 systemd[1]: Listening on Avahi mDNS/DNS-SD Stack Activation Socket. Nov 12 22:40:32 volumio2 systemd[1]: Listening on triggerhappy.socket. Nov 12 22:40:32 volumio2 systemd[1]: apt-daily.timer: Not using persistent file timestamp Sat 2024-11-16 21:54:43 WET as it is in the future. Nov 12 22:40:32 volumio2 systemd[1]: Started Daily apt download activities. Nov 12 22:40:32 volumio2 systemd[1]: Started Daily Cleanup of Temporary Directories. Nov 12 22:40:32 volumio2 systemd[1]: apt-daily-upgrade.timer: Not using persistent file timestamp Sat 2024-11-16 21:54:43 WET as it is in the future. Nov 12 22:40:32 volumio2 systemd[1]: Started Daily apt upgrade and clean activities. Nov 12 22:40:32 volumio2 systemd[1]: Reached target Timers. Nov 12 22:40:32 volumio2 systemd[1]: Listening on D-Bus System Message Bus Socket. Nov 12 22:40:32 volumio2 systemd[1]: Reached target Sockets. Nov 12 22:40:32 volumio2 systemd[1]: Reached target Basic System. Nov 12 22:40:32 volumio2 kernel: brcmfmac: brcmf_cfg80211_set_power_mgmt: power save disabled Nov 12 22:40:32 volumio2 systemd[1]: Starting Configure Bluetooth Modems connected by UART... Nov 12 22:40:32 volumio2 systemd[1]: Started Volumio Log Rotation Service. Nov 12 22:40:32 volumio2 systemd[1]: Starting Wireless Services... Nov 12 22:40:32 volumio2 systemd[1]: Condition check resulted in Volumio SSH enabler being skipped. Nov 12 22:40:32 volumio2 systemd[1]: Starting triggerhappy global hotkey daemon... Nov 12 22:40:32 volumio2 systemd[1]: Condition check resulted in getty on tty2-tty6 if dbus and logind are not available being skipped. Nov 12 22:40:32 volumio2 systemd[1]: Started volumio-remote-updater.service. Nov 12 22:40:32 volumio2 systemd[1]: Condition check resulted in Copy user wpa_supplicant.conf being skipped. Nov 12 22:40:32 volumio2 systemd[1]: Starting dhcpcd on all interfaces... Nov 12 22:40:32 volumio2 thd[597]: Unable to parse trigger line: Nov 12 22:40:32 volumio2 thd[597]: Unable to parse trigger line: KEY_MIN_INTERESTING 1 /usr/local/bin/volumio volume toggle Nov 12 22:40:32 volumio2 thd[597]: Unable to parse trigger line: Nov 12 22:40:32 volumio2 thd[597]: Found socket passed from systemd Nov 12 22:40:32 volumio2 systemd[1]: Started Manage Sound Card State (restore and store). Nov 12 22:40:32 volumio2 systemd[1]: Starting Save/Restore Sound Card State... Nov 12 22:40:32 volumio2 systemd[1]: Started UPnP Renderer front-end to MPD. Nov 12 22:40:32 volumio2 alsactl[610]: alsactl 1.1.8 daemon started Nov 12 22:40:32 volumio2 dhcpcd[606]: Not running dhcpcd because /etc/network/interfaces Nov 12 22:40:32 volumio2 dhcpcd[606]: defines some interfaces that will use a Nov 12 22:40:32 volumio2 dhcpcd[606]: DHCP client or static address Nov 12 22:40:32 volumio2 systemd[1]: Started Volumio Iptables Module. Nov 12 22:40:32 volumio2 sh[498]: eth0: waiting for carrier Nov 12 22:40:32 volumio2 kernel: lan78xx 1-1.1.1:1.0 eth0: kevent 4 may have been dropped Nov 12 22:40:32 volumio2 kernel: lan78xx 1-1.1.1:1.0 eth0: kevent 4 may have been dropped Nov 12 22:40:32 volumio2 kernel: lan78xx 1-1.1.1:1.0 eth0: kevent 4 may have been dropped Nov 12 22:40:32 volumio2 kernel: 8021q: adding VLAN 0 to HW filter on device eth0 Nov 12 22:40:32 volumio2 kernel: lan78xx 1-1.1.1:1.0 eth0: Link is Up - 1Gbps/Full - flow control rx/tx Nov 12 22:40:32 volumio2 dhcpcd[531]: eth0: waiting for carrier Nov 12 22:40:32 volumio2 dhcpcd[531]: eth0: carrier acquired Nov 12 22:40:32 volumio2 sh[498]: eth0: carrier acquired Nov 12 22:40:32 volumio2 systemd[1]: Started D-Bus System Message Bus. Nov 12 22:40:32 volumio2 sh[498]: DUID 00:01:00:01:2c:c5:40:e6:b8:27:eb:7a:73:1b Nov 12 22:40:32 volumio2 dhcpcd[531]: DUID 00:01:00:01:2c:c5:40:e6:b8:27:eb:7a:73:1b Nov 12 22:40:32 volumio2 sh[498]: eth0: IAID eb:7a:73:1b Nov 12 22:40:32 volumio2 dhcpcd[531]: eth0: IAID eb:7a:73:1b Nov 12 22:40:32 volumio2 sh[498]: eth0: adding address fe80::be1b:e1ee:fe95:68e8 Nov 12 22:40:32 volumio2 sh[498]: ipv6_addaddr1: Permission denied Nov 12 22:40:32 volumio2 dhcpcd[531]: eth0: adding address fe80::be1b:e1ee:fe95:68e8 Nov 12 22:40:32 volumio2 dhcpcd[531]: ipv6_addaddr1: Permission denied Nov 12 22:40:32 volumio2 alsactl[616]: /usr/sbin/alsactl: set_control:1461: Cannot write control '2:0:0:Cambridge AudioDAC100 USB 2 Playback Switch:1' : Operation not permitted Nov 12 22:40:32 volumio2 systemd[1]: Starting WPA supplicant... Nov 12 22:40:32 volumio2 alsactl[610]: /usr/sbin/alsactl: set_control:1461Cannot write control '2:0:0:Cambridge AudioDAC100 USB 2 Playback Switch:1' : Operation not permitted Nov 12 22:40:32 volumio2 systemd[1]: Starting Avahi mDNS/DNS-SD Stack... Nov 12 22:40:32 volumio2 systemd[1]: Starting Login Service... Nov 12 22:40:32 volumio2 systemd[1]: Reached target Remote File Systems (Pre). Nov 12 22:40:32 volumio2 systemd[1]: Reached target Remote File Systems. Nov 12 22:40:32 volumio2 systemd[1]: Starting LSB: Load kernel modules needed to enable cpufreq scaling... Nov 12 22:40:32 volumio2 systemd[1]: Reached target RPC Port Mapper. Nov 12 22:40:32 volumio2 systemd[1]: Started triggerhappy global hotkey daemon. Nov 12 22:40:32 volumio2 systemd[1]: hciuart.service: Succeeded. Nov 12 22:40:32 volumio2 systemd[1]: Started Configure Bluetooth Modems connected by UART. Nov 12 22:40:32 volumio2 systemd[1]: dhcpcd.service: Control process exited, code=exited, status=6/NOTCONFIGURED Nov 12 22:40:32 volumio2 systemd[1]: dhcpcd.service: Failed with result 'exit-code'. Nov 12 22:40:32 volumio2 systemd[1]: Failed to start dhcpcd on all interfaces. Nov 12 22:40:32 volumio2 systemd[1]: Started Save/Restore Sound Card State. Nov 12 22:40:32 volumio2 sh[498]: eth0: soliciting an IPv6 router Nov 12 22:40:32 volumio2 dhcpcd[531]: eth0: soliciting an IPv6 router Nov 12 22:40:32 volumio2 systemd[1]: Reached target Sound Card. Nov 12 22:40:32 volumio2 sh[498]: eth0: rebinding lease of 192.168.1.92 Nov 12 22:40:32 volumio2 dhcpcd[531]: eth0: rebinding lease of 192.168.1.92 Nov 12 22:40:33 volumio2 sh[539]: wlan0=wlan0 Nov 12 22:40:33 volumio2 systemd[1]: Starting Raspberry Pi bluetooth helper... Nov 12 22:40:33 volumio2 sh[498]: eth0: NAK: from 192.168.1.1 Nov 12 22:40:33 volumio2 dhcpcd[531]: eth0: NAK: from 192.168.1.1 Nov 12 22:40:33 volumio2 avahi-daemon[656]: Found user 'avahi' (UID 110) and group 'avahi' (GID 113). Nov 12 22:40:33 volumio2 avahi-daemon[656]: Successfully dropped root privileges. Nov 12 22:40:33 volumio2 avahi-daemon[656]: avahi-daemon 0.7 starting up. Nov 12 22:40:33 volumio2 systemd-logind[657]: New seat seat0. Nov 12 22:40:33 volumio2 sh[498]: eth0: soliciting a DHCP lease Nov 12 22:40:33 volumio2 dhcpcd[531]: eth0: soliciting a DHCP lease Nov 12 22:40:33 volumio2 volumio-remote-updater[603]: Error: No active session Nov 12 22:40:33 volumio2 volumio-remote-updater[603]: [2024-11-12 22:40:33] [info] asio async_connect error: system:111 (Connection refused) Nov 12 22:40:33 volumio2 volumio-remote-updater[603]: [2024-11-12 22:40:33] [info] Error getting remote endpoint: system:107 (Transport endpoint is not connected) Nov 12 22:40:33 volumio2 volumio-remote-updater[603]: [2024-11-12 22:40:33] [error] handle_connect error: Underlying Transport Error Nov 12 22:40:33 volumio2 bthelper[665]: Raspberry Pi BDADDR already set Nov 12 22:40:33 volumio2 systemd[1]: Started Raise network interfaces. Nov 12 22:40:33 volumio2 systemd[1]: Started Raspberry Pi bluetooth helper. Nov 12 22:40:33 volumio2 systemd[1]: Started Login Service. Nov 12 22:40:33 volumio2 systemd[1]: Started WPA supplicant. Nov 12 22:40:33 volumio2 wpa_supplicant[652]: Successfully initialized wpa_supplicant Nov 12 22:40:33 volumio2 avahi-daemon[656]: Successfully called chroot(). Nov 12 22:40:33 volumio2 avahi-daemon[656]: Successfully dropped remaining capabilities. Nov 12 22:40:33 volumio2 avahi-daemon[656]: Loading service file /services/volumio.service. Nov 12 22:40:33 volumio2 systemd[1]: Started Avahi mDNS/DNS-SD Stack. Nov 12 22:40:33 volumio2 avahi-daemon[656]: Network interface enumeration completed. Nov 12 22:40:33 volumio2 avahi-daemon[656]: Server startup complete. Host name is volumio2.local. Local service cookie is 2007843380. Nov 12 22:40:33 volumio2 avahi-daemon[656]: Service "Volumio2" (/services/volumio.service) successfully established. Nov 12 22:40:33 volumio2 volumio[619]: Could not open config: /tmp/upmpdcli.conf Nov 12 22:40:33 volumio2 systemd[1]: Starting Bluetooth service... Nov 12 22:40:33 volumio2 systemd[1]: Reached target Network. Nov 12 22:40:33 volumio2 systemd[1]: Starting Permit User Sessions... Nov 12 22:40:33 volumio2 systemd[1]: Condition check resulted in fast remote file copy program daemon being skipped. Nov 12 22:40:33 volumio2 systemd[1]: Reached target Network is Online. Nov 12 22:40:33 volumio2 systemd[1]: Starting LSB: Brings up/down network automatically... Nov 12 22:40:33 volumio2 systemd[1]: Starting /etc/rc.local Compatibility... Nov 12 22:40:33 volumio2 systemd[1]: Starting Samba NMB Daemon... Nov 12 22:40:33 volumio2 systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Nov 12 22:40:33 volumio2 systemd[1]: Starting Network Time Service... Nov 12 22:40:33 volumio2 systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Nov 12 22:40:33 volumio2 systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Nov 12 22:40:33 volumio2 systemd[1]: Started Permit User Sessions. Nov 12 22:40:33 volumio2 systemd[1]: Started /etc/rc.local Compatibility. Nov 12 22:40:33 volumio2 systemd[1]: Starting Terminate Plymouth Boot Screen... Nov 12 22:40:34 volumio2 systemd[1]: Starting Hold until boot process finishes up... Nov 12 22:40:34 volumio2 loadcpufreq[658]: Loading cpufreq kernel modules...done (none). Nov 12 22:40:34 volumio2 bluetoothd[717]: Bluetooth daemon 5.50 Nov 12 22:40:34 volumio2 systemd[1]: Started LSB: Load kernel modules needed to enable cpufreq scaling. Nov 12 22:40:34 volumio2 systemd[1]: Received SIGRTMIN+21 from PID 195 (plymouthd). Nov 12 22:40:34 volumio2 systemd[1]: plymouth-quit.service: Succeeded. Nov 12 22:40:34 volumio2 systemd[1]: Started Terminate Plymouth Boot Screen. Nov 12 22:40:34 volumio2 systemd[1]: plymouth-quit-wait.service: Succeeded. Nov 12 22:40:34 volumio2 systemd[1]: Started Hold until boot process finishes up. Nov 12 22:40:34 volumio2 systemd[1]: Received SIGRTMIN+21 from PID 195 (n/a). Nov 12 22:40:34 volumio2 bluetoothd[717]: Unknown key AutoConnectTimeout for group General in /etc/bluetooth/main.conf Nov 12 22:40:34 volumio2 systemd[1]: Started Getty on tty1. Nov 12 22:40:34 volumio2 systemd[1]: Reached target Login Prompts. Nov 12 22:40:34 volumio2 systemd[1]: Starting LSB: set CPUFreq kernel parameters... Nov 12 22:40:34 volumio2 systemd[1]: Started Bluetooth service. Nov 12 22:40:34 volumio2 systemd[1]: Reached target Bluetooth. Nov 12 22:40:34 volumio2 bluetoothd[717]: Starting SDP server Nov 12 22:40:34 volumio2 bluetoothd[717]: Excluding (cli) sap Nov 12 22:40:34 volumio2 ifplugd(eth0)[775]: ifplugd 0.28 initializing. Nov 12 22:40:34 volumio2 ifplugd(eth0)[775]: Using interface eth0/B8:27:EB:7A:73:1B with driver (version: 6.1.69-v7+) Nov 12 22:40:34 volumio2 ifplugd(eth0)[775]: Using detection mode: SIOCETHTOOL Nov 12 22:40:34 volumio2 ifplugd(eth0)[775]: Initialization complete, link beat detected. Nov 12 22:40:34 volumio2 ntpd[731]: ntpd 4.2.8p12@1.3728-o (1): Starting Nov 12 22:40:34 volumio2 ntpd[731]: Command line: /usr/sbin/ntpd -p /var/run/ntpd.pid -g -u 103:103 Nov 12 22:40:34 volumio2 ifplugd(eth0)[775]: Executing '/etc/ifplugd/ifplugd.action eth0 up'. Nov 12 22:40:34 volumio2 ntpd[779]: proto: precision = 1.458 usec (-19) Nov 12 22:40:34 volumio2 kernel: Bluetooth: BNEP (Ethernet Emulation) ver 1.3 Nov 12 22:40:34 volumio2 kernel: Bluetooth: BNEP filters: protocol multicast Nov 12 22:40:34 volumio2 kernel: Bluetooth: BNEP socket layer initialized Nov 12 22:40:34 volumio2 bluetoothd[717]: Bluetooth management interface 1.22 initialized Nov 12 22:40:34 volumio2 kernel: Bluetooth: MGMT ver 1.22 Nov 12 22:40:34 volumio2 dbus-daemon[632]: [system] Activating via systemd: service name='org.freedesktop.hostname1' unit='dbus-org.freedesktop.hostname1.service' requested by ':1.4' (uid=0 pid=717 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap ") Nov 12 22:40:34 volumio2 systemd[1]: Started Network Time Service. Nov 12 22:40:34 volumio2 ntpd[779]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): good hash signature Nov 12 22:40:34 volumio2 ntpd[779]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): loaded, expire=2024-12-28T00:00:00Z last=2017-01-01T00:00:00Z ofs=37 Nov 12 22:40:34 volumio2 ntpd[779]: Listen and drop on 0 v6wildcard [::]:123 Nov 12 22:40:34 volumio2 ntpd[779]: Listen and drop on 1 v4wildcard 0.0.0.0:123 Nov 12 22:40:34 volumio2 ntpd[779]: Listen normally on 2 lo 127.0.0.1:123 Nov 12 22:40:34 volumio2 ntpd[779]: Listening on routing socket on fd #19 for interface updates Nov 12 22:40:34 volumio2 ntpd[779]: kernel reports TIME_ERROR: 0x41: Clock Unsynchronized Nov 12 22:40:34 volumio2 ntpd[779]: kernel reports TIME_ERROR: 0x41: Clock Unsynchronized Nov 12 22:40:34 volumio2 systemd[1]: iptables.service: Succeeded. Nov 12 22:40:34 volumio2 ifplugd(eth0)[775]: client: ifup: waiting for lock on /run/network/ifstate.eth0 Nov 12 22:40:34 volumio2 bluetoothd[717]: Failed to set privacy: Rejected (0x0b) Nov 12 22:40:34 volumio2 cpufrequtils[766]: CPUFreq Utilities: Setting ondemand CPUFreq governor...CPU0...CPU1...CPU2...CPU3...done. Nov 12 22:40:34 volumio2 systemd[1]: Started LSB: set CPUFreq kernel parameters. Nov 12 22:40:34 volumio2 systemd[1]: Starting Hostname Service... Nov 12 22:40:35 volumio2 haveged[544]: haveged: ver: 1.9.1; arch: generic; vend: ; build: (gcc 8.2.0 CTV); collect: 128K Nov 12 22:40:35 volumio2 haveged[544]: haveged: cpu: (VC); data: 16K (D); inst: 16K (D); idx: 11/40; sz: 14768/63488 Nov 12 22:40:35 volumio2 haveged[544]: haveged: tot tests(BA8): A:1/1 B:1/1 continuous tests(B): last entropy estimate 8 Nov 12 22:40:35 volumio2 haveged[544]: haveged: fills: 0, generated: 0 Nov 12 22:40:35 volumio2 dbus-daemon[632]: [system] Successfully activated service 'org.freedesktop.hostname1' Nov 12 22:40:35 volumio2 systemd[1]: Started Hostname Service. Nov 12 22:40:35 volumio2 sh[498]: eth0: offered 192.168.1.92 from 192.168.1.1 Nov 12 22:40:35 volumio2 dhcpcd[531]: eth0: offered 192.168.1.92 from 192.168.1.1 Nov 12 22:40:35 volumio2 sh[498]: eth0: probing address 192.168.1.92/24 Nov 12 22:40:35 volumio2 dhcpcd[531]: eth0: probing address 192.168.1.92/24 Nov 12 22:40:35 volumio2 nmbd[743]: [2024/11/12 22:40:35.428205, 0] ../source3/nmbd/asyncdns.c:158(start_async_dns) Nov 12 22:40:35 volumio2 nmbd[743]: started asyncdns process 805 Nov 12 22:40:35 volumio2 nmbd[743]: [2024/11/12 22:40:35.430675, 0] ../lib/util/become_daemon.c:149(daemon_status) Nov 12 22:40:35 volumio2 nmbd[743]: daemon_status: STATUS=daemon 'nmbd' : No local IPv4 non-loopback interfaces available, waiting for interface ... Nov 12 22:40:35 volumio2 nmbd[743]: [2024/11/12 22:40:35.430851, 0] ../source3/nmbd/nmbd_subnetdb.c:254(create_subnets) Nov 12 22:40:35 volumio2 nmbd[743]: NOTE: NetBIOS name resolution is not supported for Internet Protocol Version 6 (IPv6). Nov 12 22:40:35 volumio2 ntpd[779]: error resolving pool 0.debian.pool.ntp.org: System error (-11) Nov 12 22:40:35 volumio2 wireless.js[590]: Cleaning previous... Nov 12 22:40:36 volumio2 sudo[813]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ip addr flush dev wlan0 Nov 12 22:40:36 volumio2 sudo[813]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 12 22:40:36 volumio2 sudo[813]: pam_unix(sudo:session): session closed for user root Nov 12 22:40:36 volumio2 sudo[815]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 down Nov 12 22:40:36 volumio2 sudo[815]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 12 22:40:36 volumio2 ntpd[779]: error resolving pool 1.debian.pool.ntp.org: System error (-11) Nov 12 22:40:36 volumio2 sudo[815]: pam_unix(sudo:session): session closed for user root Nov 12 22:40:36 volumio2 wireless.js[590]: Stopped aP Nov 12 22:40:36 volumio2 sudo[823]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 up Nov 12 22:40:36 volumio2 sudo[823]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 12 22:40:36 volumio2 sudo[823]: pam_unix(sudo:session): session closed for user root Nov 12 22:40:36 volumio2 kernel: brcmfmac: brcmf_cfg80211_set_power_mgmt: power save disabled Nov 12 22:40:36 volumio2 sudo[825]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iw reg get Nov 12 22:40:36 volumio2 sudo[825]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 12 22:40:36 volumio2 sudo[825]: pam_unix(sudo:session): session closed for user root Nov 12 22:40:36 volumio2 sudo[832]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 up Nov 12 22:40:36 volumio2 sudo[832]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 12 22:40:36 volumio2 sudo[832]: pam_unix(sudo:session): session closed for user root Nov 12 22:40:36 volumio2 sudo[834]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iw wlan0 scan Nov 12 22:40:36 volumio2 sudo[834]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 12 22:40:37 volumio2 systemd[1]: systemd-rfkill.service: Succeeded. Nov 12 22:40:37 volumio2 ntpd[779]: error resolving pool 2.debian.pool.ntp.org: System error (-11) Nov 12 22:40:38 volumio2 volumio-remote-updater[603]: [2024-11-12 22:40:38] [info] asio async_connect error: system:111 (Connection refused) Nov 12 22:40:38 volumio2 volumio-remote-updater[603]: [2024-11-12 22:40:38] [info] Error getting remote endpoint: system:107 (Transport endpoint is not connected) Nov 12 22:40:38 volumio2 volumio-remote-updater[603]: [2024-11-12 22:40:38] [error] handle_connect error: Underlying Transport Error Nov 12 22:40:38 volumio2 ntpd[779]: error resolving pool 3.debian.pool.ntp.org: System error (-11) Nov 12 22:40:38 volumio2 bthelper[665]: Changing power off succeeded Nov 12 22:40:38 volumio2 bthelper[665]: [CHG] Controller B8:27:EB:D0:D9:B1 Class: 0x0000041c Nov 12 22:40:38 volumio2 bthelper[665]: Changing power on succeeded Nov 12 22:40:39 volumio2 sudo[834]: pam_unix(sudo:session): session closed for user root Nov 12 22:40:39 volumio2 wireless.js[590]: SETTING APPROPRIATE REG DOMAIN: PT Nov 12 22:40:39 volumio2 sudo[846]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 up Nov 12 22:40:39 volumio2 sudo[846]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 12 22:40:39 volumio2 sudo[846]: pam_unix(sudo:session): session closed for user root Nov 12 22:40:39 volumio2 sudo[848]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iw reg set PT Nov 12 22:40:39 volumio2 sudo[848]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 12 22:40:39 volumio2 sudo[848]: pam_unix(sudo:session): session closed for user root Nov 12 22:40:39 volumio2 wireless.js[590]: SUCCESSFULLY SET NEW REGDOMAIN: PT Nov 12 22:40:39 volumio2 sudo[855]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ip addr flush dev wlan0 Nov 12 22:40:39 volumio2 sudo[855]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 12 22:40:39 volumio2 sudo[855]: pam_unix(sudo:session): session closed for user root Nov 12 22:40:39 volumio2 sudo[857]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 down Nov 12 22:40:39 volumio2 sudo[857]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 12 22:40:39 volumio2 sh[498]: eth0: leased 192.168.1.92 for 3600 seconds Nov 12 22:40:39 volumio2 dhcpcd[531]: eth0: leased 192.168.1.92 for 3600 seconds Nov 12 22:40:40 volumio2 avahi-daemon[656]: Joining mDNS multicast group on interface eth0.IPv4 with address 192.168.1.92. Nov 12 22:40:40 volumio2 sh[498]: eth0: adding route to 192.168.1.0/24 Nov 12 22:40:40 volumio2 sh[498]: eth0: adding default route via 192.168.1.1 Nov 12 22:40:40 volumio2 avahi-daemon[656]: New relevant interface eth0.IPv4 for mDNS. Nov 12 22:40:40 volumio2 avahi-daemon[656]: Registering new address record for 192.168.1.92 on eth0.IPv4. Nov 12 22:40:40 volumio2 dhcpcd[531]: eth0: adding route to 192.168.1.0/24 Nov 12 22:40:40 volumio2 dhcpcd[531]: eth0: adding default route via 192.168.1.1 Nov 12 22:40:40 volumio2 sudo[857]: pam_unix(sudo:session): session closed for user root Nov 12 22:40:40 volumio2 avahi-daemon[656]: Joining mDNS multicast group on interface wlan0.IPv4 with address 192.168.211.1. Nov 12 22:40:40 volumio2 kernel: brcmfmac: brcmf_cfg80211_set_power_mgmt: power save disabled Nov 12 22:40:40 volumio2 avahi-daemon[656]: New relevant interface wlan0.IPv4 for mDNS. Nov 12 22:40:40 volumio2 avahi-daemon[656]: Registering new address record for 192.168.211.1 on wlan0.IPv4. Nov 12 22:40:40 volumio2 sh[498]: forked to background, child pid 885 Nov 12 22:40:40 volumio2 dhcpcd[531]: forked to background, child pid 885 Nov 12 22:40:40 volumio2 systemd[1]: Starting Advanced IEEE 802.11 AP and IEEE 802.1X/WPA/WPA2/EAP Authenticator... Nov 12 22:40:40 volumio2 systemd[1]: Starting dnsmasq - A lightweight DHCP and caching DNS server... Nov 12 22:40:40 volumio2 dnsmasq[893]: dnsmasq: syntax check OK. Nov 12 22:40:40 volumio2 hostapd[886]: Configuration file: /etc/hostapd/hostapd.conf Nov 12 22:40:40 volumio2 hostapd[886]: wlan0: Could not connect to kernel driver Nov 12 22:40:40 volumio2 hostapd[886]: Using interface wlan0 with hwaddr b8:27:eb:2f:26:4e and ssid "Volumio-7982D" Nov 12 22:40:40 volumio2 nmbd[743]: [2024/11/12 22:40:40.436669, 0] ../lib/util/become_daemon.c:138(daemon_ready) Nov 12 22:40:40 volumio2 nmbd[743]: daemon_ready: STATUS=daemon 'nmbd' finished starting up and ready to serve connections Nov 12 22:40:40 volumio2 ifplugd(eth0)[775]: client: ifup: interface eth0 already configured Nov 12 22:40:40 volumio2 sh[498]: eth0=eth0 Nov 12 22:40:40 volumio2 systemd[1]: Started Samba NMB Daemon. Nov 12 22:40:40 volumio2 nmbd[743]: [2024/11/12 22:40:40.459700, 0] ../source3/nmbd/nmbd_namequery.c:109(query_name_response) Nov 12 22:40:40 volumio2 nmbd[743]: query_name_response: Multiple (2) responses received for a query on subnet 192.168.1.92 for name WORKGROUP<1d>. Nov 12 22:40:40 volumio2 nmbd[743]: This response was from IP 192.168.1.158, reporting an IP address of 192.168.1.158. Nov 12 22:40:40 volumio2 dnsmasq[920]: started, version 2.80 cachesize 150 Nov 12 22:40:40 volumio2 dnsmasq[920]: compile time options: IPv6 GNU-getopt DBus i18n IDN DHCP DHCPv6 no-Lua TFTP conntrack ipset auth DNSSEC loop-detect inotify dumpfile Nov 12 22:40:40 volumio2 hostapd[886]: wlan0: interface state UNINITIALIZED->ENABLED Nov 12 22:40:40 volumio2 hostapd[886]: wlan0: AP-ENABLED Nov 12 22:40:40 volumio2 dnsmasq-dhcp[920]: DHCP, IP range 192.168.211.100 -- 192.168.211.200, lease time 1d Nov 12 22:40:40 volumio2 systemd[1]: Starting Samba Winbind Daemon... Nov 12 22:40:40 volumio2 dnsmasq[920]: reading /etc/resolv.conf Nov 12 22:40:40 volumio2 dnsmasq[920]: using nameserver 192.168.1.1#53 Nov 12 22:40:40 volumio2 dnsmasq[920]: using nameserver 208.67.222.222#53 Nov 12 22:40:40 volumio2 dnsmasq[920]: using nameserver 208.67.220.220#53 Nov 12 22:40:40 volumio2 systemd[1]: Started Advanced IEEE 802.11 AP and IEEE 802.1X/WPA/WPA2/EAP Authenticator. Nov 12 22:40:40 volumio2 dnsmasq[920]: read /etc/hosts - 1 addresses Nov 12 22:40:40 volumio2 ifplugd(eth0)[775]: Program executed successfully. Nov 12 22:40:40 volumio2 ifplugd[724]: Network Interface Plugging Daemon...start eth0...done. Nov 12 22:40:40 volumio2 systemd[1]: Started LSB: Brings up/down network automatically. Nov 12 22:40:40 volumio2 iwconfig[926]: Error for wireless request "Set Power Management" (8B2C) : Nov 12 22:40:40 volumio2 iwconfig[926]: SET failed on device wlan0 ; Invalid argument. Nov 12 22:40:40 volumio2 systemd[1]: wireless.service: Succeeded. Nov 12 22:40:40 volumio2 systemd[1]: Started Wireless Services. Nov 12 22:40:40 volumio2 systemd[1]: Started dnsmasq - A lightweight DHCP and caching DNS server. Nov 12 22:40:40 volumio2 systemd[1]: Reached target Host and Network Name Lookups. Nov 12 22:40:40 volumio2 systemd[1]: Started Volumio Backend Module. Nov 12 22:40:40 volumio2 systemd[1]: Started Volumio Cpu Tweaker. Nov 12 22:40:40 volumio2 volumio-cpu-tweak[930]: Setting RT Priority for mpd Nov 12 22:40:40 volumio2 volumio-cpu-tweak[930]: pid 35's current scheduling policy: SCHED_OTHER Nov 12 22:40:40 volumio2 volumio-cpu-tweak[930]: pid 35's current scheduling priority: 0 Nov 12 22:40:40 volumio2 volumio-cpu-tweak[930]: Setting MPD Affinity Nov 12 22:40:40 volumio2 volumio-cpu-tweak[930]: pid 3's current affinity mask: f Nov 12 22:40:40 volumio2 volumio-cpu-tweak[930]: /bin/volumio_cpu_tweak: line 27: warning: command substitution: ignored null byte in input Nov 12 22:40:40 volumio2 volumio-cpu-tweak[930]: VOLUMIO CPU TWEAK: Setting CPU Governor: performance Nov 12 22:40:40 volumio2 systemd[1]: volumio_cpu_tweak.service: Succeeded. Nov 12 22:40:40 volumio2 winbindd[918]: [2024/11/12 22:40:40.887192, 0] ../source3/winbindd/winbindd_cache.c:3160(initialize_winbindd_cache) Nov 12 22:40:40 volumio2 winbindd[918]: initialize_winbindd_cache: clearing cache and re-creating with version number 2 Nov 12 22:40:40 volumio2 winbindd[918]: [2024/11/12 22:40:40.910194, 0] ../lib/util/become_daemon.c:138(daemon_ready) Nov 12 22:40:40 volumio2 winbindd[918]: daemon_ready: STATUS=daemon 'winbindd' finished starting up and ready to serve connections Nov 12 22:40:40 volumio2 systemd[1]: Started Samba Winbind Daemon. Nov 12 22:40:40 volumio2 systemd[1]: Starting Samba SMB Daemon... Nov 12 22:40:41 volumio2 winbindd[918]: [2024/11/12 22:40:41.459302, 0] ../source3/winbindd/wb_lookupsids.c:659(wb_lookupsids_recv) Nov 12 22:40:41 volumio2 winbindd[918]: res_names->count = 3, expected 4 Nov 12 22:40:41 volumio2 smbd[949]: [2024/11/12 22:40:41.484695, 0] ../lib/util/become_daemon.c:138(daemon_ready) Nov 12 22:40:41 volumio2 systemd[1]: Started Samba SMB Daemon. Nov 12 22:40:41 volumio2 systemd[1]: Reached target Multi-User System. Nov 12 22:40:41 volumio2 systemd[1]: Reached target Graphical Interface. Nov 12 22:40:41 volumio2 smbd[949]: daemon_ready: STATUS=daemon 'smbd' finished starting up and ready to serve connections Nov 12 22:40:41 volumio2 systemd[1]: Starting Update UTMP about System Runlevel Changes... Nov 12 22:40:41 volumio2 systemd[1]: systemd-update-utmp-runlevel.service: Succeeded. Nov 12 22:40:41 volumio2 systemd[1]: Started Update UTMP about System Runlevel Changes. Nov 12 22:40:41 volumio2 systemd[1]: Startup finished in 15.433s (kernel) + 17.330s (userspace) = 32.763s. Nov 12 22:40:42 volumio2 ntpd[779]: Listen normally on 3 eth0 192.168.1.92:123 Nov 12 22:40:42 volumio2 ntpd[779]: Listen normally on 4 wlan0 192.168.211.1:123 Nov 12 22:40:42 volumio2 ntpd[779]: new interface(s) found: waking up resolver Nov 12 22:40:43 volumio2 volumio[929]: info: ------------------------------------------- Nov 12 22:40:43 volumio2 volumio[929]: info: ----- Volumio3 ---- Nov 12 22:40:43 volumio2 volumio[929]: info: ------------------------------------------- Nov 12 22:40:43 volumio2 volumio[929]: info: ----- System startup ---- Nov 12 22:40:43 volumio2 volumio[929]: info: ------------------------------------------- Nov 12 22:40:44 volumio2 volumio[929]: info: MYVOLUMIO Environment detected Nov 12 22:40:44 volumio2 volumio[929]: info: Plugin folders cleanup Nov 12 22:40:44 volumio2 volumio[929]: info: Scanning into folder /volumio/app/plugins/ Nov 12 22:40:44 volumio2 volumio[929]: info: Scanning category audio_interface Nov 12 22:40:44 volumio2 volumio[929]: info: Scanning category miscellanea Nov 12 22:40:44 volumio2 volumio[929]: info: Scanning category music_service Nov 12 22:40:44 volumio2 volumio[929]: info: Scanning category plugins.json Nov 12 22:40:44 volumio2 volumio[929]: info: Scanning category system_controller Nov 12 22:40:44 volumio2 volumio[929]: info: Scanning category user_interface Nov 12 22:40:44 volumio2 volumio[929]: info: Scanning into folder /data/plugins/ Nov 12 22:40:44 volumio2 volumio[929]: info: Scanning category music_service Nov 12 22:40:44 volumio2 volumio[929]: info: Plugin folders cleanup completed Nov 12 22:40:44 volumio2 volumio[929]: info: ------------------------------------------- Nov 12 22:40:44 volumio2 volumio[929]: info: ----- Core plugins startup ---- Nov 12 22:40:44 volumio2 volumio[929]: info: ------------------------------------------- Nov 12 22:40:44 volumio2 volumio[929]: info: Loading plugins from folder /volumio/app/plugins/ Nov 12 22:40:44 volumio2 volumio[929]: info: Adding plugin upnp to MyMusic Plugins Nov 12 22:40:44 volumio2 volumio[929]: info: Adding plugin airplay_emulation to MyMusic Plugins Nov 12 22:40:44 volumio2 volumio[929]: info: Adding plugin upnp_browser to MyMusic Plugins Nov 12 22:40:44 volumio2 volumio[929]: info: Loading plugins from folder /data/plugins/ Nov 12 22:40:44 volumio2 volumio[929]: info: Loading plugin "system"... Nov 12 22:40:44 volumio2 volumio[929]: info: Loading plugin "appearance"... Nov 12 22:40:45 volumio2 volumio-remote-updater[603]: [2024-11-12 22:40:45] [connect] Successful connection Nov 12 22:40:46 volumio2 volumio[929]: info: Loading plugin "network"... Nov 12 22:40:46 volumio2 volumio[929]: info: Refreshing Cached IP Addresses Nov 12 22:40:46 volumio2 sudo[972]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Nov 12 22:40:46 volumio2 sudo[972]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 12 22:40:46 volumio2 sudo[972]: pam_unix(sudo:session): session closed for user root Nov 12 22:40:46 volumio2 sudo[974]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Nov 12 22:40:46 volumio2 sudo[974]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 12 22:40:46 volumio2 volumio[929]: info: Loading plugin "services"... Nov 12 22:40:46 volumio2 sudo[974]: pam_unix(sudo:session): session closed for user root Nov 12 22:40:46 volumio2 volumio[929]: info: Loading plugin "alsa_controller"... Nov 12 22:40:46 volumio2 sudo[976]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Nov 12 22:40:46 volumio2 sudo[976]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 12 22:40:46 volumio2 volumio[929]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Nov 12 22:40:46 volumio2 volumio[929]: info: Loading plugin "wizard"... Nov 12 22:40:46 volumio2 volumio[929]: info: Loading plugin "networkfs"... Nov 12 22:40:46 volumio2 volumio[929]: info: Starting Udev Watcher for removable devices Nov 12 22:40:46 volumio2 sudo[983]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=xbmc,password=xbmcpass,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //192.168.1.111/HDD1\\Music Flac /mnt/NAS/HDD1 Nov 12 22:40:46 volumio2 sudo[983]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 12 22:40:46 volumio2 volumio[929]: info: Ignoring mount for partition: boot Nov 12 22:40:46 volumio2 volumio[929]: info: Ignoring mount for partition: volumio Nov 12 22:40:46 volumio2 volumio[929]: info: Ignoring mount for partition: volumio_data Nov 12 22:40:46 volumio2 volumio[929]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Nov 12 22:40:46 volumio2 volumio[929]: info: Loading plugin "volumio_command_line_client"... Nov 12 22:40:46 volumio2 volumio[929]: info: Loading plugin "upnp"... Nov 12 22:40:46 volumio2 volumio[929]: info: [1731451246354] Starting Upmpd Daemon Nov 12 22:40:46 volumio2 volumio[929]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Nov 12 22:40:46 volumio2 volumio[929]: info: Loading plugin "my_music"... Nov 12 22:40:46 volumio2 volumio[929]: info: Loading plugin "mpd"... Nov 12 22:40:46 volumio2 kernel: Key type cifs.spnego registered Nov 12 22:40:46 volumio2 kernel: Key type cifs.idmap registered Nov 12 22:40:46 volumio2 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. Nov 12 22:40:46 volumio2 kernel: CIFS: Attempting to mount \\192.168.1.111\HDD1 Nov 12 22:40:46 volumio2 volumio[929]: info: Loading plugin "upnp_browser"... Nov 12 22:40:47 volumio2 sudo[983]: pam_unix(sudo:session): session closed for user root Nov 12 22:40:47 volumio2 volumio[929]: info: Loading plugin "alarm-clock"... Nov 12 22:40:47 volumio2 volumio[929]: info: Loading plugin "airplay_emulation"... Nov 12 22:40:47 volumio2 volumio[929]: info: Starting Shairport Sync Nov 12 22:40:47 volumio2 volumio[929]: info: Loading plugin "last_100"... Nov 12 22:40:47 volumio2 volumio[929]: info: Loading plugin "webradio"... Nov 12 22:40:47 volumio2 volumio[929]: info: Loading plugin "i2s_dacs"... Nov 12 22:40:47 volumio2 volumio[929]: info: Loading plugin "volumiodiscovery"... Nov 12 22:40:47 volumio2 volumio[929]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Nov 12 22:40:47 volumio2 volumio[929]: *** WARNING *** Please fix your application to use the native API of Avahi! Nov 12 22:40:47 volumio2 volumio[929]: *** WARNING *** For more information see Nov 12 22:40:47 volumio2 volumio[929]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Nov 12 22:40:47 volumio2 node[929]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Nov 12 22:40:47 volumio2 volumio[929]: *** WARNING *** Please fix your application to use the native API of Avahi! Nov 12 22:40:47 volumio2 volumio[929]: *** WARNING *** For more information see Nov 12 22:40:47 volumio2 node[929]: *** WARNING *** Please fix your application to use the native API of Avahi! Nov 12 22:40:47 volumio2 node[929]: *** WARNING *** For more information see Nov 12 22:40:47 volumio2 node[929]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Nov 12 22:40:47 volumio2 node[929]: *** WARNING *** Please fix your application to use the native API of Avahi! Nov 12 22:40:47 volumio2 node[929]: *** WARNING *** For more information see Nov 12 22:40:47 volumio2 volumio[929]: info: Applying required configuration parameters for plugin volumiodiscovery Nov 12 22:40:47 volumio2 volumio[929]: info: Discovery: Started advertising with name: Volumio2 Nov 12 22:40:47 volumio2 volumio[929]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Nov 12 22:40:47 volumio2 volumio[929]: info: Loading plugin "spop"... Nov 12 22:40:49 volumio2 volumio[929]: info: Loading plugin "outputs"... Nov 12 22:40:49 volumio2 volumio[929]: info: Loading plugin "albumart"... Nov 12 22:40:49 volumio2 volumio[929]: info: Plugin example_plugin is not enabled Nov 12 22:40:49 volumio2 volumio[929]: info: Loading plugin "inputs"... Nov 12 22:40:49 volumio2 volumio[929]: info: Loading plugin "updater_comm"... Nov 12 22:40:49 volumio2 volumio[929]: info: Plugin mpdemulation is not enabled Nov 12 22:40:49 volumio2 volumio[929]: info: Loading plugin "rest_api"... Nov 12 22:40:49 volumio2 volumio[929]: info: Loading plugin "websocket"... Nov 12 22:40:49 volumio2 volumio[929]: info: Starting Socket.io Server version 2.3.0 Nov 12 22:40:49 volumio2 volumio[929]: info: Loading i18n strings for locale pt Nov 12 22:40:49 volumio2 volumio[929]: Updating browse sources language Nov 12 22:40:49 volumio2 volumio[929]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 12 22:40:49 volumio2 volumio[929]: Forking 3 albumart workers Nov 12 22:40:49 volumio2 sudo[976]: pam_unix(sudo:session): session closed for user root Nov 12 22:40:50 volumio2 volumio[929]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Nov 12 22:40:50 volumio2 volumio[929]: info: CoreCommandRouter::initPlayerControls Nov 12 22:40:50 volumio2 volumio[929]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 12 22:40:50 volumio2 volumio[929]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 12 22:40:50 volumio2 volumio[929]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 12 22:40:50 volumio2 volumio[929]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 12 22:40:50 volumio2 volumio[929]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 12 22:40:50 volumio2 volumio[929]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 12 22:40:50 volumio2 volumio[929]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 12 22:40:50 volumio2 volumio[929]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 12 22:40:50 volumio2 volumio[929]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Nov 12 22:40:50 volumio2 volumio[929]: Express server listening on port 3000 Nov 12 22:40:50 volumio2 volumio[929]: [Metrics] WebUI: 7s 568.78ms Nov 12 22:40:50 volumio2 volumio[929]: info: CoreStateMachine::resetVolumioState Nov 12 22:40:50 volumio2 volumio[929]: info: CoreStateMachine::getcurrentVolume Nov 12 22:40:50 volumio2 volumio[929]: info: CoreCommandRouter::volumioRetrievevolume Nov 12 22:40:50 volumio2 volumio-remote-updater[603]: [2024-11-12 22:40:50] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1731451245 101 Nov 12 22:40:50 volumio2 volumio[929]: 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: 1 Nov 12 22:40:50 volumio2 volumio[929]: info: CoreStateMachine::pushState Nov 12 22:40:50 volumio2 volumio[929]: info: CorePlayQueue::getTrack 0 Nov 12 22:40:50 volumio2 volumio[929]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 12 22:40:50 volumio2 volumio[929]: info: CoreCommandRouter::volumioPushState Nov 12 22:40:50 volumio2 volumio[929]: info: CoreStateMachine::updateTrackBlock Nov 12 22:40:50 volumio2 volumio[929]: info: CorePlayQueue::getTrackBlock Nov 12 22:40:50 volumio2 volumio[929]: info: CoreCommandRouter::volumioRetrievevolume Nov 12 22:40:50 volumio2 volumio[929]: info: Reloading queue from file Nov 12 22:40:50 volumio2 volumio[929]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 12 22:40:50 volumio2 volumio[929]: info: CoreStateMachine::setRepeat false single undefined Nov 12 22:40:50 volumio2 volumio[929]: info: CoreStateMachine::pushState Nov 12 22:40:50 volumio2 volumio[929]: info: CorePlayQueue::getTrack 0 Nov 12 22:40:50 volumio2 volumio[929]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 12 22:40:50 volumio2 volumio[929]: info: CoreCommandRouter::volumioPushState Nov 12 22:40:50 volumio2 volumio[929]: info: CoreStateMachine::setRandom null Nov 12 22:40:50 volumio2 volumio[929]: info: CoreStateMachine::pushState Nov 12 22:40:50 volumio2 volumio[929]: info: CorePlayQueue::getTrack 0 Nov 12 22:40:50 volumio2 volumio[929]: info: CoreCommandRouter::volumioPushState Nov 12 22:40:50 volumio2 volumio[929]: info: Setting Device type: Raspberry PI Nov 12 22:40:50 volumio2 volumio[929]: info: CoreStateMachine::pushState Nov 12 22:40:50 volumio2 volumio[929]: info: CorePlayQueue::getTrack 0 Nov 12 22:40:50 volumio2 volumio[929]: info: CoreCommandRouter::volumioPushState Nov 12 22:40:50 volumio2 volumio[929]: info: Completed loading Core Plugins Nov 12 22:40:50 volumio2 volumio[929]: info: Preparing to generate the ALSA configuration file Nov 12 22:40:50 volumio2 volumio[929]: info: Discovery: adding f907a522-d0b2-4592-afd4-7311165fa4dd Nov 12 22:40:50 volumio2 volumio[929]: info: Discovery: Found device Volumio2 Nov 12 22:40:50 volumio2 volumio[929]: info: CoreCommandRouter::volumioGetState Nov 12 22:40:50 volumio2 volumio[929]: info: CorePlayQueue::getTrack 0 Nov 12 22:40:50 volumio2 volumio[929]: info: Discovery: this is already registered, f907a522-d0b2-4592-afd4-7311165fa4dd Nov 12 22:40:50 volumio2 volumio[929]: info: Discovery: Found device Volumio2 Nov 12 22:40:50 volumio2 volumio[929]: info: CoreCommandRouter::volumioGetState Nov 12 22:40:50 volumio2 volumio[929]: info: CorePlayQueue::getTrack 0 Nov 12 22:40:50 volumio2 volumio[929]: info: The plugin alsa_controller has an ALSA contribution file softvolume.postVolume.conf Nov 12 22:40:50 volumio2 volumio[929]: info: Reading ALSA contributions from plugins. Nov 12 22:40:50 volumio2 volumio[929]: info: Asound.conf file written Nov 12 22:40:50 volumio2 sudo[1060]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mv /home/volumio/.asoundrc /etc/asound.conf Nov 12 22:40:50 volumio2 sudo[1060]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 12 22:40:50 volumio2 sudo[1060]: pam_unix(sudo:session): session closed for user root Nov 12 22:40:50 volumio2 volumio[929]: /usr/sbin/alsactl: set_control:1461: Cannot write control '2:0:0:Cambridge AudioDAC100 USB 2 Playback Switch:1' : Operation not permitted Nov 12 22:40:50 volumio2 volumio[929]: info: Output device has changed, restarting MPD Nov 12 22:40:50 volumio2 volumio[929]: Starting albumart workers Nov 12 22:40:50 volumio2 volumio[929]: info: Output device has changed, restarting Shairport Sync Nov 12 22:40:50 volumio2 volumio[929]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 12 22:40:50 volumio2 volumio[929]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 12 22:40:50 volumio2 volumio[929]: Starting albumart workers Nov 12 22:40:50 volumio2 sudo[1068]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Nov 12 22:40:50 volumio2 sudo[1068]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 12 22:40:50 volumio2 sudo[1066]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Nov 12 22:40:50 volumio2 sudo[1066]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 12 22:40:50 volumio2 volumio[929]: Starting albumart workers Nov 12 22:40:50 volumio2 sudo[1066]: pam_unix(sudo:session): session closed for user root Nov 12 22:40:50 volumio2 volumio[929]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Nov 12 22:40:50 volumio2 volumio[929]: info: ___________ START PLUGINS ___________ Nov 12 22:40:50 volumio2 volumio[929]: info: ControllerMpd::onStart: Initializing MPD Nov 12 22:40:50 volumio2 volumio[929]: info: Creating MPD Configuration file Nov 12 22:40:50 volumio2 systemd[1]: Listening on mpd.socket. Nov 12 22:40:50 volumio2 systemd[1]: Starting Music Player Daemon... Nov 12 22:40:50 volumio2 sudo[1075]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Nov 12 22:40:50 volumio2 sudo[1075]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 12 22:40:50 volumio2 volumio[929]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Nov 12 22:40:50 volumio2 volumio[929]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Nov 12 22:40:50 volumio2 volumio[929]: info: [1731451250902] CoreMusicLibrary::Adding element Servidores multimédia Nov 12 22:40:50 volumio2 volumio[929]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 12 22:40:50 volumio2 sudo[1079]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Nov 12 22:40:50 volumio2 sudo[1075]: pam_unix(sudo:session): session closed for user root Nov 12 22:40:50 volumio2 sudo[1079]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 12 22:40:50 volumio2 systemd[1]: mpd.service: Control process exited, code=killed, status=15/TERM Nov 12 22:40:50 volumio2 systemd[1]: mpd.service: Succeeded. Nov 12 22:40:50 volumio2 systemd[1]: Stopped Music Player Daemon. Nov 12 22:40:50 volumio2 systemd[1]: Starting Music Player Daemon... Nov 12 22:40:50 volumio2 volumio[929]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 12 22:40:50 volumio2 volumio[929]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 12 22:40:51 volumio2 volumio[929]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Nov 12 22:40:51 volumio2 volumio[929]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 12 22:40:51 volumio2 volumio[929]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 12 22:40:51 volumio2 sudo[1081]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Nov 12 22:40:51 volumio2 sudo[1081]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 12 22:40:51 volumio2 sudo[1081]: /bin/chown: cannot access '/var/log/mpd.log': No such file or directory Nov 12 22:40:51 volumio2 sudo[1081]: pam_unix(sudo:session): session closed for user root Nov 12 22:40:51 volumio2 volumio[929]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Nov 12 22:40:51 volumio2 volumio[929]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Nov 12 22:40:51 volumio2 volumio[929]: info: [1731451251159] CoreMusicLibrary::Adding element Last_100 Nov 12 22:40:51 volumio2 volumio[929]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 12 22:40:51 volumio2 volumio[929]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Nov 12 22:40:51 volumio2 volumio[929]: info: [1731451251164] CoreMusicLibrary::Adding element Webradio Nov 12 22:40:51 volumio2 volumio[929]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 12 22:40:51 volumio2 volumio[929]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Nov 12 22:40:51 volumio2 volumio[929]: info: Initializing BBC Radios Nov 12 22:40:51 volumio2 volumio[929]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Nov 12 22:40:51 volumio2 volumio[929]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 12 22:40:51 volumio2 volumio[929]: info: Creating Spotify config file Nov 12 22:40:51 volumio2 volumio[929]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 12 22:40:51 volumio2 volumio[929]: info: Volumio Calling Home Nov 12 22:40:51 volumio2 volumio[929]: info: MPD Permissions set Nov 12 22:40:51 volumio2 volumio[929]: info: Spotify config file written Nov 12 22:40:51 volumio2 sudo[1124]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Nov 12 22:40:51 volumio2 sudo[1124]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 12 22:40:51 volumio2 volumio[929]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Nov 12 22:40:51 volumio2 volumio[929]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 12 22:40:51 volumio2 volumio[929]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 12 22:40:51 volumio2 volumio[929]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 12 22:40:51 volumio2 volumio[929]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 12 22:40:51 volumio2 volumio[929]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 12 22:40:51 volumio2 volumio[929]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 12 22:40:51 volumio2 volumio[929]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 12 22:40:51 volumio2 volumio[929]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 12 22:40:51 volumio2 systemd[1]: Started go-librespot Daemon. Nov 12 22:40:51 volumio2 go-librespot[1130]: Librespot-go daemon starting... Nov 12 22:40:51 volumio2 sudo[1124]: pam_unix(sudo:session): session closed for user root Nov 12 22:40:51 volumio2 volumio[929]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 12 22:40:52 volumio2 volumio[929]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 12 22:40:52 volumio2 volumio[929]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 12 22:40:52 volumio2 volumio[929]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 12 22:40:52 volumio2 volumio[929]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 12 22:40:52 volumio2 volumio[929]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 12 22:40:52 volumio2 volumio[929]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 12 22:40:52 volumio2 volumio[929]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 12 22:40:52 volumio2 volumio[929]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 12 22:40:52 volumio2 volumio[929]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 12 22:40:52 volumio2 volumio[929]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 12 22:40:52 volumio2 volumio[929]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 12 22:40:52 volumio2 volumio[929]: info: Volumio called home Nov 12 22:40:52 volumio2 volumio[929]: info: Starting Shairport Sync Nov 12 22:40:52 volumio2 volumio[929]: info: Starting Shairport Sync Nov 12 22:40:52 volumio2 volumio[929]: info: Starting Shairport Sync Nov 12 22:40:52 volumio2 sudo[1141]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Nov 12 22:40:52 volumio2 sudo[1141]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 12 22:40:52 volumio2 sudo[1144]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Nov 12 22:40:52 volumio2 sudo[1144]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 12 22:40:52 volumio2 sudo[1147]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Nov 12 22:40:52 volumio2 volumio[929]: info: CoreCommandRouter::volumioGetState Nov 12 22:40:52 volumio2 volumio[929]: info: CorePlayQueue::getTrack 0 Nov 12 22:40:52 volumio2 sudo[1147]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 12 22:40:52 volumio2 systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Nov 12 22:40:52 volumio2 systemd[1]: shairport-sync.service: Succeeded. Nov 12 22:40:52 volumio2 systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Nov 12 22:40:52 volumio2 systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Nov 12 22:40:52 volumio2 sudo[1144]: pam_unix(sudo:session): session closed for user root Nov 12 22:40:52 volumio2 sudo[1147]: pam_unix(sudo:session): session closed for user root Nov 12 22:40:52 volumio2 sudo[1141]: pam_unix(sudo:session): session closed for user root Nov 12 22:40:52 volumio2 volumio[929]: info: Shairport-Sync Started Nov 12 22:40:52 volumio2 volumio[929]: Error adding Membership: Error: addMembership EINVAL Nov 12 22:40:52 volumio2 volumio[929]: info: Shairport-Sync Started Nov 12 22:40:52 volumio2 volumio[929]: info: Shairport-Sync Started Nov 12 22:40:52 volumio2 volumio[929]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Nov 12 22:40:52 volumio2 volumio[929]: SPOTIFY: BQAHeZ6ZzJ3uvAvaxahb0Fi4M4TU7_JbFC6XWMAK5n1pTsJ-FH33CjDp0KetU0RTDsfJ9jesikOkYCU59us8K-5z4rwXZp-8n5KkLCLJHgcBiqWY20Ub5s1xrqEfvn2q3cXJm0iG20_dgeeO7_4vj5T22e6lzk_Gfb2jmxWurLJaQFYZb8zGs3wMpaQEgsrv3kNK-43i5-aze09r9-BiVL8yR3Xkl72PYImSXBhhrO8TNDhHaglSL_El Nov 12 22:40:52 volumio2 volumio[929]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Nov 12 22:40:52 volumio2 volumio[929]: info: New Spotify access token = BQAHeZ6ZzJ3uvAvaxahb0Fi4M4TU7_JbFC6XWMAK5n1pTsJ-FH33CjDp0KetU0RTDsfJ9jesikOkYCU59us8K-5z4rwXZp-8n5KkLCLJHgcBiqWY20Ub5s1xrqEfvn2q3cXJm0iG20_dgeeO7_4vj5T22e6lzk_Gfb2jmxWurLJaQFYZb8zGs3wMpaQEgsrv3kNK-43i5-aze09r9-BiVL8yR3Xkl72PYImSXBhhrO8TNDhHaglSL_El Nov 12 22:40:52 volumio2 volumio[929]: info: Spotify credentials grant success - running version from March 24, 2019 Nov 12 22:40:52 volumio2 volumio[929]: SPOTIFY: User informations: {"country":"PT","display_name":"opmenino","email":"opmenino@sapo.pt","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/opmenino"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/opmenino","id":"opmenino","images":[],"product":"premium","type":"user","uri":"spotify:user:opmenino"} Nov 12 22:40:52 volumio2 volumio[929]: info: Spotify Successfully logged in Nov 12 22:40:52 volumio2 volumio[929]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Nov 12 22:40:52 volumio2 volumio[929]: info: [1731451252624] CoreMusicLibrary::Adding element Spotify Nov 12 22:40:52 volumio2 volumio[929]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 12 22:40:52 volumio2 volumio[929]: Cannot find translation for source Spotify Nov 12 22:40:52 volumio2 go-librespot[1130]: time="2024-11-12T22:40:52Z" level=info msg="generated new device id: cb68969ca882d030f20a0b01f4d0df62bfefbd06" Nov 12 22:40:52 volumio2 go-librespot[1130]: time="2024-11-12T22:40:52Z" level=debug msg="stored credentials found for opmenino" Nov 12 22:40:53 volumio2 go-librespot[1130]: time="2024-11-12T22:40:53Z" 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-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Nov 12 22:40:53 volumio2 go-librespot[1130]: time="2024-11-12T22:40:53Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Nov 12 22:40:53 volumio2 go-librespot[1130]: time="2024-11-12T22:40:53Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Nov 12 22:40:53 volumio2 go-librespot[1130]: time="2024-11-12T22:40:53Z" level=debug msg="zeroconf server listening on port 46269" Nov 12 22:40:53 volumio2 go-librespot[1130]: time="2024-11-12T22:40:53Z" level=debug msg="obtained new client token: AADR8+8J5liN7ITSR66N/PHscz1+4XU+7i+vr+wnbUOPrWZKK0mEIAyDU3ZmvJc1YQVc6gEzo7dj2Hirbgz+q0Ww3W/N9KiKzJ/rQ9uW7boLcBmn+XsRvYKAVUNwNBsMRVMGbd8DS2Gr6JD3vwuFldYshstY2N5Mxb1Dglyr53FoBr1nWvUpEO5EkUFPn977BPMyoV0lE0PaTxt3X+5atWwMrvqiw6osVQ5O2fPBX2crWO4JEIFDN6cNGbI=" Nov 12 22:40:54 volumio2 mpd[1089]: Nov 12 22:40 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Nov 12 22:40:54 volumio2 systemd[1]: Started Music Player Daemon. Nov 12 22:40:54 volumio2 sudo[1079]: pam_unix(sudo:session): session closed for user root Nov 12 22:40:54 volumio2 sudo[1068]: pam_unix(sudo:session): session closed for user root Nov 12 22:40:54 volumio2 volumio[929]: info: Completed starting Core Plugins Nov 12 22:40:54 volumio2 volumio[929]: info: ------------------------------------------- Nov 12 22:40:54 volumio2 volumio[929]: info: ----- MyVolumio plugins startup ---- Nov 12 22:40:54 volumio2 volumio[929]: info: ------------------------------------------- Nov 12 22:40:54 volumio2 volumio[929]: info: [MyVolumio PluginManager] Fetching plans data.... Nov 12 22:40:54 volumio2 volumio[929]: error: MPD error: The expression evaluated to a falsy value: Nov 12 22:40:54 volumio2 volumio[929]: assert.ok(self.idling) Nov 12 22:40:54 volumio2 volumio[929]: error: The expression evaluated to a falsy value: Nov 12 22:40:54 volumio2 volumio[929]: assert.ok(self.idling) Nov 12 22:40:54 volumio2 volumio[929]: error: updateQueue error: null Nov 12 22:40:54 volumio2 volumio[929]: info: MPD running with PID1089 Nov 12 22:40:54 volumio2 volumio[929]: ,establishing connection Nov 12 22:40:54 volumio2 volumio[929]: error: updateQueue error: null Nov 12 22:40:55 volumio2 volumio[929]: info: go-librespot daemon successfully initialized Nov 12 22:40:55 volumio2 go-librespot[1130]: time="2024-11-12T22:40:55Z" level=debug msg="completed keyexchange" Nov 12 22:40:55 volumio2 go-librespot[1130]: time="2024-11-12T22:40:55Z" level=debug msg="completed challenge" Nov 12 22:40:55 volumio2 go-librespot[1130]: time="2024-11-12T22:40:55Z" level=debug msg="authenticated as opmenino" Nov 12 22:40:55 volumio2 go-librespot[1130]: time="2024-11-12T22:40:55Z" level=debug msg="authenticated as opmenino" Nov 12 22:40:55 volumio2 go-librespot[1130]: time="2024-11-12T22:40:55Z" level=debug msg="dealer connection opened" Nov 12 22:40:55 volumio2 go-librespot[1130]: time="2024-11-12T22:40:55Z" level=debug msg="initializing zeroconf session, username: opmenino" Nov 12 22:40:55 volumio2 go-librespot[1130]: time="2024-11-12T22:40:55Z" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Nov 12 22:40:55 volumio2 go-librespot[1130]: time="2024-11-12T22:40:55Z" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Nov 12 22:40:55 volumio2 go-librespot[1130]: time="2024-11-12T22:40:55Z" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Nov 12 22:40:55 volumio2 go-librespot[1130]: time="2024-11-12T22:40:55Z" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Nov 12 22:40:55 volumio2 go-librespot[1130]: time="2024-11-12T22:40:55Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Nov 12 22:40:55 volumio2 go-librespot[1130]: time="2024-11-12T22:40:55Z" level=debug msg="autoplay enabled: false" Nov 12 22:40:55 volumio2 go-librespot[1130]: time="2024-11-12T22:40:55Z" level=debug msg="received connection id: M2JmNWE2YzYtYTdhOS00Y2E5LWFmOWItNWQ4Y2E5NTExNjk1K2RlYWxlcit0Y3A6Ly8wYWNhNDBmMi5pcC5nZXcxLnNwb3RpZnkubmV0OjU3MDArRUNFNDU3NDgwRDk1MERGQzkxMDBGRDM3ODY1OTYzNDVCQTM4OUM5NUUyRUE1REI5M0Y3NzdEMTE5QUNFQzgwMw==" Nov 12 22:40:56 volumio2 go-librespot[1130]: time="2024-11-12T22:40:56Z" level=debug msg="put connect state because NEW_DEVICE" Nov 12 22:40:56 volumio2 sudo[1165]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Nov 12 22:40:56 volumio2 sudo[1165]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 12 22:40:56 volumio2 sudo[1165]: pam_unix(sudo:session): session closed for user root Nov 12 22:40:56 volumio2 sudo[1167]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Nov 12 22:40:56 volumio2 sudo[1167]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 12 22:40:56 volumio2 sudo[1167]: pam_unix(sudo:session): session closed for user root Nov 12 22:40:56 volumio2 sudo[1171]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Nov 12 22:40:56 volumio2 sudo[1171]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 12 22:40:56 volumio2 systemd[1]: Started UPnP Renderer front-end to MPD. Nov 12 22:40:56 volumio2 sudo[1171]: pam_unix(sudo:session): session closed for user root Nov 12 22:40:56 volumio2 volumio[929]: info: Upmpdcli Daemon Started Nov 12 22:40:56 volumio2 volumio[1173]: Generating RSA private key, 4096 bit long modulus (2 primes) Nov 12 22:40:57 volumio2 go-librespot[1130]: time="2024-11-12T22:40:57Z" level=debug msg="handling transfer player command from 78c857e9ee30552b1cb0176b757e7926c42882ea" Nov 12 22:40:57 volumio2 go-librespot[1130]: time="2024-11-12T22:40:57Z" level=debug msg="resolved context of track" uri="spotify:playlist:37i9dQZF1DXdbXrPNafg9d" Nov 12 22:40:57 volumio2 go-librespot[1130]: time="2024-11-12T22:40:57Z" level=trace msg="fetched new page 0 with 190 items (list: 190)" uri="spotify:playlist:37i9dQZF1DXdbXrPNafg9d" Nov 12 22:40:57 volumio2 go-librespot[1130]: time="2024-11-12T22:40:57Z" level=debug msg="loading track (paused: true, position: 92223ms)" uri="spotify:track:0rHsI1XMHFqORFBxjzgDP5" Nov 12 22:40:57 volumio2 go-librespot[1130]: time="2024-11-12T22:40:57Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Nov 12 22:40:57 volumio2 go-librespot[1130]: time="2024-11-12T22:40:57Z" level=trace msg="emitting websocket event: will_play" Nov 12 22:40:57 volumio2 go-librespot[1130]: time="2024-11-12T22:40:57Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 241" Nov 12 22:40:57 volumio2 go-librespot[1130]: time="2024-11-12T22:40:57Z" level=debug msg="selected format OGG_VORBIS_320 (282a8f391f53a10d6c23b2cd8754fd9798ad09c0)" uri="spotify:track:0rHsI1XMHFqORFBxjzgDP5" Nov 12 22:40:57 volumio2 go-librespot[1130]: time="2024-11-12T22:40:57Z" level=debug msg="requested aes key for file 282a8f391f53a10d6c23b2cd8754fd9798ad09c0, gid: 0rHsI1XMHFqORFBxjzgDP5" Nov 12 22:40:57 volumio2 go-librespot[1130]: time="2024-11-12T22:40:57Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1333" Nov 12 22:40:58 volumio2 volumio[929]: info: Initializing connection to go-librespot Websocket Nov 12 22:40:58 volumio2 go-librespot[1130]: time="2024-11-12T22:40:58Z" level=debug msg="new websocket client" Nov 12 22:40:58 volumio2 volumio[929]: info: Connection to go-librespot Websocket established Nov 12 22:40:58 volumio2 go-librespot[1130]: time="2024-11-12T22:40:58Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1111" Nov 12 22:40:58 volumio2 go-librespot[1130]: time="2024-11-12T22:40:58Z" level=debug msg="fetched first chunk of 18, total size is 9160353 bytes" uri="spotify:track:0rHsI1XMHFqORFBxjzgDP5" Nov 12 22:40:58 volumio2 go-librespot[1130]: time="2024-11-12T22:40:58Z" level=debug msg="fetched chunk 1/17, size: 524288" uri="spotify:track:0rHsI1XMHFqORFBxjzgDP5" Nov 12 22:40:58 volumio2 go-librespot[1130]: time="2024-11-12T22:40:58Z" level=debug msg="fetched chunk 2/17, size: 524288" uri="spotify:track:0rHsI1XMHFqORFBxjzgDP5" Nov 12 22:40:58 volumio2 go-librespot[1130]: time="2024-11-12T22:40:58Z" level=debug msg="fetched chunk 7/17, size: 524288" uri="spotify:track:0rHsI1XMHFqORFBxjzgDP5" Nov 12 22:40:58 volumio2 go-librespot[1130]: time="2024-11-12T22:40:58Z" level=debug msg="fetched chunk 8/17, size: 524288" uri="spotify:track:0rHsI1XMHFqORFBxjzgDP5" Nov 12 22:40:58 volumio2 go-librespot[1130]: time="2024-11-12T22:40:58Z" level=debug msg="fetched chunk 6/17, size: 524288" uri="spotify:track:0rHsI1XMHFqORFBxjzgDP5" Nov 12 22:40:58 volumio2 go-librespot[1130]: time="2024-11-12T22:40:58Z" level=trace msg="seek to 92223ms (diff: 270ms, samples: 4067034, bytes: 3285890)" uri="spotify:track:0rHsI1XMHFqORFBxjzgDP5" Nov 12 22:40:58 volumio2 go-librespot[1130]: time="2024-11-12T22:40:58Z" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 5011 us, period size = 221 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 99 frames" Nov 12 22:40:58 volumio2 go-librespot[1130]: time="2024-11-12T22:40:58Z" level=debug msg="created new output device" Nov 12 22:40:58 volumio2 go-librespot[1130]: time="2024-11-12T22:40:58Z" level=info msg="loaded track \"Mouth of a Flower\" (paused: true, position: 92223ms, duration: 257903ms, prefetched: false)" uri="spotify:track:0rHsI1XMHFqORFBxjzgDP5" Nov 12 22:40:58 volumio2 go-librespot[1130]: time="2024-11-12T22:40:58Z" level=debug msg="fetched chunk 3/17, size: 524288" uri="spotify:track:0rHsI1XMHFqORFBxjzgDP5" Nov 12 22:40:58 volumio2 go-librespot[1130]: time="2024-11-12T22:40:58Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Nov 12 22:40:58 volumio2 go-librespot[1130]: time="2024-11-12T22:40:58Z" level=trace msg="emitting websocket event: metadata" Nov 12 22:40:58 volumio2 volumio[929]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:0rHsI1XMHFqORFBxjzgDP5","name":"Mouth of a Flower","artist_names":["Haley Heynderickx"],"album_name":"Seed of a Seed","album_cover_url":"https://i.scdn.co/image/ab67616d00001e024346e5f8b58d9ac25b4d1066","position":92223,"duration":257903,"release_date":"year:2024 month:11 day:1","track_number":4,"disc_number":1}} Nov 12 22:40:58 volumio2 go-librespot[1130]: time="2024-11-12T22:40:58Z" level=debug msg="fetched chunk 9/17, size: 524288" uri="spotify:track:0rHsI1XMHFqORFBxjzgDP5" Nov 12 22:40:58 volumio2 go-librespot[1130]: time="2024-11-12T22:40:58Z" level=trace msg="emitting websocket event: active" Nov 12 22:40:58 volumio2 go-librespot[1130]: time="2024-11-12T22:40:58Z" level=debug msg="sending successful reply for dealer request" Nov 12 22:40:58 volumio2 go-librespot[1130]: time="2024-11-12T22:40:58Z" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Nov 12 22:40:58 volumio2 go-librespot[1130]: time="2024-11-12T22:40:58Z" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Nov 12 22:40:58 volumio2 go-librespot[1130]: time="2024-11-12T22:40:58Z" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Nov 12 22:40:58 volumio2 volumio[929]: SPOTIFY: received: {"type":"active","data":null} Nov 12 22:40:58 volumio2 volumio[929]: info: Aligning Spotify Volume to Volumio Volume Nov 12 22:40:58 volumio2 volumio[929]: info: CoreCommandRouter::volumioGetState Nov 12 22:40:58 volumio2 volumio[929]: info: CorePlayQueue::getTrack 0 Nov 12 22:40:58 volumio2 volumio[929]: info: Setting Spotify Volume from Volumio: 78 Nov 12 22:40:58 volumio2 go-librespot[1130]: time="2024-11-12T22:40:58Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Nov 12 22:40:58 volumio2 go-librespot[1130]: time="2024-11-12T22:40:58Z" level=trace msg="emitting websocket event: paused" Nov 12 22:40:58 volumio2 volumio[929]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:0rHsI1XMHFqORFBxjzgDP5","play_origin":"playlist/ondemand"}} Nov 12 22:40:58 volumio2 volumio[929]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Nov 12 22:40:58 volumio2 volumio[929]: TypeError: Cannot read property 'service' of undefined Nov 12 22:40:58 volumio2 volumio[929]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:336:50) Nov 12 22:40:58 volumio2 volumio[929]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:270:18) Nov 12 22:40:58 volumio2 volumio[929]: at WebSocket.message (/data/plugins/music_service/spop/index.js:189:14) Nov 12 22:40:58 volumio2 volumio[929]: at WebSocket.emit (events.js:315:20) Nov 12 22:40:58 volumio2 volumio[929]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20) Nov 12 22:40:58 volumio2 volumio[929]: at Receiver.emit (events.js:315:20) Nov 12 22:40:58 volumio2 volumio[929]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) Nov 12 22:40:58 volumio2 volumio[929]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) Nov 12 22:40:58 volumio2 volumio[929]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) Nov 12 22:40:58 volumio2 volumio[929]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) Nov 12 22:40:58 volumio2 volumio[929]: at writeOrBuffer (internal/streams/writable.js:358:12) Nov 12 22:40:58 volumio2 volumio[929]: at Receiver.Writable.write (internal/streams/writable.js:303:10) Nov 12 22:40:58 volumio2 volumio[929]: at Socket.socketOnData (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1355:35) Nov 12 22:40:58 volumio2 volumio[929]: at Socket.emit (events.js:315:20) Nov 12 22:40:58 volumio2 volumio[929]: at addChunk (internal/streams/readable.js:309:12) Nov 12 22:40:58 volumio2 volumio[929]: at readableAddChunk (internal/streams/readable.js:284:9) Nov 12 22:40:58 volumio2 volumio[929]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Nov 12 22:40:59 volumio2 sudo[1198]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-11-12 22:39 Nov 12 22:40:59 volumio2 sudo[1198]: 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"