-- Logs begin at Sat 2024-04-13 21:45:44 PDT, end at Sat 2024-04-13 21:47:28 PDT. -- Apr 13 21:46:00 coffee volumio-remote-updater[463]: Error: No active session Apr 13 21:46:00 coffee volumio-remote-updater[463]: [2024-04-13 21:46:00] [info] asio async_connect error: system:111 (Connection refused) Apr 13 21:46:00 coffee volumio-remote-updater[463]: [2024-04-13 21:46:00] [info] Error getting remote endpoint: system:107 (Transport endpoint is not connected) Apr 13 21:46:00 coffee volumio-remote-updater[463]: [2024-04-13 21:46:00] [error] handle_connect error: Underlying Transport Error Apr 13 21:46:00 coffee systemd[1]: Starting Hostname Service... Apr 13 21:46:00 coffee systemd[1]: Started Raise network interfaces. Apr 13 21:46:00 coffee systemd[1]: Reached target Network. Apr 13 21:46:00 coffee systemd[1]: Condition check resulted in fast remote file copy program daemon being skipped. Apr 13 21:46:00 coffee systemd[1]: Reached target Network is Online. Apr 13 21:46:00 coffee volumio[473]: Could not open config: /tmp/upmpdcli.conf Apr 13 21:46:00 coffee systemd[1]: Starting LSB: Brings up/down network automatically... Apr 13 21:46:00 coffee systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Apr 13 21:46:00 coffee systemd[1]: Starting Samba NMB Daemon... Apr 13 21:46:00 coffee systemd[1]: Starting /etc/rc.local Compatibility... Apr 13 21:46:00 coffee systemd[1]: Starting Network Time Service... Apr 13 21:46:00 coffee systemd[1]: Starting Permit User Sessions... Apr 13 21:46:00 coffee systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Apr 13 21:46:00 coffee systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Apr 13 21:46:00 coffee systemd[1]: Started /etc/rc.local Compatibility. Apr 13 21:46:00 coffee systemd[1]: iptables.service: Succeeded. Apr 13 21:46:00 coffee systemd[1]: Started Permit User Sessions. Apr 13 21:46:00 coffee systemd[1]: Starting Hold until boot process finishes up... Apr 13 21:46:00 coffee dbus-daemon[464]: [system] Successfully activated service 'org.freedesktop.hostname1' Apr 13 21:46:00 coffee systemd[1]: Starting Terminate Plymouth Boot Screen... Apr 13 21:46:00 coffee systemd[1]: Started Hostname Service. Apr 13 21:46:00 coffee systemd[1]: Received SIGRTMIN+21 from PID 274 (plymouthd). Apr 13 21:46:00 coffee systemd[1]: Received SIGRTMIN+21 from PID 274 (plymouthd). Apr 13 21:46:01 coffee systemd[1]: plymouth-quit.service: Succeeded. Apr 13 21:46:01 coffee systemd[1]: Started Terminate Plymouth Boot Screen. Apr 13 21:46:01 coffee systemd[1]: plymouth-start.service: Succeeded. Apr 13 21:46:01 coffee systemd[1]: plymouth-quit-wait.service: Succeeded. Apr 13 21:46:01 coffee systemd[1]: Started Hold until boot process finishes up. Apr 13 21:46:01 coffee systemd[1]: Started Getty on tty1. Apr 13 21:46:01 coffee systemd[1]: Reached target Login Prompts. Apr 13 21:46:01 coffee ifplugd(eth0)[650]: ifplugd 0.28 initializing. Apr 13 21:46:01 coffee ifplugd(eth0)[650]: Using interface eth0/E0:CB:4E:3C:06:D3 with driver (version: 6.6.7-volumio) Apr 13 21:46:01 coffee ifplugd(eth0)[650]: Using detection mode: SIOCETHTOOL Apr 13 21:46:01 coffee ifplugd(eth0)[650]: Initialization complete, link beat not detected. Apr 13 21:46:01 coffee ifplugd[598]: Network Interface Plugging Daemon...start eth0...done. Apr 13 21:46:01 coffee systemd[1]: Started LSB: Brings up/down network automatically. Apr 13 21:46:01 coffee loadcpufreq[570]: Loading cpufreq kernel modules...done (acpi-cpufreq). Apr 13 21:46:01 coffee systemd[1]: Started LSB: Load kernel modules needed to enable cpufreq scaling. Apr 13 21:46:01 coffee ntpd[607]: ntpd 4.2.8p12@1.3728-o (1): Starting Apr 13 21:46:01 coffee ntpd[607]: Command line: /usr/sbin/ntpd -p /var/run/ntpd.pid -g -u 104:103 Apr 13 21:46:01 coffee systemd[1]: Starting LSB: set CPUFreq kernel parameters... Apr 13 21:46:01 coffee systemd[1]: Started Network Time Service. Apr 13 21:46:01 coffee ntpd[663]: proto: precision = 2.165 usec (-19) Apr 13 21:46:01 coffee ntpd[663]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): good hash signature Apr 13 21:46:01 coffee ntpd[663]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): loaded, expire=2022-12-28T00:00:00Z last=2017-01-01T00:00:00Z ofs=37 Apr 13 21:46:01 coffee ntpd[663]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): expired less than 474 days ago Apr 13 21:46:01 coffee ntpd[663]: Listen and drop on 0 v6wildcard [::]:123 Apr 13 21:46:01 coffee ntpd[663]: Listen and drop on 1 v4wildcard 0.0.0.0:123 Apr 13 21:46:01 coffee ntpd[663]: Listen normally on 2 lo 127.0.0.1:123 Apr 13 21:46:01 coffee ntpd[663]: Listening on routing socket on fd #19 for interface updates Apr 13 21:46:01 coffee ntpd[663]: kernel reports TIME_ERROR: 0x41: Clock Unsynchronized Apr 13 21:46:01 coffee ntpd[663]: kernel reports TIME_ERROR: 0x41: Clock Unsynchronized Apr 13 21:46:01 coffee cpufrequtils[662]: CPUFreq Utilities: Setting ondemand CPUFreq governor...disabled, governor not available...done. Apr 13 21:46:01 coffee systemd[1]: Started LSB: set CPUFreq kernel parameters. Apr 13 21:46:02 coffee systemd[1]: systemd-rfkill.service: Succeeded. Apr 13 21:46:02 coffee ntpd[663]: error resolving pool 0.debian.pool.ntp.org: System error (-11) Apr 13 21:46:02 coffee nmbd[615]: [2024/04/13 21:46:02.797743, 0] ../source3/nmbd/asyncdns.c:158(start_async_dns) Apr 13 21:46:02 coffee nmbd[615]: started asyncdns process 678 Apr 13 21:46:02 coffee nmbd[615]: [2024/04/13 21:46:02.807635, 0] ../lib/util/become_daemon.c:149(daemon_status) Apr 13 21:46:02 coffee nmbd[615]: daemon_status: STATUS=daemon 'nmbd' : No local IPv4 non-loopback interfaces available, waiting for interface ... Apr 13 21:46:02 coffee nmbd[615]: [2024/04/13 21:46:02.808808, 0] ../source3/nmbd/nmbd_subnetdb.c:254(create_subnets) Apr 13 21:46:02 coffee nmbd[615]: NOTE: NetBIOS name resolution is not supported for Internet Protocol Version 6 (IPv6). Apr 13 21:46:03 coffee wireless.js[458]: Cleaning previous... Apr 13 21:46:03 coffee ntpd[663]: error resolving pool 1.debian.pool.ntp.org: System error (-11) Apr 13 21:46:03 coffee sudo[686]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ip addr flush dev wlan0 Apr 13 21:46:03 coffee sudo[686]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 13 21:46:03 coffee sudo[686]: pam_unix(sudo:session): session closed for user root Apr 13 21:46:03 coffee sudo[688]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 down Apr 13 21:46:03 coffee sudo[688]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 13 21:46:03 coffee sudo[688]: pam_unix(sudo:session): session closed for user root Apr 13 21:46:03 coffee wireless.js[458]: Stopped aP Apr 13 21:46:03 coffee sudo[695]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 up Apr 13 21:46:03 coffee sudo[695]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 13 21:46:03 coffee sudo[695]: pam_unix(sudo:session): session closed for user root Apr 13 21:46:03 coffee sudo[697]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iw reg get Apr 13 21:46:03 coffee sudo[697]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 13 21:46:03 coffee sudo[697]: pam_unix(sudo:session): session closed for user root Apr 13 21:46:03 coffee sudo[704]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 up Apr 13 21:46:03 coffee sudo[704]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 13 21:46:03 coffee sudo[704]: pam_unix(sudo:session): session closed for user root Apr 13 21:46:03 coffee sudo[706]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iw wlan0 scan Apr 13 21:46:03 coffee sudo[706]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 13 21:46:04 coffee ntpd[663]: error resolving pool 2.debian.pool.ntp.org: System error (-11) Apr 13 21:46:04 coffee sudo[706]: pam_unix(sudo:session): session closed for user root Apr 13 21:46:04 coffee wireless.js[458]: SETTING APPROPRIATE REG DOMAIN: US Apr 13 21:46:04 coffee sudo[711]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 up Apr 13 21:46:04 coffee sudo[711]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 13 21:46:04 coffee sudo[711]: pam_unix(sudo:session): session closed for user root Apr 13 21:46:04 coffee sudo[713]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iw reg set US Apr 13 21:46:04 coffee sudo[713]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 13 21:46:04 coffee sudo[713]: pam_unix(sudo:session): session closed for user root Apr 13 21:46:04 coffee wireless.js[458]: SUCCESSFULLY SET NEW REGDOMAIN: US Apr 13 21:46:04 coffee wireless.js[458]: Start wireless flow Apr 13 21:46:04 coffee wireless.js[458]: Stopped hotspot (if there).. Apr 13 21:46:04 coffee sudo[718]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ip addr flush dev wlan0 Apr 13 21:46:04 coffee sudo[718]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 13 21:46:04 coffee sudo[718]: pam_unix(sudo:session): session closed for user root Apr 13 21:46:04 coffee sudo[720]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 down Apr 13 21:46:04 coffee sudo[720]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 13 21:46:04 coffee sudo[720]: pam_unix(sudo:session): session closed for user root Apr 13 21:46:04 coffee wireless.js[458]: DHCP IP Apr 13 21:46:04 coffee wireless.js[458]: Start ap Apr 13 21:46:04 coffee wpa_supplicant[722]: Successfully initialized wpa_supplicant Apr 13 21:46:04 coffee sudo[723]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/dhcpcd Apr 13 21:46:04 coffee sudo[723]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 13 21:46:04 coffee dhcpcd[724]: sending commands to master dhcpcd process Apr 13 21:46:04 coffee dhcpcd[545]: control command: /sbin/dhcpcd Apr 13 21:46:04 coffee sudo[723]: pam_unix(sudo:session): session closed for user root Apr 13 21:46:05 coffee ntpd[663]: error resolving pool 3.debian.pool.ntp.org: System error (-11) Apr 13 21:46:05 coffee volumio-remote-updater[463]: [2024-04-13 21:46:05] [info] asio async_connect error: system:111 (Connection refused) Apr 13 21:46:05 coffee volumio-remote-updater[463]: [2024-04-13 21:46:05] [info] Error getting remote endpoint: system:107 (Transport endpoint is not connected) Apr 13 21:46:05 coffee volumio-remote-updater[463]: [2024-04-13 21:46:05] [error] handle_connect error: Underlying Transport Error Apr 13 21:46:05 coffee wpa_supplicant[725]: wlan0: SME: Trying to authenticate with a0:36:bc:14:17:59 (SSID='KONA' freq=2447 MHz) Apr 13 21:46:05 coffee kernel: wlan0: authenticate with a0:36:bc:14:17:59 Apr 13 21:46:05 coffee kernel: wlan0: 80 MHz not supported, disabling VHT Apr 13 21:46:05 coffee kernel: wlan0: send auth to a0:36:bc:14:17:59 (try 1/3) Apr 13 21:46:05 coffee wireless.js[458]: trying... Apr 13 21:46:05 coffee wpa_supplicant[725]: wlan0: Trying to associate with a0:36:bc:14:17:59 (SSID='KONA' freq=2447 MHz) Apr 13 21:46:05 coffee kernel: wlan0: authenticated Apr 13 21:46:05 coffee kernel: wlan0: associate with a0:36:bc:14:17:59 (try 1/3) Apr 13 21:46:05 coffee sudo[727]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Apr 13 21:46:05 coffee sudo[727]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 13 21:46:05 coffee sudo[727]: pam_unix(sudo:session): session closed for user root Apr 13 21:46:06 coffee wpa_supplicant[725]: wlan0: Associated with a0:36:bc:14:17:59 Apr 13 21:46:06 coffee kernel: wlan0: RX AssocResp from a0:36:bc:14:17:59 (capab=0x1011 status=0 aid=22) Apr 13 21:46:06 coffee kernel: wlan0: associated Apr 13 21:46:06 coffee kernel: ath: EEPROM regdomain: 0x8348 Apr 13 21:46:06 coffee kernel: ath: EEPROM indicates we should expect a country code Apr 13 21:46:06 coffee kernel: ath: doing EEPROM country->regdmn map search Apr 13 21:46:06 coffee kernel: ath: country maps to regdmn code: 0x3a Apr 13 21:46:06 coffee kernel: ath: Country alpha2 being used: US Apr 13 21:46:06 coffee kernel: ath: Regpair used: 0x3a Apr 13 21:46:06 coffee kernel: ath: regdomain 0x8348 dynamically updated by country element Apr 13 21:46:06 coffee wpa_supplicant[725]: wlan0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0 Apr 13 21:46:06 coffee wpa_supplicant[725]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=COUNTRY_IE type=COUNTRY alpha2=US Apr 13 21:46:06 coffee kernel: wlan0: Limiting TX power to 27 (27 - 0) dBm as advertised by a0:36:bc:14:17:59 Apr 13 21:46:06 coffee wpa_supplicant[725]: wlan0: WPA: Key negotiation completed with a0:36:bc:14:17:59 [PTK=CCMP GTK=CCMP] Apr 13 21:46:06 coffee wpa_supplicant[725]: wlan0: CTRL-EVENT-CONNECTED - Connection to a0:36:bc:14:17:59 completed [id=0 id_str=] Apr 13 21:46:06 coffee dhcpcd[545]: wlan0: carrier acquired Apr 13 21:46:06 coffee dhcpcd[545]: wlan0: IAID d3:e6:20:45 Apr 13 21:46:06 coffee dhcpcd[545]: wlan0: adding address fe80::225:d3ff:fee6:2045 Apr 13 21:46:06 coffee dhcpcd[545]: ipv6_addaddr1: Permission denied Apr 13 21:46:06 coffee wireless.js[458]: trying... Apr 13 21:46:06 coffee dhcpcd[545]: wlan0: soliciting an IPv6 router Apr 13 21:46:06 coffee sudo[746]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Apr 13 21:46:06 coffee sudo[746]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 13 21:46:06 coffee sudo[746]: pam_unix(sudo:session): session closed for user root Apr 13 21:46:07 coffee dhcpcd[545]: wlan0: rebinding lease of 192.168.50.56 Apr 13 21:46:07 coffee dhcpcd[545]: wlan0: NAK: wrong address from 192.168.50.1 Apr 13 21:46:07 coffee dhcpcd[545]: wlan0: message: wrong address Apr 13 21:46:07 coffee dhcpcd[545]: wlan0: soliciting a DHCP lease Apr 13 21:46:07 coffee wireless.js[458]: trying... Apr 13 21:46:07 coffee sudo[758]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Apr 13 21:46:07 coffee sudo[758]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 13 21:46:07 coffee sudo[758]: pam_unix(sudo:session): session closed for user root Apr 13 21:46:08 coffee wireless.js[458]: trying... Apr 13 21:46:08 coffee sudo[761]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Apr 13 21:46:08 coffee sudo[761]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 13 21:46:08 coffee sudo[761]: pam_unix(sudo:session): session closed for user root Apr 13 21:46:09 coffee wireless.js[458]: trying... Apr 13 21:46:09 coffee sudo[764]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Apr 13 21:46:09 coffee sudo[764]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 13 21:46:09 coffee sudo[764]: pam_unix(sudo:session): session closed for user root Apr 13 21:46:10 coffee wireless.js[458]: trying... Apr 13 21:46:10 coffee sudo[767]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Apr 13 21:46:10 coffee sudo[767]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 13 21:46:10 coffee sudo[767]: pam_unix(sudo:session): session closed for user root Apr 13 21:46:11 coffee dhcpcd[545]: wlan0: offered 192.168.50.110 from 192.168.50.1 Apr 13 21:46:11 coffee dhcpcd[545]: wlan0: probing address 192.168.50.110/24 Apr 13 21:46:11 coffee wireless.js[458]: trying... Apr 13 21:46:11 coffee sudo[770]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Apr 13 21:46:11 coffee sudo[770]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 13 21:46:11 coffee sudo[770]: pam_unix(sudo:session): session closed for user root Apr 13 21:46:12 coffee volumio-remote-updater[463]: [2024-04-13 21:46:12] [info] asio async_connect error: system:111 (Connection refused) Apr 13 21:46:12 coffee volumio-remote-updater[463]: [2024-04-13 21:46:12] [info] Error getting remote endpoint: system:107 (Transport endpoint is not connected) Apr 13 21:46:12 coffee volumio-remote-updater[463]: [2024-04-13 21:46:12] [error] handle_connect error: Underlying Transport Error Apr 13 21:46:12 coffee wireless.js[458]: trying... Apr 13 21:46:12 coffee sudo[773]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Apr 13 21:46:12 coffee sudo[773]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 13 21:46:12 coffee sudo[773]: pam_unix(sudo:session): session closed for user root Apr 13 21:46:13 coffee wireless.js[458]: trying... Apr 13 21:46:13 coffee sudo[776]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Apr 13 21:46:13 coffee sudo[776]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 13 21:46:13 coffee sudo[776]: pam_unix(sudo:session): session closed for user root Apr 13 21:46:14 coffee wireless.js[458]: trying... Apr 13 21:46:14 coffee sudo[779]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Apr 13 21:46:14 coffee sudo[779]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 13 21:46:14 coffee sudo[779]: pam_unix(sudo:session): session closed for user root Apr 13 21:46:15 coffee wireless.js[458]: trying... Apr 13 21:46:15 coffee sudo[782]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Apr 13 21:46:15 coffee sudo[782]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 13 21:46:15 coffee sudo[782]: pam_unix(sudo:session): session closed for user root Apr 13 21:46:16 coffee dhcpcd[545]: wlan0: leased 192.168.50.110 for 86400 seconds Apr 13 21:46:16 coffee avahi-daemon[470]: Joining mDNS multicast group on interface wlan0.IPv4 with address 192.168.50.110. Apr 13 21:46:16 coffee avahi-daemon[470]: New relevant interface wlan0.IPv4 for mDNS. Apr 13 21:46:16 coffee avahi-daemon[470]: Registering new address record for 192.168.50.110 on wlan0.IPv4. Apr 13 21:46:16 coffee dhcpcd[545]: wlan0: adding route to 192.168.50.0/24 Apr 13 21:46:16 coffee dhcpcd[545]: wlan0: adding default route via 192.168.50.1 Apr 13 21:46:16 coffee wireless.js[458]: trying... Apr 13 21:46:16 coffee sudo[814]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Apr 13 21:46:16 coffee sudo[814]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 13 21:46:16 coffee sudo[814]: pam_unix(sudo:session): session closed for user root Apr 13 21:46:16 coffee wireless.js[458]: Connected to: ----KONA Apr 13 21:46:16 coffee wireless.js[458]: ---- Apr 13 21:46:16 coffee ntpd[663]: ntpd exiting on signal 15 (Terminated) Apr 13 21:46:16 coffee systemd[1]: Stopping Network Time Service... Apr 13 21:46:16 coffee systemd[1]: ntp.service: Succeeded. Apr 13 21:46:16 coffee systemd[1]: Stopped Network Time Service. Apr 13 21:46:16 coffee sudo[819]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Apr 13 21:46:16 coffee sudo[819]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 13 21:46:16 coffee systemd[1]: Starting Network Time Service... Apr 13 21:46:16 coffee sudo[819]: pam_unix(sudo:session): session closed for user root Apr 13 21:46:16 coffee wireless.js[458]: ... joined AP, wlan0 IPv4 is 192.168.50.110, ipV6 is undefined Apr 13 21:46:16 coffee wireless.js[458]: It's done! AP Apr 13 21:46:17 coffee ntpd[822]: ntpd 4.2.8p12@1.3728-o (1): Starting Apr 13 21:46:17 coffee ntpd[822]: Command line: /usr/sbin/ntpd -p /var/run/ntpd.pid -g -u 104:103 Apr 13 21:46:17 coffee ntpd[830]: proto: precision = 1.816 usec (-19) Apr 13 21:46:17 coffee ntpd[830]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): good hash signature Apr 13 21:46:17 coffee ntpd[830]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): loaded, expire=2022-12-28T00:00:00Z last=2017-01-01T00:00:00Z ofs=37 Apr 13 21:46:17 coffee ntpd[830]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): expired less than 474 days ago Apr 13 21:46:17 coffee ntpd[830]: Listen and drop on 0 v6wildcard [::]:123 Apr 13 21:46:17 coffee ntpd[830]: Listen and drop on 1 v4wildcard 0.0.0.0:123 Apr 13 21:46:17 coffee ntpd[830]: Listen normally on 2 lo 127.0.0.1:123 Apr 13 21:46:17 coffee ntpd[830]: Listen normally on 3 wlan0 192.168.50.110:123 Apr 13 21:46:17 coffee systemd[1]: Started Network Time Service. Apr 13 21:46:17 coffee ntpd[830]: Listening on routing socket on fd #20 for interface updates Apr 13 21:46:17 coffee ntpd[830]: kernel reports TIME_ERROR: 0x41: Clock Unsynchronized Apr 13 21:46:17 coffee ntpd[830]: kernel reports TIME_ERROR: 0x41: Clock Unsynchronized Apr 13 21:46:17 coffee iwconfig[833]: Error for wireless request "Set Power Management" (8B2C) : Apr 13 21:46:17 coffee iwconfig[833]: SET failed on device wlan0 ; Operation not supported. Apr 13 21:46:17 coffee systemd[1]: Started Wireless Services. Apr 13 21:46:17 coffee systemd[1]: Started Volumio Backend Module. Apr 13 21:46:17 coffee systemd[1]: Started Start Volumio Kiosk. Apr 13 21:46:17 coffee systemd[1]: Started Volumio Cpu Tweaker. Apr 13 21:46:17 coffee systemd[1]: Started Intel SST and HDA soundcard init service. Apr 13 21:46:17 coffee volumio-cpu-tweak[836]: Setting RT Priority for mpd Apr 13 21:46:17 coffee volumio-cpu-tweak[836]: pid 35's current scheduling policy: SCHED_OTHER Apr 13 21:46:17 coffee volumio-cpu-tweak[836]: pid 35's current scheduling priority: 0 Apr 13 21:46:17 coffee volumio-cpu-tweak[836]: Not enough cores to set MPD affinity Apr 13 21:46:17 coffee volumio-cpu-tweak[836]: VOLUMIO CPU TWEAK: Setting CPU Governor: performance Apr 13 21:46:17 coffee systemd[1]: volumio_cpu_tweak.service: Succeeded. Apr 13 21:46:17 coffee nmbd[615]: [2024/04/13 21:46:17.863488, 0] ../lib/util/become_daemon.c:138(daemon_ready) Apr 13 21:46:17 coffee nmbd[615]: daemon_ready: STATUS=daemon 'nmbd' finished starting up and ready to serve connections Apr 13 21:46:17 coffee systemd[1]: Started Samba NMB Daemon. Apr 13 21:46:17 coffee startx[835]: X.Org X Server 1.20.4 Apr 13 21:46:17 coffee startx[835]: X Protocol Version 11, Revision 0 Apr 13 21:46:17 coffee startx[835]: Build Operating System: Linux 5.10.0-10-amd64 x86_64 Debian Apr 13 21:46:17 coffee startx[835]: Current Operating System: Linux coffee 6.6.7-volumio #2 SMP PREEMPT_DYNAMIC Mon Dec 18 16:22:28 CET 2023 x86_64 Apr 13 21:46:17 coffee startx[835]: Kernel command line: BOOT_IMAGE=vmlinuz biosdevname=0 splash plymouth.ignore-serial-consoles quiet ro rootwait imgpart=UUID=e8396e64-ac09-46ae-b60c-b73932d465af bootpart=UUID=2138-C5D3 datapart=UUID=5c3c6231-72b1-4d40-99f1-8e542b29b6d6 imgfile=/volumio_current.sqsh logo.nologo vt.global_cursor_default=0 acpi_backlight=vendor use_kmsg=yes net.ifnames=0 loglevel=0 initrd=volumio.initrd Apr 13 21:46:17 coffee startx[835]: Build Date: 18 December 2021 09:05:36AM Apr 13 21:46:17 coffee startx[835]: xorg-server 2:1.20.4-1+deb10u4 (https://www.debian.org/support) Apr 13 21:46:17 coffee startx[835]: Current version of pixman: 0.36.0 Apr 13 21:46:17 coffee startx[835]: Before reporting problems, check http://wiki.x.org Apr 13 21:46:17 coffee startx[835]: to make sure that you have the latest version. Apr 13 21:46:17 coffee startx[835]: Markers: (--) probed, (**) from config file, (==) default setting, Apr 13 21:46:17 coffee startx[835]: (++) from command line, (!!) notice, (II) informational, Apr 13 21:46:17 coffee startx[835]: (WW) warning, (EE) error, (NI) not implemented, (??) unknown. Apr 13 21:46:17 coffee startx[835]: (==) Log file: "/var/log/Xorg.0.log", Time: Sat Apr 13 21:46:17 2024 Apr 13 21:46:17 coffee startx[835]: (==) Using system config directory "/usr/share/X11/xorg.conf.d" Apr 13 21:46:17 coffee systemd[1]: Starting Samba Winbind Daemon... Apr 13 21:46:18 coffee ntpd[830]: Soliciting pool server 162.159.200.123 Apr 13 21:46:19 coffee ntpd[830]: Soliciting pool server 65.100.46.166 Apr 13 21:46:19 coffee ntpd[830]: Soliciting pool server 129.146.193.200 Apr 13 21:46:19 coffee winbindd[890]: [2024/04/13 21:46:19.231419, 0] ../source3/winbindd/winbindd_cache.c:3160(initialize_winbindd_cache) Apr 13 21:46:19 coffee winbindd[890]: initialize_winbindd_cache: clearing cache and re-creating with version number 2 Apr 13 21:46:19 coffee winbindd[890]: [2024/04/13 21:46:19.359529, 0] ../lib/util/become_daemon.c:138(daemon_ready) Apr 13 21:46:19 coffee winbindd[890]: daemon_ready: STATUS=daemon 'winbindd' finished starting up and ready to serve connections Apr 13 21:46:19 coffee systemd[1]: Started Samba Winbind Daemon. Apr 13 21:46:19 coffee systemd[1]: Starting Samba SMB Daemon... Apr 13 21:46:19 coffee startx[835]: Require OpenGL version 2.1 or later. Apr 13 21:46:19 coffee startx[835]: (EE) Apr 13 21:46:19 coffee startx[835]: Fatal server error: Apr 13 21:46:19 coffee startx[835]: (EE) AddScreen/ScreenInit failed for driver 0 Apr 13 21:46:19 coffee startx[835]: (EE) Apr 13 21:46:19 coffee startx[835]: Please consult the The X.Org Foundation support Apr 13 21:46:19 coffee startx[835]: at http://wiki.x.org Apr 13 21:46:19 coffee startx[835]: for help. Apr 13 21:46:19 coffee startx[835]: (EE) Please also check the log file at "/var/log/Xorg.0.log" for additional information. Apr 13 21:46:19 coffee startx[835]: (EE) Apr 13 21:46:19 coffee startx[835]: (EE) Server terminated with error (1). Closing log file. Apr 13 21:46:20 coffee ntpd[830]: Soliciting pool server 23.150.40.242 Apr 13 21:46:20 coffee systemd[1]: soundcard-init.service: Succeeded. Apr 13 21:46:20 coffee winbindd[890]: [2024/04/13 21:46:20.821657, 0] ../source3/winbindd/wb_lookupsids.c:659(wb_lookupsids_recv) Apr 13 21:46:20 coffee winbindd[890]: res_names->count = 3, expected 4 Apr 13 21:46:20 coffee systemd[1]: Started Samba SMB Daemon. Apr 13 21:46:20 coffee smbd[940]: [2024/04/13 21:46:20.885611, 0] ../lib/util/become_daemon.c:138(daemon_ready) Apr 13 21:46:20 coffee systemd[1]: Reached target Multi-User System. Apr 13 21:46:20 coffee smbd[940]: daemon_ready: STATUS=daemon 'smbd' finished starting up and ready to serve connections Apr 13 21:46:20 coffee systemd[1]: Reached target Graphical Interface. Apr 13 21:46:20 coffee systemd[1]: Starting Update UTMP about System Runlevel Changes... Apr 13 21:46:21 coffee systemd[1]: systemd-update-utmp-runlevel.service: Succeeded. Apr 13 21:46:21 coffee systemd[1]: Started Update UTMP about System Runlevel Changes. Apr 13 21:46:21 coffee systemd[1]: Startup finished in 27.340s (kernel) + 39.770s (userspace) = 1min 7.111s. Apr 13 21:46:22 coffee volumio-remote-updater[463]: [2024-04-13 21:46:22] [connect] Successful connection Apr 13 21:46:22 coffee volumio[834]: info: ------------------------------------------- Apr 13 21:46:22 coffee volumio[834]: info: ----- Volumio3 ---- Apr 13 21:46:22 coffee volumio[834]: info: ------------------------------------------- Apr 13 21:46:22 coffee volumio[834]: info: ----- System startup ---- Apr 13 21:46:22 coffee volumio[834]: info: ------------------------------------------- Apr 13 21:46:24 coffee volumio[834]: info: MYVOLUMIO Environment detected Apr 13 21:46:24 coffee volumio[834]: info: Plugin folders cleanup Apr 13 21:46:24 coffee volumio[834]: info: Scanning into folder /volumio/app/plugins/ Apr 13 21:46:24 coffee volumio[834]: info: Scanning category audio_interface Apr 13 21:46:24 coffee volumio[834]: info: Scanning category miscellanea Apr 13 21:46:24 coffee volumio[834]: info: Scanning category music_service Apr 13 21:46:24 coffee volumio[834]: info: Scanning category plugins.json Apr 13 21:46:24 coffee volumio[834]: info: Scanning category system_controller Apr 13 21:46:24 coffee volumio[834]: info: Scanning category user_interface Apr 13 21:46:24 coffee volumio[834]: info: Scanning into folder /data/plugins/ Apr 13 21:46:24 coffee volumio[834]: info: Scanning category music_service Apr 13 21:46:24 coffee volumio[834]: info: Scanning category user_interface Apr 13 21:46:24 coffee volumio[834]: info: Plugin folders cleanup completed Apr 13 21:46:24 coffee volumio[834]: info: ------------------------------------------- Apr 13 21:46:24 coffee volumio[834]: info: ----- Core plugins startup ---- Apr 13 21:46:24 coffee volumio[834]: info: ------------------------------------------- Apr 13 21:46:24 coffee volumio[834]: info: Loading plugins from folder /volumio/app/plugins/ Apr 13 21:46:24 coffee volumio[834]: info: Adding plugin upnp to MyMusic Plugins Apr 13 21:46:24 coffee volumio[834]: info: Adding plugin airplay_emulation to MyMusic Plugins Apr 13 21:46:24 coffee volumio[834]: info: Adding plugin upnp_browser to MyMusic Plugins Apr 13 21:46:24 coffee volumio[834]: info: Loading plugins from folder /data/plugins/ Apr 13 21:46:24 coffee volumio[834]: info: Loading plugin "system"... Apr 13 21:46:24 coffee volumio[834]: info: Loading plugin "appearance"... Apr 13 21:46:26 coffee volumio[834]: info: Loading plugin "network"... Apr 13 21:46:26 coffee volumio[834]: info: Refreshing Cached IP Addresses Apr 13 21:46:26 coffee sudo[990]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Apr 13 21:46:27 coffee sudo[990]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 13 21:46:27 coffee volumio[834]: info: Loading plugin "services"... Apr 13 21:46:27 coffee sudo[990]: pam_unix(sudo:session): session closed for user root Apr 13 21:46:27 coffee volumio[834]: info: Loading plugin "alsa_controller"... Apr 13 21:46:27 coffee sudo[992]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Apr 13 21:46:27 coffee sudo[992]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 13 21:46:27 coffee sudo[992]: pam_unix(sudo:session): session closed for user root Apr 13 21:46:27 coffee sudo[994]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Apr 13 21:46:27 coffee sudo[994]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 13 21:46:27 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Apr 13 21:46:27 coffee volumio[834]: info: Loading plugin "wizard"... Apr 13 21:46:27 coffee systemd[1]: systemd-fsckd.service: Succeeded. Apr 13 21:46:27 coffee volumio[834]: info: Loading plugin "networkfs"... Apr 13 21:46:27 coffee volumio[834]: info: Starting Udev Watcher for removable devices Apr 13 21:46:27 coffee volumio[834]: info: Ignoring mount for partition: boot Apr 13 21:46:27 coffee volumio[834]: info: Ignoring mount for partition: volumio Apr 13 21:46:27 coffee volumio[834]: info: Ignoring mount for partition: volumio_data Apr 13 21:46:27 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Apr 13 21:46:27 coffee volumio[834]: info: Loading plugin "volumio_command_line_client"... Apr 13 21:46:27 coffee volumio[834]: info: Loading plugin "upnp"... Apr 13 21:46:27 coffee volumio[834]: info: [1713069987374] Starting Upmpd Daemon Apr 13 21:46:27 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Apr 13 21:46:27 coffee volumio[834]: info: Loading plugin "my_music"... Apr 13 21:46:27 coffee volumio[834]: info: Loading plugin "mpd"... Apr 13 21:46:27 coffee ntpd[830]: receive: Unexpected origin timestamp 0xe9c5de21.0526e32a does not match aorg 0xe9c5de23.05274b16 from server@65.100.46.166 xmt 0xe9c5de20.fd65c4e4 Apr 13 21:46:27 coffee ntpd[830]: Soliciting pool server 159.203.82.102 Apr 13 21:46:28 coffee ntpd[830]: Soliciting pool server 137.184.81.69 Apr 13 21:46:28 coffee volumio[834]: info: Loading plugin "upnp_browser"... Apr 13 21:46:28 coffee ntpd[830]: Soliciting pool server 208.67.75.242 Apr 13 21:46:28 coffee volumio[834]: info: Loading plugin "alarm-clock"... Apr 13 21:46:28 coffee volumio[834]: info: Loading plugin "airplay_emulation"... Apr 13 21:46:28 coffee volumio[834]: info: Starting Shairport Sync Apr 13 21:46:28 coffee volumio[834]: info: Loading plugin "last_100"... Apr 13 21:46:28 coffee volumio[834]: info: Loading plugin "webradio"... Apr 13 21:46:29 coffee ntpd[830]: Soliciting pool server 207.246.65.226 Apr 13 21:46:29 coffee volumio[834]: info: Loading plugin "i2s_dacs"... Apr 13 21:46:29 coffee volumio[834]: info: I2S DAC not set, start Auto-detection Apr 13 21:46:29 coffee volumio[834]: info: Loading plugin "volumiodiscovery"... Apr 13 21:46:29 coffee sh[387]: timed out Apr 13 21:46:29 coffee sh[387]: dhcpcd exited Apr 13 21:46:29 coffee dhcpcd[435]: timed out Apr 13 21:46:29 coffee dhcpcd[435]: dhcpcd exited Apr 13 21:46:29 coffee sh[387]: ifup: failed to bring up eth0 Apr 13 21:46:29 coffee systemd[1]: ifup@eth0.service: Main process exited, code=exited, status=1/FAILURE Apr 13 21:46:29 coffee systemd[1]: ifup@eth0.service: Failed with result 'exit-code'. Apr 13 21:46:29 coffee volumio[834]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Apr 13 21:46:29 coffee volumio[834]: *** WARNING *** Please fix your application to use the native API of Avahi! Apr 13 21:46:29 coffee node[834]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Apr 13 21:46:29 coffee volumio[834]: *** WARNING *** For more information see Apr 13 21:46:29 coffee volumio[834]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Apr 13 21:46:29 coffee volumio[834]: *** WARNING *** Please fix your application to use the native API of Avahi! Apr 13 21:46:29 coffee volumio[834]: *** WARNING *** For more information see Apr 13 21:46:29 coffee node[834]: *** WARNING *** Please fix your application to use the native API of Avahi! Apr 13 21:46:29 coffee node[834]: *** WARNING *** For more information see Apr 13 21:46:29 coffee node[834]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Apr 13 21:46:29 coffee node[834]: *** WARNING *** Please fix your application to use the native API of Avahi! Apr 13 21:46:29 coffee node[834]: *** WARNING *** For more information see Apr 13 21:46:29 coffee sudo[994]: pam_unix(sudo:session): session closed for user root Apr 13 21:46:29 coffee volumio[834]: info: Applying required configuration parameters for plugin volumiodiscovery Apr 13 21:46:29 coffee volumio[834]: info: Discovery: Started advertising with name: coffee Apr 13 21:46:29 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Apr 13 21:46:29 coffee volumio[834]: info: Loading plugin "spop"... Apr 13 21:46:30 coffee ntpd[830]: Soliciting pool server 73.193.62.54 Apr 13 21:46:30 coffee ntpd[830]: Soliciting pool server 23.157.160.168 Apr 13 21:46:30 coffee systemd[1]: systemd-hostnamed.service: Succeeded. Apr 13 21:46:31 coffee ntpd[830]: Soliciting pool server 51.81.226.229 Apr 13 21:46:31 coffee ntpd[830]: Soliciting pool server 108.61.73.244 Apr 13 21:46:31 coffee volumio[834]: info: Loading plugin "youtube2"... Apr 13 21:46:32 coffee ntpd[830]: Soliciting pool server 162.159.200.1 Apr 13 21:46:32 coffee ntpd[830]: Soliciting pool server 2603:c020:0:8369:1111:1111:1111:1112 Apr 13 21:46:32 coffee startx[835]: xinit: giving up Apr 13 21:46:32 coffee startx[835]: xinit: unable to connect to X server: Connection refused Apr 13 21:46:32 coffee startx[835]: xinit: server error Apr 13 21:46:32 coffee systemd[1]: volumio-kiosk.service: Main process exited, code=exited, status=1/FAILURE Apr 13 21:46:32 coffee systemd[1]: volumio-kiosk.service: Failed with result 'exit-code'. Apr 13 21:46:33 coffee volumio[834]: info: Loading plugin "ytcr"... Apr 13 21:46:37 coffee volumio-remote-updater[463]: [2024-04-13 21:46:37] [connect] Successful connection Apr 13 21:46:38 coffee volumio[834]: info: Loading plugin "ytmusic"... Apr 13 21:46:40 coffee volumio[834]: info: Loading plugin "outputs"... Apr 13 21:46:40 coffee volumio[834]: info: Loading plugin "albumart"... Apr 13 21:46:40 coffee volumio[834]: info: Plugin example_plugin is not enabled Apr 13 21:46:40 coffee volumio[834]: info: Loading plugin "inputs"... Apr 13 21:46:40 coffee volumio[834]: info: Loading plugin "updater_comm"... Apr 13 21:46:40 coffee volumio[834]: info: Plugin mpdemulation is not enabled Apr 13 21:46:40 coffee volumio[834]: info: Loading plugin "rest_api"... Apr 13 21:46:40 coffee volumio[834]: info: Loading plugin "websocket"... Apr 13 21:46:40 coffee volumio[834]: info: Loading plugin "Systeminfo"... Apr 13 21:46:40 coffee volumio[834]: Forking 1 albumart workers Apr 13 21:46:41 coffee volumio[834]: info: Loading i18n strings for locale en Apr 13 21:46:41 coffee volumio[834]: Updating browse sources language Apr 13 21:46:41 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 13 21:46:41 coffee volumio[834]: Starting albumart workers Apr 13 21:46:42 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Apr 13 21:46:42 coffee volumio[834]: info: CoreCommandRouter::initPlayerControls Apr 13 21:46:42 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 13 21:46:42 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 13 21:46:42 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 13 21:46:42 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 13 21:46:42 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 13 21:46:42 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 13 21:46:42 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Apr 13 21:46:42 coffee volumio[834]: Express server listening on port 3000 Apr 13 21:46:42 coffee volumio[834]: [Metrics] WebUI: 20s 656.11ms Apr 13 21:46:42 coffee volumio[834]: info: Setting Device type: x86 Apr 13 21:46:42 coffee volumio[834]: info: CoreStateMachine::resetVolumioState Apr 13 21:46:42 coffee volumio[834]: info: CoreStateMachine::getcurrentVolume Apr 13 21:46:42 coffee volumio[834]: info: CoreCommandRouter::volumioRetrievevolume Apr 13 21:46:42 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 13 21:46:42 coffee sudo[1024]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Apr 13 21:46:42 coffee sudo[1024]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 13 21:46:42 coffee sudo[1024]: pam_unix(sudo:session): session closed for user root Apr 13 21:46:42 coffee volumio[834]: error: Cannot read config.txt file: Error: ENOENT: no such file or directory, open '/boot/config.txt' Apr 13 21:46:42 coffee volumio[834]: info: Completed loading Core Plugins Apr 13 21:46:42 coffee sudo[1027]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Apr 13 21:46:42 coffee sudo[1027]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 13 21:46:42 coffee volumio[834]: info: Preparing to generate the ALSA configuration file Apr 13 21:46:42 coffee sudo[1027]: pam_unix(sudo:session): session closed for user root Apr 13 21:46:42 coffee volumio[834]: info: Cannot read proc/cpuinfo: Error: Command failed: cat /proc/cpuinfo | grep Revision Apr 13 21:46:43 coffee volumio[834]: info: VolumeController:: Volume=100 Mute =false Apr 13 21:46:43 coffee volumio[834]: info: CoreStateMachine::pushState Apr 13 21:46:43 coffee volumio[834]: info: CorePlayQueue::getTrack 0 Apr 13 21:46:43 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 13 21:46:43 coffee volumio[834]: info: CoreCommandRouter::volumioPushState Apr 13 21:46:43 coffee volumio[834]: info: CoreStateMachine::updateTrackBlock Apr 13 21:46:43 coffee volumio[834]: info: CorePlayQueue::getTrackBlock Apr 13 21:46:43 coffee volumio[834]: info: CoreCommandRouter::volumioRetrievevolume Apr 13 21:46:43 coffee volumio[834]: info: Reloading queue from file Apr 13 21:46:43 coffee volumio[834]: info: Asound.conf file unchanged, so no further update is needed Apr 13 21:46:43 coffee volumio[834]: info: Output device has changed, restarting MPD Apr 13 21:46:43 coffee sudo[1045]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Apr 13 21:46:43 coffee volumio[834]: info: Output device has changed, restarting Shairport Sync Apr 13 21:46:43 coffee sudo[1045]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 13 21:46:43 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 13 21:46:43 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 13 21:46:43 coffee sudo[1045]: pam_unix(sudo:session): session closed for user root Apr 13 21:46:43 coffee sudo[1047]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Apr 13 21:46:43 coffee sudo[1047]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 13 21:46:43 coffee volumio[834]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Apr 13 21:46:43 coffee systemd[1]: Listening on mpd.socket. Apr 13 21:46:43 coffee volumio[834]: info: ___________ START PLUGINS ___________ Apr 13 21:46:43 coffee volumio[834]: info: ControllerMpd::onStart: Initializing MPD Apr 13 21:46:43 coffee volumio[834]: info: Creating MPD Configuration file Apr 13 21:46:43 coffee systemd[1]: Starting Music Player Daemon... Apr 13 21:46:43 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Apr 13 21:46:43 coffee volumio[834]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Apr 13 21:46:43 coffee volumio[834]: info: [1713070003486] CoreMusicLibrary::Adding element Media Servers Apr 13 21:46:43 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 13 21:46:43 coffee sudo[1055]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Apr 13 21:46:43 coffee sudo[1055]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 13 21:46:43 coffee sudo[1057]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Apr 13 21:46:43 coffee sudo[1057]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 13 21:46:43 coffee sudo[1055]: pam_unix(sudo:session): session closed for user root Apr 13 21:46:43 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 13 21:46:43 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 13 21:46:43 coffee systemd[1]: mpd.service: Main process exited, code=killed, status=15/TERM Apr 13 21:46:43 coffee systemd[1]: mpd.service: Succeeded. Apr 13 21:46:43 coffee systemd[1]: Stopped Music Player Daemon. Apr 13 21:46:43 coffee systemd[1]: Starting Music Player Daemon... Apr 13 21:46:43 coffee volumio[834]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Apr 13 21:46:43 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 13 21:46:43 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 13 21:46:43 coffee volumio[834]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Apr 13 21:46:43 coffee volumio[834]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Apr 13 21:46:43 coffee volumio[834]: info: [1713070003808] CoreMusicLibrary::Adding element Last_100 Apr 13 21:46:43 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 13 21:46:43 coffee volumio[834]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Apr 13 21:46:43 coffee volumio[834]: info: [1713070003816] CoreMusicLibrary::Adding element Webradio Apr 13 21:46:43 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 13 21:46:43 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Apr 13 21:46:43 coffee volumio[834]: info: Creating Spotify config file Apr 13 21:46:43 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 13 21:46:44 coffee volumio[834]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Apr 13 21:46:44 coffee volumio[834]: info: [1713070004090] CoreMusicLibrary::Adding element YouTube2 Apr 13 21:46:44 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 13 21:46:44 coffee volumio[834]: Cannot find translation for source YouTube2 Apr 13 21:46:44 coffee volumio[834]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Apr 13 21:46:44 coffee volumio[834]: info: [1713070004289] CoreMusicLibrary::Adding element YouTube Music Apr 13 21:46:44 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 13 21:46:44 coffee volumio[834]: Cannot find translation for source YouTube2 Apr 13 21:46:44 coffee volumio[834]: Cannot find translation for source YouTube Music Apr 13 21:46:44 coffee volumio[834]: info: Volumio Calling Home Apr 13 21:46:44 coffee volumio[834]: info: CoreStateMachine::setRepeat null single undefined Apr 13 21:46:44 coffee volumio[834]: info: CoreStateMachine::pushState Apr 13 21:46:44 coffee volumio[834]: info: CorePlayQueue::getTrack 0 Apr 13 21:46:44 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 13 21:46:44 coffee volumio[834]: info: CoreCommandRouter::volumioPushState Apr 13 21:46:44 coffee volumio[834]: info: CoreStateMachine::setRandom null Apr 13 21:46:44 coffee volumio[834]: info: CoreStateMachine::pushState Apr 13 21:46:44 coffee volumio[834]: info: CorePlayQueue::getTrack 0 Apr 13 21:46:44 coffee volumio[834]: info: CoreCommandRouter::volumioPushState Apr 13 21:46:44 coffee volumio[834]: info: MPD Permissions set Apr 13 21:46:44 coffee volumio[834]: info: MPD Permissions set Apr 13 21:46:44 coffee volumio[834]: info: VolumeController:: Volume=100 Mute =false Apr 13 21:46:44 coffee volumio[834]: info: CoreCommandRouter::volumioGetState Apr 13 21:46:44 coffee sudo[1073]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Apr 13 21:46:44 coffee sudo[1073]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 13 21:46:44 coffee volumio[834]: info: CorePlayQueue::getTrack 0 Apr 13 21:46:44 coffee volumio[834]: info: CoreStateMachine::pushState Apr 13 21:46:44 coffee volumio[834]: info: CorePlayQueue::getTrack 0 Apr 13 21:46:44 coffee volumio[834]: info: CoreCommandRouter::volumioPushState Apr 13 21:46:44 coffee volumio[834]: info: Spotify config file written Apr 13 21:46:44 coffee systemd[1]: Started UPnP Renderer front-end to MPD. Apr 13 21:46:44 coffee sudo[1073]: pam_unix(sudo:session): session closed for user root Apr 13 21:46:44 coffee sudo[1077]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Apr 13 21:46:44 coffee sudo[1077]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 13 21:46:45 coffee volumio[834]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 1 Apr 13 21:46:45 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 13 21:46:45 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 13 21:46:45 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 13 21:46:45 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 13 21:46:45 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 13 21:46:45 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: system , getCPUCoresNumber Apr 13 21:46:45 coffee systemd[1]: Started go-librespot Daemon. Apr 13 21:46:45 coffee go-librespot[1084]: Librespot-go daemon starting... Apr 13 21:46:45 coffee sudo[1077]: pam_unix(sudo:session): session closed for user root Apr 13 21:46:45 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 13 21:46:45 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 13 21:46:45 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 13 21:46:45 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 13 21:46:45 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 13 21:46:45 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 13 21:46:45 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 13 21:46:45 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 13 21:46:45 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 13 21:46:45 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 13 21:46:45 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: system , getCPUCoresNumber Apr 13 21:46:45 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 13 21:46:45 coffee volumio[834]: info: Discovery: Browse raised the following error Error: getaddrinfo -3007 Apr 13 21:46:45 coffee volumio[834]: info: Discovery: Browse raised the following error Error: getaddrinfo -3007 Apr 13 21:46:45 coffee volumio[834]: info: Volumio called home Apr 13 21:46:45 coffee volumio[834]: info: Upmpdcli Daemon Started Apr 13 21:46:45 coffee volumio[834]: info: Starting Shairport Sync Apr 13 21:46:45 coffee volumio[834]: info: Starting Shairport Sync Apr 13 21:46:45 coffee sudo[1099]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Apr 13 21:46:45 coffee sudo[1099]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 13 21:46:45 coffee volumio[834]: info: Starting Shairport Sync Apr 13 21:46:45 coffee systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Apr 13 21:46:45 coffee systemd[1]: shairport-sync.service: Succeeded. Apr 13 21:46:45 coffee systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Apr 13 21:46:45 coffee systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Apr 13 21:46:45 coffee sudo[1102]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Apr 13 21:46:45 coffee sudo[1102]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 13 21:46:45 coffee sudo[1099]: pam_unix(sudo:session): session closed for user root Apr 13 21:46:45 coffee systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Apr 13 21:46:45 coffee systemd[1]: shairport-sync.service: Succeeded. Apr 13 21:46:45 coffee systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Apr 13 21:46:45 coffee sudo[1105]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Apr 13 21:46:45 coffee sudo[1105]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 13 21:46:45 coffee volumio[834]: info: Shairport-Sync Started Apr 13 21:46:45 coffee volumio[834]: Error adding Membership: Error: addMembership EINVAL Apr 13 21:46:45 coffee systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Apr 13 21:46:45 coffee sudo[1102]: pam_unix(sudo:session): session closed for user root Apr 13 21:46:46 coffee volumio[834]: info: CoreCommandRouter::volumioGetState Apr 13 21:46:46 coffee volumio[834]: info: CorePlayQueue::getTrack 0 Apr 13 21:46:46 coffee systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Apr 13 21:46:46 coffee systemd[1]: shairport-sync.service: Main process exited, code=killed, status=15/TERM Apr 13 21:46:46 coffee systemd[1]: shairport-sync.service: Succeeded. Apr 13 21:46:46 coffee systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Apr 13 21:46:46 coffee systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Apr 13 21:46:46 coffee sudo[1105]: pam_unix(sudo:session): session closed for user root Apr 13 21:46:46 coffee volumio[834]: info: Shairport-Sync Started Apr 13 21:46:46 coffee volumio[834]: info: Shairport-Sync Started Apr 13 21:46:46 coffee go-librespot[1084]: time="2024-04-13T21:46:46-07:00" level=info msg="generated new device id: daf0ad49b4b2fdea4df971305d869499fc2f73be" Apr 13 21:46:46 coffee go-librespot[1084]: time="2024-04-13T21:46:46-07:00" level=debug msg="stored credentials found for 31yzys2yngvcw4bum242ekfnfzrq" Apr 13 21:46:48 coffee volumio[834]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Apr 13 21:46:48 coffee volumio[834]: SPOTIFY: BQBqwVt9_kDy5pmWpLfNzNAFBkFueksimFcGWIqdsPyUOxf795umd7bQ05-0HSHy4LSdVY2QMl3CiTNY7o3xBNh6Ncrf2Nm7BG0m7K3mENEju6UTABjufAt1fZNlpYJV1mG4YWoy7mMxQhxXwYHz6o8xQV-VDse8o4HBCbnjy2O7Rnb1_Ldlw0Kx7RDPfyROjf1PYoD_UdDAfDiCyOdPO38xr9OemZJB4Ssprb6Mla7tf7j0iOck_KQ9rhDvxtUBsRT42QzGUyk Apr 13 21:46:48 coffee volumio[834]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Apr 13 21:46:48 coffee volumio[834]: info: New Spotify access token = BQBqwVt9_kDy5pmWpLfNzNAFBkFueksimFcGWIqdsPyUOxf795umd7bQ05-0HSHy4LSdVY2QMl3CiTNY7o3xBNh6Ncrf2Nm7BG0m7K3mENEju6UTABjufAt1fZNlpYJV1mG4YWoy7mMxQhxXwYHz6o8xQV-VDse8o4HBCbnjy2O7Rnb1_Ldlw0Kx7RDPfyROjf1PYoD_UdDAfDiCyOdPO38xr9OemZJB4Ssprb6Mla7tf7j0iOck_KQ9rhDvxtUBsRT42QzGUyk Apr 13 21:46:48 coffee volumio[834]: info: Spotify credentials grant success - running version from March 24, 2019 Apr 13 21:46:48 coffee go-librespot[1084]: time="2024-04-13T21:46:48-07:00" level=debug msg="obtained new client token: AADKA5oUHgh42KY+Bk6GKAewumYWxiHtup9SCejTDQGlv+wHx0TKG+1DZ0OL+dLVoar2VfuXi1swll+IPaJfHUPjq+VI+IDaRACU3RZqjEkqWSAARgfmFIRLX2a7KOee+xA5pHDdloPiLxBVClmGcYZRNXChogJxq4/CNw1lnppC0xM51IpzDJEXbarx0ozeoZNh6R9A0Pjm7FhF0vM9CgMNSh8Q5UKHjSBqZfCwUdtUITttkGQJkUOSdMgjfA==" Apr 13 21:46:48 coffee go-librespot[1084]: time="2024-04-13T21:46:48-07:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 13 21:46:48 coffee volumio[834]: info: go-librespot daemon successfully initialized Apr 13 21:46:48 coffee sudo[1116]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Apr 13 21:46:48 coffee sudo[1116]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 13 21:46:48 coffee sudo[1114]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Apr 13 21:46:48 coffee sudo[1114]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 13 21:46:48 coffee go-librespot[1084]: time="2024-04-13T21:46:48-07:00" level=debug msg="completed keyexchange" Apr 13 21:46:48 coffee sudo[1114]: pam_unix(sudo:session): session closed for user root Apr 13 21:46:48 coffee sudo[1116]: pam_unix(sudo:session): session closed for user root Apr 13 21:46:48 coffee volumio[834]: SPOTIFY: User informations: {"display_name":"SweetJudo","external_urls":{"spotify":"https://open.spotify.com/user/31yzys2yngvcw4bum242ekfnfzrq"},"href":"https://api.spotify.com/v1/users/31yzys2yngvcw4bum242ekfnfzrq","id":"31yzys2yngvcw4bum242ekfnfzrq","images":[],"type":"user","uri":"spotify:user:31yzys2yngvcw4bum242ekfnfzrq","followers":{"href":null,"total":1},"country":"US","product":"premium","explicit_content":{"filter_enabled":false,"filter_locked":false},"email":"sweetjudo@icloud.com"} Apr 13 21:46:48 coffee volumio[834]: info: Spotify Successfully logged in Apr 13 21:46:48 coffee volumio[834]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Apr 13 21:46:48 coffee volumio[834]: info: [1713070008713] CoreMusicLibrary::Adding element Spotify Apr 13 21:46:48 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 13 21:46:48 coffee volumio[834]: Cannot find translation for source YouTube2 Apr 13 21:46:48 coffee volumio[834]: Cannot find translation for source YouTube Music Apr 13 21:46:48 coffee volumio[834]: Cannot find translation for source Spotify Apr 13 21:46:49 coffee go-librespot[1084]: time="2024-04-13T21:46:49-07:00" level=debug msg="completed challenge" Apr 13 21:46:49 coffee volumio[834]: verbose: New Socket.io Connection to 192.168.50.110 from 192.168.50.177 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/123.0.0.0 Safari/537.36 Edg/123.0.0.0 Total Clients: 2 Apr 13 21:46:49 coffee go-librespot[1084]: time="2024-04-13T21:46:49-07:00" level=debug msg="authenticated as 31yzys2yngvcw4bum242ekfnfzrq" Apr 13 21:46:49 coffee go-librespot[1084]: time="2024-04-13T21:46:49-07:00" level=debug msg="authenticated as 31yzys2yngvcw4bum242ekfnfzrq" Apr 13 21:46:49 coffee volumio[834]: info: [yt-cast-receiver] DIAL server listening on port 8098 Apr 13 21:46:49 coffee sudo[1122]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Apr 13 21:46:50 coffee sudo[1122]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 13 21:46:50 coffee sudo[1122]: pam_unix(sudo:session): session closed for user root Apr 13 21:46:50 coffee sudo[1120]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Apr 13 21:46:50 coffee sudo[1120]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 13 21:46:50 coffee sudo[1120]: pam_unix(sudo:session): session closed for user root Apr 13 21:46:50 coffee go-librespot[1084]: time="2024-04-13T21:46:50-07:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Apr 13 21:46:50 coffee mpd[1063]: Apr 13 21:46 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Apr 13 21:46:50 coffee systemd[1]: Started Music Player Daemon. Apr 13 21:46:50 coffee volumio[834]: Upnp client error: Error: This socket has been ended by the other party Apr 13 21:46:50 coffee sudo[1047]: pam_unix(sudo:session): session closed for user root Apr 13 21:46:50 coffee sudo[1057]: pam_unix(sudo:session): session closed for user root Apr 13 21:46:51 coffee volumio[834]: info: Completed starting Core Plugins Apr 13 21:46:51 coffee volumio[834]: info: ------------------------------------------- Apr 13 21:46:51 coffee volumio[834]: info: ----- MyVolumio plugins startup ---- Apr 13 21:46:51 coffee volumio[834]: info: ------------------------------------------- Apr 13 21:46:51 coffee volumio[834]: info: [MyVolumio PluginManager] Fetching plans data.... Apr 13 21:46:51 coffee volumio[834]: error: MPD error: The expression evaluated to a falsy value: Apr 13 21:46:51 coffee volumio[834]: assert.ok(self.idling) Apr 13 21:46:51 coffee volumio[834]: error: The expression evaluated to a falsy value: Apr 13 21:46:51 coffee volumio[834]: assert.ok(self.idling) Apr 13 21:46:51 coffee volumio[834]: info: MPD running with PID1063 Apr 13 21:46:51 coffee volumio[834]: ,establishing connection Apr 13 21:46:51 coffee volumio[834]: error: MPD error: The expression evaluated to a falsy value: Apr 13 21:46:51 coffee volumio[834]: assert.ok(self.idling) Apr 13 21:46:51 coffee volumio[834]: error: The expression evaluated to a falsy value: Apr 13 21:46:51 coffee volumio[834]: assert.ok(self.idling) Apr 13 21:46:51 coffee volumio[834]: error: updateQueue error: null Apr 13 21:46:51 coffee volumio[1075]: Generating RSA private key, 4096 bit long modulus (2 primes) Apr 13 21:46:51 coffee volumio[834]: info: Initializing connection to go-librespot Websocket Apr 13 21:46:51 coffee go-librespot[1084]: time="2024-04-13T21:46:51-07:00" level=debug msg="new websocket client" Apr 13 21:46:51 coffee volumio[834]: info: Connection to go-librespot Websocket established Apr 13 21:46:51 coffee go-librespot[1084]: time="2024-04-13T21:46:51-07:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Apr 13 21:46:52 coffee volumio-remote-updater[463]: [2024-04-13 21:46:52] [connect] Successful connection Apr 13 21:46:52 coffee volumio-remote-updater[463]: [2024-04-13 21:46:52] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1713070012 101 Apr 13 21:46:52 coffee volumio[834]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Total Clients: 3 Apr 13 21:46:53 coffee volumio[1075]: ........................++++ Apr 13 21:46:53 coffee go-librespot[1084]: time="2024-04-13T21:46:53-07:00" level=debug msg="dealer connection opened" Apr 13 21:46:53 coffee go-librespot[1084]: time="2024-04-13T21:46:53-07:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Apr 13 21:46:53 coffee go-librespot[1084]: time="2024-04-13T21:46:53-07:00" level=debug msg="received connection id: ODFkNzcxYTYtOGFiYS00YzdlLTg1MzYtYjc1ZWFlNTVmN2E4K2RlYWxlcit0Y3A6Ly9ndWMzLWRlYWxlci1hLWh6cmQuZ3VjMy5zcG90aWZ5Lm5ldDo1NzAwKzhEQTI1Q0U4QkRGOEExOTg4MTNGMEZDNDY5RUQyMEQ3ODUwMEEyREYzMTZGOTJBOTY2NzZGRDBEM0M1Q0QyNjI=" Apr 13 21:46:53 coffee go-librespot[1084]: time="2024-04-13T21:46:53-07:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Apr 13 21:46:53 coffee go-librespot[1084]: time="2024-04-13T21:46:53-07:00" level=debug msg="put connect state because NEW_DEVICE" Apr 13 21:46:53 coffee go-librespot[1084]: time="2024-04-13T21:46:53-07:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Apr 13 21:46:53 coffee go-librespot[1084]: time="2024-04-13T21:46:53-07:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Apr 13 21:46:53 coffee go-librespot[1084]: time="2024-04-13T21:46:53-07:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 517" Apr 13 21:46:54 coffee volumio[834]: verbose: New Socket.io Connection to 192.168.50.110 from 192.168.50.177 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/123.0.0.0 Safari/537.36 Edg/123.0.0.0 Total Clients: 4 Apr 13 21:46:54 coffee volumio[834]: verbose: New Socket.io Connection to 192.168.50.110 from 192.168.50.177 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/123.0.0.0 Safari/537.36 Edg/123.0.0.0 Total Clients: 5 Apr 13 21:46:54 coffee volumio[834]: info: Getting Spotify volume Apr 13 21:46:54 coffee volumio[834]: info: Spotify volume: 100 Apr 13 21:46:54 coffee volumio[834]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 6 Apr 13 21:46:54 coffee volumio[834]: info: CoreCommandRouter::volumioGetState Apr 13 21:46:54 coffee volumio[834]: info: CorePlayQueue::getTrack 0 Apr 13 21:46:54 coffee volumio[834]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 13 21:46:56 coffee volumio[834]: verbose: New Socket.io Connection to 192.168.50.110 from 192.168.50.177 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/123.0.0.0 Safari/537.36 Edg/123.0.0.0 Total Clients: 7 Apr 13 21:46:56 coffee volumio[834]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Apr 13 21:46:56 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Apr 13 21:46:56 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Apr 13 21:46:56 coffee volumio[834]: info: CoreCommandRouter::volumioGetVisibleSources Apr 13 21:46:56 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 13 21:46:56 coffee volumio[834]: info: CoreCommandRouter::volumioGetState Apr 13 21:46:56 coffee volumio[834]: info: CorePlayQueue::getTrack 0 Apr 13 21:46:56 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Apr 13 21:46:56 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Apr 13 21:46:56 coffee volumio[834]: info: Received Get System Info Apr 13 21:46:56 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 13 21:46:56 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 13 21:46:56 coffee volumio[834]: info: Discovery: Getting this device information Apr 13 21:46:56 coffee volumio[834]: info: CoreCommandRouter::volumioGetState Apr 13 21:46:56 coffee volumio[834]: info: CorePlayQueue::getTrack 0 Apr 13 21:46:56 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 13 21:46:56 coffee volumio[834]: info: CoreCommandRouter::volumioGetState Apr 13 21:46:56 coffee volumio[834]: info: CorePlayQueue::getTrack 0 Apr 13 21:46:56 coffee volumio[834]: info: Listing playlists Apr 13 21:46:56 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Apr 13 21:46:56 coffee volumio[834]: info: Received Get System Info Apr 13 21:46:56 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 13 21:46:56 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 13 21:46:56 coffee volumio[834]: info: Discovery: Getting this device information Apr 13 21:46:56 coffee volumio[834]: info: CoreCommandRouter::volumioGetState Apr 13 21:46:56 coffee volumio[834]: info: CorePlayQueue::getTrack 0 Apr 13 21:46:56 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 13 21:46:56 coffee volumio[834]: info: CoreCommandRouter::volumioGetState Apr 13 21:46:56 coffee volumio[834]: info: CorePlayQueue::getTrack 0 Apr 13 21:46:56 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Apr 13 21:46:56 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Apr 13 21:46:56 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Apr 13 21:46:56 coffee volumio[834]: info: Received Get System Info Apr 13 21:46:56 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 13 21:46:56 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 13 21:46:56 coffee volumio[834]: info: Discovery: Getting this device information Apr 13 21:46:56 coffee volumio[834]: info: CoreCommandRouter::volumioGetState Apr 13 21:46:56 coffee volumio[834]: info: CorePlayQueue::getTrack 0 Apr 13 21:46:56 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 13 21:46:56 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Apr 13 21:46:56 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Apr 13 21:46:56 coffee volumio[834]: info: CoreCommandRouter::volumioGetVisibleSources Apr 13 21:46:56 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 13 21:46:56 coffee volumio[834]: info: CoreCommandRouter::volumioGetState Apr 13 21:46:56 coffee volumio[834]: info: CorePlayQueue::getTrack 0 Apr 13 21:46:56 coffee volumio[834]: info: CoreCommandRouter::volumioGetState Apr 13 21:46:56 coffee volumio[834]: info: CorePlayQueue::getTrack 0 Apr 13 21:46:56 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Apr 13 21:46:56 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Apr 13 21:46:56 coffee volumio[834]: info: Received Get System Info Apr 13 21:46:56 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 13 21:46:56 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 13 21:46:56 coffee volumio[834]: info: Discovery: Getting this device information Apr 13 21:46:56 coffee volumio[834]: info: CoreCommandRouter::volumioGetState Apr 13 21:46:56 coffee volumio[834]: info: CorePlayQueue::getTrack 0 Apr 13 21:46:56 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 13 21:46:56 coffee volumio[834]: info: CoreCommandRouter::volumioGetState Apr 13 21:46:56 coffee volumio[834]: info: CorePlayQueue::getTrack 0 Apr 13 21:46:56 coffee volumio[834]: info: Listing playlists Apr 13 21:46:57 coffee volumio[1075]: .....................................................++++ Apr 13 21:46:57 coffee volumio[1075]: e is 65537 (0x010001) Apr 13 21:46:57 coffee volumio[1075]: writing RSA key Apr 13 21:46:59 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: my_volumio , setMyVolumioToken Apr 13 21:46:59 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: my_volumio , setMyVolumioToken Apr 13 21:47:03 coffee volumio[834]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Apr 13 21:47:03 coffee volumio[834]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Apr 13 21:47:03 coffee volumio[834]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Apr 13 21:47:03 coffee volumio[834]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Apr 13 21:47:03 coffee volumio[834]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Apr 13 21:47:03 coffee volumio[834]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Apr 13 21:47:03 coffee volumio[834]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Apr 13 21:47:03 coffee volumio[834]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Apr 13 21:47:03 coffee volumio[834]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Apr 13 21:47:03 coffee volumio[834]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Apr 13 21:47:03 coffee volumio[834]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Apr 13 21:47:03 coffee volumio[834]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Apr 13 21:47:03 coffee volumio[834]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Apr 13 21:47:03 coffee volumio[834]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Apr 13 21:47:03 coffee volumio[834]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Apr 13 21:47:03 coffee volumio[834]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Apr 13 21:47:03 coffee volumio[834]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Apr 13 21:47:03 coffee volumio[834]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Apr 13 21:47:03 coffee volumio[834]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Apr 13 21:47:03 coffee volumio[834]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Apr 13 21:47:03 coffee volumio[834]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Apr 13 21:47:03 coffee volumio[834]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Apr 13 21:47:03 coffee volumio[834]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Apr 13 21:47:03 coffee volumio[834]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Apr 13 21:47:03 coffee volumio[834]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Apr 13 21:47:03 coffee volumio[834]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Apr 13 21:47:03 coffee volumio[834]: info: Adding plugin bluetooth to MyMusic Plugins Apr 13 21:47:03 coffee volumio[834]: info: Adding plugin multiroom to MyMusic Plugins Apr 13 21:47:03 coffee volumio[834]: info: Adding plugin metavolumio to MyMusic Plugins Apr 13 21:47:03 coffee volumio[834]: info: Adding plugin cd_controller to MyMusic Plugins Apr 13 21:47:03 coffee volumio[834]: info: Adding plugin smart_inputs to MyMusic Plugins Apr 13 21:47:03 coffee volumio[834]: info: Adding plugin tidalconnect to MyMusic Plugins Apr 13 21:47:03 coffee volumio[834]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Apr 13 21:47:05 coffee volumio[834]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Apr 13 21:47:05 coffee volumio[834]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Apr 13 21:47:05 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 13 21:47:05 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 13 21:47:05 coffee volumio[834]: info: Starting MyVolumio Remote Streaming Endpoints Apr 13 21:47:05 coffee volumio[834]: info: MyVolumio login type: Token Apr 13 21:47:05 coffee volumio[834]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Apr 13 21:47:05 coffee volumio[834]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Apr 13 21:47:06 coffee volumio[834]: info: Starting Streaming Service Transparent Proxy Apr 13 21:47:06 coffee volumio[834]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Apr 13 21:47:06 coffee volumio[834]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Apr 13 21:47:06 coffee volumio[834]: info: Streaming services startup Apr 13 21:47:06 coffee volumio[834]: info: Starting Streaming Daemon Apr 13 21:47:06 coffee sudo[1213]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Apr 13 21:47:06 coffee sudo[1213]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 13 21:47:06 coffee sudo[1213]: pam_unix(sudo:session): session closed for user root Apr 13 21:47:07 coffee volumio[834]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Apr 13 21:47:07 coffee volumio[834]: error: Cannot start Volumio Streaming Daemon Apr 13 21:47:07 coffee volumio[834]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Apr 13 21:47:07 coffee volumio[834]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Apr 13 21:47:08 coffee volumio[834]: STREAMING PROXY: Starting server on port 3245 Apr 13 21:47:08 coffee volumio[834]: Node JS runtime: 14 Apr 13 21:47:08 coffee volumio[834]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Apr 13 21:47:09 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Apr 13 21:47:09 coffee volumio[834]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Apr 13 21:47:09 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Apr 13 21:47:09 coffee volumio[834]: info: Received Get System Version Apr 13 21:47:09 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Apr 13 21:47:09 coffee volumio[834]: info: Received Get System Info Apr 13 21:47:09 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 13 21:47:09 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 13 21:47:09 coffee volumio[834]: info: Discovery: Getting this device information Apr 13 21:47:09 coffee volumio[834]: info: CoreCommandRouter::volumioGetState Apr 13 21:47:09 coffee volumio[834]: info: CorePlayQueue::getTrack 0 Apr 13 21:47:09 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 13 21:47:09 coffee volumio[834]: info: MyVolumio token set successfully Apr 13 21:47:09 coffee volumio[834]: info: MYVOLUMIO: Adding device Apr 13 21:47:09 coffee volumio[834]: info: MYVOLUMIO: Evaluating Server Apr 13 21:47:10 coffee volumio[834]: info: MyVolumio Plan changed: premium Apr 13 21:47:10 coffee volumio[834]: info: [MyVolumio PluginManager] Subscribed plan changed to premium Apr 13 21:47:10 coffee volumio[834]: info: Removing browser output: myVolumio user plan is not superstar Apr 13 21:47:10 coffee volumio[834]: info: Removing audio output: Apr 13 21:47:10 coffee volumio[834]: info: MYVOLUMIO: Adding device Apr 13 21:47:10 coffee volumio[834]: info: MYVOLUMIO: Evaluating Server Apr 13 21:47:10 coffee volumio[834]: info: Remote config written successfully Apr 13 21:47:10 coffee volumio[834]: info: Starting Tunnel 1 Apr 13 21:47:10 coffee volumio[834]: info: Starting Tunnel Connection Checker Apr 13 21:47:10 coffee volumio[834]: info: Completed starting MyVolumio Plugin Apr 13 21:47:11 coffee volumio[834]: info: MYVolumio Device enabled Apr 13 21:47:11 coffee volumio[834]: info: [MyVolumio PluginManager] Device activated, enabling myvolumio plugins... Apr 13 21:47:11 coffee volumio[834]: info: MyVolumio status changed Apr 13 21:47:11 coffee volumio[834]: info: Streaming services startup Apr 13 21:47:11 coffee volumio[834]: info: Starting Streaming Daemon Apr 13 21:47:11 coffee sudo[1252]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Apr 13 21:47:11 coffee sudo[1252]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 13 21:47:11 coffee volumio[834]: info: Setting Geolocation for MyVolumio to us2 Apr 13 21:47:11 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 13 21:47:11 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 13 21:47:11 coffee sudo[1252]: pam_unix(sudo:session): session closed for user root Apr 13 21:47:11 coffee volumio[834]: error: Cannot start Volumio Streaming Daemon Apr 13 21:47:11 coffee volumio[834]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Apr 13 21:47:11 coffee volumio[834]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Apr 13 21:47:11 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getHwuuid Apr 13 21:47:11 coffee volumio[834]: info: [MyVolumio PluginManager] Loading plugin "bluetooth"... Apr 13 21:47:11 coffee volumio[834]: info: [1713070031429] Starting BluetoothController Apr 13 21:47:11 coffee volumio[834]: info: [MyVolumio PluginManager] Loading plugin "multiroom"... Apr 13 21:47:13 coffee volumio[834]: info: [MyVolumio PluginManager] Applying required configuration parameters for plugin multiroom Apr 13 21:47:13 coffee sudo[1255]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/rm -rf /tmp/multiroom Apr 13 21:47:13 coffee sudo[1255]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 13 21:47:13 coffee sudo[1255]: pam_unix(sudo:session): session closed for user root Apr 13 21:47:13 coffee volumio[834]: info: MRS: MultiRoom plugin initialized Apr 13 21:47:13 coffee volumio[834]: info: MRS: STOPPING SNAPCLIENT Apr 13 21:47:13 coffee volumio[834]: info: MRS: Snap server stop Apr 13 21:47:13 coffee sudo[1271]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop volumioSnapclient Apr 13 21:47:13 coffee sudo[1271]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 13 21:47:13 coffee volumio[834]: info: MRS: STOPPING volumioStreaming Apr 13 21:47:13 coffee sudo[1274]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop volumioSnapserver Apr 13 21:47:13 coffee sudo[1274]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 13 21:47:13 coffee sudo[1271]: pam_unix(sudo:session): session closed for user root Apr 13 21:47:13 coffee sudo[1277]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop volumioStreaming Apr 13 21:47:13 coffee sudo[1277]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 13 21:47:13 coffee sudo[1274]: pam_unix(sudo:session): session closed for user root Apr 13 21:47:13 coffee volumio[834]: info: [MyVolumio PluginManager] Loading plugin "metavolumio"... Apr 13 21:47:13 coffee sudo[1277]: pam_unix(sudo:session): session closed for user root Apr 13 21:47:13 coffee volumio[834]: info: [MyVolumio PluginManager] Loading plugin "manifestui"... Apr 13 21:47:13 coffee sudo[1280]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/rm -f /tmp/hls/* Apr 13 21:47:13 coffee sudo[1280]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 13 21:47:13 coffee sudo[1280]: pam_unix(sudo:session): session closed for user root Apr 13 21:47:14 coffee volumio[834]: info: [MyVolumio PluginManager] Loading plugin "cd_controller"... Apr 13 21:47:14 coffee volumio[834]: info: [MyVolumio PluginManager] Loading plugin "smart_inputs"... Apr 13 21:47:14 coffee volumio[834]: info: [MyVolumio PluginManager] Loading plugin "hi_res_audio"... Apr 13 21:47:14 coffee volumio[834]: info: [MyVolumio PluginManager] Applying required configuration parameters for plugin hi_res_audio Apr 13 21:47:14 coffee volumio[834]: info: [MyVolumio PluginManager] Loading plugin "tidal"... Apr 13 21:47:14 coffee volumio[834]: info: [MyVolumio PluginManager] Loading plugin "qobuz"... Apr 13 21:47:14 coffee volumio[834]: info: [MyVolumio PluginManager] Loading plugin "tidalconnect"... Apr 13 21:47:14 coffee volumio[834]: info: Preparing to generate the ALSA configuration file Apr 13 21:47:14 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Apr 13 21:47:14 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 13 21:47:14 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Apr 13 21:47:14 coffee volumio[834]: info: Updating MyVolumio device info Apr 13 21:47:14 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 13 21:47:14 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 13 21:47:14 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 13 21:47:14 coffee volumio[834]: info: The plugin multiroom has an ALSA contribution file volumioMultiRoomServer.postMultiRoom.1000.conf Apr 13 21:47:14 coffee volumio[834]: info: Reading ALSA contributions from plugins. Apr 13 21:47:14 coffee volumio[834]: info: Setting Geolocation for MyVolumio to us2 Apr 13 21:47:14 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 13 21:47:14 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 13 21:47:14 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 13 21:47:14 coffee volumio[834]: info: MRS: Removed streaming files Apr 13 21:47:14 coffee volumio[834]: info: MRS: volumioStreaming STOPPED Apr 13 21:47:14 coffee volumio[834]: info: MRS: SNAPSERVER STOPPED Apr 13 21:47:14 coffee volumio[834]: info: MRS: SNAPCLIENT STOPPED Apr 13 21:47:15 coffee volumio[834]: info: Successfully Added MyVolumio device Apr 13 21:47:15 coffee volumio[834]: info: Asound.conf file written Apr 13 21:47:15 coffee sudo[1286]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mv /home/volumio/.asoundrc /etc/asound.conf Apr 13 21:47:15 coffee sudo[1286]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 13 21:47:15 coffee sudo[1286]: pam_unix(sudo:session): session closed for user root Apr 13 21:47:15 coffee volumio[834]: info: Output device has changed, restarting MPD Apr 13 21:47:15 coffee sudo[1291]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Apr 13 21:47:15 coffee sudo[1291]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 13 21:47:15 coffee sudo[1291]: pam_unix(sudo:session): session closed for user root Apr 13 21:47:15 coffee volumio[834]: info: Output device has changed, restarting Shairport Sync Apr 13 21:47:15 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 13 21:47:15 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 13 21:47:15 coffee sudo[1294]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Apr 13 21:47:15 coffee sudo[1294]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 13 21:47:15 coffee systemd[1]: Stopping Music Player Daemon... Apr 13 21:47:15 coffee volumio[834]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Apr 13 21:47:15 coffee volumio[834]: info: MRS: Audio Device Changed, rebuilding Multiroom Configuration Apr 13 21:47:15 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 13 21:47:15 coffee volumio[834]: info: [MyVolumio PluginManager] Starting plugin audio_interface.bluetooth Apr 13 21:47:15 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Apr 13 21:47:15 coffee volumio[834]: info: [MyVolumio PluginManager] Starting plugin audio_interface.multiroom Apr 13 21:47:15 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , pushMultiRoomStatus Apr 13 21:47:15 coffee sudo[1302]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/hciconfig hci0 name coffee Apr 13 21:47:15 coffee sudo[1302]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 13 21:47:15 coffee volumio[834]: info: MRS: Audio Device Changed, rebuilding Multiroom Configuration Apr 13 21:47:15 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 13 21:47:15 coffee volumio[834]: info: [MyVolumio PluginManager] Starting plugin miscellanea.metavolumio Apr 13 21:47:15 coffee volumio[834]: info: Adding METAVOLUMIO REST API Endpoints Apr 13 21:47:15 coffee volumio[834]: info: Adding metavolumio REST Endpoint for plugin: miscellanea/metavolumio Apr 13 21:47:15 coffee volumio[834]: info: Adding getSimilarArtists REST Endpoint for plugin: miscellanea/metavolumio Apr 13 21:47:15 coffee volumio[834]: info: Adding getSimilarAlbums REST Endpoint for plugin: miscellanea/metavolumio Apr 13 21:47:15 coffee volumio[834]: info: Adding getSimilarTracks REST Endpoint for plugin: miscellanea/metavolumio Apr 13 21:47:15 coffee volumio[834]: info: [MyVolumio PluginManager] Starting plugin miscellanea.manifestui Apr 13 21:47:15 coffee volumio[834]: info: Adding Manifest REST API Endpoints Apr 13 21:47:15 coffee volumio[834]: info: Adding manifestui REST Endpoint for plugin: miscellanea/manifestui Apr 13 21:47:15 coffee volumio[834]: info: [MyVolumio PluginManager] Starting plugin music_service.cd_controller Apr 13 21:47:15 coffee volumio[834]: info: Preparing CD Folders Apr 13 21:47:15 coffee volumio[834]: info: Adding CD REST API Endpoints Apr 13 21:47:15 coffee volumio[834]: info: Adding cdPostRip REST Endpoint for plugin: music_service/cd_controller Apr 13 21:47:15 coffee volumio[834]: info: Starting UDEV Watcher for CD Apr 13 21:47:15 coffee volumio[834]: info: Detecting CD presence with UDEV Apr 13 21:47:15 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: networkfs , getUdevDevices Apr 13 21:47:15 coffee sudo[1302]: pam_unix(sudo:session): session closed for user root Apr 13 21:47:15 coffee volumio[834]: info: [MyVolumio PluginManager] Starting plugin music_service.smart_inputs Apr 13 21:47:15 coffee volumio[834]: info: Adding inputs REST Endpoints Apr 13 21:47:15 coffee volumio[834]: info: Adding scanAudioInputs REST Endpoint for plugin: music_service/smart_inputs Apr 13 21:47:15 coffee volumio[834]: info: Scanning Audio Inputs Apr 13 21:47:15 coffee systemd[1]: mpd.service: Succeeded. Apr 13 21:47:15 coffee systemd[1]: Stopped Music Player Daemon. Apr 13 21:47:15 coffee systemd[1]: Starting Music Player Daemon... Apr 13 21:47:15 coffee volumio[834]: info: Checking against Known Cards name Apr 13 21:47:15 coffee volumio[834]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Apr 13 21:47:15 coffee volumio[834]: info: [1713070035890] CoreMusicLibrary::Adding element HDA Intel Apr 13 21:47:15 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 13 21:47:15 coffee volumio[834]: Cannot find translation for source YouTube2 Apr 13 21:47:15 coffee volumio[834]: Cannot find translation for source YouTube Music Apr 13 21:47:15 coffee volumio[834]: Cannot find translation for source Spotify Apr 13 21:47:15 coffee volumio[834]: Cannot find translation for source HDA Intel Apr 13 21:47:15 coffee volumio[834]: info: Checking against Known Cards name Apr 13 21:47:15 coffee volumio[834]: info: Adding Server instance for streaming Apr 13 21:47:15 coffee volumio[834]: info: [MyVolumio PluginManager] Starting plugin music_service.hi_res_audio Apr 13 21:47:15 coffee volumio[834]: error: Hi Res Audio Failed Login: Missing Login Data Apr 13 21:47:15 coffee volumio[834]: info: Adding HIGHRESAUDIO REST API Endpoints Apr 13 21:47:15 coffee volumio[834]: info: Adding getStreamUrlhi_res_audio REST Endpoint for plugin: music_service/hi_res_audio Apr 13 21:47:15 coffee volumio[834]: info: [MyVolumio PluginManager] Starting plugin music_service.tidal Apr 13 21:47:15 coffee volumio[834]: info: Refreshing TIDAL token Apr 13 21:47:15 coffee volumio[834]: info: [MyVolumio PluginManager] Starting plugin music_service.qobuz Apr 13 21:47:15 coffee volumio[834]: info: [MyVolumio PluginManager] Starting plugin music_service.tidalconnect Apr 13 21:47:15 coffee volumio[834]: info: Stopping AccessToken refresher cron for QOBUZ Apr 13 21:47:16 coffee volumio[834]: info: AccessToken refresher cron started for QOBUZ Apr 13 21:47:16 coffee sudo[1311]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service Apr 13 21:47:16 coffee volumio[834]: info: Adding QOBUZ REST API Endpoints Apr 13 21:47:16 coffee volumio[834]: info: Adding getStreamUrlqobuz REST Endpoint for plugin: music_service/qobuz Apr 13 21:47:16 coffee sudo[1311]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 13 21:47:16 coffee volumio[834]: info: Updating MyVolumio device info Apr 13 21:47:16 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 13 21:47:16 coffee sudo[1311]: pam_unix(sudo:session): session closed for user root Apr 13 21:47:16 coffee volumio[834]: info: Bluetooth name changed to coffee Apr 13 21:47:16 coffee volumio[834]: info: MPD Permissions set Apr 13 21:47:16 coffee volumio[834]: info: CoreCommandRouter::volumioGetState Apr 13 21:47:16 coffee volumio[834]: info: CorePlayQueue::getTrack 0 Apr 13 21:47:16 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 13 21:47:16 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 13 21:47:16 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 13 21:47:16 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 13 21:47:16 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 13 21:47:16 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 13 21:47:16 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: system , getCPUCoresNumber Apr 13 21:47:16 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 13 21:47:16 coffee volumio[834]: info: Discovery: Browse raised the following error Error: getaddrinfo -3007 Apr 13 21:47:16 coffee volumio[834]: Cast browser error: Error: getaddrinfo -3007 Apr 13 21:47:16 coffee volumio[834]: info: Successfully Updated MyVolumio device Apr 13 21:47:16 coffee volumio[834]: info: Starting Shairport Sync Apr 13 21:47:16 coffee sudo[1330]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart sshtunnel.service Apr 13 21:47:16 coffee sudo[1330]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 13 21:47:16 coffee sudo[1332]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Apr 13 21:47:17 coffee sudo[1332]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 13 21:47:17 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateEnabled Apr 13 21:47:17 coffee volumio-remote-updater[463]: No test mode Apr 13 21:47:17 coffee volumio-remote-updater[463]: No alpha test mode Apr 13 21:47:17 coffee volumio[834]: Cast browser error: Error: getaddrinfo -3007 Apr 13 21:47:17 coffee volumio[834]: Cast browser error: Error: getaddrinfo -3007 Apr 13 21:47:17 coffee volumio[834]: Cast browser error: Error: getaddrinfo -3007 Apr 13 21:47:17 coffee systemd[1]: Started MyVolumio SSH Tunnel. Apr 13 21:47:17 coffee volumio[834]: info: CoreCommandRouter::getUIConfigOnPlugin Apr 13 21:47:17 coffee volumio[834]: info: CoreCommandRouter::getUIConfigOnPlugin Apr 13 21:47:17 coffee volumio[834]: info: Retrieving Cloud Streaming UI Apr 13 21:47:17 coffee sudo[1330]: pam_unix(sudo:session): session closed for user root Apr 13 21:47:17 coffee systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Apr 13 21:47:17 coffee systemd[1]: shairport-sync.service: Succeeded. Apr 13 21:47:17 coffee systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Apr 13 21:47:17 coffee systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Apr 13 21:47:17 coffee autossh[1339]: port set to 0, monitoring disabled Apr 13 21:47:17 coffee autossh[1339]: starting ssh (count 1) Apr 13 21:47:17 coffee autossh[1339]: ssh child pid is 1345 Apr 13 21:47:17 coffee sudo[1332]: pam_unix(sudo:session): session closed for user root Apr 13 21:47:17 coffee volumio[834]: info: Remote SSH Started Apr 13 21:47:17 coffee volumiossh-tunnel[1338]: Warning: Permanently added '[us2.myvolumio.org]:2222,[137.184.235.84]:2222' (RSA) to the list of known hosts. Apr 13 21:47:17 coffee volumio[834]: info: MRS: Found cast device: Chromecast-HD-821a081b75fac934137013e4a7895e3a Apr 13 21:47:17 coffee volumio[834]: info: Adding audio output: Apr 13 21:47:17 coffee volumio[834]: Cast browser error: Error: getaddrinfo -3007 Apr 13 21:47:17 coffee volumio[834]: Cast browser error: Error: getaddrinfo -3007 Apr 13 21:47:17 coffee volumio[834]: info: Access Token successfully retrieved Apr 13 21:47:17 coffee volumio[834]: info: Successfully Updated MyVolumio device Apr 13 21:47:17 coffee volumiossh-tunnel[1338]: Warning: remote port forwarding failed for listen port 8091 Apr 13 21:47:17 coffee volumio[834]: info: Update Ready: {"changeLogLink":"","description":"You're already on the latest version","title":"No Updates Available","updateavailable":false} Apr 13 21:47:17 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache Apr 13 21:47:17 coffee volumio[834]: info: Shairport-Sync Started Apr 13 21:47:17 coffee volumio[834]: Cast browser error: Error: getaddrinfo -3007 Apr 13 21:47:17 coffee volumio[834]: info: Getting Tidal Cloud Configuration Apr 13 21:47:17 coffee volumio[834]: info: CoreCommandRouter::getUIConfigOnPlugin Apr 13 21:47:17 coffee volumio[834]: info: Getting Qobuz Cloud Configuration Apr 13 21:47:17 coffee volumio[834]: info: Asking plugin for UI Config Apr 13 21:47:17 coffee volumio[834]: info: CoreCommandRouter::getUIConfigOnPlugin Apr 13 21:47:18 coffee volumio[834]: info: Getting Spotify Cloud Configuration Apr 13 21:47:18 coffee volumio[834]: info: Asking plugin for UI Config Apr 13 21:47:18 coffee volumio[834]: info: CoreCommandRouter::getUIConfigOnPlugin Apr 13 21:47:18 coffee volumio[834]: info: Saving Spotify Acccount Apr 13 21:47:18 coffee volumio[834]: info: Got it Apr 13 21:47:18 coffee volumio[834]: error: Could not retrieve Spotify Config from plugin Spotify: no section found Apr 13 21:47:18 coffee volumio[834]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 8 Apr 13 21:47:18 coffee volumio[834]: Cast browser error: Error: getaddrinfo -3007 Apr 13 21:47:18 coffee volumio[834]: info: Got it Apr 13 21:47:18 coffee volumio[834]: info: Got Tidal Cloud Configuration Apr 13 21:47:18 coffee volumio[834]: info: CoreCommandRouter::getUIConfigOnPlugin Apr 13 21:47:18 coffee volumio[834]: info: Successfully Added MyVolumio device Apr 13 21:47:18 coffee volumio[834]: info: CoreCommandRouter::volumioGetState Apr 13 21:47:18 coffee volumio[834]: info: CorePlayQueue::getTrack 0 Apr 13 21:47:18 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus Apr 13 21:47:18 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Apr 13 21:47:18 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Apr 13 21:47:18 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Apr 13 21:47:18 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Apr 13 21:47:18 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Apr 13 21:47:18 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Apr 13 21:47:18 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Apr 13 21:47:18 coffee volumio[834]: info: CoreCommandRouter::volumioGetBrowseSources Apr 13 21:47:18 coffee volumio[834]: info: CoreCommandRouter::volumioGetBrowseSources Apr 13 21:47:18 coffee volumio[834]: info: CoreCommandRouter::volumioGetBrowseSources Apr 13 21:47:18 coffee volumio[834]: info: Successfully retrieved User Session From TIDAL Apr 13 21:47:18 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Apr 13 21:47:18 coffee volumio[834]: error: MPD error: Error: This socket has been ended by the other party Apr 13 21:47:18 coffee volumio[834]: error: This socket has been ended by the other party {"code":"EPIPE"} Apr 13 21:47:18 coffee volumio[834]: error: MPD error: Error: This socket has been ended by the other party Apr 13 21:47:18 coffee volumio[834]: error: This socket has been ended by the other party {"code":"EPIPE"} Apr 13 21:47:18 coffee volumio[834]: error: MPD error: Error: This socket has been ended by the other party Apr 13 21:47:18 coffee volumio[834]: error: This socket has been ended by the other party {"code":"EPIPE"} Apr 13 21:47:18 coffee sudo[1349]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumiobt.service Apr 13 21:47:18 coffee sudo[1349]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 13 21:47:18 coffee volumio[834]: info: Successfully retrieved User Subscription From TIDAL Apr 13 21:47:18 coffee volumio[834]: info: Adding TIDAL to Browse Sources Apr 13 21:47:18 coffee volumio[834]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Apr 13 21:47:18 coffee volumio[834]: info: [1713070038710] CoreMusicLibrary::Adding element TIDAL Apr 13 21:47:18 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 13 21:47:18 coffee volumio[834]: Cannot find translation for source YouTube2 Apr 13 21:47:18 coffee volumio[834]: Cannot find translation for source YouTube Music Apr 13 21:47:18 coffee volumio[834]: Cannot find translation for source Spotify Apr 13 21:47:18 coffee volumio[834]: Cannot find translation for source HDA Intel Apr 13 21:47:18 coffee volumio[834]: Cannot find translation for source TIDAL Apr 13 21:47:18 coffee volumio[834]: info: Stopping AccessToken refresher cron Apr 13 21:47:18 coffee volumio[834]: info: AccessToken refresher cron started Apr 13 21:47:18 coffee volumio[834]: info: Adding TIDAL REST API Endpoints Apr 13 21:47:18 coffee volumio[834]: info: Adding getStreamUrltidal REST Endpoint for plugin: music_service/tidal Apr 13 21:47:18 coffee systemd[1]: Started Volumio Bluetooth Module. Apr 13 21:47:18 coffee sudo[1349]: pam_unix(sudo:session): session closed for user root Apr 13 21:47:18 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: networkfs , listShares Apr 13 21:47:18 coffee sudo[1352]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod -R 777 /var/lib/bluetooth/* Apr 13 21:47:18 coffee sudo[1352]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 13 21:47:18 coffee volumiobt[1351]: /bin/chmod: cannot access '/var/lib/bluetooth/*': No such file or directory Apr 13 21:47:18 coffee sudo[1352]: pam_unix(sudo:session): session closed for user root Apr 13 21:47:19 coffee volumio[834]: info: Volumio BT Module successfully started Apr 13 21:47:19 coffee volumio[834]: info: TidalConnect service stoped! Apr 13 21:47:19 coffee volumio[834]: info: Adding tc_getconfig REST Endpoint for plugin: music_service/tidalconnect Apr 13 21:47:19 coffee volumio[834]: info: Adding tc_connect REST Endpoint for plugin: music_service/tidalconnect Apr 13 21:47:19 coffee sudo[1364]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start vtcs.service Apr 13 21:47:19 coffee sudo[1364]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 13 21:47:19 coffee systemd[1]: Started Volumio Tidal Connect Service. Apr 13 21:47:19 coffee sudo[1364]: pam_unix(sudo:session): session closed for user root Apr 13 21:47:19 coffee mpd[1309]: Apr 13 21:47 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Apr 13 21:47:19 coffee systemd[1]: Started Music Player Daemon. Apr 13 21:47:19 coffee sudo[1294]: pam_unix(sudo:session): session closed for user root Apr 13 21:47:19 coffee volumio[834]: error: updateQueue error: null Apr 13 21:47:20 coffee sudo[1371]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/bin/killall pulseaudio Apr 13 21:47:20 coffee sudo[1371]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 13 21:47:20 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Apr 13 21:47:20 coffee volumiobt[1351]: pulseaudio: no process found Apr 13 21:47:20 coffee sudo[1371]: pam_unix(sudo:session): session closed for user root Apr 13 21:47:20 coffee volumio[834]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 9 Apr 13 21:47:20 coffee volumio[834]: info: Executing endpoint tc_getconfig Apr 13 21:47:20 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: tidalconnect , onGetConfig Apr 13 21:47:20 coffee vtcs[1366]: STARTING TidalConnect services, version: 1.3.0.19 Apr 13 21:47:20 coffee volumio[834]: info: CoreCommandRouter::volumioGetState Apr 13 21:47:20 coffee volumio[834]: info: CorePlayQueue::getTrack 0 Apr 13 21:47:20 coffee dbus-daemon[464]: [system] Activating via systemd: service name='org.freedesktop.RealtimeKit1' unit='rtkit-daemon.service' requested by ':1.29' (uid=1000 pid=1376 comm="/usr/bin/pulseaudio --high-priority=true ") Apr 13 21:47:20 coffee kernel: perf: interrupt took too long (2548 > 2500), lowering kernel.perf_event_max_sample_rate to 78250 Apr 13 21:47:20 coffee systemd[1]: Starting RealtimeKit Scheduling Policy Service... Apr 13 21:47:20 coffee volumio[834]: ------------------------------------ BT MESSAGE: BT STATUS: running Apr 13 21:47:20 coffee vtcs[1366]: STARTED TidalConnect services. Apr 13 21:47:20 coffee volumio[834]: info: Executing endpoint tc_connect Apr 13 21:47:20 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: tidalconnect , onConnect Apr 13 21:47:20 coffee dbus-daemon[464]: [system] Successfully activated service 'org.freedesktop.RealtimeKit1' Apr 13 21:47:20 coffee systemd[1]: Started RealtimeKit Scheduling Policy Service. Apr 13 21:47:20 coffee volumio[834]: info: Connecting to TidalConnect Apr 13 21:47:20 coffee rtkit-daemon[1377]: Successfully called chroot. Apr 13 21:47:20 coffee rtkit-daemon[1377]: Successfully dropped privileges. Apr 13 21:47:20 coffee rtkit-daemon[1377]: Successfully limited resources. Apr 13 21:47:20 coffee rtkit-daemon[1377]: Running. Apr 13 21:47:20 coffee rtkit-daemon[1377]: Canary thread running. Apr 13 21:47:20 coffee dbus-daemon[464]: [system] Activating via systemd: service name='org.freedesktop.PolicyKit1' unit='polkit.service' requested by ':1.30' (uid=0 pid=1377 comm="/usr/lib/rtkit/rtkit-daemon ") Apr 13 21:47:20 coffee rtkit-daemon[1377]: Watchdog thread running. Apr 13 21:47:20 coffee volumio[834]: info: CoreCommandRouter::servicePushState Apr 13 21:47:20 coffee volumio[834]: info: CoreStateMachine::pushState Apr 13 21:47:20 coffee volumio[834]: info: CorePlayQueue::getTrack 0 Apr 13 21:47:20 coffee volumio[834]: info: CoreCommandRouter::volumioPushState Apr 13 21:47:20 coffee systemd[1]: Starting Authorization Manager... Apr 13 21:47:20 coffee volumio[834]: info: CorePlayQueue::getTrack 0 Apr 13 21:47:20 coffee volumio[834]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current ytmusic Received tidalconnect Apr 13 21:47:20 coffee volumio[834]: info: CoreCommandRouter::servicePushState Apr 13 21:47:20 coffee volumio[834]: info: CoreStateMachine::pushState Apr 13 21:47:20 coffee volumio[834]: info: CorePlayQueue::getTrack 0 Apr 13 21:47:20 coffee volumio[834]: info: CoreCommandRouter::volumioPushState Apr 13 21:47:20 coffee volumio[834]: info: CorePlayQueue::getTrack 0 Apr 13 21:47:20 coffee volumio[834]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current ytmusic Received tidalconnect Apr 13 21:47:20 coffee volumio[834]: ------------------------------------ BT MESSAGE: BT STATUS: running Apr 13 21:47:20 coffee volumio[834]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 13 21:47:20 coffee volumio[834]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 13 21:47:20 coffee volumio[834]: info: MRS: Getting audio outputs on start Apr 13 21:47:20 coffee volumio[834]: info: MRS: Requesting all other devices output Apr 13 21:47:20 coffee polkitd[1387]: started daemon version 0.105 using authority implementation `local' version `0.105' Apr 13 21:47:20 coffee dbus-daemon[464]: [system] Successfully activated service 'org.freedesktop.PolicyKit1' Apr 13 21:47:20 coffee systemd[1]: Started Authorization Manager. Apr 13 21:47:21 coffee pulseaudio[1376]: Unable to contact D-Bus: org.freedesktop.DBus.Error.NotSupported: Unable to autolaunch a dbus-daemon without a $DISPLAY for X11 Apr 13 21:47:21 coffee pulseaudio[1376]: Unable to contact D-Bus: org.freedesktop.DBus.Error.NotSupported: Unable to autolaunch a dbus-daemon without a $DISPLAY for X11 Apr 13 21:47:21 coffee bluetoothd[483]: Endpoint registered: sender=:1.51 path=/MediaEndpoint/A2DPSource Apr 13 21:47:21 coffee bluetoothd[483]: Endpoint registered: sender=:1.51 path=/MediaEndpoint/A2DPSink Apr 13 21:47:21 coffee pulseaudio[1376]: Failed to register as a handsfree audio agent with ofono: org.freedesktop.DBus.Error.ServiceUnknown: The name org.ofono was not provided by any .service files Apr 13 21:47:21 coffee volumiobt[1351]: Applying permissions Apr 13 21:47:21 coffee volumiobt[1351]: Setting BT discoverable and pairable Apr 13 21:47:21 coffee kernel: Bluetooth: RFCOMM TTY layer initialized Apr 13 21:47:21 coffee kernel: Bluetooth: RFCOMM socket layer initialized Apr 13 21:47:21 coffee kernel: Bluetooth: RFCOMM ver 1.11 Apr 13 21:47:21 coffee volumiobt[1351]: Agent registered Apr 13 21:47:21 coffee volumiobt[1351]: [bluetooth]# -e power on Apr 13 21:47:21 coffee volumiobt[1351]: Invalid command in menu main: -e Apr 13 21:47:21 coffee volumiobt[1351]: Apr 13 21:47:21 coffee volumiobt[1351]: Use "help" for a list of available commands in a menu. Apr 13 21:47:21 coffee volumiobt[1351]: Use "menu " if you want to enter any submenu. Apr 13 21:47:21 coffee volumiobt[1351]: Use "back" if you want to return to menu main. Apr 13 21:47:21 coffee volumiobt[1351]: [bluetooth]# agent on Apr 13 21:47:21 coffee volumiobt[1351]: Agent is already registered Apr 13 21:47:21 coffee volumiobt[1351]: [bluetooth]# discoverable on Apr 13 21:47:21 coffee volumiobt[1351]: [bluetooth]# pairable on Apr 13 21:47:21 coffee volumiobt[1351]: [bluetooth]# agent NoInputNoOutput Apr 13 21:47:21 coffee volumiobt[1351]: Agent is already registered Apr 13 21:47:21 coffee volumiobt[1351]: [bluetooth]# default-agent Apr 13 21:47:21 coffee volumiobt[1351]: [bluetooth]# quit Apr 13 21:47:21 coffee volumiobt[1351]: [59B blob data] Apr 13 21:47:22 coffee volumio[834]: info: TidalConnect service started! Apr 13 21:47:22 coffee volumio[834]: info: BOOT COMPLETED Apr 13 21:47:22 coffee volumio[834]: [Metrics] CommandRouter: 59s 837.91ms Apr 13 21:47:22 coffee volumio[834]: info: CoreCommandRouter::volumiosetStartupVolume Apr 13 21:47:22 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 13 21:47:22 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 13 21:47:22 coffee volumio[834]: info: CoreCommandRouter::Close All Modals sent Apr 13 21:47:22 coffee volumio[834]: info: CoreCommandRouter::Close All Modals sent Apr 13 21:47:23 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable Apr 13 21:47:23 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Apr 13 21:47:23 coffee volumio[834]: xcb_connection_has_error() returned true Apr 13 21:47:23 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect Apr 13 21:47:24 coffee kernel: snd_hda_intel 0000:00:1b.0: IRQ timing workaround is activated for card #0. Suggest a bigger bdl_pos_adj. Apr 13 21:47:25 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 13 21:47:25 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam Apr 13 21:47:25 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Apr 13 21:47:25 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Apr 13 21:47:25 coffee volumio[834]: info: CoreCommandRouter::volumioGetBrowseSources Apr 13 21:47:25 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Apr 13 21:47:27 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Apr 13 21:47:27 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Apr 13 21:47:27 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: networkfs , discoverShares Apr 13 21:47:27 coffee volumio[834]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , browseForService Apr 13 21:47:27 coffee volumio[834]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 13 21:47:27 coffee volumio[834]: Error: getaddrinfo -3007 Apr 13 21:47:27 coffee volumio[834]: at errnoException (/volumio/node_modules/mdns/lib/resolver_sequence_tasks.js:199:11) Apr 13 21:47:27 coffee volumio[834]: at getaddrinfo_complete (/volumio/node_modules/mdns/lib/resolver_sequence_tasks.js:112:10) Apr 13 21:47:27 coffee volumio[834]: at GetAddrInfoReqWrap.oncomplete (/volumio/node_modules/mdns/lib/resolver_sequence_tasks.js:120:9) { Apr 13 21:47:27 coffee volumio[834]: code: -3007, Apr 13 21:47:27 coffee volumio[834]: errno: -3007, Apr 13 21:47:27 coffee volumio[834]: syscall: 'getaddrinfo' Apr 13 21:47:27 coffee volumio[834]: } Apr 13 21:47:27 coffee volumio[834]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 13 21:47:28 coffee sudo[1421]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-04-13 21:46 Apr 13 21:47:28 coffee sudo[1421]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Debian GNU/Linux 10 (buster)" NAME="Debian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=debian HOME_URL="https://www.debian.org/" SUPPORT_URL="https://www.debian.org/support" BUG_REPORT_URL="https://bugs.debian.org/" VOLUMIO_BUILD_VERSION="7b9cb4a8b52fb7148a38d6ac651c1c29e09bb92c" VOLUMIO_FE_VERSION="614d7b13ffdcb0cc5a6072e7d06f59d52e323e71" VOLUMIO_FE3_VERSION="570aaed971c1346d45d1172dc445b086b258c6d1" VOLUMIO_BE_VERSION="b1dcc17f6d31bf91f0abd3c3fa57506d1e0d2b6b" VOLUMIO_ARCH="x64" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri 01 Mar 2024 08:52:33 PM CET" VOLUMIO_VERSION="3.634" VOLUMIO_HARDWARE="x86_amd64" VOLUMIO_DEVICENAME="x86_64" VOLUMIO_HASH="93edfc70711724967af109c0a39fa069"