-- Logs begin at Thu 2025-10-23 15:34:01 -03, end at Fri 2025-10-31 09:27:37 -03. -- Oct 31 09:26:59 volumiosplendid systemd-timedated[1032]: Changed local time to Fri Oct 31 09:26:59 2025 Oct 31 09:26:59 volumiosplendid sudo[1030]: pam_unix(sudo:session): session closed for user root Oct 31 09:26:59 volumiosplendid volumio-time-update[599]: volumio-time-update-util: System time updated successfully. Oct 31 09:26:59 volumiosplendid systemd[1]: Starting Daily apt download activities... Oct 31 09:26:59 volumiosplendid systemd[1]: Started Volumio Time Update Utility. Oct 31 09:26:59 volumiosplendid wireless.js[585]: trying... Oct 31 09:26:59 volumiosplendid sudo[1055]: volumio : unable to resolve host volumiosplendid Oct 31 09:26:59 volumiosplendid sudo[1055]: volumio : problem with defaults entries ; TTY=unknown ; PWD=/ ; USER=root ; Oct 31 09:26:59 volumiosplendid sudo[1055]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Oct 31 09:26:59 volumiosplendid sudo[1055]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 31 09:26:59 volumiosplendid sudo[1055]: pam_unix(sudo:session): session closed for user root Oct 31 09:26:59 volumiosplendid wireless.js[585]: sudo: unable to resolve host volumiosplendid: System error Oct 31 09:27:00 volumiosplendid wireless.js[585]: trying... Oct 31 09:27:00 volumiosplendid sudo[1059]: volumio : unable to resolve host volumiosplendid Oct 31 09:27:00 volumiosplendid sudo[1059]: volumio : problem with defaults entries ; TTY=unknown ; PWD=/ ; USER=root ; Oct 31 09:27:00 volumiosplendid sudo[1059]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Oct 31 09:27:00 volumiosplendid sudo[1059]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 31 09:27:00 volumiosplendid sudo[1059]: pam_unix(sudo:session): session closed for user root Oct 31 09:27:00 volumiosplendid wireless.js[585]: sudo: unable to resolve host volumiosplendid: System error Oct 31 09:27:00 volumiosplendid systemd[1]: apt-daily.service: Succeeded. Oct 31 09:27:00 volumiosplendid systemd[1]: Started Daily apt download activities. Oct 31 09:27:01 volumiosplendid systemd[1]: Starting Daily apt upgrade and clean activities... Oct 31 09:27:01 volumiosplendid wireless.js[585]: trying... Oct 31 09:27:01 volumiosplendid sudo[1110]: volumio : unable to resolve host volumiosplendid Oct 31 09:27:01 volumiosplendid sudo[1110]: volumio : problem with defaults entries ; TTY=unknown ; PWD=/ ; USER=root ; Oct 31 09:27:01 volumiosplendid sudo[1110]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Oct 31 09:27:01 volumiosplendid sudo[1110]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 31 09:27:01 volumiosplendid sudo[1110]: pam_unix(sudo:session): session closed for user root Oct 31 09:27:01 volumiosplendid wireless.js[585]: sudo: unable to resolve host volumiosplendid: System error Oct 31 09:27:02 volumiosplendid systemd[1]: apt-daily-upgrade.service: Succeeded. Oct 31 09:27:02 volumiosplendid systemd[1]: Started Daily apt upgrade and clean activities. Oct 31 09:27:02 volumiosplendid wireless.js[585]: trying... Oct 31 09:27:02 volumiosplendid sudo[1142]: volumio : unable to resolve host volumiosplendid Oct 31 09:27:02 volumiosplendid sudo[1142]: volumio : problem with defaults entries ; TTY=unknown ; PWD=/ ; USER=root ; Oct 31 09:27:02 volumiosplendid sudo[1142]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Oct 31 09:27:02 volumiosplendid sudo[1142]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 31 09:27:02 volumiosplendid sudo[1142]: pam_unix(sudo:session): session closed for user root Oct 31 09:27:02 volumiosplendid wireless.js[585]: sudo: unable to resolve host volumiosplendid: System error Oct 31 09:27:03 volumiosplendid wireless.js[585]: trying... Oct 31 09:27:03 volumiosplendid sudo[1145]: volumio : unable to resolve host volumiosplendid Oct 31 09:27:03 volumiosplendid sudo[1145]: volumio : problem with defaults entries ; TTY=unknown ; PWD=/ ; USER=root ; Oct 31 09:27:03 volumiosplendid sudo[1145]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Oct 31 09:27:03 volumiosplendid sudo[1145]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 31 09:27:03 volumiosplendid sudo[1145]: pam_unix(sudo:session): session closed for user root Oct 31 09:27:03 volumiosplendid wireless.js[585]: sudo: unable to resolve host volumiosplendid: System error Oct 31 09:27:04 volumiosplendid wireless.js[585]: trying... Oct 31 09:27:04 volumiosplendid sudo[1148]: volumio : unable to resolve host volumiosplendid Oct 31 09:27:04 volumiosplendid sudo[1148]: volumio : problem with defaults entries ; TTY=unknown ; PWD=/ ; USER=root ; Oct 31 09:27:04 volumiosplendid sudo[1148]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Oct 31 09:27:04 volumiosplendid sudo[1148]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 31 09:27:04 volumiosplendid sudo[1148]: pam_unix(sudo:session): session closed for user root Oct 31 09:27:04 volumiosplendid wireless.js[585]: sudo: unable to resolve host volumiosplendid: System error Oct 31 09:27:05 volumiosplendid wireless.js[585]: trying... Oct 31 09:27:05 volumiosplendid sudo[1151]: volumio : unable to resolve host volumiosplendid Oct 31 09:27:05 volumiosplendid sudo[1151]: volumio : problem with defaults entries ; TTY=unknown ; PWD=/ ; USER=root ; Oct 31 09:27:05 volumiosplendid sudo[1151]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Oct 31 09:27:05 volumiosplendid sudo[1151]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 31 09:27:05 volumiosplendid sudo[1151]: pam_unix(sudo:session): session closed for user root Oct 31 09:27:05 volumiosplendid wireless.js[585]: sudo: unable to resolve host volumiosplendid: System error Oct 31 09:27:05 volumiosplendid volumio-remote-updater[587]: [2025-10-31 09:27:05] [info] asio async_connect error: system:111 (Connection refused) Oct 31 09:27:05 volumiosplendid volumio-remote-updater[587]: [2025-10-31 09:27:05] [info] Error getting remote endpoint: system:107 (Transport endpoint is not connected) Oct 31 09:27:05 volumiosplendid volumio-remote-updater[587]: [2025-10-31 09:27:05] [error] handle_connect error: Underlying Transport Error Oct 31 09:27:06 volumiosplendid wireless.js[585]: trying... Oct 31 09:27:06 volumiosplendid sudo[1157]: volumio : unable to resolve host volumiosplendid Oct 31 09:27:06 volumiosplendid sudo[1157]: volumio : problem with defaults entries ; TTY=unknown ; PWD=/ ; USER=root ; Oct 31 09:27:06 volumiosplendid sudo[1157]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Oct 31 09:27:06 volumiosplendid sudo[1157]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 31 09:27:06 volumiosplendid sudo[1157]: pam_unix(sudo:session): session closed for user root Oct 31 09:27:06 volumiosplendid wireless.js[585]: sudo: unable to resolve host volumiosplendid: System error Oct 31 09:27:07 volumiosplendid wireless.js[585]: trying... Oct 31 09:27:07 volumiosplendid sudo[1160]: volumio : unable to resolve host volumiosplendid Oct 31 09:27:07 volumiosplendid sudo[1160]: volumio : problem with defaults entries ; TTY=unknown ; PWD=/ ; USER=root ; Oct 31 09:27:07 volumiosplendid sudo[1160]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Oct 31 09:27:07 volumiosplendid sudo[1160]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 31 09:27:07 volumiosplendid sudo[1160]: pam_unix(sudo:session): session closed for user root Oct 31 09:27:07 volumiosplendid wireless.js[585]: sudo: unable to resolve host volumiosplendid: System error Oct 31 09:27:08 volumiosplendid wireless.js[585]: trying... Oct 31 09:27:08 volumiosplendid sudo[1163]: volumio : unable to resolve host volumiosplendid Oct 31 09:27:08 volumiosplendid sudo[1163]: volumio : problem with defaults entries ; TTY=unknown ; PWD=/ ; USER=root ; Oct 31 09:27:08 volumiosplendid sudo[1163]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Oct 31 09:27:08 volumiosplendid sudo[1163]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 31 09:27:08 volumiosplendid sudo[1163]: pam_unix(sudo:session): session closed for user root Oct 31 09:27:08 volumiosplendid wireless.js[585]: sudo: unable to resolve host volumiosplendid: System error Oct 31 09:27:09 volumiosplendid wireless.js[585]: Overtime, starting plan B Oct 31 09:27:09 volumiosplendid wireless.js[585]: STARTING HOTSPOT Oct 31 09:27:09 volumiosplendid wpa_supplicant[898]: nl80211: Failed to open /proc/sys/net/ipv4/conf/p2p-dev-wlan0/drop_unicast_in_l2_multicast: No such file or directory Oct 31 09:27:09 volumiosplendid wpa_supplicant[898]: nl80211: Failed to set IPv4 unicast in multicast filter Oct 31 09:27:09 volumiosplendid wpa_supplicant[898]: nl80211: Failed to open /proc/sys/net/ipv4/conf/p2p-dev-wlan0/drop_unicast_in_l2_multicast: No such file or directory Oct 31 09:27:09 volumiosplendid wpa_supplicant[898]: nl80211: Failed to set IPv4 unicast in multicast filter Oct 31 09:27:09 volumiosplendid wpa_supplicant[898]: nl80211: deinit ifname=p2p-dev-wlan0 disabled_11b_rates=0 Oct 31 09:27:09 volumiosplendid wpa_supplicant[898]: p2p-dev-wlan0: CTRL-EVENT-TERMINATING Oct 31 09:27:09 volumiosplendid wpa_supplicant[898]: nl80211: deinit ifname=wlan0 disabled_11b_rates=0 Oct 31 09:27:10 volumiosplendid wpa_supplicant[898]: wlan0: CTRL-EVENT-TERMINATING Oct 31 09:27:11 volumiosplendid systemd[1]: systemd-fsckd.service: Succeeded. Oct 31 09:27:12 volumiosplendid sudo[1172]: root : unable to resolve host volumiosplendid Oct 31 09:27:12 volumiosplendid sudo[1172]: root : problem with defaults entries ; TTY=unknown ; PWD=/ ; USER=root ; Oct 31 09:27:12 volumiosplendid sudo[1172]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ip addr flush dev wlan0 Oct 31 09:27:12 volumiosplendid sudo[1172]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 31 09:27:12 volumiosplendid sudo[1172]: pam_unix(sudo:session): session closed for user root Oct 31 09:27:12 volumiosplendid sudo[1174]: root : unable to resolve host volumiosplendid Oct 31 09:27:12 volumiosplendid sudo[1174]: root : problem with defaults entries ; TTY=unknown ; PWD=/ ; USER=root ; Oct 31 09:27:12 volumiosplendid sudo[1174]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 down Oct 31 09:27:12 volumiosplendid sudo[1174]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 31 09:27:12 volumiosplendid sudo[1174]: pam_unix(sudo:session): session closed for user root Oct 31 09:27:12 volumiosplendid avahi-daemon[590]: Joining mDNS multicast group on interface wlan0.IPv4 with address 192.168.211.1. Oct 31 09:27:12 volumiosplendid avahi-daemon[590]: New relevant interface wlan0.IPv4 for mDNS. Oct 31 09:27:12 volumiosplendid avahi-daemon[590]: Registering new address record for 192.168.211.1 on wlan0.IPv4. Oct 31 09:27:12 volumiosplendid kernel: brcmfmac: brcmf_cfg80211_set_power_mgmt: power save disabled Oct 31 09:27:12 volumiosplendid systemd[1]: Starting dnsmasq - A lightweight DHCP and caching DNS server... Oct 31 09:27:12 volumiosplendid systemd[1]: Starting Advanced IEEE 802.11 AP and IEEE 802.1X/WPA/WPA2/EAP Authenticator... Oct 31 09:27:12 volumiosplendid dnsmasq[1180]: dnsmasq: syntax check OK. Oct 31 09:27:12 volumiosplendid hostapd[1181]: Configuration file: /etc/hostapd/hostapd.conf Oct 31 09:27:12 volumiosplendid hostapd[1181]: wlan0: Could not connect to kernel driver Oct 31 09:27:12 volumiosplendid hostapd[1181]: Using interface wlan0 with hwaddr dc:a6:32:fd:06:b2 and ssid "Volumio-76B83" Oct 31 09:27:12 volumiosplendid dnsmasq[1187]: started, version 2.80 cachesize 150 Oct 31 09:27:12 volumiosplendid dnsmasq[1187]: compile time options: IPv6 GNU-getopt DBus i18n IDN DHCP DHCPv6 no-Lua TFTP conntrack ipset auth DNSSEC loop-detect inotify dumpfile Oct 31 09:27:12 volumiosplendid dnsmasq-dhcp[1187]: DHCP, IP range 192.168.211.100 -- 192.168.211.200, lease time 1d Oct 31 09:27:12 volumiosplendid dnsmasq[1187]: reading /etc/resolv.conf Oct 31 09:27:12 volumiosplendid dnsmasq[1187]: using nameserver 8.8.8.8#53 Oct 31 09:27:12 volumiosplendid dnsmasq[1187]: using nameserver 1.1.1.1#53 Oct 31 09:27:12 volumiosplendid dnsmasq[1187]: using nameserver 208.67.222.222#53 Oct 31 09:27:12 volumiosplendid dnsmasq[1187]: using nameserver 208.67.220.220#53 Oct 31 09:27:12 volumiosplendid dnsmasq[1187]: read /etc/hosts - 1 addresses Oct 31 09:27:13 volumiosplendid dhcpcd[950]: wlan0: carrier acquired Oct 31 09:27:13 volumiosplendid hostapd[1181]: wlan0: interface state UNINITIALIZED->ENABLED Oct 31 09:27:13 volumiosplendid hostapd[1181]: wlan0: AP-ENABLED Oct 31 09:27:13 volumiosplendid systemd[1]: Started Advanced IEEE 802.11 AP and IEEE 802.1X/WPA/WPA2/EAP Authenticator. Oct 31 09:27:13 volumiosplendid systemd[1]: Started dnsmasq - A lightweight DHCP and caching DNS server. Oct 31 09:27:13 volumiosplendid dhcpcd[950]: wlan0: IAID 32:fd:06:b2 Oct 31 09:27:13 volumiosplendid dhcpcd[950]: wlan0: adding address fe80::dea6:32ff:fefd:6b2 Oct 31 09:27:13 volumiosplendid dhcpcd[950]: ipv6_addaddr1: Permission denied Oct 31 09:27:13 volumiosplendid systemd[1]: Reached target Host and Network Name Lookups. Oct 31 09:27:13 volumiosplendid iwconfig[1196]: Error for wireless request "Set Power Management" (8B2C) : Oct 31 09:27:13 volumiosplendid iwconfig[1196]: SET failed on device wlan0 ; Invalid argument. Oct 31 09:27:13 volumiosplendid systemd[1]: Started Wireless Services. Oct 31 09:27:13 volumiosplendid systemd[1]: Started Volumio Backend Module. Oct 31 09:27:13 volumiosplendid systemd[1]: Started Volumio Cpu Tweaker. Oct 31 09:27:13 volumiosplendid systemd[1]: Reached target Multi-User System. Oct 31 09:27:13 volumiosplendid systemd[1]: Reached target Graphical Interface. Oct 31 09:27:13 volumiosplendid systemd[1]: Starting Update UTMP about System Runlevel Changes... Oct 31 09:27:13 volumiosplendid systemd[1]: systemd-update-utmp-runlevel.service: Succeeded. Oct 31 09:27:13 volumiosplendid systemd[1]: Started Update UTMP about System Runlevel Changes. Oct 31 09:27:13 volumiosplendid systemd[1]: Startup finished in 11.800s (kernel) + 34.021s (userspace) = 45.821s. Oct 31 09:27:13 volumiosplendid volumio-cpu-tweak[1198]: Setting RT Priority for mpd Oct 31 09:27:13 volumiosplendid volumio-cpu-tweak[1198]: Setting MPD Affinity Oct 31 09:27:13 volumiosplendid volumio-cpu-tweak[1198]: pid 814's current affinity mask: f Oct 31 09:27:13 volumiosplendid volumio-cpu-tweak[1198]: pid 814's new affinity mask: 3 Oct 31 09:27:13 volumiosplendid volumio-cpu-tweak[1198]: /bin/volumio_cpu_tweak: line 27: warning: command substitution: ignored null byte in input Oct 31 09:27:13 volumiosplendid volumio-cpu-tweak[1198]: VOLUMIO CPU TWEAK: Setting CPU Governor: performance Oct 31 09:27:13 volumiosplendid systemd[1]: volumio_cpu_tweak.service: Succeeded. Oct 31 09:27:13 volumiosplendid dhcpcd[950]: wlan0: soliciting an IPv6 router Oct 31 09:27:13 volumiosplendid systemd[1]: systemd-hostnamed.service: Succeeded. Oct 31 09:27:13 volumiosplendid kernel: hwmon hwmon1: Undervoltage detected! Oct 31 09:27:13 volumiosplendid dhcpcd[950]: wlan0: soliciting a DHCP lease Oct 31 09:27:14 volumiosplendid ntpd[805]: Listen normally on 4 wlan0 192.168.211.1:123 Oct 31 09:27:14 volumiosplendid ntpd[805]: new interface(s) found: waking up resolver Oct 31 09:27:15 volumiosplendid volumio-remote-updater[587]: [2025-10-31 09:27:15] [connect] Successful connection Oct 31 09:27:16 volumiosplendid volumio[1197]: info: ------------------------------------------- Oct 31 09:27:16 volumiosplendid volumio[1197]: info: ----- Volumio3 ---- Oct 31 09:27:16 volumiosplendid volumio[1197]: info: ------------------------------------------- Oct 31 09:27:16 volumiosplendid volumio[1197]: info: ----- System startup ---- Oct 31 09:27:16 volumiosplendid volumio[1197]: info: ------------------------------------------- Oct 31 09:27:16 volumiosplendid volumio[1197]: info: MYVOLUMIO Environment detected Oct 31 09:27:16 volumiosplendid volumio[1197]: info: Plugin folders cleanup Oct 31 09:27:16 volumiosplendid volumio[1197]: info: Scanning into folder /volumio/app/plugins/ Oct 31 09:27:16 volumiosplendid volumio[1197]: info: Scanning category audio_interface Oct 31 09:27:16 volumiosplendid volumio[1197]: info: Scanning category miscellanea Oct 31 09:27:16 volumiosplendid volumio[1197]: info: Scanning category music_service Oct 31 09:27:16 volumiosplendid volumio[1197]: info: Scanning category plugins.json Oct 31 09:27:16 volumiosplendid volumio[1197]: info: Scanning category system_controller Oct 31 09:27:16 volumiosplendid volumio[1197]: info: Scanning category user_interface Oct 31 09:27:16 volumiosplendid volumio[1197]: info: Scanning into folder /data/plugins/ Oct 31 09:27:16 volumiosplendid volumio[1197]: info: Scanning category audio_interface Oct 31 09:27:16 volumiosplendid volumio[1197]: info: Scanning category music_service Oct 31 09:27:16 volumiosplendid volumio[1197]: info: Plugin folders cleanup completed Oct 31 09:27:16 volumiosplendid volumio[1197]: info: ------------------------------------------- Oct 31 09:27:16 volumiosplendid volumio[1197]: info: ----- Core plugins startup ---- Oct 31 09:27:16 volumiosplendid volumio[1197]: info: ------------------------------------------- Oct 31 09:27:16 volumiosplendid volumio[1197]: info: Loading plugins from folder /volumio/app/plugins/ Oct 31 09:27:16 volumiosplendid volumio[1197]: info: Adding plugin upnp to MyMusic Plugins Oct 31 09:27:16 volumiosplendid volumio[1197]: info: Adding plugin airplay_emulation to MyMusic Plugins Oct 31 09:27:16 volumiosplendid volumio[1197]: info: Adding plugin upnp_browser to MyMusic Plugins Oct 31 09:27:16 volumiosplendid volumio[1197]: info: Loading plugins from folder /data/plugins/ Oct 31 09:27:16 volumiosplendid volumio[1197]: info: Loading plugin "system"... Oct 31 09:27:16 volumiosplendid volumio[1197]: info: Loading plugin "appearance"... Oct 31 09:27:18 volumiosplendid volumio[1197]: info: Loading plugin "network"... Oct 31 09:27:18 volumiosplendid volumio[1197]: info: Refreshing Cached IP Addresses Oct 31 09:27:18 volumiosplendid volumio[1197]: info: Loading plugin "services"... Oct 31 09:27:18 volumiosplendid volumio[1197]: info: Loading plugin "alsa_controller"... Oct 31 09:27:18 volumiosplendid sudo[1233]: volumio : unable to resolve host volumiosplendid Oct 31 09:27:18 volumiosplendid sudo[1233]: volumio : problem with defaults entries ; TTY=unknown ; PWD=/ ; USER=root ; Oct 31 09:27:18 volumiosplendid sudo[1233]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 31 09:27:18 volumiosplendid sudo[1233]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 31 09:27:18 volumiosplendid sudo[1235]: volumio : unable to resolve host volumiosplendid Oct 31 09:27:18 volumiosplendid sudo[1235]: volumio : problem with defaults entries ; TTY=unknown ; PWD=/ ; USER=root ; Oct 31 09:27:18 volumiosplendid sudo[1235]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 31 09:27:18 volumiosplendid sudo[1233]: pam_unix(sudo:session): session closed for user root Oct 31 09:27:18 volumiosplendid sudo[1235]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 31 09:27:18 volumiosplendid sudo[1235]: pam_unix(sudo:session): session closed for user root Oct 31 09:27:18 volumiosplendid sudo[1242]: volumio : unable to resolve host volumiosplendid Oct 31 09:27:18 volumiosplendid sudo[1242]: volumio : problem with defaults entries ; TTY=unknown ; PWD=/ ; USER=root ; Oct 31 09:27:18 volumiosplendid sudo[1242]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Oct 31 09:27:18 volumiosplendid sudo[1242]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 31 09:27:18 volumiosplendid sudo[1242]: pam_unix(sudo:session): session closed for user root Oct 31 09:27:18 volumiosplendid kernel: ieee80211 phy0: brcmf_vif_set_mgmt_ie: vndr ie set error : -52 Oct 31 09:27:18 volumiosplendid kernel: ieee80211 phy0: brcmf_cfg80211_scan: scan error (-52) Oct 31 09:27:18 volumiosplendid volumio[1197]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 31 09:27:18 volumiosplendid volumio[1197]: info: Loading plugin "wizard"... Oct 31 09:27:18 volumiosplendid volumio[1197]: info: Loading plugin "networkfs"... Oct 31 09:27:18 volumiosplendid volumio[1197]: info: Starting Udev Watcher for removable devices Oct 31 09:27:18 volumiosplendid volumio[1197]: info: Ignoring mount for partition: boot Oct 31 09:27:18 volumiosplendid volumio[1197]: info: Ignoring mount for partition: volumio Oct 31 09:27:18 volumiosplendid volumio[1197]: info: Ignoring mount for partition: volumio_data Oct 31 09:27:18 volumiosplendid volumio[1197]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 31 09:27:18 volumiosplendid volumio[1197]: info: Loading plugin "volumio_command_line_client"... Oct 31 09:27:18 volumiosplendid volumio[1197]: info: Loading plugin "upnp"... Oct 31 09:27:18 volumiosplendid volumio[1197]: info: [1761913638627] Starting Upmpd Daemon Oct 31 09:27:18 volumiosplendid volumio[1197]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 31 09:27:18 volumiosplendid volumio[1197]: info: Loading plugin "my_music"... Oct 31 09:27:18 volumiosplendid volumio[1197]: info: Loading plugin "mpd"... Oct 31 09:27:18 volumiosplendid dhcpcd[950]: wlan0: probing for an IPv4LL address Oct 31 09:27:19 volumiosplendid volumio[1197]: info: Loading plugin "upnp_browser"... Oct 31 09:27:19 volumiosplendid volumio[1197]: info: Loading plugin "alarm-clock"... Oct 31 09:27:20 volumiosplendid volumio[1197]: info: Loading plugin "airplay_emulation"... Oct 31 09:27:20 volumiosplendid volumio[1197]: info: Starting Shairport Sync Oct 31 09:27:20 volumiosplendid volumio[1197]: info: Loading plugin "last_100"... Oct 31 09:27:20 volumiosplendid volumio[1197]: info: Loading plugin "webradio"... Oct 31 09:27:20 volumiosplendid volumio[1197]: info: Loading plugin "i2s_dacs"... Oct 31 09:27:20 volumiosplendid volumio[1197]: info: Loading plugin "volumiodiscovery"... Oct 31 09:27:20 volumiosplendid volumio[1197]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Oct 31 09:27:20 volumiosplendid node[1197]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Oct 31 09:27:20 volumiosplendid volumio[1197]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 31 09:27:20 volumiosplendid volumio[1197]: *** WARNING *** For more information see Oct 31 09:27:20 volumiosplendid volumio[1197]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Oct 31 09:27:20 volumiosplendid volumio[1197]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 31 09:27:20 volumiosplendid volumio[1197]: *** WARNING *** For more information see Oct 31 09:27:20 volumiosplendid node[1197]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 31 09:27:20 volumiosplendid node[1197]: *** WARNING *** For more information see Oct 31 09:27:20 volumiosplendid node[1197]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Oct 31 09:27:20 volumiosplendid node[1197]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 31 09:27:20 volumiosplendid node[1197]: *** WARNING *** For more information see Oct 31 09:27:20 volumiosplendid volumio[1197]: info: Applying required configuration parameters for plugin volumiodiscovery Oct 31 09:27:20 volumiosplendid volumio[1197]: info: Discovery: Started advertising with name: Volumio_Splendid Oct 31 09:27:20 volumiosplendid volumio[1197]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 31 09:27:20 volumiosplendid volumio[1197]: info: Loading plugin "spop"... Oct 31 09:27:21 volumiosplendid volumio[1197]: info: Loading plugin "outputs"... Oct 31 09:27:21 volumiosplendid volumio[1197]: info: Loading plugin "albumart"... Oct 31 09:27:21 volumiosplendid volumio[1197]: info: Plugin example_plugin is not enabled Oct 31 09:27:21 volumiosplendid volumio[1197]: info: Loading plugin "inputs"... Oct 31 09:27:21 volumiosplendid volumio[1197]: info: Loading plugin "updater_comm"... Oct 31 09:27:22 volumiosplendid volumio[1197]: info: Plugin mpdemulation is not enabled Oct 31 09:27:22 volumiosplendid volumio[1197]: info: Loading plugin "rest_api"... Oct 31 09:27:22 volumiosplendid volumio[1197]: info: Loading plugin "websocket"... Oct 31 09:27:22 volumiosplendid volumio[1197]: info: Starting Socket.io Server version 2.3.0 Oct 31 09:27:22 volumiosplendid volumio[1197]: info: Loading plugin "fusiondsp"... Oct 31 09:27:22 volumiosplendid volumio[1197]: Forking 3 albumart workers Oct 31 09:27:22 volumiosplendid volumio[1197]: info: Applying required configuration parameters for plugin fusiondsp Oct 31 09:27:22 volumiosplendid volumio[1197]: info: Loading plugin "mpdoutput"... Oct 31 09:27:23 volumiosplendid volumio[1197]: info: Loading i18n strings for locale es Oct 31 09:27:23 volumiosplendid volumio[1197]: Updating browse sources language Oct 31 09:27:23 volumiosplendid volumio[1197]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 31 09:27:23 volumiosplendid volumio[1197]: Starting albumart workers Oct 31 09:27:23 volumiosplendid volumio[1197]: Starting albumart workers Oct 31 09:27:23 volumiosplendid volumio[1197]: Starting albumart workers Oct 31 09:27:23 volumiosplendid volumio[1197]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 31 09:27:23 volumiosplendid volumio[1197]: info: CoreCommandRouter::initPlayerControls Oct 31 09:27:23 volumiosplendid volumio[1197]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 09:27:23 volumiosplendid volumio[1197]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 09:27:23 volumiosplendid volumio[1197]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 09:27:23 volumiosplendid volumio[1197]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 09:27:23 volumiosplendid volumio[1197]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 09:27:23 volumiosplendid volumio[1197]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 09:27:23 volumiosplendid volumio[1197]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 09:27:23 volumiosplendid volumio[1197]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 09:27:23 volumiosplendid volumio[1197]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 31 09:27:23 volumiosplendid volumio[1197]: Express server listening on port 3000 Oct 31 09:27:23 volumiosplendid volumio[1197]: [Metrics] WebUI: 8s 356.99ms Oct 31 09:27:23 volumiosplendid volumio[1197]: info: CoreStateMachine::resetVolumioState Oct 31 09:27:23 volumiosplendid volumio[1197]: info: CoreStateMachine::getcurrentVolume Oct 31 09:27:23 volumiosplendid volumio[1197]: info: CoreCommandRouter::volumioRetrievevolume Oct 31 09:27:23 volumiosplendid volumio[1197]: info: Volumio Network Manager: Network status updated: 1 Oct 31 09:27:23 volumiosplendid volumio[1197]: error: An error occurred while scanning: Error: Command failed: sudo /sbin/iwlist wlan0 scan Oct 31 09:27:23 volumiosplendid volumio[1197]: sudo: unable to resolve host volumiosplendid: System error Oct 31 09:27:23 volumiosplendid volumio[1197]: wlan0 Interface doesn't support scanning : Invalid exchange Oct 31 09:27:23 volumiosplendid volumio[1197]: info: Cannot use regular scanning, forcing with ap-force Oct 31 09:27:23 volumiosplendid dhcpcd[950]: wlan0: using IPv4LL address 169.254.248.163 Oct 31 09:27:23 volumiosplendid avahi-daemon[590]: Registering new address record for 169.254.248.163 on wlan0.IPv4. Oct 31 09:27:23 volumiosplendid dhcpcd[950]: wlan0: adding route to 169.254.0.0/16 Oct 31 09:27:24 volumiosplendid sudo[1295]: volumio : unable to resolve host volumiosplendid Oct 31 09:27:24 volumiosplendid sudo[1295]: volumio : problem with defaults entries ; TTY=unknown ; PWD=/ ; USER=root ; Oct 31 09:27:24 volumiosplendid sudo[1295]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iw dev wlan0 scan ap-force Oct 31 09:27:24 volumiosplendid sudo[1295]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 31 09:27:25 volumiosplendid ntpd[805]: Listen normally on 5 wlan0 169.254.248.163:123 Oct 31 09:27:25 volumiosplendid ntpd[805]: new interface(s) found: waking up resolver Oct 31 09:27:27 volumiosplendid sudo[1295]: pam_unix(sudo:session): session closed for user root Oct 31 09:27:27 volumiosplendid volumio[1197]: sudo: unable to resolve host volumiosplendid: System error Oct 31 09:27:27 volumiosplendid volumio[1197]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 31 09:27:27 volumiosplendid volumio[1197]: info: Reloading queue from file Oct 31 09:27:27 volumiosplendid volumio[1197]: info: CoreStateMachine::setRepeat null single undefined Oct 31 09:27:27 volumiosplendid volumio[1197]: info: CoreStateMachine::pushState Oct 31 09:27:27 volumiosplendid volumio[1197]: info: CorePlayQueue::getTrack 0 Oct 31 09:27:27 volumiosplendid volumio[1197]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 31 09:27:27 volumiosplendid volumio[1197]: info: CoreCommandRouter::volumioPushState Oct 31 09:27:27 volumiosplendid volumio[1197]: info: CoreStateMachine::setRandom true Oct 31 09:27:27 volumiosplendid volumio[1197]: info: CoreStateMachine::pushState Oct 31 09:27:27 volumiosplendid volumio[1197]: info: CorePlayQueue::getTrack 0 Oct 31 09:27:27 volumiosplendid volumio[1197]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 31 09:27:27 volumiosplendid volumio[1197]: info: CoreCommandRouter::volumioPushState Oct 31 09:27:27 volumiosplendid volumio[1197]: info: VolumeController:: Volume=99 Mute =false Oct 31 09:27:27 volumiosplendid volumio[1197]: info: CoreStateMachine::pushState Oct 31 09:27:27 volumiosplendid volumio[1197]: info: CorePlayQueue::getTrack 0 Oct 31 09:27:27 volumiosplendid volumio[1197]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 31 09:27:27 volumiosplendid volumio[1197]: info: CoreCommandRouter::volumioPushState Oct 31 09:27:27 volumiosplendid volumio[1197]: info: CoreStateMachine::updateTrackBlock Oct 31 09:27:27 volumiosplendid volumio[1197]: info: CorePlayQueue::getTrackBlock Oct 31 09:27:27 volumiosplendid volumio[1197]: info: CoreCommandRouter::volumioRetrievevolume Oct 31 09:27:27 volumiosplendid volumio[1197]: info: Setting Device type: Raspberry PI Oct 31 09:27:27 volumiosplendid volumio[1197]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Oct 31 09:27:27 volumiosplendid volumio[1197]: info: USB Boot Capable - System SBC Revision found in cpuinfo: d03114 Oct 31 09:27:27 volumiosplendid volumio[1197]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Oct 31 09:27:27 volumiosplendid volumio[1197]: info: Completed loading Core Plugins Oct 31 09:27:27 volumiosplendid volumio[1197]: info: Preparing to generate the ALSA configuration file Oct 31 09:27:27 volumiosplendid volumio[1197]: info: The plugin fusiondsp has an ALSA contribution file volumioDsp.postDsp.10.conf Oct 31 09:27:27 volumiosplendid volumio[1197]: info: Reading ALSA contributions from plugins. Oct 31 09:27:27 volumiosplendid volumio[1197]: info: Asound.conf file unchanged, so no further update is needed Oct 31 09:27:27 volumiosplendid volumio[1197]: info: Output device has changed, restarting MPD Oct 31 09:27:27 volumiosplendid volumio[1197]: info: Output device has changed, restarting Shairport Sync Oct 31 09:27:27 volumiosplendid volumio[1197]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 09:27:27 volumiosplendid volumio[1197]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 31 09:27:27 volumiosplendid volumio[1197]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 31 09:27:27 volumiosplendid volumio[1197]: info: ___________ START PLUGINS ___________ Oct 31 09:27:27 volumiosplendid volumio[1197]: info: ControllerMpd::onStart: Initializing MPD Oct 31 09:27:27 volumiosplendid volumio[1197]: info: Creating MPD Configuration file Oct 31 09:27:28 volumiosplendid volumio[1197]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 31 09:27:28 volumiosplendid volumio[1197]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 31 09:27:28 volumiosplendid volumio[1197]: info: [1761913648021] CoreMusicLibrary::Adding element Media Servers Oct 31 09:27:28 volumiosplendid volumio[1197]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 31 09:27:28 volumiosplendid volumio[1197]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 09:27:28 volumiosplendid volumio[1197]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 31 09:27:28 volumiosplendid sudo[1352]: volumio : unable to resolve host volumiosplendid Oct 31 09:27:28 volumiosplendid sudo[1352]: volumio : problem with defaults entries ; TTY=unknown ; PWD=/ ; USER=root ; Oct 31 09:27:28 volumiosplendid sudo[1352]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 31 09:27:28 volumiosplendid sudo[1352]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 31 09:27:28 volumiosplendid sudo[1352]: pam_unix(sudo:session): session closed for user root Oct 31 09:27:28 volumiosplendid sudo[1354]: volumio : unable to resolve host volumiosplendid Oct 31 09:27:28 volumiosplendid sudo[1354]: volumio : problem with defaults entries ; TTY=unknown ; PWD=/ ; USER=root ; Oct 31 09:27:28 volumiosplendid sudo[1354]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 31 09:27:28 volumiosplendid sudo[1354]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 31 09:27:28 volumiosplendid volumio[1197]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 31 09:27:28 volumiosplendid volumio[1197]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 09:27:28 volumiosplendid volumio[1197]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 31 09:27:28 volumiosplendid systemd[1]: Stopping Music Player Daemon... Oct 31 09:27:28 volumiosplendid volumio[1197]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 31 09:27:28 volumiosplendid volumio[1197]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 31 09:27:28 volumiosplendid volumio[1197]: info: [1761913648114] CoreMusicLibrary::Adding element Last_100 Oct 31 09:27:28 volumiosplendid volumio[1197]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 31 09:27:28 volumiosplendid volumio[1197]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 31 09:27:28 volumiosplendid volumio[1197]: info: [1761913648116] CoreMusicLibrary::Adding element Webradio Oct 31 09:27:28 volumiosplendid volumio[1197]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 31 09:27:28 volumiosplendid volumio[1197]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 31 09:27:28 volumiosplendid sudo[1359]: volumio : unable to resolve host volumiosplendid Oct 31 09:27:28 volumiosplendid sudo[1361]: volumio : unable to resolve host volumiosplendid Oct 31 09:27:28 volumiosplendid sudo[1359]: volumio : problem with defaults entries ; TTY=unknown ; PWD=/ ; USER=root ; Oct 31 09:27:28 volumiosplendid volumio[1197]: info: Initializing BBC Radios Oct 31 09:27:28 volumiosplendid sudo[1361]: volumio : problem with defaults entries ; TTY=unknown ; PWD=/ ; USER=root ; Oct 31 09:27:28 volumiosplendid sudo[1359]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 31 09:27:28 volumiosplendid sudo[1359]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 31 09:27:28 volumiosplendid sudo[1361]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 31 09:27:28 volumiosplendid sudo[1361]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 31 09:27:28 volumiosplendid sudo[1359]: pam_unix(sudo:session): session closed for user root Oct 31 09:27:28 volumiosplendid volumio[1197]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 31 09:27:28 volumiosplendid volumio[1197]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 31 09:27:28 volumiosplendid systemd[1]: mpd.service: Succeeded. Oct 31 09:27:28 volumiosplendid systemd[1]: Stopped Music Player Daemon. Oct 31 09:27:28 volumiosplendid volumio[1197]: info: Creating Spotify config file Oct 31 09:27:28 volumiosplendid volumio[1197]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 09:27:28 volumiosplendid systemd[1]: Starting Music Player Daemon... Oct 31 09:27:28 volumiosplendid volumio[1197]: info: Loading i18n strings for locale es Oct 31 09:27:28 volumiosplendid volumio[1197]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , updateALSAConfigFile Oct 31 09:27:28 volumiosplendid volumio[1197]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 09:27:28 volumiosplendid volumio[1197]: info: FusionDsp - mixtype--------------------- Hardware Oct 31 09:27:28 volumiosplendid volumio[1197]: info: Volumio Calling Home Oct 31 09:27:28 volumiosplendid sudo[1382]: root : unable to resolve host volumiosplendid Oct 31 09:27:28 volumiosplendid sudo[1382]: root : problem with defaults entries ; TTY=unknown ; PWD=/ ; USER=root ; Oct 31 09:27:28 volumiosplendid sudo[1382]: sudo: unable to resolve host volumiosplendid: System error Oct 31 09:27:28 volumiosplendid volumio[1197]: info: Preparing to generate the ALSA configuration file Oct 31 09:27:28 volumiosplendid sudo[1382]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Oct 31 09:27:28 volumiosplendid sudo[1382]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 31 09:27:28 volumiosplendid sudo[1382]: pam_unix(sudo:session): session closed for user root Oct 31 09:27:28 volumiosplendid volumio[1197]: info: Discovery: adding a396bbe5-1d27-4fda-8d3a-0f7e20475f69 Oct 31 09:27:28 volumiosplendid volumio[1197]: info: Discovery: Found device Volumio_Splendid Oct 31 09:27:28 volumiosplendid volumio[1197]: info: CoreCommandRouter::volumioGetState Oct 31 09:27:28 volumiosplendid volumio[1197]: info: CorePlayQueue::getTrack 0 Oct 31 09:27:28 volumiosplendid volumio[1197]: info: Discovery: this is already registered, a396bbe5-1d27-4fda-8d3a-0f7e20475f69 Oct 31 09:27:28 volumiosplendid volumio[1197]: info: Discovery: Found device Volumio_Splendid Oct 31 09:27:28 volumiosplendid volumio[1197]: info: CoreCommandRouter::volumioGetState Oct 31 09:27:28 volumiosplendid volumio[1197]: info: CorePlayQueue::getTrack 0 Oct 31 09:27:28 volumiosplendid volumio[1197]: info: The plugin fusiondsp has an ALSA contribution file volumioDsp.postDsp.10.conf Oct 31 09:27:28 volumiosplendid volumio[1197]: info: Reading ALSA contributions from plugins. Oct 31 09:27:28 volumiosplendid volumio[1197]: info: MPD Permissions set Oct 31 09:27:28 volumiosplendid volumio[1197]: info: MPD Permissions set Oct 31 09:27:28 volumiosplendid volumio[1197]: info: VolumeController:: Volume=99 Mute =false Oct 31 09:27:28 volumiosplendid volumio[1197]: info: CoreStateMachine::pushState Oct 31 09:27:28 volumiosplendid volumio[1197]: info: CorePlayQueue::getTrack 0 Oct 31 09:27:28 volumiosplendid volumio[1197]: info: CoreCommandRouter::volumioPushState Oct 31 09:27:28 volumiosplendid volumio[1197]: info: Spotify config file written Oct 31 09:27:28 volumiosplendid sudo[1403]: volumio : unable to resolve host volumiosplendid Oct 31 09:27:28 volumiosplendid sudo[1403]: volumio : problem with defaults entries ; TTY=unknown ; PWD=/ ; USER=root ; Oct 31 09:27:28 volumiosplendid sudo[1405]: volumio : unable to resolve host volumiosplendid Oct 31 09:27:28 volumiosplendid sudo[1405]: volumio : problem with defaults entries ; TTY=unknown ; PWD=/ ; USER=root ; Oct 31 09:27:28 volumiosplendid sudo[1403]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 31 09:27:28 volumiosplendid sudo[1403]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 31 09:27:28 volumiosplendid sudo[1405]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 31 09:27:28 volumiosplendid sudo[1405]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 31 09:27:28 volumiosplendid sudo[1403]: pam_unix(sudo:session): session closed for user root Oct 31 09:27:28 volumiosplendid sudo[1405]: pam_unix(sudo:session): session closed for user root Oct 31 09:27:28 volumiosplendid volumio[1197]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 1 Oct 31 09:27:28 volumiosplendid volumio[1197]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 09:27:28 volumiosplendid volumio[1197]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 09:27:28 volumiosplendid volumio[1197]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 09:27:28 volumiosplendid volumio[1197]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 09:27:28 volumiosplendid volumio[1197]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 09:27:28 volumiosplendid volumio[1197]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 09:27:28 volumiosplendid volumio[1197]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 09:27:28 volumiosplendid volumio[1197]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 09:27:28 volumiosplendid volumio[1197]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 31 09:27:28 volumiosplendid volumio[1197]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 09:27:28 volumiosplendid volumio[1197]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 09:27:28 volumiosplendid sudo[1407]: volumio : unable to resolve host volumiosplendid Oct 31 09:27:28 volumiosplendid sudo[1407]: volumio : problem with defaults entries ; TTY=unknown ; PWD=/ ; USER=root ; Oct 31 09:27:28 volumiosplendid sudo[1407]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Oct 31 09:27:28 volumiosplendid sudo[1407]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 31 09:27:28 volumiosplendid volumio[1197]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 31 09:27:28 volumiosplendid volumio[1197]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 09:27:28 volumiosplendid volumio[1197]: info: No need to fix Spotify hosts Oct 31 09:27:29 volumiosplendid systemd[1]: Started go-librespot Daemon. Oct 31 09:27:29 volumiosplendid go-librespot[1419]: go-librespot daemon starting... Oct 31 09:27:29 volumiosplendid systemd[1]: systemd-timedated.service: Succeeded. Oct 31 09:27:29 volumiosplendid sudo[1407]: pam_unix(sudo:session): session closed for user root Oct 31 09:27:29 volumiosplendid volumio[1197]: info: Starting Shairport Sync Oct 31 09:27:29 volumiosplendid volumio[1197]: info: Starting Shairport Sync Oct 31 09:27:29 volumiosplendid volumio[1197]: info: Starting Shairport Sync Oct 31 09:27:29 volumiosplendid sudo[1429]: volumio : unable to resolve host volumiosplendid Oct 31 09:27:29 volumiosplendid sudo[1429]: volumio : problem with defaults entries ; TTY=unknown ; PWD=/ ; USER=root ; Oct 31 09:27:29 volumiosplendid volumio[1197]: info: CoreCommandRouter::volumioGetState Oct 31 09:27:29 volumiosplendid volumio[1197]: info: CorePlayQueue::getTrack 0 Oct 31 09:27:29 volumiosplendid sudo[1429]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 31 09:27:29 volumiosplendid sudo[1429]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 31 09:27:29 volumiosplendid sudo[1431]: volumio : unable to resolve host volumiosplendid Oct 31 09:27:29 volumiosplendid sudo[1431]: volumio : problem with defaults entries ; TTY=unknown ; PWD=/ ; USER=root ; Oct 31 09:27:29 volumiosplendid sudo[1431]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 31 09:27:29 volumiosplendid sudo[1433]: volumio : unable to resolve host volumiosplendid Oct 31 09:27:29 volumiosplendid sudo[1433]: volumio : problem with defaults entries ; TTY=unknown ; PWD=/ ; USER=root ; Oct 31 09:27:29 volumiosplendid sudo[1431]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 31 09:27:29 volumiosplendid sudo[1433]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 31 09:27:29 volumiosplendid sudo[1433]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 31 09:27:29 volumiosplendid systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Oct 31 09:27:29 volumiosplendid sudo[1435]: volumio : unable to resolve host volumiosplendid Oct 31 09:27:29 volumiosplendid systemd[1]: shairport-sync.service: Succeeded. Oct 31 09:27:29 volumiosplendid systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Oct 31 09:27:29 volumiosplendid sudo[1435]: volumio : problem with defaults entries ; TTY=unknown ; PWD=/ ; USER=root ; Oct 31 09:27:29 volumiosplendid sudo[1435]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Oct 31 09:27:29 volumiosplendid sudo[1435]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 31 09:27:29 volumiosplendid volumio[1197]: info: Asound.conf file unchanged, so no further update is needed Oct 31 09:27:29 volumiosplendid volumio[1197]: info: Output device has changed, restarting MPD Oct 31 09:27:29 volumiosplendid go-librespot[1419]: time="2025-10-31T09:27:29-03:00" level=info msg="running go-librespot 0.3.2" Oct 31 09:27:29 volumiosplendid go-librespot[1419]: time="2025-10-31T09:27:29-03:00" level=debug msg="app state loaded" Oct 31 09:27:29 volumiosplendid go-librespot[1419]: time="2025-10-31T09:27:29-03:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 31 09:27:29 volumiosplendid volumio[1197]: info: Output device has changed, restarting Shairport Sync Oct 31 09:27:29 volumiosplendid volumio[1197]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 09:27:29 volumiosplendid volumio[1197]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 31 09:27:29 volumiosplendid systemd[1]: Started UPnP Renderer front-end to MPD. Oct 31 09:27:29 volumiosplendid sudo[1435]: pam_unix(sudo:session): session closed for user root Oct 31 09:27:29 volumiosplendid systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Oct 31 09:27:29 volumiosplendid sudo[1433]: pam_unix(sudo:session): session closed for user root Oct 31 09:27:29 volumiosplendid sudo[1431]: pam_unix(sudo:session): session closed for user root Oct 31 09:27:29 volumiosplendid sudo[1441]: volumio : unable to resolve host volumiosplendid Oct 31 09:27:29 volumiosplendid sudo[1441]: volumio : problem with defaults entries ; TTY=unknown ; PWD=/ ; USER=root ; Oct 31 09:27:29 volumiosplendid sudo[1429]: pam_unix(sudo:session): session closed for user root Oct 31 09:27:29 volumiosplendid sudo[1441]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 31 09:27:29 volumiosplendid sudo[1441]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 31 09:27:29 volumiosplendid sudo[1443]: volumio : unable to resolve host volumiosplendid Oct 31 09:27:29 volumiosplendid sudo[1443]: volumio : problem with defaults entries ; TTY=unknown ; PWD=/ ; USER=root ; Oct 31 09:27:29 volumiosplendid sudo[1441]: pam_unix(sudo:session): session closed for user root Oct 31 09:27:29 volumiosplendid sudo[1443]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 31 09:27:29 volumiosplendid sudo[1443]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 31 09:27:29 volumiosplendid volumio[1197]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 31 09:27:29 volumiosplendid systemd[1]: mpd.service: Main process exited, code=killed, status=15/TERM Oct 31 09:27:29 volumiosplendid systemd[1]: mpd.service: Succeeded. Oct 31 09:27:29 volumiosplendid systemd[1]: Stopped Music Player Daemon. Oct 31 09:27:29 volumiosplendid volumio[1197]: info: Volumio called home Oct 31 09:27:29 volumiosplendid volumio[1197]: info: MPD Permissions set Oct 31 09:27:29 volumiosplendid volumio[1197]: info: Shairport-Sync Started Oct 31 09:27:29 volumiosplendid volumio[1197]: Error adding Membership: Error: addMembership EINVAL Oct 31 09:27:29 volumiosplendid volumio[1197]: info: Upmpdcli Daemon Started Oct 31 09:27:29 volumiosplendid volumio[1197]: info: Shairport-Sync Started Oct 31 09:27:29 volumiosplendid volumio[1197]: info: Shairport-Sync Started Oct 31 09:27:29 volumiosplendid systemd[1]: Starting Music Player Daemon... Oct 31 09:27:29 volumiosplendid volumio[1197]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Oct 31 09:27:29 volumiosplendid volumio[1197]: SPOTIFY: BQAe2aKmFsD7EcfS6X6Qo24QvM3mhft1mRF0u2UA86X4ZVUE14ec3e1vbLpTt9U8NnfzRz_RnOpWp7RLDuEEeXY3wkdq7r5aU2-OHAE8CFC5aiK-7ecCfoEybzITZ9mBygO-n5FpNi7GufI1TpzdXs8vnVJD0vfzXiE7hXWn5-xNyY0XTVuDL7wG7czkwEdrZvvIY7BEzFhv9RvxwoU-2LALtMHqShO5SCs_wQdL3hC2pVw8SghKfAdQIh3_wfqQ_9bom9wSnLtW0ToWj8P37CdHpaOt1Uq7GN4_dzOn7ZQd_uIPINKy0Rc Oct 31 09:27:29 volumiosplendid volumio[1197]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Oct 31 09:27:29 volumiosplendid volumio[1197]: info: New Spotify access token = BQAe2aKmFsD7EcfS6X6Qo24QvM3mhft1mRF0u2UA86X4ZVUE14ec3e1vbLpTt9U8NnfzRz_RnOpWp7RLDuEEeXY3wkdq7r5aU2-OHAE8CFC5aiK-7ecCfoEybzITZ9mBygO-n5FpNi7GufI1TpzdXs8vnVJD0vfzXiE7hXWn5-xNyY0XTVuDL7wG7czkwEdrZvvIY7BEzFhv9RvxwoU-2LALtMHqShO5SCs_wQdL3hC2pVw8SghKfAdQIh3_wfqQ_9bom9wSnLtW0ToWj8P37CdHpaOt1Uq7GN4_dzOn7ZQd_uIPINKy0Rc Oct 31 09:27:29 volumiosplendid volumio[1197]: info: Spotify credentials grant success - running version from March 24, 2019 Oct 31 09:27:29 volumiosplendid volumio[1197]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 09:27:29 volumiosplendid volumio[1197]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 09:27:29 volumiosplendid volumio[1197]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 09:27:29 volumiosplendid volumio[1197]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 09:27:29 volumiosplendid volumio[1197]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 09:27:29 volumiosplendid volumio[1197]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 09:27:29 volumiosplendid volumio[1197]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 09:27:29 volumiosplendid volumio[1197]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 09:27:30 volumiosplendid volumio[1197]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 31 09:27:30 volumiosplendid volumio[1197]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 09:27:30 volumiosplendid volumio[1197]: info: Starting Shairport Sync Oct 31 09:27:30 volumiosplendid volumio[1197]: info: CoreCommandRouter::volumioGetState Oct 31 09:27:30 volumiosplendid volumio[1197]: info: CorePlayQueue::getTrack 0 Oct 31 09:27:30 volumiosplendid volumio[1197]: info: CoreCommandRouter::volumioPause Oct 31 09:27:30 volumiosplendid volumio[1197]: info: CoreStateMachine::pause Oct 31 09:27:30 volumiosplendid volumio[1197]: info: mpdhttpout --- Volumio set on pause Oct 31 09:27:30 volumiosplendid volumio[1197]: info: mpdhttpout ---Configuration successfully added to mpd.conf. Oct 31 09:27:30 volumiosplendid sudo[1462]: volumio : unable to resolve host volumiosplendid Oct 31 09:27:30 volumiosplendid sudo[1462]: volumio : problem with defaults entries ; TTY=unknown ; PWD=/ ; USER=root ; Oct 31 09:27:30 volumiosplendid sudo[1454]: root : unable to resolve host volumiosplendid Oct 31 09:27:30 volumiosplendid sudo[1454]: sudo: unable to resolve host volumiosplendid: System error Oct 31 09:27:30 volumiosplendid sudo[1454]: root : problem with defaults entries ; TTY=unknown ; PWD=/ ; USER=root ; Oct 31 09:27:30 volumiosplendid sudo[1462]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 31 09:27:30 volumiosplendid sudo[1462]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 31 09:27:30 volumiosplendid sudo[1454]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Oct 31 09:27:30 volumiosplendid sudo[1454]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 31 09:27:30 volumiosplendid sudo[1454]: pam_unix(sudo:session): session closed for user root Oct 31 09:27:30 volumiosplendid go-librespot[1419]: time="2025-10-31T09:27:30-03:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Oct 31 09:27:30 volumiosplendid go-librespot[1419]: time="2025-10-31T09:27:30-03: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]" Oct 31 09:27:30 volumiosplendid go-librespot[1419]: time="2025-10-31T09:27:30-03:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Oct 31 09:27:30 volumiosplendid go-librespot[1419]: time="2025-10-31T09:27:30-03:00" level=info msg="zeroconf server listening on port 36841" Oct 31 09:27:30 volumiosplendid systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Oct 31 09:27:30 volumiosplendid systemd[1]: shairport-sync.service: Succeeded. Oct 31 09:27:30 volumiosplendid systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Oct 31 09:27:30 volumiosplendid systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Oct 31 09:27:30 volumiosplendid sudo[1462]: pam_unix(sudo:session): session closed for user root Oct 31 09:27:30 volumiosplendid volumio[1197]: info: Shairport-Sync Started Oct 31 09:27:30 volumiosplendid volumio[1197]: SPOTIFY: User informations: {"country":"AR","display_name":"Ateneo Splendid","email":"mktsplendid@elateneo.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/31w5lzin2hzuavl5uma36fi6d23e"},"followers":{"href":null,"total":1},"href":"https://api.spotify.com/v1/users/31w5lzin2hzuavl5uma36fi6d23e","id":"31w5lzin2hzuavl5uma36fi6d23e","images":[{"height":300,"url":"https://i.scdn.co/image/ab6775700000ee856828d36c433fe641303a52a9","width":300},{"height":64,"url":"https://i.scdn.co/image/ab67757000003b826828d36c433fe641303a52a9","width":64}],"product":"premium","type":"user","uri":"spotify:user:31w5lzin2hzuavl5uma36fi6d23e"} Oct 31 09:27:30 volumiosplendid volumio[1197]: info: Spotify Successfully logged in Oct 31 09:27:30 volumiosplendid volumio[1197]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 31 09:27:30 volumiosplendid volumio[1197]: info: [1761913650437] CoreMusicLibrary::Adding element Spotify Oct 31 09:27:30 volumiosplendid volumio[1197]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 31 09:27:30 volumiosplendid volumio[1197]: Cannot find translation for source Spotify Oct 31 09:27:30 volumiosplendid go-librespot[1419]: time="2025-10-31T09:27:30-03:00" level=debug msg="obtained new client token: AACmxSWVARnqK8I+RtEynlHlMNoNuQ98dhwTiFfi7/mMn43cky4G5hg10CQTL7nCQ3dBVASchkbZWQ60nwb0lVgnpFzQqJ314lAzGyAxmdqcjyB1ZrFtOKpwRbiQhho+5RIbE/FLnD6J83Pvc/7tN0y3F3d4A+TcNPI+3cZHdMz2vueRjUjkmeyCSOvxnJXO0UmUuCaK6P6atn3XlaSg102pggQFa1skNx4m0QAaR5JSgQhlBflpHc3trA==" Oct 31 09:27:30 volumiosplendid volumio[1197]: info: camilladsp service started and running in background, instance 1 Oct 31 09:27:30 volumiosplendid volumio[1197]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 09:27:30 volumiosplendid volumio[1197]: info: FusionDsp - AAAAAAAAAAAAAA-> 22050 44100 48000 88200 96000 176400 192000 <-AAAAAAAAAAAAA Oct 31 09:27:30 volumiosplendid volumio[1197]: info: FusionDsp loaded Oct 31 09:27:30 volumiosplendid volumio[1197]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 31 09:27:30 volumiosplendid go-librespot[1419]: time="2025-10-31T09:27:30-03:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Oct 31 09:27:30 volumiosplendid volumio[1197]: info: FusionDsp - Reporting Fusion DSP Enabled Oct 31 09:27:30 volumiosplendid volumio[1197]: info: Adding Signal Path Element [object Object] Oct 31 09:27:30 volumiosplendid volumio[1197]: info: Adding fusiondspeq DSP Signal Path Element Oct 31 09:27:30 volumiosplendid volumio[1197]: info: FusionDsp - ---- installed callbackRead Oct 31 09:27:30 volumiosplendid volumio[1197]: info: FusionDsp - If filter freq >samplerate/2 then disable it Oct 31 09:27:30 volumiosplendid volumio[1197]: info: FusionDsp - Effects disabled Oct 31 09:27:30 volumiosplendid volumio[1197]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Oct 31 09:27:30 volumiosplendid sudo[1482]: volumio : unable to resolve host volumiosplendid Oct 31 09:27:30 volumiosplendid sudo[1482]: volumio : problem with defaults entries ; TTY=unknown ; PWD=/ ; USER=root ; Oct 31 09:27:30 volumiosplendid sudo[1482]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start fusiondsp.service Oct 31 09:27:30 volumiosplendid sudo[1482]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 31 09:27:30 volumiosplendid volumio[1197]: info: FusionDsp - {"Reload":{"result":"Ok"}} Oct 31 09:27:30 volumiosplendid go-librespot[1419]: time="2025-10-31T09:27:30-03:00" level=debug msg="completed keyexchange" Oct 31 09:27:30 volumiosplendid go-librespot[1419]: time="2025-10-31T09:27:30-03:00" level=debug msg="completed challenge" Oct 31 09:27:30 volumiosplendid volumio-remote-updater[587]: [2025-10-31 09:27:30] [connect] Successful connection Oct 31 09:27:30 volumiosplendid systemd[1]: Started FusionDsp Daemon. Oct 31 09:27:30 volumiosplendid sudo[1482]: pam_unix(sudo:session): session closed for user root Oct 31 09:27:30 volumiosplendid volumio-remote-updater[587]: [2025-10-31 09:27:30] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1761913650 101 Oct 31 09:27:30 volumiosplendid volumio[1197]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 4 Transport: websocket Total Clients: 3 Oct 31 09:27:31 volumiosplendid go-librespot[1419]: time="2025-10-31T09:27:31-03:00" level=info msg="authenticated AP" username="31************************3e" Oct 31 09:27:31 volumiosplendid go-librespot[1419]: time="2025-10-31T09:27:31-03:00" level=info msg="authenticated Login5" username="31************************3e" Oct 31 09:27:31 volumiosplendid go-librespot[1419]: time="2025-10-31T09:27:31-03:00" level=debug msg="initializing zeroconf session" username="31************************3e" Oct 31 09:27:31 volumiosplendid go-librespot[1419]: time="2025-10-31T09:27:31-03:00" level=debug msg="dealer connection opened" Oct 31 09:27:31 volumiosplendid go-librespot[1419]: time="2025-10-31T09:27:31-03:00" level=trace msg="starting accesspoint recv loop" Oct 31 09:27:31 volumiosplendid go-librespot[1419]: time="2025-10-31T09:27:31-03:00" level=trace msg="starting dealer recv loop" Oct 31 09:27:31 volumiosplendid go-librespot[1419]: time="2025-10-31T09:27:31-03:00" level=trace msg="received accesspoint ping" Oct 31 09:27:31 volumiosplendid go-librespot[1419]: time="2025-10-31T09:27:31-03:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Oct 31 09:27:31 volumiosplendid go-librespot[1419]: time="2025-10-31T09:27:31-03:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Oct 31 09:27:31 volumiosplendid go-librespot[1419]: time="2025-10-31T09:27:31-03:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Oct 31 09:27:31 volumiosplendid go-librespot[1419]: time="2025-10-31T09:27:31-03:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Oct 31 09:27:31 volumiosplendid go-librespot[1419]: time="2025-10-31T09:27:31-03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Oct 31 09:27:31 volumiosplendid go-librespot[1419]: time="2025-10-31T09:27:31-03:00" level=debug msg="received connection id: MGE3Y2NlZjgtZTRk...NzE1MTA5QjZEMw==" Oct 31 09:27:31 volumiosplendid mpd[1465]: Oct 31 09:27 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Oct 31 09:27:31 volumiosplendid systemd[1]: Started Music Player Daemon. Oct 31 09:27:31 volumiosplendid sudo[1354]: pam_unix(sudo:session): session closed for user root Oct 31 09:27:31 volumiosplendid sudo[1443]: pam_unix(sudo:session): session closed for user root Oct 31 09:27:31 volumiosplendid sudo[1361]: pam_unix(sudo:session): session closed for user root Oct 31 09:27:31 volumiosplendid volumio[1197]: info: Completed starting Core Plugins Oct 31 09:27:31 volumiosplendid volumio[1197]: info: ------------------------------------------- Oct 31 09:27:31 volumiosplendid volumio[1197]: info: ----- MyVolumio plugins startup ---- Oct 31 09:27:31 volumiosplendid volumio[1197]: info: ------------------------------------------- Oct 31 09:27:31 volumiosplendid volumio[1197]: info: [MyVolumio PluginManager] Fetching plans data.... Oct 31 09:27:31 volumiosplendid volumio[1197]: error: MPD error: The expression evaluated to a falsy value: Oct 31 09:27:31 volumiosplendid volumio[1197]: assert.ok(self.idling) Oct 31 09:27:31 volumiosplendid volumio[1197]: error: The expression evaluated to a falsy value: Oct 31 09:27:31 volumiosplendid volumio[1197]: assert.ok(self.idling) Oct 31 09:27:31 volumiosplendid volumio[1197]: error: MPD error: The expression evaluated to a falsy value: Oct 31 09:27:31 volumiosplendid volumio[1197]: assert.ok(self.idling) Oct 31 09:27:31 volumiosplendid volumio[1197]: error: The expression evaluated to a falsy value: Oct 31 09:27:31 volumiosplendid volumio[1197]: assert.ok(self.idling) Oct 31 09:27:31 volumiosplendid volumio[1197]: info: MPD running with PID1465 Oct 31 09:27:31 volumiosplendid volumio[1197]: ,establishing connection Oct 31 09:27:31 volumiosplendid volumio[1197]: error: MPD error: The expression evaluated to a falsy value: Oct 31 09:27:31 volumiosplendid volumio[1197]: assert.ok(self.idling) Oct 31 09:27:31 volumiosplendid volumio[1197]: error: The expression evaluated to a falsy value: Oct 31 09:27:31 volumiosplendid volumio[1197]: assert.ok(self.idling) Oct 31 09:27:31 volumiosplendid volumio[1197]: error: updateQueue error: null Oct 31 09:27:31 volumiosplendid go-librespot[1419]: time="2025-10-31T09:27:31-03:00" level=trace msg="received accesspoint pong ack" Oct 31 09:27:31 volumiosplendid volumio[1445]: Generating RSA private key, 4096 bit long modulus (2 primes) Oct 31 09:27:31 volumiosplendid go-librespot[1419]: time="2025-10-31T09:27:31-03:00" level=debug msg="put connect state because NEW_DEVICE" Oct 31 09:27:32 volumiosplendid volumio[1197]: info: CoreCommandRouter::executeOnPlugin: mpd , restartMpd Oct 31 09:27:32 volumiosplendid volumio[1197]: info: go-librespot daemon successfully initialized Oct 31 09:27:32 volumiosplendid sudo[1510]: volumio : unable to resolve host volumiosplendid Oct 31 09:27:32 volumiosplendid sudo[1510]: volumio : problem with defaults entries ; TTY=unknown ; PWD=/ ; USER=root ; Oct 31 09:27:32 volumiosplendid sudo[1510]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 31 09:27:32 volumiosplendid sudo[1510]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 31 09:27:32 volumiosplendid systemd[1]: Stopping Music Player Daemon... Oct 31 09:27:32 volumiosplendid systemd[1]: mpd.service: Succeeded. Oct 31 09:27:32 volumiosplendid systemd[1]: Stopped Music Player Daemon. Oct 31 09:27:32 volumiosplendid systemd[1]: Starting Music Player Daemon... Oct 31 09:27:32 volumiosplendid sudo[1512]: root : unable to resolve host volumiosplendid Oct 31 09:27:32 volumiosplendid sudo[1512]: sudo: unable to resolve host volumiosplendid: System error Oct 31 09:27:32 volumiosplendid sudo[1512]: root : problem with defaults entries ; TTY=unknown ; PWD=/ ; USER=root ; Oct 31 09:27:32 volumiosplendid sudo[1512]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Oct 31 09:27:32 volumiosplendid sudo[1512]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 31 09:27:32 volumiosplendid sudo[1512]: pam_unix(sudo:session): session closed for user root Oct 31 09:27:33 volumiosplendid volumio[1445]: .........++++ Oct 31 09:27:34 volumiosplendid mpd[1514]: Oct 31 09:27 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Oct 31 09:27:34 volumiosplendid systemd[1]: Started Music Player Daemon. Oct 31 09:27:34 volumiosplendid sudo[1510]: pam_unix(sudo:session): session closed for user root Oct 31 09:27:34 volumiosplendid volumio[1197]: error: updateQueue error: null Oct 31 09:27:34 volumiosplendid go-librespot[1419]: time="2025-10-31T09:27:34-03:00" level=debug msg="handling transfer player command from 0ca25fe9e2b7d447ed634006da1b5a94ff748f68" Oct 31 09:27:35 volumiosplendid go-librespot[1419]: time="2025-10-31T09:27:35-03:00" level=debug msg="resolved context of track" uri="spotify:playlist:66XF0sumnRWVXAZxAO7RKV" Oct 31 09:27:35 volumiosplendid go-librespot[1419]: time="2025-10-31T09:27:35-03:00" level=trace msg="fetched new page 0 with 777 items (list: 777)" uri="spotify:playlist:66XF0sumnRWVXAZxAO7RKV" Oct 31 09:27:35 volumiosplendid go-librespot[1419]: time="2025-10-31T09:27:35-03:00" level=debug msg="loading track (paused: false, position: 115920ms)" uri="spotify:track:25VmzSltVSB9vwNi6fbhr7" Oct 31 09:27:35 volumiosplendid volumio[1197]: info: Initializing connection to go-librespot Websocket Oct 31 09:27:35 volumiosplendid go-librespot[1419]: time="2025-10-31T09:27:35-03:00" level=debug msg="new websocket client" Oct 31 09:27:35 volumiosplendid volumio[1197]: info: Connection to go-librespot Websocket established Oct 31 09:27:35 volumiosplendid go-librespot[1419]: time="2025-10-31T09:27:35-03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 31 09:27:35 volumiosplendid go-librespot[1419]: time="2025-10-31T09:27:35-03:00" level=trace msg="emitting websocket event: will_play" Oct 31 09:27:35 volumiosplendid volumio[1197]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:25VmzSltVSB9vwNi6fbhr7","play_origin":"playlist"}} Oct 31 09:27:35 volumiosplendid go-librespot[1419]: time="2025-10-31T09:27:35-03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 290" Oct 31 09:27:35 volumiosplendid go-librespot[1419]: time="2025-10-31T09:27:35-03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1727" Oct 31 09:27:35 volumiosplendid go-librespot[1419]: time="2025-10-31T09:27:35-03:00" level=debug msg="selected format OGG_VORBIS_320 (854a9a4f29e2affae07ed37e7c939515eaba949e)" uri="spotify:track:25VmzSltVSB9vwNi6fbhr7" Oct 31 09:27:35 volumiosplendid go-librespot[1419]: time="2025-10-31T09:27:35-03:00" level=debug msg="requested aes key for file 854a9a4f29e2affae07ed37e7c939515eaba949e, gid: 25VmzSltVSB9vwNi6fbhr7" Oct 31 09:27:35 volumiosplendid go-librespot[1419]: time="2025-10-31T09:27:35-03:00" level=trace msg="found 2 cdn urls" uri="spotify:track:25VmzSltVSB9vwNi6fbhr7" Oct 31 09:27:36 volumiosplendid go-librespot[1419]: time="2025-10-31T09:27:36-03:00" level=debug msg="fetched first chunk of 21, total size is 10669436 bytes" uri="spotify:track:25VmzSltVSB9vwNi6fbhr7" Oct 31 09:27:36 volumiosplendid go-librespot[1419]: time="2025-10-31T09:27:36-03:00" level=warning msg="reducing track normalisation factor to prevent clipping, please add negative pregain to avoid" Oct 31 09:27:36 volumiosplendid go-librespot[1419]: time="2025-10-31T09:27:36-03:00" level=debug msg="fetched chunk 2/20, size: 524288" uri="spotify:track:25VmzSltVSB9vwNi6fbhr7" Oct 31 09:27:36 volumiosplendid go-librespot[1419]: time="2025-10-31T09:27:36-03:00" level=debug msg="fetched chunk 3/20, size: 524288" uri="spotify:track:25VmzSltVSB9vwNi6fbhr7" Oct 31 09:27:36 volumiosplendid go-librespot[1419]: time="2025-10-31T09:27:36-03:00" level=debug msg="fetched chunk 1/20, size: 524288" uri="spotify:track:25VmzSltVSB9vwNi6fbhr7" Oct 31 09:27:36 volumiosplendid go-librespot[1419]: time="2025-10-31T09:27:36-03:00" level=debug msg="fetched chunk 10/20, size: 524288" uri="spotify:track:25VmzSltVSB9vwNi6fbhr7" Oct 31 09:27:36 volumiosplendid go-librespot[1419]: time="2025-10-31T09:27:36-03:00" level=debug msg="fetched chunk 8/20, size: 524288" uri="spotify:track:25VmzSltVSB9vwNi6fbhr7" Oct 31 09:27:36 volumiosplendid go-librespot[1419]: time="2025-10-31T09:27:36-03:00" level=debug msg="fetched chunk 9/20, size: 524288" uri="spotify:track:25VmzSltVSB9vwNi6fbhr7" Oct 31 09:27:36 volumiosplendid go-librespot[1419]: time="2025-10-31T09:27:36-03:00" level=debug msg="fetched chunk 7/20, size: 524288" uri="spotify:track:25VmzSltVSB9vwNi6fbhr7" Oct 31 09:27:36 volumiosplendid go-librespot[1419]: time="2025-10-31T09:27:36-03:00" level=trace msg="seek to 115920ms (diff: 78ms, samples: 5112072, bytes: 3674375)" uri="spotify:track:25VmzSltVSB9vwNi6fbhr7" Oct 31 09:27:36 volumiosplendid go-librespot[1419]: time="2025-10-31T09:27:36-03:00" level=debug msg="created new output device" Oct 31 09:27:36 volumiosplendid volumio[1197]: info: FusionDsp - ---- read samplerate, raw: Oct 31 09:27:36 volumiosplendid go-librespot[1419]: time="2025-10-31T09:27:36-03:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 124988 us, period size = 5512 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 4 frames" Oct 31 09:27:36 volumiosplendid go-librespot[1419]: time="2025-10-31T09:27:36-03:00" level=info msg="loaded track \"Since I Fell For You\" (paused: false, position: 115920ms, duration: 336133ms, prefetched: false)" uri="spotify:track:25VmzSltVSB9vwNi6fbhr7" Oct 31 09:27:36 volumiosplendid volumio[1197]: error: FusionDsp - invalid sample rate Oct 31 09:27:36 volumiosplendid volumio[1197]: info: FusionDsp - ---- read samplerate, raw: 44100,S32_LE,2,32 Oct 31 09:27:36 volumiosplendid volumio[1197]: info: FusionDsp - ---- read samplerate from file: 44100 Oct 31 09:27:36 volumiosplendid volumio[1197]: info: camilladsp stopping service pid 1476... Oct 31 09:27:36 volumiosplendid volumio[1197]: info: camilladsp service terminated, instance 1 Oct 31 09:27:36 volumiosplendid volumio[1197]: info: FusionDsp - If filter freq >samplerate/2 then disable it Oct 31 09:27:36 volumiosplendid volumio[1197]: info: FusionDsp - Effects disabled Oct 31 09:27:36 volumiosplendid volumio[1197]: info: camilladsp service started and running in background, instance 1 Oct 31 09:27:36 volumiosplendid volumio[1197]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Oct 31 09:27:36 volumiosplendid go-librespot[1419]: time="2025-10-31T09:27:36-03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 31 09:27:36 volumiosplendid go-librespot[1419]: time="2025-10-31T09:27:36-03:00" level=trace msg="scheduling prefetch in 190s" Oct 31 09:27:36 volumiosplendid go-librespot[1419]: time="2025-10-31T09:27:36-03:00" level=trace msg="emitting websocket event: metadata" Oct 31 09:27:36 volumiosplendid go-librespot[1419]: time="2025-10-31T09:27:36-03:00" level=trace msg="emitting websocket event: active" Oct 31 09:27:36 volumiosplendid go-librespot[1419]: time="2025-10-31T09:27:36-03:00" level=debug msg="sending successful reply for dealer request" Oct 31 09:27:36 volumiosplendid volumio[1197]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:25VmzSltVSB9vwNi6fbhr7","name":"Since I Fell For You","artist_names":["Lee Morgan"],"album_name":"The Best Of Lee Morgan","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02ac1d47b73344281d6de3ea6f","position":115920,"duration":336133,"release_date":"year:1988 month:11 day:2","track_number":5,"disc_number":1}} Oct 31 09:27:36 volumiosplendid volumio[1197]: SPOTIFY: received: {"type":"active","data":null} Oct 31 09:27:36 volumiosplendid volumio[1197]: info: Aligning Spotify Volume to Volumio Volume Oct 31 09:27:36 volumiosplendid volumio[1197]: info: CoreCommandRouter::volumioGetState Oct 31 09:27:36 volumiosplendid volumio[1197]: info: CorePlayQueue::getTrack 0 Oct 31 09:27:36 volumiosplendid volumio[1197]: info: Setting Spotify Volume from Volumio: 99 Oct 31 09:27:36 volumiosplendid go-librespot[1419]: time="2025-10-31T09:27:36-03:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Oct 31 09:27:36 volumiosplendid go-librespot[1419]: time="2025-10-31T09:27:36-03:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Oct 31 09:27:37 volumiosplendid go-librespot[1419]: time="2025-10-31T09:27:37-03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 31 09:27:37 volumiosplendid go-librespot[1419]: time="2025-10-31T09:27:37-03:00" level=trace msg="emitting websocket event: playing" Oct 31 09:27:37 volumiosplendid volumio[1197]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:25VmzSltVSB9vwNi6fbhr7","resume":false,"play_origin":"playlist"}} Oct 31 09:27:37 volumiosplendid volumio[1197]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 31 09:27:37 volumiosplendid volumio[1197]: TypeError: Cannot read property 'service' of undefined Oct 31 09:27:37 volumiosplendid volumio[1197]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:346:50) Oct 31 09:27:37 volumiosplendid volumio[1197]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:272:18) Oct 31 09:27:37 volumiosplendid volumio[1197]: at WebSocket.message (/data/plugins/music_service/spop/index.js:199:14) Oct 31 09:27:37 volumiosplendid volumio[1197]: at WebSocket.emit (events.js:315:20) Oct 31 09:27:37 volumiosplendid volumio[1197]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20) Oct 31 09:27:37 volumiosplendid volumio[1197]: at Receiver.emit (events.js:315:20) Oct 31 09:27:37 volumiosplendid volumio[1197]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) Oct 31 09:27:37 volumiosplendid volumio[1197]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) Oct 31 09:27:37 volumiosplendid volumio[1197]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) Oct 31 09:27:37 volumiosplendid volumio[1197]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) Oct 31 09:27:37 volumiosplendid volumio[1197]: at writeOrBuffer (internal/streams/writable.js:358:12) Oct 31 09:27:37 volumiosplendid volumio[1197]: at Receiver.Writable.write (internal/streams/writable.js:303:10) Oct 31 09:27:37 volumiosplendid volumio[1197]: at Socket.socketOnData (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1355:35) Oct 31 09:27:37 volumiosplendid volumio[1197]: at Socket.emit (events.js:315:20) Oct 31 09:27:37 volumiosplendid volumio[1197]: at addChunk (internal/streams/readable.js:309:12) Oct 31 09:27:37 volumiosplendid volumio[1197]: at readableAddChunk (internal/streams/readable.js:284:9) Oct 31 09:27:37 volumiosplendid volumio[1197]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 31 09:27:37 volumiosplendid sudo[1536]: volumio : unable to resolve host volumiosplendid Oct 31 09:27:37 volumiosplendid sudo[1536]: volumio : problem with defaults entries ; TTY=unknown ; PWD=/ ; USER=root ; Oct 31 09:27:37 volumiosplendid sudo[1536]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-10-31 09:26 Oct 31 09:27:37 volumiosplendid sudo[1536]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Raspbian GNU/Linux 10 (buster)" NAME="Raspbian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="29866754e5f1d7e4d0f581c10d9f22852f6f21db" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="fc4c820ddd3b5fc1a7a6b54ef112273ebd122010" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Sat 26 Jul 2025 10:25:36 AM CEST" VOLUMIO_VERSION="3.832" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="cf6e14681b2ecbbdc9a62186b0f3114c"