-- Logs begin at Thu 2019-02-14 11:11:59 CET, end at Sun 2024-10-06 16:18:19 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) 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"