Mar 27 14:31:05 volumio volumio[1990]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 27 14:31:05 volumio volumio[1990]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 27 14:31:05 volumio volumio[1990]: info: Discovery: Getting this device information Mar 27 14:31:05 volumio volumio[1990]: info: CoreCommandRouter::volumioGetState Mar 27 14:31:05 volumio volumio[1990]: info: CorePlayQueue::getTrack 7 Mar 27 14:31:05 volumio volumio[1990]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 27 14:31:05 volumio volumio[1990]: verbose: New Socket.io Connection to 192.168.1.211:3000 from 192.168.1.27 UA: Dart/3.10 (dart:io) Engine version: 3 Transport: websocket Total Clients: 14 Mar 27 14:31:05 volumio volumio[1990]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Mar 27 14:31:05 volumio volumio[1990]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Mar 27 14:31:05 volumio volumio5-onboarding[1684]: time=2026-03-27T14:31:05.927Z level=INFO msg="established new WebSocket connection" component=conn/ws remoteAddr=192.168.1.27:60166 Mar 27 14:31:06 volumio volumio[1990]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 27 14:31:06 volumio volumio[1990]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 27 14:31:06 volumio volumio[1990]: info: Discovery: Getting this device information Mar 27 14:31:06 volumio volumio[1990]: info: CoreCommandRouter::volumioGetState Mar 27 14:31:06 volumio volumio[1990]: info: CorePlayQueue::getTrack 7 Mar 27 14:31:06 volumio volumio[1990]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 27 14:31:06 volumio volumio[1990]: verbose: New Socket.io Connection to 192.168.1.211:3000 from 192.168.1.27 UA: Dart/3.10 (dart:io) Engine version: 3 Transport: websocket Total Clients: 14 Mar 27 14:31:06 volumio volumio[1990]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Mar 27 14:31:06 volumio volumio[1990]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Mar 27 14:31:06 volumio volumio[1990]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 27 14:31:06 volumio volumio[1990]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 27 14:31:06 volumio volumio[1990]: info: Discovery: Getting this device information Mar 27 14:31:06 volumio volumio[1990]: info: CoreCommandRouter::volumioGetState Mar 27 14:31:06 volumio volumio[1990]: info: CorePlayQueue::getTrack 7 Mar 27 14:31:06 volumio volumio[1990]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 27 14:31:06 volumio volumio[1990]: verbose: New Socket.io Connection to 192.168.1.211:3000 from 192.168.1.27 UA: Dart/3.10 (dart:io) Engine version: 3 Transport: websocket Total Clients: 14 Mar 27 14:31:06 volumio volumio[1990]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Mar 27 14:31:06 volumio volumio[1990]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Mar 27 14:31:11 volumio systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 15951. Mar 27 14:31:11 volumio systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Mar 27 14:31:11 volumio systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Mar 27 14:31:11 volumio upmpdcli[3361]: Could not open config: /tmp/upmpdcli.conf Mar 27 14:31:11 volumio systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Mar 27 14:31:11 volumio systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Mar 27 14:31:26 volumio go-librespot[2477]: time="2026-03-27T14:31:26Z" level=trace msg="sent dealer ping" Mar 27 14:31:26 volumio go-librespot[2477]: time="2026-03-27T14:31:26Z" level=trace msg="received dealer pong" Mar 27 14:31:26 volumio systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 15952. Mar 27 14:31:26 volumio systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Mar 27 14:31:26 volumio systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Mar 27 14:31:26 volumio upmpdcli[3378]: Could not open config: /tmp/upmpdcli.conf Mar 27 14:31:26 volumio systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Mar 27 14:31:26 volumio systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Mar 27 14:31:41 volumio systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 15953. Mar 27 14:31:41 volumio systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Mar 27 14:31:41 volumio systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Mar 27 14:31:41 volumio upmpdcli[3408]: Could not open config: /tmp/upmpdcli.conf Mar 27 14:31:41 volumio systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Mar 27 14:31:41 volumio systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Mar 27 14:31:43 volumio bluealsa[1180]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_4E_0E_F7_5E_D9_76, ...) Mar 27 14:31:47 volumio volumio5-onboarding[1684]: time=2026-03-27T14:31:47.425Z level=INFO msg="new address was allocated" component=ble/conn old=11 new=12 Mar 27 14:31:47 volumio dbus-daemon[965]: [system] Rejected send message, 0 matched rules; type="error", sender=":1.14" (uid=0 pid=1684 comm="/usr/bin/volumio5-onboarding") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.2" (uid=0 pid=964 comm="/usr/libexec/bluetooth/bluetoothd --noplugin=sap,b") Mar 27 14:31:56 volumio go-librespot[2477]: time="2026-03-27T14:31:56Z" level=trace msg="sent dealer ping" Mar 27 14:31:56 volumio go-librespot[2477]: time="2026-03-27T14:31:56Z" level=trace msg="received dealer pong" Mar 27 14:31:56 volumio systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 15954. Mar 27 14:31:56 volumio systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Mar 27 14:31:56 volumio systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Mar 27 14:31:56 volumio upmpdcli[3425]: Could not open config: /tmp/upmpdcli.conf Mar 27 14:31:56 volumio systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Mar 27 14:31:56 volumio systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Mar 27 14:32:09 volumio volumio5-onboarding[1684]: time=2026-03-27T14:32:09.088Z level=INFO msg="device data request" component=server type=REQUEST_TYPE_DEVICE_DATA peer="192.168.1.27:60166 @ 0x18c81b0" latency=-1.571162388s timeout=10s Mar 27 14:32:09 volumio volumio5-onboarding[1684]: time=2026-03-27T14:32:09.088Z level=INFO msg="emitting device capabilities changed event" component=server peer="192.168.1.27:60166 @ 0x18c81b0" Mar 27 14:32:09 volumio volumio5-onboarding[1684]: time=2026-03-27T14:32:09.088Z level=INFO msg="app ready event" component=server event=CLIENT_EVENT_TYPE_APP_READY peer="192.168.1.27:60166 @ 0x18c81b0" latency=-1.570148962s platform=PLATFORM_ANDROID version=5.260209.0 Mar 27 14:32:09 volumio volumio[1990]: info: Received Get System Info Mar 27 14:32:09 volumio volumio[1990]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 27 14:32:09 volumio volumio[1990]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 27 14:32:09 volumio volumio[1990]: info: Discovery: Getting this device information Mar 27 14:32:09 volumio volumio[1990]: info: CoreCommandRouter::volumioGetState Mar 27 14:32:09 volumio volumio[1990]: info: CorePlayQueue::getTrack 7 Mar 27 14:32:09 volumio volumio[1990]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 27 14:32:09 volumio volumio5-onboarding[1684]: time=2026-03-27T14:32:09.090Z level=INFO msg="emitting device name changed event" component=server peer="192.168.1.27:60166 @ 0x18c81b0" name=Volumio Mar 27 14:32:09 volumio volumio5-onboarding[1684]: time=2026-03-27T14:32:09.091Z level=INFO msg="emitting device language changed event" component=server peer="192.168.1.27:60166 @ 0x18c81b0" language=en Mar 27 14:32:09 volumio volumio[1990]: info: CoreCommandRouter::executeOnPlugin: system , getCurrentTimezone Mar 27 14:32:09 volumio volumio5-onboarding[1684]: time=2026-03-27T14:32:09.092Z level=INFO msg="emitting device timezone changed event" component=server peer="192.168.1.27:60166 @ 0x18c81b0" timezone=Europe/London Mar 27 14:32:09 volumio volumio5-onboarding[1684]: time=2026-03-27T14:32:09.093Z level=INFO msg="emitting ethernet info changed event" component=server peer="192.168.1.27:60166 @ 0x18c81b0" available=true connected=false macAddress= ip4Address= ip6Address= Mar 27 14:32:09 volumio volumio5-onboarding[1684]: time=2026-03-27T14:32:09.094Z level=INFO msg="emitting wifi info changed event" component=server peer="192.168.1.27:60166 @ 0x18c81b0" available=true connected=true macAddress=d8:3a:dd:eb:6c:cd ip4Address=192.168.1.211/24 ip6Address= ssid=Stan Mar 27 14:32:09 volumio volumio5-onboarding[1684]: time=2026-03-27T14:32:09.094Z level=INFO msg="emitting device setup status changed event" component=server peer="192.168.1.27:60166 @ 0x18c81b0" setupComplete=true Mar 27 14:32:09 volumio volumio[1990]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getExtendedOutputDevices Mar 27 14:32:09 volumio volumio[1990]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions Mar 27 14:32:09 volumio volumio[1990]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 27 14:32:09 volumio volumio[1990]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Mar 27 14:32:09 volumio volumio[1990]: amixer -c 0 info | grep "vc4-hdmi-0" Mar 27 14:32:09 volumio volumio[1990]: Card sysdefault:0 'vc4hdmi0'/'vc4-hdmi-0' Mar 27 14:32:09 volumio volumio[1990]: amixer -c 1 info | grep "vc4-hdmi-1" Mar 27 14:32:09 volumio volumio[1990]: Card sysdefault:1 'vc4hdmi1'/'vc4-hdmi-1' Mar 27 14:32:09 volumio volumio[1990]: amixer -c 2 info | grep "snd_rpi_hifiberry_dacplus" Mar 27 14:32:09 volumio volumio[1990]: Card sysdefault:2 'sndrpihifiberry'/'snd_rpi_hifiberry_dacplus' Mar 27 14:32:09 volumio volumio[1990]: error: Cannot read Audio Device Capabilities Command failed: /usr/local/bin/alsacap -C 2 Mar 27 14:32:09 volumio volumio[1990]: /bin/sh: 1: /usr/local/bin/alsacap: not found Mar 27 14:32:09 volumio volumio[1990]: {"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)"} Mar 27 14:32:09 volumio volumio[1990]: amixer -c 2 info | grep "HiFiBerry Amp4 Pro [Pi5]" Mar 27 14:32:09 volumio volumio[1990]: error: Cannot read Audio Device Capabilities Command failed: /usr/local/bin/alsacap -C 5 Mar 27 14:32:09 volumio volumio[1990]: /bin/sh: 1: /usr/local/bin/alsacap: not found Mar 27 14:32:09 volumio volumio[1990]: {"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)"} Mar 27 14:32:09 volumio volumio[1990]: amixer -c 5 info | grep "USB AUDIO CODEC" Mar 27 14:32:09 volumio volumio[1990]: Card sysdefault:5 'CODEC'/'BurrBrown from Texas Instruments USB AUDIO CODEC at usb-xhci-hcd.1-1, full spe' Mar 27 14:32:09 volumio volumio5-onboarding[1684]: time=2026-03-27T14:32:09.181Z level=INFO msg="emitting audio outputs changed event" component=server peer="192.168.1.27:60166 @ 0x18c81b0" selectedOutputId=2 Mar 27 14:32:09 volumio volumio[1990]: info: Received Get System Info Mar 27 14:32:09 volumio volumio[1990]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 27 14:32:09 volumio volumio[1990]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 27 14:32:09 volumio volumio[1990]: info: Discovery: Getting this device information Mar 27 14:32:09 volumio volumio[1990]: info: CoreCommandRouter::volumioGetState Mar 27 14:32:09 volumio volumio[1990]: info: CorePlayQueue::getTrack 7 Mar 27 14:32:09 volumio volumio[1990]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 27 14:32:09 volumio volumio5-onboarding[1684]: time=2026-03-27T14:32:09.194Z level=INFO msg="emitting software info changed event" component=server peer="192.168.1.27:60166 @ 0x18c81b0" currentVersion=4.103 latestVersion=4.103 Mar 27 14:32:09 volumio volumio5-onboarding[1684]: time=2026-03-27T14:32:09.194Z level=INFO msg="emitting software update progress event" component=server peer="192.168.1.27:60166 @ 0x18c81b0" status=UPDATE_STATUS_NONE progress=0 Mar 27 14:32:09 volumio volumio5-onboarding[1684]: time=2026-03-27T14:32:09.194Z level=INFO msg="emitting user changed event" component=server peer="192.168.1.27:60166 @ 0x18c81b0" userId=N3kiJYUF15QnKlFRysActr6hCt63 Mar 27 14:32:09 volumio volumio5-onboarding[1684]: time=2026-03-27T14:32:09.194Z level=INFO msg="emitting music providers changed event" component=server peer="192.168.1.27:60166 @ 0x18c81b0" providers=9 Mar 27 14:32:09 volumio volumio5-onboarding[1684]: time=2026-03-27T14:32:09.195Z level=INFO msg="emitting plugins changed event" component=server peer="192.168.1.27:60166 @ 0x18c81b0" plugins=62 Mar 27 14:32:09 volumio volumio[1990]: info: CoreCommandRouter::volumioGetState Mar 27 14:32:09 volumio volumio[1990]: info: CorePlayQueue::getTrack 7 Mar 27 14:32:09 volumio volumio5-onboarding[1684]: time=2026-03-27T14:32:09.196Z level=INFO msg="emitting player state changed event" component=server peer="192.168.1.27:60166 @ 0x18c81b0" state=STATUS_PAUSED positionMs=51805 volume=39 Mar 27 14:32:09 volumio volumio5-onboarding[1684]: time=2026-03-27T14:32:09.196Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.27:60166 @ 0x18c81b0" id=spotify:track:3CmHvyZQQAGkKkTjTBFWN6 title="Have a Cigar" Mar 27 14:32:09 volumio sudo[3485]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Mar 27 14:32:09 volumio sudo[3485]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 27 14:32:09 volumio sudo[3485]: pam_unix(sudo:session): session closed for user root Mar 27 14:32:09 volumio sudo[3487]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 27 14:32:09 volumio sudo[3487]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 27 14:32:09 volumio sudo[3487]: pam_unix(sudo:session): session closed for user root Mar 27 14:32:10 volumio volumio[1990]: verbose: New Socket.io Connection to 192.168.1.211 from 192.168.1.27 UA: Mozilla/5.0 (Linux; Android 16; Pixel 10a Build/CP1A.260305.018; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/146.0.7680.120 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 14 Mar 27 14:32:10 volumio sudo[3492]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Mar 27 14:32:10 volumio sudo[3492]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 27 14:32:10 volumio sudo[3492]: pam_unix(sudo:session): session closed for user root Mar 27 14:32:10 volumio sudo[3494]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 27 14:32:10 volumio sudo[3494]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 27 14:32:10 volumio sudo[3494]: pam_unix(sudo:session): session closed for user root Mar 27 14:32:10 volumio volumio[1990]: verbose: New Socket.io Connection to 192.168.1.211 from 192.168.1.27 UA: Mozilla/5.0 (Linux; Android 16; Pixel 10a Build/CP1A.260305.018; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/146.0.7680.120 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 15 Mar 27 14:32:10 volumio volumio[1990]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Mar 27 14:32:10 volumio volumio[1990]: info: CoreCommandRouter::volumioGetVisibleSources Mar 27 14:32:10 volumio volumio[1990]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 27 14:32:10 volumio volumio[1990]: info: CoreCommandRouter::volumioGetState Mar 27 14:32:10 volumio volumio[1990]: info: CorePlayQueue::getTrack 7 Mar 27 14:32:10 volumio volumio[1990]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Mar 27 14:32:10 volumio volumio[1990]: info: CoreCommandRouter::volumioGetQueue Mar 27 14:32:10 volumio volumio[1990]: info: CoreStateMachine::getQueue Mar 27 14:32:10 volumio volumio[1990]: info: CorePlayQueue::getQueue Mar 27 14:32:10 volumio volumio[1990]: info: Listing playlists Mar 27 14:32:10 volumio volumio[1990]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Mar 27 14:32:10 volumio volumio[1990]: info: Error : CoreCommandRouter::executeOnPlugin: No method [getMultiroom] in plugin multiroom Mar 27 14:32:10 volumio volumio[1990]: info: Received Get System Info Mar 27 14:32:10 volumio volumio[1990]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 27 14:32:10 volumio volumio[1990]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 27 14:32:10 volumio volumio[1990]: info: Discovery: Getting this device information Mar 27 14:32:10 volumio volumio[1990]: info: CoreCommandRouter::volumioGetState Mar 27 14:32:10 volumio volumio[1990]: info: CorePlayQueue::getTrack 7 Mar 27 14:32:10 volumio volumio[1990]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 27 14:32:10 volumio volumio[1990]: info: CoreCommandRouter::volumioGetState Mar 27 14:32:10 volumio volumio[1990]: info: CorePlayQueue::getTrack 7 Mar 27 14:32:10 volumio volumio[1990]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Mar 27 14:32:10 volumio volumio[1990]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Mar 27 14:32:10 volumio volumio[1990]: info: CoreCommandRouter::getUIConfigOnPlugin Mar 27 14:32:10 volumio volumio[1990]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Mar 27 14:32:12 volumio systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 15955. Mar 27 14:32:12 volumio systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Mar 27 14:32:12 volumio volumio[1990]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Mar 27 14:32:12 volumio systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Mar 27 14:32:12 volumio upmpdcli[3497]: Could not open config: /tmp/upmpdcli.conf Mar 27 14:32:12 volumio systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Mar 27 14:32:12 volumio systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Mar 27 14:32:12 volumio volumio[1990]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Mar 27 14:32:12 volumio volumio[1990]: info: Received Get System Info Mar 27 14:32:12 volumio volumio[1990]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 27 14:32:12 volumio volumio[1990]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 27 14:32:12 volumio volumio[1990]: info: Discovery: Getting this device information Mar 27 14:32:12 volumio volumio[1990]: info: CoreCommandRouter::volumioGetState Mar 27 14:32:12 volumio volumio[1990]: info: CorePlayQueue::getTrack 7 Mar 27 14:32:12 volumio volumio[1990]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 27 14:32:13 volumio volumio[1990]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Mar 27 14:32:13 volumio volumio[1990]: info: Received Get System Info Mar 27 14:32:13 volumio volumio[1990]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 27 14:32:13 volumio volumio[1990]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 27 14:32:13 volumio volumio[1990]: info: Discovery: Getting this device information Mar 27 14:32:13 volumio volumio[1990]: info: CoreCommandRouter::volumioGetState Mar 27 14:32:13 volumio volumio[1990]: info: CorePlayQueue::getTrack 7 Mar 27 14:32:13 volumio volumio[1990]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 27 14:32:15 volumio volumio5-onboarding[1684]: time=2026-03-27T14:32:15.266Z level=WARN msg="pending write exceeded maximum retries, dropping" component=ble/conn addr=11 chunks=17 index=5 tries=11 Mar 27 14:32:15 volumio volumio[1990]: Searching plugin music_service/spop Mar 27 14:32:15 volumio volumio[1990]: info: CoreCommandRouter::executeOnPlugin: spop , search Mar 27 14:32:16 volumio volumio[1990]: info: New access token = BQAsQDjAEYZc3A4q1vDPUJPBjy7HaMdXwSpRz3d1Ok8NhpOqlcvPGt7IY9wkgDCZ1gTrUmlFSluRIwMxBe5BtCBCOIQUqt1vYkEKQz_3TREuPDUiVvYK368jM0cabL1k69Hfo2zmIc9_RQBNfqkRlm9dVB-TDktFdcPIE5BKnmekNKTAKBl61Isja0uGwLV7wxX1UsF1oHpc56B3NdTxIkwC1OOXIJGxm5I4oJQ4pcRtk4bPibEgYek5u5ziGediaXTg6AfktAYxzvTe3kFWxgKm0V-az0XH6IQovx8 Mar 27 14:32:16 volumio volumio[1990]: info: All search sources collected, pushing search results Mar 27 14:32:18 volumio volumio[1990]: info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri Mar 27 14:32:18 volumio volumio[1990]: info: In handleBrowseUri, curUri=spotify:artist:4S9EykWXhStSc15wEx8QFK Mar 27 14:32:19 volumio volumio[1990]: info: Preload queue cleared Mar 27 14:32:19 volumio volumio[1990]: info: Preloading song: spotify:track:28UMiBhn383n9S7GL4tsxD Mar 27 14:32:19 volumio volumio[1990]: info: Preloading song: spotify:track:5EQzuYfTZt7B2LqlvTF49l Mar 27 14:32:19 volumio volumio[1990]: info: Preloading song: spotify:track:33LC84JgLvK2KuW43MfaNq Mar 27 14:32:19 volumio volumio[1990]: info: Preloading song: spotify:track:5kK1Iru9ogP3Iy1zsANU1n Mar 27 14:32:19 volumio volumio[1990]: info: Preloading song: spotify:track:2FTZeRHQ4gRPViPMpWL9uX Mar 27 14:32:19 volumio volumio[1990]: info: Preloading song: spotify:track:0aKWpnMZCR42M9lLhnzJEZ Mar 27 14:32:19 volumio volumio[1990]: info: Preloading song: spotify:track:0gsl92EMIScPGV1AU35nuD Mar 27 14:32:19 volumio volumio[1990]: info: Preloading song: spotify:track:7hyFKrPZo1Zv4D35MpTBdr Mar 27 14:32:19 volumio volumio[1990]: info: Preloading song: spotify:track:6qlpXtA29VcxCNgLWR5IWx Mar 27 14:32:19 volumio volumio[1990]: info: Preloading song: spotify:track:7B3UAPLYAbwXVgbHSKEaTw Mar 27 14:32:19 volumio volumio[1990]: info: Preload queue cleared Mar 27 14:32:19 volumio volumio[1990]: info: Preload queue cleared Mar 27 14:32:19 volumio volumio[1990]: info: Executing endpoint getSimilarArtists Mar 27 14:32:19 volumio volumio[1990]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getSimilarArtists Mar 27 14:32:19 volumio volumio[1990]: info: Executing endpoint metavolumio Mar 27 14:32:19 volumio volumio[1990]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Mar 27 14:32:20 volumio volumio[1990]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Mar 27 14:32:26 volumio go-librespot[2477]: time="2026-03-27T14:32:26Z" level=trace msg="sent dealer ping" Mar 27 14:32:26 volumio go-librespot[2477]: time="2026-03-27T14:32:26Z" level=trace msg="received dealer pong" Mar 27 14:32:26 volumio systemd[1]: Starting setdatetime-helper.service - Time Synchronization Helper Service... Mar 27 14:32:27 volumio systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 15956. Mar 27 14:32:27 volumio systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Mar 27 14:32:27 volumio systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Mar 27 14:32:27 volumio systemd[1]: setdatetime-helper.service: Deactivated successfully. Mar 27 14:32:27 volumio systemd[1]: Finished setdatetime-helper.service - Time Synchronization Helper Service. Mar 27 14:32:27 volumio upmpdcli[3538]: Could not open config: /tmp/upmpdcli.conf Mar 27 14:32:27 volumio systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Mar 27 14:32:27 volumio systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Mar 27 14:32:28 volumio volumio[1990]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Mar 27 14:32:28 volumio volumio[1990]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Mar 27 14:32:28 volumio volumio[1990]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Mar 27 14:32:28 volumio volumio[1990]: info: Received Get System Version Mar 27 14:32:28 volumio volumio[1990]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 27 14:32:28 volumio volumio[1990]: info: Received Get System Info Mar 27 14:32:28 volumio volumio[1990]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 27 14:32:28 volumio volumio[1990]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 27 14:32:28 volumio volumio[1990]: info: Discovery: Getting this device information Mar 27 14:32:28 volumio volumio[1990]: info: CoreCommandRouter::volumioGetState Mar 27 14:32:28 volumio volumio[1990]: info: CorePlayQueue::getTrack 7 Mar 27 14:32:28 volumio volumio[1990]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 27 14:32:34 volumio volumio5-onboarding[1684]: time=2026-03-27T14:32:34.590Z level=ERROR msg="failed to read message" component=conn/ws remoteAddr=192.168.1.27:60166 error="read tcp 192.168.1.211:7331->192.168.1.27:60166: read: connection reset by peer" Mar 27 14:32:34 volumio volumio5-onboarding[1684]: time=2026-03-27T14:32:34.590Z level=INFO msg="WebSocket connection closed" component=conn/ws remoteAddr=192.168.1.27:60166 Mar 27 14:32:34 volumio volumio5-onboarding[1684]: time=2026-03-27T14:32:34.590Z level=INFO msg="connection to address closed" component=conn/multi addr=192.168.1.27:60166 Mar 27 14:32:39 volumio volumio[1990]: verbose: New Socket.io Connection to 192.168.1.211 from 192.168.1.27 UA: Mozilla/5.0 (Linux; Android 16; Pixel 10a Build/CP1A.260305.018; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/146.0.7680.120 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 15 Mar 27 14:32:39 volumio volumio[1990]: verbose: New Socket.io Connection to 192.168.1.211 from 192.168.1.27 UA: Mozilla/5.0 (Linux; Android 16; Pixel 10a Build/CP1A.260305.018; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/146.0.7680.120 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 16 Mar 27 14:32:39 volumio volumio[1990]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Mar 27 14:32:40 volumio volumio[1990]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Mar 27 14:32:40 volumio volumio[1990]: info: CoreCommandRouter::volumioGetVisibleSources Mar 27 14:32:40 volumio volumio[1990]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 27 14:32:40 volumio volumio[1990]: info: CoreCommandRouter::volumioGetState Mar 27 14:32:40 volumio volumio[1990]: info: CorePlayQueue::getTrack 7 Mar 27 14:32:40 volumio volumio[1990]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Mar 27 14:32:40 volumio volumio[1990]: info: CoreCommandRouter::volumioGetQueue Mar 27 14:32:40 volumio volumio[1990]: info: CoreStateMachine::getQueue Mar 27 14:32:40 volumio volumio[1990]: info: CorePlayQueue::getQueue Mar 27 14:32:40 volumio volumio[1990]: info: Listing playlists Mar 27 14:32:40 volumio volumio[1990]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Mar 27 14:32:40 volumio volumio[1990]: info: Error : CoreCommandRouter::executeOnPlugin: No method [getMultiroom] in plugin multiroom Mar 27 14:32:40 volumio volumio[1990]: info: Received Get System Info Mar 27 14:32:40 volumio volumio[1990]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 27 14:32:40 volumio volumio[1990]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 27 14:32:40 volumio volumio[1990]: info: Discovery: Getting this device information Mar 27 14:32:40 volumio volumio[1990]: info: CoreCommandRouter::volumioGetState Mar 27 14:32:40 volumio volumio[1990]: info: CorePlayQueue::getTrack 7 Mar 27 14:32:40 volumio volumio[1990]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 27 14:32:40 volumio volumio[1990]: info: CoreCommandRouter::volumioGetState Mar 27 14:32:40 volumio volumio[1990]: info: CorePlayQueue::getTrack 7 Mar 27 14:32:40 volumio volumio[1990]: info: CoreCommandRouter::getUIConfigOnPlugin Mar 27 14:32:40 volumio volumio[1990]: info: CoreCommandRouter::getUIConfigOnPlugin Mar 27 14:32:40 volumio volumio5-onboarding[1684]: time=2026-03-27T14:32:40.638Z level=INFO msg="established new WebSocket connection" component=conn/ws remoteAddr=192.168.1.27:58862 Mar 27 14:32:41 volumio volumio5-onboarding[1684]: time=2026-03-27T14:32:41.868Z level=INFO msg="established new WebSocket connection" component=conn/ws remoteAddr=192.168.1.27:36368 Mar 27 14:32:42 volumio systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 15957. Mar 27 14:32:42 volumio systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Mar 27 14:32:42 volumio systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Mar 27 14:32:42 volumio upmpdcli[3568]: Could not open config: /tmp/upmpdcli.conf Mar 27 14:32:42 volumio systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Mar 27 14:32:42 volumio systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Mar 27 14:32:43 volumio volumio5-onboarding[1684]: time=2026-03-27T14:32:43.185Z level=INFO msg="WebSocket connection closed" component=conn/ws remoteAddr=192.168.1.27:58862 Mar 27 14:32:43 volumio volumio5-onboarding[1684]: time=2026-03-27T14:32:43.185Z level=INFO msg="connection to address closed" component=conn/multi addr=192.168.1.27:58862 Mar 27 14:32:43 volumio volumio5-onboarding[1684]: time=2026-03-27T14:32:43.196Z level=INFO msg="established new WebSocket connection" component=conn/ws remoteAddr=192.168.1.27:58876 Mar 27 14:32:44 volumio volumio5-onboarding[1684]: time=2026-03-27T14:32:44.739Z level=INFO msg="WebSocket connection closed" component=conn/ws remoteAddr=192.168.1.27:58876 Mar 27 14:32:44 volumio volumio5-onboarding[1684]: time=2026-03-27T14:32:44.739Z level=INFO msg="connection to address closed" component=conn/multi addr=192.168.1.27:58876 Mar 27 14:32:44 volumio volumio5-onboarding[1684]: time=2026-03-27T14:32:44.762Z level=INFO msg="established new WebSocket connection" component=conn/ws remoteAddr=192.168.1.27:58894 Mar 27 14:32:47 volumio go-librespot[2477]: time="2026-03-27T14:32:47Z" level=trace msg="received accesspoint ping" Mar 27 14:32:47 volumio go-librespot[2477]: time="2026-03-27T14:32:47Z" level=trace msg="received accesspoint pong ack" Mar 27 14:32:47 volumio volumio5-onboarding[1684]: time=2026-03-27T14:32:47.788Z level=INFO msg="new address was allocated" component=ble/conn old=12 new=13 Mar 27 14:32:49 volumio volumio5-onboarding[1684]: time=2026-03-27T14:32:49.839Z level=INFO msg="new address was allocated" component=ble/conn old=13 new=14 Mar 27 14:32:51 volumio volumio[1990]: Searching plugin music_service/spop Mar 27 14:32:51 volumio volumio[1990]: info: CoreCommandRouter::executeOnPlugin: spop , search Mar 27 14:32:51 volumio volumio[1990]: info: All search sources collected, pushing search results Mar 27 14:32:52 volumio volumio[1990]: Searching plugin music_service/spop Mar 27 14:32:52 volumio volumio[1990]: info: CoreCommandRouter::executeOnPlugin: spop , search Mar 27 14:32:53 volumio volumio[1990]: Searching plugin music_service/spop Mar 27 14:32:53 volumio volumio[1990]: info: CoreCommandRouter::executeOnPlugin: spop , search Mar 27 14:32:53 volumio volumio[1990]: info: All search sources collected, pushing search results Mar 27 14:32:54 volumio volumio[1990]: info: All search sources collected, pushing search results Mar 27 14:32:56 volumio volumio[1990]: info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri Mar 27 14:32:56 volumio volumio[1990]: info: In handleBrowseUri, curUri=spotify:artist:1LosuiVNhK4bDX9VcVDzbR Mar 27 14:32:56 volumio go-librespot[2477]: time="2026-03-27T14:32:56Z" level=trace msg="sent dealer ping" Mar 27 14:32:56 volumio go-librespot[2477]: time="2026-03-27T14:32:56Z" level=trace msg="received dealer pong" Mar 27 14:32:56 volumio volumio[1990]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 27 14:32:56 volumio volumio[1990]: TypeError: Cannot read properties of undefined (reading 'url') Mar 27 14:32:56 volumio volumio[1990]: at /data/plugins/music_service/spop/index.js:2446:60 Mar 27 14:32:56 volumio volumio[1990]: at process.processTicksAndRejections (node:internal/process/task_queues:95:5) Mar 27 14:32:56 volumio volumio[1990]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 27 14:32:56 volumio sudo[3597]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-03-27 14:31' Mar 27 14:32:56 volumio sudo[3597]: 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="dc61260dec5515dafd2b634881860b4c46c919ff" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="0e58f1861fa88e02087981b8d91f7511f0e7011b" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri Mar 6 16:46:58 UTC 2026" VOLUMIO_VERSION="4.103" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="aa741395b8bfc648ff5d04e312f53d2c"