Aug 31 18:54:07 volumio volumio5-onboarding[2204]: time=2026-08-31T15:54:07.398Z level=ERROR msg="failed to read message" component=conn/ws remoteAddr=192.168.1.24:60166 error="websocket: close 1006 (abnormal closure): unexpected EOF" Aug 31 18:54:07 volumio volumio5-onboarding[2204]: time=2026-08-31T15:54:07.398Z level=INFO msg="WebSocket connection closed" component=conn/ws remoteAddr=192.168.1.24:60166 Aug 31 18:54:07 volumio volumio5-onboarding[2204]: time=2026-08-31T15:54:07.398Z level=INFO msg="connection to address closed" component=conn/multi addr=192.168.1.24:60166 Aug 31 18:54:11 volumio dbus-daemon[1030]: [system] Rejected send message, 0 matched rules; type="error", sender=":1.16" (uid=0 pid=2204 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=1029 comm="/usr/libexec/bluetooth/bluetoothd --noplugin=sap,b") Aug 31 18:54:17 volumio volumio[1429]: info: [yt-cast-receiver] Connecting sender through DIAL... Aug 31 18:54:19 volumio volumio[1429]: info: [yt-cast-receiver] (YouTube) Sender connected: GOOGLE Pixel 10 Pro XL (user: Monir) Aug 31 18:54:19 volumio volumio[1429]: info: [ytcr] ***** Sender connected ***** Aug 31 18:54:19 volumio volumio[1429]: info: CoreCommandRouter::getUIConfigOnPlugin Aug 31 18:54:23 volumio volumio[1429]: info: [yt-cast-receiver] Player.play(): u8KxLq3MNZc @ 0s Aug 31 18:54:23 volumio volumio[1429]: info: CoreCommandRouter::volumioGetState Aug 31 18:54:23 volumio volumio[1429]: info: CorePlayQueue::getTrack 0 Aug 31 18:54:23 volumio volumio[1429]: info: CoreCommandRouter::volumioGetState Aug 31 18:54:23 volumio volumio[1429]: info: CorePlayQueue::getTrack 0 Aug 31 18:54:23 volumio volumio[1429]: info: CoreCommandRouter::volumioStop Aug 31 18:54:23 volumio volumio[1429]: info: CoreStateMachine::stop Aug 31 18:54:23 volumio volumio[1429]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 31 18:54:23 volumio volumio[1429]: info: CoreCommandRouter::volumioGetState Aug 31 18:54:23 volumio volumio[1429]: info: CorePlayQueue::getTrack 0 Aug 31 18:54:23 volumio volumio[1429]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 31 18:54:23 volumio volumio[1429]: info: CoreCommandRouter::servicePushState Aug 31 18:54:23 volumio volumio[1429]: info: CoreStateMachine::pushState Aug 31 18:54:23 volumio volumio[1429]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 31 18:54:23 volumio volumio[1429]: info: CoreCommandRouter::volumioPushState Aug 31 18:54:23 volumio volumio[1429]: info: CoreCommandRouter::servicePushState Aug 31 18:54:23 volumio volumio[1429]: info: CoreStateMachine::pushState Aug 31 18:54:23 volumio volumio[1429]: info: CoreCommandRouter::volumioPushState Aug 31 18:54:23 volumio volumio5-onboarding[2204]: time=2026-08-31T15:54:23.453Z level=INFO msg="emitting player state changed event" component=server peer="192.168.1.24:60166 @ 0xc000316150" state=STATUS_PAUSED positionMs=0 volume=41 Aug 31 18:54:23 volumio volumio5-onboarding[2204]: time=2026-08-31T15:54:23.453Z level=INFO msg="emitting player state changed event" component=server peer="192.168.1.24:60166 @ 0xc000316150" state=STATUS_PAUSED positionMs=0 volume=41 Aug 31 18:54:23 volumio volumio5-onboarding[2204]: time=2026-08-31T15:54:23.454Z level=ERROR msg="failed to send event" component=server dst="192.168.1.24:60166 @ 0xc000316150" event=SERVER_EVENT_TYPE_PLAYER_STATE_CHANGED error="no WebSocket connection found for address: 192.168.1.24:60166" Aug 31 18:54:23 volumio volumio5-onboarding[2204]: time=2026-08-31T15:54:23.454Z level=ERROR msg="failed to send event" component=server dst="192.168.1.24:60166 @ 0xc000316150" event=SERVER_EVENT_TYPE_PLAYER_STATE_CHANGED error="no WebSocket connection found for address: 192.168.1.24:60166" Aug 31 18:54:23 volumio volumio5-onboarding[2204]: time=2026-08-31T15:54:23.454Z level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%04 @ 0xc000382ea0" state=STATUS_PAUSED positionMs=0 volume=41 Aug 31 18:54:23 volumio volumio5-onboarding[2204]: time=2026-08-31T15:54:23.454Z level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%04 @ 0xc000382ea0" state=STATUS_PAUSED positionMs=0 volume=41 Aug 31 18:54:23 volumio volumio[1429]: info: CoreCommandRouter::volumioGetState Aug 31 18:54:23 volumio volumio[1429]: info: CoreCommandRouter::servicePushState Aug 31 18:54:23 volumio volumio[1429]: info: CoreStateMachine::pushState Aug 31 18:54:23 volumio volumio[1429]: info: CoreCommandRouter::volumioPushState Aug 31 18:54:23 volumio volumio[1429]: info: CorePlayQueue::getTrack 0 Aug 31 18:54:23 volumio volumio[1429]: verbose: STATE SERVICE {"status":"stop","service":"ytcr","albumart":"/albumart","uri":"","trackType":"YouTube","seek":0,"duration":0,"volume":41,"mute":false} Aug 31 18:54:23 volumio volumio[1429]: verbose: CURRENT POSITION 0 Aug 31 18:54:23 volumio volumio[1429]: info: CoreStateMachine::syncState stateService stop Aug 31 18:54:23 volumio volumio[1429]: info: CoreStateMachine::syncState currentStatus pause Aug 31 18:54:23 volumio volumio[1429]: info: CoreStateMachine::pushState Aug 31 18:54:23 volumio volumio[1429]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 31 18:54:23 volumio volumio[1429]: info: CoreCommandRouter::volumioPushState Aug 31 18:54:23 volumio volumio5-onboarding[2204]: time=2026-08-31T15:54:23.456Z level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%04 @ 0xc000382ea0" state=STATUS_PAUSED positionMs=0 volume=41 Aug 31 18:54:23 volumio volumio5-onboarding[2204]: time=2026-08-31T15:54:23.456Z level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%04 @ 0xc000382ea0" state=STATUS_PAUSED positionMs=0 volume=41 Aug 31 18:54:25 volumio volumio[1429]: info: [ytcr] Innertube support service: Start service with Deno: deno 2.9.6 (stable, release, x86_64-unknown-linux-gnu) Aug 31 18:54:26 volumio volumio[1429]: info: [ytcr] Innertube support service: result: {"status":"started","server":{"address":"127.0.0.1","port":42553}} Aug 31 18:54:26 volumio volumio[1429]: info: [ytcr] Innertube support service running at http://127.0.0.1:42553 Aug 31 18:54:26 volumio volumio[1429]: error: [ytcr] Innertube support service: libEGL warning: failed to open /dev/dri/renderD128: Permission denied Aug 31 18:54:26 volumio volumio5-onboarding[2204]: time=2026-08-31T15:54:26.763Z level=WARN msg="pending write exceeded maximum retries, dropping" component=ble/conn addr=4 chunks=1 index=0 tries=11 Aug 31 18:54:26 volumio volumio5-onboarding[2204]: time=2026-08-31T15:54:26.764Z level=ERROR msg="failed to send event" component=server dst="00:00:00:00:00:00%04 @ 0xc000382ea0" event=SERVER_EVENT_TYPE_PLAYER_STATE_CHANGED error="peer is gone" Aug 31 18:54:26 volumio volumio[1429]: info: [ytcr] Obtained session PO token using visitorData (expires in 43199 seconds) Aug 31 18:54:26 volumio volumio[1429]: info: [ytcr] Going to refresh session PO token in 43099 seconds Aug 31 18:54:26 volumio volumio[1429]: info: [ytcr] Obtained PO token for video #u8KxLq3MNZc: MlvA-XHZVbJkTcC9vVR6R-FaIy1VCL3-2Uw34wWk-toQH2DmwRBrzDPiSa7MQNKJ1ezuygT50NZ1Y81RZpnbZCIkYt1yPdh7yyMOMIcba0-JHuvyp9wqxrWkQIQ_ Aug 31 18:54:27 volumio volumio[1429]: info: [ytcr] (u8KxLq3MNZc) fetching player data using YTMUSIC client... Aug 31 18:54:27 volumio volumio[1429]: info: [ytcr] (Black (Live at GTE Amphitheater, Virginia Beach, VA - September 1998)) validating stream URL "https://rr2---sn-wvgq5ouxaxjvh-5hhr.googlevideo.com/videoplayback?expire=1788213267&ei=s6OVav-uJ7vEv_IPpobKuA4&ip=92.253.32.149&id=o-AH079LXZXTrIaSFmknmz2Z4EHszoCPcQbu-vByKXoV5u&itag=774&source=youtube&requiressl=yes&xpc=EgVo2aDSNQ%3D%3D&cps=192&met=1788191667%2C&mh=TI&mm=31%2C29&mn=sn-wvgq5ouxaxjvh-5hhr%2Csn-4g5ednsy&ms=au%2Crdu&mv=m&mvi=2&pl=24&rms=au%2Cau&ctier=A&pfa=5&gcr=jo&initcwndbps=1738750&hightc=yes&siu=1&bui=AR3QkAn-yh9EHxfdega1RPVLN84tg_6qJ3Q4kQZrTzY3_DuUoEGpfJ5hwlQnoPsRDscL3ktKkQ&spc=KBGBctiUhX4hrjQrU1Iyb8svl4Z6pAHs6kTu_ipRz6fFMi8BeRjADVS-B4XWYsw&vprv=1&svpuc=1&mime=audio%2Fwebm&ns=tHzjyrbwqmjf6kM8wmdgNwMY&rqh=1&gir=yes&clen=13237879&dur=415.641&lmt=1714882729264029&mt=1788191362&fvip=1&keepalive=yes&fexp=51565116%2C52135441&c=WEB_REMIX&sefc=1&txp=1432434&n=P1j7TlQV8NpWmw&sparams=expire%2Cei%2Cip%2Cid%2Citag%2Csource%2Crequiressl%2Cxpc%2Cctier%2Cpfa%2Cgcr%2Chightc%2Csiu%2Cbui%2Cspc%2Cvprv%2Csvpuc%2Cmime%2Cns%2Crqh%2Cgir%2Cclen%2Cdur%2Clmt&lsparams=cps%2Cmet%2Cmh%2Cmm%2Cmn%2Cms%2Cmv%2Cmvi%2Cpl%2Crms%2Cinitcwndbps&lsig=APaTxxMwRQIhAJcNrzVgxOllXQcdhCh3WPF30fbZGMYtpVaK3BD6_dC3AiAWR2JakKdnW2CW2-nnETV1hO0oJAQEouBGFNfGAyvAVg%3D%3D&sig=AE0s2JYwRQIhAOsEWdJYPwbcMX71dA0pY18n-PzjWJdUCgkOFO5jsJOHAiAhLgppF_UlR03RuknDlg0wcou9kBSF2KaTY6DLxoi2Fw%3D%3D&cver=1.20250219.01.00&pot=MlvA-XHZVbJkTcC9vVR6R-FaIy1VCL3-2Uw34wWk-toQH2DmwRBrzDPiSa7MQNKJ1ezuygT50NZ1Y81RZpnbZCIkYt1yPdh7yyMOMIcba0-JHuvyp9wqxrWkQIQ_"... Aug 31 18:54:27 volumio volumio[1429]: info: [ytcr] (Black (Live at GTE Amphitheater, Virginia Beach, VA - September 1998)) stream validated in 0.039s. Aug 31 18:54:27 volumio volumio[1429]: info: Ignoring MPD Status Update Aug 31 18:54:27 volumio volumio[1429]: info: Ignoring MPD Status Update Aug 31 18:54:27 volumio volumio[1429]: info: Ignoring MPD Status Update Aug 31 18:54:27 volumio volumio[1429]: info: Ignoring MPD Status Update Aug 31 18:54:27 volumio volumio[1429]: info: Ignoring MPD Status Update Aug 31 18:54:27 volumio volumio[1429]: info: Ignoring MPD Status Update Aug 31 18:54:27 volumio volumio[1429]: info: Ignoring MPD Status Update Aug 31 18:54:27 volumio volumio[1429]: info: Ignoring MPD Status Update Aug 31 18:54:27 volumio volumio[1429]: info: Ignoring MPD Status Update Aug 31 18:54:27 volumio volumio[1429]: info: Ignoring MPD Status Update Aug 31 18:54:27 volumio volumio[1429]: info: Ignoring MPD Status Update Aug 31 18:54:27 volumio volumio[1429]: info: Ignoring MPD Status Update Aug 31 18:54:27 volumio volumio[1429]: info: Ignoring MPD Status Update Aug 31 18:54:27 volumio volumio[1429]: info: Ignoring MPD Status Update Aug 31 18:54:27 volumio volumio[1429]: info: Ignoring MPD Status Update Aug 31 18:54:27 volumio volumio[1429]: info: Ignoring MPD Status Update Aug 31 18:54:27 volumio volumio[1429]: info: Ignoring MPD Status Update Aug 31 18:54:27 volumio volumio[1429]: info: Ignoring MPD Status Update Aug 31 18:54:27 volumio volumio[1429]: info: Ignoring MPD Status Update Aug 31 18:54:27 volumio volumio[1429]: info: Ignoring MPD Status Update Aug 31 18:54:27 volumio volumio[1429]: info: Ignoring MPD Status Update Aug 31 18:54:27 volumio volumio[1429]: info: Ignoring MPD Status Update Aug 31 18:54:27 volumio volumio[1429]: info: Ignoring MPD Status Update Aug 31 18:54:27 volumio volumio[1429]: info: Ignoring MPD Status Update Aug 31 18:54:27 volumio volumio[1429]: info: Ignoring MPD Status Update Aug 31 18:54:27 volumio volumio[1429]: info: Ignoring MPD Status Update Aug 31 18:54:27 volumio volumio[1429]: info: Ignoring MPD Status Update Aug 31 18:54:27 volumio volumio[1429]: info: Ignoring MPD Status Update Aug 31 18:54:27 volumio volumio[1429]: info: Ignoring MPD Status Update Aug 31 18:54:27 volumio volumio[1429]: info: Ignoring MPD Status Update Aug 31 18:54:27 volumio volumio[1429]: info: Ignoring MPD Status Update Aug 31 18:54:27 volumio volumio[1429]: info: Ignoring MPD Status Update Aug 31 18:54:27 volumio volumio[1429]: info: Ignoring MPD Status Update Aug 31 18:54:28 volumio volumio[1429]: info: Ignoring MPD Status Update Aug 31 18:54:28 volumio volumio[1429]: info: Ignoring MPD Status Update Aug 31 18:54:28 volumio volumio[1429]: info: Ignoring MPD Status Update Aug 31 18:54:28 volumio volumio[1429]: info: Ignoring MPD Status Update Aug 31 18:54:28 volumio volumio[1429]: info: Ignoring MPD Status Update Aug 31 18:54:28 volumio volumio[1429]: info: Ignoring MPD Status Update Aug 31 18:54:28 volumio volumio[1429]: info: CoreCommandRouter::volumioGetState Aug 31 18:54:28 volumio volumio[1429]: info: CoreCommandRouter::servicePushState Aug 31 18:54:28 volumio volumio[1429]: info: CoreStateMachine::pushState Aug 31 18:54:28 volumio volumio[1429]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 31 18:54:28 volumio volumio[1429]: info: CoreCommandRouter::volumioPushState Aug 31 18:54:30 volumio volumio5-onboarding[2204]: time=2026-08-31T15:54:30.073Z level=WARN msg="pending write exceeded maximum retries, dropping" component=ble/conn addr=4 chunks=1 index=0 tries=11 Aug 31 18:54:30 volumio volumio5-onboarding[2204]: time=2026-08-31T15:54:30.073Z level=ERROR msg="failed to send event" component=server dst="00:00:00:00:00:00%04 @ 0xc000382ea0" event=SERVER_EVENT_TYPE_PLAYER_STATE_CHANGED error="peer is gone" Aug 31 18:54:33 volumio volumio5-onboarding[2204]: time=2026-08-31T15:54:33.382Z level=WARN msg="pending write exceeded maximum retries, dropping" component=ble/conn addr=4 chunks=1 index=0 tries=11 Aug 31 18:54:33 volumio volumio5-onboarding[2204]: time=2026-08-31T15:54:33.382Z level=ERROR msg="failed to send event" component=server dst="00:00:00:00:00:00%04 @ 0xc000382ea0" event=SERVER_EVENT_TYPE_PLAYER_STATE_CHANGED error="peer is gone" Aug 31 18:54:36 volumio volumio5-onboarding[2204]: time=2026-08-31T15:54:36.693Z level=WARN msg="pending write exceeded maximum retries, dropping" component=ble/conn addr=4 chunks=1 index=0 tries=11 Aug 31 18:54:36 volumio volumio5-onboarding[2204]: time=2026-08-31T15:54:36.693Z level=ERROR msg="failed to send event" component=server dst="00:00:00:00:00:00%04 @ 0xc000382ea0" event=SERVER_EVENT_TYPE_PLAYER_STATE_CHANGED error="peer is gone" Aug 31 18:54:41 volumio bluealsa[1063]: bluez.c:1393: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved(/org/bluez/hci0/dev_57_51_DF_64_40_EC, ...) Aug 31 18:54:47 volumio volumio[1429]: info: VolumeController::SetAlsaVolume55 Aug 31 18:54:47 volumio volumio[1429]: info: CoreCommandRouter::volumioGetState Aug 31 18:54:47 volumio volumio[1429]: info: CoreStateMachine::pushState Aug 31 18:54:47 volumio volumio[1429]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 31 18:54:47 volumio volumio[1429]: info: CoreCommandRouter::volumioPushState Aug 31 18:54:47 volumio volumio[1429]: info: CoreCommandRouter::servicePushState Aug 31 18:54:47 volumio volumio[1429]: info: CoreStateMachine::pushState Aug 31 18:54:47 volumio volumio[1429]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 31 18:54:47 volumio volumio[1429]: info: CoreCommandRouter::volumioPushState Aug 31 18:54:47 volumio volumio[1429]: info: Setting Spotify Volume from Volumio: 55 Aug 31 18:54:47 volumio volumio[1429]: info: CoreCommandRouter::servicePushState Aug 31 18:54:47 volumio volumio[1429]: info: CoreStateMachine::pushState Aug 31 18:54:47 volumio volumio[1429]: info: CoreCommandRouter::volumioPushState Aug 31 18:54:47 volumio volumio[1429]: info: CoreCommandRouter::volumioGetState Aug 31 18:54:47 volumio volumio[1429]: info: CoreCommandRouter::servicePushState Aug 31 18:54:47 volumio volumio[1429]: info: CoreStateMachine::pushState Aug 31 18:54:47 volumio volumio[1429]: info: CoreCommandRouter::volumioPushState Aug 31 18:54:48 volumio volumio[1429]: info: VolumeController::SetAlsaVolume98 Aug 31 18:54:48 volumio volumio[1429]: info: CoreCommandRouter::volumioGetState Aug 31 18:54:48 volumio volumio[1429]: info: CoreStateMachine::pushState Aug 31 18:54:48 volumio volumio[1429]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 31 18:54:48 volumio volumio[1429]: info: CoreCommandRouter::volumioPushState Aug 31 18:54:48 volumio volumio[1429]: info: CoreCommandRouter::servicePushState Aug 31 18:54:48 volumio volumio[1429]: info: CoreStateMachine::pushState Aug 31 18:54:48 volumio volumio[1429]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 31 18:54:48 volumio volumio[1429]: info: CoreCommandRouter::volumioPushState Aug 31 18:54:48 volumio volumio[1429]: info: Setting Spotify Volume from Volumio: 98 Aug 31 18:54:48 volumio volumio[1429]: info: CoreCommandRouter::servicePushState Aug 31 18:54:48 volumio volumio[1429]: info: CoreStateMachine::pushState Aug 31 18:54:48 volumio volumio[1429]: info: CoreCommandRouter::volumioPushState Aug 31 18:54:48 volumio volumio[1429]: info: CoreCommandRouter::volumioGetState Aug 31 18:54:48 volumio volumio[1429]: info: CoreCommandRouter::servicePushState Aug 31 18:54:48 volumio volumio[1429]: info: CoreStateMachine::pushState Aug 31 18:54:48 volumio volumio[1429]: info: CoreCommandRouter::volumioPushState Aug 31 18:54:48 volumio volumio[1429]: info: VolumeController::SetAlsaVolume100 Aug 31 18:54:48 volumio volumio[1429]: info: CoreCommandRouter::volumioGetState Aug 31 18:54:48 volumio volumio[1429]: info: CoreStateMachine::pushState Aug 31 18:54:48 volumio volumio[1429]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 31 18:54:48 volumio volumio[1429]: info: CoreCommandRouter::volumioPushState Aug 31 18:54:48 volumio volumio[1429]: info: CoreCommandRouter::servicePushState Aug 31 18:54:48 volumio volumio[1429]: info: CoreStateMachine::pushState Aug 31 18:54:48 volumio volumio[1429]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 31 18:54:48 volumio volumio[1429]: info: CoreCommandRouter::volumioPushState Aug 31 18:54:48 volumio volumio[1429]: info: Setting Spotify Volume from Volumio: 100 Aug 31 18:54:48 volumio volumio[1429]: info: CoreCommandRouter::servicePushState Aug 31 18:54:48 volumio volumio[1429]: info: CoreStateMachine::pushState Aug 31 18:54:48 volumio volumio[1429]: info: CoreCommandRouter::volumioPushState Aug 31 18:54:48 volumio volumio[1429]: info: CoreCommandRouter::volumioGetState Aug 31 18:54:48 volumio volumio[1429]: info: CoreCommandRouter::servicePushState Aug 31 18:54:48 volumio volumio[1429]: info: CoreStateMachine::pushState Aug 31 18:54:48 volumio volumio[1429]: info: CoreCommandRouter::volumioPushState Aug 31 18:54:49 volumio volumio[1429]: info: Sending Spotify command with payload to local API: /player/volume Aug 31 18:54:59 volumio kernel: usb 3-3: USB disconnect, device number 2 Aug 31 18:54:59 volumio volumio[1429]: info: Aug 31 18:54:59 volumio volumio[1429]: ---------------------------- USB Audio Device Detached Aug 31 18:54:59 volumio volumio[1429]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , usbAudioDetach Aug 31 18:54:59 volumio volumio[1429]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Aug 31 18:55:03 volumio kernel: usb 3-3: new high-speed USB device number 5 using xhci_hcd Aug 31 18:55:03 volumio kernel: usb 3-3: New USB device found, idVendor=262a, idProduct=0001, bcdDevice= 0.01 Aug 31 18:55:03 volumio kernel: usb 3-3: New USB device strings: Mfr=1, Product=2, SerialNumber=6 Aug 31 18:55:03 volumio kernel: usb 3-3: Product: USB HIFI Audio Aug 31 18:55:03 volumio kernel: usb 3-3: Manufacturer: SUCA AUDIO Aug 31 18:55:03 volumio kernel: usb 3-3: SerialNumber: 5000000001 Aug 31 18:55:03 volumio kernel: hid-generic 0003:262A:0001.0004: No inputs registered, leaving Aug 31 18:55:03 volumio kernel: hid-generic 0003:262A:0001.0004: hidraw0: USB HID v1.00 Device [SUCA AUDIO USB HIFI Audio] on usb-0000:00:14.0-3/input0 Aug 31 18:55:03 volumio mtp-probe[194287]: checking bus 3, device 5: "/sys/devices/pci0000:00/0000:00:14.0/usb3/3-3" Aug 31 18:55:03 volumio mtp-probe[194287]: bus: 3, device: 5 was not an MTP device Aug 31 18:55:03 volumio (udev-worker)[194291]: controlC5: Process '/usr/sbin/alsactl -E HOME=/run/alsa -E XDG_RUNTIME_DIR=/run/alsa/runtime restore 5' failed with exit code 99. Aug 31 18:55:03 volumio volumio[1429]: info: Aug 31 18:55:03 volumio volumio[1429]: ---------------------------- USB Audio Device Attached Aug 31 18:55:03 volumio volumio[1429]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , usbAudioAttach Aug 31 18:55:03 volumio mtp-probe[194295]: checking bus 3, device 5: "/sys/devices/pci0000:00/0000:00:14.0/usb3/3-3" Aug 31 18:55:03 volumio mtp-probe[194295]: bus: 3, device: 5 was not an MTP device Aug 31 18:55:10 volumio volumio[1429]: info: CoreCommandRouter::getUIConfigOnPlugin Aug 31 18:55:10 volumio volumio[1429]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions Aug 31 18:55:10 volumio volumio[1429]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 31 18:55:10 volumio volumio[1429]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Aug 31 18:55:10 volumio volumio[1429]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 31 18:55:10 volumio volumio[1429]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 31 18:55:10 volumio volumio[1429]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 31 18:55:10 volumio volumio[1429]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 31 18:55:10 volumio volumio[1429]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 31 18:55:10 volumio volumio[1429]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 31 18:55:10 volumio volumio[1429]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 31 18:55:10 volumio volumio[1429]: info: CoreCommandRouter::executeOnPlugin: mpd , getPlaybackMode Aug 31 18:55:10 volumio volumio[1429]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus Aug 31 18:55:13 volumio volumio[1429]: info: CALLMETHOD: audio_interface alsa_controller saveAlsaOptions [object Object] Aug 31 18:55:13 volumio volumio[1429]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , saveAlsaOptions Aug 31 18:55:13 volumio volumio[1429]: info: Preparing to save Alsa Options, stopping services first Aug 31 18:55:13 volumio volumio[1429]: info: CoreCommandRouter::volumioGetState Aug 31 18:55:13 volumio volumio[1429]: info: CoreCommandRouter::volumioPause Aug 31 18:55:13 volumio volumio[1429]: info: CoreStateMachine::pause Aug 31 18:55:13 volumio volumio[1429]: info: CoreStateMachine::stPlaybackTimer Aug 31 18:55:13 volumio volumio[1429]: info: CoreStateMachine::servicePause Aug 31 18:55:13 volumio volumio[1429]: info: CoreCommandRouter::servicePause Aug 31 18:55:13 volumio volumio[1429]: info: [yt-cast-receiver] Player.pause() Aug 31 18:55:13 volumio volumio[1429]: info: Saving Audio Output to: {"output_device":{"value":"5","label":"USB HIFI Audio"}} Aug 31 18:55:13 volumio volumio[1429]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Aug 31 18:55:13 volumio volumio[1429]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Aug 31 18:55:13 volumio volumio[1429]: info: Setting mixer PCM for card USB HIFI Audio Aug 31 18:55:13 volumio volumio[1429]: info: CoreCommandRouter::volumioUpdateVolumeSettings Aug 31 18:55:13 volumio volumio[1429]: info: Updating Volume Controller Parameters: Device: 5 Name: USB HIFI Audio Mixer: PCM Max Vol: 100 Vol Curve; logarithmic Vol Steps: 1 Aug 31 18:55:13 volumio volumio[1429]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , setExternalVolume Aug 31 18:55:13 volumio volumio[1429]: info: Disabling external Volume Control Aug 31 18:55:13 volumio volumio[1429]: info: CoreCommandRouter::getUIConfigOnPlugin Aug 31 18:55:13 volumio volumio[1429]: info: Preparing to generate the ALSA configuration file Aug 31 18:55:13 volumio volumio[1429]: info: Ignoring MPD Status Update Aug 31 18:55:13 volumio volumio[1429]: info: Ignoring MPD Status Update Aug 31 18:55:13 volumio volumio[1429]: info: Ignoring MPD Status Update Aug 31 18:55:13 volumio volumio[1429]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions Aug 31 18:55:13 volumio volumio[1429]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 31 18:55:13 volumio volumio[1429]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Aug 31 18:55:13 volumio volumio[1429]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 31 18:55:13 volumio volumio[1429]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 31 18:55:13 volumio volumio[1429]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 31 18:55:13 volumio volumio[1429]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 31 18:55:13 volumio volumio[1429]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 31 18:55:13 volumio volumio[1429]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 31 18:55:13 volumio volumio[1429]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 31 18:55:13 volumio volumio[1429]: info: CoreCommandRouter::executeOnPlugin: mpd , getPlaybackMode Aug 31 18:55:13 volumio volumio[1429]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus Aug 31 18:55:13 volumio volumio[1429]: info: VolumeController:: Volume=33 Mute =false Aug 31 18:55:13 volumio volumio[1429]: info: CoreCommandRouter::volumioGetState Aug 31 18:55:13 volumio volumio[1429]: info: CoreStateMachine::pushState Aug 31 18:55:13 volumio volumio[1429]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 31 18:55:13 volumio volumio[1429]: info: CoreCommandRouter::volumioPushState Aug 31 18:55:13 volumio volumio[1429]: info: Setting Spotify Volume from Volumio: 33 Aug 31 18:55:13 volumio volumio[1429]: info: CoreCommandRouter::servicePushState Aug 31 18:55:13 volumio volumio[1429]: info: CoreStateMachine::pushState Aug 31 18:55:13 volumio volumio[1429]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 31 18:55:13 volumio volumio[1429]: info: CoreCommandRouter::volumioPushState Aug 31 18:55:13 volumio volumio[1429]: info: CoreCommandRouter::servicePushState Aug 31 18:55:13 volumio volumio[1429]: info: CoreStateMachine::pushState Aug 31 18:55:13 volumio volumio[1429]: info: CoreCommandRouter::volumioPushState Aug 31 18:55:13 volumio volumio[1429]: info: Asound.conf file written Aug 31 18:55:13 volumio sudo[194382]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mv /home/volumio/.asoundrc /etc/asound.conf Aug 31 18:55:13 volumio sudo[194382]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 18:55:13 volumio sudo[194382]: pam_unix(sudo:session): session closed for user root Aug 31 18:55:13 volumio volumio[1429]: No state is present for card PCH Aug 31 18:55:13 volumio volumio[1429]: Found hardware: "HDA-Intel" "Realtek Generic" "HDA:10ec0269,80863024,00100100 HDA:8086281c,80860101,00100000" "0x8086" "0x3024" Aug 31 18:55:13 volumio volumio[1429]: Hardware is initialized using a generic method Aug 31 18:55:13 volumio volumio[1429]: No state is present for card PCH Aug 31 18:55:13 volumio volumio[1429]: No state is present for card Audio Aug 31 18:55:13 volumio volumio[1429]: Found hardware: "USB-Audio" "USB Mixer" "USB262a:0001" "" "" Aug 31 18:55:13 volumio volumio[1429]: Hardware is initialized using a generic method Aug 31 18:55:13 volumio volumio[1429]: No state is present for card Audio Aug 31 18:55:13 volumio volumio[1429]: info: Output device has changed, restarting MPD Aug 31 18:55:13 volumio volumio[1429]: info: Output device has changed, restarting Shairport Sync Aug 31 18:55:13 volumio volumio[1429]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 18:55:13 volumio volumio[1429]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 31 18:55:13 volumio sudo[194388]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Aug 31 18:55:13 volumio sudo[194388]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 18:55:13 volumio sudo[194388]: pam_unix(sudo:session): session closed for user root Aug 31 18:55:13 volumio sudo[194390]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Aug 31 18:55:13 volumio sudo[194390]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 18:55:13 volumio volumio[1429]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Aug 31 18:55:13 volumio volumio[1429]: info: Output device has changed, restarting MPD Aug 31 18:55:13 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Aug 31 18:55:13 volumio volumio[1429]: info: Output device has changed, restarting Shairport Sync Aug 31 18:55:13 volumio volumio[1429]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 18:55:13 volumio volumio[1429]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 31 18:55:13 volumio sudo[194398]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Aug 31 18:55:13 volumio sudo[194398]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 18:55:13 volumio sudo[194398]: pam_unix(sudo:session): session closed for user root Aug 31 18:55:13 volumio sudo[194400]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Aug 31 18:55:13 volumio sudo[194400]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 18:55:13 volumio volumio[1429]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Aug 31 18:55:13 volumio volumio[1429]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 31 18:55:13 volumio volumio[1429]: MPDError: Not connected Aug 31 18:55:13 volumio volumio[1429]: at MPDClient.send (/data/plugins/music_service/ytcr/node_modules/mpd2/lib/index.js:101:13) Aug 31 18:55:13 volumio volumio[1429]: at MPDClient.sendCommand (/data/plugins/music_service/ytcr/node_modules/mpd2/lib/index.js:65:10) Aug 31 18:55:13 volumio volumio[1429]: at Object.get (/data/plugins/music_service/ytcr/node_modules/mpd-api/lib/api/index.js:60:16) Aug 31 18:55:13 volumio volumio[1429]: at MPDPlayer.doGetDuration (/data/plugins/music_service/ytcr/dist/lib/MPDPlayer.js:220:100) Aug 31 18:55:13 volumio volumio[1429]: at MPDPlayer.getDuration (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/lib/Player.js:260:21) Aug 31 18:55:13 volumio volumio[1429]: at MPDPlayer.getState (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/lib/Player.js:303:34) Aug 31 18:55:13 volumio volumio[1429]: at process.processTicksAndRejections (node:internal/process/task_queues:95:5) Aug 31 18:55:13 volumio volumio[1429]: at async MPDPlayer._Player_setStatusAndEmit (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/lib/Player.js:333:73) Aug 31 18:55:13 volumio volumio[1429]: at async /data/plugins/music_service/ytcr/dist/index.js:312:17 { Aug 31 18:55:13 volumio volumio[1429]: code: 'ENOTCONNECTED' Aug 31 18:55:13 volumio volumio[1429]: } Aug 31 18:55:13 volumio volumio[1429]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 31 18:55:13 volumio systemd[1]: mpd.service: Deactivated successfully. Aug 31 18:55:13 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Aug 31 18:55:13 volumio systemd[1]: mpd.service: Consumed 2.692s CPU time. Aug 31 18:55:13 volumio systemd[1]: mpd.socket: Deactivated successfully. Aug 31 18:55:13 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Aug 31 18:55:13 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Aug 31 18:55:13 volumio sudo[194422]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-08-31 18:54' Aug 31 18:55:13 volumio sudo[194422]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 18:55:13 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Aug 31 18:55:13 volumio systemd[1]: Starting mpd.service - Music Player Daemon... PRETTY_NAME="Debian GNU/Linux 12 (bookworm)" NAME="Debian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm ID=debian HOME_URL="https://www.debian.org/" SUPPORT_URL="https://www.debian.org/support" BUG_REPORT_URL="https://bugs.debian.org/" VOLUMIO_BUILD_VERSION="18952480e8d8c63f22208e9007a0f47a9563eae6" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="0e58f1861fa88e02087981b8d91f7511f0e7011b" VOLUMIO_ARCH="x64" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue Mar 24 17:45:45 UTC 2026" VOLUMIO_VERSION="4.119" VOLUMIO_HARDWARE="x86_amd64" VOLUMIO_DEVICENAME="x86_64" VOLUMIO_HASH="6bf7cd61fe53483b72878254df87f1c0"