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