-- Logs begin at Thu 2019-02-14 10:11:59 UTC, end at Tue 2024-11-26 03:48:52 UTC. -- Nov 26 03:47:37 kitschypi kernel: i2c_dev: i2c /dev entries driver Nov 26 03:47:37 kitschypi systemd[1]: Starting Load/Save Random Seed... Nov 26 03:47:37 kitschypi fake-hwclock[316]: Tue Nov 26 03:47:37 UTC 2024 Nov 26 03:47:37 kitschypi systemd[1]: Starting Create System Users... Nov 26 03:47:37 kitschypi systemd[1]: Condition check resulted in Rebuild Hardware Database being skipped. Nov 26 03:47:37 kitschypi systemd[1]: Started Load Kernel Modules. Nov 26 03:47:37 kitschypi systemd[1]: Started Restore / save the current clock. Nov 26 03:47:37 kitschypi systemd[1]: Mounting FUSE Control File System... Nov 26 03:47:37 kitschypi systemd[1]: Starting Apply Kernel Variables... Nov 26 03:47:37 kitschypi systemd[1]: Mounting Kernel Configuration File System... Nov 26 03:47:37 kitschypi systemd[1]: Started Load/Save Random Seed. Nov 26 03:47:37 kitschypi systemd[1]: Mounted FUSE Control File System. Nov 26 03:47:37 kitschypi systemd[1]: Mounted Kernel Configuration File System. Nov 26 03:47:37 kitschypi systemd[1]: dynamicswap.service: Succeeded. Nov 26 03:47:37 kitschypi systemd[1]: Started Apply Kernel Variables. Nov 26 03:47:37 kitschypi systemd[1]: Started Create System Users. Nov 26 03:47:37 kitschypi systemd[1]: Starting Create Static Device Nodes in /dev... Nov 26 03:47:37 kitschypi systemd[1]: Started Create Static Device Nodes in /dev. Nov 26 03:47:37 kitschypi systemd[1]: Reached target Local File Systems (Pre). Nov 26 03:47:37 kitschypi systemd[1]: Mounting /var/spool/cups... Nov 26 03:47:37 kitschypi systemd[1]: var-log.mount: Directory /var/log to mount over is not empty, mounting anyway. Nov 26 03:47:37 kitschypi systemd[1]: Mounting /var/log... Nov 26 03:47:37 kitschypi systemd[1]: tmp.mount: Directory /tmp to mount over is not empty, mounting anyway. Nov 26 03:47:37 kitschypi systemd[1]: Mounting /tmp... Nov 26 03:47:37 kitschypi systemd[1]: Starting udev Kernel Device Manager... Nov 26 03:47:37 kitschypi systemd[1]: Started udev Coldplug all Devices. Nov 26 03:47:37 kitschypi systemd[1]: Mounted /var/spool/cups. Nov 26 03:47:37 kitschypi systemd[1]: Mounted /var/log. Nov 26 03:47:37 kitschypi systemd[1]: Mounted /tmp. Nov 26 03:47:37 kitschypi systemd[1]: Starting Flush Journal to Persistent Storage... Nov 26 03:47:37 kitschypi systemd[1]: Mounting /var/spool/cups/tmp... Nov 26 03:47:37 kitschypi systemd[1]: Starting Helper to synchronize boot up for ifupdown... Nov 26 03:47:37 kitschypi systemd[1]: Mounted /var/spool/cups/tmp. Nov 26 03:47:37 kitschypi systemd-udevd[341]: Network interface NamePolicy= disabled on kernel command line, ignoring. Nov 26 03:47:37 kitschypi systemd-journald[306]: Runtime journal (/run/log/journal/26288ad12cf0817baa21aee262cc2d39) is 11.2M, max 30.0M, 18.7M free. Nov 26 03:47:37 kitschypi systemd[1]: Started Flush Journal to Persistent Storage. Nov 26 03:47:37 kitschypi systemd[1]: Started udev Kernel Device Manager. Nov 26 03:47:37 kitschypi systemd[1]: Starting Show Plymouth Boot Screen... Nov 26 03:47:37 kitschypi systemd[1]: plymouth-start.service: Succeeded. Nov 26 03:47:37 kitschypi systemd[1]: Started Show Plymouth Boot Screen. Nov 26 03:47:37 kitschypi systemd[1]: Condition check resulted in Dispatch Password Requests to Console Directory Watch being skipped. Nov 26 03:47:37 kitschypi systemd[1]: Reached target Local Encrypted Volumes. Nov 26 03:47:37 kitschypi systemd[1]: Reached target Paths. Nov 26 03:47:37 kitschypi systemd[1]: Started Forward Password Requests to Plymouth Directory Watch. Nov 26 03:47:37 kitschypi kernel: rpi-gpiomem fe200000.gpiomem: window base 0xfe200000 size 0x00001000 Nov 26 03:47:37 kitschypi kernel: rpi-gpiomem fe200000.gpiomem: initialised 1 regions as /dev/gpiomem Nov 26 03:47:38 kitschypi systemd-udevd[373]: Using default interface naming scheme 'v240'. Nov 26 03:47:38 kitschypi systemd-udevd[373]: link_config: autonegotiation is unset or enabled, the speed and duplex are not writable. Nov 26 03:47:38 kitschypi kernel: mc: Linux media interface: v0.10 Nov 26 03:47:38 kitschypi kernel: vc_sm_cma: module is from the staging directory, the quality is unknown, you have been warned. Nov 26 03:47:38 kitschypi kernel: bcm2835_vc_sm_cma_probe: Videocore shared memory driver Nov 26 03:47:38 kitschypi kernel: [vc_sm_connected_init]: start Nov 26 03:47:38 kitschypi kernel: [vc_sm_connected_init]: installed successfully Nov 26 03:47:38 kitschypi kernel: input: raspberrypi-ts as /devices/platform/soc/soc:firmware/soc:firmware:touchscreen/input/input0 Nov 26 03:47:38 kitschypi kernel: videodev: Linux video capture interface: v2.00 Nov 26 03:47:38 kitschypi systemd[1]: Found device /sys/subsystem/net/devices/eth0. Nov 26 03:47:38 kitschypi kernel: cfg80211: Loading compiled-in X.509 certificates for regulatory database Nov 26 03:47:38 kitschypi kernel: Loaded X.509 cert 'benh@debian.org: 577e021cb980e0e820821ba7b54b4961b8b4fadf' Nov 26 03:47:38 kitschypi kernel: Loaded X.509 cert 'romain.perier@gmail.com: 3abbc6ec146e09d1b6016ab9d6cf71dd233f0328' Nov 26 03:47:38 kitschypi kernel: Loaded X.509 cert 'sforshee: 00b28ddf47aef9cea7' Nov 26 03:47:38 kitschypi kernel: Loaded X.509 cert 'wens: 61c038651aabdcf94bd0ac7ff06c7248db18c600' Nov 26 03:47:38 kitschypi kernel: snd_bcm2835: module is from the staging directory, the quality is unknown, you have been warned. Nov 26 03:47:38 kitschypi kernel: snd_bcm2835: unknown parameter 'enable_compat_alsa' ignored Nov 26 03:47:38 kitschypi kernel: bcm2835_audio bcm2835_audio: card created with 8 channels Nov 26 03:47:38 kitschypi kernel: bcm2835_mmal_vchiq: module is from the staging directory, the quality is unknown, you have been warned. Nov 26 03:47:38 kitschypi kernel: bcm2835_isp: module is from the staging directory, the quality is unknown, you have been warned. Nov 26 03:47:38 kitschypi kernel: rpivid_hevc: module is from the staging directory, the quality is unknown, you have been warned. Nov 26 03:47:38 kitschypi kernel: rpivid feb10000.codec: Device registered as /dev/video19 Nov 26 03:47:39 kitschypi kernel: snd-rpi-hifiberry-dacplus soc:sound: activating headphone amplifier Nov 26 03:47:39 kitschypi kernel: bcm2835-isp bcm2835-isp: Device node output[0] registered as /dev/video13 Nov 26 03:47:39 kitschypi kernel: bcm2835-isp bcm2835-isp: Device node capture[0] registered as /dev/video14 Nov 26 03:47:39 kitschypi kernel: bcm2835-isp bcm2835-isp: Device node capture[1] registered as /dev/video15 Nov 26 03:47:39 kitschypi kernel: bcm2835-isp bcm2835-isp: Device node stats[2] registered as /dev/video16 Nov 26 03:47:39 kitschypi kernel: bcm2835-isp bcm2835-isp: Register output node 0 with media controller Nov 26 03:47:39 kitschypi kernel: bcm2835-isp bcm2835-isp: Register capture node 1 with media controller Nov 26 03:47:39 kitschypi kernel: bcm2835-isp bcm2835-isp: Register capture node 2 with media controller Nov 26 03:47:39 kitschypi kernel: bcm2835-isp bcm2835-isp: Register capture node 3 with media controller Nov 26 03:47:39 kitschypi kernel: bcm2835-isp bcm2835-isp: Device node output[0] registered as /dev/video20 Nov 26 03:47:39 kitschypi kernel: bcm2835_codec: module is from the staging directory, the quality is unknown, you have been warned. Nov 26 03:47:39 kitschypi kernel: bcm2835-isp bcm2835-isp: Device node capture[0] registered as /dev/video21 Nov 26 03:47:39 kitschypi kernel: bcm2835-isp bcm2835-isp: Device node capture[1] registered as /dev/video22 Nov 26 03:47:39 kitschypi kernel: bcm2835-isp bcm2835-isp: Device node stats[2] registered as /dev/video23 Nov 26 03:47:39 kitschypi kernel: bcm2835-isp bcm2835-isp: Register output node 0 with media controller Nov 26 03:47:39 kitschypi kernel: bcm2835-isp bcm2835-isp: Register capture node 1 with media controller Nov 26 03:47:39 kitschypi kernel: bcm2835-isp bcm2835-isp: Register capture node 2 with media controller Nov 26 03:47:39 kitschypi kernel: bcm2835-isp bcm2835-isp: Register capture node 3 with media controller Nov 26 03:47:39 kitschypi kernel: bcm2835-isp bcm2835-isp: Loaded V4L2 bcm2835-isp Nov 26 03:47:39 kitschypi systemd-udevd[365]: link_config: autonegotiation is unset or enabled, the speed and duplex are not writable. Nov 26 03:47:39 kitschypi kernel: bcm2835_v4l2: module is from the staging directory, the quality is unknown, you have been warned. Nov 26 03:47:39 kitschypi kernel: Bluetooth: Core ver 2.22 Nov 26 03:47:39 kitschypi kernel: NET: Registered PF_BLUETOOTH protocol family Nov 26 03:47:39 kitschypi kernel: Bluetooth: HCI device and connection manager initialized Nov 26 03:47:39 kitschypi kernel: Bluetooth: HCI socket layer initialized Nov 26 03:47:39 kitschypi kernel: Bluetooth: L2CAP socket layer initialized Nov 26 03:47:39 kitschypi kernel: Bluetooth: SCO socket layer initialized Nov 26 03:47:39 kitschypi kernel: bcm2835-codec bcm2835-codec: Device registered as /dev/video10 Nov 26 03:47:39 kitschypi kernel: bcm2835-codec bcm2835-codec: Loaded V4L2 decode Nov 26 03:47:39 kitschypi kernel: bcm2835-codec bcm2835-codec: Device registered as /dev/video11 Nov 26 03:47:39 kitschypi kernel: bcm2835-codec bcm2835-codec: Loaded V4L2 encode Nov 26 03:47:39 kitschypi kernel: bcm2835-codec bcm2835-codec: Device registered as /dev/video12 Nov 26 03:47:39 kitschypi kernel: bcm2835-codec bcm2835-codec: Loaded V4L2 isp Nov 26 03:47:39 kitschypi kernel: Bluetooth: HCI UART driver ver 2.3 Nov 26 03:47:39 kitschypi kernel: Bluetooth: HCI UART protocol H4 registered Nov 26 03:47:39 kitschypi kernel: Bluetooth: HCI UART protocol Three-wire (H5) registered Nov 26 03:47:39 kitschypi kernel: Bluetooth: HCI UART protocol Broadcom registered Nov 26 03:47:39 kitschypi kernel: hci_uart_bcm serial0-0: supply vbat not found, using dummy regulator Nov 26 03:47:39 kitschypi kernel: hci_uart_bcm serial0-0: supply vddio not found, using dummy regulator Nov 26 03:47:39 kitschypi kernel: bcm2835-codec bcm2835-codec: Device registered as /dev/video18 Nov 26 03:47:39 kitschypi kernel: bcm2835-codec bcm2835-codec: Loaded V4L2 image_fx Nov 26 03:47:39 kitschypi kernel: bcm2835-codec bcm2835-codec: Device registered as /dev/video31 Nov 26 03:47:39 kitschypi kernel: bcm2835-codec bcm2835-codec: Loaded V4L2 encode_image Nov 26 03:47:39 kitschypi kernel: brcmfmac: F1 signature read @0x18000000=0x15264345 Nov 26 03:47:39 kitschypi kernel: brcmfmac: brcmf_fw_alloc_request: using brcm/brcmfmac43455-sdio for chip BCM4345/6 Nov 26 03:47:39 kitschypi kernel: usbcore: registered new interface driver brcmfmac Nov 26 03:47:39 kitschypi kernel: uart-pl011 fe201000.serial: no DMA platform data Nov 26 03:47:39 kitschypi kernel: Bluetooth: hci0: BCM: chip id 107 Nov 26 03:47:39 kitschypi kernel: Bluetooth: hci0: BCM: features 0x2f Nov 26 03:47:39 kitschypi kernel: Bluetooth: hci0: BCM4345C0 Nov 26 03:47:39 kitschypi kernel: Bluetooth: hci0: BCM4345C0 (003.001.025) build 0000 Nov 26 03:47:39 kitschypi kernel: tpa6130a2 1-0060: supply Vdd not found, using dummy regulator Nov 26 03:47:39 kitschypi kernel: Bluetooth: hci0: BCM4345C0 'brcm/BCM4345C0.hcd' Patch Nov 26 03:47:39 kitschypi systemd-udevd[363]: Process '/usr/sbin/th-cmd --socket /var/run/thd.socket --passfd --udev' failed with exit code 1. Nov 26 03:47:39 kitschypi kernel: brcmfmac: brcmf_c_process_txcap_blob: no txcap_blob available (err=-2) Nov 26 03:47:39 kitschypi kernel: brcmfmac: brcmf_c_preinit_dcmds: Firmware: BCM4345/6 wl0: Nov 1 2021 00:37:25 version 7.45.241 (1a2f2fa CY) FWID 01-703fd60 Nov 26 03:47:39 kitschypi systemd-udevd[377]: Using default interface naming scheme 'v240'. Nov 26 03:47:39 kitschypi systemd-udevd[377]: link_config: autonegotiation is unset or enabled, the speed and duplex are not writable. Nov 26 03:47:40 kitschypi systemd[1]: Found device /dev/disk/by-uuid/DC0C-AF04. Nov 26 03:47:40 kitschypi kernel: alsactl[487]: memfd_create() called without MFD_EXEC or MFD_NOEXEC_SEAL set Nov 26 03:47:40 kitschypi systemd-udevd[359]: Process '/usr/sbin/th-cmd --socket /var/run/thd.socket --passfd --udev' failed with exit code 1. Nov 26 03:47:40 kitschypi systemd[1]: Created slice system-bthelper.slice. Nov 26 03:47:40 kitschypi systemd[1]: Condition check resulted in Set Up Additional Binary Formats being skipped. Nov 26 03:47:40 kitschypi systemd[1]: Condition check resulted in Huge Pages File System being skipped. Nov 26 03:47:40 kitschypi systemd[1]: Condition check resulted in Rebuild Hardware Database being skipped. Nov 26 03:47:40 kitschypi kernel: Bluetooth: hci0: BCM: features 0x2f Nov 26 03:47:40 kitschypi kernel: Bluetooth: hci0: BCM43455 37.4MHz Raspberry Pi 3+ Nov 26 03:47:40 kitschypi kernel: Bluetooth: hci0: BCM4345C0 (003.001.025) build 0342 Nov 26 03:47:40 kitschypi systemd[1]: Starting Show Plymouth Boot Screen... Nov 26 03:47:40 kitschypi systemd[1]: Created slice system-systemd\x2dbacklight.slice. Nov 26 03:47:40 kitschypi systemd[1]: Starting Load/Save Screen Backlight Brightness of backlight:rpi_backlight... Nov 26 03:47:40 kitschypi systemd[1]: Listening on Load/Save RF Kill Switch Status /dev/rfkill Watch. Nov 26 03:47:40 kitschypi systemd[1]: Starting File System Check on /dev/disk/by-uuid/DC0C-AF04... Nov 26 03:47:40 kitschypi systemd[1]: Started Helper to synchronize boot up for ifupdown. Nov 26 03:47:40 kitschypi systemd[1]: Found device /sys/subsystem/net/devices/wlan0. Nov 26 03:47:40 kitschypi systemd[1]: Started Load/Save Screen Backlight Brightness of backlight:rpi_backlight. Nov 26 03:47:40 kitschypi systemd[1]: plymouth-start.service: Succeeded. Nov 26 03:47:40 kitschypi systemd[1]: Started Show Plymouth Boot Screen. Nov 26 03:47:40 kitschypi systemd[1]: Started File System Check Daemon to report status. Nov 26 03:47:40 kitschypi systemd[1]: Starting Load/Save RF Kill Switch Status... Nov 26 03:47:40 kitschypi systemd[1]: Condition check resulted in Dispatch Password Requests to Console Directory Watch being skipped. Nov 26 03:47:40 kitschypi systemd-fsck[533]: fsck.fat 4.1 (2017-01-24) Nov 26 03:47:40 kitschypi systemd-fsck[533]: /dev/mmcblk0p1: 502 files, 42232/46774 clusters Nov 26 03:47:40 kitschypi systemd[1]: Started File System Check on /dev/disk/by-uuid/DC0C-AF04. Nov 26 03:47:40 kitschypi systemd[1]: Mounting /boot... Nov 26 03:47:40 kitschypi systemd[1]: Started Load/Save RF Kill Switch Status. Nov 26 03:47:41 kitschypi systemd[1]: Mounted /boot. Nov 26 03:47:41 kitschypi systemd[1]: Reached target Local File Systems. Nov 26 03:47:41 kitschypi systemd[1]: Starting Tell Plymouth To Write Out Runtime Data... Nov 26 03:47:41 kitschypi systemd[1]: Started ifup for eth0. Nov 26 03:47:41 kitschypi systemd[1]: Started ifup for wlan0. Nov 26 03:47:41 kitschypi systemd[1]: Starting Create Volatile Files and Directories... Nov 26 03:47:41 kitschypi systemd[1]: Condition check resulted in Commit a transient machine-id on disk being skipped. Nov 26 03:47:41 kitschypi systemd[1]: Starting Raise network interfaces... Nov 26 03:47:41 kitschypi systemd[1]: Starting Preprocess NFS configuration... Nov 26 03:47:41 kitschypi systemd[1]: plymouth-read-write.service: Succeeded. Nov 26 03:47:41 kitschypi systemd[1]: Started Tell Plymouth To Write Out Runtime Data. Nov 26 03:47:41 kitschypi systemd[1]: Received SIGRTMIN+20 from PID 197 (plymouthd). Nov 26 03:47:41 kitschypi systemd[1]: nfs-config.service: Succeeded. Nov 26 03:47:41 kitschypi systemd[1]: Started Preprocess NFS configuration. Nov 26 03:47:41 kitschypi systemd[1]: Condition check resulted in RPC security service for NFS client and server being skipped. Nov 26 03:47:41 kitschypi systemd[1]: Condition check resulted in RPC security service for NFS server being skipped. Nov 26 03:47:41 kitschypi systemd[1]: Reached target NFS client services. Nov 26 03:47:41 kitschypi systemd[1]: Started Create Volatile Files and Directories. Nov 26 03:47:41 kitschypi kernel: warning: `iwconfig' uses wireless extensions which will stop working for Wi-Fi 7 hardware; use nl80211 Nov 26 03:47:41 kitschypi systemd[1]: Started Entropy daemon using the HAVEGE algorithm. Nov 26 03:47:41 kitschypi systemd[1]: Starting RPC bind portmap service... Nov 26 03:47:41 kitschypi systemd[1]: Condition check resulted in Network Time Synchronization being skipped. Nov 26 03:47:41 kitschypi systemd[1]: Starting Update UTMP about System Boot/Shutdown... Nov 26 03:47:41 kitschypi kernel: brcmfmac: brcmf_cfg80211_set_power_mgmt: power save disabled Nov 26 03:47:41 kitschypi systemd[1]: Started Update UTMP about System Boot/Shutdown. Nov 26 03:47:41 kitschypi systemd[1]: Reached target System Initialization. Nov 26 03:47:41 kitschypi systemd[1]: Listening on Avahi mDNS/DNS-SD Stack Activation Socket. Nov 26 03:47:41 kitschypi systemd[1]: Listening on triggerhappy.socket. Nov 26 03:47:41 kitschypi systemd[1]: Started Daily man-db regeneration. Nov 26 03:47:41 kitschypi systemd[1]: Started Daily apt download activities. Nov 26 03:47:41 kitschypi systemd[1]: Started Daily apt upgrade and clean activities. Nov 26 03:47:41 kitschypi systemd[1]: Listening on D-Bus System Message Bus Socket. Nov 26 03:47:41 kitschypi systemd[1]: Reached target Sockets. Nov 26 03:47:41 kitschypi systemd[1]: Started Daily Cleanup of Temporary Directories. Nov 26 03:47:41 kitschypi systemd[1]: Reached target Timers. Nov 26 03:47:41 kitschypi systemd[1]: Reached target Basic System. Nov 26 03:47:41 kitschypi systemd[1]: Condition check resulted in Copy user wpa_supplicant.conf being skipped. Nov 26 03:47:41 kitschypi kernel: 8021q: 802.1Q VLAN Support v1.8 Nov 26 03:47:41 kitschypi systemd[1]: Starting Configure Bluetooth Modems connected by UART... Nov 26 03:47:41 kitschypi systemd[1]: Started MPD Monitor Service. Nov 26 03:47:41 kitschypi systemd[1]: Starting Avahi mDNS/DNS-SD Stack... Nov 26 03:47:41 kitschypi systemd[1]: Starting triggerhappy global hotkey daemon... Nov 26 03:47:41 kitschypi systemd[1]: Starting Login Service... Nov 26 03:47:41 kitschypi systemd[1]: Started D-Bus System Message Bus. Nov 26 03:47:41 kitschypi thd[654]: Unable to parse trigger line: Nov 26 03:47:41 kitschypi thd[654]: Unable to parse trigger line: KEY_MIN_INTERESTING 1 /usr/local/bin/volumio volume toggle Nov 26 03:47:41 kitschypi thd[654]: Unable to parse trigger line: Nov 26 03:47:41 kitschypi thd[654]: Found socket passed from systemd Nov 26 03:47:41 kitschypi systemd[1]: Starting WPA supplicant... Nov 26 03:47:41 kitschypi systemd[1]: Started Volumio Log Rotation Service. Nov 26 03:47:41 kitschypi systemd[1]: Started volumio-remote-updater.service. Nov 26 03:47:41 kitschypi systemd[1]: Starting dhcpcd on all interfaces... Nov 26 03:47:41 kitschypi systemd[1]: Starting Wireless Services... Nov 26 03:47:41 kitschypi systemd[1]: Started Volumio Iptables Module. Nov 26 03:47:41 kitschypi systemd[1]: Condition check resulted in Volumio SSH enabler being skipped. Nov 26 03:47:41 kitschypi systemd[1]: Started Manage Sound Card State (restore and store). Nov 26 03:47:41 kitschypi systemd[1]: Starting Save/Restore Sound Card State... Nov 26 03:47:41 kitschypi alsactl[671]: alsactl 1.1.8 daemon started Nov 26 03:47:41 kitschypi systemd[1]: Started UPnP Renderer front-end to MPD. Nov 26 03:47:41 kitschypi systemd[1]: Starting Volumio Time Update Utility... Nov 26 03:47:41 kitschypi systemd[1]: Condition check resulted in getty on tty2-tty6 if dbus and logind are not available being skipped. Nov 26 03:47:41 kitschypi systemd[1]: Reached target Login Prompts. Nov 26 03:47:41 kitschypi systemd[1]: Started RPC bind portmap service. Nov 26 03:47:41 kitschypi dhcpcd[666]: Not running dhcpcd because /etc/network/interfaces Nov 26 03:47:41 kitschypi dhcpcd[666]: defines some interfaces that will use a Nov 26 03:47:41 kitschypi dhcpcd[666]: DHCP client or static address Nov 26 03:47:41 kitschypi systemd[1]: Started triggerhappy global hotkey daemon. Nov 26 03:47:41 kitschypi systemd[1]: hciuart.service: Succeeded. Nov 26 03:47:41 kitschypi systemd[1]: Started Configure Bluetooth Modems connected by UART. Nov 26 03:47:41 kitschypi systemd[1]: dhcpcd.service: Control process exited, code=exited, status=6/NOTCONFIGURED Nov 26 03:47:41 kitschypi systemd[1]: dhcpcd.service: Failed with result 'exit-code'. Nov 26 03:47:42 kitschypi systemd[1]: Failed to start dhcpcd on all interfaces. Nov 26 03:47:42 kitschypi systemd[1]: Started Save/Restore Sound Card State. Nov 26 03:47:42 kitschypi systemd-logind[656]: New seat seat0. Nov 26 03:47:42 kitschypi avahi-daemon[650]: Found user 'avahi' (UID 110) and group 'avahi' (GID 113). Nov 26 03:47:42 kitschypi volumio-time-update[676]: volumio-time-update-util: Fetching time from Volumio... Nov 26 03:47:42 kitschypi avahi-daemon[650]: Successfully dropped root privileges. Nov 26 03:47:42 kitschypi avahi-daemon[650]: avahi-daemon 0.7 starting up. Nov 26 03:47:42 kitschypi mpd_monitor.sh[649]: MPD error: Connection refused Nov 26 03:47:42 kitschypi systemd[1]: Reached target Sound Card. Nov 26 03:47:42 kitschypi systemd[1]: Starting Raspberry Pi bluetooth helper... Nov 26 03:47:42 kitschypi systemd[1]: Reached target Remote File Systems (Pre). Nov 26 03:47:42 kitschypi systemd[1]: Reached target Remote File Systems. Nov 26 03:47:42 kitschypi systemd[1]: Starting LSB: Load kernel modules needed to enable cpufreq scaling... Nov 26 03:47:42 kitschypi systemd[1]: Started Regular background program processing daemon. Nov 26 03:47:42 kitschypi systemd[1]: Reached target RPC Port Mapper. Nov 26 03:47:42 kitschypi cron[693]: (CRON) INFO (pidfile fd = 3) Nov 26 03:47:42 kitschypi kernel: bcmgenet fd580000.ethernet: configuring instance for external RGMII (RX delay) Nov 26 03:47:42 kitschypi kernel: bcmgenet fd580000.ethernet eth0: Link is Down Nov 26 03:47:42 kitschypi dhcpcd[596]: eth0: waiting for carrier Nov 26 03:47:42 kitschypi sh[547]: eth0: waiting for carrier Nov 26 03:47:42 kitschypi mpd_monitor.sh[649]: mpd: no process found Nov 26 03:47:42 kitschypi cron[693]: (CRON) INFO (Running @reboot jobs) Nov 26 03:47:42 kitschypi ifup[554]: ifup: waiting for lock on /run/network/ifstate.wlan0 Nov 26 03:47:42 kitschypi sh[548]: wlan0=wlan0 Nov 26 03:47:42 kitschypi bthelper[689]: Raspberry Pi BDADDR already set Nov 26 03:47:42 kitschypi systemd[1]: Started Raspberry Pi bluetooth helper. Nov 26 03:47:42 kitschypi avahi-daemon[650]: Successfully called chroot(). Nov 26 03:47:42 kitschypi avahi-daemon[650]: Successfully dropped remaining capabilities. Nov 26 03:47:42 kitschypi wpa_supplicant[662]: Successfully initialized wpa_supplicant Nov 26 03:47:42 kitschypi avahi-daemon[650]: Loading service file /services/volumio.service. Nov 26 03:47:43 kitschypi avahi-daemon[650]: Network interface enumeration completed. Nov 26 03:47:43 kitschypi avahi-daemon[650]: Server startup complete. Host name is kitschypi.local. Local service cookie is 3357352824. Nov 26 03:47:43 kitschypi avahi-daemon[650]: Service "KitschyPi" (/services/volumio.service) successfully established. Nov 26 03:47:43 kitschypi systemd[1]: Started Login Service. Nov 26 03:47:43 kitschypi systemd[1]: Started Raise network interfaces. Nov 26 03:47:43 kitschypi systemd[1]: Started WPA supplicant. Nov 26 03:47:43 kitschypi systemd[1]: Started Avahi mDNS/DNS-SD Stack. Nov 26 03:47:43 kitschypi volumio-remote-updater[665]: Error: No active session Nov 26 03:47:43 kitschypi systemd[1]: Reached target Network. Nov 26 03:47:43 kitschypi volumio-remote-updater[665]: [2024-11-26 03:47:43] [info] asio async_connect error: system:111 (Connection refused) Nov 26 03:47:43 kitschypi volumio-remote-updater[665]: [2024-11-26 03:47:43] [info] Error getting remote endpoint: system:107 (Transport endpoint is not connected) Nov 26 03:47:43 kitschypi volumio-remote-updater[665]: [2024-11-26 03:47:43] [error] handle_connect error: Underlying Transport Error Nov 26 03:47:43 kitschypi systemd[1]: Condition check resulted in fast remote file copy program daemon being skipped. Nov 26 03:47:43 kitschypi systemd[1]: Reached target Network is Online. Nov 26 03:47:43 kitschypi systemd[1]: Starting LSB: exim Mail Transport Agent... Nov 26 03:47:43 kitschypi loadcpufreq[690]: Loading cpufreq kernel modules...libkmod: ERROR ../libkmod/libkmod-module.c:1931 kmod_module_get_holders: could not open '/sys/module/nf_conntrack/holders': No such file or directory Nov 26 03:47:43 kitschypi volumio[674]: Could not open config: /tmp/upmpdcli.conf Nov 26 03:47:43 kitschypi systemd[1]: Starting LSB: Brings up/down network automatically... Nov 26 03:47:43 kitschypi systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Nov 26 03:47:43 kitschypi systemd[1]: Starting Samba NMB Daemon... Nov 26 03:47:43 kitschypi systemd[1]: Starting /etc/rc.local Compatibility... Nov 26 03:47:43 kitschypi volumio-time-update[676]: volumio-time-update-util: Date not found in response Nov 26 03:47:43 kitschypi volumio-time-update[676]: volumio-time-update-util: Retrying in 5 seconds... Nov 26 03:47:43 kitschypi systemd[1]: Starting Network Time Service... Nov 26 03:47:43 kitschypi systemd[1]: Starting Permit User Sessions... Nov 26 03:47:43 kitschypi systemd[1]: Starting OpenBSD Secure Shell server... Nov 26 03:47:43 kitschypi systemd[1]: Listening on mpd.socket. Nov 26 03:47:43 kitschypi systemd[1]: Starting Music Player Daemon... Nov 26 03:47:43 kitschypi systemd[1]: Starting Bluetooth service... Nov 26 03:47:43 kitschypi systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Nov 26 03:47:43 kitschypi systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Nov 26 03:47:43 kitschypi systemd[1]: Started /etc/rc.local Compatibility. Nov 26 03:47:43 kitschypi systemd[1]: Started Permit User Sessions. Nov 26 03:47:43 kitschypi systemd[1]: iptables.service: Succeeded. Nov 26 03:47:43 kitschypi systemd[1]: Starting Hold until boot process finishes up... Nov 26 03:47:43 kitschypi loadcpufreq[690]: done (none). Nov 26 03:47:43 kitschypi systemd[1]: Starting Terminate Plymouth Boot Screen... Nov 26 03:47:43 kitschypi systemd[1]: Started LSB: Load kernel modules needed to enable cpufreq scaling. Nov 26 03:47:43 kitschypi ntpd[763]: ntpd 4.2.8p12@1.3728-o (1): Starting Nov 26 03:47:43 kitschypi ntpd[763]: Command line: /usr/sbin/ntpd -p /var/run/ntpd.pid -g -u 103:103 Nov 26 03:47:43 kitschypi systemd[1]: Started Network Time Service. Nov 26 03:47:43 kitschypi ntpd[803]: proto: precision = 2.037 usec (-19) Nov 26 03:47:44 kitschypi systemd[1]: Received SIGRTMIN+21 from PID 197 (plymouthd). Nov 26 03:47:44 kitschypi ntpd[803]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): good hash signature Nov 26 03:47:44 kitschypi ntpd[803]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): loaded, expire=2024-12-28T00:00:00Z last=2017-01-01T00:00:00Z ofs=37 Nov 26 03:47:44 kitschypi ntpd[803]: Listen and drop on 0 v6wildcard [::]:123 Nov 26 03:47:44 kitschypi ntpd[803]: Listen and drop on 1 v4wildcard 0.0.0.0:123 Nov 26 03:47:44 kitschypi ntpd[803]: Listen normally on 2 lo 127.0.0.1:123 Nov 26 03:47:44 kitschypi ntpd[803]: Listening on routing socket on fd #19 for interface updates Nov 26 03:47:44 kitschypi ntpd[803]: kernel reports TIME_ERROR: 0x41: Clock Unsynchronized Nov 26 03:47:44 kitschypi ntpd[803]: kernel reports TIME_ERROR: 0x41: Clock Unsynchronized Nov 26 03:47:44 kitschypi systemd[1]: plymouth-quit-wait.service: Succeeded. Nov 26 03:47:44 kitschypi systemd[1]: Started Hold until boot process finishes up. Nov 26 03:47:44 kitschypi systemd[1]: plymouth-quit.service: Succeeded. Nov 26 03:47:44 kitschypi systemd[1]: Started Terminate Plymouth Boot Screen. Nov 26 03:47:44 kitschypi systemd[1]: Received SIGRTMIN+21 from PID 197 (n/a). Nov 26 03:47:44 kitschypi ifplugd(eth0)[823]: ifplugd 0.28 initializing. Nov 26 03:47:44 kitschypi ifplugd(eth0)[823]: Using interface eth0/DC:A6:32:79:DD:64 with driver (version: 6.6.56-v7l+) Nov 26 03:47:44 kitschypi ifplugd(eth0)[823]: Using detection mode: SIOCETHTOOL Nov 26 03:47:44 kitschypi ifplugd(eth0)[823]: Initialization complete, link beat not detected. Nov 26 03:47:44 kitschypi systemd[1]: Starting LSB: set CPUFreq kernel parameters... Nov 26 03:47:44 kitschypi sshd[809]: Server listening on 0.0.0.0 port 22. Nov 26 03:47:44 kitschypi sshd[809]: Server listening on :: port 22. Nov 26 03:47:44 kitschypi systemd[1]: Started OpenBSD Secure Shell server. Nov 26 03:47:44 kitschypi ifplugd[755]: Network Interface Plugging Daemon...start eth0...done. Nov 26 03:47:44 kitschypi systemd[1]: Started LSB: Brings up/down network automatically. Nov 26 03:47:44 kitschypi bluetoothd[788]: Bluetooth daemon 5.50 Nov 26 03:47:44 kitschypi bluetoothd[788]: Unknown key AutoConnectTimeout for group General in /etc/bluetooth/main.conf Nov 26 03:47:44 kitschypi systemd[1]: Started Bluetooth service. Nov 26 03:47:44 kitschypi systemd[1]: Reached target Bluetooth. Nov 26 03:47:44 kitschypi bluetoothd[788]: Starting SDP server Nov 26 03:47:44 kitschypi bluetoothd[788]: Excluding (cli) sap Nov 26 03:47:44 kitschypi cpufrequtils[822]: CPUFreq Utilities: Setting ondemand CPUFreq governor...CPU0...CPU1...CPU2...CPU3...done. Nov 26 03:47:44 kitschypi systemd[1]: Started LSB: set CPUFreq kernel parameters. Nov 26 03:47:44 kitschypi kernel: Bluetooth: BNEP (Ethernet Emulation) ver 1.3 Nov 26 03:47:44 kitschypi kernel: Bluetooth: BNEP filters: protocol multicast Nov 26 03:47:44 kitschypi kernel: Bluetooth: BNEP socket layer initialized Nov 26 03:47:44 kitschypi dbus-daemon[659]: [system] Activating via systemd: service name='org.freedesktop.hostname1' unit='dbus-org.freedesktop.hostname1.service' requested by ':1.5' (uid=0 pid=788 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap ") Nov 26 03:47:44 kitschypi bluetoothd[788]: Bluetooth management interface 1.22 initialized Nov 26 03:47:44 kitschypi kernel: Bluetooth: MGMT ver 1.22 Nov 26 03:47:44 kitschypi sudo[784]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Nov 26 03:47:44 kitschypi sudo[784]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 26 03:47:44 kitschypi sudo[784]: /bin/chown: cannot access '/var/log/mpd.log': No such file or directory Nov 26 03:47:44 kitschypi sudo[784]: pam_unix(sudo:session): session closed for user root Nov 26 03:47:44 kitschypi bluetoothd[788]: Failed to set privacy: Rejected (0x0b) Nov 26 03:47:44 kitschypi systemd[1]: Starting Hostname Service... Nov 26 03:47:44 kitschypi haveged[584]: haveged: ver: 1.9.1; arch: generic; vend: ; build: (gcc 8.2.0 CTV); collect: 128K Nov 26 03:47:44 kitschypi haveged[584]: haveged: cpu: (VC); data: 16K (D); inst: 16K (D); idx: 11/40; sz: 14768/63488 Nov 26 03:47:44 kitschypi haveged[584]: haveged: tot tests(BA8): A:1/1 B:1/1 continuous tests(B): last entropy estimate 8.00214 Nov 26 03:47:44 kitschypi haveged[584]: haveged: fills: 0, generated: 0 Nov 26 03:47:44 kitschypi dbus-daemon[659]: [system] Successfully activated service 'org.freedesktop.hostname1' Nov 26 03:47:44 kitschypi systemd[1]: Started Hostname Service. Nov 26 03:47:44 kitschypi ntpd[803]: error resolving pool 0.debian.pool.ntp.org: System error (-11) Nov 26 03:47:45 kitschypi nmbd[791]: [2024/11/26 03:47:45.230109, 0] ../source3/nmbd/asyncdns.c:158(start_async_dns) Nov 26 03:47:45 kitschypi nmbd[791]: started asyncdns process 1088 Nov 26 03:47:45 kitschypi exim4[751]: Starting MTA: exim4. Nov 26 03:47:45 kitschypi nmbd[791]: [2024/11/26 03:47:45.231994, 0] ../lib/util/become_daemon.c:149(daemon_status) Nov 26 03:47:45 kitschypi systemd[1]: Started LSB: exim Mail Transport Agent. Nov 26 03:47:45 kitschypi nmbd[791]: daemon_status: STATUS=daemon 'nmbd' : No local IPv4 non-loopback interfaces available, waiting for interface ... Nov 26 03:47:45 kitschypi nmbd[791]: [2024/11/26 03:47:45.232138, 0] ../source3/nmbd/nmbd_subnetdb.c:254(create_subnets) Nov 26 03:47:45 kitschypi nmbd[791]: NOTE: NetBIOS name resolution is not supported for Internet Protocol Version 6 (IPv6). Nov 26 03:47:45 kitschypi exim[1087]: 2024-11-26 03:47:45 socket bind() to port 25 for address ::1 failed: Cannot assign requested address: waiting 30s before trying again (9 more tries) Nov 26 03:47:45 kitschypi exim[1087]: 2024-11-26 03:47:45 Cannot open main log file "/var/log/exim4/mainlog": Permission denied: euid=0 egid=125 Nov 26 03:47:45 kitschypi exim[1087]: exim: could not open panic log - aborting: see message(s) above Nov 26 03:47:45 kitschypi wireless.js[667]: Cleaning previous... Nov 26 03:47:45 kitschypi sudo[1098]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ip addr flush dev wlan0 Nov 26 03:47:45 kitschypi sudo[1098]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 26 03:47:45 kitschypi sudo[1098]: pam_unix(sudo:session): session closed for user root Nov 26 03:47:45 kitschypi sudo[1100]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 down Nov 26 03:47:45 kitschypi sudo[1100]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 26 03:47:45 kitschypi systemd[1]: systemd-rfkill.service: Succeeded. Nov 26 03:47:45 kitschypi ntpd[803]: error resolving pool 1.debian.pool.ntp.org: System error (-11) Nov 26 03:47:46 kitschypi sudo[1100]: pam_unix(sudo:session): session closed for user root Nov 26 03:47:46 kitschypi wireless.js[667]: Stopped aP Nov 26 03:47:46 kitschypi sudo[1107]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 up Nov 26 03:47:46 kitschypi sudo[1107]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 26 03:47:46 kitschypi sudo[1107]: pam_unix(sudo:session): session closed for user root Nov 26 03:47:46 kitschypi kernel: brcmfmac: brcmf_cfg80211_set_power_mgmt: power save disabled Nov 26 03:47:46 kitschypi sudo[1109]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iw reg get Nov 26 03:47:46 kitschypi sudo[1109]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 26 03:47:46 kitschypi sudo[1109]: pam_unix(sudo:session): session closed for user root Nov 26 03:47:46 kitschypi sudo[1116]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 up Nov 26 03:47:46 kitschypi sudo[1116]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 26 03:47:46 kitschypi sudo[1116]: pam_unix(sudo:session): session closed for user root Nov 26 03:47:46 kitschypi sudo[1118]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iw wlan0 scan Nov 26 03:47:46 kitschypi sudo[1118]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 26 03:47:46 kitschypi mpd[936]: Nov 26 03:47 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Nov 26 03:47:46 kitschypi ntpd[803]: error resolving pool 2.debian.pool.ntp.org: System error (-11) Nov 26 03:47:47 kitschypi systemd[1]: Started Music Player Daemon. Nov 26 03:47:47 kitschypi mpd_monitor.sh[649]: MPD restarted due to no mpc output. Nov 26 03:47:47 kitschypi bthelper[689]: Changing power off succeeded Nov 26 03:47:47 kitschypi bthelper[689]: [CHG] Controller DC:A6:32:79:DD:66 Class: 0x0000041c Nov 26 03:47:47 kitschypi bthelper[689]: Changing power on succeeded Nov 26 03:47:47 kitschypi ntpd[803]: error resolving pool 3.debian.pool.ntp.org: System error (-11) Nov 26 03:47:48 kitschypi volumio-remote-updater[665]: [2024-11-26 03:47:48] [info] asio async_connect error: system:111 (Connection refused) Nov 26 03:47:48 kitschypi volumio-remote-updater[665]: [2024-11-26 03:47:48] [info] Error getting remote endpoint: system:107 (Transport endpoint is not connected) Nov 26 03:47:48 kitschypi volumio-remote-updater[665]: [2024-11-26 03:47:48] [error] handle_connect error: Underlying Transport Error Nov 26 03:47:48 kitschypi volumio-time-update[676]: volumio-time-update-util: Fetching time from Volumio... Nov 26 03:47:48 kitschypi volumio-time-update[676]: volumio-time-update-util: Date not found in response Nov 26 03:47:48 kitschypi volumio-time-update[676]: volumio-time-update-util: Retrying in 5 seconds... Nov 26 03:47:49 kitschypi sudo[1118]: pam_unix(sudo:session): session closed for user root Nov 26 03:47:49 kitschypi wireless.js[667]: SETTING APPROPRIATE REG DOMAIN: US Nov 26 03:47:49 kitschypi sudo[1138]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 up Nov 26 03:47:49 kitschypi sudo[1138]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 26 03:47:49 kitschypi sudo[1138]: pam_unix(sudo:session): session closed for user root Nov 26 03:47:49 kitschypi sudo[1140]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iw reg set US Nov 26 03:47:49 kitschypi sudo[1140]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 26 03:47:49 kitschypi sudo[1140]: pam_unix(sudo:session): session closed for user root Nov 26 03:47:49 kitschypi wireless.js[667]: SUCCESSFULLY SET NEW REGDOMAIN: US Nov 26 03:47:49 kitschypi wireless.js[667]: Start wireless flow Nov 26 03:47:49 kitschypi wireless.js[667]: Stopped hotspot (if there).. Nov 26 03:47:49 kitschypi sudo[1145]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ip addr flush dev wlan0 Nov 26 03:47:49 kitschypi sudo[1145]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 26 03:47:49 kitschypi sudo[1145]: pam_unix(sudo:session): session closed for user root Nov 26 03:47:49 kitschypi sudo[1147]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 down Nov 26 03:47:49 kitschypi sudo[1147]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 26 03:47:49 kitschypi sudo[1147]: pam_unix(sudo:session): session closed for user root Nov 26 03:47:49 kitschypi wireless.js[667]: DHCP IP Nov 26 03:47:49 kitschypi wireless.js[667]: Start ap Nov 26 03:47:49 kitschypi wpa_supplicant[1149]: Successfully initialized wpa_supplicant Nov 26 03:47:49 kitschypi sudo[1150]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/dhcpcd Nov 26 03:47:49 kitschypi sudo[1150]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 26 03:47:49 kitschypi dhcpcd[1151]: dev: loaded udev Nov 26 03:47:49 kitschypi kernel: brcmfmac: brcmf_cfg80211_set_power_mgmt: power save disabled Nov 26 03:47:49 kitschypi dhcpcd-run-hooks[1169]: wlan0: starting wpa_supplicant Nov 26 03:47:50 kitschypi dhcpcd-run-hooks[1174]: wlan0: failed to start wpa_supplicant Nov 26 03:47:50 kitschypi dhcpcd-run-hooks[1175]: wlan0: Successfully initialized wpa_supplicant nl80211: kernel reports: Match already configured nl80211: kernel reports: Match already configured nl80211: kernel reports: Match already configured nl80211: kernel reports: Match already configured nl80211: kernel reports: Match already configured nl80211: kernel reports: Match already configured nl80211: kernel reports: Match already configured nl80211: kernel reports: Match already configured nl80211: kernel reports: Match already configured nl80211: kernel reports: Match already configured nl80211: kernel reports: Match already configured nl80211: kernel reports: Match already configured nl80211: kernel reports: Match already configured nl80211: kernel reports: Match already configured nl80211: kernel reports: Match already configured nl80211: kernel reports: Match already configured nl80211: kernel reports: Match already configured nl80211: kernel reports: Match already configured nl80211: kernel reports: Match already configured nl80211: kernel reports: Ma Nov 26 03:47:50 kitschypi dhcpcd[1151]: wlan0: connected to Access Point `' Nov 26 03:47:50 kitschypi dhcpcd[1151]: no interfaces have a carrier Nov 26 03:47:50 kitschypi dhcpcd[1151]: forked to background, child pid 1185 Nov 26 03:47:50 kitschypi dhcpcd[1185]: eth0: waiting for carrier Nov 26 03:47:50 kitschypi dhcpcd[1185]: wlan0: waiting for carrier Nov 26 03:47:50 kitschypi sudo[1150]: pam_unix(sudo:session): session closed for user root Nov 26 03:47:50 kitschypi wireless.js[667]: trying... Nov 26 03:47:50 kitschypi sudo[1187]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Nov 26 03:47:50 kitschypi sudo[1187]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 26 03:47:50 kitschypi sudo[1187]: pam_unix(sudo:session): session closed for user root Nov 26 03:47:51 kitschypi wireless.js[667]: trying... Nov 26 03:47:51 kitschypi sudo[1190]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Nov 26 03:47:51 kitschypi sudo[1190]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 26 03:47:51 kitschypi sudo[1190]: pam_unix(sudo:session): session closed for user root Nov 26 03:47:52 kitschypi wireless.js[667]: trying... Nov 26 03:47:52 kitschypi sudo[1193]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Nov 26 03:47:52 kitschypi sudo[1193]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 26 03:47:52 kitschypi sudo[1193]: pam_unix(sudo:session): session closed for user root Nov 26 03:47:53 kitschypi volumio-time-update[676]: volumio-time-update-util: Fetching time from Volumio... Nov 26 03:47:53 kitschypi volumio-time-update[676]: volumio-time-update-util: Date not found in response Nov 26 03:47:53 kitschypi volumio-time-update[676]: volumio-time-update-util: Retrying in 5 seconds... Nov 26 03:47:53 kitschypi wireless.js[667]: trying... Nov 26 03:47:53 kitschypi sudo[1201]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Nov 26 03:47:53 kitschypi sudo[1201]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 26 03:47:53 kitschypi sudo[1201]: pam_unix(sudo:session): session closed for user root Nov 26 03:47:53 kitschypi kernel: brcmfmac: brcmf_set_channel: set chanspec 0xd022 fail, reason -52 Nov 26 03:47:54 kitschypi kernel: brcmfmac: brcmf_set_channel: set chanspec 0xd026 fail, reason -52 Nov 26 03:47:54 kitschypi kernel: brcmfmac: brcmf_set_channel: set chanspec 0xd02a fail, reason -52 Nov 26 03:47:54 kitschypi kernel: brcmfmac: brcmf_set_channel: set chanspec 0xd02e fail, reason -52 Nov 26 03:47:54 kitschypi wireless.js[667]: trying... Nov 26 03:47:54 kitschypi sudo[1204]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Nov 26 03:47:54 kitschypi sudo[1204]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 26 03:47:54 kitschypi sudo[1204]: pam_unix(sudo:session): session closed for user root Nov 26 03:47:55 kitschypi volumio-remote-updater[665]: [2024-11-26 03:47:55] [info] asio async_connect error: system:111 (Connection refused) Nov 26 03:47:55 kitschypi volumio-remote-updater[665]: [2024-11-26 03:47:55] [info] Error getting remote endpoint: system:107 (Transport endpoint is not connected) Nov 26 03:47:55 kitschypi volumio-remote-updater[665]: [2024-11-26 03:47:55] [error] handle_connect error: Underlying Transport Error Nov 26 03:47:55 kitschypi wireless.js[667]: trying... Nov 26 03:47:55 kitschypi sudo[1207]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Nov 26 03:47:55 kitschypi sudo[1207]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 26 03:47:55 kitschypi sudo[1207]: pam_unix(sudo:session): session closed for user root Nov 26 03:47:56 kitschypi wpa_supplicant[1173]: wlan0: Trying to associate with SSID 'PublicGood' Nov 26 03:47:56 kitschypi wireless.js[667]: trying... Nov 26 03:47:56 kitschypi sudo[1210]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Nov 26 03:47:56 kitschypi sudo[1210]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 26 03:47:56 kitschypi sudo[1210]: pam_unix(sudo:session): session closed for user root Nov 26 03:47:56 kitschypi dhcpcd[1185]: wlan0: carrier acquired Nov 26 03:47:56 kitschypi wpa_supplicant[1173]: wlan0: Associated with 3c:84:6a:68:23:0b Nov 26 03:47:56 kitschypi wpa_supplicant[1173]: wlan0: CTRL-EVENT-CONNECTED - Connection to 3c:84:6a:68:23:0b completed [id=0 id_str=] Nov 26 03:47:56 kitschypi wpa_supplicant[1173]: wlan0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0 Nov 26 03:47:56 kitschypi wpa_supplicant[1173]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=COUNTRY_IE type=COUNTRY alpha2=US Nov 26 03:47:56 kitschypi dhcpcd[1185]: DUID 00:01:00:01:2a:5e:eb:68:b8:27:eb:b9:54:41 Nov 26 03:47:56 kitschypi dhcpcd[1185]: wlan0: IAID 32:79:dd:65 Nov 26 03:47:56 kitschypi dhcpcd[1185]: wlan0: adding address fe80::dea6:32ff:fe79:dd65 Nov 26 03:47:56 kitschypi dhcpcd[1185]: ipv6_addaddr1: Permission denied Nov 26 03:47:56 kitschypi dhcpcd[1185]: wlan0: carrier lost Nov 26 03:47:56 kitschypi dhcpcd[1185]: wlan0: carrier acquired Nov 26 03:47:56 kitschypi dhcpcd[1185]: wlan0: connected to Access Point `PublicGood' Nov 26 03:47:56 kitschypi dhcpcd[1185]: wlan0: IAID 32:79:dd:65 Nov 26 03:47:57 kitschypi dhcpcd[1185]: wlan0: soliciting an IPv6 router Nov 26 03:47:57 kitschypi wpa_supplicant[1173]: RRM: Ignoring radio measurement request: Not RRM network Nov 26 03:47:57 kitschypi wireless.js[667]: trying... Nov 26 03:47:57 kitschypi sudo[1229]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Nov 26 03:47:57 kitschypi sudo[1229]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 26 03:47:57 kitschypi sudo[1229]: pam_unix(sudo:session): session closed for user root Nov 26 03:47:57 kitschypi dhcpcd[1185]: wlan0: rebinding lease of 192.168.68.103 Nov 26 03:47:57 kitschypi dhcpcd[1185]: wlan0: probing address 192.168.68.103/24 Nov 26 03:47:58 kitschypi volumio-time-update[676]: volumio-time-update-util: Fetching time from Volumio... Nov 26 03:47:58 kitschypi volumio-time-update[676]: volumio-time-update-util: Date not found in response Nov 26 03:47:58 kitschypi volumio-time-update[676]: volumio-time-update-util: Retrying in 5 seconds... Nov 26 03:47:58 kitschypi wireless.js[667]: trying... Nov 26 03:47:58 kitschypi sudo[1237]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Nov 26 03:47:58 kitschypi sudo[1237]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 26 03:47:58 kitschypi sudo[1237]: pam_unix(sudo:session): session closed for user root Nov 26 03:47:59 kitschypi wireless.js[667]: trying... Nov 26 03:47:59 kitschypi sudo[1240]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Nov 26 03:47:59 kitschypi sudo[1240]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 26 03:47:59 kitschypi sudo[1240]: pam_unix(sudo:session): session closed for user root Nov 26 03:48:00 kitschypi wireless.js[667]: trying... Nov 26 03:48:00 kitschypi sudo[1243]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Nov 26 03:48:00 kitschypi sudo[1243]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 26 03:48:00 kitschypi sudo[1243]: pam_unix(sudo:session): session closed for user root Nov 26 03:48:01 kitschypi wireless.js[667]: trying... Nov 26 03:48:01 kitschypi sudo[1246]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Nov 26 03:48:01 kitschypi sudo[1246]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 26 03:48:01 kitschypi sudo[1246]: pam_unix(sudo:session): session closed for user root Nov 26 03:48:02 kitschypi wireless.js[667]: trying... Nov 26 03:48:02 kitschypi sudo[1249]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Nov 26 03:48:02 kitschypi sudo[1249]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 26 03:48:02 kitschypi sudo[1249]: pam_unix(sudo:session): session closed for user root Nov 26 03:48:03 kitschypi dhcpcd[1185]: wlan0: leased 192.168.68.103 for 7200 seconds Nov 26 03:48:03 kitschypi avahi-daemon[650]: Joining mDNS multicast group on interface wlan0.IPv4 with address 192.168.68.103. Nov 26 03:48:03 kitschypi avahi-daemon[650]: New relevant interface wlan0.IPv4 for mDNS. Nov 26 03:48:03 kitschypi dhcpcd[1185]: wlan0: adding route to 192.168.68.0/24 Nov 26 03:48:03 kitschypi avahi-daemon[650]: Registering new address record for 192.168.68.103 on wlan0.IPv4. Nov 26 03:48:03 kitschypi dhcpcd[1185]: wlan0: adding default route via 192.168.68.1 Nov 26 03:48:03 kitschypi volumio-time-update[676]: volumio-time-update-util: Fetching time from Volumio... Nov 26 03:48:03 kitschypi volumio-time-update[676]: volumio-time-update-util: Setting system time to: 2024-11-26 03:48:36 Nov 26 03:48:03 kitschypi wireless.js[667]: trying... Nov 26 03:48:03 kitschypi sudo[1276]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/bin/timedatectl set-time 2024-11-26 03:48:36 Nov 26 03:48:03 kitschypi sudo[1276]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 26 03:48:03 kitschypi sudo[1278]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Nov 26 03:48:03 kitschypi sudo[1278]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 26 03:48:03 kitschypi sudo[1278]: pam_unix(sudo:session): session closed for user root Nov 26 03:48:03 kitschypi wireless.js[667]: Connected to: ----PublicGood Nov 26 03:48:03 kitschypi wireless.js[667]: ---- Nov 26 03:48:03 kitschypi dbus-daemon[659]: [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service' requested by ':1.9' (uid=0 pid=1279 comm="timedatectl set-time 2024-11-26 03:48:36 ") Nov 26 03:48:03 kitschypi sudo[1282]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Nov 26 03:48:03 kitschypi sudo[1282]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 26 03:48:03 kitschypi sudo[1282]: pam_unix(sudo:session): session closed for user root Nov 26 03:48:03 kitschypi wireless.js[667]: ... joined AP, wlan0 IPv4 is 192.168.68.103, ipV6 is undefined Nov 26 03:48:03 kitschypi wireless.js[667]: It's done! AP Nov 26 03:48:03 kitschypi systemd[1]: Starting Time & Date Service... Nov 26 03:48:03 kitschypi systemd[1]: Started Wireless Services. Nov 26 03:48:03 kitschypi kernel: brcmfmac: brcmf_cfg80211_set_power_mgmt: power save disabled Nov 26 03:48:03 kitschypi systemd[1]: Started Volumio Backend Module. Nov 26 03:48:03 kitschypi systemd[1]: Started Volumio Cpu Tweaker. Nov 26 03:48:03 kitschypi volumio-cpu-tweak[1289]: Setting RT Priority for mpd Nov 26 03:48:03 kitschypi volumio-cpu-tweak[1289]: Setting MPD Affinity Nov 26 03:48:03 kitschypi volumio-cpu-tweak[1289]: pid 936's current affinity mask: f Nov 26 03:48:03 kitschypi volumio-cpu-tweak[1289]: pid 936's new affinity mask: 3 Nov 26 03:48:04 kitschypi volumio-cpu-tweak[1289]: /bin/volumio_cpu_tweak: line 27: warning: command substitution: ignored null byte in input Nov 26 03:48:04 kitschypi volumio-cpu-tweak[1289]: VOLUMIO CPU TWEAK: Setting CPU Governor: performance Nov 26 03:48:04 kitschypi dbus-daemon[659]: [system] Successfully activated service 'org.freedesktop.timedate1' Nov 26 03:48:04 kitschypi systemd[1]: Started Time & Date Service. Nov 26 03:48:36 kitschypi systemd-timedated[1284]: Changed local time to Tue Nov 26 03:48:36 2024 Nov 26 03:48:36 kitschypi sudo[1276]: pam_unix(sudo:session): session closed for user root Nov 26 03:48:36 kitschypi volumio-time-update[676]: volumio-time-update-util: System time updated successfully. Nov 26 03:48:36 kitschypi systemd[1]: Started Volumio Time Update Utility. Nov 26 03:48:36 kitschypi systemd[1]: volumio_cpu_tweak.service: Succeeded. Nov 26 03:48:36 kitschypi ntpd[803]: Listen normally on 3 wlan0 192.168.68.103:123 Nov 26 03:48:36 kitschypi ntpd[803]: new interface(s) found: waking up resolver Nov 26 03:48:37 kitschypi nmbd[791]: [2024/11/26 03:48:37.223438, 0] ../lib/util/become_daemon.c:138(daemon_ready) Nov 26 03:48:37 kitschypi systemd[1]: Started Samba NMB Daemon. Nov 26 03:48:37 kitschypi nmbd[791]: daemon_ready: STATUS=daemon 'nmbd' finished starting up and ready to serve connections Nov 26 03:48:37 kitschypi systemd[1]: Starting Samba Winbind Daemon... Nov 26 03:48:37 kitschypi winbindd[1305]: [2024/11/26 03:48:37.481041, 0] ../source3/winbindd/winbindd_cache.c:3160(initialize_winbindd_cache) Nov 26 03:48:37 kitschypi winbindd[1305]: initialize_winbindd_cache: clearing cache and re-creating with version number 2 Nov 26 03:48:37 kitschypi winbindd[1305]: [2024/11/26 03:48:37.499062, 0] ../lib/util/become_daemon.c:138(daemon_ready) Nov 26 03:48:37 kitschypi systemd[1]: Started Samba Winbind Daemon. Nov 26 03:48:37 kitschypi winbindd[1305]: daemon_ready: STATUS=daemon 'winbindd' finished starting up and ready to serve connections Nov 26 03:48:37 kitschypi systemd[1]: Starting Samba SMB Daemon... Nov 26 03:48:37 kitschypi volumio[1288]: info: ------------------------------------------- Nov 26 03:48:37 kitschypi volumio[1288]: info: ----- Volumio3 ---- Nov 26 03:48:37 kitschypi volumio[1288]: info: ------------------------------------------- Nov 26 03:48:37 kitschypi volumio[1288]: info: ----- System startup ---- Nov 26 03:48:37 kitschypi volumio[1288]: info: ------------------------------------------- Nov 26 03:48:37 kitschypi volumio-remote-updater[665]: [2024-11-26 03:48:37] [connect] Successful connection Nov 26 03:48:37 kitschypi smbd[1318]: [2024/11/26 03:48:37.901870, 0] ../lib/util/become_daemon.c:138(daemon_ready) Nov 26 03:48:37 kitschypi smbd[1318]: daemon_ready: STATUS=daemon 'smbd' finished starting up and ready to serve connections Nov 26 03:48:37 kitschypi systemd[1]: Started Samba SMB Daemon. Nov 26 03:48:37 kitschypi systemd[1]: Reached target Multi-User System. Nov 26 03:48:37 kitschypi systemd[1]: Reached target Graphical Interface. Nov 26 03:48:37 kitschypi systemd[1]: Starting Update UTMP about System Runlevel Changes... Nov 26 03:48:37 kitschypi systemd[1]: systemd-update-utmp-runlevel.service: Succeeded. Nov 26 03:48:37 kitschypi systemd[1]: Started Update UTMP about System Runlevel Changes. Nov 26 03:48:37 kitschypi systemd[1]: Startup finished in 13.747s (kernel) + 30.782s (userspace) = 44.529s. Nov 26 03:48:38 kitschypi volumio[1288]: info: MYVOLUMIO Environment detected Nov 26 03:48:38 kitschypi volumio[1288]: info: Plugin folders cleanup Nov 26 03:48:38 kitschypi volumio[1288]: info: Scanning into folder /volumio/app/plugins/ Nov 26 03:48:38 kitschypi volumio[1288]: info: Scanning category audio_interface Nov 26 03:48:38 kitschypi volumio[1288]: info: Scanning category miscellanea Nov 26 03:48:38 kitschypi volumio[1288]: info: Scanning category music_service Nov 26 03:48:38 kitschypi volumio[1288]: info: Scanning category plugins.json Nov 26 03:48:38 kitschypi volumio[1288]: info: Scanning category system_controller Nov 26 03:48:38 kitschypi volumio[1288]: info: Scanning category user_interface Nov 26 03:48:38 kitschypi volumio[1288]: info: Scanning into folder /data/plugins/ Nov 26 03:48:38 kitschypi volumio[1288]: info: Scanning category music_service Nov 26 03:48:38 kitschypi volumio[1288]: info: Scanning category user_interface Nov 26 03:48:38 kitschypi volumio[1288]: info: Plugin folders cleanup completed Nov 26 03:48:38 kitschypi volumio[1288]: info: ------------------------------------------- Nov 26 03:48:38 kitschypi volumio[1288]: info: ----- Core plugins startup ---- Nov 26 03:48:38 kitschypi volumio[1288]: info: ------------------------------------------- Nov 26 03:48:38 kitschypi volumio[1288]: info: Loading plugins from folder /volumio/app/plugins/ Nov 26 03:48:38 kitschypi volumio[1288]: info: Adding plugin upnp to MyMusic Plugins Nov 26 03:48:38 kitschypi volumio[1288]: info: Adding plugin airplay_emulation to MyMusic Plugins Nov 26 03:48:38 kitschypi volumio[1288]: info: Adding plugin upnp_browser to MyMusic Plugins Nov 26 03:48:38 kitschypi volumio[1288]: info: Loading plugins from folder /data/plugins/ Nov 26 03:48:38 kitschypi volumio[1288]: info: Loading plugin "system"... Nov 26 03:48:38 kitschypi volumio[1288]: info: Loading plugin "appearance"... Nov 26 03:48:39 kitschypi volumio[1288]: info: Loading plugin "network"... Nov 26 03:48:39 kitschypi volumio[1288]: info: Refreshing Cached IP Addresses Nov 26 03:48:39 kitschypi sudo[1336]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Nov 26 03:48:39 kitschypi sudo[1336]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 26 03:48:39 kitschypi sudo[1338]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Nov 26 03:48:39 kitschypi sudo[1336]: pam_unix(sudo:session): session closed for user root Nov 26 03:48:39 kitschypi sudo[1338]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 26 03:48:39 kitschypi sudo[1338]: pam_unix(sudo:session): session closed for user root Nov 26 03:48:39 kitschypi volumio[1288]: info: Loading plugin "services"... Nov 26 03:48:39 kitschypi volumio[1288]: info: Loading plugin "alsa_controller"... Nov 26 03:48:39 kitschypi sudo[1347]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Nov 26 03:48:39 kitschypi sudo[1347]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 26 03:48:39 kitschypi volumio[1288]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Nov 26 03:48:39 kitschypi volumio[1288]: info: Loading plugin "wizard"... Nov 26 03:48:39 kitschypi volumio[1288]: info: Loading plugin "networkfs"... Nov 26 03:48:39 kitschypi volumio[1288]: info: Starting Udev Watcher for removable devices Nov 26 03:48:39 kitschypi sudo[1364]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o guest,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //192.168.68.102/USB/library/Music /mnt/NAS/HiFiPi Nov 26 03:48:39 kitschypi sudo[1364]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 26 03:48:39 kitschypi volumio[1288]: info: Ignoring mount for partition: boot Nov 26 03:48:39 kitschypi volumio[1288]: info: Ignoring mount for partition: volumio Nov 26 03:48:39 kitschypi volumio[1288]: info: Ignoring mount for partition: volumio_data Nov 26 03:48:39 kitschypi volumio[1288]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Nov 26 03:48:39 kitschypi volumio[1288]: info: Loading plugin "volumio_command_line_client"... Nov 26 03:48:39 kitschypi volumio[1288]: info: Loading plugin "upnp"... Nov 26 03:48:39 kitschypi volumio[1288]: info: [1732592919705] Starting Upmpd Daemon Nov 26 03:48:39 kitschypi volumio[1288]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Nov 26 03:48:39 kitschypi volumio[1288]: info: Loading plugin "my_music"... Nov 26 03:48:39 kitschypi volumio[1288]: info: Loading plugin "mpd"... Nov 26 03:48:39 kitschypi kernel: Key type cifs.spnego registered Nov 26 03:48:39 kitschypi kernel: Key type cifs.idmap registered Nov 26 03:48:39 kitschypi kernel: CIFS: No dialect specified on mount. Default has changed to a more secure dialect, SMB2.1 or later (e.g. SMB3.1.1), from CIFS (SMB1). To use the less secure SMB1 dialect to access old servers which do not support SMB3.1.1 (or even SMB3 or SMB2.1) specify vers=1.0 on mount. Nov 26 03:48:39 kitschypi kernel: CIFS: Attempting to mount //192.168.68.102/USB/library/Music Nov 26 03:48:40 kitschypi volumio[1288]: info: Loading plugin "upnp_browser"... Nov 26 03:48:40 kitschypi volumio[1288]: info: Loading plugin "alarm-clock"... Nov 26 03:48:40 kitschypi volumio[1288]: info: Loading plugin "airplay_emulation"... Nov 26 03:48:40 kitschypi volumio[1288]: info: Starting Shairport Sync Nov 26 03:48:40 kitschypi volumio[1288]: info: Loading plugin "last_100"... Nov 26 03:48:40 kitschypi volumio[1288]: info: Loading plugin "webradio"... Nov 26 03:48:40 kitschypi sudo[1364]: pam_unix(sudo:session): session closed for user root Nov 26 03:48:40 kitschypi volumio[1288]: info: Loading plugin "i2s_dacs"... Nov 26 03:48:40 kitschypi volumio[1288]: info: Loading plugin "volumiodiscovery"... Nov 26 03:48:40 kitschypi volumio[1288]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Nov 26 03:48:40 kitschypi volumio[1288]: *** WARNING *** Please fix your application to use the native API of Avahi! Nov 26 03:48:40 kitschypi volumio[1288]: *** WARNING *** For more information see Nov 26 03:48:40 kitschypi node[1288]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Nov 26 03:48:40 kitschypi volumio[1288]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Nov 26 03:48:40 kitschypi volumio[1288]: *** WARNING *** Please fix your application to use the native API of Avahi! Nov 26 03:48:40 kitschypi volumio[1288]: *** WARNING *** For more information see Nov 26 03:48:40 kitschypi node[1288]: *** WARNING *** Please fix your application to use the native API of Avahi! Nov 26 03:48:40 kitschypi node[1288]: *** WARNING *** For more information see Nov 26 03:48:40 kitschypi node[1288]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Nov 26 03:48:40 kitschypi node[1288]: *** WARNING *** Please fix your application to use the native API of Avahi! Nov 26 03:48:40 kitschypi node[1288]: *** WARNING *** For more information see Nov 26 03:48:40 kitschypi volumio[1288]: info: Applying required configuration parameters for plugin volumiodiscovery Nov 26 03:48:40 kitschypi volumio[1288]: info: Discovery: Started advertising with name: KitschyPi Nov 26 03:48:40 kitschypi volumio[1288]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Nov 26 03:48:40 kitschypi volumio[1288]: info: Loading plugin "spop"... Nov 26 03:48:41 kitschypi volumio[1288]: info: Loading plugin "now_playing"... Nov 26 03:48:42 kitschypi volumio[1288]: info: Loading plugin "outputs"... Nov 26 03:48:42 kitschypi volumio[1288]: info: Loading plugin "albumart"... Nov 26 03:48:42 kitschypi volumio[1288]: info: Plugin example_plugin is not enabled Nov 26 03:48:42 kitschypi volumio[1288]: info: Loading plugin "inputs"... Nov 26 03:48:42 kitschypi volumio[1288]: info: Loading plugin "updater_comm"... Nov 26 03:48:42 kitschypi systemd[1]: systemd-fsckd.service: Succeeded. Nov 26 03:48:42 kitschypi volumio[1288]: info: Plugin mpdemulation is not enabled Nov 26 03:48:42 kitschypi volumio[1288]: info: Loading plugin "rest_api"... Nov 26 03:48:42 kitschypi volumio[1288]: info: Loading plugin "websocket"... Nov 26 03:48:42 kitschypi volumio[1288]: info: Starting Socket.io Server version 2.3.0 Nov 26 03:48:42 kitschypi volumio[1288]: info: Loading plugin "touch_display"... Nov 26 03:48:42 kitschypi volumio[1288]: Forking 3 albumart workers Nov 26 03:48:43 kitschypi volumio[1288]: info: Applying required configuration parameters for plugin touch_display Nov 26 03:48:43 kitschypi volumio[1288]: info: Loading i18n strings for locale en Nov 26 03:48:43 kitschypi volumio[1288]: Updating browse sources language Nov 26 03:48:43 kitschypi volumio[1288]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 26 03:48:43 kitschypi volumio[1288]: Starting albumart workers Nov 26 03:48:43 kitschypi volumio[1288]: Starting albumart workers Nov 26 03:48:43 kitschypi volumio[1288]: Starting albumart workers Nov 26 03:48:43 kitschypi sudo[1347]: pam_unix(sudo:session): session closed for user root Nov 26 03:48:43 kitschypi volumio[1288]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Nov 26 03:48:43 kitschypi volumio[1288]: info: CoreCommandRouter::initPlayerControls Nov 26 03:48:43 kitschypi volumio[1288]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 26 03:48:43 kitschypi volumio[1288]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 26 03:48:43 kitschypi volumio[1288]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 26 03:48:43 kitschypi volumio[1288]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 26 03:48:43 kitschypi volumio[1288]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 26 03:48:43 kitschypi volumio[1288]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 26 03:48:43 kitschypi volumio[1288]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 26 03:48:43 kitschypi volumio[1288]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 26 03:48:43 kitschypi volumio[1288]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Nov 26 03:48:43 kitschypi volumio[1288]: Express server listening on port 3000 Nov 26 03:48:43 kitschypi volumio[1288]: [Metrics] WebUI: 6s 772.46ms Nov 26 03:48:43 kitschypi volumio[1288]: info: CoreStateMachine::resetVolumioState Nov 26 03:48:43 kitschypi volumio[1288]: info: CoreStateMachine::getcurrentVolume Nov 26 03:48:43 kitschypi volumio[1288]: info: CoreCommandRouter::volumioRetrievevolume Nov 26 03:48:43 kitschypi volumio[1288]: info: Volumio Network Manager: Network status updated: 2 Nov 26 03:48:44 kitschypi volumio[1288]: verbose: New Socket.io Connection to 192.168.68.103:3000 from 192.168.68.102 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 1 Nov 26 03:48:44 kitschypi volumio[1288]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Nov 26 03:48:44 kitschypi volumio[1288]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Nov 26 03:48:44 kitschypi volumio[1288]: info: Discovery: Getting this device information Nov 26 03:48:44 kitschypi volumio[1288]: info: CoreCommandRouter::volumioGetState Nov 26 03:48:44 kitschypi volumio[1288]: info: CorePlayQueue::getTrack 0 Nov 26 03:48:44 kitschypi volumio[1288]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Nov 26 03:48:44 kitschypi volumio[1288]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Nov 26 03:48:44 kitschypi volumio[1288]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 26 03:48:44 kitschypi volumio[1288]: info: Reloading queue from file Nov 26 03:48:44 kitschypi volumio[1288]: info: VolumeController:: Volume=79 Mute =false Nov 26 03:48:44 kitschypi volumio[1288]: info: CoreStateMachine::pushState Nov 26 03:48:44 kitschypi volumio[1288]: info: CorePlayQueue::getTrack 0 Nov 26 03:48:44 kitschypi volumio[1288]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 26 03:48:44 kitschypi volumio[1288]: info: CoreCommandRouter::volumioPushState Nov 26 03:48:44 kitschypi volumio[1288]: info: CoreStateMachine::updateTrackBlock Nov 26 03:48:44 kitschypi volumio[1288]: info: CorePlayQueue::getTrackBlock Nov 26 03:48:44 kitschypi volumio[1288]: info: CoreCommandRouter::volumioRetrievevolume Nov 26 03:48:44 kitschypi volumio[1288]: info: Setting Device type: Raspberry PI Nov 26 03:48:44 kitschypi volumio[1288]: info: CoreStateMachine::setRepeat null single undefined Nov 26 03:48:44 kitschypi volumio[1288]: info: CoreStateMachine::pushState Nov 26 03:48:44 kitschypi volumio[1288]: info: CorePlayQueue::getTrack 0 Nov 26 03:48:44 kitschypi volumio[1288]: info: CoreCommandRouter::volumioPushState Nov 26 03:48:44 kitschypi volumio[1288]: info: CoreStateMachine::setRandom false Nov 26 03:48:44 kitschypi volumio[1288]: info: CoreStateMachine::pushState Nov 26 03:48:44 kitschypi volumio[1288]: info: CorePlayQueue::getTrack 0 Nov 26 03:48:44 kitschypi volumio[1288]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 26 03:48:44 kitschypi volumio[1288]: info: CoreCommandRouter::volumioPushState Nov 26 03:48:44 kitschypi volumio[1288]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , initSocket Nov 26 03:48:44 kitschypi volumio[1288]: info: Completed loading Core Plugins Nov 26 03:48:44 kitschypi volumio[1288]: info: Preparing to generate the ALSA configuration file Nov 26 03:48:44 kitschypi volumio[1288]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Nov 26 03:48:44 kitschypi volumio[1288]: info: USB Boot Capable - System SBC Revision found in cpuinfo: c03112 Nov 26 03:48:44 kitschypi volumio[1288]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Nov 26 03:48:44 kitschypi sh[547]: timed out Nov 26 03:48:44 kitschypi dhcpcd[596]: timed out Nov 26 03:48:44 kitschypi sh[547]: dhcpcd exited Nov 26 03:48:44 kitschypi dhcpcd[596]: dhcpcd exited Nov 26 03:48:44 kitschypi volumio[1288]: info: CoreCommandRouter::volumioGetState Nov 26 03:48:44 kitschypi volumio[1288]: info: CorePlayQueue::getTrack 0 Nov 26 03:48:44 kitschypi sh[547]: ifup: failed to bring up eth0 Nov 26 03:48:44 kitschypi systemd[1]: ifup@eth0.service: Main process exited, code=exited, status=1/FAILURE Nov 26 03:48:44 kitschypi systemd[1]: ifup@eth0.service: Failed with result 'exit-code'. Nov 26 03:48:44 kitschypi volumio[1288]: info: Asound.conf file unchanged, so no further update is needed Nov 26 03:48:44 kitschypi volumio[1288]: info: Output device has changed, restarting MPD Nov 26 03:48:44 kitschypi sudo[1459]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Nov 26 03:48:44 kitschypi volumio[1288]: info: Output device has changed, restarting Shairport Sync Nov 26 03:48:44 kitschypi volumio[1288]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 26 03:48:44 kitschypi sudo[1459]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 26 03:48:44 kitschypi volumio[1288]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 26 03:48:44 kitschypi sudo[1459]: pam_unix(sudo:session): session closed for user root Nov 26 03:48:44 kitschypi sudo[1461]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Nov 26 03:48:44 kitschypi sudo[1461]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 26 03:48:44 kitschypi systemd[1]: Stopping Music Player Daemon... Nov 26 03:48:44 kitschypi volumio[1288]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Nov 26 03:48:44 kitschypi volumio[1288]: info: ___________ START PLUGINS ___________ Nov 26 03:48:44 kitschypi volumio[1288]: info: ControllerMpd::onStart: Initializing MPD Nov 26 03:48:44 kitschypi volumio[1288]: info: Creating MPD Configuration file Nov 26 03:48:44 kitschypi sudo[1468]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Nov 26 03:48:44 kitschypi volumio[1288]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Nov 26 03:48:44 kitschypi volumio[1288]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Nov 26 03:48:44 kitschypi volumio[1288]: info: [1732592924342] CoreMusicLibrary::Adding element Media Servers Nov 26 03:48:44 kitschypi sudo[1468]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 26 03:48:44 kitschypi volumio[1288]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 26 03:48:44 kitschypi sudo[1468]: pam_unix(sudo:session): session closed for user root Nov 26 03:48:44 kitschypi sudo[1470]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Nov 26 03:48:44 kitschypi sudo[1470]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 26 03:48:44 kitschypi volumio[1288]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 26 03:48:44 kitschypi volumio[1288]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 26 03:48:44 kitschypi volumio[1288]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Nov 26 03:48:44 kitschypi volumio[1288]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 26 03:48:44 kitschypi volumio[1288]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 26 03:48:44 kitschypi systemd[1]: mpd.service: Succeeded. Nov 26 03:48:44 kitschypi systemd[1]: Stopped Music Player Daemon. Nov 26 03:48:44 kitschypi volumio[1288]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Nov 26 03:48:44 kitschypi volumio[1288]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Nov 26 03:48:44 kitschypi volumio[1288]: info: [1732592924429] CoreMusicLibrary::Adding element Last_100 Nov 26 03:48:44 kitschypi volumio[1288]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 26 03:48:44 kitschypi volumio[1288]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Nov 26 03:48:44 kitschypi volumio[1288]: info: [1732592924431] CoreMusicLibrary::Adding element Webradio Nov 26 03:48:44 kitschypi volumio[1288]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 26 03:48:44 kitschypi volumio[1288]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Nov 26 03:48:44 kitschypi volumio[1288]: info: Initializing BBC Radios Nov 26 03:48:44 kitschypi systemd[1]: Starting Music Player Daemon... Nov 26 03:48:44 kitschypi volumio[1288]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Nov 26 03:48:44 kitschypi volumio[1288]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 26 03:48:44 kitschypi volumio[1288]: info: Creating Spotify config file Nov 26 03:48:44 kitschypi volumio[1288]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 26 03:48:44 kitschypi sudo[1479]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Nov 26 03:48:44 kitschypi sudo[1479]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 26 03:48:44 kitschypi sudo[1479]: pam_unix(sudo:session): session closed for user root Nov 26 03:48:44 kitschypi volumio[1288]: info: [now-playing-config] Config is up to date. Nov 26 03:48:44 kitschypi volumio[1288]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Nov 26 03:48:44 kitschypi volumio[1288]: info: Discovery: Getting this device information Nov 26 03:48:44 kitschypi volumio[1288]: info: CoreCommandRouter::volumioGetState Nov 26 03:48:44 kitschypi volumio[1288]: info: CorePlayQueue::getTrack 0 Nov 26 03:48:44 kitschypi volumio[1288]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Nov 26 03:48:44 kitschypi volumio[1288]: info: Loading i18n strings for locale en Nov 26 03:48:44 kitschypi volumio[1288]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Nov 26 03:48:44 kitschypi volumio[1288]: info: Volumio Calling Home Nov 26 03:48:44 kitschypi volumio[1288]: info: [now-playing-app] App is listening on port 4004. Nov 26 03:48:44 kitschypi sudo[1496]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop getty@tty1.service Nov 26 03:48:44 kitschypi sudo[1496]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 26 03:48:44 kitschypi sudo[1498]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl disable getty@tty1.service Nov 26 03:48:44 kitschypi sudo[1501]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl daemon-reload Nov 26 03:48:44 kitschypi sudo[1501]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 26 03:48:44 kitschypi sudo[1498]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 26 03:48:44 kitschypi systemd[1]: Reloading. Nov 26 03:48:44 kitschypi sudo[1496]: pam_unix(sudo:session): session closed for user root Nov 26 03:48:44 kitschypi volumio[1288]: info: VolumeController:: Volume=79 Mute =false Nov 26 03:48:44 kitschypi volumio[1288]: info: CoreStateMachine::pushState Nov 26 03:48:44 kitschypi volumio[1288]: info: CorePlayQueue::getTrack 0 Nov 26 03:48:44 kitschypi volumio[1288]: info: CoreCommandRouter::volumioPushState Nov 26 03:48:44 kitschypi volumio[1288]: info: Discovery: adding 0034b1d0-6179-4523-8966-2692a7fb32c0 Nov 26 03:48:44 kitschypi volumio[1288]: info: Discovery: Found device Hifipi Nov 26 03:48:44 kitschypi volumio[1288]: info: Discovery: Connecting to remote: 192.168.68.102 Nov 26 03:48:44 kitschypi volumio[1288]: info: Discovery: adding f54b7432-1348-4ff0-81b5-e7447aeb97bd Nov 26 03:48:44 kitschypi volumio[1288]: info: Discovery: Found device KitschyPi Nov 26 03:48:44 kitschypi volumio[1288]: info: CoreCommandRouter::volumioGetState Nov 26 03:48:44 kitschypi volumio[1288]: info: CorePlayQueue::getTrack 0 Nov 26 03:48:44 kitschypi volumio[1288]: info: touch_display: Backlight interface detected. Nov 26 03:48:44 kitschypi volumio[1288]: info: touch_display: systemctl stop getty@tty1.service succeeded. Nov 26 03:48:44 kitschypi volumio[1288]: info: MPD Permissions set Nov 26 03:48:44 kitschypi volumio[1288]: info: MPD Permissions set Nov 26 03:48:44 kitschypi volumio[1288]: info: Spotify config file written Nov 26 03:48:44 kitschypi volumio[1288]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Nov 26 03:48:44 kitschypi sudo[1509]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Nov 26 03:48:44 kitschypi sudo[1509]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 26 03:48:44 kitschypi volumio[1288]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 26 03:48:44 kitschypi volumio[1288]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 26 03:48:44 kitschypi volumio[1288]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 26 03:48:44 kitschypi volumio[1288]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 26 03:48:44 kitschypi volumio[1288]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 26 03:48:44 kitschypi volumio[1288]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 26 03:48:44 kitschypi volumio[1288]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 26 03:48:44 kitschypi volumio[1288]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 26 03:48:44 kitschypi volumio[1288]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 26 03:48:44 kitschypi volumio[1288]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 26 03:48:44 kitschypi volumio[1288]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 26 03:48:44 kitschypi volumio[1288]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 26 03:48:44 kitschypi volumio[1288]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 26 03:48:44 kitschypi volumio[1288]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 26 03:48:44 kitschypi volumio[1288]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 26 03:48:44 kitschypi volumio[1288]: info: No need to fix Spotify hosts Nov 26 03:48:44 kitschypi volumio[1288]: info: Discovery: Connected to remote: 192.168.68.102 Nov 26 03:48:44 kitschypi systemd[1]: /lib/systemd/system/winbind.service:8: PIDFile= references path below legacy directory /var/run/, updating /var/run/samba/winbindd.pid → /run/samba/winbindd.pid; please update the unit file accordingly. Nov 26 03:48:45 kitschypi volumio[1288]: info: Volumio called home Nov 26 03:48:45 kitschypi volumio[1288]: info: touch_display: Raspberry Pi Foundation touch screen detected. Nov 26 03:48:45 kitschypi sudo[1529]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod a+rw /etc/X11/xorg.conf.d/99-vc4.conf Nov 26 03:48:45 kitschypi sudo[1529]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 26 03:48:45 kitschypi sudo[1531]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod a+w /sys/class/backlight/rpi_backlight/brightness Nov 26 03:48:45 kitschypi sudo[1531]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 26 03:48:45 kitschypi sudo[1529]: pam_unix(sudo:session): session closed for user root Nov 26 03:48:45 kitschypi volumio[1288]: info: Starting Shairport Sync Nov 26 03:48:45 kitschypi sudo[1531]: pam_unix(sudo:session): session closed for user root Nov 26 03:48:45 kitschypi volumio[1288]: info: Starting Shairport Sync Nov 26 03:48:45 kitschypi sudo[1535]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Nov 26 03:48:45 kitschypi volumio[1288]: info: Starting Shairport Sync Nov 26 03:48:45 kitschypi sudo[1535]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 26 03:48:45 kitschypi sudo[1537]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Nov 26 03:48:45 kitschypi sudo[1537]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 26 03:48:45 kitschypi sudo[1541]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Nov 26 03:48:45 kitschypi sudo[1541]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 26 03:48:45 kitschypi volumio[1288]: info: CoreCommandRouter::volumioGetState Nov 26 03:48:45 kitschypi volumio[1288]: info: CorePlayQueue::getTrack 0 Nov 26 03:48:45 kitschypi volumio[1288]: info: touch_display: File permissions for backlight brightness control set. Nov 26 03:48:45 kitschypi volumio[1288]: info: touch_display: File permissions for /etc/X11/xorg.conf.d/99-vc4.conf set. Nov 26 03:48:45 kitschypi sudo[1501]: pam_unix(sudo:session): session closed for user root Nov 26 03:48:45 kitschypi volumio[1288]: info: touch_display: systemctl daemon-reload succeeded. Nov 26 03:48:45 kitschypi mpd[1491]: Nov 26 03:48 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Nov 26 03:48:45 kitschypi systemd[1]: Reloading. Nov 26 03:48:45 kitschypi sudo[1544]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumio-kiosk.service Nov 26 03:48:45 kitschypi sudo[1544]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 26 03:48:45 kitschypi systemd[1]: /lib/systemd/system/winbind.service:8: PIDFile= references path below legacy directory /var/run/, updating /var/run/samba/winbindd.pid → /run/samba/winbindd.pid; please update the unit file accordingly. Nov 26 03:48:45 kitschypi systemd[1]: Started Music Player Daemon. Nov 26 03:48:45 kitschypi sudo[1498]: pam_unix(sudo:session): session closed for user root Nov 26 03:48:45 kitschypi sudo[1461]: pam_unix(sudo:session): session closed for user root Nov 26 03:48:45 kitschypi volumio[1288]: info: touch_display: systemctl disable getty@tty1.service succeeded. Nov 26 03:48:45 kitschypi sudo[1470]: pam_unix(sudo:session): session closed for user root Nov 26 03:48:46 kitschypi systemd[1]: Started Volumio Kiosk. Nov 26 03:48:46 kitschypi sudo[1544]: pam_unix(sudo:session): session closed for user root Nov 26 03:48:46 kitschypi systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Nov 26 03:48:46 kitschypi systemd[1]: Started go-librespot Daemon. Nov 26 03:48:46 kitschypi sudo[1509]: pam_unix(sudo:session): session closed for user root Nov 26 03:48:46 kitschypi systemd[1]: shairport-sync.service: Succeeded. Nov 26 03:48:46 kitschypi systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Nov 26 03:48:46 kitschypi go-librespot[1565]: Librespot-go daemon starting... Nov 26 03:48:46 kitschypi systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Nov 26 03:48:46 kitschypi sudo[1537]: pam_unix(sudo:session): session closed for user root Nov 26 03:48:46 kitschypi sudo[1535]: pam_unix(sudo:session): session closed for user root Nov 26 03:48:46 kitschypi sudo[1541]: pam_unix(sudo:session): session closed for user root Nov 26 03:48:46 kitschypi volumio[1288]: error: MPD error: The expression evaluated to a falsy value: Nov 26 03:48:46 kitschypi volumio[1288]: assert.ok(self.idling) Nov 26 03:48:46 kitschypi volumio[1288]: error: The expression evaluated to a falsy value: Nov 26 03:48:46 kitschypi volumio[1288]: assert.ok(self.idling) Nov 26 03:48:46 kitschypi volumio[1288]: info: Shairport-Sync Started Nov 26 03:48:46 kitschypi volumio[1288]: Error adding Membership: Error: addMembership EINVAL Nov 26 03:48:46 kitschypi volumio[1288]: info: Shairport-Sync Started Nov 26 03:48:46 kitschypi volumio[1288]: info: Shairport-Sync Started Nov 26 03:48:46 kitschypi volumio[1288]: info: touch_display: systemctl start volumio-kiosk.service succeeded. Nov 26 03:48:46 kitschypi volumio[1288]: info: touch_display: Volumio Kiosk started. Nov 26 03:48:46 kitschypi volumio[1288]: info: CoreCommandRouter::volumioGetState Nov 26 03:48:46 kitschypi volumio[1288]: info: CorePlayQueue::getTrack 0 Nov 26 03:48:46 kitschypi volumio[1288]: info: Completed starting Core Plugins Nov 26 03:48:46 kitschypi volumio[1288]: info: ------------------------------------------- Nov 26 03:48:46 kitschypi volumio[1288]: info: ----- MyVolumio plugins startup ---- Nov 26 03:48:46 kitschypi volumio[1288]: info: ------------------------------------------- Nov 26 03:48:46 kitschypi volumio[1288]: info: [MyVolumio PluginManager] Fetching plans data.... Nov 26 03:48:46 kitschypi volumio[1288]: info: MPD running with PID1491 Nov 26 03:48:46 kitschypi volumio[1288]: ,establishing connection Nov 26 03:48:46 kitschypi volumio[1288]: error: updateQueue error: null Nov 26 03:48:46 kitschypi volumio[1288]: info: CoreCommandRouter::volumioGetState Nov 26 03:48:46 kitschypi volumio[1288]: info: CorePlayQueue::getTrack 0 Nov 26 03:48:46 kitschypi volumio[1288]: info: touch_display: X display number found: Nov 26 03:48:46 kitschypi volumio[1288]: error: updateQueue error: null Nov 26 03:48:46 kitschypi volumio[1288]: info: touch_display: X display number found: 0 Nov 26 03:48:46 kitschypi startx[1564]: X.Org X Server 1.20.4 Nov 26 03:48:46 kitschypi startx[1564]: X Protocol Version 11, Revision 0 Nov 26 03:48:46 kitschypi startx[1564]: Build Operating System: Linux 5.4.0-109-generic armv8l Raspbian Nov 26 03:48:46 kitschypi startx[1564]: Current Operating System: Linux kitschypi 6.6.56-v7l+ #1803 SMP Thu Oct 10 14:10:41 BST 2024 armv7l Nov 26 03:48:46 kitschypi startx[1564]: Kernel command line: coherent_pool=1M 8250.nr_uarts=0 snd_bcm2835.enable_headphones=0 snd_bcm2835.enable_headphones=1 snd_bcm2835.enable_hdmi=1 bcm2708_fb.fbwidth=800 bcm2708_fb.fbheight=480 bcm2708_fb.fbswap=1 smsc95xx.macaddr=DC:A6:32:79:DD:64 vc_mem.mem_base=0x3ec00000 vc_mem.mem_size=0x40000000 splash plymouth.ignore-serial-consoles dwc_otg.fiq_enable=1 dwc_otg.fiq_fsm_enable=1 dwc_otg.fiq_fsm_mask=0xF dwc_otg.nak_holdoff=1 quiet console=ttyS0,115200 console=tty1 imgpart=UUID=634d688a-b96e-44c7-9dc6-4a37ca78c1a6 imgfile=/volumio_current.sqsh bootpart=UUID=DC0C-AF04 datapart=UUID=2994e2c7-186b-4aa1-b0dc-282cd5b018ed uuidconfig=cmdline.txt pcie_aspm=off pci=pcie_bus_safe rootwait bootdelay=7 logo.nologo vt.global_cursor_default=0 net.ifnames=0 snd-bcm2835.enable_compat_alsa= snd_bcm2835.enable_hdmi=1 snd_bcm2835.enable_headphones=1 loglevel=0 nodebug use_kmsg=no Nov 26 03:48:46 kitschypi startx[1564]: Build Date: 04 August 2022 12:56:42PM Nov 26 03:48:46 kitschypi startx[1564]: xorg-server 2:1.20.4-1+rpt4+deb10u5 (https://www.debian.org/support) Nov 26 03:48:46 kitschypi startx[1564]: Current version of pixman: 0.36.0 Nov 26 03:48:46 kitschypi startx[1564]: Before reporting problems, check http://wiki.x.org Nov 26 03:48:46 kitschypi startx[1564]: to make sure that you have the latest version. Nov 26 03:48:46 kitschypi startx[1564]: Markers: (--) probed, (**) from config file, (==) default setting, Nov 26 03:48:46 kitschypi startx[1564]: (++) from command line, (!!) notice, (II) informational, Nov 26 03:48:46 kitschypi startx[1564]: (WW) warning, (EE) error, (NI) not implemented, (??) unknown. Nov 26 03:48:46 kitschypi startx[1564]: (==) Log file: "/var/log/Xorg.0.log", Time: Tue Nov 26 03:48:46 2024 Nov 26 03:48:46 kitschypi startx[1564]: (==) Using config directory: "/etc/X11/xorg.conf.d" Nov 26 03:48:46 kitschypi startx[1564]: (==) Using system config directory "/usr/share/X11/xorg.conf.d" Nov 26 03:48:46 kitschypi volumio[1288]: info: touch_display: Using Xserver unix domain socket /tmp/.X11-unix/X0 Nov 26 03:48:46 kitschypi volumio[1288]: info: touch_display: X display number found: 0 Nov 26 03:48:46 kitschypi go-librespot[1565]: time="2024-11-26T03:48:46Z" level=info msg="generated new device id: 73078b95e9d34ea007ba3fbf71b8251794f11193" Nov 26 03:48:46 kitschypi go-librespot[1565]: time="2024-11-26T03:48:46Z" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew1.spotify.com:80]" Nov 26 03:48:46 kitschypi go-librespot[1565]: time="2024-11-26T03:48:46Z" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Nov 26 03:48:46 kitschypi go-librespot[1565]: time="2024-11-26T03:48:46Z" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Nov 26 03:48:46 kitschypi go-librespot[1565]: time="2024-11-26T03:48:46Z" level=debug msg="zeroconf server listening on port 38883" Nov 26 03:48:46 kitschypi systemd[1]: systemd-hostnamed.service: Succeeded. Nov 26 03:48:47 kitschypi volumio[1288]: info: touch_display: Setting screensaver timeout to 120 seconds. Nov 26 03:48:49 kitschypi volumio[1288]: info: go-librespot daemon successfully initialized Nov 26 03:48:49 kitschypi go-librespot[1565]: time="2024-11-26T03:48:49Z" level=debug msg="obtained new client token: AACf48v8htEtB/2FbZesVcU+2LS1fmp+hJ9ojGUl7V7+feZLGVokA8ymWWSfsklPC56a79QkWETqVSy4JNlqmFpRABd2yUfiYBQyt67eIZW9wpKKP3S9mcagwpgdxXC8MdOyr+nzSGBcJq2urB2XJG/o1JwLsrSsPiK1g0x4GsbHKc52Zjbd/XsEsRY6Im+/qCP69i0E5xyQr/Zl8/lOW0o8O9GstV4AXWqd3/oSINBbyrNFpdnS+AIM7kHB3g==" Nov 26 03:48:49 kitschypi go-librespot[1565]: time="2024-11-26T03:48:49Z" level=info msg="connected to ap-gue1.spotify.com:4070" Nov 26 03:48:49 kitschypi go-librespot[1565]: time="2024-11-26T03:48:49Z" level=debug msg="completed keyexchange" Nov 26 03:48:49 kitschypi sudo[1707]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Nov 26 03:48:49 kitschypi sudo[1707]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 26 03:48:49 kitschypi sudo[1707]: pam_unix(sudo:session): session closed for user root Nov 26 03:48:49 kitschypi sudo[1709]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Nov 26 03:48:49 kitschypi sudo[1709]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 26 03:48:49 kitschypi sudo[1709]: pam_unix(sudo:session): session closed for user root Nov 26 03:48:49 kitschypi sudo[1713]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Nov 26 03:48:49 kitschypi sudo[1713]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 26 03:48:49 kitschypi systemd[1]: Started UPnP Renderer front-end to MPD. Nov 26 03:48:49 kitschypi sudo[1713]: pam_unix(sudo:session): session closed for user root Nov 26 03:48:49 kitschypi volumio[1288]: info: Upmpdcli Daemon Started Nov 26 03:48:49 kitschypi volumio[1715]: Generating RSA private key, 4096 bit long modulus (2 primes) Nov 26 03:48:50 kitschypi go-librespot[1565]: time="2024-11-26T03:48:50Z" level=debug msg="completed challenge" Nov 26 03:48:50 kitschypi go-librespot[1565]: time="2024-11-26T03:48:50Z" level=debug msg="authenticated as 3p3cvdkfvah7hw0fr0im0pop3" Nov 26 03:48:50 kitschypi go-librespot[1565]: time="2024-11-26T03:48:50Z" level=debug msg="authenticated as 3p3cvdkfvah7hw0fr0im0pop3" Nov 26 03:48:50 kitschypi go-librespot[1565]: time="2024-11-26T03:48:50Z" level=debug msg="dealer connection opened" Nov 26 03:48:50 kitschypi go-librespot[1565]: time="2024-11-26T03:48:50Z" level=info msg="accepted zeroconf user 3p3cvdkfvah7hw0fr0im0pop3 from iPhone" Nov 26 03:48:50 kitschypi go-librespot[1565]: time="2024-11-26T03:48:50Z" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Nov 26 03:48:50 kitschypi go-librespot[1565]: time="2024-11-26T03:48:50Z" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Nov 26 03:48:50 kitschypi go-librespot[1565]: time="2024-11-26T03:48:50Z" level=debug msg="received connection id: YjNkMWQzMDMtMGVmNi00NjU0LTk5YzQtNDFjMjVjZTFlYjEwK2RlYWxlcit0Y3A6Ly8wYWNiZjllMi5pcC5ndWUxLnNwb3RpZnkubmV0OjU3MDArMTE5RUY5QzAxQ0Q2RkY0NjIyNjgxNjg2RDBCNEIyQTBGMkI1Qjk2REQ5Mzc4RTQ0QUUzOEMzMkU0NjQwMTYwRg==" Nov 26 03:48:50 kitschypi go-librespot[1565]: time="2024-11-26T03:48:50Z" level=debug msg="put connect state because NEW_DEVICE" Nov 26 03:48:50 kitschypi go-librespot[1565]: time="2024-11-26T03:48:50Z" level=debug msg="autoplay enabled: false" Nov 26 03:48:50 kitschypi go-librespot[1565]: time="2024-11-26T03:48:50Z" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Nov 26 03:48:50 kitschypi go-librespot[1565]: time="2024-11-26T03:48:50Z" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Nov 26 03:48:50 kitschypi go-librespot[1565]: time="2024-11-26T03:48:50Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Nov 26 03:48:50 kitschypi go-librespot[1565]: time="2024-11-26T03:48:50Z" level=debug msg="handling transfer player command from 293e55491ebbf023784f238021df1dd7ab5a5123" Nov 26 03:48:50 kitschypi go-librespot[1565]: time="2024-11-26T03:48:50Z" level=debug msg="resolved context of track" uri="spotify:playlist:37i9dQZF1E4ye6NmvRaPS3" Nov 26 03:48:50 kitschypi go-librespot[1565]: time="2024-11-26T03:48:50Z" level=trace msg="fetched new page 0 with 36 items (list: 36)" uri="spotify:playlist:37i9dQZF1E4ye6NmvRaPS3" Nov 26 03:48:50 kitschypi go-librespot[1565]: time="2024-11-26T03:48:50Z" level=debug msg="loading track (paused: true, position: 315214ms)" uri="spotify:track:3AhXZa8sUQht0UEdBJgpGc" Nov 26 03:48:50 kitschypi go-librespot[1565]: time="2024-11-26T03:48:50Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Nov 26 03:48:50 kitschypi go-librespot[1565]: time="2024-11-26T03:48:50Z" level=trace msg="emitting websocket event: will_play" Nov 26 03:48:50 kitschypi go-librespot[1565]: time="2024-11-26T03:48:50Z" level=debug msg="selected format OGG_VORBIS_320 (fc859c75f3d9bdf5fa65049720a40193ade395a2)" uri="spotify:track:3AhXZa8sUQht0UEdBJgpGc" Nov 26 03:48:50 kitschypi go-librespot[1565]: time="2024-11-26T03:48:50Z" level=debug msg="requested aes key for file fc859c75f3d9bdf5fa65049720a40193ade395a2, gid: 3AhXZa8sUQht0UEdBJgpGc" Nov 26 03:48:50 kitschypi go-librespot[1565]: time="2024-11-26T03:48:50Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1128" Nov 26 03:48:50 kitschypi go-librespot[1565]: time="2024-11-26T03:48:50Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 241" Nov 26 03:48:51 kitschypi volumio[1288]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Nov 26 03:48:51 kitschypi go-librespot[1565]: time="2024-11-26T03:48:51Z" level=debug msg="fetched first chunk of 34, total size is 17586052 bytes" uri="spotify:track:3AhXZa8sUQht0UEdBJgpGc" Nov 26 03:48:51 kitschypi go-librespot[1565]: time="2024-11-26T03:48:51Z" level=debug msg="fetched chunk 3/33, size: 524288" uri="spotify:track:3AhXZa8sUQht0UEdBJgpGc" Nov 26 03:48:51 kitschypi go-librespot[1565]: time="2024-11-26T03:48:51Z" level=debug msg="fetched chunk 2/33, size: 524288" uri="spotify:track:3AhXZa8sUQht0UEdBJgpGc" Nov 26 03:48:51 kitschypi go-librespot[1565]: time="2024-11-26T03:48:51Z" level=debug msg="fetched chunk 29/33, size: 524288" uri="spotify:track:3AhXZa8sUQht0UEdBJgpGc" Nov 26 03:48:51 kitschypi go-librespot[1565]: time="2024-11-26T03:48:51Z" level=debug msg="fetched chunk 31/33, size: 524288" uri="spotify:track:3AhXZa8sUQht0UEdBJgpGc" Nov 26 03:48:51 kitschypi go-librespot[1565]: time="2024-11-26T03:48:51Z" level=debug msg="fetched chunk 1/33, size: 524288" uri="spotify:track:3AhXZa8sUQht0UEdBJgpGc" Nov 26 03:48:51 kitschypi go-librespot[1565]: time="2024-11-26T03:48:51Z" level=debug msg="fetched chunk 30/33, size: 524288" uri="spotify:track:3AhXZa8sUQht0UEdBJgpGc" Nov 26 03:48:52 kitschypi go-librespot[1565]: time="2024-11-26T03:48:52Z" level=debug msg="fetched chunk 28/33, size: 524288" uri="spotify:track:3AhXZa8sUQht0UEdBJgpGc" Nov 26 03:48:52 kitschypi go-librespot[1565]: time="2024-11-26T03:48:52Z" level=trace msg="seek to 315214ms (diff: 144ms, samples: 13900937, bytes: 15116100)" uri="spotify:track:3AhXZa8sUQht0UEdBJgpGc" Nov 26 03:48:52 kitschypi go-librespot[1565]: time="2024-11-26T03:48:52Z" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 5102 us, period size = 225 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 98 frames" Nov 26 03:48:52 kitschypi go-librespot[1565]: time="2024-11-26T03:48:52Z" level=debug msg="created new output device" Nov 26 03:48:52 kitschypi go-librespot[1565]: time="2024-11-26T03:48:52Z" level=info msg="loaded track \"Like a Rolling Stone\" (paused: true, position: 315214ms, duration: 369600ms, prefetched: false)" uri="spotify:track:3AhXZa8sUQht0UEdBJgpGc" Nov 26 03:48:52 kitschypi volumio[1288]: info: Initializing connection to go-librespot Websocket Nov 26 03:48:52 kitschypi go-librespot[1565]: time="2024-11-26T03:48:52Z" level=debug msg="new websocket client" Nov 26 03:48:52 kitschypi volumio[1288]: info: Connection to go-librespot Websocket established Nov 26 03:48:52 kitschypi go-librespot[1565]: time="2024-11-26T03:48:52Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Nov 26 03:48:52 kitschypi go-librespot[1565]: time="2024-11-26T03:48:52Z" level=trace msg="emitting websocket event: metadata" Nov 26 03:48:52 kitschypi go-librespot[1565]: time="2024-11-26T03:48:52Z" level=trace msg="emitting websocket event: active" Nov 26 03:48:52 kitschypi go-librespot[1565]: time="2024-11-26T03:48:52Z" level=debug msg="sending successful reply for dealer request" Nov 26 03:48:52 kitschypi go-librespot[1565]: time="2024-11-26T03:48:52Z" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Nov 26 03:48:52 kitschypi go-librespot[1565]: time="2024-11-26T03:48:52Z" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Nov 26 03:48:52 kitschypi volumio[1288]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:3AhXZa8sUQht0UEdBJgpGc","name":"Like a Rolling Stone","artist_names":["Bob Dylan"],"album_name":"Highway 61 Revisited","album_cover_url":"https://i.scdn.co/image/ab67616d00001e0241720ef0ae31e10d39e43ca2","position":315214,"duration":369600,"release_date":"year:1965 month:8 day:30","track_number":1,"disc_number":1}} Nov 26 03:48:52 kitschypi volumio[1288]: SPOTIFY: received: {"type":"active","data":null} Nov 26 03:48:52 kitschypi volumio[1288]: info: Aligning Spotify Volume to Volumio Volume Nov 26 03:48:52 kitschypi volumio[1288]: info: CoreCommandRouter::volumioGetState Nov 26 03:48:52 kitschypi volumio[1288]: info: CorePlayQueue::getTrack 0 Nov 26 03:48:52 kitschypi volumio[1288]: info: Setting Spotify Volume from Volumio: 79 Nov 26 03:48:52 kitschypi go-librespot[1565]: time="2024-11-26T03:48:52Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Nov 26 03:48:52 kitschypi go-librespot[1565]: time="2024-11-26T03:48:52Z" level=trace msg="emitting websocket event: paused" Nov 26 03:48:52 kitschypi volumio[1288]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:3AhXZa8sUQht0UEdBJgpGc","play_origin":"playlist/ondemand"}} Nov 26 03:48:52 kitschypi volumio[1288]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Nov 26 03:48:52 kitschypi volumio[1288]: TypeError: Cannot read property 'service' of undefined Nov 26 03:48:52 kitschypi volumio[1288]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:337:50) Nov 26 03:48:52 kitschypi volumio[1288]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:271:18) Nov 26 03:48:52 kitschypi volumio[1288]: at WebSocket.message (/data/plugins/music_service/spop/index.js:190:14) Nov 26 03:48:52 kitschypi volumio[1288]: at WebSocket.emit (events.js:315:20) Nov 26 03:48:52 kitschypi volumio[1288]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20) Nov 26 03:48:52 kitschypi volumio[1288]: at Receiver.emit (events.js:315:20) Nov 26 03:48:52 kitschypi volumio[1288]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) Nov 26 03:48:52 kitschypi volumio[1288]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) Nov 26 03:48:52 kitschypi volumio[1288]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) Nov 26 03:48:52 kitschypi volumio[1288]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) Nov 26 03:48:52 kitschypi volumio[1288]: at writeOrBuffer (internal/streams/writable.js:358:12) Nov 26 03:48:52 kitschypi volumio[1288]: at Receiver.Writable.write (internal/streams/writable.js:303:10) Nov 26 03:48:52 kitschypi volumio[1288]: at Socket.socketOnData (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1355:35) Nov 26 03:48:52 kitschypi volumio[1288]: at Socket.emit (events.js:315:20) Nov 26 03:48:52 kitschypi volumio[1288]: at addChunk (internal/streams/readable.js:309:12) Nov 26 03:48:52 kitschypi volumio[1288]: at readableAddChunk (internal/streams/readable.js:284:9) Nov 26 03:48:52 kitschypi volumio[1288]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Nov 26 03:48:52 kitschypi go-librespot[1565]: time="2024-11-26T03:48:52Z" level=debug msg="handling resume player command from 293e55491ebbf023784f238021df1dd7ab5a5123" Nov 26 03:48:52 kitschypi go-librespot[1565]: time="2024-11-26T03:48:52Z" level=trace msg="seek to 315214ms (diff: 144ms, samples: 13900937, bytes: 15116100)" uri="spotify:track:3AhXZa8sUQht0UEdBJgpGc" Nov 26 03:48:52 kitschypi go-librespot[1565]: time="2024-11-26T03:48:52Z" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 5102 us, period size = 225 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 98 frames" Nov 26 03:48:52 kitschypi go-librespot[1565]: time="2024-11-26T03:48:52Z" level=debug msg="resume track at 315070ms" Nov 26 03:48:52 kitschypi volumio[1715]: ...........................++++ Nov 26 03:48:52 kitschypi go-librespot[1565]: time="2024-11-26T03:48:52Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Nov 26 03:48:52 kitschypi go-librespot[1565]: time="2024-11-26T03:48:52Z" level=trace msg="scheduling prefetch in 24s" Nov 26 03:48:52 kitschypi go-librespot[1565]: time="2024-11-26T03:48:52Z" level=debug msg="sending successful reply for dealer request" Nov 26 03:48:52 kitschypi go-librespot[1565]: time="2024-11-26T03:48:52Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Nov 26 03:48:52 kitschypi go-librespot[1565]: time="2024-11-26T03:48:52Z" level=trace msg="emitting websocket event: playing" Nov 26 03:48:52 kitschypi volumio-remote-updater[665]: [2024-11-26 03:48:52] [connect] Successful connection Nov 26 03:48:52 kitschypi sudo[1802]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-11-26 03:47 Nov 26 03:48:52 kitschypi sudo[1802]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Raspbian GNU/Linux 10 (buster)" NAME="Raspbian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="70bcab5180cf11352f5a5197ade215ea8ee93db0" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="678d37490b3eb2102ce7c6d7a6dc3cf042ff2347" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri 08 Nov 2024 06:51:56 PM CET" VOLUMIO_VERSION="3.779" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="b9009e0280f50389e80a537357ff3961"