-- Logs begin at Thu 2019-02-14 21:11:58 AEDT, end at Wed 2025-07-09 12:53:37 AEST. -- Jul 09 12:52:00 volumio systemd[1]: Starting dhcpcd on all interfaces... Jul 09 12:52:00 volumio systemd[1]: Starting Avahi mDNS/DNS-SD Stack... Jul 09 12:52:00 volumio mpd_monitor.sh[596]: MPD Monitor Service: Starting MPD Monitor Service Jul 09 12:52:00 volumio systemd[1]: Starting Login Service... Jul 09 12:52:00 volumio systemd[1]: Condition check resulted in getty on tty2-tty6 if dbus and logind are not available being skipped. Jul 09 12:52:00 volumio systemd[1]: Started D-Bus System Message Bus. Jul 09 12:52:00 volumio systemd[1]: Condition check resulted in Volumio SSH enabler being skipped. Jul 09 12:52:00 volumio systemd[1]: Starting triggerhappy global hotkey daemon... Jul 09 12:52:00 volumio systemd[1]: Starting Volumio Time Update Utility... Jul 09 12:52:00 volumio dhcpcd[609]: Not running dhcpcd because /etc/network/interfaces Jul 09 12:52:00 volumio dhcpcd[609]: defines some interfaces that will use a Jul 09 12:52:00 volumio dhcpcd[609]: DHCP client or static address Jul 09 12:52:00 volumio systemd[1]: Started Volumio Iptables Module. Jul 09 12:52:00 volumio systemd[1]: Started Volumio Log Rotation Service. Jul 09 12:52:00 volumio systemd[1]: Starting Wireless Services... Jul 09 12:52:00 volumio systemd[1]: Starting WPA supplicant... Jul 09 12:52:00 volumio systemd[1]: Starting Save/Restore Sound Card State... Jul 09 12:52:00 volumio systemd[1]: Started RPC bind portmap service. Jul 09 12:52:00 volumio systemd[1]: hciuart.service: Succeeded. Jul 09 12:52:00 volumio systemd[1]: Started Configure Bluetooth Modems connected by UART. Jul 09 12:52:00 volumio systemd[1]: dhcpcd.service: Control process exited, code=exited, status=6/NOTCONFIGURED Jul 09 12:52:00 volumio systemd[1]: dhcpcd.service: Failed with result 'exit-code'. Jul 09 12:52:00 volumio systemd[1]: Failed to start dhcpcd on all interfaces. Jul 09 12:52:00 volumio systemd[1]: Starting Raspberry Pi bluetooth helper... Jul 09 12:52:00 volumio systemd[1]: Reached target Remote File Systems (Pre). Jul 09 12:52:00 volumio systemd[1]: Reached target Remote File Systems. Jul 09 12:52:00 volumio systemd[1]: Starting LSB: Load kernel modules needed to enable cpufreq scaling... Jul 09 12:52:00 volumio systemd[1]: Reached target RPC Port Mapper. Jul 09 12:52:00 volumio volumio-time-update[623]: volumio-time-update-util: Fetching time from Volumio... Jul 09 12:52:00 volumio kernel: Bluetooth: hci0: BCM: features 0x2f Jul 09 12:52:00 volumio kernel: Bluetooth: hci0: BCM43455 37.4MHz Raspberry Pi 3+ Jul 09 12:52:00 volumio kernel: Bluetooth: hci0: BCM4345C0 (003.001.025) build 0342 Jul 09 12:52:00 volumio thd[622]: Unable to parse trigger line: Jul 09 12:52:00 volumio thd[622]: Unable to parse trigger line: KEY_MIN_INTERESTING 1 /usr/local/bin/volumio volume toggle Jul 09 12:52:00 volumio thd[622]: Unable to parse trigger line: Jul 09 12:52:00 volumio thd[622]: Found socket passed from systemd Jul 09 12:52:00 volumio sh[517]: wlan0=wlan0 Jul 09 12:52:00 volumio systemd-logind[614]: New seat seat0. Jul 09 12:52:00 volumio bthelper[631]: Raspberry Pi BDADDR already set Jul 09 12:52:00 volumio avahi-daemon[613]: Found user 'avahi' (UID 110) and group 'avahi' (GID 113). Jul 09 12:52:00 volumio avahi-daemon[613]: Successfully dropped root privileges. Jul 09 12:52:00 volumio avahi-daemon[613]: avahi-daemon 0.7 starting up. Jul 09 12:52:00 volumio mpd_monitor.sh[596]: MPD error: Cannot assign requested address Jul 09 12:52:00 volumio mpd_monitor.sh[596]: MPD Monitor Service: MPD Appears to be inactive, restarting Jul 09 12:52:00 volumio mpd_monitor.sh[596]: mpd: no process found Jul 09 12:52:00 volumio sh[512]: eth0: waiting for carrier Jul 09 12:52:00 volumio dhcpcd[564]: eth0: waiting for carrier Jul 09 12:52:00 volumio kernel: bcmgenet fd580000.ethernet: configuring instance for external RGMII (RX delay) Jul 09 12:52:00 volumio kernel: bcmgenet fd580000.ethernet eth0: Link is Down Jul 09 12:52:00 volumio systemd[1]: Started triggerhappy global hotkey daemon. Jul 09 12:52:00 volumio wpa_supplicant[628]: Successfully initialized wpa_supplicant Jul 09 12:52:00 volumio systemd[1]: Started Save/Restore Sound Card State. Jul 09 12:52:00 volumio avahi-daemon[613]: Successfully called chroot(). Jul 09 12:52:00 volumio avahi-daemon[613]: Successfully dropped remaining capabilities. Jul 09 12:52:00 volumio systemd[1]: Started Raspberry Pi bluetooth helper. Jul 09 12:52:00 volumio avahi-daemon[613]: No service file found in /etc/avahi/services. Jul 09 12:52:00 volumio avahi-daemon[613]: Network interface enumeration completed. Jul 09 12:52:00 volumio avahi-daemon[613]: Server startup complete. Host name is volumio.local. Local service cookie is 3971938603. Jul 09 12:52:00 volumio systemd[1]: Started Login Service. Jul 09 12:52:00 volumio systemd[1]: Started WPA supplicant. Jul 09 12:52:00 volumio systemd[1]: Started Avahi mDNS/DNS-SD Stack. Jul 09 12:52:00 volumio systemd[1]: Started Raise network interfaces. Jul 09 12:52:00 volumio systemd[1]: Reached target Network. Jul 09 12:52:00 volumio systemd[1]: Reached target Network is Online. Jul 09 12:52:00 volumio systemd[1]: Starting LSB: Brings up/down network automatically... Jul 09 12:52:00 volumio systemd[1]: Starting Samba NMB Daemon... Jul 09 12:52:00 volumio systemd[1]: Starting /etc/rc.local Compatibility... Jul 09 12:52:00 volumio systemd[1]: Condition check resulted in fast remote file copy program daemon being skipped. Jul 09 12:52:00 volumio systemd[1]: Starting Network Time Service... Jul 09 12:52:00 volumio systemd[1]: Starting Permit User Sessions... Jul 09 12:52:00 volumio volumio-remote-updater[592]: Error: No active session Jul 09 12:52:00 volumio systemd[1]: Listening on mpd.socket. Jul 09 12:52:00 volumio systemd[1]: Starting Bluetooth service... Jul 09 12:52:00 volumio systemd[1]: Reached target Sound Card. Jul 09 12:52:00 volumio volumio-remote-updater[592]: [2025-07-09 12:52:00] [info] asio async_connect error: system:111 (Connection refused) Jul 09 12:52:00 volumio volumio-remote-updater[592]: [2025-07-09 12:52:00] [info] Error getting remote endpoint: system:107 (Transport endpoint is not connected) Jul 09 12:52:00 volumio volumio-remote-updater[592]: [2025-07-09 12:52:00] [error] handle_connect error: Underlying Transport Error Jul 09 12:52:00 volumio systemd[1]: Starting Music Player Daemon... Jul 09 12:52:00 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Jul 09 12:52:00 volumio systemd[1]: Started /etc/rc.local Compatibility. Jul 09 12:52:00 volumio systemd[1]: Started Permit User Sessions. Jul 09 12:52:00 volumio systemd[1]: Starting Terminate Plymouth Boot Screen... Jul 09 12:52:00 volumio systemd[1]: Starting Hold until boot process finishes up... Jul 09 12:52:00 volumio systemd[1]: Received SIGRTMIN+21 from PID 196 (plymouthd). Jul 09 12:52:01 volumio volumio[601]: Could not open config: /tmp/upmpdcli.conf Jul 09 12:52:01 volumio loadcpufreq[632]: Loading cpufreq kernel modules...done (none). Jul 09 12:52:01 volumio systemd[1]: Started LSB: Load kernel modules needed to enable cpufreq scaling. Jul 09 12:52:01 volumio volumio-time-update[623]: volumio-time-update-util: Date not found in response Jul 09 12:52:01 volumio volumio-time-update[623]: volumio-time-update-util: Retrying in 5 seconds... Jul 09 12:52:01 volumio ifplugd(eth0)[769]: ifplugd 0.28 initializing. Jul 09 12:52:01 volumio ifplugd(eth0)[769]: Using interface eth0/E4:5F:01:E6:08:7F with driver (version: 6.6.62-v7l+) Jul 09 12:52:01 volumio ifplugd(eth0)[769]: Using detection mode: SIOCETHTOOL Jul 09 12:52:01 volumio ifplugd(eth0)[769]: Initialization complete, link beat not detected. Jul 09 12:52:01 volumio systemd[1]: Starting LSB: set CPUFreq kernel parameters... Jul 09 12:52:01 volumio systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Jul 09 12:52:01 volumio systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Jul 09 12:52:01 volumio systemd[1]: plymouth-quit.service: Succeeded. Jul 09 12:52:01 volumio systemd[1]: Started Terminate Plymouth Boot Screen. Jul 09 12:52:01 volumio systemd[1]: plymouth-quit-wait.service: Succeeded. Jul 09 12:52:01 volumio systemd[1]: Started Hold until boot process finishes up. Jul 09 12:52:01 volumio systemd[1]: Received SIGRTMIN+21 from PID 196 (n/a). Jul 09 12:52:01 volumio systemd[1]: Started Getty on tty1. Jul 09 12:52:01 volumio systemd[1]: Reached target Login Prompts. Jul 09 12:52:01 volumio systemd[1]: iptables.service: Succeeded. Jul 09 12:52:01 volumio ifplugd[708]: Network Interface Plugging Daemon...start eth0...done. Jul 09 12:52:01 volumio systemd[1]: Started LSB: Brings up/down network automatically. Jul 09 12:52:01 volumio ntpd[720]: ntpd 4.2.8p12@1.3728-o (1): Starting Jul 09 12:52:01 volumio ntpd[720]: Command line: /usr/sbin/ntpd -p /var/run/ntpd.pid -g -u 103:103 Jul 09 12:52:01 volumio systemd[1]: Started Network Time Service. Jul 09 12:52:01 volumio ntpd[781]: proto: precision = 0.815 usec (-20) Jul 09 12:52:01 volumio cpufrequtils[759]: CPUFreq Utilities: Setting ondemand CPUFreq governor...CPU0...CPU1...CPU2...CPU3...done. Jul 09 12:52:01 volumio systemd[1]: Started LSB: set CPUFreq kernel parameters. Jul 09 12:52:01 volumio ntpd[781]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): good hash signature Jul 09 12:52:01 volumio ntpd[781]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): loaded, expire=2024-12-28T00:00:00Z last=2017-01-01T00:00:00Z ofs=37 Jul 09 12:52:01 volumio ntpd[781]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): expired less than 194 days ago Jul 09 12:52:01 volumio ntpd[781]: Listen and drop on 0 v6wildcard [::]:123 Jul 09 12:52:01 volumio ntpd[781]: Listen and drop on 1 v4wildcard 0.0.0.0:123 Jul 09 12:52:01 volumio ntpd[781]: Listen normally on 2 lo 127.0.0.1:123 Jul 09 12:52:01 volumio ntpd[781]: Listening on routing socket on fd #19 for interface updates Jul 09 12:52:01 volumio ntpd[781]: kernel reports TIME_ERROR: 0x41: Clock Unsynchronized Jul 09 12:52:01 volumio ntpd[781]: kernel reports TIME_ERROR: 0x41: Clock Unsynchronized Jul 09 12:52:01 volumio bluetoothd[730]: Bluetooth daemon 5.50 Jul 09 12:52:01 volumio bluetoothd[730]: Unknown key AutoConnectTimeout for group General in /etc/bluetooth/main.conf Jul 09 12:52:01 volumio systemd[1]: Started Bluetooth service. Jul 09 12:52:01 volumio systemd[1]: Reached target Bluetooth. Jul 09 12:52:01 volumio bluetoothd[730]: Starting SDP server Jul 09 12:52:01 volumio bluetoothd[730]: Excluding (cli) sap Jul 09 12:52:01 volumio haveged[566]: haveged: ver: 1.9.1; arch: generic; vend: ; build: (gcc 8.2.0 CTV); collect: 128K Jul 09 12:52:01 volumio haveged[566]: haveged: cpu: (VC); data: 16K (D); inst: 16K (D); idx: 11/40; sz: 14768/63488 Jul 09 12:52:01 volumio haveged[566]: haveged: tot tests(BA8): A:1/1 B:1/1 continuous tests(B): last entropy estimate 8.00151 Jul 09 12:52:01 volumio haveged[566]: haveged: fills: 0, generated: 0 Jul 09 12:52:01 volumio kernel: Bluetooth: BNEP (Ethernet Emulation) ver 1.3 Jul 09 12:52:01 volumio kernel: Bluetooth: BNEP filters: protocol multicast Jul 09 12:52:01 volumio kernel: Bluetooth: BNEP socket layer initialized Jul 09 12:52:01 volumio dbus-daemon[616]: [system] Activating via systemd: service name='org.freedesktop.hostname1' unit='dbus-org.freedesktop.hostname1.service' requested by ':1.5' (uid=0 pid=730 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap ") Jul 09 12:52:01 volumio bluetoothd[730]: Bluetooth management interface 1.22 initialized Jul 09 12:52:01 volumio kernel: Bluetooth: MGMT ver 1.22 Jul 09 12:52:01 volumio sudo[731]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jul 09 12:52:01 volumio sudo[731]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 09 12:52:01 volumio sudo[731]: /bin/chown: cannot access '/var/log/mpd.log': No such file or directory Jul 09 12:52:01 volumio sudo[731]: pam_unix(sudo:session): session closed for user root Jul 09 12:52:01 volumio bluetoothd[730]: Failed to set privacy: Rejected (0x0b) Jul 09 12:52:01 volumio systemd[1]: Starting Hostname Service... Jul 09 12:52:01 volumio dbus-daemon[616]: [system] Successfully activated service 'org.freedesktop.hostname1' Jul 09 12:52:01 volumio systemd[1]: Started Hostname Service. Jul 09 12:52:02 volumio nmbd[736]: [2025/07/09 12:52:02.191082, 0] ../source3/nmbd/asyncdns.c:158(start_async_dns) Jul 09 12:52:02 volumio nmbd[736]: started asyncdns process 799 Jul 09 12:52:02 volumio nmbd[736]: [2025/07/09 12:52:02.192763, 0] ../lib/util/become_daemon.c:149(daemon_status) Jul 09 12:52:02 volumio nmbd[736]: daemon_status: STATUS=daemon 'nmbd' : No local IPv4 non-loopback interfaces available, waiting for interface ... Jul 09 12:52:02 volumio nmbd[736]: [2025/07/09 12:52:02.192913, 0] ../source3/nmbd/nmbd_subnetdb.c:254(create_subnets) Jul 09 12:52:02 volumio nmbd[736]: NOTE: NetBIOS name resolution is not supported for Internet Protocol Version 6 (IPv6). Jul 09 12:52:02 volumio ntpd[781]: error resolving pool 0.debian.pool.ntp.org: System error (-11) Jul 09 12:52:02 volumio wireless.js[627]: Cleaning previous... Jul 09 12:52:02 volumio sudo[807]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ip addr flush dev wlan0 Jul 09 12:52:02 volumio sudo[807]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 09 12:52:02 volumio sudo[807]: pam_unix(sudo:session): session closed for user root Jul 09 12:52:02 volumio sudo[809]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 down Jul 09 12:52:02 volumio sudo[809]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 09 12:52:03 volumio sudo[809]: pam_unix(sudo:session): session closed for user root Jul 09 12:52:03 volumio ntpd[781]: error resolving pool 1.debian.pool.ntp.org: System error (-11) Jul 09 12:52:03 volumio wireless.js[627]: Stopped aP Jul 09 12:52:03 volumio sudo[816]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 up Jul 09 12:52:03 volumio sudo[816]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 09 12:52:03 volumio sudo[816]: pam_unix(sudo:session): session closed for user root Jul 09 12:52:03 volumio kernel: brcmfmac: brcmf_cfg80211_set_power_mgmt: power save disabled Jul 09 12:52:03 volumio sudo[818]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iw reg get Jul 09 12:52:03 volumio sudo[818]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 09 12:52:03 volumio sudo[818]: pam_unix(sudo:session): session closed for user root Jul 09 12:52:03 volumio sudo[825]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 up Jul 09 12:52:03 volumio sudo[825]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 09 12:52:03 volumio sudo[825]: pam_unix(sudo:session): session closed for user root Jul 09 12:52:03 volumio sudo[827]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iw wlan0 scan Jul 09 12:52:03 volumio sudo[827]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 09 12:52:03 volumio mpd[795]: Jul 09 12:52 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jul 09 12:52:03 volumio systemd[1]: Started Music Player Daemon. Jul 09 12:52:03 volumio mpd_monitor.sh[596]: MPD Monitor Service: MPD restarted due to no mpc output. Jul 09 12:52:04 volumio ntpd[781]: error resolving pool 2.debian.pool.ntp.org: System error (-11) Jul 09 12:52:04 volumio sh[512]: eth0: carrier acquired Jul 09 12:52:04 volumio dhcpcd[564]: eth0: carrier acquired Jul 09 12:52:04 volumio sh[512]: DUID 00:01:00:01:2b:75:13:3f:e4:5f:01:e6:08:7f Jul 09 12:52:04 volumio sh[512]: eth0: IAID 01:e6:08:7f Jul 09 12:52:04 volumio dhcpcd[564]: DUID 00:01:00:01:2b:75:13:3f:e4:5f:01:e6:08:7f Jul 09 12:52:04 volumio dhcpcd[564]: eth0: IAID 01:e6:08:7f Jul 09 12:52:04 volumio sh[512]: eth0: adding address fe80::ae76:fb27:4e96:c859 Jul 09 12:52:04 volumio sh[512]: ipv6_addaddr1: Permission denied Jul 09 12:52:04 volumio dhcpcd[564]: eth0: adding address fe80::ae76:fb27:4e96:c859 Jul 09 12:52:04 volumio dhcpcd[564]: ipv6_addaddr1: Permission denied Jul 09 12:52:04 volumio kernel: bcmgenet fd580000.ethernet eth0: Link is Up - 1Gbps/Full - flow control rx/tx Jul 09 12:52:04 volumio sh[512]: eth0: soliciting a DHCP lease Jul 09 12:52:04 volumio dhcpcd[564]: eth0: soliciting a DHCP lease Jul 09 12:52:04 volumio systemd[1]: systemd-rfkill.service: Succeeded. Jul 09 12:52:04 volumio sh[512]: eth0: soliciting an IPv6 router Jul 09 12:52:04 volumio dhcpcd[564]: eth0: soliciting an IPv6 router Jul 09 12:52:05 volumio ifplugd(eth0)[769]: Link beat detected. Jul 09 12:52:05 volumio ntpd[781]: error resolving pool 3.debian.pool.ntp.org: System error (-11) Jul 09 12:52:05 volumio ifplugd(eth0)[769]: Executing '/etc/ifplugd/ifplugd.action eth0 up'. Jul 09 12:52:05 volumio ifplugd(eth0)[769]: client: ifup: waiting for lock on /run/network/ifstate.eth0 Jul 09 12:52:05 volumio bthelper[631]: Changing power off succeeded Jul 09 12:52:05 volumio bthelper[631]: [CHG] Controller E4:5F:01:E6:08:82 Powered: no Jul 09 12:52:05 volumio bthelper[631]: [CHG] Controller E4:5F:01:E6:08:82 Discovering: no Jul 09 12:52:05 volumio bthelper[631]: [CHG] Controller E4:5F:01:E6:08:82 Class: 0x00000000 Jul 09 12:52:05 volumio bthelper[631]: [CHG] Controller E4:5F:01:E6:08:82 Class: 0x0000041c Jul 09 12:52:05 volumio bthelper[631]: Changing power on succeeded Jul 09 12:52:05 volumio sudo[827]: pam_unix(sudo:session): session closed for user root Jul 09 12:52:05 volumio wireless.js[627]: SETTING APPROPRIATE REG DOMAIN: AU Jul 09 12:52:05 volumio sudo[849]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 up Jul 09 12:52:05 volumio sudo[849]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 09 12:52:05 volumio sudo[849]: pam_unix(sudo:session): session closed for user root Jul 09 12:52:05 volumio sudo[851]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iw reg set AU Jul 09 12:52:05 volumio sudo[851]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 09 12:52:05 volumio sudo[851]: pam_unix(sudo:session): session closed for user root Jul 09 12:52:05 volumio wireless.js[627]: SUCCESSFULLY SET NEW REGDOMAIN: AU Jul 09 12:52:05 volumio wireless.js[627]: Start wireless flow Jul 09 12:52:05 volumio wireless.js[627]: Stopped hotspot (if there).. Jul 09 12:52:05 volumio sudo[856]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ip addr flush dev wlan0 Jul 09 12:52:05 volumio sudo[856]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 09 12:52:05 volumio sudo[856]: pam_unix(sudo:session): session closed for user root Jul 09 12:52:05 volumio sudo[858]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 down Jul 09 12:52:05 volumio sudo[858]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 09 12:52:06 volumio volumio-time-update[623]: volumio-time-update-util: Fetching time from Volumio... Jul 09 12:52:06 volumio volumio-time-update[623]: volumio-time-update-util: Date not found in response Jul 09 12:52:06 volumio volumio-time-update[623]: volumio-time-update-util: Retrying in 5 seconds... Jul 09 12:52:06 volumio volumio-remote-updater[592]: [2025-07-09 12:52:06] [info] asio async_connect error: system:111 (Connection refused) Jul 09 12:52:06 volumio volumio-remote-updater[592]: [2025-07-09 12:52:06] [info] Error getting remote endpoint: system:107 (Transport endpoint is not connected) Jul 09 12:52:06 volumio volumio-remote-updater[592]: [2025-07-09 12:52:06] [error] handle_connect error: Underlying Transport Error Jul 09 12:52:06 volumio sudo[858]: pam_unix(sudo:session): session closed for user root Jul 09 12:52:06 volumio wireless.js[627]: DHCP IP Jul 09 12:52:06 volumio wireless.js[627]: Start ap Jul 09 12:52:06 volumio wpa_supplicant[865]: Successfully initialized wpa_supplicant Jul 09 12:52:06 volumio sudo[866]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/dhcpcd Jul 09 12:52:06 volumio sudo[866]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 09 12:52:06 volumio dhcpcd[867]: dev: loaded udev Jul 09 12:52:06 volumio kernel: brcmfmac: brcmf_cfg80211_set_power_mgmt: power save disabled Jul 09 12:52:06 volumio dhcpcd-run-hooks[876]: wlan0: starting wpa_supplicant Jul 09 12:52:06 volumio dhcpcd-run-hooks[881]: wlan0: failed to start wpa_supplicant Jul 09 12:52:06 volumio dhcpcd-run-hooks[882]: 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 Jul 09 12:52:06 volumio dhcpcd[867]: wlan0: connected to Access Point `' Jul 09 12:52:06 volumio dhcpcd[867]: DUID 00:01:00:01:2b:75:13:3f:e4:5f:01:e6:08:7f Jul 09 12:52:06 volumio dhcpcd[867]: eth0: IAID 01:e6:08:7f Jul 09 12:52:06 volumio dhcpcd[867]: eth0: adding address fe80::ae76:fb27:4e96:c859 Jul 09 12:52:06 volumio dhcpcd[867]: ipv6_addaddr1: Permission denied Jul 09 12:52:06 volumio dhcpcd[867]: wlan0: waiting for carrier Jul 09 12:52:07 volumio wireless.js[627]: trying... Jul 09 12:52:07 volumio sudo[893]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Jul 09 12:52:07 volumio sudo[893]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 09 12:52:07 volumio sudo[893]: pam_unix(sudo:session): session closed for user root Jul 09 12:52:07 volumio dhcpcd[867]: eth0: soliciting an IPv6 router Jul 09 12:52:07 volumio dhcpcd[867]: eth0: soliciting a DHCP lease Jul 09 12:52:07 volumio dhcpcd[867]: eth0: offered 192.168.1.100 from 192.168.1.1 Jul 09 12:52:08 volumio dhcpcd[867]: eth0: probing address 192.168.1.100/24 Jul 09 12:52:08 volumio wireless.js[627]: trying... Jul 09 12:52:08 volumio sudo[896]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Jul 09 12:52:08 volumio sudo[896]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 09 12:52:08 volumio sudo[896]: pam_unix(sudo:session): session closed for user root Jul 09 12:52:08 volumio sh[512]: eth0: offered 192.168.1.100 from 192.168.1.1 Jul 09 12:52:08 volumio dhcpcd[564]: eth0: offered 192.168.1.100 from 192.168.1.1 Jul 09 12:52:09 volumio sh[512]: eth0: probing address 192.168.1.100/24 Jul 09 12:52:09 volumio dhcpcd[564]: eth0: probing address 192.168.1.100/24 Jul 09 12:52:09 volumio wireless.js[627]: trying... Jul 09 12:52:09 volumio sudo[899]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Jul 09 12:52:09 volumio sudo[899]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 09 12:52:09 volumio sudo[899]: pam_unix(sudo:session): session closed for user root Jul 09 12:52:10 volumio wireless.js[627]: trying... Jul 09 12:52:10 volumio sudo[902]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Jul 09 12:52:10 volumio sudo[902]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 09 12:52:10 volumio sudo[902]: pam_unix(sudo:session): session closed for user root Jul 09 12:52:11 volumio volumio-time-update[623]: volumio-time-update-util: Fetching time from Volumio... Jul 09 12:52:11 volumio volumio-time-update[623]: volumio-time-update-util: Date not found in response Jul 09 12:52:11 volumio volumio-time-update[623]: volumio-time-update-util: Retrying in 5 seconds... Jul 09 12:52:11 volumio wireless.js[627]: trying... Jul 09 12:52:11 volumio sudo[910]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Jul 09 12:52:11 volumio sudo[910]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 09 12:52:11 volumio sudo[910]: pam_unix(sudo:session): session closed for user root Jul 09 12:52:12 volumio wireless.js[627]: trying... Jul 09 12:52:12 volumio sudo[913]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Jul 09 12:52:12 volumio sudo[913]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 09 12:52:12 volumio sudo[913]: pam_unix(sudo:session): session closed for user root Jul 09 12:52:12 volumio wpa_supplicant[880]: wlan0: Trying to associate with SSID 'WiFi-273C' Jul 09 12:52:12 volumio dhcpcd[867]: wlan0: carrier acquired Jul 09 12:52:12 volumio wpa_supplicant[880]: wlan0: Associated with 10:27:f5:ca:27:3c Jul 09 12:52:12 volumio dhcpcd[867]: wlan0: connected to Access Point `WiFi-273C' Jul 09 12:52:12 volumio wpa_supplicant[880]: wlan0: CTRL-EVENT-CONNECTED - Connection to 10:27:f5:ca:27:3c completed [id=0 id_str=] Jul 09 12:52:12 volumio wpa_supplicant[880]: wlan0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0 Jul 09 12:52:12 volumio dhcpcd[867]: wlan0: IAID 01:e6:08:80 Jul 09 12:52:12 volumio dhcpcd[867]: wlan0: adding address fe80::708f:3d34:e774:e14e Jul 09 12:52:12 volumio dhcpcd[867]: ipv6_addaddr1: Permission denied Jul 09 12:52:12 volumio dhcpcd[867]: wlan0: carrier lost Jul 09 12:52:12 volumio dhcpcd[867]: wlan0: carrier acquired Jul 09 12:52:12 volumio dhcpcd[867]: wlan0: IAID 01:e6:08:80 Jul 09 12:52:12 volumio dhcpcd[867]: wlan0: rebinding lease of 192.168.1.101 Jul 09 12:52:13 volumio dhcpcd[867]: wlan0: probing address 192.168.1.101/24 Jul 09 12:52:13 volumio wireless.js[627]: trying... Jul 09 12:52:13 volumio sudo[928]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Jul 09 12:52:13 volumio sudo[928]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 09 12:52:13 volumio sudo[928]: pam_unix(sudo:session): session closed for user root Jul 09 12:52:13 volumio dhcpcd[867]: eth0: leased 192.168.1.100 for 86400 seconds Jul 09 12:52:13 volumio dhcpcd[867]: eth0: adding route to 192.168.1.0/24 Jul 09 12:52:13 volumio dhcpcd[867]: eth0: adding default route via 192.168.1.1 Jul 09 12:52:13 volumio avahi-daemon[613]: Joining mDNS multicast group on interface eth0.IPv4 with address 192.168.1.100. Jul 09 12:52:13 volumio avahi-daemon[613]: New relevant interface eth0.IPv4 for mDNS. Jul 09 12:52:13 volumio avahi-daemon[613]: Registering new address record for 192.168.1.100 on eth0.IPv4. Jul 09 12:52:13 volumio dhcpcd[867]: forked to background, child pid 950 Jul 09 12:52:13 volumio sudo[866]: pam_unix(sudo:session): session closed for user root Jul 09 12:52:13 volumio dhcpcd[950]: wlan0: soliciting an IPv6 router Jul 09 12:52:13 volumio volumio-remote-updater[592]: [2025-07-09 12:52:13] [info] asio async_connect error: system:111 (Connection refused) Jul 09 12:52:13 volumio volumio-remote-updater[592]: [2025-07-09 12:52:13] [info] Error getting remote endpoint: system:107 (Transport endpoint is not connected) Jul 09 12:52:13 volumio volumio-remote-updater[592]: [2025-07-09 12:52:13] [error] handle_connect error: Underlying Transport Error Jul 09 12:52:14 volumio sh[512]: eth0: leased 192.168.1.100 for 86400 seconds Jul 09 12:52:14 volumio sh[512]: eth0: adding route to 192.168.1.0/24 Jul 09 12:52:14 volumio sh[512]: eth0: adding default route via 192.168.1.1 Jul 09 12:52:14 volumio dhcpcd[564]: eth0: leased 192.168.1.100 for 86400 seconds Jul 09 12:52:14 volumio dhcpcd[564]: eth0: adding route to 192.168.1.0/24 Jul 09 12:52:14 volumio dhcpcd[564]: eth0: adding default route via 192.168.1.1 Jul 09 12:52:14 volumio sh[512]: forked to background, child pid 971 Jul 09 12:52:14 volumio dhcpcd[564]: forked to background, child pid 971 Jul 09 12:52:14 volumio ifplugd(eth0)[769]: client: ifup: interface eth0 already configured Jul 09 12:52:14 volumio sh[512]: eth0=eth0 Jul 09 12:52:14 volumio ifplugd(eth0)[769]: Program executed successfully. Jul 09 12:52:14 volumio wireless.js[627]: trying... Jul 09 12:52:14 volumio sudo[998]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Jul 09 12:52:14 volumio sudo[998]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 09 12:52:14 volumio sudo[998]: pam_unix(sudo:session): session closed for user root Jul 09 12:52:15 volumio ntpd[781]: Listen normally on 3 eth0 192.168.1.100:123 Jul 09 12:52:15 volumio ntpd[781]: new interface(s) found: waking up resolver Jul 09 12:52:15 volumio wireless.js[627]: trying... Jul 09 12:52:15 volumio sudo[1001]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Jul 09 12:52:15 volumio sudo[1001]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 09 12:52:15 volumio sudo[1001]: pam_unix(sudo:session): session closed for user root Jul 09 12:52:16 volumio volumio-time-update[623]: volumio-time-update-util: Fetching time from Volumio... Jul 09 12:52:16 volumio wireless.js[627]: trying... Jul 09 12:52:16 volumio sudo[1008]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Jul 09 12:52:16 volumio sudo[1008]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 09 12:52:16 volumio sudo[1008]: pam_unix(sudo:session): session closed for user root Jul 09 12:52:16 volumio volumio-time-update[623]: volumio-time-update-util: Setting system time to: 2025-07-09 12:53:19 Jul 09 12:52:16 volumio sudo[1011]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/bin/timedatectl set-time 2025-07-09 12:53:19 Jul 09 12:52:16 volumio sudo[1011]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 09 12:52:16 volumio dbus-daemon[616]: [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service' requested by ':1.9' (uid=0 pid=1012 comm="timedatectl set-time 2025-07-09 12:53:19 ") Jul 09 12:52:16 volumio systemd[1]: Starting Time & Date Service... Jul 09 12:52:16 volumio dbus-daemon[616]: [system] Successfully activated service 'org.freedesktop.timedate1' Jul 09 12:52:16 volumio systemd[1]: Started Time & Date Service. Jul 09 12:53:19 volumio systemd-timedated[1013]: Changed local time to Wed Jul 9 12:53:19 2025 Jul 09 12:53:19 volumio sudo[1011]: pam_unix(sudo:session): session closed for user root Jul 09 12:53:19 volumio volumio-time-update[623]: volumio-time-update-util: System time updated successfully. Jul 09 12:53:19 volumio systemd[1]: Started Volumio Time Update Utility. Jul 09 12:53:19 volumio nmbd[736]: [2025/07/09 12:53:19.270784, 0] ../lib/util/become_daemon.c:138(daemon_ready) Jul 09 12:53:19 volumio nmbd[736]: daemon_ready: STATUS=daemon 'nmbd' finished starting up and ready to serve connections Jul 09 12:53:19 volumio systemd[1]: Started Samba NMB Daemon. Jul 09 12:53:19 volumio nmbd[736]: [2025/07/09 12:53:19.281499, 0] ../source3/nmbd/nmbd_namequery.c:109(query_name_response) Jul 09 12:53:19 volumio nmbd[736]: query_name_response: Multiple (2) responses received for a query on subnet 192.168.1.100 for name WORKGROUP<1d>. Jul 09 12:53:19 volumio nmbd[736]: This response was from IP 192.168.1.1, reporting an IP address of 192.168.1.1. Jul 09 12:53:19 volumio systemd[1]: Starting Samba Winbind Daemon... Jul 09 12:53:19 volumio wireless.js[627]: trying... Jul 09 12:53:19 volumio winbindd[1014]: [2025/07/09 12:53:19.484467, 0] ../source3/winbindd/winbindd_cache.c:3160(initialize_winbindd_cache) Jul 09 12:53:19 volumio winbindd[1014]: initialize_winbindd_cache: clearing cache and re-creating with version number 2 Jul 09 12:53:19 volumio sudo[1017]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Jul 09 12:53:19 volumio sudo[1017]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 09 12:53:19 volumio sudo[1017]: pam_unix(sudo:session): session closed for user root Jul 09 12:53:19 volumio winbindd[1014]: [2025/07/09 12:53:19.504993, 0] ../lib/util/become_daemon.c:138(daemon_ready) Jul 09 12:53:19 volumio winbindd[1014]: daemon_ready: STATUS=daemon 'winbindd' finished starting up and ready to serve connections Jul 09 12:53:19 volumio systemd[1]: Started Samba Winbind Daemon. Jul 09 12:53:19 volumio systemd[1]: Starting Samba SMB Daemon... Jul 09 12:53:19 volumio dhcpcd[950]: wlan0: leased 192.168.1.101 for 86400 seconds Jul 09 12:53:19 volumio avahi-daemon[613]: Joining mDNS multicast group on interface wlan0.IPv4 with address 192.168.1.101. Jul 09 12:53:19 volumio dhcpcd[950]: wlan0: adding route to 192.168.1.0/24 Jul 09 12:53:19 volumio avahi-daemon[613]: New relevant interface wlan0.IPv4 for mDNS. Jul 09 12:53:19 volumio dhcpcd[950]: wlan0: adding default route via 192.168.1.1 Jul 09 12:53:19 volumio avahi-daemon[613]: Registering new address record for 192.168.1.101 on wlan0.IPv4. Jul 09 12:53:19 volumio smbd[1022]: [2025/07/09 12:53:19.862399, 0] ../lib/util/become_daemon.c:138(daemon_ready) Jul 09 12:53:19 volumio systemd[1]: Started Samba SMB Daemon. Jul 09 12:53:19 volumio smbd[1022]: daemon_ready: STATUS=daemon 'smbd' finished starting up and ready to serve connections Jul 09 12:53:20 volumio wireless.js[627]: trying... Jul 09 12:53:20 volumio sudo[1051]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Jul 09 12:53:20 volumio sudo[1051]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 09 12:53:20 volumio sudo[1051]: pam_unix(sudo:session): session closed for user root Jul 09 12:53:20 volumio wireless.js[627]: Connected to: ----WiFi-273C Jul 09 12:53:20 volumio wireless.js[627]: ---- Jul 09 12:53:20 volumio sudo[1054]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jul 09 12:53:20 volumio sudo[1054]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 09 12:53:20 volumio sudo[1054]: pam_unix(sudo:session): session closed for user root Jul 09 12:53:20 volumio wireless.js[627]: ... joined AP, wlan0 IPv4 is 192.168.1.101, ipV6 is undefined Jul 09 12:53:20 volumio wireless.js[627]: It's done! AP Jul 09 12:53:20 volumio kernel: brcmfmac: brcmf_cfg80211_set_power_mgmt: power save disabled Jul 09 12:53:20 volumio systemd[1]: Started Wireless Services. Jul 09 12:53:20 volumio systemd[1]: Started Volumio Backend Module. Jul 09 12:53:20 volumio systemd[1]: Started Volumio Cpu Tweaker. Jul 09 12:53:20 volumio systemd[1]: Reached target Multi-User System. Jul 09 12:53:20 volumio systemd[1]: Reached target Graphical Interface. Jul 09 12:53:20 volumio systemd[1]: Starting Update UTMP about System Runlevel Changes... Jul 09 12:53:20 volumio systemd[1]: systemd-update-utmp-runlevel.service: Succeeded. Jul 09 12:53:20 volumio systemd[1]: Started Update UTMP about System Runlevel Changes. Jul 09 12:53:20 volumio systemd[1]: Startup finished in 12.210s (kernel) + 21.592s (userspace) = 33.803s. Jul 09 12:53:20 volumio volumio-cpu-tweak[1060]: Setting RT Priority for mpd Jul 09 12:53:20 volumio volumio-cpu-tweak[1060]: Setting MPD Affinity Jul 09 12:53:20 volumio volumio-cpu-tweak[1060]: pid 795's current affinity mask: f Jul 09 12:53:20 volumio volumio-cpu-tweak[1060]: pid 795's new affinity mask: 3 Jul 09 12:53:20 volumio volumio-cpu-tweak[1060]: /bin/volumio_cpu_tweak: line 27: warning: command substitution: ignored null byte in input Jul 09 12:53:20 volumio volumio-cpu-tweak[1060]: VOLUMIO CPU TWEAK: Setting CPU Governor: performance Jul 09 12:53:20 volumio systemd[1]: volumio_cpu_tweak.service: Succeeded. Jul 09 12:53:21 volumio ntpd[781]: Listen normally on 4 wlan0 192.168.1.101:123 Jul 09 12:53:21 volumio ntpd[781]: new interface(s) found: waking up resolver Jul 09 12:53:22 volumio volumio[1059]: info: ------------------------------------------- Jul 09 12:53:22 volumio volumio[1059]: info: ----- Volumio3 ---- Jul 09 12:53:22 volumio volumio[1059]: info: ------------------------------------------- Jul 09 12:53:22 volumio volumio[1059]: info: ----- System startup ---- Jul 09 12:53:22 volumio volumio[1059]: info: ------------------------------------------- Jul 09 12:53:22 volumio volumio[1059]: info: MYVOLUMIO Environment detected Jul 09 12:53:23 volumio volumio[1059]: info: Plugin folders cleanup Jul 09 12:53:23 volumio volumio[1059]: info: Scanning into folder /volumio/app/plugins/ Jul 09 12:53:23 volumio volumio[1059]: info: Scanning category audio_interface Jul 09 12:53:23 volumio volumio[1059]: info: Scanning category miscellanea Jul 09 12:53:23 volumio volumio[1059]: info: Scanning category music_service Jul 09 12:53:23 volumio volumio[1059]: info: Scanning category plugins.json Jul 09 12:53:23 volumio volumio[1059]: info: Scanning category system_controller Jul 09 12:53:23 volumio volumio[1059]: info: Scanning category user_interface Jul 09 12:53:23 volumio volumio[1059]: info: Scanning into folder /data/plugins/ Jul 09 12:53:23 volumio volumio[1059]: info: Scanning category audio_interface Jul 09 12:53:23 volumio volumio[1059]: info: Scanning category music_service Jul 09 12:53:23 volumio volumio[1059]: info: Plugin folders cleanup completed Jul 09 12:53:23 volumio volumio[1059]: info: ------------------------------------------- Jul 09 12:53:23 volumio volumio[1059]: info: ----- Core plugins startup ---- Jul 09 12:53:23 volumio volumio[1059]: info: ------------------------------------------- Jul 09 12:53:23 volumio volumio[1059]: info: Loading plugins from folder /volumio/app/plugins/ Jul 09 12:53:23 volumio volumio[1059]: info: Adding plugin upnp to MyMusic Plugins Jul 09 12:53:23 volumio volumio[1059]: info: Adding plugin airplay_emulation to MyMusic Plugins Jul 09 12:53:23 volumio volumio[1059]: info: Adding plugin upnp_browser to MyMusic Plugins Jul 09 12:53:23 volumio volumio[1059]: info: Loading plugins from folder /data/plugins/ Jul 09 12:53:23 volumio volumio[1059]: info: Loading plugin "system"... Jul 09 12:53:23 volumio volumio[1059]: info: Loading plugin "appearance"... Jul 09 12:53:24 volumio volumio[1059]: info: Loading plugin "network"... Jul 09 12:53:24 volumio volumio[1059]: info: Refreshing Cached IP Addresses Jul 09 12:53:24 volumio sudo[1091]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jul 09 12:53:24 volumio sudo[1091]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 09 12:53:24 volumio sudo[1091]: pam_unix(sudo:session): session closed for user root Jul 09 12:53:24 volumio sudo[1093]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jul 09 12:53:24 volumio sudo[1093]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 09 12:53:24 volumio volumio[1059]: info: Loading plugin "services"... Jul 09 12:53:24 volumio sudo[1093]: pam_unix(sudo:session): session closed for user root Jul 09 12:53:24 volumio volumio[1059]: info: Loading plugin "alsa_controller"... Jul 09 12:53:24 volumio sudo[1102]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Jul 09 12:53:24 volumio sudo[1102]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 09 12:53:24 volumio volumio[1059]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jul 09 12:53:24 volumio volumio[1059]: info: Loading plugin "wizard"... Jul 09 12:53:24 volumio volumio[1059]: info: Loading plugin "networkfs"... Jul 09 12:53:24 volumio volumio[1059]: info: Starting Udev Watcher for removable devices Jul 09 12:53:24 volumio volumio[1059]: info: Ignoring mount for partition: boot Jul 09 12:53:24 volumio volumio[1059]: info: Ignoring mount for partition: volumio Jul 09 12:53:24 volumio volumio[1059]: info: Ignoring mount for partition: volumio_data Jul 09 12:53:24 volumio volumio[1059]: info: Mounting Device CAE7-3BE6 Jul 09 12:53:24 volumio sudo[1120]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount /dev/sda1 /mnt/USB/CAE7-3BE6 -o noatime Jul 09 12:53:24 volumio sudo[1120]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 09 12:53:24 volumio sudo[1120]: pam_unix(sudo:session): session closed for user root Jul 09 12:53:24 volumio volumio[1059]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jul 09 12:53:24 volumio volumio[1059]: info: Loading plugin "volumio_command_line_client"... Jul 09 12:53:24 volumio volumio[1059]: info: Loading plugin "upnp"... Jul 09 12:53:24 volumio volumio[1059]: info: [1752029604331] Starting Upmpd Daemon Jul 09 12:53:24 volumio volumio[1059]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jul 09 12:53:24 volumio volumio[1059]: info: Loading plugin "my_music"... Jul 09 12:53:24 volumio volumio[1059]: info: Loading plugin "mpd"... Jul 09 12:53:24 volumio volumio[1059]: info: Loading plugin "upnp_browser"... Jul 09 12:53:24 volumio volumio[1059]: info: Loading plugin "alarm-clock"... Jul 09 12:53:25 volumio volumio[1059]: info: Loading plugin "airplay_emulation"... Jul 09 12:53:25 volumio volumio[1059]: info: Starting Shairport Sync Jul 09 12:53:25 volumio volumio[1059]: info: Loading plugin "last_100"... Jul 09 12:53:25 volumio volumio[1059]: info: Loading plugin "webradio"... Jul 09 12:53:25 volumio volumio[1059]: info: Loading plugin "i2s_dacs"... Jul 09 12:53:25 volumio volumio[1059]: info: Loading plugin "volumiodiscovery"... Jul 09 12:53:25 volumio volumio[1059]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jul 09 12:53:25 volumio volumio[1059]: *** WARNING *** Please fix your application to use the native API of Avahi! Jul 09 12:53:25 volumio node[1059]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jul 09 12:53:25 volumio volumio[1059]: *** WARNING *** For more information see Jul 09 12:53:25 volumio volumio[1059]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jul 09 12:53:25 volumio volumio[1059]: *** WARNING *** Please fix your application to use the native API of Avahi! Jul 09 12:53:25 volumio volumio[1059]: *** WARNING *** For more information see Jul 09 12:53:25 volumio node[1059]: *** WARNING *** Please fix your application to use the native API of Avahi! Jul 09 12:53:25 volumio node[1059]: *** WARNING *** For more information see Jul 09 12:53:25 volumio node[1059]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jul 09 12:53:25 volumio node[1059]: *** WARNING *** Please fix your application to use the native API of Avahi! Jul 09 12:53:25 volumio node[1059]: *** WARNING *** For more information see Jul 09 12:53:25 volumio volumio[1059]: info: Applying required configuration parameters for plugin volumiodiscovery Jul 09 12:53:25 volumio volumio[1059]: info: Discovery: Started advertising with name: Volumio Jul 09 12:53:25 volumio volumio[1059]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jul 09 12:53:25 volumio volumio[1059]: info: Loading plugin "spop"... Jul 09 12:53:25 volumio volumio-remote-updater[592]: [2025-07-09 12:53:25] [connect] Successful connection Jul 09 12:53:26 volumio volumio[1059]: info: Loading plugin "outputs"... Jul 09 12:53:26 volumio volumio[1059]: info: Loading plugin "albumart"... Jul 09 12:53:26 volumio volumio[1059]: info: Plugin example_plugin is not enabled Jul 09 12:53:26 volumio volumio[1059]: info: Loading plugin "inputs"... Jul 09 12:53:26 volumio volumio[1059]: info: Loading plugin "updater_comm"... Jul 09 12:53:26 volumio volumio[1059]: info: Plugin mpdemulation is not enabled Jul 09 12:53:26 volumio volumio[1059]: info: Loading plugin "rest_api"... Jul 09 12:53:26 volumio volumio[1059]: info: Loading plugin "websocket"... Jul 09 12:53:26 volumio volumio[1059]: info: Starting Socket.io Server version 2.3.0 Jul 09 12:53:26 volumio volumio[1059]: info: Loading plugin "fusiondsp"... Jul 09 12:53:26 volumio volumio[1059]: Forking 3 albumart workers Jul 09 12:53:26 volumio volumio[1059]: info: Applying required configuration parameters for plugin fusiondsp Jul 09 12:53:27 volumio volumio[1059]: info: Loading i18n strings for locale en Jul 09 12:53:27 volumio volumio[1059]: Updating browse sources language Jul 09 12:53:27 volumio volumio[1059]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jul 09 12:53:27 volumio volumio[1059]: Starting albumart workers Jul 09 12:53:27 volumio volumio[1059]: Starting albumart workers Jul 09 12:53:27 volumio volumio[1059]: Starting albumart workers Jul 09 12:53:27 volumio volumio[1059]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jul 09 12:53:27 volumio volumio[1059]: info: CoreCommandRouter::initPlayerControls Jul 09 12:53:27 volumio volumio[1059]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 09 12:53:27 volumio volumio[1059]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 09 12:53:27 volumio volumio[1059]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 09 12:53:27 volumio volumio[1059]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 09 12:53:27 volumio volumio[1059]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 09 12:53:27 volumio volumio[1059]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 09 12:53:27 volumio volumio[1059]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 09 12:53:27 volumio volumio[1059]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 09 12:53:27 volumio volumio[1059]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jul 09 12:53:27 volumio volumio[1059]: Express server listening on port 3000 Jul 09 12:53:27 volumio volumio[1059]: [Metrics] WebUI: 5s 768.94ms Jul 09 12:53:27 volumio volumio[1059]: info: CoreStateMachine::resetVolumioState Jul 09 12:53:27 volumio volumio[1059]: info: CoreStateMachine::getcurrentVolume Jul 09 12:53:27 volumio volumio[1059]: info: CoreCommandRouter::volumioRetrievevolume Jul 09 12:53:27 volumio volumio[1059]: info: Volumio Network Manager: Network status updated: 3 Jul 09 12:53:27 volumio volumio-remote-updater[592]: [2025-07-09 12:53:27] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1752029605 101 Jul 09 12:53:27 volumio volumio[1059]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 4 Transport: websocket Total Clients: 1 Jul 09 12:53:27 volumio volumio[1059]: info: CoreStateMachine::pushState Jul 09 12:53:27 volumio volumio[1059]: info: CorePlayQueue::getTrack 0 Jul 09 12:53:27 volumio volumio[1059]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 09 12:53:27 volumio volumio[1059]: info: CoreCommandRouter::volumioPushState Jul 09 12:53:27 volumio volumio[1059]: info: CoreStateMachine::updateTrackBlock Jul 09 12:53:27 volumio volumio[1059]: info: CorePlayQueue::getTrackBlock Jul 09 12:53:27 volumio volumio[1059]: info: CoreCommandRouter::volumioRetrievevolume Jul 09 12:53:27 volumio sudo[1102]: pam_unix(sudo:session): session closed for user root Jul 09 12:53:27 volumio volumio[1059]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jul 09 12:53:27 volumio volumio[1059]: info: Reloading queue from file Jul 09 12:53:27 volumio volumio[1059]: info: CoreStateMachine::setRepeat false single undefined Jul 09 12:53:27 volumio volumio[1059]: info: CoreStateMachine::pushState Jul 09 12:53:27 volumio volumio[1059]: info: CorePlayQueue::getTrack 0 Jul 09 12:53:27 volumio volumio[1059]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 09 12:53:27 volumio volumio[1059]: info: CoreCommandRouter::volumioPushState Jul 09 12:53:27 volumio volumio[1059]: info: CoreStateMachine::setRandom true Jul 09 12:53:27 volumio volumio[1059]: info: CoreStateMachine::pushState Jul 09 12:53:27 volumio volumio[1059]: info: CorePlayQueue::getTrack 0 Jul 09 12:53:27 volumio volumio[1059]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 09 12:53:27 volumio volumio[1059]: info: CoreCommandRouter::volumioPushState Jul 09 12:53:27 volumio volumio[1059]: info: Setting Device type: Raspberry PI Jul 09 12:53:27 volumio volumio[1059]: info: Completed loading Core Plugins Jul 09 12:53:27 volumio volumio[1059]: info: Preparing to generate the ALSA configuration file Jul 09 12:53:27 volumio volumio[1059]: info: CoreStateMachine::pushState Jul 09 12:53:27 volumio volumio[1059]: info: CorePlayQueue::getTrack 0 Jul 09 12:53:27 volumio volumio[1059]: info: CoreCommandRouter::volumioPushState Jul 09 12:53:27 volumio volumio[1059]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Jul 09 12:53:27 volumio volumio[1059]: info: USB Boot Capable - System SBC Revision found in cpuinfo: b03115 Jul 09 12:53:27 volumio volumio[1059]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Jul 09 12:53:27 volumio volumio[1059]: info: The plugin alsa_controller has an ALSA contribution file softvolume.postVolume.conf Jul 09 12:53:27 volumio volumio[1059]: info: The plugin fusiondsp has an ALSA contribution file volumioDsp.postDsp.10.conf Jul 09 12:53:27 volumio volumio[1059]: info: Reading ALSA contributions from plugins. Jul 09 12:53:27 volumio volumio[1059]: info: Asound.conf file unchanged, so no further update is needed Jul 09 12:53:27 volumio volumio[1059]: info: Output device has changed, restarting MPD Jul 09 12:53:27 volumio volumio[1059]: info: Output device has changed, restarting Shairport Sync Jul 09 12:53:27 volumio sudo[1204]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jul 09 12:53:27 volumio volumio[1059]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 09 12:53:27 volumio volumio[1059]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jul 09 12:53:27 volumio sudo[1204]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 09 12:53:27 volumio sudo[1204]: pam_unix(sudo:session): session closed for user root Jul 09 12:53:27 volumio sudo[1206]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jul 09 12:53:27 volumio sudo[1206]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 09 12:53:27 volumio systemd[1]: Stopping Music Player Daemon... Jul 09 12:53:27 volumio volumio[1059]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jul 09 12:53:27 volumio volumio[1059]: info: ___________ START PLUGINS ___________ Jul 09 12:53:27 volumio volumio[1059]: info: ControllerMpd::onStart: Initializing MPD Jul 09 12:53:27 volumio volumio[1059]: info: Creating MPD Configuration file Jul 09 12:53:27 volumio volumio[1059]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jul 09 12:53:27 volumio volumio[1059]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jul 09 12:53:27 volumio volumio[1059]: info: [1752029607858] CoreMusicLibrary::Adding element Media Servers Jul 09 12:53:27 volumio volumio[1059]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jul 09 12:53:27 volumio sudo[1213]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jul 09 12:53:27 volumio sudo[1213]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 09 12:53:27 volumio sudo[1213]: pam_unix(sudo:session): session closed for user root Jul 09 12:53:27 volumio sudo[1215]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jul 09 12:53:27 volumio sudo[1215]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 09 12:53:27 volumio volumio[1059]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 09 12:53:27 volumio volumio[1059]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jul 09 12:53:27 volumio systemd[1]: mpd.service: Succeeded. Jul 09 12:53:27 volumio systemd[1]: Stopped Music Player Daemon. Jul 09 12:53:27 volumio volumio[1059]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jul 09 12:53:27 volumio volumio[1059]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 09 12:53:27 volumio volumio[1059]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jul 09 12:53:27 volumio volumio[1059]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jul 09 12:53:27 volumio volumio[1059]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jul 09 12:53:27 volumio volumio[1059]: info: [1752029607951] CoreMusicLibrary::Adding element Last_100 Jul 09 12:53:27 volumio volumio[1059]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jul 09 12:53:27 volumio volumio[1059]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jul 09 12:53:27 volumio volumio[1059]: info: [1752029607953] CoreMusicLibrary::Adding element Webradio Jul 09 12:53:27 volumio volumio[1059]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jul 09 12:53:27 volumio volumio[1059]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jul 09 12:53:27 volumio volumio[1059]: info: Initializing BBC Radios Jul 09 12:53:27 volumio systemd[1]: Starting Music Player Daemon... Jul 09 12:53:28 volumio volumio[1059]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jul 09 12:53:28 volumio volumio[1059]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jul 09 12:53:28 volumio volumio[1059]: info: Creating Spotify config file Jul 09 12:53:28 volumio volumio[1059]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 09 12:53:28 volumio volumio[1059]: info: Loading i18n strings for locale en Jul 09 12:53:28 volumio volumio[1059]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , updateALSAConfigFile Jul 09 12:53:28 volumio volumio[1059]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 09 12:53:28 volumio volumio[1059]: info: FusionDsp - mixtype--------------------- Software Jul 09 12:53:28 volumio volumio[1059]: info: Volumio Calling Home Jul 09 12:53:28 volumio sudo[1221]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jul 09 12:53:28 volumio sudo[1221]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 09 12:53:28 volumio sudo[1221]: pam_unix(sudo:session): session closed for user root Jul 09 12:53:28 volumio volumio[1059]: info: Preparing to generate the ALSA configuration file Jul 09 12:53:28 volumio volumio[1059]: info: Discovery: adding 3aa091d6-8ec6-4f12-a606-dce7d9365697 Jul 09 12:53:28 volumio volumio[1059]: info: Discovery: Found device Volumio Jul 09 12:53:28 volumio volumio[1059]: info: CoreCommandRouter::volumioGetState Jul 09 12:53:28 volumio volumio[1059]: info: CorePlayQueue::getTrack 0 Jul 09 12:53:28 volumio volumio[1059]: info: Discovery: this is already registered, 3aa091d6-8ec6-4f12-a606-dce7d9365697 Jul 09 12:53:28 volumio volumio[1059]: info: Discovery: Found device Volumio Jul 09 12:53:28 volumio volumio[1059]: info: CoreCommandRouter::volumioGetState Jul 09 12:53:28 volumio volumio[1059]: info: CorePlayQueue::getTrack 0 Jul 09 12:53:28 volumio volumio[1059]: info: The plugin alsa_controller has an ALSA contribution file softvolume.postVolume.conf Jul 09 12:53:28 volumio volumio[1059]: info: The plugin fusiondsp has an ALSA contribution file volumioDsp.postDsp.10.conf Jul 09 12:53:28 volumio volumio[1059]: info: Reading ALSA contributions from plugins. Jul 09 12:53:28 volumio volumio[1059]: info: MPD Permissions set Jul 09 12:53:28 volumio volumio[1059]: info: MPD Permissions set Jul 09 12:53:28 volumio volumio[1059]: info: Spotify config file written Jul 09 12:53:28 volumio sudo[1242]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jul 09 12:53:28 volumio sudo[1242]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 09 12:53:28 volumio volumio[1059]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Jul 09 12:53:28 volumio volumio[1059]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 09 12:53:28 volumio volumio[1059]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 09 12:53:28 volumio volumio[1059]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 09 12:53:28 volumio volumio[1059]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 09 12:53:28 volumio volumio[1059]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 09 12:53:28 volumio volumio[1059]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 09 12:53:28 volumio volumio[1059]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 09 12:53:28 volumio volumio[1059]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 09 12:53:28 volumio volumio[1059]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jul 09 12:53:28 volumio volumio[1059]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 09 12:53:28 volumio volumio[1059]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 09 12:53:28 volumio volumio[1059]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 09 12:53:28 volumio volumio[1059]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 09 12:53:28 volumio volumio[1059]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 09 12:53:28 volumio volumio[1059]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 09 12:53:28 volumio volumio[1059]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 09 12:53:28 volumio volumio[1059]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 09 12:53:28 volumio volumio[1059]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 09 12:53:28 volumio volumio[1059]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jul 09 12:53:28 volumio volumio[1059]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 09 12:53:28 volumio volumio[1059]: info: No need to fix Spotify hosts Jul 09 12:53:28 volumio systemd[1]: Started go-librespot Daemon. Jul 09 12:53:28 volumio go-librespot[1244]: go-librespot daemon starting... Jul 09 12:53:28 volumio sudo[1242]: pam_unix(sudo:session): session closed for user root Jul 09 12:53:28 volumio volumio[1059]: info: Starting Shairport Sync Jul 09 12:53:28 volumio volumio[1059]: info: Starting Shairport Sync Jul 09 12:53:28 volumio volumio[1059]: info: Starting Shairport Sync Jul 09 12:53:28 volumio sudo[1255]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jul 09 12:53:28 volumio sudo[1255]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 09 12:53:28 volumio sudo[1257]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jul 09 12:53:28 volumio sudo[1257]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 09 12:53:28 volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Jul 09 12:53:28 volumio systemd[1]: shairport-sync.service: Succeeded. Jul 09 12:53:28 volumio sudo[1260]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jul 09 12:53:28 volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Jul 09 12:53:28 volumio sudo[1260]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 09 12:53:28 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Jul 09 12:53:28 volumio sudo[1255]: pam_unix(sudo:session): session closed for user root Jul 09 12:53:28 volumio volumio[1059]: info: CoreCommandRouter::volumioGetState Jul 09 12:53:28 volumio volumio[1059]: info: CorePlayQueue::getTrack 0 Jul 09 12:53:28 volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Jul 09 12:53:28 volumio systemd[1]: shairport-sync.service: Succeeded. Jul 09 12:53:28 volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Jul 09 12:53:28 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Jul 09 12:53:28 volumio volumio[1059]: info: Shairport-Sync Started Jul 09 12:53:28 volumio sudo[1257]: pam_unix(sudo:session): session closed for user root Jul 09 12:53:28 volumio volumio[1059]: Error adding Membership: Error: addMembership EINVAL Jul 09 12:53:28 volumio volumio[1059]: info: Asound.conf file unchanged, so no further update is needed Jul 09 12:53:28 volumio sudo[1260]: pam_unix(sudo:session): session closed for user root Jul 09 12:53:28 volumio volumio[1059]: info: Output device has changed, restarting MPD Jul 09 12:53:28 volumio volumio[1059]: info: Output device has changed, restarting Shairport Sync Jul 09 12:53:28 volumio volumio[1059]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 09 12:53:28 volumio volumio[1059]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jul 09 12:53:28 volumio sudo[1272]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jul 09 12:53:28 volumio sudo[1272]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 09 12:53:28 volumio sudo[1272]: pam_unix(sudo:session): session closed for user root Jul 09 12:53:28 volumio sudo[1274]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jul 09 12:53:28 volumio sudo[1274]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 09 12:53:28 volumio systemd[1]: mpd.service: Main process exited, code=killed, status=15/TERM Jul 09 12:53:28 volumio systemd[1]: mpd.service: Succeeded. Jul 09 12:53:28 volumio systemd[1]: Stopped Music Player Daemon. Jul 09 12:53:28 volumio volumio[1059]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jul 09 12:53:28 volumio volumio[1059]: info: MPD Permissions set Jul 09 12:53:28 volumio volumio[1059]: info: Shairport-Sync Started Jul 09 12:53:28 volumio volumio[1059]: info: Shairport-Sync Started Jul 09 12:53:28 volumio volumio[1059]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 09 12:53:28 volumio volumio[1059]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 09 12:53:28 volumio volumio[1059]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 09 12:53:28 volumio volumio[1059]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 09 12:53:28 volumio volumio[1059]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 09 12:53:28 volumio volumio[1059]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 09 12:53:28 volumio volumio[1059]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 09 12:53:28 volumio volumio[1059]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 09 12:53:28 volumio volumio[1059]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jul 09 12:53:28 volumio volumio[1059]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 09 12:53:28 volumio volumio[1059]: info: Starting Shairport Sync Jul 09 12:53:28 volumio systemd[1]: Starting Music Player Daemon... Jul 09 12:53:28 volumio volumio[1059]: info: Volumio called home Jul 09 12:53:28 volumio sudo[1288]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jul 09 12:53:28 volumio sudo[1288]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 09 12:53:28 volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Jul 09 12:53:28 volumio systemd[1]: shairport-sync.service: Succeeded. Jul 09 12:53:28 volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Jul 09 12:53:28 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Jul 09 12:53:28 volumio sudo[1288]: pam_unix(sudo:session): session closed for user root Jul 09 12:53:28 volumio volumio[1059]: info: Shairport-Sync Started Jul 09 12:53:28 volumio sudo[1282]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jul 09 12:53:28 volumio sudo[1282]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 09 12:53:28 volumio go-librespot[1244]: time="2025-07-09T12:53:28+10:00" level=info msg="running go-librespot 0.1.3" Jul 09 12:53:28 volumio go-librespot[1244]: time="2025-07-09T12:53:28+10:00" level=debug msg="app state loaded" Jul 09 12:53:28 volumio go-librespot[1244]: time="2025-07-09T12:53:28+10:00" level=debug msg="stored credentials not found" Jul 09 12:53:28 volumio sudo[1282]: pam_unix(sudo:session): session closed for user root Jul 09 12:53:28 volumio go-librespot[1244]: time="2025-07-09T12:53:28+10:00" level=info msg="api server listening on 127.0.0.1:9879" Jul 09 12:53:29 volumio go-librespot[1244]: time="2025-07-09T12:53:29+10:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jul 09 12:53:29 volumio go-librespot[1244]: time="2025-07-09T12:53:29+10:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jul 09 12:53:29 volumio go-librespot[1244]: time="2025-07-09T12:53:29+10:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jul 09 12:53:29 volumio go-librespot[1244]: time="2025-07-09T12:53:29+10:00" level=info msg="zeroconf server listening on port 36019" Jul 09 12:53:29 volumio mpd[1294]: Jul 09 12:53 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jul 09 12:53:29 volumio systemd[1]: Started Music Player Daemon. Jul 09 12:53:29 volumio sudo[1274]: pam_unix(sudo:session): session closed for user root Jul 09 12:53:29 volumio sudo[1215]: pam_unix(sudo:session): session closed for user root Jul 09 12:53:29 volumio sudo[1206]: pam_unix(sudo:session): session closed for user root Jul 09 12:53:29 volumio volumio[1059]: info: Completed starting Core Plugins Jul 09 12:53:29 volumio volumio[1059]: info: ------------------------------------------- Jul 09 12:53:29 volumio volumio[1059]: info: ----- MyVolumio plugins startup ---- Jul 09 12:53:29 volumio volumio[1059]: info: ------------------------------------------- Jul 09 12:53:29 volumio volumio[1059]: info: [MyVolumio PluginManager] Fetching plans data.... Jul 09 12:53:29 volumio volumio[1059]: error: MPD error: The expression evaluated to a falsy value: Jul 09 12:53:29 volumio volumio[1059]: assert.ok(self.idling) Jul 09 12:53:29 volumio volumio[1059]: error: The expression evaluated to a falsy value: Jul 09 12:53:29 volumio volumio[1059]: assert.ok(self.idling) Jul 09 12:53:29 volumio volumio[1059]: info: MPD running with PID1294 Jul 09 12:53:29 volumio volumio[1059]: ,establishing connection Jul 09 12:53:29 volumio volumio[1059]: error: MPD error: The expression evaluated to a falsy value: Jul 09 12:53:29 volumio volumio[1059]: assert.ok(self.idling) Jul 09 12:53:29 volumio volumio[1059]: error: The expression evaluated to a falsy value: Jul 09 12:53:29 volumio volumio[1059]: assert.ok(self.idling) Jul 09 12:53:29 volumio volumio[1059]: error: MPD error: The expression evaluated to a falsy value: Jul 09 12:53:29 volumio volumio[1059]: assert.ok(self.idling) Jul 09 12:53:29 volumio volumio[1059]: error: The expression evaluated to a falsy value: Jul 09 12:53:29 volumio volumio[1059]: assert.ok(self.idling) Jul 09 12:53:29 volumio volumio[1059]: error: updateQueue error: null Jul 09 12:53:30 volumio volumio[1059]: info: camilladsp spawned new process with pid 1307, instance 1, run: true Jul 09 12:53:30 volumio volumio[1059]: info: camilladsp service started and running in background, instance 1 Jul 09 12:53:30 volumio volumio[1059]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 09 12:53:30 volumio volumio[1059]: info: FusionDsp - AAAAAAAAAAAAAA-> 44100 48000 88200 96000 176400 192000 <-AAAAAAAAAAAAA Jul 09 12:53:30 volumio volumio[1059]: info: FusionDsp loaded Jul 09 12:53:30 volumio volumio[1059]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jul 09 12:53:30 volumio sudo[1311]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start fusiondsp.service Jul 09 12:53:30 volumio sudo[1311]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 09 12:53:30 volumio volumio[1059]: info: FusionDsp - Reporting Fusion DSP Enabled Jul 09 12:53:30 volumio volumio[1059]: info: Adding Signal Path Element [object Object] Jul 09 12:53:30 volumio volumio[1059]: info: Adding fusiondspeq DSP Signal Path Element Jul 09 12:53:30 volumio volumio[1059]: info: FusionDsp - ---- installed callbackRead Jul 09 12:53:30 volumio volumio[1059]: info: FusionDsp - If filter freq >samplerate/2 then disable it Jul 09 12:53:30 volumio volumio[1059]: error: FusionDsp - WebSocket error: [object Object] Jul 09 12:53:30 volumio volumio[1059]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Jul 09 12:53:30 volumio kernel: bcm2835-i2s fe203000.i2s: I2S SYNC error! Jul 09 12:53:30 volumio systemd[1]: Started FusionDsp Daemon. Jul 09 12:53:30 volumio sudo[1311]: pam_unix(sudo:session): session closed for user root Jul 09 12:53:31 volumio systemd[1]: systemd-fsckd.service: Succeeded. Jul 09 12:53:31 volumio volumio[1059]: info: go-librespot daemon successfully initialized Jul 09 12:53:32 volumio go-librespot[1244]: time="2025-07-09T12:53:32+10:00" level=debug msg="obtained new client token: AAC0MNByC22SnUA1WZBJjiAuHEcSLfG8rr61o9tdEB17bHwH5KKcZlQ1WqUVxeCv+By97T/UyBYGB91/qSOkfxxL0uhXZZAWgHVqUTLxeHkKIU9mBvNNAvPFYEUlLsYjBot4v02fuXcembXDhH3XLdd/P2fV+GWbiH3kE4bRSW0qchB6ISlXFR2gKzBVCmh8T1q3aU+O9NTrTIrOUuKE0FVi6P7NUkHb3CbOgVJ2kbxDUVql9JDH/EMfwR8=" Jul 09 12:53:33 volumio go-librespot[1244]: time="2025-07-09T12:53:33+10:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jul 09 12:53:33 volumio go-librespot[1244]: time="2025-07-09T12:53:33+10:00" level=debug msg="completed keyexchange" Jul 09 12:53:33 volumio go-librespot[1244]: time="2025-07-09T12:53:33+10:00" level=debug msg="completed challenge" Jul 09 12:53:33 volumio systemd[1]: systemd-hostnamed.service: Succeeded. Jul 09 12:53:33 volumio go-librespot[1244]: time="2025-07-09T12:53:33+10:00" level=info msg="authenticated AP as tcradtke" Jul 09 12:53:34 volumio go-librespot[1244]: time="2025-07-09T12:53:34+10:00" level=info msg="authenticated Login5 as tcradtke" Jul 09 12:53:34 volumio go-librespot[1244]: time="2025-07-09T12:53:34+10:00" level=info msg="accepted zeroconf user tcradtke from iPhone" Jul 09 12:53:34 volumio go-librespot[1244]: time="2025-07-09T12:53:34+10:00" level=debug msg="dealer connection opened" Jul 09 12:53:34 volumio go-librespot[1244]: time="2025-07-09T12:53:34+10:00" level=trace msg="starting accesspoint recv loop" Jul 09 12:53:34 volumio go-librespot[1244]: time="2025-07-09T12:53:34+10:00" level=trace msg="starting dealer recv loop" Jul 09 12:53:34 volumio go-librespot[1244]: time="2025-07-09T12:53:34+10:00" level=trace msg="received accesspoint ping" Jul 09 12:53:34 volumio go-librespot[1244]: time="2025-07-09T12:53:34+10:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Jul 09 12:53:34 volumio go-librespot[1244]: time="2025-07-09T12:53:34+10:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Jul 09 12:53:34 volumio go-librespot[1244]: time="2025-07-09T12:53:34+10:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Jul 09 12:53:34 volumio go-librespot[1244]: time="2025-07-09T12:53:34+10:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Jul 09 12:53:34 volumio go-librespot[1244]: time="2025-07-09T12:53:34+10:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Jul 09 12:53:34 volumio go-librespot[1244]: time="2025-07-09T12:53:34+10:00" level=debug msg="received connection id: YWNjYmU3MzEtZjJlNC00MWYzLWE2N2MtZmUwNjk5NDk1Y2E4K2RlYWxlcit0Y3A6Ly8wYWIxNTgzMC5pcC5nYWUyLnNwb3RpZnkubmV0OjU3MDArMkQ1RDJEQkE1MUE0Mzg5RUIxOEE0NTA0NkE2NDFBQUQ4ODgzRDJEQzhCMUU3RjhCOTg2NkUxRjlCNDcyN0ZDNA==" Jul 09 12:53:34 volumio sudo[1338]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jul 09 12:53:34 volumio sudo[1338]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 09 12:53:34 volumio sudo[1338]: pam_unix(sudo:session): session closed for user root Jul 09 12:53:34 volumio sudo[1340]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jul 09 12:53:34 volumio sudo[1340]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 09 12:53:34 volumio sudo[1340]: pam_unix(sudo:session): session closed for user root Jul 09 12:53:34 volumio sudo[1344]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Jul 09 12:53:34 volumio sudo[1344]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 09 12:53:34 volumio go-librespot[1244]: time="2025-07-09T12:53:34+10:00" level=trace msg="received accesspoint pong ack" Jul 09 12:53:34 volumio volumio[1059]: info: Initializing connection to go-librespot Websocket Jul 09 12:53:34 volumio volumio[1059]: info: Connection to go-librespot Websocket established Jul 09 12:53:34 volumio go-librespot[1244]: time="2025-07-09T12:53:34+10:00" level=debug msg="new websocket client" Jul 09 12:53:34 volumio systemd[1]: Started UPnP Renderer front-end to MPD. Jul 09 12:53:34 volumio sudo[1344]: pam_unix(sudo:session): session closed for user root Jul 09 12:53:34 volumio volumio[1059]: info: Upmpdcli Daemon Started Jul 09 12:53:34 volumio go-librespot[1244]: time="2025-07-09T12:53:34+10:00" level=debug msg="put connect state because NEW_DEVICE" Jul 09 12:53:34 volumio volumio[1346]: Generating RSA private key, 4096 bit long modulus (2 primes) Jul 09 12:53:34 volumio go-librespot[1244]: time="2025-07-09T12:53:34+10:00" level=debug msg="handling transfer player command from 62d651a410defc8059c05533032431645bf3bdb9" Jul 09 12:53:34 volumio go-librespot[1244]: time="2025-07-09T12:53:34+10:00" level=debug msg="resolved context of track" uri="spotify:playlist:6KQqLkBd9WZ69mAJKEquuu" Jul 09 12:53:34 volumio go-librespot[1244]: time="2025-07-09T12:53:34+10:00" level=trace msg="fetched new page 0 with 190 items (list: 190)" uri="spotify:playlist:6KQqLkBd9WZ69mAJKEquuu" Jul 09 12:53:34 volumio go-librespot[1244]: time="2025-07-09T12:53:34+10:00" level=warning msg="failed seeking to track in context spotify:playlist:6KQqLkBd9WZ69mAJKEquuu" error="could not find track" Jul 09 12:53:34 volumio go-librespot[1244]: time="2025-07-09T12:53:34+10:00" level=debug msg="shuffled context with seed 8331509329475185832 (len: 190, keep: 134)" Jul 09 12:53:34 volumio go-librespot[1244]: time="2025-07-09T12:53:34+10:00" level=debug msg="loading track (paused: false, position: 235916ms)" uri="spotify:track:59nLvM1AqsAyv9SR00MNso" Jul 09 12:53:35 volumio go-librespot[1244]: time="2025-07-09T12:53:35+10:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 09 12:53:35 volumio go-librespot[1244]: time="2025-07-09T12:53:35+10:00" level=trace msg="emitting websocket event: will_play" Jul 09 12:53:35 volumio volumio[1059]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:59nLvM1AqsAyv9SR00MNso","play_origin":"playlist/ondemand"}} Jul 09 12:53:35 volumio go-librespot[1244]: time="2025-07-09T12:53:35+10:00" level=debug msg="selected format OGG_VORBIS_320 (4e3d74a63c9e49f46cb0c731c4ed4ccced53e155)" uri="spotify:track:59nLvM1AqsAyv9SR00MNso" Jul 09 12:53:35 volumio go-librespot[1244]: time="2025-07-09T12:53:35+10:00" level=debug msg="requested aes key for file 4e3d74a63c9e49f46cb0c731c4ed4ccced53e155, gid: 59nLvM1AqsAyv9SR00MNso" Jul 09 12:53:35 volumio go-librespot[1244]: time="2025-07-09T12:53:35+10:00" level=debug msg="fetched first chunk of 26, total size is 13130143 bytes" uri="spotify:track:59nLvM1AqsAyv9SR00MNso" Jul 09 12:53:35 volumio go-librespot[1244]: time="2025-07-09T12:53:35+10:00" level=debug msg="fetched chunk 1/25, size: 524288" uri="spotify:track:59nLvM1AqsAyv9SR00MNso" Jul 09 12:53:36 volumio go-librespot[1244]: time="2025-07-09T12:53:36+10:00" level=debug msg="fetched chunk 3/25, size: 524288" uri="spotify:track:59nLvM1AqsAyv9SR00MNso" Jul 09 12:53:36 volumio go-librespot[1244]: time="2025-07-09T12:53:36+10:00" level=debug msg="fetched chunk 2/25, size: 524288" uri="spotify:track:59nLvM1AqsAyv9SR00MNso" Jul 09 12:53:36 volumio go-librespot[1244]: time="2025-07-09T12:53:36+10:00" level=debug msg="fetched chunk 16/25, size: 524288" uri="spotify:track:59nLvM1AqsAyv9SR00MNso" Jul 09 12:53:36 volumio go-librespot[1244]: time="2025-07-09T12:53:36+10:00" level=trace msg="seek to 235916ms (diff: 98ms, samples: 10403895, bytes: 8893046)" uri="spotify:track:59nLvM1AqsAyv9SR00MNso" Jul 09 12:53:36 volumio go-librespot[1244]: time="2025-07-09T12:53:36+10:00" level=debug msg="created new output device" Jul 09 12:53:36 volumio go-librespot[1244]: time="2025-07-09T12:53:36+10:00" level=debug msg="fetched chunk 18/25, size: 524288" uri="spotify:track:59nLvM1AqsAyv9SR00MNso" Jul 09 12:53:36 volumio go-librespot[1244]: time="2025-07-09T12:53:36+10:00" level=debug msg="fetched chunk 19/25, size: 524288" uri="spotify:track:59nLvM1AqsAyv9SR00MNso" Jul 09 12:53:36 volumio go-librespot[1244]: time="2025-07-09T12:53:36+10:00" level=debug msg="fetched chunk 17/25, size: 524288" uri="spotify:track:59nLvM1AqsAyv9SR00MNso" Jul 09 12:53:36 volumio go-librespot[1244]: time="2025-07-09T12:53:36+10:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 124988 us, period size = 5512 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 4 frames" Jul 09 12:53:36 volumio go-librespot[1244]: time="2025-07-09T12:53:36+10:00" level=info msg="loaded track \"Coconut Dance\" (paused: false, position: 235916ms, duration: 346274ms, prefetched: false)" uri="spotify:track:59nLvM1AqsAyv9SR00MNso" Jul 09 12:53:36 volumio volumio[1059]: info: FusionDsp - ---- read samplerate, raw: 44100,S32_LE,2,32 Jul 09 12:53:36 volumio volumio[1059]: info: FusionDsp - ---- read samplerate from file: 44100 Jul 09 12:53:36 volumio volumio[1059]: info: camilladsp stopping service pid 1307... Jul 09 12:53:36 volumio volumio[1059]: info: camilladsp service terminated, instance 1 Jul 09 12:53:36 volumio volumio[1059]: info: FusionDsp - If filter freq >samplerate/2 then disable it Jul 09 12:53:36 volumio volumio[1059]: info: camilladsp service started and running in background, instance 1 Jul 09 12:53:36 volumio volumio[1059]: info: camilladsp spawned new process with pid 1366, instance 1, run: true Jul 09 12:53:36 volumio go-librespot[1244]: time="2025-07-09T12:53:36+10:00" level=debug msg="fetched chunk 20/25, size: 524288" uri="spotify:track:59nLvM1AqsAyv9SR00MNso" Jul 09 12:53:36 volumio go-librespot[1244]: time="2025-07-09T12:53:36+10:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 09 12:53:36 volumio go-librespot[1244]: time="2025-07-09T12:53:36+10:00" level=trace msg="scheduling prefetch in 79s" Jul 09 12:53:36 volumio go-librespot[1244]: time="2025-07-09T12:53:36+10:00" level=trace msg="emitting websocket event: metadata" Jul 09 12:53:36 volumio go-librespot[1244]: time="2025-07-09T12:53:36+10:00" level=trace msg="emitting websocket event: active" Jul 09 12:53:36 volumio go-librespot[1244]: time="2025-07-09T12:53:36+10:00" level=debug msg="sending successful reply for dealer request" Jul 09 12:53:36 volumio volumio[1059]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:59nLvM1AqsAyv9SR00MNso","name":"Coconut Dance","artist_names":["Saphileaum"],"album_name":"Banana Leaf Paradise","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02e0d7101f583d9dbcffb09521","position":235916,"duration":346274,"release_date":"year:2024 month:2 day:23","track_number":1,"disc_number":1}} Jul 09 12:53:36 volumio volumio[1059]: SPOTIFY: received: {"type":"active","data":null} Jul 09 12:53:36 volumio volumio[1059]: info: Aligning Spotify Volume to Volumio Volume Jul 09 12:53:36 volumio volumio[1059]: info: CoreCommandRouter::volumioGetState Jul 09 12:53:36 volumio volumio[1059]: info: CorePlayQueue::getTrack 0 Jul 09 12:53:36 volumio volumio[1059]: info: Setting Spotify Volume from Volumio: 57 Jul 09 12:53:36 volumio go-librespot[1244]: time="2025-07-09T12:53:36+10:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 09 12:53:36 volumio go-librespot[1244]: time="2025-07-09T12:53:36+10:00" level=trace msg="emitting websocket event: playing" Jul 09 12:53:36 volumio volumio[1059]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:59nLvM1AqsAyv9SR00MNso","play_origin":"playlist/ondemand"}} Jul 09 12:53:36 volumio volumio[1059]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jul 09 12:53:36 volumio volumio[1059]: TypeError: Cannot read property 'service' of undefined Jul 09 12:53:36 volumio volumio[1059]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:337:50) Jul 09 12:53:36 volumio volumio[1059]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:263:18) Jul 09 12:53:36 volumio volumio[1059]: at WebSocket.message (/data/plugins/music_service/spop/index.js:190:14) Jul 09 12:53:36 volumio volumio[1059]: at WebSocket.emit (events.js:315:20) Jul 09 12:53:36 volumio volumio[1059]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20) Jul 09 12:53:36 volumio volumio[1059]: at Receiver.emit (events.js:315:20) Jul 09 12:53:36 volumio volumio[1059]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) Jul 09 12:53:36 volumio volumio[1059]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) Jul 09 12:53:36 volumio volumio[1059]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) Jul 09 12:53:36 volumio volumio[1059]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) Jul 09 12:53:36 volumio volumio[1059]: at writeOrBuffer (internal/streams/writable.js:358:12) Jul 09 12:53:36 volumio volumio[1059]: at Receiver.Writable.write (internal/streams/writable.js:303:10) Jul 09 12:53:36 volumio volumio[1059]: at Socket.socketOnData (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1355:35) Jul 09 12:53:36 volumio volumio[1059]: at Socket.emit (events.js:315:20) Jul 09 12:53:36 volumio volumio[1059]: at addChunk (internal/streams/readable.js:309:12) Jul 09 12:53:36 volumio volumio[1059]: at readableAddChunk (internal/streams/readable.js:284:9) Jul 09 12:53:36 volumio volumio[1059]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jul 09 12:53:37 volumio sudo[1382]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-07-09 12:52 Jul 09 12:53:37 volumio sudo[1382]: 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="a142ed2648fb91920de0dde3a60cd39b5d0ba4f6" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="811ff8312d42f9da0260be1d353081a805678820" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Wed 02 Jul 2025 04:07:25 PM CEST" VOLUMIO_VERSION="3.819" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="3b9115b1943141a9d7186aa434f8f3c2"