Aug 31 12:39:02 volumio volumio[1252]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Aug 31 12:39:02 volumio volumio5-onboarding[1596]: time=2026-08-31T12:39:02.947+05:30 level=ERROR msg="failed to read message" component=conn/ws remoteAddr=192.168.68.105:50092 error="websocket: close 1006 (abnormal closure): unexpected EOF" Aug 31 12:39:02 volumio volumio5-onboarding[1596]: time=2026-08-31T12:39:02.947+05:30 level=INFO msg="WebSocket connection closed" component=conn/ws remoteAddr=192.168.68.105:50092 Aug 31 12:39:02 volumio volumio5-onboarding[1596]: time=2026-08-31T12:39:02.947+05:30 level=INFO msg="connection to address closed" component=conn/multi addr=192.168.68.105:50092 Aug 31 12:39:04 volumio dbus-daemon[726]: [system] Rejected send message, 0 matched rules; type="error", sender=":1.20" (uid=0 pid=1596 comm="/usr/bin/volumio5-onboarding") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.4" (uid=0 pid=825 comm="/usr/libexec/bluetooth/bluetoothd --noplugin=sap,b") Aug 31 12:39:04 volumio volumio5-onboarding[1596]: time=2026-08-31T12:39:04.798+05:30 level=INFO msg="established new WebSocket connection" component=conn/ws remoteAddr=192.168.68.105:54736 Aug 31 12:39:04 volumio volumio5-onboarding[1596]: time=2026-08-31T12:39:04.818+05:30 level=INFO msg="app ready event" component=server event=CLIENT_EVENT_TYPE_APP_READY peer="192.168.68.105:54736 @ 0x2855140" latency=12.676978ms platform=PLATFORM_ANDROID version=6.260807.0 Aug 31 12:39:04 volumio volumio5-onboarding[1596]: time=2026-08-31T12:39:04.819+05:30 level=INFO msg="device data request" component=server type=REQUEST_TYPE_DEVICE_DATA peer="192.168.68.105:54736 @ 0x2855140" latency=13.116972ms timeout=20s Aug 31 12:39:04 volumio volumio5-onboarding[1596]: time=2026-08-31T12:39:04.819+05:30 level=INFO msg="emitting device capabilities changed event" component=server peer="192.168.68.105:54736 @ 0x2855140" Aug 31 12:39:04 volumio volumio[1252]: info: Received Get System Info Aug 31 12:39:04 volumio volumio[1252]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 31 12:39:04 volumio volumio[1252]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 31 12:39:04 volumio volumio[1252]: info: Discovery: Getting this device information Aug 31 12:39:04 volumio volumio[1252]: info: CoreCommandRouter::volumioGetState Aug 31 12:39:04 volumio volumio[1252]: info: CorePlayQueue::getTrack 0 Aug 31 12:39:04 volumio volumio[1252]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 31 12:39:04 volumio volumio5-onboarding[1596]: time=2026-08-31T12:39:04.822+05:30 level=INFO msg="emitting device name changed event" component=server peer="192.168.68.105:54736 @ 0x2855140" name=Volumio Aug 31 12:39:04 volumio volumio5-onboarding[1596]: time=2026-08-31T12:39:04.823+05:30 level=INFO msg="emitting device language changed event" component=server peer="192.168.68.105:54736 @ 0x2855140" language=en Aug 31 12:39:04 volumio volumio[1252]: info: CoreCommandRouter::executeOnPlugin: system , getCurrentTimezone Aug 31 12:39:04 volumio volumio5-onboarding[1596]: time=2026-08-31T12:39:04.825+05:30 level=INFO msg="emitting device timezone changed event" component=server peer="192.168.68.105:54736 @ 0x2855140" timezone=Asia/Calcutta Aug 31 12:39:04 volumio volumio5-onboarding[1596]: time=2026-08-31T12:39:04.828+05:30 level=INFO msg="emitting ethernet info changed event" component=server peer="192.168.68.105:54736 @ 0x2855140" available=true connected=false macAddress= ip4Address= ip6Address= Aug 31 12:39:04 volumio volumio5-onboarding[1596]: time=2026-08-31T12:39:04.833+05:30 level=INFO msg="emitting wifi info changed event" component=server peer="192.168.68.105:54736 @ 0x2855140" available=true connected=true macAddress=88:a2:9e:a7:72:f0 ip4Address=192.168.68.110/24 ip6Address= ssid=RSC_A2_SNMS_SSID Aug 31 12:39:04 volumio volumio5-onboarding[1596]: time=2026-08-31T12:39:04.833+05:30 level=INFO msg="emitting device setup status changed event" component=server peer="192.168.68.105:54736 @ 0x2855140" setupComplete=true Aug 31 12:39:04 volumio volumio[1252]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getExtendedOutputDevices Aug 31 12:39:04 volumio volumio[1252]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions Aug 31 12:39:04 volumio volumio[1252]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 31 12:39:04 volumio volumio[1252]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Aug 31 12:39:04 volumio volumio[1252]: amixer -c 0 info | grep "bcm2835 ALSA" Aug 31 12:39:04 volumio volumio[1252]: amixer -c 1 info | grep "bcm2835 Headphones" Aug 31 12:39:04 volumio volumio[1252]: Card sysdefault:1 'Headphones'/'bcm2835 Headphones' Aug 31 12:39:04 volumio volumio[1252]: amixer -c 2 info | grep "vc4-hdmi-0" Aug 31 12:39:04 volumio volumio[1252]: Card sysdefault:2 'vc4hdmi0'/'vc4-hdmi-0' Aug 31 12:39:04 volumio volumio[1252]: amixer -c 3 info | grep "vc4-hdmi-1" Aug 31 12:39:04 volumio volumio[1252]: Card sysdefault:3 'vc4hdmi1'/'vc4-hdmi-1' Aug 31 12:39:04 volumio volumio[1252]: error: Cannot read Audio Device Capabilities Command failed: /usr/local/bin/alsacap -C 4 Aug 31 12:39:04 volumio volumio[1252]: /bin/sh: 1: /usr/local/bin/alsacap: not found Aug 31 12:39:04 volumio volumio[1252]: {"cmd":"/usr/local/bin/alsacap -C 4","code":127,"killed":false,"signal":null,"stack":"Error: Command failed: /usr/local/bin/alsacap -C 4\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)"} Aug 31 12:39:04 volumio volumio[1252]: amixer -c 4 info | grep "Raspberry Pi DAC+" Aug 31 12:39:04 volumio volumio[1252]: error: Cannot read Audio Device Capabilities Command failed: /usr/local/bin/alsacap -C 4 Aug 31 12:39:04 volumio volumio[1252]: /bin/sh: 1: /usr/local/bin/alsacap: not found Aug 31 12:39:04 volumio volumio[1252]: {"cmd":"/usr/local/bin/alsacap -C 4","code":127,"killed":false,"signal":null,"stack":"Error: Command failed: /usr/local/bin/alsacap -C 4\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)"} Aug 31 12:39:04 volumio volumio[1252]: amixer -c 4 info | grep "RPi DAC+" Aug 31 12:39:05 volumio volumio[1252]: Card sysdefault:4 'DAC'/'RPi DAC+' Aug 31 12:39:05 volumio volumio5-onboarding[1596]: time=2026-08-31T12:39:05.004+05:30 level=INFO msg="emitting audio outputs changed event" component=server peer="192.168.68.105:54736 @ 0x2855140" selectedOutputId=4 Aug 31 12:39:05 volumio volumio[1252]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 31 12:39:05 volumio volumio[1252]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 31 12:39:05 volumio volumio[1252]: info: Discovery: Getting this device information Aug 31 12:39:05 volumio volumio[1252]: info: CoreCommandRouter::volumioGetState Aug 31 12:39:05 volumio volumio[1252]: info: CorePlayQueue::getTrack 0 Aug 31 12:39:05 volumio volumio[1252]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 31 12:39:05 volumio volumio[1252]: info: Received Get System Info Aug 31 12:39:05 volumio volumio[1252]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 31 12:39:05 volumio volumio[1252]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 31 12:39:05 volumio volumio[1252]: info: Discovery: Getting this device information Aug 31 12:39:05 volumio volumio[1252]: info: CoreCommandRouter::volumioGetState Aug 31 12:39:05 volumio volumio[1252]: info: CorePlayQueue::getTrack 0 Aug 31 12:39:05 volumio volumio[1252]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 31 12:39:05 volumio volumio5-onboarding[1596]: time=2026-08-31T12:39:05.020+05:30 level=INFO msg="emitting software info changed event" component=server peer="192.168.68.105:54736 @ 0x2855140" currentVersion=4.119 latestVersion=4.119 Aug 31 12:39:05 volumio volumio5-onboarding[1596]: time=2026-08-31T12:39:05.020+05:30 level=INFO msg="emitting software update progress event" component=server peer="192.168.68.105:54736 @ 0x2855140" status=UPDATE_STATUS_NONE progress=0 Aug 31 12:39:05 volumio volumio5-onboarding[1596]: time=2026-08-31T12:39:05.020+05:30 level=INFO msg="emitting user changed event" component=server peer="192.168.68.105:54736 @ 0x2855140" userId= Aug 31 12:39:05 volumio volumio5-onboarding[1596]: time=2026-08-31T12:39:05.020+05:30 level=INFO msg="emitting music providers changed event" component=server peer="192.168.68.105:54736 @ 0x2855140" providers=3 Aug 31 12:39:05 volumio volumio5-onboarding[1596]: time=2026-08-31T12:39:05.020+05:30 level=INFO msg="emitting plugins changed event" component=server peer="192.168.68.105:54736 @ 0x2855140" plugins=71 Aug 31 12:39:05 volumio volumio[1252]: info: CoreCommandRouter::volumioGetState Aug 31 12:39:05 volumio volumio[1252]: info: CorePlayQueue::getTrack 0 Aug 31 12:39:05 volumio volumio5-onboarding[1596]: time=2026-08-31T12:39:05.025+05:30 level=INFO msg="emitting player state changed event" component=server peer="192.168.68.105:54736 @ 0x2855140" state=STATUS_STOPPED positionMs=0 volume=96 Aug 31 12:39:05 volumio volumio5-onboarding[1596]: time=2026-08-31T12:39:05.025+05:30 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.68.105:54736 @ 0x2855140" id=spotify:track:1Icl1ktQ2JQl4rfP5JQ9br title=Oorellam Aug 31 12:39:05 volumio volumio[1252]: verbose: New Socket.io Connection to 192.168.68.110:3000 from 192.168.68.105 UA: Dart/3.12 (dart:io) Engine version: 3 Transport: websocket Total Clients: 5 Aug 31 12:39:05 volumio volumio[1252]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Aug 31 12:39:05 volumio volumio[1252]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Aug 31 12:39:05 volumio bluealsa[1019]: bluez.c:1393: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved(/org/bluez/hci0/dev_59_79_19_E6_11_DA, ...) Aug 31 12:39:05 volumio volumio5-onboarding[1596]: time=2026-08-31T12:39:05.813+05:30 level=INFO msg="navigate to next page" component=server type=REQUEST_TYPE_CONTINUE_NAVIGATION peer="192.168.68.105:54736 @ 0x2855140" latency=20.26202ms timeout=10s from=APP_PAGE_ROOT to=APP_PAGE_LEGACY_DEVICE Aug 31 12:39:05 volumio volumio5-onboarding[1596]: time=2026-08-31T12:39:05.831+05:30 level=INFO msg="check connectivity" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.68.105:54736 @ 0x2855140" latency=14.462519ms timeout=10s Aug 31 12:39:05 volumio volumio5-onboarding[1596]: time=2026-08-31T12:39:05.845+05:30 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.68.105:54736 @ 0x2855140" latency=14.462519ms timeout=10s endpoint=https://radio-directory.firebaseapp.com duration=13.687801ms Aug 31 12:39:05 volumio volumio5-onboarding[1596]: time=2026-08-31T12:39:05.950+05:30 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.68.105:54736 @ 0x2855140" latency=14.462519ms timeout=10s endpoint=https://www.googleapis.com duration=117.758935ms Aug 31 12:39:05 volumio volumio5-onboarding[1596]: time=2026-08-31T12:39:05.989+05:30 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.68.105:54736 @ 0x2855140" latency=14.462519ms timeout=10s endpoint=https://browsing-performer.dfs.volumio.org duration=157.082183ms Aug 31 12:39:05 volumio volumio5-onboarding[1596]: time=2026-08-31T12:39:05.991+05:30 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.68.105:54736 @ 0x2855140" latency=14.462519ms timeout=10s endpoint=http://pushupdates.volumio.org duration=159.309539ms Aug 31 12:39:05 volumio volumio5-onboarding[1596]: time=2026-08-31T12:39:05.997+05:30 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.68.105:54736 @ 0x2855140" latency=14.462519ms timeout=10s endpoint=https://oauth-performer.dfs.volumio.org duration=165.209625ms Aug 31 12:39:06 volumio volumio5-onboarding[1596]: time=2026-08-31T12:39:06.107+05:30 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.68.105:54736 @ 0x2855140" latency=14.462519ms timeout=10s endpoint=https://securetoken.googleapis.com duration=275.496512ms Aug 31 12:39:06 volumio volumio5-onboarding[1596]: time=2026-08-31T12:39:06.123+05:30 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.68.105:54736 @ 0x2855140" latency=14.462519ms timeout=10s endpoint=https://myvolumio.firebaseio.com duration=291.249165ms Aug 31 12:39:06 volumio volumio5-onboarding[1596]: time=2026-08-31T12:39:06.168+05:30 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.68.105:54736 @ 0x2855140" latency=14.462519ms timeout=10s endpoint=https://database.volumio.cloud duration=335.712185ms Aug 31 12:39:06 volumio volumio5-onboarding[1596]: time=2026-08-31T12:39:06.177+05:30 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.68.105:54736 @ 0x2855140" latency=14.462519ms timeout=10s endpoint=https://functions.volumio.cloud duration=345.439134ms Aug 31 12:39:06 volumio volumio5-onboarding[1596]: time=2026-08-31T12:39:06.211+05:30 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.68.105:54736 @ 0x2855140" latency=14.462519ms timeout=10s endpoint=https://google.com duration=379.34704ms Aug 31 12:39:06 volumio sudo[2489]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Aug 31 12:39:06 volumio sudo[2489]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 12:39:06 volumio sudo[2489]: pam_unix(sudo:session): session closed for user root Aug 31 12:39:06 volumio sudo[2491]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Aug 31 12:39:06 volumio sudo[2491]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 12:39:06 volumio sudo[2491]: pam_unix(sudo:session): session closed for user root Aug 31 12:39:06 volumio volumio[1252]: verbose: New Socket.io Connection to 192.168.68.110 from 192.168.68.105 UA: Mozilla/5.0 (Linux; Android 16; SM-F966B Build/BP4A.251205.006; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/151.0.7922.199 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 5 Aug 31 12:39:06 volumio sudo[2495]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Aug 31 12:39:06 volumio sudo[2495]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 12:39:06 volumio sudo[2495]: pam_unix(sudo:session): session closed for user root Aug 31 12:39:06 volumio sudo[2497]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Aug 31 12:39:06 volumio sudo[2497]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 12:39:06 volumio sudo[2497]: pam_unix(sudo:session): session closed for user root Aug 31 12:39:06 volumio volumio[1252]: verbose: New Socket.io Connection to 192.168.68.110 from 192.168.68.105 UA: Mozilla/5.0 (Linux; Android 16; SM-F966B Build/BP4A.251205.006; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/151.0.7922.199 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 6 Aug 31 12:39:06 volumio volumio5-onboarding[1596]: time=2026-08-31T12:39:06.437+05:30 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.68.105:54736 @ 0x2855140" latency=14.462519ms timeout=10s endpoint=https://functions.volumio.cloud duration=604.716303ms Aug 31 12:39:06 volumio volumio[1252]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Aug 31 12:39:06 volumio volumio[1252]: info: CoreCommandRouter::volumioGetVisibleSources Aug 31 12:39:06 volumio volumio[1252]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 31 12:39:06 volumio volumio[1252]: info: CoreCommandRouter::volumioGetState Aug 31 12:39:06 volumio volumio[1252]: info: CorePlayQueue::getTrack 0 Aug 31 12:39:06 volumio volumio[1252]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Aug 31 12:39:06 volumio volumio[1252]: info: CoreCommandRouter::volumioGetQueue Aug 31 12:39:06 volumio volumio[1252]: info: CoreStateMachine::getQueue Aug 31 12:39:06 volumio volumio[1252]: info: CorePlayQueue::getQueue Aug 31 12:39:06 volumio volumio[1252]: info: Listing playlists Aug 31 12:39:06 volumio volumio[1252]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Aug 31 12:39:06 volumio volumio[1252]: info: Received Get System Info Aug 31 12:39:06 volumio volumio[1252]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 31 12:39:06 volumio volumio[1252]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 31 12:39:06 volumio volumio[1252]: info: Discovery: Getting this device information Aug 31 12:39:06 volumio volumio[1252]: info: CoreCommandRouter::volumioGetState Aug 31 12:39:06 volumio volumio[1252]: info: CorePlayQueue::getTrack 0 Aug 31 12:39:06 volumio volumio[1252]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 31 12:39:06 volumio volumio[1252]: info: CoreCommandRouter::volumioGetState Aug 31 12:39:06 volumio volumio[1252]: info: CorePlayQueue::getTrack 0 Aug 31 12:39:06 volumio volumio[1252]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Aug 31 12:39:06 volumio volumio[1252]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Aug 31 12:39:06 volumio volumio5-onboarding[1596]: time=2026-08-31T12:39:06.733+05:30 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.68.105:54736 @ 0x2855140" latency=14.462519ms timeout=10s endpoint=http://cddb.volumio.org duration=901.077996ms Aug 31 12:39:06 volumio volumio[1252]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Aug 31 12:39:07 volumio volumio5-onboarding[1596]: time=2026-08-31T12:39:07.107+05:30 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.68.105:54736 @ 0x2855140" latency=14.462519ms timeout=10s endpoint=http://plugins.volumio.org duration=1.274758442s Aug 31 12:39:08 volumio volumio[1252]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Aug 31 12:39:08 volumio volumio[1252]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 31 12:39:08 volumio volumio[1252]: info: Received Get System Info Aug 31 12:39:08 volumio volumio[1252]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 31 12:39:08 volumio volumio[1252]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 31 12:39:08 volumio volumio[1252]: info: Discovery: Getting this device information Aug 31 12:39:08 volumio volumio[1252]: info: CoreCommandRouter::volumioGetState Aug 31 12:39:08 volumio volumio[1252]: info: CorePlayQueue::getTrack 0 Aug 31 12:39:08 volumio volumio[1252]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 31 12:39:09 volumio volumio[1252]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 31 12:39:09 volumio volumio[1252]: info: Received Get System Info Aug 31 12:39:09 volumio volumio[1252]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 31 12:39:09 volumio volumio[1252]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 31 12:39:09 volumio volumio[1252]: info: Discovery: Getting this device information Aug 31 12:39:09 volumio volumio[1252]: info: CoreCommandRouter::volumioGetState Aug 31 12:39:09 volumio volumio[1252]: info: CorePlayQueue::getTrack 0 Aug 31 12:39:09 volumio volumio[1252]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 31 12:39:10 volumio bluealsa[1019]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_6A_1D_8D_8C_CC_10, ...) Aug 31 12:39:12 volumio volumio5-onboarding[1596]: time=2026-08-31T12:39:12.356+05:30 level=INFO msg="new address was allocated" component=ble/conn old=3 new=4 Aug 31 12:39:12 volumio dbus-daemon[726]: [system] Rejected send message, 0 matched rules; type="error", sender=":1.20" (uid=0 pid=1596 comm="/usr/bin/volumio5-onboarding") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.4" (uid=0 pid=825 comm="/usr/libexec/bluetooth/bluetoothd --noplugin=sap,b") Aug 31 12:39:16 volumio volumio[1252]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Aug 31 12:39:17 volumio volumio[1252]: info: Preload queue cleared Aug 31 12:39:24 volumio volumio[1252]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 31 12:39:24 volumio volumio[1252]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Aug 31 12:39:25 volumio volumio[1252]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Aug 31 12:39:25 volumio volumio[1252]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Aug 31 12:39:25 volumio volumio[1252]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Aug 31 12:39:25 volumio volumio[1252]: info: Received Get System Version Aug 31 12:39:25 volumio volumio[1252]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 31 12:39:25 volumio volumio[1252]: info: Received Get System Info Aug 31 12:39:25 volumio volumio[1252]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 31 12:39:25 volumio volumio[1252]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 31 12:39:25 volumio volumio[1252]: info: Discovery: Getting this device information Aug 31 12:39:25 volumio volumio[1252]: info: CoreCommandRouter::volumioGetState Aug 31 12:39:25 volumio volumio[1252]: info: CorePlayQueue::getTrack 0 Aug 31 12:39:25 volumio volumio[1252]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 31 12:39:28 volumio volumio[1252]: info: Enabling plugin ytmusic Aug 31 12:39:28 volumio volumio[1252]: info: Loading plugin "ytmusic"... Aug 31 12:39:28 volumio volumio[1252]: info: PLUGIN START: ytmusic Aug 31 12:39:28 volumio volumio[1252]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 31 12:39:28 volumio volumio[1252]: info: [1788160168296] CoreMusicLibrary::Adding element YouTube Music Aug 31 12:39:28 volumio volumio[1252]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 31 12:39:28 volumio volumio[1252]: Cannot find translation for source YouTube Music Aug 31 12:39:28 volumio volumio[1252]: info: Done. Aug 31 12:39:29 volumio volumio[1252]: info: CoreCommandRouter::volumioRemoveToBrowseSourcesYouTube Music Aug 31 12:39:29 volumio volumio[1252]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 31 12:39:29 volumio volumio[1252]: info: [ytmusic] (AutoplayManager) Disabled Aug 31 12:39:29 volumio volumio[1252]: info: Error: Error: VM operation timed out Aug 31 12:39:32 volumio volumio[1252]: info: Starting Uninstall of plugin music_service - ytmusic Aug 31 12:39:32 volumio volumio[1252]: info: Uninstalling plugin ytmusic Aug 31 12:39:32 volumio volumio[1252]: info: CoreCommandRouter::volumioRemoveToBrowseSourcesYouTube Music Aug 31 12:39:32 volumio volumio[1252]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 31 12:39:32 volumio volumio5-onboarding[1596]: time=2026-08-31T12:39:32.263+05:30 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Aug 31 12:39:34 volumio bluealsa[1019]: bluez.c:1393: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved(/org/bluez/hci0/dev_75_BE_12_6B_46_AB, ...) Aug 31 12:39:35 volumio volumio[1252]: info: CoreCommandRouter::volumioRemoveToBrowseSourcesYouTube Music Aug 31 12:39:35 volumio volumio[1252]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 31 12:39:35 volumio volumio[1252]: info: Error: Error: VM operation timed out Aug 31 12:39:36 volumio volumio[1252]: info: CoreCommandRouter::getUIConfigOnPlugin Aug 31 12:39:36 volumio volumio[1252]: error: [ytmusic] Error getting i18n options: VM operation timed out Error: VM operation timed out Aug 31 12:39:36 volumio volumio[1252]: at InnertubeWrapper.generatePoToken (/data/plugins/music_service/ytmusic/node_modules/volumio-yt-support/dist/lib/innertube/Wrapper.js:145:15) Aug 31 12:39:36 volumio volumio[1252]: at process.processTicksAndRejections (node:internal/process/task_queues:95:5) Aug 31 12:39:36 volumio volumio[1252]: at async #generateSessionPoToken (/data/plugins/music_service/ytmusic/node_modules/volumio-yt-support/dist/lib/innertube/Wrapper.js:169:35) Aug 31 12:39:36 volumio volumio[1252]: at async #doGetSessionPoToken (/data/plugins/music_service/ytmusic/node_modules/volumio-yt-support/dist/lib/innertube/Wrapper.js:113:25) Aug 31 12:39:36 volumio volumio[1252]: at async #init (/data/plugins/music_service/ytmusic/node_modules/volumio-yt-support/dist/lib/innertube/Wrapper.js:97:9) Aug 31 12:39:36 volumio volumio[1252]: at async InnertubeWrapper.create (/data/plugins/music_service/ytmusic/node_modules/volumio-yt-support/dist/lib/innertube/Wrapper.js:57:9) Aug 31 12:39:36 volumio volumio[1252]: warn: [ytmusic] Failed to get account config: VM operation timed out Error: VM operation timed out Aug 31 12:39:36 volumio volumio[1252]: at InnertubeWrapper.generatePoToken (/data/plugins/music_service/ytmusic/node_modules/volumio-yt-support/dist/lib/innertube/Wrapper.js:145:15) Aug 31 12:39:36 volumio volumio[1252]: at process.processTicksAndRejections (node:internal/process/task_queues:95:5) Aug 31 12:39:36 volumio volumio[1252]: at async #generateSessionPoToken (/data/plugins/music_service/ytmusic/node_modules/volumio-yt-support/dist/lib/innertube/Wrapper.js:169:35) Aug 31 12:39:36 volumio volumio[1252]: at async #doGetSessionPoToken (/data/plugins/music_service/ytmusic/node_modules/volumio-yt-support/dist/lib/innertube/Wrapper.js:113:25) Aug 31 12:39:36 volumio volumio[1252]: at async #init (/data/plugins/music_service/ytmusic/node_modules/volumio-yt-support/dist/lib/innertube/Wrapper.js:97:9) Aug 31 12:39:36 volumio volumio[1252]: at async InnertubeWrapper.create (/data/plugins/music_service/ytmusic/node_modules/volumio-yt-support/dist/lib/innertube/Wrapper.js:57:9) Aug 31 12:40:18 volumio volumio[1252]: info: CALLMETHOD: music_service ytmusic configSaveAccount [object Object] Aug 31 12:40:18 volumio volumio[1252]: info: CoreCommandRouter::executeOnPlugin: ytmusic , configSaveAccount Aug 31 12:40:18 volumio volumio[1252]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 31 12:40:18 volumio volumio[1252]: Error: VM operation timed out Aug 31 12:40:18 volumio volumio[1252]: at InnertubeWrapper.generatePoToken (/data/plugins/music_service/ytmusic/node_modules/volumio-yt-support/dist/lib/innertube/Wrapper.js:145:15) Aug 31 12:40:18 volumio volumio[1252]: at process.processTicksAndRejections (node:internal/process/task_queues:95:5) Aug 31 12:40:18 volumio volumio[1252]: at async #generateSessionPoToken (/data/plugins/music_service/ytmusic/node_modules/volumio-yt-support/dist/lib/innertube/Wrapper.js:169:35) Aug 31 12:40:18 volumio volumio[1252]: at async #doGetSessionPoToken (/data/plugins/music_service/ytmusic/node_modules/volumio-yt-support/dist/lib/innertube/Wrapper.js:113:25) Aug 31 12:40:18 volumio volumio[1252]: at async #init (/data/plugins/music_service/ytmusic/node_modules/volumio-yt-support/dist/lib/innertube/Wrapper.js:97:9) Aug 31 12:40:18 volumio volumio[1252]: at async InnertubeWrapper.create (/data/plugins/music_service/ytmusic/node_modules/volumio-yt-support/dist/lib/innertube/Wrapper.js:57:9) Aug 31 12:40:18 volumio volumio[1252]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 31 12:40:18 volumio sudo[2625]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-08-31 12:39' Aug 31 12:40:18 volumio sudo[2625]: 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"