-- Logs begin at Thu 2019-02-14 04:11:58 CST, end at Mon 2025-09-01 15:11:06 CDT. -- Sep 01 15:10:00 volumio dbus-daemon[627]: [system] Successfully activated service 'org.freedesktop.hostname1' Sep 01 15:10:00 volumio systemd[1]: Started Hostname Service. Sep 01 15:10:00 volumio nmbd[746]: [2025/09/01 15:10:00.338529, 0] ../source3/nmbd/asyncdns.c:158(start_async_dns) Sep 01 15:10:00 volumio nmbd[746]: started asyncdns process 819 Sep 01 15:10:00 volumio nmbd[746]: [2025/09/01 15:10:00.341881, 0] ../lib/util/become_daemon.c:149(daemon_status) Sep 01 15:10:00 volumio nmbd[746]: daemon_status: STATUS=daemon 'nmbd' : No local IPv4 non-loopback interfaces available, waiting for interface ... Sep 01 15:10:00 volumio nmbd[746]: [2025/09/01 15:10:00.342038, 0] ../source3/nmbd/nmbd_subnetdb.c:254(create_subnets) Sep 01 15:10:00 volumio nmbd[746]: NOTE: NetBIOS name resolution is not supported for Internet Protocol Version 6 (IPv6). Sep 01 15:10:00 volumio ntpd[796]: error resolving pool 0.debian.pool.ntp.org: System error (-11) Sep 01 15:10:00 volumio wireless.js[602]: Cleaning previous... Sep 01 15:10:00 volumio sudo[827]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ip addr flush dev wlan0 Sep 01 15:10:00 volumio sudo[827]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 01 15:10:00 volumio sudo[827]: pam_unix(sudo:session): session closed for user root Sep 01 15:10:00 volumio sudo[829]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 down Sep 01 15:10:00 volumio sudo[829]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 01 15:10:01 volumio sudo[829]: pam_unix(sudo:session): session closed for user root Sep 01 15:10:01 volumio wireless.js[602]: Stopped aP Sep 01 15:10:01 volumio sudo[836]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 up Sep 01 15:10:01 volumio sudo[836]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 01 15:10:01 volumio sudo[836]: pam_unix(sudo:session): session closed for user root Sep 01 15:10:01 volumio kernel: brcmfmac: brcmf_cfg80211_set_power_mgmt: power save disabled Sep 01 15:10:01 volumio sudo[838]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iw reg get Sep 01 15:10:01 volumio sudo[838]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 01 15:10:01 volumio sudo[838]: pam_unix(sudo:session): session closed for user root Sep 01 15:10:01 volumio sudo[845]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 up Sep 01 15:10:01 volumio sudo[845]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 01 15:10:01 volumio sudo[845]: pam_unix(sudo:session): session closed for user root Sep 01 15:10:01 volumio sudo[847]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iw wlan0 scan Sep 01 15:10:01 volumio sudo[847]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 01 15:10:01 volumio ntpd[796]: error resolving pool 1.debian.pool.ntp.org: System error (-11) Sep 01 15:10:01 volumio mpd[807]: Sep 01 15:10 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Sep 01 15:10:01 volumio systemd[1]: Started Music Player Daemon. Sep 01 15:10:01 volumio mpd_monitor.sh[608]: MPD Monitor Service: MPD restarted due to no mpc output. Sep 01 15:10:02 volumio ntpd[796]: error resolving pool 2.debian.pool.ntp.org: System error (-11) Sep 01 15:10:02 volumio systemd[1]: systemd-rfkill.service: Succeeded. Sep 01 15:10:03 volumio ntpd[796]: error resolving pool 3.debian.pool.ntp.org: System error (-11) Sep 01 15:10:03 volumio volumio-remote-updater[610]: [2025-09-01 15:10:03] [info] asio async_connect error: system:111 (Connection refused) Sep 01 15:10:03 volumio volumio-remote-updater[610]: [2025-09-01 15:10:03] [info] Error getting remote endpoint: system:107 (Transport endpoint is not connected) Sep 01 15:10:03 volumio volumio-remote-updater[610]: [2025-09-01 15:10:03] [error] handle_connect error: Underlying Transport Error Sep 01 15:10:03 volumio volumio-time-update[613]: volumio-time-update-util: Fetching time from Volumio... Sep 01 15:10:03 volumio volumio-time-update[613]: volumio-time-update-util: Date not found in response Sep 01 15:10:03 volumio volumio-time-update[613]: volumio-time-update-util: Retrying in 5 seconds... Sep 01 15:10:04 volumio bthelper[717]: Changing power off succeeded Sep 01 15:10:04 volumio sudo[847]: pam_unix(sudo:session): session closed for user root Sep 01 15:10:04 volumio wireless.js[602]: SETTING APPROPRIATE REG DOMAIN: US Sep 01 15:10:04 volumio sudo[861]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 up Sep 01 15:10:04 volumio sudo[861]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 01 15:10:04 volumio sudo[861]: pam_unix(sudo:session): session closed for user root Sep 01 15:10:04 volumio sudo[863]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iw reg set US Sep 01 15:10:04 volumio sudo[863]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 01 15:10:04 volumio sudo[863]: pam_unix(sudo:session): session closed for user root Sep 01 15:10:04 volumio wireless.js[602]: SUCCESSFULLY SET NEW REGDOMAIN: US Sep 01 15:10:04 volumio wireless.js[602]: Start wireless flow Sep 01 15:10:04 volumio wireless.js[602]: Stopped hotspot (if there).. Sep 01 15:10:04 volumio sudo[868]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ip addr flush dev wlan0 Sep 01 15:10:04 volumio sudo[868]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 01 15:10:04 volumio sudo[868]: pam_unix(sudo:session): session closed for user root Sep 01 15:10:04 volumio sudo[870]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 down Sep 01 15:10:04 volumio sudo[870]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 01 15:10:04 volumio bthelper[717]: [CHG] Controller DC:A6:32:EB:4E:EC Class: 0x0000041c Sep 01 15:10:04 volumio bthelper[717]: Changing power on succeeded Sep 01 15:10:04 volumio sudo[870]: pam_unix(sudo:session): session closed for user root Sep 01 15:10:04 volumio wireless.js[602]: DHCP IP Sep 01 15:10:04 volumio wireless.js[602]: Start ap Sep 01 15:10:04 volumio wpa_supplicant[879]: Successfully initialized wpa_supplicant Sep 01 15:10:04 volumio sudo[880]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/dhcpcd Sep 01 15:10:04 volumio sudo[880]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 01 15:10:04 volumio kernel: brcmfmac: brcmf_cfg80211_set_power_mgmt: power save disabled Sep 01 15:10:04 volumio dhcpcd[881]: dev: loaded udev Sep 01 15:10:04 volumio dhcpcd-run-hooks[899]: wlan0: starting wpa_supplicant Sep 01 15:10:05 volumio dhcpcd-run-hooks[904]: wlan0: failed to start wpa_supplicant Sep 01 15:10:05 volumio dhcpcd-run-hooks[905]: wlan0: Successfully initialized wpa_supplicant nl80211: kernel reports: Match already configured nl80211: kernel reports: Match already configured nl80211: kernel reports: Match already configured nl80211: kernel reports: Match already configured nl80211: kernel reports: Match already configured nl80211: kernel reports: Match already configured nl80211: kernel reports: Match already configured nl80211: kernel reports: Match already configured nl80211: kernel reports: Match already configured nl80211: kernel reports: Match already configured nl80211: kernel reports: Match already configured nl80211: kernel reports: Match already configured nl80211: kernel reports: Match already configured nl80211: kernel reports: Match already configured nl80211: kernel reports: Match already configured nl80211: kernel reports: Match already configured nl80211: kernel reports: Match already configured nl80211: kernel reports: Match already configured nl80211: kernel reports: Match already configured nl80211: kernel reports: Ma Sep 01 15:10:05 volumio dhcpcd[881]: wlan0: connected to Access Point `' Sep 01 15:10:05 volumio dhcpcd[881]: no interfaces have a carrier Sep 01 15:10:05 volumio dhcpcd[881]: forked to background, child pid 915 Sep 01 15:10:05 volumio dhcpcd[915]: eth0: waiting for carrier Sep 01 15:10:05 volumio dhcpcd[915]: wlan0: waiting for carrier Sep 01 15:10:05 volumio sudo[880]: pam_unix(sudo:session): session closed for user root Sep 01 15:10:05 volumio wireless.js[602]: trying... Sep 01 15:10:05 volumio sudo[917]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Sep 01 15:10:05 volumio sudo[917]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 01 15:10:05 volumio sudo[917]: pam_unix(sudo:session): session closed for user root Sep 01 15:10:06 volumio wireless.js[602]: trying... Sep 01 15:10:06 volumio sudo[920]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Sep 01 15:10:06 volumio sudo[920]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 01 15:10:06 volumio sudo[920]: pam_unix(sudo:session): session closed for user root Sep 01 15:10:07 volumio wireless.js[602]: trying... Sep 01 15:10:07 volumio sudo[923]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Sep 01 15:10:07 volumio sudo[923]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 01 15:10:07 volumio sudo[923]: pam_unix(sudo:session): session closed for user root Sep 01 15:10:08 volumio wireless.js[602]: trying... Sep 01 15:10:08 volumio sudo[926]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Sep 01 15:10:08 volumio sudo[926]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 01 15:10:08 volumio sudo[926]: pam_unix(sudo:session): session closed for user root Sep 01 15:10:08 volumio volumio-time-update[613]: volumio-time-update-util: Fetching time from Volumio... Sep 01 15:10:08 volumio kernel: brcmfmac: brcmf_set_channel: set chanspec 0xd022 fail, reason -52 Sep 01 15:10:09 volumio volumio-time-update[613]: volumio-time-update-util: Date not found in response Sep 01 15:10:09 volumio volumio-time-update[613]: volumio-time-update-util: Retrying in 5 seconds... Sep 01 15:10:09 volumio kernel: brcmfmac: brcmf_set_channel: set chanspec 0xd026 fail, reason -52 Sep 01 15:10:09 volumio kernel: brcmfmac: brcmf_set_channel: set chanspec 0xd02a fail, reason -52 Sep 01 15:10:09 volumio kernel: brcmfmac: brcmf_set_channel: set chanspec 0xd02e fail, reason -52 Sep 01 15:10:09 volumio wireless.js[602]: trying... Sep 01 15:10:09 volumio sudo[934]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Sep 01 15:10:09 volumio sudo[934]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 01 15:10:09 volumio sudo[934]: pam_unix(sudo:session): session closed for user root Sep 01 15:10:10 volumio wireless.js[602]: trying... Sep 01 15:10:10 volumio sudo[937]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Sep 01 15:10:10 volumio sudo[937]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 01 15:10:10 volumio sudo[937]: pam_unix(sudo:session): session closed for user root Sep 01 15:10:11 volumio volumio-remote-updater[610]: [2025-09-01 15:10:11] [info] asio async_connect error: system:111 (Connection refused) Sep 01 15:10:11 volumio volumio-remote-updater[610]: [2025-09-01 15:10:11] [info] Error getting remote endpoint: system:107 (Transport endpoint is not connected) Sep 01 15:10:11 volumio volumio-remote-updater[610]: [2025-09-01 15:10:11] [error] handle_connect error: Underlying Transport Error Sep 01 15:10:11 volumio wireless.js[602]: trying... Sep 01 15:10:11 volumio sudo[940]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Sep 01 15:10:11 volumio sudo[940]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 01 15:10:11 volumio sudo[940]: pam_unix(sudo:session): session closed for user root Sep 01 15:10:11 volumio wpa_supplicant[903]: wlan0: Trying to associate with SSID 'ATTwNC7nb8' Sep 01 15:10:11 volumio dhcpcd[915]: wlan0: carrier acquired Sep 01 15:10:11 volumio dhcpcd[915]: wlan0: connected to Access Point `ATTwNC7nb8' Sep 01 15:10:11 volumio wpa_supplicant[903]: wlan0: Associated with ac:91:9b:1f:8d:a8 Sep 01 15:10:11 volumio wpa_supplicant[903]: wlan0: CTRL-EVENT-CONNECTED - Connection to ac:91:9b:1f:8d:a8 completed [id=0 id_str=] Sep 01 15:10:11 volumio wpa_supplicant[903]: wlan0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0 Sep 01 15:10:11 volumio wpa_supplicant[903]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=COUNTRY_IE type=COUNTRY alpha2=US Sep 01 15:10:11 volumio dhcpcd[915]: DUID 00:01:00:01:2d:69:1d:c2:dc:a6:32:eb:4e:eb Sep 01 15:10:11 volumio dhcpcd[915]: wlan0: IAID 32:eb:4e:eb Sep 01 15:10:11 volumio dhcpcd[915]: wlan0: adding address fe80::94e:ff90:438f:800 Sep 01 15:10:11 volumio dhcpcd[915]: ipv6_addaddr1: Permission denied Sep 01 15:10:11 volumio dhcpcd[915]: wlan0: carrier lost Sep 01 15:10:11 volumio dhcpcd[915]: wlan0: carrier acquired Sep 01 15:10:11 volumio dhcpcd[915]: wlan0: IAID 32:eb:4e:eb Sep 01 15:10:11 volumio dhcpcd[915]: wlan0: soliciting an IPv6 router Sep 01 15:10:12 volumio dhcpcd[915]: wlan0: rebinding lease of 192.168.1.148 Sep 01 15:10:12 volumio dhcpcd[915]: wlan0: probing address 192.168.1.148/24 Sep 01 15:10:12 volumio wireless.js[602]: trying... Sep 01 15:10:12 volumio sudo[956]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Sep 01 15:10:12 volumio sudo[956]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 01 15:10:12 volumio sudo[956]: pam_unix(sudo:session): session closed for user root Sep 01 15:10:13 volumio wireless.js[602]: trying... Sep 01 15:10:13 volumio sudo[959]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Sep 01 15:10:13 volumio sudo[959]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 01 15:10:13 volumio sudo[959]: pam_unix(sudo:session): session closed for user root Sep 01 15:10:14 volumio volumio-time-update[613]: volumio-time-update-util: Fetching time from Volumio... Sep 01 15:10:14 volumio volumio-time-update[613]: volumio-time-update-util: Date not found in response Sep 01 15:10:14 volumio volumio-time-update[613]: volumio-time-update-util: Retrying in 5 seconds... Sep 01 15:10:14 volumio wireless.js[602]: trying... Sep 01 15:10:14 volumio sudo[967]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Sep 01 15:10:14 volumio sudo[967]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 01 15:10:14 volumio sudo[967]: pam_unix(sudo:session): session closed for user root Sep 01 15:10:15 volumio wireless.js[602]: trying... Sep 01 15:10:15 volumio sudo[970]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Sep 01 15:10:15 volumio sudo[970]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 01 15:10:15 volumio sudo[970]: pam_unix(sudo:session): session closed for user root Sep 01 15:10:16 volumio wireless.js[602]: trying... Sep 01 15:10:16 volumio sudo[973]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Sep 01 15:10:16 volumio sudo[973]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 01 15:10:16 volumio sudo[973]: pam_unix(sudo:session): session closed for user root Sep 01 15:10:17 volumio dhcpcd[915]: wlan0: leased 192.168.1.148 for 86400 seconds Sep 01 15:10:17 volumio avahi-daemon[619]: Joining mDNS multicast group on interface wlan0.IPv4 with address 192.168.1.148. Sep 01 15:10:17 volumio dhcpcd[915]: wlan0: adding route to 192.168.1.0/24 Sep 01 15:10:17 volumio avahi-daemon[619]: New relevant interface wlan0.IPv4 for mDNS. Sep 01 15:10:17 volumio dhcpcd[915]: wlan0: adding default route via 192.168.1.254 Sep 01 15:10:17 volumio avahi-daemon[619]: Registering new address record for 192.168.1.148 on wlan0.IPv4. Sep 01 15:10:17 volumio wireless.js[602]: trying... Sep 01 15:10:17 volumio sudo[997]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Sep 01 15:10:17 volumio sudo[997]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 01 15:10:17 volumio sudo[997]: pam_unix(sudo:session): session closed for user root Sep 01 15:10:17 volumio wireless.js[602]: Connected to: ----ATTwNC7nb8 Sep 01 15:10:17 volumio wireless.js[602]: ---- Sep 01 15:10:17 volumio sudo[1000]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Sep 01 15:10:17 volumio sudo[1000]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 01 15:10:17 volumio sudo[1000]: pam_unix(sudo:session): session closed for user root Sep 01 15:10:17 volumio wireless.js[602]: ... joined AP, wlan0 IPv4 is 192.168.1.148, ipV6 is undefined Sep 01 15:10:17 volumio wireless.js[602]: It's done! AP Sep 01 15:10:17 volumio kernel: brcmfmac: brcmf_cfg80211_set_power_mgmt: power save disabled Sep 01 15:10:17 volumio systemd[1]: Started Wireless Services. Sep 01 15:10:17 volumio systemd[1]: Started Volumio Backend Module. Sep 01 15:10:17 volumio systemd[1]: Started Volumio Cpu Tweaker. Sep 01 15:10:17 volumio volumio-cpu-tweak[1006]: Setting RT Priority for mpd Sep 01 15:10:17 volumio volumio-cpu-tweak[1006]: Setting MPD Affinity Sep 01 15:10:17 volumio volumio-cpu-tweak[1006]: pid 807's current affinity mask: f Sep 01 15:10:17 volumio volumio-cpu-tweak[1006]: pid 807's new affinity mask: 3 Sep 01 15:10:17 volumio volumio-cpu-tweak[1006]: /bin/volumio_cpu_tweak: line 27: warning: command substitution: ignored null byte in input Sep 01 15:10:17 volumio volumio-cpu-tweak[1006]: VOLUMIO CPU TWEAK: Setting CPU Governor: performance Sep 01 15:10:18 volumio systemd[1]: volumio_cpu_tweak.service: Succeeded. Sep 01 15:10:19 volumio volumio-time-update[613]: volumio-time-update-util: Fetching time from Volumio... Sep 01 15:10:19 volumio volumio-time-update[613]: volumio-time-update-util: Setting system time to: 2025-09-01 15:10:48 Sep 01 15:10:19 volumio sudo[1035]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/bin/timedatectl set-time 2025-09-01 15:10:48 Sep 01 15:10:19 volumio sudo[1035]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 01 15:10:19 volumio ntpd[796]: Listen normally on 3 wlan0 192.168.1.148:123 Sep 01 15:10:19 volumio ntpd[796]: new interface(s) found: waking up resolver Sep 01 15:10:19 volumio dbus-daemon[627]: [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service' requested by ':1.9' (uid=0 pid=1036 comm="timedatectl set-time 2025-09-01 15:10:48 ") Sep 01 15:10:19 volumio systemd[1]: Starting Time & Date Service... Sep 01 15:10:19 volumio volumio[1005]: info: ------------------------------------------- Sep 01 15:10:19 volumio volumio[1005]: info: ----- Volumio3 ---- Sep 01 15:10:19 volumio volumio[1005]: info: ------------------------------------------- Sep 01 15:10:19 volumio volumio[1005]: info: ----- System startup ---- Sep 01 15:10:19 volumio volumio[1005]: info: ------------------------------------------- Sep 01 15:10:19 volumio dbus-daemon[627]: [system] Successfully activated service 'org.freedesktop.timedate1' Sep 01 15:10:19 volumio systemd[1]: Started Time & Date Service. Sep 01 15:10:48 volumio systemd-timedated[1037]: Changed local time to Mon Sep 1 15:10:48 2025 Sep 01 15:10:48 volumio sudo[1035]: pam_unix(sudo:session): session closed for user root Sep 01 15:10:48 volumio volumio-time-update[613]: volumio-time-update-util: System time updated successfully. Sep 01 15:10:48 volumio systemd[1]: Started Volumio Time Update Utility. Sep 01 15:10:48 volumio volumio[1005]: info: MYVOLUMIO Environment detected Sep 01 15:10:48 volumio nmbd[746]: [2025/09/01 15:10:48.734238, 0] ../lib/util/become_daemon.c:138(daemon_ready) Sep 01 15:10:48 volumio nmbd[746]: daemon_ready: STATUS=daemon 'nmbd' finished starting up and ready to serve connections Sep 01 15:10:48 volumio systemd[1]: Started Samba NMB Daemon. Sep 01 15:10:48 volumio systemd[1]: Starting Samba Winbind Daemon... Sep 01 15:10:48 volumio volumio[1005]: info: Plugin folders cleanup Sep 01 15:10:48 volumio volumio[1005]: info: Scanning into folder /volumio/app/plugins/ Sep 01 15:10:48 volumio volumio[1005]: info: Scanning category audio_interface Sep 01 15:10:48 volumio volumio[1005]: info: Scanning category miscellanea Sep 01 15:10:48 volumio volumio[1005]: info: Scanning category music_service Sep 01 15:10:48 volumio volumio[1005]: info: Scanning category plugins.json Sep 01 15:10:48 volumio volumio[1005]: info: Scanning category system_controller Sep 01 15:10:48 volumio volumio[1005]: info: Scanning category user_interface Sep 01 15:10:48 volumio volumio[1005]: info: Scanning into folder /data/plugins/ Sep 01 15:10:48 volumio volumio[1005]: info: Scanning category music_service Sep 01 15:10:48 volumio volumio[1005]: info: Plugin folders cleanup completed Sep 01 15:10:48 volumio volumio[1005]: info: ------------------------------------------- Sep 01 15:10:48 volumio volumio[1005]: info: ----- Core plugins startup ---- Sep 01 15:10:48 volumio volumio[1005]: info: ------------------------------------------- Sep 01 15:10:48 volumio volumio[1005]: info: Loading plugins from folder /volumio/app/plugins/ Sep 01 15:10:48 volumio volumio[1005]: info: Adding plugin upnp to MyMusic Plugins Sep 01 15:10:48 volumio volumio[1005]: info: Adding plugin airplay_emulation to MyMusic Plugins Sep 01 15:10:48 volumio volumio[1005]: info: Adding plugin upnp_browser to MyMusic Plugins Sep 01 15:10:48 volumio volumio[1005]: info: Loading plugins from folder /data/plugins/ Sep 01 15:10:48 volumio volumio[1005]: info: Loading plugin "system"... Sep 01 15:10:48 volumio volumio[1005]: info: Loading plugin "appearance"... Sep 01 15:10:49 volumio winbindd[1040]: [2025/09/01 15:10:49.019676, 0] ../source3/winbindd/winbindd_cache.c:3160(initialize_winbindd_cache) Sep 01 15:10:49 volumio winbindd[1040]: initialize_winbindd_cache: clearing cache and re-creating with version number 2 Sep 01 15:10:49 volumio winbindd[1040]: [2025/09/01 15:10:49.044980, 0] ../lib/util/become_daemon.c:138(daemon_ready) Sep 01 15:10:49 volumio winbindd[1040]: daemon_ready: STATUS=daemon 'winbindd' finished starting up and ready to serve connections Sep 01 15:10:49 volumio systemd[1]: Started Samba Winbind Daemon. Sep 01 15:10:49 volumio systemd[1]: Starting Samba SMB Daemon... Sep 01 15:10:49 volumio smbd[1048]: [2025/09/01 15:10:49.504332, 0] ../lib/util/become_daemon.c:138(daemon_ready) Sep 01 15:10:49 volumio systemd[1]: Started Samba SMB Daemon. Sep 01 15:10:49 volumio smbd[1048]: daemon_ready: STATUS=daemon 'smbd' finished starting up and ready to serve connections Sep 01 15:10:49 volumio systemd[1]: Reached target Multi-User System. Sep 01 15:10:49 volumio systemd[1]: Reached target Graphical Interface. Sep 01 15:10:49 volumio systemd[1]: Starting Update UTMP about System Runlevel Changes... Sep 01 15:10:49 volumio systemd[1]: systemd-update-utmp-runlevel.service: Succeeded. Sep 01 15:10:49 volumio systemd[1]: Started Update UTMP about System Runlevel Changes. Sep 01 15:10:49 volumio systemd[1]: Startup finished in 11.873s (kernel) + 26.143s (userspace) = 38.017s. Sep 01 15:10:49 volumio volumio-remote-updater[610]: [2025-09-01 15:10:49] [connect] Successful connection Sep 01 15:10:50 volumio volumio[1005]: info: Loading plugin "network"... Sep 01 15:10:50 volumio volumio[1005]: info: Refreshing Cached IP Addresses Sep 01 15:10:50 volumio sudo[1058]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Sep 01 15:10:50 volumio sudo[1058]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 01 15:10:50 volumio sudo[1058]: pam_unix(sudo:session): session closed for user root Sep 01 15:10:50 volumio sudo[1060]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Sep 01 15:10:50 volumio sudo[1060]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 01 15:10:50 volumio sudo[1060]: pam_unix(sudo:session): session closed for user root Sep 01 15:10:50 volumio volumio[1005]: info: Loading plugin "services"... Sep 01 15:10:50 volumio volumio[1005]: info: Loading plugin "alsa_controller"... Sep 01 15:10:50 volumio sudo[1069]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Sep 01 15:10:50 volumio sudo[1069]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 01 15:10:50 volumio volumio[1005]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Sep 01 15:10:50 volumio volumio[1005]: info: Loading plugin "wizard"... Sep 01 15:10:50 volumio volumio[1005]: info: Loading plugin "networkfs"... Sep 01 15:10:50 volumio volumio[1005]: info: Starting Udev Watcher for removable devices Sep 01 15:10:50 volumio sudo[1086]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=mom,password=coffee,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //192.168.1.145/MUSIC /mnt/NAS/MUSIC Sep 01 15:10:50 volumio sudo[1086]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 01 15:10:50 volumio volumio[1005]: info: Ignoring mount for partition: boot Sep 01 15:10:50 volumio volumio[1005]: info: Ignoring mount for partition: volumio Sep 01 15:10:50 volumio volumio[1005]: info: Ignoring mount for partition: volumio_data Sep 01 15:10:50 volumio volumio[1005]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Sep 01 15:10:50 volumio volumio[1005]: info: Loading plugin "volumio_command_line_client"... Sep 01 15:10:50 volumio volumio[1005]: info: Plugin upnp is not enabled Sep 01 15:10:50 volumio volumio[1005]: info: Loading plugin "my_music"... Sep 01 15:10:50 volumio volumio[1005]: info: Loading plugin "mpd"... Sep 01 15:10:50 volumio kernel: Key type cifs.spnego registered Sep 01 15:10:50 volumio kernel: Key type cifs.idmap registered Sep 01 15:10:50 volumio kernel: CIFS: No dialect specified on mount. Default has changed to a more secure dialect, SMB2.1 or later (e.g. SMB3.1.1), from CIFS (SMB1). To use the less secure SMB1 dialect to access old servers which do not support SMB3.1.1 (or even SMB3 or SMB2.1) specify vers=1.0 on mount. Sep 01 15:10:50 volumio kernel: CIFS: Attempting to mount //192.168.1.145/MUSIC Sep 01 15:10:50 volumio volumio[1005]: info: Loading plugin "upnp_browser"... Sep 01 15:10:50 volumio kernel: cryptd: max_cpu_qlen set to 1000 Sep 01 15:10:50 volumio volumio[1005]: info: Loading plugin "alarm-clock"... Sep 01 15:10:51 volumio sudo[1086]: pam_unix(sudo:session): session closed for user root Sep 01 15:10:51 volumio volumio[1005]: info: Loading plugin "airplay_emulation"... Sep 01 15:10:51 volumio volumio[1005]: info: Starting Shairport Sync Sep 01 15:10:51 volumio volumio[1005]: info: Loading plugin "last_100"... Sep 01 15:10:51 volumio volumio[1005]: info: Loading plugin "webradio"... Sep 01 15:10:51 volumio volumio[1005]: info: Loading plugin "i2s_dacs"... Sep 01 15:10:51 volumio volumio[1005]: info: I2S DAC not set, start Auto-detection Sep 01 15:10:51 volumio volumio[1005]: info: Loading plugin "volumiodiscovery"... Sep 01 15:10:51 volumio volumio[1005]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Sep 01 15:10:51 volumio volumio[1005]: *** WARNING *** Please fix your application to use the native API of Avahi! Sep 01 15:10:51 volumio node[1005]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Sep 01 15:10:51 volumio volumio[1005]: *** WARNING *** For more information see Sep 01 15:10:51 volumio volumio[1005]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Sep 01 15:10:51 volumio volumio[1005]: *** WARNING *** Please fix your application to use the native API of Avahi! Sep 01 15:10:51 volumio volumio[1005]: *** WARNING *** For more information see Sep 01 15:10:51 volumio node[1005]: *** WARNING *** Please fix your application to use the native API of Avahi! Sep 01 15:10:51 volumio node[1005]: *** WARNING *** For more information see Sep 01 15:10:51 volumio node[1005]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Sep 01 15:10:51 volumio node[1005]: *** WARNING *** Please fix your application to use the native API of Avahi! Sep 01 15:10:51 volumio node[1005]: *** WARNING *** For more information see Sep 01 15:10:51 volumio volumio[1005]: info: Applying required configuration parameters for plugin volumiodiscovery Sep 01 15:10:51 volumio volumio[1005]: info: Discovery: Started advertising with name: Volumio Sep 01 15:10:51 volumio volumio[1005]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Sep 01 15:10:51 volumio volumio[1005]: info: Loading plugin "jellyfin"... Sep 01 15:10:52 volumio volumio[1005]: info: Loading plugin "spop"... Sep 01 15:10:53 volumio volumio[1005]: info: Loading plugin "youtube2"... Sep 01 15:10:54 volumio volumio[1005]: info: Loading plugin "outputs"... Sep 01 15:10:54 volumio volumio[1005]: info: Loading plugin "albumart"... Sep 01 15:10:54 volumio volumio[1005]: info: Plugin example_plugin is not enabled Sep 01 15:10:54 volumio volumio[1005]: info: Loading plugin "inputs"... Sep 01 15:10:54 volumio volumio[1005]: info: Loading plugin "updater_comm"... Sep 01 15:10:54 volumio sudo[1069]: pam_unix(sudo:session): session closed for user root Sep 01 15:10:54 volumio volumio[1005]: info: Plugin mpdemulation is not enabled Sep 01 15:10:54 volumio volumio[1005]: info: Loading plugin "rest_api"... Sep 01 15:10:54 volumio volumio[1005]: info: Loading plugin "websocket"... Sep 01 15:10:54 volumio volumio[1005]: info: Starting Socket.io Server version 2.3.0 Sep 01 15:10:54 volumio volumio[1005]: info: Loading plugin "pandora"... Sep 01 15:10:54 volumio volumio[1005]: Forking 3 albumart workers Sep 01 15:10:54 volumio volumio[1005]: Starting albumart workers Sep 01 15:10:54 volumio volumio[1005]: Starting albumart workers Sep 01 15:10:54 volumio volumio[1005]: Starting albumart workers Sep 01 15:10:55 volumio volumio[1005]: info: Applying required configuration parameters for plugin pandora Sep 01 15:10:55 volumio volumio[1005]: info: Loading plugin "radio_paradise"... Sep 01 15:10:55 volumio volumio[1005]: info: Applying required configuration parameters for plugin radio_paradise Sep 01 15:10:55 volumio volumio[1005]: info: [1756757455901] [RadioParadise] API delay: 5 Sep 01 15:10:55 volumio volumio[1005]: info: Loading i18n strings for locale en Sep 01 15:10:55 volumio volumio[1005]: Updating browse sources language Sep 01 15:10:55 volumio volumio[1005]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 01 15:10:56 volumio volumio[1005]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Sep 01 15:10:56 volumio volumio[1005]: info: CoreCommandRouter::initPlayerControls Sep 01 15:10:56 volumio volumio[1005]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 15:10:56 volumio volumio[1005]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 15:10:56 volumio volumio[1005]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 15:10:56 volumio volumio[1005]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 15:10:56 volumio volumio[1005]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 15:10:56 volumio volumio[1005]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 15:10:56 volumio volumio[1005]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 15:10:56 volumio volumio[1005]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 15:10:56 volumio volumio[1005]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Sep 01 15:10:56 volumio volumio[1005]: Express server listening on port 3000 Sep 01 15:10:56 volumio volumio[1005]: [Metrics] WebUI: 8s 739.77ms Sep 01 15:10:56 volumio volumio[1005]: info: CoreStateMachine::resetVolumioState Sep 01 15:10:56 volumio volumio[1005]: info: CoreStateMachine::getcurrentVolume Sep 01 15:10:56 volumio volumio[1005]: info: CoreCommandRouter::volumioRetrievevolume Sep 01 15:10:56 volumio volumio[1005]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 01 15:10:56 volumio volumio[1005]: info: Volumio Network Manager: Network status updated: 2 Sep 01 15:10:56 volumio systemd[1]: systemd-fsckd.service: Succeeded. Sep 01 15:10:56 volumio volumio[1005]: verbose: New Socket.io Connection to 192.168.1.148 from 192.168.1.137 UA: Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:142.0) Gecko/20100101 Firefox/142.0 Engine version: 3 Transport: polling Total Clients: 1 Sep 01 15:10:56 volumio volumio[1005]: info: CoreCommandRouter::volumioGetState Sep 01 15:10:56 volumio volumio[1005]: info: CorePlayQueue::getTrack 0 Sep 01 15:10:56 volumio volumio[1005]: info: Reloading queue from file Sep 01 15:10:56 volumio volumio[1005]: info: VolumeController:: Volume=0 Mute =false Sep 01 15:10:56 volumio volumio[1005]: info: CoreStateMachine::pushState Sep 01 15:10:56 volumio volumio[1005]: info: CorePlayQueue::getTrack 0 Sep 01 15:10:56 volumio volumio[1005]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 01 15:10:56 volumio volumio[1005]: info: CoreCommandRouter::volumioPushState Sep 01 15:10:56 volumio volumio[1005]: info: CoreStateMachine::updateTrackBlock Sep 01 15:10:56 volumio volumio[1005]: info: CorePlayQueue::getTrackBlock Sep 01 15:10:56 volumio volumio[1005]: info: CoreCommandRouter::volumioRetrievevolume Sep 01 15:10:56 volumio volumio[1005]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Sep 01 15:10:56 volumio volumio[1005]: info: USB Boot Capable - System SBC Revision found in cpuinfo: d03114 Sep 01 15:10:56 volumio volumio[1005]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Sep 01 15:10:56 volumio volumio[1005]: info: Setting Device type: Raspberry PI Sep 01 15:10:56 volumio volumio[1005]: info: CoreStateMachine::setRepeat false single undefined Sep 01 15:10:56 volumio volumio[1005]: info: CoreStateMachine::pushState Sep 01 15:10:56 volumio volumio[1005]: info: CorePlayQueue::getTrack 0 Sep 01 15:10:56 volumio volumio[1005]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 01 15:10:56 volumio volumio[1005]: info: CoreCommandRouter::volumioPushState Sep 01 15:10:56 volumio volumio[1005]: info: CoreStateMachine::setRandom false Sep 01 15:10:56 volumio volumio[1005]: info: CoreStateMachine::pushState Sep 01 15:10:56 volumio volumio[1005]: info: CorePlayQueue::getTrack 0 Sep 01 15:10:56 volumio volumio[1005]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 01 15:10:56 volumio volumio[1005]: info: CoreCommandRouter::volumioPushState Sep 01 15:10:56 volumio volumio[1005]: verbose: New Socket.io Connection to 192.168.1.148 from 192.168.1.137 UA: Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:142.0) Gecko/20100101 Firefox/142.0 Engine version: 3 Transport: polling Total Clients: 2 Sep 01 15:10:56 volumio volumio[1005]: info: Listing playlists Sep 01 15:10:56 volumio volumio[1005]: info: Listing playlists Sep 01 15:10:56 volumio volumio[1005]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Sep 01 15:10:56 volumio volumio[1005]: info: VolumeController:: Volume=0 Mute =false Sep 01 15:10:56 volumio volumio[1005]: info: CoreStateMachine::pushState Sep 01 15:10:56 volumio volumio[1005]: info: CorePlayQueue::getTrack 0 Sep 01 15:10:56 volumio volumio[1005]: info: CoreCommandRouter::volumioPushState Sep 01 15:10:56 volumio volumio[1005]: info: CoreCommandRouter::volumioGetVisibleSources Sep 01 15:10:56 volumio volumio[1005]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 01 15:10:56 volumio volumio[1005]: info: CoreCommandRouter::volumioGetState Sep 01 15:10:56 volumio volumio[1005]: info: CorePlayQueue::getTrack 0 Sep 01 15:10:56 volumio volumio[1005]: info: CoreCommandRouter::volumioGetState Sep 01 15:10:56 volumio volumio[1005]: info: CorePlayQueue::getTrack 0 Sep 01 15:10:56 volumio volumio[1005]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Sep 01 15:10:56 volumio volumio[1005]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Sep 01 15:10:56 volumio volumio[1005]: info: Received Get System Info Sep 01 15:10:56 volumio volumio[1005]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Sep 01 15:10:56 volumio volumio[1005]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Sep 01 15:10:56 volumio volumio[1005]: info: Discovery: Getting this device information Sep 01 15:10:56 volumio volumio[1005]: info: CoreCommandRouter::volumioGetState Sep 01 15:10:56 volumio volumio[1005]: info: CorePlayQueue::getTrack 0 Sep 01 15:10:56 volumio volumio[1005]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Sep 01 15:10:56 volumio volumio[1005]: info: CoreCommandRouter::volumioGetState Sep 01 15:10:56 volumio volumio[1005]: info: CorePlayQueue::getTrack 0 Sep 01 15:10:56 volumio volumio[1005]: info: Listing playlists Sep 01 15:10:56 volumio volumio[1005]: info: CoreCommandRouter::volumioGetQueue Sep 01 15:10:56 volumio volumio[1005]: info: CoreStateMachine::getQueue Sep 01 15:10:56 volumio volumio[1005]: info: CorePlayQueue::getQueue Sep 01 15:10:56 volumio volumio[1005]: info: Completed loading Core Plugins Sep 01 15:10:56 volumio volumio[1005]: info: Preparing to generate the ALSA configuration file Sep 01 15:10:56 volumio volumio[1005]: info: Asound.conf file unchanged, so no further update is needed Sep 01 15:10:56 volumio volumio[1005]: info: Output device has changed, restarting MPD Sep 01 15:10:56 volumio sudo[1193]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Sep 01 15:10:56 volumio sudo[1193]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 01 15:10:56 volumio volumio[1005]: info: Output device has changed, restarting Shairport Sync Sep 01 15:10:56 volumio volumio[1005]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 15:10:56 volumio volumio[1005]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 01 15:10:56 volumio sudo[1193]: pam_unix(sudo:session): session closed for user root Sep 01 15:10:56 volumio sudo[1196]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Sep 01 15:10:56 volumio sudo[1196]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 01 15:10:56 volumio systemd[1]: Stopping Music Player Daemon... Sep 01 15:10:56 volumio volumio[1005]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Sep 01 15:10:56 volumio volumio[1005]: info: ___________ START PLUGINS ___________ Sep 01 15:10:56 volumio volumio[1005]: info: ControllerMpd::onStart: Initializing MPD Sep 01 15:10:56 volumio volumio[1005]: info: Creating MPD Configuration file Sep 01 15:10:56 volumio sudo[1202]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Sep 01 15:10:56 volumio sudo[1202]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 01 15:10:56 volumio volumio[1005]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Sep 01 15:10:56 volumio volumio[1005]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Sep 01 15:10:56 volumio volumio[1005]: info: [1756757456651] CoreMusicLibrary::Adding element Media Servers Sep 01 15:10:56 volumio volumio[1005]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 01 15:10:56 volumio sudo[1202]: pam_unix(sudo:session): session closed for user root Sep 01 15:10:56 volumio sudo[1205]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Sep 01 15:10:56 volumio sudo[1205]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 01 15:10:56 volumio volumio[1005]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 15:10:56 volumio volumio[1005]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 01 15:10:56 volumio volumio[1005]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Sep 01 15:10:56 volumio volumio[1005]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 15:10:56 volumio volumio[1005]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 01 15:10:56 volumio systemd[1]: mpd.service: Succeeded. Sep 01 15:10:56 volumio systemd[1]: Stopped Music Player Daemon. Sep 01 15:10:56 volumio volumio[1005]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Sep 01 15:10:56 volumio volumio[1005]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Sep 01 15:10:56 volumio volumio[1005]: info: [1756757456742] CoreMusicLibrary::Adding element Last_100 Sep 01 15:10:56 volumio volumio[1005]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 01 15:10:56 volumio volumio[1005]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Sep 01 15:10:56 volumio volumio[1005]: info: [1756757456744] CoreMusicLibrary::Adding element Webradio Sep 01 15:10:56 volumio volumio[1005]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 01 15:10:56 volumio volumio[1005]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Sep 01 15:10:56 volumio volumio[1005]: info: Initializing BBC Radios Sep 01 15:10:56 volumio systemd[1]: Starting Music Player Daemon... Sep 01 15:10:56 volumio volumio[1005]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Sep 01 15:10:56 volumio volumio[1005]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 01 15:10:56 volumio volumio[1005]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Sep 01 15:10:56 volumio volumio[1005]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Sep 01 15:10:56 volumio volumio[1005]: info: Discovery: Getting this device information Sep 01 15:10:56 volumio volumio[1005]: info: CoreCommandRouter::volumioGetState Sep 01 15:10:56 volumio volumio[1005]: info: CorePlayQueue::getTrack 0 Sep 01 15:10:56 volumio volumio[1005]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Sep 01 15:10:56 volumio volumio[1005]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Sep 01 15:10:56 volumio volumio[1005]: info: [1756757456820] CoreMusicLibrary::Adding element Jellyfin Sep 01 15:10:56 volumio volumio[1005]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 01 15:10:56 volumio volumio[1005]: Cannot find translation for source Jellyfin Sep 01 15:10:56 volumio volumio[1005]: info: [jellyfin] Initialized plugin with device info: {"id":"a5748a65-3da6-42f5-b4ce-3c4bdc02a23d","host":"http://192.168.1.148","name":"Volumio","type":"device","serviceName":"Volumio","state":{"status":"stop","volume":"","mute":false,"artist":"Bill Withers","track":"Lovely Day","albumart":"https://i.scdn.co/image/ab67616d0000b2735ade9b4d547203c9061fc340"}} Sep 01 15:10:56 volumio sudo[1211]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Sep 01 15:10:56 volumio sudo[1211]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 01 15:10:56 volumio sudo[1211]: pam_unix(sudo:session): session closed for user root Sep 01 15:10:56 volumio volumio[1005]: info: Creating Spotify config file Sep 01 15:10:56 volumio volumio[1005]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 15:10:56 volumio volumio[1005]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Sep 01 15:10:56 volumio volumio[1005]: info: [1756757456905] CoreMusicLibrary::Adding element YouTube2 Sep 01 15:10:56 volumio volumio[1005]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 01 15:10:56 volumio volumio[1005]: Cannot find translation for source Jellyfin Sep 01 15:10:56 volumio volumio[1005]: Cannot find translation for source YouTube2 Sep 01 15:10:56 volumio volumio[1005]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Sep 01 15:10:56 volumio volumio[1005]: info: [1756757456910] CoreMusicLibrary::Adding element Pandora Radio Sep 01 15:10:56 volumio volumio[1005]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 01 15:10:56 volumio volumio[1005]: Cannot find translation for source Jellyfin Sep 01 15:10:56 volumio volumio[1005]: Cannot find translation for source YouTube2 Sep 01 15:10:56 volumio volumio[1005]: Cannot find translation for source Pandora Radio Sep 01 15:10:56 volumio volumio[1005]: info: [1756757456912] ControllerPandora::initializeMQTT Sep 01 15:10:56 volumio volumio[1005]: info: [1756757456913] [Pandora] initializeMQTT: MQTT is not enabled in Plugin Configuration Sep 01 15:10:56 volumio volumio[1005]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Sep 01 15:10:56 volumio volumio[1005]: info: [1756757456920] CoreMusicLibrary::Adding element Radio Paradise Sep 01 15:10:56 volumio volumio[1005]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 01 15:10:56 volumio volumio[1005]: Cannot find translation for source Jellyfin Sep 01 15:10:56 volumio volumio[1005]: Cannot find translation for source YouTube2 Sep 01 15:10:56 volumio volumio[1005]: Cannot find translation for source Pandora Radio Sep 01 15:10:56 volumio volumio[1005]: Cannot find translation for source Radio Paradise Sep 01 15:10:56 volumio volumio[1005]: info: Volumio Calling Home Sep 01 15:10:56 volumio volumio[1005]: info: [1756757456983] ControllerPandora::initialSetup Sep 01 15:10:56 volumio volumio[1005]: info: [1756757456989] ControllerPandora::PandoraHandler::init Sep 01 15:10:56 volumio volumio[1005]: info: [1756757456990] ControllerPandora::PandoraHandler::loadErrorCodes Sep 01 15:10:56 volumio volumio[1005]: info: [1756757456998] [Pandora] PandoraHandler::setMaxStationTracks: 16 Sep 01 15:10:56 volumio volumio[1005]: info: [1756757456999] [Pandora] PandoraHandler::setBandFilter: bandfilter is empty Sep 01 15:10:57 volumio volumio[1005]: info: [1756757457000] ControllerPandora::flushPandora Sep 01 15:10:57 volumio volumio[1005]: info: CorePlayQueue::getQueue Sep 01 15:10:57 volumio volumio[1005]: info: CorePlayQueue::clearAddPlayQueue Sep 01 15:10:57 volumio volumio[1005]: info: CorePlayQueue::saveQueue Sep 01 15:10:57 volumio volumio[1005]: info: CoreCommandRouter::serviceClearAddPlayTracks Sep 01 15:10:57 volumio volumio[1005]: error: WARNING: No clearAddPlayTracks method for service spop Sep 01 15:10:57 volumio volumio[1005]: info: CoreCommandRouter::volumioPushQueue Sep 01 15:10:57 volumio volumio[1005]: info: [1756757457005] ControllerPandora::validateAndSetAccountOptions Sep 01 15:10:57 volumio volumio[1005]: info: [1756757457006] ControllerPandora::PandoraHandler::setAccountOptions Sep 01 15:10:57 volumio volumio[1005]: info: [1756757457007] ControllerPandora::flushPandora Sep 01 15:10:57 volumio volumio[1005]: info: CorePlayQueue::getQueue Sep 01 15:10:57 volumio volumio[1005]: info: CorePlayQueue::clearAddPlayQueue Sep 01 15:10:57 volumio volumio[1005]: info: CorePlayQueue::saveQueue Sep 01 15:10:57 volumio volumio[1005]: info: CoreCommandRouter::serviceClearAddPlayTracks Sep 01 15:10:57 volumio volumio[1005]: error: WARNING: No clearAddPlayTracks method for service spop Sep 01 15:10:57 volumio volumio[1005]: info: CoreCommandRouter::volumioPushQueue Sep 01 15:10:57 volumio volumio[1005]: info: [1756757457013] [Pandora] PreventAuthTimeout::init: Timer loaded Sep 01 15:10:57 volumio volumio[1005]: info: [1756757457013] [Pandora] PreventAuthTimeout::init: Interval set to 10800000 ms Sep 01 15:10:57 volumio volumio[1005]: info: [1756757457013] [Pandora] PreventAuthTimeout::init: Starting delayed timer after next interval Sep 01 15:10:57 volumio volumio[1005]: info: [1756757457014] ControllerPandora::PandoraHandler::pandoraLoginAndGetStations Sep 01 15:10:57 volumio volumio[1005]: info: Discovery: adding a5748a65-3da6-42f5-b4ce-3c4bdc02a23d Sep 01 15:10:57 volumio volumio[1005]: info: Discovery: Found device Volumio Sep 01 15:10:57 volumio volumio[1005]: info: CoreCommandRouter::volumioGetState Sep 01 15:10:57 volumio volumio[1005]: info: CorePlayQueue::getTrack 0 Sep 01 15:10:57 volumio volumio[1005]: info: MPD Permissions set Sep 01 15:10:57 volumio volumio[1005]: info: MPD Permissions set Sep 01 15:10:57 volumio volumio[1005]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Sep 01 15:10:57 volumio volumio[1005]: info: Spotify config file written Sep 01 15:10:57 volumio sudo[1230]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Sep 01 15:10:57 volumio sudo[1230]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 01 15:10:57 volumio sh[545]: timed out Sep 01 15:10:57 volumio dhcpcd[584]: timed out Sep 01 15:10:57 volumio volumio[1005]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 15:10:57 volumio sh[545]: dhcpcd exited Sep 01 15:10:57 volumio dhcpcd[584]: dhcpcd exited Sep 01 15:10:57 volumio sh[545]: ifup: failed to bring up eth0 Sep 01 15:10:57 volumio volumio[1005]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 15:10:57 volumio volumio[1005]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 15:10:57 volumio volumio[1005]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 15:10:57 volumio volumio[1005]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 15:10:57 volumio systemd[1]: ifup@eth0.service: Main process exited, code=exited, status=1/FAILURE Sep 01 15:10:57 volumio systemd[1]: ifup@eth0.service: Failed with result 'exit-code'. Sep 01 15:10:57 volumio volumio[1005]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 01 15:10:57 volumio volumio[1005]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 15:10:57 volumio volumio[1005]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 15:10:57 volumio volumio[1005]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 15:10:57 volumio volumio[1005]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 15:10:57 volumio volumio[1005]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 15:10:57 volumio volumio[1005]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 15:10:57 volumio volumio[1005]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 15:10:57 volumio volumio[1005]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 15:10:57 volumio volumio[1005]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 15:10:57 volumio volumio[1005]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 01 15:10:57 volumio volumio[1005]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 15:10:57 volumio volumio[1005]: info: No need to fix Spotify hosts Sep 01 15:10:57 volumio systemd[1]: Started go-librespot Daemon. Sep 01 15:10:57 volumio go-librespot[1237]: go-librespot daemon starting... Sep 01 15:10:57 volumio sudo[1230]: pam_unix(sudo:session): session closed for user root Sep 01 15:10:57 volumio volumio[1005]: info: CoreCommandRouter::volumioGetState Sep 01 15:10:57 volumio volumio[1005]: info: CorePlayQueue::getTrack 0 Sep 01 15:10:57 volumio volumio[1005]: info: Starting Shairport Sync Sep 01 15:10:57 volumio volumio[1005]: info: Starting Shairport Sync Sep 01 15:10:57 volumio sudo[1244]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Sep 01 15:10:57 volumio sudo[1244]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 01 15:10:57 volumio volumio[1005]: info: Starting Shairport Sync Sep 01 15:10:57 volumio sudo[1246]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Sep 01 15:10:57 volumio sudo[1246]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 01 15:10:57 volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Sep 01 15:10:57 volumio sudo[1249]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Sep 01 15:10:57 volumio sudo[1249]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 01 15:10:57 volumio systemd[1]: shairport-sync.service: Succeeded. Sep 01 15:10:57 volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Sep 01 15:10:57 volumio volumio[1005]: info: Volumio called home Sep 01 15:10:57 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Sep 01 15:10:57 volumio sudo[1244]: pam_unix(sudo:session): session closed for user root Sep 01 15:10:57 volumio volumio[1005]: info: Shairport-Sync Started Sep 01 15:10:57 volumio volumio[1005]: Error adding Membership: Error: addMembership EINVAL Sep 01 15:10:57 volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Sep 01 15:10:57 volumio systemd[1]: shairport-sync.service: Main process exited, code=killed, status=15/TERM Sep 01 15:10:57 volumio systemd[1]: shairport-sync.service: Succeeded. Sep 01 15:10:57 volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Sep 01 15:10:57 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Sep 01 15:10:57 volumio sudo[1246]: pam_unix(sudo:session): session closed for user root Sep 01 15:10:57 volumio volumio[1005]: info: Shairport-Sync Started Sep 01 15:10:57 volumio sudo[1249]: pam_unix(sudo:session): session closed for user root Sep 01 15:10:57 volumio volumio[1005]: info: Shairport-Sync Started Sep 01 15:10:57 volumio go-librespot[1237]: time="2025-09-01T15:10:57-05:00" level=info msg="running go-librespot 0.3.2" Sep 01 15:10:57 volumio go-librespot[1237]: time="2025-09-01T15:10:57-05:00" level=debug msg="no app state found" Sep 01 15:10:57 volumio go-librespot[1237]: time="2025-09-01T15:10:57-05:00" level=debug msg="stored credentials not found" Sep 01 15:10:57 volumio go-librespot[1237]: time="2025-09-01T15:10:57-05:00" level=info msg="generated new device id: a19b30be179497641816cccc409c65ab40d07ecb" Sep 01 15:10:57 volumio go-librespot[1237]: time="2025-09-01T15:10:57-05:00" level=info msg="api server listening on 127.0.0.1:9879" Sep 01 15:10:57 volumio mpd[1225]: Sep 01 15:10 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Sep 01 15:10:57 volumio systemd[1]: Started Music Player Daemon. Sep 01 15:10:57 volumio sudo[1196]: pam_unix(sudo:session): session closed for user root Sep 01 15:10:57 volumio sudo[1205]: pam_unix(sudo:session): session closed for user root Sep 01 15:10:57 volumio volumio[1005]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Sep 01 15:10:57 volumio volumio[1005]: SPOTIFY: BQBwS1XvhJOd91jPkExpd6iYfwInkMW7TZoh-kmdpla3PHVCKtWfuOnVXp-vl26l26CHAouWb72AaXHQFE5SwLbwJOX4E3x4gkeKhjDftlaU1u5c6VPIm3VN1gH3s3og_ICeRlmIAMWSL3xI5Pawg1FbbwERfCS_JJNH1zK1y7QOXk0sU2i1pD0YfeE8Jv2sCibVP1W97-6a03SA57NsjPx2uhyjV3hdSwyOAdSFevRDT2of8r-72g16yXwM3Z-GDCBErGDws_9ajdZuJ6NHLlyTsGK-6D-A4uW1BYcoWpDrc7i6kaU Sep 01 15:10:57 volumio volumio[1005]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Sep 01 15:10:57 volumio volumio[1005]: info: New Spotify access token = BQBwS1XvhJOd91jPkExpd6iYfwInkMW7TZoh-kmdpla3PHVCKtWfuOnVXp-vl26l26CHAouWb72AaXHQFE5SwLbwJOX4E3x4gkeKhjDftlaU1u5c6VPIm3VN1gH3s3og_ICeRlmIAMWSL3xI5Pawg1FbbwERfCS_JJNH1zK1y7QOXk0sU2i1pD0YfeE8Jv2sCibVP1W97-6a03SA57NsjPx2uhyjV3hdSwyOAdSFevRDT2of8r-72g16yXwM3Z-GDCBErGDws_9ajdZuJ6NHLlyTsGK-6D-A4uW1BYcoWpDrc7i6kaU Sep 01 15:10:57 volumio volumio[1005]: info: Spotify credentials grant success - running version from March 24, 2019 Sep 01 15:10:57 volumio volumio[1005]: error: MPD error: The expression evaluated to a falsy value: Sep 01 15:10:57 volumio volumio[1005]: assert.ok(self.idling) Sep 01 15:10:57 volumio volumio[1005]: error: The expression evaluated to a falsy value: Sep 01 15:10:57 volumio volumio[1005]: assert.ok(self.idling) Sep 01 15:10:57 volumio volumio[1005]: info: MPD running with PID1225 Sep 01 15:10:57 volumio volumio[1005]: ,establishing connection Sep 01 15:10:57 volumio volumio[1005]: error: updateQueue error: null Sep 01 15:10:57 volumio volumio[1005]: info: CoreCommandRouter::volumioGetState Sep 01 15:10:57 volumio volumio[1005]: info: CorePlayQueue::getTrack 0 Sep 01 15:10:57 volumio volumio[1005]: error: updateQueue error: null Sep 01 15:10:57 volumio volumio[1005]: info: [1756757457850] [Pandora] PandoraHandler::pandoraLoginAndGetStations::pandoraLogin: [<=- Logged in to Pandora Servers -=>] Sep 01 15:10:57 volumio volumio[1005]: info: [1756757457854] [Pandora] validateAndSetAccountOptions: ***DEBUG*** self.loggedIn: true Sep 01 15:10:57 volumio volumio[1005]: info: [1756757457855] [Pandora] ExpireOldTracks::init: Timer loaded Sep 01 15:10:57 volumio volumio[1005]: info: [1756757457855] [Pandora] ExpireOldTracks::init: Interval set to 300000 ms Sep 01 15:10:57 volumio volumio[1005]: info: [1756757457855] [Pandora] ExpireOldTracks::init: Starting delayed timer after next interval Sep 01 15:10:57 volumio volumio[1005]: info: [1756757457855] ControllerPandora::PandoraHandler::fillStationData Sep 01 15:10:57 volumio go-librespot[1237]: time="2025-09-01T15:10:57-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Sep 01 15:10:57 volumio go-librespot[1237]: time="2025-09-01T15:10:57-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Sep 01 15:10:57 volumio go-librespot[1237]: time="2025-09-01T15:10:57-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Sep 01 15:10:57 volumio go-librespot[1237]: time="2025-09-01T15:10:57-05:00" level=info msg="zeroconf server listening on port 35029" Sep 01 15:10:57 volumio volumio[1005]: SPOTIFY: User informations: {"country":"US","display_name":"Autistic Boy Remix","email":"zrhoch@comcast.net","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/31rbxqfkvr7econankc6fm34nl6i"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/31rbxqfkvr7econankc6fm34nl6i","id":"31rbxqfkvr7econankc6fm34nl6i","images":[{"height":300,"url":"https://i.scdn.co/image/ab6775700000ee853fa9f93d7b5f1630254425cb","width":300},{"height":64,"url":"https://i.scdn.co/image/ab67757000003b823fa9f93d7b5f1630254425cb","width":64}],"product":"premium","type":"user","uri":"spotify:user:31rbxqfkvr7econankc6fm34nl6i"} Sep 01 15:10:57 volumio volumio[1005]: info: Spotify Successfully logged in Sep 01 15:10:57 volumio volumio[1005]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Sep 01 15:10:57 volumio volumio[1005]: info: [1756757457958] CoreMusicLibrary::Adding element Spotify Sep 01 15:10:57 volumio volumio[1005]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 01 15:10:57 volumio volumio[1005]: Cannot find translation for source Jellyfin Sep 01 15:10:57 volumio volumio[1005]: Cannot find translation for source YouTube2 Sep 01 15:10:57 volumio volumio[1005]: Cannot find translation for source Pandora Radio Sep 01 15:10:57 volumio volumio[1005]: Cannot find translation for source Radio Paradise Sep 01 15:10:57 volumio volumio[1005]: Cannot find translation for source Spotify Sep 01 15:10:58 volumio go-librespot[1237]: time="2025-09-01T15:10:58-05:00" level=debug msg="obtained new client token: AACjp8vEzLL//JzGbKFJd+baHHHHoWq8+Of6p60LUnrx8scVbQU5Ru2kTYIvQLgq7IHujgBr5LBUXgH/1nAaMOlnASPifwF2YGvFt2ghdzMWHS8jU7T5+To3tyUOfWUfd293BANBbgMDCbDa+ucv45x0SlsPdFntbET1qD9u0nz8kblOIivNe7FgL802Tm9bv7VBRI6aH7iQWSS8NjOE+91EHuJJkMgB1TkwLESu3B/3WDnAV7j5eT4w" Sep 01 15:10:58 volumio go-librespot[1237]: time="2025-09-01T15:10:58-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Sep 01 15:10:58 volumio go-librespot[1237]: time="2025-09-01T15:10:58-05:00" level=debug msg="completed keyexchange" Sep 01 15:10:58 volumio go-librespot[1237]: time="2025-09-01T15:10:58-05:00" level=debug msg="completed challenge" Sep 01 15:10:58 volumio go-librespot[1237]: time="2025-09-01T15:10:58-05:00" level=info msg="authenticated AP" username="31************************6i" Sep 01 15:10:58 volumio systemd[1]: systemd-hostnamed.service: Succeeded. Sep 01 15:10:58 volumio volumio[1005]: info: Completed starting Core Plugins Sep 01 15:10:58 volumio volumio[1005]: info: ------------------------------------------- Sep 01 15:10:58 volumio volumio[1005]: info: ----- MyVolumio plugins startup ---- Sep 01 15:10:58 volumio volumio[1005]: info: ------------------------------------------- Sep 01 15:10:58 volumio volumio[1005]: info: [MyVolumio PluginManager] Fetching plans data.... Sep 01 15:10:58 volumio go-librespot[1237]: time="2025-09-01T15:10:58-05:00" level=info msg="authenticated Login5" username="31************************6i" Sep 01 15:10:58 volumio go-librespot[1237]: time="2025-09-01T15:10:58-05:00" level=debug msg="stored credentials" username="31************************6i" Sep 01 15:10:58 volumio go-librespot[1237]: time="2025-09-01T15:10:58-05:00" level=debug msg="initializing zeroconf session" username="31************************6i" Sep 01 15:10:58 volumio go-librespot[1237]: time="2025-09-01T15:10:58-05:00" level=debug msg="dealer connection opened" Sep 01 15:10:58 volumio go-librespot[1237]: time="2025-09-01T15:10:58-05:00" level=trace msg="starting accesspoint recv loop" Sep 01 15:10:58 volumio go-librespot[1237]: time="2025-09-01T15:10:58-05:00" level=trace msg="starting dealer recv loop" Sep 01 15:10:58 volumio go-librespot[1237]: time="2025-09-01T15:10:58-05:00" level=trace msg="received accesspoint ping" Sep 01 15:10:58 volumio go-librespot[1237]: time="2025-09-01T15:10:58-05:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Sep 01 15:10:58 volumio go-librespot[1237]: time="2025-09-01T15:10:58-05:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Sep 01 15:10:58 volumio go-librespot[1237]: time="2025-09-01T15:10:58-05:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Sep 01 15:10:58 volumio go-librespot[1237]: time="2025-09-01T15:10:58-05:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Sep 01 15:10:58 volumio go-librespot[1237]: time="2025-09-01T15:10:58-05:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Sep 01 15:10:58 volumio go-librespot[1237]: time="2025-09-01T15:10:58-05:00" level=debug msg="received connection id: NjgwZGM0ODctNzA1...QjI0MEU4Q0I5Qw==" Sep 01 15:10:58 volumio go-librespot[1237]: time="2025-09-01T15:10:58-05:00" level=trace msg="received accesspoint pong ack" Sep 01 15:10:59 volumio go-librespot[1237]: time="2025-09-01T15:10:59-05:00" level=debug msg="put connect state because NEW_DEVICE" Sep 01 15:11:00 volumio volumio[1005]: info: go-librespot daemon successfully initialized Sep 01 15:11:02 volumio volumio[1005]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Sep 01 15:11:03 volumio volumio[1005]: Cannot compose Albumart path Sep 01 15:11:03 volumio volumio[1005]: info: Initializing connection to go-librespot Websocket Sep 01 15:11:03 volumio go-librespot[1237]: time="2025-09-01T15:11:03-05:00" level=debug msg="new websocket client" Sep 01 15:11:03 volumio volumio[1005]: info: Connection to go-librespot Websocket established Sep 01 15:11:04 volumio volumio-remote-updater[610]: [2025-09-01 15:11:04] [connect] Successful connection Sep 01 15:11:04 volumio volumio-remote-updater[610]: [2025-09-01 15:11:04] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1756757464 101 Sep 01 15:11:04 volumio volumio[1005]: 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: 4 Sep 01 15:11:05 volumio go-librespot[1237]: time="2025-09-01T15:11:05-05:00" level=debug msg="handling transfer player command from 927b4bcf8a9e0c44be1fa5b6bac0675a4d5098f7" Sep 01 15:11:05 volumio go-librespot[1237]: time="2025-09-01T15:11:05-05:00" level=debug msg="resolved context of track" uri="spotify:playlist:6NgHGJz1EYeEek4LIrdzy1" Sep 01 15:11:05 volumio go-librespot[1237]: time="2025-09-01T15:11:05-05:00" level=trace msg="fetched new page 0 with 56 items (list: 56)" uri="spotify:playlist:6NgHGJz1EYeEek4LIrdzy1" Sep 01 15:11:05 volumio go-librespot[1237]: time="2025-09-01T15:11:05-05:00" level=debug msg="loading track (paused: true, position: 4672ms)" uri="spotify:track:0bRXwKfigvpKZUurwqAlEh" Sep 01 15:11:05 volumio go-librespot[1237]: time="2025-09-01T15:11:05-05:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 01 15:11:05 volumio go-librespot[1237]: time="2025-09-01T15:11:05-05:00" level=trace msg="emitting websocket event: will_play" Sep 01 15:11:05 volumio volumio[1005]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:0bRXwKfigvpKZUurwqAlEh","play_origin":"playlist"}} Sep 01 15:11:05 volumio go-librespot[1237]: time="2025-09-01T15:11:05-05:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 345" Sep 01 15:11:05 volumio go-librespot[1237]: time="2025-09-01T15:11:05-05:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1720" Sep 01 15:11:05 volumio go-librespot[1237]: time="2025-09-01T15:11:05-05:00" level=debug msg="selected format OGG_VORBIS_320 (94f7a1a6d8217395cd86e4499d2bd6dd0ed744da)" uri="spotify:track:0bRXwKfigvpKZUurwqAlEh" Sep 01 15:11:05 volumio go-librespot[1237]: time="2025-09-01T15:11:05-05:00" level=debug msg="requested aes key for file 94f7a1a6d8217395cd86e4499d2bd6dd0ed744da, gid: 0bRXwKfigvpKZUurwqAlEh" Sep 01 15:11:05 volumio go-librespot[1237]: time="2025-09-01T15:11:05-05:00" level=trace msg="found 2 cdn urls" uri="spotify:track:0bRXwKfigvpKZUurwqAlEh" Sep 01 15:11:06 volumio go-librespot[1237]: time="2025-09-01T15:11:06-05:00" level=debug msg="fetched first chunk of 21, total size is 10545928 bytes" uri="spotify:track:0bRXwKfigvpKZUurwqAlEh" Sep 01 15:11:06 volumio go-librespot[1237]: time="2025-09-01T15:11:06-05:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1304" Sep 01 15:11:06 volumio go-librespot[1237]: time="2025-09-01T15:11:06-05:00" level=trace msg="seek to 4672ms (diff: 81ms, samples: 206035, bytes: 197329)" uri="spotify:track:0bRXwKfigvpKZUurwqAlEh" Sep 01 15:11:06 volumio go-librespot[1237]: time="2025-09-01T15:11:06-05:00" level=debug msg="created new output device" Sep 01 15:11:06 volumio go-librespot[1237]: time="2025-09-01T15:11:06-05:00" level=info msg="loaded track \"Lovely Day\" (paused: true, position: 4672ms, duration: 254560ms, prefetched: false)" uri="spotify:track:0bRXwKfigvpKZUurwqAlEh" Sep 01 15:11:06 volumio go-librespot[1237]: time="2025-09-01T15:11:06-05:00" level=debug msg="fetched chunk 1/20, size: 524288" uri="spotify:track:0bRXwKfigvpKZUurwqAlEh" Sep 01 15:11:06 volumio go-librespot[1237]: time="2025-09-01T15:11:06-05:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 01 15:11:06 volumio go-librespot[1237]: time="2025-09-01T15:11:06-05:00" level=trace msg="emitting websocket event: metadata" Sep 01 15:11:06 volumio go-librespot[1237]: time="2025-09-01T15:11:06-05:00" level=trace msg="emitting websocket event: active" Sep 01 15:11:06 volumio go-librespot[1237]: time="2025-09-01T15:11:06-05:00" level=debug msg="sending successful reply for dealer request" Sep 01 15:11:06 volumio volumio[1005]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:0bRXwKfigvpKZUurwqAlEh","name":"Lovely Day","artist_names":["Bill Withers"],"album_name":"Menagerie","album_cover_url":"https://i.scdn.co/image/ab67616d00001e025ade9b4d547203c9061fc340","position":4672,"duration":254560,"release_date":"year:1977 month:10 day:29","track_number":1,"disc_number":1}} Sep 01 15:11:06 volumio volumio[1005]: SPOTIFY: received: {"type":"active","data":null} Sep 01 15:11:06 volumio go-librespot[1237]: time="2025-09-01T15:11:06-05:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Sep 01 15:11:06 volumio go-librespot[1237]: time="2025-09-01T15:11:06-05:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Sep 01 15:11:06 volumio volumio[1005]: info: Aligning Spotify Volume to Volumio Volume Sep 01 15:11:06 volumio volumio[1005]: info: CoreCommandRouter::volumioGetState Sep 01 15:11:06 volumio volumio[1005]: info: CorePlayQueue::getTrack 0 Sep 01 15:11:06 volumio go-librespot[1237]: time="2025-09-01T15:11:06-05:00" level=debug msg="fetched chunk 3/20, size: 524288" uri="spotify:track:0bRXwKfigvpKZUurwqAlEh" Sep 01 15:11:06 volumio volumio[1005]: info: Getting Spotify volume Sep 01 15:11:06 volumio volumio[1005]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 5 Sep 01 15:11:06 volumio go-librespot[1237]: time="2025-09-01T15:11:06-05:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 01 15:11:06 volumio go-librespot[1237]: time="2025-09-01T15:11:06-05:00" level=trace msg="emitting websocket event: paused" Sep 01 15:11:06 volumio volumio[1005]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:0bRXwKfigvpKZUurwqAlEh","play_origin":"playlist"}} Sep 01 15:11:06 volumio volumio[1005]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Sep 01 15:11:06 volumio volumio[1005]: TypeError: Cannot read property 'service' of undefined Sep 01 15:11:06 volumio volumio[1005]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:346:50) Sep 01 15:11:06 volumio volumio[1005]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:280:18) Sep 01 15:11:06 volumio volumio[1005]: at WebSocket.message (/data/plugins/music_service/spop/index.js:199:14) Sep 01 15:11:06 volumio volumio[1005]: at WebSocket.emit (events.js:315:20) Sep 01 15:11:06 volumio volumio[1005]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20) Sep 01 15:11:06 volumio volumio[1005]: at Receiver.emit (events.js:315:20) Sep 01 15:11:06 volumio volumio[1005]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) Sep 01 15:11:06 volumio volumio[1005]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) Sep 01 15:11:06 volumio volumio[1005]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) Sep 01 15:11:06 volumio volumio[1005]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) Sep 01 15:11:06 volumio volumio[1005]: at writeOrBuffer (internal/streams/writable.js:358:12) Sep 01 15:11:06 volumio volumio[1005]: at Receiver.Writable.write (internal/streams/writable.js:303:10) Sep 01 15:11:06 volumio volumio[1005]: at Socket.socketOnData (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1355:35) Sep 01 15:11:06 volumio volumio[1005]: at Socket.emit (events.js:315:20) Sep 01 15:11:06 volumio volumio[1005]: at addChunk (internal/streams/readable.js:309:12) Sep 01 15:11:06 volumio volumio[1005]: at readableAddChunk (internal/streams/readable.js:284:9) Sep 01 15:11:06 volumio volumio[1005]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Sep 01 15:11:06 volumio go-librespot[1237]: time="2025-09-01T15:11:06-05:00" level=debug msg="fetched chunk 2/20, size: 524288" uri="spotify:track:0bRXwKfigvpKZUurwqAlEh" Sep 01 15:11:06 volumio sudo[1293]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-09-01 15:10 Sep 01 15:11:06 volumio sudo[1293]: 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"