-- Logs begin at Thu 2019-02-14 11:11:59 CET, end at Sun 2024-10-06 16:18:55 CEST. -- Oct 06 16:17:00 volumio dhcpcd-run-hooks[3576]: wlan0: starting wpa_supplicant Oct 06 16:17:00 volumio dhcpcd-run-hooks[3581]: wlan0: failed to start wpa_supplicant Oct 06 16:17:00 volumio dhcpcd-run-hooks[3582]: 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 Oct 06 16:17:00 volumio dhcpcd[3551]: wlan0: connected to Access Point `' Oct 06 16:17:00 volumio dhcpcd[3551]: no interfaces have a carrier Oct 06 16:17:00 volumio dhcpcd[3551]: forked to background, child pid 3600 Oct 06 16:17:00 volumio dhcpcd[3600]: eth0: waiting for carrier Oct 06 16:17:00 volumio dhcpcd[3600]: wlan0: waiting for carrier Oct 06 16:17:00 volumio sudo[3550]: pam_unix(sudo:session): session closed for user root Oct 06 16:17:00 volumio volumio[858]: info: Discovery: Started advertising with name: Volumio Oct 06 16:17:00 volumio wireless.js[3497]: trying... Oct 06 16:17:00 volumio sudo[3603]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Oct 06 16:17:00 volumio sudo[3603]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 06 16:17:00 volumio sudo[3603]: pam_unix(sudo:session): session closed for user root Oct 06 16:17:01 volumio wireless.js[3497]: trying... Oct 06 16:17:01 volumio sudo[3606]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Oct 06 16:17:01 volumio sudo[3606]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 06 16:17:01 volumio sudo[3606]: pam_unix(sudo:session): session closed for user root Oct 06 16:17:02 volumio wpa_supplicant[3580]: wlan0: Trying to associate with SSID 'Ubi' Oct 06 16:17:02 volumio wireless.js[3497]: trying... Oct 06 16:17:02 volumio sudo[3609]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Oct 06 16:17:02 volumio sudo[3609]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 06 16:17:02 volumio sudo[3609]: pam_unix(sudo:session): session closed for user root Oct 06 16:17:03 volumio nmbd[718]: [2024/10/06 16:17:03.516898, 0] ../source3/nmbd/nmbd.c:361(reload_interfaces) Oct 06 16:17:03 volumio nmbd[718]: reload_interfaces: No subnets to listen to. Waiting.. Oct 06 16:17:03 volumio wireless.js[3497]: trying... Oct 06 16:17:03 volumio sudo[3613]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Oct 06 16:17:03 volumio sudo[3613]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 06 16:17:03 volumio sudo[3613]: pam_unix(sudo:session): session closed for user root Oct 06 16:17:04 volumio wireless.js[3497]: trying... Oct 06 16:17:04 volumio sudo[3616]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Oct 06 16:17:04 volumio sudo[3616]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 06 16:17:04 volumio sudo[3616]: pam_unix(sudo:session): session closed for user root Oct 06 16:17:05 volumio dhcpcd[3600]: wlan0: carrier acquired Oct 06 16:17:05 volumio dhcpcd[3600]: wlan0: connected to Access Point `Ubi' Oct 06 16:17:05 volumio wpa_supplicant[3580]: wlan0: Associated with 44:d9:e7:fd:21:90 Oct 06 16:17:05 volumio wpa_supplicant[3580]: wlan0: CTRL-EVENT-CONNECTED - Connection to 44:d9:e7:fd:21:90 completed [id=0 id_str=] Oct 06 16:17:05 volumio wpa_supplicant[3580]: wlan0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0 Oct 06 16:17:05 volumio wpa_supplicant[3580]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=COUNTRY_IE type=COUNTRY alpha2=SE Oct 06 16:17:05 volumio dhcpcd[3600]: DUID 00:01:00:01:2e:7c:58:d6:e4:5f:01:fd:45:81 Oct 06 16:17:05 volumio dhcpcd[3600]: wlan0: IAID 01:fd:45:81 Oct 06 16:17:05 volumio dhcpcd[3600]: wlan0: adding address fe80::4bd2:1978:f48d:54ec Oct 06 16:17:05 volumio dhcpcd[3600]: ipv6_addaddr1: Permission denied Oct 06 16:17:05 volumio dhcpcd[3600]: wlan0: carrier lost Oct 06 16:17:05 volumio dhcpcd[3600]: wlan0: carrier acquired Oct 06 16:17:05 volumio dhcpcd[3600]: wlan0: IAID 01:fd:45:81 Oct 06 16:17:05 volumio dhcpcd[3600]: wlan0: soliciting an IPv6 router Oct 06 16:17:05 volumio dhcpcd[3600]: wlan0: soliciting a DHCP lease Oct 06 16:17:05 volumio dhcpcd[3600]: wlan0: offered 192.168.2.53 from 192.168.2.1 Oct 06 16:17:05 volumio dhcpcd[3600]: wlan0: probing address 192.168.2.53/24 Oct 06 16:17:05 volumio wireless.js[3497]: trying... Oct 06 16:17:05 volumio sudo[3638]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Oct 06 16:17:05 volumio sudo[3638]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 06 16:17:05 volumio sudo[3638]: pam_unix(sudo:session): session closed for user root Oct 06 16:17:06 volumio wireless.js[3497]: trying... Oct 06 16:17:06 volumio sudo[3641]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Oct 06 16:17:06 volumio sudo[3641]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 06 16:17:06 volumio sudo[3641]: pam_unix(sudo:session): session closed for user root Oct 06 16:17:07 volumio wireless.js[3497]: trying... Oct 06 16:17:07 volumio sudo[3644]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Oct 06 16:17:07 volumio sudo[3644]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 06 16:17:07 volumio sudo[3644]: pam_unix(sudo:session): session closed for user root Oct 06 16:17:08 volumio wireless.js[3497]: trying... Oct 06 16:17:08 volumio sudo[3647]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Oct 06 16:17:08 volumio sudo[3647]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 06 16:17:08 volumio sudo[3647]: pam_unix(sudo:session): session closed for user root Oct 06 16:17:09 volumio wireless.js[3497]: trying... Oct 06 16:17:09 volumio sudo[3651]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Oct 06 16:17:09 volumio sudo[3651]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 06 16:17:09 volumio sudo[3651]: pam_unix(sudo:session): session closed for user root Oct 06 16:17:10 volumio wireless.js[3497]: trying... Oct 06 16:17:10 volumio sudo[3654]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Oct 06 16:17:10 volumio sudo[3654]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 06 16:17:10 volumio sudo[3654]: pam_unix(sudo:session): session closed for user root Oct 06 16:17:11 volumio dhcpcd[3600]: wlan0: leased 192.168.2.53 for 172800 seconds Oct 06 16:17:11 volumio avahi-daemon[622]: Joining mDNS multicast group on interface wlan0.IPv4 with address 192.168.2.53. Oct 06 16:17:11 volumio avahi-daemon[622]: New relevant interface wlan0.IPv4 for mDNS. Oct 06 16:17:11 volumio dhcpcd[3600]: wlan0: adding route to 192.168.2.0/24 Oct 06 16:17:11 volumio avahi-daemon[622]: Registering new address record for 192.168.2.53 on wlan0.IPv4. Oct 06 16:17:11 volumio dhcpcd[3600]: wlan0: adding default route via 192.168.2.1 Oct 06 16:17:11 volumio wireless.js[3497]: trying... Oct 06 16:17:11 volumio sudo[3678]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Oct 06 16:17:11 volumio sudo[3678]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 06 16:17:11 volumio sudo[3678]: pam_unix(sudo:session): session closed for user root Oct 06 16:17:11 volumio wireless.js[3497]: Connected to: ----Ubi Oct 06 16:17:11 volumio wireless.js[3497]: ---- Oct 06 16:17:11 volumio sudo[3681]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 06 16:17:11 volumio sudo[3681]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 06 16:17:11 volumio sudo[3681]: pam_unix(sudo:session): session closed for user root Oct 06 16:17:12 volumio wireless.js[3497]: ... joined AP, wlan0 IPv4 is 192.168.2.53, ipV6 is undefined Oct 06 16:17:12 volumio wireless.js[3497]: It's done! AP Oct 06 16:17:12 volumio systemd[1]: Started Wireless Services. Oct 06 16:17:12 volumio sudo[3490]: pam_unix(sudo:session): session closed for user root Oct 06 16:17:12 volumio kernel: brcmfmac: brcmf_cfg80211_set_power_mgmt: power save disabled Oct 06 16:17:12 volumio volumio[858]: info: Discovery: adding bdec9109-a559-4acf-9692-dc69c4c6c743 Oct 06 16:17:12 volumio volumio[858]: info: Discovery: Found device Volumio Oct 06 16:17:12 volumio volumio[858]: info: CoreCommandRouter::volumioGetState Oct 06 16:17:12 volumio volumio[858]: info: CorePlayQueue::getTrack 1 Oct 06 16:17:12 volumio ntpd[764]: Listen normally on 5 wlan0 192.168.2.53:123 Oct 06 16:17:12 volumio ntpd[764]: new interface(s) found: waking up resolver Oct 06 16:17:13 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 06 16:17:13 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 06 16:17:13 volumio volumio[858]: info: Discovery: Getting this device information Oct 06 16:17:13 volumio volumio[858]: info: CoreCommandRouter::volumioGetState Oct 06 16:17:13 volumio volumio[858]: info: CorePlayQueue::getTrack 1 Oct 06 16:17:13 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 06 16:17:14 volumio volumio[858]: verbose: New Socket.io Connection to 192.168.2.53 from 192.168.2.42 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 17_6_1 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Engine version: 3 Transport: polling Total Clients: 5 Oct 06 16:17:14 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 06 16:17:14 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 06 16:17:14 volumio volumio[858]: info: Discovery: Getting this device information Oct 06 16:17:14 volumio volumio[858]: info: CoreCommandRouter::volumioGetState Oct 06 16:17:14 volumio volumio[858]: info: CorePlayQueue::getTrack 1 Oct 06 16:17:14 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 06 16:17:14 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Oct 06 16:17:14 volumio volumio[858]: info: CoreCommandRouter::volumioGetVisibleSources Oct 06 16:17:14 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 06 16:17:14 volumio volumio[858]: info: CoreCommandRouter::volumioGetState Oct 06 16:17:14 volumio volumio[858]: info: CorePlayQueue::getTrack 1 Oct 06 16:17:14 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Oct 06 16:17:14 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Oct 06 16:17:14 volumio volumio[858]: info: Received Get System Info Oct 06 16:17:14 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 06 16:17:14 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 06 16:17:14 volumio volumio[858]: info: Discovery: Getting this device information Oct 06 16:17:14 volumio volumio[858]: info: CoreCommandRouter::volumioGetState Oct 06 16:17:14 volumio volumio[858]: info: CorePlayQueue::getTrack 1 Oct 06 16:17:14 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 06 16:17:14 volumio volumio[858]: info: CoreCommandRouter::volumioGetState Oct 06 16:17:14 volumio volumio[858]: info: CorePlayQueue::getTrack 1 Oct 06 16:17:14 volumio volumio[858]: info: Listing playlists Oct 06 16:17:15 volumio sudo[3725]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 06 16:17:15 volumio sudo[3725]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 06 16:17:15 volumio sudo[3725]: pam_unix(sudo:session): session closed for user root Oct 06 16:17:15 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Oct 06 16:17:15 volumio sudo[3728]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 06 16:17:15 volumio sudo[3728]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 06 16:17:15 volumio sudo[3728]: pam_unix(sudo:session): session closed for user root Oct 06 16:17:15 volumio volumio[858]: verbose: New Socket.io Connection to 192.168.2.53 from 192.168.2.42 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 17_6_1 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Engine version: 3 Transport: polling Total Clients: 6 Oct 06 16:17:15 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Oct 06 16:17:15 volumio volumio[858]: info: CoreCommandRouter::volumioGetVisibleSources Oct 06 16:17:15 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 06 16:17:15 volumio volumio[858]: info: CoreCommandRouter::volumioGetState Oct 06 16:17:15 volumio volumio[858]: info: CorePlayQueue::getTrack 1 Oct 06 16:17:15 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Oct 06 16:17:15 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Oct 06 16:17:15 volumio volumio[858]: info: Received Get System Info Oct 06 16:17:15 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 06 16:17:15 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 06 16:17:15 volumio volumio[858]: info: Discovery: Getting this device information Oct 06 16:17:15 volumio volumio[858]: info: CoreCommandRouter::volumioGetState Oct 06 16:17:15 volumio volumio[858]: info: CorePlayQueue::getTrack 1 Oct 06 16:17:15 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 06 16:17:15 volumio volumio[858]: info: CoreCommandRouter::volumioGetState Oct 06 16:17:15 volumio volumio[858]: info: CorePlayQueue::getTrack 1 Oct 06 16:17:15 volumio volumio[858]: info: Listing playlists Oct 06 16:17:15 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Oct 06 16:17:15 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Oct 06 16:17:15 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Oct 06 16:17:16 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Oct 06 16:17:16 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Oct 06 16:17:16 volumio volumio[858]: info: Received Get System Info Oct 06 16:17:16 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 06 16:17:16 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 06 16:17:16 volumio volumio[858]: info: Discovery: Getting this device information Oct 06 16:17:16 volumio volumio[858]: info: CoreCommandRouter::volumioGetState Oct 06 16:17:16 volumio volumio[858]: info: CorePlayQueue::getTrack 1 Oct 06 16:17:16 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 06 16:17:17 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: wizard , reportWirelessConnection Oct 06 16:17:17 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: network , getWirelessInfo Oct 06 16:17:17 volumio sudo[3731]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 06 16:17:17 volumio sudo[3731]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 06 16:17:17 volumio sudo[3731]: pam_unix(sudo:session): session closed for user root Oct 06 16:17:17 volumio sudo[3734]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwconfig wlan0 Oct 06 16:17:17 volumio sudo[3734]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 06 16:17:17 volumio sudo[3734]: pam_unix(sudo:session): session closed for user root Oct 06 16:17:17 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Oct 06 16:17:17 volumio volumio[858]: info: Received Get System Info Oct 06 16:17:17 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 06 16:17:17 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 06 16:17:17 volumio volumio[858]: info: Discovery: Getting this device information Oct 06 16:17:17 volumio volumio[858]: info: CoreCommandRouter::volumioGetState Oct 06 16:17:17 volumio volumio[858]: info: CorePlayQueue::getTrack 1 Oct 06 16:17:17 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 06 16:17:21 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: wizard , setOnboardingWizardFalse Oct 06 16:17:22 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: upnp , onRestart Oct 06 16:17:22 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: network , onNetworkingRestart Oct 06 16:17:22 volumio volumio[858]: info: Refreshing Cached IP Addresses Oct 06 16:17:22 volumio sudo[3739]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/bin/killall upmpdcli Oct 06 16:17:22 volumio sudo[3739]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 06 16:17:22 volumio sudo[3739]: pam_unix(sudo:session): session closed for user root Oct 06 16:17:22 volumio sudo[3742]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 06 16:17:22 volumio sudo[3742]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 06 16:17:22 volumio sudo[3742]: pam_unix(sudo:session): session closed for user root Oct 06 16:17:22 volumio volumio[858]: error: Upnp client error: Error: This socket has been ended by the other party Oct 06 16:17:22 volumio sudo[3745]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 06 16:17:22 volumio sudo[3745]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 06 16:17:22 volumio sudo[3745]: pam_unix(sudo:session): session closed for user root Oct 06 16:17:25 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Oct 06 16:17:28 volumio volumio[858]: info: CoreCommandRouter::volumioGetQueue Oct 06 16:17:28 volumio volumio[858]: info: CoreStateMachine::getQueue Oct 06 16:17:28 volumio volumio[858]: info: CorePlayQueue::getQueue Oct 06 16:17:32 volumio sudo[3749]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 06 16:17:32 volumio sudo[3749]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 06 16:17:32 volumio sudo[3749]: pam_unix(sudo:session): session closed for user root Oct 06 16:17:32 volumio sudo[3752]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 06 16:17:32 volumio sudo[3752]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 06 16:17:32 volumio sudo[3752]: pam_unix(sudo:session): session closed for user root Oct 06 16:17:32 volumio sudo[3755]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Oct 06 16:17:32 volumio sudo[3755]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 06 16:17:32 volumio sudo[3755]: pam_unix(sudo:session): session closed for user root Oct 06 16:17:32 volumio volumio[858]: info: Upmpdcli Daemon Started Oct 06 16:17:33 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Oct 06 16:17:33 volumio volumio[858]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Oct 06 16:17:33 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Oct 06 16:17:33 volumio volumio[858]: info: Received Get System Version Oct 06 16:17:33 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 06 16:17:33 volumio volumio[858]: info: Received Get System Info Oct 06 16:17:33 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 06 16:17:33 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 06 16:17:33 volumio volumio[858]: info: Discovery: Getting this device information Oct 06 16:17:33 volumio volumio[858]: info: CoreCommandRouter::volumioGetState Oct 06 16:17:33 volumio volumio[858]: info: CorePlayQueue::getTrack 1 Oct 06 16:17:33 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 06 16:17:38 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri Oct 06 16:17:38 volumio volumio[858]: info: In handleBrowseUri, curUri=spotify:user:spotify:playlist:2BVY2yzo7DVTU8II5DffW7 Oct 06 16:17:39 volumio volumio[858]: info: Preload queue cleared Oct 06 16:17:43 volumio volumio[858]: info: Preload queue cleared Oct 06 16:17:43 volumio volumio[858]: info: CoreCommandRouter::volumioReplaceandPlayItems Oct 06 16:17:43 volumio volumio[858]: info: CoreStateMachine::ClearQueue Oct 06 16:17:43 volumio volumio[858]: info: CoreStateMachine::stop Oct 06 16:17:43 volumio volumio[858]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 06 16:17:43 volumio volumio[858]: info: CorePlayQueue::clearPlayQueue Oct 06 16:17:43 volumio volumio[858]: info: CorePlayQueue::saveQueue Oct 06 16:17:43 volumio volumio[858]: info: CoreCommandRouter::volumioPushQueue Oct 06 16:17:43 volumio volumio[858]: info: CoreStateMachine::addQueueItems Oct 06 16:17:43 volumio volumio[858]: info: CorePlayQueue::addQueueItems Oct 06 16:17:43 volumio volumio[858]: info: Preload queue cleared Oct 06 16:17:43 volumio volumio[858]: info: Adding Item to queue: spotify:track:3516iojARW7wmWOEChuUPD Oct 06 16:17:43 volumio volumio[858]: info: Using cached record of: spotify:track:3516iojARW7wmWOEChuUPD Oct 06 16:17:43 volumio volumio[858]: info: Adding Item to queue: spotify:track:0FMhMAFPLg8EljnROSoVnj Oct 06 16:17:43 volumio volumio[858]: info: Using cached record of: spotify:track:0FMhMAFPLg8EljnROSoVnj Oct 06 16:17:43 volumio volumio[858]: info: Adding Item to queue: spotify:track:6jAjsymjh5WGKkiFf0K7we Oct 06 16:17:43 volumio volumio[858]: info: Using cached record of: spotify:track:6jAjsymjh5WGKkiFf0K7we Oct 06 16:17:43 volumio volumio[858]: info: Adding Item to queue: spotify:track:2vN0yJIIsjfUE5EgcBT6hf Oct 06 16:17:43 volumio volumio[858]: info: Using cached record of: spotify:track:2vN0yJIIsjfUE5EgcBT6hf Oct 06 16:17:43 volumio volumio[858]: info: Adding Item to queue: spotify:track:7KhDEHXsKCfod1QilTbYaf Oct 06 16:17:43 volumio volumio[858]: info: Using cached record of: spotify:track:7KhDEHXsKCfod1QilTbYaf Oct 06 16:17:43 volumio volumio[858]: info: Adding Item to queue: spotify:track:6x3QJKhJtZrWGCMeGMjbcx Oct 06 16:17:43 volumio volumio[858]: info: Using cached record of: spotify:track:6x3QJKhJtZrWGCMeGMjbcx Oct 06 16:17:43 volumio volumio[858]: info: Adding Item to queue: spotify:track:3cEceHck84YzLF3fz5zk5e Oct 06 16:17:43 volumio volumio[858]: info: Using cached record of: spotify:track:3cEceHck84YzLF3fz5zk5e Oct 06 16:17:43 volumio volumio[858]: info: Adding Item to queue: spotify:track:6ILtG4u8o34KH6vemuoJhF Oct 06 16:17:43 volumio volumio[858]: info: Using cached record of: spotify:track:6ILtG4u8o34KH6vemuoJhF Oct 06 16:17:43 volumio volumio[858]: info: Adding Item to queue: spotify:track:6xhEQmrVvtpEdw5mfySgJw Oct 06 16:17:43 volumio volumio[858]: info: Using cached record of: spotify:track:6xhEQmrVvtpEdw5mfySgJw Oct 06 16:17:43 volumio volumio[858]: info: Adding Item to queue: spotify:track:2UVSP6BlF8AgQOpzfDUVL2 Oct 06 16:17:43 volumio volumio[858]: info: Using cached record of: spotify:track:2UVSP6BlF8AgQOpzfDUVL2 Oct 06 16:17:43 volumio volumio[858]: info: Adding Item to queue: spotify:track:7E5KQijzkMmZKp7RUybvpr Oct 06 16:17:43 volumio volumio[858]: info: Using cached record of: spotify:track:7E5KQijzkMmZKp7RUybvpr Oct 06 16:17:43 volumio volumio[858]: info: Adding Item to queue: spotify:track:4Bcs8WOI3lpH7w9x7bBCiT Oct 06 16:17:43 volumio volumio[858]: info: Using cached record of: spotify:track:4Bcs8WOI3lpH7w9x7bBCiT Oct 06 16:17:43 volumio volumio[858]: info: Adding Item to queue: spotify:track:3Ke5UWL9sZQOXli7XSiKRX Oct 06 16:17:43 volumio volumio[858]: info: Using cached record of: spotify:track:3Ke5UWL9sZQOXli7XSiKRX Oct 06 16:17:43 volumio volumio[858]: info: Adding Item to queue: spotify:track:22G8rQDLJTeJzjQWXZErre Oct 06 16:17:43 volumio volumio[858]: info: Using cached record of: spotify:track:22G8rQDLJTeJzjQWXZErre Oct 06 16:17:43 volumio volumio[858]: info: Adding Item to queue: spotify:track:7AWlSSW5n7SXpFEWkRm2Wz Oct 06 16:17:43 volumio volumio[858]: info: Using cached record of: spotify:track:7AWlSSW5n7SXpFEWkRm2Wz Oct 06 16:17:43 volumio volumio[858]: info: Adding Item to queue: spotify:track:4cJC5AjLjRUH2qtemrqLbD Oct 06 16:17:43 volumio volumio[858]: info: Using cached record of: spotify:track:4cJC5AjLjRUH2qtemrqLbD Oct 06 16:17:43 volumio volumio[858]: info: Adding Item to queue: spotify:track:19vVghIuHm3IAfN4xpRF3q Oct 06 16:17:43 volumio volumio[858]: info: Using cached record of: spotify:track:19vVghIuHm3IAfN4xpRF3q Oct 06 16:17:43 volumio volumio[858]: info: Adding Item to queue: spotify:track:68d6ZfyMUYURol2y15Ta2Y Oct 06 16:17:43 volumio volumio[858]: info: Using cached record of: spotify:track:68d6ZfyMUYURol2y15Ta2Y Oct 06 16:17:43 volumio volumio[858]: info: Adding Item to queue: spotify:track:190Tz6CYjyOAq5ypbV8CFi Oct 06 16:17:43 volumio volumio[858]: info: Using cached record of: spotify:track:190Tz6CYjyOAq5ypbV8CFi Oct 06 16:17:43 volumio volumio[858]: info: CoreCommandRouter::volumioPushQueue Oct 06 16:17:43 volumio volumio[858]: info: CorePlayQueue::saveQueue Oct 06 16:17:43 volumio volumio[858]: info: CoreStateMachine::updateTrackBlock Oct 06 16:17:43 volumio volumio[858]: info: CorePlayQueue::getTrackBlock Oct 06 16:17:43 volumio volumio[858]: info: CoreCommandRouter::volumioPlay Oct 06 16:17:43 volumio volumio[858]: info: CoreStateMachine::play index 3 Oct 06 16:17:43 volumio volumio[858]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 06 16:17:43 volumio volumio[858]: info: CoreStateMachine::stop Oct 06 16:17:43 volumio volumio[858]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 06 16:17:43 volumio volumio[858]: info: CoreStateMachine::play index undefined Oct 06 16:17:43 volumio volumio[858]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 06 16:17:43 volumio volumio[858]: info: CorePlayQueue::getTrack 3 Oct 06 16:17:43 volumio volumio[858]: info: CoreStateMachine::startPlaybackTimer Oct 06 16:17:43 volumio volumio[858]: info: CorePlayQueue::getTrack 3 Oct 06 16:17:43 volumio volumio[858]: info: [1728224263466] ControllerSpotify::clearAddPlayTrack Oct 06 16:17:43 volumio volumio[858]: info: Sending Spotify command with payload to local API: /player/play Oct 06 16:17:43 volumio go-librespot[2399]: time="2024-10-06T16:17:43+02:00" level=debug msg="resolved context of track" uri="spotify:track:2vN0yJIIsjfUE5EgcBT6hf" Oct 06 16:17:43 volumio go-librespot[2399]: time="2024-10-06T16:17:43+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:2vN0yJIIsjfUE5EgcBT6hf" Oct 06 16:17:43 volumio go-librespot[2399]: time="2024-10-06T16:17:43+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:2vN0yJIIsjfUE5EgcBT6hf" Oct 06 16:17:43 volumio go-librespot[2399]: time="2024-10-06T16:17:43+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 06 16:17:43 volumio go-librespot[2399]: time="2024-10-06T16:17:43+02:00" level=trace msg="emitting websocket event: will_play" Oct 06 16:17:43 volumio volumio[858]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:2vN0yJIIsjfUE5EgcBT6hf","play_origin":"go-librespot"}} Oct 06 16:17:43 volumio volumio[858]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:2vN0yJIIsjfUE5EgcBT6hf","play_origin":"go-librespot"}} Oct 06 16:17:43 volumio go-librespot[2399]: time="2024-10-06T16:17:43+02:00" level=debug msg="selected format OGG_VORBIS_320 (5d84ad369c10da337d5a6c3604889587fafbd725)" uri="spotify:track:2vN0yJIIsjfUE5EgcBT6hf" Oct 06 16:17:43 volumio go-librespot[2399]: time="2024-10-06T16:17:43+02:00" level=debug msg="requested aes key for file 5d84ad369c10da337d5a6c3604889587fafbd725, gid: 2vN0yJIIsjfUE5EgcBT6hf" Oct 06 16:17:44 volumio go-librespot[2399]: time="2024-10-06T16:17:44+02:00" level=debug msg="fetched first chunk of 44, total size is 22639680 bytes" uri="spotify:track:2vN0yJIIsjfUE5EgcBT6hf" Oct 06 16:17:44 volumio go-librespot[2399]: time="2024-10-06T16:17:44+02:00" level=trace msg="seek to 0ms (diff: -570ms, samples: 0, bytes: 20029)" uri="spotify:track:2vN0yJIIsjfUE5EgcBT6hf" Oct 06 16:17:44 volumio go-librespot[2399]: time="2024-10-06T16:17:44+02:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 5102 us, period size = 225 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 98 frames" Oct 06 16:17:44 volumio go-librespot[2399]: time="2024-10-06T16:17:44+02:00" level=debug msg="created new output device" Oct 06 16:17:44 volumio go-librespot[2399]: time="2024-10-06T16:17:44+02:00" level=info msg="loaded track \"Bubbles\" (paused: false, position: 0ms, duration: 539000ms, prefetched: false)" uri="spotify:track:2vN0yJIIsjfUE5EgcBT6hf" Oct 06 16:17:44 volumio go-librespot[2399]: time="2024-10-06T16:17:44+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 06 16:17:44 volumio go-librespot[2399]: time="2024-10-06T16:17:44+02:00" level=trace msg="scheduling prefetch in 508s" Oct 06 16:17:44 volumio go-librespot[2399]: time="2024-10-06T16:17:44+02:00" level=trace msg="emitting websocket event: metadata" Oct 06 16:17:44 volumio volumio[858]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:2vN0yJIIsjfUE5EgcBT6hf","name":"Bubbles","artist_names":["Herbie Hancock"],"album_name":"Man-Child","album_cover_url":"https://i.scdn.co/image/ab67616d00001e027afa2b4902f160aad93c5cfe","position":0,"duration":539000,"release_date":"year:1975","track_number":4,"disc_number":1}} Oct 06 16:17:44 volumio volumio[858]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:2vN0yJIIsjfUE5EgcBT6hf","name":"Bubbles","artist_names":["Herbie Hancock"],"album_name":"Man-Child","album_cover_url":"https://i.scdn.co/image/ab67616d00001e027afa2b4902f160aad93c5cfe","position":0,"duration":539000,"release_date":"year:1975","track_number":4,"disc_number":1}} Oct 06 16:17:44 volumio go-librespot[2399]: time="2024-10-06T16:17:44+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 06 16:17:44 volumio go-librespot[2399]: time="2024-10-06T16:17:44+02:00" level=trace msg="emitting websocket event: playing" Oct 06 16:17:44 volumio volumio[858]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:2vN0yJIIsjfUE5EgcBT6hf","play_origin":"go-librespot"}} Oct 06 16:17:44 volumio volumio[858]: SPOTIFY: PUSH STATE SPOTIFY Oct 06 16:17:44 volumio volumio[858]: SPOTIFY: {"status":"play","service":"spop","title":"Bubbles","artist":"Herbie Hancock","album":"Man-Child","albumart":"https://i.scdn.co/image/ab67616d00001e027afa2b4902f160aad93c5cfe","uri":"spotify:track:2vN0yJIIsjfUE5EgcBT6hf","trackType":"spotify","seek":0,"duration":539,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Oct 06 16:17:44 volumio volumio[858]: info: CoreCommandRouter::servicePushState Oct 06 16:17:44 volumio volumio[858]: info: CorePlayQueue::getTrack 3 Oct 06 16:17:44 volumio volumio[858]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Bubbles","artist":"Herbie Hancock","album":"Man-Child","albumart":"https://i.scdn.co/image/ab67616d00001e027afa2b4902f160aad93c5cfe","uri":"spotify:track:2vN0yJIIsjfUE5EgcBT6hf","trackType":"spotify","seek":0,"duration":539,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Oct 06 16:17:44 volumio volumio[858]: verbose: CURRENT POSITION 3 Oct 06 16:17:44 volumio volumio[858]: info: CoreStateMachine::syncState stateService play Oct 06 16:17:44 volumio volumio[858]: info: CoreStateMachine::syncState currentStatus stop Oct 06 16:17:44 volumio volumio[858]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:2vN0yJIIsjfUE5EgcBT6hf","play_origin":"go-librespot"}} Oct 06 16:17:44 volumio volumio[858]: SPOTIFY: PUSH STATE SPOTIFY Oct 06 16:17:44 volumio volumio[858]: SPOTIFY: {"status":"play","service":"spop","title":"Bubbles","artist":"Herbie Hancock","album":"Man-Child","albumart":"https://i.scdn.co/image/ab67616d00001e027afa2b4902f160aad93c5cfe","uri":"spotify:track:2vN0yJIIsjfUE5EgcBT6hf","trackType":"spotify","seek":0,"duration":539,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Oct 06 16:17:44 volumio volumio[858]: info: CoreCommandRouter::servicePushState Oct 06 16:17:44 volumio volumio[858]: info: CorePlayQueue::getTrack 3 Oct 06 16:17:44 volumio volumio[858]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Bubbles","artist":"Herbie Hancock","album":"Man-Child","albumart":"https://i.scdn.co/image/ab67616d00001e027afa2b4902f160aad93c5cfe","uri":"spotify:track:2vN0yJIIsjfUE5EgcBT6hf","trackType":"spotify","seek":0,"duration":539,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Oct 06 16:17:44 volumio volumio[858]: verbose: CURRENT POSITION 3 Oct 06 16:17:44 volumio volumio[858]: info: CoreStateMachine::syncState stateService play Oct 06 16:17:44 volumio volumio[858]: info: CoreStateMachine::syncState currentStatus play Oct 06 16:17:44 volumio volumio[858]: info: Received an update from plugin. extracting info from payload Oct 06 16:17:44 volumio volumio[858]: info: CoreStateMachine::pushState Oct 06 16:17:44 volumio volumio[858]: info: CorePlayQueue::getTrack 3 Oct 06 16:17:44 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 06 16:17:44 volumio volumio[858]: info: CoreCommandRouter::volumioPushState Oct 06 16:17:44 volumio volumio[858]: info: CoreStateMachine::pushState Oct 06 16:17:44 volumio volumio[858]: info: CorePlayQueue::getTrack 3 Oct 06 16:17:44 volumio volumio[858]: info: CoreCommandRouter::volumioPushState Oct 06 16:17:44 volumio volumio[858]: SPOTIFY: PUSH STATE SPOTIFY Oct 06 16:17:44 volumio volumio[858]: SPOTIFY: {"status":"play","service":"spop","title":"Bubbles","artist":"Herbie Hancock","album":"Man-Child","albumart":"https://i.scdn.co/image/ab67616d00001e027afa2b4902f160aad93c5cfe","uri":"spotify:track:2vN0yJIIsjfUE5EgcBT6hf","trackType":"spotify","seek":0,"duration":539,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Oct 06 16:17:44 volumio volumio[858]: info: CoreCommandRouter::servicePushState Oct 06 16:17:44 volumio volumio[858]: info: CorePlayQueue::getTrack 3 Oct 06 16:17:44 volumio volumio[858]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Bubbles","artist":"Herbie Hancock","album":"Man-Child","albumart":"https://i.scdn.co/image/ab67616d00001e027afa2b4902f160aad93c5cfe","uri":"spotify:track:2vN0yJIIsjfUE5EgcBT6hf","trackType":"spotify","seek":0,"duration":539,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Oct 06 16:17:44 volumio volumio[858]: verbose: CURRENT POSITION 3 Oct 06 16:17:44 volumio volumio[858]: info: CoreStateMachine::syncState stateService play Oct 06 16:17:44 volumio volumio[858]: info: CoreStateMachine::syncState currentStatus play Oct 06 16:17:44 volumio volumio[858]: info: Received an update from plugin. extracting info from payload Oct 06 16:17:44 volumio volumio[858]: info: CoreStateMachine::pushState Oct 06 16:17:44 volumio volumio[858]: info: CorePlayQueue::getTrack 3 Oct 06 16:17:44 volumio volumio[858]: info: CoreCommandRouter::volumioPushState Oct 06 16:17:44 volumio volumio[858]: info: CoreStateMachine::pushState Oct 06 16:17:44 volumio volumio[858]: info: CorePlayQueue::getTrack 3 Oct 06 16:17:44 volumio volumio[858]: info: CoreCommandRouter::volumioPushState Oct 06 16:17:44 volumio volumio[858]: SPOTIFY: PUSH STATE SPOTIFY Oct 06 16:17:44 volumio volumio[858]: SPOTIFY: {"status":"play","service":"spop","title":"Bubbles","artist":"Herbie Hancock","album":"Man-Child","albumart":"https://i.scdn.co/image/ab67616d00001e027afa2b4902f160aad93c5cfe","uri":"spotify:track:2vN0yJIIsjfUE5EgcBT6hf","trackType":"spotify","seek":0,"duration":539,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Oct 06 16:17:44 volumio volumio[858]: info: CoreCommandRouter::servicePushState Oct 06 16:17:44 volumio volumio[858]: info: CorePlayQueue::getTrack 3 Oct 06 16:17:44 volumio volumio[858]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Bubbles","artist":"Herbie Hancock","album":"Man-Child","albumart":"https://i.scdn.co/image/ab67616d00001e027afa2b4902f160aad93c5cfe","uri":"spotify:track:2vN0yJIIsjfUE5EgcBT6hf","trackType":"spotify","seek":0,"duration":539,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Oct 06 16:17:44 volumio volumio[858]: verbose: CURRENT POSITION 3 Oct 06 16:17:44 volumio volumio[858]: info: CoreStateMachine::syncState stateService play Oct 06 16:17:44 volumio volumio[858]: info: CoreStateMachine::syncState currentStatus play Oct 06 16:17:44 volumio volumio[858]: info: Received an update from plugin. extracting info from payload Oct 06 16:17:44 volumio volumio[858]: info: CoreStateMachine::pushState Oct 06 16:17:44 volumio volumio[858]: info: CorePlayQueue::getTrack 3 Oct 06 16:17:44 volumio volumio[858]: info: CoreCommandRouter::volumioPushState Oct 06 16:17:44 volumio volumio[858]: info: CoreStateMachine::pushState Oct 06 16:17:44 volumio volumio[858]: info: CorePlayQueue::getTrack 3 Oct 06 16:17:44 volumio volumio[858]: info: CoreCommandRouter::volumioPushState Oct 06 16:17:45 volumio go-librespot[2399]: time="2024-10-06T16:17:45+02:00" level=debug msg="fetched chunk 3/43, size: 524288" uri="spotify:track:2vN0yJIIsjfUE5EgcBT6hf" Oct 06 16:17:45 volumio go-librespot[2399]: time="2024-10-06T16:17:45+02:00" level=debug msg="fetched chunk 1/43, size: 524288" uri="spotify:track:2vN0yJIIsjfUE5EgcBT6hf" Oct 06 16:17:45 volumio go-librespot[2399]: time="2024-10-06T16:17:45+02:00" level=debug msg="fetched chunk 2/43, size: 524288" uri="spotify:track:2vN0yJIIsjfUE5EgcBT6hf" Oct 06 16:17:49 volumio ntpd[764]: Soliciting pool server 194.58.207.148 Oct 06 16:17:52 volumio ntpd[764]: Soliciting pool server 194.58.202.148 Oct 06 16:17:53 volumio ntpd[764]: Soliciting pool server 162.159.200.123 Oct 06 16:17:54 volumio ntpd[764]: Soliciting pool server 83.233.116.10 Oct 06 16:17:55 volumio go-librespot[2399]: time="2024-10-06T16:17:55+02:00" level=debug msg="fetched chunk 4/43, size: 524288" uri="spotify:track:2vN0yJIIsjfUE5EgcBT6hf" Oct 06 16:17:55 volumio ntpd[764]: Soliciting pool server 193.182.111.13 Oct 06 16:17:56 volumio ntpd[764]: Soliciting pool server 193.182.111.12 Oct 06 16:17:57 volumio ntpd[764]: Soliciting pool server 194.58.200.20 Oct 06 16:18:04 volumio ntpd[764]: Soliciting pool server 2a03:8600::cc Oct 06 16:18:05 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri Oct 06 16:18:05 volumio volumio[858]: info: CURURI: albums:// Oct 06 16:18:05 volumio volumio[858]: info: listAlbums - loading Albums from cache Oct 06 16:18:05 volumio volumio[858]: info: Preload queue cleared Oct 06 16:18:08 volumio go-librespot[2399]: time="2024-10-06T16:18:08+02:00" level=debug msg="fetched chunk 5/43, size: 524288" uri="spotify:track:2vN0yJIIsjfUE5EgcBT6hf" Oct 06 16:18:10 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Oct 06 16:18:11 volumio volumio[858]: info: Preload queue cleared Oct 06 16:18:12 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Oct 06 16:18:12 volumio volumio[858]: info: Preload queue cleared Oct 06 16:18:12 volumio ntpd[764]: Soliciting pool server 85.24.237.71 Oct 06 16:18:13 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Oct 06 16:18:13 volumio volumio[858]: info: Preload queue cleared Oct 06 16:18:18 volumio volumio[858]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Oct 06 16:18:18 volumio volumio[858]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 06 16:18:18 volumio volumio[858]: TypeError: Cannot read property 'length' of undefined Oct 06 16:18:18 volumio volumio[858]: at /volumio/app/plugins/music_service/upnp_browser/index.js:341:25 Oct 06 16:18:18 volumio volumio[858]: at /volumio/app/plugins/music_service/upnp_browser/dlna-browser.js:131:13 Oct 06 16:18:18 volumio volumio[858]: at Parser. (/volumio/node_modules/xml2js/lib/parser.js:304:18) Oct 06 16:18:18 volumio volumio[858]: at Parser.emit (events.js:315:20) Oct 06 16:18:18 volumio volumio[858]: at SAXParser.onclosetag (/volumio/node_modules/xml2js/lib/parser.js:262:26) Oct 06 16:18:18 volumio volumio[858]: at emit (/volumio/node_modules/sax/lib/sax.js:624:35) Oct 06 16:18:18 volumio volumio[858]: at emitNode (/volumio/node_modules/sax/lib/sax.js:629:5) Oct 06 16:18:18 volumio volumio[858]: at closeTag (/volumio/node_modules/sax/lib/sax.js:889:7) Oct 06 16:18:18 volumio volumio[858]: at SAXParser.write (/volumio/node_modules/sax/lib/sax.js:1436:13) Oct 06 16:18:18 volumio volumio[858]: at Parser.exports.Parser.Parser.parseString (/volumio/node_modules/xml2js/lib/parser.js:323:31) Oct 06 16:18:18 volumio volumio[858]: at Parser.parseString (/volumio/node_modules/xml2js/lib/parser.js:5:59) Oct 06 16:18:18 volumio volumio[858]: at Object.exports.parseString (/volumio/node_modules/xml2js/lib/parser.js:369:19) Oct 06 16:18:18 volumio volumio[858]: at IncomingMessage. (/volumio/app/plugins/music_service/upnp_browser/dlna-browser.js:92:15) Oct 06 16:18:18 volumio volumio[858]: at IncomingMessage.emit (events.js:327:22) Oct 06 16:18:18 volumio volumio[858]: at endReadableNT (internal/streams/readable.js:1327:12) Oct 06 16:18:18 volumio volumio[858]: at processTicksAndRejections (internal/process/task_queues.js:80:21) Oct 06 16:18:18 volumio volumio[858]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 06 16:18:19 volumio sudo[3807]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-10-06 16:17 Oct 06 16:18:19 volumio sudo[3807]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 06 16:18:19 volumio sudo[3807]: pam_unix(sudo:session): session closed for user root Oct 06 16:18:19 volumio go-librespot[2399]: time="2024-10-06T16:18:19+02:00" level=error msg="websocket connection errored" error="failed to get reader: failed to read frame header: EOF" Oct 06 16:18:19 volumio go-librespot[2399]: time="2024-10-06T16:18:19+02:00" level=error msg="websocket connection errored" error="failed to get reader: failed to read frame header: EOF" Oct 06 16:18:19 volumio volumio-remote-updater[1339]: [2024-10-06 16:18:19] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Oct 06 16:18:19 volumio volumio-remote-updater[1339]: [2024-10-06 16:18:19] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Oct 06 16:18:19 volumio systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Oct 06 16:18:19 volumio systemd[1]: upmpdcli.service: Succeeded. Oct 06 16:18:19 volumio systemd[1]: volumio.service: Failed with result 'exit-code'. Oct 06 16:18:19 volumio systemd[1]: Started dynamicswap service. Oct 06 16:18:19 volumio systemd[1]: dynamicswap.service: Succeeded. Oct 06 16:18:19 volumio systemd[1]: volumio.service: Service RestartSec=100ms expired, scheduling restart. Oct 06 16:18:19 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 1. Oct 06 16:18:19 volumio systemd[1]: Stopped Volumio Backend Module. Oct 06 16:18:19 volumio systemd[1]: Started Volumio Backend Module. Oct 06 16:18:19 volumio systemd[1]: Started dynamicswap service. Oct 06 16:18:19 volumio systemd[1]: dynamicswap.service: Succeeded. Oct 06 16:18:20 volumio volumio[3821]: info: ------------------------------------------- Oct 06 16:18:20 volumio volumio[3821]: info: ----- Volumio3 ---- Oct 06 16:18:20 volumio volumio[3821]: info: ------------------------------------------- Oct 06 16:18:20 volumio volumio[3821]: info: ----- System startup ---- Oct 06 16:18:20 volumio volumio[3821]: info: ------------------------------------------- Oct 06 16:18:21 volumio volumio[3821]: info: MYVOLUMIO Environment detected Oct 06 16:18:21 volumio volumio[3821]: info: Plugin folders cleanup Oct 06 16:18:21 volumio volumio[3821]: info: Scanning into folder /volumio/app/plugins/ Oct 06 16:18:21 volumio volumio[3821]: info: Scanning category audio_interface Oct 06 16:18:21 volumio volumio[3821]: info: Scanning category miscellanea Oct 06 16:18:21 volumio volumio[3821]: info: Scanning category music_service Oct 06 16:18:21 volumio volumio[3821]: info: Scanning category plugins.json Oct 06 16:18:21 volumio volumio[3821]: info: Scanning category system_controller Oct 06 16:18:21 volumio volumio[3821]: info: Scanning category user_interface Oct 06 16:18:21 volumio volumio[3821]: info: Scanning into folder /data/plugins/ Oct 06 16:18:21 volumio volumio[3821]: info: Scanning category music_service Oct 06 16:18:21 volumio volumio[3821]: info: Plugin folders cleanup completed Oct 06 16:18:21 volumio volumio[3821]: info: ------------------------------------------- Oct 06 16:18:21 volumio volumio[3821]: info: ----- Core plugins startup ---- Oct 06 16:18:21 volumio volumio[3821]: info: ------------------------------------------- Oct 06 16:18:21 volumio volumio[3821]: info: Loading plugins from folder /volumio/app/plugins/ Oct 06 16:18:21 volumio volumio[3821]: info: Adding plugin upnp to MyMusic Plugins Oct 06 16:18:21 volumio volumio[3821]: info: Adding plugin airplay_emulation to MyMusic Plugins Oct 06 16:18:21 volumio volumio[3821]: info: Adding plugin upnp_browser to MyMusic Plugins Oct 06 16:18:21 volumio volumio[3821]: info: Loading plugins from folder /data/plugins/ Oct 06 16:18:21 volumio volumio[3821]: info: Loading plugin "system"... Oct 06 16:18:21 volumio volumio[3821]: info: Loading plugin "appearance"... Oct 06 16:18:22 volumio volumio[3821]: info: Loading plugin "network"... Oct 06 16:18:22 volumio volumio[3821]: info: Refreshing Cached IP Addresses Oct 06 16:18:22 volumio sudo[3848]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 06 16:18:22 volumio sudo[3848]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 06 16:18:22 volumio sudo[3848]: pam_unix(sudo:session): session closed for user root Oct 06 16:18:22 volumio sudo[3850]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 06 16:18:22 volumio sudo[3850]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 06 16:18:22 volumio volumio[3821]: info: Loading plugin "services"... Oct 06 16:18:22 volumio volumio[3821]: info: Loading plugin "alsa_controller"... Oct 06 16:18:22 volumio sudo[3850]: pam_unix(sudo:session): session closed for user root Oct 06 16:18:22 volumio sudo[3853]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Oct 06 16:18:22 volumio sudo[3853]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 06 16:18:22 volumio volumio[3821]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 06 16:18:22 volumio volumio[3821]: info: Loading plugin "wizard"... Oct 06 16:18:22 volumio volumio[3821]: info: Loading plugin "networkfs"... Oct 06 16:18:22 volumio volumio[3821]: info: Cannot mount NAS Diskstation at system boot, trial number 1 ,retrying in 5 seconds Oct 06 16:18:22 volumio volumio[3821]: info: Starting Udev Watcher for removable devices Oct 06 16:18:22 volumio volumio[3821]: info: Ignoring mount for partition: boot Oct 06 16:18:22 volumio volumio[3821]: info: Ignoring mount for partition: volumio Oct 06 16:18:22 volumio volumio[3821]: info: Ignoring mount for partition: volumio_data Oct 06 16:18:22 volumio volumio[3821]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 06 16:18:22 volumio volumio[3821]: info: Loading plugin "volumio_command_line_client"... Oct 06 16:18:22 volumio volumio[3821]: info: Loading plugin "upnp"... Oct 06 16:18:22 volumio volumio[3821]: info: [1728224302253] Starting Upmpd Daemon Oct 06 16:18:22 volumio volumio[3821]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 06 16:18:22 volumio volumio[3821]: info: Loading plugin "my_music"... Oct 06 16:18:22 volumio volumio[3821]: info: Loading plugin "mpd"... Oct 06 16:18:22 volumio volumio[3821]: info: Loading plugin "upnp_browser"... Oct 06 16:18:22 volumio volumio[3821]: info: Loading plugin "alarm-clock"... Oct 06 16:18:22 volumio volumio[3821]: info: Loading plugin "airplay_emulation"... Oct 06 16:18:22 volumio volumio[3821]: info: Starting Shairport Sync Oct 06 16:18:22 volumio volumio[3821]: info: Loading plugin "last_100"... Oct 06 16:18:22 volumio volumio[3821]: info: Loading plugin "webradio"... Oct 06 16:18:22 volumio volumio[3821]: info: Loading plugin "i2s_dacs"... Oct 06 16:18:22 volumio volumio[3821]: info: Loading plugin "volumiodiscovery"... Oct 06 16:18:22 volumio volumio[3821]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Oct 06 16:18:22 volumio volumio[3821]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 06 16:18:22 volumio volumio[3821]: *** WARNING *** For more information see Oct 06 16:18:22 volumio node[3821]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Oct 06 16:18:22 volumio volumio[3821]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Oct 06 16:18:22 volumio volumio[3821]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 06 16:18:22 volumio volumio[3821]: *** WARNING *** For more information see Oct 06 16:18:22 volumio node[3821]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 06 16:18:22 volumio node[3821]: *** WARNING *** For more information see Oct 06 16:18:22 volumio node[3821]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Oct 06 16:18:22 volumio node[3821]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 06 16:18:22 volumio node[3821]: *** WARNING *** For more information see Oct 06 16:18:22 volumio volumio[3821]: info: Applying required configuration parameters for plugin volumiodiscovery Oct 06 16:18:22 volumio volumio[3821]: info: Discovery: Started advertising with name: Volumio Oct 06 16:18:22 volumio volumio[3821]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 06 16:18:22 volumio volumio[3821]: info: Loading plugin "bandcamp"... Oct 06 16:18:23 volumio volumio[3821]: info: Loading plugin "soundcloud"... Oct 06 16:18:23 volumio volumio[3821]: info: Loading plugin "spop"... Oct 06 16:18:24 volumio go-librespot[2399]: time="2024-10-06T16:18:24+02:00" level=debug msg="fetched chunk 6/43, size: 524288" uri="spotify:track:2vN0yJIIsjfUE5EgcBT6hf" Oct 06 16:18:24 volumio volumio[3821]: info: Loading plugin "outputs"... Oct 06 16:18:24 volumio volumio[3821]: info: Loading plugin "albumart"... Oct 06 16:18:24 volumio volumio[3821]: info: Plugin example_plugin is not enabled Oct 06 16:18:24 volumio volumio[3821]: info: Loading plugin "inputs"... Oct 06 16:18:24 volumio volumio[3821]: info: Loading plugin "updater_comm"... Oct 06 16:18:24 volumio volumio[3821]: info: Plugin mpdemulation is not enabled Oct 06 16:18:24 volumio volumio[3821]: info: Loading plugin "rest_api"... Oct 06 16:18:24 volumio volumio[3821]: info: Loading plugin "websocket"... Oct 06 16:18:24 volumio volumio[3821]: info: Starting Socket.io Server version 2.3.0 Oct 06 16:18:24 volumio volumio[3821]: info: Loading i18n strings for locale sv Oct 06 16:18:24 volumio volumio[3821]: Updating browse sources language Oct 06 16:18:24 volumio volumio[3821]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 06 16:18:24 volumio volumio-remote-updater[1339]: [2024-10-06 16:18:24] [connect] Successful connection Oct 06 16:18:24 volumio volumio[3821]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 06 16:18:24 volumio volumio[3821]: info: CoreCommandRouter::initPlayerControls Oct 06 16:18:24 volumio volumio[3821]: Forking 3 albumart workers Oct 06 16:18:24 volumio volumio[3821]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 06 16:18:24 volumio volumio[3821]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 06 16:18:24 volumio volumio[3821]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 06 16:18:24 volumio volumio[3821]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 06 16:18:24 volumio volumio[3821]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 06 16:18:24 volumio volumio[3821]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 06 16:18:24 volumio volumio[3821]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 06 16:18:24 volumio volumio[3821]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 06 16:18:24 volumio volumio[3821]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 06 16:18:24 volumio volumio[3821]: Express server listening on port 3000 Oct 06 16:18:24 volumio volumio[3821]: [Metrics] WebUI: 4s 42.82ms Oct 06 16:18:24 volumio volumio[3821]: info: CoreStateMachine::resetVolumioState Oct 06 16:18:24 volumio volumio[3821]: info: CoreStateMachine::getcurrentVolume Oct 06 16:18:24 volumio volumio[3821]: info: CoreCommandRouter::volumioRetrievevolume Oct 06 16:18:24 volumio volumio[3821]: info: CoreStateMachine::pushState Oct 06 16:18:24 volumio volumio[3821]: info: CorePlayQueue::getTrack 0 Oct 06 16:18:24 volumio volumio[3821]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 06 16:18:24 volumio volumio[3821]: info: CoreCommandRouter::volumioPushState Oct 06 16:18:24 volumio volumio[3821]: verbose: New Socket.io Connection to 192.168.2.53 from 192.168.2.42 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 17_6_1 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Engine version: 3 Transport: polling Total Clients: 1 Oct 06 16:18:24 volumio volumio[3821]: verbose: New Socket.io Connection to 192.168.2.53 from 192.168.2.42 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 17_6_1 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Engine version: 3 Transport: polling Total Clients: 2 Oct 06 16:18:24 volumio volumio-remote-updater[1339]: [2024-10-06 16:18:24] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1728224304 101 Oct 06 16:18:24 volumio volumio[3821]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 4 Transport: websocket Total Clients: 3 Oct 06 16:18:24 volumio volumio[3821]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 06 16:18:24 volumio volumio[3821]: info: Reloading queue from file Oct 06 16:18:24 volumio volumio[3821]: info: CoreStateMachine::setRepeat null single undefined Oct 06 16:18:24 volumio volumio[3821]: info: CoreStateMachine::pushState Oct 06 16:18:24 volumio volumio[3821]: info: CorePlayQueue::getTrack 0 Oct 06 16:18:24 volumio volumio[3821]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 06 16:18:24 volumio volumio[3821]: info: CoreCommandRouter::volumioPushState Oct 06 16:18:24 volumio volumio[3821]: info: CoreStateMachine::setRandom null Oct 06 16:18:24 volumio volumio[3821]: info: CoreStateMachine::pushState Oct 06 16:18:24 volumio volumio[3821]: info: CorePlayQueue::getTrack 0 Oct 06 16:18:24 volumio volumio[3821]: info: CoreCommandRouter::volumioPushState Oct 06 16:18:24 volumio volumio[3821]: info: Setting Device type: Raspberry PI Oct 06 16:18:24 volumio volumio[3821]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Oct 06 16:18:24 volumio volumio[3821]: info: USB Boot Capable - System SBC Revision found in cpuinfo: c03115 Oct 06 16:18:24 volumio volumio[3821]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Oct 06 16:18:24 volumio volumio[3821]: info: Completed loading Core Plugins Oct 06 16:18:24 volumio volumio[3821]: info: Preparing to generate the ALSA configuration file Oct 06 16:18:25 volumio volumio[3821]: info: Asound.conf file unchanged, so no further update is needed Oct 06 16:18:25 volumio volumio[3821]: info: Output device has changed, restarting MPD Oct 06 16:18:25 volumio volumio[3821]: info: Output device has changed, restarting Shairport Sync Oct 06 16:18:25 volumio volumio[3821]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 06 16:18:25 volumio volumio[3821]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 06 16:18:25 volumio sudo[3899]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 06 16:18:25 volumio sudo[3899]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 06 16:18:25 volumio sudo[3900]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 06 16:18:25 volumio sudo[3900]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 06 16:18:25 volumio sudo[3899]: pam_unix(sudo:session): session closed for user root Oct 06 16:18:25 volumio systemd[1]: Stopping Music Player Daemon... Oct 06 16:18:25 volumio volumio[3821]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 06 16:18:25 volumio volumio[3821]: info: ___________ START PLUGINS ___________ Oct 06 16:18:25 volumio volumio[3821]: info: ControllerMpd::onStart: Initializing MPD Oct 06 16:18:25 volumio volumio[3821]: info: Creating MPD Configuration file Oct 06 16:18:25 volumio systemd[1]: mpd.service: Succeeded. Oct 06 16:18:25 volumio systemd[1]: Stopped Music Player Daemon. Oct 06 16:18:25 volumio systemd[1]: Starting Music Player Daemon... Oct 06 16:18:25 volumio volumio[3821]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 06 16:18:25 volumio volumio[3821]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 06 16:18:25 volumio volumio[3821]: info: [1728224305239] CoreMusicLibrary::Adding element Mediaservrar Oct 06 16:18:25 volumio volumio[3821]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 06 16:18:25 volumio sudo[3908]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 06 16:18:25 volumio sudo[3908]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 06 16:18:25 volumio sudo[3908]: pam_unix(sudo:session): session closed for user root Oct 06 16:18:25 volumio volumio[3821]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 06 16:18:25 volumio volumio[3821]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 06 16:18:25 volumio sudo[3906]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Oct 06 16:18:25 volumio sudo[3906]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 06 16:18:25 volumio sudo[3906]: pam_unix(sudo:session): session closed for user root Oct 06 16:18:25 volumio sudo[3910]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 06 16:18:25 volumio sudo[3910]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 06 16:18:25 volumio systemd[1]: mpd.service: Main process exited, code=killed, status=15/TERM Oct 06 16:18:25 volumio systemd[1]: mpd.service: Succeeded. Oct 06 16:18:25 volumio volumio[3821]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 06 16:18:25 volumio volumio[3821]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 06 16:18:25 volumio volumio[3821]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 06 16:18:25 volumio systemd[1]: Stopped Music Player Daemon. Oct 06 16:18:25 volumio systemd[1]: Starting Music Player Daemon... Oct 06 16:18:25 volumio volumio[3821]: Starting albumart workers Oct 06 16:18:25 volumio volumio[3821]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 06 16:18:25 volumio volumio[3821]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 06 16:18:25 volumio volumio[3821]: info: [1728224305412] CoreMusicLibrary::Adding element Last_100 Oct 06 16:18:25 volumio volumio[3821]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 06 16:18:25 volumio volumio[3821]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 06 16:18:25 volumio volumio[3821]: info: [1728224305417] CoreMusicLibrary::Adding element Webradio Oct 06 16:18:25 volumio volumio[3821]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 06 16:18:25 volumio volumio[3821]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 06 16:18:25 volumio volumio[3821]: info: Initializing BBC Radios Oct 06 16:18:25 volumio sudo[3918]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Oct 06 16:18:25 volumio sudo[3918]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 06 16:18:25 volumio sudo[3918]: pam_unix(sudo:session): session closed for user root Oct 06 16:18:25 volumio volumio[3821]: Starting albumart workers Oct 06 16:18:25 volumio volumio[3821]: Starting albumart workers Oct 06 16:18:25 volumio volumio[3821]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 06 16:18:25 volumio volumio[3821]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 06 16:18:25 volumio volumio[3821]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 06 16:18:25 volumio volumio[3821]: info: [1728224305637] CoreMusicLibrary::Adding element Bandcamp Discover Oct 06 16:18:25 volumio volumio[3821]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 06 16:18:25 volumio volumio[3821]: Cannot find translation for source Bandcamp Discover Oct 06 16:18:25 volumio volumio[3821]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 06 16:18:25 volumio volumio[3821]: info: [1728224305650] CoreMusicLibrary::Adding element SoundCloud Oct 06 16:18:25 volumio volumio[3821]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 06 16:18:25 volumio volumio[3821]: Cannot find translation for source Bandcamp Discover Oct 06 16:18:25 volumio volumio[3821]: Cannot find translation for source SoundCloud Oct 06 16:18:25 volumio volumio[3821]: info: Creating Spotify config file Oct 06 16:18:25 volumio volumio[3821]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 06 16:18:25 volumio volumio[3821]: info: Volumio Calling Home Oct 06 16:18:25 volumio sudo[3853]: pam_unix(sudo:session): session closed for user root Oct 06 16:18:26 volumio volumio[3821]: info: Discovery: adding bdec9109-a559-4acf-9692-dc69c4c6c743 Oct 06 16:18:26 volumio volumio[3821]: info: Discovery: Found device Volumio Oct 06 16:18:26 volumio volumio[3821]: info: CoreCommandRouter::volumioGetState Oct 06 16:18:26 volumio volumio[3821]: info: CorePlayQueue::getTrack 0 Oct 06 16:18:26 volumio volumio[3821]: info: MPD Permissions set Oct 06 16:18:26 volumio volumio[3821]: info: MPD Permissions set Oct 06 16:18:26 volumio volumio[3821]: info: Spotify config file written Oct 06 16:18:26 volumio volumio[3821]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 4 Oct 06 16:18:26 volumio volumio[3821]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 06 16:18:26 volumio volumio[3821]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 06 16:18:26 volumio volumio[3821]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 06 16:18:26 volumio volumio[3821]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 06 16:18:26 volumio volumio[3821]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 06 16:18:26 volumio volumio[3821]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 06 16:18:26 volumio volumio[3821]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 06 16:18:26 volumio volumio[3821]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 06 16:18:26 volumio sudo[3962]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Oct 06 16:18:26 volumio sudo[3962]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 06 16:18:26 volumio systemd[1]: Stopping go-librespot Daemon... Oct 06 16:18:26 volumio volumio[3821]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 06 16:18:26 volumio volumio[3821]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 06 16:18:26 volumio volumio[3821]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 06 16:18:26 volumio volumio[3821]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 06 16:18:26 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=killed, status=15/TERM Oct 06 16:18:26 volumio systemd[1]: go-librespot-daemon.service: Succeeded. Oct 06 16:18:26 volumio systemd[1]: Stopped go-librespot Daemon. Oct 06 16:18:26 volumio volumio[3821]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 06 16:18:26 volumio volumio[3821]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 06 16:18:26 volumio volumio[3821]: info: No need to fix Spotify hosts Oct 06 16:18:26 volumio systemd[1]: Started go-librespot Daemon. Oct 06 16:18:26 volumio go-librespot[3968]: Librespot-go daemon starting... Oct 06 16:18:26 volumio sudo[3962]: pam_unix(sudo:session): session closed for user root Oct 06 16:18:26 volumio go-librespot[3968]: time="2024-10-06T16:18:26+02:00" level=info msg="generated new device id: 5404c12183b748e0c7670619c743bccadbc9dd24" Oct 06 16:18:26 volumio go-librespot[3968]: time="2024-10-06T16:18:26+02:00" level=debug msg="stored credentials found for gronk" Oct 06 16:18:26 volumio volumio[3821]: info: Starting Shairport Sync Oct 06 16:18:26 volumio volumio[3821]: info: Starting Shairport Sync Oct 06 16:18:26 volumio volumio[3821]: info: Starting Shairport Sync Oct 06 16:18:26 volumio sudo[3980]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 06 16:18:26 volumio sudo[3980]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 06 16:18:26 volumio sudo[3982]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 06 16:18:26 volumio sudo[3982]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 06 16:18:26 volumio volumio[3821]: info: CoreCommandRouter::volumioGetState Oct 06 16:18:26 volumio volumio[3821]: info: CorePlayQueue::getTrack 0 Oct 06 16:18:26 volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Oct 06 16:18:26 volumio systemd[1]: shairport-sync.service: Succeeded. Oct 06 16:18:26 volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Oct 06 16:18:26 volumio sudo[3985]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 06 16:18:26 volumio sudo[3985]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 06 16:18:26 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Oct 06 16:18:26 volumio sudo[3980]: pam_unix(sudo:session): session closed for user root Oct 06 16:18:26 volumio volumio[3821]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Oct 06 16:18:26 volumio volumio[3821]: SPOTIFY: BQDgC9pTMMOjLaNcYb7Xji_Gn7hALh58cookPgCPd0kPtensaJZ9k_VI2nojQujygSzkjvl8fa8fdmmM_s7W_WPVgNBcqPdek47gX1DvmrRdMc1Hmp1qESkAHN6-Ebg8wgJvsc9f6AfhQfZ2fGTASQygE8effkwinicGQPg7lRMin4sEz2FObX5T3lS6IWZdWYPRcj1OaQmXIh4pOHBzWzkiLUB3xEgOeo_9nHlex-M-xTdswOiZ Oct 06 16:18:26 volumio volumio[3821]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Oct 06 16:18:26 volumio volumio[3821]: info: New Spotify access token = BQDgC9pTMMOjLaNcYb7Xji_Gn7hALh58cookPgCPd0kPtensaJZ9k_VI2nojQujygSzkjvl8fa8fdmmM_s7W_WPVgNBcqPdek47gX1DvmrRdMc1Hmp1qESkAHN6-Ebg8wgJvsc9f6AfhQfZ2fGTASQygE8effkwinicGQPg7lRMin4sEz2FObX5T3lS6IWZdWYPRcj1OaQmXIh4pOHBzWzkiLUB3xEgOeo_9nHlex-M-xTdswOiZ Oct 06 16:18:26 volumio volumio[3821]: info: Spotify credentials grant success - running version from March 24, 2019 Oct 06 16:18:26 volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Oct 06 16:18:26 volumio systemd[1]: shairport-sync.service: Succeeded. Oct 06 16:18:26 volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Oct 06 16:18:26 volumio mpd[3925]: Oct 06 16:18 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Oct 06 16:18:26 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Oct 06 16:18:26 volumio go-librespot[3968]: time="2024-10-06T16:18:26+02: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-gew1.spotify.com:80]" Oct 06 16:18:26 volumio go-librespot[3968]: time="2024-10-06T16:18:26+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Oct 06 16:18:26 volumio go-librespot[3968]: time="2024-10-06T16:18:26+02: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]" Oct 06 16:18:26 volumio sudo[3982]: pam_unix(sudo:session): session closed for user root Oct 06 16:18:26 volumio systemd[1]: Started Music Player Daemon. Oct 06 16:18:26 volumio sudo[3985]: pam_unix(sudo:session): session closed for user root Oct 06 16:18:26 volumio go-librespot[3968]: time="2024-10-06T16:18:26+02:00" level=debug msg="zeroconf server listening on port 35457" Oct 06 16:18:26 volumio sudo[3910]: pam_unix(sudo:session): session closed for user root Oct 06 16:18:26 volumio sudo[3900]: pam_unix(sudo:session): session closed for user root Oct 06 16:18:26 volumio volumio[3821]: info: Shairport-Sync Started Oct 06 16:18:26 volumio volumio[3821]: Error adding Membership: Error: addMembership EINVAL Oct 06 16:18:26 volumio volumio[3821]: info: Completed starting Core Plugins Oct 06 16:18:26 volumio volumio[3821]: info: ------------------------------------------- Oct 06 16:18:26 volumio volumio[3821]: info: ----- MyVolumio plugins startup ---- Oct 06 16:18:26 volumio volumio[3821]: info: ------------------------------------------- Oct 06 16:18:26 volumio volumio[3821]: info: [MyVolumio PluginManager] Fetching plans data.... Oct 06 16:18:26 volumio volumio[3821]: info: Shairport-Sync Started Oct 06 16:18:26 volumio volumio[3821]: info: Shairport-Sync Started Oct 06 16:18:26 volumio go-librespot[3968]: time="2024-10-06T16:18:26+02:00" level=debug msg="obtained new client token: AADHGqsOIE+ykYWHtGbl7YjUEEt7BUjoi4gL0n8FrLH4la1tPsf1EgMLi5+jJ1I4euqrv9Tuwmm3X/mBBQqyA9oegc+Yhub73wZMP4tpwtGTiiUoskxvF1zPDhfbQyWYY4n7P1PlH9t+Qz++AE/X93QMiTFZUvHryRsmgD/UHA9fin4d0/0yg6hkK2eHt+Ev7b5H1hhkXJsxFYn1wmfGMtQl3cjtHR4H6ukOoNMTCv2vhH902/Eaw3KaS4QxPg==" Oct 06 16:18:26 volumio volumio[3821]: error: MPD error: The expression evaluated to a falsy value: Oct 06 16:18:26 volumio volumio[3821]: assert.ok(self.idling) Oct 06 16:18:26 volumio volumio[3821]: error: The expression evaluated to a falsy value: Oct 06 16:18:26 volumio volumio[3821]: assert.ok(self.idling) Oct 06 16:18:26 volumio volumio[3821]: info: MPD running with PID3925 Oct 06 16:18:26 volumio volumio[3821]: ,establishing connection Oct 06 16:18:26 volumio volumio[3821]: error: updateQueue error: null Oct 06 16:18:26 volumio volumio[3821]: error: updateQueue error: null Oct 06 16:18:26 volumio go-librespot[3968]: time="2024-10-06T16:18:26+02:00" level=info msg="connected to ap-gew4.spotify.com:4070" Oct 06 16:18:26 volumio go-librespot[3968]: time="2024-10-06T16:18:26+02:00" level=debug msg="completed keyexchange" Oct 06 16:18:26 volumio volumio[3821]: SPOTIFY: User informations: {"display_name":"gronk","external_urls":{"spotify":"https://open.spotify.com/user/gronk"},"href":"https://api.spotify.com/v1/users/gronk","id":"gronk","images":[],"type":"user","uri":"spotify:user:gronk","followers":{"href":null,"total":3},"country":"SE","product":"premium","explicit_content":{"filter_enabled":false,"filter_locked":false},"email":"maglar@me.com"} Oct 06 16:18:26 volumio volumio[3821]: info: Spotify Successfully logged in Oct 06 16:18:26 volumio volumio[3821]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 06 16:18:26 volumio volumio[3821]: info: [1728224306912] CoreMusicLibrary::Adding element Spotify Oct 06 16:18:26 volumio volumio[3821]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 06 16:18:26 volumio volumio[3821]: Cannot find translation for source Bandcamp Discover Oct 06 16:18:26 volumio volumio[3821]: Cannot find translation for source SoundCloud Oct 06 16:18:26 volumio volumio[3821]: Cannot find translation for source Spotify Oct 06 16:18:27 volumio volumio[3821]: info: Cannot mount NAS Diskstation at system boot, trial number 2 ,retrying in 5 seconds Oct 06 16:18:27 volumio go-librespot[3968]: time="2024-10-06T16:18:27+02:00" level=debug msg="completed challenge" Oct 06 16:18:27 volumio go-librespot[3968]: time="2024-10-06T16:18:27+02:00" level=debug msg="authenticated as gronk" Oct 06 16:18:27 volumio go-librespot[3968]: time="2024-10-06T16:18:27+02:00" level=debug msg="authenticated as gronk" Oct 06 16:18:27 volumio go-librespot[3968]: time="2024-10-06T16:18:27+02:00" level=debug msg="dealer connection opened" Oct 06 16:18:27 volumio go-librespot[3968]: time="2024-10-06T16:18:27+02:00" level=debug msg="initializing zeroconf session, username: gronk" Oct 06 16:18:27 volumio go-librespot[3968]: time="2024-10-06T16:18:27+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Oct 06 16:18:27 volumio go-librespot[3968]: time="2024-10-06T16:18:27+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Oct 06 16:18:27 volumio go-librespot[3968]: time="2024-10-06T16:18:27+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Oct 06 16:18:27 volumio go-librespot[3968]: time="2024-10-06T16:18:27+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Oct 06 16:18:27 volumio go-librespot[3968]: time="2024-10-06T16:18:27+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 493" Oct 06 16:18:27 volumio go-librespot[3968]: time="2024-10-06T16:18:27+02:00" level=debug msg="autoplay enabled: false" Oct 06 16:18:27 volumio go-librespot[3968]: time="2024-10-06T16:18:27+02:00" level=debug msg="received connection id: MjRiNTJjOTEtNjZhYi00YjA0LTljZjctZTJjODUzYjhkMGNlK2RlYWxlcit0Y3A6Ly8wYWNhNTg0Mi5pcC5nZXc0LnNwb3RpZnkubmV0OjU3MDArMzQ1OEFENThFQjU1Qjg5N0E1MDg1MkM1MjBEMTg4N0I2ODQwN0NDOEVCQ0VCMkQwQkREOUM5ODZERTM4QUJBNg==" Oct 06 16:18:27 volumio go-librespot[3968]: time="2024-10-06T16:18:27+02:00" level=debug msg="put connect state because NEW_DEVICE" Oct 06 16:18:28 volumio volumio[3821]: verbose: New Socket.io Connection to 192.168.2.53 from 192.168.2.42 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 17_6_1 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Engine version: 3 Transport: polling Total Clients: 5 Oct 06 16:18:28 volumio volumio[3821]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Oct 06 16:18:28 volumio volumio[3821]: info: CoreCommandRouter::volumioGetVisibleSources Oct 06 16:18:28 volumio volumio[3821]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 06 16:18:28 volumio volumio[3821]: info: CoreCommandRouter::volumioGetState Oct 06 16:18:28 volumio volumio[3821]: info: CorePlayQueue::getTrack 0 Oct 06 16:18:28 volumio volumio[3821]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Oct 06 16:18:28 volumio volumio[3821]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Oct 06 16:18:28 volumio volumio[3821]: info: Received Get System Info Oct 06 16:18:28 volumio volumio[3821]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 06 16:18:28 volumio volumio[3821]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 06 16:18:28 volumio volumio[3821]: info: Discovery: Getting this device information Oct 06 16:18:28 volumio volumio[3821]: info: CoreCommandRouter::volumioGetState Oct 06 16:18:28 volumio volumio[3821]: info: CorePlayQueue::getTrack 0 Oct 06 16:18:28 volumio volumio[3821]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 06 16:18:28 volumio volumio[3821]: info: CoreCommandRouter::volumioGetState Oct 06 16:18:28 volumio volumio[3821]: info: CorePlayQueue::getTrack 0 Oct 06 16:18:28 volumio volumio[3821]: info: Listing playlists Oct 06 16:18:28 volumio volumio[3821]: info: CoreCommandRouter::volumioGetQueue Oct 06 16:18:28 volumio volumio[3821]: info: CoreStateMachine::getQueue Oct 06 16:18:28 volumio volumio[3821]: info: CorePlayQueue::getQueue Oct 06 16:18:29 volumio volumio[3821]: info: go-librespot daemon successfully initialized Oct 06 16:18:31 volumio volumio[3821]: info: Volumio called home Oct 06 16:18:31 volumio volumio[3821]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Oct 06 16:18:31 volumio volumio[3821]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Oct 06 16:18:31 volumio volumio[3821]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 06 16:18:31 volumio volumio[3821]: TypeError: Cannot read property 'length' of undefined Oct 06 16:18:31 volumio volumio[3821]: at /volumio/app/plugins/music_service/upnp_browser/index.js:341:25 Oct 06 16:18:31 volumio volumio[3821]: at /volumio/app/plugins/music_service/upnp_browser/dlna-browser.js:131:13 Oct 06 16:18:31 volumio volumio[3821]: at Parser. (/volumio/node_modules/xml2js/lib/parser.js:304:18) Oct 06 16:18:31 volumio volumio[3821]: at Parser.emit (events.js:315:20) Oct 06 16:18:31 volumio volumio[3821]: at SAXParser.onclosetag (/volumio/node_modules/xml2js/lib/parser.js:262:26) Oct 06 16:18:31 volumio volumio[3821]: at emit (/volumio/node_modules/sax/lib/sax.js:624:35) Oct 06 16:18:31 volumio volumio[3821]: at emitNode (/volumio/node_modules/sax/lib/sax.js:629:5) Oct 06 16:18:31 volumio volumio[3821]: at closeTag (/volumio/node_modules/sax/lib/sax.js:889:7) Oct 06 16:18:31 volumio volumio[3821]: at SAXParser.write (/volumio/node_modules/sax/lib/sax.js:1436:13) Oct 06 16:18:31 volumio volumio[3821]: at Parser.exports.Parser.Parser.parseString (/volumio/node_modules/xml2js/lib/parser.js:323:31) Oct 06 16:18:31 volumio volumio[3821]: at Parser.parseString (/volumio/node_modules/xml2js/lib/parser.js:5:59) Oct 06 16:18:31 volumio volumio[3821]: at Object.exports.parseString (/volumio/node_modules/xml2js/lib/parser.js:369:19) Oct 06 16:18:31 volumio volumio[3821]: at IncomingMessage. (/volumio/app/plugins/music_service/upnp_browser/dlna-browser.js:92:15) Oct 06 16:18:31 volumio volumio[3821]: at IncomingMessage.emit (events.js:327:22) Oct 06 16:18:31 volumio volumio[3821]: at endReadableNT (internal/streams/readable.js:1327:12) Oct 06 16:18:31 volumio volumio[3821]: at processTicksAndRejections (internal/process/task_queues.js:80:21) Oct 06 16:18:31 volumio volumio[3821]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 06 16:18:32 volumio sudo[4010]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-10-06 16:17 Oct 06 16:18:32 volumio sudo[4010]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 06 16:18:32 volumio sudo[4010]: pam_unix(sudo:session): session closed for user root Oct 06 16:18:32 volumio volumio-remote-updater[1339]: [2024-10-06 16:18:32] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Oct 06 16:18:32 volumio volumio-remote-updater[1339]: [2024-10-06 16:18:32] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Oct 06 16:18:32 volumio systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Oct 06 16:18:32 volumio systemd[1]: volumio.service: Failed with result 'exit-code'. Oct 06 16:18:32 volumio systemd[1]: Started dynamicswap service. Oct 06 16:18:32 volumio systemd[1]: dynamicswap.service: Succeeded. Oct 06 16:18:32 volumio systemd[1]: volumio.service: Service RestartSec=100ms expired, scheduling restart. Oct 06 16:18:32 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 2. Oct 06 16:18:32 volumio systemd[1]: Stopped Volumio Backend Module. Oct 06 16:18:32 volumio systemd[1]: Started Volumio Backend Module. Oct 06 16:18:32 volumio systemd[1]: Started dynamicswap service. Oct 06 16:18:32 volumio systemd[1]: dynamicswap.service: Succeeded. Oct 06 16:18:33 volumio volumio[4021]: info: ------------------------------------------- Oct 06 16:18:33 volumio volumio[4021]: info: ----- Volumio3 ---- Oct 06 16:18:33 volumio volumio[4021]: info: ------------------------------------------- Oct 06 16:18:33 volumio volumio[4021]: info: ----- System startup ---- Oct 06 16:18:33 volumio volumio[4021]: info: ------------------------------------------- Oct 06 16:18:34 volumio volumio[4021]: info: MYVOLUMIO Environment detected Oct 06 16:18:34 volumio volumio[4021]: info: Plugin folders cleanup Oct 06 16:18:34 volumio volumio[4021]: info: Scanning into folder /volumio/app/plugins/ Oct 06 16:18:34 volumio volumio[4021]: info: Scanning category audio_interface Oct 06 16:18:34 volumio volumio[4021]: info: Scanning category miscellanea Oct 06 16:18:34 volumio volumio[4021]: info: Scanning category music_service Oct 06 16:18:34 volumio volumio[4021]: info: Scanning category plugins.json Oct 06 16:18:34 volumio volumio[4021]: info: Scanning category system_controller Oct 06 16:18:34 volumio volumio[4021]: info: Scanning category user_interface Oct 06 16:18:34 volumio volumio[4021]: info: Scanning into folder /data/plugins/ Oct 06 16:18:34 volumio volumio[4021]: info: Scanning category music_service Oct 06 16:18:34 volumio volumio[4021]: info: Plugin folders cleanup completed Oct 06 16:18:34 volumio volumio[4021]: info: ------------------------------------------- Oct 06 16:18:34 volumio volumio[4021]: info: ----- Core plugins startup ---- Oct 06 16:18:34 volumio volumio[4021]: info: ------------------------------------------- Oct 06 16:18:34 volumio volumio[4021]: info: Loading plugins from folder /volumio/app/plugins/ Oct 06 16:18:34 volumio volumio[4021]: info: Adding plugin upnp to MyMusic Plugins Oct 06 16:18:34 volumio volumio[4021]: info: Adding plugin airplay_emulation to MyMusic Plugins Oct 06 16:18:34 volumio volumio[4021]: info: Adding plugin upnp_browser to MyMusic Plugins Oct 06 16:18:34 volumio volumio[4021]: info: Loading plugins from folder /data/plugins/ Oct 06 16:18:34 volumio volumio[4021]: info: Loading plugin "system"... Oct 06 16:18:34 volumio volumio[4021]: info: Loading plugin "appearance"... Oct 06 16:18:34 volumio volumio[4021]: info: Loading plugin "network"... Oct 06 16:18:34 volumio volumio[4021]: info: Refreshing Cached IP Addresses Oct 06 16:18:34 volumio sudo[4048]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 06 16:18:34 volumio sudo[4048]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 06 16:18:34 volumio sudo[4048]: pam_unix(sudo:session): session closed for user root Oct 06 16:18:34 volumio sudo[4050]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 06 16:18:34 volumio sudo[4050]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 06 16:18:34 volumio volumio[4021]: info: Loading plugin "services"... Oct 06 16:18:34 volumio volumio[4021]: info: Loading plugin "alsa_controller"... Oct 06 16:18:34 volumio sudo[4050]: pam_unix(sudo:session): session closed for user root Oct 06 16:18:34 volumio sudo[4053]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Oct 06 16:18:34 volumio sudo[4053]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 06 16:18:34 volumio volumio[4021]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 06 16:18:34 volumio volumio[4021]: info: Loading plugin "wizard"... Oct 06 16:18:34 volumio volumio[4021]: info: Loading plugin "networkfs"... Oct 06 16:18:34 volumio volumio[4021]: info: Cannot mount NAS Diskstation at system boot, trial number 1 ,retrying in 5 seconds Oct 06 16:18:34 volumio volumio[4021]: info: Starting Udev Watcher for removable devices Oct 06 16:18:34 volumio volumio[4021]: info: Ignoring mount for partition: boot Oct 06 16:18:34 volumio volumio[4021]: info: Ignoring mount for partition: volumio Oct 06 16:18:34 volumio volumio[4021]: info: Ignoring mount for partition: volumio_data Oct 06 16:18:34 volumio volumio[4021]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 06 16:18:34 volumio volumio[4021]: info: Loading plugin "volumio_command_line_client"... Oct 06 16:18:34 volumio volumio[4021]: info: Loading plugin "upnp"... Oct 06 16:18:34 volumio volumio[4021]: info: [1728224314869] Starting Upmpd Daemon Oct 06 16:18:34 volumio volumio[4021]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 06 16:18:34 volumio volumio[4021]: info: Loading plugin "my_music"... Oct 06 16:18:34 volumio volumio[4021]: info: Loading plugin "mpd"... Oct 06 16:18:35 volumio volumio[4021]: info: Loading plugin "upnp_browser"... Oct 06 16:18:35 volumio volumio[4021]: info: Loading plugin "alarm-clock"... Oct 06 16:18:35 volumio volumio[4021]: info: Loading plugin "airplay_emulation"... Oct 06 16:18:35 volumio volumio[4021]: info: Starting Shairport Sync Oct 06 16:18:35 volumio volumio[4021]: info: Loading plugin "last_100"... Oct 06 16:18:35 volumio volumio[4021]: info: Loading plugin "webradio"... Oct 06 16:18:35 volumio volumio[4021]: info: Loading plugin "i2s_dacs"... Oct 06 16:18:35 volumio volumio[4021]: info: Loading plugin "volumiodiscovery"... Oct 06 16:18:35 volumio volumio[4021]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Oct 06 16:18:35 volumio volumio[4021]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 06 16:18:35 volumio node[4021]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Oct 06 16:18:35 volumio volumio[4021]: *** WARNING *** For more information see Oct 06 16:18:35 volumio volumio[4021]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Oct 06 16:18:35 volumio volumio[4021]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 06 16:18:35 volumio volumio[4021]: *** WARNING *** For more information see Oct 06 16:18:35 volumio node[4021]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 06 16:18:35 volumio node[4021]: *** WARNING *** For more information see Oct 06 16:18:35 volumio node[4021]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Oct 06 16:18:35 volumio node[4021]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 06 16:18:35 volumio node[4021]: *** WARNING *** For more information see Oct 06 16:18:35 volumio volumio[4021]: info: Applying required configuration parameters for plugin volumiodiscovery Oct 06 16:18:35 volumio volumio[4021]: info: Discovery: Started advertising with name: Volumio Oct 06 16:18:35 volumio volumio[4021]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 06 16:18:35 volumio volumio[4021]: info: Loading plugin "bandcamp"... Oct 06 16:18:36 volumio volumio[4021]: info: Loading plugin "soundcloud"... Oct 06 16:18:36 volumio volumio[4021]: info: Loading plugin "spop"... Oct 06 16:18:36 volumio volumio[4021]: info: Loading plugin "outputs"... Oct 06 16:18:36 volumio volumio[4021]: info: Loading plugin "albumart"... Oct 06 16:18:36 volumio volumio[4021]: info: Plugin example_plugin is not enabled Oct 06 16:18:36 volumio volumio[4021]: info: Loading plugin "inputs"... Oct 06 16:18:36 volumio volumio[4021]: info: Loading plugin "updater_comm"... Oct 06 16:18:37 volumio volumio[4021]: info: Plugin mpdemulation is not enabled Oct 06 16:18:37 volumio volumio[4021]: info: Loading plugin "rest_api"... Oct 06 16:18:37 volumio volumio[4021]: info: Loading plugin "websocket"... Oct 06 16:18:37 volumio volumio[4021]: info: Starting Socket.io Server version 2.3.0 Oct 06 16:18:37 volumio volumio[4021]: info: Loading i18n strings for locale sv Oct 06 16:18:37 volumio volumio[4021]: Updating browse sources language Oct 06 16:18:37 volumio volumio[4021]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 06 16:18:37 volumio volumio[4021]: Forking 3 albumart workers Oct 06 16:18:37 volumio volumio[4021]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 06 16:18:37 volumio volumio[4021]: info: CoreCommandRouter::initPlayerControls Oct 06 16:18:37 volumio volumio[4021]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 06 16:18:37 volumio volumio[4021]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 06 16:18:37 volumio volumio[4021]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 06 16:18:37 volumio volumio[4021]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 06 16:18:37 volumio volumio[4021]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 06 16:18:37 volumio volumio[4021]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 06 16:18:37 volumio volumio[4021]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 06 16:18:37 volumio volumio[4021]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 06 16:18:37 volumio volumio[4021]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 06 16:18:37 volumio volumio[4021]: Express server listening on port 3000 Oct 06 16:18:37 volumio volumio[4021]: [Metrics] WebUI: 3s 841.39ms Oct 06 16:18:37 volumio volumio[4021]: info: CoreStateMachine::resetVolumioState Oct 06 16:18:37 volumio volumio[4021]: info: CoreStateMachine::getcurrentVolume Oct 06 16:18:37 volumio volumio[4021]: info: CoreCommandRouter::volumioRetrievevolume Oct 06 16:18:37 volumio volumio[4021]: info: CoreStateMachine::pushState Oct 06 16:18:37 volumio volumio[4021]: info: CorePlayQueue::getTrack 0 Oct 06 16:18:37 volumio volumio[4021]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 06 16:18:37 volumio volumio[4021]: info: CoreCommandRouter::volumioPushState Oct 06 16:18:37 volumio volumio-remote-updater[1339]: [2024-10-06 16:18:37] [connect] Successful connection Oct 06 16:18:37 volumio volumio[4021]: verbose: New Socket.io Connection to 192.168.2.53 from 192.168.2.42 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 17_6_1 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Engine version: 3 Transport: polling Total Clients: 1 Oct 06 16:18:37 volumio volumio[4021]: verbose: New Socket.io Connection to 192.168.2.53 from 192.168.2.42 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 17_6_1 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Engine version: 3 Transport: polling Total Clients: 2 Oct 06 16:18:37 volumio volumio[4021]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 06 16:18:37 volumio volumio[4021]: info: Reloading queue from file Oct 06 16:18:37 volumio volumio-remote-updater[1339]: [2024-10-06 16:18:37] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1728224317 101 Oct 06 16:18:37 volumio volumio[4021]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 4 Transport: websocket Total Clients: 3 Oct 06 16:18:37 volumio volumio[4021]: info: CoreStateMachine::setRepeat null single undefined Oct 06 16:18:37 volumio volumio[4021]: info: CoreStateMachine::pushState Oct 06 16:18:37 volumio volumio[4021]: info: CorePlayQueue::getTrack 0 Oct 06 16:18:37 volumio volumio[4021]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 06 16:18:37 volumio volumio[4021]: info: CoreCommandRouter::volumioPushState Oct 06 16:18:37 volumio volumio[4021]: info: CoreStateMachine::setRandom null Oct 06 16:18:37 volumio volumio[4021]: info: CoreStateMachine::pushState Oct 06 16:18:37 volumio volumio[4021]: info: CorePlayQueue::getTrack 0 Oct 06 16:18:37 volumio volumio[4021]: info: CoreCommandRouter::volumioPushState Oct 06 16:18:37 volumio volumio[4021]: info: Setting Device type: Raspberry PI Oct 06 16:18:37 volumio volumio[4021]: info: Completed loading Core Plugins Oct 06 16:18:37 volumio volumio[4021]: info: Preparing to generate the ALSA configuration file Oct 06 16:18:37 volumio volumio[4021]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Oct 06 16:18:37 volumio volumio[4021]: info: USB Boot Capable - System SBC Revision found in cpuinfo: c03115 Oct 06 16:18:37 volumio volumio[4021]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Oct 06 16:18:37 volumio volumio[4021]: info: Asound.conf file unchanged, so no further update is needed Oct 06 16:18:37 volumio volumio[4021]: info: Output device has changed, restarting MPD Oct 06 16:18:37 volumio volumio[4021]: info: Output device has changed, restarting Shairport Sync Oct 06 16:18:37 volumio volumio[4021]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 06 16:18:37 volumio volumio[4021]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 06 16:18:37 volumio sudo[4097]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 06 16:18:37 volumio sudo[4097]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 06 16:18:37 volumio sudo[4097]: pam_unix(sudo:session): session closed for user root Oct 06 16:18:37 volumio sudo[4099]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 06 16:18:37 volumio sudo[4099]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 06 16:18:37 volumio volumio[4021]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 06 16:18:37 volumio volumio[4021]: info: ___________ START PLUGINS ___________ Oct 06 16:18:37 volumio volumio[4021]: info: ControllerMpd::onStart: Initializing MPD Oct 06 16:18:37 volumio volumio[4021]: info: Creating MPD Configuration file Oct 06 16:18:37 volumio systemd[1]: Stopping Music Player Daemon... Oct 06 16:18:37 volumio systemd[1]: mpd.service: Succeeded. Oct 06 16:18:37 volumio systemd[1]: Stopped Music Player Daemon. Oct 06 16:18:37 volumio volumio[4021]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 06 16:18:37 volumio volumio[4021]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 06 16:18:37 volumio volumio[4021]: info: [1728224317689] CoreMusicLibrary::Adding element Mediaservrar Oct 06 16:18:37 volumio volumio[4021]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 06 16:18:37 volumio sudo[4107]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 06 16:18:37 volumio sudo[4107]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 06 16:18:37 volumio volumio[4021]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 06 16:18:37 volumio volumio[4021]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 06 16:18:37 volumio sudo[4107]: pam_unix(sudo:session): session closed for user root Oct 06 16:18:37 volumio systemd[1]: Starting Music Player Daemon... Oct 06 16:18:37 volumio sudo[4110]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 06 16:18:37 volumio sudo[4110]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 06 16:18:37 volumio systemd[1]: mpd.service: Control process exited, code=killed, status=15/TERM Oct 06 16:18:37 volumio systemd[1]: mpd.service: Succeeded. Oct 06 16:18:37 volumio systemd[1]: Stopped Music Player Daemon. Oct 06 16:18:37 volumio systemd[1]: Starting Music Player Daemon... Oct 06 16:18:37 volumio volumio[4021]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 06 16:18:37 volumio volumio[4021]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 06 16:18:37 volumio volumio[4021]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 06 16:18:37 volumio volumio[4021]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 06 16:18:37 volumio volumio[4021]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 06 16:18:37 volumio volumio[4021]: info: [1728224317831] CoreMusicLibrary::Adding element Last_100 Oct 06 16:18:37 volumio volumio[4021]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 06 16:18:37 volumio volumio[4021]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 06 16:18:37 volumio volumio[4021]: info: [1728224317834] CoreMusicLibrary::Adding element Webradio Oct 06 16:18:37 volumio volumio[4021]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 06 16:18:37 volumio volumio[4021]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 06 16:18:37 volumio volumio[4021]: info: Initializing BBC Radios Oct 06 16:18:37 volumio sudo[4115]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Oct 06 16:18:37 volumio sudo[4115]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 06 16:18:37 volumio sudo[4115]: pam_unix(sudo:session): session closed for user root Oct 06 16:18:37 volumio volumio[4021]: Starting albumart workers Oct 06 16:18:37 volumio volumio[4021]: Starting albumart workers Oct 06 16:18:37 volumio volumio[4021]: Starting albumart workers Oct 06 16:18:37 volumio volumio[4021]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 06 16:18:37 volumio volumio[4021]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 06 16:18:37 volumio volumio[4021]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 06 16:18:38 volumio volumio[4021]: info: [1728224318005] CoreMusicLibrary::Adding element Bandcamp Discover Oct 06 16:18:38 volumio volumio[4021]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 06 16:18:38 volumio volumio[4021]: Cannot find translation for source Bandcamp Discover Oct 06 16:18:38 volumio volumio[4021]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 06 16:18:38 volumio volumio[4021]: info: [1728224318017] CoreMusicLibrary::Adding element SoundCloud Oct 06 16:18:38 volumio volumio[4021]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 06 16:18:38 volumio volumio[4021]: Cannot find translation for source Bandcamp Discover Oct 06 16:18:38 volumio volumio[4021]: Cannot find translation for source SoundCloud Oct 06 16:18:38 volumio volumio[4021]: info: Creating Spotify config file Oct 06 16:18:38 volumio volumio[4021]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 06 16:18:38 volumio volumio[4021]: info: Volumio Calling Home Oct 06 16:18:38 volumio volumio[4021]: info: Discovery: adding bdec9109-a559-4acf-9692-dc69c4c6c743 Oct 06 16:18:38 volumio volumio[4021]: info: Discovery: Found device Volumio Oct 06 16:18:38 volumio volumio[4021]: info: CoreCommandRouter::volumioGetState Oct 06 16:18:38 volumio volumio[4021]: info: CorePlayQueue::getTrack 0 Oct 06 16:18:38 volumio sudo[4053]: pam_unix(sudo:session): session closed for user root Oct 06 16:18:38 volumio volumio[4021]: info: MPD Permissions set Oct 06 16:18:38 volumio volumio[4021]: info: MPD Permissions set Oct 06 16:18:38 volumio volumio[4021]: info: Spotify config file written Oct 06 16:18:38 volumio sudo[4151]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Oct 06 16:18:38 volumio sudo[4151]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 06 16:18:38 volumio systemd[1]: Stopping go-librespot Daemon... Oct 06 16:18:38 volumio volumio[4021]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 4 Oct 06 16:18:38 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=killed, status=15/TERM Oct 06 16:18:38 volumio systemd[1]: go-librespot-daemon.service: Succeeded. Oct 06 16:18:38 volumio systemd[1]: Stopped go-librespot Daemon. Oct 06 16:18:38 volumio volumio[4021]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 06 16:18:38 volumio volumio[4021]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 06 16:18:38 volumio volumio[4021]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 06 16:18:38 volumio volumio[4021]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 06 16:18:38 volumio volumio[4021]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 06 16:18:38 volumio volumio[4021]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 06 16:18:38 volumio volumio[4021]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 06 16:18:38 volumio volumio[4021]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 06 16:18:38 volumio volumio[4021]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 06 16:18:38 volumio volumio[4021]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 06 16:18:38 volumio volumio[4021]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 06 16:18:38 volumio volumio[4021]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 06 16:18:38 volumio volumio[4021]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 06 16:18:38 volumio volumio[4021]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 06 16:18:38 volumio systemd[1]: Started go-librespot Daemon. Oct 06 16:18:38 volumio volumio[4021]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 06 16:18:38 volumio volumio[4021]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 06 16:18:38 volumio go-librespot[4161]: Librespot-go daemon starting... Oct 06 16:18:38 volumio volumio[4021]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 06 16:18:38 volumio volumio[4021]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 06 16:18:38 volumio sudo[4151]: pam_unix(sudo:session): session closed for user root Oct 06 16:18:38 volumio go-librespot[4161]: time="2024-10-06T16:18:38+02:00" level=info msg="generated new device id: 1b2b776c9f39d23db5baed0a54a737cbd36d9279" Oct 06 16:18:38 volumio go-librespot[4161]: time="2024-10-06T16:18:38+02:00" level=debug msg="stored credentials found for gronk" Oct 06 16:18:38 volumio volumio[4021]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 06 16:18:38 volumio volumio[4021]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 06 16:18:38 volumio volumio[4021]: info: No need to fix Spotify hosts Oct 06 16:18:38 volumio volumio[4021]: info: Volumio called home Oct 06 16:18:38 volumio volumio[4021]: verbose: New Socket.io Connection to 192.168.2.53 from 192.168.2.42 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 17_6_1 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Engine version: 3 Transport: polling Total Clients: 5 Oct 06 16:18:38 volumio volumio[4021]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Oct 06 16:18:38 volumio volumio[4021]: SPOTIFY: BQDOKqaaVnk4xXjgxh1Z7XBfI9kghTKYpd0xzdsnQDU_pPRzqHhHS4LY4V0BpiPnFMCYzAWBcyQfccF1cmLpc5E38LRsMjpc2Q1VWCluZNfBBMeTJOwW2tOGM3kX3goDTlbiPf1kzD_F39SKw1szhwC9gtiqwPsrKt_PXxh5owtEw551D_FUgtetUR98dE8Wkg_YG8YHueNkvle-oJkT1KxHXnC0jdbQ496_lGUrFTujkmyFNYcs Oct 06 16:18:38 volumio volumio[4021]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Oct 06 16:18:38 volumio volumio[4021]: info: New Spotify access token = BQDOKqaaVnk4xXjgxh1Z7XBfI9kghTKYpd0xzdsnQDU_pPRzqHhHS4LY4V0BpiPnFMCYzAWBcyQfccF1cmLpc5E38LRsMjpc2Q1VWCluZNfBBMeTJOwW2tOGM3kX3goDTlbiPf1kzD_F39SKw1szhwC9gtiqwPsrKt_PXxh5owtEw551D_FUgtetUR98dE8Wkg_YG8YHueNkvle-oJkT1KxHXnC0jdbQ496_lGUrFTujkmyFNYcs Oct 06 16:18:38 volumio volumio[4021]: info: Spotify credentials grant success - running version from March 24, 2019 Oct 06 16:18:38 volumio go-librespot[4161]: time="2024-10-06T16:18:38+02: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]" Oct 06 16:18:38 volumio go-librespot[4161]: time="2024-10-06T16:18:38+02: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]" Oct 06 16:18:38 volumio go-librespot[4161]: time="2024-10-06T16:18:38+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 06 16:18:38 volumio volumio[4021]: info: Starting Shairport Sync Oct 06 16:18:38 volumio go-librespot[4161]: time="2024-10-06T16:18:38+02:00" level=debug msg="zeroconf server listening on port 44385" Oct 06 16:18:38 volumio volumio[4021]: info: Starting Shairport Sync Oct 06 16:18:38 volumio sudo[4178]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 06 16:18:38 volumio sudo[4178]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 06 16:18:38 volumio volumio[4021]: info: Starting Shairport Sync Oct 06 16:18:38 volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Oct 06 16:18:38 volumio systemd[1]: shairport-sync.service: Succeeded. Oct 06 16:18:38 volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Oct 06 16:18:38 volumio sudo[4181]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 06 16:18:38 volumio go-librespot[4161]: time="2024-10-06T16:18:38+02:00" level=debug msg="obtained new client token: AADKTXp4ttRe1mIQxw/TEo08/n5P4Vzv3IVjpFxhB7EZHOVkrF+PtRQIMpYplSrewlYwf8jlgOFaQHvZVE/Ca0wpvZOJN+dQ9K7F3DIeim3915qnqyaexjYWV/P/MN/dk0dFV2kJg5KHpKep+DeS0yAQ6rB/ZvFwctJfq4zMB4MmaRLK8gloEHtJVmJTiY7mg8nRAHdKiX2tBJE7E83uSZmtyge2Kht/0RigRTXLpONixge8LhxeItMxh1VIXw==" Oct 06 16:18:38 volumio volumio[4021]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Oct 06 16:18:38 volumio volumio[4021]: info: CoreCommandRouter::volumioGetState Oct 06 16:18:38 volumio volumio[4021]: info: CorePlayQueue::getTrack 0 Oct 06 16:18:38 volumio sudo[4181]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 06 16:18:38 volumio sudo[4185]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 06 16:18:38 volumio sudo[4185]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 06 16:18:38 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Oct 06 16:18:38 volumio sudo[4178]: pam_unix(sudo:session): session closed for user root Oct 06 16:18:39 volumio mpd[4121]: Oct 06 16:18 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Oct 06 16:18:39 volumio go-librespot[4161]: time="2024-10-06T16:18:39+02:00" level=warning msg="failed to connect to AP ap-gew4.spotify.com:4070 (error: dial tcp 34.158.1.133:4070: connect: connection refused), retrying with a different AP" Oct 06 16:18:39 volumio systemd[1]: Started Music Player Daemon. Oct 06 16:18:39 volumio sudo[4110]: pam_unix(sudo:session): session closed for user root Oct 06 16:18:39 volumio sudo[4099]: pam_unix(sudo:session): session closed for user root Oct 06 16:18:39 volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Oct 06 16:18:39 volumio systemd[1]: shairport-sync.service: Main process exited, code=killed, status=15/TERM Oct 06 16:18:39 volumio systemd[1]: shairport-sync.service: Succeeded. Oct 06 16:18:39 volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Oct 06 16:18:39 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Oct 06 16:18:39 volumio go-librespot[4161]: time="2024-10-06T16:18:39+02:00" level=info msg="connected to ap-gew4.spotify.com:443" Oct 06 16:18:39 volumio sudo[4185]: pam_unix(sudo:session): session closed for user root Oct 06 16:18:39 volumio sudo[4181]: pam_unix(sudo:session): session closed for user root Oct 06 16:18:39 volumio go-librespot[4161]: time="2024-10-06T16:18:39+02:00" level=debug msg="completed keyexchange" Oct 06 16:18:39 volumio volumio[4021]: info: CoreCommandRouter::volumioGetVisibleSources Oct 06 16:18:39 volumio volumio[4021]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 06 16:18:39 volumio volumio[4021]: info: CoreCommandRouter::volumioGetState Oct 06 16:18:39 volumio volumio[4021]: info: CorePlayQueue::getTrack 0 Oct 06 16:18:39 volumio volumio[4021]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Oct 06 16:18:39 volumio volumio[4021]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Oct 06 16:18:39 volumio volumio[4021]: info: Received Get System Info Oct 06 16:18:39 volumio volumio[4021]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 06 16:18:39 volumio volumio[4021]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 06 16:18:39 volumio volumio[4021]: info: Discovery: Getting this device information Oct 06 16:18:39 volumio volumio[4021]: info: CoreCommandRouter::volumioGetState Oct 06 16:18:39 volumio volumio[4021]: info: CorePlayQueue::getTrack 0 Oct 06 16:18:39 volumio volumio[4021]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 06 16:18:39 volumio volumio[4021]: info: CoreCommandRouter::volumioGetState Oct 06 16:18:39 volumio volumio[4021]: info: CorePlayQueue::getTrack 0 Oct 06 16:18:39 volumio volumio[4021]: info: Listing playlists Oct 06 16:18:39 volumio volumio[4021]: info: CoreCommandRouter::volumioGetQueue Oct 06 16:18:39 volumio volumio[4021]: info: CoreStateMachine::getQueue Oct 06 16:18:39 volumio volumio[4021]: info: CorePlayQueue::getQueue Oct 06 16:18:39 volumio volumio[4021]: info: Shairport-Sync Started Oct 06 16:18:39 volumio volumio[4021]: Error adding Membership: Error: addMembership EINVAL Oct 06 16:18:39 volumio volumio[4021]: info: Shairport-Sync Started Oct 06 16:18:39 volumio volumio[4021]: info: Completed starting Core Plugins Oct 06 16:18:39 volumio volumio[4021]: info: ------------------------------------------- Oct 06 16:18:39 volumio volumio[4021]: info: ----- MyVolumio plugins startup ---- Oct 06 16:18:39 volumio volumio[4021]: info: ------------------------------------------- Oct 06 16:18:39 volumio volumio[4021]: info: [MyVolumio PluginManager] Fetching plans data.... Oct 06 16:18:39 volumio volumio[4021]: info: Shairport-Sync Started Oct 06 16:18:39 volumio volumio[4021]: error: MPD error: The expression evaluated to a falsy value: Oct 06 16:18:39 volumio volumio[4021]: assert.ok(self.idling) Oct 06 16:18:39 volumio volumio[4021]: error: The expression evaluated to a falsy value: Oct 06 16:18:39 volumio volumio[4021]: assert.ok(self.idling) Oct 06 16:18:39 volumio volumio[4021]: info: MPD running with PID4121 Oct 06 16:18:39 volumio volumio[4021]: ,establishing connection Oct 06 16:18:39 volumio volumio[4021]: error: updateQueue error: null Oct 06 16:18:39 volumio volumio[4021]: error: updateQueue error: null Oct 06 16:18:39 volumio volumio[4021]: SPOTIFY: User informations: {"display_name":"gronk","external_urls":{"spotify":"https://open.spotify.com/user/gronk"},"href":"https://api.spotify.com/v1/users/gronk","id":"gronk","images":[],"type":"user","uri":"spotify:user:gronk","followers":{"href":null,"total":3},"country":"SE","product":"premium","explicit_content":{"filter_enabled":false,"filter_locked":false},"email":"maglar@me.com"} Oct 06 16:18:39 volumio volumio[4021]: info: Spotify Successfully logged in Oct 06 16:18:39 volumio volumio[4021]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 06 16:18:39 volumio volumio[4021]: info: [1728224319296] CoreMusicLibrary::Adding element Spotify Oct 06 16:18:39 volumio volumio[4021]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 06 16:18:39 volumio volumio[4021]: Cannot find translation for source Bandcamp Discover Oct 06 16:18:39 volumio volumio[4021]: Cannot find translation for source SoundCloud Oct 06 16:18:39 volumio volumio[4021]: Cannot find translation for source Spotify Oct 06 16:18:39 volumio go-librespot[4161]: time="2024-10-06T16:18:39+02:00" level=debug msg="completed challenge" Oct 06 16:18:39 volumio go-librespot[4161]: time="2024-10-06T16:18:39+02:00" level=debug msg="authenticated as gronk" Oct 06 16:18:39 volumio go-librespot[4161]: time="2024-10-06T16:18:39+02:00" level=debug msg="authenticated as gronk" Oct 06 16:18:39 volumio go-librespot[4161]: time="2024-10-06T16:18:39+02:00" level=debug msg="dealer connection opened" Oct 06 16:18:39 volumio go-librespot[4161]: time="2024-10-06T16:18:39+02:00" level=debug msg="initializing zeroconf session, username: gronk" Oct 06 16:18:39 volumio go-librespot[4161]: time="2024-10-06T16:18:39+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Oct 06 16:18:39 volumio go-librespot[4161]: time="2024-10-06T16:18:39+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Oct 06 16:18:39 volumio go-librespot[4161]: time="2024-10-06T16:18:39+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Oct 06 16:18:39 volumio go-librespot[4161]: time="2024-10-06T16:18:39+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Oct 06 16:18:39 volumio go-librespot[4161]: time="2024-10-06T16:18:39+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 493" Oct 06 16:18:39 volumio volumio[4021]: info: Cannot mount NAS Diskstation at system boot, trial number 2 ,retrying in 5 seconds Oct 06 16:18:39 volumio go-librespot[4161]: time="2024-10-06T16:18:39+02:00" level=debug msg="autoplay enabled: false" Oct 06 16:18:39 volumio go-librespot[4161]: time="2024-10-06T16:18:39+02:00" level=debug msg="received connection id: NWE2MzMxMGUtYmE1OS00ZjkzLTlmOTMtNWZkZmE4MTBkMDAyK2RlYWxlcit0Y3A6Ly8wYWNhNTg4Yy5pcC5nZXc0LnNwb3RpZnkubmV0OjU3MDArREMwQjg5NzUxMjkyQzU3NjI2NjdDM0RFNjAwQTkxRkQxODM2NTIyQkZEMEMwQzhGNUVCRDY3ODY3MUU5ODc0Qg==" Oct 06 16:18:41 volumio volumio[4021]: info: go-librespot daemon successfully initialized Oct 06 16:18:44 volumio volumio[4021]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Oct 06 16:18:44 volumio volumio[4021]: info: Initializing connection to go-librespot Websocket Oct 06 16:18:44 volumio go-librespot[4161]: time="2024-10-06T16:18:44+02:00" level=debug msg="new websocket client" Oct 06 16:18:44 volumio volumio[4021]: info: Connection to go-librespot Websocket established Oct 06 16:18:44 volumio volumio[4021]: info: Cannot mount NAS Diskstation at system boot, trial number 3 ,retrying in 5 seconds Oct 06 16:18:44 volumio sudo[4197]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 06 16:18:44 volumio sudo[4197]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 06 16:18:44 volumio sudo[4197]: pam_unix(sudo:session): session closed for user root Oct 06 16:18:44 volumio sudo[4200]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 06 16:18:44 volumio sudo[4200]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 06 16:18:44 volumio sudo[4200]: pam_unix(sudo:session): session closed for user root Oct 06 16:18:44 volumio sudo[4203]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Oct 06 16:18:44 volumio sudo[4203]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 06 16:18:45 volumio systemd[1]: Started UPnP Renderer front-end to MPD. Oct 06 16:18:45 volumio sudo[4203]: pam_unix(sudo:session): session closed for user root Oct 06 16:18:45 volumio volumio[4021]: info: Upmpdcli Daemon Started Oct 06 16:18:45 volumio volumio[4205]: writing RSA key Oct 06 16:18:45 volumio go-librespot[4161]: time="2024-10-06T16:18:45+02:00" level=debug msg="put connect state because NEW_DEVICE" Oct 06 16:18:47 volumio volumio[4021]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Oct 06 16:18:47 volumio volumio[4021]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Oct 06 16:18:47 volumio volumio[4021]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Oct 06 16:18:47 volumio volumio[4021]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Oct 06 16:18:47 volumio volumio[4021]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Oct 06 16:18:47 volumio volumio[4021]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Oct 06 16:18:47 volumio volumio[4021]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Oct 06 16:18:47 volumio volumio[4021]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Oct 06 16:18:47 volumio volumio[4021]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Oct 06 16:18:47 volumio volumio[4021]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Oct 06 16:18:47 volumio volumio[4021]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Oct 06 16:18:47 volumio volumio[4021]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Oct 06 16:18:47 volumio volumio[4021]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Oct 06 16:18:47 volumio volumio[4021]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Oct 06 16:18:47 volumio volumio[4021]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Oct 06 16:18:47 volumio volumio[4021]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Oct 06 16:18:47 volumio volumio[4021]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Oct 06 16:18:47 volumio volumio[4021]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Oct 06 16:18:47 volumio volumio[4021]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Oct 06 16:18:47 volumio volumio[4021]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Oct 06 16:18:47 volumio volumio[4021]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Oct 06 16:18:47 volumio volumio[4021]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Oct 06 16:18:47 volumio volumio[4021]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Oct 06 16:18:47 volumio volumio[4021]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Oct 06 16:18:47 volumio volumio[4021]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Oct 06 16:18:47 volumio volumio[4021]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Oct 06 16:18:47 volumio volumio[4021]: info: Adding plugin bluetooth to MyMusic Plugins Oct 06 16:18:47 volumio volumio[4021]: info: Adding plugin multiroom to MyMusic Plugins Oct 06 16:18:47 volumio volumio[4021]: info: Adding plugin metavolumio to MyMusic Plugins Oct 06 16:18:47 volumio volumio[4021]: info: Adding plugin cd_controller to MyMusic Plugins Oct 06 16:18:47 volumio volumio[4021]: info: Adding plugin smart_inputs to MyMusic Plugins Oct 06 16:18:47 volumio volumio[4021]: info: Adding plugin tidalconnect to MyMusic Plugins Oct 06 16:18:47 volumio volumio[4021]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Oct 06 16:18:48 volumio volumio[4021]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Oct 06 16:18:48 volumio volumio[4021]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Oct 06 16:18:48 volumio volumio[4021]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 06 16:18:48 volumio volumio[4021]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 06 16:18:48 volumio volumio[4021]: info: Starting MyVolumio Remote Streaming Endpoints Oct 06 16:18:48 volumio volumio[4021]: info: MyVolumio login type: Token Oct 06 16:18:48 volumio volumio[4021]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Oct 06 16:18:48 volumio volumio[4021]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Oct 06 16:18:48 volumio volumio[4021]: info: Starting Streaming Service Transparent Proxy Oct 06 16:18:48 volumio volumio[4021]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Oct 06 16:18:48 volumio volumio[4021]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Oct 06 16:18:48 volumio volumio[4021]: info: Streaming services startup Oct 06 16:18:48 volumio volumio[4021]: info: Starting Streaming Daemon Oct 06 16:18:48 volumio sudo[4249]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Oct 06 16:18:48 volumio sudo[4249]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 06 16:18:48 volumio sudo[4249]: pam_unix(sudo:session): session closed for user root Oct 06 16:18:48 volumio volumio[4021]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Oct 06 16:18:48 volumio volumio[4021]: info: Getting Spotify volume Oct 06 16:18:48 volumio volumio[4021]: error: Cannot start Volumio Streaming Daemon Oct 06 16:18:48 volumio volumio[4021]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Oct 06 16:18:48 volumio volumio[4021]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Oct 06 16:18:48 volumio volumio[4021]: info: Spotify volume: 100 Oct 06 16:18:48 volumio volumio[4021]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 6 Oct 06 16:18:49 volumio volumio[4021]: info: CoreCommandRouter::volumioGetState Oct 06 16:18:49 volumio volumio[4021]: info: CorePlayQueue::getTrack 0 Oct 06 16:18:49 volumio volumio[4021]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Oct 06 16:18:49 volumio volumio[4021]: STREAMING PROXY: Starting server on port 3245 Oct 06 16:18:49 volumio volumio[4021]: Node JS runtime: 14 Oct 06 16:18:49 volumio volumio[4021]: info: Cannot mount NAS Diskstation at system boot, trial number 4 ,retrying in 5 seconds Oct 06 16:18:49 volumio volumio[4021]: info: MyVolumio token set successfully Oct 06 16:18:49 volumio volumio[4021]: info: MYVOLUMIO: Adding device Oct 06 16:18:49 volumio volumio[4021]: info: MYVOLUMIO: Evaluating Server Oct 06 16:18:50 volumio volumio[4021]: info: MyVolumio status changed Oct 06 16:18:50 volumio volumio[4021]: info: Streaming services startup Oct 06 16:18:50 volumio volumio[4021]: info: Starting Streaming Daemon Oct 06 16:18:50 volumio volumio[4021]: info: Removing browser output: myVolumio user plan is not superstar Oct 06 16:18:50 volumio volumio[4021]: info: Removing audio output: Oct 06 16:18:50 volumio volumio[4021]: info: Stoppping Tunnel 1 Oct 06 16:18:50 volumio sudo[4275]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Oct 06 16:18:50 volumio sudo[4275]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 06 16:18:50 volumio sudo[4275]: pam_unix(sudo:session): session closed for user root Oct 06 16:18:50 volumio volumio[4021]: error: Cannot start Volumio Streaming Daemon Oct 06 16:18:50 volumio volumio[4021]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Oct 06 16:18:50 volumio volumio[4021]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Oct 06 16:18:50 volumio sudo[4278]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service Oct 06 16:18:50 volumio sudo[4278]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 06 16:18:50 volumio sudo[4278]: pam_unix(sudo:session): session closed for user root Oct 06 16:18:50 volumio volumio[4021]: info: Remote SSH Stopped Oct 06 16:18:50 volumio volumio[4021]: info: CoreCommandRouter::getUIConfigOnPlugin Oct 06 16:18:50 volumio volumio[4021]: info: CoreCommandRouter::getUIConfigOnPlugin Oct 06 16:18:50 volumio volumio[4021]: info: Retrieving Cloud Streaming UI Oct 06 16:18:50 volumio volumio[4021]: info: Getting Tidal Cloud Configuration Oct 06 16:18:50 volumio volumio[4021]: info: CoreCommandRouter::getUIConfigOnPlugin Oct 06 16:18:50 volumio volumio[4021]: info: Getting Qobuz Cloud Configuration Oct 06 16:18:50 volumio volumio[4021]: info: Asking plugin for UI Config Oct 06 16:18:50 volumio volumio[4021]: info: CoreCommandRouter::getUIConfigOnPlugin Oct 06 16:18:50 volumio volumio[4021]: info: Getting Spotify Cloud Configuration Oct 06 16:18:50 volumio volumio[4021]: info: Asking plugin for UI Config Oct 06 16:18:50 volumio volumio[4021]: info: CoreCommandRouter::getUIConfigOnPlugin Oct 06 16:18:50 volumio volumio[4021]: info: Saving Spotify Acccount Oct 06 16:18:50 volumio volumio[4021]: info: Got Tidal Cloud Configuration Oct 06 16:18:50 volumio volumio[4021]: info: Got it Oct 06 16:18:50 volumio volumio[4021]: info: Got it Oct 06 16:18:50 volumio volumio[4021]: error: Could not retrieve Spotify Config from plugin Spotify: no section found Oct 06 16:18:50 volumio volumio[4021]: info: CoreCommandRouter::getUIConfigOnPlugin Oct 06 16:18:50 volumio volumio[4021]: error: Error retrieving Highresaudio conf: TypeError: Cannot read property 'onSave' of undefined Oct 06 16:18:50 volumio volumio[4021]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus Oct 06 16:18:50 volumio volumio[4021]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Oct 06 16:18:50 volumio volumio[4021]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Oct 06 16:18:50 volumio volumio[4021]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Oct 06 16:18:50 volumio volumio[4021]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 06 16:18:50 volumio volumio[4021]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 06 16:18:50 volumio volumio[4021]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 06 16:18:50 volumio volumio[4021]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 06 16:18:50 volumio volumio[4021]: info: CoreCommandRouter::volumioGetBrowseSources Oct 06 16:18:50 volumio volumio[4021]: info: CoreCommandRouter::volumioGetBrowseSources Oct 06 16:18:50 volumio volumio[4021]: info: CoreCommandRouter::volumioGetBrowseSources Oct 06 16:18:50 volumio volumio[4021]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Oct 06 16:18:50 volumio volumio[4021]: info: CoreCommandRouter::executeOnPlugin: networkfs , listShares Oct 06 16:18:54 volumio volumio[4021]: info: CoreCommandRouter::executeOnPlugin: networkfs , deleteShare Oct 06 16:18:54 volumio volumio[4021]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Oct 06 16:18:54 volumio sudo[4284]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/umount /mnt/NAS/Diskstation Oct 06 16:18:54 volumio sudo[4284]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 06 16:18:54 volumio systemd[1]: mnt-NAS-Diskstation.mount: Succeeded. Oct 06 16:18:54 volumio sudo[4288]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t nfs -o ro,soft,noauto 192.168.2.64:/volume1/Music /mnt/NAS/Diskstation Oct 06 16:18:54 volumio sudo[4288]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 06 16:18:54 volumio sudo[4284]: pam_unix(sudo:session): session closed for user root Oct 06 16:18:54 volumio volumio[4021]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 06 16:18:54 volumio volumio[4021]: Error: EBUSY: resource busy or locked, rmdir '/mnt/NAS/Diskstation' Oct 06 16:18:54 volumio volumio[4021]: at Object.rmdirSync (fs.js:890:10) Oct 06 16:18:54 volumio volumio[4021]: at /volumio/node_modules/linux-mountutils/mountutils.js:178:12 Oct 06 16:18:54 volumio volumio[4021]: at ChildProcess.exithandler (child_process.js:299:7) Oct 06 16:18:54 volumio volumio[4021]: at ChildProcess.emit (events.js:315:20) Oct 06 16:18:54 volumio volumio[4021]: at maybeClose (internal/child_process.js:1048:16) Oct 06 16:18:54 volumio volumio[4021]: at Process.ChildProcess._handle.onexit (internal/child_process.js:288:5) { Oct 06 16:18:54 volumio volumio[4021]: errno: -16, Oct 06 16:18:54 volumio volumio[4021]: syscall: 'rmdir', Oct 06 16:18:54 volumio volumio[4021]: code: 'EBUSY', Oct 06 16:18:54 volumio volumio[4021]: path: '/mnt/NAS/Diskstation' Oct 06 16:18:54 volumio volumio[4021]: } Oct 06 16:18:54 volumio volumio[4021]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 06 16:18:54 volumio sudo[4288]: pam_unix(sudo:session): session closed for user root Oct 06 16:18:55 volumio sudo[4304]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-10-06 16:17 Oct 06 16:18:55 volumio sudo[4304]: 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="bba9e3185e150dd0995f9a49355b34fc6218d5a2" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="8aa57e3ae5b742ea1069404608336a9884ccfb4e" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue 17 Sep 2024 05:01:09 PM CEST" VOLUMIO_VERSION="3.757" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="e0a6dc7e914e3fb93cbf2123f2f73eac"