-- Logs begin at Thu 2019-02-14 11:11:59 CET, end at Wed 2024-02-21 21:44:02 CET. -- Feb 21 21:43:00 volumioscholz ntpd[663]: error resolving pool 3.debian.pool.ntp.org: System error (-11) Feb 21 21:43:00 volumioscholz bthelper[595]: Changing power off succeeded Feb 21 21:43:01 volumioscholz sh[387]: eth0: leased 10.0.0.33 for 864000 seconds Feb 21 21:43:01 volumioscholz dhcpcd[431]: eth0: leased 10.0.0.33 for 864000 seconds Feb 21 21:43:01 volumioscholz avahi-daemon[470]: Joining mDNS multicast group on interface eth0.IPv4 with address 10.0.0.33. Feb 21 21:43:01 volumioscholz sh[387]: eth0: adding route to 10.0.0.0/24 Feb 21 21:43:01 volumioscholz sh[387]: eth0: adding default route via 10.0.0.138 Feb 21 21:43:01 volumioscholz avahi-daemon[470]: New relevant interface eth0.IPv4 for mDNS. Feb 21 21:43:01 volumioscholz dhcpcd[431]: eth0: adding route to 10.0.0.0/24 Feb 21 21:43:01 volumioscholz avahi-daemon[470]: Registering new address record for 10.0.0.33 on eth0.IPv4. Feb 21 21:43:01 volumioscholz dhcpcd[431]: eth0: adding default route via 10.0.0.138 Feb 21 21:43:01 volumioscholz bthelper[595]: [CHG] Controller B8:27:EB:9C:D9:1A Class: 0x0000041c Feb 21 21:43:01 volumioscholz bthelper[595]: Changing power on succeeded Feb 21 21:43:01 volumioscholz sh[387]: forked to background, child pid 736 Feb 21 21:43:01 volumioscholz dhcpcd[431]: forked to background, child pid 736 Feb 21 21:43:01 volumioscholz sudo[704]: pam_unix(sudo:session): session closed for user root Feb 21 21:43:01 volumioscholz wireless.js[464]: sudo: unable to resolve host volumioscholz: System error Feb 21 21:43:01 volumioscholz wireless.js[464]: SETTING APPROPRIATE REG DOMAIN: EU Feb 21 21:43:01 volumioscholz sudo[738]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 up Feb 21 21:43:01 volumioscholz sudo[738]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 21 21:43:01 volumioscholz sudo[738]: pam_unix(sudo:session): session closed for user root Feb 21 21:43:01 volumioscholz sudo[756]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iw reg set EU Feb 21 21:43:01 volumioscholz sudo[756]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 21 21:43:01 volumioscholz sudo[756]: pam_unix(sudo:session): session closed for user root Feb 21 21:43:01 volumioscholz wireless.js[464]: SUCCESSFULLY SET NEW REGDOMAIN: EU Feb 21 21:43:01 volumioscholz wireless.js[464]: Start wireless flow Feb 21 21:43:01 volumioscholz wireless.js[464]: Stopped hotspot (if there).. Feb 21 21:43:01 volumioscholz systemd-udevd[719]: Process '/sbin/crda' failed with exit code 255. Feb 21 21:43:01 volumioscholz ifplugd(eth0)[653]: client: ifup: interface eth0 already configured Feb 21 21:43:01 volumioscholz sh[387]: eth0=eth0 Feb 21 21:43:01 volumioscholz sudo[767]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ip addr flush dev wlan0 Feb 21 21:43:01 volumioscholz sudo[767]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 21 21:43:01 volumioscholz sudo[767]: pam_unix(sudo:session): session closed for user root Feb 21 21:43:01 volumioscholz sudo[773]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 down Feb 21 21:43:01 volumioscholz sudo[773]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 21 21:43:01 volumioscholz ifplugd(eth0)[653]: Program executed successfully. Feb 21 21:43:01 volumioscholz ifplugd[586]: Network Interface Plugging Daemon...start eth0...done. Feb 21 21:43:01 volumioscholz systemd[1]: Started LSB: Brings up/down network automatically. Feb 21 21:43:01 volumioscholz sudo[773]: pam_unix(sudo:session): session closed for user root Feb 21 21:43:01 volumioscholz wireless.js[464]: DHCP IP Feb 21 21:43:01 volumioscholz wireless.js[464]: Start ap Feb 21 21:43:01 volumioscholz wpa_supplicant[775]: Successfully initialized wpa_supplicant Feb 21 21:43:01 volumioscholz sudo[776]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/dhcpcd Feb 21 21:43:01 volumioscholz sudo[776]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 21 21:43:01 volumioscholz dhcpcd[777]: dev: loaded udev Feb 21 21:43:01 volumioscholz kernel: brcmfmac: brcmf_cfg80211_set_power_mgmt: power save disabled Feb 21 21:43:02 volumioscholz dhcpcd-run-hooks[786]: wlan0: starting wpa_supplicant Feb 21 21:43:02 volumioscholz nmbd[596]: [2024/02/21 21:43:02.010812, 0] ../lib/util/become_daemon.c:138(daemon_ready) Feb 21 21:43:02 volumioscholz nmbd[596]: daemon_ready: STATUS=daemon 'nmbd' finished starting up and ready to serve connections Feb 21 21:43:02 volumioscholz systemd[1]: Started Samba NMB Daemon. Feb 21 21:43:02 volumioscholz systemd[1]: Starting Samba Winbind Daemon... Feb 21 21:43:02 volumioscholz dhcpcd-run-hooks[793]: wlan0: failed to start wpa_supplicant Feb 21 21:43:02 volumioscholz dhcpcd-run-hooks[794]: 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 Feb 21 21:43:02 volumioscholz dhcpcd[777]: wlan0: connected to Access Point `' Feb 21 21:43:02 volumioscholz dhcpcd[777]: DUID 00:01:00:01:2d:69:1c:cd:b8:27:eb:36:73:b0 Feb 21 21:43:02 volumioscholz dhcpcd[777]: eth0: IAID eb:36:73:b0 Feb 21 21:43:02 volumioscholz dhcpcd[777]: eth0: adding address fe80::b1d6:e903:c414:a9aa Feb 21 21:43:02 volumioscholz dhcpcd[777]: ipv6_addaddr1: Permission denied Feb 21 21:43:02 volumioscholz dhcpcd[777]: wlan0: waiting for carrier Feb 21 21:43:02 volumioscholz winbindd[788]: [2024/02/21 21:43:02.461470, 0] ../source3/winbindd/winbindd_cache.c:3160(initialize_winbindd_cache) Feb 21 21:43:02 volumioscholz winbindd[788]: initialize_winbindd_cache: clearing cache and re-creating with version number 2 Feb 21 21:43:02 volumioscholz winbindd[788]: [2024/02/21 21:43:02.494562, 0] ../lib/util/become_daemon.c:138(daemon_ready) Feb 21 21:43:02 volumioscholz winbindd[788]: daemon_ready: STATUS=daemon 'winbindd' finished starting up and ready to serve connections Feb 21 21:43:02 volumioscholz systemd[1]: Started Samba Winbind Daemon. Feb 21 21:43:02 volumioscholz systemd[1]: Starting Samba SMB Daemon... Feb 21 21:43:02 volumioscholz dhcpcd[777]: eth0: soliciting an IPv6 router Feb 21 21:43:02 volumioscholz wireless.js[464]: trying... Feb 21 21:43:02 volumioscholz sudo[818]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Feb 21 21:43:02 volumioscholz sudo[818]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 21 21:43:02 volumioscholz sudo[818]: pam_unix(sudo:session): session closed for user root Feb 21 21:43:03 volumioscholz smbd[815]: [2024/02/21 21:43:03.099330, 0] ../lib/util/become_daemon.c:138(daemon_ready) Feb 21 21:43:03 volumioscholz smbd[815]: daemon_ready: STATUS=daemon 'smbd' finished starting up and ready to serve connections Feb 21 21:43:03 volumioscholz systemd[1]: Started Samba SMB Daemon. Feb 21 21:43:03 volumioscholz dhcpcd[777]: eth0: rebinding lease of 10.0.0.33 Feb 21 21:43:03 volumioscholz dhcpcd[777]: eth0: leased 10.0.0.33 for 864000 seconds Feb 21 21:43:03 volumioscholz dhcpcd[777]: eth0: adding route to 10.0.0.0/24 Feb 21 21:43:03 volumioscholz dhcpcd[777]: eth0: adding default route via 10.0.0.138 Feb 21 21:43:03 volumioscholz dhcpcd[777]: forked to background, child pid 847 Feb 21 21:43:03 volumioscholz sudo[776]: pam_unix(sudo:session): session closed for user root Feb 21 21:43:03 volumioscholz wireless.js[464]: trying... Feb 21 21:43:03 volumioscholz sudo[849]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Feb 21 21:43:03 volumioscholz sudo[849]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 21 21:43:03 volumioscholz sudo[849]: pam_unix(sudo:session): session closed for user root Feb 21 21:43:04 volumioscholz wpa_supplicant[792]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=CORE type=WORLD Feb 21 21:43:04 volumioscholz wireless.js[464]: trying... Feb 21 21:43:04 volumioscholz wpa_supplicant[792]: wlan0: Trying to associate with SSID 'scholz' Feb 21 21:43:04 volumioscholz sudo[852]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Feb 21 21:43:04 volumioscholz sudo[852]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 21 21:43:04 volumioscholz sudo[852]: pam_unix(sudo:session): session closed for user root Feb 21 21:43:05 volumioscholz wireless.js[464]: trying... Feb 21 21:43:05 volumioscholz sudo[855]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Feb 21 21:43:05 volumioscholz sudo[855]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 21 21:43:05 volumioscholz sudo[855]: pam_unix(sudo:session): session closed for user root Feb 21 21:43:06 volumioscholz ntpd[663]: Listen normally on 3 eth0 10.0.0.33:123 Feb 21 21:43:06 volumioscholz ntpd[663]: new interface(s) found: waking up resolver Feb 21 21:43:06 volumioscholz wireless.js[464]: trying... Feb 21 21:43:06 volumioscholz volumio-remote-updater[474]: [2024-02-21 21:43:06] [info] asio async_connect error: system:111 (Connection refused) Feb 21 21:43:06 volumioscholz volumio-remote-updater[474]: [2024-02-21 21:43:06] [info] Error getting remote endpoint: system:107 (Transport endpoint is not connected) Feb 21 21:43:06 volumioscholz volumio-remote-updater[474]: [2024-02-21 21:43:06] [error] handle_connect error: Underlying Transport Error Feb 21 21:43:06 volumioscholz sudo[858]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Feb 21 21:43:06 volumioscholz sudo[858]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 21 21:43:06 volumioscholz sudo[858]: pam_unix(sudo:session): session closed for user root Feb 21 21:43:07 volumioscholz dhcpcd[847]: wlan0: carrier acquired Feb 21 21:43:07 volumioscholz dhcpcd[847]: wlan0: connected to Access Point `scholz' Feb 21 21:43:07 volumioscholz wpa_supplicant[792]: wlan0: Associated with 34:98:b5:0e:ab:b1 Feb 21 21:43:07 volumioscholz wpa_supplicant[792]: wlan0: CTRL-EVENT-CONNECTED - Connection to 34:98:b5:0e:ab:b1 completed [id=0 id_str=] Feb 21 21:43:07 volumioscholz wpa_supplicant[792]: wlan0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0 Feb 21 21:43:07 volumioscholz dhcpcd[847]: wlan0: IAID eb:63:26:e5 Feb 21 21:43:07 volumioscholz dhcpcd[847]: wlan0: adding address fe80::7bff:e02:f095:ba85 Feb 21 21:43:07 volumioscholz dhcpcd[847]: ipv6_addaddr1: Permission denied Feb 21 21:43:07 volumioscholz dhcpcd[847]: wlan0: carrier lost Feb 21 21:43:07 volumioscholz systemd-udevd[860]: Process '/sbin/crda' failed with exit code 255. Feb 21 21:43:07 volumioscholz wireless.js[464]: trying... Feb 21 21:43:07 volumioscholz dhcpcd[847]: wlan0: carrier acquired Feb 21 21:43:07 volumioscholz dhcpcd[847]: wlan0: IAID eb:63:26:e5 Feb 21 21:43:07 volumioscholz sudo[879]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Feb 21 21:43:07 volumioscholz sudo[879]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 21 21:43:07 volumioscholz sudo[879]: pam_unix(sudo:session): session closed for user root Feb 21 21:43:08 volumioscholz dhcpcd[847]: wlan0: soliciting an IPv6 router Feb 21 21:43:08 volumioscholz dhcpcd[847]: wlan0: rebinding lease of 10.0.0.80 Feb 21 21:43:08 volumioscholz dhcpcd[847]: wlan0: probing address 10.0.0.80/24 Feb 21 21:43:08 volumioscholz wireless.js[464]: trying... Feb 21 21:43:08 volumioscholz sudo[886]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Feb 21 21:43:08 volumioscholz sudo[886]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 21 21:43:08 volumioscholz sudo[886]: pam_unix(sudo:session): session closed for user root Feb 21 21:43:09 volumioscholz wireless.js[464]: trying... Feb 21 21:43:09 volumioscholz sudo[889]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Feb 21 21:43:09 volumioscholz sudo[889]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 21 21:43:09 volumioscholz sudo[889]: pam_unix(sudo:session): session closed for user root Feb 21 21:43:10 volumioscholz wireless.js[464]: trying... Feb 21 21:43:11 volumioscholz wpa_supplicant[792]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=CORE type=WORLD Feb 21 21:43:11 volumioscholz sudo[892]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Feb 21 21:43:11 volumioscholz sudo[892]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 21 21:43:11 volumioscholz sudo[892]: pam_unix(sudo:session): session closed for user root Feb 21 21:43:11 volumioscholz wireless.js[464]: trying... Feb 21 21:43:11 volumioscholz sudo[895]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Feb 21 21:43:11 volumioscholz sudo[895]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 21 21:43:11 volumioscholz sudo[895]: pam_unix(sudo:session): session closed for user root Feb 21 21:43:12 volumioscholz wireless.js[464]: trying... Feb 21 21:43:12 volumioscholz sudo[898]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Feb 21 21:43:12 volumioscholz sudo[898]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 21 21:43:12 volumioscholz sudo[898]: pam_unix(sudo:session): session closed for user root Feb 21 21:43:13 volumioscholz dhcpcd[847]: wlan0: leased 10.0.0.80 for 864000 seconds Feb 21 21:43:13 volumioscholz avahi-daemon[470]: Joining mDNS multicast group on interface wlan0.IPv4 with address 10.0.0.80. Feb 21 21:43:13 volumioscholz dhcpcd[847]: wlan0: adding route to 10.0.0.0/24 Feb 21 21:43:13 volumioscholz dhcpcd[847]: wlan0: adding default route via 10.0.0.138 Feb 21 21:43:13 volumioscholz avahi-daemon[470]: New relevant interface wlan0.IPv4 for mDNS. Feb 21 21:43:13 volumioscholz avahi-daemon[470]: Registering new address record for 10.0.0.80 on wlan0.IPv4. Feb 21 21:43:13 volumioscholz wireless.js[464]: trying... Feb 21 21:43:13 volumioscholz sudo[922]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Feb 21 21:43:13 volumioscholz sudo[922]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 21 21:43:13 volumioscholz sudo[922]: pam_unix(sudo:session): session closed for user root Feb 21 21:43:13 volumioscholz wireless.js[464]: Connected to: ----scholz Feb 21 21:43:13 volumioscholz wireless.js[464]: ---- Feb 21 21:43:14 volumioscholz sudo[925]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Feb 21 21:43:14 volumioscholz sudo[925]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 21 21:43:14 volumioscholz sudo[925]: pam_unix(sudo:session): session closed for user root Feb 21 21:43:14 volumioscholz wireless.js[464]: ... joined AP, wlan0 IPv4 is 10.0.0.80, ipV6 is undefined Feb 21 21:43:14 volumioscholz wireless.js[464]: It's done! AP Feb 21 21:43:14 volumioscholz kernel: brcmfmac: brcmf_cfg80211_set_power_mgmt: power save disabled Feb 21 21:43:14 volumioscholz systemd[1]: Started Wireless Services. Feb 21 21:43:14 volumioscholz systemd[1]: Started Volumio Backend Module. Feb 21 21:43:14 volumioscholz systemd[1]: Started Volumio Cpu Tweaker. Feb 21 21:43:14 volumioscholz systemd[1]: Reached target Multi-User System. Feb 21 21:43:14 volumioscholz systemd[1]: Reached target Graphical Interface. Feb 21 21:43:14 volumioscholz systemd[1]: Starting Update UTMP about System Runlevel Changes... Feb 21 21:43:14 volumioscholz systemd[1]: systemd-update-utmp-runlevel.service: Succeeded. Feb 21 21:43:14 volumioscholz systemd[1]: Started Update UTMP about System Runlevel Changes. Feb 21 21:43:14 volumioscholz systemd[1]: Startup finished in 10.400s (kernel) + 29.305s (userspace) = 39.706s. Feb 21 21:43:14 volumioscholz volumio-cpu-tweak[931]: Setting RT Priority for mpd Feb 21 21:43:14 volumioscholz volumio-cpu-tweak[931]: pid 35's current scheduling policy: SCHED_OTHER Feb 21 21:43:14 volumioscholz volumio-cpu-tweak[931]: pid 35's current scheduling priority: 0 Feb 21 21:43:14 volumioscholz volumio-cpu-tweak[931]: Setting MPD Affinity Feb 21 21:43:14 volumioscholz volumio-cpu-tweak[931]: pid 3's current affinity mask: f Feb 21 21:43:14 volumioscholz volumio-cpu-tweak[931]: /bin/volumio_cpu_tweak: line 27: warning: command substitution: ignored null byte in input Feb 21 21:43:14 volumioscholz volumio-cpu-tweak[931]: VOLUMIO CPU TWEAK: Setting CPU Governor: performance Feb 21 21:43:14 volumioscholz systemd[1]: volumio_cpu_tweak.service: Succeeded. Feb 21 21:43:15 volumioscholz ntpd[663]: Listen normally on 4 wlan0 10.0.0.80:123 Feb 21 21:43:15 volumioscholz ntpd[663]: new interface(s) found: waking up resolver Feb 21 21:43:16 volumioscholz volumio[930]: info: ------------------------------------------- Feb 21 21:43:16 volumioscholz volumio[930]: info: ----- Volumio3 ---- Feb 21 21:43:16 volumioscholz volumio[930]: info: ------------------------------------------- Feb 21 21:43:16 volumioscholz volumio[930]: info: ----- System startup ---- Feb 21 21:43:16 volumioscholz volumio[930]: info: ------------------------------------------- Feb 21 21:43:16 volumioscholz volumio-remote-updater[474]: [2024-02-21 21:43:16] [connect] Successful connection Feb 21 21:43:17 volumioscholz volumio[930]: info: MYVOLUMIO Environment detected Feb 21 21:43:18 volumioscholz volumio[930]: info: Plugin folders cleanup Feb 21 21:43:18 volumioscholz volumio[930]: info: Scanning into folder /volumio/app/plugins/ Feb 21 21:43:18 volumioscholz volumio[930]: info: Scanning category audio_interface Feb 21 21:43:18 volumioscholz volumio[930]: info: Scanning category miscellanea Feb 21 21:43:18 volumioscholz volumio[930]: info: Scanning category music_service Feb 21 21:43:18 volumioscholz volumio[930]: info: Scanning category plugins.json Feb 21 21:43:18 volumioscholz volumio[930]: info: Scanning category system_controller Feb 21 21:43:18 volumioscholz volumio[930]: info: Scanning category user_interface Feb 21 21:43:18 volumioscholz volumio[930]: info: Scanning into folder /data/plugins/ Feb 21 21:43:18 volumioscholz volumio[930]: info: Scanning category music_service Feb 21 21:43:18 volumioscholz volumio[930]: info: Plugin folders cleanup completed Feb 21 21:43:18 volumioscholz volumio[930]: info: ------------------------------------------- Feb 21 21:43:18 volumioscholz volumio[930]: info: ----- Core plugins startup ---- Feb 21 21:43:18 volumioscholz volumio[930]: info: ------------------------------------------- Feb 21 21:43:18 volumioscholz volumio[930]: info: Loading plugins from folder /volumio/app/plugins/ Feb 21 21:43:18 volumioscholz volumio[930]: info: Adding plugin upnp to MyMusic Plugins Feb 21 21:43:18 volumioscholz volumio[930]: info: Adding plugin airplay_emulation to MyMusic Plugins Feb 21 21:43:18 volumioscholz volumio[930]: info: Adding plugin upnp_browser to MyMusic Plugins Feb 21 21:43:18 volumioscholz volumio[930]: info: Loading plugins from folder /data/plugins/ Feb 21 21:43:18 volumioscholz volumio[930]: info: Loading plugin "system"... Feb 21 21:43:18 volumioscholz volumio[930]: info: Loading plugin "appearance"... Feb 21 21:43:19 volumioscholz volumio[930]: info: Loading plugin "network"... Feb 21 21:43:19 volumioscholz volumio[930]: info: Refreshing Cached IP Addresses Feb 21 21:43:19 volumioscholz sudo[962]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Feb 21 21:43:19 volumioscholz sudo[962]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 21 21:43:19 volumioscholz volumio[930]: info: Loading plugin "services"... Feb 21 21:43:19 volumioscholz sudo[964]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Feb 21 21:43:19 volumioscholz sudo[964]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 21 21:43:19 volumioscholz volumio[930]: info: Loading plugin "alsa_controller"... Feb 21 21:43:19 volumioscholz sudo[962]: pam_unix(sudo:session): session closed for user root Feb 21 21:43:19 volumioscholz sudo[964]: pam_unix(sudo:session): session closed for user root Feb 21 21:43:19 volumioscholz sudo[966]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Feb 21 21:43:19 volumioscholz sudo[966]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 21 21:43:19 volumioscholz volumio[930]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Feb 21 21:43:19 volumioscholz volumio[930]: info: Loading plugin "wizard"... Feb 21 21:43:19 volumioscholz volumio[930]: info: Loading plugin "networkfs"... Feb 21 21:43:19 volumioscholz volumio[930]: info: Starting Udev Watcher for removable devices Feb 21 21:43:19 volumioscholz sudo[975]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=forestjoe,password=Mbejh51w#14!,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //10.0.0.10/Music/ /mnt/NAS/diskstation Feb 21 21:43:19 volumioscholz sudo[975]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 21 21:43:19 volumioscholz volumio[930]: info: Ignoring mount for partition: boot Feb 21 21:43:19 volumioscholz volumio[930]: info: Ignoring mount for partition: volumio Feb 21 21:43:19 volumioscholz volumio[930]: info: Ignoring mount for partition: volumio_data Feb 21 21:43:19 volumioscholz volumio[930]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Feb 21 21:43:19 volumioscholz volumio[930]: info: Loading plugin "volumio_command_line_client"... Feb 21 21:43:19 volumioscholz volumio[930]: info: Loading plugin "upnp"... Feb 21 21:43:20 volumioscholz volumio[930]: info: [1708548200002] Starting Upmpd Daemon Feb 21 21:43:20 volumioscholz volumio[930]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Feb 21 21:43:20 volumioscholz volumio[930]: info: Loading plugin "my_music"... Feb 21 21:43:20 volumioscholz volumio[930]: info: Loading plugin "mpd"... Feb 21 21:43:20 volumioscholz kernel: Key type cifs.spnego registered Feb 21 21:43:20 volumioscholz kernel: Key type cifs.idmap registered Feb 21 21:43:20 volumioscholz 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. Feb 21 21:43:20 volumioscholz kernel: CIFS: Attempting to mount \\10.0.0.10\Music Feb 21 21:43:20 volumioscholz volumio[930]: info: Loading plugin "upnp_browser"... Feb 21 21:43:20 volumioscholz volumio[930]: info: Loading plugin "alarm-clock"... Feb 21 21:43:21 volumioscholz volumio[930]: info: Loading plugin "airplay_emulation"... Feb 21 21:43:21 volumioscholz volumio[930]: info: Starting Shairport Sync Feb 21 21:43:21 volumioscholz volumio[930]: info: Loading plugin "last_100"... Feb 21 21:43:21 volumioscholz volumio[930]: info: Loading plugin "webradio"... Feb 21 21:43:21 volumioscholz volumio[930]: info: Loading plugin "i2s_dacs"... Feb 21 21:43:21 volumioscholz volumio[930]: info: I2S DAC not set, start Auto-detection Feb 21 21:43:21 volumioscholz volumio[930]: info: Loading plugin "volumiodiscovery"... Feb 21 21:43:21 volumioscholz volumio[930]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Feb 21 21:43:21 volumioscholz volumio[930]: *** WARNING *** Please fix your application to use the native API of Avahi! Feb 21 21:43:21 volumioscholz volumio[930]: *** WARNING *** For more information see Feb 21 21:43:21 volumioscholz volumio[930]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Feb 21 21:43:21 volumioscholz node[930]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Feb 21 21:43:21 volumioscholz volumio[930]: *** WARNING *** Please fix your application to use the native API of Avahi! Feb 21 21:43:21 volumioscholz volumio[930]: *** WARNING *** For more information see Feb 21 21:43:21 volumioscholz node[930]: *** WARNING *** Please fix your application to use the native API of Avahi! Feb 21 21:43:21 volumioscholz node[930]: *** WARNING *** For more information see Feb 21 21:43:21 volumioscholz node[930]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Feb 21 21:43:21 volumioscholz node[930]: *** WARNING *** Please fix your application to use the native API of Avahi! Feb 21 21:43:21 volumioscholz node[930]: *** WARNING *** For more information see Feb 21 21:43:21 volumioscholz volumio[930]: info: Applying required configuration parameters for plugin volumiodiscovery Feb 21 21:43:21 volumioscholz volumio[930]: info: Discovery: Started advertising with name: Volumio_Scholz Feb 21 21:43:21 volumioscholz volumio[930]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Feb 21 21:43:21 volumioscholz volumio[930]: info: Loading plugin "spop"... Feb 21 21:43:22 volumioscholz systemd[1]: systemd-fsckd.service: Succeeded. Feb 21 21:43:23 volumioscholz volumio[930]: info: Loading plugin "outputs"... Feb 21 21:43:23 volumioscholz volumio[930]: info: Loading plugin "albumart"... Feb 21 21:43:23 volumioscholz volumio[930]: info: Plugin example_plugin is not enabled Feb 21 21:43:23 volumioscholz volumio[930]: info: Loading plugin "inputs"... Feb 21 21:43:23 volumioscholz volumio[930]: info: Loading plugin "updater_comm"... Feb 21 21:43:23 volumioscholz volumio[930]: info: Plugin mpdemulation is not enabled Feb 21 21:43:23 volumioscholz volumio[930]: info: Loading plugin "rest_api"... Feb 21 21:43:23 volumioscholz volumio[930]: info: Loading plugin "websocket"... Feb 21 21:43:23 volumioscholz volumio[930]: info: Loading i18n strings for locale en Feb 21 21:43:23 volumioscholz volumio[930]: Updating browse sources language Feb 21 21:43:23 volumioscholz volumio[930]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 21 21:43:23 volumioscholz volumio[930]: Forking 3 albumart workers Feb 21 21:43:23 volumioscholz sudo[966]: pam_unix(sudo:session): session closed for user root Feb 21 21:43:23 volumioscholz volumio[930]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 21 21:43:23 volumioscholz volumio[930]: info: CoreCommandRouter::initPlayerControls Feb 21 21:43:23 volumioscholz volumio[930]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 21 21:43:23 volumioscholz volumio[930]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 21 21:43:23 volumioscholz volumio[930]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 21 21:43:23 volumioscholz volumio[930]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 21 21:43:23 volumioscholz volumio[930]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 21 21:43:23 volumioscholz volumio[930]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 21 21:43:23 volumioscholz volumio[930]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 21 21:43:23 volumioscholz volumio[930]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 21 21:43:23 volumioscholz volumio[930]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 21 21:43:23 volumioscholz volumio[930]: Express server listening on port 3000 Feb 21 21:43:23 volumioscholz volumio[930]: [Metrics] WebUI: 8s 76.64ms Feb 21 21:43:24 volumioscholz volumio[930]: info: CoreStateMachine::resetVolumioState Feb 21 21:43:24 volumioscholz volumio[930]: info: CoreStateMachine::getcurrentVolume Feb 21 21:43:24 volumioscholz volumio[930]: info: CoreCommandRouter::volumioRetrievevolume Feb 21 21:43:24 volumioscholz volumio[930]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 21 21:43:24 volumioscholz volumio[930]: info: Reloading queue from file Feb 21 21:43:24 volumioscholz volumio[930]: info: Setting Device type: Raspberry PI Feb 21 21:43:24 volumioscholz volumio[930]: info: VolumeController:: Volume=61 Mute =false Feb 21 21:43:24 volumioscholz volumio[930]: info: CoreStateMachine::pushState Feb 21 21:43:24 volumioscholz volumio[930]: info: CorePlayQueue::getTrack 0 Feb 21 21:43:24 volumioscholz volumio[930]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 21 21:43:24 volumioscholz volumio[930]: info: CoreCommandRouter::volumioPushState Feb 21 21:43:24 volumioscholz volumio[930]: info: CoreStateMachine::updateTrackBlock Feb 21 21:43:24 volumioscholz volumio[930]: info: CorePlayQueue::getTrackBlock Feb 21 21:43:24 volumioscholz volumio[930]: info: CoreCommandRouter::volumioRetrievevolume Feb 21 21:43:24 volumioscholz volumio[930]: info: CoreStateMachine::setRepeat null single undefined Feb 21 21:43:24 volumioscholz volumio[930]: info: CoreStateMachine::pushState Feb 21 21:43:24 volumioscholz volumio[930]: info: CorePlayQueue::getTrack 0 Feb 21 21:43:24 volumioscholz volumio[930]: info: CoreCommandRouter::volumioPushState Feb 21 21:43:24 volumioscholz volumio[930]: info: CoreStateMachine::setRandom null Feb 21 21:43:24 volumioscholz volumio[930]: info: CoreStateMachine::pushState Feb 21 21:43:24 volumioscholz volumio[930]: info: CorePlayQueue::getTrack 0 Feb 21 21:43:24 volumioscholz volumio[930]: info: CoreCommandRouter::volumioPushState Feb 21 21:43:24 volumioscholz volumio[930]: info: Discovery: adding fa4e78ad-0246-4c6c-aa0c-fee0f6b7009c Feb 21 21:43:24 volumioscholz volumio[930]: info: Discovery: Found device Volumio_Scholz Feb 21 21:43:24 volumioscholz volumio[930]: info: CoreCommandRouter::volumioGetState Feb 21 21:43:24 volumioscholz volumio[930]: info: CorePlayQueue::getTrack 0 Feb 21 21:43:24 volumioscholz volumio[930]: info: Discovery: this is already registered, fa4e78ad-0246-4c6c-aa0c-fee0f6b7009c Feb 21 21:43:24 volumioscholz volumio[930]: info: Discovery: Found device Volumio_Scholz Feb 21 21:43:24 volumioscholz volumio[930]: info: CoreCommandRouter::volumioGetState Feb 21 21:43:24 volumioscholz volumio[930]: info: CorePlayQueue::getTrack 0 Feb 21 21:43:24 volumioscholz volumio[930]: info: VolumeController:: Volume=61 Mute =false Feb 21 21:43:24 volumioscholz volumio[930]: info: CoreStateMachine::pushState Feb 21 21:43:24 volumioscholz volumio[930]: info: CorePlayQueue::getTrack 0 Feb 21 21:43:24 volumioscholz volumio[930]: info: CoreCommandRouter::volumioPushState Feb 21 21:43:24 volumioscholz volumio[930]: Starting albumart workers Feb 21 21:43:24 volumioscholz volumio[930]: Starting albumart workers Feb 21 21:43:24 volumioscholz volumio[930]: Starting albumart workers Feb 21 21:43:26 volumioscholz systemd[1]: systemd-hostnamed.service: Succeeded. Feb 21 21:43:30 volumioscholz sudo[1070]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Feb 21 21:43:30 volumioscholz sudo[1070]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 21 21:43:30 volumioscholz sudo[1070]: pam_unix(sudo:session): session closed for user root Feb 21 21:43:30 volumioscholz sudo[1072]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Feb 21 21:43:30 volumioscholz sudo[1072]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 21 21:43:30 volumioscholz sudo[1072]: pam_unix(sudo:session): session closed for user root Feb 21 21:43:30 volumioscholz sudo[1076]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Feb 21 21:43:30 volumioscholz sudo[1076]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 21 21:43:30 volumioscholz systemd[1]: Started UPnP Renderer front-end to MPD. Feb 21 21:43:30 volumioscholz sudo[1076]: pam_unix(sudo:session): session closed for user root Feb 21 21:43:30 volumioscholz volumio[930]: info: Upmpdcli Daemon Started Feb 21 21:43:30 volumioscholz volumio[930]: error: Upnp client error: Error: connect ECONNREFUSED 127.0.0.1:6600 Feb 21 21:43:31 volumioscholz volumio-remote-updater[474]: [2024-02-21 21:43:31] [connect] Successful connection Feb 21 21:43:31 volumioscholz volumio-remote-updater[474]: [2024-02-21 21:43:31] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1708548211 101 Feb 21 21:43:31 volumioscholz volumio[930]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Total Clients: 1 Feb 21 21:43:32 volumioscholz sudo[975]: pam_unix(sudo:session): session closed for user root Feb 21 21:43:34 volumioscholz volumio[930]: error: Upnp client error: Error: connect ECONNREFUSED 127.0.0.1:6600 Feb 21 21:43:40 volumioscholz volumio[930]: error: Upnp client error: Error: connect ECONNREFUSED 127.0.0.1:6600 Feb 21 21:43:50 volumioscholz volumio[930]: error: Upnp client error: Error: connect ECONNREFUSED 127.0.0.1:6600 Feb 21 21:43:53 volumioscholz volumio[930]: error: Plugin system_controller system failed to complete 'onVolumioStart' in a timely fashion Feb 21 21:43:53 volumioscholz volumio[930]: info: Preparing to generate the ALSA configuration file Feb 21 21:43:53 volumioscholz volumio[930]: info: Asound.conf file unchanged, so no further update is needed Feb 21 21:43:53 volumioscholz volumio[930]: info: Output device has changed, restarting MPD Feb 21 21:43:53 volumioscholz volumio[930]: info: Output device has changed, restarting Shairport Sync Feb 21 21:43:53 volumioscholz volumio[930]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 21 21:43:53 volumioscholz volumio[930]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 21 21:43:53 volumioscholz sudo[1081]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Feb 21 21:43:53 volumioscholz sudo[1081]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 21 21:43:53 volumioscholz sudo[1081]: pam_unix(sudo:session): session closed for user root Feb 21 21:43:53 volumioscholz sudo[1083]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Feb 21 21:43:53 volumioscholz sudo[1083]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 21 21:43:53 volumioscholz volumio[930]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Feb 21 21:43:53 volumioscholz volumio[930]: info: ___________ START PLUGINS ___________ Feb 21 21:43:53 volumioscholz volumio[930]: info: ControllerMpd::onStart: Initializing MPD Feb 21 21:43:53 volumioscholz volumio[930]: info: Creating MPD Configuration file Feb 21 21:43:53 volumioscholz volumio[930]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 21 21:43:53 volumioscholz volumio[930]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Feb 21 21:43:53 volumioscholz volumio[930]: info: [1708548233754] CoreMusicLibrary::Adding element Media Servers Feb 21 21:43:53 volumioscholz volumio[930]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 21 21:43:53 volumioscholz sudo[1091]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Feb 21 21:43:53 volumioscholz sudo[1091]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 21 21:43:53 volumioscholz systemd[1]: Listening on mpd.socket. Feb 21 21:43:53 volumioscholz systemd[1]: Starting Music Player Daemon... Feb 21 21:43:53 volumioscholz sudo[1093]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Feb 21 21:43:53 volumioscholz sudo[1093]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 21 21:43:53 volumioscholz sudo[1091]: pam_unix(sudo:session): session closed for user root Feb 21 21:43:53 volumioscholz systemd[1]: mpd.service: Main process exited, code=killed, status=15/TERM Feb 21 21:43:53 volumioscholz systemd[1]: mpd.service: Succeeded. Feb 21 21:43:53 volumioscholz systemd[1]: Stopped Music Player Daemon. Feb 21 21:43:53 volumioscholz volumio[930]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 21 21:43:53 volumioscholz volumio[930]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 21 21:43:53 volumioscholz systemd[1]: Starting Music Player Daemon... Feb 21 21:43:53 volumioscholz volumio[930]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Feb 21 21:43:53 volumioscholz volumio[930]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 21 21:43:53 volumioscholz volumio[930]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 21 21:43:53 volumioscholz volumio[930]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Feb 21 21:43:53 volumioscholz volumio[930]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Feb 21 21:43:53 volumioscholz volumio[930]: info: [1708548233890] CoreMusicLibrary::Adding element Last_100 Feb 21 21:43:53 volumioscholz volumio[930]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 21 21:43:53 volumioscholz volumio[930]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Feb 21 21:43:53 volumioscholz volumio[930]: info: [1708548233895] CoreMusicLibrary::Adding element Webradio Feb 21 21:43:53 volumioscholz volumio[930]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 21 21:43:53 volumioscholz volumio[930]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Feb 21 21:43:53 volumioscholz volumio[930]: info: Creating Spotify config file Feb 21 21:43:53 volumioscholz volumio[930]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 21 21:43:54 volumioscholz volumio[930]: info: Volumio Calling Home Feb 21 21:43:54 volumioscholz volumio[930]: info: MPD Permissions set Feb 21 21:43:54 volumioscholz volumio[930]: info: MPD Permissions set Feb 21 21:43:54 volumioscholz volumio[930]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 2 Feb 21 21:43:54 volumioscholz volumio[930]: info: Spotify config file written Feb 21 21:43:54 volumioscholz sudo[1108]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Feb 21 21:43:54 volumioscholz sudo[1108]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 21 21:43:54 volumioscholz volumio[930]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 21 21:43:54 volumioscholz volumio[930]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 21 21:43:54 volumioscholz volumio[930]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 21 21:43:54 volumioscholz volumio[930]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 21 21:43:54 volumioscholz volumio[930]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 21 21:43:54 volumioscholz volumio[930]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 21 21:43:54 volumioscholz volumio[930]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 21 21:43:54 volumioscholz volumio[930]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 21 21:43:54 volumioscholz volumio[930]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 21 21:43:54 volumioscholz volumio[930]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 21 21:43:54 volumioscholz volumio[930]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 21 21:43:54 volumioscholz volumio[930]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 21 21:43:54 volumioscholz volumio[930]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 21 21:43:54 volumioscholz volumio[930]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 21 21:43:54 volumioscholz volumio[930]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 21 21:43:54 volumioscholz volumio[930]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 21 21:43:54 volumioscholz volumio[930]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 21 21:43:54 volumioscholz volumio[930]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 21 21:43:54 volumioscholz systemd[1]: Started go-librespot Daemon. Feb 21 21:43:54 volumioscholz go-librespot[1110]: Librespot-go daemon starting... Feb 21 21:43:54 volumioscholz sudo[1108]: pam_unix(sudo:session): session closed for user root Feb 21 21:43:54 volumioscholz volumio[930]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 21 21:43:54 volumioscholz volumio[930]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 21 21:43:54 volumioscholz volumio[930]: info: Volumio called home Feb 21 21:43:54 volumioscholz volumio[930]: info: Starting Shairport Sync Feb 21 21:43:54 volumioscholz volumio[930]: info: Starting Shairport Sync Feb 21 21:43:54 volumioscholz volumio[930]: info: Starting Shairport Sync Feb 21 21:43:54 volumioscholz sudo[1121]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Feb 21 21:43:54 volumioscholz sudo[1121]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 21 21:43:54 volumioscholz sudo[1123]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Feb 21 21:43:54 volumioscholz sudo[1123]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 21 21:43:54 volumioscholz sudo[1125]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Feb 21 21:43:54 volumioscholz sudo[1125]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 21 21:43:54 volumioscholz volumio[930]: info: An error occurred while refreshing Spotify Token Error: certificate is not yet valid Feb 21 21:43:54 volumioscholz systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Feb 21 21:43:54 volumioscholz systemd[1]: shairport-sync.service: Succeeded. Feb 21 21:43:54 volumioscholz systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Feb 21 21:43:54 volumioscholz volumio[930]: info: CoreCommandRouter::volumioGetState Feb 21 21:43:54 volumioscholz volumio[930]: info: CorePlayQueue::getTrack 0 Feb 21 21:43:54 volumioscholz systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Feb 21 21:43:54 volumioscholz sudo[1121]: pam_unix(sudo:session): session closed for user root Feb 21 21:43:54 volumioscholz sudo[1123]: pam_unix(sudo:session): session closed for user root Feb 21 21:43:54 volumioscholz sudo[1125]: pam_unix(sudo:session): session closed for user root Feb 21 21:43:54 volumioscholz volumio[930]: info: Shairport-Sync Started Feb 21 21:43:54 volumioscholz volumio[930]: Error adding Membership: Error: addMembership EINVAL Feb 21 21:43:54 volumioscholz volumio[930]: info: Shairport-Sync Started Feb 21 21:43:54 volumioscholz volumio[930]: info: Shairport-Sync Started Feb 21 21:43:55 volumioscholz go-librespot[1110]: time="2024-02-21T21:43:55+01:00" level=info msg="generated new device id: abfa4d256a50002eaed6bce2a40f6c346d8d645b" Feb 21 21:43:55 volumioscholz go-librespot[1110]: time="2024-02-21T21:43:55+01:00" level=debug msg="stored credentials found for o3295osshkmd0iuru3mkqg701" Feb 21 21:43:55 volumioscholz go-librespot[1110]: time="2024-02-21T21:43:55+01:00" level=debug msg="obtained new client token: AAA/jaS1GxzT9oa0bWZ55EERUfIz4wF34VdTgyoODe41kci0yHbt5EGWY19Y1jDEHpccgc7XwmX308F2MrjIK7XSkYlzK4YlZURM+ffEz596DiNBlYbUKJdyKM5R21R6eDn705Eoaqv9pwW3BMMxdqPetLdul4+jLl4SUnvJwNtkd5J+yR0GCvToZSQtuLZFSVdImi/hI/uY3Vx2nWT9FDijMHvbUjgr8utfWmBupri2dAMS0L3yjBOvkzQ=" Feb 21 21:43:55 volumioscholz go-librespot[1110]: time="2024-02-21T21:43:55+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Feb 21 21:43:56 volumioscholz go-librespot[1110]: time="2024-02-21T21:43:56+01:00" level=debug msg="completed keyexchange" Feb 21 21:43:56 volumioscholz mpd[1097]: Feb 21 21:43 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Feb 21 21:43:56 volumioscholz systemd[1]: Started Music Player Daemon. Feb 21 21:43:56 volumioscholz sudo[1083]: pam_unix(sudo:session): session closed for user root Feb 21 21:43:56 volumioscholz sudo[1093]: pam_unix(sudo:session): session closed for user root Feb 21 21:43:56 volumioscholz go-librespot[1110]: time="2024-02-21T21:43:56+01:00" level=debug msg="completed challenge" Feb 21 21:43:56 volumioscholz volumio[930]: info: Completed starting Core Plugins Feb 21 21:43:56 volumioscholz volumio[930]: info: ------------------------------------------- Feb 21 21:43:56 volumioscholz volumio[930]: info: ----- MyVolumio plugins startup ---- Feb 21 21:43:56 volumioscholz volumio[930]: info: ------------------------------------------- Feb 21 21:43:56 volumioscholz volumio[930]: info: [MyVolumio PluginManager] Fetching plans data.... Feb 21 21:43:56 volumioscholz volumio[930]: info: MPD running with PID1097 Feb 21 21:43:56 volumioscholz volumio[930]: ,establishing connection Feb 21 21:43:56 volumioscholz go-librespot[1110]: time="2024-02-21T21:43:56+01:00" level=debug msg="authenticated as o3295osshkmd0iuru3mkqg701" Feb 21 21:43:56 volumioscholz volumio[930]: error: MPD error: The expression evaluated to a falsy value: Feb 21 21:43:56 volumioscholz volumio[930]: assert.ok(self.idling) Feb 21 21:43:56 volumioscholz volumio[930]: error: The expression evaluated to a falsy value: Feb 21 21:43:56 volumioscholz volumio[930]: assert.ok(self.idling) Feb 21 21:43:56 volumioscholz volumio[930]: error: MPD error: The expression evaluated to a falsy value: Feb 21 21:43:56 volumioscholz volumio[930]: assert.ok(self.idling) Feb 21 21:43:56 volumioscholz volumio[930]: error: The expression evaluated to a falsy value: Feb 21 21:43:56 volumioscholz volumio[930]: assert.ok(self.idling) Feb 21 21:43:56 volumioscholz volumio[930]: error: updateQueue error: null Feb 21 21:43:56 volumioscholz go-librespot[1110]: time="2024-02-21T21:43:56+01:00" level=debug msg="authenticated as o3295osshkmd0iuru3mkqg701" Feb 21 21:43:56 volumioscholz go-librespot[1110]: time="2024-02-21T21:43:56+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Feb 21 21:43:56 volumioscholz go-librespot[1110]: time="2024-02-21T21:43:56+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Feb 21 21:43:57 volumioscholz go-librespot[1110]: time="2024-02-21T21:43:57+01:00" level=debug msg="dealer connection opened" Feb 21 21:43:57 volumioscholz go-librespot[1110]: time="2024-02-21T21:43:57+01:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Feb 21 21:43:57 volumioscholz go-librespot[1110]: time="2024-02-21T21:43:57+01:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Feb 21 21:43:57 volumioscholz go-librespot[1110]: time="2024-02-21T21:43:57+01:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Feb 21 21:43:57 volumioscholz go-librespot[1110]: time="2024-02-21T21:43:57+01:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Feb 21 21:43:57 volumioscholz go-librespot[1110]: time="2024-02-21T21:43:57+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 513" Feb 21 21:43:57 volumioscholz go-librespot[1110]: time="2024-02-21T21:43:57+01:00" level=debug msg="received connection id: ODQ4YzE1YzUtNWFjMi00N2Q4LWIwNDMtMmZkMDA4YjliZWNjK2RlYWxlcit0Y3A6Ly9nZXc0LWRlYWxlci1hLXZyenIuZ2V3NC5zcG90aWZ5Lm5ldDo1NzAwKzEzOTdBMDVGQjgyN0ZEQjc0QUM1OTEwQzA1MzRBNzVCMjhENUE0RkUzQTY2NzI4Q0Q2Qzk5OTUxNkQxRjRDMDI=" Feb 21 21:43:57 volumioscholz go-librespot[1110]: time="2024-02-21T21:43:57+01:00" level=debug msg="put connect state because NEW_DEVICE" Feb 21 21:43:57 volumioscholz volumio[930]: info: go-librespot daemon successfully initialized Feb 21 21:44:00 volumioscholz volumio[930]: info: Initializing connection to go-librespot Websocket Feb 21 21:44:00 volumioscholz go-librespot[1110]: time="2024-02-21T21:44:00+01:00" level=debug msg="new websocket client" Feb 21 21:44:00 volumioscholz volumio[930]: info: Connection to go-librespot Websocket established Feb 21 21:44:00 volumioscholz go-librespot[1110]: time="2024-02-21T21:44:00+01:00" level=debug msg="handling transfer player command from 1dbac859d9a93f6d1824ffbd47985ff93ac79df7" Feb 21 21:44:00 volumioscholz go-librespot[1110]: time="2024-02-21T21:44:00+01:00" level=trace msg="fetched new page 0 with 50 items (list: 50)" Feb 21 21:44:00 volumioscholz go-librespot[1110]: time="2024-02-21T21:44:00+01:00" level=debug msg="loading track spotify:track:7mtnay1VGQQbtOM70HYsV0 (paused: false, position: -5651674001ms)" Feb 21 21:44:00 volumioscholz go-librespot[1110]: time="2024-02-21T21:44:00+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 21 21:44:00 volumioscholz go-librespot[1110]: time="2024-02-21T21:44:00+01:00" level=trace msg="emitting websocket event: will_play" Feb 21 21:44:00 volumioscholz volumio[930]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:7mtnay1VGQQbtOM70HYsV0","play_origin":"playlist"}} Feb 21 21:44:01 volumioscholz go-librespot[1110]: time="2024-02-21T21:44:01+01:00" level=debug msg="selected format OGG_VORBIS_320 for spotify:track:7mtnay1VGQQbtOM70HYsV0" Feb 21 21:44:01 volumioscholz go-librespot[1110]: time="2024-02-21T21:44:01+01:00" level=debug msg="requested aes key for file 4107fcd8ca2b6fd155cdf550418191fc430136fb, gid: 7mtnay1VGQQbtOM70HYsV0" Feb 21 21:44:01 volumioscholz ntpd[663]: Soliciting pool server 46.102.157.67 Feb 21 21:44:01 volumioscholz go-librespot[1110]: time="2024-02-21T21:44:01+01:00" level=debug msg="fetched first chunk of 15, total size is 7397884 bytes" Feb 21 21:44:01 volumioscholz go-librespot[1110]: time="2024-02-21T21:44:01+01:00" level=trace msg="seek to -5651674001ms (diff: -5651674001ms, samples: -249238823444, bytes: 0)" Feb 21 21:44:01 volumioscholz go-librespot[1110]: time="2024-02-21T21:44:01+01:00" level=info msg="loaded track \"My Way\" (uri: spotify:track:7mtnay1VGQQbtOM70HYsV0, paused: false, position: -5651674001ms, duration: 164826ms)" Feb 21 21:44:01 volumioscholz go-librespot[1110]: time="2024-02-21T21:44:01+01:00" level=debug msg="fetched chunk 1/14, size: 524288" Feb 21 21:44:01 volumioscholz go-librespot[1110]: time="2024-02-21T21:44:01+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 21 21:44:01 volumioscholz go-librespot[1110]: time="2024-02-21T21:44:01+01:00" level=trace msg="emitting websocket event: metadata" Feb 21 21:44:01 volumioscholz volumio[930]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:7mtnay1VGQQbtOM70HYsV0","name":"My Way","artist_names":["PVRIS"],"album_name":"My Way","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02765b7e5289b27fad3ee2e4c1","position":-5651674001,"duration":164826,"release_date":"year:2021 month:10 day:22","track_number":1,"disc_number":1}} Feb 21 21:44:01 volumioscholz go-librespot[1110]: time="2024-02-21T21:44:01+01:00" level=trace msg="emitting websocket event: active" Feb 21 21:44:01 volumioscholz volumio[930]: SPOTIFY: received: {"type":"active","data":null} Feb 21 21:44:01 volumioscholz volumio[930]: info: Aligning Spotify Volume to Volumio Volume Feb 21 21:44:01 volumioscholz volumio[930]: info: CoreCommandRouter::volumioGetState Feb 21 21:44:01 volumioscholz volumio[930]: info: CorePlayQueue::getTrack 0 Feb 21 21:44:01 volumioscholz volumio[930]: info: Setting Spotify Volume from Volumio: 61 Feb 21 21:44:01 volumioscholz go-librespot[1110]: time="2024-02-21T21:44:01+01:00" level=debug msg="fetched chunk 3/14, size: 524288" Feb 21 21:44:01 volumioscholz go-librespot[1110]: time="2024-02-21T21:44:01+01:00" level=debug msg="sending successful reply for delaer request" Feb 21 21:44:01 volumioscholz go-librespot[1110]: time="2024-02-21T21:44:01+01:00" level=debug msg="fetched chunk 2/14, size: 524288" Feb 21 21:44:01 volumioscholz go-librespot[1110]: time="2024-02-21T21:44:01+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 21 21:44:01 volumioscholz go-librespot[1110]: time="2024-02-21T21:44:01+01:00" level=trace msg="emitting websocket event: playing" Feb 21 21:44:01 volumioscholz volumio[930]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:7mtnay1VGQQbtOM70HYsV0","play_origin":"playlist"}} Feb 21 21:44:01 volumioscholz volumio[930]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 21 21:44:01 volumioscholz volumio[930]: TypeError: Cannot read property 'service' of undefined Feb 21 21:44:01 volumioscholz volumio[930]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:336:50) Feb 21 21:44:01 volumioscholz volumio[930]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:262:18) Feb 21 21:44:01 volumioscholz volumio[930]: at WebSocket.message (/data/plugins/music_service/spop/index.js:189:14) Feb 21 21:44:01 volumioscholz volumio[930]: at WebSocket.emit (events.js:315:20) Feb 21 21:44:01 volumioscholz volumio[930]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1203:20) Feb 21 21:44:01 volumioscholz volumio[930]: at Receiver.emit (events.js:315:20) Feb 21 21:44:01 volumioscholz volumio[930]: at /data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:608:16 Feb 21 21:44:01 volumioscholz volumio[930]: at internal/process/task_queues.js:149:7 Feb 21 21:44:01 volumioscholz volumio[930]: at AsyncResource.runInAsyncScope (async_hooks.js:197:9) Feb 21 21:44:01 volumioscholz volumio[930]: at AsyncResource.runMicrotask (internal/process/task_queues.js:146:8) Feb 21 21:44:01 volumioscholz volumio[930]: at processTicksAndRejections (internal/process/task_queues.js:93:5) Feb 21 21:44:01 volumioscholz volumio[930]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 21 21:44:01 volumioscholz go-librespot[1110]: time="2024-02-21T21:44:01+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Feb 21 21:44:01 volumioscholz go-librespot[1110]: time="2024-02-21T21:44:01+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 241" Feb 21 21:44:01 volumioscholz go-librespot[1110]: time="2024-02-21T21:44:01+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Feb 21 21:44:01 volumioscholz go-librespot[1110]: time="2024-02-21T21:44:01+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1577" Feb 21 21:44:01 volumioscholz go-librespot[1110]: time="2024-02-21T21:44:01+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Feb 21 21:44:01 volumioscholz go-librespot[1110]: time="2024-02-21T21:44:01+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1341" Feb 21 21:44:02 volumioscholz sudo[1188]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-02-21 21:43 Feb 21 21:44:02 volumioscholz sudo[1188]: 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="7f9f1bf001add7a8b19a4516e3c74ef598b2730d" VOLUMIO_FE_VERSION="614d7b13ffdcb0cc5a6072e7d06f59d52e323e71" VOLUMIO_FE3_VERSION="570aaed971c1346d45d1172dc445b086b258c6d1" VOLUMIO_BE_VERSION="512433c3e91cdaed7ecd2808b21adeffc2137d7f" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Wed 21 Feb 2024 09:37:22 PM CET" VOLUMIO_VERSION="3.631" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="fdd9dd1169c06c1ad0a30ddd24c91b6b"