-- 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"