-- Logs begin at Thu 2019-02-14 10:11:58 GMT, end at Sun 2026-01-11 16:20:09 GMT. -- Jan 11 16:19:05 volumio2 fake-hwclock[304]: Sun Jan 11 16:19:05 UTC 2026 Jan 11 16:19:05 volumio2 systemd[1]: Started Restore / save the current clock. Jan 11 16:19:05 volumio2 systemd[1]: Mounted Kernel Configuration File System. Jan 11 16:19:05 volumio2 systemd[1]: Started Remount Root and Kernel File Systems. Jan 11 16:19:05 volumio2 systemd[1]: Starting Create System Users... Jan 11 16:19:05 volumio2 systemd[1]: Condition check resulted in Rebuild Hardware Database being skipped. Jan 11 16:19:05 volumio2 systemd[1]: Starting Load/Save Random Seed... Jan 11 16:19:05 volumio2 systemd[1]: Started Apply Kernel Variables. Jan 11 16:19:05 volumio2 systemd[1]: dynamicswap.service: Succeeded. Jan 11 16:19:05 volumio2 systemd[1]: Started Load/Save Random Seed. Jan 11 16:19:05 volumio2 systemd[1]: Started udev Coldplug all Devices. Jan 11 16:19:05 volumio2 systemd[1]: Starting Helper to synchronize boot up for ifupdown... Jan 11 16:19:05 volumio2 systemd[1]: Started Create System Users. Jan 11 16:19:05 volumio2 systemd[1]: Starting Create Static Device Nodes in /dev... Jan 11 16:19:05 volumio2 systemd[1]: Started Create Static Device Nodes in /dev. Jan 11 16:19:05 volumio2 systemd[1]: Reached target Local File Systems (Pre). Jan 11 16:19:05 volumio2 systemd[1]: Mounting /var/spool/cups... Jan 11 16:19:05 volumio2 systemd[1]: var-log.mount: Directory /var/log to mount over is not empty, mounting anyway. Jan 11 16:19:05 volumio2 systemd[1]: Mounting /var/log... Jan 11 16:19:05 volumio2 systemd[1]: tmp.mount: Directory /tmp to mount over is not empty, mounting anyway. Jan 11 16:19:05 volumio2 systemd[1]: Mounting /tmp... Jan 11 16:19:05 volumio2 systemd[1]: Starting udev Kernel Device Manager... Jan 11 16:19:05 volumio2 systemd[1]: Mounted /var/spool/cups. Jan 11 16:19:05 volumio2 systemd[1]: Mounted /var/log. Jan 11 16:19:05 volumio2 systemd[1]: Mounted /tmp. Jan 11 16:19:05 volumio2 systemd[1]: Starting Flush Journal to Persistent Storage... Jan 11 16:19:05 volumio2 systemd[1]: Mounting /var/spool/cups/tmp... Jan 11 16:19:05 volumio2 systemd[1]: Mounted /var/spool/cups/tmp. Jan 11 16:19:05 volumio2 systemd-udevd[335]: Network interface NamePolicy= disabled on kernel command line, ignoring. Jan 11 16:19:05 volumio2 systemd-journald[302]: Runtime journal (/run/log/journal/a4d620ccb4a6a12010c39c5d649876fe) is 7.5M, max 30.0M, 22.5M free. Jan 11 16:19:05 volumio2 systemd[1]: Started udev Kernel Device Manager. Jan 11 16:19:05 volumio2 systemd[1]: Starting Show Plymouth Boot Screen... Jan 11 16:19:05 volumio2 systemd[1]: Started Flush Journal to Persistent Storage. Jan 11 16:19:05 volumio2 systemd[1]: plymouth-start.service: Succeeded. Jan 11 16:19:05 volumio2 systemd[1]: Started Show Plymouth Boot Screen. Jan 11 16:19:05 volumio2 systemd[1]: Started Forward Password Requests to Plymouth Directory Watch. Jan 11 16:19:05 volumio2 systemd[1]: Condition check resulted in Dispatch Password Requests to Console Directory Watch being skipped. Jan 11 16:19:05 volumio2 systemd[1]: Reached target Paths. Jan 11 16:19:05 volumio2 systemd[1]: Reached target Local Encrypted Volumes. Jan 11 16:19:05 volumio2 systemd-udevd[349]: Using default interface naming scheme 'v240'. Jan 11 16:19:05 volumio2 systemd-udevd[349]: link_config: autonegotiation is unset or enabled, the speed and duplex are not writable. Jan 11 16:19:05 volumio2 kernel: rpi-gpiomem fe200000.gpiomem: window base 0xfe200000 size 0x00001000 Jan 11 16:19:05 volumio2 kernel: rpi-gpiomem fe200000.gpiomem: initialised 1 regions as /dev/gpiomem Jan 11 16:19:05 volumio2 kernel: vc_sm_cma: module is from the staging directory, the quality is unknown, you have been warned. Jan 11 16:19:05 volumio2 kernel: bcm2835_vc_sm_cma_probe: Videocore shared memory driver Jan 11 16:19:05 volumio2 kernel: [vc_sm_connected_init]: start Jan 11 16:19:05 volumio2 kernel: [vc_sm_connected_init]: installed successfully Jan 11 16:19:05 volumio2 kernel: mc: Linux media interface: v0.10 Jan 11 16:19:05 volumio2 kernel: cfg80211: Loading compiled-in X.509 certificates for regulatory database Jan 11 16:19:05 volumio2 kernel: Loaded X.509 cert 'benh@debian.org: 577e021cb980e0e820821ba7b54b4961b8b4fadf' Jan 11 16:19:05 volumio2 kernel: Loaded X.509 cert 'romain.perier@gmail.com: 3abbc6ec146e09d1b6016ab9d6cf71dd233f0328' Jan 11 16:19:05 volumio2 kernel: Loaded X.509 cert 'sforshee: 00b28ddf47aef9cea7' Jan 11 16:19:05 volumio2 kernel: Loaded X.509 cert 'wens: 61c038651aabdcf94bd0ac7ff06c7248db18c600' Jan 11 16:19:05 volumio2 kernel: videodev: Linux video capture interface: v2.00 Jan 11 16:19:05 volumio2 kernel: snd_bcm2835: module is from the staging directory, the quality is unknown, you have been warned. Jan 11 16:19:05 volumio2 kernel: snd_bcm2835: unknown parameter 'enable_compat_alsa' ignored Jan 11 16:19:05 volumio2 kernel: bcm2835_audio bcm2835_audio: card created with 4 channels Jan 11 16:19:05 volumio2 kernel: Bluetooth: Core ver 2.22 Jan 11 16:19:05 volumio2 kernel: NET: Registered PF_BLUETOOTH protocol family Jan 11 16:19:05 volumio2 kernel: Bluetooth: HCI device and connection manager initialized Jan 11 16:19:05 volumio2 kernel: Bluetooth: HCI socket layer initialized Jan 11 16:19:05 volumio2 kernel: Bluetooth: L2CAP socket layer initialized Jan 11 16:19:05 volumio2 kernel: Bluetooth: SCO socket layer initialized Jan 11 16:19:05 volumio2 kernel: bcm2835_mmal_vchiq: module is from the staging directory, the quality is unknown, you have been warned. Jan 11 16:19:05 volumio2 kernel: bcm2835_audio bcm2835_audio: card created with 4 channels Jan 11 16:19:05 volumio2 systemd[1]: Found device /dev/disk/by-uuid/7883-9333. Jan 11 16:19:05 volumio2 kernel: bcm2835_v4l2: module is from the staging directory, the quality is unknown, you have been warned. Jan 11 16:19:05 volumio2 kernel: bcm2835_isp: module is from the staging directory, the quality is unknown, you have been warned. Jan 11 16:19:05 volumio2 kernel: rpivid_hevc: module is from the staging directory, the quality is unknown, you have been warned. Jan 11 16:19:05 volumio2 kernel: bcm2835_codec: module is from the staging directory, the quality is unknown, you have been warned. Jan 11 16:19:05 volumio2 kernel: bcm2835-isp bcm2835-isp: Device node output[0] registered as /dev/video13 Jan 11 16:19:05 volumio2 kernel: bcm2835-isp bcm2835-isp: Device node capture[0] registered as /dev/video14 Jan 11 16:19:05 volumio2 kernel: bcm2835-isp bcm2835-isp: Device node capture[1] registered as /dev/video15 Jan 11 16:19:05 volumio2 kernel: bcm2835-isp bcm2835-isp: Device node stats[2] registered as /dev/video16 Jan 11 16:19:05 volumio2 kernel: bcm2835-isp bcm2835-isp: Register output node 0 with media controller Jan 11 16:19:05 volumio2 kernel: bcm2835-isp bcm2835-isp: Register capture node 1 with media controller Jan 11 16:19:05 volumio2 kernel: bcm2835-isp bcm2835-isp: Register capture node 2 with media controller Jan 11 16:19:05 volumio2 kernel: bcm2835-isp bcm2835-isp: Register capture node 3 with media controller Jan 11 16:19:05 volumio2 kernel: rpivid feb10000.codec: Device registered as /dev/video19 Jan 11 16:19:05 volumio2 kernel: bcm2835-isp bcm2835-isp: Device node output[0] registered as /dev/video20 Jan 11 16:19:05 volumio2 kernel: bcm2835-isp bcm2835-isp: Device node capture[0] registered as /dev/video21 Jan 11 16:19:05 volumio2 kernel: bcm2835-isp bcm2835-isp: Device node capture[1] registered as /dev/video22 Jan 11 16:19:05 volumio2 kernel: bcm2835-isp bcm2835-isp: Device node stats[2] registered as /dev/video23 Jan 11 16:19:05 volumio2 kernel: bcm2835-isp bcm2835-isp: Register output node 0 with media controller Jan 11 16:19:05 volumio2 kernel: bcm2835-isp bcm2835-isp: Register capture node 1 with media controller Jan 11 16:19:05 volumio2 kernel: bcm2835-isp bcm2835-isp: Register capture node 2 with media controller Jan 11 16:19:05 volumio2 kernel: bcm2835-isp bcm2835-isp: Register capture node 3 with media controller Jan 11 16:19:05 volumio2 kernel: bcm2835-isp bcm2835-isp: Loaded V4L2 bcm2835-isp Jan 11 16:19:05 volumio2 kernel: Bluetooth: HCI UART driver ver 2.3 Jan 11 16:19:05 volumio2 kernel: Bluetooth: HCI UART protocol H4 registered Jan 11 16:19:05 volumio2 kernel: Bluetooth: HCI UART protocol Three-wire (H5) registered Jan 11 16:19:05 volumio2 kernel: Bluetooth: HCI UART protocol Broadcom registered Jan 11 16:19:05 volumio2 kernel: hci_uart_bcm serial0-0: supply vbat not found, using dummy regulator Jan 11 16:19:06 volumio2 kernel: hci_uart_bcm serial0-0: supply vddio not found, using dummy regulator Jan 11 16:19:06 volumio2 kernel: brcmfmac: F1 signature read @0x18000000=0x15264345 Jan 11 16:19:06 volumio2 kernel: brcmfmac: brcmf_fw_alloc_request: using brcm/brcmfmac43455-sdio for chip BCM4345/6 Jan 11 16:19:06 volumio2 kernel: usbcore: registered new interface driver brcmfmac Jan 11 16:19:06 volumio2 kernel: bcm2835-codec bcm2835-codec: Device registered as /dev/video10 Jan 11 16:19:06 volumio2 kernel: bcm2835-codec bcm2835-codec: Loaded V4L2 decode Jan 11 16:19:06 volumio2 kernel: bcm2835-codec bcm2835-codec: Device registered as /dev/video11 Jan 11 16:19:06 volumio2 kernel: bcm2835-codec bcm2835-codec: Loaded V4L2 encode Jan 11 16:19:06 volumio2 kernel: bcm2835-codec bcm2835-codec: Device registered as /dev/video12 Jan 11 16:19:06 volumio2 kernel: bcm2835-codec bcm2835-codec: Loaded V4L2 isp Jan 11 16:19:06 volumio2 kernel: bcm2835-codec bcm2835-codec: Device registered as /dev/video18 Jan 11 16:19:06 volumio2 kernel: bcm2835-codec bcm2835-codec: Loaded V4L2 image_fx Jan 11 16:19:06 volumio2 kernel: bcm2835-codec bcm2835-codec: Device registered as /dev/video31 Jan 11 16:19:06 volumio2 kernel: bcm2835-codec bcm2835-codec: Loaded V4L2 encode_image Jan 11 16:19:06 volumio2 kernel: uart-pl011 fe201000.serial: no DMA platform data Jan 11 16:19:06 volumio2 systemd[1]: Starting File System Check on /dev/disk/by-uuid/7883-9333... Jan 11 16:19:06 volumio2 systemd[1]: Started File System Check Daemon to report status. Jan 11 16:19:06 volumio2 systemd-udevd[349]: link_config: autonegotiation is unset or enabled, the speed and duplex are not writable. Jan 11 16:19:06 volumio2 systemd[1]: Found device /sys/subsystem/net/devices/eth0. Jan 11 16:19:06 volumio2 systemd-fsck[423]: fsck.fat 4.1 (2017-01-24) Jan 11 16:19:06 volumio2 systemd-fsck[423]: /dev/mmcblk0p1: 412 files, 41776/46774 clusters Jan 11 16:19:06 volumio2 systemd[1]: Started File System Check on /dev/disk/by-uuid/7883-9333. Jan 11 16:19:06 volumio2 kernel: brcmfmac: brcmf_c_process_txcap_blob: no txcap_blob available (err=-2) Jan 11 16:19:06 volumio2 kernel: brcmfmac: brcmf_c_preinit_dcmds: Firmware: BCM4345/6 wl0: Nov 1 2021 00:37:25 version 7.45.241 (1a2f2fa CY) FWID 01-703fd60 Jan 11 16:19:06 volumio2 kernel: Bluetooth: hci0: BCM: chip id 107 Jan 11 16:19:06 volumio2 kernel: Bluetooth: hci0: BCM: features 0x2f Jan 11 16:19:06 volumio2 kernel: Bluetooth: hci0: BCM4345C0 Jan 11 16:19:06 volumio2 kernel: Bluetooth: hci0: BCM4345C0 (003.001.025) build 0000 Jan 11 16:19:06 volumio2 kernel: Bluetooth: hci0: BCM4345C0 'brcm/BCM4345C0.hcd' Patch Jan 11 16:19:06 volumio2 systemd-udevd[344]: Using default interface naming scheme 'v240'. Jan 11 16:19:06 volumio2 systemd-udevd[344]: link_config: autonegotiation is unset or enabled, the speed and duplex are not writable. Jan 11 16:19:06 volumio2 kernel: usb 1-1.4: 1:3 : unsupported format bits 0x100000000 Jan 11 16:19:06 volumio2 kernel: usbcore: registered new interface driver snd-usb-audio Jan 11 16:19:06 volumio2 kernel: alsactl[453]: memfd_create() called without MFD_EXEC or MFD_NOEXEC_SEAL set Jan 11 16:19:07 volumio2 systemd[1]: Created slice system-bthelper.slice. Jan 11 16:19:07 volumio2 systemd-udevd[345]: Process '/bin/bash -c '/usr/local/bin/volumio usbattach'' failed with exit code 7. Jan 11 16:19:07 volumio2 kernel: Bluetooth: hci0: BCM: features 0x2f Jan 11 16:19:07 volumio2 kernel: Bluetooth: hci0: BCM43455 37.4MHz Raspberry Pi 3+ Jan 11 16:19:07 volumio2 kernel: Bluetooth: hci0: BCM4345C0 (003.001.025) build 0342 Jan 11 16:19:07 volumio2 systemd[1]: Starting Show Plymouth Boot Screen... Jan 11 16:19:07 volumio2 systemd[1]: Condition check resulted in Rebuild Hardware Database being skipped. Jan 11 16:19:07 volumio2 systemd[1]: Condition check resulted in Set Up Additional Binary Formats being skipped. Jan 11 16:19:07 volumio2 systemd[1]: Condition check resulted in Huge Pages File System being skipped. Jan 11 16:19:07 volumio2 systemd[1]: Listening on Load/Save RF Kill Switch Status /dev/rfkill Watch. Jan 11 16:19:07 volumio2 systemd[1]: Mounting /boot... Jan 11 16:19:07 volumio2 systemd[1]: Starting Load/Save RF Kill Switch Status... Jan 11 16:19:07 volumio2 systemd[1]: plymouth-start.service: Succeeded. Jan 11 16:19:07 volumio2 systemd[1]: Started Show Plymouth Boot Screen. Jan 11 16:19:07 volumio2 systemd[1]: Condition check resulted in Dispatch Password Requests to Console Directory Watch being skipped. Jan 11 16:19:07 volumio2 systemd[1]: Mounted /boot. Jan 11 16:19:07 volumio2 systemd[1]: Found device /sys/subsystem/net/devices/wlan0. Jan 11 16:19:07 volumio2 systemd[1]: Started Load/Save RF Kill Switch Status. Jan 11 16:19:07 volumio2 systemd[1]: Reached target Local File Systems. Jan 11 16:19:07 volumio2 systemd[1]: Started ifup for eth0. Jan 11 16:19:07 volumio2 systemd[1]: Starting Create Volatile Files and Directories... Jan 11 16:19:07 volumio2 systemd[1]: Starting Tell Plymouth To Write Out Runtime Data... Jan 11 16:19:07 volumio2 systemd[1]: Started ifup for wlan0. Jan 11 16:19:07 volumio2 systemd[1]: Starting Preprocess NFS configuration... Jan 11 16:19:07 volumio2 systemd[1]: Condition check resulted in Commit a transient machine-id on disk being skipped. Jan 11 16:19:07 volumio2 systemd[1]: Received SIGRTMIN+20 from PID 190 (plymouthd). Jan 11 16:19:07 volumio2 systemd[1]: plymouth-read-write.service: Succeeded. Jan 11 16:19:07 volumio2 systemd[1]: Started Tell Plymouth To Write Out Runtime Data. Jan 11 16:19:07 volumio2 systemd[1]: nfs-config.service: Succeeded. Jan 11 16:19:07 volumio2 systemd[1]: Started Preprocess NFS configuration. Jan 11 16:19:07 volumio2 systemd[1]: Condition check resulted in RPC security service for NFS client and server being skipped. Jan 11 16:19:07 volumio2 systemd[1]: Condition check resulted in RPC security service for NFS server being skipped. Jan 11 16:19:07 volumio2 systemd[1]: Reached target NFS client services. Jan 11 16:19:07 volumio2 systemd[1]: Started Create Volatile Files and Directories. Jan 11 16:19:07 volumio2 systemd[1]: Starting RPC bind portmap service... Jan 11 16:19:07 volumio2 kernel: warning: `iwconfig' uses wireless extensions which will stop working for Wi-Fi 7 hardware; use nl80211 Jan 11 16:19:07 volumio2 systemd[1]: Started Entropy daemon using the HAVEGE algorithm. Jan 11 16:19:07 volumio2 systemd[1]: Starting Update UTMP about System Boot/Shutdown... Jan 11 16:19:07 volumio2 systemd[1]: Condition check resulted in Network Time Synchronization being skipped. Jan 11 16:19:07 volumio2 systemd[1]: Started RPC bind portmap service. Jan 11 16:19:07 volumio2 systemd[1]: Reached target RPC Port Mapper. Jan 11 16:19:07 volumio2 systemd[1]: Reached target Remote File Systems (Pre). Jan 11 16:19:07 volumio2 systemd[1]: Reached target Remote File Systems. Jan 11 16:19:07 volumio2 systemd[1]: Started Update UTMP about System Boot/Shutdown. Jan 11 16:19:07 volumio2 systemd[1]: Reached target System Initialization. Jan 11 16:19:07 volumio2 systemd[1]: Listening on Avahi mDNS/DNS-SD Stack Activation Socket. Jan 11 16:19:07 volumio2 systemd[1]: Started Daily apt download activities. Jan 11 16:19:07 volumio2 systemd[1]: Started Daily apt upgrade and clean activities. Jan 11 16:19:07 volumio2 systemd[1]: Started Daily Cleanup of Temporary Directories. Jan 11 16:19:07 volumio2 systemd[1]: Reached target Timers. Jan 11 16:19:07 volumio2 systemd[1]: Listening on triggerhappy.socket. Jan 11 16:19:07 volumio2 systemd[1]: Listening on D-Bus System Message Bus Socket. Jan 11 16:19:07 volumio2 systemd[1]: Listening on lircd.socket. Jan 11 16:19:07 volumio2 systemd[1]: Reached target Sockets. Jan 11 16:19:07 volumio2 systemd[1]: Reached target Basic System. Jan 11 16:19:07 volumio2 kernel: brcmfmac: brcmf_cfg80211_set_power_mgmt: power save disabled Jan 11 16:19:07 volumio2 kernel: bcmgenet fd580000.ethernet: configuring instance for external RGMII (RX delay) Jan 11 16:19:07 volumio2 kernel: bcmgenet fd580000.ethernet eth0: Link is Down Jan 11 16:19:07 volumio2 systemd[1]: Starting Configure Bluetooth Modems connected by UART... Jan 11 16:19:07 volumio2 systemd[1]: Starting LSB: Load kernel modules needed to enable cpufreq scaling... Jan 11 16:19:07 volumio2 systemd[1]: Started Volumio Log Rotation Service. Jan 11 16:19:07 volumio2 systemd[1]: Started volumio-remote-updater.service. Jan 11 16:19:07 volumio2 systemd[1]: Condition check resulted in getty on tty2-tty6 if dbus and logind are not available being skipped. Jan 11 16:19:07 volumio2 systemd[1]: Starting Wireless Services... Jan 11 16:19:07 volumio2 systemd[1]: Condition check resulted in Copy user wpa_supplicant.conf being skipped. Jan 11 16:19:07 volumio2 systemd[1]: Started UPnP Renderer front-end to MPD. Jan 11 16:19:07 volumio2 systemd[1]: Starting Login Service... Jan 11 16:19:07 volumio2 systemd[1]: Condition check resulted in Volumio SSH enabler being skipped. Jan 11 16:19:07 volumio2 systemd[1]: Started Manage Sound Card State (restore and store). Jan 11 16:19:07 volumio2 systemd[1]: Starting Avahi mDNS/DNS-SD Stack... Jan 11 16:19:07 volumio2 alsactl[572]: alsactl 1.1.8 daemon started Jan 11 16:19:07 volumio2 systemd[1]: Starting dhcpcd on all interfaces... Jan 11 16:19:07 volumio2 systemd[1]: Starting Volumio Time Update Utility... Jan 11 16:19:07 volumio2 systemd[1]: Started Volumio Iptables Module. Jan 11 16:19:07 volumio2 systemd[1]: Started D-Bus System Message Bus. Jan 11 16:19:07 volumio2 systemd[1]: Starting WPA supplicant... Jan 11 16:19:07 volumio2 systemd[1]: Starting Save/Restore Sound Card State... Jan 11 16:19:07 volumio2 systemd[1]: Starting triggerhappy global hotkey daemon... Jan 11 16:19:07 volumio2 systemd[1]: Started Helper to synchronize boot up for ifupdown. Jan 11 16:19:07 volumio2 systemd[1]: Starting Raise network interfaces... Jan 11 16:19:07 volumio2 volumio-time-update[576]: volumio-time-update-util: Fetching time from Volumio... Jan 11 16:19:07 volumio2 sh[489]: wlan0=wlan0 Jan 11 16:19:07 volumio2 sh[484]: eth0=eth0 Jan 11 16:19:07 volumio2 systemd-logind[570]: New seat seat0. Jan 11 16:19:07 volumio2 thd[584]: Unable to parse trigger line: Jan 11 16:19:07 volumio2 thd[584]: Unable to parse trigger line: KEY_MIN_INTERESTING 1 /usr/local/bin/volumio volume toggle Jan 11 16:19:07 volumio2 thd[584]: Unable to parse trigger line: Jan 11 16:19:07 volumio2 thd[584]: Found socket passed from systemd Jan 11 16:19:07 volumio2 avahi-daemon[573]: Found user 'avahi' (UID 110) and group 'avahi' (GID 113). Jan 11 16:19:07 volumio2 avahi-daemon[573]: Successfully dropped root privileges. Jan 11 16:19:07 volumio2 avahi-daemon[573]: avahi-daemon 0.7 starting up. Jan 11 16:19:07 volumio2 dhcpcd[575]: dev: loaded udev Jan 11 16:19:08 volumio2 volumio-remote-updater[566]: Error: No active session Jan 11 16:19:08 volumio2 volumio-remote-updater[566]: [2026-01-11 16:19:08] [info] asio async_connect error: system:111 (Connection refused) Jan 11 16:19:08 volumio2 volumio-remote-updater[566]: [2026-01-11 16:19:08] [info] Error getting remote endpoint: system:107 (Transport endpoint is not connected) Jan 11 16:19:08 volumio2 volumio-remote-updater[566]: [2026-01-11 16:19:08] [error] handle_connect error: Underlying Transport Error Jan 11 16:19:08 volumio2 kernel: 8021q: 802.1Q VLAN Support v1.8 Jan 11 16:19:08 volumio2 dhcpcd[575]: forked to background, child pid 652 Jan 11 16:19:08 volumio2 volumio-time-update[576]: volumio-time-update-util: Date not found in response Jan 11 16:19:08 volumio2 volumio-time-update[576]: volumio-time-update-util: Retrying in 5 seconds... Jan 11 16:19:08 volumio2 volumio[569]: Could not open config: /tmp/upmpdcli.conf Jan 11 16:19:08 volumio2 dbus-daemon[579]: [system] Successfully activated service 'org.freedesktop.systemd1' Jan 11 16:19:08 volumio2 systemd[1]: Started Login Service. Jan 11 16:19:08 volumio2 avahi-daemon[573]: Successfully called chroot(). Jan 11 16:19:08 volumio2 systemd[1]: Started triggerhappy global hotkey daemon. Jan 11 16:19:08 volumio2 avahi-daemon[573]: Successfully dropped remaining capabilities. Jan 11 16:19:08 volumio2 systemd[1]: hciuart.service: Succeeded. Jan 11 16:19:08 volumio2 systemd[1]: Started Configure Bluetooth Modems connected by UART. Jan 11 16:19:08 volumio2 systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Jan 11 16:19:08 volumio2 systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Jan 11 16:19:08 volumio2 systemd[1]: Started dhcpcd on all interfaces. Jan 11 16:19:08 volumio2 systemd[1]: Started Save/Restore Sound Card State. Jan 11 16:19:08 volumio2 avahi-daemon[573]: Loading service file /services/volumio.service. Jan 11 16:19:08 volumio2 wpa_supplicant[580]: Successfully initialized wpa_supplicant Jan 11 16:19:08 volumio2 avahi-daemon[573]: Network interface enumeration completed. Jan 11 16:19:08 volumio2 avahi-daemon[573]: Server startup complete. Host name is volumio2.local. Local service cookie is 2139246052. Jan 11 16:19:08 volumio2 avahi-daemon[573]: Service "Volumio2" (/services/volumio.service) successfully established. Jan 11 16:19:08 volumio2 systemd[1]: Started Avahi mDNS/DNS-SD Stack. Jan 11 16:19:08 volumio2 systemd[1]: Started WPA supplicant. Jan 11 16:19:08 volumio2 systemd[1]: Reached target Sound Card. Jan 11 16:19:08 volumio2 systemd[1]: Starting Raspberry Pi bluetooth helper... Jan 11 16:19:08 volumio2 haveged[513]: haveged: ver: 1.9.1; arch: generic; vend: ; build: (gcc 8.2.0 CTV); collect: 128K Jan 11 16:19:08 volumio2 haveged[513]: haveged: cpu: (VC); data: 16K (D); inst: 16K (D); idx: 11/40; sz: 14768/63488 Jan 11 16:19:08 volumio2 haveged[513]: haveged: tot tests(BA8): A:1/1 B:1/1 continuous tests(B): last entropy estimate 8.00245 Jan 11 16:19:08 volumio2 haveged[513]: haveged: fills: 0, generated: 0 Jan 11 16:19:08 volumio2 systemd[1]: Started Raise network interfaces. Jan 11 16:19:08 volumio2 systemd[1]: Reached target Network. Jan 11 16:19:08 volumio2 systemd[1]: Condition check resulted in fast remote file copy program daemon being skipped. Jan 11 16:19:08 volumio2 systemd[1]: Starting Permit User Sessions... Jan 11 16:19:08 volumio2 systemd[1]: Starting Network Time Service... Jan 11 16:19:08 volumio2 systemd[1]: Reached target Network is Online. Jan 11 16:19:08 volumio2 systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Jan 11 16:19:08 volumio2 bthelper[669]: Raspberry Pi BDADDR already set Jan 11 16:19:08 volumio2 systemd[1]: Starting Samba NMB Daemon... Jan 11 16:19:08 volumio2 systemd[1]: Starting LSB: Brings up/down network automatically... Jan 11 16:19:08 volumio2 systemd[1]: Starting /etc/rc.local Compatibility... Jan 11 16:19:08 volumio2 systemd[1]: Started Raspberry Pi bluetooth helper. Jan 11 16:19:08 volumio2 systemd[1]: Started Permit User Sessions. Jan 11 16:19:08 volumio2 systemd[1]: Starting Bluetooth service... Jan 11 16:19:08 volumio2 systemd[1]: Started /etc/rc.local Compatibility. Jan 11 16:19:08 volumio2 systemd[1]: iptables.service: Succeeded. Jan 11 16:19:08 volumio2 dhcpcd-run-hooks[743]: wlan0: starting wpa_supplicant Jan 11 16:19:08 volumio2 systemd[1]: Starting Hold until boot process finishes up... Jan 11 16:19:08 volumio2 systemd[1]: Starting Terminate Plymouth Boot Screen... Jan 11 16:19:08 volumio2 systemd[1]: Received SIGRTMIN+21 from PID 190 (plymouthd). Jan 11 16:19:08 volumio2 loadcpufreq[564]: Loading cpufreq kernel modules...done (none). Jan 11 16:19:08 volumio2 systemd[1]: Started LSB: Load kernel modules needed to enable cpufreq scaling. Jan 11 16:19:08 volumio2 systemd[1]: Starting LSB: set CPUFreq kernel parameters... Jan 11 16:19:08 volumio2 systemd[1]: plymouth-quit-wait.service: Succeeded. Jan 11 16:19:08 volumio2 systemd[1]: Started Hold until boot process finishes up. Jan 11 16:19:08 volumio2 systemd[1]: plymouth-quit.service: Succeeded. Jan 11 16:19:08 volumio2 systemd[1]: Started Terminate Plymouth Boot Screen. Jan 11 16:19:08 volumio2 systemd[1]: Received SIGRTMIN+21 from PID 190 (n/a). Jan 11 16:19:08 volumio2 ifplugd(eth0)[766]: ifplugd 0.28 initializing. Jan 11 16:19:08 volumio2 ifplugd(eth0)[766]: Using interface eth0/DC:A6:32:C8:AD:D6 with driver (version: 6.6.62-v7l+) Jan 11 16:19:08 volumio2 ifplugd(eth0)[766]: Using detection mode: SIOCETHTOOL Jan 11 16:19:08 volumio2 ifplugd(eth0)[766]: Initialization complete, link beat not detected. Jan 11 16:19:08 volumio2 dhcpcd[652]: wlan0: connected to Access Point `' Jan 11 16:19:08 volumio2 systemd[1]: Started Getty on tty1. Jan 11 16:19:08 volumio2 systemd[1]: Reached target Login Prompts. Jan 11 16:19:08 volumio2 bluetoothd[744]: Bluetooth daemon 5.83 Jan 11 16:19:08 volumio2 dhcpcd[652]: eth0: waiting for carrier Jan 11 16:19:08 volumio2 dhcpcd[652]: wlan0: waiting for carrier Jan 11 16:19:08 volumio2 ifplugd[725]: Network Interface Plugging Daemon...start eth0...done. Jan 11 16:19:08 volumio2 systemd[1]: Started LSB: Brings up/down network automatically. Jan 11 16:19:08 volumio2 bluetoothd[744]: src/main.c:check_options() Unknown key AutoConnectTimeout for group General in /etc/bluetooth/main.conf Jan 11 16:19:08 volumio2 systemd[1]: Started Bluetooth service. Jan 11 16:19:08 volumio2 systemd[1]: Reached target Bluetooth. Jan 11 16:19:08 volumio2 ntpd[711]: ntpd 4.2.8p12@1.3728-o (1): Starting Jan 11 16:19:08 volumio2 ntpd[711]: Command line: /usr/sbin/ntpd -p /var/run/ntpd.pid -g -u 103:103 Jan 11 16:19:08 volumio2 systemd[1]: Started Network Time Service. Jan 11 16:19:08 volumio2 ntpd[787]: proto: precision = 0.815 usec (-20) Jan 11 16:19:08 volumio2 bluetoothd[744]: Starting SDP server Jan 11 16:19:08 volumio2 bluetoothd[744]: Excluding (cli) hostname Jan 11 16:19:08 volumio2 bluetoothd[744]: Excluding (cli) scanparam Jan 11 16:19:08 volumio2 bluetoothd[744]: Excluding (cli) battery Jan 11 16:19:08 volumio2 cpufrequtils[755]: CPUFreq Utilities: Setting ondemand CPUFreq governor...CPU0...CPU1...CPU2...CPU3...done. Jan 11 16:19:08 volumio2 systemd[1]: Started LSB: set CPUFreq kernel parameters. Jan 11 16:19:08 volumio2 ntpd[787]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): good hash signature Jan 11 16:19:08 volumio2 ntpd[787]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): loaded, expire=2024-12-28T00:00:00Z last=2017-01-01T00:00:00Z ofs=37 Jan 11 16:19:08 volumio2 ntpd[787]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): expired less than 380 days ago Jan 11 16:19:08 volumio2 ntpd[787]: Listen and drop on 0 v6wildcard [::]:123 Jan 11 16:19:08 volumio2 ntpd[787]: Listen and drop on 1 v4wildcard 0.0.0.0:123 Jan 11 16:19:08 volumio2 ntpd[787]: Listen normally on 2 lo 127.0.0.1:123 Jan 11 16:19:08 volumio2 ntpd[787]: Listening on routing socket on fd #19 for interface updates Jan 11 16:19:08 volumio2 ntpd[787]: kernel reports TIME_ERROR: 0x41: Clock Unsynchronized Jan 11 16:19:08 volumio2 ntpd[787]: kernel reports TIME_ERROR: 0x41: Clock Unsynchronized Jan 11 16:19:08 volumio2 bluetoothd[744]: Bluetooth management interface 1.22 initialized Jan 11 16:19:08 volumio2 bluetoothd[744]: Battery Provider Manager created Jan 11 16:19:08 volumio2 kernel: Bluetooth: BNEP (Ethernet Emulation) ver 1.3 Jan 11 16:19:08 volumio2 kernel: Bluetooth: BNEP filters: protocol multicast Jan 11 16:19:08 volumio2 kernel: Bluetooth: BNEP socket layer initialized Jan 11 16:19:08 volumio2 kernel: Bluetooth: MGMT ver 1.22 Jan 11 16:19:09 volumio2 kernel: NET: Registered PF_ALG protocol family Jan 11 16:19:09 volumio2 kernel: cryptd: max_cpu_qlen set to 1000 Jan 11 16:19:09 volumio2 bluetoothd[744]: Failed to set privacy: Rejected (0x0b) Jan 11 16:19:09 volumio2 nmbd[738]: [2026/01/11 16:19:09.657913, 0] ../source3/nmbd/asyncdns.c:158(start_async_dns) Jan 11 16:19:09 volumio2 nmbd[738]: started asyncdns process 817 Jan 11 16:19:09 volumio2 nmbd[738]: [2026/01/11 16:19:09.659400, 0] ../lib/util/become_daemon.c:149(daemon_status) Jan 11 16:19:09 volumio2 nmbd[738]: daemon_status: STATUS=daemon 'nmbd' : No local IPv4 non-loopback interfaces available, waiting for interface ... Jan 11 16:19:09 volumio2 nmbd[738]: [2026/01/11 16:19:09.659509, 0] ../source3/nmbd/nmbd_subnetdb.c:254(create_subnets) Jan 11 16:19:09 volumio2 nmbd[738]: NOTE: NetBIOS name resolution is not supported for Internet Protocol Version 6 (IPv6). Jan 11 16:19:09 volumio2 wireless.js[567]: Cleaning previous... Jan 11 16:19:09 volumio2 ntpd[787]: error resolving pool 0.debian.pool.ntp.org: System error (-11) Jan 11 16:19:09 volumio2 sudo[825]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ip addr flush dev wlan0 Jan 11 16:19:09 volumio2 sudo[825]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 11 16:19:09 volumio2 sudo[825]: pam_unix(sudo:session): session closed for user root Jan 11 16:19:10 volumio2 sudo[827]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 down Jan 11 16:19:10 volumio2 sudo[827]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 11 16:19:10 volumio2 sudo[827]: pam_unix(sudo:session): session closed for user root Jan 11 16:19:10 volumio2 wireless.js[567]: Stopped aP Jan 11 16:19:10 volumio2 sudo[834]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 up Jan 11 16:19:10 volumio2 sudo[834]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 11 16:19:10 volumio2 sudo[834]: pam_unix(sudo:session): session closed for user root Jan 11 16:19:10 volumio2 kernel: brcmfmac: brcmf_cfg80211_set_power_mgmt: power save disabled Jan 11 16:19:10 volumio2 sudo[836]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iw reg get Jan 11 16:19:10 volumio2 sudo[836]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 11 16:19:10 volumio2 sudo[836]: pam_unix(sudo:session): session closed for user root Jan 11 16:19:10 volumio2 sudo[843]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 up Jan 11 16:19:10 volumio2 sudo[843]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 11 16:19:10 volumio2 sudo[843]: pam_unix(sudo:session): session closed for user root Jan 11 16:19:10 volumio2 sudo[845]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iw wlan0 scan Jan 11 16:19:10 volumio2 sudo[845]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 11 16:19:10 volumio2 sudo[845]: pam_unix(sudo:session): session closed for user root Jan 11 16:19:10 volumio2 wireless.js[567]: Start wireless flow Jan 11 16:19:10 volumio2 wireless.js[567]: Stopped hotspot (if there).. Jan 11 16:19:10 volumio2 sudo[850]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ip addr flush dev wlan0 Jan 11 16:19:10 volumio2 sudo[850]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 11 16:19:10 volumio2 sudo[850]: pam_unix(sudo:session): session closed for user root Jan 11 16:19:10 volumio2 sudo[852]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 down Jan 11 16:19:10 volumio2 sudo[852]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 11 16:19:10 volumio2 ntpd[787]: error resolving pool 1.debian.pool.ntp.org: System error (-11) Jan 11 16:19:11 volumio2 sudo[852]: pam_unix(sudo:session): session closed for user root Jan 11 16:19:11 volumio2 wireless.js[567]: DHCP IP Jan 11 16:19:11 volumio2 wireless.js[567]: Start ap Jan 11 16:19:11 volumio2 wpa_supplicant[854]: Successfully initialized wpa_supplicant Jan 11 16:19:11 volumio2 sudo[855]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/dhcpcd Jan 11 16:19:11 volumio2 sudo[855]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 11 16:19:11 volumio2 dhcpcd[856]: sending commands to master dhcpcd process Jan 11 16:19:11 volumio2 dhcpcd[652]: control command: /sbin/dhcpcd Jan 11 16:19:11 volumio2 sudo[855]: pam_unix(sudo:session): session closed for user root Jan 11 16:19:11 volumio2 kernel: brcmfmac: brcmf_cfg80211_set_power_mgmt: power save disabled Jan 11 16:19:11 volumio2 dhcpcd[652]: lo: carrier acquired Jan 11 16:19:11 volumio2 dhcpcd[652]: DUID 00:01:00:01:2c:2b:35:46:dc:a6:32:c8:ad:d6 Jan 11 16:19:11 volumio2 dhcpcd[652]: lo: IAID 6c:6f:00:00 Jan 11 16:19:11 volumio2 dhcpcd[652]: lo: ipv6_start: Operation not supported Jan 11 16:19:11 volumio2 dhcpcd[652]: lo: using static address 127.0.0.1/8 Jan 11 16:19:11 volumio2 dhcpcd[652]: lo: adding route to 127.0.0.0/8 Jan 11 16:19:11 volumio2 dhcpcd[652]: arp_announce: Invalid argument Jan 11 16:19:11 volumio2 dhcpcd[652]: eth0: carrier acquired Jan 11 16:19:11 volumio2 dhcpcd[652]: eth0: IAID 32:c8:ad:d6 Jan 11 16:19:11 volumio2 dhcpcd[652]: eth0: adding address fe80::dea6:32ff:fec8:add6 Jan 11 16:19:11 volumio2 dhcpcd[652]: ipv6_addaddr1: Permission denied Jan 11 16:19:11 volumio2 dhcpcd[652]: eth0: probing address 192.168.1.192/24 Jan 11 16:19:11 volumio2 kernel: bcmgenet fd580000.ethernet eth0: Link is Up - 1Gbps/Full - flow control rx/tx Jan 11 16:19:11 volumio2 ntpd[787]: error resolving pool 2.debian.pool.ntp.org: System error (-11) Jan 11 16:19:12 volumio2 systemd[1]: systemd-rfkill.service: Succeeded. Jan 11 16:19:12 volumio2 dhcpcd[652]: eth0: soliciting an IPv6 router Jan 11 16:19:12 volumio2 ifplugd(eth0)[766]: Link beat detected. Jan 11 16:19:12 volumio2 wireless.js[567]: trying... Jan 11 16:19:12 volumio2 sudo[887]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Jan 11 16:19:12 volumio2 sudo[887]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 11 16:19:12 volumio2 sudo[887]: pam_unix(sudo:session): session closed for user root Jan 11 16:19:12 volumio2 ifplugd(eth0)[766]: Executing '/etc/ifplugd/ifplugd.action eth0 up'. Jan 11 16:19:12 volumio2 ifplugd(eth0)[766]: client: ifup: interface eth0 already configured Jan 11 16:19:12 volumio2 ifplugd(eth0)[766]: Program executed successfully. Jan 11 16:19:12 volumio2 ntpd[787]: error resolving pool 3.debian.pool.ntp.org: System error (-11) Jan 11 16:19:13 volumio2 volumio-remote-updater[566]: [2026-01-11 16:19:13] [info] asio async_connect error: system:111 (Connection refused) Jan 11 16:19:13 volumio2 volumio-remote-updater[566]: [2026-01-11 16:19:13] [info] Error getting remote endpoint: system:107 (Transport endpoint is not connected) Jan 11 16:19:13 volumio2 volumio-remote-updater[566]: [2026-01-11 16:19:13] [error] handle_connect error: Underlying Transport Error Jan 11 16:19:13 volumio2 volumio-time-update[576]: volumio-time-update-util: Fetching time from Volumio... Jan 11 16:19:13 volumio2 volumio-time-update[576]: volumio-time-update-util: Date not found in response Jan 11 16:19:13 volumio2 volumio-time-update[576]: volumio-time-update-util: Retrying in 5 seconds... Jan 11 16:19:13 volumio2 wireless.js[567]: trying... Jan 11 16:19:13 volumio2 sudo[902]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Jan 11 16:19:13 volumio2 sudo[902]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 11 16:19:13 volumio2 sudo[902]: pam_unix(sudo:session): session closed for user root Jan 11 16:19:13 volumio2 bthelper[669]: [NEW] Media /org/bluez/hci0 Jan 11 16:19:13 volumio2 bthelper[669]: SupportedUUIDs: 0000110a-0000-1000-8000-00805f9b34fb Jan 11 16:19:13 volumio2 bthelper[669]: SupportedUUIDs: 0000110b-0000-1000-8000-00805f9b34fb Jan 11 16:19:13 volumio2 bluetoothd[744]: src/adv_monitor.c:btd_adv_monitor_power_down() Unexpected NULL btd_adv_monitor_manager object upon power down Jan 11 16:19:13 volumio2 bthelper[669]: hci0 class of device changed: 0x000000 Jan 11 16:19:13 volumio2 bthelper[669]: hci0 new_settings: ssp br/edr le secure-conn Jan 11 16:19:13 volumio2 bthelper[669]: [CHG] Controller DC:A6:32:C8:AD:D8 PowerState: on-disabling Jan 11 16:19:13 volumio2 bthelper[669]: Changing power off succeeded Jan 11 16:19:13 volumio2 bthelper[669]: [CHG] Controller DC:A6:32:C8:AD:D8 PowerState: off Jan 11 16:19:13 volumio2 bthelper[669]: [CHG] Controller DC:A6:32:C8:AD:D8 Powered: no Jan 11 16:19:13 volumio2 bthelper[669]: [CHG] Controller DC:A6:32:C8:AD:D8 Discovering: no Jan 11 16:19:13 volumio2 bthelper[669]: [CHG] Controller DC:A6:32:C8:AD:D8 Class: 0x00000000 (0) Jan 11 16:19:13 volumio2 bthelper[669]: [NEW] Media /org/bluez/hci0 Jan 11 16:19:13 volumio2 bthelper[669]: SupportedUUIDs: 0000110a-0000-1000-8000-00805f9b34fb Jan 11 16:19:13 volumio2 bthelper[669]: SupportedUUIDs: 0000110b-0000-1000-8000-00805f9b34fb Jan 11 16:19:13 volumio2 bthelper[669]: [CHG] Controller DC:A6:32:C8:AD:D8 PowerState: off-enabling Jan 11 16:19:13 volumio2 bthelper[669]: hci0 class of device changed: 0x00041c Jan 11 16:19:13 volumio2 bthelper[669]: [CHG] Controller DC:A6:32:C8:AD:D8 Class: 0x0000041c (1052) Jan 11 16:19:13 volumio2 bthelper[669]: hci0 new_settings: powered ssp br/edr le secure-conn Jan 11 16:19:13 volumio2 bthelper[669]: Changing power on succeeded Jan 11 16:19:14 volumio2 wireless.js[567]: trying... Jan 11 16:19:14 volumio2 sudo[906]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Jan 11 16:19:14 volumio2 sudo[906]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 11 16:19:14 volumio2 sudo[906]: pam_unix(sudo:session): session closed for user root Jan 11 16:19:15 volumio2 wireless.js[567]: trying... Jan 11 16:19:15 volumio2 sudo[909]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Jan 11 16:19:15 volumio2 sudo[909]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 11 16:19:15 volumio2 sudo[909]: pam_unix(sudo:session): session closed for user root Jan 11 16:19:16 volumio2 dhcpcd[652]: eth0: using static address 192.168.1.192/24 Jan 11 16:19:16 volumio2 avahi-daemon[573]: Joining mDNS multicast group on interface eth0.IPv4 with address 192.168.1.192. Jan 11 16:19:16 volumio2 avahi-daemon[573]: New relevant interface eth0.IPv4 for mDNS. Jan 11 16:19:16 volumio2 dhcpcd[652]: eth0: adding route to 192.168.1.0/24 Jan 11 16:19:16 volumio2 dhcpcd[652]: eth0: adding default route via 192.168.1.1 Jan 11 16:19:16 volumio2 avahi-daemon[573]: Registering new address record for 192.168.1.192 on eth0.IPv4. Jan 11 16:19:16 volumio2 wireless.js[567]: trying... Jan 11 16:19:16 volumio2 sudo[932]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Jan 11 16:19:16 volumio2 sudo[932]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 11 16:19:16 volumio2 sudo[932]: pam_unix(sudo:session): session closed for user root Jan 11 16:19:17 volumio2 wireless.js[567]: trying... Jan 11 16:19:17 volumio2 sudo[935]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Jan 11 16:19:17 volumio2 sudo[935]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 11 16:19:17 volumio2 sudo[935]: pam_unix(sudo:session): session closed for user root Jan 11 16:19:17 volumio2 wpa_supplicant[873]: wlan0: Trying to associate with SSID 'TALKTALKCF5951' Jan 11 16:19:17 volumio2 wpa_supplicant[873]: wlan0: Associated with 34:db:9c:cf:59:4e Jan 11 16:19:17 volumio2 wpa_supplicant[873]: wlan0: CTRL-EVENT-CONNECTED - Connection to 34:db:9c:cf:59:4e completed [id=0 id_str=] Jan 11 16:19:17 volumio2 dhcpcd[652]: wlan0: carrier acquired Jan 11 16:19:17 volumio2 wpa_supplicant[873]: wlan0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0 Jan 11 16:19:17 volumio2 dhcpcd[652]: wlan0: connected to Access Point `TALKTALKCF5951' Jan 11 16:19:17 volumio2 dhcpcd[652]: wlan0: IAID 32:c8:ad:d7 Jan 11 16:19:17 volumio2 dhcpcd[652]: wlan0: adding address fe80::dea6:32ff:fec8:add7 Jan 11 16:19:17 volumio2 dhcpcd[652]: ipv6_addaddr1: Permission denied Jan 11 16:19:18 volumio2 volumio-time-update[576]: volumio-time-update-util: Fetching time from Volumio... Jan 11 16:19:18 volumio2 wireless.js[567]: trying... Jan 11 16:19:18 volumio2 sudo[944]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Jan 11 16:19:18 volumio2 sudo[944]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 11 16:19:18 volumio2 sudo[944]: pam_unix(sudo:session): session closed for user root Jan 11 16:19:18 volumio2 volumio-time-update[576]: volumio-time-update-util: Setting system time to: 2026-01-11 16:19:41 Jan 11 16:19:18 volumio2 sudo[947]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/bin/timedatectl set-time 2026-01-11 16:19:41 Jan 11 16:19:18 volumio2 sudo[947]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 11 16:19:18 volumio2 dhcpcd[652]: wlan0: soliciting an IPv6 router Jan 11 16:19:18 volumio2 dbus-daemon[579]: [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service' requested by ':1.8' (uid=0 pid=948 comm="timedatectl set-time 2026-01-11 16:19:41 ") Jan 11 16:19:18 volumio2 systemd[1]: Starting Time & Date Service... Jan 11 16:19:18 volumio2 dbus-daemon[579]: [system] Successfully activated service 'org.freedesktop.timedate1' Jan 11 16:19:18 volumio2 systemd[1]: Started Time & Date Service. Jan 11 16:19:41 volumio2 systemd-timedated[949]: Changed local time to Sun Jan 11 16:19:41 2026 Jan 11 16:19:41 volumio2 sudo[947]: pam_unix(sudo:session): session closed for user root Jan 11 16:19:41 volumio2 volumio-time-update[576]: volumio-time-update-util: System time updated successfully. Jan 11 16:19:41 volumio2 systemd[1]: Started Volumio Time Update Utility. Jan 11 16:19:41 volumio2 dhcpcd[652]: wlan0: rebinding lease of 192.168.1.199 Jan 11 16:19:41 volumio2 dhcpcd[652]: wlan0: probing address 192.168.1.199/24 Jan 11 16:19:41 volumio2 ntpd[787]: Listen normally on 3 eth0 192.168.1.192:123 Jan 11 16:19:41 volumio2 ntpd[787]: new interface(s) found: waking up resolver Jan 11 16:19:41 volumio2 wireless.js[567]: trying... Jan 11 16:19:41 volumio2 sudo[951]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Jan 11 16:19:41 volumio2 sudo[951]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 11 16:19:41 volumio2 sudo[951]: pam_unix(sudo:session): session closed for user root Jan 11 16:19:42 volumio2 nmbd[738]: [2026/01/11 16:19:42.123491, 0] ../lib/util/become_daemon.c:138(daemon_ready) Jan 11 16:19:42 volumio2 nmbd[738]: daemon_ready: STATUS=daemon 'nmbd' finished starting up and ready to serve connections Jan 11 16:19:42 volumio2 systemd[1]: Started Samba NMB Daemon. Jan 11 16:19:42 volumio2 systemd[1]: Starting Samba Winbind Daemon... Jan 11 16:19:42 volumio2 winbindd[953]: [2026/01/11 16:19:42.389780, 0] ../source3/winbindd/winbindd_cache.c:3160(initialize_winbindd_cache) Jan 11 16:19:42 volumio2 winbindd[953]: initialize_winbindd_cache: clearing cache and re-creating with version number 2 Jan 11 16:19:42 volumio2 winbindd[953]: [2026/01/11 16:19:42.403813, 0] ../lib/util/become_daemon.c:138(daemon_ready) Jan 11 16:19:42 volumio2 winbindd[953]: daemon_ready: STATUS=daemon 'winbindd' finished starting up and ready to serve connections Jan 11 16:19:42 volumio2 systemd[1]: Started Samba Winbind Daemon. Jan 11 16:19:42 volumio2 systemd[1]: Starting Samba SMB Daemon... Jan 11 16:19:42 volumio2 wireless.js[567]: trying... Jan 11 16:19:42 volumio2 sudo[963]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Jan 11 16:19:42 volumio2 sudo[963]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 11 16:19:42 volumio2 sudo[963]: pam_unix(sudo:session): session closed for user root Jan 11 16:19:42 volumio2 smbd[958]: [2026/01/11 16:19:42.783543, 0] ../lib/util/become_daemon.c:138(daemon_ready) Jan 11 16:19:42 volumio2 smbd[958]: daemon_ready: STATUS=daemon 'smbd' finished starting up and ready to serve connections Jan 11 16:19:42 volumio2 systemd[1]: Started Samba SMB Daemon. Jan 11 16:19:42 volumio2 volumio-remote-updater[566]: [2026-01-11 16:19:42] [info] asio async_connect error: system:111 (Connection refused) Jan 11 16:19:42 volumio2 volumio-remote-updater[566]: [2026-01-11 16:19:42] [info] Error getting remote endpoint: system:107 (Transport endpoint is not connected) Jan 11 16:19:42 volumio2 volumio-remote-updater[566]: [2026-01-11 16:19:42] [error] handle_connect error: Underlying Transport Error Jan 11 16:19:43 volumio2 wireless.js[567]: trying... Jan 11 16:19:43 volumio2 sudo[970]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Jan 11 16:19:43 volumio2 sudo[970]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 11 16:19:43 volumio2 sudo[970]: pam_unix(sudo:session): session closed for user root Jan 11 16:19:44 volumio2 wireless.js[567]: trying... Jan 11 16:19:44 volumio2 sudo[973]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Jan 11 16:19:44 volumio2 sudo[973]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 11 16:19:44 volumio2 sudo[973]: pam_unix(sudo:session): session closed for user root Jan 11 16:19:45 volumio2 wireless.js[567]: trying... Jan 11 16:19:45 volumio2 sudo[976]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Jan 11 16:19:45 volumio2 sudo[976]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 11 16:19:45 volumio2 sudo[976]: pam_unix(sudo:session): session closed for user root Jan 11 16:19:46 volumio2 dhcpcd[652]: wlan0: leased 192.168.1.199 for 86400 seconds Jan 11 16:19:46 volumio2 avahi-daemon[573]: Joining mDNS multicast group on interface wlan0.IPv4 with address 192.168.1.199. Jan 11 16:19:46 volumio2 avahi-daemon[573]: New relevant interface wlan0.IPv4 for mDNS. Jan 11 16:19:46 volumio2 dhcpcd[652]: wlan0: adding route to 192.168.1.0/24 Jan 11 16:19:46 volumio2 dhcpcd[652]: wlan0: adding default route via 192.168.1.1 Jan 11 16:19:46 volumio2 avahi-daemon[573]: Registering new address record for 192.168.1.199 on wlan0.IPv4. Jan 11 16:19:46 volumio2 wireless.js[567]: trying... Jan 11 16:19:46 volumio2 sudo[1000]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Jan 11 16:19:46 volumio2 sudo[1000]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 11 16:19:46 volumio2 sudo[1000]: pam_unix(sudo:session): session closed for user root Jan 11 16:19:46 volumio2 wireless.js[567]: Connected to: ----TALKTALKCF5951 Jan 11 16:19:46 volumio2 wireless.js[567]: ---- Jan 11 16:19:46 volumio2 sudo[1003]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 11 16:19:46 volumio2 sudo[1003]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 11 16:19:46 volumio2 sudo[1003]: pam_unix(sudo:session): session closed for user root Jan 11 16:19:46 volumio2 wireless.js[567]: ... joined AP, wlan0 IPv4 is 192.168.1.199, ipV6 is undefined Jan 11 16:19:46 volumio2 wireless.js[567]: It's done! AP Jan 11 16:19:46 volumio2 kernel: brcmfmac: brcmf_cfg80211_set_power_mgmt: power save disabled Jan 11 16:19:46 volumio2 systemd[1]: Started Wireless Services. Jan 11 16:19:46 volumio2 systemd[1]: Started Volumio Backend Module. Jan 11 16:19:46 volumio2 systemd[1]: Started Volumio Cpu Tweaker. Jan 11 16:19:46 volumio2 systemd[1]: Reached target Multi-User System. Jan 11 16:19:46 volumio2 systemd[1]: Reached target Graphical Interface. Jan 11 16:19:46 volumio2 systemd[1]: Starting Update UTMP about System Runlevel Changes... Jan 11 16:19:46 volumio2 systemd[1]: systemd-update-utmp-runlevel.service: Succeeded. Jan 11 16:19:46 volumio2 systemd[1]: Started Update UTMP about System Runlevel Changes. Jan 11 16:19:46 volumio2 systemd[1]: Startup finished in 12.265s (kernel) + 20.470s (userspace) = 32.735s. Jan 11 16:19:46 volumio2 volumio-cpu-tweak[1009]: Setting RT Priority for mpd Jan 11 16:19:46 volumio2 volumio-cpu-tweak[1009]: pid 35's current scheduling policy: SCHED_OTHER Jan 11 16:19:46 volumio2 volumio-cpu-tweak[1009]: pid 35's current scheduling priority: 0 Jan 11 16:19:46 volumio2 volumio-cpu-tweak[1009]: Setting MPD Affinity Jan 11 16:19:46 volumio2 volumio-cpu-tweak[1009]: pid 3's current affinity mask: f Jan 11 16:19:46 volumio2 volumio-cpu-tweak[1009]: /bin/volumio_cpu_tweak: line 27: warning: command substitution: ignored null byte in input Jan 11 16:19:46 volumio2 volumio-cpu-tweak[1009]: VOLUMIO CPU TWEAK: Setting CPU Governor: performance Jan 11 16:19:47 volumio2 systemd[1]: volumio_cpu_tweak.service: Succeeded. Jan 11 16:19:47 volumio2 ntpd[787]: Listen normally on 4 wlan0 192.168.1.199:123 Jan 11 16:19:47 volumio2 ntpd[787]: new interface(s) found: waking up resolver Jan 11 16:19:48 volumio2 volumio[1008]: info: ------------------------------------------- Jan 11 16:19:48 volumio2 volumio[1008]: info: ----- Volumio3 ---- Jan 11 16:19:48 volumio2 volumio[1008]: info: ------------------------------------------- Jan 11 16:19:48 volumio2 volumio[1008]: info: ----- System startup ---- Jan 11 16:19:48 volumio2 volumio[1008]: info: ------------------------------------------- Jan 11 16:19:49 volumio2 volumio[1008]: info: MYVOLUMIO Environment detected Jan 11 16:19:49 volumio2 volumio[1008]: info: Plugin folders cleanup Jan 11 16:19:49 volumio2 volumio[1008]: info: Scanning into folder /volumio/app/plugins/ Jan 11 16:19:49 volumio2 volumio[1008]: info: Scanning category audio_interface Jan 11 16:19:49 volumio2 volumio[1008]: info: Scanning category miscellanea Jan 11 16:19:49 volumio2 volumio[1008]: info: Scanning category music_service Jan 11 16:19:49 volumio2 volumio[1008]: info: Scanning category plugins.json Jan 11 16:19:49 volumio2 volumio[1008]: info: Scanning category system_controller Jan 11 16:19:49 volumio2 volumio[1008]: info: Scanning category user_interface Jan 11 16:19:49 volumio2 volumio[1008]: info: Scanning into folder /data/plugins/ Jan 11 16:19:49 volumio2 volumio[1008]: info: Scanning category music_service Jan 11 16:19:49 volumio2 volumio[1008]: info: Scanning category system_hardware Jan 11 16:19:49 volumio2 volumio[1008]: info: Plugin folders cleanup completed Jan 11 16:19:49 volumio2 volumio[1008]: info: ------------------------------------------- Jan 11 16:19:49 volumio2 volumio[1008]: info: ----- Core plugins startup ---- Jan 11 16:19:49 volumio2 volumio[1008]: info: ------------------------------------------- Jan 11 16:19:49 volumio2 volumio[1008]: info: Loading plugins from folder /volumio/app/plugins/ Jan 11 16:19:49 volumio2 volumio[1008]: info: Adding plugin upnp to MyMusic Plugins Jan 11 16:19:49 volumio2 volumio[1008]: info: Adding plugin airplay_emulation to MyMusic Plugins Jan 11 16:19:49 volumio2 volumio[1008]: info: Adding plugin upnp_browser to MyMusic Plugins Jan 11 16:19:49 volumio2 volumio[1008]: info: Loading plugins from folder /data/plugins/ Jan 11 16:19:49 volumio2 volumio[1008]: info: Loading plugin "system"... Jan 11 16:19:49 volumio2 volumio[1008]: info: Loading plugin "appearance"... Jan 11 16:19:50 volumio2 volumio[1008]: info: Loading plugin "network"... Jan 11 16:19:50 volumio2 volumio[1008]: info: Refreshing Cached IP Addresses Jan 11 16:19:50 volumio2 sudo[1040]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 11 16:19:50 volumio2 sudo[1040]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 11 16:19:50 volumio2 sudo[1040]: pam_unix(sudo:session): session closed for user root Jan 11 16:19:50 volumio2 sudo[1042]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 11 16:19:50 volumio2 sudo[1042]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 11 16:19:50 volumio2 sudo[1042]: pam_unix(sudo:session): session closed for user root Jan 11 16:19:50 volumio2 volumio[1008]: info: Loading plugin "services"... Jan 11 16:19:50 volumio2 volumio[1008]: info: Loading plugin "alsa_controller"... Jan 11 16:19:50 volumio2 sudo[1051]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Jan 11 16:19:50 volumio2 sudo[1051]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 11 16:19:50 volumio2 volumio[1008]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 11 16:19:50 volumio2 volumio[1008]: info: Loading plugin "wizard"... Jan 11 16:19:50 volumio2 volumio[1008]: info: Loading plugin "networkfs"... Jan 11 16:19:50 volumio2 volumio[1008]: info: Starting Udev Watcher for removable devices Jan 11 16:19:50 volumio2 sudo[1068]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=JLH,password=astra18,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //192.168.1.6/music /mnt/NAS/DS116 Jan 11 16:19:50 volumio2 sudo[1068]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 11 16:19:50 volumio2 sudo[1070]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=JLH64,password=124_Astrib!,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //192.168.1.250/music /mnt/NAS/DS124 Jan 11 16:19:50 volumio2 sudo[1070]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 11 16:19:50 volumio2 volumio[1008]: info: Ignoring mount for partition: boot Jan 11 16:19:50 volumio2 volumio[1008]: info: Ignoring mount for partition: volumio Jan 11 16:19:50 volumio2 volumio[1008]: info: Ignoring mount for partition: volumio_data Jan 11 16:19:50 volumio2 volumio[1008]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 11 16:19:50 volumio2 volumio[1008]: info: Loading plugin "volumio_command_line_client"... Jan 11 16:19:50 volumio2 volumio[1008]: info: Loading plugin "upnp"... Jan 11 16:19:50 volumio2 volumio[1008]: info: [1768148390671] Starting Upmpd Daemon Jan 11 16:19:50 volumio2 volumio[1008]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 11 16:19:50 volumio2 volumio[1008]: info: Loading plugin "my_music"... Jan 11 16:19:50 volumio2 volumio[1008]: info: Loading plugin "mpd"... Jan 11 16:19:50 volumio2 kernel: Key type cifs.spnego registered Jan 11 16:19:50 volumio2 kernel: Key type cifs.idmap registered Jan 11 16:19:50 volumio2 kernel: CIFS: No dialect specified on mount. Default has changed to a more secure dialect, SMB2.1 or later (e.g. SMB3.1.1), from CIFS (SMB1). To use the less secure SMB1 dialect to access old servers which do not support SMB3.1.1 (or even SMB3 or SMB2.1) specify vers=1.0 on mount. Jan 11 16:19:50 volumio2 kernel: CIFS: Attempting to mount //192.168.1.250/music Jan 11 16:19:50 volumio2 sudo[1070]: pam_unix(sudo:session): session closed for user root Jan 11 16:19:50 volumio2 kernel: CIFS: Attempting to mount //192.168.1.6/music Jan 11 16:19:51 volumio2 volumio[1008]: info: Loading plugin "upnp_browser"... Jan 11 16:19:51 volumio2 volumio[1008]: info: Starting UPNP Browser Jan 11 16:19:51 volumio2 volumio[1008]: info: Loading plugin "alarm-clock"... Jan 11 16:19:51 volumio2 volumio[1008]: info: Loading plugin "airplay_emulation"... Jan 11 16:19:51 volumio2 volumio[1008]: info: Starting Shairport Sync Jan 11 16:19:51 volumio2 volumio[1008]: info: Loading plugin "last_100"... Jan 11 16:19:51 volumio2 volumio[1008]: info: Loading plugin "webradio"... Jan 11 16:19:51 volumio2 volumio[1008]: info: Loading plugin "i2s_dacs"... Jan 11 16:19:51 volumio2 volumio[1008]: info: Loading plugin "volumiodiscovery"... Jan 11 16:19:51 volumio2 volumio[1008]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jan 11 16:19:51 volumio2 volumio[1008]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 11 16:19:51 volumio2 node[1008]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jan 11 16:19:51 volumio2 volumio[1008]: *** WARNING *** For more information see Jan 11 16:19:51 volumio2 volumio[1008]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jan 11 16:19:51 volumio2 volumio[1008]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 11 16:19:51 volumio2 volumio[1008]: *** WARNING *** For more information see Jan 11 16:19:51 volumio2 node[1008]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 11 16:19:51 volumio2 node[1008]: *** WARNING *** For more information see Jan 11 16:19:51 volumio2 node[1008]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jan 11 16:19:51 volumio2 node[1008]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 11 16:19:51 volumio2 node[1008]: *** WARNING *** For more information see Jan 11 16:19:51 volumio2 volumio[1008]: info: Applying required configuration parameters for plugin volumiodiscovery Jan 11 16:19:51 volumio2 volumio[1008]: info: Discovery: Started advertising with name: Volumio2 Jan 11 16:19:51 volumio2 volumio[1008]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 11 16:19:51 volumio2 volumio[1008]: info: Loading plugin "soundcloud"... Jan 11 16:19:52 volumio2 volumio[1008]: info: Loading plugin "spop"... Jan 11 16:19:52 volumio2 volumio-remote-updater[566]: [2026-01-11 16:19:52] [connect] Successful connection Jan 11 16:19:52 volumio2 volumio[1008]: info: Loading plugin "outputs"... Jan 11 16:19:52 volumio2 volumio[1008]: info: Loading plugin "albumart"... Jan 11 16:19:53 volumio2 volumio[1008]: info: Plugin example_plugin is not enabled Jan 11 16:19:53 volumio2 volumio[1008]: info: Loading plugin "inputs"... Jan 11 16:19:53 volumio2 volumio[1008]: info: Loading plugin "updater_comm"... Jan 11 16:19:53 volumio2 volumio[1008]: info: Plugin mpdemulation is not enabled Jan 11 16:19:53 volumio2 volumio[1008]: info: Loading plugin "rest_api"... Jan 11 16:19:53 volumio2 volumio[1008]: info: Loading plugin "websocket"... Jan 11 16:19:53 volumio2 volumio[1008]: info: Starting Socket.io Server version 2.3.0 Jan 11 16:19:53 volumio2 volumio[1008]: info: Loading plugin "radio_paradise"... Jan 11 16:19:53 volumio2 volumio[1008]: Forking 3 albumart workers Jan 11 16:19:53 volumio2 volumio[1008]: info: Applying required configuration parameters for plugin radio_paradise Jan 11 16:19:53 volumio2 volumio[1008]: info: [1768148393512] [RadioParadise] API delay: 5 Jan 11 16:19:53 volumio2 volumio[1008]: info: Loading plugin "ir_controller"... Jan 11 16:19:53 volumio2 volumio[1008]: info: Applying required configuration parameters for plugin ir_controller Jan 11 16:19:53 volumio2 volumio[1008]: info: Loading i18n strings for locale en Jan 11 16:19:53 volumio2 volumio[1008]: Updating browse sources language Jan 11 16:19:53 volumio2 volumio[1008]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 11 16:19:53 volumio2 volumio[1008]: Starting albumart workers Jan 11 16:19:53 volumio2 volumio[1008]: Starting albumart workers Jan 11 16:19:53 volumio2 volumio[1008]: Starting albumart workers Jan 11 16:19:54 volumio2 volumio[1008]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 11 16:19:54 volumio2 volumio[1008]: info: CoreCommandRouter::initPlayerControls Jan 11 16:19:54 volumio2 volumio[1008]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 16:19:54 volumio2 volumio[1008]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 16:19:54 volumio2 volumio[1008]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 16:19:54 volumio2 volumio[1008]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 16:19:54 volumio2 volumio[1008]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 16:19:54 volumio2 volumio[1008]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 16:19:54 volumio2 volumio[1008]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 16:19:54 volumio2 volumio[1008]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 16:19:54 volumio2 volumio[1008]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 11 16:19:54 volumio2 volumio[1008]: Express server listening on port 3000 Jan 11 16:19:54 volumio2 volumio[1008]: [Metrics] WebUI: 6s 94.99ms Jan 11 16:19:54 volumio2 sudo[1051]: pam_unix(sudo:session): session closed for user root Jan 11 16:19:54 volumio2 volumio[1008]: info: CoreStateMachine::resetVolumioState Jan 11 16:19:54 volumio2 volumio[1008]: info: CoreStateMachine::getcurrentVolume Jan 11 16:19:54 volumio2 volumio[1008]: info: CoreCommandRouter::volumioRetrievevolume Jan 11 16:19:54 volumio2 volumio[1008]: info: Volumio Network Manager: Network status updated: 3 Jan 11 16:19:54 volumio2 volumio[1008]: verbose: New Socket.io Connection to 192.168.1.192 from 192.168.1.252 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:146.0) Gecko/20100101 Firefox/146.0 Engine version: 3 Transport: polling Total Clients: 1 Jan 11 16:19:54 volumio2 volumio[1008]: verbose: New Socket.io Connection to 192.168.1.199 from 192.168.1.252 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:146.0) Gecko/20100101 Firefox/146.0 Engine version: 3 Transport: polling Total Clients: 2 Jan 11 16:19:54 volumio2 volumio[1008]: verbose: New Socket.io Connection to 192.168.1.192 from 192.168.1.252 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:146.0) Gecko/20100101 Firefox/146.0 Engine version: 3 Transport: polling Total Clients: 3 Jan 11 16:19:54 volumio2 volumio[1008]: verbose: New Socket.io Connection to 192.168.1.199 from 192.168.1.252 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:146.0) Gecko/20100101 Firefox/146.0 Engine version: 3 Transport: polling Total Clients: 4 Jan 11 16:19:54 volumio2 volumio[1008]: verbose: New Socket.io Connection to 192.168.1.192 from 192.168.1.252 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:146.0) Gecko/20100101 Firefox/146.0 Engine version: 3 Transport: polling Total Clients: 5 Jan 11 16:19:54 volumio2 volumio[1008]: verbose: New Socket.io Connection to 192.168.1.192 from 192.168.1.252 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:146.0) Gecko/20100101 Firefox/146.0 Engine version: 3 Transport: polling Total Clients: 6 Jan 11 16:19:54 volumio2 volumio[1008]: verbose: New Socket.io Connection to 192.168.1.192 from 192.168.1.252 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:146.0) Gecko/20100101 Firefox/146.0 Engine version: 3 Transport: polling Total Clients: 7 Jan 11 16:19:54 volumio2 volumio[1008]: verbose: New Socket.io Connection to 192.168.1.192 from 192.168.1.252 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:146.0) Gecko/20100101 Firefox/146.0 Engine version: 3 Transport: polling Total Clients: 8 Jan 11 16:19:54 volumio2 volumio[1008]: verbose: New Socket.io Connection to 192.168.1.192 from 192.168.1.252 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:146.0) Gecko/20100101 Firefox/146.0 Engine version: 3 Transport: polling Total Clients: 9 Jan 11 16:19:54 volumio2 volumio[1008]: verbose: New Socket.io Connection to 192.168.1.192 from 192.168.1.252 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:146.0) Gecko/20100101 Firefox/146.0 Engine version: 3 Transport: polling Total Clients: 10 Jan 11 16:19:54 volumio2 volumio[1008]: verbose: New Socket.io Connection to 192.168.1.199 from 192.168.1.252 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:146.0) Gecko/20100101 Firefox/146.0 Engine version: 3 Transport: polling Total Clients: 11 Jan 11 16:19:54 volumio2 volumio[1008]: verbose: New Socket.io Connection to 192.168.1.199 from 192.168.1.252 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:146.0) Gecko/20100101 Firefox/146.0 Engine version: 3 Transport: polling Total Clients: 12 Jan 11 16:19:54 volumio2 volumio[1008]: verbose: New Socket.io Connection to 192.168.1.192 from 192.168.1.252 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:146.0) Gecko/20100101 Firefox/146.0 Engine version: 3 Transport: polling Total Clients: 13 Jan 11 16:19:54 volumio2 volumio[1008]: verbose: New Socket.io Connection to 192.168.1.192 from 192.168.1.252 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:146.0) Gecko/20100101 Firefox/146.0 Engine version: 3 Transport: polling Total Clients: 14 Jan 11 16:19:54 volumio2 volumio[1008]: verbose: New Socket.io Connection to 192.168.1.192 from 192.168.1.252 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:146.0) Gecko/20100101 Firefox/146.0 Engine version: 3 Transport: polling Total Clients: 15 Jan 11 16:19:54 volumio2 volumio[1008]: verbose: New Socket.io Connection to 192.168.1.192 from 192.168.1.252 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:146.0) Gecko/20100101 Firefox/146.0 Engine version: 3 Transport: polling Total Clients: 16 Jan 11 16:19:54 volumio2 volumio[1008]: verbose: New Socket.io Connection to 192.168.1.192 from 192.168.1.252 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:146.0) Gecko/20100101 Firefox/146.0 Engine version: 3 Transport: polling Total Clients: 17 Jan 11 16:19:54 volumio2 volumio[1008]: verbose: New Socket.io Connection to 192.168.1.199 from 192.168.1.252 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:146.0) Gecko/20100101 Firefox/146.0 Engine version: 3 Transport: polling Total Clients: 18 Jan 11 16:19:54 volumio2 volumio[1008]: verbose: New Socket.io Connection to 192.168.1.199 from 192.168.1.252 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:146.0) Gecko/20100101 Firefox/146.0 Engine version: 3 Transport: polling Total Clients: 19 Jan 11 16:19:54 volumio2 volumio[1008]: verbose: New Socket.io Connection to 192.168.1.199 from 192.168.1.252 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:146.0) Gecko/20100101 Firefox/146.0 Engine version: 3 Transport: polling Total Clients: 20 Jan 11 16:19:54 volumio2 volumio[1008]: verbose: New Socket.io Connection to 192.168.1.199 from 192.168.1.252 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:146.0) Gecko/20100101 Firefox/146.0 Engine version: 3 Transport: polling Total Clients: 21 Jan 11 16:19:54 volumio2 volumio-remote-updater[566]: [2026-01-11 16:19:54] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1768148392 101 Jan 11 16:19:54 volumio2 volumio[1008]: 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: 22 Jan 11 16:19:54 volumio2 volumio[1008]: verbose: New Socket.io Connection to 192.168.1.192 from 192.168.1.252 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:146.0) Gecko/20100101 Firefox/146.0 Engine version: 3 Transport: polling Total Clients: 23 Jan 11 16:19:54 volumio2 volumio[1008]: verbose: New Socket.io Connection to 192.168.1.199 from 192.168.1.252 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:146.0) Gecko/20100101 Firefox/146.0 Engine version: 3 Transport: polling Total Clients: 24 Jan 11 16:19:54 volumio2 volumio[1008]: verbose: New Socket.io Connection to 192.168.1.192 from 192.168.1.252 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:146.0) Gecko/20100101 Firefox/146.0 Engine version: 3 Transport: polling Total Clients: 25 Jan 11 16:19:54 volumio2 volumio[1008]: verbose: New Socket.io Connection to 192.168.1.199 from 192.168.1.252 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:146.0) Gecko/20100101 Firefox/146.0 Engine version: 3 Transport: polling Total Clients: 26 Jan 11 16:19:54 volumio2 volumio[1008]: verbose: New Socket.io Connection to 192.168.1.192 from 192.168.1.252 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:146.0) Gecko/20100101 Firefox/146.0 Engine version: 3 Transport: polling Total Clients: 27 Jan 11 16:19:54 volumio2 volumio[1008]: verbose: New Socket.io Connection to 192.168.1.192 from 192.168.1.252 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:146.0) Gecko/20100101 Firefox/146.0 Engine version: 3 Transport: polling Total Clients: 28 Jan 11 16:19:54 volumio2 volumio[1008]: verbose: New Socket.io Connection to 192.168.1.192 from 192.168.1.252 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:146.0) Gecko/20100101 Firefox/146.0 Engine version: 3 Transport: polling Total Clients: 29 Jan 11 16:19:54 volumio2 volumio[1008]: verbose: New Socket.io Connection to 192.168.1.192 from 192.168.1.252 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:146.0) Gecko/20100101 Firefox/146.0 Engine version: 3 Transport: polling Total Clients: 30 Jan 11 16:19:54 volumio2 volumio[1008]: verbose: New Socket.io Connection to 192.168.1.199 from 192.168.1.252 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:146.0) Gecko/20100101 Firefox/146.0 Engine version: 3 Transport: polling Total Clients: 31 Jan 11 16:19:54 volumio2 volumio[1008]: verbose: New Socket.io Connection to 192.168.1.199 from 192.168.1.252 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:146.0) Gecko/20100101 Firefox/146.0 Engine version: 3 Transport: polling Total Clients: 32 Jan 11 16:19:54 volumio2 volumio[1008]: verbose: New Socket.io Connection to 192.168.1.199 from 192.168.1.252 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:146.0) Gecko/20100101 Firefox/146.0 Engine version: 3 Transport: polling Total Clients: 33 Jan 11 16:19:54 volumio2 volumio[1008]: verbose: New Socket.io Connection to 192.168.1.199 from 192.168.1.252 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:146.0) Gecko/20100101 Firefox/146.0 Engine version: 3 Transport: polling Total Clients: 34 Jan 11 16:19:54 volumio2 volumio[1008]: verbose: New Socket.io Connection to 192.168.1.199 from 192.168.1.252 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:146.0) Gecko/20100101 Firefox/146.0 Engine version: 3 Transport: polling Total Clients: 35 Jan 11 16:19:54 volumio2 volumio[1008]: verbose: New Socket.io Connection to 192.168.1.199 from 192.168.1.252 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:146.0) Gecko/20100101 Firefox/146.0 Engine version: 3 Transport: polling Total Clients: 36 Jan 11 16:19:54 volumio2 volumio[1008]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 11 16:19:54 volumio2 volumio[1008]: info: Reloading queue from file Jan 11 16:19:54 volumio2 volumio[1008]: verbose: New Socket.io Connection to 192.168.1.199 from 192.168.1.252 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:146.0) Gecko/20100101 Firefox/146.0 Engine version: 3 Transport: polling Total Clients: 37 Jan 11 16:19:54 volumio2 volumio[1008]: verbose: New Socket.io Connection to 192.168.1.199 from 192.168.1.252 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:146.0) Gecko/20100101 Firefox/146.0 Engine version: 3 Transport: polling Total Clients: 38 Jan 11 16:19:54 volumio2 volumio[1008]: verbose: New Socket.io Connection to 192.168.1.199 from 192.168.1.252 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:146.0) Gecko/20100101 Firefox/146.0 Engine version: 3 Transport: polling Total Clients: 39 Jan 11 16:19:54 volumio2 volumio[1008]: verbose: New Socket.io Connection to 192.168.1.199 from 192.168.1.252 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:146.0) Gecko/20100101 Firefox/146.0 Engine version: 3 Transport: polling Total Clients: 40 Jan 11 16:19:54 volumio2 volumio[1008]: verbose: New Socket.io Connection to 192.168.1.199 from 192.168.1.252 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:146.0) Gecko/20100101 Firefox/146.0 Engine version: 3 Transport: polling Total Clients: 41 Jan 11 16:19:54 volumio2 volumio[1008]: verbose: New Socket.io Connection to 192.168.1.199 from 192.168.1.252 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:146.0) Gecko/20100101 Firefox/146.0 Engine version: 3 Transport: polling Total Clients: 42 Jan 11 16:19:54 volumio2 volumio[1008]: info: VolumeController:: Volume=13 Mute =false Jan 11 16:19:54 volumio2 volumio[1008]: info: CoreStateMachine::pushState Jan 11 16:19:54 volumio2 volumio[1008]: info: CorePlayQueue::getTrack 0 Jan 11 16:19:54 volumio2 volumio[1008]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 11 16:19:54 volumio2 volumio[1008]: info: CoreCommandRouter::volumioPushState Jan 11 16:19:54 volumio2 volumio[1008]: info: CoreStateMachine::updateTrackBlock Jan 11 16:19:54 volumio2 volumio[1008]: info: CorePlayQueue::getTrackBlock Jan 11 16:19:54 volumio2 volumio[1008]: info: CoreCommandRouter::volumioRetrievevolume Jan 11 16:19:54 volumio2 volumio[1008]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Jan 11 16:19:54 volumio2 volumio[1008]: info: USB Boot Capable - System SBC Revision found in cpuinfo: b03112 Jan 11 16:19:54 volumio2 volumio[1008]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Jan 11 16:19:54 volumio2 volumio[1008]: info: Setting Device type: Raspberry PI Jan 11 16:19:54 volumio2 volumio[1008]: info: CoreStateMachine::setRepeat null single undefined Jan 11 16:19:54 volumio2 volumio[1008]: info: CoreStateMachine::pushState Jan 11 16:19:54 volumio2 volumio[1008]: info: CorePlayQueue::getTrack 0 Jan 11 16:19:54 volumio2 volumio[1008]: info: CoreCommandRouter::volumioPushState Jan 11 16:19:54 volumio2 volumio[1008]: info: CoreStateMachine::setRandom null Jan 11 16:19:54 volumio2 volumio[1008]: info: CoreStateMachine::pushState Jan 11 16:19:54 volumio2 volumio[1008]: info: CorePlayQueue::getTrack 0 Jan 11 16:19:54 volumio2 volumio[1008]: info: CoreCommandRouter::volumioPushState Jan 11 16:19:54 volumio2 volumio[1008]: verbose: New Socket.io Connection to 192.168.1.199 from 192.168.1.252 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:146.0) Gecko/20100101 Firefox/146.0 Engine version: 3 Transport: polling Total Clients: 43 Jan 11 16:19:54 volumio2 volumio[1008]: verbose: New Socket.io Connection to 192.168.1.199 from 192.168.1.252 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:146.0) Gecko/20100101 Firefox/146.0 Engine version: 3 Transport: polling Total Clients: 44 Jan 11 16:19:54 volumio2 volumio[1008]: verbose: New Socket.io Connection to 192.168.1.199 from 192.168.1.252 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:146.0) Gecko/20100101 Firefox/146.0 Engine version: 3 Transport: polling Total Clients: 45 Jan 11 16:19:54 volumio2 volumio[1008]: verbose: New Socket.io Connection to 192.168.1.199 from 192.168.1.252 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:146.0) Gecko/20100101 Firefox/146.0 Engine version: 3 Transport: polling Total Clients: 46 Jan 11 16:19:54 volumio2 volumio[1008]: verbose: New Socket.io Connection to 192.168.1.199 from 192.168.1.252 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:146.0) Gecko/20100101 Firefox/146.0 Engine version: 3 Transport: polling Total Clients: 47 Jan 11 16:19:54 volumio2 volumio[1008]: verbose: New Socket.io Connection to 192.168.1.199 from 192.168.1.252 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:146.0) Gecko/20100101 Firefox/146.0 Engine version: 3 Transport: polling Total Clients: 48 Jan 11 16:19:54 volumio2 volumio[1008]: verbose: New Socket.io Connection to 192.168.1.199 from 192.168.1.252 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:146.0) Gecko/20100101 Firefox/146.0 Engine version: 3 Transport: polling Total Clients: 49 Jan 11 16:19:54 volumio2 volumio[1008]: verbose: New Socket.io Connection to 192.168.1.199 from 192.168.1.252 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:146.0) Gecko/20100101 Firefox/146.0 Engine version: 3 Transport: polling Total Clients: 50 Jan 11 16:19:54 volumio2 volumio[1008]: verbose: New Socket.io Connection to 192.168.1.192 from 192.168.1.252 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:146.0) Gecko/20100101 Firefox/146.0 Engine version: 3 Transport: polling Total Clients: 51 Jan 11 16:19:54 volumio2 volumio[1008]: verbose: New Socket.io Connection to 192.168.1.199 from 192.168.1.252 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:146.0) Gecko/20100101 Firefox/146.0 Engine version: 3 Transport: polling Total Clients: 52 Jan 11 16:19:54 volumio2 volumio[1008]: verbose: New Socket.io Connection to 192.168.1.199 from 192.168.1.252 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:146.0) Gecko/20100101 Firefox/146.0 Engine version: 3 Transport: polling Total Clients: 53 Jan 11 16:19:54 volumio2 volumio[1008]: verbose: New Socket.io Connection to 192.168.1.199 from 192.168.1.252 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:146.0) Gecko/20100101 Firefox/146.0 Engine version: 3 Transport: polling Total Clients: 54 Jan 11 16:19:54 volumio2 volumio[1008]: verbose: New Socket.io Connection to 192.168.1.199 from 192.168.1.252 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:146.0) Gecko/20100101 Firefox/146.0 Engine version: 3 Transport: polling Total Clients: 55 Jan 11 16:19:54 volumio2 volumio[1008]: verbose: New Socket.io Connection to 192.168.1.199 from 192.168.1.252 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:146.0) Gecko/20100101 Firefox/146.0 Engine version: 3 Transport: polling Total Clients: 56 Jan 11 16:19:54 volumio2 volumio[1008]: info: Discovery: adding 5a45eb55-60fe-402c-ae19-b8b113c7fdcb Jan 11 16:19:54 volumio2 volumio[1008]: info: Discovery: Found device Volumio2 Jan 11 16:19:54 volumio2 volumio[1008]: info: CoreCommandRouter::volumioGetState Jan 11 16:19:54 volumio2 volumio[1008]: info: CorePlayQueue::getTrack 0 Jan 11 16:19:54 volumio2 volumio[1008]: info: CoreCommandRouter::volumioGetState Jan 11 16:19:54 volumio2 volumio[1008]: info: CorePlayQueue::getTrack 0 Jan 11 16:19:54 volumio2 volumio[1008]: info: Discovery: this is already registered, 5a45eb55-60fe-402c-ae19-b8b113c7fdcb Jan 11 16:19:54 volumio2 volumio[1008]: info: Discovery: Found device Volumio2 Jan 11 16:19:54 volumio2 volumio[1008]: info: CoreCommandRouter::volumioGetState Jan 11 16:19:54 volumio2 volumio[1008]: info: CorePlayQueue::getTrack 0 Jan 11 16:19:54 volumio2 volumio[1008]: info: Received Get System Info Jan 11 16:19:54 volumio2 volumio[1008]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jan 11 16:19:54 volumio2 volumio[1008]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jan 11 16:19:54 volumio2 volumio[1008]: info: Discovery: Getting this device information Jan 11 16:19:54 volumio2 volumio[1008]: info: CoreCommandRouter::volumioGetState Jan 11 16:19:54 volumio2 volumio[1008]: info: CorePlayQueue::getTrack 0 Jan 11 16:19:54 volumio2 volumio[1008]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jan 11 16:19:54 volumio2 volumio[1008]: info: CoreCommandRouter::volumioGetState Jan 11 16:19:54 volumio2 volumio[1008]: info: CorePlayQueue::getTrack 0 Jan 11 16:19:54 volumio2 volumio[1008]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Jan 11 16:19:54 volumio2 volumio[1008]: info: CoreCommandRouter::volumioGetVisibleSources Jan 11 16:19:54 volumio2 volumio[1008]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 11 16:19:54 volumio2 volumio[1008]: info: CoreCommandRouter::volumioGetState Jan 11 16:19:54 volumio2 volumio[1008]: info: CorePlayQueue::getTrack 0 Jan 11 16:19:54 volumio2 volumio[1008]: info: CoreCommandRouter::volumioGetState Jan 11 16:19:54 volumio2 volumio[1008]: info: CorePlayQueue::getTrack 0 Jan 11 16:19:54 volumio2 volumio[1008]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Jan 11 16:19:54 volumio2 volumio[1008]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Jan 11 16:19:54 volumio2 volumio[1008]: info: Received Get System Info Jan 11 16:19:54 volumio2 volumio[1008]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jan 11 16:19:54 volumio2 volumio[1008]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jan 11 16:19:54 volumio2 volumio[1008]: info: Discovery: Getting this device information Jan 11 16:19:54 volumio2 volumio[1008]: info: CoreCommandRouter::volumioGetState Jan 11 16:19:54 volumio2 volumio[1008]: info: CorePlayQueue::getTrack 0 Jan 11 16:19:54 volumio2 volumio[1008]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jan 11 16:19:54 volumio2 volumio[1008]: info: CoreCommandRouter::volumioGetState Jan 11 16:19:54 volumio2 volumio[1008]: info: CorePlayQueue::getTrack 0 Jan 11 16:19:54 volumio2 volumio[1008]: info: Listing playlists Jan 11 16:19:54 volumio2 volumio[1008]: info: VolumeController:: Volume=13 Mute =false Jan 11 16:19:54 volumio2 volumio[1008]: info: CoreStateMachine::pushState Jan 11 16:19:54 volumio2 volumio[1008]: info: CorePlayQueue::getTrack 0 Jan 11 16:19:54 volumio2 volumio[1008]: info: CoreCommandRouter::volumioPushState Jan 11 16:19:55 volumio2 volumio[1008]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Jan 11 16:19:55 volumio2 volumio[1008]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Jan 11 16:19:56 volumio2 volumio[1008]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Jan 11 16:19:56 volumio2 volumio[1008]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Jan 11 16:19:57 volumio2 volumio[1008]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Jan 11 16:19:57 volumio2 sudo[1068]: pam_unix(sudo:session): session closed for user root Jan 11 16:19:57 volumio2 volumio[1008]: info: Cannot mount NAS DS116 at system boot, trial number 1 ,retrying in 5 seconds Jan 11 16:19:57 volumio2 volumio[1008]: info: Completed loading Core Plugins Jan 11 16:19:57 volumio2 volumio[1008]: info: Preparing to generate the ALSA configuration file Jan 11 16:19:57 volumio2 kernel: CIFS: VFS: Error connecting to socket. Aborting operation. Jan 11 16:19:57 volumio2 kernel: CIFS: VFS: cifs_mount failed w/return code = -113 Jan 11 16:19:57 volumio2 volumio[1008]: info: Asound.conf file unchanged, so no further update is needed Jan 11 16:19:57 volumio2 volumio[1008]: info: Output device has changed, restarting MPD Jan 11 16:19:57 volumio2 volumio[1008]: info: Output device has changed, restarting Shairport Sync Jan 11 16:19:57 volumio2 volumio[1008]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 16:19:57 volumio2 volumio[1008]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 11 16:19:57 volumio2 sudo[1178]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 11 16:19:57 volumio2 sudo[1178]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 11 16:19:57 volumio2 sudo[1178]: pam_unix(sudo:session): session closed for user root Jan 11 16:19:57 volumio2 sudo[1180]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 11 16:19:57 volumio2 sudo[1180]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 11 16:19:57 volumio2 volumio[1008]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 11 16:19:57 volumio2 volumio[1008]: info: ___________ START PLUGINS ___________ Jan 11 16:19:57 volumio2 volumio[1008]: info: ControllerMpd::onStart: Initializing MPD Jan 11 16:19:57 volumio2 volumio[1008]: info: Creating MPD Configuration file Jan 11 16:19:57 volumio2 volumio[1008]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 11 16:19:57 volumio2 volumio[1008]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 11 16:19:57 volumio2 volumio[1008]: info: [1768148397341] CoreMusicLibrary::Adding element Media Servers Jan 11 16:19:57 volumio2 volumio[1008]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 11 16:19:57 volumio2 sudo[1188]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 11 16:19:57 volumio2 sudo[1188]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 11 16:19:57 volumio2 sudo[1188]: pam_unix(sudo:session): session closed for user root Jan 11 16:19:57 volumio2 systemd[1]: Listening on mpd.socket. Jan 11 16:19:57 volumio2 systemd[1]: Starting Music Player Daemon... Jan 11 16:19:57 volumio2 volumio[1008]: info: UPNP Browser: Client initialized successfully Jan 11 16:19:57 volumio2 sudo[1190]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 11 16:19:57 volumio2 sudo[1190]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 11 16:19:57 volumio2 volumio[1008]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 16:19:57 volumio2 volumio[1008]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 11 16:19:57 volumio2 systemd[1]: mpd.service: Control process exited, code=killed, status=15/TERM Jan 11 16:19:57 volumio2 systemd[1]: mpd.service: Succeeded. Jan 11 16:19:57 volumio2 systemd[1]: Stopped Music Player Daemon. Jan 11 16:19:57 volumio2 systemd[1]: Starting Music Player Daemon... Jan 11 16:19:57 volumio2 volumio[1008]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 11 16:19:57 volumio2 volumio[1008]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 16:19:57 volumio2 volumio[1008]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 11 16:19:57 volumio2 volumio[1008]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 11 16:19:57 volumio2 volumio[1008]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 11 16:19:57 volumio2 volumio[1008]: info: [1768148397435] CoreMusicLibrary::Adding element Last_100 Jan 11 16:19:57 volumio2 volumio[1008]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 11 16:19:57 volumio2 volumio[1008]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 11 16:19:57 volumio2 volumio[1008]: info: [1768148397438] CoreMusicLibrary::Adding element Webradio Jan 11 16:19:57 volumio2 volumio[1008]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 11 16:19:57 volumio2 volumio[1008]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 11 16:19:57 volumio2 sudo[1197]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jan 11 16:19:57 volumio2 volumio[1008]: info: Initializing BBC Radios Jan 11 16:19:57 volumio2 sudo[1197]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 11 16:19:57 volumio2 sudo[1197]: /bin/chown: cannot access '/var/log/mpd.log': No such file or directory Jan 11 16:19:57 volumio2 sudo[1197]: pam_unix(sudo:session): session closed for user root Jan 11 16:19:57 volumio2 volumio[1008]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 11 16:19:57 volumio2 volumio[1008]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 11 16:19:57 volumio2 volumio[1008]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 11 16:19:57 volumio2 volumio[1008]: info: [1768148397499] CoreMusicLibrary::Adding element SoundCloud Jan 11 16:19:57 volumio2 volumio[1008]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 11 16:19:57 volumio2 volumio[1008]: Cannot find translation for source SoundCloud Jan 11 16:19:57 volumio2 volumio[1008]: info: Creating Spotify config file Jan 11 16:19:57 volumio2 volumio[1008]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 16:19:57 volumio2 volumio[1008]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 11 16:19:57 volumio2 volumio[1008]: info: [1768148397578] CoreMusicLibrary::Adding element Radio Paradise Jan 11 16:19:57 volumio2 volumio[1008]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 11 16:19:57 volumio2 volumio[1008]: Cannot find translation for source SoundCloud Jan 11 16:19:57 volumio2 volumio[1008]: Cannot find translation for source Radio Paradise Jan 11 16:19:57 volumio2 volumio[1008]: info: Loading i18n strings for locale en Jan 11 16:19:57 volumio2 volumio[1008]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 11 16:19:57 volumio2 volumio[1008]: info: Volumio Calling Home Jan 11 16:19:57 volumio2 sudo[1219]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod -R a+rwX /etc/lirc/irexec.lircrc /etc/lirc/lirc_options.conf /etc/lirc/lircd.conf /etc/lirc/lircd.conf.d /etc/lirc/lircmd.conf /etc/lirc/lircrc Jan 11 16:19:57 volumio2 sudo[1219]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 11 16:19:57 volumio2 sudo[1219]: pam_unix(sudo:session): session closed for user root Jan 11 16:19:57 volumio2 volumio[1008]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Jan 11 16:19:57 volumio2 volumio[1008]: info: ir_controller: File permissions successfully set on /etc/lirc/*. Jan 11 16:19:57 volumio2 volumio[1008]: info: MPD Permissions set Jan 11 16:19:57 volumio2 volumio[1008]: info: Volumio called home Jan 11 16:19:57 volumio2 volumio[1008]: info: Spotify config file written Jan 11 16:19:57 volumio2 sudo[1222]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jan 11 16:19:57 volumio2 sudo[1222]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 11 16:19:57 volumio2 volumio[1008]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 57 Jan 11 16:19:57 volumio2 volumio[1008]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 16:19:57 volumio2 volumio[1008]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 16:19:57 volumio2 volumio[1008]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 16:19:57 volumio2 volumio[1008]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 16:19:57 volumio2 volumio[1008]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 16:19:57 volumio2 volumio[1008]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 16:19:57 volumio2 volumio[1008]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 16:19:57 volumio2 volumio[1008]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 16:19:57 volumio2 volumio[1008]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 11 16:19:57 volumio2 volumio[1008]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 16:19:57 volumio2 volumio[1008]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 16:19:57 volumio2 volumio[1008]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 16:19:57 volumio2 volumio[1008]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 16:19:57 volumio2 volumio[1008]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 16:19:57 volumio2 volumio[1008]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 16:19:57 volumio2 volumio[1008]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 16:19:57 volumio2 volumio[1008]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 16:19:57 volumio2 volumio[1008]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 16:19:57 volumio2 volumio[1008]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 11 16:19:57 volumio2 volumio[1008]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 16:19:57 volumio2 volumio[1008]: info: No need to fix Spotify hosts Jan 11 16:19:58 volumio2 volumio[1008]: info: Starting Shairport Sync Jan 11 16:19:58 volumio2 volumio[1008]: info: Starting Shairport Sync Jan 11 16:19:58 volumio2 systemd[1]: Started go-librespot Daemon. Jan 11 16:19:58 volumio2 volumio[1008]: info: Starting Shairport Sync Jan 11 16:19:58 volumio2 go-librespot[1228]: go-librespot daemon starting... Jan 11 16:19:58 volumio2 sudo[1222]: pam_unix(sudo:session): session closed for user root Jan 11 16:19:58 volumio2 sudo[1236]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 11 16:19:58 volumio2 sudo[1234]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 11 16:19:58 volumio2 sudo[1234]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 11 16:19:58 volumio2 sudo[1236]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 11 16:19:58 volumio2 volumio[1008]: info: CoreCommandRouter::volumioGetState Jan 11 16:19:58 volumio2 volumio[1008]: info: CorePlayQueue::getTrack 0 Jan 11 16:19:58 volumio2 sudo[1239]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 11 16:19:58 volumio2 sudo[1239]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 11 16:19:58 volumio2 systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Jan 11 16:19:58 volumio2 systemd[1]: shairport-sync.service: Succeeded. Jan 11 16:19:58 volumio2 systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Jan 11 16:19:58 volumio2 systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Jan 11 16:19:58 volumio2 sudo[1234]: pam_unix(sudo:session): session closed for user root Jan 11 16:19:58 volumio2 sudo[1239]: pam_unix(sudo:session): session closed for user root Jan 11 16:19:58 volumio2 sudo[1236]: pam_unix(sudo:session): session closed for user root Jan 11 16:19:58 volumio2 volumio[1008]: info: ir_controller: LIRC correctly updated. Jan 11 16:19:58 volumio2 volumio[1008]: info: ir_controller: HAT did not load /proc/device-tree/ir_receiver! Jan 11 16:19:58 volumio2 volumio[1008]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Jan 11 16:19:58 volumio2 volumio[1008]: info: ir_controller: Raspberry Pi revision code: b03112 Jan 11 16:19:58 volumio2 volumio[1008]: info: Shairport-Sync Started Jan 11 16:19:58 volumio2 volumio[1008]: Error adding Membership: Error: addMembership EINVAL Jan 11 16:19:58 volumio2 volumio[1008]: info: Shairport-Sync Started Jan 11 16:19:58 volumio2 volumio[1008]: info: Shairport-Sync Started Jan 11 16:19:58 volumio2 volumio[1008]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jan 11 16:19:58 volumio2 volumio[1008]: SPOTIFY: BQBrqD3c37KYshjB7uF3blZa_2Uj6rsjOEJ5CjbXCY41PwMWiApPuRnm8KVn0jHnGgNVl3xDezK-JMKW85RpFTqD67uSd2IjCHaj4TOh3Z2WRKVBtyYQ5s8aYQn9IcXjAVEGmvihR4clLrMQFsyiasFVuZ-wcBY57tzKy5-L3E6hfRAMo7PflpKgBorSwnW--ev_rwSIFBBbzHvfPPzeokajqW8xnZVxbfi79YnqOLLQu9UvCGgU2FH-i12TiRu8KnkJWBPgjF9pAc8Dql_MZaVQZM1AeNFmi9AR6LL2CLF6l1B_41ZH9ZOj Jan 11 16:19:58 volumio2 volumio[1008]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jan 11 16:19:58 volumio2 volumio[1008]: info: New Spotify access token = BQBrqD3c37KYshjB7uF3blZa_2Uj6rsjOEJ5CjbXCY41PwMWiApPuRnm8KVn0jHnGgNVl3xDezK-JMKW85RpFTqD67uSd2IjCHaj4TOh3Z2WRKVBtyYQ5s8aYQn9IcXjAVEGmvihR4clLrMQFsyiasFVuZ-wcBY57tzKy5-L3E6hfRAMo7PflpKgBorSwnW--ev_rwSIFBBbzHvfPPzeokajqW8xnZVxbfi79YnqOLLQu9UvCGgU2FH-i12TiRu8KnkJWBPgjF9pAc8Dql_MZaVQZM1AeNFmi9AR6LL2CLF6l1B_41ZH9ZOj Jan 11 16:19:58 volumio2 volumio[1008]: info: Spotify credentials grant success - running version from March 24, 2019 Jan 11 16:19:58 volumio2 sudo[1256]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/bin/dtoverlay -r -1 Jan 11 16:19:58 volumio2 sudo[1256]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 11 16:19:58 volumio2 volumio[1008]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Jan 11 16:19:58 volumio2 sudo[1256]: pam_unix(sudo:session): session closed for user root Jan 11 16:19:58 volumio2 volumio[1008]: SPOTIFY: User informations: {"country":"GB","display_name":"John","email":"johnlhaughton@hotmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/qd6jt1alblyc813ytbf48nlgs"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/qd6jt1alblyc813ytbf48nlgs","id":"qd6jt1alblyc813ytbf48nlgs","images":[],"product":"premium","type":"user","uri":"spotify:user:qd6jt1alblyc813ytbf48nlgs"} Jan 11 16:19:58 volumio2 volumio[1008]: info: Spotify Successfully logged in Jan 11 16:19:58 volumio2 volumio[1008]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 11 16:19:58 volumio2 volumio[1008]: info: [1768148398618] CoreMusicLibrary::Adding element Spotify Jan 11 16:19:58 volumio2 volumio[1008]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 11 16:19:58 volumio2 volumio[1008]: Cannot find translation for source SoundCloud Jan 11 16:19:58 volumio2 volumio[1008]: Cannot find translation for source Radio Paradise Jan 11 16:19:58 volumio2 volumio[1008]: Cannot find translation for source Spotify Jan 11 16:19:58 volumio2 sudo[1263]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/bin/dtoverlay gpio-ir gpio_pin=25 gpio_pull=up Jan 11 16:19:58 volumio2 sudo[1263]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 11 16:19:58 volumio2 systemd[1]: systemd-fsckd.service: Succeeded. Jan 11 16:19:58 volumio2 kernel: Registered IR keymap rc-rc6-mce Jan 11 16:19:58 volumio2 kernel: IR RC6 protocol handler initialized Jan 11 16:19:58 volumio2 sudo[1263]: pam_unix(sudo:session): session closed for user root Jan 11 16:19:58 volumio2 volumio[1008]: info: ir_controller: Overlay gpio-ir gpio_pin=25 gpio_pull=up loaded. Jan 11 16:19:58 volumio2 go-librespot[1228]: time="2026-01-11T16:19:58Z" level=info msg="running go-librespot 0.4.0" Jan 11 16:19:58 volumio2 go-librespot[1228]: time="2026-01-11T16:19:58Z" level=debug msg="app state loaded" Jan 11 16:19:58 volumio2 sudo[1276]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart lircd.service Jan 11 16:19:58 volumio2 kernel: rc rc0: gpio_ir_recv as /devices/platform/ir-receiver@19/rc/rc0 Jan 11 16:19:58 volumio2 kernel: rc rc0: lirc_dev: driver gpio_ir_recv registered at minor = 0, raw IR receiver, no transmitter Jan 11 16:19:58 volumio2 kernel: input: gpio_ir_recv as /devices/platform/ir-receiver@19/rc/rc0/input0 Jan 11 16:19:58 volumio2 sudo[1276]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 11 16:19:58 volumio2 go-librespot[1228]: time="2026-01-11T16:19:58Z" level=info msg="api server listening on 127.0.0.1:9879" Jan 11 16:19:59 volumio2 systemd[1]: Starting lircd(8) initialization helper tool... Jan 11 16:19:59 volumio2 volumio[1008]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Jan 11 16:19:59 volumio2 kernel: rc rc0: two consecutive events of type space Jan 11 16:19:59 volumio2 sudo[1285]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart lircd.service Jan 11 16:19:59 volumio2 sudo[1285]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 11 16:19:59 volumio2 systemd-udevd[1279]: Process '/usr/sbin/th-cmd --socket /var/run/thd.socket --passfd --udev' failed with exit code 1. Jan 11 16:19:59 volumio2 systemd-logind[570]: Watching system buttons on /dev/input/event0 (gpio_ir_recv) Jan 11 16:19:59 volumio2 go-librespot[1228]: time="2026-01-11T16:19:59Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Jan 11 16:19:59 volumio2 go-librespot[1228]: time="2026-01-11T16:19:59Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Jan 11 16:19:59 volumio2 go-librespot[1228]: time="2026-01-11T16:19:59Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Jan 11 16:19:59 volumio2 go-librespot[1228]: time="2026-01-11T16:19:59Z" level=info msg="zeroconf server listening on port 46091" Jan 11 16:19:59 volumio2 go-librespot[1228]: time="2026-01-11T16:19:59Z" level=debug msg="obtained new client token: AADPFG1I0F9aw55J0DvKa2GGSyYZopLm/51lhIRpzq27+zX7920J06Ad8pKKO4b9r3gpa9C6s478qXlN3kLAh4xXyUrEt67ybAH3oxzqdj03XMSyRfPa0RGGIOQYSlTXkfRZfsze/zaMrtqYg9ZHGn5B1akgmw3SRz3ycXaLyeRq1boQWZWiC9VA9k6P6/zJV28tZivPn/1SO71V1w67rN5S5jdgtpja+/baKhI/Dx7d68shlCKVj1g4aw==" Jan 11 16:19:59 volumio2 volumio[1008]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Jan 11 16:19:59 volumio2 go-librespot[1228]: time="2026-01-11T16:19:59Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Jan 11 16:19:59 volumio2 lircd-setup[1282]: /usr/sbin/lircd-setup:37: DeprecationWarning: The SafeConfigParser class has been renamed to ConfigParser in Python 3.2. This alias will be removed in future versions. Use ConfigParser directly instead. Jan 11 16:19:59 volumio2 lircd-setup[1282]: parser = configparser.SafeConfigParser() Jan 11 16:19:59 volumio2 go-librespot[1228]: time="2026-01-11T16:19:59Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: EOF" Jan 11 16:19:59 volumio2 systemd[1]: lircd-setup.service: Succeeded. Jan 11 16:19:59 volumio2 systemd[1]: Started lircd(8) initialization helper tool. Jan 11 16:19:59 volumio2 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 11 16:19:59 volumio2 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 11 16:19:59 volumio2 systemd[1]: Starting Flexible IR remote input/output application support... Jan 11 16:19:59 volumio2 lircd-0.10.1[1288]: Info: lircd: Opening log, level: Info Jan 11 16:19:59 volumio2 lircd-0.10.1[1288]: Notice: Version: lircd 0.10.1 Jan 11 16:19:59 volumio2 lircd-0.10.1[1288]: Notice: System info: Linux volumio2 6.6.62-v7l+ #1816 SMP Mon Nov 18 15:33:33 GMT 2024 armv7l GNU/Linux Jan 11 16:19:59 volumio2 lircd-0.10.1[1288]: Info: Initial device: /dev/lirc0 Jan 11 16:19:59 volumio2 lircd[1288]: lircd-0.10.1[1288]: Info: lircd: Opening log, level: Info Jan 11 16:19:59 volumio2 lircd[1288]: lircd-0.10.1[1288]: Notice: Using systemd fd Jan 11 16:19:59 volumio2 lircd[1288]: lircd-0.10.1[1288]: Warning: Running as root Jan 11 16:19:59 volumio2 lircd[1288]: lircd-0.10.1[1288]: Info: Using remote: lircd.conf. Jan 11 16:19:59 volumio2 lircd[1288]: lircd-0.10.1[1288]: Notice: lircd(default) ready, using /var/run/lirc/lircd Jan 11 16:19:59 volumio2 systemd[1]: Started Flexible IR remote input/output application support. Jan 11 16:19:59 volumio2 lircd-0.10.1[1288]: Notice: 'lirc' written to protocols file /sys/class/rc/rc0/protocols Jan 11 16:19:59 volumio2 lircd-0.10.1[1288]: Info: Initial device: /dev/lirc0 Jan 11 16:19:59 volumio2 lircd-0.10.1[1288]: Info: [lirc] protocol is enabled Jan 11 16:19:59 volumio2 lircd-0.10.1[1288]: Notice: Options: driver: default Jan 11 16:19:59 volumio2 lircd-0.10.1[1288]: Notice: Options: output: /var/run/lirc/lircd Jan 11 16:19:59 volumio2 lircd-0.10.1[1288]: Notice: Options: nodaemon: 1 Jan 11 16:19:59 volumio2 lircd-0.10.1[1288]: Notice: Options: plugindir: /usr/lib/arm-linux-gnueabihf/lirc/plugins Jan 11 16:19:59 volumio2 lircd-0.10.1[1288]: Notice: Options: logfile: syslog Jan 11 16:19:59 volumio2 lircd-0.10.1[1288]: Notice: Options: immediate-init: 0 Jan 11 16:19:59 volumio2 lircd-0.10.1[1288]: Notice: Options: permission: 666 Jan 11 16:19:59 volumio2 lircd-0.10.1[1288]: Notice: Options: driver-options: Jan 11 16:19:59 volumio2 lircd-0.10.1[1288]: Notice: Options: pidfile: /var/run/lirc/lircd.pid Jan 11 16:19:59 volumio2 lircd-0.10.1[1288]: Notice: Options: listen: 0 Jan 11 16:19:59 volumio2 lircd-0.10.1[1288]: Notice: Options: connect: (null) Jan 11 16:19:59 volumio2 lircd-0.10.1[1288]: Notice: Options: userelease: 0 Jan 11 16:19:59 volumio2 lircd-0.10.1[1288]: Notice: Options: effective_user: (null) Jan 11 16:19:59 volumio2 lircd-0.10.1[1288]: Notice: Options: release_suffix: _EVUP Jan 11 16:19:59 volumio2 lircd-0.10.1[1288]: Notice: Options: allow_simulate: 0 Jan 11 16:19:59 volumio2 lircd-0.10.1[1288]: Notice: Options: repeat_max: 600 Jan 11 16:19:59 volumio2 lircd-0.10.1[1288]: Notice: Options: configfile: /etc/lirc/lircd.conf Jan 11 16:19:59 volumio2 lircd-0.10.1[1288]: Notice: Options: dynamic_codes: (null) Jan 11 16:19:59 volumio2 lircd-0.10.1[1288]: Notice: Current driver: default Jan 11 16:19:59 volumio2 lircd-0.10.1[1288]: Notice: Driver API version: 3 Jan 11 16:19:59 volumio2 lircd-0.10.1[1288]: Notice: Driver version: 0.10.0 Jan 11 16:19:59 volumio2 lircd-0.10.1[1288]: Notice: Driver info: See file:///usr/share/doc/lirc/plugindocs/default.html Jan 11 16:19:59 volumio2 lircd-0.10.1[1288]: Info: lircd: Opening log, level: Info Jan 11 16:19:59 volumio2 lircd-0.10.1[1288]: Notice: Using systemd fd Jan 11 16:19:59 volumio2 lircd-0.10.1[1288]: Warning: Running as root Jan 11 16:19:59 volumio2 lircd-0.10.1[1288]: Info: Using remote: lircd.conf. Jan 11 16:19:59 volumio2 lircd-0.10.1[1288]: Notice: lircd(default) ready, using /var/run/lirc/lircd Jan 11 16:19:59 volumio2 sudo[1285]: pam_unix(sudo:session): session closed for user root Jan 11 16:19:59 volumio2 sudo[1276]: pam_unix(sudo:session): session closed for user root Jan 11 16:19:59 volumio2 volumio[1008]: info: ir_controller: systemctl restart lircd.service succeeded. Jan 11 16:19:59 volumio2 volumio[1008]: info: ir_controller: systemctl restart lircd.service succeeded. Jan 11 16:19:59 volumio2 sudo[1292]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart irexec.service Jan 11 16:19:59 volumio2 sudo[1292]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 11 16:19:59 volumio2 sudo[1294]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart irexec.service Jan 11 16:19:59 volumio2 sudo[1294]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 11 16:19:59 volumio2 systemd[1]: Started Handle events from IR remotes decoded by lircd(8). Jan 11 16:19:59 volumio2 systemd[1]: Stopping Handle events from IR remotes decoded by lircd(8)... Jan 11 16:19:59 volumio2 sudo[1292]: pam_unix(sudo:session): session closed for user root Jan 11 16:19:59 volumio2 systemd[1]: irexec.service: Main process exited, code=killed, status=15/TERM Jan 11 16:19:59 volumio2 systemd[1]: irexec.service: Succeeded. Jan 11 16:19:59 volumio2 volumio[1008]: info: ir_controller: systemctl restart irexec.service succeeded. Jan 11 16:19:59 volumio2 systemd[1]: Stopped Handle events from IR remotes decoded by lircd(8). Jan 11 16:19:59 volumio2 systemd[1]: Started Handle events from IR remotes decoded by lircd(8). Jan 11 16:20:00 volumio2 lircd[1288]: lircd-0.10.1[1288]: Notice: accepted new client on /var/run/lirc/lircd Jan 11 16:20:00 volumio2 lircd[1288]: lircd-0.10.1[1288]: Info: [lirc] protocol is enabled Jan 11 16:20:00 volumio2 lircd-0.10.1[1288]: Notice: accepted new client on /var/run/lirc/lircd Jan 11 16:20:00 volumio2 lircd-0.10.1[1288]: Info: [lirc] protocol is enabled Jan 11 16:20:00 volumio2 sudo[1294]: pam_unix(sudo:session): session closed for user root Jan 11 16:20:00 volumio2 volumio[1008]: info: ir_controller: systemctl restart irexec.service succeeded. Jan 11 16:20:00 volumio2 volumio[1008]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Jan 11 16:20:00 volumio2 mpd[1203]: Jan 11 16:20 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jan 11 16:20:00 volumio2 volumio[1008]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Jan 11 16:20:00 volumio2 sudo[1314]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 11 16:20:00 volumio2 sudo[1314]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 11 16:20:00 volumio2 sudo[1314]: pam_unix(sudo:session): session closed for user root Jan 11 16:20:00 volumio2 sudo[1316]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 11 16:20:00 volumio2 sudo[1316]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 11 16:20:00 volumio2 sudo[1316]: pam_unix(sudo:session): session closed for user root Jan 11 16:20:00 volumio2 sudo[1320]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Jan 11 16:20:00 volumio2 sudo[1320]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 11 16:20:00 volumio2 systemd[1]: Started UPnP Renderer front-end to MPD. Jan 11 16:20:00 volumio2 systemd[1]: Started Music Player Daemon. Jan 11 16:20:00 volumio2 sudo[1180]: pam_unix(sudo:session): session closed for user root Jan 11 16:20:00 volumio2 sudo[1190]: pam_unix(sudo:session): session closed for user root Jan 11 16:20:00 volumio2 sudo[1320]: pam_unix(sudo:session): session closed for user root Jan 11 16:20:00 volumio2 volumio[1008]: info: Upmpdcli Daemon Started Jan 11 16:20:00 volumio2 volumio[1008]: info: Completed starting Core Plugins Jan 11 16:20:00 volumio2 volumio[1008]: info: ------------------------------------------- Jan 11 16:20:00 volumio2 volumio[1008]: info: ----- MyVolumio plugins startup ---- Jan 11 16:20:00 volumio2 volumio[1008]: info: ------------------------------------------- Jan 11 16:20:00 volumio2 volumio[1008]: info: [MyVolumio PluginManager] Fetching plans data.... Jan 11 16:20:00 volumio2 volumio[1008]: error: MPD error: The expression evaluated to a falsy value: Jan 11 16:20:00 volumio2 volumio[1008]: assert.ok(self.idling) Jan 11 16:20:00 volumio2 volumio[1008]: error: The expression evaluated to a falsy value: Jan 11 16:20:00 volumio2 volumio[1008]: assert.ok(self.idling) Jan 11 16:20:00 volumio2 volumio[1008]: info: MPD running with PID1203 Jan 11 16:20:00 volumio2 volumio[1008]: ,establishing connection Jan 11 16:20:00 volumio2 volumio[1008]: error: updateQueue error: null Jan 11 16:20:00 volumio2 volumio[1008]: error: updateQueue error: null Jan 11 16:20:01 volumio2 volumio[1322]: Generating RSA private key, 4096 bit long modulus (2 primes) Jan 11 16:20:01 volumio2 volumio[1008]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Jan 11 16:20:01 volumio2 volumio[1008]: info: go-librespot daemon successfully initialized Jan 11 16:20:01 volumio2 volumio[1008]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Jan 11 16:20:02 volumio2 volumio[1008]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Jan 11 16:20:02 volumio2 sudo[1343]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=JLH,password=astra18,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //192.168.1.6/music /mnt/NAS/DS116 Jan 11 16:20:02 volumio2 sudo[1343]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 11 16:20:02 volumio2 kernel: CIFS: Attempting to mount //192.168.1.6/music Jan 11 16:20:02 volumio2 volumio[1008]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Jan 11 16:20:02 volumio2 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jan 11 16:20:02 volumio2 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Jan 11 16:20:02 volumio2 systemd[1]: Stopped go-librespot Daemon. Jan 11 16:20:02 volumio2 systemd[1]: Started go-librespot Daemon. Jan 11 16:20:02 volumio2 go-librespot[1347]: go-librespot daemon starting... Jan 11 16:20:02 volumio2 go-librespot[1347]: time="2026-01-11T16:20:02Z" level=info msg="running go-librespot 0.4.0" Jan 11 16:20:02 volumio2 go-librespot[1347]: time="2026-01-11T16:20:02Z" level=debug msg="app state loaded" Jan 11 16:20:02 volumio2 go-librespot[1347]: time="2026-01-11T16:20:02Z" level=info msg="api server listening on 127.0.0.1:9879" Jan 11 16:20:03 volumio2 go-librespot[1347]: time="2026-01-11T16:20:03Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 11 16:20:03 volumio2 go-librespot[1347]: time="2026-01-11T16:20:03Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 11 16:20:03 volumio2 go-librespot[1347]: time="2026-01-11T16:20:03Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 11 16:20:03 volumio2 go-librespot[1347]: time="2026-01-11T16:20:03Z" level=info msg="zeroconf server listening on port 45671" Jan 11 16:20:03 volumio2 volumio[1008]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Jan 11 16:20:03 volumio2 go-librespot[1347]: time="2026-01-11T16:20:03Z" level=debug msg="obtained new client token: AAD2iSxI8bHPQUa+Bd3AmvYCqcrpD9CJ6xOepYITVW4jU7fBF2lNH5UYTrMY1Xg4e3CAexYe5u7bAKtQc8Y9qY9lgd/8Xo4iU/eHlH6jHDnTjiiltBJH3b9JfOR9aqfmvbP/4qAa2fKg3M69GXw6erTuhSntkPWyA8yTKZDcWJXAszq+x6IqOg56fRf5FWgf/JMjZRdP/fOp+LilcZzuScS0KcVy2Mr/CA7Hme/w6Fn47bqi+u8fHFSzTQ==" Jan 11 16:20:03 volumio2 go-librespot[1347]: time="2026-01-11T16:20:03Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Jan 11 16:20:03 volumio2 volumio[1008]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Jan 11 16:20:03 volumio2 sudo[1356]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Jan 11 16:20:03 volumio2 sudo[1356]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 11 16:20:03 volumio2 sudo[1358]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Jan 11 16:20:03 volumio2 sudo[1358]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 11 16:20:03 volumio2 systemd[1]: Started MPD Monitor Service. Jan 11 16:20:03 volumio2 sudo[1356]: pam_unix(sudo:session): session closed for user root Jan 11 16:20:03 volumio2 mpd_monitor.sh[1361]: MPD Monitor Service: Starting MPD Monitor Service Jan 11 16:20:03 volumio2 volumio[1008]: info: Successfully started MPD Monitor Jan 11 16:20:03 volumio2 sudo[1358]: pam_unix(sudo:session): session closed for user root Jan 11 16:20:03 volumio2 volumio[1008]: info: Successfully started MPD Monitor Jan 11 16:20:04 volumio2 volumio[1008]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Jan 11 16:20:04 volumio2 go-librespot[1347]: time="2026-01-11T16:20:04Z" level=debug msg="completed keyexchange" Jan 11 16:20:04 volumio2 go-librespot[1347]: time="2026-01-11T16:20:04Z" level=debug msg="completed challenge" Jan 11 16:20:04 volumio2 go-librespot[1347]: time="2026-01-11T16:20:04Z" level=info msg="authenticated AP" username="qd*********************gs" Jan 11 16:20:04 volumio2 volumio[1008]: info: Initializing connection to go-librespot Websocket Jan 11 16:20:04 volumio2 go-librespot[1347]: time="2026-01-11T16:20:04Z" level=debug msg="new websocket client" Jan 11 16:20:04 volumio2 volumio[1008]: info: Connection to go-librespot Websocket established Jan 11 16:20:04 volumio2 go-librespot[1347]: time="2026-01-11T16:20:04Z" level=info msg="authenticated Login5" username="qd*********************gs" Jan 11 16:20:04 volumio2 go-librespot[1347]: time="2026-01-11T16:20:04Z" level=debug msg="initializing zeroconf session" username="qd*********************gs" Jan 11 16:20:04 volumio2 volumio[1008]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Jan 11 16:20:06 volumio2 volumio[1008]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Jan 11 16:20:06 volumio2 go-librespot[1347]: time="2026-01-11T16:20:06Z" level=debug msg="dealer connection opened" Jan 11 16:20:06 volumio2 go-librespot[1347]: time="2026-01-11T16:20:06Z" level=trace msg="starting accesspoint recv loop" Jan 11 16:20:06 volumio2 go-librespot[1347]: time="2026-01-11T16:20:06Z" level=trace msg="starting dealer recv loop" Jan 11 16:20:06 volumio2 go-librespot[1347]: time="2026-01-11T16:20:06Z" level=trace msg="received accesspoint ping" Jan 11 16:20:06 volumio2 go-librespot[1347]: time="2026-01-11T16:20:06Z" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Jan 11 16:20:06 volumio2 go-librespot[1347]: time="2026-01-11T16:20:06Z" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Jan 11 16:20:06 volumio2 go-librespot[1347]: time="2026-01-11T16:20:06Z" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Jan 11 16:20:06 volumio2 go-librespot[1347]: time="2026-01-11T16:20:06Z" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Jan 11 16:20:06 volumio2 go-librespot[1347]: time="2026-01-11T16:20:06Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Jan 11 16:20:06 volumio2 go-librespot[1347]: time="2026-01-11T16:20:06Z" level=debug msg="received connection id: ZTM0ZTQ1MDctZGI4...MTE0QTFEMUU1Rg==" Jan 11 16:20:06 volumio2 go-librespot[1347]: time="2026-01-11T16:20:06Z" level=trace msg="received accesspoint pong ack" Jan 11 16:20:06 volumio2 go-librespot[1347]: time="2026-01-11T16:20:06Z" level=debug msg="put connect state because NEW_DEVICE" Jan 11 16:20:07 volumio2 go-librespot[1347]: time="2026-01-11T16:20:07Z" level=debug msg="handling transfer player command from 8d24e398d86ea984dd1ccf8c73ad80922f04424e" Jan 11 16:20:07 volumio2 go-librespot[1347]: time="2026-01-11T16:20:07Z" level=debug msg="resolved context of track" uri="spotify:artist:1PWHsS9haruM3AEebZuGs9" Jan 11 16:20:07 volumio2 go-librespot[1347]: time="2026-01-11T16:20:07Z" level=trace msg="fetched new page 0 with 10 items (list: 10)" uri="spotify:artist:1PWHsS9haruM3AEebZuGs9" Jan 11 16:20:07 volumio2 go-librespot[1347]: time="2026-01-11T16:20:07Z" level=trace msg="fetched new page 1 with 11 items (list: 21)" uri="spotify:artist:1PWHsS9haruM3AEebZuGs9" Jan 11 16:20:07 volumio2 go-librespot[1347]: time="2026-01-11T16:20:07Z" level=trace msg="fetched new page from (has next: false)" uri="spotify:artist:1PWHsS9haruM3AEebZuGs9" Jan 11 16:20:07 volumio2 go-librespot[1347]: time="2026-01-11T16:20:07Z" level=trace msg="fetched new page 2 with 12 items (list: 33)" uri="spotify:artist:1PWHsS9haruM3AEebZuGs9" Jan 11 16:20:07 volumio2 go-librespot[1347]: time="2026-01-11T16:20:07Z" level=debug msg="loading track (paused: false, position: 212519ms)" uri="spotify:track:04mvrWQLC4ELnshJGLFVxu" Jan 11 16:20:07 volumio2 go-librespot[1347]: time="2026-01-11T16:20:07Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jan 11 16:20:07 volumio2 go-librespot[1347]: time="2026-01-11T16:20:07Z" level=trace msg="emitting websocket event: will_play" Jan 11 16:20:07 volumio2 go-librespot[1347]: time="2026-01-11T16:20:07Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 411" Jan 11 16:20:07 volumio2 go-librespot[1347]: time="2026-01-11T16:20:07Z" level=debug msg="selected format OGG_VORBIS_320 (e37e2614e1cfd6ee161bd3252230c7fd938089ba)" uri="spotify:track:04mvrWQLC4ELnshJGLFVxu" Jan 11 16:20:07 volumio2 go-librespot[1347]: time="2026-01-11T16:20:07Z" level=debug msg="requested aes key for file e37e2614e1cfd6ee161bd3252230c7fd938089ba, gid: 04mvrWQLC4ELnshJGLFVxu" Jan 11 16:20:07 volumio2 go-librespot[1347]: time="2026-01-11T16:20:07Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1359" Jan 11 16:20:07 volumio2 go-librespot[1347]: time="2026-01-11T16:20:07Z" level=trace msg="found 2 cdn urls" uri="spotify:track:04mvrWQLC4ELnshJGLFVxu" Jan 11 16:20:07 volumio2 volumio[1008]: info: Getting Spotify volume Jan 11 16:20:07 volumio2 go-librespot[1347]: time="2026-01-11T16:20:07Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1124" Jan 11 16:20:07 volumio2 go-librespot[1347]: time="2026-01-11T16:20:07Z" level=debug msg="fetched first chunk of 22, total size is 11226560 bytes" uri="spotify:track:04mvrWQLC4ELnshJGLFVxu" Jan 11 16:20:08 volumio2 go-librespot[1347]: time="2026-01-11T16:20:08Z" level=debug msg="fetched chunk 16/21, size: 524288" uri="spotify:track:04mvrWQLC4ELnshJGLFVxu" Jan 11 16:20:08 volumio2 go-librespot[1347]: time="2026-01-11T16:20:08Z" level=trace msg="seek to 212519ms (diff: 116ms, samples: 9372087, bytes: 8806408)" uri="spotify:track:04mvrWQLC4ELnshJGLFVxu" Jan 11 16:20:08 volumio2 go-librespot[1347]: time="2026-01-11T16:20:08Z" level=debug msg="created new output device" Jan 11 16:20:08 volumio2 go-librespot[1347]: time="2026-01-11T16:20:08Z" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 124988 us, period size = 5512 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 4 frames, PCM format = FLOAT_LE" Jan 11 16:20:08 volumio2 go-librespot[1347]: time="2026-01-11T16:20:08Z" level=info msg="loaded track \"When I Go Away\" (paused: false, position: 212519ms, duration: 272573ms, prefetched: false)" uri="spotify:track:04mvrWQLC4ELnshJGLFVxu" Jan 11 16:20:08 volumio2 go-librespot[1347]: time="2026-01-11T16:20:08Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jan 11 16:20:08 volumio2 go-librespot[1347]: time="2026-01-11T16:20:08Z" level=trace msg="scheduling prefetch in 30s" Jan 11 16:20:08 volumio2 go-librespot[1347]: time="2026-01-11T16:20:08Z" level=trace msg="emitting websocket event: metadata" Jan 11 16:20:08 volumio2 go-librespot[1347]: time="2026-01-11T16:20:08Z" level=trace msg="emitting websocket event: active" Jan 11 16:20:08 volumio2 go-librespot[1347]: time="2026-01-11T16:20:08Z" level=debug msg="sending successful reply for dealer request" Jan 11 16:20:08 volumio2 go-librespot[1347]: time="2026-01-11T16:20:08Z" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Jan 11 16:20:08 volumio2 go-librespot[1347]: time="2026-01-11T16:20:08Z" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Jan 11 16:20:08 volumio2 sudo[1343]: pam_unix(sudo:session): session closed for user root Jan 11 16:20:08 volumio2 kernel: CIFS: VFS: Error connecting to socket. Aborting operation. Jan 11 16:20:08 volumio2 kernel: CIFS: VFS: cifs_mount failed w/return code = -113 Jan 11 16:20:08 volumio2 go-librespot[1347]: time="2026-01-11T16:20:08Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jan 11 16:20:08 volumio2 go-librespot[1347]: time="2026-01-11T16:20:08Z" level=trace msg="emitting websocket event: playing" Jan 11 16:20:08 volumio2 go-librespot[1347]: time="2026-01-11T16:20:08Z" level=debug msg="fetched chunk 18/21, size: 524288" uri="spotify:track:04mvrWQLC4ELnshJGLFVxu" Jan 11 16:20:08 volumio2 volumio[1008]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:artist:1PWHsS9haruM3AEebZuGs9","uri":"spotify:track:04mvrWQLC4ELnshJGLFVxu","play_origin":"artist"}} Jan 11 16:20:08 volumio2 volumio[1008]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:04mvrWQLC4ELnshJGLFVxu","name":"When I Go Away","artist_names":["Levon Helm"],"album_name":"Electric Dirt","album_cover_url":"https://i.scdn.co/image/ab67616d00001e027b6b6b50cb21c0b69e674232","position":212519,"duration":272573,"release_date":"year:2009 month:1 day:1","track_number":9,"disc_number":1}} Jan 11 16:20:08 volumio2 volumio[1008]: SPOTIFY: received: {"type":"active","data":null} Jan 11 16:20:08 volumio2 volumio[1008]: info: Aligning Spotify Volume to Volumio Volume Jan 11 16:20:08 volumio2 volumio[1008]: info: CoreCommandRouter::volumioGetState Jan 11 16:20:08 volumio2 volumio[1008]: info: CorePlayQueue::getTrack 0 Jan 11 16:20:08 volumio2 volumio[1008]: info: Setting Spotify Volume from Volumio: 13 Jan 11 16:20:08 volumio2 volumio[1008]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:artist:1PWHsS9haruM3AEebZuGs9","uri":"spotify:track:04mvrWQLC4ELnshJGLFVxu","resume":false,"play_origin":"artist"}} Jan 11 16:20:08 volumio2 volumio[1008]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 11 16:20:08 volumio2 volumio[1008]: TypeError: Cannot read property 'service' of undefined Jan 11 16:20:08 volumio2 volumio[1008]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:346:50) Jan 11 16:20:08 volumio2 volumio[1008]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:272:18) Jan 11 16:20:08 volumio2 volumio[1008]: at WebSocket.message (/data/plugins/music_service/spop/index.js:199:14) Jan 11 16:20:08 volumio2 volumio[1008]: at WebSocket.emit (events.js:315:20) Jan 11 16:20:08 volumio2 volumio[1008]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20) Jan 11 16:20:08 volumio2 volumio[1008]: at Receiver.emit (events.js:315:20) Jan 11 16:20:08 volumio2 volumio[1008]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) Jan 11 16:20:08 volumio2 volumio[1008]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) Jan 11 16:20:08 volumio2 volumio[1008]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) Jan 11 16:20:08 volumio2 volumio[1008]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) Jan 11 16:20:08 volumio2 volumio[1008]: at writeOrBuffer (internal/streams/writable.js:358:12) Jan 11 16:20:08 volumio2 volumio[1008]: at Receiver.Writable.write (internal/streams/writable.js:303:10) Jan 11 16:20:08 volumio2 volumio[1008]: at Socket.socketOnData (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1355:35) Jan 11 16:20:08 volumio2 volumio[1008]: at Socket.emit (events.js:315:20) Jan 11 16:20:08 volumio2 volumio[1008]: at addChunk (internal/streams/readable.js:309:12) Jan 11 16:20:08 volumio2 volumio[1008]: at readableAddChunk (internal/streams/readable.js:284:9) Jan 11 16:20:08 volumio2 volumio[1008]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 11 16:20:08 volumio2 go-librespot[1347]: time="2026-01-11T16:20:08Z" level=debug msg="fetched chunk 1/21, size: 524288" uri="spotify:track:04mvrWQLC4ELnshJGLFVxu" Jan 11 16:20:09 volumio2 go-librespot[1347]: time="2026-01-11T16:20:09Z" level=debug msg="fetched chunk 3/21, size: 524288" uri="spotify:track:04mvrWQLC4ELnshJGLFVxu" Jan 11 16:20:09 volumio2 go-librespot[1347]: time="2026-01-11T16:20:09Z" level=debug msg="fetched chunk 17/21, size: 524288" uri="spotify:track:04mvrWQLC4ELnshJGLFVxu" Jan 11 16:20:09 volumio2 go-librespot[1347]: time="2026-01-11T16:20:09Z" level=debug msg="fetched chunk 2/21, size: 524288" uri="spotify:track:04mvrWQLC4ELnshJGLFVxu" Jan 11 16:20:09 volumio2 sudo[1375]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2026-01-11 16:19 Jan 11 16:20:09 volumio2 sudo[1375]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 11 16:20:09 volumio2 go-librespot[1347]: time="2026-01-11T16:20:09Z" level=debug msg="fetched chunk 19/21, size: 524288" uri="spotify:track:04mvrWQLC4ELnshJGLFVxu" 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="b43c85cc0006d3f1efecba101311ec96e334d1fd" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="6cbc2303e10f00c3a01cb7f02c6d12448bd32c62" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Thu 11 Dec 2025 05:43:24 PM CET" VOLUMIO_VERSION="3.886" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="15d0241b0cd805792809f3ddf4a0fc4e"