Oct 15 05:38:01 volumio volumio[233279]: info: [ytcr] Innertube support service: Start service with Deno: deno 2.9.6 (stable, release, x86_64-unknown-linux-gnu) Oct 15 05:38:02 volumio volumio[233279]: info: [yt-cast-receiver] Player.stop() Oct 15 05:38:02 volumio volumio[233279]: info: CoreCommandRouter::volumioGetState Oct 15 05:38:02 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:38:02 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:38:02 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:38:02 volumio volumio[233279]: info: [yt-cast-receiver] Player.play(): nec0bVdnH1I @ 36s Oct 15 05:38:02 volumio volumio[233279]: info: CoreCommandRouter::volumioGetState Oct 15 05:38:02 volumio volumio[233279]: info: CoreCommandRouter::volumioGetState Oct 15 05:38:02 volumio volumio[233279]: info: [yt-cast-receiver] Player.stop() Oct 15 05:38:02 volumio volumio[233279]: info: CoreCommandRouter::volumioGetState Oct 15 05:38:02 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:38:02 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:38:02 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:38:02 volumio volumio[233279]: info: [yt-cast-receiver] Player.play(): nec0bVdnH1I @ 0s Oct 15 05:38:02 volumio volumio[233279]: info: CoreCommandRouter::volumioGetState Oct 15 05:38:02 volumio volumio[233279]: info: CoreCommandRouter::volumioGetState Oct 15 05:38:06 volumio volumio[233279]: info: [ytcr] Innertube support service: result: {"status":"started","server":{"address":"127.0.0.1","port":34509}} Oct 15 05:38:06 volumio volumio[233279]: info: [ytcr] Innertube support service running at http://127.0.0.1:34509 Oct 15 05:38:08 volumio volumio[233279]: error: [ytcr] Innertube support service: libEGL warning: failed to open /dev/dri/renderD128: Permission denied Oct 15 05:38:08 volumio volumio[233279]: info: [ytcr] Obtained session PO token using visitorData (expires in 43199 seconds) Oct 15 05:38:08 volumio volumio[233279]: info: [ytcr] Going to refresh session PO token in 43099 seconds Oct 15 05:38:08 volumio volumio[233279]: info: [ytcr] Obtained PO token for video #fjPTB4fvg_M: Ml1cQgI778_VUFwEdY6pFZjEI8N3rGwnfvD489yF5F7Gaa1NXgE-0WjTJVcLXgqUI9Nd7YFhE4Um2r26cLP5_HJNUC4ytcl5wNMxtmc4s_g_KRd7wUOTsWCvYWw48Lg= Oct 15 05:38:08 volumio volumio[233279]: info: CoreCommandRouter::volumioGetState Oct 15 05:38:08 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:38:08 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:38:08 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:38:08 volumio volumio[233279]: info: [ytcr] Obtained PO token for video #nec0bVdnH1I: Ml2Vpzq9cn46kpXhTQg0pHcG6iZPKvGWkTIxFuQDee8pq2SoZoejYIcR7LIz2JclzBGUCLnnjjTJGHRfSDVkTZ2PmcsKM1TILxH4U1--LknQ65A0qXQMoQYzNzdX-8Q= Oct 15 05:38:08 volumio volumio[233279]: info: CoreCommandRouter::volumioGetState Oct 15 05:38:08 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:38:08 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:38:08 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:38:08 volumio volumio[233279]: info: [ytcr] Obtained PO token for video #nec0bVdnH1I: Ml0Yvb9ZoxKboBj7yOzlyNY0ZzzKziD6MAC8DGHnqIOImemy42NyDCYjYai2PEZJbSMZEjwDX1hoKvlFzdG1ITy9FNGP14WkjiN1Sdpa_yVx2Vc6JDC0bDpRkRLW0Mo= Oct 15 05:38:09 volumio volumio[233279]: info: [ytcr] (nec0bVdnH1I) fetching player data using YTMUSIC client... Oct 15 05:38:09 volumio volumio[233279]: info: [ytcr] (Loving Arms) validating stream URL "https://rr2---sn-o5fg5n-hju6.googlevideo.com/videoplayback?expire=1792049890&ei=gi7QaoTTIZ-GvdIPwaWEyQI&ip=5.21.56.236&id=o-AN4d1vlO62ikwLzqk_2Us7dRV6BP2tFWGp23_uLodGNz&itag=774&source=youtube&requiressl=yes&xpc=EgVo2aDSNQ%3D%3D&cps=351&met=1792028290%2C&mh=7k&mm=18%2C29&mn=sn-o5fg5n-hju6%2Csn-ajhju5-5o&ms=aub%2Crdu&mv=m&mvi=2&pl=25&rms=aub%2Caub&ctier=A&pfa=5&gcr=om&initcwndbps=1172375&hightc=yes&siu=1&bui=AWzQHwp0OrQx8LVLDxoFKze2lQ1lEJN9Rf-As_U_vf55Yw0xOqxVPMXF_Eu4655rKP4Hpoup9Q&spc=mpRQ_y7y6uxzfky_X7nmSxgu4W40O0NF-4GArphqi-Z_VURsFxhJ&vprv=1&svpuc=1&mime=audio%2Fwebm&ns=6enoyzY4MFm0uYyNjIKXav4Z&rqh=1&gir=yes&clen=7176875&dur=220.841&lmt=1759791999372850&mt=1792027787&fvip=4&keepalive=yes&fexp=51565116%2C52184231%2C52190884&c=WEB_REMIX&sefc=1&txp=1432534&n=FvmIfwImdR7FKw&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=APaTxxMwRgIhALaPanBD4-C_yY2kiEE3y4CaRGGch_sPosaVMCND-nmmAiEAqbRfAwksNzPs7IqwSKL5RI4lcltSjFLDScUAE9EdQI8%3D&sig=AE0s2JYwRAIgDvTIQSVcqdfG89jMVybaDAWfL-rBV_EyvmXbd-79I1QCIFzv7wGFKv4XdOTpgS1OBhCfvhMD76cFJg0yPWLUSKzH&cver=1.20250219.01.00&pot=Ml0Yvb9ZoxKboBj7yOzlyNY0ZzzKziD6MAC8DGHnqIOImemy42NyDCYjYai2PEZJbSMZEjwDX1hoKvlFzdG1ITy9FNGP14WkjiN1Sdpa_yVx2Vc6JDC0bDpRkRLW0Mo%3D"... Oct 15 05:38:09 volumio volumio[233279]: info: [ytcr] (Loving Arms) stream validated in 0.039s. Oct 15 05:38:09 volumio volumio[233279]: info: Ignoring MPD Status Update Oct 15 05:38:09 volumio volumio[233279]: info: Ignoring MPD Status Update Oct 15 05:38:09 volumio volumio[233279]: info: Ignoring MPD Status Update Oct 15 05:38:09 volumio volumio[233279]: info: Ignoring MPD Status Update Oct 15 05:38:09 volumio volumio[233279]: info: Ignoring MPD Status Update Oct 15 05:38:09 volumio volumio[233279]: info: Ignoring MPD Status Update Oct 15 05:38:09 volumio volumio[233279]: info: Ignoring MPD Status Update Oct 15 05:38:09 volumio volumio[233279]: info: Ignoring MPD Status Update Oct 15 05:38:09 volumio volumio[233279]: info: Ignoring MPD Status Update Oct 15 05:38:09 volumio volumio[233279]: info: Ignoring MPD Status Update Oct 15 05:38:09 volumio volumio[233279]: info: Ignoring MPD Status Update Oct 15 05:38:09 volumio volumio[233279]: info: Ignoring MPD Status Update Oct 15 05:38:09 volumio volumio[233279]: info: Ignoring MPD Status Update Oct 15 05:38:09 volumio volumio[233279]: info: Ignoring MPD Status Update Oct 15 05:38:09 volumio volumio[233279]: info: Ignoring MPD Status Update Oct 15 05:38:09 volumio volumio[233279]: info: Ignoring MPD Status Update Oct 15 05:38:09 volumio volumio[233279]: info: Ignoring MPD Status Update Oct 15 05:38:09 volumio volumio[233279]: info: Ignoring MPD Status Update Oct 15 05:38:09 volumio volumio[233279]: info: Ignoring MPD Status Update Oct 15 05:38:09 volumio volumio[233279]: info: Ignoring MPD Status Update Oct 15 05:38:09 volumio volumio[233279]: info: Ignoring MPD Status Update Oct 15 05:38:09 volumio volumio[233279]: info: Ignoring MPD Status Update Oct 15 05:38:09 volumio volumio[233279]: info: Ignoring MPD Status Update Oct 15 05:38:09 volumio volumio[233279]: info: Ignoring MPD Status Update Oct 15 05:38:09 volumio volumio[233279]: info: Ignoring MPD Status Update Oct 15 05:38:09 volumio volumio[233279]: info: Ignoring MPD Status Update Oct 15 05:38:09 volumio volumio[233279]: info: Ignoring MPD Status Update Oct 15 05:38:10 volumio volumio[233279]: info: Ignoring MPD Status Update Oct 15 05:38:10 volumio volumio[233279]: info: Ignoring MPD Status Update Oct 15 05:38:10 volumio volumio[233279]: info: Ignoring MPD Status Update Oct 15 05:38:10 volumio volumio[233279]: info: Ignoring MPD Status Update Oct 15 05:38:10 volumio volumio[233279]: info: Ignoring MPD Status Update Oct 15 05:38:10 volumio volumio[233279]: info: Ignoring MPD Status Update Oct 15 05:38:10 volumio volumio[233279]: info: CoreCommandRouter::volumioGetState Oct 15 05:38:10 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:38:10 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:38:10 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 15 05:38:10 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:38:14 volumio volumio[233279]: info: [yt-cast-receiver] Player.setVolume(): Oct 15 05:38:14 volumio volumio[233279]: { level: 89, muted: false } Oct 15 05:38:14 volumio volumio[233279]: info: CoreCommandRouter::volumioGetState Oct 15 05:38:14 volumio volumio[233279]: info: VolumeController::SetAlsaVolume89 Oct 15 05:38:14 volumio volumio[233279]: info: CoreCommandRouter::volumioGetState Oct 15 05:38:14 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:38:14 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 15 05:38:14 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:38:14 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:38:14 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:38:14 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 15 05:38:14 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:38:14 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:38:14 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:38:14 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:38:14 volumio volumio[233279]: info: CoreCommandRouter::volumioGetState Oct 15 05:38:14 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:38:14 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:38:14 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:38:14 volumio volumio[233279]: info: CoreCommandRouter::volumioGetState Oct 15 05:38:14 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:38:14 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:38:14 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 15 05:38:14 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:38:15 volumio volumio[233279]: info: [yt-cast-receiver] Player.setVolume(): Oct 15 05:38:15 volumio volumio[233279]: { level: 86, muted: false } Oct 15 05:38:15 volumio volumio[233279]: info: CoreCommandRouter::volumioGetState Oct 15 05:38:15 volumio volumio[233279]: info: VolumeController::SetAlsaVolume86 Oct 15 05:38:15 volumio volumio[233279]: info: CoreCommandRouter::volumioGetState Oct 15 05:38:15 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:38:15 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 15 05:38:15 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:38:15 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:38:15 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:38:15 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 15 05:38:15 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:38:15 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:38:15 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:38:15 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 15 05:38:15 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:38:15 volumio volumio[233279]: info: CoreCommandRouter::volumioGetState Oct 15 05:38:15 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:38:15 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:38:15 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:38:15 volumio volumio[233279]: info: CoreCommandRouter::volumioGetState Oct 15 05:38:15 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:38:15 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:38:15 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:38:15 volumio volumio[233279]: info: [yt-cast-receiver] Player.setVolume(): Oct 15 05:38:15 volumio volumio[233279]: { level: 83, muted: false } Oct 15 05:38:15 volumio volumio[233279]: info: CoreCommandRouter::volumioGetState Oct 15 05:38:15 volumio volumio[233279]: info: VolumeController::SetAlsaVolume83 Oct 15 05:38:15 volumio volumio[233279]: info: CoreCommandRouter::volumioGetState Oct 15 05:38:15 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:38:15 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 15 05:38:15 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:38:15 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:38:15 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:38:15 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 15 05:38:15 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:38:15 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:38:15 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:38:15 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:38:15 volumio volumio[233279]: info: CoreCommandRouter::volumioGetState Oct 15 05:38:15 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:38:15 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:38:15 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:38:16 volumio volumio[233279]: info: CoreCommandRouter::volumioGetState Oct 15 05:38:16 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:38:16 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:38:16 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:38:16 volumio volumio[233279]: info: [yt-cast-receiver] Player.setVolume(): Oct 15 05:38:16 volumio volumio[233279]: { level: 80, muted: false } Oct 15 05:38:16 volumio volumio[233279]: info: CoreCommandRouter::volumioGetState Oct 15 05:38:16 volumio volumio[233279]: info: VolumeController::SetAlsaVolume80 Oct 15 05:38:16 volumio volumio[233279]: info: CoreCommandRouter::volumioGetState Oct 15 05:38:16 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:38:16 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 15 05:38:16 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:38:16 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:38:16 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:38:16 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 15 05:38:16 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:38:16 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:38:16 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:38:16 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:38:16 volumio volumio[233279]: info: CoreCommandRouter::volumioGetState Oct 15 05:38:16 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:38:16 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:38:16 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:38:16 volumio volumio[233279]: info: CoreCommandRouter::volumioGetState Oct 15 05:38:16 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:38:16 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:38:16 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 15 05:38:16 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:38:17 volumio volumio[233279]: info: [yt-cast-receiver] Player.setVolume(): Oct 15 05:38:17 volumio volumio[233279]: { level: 77, muted: false } Oct 15 05:38:17 volumio volumio[233279]: info: CoreCommandRouter::volumioGetState Oct 15 05:38:17 volumio volumio[233279]: info: VolumeController::SetAlsaVolume77 Oct 15 05:38:17 volumio volumio[233279]: info: CoreCommandRouter::volumioGetState Oct 15 05:38:17 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:38:17 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 15 05:38:17 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:38:17 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:38:17 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:38:17 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 15 05:38:17 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:38:17 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:38:17 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:38:17 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:38:17 volumio volumio[233279]: info: CoreCommandRouter::volumioGetState Oct 15 05:38:17 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:38:17 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:38:17 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:38:17 volumio volumio[233279]: info: CoreCommandRouter::volumioGetState Oct 15 05:38:17 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:38:17 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:38:17 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:38:18 volumio volumio[233279]: info: [yt-cast-receiver] Player.setVolume(): Oct 15 05:38:18 volumio volumio[233279]: { level: 80, muted: false } Oct 15 05:38:18 volumio volumio[233279]: info: CoreCommandRouter::volumioGetState Oct 15 05:38:18 volumio volumio[233279]: info: VolumeController::SetAlsaVolume80 Oct 15 05:38:18 volumio volumio[233279]: info: CoreCommandRouter::volumioGetState Oct 15 05:38:18 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:38:18 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 15 05:38:18 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:38:18 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:38:18 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:38:18 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 15 05:38:18 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:38:18 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:38:18 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:38:18 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:38:18 volumio volumio[233279]: info: CoreCommandRouter::volumioGetState Oct 15 05:38:18 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:38:18 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:38:18 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 15 05:38:18 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:38:18 volumio volumio[233279]: info: CoreCommandRouter::volumioGetState Oct 15 05:38:18 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:38:18 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:38:18 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:38:18 volumio volumio[233279]: info: [yt-cast-receiver] Player.setVolume(): Oct 15 05:38:18 volumio volumio[233279]: { level: 74, muted: false } Oct 15 05:38:18 volumio volumio[233279]: info: CoreCommandRouter::volumioGetState Oct 15 05:38:18 volumio volumio[233279]: info: VolumeController::SetAlsaVolume74 Oct 15 05:38:18 volumio volumio[233279]: info: CoreCommandRouter::volumioGetState Oct 15 05:38:18 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:38:18 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 15 05:38:18 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:38:18 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:38:18 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:38:18 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 15 05:38:18 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:38:18 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:38:18 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:38:18 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:38:18 volumio volumio[233279]: info: CoreCommandRouter::volumioGetState Oct 15 05:38:18 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:38:18 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:38:18 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:38:18 volumio volumio[233279]: info: CoreCommandRouter::volumioGetState Oct 15 05:38:18 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:38:18 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:38:18 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:38:34 volumio volumio5-onboarding[1682]: time=2026-10-15T01:38:34.414Z level=INFO msg="established new WebSocket connection" component=conn/ws remoteAddr=192.168.100.226:53722 Oct 15 05:38:34 volumio volumio5-onboarding[1682]: time=2026-10-15T01:38:34.749Z level=INFO msg="app ready event" component=server event=CLIENT_EVENT_TYPE_APP_READY peer="192.168.100.226:53722 @ 0xc0002e86c0" latency=-3.846566188s platform=PLATFORM_ANDROID version=6.260930.0 Oct 15 05:38:34 volumio volumio5-onboarding[1682]: time=2026-10-15T01:38:34.749Z level=INFO msg="device data request" component=server type=REQUEST_TYPE_DEVICE_DATA peer="192.168.100.226:53722 @ 0xc0002e86c0" latency=-3.847233863s timeout=20s Oct 15 05:38:34 volumio volumio5-onboarding[1682]: time=2026-10-15T01:38:34.749Z level=INFO msg="emitting device capabilities changed event" component=server peer="192.168.100.226:53722 @ 0xc0002e86c0" Oct 15 05:38:34 volumio volumio[233279]: info: Received Get System Info Oct 15 05:38:34 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 15 05:38:34 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 15 05:38:34 volumio volumio[233279]: info: Discovery: Getting this device information Oct 15 05:38:34 volumio volumio[233279]: info: CoreCommandRouter::volumioGetState Oct 15 05:38:34 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 15 05:38:34 volumio volumio5-onboarding[1682]: time=2026-10-15T01:38:34.755Z level=INFO msg="emitting device name changed event" component=server peer="192.168.100.226:53722 @ 0xc0002e86c0" name=Volumio Oct 15 05:38:34 volumio volumio5-onboarding[1682]: time=2026-10-15T01:38:34.756Z level=INFO msg="emitting device language changed event" component=server peer="192.168.100.226:53722 @ 0xc0002e86c0" language=en Oct 15 05:38:34 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: system , getCurrentTimezone Oct 15 05:38:34 volumio volumio5-onboarding[1682]: time=2026-10-15T01:38:34.760Z level=INFO msg="emitting device timezone changed event" component=server peer="192.168.100.226:53722 @ 0xc0002e86c0" timezone=Asia/Muscat Oct 15 05:38:34 volumio volumio5-onboarding[1682]: time=2026-10-15T01:38:34.760Z level=INFO msg="emitting ethernet info changed event" component=server peer="192.168.100.226:53722 @ 0xc0002e86c0" available=false connected=false macAddress= ip4Address= ip6Address= Oct 15 05:38:34 volumio volumio5-onboarding[1682]: time=2026-10-15T01:38:34.764Z level=INFO msg="emitting wifi info changed event" component=server peer="192.168.100.226:53722 @ 0xc0002e86c0" available=true connected=true macAddress=10:02:b5:29:0b:0d ip4Address=192.168.100.190/24 ip6Address= ssid=Riju Oct 15 05:38:34 volumio volumio5-onboarding[1682]: time=2026-10-15T01:38:34.764Z level=INFO msg="emitting device setup status changed event" component=server peer="192.168.100.226:53722 @ 0xc0002e86c0" setupComplete=true Oct 15 05:38:34 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getExtendedOutputDevices Oct 15 05:38:34 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions Oct 15 05:38:34 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 15 05:38:34 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Oct 15 05:38:34 volumio volumio[233279]: error: Cannot read Audio Device Capabilities Command failed: /usr/local/bin/alsacap -C 0 -D 0 Oct 15 05:38:34 volumio volumio[233279]: /bin/sh: 1: /usr/local/bin/alsacap: not found Oct 15 05:38:34 volumio volumio[233279]: {"cmd":"/usr/local/bin/alsacap -C 0 -D 0","code":127,"killed":false,"signal":null,"stack":"Error: Command failed: /usr/local/bin/alsacap -C 0 -D 0\n/bin/sh: 1: /usr/local/bin/alsacap: not found\n\n at ChildProcess.exithandler (node:child_process:421:12)\n at ChildProcess.emit (node:events:514:28)\n at maybeClose (node:internal/child_process:1105:16)\n at Socket. (node:internal/child_process:457:11)\n at Socket.emit (node:events:514:28)\n at Pipe. (node:net:337:12)"} Oct 15 05:38:34 volumio volumio[233279]: error: Cannot read Audio Device Capabilities Command failed: /usr/local/bin/alsacap -C 5 Oct 15 05:38:34 volumio volumio[233279]: /bin/sh: 1: /usr/local/bin/alsacap: not found Oct 15 05:38:34 volumio volumio[233279]: {"cmd":"/usr/local/bin/alsacap -C 5","code":127,"killed":false,"signal":null,"stack":"Error: Command failed: /usr/local/bin/alsacap -C 5\n/bin/sh: 1: /usr/local/bin/alsacap: not found\n\n at ChildProcess.exithandler (node:child_process:421:12)\n at ChildProcess.emit (node:events:514:28)\n at maybeClose (node:internal/child_process:1105:16)\n at Socket. (node:internal/child_process:457:11)\n at Socket.emit (node:events:514:28)\n at Pipe. (node:net:337:12)"} Oct 15 05:38:34 volumio volumio[233279]: amixer -c 5 info | grep "2Qute" Oct 15 05:38:34 volumio volumio[233279]: Card sysdefault:5 'D2Qute'/'Chord Electronics Ltd 2Qute at usb-0000:00:14.0-1.1, high speed' Oct 15 05:38:34 volumio volumio[233279]: error: Cannot read Audio Device Capabilities Command failed: /usr/local/bin/alsacap -C 5 Oct 15 05:38:34 volumio volumio[233279]: /bin/sh: 1: /usr/local/bin/alsacap: not found Oct 15 05:38:34 volumio volumio[233279]: {"cmd":"/usr/local/bin/alsacap -C 5","code":127,"killed":false,"signal":null,"stack":"Error: Command failed: /usr/local/bin/alsacap -C 5\n/bin/sh: 1: /usr/local/bin/alsacap: not found\n\n at ChildProcess.exithandler (node:child_process:421:12)\n at ChildProcess.emit (node:events:514:28)\n at maybeClose (node:internal/child_process:1105:16)\n at Socket. (node:internal/child_process:457:11)\n at Socket.emit (node:events:514:28)\n at Pipe. (node:net:337:12)"} Oct 15 05:38:34 volumio volumio[233279]: amixer -c 5 info | grep "2Qute" Oct 15 05:38:34 volumio volumio[233279]: Card sysdefault:5 'D2Qute'/'Chord Electronics Ltd 2Qute at usb-0000:00:14.0-1.1, high speed' Oct 15 05:38:34 volumio volumio5-onboarding[1682]: time=2026-10-15T01:38:34.924Z level=INFO msg="emitting audio outputs changed event" component=server peer="192.168.100.226:53722 @ 0xc0002e86c0" selectedOutputId=5 Oct 15 05:38:34 volumio volumio[233279]: info: Received Get System Info Oct 15 05:38:34 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 15 05:38:34 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 15 05:38:34 volumio volumio[233279]: info: Discovery: Getting this device information Oct 15 05:38:34 volumio volumio[233279]: info: CoreCommandRouter::volumioGetState Oct 15 05:38:34 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 15 05:38:34 volumio volumio5-onboarding[1682]: time=2026-10-15T01:38:34.943Z level=INFO msg="emitting software info changed event" component=server peer="192.168.100.226:53722 @ 0xc0002e86c0" currentVersion=4.119 latestVersion=4.119 Oct 15 05:38:34 volumio volumio5-onboarding[1682]: time=2026-10-15T01:38:34.944Z level=INFO msg="emitting software update progress event" component=server peer="192.168.100.226:53722 @ 0xc0002e86c0" status=UPDATE_STATUS_NONE progress=0 Oct 15 05:38:34 volumio volumio5-onboarding[1682]: time=2026-10-15T01:38:34.944Z level=INFO msg="emitting user changed event" component=server peer="192.168.100.226:53722 @ 0xc0002e86c0" userId= Oct 15 05:38:34 volumio volumio5-onboarding[1682]: time=2026-10-15T01:38:34.944Z level=INFO msg="emitting music providers changed event" component=server peer="192.168.100.226:53722 @ 0xc0002e86c0" providers=3 Oct 15 05:38:34 volumio volumio5-onboarding[1682]: time=2026-10-15T01:38:34.944Z level=INFO msg="emitting plugins changed event" component=server peer="192.168.100.226:53722 @ 0xc0002e86c0" plugins=57 Oct 15 05:38:34 volumio volumio[233279]: info: CoreCommandRouter::volumioGetState Oct 15 05:38:34 volumio volumio5-onboarding[1682]: time=2026-10-15T01:38:34.950Z level=INFO msg="emitting player state changed event" component=server peer="192.168.100.226:53722 @ 0xc0002e86c0" state=STATUS_PLAYING positionMs=9365 volume=74 Oct 15 05:38:34 volumio volumio5-onboarding[1682]: time=2026-10-15T01:38:34.951Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.226:53722 @ 0xc0002e86c0" id= title="Loving Arms" Oct 15 05:38:36 volumio volumio5-onboarding[1682]: time=2026-10-15T01:38:36.618Z level=INFO msg="navigate to next page" component=server type=REQUEST_TYPE_CONTINUE_NAVIGATION peer="192.168.100.226:53722 @ 0xc0002e86c0" latency=-3.850114775s timeout=10s from=APP_PAGE_ROOT to=APP_PAGE_LEGACY_DEVICE Oct 15 05:38:36 volumio volumio5-onboarding[1682]: time=2026-10-15T01:38:36.635Z level=INFO msg="check connectivity" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.100.226:53722 @ 0xc0002e86c0" latency=-3.854028763s timeout=10s Oct 15 05:38:36 volumio bluealsa[1074]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_5D_9E_7F_70_36_2F, ...) Oct 15 05:38:36 volumio rfkill[255474]: unblock set for type bluetooth Oct 15 05:38:36 volumio volumio5-onboarding[1682]: time=2026-10-15T01:38:36.963Z level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.100.226:53722 @ 0xc0002e86c0" latency=-3.854028763s timeout=10s endpoint=https://www.googleapis.com duration=324.9377ms Oct 15 05:38:36 volumio volumio5-onboarding[1682]: time=2026-10-15T01:38:36.981Z level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.100.226:53722 @ 0xc0002e86c0" latency=-3.854028763s timeout=10s endpoint=https://radio-directory.firebaseapp.com duration=346.116313ms Oct 15 05:38:37 volumio volumio5-onboarding[1682]: time=2026-10-15T01:38:37.179Z level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.100.226:53722 @ 0xc0002e86c0" latency=-3.854028763s timeout=10s endpoint=http://pushupdates.volumio.org duration=540.406188ms Oct 15 05:38:37 volumio volumio5-onboarding[1682]: time=2026-10-15T01:38:37.212Z level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.100.226:53722 @ 0xc0002e86c0" latency=-3.854028763s timeout=10s endpoint=https://securetoken.googleapis.com duration=573.684813ms Oct 15 05:38:37 volumio volumio5-onboarding[1682]: time=2026-10-15T01:38:37.285Z level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.100.226:53722 @ 0xc0002e86c0" latency=-3.854028763s timeout=10s endpoint=https://google.com duration=647.862487ms Oct 15 05:38:37 volumio volumio5-onboarding[1682]: time=2026-10-15T01:38:37.454Z level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.100.226:53722 @ 0xc0002e86c0" latency=-3.854028763s timeout=10s endpoint=https://myvolumio.firebaseio.com duration=810.801313ms Oct 15 05:38:37 volumio volumio5-onboarding[1682]: time=2026-10-15T01:38:37.531Z level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.100.226:53722 @ 0xc0002e86c0" latency=-3.854028763s timeout=10s endpoint=https://browsing-performer.dfs.volumio.org duration=894.635763ms Oct 15 05:38:37 volumio volumio5-onboarding[1682]: time=2026-10-15T01:38:37.645Z level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.100.226:53722 @ 0xc0002e86c0" latency=-3.854028763s timeout=10s endpoint=https://oauth-performer.dfs.volumio.org duration=1.009444225s Oct 15 05:38:37 volumio volumio5-onboarding[1682]: time=2026-10-15T01:38:37.755Z level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.100.226:53722 @ 0xc0002e86c0" latency=-3.854028763s timeout=10s endpoint=https://database.volumio.cloud duration=1.110884625s Oct 15 05:38:37 volumio volumio5-onboarding[1682]: time=2026-10-15T01:38:37.815Z level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.100.226:53722 @ 0xc0002e86c0" latency=-3.854028763s timeout=10s endpoint=http://plugins.volumio.org duration=1.174308025s Oct 15 05:38:37 volumio sudo[255479]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 15 05:38:37 volumio sudo[255479]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 15 05:38:37 volumio sudo[255483]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 15 05:38:37 volumio sudo[255479]: pam_unix(sudo:session): session closed for user root Oct 15 05:38:37 volumio sudo[255483]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 15 05:38:37 volumio sudo[255483]: pam_unix(sudo:session): session closed for user root Oct 15 05:38:37 volumio volumio[233279]: verbose: New Socket.io Connection to 192.168.100.190 from 192.168.100.226 UA: Mozilla/5.0 (Linux; Android 17; Pixel 8a Build/CP3A.261005.005; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/154.0.8037.106 Mobile Safari/537.36 VolumioApp/6.260930.0 Engine version: 3 Transport: polling Total Clients: 6 Oct 15 05:38:38 volumio sudo[255489]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 15 05:38:38 volumio sudo[255489]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 15 05:38:38 volumio volumio5-onboarding[1682]: time=2026-10-15T01:38:38.204Z level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.100.226:53722 @ 0xc0002e86c0" latency=-3.854028763s timeout=10s endpoint=https://functions.volumio.cloud duration=1.566545238s Oct 15 05:38:38 volumio volumio5-onboarding[1682]: time=2026-10-15T01:38:38.204Z level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.100.226:53722 @ 0xc0002e86c0" latency=-3.854028763s timeout=10s endpoint=https://functions.volumio.cloud duration=1.556137912s Oct 15 05:38:38 volumio sudo[255489]: pam_unix(sudo:session): session closed for user root Oct 15 05:38:38 volumio sudo[255491]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 15 05:38:38 volumio sudo[255491]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 15 05:38:38 volumio sudo[255491]: pam_unix(sudo:session): session closed for user root Oct 15 05:38:38 volumio volumio5-onboarding[1682]: time=2026-10-15T01:38:38.289Z level=ERROR msg="endpoint is not reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.100.226:53722 @ 0xc0002e86c0" latency=-3.854028763s timeout=10s endpoint=http://cddb.volumio.org duration=1.652239262s error="Head \"http://gnudb.gnudb.org/~cddb/cddb.cgi/\": EOF" Oct 15 05:38:38 volumio volumio[233279]: verbose: New Socket.io Connection to 192.168.100.190 from 192.168.100.226 UA: Mozilla/5.0 (Linux; Android 17; Pixel 8a Build/CP3A.261005.005; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/154.0.8037.106 Mobile Safari/537.36 VolumioApp/6.260930.0 Engine version: 3 Transport: polling Total Clients: 7 Oct 15 05:38:38 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Oct 15 05:38:38 volumio volumio[233279]: info: CoreCommandRouter::volumioGetVisibleSources Oct 15 05:38:38 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 15 05:38:38 volumio volumio[233279]: info: CoreCommandRouter::volumioGetState Oct 15 05:38:38 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Oct 15 05:38:38 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Oct 15 05:38:38 volumio volumio[233279]: info: Received Get System Info Oct 15 05:38:38 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 15 05:38:38 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 15 05:38:38 volumio volumio[233279]: info: Discovery: Getting this device information Oct 15 05:38:38 volumio volumio[233279]: info: CoreCommandRouter::volumioGetState Oct 15 05:38:38 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 15 05:38:38 volumio volumio[233279]: info: CoreCommandRouter::volumioGetState Oct 15 05:38:38 volumio volumio[233279]: info: Listing playlists Oct 15 05:38:38 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Oct 15 05:38:38 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Oct 15 05:38:38 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Oct 15 05:38:39 volumio volumio5-onboarding[1682]: time=2026-10-15T01:38:39.153Z level=INFO msg="new address was allocated" component=ble/conn old=5 new=6 Oct 15 05:38:39 volumio dbus-daemon[703]: [system] Rejected send message, 0 matched rules; type="error", sender=":1.16" (uid=0 pid=1682 comm="/usr/bin/volumio5-onboarding") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.6" (uid=0 pid=1041 comm="/usr/libexec/bluetooth/bluetoothd --noplugin=sap,b") Oct 15 05:38:40 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Oct 15 05:38:40 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Oct 15 05:38:40 volumio volumio[233279]: info: Received Get System Info Oct 15 05:38:40 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 15 05:38:40 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 15 05:38:40 volumio volumio[233279]: info: Discovery: Getting this device information Oct 15 05:38:40 volumio volumio[233279]: info: CoreCommandRouter::volumioGetState Oct 15 05:38:40 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 15 05:38:40 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Oct 15 05:38:42 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Oct 15 05:38:42 volumio volumio[233279]: info: Received Get System Info Oct 15 05:38:42 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 15 05:38:42 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 15 05:38:42 volumio volumio[233279]: info: Discovery: Getting this device information Oct 15 05:38:42 volumio volumio[233279]: info: CoreCommandRouter::volumioGetState Oct 15 05:38:42 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 15 05:38:44 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Oct 15 05:38:44 volumio volumio[233279]: info: Received Get System Info Oct 15 05:38:44 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 15 05:38:44 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 15 05:38:44 volumio volumio[233279]: info: Discovery: Getting this device information Oct 15 05:38:44 volumio volumio[233279]: info: CoreCommandRouter::volumioGetState Oct 15 05:38:44 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 15 05:38:44 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Oct 15 05:38:44 volumio volumio[233279]: info: Received Get System Info Oct 15 05:38:44 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 15 05:38:44 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 15 05:38:44 volumio volumio[233279]: info: Discovery: Getting this device information Oct 15 05:38:44 volumio volumio[233279]: info: CoreCommandRouter::volumioGetState Oct 15 05:38:44 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 15 05:38:47 volumio volumio[233279]: info: CoreCommandRouter::getUIConfigOnPlugin Oct 15 05:38:47 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions Oct 15 05:38:47 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 15 05:38:47 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Oct 15 05:38:47 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 15 05:38:47 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 15 05:38:47 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 15 05:38:47 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 15 05:38:47 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 15 05:38:47 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 15 05:38:47 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 15 05:38:47 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: mpd , getPlaybackMode Oct 15 05:38:47 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus Oct 15 05:38:48 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Oct 15 05:38:56 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 15 05:38:56 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 15 05:38:56 volumio volumio[233279]: info: Discovery: Getting this device information Oct 15 05:38:56 volumio volumio[233279]: info: CoreCommandRouter::volumioGetState Oct 15 05:38:56 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 15 05:38:56 volumio volumio[233279]: verbose: New Socket.io Connection to 192.168.100.190:3000 from 192.168.100.226 UA: Dart/3.12 (dart:io) Engine version: 3 Transport: websocket Total Clients: 8 Oct 15 05:38:56 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Oct 15 05:38:56 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Oct 15 05:38:56 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Oct 15 05:38:56 volumio volumio[233279]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Oct 15 05:38:56 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Oct 15 05:38:56 volumio volumio[233279]: info: Received Get System Version Oct 15 05:38:56 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 15 05:38:56 volumio volumio[233279]: info: Received Get System Info Oct 15 05:38:56 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 15 05:38:56 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 15 05:38:56 volumio volumio[233279]: info: Discovery: Getting this device information Oct 15 05:38:56 volumio volumio[233279]: info: CoreCommandRouter::volumioGetState Oct 15 05:38:56 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 15 05:39:09 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:09.391Z level=INFO msg="set volume" component=server type=REQUEST_TYPE_SET_VOLUME peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" latency=-3.848283213s timeout=3s volume=73 Oct 15 05:39:09 volumio volumio[233279]: info: VolumeController::SetAlsaVolume73 Oct 15 05:39:09 volumio volumio[233279]: info: CoreCommandRouter::volumioGetState Oct 15 05:39:09 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:39:09 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 15 05:39:09 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:39:09 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:09.414Z level=INFO msg="emitting player state changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" state=STATUS_PLAYING positionMs=9365 volume=73 Oct 15 05:39:09 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:09.414Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" id= title="Loving Arms" Oct 15 05:39:09 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:39:09 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:39:09 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 15 05:39:09 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:39:09 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:09.439Z level=INFO msg="emitting player state changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" state=STATUS_PLAYING positionMs=59990 volume=73 Oct 15 05:39:09 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:09.439Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" id= title="Loving Arms" Oct 15 05:39:09 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:39:09 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:39:09 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:39:09 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:09.456Z level=INFO msg="emitting player state changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" state=STATUS_PLAYING positionMs=59990 volume=73 Oct 15 05:39:09 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:09.456Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" id= title="Loving Arms" Oct 15 05:39:09 volumio volumio[233279]: info: CoreCommandRouter::volumioGetState Oct 15 05:39:09 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:39:09 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:39:09 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:39:09 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:09.487Z level=INFO msg="emitting player state changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" state=STATUS_PLAYING positionMs=59990 volume=73 Oct 15 05:39:09 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:09.487Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" id= title="Loving Arms" Oct 15 05:39:10 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:10.229Z level=INFO msg="set volume" component=server type=REQUEST_TYPE_SET_VOLUME peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" latency=-3.850527838s timeout=3s volume=72 Oct 15 05:39:10 volumio volumio[233279]: info: VolumeController::SetAlsaVolume72 Oct 15 05:39:10 volumio volumio[233279]: info: CoreCommandRouter::volumioGetState Oct 15 05:39:10 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:39:10 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 15 05:39:10 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:39:10 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:10.269Z level=INFO msg="emitting player state changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" state=STATUS_PLAYING positionMs=59990 volume=72 Oct 15 05:39:10 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:10.269Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" id= title="Loving Arms" Oct 15 05:39:10 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:39:10 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:39:10 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 15 05:39:10 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:39:10 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:10.288Z level=INFO msg="emitting player state changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" state=STATUS_PLAYING positionMs=60744 volume=72 Oct 15 05:39:10 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:10.288Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" id= title="Loving Arms" Oct 15 05:39:10 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:39:10 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:39:10 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 15 05:39:10 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:39:10 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:10.322Z level=INFO msg="emitting player state changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" state=STATUS_PLAYING positionMs=60870 volume=72 Oct 15 05:39:10 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:10.323Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" id= title="Loving Arms" Oct 15 05:39:10 volumio volumio[233279]: info: CoreCommandRouter::volumioGetState Oct 15 05:39:10 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:39:10 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:39:10 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:39:10 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:10.369Z level=INFO msg="emitting player state changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" state=STATUS_PLAYING positionMs=60870 volume=72 Oct 15 05:39:10 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:10.370Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" id= title="Loving Arms" Oct 15 05:39:10 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:10.568Z level=INFO msg="set volume" component=server type=REQUEST_TYPE_SET_VOLUME peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" latency=-3.850912063s timeout=3s volume=71 Oct 15 05:39:10 volumio volumio[233279]: info: VolumeController::SetAlsaVolume71 Oct 15 05:39:10 volumio volumio[233279]: info: CoreCommandRouter::volumioGetState Oct 15 05:39:10 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:39:10 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 15 05:39:10 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:39:10 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:10.607Z level=INFO msg="emitting player state changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" state=STATUS_PLAYING positionMs=60870 volume=71 Oct 15 05:39:10 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:10.607Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" id= title="Loving Arms" Oct 15 05:39:10 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:39:10 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:39:10 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 15 05:39:10 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:39:10 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:10.614Z level=INFO msg="emitting player state changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" state=STATUS_PLAYING positionMs=61122 volume=71 Oct 15 05:39:10 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:10.615Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" id= title="Loving Arms" Oct 15 05:39:10 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:39:10 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:39:10 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:39:10 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:10.626Z level=INFO msg="emitting player state changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" state=STATUS_PLAYING positionMs=61122 volume=71 Oct 15 05:39:10 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:10.626Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" id= title="Loving Arms" Oct 15 05:39:10 volumio volumio[233279]: info: CoreCommandRouter::volumioGetState Oct 15 05:39:10 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:39:10 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:39:10 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 15 05:39:10 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:39:10 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:10.673Z level=INFO msg="emitting player state changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" state=STATUS_PLAYING positionMs=61236 volume=71 Oct 15 05:39:10 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:10.674Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" id= title="Loving Arms" Oct 15 05:39:10 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:10.948Z level=INFO msg="set volume" component=server type=REQUEST_TYPE_SET_VOLUME peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" latency=-3.85248475s timeout=3s volume=70 Oct 15 05:39:10 volumio volumio[233279]: info: VolumeController::SetAlsaVolume70 Oct 15 05:39:10 volumio volumio[233279]: info: CoreCommandRouter::volumioGetState Oct 15 05:39:10 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:39:10 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 15 05:39:10 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:39:10 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:10.981Z level=INFO msg="emitting player state changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" state=STATUS_PLAYING positionMs=61236 volume=70 Oct 15 05:39:10 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:10.982Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" id= title="Loving Arms" Oct 15 05:39:10 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:39:10 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:39:10 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 15 05:39:10 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:39:10 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:10.996Z level=INFO msg="emitting player state changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" state=STATUS_PLAYING positionMs=61489 volume=70 Oct 15 05:39:10 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:10.996Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" id= title="Loving Arms" Oct 15 05:39:11 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:39:11 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:39:11 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:39:11 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:11.012Z level=INFO msg="emitting player state changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" state=STATUS_PLAYING positionMs=61489 volume=70 Oct 15 05:39:11 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:11.013Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" id= title="Loving Arms" Oct 15 05:39:11 volumio volumio[233279]: info: CoreCommandRouter::volumioGetState Oct 15 05:39:11 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:39:11 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:39:11 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 15 05:39:11 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:39:11 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:11.030Z level=INFO msg="emitting player state changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" state=STATUS_PLAYING positionMs=61614 volume=70 Oct 15 05:39:11 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:11.031Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" id= title="Loving Arms" Oct 15 05:39:11 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:11.316Z level=INFO msg="set volume" component=server type=REQUEST_TYPE_SET_VOLUME peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" latency=-3.85254s timeout=3s volume=69 Oct 15 05:39:11 volumio volumio[233279]: info: VolumeController::SetAlsaVolume69 Oct 15 05:39:11 volumio volumio[233279]: info: CoreCommandRouter::volumioGetState Oct 15 05:39:11 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:39:11 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 15 05:39:11 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:39:11 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:11.340Z level=INFO msg="emitting player state changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" state=STATUS_PLAYING positionMs=61614 volume=69 Oct 15 05:39:11 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:11.341Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" id= title="Loving Arms" Oct 15 05:39:11 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:39:11 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:39:11 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 15 05:39:11 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:39:11 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:11.354Z level=INFO msg="emitting player state changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" state=STATUS_PLAYING positionMs=61866 volume=69 Oct 15 05:39:11 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:11.354Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" id= title="Loving Arms" Oct 15 05:39:11 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:39:11 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:39:11 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:39:11 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:11.370Z level=INFO msg="emitting player state changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" state=STATUS_PLAYING positionMs=61866 volume=69 Oct 15 05:39:11 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:11.373Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" id= title="Loving Arms" Oct 15 05:39:11 volumio volumio[233279]: info: CoreCommandRouter::volumioGetState Oct 15 05:39:11 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:39:11 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:39:11 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:39:11 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:11.403Z level=INFO msg="emitting player state changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" state=STATUS_PLAYING positionMs=61866 volume=69 Oct 15 05:39:11 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:11.403Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" id= title="Loving Arms" Oct 15 05:39:11 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:11.573Z level=INFO msg="set volume" component=server type=REQUEST_TYPE_SET_VOLUME peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" latency=-3.853122363s timeout=3s volume=68 Oct 15 05:39:11 volumio volumio[233279]: info: VolumeController::SetAlsaVolume68 Oct 15 05:39:11 volumio volumio[233279]: info: CoreCommandRouter::volumioGetState Oct 15 05:39:11 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:39:11 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 15 05:39:11 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:39:11 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:39:11 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:39:11 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 15 05:39:11 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:39:11 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:11.622Z level=INFO msg="emitting player state changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" state=STATUS_PLAYING positionMs=61866 volume=68 Oct 15 05:39:11 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:11.624Z level=INFO msg="emitting player state changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" state=STATUS_PLAYING positionMs=62117 volume=68 Oct 15 05:39:11 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:11.624Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" id= title="Loving Arms" Oct 15 05:39:11 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:11.625Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" id= title="Loving Arms" Oct 15 05:39:11 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:39:11 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:39:11 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:39:11 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:11.652Z level=INFO msg="emitting player state changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" state=STATUS_PLAYING positionMs=62117 volume=68 Oct 15 05:39:11 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:11.653Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" id= title="Loving Arms" Oct 15 05:39:11 volumio volumio[233279]: info: CoreCommandRouter::volumioGetState Oct 15 05:39:11 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:39:11 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:39:11 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 15 05:39:11 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:39:11 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:11.696Z level=INFO msg="emitting player state changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" state=STATUS_PLAYING positionMs=62243 volume=68 Oct 15 05:39:11 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:11.697Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" id= title="Loving Arms" Oct 15 05:39:11 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:11.867Z level=INFO msg="set volume" component=server type=REQUEST_TYPE_SET_VOLUME peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" latency=-3.8535171s timeout=3s volume=67 Oct 15 05:39:11 volumio volumio[233279]: info: VolumeController::SetAlsaVolume67 Oct 15 05:39:11 volumio volumio[233279]: info: CoreCommandRouter::volumioGetState Oct 15 05:39:11 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:39:11 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 15 05:39:11 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:39:11 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:11.898Z level=INFO msg="emitting player state changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" state=STATUS_PLAYING positionMs=62243 volume=67 Oct 15 05:39:11 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:11.899Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" id= title="Loving Arms" Oct 15 05:39:11 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:39:11 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:39:11 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 15 05:39:11 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:39:11 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:11.921Z level=INFO msg="emitting player state changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" state=STATUS_PLAYING positionMs=62495 volume=67 Oct 15 05:39:11 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:11.921Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" id= title="Loving Arms" Oct 15 05:39:11 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:39:11 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:39:11 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:39:11 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:11.940Z level=INFO msg="emitting player state changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" state=STATUS_PLAYING positionMs=62495 volume=67 Oct 15 05:39:11 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:11.940Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" id= title="Loving Arms" Oct 15 05:39:11 volumio volumio[233279]: info: CoreCommandRouter::volumioGetState Oct 15 05:39:11 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:39:11 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:39:11 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:39:11 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:11.965Z level=INFO msg="emitting player state changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" state=STATUS_PLAYING positionMs=62495 volume=67 Oct 15 05:39:11 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:11.966Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" id= title="Loving Arms" Oct 15 05:39:14 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:14.153Z level=INFO msg="set volume" component=server type=REQUEST_TYPE_SET_VOLUME peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" latency=-3.849326975s timeout=3s volume=66 Oct 15 05:39:14 volumio volumio[233279]: info: VolumeController::SetAlsaVolume66 Oct 15 05:39:14 volumio volumio[233279]: info: CoreCommandRouter::volumioGetState Oct 15 05:39:14 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:39:14 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 15 05:39:14 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:39:14 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:14.180Z level=INFO msg="emitting player state changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" state=STATUS_PLAYING positionMs=62495 volume=66 Oct 15 05:39:14 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:14.184Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" id= title="Loving Arms" Oct 15 05:39:14 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:39:14 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:39:14 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 15 05:39:14 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:39:14 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:14.195Z level=INFO msg="emitting player state changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" state=STATUS_PLAYING positionMs=64737 volume=66 Oct 15 05:39:14 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:14.195Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" id= title="Loving Arms" Oct 15 05:39:14 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:39:14 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:39:14 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:39:14 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:14.229Z level=INFO msg="emitting player state changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" state=STATUS_PLAYING positionMs=64737 volume=66 Oct 15 05:39:14 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:14.230Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" id= title="Loving Arms" Oct 15 05:39:14 volumio volumio[233279]: info: CoreCommandRouter::volumioGetState Oct 15 05:39:14 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:39:14 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:39:14 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:39:14 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:14.276Z level=INFO msg="emitting player state changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" state=STATUS_PLAYING positionMs=64737 volume=66 Oct 15 05:39:14 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:14.276Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" id= title="Loving Arms" Oct 15 05:39:14 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:14.426Z level=INFO msg="set volume" component=server type=REQUEST_TYPE_SET_VOLUME peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" latency=-3.853578238s timeout=3s volume=65 Oct 15 05:39:14 volumio volumio[233279]: info: VolumeController::SetAlsaVolume65 Oct 15 05:39:14 volumio volumio[233279]: info: CoreCommandRouter::volumioGetState Oct 15 05:39:14 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:39:14 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 15 05:39:14 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:39:14 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:14.456Z level=INFO msg="emitting player state changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" state=STATUS_PLAYING positionMs=64737 volume=65 Oct 15 05:39:14 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:14.456Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" id= title="Loving Arms" Oct 15 05:39:14 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:39:14 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:39:14 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 15 05:39:14 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:39:14 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:14.481Z level=INFO msg="emitting player state changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" state=STATUS_PLAYING positionMs=64989 volume=65 Oct 15 05:39:14 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:14.482Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" id= title="Loving Arms" Oct 15 05:39:14 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:39:14 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:39:14 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:39:14 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:14.502Z level=INFO msg="emitting player state changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" state=STATUS_PLAYING positionMs=64989 volume=65 Oct 15 05:39:14 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:14.504Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" id= title="Loving Arms" Oct 15 05:39:14 volumio volumio[233279]: info: CoreCommandRouter::volumioGetState Oct 15 05:39:14 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:39:14 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:39:14 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 15 05:39:14 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:39:14 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:14.540Z level=INFO msg="emitting player state changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" state=STATUS_PLAYING positionMs=65114 volume=65 Oct 15 05:39:14 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:14.543Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" id= title="Loving Arms" Oct 15 05:39:14 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:14.667Z level=INFO msg="set volume" component=server type=REQUEST_TYPE_SET_VOLUME peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" latency=-3.8525837s timeout=3s volume=64 Oct 15 05:39:14 volumio volumio[233279]: info: VolumeController::SetAlsaVolume64 Oct 15 05:39:14 volumio volumio[233279]: info: CoreCommandRouter::volumioGetState Oct 15 05:39:14 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:39:14 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 15 05:39:14 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:39:14 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:14.691Z level=INFO msg="emitting player state changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" state=STATUS_PLAYING positionMs=65114 volume=64 Oct 15 05:39:14 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:14.692Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" id= title="Loving Arms" Oct 15 05:39:14 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:39:14 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:39:14 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 15 05:39:14 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:39:14 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:14.708Z level=INFO msg="emitting player state changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" state=STATUS_PLAYING positionMs=65240 volume=64 Oct 15 05:39:14 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:14.710Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" id= title="Loving Arms" Oct 15 05:39:14 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:39:14 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:39:14 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:39:14 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:14.735Z level=INFO msg="emitting player state changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" state=STATUS_PLAYING positionMs=65240 volume=64 Oct 15 05:39:14 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:14.740Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" id= title="Loving Arms" Oct 15 05:39:14 volumio volumio[233279]: info: CoreCommandRouter::volumioGetState Oct 15 05:39:14 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:39:14 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:39:14 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:39:14 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:14.752Z level=INFO msg="emitting player state changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" state=STATUS_PLAYING positionMs=65240 volume=64 Oct 15 05:39:14 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:14.752Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" id= title="Loving Arms" Oct 15 05:39:14 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:14.898Z level=INFO msg="set volume" component=server type=REQUEST_TYPE_SET_VOLUME peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" latency=-3.853264788s timeout=3s volume=63 Oct 15 05:39:14 volumio volumio[233279]: info: VolumeController::SetAlsaVolume63 Oct 15 05:39:14 volumio volumio[233279]: info: CoreCommandRouter::volumioGetState Oct 15 05:39:14 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:39:14 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 15 05:39:14 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:39:14 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:14.922Z level=INFO msg="emitting player state changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" state=STATUS_PLAYING positionMs=65240 volume=63 Oct 15 05:39:14 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:14.923Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" id= title="Loving Arms" Oct 15 05:39:14 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:39:14 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:39:14 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 15 05:39:14 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:39:14 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:14.933Z level=INFO msg="emitting player state changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" state=STATUS_PLAYING positionMs=65492 volume=63 Oct 15 05:39:14 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:14.935Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" id= title="Loving Arms" Oct 15 05:39:14 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:39:14 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:39:14 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:39:14 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:14.948Z level=INFO msg="emitting player state changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" state=STATUS_PLAYING positionMs=65492 volume=63 Oct 15 05:39:14 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:14.948Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" id= title="Loving Arms" Oct 15 05:39:14 volumio volumio[233279]: info: CoreCommandRouter::volumioGetState Oct 15 05:39:14 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:39:14 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:39:14 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:39:14 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:14.963Z level=INFO msg="emitting player state changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" state=STATUS_PLAYING positionMs=65492 volume=63 Oct 15 05:39:14 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:14.964Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" id= title="Loving Arms" Oct 15 05:39:15 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:15.111Z level=INFO msg="set volume" component=server type=REQUEST_TYPE_SET_VOLUME peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" latency=-3.852706725s timeout=3s volume=62 Oct 15 05:39:15 volumio volumio[233279]: info: VolumeController::SetAlsaVolume62 Oct 15 05:39:15 volumio volumio[233279]: info: CoreCommandRouter::volumioGetState Oct 15 05:39:15 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:39:15 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 15 05:39:15 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:39:15 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:15.137Z level=INFO msg="emitting player state changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" state=STATUS_PLAYING positionMs=65492 volume=62 Oct 15 05:39:15 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:15.137Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" id= title="Loving Arms" Oct 15 05:39:15 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:39:15 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:39:15 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 15 05:39:15 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:39:15 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:15.151Z level=INFO msg="emitting player state changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" state=STATUS_PLAYING positionMs=65617 volume=62 Oct 15 05:39:15 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:15.151Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" id= title="Loving Arms" Oct 15 05:39:15 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:39:15 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:39:15 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 15 05:39:15 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:39:15 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:15.165Z level=INFO msg="emitting player state changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" state=STATUS_PLAYING positionMs=65743 volume=62 Oct 15 05:39:15 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:15.165Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" id= title="Loving Arms" Oct 15 05:39:15 volumio volumio[233279]: info: CoreCommandRouter::volumioGetState Oct 15 05:39:15 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:39:15 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:39:15 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:39:15 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:15.189Z level=INFO msg="emitting player state changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" state=STATUS_PLAYING positionMs=65743 volume=62 Oct 15 05:39:15 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:15.192Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" id= title="Loving Arms" Oct 15 05:39:15 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:15.363Z level=INFO msg="set volume" component=server type=REQUEST_TYPE_SET_VOLUME peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" latency=-3.850953075s timeout=3s volume=61 Oct 15 05:39:15 volumio volumio[233279]: info: VolumeController::SetAlsaVolume61 Oct 15 05:39:15 volumio volumio[233279]: info: CoreCommandRouter::volumioGetState Oct 15 05:39:15 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:39:15 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 15 05:39:15 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:39:15 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:15.388Z level=INFO msg="emitting player state changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" state=STATUS_PLAYING positionMs=65743 volume=61 Oct 15 05:39:15 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:15.390Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" id= title="Loving Arms" Oct 15 05:39:15 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:39:15 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:39:15 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 15 05:39:15 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:39:15 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:15.401Z level=INFO msg="emitting player state changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" state=STATUS_PLAYING positionMs=65869 volume=61 Oct 15 05:39:15 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:15.402Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" id= title="Loving Arms" Oct 15 05:39:15 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:39:15 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:39:15 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 15 05:39:15 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:39:15 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:15.413Z level=INFO msg="emitting player state changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" state=STATUS_PLAYING positionMs=65995 volume=61 Oct 15 05:39:15 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:15.414Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" id= title="Loving Arms" Oct 15 05:39:15 volumio volumio[233279]: info: CoreCommandRouter::volumioGetState Oct 15 05:39:15 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:39:15 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:39:15 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:39:15 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:15.457Z level=INFO msg="emitting player state changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" state=STATUS_PLAYING positionMs=65995 volume=61 Oct 15 05:39:15 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:15.458Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" id= title="Loving Arms" Oct 15 05:39:15 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:15.613Z level=INFO msg="set volume" component=server type=REQUEST_TYPE_SET_VOLUME peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" latency=-3.852747425s timeout=3s volume=60 Oct 15 05:39:15 volumio volumio[233279]: info: VolumeController::SetAlsaVolume60 Oct 15 05:39:15 volumio volumio[233279]: info: CoreCommandRouter::volumioGetState Oct 15 05:39:15 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:39:15 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 15 05:39:15 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:39:15 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:15.641Z level=INFO msg="emitting player state changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" state=STATUS_PLAYING positionMs=65995 volume=60 Oct 15 05:39:15 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:15.642Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" id= title="Loving Arms" Oct 15 05:39:15 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:39:15 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:39:15 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 15 05:39:15 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:39:15 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:15.661Z level=INFO msg="emitting player state changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" state=STATUS_PLAYING positionMs=66120 volume=60 Oct 15 05:39:15 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:15.661Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" id= title="Loving Arms" Oct 15 05:39:15 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:39:15 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:39:15 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 15 05:39:15 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:39:15 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:15.685Z level=INFO msg="emitting player state changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" state=STATUS_PLAYING positionMs=66246 volume=60 Oct 15 05:39:15 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:15.685Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" id= title="Loving Arms" Oct 15 05:39:15 volumio volumio[233279]: info: CoreCommandRouter::volumioGetState Oct 15 05:39:15 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:39:15 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:39:15 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:39:15 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:15.714Z level=INFO msg="emitting player state changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" state=STATUS_PLAYING positionMs=66246 volume=60 Oct 15 05:39:15 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:15.714Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" id= title="Loving Arms" Oct 15 05:39:15 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:15.820Z level=INFO msg="set volume" component=server type=REQUEST_TYPE_SET_VOLUME peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" latency=-3.8554954s timeout=3s volume=57 Oct 15 05:39:15 volumio volumio[233279]: info: VolumeController::SetAlsaVolume57 Oct 15 05:39:15 volumio volumio[233279]: info: CoreCommandRouter::volumioGetState Oct 15 05:39:15 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:39:15 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 15 05:39:15 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:39:15 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:15.847Z level=INFO msg="emitting player state changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" state=STATUS_PLAYING positionMs=66246 volume=57 Oct 15 05:39:15 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:15.848Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" id= title="Loving Arms" Oct 15 05:39:15 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:39:15 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:39:15 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 15 05:39:15 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:39:15 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:15.862Z level=INFO msg="emitting player state changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" state=STATUS_PLAYING positionMs=66361 volume=57 Oct 15 05:39:15 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:15.862Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" id= title="Loving Arms" Oct 15 05:39:15 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:39:15 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:39:15 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:39:15 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:15.876Z level=INFO msg="emitting player state changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" state=STATUS_PLAYING positionMs=66361 volume=57 Oct 15 05:39:15 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:15.876Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" id= title="Loving Arms" Oct 15 05:39:15 volumio volumio[233279]: info: CoreCommandRouter::volumioGetState Oct 15 05:39:15 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:39:15 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:39:15 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:39:15 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:15.904Z level=INFO msg="emitting player state changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" state=STATUS_PLAYING positionMs=66361 volume=57 Oct 15 05:39:15 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:15.905Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" id= title="Loving Arms" Oct 15 05:39:16 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:16.022Z level=INFO msg="set volume" component=server type=REQUEST_TYPE_SET_VOLUME peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" latency=-3.853459713s timeout=3s volume=52 Oct 15 05:39:16 volumio volumio[233279]: info: VolumeController::SetAlsaVolume52 Oct 15 05:39:16 volumio volumio[233279]: info: CoreCommandRouter::volumioGetState Oct 15 05:39:16 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:39:16 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 15 05:39:16 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:39:16 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:16.044Z level=INFO msg="emitting player state changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" state=STATUS_PLAYING positionMs=66361 volume=52 Oct 15 05:39:16 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:16.045Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" id= title="Loving Arms" Oct 15 05:39:16 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:39:16 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:39:16 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 15 05:39:16 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:39:16 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:16.052Z level=INFO msg="emitting player state changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" state=STATUS_PLAYING positionMs=66612 volume=52 Oct 15 05:39:16 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:16.052Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" id= title="Loving Arms" Oct 15 05:39:16 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:39:16 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:39:16 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:39:16 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:16.064Z level=INFO msg="emitting player state changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" state=STATUS_PLAYING positionMs=66612 volume=52 Oct 15 05:39:16 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:16.065Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" id= title="Loving Arms" Oct 15 05:39:16 volumio volumio[233279]: info: CoreCommandRouter::volumioGetState Oct 15 05:39:16 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:39:16 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:39:16 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:39:16 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:16.074Z level=INFO msg="emitting player state changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" state=STATUS_PLAYING positionMs=66612 volume=52 Oct 15 05:39:16 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:16.074Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" id= title="Loving Arms" Oct 15 05:39:16 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:16.227Z level=INFO msg="set volume" component=server type=REQUEST_TYPE_SET_VOLUME peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" latency=-3.8494292s timeout=3s volume=48 Oct 15 05:39:16 volumio volumio[233279]: info: VolumeController::SetAlsaVolume48 Oct 15 05:39:16 volumio volumio[233279]: info: CoreCommandRouter::volumioGetState Oct 15 05:39:16 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:39:16 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 15 05:39:16 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:39:16 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:16.254Z level=INFO msg="emitting player state changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" state=STATUS_PLAYING positionMs=66612 volume=48 Oct 15 05:39:16 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:16.255Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" id= title="Loving Arms" Oct 15 05:39:16 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:39:16 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:39:16 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 15 05:39:16 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:39:16 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:16.268Z level=INFO msg="emitting player state changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" state=STATUS_PLAYING positionMs=66738 volume=48 Oct 15 05:39:16 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:16.268Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" id= title="Loving Arms" Oct 15 05:39:16 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:39:16 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:39:16 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:39:16 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:16.278Z level=INFO msg="emitting player state changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" state=STATUS_PLAYING positionMs=66738 volume=48 Oct 15 05:39:16 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:16.279Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" id= title="Loving Arms" Oct 15 05:39:16 volumio volumio[233279]: info: CoreCommandRouter::volumioGetState Oct 15 05:39:16 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:39:16 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:39:16 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 15 05:39:16 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:39:16 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:16.301Z level=INFO msg="emitting player state changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" state=STATUS_PLAYING positionMs=66864 volume=48 Oct 15 05:39:16 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:16.302Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" id= title="Loving Arms" Oct 15 05:39:16 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:16.427Z level=INFO msg="set volume" component=server type=REQUEST_TYPE_SET_VOLUME peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" latency=-3.850983888s timeout=3s volume=44 Oct 15 05:39:16 volumio volumio[233279]: info: VolumeController::SetAlsaVolume44 Oct 15 05:39:16 volumio volumio[233279]: info: CoreCommandRouter::volumioGetState Oct 15 05:39:16 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:39:16 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 15 05:39:16 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:39:16 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:16.462Z level=INFO msg="emitting player state changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" state=STATUS_PLAYING positionMs=66864 volume=44 Oct 15 05:39:16 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:16.462Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" id= title="Loving Arms" Oct 15 05:39:16 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:39:16 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:39:16 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 15 05:39:16 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:39:16 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:16.478Z level=INFO msg="emitting player state changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" state=STATUS_PLAYING positionMs=66990 volume=44 Oct 15 05:39:16 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:16.480Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" id= title="Loving Arms" Oct 15 05:39:16 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:39:16 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:39:16 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:39:16 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:16.502Z level=INFO msg="emitting player state changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" state=STATUS_PLAYING positionMs=66990 volume=44 Oct 15 05:39:16 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:16.503Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" id= title="Loving Arms" Oct 15 05:39:16 volumio volumio[233279]: info: CoreCommandRouter::volumioGetState Oct 15 05:39:16 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:39:16 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:39:16 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 15 05:39:16 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:39:16 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:16.524Z level=INFO msg="emitting player state changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" state=STATUS_PLAYING positionMs=67115 volume=44 Oct 15 05:39:16 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:16.525Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" id= title="Loving Arms" Oct 15 05:39:16 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:16.626Z level=INFO msg="set volume" component=server type=REQUEST_TYPE_SET_VOLUME peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" latency=-3.8537661s timeout=3s volume=41 Oct 15 05:39:16 volumio volumio[233279]: info: VolumeController::SetAlsaVolume41 Oct 15 05:39:16 volumio volumio[233279]: info: CoreCommandRouter::volumioGetState Oct 15 05:39:16 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:39:16 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 15 05:39:16 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:39:16 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:16.656Z level=INFO msg="emitting player state changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" state=STATUS_PLAYING positionMs=67115 volume=41 Oct 15 05:39:16 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:16.656Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" id= title="Loving Arms" Oct 15 05:39:16 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:39:16 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:39:16 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 15 05:39:16 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:39:16 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:16.670Z level=INFO msg="emitting player state changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" state=STATUS_PLAYING positionMs=67242 volume=41 Oct 15 05:39:16 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:16.671Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" id= title="Loving Arms" Oct 15 05:39:16 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:39:16 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:39:16 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:39:16 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:16.681Z level=INFO msg="emitting player state changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" state=STATUS_PLAYING positionMs=67242 volume=41 Oct 15 05:39:16 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:16.682Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" id= title="Loving Arms" Oct 15 05:39:16 volumio volumio[233279]: info: CoreCommandRouter::volumioGetState Oct 15 05:39:16 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:39:16 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:39:16 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:39:16 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:16.700Z level=INFO msg="emitting player state changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" state=STATUS_PLAYING positionMs=67242 volume=41 Oct 15 05:39:16 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:16.700Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" id= title="Loving Arms" Oct 15 05:39:16 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:16.825Z level=INFO msg="set volume" component=server type=REQUEST_TYPE_SET_VOLUME peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" latency=-3.853983425s timeout=3s volume=37 Oct 15 05:39:16 volumio volumio[233279]: info: VolumeController::SetAlsaVolume37 Oct 15 05:39:16 volumio volumio[233279]: info: CoreCommandRouter::volumioGetState Oct 15 05:39:16 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:39:16 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 15 05:39:16 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:39:16 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:16.851Z level=INFO msg="emitting player state changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" state=STATUS_PLAYING positionMs=67242 volume=37 Oct 15 05:39:16 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:16.856Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" id= title="Loving Arms" Oct 15 05:39:16 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:39:16 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:39:16 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 15 05:39:16 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:39:16 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:16.868Z level=INFO msg="emitting player state changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" state=STATUS_PLAYING positionMs=67367 volume=37 Oct 15 05:39:16 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:16.870Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" id= title="Loving Arms" Oct 15 05:39:16 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:39:16 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:39:16 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:39:16 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:16.881Z level=INFO msg="emitting player state changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" state=STATUS_PLAYING positionMs=67367 volume=37 Oct 15 05:39:16 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:16.884Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" id= title="Loving Arms" Oct 15 05:39:16 volumio volumio[233279]: info: CoreCommandRouter::volumioGetState Oct 15 05:39:16 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:39:16 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:39:16 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:39:16 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:16.902Z level=INFO msg="emitting player state changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" state=STATUS_PLAYING positionMs=67367 volume=37 Oct 15 05:39:16 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:16.902Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" id= title="Loving Arms" Oct 15 05:39:17 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:17.027Z level=INFO msg="set volume" component=server type=REQUEST_TYPE_SET_VOLUME peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" latency=-3.852567775s timeout=3s volume=36 Oct 15 05:39:17 volumio volumio[233279]: info: VolumeController::SetAlsaVolume36 Oct 15 05:39:17 volumio volumio[233279]: info: CoreCommandRouter::volumioGetState Oct 15 05:39:17 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:39:17 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 15 05:39:17 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:39:17 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:17.054Z level=INFO msg="emitting player state changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" state=STATUS_PLAYING positionMs=67367 volume=36 Oct 15 05:39:17 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:17.055Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" id= title="Loving Arms" Oct 15 05:39:17 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:39:17 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:39:17 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 15 05:39:17 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:39:17 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:17.072Z level=INFO msg="emitting player state changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" state=STATUS_PLAYING positionMs=67618 volume=36 Oct 15 05:39:17 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:17.074Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" id= title="Loving Arms" Oct 15 05:39:17 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:39:17 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:39:17 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:39:17 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:17.087Z level=INFO msg="emitting player state changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" state=STATUS_PLAYING positionMs=67618 volume=36 Oct 15 05:39:17 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:17.089Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" id= title="Loving Arms" Oct 15 05:39:17 volumio volumio[233279]: info: CoreCommandRouter::volumioGetState Oct 15 05:39:17 volumio volumio[233279]: info: CoreCommandRouter::servicePushState Oct 15 05:39:17 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:39:17 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:39:17 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:17.114Z level=INFO msg="emitting player state changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" state=STATUS_PLAYING positionMs=67618 volume=36 Oct 15 05:39:17 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:17.116Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" id= title="Loving Arms" Oct 15 05:39:23 volumio volumio[233279]: info: CALLMETHOD: audio_interface alsa_controller saveVolumeOptions [object Object] Oct 15 05:39:23 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , saveVolumeOptions Oct 15 05:39:23 volumio volumio[233279]: info: CoreCommandRouter::volumioGetState Oct 15 05:39:23 volumio volumio[233279]: info: Restoring Previous Volume level: 36 false true Oct 15 05:39:23 volumio volumio[233279]: info: VolumeController::SetAlsaVolume100 Oct 15 05:39:23 volumio volumio[233279]: info: Enable softmixer device for audio device number 5 Oct 15 05:39:23 volumio volumio[233279]: info: CoreCommandRouter::volumioStop Oct 15 05:39:23 volumio volumio[233279]: info: CoreStateMachine::stop Oct 15 05:39:23 volumio volumio[233279]: info: CoreStateMachine::serviceStop Oct 15 05:39:23 volumio volumio[233279]: info: CoreCommandRouter::serviceStop Oct 15 05:39:23 volumio volumio[233279]: info: [yt-cast-receiver] Player.stop() Oct 15 05:39:23 volumio volumio[233279]: info: Enable softmixer device for audio device undefined Oct 15 05:39:23 volumio volumio[233279]: info: CoreCommandRouter::volumioUpdateVolumeSettings Oct 15 05:39:23 volumio volumio[233279]: info: Updating Volume Controller Parameters: Device: 5 Name: 2Qute Mixer: PCM Max Vol: 100 Vol Curve; logarithmic Vol Steps: 1 Oct 15 05:39:23 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , setExternalVolume Oct 15 05:39:23 volumio volumio[233279]: info: Disabling external Volume Control Oct 15 05:39:23 volumio volumio[233279]: info: Output device has changed, restarting MPD Oct 15 05:39:23 volumio volumio[233279]: info: Output device has changed, restarting Shairport Sync Oct 15 05:39:23 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 15 05:39:23 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 15 05:39:23 volumio sudo[255759]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 15 05:39:23 volumio sudo[255759]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 15 05:39:23 volumio sudo[255759]: pam_unix(sudo:session): session closed for user root Oct 15 05:39:23 volumio sudo[255761]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 15 05:39:23 volumio sudo[255761]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 15 05:39:23 volumio volumio[233279]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 15 05:39:23 volumio volumio[233279]: info: Volume configurations have been set Oct 15 05:39:23 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Oct 15 05:39:23 volumio volumio[233279]: info: CoreCommandRouter::volumioUpdateVolumeSettings Oct 15 05:39:23 volumio volumio[233279]: info: Updating Volume Controller Parameters: Device: 5 Name: 2Qute Mixer: PCM Max Vol: 100 Vol Curve; logarithmic Vol Steps: 1 Oct 15 05:39:23 volumio systemd[1]: mpd.service: Deactivated successfully. Oct 15 05:39:23 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Oct 15 05:39:23 volumio systemd[1]: mpd.service: Consumed 4.680s CPU time. Oct 15 05:39:23 volumio systemd[1]: mpd.socket: Deactivated successfully. Oct 15 05:39:23 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Oct 15 05:39:23 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Oct 15 05:39:23 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , setExternalVolume Oct 15 05:39:23 volumio volumio[233279]: info: Disabling external Volume Control Oct 15 05:39:23 volumio volumio[233279]: info: CoreCommandRouter::getUIConfigOnPlugin Oct 15 05:39:23 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Oct 15 05:39:23 volumio volumio[233279]: info: CoreCommandRouter::volumioGetState Oct 15 05:39:23 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Oct 15 05:39:23 volumio volumio[233279]: info: CoreStateMachine::pushState Oct 15 05:39:23 volumio volumio[233279]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 15 05:39:23 volumio volumio[233279]: info: CoreCommandRouter::volumioPushState Oct 15 05:39:23 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:23.526Z level=INFO msg="emitting player state changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" state=STATUS_PLAYING positionMs=67618 volume=100 Oct 15 05:39:23 volumio volumio5-onboarding[1682]: time=2026-10-15T01:39:23.526Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.226:53722,00:00:00:00:00:00%05 @ 0xc0002e86c0" id= title="Loving Arms" Oct 15 05:39:23 volumio volumio[233279]: error: [ytcr] MPD error: Oct 15 05:39:23 volumio volumio[233279]: (AssertionError) The expression evaluated to a falsy value: Oct 15 05:39:23 volumio volumio[233279]: assert.ok(this.idling) Oct 15 05:39:23 volumio volumio[233279]: AssertionError [ERR_ASSERTION]: The expression evaluated to a falsy value: Oct 15 05:39:23 volumio volumio[233279]: assert.ok(this.idling) Oct 15 05:39:23 volumio volumio[233279]: at MPDClient.sendCommand (/data/plugins/music_service/ytcr/node_modules/mpd2/lib/index.js:62:12) Oct 15 05:39:23 volumio volumio[233279]: at MPDPlayer. (/data/plugins/music_service/ytcr/node_modules/mpd-api/lib/api/index.js:60:16) Oct 15 05:39:23 volumio volumio[233279]: at /data/plugins/music_service/ytcr/dist/lib/MPDPlayer.js:296:13 Oct 15 05:39:23 volumio volumio[233279]: at new Promise () Oct 15 05:39:23 volumio volumio[233279]: at MPDPlayer.resolveOnMPDStatusChanged (/data/plugins/music_service/ytcr/dist/lib/MPDPlayer.js:275:16) Oct 15 05:39:23 volumio volumio[233279]: at MPDPlayer.doStop (/data/plugins/music_service/ytcr/dist/lib/MPDPlayer.js:158:37) Oct 15 05:39:23 volumio volumio[233279]: at process.processTicksAndRejections (node:internal/process/task_queues:95:5) Oct 15 05:39:23 volumio volumio[233279]: at async MPDPlayer.stop (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/lib/Player.js:121:24) Oct 15 05:39:23 volumio volumio[233279]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 15 05:39:23 volumio volumio[233279]: MPDError: Not connected Oct 15 05:39:23 volumio volumio[233279]: at MPDClient.send (/data/plugins/music_service/ytcr/node_modules/mpd2/lib/index.js:101:13) Oct 15 05:39:23 volumio volumio[233279]: at MPDClient.sendCommand (/data/plugins/music_service/ytcr/node_modules/mpd2/lib/index.js:65:10) Oct 15 05:39:23 volumio volumio[233279]: at Object.get (/data/plugins/music_service/ytcr/node_modules/mpd-api/lib/api/index.js:60:16) Oct 15 05:39:23 volumio volumio[233279]: at MPDPlayer.getVolumioState (/data/plugins/music_service/ytcr/dist/lib/MPDPlayer.js:303:100) Oct 15 05:39:23 volumio volumio[233279]: at ControllerYTCR.pushState (/data/plugins/music_service/ytcr/dist/index.js:567:104) Oct 15 05:39:23 volumio volumio[233279]: at /data/plugins/music_service/ytcr/dist/index.js:309:28 Oct 15 05:39:23 volumio volumio[233279]: at CoreCommandRouter.callCallback (/volumio/app/index.js:214:9) Oct 15 05:39:23 volumio volumio[233279]: at CoreCommandRouter.volumioupdatevolume (/volumio/app/index.js:143:8) Oct 15 05:39:23 volumio volumio[233279]: at Promise._successFn (/volumio/app/index.js:137:16) Oct 15 05:39:23 volumio volumio[233279]: at nextTickCallback (/volumio/node_modules/kew/kew.js:47:28) Oct 15 05:39:23 volumio volumio[233279]: at process.processTicksAndRejections (node:internal/process/task_queues:77:11) { Oct 15 05:39:23 volumio volumio[233279]: code: 'ENOTCONNECTED' Oct 15 05:39:23 volumio volumio[233279]: } Oct 15 05:39:23 volumio volumio[233279]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 15 05:39:23 volumio sudo[255779]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Oct 15 05:39:23 volumio sudo[255779]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Oct 15 05:39:23 volumio sudo[255779]: pam_unix(sudo:session): session closed for user root Oct 15 05:39:23 volumio sudo[255797]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-10-15 05:38' Oct 15 05:39:23 volumio sudo[255797]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) 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"