-- Logs begin at Thu 2019-02-14 10:11:59 UTC, end at Mon 2025-05-26 19:08:36 UTC. -- May 26 19:07:52 raspberry kernel: bcm2835-power bcm2835-power: Broadcom BCM2835 power domains driver May 26 19:07:52 raspberry kernel: mmc-bcm2835 fe300000.mmcnr: mmc_debug:0 mmc_debug2:0 May 26 19:07:52 raspberry kernel: mmc-bcm2835 fe300000.mmcnr: DMA channel allocated May 26 19:07:52 raspberry kernel: of_cfs_init May 26 19:07:52 raspberry kernel: of_cfs_init: OK May 26 19:07:52 raspberry kernel: mmc1: queuing unknown CIS tuple 0x80 (2 bytes) May 26 19:07:52 raspberry kernel: mmc1: queuing unknown CIS tuple 0x80 (3 bytes) May 26 19:07:52 raspberry kernel: mmc1: queuing unknown CIS tuple 0x80 (3 bytes) May 26 19:07:52 raspberry kernel: mmc1: queuing unknown CIS tuple 0x80 (7 bytes) May 26 19:07:52 raspberry kernel: mmc1: queuing unknown CIS tuple 0x80 (3 bytes) May 26 19:07:52 raspberry kernel: mmc0: SDHCI controller on fe340000.mmc [fe340000.mmc] using ADMA May 26 19:07:52 raspberry kernel: Freeing unused kernel memory: 2048K May 26 19:07:52 raspberry kernel: Run /init as init process May 26 19:07:52 raspberry kernel: with arguments: May 26 19:07:52 raspberry kernel: /init May 26 19:07:52 raspberry kernel: splash May 26 19:07:52 raspberry kernel: with environment: May 26 19:07:52 raspberry kernel: HOME=/ May 26 19:07:52 raspberry kernel: TERM=linux May 26 19:07:52 raspberry kernel: imgpart=/dev/mmcblk0p2 May 26 19:07:52 raspberry kernel: imgfile=/volumio_current.sqsh May 26 19:07:52 raspberry kernel: bootdelay=5 May 26 19:07:52 raspberry kernel: mmc1: new high speed SDIO card at address 0001 May 26 19:07:52 raspberry kernel: mmc0: new ultra high speed DDR50 SDXC card at address aaaa May 26 19:07:52 raspberry kernel: mmcblk0: mmc0:aaaa SD64G 59.5 GiB May 26 19:07:52 raspberry kernel: mmcblk0: p1 p2 p3 May 26 19:07:52 raspberry kernel: usb 1-1: new high-speed USB device number 2 using xhci_hcd May 26 19:07:52 raspberry initramfs: Booting Volumio for BCM2711 May 26 19:07:52 raspberry initramfs: This script mounts rootfs RO with an overlay RW layer. May 26 19:07:52 raspberry kernel: squashfs: version 4.0 (2009/01/31) Phillip Lougher May 26 19:07:52 raspberry initramfs: IMGPART=/dev/mmcblk0p2 May 26 19:07:52 raspberry initramfs: IMGFILE=/volumio_current.sqsh May 26 19:07:52 raspberry initramfs: Boot delay (except first time) will be 5 seconds May 26 19:07:52 raspberry initramfs: /dev/mmcblk0p2: May 26 19:07:52 raspberry kernel: usb 1-1: New USB device found, idVendor=2109, idProduct=3431, bcdDevice= 4.21 May 26 19:07:52 raspberry kernel: usb 1-1: New USB device strings: Mfr=0, Product=1, SerialNumber=0 May 26 19:07:52 raspberry kernel: usb 1-1: Product: USB2.0 Hub May 26 19:07:52 raspberry kernel: hub 1-1:1.0: USB hub found May 26 19:07:52 raspberry kernel: hub 1-1:1.0: 4 ports detected May 26 19:07:52 raspberry kernel: EXT4-fs (mmcblk0p2): recovery complete May 26 19:07:52 raspberry kernel: EXT4-fs (mmcblk0p2): mounted filesystem with ordered data mode. Opts: (null) May 26 19:07:52 raspberry initramfs: Doing a 5 second delay here to give kernel load a headstart May 26 19:07:52 raspberry kernel: usb 1-1.3: new full-speed USB device number 3 using xhci_hcd May 26 19:07:52 raspberry kernel: usb 1-1.3: New USB device found, idVendor=1cf1, idProduct=0030, bcdDevice= 1.00 May 26 19:07:52 raspberry kernel: usb 1-1.3: New USB device strings: Mfr=1, Product=2, SerialNumber=3 May 26 19:07:52 raspberry kernel: usb 1-1.3: Product: ConBee II May 26 19:07:52 raspberry kernel: usb 1-1.3: Manufacturer: dresden elektronik ingenieurtechnik GmbH May 26 19:07:52 raspberry kernel: usb 1-1.3: SerialNumber: DE2482452 May 26 19:07:52 raspberry initramfs: Checking for USB updates May 26 19:07:52 raspberry initramfs: No USB device detected (when incorrect, try adding 'bootdelay=5' to your boot cmdline) May 26 19:07:52 raspberry kernel: EXT4-fs (mmcblk0p3): recovery complete May 26 19:07:52 raspberry kernel: EXT4-fs (mmcblk0p3): mounted filesystem with ordered data mode. Opts: (null) May 26 19:07:52 raspberry initramfs: With Option: May 26 19:07:52 raspberry initramfs: VOLUMIO_VERSION="3.251" May 26 19:07:52 raspberry initramfs: Finish initramfs, continue booting Volumio May 26 19:07:52 raspberry systemd[1]: System time before build time, advancing clock. May 26 19:07:52 raspberry kernel: NET: Registered protocol family 10 May 26 19:07:52 raspberry kernel: Segment Routing with IPv6 May 26 19:07:52 raspberry 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) May 26 19:07:52 raspberry systemd[1]: Detected architecture arm. May 26 19:07:52 raspberry systemd[1]: Set hostname to . May 26 19:07:52 raspberry 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. May 26 19:07:52 raspberry kernel: random: systemd: uninitialized urandom read (16 bytes read) May 26 19:07:52 raspberry kernel: random: systemd: uninitialized urandom read (16 bytes read) May 26 19:07:52 raspberry kernel: random: systemd: uninitialized urandom read (16 bytes read) May 26 19:07:52 raspberry systemd[1]: Listening on initctl Compatibility Named Pipe. May 26 19:07:52 raspberry systemd[1]: Listening on RPCbind Server Activation Socket. May 26 19:07:52 raspberry systemd[1]: Created slice system-getty.slice. May 26 19:07:52 raspberry systemd[1]: Created slice system-systemd\x2dfsck.slice. May 26 19:07:52 raspberry systemd[1]: Reached target System Time Synchronized. May 26 19:07:52 raspberry systemd[1]: Set up automount Arbitrary Executable File Formats File System Automount Point. May 26 19:07:52 raspberry kernel: i2c /dev entries driver May 26 19:07:52 raspberry systemd-journald[199]: Journal started May 26 19:07:52 raspberry systemd-journald[199]: Runtime journal (/run/log/journal/f19fe563bf7dcaf9ed2201976245a35f) is 7.5M, max 30.0M, 22.5M free. Feb 14 10:11:59 raspberry systemd-modules-load[201]: Inserted module 'i2c_dev' May 26 19:07:52 raspberry systemd[1]: Started Apply Kernel Variables. May 26 19:07:52 raspberry fake-hwclock[197]: Mon May 26 19:07:52 UTC 2025 May 26 19:07:52 raspberry systemd[1]: Started Load/Save Random Seed. May 26 19:07:52 raspberry systemd[1]: Started Create System Users. May 26 19:07:52 raspberry systemd[1]: Starting Create Static Device Nodes in /dev... May 26 19:07:52 raspberry systemd[1]: dynamicswap.service: Succeeded. May 26 19:07:52 raspberry systemd[1]: Started Create Static Device Nodes in /dev. May 26 19:07:52 raspberry systemd[1]: Reached target Local File Systems (Pre). May 26 19:07:52 raspberry systemd[1]: tmp.mount: Directory /tmp to mount over is not empty, mounting anyway. May 26 19:07:52 raspberry systemd[1]: Mounting /tmp... May 26 19:07:52 raspberry systemd[1]: var-log.mount: Directory /var/log to mount over is not empty, mounting anyway. May 26 19:07:52 raspberry systemd[1]: Mounting /var/log... May 26 19:07:52 raspberry systemd[1]: Mounting /var/spool/cups... May 26 19:07:52 raspberry systemd[1]: Starting udev Kernel Device Manager... May 26 19:07:52 raspberry systemd[1]: Mounted /tmp. May 26 19:07:52 raspberry systemd[1]: Mounted /var/log. May 26 19:07:52 raspberry systemd[1]: Mounted /var/spool/cups. May 26 19:07:52 raspberry systemd[1]: Mounting /var/spool/cups/tmp... May 26 19:07:52 raspberry systemd[1]: Starting Flush Journal to Persistent Storage... May 26 19:07:52 raspberry systemd[1]: Mounted /var/spool/cups/tmp. May 26 19:07:52 raspberry systemd-udevd[223]: Network interface NamePolicy= disabled on kernel command line, ignoring. May 26 19:07:52 raspberry systemd[1]: Started udev Coldplug all Devices. May 26 19:07:52 raspberry systemd[1]: Starting Helper to synchronize boot up for ifupdown... May 26 19:07:52 raspberry systemd-journald[199]: Runtime journal (/run/log/journal/f19fe563bf7dcaf9ed2201976245a35f) is 7.5M, max 30.0M, 22.5M free. May 26 19:07:52 raspberry systemd[1]: Started Flush Journal to Persistent Storage. May 26 19:07:52 raspberry systemd[1]: Started udev Kernel Device Manager. May 26 19:07:52 raspberry systemd[1]: Starting Show Plymouth Boot Screen... May 26 19:07:52 raspberry systemd[1]: Started Helper to synchronize boot up for ifupdown. May 26 19:07:52 raspberry systemd[1]: Received SIGRTMIN+20 from PID 242 (plymouthd). May 26 19:07:52 raspberry systemd[1]: Started Show Plymouth Boot Screen. May 26 19:07:52 raspberry systemd[1]: Started Forward Password Requests to Plymouth Directory Watch. May 26 19:07:52 raspberry systemd[1]: Condition check resulted in Dispatch Password Requests to Console Directory Watch being skipped. May 26 19:07:52 raspberry systemd[1]: Reached target Local Encrypted Volumes. May 26 19:07:52 raspberry systemd[1]: Reached target Paths. May 26 19:07:52 raspberry kernel: rpivid-mem feb00000.hevc-decoder: rpivid-hevcmem initialised: Registers at 0xfeb00000 length 0x00010000 May 26 19:07:52 raspberry kernel: rpivid-mem feb10000.rpivid-local-intc: rpivid-intcmem initialised: Registers at 0xfeb10000 length 0x00001000 May 26 19:07:52 raspberry kernel: rpivid-mem feb20000.h264-decoder: rpivid-h264mem initialised: Registers at 0xfeb20000 length 0x00010000 May 26 19:07:52 raspberry kernel: rpivid-mem feb30000.vp9-decoder: rpivid-vp9mem initialised: Registers at 0xfeb30000 length 0x00010000 May 26 19:07:52 raspberry systemd-udevd[246]: Using default interface naming scheme 'v240'. May 26 19:07:52 raspberry kernel: vc_sm_cma: module is from the staging directory, the quality is unknown, you have been warned. May 26 19:07:52 raspberry kernel: bcm2835_vc_sm_cma_probe: Videocore shared memory driver May 26 19:07:52 raspberry kernel: [vc_sm_connected_init]: start May 26 19:07:52 raspberry kernel: [vc_sm_connected_init]: installed successfully May 26 19:07:52 raspberry kernel: mc: Linux media interface: v0.10 May 26 19:07:53 raspberry kernel: videodev: Linux video capture interface: v2.00 May 26 19:07:53 raspberry kernel: bcm2835_mmal_vchiq: module is from the staging directory, the quality is unknown, you have been warned. May 26 19:07:53 raspberry kernel: bcm2835_mmal_vchiq: module is from the staging directory, the quality is unknown, you have been warned. May 26 19:07:53 raspberry kernel: bcm2835_isp: module is from the staging directory, the quality is unknown, you have been warned. May 26 19:07:53 raspberry kernel: bcm2835_codec: module is from the staging directory, the quality is unknown, you have been warned. May 26 19:07:53 raspberry kernel: snd_bcm2835: module is from the staging directory, the quality is unknown, you have been warned. May 26 19:07:53 raspberry kernel: bcm2835-codec bcm2835-codec: Device registered as /dev/video10 May 26 19:07:53 raspberry kernel: bcm2835-codec bcm2835-codec: Loaded V4L2 decode May 26 19:07:53 raspberry kernel: bcm2835_v4l2: module is from the staging directory, the quality is unknown, you have been warned. May 26 19:07:53 raspberry kernel: bcm2835-codec bcm2835-codec: Device registered as /dev/video11 May 26 19:07:53 raspberry kernel: bcm2835-codec bcm2835-codec: Loaded V4L2 encode May 26 19:07:53 raspberry kernel: bcm2835_audio bcm2835_audio: card created with 4 channels May 26 19:07:53 raspberry kernel: bcm2835-isp bcm2835-isp: Device node output[0] registered as /dev/video13 May 26 19:07:53 raspberry kernel: bcm2835-isp bcm2835-isp: Device node capture[0] registered as /dev/video14 May 26 19:07:53 raspberry kernel: bcm2835-isp bcm2835-isp: Device node capture[1] registered as /dev/video15 May 26 19:07:53 raspberry kernel: bcm2835-isp bcm2835-isp: Device node stats[2] registered as /dev/video16 May 26 19:07:53 raspberry kernel: bcm2835-isp bcm2835-isp: Register output node 0 with media controller May 26 19:07:53 raspberry kernel: bcm2835-isp bcm2835-isp: Register capture node 1 with media controller May 26 19:07:53 raspberry kernel: bcm2835-isp bcm2835-isp: Register capture node 2 with media controller May 26 19:07:53 raspberry kernel: bcm2835-isp bcm2835-isp: Register capture node 3 with media controller May 26 19:07:53 raspberry kernel: bcm2835_audio bcm2835_audio: card created with 4 channels May 26 19:07:53 raspberry kernel: bcm2835-codec bcm2835-codec: Device registered as /dev/video12 May 26 19:07:53 raspberry kernel: bcm2835-codec bcm2835-codec: Loaded V4L2 isp May 26 19:07:53 raspberry kernel: bcm2835-isp bcm2835-isp: Device node output[0] registered as /dev/video20 May 26 19:07:53 raspberry kernel: bcm2835-codec bcm2835-codec: Device registered as /dev/video18 May 26 19:07:53 raspberry kernel: bcm2835-codec bcm2835-codec: Loaded V4L2 image_fx May 26 19:07:53 raspberry kernel: bcm2835-isp bcm2835-isp: Device node capture[0] registered as /dev/video21 May 26 19:07:53 raspberry kernel: bcm2835-isp bcm2835-isp: Device node capture[1] registered as /dev/video22 May 26 19:07:53 raspberry kernel: bcm2835-isp bcm2835-isp: Device node stats[2] registered as /dev/video23 May 26 19:07:53 raspberry kernel: bcm2835-isp bcm2835-isp: Register output node 0 with media controller May 26 19:07:53 raspberry kernel: bcm2835-isp bcm2835-isp: Register capture node 1 with media controller May 26 19:07:53 raspberry kernel: bcm2835-isp bcm2835-isp: Register capture node 2 with media controller May 26 19:07:53 raspberry kernel: bcm2835-isp bcm2835-isp: Register capture node 3 with media controller May 26 19:07:53 raspberry kernel: bcm2835-isp bcm2835-isp: Loaded V4L2 bcm2835-isp May 26 19:07:53 raspberry systemd-udevd[306]: link_config: autonegotiation is unset or enabled, the speed and duplex are not writable. May 26 19:07:53 raspberry systemd-udevd[246]: link_config: autonegotiation is unset or enabled, the speed and duplex are not writable. May 26 19:07:53 raspberry kernel: cdc_acm 1-1.3:1.0: ttyACM0: USB ACM device May 26 19:07:53 raspberry kernel: usbcore: registered new interface driver cdc_acm May 26 19:07:53 raspberry kernel: cdc_acm: USB Abstract Control Model driver for USB modems and ISDN adapters May 26 19:07:54 raspberry kernel: cfg80211: Loading compiled-in X.509 certificates for regulatory database May 26 19:07:54 raspberry kernel: cfg80211: Loaded X.509 cert 'sforshee: 00b28ddf47aef9cea7' May 26 19:07:54 raspberry systemd[1]: Found device /dev/mmcblk0p1. May 26 19:07:55 raspberry kernel: brcmfmac: F1 signature read @0x18000000=0x15264345 May 26 19:07:55 raspberry kernel: brcmfmac: brcmf_fw_alloc_request: using brcm/brcmfmac43455-sdio for chip BCM4345/6 May 26 19:07:55 raspberry kernel: usbcore: registered new interface driver brcmfmac May 26 19:07:55 raspberry kernel: brcmfmac: brcmf_fw_alloc_request: using brcm/brcmfmac43455-sdio for chip BCM4345/6 May 26 19:07:55 raspberry kernel: brcmfmac: brcmf_fw_alloc_request: using brcm/brcmfmac43455-sdio for chip BCM4345/6 May 26 19:07:55 raspberry kernel: brcmfmac: brcmf_c_preinit_dcmds: Firmware: BCM4345/6 wl0: Jan 4 2021 19:56:29 version 7.45.229 (617f1f5 CY) FWID 01-2dbd9d2e May 26 19:07:55 raspberry systemd-udevd[253]: Using default interface naming scheme 'v240'. May 26 19:07:55 raspberry systemd-udevd[253]: link_config: autonegotiation is unset or enabled, the speed and duplex are not writable. May 26 19:07:55 raspberry systemd[1]: Listening on Load/Save RF Kill Switch Status /dev/rfkill Watch. May 26 19:07:55 raspberry systemd[1]: Condition check resulted in Set Up Additional Binary Formats being skipped. May 26 19:07:55 raspberry systemd[1]: Condition check resulted in Huge Pages File System being skipped. May 26 19:07:55 raspberry systemd[1]: Condition check resulted in Dispatch Password Requests to Console Directory Watch being skipped. May 26 19:07:55 raspberry systemd[1]: Condition check resulted in FUSE Control File System being skipped. May 26 19:07:55 raspberry systemd[1]: Condition check resulted in Rebuild Hardware Database being skipped. May 26 19:07:55 raspberry systemd[1]: Starting File System Check on /dev/mmcblk0p1... May 26 19:07:55 raspberry systemd[1]: Starting Load/Save RF Kill Switch Status... May 26 19:07:55 raspberry systemd[1]: Started Load/Save RF Kill Switch Status. May 26 19:07:55 raspberry systemd[1]: Found device /sys/subsystem/net/devices/eth0. May 26 19:07:55 raspberry systemd[1]: Started File System Check Daemon to report status. May 26 19:07:55 raspberry systemd-fsck[392]: fsck.fat 4.1 (2017-01-24) May 26 19:07:55 raspberry systemd-fsck[392]: /dev/mmcblk0p1: 297 files, 27490/46774 clusters May 26 19:07:55 raspberry systemd[1]: Started File System Check on /dev/mmcblk0p1. May 26 19:07:55 raspberry systemd[1]: Mounting /boot... May 26 19:07:55 raspberry systemd[1]: Found device /sys/subsystem/net/devices/wlan0. May 26 19:07:56 raspberry systemd[1]: Mounted /boot. May 26 19:07:56 raspberry systemd[1]: Reached target Local File Systems. May 26 19:07:56 raspberry systemd[1]: Started ifup for eth0. May 26 19:07:56 raspberry systemd[1]: Starting Raise network interfaces... May 26 19:07:56 raspberry systemd[1]: Started ifup for wlan0. May 26 19:07:56 raspberry systemd[1]: Starting Tell Plymouth To Write Out Runtime Data... May 26 19:07:56 raspberry systemd[1]: Starting Create Volatile Files and Directories... May 26 19:07:56 raspberry systemd[1]: Condition check resulted in Commit a transient machine-id on disk being skipped. May 26 19:07:56 raspberry systemd[1]: Starting Preprocess NFS configuration... May 26 19:07:56 raspberry systemd[1]: Received SIGRTMIN+20 from PID 242 (plymouthd). May 26 19:07:56 raspberry systemd[1]: plymouth-read-write.service: Succeeded. May 26 19:07:56 raspberry systemd[1]: Started Tell Plymouth To Write Out Runtime Data. May 26 19:07:56 raspberry systemd[1]: nfs-config.service: Succeeded. May 26 19:07:56 raspberry systemd[1]: Started Preprocess NFS configuration. May 26 19:07:56 raspberry systemd[1]: Condition check resulted in RPC security service for NFS server being skipped. May 26 19:07:56 raspberry systemd[1]: Condition check resulted in RPC security service for NFS client and server being skipped. May 26 19:07:56 raspberry systemd[1]: Reached target NFS client services. May 26 19:07:56 raspberry systemd[1]: Started Create Volatile Files and Directories. May 26 19:07:56 raspberry systemd[1]: Started Entropy daemon using the HAVEGE algorithm. May 26 19:07:56 raspberry systemd[1]: Starting RPC bind portmap service... May 26 19:07:56 raspberry systemd[1]: Condition check resulted in Network Time Synchronization being skipped. May 26 19:07:56 raspberry systemd[1]: Starting Update UTMP about System Boot/Shutdown... May 26 19:07:56 raspberry systemd[1]: Started Update UTMP about System Boot/Shutdown. May 26 19:07:56 raspberry systemd[1]: Reached target System Initialization. May 26 19:07:56 raspberry systemd[1]: Starting Docker Socket for the API. May 26 19:07:56 raspberry systemd[1]: Started Daily Cleanup of Temporary Directories. May 26 19:07:56 raspberry systemd[1]: Listening on D-Bus System Message Bus Socket. May 26 19:07:56 raspberry systemd[1]: Listening on Avahi mDNS/DNS-SD Stack Activation Socket. May 26 19:07:56 raspberry systemd[1]: Listening on triggerhappy.socket. May 26 19:07:56 raspberry systemd[1]: Started Daily apt download activities. May 26 19:07:56 raspberry systemd[1]: Started Daily apt upgrade and clean activities. May 26 19:07:56 raspberry systemd[1]: Reached target Timers. May 26 19:07:56 raspberry systemd[1]: Listening on Docker Socket for the API. May 26 19:07:56 raspberry systemd[1]: Reached target Sockets. May 26 19:07:56 raspberry systemd[1]: Reached target Basic System. May 26 19:07:56 raspberry systemd[1]: Started Volumio Iptables Module. May 26 19:07:56 raspberry systemd[1]: Condition check resulted in Copy user wpa_supplicant.conf being skipped. May 26 19:07:56 raspberry systemd[1]: Starting dhcpcd on all interfaces... May 26 19:07:56 raspberry systemd[1]: Starting Wireless Services... May 26 19:07:56 raspberry systemd[1]: Condition check resulted in Volumio SSH enabler being skipped. May 26 19:07:56 raspberry systemd[1]: Started Manage Sound Card State (restore and store). May 26 19:07:56 raspberry systemd[1]: Starting triggerhappy global hotkey daemon... May 26 19:07:56 raspberry systemd[1]: Started D-Bus System Message Bus. May 26 19:07:56 raspberry alsactl[475]: alsactl 1.1.8 daemon started May 26 19:07:56 raspberry dhcpcd[473]: Not running dhcpcd because /etc/network/interfaces May 26 19:07:56 raspberry kernel: 8021q: 802.1Q VLAN Support v1.8 May 26 19:07:56 raspberry systemd[1]: Started volumio-remote-updater.service. May 26 19:07:56 raspberry dhcpcd[473]: defines some interfaces that will use a May 26 19:07:56 raspberry dhcpcd[473]: DHCP client or static address May 26 19:07:56 raspberry systemd[1]: Starting Login Service... May 26 19:07:56 raspberry systemd[1]: Starting Avahi mDNS/DNS-SD Stack... May 26 19:07:56 raspberry systemd[1]: Starting Configure Bluetooth Modems connected by UART... May 26 19:07:56 raspberry systemd[1]: Starting Save/Restore Sound Card State... May 26 19:07:56 raspberry systemd[1]: Started UPnP Renderer front-end to MPD. May 26 19:07:56 raspberry systemd[1]: Condition check resulted in getty on tty2-tty6 if dbus and logind are not available being skipped. May 26 19:07:56 raspberry systemd[1]: Starting WPA supplicant... May 26 19:07:56 raspberry systemd[1]: dhcpcd.service: Control process exited, code=exited, status=6/NOTCONFIGURED May 26 19:07:56 raspberry systemd[1]: dhcpcd.service: Failed with result 'exit-code'. May 26 19:07:56 raspberry systemd[1]: Failed to start dhcpcd on all interfaces. May 26 19:07:56 raspberry systemd[1]: Started Save/Restore Sound Card State. May 26 19:07:56 raspberry systemd[1]: Reached target Sound Card. May 26 19:07:57 raspberry systemd-logind[481]: New seat seat0. May 26 19:07:57 raspberry kernel: uart-pl011 fe201000.serial: no DMA platform data May 26 19:07:57 raspberry kernel: brcmfmac: brcmf_cfg80211_set_power_mgmt: power save disabled May 26 19:07:57 raspberry sh[400]: eth0: waiting for carrier May 26 19:07:57 raspberry kernel: bcmgenet fd580000.ethernet: configuring instance for external RGMII (RX delay) May 26 19:07:57 raspberry kernel: bcmgenet fd580000.ethernet eth0: Link is Down May 26 19:07:57 raspberry dhcpcd[450]: eth0: waiting for carrier May 26 19:07:57 raspberry avahi-daemon[482]: Found user 'avahi' (UID 110) and group 'avahi' (GID 113). May 26 19:07:57 raspberry avahi-daemon[482]: Successfully dropped root privileges. May 26 19:07:57 raspberry avahi-daemon[482]: avahi-daemon 0.7 starting up. May 26 19:07:57 raspberry thd[476]: Unable to parse trigger line: May 26 19:07:57 raspberry thd[476]: Unable to parse trigger line: KEY_MIN_INTERESTING 1 /usr/local/bin/volumio volume toggle May 26 19:07:57 raspberry thd[476]: Unable to parse trigger line: May 26 19:07:58 raspberry thd[476]: Found socket passed from systemd May 26 19:07:58 raspberry systemd[1]: Started Login Service. May 26 19:07:58 raspberry systemd[1]: Started triggerhappy global hotkey daemon. May 26 19:07:58 raspberry systemd[1]: Started RPC bind portmap service. May 26 19:07:58 raspberry avahi-daemon[482]: Successfully called chroot(). May 26 19:07:58 raspberry avahi-daemon[482]: Successfully dropped remaining capabilities. May 26 19:07:58 raspberry avahi-daemon[482]: Loading service file /services/volumio.service. May 26 19:07:58 raspberry avahi-daemon[482]: Network interface enumeration completed. May 26 19:07:58 raspberry avahi-daemon[482]: Server startup complete. Host name is raspberry.local. Local service cookie is 2994598480. May 26 19:07:58 raspberry avahi-daemon[482]: Service "Raspberry" (/services/volumio.service) successfully established. May 26 19:07:58 raspberry systemd[1]: Started Avahi mDNS/DNS-SD Stack. May 26 19:07:58 raspberry systemd[1]: Reached target RPC Port Mapper. May 26 19:07:58 raspberry systemd[1]: Reached target Remote File Systems (Pre). May 26 19:07:58 raspberry systemd[1]: Reached target Remote File Systems. May 26 19:07:58 raspberry systemd[1]: Starting LSB: Load kernel modules needed to enable cpufreq scaling... May 26 19:07:58 raspberry systemd[1]: iptables.service: Succeeded. May 26 19:07:59 raspberry sh[403]: wlan0=wlan0 May 26 19:07:59 raspberry systemd[1]: Started Raise network interfaces. May 26 19:07:59 raspberry systemd[1]: Started WPA supplicant. May 26 19:07:59 raspberry systemd[1]: Reached target Network. May 26 19:07:59 raspberry wpa_supplicant[486]: Successfully initialized wpa_supplicant May 26 19:07:59 raspberry systemd[1]: Reached target Network is Online. May 26 19:07:59 raspberry systemd[1]: Starting LSB: Brings up/down network automatically... May 26 19:07:59 raspberry systemd[1]: Starting Transmission BitTorrent Daemon... May 26 19:07:59 raspberry systemd[1]: Condition check resulted in fast remote file copy program daemon being skipped. May 26 19:07:59 raspberry systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. May 26 19:07:59 raspberry systemd[1]: Starting Samba NMB Daemon... May 26 19:07:59 raspberry systemd[1]: Starting OpenBSD Secure Shell server... May 26 19:07:59 raspberry systemd[1]: Starting /etc/rc.local Compatibility... May 26 19:07:59 raspberry systemd[1]: Starting containerd container runtime... May 26 19:07:59 raspberry systemd[1]: Starting Permit User Sessions... May 26 19:07:59 raspberry systemd[1]: Starting Network Time Service... May 26 19:07:59 raspberry loadcpufreq[545]: Loading cpufreq kernel modules...done (none). May 26 19:07:59 raspberry systemd[1]: Started LSB: Load kernel modules needed to enable cpufreq scaling. May 26 19:07:59 raspberry systemd[1]: Starting LSB: set CPUFreq kernel parameters... May 26 19:07:59 raspberry systemd[1]: Started /etc/rc.local Compatibility. May 26 19:07:59 raspberry systemd[1]: Started Permit User Sessions. May 26 19:07:59 raspberry systemd[1]: Starting Hold until boot process finishes up... May 26 19:07:59 raspberry systemd[1]: Starting Terminate Plymouth Boot Screen... May 26 19:07:59 raspberry systemd[1]: Received SIGRTMIN+21 from PID 242 (plymouthd). May 26 19:07:59 raspberry systemd[1]: Received SIGRTMIN+21 from PID 242 (plymouthd). May 26 19:08:00 raspberry systemd[1]: plymouth-quit.service: Succeeded. May 26 19:08:00 raspberry systemd[1]: Started Terminate Plymouth Boot Screen. May 26 19:08:00 raspberry systemd[1]: plymouth-quit-wait.service: Succeeded. May 26 19:08:00 raspberry ifplugd(eth0)[635]: ifplugd 0.28 initializing. May 26 19:08:00 raspberry ifplugd(eth0)[635]: Using interface eth0/E4:5F:01:A4:7E:9C with driver (version: 5.10.92-v7l+) May 26 19:08:00 raspberry ifplugd(eth0)[635]: Using detection mode: SIOCETHTOOL May 26 19:08:00 raspberry ifplugd(eth0)[635]: Initialization complete, link beat not detected. May 26 19:08:00 raspberry systemd[1]: Started Hold until boot process finishes up. May 26 19:08:00 raspberry systemd[1]: Started Getty on tty1. May 26 19:08:00 raspberry systemd[1]: Reached target Login Prompts. May 26 19:08:00 raspberry ifplugd[597]: Network Interface Plugging Daemon...start eth0...done. May 26 19:08:00 raspberry systemd[1]: Started LSB: Brings up/down network automatically. May 26 19:08:00 raspberry haveged[439]: haveged: ver: 1.9.1; arch: generic; vend: ; build: (gcc 8.2.0 CTV); collect: 128K May 26 19:08:00 raspberry haveged[439]: haveged: cpu: (VC); data: 16K (D); inst: 16K (D); idx: 11/40; sz: 14768/63488 May 26 19:08:00 raspberry haveged[439]: haveged: tot tests(BA8): A:1/1 B:1/1 continuous tests(B): last entropy estimate 8.00085 May 26 19:08:00 raspberry haveged[439]: haveged: fills: 0, generated: 0 May 26 19:08:00 raspberry kernel: random: crng init done May 26 19:08:00 raspberry kernel: random: 7 urandom warning(s) missed due to ratelimiting May 26 19:08:00 raspberry systemd[1]: systemd-rfkill.service: Succeeded. May 26 19:08:00 raspberry cpufrequtils[614]: CPUFreq Utilities: Setting performance CPUFreq governor...error: unexpectedly disconnected from boot status daemon May 26 19:08:00 raspberry systemd[1]: plymouth-start.service: Succeeded. May 26 19:08:00 raspberry cpufrequtils[614]: CPU0...CPU1...CPU2...CPU3...done. May 26 19:08:00 raspberry systemd[1]: Started LSB: set CPUFreq kernel parameters. May 26 19:08:00 raspberry ntpd[612]: ntpd 4.2.8p12@1.3728-o (1): Starting May 26 19:08:00 raspberry ntpd[612]: Command line: /usr/sbin/ntpd -p /var/run/ntpd.pid -g -u 103:103 May 26 19:08:00 raspberry systemd[1]: Started Network Time Service. May 26 19:08:00 raspberry containerd[615]: time="2025-05-26T19:08:00Z" level=warning msg="deprecated version : `1`, please switch to version `2`" May 26 19:08:00 raspberry containerd[615]: time="2025-05-26T19:08:00.991122013Z" level=info msg="starting containerd" revision=3df54a852345ae127d1fa3092b95168e4a88e2f8 version=1.5.11 May 26 19:08:01 raspberry ntpd[653]: proto: precision = 0.815 usec (-20) May 26 19:08:01 raspberry ntpd[653]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): good hash signature May 26 19:08:01 raspberry ntpd[653]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): loaded, expire=2022-06-28T00:00:00Z last=2017-01-01T00:00:00Z ofs=37 May 26 19:08:01 raspberry ntpd[653]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): expired less than 1064 days ago May 26 19:08:01 raspberry ntpd[653]: Listen and drop on 0 v6wildcard [::]:123 May 26 19:08:01 raspberry ntpd[653]: Listen and drop on 1 v4wildcard 0.0.0.0:123 May 26 19:08:01 raspberry ntpd[653]: Listen normally on 2 lo 127.0.0.1:123 May 26 19:08:01 raspberry ntpd[653]: Listening on routing socket on fd #19 for interface updates May 26 19:08:01 raspberry ntpd[653]: kernel reports TIME_ERROR: 0x41: Clock Unsynchronized May 26 19:08:01 raspberry ntpd[653]: kernel reports TIME_ERROR: 0x41: Clock Unsynchronized May 26 19:08:01 raspberry containerd[615]: time="2025-05-26T19:08:01.153312993Z" level=info msg="loading plugin \"io.containerd.content.v1.content\"..." type=io.containerd.content.v1 May 26 19:08:01 raspberry containerd[615]: time="2025-05-26T19:08:01.157286256Z" level=info msg="loading plugin \"io.containerd.snapshotter.v1.aufs\"..." type=io.containerd.snapshotter.v1 May 26 19:08:01 raspberry containerd[615]: time="2025-05-26T19:08:01.167645772Z" level=info msg="skip loading plugin \"io.containerd.snapshotter.v1.aufs\"..." error="aufs is not supported (modprobe aufs failed: exit status 1 \"modprobe: FATAL: Module aufs not found in directory /lib/modules/5.10.92-v7l+\\n\"): skip plugin" type=io.containerd.snapshotter.v1 May 26 19:08:01 raspberry containerd[615]: time="2025-05-26T19:08:01.167824661Z" level=info msg="loading plugin \"io.containerd.snapshotter.v1.btrfs\"..." type=io.containerd.snapshotter.v1 May 26 19:08:01 raspberry containerd[615]: time="2025-05-26T19:08:01.168528436Z" level=info msg="skip loading plugin \"io.containerd.snapshotter.v1.btrfs\"..." error="path /var/lib/containerd/io.containerd.snapshotter.v1.btrfs (overlay) must be a btrfs filesystem to be used with the btrfs snapshotter: skip plugin" type=io.containerd.snapshotter.v1 May 26 19:08:01 raspberry containerd[615]: time="2025-05-26T19:08:01.168617732Z" level=info msg="loading plugin \"io.containerd.snapshotter.v1.devmapper\"..." type=io.containerd.snapshotter.v1 May 26 19:08:01 raspberry containerd[615]: time="2025-05-26T19:08:01.168694546Z" level=warning msg="failed to load plugin io.containerd.snapshotter.v1.devmapper" error="devmapper not configured" May 26 19:08:01 raspberry containerd[615]: time="2025-05-26T19:08:01.168748620Z" level=info msg="loading plugin \"io.containerd.snapshotter.v1.native\"..." type=io.containerd.snapshotter.v1 May 26 19:08:01 raspberry containerd[615]: time="2025-05-26T19:08:01.170800501Z" level=info msg="loading plugin \"io.containerd.snapshotter.v1.overlayfs\"..." type=io.containerd.snapshotter.v1 May 26 19:08:01 raspberry containerd[615]: time="2025-05-26T19:08:01.173769268Z" level=info msg="loading plugin \"io.containerd.snapshotter.v1.zfs\"..." type=io.containerd.snapshotter.v1 May 26 19:08:01 raspberry containerd[615]: time="2025-05-26T19:08:01.174620728Z" level=info msg="skip loading plugin \"io.containerd.snapshotter.v1.zfs\"..." error="path /var/lib/containerd/io.containerd.snapshotter.v1.zfs must be a zfs filesystem to be used with the zfs snapshotter: skip plugin" type=io.containerd.snapshotter.v1 May 26 19:08:01 raspberry containerd[615]: time="2025-05-26T19:08:01.174731727Z" level=info msg="loading plugin \"io.containerd.metadata.v1.bolt\"..." type=io.containerd.metadata.v1 May 26 19:08:01 raspberry containerd[615]: time="2025-05-26T19:08:01.177221051Z" level=warning msg="could not use snapshotter devmapper in metadata plugin" error="devmapper not configured" May 26 19:08:01 raspberry containerd[615]: time="2025-05-26T19:08:01.177329125Z" level=info msg="metadata content store policy set" policy=shared May 26 19:08:01 raspberry containerd[615]: time="2025-05-26T19:08:01.193345157Z" level=info msg="loading plugin \"io.containerd.differ.v1.walking\"..." type=io.containerd.differ.v1 May 26 19:08:01 raspberry containerd[615]: time="2025-05-26T19:08:01.193486083Z" level=info msg="loading plugin \"io.containerd.gc.v1.scheduler\"..." type=io.containerd.gc.v1 May 26 19:08:01 raspberry containerd[615]: time="2025-05-26T19:08:01.198472323Z" level=info msg="loading plugin \"io.containerd.service.v1.introspection-service\"..." type=io.containerd.service.v1 May 26 19:08:01 raspberry containerd[615]: time="2025-05-26T19:08:01.199189876Z" level=info msg="loading plugin \"io.containerd.service.v1.containers-service\"..." type=io.containerd.service.v1 May 26 19:08:01 raspberry containerd[615]: time="2025-05-26T19:08:01.199724948Z" level=info msg="loading plugin \"io.containerd.service.v1.content-service\"..." type=io.containerd.service.v1 May 26 19:08:01 raspberry containerd[615]: time="2025-05-26T19:08:01.199967521Z" level=info msg="loading plugin \"io.containerd.service.v1.diff-service\"..." type=io.containerd.service.v1 May 26 19:08:01 raspberry containerd[615]: time="2025-05-26T19:08:01.200203891Z" level=info msg="loading plugin \"io.containerd.service.v1.images-service\"..." type=io.containerd.service.v1 May 26 19:08:01 raspberry containerd[615]: time="2025-05-26T19:08:01.200424242Z" level=info msg="loading plugin \"io.containerd.service.v1.leases-service\"..." type=io.containerd.service.v1 May 26 19:08:01 raspberry containerd[615]: time="2025-05-26T19:08:01.200636500Z" level=info msg="loading plugin \"io.containerd.service.v1.namespaces-service\"..." type=io.containerd.service.v1 May 26 19:08:01 raspberry containerd[615]: time="2025-05-26T19:08:01.200865703Z" level=info msg="loading plugin \"io.containerd.service.v1.snapshots-service\"..." type=io.containerd.service.v1 May 26 19:08:01 raspberry containerd[615]: time="2025-05-26T19:08:01.201078961Z" level=info msg="loading plugin \"io.containerd.runtime.v1.linux\"..." type=io.containerd.runtime.v1 May 26 19:08:01 raspberry containerd[615]: time="2025-05-26T19:08:01.201476960Z" level=info msg="loading plugin \"io.containerd.runtime.v2.task\"..." type=io.containerd.runtime.v2 May 26 19:08:01 raspberry containerd[615]: time="2025-05-26T19:08:01.204179024Z" level=info msg="loading plugin \"io.containerd.monitor.v1.cgroups\"..." type=io.containerd.monitor.v1 May 26 19:08:01 raspberry containerd[615]: time="2025-05-26T19:08:01.206414275Z" level=info msg="loading plugin \"io.containerd.service.v1.tasks-service\"..." type=io.containerd.service.v1 May 26 19:08:01 raspberry containerd[615]: time="2025-05-26T19:08:01.206990087Z" level=info msg="loading plugin \"io.containerd.internal.v1.restart\"..." type=io.containerd.internal.v1 May 26 19:08:01 raspberry containerd[615]: time="2025-05-26T19:08:01.207689733Z" level=info msg="loading plugin \"io.containerd.grpc.v1.containers\"..." type=io.containerd.grpc.v1 May 26 19:08:01 raspberry containerd[615]: time="2025-05-26T19:08:01.208180694Z" level=info msg="loading plugin \"io.containerd.grpc.v1.content\"..." type=io.containerd.grpc.v1 May 26 19:08:01 raspberry containerd[615]: time="2025-05-26T19:08:01.208719377Z" level=info msg="loading plugin \"io.containerd.grpc.v1.diff\"..." type=io.containerd.grpc.v1 May 26 19:08:01 raspberry containerd[615]: time="2025-05-26T19:08:01.209164042Z" level=info msg="loading plugin \"io.containerd.grpc.v1.events\"..." type=io.containerd.grpc.v1 May 26 19:08:01 raspberry containerd[615]: time="2025-05-26T19:08:01.209721114Z" level=info msg="loading plugin \"io.containerd.grpc.v1.healthcheck\"..." type=io.containerd.grpc.v1 May 26 19:08:01 raspberry containerd[615]: time="2025-05-26T19:08:01.210080335Z" level=info msg="loading plugin \"io.containerd.grpc.v1.images\"..." type=io.containerd.grpc.v1 May 26 19:08:01 raspberry containerd[615]: time="2025-05-26T19:08:01.210311223Z" level=info msg="loading plugin \"io.containerd.grpc.v1.leases\"..." type=io.containerd.grpc.v1 May 26 19:08:01 raspberry containerd[615]: time="2025-05-26T19:08:01.210539796Z" level=info msg="loading plugin \"io.containerd.grpc.v1.namespaces\"..." type=io.containerd.grpc.v1 May 26 19:08:01 raspberry containerd[615]: time="2025-05-26T19:08:01.210745332Z" level=info msg="loading plugin \"io.containerd.internal.v1.opt\"..." type=io.containerd.internal.v1 May 26 19:08:01 raspberry containerd[615]: time="2025-05-26T19:08:01.230430814Z" level=info msg="loading plugin \"io.containerd.grpc.v1.snapshots\"..." type=io.containerd.grpc.v1 May 26 19:08:01 raspberry containerd[615]: time="2025-05-26T19:08:01.230552425Z" level=info msg="loading plugin \"io.containerd.grpc.v1.tasks\"..." type=io.containerd.grpc.v1 May 26 19:08:01 raspberry containerd[615]: time="2025-05-26T19:08:01.230620072Z" level=info msg="loading plugin \"io.containerd.grpc.v1.version\"..." type=io.containerd.grpc.v1 May 26 19:08:01 raspberry containerd[615]: time="2025-05-26T19:08:01.230679480Z" level=info msg="loading plugin \"io.containerd.grpc.v1.introspection\"..." type=io.containerd.grpc.v1 May 26 19:08:01 raspberry containerd[615]: time="2025-05-26T19:08:01.231587884Z" level=info msg=serving... address=/run/containerd/containerd.sock.ttrpc May 26 19:08:01 raspberry containerd[615]: time="2025-05-26T19:08:01.231814975Z" level=info msg=serving... address=/run/containerd/containerd.sock May 26 19:08:01 raspberry containerd[615]: time="2025-05-26T19:08:01.232055993Z" level=info msg="containerd successfully booted in 0.250134s" May 26 19:08:01 raspberry systemd[1]: Started containerd container runtime. May 26 19:08:01 raspberry systemd[1]: Starting Docker Application Container Engine... May 26 19:08:01 raspberry volumio-remote-updater[479]: Error: No active session May 26 19:08:01 raspberry volumio-remote-updater[479]: [2025-05-26 19:08:01] [info] asio async_connect error: system:111 (Connection refused) May 26 19:08:01 raspberry volumio-remote-updater[479]: [2025-05-26 19:08:01] [info] Error getting remote endpoint: system:107 (Transport endpoint is not connected) May 26 19:08:01 raspberry volumio-remote-updater[479]: [2025-05-26 19:08:01] [error] handle_connect error: Underlying Transport Error May 26 19:08:01 raspberry systemd[1]: Started Transmission BitTorrent Daemon. May 26 19:08:01 raspberry sshd[665]: Server listening on 0.0.0.0 port 22. May 26 19:08:01 raspberry sshd[665]: Server listening on :: port 22. May 26 19:08:01 raspberry systemd[1]: Started OpenBSD Secure Shell server. May 26 19:08:01 raspberry volumio[485]: Could not open config: /tmp/upmpdcli.conf May 26 19:08:01 raspberry systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE May 26 19:08:01 raspberry systemd[1]: upmpdcli.service: Failed with result 'exit-code'. May 26 19:08:02 raspberry ntpd[653]: error resolving pool 0.debian.pool.ntp.org: System error (-11) May 26 19:08:02 raspberry transmission-daemon[599]: [2025-05-26 19:08:02.505] UDP Failed to set receive buffer: requested 4194304, got 360448 (tr-udp.c:84) May 26 19:08:02 raspberry transmission-daemon[599]: [2025-05-26 19:08:02.505] UDP Failed to set send buffer: requested 1048576, got 360448 (tr-udp.c:95) May 26 19:08:02 raspberry nmbd[613]: [2025/05/26 19:08:02.548817, 0] ../source3/nmbd/asyncdns.c:158(start_async_dns) May 26 19:08:02 raspberry nmbd[613]: started asyncdns process 679 May 26 19:08:02 raspberry nmbd[613]: [2025/05/26 19:08:02.550876, 0] ../lib/util/become_daemon.c:149(daemon_status) May 26 19:08:02 raspberry nmbd[613]: daemon_status: STATUS=daemon 'nmbd' : No local IPv4 non-loopback interfaces available, waiting for interface ... May 26 19:08:02 raspberry nmbd[613]: [2025/05/26 19:08:02.551047, 0] ../source3/nmbd/nmbd_subnetdb.c:254(create_subnets) May 26 19:08:02 raspberry nmbd[613]: NOTE: NetBIOS name resolution is not supported for Internet Protocol Version 6 (IPv6). May 26 19:08:02 raspberry dockerd[658]: time="2025-05-26T19:08:02.864587758Z" level=info msg="Starting up" May 26 19:08:02 raspberry dockerd[658]: time="2025-05-26T19:08:02.886458898Z" level=info msg="parsed scheme: \"unix\"" module=grpc May 26 19:08:02 raspberry dockerd[658]: time="2025-05-26T19:08:02.886533916Z" level=info msg="scheme \"unix\" not registered, fallback to default scheme" module=grpc May 26 19:08:02 raspberry dockerd[658]: time="2025-05-26T19:08:02.886608656Z" level=info msg="ccResolverWrapper: sending update to cc: {[{unix:///run/containerd/containerd.sock 0 }] }" module=grpc May 26 19:08:02 raspberry dockerd[658]: time="2025-05-26T19:08:02.886671490Z" level=info msg="ClientConn switching balancer to \"pick_first\"" module=grpc May 26 19:08:02 raspberry dockerd[658]: time="2025-05-26T19:08:02.915716751Z" level=info msg="parsed scheme: \"unix\"" module=grpc May 26 19:08:02 raspberry dockerd[658]: time="2025-05-26T19:08:02.915876824Z" level=info msg="scheme \"unix\" not registered, fallback to default scheme" module=grpc May 26 19:08:02 raspberry dockerd[658]: time="2025-05-26T19:08:02.916037935Z" level=info msg="ccResolverWrapper: sending update to cc: {[{unix:///run/containerd/containerd.sock 0 }] }" module=grpc May 26 19:08:02 raspberry dockerd[658]: time="2025-05-26T19:08:02.916142249Z" level=info msg="ClientConn switching balancer to \"pick_first\"" module=grpc May 26 19:08:02 raspberry kernel: device-mapper: ioctl: 4.43.0-ioctl (2020-10-01) initialised: dm-devel@redhat.com May 26 19:08:03 raspberry ntpd[653]: error resolving pool 1.debian.pool.ntp.org: System error (-11) May 26 19:08:03 raspberry dockerd[658]: time="2025-05-26T19:08:03.225768047Z" level=warning msg="Usage of loopback devices is strongly discouraged for production use. Please use `--storage-opt dm.thinpooldev` or use `man dockerd` to refer to dm.thinpooldev section." storage-driver=devicemapper May 26 19:08:03 raspberry wireless.js[474]: WIRELESS DAEMON: start May 26 19:08:03 raspberry wireless.js[474]: WIRELESS: Loaded configuration May 26 19:08:03 raspberry wireless.js[474]: Cleaning previous... May 26 19:08:03 raspberry dockerd[658]: time="2025-05-26T19:08:03.382623642Z" level=warning msg="Base device already exists and has filesystem ext4 on it. User specified filesystem will be ignored." storage-driver=devicemapper May 26 19:08:03 raspberry sudo[704]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ip addr flush dev wlan0 May 26 19:08:03 raspberry sudo[704]: pam_unix(sudo:session): session opened for user root by (uid=0) May 26 19:08:03 raspberry sudo[704]: pam_unix(sudo:session): session closed for user root May 26 19:08:03 raspberry sudo[709]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 down May 26 19:08:03 raspberry sudo[709]: pam_unix(sudo:session): session opened for user root by (uid=0) May 26 19:08:03 raspberry dockerd[658]: time="2025-05-26T19:08:03.436163126Z" level=info msg="[graphdriver] using prior storage driver: devicemapper" May 26 19:08:03 raspberry dockerd[658]: time="2025-05-26T19:08:03.436516143Z" level=warning msg="[graphdriver] WARNING: the devicemapper storage-driver is deprecated, and will be removed in a future release" May 26 19:08:03 raspberry dockerd[658]: time="2025-05-26T19:08:03.538688851Z" level=warning msg="Your kernel does not support cgroup memory limit" May 26 19:08:03 raspberry dockerd[658]: time="2025-05-26T19:08:03.539131461Z" level=warning msg="Your kernel does not support CPU realtime scheduler" May 26 19:08:03 raspberry dockerd[658]: time="2025-05-26T19:08:03.539323830Z" level=warning msg="Your kernel does not support cgroup blkio weight" May 26 19:08:03 raspberry dockerd[658]: time="2025-05-26T19:08:03.539503922Z" level=warning msg="Your kernel does not support cgroup blkio weight_device" May 26 19:08:03 raspberry dockerd[658]: time="2025-05-26T19:08:03.540619344Z" level=info msg="Loading containers: start." May 26 19:08:03 raspberry sudo[709]: pam_unix(sudo:session): session closed for user root May 26 19:08:03 raspberry kernel: bridge: filtering via arp/ip/ip6tables is no longer available by default. Update your scripts to load br_netfilter if you need this. May 26 19:08:03 raspberry kernel: Bridge firewalling registered May 26 19:08:04 raspberry wireless.js[474]: Stopped aP May 26 19:08:04 raspberry wireless.js[474]: Start wireless flow May 26 19:08:04 raspberry wireless.js[474]: Stopped hotspot (if there).. May 26 19:08:04 raspberry sudo[723]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ip addr flush dev wlan0 May 26 19:08:04 raspberry sudo[723]: pam_unix(sudo:session): session opened for user root by (uid=0) May 26 19:08:04 raspberry sudo[723]: pam_unix(sudo:session): session closed for user root May 26 19:08:04 raspberry sudo[727]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 down May 26 19:08:04 raspberry sudo[727]: pam_unix(sudo:session): session opened for user root by (uid=0) May 26 19:08:04 raspberry sudo[727]: pam_unix(sudo:session): session closed for user root May 26 19:08:04 raspberry ntpd[653]: error resolving pool 2.debian.pool.ntp.org: System error (-11) May 26 19:08:04 raspberry wireless.js[474]: DHCP IP May 26 19:08:04 raspberry wireless.js[474]: Start ap May 26 19:08:04 raspberry wpa_supplicant[732]: Successfully initialized wpa_supplicant May 26 19:08:04 raspberry kernel: brcmfmac: brcmf_cfg80211_set_power_mgmt: power save disabled May 26 19:08:04 raspberry sudo[734]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/dhcpcd May 26 19:08:04 raspberry sudo[734]: pam_unix(sudo:session): session opened for user root by (uid=0) May 26 19:08:04 raspberry dhcpcd[738]: dev: loaded udev May 26 19:08:04 raspberry dhcpcd-run-hooks[765]: wlan0: starting wpa_supplicant May 26 19:08:04 raspberry kernel: Bluetooth: Core ver 2.22 May 26 19:08:04 raspberry kernel: NET: Registered protocol family 31 May 26 19:08:04 raspberry kernel: Bluetooth: HCI device and connection manager initialized May 26 19:08:04 raspberry kernel: Bluetooth: HCI socket layer initialized May 26 19:08:04 raspberry kernel: Bluetooth: L2CAP socket layer initialized May 26 19:08:04 raspberry kernel: Bluetooth: SCO socket layer initialized May 26 19:08:04 raspberry kernel: Bluetooth: HCI UART driver ver 2.3 May 26 19:08:04 raspberry kernel: Bluetooth: HCI UART protocol H4 registered May 26 19:08:04 raspberry kernel: Bluetooth: HCI UART protocol Three-wire (H5) registered May 26 19:08:04 raspberry kernel: Bluetooth: HCI UART protocol Broadcom registered May 26 19:08:04 raspberry btuart[483]: bcm43xx_init May 26 19:08:04 raspberry btuart[483]: Flash firmware /lib/firmware/brcm/BCM4345C0.hcd May 26 19:08:04 raspberry btuart[483]: Set Controller UART speed to 3000000 bit/s May 26 19:08:04 raspberry btuart[483]: Device setup complete May 26 19:08:04 raspberry systemd[1]: Starting Load/Save RF Kill Switch Status... May 26 19:08:04 raspberry systemd[1]: Started Configure Bluetooth Modems connected by UART. May 26 19:08:04 raspberry systemd[1]: Started Load/Save RF Kill Switch Status. May 26 19:08:04 raspberry systemd[1]: Created slice system-bthelper.slice. May 26 19:08:04 raspberry systemd-udevd[688]: Using default interface naming scheme 'v240'. May 26 19:08:04 raspberry systemd-udevd[688]: link_config: autonegotiation is unset or enabled, the speed and duplex are not writable. May 26 19:08:04 raspberry systemd[1]: Starting Raspberry Pi bluetooth helper... May 26 19:08:04 raspberry bthelper[788]: Raspberry Pi BDADDR already set May 26 19:08:04 raspberry systemd[1]: Started Raspberry Pi bluetooth helper. May 26 19:08:04 raspberry systemd[1]: Starting Bluetooth service... May 26 19:08:04 raspberry bluetoothd[811]: Bluetooth daemon 5.50 May 26 19:08:04 raspberry bluetoothd[811]: Unknown key AutoConnectTimeout for group General in /etc/bluetooth/main.conf May 26 19:08:04 raspberry systemd[1]: Started Bluetooth service. May 26 19:08:04 raspberry systemd[1]: Reached target Bluetooth. May 26 19:08:04 raspberry bluetoothd[811]: Starting SDP server May 26 19:08:04 raspberry bluetoothd[811]: Excluding (cli) sap May 26 19:08:04 raspberry kernel: Bluetooth: BNEP (Ethernet Emulation) ver 1.3 May 26 19:08:04 raspberry kernel: Bluetooth: BNEP filters: protocol multicast May 26 19:08:04 raspberry kernel: Bluetooth: BNEP socket layer initialized May 26 19:08:04 raspberry bluetoothd[811]: Bluetooth management interface 1.18 initialized May 26 19:08:04 raspberry dbus-daemon[477]: [system] Activating via systemd: service name='org.freedesktop.hostname1' unit='dbus-org.freedesktop.hostname1.service' requested by ':1.6' (uid=0 pid=811 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap ") May 26 19:08:04 raspberry systemd[1]: Starting Hostname Service... May 26 19:08:04 raspberry dhcpcd-run-hooks[825]: wlan0: failed to start wpa_supplicant May 26 19:08:04 raspberry dhcpcd-run-hooks[826]: wlan0: Successfully initialized wpa_supplicant nl80211: kernel reports: Match already configured nl80211: kernel reports: Match already configured nl80211: kernel reports: Match already configured nl80211: kernel reports: Match already configured nl80211: kernel reports: Match already configured nl80211: kernel reports: Match already configured nl80211: kernel reports: Match already configured nl80211: kernel reports: Match already configured nl80211: kernel reports: Match already configured nl80211: kernel reports: Match already configured nl80211: kernel reports: Match already configured nl80211: kernel reports: Match already configured nl80211: kernel reports: Match already configured nl80211: kernel reports: Match already configured nl80211: kernel reports: Match already configured nl80211: kernel reports: Match already configured nl80211: kernel reports: Match already configured nl80211: kernel reports: Match already configured nl80211: kernel reports: Match already configured nl80211: kernel reports: Ma May 26 19:08:04 raspberry dhcpcd[738]: wlan0: connected to Access Point `' May 26 19:08:04 raspberry dhcpcd[738]: no interfaces have a carrier May 26 19:08:04 raspberry dhcpcd[738]: forked to background, child pid 839 May 26 19:08:04 raspberry dhcpcd[839]: eth0: waiting for carrier May 26 19:08:04 raspberry dhcpcd[839]: wlan0: waiting for carrier May 26 19:08:04 raspberry sudo[734]: pam_unix(sudo:session): session closed for user root May 26 19:08:04 raspberry bluetoothd[811]: Failed to set privacy: Rejected (0x0b) May 26 19:08:04 raspberry dbus-daemon[477]: [system] Successfully activated service 'org.freedesktop.hostname1' May 26 19:08:04 raspberry systemd[1]: Started Hostname Service. May 26 19:08:04 raspberry avahi-daemon[482]: Joining mDNS multicast group on interface docker0.IPv4 with address 172.17.0.1. May 26 19:08:04 raspberry avahi-daemon[482]: New relevant interface docker0.IPv4 for mDNS. May 26 19:08:04 raspberry avahi-daemon[482]: Registering new address record for 172.17.0.1 on docker0.IPv4. May 26 19:08:04 raspberry dockerd[658]: time="2025-05-26T19:08:04.812413670Z" level=info msg="Default bridge (docker0) is assigned with an IP address 172.17.0.0/16. Daemon option --bip can be used to set a preferred IP address" May 26 19:08:05 raspberry ntpd[653]: error resolving pool 3.debian.pool.ntp.org: System error (-11) May 26 19:08:05 raspberry wireless.js[474]: trying... May 26 19:08:05 raspberry sudo[887]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r May 26 19:08:05 raspberry sudo[887]: pam_unix(sudo:session): session opened for user root by (uid=0) May 26 19:08:05 raspberry sudo[887]: pam_unix(sudo:session): session closed for user root May 26 19:08:05 raspberry kernel: EXT4-fs (dm-1): mounted filesystem with ordered data mode. Opts: (null) May 26 19:08:05 raspberry containerd[615]: time="2025-05-26T19:08:05.809591418Z" level=info msg="starting signal loop" namespace=moby path=/run/containerd/io.containerd.runtime.v2.task/moby/6810805a46771709e976e6621e9f69ad65347a5c2e893c8bc3138ddcb0e0d842 pid=914 May 26 19:08:06 raspberry wireless.js[474]: trying... May 26 19:08:06 raspberry sudo[935]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r May 26 19:08:06 raspberry sudo[935]: pam_unix(sudo:session): session opened for user root by (uid=0) May 26 19:08:06 raspberry sudo[935]: pam_unix(sudo:session): session closed for user root May 26 19:08:06 raspberry kernel: cgroup: cgroup: disabling cgroup2 socket matching due to net_prio or net_cls activation May 26 19:08:06 raspberry containerd[615]: time="2025-05-26T19:08:06.223667471Z" level=error msg="add cg to OOM monitor" error="cgroups: memory cgroup not supported on this system" May 26 19:08:06 raspberry dockerd[658]: time="2025-05-26T19:08:06.291191532Z" level=info msg="Loading containers: done." May 26 19:08:06 raspberry volumio-remote-updater[479]: [2025-05-26 19:08:06] [info] asio async_connect error: system:111 (Connection refused) May 26 19:08:06 raspberry volumio-remote-updater[479]: [2025-05-26 19:08:06] [info] Error getting remote endpoint: system:107 (Transport endpoint is not connected) May 26 19:08:06 raspberry volumio-remote-updater[479]: [2025-05-26 19:08:06] [error] handle_connect error: Underlying Transport Error May 26 19:08:06 raspberry dockerd[658]: time="2025-05-26T19:08:06.345941140Z" level=info msg="Docker daemon" commit=87a90dc graphdriver(s)=devicemapper version=20.10.14 May 26 19:08:06 raspberry dockerd[658]: time="2025-05-26T19:08:06.347652541Z" level=info msg="Daemon has completed initialization" May 26 19:08:06 raspberry systemd[1]: Started Docker Application Container Engine. May 26 19:08:06 raspberry dockerd[658]: time="2025-05-26T19:08:06.484733896Z" level=info msg="API listen on /var/run/docker.sock" May 26 19:08:06 raspberry wpa_supplicant[780]: wlan0: Trying to associate with SSID 'maison_brutal' May 26 19:08:07 raspberry wireless.js[474]: trying... May 26 19:08:07 raspberry sudo[1175]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r May 26 19:08:07 raspberry sudo[1175]: pam_unix(sudo:session): session opened for user root by (uid=0) May 26 19:08:07 raspberry sudo[1175]: pam_unix(sudo:session): session closed for user root May 26 19:08:07 raspberry nmbd[613]: [2025/05/26 19:08:07.576472, 0] ../lib/util/become_daemon.c:138(daemon_ready) May 26 19:08:07 raspberry systemd[1]: Started Samba NMB Daemon. May 26 19:08:07 raspberry nmbd[613]: daemon_ready: STATUS=daemon 'nmbd' finished starting up and ready to serve connections May 26 19:08:07 raspberry systemd[1]: Starting Samba Winbind Daemon... May 26 19:08:07 raspberry winbindd[1177]: [2025/05/26 19:08:07.865999, 0] ../source3/winbindd/winbindd_cache.c:3160(initialize_winbindd_cache) May 26 19:08:07 raspberry winbindd[1177]: initialize_winbindd_cache: clearing cache and re-creating with version number 2 May 26 19:08:07 raspberry winbindd[1177]: [2025/05/26 19:08:07.887656, 0] ../lib/util/become_daemon.c:138(daemon_ready) May 26 19:08:07 raspberry winbindd[1177]: daemon_ready: STATUS=daemon 'winbindd' finished starting up and ready to serve connections May 26 19:08:07 raspberry systemd[1]: Started Samba Winbind Daemon. May 26 19:08:07 raspberry systemd[1]: Starting Samba SMB Daemon... May 26 19:08:08 raspberry wireless.js[474]: trying... May 26 19:08:08 raspberry sudo[1184]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r May 26 19:08:08 raspberry sudo[1184]: pam_unix(sudo:session): session opened for user root by (uid=0) May 26 19:08:08 raspberry sudo[1184]: pam_unix(sudo:session): session closed for user root May 26 19:08:08 raspberry smbd[1182]: [2025/05/26 19:08:08.326051, 0] ../lib/util/become_daemon.c:138(daemon_ready) May 26 19:08:08 raspberry smbd[1182]: daemon_ready: STATUS=daemon 'smbd' finished starting up and ready to serve connections May 26 19:08:08 raspberry systemd[1]: Started Samba SMB Daemon. May 26 19:08:09 raspberry wireless.js[474]: trying... May 26 19:08:09 raspberry sudo[1194]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r May 26 19:08:09 raspberry sudo[1194]: pam_unix(sudo:session): session opened for user root by (uid=0) May 26 19:08:09 raspberry sudo[1194]: pam_unix(sudo:session): session closed for user root May 26 19:08:09 raspberry systemd[1]: systemd-rfkill.service: Succeeded. May 26 19:08:09 raspberry bthelper[788]: Changing power off succeeded May 26 19:08:09 raspberry dhcpcd[839]: wlan0: carrier acquired May 26 19:08:09 raspberry dhcpcd[839]: wlan0: connected to Access Point `maison_brutal' May 26 19:08:09 raspberry wpa_supplicant[780]: wlan0: Associated with d8:78:7f:a0:27:f1 May 26 19:08:09 raspberry wpa_supplicant[780]: wlan0: CTRL-EVENT-CONNECTED - Connection to d8:78:7f:a0:27:f1 completed [id=0 id_str=] May 26 19:08:09 raspberry wpa_supplicant[780]: wlan0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0 May 26 19:08:09 raspberry wpa_supplicant[780]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=COUNTRY_IE type=COUNTRY alpha2=PT May 26 19:08:09 raspberry dhcpcd[839]: DUID 00:01:00:01:29:d8:62:26:e4:5f:01:a4:7e:9d May 26 19:08:09 raspberry dhcpcd[839]: wlan0: IAID 01:a4:7e:9d May 26 19:08:09 raspberry dhcpcd[839]: wlan0: adding address fe80::591f:8376:f318:35b7 May 26 19:08:09 raspberry dhcpcd[839]: ipv6_addaddr1: Permission denied May 26 19:08:09 raspberry dhcpcd[839]: wlan0: carrier lost May 26 19:08:09 raspberry dhcpcd[839]: wlan0: carrier acquired May 26 19:08:09 raspberry dhcpcd[839]: wlan0: IAID 01:a4:7e:9d May 26 19:08:09 raspberry bthelper[788]: [CHG] Controller E4:5F:01:A4:7E:9E Class: 0x0000041c May 26 19:08:09 raspberry bthelper[788]: Changing power on succeeded May 26 19:08:09 raspberry dhcpcd[839]: wlan0: soliciting an IPv6 router May 26 19:08:09 raspberry dhcpcd[839]: wlan0: rebinding lease of 192.168.1.167 May 26 19:08:10 raspberry wireless.js[474]: trying... May 26 19:08:10 raspberry sudo[1216]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r May 26 19:08:10 raspberry sudo[1216]: pam_unix(sudo:session): session opened for user root by (uid=0) May 26 19:08:10 raspberry sudo[1216]: pam_unix(sudo:session): session closed for user root May 26 19:08:11 raspberry wireless.js[474]: trying... May 26 19:08:11 raspberry sudo[1219]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r May 26 19:08:11 raspberry sudo[1219]: pam_unix(sudo:session): session opened for user root by (uid=0) May 26 19:08:11 raspberry sudo[1219]: pam_unix(sudo:session): session closed for user root May 26 19:08:12 raspberry wireless.js[474]: trying... May 26 19:08:12 raspberry sudo[1222]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r May 26 19:08:12 raspberry sudo[1222]: pam_unix(sudo:session): session opened for user root by (uid=0) May 26 19:08:12 raspberry sudo[1222]: pam_unix(sudo:session): session closed for user root May 26 19:08:13 raspberry wireless.js[474]: trying... May 26 19:08:13 raspberry sudo[1225]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r May 26 19:08:13 raspberry sudo[1225]: pam_unix(sudo:session): session opened for user root by (uid=0) May 26 19:08:13 raspberry sudo[1225]: pam_unix(sudo:session): session closed for user root May 26 19:08:13 raspberry kernel: cam-dummy-reg: disabling May 26 19:08:13 raspberry kernel: cam1-reg: disabling May 26 19:08:13 raspberry dhcpcd[839]: wlan0: probing address 192.168.1.167/24 May 26 19:08:13 raspberry volumio-remote-updater[479]: [2025-05-26 19:08:13] [info] asio async_connect error: system:111 (Connection refused) May 26 19:08:13 raspberry volumio-remote-updater[479]: [2025-05-26 19:08:13] [info] Error getting remote endpoint: system:107 (Transport endpoint is not connected) May 26 19:08:13 raspberry volumio-remote-updater[479]: [2025-05-26 19:08:13] [error] handle_connect error: Underlying Transport Error May 26 19:08:14 raspberry wireless.js[474]: trying... May 26 19:08:14 raspberry sudo[1228]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r May 26 19:08:14 raspberry sudo[1228]: pam_unix(sudo:session): session opened for user root by (uid=0) May 26 19:08:14 raspberry sudo[1228]: pam_unix(sudo:session): session closed for user root May 26 19:08:15 raspberry wireless.js[474]: trying... May 26 19:08:15 raspberry sudo[1238]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r May 26 19:08:15 raspberry sudo[1238]: pam_unix(sudo:session): session opened for user root by (uid=0) May 26 19:08:15 raspberry sudo[1238]: pam_unix(sudo:session): session closed for user root May 26 19:08:16 raspberry wireless.js[474]: trying... May 26 19:08:16 raspberry sudo[1242]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r May 26 19:08:16 raspberry sudo[1242]: pam_unix(sudo:session): session opened for user root by (uid=0) May 26 19:08:16 raspberry sudo[1242]: pam_unix(sudo:session): session closed for user root May 26 19:08:17 raspberry wireless.js[474]: trying... May 26 19:08:17 raspberry sudo[1246]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r May 26 19:08:17 raspberry sudo[1246]: pam_unix(sudo:session): session opened for user root by (uid=0) May 26 19:08:17 raspberry sudo[1246]: pam_unix(sudo:session): session closed for user root May 26 19:08:18 raspberry wireless.js[474]: trying... May 26 19:08:18 raspberry sudo[1249]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r May 26 19:08:18 raspberry sudo[1249]: pam_unix(sudo:session): session opened for user root by (uid=0) May 26 19:08:18 raspberry sudo[1249]: pam_unix(sudo:session): session closed for user root May 26 19:08:18 raspberry dhcpcd[839]: wlan0: leased 192.168.1.167 for 3600 seconds May 26 19:08:18 raspberry avahi-daemon[482]: Joining mDNS multicast group on interface wlan0.IPv4 with address 192.168.1.167. May 26 19:08:18 raspberry avahi-daemon[482]: New relevant interface wlan0.IPv4 for mDNS. May 26 19:08:18 raspberry avahi-daemon[482]: Registering new address record for 192.168.1.167 on wlan0.IPv4. May 26 19:08:18 raspberry dhcpcd[839]: wlan0: adding route to 192.168.1.0/24 May 26 19:08:18 raspberry dhcpcd[839]: wlan0: adding default route via 192.168.1.254 May 26 19:08:19 raspberry wireless.js[474]: trying... May 26 19:08:19 raspberry sudo[1272]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r May 26 19:08:19 raspberry sudo[1272]: pam_unix(sudo:session): session opened for user root by (uid=0) May 26 19:08:19 raspberry sudo[1272]: pam_unix(sudo:session): session closed for user root May 26 19:08:19 raspberry wireless.js[474]: Connected to: ----maison_brutal May 26 19:08:19 raspberry wireless.js[474]: ---- May 26 19:08:19 raspberry sudo[1275]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 May 26 19:08:19 raspberry sudo[1275]: pam_unix(sudo:session): session opened for user root by (uid=0) May 26 19:08:19 raspberry sudo[1275]: pam_unix(sudo:session): session closed for user root May 26 19:08:19 raspberry wireless.js[474]: ... joined AP, wlan0 IPv4 is 192.168.1.167, ipV6 is undefined May 26 19:08:19 raspberry wireless.js[474]: It's done! AP May 26 19:08:19 raspberry systemd[1]: Started Wireless Services. May 26 19:08:19 raspberry systemd[1]: Started Volumio Backend Module. May 26 19:08:19 raspberry systemd[1]: Started Volumio Streaming Daemon. May 26 19:08:19 raspberry systemd[1]: Reached target Multi-User System. May 26 19:08:19 raspberry systemd[1]: Reached target Graphical Interface. May 26 19:08:19 raspberry systemd[1]: Starting Update UTMP about System Runlevel Changes... May 26 19:08:19 raspberry systemd[1]: systemd-update-utmp-runlevel.service: Succeeded. May 26 19:08:19 raspberry systemd[1]: Started Update UTMP about System Runlevel Changes. May 26 19:08:19 raspberry systemd[1]: Startup finished in 9.726s (kernel) + 28.959s (userspace) = 38.686s. May 26 19:08:19 raspberry volumio-streaming-daemon[1280]: ############################ May 26 19:08:19 raspberry volumio-streaming-daemon[1280]: # Volumio Streaming Daemon # May 26 19:08:19 raspberry volumio-streaming-daemon[1280]: # Running on port 7777 # May 26 19:08:19 raspberry volumio-streaming-daemon[1280]: ############################ May 26 19:08:19 raspberry volumio-streaming-daemon[1280]: Environment: production May 26 19:08:20 raspberry ntpd[653]: Listen normally on 3 wlan0 192.168.1.167:123 May 26 19:08:20 raspberry ntpd[653]: new interface(s) found: waking up resolver May 26 19:08:21 raspberry volumio[1279]: info: ------------------------------------------- May 26 19:08:21 raspberry volumio[1279]: info: ----- Volumio3 ---- May 26 19:08:21 raspberry volumio[1279]: info: ------------------------------------------- May 26 19:08:21 raspberry volumio[1279]: info: ----- System startup ---- May 26 19:08:21 raspberry volumio[1279]: info: ------------------------------------------- May 26 19:08:21 raspberry volumio[1279]: info: MYVOLUMIO Environment detected May 26 19:08:22 raspberry volumio[1279]: info: Plugin folders cleanup May 26 19:08:22 raspberry volumio[1279]: info: Scanning into folder /volumio/app/plugins/ May 26 19:08:22 raspberry volumio[1279]: info: Scanning category audio_interface May 26 19:08:22 raspberry volumio[1279]: info: Scanning category miscellanea May 26 19:08:22 raspberry volumio[1279]: info: Scanning category music_service May 26 19:08:22 raspberry volumio[1279]: info: Scanning category plugins.json May 26 19:08:22 raspberry volumio[1279]: info: Scanning category system_controller May 26 19:08:22 raspberry volumio[1279]: info: Scanning category user_interface May 26 19:08:22 raspberry volumio[1279]: info: Scanning into folder /data/plugins/ May 26 19:08:22 raspberry volumio[1279]: info: Scanning category music_service May 26 19:08:22 raspberry volumio[1279]: info: Plugin folders cleanup completed May 26 19:08:22 raspberry volumio[1279]: info: ------------------------------------------- May 26 19:08:22 raspberry volumio[1279]: info: ----- Core plugins startup ---- May 26 19:08:22 raspberry volumio[1279]: info: ------------------------------------------- May 26 19:08:22 raspberry volumio[1279]: info: Loading plugins from folder /volumio/app/plugins/ May 26 19:08:22 raspberry volumio[1279]: info: Adding plugin upnp to MyMusic Plugins May 26 19:08:22 raspberry volumio[1279]: info: Adding plugin airplay_emulation to MyMusic Plugins May 26 19:08:22 raspberry volumio[1279]: info: Adding plugin upnp_browser to MyMusic Plugins May 26 19:08:22 raspberry volumio[1279]: info: Loading plugins from folder /data/plugins/ May 26 19:08:22 raspberry volumio[1279]: info: Loading plugin "system"... May 26 19:08:22 raspberry volumio[1279]: info: Loading plugin "appearance"... May 26 19:08:23 raspberry volumio[1279]: info: Loading plugin "network"... May 26 19:08:23 raspberry volumio[1279]: info: Refreshing Cached IP Addresses May 26 19:08:23 raspberry sudo[1306]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 May 26 19:08:23 raspberry sudo[1306]: pam_unix(sudo:session): session opened for user root by (uid=0) May 26 19:08:23 raspberry sudo[1306]: pam_unix(sudo:session): session closed for user root May 26 19:08:23 raspberry volumio[1279]: info: Loading plugin "services"... May 26 19:08:23 raspberry sudo[1308]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 May 26 19:08:23 raspberry sudo[1308]: pam_unix(sudo:session): session opened for user root by (uid=0) May 26 19:08:23 raspberry volumio[1279]: info: Loading plugin "alsa_controller"... May 26 19:08:23 raspberry sudo[1308]: pam_unix(sudo:session): session closed for user root May 26 19:08:23 raspberry sudo[1311]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan May 26 19:08:23 raspberry sudo[1311]: pam_unix(sudo:session): session opened for user root by (uid=0) May 26 19:08:23 raspberry volumio[1279]: info: Loading plugin "wizard"... May 26 19:08:23 raspberry volumio[1279]: info: Loading plugin "volumio_command_line_client"... May 26 19:08:23 raspberry volumio[1279]: info: Loading plugin "upnp"... May 26 19:08:23 raspberry volumio[1279]: info: [1748286503407] Starting Upmpd Daemon May 26 19:08:23 raspberry volumio[1279]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback May 26 19:08:23 raspberry volumio[1279]: info: Loading plugin "my_music"... May 26 19:08:23 raspberry volumio[1279]: info: Loading plugin "mpd"... May 26 19:08:23 raspberry volumio[1279]: info: Creating MPD Configuration file May 26 19:08:23 raspberry volumio[1279]: info: Loading plugin "upnp_browser"... May 26 19:08:23 raspberry sudo[1320]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf May 26 19:08:23 raspberry sudo[1320]: pam_unix(sudo:session): session opened for user root by (uid=0) May 26 19:08:23 raspberry sudo[1320]: pam_unix(sudo:session): session closed for user root May 26 19:08:23 raspberry sudo[1322]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service May 26 19:08:23 raspberry sudo[1322]: pam_unix(sudo:session): session opened for user root by (uid=0) May 26 19:08:23 raspberry sudo[1322]: pam_unix(sudo:session): session closed for user root May 26 19:08:23 raspberry volumio-remote-updater[479]: [2025-05-26 19:08:23] [connect] Successful connection May 26 19:08:24 raspberry volumio[1279]: info: Loading plugin "networkfs"... May 26 19:08:24 raspberry volumio[1279]: info: Starting Udev Watcher for removable devices May 26 19:08:24 raspberry sudo[1327]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o guest,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //127.0.0.1/usb/DCA2C828A2C8094A/media/Music /mnt/NAS/ssd May 26 19:08:24 raspberry sudo[1327]: pam_unix(sudo:session): session opened for user root by (uid=0) May 26 19:08:24 raspberry kernel: FS-Cache: Netfs 'cifs' registered for caching May 26 19:08:24 raspberry kernel: Key type cifs.spnego registered May 26 19:08:24 raspberry kernel: Key type cifs.idmap registered May 26 19:08:24 raspberry kernel: CIFS: Attempting to mount //127.0.0.1/usb/DCA2C828A2C8094A/media/Music May 26 19:08:24 raspberry 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. May 26 19:08:24 raspberry sudo[1327]: pam_unix(sudo:session): session closed for user root May 26 19:08:24 raspberry kernel: CIFS: VFS: cifs_mount failed w/return code = -2 May 26 19:08:24 raspberry volumio[1279]: info: Ignoring mount for partition: boot May 26 19:08:24 raspberry volumio[1279]: info: Ignoring mount for partition: volumio May 26 19:08:24 raspberry volumio[1279]: info: Ignoring mount for partition: volumio_data May 26 19:08:24 raspberry volumio[1279]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback May 26 19:08:24 raspberry volumio[1279]: info: Loading plugin "alarm-clock"... May 26 19:08:24 raspberry volumio[1279]: info: Loading plugin "airplay_emulation"... May 26 19:08:24 raspberry volumio[1279]: info: Starting Shairport Sync May 26 19:08:24 raspberry volumio[1279]: info: Loading plugin "last_100"... May 26 19:08:24 raspberry volumio[1279]: info: Loading plugin "webradio"... May 26 19:08:25 raspberry volumio[1279]: info: Loading plugin "i2s_dacs"... May 26 19:08:25 raspberry volumio[1279]: info: Loading plugin "volumiodiscovery"... May 26 19:08:25 raspberry volumio[1279]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. May 26 19:08:25 raspberry volumio[1279]: *** WARNING *** Please fix your application to use the native API of Avahi! May 26 19:08:25 raspberry volumio[1279]: *** WARNING *** For more information see May 26 19:08:25 raspberry node[1279]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. May 26 19:08:25 raspberry volumio[1279]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. May 26 19:08:25 raspberry volumio[1279]: *** WARNING *** Please fix your application to use the native API of Avahi! May 26 19:08:25 raspberry volumio[1279]: *** WARNING *** For more information see May 26 19:08:25 raspberry node[1279]: *** WARNING *** Please fix your application to use the native API of Avahi! May 26 19:08:25 raspberry node[1279]: *** WARNING *** For more information see May 26 19:08:25 raspberry node[1279]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. May 26 19:08:25 raspberry node[1279]: *** WARNING *** Please fix your application to use the native API of Avahi! May 26 19:08:25 raspberry node[1279]: *** WARNING *** For more information see May 26 19:08:25 raspberry volumio[1279]: info: Applying required configuration parameters for plugin volumiodiscovery May 26 19:08:25 raspberry volumio[1279]: info: Discovery: Started advertising with name: Raspberry May 26 19:08:25 raspberry volumio[1279]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback May 26 19:08:25 raspberry volumio[1279]: info: Loading plugin "spop"... May 26 19:08:25 raspberry systemd[1]: systemd-fsckd.service: Succeeded. May 26 19:08:26 raspberry volumio[1279]: info: Loading plugin "outputs"... May 26 19:08:26 raspberry volumio[1279]: info: Loading plugin "albumart"... May 26 19:08:26 raspberry volumio[1279]: info: Plugin example_plugin is not enabled May 26 19:08:26 raspberry volumio[1279]: info: Loading plugin "inputs"... May 26 19:08:26 raspberry volumio[1279]: info: Loading plugin "updater_comm"... May 26 19:08:26 raspberry volumio[1279]: info: Plugin mpdemulation is not enabled May 26 19:08:26 raspberry volumio[1279]: info: Loading plugin "rest_api"... May 26 19:08:26 raspberry volumio[1279]: info: Loading plugin "websocket"... May 26 19:08:26 raspberry volumio[1279]: info: Loading i18n strings for locale pt May 26 19:08:26 raspberry volumio[1279]: Updating browse sources language May 26 19:08:26 raspberry volumio[1279]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 26 19:08:26 raspberry volumio[1279]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 26 19:08:26 raspberry volumio[1279]: info: CoreCommandRouter::initPlayerControls May 26 19:08:26 raspberry volumio[1279]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 26 19:08:26 raspberry volumio[1279]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 26 19:08:26 raspberry volumio[1279]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 26 19:08:26 raspberry volumio[1279]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 26 19:08:26 raspberry volumio[1279]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 26 19:08:26 raspberry volumio[1279]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 26 19:08:26 raspberry volumio[1279]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 26 19:08:26 raspberry volumio[1279]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 26 19:08:26 raspberry volumio[1279]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 26 19:08:26 raspberry volumio[1279]: Express server listening on port 3000 May 26 19:08:26 raspberry volumio[1279]: [Metrics] WebUI: 6s 236.12ms May 26 19:08:26 raspberry sudo[1311]: pam_unix(sudo:session): session closed for user root May 26 19:08:26 raspberry volumio[1279]: Forking 3 albumart workers May 26 19:08:26 raspberry volumio[1279]: info: CoreStateMachine::resetVolumioState May 26 19:08:26 raspberry volumio[1279]: info: CoreStateMachine::getcurrentVolume May 26 19:08:26 raspberry volumio[1279]: info: CoreCommandRouter::volumioRetrievevolume May 26 19:08:26 raspberry volumio[1279]: info: Cannot read play queue from file May 26 19:08:26 raspberry volumio[1279]: info: Cannot mount NAS ssd at system boot, trial number 1 ,retrying in 5 seconds May 26 19:08:26 raspberry volumio[1279]: error: Cannot start MPD on system Start: Error: Command failed: /usr/bin/sudo /bin/systemctl restart mpd.service May 26 19:08:26 raspberry volumio[1279]: Failed to restart mpd.service: Unit mpd.service is masked. May 26 19:08:26 raspberry volumio[1279]: info: MPD Permissions set May 26 19:08:26 raspberry volumio[1279]: error: MPD error: Error: connect ENOENT /run/mpd/socket May 26 19:08:26 raspberry volumio-remote-updater[479]: [2025-05-26 19:08:26] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1748286503 101 May 26 19:08:26 raspberry volumio[1279]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Total Clients: 1 May 26 19:08:26 raspberry volumio[1279]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 26 19:08:27 raspberry volumio[1279]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 26 19:08:27 raspberry volumio[1279]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 26 19:08:27 raspberry volumio[1279]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 26 19:08:27 raspberry volumio[1279]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 26 19:08:27 raspberry volumio[1279]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 26 19:08:27 raspberry volumio[1279]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 26 19:08:27 raspberry volumio[1279]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 26 19:08:27 raspberry volumio[1279]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 26 19:08:27 raspberry volumio[1279]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 26 19:08:27 raspberry volumio[1279]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 26 19:08:27 raspberry volumio[1279]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 26 19:08:27 raspberry volumio[1279]: info: VolumeController:: Volume=49 Mute =false May 26 19:08:27 raspberry volumio[1279]: info: CoreStateMachine::pushState May 26 19:08:27 raspberry volumio[1279]: info: CorePlayQueue::getTrack 0 May 26 19:08:27 raspberry volumio[1279]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 26 19:08:27 raspberry volumio[1279]: info: CoreCommandRouter::volumioPushState May 26 19:08:27 raspberry volumio[1279]: info: CoreStateMachine::updateTrackBlock May 26 19:08:27 raspberry volumio[1279]: info: CorePlayQueue::getTrackBlock May 26 19:08:27 raspberry volumio[1279]: info: CoreCommandRouter::volumioRetrievevolume May 26 19:08:27 raspberry volumio[1279]: info: CoreStateMachine::setRepeat true single undefined May 26 19:08:27 raspberry volumio[1279]: info: CoreStateMachine::pushState May 26 19:08:27 raspberry volumio[1279]: info: CorePlayQueue::getTrack 0 May 26 19:08:27 raspberry volumio[1279]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 26 19:08:27 raspberry volumio[1279]: info: CoreCommandRouter::volumioPushState May 26 19:08:27 raspberry volumio[1279]: info: CoreStateMachine::setRandom null May 26 19:08:27 raspberry volumio[1279]: info: CoreStateMachine::pushState May 26 19:08:27 raspberry volumio[1279]: info: CorePlayQueue::getTrack 0 May 26 19:08:27 raspberry volumio[1279]: info: CoreCommandRouter::volumioPushState May 26 19:08:27 raspberry volumio[1279]: info: Setting Device type: Raspberry PI May 26 19:08:27 raspberry volumio[1279]: info: Completed loading Core Plugins May 26 19:08:27 raspberry volumio[1279]: info: Preparing to generate the ALSA configuration file May 26 19:08:27 raspberry volumio[1279]: info: Asound.conf file unchanged, so no further update is needed May 26 19:08:27 raspberry volumio[1279]: info: Output device has changed, restarting MPD May 26 19:08:27 raspberry volumio[1279]: info: Output device has changed, restarting Shairport Sync May 26 19:08:27 raspberry volumio[1279]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 26 19:08:27 raspberry volumio[1279]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 26 19:08:27 raspberry volumio[1279]: Starting albumart workers May 26 19:08:27 raspberry volumio[1279]: Starting albumart workers May 26 19:08:27 raspberry volumio[1279]: Starting albumart workers May 26 19:08:27 raspberry sh[400]: timed out May 26 19:08:27 raspberry dhcpcd[450]: timed out May 26 19:08:28 raspberry sh[400]: dhcpcd exited May 26 19:08:28 raspberry dhcpcd[450]: dhcpcd exited May 26 19:08:28 raspberry sh[400]: ifup: failed to bring up eth0 May 26 19:08:28 raspberry sudo[1407]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf May 26 19:08:28 raspberry systemd[1]: ifup@eth0.service: Main process exited, code=exited, status=1/FAILURE May 26 19:08:28 raspberry sudo[1407]: pam_unix(sudo:session): session opened for user root by (uid=0) May 26 19:08:28 raspberry systemd[1]: ifup@eth0.service: Failed with result 'exit-code'. May 26 19:08:28 raspberry sudo[1409]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service May 26 19:08:28 raspberry sudo[1409]: pam_unix(sudo:session): session opened for user root by (uid=0) May 26 19:08:28 raspberry sudo[1407]: pam_unix(sudo:session): session closed for user root May 26 19:08:28 raspberry volumio[1279]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 May 26 19:08:28 raspberry volumio[1279]: info: ___________ START PLUGINS ___________ May 26 19:08:28 raspberry volumio[1279]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 26 19:08:28 raspberry volumio[1279]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 26 19:08:28 raspberry volumio[1279]: info: [1748286508133] CoreMusicLibrary::Adding element Media Servers May 26 19:08:28 raspberry volumio[1279]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 26 19:08:28 raspberry volumio[1279]: Cannot find translation for sourceMedia Servers May 26 19:08:28 raspberry sudo[1409]: pam_unix(sudo:session): session closed for user root May 26 19:08:28 raspberry volumio[1279]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 26 19:08:28 raspberry volumio[1279]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 26 19:08:28 raspberry volumio[1279]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 May 26 19:08:28 raspberry volumio[1279]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 26 19:08:28 raspberry volumio[1279]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 26 19:08:28 raspberry volumio[1279]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 May 26 19:08:28 raspberry volumio[1279]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 26 19:08:28 raspberry volumio[1279]: info: [1748286508201] CoreMusicLibrary::Adding element Last_100 May 26 19:08:28 raspberry volumio[1279]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 26 19:08:28 raspberry volumio[1279]: Cannot find translation for sourceMedia Servers May 26 19:08:28 raspberry volumio[1279]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 26 19:08:28 raspberry volumio[1279]: info: [1748286508204] CoreMusicLibrary::Adding element Webradio May 26 19:08:28 raspberry volumio[1279]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 26 19:08:28 raspberry volumio[1279]: Cannot find translation for sourceMedia Servers May 26 19:08:28 raspberry volumio[1279]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 26 19:08:28 raspberry volumio[1279]: info: Creating Spotify config file May 26 19:08:28 raspberry volumio[1279]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 26 19:08:28 raspberry volumio[1279]: info: Volumio Calling Home May 26 19:08:28 raspberry volumio[1279]: info: Completed starting Core Plugins May 26 19:08:28 raspberry volumio[1279]: info: ------------------------------------------- May 26 19:08:28 raspberry volumio[1279]: info: ----- MyVolumio plugins startup ---- May 26 19:08:28 raspberry volumio[1279]: info: ------------------------------------------- May 26 19:08:28 raspberry volumio[1279]: info: [MyVolumio PluginManager] Fetching plans data.... May 26 19:08:28 raspberry volumio[1279]: info: Discovery: adding 7e06616f-2781-4373-b61b-704a7c37343c May 26 19:08:28 raspberry volumio[1279]: info: mDNS: Found device Raspberry May 26 19:08:28 raspberry volumio[1279]: info: CoreCommandRouter::volumioGetState May 26 19:08:28 raspberry volumio[1279]: info: CorePlayQueue::getTrack 0 May 26 19:08:28 raspberry volumio[1279]: info: Discovery: this is already registered, 7e06616f-2781-4373-b61b-704a7c37343c May 26 19:08:28 raspberry volumio[1279]: info: mDNS: Found device Raspberry May 26 19:08:28 raspberry volumio[1279]: info: CoreCommandRouter::volumioGetState May 26 19:08:28 raspberry volumio[1279]: info: CorePlayQueue::getTrack 0 May 26 19:08:29 raspberry volumio[1279]: info: Cannot restart MPD: Error: Command failed: /usr/bin/sudo /bin/systemctl restart mpd.service May 26 19:08:29 raspberry volumio[1279]: Failed to restart mpd.service: Unit mpd.service is masked. May 26 19:08:29 raspberry volumio[1279]: info: MPD Permissions set May 26 19:08:29 raspberry volumio[1279]: info: VolumeController:: Volume=49 Mute =false May 26 19:08:29 raspberry volumio[1279]: info: CoreStateMachine::pushState May 26 19:08:29 raspberry volumio[1279]: info: CorePlayQueue::getTrack 0 May 26 19:08:29 raspberry volumio[1279]: info: CoreCommandRouter::volumioPushState May 26 19:08:29 raspberry volumio[1279]: error: MPD error: Error: connect ENOENT /run/mpd/socket May 26 19:08:29 raspberry volumio[1279]: info: Spotify config file written May 26 19:08:29 raspberry volumio[1279]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 26 19:08:29 raspberry volumio[1279]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 2 May 26 19:08:29 raspberry sudo[1449]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service May 26 19:08:29 raspberry volumio[1279]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 26 19:08:29 raspberry sudo[1449]: pam_unix(sudo:session): session opened for user root by (uid=0) May 26 19:08:29 raspberry volumio[1279]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 26 19:08:29 raspberry systemd[1]: Started go-librespot Daemon. May 26 19:08:29 raspberry volumio[1279]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 26 19:08:29 raspberry sudo[1449]: pam_unix(sudo:session): session closed for user root May 26 19:08:29 raspberry go-librespot[1455]: Librespot-go daemon starting... May 26 19:08:29 raspberry volumio[1279]: info: Volumio called home May 26 19:08:29 raspberry volumio[1279]: info: Starting Shairport Sync May 26 19:08:29 raspberry volumio[1279]: info: Starting Shairport Sync May 26 19:08:29 raspberry sudo[1458]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync May 26 19:08:29 raspberry sudo[1458]: pam_unix(sudo:session): session opened for user root by (uid=0) May 26 19:08:29 raspberry volumio[1279]: info: Starting Shairport Sync May 26 19:08:29 raspberry sudo[1461]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync May 26 19:08:29 raspberry sudo[1461]: pam_unix(sudo:session): session opened for user root by (uid=0) May 26 19:08:29 raspberry systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... May 26 19:08:29 raspberry systemd[1]: shairport-sync.service: Succeeded. May 26 19:08:29 raspberry systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. May 26 19:08:29 raspberry systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. May 26 19:08:29 raspberry sudo[1458]: pam_unix(sudo:session): session closed for user root May 26 19:08:29 raspberry systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... May 26 19:08:29 raspberry systemd[1]: shairport-sync.service: Main process exited, code=killed, status=15/TERM May 26 19:08:29 raspberry systemd[1]: shairport-sync.service: Succeeded. May 26 19:08:29 raspberry systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. May 26 19:08:29 raspberry sudo[1463]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync May 26 19:08:29 raspberry sudo[1463]: pam_unix(sudo:session): session opened for user root by (uid=0) May 26 19:08:29 raspberry systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. May 26 19:08:29 raspberry sudo[1461]: pam_unix(sudo:session): session closed for user root May 26 19:08:29 raspberry systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... May 26 19:08:29 raspberry systemd[1]: shairport-sync.service: Main process exited, code=killed, status=15/TERM May 26 19:08:29 raspberry systemd[1]: shairport-sync.service: Succeeded. May 26 19:08:29 raspberry systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. May 26 19:08:29 raspberry systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. May 26 19:08:29 raspberry sudo[1463]: pam_unix(sudo:session): session closed for user root May 26 19:08:29 raspberry volumio[1279]: info: Shairport-Sync Started May 26 19:08:29 raspberry volumio[1279]: Error adding Membership: Error: addMembership EINVAL May 26 19:08:29 raspberry volumio[1279]: info: Shairport-Sync Started May 26 19:08:29 raspberry volumio[1279]: info: Shairport-Sync Started May 26 19:08:29 raspberry volumio[1279]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ May 26 19:08:29 raspberry volumio[1279]: SPOTIFY: BQBxdpsguU_De0lpJ3px919AZtupt9b5UCa2KS3rQQx6dx4jhIEWmArHYZhjLFntXZhL3X3clpMOfFQLT_KHS1viOCv1yX-PpUwnYDbQL53WasdGuqTtH_jrfgp8TCOQIAy_y1luwfZhpW-oD44DIQTJCk9MtFIj1t2EmrsyBLGfqis5m9paeC28MdoFf8T_gyVG6oM70IeFxJmcAZSmn5WOiQlrJp4PAKj4YT40Km6EhcRG8WWp6Q97hiPiYEvCJXRxZFv5lqga2rF1AiWnohmNhFo May 26 19:08:29 raspberry volumio[1279]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ May 26 19:08:29 raspberry volumio[1279]: info: New Spotify access token = BQBxdpsguU_De0lpJ3px919AZtupt9b5UCa2KS3rQQx6dx4jhIEWmArHYZhjLFntXZhL3X3clpMOfFQLT_KHS1viOCv1yX-PpUwnYDbQL53WasdGuqTtH_jrfgp8TCOQIAy_y1luwfZhpW-oD44DIQTJCk9MtFIj1t2EmrsyBLGfqis5m9paeC28MdoFf8T_gyVG6oM70IeFxJmcAZSmn5WOiQlrJp4PAKj4YT40Km6EhcRG8WWp6Q97hiPiYEvCJXRxZFv5lqga2rF1AiWnohmNhFo May 26 19:08:29 raspberry volumio[1279]: info: Spotify credentials grant success - running version from March 24, 2019 May 26 19:08:29 raspberry volumio[1279]: info: CoreCommandRouter::volumioGetState May 26 19:08:29 raspberry volumio[1279]: info: CorePlayQueue::getTrack 0 May 26 19:08:29 raspberry sudo[1477]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 May 26 19:08:29 raspberry sudo[1477]: pam_unix(sudo:session): session opened for user root by (uid=0) May 26 19:08:29 raspberry sudo[1477]: pam_unix(sudo:session): session closed for user root May 26 19:08:29 raspberry volumio[1279]: SPOTIFY: User informations: {"country":"PT","display_name":"jcchemical","email":"jcchemical@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/jcchemical"},"followers":{"href":null,"total":48},"href":"https://api.spotify.com/v1/users/jcchemical","id":"jcchemical","images":[{"height":300,"url":"https://i.scdn.co/image/ab6775700000ee8552fb15d524c0ea74a5c39cb9","width":300},{"height":64,"url":"https://i.scdn.co/image/ab67757000003b8252fb15d524c0ea74a5c39cb9","width":64}],"product":"premium","type":"user","uri":"spotify:user:jcchemical"} May 26 19:08:29 raspberry go-librespot[1455]: time="2025-05-26T19:08:29Z" level=info msg="generated new device id: 826f379182b504b943b907105855090193e56ecc" May 26 19:08:29 raspberry volumio[1279]: info: Spotify Successfully logged in May 26 19:08:29 raspberry sudo[1479]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 May 26 19:08:29 raspberry go-librespot[1455]: time="2025-05-26T19:08:29Z" level=debug msg="stored credentials found for jcchemical" May 26 19:08:29 raspberry volumio[1279]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 26 19:08:29 raspberry volumio[1279]: info: [1748286509612] CoreMusicLibrary::Adding element Spotify May 26 19:08:29 raspberry volumio[1279]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 26 19:08:29 raspberry sudo[1479]: pam_unix(sudo:session): session opened for user root by (uid=0) May 26 19:08:29 raspberry volumio[1279]: Cannot find translation for sourceMedia Servers May 26 19:08:29 raspberry volumio[1279]: Cannot find translation for sourceSpotify May 26 19:08:29 raspberry sudo[1479]: pam_unix(sudo:session): session closed for user root May 26 19:08:29 raspberry volumio[1279]: verbose: New Socket.io Connection to 192.168.1.167 from 192.168.1.237 UA: Mozilla/5.0 (Linux; Android 10; K) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/136.0.0.0 Mobile Safari/537.36 Total Clients: 3 May 26 19:08:29 raspberry volumio[1279]: info: CoreCommandRouter::volumioGetState May 26 19:08:29 raspberry volumio[1279]: info: CorePlayQueue::getTrack 0 May 26 19:08:29 raspberry volumio[1279]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom May 26 19:08:29 raspberry volumio[1279]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings May 26 19:08:29 raspberry volumio[1279]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard May 26 19:08:29 raspberry volumio[1279]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard May 26 19:08:29 raspberry volumio[1279]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings May 26 19:08:29 raspberry go-librespot[1455]: time="2025-05-26T19:08:29Z" level=debug msg="obtained new client token: AADChPgk37l0m1EDXXrt1mIF4huw5Cb4Ka9d0gR5zNaCVIqeKAh2fS80feK3jAAQbAv6X+FEKYtQ5IlSsErB5hgfph8oR3LMbKCEFMQ4SC+MKfw54oggwxn7kO1d9DVgOlf4bQR1E4rsErhbMCYRwcmHmbb4hD5ZOFxBqnkq1AygCanhZvbcGawkHdc19Pg4exJ8FCX6UYBzj/OJQAYTSFXBt4lDoJYjitcoYULRX8rROzcf6BtRgqNROlMp0Cs=" May 26 19:08:30 raspberry go-librespot[1455]: time="2025-05-26T19:08:30Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" May 26 19:08:30 raspberry go-librespot[1455]: time="2025-05-26T19:08:30Z" level=debug msg="completed keyexchange" May 26 19:08:30 raspberry go-librespot[1455]: time="2025-05-26T19:08:30Z" level=debug msg="completed challenge" May 26 19:08:30 raspberry go-librespot[1455]: time="2025-05-26T19:08:30Z" level=debug msg="authenticated as jcchemical" May 26 19:08:30 raspberry go-librespot[1455]: time="2025-05-26T19:08:30Z" level=debug msg="authenticated as jcchemical" May 26 19:08:30 raspberry go-librespot[1455]: time="2025-05-26T19:08:30Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" May 26 19:08:31 raspberry go-librespot[1455]: time="2025-05-26T19:08:31Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" May 26 19:08:31 raspberry go-librespot[1455]: time="2025-05-26T19:08:31Z" level=debug msg="dealer connection opened" May 26 19:08:31 raspberry go-librespot[1455]: time="2025-05-26T19:08:31Z" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" May 26 19:08:31 raspberry go-librespot[1455]: time="2025-05-26T19:08:31Z" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" May 26 19:08:31 raspberry go-librespot[1455]: time="2025-05-26T19:08:31Z" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" May 26 19:08:31 raspberry go-librespot[1455]: time="2025-05-26T19:08:31Z" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" May 26 19:08:31 raspberry go-librespot[1455]: time="2025-05-26T19:08:31Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" May 26 19:08:31 raspberry go-librespot[1455]: time="2025-05-26T19:08:31Z" level=debug msg="received connection id: OWM3ZGU3YmEtNDE5ZS00OTYwLWJkMDAtMmIyOGI0NjU4Y2QxK2RlYWxlcit0Y3A6Ly8wYWNhNDEzMS5pcC5nZXcxLnNwb3RpZnkubmV0OjU3MDArMzNFM0Q2QzAzNDg0NDY2MDNFNzUwRDAyMUJCMTJFM0VFNUVBQzc2MjMzOTA5QkU4OENFNkY1Q0M5OUM5NkM1OQ==" May 26 19:08:31 raspberry go-librespot[1455]: time="2025-05-26T19:08:31Z" level=debug msg="put connect state because NEW_DEVICE" May 26 19:08:31 raspberry volumio[1279]: error: MPD error: Error: connect ENOENT /run/mpd/socket May 26 19:08:31 raspberry sudo[1488]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o guest,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //127.0.0.1/usb/DCA2C828A2C8094A/media/Music /mnt/NAS/ssd May 26 19:08:31 raspberry sudo[1488]: pam_unix(sudo:session): session opened for user root by (uid=0) May 26 19:08:31 raspberry kernel: CIFS: Attempting to mount //127.0.0.1/usb/DCA2C828A2C8094A/media/Music May 26 19:08:31 raspberry kernel: CIFS: VFS: cifs_mount failed w/return code = -2 May 26 19:08:31 raspberry sudo[1488]: pam_unix(sudo:session): session closed for user root May 26 19:08:31 raspberry volumio[1279]: info: Cannot mount NAS ssd at system boot, trial number 2 ,retrying in 5 seconds May 26 19:08:32 raspberry volumio[1279]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus May 26 19:08:32 raspberry volumio[1279]: info: go-librespot daemon successfully initialized May 26 19:08:32 raspberry volumio[1279]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus May 26 19:08:32 raspberry volumio[1279]: info: CoreCommandRouter::executeOnPlugin: my_volumio , setMyVolumioToken May 26 19:08:33 raspberry volumio[1279]: info: CoreCommandRouter::executeOnPlugin: my_volumio , setMyVolumioToken May 26 19:08:33 raspberry sudo[1495]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 May 26 19:08:33 raspberry sudo[1495]: pam_unix(sudo:session): session opened for user root by (uid=0) May 26 19:08:33 raspberry sudo[1495]: pam_unix(sudo:session): session closed for user root May 26 19:08:33 raspberry sudo[1497]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 May 26 19:08:33 raspberry sudo[1497]: pam_unix(sudo:session): session opened for user root by (uid=0) May 26 19:08:33 raspberry sudo[1497]: pam_unix(sudo:session): session closed for user root May 26 19:08:33 raspberry sudo[1501]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service May 26 19:08:33 raspberry sudo[1501]: pam_unix(sudo:session): session opened for user root by (uid=0) May 26 19:08:33 raspberry systemd[1]: Started UPnP Renderer front-end to MPD. May 26 19:08:33 raspberry sudo[1501]: pam_unix(sudo:session): session closed for user root May 26 19:08:33 raspberry volumio[1279]: info: Upmpdcli Daemon Started May 26 19:08:33 raspberry volumio[1279]: error: Upnp client error: Error: connect ECONNREFUSED 127.0.0.1:6600 May 26 19:08:34 raspberry volumio[1279]: error: MPD error: Error: connect ENOENT /run/mpd/socket May 26 19:08:34 raspberry systemd[1]: systemd-hostnamed.service: Succeeded. May 26 19:08:34 raspberry go-librespot[1455]: time="2025-05-26T19:08:34Z" level=debug msg="handling transfer player command from a9245c8a38ab198e568dea80cbd8d0bdb3fa3b83" May 26 19:08:35 raspberry go-librespot[1455]: time="2025-05-26T19:08:35Z" level=trace msg="fetched new page 0 with 3140 items (list: 3140)" May 26 19:08:35 raspberry go-librespot[1455]: time="2025-05-26T19:08:35Z" level=debug msg="shuffled context with seed 12673692281370237503 (len: 3140, keep: 566)" May 26 19:08:35 raspberry go-librespot[1455]: time="2025-05-26T19:08:35Z" level=debug msg="loading track spotify:track:0w4RLxsMnxFoiyKjC4nIiy (paused: false, position: 86359ms)" May 26 19:08:35 raspberry go-librespot[1455]: time="2025-05-26T19:08:35Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 26 19:08:35 raspberry go-librespot[1455]: time="2025-05-26T19:08:35Z" level=trace msg="emitting websocket event: will_play" May 26 19:08:35 raspberry go-librespot[1455]: time="2025-05-26T19:08:35Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 345" May 26 19:08:35 raspberry volumio[1279]: info: Initializing connection to go-librespot Websocket May 26 19:08:35 raspberry go-librespot[1455]: time="2025-05-26T19:08:35Z" level=debug msg="new websocket client" May 26 19:08:35 raspberry volumio[1279]: info: Connection to go-librespot Websocket established May 26 19:08:35 raspberry go-librespot[1455]: time="2025-05-26T19:08:35Z" level=debug msg="selected format OGG_VORBIS_320 for spotify:track:0w4RLxsMnxFoiyKjC4nIiy" May 26 19:08:35 raspberry go-librespot[1455]: time="2025-05-26T19:08:35Z" level=debug msg="requested aes key for file ad111822650cfb4ebcc51f2459e9acf3ab623c14, gid: 0w4RLxsMnxFoiyKjC4nIiy" May 26 19:08:35 raspberry go-librespot[1455]: time="2025-05-26T19:08:35Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1670" May 26 19:08:35 raspberry go-librespot[1455]: time="2025-05-26T19:08:35Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1280" May 26 19:08:35 raspberry go-librespot[1455]: time="2025-05-26T19:08:35Z" level=debug msg="fetched first chunk of 25, total size is 12751904 bytes" May 26 19:08:35 raspberry go-librespot[1455]: time="2025-05-26T19:08:35Z" level=debug msg="fetched chunk 2/24, size: 524288" May 26 19:08:36 raspberry go-librespot[1455]: time="2025-05-26T19:08:36Z" level=debug msg="fetched chunk 1/24, size: 524288" May 26 19:08:36 raspberry go-librespot[1455]: time="2025-05-26T19:08:36Z" level=debug msg="fetched chunk 7/24, size: 524288" May 26 19:08:36 raspberry go-librespot[1455]: time="2025-05-26T19:08:36Z" level=debug msg="fetched chunk 6/24, size: 524288" May 26 19:08:36 raspberry go-librespot[1455]: time="2025-05-26T19:08:36Z" level=trace msg="seek to 86359ms (diff: 147ms, samples: 3808431, bytes: 3481105)" May 26 19:08:36 raspberry kernel: pcm512x 1-004d: No SCLK, using BCLK: -2 May 26 19:08:36 raspberry go-librespot[1455]: time="2025-05-26T19:08:36Z" level=debug msg="fetched chunk 3/24, size: 524288" May 26 19:08:36 raspberry go-librespot[1455]: time="2025-05-26T19:08:36Z" level=debug msg="fetched chunk 9/24, size: 524288" May 26 19:08:36 raspberry go-librespot[1455]: time="2025-05-26T19:08:36Z" level=info msg="loaded track \"Little Darlin'\" (uri: spotify:track:0w4RLxsMnxFoiyKjC4nIiy, paused: false, position: 86359ms, duration: 328386ms)" May 26 19:08:36 raspberry go-librespot[1455]: time="2025-05-26T19:08:36Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 26 19:08:36 raspberry go-librespot[1455]: time="2025-05-26T19:08:36Z" level=trace msg="emitting websocket event: metadata" May 26 19:08:36 raspberry go-librespot[1455]: time="2025-05-26T19:08:36Z" level=trace msg="emitting websocket event: active" May 26 19:08:36 raspberry go-librespot[1455]: time="2025-05-26T19:08:36Z" level=debug msg="sending successful reply for delaer request" May 26 19:08:36 raspberry volumio[1279]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:0w4RLxsMnxFoiyKjC4nIiy","name":"Little Darlin'","artist_names":["Benjamin Biolay"],"album_name":"Négatif","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02ef677035443438fb709c5a84","position":86359,"duration":328386,"release_date":"year:2003 month:4 day:7","track_number":7,"disc_number":1}} May 26 19:08:36 raspberry volumio[1279]: SPOTIFY: received: {"type":"active","data":null} May 26 19:08:36 raspberry volumio[1279]: info: Aligning Spotify Volume to Volumio Volume May 26 19:08:36 raspberry volumio[1279]: info: CoreCommandRouter::volumioGetState May 26 19:08:36 raspberry volumio[1279]: info: CorePlayQueue::getTrack 0 May 26 19:08:36 raspberry volumio[1279]: info: Setting Spotify Volume from Volumio: 49 May 26 19:08:36 raspberry go-librespot[1455]: time="2025-05-26T19:08:36Z" level=debug msg="fetched chunk 8/24, size: 524288" May 26 19:08:36 raspberry go-librespot[1455]: time="2025-05-26T19:08:36Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 26 19:08:36 raspberry go-librespot[1455]: time="2025-05-26T19:08:36Z" level=trace msg="emitting websocket event: playing" May 26 19:08:36 raspberry go-librespot[1455]: time="2025-05-26T19:08:36Z" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update May 26 19:08:36 raspberry volumio[1279]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:0w4RLxsMnxFoiyKjC4nIiy","play_origin":"playlist"}} May 26 19:08:36 raspberry go-librespot[1455]: time="2025-05-26T19:08:36Z" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update May 26 19:08:36 raspberry go-librespot[1455]: time="2025-05-26T19:08:36Z" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update May 26 19:08:36 raspberry volumio[1279]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 26 19:08:36 raspberry volumio[1279]: TypeError: Cannot read property 'service' of undefined May 26 19:08:36 raspberry volumio[1279]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:336:50) May 26 19:08:36 raspberry volumio[1279]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:262:18) May 26 19:08:36 raspberry volumio[1279]: at WebSocket.message (/data/plugins/music_service/spop/index.js:189:14) May 26 19:08:36 raspberry volumio[1279]: at WebSocket.emit (events.js:315:20) May 26 19:08:36 raspberry volumio[1279]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1203:20) May 26 19:08:36 raspberry volumio[1279]: at Receiver.emit (events.js:315:20) May 26 19:08:36 raspberry volumio[1279]: at /data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:608:16 May 26 19:08:36 raspberry volumio[1279]: at internal/process/task_queues.js:149:7 May 26 19:08:36 raspberry volumio[1279]: at AsyncResource.runInAsyncScope (async_hooks.js:197:9) May 26 19:08:36 raspberry volumio[1279]: at AsyncResource.runMicrotask (internal/process/task_queues.js:146:8) May 26 19:08:36 raspberry volumio[1279]: at processTicksAndRejections (internal/process/task_queues.js:93:5) May 26 19:08:36 raspberry volumio[1279]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 26 19:08:36 raspberry go-librespot[1455]: time="2025-05-26T19:08:36Z" level=debug msg="put connect state inactive" May 26 19:08:36 raspberry go-librespot[1455]: time="2025-05-26T19:08:36Z" level=trace msg="emitting websocket event: inactive" May 26 19:08:36 raspberry sudo[1519]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-05-26 19:07 May 26 19:08:36 raspberry sudo[1519]: 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="1c5fa5a8788b087ca429be9d10851b25c5cc4f5b" VOLUMIO_FE_VERSION="e5ce74e254a237ac98580c4437c4ed223c7d5cd9" VOLUMIO_FE3_VERSION="a86adf3c7ed2d6c50d9bca768f58ab2f56832dc1" VOLUMIO_BE_VERSION="c8882d89d3d4e0a1571e0dc9701741128f5a1656" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Thu 31 Mar 2022 02:51:41 PM CEST" VOLUMIO_VERSION="3.251" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="e83cc5fcd68eb3ee4105ab0b8b3779ea"