-- Logs begin at Thu 2019-02-14 12:11:58 EET, end at Sun 2025-05-11 11:56:34 EEST. -- May 11 11:55:23 streamer kernel: usb 1-1: New USB device strings: Mfr=0, Product=1, SerialNumber=0 May 11 11:55:23 streamer kernel: usb 1-1: Product: USB2.0 Hub May 11 11:55:23 streamer kernel: hub 1-1:1.0: USB hub found May 11 11:55:23 streamer kernel: hub 1-1:1.0: 4 ports detected May 11 11:55:23 streamer kernel: fuse: init (API version 7.39) May 11 11:55:23 streamer kernel: squashfs: version 4.0 (2009/01/31) Phillip Lougher May 11 11:55:23 streamer kernel: EXT4-fs (mmcblk0p2): recovery complete May 11 11:55:23 streamer kernel: EXT4-fs (mmcblk0p2): mounted filesystem fb80cb44-b4d3-4b36-be35-613cba0a09fb r/w with ordered data mode. Quota mode: none. May 11 11:55:23 streamer kernel: loop0: detected capacity change from 0 to 995064 May 11 11:55:23 streamer kernel: EXT4-fs (mmcblk0p3): recovery complete May 11 11:55:23 streamer kernel: EXT4-fs (mmcblk0p3): mounted filesystem 2899bccc-8620-4c7a-b56a-43fd2f7a836a r/w with ordered data mode. Quota mode: none. May 11 11:55:23 streamer systemd[1]: System time before build time, advancing clock. May 11 11:55:23 streamer kernel: NET: Registered PF_INET6 protocol family May 11 11:55:23 streamer kernel: Segment Routing with IPv6 May 11 11:55:23 streamer kernel: In-situ OAM (IOAM) with IPv6 May 11 11:55:23 streamer 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 11 11:55:23 streamer systemd[1]: Detected architecture arm. May 11 11:55:23 streamer systemd[1]: Set hostname to . May 11 11:55:23 streamer 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 11 11:55:23 streamer systemd[1]: Listening on udev Control Socket. May 11 11:55:23 streamer systemd[1]: Reached target System Time Synchronized. May 11 11:55:23 streamer systemd[1]: Listening on fsck to fsckd communication Socket. May 11 11:55:23 streamer systemd[1]: Listening on Journal Audit Socket. May 11 11:55:23 streamer systemd[1]: Listening on RPCbind Server Activation Socket. May 11 11:55:23 streamer systemd[1]: Started Forward Password Requests to Wall Directory Watch. May 11 11:55:23 streamer kernel: i2c_dev: i2c /dev entries driver May 11 11:55:23 streamer systemd-journald[308]: Journal started May 11 11:55:23 streamer systemd-journald[308]: Runtime journal (/run/log/journal/a89b7be63bc86b985c184d84675fe488) is 7.5M, max 30.0M, 22.5M free. Feb 14 12:11:58 streamer systemd-modules-load[304]: Inserted module 'i2c_dev' May 11 11:55:23 streamer fake-hwclock[300]: Sun May 11 08:55:23 UTC 2025 May 11 11:55:23 streamer systemd[1]: Started Restore / save the current clock. May 11 11:55:23 streamer systemd[1]: Started Load Kernel Modules. May 11 11:55:23 streamer systemd[1]: Starting Apply Kernel Variables... May 11 11:55:23 streamer systemd[1]: Mounting Kernel Configuration File System... May 11 11:55:23 streamer systemd[1]: Mounting FUSE Control File System... May 11 11:55:23 streamer systemd[1]: Started Load/Save Random Seed. May 11 11:55:23 streamer systemd[1]: Mounted Kernel Configuration File System. May 11 11:55:23 streamer systemd[1]: Mounted FUSE Control File System. May 11 11:55:23 streamer systemd[1]: Started Apply Kernel Variables. May 11 11:55:23 streamer systemd[1]: dynamicswap.service: Succeeded. May 11 11:55:23 streamer systemd[1]: Started Create System Users. May 11 11:55:23 streamer systemd[1]: Starting Create Static Device Nodes in /dev... May 11 11:55:23 streamer systemd[1]: Started udev Coldplug all Devices. May 11 11:55:23 streamer systemd[1]: Starting Helper to synchronize boot up for ifupdown... May 11 11:55:23 streamer systemd[1]: Started Create Static Device Nodes in /dev. May 11 11:55:23 streamer systemd[1]: Reached target Local File Systems (Pre). May 11 11:55:23 streamer systemd[1]: var-log.mount: Directory /var/log to mount over is not empty, mounting anyway. May 11 11:55:23 streamer systemd[1]: Mounting /var/log... May 11 11:55:23 streamer systemd[1]: Mounting /var/spool/cups... May 11 11:55:23 streamer systemd[1]: tmp.mount: Directory /tmp to mount over is not empty, mounting anyway. May 11 11:55:23 streamer systemd[1]: Mounting /tmp... May 11 11:55:23 streamer systemd[1]: Starting udev Kernel Device Manager... May 11 11:55:23 streamer systemd[1]: Started Helper to synchronize boot up for ifupdown. May 11 11:55:23 streamer systemd[1]: Mounted /var/log. May 11 11:55:23 streamer systemd[1]: Mounted /var/spool/cups. May 11 11:55:23 streamer systemd[1]: Mounted /tmp. May 11 11:55:23 streamer systemd[1]: Mounting /var/spool/cups/tmp... May 11 11:55:23 streamer systemd[1]: Starting Flush Journal to Persistent Storage... May 11 11:55:23 streamer systemd[1]: Mounted /var/spool/cups/tmp. May 11 11:55:23 streamer systemd-udevd[331]: Network interface NamePolicy= disabled on kernel command line, ignoring. May 11 11:55:23 streamer systemd-journald[308]: Runtime journal (/run/log/journal/a89b7be63bc86b985c184d84675fe488) is 7.5M, max 30.0M, 22.5M free. May 11 11:55:23 streamer systemd[1]: Started udev Kernel Device Manager. May 11 11:55:23 streamer systemd[1]: Starting Show Plymouth Boot Screen... May 11 11:55:23 streamer systemd[1]: Started Flush Journal to Persistent Storage. May 11 11:55:23 streamer systemd[1]: plymouth-start.service: Succeeded. May 11 11:55:23 streamer systemd[1]: Started Show Plymouth Boot Screen. May 11 11:55:23 streamer systemd[1]: Started Forward Password Requests to Plymouth Directory Watch. May 11 11:55:23 streamer systemd[1]: Condition check resulted in Dispatch Password Requests to Console Directory Watch being skipped. May 11 11:55:23 streamer systemd[1]: Reached target Local Encrypted Volumes. May 11 11:55:23 streamer systemd[1]: Reached target Paths. May 11 11:55:23 streamer systemd-udevd[336]: Using default interface naming scheme 'v240'. May 11 11:55:23 streamer kernel: mc: Linux media interface: v0.10 May 11 11:55:23 streamer systemd-udevd[336]: link_config: autonegotiation is unset or enabled, the speed and duplex are not writable. May 11 11:55:23 streamer kernel: vc_sm_cma: module is from the staging directory, the quality is unknown, you have been warned. May 11 11:55:23 streamer kernel: bcm2835_vc_sm_cma_probe: Videocore shared memory driver May 11 11:55:23 streamer kernel: [vc_sm_connected_init]: start May 11 11:55:23 streamer kernel: [vc_sm_connected_init]: installed successfully May 11 11:55:23 streamer kernel: videodev: Linux video capture interface: v2.00 May 11 11:55:23 streamer kernel: rpi-gpiomem fe200000.gpiomem: window base 0xfe200000 size 0x00001000 May 11 11:55:23 streamer kernel: rpi-gpiomem fe200000.gpiomem: initialised 1 regions as /dev/gpiomem May 11 11:55:23 streamer kernel: bcm2835_mmal_vchiq: module is from the staging directory, the quality is unknown, you have been warned. May 11 11:55:23 streamer kernel: bcm2835_isp: module is from the staging directory, the quality is unknown, you have been warned. May 11 11:55:23 streamer kernel: bcm2835-isp bcm2835-isp: Device node output[0] registered as /dev/video13 May 11 11:55:23 streamer kernel: bcm2835-isp bcm2835-isp: Device node capture[0] registered as /dev/video14 May 11 11:55:23 streamer kernel: bcm2835-isp bcm2835-isp: Device node capture[1] registered as /dev/video15 May 11 11:55:23 streamer kernel: bcm2835-isp bcm2835-isp: Device node stats[2] registered as /dev/video16 May 11 11:55:23 streamer kernel: bcm2835-isp bcm2835-isp: Register output node 0 with media controller May 11 11:55:23 streamer kernel: bcm2835-isp bcm2835-isp: Register capture node 1 with media controller May 11 11:55:23 streamer kernel: bcm2835-isp bcm2835-isp: Register capture node 2 with media controller May 11 11:55:23 streamer kernel: bcm2835-isp bcm2835-isp: Register capture node 3 with media controller May 11 11:55:23 streamer kernel: bcm2835-isp bcm2835-isp: Device node output[0] registered as /dev/video20 May 11 11:55:23 streamer kernel: bcm2835_codec: module is from the staging directory, the quality is unknown, you have been warned. May 11 11:55:23 streamer kernel: bcm2835-isp bcm2835-isp: Device node capture[0] registered as /dev/video21 May 11 11:55:23 streamer kernel: bcm2835-isp bcm2835-isp: Device node capture[1] registered as /dev/video22 May 11 11:55:23 streamer kernel: bcm2835-isp bcm2835-isp: Device node stats[2] registered as /dev/video23 May 11 11:55:23 streamer kernel: bcm2835-isp bcm2835-isp: Register output node 0 with media controller May 11 11:55:23 streamer kernel: bcm2835-isp bcm2835-isp: Register capture node 1 with media controller May 11 11:55:23 streamer kernel: bcm2835-isp bcm2835-isp: Register capture node 2 with media controller May 11 11:55:23 streamer kernel: bcm2835-isp bcm2835-isp: Register capture node 3 with media controller May 11 11:55:23 streamer kernel: bcm2835-isp bcm2835-isp: Loaded V4L2 bcm2835-isp May 11 11:55:23 streamer kernel: bcm2835_v4l2: module is from the staging directory, the quality is unknown, you have been warned. May 11 11:55:23 streamer kernel: bcm2835-codec bcm2835-codec: Device registered as /dev/video10 May 11 11:55:23 streamer kernel: bcm2835-codec bcm2835-codec: Loaded V4L2 decode May 11 11:55:23 streamer kernel: bcm2835-codec bcm2835-codec: Device registered as /dev/video11 May 11 11:55:23 streamer kernel: bcm2835-codec bcm2835-codec: Loaded V4L2 encode May 11 11:55:23 streamer kernel: bcm2835-codec bcm2835-codec: Device registered as /dev/video12 May 11 11:55:23 streamer kernel: bcm2835-codec bcm2835-codec: Loaded V4L2 isp May 11 11:55:23 streamer kernel: bcm2835-codec bcm2835-codec: Device registered as /dev/video18 May 11 11:55:23 streamer kernel: bcm2835-codec bcm2835-codec: Loaded V4L2 image_fx May 11 11:55:23 streamer kernel: bcm2835-codec bcm2835-codec: Device registered as /dev/video31 May 11 11:55:23 streamer kernel: bcm2835-codec bcm2835-codec: Loaded V4L2 encode_image May 11 11:55:23 streamer kernel: rpivid_hevc: module is from the staging directory, the quality is unknown, you have been warned. May 11 11:55:23 streamer kernel: rpivid feb10000.codec: Device registered as /dev/video19 May 11 11:55:23 streamer kernel: cfg80211: Loading compiled-in X.509 certificates for regulatory database May 11 11:55:23 streamer kernel: Loaded X.509 cert 'benh@debian.org: 577e021cb980e0e820821ba7b54b4961b8b4fadf' May 11 11:55:23 streamer kernel: Loaded X.509 cert 'romain.perier@gmail.com: 3abbc6ec146e09d1b6016ab9d6cf71dd233f0328' May 11 11:55:23 streamer kernel: Loaded X.509 cert 'sforshee: 00b28ddf47aef9cea7' May 11 11:55:23 streamer kernel: Loaded X.509 cert 'wens: 61c038651aabdcf94bd0ac7ff06c7248db18c600' May 11 11:55:23 streamer kernel: Bluetooth: Core ver 2.22 May 11 11:55:23 streamer kernel: NET: Registered PF_BLUETOOTH protocol family May 11 11:55:23 streamer kernel: Bluetooth: HCI device and connection manager initialized May 11 11:55:23 streamer kernel: Bluetooth: HCI socket layer initialized May 11 11:55:23 streamer kernel: Bluetooth: L2CAP socket layer initialized May 11 11:55:23 streamer kernel: Bluetooth: SCO socket layer initialized May 11 11:55:23 streamer kernel: Bluetooth: HCI UART driver ver 2.3 May 11 11:55:23 streamer kernel: Bluetooth: HCI UART protocol H4 registered May 11 11:55:23 streamer kernel: Bluetooth: HCI UART protocol Three-wire (H5) registered May 11 11:55:23 streamer kernel: Bluetooth: HCI UART protocol Broadcom registered May 11 11:55:23 streamer kernel: hci_uart_bcm serial0-0: supply vbat not found, using dummy regulator May 11 11:55:23 streamer kernel: hci_uart_bcm serial0-0: supply vddio not found, using dummy regulator May 11 11:55:24 streamer kernel: brcmfmac: F1 signature read @0x18000000=0x15264345 May 11 11:55:24 streamer kernel: brcmfmac: brcmf_fw_alloc_request: using brcm/brcmfmac43455-sdio for chip BCM4345/6 May 11 11:55:24 streamer kernel: usbcore: registered new interface driver brcmfmac May 11 11:55:24 streamer kernel: uart-pl011 fe201000.serial: no DMA platform data May 11 11:55:23 streamer systemd[1]: Found device /dev/disk/by-uuid/51B1-040D. May 11 11:55:23 streamer systemd[1]: Starting File System Check on /dev/disk/by-uuid/51B1-040D... May 11 11:55:23 streamer systemd-udevd[341]: link_config: autonegotiation is unset or enabled, the speed and duplex are not writable. May 11 11:55:24 streamer kernel: snd_bcm2835: module is from the staging directory, the quality is unknown, you have been warned. May 11 11:55:24 streamer kernel: snd_bcm2835: unknown parameter 'enable_compat_alsa' ignored May 11 11:55:24 streamer kernel: brcmfmac: brcmf_c_process_txcap_blob: no txcap_blob available (err=-2) May 11 11:55:24 streamer kernel: brcmfmac: brcmf_c_preinit_dcmds: Firmware: BCM4345/6 wl0: Nov 1 2021 00:37:25 version 7.45.241 (1a2f2fa CY) FWID 01-703fd60 May 11 11:55:24 streamer kernel: Bluetooth: hci0: BCM: chip id 107 May 11 11:55:24 streamer kernel: Bluetooth: hci0: BCM: features 0x2f May 11 11:55:24 streamer kernel: Bluetooth: hci0: BCM4345C0 May 11 11:55:24 streamer kernel: Bluetooth: hci0: BCM4345C0 (003.001.025) build 0000 May 11 11:55:24 streamer kernel: bcm2835_audio bcm2835_audio: card created with 4 channels May 11 11:55:24 streamer kernel: bcm2835_audio bcm2835_audio: card created with 4 channels May 11 11:55:24 streamer kernel: Bluetooth: hci0: BCM4345C0 'brcm/BCM4345C0.hcd' Patch May 11 11:55:24 streamer systemd-udevd[336]: link_config: autonegotiation is unset or enabled, the speed and duplex are not writable. May 11 11:55:24 streamer kernel: wm8804 1-003b: revision E May 11 11:55:24 streamer systemd-fsck[440]: fsck.fat 4.1 (2017-01-24) May 11 11:55:24 streamer systemd-fsck[440]: /dev/mmcblk0p1: 479 files, 168040/184582 clusters May 11 11:55:24 streamer systemd[1]: Started File System Check on /dev/disk/by-uuid/51B1-040D. May 11 11:55:24 streamer kernel: alsactl[475]: memfd_create() called without MFD_EXEC or MFD_NOEXEC_SEAL set May 11 11:55:24 streamer systemd[1]: Condition check resulted in /sys/subsystem/net/devices/eth0 being skipped. May 11 11:55:24 streamer systemd[1]: Condition check resulted in /sys/subsystem/net/devices/wlan0 being skipped. May 11 11:55:24 streamer systemd[1]: Created slice system-bthelper.slice. May 11 11:55:24 streamer systemd[1]: Starting Show Plymouth Boot Screen... May 11 11:55:24 streamer systemd[1]: Condition check resulted in Rebuild Hardware Database being skipped. May 11 11:55:24 streamer systemd[1]: Condition check resulted in Huge Pages File System being skipped. May 11 11:55:24 streamer systemd[1]: Condition check resulted in Set Up Additional Binary Formats being skipped. May 11 11:55:24 streamer systemd[1]: Listening on Load/Save RF Kill Switch Status /dev/rfkill Watch. May 11 11:55:24 streamer systemd[1]: Mounting /boot... May 11 11:55:24 streamer systemd[1]: Started File System Check Daemon to report status. May 11 11:55:24 streamer systemd[1]: Starting Load/Save RF Kill Switch Status... May 11 11:55:24 streamer systemd[1]: plymouth-start.service: Succeeded. May 11 11:55:24 streamer systemd[1]: Started Show Plymouth Boot Screen. May 11 11:55:24 streamer systemd[1]: Condition check resulted in Dispatch Password Requests to Console Directory Watch being skipped. May 11 11:55:24 streamer systemd[1]: Mounted /boot. May 11 11:55:24 streamer systemd[1]: Reached target Local File Systems. May 11 11:55:24 streamer systemd[1]: Started ifup for eth0. May 11 11:55:24 streamer systemd[1]: Starting Raise network interfaces... May 11 11:55:24 streamer systemd[1]: Starting Tell Plymouth To Write Out Runtime Data... May 11 11:55:24 streamer systemd[1]: Started ifup for wlan0. May 11 11:55:24 streamer systemd[1]: Starting Create Volatile Files and Directories... May 11 11:55:24 streamer systemd[1]: Starting Preprocess NFS configuration... May 11 11:55:24 streamer systemd[1]: Condition check resulted in Commit a transient machine-id on disk being skipped. May 11 11:55:24 streamer systemd[1]: Started Load/Save RF Kill Switch Status. May 11 11:55:24 streamer systemd[1]: plymouth-read-write.service: Succeeded. May 11 11:55:24 streamer systemd[1]: Started Tell Plymouth To Write Out Runtime Data. May 11 11:55:24 streamer systemd[1]: Received SIGRTMIN+20 from PID 192 (plymouthd). May 11 11:55:24 streamer systemd[1]: nfs-config.service: Succeeded. May 11 11:55:24 streamer systemd[1]: Started Preprocess NFS configuration. May 11 11:55:24 streamer systemd[1]: Condition check resulted in RPC security service for NFS client and server being skipped. May 11 11:55:24 streamer systemd[1]: Condition check resulted in RPC security service for NFS server being skipped. May 11 11:55:24 streamer systemd[1]: Reached target NFS client services. May 11 11:55:24 streamer kernel: warning: `iwconfig' uses wireless extensions which will stop working for Wi-Fi 7 hardware; use nl80211 May 11 11:55:24 streamer systemd[1]: Started Create Volatile Files and Directories. May 11 11:55:24 streamer systemd[1]: Condition check resulted in Network Time Synchronization being skipped. May 11 11:55:24 streamer systemd[1]: Started Entropy daemon using the HAVEGE algorithm. May 11 11:55:24 streamer systemd[1]: Starting RPC bind portmap service... May 11 11:55:24 streamer systemd[1]: Starting Update UTMP about System Boot/Shutdown... May 11 11:55:24 streamer systemd[1]: Started Update UTMP about System Boot/Shutdown. May 11 11:55:24 streamer systemd[1]: Reached target System Initialization. May 11 11:55:24 streamer systemd[1]: Started Daily apt download activities. May 11 11:55:24 streamer systemd[1]: Started Daily apt upgrade and clean activities. May 11 11:55:24 streamer systemd[1]: Listening on triggerhappy.socket. May 11 11:55:24 streamer systemd[1]: Started Daily Cleanup of Temporary Directories. May 11 11:55:24 streamer systemd[1]: Reached target Timers. May 11 11:55:24 streamer systemd[1]: Listening on D-Bus System Message Bus Socket. May 11 11:55:24 streamer kernel: 8021q: 802.1Q VLAN Support v1.8 May 11 11:55:24 streamer systemd[1]: Listening on Avahi mDNS/DNS-SD Stack Activation Socket. May 11 11:55:24 streamer systemd[1]: Reached target Sockets. May 11 11:55:24 streamer systemd[1]: Reached target Basic System. May 11 11:55:24 streamer kernel: Bluetooth: hci0: BCM: features 0x2f May 11 11:55:24 streamer kernel: Bluetooth: hci0: BCM43455 37.4MHz Raspberry Pi 3+ May 11 11:55:24 streamer kernel: Bluetooth: hci0: BCM4345C0 (003.001.025) build 0342 May 11 11:55:24 streamer kernel: brcmfmac: brcmf_cfg80211_set_power_mgmt: power save disabled May 11 11:55:24 streamer systemd[1]: Started D-Bus System Message Bus. May 11 11:55:25 streamer systemd[1]: Starting triggerhappy global hotkey daemon... May 11 11:55:25 streamer systemd[1]: Condition check resulted in Volumio SSH enabler being skipped. May 11 11:55:25 streamer systemd[1]: Started Volumio Iptables Module. May 11 11:55:25 streamer systemd[1]: Starting Wireless Services... May 11 11:55:25 streamer systemd[1]: Started UPnP Renderer front-end to MPD. May 11 11:55:25 streamer systemd[1]: Started Manage Sound Card State (restore and store). May 11 11:55:25 streamer systemd[1]: Condition check resulted in getty on tty2-tty6 if dbus and logind are not available being skipped. May 11 11:55:25 streamer alsactl[606]: alsactl 1.1.8 daemon started May 11 11:55:25 streamer thd[599]: Unable to parse trigger line: May 11 11:55:25 streamer thd[599]: Unable to parse trigger line: KEY_MIN_INTERESTING 1 /usr/local/bin/volumio volume toggle May 11 11:55:25 streamer thd[599]: Unable to parse trigger line: May 11 11:55:25 streamer thd[599]: Found socket passed from systemd May 11 11:55:25 streamer systemd[1]: Starting WPA supplicant... May 11 11:55:25 streamer systemd[1]: Started Volumio Log Rotation Service. May 11 11:55:25 streamer systemd[1]: Condition check resulted in Copy user wpa_supplicant.conf being skipped. May 11 11:55:25 streamer systemd[1]: Starting dhcpcd on all interfaces... May 11 11:55:25 streamer systemd[1]: Started MPD Monitor Service. May 11 11:55:25 streamer systemd[1]: Started volumio-remote-updater.service. May 11 11:55:25 streamer systemd[1]: Starting Volumio Time Update Utility... May 11 11:55:25 streamer systemd[1]: Starting Save/Restore Sound Card State... May 11 11:55:25 streamer systemd[1]: Starting Avahi mDNS/DNS-SD Stack... May 11 11:55:25 streamer systemd[1]: Starting Configure Bluetooth Modems connected by UART... May 11 11:55:25 streamer systemd[1]: Starting Login Service... May 11 11:55:25 streamer systemd[1]: Started RPC bind portmap service. May 11 11:55:25 streamer volumio-time-update[618]: volumio-time-update-util: Fetching time from Volumio... May 11 11:55:25 streamer systemd[1]: Started triggerhappy global hotkey daemon. May 11 11:55:25 streamer dhcpcd[612]: Not running dhcpcd because /etc/network/interfaces May 11 11:55:25 streamer dhcpcd[612]: defines some interfaces that will use a May 11 11:55:25 streamer dhcpcd[612]: DHCP client or static address May 11 11:55:25 streamer systemd[1]: dhcpcd.service: Control process exited, code=exited, status=6/NOTCONFIGURED May 11 11:55:25 streamer systemd[1]: dhcpcd.service: Failed with result 'exit-code'. May 11 11:55:25 streamer systemd[1]: Failed to start dhcpcd on all interfaces. May 11 11:55:25 streamer systemd[1]: Reached target RPC Port Mapper. May 11 11:55:25 streamer systemd[1]: Reached target Remote File Systems (Pre). May 11 11:55:25 streamer systemd[1]: Reached target Remote File Systems. May 11 11:55:25 streamer systemd[1]: Starting LSB: Load kernel modules needed to enable cpufreq scaling... May 11 11:55:25 streamer sh[496]: eth0: waiting for carrier May 11 11:55:25 streamer kernel: bcmgenet fd580000.ethernet: configuring instance for external RGMII (RX delay) May 11 11:55:25 streamer kernel: bcmgenet fd580000.ethernet eth0: Link is Down May 11 11:55:25 streamer dhcpcd[545]: eth0: waiting for carrier May 11 11:55:25 streamer sh[503]: wlan0=wlan0 May 11 11:55:25 streamer systemd-logind[622]: New seat seat0. May 11 11:55:25 streamer mpd_monitor.sh[613]: MPD error: Connection refused May 11 11:55:25 streamer avahi-daemon[620]: Found user 'avahi' (UID 110) and group 'avahi' (GID 113). May 11 11:55:25 streamer mpd_monitor.sh[613]: mpd: no process found May 11 11:55:25 streamer avahi-daemon[620]: Successfully dropped root privileges. May 11 11:55:25 streamer avahi-daemon[620]: avahi-daemon 0.7 starting up. May 11 11:55:25 streamer systemd[1]: Started Login Service. May 11 11:55:25 streamer systemd[1]: Started Save/Restore Sound Card State. May 11 11:55:25 streamer systemd[1]: hciuart.service: Succeeded. May 11 11:55:25 streamer wpa_supplicant[609]: Successfully initialized wpa_supplicant May 11 11:55:25 streamer systemd[1]: Started Configure Bluetooth Modems connected by UART. May 11 11:55:25 streamer avahi-daemon[620]: Successfully called chroot(). May 11 11:55:25 streamer avahi-daemon[620]: Successfully dropped remaining capabilities. May 11 11:55:25 streamer avahi-daemon[620]: Loading service file /services/volumio.service. May 11 11:55:25 streamer avahi-daemon[620]: Network interface enumeration completed. May 11 11:55:25 streamer avahi-daemon[620]: Server startup complete. Host name is streamer.local. Local service cookie is 369068464. May 11 11:55:25 streamer avahi-daemon[620]: Service "Streamer" (/services/volumio.service) successfully established. May 11 11:55:25 streamer systemd[1]: Started Raise network interfaces. May 11 11:55:25 streamer systemd[1]: Started WPA supplicant. May 11 11:55:25 streamer systemd[1]: Started Avahi mDNS/DNS-SD Stack. May 11 11:55:25 streamer systemd[1]: Listening on mpd.socket. May 11 11:55:25 streamer systemd[1]: Reached target Network. May 11 11:55:25 streamer systemd[1]: Starting Network Time Service... May 11 11:55:25 streamer systemd[1]: Condition check resulted in fast remote file copy program daemon being skipped. May 11 11:55:25 streamer systemd[1]: Starting Permit User Sessions... May 11 11:55:25 streamer systemd[1]: Reached target Network is Online. May 11 11:55:25 streamer systemd[1]: Starting LSB: Brings up/down network automatically... May 11 11:55:25 streamer systemd[1]: Starting /etc/rc.local Compatibility... May 11 11:55:25 streamer systemd[1]: Starting Samba NMB Daemon... May 11 11:55:25 streamer systemd[1]: Starting Raspberry Pi bluetooth helper... May 11 11:55:25 streamer systemd[1]: Reached target Sound Card. May 11 11:55:25 streamer systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. May 11 11:55:25 streamer systemd[1]: Starting Music Player Daemon... May 11 11:55:25 streamer systemd[1]: Started /etc/rc.local Compatibility. May 11 11:55:25 streamer volumio-remote-updater[614]: Error: No active session May 11 11:55:25 streamer volumio-remote-updater[614]: [2025-05-11 11:55:25] [info] asio async_connect error: system:111 (Connection refused) May 11 11:55:25 streamer volumio-remote-updater[614]: [2025-05-11 11:55:25] [info] Error getting remote endpoint: system:107 (Transport endpoint is not connected) May 11 11:55:25 streamer volumio-remote-updater[614]: [2025-05-11 11:55:25] [error] handle_connect error: Underlying Transport Error May 11 11:55:25 streamer systemd[1]: Started Permit User Sessions. May 11 11:55:25 streamer systemd[1]: Starting Hold until boot process finishes up... May 11 11:55:25 streamer systemd[1]: Starting Terminate Plymouth Boot Screen... May 11 11:55:25 streamer systemd[1]: iptables.service: Succeeded. May 11 11:55:25 streamer systemd[1]: Received SIGRTMIN+21 from PID 192 (plymouthd). May 11 11:55:25 streamer volumio[605]: Could not open config: /tmp/upmpdcli.conf May 11 11:55:26 streamer systemd[1]: plymouth-quit-wait.service: Succeeded. May 11 11:55:26 streamer systemd[1]: Started Hold until boot process finishes up. May 11 11:55:26 streamer systemd[1]: plymouth-quit.service: Succeeded. May 11 11:55:26 streamer systemd[1]: Started Terminate Plymouth Boot Screen. May 11 11:55:26 streamer systemd[1]: Received SIGRTMIN+21 from PID 192 (n/a). May 11 11:55:26 streamer systemd[1]: Started Getty on tty1. May 11 11:55:26 streamer systemd[1]: Reached target Login Prompts. May 11 11:55:26 streamer systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE May 11 11:55:26 streamer systemd[1]: upmpdcli.service: Failed with result 'exit-code'. May 11 11:55:26 streamer bthelper[700]: Raspberry Pi BDADDR already set May 11 11:55:26 streamer loadcpufreq[631]: Loading cpufreq kernel modules...done (none). May 11 11:55:26 streamer systemd[1]: Started Raspberry Pi bluetooth helper. May 11 11:55:26 streamer systemd[1]: Started LSB: Load kernel modules needed to enable cpufreq scaling. May 11 11:55:26 streamer systemd[1]: Starting LSB: set CPUFreq kernel parameters... May 11 11:55:26 streamer systemd[1]: Starting Bluetooth service... May 11 11:55:26 streamer volumio-time-update[618]: volumio-time-update-util: Date not found in response May 11 11:55:26 streamer volumio-time-update[618]: volumio-time-update-util: Retrying in 5 seconds... May 11 11:55:26 streamer ifplugd(eth0)[759]: ifplugd 0.28 initializing. May 11 11:55:26 streamer ifplugd(eth0)[759]: Using interface eth0/E4:5F:01:4D:AC:BB with driver (version: 6.6.62-v7l+) May 11 11:55:26 streamer ifplugd(eth0)[759]: Using detection mode: SIOCETHTOOL May 11 11:55:26 streamer ifplugd(eth0)[759]: Initialization complete, link beat not detected. May 11 11:55:26 streamer ntpd[692]: ntpd 4.2.8p12@1.3728-o (1): Starting May 11 11:55:26 streamer ntpd[692]: Command line: /usr/sbin/ntpd -p /var/run/ntpd.pid -g -u 103:103 May 11 11:55:26 streamer ntpd[760]: proto: precision = 0.833 usec (-20) May 11 11:55:26 streamer systemd[1]: Started Network Time Service. May 11 11:55:26 streamer ntpd[760]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): good hash signature May 11 11:55:26 streamer ntpd[760]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): loaded, expire=2024-12-28T00:00:00Z last=2017-01-01T00:00:00Z ofs=37 May 11 11:55:26 streamer ntpd[760]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): expired less than 135 days ago May 11 11:55:26 streamer ntpd[760]: Listen and drop on 0 v6wildcard [::]:123 May 11 11:55:26 streamer ntpd[760]: Listen and drop on 1 v4wildcard 0.0.0.0:123 May 11 11:55:26 streamer ntpd[760]: Listen normally on 2 lo 127.0.0.1:123 May 11 11:55:26 streamer ntpd[760]: Listening on routing socket on fd #19 for interface updates May 11 11:55:26 streamer ntpd[760]: kernel reports TIME_ERROR: 0x41: Clock Unsynchronized May 11 11:55:26 streamer ntpd[760]: kernel reports TIME_ERROR: 0x41: Clock Unsynchronized May 11 11:55:26 streamer ifplugd[695]: Network Interface Plugging Daemon...start eth0...done. May 11 11:55:26 streamer systemd[1]: Started LSB: Brings up/down network automatically. May 11 11:55:26 streamer cpufrequtils[745]: CPUFreq Utilities: Setting ondemand CPUFreq governor...CPU0...CPU1...CPU2...CPU3...done. May 11 11:55:26 streamer systemd[1]: Started LSB: set CPUFreq kernel parameters. May 11 11:55:26 streamer haveged[548]: haveged: ver: 1.9.1; arch: generic; vend: ; build: (gcc 8.2.0 CTV); collect: 128K May 11 11:55:26 streamer haveged[548]: haveged: cpu: (VC); data: 16K (D); inst: 16K (D); idx: 11/40; sz: 14768/63488 May 11 11:55:26 streamer haveged[548]: haveged: tot tests(BA8): A:1/1 B:1/1 continuous tests(B): last entropy estimate 8.00132 May 11 11:55:26 streamer haveged[548]: haveged: fills: 0, generated: 0 May 11 11:55:26 streamer bluetoothd[746]: Bluetooth daemon 5.50 May 11 11:55:26 streamer bluetoothd[746]: Unknown key AutoConnectTimeout for group General in /etc/bluetooth/main.conf May 11 11:55:26 streamer systemd[1]: Started Bluetooth service. May 11 11:55:26 streamer systemd[1]: Reached target Bluetooth. May 11 11:55:26 streamer bluetoothd[746]: Starting SDP server May 11 11:55:26 streamer bluetoothd[746]: Excluding (cli) sap May 11 11:55:26 streamer sudo[706]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log May 11 11:55:26 streamer sudo[706]: pam_unix(sudo:session): session opened for user root by (uid=0) May 11 11:55:26 streamer dbus-daemon[570]: [system] Activating via systemd: service name='org.freedesktop.hostname1' unit='dbus-org.freedesktop.hostname1.service' requested by ':1.5' (uid=0 pid=746 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap ") May 11 11:55:26 streamer kernel: Bluetooth: BNEP (Ethernet Emulation) ver 1.3 May 11 11:55:26 streamer kernel: Bluetooth: BNEP filters: protocol multicast May 11 11:55:26 streamer kernel: Bluetooth: BNEP socket layer initialized May 11 11:55:26 streamer kernel: Bluetooth: MGMT ver 1.22 May 11 11:55:26 streamer bluetoothd[746]: Bluetooth management interface 1.22 initialized May 11 11:55:26 streamer sudo[706]: /bin/chown: cannot access '/var/log/mpd.log': No such file or directory May 11 11:55:26 streamer sudo[706]: pam_unix(sudo:session): session closed for user root May 11 11:55:26 streamer bluetoothd[746]: Failed to set privacy: Rejected (0x0b) May 11 11:55:26 streamer systemd[1]: Starting Hostname Service... May 11 11:55:26 streamer dbus-daemon[570]: [system] Successfully activated service 'org.freedesktop.hostname1' May 11 11:55:26 streamer systemd[1]: Started Hostname Service. May 11 11:55:27 streamer ntpd[760]: error resolving pool 0.debian.pool.ntp.org: System error (-11) May 11 11:55:27 streamer nmbd[713]: [2025/05/11 11:55:27.150348, 0] ../source3/nmbd/asyncdns.c:158(start_async_dns) May 11 11:55:27 streamer nmbd[713]: started asyncdns process 783 May 11 11:55:27 streamer nmbd[713]: [2025/05/11 11:55:27.151923, 0] ../lib/util/become_daemon.c:149(daemon_status) May 11 11:55:27 streamer nmbd[713]: daemon_status: STATUS=daemon 'nmbd' : No local IPv4 non-loopback interfaces available, waiting for interface ... May 11 11:55:27 streamer nmbd[713]: [2025/05/11 11:55:27.152028, 0] ../source3/nmbd/nmbd_subnetdb.c:254(create_subnets) May 11 11:55:27 streamer nmbd[713]: NOTE: NetBIOS name resolution is not supported for Internet Protocol Version 6 (IPv6). May 11 11:55:27 streamer wireless.js[604]: Cleaning previous... May 11 11:55:27 streamer sudo[791]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ip addr flush dev wlan0 May 11 11:55:27 streamer sudo[791]: pam_unix(sudo:session): session opened for user root by (uid=0) May 11 11:55:27 streamer sudo[791]: pam_unix(sudo:session): session closed for user root May 11 11:55:27 streamer sudo[793]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 down May 11 11:55:27 streamer sudo[793]: pam_unix(sudo:session): session opened for user root by (uid=0) May 11 11:55:28 streamer ntpd[760]: error resolving pool 1.debian.pool.ntp.org: System error (-11) May 11 11:55:28 streamer sudo[793]: pam_unix(sudo:session): session closed for user root May 11 11:55:28 streamer wireless.js[604]: Stopped aP May 11 11:55:28 streamer sudo[800]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 up May 11 11:55:28 streamer sudo[800]: pam_unix(sudo:session): session opened for user root by (uid=0) May 11 11:55:28 streamer kernel: brcmfmac: brcmf_cfg80211_set_power_mgmt: power save disabled May 11 11:55:28 streamer sudo[800]: pam_unix(sudo:session): session closed for user root May 11 11:55:28 streamer sudo[802]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iw reg get May 11 11:55:28 streamer sudo[802]: pam_unix(sudo:session): session opened for user root by (uid=0) May 11 11:55:28 streamer sudo[802]: pam_unix(sudo:session): session closed for user root May 11 11:55:28 streamer sudo[809]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 up May 11 11:55:28 streamer sudo[809]: pam_unix(sudo:session): session opened for user root by (uid=0) May 11 11:55:28 streamer sudo[809]: pam_unix(sudo:session): session closed for user root May 11 11:55:28 streamer sudo[811]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iw wlan0 scan May 11 11:55:28 streamer sudo[811]: pam_unix(sudo:session): session opened for user root by (uid=0) May 11 11:55:28 streamer mpd[780]: May 11 11:55 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg May 11 11:55:28 streamer systemd[1]: Started Music Player Daemon. May 11 11:55:28 streamer mpd_monitor.sh[613]: MPD restarted due to no mpc output. May 11 11:55:29 streamer ntpd[760]: error resolving pool 2.debian.pool.ntp.org: System error (-11) May 11 11:55:29 streamer systemd[1]: systemd-rfkill.service: Succeeded. May 11 11:55:30 streamer ntpd[760]: error resolving pool 3.debian.pool.ntp.org: System error (-11) May 11 11:55:30 streamer sudo[811]: pam_unix(sudo:session): session closed for user root May 11 11:55:30 streamer wireless.js[604]: SETTING APPROPRIATE REG DOMAIN: NL May 11 11:55:30 streamer sudo[819]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 up May 11 11:55:30 streamer sudo[819]: pam_unix(sudo:session): session opened for user root by (uid=0) May 11 11:55:30 streamer sudo[819]: pam_unix(sudo:session): session closed for user root May 11 11:55:30 streamer sudo[821]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iw reg set NL May 11 11:55:30 streamer sudo[821]: pam_unix(sudo:session): session opened for user root by (uid=0) May 11 11:55:30 streamer volumio-remote-updater[614]: [2025-05-11 11:55:30] [info] asio async_connect error: system:111 (Connection refused) May 11 11:55:30 streamer volumio-remote-updater[614]: [2025-05-11 11:55:30] [info] Error getting remote endpoint: system:107 (Transport endpoint is not connected) May 11 11:55:30 streamer volumio-remote-updater[614]: [2025-05-11 11:55:30] [error] handle_connect error: Underlying Transport Error May 11 11:55:30 streamer sudo[821]: pam_unix(sudo:session): session closed for user root May 11 11:55:30 streamer wireless.js[604]: SUCCESSFULLY SET NEW REGDOMAIN: NL May 11 11:55:30 streamer wireless.js[604]: Start wireless flow May 11 11:55:30 streamer wireless.js[604]: Stopped hotspot (if there).. May 11 11:55:30 streamer sudo[826]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ip addr flush dev wlan0 May 11 11:55:30 streamer sudo[826]: pam_unix(sudo:session): session opened for user root by (uid=0) May 11 11:55:30 streamer sudo[826]: pam_unix(sudo:session): session closed for user root May 11 11:55:30 streamer sudo[828]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 down May 11 11:55:30 streamer sudo[828]: pam_unix(sudo:session): session opened for user root by (uid=0) May 11 11:55:31 streamer bthelper[700]: Changing power off succeeded May 11 11:55:31 streamer volumio-time-update[618]: volumio-time-update-util: Fetching time from Volumio... May 11 11:55:31 streamer volumio-time-update[618]: volumio-time-update-util: Date not found in response May 11 11:55:31 streamer volumio-time-update[618]: volumio-time-update-util: Retrying in 5 seconds... May 11 11:55:31 streamer bthelper[700]: [CHG] Controller E4:5F:01:4D:AC:BD Class: 0x0000041c May 11 11:55:31 streamer bthelper[700]: Changing power on succeeded May 11 11:55:31 streamer sudo[828]: pam_unix(sudo:session): session closed for user root May 11 11:55:31 streamer wireless.js[604]: DHCP IP May 11 11:55:31 streamer wireless.js[604]: Start ap May 11 11:55:31 streamer wpa_supplicant[843]: Successfully initialized wpa_supplicant May 11 11:55:31 streamer sudo[844]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/dhcpcd May 11 11:55:31 streamer sudo[844]: pam_unix(sudo:session): session opened for user root by (uid=0) May 11 11:55:31 streamer kernel: brcmfmac: brcmf_cfg80211_set_power_mgmt: power save disabled May 11 11:55:31 streamer dhcpcd[845]: dev: loaded udev May 11 11:55:31 streamer dhcpcd-run-hooks[863]: wlan0: starting wpa_supplicant May 11 11:55:31 streamer dhcpcd-run-hooks[868]: wlan0: failed to start wpa_supplicant May 11 11:55:31 streamer dhcpcd-run-hooks[869]: 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 11 11:55:31 streamer dhcpcd[845]: wlan0: connected to Access Point `' May 11 11:55:31 streamer dhcpcd[845]: no interfaces have a carrier May 11 11:55:31 streamer dhcpcd[845]: forked to background, child pid 879 May 11 11:55:31 streamer dhcpcd[879]: eth0: waiting for carrier May 11 11:55:31 streamer dhcpcd[879]: wlan0: waiting for carrier May 11 11:55:31 streamer sudo[844]: pam_unix(sudo:session): session closed for user root May 11 11:55:32 streamer wireless.js[604]: trying... May 11 11:55:32 streamer sudo[881]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r May 11 11:55:32 streamer sudo[881]: pam_unix(sudo:session): session opened for user root by (uid=0) May 11 11:55:32 streamer sudo[881]: pam_unix(sudo:session): session closed for user root May 11 11:55:33 streamer wireless.js[604]: trying... May 11 11:55:33 streamer sudo[884]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r May 11 11:55:33 streamer sudo[884]: pam_unix(sudo:session): session opened for user root by (uid=0) May 11 11:55:33 streamer sudo[884]: pam_unix(sudo:session): session closed for user root May 11 11:55:34 streamer wireless.js[604]: trying... May 11 11:55:34 streamer sudo[887]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r May 11 11:55:34 streamer sudo[887]: pam_unix(sudo:session): session opened for user root by (uid=0) May 11 11:55:34 streamer sudo[887]: pam_unix(sudo:session): session closed for user root May 11 11:55:35 streamer wireless.js[604]: trying... May 11 11:55:35 streamer sudo[890]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r May 11 11:55:35 streamer sudo[890]: pam_unix(sudo:session): session opened for user root by (uid=0) May 11 11:55:35 streamer sudo[890]: pam_unix(sudo:session): session closed for user root May 11 11:55:36 streamer volumio-time-update[618]: volumio-time-update-util: Fetching time from Volumio... May 11 11:55:36 streamer volumio-time-update[618]: volumio-time-update-util: Date not found in response May 11 11:55:36 streamer volumio-time-update[618]: volumio-time-update-util: Retrying in 5 seconds... May 11 11:55:36 streamer wireless.js[604]: trying... May 11 11:55:36 streamer sudo[898]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r May 11 11:55:36 streamer sudo[898]: pam_unix(sudo:session): session opened for user root by (uid=0) May 11 11:55:36 streamer sudo[898]: pam_unix(sudo:session): session closed for user root May 11 11:55:37 streamer wireless.js[604]: trying... May 11 11:55:37 streamer sudo[901]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r May 11 11:55:37 streamer sudo[901]: pam_unix(sudo:session): session opened for user root by (uid=0) May 11 11:55:37 streamer sudo[901]: pam_unix(sudo:session): session closed for user root May 11 11:55:37 streamer wpa_supplicant[867]: wlan0: Trying to associate with SSID 'VillaTattaritar' May 11 11:55:37 streamer dhcpcd[879]: wlan0: carrier acquired May 11 11:55:37 streamer dhcpcd[879]: wlan0: connected to Access Point `VillaTattaritar' May 11 11:55:37 streamer wpa_supplicant[867]: wlan0: Associated with 78:8c:b5:5f:58:e3 May 11 11:55:37 streamer wpa_supplicant[867]: wlan0: CTRL-EVENT-CONNECTED - Connection to 78:8c:b5:5f:58:e3 completed [id=0 id_str=] May 11 11:55:37 streamer wpa_supplicant[867]: wlan0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0 May 11 11:55:37 streamer wpa_supplicant[867]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=COUNTRY_IE type=COUNTRY alpha2=DE May 11 11:55:37 streamer dhcpcd[879]: DUID 00:01:00:01:2e:f2:a3:88:e4:5f:01:4d:ac:bc May 11 11:55:37 streamer dhcpcd[879]: wlan0: IAID 01:4d:ac:bc May 11 11:55:37 streamer dhcpcd[879]: wlan0: adding address fe80::c5d4:f514:351:f52b May 11 11:55:37 streamer dhcpcd[879]: ipv6_addaddr1: Permission denied May 11 11:55:37 streamer dhcpcd[879]: wlan0: carrier lost May 11 11:55:37 streamer dhcpcd[879]: wlan0: carrier acquired May 11 11:55:37 streamer dhcpcd[879]: wlan0: IAID 01:4d:ac:bc May 11 11:55:38 streamer volumio-remote-updater[614]: [2025-05-11 11:55:38] [info] asio async_connect error: system:111 (Connection refused) May 11 11:55:38 streamer volumio-remote-updater[614]: [2025-05-11 11:55:38] [info] Error getting remote endpoint: system:107 (Transport endpoint is not connected) May 11 11:55:38 streamer volumio-remote-updater[614]: [2025-05-11 11:55:38] [error] handle_connect error: Underlying Transport Error May 11 11:55:38 streamer wireless.js[604]: trying... May 11 11:55:38 streamer sudo[917]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r May 11 11:55:38 streamer sudo[917]: pam_unix(sudo:session): session opened for user root by (uid=0) May 11 11:55:38 streamer sudo[917]: pam_unix(sudo:session): session closed for user root May 11 11:55:38 streamer dhcpcd[879]: wlan0: rebinding lease of 192.168.1.153 May 11 11:55:38 streamer dhcpcd[879]: wlan0: probing address 192.168.1.153/24 May 11 11:55:38 streamer dhcpcd[879]: wlan0: soliciting an IPv6 router May 11 11:55:39 streamer wireless.js[604]: trying... May 11 11:55:39 streamer sudo[923]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r May 11 11:55:39 streamer sudo[923]: pam_unix(sudo:session): session opened for user root by (uid=0) May 11 11:55:39 streamer sudo[923]: pam_unix(sudo:session): session closed for user root May 11 11:55:40 streamer wireless.js[604]: trying... May 11 11:55:40 streamer sudo[926]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r May 11 11:55:40 streamer sudo[926]: pam_unix(sudo:session): session opened for user root by (uid=0) May 11 11:55:40 streamer sudo[926]: pam_unix(sudo:session): session closed for user root May 11 11:55:41 streamer volumio-time-update[618]: volumio-time-update-util: Fetching time from Volumio... May 11 11:55:41 streamer volumio-time-update[618]: volumio-time-update-util: Date not found in response May 11 11:55:41 streamer volumio-time-update[618]: volumio-time-update-util: Retrying in 5 seconds... May 11 11:55:41 streamer wireless.js[604]: trying... May 11 11:55:41 streamer sudo[934]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r May 11 11:55:41 streamer sudo[934]: pam_unix(sudo:session): session opened for user root by (uid=0) May 11 11:55:41 streamer sudo[934]: pam_unix(sudo:session): session closed for user root May 11 11:55:42 streamer wireless.js[604]: trying... May 11 11:55:42 streamer sudo[937]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r May 11 11:55:42 streamer sudo[937]: pam_unix(sudo:session): session opened for user root by (uid=0) May 11 11:55:42 streamer sudo[937]: pam_unix(sudo:session): session closed for user root May 11 11:55:43 streamer wireless.js[604]: trying... May 11 11:55:43 streamer sudo[940]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r May 11 11:55:43 streamer sudo[940]: pam_unix(sudo:session): session opened for user root by (uid=0) May 11 11:55:43 streamer sudo[940]: pam_unix(sudo:session): session closed for user root May 11 11:55:43 streamer dhcpcd[879]: wlan0: leased 192.168.1.153 for 43200 seconds May 11 11:55:43 streamer avahi-daemon[620]: Joining mDNS multicast group on interface wlan0.IPv4 with address 192.168.1.153. May 11 11:55:43 streamer avahi-daemon[620]: New relevant interface wlan0.IPv4 for mDNS. May 11 11:55:43 streamer dhcpcd[879]: wlan0: adding route to 192.168.1.0/24 May 11 11:55:43 streamer avahi-daemon[620]: Registering new address record for 192.168.1.153 on wlan0.IPv4. May 11 11:55:43 streamer dhcpcd[879]: wlan0: adding default route via 192.168.1.1 May 11 11:55:44 streamer wireless.js[604]: trying... May 11 11:55:44 streamer sudo[964]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r May 11 11:55:44 streamer sudo[964]: pam_unix(sudo:session): session opened for user root by (uid=0) May 11 11:55:44 streamer sudo[964]: pam_unix(sudo:session): session closed for user root May 11 11:55:44 streamer wireless.js[604]: Connected to: ----VillaTattaritar May 11 11:55:44 streamer wireless.js[604]: ---- May 11 11:55:44 streamer sudo[967]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 May 11 11:55:44 streamer sudo[967]: pam_unix(sudo:session): session opened for user root by (uid=0) May 11 11:55:44 streamer sudo[967]: pam_unix(sudo:session): session closed for user root May 11 11:55:44 streamer wireless.js[604]: ... joined AP, wlan0 IPv4 is 192.168.1.153, ipV6 is undefined May 11 11:55:44 streamer wireless.js[604]: It's done! AP May 11 11:55:44 streamer kernel: brcmfmac: brcmf_cfg80211_set_power_mgmt: power save disabled May 11 11:55:44 streamer systemd[1]: Started Wireless Services. May 11 11:55:44 streamer systemd[1]: Started Volumio Backend Module. May 11 11:55:44 streamer systemd[1]: Started Volumio Cpu Tweaker. May 11 11:55:44 streamer volumio-cpu-tweak[973]: Setting RT Priority for mpd May 11 11:55:44 streamer volumio-cpu-tweak[973]: Setting MPD Affinity May 11 11:55:44 streamer volumio-cpu-tweak[973]: pid 780's current affinity mask: f May 11 11:55:44 streamer volumio-cpu-tweak[973]: pid 780's new affinity mask: 3 May 11 11:55:44 streamer volumio-cpu-tweak[973]: /bin/volumio_cpu_tweak: line 27: warning: command substitution: ignored null byte in input May 11 11:55:44 streamer volumio-cpu-tweak[973]: VOLUMIO CPU TWEAK: Setting CPU Governor: performance May 11 11:55:44 streamer systemd[1]: volumio_cpu_tweak.service: Succeeded. May 11 11:55:45 streamer ntpd[760]: Listen normally on 3 wlan0 192.168.1.153:123 May 11 11:55:45 streamer ntpd[760]: new interface(s) found: waking up resolver May 11 11:55:46 streamer volumio-time-update[618]: volumio-time-update-util: Fetching time from Volumio... May 11 11:55:46 streamer volumio-time-update[618]: volumio-time-update-util: Setting system time to: 2025-05-11 11:56:17 May 11 11:55:46 streamer sudo[1002]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/bin/timedatectl set-time 2025-05-11 11:56:17 May 11 11:55:46 streamer sudo[1002]: pam_unix(sudo:session): session opened for user root by (uid=0) May 11 11:55:46 streamer volumio[972]: info: ------------------------------------------- May 11 11:55:46 streamer dbus-daemon[570]: [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service' requested by ':1.9' (uid=0 pid=1003 comm="timedatectl set-time 2025-05-11 11:56:17 ") May 11 11:55:46 streamer volumio[972]: info: ----- Volumio3 ---- May 11 11:55:46 streamer volumio[972]: info: ------------------------------------------- May 11 11:55:46 streamer volumio[972]: info: ----- System startup ---- May 11 11:55:46 streamer volumio[972]: info: ------------------------------------------- May 11 11:55:46 streamer systemd[1]: Starting Time & Date Service... May 11 11:55:46 streamer dbus-daemon[570]: [system] Successfully activated service 'org.freedesktop.timedate1' May 11 11:55:46 streamer systemd[1]: Started Time & Date Service. May 11 11:56:17 streamer systemd-timedated[1004]: Changed local time to Sun May 11 11:56:17 2025 May 11 11:56:17 streamer sudo[1002]: pam_unix(sudo:session): session closed for user root May 11 11:56:17 streamer volumio-time-update[618]: volumio-time-update-util: System time updated successfully. May 11 11:56:17 streamer systemd[1]: Started Volumio Time Update Utility. May 11 11:56:17 streamer volumio[972]: info: MYVOLUMIO Environment detected May 11 11:56:17 streamer volumio[972]: info: Plugin folders cleanup May 11 11:56:17 streamer volumio[972]: info: Scanning into folder /volumio/app/plugins/ May 11 11:56:17 streamer volumio[972]: info: Scanning category audio_interface May 11 11:56:17 streamer volumio[972]: info: Scanning category miscellanea May 11 11:56:17 streamer volumio[972]: info: Scanning category music_service May 11 11:56:17 streamer volumio[972]: info: Scanning category plugins.json May 11 11:56:17 streamer volumio[972]: info: Scanning category system_controller May 11 11:56:17 streamer volumio[972]: info: Scanning category user_interface May 11 11:56:17 streamer volumio[972]: info: Scanning into folder /data/plugins/ May 11 11:56:17 streamer volumio[972]: info: Scanning category audio_interface May 11 11:56:17 streamer volumio[972]: info: Scanning category music_service May 11 11:56:17 streamer volumio[972]: info: Plugin folders cleanup completed May 11 11:56:17 streamer volumio[972]: info: ------------------------------------------- May 11 11:56:17 streamer volumio[972]: info: ----- Core plugins startup ---- May 11 11:56:17 streamer volumio[972]: info: ------------------------------------------- May 11 11:56:17 streamer volumio[972]: info: Loading plugins from folder /volumio/app/plugins/ May 11 11:56:17 streamer volumio[972]: info: Adding plugin upnp to MyMusic Plugins May 11 11:56:17 streamer volumio[972]: info: Adding plugin airplay_emulation to MyMusic Plugins May 11 11:56:17 streamer volumio[972]: info: Adding plugin upnp_browser to MyMusic Plugins May 11 11:56:17 streamer volumio[972]: info: Loading plugins from folder /data/plugins/ May 11 11:56:17 streamer volumio[972]: info: Loading plugin "system"... May 11 11:56:17 streamer volumio[972]: info: Loading plugin "appearance"... May 11 11:56:17 streamer nmbd[713]: [2025/05/11 11:56:17.686303, 0] ../lib/util/become_daemon.c:138(daemon_ready) May 11 11:56:17 streamer nmbd[713]: daemon_ready: STATUS=daemon 'nmbd' finished starting up and ready to serve connections May 11 11:56:17 streamer systemd[1]: Started Samba NMB Daemon. May 11 11:56:17 streamer systemd[1]: Starting Samba Winbind Daemon... May 11 11:56:17 streamer winbindd[1010]: [2025/05/11 11:56:17.936526, 0] ../source3/winbindd/winbindd_cache.c:3160(initialize_winbindd_cache) May 11 11:56:17 streamer winbindd[1010]: initialize_winbindd_cache: clearing cache and re-creating with version number 2 May 11 11:56:18 streamer winbindd[1010]: [2025/05/11 11:56:18.015583, 0] ../lib/util/become_daemon.c:138(daemon_ready) May 11 11:56:18 streamer systemd[1]: Started Samba Winbind Daemon. May 11 11:56:18 streamer winbindd[1010]: daemon_ready: STATUS=daemon 'winbindd' finished starting up and ready to serve connections May 11 11:56:18 streamer systemd[1]: Starting Samba SMB Daemon... May 11 11:56:18 streamer smbd[1015]: [2025/05/11 11:56:18.513415, 0] ../lib/util/become_daemon.c:138(daemon_ready) May 11 11:56:18 streamer systemd[1]: Started Samba SMB Daemon. May 11 11:56:18 streamer smbd[1015]: daemon_ready: STATUS=daemon 'smbd' finished starting up and ready to serve connections May 11 11:56:18 streamer systemd[1]: Reached target Multi-User System. May 11 11:56:18 streamer systemd[1]: Reached target Graphical Interface. May 11 11:56:18 streamer systemd[1]: Starting Update UTMP about System Runlevel Changes... May 11 11:56:18 streamer systemd[1]: systemd-update-utmp-runlevel.service: Succeeded. May 11 11:56:18 streamer systemd[1]: Started Update UTMP about System Runlevel Changes. May 11 11:56:18 streamer systemd[1]: Startup finished in 11.907s (kernel) + 25.972s (userspace) = 37.879s. May 11 11:56:18 streamer volumio[972]: info: Loading plugin "network"... May 11 11:56:18 streamer volumio[972]: info: Refreshing Cached IP Addresses May 11 11:56:18 streamer sudo[1025]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 May 11 11:56:18 streamer sudo[1025]: pam_unix(sudo:session): session opened for user root by (uid=0) May 11 11:56:18 streamer sudo[1025]: pam_unix(sudo:session): session closed for user root May 11 11:56:18 streamer sudo[1027]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 May 11 11:56:18 streamer sudo[1027]: pam_unix(sudo:session): session opened for user root by (uid=0) May 11 11:56:18 streamer sudo[1027]: pam_unix(sudo:session): session closed for user root May 11 11:56:18 streamer volumio[972]: info: Loading plugin "services"... May 11 11:56:18 streamer volumio[972]: info: Loading plugin "alsa_controller"... May 11 11:56:18 streamer sudo[1036]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan May 11 11:56:18 streamer sudo[1036]: pam_unix(sudo:session): session opened for user root by (uid=0) May 11 11:56:18 streamer volumio[972]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 11 11:56:18 streamer volumio[972]: info: Loading plugin "wizard"... May 11 11:56:18 streamer volumio[972]: info: Loading plugin "networkfs"... May 11 11:56:18 streamer volumio-remote-updater[614]: [2025-05-11 11:56:18] [connect] Successful connection May 11 11:56:18 streamer volumio[972]: info: Starting Udev Watcher for removable devices May 11 11:56:18 streamer sudo[1051]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=jonttu,password=HVSdWH4DSzkEKRBiK6RSL,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //diskstation.local/media/music /mnt/NAS/Diskstation May 11 11:56:18 streamer sudo[1051]: pam_unix(sudo:session): session opened for user root by (uid=0) May 11 11:56:18 streamer volumio[972]: info: Ignoring mount for partition: boot May 11 11:56:18 streamer volumio[972]: info: Ignoring mount for partition: volumio May 11 11:56:18 streamer volumio[972]: info: Ignoring mount for partition: volumio_data May 11 11:56:18 streamer volumio[972]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback May 11 11:56:18 streamer volumio[972]: info: Loading plugin "volumio_command_line_client"... May 11 11:56:18 streamer volumio[972]: info: Loading plugin "upnp"... May 11 11:56:18 streamer volumio[972]: info: [1746953778977] Starting Upmpd Daemon May 11 11:56:18 streamer volumio[972]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback May 11 11:56:18 streamer volumio[972]: info: Loading plugin "my_music"... May 11 11:56:18 streamer volumio[972]: info: Loading plugin "mpd"... May 11 11:56:19 streamer kernel: Key type cifs.spnego registered May 11 11:56:19 streamer kernel: Key type cifs.idmap registered May 11 11:56:19 streamer 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 11 11:56:19 streamer kernel: CIFS: Attempting to mount //diskstation.local/media/music May 11 11:56:19 streamer kernel: cryptd: max_cpu_qlen set to 1000 May 11 11:56:19 streamer volumio[972]: info: Loading plugin "upnp_browser"... May 11 11:56:19 streamer volumio[972]: info: Loading plugin "alarm-clock"... May 11 11:56:19 streamer volumio[972]: info: Loading plugin "airplay_emulation"... May 11 11:56:19 streamer volumio[972]: info: Starting Shairport Sync May 11 11:56:19 streamer volumio[972]: info: Loading plugin "last_100"... May 11 11:56:19 streamer volumio[972]: info: Loading plugin "webradio"... May 11 11:56:19 streamer volumio[972]: info: Loading plugin "i2s_dacs"... May 11 11:56:19 streamer volumio[972]: info: Loading plugin "volumiodiscovery"... May 11 11:56:19 streamer volumio[972]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. May 11 11:56:19 streamer volumio[972]: *** WARNING *** Please fix your application to use the native API of Avahi! May 11 11:56:19 streamer node[972]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. May 11 11:56:19 streamer volumio[972]: *** WARNING *** For more information see May 11 11:56:19 streamer volumio[972]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. May 11 11:56:19 streamer volumio[972]: *** WARNING *** Please fix your application to use the native API of Avahi! May 11 11:56:19 streamer volumio[972]: *** WARNING *** For more information see May 11 11:56:19 streamer node[972]: *** WARNING *** Please fix your application to use the native API of Avahi! May 11 11:56:19 streamer node[972]: *** WARNING *** For more information see May 11 11:56:19 streamer node[972]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. May 11 11:56:19 streamer node[972]: *** WARNING *** Please fix your application to use the native API of Avahi! May 11 11:56:19 streamer node[972]: *** WARNING *** For more information see May 11 11:56:19 streamer volumio[972]: info: Applying required configuration parameters for plugin volumiodiscovery May 11 11:56:19 streamer volumio[972]: info: Discovery: Started advertising with name: Streamer May 11 11:56:19 streamer volumio[972]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback May 11 11:56:19 streamer volumio[972]: info: Loading plugin "soundcloud"... May 11 11:56:20 streamer sudo[1051]: pam_unix(sudo:session): session closed for user root May 11 11:56:20 streamer volumio[972]: info: Loading plugin "spop"... May 11 11:56:21 streamer volumio[972]: info: Loading plugin "ytcr"... May 11 11:56:22 streamer sudo[1036]: pam_unix(sudo:session): session closed for user root May 11 11:56:24 streamer volumio[972]: info: Loading plugin "outputs"... May 11 11:56:24 streamer volumio[972]: info: Loading plugin "albumart"... May 11 11:56:24 streamer volumio[972]: info: Plugin example_plugin is not enabled May 11 11:56:24 streamer volumio[972]: info: Loading plugin "inputs"... May 11 11:56:24 streamer volumio[972]: info: Loading plugin "updater_comm"... May 11 11:56:25 streamer volumio[972]: info: Plugin mpdemulation is not enabled May 11 11:56:25 streamer volumio[972]: info: Loading plugin "rest_api"... May 11 11:56:25 streamer volumio[972]: info: Loading plugin "websocket"... May 11 11:56:25 streamer volumio[972]: info: Starting Socket.io Server version 2.3.0 May 11 11:56:25 streamer volumio[972]: info: Loading plugin "fusiondsp"... May 11 11:56:25 streamer volumio[972]: Forking 3 albumart workers May 11 11:56:25 streamer systemd[1]: systemd-fsckd.service: Succeeded. May 11 11:56:25 streamer volumio[972]: info: Applying required configuration parameters for plugin fusiondsp May 11 11:56:25 streamer volumio[972]: info: Loading plugin "radio_paradise"... May 11 11:56:25 streamer sh[496]: timed out May 11 11:56:25 streamer dhcpcd[545]: timed out May 11 11:56:25 streamer sh[496]: dhcpcd exited May 11 11:56:25 streamer dhcpcd[545]: dhcpcd exited May 11 11:56:25 streamer sh[496]: ifup: failed to bring up eth0 May 11 11:56:25 streamer systemd[1]: ifup@eth0.service: Main process exited, code=exited, status=1/FAILURE May 11 11:56:25 streamer systemd[1]: ifup@eth0.service: Failed with result 'exit-code'. May 11 11:56:25 streamer volumio[972]: Starting albumart workers May 11 11:56:25 streamer volumio[972]: Starting albumart workers May 11 11:56:25 streamer volumio[972]: Starting albumart workers May 11 11:56:25 streamer volumio[972]: info: Applying required configuration parameters for plugin radio_paradise May 11 11:56:25 streamer volumio[972]: info: [1746953785910] [RadioParadise] API delay: 5 May 11 11:56:25 streamer volumio[972]: info: Loading i18n strings for locale en May 11 11:56:25 streamer volumio[972]: Updating browse sources language May 11 11:56:25 streamer volumio[972]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 11 11:56:26 streamer volumio[972]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 11 11:56:26 streamer volumio[972]: info: CoreCommandRouter::initPlayerControls May 11 11:56:26 streamer volumio[972]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 11:56:26 streamer volumio[972]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 11:56:26 streamer volumio[972]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 11:56:26 streamer volumio[972]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 11:56:26 streamer volumio[972]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 11:56:26 streamer volumio[972]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 11:56:26 streamer volumio[972]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 11:56:26 streamer volumio[972]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 11:56:26 streamer volumio[972]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 11 11:56:26 streamer volumio[972]: Express server listening on port 3000 May 11 11:56:26 streamer volumio[972]: [Metrics] WebUI: 9s 992.54ms May 11 11:56:26 streamer volumio[972]: info: CoreStateMachine::resetVolumioState May 11 11:56:26 streamer volumio[972]: info: CoreStateMachine::getcurrentVolume May 11 11:56:26 streamer volumio[972]: info: CoreCommandRouter::volumioRetrievevolume May 11 11:56:26 streamer volumio[972]: info: CoreStateMachine::pushState May 11 11:56:26 streamer volumio[972]: info: CorePlayQueue::getTrack 0 May 11 11:56:26 streamer volumio[972]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 11 11:56:26 streamer volumio[972]: info: CoreCommandRouter::volumioPushState May 11 11:56:26 streamer volumio[972]: info: Volumio Network Manager: Network status updated: 2 May 11 11:56:26 streamer volumio[972]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 11 11:56:26 streamer volumio[972]: info: Reloading queue from file May 11 11:56:26 streamer volumio[972]: info: CoreStateMachine::setRepeat null single undefined May 11 11:56:26 streamer volumio[972]: info: CoreStateMachine::pushState May 11 11:56:26 streamer volumio[972]: info: CorePlayQueue::getTrack 0 May 11 11:56:26 streamer volumio[972]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 11 11:56:26 streamer volumio[972]: info: CoreCommandRouter::volumioPushState May 11 11:56:26 streamer volumio[972]: info: CoreStateMachine::setRandom null May 11 11:56:26 streamer volumio[972]: info: CoreStateMachine::pushState May 11 11:56:26 streamer volumio[972]: info: CorePlayQueue::getTrack 0 May 11 11:56:26 streamer volumio[972]: info: CoreCommandRouter::volumioPushState May 11 11:56:26 streamer volumio[972]: info: Setting Device type: Raspberry PI May 11 11:56:26 streamer volumio[972]: info: Completed loading Core Plugins May 11 11:56:26 streamer volumio[972]: info: Preparing to generate the ALSA configuration file May 11 11:56:26 streamer volumio[972]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb May 11 11:56:26 streamer volumio[972]: info: USB Boot Capable - System SBC Revision found in cpuinfo: b03114 May 11 11:56:26 streamer volumio[972]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI May 11 11:56:26 streamer volumio[972]: info: The plugin fusiondsp has an ALSA contribution file volumioDsp.postDsp.10.conf May 11 11:56:26 streamer volumio[972]: info: Reading ALSA contributions from plugins. May 11 11:56:26 streamer volumio[972]: info: Asound.conf file unchanged, so no further update is needed May 11 11:56:26 streamer volumio[972]: info: Output device has changed, restarting MPD May 11 11:56:26 streamer sudo[1157]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf May 11 11:56:26 streamer sudo[1157]: pam_unix(sudo:session): session opened for user root by (uid=0) May 11 11:56:26 streamer volumio[972]: info: Output device has changed, restarting Shairport Sync May 11 11:56:26 streamer volumio[972]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 11:56:26 streamer volumio[972]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 11 11:56:26 streamer sudo[1157]: pam_unix(sudo:session): session closed for user root May 11 11:56:26 streamer sudo[1160]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service May 11 11:56:26 streamer sudo[1160]: pam_unix(sudo:session): session opened for user root by (uid=0) May 11 11:56:26 streamer systemd[1]: Stopping Music Player Daemon... May 11 11:56:26 streamer volumio[972]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 May 11 11:56:26 streamer volumio[972]: info: ___________ START PLUGINS ___________ May 11 11:56:26 streamer volumio[972]: info: ControllerMpd::onStart: Initializing MPD May 11 11:56:26 streamer volumio[972]: info: Creating MPD Configuration file May 11 11:56:26 streamer sudo[1166]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf May 11 11:56:26 streamer sudo[1166]: pam_unix(sudo:session): session opened for user root by (uid=0) May 11 11:56:26 streamer sudo[1166]: pam_unix(sudo:session): session closed for user root May 11 11:56:26 streamer volumio[972]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 11 11:56:26 streamer volumio[972]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 11 11:56:26 streamer volumio[972]: info: [1746953786530] CoreMusicLibrary::Adding element Media Servers May 11 11:56:26 streamer volumio[972]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 11 11:56:26 streamer sudo[1169]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service May 11 11:56:26 streamer sudo[1169]: pam_unix(sudo:session): session opened for user root by (uid=0) May 11 11:56:26 streamer volumio[972]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 11:56:26 streamer volumio[972]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 11 11:56:26 streamer systemd[1]: mpd.service: Succeeded. May 11 11:56:26 streamer systemd[1]: Stopped Music Player Daemon. May 11 11:56:26 streamer volumio[972]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 May 11 11:56:26 streamer volumio[972]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 11:56:26 streamer volumio[972]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 11 11:56:26 streamer volumio[972]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 May 11 11:56:26 streamer volumio[972]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 11 11:56:26 streamer volumio[972]: info: [1746953786627] CoreMusicLibrary::Adding element Last_100 May 11 11:56:26 streamer volumio[972]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 11 11:56:26 streamer volumio[972]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 11 11:56:26 streamer volumio[972]: info: [1746953786629] CoreMusicLibrary::Adding element Webradio May 11 11:56:26 streamer systemd[1]: Starting Music Player Daemon... May 11 11:56:26 streamer volumio[972]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 11 11:56:26 streamer volumio[972]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 11 11:56:26 streamer volumio[972]: info: Initializing BBC Radios May 11 11:56:26 streamer volumio[972]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 11 11:56:26 streamer volumio[972]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 11 11:56:26 streamer sudo[1174]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log May 11 11:56:26 streamer sudo[1174]: pam_unix(sudo:session): session opened for user root by (uid=0) May 11 11:56:26 streamer volumio[972]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 11 11:56:26 streamer volumio[972]: info: [1746953786700] CoreMusicLibrary::Adding element SoundCloud May 11 11:56:26 streamer volumio[972]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 11 11:56:26 streamer sudo[1174]: pam_unix(sudo:session): session closed for user root May 11 11:56:26 streamer volumio[972]: Cannot find translation for source SoundCloud May 11 11:56:26 streamer volumio[972]: info: Creating Spotify config file May 11 11:56:26 streamer volumio[972]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 11:56:26 streamer volumio[972]: info: Loading i18n strings for locale en May 11 11:56:26 streamer volumio[972]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , updateALSAConfigFile May 11 11:56:26 streamer volumio[972]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 11:56:26 streamer volumio[972]: info: FusionDsp - mixtype--------------------- None May 11 11:56:26 streamer volumio[972]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 11 11:56:26 streamer volumio[972]: info: [1746953786825] CoreMusicLibrary::Adding element Radio Paradise May 11 11:56:26 streamer volumio[972]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 11 11:56:26 streamer volumio[972]: Cannot find translation for source SoundCloud May 11 11:56:26 streamer volumio[972]: Cannot find translation for source Radio Paradise May 11 11:56:26 streamer volumio[972]: info: Volumio Calling Home May 11 11:56:26 streamer volumio[972]: info: Preparing to generate the ALSA configuration file May 11 11:56:26 streamer volumio[972]: info: Discovery: adding 8eebf7db-761d-4600-aee5-6cdada14d4a0 May 11 11:56:26 streamer volumio[972]: info: Discovery: Found device Streamer May 11 11:56:26 streamer volumio[972]: info: CoreCommandRouter::volumioGetState May 11 11:56:26 streamer volumio[972]: info: CorePlayQueue::getTrack 0 May 11 11:56:26 streamer volumio[972]: info: The plugin fusiondsp has an ALSA contribution file volumioDsp.postDsp.10.conf May 11 11:56:26 streamer volumio[972]: info: Reading ALSA contributions from plugins. May 11 11:56:26 streamer volumio[972]: info: MPD Permissions set May 11 11:56:26 streamer volumio[972]: info: MPD Permissions set May 11 11:56:27 streamer volumio[972]: info: Volumio called home May 11 11:56:27 streamer volumio[972]: info: Spotify config file written May 11 11:56:27 streamer sudo[1194]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service May 11 11:56:27 streamer sudo[1194]: pam_unix(sudo:session): session opened for user root by (uid=0) May 11 11:56:27 streamer volumio[972]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 1 May 11 11:56:27 streamer volumio[972]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 11:56:27 streamer volumio[972]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 11:56:27 streamer volumio[972]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 11:56:27 streamer volumio[972]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 11:56:27 streamer volumio[972]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 11:56:27 streamer volumio[972]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 11:56:27 streamer volumio[972]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 11:56:27 streamer volumio[972]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 11:56:27 streamer volumio[972]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 11 11:56:27 streamer volumio[972]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 11:56:27 streamer volumio[972]: info: No need to fix Spotify hosts May 11 11:56:27 streamer volumio[972]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 11:56:27 streamer volumio[972]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 11:56:27 streamer volumio[972]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 11:56:27 streamer volumio[972]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 11:56:27 streamer volumio[972]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 11:56:27 streamer volumio[972]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 11:56:27 streamer volumio[972]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 11:56:27 streamer volumio[972]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 11:56:27 streamer volumio[972]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 11 11:56:27 streamer volumio[972]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 11:56:27 streamer systemd[1]: Started go-librespot Daemon. May 11 11:56:27 streamer sudo[1194]: pam_unix(sudo:session): session closed for user root May 11 11:56:27 streamer go-librespot[1197]: go-librespot daemon starting... May 11 11:56:27 streamer volumio[972]: info: Starting Shairport Sync May 11 11:56:27 streamer volumio[972]: info: Starting Shairport Sync May 11 11:56:27 streamer sudo[1212]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync May 11 11:56:27 streamer sudo[1212]: pam_unix(sudo:session): session opened for user root by (uid=0) May 11 11:56:27 streamer volumio[972]: info: Starting Shairport Sync May 11 11:56:27 streamer sudo[1215]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync May 11 11:56:27 streamer sudo[1215]: pam_unix(sudo:session): session opened for user root by (uid=0) May 11 11:56:27 streamer systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... May 11 11:56:27 streamer volumio[972]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ May 11 11:56:27 streamer volumio[972]: SPOTIFY: BQCrJRjlXWyH9grcFtBan9iriomgre1y9xakUc3R8bj-VL0Qg8_g1DfDxzY84pR8iob8IqdXPbXTthjnwe89A-2YD6DiGM_jOhQfPHxONZKfgvZKjV_3mQlwXoLiiLCrdbQDVuRkyg0AjFdszYRzW-cQeVv5M9e53V3oiwJ9W5auQ8j0An0cn7FppUKqwhWYBcPBVKBqPE1NgF77--JqmiGGm2kXOQVfB21UYu3Uh7HUamM02u_9pZKUUErojWcUCzGZDMU2uRTfjnyB6qjoqSV1oA May 11 11:56:27 streamer volumio[972]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ May 11 11:56:27 streamer volumio[972]: info: New Spotify access token = BQCrJRjlXWyH9grcFtBan9iriomgre1y9xakUc3R8bj-VL0Qg8_g1DfDxzY84pR8iob8IqdXPbXTthjnwe89A-2YD6DiGM_jOhQfPHxONZKfgvZKjV_3mQlwXoLiiLCrdbQDVuRkyg0AjFdszYRzW-cQeVv5M9e53V3oiwJ9W5auQ8j0An0cn7FppUKqwhWYBcPBVKBqPE1NgF77--JqmiGGm2kXOQVfB21UYu3Uh7HUamM02u_9pZKUUErojWcUCzGZDMU2uRTfjnyB6qjoqSV1oA May 11 11:56:27 streamer volumio[972]: info: Spotify credentials grant success - running version from March 24, 2019 May 11 11:56:27 streamer systemd[1]: shairport-sync.service: Succeeded. May 11 11:56:27 streamer sudo[1218]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync May 11 11:56:27 streamer sudo[1218]: pam_unix(sudo:session): session opened for user root by (uid=0) May 11 11:56:27 streamer systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. May 11 11:56:27 streamer volumio[972]: info: CoreCommandRouter::volumioGetState May 11 11:56:27 streamer volumio[972]: info: CorePlayQueue::getTrack 0 May 11 11:56:27 streamer systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. May 11 11:56:27 streamer go-librespot[1197]: time="2025-05-11T11:56:27+03:00" level=info msg="running go-librespot 0.2.0" May 11 11:56:27 streamer go-librespot[1197]: time="2025-05-11T11:56:27+03:00" level=debug msg="app state loaded" May 11 11:56:27 streamer volumio[972]: info: Asound.conf file unchanged, so no further update is needed May 11 11:56:27 streamer volumio[972]: info: Output device has changed, restarting MPD May 11 11:56:27 streamer go-librespot[1197]: time="2025-05-11T11:56:27+03:00" level=info msg="api server listening on 127.0.0.1:9879" May 11 11:56:27 streamer sudo[1215]: pam_unix(sudo:session): session closed for user root May 11 11:56:27 streamer systemd[1]: systemd-hostnamed.service: Succeeded. May 11 11:56:27 streamer sudo[1212]: pam_unix(sudo:session): session closed for user root May 11 11:56:27 streamer sudo[1224]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf May 11 11:56:27 streamer sudo[1224]: pam_unix(sudo:session): session opened for user root by (uid=0) May 11 11:56:27 streamer volumio[972]: info: Output device has changed, restarting Shairport Sync May 11 11:56:27 streamer volumio[972]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 11:56:27 streamer volumio[972]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 11 11:56:27 streamer mpd[1189]: May 11 11:56 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg May 11 11:56:27 streamer systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... May 11 11:56:27 streamer sudo[1224]: pam_unix(sudo:session): session closed for user root May 11 11:56:27 streamer systemd[1]: shairport-sync.service: Succeeded. May 11 11:56:27 streamer systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. May 11 11:56:27 streamer sudo[1228]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service May 11 11:56:27 streamer volumio[972]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 May 11 11:56:27 streamer sudo[1228]: pam_unix(sudo:session): session opened for user root by (uid=0) May 11 11:56:27 streamer systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. May 11 11:56:27 streamer sudo[1218]: pam_unix(sudo:session): session closed for user root May 11 11:56:27 streamer systemd[1]: mpd.service: Main process exited, code=killed, status=15/TERM May 11 11:56:27 streamer systemd[1]: mpd.service: Succeeded. May 11 11:56:27 streamer systemd[1]: Stopped Music Player Daemon. May 11 11:56:27 streamer systemd[1]: Starting Music Player Daemon... May 11 11:56:27 streamer volumio[972]: info: MPD Permissions set May 11 11:56:27 streamer volumio[972]: info: Shairport-Sync Started May 11 11:56:27 streamer volumio[972]: Error adding Membership: Error: addMembership EINVAL May 11 11:56:27 streamer volumio[972]: info: Shairport-Sync Started May 11 11:56:27 streamer volumio[972]: info: Shairport-Sync Started May 11 11:56:27 streamer volumio[972]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 11:56:27 streamer volumio[972]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 11:56:27 streamer sudo[1235]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log May 11 11:56:27 streamer sudo[1235]: pam_unix(sudo:session): session opened for user root by (uid=0) May 11 11:56:27 streamer volumio[972]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 11:56:27 streamer volumio[972]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 11:56:27 streamer sudo[1235]: pam_unix(sudo:session): session closed for user root May 11 11:56:27 streamer volumio[972]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 11 11:56:27 streamer volumio[972]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 11:56:27 streamer volumio[972]: info: Starting Shairport Sync May 11 11:56:27 streamer sudo[1247]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync May 11 11:56:27 streamer sudo[1247]: pam_unix(sudo:session): session opened for user root by (uid=0) May 11 11:56:27 streamer volumio[972]: SPOTIFY: User informations: {"country":"FI","display_name":"aprilnine","email":"jonttuleskinen@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/aprilnine"},"followers":{"href":null,"total":18},"href":"https://api.spotify.com/v1/users/aprilnine","id":"aprilnine","images":[{"height":300,"url":"https://i.scdn.co/image/ab6775700000ee85b0c21597facdc19900fc60f8","width":300},{"height":64,"url":"https://i.scdn.co/image/ab67757000003b82b0c21597facdc19900fc60f8","width":64}],"product":"premium","type":"user","uri":"spotify:user:aprilnine"} May 11 11:56:27 streamer volumio[972]: info: Spotify Successfully logged in May 11 11:56:27 streamer volumio[972]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 11 11:56:27 streamer volumio[972]: info: [1746953787777] CoreMusicLibrary::Adding element Spotify May 11 11:56:27 streamer volumio[972]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 11 11:56:27 streamer volumio[972]: Cannot find translation for source SoundCloud May 11 11:56:27 streamer volumio[972]: Cannot find translation for source Radio Paradise May 11 11:56:27 streamer volumio[972]: Cannot find translation for source Spotify May 11 11:56:27 streamer go-librespot[1197]: time="2025-05-11T11:56:27+03:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" May 11 11:56:27 streamer go-librespot[1197]: time="2025-05-11T11:56:27+03:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" May 11 11:56:27 streamer go-librespot[1197]: time="2025-05-11T11:56:27+03:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" May 11 11:56:27 streamer go-librespot[1197]: time="2025-05-11T11:56:27+03:00" level=info msg="zeroconf server listening on port 45763" May 11 11:56:27 streamer systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... May 11 11:56:27 streamer systemd[1]: shairport-sync.service: Succeeded. May 11 11:56:27 streamer systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. May 11 11:56:27 streamer systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. May 11 11:56:27 streamer sudo[1247]: pam_unix(sudo:session): session closed for user root May 11 11:56:27 streamer volumio[972]: info: Shairport-Sync Started May 11 11:56:27 streamer go-librespot[1197]: time="2025-05-11T11:56:27+03:00" level=debug msg="obtained new client token: AABPs8O0H6WD8ZMPnd5Lyk4C5TcQdPG8orfzQ8gHOeQ9cHWM868wRHfyxpIuAPNCxPqTLvvMkBaFcFuqVEHjfzb+ggNdDLLxlZKocroSca08u+p/neZReqTUcZyCNFwfqc644Wig0rH9rDNTCkGc9GTTXCYpl1pVJZ4kDPVt3mJDTrsOqvCP7m6BbghBBpjjtNq0oKLDu0JxoNEC6SEzZlMpbyyrlP/DoU12VT69O6YWQf9tWdJSUTMZdv0=" May 11 11:56:27 streamer go-librespot[1197]: time="2025-05-11T11:56:27+03:00" level=debug msg="connected to ap-gew4.spotify.com:4070" May 11 11:56:27 streamer go-librespot[1197]: time="2025-05-11T11:56:27+03:00" level=debug msg="completed keyexchange" May 11 11:56:27 streamer go-librespot[1197]: time="2025-05-11T11:56:27+03:00" level=debug msg="completed challenge" May 11 11:56:27 streamer go-librespot[1197]: time="2025-05-11T11:56:27+03:00" level=info msg="authenticated AP as aprilnine" May 11 11:56:28 streamer go-librespot[1197]: time="2025-05-11T11:56:28+03:00" level=info msg="authenticated Login5 as aprilnine" May 11 11:56:28 streamer go-librespot[1197]: time="2025-05-11T11:56:28+03:00" level=debug msg="initializing zeroconf session, username: aprilnine" May 11 11:56:28 streamer volumio[972]: info: [yt-cast-receiver] DIAL server listening on port 8098 May 11 11:56:28 streamer volumio[972]: info: CoreCommandRouter::volumioRetrievevolume May 11 11:56:28 streamer volumio[972]: info: CoreCommandRouter::volumioGetState May 11 11:56:28 streamer volumio[972]: info: CorePlayQueue::getTrack 0 May 11 11:56:28 streamer volumio[972]: info: CoreStateMachine::pushState May 11 11:56:28 streamer volumio[972]: info: CorePlayQueue::getTrack 0 May 11 11:56:28 streamer volumio[972]: info: CoreCommandRouter::volumioPushState May 11 11:56:28 streamer volumio[972]: error: [ytcr] VolumeControl failed to obtain volume from Volumio: May 11 11:56:28 streamer volumio[972]: (TypeError) Cannot read property 'vol' of undefined May 11 11:56:28 streamer volumio[972]: TypeError: Cannot read property 'vol' of undefined May 11 11:56:28 streamer volumio[972]: at VolumeControl.getVolume (/data/plugins/music_service/ytcr/dist/lib/VolumeControl.js:56:42) May 11 11:56:28 streamer volumio[972]: at processTicksAndRejections (internal/process/task_queues.js:93:5) May 11 11:56:28 streamer volumio[972]: at async VolumeControl.init (/data/plugins/music_service/ytcr/dist/lib/VolumeControl.js:28:68) May 11 11:56:28 streamer volumio[972]: at async /data/plugins/music_service/ytcr/dist/index.js:326:13 May 11 11:56:28 streamer go-librespot[1197]: time="2025-05-11T11:56:28+03:00" level=debug msg="dealer connection opened" May 11 11:56:28 streamer go-librespot[1197]: time="2025-05-11T11:56:28+03:00" level=trace msg="starting accesspoint recv loop" May 11 11:56:28 streamer go-librespot[1197]: time="2025-05-11T11:56:28+03:00" level=trace msg="starting dealer recv loop" May 11 11:56:28 streamer go-librespot[1197]: time="2025-05-11T11:56:28+03:00" level=trace msg="received accesspoint ping" May 11 11:56:28 streamer go-librespot[1197]: time="2025-05-11T11:56:28+03:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" May 11 11:56:28 streamer go-librespot[1197]: time="2025-05-11T11:56:28+03:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" May 11 11:56:28 streamer go-librespot[1197]: time="2025-05-11T11:56:28+03:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" May 11 11:56:28 streamer go-librespot[1197]: time="2025-05-11T11:56:28+03:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" May 11 11:56:28 streamer go-librespot[1197]: time="2025-05-11T11:56:28+03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" May 11 11:56:28 streamer go-librespot[1197]: time="2025-05-11T11:56:28+03:00" level=debug msg="received connection id: NjFmNzI4ZjQtOWIxZS00MTYxLTk1NjktZGI2Y2IyNGRkNzU4K2RlYWxlcit0Y3A6Ly8wYWNhNThkYy5pcC5nZXc0LnNwb3RpZnkubmV0OjU3MDArQUI4QTI0M0Q0MEUyMTdDQjc0OThCMzAyRjJENUU1MTZGNzA2QzgzMzVGMEU4RTAzOEE5QUI5RUU2RThENTFEMg==" May 11 11:56:28 streamer go-librespot[1197]: time="2025-05-11T11:56:28+03:00" level=trace msg="received accesspoint pong ack" May 11 11:56:28 streamer go-librespot[1197]: time="2025-05-11T11:56:28+03:00" level=debug msg="put connect state because NEW_DEVICE" May 11 11:56:28 streamer go-librespot[1197]: time="2025-05-11T11:56:28+03:00" level=debug msg="update volume to 65535/65535" May 11 11:56:28 streamer mpd[1245]: May 11 11:56 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg May 11 11:56:28 streamer systemd[1]: Started Music Player Daemon. May 11 11:56:28 streamer sudo[1169]: pam_unix(sudo:session): session closed for user root May 11 11:56:28 streamer sudo[1160]: pam_unix(sudo:session): session closed for user root May 11 11:56:28 streamer sudo[1228]: pam_unix(sudo:session): session closed for user root May 11 11:56:28 streamer volumio[972]: error: MPD error: The expression evaluated to a falsy value: May 11 11:56:28 streamer volumio[972]: assert.ok(self.idling) May 11 11:56:28 streamer volumio[972]: error: The expression evaluated to a falsy value: May 11 11:56:28 streamer volumio[972]: assert.ok(self.idling) May 11 11:56:28 streamer volumio[972]: error: MPD error: The expression evaluated to a falsy value: May 11 11:56:28 streamer volumio[972]: assert.ok(self.idling) May 11 11:56:28 streamer volumio[972]: error: The expression evaluated to a falsy value: May 11 11:56:28 streamer volumio[972]: assert.ok(self.idling) May 11 11:56:28 streamer volumio[972]: info: MPD running with PID1245 May 11 11:56:28 streamer volumio[972]: ,establishing connection May 11 11:56:28 streamer volumio[972]: error: updateQueue error: null May 11 11:56:28 streamer volumio[972]: error: updateQueue error: null May 11 11:56:28 streamer volumio[972]: info: Completed starting Core Plugins May 11 11:56:28 streamer volumio[972]: info: ------------------------------------------- May 11 11:56:28 streamer volumio[972]: info: ----- MyVolumio plugins startup ---- May 11 11:56:28 streamer volumio[972]: info: ------------------------------------------- May 11 11:56:28 streamer volumio[972]: info: [MyVolumio PluginManager] Fetching plans data.... May 11 11:56:28 streamer volumio[972]: info: camilladsp service started and running in background, instance 1 May 11 11:56:28 streamer volumio[972]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 11:56:28 streamer volumio[972]: info: FusionDsp - AAAAAAAAAAAAAA-> 44100 48000 88200 96000 176400 192000 <-AAAAAAAAAAAAA May 11 11:56:28 streamer volumio[972]: info: FusionDsp loaded May 11 11:56:28 streamer volumio[972]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 11 11:56:28 streamer sudo[1280]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start fusiondsp.service May 11 11:56:28 streamer sudo[1280]: pam_unix(sudo:session): session opened for user root by (uid=0) May 11 11:56:28 streamer volumio[972]: info: FusionDsp - Reporting Fusion DSP Enabled May 11 11:56:28 streamer volumio[972]: info: Adding Signal Path Element [object Object] May 11 11:56:28 streamer volumio[972]: info: Adding fusiondspeq DSP Signal Path Element May 11 11:56:28 streamer volumio[972]: info: FusionDsp - ---- installed callbackRead May 11 11:56:28 streamer volumio[972]: info: FusionDsp - If filter freq >samplerate/2 then disable it May 11 11:56:28 streamer volumio[972]: info: FusionDsp - else 1 -2.5 May 11 11:56:29 streamer systemd[1]: Started FusionDsp Daemon. May 11 11:56:29 streamer sudo[1290]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 May 11 11:56:29 streamer sudo[1290]: pam_unix(sudo:session): session opened for user root by (uid=0) May 11 11:56:29 streamer kernel: bcm2835-i2s fe203000.i2s: I2S SYNC error! May 11 11:56:29 streamer sudo[1280]: pam_unix(sudo:session): session closed for user root May 11 11:56:29 streamer sudo[1290]: pam_unix(sudo:session): session closed for user root May 11 11:56:29 streamer volumio[972]: error: FusionDsp - WebSocket error: [object Object] May 11 11:56:29 streamer volumio[972]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 May 11 11:56:29 streamer sudo[1293]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 May 11 11:56:29 streamer sudo[1293]: pam_unix(sudo:session): session opened for user root by (uid=0) May 11 11:56:29 streamer sudo[1293]: pam_unix(sudo:session): session closed for user root May 11 11:56:29 streamer sudo[1296]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service May 11 11:56:29 streamer sudo[1296]: pam_unix(sudo:session): session opened for user root by (uid=0) May 11 11:56:29 streamer systemd[1]: Started UPnP Renderer front-end to MPD. May 11 11:56:29 streamer sudo[1296]: pam_unix(sudo:session): session closed for user root May 11 11:56:29 streamer volumio[972]: info: Upmpdcli Daemon Started May 11 11:56:29 streamer volumio[1298]: Generating RSA private key, 4096 bit long modulus (2 primes) May 11 11:56:29 streamer go-librespot[1197]: time="2025-05-11T11:56:29+03:00" level=debug msg="put connect state because VOLUME_CHANGED" May 11 11:56:29 streamer go-librespot[1197]: time="2025-05-11T11:56:29+03:00" level=trace msg="emitting websocket event: volume" May 11 11:56:30 streamer volumio[972]: info: go-librespot daemon successfully initialized May 11 11:56:30 streamer volumio[1298]: ..............++++ May 11 11:56:32 streamer go-librespot[1197]: time="2025-05-11T11:56:32+03:00" level=debug msg="dealer connection closed" May 11 11:56:32 streamer go-librespot[1197]: time="2025-05-11T11:56:32+03:00" level=debug msg="dealer recv loop stopped" May 11 11:56:32 streamer go-librespot[1197]: time="2025-05-11T11:56:32+03:00" level=debug msg="obtained new client token: AABd5fe42Qw064Zc6LPkazT+10fTYTDC17KQ1qF0aQIs/6IAEdVFZoeiS8apbxIhM3RJriJnIj5/fKw0bDf9v/SkPb4uvuyWV1W4o5A+ylOGT40tPTUzOY9ZwezSzm7ly7JGY7/CLXyx73lpaiqozII4MeqKVVedVfVfIO9w+7KRY+BXZkeWYAphb6yry3LFYXkD3Loz/9Hy8tsdU5qIq3uckePsodL/nXRwqdgdm2NcAbYoAN/JT1ioR2Q=" May 11 11:56:32 streamer go-librespot[1197]: time="2025-05-11T11:56:32+03:00" level=debug msg="connected to ap-gew4.spotify.com:4070" May 11 11:56:33 streamer go-librespot[1197]: time="2025-05-11T11:56:33+03:00" level=debug msg="completed keyexchange" May 11 11:56:33 streamer go-librespot[1197]: time="2025-05-11T11:56:33+03:00" level=debug msg="completed challenge" May 11 11:56:33 streamer go-librespot[1197]: time="2025-05-11T11:56:33+03:00" level=info msg="authenticated AP as 31lgde2jbmfzvk5bncwqa7sbckp4" May 11 11:56:33 streamer go-librespot[1197]: time="2025-05-11T11:56:33+03:00" level=info msg="authenticated Login5 as 31lgde2jbmfzvk5bncwqa7sbckp4" May 11 11:56:33 streamer go-librespot[1197]: time="2025-05-11T11:56:33+03:00" level=info msg="accepted zeroconf user 31lgde2jbmfzvk5bncwqa7sbckp4 from iPhone" May 11 11:56:33 streamer go-librespot[1197]: time="2025-05-11T11:56:33+03:00" level=debug msg="dealer connection opened" May 11 11:56:33 streamer go-librespot[1197]: time="2025-05-11T11:56:33+03:00" level=trace msg="starting accesspoint recv loop" May 11 11:56:33 streamer go-librespot[1197]: time="2025-05-11T11:56:33+03:00" level=trace msg="starting dealer recv loop" May 11 11:56:33 streamer go-librespot[1197]: time="2025-05-11T11:56:33+03:00" level=trace msg="received accesspoint ping" May 11 11:56:33 streamer go-librespot[1197]: time="2025-05-11T11:56:33+03:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" May 11 11:56:33 streamer go-librespot[1197]: time="2025-05-11T11:56:33+03:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" May 11 11:56:33 streamer go-librespot[1197]: time="2025-05-11T11:56:33+03:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" May 11 11:56:33 streamer go-librespot[1197]: time="2025-05-11T11:56:33+03:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" May 11 11:56:33 streamer go-librespot[1197]: time="2025-05-11T11:56:33+03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" May 11 11:56:33 streamer go-librespot[1197]: time="2025-05-11T11:56:33+03:00" level=debug msg="received connection id: MTEwNjgyZjMtYTJlMi00ODk5LWFmY2QtZTlmODNiMmM0ZWU5K2RlYWxlcit0Y3A6Ly8wYWNhNTkxOS5pcC5nZXc0LnNwb3RpZnkubmV0OjU3MDArQjdENkFFREZEOEMzMTExQjU3NUY5MTE0QzIyMzY1MDVGOTU4QTc0NUFGMzJBQjMyMjAzMERBRERGREREQTczNw==" May 11 11:56:33 streamer go-librespot[1197]: time="2025-05-11T11:56:33+03:00" level=trace msg="received accesspoint pong ack" May 11 11:56:33 streamer volumio[972]: info: Initializing connection to go-librespot Websocket May 11 11:56:33 streamer go-librespot[1197]: time="2025-05-11T11:56:33+03:00" level=debug msg="new websocket client" May 11 11:56:33 streamer volumio[972]: info: Connection to go-librespot Websocket established May 11 11:56:33 streamer go-librespot[1197]: time="2025-05-11T11:56:33+03:00" level=debug msg="put connect state because NEW_DEVICE" May 11 11:56:33 streamer go-librespot[1197]: time="2025-05-11T11:56:33+03:00" level=debug msg="update volume to 65535/65535" May 11 11:56:33 streamer go-librespot[1197]: time="2025-05-11T11:56:33+03:00" level=debug msg="handling transfer player command from fcd19ad70b2fc5c71ed5ab2b3b48792b6e38ac75" May 11 11:56:33 streamer go-librespot[1197]: time="2025-05-11T11:56:33+03:00" level=debug msg="resolved context of track" uri="spotify:playlist:19MYW5NrtdcMdzimEYqmtV" May 11 11:56:33 streamer go-librespot[1197]: time="2025-05-11T11:56:33+03:00" level=trace msg="fetched new page 0 with 22 items (list: 22)" uri="spotify:playlist:19MYW5NrtdcMdzimEYqmtV" May 11 11:56:33 streamer go-librespot[1197]: time="2025-05-11T11:56:33+03:00" level=warning msg="failed seeking to track in context spotify:playlist:19MYW5NrtdcMdzimEYqmtV" error="could not find track" uri="spotify:playlist:19MYW5NrtdcMdzimEYqmtV" May 11 11:56:33 streamer go-librespot[1197]: time="2025-05-11T11:56:33+03:00" level=debug msg="shuffled context with seed 6798618363596472998 (len: 22, keep: 12)" uri="spotify:playlist:19MYW5NrtdcMdzimEYqmtV" May 11 11:56:33 streamer go-librespot[1197]: time="2025-05-11T11:56:33+03:00" level=debug msg="loading track (paused: true, position: 171980ms)" uri="spotify:track:7aux5UvnlBDYlrlwoczifW" May 11 11:56:33 streamer go-librespot[1197]: time="2025-05-11T11:56:33+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 11 11:56:33 streamer go-librespot[1197]: time="2025-05-11T11:56:33+03:00" level=trace msg="emitting websocket event: will_play" May 11 11:56:33 streamer volumio[972]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:7aux5UvnlBDYlrlwoczifW","play_origin":"playlist/ondemand"}} May 11 11:56:33 streamer go-librespot[1197]: time="2025-05-11T11:56:33+03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 345" May 11 11:56:33 streamer go-librespot[1197]: time="2025-05-11T11:56:33+03:00" level=debug msg="selected format OGG_VORBIS_320 (cc6bda1c93b12029bea10aa3fd1c2fa915ab2633)" uri="spotify:track:7aux5UvnlBDYlrlwoczifW" May 11 11:56:33 streamer go-librespot[1197]: time="2025-05-11T11:56:33+03:00" level=debug msg="requested aes key for file cc6bda1c93b12029bea10aa3fd1c2fa915ab2633, gid: 7aux5UvnlBDYlrlwoczifW" May 11 11:56:33 streamer go-librespot[1197]: time="2025-05-11T11:56:33+03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1697" May 11 11:56:33 streamer volumio[1298]: ................................++++ May 11 11:56:33 streamer volumio[1298]: e is 65537 (0x010001) May 11 11:56:33 streamer volumio[1298]: writing RSA key May 11 11:56:33 streamer go-librespot[1197]: time="2025-05-11T11:56:33+03:00" level=debug msg="fetched first chunk of 18, total size is 9299628 bytes" uri="spotify:track:7aux5UvnlBDYlrlwoczifW" May 11 11:56:33 streamer volumio[972]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory May 11 11:56:33 streamer go-librespot[1197]: time="2025-05-11T11:56:33+03:00" level=debug msg="fetched chunk 3/17, size: 524288" uri="spotify:track:7aux5UvnlBDYlrlwoczifW" May 11 11:56:33 streamer go-librespot[1197]: time="2025-05-11T11:56:33+03:00" level=debug msg="fetched chunk 1/17, size: 524288" uri="spotify:track:7aux5UvnlBDYlrlwoczifW" May 11 11:56:33 streamer volumio-remote-updater[614]: [2025-05-11 11:56:33] [connect] Successful connection May 11 11:56:33 streamer go-librespot[1197]: time="2025-05-11T11:56:33+03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1293" May 11 11:56:34 streamer volumio-remote-updater[614]: [2025-05-11 11:56:34] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1746953793 101 May 11 11:56:34 streamer volumio[972]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 4 Transport: websocket Total Clients: 3 May 11 11:56:34 streamer go-librespot[1197]: time="2025-05-11T11:56:34+03:00" level=debug msg="fetched chunk 13/17, size: 524288" uri="spotify:track:7aux5UvnlBDYlrlwoczifW" May 11 11:56:34 streamer go-librespot[1197]: time="2025-05-11T11:56:34+03:00" level=trace msg="seek to 171980ms (diff: 85ms, samples: 7584318, bytes: 6904650)" uri="spotify:track:7aux5UvnlBDYlrlwoczifW" May 11 11:56:34 streamer go-librespot[1197]: time="2025-05-11T11:56:34+03:00" level=debug msg="created new output device" May 11 11:56:34 streamer go-librespot[1197]: time="2025-05-11T11:56:34+03:00" level=info msg="loaded track \"Miku\" (paused: true, position: 171980ms, duration: 223124ms, prefetched: false)" uri="spotify:track:7aux5UvnlBDYlrlwoczifW" May 11 11:56:34 streamer go-librespot[1197]: time="2025-05-11T11:56:34+03:00" level=debug msg="fetched chunk 15/17, size: 524288" uri="spotify:track:7aux5UvnlBDYlrlwoczifW" May 11 11:56:34 streamer go-librespot[1197]: time="2025-05-11T11:56:34+03:00" level=debug msg="fetched chunk 14/17, size: 524288" uri="spotify:track:7aux5UvnlBDYlrlwoczifW" May 11 11:56:34 streamer go-librespot[1197]: time="2025-05-11T11:56:34+03:00" level=debug msg="fetched chunk 16/17, size: 524288" uri="spotify:track:7aux5UvnlBDYlrlwoczifW" May 11 11:56:34 streamer go-librespot[1197]: time="2025-05-11T11:56:34+03:00" level=debug msg="fetched chunk 2/17, size: 524288" uri="spotify:track:7aux5UvnlBDYlrlwoczifW" May 11 11:56:34 streamer go-librespot[1197]: time="2025-05-11T11:56:34+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 11 11:56:34 streamer go-librespot[1197]: time="2025-05-11T11:56:34+03:00" level=trace msg="emitting websocket event: metadata" May 11 11:56:34 streamer go-librespot[1197]: time="2025-05-11T11:56:34+03:00" level=trace msg="emitting websocket event: active" May 11 11:56:34 streamer go-librespot[1197]: time="2025-05-11T11:56:34+03:00" level=debug msg="sending successful reply for dealer request" May 11 11:56:34 streamer go-librespot[1197]: time="2025-05-11T11:56:34+03:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update May 11 11:56:34 streamer go-librespot[1197]: time="2025-05-11T11:56:34+03:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update May 11 11:56:34 streamer go-librespot[1197]: time="2025-05-11T11:56:34+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 11 11:56:34 streamer go-librespot[1197]: time="2025-05-11T11:56:34+03:00" level=trace msg="emitting websocket event: paused" May 11 11:56:34 streamer volumio[972]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:7aux5UvnlBDYlrlwoczifW","name":"Miku","artist_names":["Anamanaguchi","Hatsune Miku"],"album_name":"Miku","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02154c3562dc92bcd302c72c9c","position":171980,"duration":223124,"release_date":"year:2016 month:5 day:24","track_number":1,"disc_number":1}} May 11 11:56:34 streamer volumio[972]: SPOTIFY: received: {"type":"active","data":null} May 11 11:56:34 streamer volumio[972]: info: Aligning Spotify Volume to Volumio Volume May 11 11:56:34 streamer volumio[972]: info: CoreCommandRouter::volumioGetState May 11 11:56:34 streamer volumio[972]: info: CorePlayQueue::getTrack 0 May 11 11:56:34 streamer volumio[972]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:7aux5UvnlBDYlrlwoczifW","play_origin":"playlist/ondemand"}} May 11 11:56:34 streamer volumio[972]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 11 11:56:34 streamer volumio[972]: TypeError: Cannot read property 'service' of undefined May 11 11:56:34 streamer volumio[972]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:337:50) May 11 11:56:34 streamer volumio[972]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:271:18) May 11 11:56:34 streamer volumio[972]: at WebSocket.message (/data/plugins/music_service/spop/index.js:190:14) May 11 11:56:34 streamer volumio[972]: at WebSocket.emit (events.js:315:20) May 11 11:56:34 streamer volumio[972]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20) May 11 11:56:34 streamer volumio[972]: at Receiver.emit (events.js:315:20) May 11 11:56:34 streamer volumio[972]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) May 11 11:56:34 streamer volumio[972]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) May 11 11:56:34 streamer volumio[972]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) May 11 11:56:34 streamer volumio[972]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) May 11 11:56:34 streamer volumio[972]: at writeOrBuffer (internal/streams/writable.js:358:12) May 11 11:56:34 streamer volumio[972]: at Receiver.Writable.write (internal/streams/writable.js:303:10) May 11 11:56:34 streamer volumio[972]: at Socket.socketOnData (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1355:35) May 11 11:56:34 streamer volumio[972]: at Socket.emit (events.js:315:20) May 11 11:56:34 streamer volumio[972]: at addChunk (internal/streams/readable.js:309:12) May 11 11:56:34 streamer volumio[972]: at readableAddChunk (internal/streams/readable.js:284:9) May 11 11:56:34 streamer volumio[972]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 11 11:56:34 streamer go-librespot[1197]: time="2025-05-11T11:56:34+03:00" level=debug msg="put connect state because VOLUME_CHANGED" May 11 11:56:34 streamer go-librespot[1197]: time="2025-05-11T11:56:34+03:00" level=trace msg="emitting websocket event: volume" May 11 11:56:34 streamer sudo[1344]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-05-11 11:55 May 11 11:56:34 streamer sudo[1344]: 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="f6610a1100d2380eef33bd3004af43153c786f96" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="1c0e5daee99fe3a72cc38b0d1fe6cd78d7f001fe" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Mon 16 Dec 2024 09:30:04 AM CET" VOLUMIO_VERSION="3.785" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="fe0ac4b79aed19ccde4b5bd83d468193"