-- Logs begin at Thu 2019-02-14 11:11:59 CET, end at Sun 2025-06-01 16:45:09 CEST. -- Jun 01 16:44:00 volumiokeller ntpd[753]: Listen normally on 24 wlan0 192.168.178.130:123 Jun 01 16:44:00 volumiokeller ntpd[753]: new interface(s) found: waking up resolver Jun 01 16:44:08 volumiokeller volumio[14464]: info: Volumio Network Manager: Network status updated: 2 Jun 01 16:44:15 volumiokeller wpa_supplicant[849]: wlan0: CTRL-EVENT-DISCONNECTED bssid=b0:f2:08:ec:0b:28 reason=34 Jun 01 16:44:15 volumiokeller dhcpcd[861]: wlan0: carrier lost Jun 01 16:44:15 volumiokeller wpa_supplicant[849]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=CORE type=WORLD Jun 01 16:44:15 volumiokeller wpa_supplicant[849]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=USER type=COUNTRY alpha2=DE Jun 01 16:44:15 volumiokeller avahi-daemon[547]: Withdrawing address record for 192.168.178.130 on wlan0. Jun 01 16:44:15 volumiokeller avahi-daemon[547]: Leaving mDNS multicast group on interface wlan0.IPv4 with address 192.168.178.130. Jun 01 16:44:15 volumiokeller avahi-daemon[547]: Interface wlan0.IPv4 no longer relevant for mDNS. Jun 01 16:44:15 volumiokeller dhcpcd[861]: wlan0: deleting route to 192.168.178.0/24 Jun 01 16:44:15 volumiokeller dhcpcd[861]: wlan0: deleting default route via 192.168.178.1 Jun 01 16:44:15 volumiokeller volumio[14464]: info: Discovery: A device disappeared from network Jun 01 16:44:15 volumiokeller volumio[14464]: info: Discovery: A device disappeared from network Jun 01 16:44:15 volumiokeller volumio[14464]: info: Discovery: Device volumiosimon disappeared from network Jun 01 16:44:15 volumiokeller volumio[14464]: info: Discovery: A device disappeared from network Jun 01 16:44:17 volumiokeller kernel: brcmfmac: brcmf_set_channel: set chanspec 0xd022 fail, reason -52 Jun 01 16:44:17 volumiokeller ntpd[753]: Deleting interface #24 wlan0, 192.168.178.130#123, interface stats: received=0, sent=12, dropped=0, active_time=17 secs Jun 01 16:44:17 volumiokeller ntpd[753]: 195.201.20.16 local addr 192.168.178.130 -> Jun 01 16:44:17 volumiokeller ntpd[753]: 116.203.244.102 local addr 192.168.178.130 -> Jun 01 16:44:17 volumiokeller ntpd[753]: 78.46.87.46 local addr 192.168.178.130 -> Jun 01 16:44:17 volumiokeller ntpd[753]: 81.3.27.46 local addr 192.168.178.130 -> Jun 01 16:44:17 volumiokeller ntpd[753]: 158.180.28.150 local addr 192.168.178.130 -> Jun 01 16:44:17 volumiokeller ntpd[753]: 148.251.235.164 local addr 192.168.178.130 -> Jun 01 16:44:17 volumiokeller ntpd[753]: 178.215.228.24 local addr 192.168.178.130 -> Jun 01 16:44:17 volumiokeller ntpd[753]: 144.76.76.107 local addr 192.168.178.130 -> Jun 01 16:44:17 volumiokeller ntpd[753]: 144.76.43.40 local addr 192.168.178.130 -> Jun 01 16:44:17 volumiokeller ntpd[753]: 144.76.66.156 local addr 192.168.178.130 -> Jun 01 16:44:17 volumiokeller ntpd[753]: 107.189.12.98 local addr 192.168.178.130 -> Jun 01 16:44:17 volumiokeller ntpd[753]: 79.133.44.138 local addr 192.168.178.130 -> Jun 01 16:44:17 volumiokeller kernel: brcmfmac: brcmf_set_channel: set chanspec 0xd026 fail, reason -52 Jun 01 16:44:17 volumiokeller kernel: brcmfmac: brcmf_set_channel: set chanspec 0xd02a fail, reason -52 Jun 01 16:44:17 volumiokeller kernel: brcmfmac: brcmf_set_channel: set chanspec 0xd02e fail, reason -52 Jun 01 16:44:18 volumiokeller volumio[14464]: info: Volumio Network Manager: Network status updated: 0 Jun 01 16:44:19 volumiokeller wpa_supplicant[849]: wlan0: Trying to associate with SSID 'FRITZ!Box 5590 SF' Jun 01 16:44:19 volumiokeller kernel: brcmfmac: brcmf_set_channel: set chanspec 0xd090 fail, reason -52 Jun 01 16:44:19 volumiokeller kernel: brcmfmac: brcmf_set_channel: set chanspec 0xd095 fail, reason -52 Jun 01 16:44:19 volumiokeller kernel: brcmfmac: brcmf_set_channel: set chanspec 0xd099 fail, reason -52 Jun 01 16:44:19 volumiokeller kernel: brcmfmac: brcmf_set_channel: set chanspec 0xd09d fail, reason -52 Jun 01 16:44:19 volumiokeller kernel: brcmfmac: brcmf_set_channel: set chanspec 0xd0a1 fail, reason -52 Jun 01 16:44:19 volumiokeller kernel: brcmfmac: brcmf_set_channel: set chanspec 0xd0a5 fail, reason -52 Jun 01 16:44:19 volumiokeller dhcpcd[861]: wlan0: carrier acquired Jun 01 16:44:19 volumiokeller wpa_supplicant[849]: wlan0: Associated with b0:f2:08:ec:0b:29 Jun 01 16:44:19 volumiokeller wpa_supplicant[849]: wlan0: CTRL-EVENT-CONNECTED - Connection to b0:f2:08:ec:0b:29 completed [id=0 id_str=] Jun 01 16:44:19 volumiokeller wpa_supplicant[849]: wlan0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0 Jun 01 16:44:19 volumiokeller wpa_supplicant[849]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=COUNTRY_IE type=COUNTRY alpha2=DE Jun 01 16:44:19 volumiokeller dhcpcd[861]: wlan0: IAID eb:25:9d:91 Jun 01 16:44:19 volumiokeller dhcpcd[861]: wlan0: carrier lost Jun 01 16:44:19 volumiokeller dhcpcd[861]: wlan0: carrier acquired Jun 01 16:44:19 volumiokeller dhcpcd[861]: wlan0: IAID eb:25:9d:91 Jun 01 16:44:19 volumiokeller dhcpcd[861]: wlan0: soliciting an IPv6 router Jun 01 16:44:20 volumiokeller dhcpcd[861]: wlan0: rebinding lease of 192.168.178.130 Jun 01 16:44:20 volumiokeller dhcpcd[861]: wlan0: probing address 192.168.178.130/24 Jun 01 16:44:21 volumiokeller wpa_supplicant[849]: RRM: Ignoring radio measurement request: Not RRM network Jun 01 16:44:23 volumiokeller volumio[14464]: info: Discovery: Browse raised the following error Error: getaddrinfo -3008 Jun 01 16:44:23 volumiokeller volumio[14464]: info: Discovery: Browse raised the following error Error: getaddrinfo -3008 Jun 01 16:44:23 volumiokeller wpa_supplicant[849]: RRM: Ignoring radio measurement request: Not RRM network Jun 01 16:44:25 volumiokeller dhcpcd[861]: wlan0: leased 192.168.178.130 for 864000 seconds Jun 01 16:44:25 volumiokeller avahi-daemon[547]: Joining mDNS multicast group on interface wlan0.IPv4 with address 192.168.178.130. Jun 01 16:44:25 volumiokeller dhcpcd[861]: wlan0: adding route to 192.168.178.0/24 Jun 01 16:44:25 volumiokeller dhcpcd[861]: wlan0: adding default route via 192.168.178.1 Jun 01 16:44:25 volumiokeller avahi-daemon[547]: New relevant interface wlan0.IPv4 for mDNS. Jun 01 16:44:25 volumiokeller avahi-daemon[547]: Registering new address record for 192.168.178.130 on wlan0.IPv4. Jun 01 16:44:25 volumiokeller volumio[14464]: verbose: New Socket.io Connection to 192.168.178.130:3000 from 192.168.178.41 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Jun 01 16:44:25 volumiokeller volumio[14464]: verbose: New Socket.io Connection to 192.168.178.130:3000 from 192.168.178.41 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 9 Jun 01 16:44:25 volumiokeller volumio[14464]: verbose: New Socket.io Connection to 192.168.178.130:3000 from 192.168.178.143 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 10 Jun 01 16:44:25 volumiokeller volumio[14464]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , initSocket Jun 01 16:44:25 volumiokeller volumio[14464]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , initSocket Jun 01 16:44:25 volumiokeller volumio[14464]: info: CoreCommandRouter::volumioGetState Jun 01 16:44:25 volumiokeller volumio[14464]: info: CorePlayQueue::getTrack 0 Jun 01 16:44:25 volumiokeller volumio[14464]: info: CoreCommandRouter::volumioGetState Jun 01 16:44:25 volumiokeller volumio[14464]: info: CorePlayQueue::getTrack 0 Jun 01 16:44:25 volumiokeller volumio[14464]: verbose: New Socket.io Connection to 192.168.178.130:3000 from 192.168.178.143 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 10 Jun 01 16:44:26 volumiokeller volumio[14464]: info: Discovery: adding 21153d5e-c4d4-47e4-a187-1149c660bae3 Jun 01 16:44:26 volumiokeller volumio[14464]: info: Discovery: Found device VolumioKeller Jun 01 16:44:26 volumiokeller volumio[14464]: info: CoreCommandRouter::volumioGetState Jun 01 16:44:26 volumiokeller volumio[14464]: info: CorePlayQueue::getTrack 0 Jun 01 16:44:26 volumiokeller ntpd[753]: Listen normally on 25 wlan0 192.168.178.130:123 Jun 01 16:44:26 volumiokeller ntpd[753]: new interface(s) found: waking up resolver Jun 01 16:44:28 volumiokeller wpa_supplicant[849]: RRM: Ignoring radio measurement request: Not RRM network Jun 01 16:44:28 volumiokeller dhcpcd[861]: wlan0: carrier lost Jun 01 16:44:28 volumiokeller wpa_supplicant[849]: wlan0: Associated with b0:f2:08:ec:0b:28 Jun 01 16:44:28 volumiokeller wpa_supplicant[849]: wlan0: CTRL-EVENT-CONNECTED - Connection to b0:f2:08:ec:0b:28 completed [id=0 id_str=] Jun 01 16:44:28 volumiokeller wpa_supplicant[849]: wlan0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0 Jun 01 16:44:28 volumiokeller avahi-daemon[547]: Withdrawing address record for 192.168.178.130 on wlan0. Jun 01 16:44:28 volumiokeller avahi-daemon[547]: Leaving mDNS multicast group on interface wlan0.IPv4 with address 192.168.178.130. Jun 01 16:44:28 volumiokeller avahi-daemon[547]: Interface wlan0.IPv4 no longer relevant for mDNS. Jun 01 16:44:28 volumiokeller dhcpcd[861]: wlan0: deleting route to 192.168.178.0/24 Jun 01 16:44:28 volumiokeller dhcpcd[861]: wlan0: deleting default route via 192.168.178.1 Jun 01 16:44:28 volumiokeller volumio[14464]: info: Discovery: A device disappeared from network Jun 01 16:44:28 volumiokeller volumio[14464]: info: Discovery: Device volumiokeller disappeared from network Jun 01 16:44:28 volumiokeller dhcpcd[861]: wlan0: carrier acquired Jun 01 16:44:28 volumiokeller dhcpcd[861]: wlan0: IAID eb:25:9d:91 Jun 01 16:44:28 volumiokeller dhcpcd[861]: wlan0: soliciting an IPv6 router Jun 01 16:44:29 volumiokeller dhcpcd[861]: wlan0: rebinding lease of 192.168.178.130 Jun 01 16:44:29 volumiokeller dhcpcd[861]: wlan0: probing address 192.168.178.130/24 Jun 01 16:44:30 volumiokeller volumio[14464]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jun 01 16:44:30 volumiokeller volumio[14464]: Error: send ENETUNREACH 255.255.255.255:3483 Jun 01 16:44:30 volumiokeller volumio[14464]: at doSend (dgram.js:692:16) Jun 01 16:44:30 volumiokeller volumio[14464]: at defaultTriggerAsyncIdScope (internal/async_hooks.js:430:12) Jun 01 16:44:30 volumiokeller volumio[14464]: at afterDns (dgram.js:638:5) Jun 01 16:44:30 volumiokeller volumio[14464]: at processTicksAndRejections (internal/process/task_queues.js:81:21) { Jun 01 16:44:30 volumiokeller volumio[14464]: errno: -101, Jun 01 16:44:30 volumiokeller volumio[14464]: code: 'ENETUNREACH', Jun 01 16:44:30 volumiokeller volumio[14464]: syscall: 'send', Jun 01 16:44:30 volumiokeller volumio[14464]: address: '255.255.255.255', Jun 01 16:44:30 volumiokeller volumio[14464]: port: 3483 Jun 01 16:44:30 volumiokeller volumio[14464]: } Jun 01 16:44:30 volumiokeller volumio[14464]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jun 01 16:44:30 volumiokeller ntpd[753]: Deleting interface #25 wlan0, 192.168.178.130#123, interface stats: received=3, sent=5, dropped=7, active_time=4 secs Jun 01 16:44:30 volumiokeller ntpd[753]: 195.201.20.16 local addr 192.168.178.130 -> Jun 01 16:44:30 volumiokeller ntpd[753]: 116.203.244.102 local addr 192.168.178.130 -> Jun 01 16:44:30 volumiokeller ntpd[753]: 78.46.87.46 local addr 192.168.178.130 -> Jun 01 16:44:30 volumiokeller ntpd[753]: 81.3.27.46 local addr 192.168.178.130 -> Jun 01 16:44:30 volumiokeller ntpd[753]: 158.180.28.150 local addr 192.168.178.130 -> Jun 01 16:44:30 volumiokeller ntpd[753]: 148.251.235.164 local addr 192.168.178.130 -> Jun 01 16:44:30 volumiokeller ntpd[753]: 178.215.228.24 local addr 192.168.178.130 -> Jun 01 16:44:30 volumiokeller ntpd[753]: 144.76.76.107 local addr 192.168.178.130 -> Jun 01 16:44:30 volumiokeller ntpd[753]: 144.76.43.40 local addr 192.168.178.130 -> Jun 01 16:44:30 volumiokeller ntpd[753]: 144.76.66.156 local addr 192.168.178.130 -> Jun 01 16:44:30 volumiokeller ntpd[753]: 107.189.12.98 local addr 192.168.178.130 -> Jun 01 16:44:30 volumiokeller ntpd[753]: 79.133.44.138 local addr 192.168.178.130 -> Jun 01 16:44:30 volumiokeller sudo[18030]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-06-01 16:43 Jun 01 16:44:30 volumiokeller sudo[18030]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 01 16:44:30 volumiokeller sudo[18030]: pam_unix(sudo:session): session closed for user root Jun 01 16:44:30 volumiokeller volumio-remote-updater[554]: [2025-06-01 16:44:30] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Jun 01 16:44:30 volumiokeller volumio-remote-updater[554]: [2025-06-01 16:44:30] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Jun 01 16:44:30 volumiokeller systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Jun 01 16:44:30 volumiokeller go-librespot[14677]: time="2025-06-01T16:44:30+02:00" level=error msg="websocket connection errored" error="failed to get reader: failed to read frame header: EOF" Jun 01 16:44:30 volumiokeller systemd[1]: volumio.service: Failed with result 'exit-code'. Jun 01 16:44:30 volumiokeller systemd[1]: Started dynamicswap service. Jun 01 16:44:30 volumiokeller systemd[1]: dynamicswap.service: Succeeded. Jun 01 16:44:31 volumiokeller systemd[1]: volumio.service: Service RestartSec=100ms expired, scheduling restart. Jun 01 16:44:31 volumiokeller systemd[1]: volumio.service: Scheduled restart job, restart counter is at 18. Jun 01 16:44:31 volumiokeller systemd[1]: Stopped Volumio Backend Module. Jun 01 16:44:31 volumiokeller systemd[1]: Started Volumio Backend Module. Jun 01 16:44:31 volumiokeller systemd[1]: Started dynamicswap service. Jun 01 16:44:31 volumiokeller systemd[1]: dynamicswap.service: Succeeded. Jun 01 16:44:31 volumiokeller go-librespot[14677]: time="2025-06-01T16:44:31+02:00" level=error msg="did not receive last pong from dealer, 60s passed" Jun 01 16:44:32 volumiokeller volumio[18044]: info: ------------------------------------------- Jun 01 16:44:32 volumiokeller volumio[18044]: info: ----- Volumio3 ---- Jun 01 16:44:32 volumiokeller volumio[18044]: info: ------------------------------------------- Jun 01 16:44:32 volumiokeller volumio[18044]: info: ----- System startup ---- Jun 01 16:44:32 volumiokeller volumio[18044]: info: ------------------------------------------- Jun 01 16:44:33 volumiokeller volumio[18044]: info: MYVOLUMIO Environment detected Jun 01 16:44:33 volumiokeller volumio[18044]: info: Plugin folders cleanup Jun 01 16:44:33 volumiokeller volumio[18044]: info: Scanning into folder /volumio/app/plugins/ Jun 01 16:44:33 volumiokeller volumio[18044]: info: Scanning category audio_interface Jun 01 16:44:33 volumiokeller volumio[18044]: info: Scanning category miscellanea Jun 01 16:44:33 volumiokeller volumio[18044]: info: Scanning category music_service Jun 01 16:44:33 volumiokeller volumio[18044]: info: Scanning category plugins.json Jun 01 16:44:33 volumiokeller volumio[18044]: info: Scanning category system_controller Jun 01 16:44:33 volumiokeller volumio[18044]: info: Scanning category user_interface Jun 01 16:44:33 volumiokeller volumio[18044]: info: Scanning into folder /data/plugins/ Jun 01 16:44:33 volumiokeller volumio[18044]: info: Scanning category music_service Jun 01 16:44:33 volumiokeller volumio[18044]: info: Plugin folders cleanup completed Jun 01 16:44:33 volumiokeller volumio[18044]: info: ------------------------------------------- Jun 01 16:44:33 volumiokeller volumio[18044]: info: ----- Core plugins startup ---- Jun 01 16:44:33 volumiokeller volumio[18044]: info: ------------------------------------------- Jun 01 16:44:33 volumiokeller volumio[18044]: info: Loading plugins from folder /volumio/app/plugins/ Jun 01 16:44:33 volumiokeller volumio[18044]: info: Adding plugin upnp to MyMusic Plugins Jun 01 16:44:33 volumiokeller volumio[18044]: info: Adding plugin airplay_emulation to MyMusic Plugins Jun 01 16:44:33 volumiokeller volumio[18044]: info: Adding plugin upnp_browser to MyMusic Plugins Jun 01 16:44:33 volumiokeller volumio[18044]: info: Loading plugins from folder /data/plugins/ Jun 01 16:44:33 volumiokeller volumio[18044]: info: Loading plugin "system"... Jun 01 16:44:33 volumiokeller volumio[18044]: info: Loading plugin "appearance"... Jun 01 16:44:34 volumiokeller volumio[18044]: info: Loading plugin "network"... Jun 01 16:44:34 volumiokeller volumio[18044]: info: Refreshing Cached IP Addresses Jun 01 16:44:34 volumiokeller sudo[18074]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jun 01 16:44:34 volumiokeller sudo[18074]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 01 16:44:34 volumiokeller sudo[18074]: pam_unix(sudo:session): session closed for user root Jun 01 16:44:34 volumiokeller sudo[18076]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jun 01 16:44:34 volumiokeller sudo[18076]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 01 16:44:34 volumiokeller sudo[18076]: pam_unix(sudo:session): session closed for user root Jun 01 16:44:34 volumiokeller volumio[18044]: info: Loading plugin "services"... Jun 01 16:44:34 volumiokeller volumio[18044]: info: Loading plugin "alsa_controller"... Jun 01 16:44:34 volumiokeller sudo[18086]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Jun 01 16:44:34 volumiokeller sudo[18086]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 01 16:44:34 volumiokeller volumio[18044]: warn: Unable to locate the audio output device Allo BOSS. Please configure a valid output device. Jun 01 16:44:34 volumiokeller volumio[18044]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jun 01 16:44:34 volumiokeller volumio[18044]: info: Loading plugin "wizard"... Jun 01 16:44:34 volumiokeller volumio[18044]: info: Loading plugin "networkfs"... Jun 01 16:44:34 volumiokeller volumio[18044]: info: Starting Udev Watcher for removable devices Jun 01 16:44:34 volumiokeller volumio[18044]: info: Ignoring mount for partition: boot Jun 01 16:44:34 volumiokeller volumio[18044]: info: Ignoring mount for partition: volumio Jun 01 16:44:34 volumiokeller volumio[18044]: info: Ignoring mount for partition: volumio_data Jun 01 16:44:34 volumiokeller volumio[18044]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jun 01 16:44:34 volumiokeller volumio[18044]: info: Loading plugin "volumio_command_line_client"... Jun 01 16:44:34 volumiokeller volumio[18044]: info: Loading plugin "upnp"... Jun 01 16:44:34 volumiokeller volumio[18044]: info: [1748789074483] Starting Upmpd Daemon Jun 01 16:44:34 volumiokeller volumio[18044]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jun 01 16:44:34 volumiokeller volumio[18044]: info: Loading plugin "my_music"... Jun 01 16:44:34 volumiokeller volumio[18044]: info: Loading plugin "mpd"... Jun 01 16:44:34 volumiokeller volumio[18044]: info: Loading plugin "upnp_browser"... Jun 01 16:44:34 volumiokeller dhcpcd[861]: wlan0: leased 192.168.178.130 for 864000 seconds Jun 01 16:44:35 volumiokeller avahi-daemon[547]: Joining mDNS multicast group on interface wlan0.IPv4 with address 192.168.178.130. Jun 01 16:44:35 volumiokeller dhcpcd[861]: wlan0: adding route to 192.168.178.0/24 Jun 01 16:44:35 volumiokeller dhcpcd[861]: wlan0: adding default route via 192.168.178.1 Jun 01 16:44:35 volumiokeller avahi-daemon[547]: New relevant interface wlan0.IPv4 for mDNS. Jun 01 16:44:35 volumiokeller avahi-daemon[547]: Registering new address record for 192.168.178.130 on wlan0.IPv4. Jun 01 16:44:35 volumiokeller volumio[18044]: info: Loading plugin "alarm-clock"... Jun 01 16:44:35 volumiokeller volumio[18044]: info: Loading plugin "airplay_emulation"... Jun 01 16:44:35 volumiokeller volumio[18044]: info: Starting Shairport Sync Jun 01 16:44:35 volumiokeller volumio[18044]: info: Loading plugin "last_100"... Jun 01 16:44:35 volumiokeller volumio[18044]: info: Loading plugin "webradio"... Jun 01 16:44:35 volumiokeller volumio[18044]: info: Loading plugin "i2s_dacs"... Jun 01 16:44:35 volumiokeller volumio[18044]: info: Loading plugin "volumiodiscovery"... Jun 01 16:44:35 volumiokeller volumio[18044]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jun 01 16:44:35 volumiokeller volumio[18044]: *** WARNING *** Please fix your application to use the native API of Avahi! Jun 01 16:44:35 volumiokeller volumio[18044]: *** WARNING *** For more information see Jun 01 16:44:35 volumiokeller node[18044]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jun 01 16:44:35 volumiokeller volumio[18044]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jun 01 16:44:35 volumiokeller volumio[18044]: *** WARNING *** Please fix your application to use the native API of Avahi! Jun 01 16:44:35 volumiokeller volumio[18044]: *** WARNING *** For more information see Jun 01 16:44:35 volumiokeller node[18044]: *** WARNING *** Please fix your application to use the native API of Avahi! Jun 01 16:44:35 volumiokeller node[18044]: *** WARNING *** For more information see Jun 01 16:44:35 volumiokeller node[18044]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jun 01 16:44:35 volumiokeller node[18044]: *** WARNING *** Please fix your application to use the native API of Avahi! Jun 01 16:44:35 volumiokeller node[18044]: *** WARNING *** For more information see Jun 01 16:44:35 volumiokeller volumio[18044]: info: Applying required configuration parameters for plugin volumiodiscovery Jun 01 16:44:35 volumiokeller volumio[18044]: info: Discovery: Started advertising with name: VolumioKeller Jun 01 16:44:35 volumiokeller volumio[18044]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jun 01 16:44:35 volumiokeller volumio[18044]: info: Loading plugin "spop"... Jun 01 16:44:35 volumiokeller volumio-remote-updater[554]: [2025-06-01 16:44:35] [connect] Successful connection Jun 01 16:44:36 volumiokeller ntpd[753]: Listen normally on 26 wlan0 192.168.178.130:123 Jun 01 16:44:36 volumiokeller ntpd[753]: new interface(s) found: waking up resolver Jun 01 16:44:36 volumiokeller volumio[18044]: info: Loading plugin "squeezelite_mc"... Jun 01 16:44:36 volumiokeller go-librespot[14677]: time="2025-06-01T16:44:36+02:00" level=error msg="failed receiving dealer message" error="failed to get reader: WebSocket closed: sent close frame: status = StatusServiceRestart and reason = \"\"" Jun 01 16:44:37 volumiokeller volumio[18044]: info: Plugin ytcr is not enabled Jun 01 16:44:37 volumiokeller volumio[18044]: info: Loading plugin "outputs"... Jun 01 16:44:37 volumiokeller volumio[18044]: info: Loading plugin "albumart"... Jun 01 16:44:37 volumiokeller volumio[18044]: info: Plugin example_plugin is not enabled Jun 01 16:44:37 volumiokeller volumio[18044]: info: Loading plugin "inputs"... Jun 01 16:44:37 volumiokeller volumio[18044]: info: Loading plugin "updater_comm"... Jun 01 16:44:37 volumiokeller volumio[18044]: info: Plugin mpdemulation is not enabled Jun 01 16:44:37 volumiokeller volumio[18044]: info: Loading plugin "rest_api"... Jun 01 16:44:37 volumiokeller volumio[18044]: info: Loading plugin "websocket"... Jun 01 16:44:37 volumiokeller volumio[18044]: info: Starting Socket.io Server version 2.3.0 Jun 01 16:44:37 volumiokeller volumio[18044]: info: Loading i18n strings for locale de Jun 01 16:44:37 volumiokeller volumio[18044]: Updating browse sources language Jun 01 16:44:37 volumiokeller volumio[18044]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 01 16:44:37 volumiokeller volumio[18044]: Forking 3 albumart workers Jun 01 16:44:37 volumiokeller volumio[18044]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jun 01 16:44:37 volumiokeller volumio[18044]: info: CoreCommandRouter::initPlayerControls Jun 01 16:44:37 volumiokeller volumio[18044]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 16:44:37 volumiokeller volumio[18044]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 16:44:37 volumiokeller volumio[18044]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 16:44:37 volumiokeller volumio[18044]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 16:44:37 volumiokeller volumio[18044]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 16:44:37 volumiokeller volumio[18044]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 16:44:37 volumiokeller volumio[18044]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jun 01 16:44:37 volumiokeller volumio[18044]: Express server listening on port 3000 Jun 01 16:44:37 volumiokeller volumio[18044]: [Metrics] WebUI: 5s 532.50ms Jun 01 16:44:37 volumiokeller volumio[18044]: info: CoreStateMachine::resetVolumioState Jun 01 16:44:37 volumiokeller volumio[18044]: info: CoreStateMachine::getcurrentVolume Jun 01 16:44:37 volumiokeller volumio[18044]: info: CoreCommandRouter::volumioRetrievevolume Jun 01 16:44:37 volumiokeller volumio[18044]: info: Cannot read play queue from file Jun 01 16:44:37 volumiokeller volumio[18044]: info: Volumio Network Manager: Network status updated: 0 Jun 01 16:44:37 volumiokeller volumio-remote-updater[554]: [2025-06-01 16:44:37] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1748789075 101 Jun 01 16:44:37 volumiokeller volumio[18044]: 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: 1 Jun 01 16:44:37 volumiokeller volumio[18044]: verbose: New Socket.io Connection to 192.168.178.130:3000 from 192.168.178.41 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Jun 01 16:44:37 volumiokeller volumio[18044]: info: CoreStateMachine::pushState Jun 01 16:44:37 volumiokeller volumio[18044]: info: CorePlayQueue::getTrack 0 Jun 01 16:44:37 volumiokeller volumio[18044]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 01 16:44:37 volumiokeller volumio[18044]: info: CoreCommandRouter::volumioPushState Jun 01 16:44:37 volumiokeller volumio[18044]: info: CoreStateMachine::updateTrackBlock Jun 01 16:44:37 volumiokeller volumio[18044]: info: CorePlayQueue::getTrackBlock Jun 01 16:44:37 volumiokeller volumio[18044]: info: CoreCommandRouter::volumioRetrievevolume Jun 01 16:44:37 volumiokeller volumio[18044]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 01 16:44:37 volumiokeller volumio[18044]: info: CoreStateMachine::pushState Jun 01 16:44:37 volumiokeller volumio[18044]: info: CorePlayQueue::getTrack 0 Jun 01 16:44:37 volumiokeller volumio[18044]: info: CoreCommandRouter::volumioPushState Jun 01 16:44:37 volumiokeller volumio[18044]: info: Setting Device type: Raspberry PI Jun 01 16:44:37 volumiokeller volumio[18044]: info: CoreStateMachine::setRepeat null single undefined Jun 01 16:44:37 volumiokeller volumio[18044]: info: CoreStateMachine::pushState Jun 01 16:44:37 volumiokeller volumio[18044]: info: CorePlayQueue::getTrack 0 Jun 01 16:44:37 volumiokeller volumio[18044]: info: CoreCommandRouter::volumioPushState Jun 01 16:44:38 volumiokeller volumio[18044]: info: CoreStateMachine::setRandom null Jun 01 16:44:38 volumiokeller volumio[18044]: info: CoreStateMachine::pushState Jun 01 16:44:38 volumiokeller volumio[18044]: info: CorePlayQueue::getTrack 0 Jun 01 16:44:38 volumiokeller volumio[18044]: info: CoreCommandRouter::volumioPushState Jun 01 16:44:38 volumiokeller volumio[18044]: info: Completed loading Core Plugins Jun 01 16:44:38 volumiokeller volumio[18044]: info: Preparing to generate the ALSA configuration file Jun 01 16:44:38 volumiokeller sudo[18086]: pam_unix(sudo:session): session closed for user root Jun 01 16:44:38 volumiokeller volumio[18044]: info: The plugin alsa_controller has an ALSA contribution file softvolume.postVolume.conf Jun 01 16:44:38 volumiokeller volumio[18044]: info: Reading ALSA contributions from plugins. Jun 01 16:44:38 volumiokeller volumio[18044]: info: Asound.conf file unchanged, so no further update is needed Jun 01 16:44:38 volumiokeller volumio[18044]: info: Output device has changed, restarting MPD Jun 01 16:44:38 volumiokeller sudo[18173]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jun 01 16:44:38 volumiokeller volumio[18044]: info: Output device has changed, restarting Shairport Sync Jun 01 16:44:38 volumiokeller volumio[18044]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 16:44:38 volumiokeller volumio[18044]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 01 16:44:38 volumiokeller sudo[18173]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 01 16:44:38 volumiokeller sudo[18173]: pam_unix(sudo:session): session closed for user root Jun 01 16:44:38 volumiokeller sudo[18175]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jun 01 16:44:38 volumiokeller sudo[18175]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 01 16:44:38 volumiokeller systemd[1]: Stopping Music Player Daemon... Jun 01 16:44:38 volumiokeller systemd[1]: mpd.service: Succeeded. Jun 01 16:44:38 volumiokeller systemd[1]: Stopped Music Player Daemon. Jun 01 16:44:38 volumiokeller volumio[18044]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jun 01 16:44:38 volumiokeller volumio[18044]: info: ___________ START PLUGINS ___________ Jun 01 16:44:38 volumiokeller volumio[18044]: info: ControllerMpd::onStart: Initializing MPD Jun 01 16:44:38 volumiokeller volumio[18044]: info: Creating MPD Configuration file Jun 01 16:44:38 volumiokeller systemd[1]: Starting Music Player Daemon... Jun 01 16:44:38 volumiokeller volumio[18044]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jun 01 16:44:38 volumiokeller volumio[18044]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jun 01 16:44:38 volumiokeller volumio[18044]: info: [1748789078401] CoreMusicLibrary::Adding element Medienserver Jun 01 16:44:38 volumiokeller volumio[18044]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 01 16:44:38 volumiokeller sudo[18183]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jun 01 16:44:38 volumiokeller sudo[18183]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 01 16:44:38 volumiokeller sudo[18183]: pam_unix(sudo:session): session closed for user root Jun 01 16:44:38 volumiokeller sudo[18185]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jun 01 16:44:38 volumiokeller sudo[18185]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 01 16:44:38 volumiokeller sudo[18181]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jun 01 16:44:38 volumiokeller sudo[18181]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 01 16:44:38 volumiokeller volumio[18044]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 16:44:38 volumiokeller volumio[18044]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 01 16:44:38 volumiokeller sudo[18181]: pam_unix(sudo:session): session closed for user root Jun 01 16:44:38 volumiokeller volumio[18044]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jun 01 16:44:38 volumiokeller volumio[18044]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 16:44:38 volumiokeller volumio[18044]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 01 16:44:38 volumiokeller systemd[1]: mpd.service: Main process exited, code=killed, status=15/TERM Jun 01 16:44:38 volumiokeller systemd[1]: mpd.service: Succeeded. Jun 01 16:44:38 volumiokeller systemd[1]: Stopped Music Player Daemon. Jun 01 16:44:38 volumiokeller systemd[1]: Starting Music Player Daemon... Jun 01 16:44:38 volumiokeller volumio[18044]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jun 01 16:44:38 volumiokeller volumio[18044]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jun 01 16:44:38 volumiokeller volumio[18044]: info: [1748789078643] CoreMusicLibrary::Adding element Last_100 Jun 01 16:44:38 volumiokeller volumio[18044]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 01 16:44:38 volumiokeller volumio[18044]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jun 01 16:44:38 volumiokeller volumio[18044]: info: [1748789078647] CoreMusicLibrary::Adding element Webradio Jun 01 16:44:38 volumiokeller volumio[18044]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 01 16:44:38 volumiokeller volumio[18044]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jun 01 16:44:38 volumiokeller volumio[18044]: info: Initializing BBC Radios Jun 01 16:44:38 volumiokeller volumio[18044]: Starting albumart workers Jun 01 16:44:38 volumiokeller sudo[18196]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jun 01 16:44:38 volumiokeller sudo[18196]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 01 16:44:38 volumiokeller volumio[18044]: Starting albumart workers Jun 01 16:44:38 volumiokeller sudo[18196]: pam_unix(sudo:session): session closed for user root Jun 01 16:44:38 volumiokeller volumio[18044]: Starting albumart workers Jun 01 16:44:38 volumiokeller volumio[18044]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jun 01 16:44:38 volumiokeller volumio[18044]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 01 16:44:38 volumiokeller volumio[18044]: info: Creating Spotify config file Jun 01 16:44:38 volumiokeller volumio[18044]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 16:44:39 volumiokeller volumio[18044]: info: [squeezelite_mc] Starting proxy server... Jun 01 16:44:39 volumiokeller volumio[18044]: info: Volumio Calling Home Jun 01 16:44:39 volumiokeller volumio[18044]: info: [squeezelite_mc] Proxy server started on port 42579 Jun 01 16:44:39 volumiokeller volumio[18044]: info: CoreCommandRouter::volumioRetrievevolume Jun 01 16:44:39 volumiokeller volumio[18044]: info: CoreStateMachine::pushState Jun 01 16:44:39 volumiokeller volumio[18044]: info: CorePlayQueue::getTrack 0 Jun 01 16:44:39 volumiokeller volumio[18044]: info: CoreCommandRouter::volumioPushState Jun 01 16:44:39 volumiokeller volumio[18044]: info: [squeezelite_mc] Server discovery started Jun 01 16:44:39 volumiokeller volumio[18044]: info: [squeezelite_mc] Player finder started Jun 01 16:44:39 volumiokeller volumio[18044]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 16:44:39 volumiokeller volumio[18044]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 16:44:39 volumiokeller volumio[18044]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 16:44:39 volumiokeller volumio[18044]: info: [squeezelite_mc] Executing aplay -D hw:2 --nonblock -f MPEG /dev/zero 2>&1 || true Jun 01 16:44:39 volumiokeller volumio[18044]: info: MPD Permissions set Jun 01 16:44:39 volumiokeller volumio[18044]: info: MPD Permissions set Jun 01 16:44:39 volumiokeller volumio[18044]: info: Spotify config file written Jun 01 16:44:39 volumiokeller volumio[18044]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 16:44:39 volumiokeller volumio[18044]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 16:44:39 volumiokeller volumio[18044]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 16:44:39 volumiokeller volumio[18044]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 16:44:39 volumiokeller volumio[18044]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 01 16:44:39 volumiokeller volumio[18044]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 16:44:39 volumiokeller volumio[18044]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 16:44:39 volumiokeller volumio[18044]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 16:44:39 volumiokeller volumio[18044]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 16:44:39 volumiokeller volumio[18044]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 16:44:39 volumiokeller volumio[18044]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 16:44:39 volumiokeller volumio[18044]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 16:44:39 volumiokeller volumio[18044]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 16:44:39 volumiokeller volumio[18044]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 16:44:39 volumiokeller sudo[18229]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jun 01 16:44:39 volumiokeller sudo[18229]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 01 16:44:39 volumiokeller volumio[18044]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 01 16:44:39 volumiokeller volumio[18044]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 16:44:39 volumiokeller volumio[18044]: info: No need to fix Spotify hosts Jun 01 16:44:39 volumiokeller volumio[18044]: warn: [squeezelite_mc] No supported ALSA formats found for card 2 Jun 01 16:44:39 volumiokeller volumio[18044]: warn: [squeezelite_mc] No ALSA formats returned for card 2 Jun 01 16:44:39 volumiokeller volumio[18044]: info: [squeezelite_mc] Starting Squeezelite service with params: {"type":"basic","playerName":"volumiokeller","card":"2","mixerType":"Software","mixer":"SoftMaster","dsdFormat":null} Jun 01 16:44:39 volumiokeller volumio[18044]: info: [squeezelite_mc] Executing cp /data/plugins/music_service/squeezelite_mc/dist/lib/../templates/alsa/100-squeezelite.conf.template.out /etc/alsa/conf.d/100-squeezelite.conf Jun 01 16:44:39 volumiokeller systemd[1]: Stopping go-librespot Daemon... Jun 01 16:44:39 volumiokeller volumio[18044]: info: Starting Shairport Sync Jun 01 16:44:39 volumiokeller systemd[1]: go-librespot-daemon.service: Main process exited, code=killed, status=15/TERM Jun 01 16:44:39 volumiokeller systemd[1]: go-librespot-daemon.service: Succeeded. Jun 01 16:44:39 volumiokeller systemd[1]: Stopped go-librespot Daemon. Jun 01 16:44:39 volumiokeller volumio[18044]: info: Starting Shairport Sync Jun 01 16:44:39 volumiokeller volumio[18044]: info: Starting Shairport Sync Jun 01 16:44:39 volumiokeller sudo[18253]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jun 01 16:44:39 volumiokeller systemd[1]: Started go-librespot Daemon. Jun 01 16:44:39 volumiokeller go-librespot[18252]: Librespot-go daemon starting... Jun 01 16:44:39 volumiokeller sudo[18253]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 01 16:44:39 volumiokeller sudo[18255]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jun 01 16:44:39 volumiokeller sudo[18255]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 01 16:44:39 volumiokeller go-librespot[18252]: time="2025-06-01T16:44:39+02:00" level=info msg="generated new device id: be28cfe6ae181e836aba1d2c3989d454808d8361" Jun 01 16:44:39 volumiokeller go-librespot[18252]: time="2025-06-01T16:44:39+02:00" level=debug msg="stored credentials found for lsbhhixyjsen5v2myc9cmhqa5" Jun 01 16:44:39 volumiokeller sudo[18229]: pam_unix(sudo:session): session closed for user root Jun 01 16:44:39 volumiokeller systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Jun 01 16:44:39 volumiokeller systemd[1]: shairport-sync.service: Succeeded. Jun 01 16:44:39 volumiokeller systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Jun 01 16:44:39 volumiokeller sudo[18265]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jun 01 16:44:39 volumiokeller sudo[18265]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 01 16:44:39 volumiokeller systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Jun 01 16:44:39 volumiokeller sudo[18253]: pam_unix(sudo:session): session closed for user root Jun 01 16:44:39 volumiokeller volumio[18044]: info: Shairport-Sync Started Jun 01 16:44:39 volumiokeller systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Jun 01 16:44:39 volumiokeller systemd[1]: shairport-sync.service: Main process exited, code=killed, status=15/TERM Jun 01 16:44:39 volumiokeller systemd[1]: shairport-sync.service: Succeeded. Jun 01 16:44:39 volumiokeller sudo[18249]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/cp /data/plugins/music_service/squeezelite_mc/dist/lib/../templates/alsa/100-squeezelite.conf.template.out /etc/alsa/conf.d/100-squeezelite.conf Jun 01 16:44:39 volumiokeller sudo[18249]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 01 16:44:39 volumiokeller systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Jun 01 16:44:39 volumiokeller volumio[18044]: Error adding Membership: Error: addMembership EINVAL Jun 01 16:44:39 volumiokeller sudo[18249]: pam_unix(sudo:session): session closed for user root Jun 01 16:44:39 volumiokeller systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Jun 01 16:44:39 volumiokeller sudo[18265]: pam_unix(sudo:session): session closed for user root Jun 01 16:44:39 volumiokeller volumio[18044]: info: Shairport-Sync Started Jun 01 16:44:39 volumiokeller sudo[18255]: pam_unix(sudo:session): session closed for user root Jun 01 16:44:39 volumiokeller volumio[18044]: info: [squeezelite_mc] Executing cp /data/plugins/music_service/squeezelite_mc/dist/lib/../templates/systemd/squeezelite.service.template.out /etc/systemd/system/squeezelite.service Jun 01 16:44:39 volumiokeller volumio[18044]: info: Shairport-Sync Started Jun 01 16:44:40 volumiokeller sudo[18277]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/cp /data/plugins/music_service/squeezelite_mc/dist/lib/../templates/systemd/squeezelite.service.template.out /etc/systemd/system/squeezelite.service Jun 01 16:44:40 volumiokeller sudo[18277]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 01 16:44:40 volumiokeller sudo[18277]: pam_unix(sudo:session): session closed for user root Jun 01 16:44:40 volumiokeller volumio[18044]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl daemon-reload || true Jun 01 16:44:40 volumiokeller sudo[18285]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl daemon-reload Jun 01 16:44:40 volumiokeller sudo[18285]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 01 16:44:40 volumiokeller systemd[1]: Reloading. Jun 01 16:44:40 volumiokeller systemd[1]: /lib/systemd/system/winbind.service:8: PIDFile= references path below legacy directory /var/run/, updating /var/run/samba/winbindd.pid → /run/samba/winbindd.pid; please update the unit file accordingly. Jun 01 16:44:40 volumiokeller mpd[18204]: Jun 01 16:44 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jun 01 16:44:40 volumiokeller systemd[1]: Started Music Player Daemon. Jun 01 16:44:40 volumiokeller sudo[18285]: pam_unix(sudo:session): session closed for user root Jun 01 16:44:40 volumiokeller sudo[18175]: pam_unix(sudo:session): session closed for user root Jun 01 16:44:40 volumiokeller sudo[18185]: pam_unix(sudo:session): session closed for user root Jun 01 16:44:40 volumiokeller volumio[18044]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Jun 01 16:44:40 volumiokeller volumio[18044]: info: MPD running with PID18204 Jun 01 16:44:40 volumiokeller volumio[18044]: ,establishing connection Jun 01 16:44:40 volumiokeller sudo[18306]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Jun 01 16:44:40 volumiokeller sudo[18306]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 01 16:44:41 volumiokeller sudo[18306]: pam_unix(sudo:session): session closed for user root Jun 01 16:44:41 volumiokeller volumio[18044]: error: MPD error: The expression evaluated to a falsy value: Jun 01 16:44:41 volumiokeller volumio[18044]: assert.ok(self.idling) Jun 01 16:44:41 volumiokeller volumio[18044]: error: The expression evaluated to a falsy value: Jun 01 16:44:41 volumiokeller volumio[18044]: assert.ok(self.idling) Jun 01 16:44:41 volumiokeller volumio[18044]: error: MPD error: The expression evaluated to a falsy value: Jun 01 16:44:41 volumiokeller volumio[18044]: assert.ok(self.idling) Jun 01 16:44:41 volumiokeller volumio[18044]: error: The expression evaluated to a falsy value: Jun 01 16:44:41 volumiokeller volumio[18044]: assert.ok(self.idling) Jun 01 16:44:41 volumiokeller volumio[18044]: info: [squeezelite_mc] Executing rm /tmp/squeezelite.log Jun 01 16:44:41 volumiokeller volumio[18044]: error: updateQueue error: null Jun 01 16:44:41 volumiokeller sudo[18310]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/rm /tmp/squeezelite.log Jun 01 16:44:41 volumiokeller sudo[18310]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 01 16:44:41 volumiokeller sudo[18310]: pam_unix(sudo:session): session closed for user root Jun 01 16:44:41 volumiokeller volumio[18044]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl start squeezelite || true Jun 01 16:44:41 volumiokeller sudo[18313]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start squeezelite Jun 01 16:44:41 volumiokeller sudo[18313]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 01 16:44:41 volumiokeller systemd[1]: Starting Squeezelite lightweight headless Squeezebox emulator... Jun 01 16:44:41 volumiokeller systemd[1]: Started Squeezelite lightweight headless Squeezebox emulator. Jun 01 16:44:41 volumiokeller sudo[18313]: pam_unix(sudo:session): session closed for user root Jun 01 16:44:41 volumiokeller systemd[1]: squeezelite.service: Succeeded. Jun 01 16:44:41 volumiokeller systemd[1]: squeezelite.service: Service RestartSec=100ms expired, scheduling restart. Jun 01 16:44:41 volumiokeller systemd[1]: squeezelite.service: Scheduled restart job, restart counter is at 1. Jun 01 16:44:41 volumiokeller systemd[1]: Stopped Squeezelite lightweight headless Squeezebox emulator. Jun 01 16:44:41 volumiokeller systemd[1]: Starting Squeezelite lightweight headless Squeezebox emulator... Jun 01 16:44:41 volumiokeller systemd[1]: Started Squeezelite lightweight headless Squeezebox emulator. Jun 01 16:44:41 volumiokeller systemd[1]: squeezelite.service: Succeeded. Jun 01 16:44:41 volumiokeller volumio[18044]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Jun 01 16:44:41 volumiokeller sudo[18320]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Jun 01 16:44:41 volumiokeller sudo[18320]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 01 16:44:41 volumiokeller systemd[1]: squeezelite.service: Service RestartSec=100ms expired, scheduling restart. Jun 01 16:44:41 volumiokeller systemd[1]: squeezelite.service: Scheduled restart job, restart counter is at 2. Jun 01 16:44:41 volumiokeller systemd[1]: Stopped Squeezelite lightweight headless Squeezebox emulator. Jun 01 16:44:41 volumiokeller sudo[18320]: pam_unix(sudo:session): session closed for user root Jun 01 16:44:41 volumiokeller systemd[1]: Starting Squeezelite lightweight headless Squeezebox emulator... Jun 01 16:44:41 volumiokeller systemd[1]: Started Squeezelite lightweight headless Squeezebox emulator. Jun 01 16:44:41 volumiokeller systemd[1]: squeezelite.service: Succeeded. Jun 01 16:44:42 volumiokeller systemd[1]: squeezelite.service: Service RestartSec=100ms expired, scheduling restart. Jun 01 16:44:42 volumiokeller systemd[1]: squeezelite.service: Scheduled restart job, restart counter is at 3. Jun 01 16:44:42 volumiokeller systemd[1]: Stopped Squeezelite lightweight headless Squeezebox emulator. Jun 01 16:44:42 volumiokeller systemd[1]: Starting Squeezelite lightweight headless Squeezebox emulator... Jun 01 16:44:42 volumiokeller systemd[1]: Started Squeezelite lightweight headless Squeezebox emulator. Jun 01 16:44:42 volumiokeller systemd[1]: squeezelite.service: Succeeded. Jun 01 16:44:42 volumiokeller systemd[1]: squeezelite.service: Service RestartSec=100ms expired, scheduling restart. Jun 01 16:44:42 volumiokeller systemd[1]: squeezelite.service: Scheduled restart job, restart counter is at 4. Jun 01 16:44:42 volumiokeller systemd[1]: Stopped Squeezelite lightweight headless Squeezebox emulator. Jun 01 16:44:42 volumiokeller volumio[18044]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Jun 01 16:44:42 volumiokeller sudo[18328]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Jun 01 16:44:42 volumiokeller sudo[18328]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 01 16:44:42 volumiokeller systemd[1]: Starting Squeezelite lightweight headless Squeezebox emulator... Jun 01 16:44:42 volumiokeller systemd[1]: Started Squeezelite lightweight headless Squeezebox emulator. Jun 01 16:44:42 volumiokeller sudo[18328]: pam_unix(sudo:session): session closed for user root Jun 01 16:44:42 volumiokeller systemd[1]: squeezelite.service: Succeeded. Jun 01 16:44:42 volumiokeller systemd[1]: squeezelite.service: Service RestartSec=100ms expired, scheduling restart. Jun 01 16:44:42 volumiokeller systemd[1]: squeezelite.service: Scheduled restart job, restart counter is at 5. Jun 01 16:44:42 volumiokeller systemd[1]: Stopped Squeezelite lightweight headless Squeezebox emulator. Jun 01 16:44:42 volumiokeller systemd[1]: squeezelite.service: Start request repeated too quickly. Jun 01 16:44:42 volumiokeller systemd[1]: squeezelite.service: Failed with result 'start-limit-hit'. Jun 01 16:44:42 volumiokeller systemd[1]: Failed to start Squeezelite lightweight headless Squeezebox emulator. Jun 01 16:44:42 volumiokeller volumio[18044]: info: go-librespot daemon successfully initialized Jun 01 16:44:42 volumiokeller volumio[18044]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Jun 01 16:44:42 volumiokeller sudo[18332]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Jun 01 16:44:42 volumiokeller sudo[18332]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 01 16:44:42 volumiokeller sudo[18332]: pam_unix(sudo:session): session closed for user root Jun 01 16:44:42 volumiokeller volumio[18044]: info: Completed starting Core Plugins Jun 01 16:44:42 volumiokeller volumio[18044]: info: ------------------------------------------- Jun 01 16:44:42 volumiokeller volumio[18044]: info: ----- MyVolumio plugins startup ---- Jun 01 16:44:42 volumiokeller volumio[18044]: info: ------------------------------------------- Jun 01 16:44:42 volumiokeller volumio[18044]: info: [MyVolumio PluginManager] Fetching plans data.... Jun 01 16:44:44 volumiokeller volumio[18044]: info: Volumio Network Manager: Network status updated: 2 Jun 01 16:44:44 volumiokeller sudo[18349]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jun 01 16:44:44 volumiokeller sudo[18349]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 01 16:44:44 volumiokeller sudo[18349]: pam_unix(sudo:session): session closed for user root Jun 01 16:44:44 volumiokeller sudo[18351]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jun 01 16:44:44 volumiokeller sudo[18351]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 01 16:44:44 volumiokeller sudo[18351]: pam_unix(sudo:session): session closed for user root Jun 01 16:44:44 volumiokeller sudo[18355]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Jun 01 16:44:44 volumiokeller sudo[18355]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 01 16:44:44 volumiokeller sudo[18355]: pam_unix(sudo:session): session closed for user root Jun 01 16:44:44 volumiokeller volumio[18044]: info: Upmpdcli Daemon Started Jun 01 16:44:45 volumiokeller volumio[18044]: info: Initializing connection to go-librespot Websocket Jun 01 16:44:45 volumiokeller volumio[18044]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Jun 01 16:44:54 volumiokeller wpa_supplicant[849]: wlan0: CTRL-EVENT-DISCONNECTED bssid=b0:f2:08:ec:0b:28 reason=34 Jun 01 16:44:54 volumiokeller dhcpcd[861]: wlan0: carrier lost Jun 01 16:44:54 volumiokeller wpa_supplicant[849]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=CORE type=WORLD Jun 01 16:44:54 volumiokeller wpa_supplicant[849]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=USER type=COUNTRY alpha2=DE Jun 01 16:44:54 volumiokeller avahi-daemon[547]: Withdrawing address record for 192.168.178.130 on wlan0. Jun 01 16:44:54 volumiokeller avahi-daemon[547]: Leaving mDNS multicast group on interface wlan0.IPv4 with address 192.168.178.130. Jun 01 16:44:54 volumiokeller avahi-daemon[547]: Interface wlan0.IPv4 no longer relevant for mDNS. Jun 01 16:44:54 volumiokeller dhcpcd[861]: wlan0: deleting route to 192.168.178.0/24 Jun 01 16:44:54 volumiokeller dhcpcd[861]: wlan0: deleting default route via 192.168.178.1 Jun 01 16:44:54 volumiokeller volumio[18044]: info: Discovery: A device disappeared from network Jun 01 16:44:54 volumiokeller volumio[18044]: info: Discovery: Browse raised the following error TypeError: Cannot read property 'toLowerCase' of undefined Jun 01 16:44:54 volumiokeller volumio[18044]: info: Discovery: A device disappeared from network Jun 01 16:44:54 volumiokeller volumio[18044]: info: Discovery: Browse raised the following error TypeError: Cannot read property 'toLowerCase' of undefined Jun 01 16:44:54 volumiokeller volumio[18044]: info: Volumio Network Manager: Network status updated: 0 Jun 01 16:44:55 volumiokeller kernel: brcmfmac: brcmf_set_channel: set chanspec 0xd022 fail, reason -52 Jun 01 16:44:56 volumiokeller kernel: brcmfmac: brcmf_set_channel: set chanspec 0xd026 fail, reason -52 Jun 01 16:44:56 volumiokeller kernel: brcmfmac: brcmf_set_channel: set chanspec 0xd02a fail, reason -52 Jun 01 16:44:56 volumiokeller kernel: brcmfmac: brcmf_set_channel: set chanspec 0xd02e fail, reason -52 Jun 01 16:44:56 volumiokeller ntpd[753]: Deleting interface #26 wlan0, 192.168.178.130#123, interface stats: received=5, sent=13, dropped=0, active_time=20 secs Jun 01 16:44:56 volumiokeller ntpd[753]: 195.201.20.16 local addr 192.168.178.130 -> Jun 01 16:44:56 volumiokeller ntpd[753]: 116.203.244.102 local addr 192.168.178.130 -> Jun 01 16:44:56 volumiokeller ntpd[753]: 78.46.87.46 local addr 192.168.178.130 -> Jun 01 16:44:56 volumiokeller ntpd[753]: 81.3.27.46 local addr 192.168.178.130 -> Jun 01 16:44:56 volumiokeller ntpd[753]: 158.180.28.150 local addr 192.168.178.130 -> Jun 01 16:44:56 volumiokeller ntpd[753]: 148.251.235.164 local addr 192.168.178.130 -> Jun 01 16:44:56 volumiokeller ntpd[753]: 178.215.228.24 local addr 192.168.178.130 -> Jun 01 16:44:56 volumiokeller ntpd[753]: 144.76.76.107 local addr 192.168.178.130 -> Jun 01 16:44:56 volumiokeller ntpd[753]: 144.76.43.40 local addr 192.168.178.130 -> Jun 01 16:44:56 volumiokeller ntpd[753]: 144.76.66.156 local addr 192.168.178.130 -> Jun 01 16:44:56 volumiokeller ntpd[753]: 107.189.12.98 local addr 192.168.178.130 -> Jun 01 16:44:56 volumiokeller ntpd[753]: 79.133.44.138 local addr 192.168.178.130 -> Jun 01 16:44:58 volumiokeller wpa_supplicant[849]: wlan0: Trying to associate with SSID 'FRITZ!Box 5590 SF' Jun 01 16:44:58 volumiokeller kernel: brcmfmac: brcmf_set_channel: set chanspec 0xd090 fail, reason -52 Jun 01 16:44:58 volumiokeller kernel: brcmfmac: brcmf_set_channel: set chanspec 0xd095 fail, reason -52 Jun 01 16:44:58 volumiokeller kernel: brcmfmac: brcmf_set_channel: set chanspec 0xd099 fail, reason -52 Jun 01 16:44:58 volumiokeller kernel: brcmfmac: brcmf_set_channel: set chanspec 0xd09d fail, reason -52 Jun 01 16:44:58 volumiokeller kernel: brcmfmac: brcmf_set_channel: set chanspec 0xd0a1 fail, reason -52 Jun 01 16:44:58 volumiokeller kernel: brcmfmac: brcmf_set_channel: set chanspec 0xd0a5 fail, reason -52 Jun 01 16:44:58 volumiokeller wpa_supplicant[849]: wlan0: CTRL-EVENT-ASSOC-REJECT bssid=00:00:00:00:00:00 status_code=16 Jun 01 16:44:58 volumiokeller ntpd[753]: error resolving pool 2.debian.pool.ntp.org: System error (-11) Jun 01 16:44:58 volumiokeller ntpd[753]: error resolving pool 1.debian.pool.ntp.org: System error (-11) Jun 01 16:44:58 volumiokeller ntpd[753]: error resolving pool 3.debian.pool.ntp.org: System error (-11) Jun 01 16:44:58 volumiokeller go-librespot[18252]: time="2025-06-01T16:44:58+02:00" level=fatal msg="failed running with username and spotify token" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": dial tcp: lookup apresolve.spotify.com: device or resource busy" Jun 01 16:44:58 volumiokeller systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 01 16:44:58 volumiokeller systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 01 16:45:02 volumiokeller systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jun 01 16:45:02 volumiokeller systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Jun 01 16:45:02 volumiokeller systemd[1]: Stopped go-librespot Daemon. Jun 01 16:45:02 volumiokeller systemd[1]: Started go-librespot Daemon. Jun 01 16:45:02 volumiokeller go-librespot[18444]: Librespot-go daemon starting... Jun 01 16:45:02 volumiokeller go-librespot[18444]: time="2025-06-01T16:45:02+02:00" level=info msg="generated new device id: 403c4babb7a078bbb4c30eba0105b130a627e235" Jun 01 16:45:02 volumiokeller go-librespot[18444]: time="2025-06-01T16:45:02+02:00" level=debug msg="stored credentials found for lsbhhixyjsen5v2myc9cmhqa5" Jun 01 16:45:02 volumiokeller go-librespot[18444]: time="2025-06-01T16:45:02+02:00" level=fatal msg="failed running with username and spotify token" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": dial tcp: lookup apresolve.spotify.com: device or resource busy" Jun 01 16:45:02 volumiokeller volumio[18044]: info: Discovery: Browse raised the following error Error: getaddrinfo -3008 Jun 01 16:45:02 volumiokeller systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 01 16:45:02 volumiokeller systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 01 16:45:02 volumiokeller volumio[18044]: info: An error occurred while refreshing Spotify Token Error: getaddrinfo EBUSY oauth-performer.prod.vlmapi.io Jun 01 16:45:02 volumiokeller volumio[18044]: info: Discovery: Browse raised the following error Error: getaddrinfo -3008 Jun 01 16:45:02 volumiokeller volumio[18044]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 01 16:45:02 volumiokeller volumio[18044]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Jun 01 16:45:02 volumiokeller volumio[18044]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 4 Jun 01 16:45:02 volumiokeller volumio[18044]: info: CoreCommandRouter::volumioGetState Jun 01 16:45:02 volumiokeller volumio[18044]: info: CorePlayQueue::getTrack 0 Jun 01 16:45:02 volumiokeller kernel: brcmfmac: brcmf_set_channel: set chanspec 0xd022 fail, reason -52 Jun 01 16:45:02 volumiokeller kernel: brcmfmac: brcmf_set_channel: set chanspec 0xd026 fail, reason -52 Jun 01 16:45:02 volumiokeller kernel: brcmfmac: brcmf_set_channel: set chanspec 0xd02a fail, reason -52 Jun 01 16:45:02 volumiokeller kernel: brcmfmac: brcmf_set_channel: set chanspec 0xd02e fail, reason -52 Jun 01 16:45:02 volumiokeller volumio[18044]: error: MyVolumio Plugin failed to start in a timely fashion Jun 01 16:45:02 volumiokeller volumio[18044]: [Metrics] CommandRouter: 30s 338.21ms Jun 01 16:45:02 volumiokeller volumio[18044]: info: CoreCommandRouter::volumiosetStartupVolume Jun 01 16:45:02 volumiokeller volumio[18044]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 16:45:02 volumiokeller volumio[18044]: info: VolumeController:: Setting startup Volume 100 Jun 01 16:45:02 volumiokeller volumio[18044]: info: VolumeController::SetAlsaVolume100 Jun 01 16:45:02 volumiokeller volumio[18044]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 01 16:45:02 volumiokeller volumio[18044]: info: CoreCommandRouter::Close All Modals sent Jun 01 16:45:02 volumiokeller volumio[18044]: info: CoreCommandRouter::Close All Modals sent Jun 01 16:45:02 volumiokeller volumio[18044]: info: CoreStateMachine::pushState Jun 01 16:45:02 volumiokeller volumio[18044]: info: CorePlayQueue::getTrack 0 Jun 01 16:45:02 volumiokeller volumio[18044]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 01 16:45:02 volumiokeller volumio[18044]: info: CoreCommandRouter::volumioPushState Jun 01 16:45:03 volumiokeller volumio[18044]: error: Cannot set ALSA Volume: Error: Alsa Mixer Error: Invalid card number. Jun 01 16:45:03 volumiokeller volumio[18044]: info: Cannot play startup sound: Error: Command failed: /usr/bin/aplay -D volumio /volumio/app/startup.wav Jun 01 16:45:03 volumiokeller volumio[18044]: ALSA lib pcm_hw.c:1822:(_snd_pcm_hw_open) Invalid value for card Jun 01 16:45:03 volumiokeller volumio[18044]: aplay: main:828: audio open error: No such device Jun 01 16:45:03 volumiokeller volumio[18044]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable Jun 01 16:45:03 volumiokeller volumio[18044]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Jun 01 16:45:03 volumiokeller volumio[18044]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect Jun 01 16:45:04 volumiokeller wpa_supplicant[849]: wlan0: Trying to associate with SSID 'FRITZ!Box 5590 SF' Jun 01 16:45:04 volumiokeller kernel: brcmfmac: brcmf_set_channel: set chanspec 0xd090 fail, reason -52 Jun 01 16:45:04 volumiokeller kernel: brcmfmac: brcmf_set_channel: set chanspec 0xd095 fail, reason -52 Jun 01 16:45:04 volumiokeller kernel: brcmfmac: brcmf_set_channel: set chanspec 0xd099 fail, reason -52 Jun 01 16:45:04 volumiokeller kernel: brcmfmac: brcmf_set_channel: set chanspec 0xd09d fail, reason -52 Jun 01 16:45:04 volumiokeller kernel: brcmfmac: brcmf_set_channel: set chanspec 0xd0a1 fail, reason -52 Jun 01 16:45:04 volumiokeller kernel: brcmfmac: brcmf_set_channel: set chanspec 0xd0a5 fail, reason -52 Jun 01 16:45:04 volumiokeller ntpd[753]: error resolving pool 0.debian.pool.ntp.org: System error (-11) Jun 01 16:45:04 volumiokeller wpa_supplicant[849]: wlan0: Associated with 48:5d:35:cb:9a:17 Jun 01 16:45:04 volumiokeller wpa_supplicant[849]: wlan0: CTRL-EVENT-CONNECTED - Connection to 48:5d:35:cb:9a:17 completed [id=0 id_str=] Jun 01 16:45:04 volumiokeller dhcpcd[861]: wlan0: carrier acquired Jun 01 16:45:04 volumiokeller wpa_supplicant[849]: wlan0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0 Jun 01 16:45:04 volumiokeller wpa_supplicant[849]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=COUNTRY_IE type=COUNTRY alpha2=DE Jun 01 16:45:04 volumiokeller dhcpcd[861]: wlan0: IAID eb:25:9d:91 Jun 01 16:45:04 volumiokeller dhcpcd[861]: wlan0: carrier lost Jun 01 16:45:04 volumiokeller dhcpcd[861]: wlan0: carrier acquired Jun 01 16:45:04 volumiokeller dhcpcd[861]: wlan0: IAID eb:25:9d:91 Jun 01 16:45:04 volumiokeller dhcpcd[861]: wlan0: soliciting an IPv6 router Jun 01 16:45:04 volumiokeller dhcpcd[861]: wlan0: rebinding lease of 192.168.178.130 Jun 01 16:45:05 volumiokeller dhcpcd[861]: wlan0: probing address 192.168.178.130/24 Jun 01 16:45:05 volumiokeller volumio[18044]: info: Initializing connection to go-librespot Websocket Jun 01 16:45:05 volumiokeller volumio[18044]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 01 16:45:05 volumiokeller systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jun 01 16:45:05 volumiokeller systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Jun 01 16:45:05 volumiokeller systemd[1]: Stopped go-librespot Daemon. Jun 01 16:45:05 volumiokeller systemd[1]: Started go-librespot Daemon. Jun 01 16:45:05 volumiokeller go-librespot[18480]: Librespot-go daemon starting... Jun 01 16:45:05 volumiokeller go-librespot[18480]: time="2025-06-01T16:45:05+02:00" level=info msg="generated new device id: 82adff91f0a0a5230bb24b7ec4fbec676476e51f" Jun 01 16:45:05 volumiokeller go-librespot[18480]: time="2025-06-01T16:45:05+02:00" level=debug msg="stored credentials found for lsbhhixyjsen5v2myc9cmhqa5" Jun 01 16:45:05 volumiokeller go-librespot[18480]: time="2025-06-01T16:45:05+02:00" level=fatal msg="failed running with username and spotify token" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": dial tcp: lookup apresolve.spotify.com: device or resource busy" Jun 01 16:45:05 volumiokeller systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 01 16:45:05 volumiokeller systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 01 16:45:08 volumiokeller volumio[18044]: info: Initializing connection to go-librespot Websocket Jun 01 16:45:08 volumiokeller volumio[18044]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 01 16:45:08 volumiokeller volumio[18044]: info: Cannot call home: Error: Command failed: /usr/bin/curl -X POST --data-binary "device=pi&variante=volumio&version=3.799&uuid=e285cb88e9af9c9aa04fed0d687cc670" http://updates.volumio.org/downloader-v1/track-device Jun 01 16:45:08 volumiokeller volumio[18044]: % Total % Received % Xferd Average Speed Time Time Time Current Jun 01 16:45:08 volumiokeller volumio[18044]: Dload Upload Total Spent Left Speed Jun 01 16:45:08 volumiokeller volumio[18044]: [1.5K blob data] Jun 01 16:45:08 volumiokeller volumio[18044]: retrying in 5 seconds, trial 0 Jun 01 16:45:08 volumiokeller volumio[18044]: info: Volumio Calling Home Jun 01 16:45:08 volumiokeller systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jun 01 16:45:08 volumiokeller systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Jun 01 16:45:08 volumiokeller systemd[1]: Stopped go-librespot Daemon. Jun 01 16:45:08 volumiokeller systemd[1]: Started go-librespot Daemon. Jun 01 16:45:08 volumiokeller go-librespot[18491]: Librespot-go daemon starting... Jun 01 16:45:08 volumiokeller go-librespot[18491]: time="2025-06-01T16:45:08+02:00" level=info msg="generated new device id: 433a20b9d2434e51e0abc46161fd1cc815aab263" Jun 01 16:45:08 volumiokeller go-librespot[18491]: time="2025-06-01T16:45:08+02:00" level=debug msg="stored credentials found for lsbhhixyjsen5v2myc9cmhqa5" Jun 01 16:45:08 volumiokeller go-librespot[18491]: time="2025-06-01T16:45:08+02:00" level=fatal msg="failed running with username and spotify token" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": dial tcp: lookup apresolve.spotify.com: device or resource busy" Jun 01 16:45:08 volumiokeller systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 01 16:45:08 volumiokeller systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 01 16:45:09 volumiokeller volumio[18044]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jun 01 16:45:09 volumiokeller volumio[18044]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 01 16:45:09 volumiokeller volumio[18044]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Jun 01 16:45:09 volumiokeller volumio[18044]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jun 01 16:45:09 volumiokeller volumio[18044]: Error: send ENETUNREACH 255.255.255.255:3483 Jun 01 16:45:09 volumiokeller volumio[18044]: at doSend (dgram.js:692:16) Jun 01 16:45:09 volumiokeller volumio[18044]: at defaultTriggerAsyncIdScope (internal/async_hooks.js:430:12) Jun 01 16:45:09 volumiokeller volumio[18044]: at afterDns (dgram.js:638:5) Jun 01 16:45:09 volumiokeller volumio[18044]: at processTicksAndRejections (internal/process/task_queues.js:81:21) { Jun 01 16:45:09 volumiokeller volumio[18044]: errno: -101, Jun 01 16:45:09 volumiokeller volumio[18044]: code: 'ENETUNREACH', Jun 01 16:45:09 volumiokeller volumio[18044]: syscall: 'send', Jun 01 16:45:09 volumiokeller volumio[18044]: address: '255.255.255.255', Jun 01 16:45:09 volumiokeller volumio[18044]: port: 3483 Jun 01 16:45:09 volumiokeller volumio[18044]: } Jun 01 16:45:09 volumiokeller volumio[18044]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jun 01 16:45:09 volumiokeller dhcpcd[861]: wlan0: leased 192.168.178.130 for 864000 seconds Jun 01 16:45:09 volumiokeller avahi-daemon[547]: Joining mDNS multicast group on interface wlan0.IPv4 with address 192.168.178.130. Jun 01 16:45:09 volumiokeller avahi-daemon[547]: New relevant interface wlan0.IPv4 for mDNS. Jun 01 16:45:09 volumiokeller avahi-daemon[547]: Registering new address record for 192.168.178.130 on wlan0.IPv4. Jun 01 16:45:09 volumiokeller dhcpcd[861]: wlan0: adding route to 192.168.178.0/24 Jun 01 16:45:09 volumiokeller dhcpcd[861]: wlan0: adding default route via 192.168.178.1 Jun 01 16:45:09 volumiokeller sudo[18531]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-06-01 16:44 Jun 01 16:45:09 volumiokeller sudo[18531]: 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="147953990fca4aa103a8f90538ef56fb0454638c" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="e32c2c71ae78852844c70357816bdd871c155ab8" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Mon 31 Mar 2025 06:54:47 PM CEST" VOLUMIO_VERSION="3.799" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="436f3f84f6d0b4ffc344f0bc132a32e8"