-- Logs begin at Thu 2019-02-14 10:11:59 UTC, end at Wed 2025-03-05 15:44:39 UTC. -- Mar 05 15:43:40 madtunes fake-hwclock[187]: Wed Mar 5 15:43:40 UTC 2025 Mar 05 15:43:40 madtunes systemd[1]: Started Restore / save the current clock. Mar 05 15:43:40 madtunes systemd[1]: Started Load/Save Random Seed. Mar 05 15:43:40 madtunes systemd[1]: dynamicswap.service: Succeeded. Mar 05 15:43:40 madtunes systemd[1]: Started Create System Users. Mar 05 15:43:40 madtunes systemd[1]: Starting Create Static Device Nodes in /dev... Mar 05 15:43:40 madtunes systemd[1]: Started udev Coldplug all Devices. Mar 05 15:43:40 madtunes systemd[1]: Starting Helper to synchronize boot up for ifupdown... Mar 05 15:43:40 madtunes systemd[1]: Started Helper to synchronize boot up for ifupdown. Mar 05 15:43:40 madtunes systemd[1]: Started Create Static Device Nodes in /dev. Mar 05 15:43:40 madtunes systemd[1]: Starting udev Kernel Device Manager... Mar 05 15:43:40 madtunes systemd[1]: Reached target Local File Systems (Pre). Mar 05 15:43:40 madtunes systemd[1]: Mounting /var/spool/cups... Mar 05 15:43:40 madtunes systemd[1]: tmp.mount: Directory /tmp to mount over is not empty, mounting anyway. Mar 05 15:43:40 madtunes systemd[1]: Mounting /tmp... Mar 05 15:43:40 madtunes systemd[1]: var-log.mount: Directory /var/log to mount over is not empty, mounting anyway. Mar 05 15:43:40 madtunes systemd[1]: Mounting /var/log... Mar 05 15:43:40 madtunes systemd[1]: Mounted /var/spool/cups. Mar 05 15:43:40 madtunes systemd[1]: Mounting /var/spool/cups/tmp... Mar 05 15:43:40 madtunes systemd[1]: Mounted /tmp. Mar 05 15:43:40 madtunes systemd[1]: Mounted /var/log. Mar 05 15:43:40 madtunes systemd[1]: Starting Flush Journal to Persistent Storage... Mar 05 15:43:40 madtunes systemd[1]: Mounted /var/spool/cups/tmp. Mar 05 15:43:40 madtunes systemd-udevd[214]: Network interface NamePolicy= disabled on kernel command line, ignoring. Mar 05 15:43:40 madtunes systemd[1]: Started udev Kernel Device Manager. Mar 05 15:43:40 madtunes systemd[1]: Starting Show Plymouth Boot Screen... Mar 05 15:43:40 madtunes systemd-journald[194]: Runtime journal (/run/log/journal/f19fe563bf7dcaf9ed2201976245a35f) is 7.5M, max 30.0M, 22.5M free. Mar 05 15:43:40 madtunes systemd[1]: Started Flush Journal to Persistent Storage. Mar 05 15:43:40 madtunes systemd[1]: Received SIGRTMIN+20 from PID 231 (plymouthd). Mar 05 15:43:40 madtunes systemd[1]: Started Show Plymouth Boot Screen. Mar 05 15:43:40 madtunes systemd[1]: Started Forward Password Requests to Plymouth Directory Watch. Mar 05 15:43:40 madtunes systemd[1]: Condition check resulted in Dispatch Password Requests to Console Directory Watch being skipped. Mar 05 15:43:40 madtunes systemd[1]: Reached target Paths. Mar 05 15:43:40 madtunes systemd[1]: Reached target Local Encrypted Volumes. Mar 05 15:43:40 madtunes kernel: mc: Linux media interface: v0.10 Mar 05 15:43:40 madtunes kernel: vc_sm_cma: module is from the staging directory, the quality is unknown, you have been warned. Mar 05 15:43:40 madtunes kernel: bcm2835_vc_sm_cma_probe: Videocore shared memory driver Mar 05 15:43:40 madtunes kernel: [vc_sm_connected_init]: start Mar 05 15:43:40 madtunes kernel: videodev: Linux video capture interface: v2.00 Mar 05 15:43:40 madtunes kernel: [vc_sm_connected_init]: installed successfully Mar 05 15:43:40 madtunes kernel: bcm2835_mmal_vchiq: module is from the staging directory, the quality is unknown, you have been warned. Mar 05 15:43:41 madtunes kernel: bcm2835_codec: module is from the staging directory, the quality is unknown, you have been warned. Mar 05 15:43:41 madtunes kernel: bcm2835_isp: module is from the staging directory, the quality is unknown, you have been warned. Mar 05 15:43:41 madtunes kernel: bcm2835-codec bcm2835-codec: Device registered as /dev/video10 Mar 05 15:43:41 madtunes kernel: bcm2835-codec bcm2835-codec: Loaded V4L2 decode Mar 05 15:43:41 madtunes kernel: bcm2835-isp bcm2835-isp: Device node output[0] registered as /dev/video13 Mar 05 15:43:41 madtunes kernel: bcm2835-isp bcm2835-isp: Device node capture[0] registered as /dev/video14 Mar 05 15:43:41 madtunes kernel: bcm2835-isp bcm2835-isp: Device node capture[1] registered as /dev/video15 Mar 05 15:43:41 madtunes kernel: bcm2835-isp bcm2835-isp: Device node stats[2] registered as /dev/video16 Mar 05 15:43:41 madtunes kernel: bcm2835-isp bcm2835-isp: Register output node 0 with media controller Mar 05 15:43:41 madtunes kernel: bcm2835-isp bcm2835-isp: Register capture node 1 with media controller Mar 05 15:43:41 madtunes kernel: bcm2835-isp bcm2835-isp: Register capture node 2 with media controller Mar 05 15:43:41 madtunes kernel: bcm2835-isp bcm2835-isp: Register capture node 3 with media controller Mar 05 15:43:41 madtunes kernel: bcm2835-codec bcm2835-codec: Device registered as /dev/video11 Mar 05 15:43:41 madtunes kernel: bcm2835-codec bcm2835-codec: Loaded V4L2 encode Mar 05 15:43:41 madtunes kernel: bcm2835-codec bcm2835-codec: Device registered as /dev/video12 Mar 05 15:43:41 madtunes kernel: bcm2835-codec bcm2835-codec: Loaded V4L2 isp Mar 05 15:43:41 madtunes kernel: bcm2835-isp bcm2835-isp: Device node output[0] registered as /dev/video20 Mar 05 15:43:41 madtunes kernel: bcm2835-isp bcm2835-isp: Device node capture[0] registered as /dev/video21 Mar 05 15:43:41 madtunes kernel: bcm2835-isp bcm2835-isp: Device node capture[1] registered as /dev/video22 Mar 05 15:43:41 madtunes kernel: bcm2835-isp bcm2835-isp: Device node stats[2] registered as /dev/video23 Mar 05 15:43:41 madtunes kernel: bcm2835-isp bcm2835-isp: Register output node 0 with media controller Mar 05 15:43:41 madtunes kernel: bcm2835-isp bcm2835-isp: Register capture node 1 with media controller Mar 05 15:43:41 madtunes kernel: bcm2835-isp bcm2835-isp: Register capture node 2 with media controller Mar 05 15:43:41 madtunes kernel: bcm2835-isp bcm2835-isp: Register capture node 3 with media controller Mar 05 15:43:41 madtunes kernel: bcm2835-isp bcm2835-isp: Loaded V4L2 bcm2835-isp Mar 05 15:43:41 madtunes kernel: bcm2835_v4l2: module is from the staging directory, the quality is unknown, you have been warned. Mar 05 15:43:41 madtunes kernel: bcm2835-codec bcm2835-codec: Device registered as /dev/video18 Mar 05 15:43:41 madtunes kernel: bcm2835-codec bcm2835-codec: Loaded V4L2 image_fx Mar 05 15:43:41 madtunes kernel: snd_bcm2835: module is from the staging directory, the quality is unknown, you have been warned. Mar 05 15:43:41 madtunes kernel: bcm2835_audio bcm2835_audio: card created with 4 channels Mar 05 15:43:41 madtunes kernel: bcm2835_audio bcm2835_audio: card created with 4 channels Mar 05 15:43:41 madtunes systemd[1]: Found device /dev/mmcblk0p1. Mar 05 15:43:41 madtunes systemd-udevd[228]: Using default interface naming scheme 'v240'. Mar 05 15:43:41 madtunes kernel: cfg80211: Loading compiled-in X.509 certificates for regulatory database Mar 05 15:43:42 madtunes systemd-udevd[220]: link_config: autonegotiation is unset or enabled, the speed and duplex are not writable. Mar 05 15:43:42 madtunes systemd-udevd[228]: link_config: autonegotiation is unset or enabled, the speed and duplex are not writable. Mar 05 15:43:42 madtunes kernel: cfg80211: Loaded X.509 cert 'sforshee: 00b28ddf47aef9cea7' Mar 05 15:43:42 madtunes kernel: cfg80211: loaded regulatory.db is malformed or signature is missing/invalid Mar 05 15:43:42 madtunes kernel: brcmfmac: F1 signature read @0x18000000=0x15264345 Mar 05 15:43:42 madtunes kernel: brcmfmac: brcmf_fw_alloc_request: using brcm/brcmfmac43455-sdio for chip BCM4345/6 Mar 05 15:43:42 madtunes kernel: usbcore: registered new interface driver brcmfmac Mar 05 15:43:42 madtunes kernel: random: crng init done Mar 05 15:43:42 madtunes kernel: random: 7 urandom warning(s) missed due to ratelimiting Mar 05 15:43:43 madtunes kernel: brcmfmac: brcmf_fw_alloc_request: using brcm/brcmfmac43455-sdio for chip BCM4345/6 Mar 05 15:43:43 madtunes 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 Mar 05 15:43:43 madtunes systemd-udevd[221]: Using default interface naming scheme 'v240'. Mar 05 15:43:43 madtunes systemd-udevd[221]: link_config: autonegotiation is unset or enabled, the speed and duplex are not writable. Mar 05 15:43:44 madtunes kernel: snd-rpi-iqaudio-dac soc:sound: snd_rpi_iqaudio_gpio_unmute: un-muting amp using GPIO22 Mar 05 15:43:44 madtunes systemd[1]: Listening on Load/Save RF Kill Switch Status /dev/rfkill Watch. Mar 05 15:43:44 madtunes systemd[1]: Condition check resulted in FUSE Control File System being skipped. Mar 05 15:43:44 madtunes systemd[1]: Condition check resulted in Set Up Additional Binary Formats being skipped. Mar 05 15:43:44 madtunes systemd[1]: Condition check resulted in Rebuild Hardware Database being skipped. Mar 05 15:43:44 madtunes systemd[1]: Condition check resulted in Dispatch Password Requests to Console Directory Watch being skipped. Mar 05 15:43:44 madtunes systemd[1]: Condition check resulted in Huge Pages File System being skipped. Mar 05 15:43:44 madtunes systemd[1]: Starting File System Check on /dev/mmcblk0p1... Mar 05 15:43:44 madtunes systemd[1]: Starting Load/Save RF Kill Switch Status... Mar 05 15:43:44 madtunes systemd-udevd[226]: Process '/usr/sbin/alsactl -E HOME=/run/alsa restore 1' failed with exit code 17. Mar 05 15:43:45 madtunes systemd[1]: Found device /sys/subsystem/net/devices/wlan0. Mar 05 15:43:45 madtunes systemd[1]: Started Load/Save RF Kill Switch Status. Mar 05 15:43:45 madtunes systemd[1]: Found device 7800. Mar 05 15:43:45 madtunes systemd[1]: Started File System Check Daemon to report status. Mar 05 15:43:45 madtunes systemd-fsck[371]: fsck.fat 4.1 (2017-01-24) Mar 05 15:43:45 madtunes systemd-fsck[371]: 0x41: Dirty bit is set. Fs was not properly unmounted and some data may be corrupt. Mar 05 15:43:45 madtunes systemd-fsck[371]: Automatically removing dirty bit. Mar 05 15:43:45 madtunes systemd-fsck[371]: Performing changes. Mar 05 15:43:45 madtunes systemd-fsck[371]: /dev/mmcblk0p1: 313 files, 109594/123044 clusters Mar 05 15:43:45 madtunes systemd[1]: Started File System Check on /dev/mmcblk0p1. Mar 05 15:43:45 madtunes systemd[1]: Mounting /boot... Mar 05 15:43:45 madtunes systemd[1]: Mounted /boot. Mar 05 15:43:45 madtunes systemd[1]: Reached target Local File Systems. Mar 05 15:43:45 madtunes systemd[1]: Condition check resulted in Commit a transient machine-id on disk being skipped. Mar 05 15:43:45 madtunes systemd[1]: Starting Create Volatile Files and Directories... Mar 05 15:43:45 madtunes systemd[1]: Started ifup for wlan0. Mar 05 15:43:45 madtunes systemd[1]: Starting Tell Plymouth To Write Out Runtime Data... Mar 05 15:43:45 madtunes systemd[1]: Started ifup for eth0. Mar 05 15:43:45 madtunes systemd[1]: Starting Preprocess NFS configuration... Mar 05 15:43:45 madtunes systemd[1]: Starting Raise network interfaces... Mar 05 15:43:45 madtunes systemd[1]: plymouth-read-write.service: Succeeded. Mar 05 15:43:45 madtunes systemd[1]: Started Tell Plymouth To Write Out Runtime Data. Mar 05 15:43:45 madtunes systemd[1]: Received SIGRTMIN+20 from PID 231 (plymouthd). Mar 05 15:43:45 madtunes systemd[1]: nfs-config.service: Succeeded. Mar 05 15:43:45 madtunes systemd[1]: Started Preprocess NFS configuration. Mar 05 15:43:45 madtunes systemd[1]: Condition check resulted in RPC security service for NFS server being skipped. Mar 05 15:43:45 madtunes systemd[1]: Condition check resulted in RPC security service for NFS client and server being skipped. Mar 05 15:43:45 madtunes systemd[1]: Reached target NFS client services. Mar 05 15:43:45 madtunes systemd[1]: Started Create Volatile Files and Directories. Mar 05 15:43:45 madtunes systemd[1]: Condition check resulted in Network Time Synchronization being skipped. Mar 05 15:43:45 madtunes systemd[1]: Starting Update UTMP about System Boot/Shutdown... Mar 05 15:43:45 madtunes systemd[1]: Starting RPC bind portmap service... Mar 05 15:43:45 madtunes systemd[1]: Started Entropy daemon using the HAVEGE algorithm. Mar 05 15:43:45 madtunes systemd[1]: Started Update UTMP about System Boot/Shutdown. Mar 05 15:43:45 madtunes systemd[1]: Reached target System Initialization. Mar 05 15:43:45 madtunes kernel: 8021q: 802.1Q VLAN Support v1.8 Mar 05 15:43:45 madtunes systemd[1]: Listening on triggerhappy.socket. Mar 05 15:43:45 madtunes systemd[1]: apt-daily.timer: Not using persistent file timestamp Sat 2025-03-15 18:50:45 UTC as it is in the future. Mar 05 15:43:45 madtunes systemd[1]: Started Daily apt download activities. Mar 05 15:43:45 madtunes systemd[1]: Listening on D-Bus System Message Bus Socket. Mar 05 15:43:45 madtunes systemd[1]: apt-daily-upgrade.timer: Not using persistent file timestamp Sat 2025-03-15 12:31:53 UTC as it is in the future. Mar 05 15:43:45 madtunes systemd[1]: Started Daily apt upgrade and clean activities. Mar 05 15:43:45 madtunes systemd[1]: Listening on Avahi mDNS/DNS-SD Stack Activation Socket. Mar 05 15:43:45 madtunes kernel: brcmfmac: brcmf_cfg80211_set_power_mgmt: power save disabled Mar 05 15:43:45 madtunes systemd[1]: Listening on mpd.socket. Mar 05 15:43:45 madtunes systemd[1]: Reached target Sockets. Mar 05 15:43:45 madtunes systemd[1]: Reached target Basic System. Mar 05 15:43:45 madtunes systemd[1]: Started Volumio Iptables Module. Mar 05 15:43:45 madtunes systemd[1]: Started UPnP Renderer front-end to MPD. Mar 05 15:43:45 madtunes systemd[1]: Starting Avahi mDNS/DNS-SD Stack... Mar 05 15:43:45 madtunes systemd[1]: Condition check resulted in getty on tty2-tty6 if dbus and logind are not available being skipped. Mar 05 15:43:45 madtunes systemd[1]: Starting Wireless Services... Mar 05 15:43:45 madtunes systemd[1]: Starting Configure Bluetooth Modems connected by UART... Mar 05 15:43:45 madtunes systemd[1]: Condition check resulted in Copy user wpa_supplicant.conf being skipped. Mar 05 15:43:45 madtunes systemd[1]: Starting triggerhappy global hotkey daemon... Mar 05 15:43:45 madtunes systemd[1]: Starting Login Service... Mar 05 15:43:45 madtunes systemd[1]: Started volumio-remote-updater.service. Mar 05 15:43:45 madtunes systemd[1]: Started Daily Cleanup of Temporary Directories. Mar 05 15:43:45 madtunes systemd[1]: Reached target Timers. Mar 05 15:43:46 madtunes thd[468]: Unable to parse trigger line: Mar 05 15:43:46 madtunes thd[468]: Unable to parse trigger line: KEY_MIN_INTERESTING 1 /usr/local/bin/volumio volume toggle Mar 05 15:43:46 madtunes thd[468]: Unable to parse trigger line: Mar 05 15:43:46 madtunes thd[468]: Unable to parse trigger line: Mar 05 15:43:46 madtunes alsactl[482]: alsactl 1.1.8 daemon started Mar 05 15:43:46 madtunes systemd[1]: Started Manage Sound Card State (restore and store). Mar 05 15:43:46 madtunes systemd[1]: Starting Save/Restore Sound Card State... Mar 05 15:43:46 madtunes systemd[1]: Condition check resulted in Volumio SSH enabler being skipped. Mar 05 15:43:46 madtunes systemd[1]: Starting dhcpcd on all interfaces... Mar 05 15:43:46 madtunes systemd[1]: Started D-Bus System Message Bus. Mar 05 15:43:46 madtunes systemd[1]: Starting WPA supplicant... Mar 05 15:43:46 madtunes dhcpcd[492]: Not running dhcpcd because /etc/network/interfaces Mar 05 15:43:46 madtunes dhcpcd[492]: defines some interfaces that will use a Mar 05 15:43:46 madtunes dhcpcd[492]: DHCP client or static address Mar 05 15:43:46 madtunes systemd[1]: Started Save/Restore Sound Card State. Mar 05 15:43:46 madtunes systemd[1]: dhcpcd.service: Control process exited, code=exited, status=6/NOTCONFIGURED Mar 05 15:43:46 madtunes systemd[1]: dhcpcd.service: Failed with result 'exit-code'. Mar 05 15:43:46 madtunes systemd[1]: Failed to start dhcpcd on all interfaces. Mar 05 15:43:46 madtunes systemd[1]: Reached target Sound Card. Mar 05 15:43:46 madtunes avahi-daemon[462]: Found user 'avahi' (UID 110) and group 'avahi' (GID 113). Mar 05 15:43:46 madtunes avahi-daemon[462]: Successfully dropped root privileges. Mar 05 15:43:46 madtunes avahi-daemon[462]: avahi-daemon 0.7 starting up. Mar 05 15:43:46 madtunes sh[381]: eth0: waiting for carrier Mar 05 15:43:46 madtunes kernel: 8021q: adding VLAN 0 to HW filter on device eth0 Mar 05 15:43:46 madtunes dhcpcd[426]: eth0: waiting for carrier Mar 05 15:43:46 madtunes thd[468]: Found socket passed from systemd Mar 05 15:43:46 madtunes systemd-logind[473]: New seat seat0. Mar 05 15:43:46 madtunes kernel: uart-pl011 3f201000.serial: no DMA platform data Mar 05 15:43:47 madtunes avahi-daemon[462]: Successfully called chroot(). Mar 05 15:43:47 madtunes avahi-daemon[462]: Successfully dropped remaining capabilities. Mar 05 15:43:47 madtunes systemd[1]: Started Login Service. Mar 05 15:43:47 madtunes systemd[1]: Started triggerhappy global hotkey daemon. Mar 05 15:43:47 madtunes avahi-daemon[462]: Loading service file /services/volumio.service. Mar 05 15:43:47 madtunes systemd[1]: Started RPC bind portmap service. Mar 05 15:43:47 madtunes avahi-daemon[462]: Network interface enumeration completed. Mar 05 15:43:47 madtunes avahi-daemon[462]: Server startup complete. Host name is madtunes.local. Local service cookie is 4069322768. Mar 05 15:43:47 madtunes avahi-daemon[462]: Service "madtunes" (/services/volumio.service) successfully established. Mar 05 15:43:47 madtunes systemd[1]: Started Avahi mDNS/DNS-SD Stack. Mar 05 15:43:47 madtunes systemd[1]: Reached target RPC Port Mapper. Mar 05 15:43:47 madtunes systemd[1]: Reached target Remote File Systems (Pre). Mar 05 15:43:47 madtunes systemd[1]: Reached target Remote File Systems. Mar 05 15:43:47 madtunes sh[378]: wlan0=wlan0 Mar 05 15:43:47 madtunes systemd[1]: Starting LSB: Load kernel modules needed to enable cpufreq scaling... Mar 05 15:43:47 madtunes systemd[1]: Started Raise network interfaces. Mar 05 15:43:48 madtunes haveged[433]: haveged: ver: 1.9.1; arch: generic; vend: ; build: (gcc 8.2.0 CTV); collect: 128K Mar 05 15:43:48 madtunes haveged[433]: haveged: cpu: (VC); data: 16K (D); inst: 16K (D); idx: 11/40; sz: 14768/63488 Mar 05 15:43:48 madtunes haveged[433]: haveged: tot tests(BA8): A:1/1 B:1/1 continuous tests(B): last entropy estimate 7.99453 Mar 05 15:43:48 madtunes haveged[433]: haveged: fills: 0, generated: 0 Mar 05 15:43:48 madtunes loadcpufreq[556]: Loading cpufreq kernel modules...done (none). Mar 05 15:43:48 madtunes systemd[1]: Started LSB: Load kernel modules needed to enable cpufreq scaling. Mar 05 15:43:48 madtunes systemd[1]: Starting LSB: set CPUFreq kernel parameters... Mar 05 15:43:48 madtunes systemd[1]: iptables.service: Succeeded. Mar 05 15:43:48 madtunes cpufrequtils[588]: CPUFreq Utilities: Setting performance CPUFreq governor...CPU0...CPU1...CPU2...CPU3...done. Mar 05 15:43:48 madtunes systemd[1]: Started LSB: set CPUFreq kernel parameters. Mar 05 15:43:48 madtunes systemd[1]: Started WPA supplicant. Mar 05 15:43:48 madtunes wpa_supplicant[506]: Successfully initialized wpa_supplicant Mar 05 15:43:49 madtunes systemd[1]: Reached target Network. Mar 05 15:43:49 madtunes systemd[1]: Reached target Network is Online. Mar 05 15:43:49 madtunes systemd[1]: Starting LSB: Brings up/down network automatically... Mar 05 15:43:49 madtunes systemd[1]: Starting Samba NMB Daemon... Mar 05 15:43:49 madtunes systemd[1]: Condition check resulted in fast remote file copy program daemon being skipped. Mar 05 15:43:49 madtunes systemd[1]: Starting Permit User Sessions... Mar 05 15:43:49 madtunes systemd[1]: Starting /etc/rc.local Compatibility... Mar 05 15:43:49 madtunes systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Mar 05 15:43:49 madtunes systemd[1]: Starting Network Time Service... Mar 05 15:43:49 madtunes systemd[1]: Starting Music Player Daemon... Mar 05 15:43:49 madtunes systemd[1]: Started /etc/rc.local Compatibility. Mar 05 15:43:49 madtunes systemd[1]: Started Permit User Sessions. Mar 05 15:43:49 madtunes systemd[1]: Starting Hold until boot process finishes up... Mar 05 15:43:49 madtunes systemd[1]: Starting Terminate Plymouth Boot Screen... Mar 05 15:43:49 madtunes systemd[1]: Received SIGRTMIN+21 from PID 231 (plymouthd). Mar 05 15:43:49 madtunes systemd[1]: plymouth-start.service: Succeeded. Mar 05 15:43:49 madtunes systemd[1]: plymouth-quit-wait.service: Succeeded. Mar 05 15:43:49 madtunes systemd[1]: Started Hold until boot process finishes up. Mar 05 15:43:49 madtunes systemd[1]: plymouth-quit.service: Succeeded. Mar 05 15:43:49 madtunes systemd[1]: Started Terminate Plymouth Boot Screen. Mar 05 15:43:49 madtunes systemd[1]: Received SIGRTMIN+21 from PID 231 (n/a). Mar 05 15:43:49 madtunes systemd[1]: Started Getty on tty1. Mar 05 15:43:49 madtunes systemd[1]: Reached target Login Prompts. Mar 05 15:43:49 madtunes ifplugd(eth0)[634]: ifplugd 0.28 initializing. Mar 05 15:43:49 madtunes ifplugd(eth0)[634]: Using interface eth0/B8:27:EB:E2:DC:D4 with driver (version: 5.10.92-v7+) Mar 05 15:43:49 madtunes ifplugd(eth0)[634]: Using detection mode: SIOCETHTOOL Mar 05 15:43:49 madtunes ifplugd(eth0)[634]: Initialization complete, link beat not detected. Mar 05 15:43:49 madtunes ifplugd[607]: Network Interface Plugging Daemon...start eth0...done. Mar 05 15:43:49 madtunes systemd[1]: Started LSB: Brings up/down network automatically. Mar 05 15:43:49 madtunes ntpd[613]: ntpd 4.2.8p12@1.3728-o (1): Starting Mar 05 15:43:49 madtunes ntpd[613]: Command line: /usr/sbin/ntpd -p /var/run/ntpd.pid -g -u 103:103 Mar 05 15:43:49 madtunes systemd[1]: Started Network Time Service. Mar 05 15:43:49 madtunes volumio-remote-updater[474]: Error: No active session Mar 05 15:43:49 madtunes volumio-remote-updater[474]: [2025-03-05 15:43:49] [info] asio async_connect error: system:111 (Connection refused) Mar 05 15:43:49 madtunes volumio-remote-updater[474]: [2025-03-05 15:43:49] [info] Error getting remote endpoint: system:107 (Transport endpoint is not connected) Mar 05 15:43:49 madtunes volumio-remote-updater[474]: [2025-03-05 15:43:49] [error] handle_connect error: Underlying Transport Error Mar 05 15:43:49 madtunes ntpd[639]: proto: precision = 0.573 usec (-21) Mar 05 15:43:49 madtunes ntpd[639]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): good hash signature Mar 05 15:43:49 madtunes ntpd[639]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): loaded, expire=2023-12-28T00:00:00Z last=2017-01-01T00:00:00Z ofs=37 Mar 05 15:43:49 madtunes ntpd[639]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): expired less than 434 days ago Mar 05 15:43:49 madtunes ntpd[639]: Listen and drop on 0 v6wildcard [::]:123 Mar 05 15:43:49 madtunes ntpd[639]: Listen and drop on 1 v4wildcard 0.0.0.0:123 Mar 05 15:43:49 madtunes ntpd[639]: Listen normally on 2 lo 127.0.0.1:123 Mar 05 15:43:49 madtunes ntpd[639]: Listening on routing socket on fd #19 for interface updates Mar 05 15:43:49 madtunes ntpd[639]: kernel reports TIME_ERROR: 0x41: Clock Unsynchronized Mar 05 15:43:49 madtunes ntpd[639]: kernel reports TIME_ERROR: 0x41: Clock Unsynchronized Mar 05 15:43:49 madtunes volumio[457]: Could not open config: /tmp/upmpdcli.conf Mar 05 15:43:49 madtunes systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Mar 05 15:43:49 madtunes systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Mar 05 15:43:49 madtunes systemd[1]: systemd-rfkill.service: Succeeded. Mar 05 15:43:50 madtunes ntpd[639]: error resolving pool 0.debian.pool.ntp.org: System error (-11) Mar 05 15:43:51 madtunes nmbd[616]: [2025/03/05 15:43:51.482164, 0] ../source3/nmbd/asyncdns.c:158(start_async_dns) Mar 05 15:43:51 madtunes nmbd[616]: started asyncdns process 648 Mar 05 15:43:51 madtunes nmbd[616]: [2025/03/05 15:43:51.485497, 0] ../lib/util/become_daemon.c:149(daemon_status) Mar 05 15:43:51 madtunes nmbd[616]: daemon_status: STATUS=daemon 'nmbd' : No local IPv4 non-loopback interfaces available, waiting for interface ... Mar 05 15:43:51 madtunes nmbd[616]: [2025/03/05 15:43:51.486090, 0] ../source3/nmbd/nmbd_subnetdb.c:254(create_subnets) Mar 05 15:43:51 madtunes nmbd[616]: NOTE: NetBIOS name resolution is not supported for Internet Protocol Version 6 (IPv6). Mar 05 15:43:51 madtunes ntpd[639]: error resolving pool 1.debian.pool.ntp.org: System error (-11) Mar 05 15:43:52 madtunes wireless.js[463]: Cleaning previous... Mar 05 15:43:52 madtunes sudo[657]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ip addr flush dev wlan0 Mar 05 15:43:52 madtunes sudo[657]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 05 15:43:52 madtunes sudo[657]: pam_unix(sudo:session): session closed for user root Mar 05 15:43:52 madtunes sudo[659]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 down Mar 05 15:43:52 madtunes sudo[659]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 05 15:43:52 madtunes ntpd[639]: error resolving pool 2.debian.pool.ntp.org: System error (-11) Mar 05 15:43:53 madtunes sudo[659]: pam_unix(sudo:session): session closed for user root Mar 05 15:43:53 madtunes mpd[635]: Mar 05 15:43 : exception: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Mar 05 15:43:53 madtunes wireless.js[463]: Stopped aP Mar 05 15:43:53 madtunes sudo[666]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 up Mar 05 15:43:53 madtunes sudo[666]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 05 15:43:53 madtunes kernel: brcmfmac: brcmf_cfg80211_set_power_mgmt: power save disabled Mar 05 15:43:53 madtunes sudo[666]: pam_unix(sudo:session): session closed for user root Mar 05 15:43:53 madtunes sudo[668]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iw reg get Mar 05 15:43:53 madtunes sudo[668]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 05 15:43:53 madtunes sudo[668]: pam_unix(sudo:session): session closed for user root Mar 05 15:43:53 madtunes sudo[675]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 up Mar 05 15:43:53 madtunes sudo[675]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 05 15:43:53 madtunes sudo[675]: pam_unix(sudo:session): session closed for user root Mar 05 15:43:53 madtunes sudo[677]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iw wlan0 scan Mar 05 15:43:53 madtunes sudo[677]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 05 15:43:53 madtunes ntpd[639]: error resolving pool 3.debian.pool.ntp.org: System error (-11) Mar 05 15:43:53 madtunes mpd[635]: Mar 05 15:43 : exception: Input plugin 'tidal' is unavailable: No Tidal application token configured Mar 05 15:43:53 madtunes mpd[635]: Mar 05 15:43 : exception: Input plugin 'qobuz' is unavailable: No Qobuz app_id configured Mar 05 15:43:53 madtunes systemd[1]: Started Music Player Daemon. Mar 05 15:43:54 madtunes kernel: Bluetooth: Core ver 2.22 Mar 05 15:43:54 madtunes kernel: NET: Registered protocol family 31 Mar 05 15:43:54 madtunes kernel: Bluetooth: HCI device and connection manager initialized Mar 05 15:43:54 madtunes kernel: Bluetooth: HCI socket layer initialized Mar 05 15:43:54 madtunes kernel: Bluetooth: L2CAP socket layer initialized Mar 05 15:43:54 madtunes kernel: Bluetooth: SCO socket layer initialized Mar 05 15:43:54 madtunes btuart[464]: bcm43xx_init Mar 05 15:43:54 madtunes btuart[464]: Flash firmware /lib/firmware/brcm/BCM4345C0.hcd Mar 05 15:43:54 madtunes btuart[464]: Set BDADDR UART: b8:27:eb:48:76:7e Mar 05 15:43:54 madtunes btuart[464]: Set Controller UART speed to 3000000 bit/s Mar 05 15:43:54 madtunes btuart[464]: Device setup complete Mar 05 15:43:54 madtunes kernel: Bluetooth: HCI UART driver ver 2.3 Mar 05 15:43:54 madtunes kernel: Bluetooth: HCI UART protocol H4 registered Mar 05 15:43:54 madtunes kernel: Bluetooth: HCI UART protocol Three-wire (H5) registered Mar 05 15:43:54 madtunes kernel: Bluetooth: HCI UART protocol Broadcom registered Mar 05 15:43:54 madtunes systemd[1]: Starting Load/Save RF Kill Switch Status... Mar 05 15:43:54 madtunes systemd[1]: Started Configure Bluetooth Modems connected by UART. Mar 05 15:43:54 madtunes systemd[1]: Started Load/Save RF Kill Switch Status. Mar 05 15:43:54 madtunes systemd[1]: Created slice system-bthelper.slice. Mar 05 15:43:54 madtunes systemd[1]: Starting Raspberry Pi bluetooth helper... Mar 05 15:43:54 madtunes bthelper[693]: Raspberry Pi BDADDR already set Mar 05 15:43:54 madtunes systemd[1]: Started Raspberry Pi bluetooth helper. Mar 05 15:43:54 madtunes systemd[1]: Starting Bluetooth service... Mar 05 15:43:54 madtunes bluetoothd[703]: Bluetooth daemon 5.50 Mar 05 15:43:54 madtunes bluetoothd[703]: Unknown key AutoConnectTimeout for group General in /etc/bluetooth/main.conf Mar 05 15:43:54 madtunes systemd[1]: Started Bluetooth service. Mar 05 15:43:54 madtunes systemd[1]: Reached target Bluetooth. Mar 05 15:43:54 madtunes bluetoothd[703]: Starting SDP server Mar 05 15:43:54 madtunes bluetoothd[703]: Excluding (cli) sap Mar 05 15:43:54 madtunes kernel: Bluetooth: BNEP (Ethernet Emulation) ver 1.3 Mar 05 15:43:54 madtunes kernel: Bluetooth: BNEP filters: protocol multicast Mar 05 15:43:54 madtunes kernel: Bluetooth: BNEP socket layer initialized Mar 05 15:43:54 madtunes bluetoothd[703]: Bluetooth management interface 1.18 initialized Mar 05 15:43:54 madtunes dbus-daemon[497]: [system] Activating via systemd: service name='org.freedesktop.hostname1' unit='dbus-org.freedesktop.hostname1.service' requested by ':1.5' (uid=0 pid=703 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap ") Mar 05 15:43:54 madtunes systemd[1]: Starting Hostname Service... Mar 05 15:43:54 madtunes volumio-remote-updater[474]: [2025-03-05 15:43:54] [info] asio async_connect error: system:111 (Connection refused) Mar 05 15:43:54 madtunes volumio-remote-updater[474]: [2025-03-05 15:43:54] [info] Error getting remote endpoint: system:107 (Transport endpoint is not connected) Mar 05 15:43:54 madtunes volumio-remote-updater[474]: [2025-03-05 15:43:54] [error] handle_connect error: Underlying Transport Error Mar 05 15:43:54 madtunes bluetoothd[703]: Failed to set privacy: Rejected (0x0b) Mar 05 15:43:54 madtunes dbus-daemon[497]: [system] Successfully activated service 'org.freedesktop.hostname1' Mar 05 15:43:54 madtunes systemd[1]: Started Hostname Service. Mar 05 15:43:55 madtunes sudo[677]: pam_unix(sudo:session): session closed for user root Mar 05 15:43:55 madtunes wireless.js[463]: Start wireless flow Mar 05 15:43:55 madtunes wireless.js[463]: Stopped hotspot (if there).. Mar 05 15:43:55 madtunes sudo[707]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ip addr flush dev wlan0 Mar 05 15:43:55 madtunes sudo[707]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 05 15:43:55 madtunes sudo[707]: pam_unix(sudo:session): session closed for user root Mar 05 15:43:55 madtunes sudo[709]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 down Mar 05 15:43:55 madtunes sudo[709]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 05 15:43:56 madtunes sudo[709]: pam_unix(sudo:session): session closed for user root Mar 05 15:43:56 madtunes wireless.js[463]: DHCP IP Mar 05 15:43:56 madtunes wireless.js[463]: Start ap Mar 05 15:43:56 madtunes wpa_supplicant[711]: Successfully initialized wpa_supplicant Mar 05 15:43:56 madtunes sudo[712]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/dhcpcd Mar 05 15:43:56 madtunes sudo[712]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 05 15:43:56 madtunes kernel: brcmfmac: brcmf_cfg80211_set_power_mgmt: power save disabled Mar 05 15:43:56 madtunes dhcpcd[713]: dev: loaded udev Mar 05 15:43:56 madtunes dhcpcd-run-hooks[731]: wlan0: starting wpa_supplicant Mar 05 15:43:56 madtunes dhcpcd-run-hooks[736]: wlan0: failed to start wpa_supplicant Mar 05 15:43:56 madtunes dhcpcd-run-hooks[737]: 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 Mar 05 15:43:56 madtunes dhcpcd[713]: wlan0: connected to Access Point `' Mar 05 15:43:56 madtunes dhcpcd[713]: no interfaces have a carrier Mar 05 15:43:56 madtunes dhcpcd[713]: forked to background, child pid 747 Mar 05 15:43:56 madtunes dhcpcd[747]: eth0: waiting for carrier Mar 05 15:43:56 madtunes dhcpcd[747]: wlan0: waiting for carrier Mar 05 15:43:56 madtunes sudo[712]: pam_unix(sudo:session): session closed for user root Mar 05 15:43:57 madtunes wireless.js[463]: trying... Mar 05 15:43:57 madtunes sudo[749]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Mar 05 15:43:57 madtunes sudo[749]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 05 15:43:57 madtunes sudo[749]: pam_unix(sudo:session): session closed for user root Mar 05 15:43:58 madtunes wireless.js[463]: trying... Mar 05 15:43:58 madtunes sudo[752]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Mar 05 15:43:58 madtunes sudo[752]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 05 15:43:58 madtunes sudo[752]: pam_unix(sudo:session): session closed for user root Mar 05 15:43:59 madtunes systemd[1]: systemd-rfkill.service: Succeeded. Mar 05 15:43:59 madtunes wpa_supplicant[735]: wlan0: Trying to associate with SSID 'SKYSXCRR' Mar 05 15:43:59 madtunes bthelper[693]: Changing power off succeeded Mar 05 15:43:59 madtunes bthelper[693]: [CHG] Controller B8:27:EB:48:76:7E Powered: no Mar 05 15:43:59 madtunes bthelper[693]: [CHG] Controller B8:27:EB:48:76:7E Discovering: no Mar 05 15:43:59 madtunes bthelper[693]: [CHG] Controller B8:27:EB:48:76:7E Class: 0x00000000 Mar 05 15:43:59 madtunes wireless.js[463]: trying... Mar 05 15:43:59 madtunes bthelper[693]: [CHG] Controller B8:27:EB:48:76:7E Class: 0x0000041c Mar 05 15:43:59 madtunes bthelper[693]: Changing power on succeeded Mar 05 15:43:59 madtunes sudo[762]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Mar 05 15:43:59 madtunes sudo[762]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 05 15:43:59 madtunes sudo[762]: pam_unix(sudo:session): session closed for user root Mar 05 15:43:59 madtunes kernel: cam1-reg: disabling Mar 05 15:43:59 madtunes kernel: cam-dummy-reg: disabling Mar 05 15:44:00 madtunes wireless.js[463]: trying... Mar 05 15:44:00 madtunes sudo[765]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Mar 05 15:44:00 madtunes sudo[765]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 05 15:44:00 madtunes sudo[765]: pam_unix(sudo:session): session closed for user root Mar 05 15:44:01 madtunes wireless.js[463]: trying... Mar 05 15:44:01 madtunes sudo[768]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Mar 05 15:44:01 madtunes sudo[768]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 05 15:44:01 madtunes sudo[768]: pam_unix(sudo:session): session closed for user root Mar 05 15:44:01 madtunes dhcpcd[747]: wlan0: carrier acquired Mar 05 15:44:01 madtunes dhcpcd[747]: wlan0: connected to Access Point `SKYSXCRR' Mar 05 15:44:01 madtunes wpa_supplicant[735]: wlan0: Associated with 9c:31:c3:ab:6f:1d Mar 05 15:44:01 madtunes wpa_supplicant[735]: wlan0: CTRL-EVENT-CONNECTED - Connection to 9c:31:c3:ab:6f:1d completed [id=0 id_str=] Mar 05 15:44:01 madtunes wpa_supplicant[735]: wlan0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0 Mar 05 15:44:01 madtunes dhcpcd[747]: DUID 00:01:00:01:29:d8:61:b9:b8:27:eb:b7:89:81 Mar 05 15:44:01 madtunes dhcpcd[747]: wlan0: IAID eb:b7:89:81 Mar 05 15:44:01 madtunes dhcpcd[747]: wlan0: adding address fe80::af9f:725d:81:6b8 Mar 05 15:44:01 madtunes dhcpcd[747]: ipv6_addaddr1: Permission denied Mar 05 15:44:01 madtunes dhcpcd[747]: wlan0: carrier lost Mar 05 15:44:01 madtunes dhcpcd[747]: wlan0: carrier acquired Mar 05 15:44:01 madtunes wpa_supplicant[735]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=COUNTRY_IE type=COUNTRY alpha2=GB Mar 05 15:44:01 madtunes dhcpcd[747]: wlan0: IAID eb:b7:89:81 Mar 05 15:44:02 madtunes volumio-remote-updater[474]: [2025-03-05 15:44:02] [info] asio async_connect error: system:111 (Connection refused) Mar 05 15:44:02 madtunes volumio-remote-updater[474]: [2025-03-05 15:44:02] [info] Error getting remote endpoint: system:107 (Transport endpoint is not connected) Mar 05 15:44:02 madtunes volumio-remote-updater[474]: [2025-03-05 15:44:02] [error] handle_connect error: Underlying Transport Error Mar 05 15:44:02 madtunes dhcpcd[747]: wlan0: rebinding lease of 192.168.0.18 Mar 05 15:44:02 madtunes wireless.js[463]: trying... Mar 05 15:44:02 madtunes sudo[784]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Mar 05 15:44:02 madtunes sudo[784]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 05 15:44:02 madtunes sudo[784]: pam_unix(sudo:session): session closed for user root Mar 05 15:44:02 madtunes dhcpcd[747]: wlan0: soliciting an IPv6 router Mar 05 15:44:03 madtunes wireless.js[463]: trying... Mar 05 15:44:03 madtunes sudo[787]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Mar 05 15:44:03 madtunes sudo[787]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 05 15:44:03 madtunes sudo[787]: pam_unix(sudo:session): session closed for user root Mar 05 15:44:04 madtunes wireless.js[463]: trying... Mar 05 15:44:04 madtunes sudo[790]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Mar 05 15:44:04 madtunes sudo[790]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 05 15:44:04 madtunes sudo[790]: pam_unix(sudo:session): session closed for user root Mar 05 15:44:05 madtunes wireless.js[463]: trying... Mar 05 15:44:05 madtunes sudo[793]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Mar 05 15:44:05 madtunes sudo[793]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 05 15:44:05 madtunes sudo[793]: pam_unix(sudo:session): session closed for user root Mar 05 15:44:06 madtunes dhcpcd[747]: wlan0: probing address 192.168.0.18/24 Mar 05 15:44:06 madtunes wireless.js[463]: trying... Mar 05 15:44:06 madtunes sudo[796]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Mar 05 15:44:06 madtunes sudo[796]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 05 15:44:06 madtunes sudo[796]: pam_unix(sudo:session): session closed for user root Mar 05 15:44:07 madtunes wireless.js[463]: trying... Mar 05 15:44:07 madtunes sudo[799]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Mar 05 15:44:07 madtunes sudo[799]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 05 15:44:07 madtunes sudo[799]: pam_unix(sudo:session): session closed for user root Mar 05 15:44:08 madtunes wireless.js[463]: trying... Mar 05 15:44:08 madtunes sudo[802]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Mar 05 15:44:08 madtunes sudo[802]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 05 15:44:08 madtunes sudo[802]: pam_unix(sudo:session): session closed for user root Mar 05 15:44:09 madtunes wireless.js[463]: trying... Mar 05 15:44:09 madtunes sudo[805]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Mar 05 15:44:09 madtunes sudo[805]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 05 15:44:09 madtunes sudo[805]: pam_unix(sudo:session): session closed for user root Mar 05 15:44:10 madtunes wireless.js[463]: trying... Mar 05 15:44:10 madtunes sudo[808]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Mar 05 15:44:10 madtunes sudo[808]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 05 15:44:10 madtunes sudo[808]: pam_unix(sudo:session): session closed for user root Mar 05 15:44:11 madtunes dhcpcd[747]: wlan0: leased 192.168.0.18 for 86400 seconds Mar 05 15:44:11 madtunes avahi-daemon[462]: Joining mDNS multicast group on interface wlan0.IPv4 with address 192.168.0.18. Mar 05 15:44:11 madtunes avahi-daemon[462]: New relevant interface wlan0.IPv4 for mDNS. Mar 05 15:44:11 madtunes dhcpcd[747]: wlan0: adding route to 192.168.0.0/24 Mar 05 15:44:11 madtunes avahi-daemon[462]: Registering new address record for 192.168.0.18 on wlan0.IPv4. Mar 05 15:44:11 madtunes dhcpcd[747]: wlan0: adding default route via 192.168.0.1 Mar 05 15:44:11 madtunes nmbd[616]: [2025/03/05 15:44:11.507332, 0] ../lib/util/become_daemon.c:138(daemon_ready) Mar 05 15:44:11 madtunes systemd[1]: Started Samba NMB Daemon. Mar 05 15:44:11 madtunes nmbd[616]: daemon_ready: STATUS=daemon 'nmbd' finished starting up and ready to serve connections Mar 05 15:44:11 madtunes systemd[1]: Starting Samba Winbind Daemon... Mar 05 15:44:11 madtunes nmbd[616]: [2025/03/05 15:44:11.532072, 0] ../source3/nmbd/nmbd_namequery.c:109(query_name_response) Mar 05 15:44:11 madtunes nmbd[616]: query_name_response: Multiple (2) responses received for a query on subnet 192.168.0.18 for name WORKGROUP<1d>. Mar 05 15:44:11 madtunes nmbd[616]: This response was from IP 192.168.0.29, reporting an IP address of 192.168.0.29. Mar 05 15:44:11 madtunes wireless.js[463]: trying... Mar 05 15:44:11 madtunes sudo[834]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Mar 05 15:44:11 madtunes sudo[834]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 05 15:44:11 madtunes sudo[834]: pam_unix(sudo:session): session closed for user root Mar 05 15:44:11 madtunes wireless.js[463]: Connected to: ----SKYSXCRR Mar 05 15:44:11 madtunes wireless.js[463]: ---- Mar 05 15:44:11 madtunes sudo[837]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 05 15:44:11 madtunes sudo[837]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 05 15:44:11 madtunes sudo[837]: pam_unix(sudo:session): session closed for user root Mar 05 15:44:11 madtunes wireless.js[463]: ... joined AP, wlan0 IPv4 is 192.168.0.18, ipV6 is undefined Mar 05 15:44:11 madtunes wireless.js[463]: It's done! AP Mar 05 15:44:11 madtunes systemd[1]: Started Wireless Services. Mar 05 15:44:11 madtunes systemd[1]: Started Volumio Backend Module. Mar 05 15:44:11 madtunes kernel: brcmfmac: brcmf_cfg80211_set_power_mgmt: power save disabled Mar 05 15:44:11 madtunes winbindd[831]: [2025/03/05 15:44:11.834582, 0] ../source3/winbindd/winbindd_cache.c:3160(initialize_winbindd_cache) Mar 05 15:44:11 madtunes winbindd[831]: initialize_winbindd_cache: clearing cache and re-creating with version number 2 Mar 05 15:44:11 madtunes winbindd[831]: [2025/03/05 15:44:11.858953, 0] ../lib/util/become_daemon.c:138(daemon_ready) Mar 05 15:44:11 madtunes systemd[1]: Started Samba Winbind Daemon. Mar 05 15:44:11 madtunes winbindd[831]: daemon_ready: STATUS=daemon 'winbindd' finished starting up and ready to serve connections Mar 05 15:44:11 madtunes systemd[1]: Starting Samba SMB Daemon... Mar 05 15:44:12 madtunes volumio-remote-updater[474]: [2025-03-05 15:44:12] [info] asio async_connect error: system:111 (Connection refused) Mar 05 15:44:12 madtunes volumio-remote-updater[474]: [2025-03-05 15:44:12] [info] Error getting remote endpoint: system:107 (Transport endpoint is not connected) Mar 05 15:44:12 madtunes volumio-remote-updater[474]: [2025-03-05 15:44:12] [error] handle_connect error: Underlying Transport Error Mar 05 15:44:12 madtunes winbindd[831]: [2025/03/05 15:44:12.438384, 0] ../source3/winbindd/wb_lookupsids.c:659(wb_lookupsids_recv) Mar 05 15:44:12 madtunes winbindd[831]: res_names->count = 3, expected 4 Mar 05 15:44:12 madtunes systemd[1]: Started Samba SMB Daemon. Mar 05 15:44:12 madtunes smbd[852]: [2025/03/05 15:44:12.479413, 0] ../lib/util/become_daemon.c:138(daemon_ready) Mar 05 15:44:12 madtunes systemd[1]: Reached target Multi-User System. Mar 05 15:44:12 madtunes smbd[852]: daemon_ready: STATUS=daemon 'smbd' finished starting up and ready to serve connections Mar 05 15:44:12 madtunes systemd[1]: Reached target Graphical Interface. Mar 05 15:44:12 madtunes systemd[1]: Starting Update UTMP about System Runlevel Changes... Mar 05 15:44:12 madtunes systemd[1]: systemd-update-utmp-runlevel.service: Succeeded. Mar 05 15:44:12 madtunes systemd[1]: Started Update UTMP about System Runlevel Changes. Mar 05 15:44:12 madtunes systemd[1]: Startup finished in 12.527s (kernel) + 34.557s (userspace) = 47.085s. Mar 05 15:44:12 madtunes ntpd[639]: Listen normally on 3 wlan0 192.168.0.18:123 Mar 05 15:44:12 madtunes ntpd[639]: new interface(s) found: waking up resolver Mar 05 15:44:14 madtunes volumio[842]: info: ------------------------------------------- Mar 05 15:44:14 madtunes volumio[842]: info: ----- Volumio3 ---- Mar 05 15:44:14 madtunes volumio[842]: info: ------------------------------------------- Mar 05 15:44:14 madtunes volumio[842]: info: ----- System startup ---- Mar 05 15:44:14 madtunes volumio[842]: info: ------------------------------------------- Mar 05 15:44:15 madtunes systemd[1]: systemd-fsckd.service: Succeeded. Mar 05 15:44:15 madtunes volumio[842]: info: MYVOLUMIO Environment detected Mar 05 15:44:15 madtunes volumio[842]: info: Plugin folders cleanup Mar 05 15:44:15 madtunes volumio[842]: info: Scanning into folder /volumio/app/plugins/ Mar 05 15:44:15 madtunes volumio[842]: info: Scanning category audio_interface Mar 05 15:44:15 madtunes volumio[842]: info: Scanning category miscellanea Mar 05 15:44:15 madtunes volumio[842]: info: Scanning category music_service Mar 05 15:44:15 madtunes volumio[842]: info: Scanning category plugins.json Mar 05 15:44:15 madtunes volumio[842]: info: Scanning category system_controller Mar 05 15:44:15 madtunes volumio[842]: info: Scanning category user_interface Mar 05 15:44:15 madtunes volumio[842]: info: Scanning into folder /data/plugins/ Mar 05 15:44:15 madtunes volumio[842]: info: Scanning category music_service Mar 05 15:44:15 madtunes volumio[842]: info: Plugin folders cleanup completed Mar 05 15:44:15 madtunes volumio[842]: info: ------------------------------------------- Mar 05 15:44:15 madtunes volumio[842]: info: ----- Core plugins startup ---- Mar 05 15:44:15 madtunes volumio[842]: info: ------------------------------------------- Mar 05 15:44:15 madtunes volumio[842]: info: Loading plugins from folder /volumio/app/plugins/ Mar 05 15:44:15 madtunes volumio[842]: info: Adding plugin upnp to MyMusic Plugins Mar 05 15:44:15 madtunes volumio[842]: info: Adding plugin airplay_emulation to MyMusic Plugins Mar 05 15:44:15 madtunes volumio[842]: info: Adding plugin upnp_browser to MyMusic Plugins Mar 05 15:44:15 madtunes volumio[842]: info: Loading plugins from folder /data/plugins/ Mar 05 15:44:15 madtunes volumio[842]: info: Loading plugin "system"... Mar 05 15:44:15 madtunes volumio[842]: info: Loading plugin "appearance"... Mar 05 15:44:16 madtunes sh[381]: timed out Mar 05 15:44:16 madtunes dhcpcd[426]: timed out Mar 05 15:44:16 madtunes sh[381]: dhcpcd exited Mar 05 15:44:16 madtunes dhcpcd[426]: dhcpcd exited Mar 05 15:44:16 madtunes sh[381]: ifup: failed to bring up eth0 Mar 05 15:44:16 madtunes systemd[1]: ifup@eth0.service: Main process exited, code=exited, status=1/FAILURE Mar 05 15:44:16 madtunes systemd[1]: ifup@eth0.service: Failed with result 'exit-code'. Mar 05 15:44:17 madtunes volumio[842]: info: Loading plugin "network"... Mar 05 15:44:17 madtunes volumio[842]: info: Refreshing Cached IP Addresses Mar 05 15:44:17 madtunes sudo[873]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Mar 05 15:44:17 madtunes sudo[873]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 05 15:44:17 madtunes sudo[873]: pam_unix(sudo:session): session closed for user root Mar 05 15:44:17 madtunes volumio[842]: info: Loading plugin "services"... Mar 05 15:44:17 madtunes sudo[875]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 05 15:44:17 madtunes sudo[875]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 05 15:44:17 madtunes volumio[842]: info: Loading plugin "alsa_controller"... Mar 05 15:44:17 madtunes sudo[875]: pam_unix(sudo:session): session closed for user root Mar 05 15:44:17 madtunes sudo[878]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Mar 05 15:44:17 madtunes sudo[878]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 05 15:44:17 madtunes volumio[842]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 05 15:44:17 madtunes volumio[842]: info: Loading plugin "wizard"... Mar 05 15:44:17 madtunes volumio[842]: info: Loading plugin "volumio_command_line_client"... Mar 05 15:44:17 madtunes volumio[842]: info: Loading plugin "upnp"... Mar 05 15:44:17 madtunes volumio[842]: info: [1741189457492] Starting Upmpd Daemon Mar 05 15:44:17 madtunes volumio[842]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Mar 05 15:44:17 madtunes volumio[842]: info: Loading plugin "my_music"... Mar 05 15:44:17 madtunes volumio[842]: info: Loading plugin "mpd"... Mar 05 15:44:17 madtunes volumio[842]: info: Creating MPD Configuration file Mar 05 15:44:17 madtunes volumio[842]: info: Loading plugin "upnp_browser"... Mar 05 15:44:17 madtunes sudo[886]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Mar 05 15:44:17 madtunes sudo[886]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 05 15:44:17 madtunes sudo[886]: pam_unix(sudo:session): session closed for user root Mar 05 15:44:17 madtunes sudo[888]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Mar 05 15:44:17 madtunes sudo[888]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 05 15:44:18 madtunes systemd[1]: Stopping Music Player Daemon... Mar 05 15:44:18 madtunes systemd[1]: mpd.service: Succeeded. Mar 05 15:44:18 madtunes systemd[1]: Stopped Music Player Daemon. Mar 05 15:44:18 madtunes systemd[1]: Starting Music Player Daemon... Mar 05 15:44:18 madtunes volumio[842]: info: Loading plugin "networkfs"... Mar 05 15:44:18 madtunes volumio[842]: info: Starting Udev Watcher for removable devices Mar 05 15:44:18 madtunes sudo[896]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=admin,password=Batmanrodtod@1,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //192.168.0.29/public/MEDIA/MUSIC /mnt/NAS/Nas Mar 05 15:44:18 madtunes sudo[896]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 05 15:44:19 madtunes kernel: FS-Cache: Netfs 'cifs' registered for caching Mar 05 15:44:19 madtunes kernel: Key type cifs.spnego registered Mar 05 15:44:19 madtunes kernel: Key type cifs.idmap registered Mar 05 15:44:19 madtunes kernel: CIFS: Attempting to mount //192.168.0.29/public/MEDIA/MUSIC Mar 05 15:44:19 madtunes 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. Mar 05 15:44:19 madtunes volumio[842]: info: Ignoring mount for partition: boot Mar 05 15:44:19 madtunes volumio[842]: info: Ignoring mount for partition: volumio Mar 05 15:44:19 madtunes volumio[842]: info: Ignoring mount for partition: volumio_data Mar 05 15:44:19 madtunes volumio[842]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Mar 05 15:44:19 madtunes volumio[842]: info: Loading plugin "alarm-clock"... Mar 05 15:44:19 madtunes mpd[893]: Mar 05 15:44 : exception: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Mar 05 15:44:19 madtunes volumio[842]: info: Loading plugin "airplay_emulation"... Mar 05 15:44:19 madtunes volumio[842]: info: Starting Shairport Sync Mar 05 15:44:19 madtunes volumio[842]: info: Loading plugin "last_100"... Mar 05 15:44:19 madtunes volumio[842]: info: Loading plugin "webradio"... Mar 05 15:44:19 madtunes sudo[896]: pam_unix(sudo:session): session closed for user root Mar 05 15:44:19 madtunes volumio[842]: info: Loading plugin "i2s_dacs"... Mar 05 15:44:19 madtunes volumio[842]: info: I2S DAC not set, start Auto-detection Mar 05 15:44:19 madtunes volumio[842]: info: Loading plugin "volumiodiscovery"... Mar 05 15:44:19 madtunes volumio[842]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Mar 05 15:44:19 madtunes node[842]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Mar 05 15:44:19 madtunes volumio[842]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 05 15:44:19 madtunes node[842]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 05 15:44:19 madtunes volumio[842]: *** WARNING *** For more information see Mar 05 15:44:19 madtunes node[842]: *** WARNING *** For more information see Mar 05 15:44:19 madtunes volumio[842]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Mar 05 15:44:19 madtunes node[842]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Mar 05 15:44:19 madtunes volumio[842]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 05 15:44:19 madtunes node[842]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 05 15:44:19 madtunes volumio[842]: *** WARNING *** For more information see Mar 05 15:44:19 madtunes node[842]: *** WARNING *** For more information see Mar 05 15:44:19 madtunes volumio[842]: info: Applying required configuration parameters for plugin volumiodiscovery Mar 05 15:44:19 madtunes volumio[842]: info: Discovery: Started advertising with name: madtunes Mar 05 15:44:19 madtunes volumio[842]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Mar 05 15:44:19 madtunes volumio[842]: info: Loading plugin "spop"... Mar 05 15:44:20 madtunes mpd[893]: Mar 05 15:44 : exception: Input plugin 'tidal' is unavailable: No Tidal application token configured Mar 05 15:44:20 madtunes mpd[893]: Mar 05 15:44 : exception: Input plugin 'qobuz' is unavailable: No Qobuz app_id configured Mar 05 15:44:20 madtunes systemd[1]: Started Music Player Daemon. Mar 05 15:44:20 madtunes sudo[888]: pam_unix(sudo:session): session closed for user root Mar 05 15:44:21 madtunes sudo[878]: pam_unix(sudo:session): session closed for user root Mar 05 15:44:21 madtunes volumio[842]: info: Loading plugin "ytcr"... Mar 05 15:44:22 madtunes volumio-remote-updater[474]: [2025-03-05 15:44:22] [connect] Successful connection Mar 05 15:44:24 madtunes systemd[1]: systemd-hostnamed.service: Succeeded. Mar 05 15:44:25 madtunes volumio[842]: info: Loading plugin "outputs"... Mar 05 15:44:25 madtunes volumio[842]: info: Loading plugin "albumart"... Mar 05 15:44:25 madtunes volumio[842]: info: Plugin example_plugin is not enabled Mar 05 15:44:25 madtunes volumio[842]: info: Loading plugin "inputs"... Mar 05 15:44:25 madtunes volumio[842]: info: Loading plugin "updater_comm"... Mar 05 15:44:25 madtunes volumio[842]: info: Plugin mpdemulation is not enabled Mar 05 15:44:25 madtunes volumio[842]: info: Loading plugin "rest_api"... Mar 05 15:44:25 madtunes volumio[842]: info: Loading plugin "websocket"... Mar 05 15:44:25 madtunes volumio[842]: info: Loading i18n strings for locale en Mar 05 15:44:25 madtunes volumio[842]: Updating browse sources language Mar 05 15:44:25 madtunes volumio[842]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 05 15:44:25 madtunes volumio[842]: Forking 3 albumart workers Mar 05 15:44:25 madtunes volumio[842]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 05 15:44:25 madtunes volumio[842]: info: CoreCommandRouter::initPlayerControls Mar 05 15:44:25 madtunes volumio[842]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 15:44:25 madtunes volumio[842]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 15:44:25 madtunes volumio[842]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 15:44:25 madtunes volumio[842]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 15:44:25 madtunes volumio[842]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 15:44:25 madtunes volumio[842]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 15:44:25 madtunes volumio[842]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 15:44:25 madtunes volumio[842]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 15:44:25 madtunes volumio[842]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 05 15:44:25 madtunes volumio[842]: Express server listening on port 3000 Mar 05 15:44:25 madtunes volumio[842]: [Metrics] WebUI: 12s 195.85ms Mar 05 15:44:25 madtunes volumio[842]: info: CoreStateMachine::resetVolumioState Mar 05 15:44:25 madtunes volumio[842]: info: CoreStateMachine::getcurrentVolume Mar 05 15:44:25 madtunes volumio[842]: info: CoreCommandRouter::volumioRetrievevolume Mar 05 15:44:25 madtunes volumio[842]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 05 15:44:25 madtunes volumio[842]: info: MPD Permissions set Mar 05 15:44:26 madtunes volumio-remote-updater[474]: [2025-03-05 15:44:26] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1741189462 101 Mar 05 15:44:26 madtunes volumio[842]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Total Clients: 1 Mar 05 15:44:26 madtunes volumio[842]: info: MPD running with PID893 Mar 05 15:44:26 madtunes volumio[842]: ,establishing connection Mar 05 15:44:26 madtunes volumio[842]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 15:44:26 madtunes volumio[842]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 15:44:26 madtunes volumio[842]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 15:44:26 madtunes volumio[842]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 15:44:26 madtunes volumio[842]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 15:44:26 madtunes volumio[842]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 15:44:26 madtunes volumio[842]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 15:44:26 madtunes volumio[842]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 05 15:44:26 madtunes volumio[842]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 15:44:26 madtunes volumio[842]: info: Reloading queue from file Mar 05 15:44:26 madtunes volumio[842]: error: updateQueue error: null Mar 05 15:44:26 madtunes volumio[842]: info: CoreStateMachine::setRepeat false single undefined Mar 05 15:44:26 madtunes volumio[842]: info: CoreStateMachine::pushState Mar 05 15:44:26 madtunes volumio[842]: info: CorePlayQueue::getTrack 0 Mar 05 15:44:26 madtunes volumio[842]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 05 15:44:26 madtunes volumio[842]: info: CoreCommandRouter::volumioPushState Mar 05 15:44:26 madtunes volumio[842]: info: CoreStateMachine::setRandom false Mar 05 15:44:26 madtunes volumio[842]: info: CoreStateMachine::pushState Mar 05 15:44:26 madtunes volumio[842]: info: CorePlayQueue::getTrack 0 Mar 05 15:44:26 madtunes volumio[842]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 05 15:44:26 madtunes volumio[842]: info: CoreCommandRouter::volumioPushState Mar 05 15:44:26 madtunes volumio[842]: info: Setting Device type: Raspberry PI Mar 05 15:44:26 madtunes volumio[842]: info: Completed loading Core Plugins Mar 05 15:44:26 madtunes volumio[842]: info: Preparing to generate the ALSA configuration file Mar 05 15:44:26 madtunes volumio[842]: info: VolumeController:: Volume=100 Mute =false Mar 05 15:44:26 madtunes volumio[842]: info: CoreStateMachine::pushState Mar 05 15:44:26 madtunes volumio[842]: info: CorePlayQueue::getTrack 0 Mar 05 15:44:26 madtunes volumio[842]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 05 15:44:26 madtunes volumio[842]: info: CoreCommandRouter::volumioPushState Mar 05 15:44:26 madtunes volumio[842]: info: CoreStateMachine::updateTrackBlock Mar 05 15:44:26 madtunes volumio[842]: info: CorePlayQueue::getTrackBlock Mar 05 15:44:26 madtunes volumio[842]: info: CoreCommandRouter::volumioRetrievevolume Mar 05 15:44:26 madtunes volumio[842]: error: updateQueue error: null Mar 05 15:44:26 madtunes volumio[842]: info: Asound.conf file unchanged, so no further update is needed Mar 05 15:44:26 madtunes volumio[842]: info: Output device has changed, restarting MPD Mar 05 15:44:26 madtunes volumio[842]: info: Output device has changed, restarting Shairport Sync Mar 05 15:44:26 madtunes volumio[842]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 15:44:26 madtunes volumio[842]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 05 15:44:26 madtunes sudo[977]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Mar 05 15:44:26 madtunes sudo[976]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Mar 05 15:44:26 madtunes sudo[976]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 05 15:44:26 madtunes sudo[977]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 05 15:44:26 madtunes sudo[976]: pam_unix(sudo:session): session closed for user root Mar 05 15:44:26 madtunes systemd[1]: Stopping Music Player Daemon... Mar 05 15:44:26 madtunes volumio[842]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 05 15:44:26 madtunes volumio[842]: info: ___________ START PLUGINS ___________ Mar 05 15:44:26 madtunes volumio[842]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 05 15:44:26 madtunes volumio[842]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 05 15:44:26 madtunes volumio[842]: info: [1741189466569] CoreMusicLibrary::Adding element Media Servers Mar 05 15:44:26 madtunes volumio[842]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 05 15:44:26 madtunes volumio[842]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 15:44:26 madtunes volumio[842]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 05 15:44:26 madtunes systemd[1]: mpd.service: Succeeded. Mar 05 15:44:26 madtunes systemd[1]: Stopped Music Player Daemon. Mar 05 15:44:26 madtunes systemd[1]: Starting Music Player Daemon... Mar 05 15:44:26 madtunes volumio[842]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 05 15:44:26 madtunes volumio[842]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 15:44:26 madtunes volumio[842]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 05 15:44:26 madtunes volumio[842]: Starting albumart workers Mar 05 15:44:26 madtunes volumio[842]: Starting albumart workers Mar 05 15:44:26 madtunes volumio[842]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 05 15:44:26 madtunes volumio[842]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 05 15:44:26 madtunes volumio[842]: info: [1741189466777] CoreMusicLibrary::Adding element Last_100 Mar 05 15:44:26 madtunes volumio[842]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 05 15:44:26 madtunes volumio[842]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 05 15:44:26 madtunes volumio[842]: info: [1741189466783] CoreMusicLibrary::Adding element Webradio Mar 05 15:44:26 madtunes volumio[842]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 05 15:44:26 madtunes volumio[842]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 05 15:44:26 madtunes volumio[842]: Starting albumart workers Mar 05 15:44:26 madtunes volumio[842]: info: Creating Spotify config file Mar 05 15:44:26 madtunes volumio[842]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 15:44:27 madtunes volumio[842]: info: Volumio Calling Home Mar 05 15:44:27 madtunes volumio[842]: info: Discovery: adding d62e01d9-0620-42b1-a2ea-7248217b4e81 Mar 05 15:44:27 madtunes volumio[842]: info: Discovery: Found device madtunes Mar 05 15:44:27 madtunes volumio[842]: info: CoreCommandRouter::volumioGetState Mar 05 15:44:27 madtunes volumio[842]: info: CorePlayQueue::getTrack 0 Mar 05 15:44:27 madtunes volumio[842]: info: MPD Permissions set Mar 05 15:44:27 madtunes volumio[842]: info: Volumio called home Mar 05 15:44:27 madtunes volumio[842]: info: Spotify config file written Mar 05 15:44:27 madtunes sudo[997]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 05 15:44:27 madtunes sudo[997]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 05 15:44:27 madtunes systemd[1]: Started go-librespot Daemon. Mar 05 15:44:27 madtunes go-librespot[1007]: Librespot-go daemon starting... Mar 05 15:44:27 madtunes sudo[997]: pam_unix(sudo:session): session closed for user root Mar 05 15:44:27 madtunes volumio[842]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 2 Mar 05 15:44:27 madtunes volumio[842]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 15:44:27 madtunes volumio[842]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 15:44:27 madtunes volumio[842]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 15:44:27 madtunes volumio[842]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 15:44:27 madtunes volumio[842]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 15:44:27 madtunes sudo[1011]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Mar 05 15:44:27 madtunes volumio[842]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 15:44:27 madtunes sudo[1011]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 05 15:44:27 madtunes volumio[842]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 15:44:27 madtunes volumio[842]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 15:44:27 madtunes sudo[1011]: pam_unix(sudo:session): session closed for user root Mar 05 15:44:27 madtunes sudo[1012]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 05 15:44:27 madtunes sudo[1012]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 05 15:44:27 madtunes volumio[842]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 05 15:44:27 madtunes volumio[842]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 15:44:27 madtunes volumio[842]: info: No need to fix Spotify hosts Mar 05 15:44:27 madtunes sudo[1012]: pam_unix(sudo:session): session closed for user root Mar 05 15:44:27 madtunes volumio[842]: info: VolumeController:: Volume=100 Mute =false Mar 05 15:44:27 madtunes volumio[842]: info: CoreCommandRouter::volumioGetState Mar 05 15:44:27 madtunes volumio[842]: info: CorePlayQueue::getTrack 0 Mar 05 15:44:27 madtunes volumio[842]: info: CoreStateMachine::pushState Mar 05 15:44:27 madtunes volumio[842]: info: CorePlayQueue::getTrack 0 Mar 05 15:44:27 madtunes volumio[842]: info: CoreCommandRouter::volumioPushState Mar 05 15:44:28 madtunes volumio[842]: info: Starting Shairport Sync Mar 05 15:44:28 madtunes volumio[842]: info: Starting Shairport Sync Mar 05 15:44:28 madtunes sudo[1041]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Mar 05 15:44:28 madtunes sudo[1041]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 05 15:44:28 madtunes volumio[842]: info: Starting Shairport Sync Mar 05 15:44:28 madtunes sudo[1043]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Mar 05 15:44:28 madtunes sudo[1043]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 05 15:44:28 madtunes systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Mar 05 15:44:28 madtunes systemd[1]: shairport-sync.service: Succeeded. Mar 05 15:44:28 madtunes systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Mar 05 15:44:28 madtunes sudo[1047]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Mar 05 15:44:28 madtunes sudo[1047]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 05 15:44:28 madtunes systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Mar 05 15:44:28 madtunes sudo[1041]: pam_unix(sudo:session): session closed for user root Mar 05 15:44:28 madtunes systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Mar 05 15:44:28 madtunes systemd[1]: shairport-sync.service: Main process exited, code=killed, status=15/TERM Mar 05 15:44:28 madtunes systemd[1]: shairport-sync.service: Succeeded. Mar 05 15:44:28 madtunes systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Mar 05 15:44:28 madtunes systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Mar 05 15:44:28 madtunes sudo[1043]: pam_unix(sudo:session): session closed for user root Mar 05 15:44:28 madtunes sudo[1047]: pam_unix(sudo:session): session closed for user root Mar 05 15:44:28 madtunes volumio[842]: info: Shairport-Sync Started Mar 05 15:44:28 madtunes volumio[842]: Error adding Membership: Error: addMembership EINVAL Mar 05 15:44:28 madtunes volumio[842]: info: Shairport-Sync Started Mar 05 15:44:28 madtunes volumio[842]: info: Shairport-Sync Started Mar 05 15:44:28 madtunes go-librespot[1007]: time="2025-03-05T15:44:28Z" level=info msg="generated new device id: 64f39122a3d16e694166d1dd5cb9112747028569" Mar 05 15:44:28 madtunes go-librespot[1007]: time="2025-03-05T15:44:28Z" level=debug msg="stored credentials found for 31tblk7drvo3bdqosd6wecaacp6q" Mar 05 15:44:28 madtunes sudo[1054]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Mar 05 15:44:28 madtunes sudo[1054]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 05 15:44:28 madtunes volumio[842]: info: CoreCommandRouter::volumioGetState Mar 05 15:44:28 madtunes volumio[842]: info: CorePlayQueue::getTrack 0 Mar 05 15:44:28 madtunes systemd[1]: Started UPnP Renderer front-end to MPD. Mar 05 15:44:28 madtunes sudo[1054]: pam_unix(sudo:session): session closed for user root Mar 05 15:44:28 madtunes volumio[842]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Mar 05 15:44:28 madtunes volumio[842]: SPOTIFY: BQBGsLko1vdU0Kib6W-Zg9dlt_tzOaXuodQQT6m5-bqsciQRLYcJwBmMi8VZexTHtVU63RgXfYXWxXBVUqaZr7RozFar0x-bflyvUYlTGTPbG3aRJMsA5Znwcr-zbKIP8NG4KlWQE13mYVilTbkN_ApLGrgvDA-O1agYbZLOxYRMXCkjYTK6mXJr7X_7g-MUYp_EHrUnzzOAD6HLDD5zvmjjWDsSln2VW9CzVEYrCWh5RYvu13bhurqPylOuQY0anr4xLzGr3MwQ0dDDgxiad0IAAbiUGLXpkrZC7H-0uKs Mar 05 15:44:28 madtunes volumio[842]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Mar 05 15:44:28 madtunes volumio[842]: info: New Spotify access token = BQBGsLko1vdU0Kib6W-Zg9dlt_tzOaXuodQQT6m5-bqsciQRLYcJwBmMi8VZexTHtVU63RgXfYXWxXBVUqaZr7RozFar0x-bflyvUYlTGTPbG3aRJMsA5Znwcr-zbKIP8NG4KlWQE13mYVilTbkN_ApLGrgvDA-O1agYbZLOxYRMXCkjYTK6mXJr7X_7g-MUYp_EHrUnzzOAD6HLDD5zvmjjWDsSln2VW9CzVEYrCWh5RYvu13bhurqPylOuQY0anr4xLzGr3MwQ0dDDgxiad0IAAbiUGLXpkrZC7H-0uKs Mar 05 15:44:28 madtunes volumio[842]: info: Spotify credentials grant success - running version from March 24, 2019 Mar 05 15:44:28 madtunes volumio[842]: info: Upmpdcli Daemon Started Mar 05 15:44:28 madtunes mpd[991]: Mar 05 15:44 : exception: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Mar 05 15:44:28 madtunes volumio[842]: SPOTIFY: User informations: {"country":"GB","display_name":"Greggygroo","email":"greg.martinpavitt@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/31tblk7drvo3bdqosd6wecaacp6q"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/31tblk7drvo3bdqosd6wecaacp6q","id":"31tblk7drvo3bdqosd6wecaacp6q","images":[],"product":"premium","type":"user","uri":"spotify:user:31tblk7drvo3bdqosd6wecaacp6q"} Mar 05 15:44:28 madtunes volumio[842]: info: Spotify Successfully logged in Mar 05 15:44:28 madtunes volumio[842]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 05 15:44:28 madtunes volumio[842]: info: [1741189468532] CoreMusicLibrary::Adding element Spotify Mar 05 15:44:28 madtunes volumio[842]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 05 15:44:28 madtunes volumio[842]: Cannot find translation for source Spotify Mar 05 15:44:28 madtunes go-librespot[1007]: time="2025-03-05T15:44:28Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Mar 05 15:44:28 madtunes go-librespot[1007]: time="2025-03-05T15:44:28Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Mar 05 15:44:28 madtunes go-librespot[1007]: time="2025-03-05T15:44:28Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Mar 05 15:44:28 madtunes go-librespot[1007]: time="2025-03-05T15:44:28Z" level=debug msg="zeroconf server listening on port 37535" Mar 05 15:44:28 madtunes go-librespot[1007]: time="2025-03-05T15:44:28Z" level=debug msg="obtained new client token: AAApYclTffA+e+jvgNRKbYvUXcze01PLtQlTujcEV/cDTCP+3Mi1wm6cy7qcvsX9QQRLmlWZRQhbiNxs7imQ4S8J2LNzPTQdguHfliDIzeT1ll8i8HhSUO+Jllxzt+6ZtymDkwWpGXRR0WBj5m56kj6h2t/a5FVtb0+vV3NIf4uF3vvb2pXjSv0cVEjXF7sQ9HbIUlf28e+zXdOJs2sq0gMEVkzmhDt6y6pMGhNM3DeA+Q3hiYHX4vN7yEg=" Mar 05 15:44:28 madtunes go-librespot[1007]: time="2025-03-05T15:44:28Z" level=info msg="connected to ap-gew1.spotify.com:4070" Mar 05 15:44:28 madtunes go-librespot[1007]: time="2025-03-05T15:44:28Z" level=debug msg="completed keyexchange" Mar 05 15:44:29 madtunes mpd[991]: Mar 05 15:44 : exception: Input plugin 'tidal' is unavailable: No Tidal application token configured Mar 05 15:44:29 madtunes mpd[991]: Mar 05 15:44 : exception: Input plugin 'qobuz' is unavailable: No Qobuz app_id configured Mar 05 15:44:29 madtunes systemd[1]: Started Music Player Daemon. Mar 05 15:44:29 madtunes sudo[977]: pam_unix(sudo:session): session closed for user root Mar 05 15:44:29 madtunes volumio[842]: info: [yt-cast-receiver] DIAL server listening on port 8098 Mar 05 15:44:29 madtunes volumio[842]: info: Completed starting Core Plugins Mar 05 15:44:29 madtunes volumio[842]: info: ------------------------------------------- Mar 05 15:44:29 madtunes volumio[842]: info: ----- MyVolumio plugins startup ---- Mar 05 15:44:29 madtunes volumio[842]: info: ------------------------------------------- Mar 05 15:44:29 madtunes volumio[842]: info: [MyVolumio PluginManager] Fetching plans data.... Mar 05 15:44:29 madtunes volumio[842]: error: updateQueue error: null Mar 05 15:44:29 madtunes volumio[1056]: Generating RSA private key, 4096 bit long modulus (2 primes) Mar 05 15:44:29 madtunes go-librespot[1007]: time="2025-03-05T15:44:29Z" level=debug msg="completed challenge" Mar 05 15:44:29 madtunes go-librespot[1007]: time="2025-03-05T15:44:29Z" level=debug msg="authenticated as 31tblk7drvo3bdqosd6wecaacp6q" Mar 05 15:44:29 madtunes go-librespot[1007]: time="2025-03-05T15:44:29Z" level=debug msg="authenticated as 31tblk7drvo3bdqosd6wecaacp6q" Mar 05 15:44:29 madtunes go-librespot[1007]: time="2025-03-05T15:44:29Z" level=debug msg="dealer connection opened" Mar 05 15:44:29 madtunes go-librespot[1007]: time="2025-03-05T15:44:29Z" level=debug msg="initializing zeroconf session, username: 31tblk7drvo3bdqosd6wecaacp6q" Mar 05 15:44:29 madtunes go-librespot[1007]: time="2025-03-05T15:44:29Z" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Mar 05 15:44:29 madtunes go-librespot[1007]: time="2025-03-05T15:44:29Z" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Mar 05 15:44:29 madtunes go-librespot[1007]: time="2025-03-05T15:44:29Z" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Mar 05 15:44:29 madtunes go-librespot[1007]: time="2025-03-05T15:44:29Z" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Mar 05 15:44:29 madtunes go-librespot[1007]: time="2025-03-05T15:44:29Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Mar 05 15:44:29 madtunes go-librespot[1007]: time="2025-03-05T15:44:29Z" level=debug msg="autoplay enabled: false" Mar 05 15:44:29 madtunes go-librespot[1007]: time="2025-03-05T15:44:29Z" level=debug msg="received connection id: NWIwN2Q5ZjctYzRiOC00NGYyLTgwNWMtMjYyOTU1M2E3ZGE0K2RlYWxlcit0Y3A6Ly8wYWNhNDIyZC5pcC5nZXcxLnNwb3RpZnkubmV0OjU3MDArODhERkZGNDYwOUI0RUM4OUNFNjI0RUMwRDcwNzZBNzIyOTFFREM2M0NBQUYwNTk4QUMyNjQwQjAxOEY2QUY3Mg==" Mar 05 15:44:29 madtunes go-librespot[1007]: time="2025-03-05T15:44:29Z" level=debug msg="put connect state because NEW_DEVICE" Mar 05 15:44:30 madtunes volumio[842]: info: go-librespot daemon successfully initialized Mar 05 15:44:31 madtunes volumio[842]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Mar 05 15:44:32 madtunes go-librespot[1007]: time="2025-03-05T15:44:32Z" level=debug msg="handling transfer player command from 196adae587ec339c510f89a800ab59c21b4affbe" Mar 05 15:44:32 madtunes go-librespot[1007]: time="2025-03-05T15:44:32Z" level=debug msg="resolved context of track" uri="spotify:album:0fSfkmx0tdPqFYkJuNX74a" Mar 05 15:44:32 madtunes go-librespot[1007]: time="2025-03-05T15:44:32Z" level=trace msg="fetched new page 0 with 30 items (list: 30)" uri="spotify:album:0fSfkmx0tdPqFYkJuNX74a" Mar 05 15:44:32 madtunes go-librespot[1007]: time="2025-03-05T15:44:32Z" level=debug msg="loading track (paused: true, position: 113091ms)" uri="spotify:track:3WRUvGqySBZC6RkB5c2w1S" Mar 05 15:44:32 madtunes go-librespot[1007]: time="2025-03-05T15:44:32Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 05 15:44:32 madtunes go-librespot[1007]: time="2025-03-05T15:44:32Z" level=trace msg="emitting websocket event: will_play" Mar 05 15:44:32 madtunes go-librespot[1007]: time="2025-03-05T15:44:32Z" level=debug msg="selected format OGG_VORBIS_320 (f70dc1996ec89623ec89f58de6d1319ee0373acc)" uri="spotify:track:3WRUvGqySBZC6RkB5c2w1S" Mar 05 15:44:32 madtunes go-librespot[1007]: time="2025-03-05T15:44:32Z" level=debug msg="requested aes key for file f70dc1996ec89623ec89f58de6d1319ee0373acc, gid: 3WRUvGqySBZC6RkB5c2w1S" Mar 05 15:44:32 madtunes go-librespot[1007]: time="2025-03-05T15:44:32Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 345" Mar 05 15:44:32 madtunes go-librespot[1007]: time="2025-03-05T15:44:32Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1377" Mar 05 15:44:32 madtunes go-librespot[1007]: time="2025-03-05T15:44:32Z" level=debug msg="fetched first chunk of 15, total size is 7728638 bytes" uri="spotify:track:3WRUvGqySBZC6RkB5c2w1S" Mar 05 15:44:33 madtunes go-librespot[1007]: time="2025-03-05T15:44:33Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1133" Mar 05 15:44:33 madtunes go-librespot[1007]: time="2025-03-05T15:44:33Z" level=debug msg="fetched chunk 1/14, size: 524288" uri="spotify:track:3WRUvGqySBZC6RkB5c2w1S" Mar 05 15:44:33 madtunes go-librespot[1007]: time="2025-03-05T15:44:33Z" level=debug msg="fetched chunk 2/14, size: 524288" uri="spotify:track:3WRUvGqySBZC6RkB5c2w1S" Mar 05 15:44:33 madtunes go-librespot[1007]: time="2025-03-05T15:44:33Z" level=debug msg="fetched chunk 3/14, size: 524288" uri="spotify:track:3WRUvGqySBZC6RkB5c2w1S" Mar 05 15:44:33 madtunes go-librespot[1007]: time="2025-03-05T15:44:33Z" level=debug msg="fetched chunk 12/14, size: 524288" uri="spotify:track:3WRUvGqySBZC6RkB5c2w1S" Mar 05 15:44:33 madtunes go-librespot[1007]: time="2025-03-05T15:44:33Z" level=debug msg="fetched chunk 13/14, size: 524288" uri="spotify:track:3WRUvGqySBZC6RkB5c2w1S" Mar 05 15:44:33 madtunes go-librespot[1007]: time="2025-03-05T15:44:33Z" level=debug msg="fetched chunk 10/14, size: 524288" uri="spotify:track:3WRUvGqySBZC6RkB5c2w1S" Mar 05 15:44:33 madtunes go-librespot[1007]: time="2025-03-05T15:44:33Z" level=trace msg="seek to 113091ms (diff: 48ms, samples: 4987313, bytes: 5638599)" uri="spotify:track:3WRUvGqySBZC6RkB5c2w1S" Mar 05 15:44:33 madtunes go-librespot[1007]: time="2025-03-05T15:44:33Z" level=debug msg="fetched chunk 11/14, size: 524288" uri="spotify:track:3WRUvGqySBZC6RkB5c2w1S" Mar 05 15:44:33 madtunes kernel: pcm512x 1-004c: No SCLK, using BCLK: -2 Mar 05 15:44:33 madtunes go-librespot[1007]: time="2025-03-05T15:44:33Z" 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" Mar 05 15:44:33 madtunes go-librespot[1007]: time="2025-03-05T15:44:33Z" level=debug msg="created new output device" Mar 05 15:44:33 madtunes go-librespot[1007]: time="2025-03-05T15:44:33Z" level=info msg="loaded track \"MOJO JOJO\" (paused: true, position: 113091ms, duration: 156293ms, prefetched: false)" uri="spotify:track:3WRUvGqySBZC6RkB5c2w1S" Mar 05 15:44:33 madtunes go-librespot[1007]: time="2025-03-05T15:44:33Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 05 15:44:33 madtunes go-librespot[1007]: time="2025-03-05T15:44:33Z" level=trace msg="emitting websocket event: metadata" Mar 05 15:44:33 madtunes go-librespot[1007]: time="2025-03-05T15:44:33Z" level=trace msg="emitting websocket event: active" Mar 05 15:44:33 madtunes go-librespot[1007]: time="2025-03-05T15:44:33Z" level=debug msg="sending successful reply for dealer request" Mar 05 15:44:33 madtunes go-librespot[1007]: time="2025-03-05T15:44:33Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 05 15:44:33 madtunes go-librespot[1007]: time="2025-03-05T15:44:33Z" level=trace msg="emitting websocket event: paused" Mar 05 15:44:33 madtunes go-librespot[1007]: time="2025-03-05T15:44:33Z" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Mar 05 15:44:33 madtunes go-librespot[1007]: time="2025-03-05T15:44:33Z" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Mar 05 15:44:33 madtunes go-librespot[1007]: time="2025-03-05T15:44:33Z" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Mar 05 15:44:34 madtunes volumio[842]: info: Initializing connection to go-librespot Websocket Mar 05 15:44:34 madtunes go-librespot[1007]: time="2025-03-05T15:44:34Z" level=debug msg="new websocket client" Mar 05 15:44:35 madtunes volumio[842]: info: Connection to go-librespot Websocket established Mar 05 15:44:37 madtunes go-librespot[1007]: time="2025-03-05T15:44:37Z" level=debug msg="handling update_context player command from 196adae587ec339c510f89a800ab59c21b4affbe" Mar 05 15:44:37 madtunes go-librespot[1007]: time="2025-03-05T15:44:37Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 05 15:44:37 madtunes go-librespot[1007]: time="2025-03-05T15:44:37Z" level=debug msg="sending successful reply for dealer request" Mar 05 15:44:38 madtunes volumio[842]: Cannot compose Albumart path Mar 05 15:44:38 madtunes go-librespot[1007]: time="2025-03-05T15:44:38Z" level=debug msg="handling play player command from 196adae587ec339c510f89a800ab59c21b4affbe" Mar 05 15:44:38 madtunes go-librespot[1007]: time="2025-03-05T15:44:38Z" level=debug msg="resolved context of track" uri="spotify:album:0fSfkmx0tdPqFYkJuNX74a" Mar 05 15:44:38 madtunes go-librespot[1007]: time="2025-03-05T15:44:38Z" level=trace msg="fetched new page 0 with 30 items (list: 30)" uri="spotify:album:0fSfkmx0tdPqFYkJuNX74a" Mar 05 15:44:38 madtunes go-librespot[1007]: time="2025-03-05T15:44:38Z" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:3j3SfV4hAcR4XjCvW393Gr" Mar 05 15:44:38 madtunes go-librespot[1007]: time="2025-03-05T15:44:38Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 05 15:44:38 madtunes go-librespot[1007]: time="2025-03-05T15:44:38Z" level=trace msg="emitting websocket event: will_play" Mar 05 15:44:38 madtunes go-librespot[1007]: time="2025-03-05T15:44:38Z" level=debug msg="selected format OGG_VORBIS_320 (0bc7dd6eb44bff026d237c747fb8007eff447e3f)" uri="spotify:track:3j3SfV4hAcR4XjCvW393Gr" Mar 05 15:44:38 madtunes go-librespot[1007]: time="2025-03-05T15:44:38Z" level=debug msg="requested aes key for file 0bc7dd6eb44bff026d237c747fb8007eff447e3f, gid: 3j3SfV4hAcR4XjCvW393Gr" Mar 05 15:44:38 madtunes go-librespot[1007]: time="2025-03-05T15:44:38Z" level=debug msg="fetched first chunk of 14, total size is 7056853 bytes" uri="spotify:track:3j3SfV4hAcR4XjCvW393Gr" Mar 05 15:44:38 madtunes go-librespot[1007]: time="2025-03-05T15:44:38Z" level=trace msg="seek to 0ms (diff: 0ms, samples: 0, bytes: 0)" uri="spotify:track:3j3SfV4hAcR4XjCvW393Gr" Mar 05 15:44:38 madtunes kernel: pcm512x 1-004c: No SCLK, using BCLK: -2 Mar 05 15:44:38 madtunes go-librespot[1007]: time="2025-03-05T15:44:38Z" 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" Mar 05 15:44:38 madtunes go-librespot[1007]: time="2025-03-05T15:44:38Z" level=info msg="loaded track \"POP OUT\" (paused: false, position: 0ms, duration: 161738ms, prefetched: false)" uri="spotify:track:3j3SfV4hAcR4XjCvW393Gr" Mar 05 15:44:38 madtunes go-librespot[1007]: time="2025-03-05T15:44:38Z" level=debug msg="fetched chunk 1/13, size: 524288" uri="spotify:track:3j3SfV4hAcR4XjCvW393Gr" Mar 05 15:44:39 madtunes go-librespot[1007]: time="2025-03-05T15:44:39Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 05 15:44:39 madtunes go-librespot[1007]: time="2025-03-05T15:44:39Z" level=trace msg="scheduling prefetch in 132s" Mar 05 15:44:39 madtunes go-librespot[1007]: time="2025-03-05T15:44:39Z" level=trace msg="emitting websocket event: metadata" Mar 05 15:44:39 madtunes go-librespot[1007]: time="2025-03-05T15:44:39Z" level=debug msg="sending successful reply for dealer request" Mar 05 15:44:39 madtunes go-librespot[1007]: time="2025-03-05T15:44:39Z" level=debug msg="fetched chunk 3/13, size: 524288" uri="spotify:track:3j3SfV4hAcR4XjCvW393Gr" Mar 05 15:44:39 madtunes go-librespot[1007]: time="2025-03-05T15:44:39Z" level=debug msg="fetched chunk 2/13, size: 524288" uri="spotify:track:3j3SfV4hAcR4XjCvW393Gr" Mar 05 15:44:39 madtunes go-librespot[1007]: time="2025-03-05T15:44:39Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 05 15:44:39 madtunes go-librespot[1007]: time="2025-03-05T15:44:39Z" level=trace msg="emitting websocket event: playing" Mar 05 15:44:39 madtunes volumio[842]: info: Getting Spotify volume Mar 05 15:44:39 madtunes volumio[842]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:3j3SfV4hAcR4XjCvW393Gr","play_origin":"playlist"}} Mar 05 15:44:39 madtunes volumio[842]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:3j3SfV4hAcR4XjCvW393Gr","name":"POP OUT","artist_names":["Playboi Carti"],"album_name":"MUSIC","album_cover_url":"https://i.scdn.co/image/ab67616d00001e024738d40fd634c7d08419b1e4","position":0,"duration":161738,"release_date":"year:2025 month:3 day:14","track_number":1,"disc_number":1}} Mar 05 15:44:39 madtunes volumio[842]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:3j3SfV4hAcR4XjCvW393Gr","play_origin":"playlist"}} Mar 05 15:44:39 madtunes volumio[842]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 05 15:44:39 madtunes volumio[842]: TypeError: Cannot read property 'service' of undefined Mar 05 15:44:39 madtunes volumio[842]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:337:50) Mar 05 15:44:39 madtunes volumio[842]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:263:18) Mar 05 15:44:39 madtunes volumio[842]: at WebSocket.message (/data/plugins/music_service/spop/index.js:190:14) Mar 05 15:44:39 madtunes volumio[842]: at WebSocket.emit (events.js:315:20) Mar 05 15:44:39 madtunes volumio[842]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20) Mar 05 15:44:39 madtunes volumio[842]: at Receiver.emit (events.js:315:20) Mar 05 15:44:39 madtunes volumio[842]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) Mar 05 15:44:39 madtunes volumio[842]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) Mar 05 15:44:39 madtunes volumio[842]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) Mar 05 15:44:39 madtunes volumio[842]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) Mar 05 15:44:39 madtunes volumio[842]: at writeOrBuffer (internal/streams/writable.js:358:12) Mar 05 15:44:39 madtunes volumio[842]: at Receiver.Writable.write (internal/streams/writable.js:303:10) Mar 05 15:44:39 madtunes volumio[842]: at Socket.socketOnData (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1355:35) Mar 05 15:44:39 madtunes volumio[842]: at Socket.emit (events.js:315:20) Mar 05 15:44:39 madtunes volumio[842]: at addChunk (internal/streams/readable.js:309:12) Mar 05 15:44:39 madtunes volumio[842]: at readableAddChunk (internal/streams/readable.js:284:9) Mar 05 15:44:39 madtunes volumio[842]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 05 15:44:39 madtunes sudo[1087]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-03-05 15:43 Mar 05 15:44:39 madtunes sudo[1087]: 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="b1c3cf61c2a0027c66bab1eb0a3795f80c1f2e95" VOLUMIO_FE_VERSION="614d7b13ffdcb0cc5a6072e7d06f59d52e323e71" VOLUMIO_FE3_VERSION="570aaed971c1346d45d1172dc445b086b258c6d1" VOLUMIO_BE_VERSION="e3eb3ee5b16063502f3a1735e11a28cfe54a0f46" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Sun 25 Jun 2023 07:20:58 PM CEST" VOLUMIO_VERSION="3.512" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="946a42b62509f37b5e7e2d86a2932a62"