Oct 02 23:42:05 volumio volumio[1229]: info: CoreCommandRouter::getUIConfigOnPlugin Oct 02 23:42:05 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus Oct 02 23:42:06 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: network , getInfoNetwork Oct 02 23:42:06 volumio sudo[16934]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ethtool eth0 Oct 02 23:42:06 volumio sudo[16934]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 02 23:42:06 volumio sudo[16939]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwconfig wlan0 Oct 02 23:42:06 volumio sudo[16939]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 02 23:42:06 volumio sudo[16934]: pam_unix(sudo:session): session closed for user root Oct 02 23:42:06 volumio sudo[16939]: pam_unix(sudo:session): session closed for user root Oct 02 23:42:06 volumio sudo[16945]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwconfig wlan0 Oct 02 23:42:06 volumio sudo[16945]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 02 23:42:06 volumio sudo[16951]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwconfig wlan0 Oct 02 23:42:06 volumio sudo[16951]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 02 23:42:06 volumio sudo[16945]: pam_unix(sudo:session): session closed for user root Oct 02 23:42:06 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: network , getWirelessNetworksScanCache Oct 02 23:42:06 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: network , getWirelessNetworks Oct 02 23:42:06 volumio sudo[16951]: pam_unix(sudo:session): session closed for user root Oct 02 23:42:06 volumio sudo[16958]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 02 23:42:06 volumio sudo[16958]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 02 23:42:06 volumio sudo[16958]: pam_unix(sudo:session): session closed for user root Oct 02 23:42:06 volumio sudo[16962]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 02 23:42:06 volumio sudo[16962]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 02 23:42:06 volumio sudo[16962]: pam_unix(sudo:session): session closed for user root Oct 02 23:42:08 volumio volumio[1229]: info: CALLMETHOD: system_controller network saveWiredNet [object Object] Oct 02 23:42:08 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: network , saveWiredNet Oct 02 23:42:08 volumio sudo[16966]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/network/interfaces Oct 02 23:42:08 volumio sudo[16966]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 02 23:42:08 volumio sudo[16966]: pam_unix(sudo:session): session closed for user root Oct 02 23:42:08 volumio sudo[16968]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/dhcpcd.conf Oct 02 23:42:08 volumio sudo[16968]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 02 23:42:08 volumio sudo[16968]: pam_unix(sudo:session): session closed for user root Oct 02 23:42:08 volumio volumio[1229]: info: Permissions for /etc/network/interfaces set Oct 02 23:42:08 volumio volumio[1229]: info: Restarting Wired Network Oct 02 23:42:08 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , onNetworkingRestart Oct 02 23:42:08 volumio sudo[16971]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/ip addr flush dev eth0 Oct 02 23:42:08 volumio sudo[16971]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 02 23:42:08 volumio avahi-daemon[665]: Withdrawing address record for 192.168.1.2 on eth0. Oct 02 23:42:08 volumio avahi-daemon[665]: Leaving mDNS multicast group on interface eth0.IPv4 with address 192.168.1.2. Oct 02 23:42:08 volumio avahi-daemon[665]: Interface eth0.IPv4 no longer relevant for mDNS. Oct 02 23:42:08 volumio dhcpcd[773]: eth0: pid 16972 deleted IP address 192.168.1.2/24 Oct 02 23:42:08 volumio dhcpcd[773]: eth0: deleting route to 192.168.1.0/24 Oct 02 23:42:08 volumio dhcpcd[773]: eth0: deleting default route via 192.168.1.1 Oct 02 23:42:08 volumio sudo[16971]: pam_unix(sudo:session): session closed for user root Oct 02 23:42:08 volumio volumio[1229]: info: Discovery: A device disappeared from network Oct 02 23:42:08 volumio volumio[1229]: info: Discovery: A device disappeared from network Oct 02 23:42:08 volumio volumio[1229]: info: Discovery: A device disappeared from network Oct 02 23:42:08 volumio dhcpcd[773]: eth0: rebinding lease of 192.168.1.2 Oct 02 23:42:08 volumio sudo[16975]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 down Oct 02 23:42:08 volumio sudo[16975]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 02 23:42:08 volumio dhcpcd[773]: eth0: carrier lost Oct 02 23:42:08 volumio sudo[16975]: pam_unix(sudo:session): session closed for user root Oct 02 23:42:08 volumio kernel: smsc95xx 1-1.1:1.0 eth0: Link is Down Oct 02 23:42:08 volumio kernel: smsc95xx 1-1.1:1.0 eth0: hardware isn't capable of remote wakeup Oct 02 23:42:08 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Oct 02 23:42:08 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Oct 02 23:42:08 volumio systemd[1]: welcome.service: Deactivated successfully. Oct 02 23:42:08 volumio systemd[1]: Stopped welcome.service - Show a welcome message on console. Oct 02 23:42:08 volumio systemd[1]: Stopping welcome.service - Show a welcome message on console... Oct 02 23:42:08 volumio dhcpcd[16985]: ps_bpf_recvmsg: Network is down Oct 02 23:42:08 volumio sudo[16988]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 up Oct 02 23:42:08 volumio sudo[16988]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 02 23:42:08 volumio sudo[16988]: pam_unix(sudo:session): session closed for user root Oct 02 23:42:08 volumio kernel: smsc95xx 1-1.1:1.0 eth0: hardware isn't capable of remote wakeup Oct 02 23:42:08 volumio kernel: smsc95xx 1-1.1:1.0 eth0: Link is Down Oct 02 23:42:08 volumio systemd[1]: Starting welcome.service - Show a welcome message on console... Oct 02 23:42:08 volumio welcome[16990]: Resolved ip:[0] Oct 02 23:42:08 volumio systemd[1]: Finished welcome.service - Show a welcome message on console. Oct 02 23:42:08 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Oct 02 23:42:09 volumio volumio[1229]: info: Received Get System Info Oct 02 23:42:09 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 02 23:42:09 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 02 23:42:09 volumio volumio[1229]: info: Discovery: Getting this device information Oct 02 23:42:09 volumio volumio[1229]: info: CoreCommandRouter::volumioGetState Oct 02 23:42:09 volumio volumio[1229]: info: CorePlayQueue::getTrack 0 Oct 02 23:42:09 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 02 23:42:09 volumio volumio5-onboarding[1702]: time=2026-10-02T23:42:09.346+09:00 level=INFO msg="emitting ethernet info changed event" component=server peer="192.168.1.3:56590 @ 0x30000c0" available=true connected=false macAddress= ip4Address= ip6Address= Oct 02 23:42:09 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Oct 02 23:42:09 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Oct 02 23:42:09 volumio bluetoothd[899]: src/advertising.c:add_client_complete() Failed to add advertisement: Rejected (0x0b) Oct 02 23:42:09 volumio volumio5-onboarding[1702]: time=2026-10-02T23:42:09.370+09:00 level=ERROR msg="failed to enable BLE discovery" error="failed to start BLE advertiser: bluetooth: could not start advertisement: Failed to register advertisement" Oct 02 23:42:09 volumio volumio[1229]: info: Volumio Network Manager: Network status updated: 0 Oct 02 23:42:09 volumio ifplugd(eth0)[1034]: Link beat lost. Oct 02 23:42:10 volumio volumio5-onboarding[1702]: time=2026-10-02T23:42:10.232+09:00 level=INFO msg="service successfully established" component=discovery/localnet Oct 02 23:42:10 volumio dhcpcd[773]: eth0: carrier acquired Oct 02 23:42:10 volumio dhcpcd[773]: eth0: config file changed, expiring leases Oct 02 23:42:10 volumio kernel: smsc95xx 1-1.1:1.0 eth0: Link is Up - 100Mbps/Full - flow control off Oct 02 23:42:10 volumio dhcpcd[773]: eth0: IAID eb:2a:44:ec Oct 02 23:42:10 volumio ifplugd(eth0)[1034]: Link beat detected. Oct 02 23:42:10 volumio volumio5-onboarding[1702]: time=2026-10-02T23:42:10.859+09:00 level=INFO msg="emitting ethernet info changed event" component=server peer="192.168.1.3:56590 @ 0x30000c0" available=true connected=false macAddress= ip4Address= ip6Address= Oct 02 23:42:10 volumio volumio[1229]: info: Received Get System Info Oct 02 23:42:10 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 02 23:42:10 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 02 23:42:10 volumio volumio[1229]: info: Discovery: Getting this device information Oct 02 23:42:10 volumio volumio[1229]: info: CoreCommandRouter::volumioGetState Oct 02 23:42:10 volumio volumio[1229]: info: CorePlayQueue::getTrack 0 Oct 02 23:42:10 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 02 23:42:10 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Oct 02 23:42:10 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Oct 02 23:42:10 volumio bluetoothd[899]: src/advertising.c:add_client_complete() Failed to add advertisement: Rejected (0x0b) Oct 02 23:42:10 volumio volumio5-onboarding[1702]: time=2026-10-02T23:42:10.889+09:00 level=ERROR msg="failed to enable BLE discovery" error="failed to start BLE advertiser: bluetooth: could not start advertisement: Failed to register advertisement" Oct 02 23:42:10 volumio dhcpcd[773]: eth0: soliciting an IPv6 router Oct 02 23:42:11 volumio ntpd[1017]: IO: Deleting interface #6 eth0, 192.168.1.2#123, interface stats: received=2, sent=2, dropped=0, active_time=81 secs Oct 02 23:42:11 volumio ntpd[1017]: PROTO: 3.39.176.65 unlink local addr 192.168.1.2 -> Oct 02 23:42:11 volumio ntpd[1017]: PROTO: 175.195.167.194 unlink local addr 192.168.1.2 -> Oct 02 23:42:11 volumio ntpd[1017]: PROTO: 194.0.5.123 unlink local addr 192.168.1.2 -> Oct 02 23:42:11 volumio ntpd[1017]: PROTO: 121.174.142.81 unlink local addr 192.168.1.2 -> Oct 02 23:42:11 volumio ntpd[1017]: PROTO: 121.134.215.104 unlink local addr 192.168.1.2 -> Oct 02 23:42:11 volumio ntpd[1017]: PROTO: 121.174.142.82 unlink local addr 192.168.1.2 -> Oct 02 23:42:11 volumio ntpd[1017]: PROTO: 193.123.243.2 unlink local addr 192.168.1.2 -> Oct 02 23:42:11 volumio volumio5-onboarding[1702]: time=2026-10-02T23:42:11.733+09:00 level=INFO msg="service successfully established" component=discovery/localnet Oct 02 23:42:12 volumio dhcpcd[773]: eth0: rebinding lease of 192.168.1.2 Oct 02 23:42:12 volumio dhcpcd[773]: eth0: probing address 192.168.1.2/24 Oct 02 23:42:17 volumio dhcpcd[773]: eth0: leased 192.168.1.2 for 86400 seconds Oct 02 23:42:17 volumio avahi-daemon[665]: Joining mDNS multicast group on interface eth0.IPv4 with address 192.168.1.2. Oct 02 23:42:17 volumio avahi-daemon[665]: New relevant interface eth0.IPv4 for mDNS. Oct 02 23:42:17 volumio avahi-daemon[665]: Registering new address record for 192.168.1.2 on eth0.IPv4. Oct 02 23:42:17 volumio dhcpcd[773]: eth0: adding route to 192.168.1.0/24 Oct 02 23:42:17 volumio dhcpcd[773]: eth0: adding default route via 192.168.1.1 Oct 02 23:42:17 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Oct 02 23:42:17 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Oct 02 23:42:17 volumio systemd[1]: welcome.service: Deactivated successfully. Oct 02 23:42:17 volumio systemd[1]: Stopped welcome.service - Show a welcome message on console. Oct 02 23:42:17 volumio systemd[1]: Stopping welcome.service - Show a welcome message on console... Oct 02 23:42:17 volumio systemd[1]: Starting welcome.service - Show a welcome message on console... Oct 02 23:42:17 volumio welcome[17045]: Resolved ip:[1] 192.168.1.2 Oct 02 23:42:17 volumio systemd[1]: Finished welcome.service - Show a welcome message on console. Oct 02 23:42:17 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Oct 02 23:42:17 volumio volumio5-onboarding[1702]: time=2026-10-02T23:42:17.475+09:00 level=INFO msg="established new WebSocket connection" component=conn/ws remoteAddr=192.168.1.3:59718 Oct 02 23:42:17 volumio volumio5-onboarding[1702]: time=2026-10-02T23:42:17.497+09:00 level=INFO msg="device data request" component=server type=REQUEST_TYPE_DEVICE_DATA peer="192.168.1.3:59718 @ 0x318e2d0" latency=25.768149ms timeout=20s Oct 02 23:42:17 volumio volumio5-onboarding[1702]: time=2026-10-02T23:42:17.498+09:00 level=INFO msg="emitting device capabilities changed event" component=server peer="192.168.1.3:59718 @ 0x318e2d0" Oct 02 23:42:17 volumio volumio[1229]: info: Received Get System Info Oct 02 23:42:17 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 02 23:42:17 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 02 23:42:17 volumio volumio[1229]: info: Discovery: Getting this device information Oct 02 23:42:17 volumio volumio[1229]: info: CoreCommandRouter::volumioGetState Oct 02 23:42:17 volumio volumio[1229]: info: CorePlayQueue::getTrack 0 Oct 02 23:42:17 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 02 23:42:17 volumio volumio5-onboarding[1702]: time=2026-10-02T23:42:17.504+09:00 level=INFO msg="emitting device name changed event" component=server peer="192.168.1.3:59718 @ 0x318e2d0" name=Volumio Oct 02 23:42:17 volumio volumio5-onboarding[1702]: time=2026-10-02T23:42:17.506+09:00 level=INFO msg="emitting device language changed event" component=server peer="192.168.1.3:59718 @ 0x318e2d0" language=ko Oct 02 23:42:17 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: system , getCurrentTimezone Oct 02 23:42:17 volumio volumio5-onboarding[1702]: time=2026-10-02T23:42:17.508+09:00 level=INFO msg="emitting device timezone changed event" component=server peer="192.168.1.3:59718 @ 0x318e2d0" timezone=Asia/Seoul Oct 02 23:42:17 volumio volumio5-onboarding[1702]: time=2026-10-02T23:42:17.509+09:00 level=INFO msg="emitting ethernet info changed event" component=server peer="192.168.1.3:59718 @ 0x318e2d0" available=true connected=true macAddress=b8:27:eb:2a:44:ec ip4Address=192.168.1.2/24 ip6Address= Oct 02 23:42:17 volumio volumio5-onboarding[1702]: time=2026-10-02T23:42:17.511+09:00 level=INFO msg="emitting wifi info changed event" component=server peer="192.168.1.3:59718 @ 0x318e2d0" available=true connected=false macAddress= ip4Address= ip6Address= ssid= Oct 02 23:42:17 volumio volumio5-onboarding[1702]: time=2026-10-02T23:42:17.512+09:00 level=INFO msg="emitting device setup status changed event" component=server peer="192.168.1.3:59718 @ 0x318e2d0" setupComplete=true Oct 02 23:42:17 volumio volumio5-onboarding[1702]: time=2026-10-02T23:42:17.512+09:00 level=INFO msg="check connectivity" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.3:59718 @ 0x318e2d0" latency=31.051382ms timeout=10s Oct 02 23:42:17 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getExtendedOutputDevices Oct 02 23:42:17 volumio volumio5-onboarding[1702]: time=2026-10-02T23:42:17.516+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.3:59718 @ 0x318e2d0" latency=31.051382ms timeout=10s endpoint=https://radio-directory.firebaseapp.com duration=4.207814ms Oct 02 23:42:17 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions Oct 02 23:42:17 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 02 23:42:17 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Oct 02 23:42:17 volumio volumio[1229]: amixer -c 0 info | grep "bcm2835 ALSA" Oct 02 23:42:17 volumio volumio[1229]: amixer -c 1 info | grep "bcm2835 Headphones" Oct 02 23:42:17 volumio volumio5-onboarding[1702]: time=2026-10-02T23:42:17.622+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.3:59718 @ 0x318e2d0" latency=31.051382ms timeout=10s endpoint=https://browsing-performer.dfs.volumio.org duration=109.190865ms Oct 02 23:42:17 volumio volumio5-onboarding[1702]: time=2026-10-02T23:42:17.622+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.3:59718 @ 0x318e2d0" latency=31.051382ms timeout=10s endpoint=https://oauth-performer.dfs.volumio.org duration=109.712636ms Oct 02 23:42:17 volumio volumio[1229]: Card sysdefault:1 'Headphones'/'bcm2835 Headphones' Oct 02 23:42:17 volumio volumio[1229]: error: Cannot read Audio Device Capabilities Command failed: /usr/local/bin/alsacap -C 2 Oct 02 23:42:17 volumio volumio[1229]: /bin/sh: 1: /usr/local/bin/alsacap: not found Oct 02 23:42:17 volumio volumio[1229]: {"cmd":"/usr/local/bin/alsacap -C 2","code":127,"killed":false,"signal":null,"stack":"Error: Command failed: /usr/local/bin/alsacap -C 2\n/bin/sh: 1: /usr/local/bin/alsacap: not found\n\n at ChildProcess.exithandler (node:child_process:421:12)\n at ChildProcess.emit (node:events:514:28)\n at maybeClose (node:internal/child_process:1105:16)\n at Socket. (node:internal/child_process:457:11)\n at Socket.emit (node:events:514:28)\n at Pipe. (node:net:337:12)"} Oct 02 23:42:17 volumio volumio[1229]: amixer -c 2 info | grep "vc4-hdmi" Oct 02 23:42:17 volumio volumio5-onboarding[1702]: time=2026-10-02T23:42:17.660+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.3:59718 @ 0x318e2d0" latency=31.051382ms timeout=10s endpoint=https://www.googleapis.com duration=147.430616ms Oct 02 23:42:17 volumio volumio[1229]: Card sysdefault:2 'vc4hdmi'/'vc4-hdmi' Oct 02 23:42:17 volumio volumio[1229]: error: Cannot read Audio Device Capabilities Command failed: /usr/local/bin/alsacap -C 5 Oct 02 23:42:17 volumio volumio[1229]: /bin/sh: 1: /usr/local/bin/alsacap: not found Oct 02 23:42:17 volumio volumio[1229]: {"cmd":"/usr/local/bin/alsacap -C 5","code":127,"killed":false,"signal":null,"stack":"Error: Command failed: /usr/local/bin/alsacap -C 5\n/bin/sh: 1: /usr/local/bin/alsacap: not found\n\n at ChildProcess.exithandler (node:child_process:421:12)\n at ChildProcess.emit (node:events:514:28)\n at maybeClose (node:internal/child_process:1105:16)\n at Socket. (node:internal/child_process:457:11)\n at Socket.emit (node:events:514:28)\n at Pipe. (node:net:337:12)"} Oct 02 23:42:17 volumio volumio[1229]: amixer -c 5 info | grep "Combo384 Amanero" Oct 02 23:42:17 volumio volumio5-onboarding[1702]: time=2026-10-02T23:42:17.696+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.3:59718 @ 0x318e2d0" latency=31.051382ms timeout=10s endpoint=https://myvolumio.firebaseio.com duration=182.955209ms Oct 02 23:42:17 volumio volumio5-onboarding[1702]: time=2026-10-02T23:42:17.702+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.3:59718 @ 0x318e2d0" latency=31.051382ms timeout=10s endpoint=https://google.com duration=189.550472ms Oct 02 23:42:17 volumio volumio[1229]: Card sysdefault:5 'Amanero'/'Amanero Technologies Combo384 Amanero at usb-3f980000.usb-1.4, high speed' Oct 02 23:42:17 volumio volumio[1229]: error: Cannot read Audio Device Capabilities Command failed: /usr/local/bin/alsacap -C 5 Oct 02 23:42:17 volumio volumio[1229]: /bin/sh: 1: /usr/local/bin/alsacap: not found Oct 02 23:42:17 volumio volumio[1229]: {"cmd":"/usr/local/bin/alsacap -C 5","code":127,"killed":false,"signal":null,"stack":"Error: Command failed: /usr/local/bin/alsacap -C 5\n/bin/sh: 1: /usr/local/bin/alsacap: not found\n\n at ChildProcess.exithandler (node:child_process:421:12)\n at ChildProcess.emit (node:events:514:28)\n at maybeClose (node:internal/child_process:1105:16)\n at Socket. (node:internal/child_process:457:11)\n at Socket.emit (node:events:514:28)\n at Pipe. (node:net:337:12)"} Oct 02 23:42:17 volumio volumio[1229]: amixer -c 5 info | grep "Combo384 Amanero" Oct 02 23:42:17 volumio volumio5-onboarding[1702]: time=2026-10-02T23:42:17.738+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.3:59718 @ 0x318e2d0" latency=31.051382ms timeout=10s endpoint=http://pushupdates.volumio.org duration=225.093867ms Oct 02 23:42:17 volumio volumio5-onboarding[1702]: time=2026-10-02T23:42:17.741+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.3:59718 @ 0x318e2d0" latency=31.051382ms timeout=10s endpoint=https://securetoken.googleapis.com duration=227.885117ms Oct 02 23:42:17 volumio volumio5-onboarding[1702]: time=2026-10-02T23:42:17.750+09:00 level=INFO msg="emitting ethernet info changed event" component=server peer="192.168.1.3:56590 @ 0x30000c0" available=true connected=true macAddress=b8:27:eb:2a:44:ec ip4Address=192.168.1.2/24 ip6Address= Oct 02 23:42:17 volumio volumio5-onboarding[1702]: time=2026-10-02T23:42:17.751+09:00 level=INFO msg="emitting ethernet info changed event" component=server peer="192.168.1.3:59718 @ 0x318e2d0" available=true connected=true macAddress=b8:27:eb:2a:44:ec ip4Address=192.168.1.2/24 ip6Address= Oct 02 23:42:17 volumio volumio[1229]: Card sysdefault:5 'Amanero'/'Amanero Technologies Combo384 Amanero at usb-3f980000.usb-1.4, high speed' Oct 02 23:42:17 volumio volumio5-onboarding[1702]: time=2026-10-02T23:42:17.754+09:00 level=INFO msg="emitting audio outputs changed event" component=server peer="192.168.1.3:59718 @ 0x318e2d0" selectedOutputId=5 Oct 02 23:42:17 volumio volumio[1229]: info: Received Get System Info Oct 02 23:42:17 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 02 23:42:17 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 02 23:42:17 volumio volumio[1229]: info: Discovery: Getting this device information Oct 02 23:42:17 volumio volumio[1229]: info: CoreCommandRouter::volumioGetState Oct 02 23:42:17 volumio volumio[1229]: info: CorePlayQueue::getTrack 0 Oct 02 23:42:17 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 02 23:42:17 volumio volumio5-onboarding[1702]: time=2026-10-02T23:42:17.755+09:00 level=ERROR msg="failed to read message" component=conn/ws remoteAddr=192.168.1.3:56590 error="read tcp 192.168.1.2:7331->192.168.1.3:56590: read: connection reset by peer" Oct 02 23:42:17 volumio volumio5-onboarding[1702]: time=2026-10-02T23:42:17.755+09:00 level=INFO msg="WebSocket connection closed" component=conn/ws remoteAddr=192.168.1.3:56590 Oct 02 23:42:17 volumio volumio5-onboarding[1702]: time=2026-10-02T23:42:17.755+09:00 level=INFO msg="connection to address closed" component=conn/multi addr=192.168.1.3:56590 Oct 02 23:42:17 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Oct 02 23:42:17 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Oct 02 23:42:17 volumio volumio5-onboarding[1702]: time=2026-10-02T23:42:17.763+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.3:59718 @ 0x318e2d0" latency=31.051382ms timeout=10s endpoint=https://database.volumio.cloud duration=250.258926ms Oct 02 23:42:17 volumio volumio5-onboarding[1702]: time=2026-10-02T23:42:17.768+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.3:59718 @ 0x318e2d0" latency=31.051382ms timeout=10s endpoint=https://functions.volumio.cloud duration=255.062365ms Oct 02 23:42:17 volumio volumio5-onboarding[1702]: time=2026-10-02T23:42:17.776+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.3:59718 @ 0x318e2d0" latency=31.051382ms timeout=10s endpoint=https://functions.volumio.cloud duration=263.138357ms Oct 02 23:42:17 volumio volumio[1229]: info: Received Get System Info Oct 02 23:42:17 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 02 23:42:17 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 02 23:42:17 volumio volumio[1229]: info: Discovery: Getting this device information Oct 02 23:42:17 volumio volumio[1229]: info: CoreCommandRouter::volumioGetState Oct 02 23:42:17 volumio volumio[1229]: info: CorePlayQueue::getTrack 0 Oct 02 23:42:17 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 02 23:42:17 volumio volumio5-onboarding[1702]: time=2026-10-02T23:42:17.796+09:00 level=INFO msg="emitting software info changed event" component=server peer="192.168.1.3:59718 @ 0x318e2d0" currentVersion=4.119 latestVersion=4.119 Oct 02 23:42:17 volumio volumio5-onboarding[1702]: time=2026-10-02T23:42:17.797+09:00 level=INFO msg="emitting software update progress event" component=server peer="192.168.1.3:59718 @ 0x318e2d0" status=UPDATE_STATUS_NONE progress=0 Oct 02 23:42:17 volumio volumio5-onboarding[1702]: time=2026-10-02T23:42:17.798+09:00 level=INFO msg="emitting user changed event" component=server peer="192.168.1.3:59718 @ 0x318e2d0" userId=WrOLSsfUwwZEN1RcIYsWy7KELw23 Oct 02 23:42:17 volumio volumio5-onboarding[1702]: time=2026-10-02T23:42:17.799+09:00 level=INFO msg="emitting music providers changed event" component=server peer="192.168.1.3:59718 @ 0x318e2d0" providers=9 Oct 02 23:42:17 volumio volumio5-onboarding[1702]: time=2026-10-02T23:42:17.800+09:00 level=INFO msg="emitting plugins changed event" component=server peer="192.168.1.3:59718 @ 0x318e2d0" plugins=74 Oct 02 23:42:17 volumio bluetoothd[899]: src/advertising.c:add_client_complete() Failed to add advertisement: Rejected (0x0b) Oct 02 23:42:17 volumio volumio5-onboarding[1702]: time=2026-10-02T23:42:17.802+09:00 level=ERROR msg="failed to enable BLE discovery" error="failed to start BLE advertiser: bluetooth: could not start advertisement: Failed to register advertisement" Oct 02 23:42:17 volumio volumio[1229]: info: CoreCommandRouter::volumioGetState Oct 02 23:42:17 volumio volumio[1229]: info: CorePlayQueue::getTrack 0 Oct 02 23:42:17 volumio volumio5-onboarding[1702]: time=2026-10-02T23:42:17.806+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.3:59718 @ 0x318e2d0" state=STATUS_STOPPED positionMs=0 volume=100 Oct 02 23:42:17 volumio volumio5-onboarding[1702]: time=2026-10-02T23:42:17.806+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.3:59718 @ 0x318e2d0" id= title= Oct 02 23:42:18 volumio volumio[1229]: info: Discovery: adding 8f82119c-51b4-4773-a91f-fd28ca0e1842 Oct 02 23:42:18 volumio volumio[1229]: info: Discovery: Found device Volumio Oct 02 23:42:18 volumio volumio[1229]: info: CoreCommandRouter::volumioGetState Oct 02 23:42:18 volumio volumio[1229]: info: CorePlayQueue::getTrack 0 Oct 02 23:42:18 volumio volumio[1229]: info: Discovery: this is already registered, 8f82119c-51b4-4773-a91f-fd28ca0e1842 Oct 02 23:42:18 volumio volumio[1229]: info: Discovery: Found device Volumio Oct 02 23:42:18 volumio volumio[1229]: info: CoreCommandRouter::volumioGetState Oct 02 23:42:18 volumio volumio[1229]: info: CorePlayQueue::getTrack 0 Oct 02 23:42:18 volumio volumio[1229]: info: Discovery: this is already registered, 8f82119c-51b4-4773-a91f-fd28ca0e1842 Oct 02 23:42:18 volumio volumio[1229]: info: Discovery: Found device Volumio Oct 02 23:42:18 volumio volumio[1229]: info: CoreCommandRouter::volumioGetState Oct 02 23:42:18 volumio volumio[1229]: info: CorePlayQueue::getTrack 0 Oct 02 23:42:18 volumio volumio5-onboarding[1702]: time=2026-10-02T23:42:18.666+09:00 level=INFO msg="service successfully established" component=discovery/localnet Oct 02 23:42:18 volumio ntpd[1017]: IO: Listen normally on 7 eth0 192.168.1.2:123 Oct 02 23:42:18 volumio ntpd[1017]: IO: new interface(s) found: waking up resolver Oct 02 23:42:18 volumio volumio[1229]: info: Discovery: Networking Restart detected, restarting advertisement and browsing Oct 02 23:42:18 volumio volumio[1229]: info: Discovery: Restarting Advertising Oct 02 23:42:18 volumio volumio[1229]: info: Discovery: Stopping existing advertisement Oct 02 23:42:18 volumio volumio[1229]: info: Discovery: Restarting Browsing Oct 02 23:42:18 volumio volumio5-onboarding[1702]: time=2026-10-02T23:42:18.733+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.3:59718 @ 0x318e2d0" latency=31.051382ms timeout=10s endpoint=http://plugins.volumio.org duration=1.220710977s Oct 02 23:42:18 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 02 23:42:18 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 02 23:42:18 volumio volumio[1229]: info: Discovery: Getting this device information Oct 02 23:42:18 volumio volumio[1229]: info: CoreCommandRouter::volumioGetState Oct 02 23:42:18 volumio volumio[1229]: info: CorePlayQueue::getTrack 0 Oct 02 23:42:18 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 02 23:42:18 volumio volumio[1229]: verbose: New Socket.io Connection to 192.168.1.2:3000 from 192.168.1.3 UA: Dart/3.12 (dart:io) Engine version: 3 Transport: websocket Total Clients: 7 Oct 02 23:42:18 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Oct 02 23:42:18 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Oct 02 23:42:18 volumio volumio5-onboarding[1702]: time=2026-10-02T23:42:18.808+09:00 level=ERROR msg="endpoint is not reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.3:59718 @ 0x318e2d0" latency=31.051382ms timeout=10s endpoint=http://cddb.volumio.org duration=1.294827925s error="Head \"http://gnudb.gnudb.org/~cddb/cddb.cgi/\": EOF" Oct 02 23:42:18 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: upnp , onRestart Oct 02 23:42:18 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: network , onNetworkingRestart Oct 02 23:42:18 volumio volumio[1229]: info: Refreshing Cached IP Addresses Oct 02 23:42:18 volumio sudo[17085]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/killall upmpdcli Oct 02 23:42:18 volumio sudo[17085]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 02 23:42:18 volumio sudo[17087]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 02 23:42:18 volumio sudo[17087]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 02 23:42:18 volumio sudo[17085]: pam_unix(sudo:session): session closed for user root Oct 02 23:42:18 volumio sudo[17087]: pam_unix(sudo:session): session closed for user root Oct 02 23:42:18 volumio sudo[17089]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 02 23:42:18 volumio sudo[17089]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 02 23:42:18 volumio sudo[17089]: pam_unix(sudo:session): session closed for user root Oct 02 23:42:19 volumio sudo[17094]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 02 23:42:19 volumio sudo[17094]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 02 23:42:19 volumio sudo[17094]: pam_unix(sudo:session): session closed for user root Oct 02 23:42:19 volumio sudo[17103]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 02 23:42:19 volumio sudo[17103]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 02 23:42:19 volumio volumio[1229]: info: Volumio Network Manager: Network status updated: 1 Oct 02 23:42:19 volumio sudo[17103]: pam_unix(sudo:session): session closed for user root Oct 02 23:42:19 volumio volumio[1229]: verbose: New Socket.io Connection to 192.168.1.2 from 192.168.1.3 UA: Mozilla/5.0 (Linux; Android 9; Lenovo YT-X705F Build/PKQ1.181218.001; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/138.0.7204.179 Safari/537.36 VolumioApp/6.260915.0 Engine version: 3 Transport: polling Total Clients: 6 Oct 02 23:42:19 volumio volumio[1229]: info: Discovery: A device disappeared from network Oct 02 23:42:19 volumio volumio[1229]: info: Discovery: A device disappeared from network Oct 02 23:42:19 volumio volumio[1229]: info: Discovery: A device disappeared from network Oct 02 23:42:19 volumio volumio[1229]: info: Discovery: A device disappeared from network Oct 02 23:42:19 volumio volumio[1229]: info: Discovery: A device disappeared from network Oct 02 23:42:19 volumio volumio[1229]: info: Discovery: A device disappeared from network Oct 02 23:42:20 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Oct 02 23:42:20 volumio volumio[1229]: info: CoreCommandRouter::volumioGetVisibleSources Oct 02 23:42:20 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 02 23:42:20 volumio volumio[1229]: info: CoreCommandRouter::volumioGetState Oct 02 23:42:20 volumio volumio[1229]: info: CorePlayQueue::getTrack 0 Oct 02 23:42:20 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Oct 02 23:42:20 volumio volumio[1229]: info: CoreCommandRouter::getUIConfigOnPlugin Oct 02 23:42:20 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Oct 02 23:42:20 volumio volumio[1229]: info: Received Get System Info Oct 02 23:42:20 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 02 23:42:20 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 02 23:42:20 volumio volumio[1229]: info: Discovery: Getting this device information Oct 02 23:42:20 volumio volumio[1229]: info: CoreCommandRouter::volumioGetState Oct 02 23:42:20 volumio volumio[1229]: info: CorePlayQueue::getTrack 0 Oct 02 23:42:20 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 02 23:42:20 volumio volumio[1229]: info: CoreCommandRouter::volumioGetState Oct 02 23:42:20 volumio volumio[1229]: info: CorePlayQueue::getTrack 0 Oct 02 23:42:20 volumio volumio[1229]: info: Listing playlists Oct 02 23:42:20 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Oct 02 23:42:20 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Oct 02 23:42:20 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus Oct 02 23:42:20 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Oct 02 23:42:21 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: network , getInfoNetwork Oct 02 23:42:21 volumio sudo[17118]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ethtool eth0 Oct 02 23:42:21 volumio sudo[17118]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 02 23:42:21 volumio sudo[17123]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwconfig wlan0 Oct 02 23:42:21 volumio sudo[17118]: pam_unix(sudo:session): session closed for user root Oct 02 23:42:21 volumio sudo[17123]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 02 23:42:21 volumio volumio5-onboarding[1702]: time=2026-10-02T23:42:21.190+09:00 level=INFO msg="check connectivity" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.3:59718 @ 0x318e2d0" latency=55.091037ms timeout=10s Oct 02 23:42:21 volumio volumio5-onboarding[1702]: time=2026-10-02T23:42:21.195+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.3:59718 @ 0x318e2d0" latency=55.091037ms timeout=10s endpoint=https://radio-directory.firebaseapp.com duration=4.825991ms Oct 02 23:42:21 volumio sudo[17123]: pam_unix(sudo:session): session closed for user root Oct 02 23:42:21 volumio sudo[17130]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwconfig wlan0 Oct 02 23:42:21 volumio sudo[17130]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 02 23:42:21 volumio sudo[17130]: pam_unix(sudo:session): session closed for user root Oct 02 23:42:21 volumio sudo[17142]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 02 23:42:21 volumio sudo[17142]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 02 23:42:21 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: network , getWirelessNetworksScanCache Oct 02 23:42:21 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: network , getWirelessNetworks Oct 02 23:42:21 volumio sudo[17138]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwconfig wlan0 Oct 02 23:42:21 volumio sudo[17138]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 02 23:42:21 volumio sudo[17142]: pam_unix(sudo:session): session closed for user root Oct 02 23:42:21 volumio sudo[17138]: pam_unix(sudo:session): session closed for user root Oct 02 23:42:21 volumio sudo[17145]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 02 23:42:21 volumio sudo[17145]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 02 23:42:21 volumio sudo[17145]: pam_unix(sudo:session): session closed for user root Oct 02 23:42:21 volumio volumio5-onboarding[1702]: time=2026-10-02T23:42:21.294+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.3:59718 @ 0x318e2d0" latency=55.091037ms timeout=10s endpoint=https://browsing-performer.dfs.volumio.org duration=102.57253ms Oct 02 23:42:21 volumio volumio5-onboarding[1702]: time=2026-10-02T23:42:21.295+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.3:59718 @ 0x318e2d0" latency=55.091037ms timeout=10s endpoint=https://oauth-performer.dfs.volumio.org duration=105.104458ms Oct 02 23:42:21 volumio volumio5-onboarding[1702]: time=2026-10-02T23:42:21.330+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.3:59718 @ 0x318e2d0" latency=55.091037ms timeout=10s endpoint=https://www.googleapis.com duration=138.496759ms Oct 02 23:42:21 volumio volumio5-onboarding[1702]: time=2026-10-02T23:42:21.355+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.3:59718 @ 0x318e2d0" latency=55.091037ms timeout=10s endpoint=https://google.com duration=164.547339ms Oct 02 23:42:21 volumio volumio5-onboarding[1702]: time=2026-10-02T23:42:21.370+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.3:59718 @ 0x318e2d0" latency=55.091037ms timeout=10s endpoint=https://myvolumio.firebaseio.com duration=177.936926ms Oct 02 23:42:21 volumio volumio5-onboarding[1702]: time=2026-10-02T23:42:21.416+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.3:59718 @ 0x318e2d0" latency=55.091037ms timeout=10s endpoint=https://securetoken.googleapis.com duration=225.013241ms Oct 02 23:42:21 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Oct 02 23:42:21 volumio volumio[1229]: info: Received Get System Info Oct 02 23:42:21 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 02 23:42:21 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 02 23:42:21 volumio volumio[1229]: info: Discovery: Getting this device information Oct 02 23:42:21 volumio volumio[1229]: info: CoreCommandRouter::volumioGetState Oct 02 23:42:21 volumio volumio[1229]: info: CorePlayQueue::getTrack 0 Oct 02 23:42:21 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 02 23:42:21 volumio volumio5-onboarding[1702]: time=2026-10-02T23:42:21.427+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.3:59718 @ 0x318e2d0" latency=55.091037ms timeout=10s endpoint=http://pushupdates.volumio.org duration=235.345484ms Oct 02 23:42:21 volumio volumio5-onboarding[1702]: time=2026-10-02T23:42:21.439+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.3:59718 @ 0x318e2d0" latency=55.091037ms timeout=10s endpoint=https://database.volumio.cloud duration=247.278978ms Oct 02 23:42:21 volumio volumio5-onboarding[1702]: time=2026-10-02T23:42:21.442+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.3:59718 @ 0x318e2d0" latency=55.091037ms timeout=10s endpoint=https://functions.volumio.cloud duration=249.391687ms Oct 02 23:42:21 volumio volumio5-onboarding[1702]: time=2026-10-02T23:42:21.443+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.3:59718 @ 0x318e2d0" latency=55.091037ms timeout=10s endpoint=https://functions.volumio.cloud duration=252.250698ms Oct 02 23:42:21 volumio volumio5-onboarding[1702]: time=2026-10-02T23:42:21.593+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.3:59718 @ 0x318e2d0" latency=55.091037ms timeout=10s endpoint=http://plugins.volumio.org duration=401.467355ms Oct 02 23:42:21 volumio volumio5-onboarding[1702]: time=2026-10-02T23:42:21.827+09:00 level=ERROR msg="endpoint is not reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.3:59718 @ 0x318e2d0" latency=55.091037ms timeout=10s endpoint=http://cddb.volumio.org duration=634.904558ms error="Head \"http://gnudb.gnudb.org/~cddb/cddb.cgi/\": EOF" Oct 02 23:42:22 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Oct 02 23:42:23 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Oct 02 23:42:23 volumio volumio[1229]: info: Received Get System Info Oct 02 23:42:23 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 02 23:42:23 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 02 23:42:23 volumio volumio[1229]: info: Discovery: Getting this device information Oct 02 23:42:23 volumio volumio[1229]: info: CoreCommandRouter::volumioGetState Oct 02 23:42:23 volumio volumio[1229]: info: CorePlayQueue::getTrack 0 Oct 02 23:42:23 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 02 23:42:23 volumio volumio[1229]: info: Discovery: Started advertising with name: Volumio Oct 02 23:42:24 volumio volumio[1229]: info: Discovery: adding 8f82119c-51b4-4773-a91f-fd28ca0e1842 Oct 02 23:42:24 volumio volumio[1229]: info: Discovery: Found device Volumio Oct 02 23:42:24 volumio volumio[1229]: info: CoreCommandRouter::volumioGetState Oct 02 23:42:24 volumio volumio[1229]: info: CorePlayQueue::getTrack 0 Oct 02 23:42:24 volumio volumio[1229]: info: Discovery: this is already registered, 8f82119c-51b4-4773-a91f-fd28ca0e1842 Oct 02 23:42:24 volumio volumio[1229]: info: Discovery: Found device Volumio Oct 02 23:42:24 volumio volumio[1229]: info: CoreCommandRouter::volumioGetState Oct 02 23:42:24 volumio volumio[1229]: info: CorePlayQueue::getTrack 0 Oct 02 23:42:24 volumio volumio[1229]: info: Discovery: this is already registered, 8f82119c-51b4-4773-a91f-fd28ca0e1842 Oct 02 23:42:24 volumio volumio[1229]: info: Discovery: Found device Volumio Oct 02 23:42:24 volumio volumio[1229]: info: CoreCommandRouter::volumioGetState Oct 02 23:42:24 volumio volumio[1229]: info: CorePlayQueue::getTrack 0 Oct 02 23:42:24 volumio volumio[1229]: info: Discovery: this is already registered, 8f82119c-51b4-4773-a91f-fd28ca0e1842 Oct 02 23:42:24 volumio volumio[1229]: info: Discovery: Found device Volumio Oct 02 23:42:24 volumio volumio[1229]: info: CoreCommandRouter::volumioGetState Oct 02 23:42:24 volumio volumio[1229]: info: CorePlayQueue::getTrack 0 Oct 02 23:42:24 volumio volumio[1229]: info: Discovery: this is already registered, 8f82119c-51b4-4773-a91f-fd28ca0e1842 Oct 02 23:42:24 volumio volumio[1229]: info: Discovery: Found device Volumio Oct 02 23:42:24 volumio volumio[1229]: info: CoreCommandRouter::volumioGetState Oct 02 23:42:24 volumio volumio[1229]: info: CorePlayQueue::getTrack 0 Oct 02 23:42:24 volumio volumio[1229]: info: Discovery: this is already registered, 8f82119c-51b4-4773-a91f-fd28ca0e1842 Oct 02 23:42:24 volumio volumio[1229]: info: Discovery: Found device Volumio Oct 02 23:42:24 volumio volumio[1229]: info: CoreCommandRouter::volumioGetState Oct 02 23:42:24 volumio volumio[1229]: info: CorePlayQueue::getTrack 0 Oct 02 23:42:24 volumio volumio[1229]: info: Discovery: this is already registered, 8f82119c-51b4-4773-a91f-fd28ca0e1842 Oct 02 23:42:24 volumio volumio[1229]: info: Discovery: Found device Volumio Oct 02 23:42:24 volumio volumio[1229]: info: CoreCommandRouter::volumioGetState Oct 02 23:42:24 volumio volumio[1229]: info: CorePlayQueue::getTrack 0 Oct 02 23:42:24 volumio volumio[1229]: info: Discovery: this is already registered, 8f82119c-51b4-4773-a91f-fd28ca0e1842 Oct 02 23:42:24 volumio volumio[1229]: info: Discovery: Found device Volumio Oct 02 23:42:24 volumio volumio[1229]: info: CoreCommandRouter::volumioGetState Oct 02 23:42:24 volumio volumio[1229]: info: CorePlayQueue::getTrack 0 Oct 02 23:42:24 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 02 23:42:24 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 02 23:42:24 volumio volumio[1229]: info: Discovery: Getting this device information Oct 02 23:42:24 volumio volumio[1229]: info: CoreCommandRouter::volumioGetState Oct 02 23:42:24 volumio volumio[1229]: info: CorePlayQueue::getTrack 0 Oct 02 23:42:24 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 02 23:42:24 volumio volumio[1229]: verbose: New Socket.io Connection to 192.168.1.2:3000 from 192.168.1.3 UA: Dart/3.12 (dart:io) Engine version: 3 Transport: websocket Total Clients: 7 Oct 02 23:42:24 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Oct 02 23:42:24 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Oct 02 23:42:25 volumio volumio[1229]: info: CoreCommandRouter::getUIConfigOnPlugin Oct 02 23:42:25 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions Oct 02 23:42:25 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 02 23:42:25 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Oct 02 23:42:25 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 02 23:42:25 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 02 23:42:25 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 02 23:42:25 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 02 23:42:25 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 02 23:42:25 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 02 23:42:25 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 02 23:42:25 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: mpd , getPlaybackMode Oct 02 23:42:25 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus Oct 02 23:42:28 volumio sudo[17169]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 02 23:42:28 volumio sudo[17171]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 02 23:42:28 volumio sudo[17169]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 02 23:42:28 volumio sudo[17171]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 02 23:42:28 volumio sudo[17169]: pam_unix(sudo:session): session closed for user root Oct 02 23:42:28 volumio sudo[17171]: pam_unix(sudo:session): session closed for user root Oct 02 23:42:28 volumio sudo[17173]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Oct 02 23:42:28 volumio sudo[17173]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 02 23:42:29 volumio sudo[17173]: pam_unix(sudo:session): session closed for user root Oct 02 23:42:29 volumio volumio[1229]: info: Upmpdcli Daemon Started Oct 02 23:42:29 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Oct 02 23:42:37 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Oct 02 23:42:37 volumio volumio[1229]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Oct 02 23:42:37 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Oct 02 23:42:37 volumio volumio[1229]: info: Received Get System Version Oct 02 23:42:37 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 02 23:42:37 volumio volumio[1229]: info: Received Get System Info Oct 02 23:42:37 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 02 23:42:37 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 02 23:42:37 volumio volumio[1229]: info: Discovery: Getting this device information Oct 02 23:42:37 volumio volumio[1229]: info: CoreCommandRouter::volumioGetState Oct 02 23:42:37 volumio volumio[1229]: info: CorePlayQueue::getTrack 0 Oct 02 23:42:37 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 02 23:42:38 volumio volumio[1229]: info: CALLMETHOD: audio_interface alsa_controller saveAlsaOptions [object Object] Oct 02 23:42:38 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , saveAlsaOptions Oct 02 23:42:38 volumio volumio[1229]: info: Preparing to save Alsa Options, stopping services first Oct 02 23:42:38 volumio volumio[1229]: info: CoreCommandRouter::volumioGetState Oct 02 23:42:38 volumio volumio[1229]: info: CorePlayQueue::getTrack 0 Oct 02 23:42:38 volumio volumio[1229]: info: CoreCommandRouter::volumioPause Oct 02 23:42:38 volumio volumio[1229]: info: CoreStateMachine::pause Oct 02 23:42:38 volumio volumio[1229]: info: Saving Audio Output to: {"output_device":{"value":"5","label":"Combo384 Amanero"},"i2s":false,"i2sid":{"value":"adafruit-max98357","label":"Adafruit MAX98357"}} Oct 02 23:42:38 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Oct 02 23:42:38 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Oct 02 23:42:38 volumio volumio[1229]: info: Setting mixer PCM for card Combo384 Amanero Oct 02 23:42:38 volumio volumio[1229]: info: CoreCommandRouter::volumioUpdateVolumeSettings Oct 02 23:42:38 volumio volumio[1229]: info: Updating Volume Controller Parameters: Device: 5 Name: Combo384 Amanero Mixer: PCM Max Vol: 100 Vol Curve; logarithmic Vol Steps: 1 Oct 02 23:42:38 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , setExternalVolume Oct 02 23:42:38 volumio volumio[1229]: info: Disabling external Volume Control Oct 02 23:42:38 volumio volumio[1229]: info: CoreCommandRouter::getUIConfigOnPlugin Oct 02 23:42:38 volumio volumio[1229]: info: Preparing to generate the ALSA configuration file Oct 02 23:42:38 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions Oct 02 23:42:38 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 02 23:42:38 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Oct 02 23:42:39 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 02 23:42:39 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 02 23:42:39 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 02 23:42:39 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 02 23:42:39 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 02 23:42:39 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 02 23:42:39 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 02 23:42:39 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: mpd , getPlaybackMode Oct 02 23:42:39 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus Oct 02 23:42:39 volumio volumio[1229]: info: Asound.conf file unchanged, so no further update is needed Oct 02 23:42:39 volumio volumio[1229]: info: Output device has changed, restarting MPD Oct 02 23:42:39 volumio sudo[17213]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 02 23:42:39 volumio sudo[17213]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 02 23:42:39 volumio sudo[17213]: pam_unix(sudo:session): session closed for user root Oct 02 23:42:39 volumio sudo[17215]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 02 23:42:39 volumio sudo[17215]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 02 23:42:39 volumio volumio[1229]: info: VolumeController:: Volume=100 Mute =false Oct 02 23:42:39 volumio volumio[1229]: info: CoreStateMachine::pushState Oct 02 23:42:39 volumio volumio[1229]: info: CorePlayQueue::getTrack 0 Oct 02 23:42:39 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 02 23:42:39 volumio volumio[1229]: info: CoreCommandRouter::volumioPushState Oct 02 23:42:39 volumio volumio5-onboarding[1702]: time=2026-10-02T23:42:39.081+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.3:59718 @ 0x318e2d0" state=STATUS_STOPPED positionMs=0 volume=100 Oct 02 23:42:39 volumio volumio5-onboarding[1702]: time=2026-10-02T23:42:39.081+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.3:59718 @ 0x318e2d0" id= title= Oct 02 23:42:39 volumio volumio[1229]: info: MPD Permissions set Oct 02 23:42:39 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 02 23:42:39 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 02 23:42:39 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 02 23:42:39 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 02 23:42:39 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 02 23:42:39 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 02 23:42:39 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 02 23:42:39 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 02 23:42:39 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Oct 02 23:42:39 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 02 23:42:39 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 02 23:42:39 volumio systemd[1]: mpd.service: Deactivated successfully. Oct 02 23:42:39 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Oct 02 23:42:39 volumio systemd[1]: mpd.service: Consumed 2.978s CPU time. Oct 02 23:42:39 volumio systemd[1]: mpd.socket: Deactivated successfully. Oct 02 23:42:39 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Oct 02 23:42:39 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Oct 02 23:42:39 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Oct 02 23:42:39 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Oct 02 23:42:39 volumio sudo[17224]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Oct 02 23:42:39 volumio sudo[17224]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Oct 02 23:42:39 volumio sudo[17224]: pam_unix(sudo:session): session closed for user root Oct 02 23:42:42 volumio mpd[17226]: 2026-10-02T23:42:42 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Oct 02 23:42:42 volumio systemd[1]: Started mpd.service - Music Player Daemon. Oct 02 23:42:42 volumio sudo[17215]: pam_unix(sudo:session): session closed for user root Oct 02 23:42:42 volumio volumio[1229]: error: updateQueue error: null Oct 02 23:42:42 volumio volumio[1229]: info: CoreCommandRouter::volumioRetrieveVolumeLevels Oct 02 23:42:42 volumio volumio[1229]: info: CoreStateMachine::getcurrentVolume Oct 02 23:42:42 volumio volumio[1229]: info: CoreCommandRouter::volumioRetrievevolume Oct 02 23:42:42 volumio volumio[1229]: info: VolumeController:: Volume=100 Mute =false Oct 02 23:42:42 volumio volumio[1229]: info: CoreStateMachine::pushState Oct 02 23:42:42 volumio volumio[1229]: info: CorePlayQueue::getTrack 0 Oct 02 23:42:42 volumio volumio[1229]: info: CoreCommandRouter::volumioPushState Oct 02 23:42:42 volumio volumio[1229]: info: CoreStateMachine::updateTrackBlock Oct 02 23:42:42 volumio volumio[1229]: info: CorePlayQueue::getTrackBlock Oct 02 23:42:42 volumio volumio[1229]: info: CoreCommandRouter::volumioRetrievevolume Oct 02 23:42:42 volumio volumio5-onboarding[1702]: time=2026-10-02T23:42:42.984+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.3:59718 @ 0x318e2d0" state=STATUS_STOPPED positionMs=0 volume=100 Oct 02 23:42:42 volumio volumio5-onboarding[1702]: time=2026-10-02T23:42:42.985+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.3:59718 @ 0x318e2d0" id= title= Oct 02 23:42:43 volumio volumio[1229]: info: VolumeController:: Volume=100 Mute =false Oct 02 23:42:43 volumio volumio[1229]: info: CoreStateMachine::pushState Oct 02 23:42:43 volumio volumio[1229]: info: CorePlayQueue::getTrack 0 Oct 02 23:42:43 volumio volumio[1229]: info: CoreCommandRouter::volumioPushState Oct 02 23:42:43 volumio volumio5-onboarding[1702]: time=2026-10-02T23:42:43.042+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.3:59718 @ 0x318e2d0" state=STATUS_STOPPED positionMs=0 volume=100 Oct 02 23:42:43 volumio volumio5-onboarding[1702]: time=2026-10-02T23:42:43.042+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.3:59718 @ 0x318e2d0" id= title= Oct 02 23:42:43 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 02 23:42:49 volumio volumio[1229]: info: CALLMETHOD: audio_interface alsa_controller saveVolumeOptions [object Object] Oct 02 23:42:49 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , saveVolumeOptions Oct 02 23:42:49 volumio volumio[1229]: info: CoreCommandRouter::volumioGetState Oct 02 23:42:49 volumio volumio[1229]: info: CorePlayQueue::getTrack 0 Oct 02 23:42:49 volumio volumio[1229]: info: Restoring Previous Volume level: 100 false false Oct 02 23:42:49 volumio volumio[1229]: info: Output device has changed, restarting MPD Oct 02 23:42:49 volumio volumio[1229]: info: Volume configurations have been set Oct 02 23:42:49 volumio sudo[17265]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 02 23:42:49 volumio sudo[17265]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 02 23:42:49 volumio sudo[17264]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 02 23:42:49 volumio sudo[17264]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 02 23:42:49 volumio sudo[17264]: pam_unix(sudo:session): session closed for user root Oct 02 23:42:49 volumio volumio[1229]: info: CoreCommandRouter::volumioUpdateVolumeSettings Oct 02 23:42:49 volumio volumio[1229]: info: Updating Volume Controller Parameters: Device: 5 Name: Combo384 Amanero Mixer: Max Vol: 100 Vol Curve; logarithmic Vol Steps: 1 Oct 02 23:42:49 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , setExternalVolume Oct 02 23:42:49 volumio volumio[1229]: info: Disabling external Volume Control Oct 02 23:42:49 volumio volumio[1229]: info: CoreCommandRouter::getUIConfigOnPlugin Oct 02 23:42:49 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Oct 02 23:42:49 volumio volumio[1229]: info: CoreStateMachine::pushState Oct 02 23:42:49 volumio volumio[1229]: info: CorePlayQueue::getTrack 0 Oct 02 23:42:49 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 02 23:42:49 volumio volumio[1229]: info: CoreCommandRouter::volumioPushState Oct 02 23:42:49 volumio volumio5-onboarding[1702]: time=2026-10-02T23:42:49.911+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.3:59718 @ 0x318e2d0" state=STATUS_STOPPED positionMs=0 volume=100 Oct 02 23:42:49 volumio volumio5-onboarding[1702]: time=2026-10-02T23:42:49.911+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.3:59718 @ 0x318e2d0" id= title= Oct 02 23:42:49 volumio volumio[1229]: info: MPD Permissions set Oct 02 23:42:49 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 02 23:42:49 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 02 23:42:49 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 02 23:42:49 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 02 23:42:49 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 02 23:42:49 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 02 23:42:49 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 02 23:42:49 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 02 23:42:49 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 02 23:42:49 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 02 23:42:49 volumio systemd[1]: mpd.service: Deactivated successfully. Oct 02 23:42:49 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Oct 02 23:42:49 volumio systemd[1]: mpd.service: Consumed 2.930s CPU time. Oct 02 23:42:49 volumio systemd[1]: mpd.socket: Deactivated successfully. Oct 02 23:42:49 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Oct 02 23:42:49 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Oct 02 23:42:49 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions Oct 02 23:42:50 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 02 23:42:50 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Oct 02 23:42:50 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 02 23:42:50 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 02 23:42:50 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 02 23:42:50 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 02 23:42:50 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 02 23:42:50 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 02 23:42:50 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 02 23:42:50 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: mpd , getPlaybackMode Oct 02 23:42:50 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus Oct 02 23:42:50 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Oct 02 23:42:50 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Oct 02 23:42:50 volumio sudo[17286]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Oct 02 23:42:50 volumio sudo[17286]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Oct 02 23:42:50 volumio sudo[17286]: pam_unix(sudo:session): session closed for user root Oct 02 23:42:52 volumio mpd[17289]: 2026-10-02T23:42:52 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Oct 02 23:42:52 volumio systemd[1]: Started mpd.service - Music Player Daemon. Oct 02 23:42:52 volumio sudo[17265]: pam_unix(sudo:session): session closed for user root Oct 02 23:42:52 volumio volumio[1229]: error: updateQueue error: null Oct 02 23:42:54 volumio volumio[1229]: info: VolumeController::SetAlsaVolume100 Oct 02 23:42:54 volumio volumio[1229]: info: CoreStateMachine::pushState Oct 02 23:42:54 volumio volumio[1229]: info: CorePlayQueue::getTrack 0 Oct 02 23:42:54 volumio volumio[1229]: info: CoreCommandRouter::volumioPushState Oct 02 23:42:54 volumio volumio5-onboarding[1702]: time=2026-10-02T23:42:54.322+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.3:59718 @ 0x318e2d0" state=STATUS_STOPPED positionMs=0 volume=100 Oct 02 23:42:54 volumio volumio5-onboarding[1702]: time=2026-10-02T23:42:54.322+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.3:59718 @ 0x318e2d0" id= title= Oct 02 23:43:10 volumio volumio5-onboarding[1702]: time=2026-10-02T23:43:10.489+09:00 level=INFO msg="check connectivity" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.3:59718 @ 0x318e2d0" latency=63.189387ms timeout=10s Oct 02 23:43:10 volumio volumio5-onboarding[1702]: time=2026-10-02T23:43:10.494+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.3:59718 @ 0x318e2d0" latency=63.189387ms timeout=10s endpoint=https://radio-directory.firebaseapp.com duration=4.731147ms Oct 02 23:43:10 volumio volumio5-onboarding[1702]: time=2026-10-02T23:43:10.593+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.3:59718 @ 0x318e2d0" latency=63.189387ms timeout=10s endpoint=https://browsing-performer.dfs.volumio.org duration=102.968467ms Oct 02 23:43:10 volumio volumio5-onboarding[1702]: time=2026-10-02T23:43:10.595+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.3:59718 @ 0x318e2d0" latency=63.189387ms timeout=10s endpoint=https://oauth-performer.dfs.volumio.org duration=105.023415ms Oct 02 23:43:10 volumio volumio5-onboarding[1702]: time=2026-10-02T23:43:10.630+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.3:59718 @ 0x318e2d0" latency=63.189387ms timeout=10s endpoint=https://www.googleapis.com duration=138.811029ms Oct 02 23:43:10 volumio volumio5-onboarding[1702]: time=2026-10-02T23:43:10.662+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.3:59718 @ 0x318e2d0" latency=63.189387ms timeout=10s endpoint=https://google.com duration=171.944112ms Oct 02 23:43:10 volumio volumio5-onboarding[1702]: time=2026-10-02T23:43:10.669+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.3:59718 @ 0x318e2d0" latency=63.189387ms timeout=10s endpoint=https://myvolumio.firebaseio.com duration=179.622655ms Oct 02 23:43:10 volumio volumio5-onboarding[1702]: time=2026-10-02T23:43:10.717+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.3:59718 @ 0x318e2d0" latency=63.189387ms timeout=10s endpoint=https://securetoken.googleapis.com duration=226.272252ms Oct 02 23:43:10 volumio volumio5-onboarding[1702]: time=2026-10-02T23:43:10.743+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.3:59718 @ 0x318e2d0" latency=63.189387ms timeout=10s endpoint=https://functions.volumio.cloud duration=253.059343ms Oct 02 23:43:10 volumio volumio5-onboarding[1702]: time=2026-10-02T23:43:10.754+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.3:59718 @ 0x318e2d0" latency=63.189387ms timeout=10s endpoint=https://functions.volumio.cloud duration=262.984138ms Oct 02 23:43:10 volumio volumio5-onboarding[1702]: time=2026-10-02T23:43:10.953+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.3:59718 @ 0x318e2d0" latency=63.189387ms timeout=10s endpoint=https://database.volumio.cloud duration=463.570653ms Oct 02 23:43:11 volumio volumio5-onboarding[1702]: time=2026-10-02T23:43:11.853+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.3:59718 @ 0x318e2d0" latency=63.189387ms timeout=10s endpoint=http://pushupdates.volumio.org duration=1.362806586s Oct 02 23:43:11 volumio volumio5-onboarding[1702]: time=2026-10-02T23:43:11.908+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.3:59718 @ 0x318e2d0" latency=63.189387ms timeout=10s endpoint=http://plugins.volumio.org duration=1.417916393s Oct 02 23:43:12 volumio volumio5-onboarding[1702]: time=2026-10-02T23:43:12.424+09:00 level=ERROR msg="endpoint is not reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.3:59718 @ 0x318e2d0" latency=63.189387ms timeout=10s endpoint=http://cddb.volumio.org duration=1.933638884s error="Head \"http://gnudb.gnudb.org/~cddb/cddb.cgi/\": EOF" Oct 02 23:43:24 volumio volumio[1229]: info: CoreCommandRouter::getUIConfigOnPlugin Oct 02 23:43:24 volumio volumio[1229]: info: CoreCommandRouter::getUIConfigOnPlugin Oct 02 23:43:24 volumio volumio[1229]: info: Retrieving Cloud Streaming UI Oct 02 23:43:24 volumio volumio[1229]: info: Getting Tidal Cloud Configuration Oct 02 23:43:24 volumio volumio[1229]: info: CoreCommandRouter::getUIConfigOnPlugin Oct 02 23:43:24 volumio volumio[1229]: info: Getting Qobuz Cloud Configuration Oct 02 23:43:24 volumio volumio[1229]: info: Asking plugin for UI Config Oct 02 23:43:24 volumio volumio[1229]: info: CoreCommandRouter::getUIConfigOnPlugin Oct 02 23:43:24 volumio volumio[1229]: info: Getting Spotify Cloud Configuration Oct 02 23:43:24 volumio volumio[1229]: info: Asking plugin for UI Config Oct 02 23:43:24 volumio volumio[1229]: info: CoreCommandRouter::getUIConfigOnPlugin Oct 02 23:43:24 volumio volumio[1229]: info: Saving Spotify Acccount Oct 02 23:43:24 volumio volumio[1229]: info: Got Tidal Cloud Configuration Oct 02 23:43:24 volumio volumio[1229]: info: Got it Oct 02 23:43:24 volumio volumio[1229]: info: Got it Oct 02 23:43:24 volumio volumio[1229]: error: Could not retrieve Spotify Config from plugin Spotify: no section found Oct 02 23:43:24 volumio volumio[1229]: info: CoreCommandRouter::getUIConfigOnPlugin Oct 02 23:43:24 volumio volumio[1229]: error: Error retrieving Highresaudio conf: TypeError: Cannot read properties of undefined (reading 'onSave') Oct 02 23:43:24 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus Oct 02 23:43:24 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Oct 02 23:43:24 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Oct 02 23:43:24 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Oct 02 23:43:24 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 02 23:43:24 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 02 23:43:24 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 02 23:43:24 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 02 23:43:24 volumio volumio[1229]: info: CoreCommandRouter::volumioGetBrowseSources Oct 02 23:43:24 volumio volumio[1229]: info: CoreCommandRouter::volumioGetBrowseSources Oct 02 23:43:24 volumio volumio[1229]: info: CoreCommandRouter::volumioGetBrowseSources Oct 02 23:43:24 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Oct 02 23:43:24 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: networkfs , listShares Oct 02 23:43:28 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Oct 02 23:43:31 volumio volumio[1229]: info: Disabling MyMusic plugin upnp Oct 02 23:43:31 volumio sudo[17351]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop upmpdcli.service Oct 02 23:43:31 volumio sudo[17351]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 02 23:43:31 volumio systemd[1]: Stopping upmpdcli.service - UPnP Renderer front-end to MPD... Oct 02 23:43:32 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Oct 02 23:43:35 volumio volumio[1229]: info: Enabling MyMusic plugin upnp Oct 02 23:43:35 volumio volumio[1229]: info: Enabling plugin upnp Oct 02 23:43:35 volumio volumio[1229]: info: Loading plugin "upnp"... Oct 02 23:43:35 volumio volumio[1229]: info: [1790952215078] Starting Upmpd Daemon Oct 02 23:43:35 volumio volumio[1229]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 02 23:43:35 volumio volumio[1229]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 02 23:43:35 volumio volumio[1229]: Error: listen EADDRINUSE: address already in use :::6599 Oct 02 23:43:35 volumio volumio[1229]: at Server.setupListenHandle [as _listen2] (node:net:1872:16) Oct 02 23:43:35 volumio volumio[1229]: at listenInCluster (node:net:1920:12) Oct 02 23:43:35 volumio volumio[1229]: at Server.listen (node:net:2008:7) Oct 02 23:43:35 volumio volumio[1229]: at UpnpInterface.onVolumioStart (/volumio/app/plugins/audio_interface/upnp/index.js:78:17) Oct 02 23:43:35 volumio volumio[1229]: at PluginManager.loadCorePlugin (/volumio/app/pluginmanager.js:255:38) Oct 02 23:43:35 volumio volumio[1229]: at Promise._successFn (/volumio/app/pluginmanager.js:1855:19) Oct 02 23:43:35 volumio volumio[1229]: at nextTickCallback (/volumio/node_modules/kew/kew.js:47:28) Oct 02 23:43:35 volumio volumio[1229]: at process.processTicksAndRejections (node:internal/process/task_queues:77:11) { Oct 02 23:43:35 volumio volumio[1229]: code: 'EADDRINUSE', Oct 02 23:43:35 volumio volumio[1229]: errno: -98, Oct 02 23:43:35 volumio volumio[1229]: syscall: 'listen', Oct 02 23:43:35 volumio volumio[1229]: address: '::', Oct 02 23:43:35 volumio volumio[1229]: port: 6599 Oct 02 23:43:35 volumio volumio[1229]: } Oct 02 23:43:35 volumio volumio[1229]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 02 23:43:35 volumio sudo[17367]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-10-02 23:42' Oct 02 23:43:35 volumio sudo[17367]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) PRETTY_NAME="Raspbian GNU/Linux 12 (bookworm)" NAME="Raspbian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm 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="18952480e8d8c63f22208e9007a0f47a9563eae6" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="0e58f1861fa88e02087981b8d91f7511f0e7011b" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue Mar 24 17:20:52 UTC 2026" VOLUMIO_VERSION="4.119" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="d0c2fd9dbc5e70e58c32413c12353563"