Aug 27 20:06:09 rivo volumio[4682]: info: CorePlayQueue::getTrack 0 Aug 27 20:06:09 rivo volumio[4682]: info: CorePlayQueue::getTrack 1 Aug 27 20:06:09 rivo volumio[4682]: info: Prefetching next song Aug 27 20:06:09 rivo volumio[4682]: info: [1787853969119] ControllerQobuz::prefetch Aug 27 20:06:09 rivo volumio[4682]: info: getStreamUrl took 362 milliseconds Aug 27 20:06:09 rivo volumio[4682]: verbose: ControllerMpd::sendMpdCommand load "https://streaming-qobuz-std.akamaized.net/file?uid=8620680&eid=122794706&fmt=6&profile=raw&app_id=539451548&cid=4523439&etsp=1787857569&hmac=iSQqsPDnf9pKgH0BHWpDDh5UWQ4" Aug 27 20:06:10 rivo volumio[4682]: verbose: ControllerMpd::sendMpdCommand add "https://streaming-qobuz-std.akamaized.net/file?uid=8620680&eid=122794706&fmt=6&profile=raw&app_id=539451548&cid=4523439&etsp=1787857569&hmac=iSQqsPDnf9pKgH0BHWpDDh5UWQ4" Aug 27 20:06:10 rivo volumio[4682]: info: Aug 27 20:06:10 rivo volumio[4682]: ---------------------------- MPD announces system playlist update Aug 27 20:06:10 rivo volumio[4682]: info: Ignoring MPD Status Update Aug 27 20:06:10 rivo volumio[4682]: info: sendMpdCommand add "https://streaming-qobuz-std.akamaized.net/file?uid=8620680&eid=122794706&fmt=6&profile=raw&app_id=539451548&cid=4523439&etsp=1787857569&hmac=iSQqsPDnf9pKgH0BHWpDDh5UWQ4" took 4 milliseconds Aug 27 20:06:10 rivo volumio[4682]: info: CoreStateMachine::setConsumeUpdateService mpd Aug 27 20:06:10 rivo volumio[4682]: verbose: ControllerMpd::sendMpdCommand consume 1 Aug 27 20:06:10 rivo volumio[4682]: info: Aug 27 20:06:10 rivo volumio[4682]: ---------------------------- MPD announces system playlist update Aug 27 20:06:10 rivo volumio[4682]: info: Ignoring MPD Status Update Aug 27 20:06:10 rivo volumio[4682]: info: Aug 27 20:06:10 rivo volumio[4682]: ---------------------------- MPD announces system playlist update Aug 27 20:06:10 rivo volumio[4682]: info: Ignoring MPD Status Update Aug 27 20:06:10 rivo volumio[4682]: info: Aug 27 20:06:10 rivo volumio[4682]: ---------------------------- MPD announces state update: options Aug 27 20:06:10 rivo volumio[4682]: info: ------------------------------ 15ms Aug 27 20:06:10 rivo volumio[4682]: info: sendMpdCommand consume 1 took 12 milliseconds Aug 27 20:06:10 rivo volumio[4682]: info: ControllerMpd::getState Aug 27 20:06:10 rivo volumio[4682]: verbose: ControllerMpd::sendMpdCommand status Aug 27 20:06:10 rivo volumio[4682]: info: ------------------------------ 13ms Aug 27 20:06:10 rivo volumio[4682]: info: ------------------------------ 11ms Aug 27 20:06:10 rivo volumio[4682]: info: Aug 27 20:06:10 rivo volumio[4682]: ---------------------------- MPD announces state update: options Aug 27 20:06:10 rivo volumio[4682]: info: ControllerMpd::getState Aug 27 20:06:10 rivo volumio[4682]: verbose: ControllerMpd::sendMpdCommand status Aug 27 20:06:10 rivo volumio[4682]: info: Aug 27 20:06:10 rivo volumio[4682]: ---------------------------- MPD announces state update: options Aug 27 20:06:10 rivo volumio[4682]: info: ControllerMpd::getState Aug 27 20:06:10 rivo volumio[4682]: verbose: ControllerMpd::sendMpdCommand status Aug 27 20:06:10 rivo volumio[4682]: info: sendMpdCommand status took 9 milliseconds Aug 27 20:06:10 rivo volumio[4682]: info: sendMpdCommand status took 5 milliseconds Aug 27 20:06:10 rivo volumio[4682]: info: sendMpdCommand status took 4 milliseconds Aug 27 20:06:10 rivo volumio[4682]: verbose: ControllerMpd::parseState Aug 27 20:06:10 rivo volumio[4682]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 27 20:06:10 rivo volumio[4682]: verbose: ControllerMpd::parseState Aug 27 20:06:10 rivo volumio[4682]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 27 20:06:10 rivo volumio[4682]: verbose: ControllerMpd::parseState Aug 27 20:06:10 rivo volumio[4682]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 27 20:06:10 rivo volumio[4682]: info: sendMpdCommand playlistinfo took 9 milliseconds Aug 27 20:06:10 rivo volumio[4682]: info: sendMpdCommand playlistinfo took 8 milliseconds Aug 27 20:06:10 rivo volumio[4682]: info: sendMpdCommand playlistinfo took 7 milliseconds Aug 27 20:06:10 rivo volumio[4682]: verbose: ControllerMpd::parseTrackInfo Aug 27 20:06:10 rivo volumio[4682]: verbose: ControllerMpd::parseTrackInfo Aug 27 20:06:10 rivo volumio[4682]: verbose: ControllerMpd::parseTrackInfo Aug 27 20:06:10 rivo volumio[4682]: info: ControllerMpd::pushState Aug 27 20:06:10 rivo volumio[4682]: info: CoreCommandRouter::servicePushState Aug 27 20:06:10 rivo volumio[4682]: info: CorePlayQueue::getTrack 0 Aug 27 20:06:10 rivo volumio[4682]: verbose: STATE SERVICE {"status":"play","position":0,"seek":176569,"duration":180,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"342 Kbps","isStreaming":false,"title":"file?uid=8620680&eid=122794705&fmt=6&profile=raw&app_id=539451548&cid=4523439&etsp=1787857393&hmac=RlamaLMDp5jvAeERggsV14e7Zd8","artist":null,"album":null,"uri":"https://streaming-qobuz-std.akamaized.net/file?uid=8620680&eid=122794705&fmt=6&profile=raw&app_id=539451548&cid=4523439&etsp=1787857393&hmac=RlamaLMDp5jvAeERggsV14e7Zd8","trackType":"qobuz"} Aug 27 20:06:10 rivo volumio[4682]: verbose: CURRENT POSITION 0 Aug 27 20:06:10 rivo volumio[4682]: info: CoreStateMachine::syncState stateService play Aug 27 20:06:10 rivo volumio[4682]: info: CoreStateMachine::syncState currentStatus play Aug 27 20:06:10 rivo volumio[4682]: info: Received an update from plugin. extracting info from payload Aug 27 20:06:10 rivo volumio[4682]: info: CoreStateMachine::pushState Aug 27 20:06:10 rivo volumio[4682]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 27 20:06:10 rivo volumio[4682]: info: CoreCommandRouter::volumioPushState Aug 27 20:06:10 rivo volumio[4682]: info: CoreCommandRouter::volumioGetState Aug 27 20:06:10 rivo volumio[4682]: info: MRS: Pushing multiroomSync output update for this device Aug 27 20:06:10 rivo volumio[4682]: info: MRS: Pushing multiroomSync output Aug 27 20:06:10 rivo volumio[4682]: info: CoreStateMachine::pushState Aug 27 20:06:10 rivo volumio[4682]: info: CoreCommandRouter::volumioPushState Aug 27 20:06:10 rivo volumio[4682]: info: CoreCommandRouter::volumioGetState Aug 27 20:06:10 rivo volumio[4682]: info: MRS: Pushing multiroomSync output update for this device Aug 27 20:06:10 rivo volumio[4682]: info: MRS: Pushing multiroomSync output Aug 27 20:06:10 rivo volumio[4682]: info: ControllerMpd::pushState Aug 27 20:06:10 rivo volumio[4682]: info: CoreCommandRouter::servicePushState Aug 27 20:06:10 rivo volumio[4682]: info: CorePlayQueue::getTrack 0 Aug 27 20:06:10 rivo volumio[4682]: verbose: STATE SERVICE {"status":"play","position":0,"seek":176569,"duration":180,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"342 Kbps","isStreaming":false,"title":"file?uid=8620680&eid=122794705&fmt=6&profile=raw&app_id=539451548&cid=4523439&etsp=1787857393&hmac=RlamaLMDp5jvAeERggsV14e7Zd8","artist":null,"album":null,"uri":"https://streaming-qobuz-std.akamaized.net/file?uid=8620680&eid=122794705&fmt=6&profile=raw&app_id=539451548&cid=4523439&etsp=1787857393&hmac=RlamaLMDp5jvAeERggsV14e7Zd8","trackType":"qobuz"} Aug 27 20:06:10 rivo volumio[4682]: verbose: CURRENT POSITION 0 Aug 27 20:06:10 rivo volumio[4682]: info: CoreStateMachine::syncState stateService play Aug 27 20:06:10 rivo volumio[4682]: info: CoreStateMachine::syncState currentStatus play Aug 27 20:06:10 rivo volumio[4682]: info: Received an update from plugin. extracting info from payload Aug 27 20:06:10 rivo volumio[4682]: info: CoreStateMachine::pushState Aug 27 20:06:10 rivo volumio[4682]: info: CoreCommandRouter::volumioPushState Aug 27 20:06:10 rivo volumio[4682]: info: CoreCommandRouter::volumioGetState Aug 27 20:06:10 rivo volumio[4682]: info: MRS: Pushing multiroomSync output update for this device Aug 27 20:06:10 rivo volumio[4682]: info: MRS: Pushing multiroomSync output Aug 27 20:06:10 rivo volumio[4682]: info: CoreStateMachine::pushState Aug 27 20:06:10 rivo volumio[4682]: info: CoreCommandRouter::volumioPushState Aug 27 20:06:10 rivo volumio[4682]: info: CoreCommandRouter::volumioGetState Aug 27 20:06:10 rivo volumio[4682]: info: MRS: Pushing multiroomSync output update for this device Aug 27 20:06:10 rivo volumio[4682]: info: MRS: Pushing multiroomSync output Aug 27 20:06:10 rivo volumio[4682]: info: ControllerMpd::pushState Aug 27 20:06:10 rivo volumio[4682]: info: CoreCommandRouter::servicePushState Aug 27 20:06:10 rivo volumio[4682]: info: CorePlayQueue::getTrack 0 Aug 27 20:06:10 rivo volumio[4682]: verbose: STATE SERVICE {"status":"play","position":0,"seek":176569,"duration":180,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"342 Kbps","isStreaming":false,"title":"file?uid=8620680&eid=122794705&fmt=6&profile=raw&app_id=539451548&cid=4523439&etsp=1787857393&hmac=RlamaLMDp5jvAeERggsV14e7Zd8","artist":null,"album":null,"uri":"https://streaming-qobuz-std.akamaized.net/file?uid=8620680&eid=122794705&fmt=6&profile=raw&app_id=539451548&cid=4523439&etsp=1787857393&hmac=RlamaLMDp5jvAeERggsV14e7Zd8","trackType":"qobuz"} Aug 27 20:06:10 rivo volumio[4682]: verbose: CURRENT POSITION 0 Aug 27 20:06:10 rivo volumio[4682]: info: CoreStateMachine::syncState stateService play Aug 27 20:06:10 rivo volumio[4682]: info: CoreStateMachine::syncState currentStatus play Aug 27 20:06:10 rivo volumio[4682]: info: Received an update from plugin. extracting info from payload Aug 27 20:06:10 rivo volumio[4682]: info: CoreStateMachine::pushState Aug 27 20:06:10 rivo volumio[4682]: info: CoreCommandRouter::volumioPushState Aug 27 20:06:10 rivo volumio[4682]: info: CoreCommandRouter::volumioGetState Aug 27 20:06:10 rivo volumio[4682]: info: MRS: Pushing multiroomSync output update for this device Aug 27 20:06:10 rivo volumio[4682]: info: MRS: Pushing multiroomSync output Aug 27 20:06:10 rivo volumio[4682]: info: CoreStateMachine::pushState Aug 27 20:06:10 rivo volumio[4682]: info: CoreCommandRouter::volumioPushState Aug 27 20:06:10 rivo volumio[4682]: info: CoreCommandRouter::volumioGetState Aug 27 20:06:10 rivo volumio[4682]: info: MRS: Pushing multiroomSync output update for this device Aug 27 20:06:10 rivo volumio[4682]: info: MRS: Pushing multiroomSync output Aug 27 20:06:10 rivo volumio5-onboarding[4482]: time=2026-08-27T20:06:10.190+02:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%05 @ 0x2a4b590" state=STATUS_PLAYING positionMs=175006 volume=100 Aug 27 20:06:10 rivo volumio5-onboarding[4482]: time=2026-08-27T20:06:10.193+02:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%05 @ 0x2a4b590" state=STATUS_PLAYING positionMs=175006 volume=100 Aug 27 20:06:10 rivo volumio5-onboarding[4482]: time=2026-08-27T20:06:10.194+02:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%05 @ 0x2a4b590" state=STATUS_PLAYING positionMs=175006 volume=100 Aug 27 20:06:10 rivo volumio5-onboarding[4482]: time=2026-08-27T20:06:10.195+02:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%05 @ 0x2a4b590" state=STATUS_PLAYING positionMs=175006 volume=100 Aug 27 20:06:10 rivo volumio5-onboarding[4482]: time=2026-08-27T20:06:10.200+02:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%05 @ 0x2a4b590" state=STATUS_PLAYING positionMs=175006 volume=100 Aug 27 20:06:10 rivo volumio5-onboarding[4482]: time=2026-08-27T20:06:10.202+02:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%05 @ 0x2a4b590" state=STATUS_PLAYING positionMs=175006 volume=100 Aug 27 20:06:10 rivo volumio[4682]: info: ------------------------------ 137ms Aug 27 20:06:10 rivo volumio[4682]: info: ------------------------------ 131ms Aug 27 20:06:10 rivo volumio[4682]: info: ------------------------------ 129ms Aug 27 20:06:13 rivo volumio[4682]: info: Aug 27 20:06:13 rivo volumio[4682]: ---------------------------- MPD announces system playlist update Aug 27 20:06:13 rivo volumio[4682]: info: Ignoring MPD Status Update Aug 27 20:06:13 rivo volumio[4682]: info: Aug 27 20:06:13 rivo volumio[4682]: ---------------------------- MPD announces state update: player Aug 27 20:06:13 rivo volumio[4682]: info: ControllerMpd::getState Aug 27 20:06:13 rivo volumio[4682]: verbose: ControllerMpd::sendMpdCommand status Aug 27 20:06:13 rivo volumio[4682]: info: Aug 27 20:06:13 rivo volumio[4682]: ---------------------------- MPD announces system playlist update Aug 27 20:06:13 rivo volumio[4682]: info: Ignoring MPD Status Update Aug 27 20:06:13 rivo volumio[4682]: info: Aug 27 20:06:13 rivo volumio[4682]: ---------------------------- MPD announces state update: player Aug 27 20:06:13 rivo volumio[4682]: info: ControllerMpd::getState Aug 27 20:06:13 rivo volumio[4682]: verbose: ControllerMpd::sendMpdCommand status Aug 27 20:06:13 rivo volumio[4682]: info: Aug 27 20:06:13 rivo volumio[4682]: ---------------------------- MPD announces system playlist update Aug 27 20:06:13 rivo volumio[4682]: info: Ignoring MPD Status Update Aug 27 20:06:13 rivo volumio[4682]: info: Aug 27 20:06:13 rivo volumio[4682]: ---------------------------- MPD announces state update: player Aug 27 20:06:13 rivo volumio[4682]: info: ControllerMpd::getState Aug 27 20:06:13 rivo volumio[4682]: verbose: ControllerMpd::sendMpdCommand status Aug 27 20:06:13 rivo volumio[4682]: info: ------------------------------ 13ms Aug 27 20:06:13 rivo volumio[4682]: info: sendMpdCommand status took 10 milliseconds Aug 27 20:06:13 rivo volumio[4682]: info: ------------------------------ 8ms Aug 27 20:06:13 rivo volumio[4682]: info: sendMpdCommand status took 6 milliseconds Aug 27 20:06:13 rivo volumio[4682]: verbose: ControllerMpd::parseState Aug 27 20:06:13 rivo volumio[4682]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 27 20:06:13 rivo volumio[4682]: verbose: ControllerMpd::parseState Aug 27 20:06:13 rivo volumio[4682]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 27 20:06:13 rivo volumio[4682]: info: ------------------------------ 11ms Aug 27 20:06:13 rivo volumio[4682]: info: sendMpdCommand status took 9 milliseconds Aug 27 20:06:13 rivo volumio[4682]: info: sendMpdCommand playlistinfo took 4 milliseconds Aug 27 20:06:13 rivo volumio[4682]: info: sendMpdCommand playlistinfo took 4 milliseconds Aug 27 20:06:13 rivo volumio[4682]: verbose: ControllerMpd::parseState Aug 27 20:06:13 rivo volumio[4682]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 27 20:06:13 rivo volumio[4682]: verbose: ControllerMpd::parseTrackInfo Aug 27 20:06:13 rivo volumio[4682]: verbose: ControllerMpd::parseTrackInfo Aug 27 20:06:13 rivo volumio[4682]: info: ControllerMpd::pushState Aug 27 20:06:13 rivo volumio[4682]: info: CoreCommandRouter::servicePushState Aug 27 20:06:13 rivo volumio[4682]: info: CorePlayQueue::getTrack 0 Aug 27 20:06:13 rivo volumio[4682]: verbose: STATE SERVICE {"status":"play","position":0,"seek":68,"duration":167,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"670 Kbps","isStreaming":false,"title":"file?uid=8620680&eid=122794706&fmt=6&profile=raw&app_id=539451548&cid=4523439&etsp=1787857569&hmac=iSQqsPDnf9pKgH0BHWpDDh5UWQ4","artist":null,"album":null,"uri":"https://streaming-qobuz-std.akamaized.net/file?uid=8620680&eid=122794706&fmt=6&profile=raw&app_id=539451548&cid=4523439&etsp=1787857569&hmac=iSQqsPDnf9pKgH0BHWpDDh5UWQ4","trackType":"qobuz"} Aug 27 20:06:13 rivo volumio[4682]: verbose: CURRENT POSITION 0 Aug 27 20:06:13 rivo volumio[4682]: info: CoreStateMachine::syncState stateService play Aug 27 20:06:13 rivo volumio[4682]: info: CoreStateMachine::syncState currentStatus play Aug 27 20:06:13 rivo volumio[4682]: info: Received an update from plugin. extracting info from payload Aug 27 20:06:13 rivo volumio[4682]: info: CoreStateMachine::pushState Aug 27 20:06:13 rivo volumio[4682]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 27 20:06:13 rivo volumio[4682]: info: CoreCommandRouter::volumioPushState Aug 27 20:06:13 rivo volumio[4682]: info: CoreCommandRouter::volumioGetState Aug 27 20:06:13 rivo volumio[4682]: info: MRS: Pushing multiroomSync output update for this device Aug 27 20:06:13 rivo volumio[4682]: info: MRS: Pushing multiroomSync output Aug 27 20:06:13 rivo volumio[4682]: info: CoreStateMachine::pushState Aug 27 20:06:13 rivo volumio[4682]: info: CoreCommandRouter::volumioPushState Aug 27 20:06:13 rivo volumio[4682]: info: CoreCommandRouter::volumioGetState Aug 27 20:06:13 rivo volumio[4682]: info: MRS: Pushing multiroomSync output update for this device Aug 27 20:06:13 rivo volumio[4682]: info: MRS: Pushing multiroomSync output Aug 27 20:06:13 rivo volumio[4682]: info: ControllerMpd::pushState Aug 27 20:06:13 rivo volumio[4682]: info: CoreCommandRouter::servicePushState Aug 27 20:06:13 rivo volumio[4682]: info: CorePlayQueue::getTrack 0 Aug 27 20:06:13 rivo volumio[4682]: verbose: STATE SERVICE {"status":"play","position":0,"seek":68,"duration":167,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"670 Kbps","isStreaming":false,"title":"file?uid=8620680&eid=122794706&fmt=6&profile=raw&app_id=539451548&cid=4523439&etsp=1787857569&hmac=iSQqsPDnf9pKgH0BHWpDDh5UWQ4","artist":null,"album":null,"uri":"https://streaming-qobuz-std.akamaized.net/file?uid=8620680&eid=122794706&fmt=6&profile=raw&app_id=539451548&cid=4523439&etsp=1787857569&hmac=iSQqsPDnf9pKgH0BHWpDDh5UWQ4","trackType":"qobuz"} Aug 27 20:06:13 rivo volumio[4682]: verbose: CURRENT POSITION 0 Aug 27 20:06:13 rivo volumio[4682]: info: CoreStateMachine::syncState stateService play Aug 27 20:06:13 rivo volumio[4682]: info: CoreStateMachine::syncState currentStatus play Aug 27 20:06:13 rivo volumio[4682]: info: Received an update from plugin. extracting info from payload Aug 27 20:06:13 rivo volumio[4682]: info: CoreStateMachine::pushState Aug 27 20:06:13 rivo volumio[4682]: info: CoreCommandRouter::volumioPushState Aug 27 20:06:13 rivo volumio[4682]: info: CoreCommandRouter::volumioGetState Aug 27 20:06:13 rivo volumio[4682]: info: MRS: Pushing multiroomSync output update for this device Aug 27 20:06:13 rivo volumio[4682]: info: MRS: Pushing multiroomSync output Aug 27 20:06:13 rivo volumio[4682]: info: CoreStateMachine::pushState Aug 27 20:06:13 rivo volumio[4682]: info: CoreCommandRouter::volumioPushState Aug 27 20:06:13 rivo volumio[4682]: info: CoreCommandRouter::volumioGetState Aug 27 20:06:13 rivo volumio[4682]: info: MRS: Pushing multiroomSync output update for this device Aug 27 20:06:13 rivo volumio[4682]: info: MRS: Pushing multiroomSync output Aug 27 20:06:13 rivo volumio5-onboarding[4482]: time=2026-08-27T20:06:13.284+02:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%05 @ 0x2a4b590" state=STATUS_PLAYING positionMs=178129 volume=100 Aug 27 20:06:13 rivo volumio5-onboarding[4482]: time=2026-08-27T20:06:13.289+02:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%05 @ 0x2a4b590" state=STATUS_PLAYING positionMs=178129 volume=100 Aug 27 20:06:13 rivo volumio5-onboarding[4482]: time=2026-08-27T20:06:13.290+02:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%05 @ 0x2a4b590" state=STATUS_PLAYING positionMs=178129 volume=100 Aug 27 20:06:13 rivo volumio5-onboarding[4482]: time=2026-08-27T20:06:13.291+02:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%05 @ 0x2a4b590" state=STATUS_PLAYING positionMs=178129 volume=100 Aug 27 20:06:13 rivo volumio[4682]: info: ------------------------------ 105ms Aug 27 20:06:13 rivo volumio[4682]: info: ------------------------------ 100ms Aug 27 20:06:13 rivo volumio[4682]: info: sendMpdCommand playlistinfo took 86 milliseconds Aug 27 20:06:13 rivo volumio[4682]: verbose: ControllerMpd::parseTrackInfo Aug 27 20:06:13 rivo volumio[4682]: info: ControllerMpd::pushState Aug 27 20:06:13 rivo volumio[4682]: info: CoreCommandRouter::servicePushState Aug 27 20:06:13 rivo volumio[4682]: info: CorePlayQueue::getTrack 0 Aug 27 20:06:13 rivo volumio[4682]: verbose: STATE SERVICE {"status":"play","position":0,"seek":68,"duration":167,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"670 Kbps","isStreaming":false,"title":"file?uid=8620680&eid=122794706&fmt=6&profile=raw&app_id=539451548&cid=4523439&etsp=1787857569&hmac=iSQqsPDnf9pKgH0BHWpDDh5UWQ4","artist":null,"album":null,"uri":"https://streaming-qobuz-std.akamaized.net/file?uid=8620680&eid=122794706&fmt=6&profile=raw&app_id=539451548&cid=4523439&etsp=1787857569&hmac=iSQqsPDnf9pKgH0BHWpDDh5UWQ4","trackType":"qobuz"} Aug 27 20:06:13 rivo volumio[4682]: verbose: CURRENT POSITION 0 Aug 27 20:06:13 rivo volumio[4682]: info: CoreStateMachine::syncState stateService play Aug 27 20:06:13 rivo volumio[4682]: info: CoreStateMachine::syncState currentStatus play Aug 27 20:06:13 rivo volumio[4682]: info: Received an update from plugin. extracting info from payload Aug 27 20:06:13 rivo volumio[4682]: info: CoreStateMachine::pushState Aug 27 20:06:13 rivo volumio[4682]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 27 20:06:13 rivo volumio[4682]: info: CoreCommandRouter::volumioPushState Aug 27 20:06:13 rivo volumio[4682]: info: CoreCommandRouter::volumioGetState Aug 27 20:06:13 rivo volumio[4682]: info: MRS: Pushing multiroomSync output update for this device Aug 27 20:06:13 rivo volumio[4682]: info: MRS: Pushing multiroomSync output Aug 27 20:06:13 rivo volumio[4682]: info: CoreStateMachine::pushState Aug 27 20:06:13 rivo volumio[4682]: info: CoreCommandRouter::volumioPushState Aug 27 20:06:13 rivo volumio[4682]: info: CoreCommandRouter::volumioGetState Aug 27 20:06:13 rivo volumio[4682]: info: MRS: Pushing multiroomSync output update for this device Aug 27 20:06:13 rivo volumio[4682]: info: MRS: Pushing multiroomSync output Aug 27 20:06:13 rivo volumio5-onboarding[4482]: time=2026-08-27T20:06:13.346+02:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%05 @ 0x2a4b590" state=STATUS_PLAYING positionMs=178448 volume=100 Aug 27 20:06:13 rivo volumio5-onboarding[4482]: time=2026-08-27T20:06:13.348+02:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%05 @ 0x2a4b590" state=STATUS_PLAYING positionMs=178448 volume=100 Aug 27 20:06:13 rivo volumio[4682]: info: ------------------------------ 135ms Aug 27 20:06:13 rivo volumio5-onboarding[4482]: time=2026-08-27T20:06:13.512+02:00 level=WARN msg="pending write exceeded maximum retries, dropping" component=ble/conn addr=5 chunks=1 index=0 tries=11 Aug 27 20:06:13 rivo volumio5-onboarding[4482]: time=2026-08-27T20:06:13.513+02:00 level=ERROR msg="failed to send event" component=server dst="00:00:00:00:00:00%05 @ 0x2a4b590" event=SERVER_EVENT_TYPE_PLAYER_STATE_CHANGED error="peer is gone" Aug 27 20:06:13 rivo volumio[4682]: info: CoreStateMachine::startPlaybackTimer Aug 27 20:06:13 rivo volumio[4682]: info: CorePlayQueue::getTrack 1 Aug 27 20:06:13 rivo volumio[4682]: info: CoreStateMachine::pushState Aug 27 20:06:13 rivo volumio[4682]: info: CorePlayQueue::getTrack 1 Aug 27 20:06:13 rivo volumio[4682]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 27 20:06:13 rivo volumio[4682]: info: CoreCommandRouter::volumioPushState Aug 27 20:06:13 rivo volumio[4682]: info: CoreCommandRouter::volumioGetState Aug 27 20:06:13 rivo volumio[4682]: info: CorePlayQueue::getTrack 1 Aug 27 20:06:13 rivo volumio[4682]: info: MRS: Pushing multiroomSync output update for this device Aug 27 20:06:13 rivo volumio[4682]: info: MRS: Pushing multiroomSync output Aug 27 20:06:16 rivo volumio5-onboarding[4482]: time=2026-08-27T20:06:16.823+02:00 level=WARN msg="pending write exceeded maximum retries, dropping" component=ble/conn addr=5 chunks=1 index=0 tries=11 Aug 27 20:06:16 rivo volumio5-onboarding[4482]: time=2026-08-27T20:06:16.824+02:00 level=ERROR msg="failed to send event" component=server dst="00:00:00:00:00:00%05 @ 0x2a4b590" event=SERVER_EVENT_TYPE_PLAYER_STATE_CHANGED error="peer is gone" Aug 27 20:06:20 rivo volumio5-onboarding[4482]: time=2026-08-27T20:06:20.131+02:00 level=WARN msg="pending write exceeded maximum retries, dropping" component=ble/conn addr=5 chunks=1 index=0 tries=11 Aug 27 20:06:20 rivo volumio5-onboarding[4482]: time=2026-08-27T20:06:20.131+02:00 level=ERROR msg="failed to send event" component=server dst="00:00:00:00:00:00%05 @ 0x2a4b590" event=SERVER_EVENT_TYPE_PLAYER_STATE_CHANGED error="peer is gone" Aug 27 20:06:23 rivo volumio5-onboarding[4482]: time=2026-08-27T20:06:23.438+02:00 level=WARN msg="pending write exceeded maximum retries, dropping" component=ble/conn addr=5 chunks=1 index=0 tries=11 Aug 27 20:06:23 rivo volumio5-onboarding[4482]: time=2026-08-27T20:06:23.439+02:00 level=ERROR msg="failed to send event" component=server dst="00:00:00:00:00:00%05 @ 0x2a4b590" event=SERVER_EVENT_TYPE_PLAYER_STATE_CHANGED error="peer is gone" Aug 27 20:06:26 rivo volumio5-onboarding[4482]: time=2026-08-27T20:06:26.747+02:00 level=WARN msg="pending write exceeded maximum retries, dropping" component=ble/conn addr=5 chunks=1 index=0 tries=11 Aug 27 20:06:26 rivo volumio5-onboarding[4482]: time=2026-08-27T20:06:26.747+02:00 level=ERROR msg="failed to send event" component=server dst="00:00:00:00:00:00%05 @ 0x2a4b590" event=SERVER_EVENT_TYPE_PLAYER_STATE_CHANGED error="peer is gone" Aug 27 20:06:29 rivo bluealsa[3537]: bluez.c:1393: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved(/org/bluez/hci0/dev_7A_BE_1D_F9_25_3D/service0001/char0002, ...) Aug 27 20:06:29 rivo bluealsa[3537]: bluez.c:1393: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved(/org/bluez/hci0/dev_7A_BE_1D_F9_25_3D/service0001/char0004, ...) Aug 27 20:06:29 rivo bluealsa[3537]: bluez.c:1393: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved(/org/bluez/hci0/dev_7A_BE_1D_F9_25_3D/service0001, ...) Aug 27 20:06:29 rivo bluealsa[3537]: bluez.c:1393: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved(/org/bluez/hci0/dev_7A_BE_1D_F9_25_3D/service0006/char0007/desc0009, ...) Aug 27 20:06:29 rivo bluealsa[3537]: bluez.c:1393: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved(/org/bluez/hci0/dev_7A_BE_1D_F9_25_3D/service0006/char0007, ...) Aug 27 20:06:29 rivo bluealsa[3537]: bluez.c:1393: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved(/org/bluez/hci0/dev_7A_BE_1D_F9_25_3D/service0006, ...) Aug 27 20:06:29 rivo bluealsa[3537]: bluez.c:1393: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved(/org/bluez/hci0/dev_7A_BE_1D_F9_25_3D/service000a/char000b, ...) Aug 27 20:06:29 rivo bluealsa[3537]: bluez.c:1393: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved(/org/bluez/hci0/dev_7A_BE_1D_F9_25_3D/service000a/char000d, ...) Aug 27 20:06:29 rivo bluealsa[3537]: bluez.c:1393: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved(/org/bluez/hci0/dev_7A_BE_1D_F9_25_3D/service000a, ...) Aug 27 20:06:29 rivo bluealsa[3537]: bluez.c:1393: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved(/org/bluez/hci0/dev_7A_BE_1D_F9_25_3D, ...) Aug 27 20:06:30 rivo volumio5-onboarding[4482]: time=2026-08-27T20:06:30.059+02:00 level=WARN msg="pending write exceeded maximum retries, dropping" component=ble/conn addr=5 chunks=1 index=0 tries=11 Aug 27 20:06:30 rivo volumio5-onboarding[4482]: time=2026-08-27T20:06:30.059+02:00 level=ERROR msg="failed to send event" component=server dst="00:00:00:00:00:00%05 @ 0x2a4b590" event=SERVER_EVENT_TYPE_PLAYER_STATE_CHANGED error="peer is gone" Aug 27 20:06:33 rivo volumio5-onboarding[4482]: time=2026-08-27T20:06:33.371+02:00 level=WARN msg="pending write exceeded maximum retries, dropping" component=ble/conn addr=5 chunks=1 index=0 tries=11 Aug 27 20:06:33 rivo volumio5-onboarding[4482]: time=2026-08-27T20:06:33.373+02:00 level=ERROR msg="failed to send event" component=server dst="00:00:00:00:00:00%05 @ 0x2a4b590" event=SERVER_EVENT_TYPE_PLAYER_STATE_CHANGED error="peer is gone" Aug 27 20:06:36 rivo volumio5-onboarding[4482]: time=2026-08-27T20:06:36.678+02:00 level=WARN msg="pending write exceeded maximum retries, dropping" component=ble/conn addr=5 chunks=1 index=0 tries=11 Aug 27 20:06:36 rivo volumio5-onboarding[4482]: time=2026-08-27T20:06:36.679+02:00 level=ERROR msg="failed to send event" component=server dst="00:00:00:00:00:00%05 @ 0x2a4b590" event=SERVER_EVENT_TYPE_PLAYER_STATE_CHANGED error="peer is gone" Aug 27 20:06:39 rivo volumio5-onboarding[4482]: time=2026-08-27T20:06:39.987+02:00 level=WARN msg="pending write exceeded maximum retries, dropping" component=ble/conn addr=5 chunks=1 index=0 tries=11 Aug 27 20:06:39 rivo volumio5-onboarding[4482]: time=2026-08-27T20:06:39.988+02:00 level=ERROR msg="failed to send event" component=server dst="00:00:00:00:00:00%05 @ 0x2a4b590" event=SERVER_EVENT_TYPE_PLAYER_STATE_CHANGED error="peer is gone" Aug 27 20:06:43 rivo volumio5-onboarding[4482]: time=2026-08-27T20:06:43.294+02:00 level=WARN msg="pending write exceeded maximum retries, dropping" component=ble/conn addr=5 chunks=1 index=0 tries=11 Aug 27 20:06:43 rivo volumio5-onboarding[4482]: time=2026-08-27T20:06:43.295+02:00 level=ERROR msg="failed to send event" component=server dst="00:00:00:00:00:00%05 @ 0x2a4b590" event=SERVER_EVENT_TYPE_PLAYER_STATE_CHANGED error="peer is gone" Aug 27 20:06:46 rivo volumio5-onboarding[4482]: time=2026-08-27T20:06:46.601+02:00 level=WARN msg="pending write exceeded maximum retries, dropping" component=ble/conn addr=5 chunks=1 index=0 tries=11 Aug 27 20:06:46 rivo volumio5-onboarding[4482]: time=2026-08-27T20:06:46.602+02:00 level=ERROR msg="failed to send event" component=server dst="00:00:00:00:00:00%05 @ 0x2a4b590" event=SERVER_EVENT_TYPE_PLAYER_STATE_CHANGED error="peer is gone" Aug 27 20:06:49 rivo volumio5-onboarding[4482]: time=2026-08-27T20:06:49.908+02:00 level=WARN msg="pending write exceeded maximum retries, dropping" component=ble/conn addr=5 chunks=1 index=0 tries=11 Aug 27 20:06:49 rivo volumio5-onboarding[4482]: time=2026-08-27T20:06:49.908+02:00 level=ERROR msg="failed to send event" component=server dst="00:00:00:00:00:00%05 @ 0x2a4b590" event=SERVER_EVENT_TYPE_PLAYER_STATE_CHANGED error="peer is gone" Aug 27 20:07:04 rivo volumio[4682]: info: CoreCommandRouter::volumioGetState Aug 27 20:07:04 rivo volumio[4682]: info: CorePlayQueue::getTrack 1 Aug 27 20:07:06 rivo volumio[4682]: info: Executing endpoint metavolumio Aug 27 20:07:06 rivo volumio[4682]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Aug 27 20:07:06 rivo volumio[4682]: info: Executing endpoint metavolumio Aug 27 20:07:06 rivo volumio[4682]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Aug 27 20:07:06 rivo volumio[4682]: info: Executing endpoint metavolumio Aug 27 20:07:06 rivo volumio[4682]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Aug 27 20:07:08 rivo volumio[4682]: info: CoreCommandRouter::getUIConfigOnPlugin Aug 27 20:07:08 rivo volumio[4682]: info: CoreCommandRouter::getUIConfigOnPlugin Aug 27 20:07:08 rivo volumio[4682]: info: Retrieving Cloud Streaming UI Aug 27 20:07:08 rivo volumio[4682]: info: Getting Tidal Cloud Configuration Aug 27 20:07:08 rivo volumio[4682]: info: CoreCommandRouter::getUIConfigOnPlugin Aug 27 20:07:08 rivo volumio[4682]: info: Getting Qobuz Cloud Configuration Aug 27 20:07:08 rivo volumio[4682]: info: Asking plugin for UI Config Aug 27 20:07:08 rivo volumio[4682]: info: CoreCommandRouter::getUIConfigOnPlugin Aug 27 20:07:08 rivo volumio[4682]: info: Getting Spotify Cloud Configuration Aug 27 20:07:08 rivo volumio[4682]: info: Asking plugin for UI Config Aug 27 20:07:08 rivo volumio[4682]: info: CoreCommandRouter::getUIConfigOnPlugin Aug 27 20:07:08 rivo volumio[4682]: info: Saving Spotify Acccount Aug 27 20:07:08 rivo volumio[4682]: info: Got it Aug 27 20:07:08 rivo volumio[4682]: error: Could not retrieve Spotify Config from plugin Spotify: no section found Aug 27 20:07:08 rivo volumio[4682]: info: Got Tidal Cloud Configuration Aug 27 20:07:08 rivo volumio[4682]: info: Got it Aug 27 20:07:08 rivo volumio[4682]: info: CoreCommandRouter::getUIConfigOnPlugin Aug 27 20:07:08 rivo volumio[4682]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus Aug 27 20:07:08 rivo volumio[4682]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Aug 27 20:07:08 rivo volumio[4682]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Aug 27 20:07:08 rivo volumio[4682]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Aug 27 20:07:08 rivo volumio[4682]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 27 20:07:08 rivo volumio[4682]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 27 20:07:08 rivo volumio[4682]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 27 20:07:08 rivo volumio[4682]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 27 20:07:08 rivo volumio[4682]: info: CoreCommandRouter::volumioGetBrowseSources Aug 27 20:07:08 rivo volumio[4682]: info: CoreCommandRouter::volumioGetBrowseSources Aug 27 20:07:08 rivo volumio[4682]: info: CoreCommandRouter::volumioGetBrowseSources Aug 27 20:07:08 rivo volumio[4682]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Aug 27 20:07:08 rivo volumio[4682]: info: CoreCommandRouter::executeOnPlugin: networkfs , listShares Aug 27 20:07:12 rivo volumio[4682]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Aug 27 20:07:13 rivo volumio[4682]: error: Failed request for metavolumio API Aug 27 20:07:13 rivo volumio[4682]: error: Failed request for metavolumio API Aug 27 20:07:13 rivo volumio[4682]: error: Failed request for metavolumio API Aug 27 20:07:16 rivo volumio[4682]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Aug 27 20:07:20 rivo volumio[4682]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Aug 27 20:07:24 rivo volumio[4682]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Aug 27 20:07:26 rivo volumio[4682]: info: Disabling MyMusic plugin upnp Aug 27 20:07:26 rivo sudo[6088]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop upmpdcli.service Aug 27 20:07:26 rivo sudo[6088]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 27 20:07:26 rivo systemd[1]: Stopping upmpdcli.service - UPnP Renderer front-end to MPD... Aug 27 20:07:28 rivo volumio[4682]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Aug 27 20:07:32 rivo volumio[4682]: info: Enabling MyMusic plugin upnp Aug 27 20:07:32 rivo volumio[4682]: info: Enabling plugin upnp Aug 27 20:07:32 rivo volumio[4682]: info: Loading plugin "upnp"... Aug 27 20:07:32 rivo volumio[4682]: info: [1787854052713] Starting Upmpd Daemon Aug 27 20:07:32 rivo volumio[4682]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Aug 27 20:07:32 rivo volumio[4682]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 27 20:07:32 rivo volumio[4682]: Error: listen EADDRINUSE: address already in use :::6599 Aug 27 20:07:32 rivo volumio[4682]: at Server.setupListenHandle [as _listen2] (node:net:1872:16) Aug 27 20:07:32 rivo volumio[4682]: at listenInCluster (node:net:1920:12) Aug 27 20:07:32 rivo volumio[4682]: at Server.listen (node:net:2008:7) Aug 27 20:07:32 rivo volumio[4682]: at UpnpInterface.onVolumioStart (/volumio/app/plugins/audio_interface/upnp/index.js:78:17) Aug 27 20:07:32 rivo volumio[4682]: at PluginManager.loadCorePlugin (/volumio/app/pluginmanager.js:255:38) Aug 27 20:07:32 rivo volumio[4682]: at Promise._successFn (/volumio/app/pluginmanager.js:1855:19) Aug 27 20:07:32 rivo volumio[4682]: at nextTickCallback (/volumio/node_modules/kew/kew.js:47:28) Aug 27 20:07:32 rivo volumio[4682]: at process.processTicksAndRejections (node:internal/process/task_queues:77:11) { Aug 27 20:07:32 rivo volumio[4682]: code: 'EADDRINUSE', Aug 27 20:07:32 rivo volumio[4682]: errno: -98, Aug 27 20:07:32 rivo volumio[4682]: syscall: 'listen', Aug 27 20:07:32 rivo volumio[4682]: address: '::', Aug 27 20:07:32 rivo volumio[4682]: port: 6599 Aug 27 20:07:32 rivo volumio[4682]: } Aug 27 20:07:32 rivo volumio[4682]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 27 20:07:33 rivo sudo[6119]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-08-27 20:06' Aug 27 20:07:33 rivo sudo[6119]: 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="ad2b65e62ee66106fc9799a5d56d019303babfad" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="9938d7179e3b7c4e41f3e2d60c255985cff08fee" VOLUMIO_ARCH="armv7" VOLUMIO_VARIANT="rivo" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Wed Jul 29 10:41:31 UTC 2026" VOLUMIO_VERSION="4.185" VOLUMIO_HARDWARE="mp1" VOLUMIO_DEVICENAME="Volumio MP1" VOLUMIO_VENDOR_MODEL="Volumio Rivo" VOLUMIO_VENDOR="Volumio" VOLUMIO_MODEL="Rivo" VOLUMIO_HASH="8dbed02e26c8684a8f81563b979083f3"