-- Logs begin at Tue 2026-02-17 23:23:24 +03, end at Tue 2026-02-17 23:33:26 +03. -- Feb 17 23:32:00 rivo volumio[3331]: STREAMING PROXY: Upstream closed. Received 380595 bytes Feb 17 23:32:00 rivo volumio[3331]: STREAMING PROXY: Incomplete transfer. Expected 44577891, got 380595 Feb 17 23:32:00 rivo volumio[3331]: STREAMING PROXY: Retrying with range: bytes=380595- (attempt 1) Feb 17 23:32:01 rivo volumio[3331]: STREAMING PROXY: Resuming with range: bytes=380595- Feb 17 23:32:01 rivo volumio[3331]: STREAMING PROXY: Resume upstream status code: 206 Feb 17 23:32:02 rivo volumio[3331]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Feb 17 23:32:02 rivo volumio[3331]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Feb 17 23:32:02 rivo volumio[3331]: info: Discovery: Getting this device information Feb 17 23:32:02 rivo volumio[3331]: info: CoreCommandRouter::volumioGetState Feb 17 23:32:02 rivo volumio[3331]: info: CorePlayQueue::getTrack 1 Feb 17 23:32:02 rivo volumio[3331]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 17 23:32:02 rivo volumio[3331]: verbose: New Socket.io Connection to 192.168.1.101:3000 from 192.168.1.150 UA: Dart/3.10 (dart:io) Engine version: 3 Transport: websocket Total Clients: 10 Feb 17 23:32:02 rivo volumio[3331]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Feb 17 23:32:02 rivo volumio[3331]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Feb 17 23:32:04 rivo volumio[3331]: info: CoreCommandRouter::volumioPause Feb 17 23:32:04 rivo volumio[3331]: info: CoreStateMachine::pause Feb 17 23:32:04 rivo volumio[3331]: info: CoreStateMachine::stPlaybackTimer Feb 17 23:32:04 rivo volumio[3331]: info: CoreStateMachine::servicePause Feb 17 23:32:04 rivo volumio[3331]: info: CorePlayQueue::getTrack 1 Feb 17 23:32:04 rivo volumio[3331]: info: CoreCommandRouter::servicePause Feb 17 23:32:04 rivo volumio[3331]: info: [1771360324627] ControllerQobuz::pause Feb 17 23:32:04 rivo volumio[3331]: info: CoreStateMachine::setConsumeUpdateService mpd Feb 17 23:32:04 rivo volumio[3331]: info: ControllerMpd::pause Feb 17 23:32:04 rivo volumio[3331]: verbose: ControllerMpd::sendMpdCommand pause Feb 17 23:32:04 rivo volumio[3331]: info: sendMpdCommand pause took 3 milliseconds Feb 17 23:32:04 rivo volumio[3331]: info: Feb 17 23:32:04 rivo volumio[3331]: ---------------------------- MPD announces state update: player Feb 17 23:32:04 rivo volumio[3331]: info: ControllerMpd::getState Feb 17 23:32:04 rivo volumio[3331]: verbose: ControllerMpd::sendMpdCommand status Feb 17 23:32:04 rivo volumio[3331]: info: Feb 17 23:32:04 rivo volumio[3331]: ---------------------------- MPD announces state update: player Feb 17 23:32:04 rivo volumio[3331]: info: ControllerMpd::getState Feb 17 23:32:04 rivo volumio[3331]: verbose: ControllerMpd::sendMpdCommand status Feb 17 23:32:04 rivo volumio[3331]: info: Feb 17 23:32:04 rivo volumio[3331]: ---------------------------- MPD announces state update: player Feb 17 23:32:04 rivo volumio[3331]: info: ControllerMpd::getState Feb 17 23:32:04 rivo volumio[3331]: verbose: ControllerMpd::sendMpdCommand status Feb 17 23:32:04 rivo volumio[3331]: info: sendMpdCommand status took 6 milliseconds Feb 17 23:32:04 rivo volumio[3331]: info: sendMpdCommand status took 4 milliseconds Feb 17 23:32:04 rivo volumio[3331]: info: sendMpdCommand status took 2 milliseconds Feb 17 23:32:04 rivo volumio[3331]: verbose: ControllerMpd::parseState Feb 17 23:32:04 rivo volumio[3331]: verbose: ControllerMpd::sendMpdCommand playlistinfo Feb 17 23:32:04 rivo volumio[3331]: verbose: ControllerMpd::parseState Feb 17 23:32:04 rivo volumio[3331]: verbose: ControllerMpd::sendMpdCommand playlistinfo Feb 17 23:32:04 rivo volumio[3331]: verbose: ControllerMpd::parseState Feb 17 23:32:04 rivo volumio[3331]: verbose: ControllerMpd::sendMpdCommand playlistinfo Feb 17 23:32:04 rivo volumio[3331]: info: sendMpdCommand playlistinfo took 4 milliseconds Feb 17 23:32:04 rivo volumio[3331]: info: sendMpdCommand playlistinfo took 3 milliseconds Feb 17 23:32:04 rivo volumio[3331]: info: sendMpdCommand playlistinfo took 3 milliseconds Feb 17 23:32:04 rivo volumio[3331]: verbose: ControllerMpd::parseTrackInfo Feb 17 23:32:04 rivo volumio[3331]: verbose: ControllerMpd::parseTrackInfo Feb 17 23:32:04 rivo volumio[3331]: verbose: ControllerMpd::parseTrackInfo Feb 17 23:32:04 rivo volumio[3331]: info: ControllerMpd::pushState Feb 17 23:32:04 rivo volumio[3331]: info: CoreCommandRouter::servicePushState Feb 17 23:32:04 rivo volumio[3331]: info: CorePlayQueue::getTrack 1 Feb 17 23:32:04 rivo volumio[3331]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":2677,"duration":234,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"1513 Kbps","isStreaming":false,"title":"163677066","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=qobuz://song/163677066","trackType":"qobuz"} Feb 17 23:32:04 rivo volumio[3331]: verbose: CURRENT POSITION 1 Feb 17 23:32:04 rivo volumio[3331]: info: CoreStateMachine::syncState stateService pause Feb 17 23:32:04 rivo volumio[3331]: info: CoreStateMachine::syncState currentStatus pause Feb 17 23:32:04 rivo volumio[3331]: info: CoreStateMachine::pushState Feb 17 23:32:04 rivo volumio[3331]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 17 23:32:04 rivo volumio[3331]: info: CoreCommandRouter::volumioPushState Feb 17 23:32:04 rivo volumio[3331]: info: CoreCommandRouter::volumioGetState Feb 17 23:32:04 rivo volumio[3331]: info: MRS: Pushing multiroomSync output update for this device Feb 17 23:32:04 rivo volumio[3331]: info: MRS: Pushing multiroomSync output Feb 17 23:32:04 rivo volumio[3331]: info: CoreStateMachine::stPlaybackTimer Feb 17 23:32:04 rivo volumio[3331]: info: ControllerMpd::pushState Feb 17 23:32:04 rivo volumio[3331]: info: CoreCommandRouter::servicePushState Feb 17 23:32:04 rivo volumio[3331]: info: CorePlayQueue::getTrack 1 Feb 17 23:32:04 rivo volumio[3331]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":2677,"duration":234,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"1513 Kbps","isStreaming":false,"title":"163677066","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=qobuz://song/163677066","trackType":"qobuz"} Feb 17 23:32:04 rivo volumio[3331]: verbose: CURRENT POSITION 1 Feb 17 23:32:04 rivo volumio[3331]: info: CoreStateMachine::syncState stateService pause Feb 17 23:32:04 rivo volumio[3331]: info: CoreStateMachine::syncState currentStatus pause Feb 17 23:32:04 rivo volumio[3331]: info: CoreStateMachine::pushState Feb 17 23:32:04 rivo volumio[3331]: info: CoreCommandRouter::volumioPushState Feb 17 23:32:04 rivo volumio[3331]: info: CoreCommandRouter::volumioGetState Feb 17 23:32:04 rivo volumio[3331]: info: MRS: Pushing multiroomSync output update for this device Feb 17 23:32:04 rivo volumio[3331]: info: MRS: Pushing multiroomSync output Feb 17 23:32:04 rivo volumio[3331]: info: CoreStateMachine::stPlaybackTimer Feb 17 23:32:04 rivo volumio[3331]: info: ControllerMpd::pushState Feb 17 23:32:04 rivo volumio[3331]: info: CoreCommandRouter::servicePushState Feb 17 23:32:04 rivo volumio[3331]: info: CorePlayQueue::getTrack 1 Feb 17 23:32:04 rivo volumio[3331]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":2677,"duration":234,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"1513 Kbps","isStreaming":false,"title":"163677066","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=qobuz://song/163677066","trackType":"qobuz"} Feb 17 23:32:04 rivo volumio[3331]: verbose: CURRENT POSITION 1 Feb 17 23:32:04 rivo volumio[3331]: info: CoreStateMachine::syncState stateService pause Feb 17 23:32:04 rivo volumio[3331]: info: CoreStateMachine::syncState currentStatus pause Feb 17 23:32:04 rivo volumio[3331]: info: CoreStateMachine::pushState Feb 17 23:32:04 rivo volumio[3331]: info: CoreCommandRouter::volumioPushState Feb 17 23:32:04 rivo volumio[3331]: info: CoreCommandRouter::volumioGetState Feb 17 23:32:04 rivo volumio[3331]: info: MRS: Pushing multiroomSync output update for this device Feb 17 23:32:04 rivo volumio[3331]: info: MRS: Pushing multiroomSync output Feb 17 23:32:04 rivo volumio[3331]: info: CoreStateMachine::stPlaybackTimer Feb 17 23:32:04 rivo volumio5-onboarding[4218]: time=2026-02-17T23:32:04.680+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.150:48512 @ 0x20a1260" state=STATUS_PAUSED positionMs=16110 volume=100 Feb 17 23:32:04 rivo volumio5-onboarding[4218]: time=2026-02-17T23:32:04.681+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.150:48512 @ 0x20a1260" id=qobuz://song/163677065 title="El Bueno Y El Malo" Feb 17 23:32:04 rivo volumio5-onboarding[4218]: time=2026-02-17T23:32:04.681+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.150:48512 @ 0x20a1260" state=STATUS_PAUSED positionMs=16110 volume=100 Feb 17 23:32:04 rivo volumio5-onboarding[4218]: time=2026-02-17T23:32:04.682+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.150:48512 @ 0x20a1260" id=qobuz://song/163677065 title="El Bueno Y El Malo" Feb 17 23:32:04 rivo volumio5-onboarding[4218]: time=2026-02-17T23:32:04.683+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.150:48512 @ 0x20a1260" state=STATUS_PAUSED positionMs=16110 volume=100 Feb 17 23:32:04 rivo volumio5-onboarding[4218]: time=2026-02-17T23:32:04.684+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.150:48512 @ 0x20a1260" id=qobuz://song/163677065 title="El Bueno Y El Malo" Feb 17 23:32:04 rivo volumio[3331]: info: ------------------------------ 85ms Feb 17 23:32:04 rivo volumio[3331]: info: ------------------------------ 84ms Feb 17 23:32:04 rivo volumio[3331]: info: ------------------------------ 83ms Feb 17 23:32:04 rivo volumio[3331]: info: MCU Signalled Playback Inactive Feb 17 23:32:08 rivo volumio[3331]: info: CoreCommandRouter::volumioPlay Feb 17 23:32:08 rivo volumio[3331]: info: CoreStateMachine::play index undefined Feb 17 23:32:08 rivo volumio[3331]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 17 23:32:08 rivo volumio[3331]: info: CorePlayQueue::getTrack 1 Feb 17 23:32:08 rivo volumio[3331]: info: CoreStateMachine::startPlaybackTimer Feb 17 23:32:08 rivo volumio[3331]: info: CorePlayQueue::getTrack 1 Feb 17 23:32:08 rivo volumio[3331]: info: [1771360328210] ControllerQobuz::resume Feb 17 23:32:08 rivo volumio[3331]: info: CoreStateMachine::setConsumeUpdateService mpd Feb 17 23:32:08 rivo volumio[3331]: info: ControllerMpd::resume Feb 17 23:32:08 rivo volumio[3331]: verbose: ControllerMpd::sendMpdCommand play Feb 17 23:32:08 rivo volumio[3331]: info: sendMpdCommand play took 25 milliseconds Feb 17 23:32:08 rivo volumio[3331]: info: Feb 17 23:32:08 rivo volumio[3331]: ---------------------------- MPD announces state update: player Feb 17 23:32:08 rivo volumio[3331]: info: ControllerMpd::getState Feb 17 23:32:08 rivo volumio[3331]: verbose: ControllerMpd::sendMpdCommand status Feb 17 23:32:08 rivo volumio[3331]: info: Feb 17 23:32:08 rivo volumio[3331]: ---------------------------- MPD announces state update: player Feb 17 23:32:08 rivo volumio[3331]: info: ControllerMpd::getState Feb 17 23:32:08 rivo volumio[3331]: verbose: ControllerMpd::sendMpdCommand status Feb 17 23:32:08 rivo volumio[3331]: info: Feb 17 23:32:08 rivo volumio[3331]: ---------------------------- MPD announces state update: player Feb 17 23:32:08 rivo volumio[3331]: info: ControllerMpd::getState Feb 17 23:32:08 rivo volumio[3331]: verbose: ControllerMpd::sendMpdCommand status Feb 17 23:32:08 rivo volumio[3331]: info: sendMpdCommand status took 6 milliseconds Feb 17 23:32:08 rivo volumio[3331]: info: sendMpdCommand status took 4 milliseconds Feb 17 23:32:08 rivo volumio[3331]: info: sendMpdCommand status took 2 milliseconds Feb 17 23:32:08 rivo volumio[3331]: verbose: ControllerMpd::parseState Feb 17 23:32:08 rivo volumio[3331]: verbose: ControllerMpd::sendMpdCommand playlistinfo Feb 17 23:32:08 rivo volumio[3331]: verbose: ControllerMpd::parseState Feb 17 23:32:08 rivo volumio[3331]: verbose: ControllerMpd::sendMpdCommand playlistinfo Feb 17 23:32:08 rivo volumio[3331]: verbose: ControllerMpd::parseState Feb 17 23:32:08 rivo volumio[3331]: verbose: ControllerMpd::sendMpdCommand playlistinfo Feb 17 23:32:08 rivo volumio[3331]: info: sendMpdCommand playlistinfo took 3 milliseconds Feb 17 23:32:08 rivo volumio[3331]: info: sendMpdCommand playlistinfo took 4 milliseconds Feb 17 23:32:08 rivo volumio[3331]: info: sendMpdCommand playlistinfo took 3 milliseconds Feb 17 23:32:08 rivo volumio[3331]: verbose: ControllerMpd::parseTrackInfo Feb 17 23:32:08 rivo volumio[3331]: verbose: ControllerMpd::parseTrackInfo Feb 17 23:32:08 rivo volumio[3331]: verbose: ControllerMpd::parseTrackInfo Feb 17 23:32:08 rivo volumio[3331]: info: ControllerMpd::pushState Feb 17 23:32:08 rivo volumio[3331]: info: CoreCommandRouter::servicePushState Feb 17 23:32:08 rivo volumio[3331]: info: CorePlayQueue::getTrack 1 Feb 17 23:32:08 rivo volumio[3331]: verbose: STATE SERVICE {"status":"play","position":0,"seek":2677,"duration":234,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"1513 Kbps","isStreaming":false,"title":"163677066","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=qobuz://song/163677066","trackType":"qobuz"} Feb 17 23:32:08 rivo volumio[3331]: verbose: CURRENT POSITION 1 Feb 17 23:32:08 rivo volumio[3331]: info: CoreStateMachine::syncState stateService play Feb 17 23:32:08 rivo volumio[3331]: info: CoreStateMachine::syncState currentStatus pause Feb 17 23:32:08 rivo volumio[3331]: info: CoreStateMachine::pushState Feb 17 23:32:08 rivo volumio[3331]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 17 23:32:08 rivo volumio[3331]: info: CoreCommandRouter::volumioPushState Feb 17 23:32:08 rivo volumio[3331]: info: CoreCommandRouter::volumioGetState Feb 17 23:32:08 rivo volumio[3331]: info: MRS: Pushing multiroomSync output update for this device Feb 17 23:32:08 rivo volumio[3331]: info: MRS: Pushing multiroomSync output Feb 17 23:32:08 rivo volumio[3331]: info: ControllerMpd::pushState Feb 17 23:32:08 rivo volumio[3331]: info: CoreCommandRouter::servicePushState Feb 17 23:32:08 rivo volumio[3331]: info: CorePlayQueue::getTrack 1 Feb 17 23:32:08 rivo volumio[3331]: verbose: STATE SERVICE {"status":"play","position":0,"seek":2677,"duration":234,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"1513 Kbps","isStreaming":false,"title":"163677066","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=qobuz://song/163677066","trackType":"qobuz"} Feb 17 23:32:08 rivo volumio[3331]: verbose: CURRENT POSITION 1 Feb 17 23:32:08 rivo volumio[3331]: info: CoreStateMachine::syncState stateService play Feb 17 23:32:08 rivo volumio[3331]: info: CoreStateMachine::syncState currentStatus play Feb 17 23:32:08 rivo volumio[3331]: info: Received an update from plugin. extracting info from payload Feb 17 23:32:08 rivo volumio[3331]: info: CoreStateMachine::pushState Feb 17 23:32:08 rivo volumio[3331]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 17 23:32:08 rivo volumio[3331]: info: CoreCommandRouter::volumioPushState Feb 17 23:32:08 rivo volumio[3331]: info: CoreCommandRouter::volumioGetState Feb 17 23:32:08 rivo volumio[3331]: info: MRS: Pushing multiroomSync output update for this device Feb 17 23:32:08 rivo volumio[3331]: info: MRS: Pushing multiroomSync output Feb 17 23:32:08 rivo volumio[3331]: info: CoreStateMachine::pushState Feb 17 23:32:08 rivo volumio[3331]: info: CoreCommandRouter::volumioPushState Feb 17 23:32:08 rivo volumio[3331]: info: CoreCommandRouter::volumioGetState Feb 17 23:32:08 rivo volumio[3331]: info: MRS: Pushing multiroomSync output update for this device Feb 17 23:32:08 rivo volumio[3331]: info: MRS: Pushing multiroomSync output Feb 17 23:32:08 rivo volumio[3331]: info: ControllerMpd::pushState Feb 17 23:32:08 rivo volumio[3331]: info: CoreCommandRouter::servicePushState Feb 17 23:32:08 rivo volumio[3331]: info: CorePlayQueue::getTrack 1 Feb 17 23:32:08 rivo volumio[3331]: verbose: STATE SERVICE {"status":"play","position":0,"seek":2677,"duration":234,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"1513 Kbps","isStreaming":false,"title":"163677066","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=qobuz://song/163677066","trackType":"qobuz"} Feb 17 23:32:08 rivo volumio[3331]: verbose: CURRENT POSITION 1 Feb 17 23:32:08 rivo volumio[3331]: info: CoreStateMachine::syncState stateService play Feb 17 23:32:08 rivo volumio[3331]: info: CoreStateMachine::syncState currentStatus play Feb 17 23:32:08 rivo volumio[3331]: info: Received an update from plugin. extracting info from payload Feb 17 23:32:08 rivo volumio[3331]: info: CoreStateMachine::pushState Feb 17 23:32:08 rivo volumio[3331]: info: CoreCommandRouter::volumioPushState Feb 17 23:32:08 rivo volumio[3331]: info: CoreCommandRouter::volumioGetState Feb 17 23:32:08 rivo volumio[3331]: info: MRS: Pushing multiroomSync output update for this device Feb 17 23:32:08 rivo volumio[3331]: info: MRS: Pushing multiroomSync output Feb 17 23:32:08 rivo volumio[3331]: info: CoreStateMachine::pushState Feb 17 23:32:08 rivo volumio[3331]: info: CoreCommandRouter::volumioPushState Feb 17 23:32:08 rivo volumio[3331]: info: CoreCommandRouter::volumioGetState Feb 17 23:32:08 rivo volumio[3331]: info: MRS: Pushing multiroomSync output update for this device Feb 17 23:32:08 rivo volumio[3331]: info: MRS: Pushing multiroomSync output Feb 17 23:32:08 rivo volumio5-onboarding[4218]: time=2026-02-17T23:32:08.302+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.150:48512 @ 0x20a1260" state=STATUS_PLAYING positionMs=16364 volume=100 Feb 17 23:32:08 rivo volumio5-onboarding[4218]: time=2026-02-17T23:32:08.303+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.150:48512 @ 0x20a1260" id=qobuz://song/163677065 title="El Bueno Y El Malo" Feb 17 23:32:08 rivo volumio5-onboarding[4218]: time=2026-02-17T23:32:08.305+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.150:48512 @ 0x20a1260" state=STATUS_PLAYING positionMs=16364 volume=100 Feb 17 23:32:08 rivo volumio5-onboarding[4218]: time=2026-02-17T23:32:08.305+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.150:48512 @ 0x20a1260" id=qobuz://song/163677066 title="Hermosa Drive" Feb 17 23:32:08 rivo volumio5-onboarding[4218]: time=2026-02-17T23:32:08.306+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.150:48512 @ 0x20a1260" state=STATUS_PLAYING positionMs=16364 volume=100 Feb 17 23:32:08 rivo volumio5-onboarding[4218]: time=2026-02-17T23:32:08.307+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.150:48512 @ 0x20a1260" id=qobuz://song/163677066 title="Hermosa Drive" Feb 17 23:32:08 rivo volumio5-onboarding[4218]: time=2026-02-17T23:32:08.308+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.150:48512 @ 0x20a1260" state=STATUS_PLAYING positionMs=16364 volume=100 Feb 17 23:32:08 rivo volumio5-onboarding[4218]: time=2026-02-17T23:32:08.308+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.150:48512 @ 0x20a1260" id=qobuz://song/163677066 title="Hermosa Drive" Feb 17 23:32:08 rivo volumio5-onboarding[4218]: time=2026-02-17T23:32:08.309+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.150:48512 @ 0x20a1260" state=STATUS_PLAYING positionMs=16364 volume=100 Feb 17 23:32:08 rivo volumio5-onboarding[4218]: time=2026-02-17T23:32:08.310+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.150:48512 @ 0x20a1260" id=qobuz://song/163677066 title="Hermosa Drive" Feb 17 23:32:08 rivo volumio[3331]: info: ------------------------------ 116ms Feb 17 23:32:08 rivo volumio[3331]: info: ------------------------------ 115ms Feb 17 23:32:08 rivo volumio[3331]: info: ------------------------------ 116ms Feb 17 23:32:08 rivo volumio[3331]: info: Signalling Playback active due to playback status change Feb 17 23:32:08 rivo volumio[3331]: info: [LastFM] Current track has sufficient metadata: title (El Bueno Y El Malo) and artist (Hermanos Gutierrez) passed on explicitly Feb 17 23:32:08 rivo volumio[3331]: info: [LastFM] Current track has sufficient metadata: title (Hermosa Drive) and artist (Hermanos Gutierrez) passed on explicitly Feb 17 23:32:08 rivo volumio[3331]: info: MCU Signalled Playback Active Feb 17 23:32:08 rivo volumio[3331]: info: [LastFM] track info: {"success":true,"trackInfo":{"name":"Hermosa Drive","url":"https://www.last.fm/music/Hermanos+Gutierrez/_/Hermosa+Drive","duration":"0","streamable":{"#":"0","@":{"fulltrack":"0"}},"listeners":"1291","playcount":"4043","artist":{"name":"Hermanos Gutierrez","url":"https://www.last.fm/music/Hermanos+Gutierrez"},"userplaycount":"0","userloved":"0","toptags":""}} Feb 17 23:32:08 rivo volumio[3331]: info: [LastFM] track info: {"success":true,"trackInfo":{"name":"El Bueno Y El Malo","url":"https://www.last.fm/music/Hermanos+Gutierrez/_/El+Bueno+Y+El+Malo","duration":"0","streamable":{"#":"0","@":{"fulltrack":"0"}},"listeners":"1090","playcount":"3708","artist":{"name":"Hermanos Gutierrez","url":"https://www.last.fm/music/Hermanos+Gutierrez"},"userplaycount":"1","userloved":"0","toptags":""}} Feb 17 23:32:14 rivo volumio[3331]: info: CoreCommandRouter::volumioNext Feb 17 23:32:14 rivo volumio[3331]: info: CoreStateMachine::next Feb 17 23:32:14 rivo volumio[3331]: info: [1771360334252] ControllerQobuz::next Feb 17 23:32:14 rivo volumio[3331]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 17 23:32:14 rivo volumio[3331]: info: CoreStateMachine::next Feb 17 23:32:14 rivo volumio[3331]: info: CoreStateMachine::stop Feb 17 23:32:14 rivo volumio[3331]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 17 23:32:14 rivo volumio[3331]: info: CoreStateMachine::stPlaybackTimer Feb 17 23:32:14 rivo volumio[3331]: info: CoreStateMachine::updateTrackBlock Feb 17 23:32:14 rivo volumio[3331]: info: CorePlayQueue::getTrackBlock Feb 17 23:32:14 rivo volumio[3331]: info: CoreStateMachine::pushState Feb 17 23:32:14 rivo volumio[3331]: info: CorePlayQueue::getTrack 1 Feb 17 23:32:14 rivo volumio[3331]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 17 23:32:14 rivo volumio[3331]: info: CoreCommandRouter::volumioPushState Feb 17 23:32:14 rivo volumio[3331]: info: CoreCommandRouter::volumioGetState Feb 17 23:32:14 rivo volumio[3331]: info: CorePlayQueue::getTrack 1 Feb 17 23:32:14 rivo volumio[3331]: info: MRS: Pushing multiroomSync output update for this device Feb 17 23:32:14 rivo volumio[3331]: info: MRS: Pushing multiroomSync output Feb 17 23:32:14 rivo volumio[3331]: info: CoreStateMachine::serviceStop Feb 17 23:32:14 rivo volumio[3331]: info: CorePlayQueue::getTrack 1 Feb 17 23:32:14 rivo volumio[3331]: info: CoreCommandRouter::serviceStop Feb 17 23:32:14 rivo volumio[3331]: info: [1771360334270] ControllerQobuz::stop Feb 17 23:32:14 rivo volumio[3331]: info: CoreStateMachine::setConsumeUpdateService mpd Feb 17 23:32:14 rivo volumio[3331]: info: ControllerMpd::stop Feb 17 23:32:14 rivo volumio[3331]: verbose: ControllerMpd::sendMpdCommand stop Feb 17 23:32:14 rivo volumio5-onboarding[4218]: time=2026-02-17T23:32:14.273+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.150:48512 @ 0x20a1260" state=STATUS_STOPPED positionMs=0 volume=100 Feb 17 23:32:14 rivo volumio5-onboarding[4218]: time=2026-02-17T23:32:14.274+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.150:48512 @ 0x20a1260" id=qobuz://song/163677066 title="Hermosa Drive" Feb 17 23:32:14 rivo volumio[3331]: STREAMING PROXY: Client closed connection Feb 17 23:32:14 rivo volumio[3331]: STREAMING PROXY: Client closed connection during resume Feb 17 23:32:14 rivo volumio[3331]: info: Feb 17 23:32:14 rivo volumio[3331]: ---------------------------- MPD announces state update: player Feb 17 23:32:14 rivo volumio[3331]: info: sendMpdCommand stop took 42 milliseconds Feb 17 23:32:14 rivo volumio[3331]: info: ControllerMpd::getState Feb 17 23:32:14 rivo volumio[3331]: verbose: ControllerMpd::sendMpdCommand status Feb 17 23:32:14 rivo volumio[3331]: info: CoreStateMachine::play index undefined Feb 17 23:32:14 rivo volumio[3331]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 17 23:32:14 rivo volumio[3331]: info: CorePlayQueue::getTrack 2 Feb 17 23:32:14 rivo volumio[3331]: info: CoreStateMachine::startPlaybackTimer Feb 17 23:32:14 rivo volumio[3331]: info: CorePlayQueue::getTrack 2 Feb 17 23:32:14 rivo volumio[3331]: info: [1771360334320] ControllerQobuz::clearAddPlayTrack Feb 17 23:32:14 rivo volumio[3331]: verbose: ControllerMpd::sendMpdCommand stop Feb 17 23:32:14 rivo volumio[3331]: info: CoreStateMachine::updateTrackBlock Feb 17 23:32:14 rivo volumio[3331]: info: CorePlayQueue::getTrackBlock Feb 17 23:32:14 rivo volumio[3331]: info: Feb 17 23:32:14 rivo volumio[3331]: ---------------------------- MPD announces state update: player Feb 17 23:32:14 rivo volumio[3331]: info: ControllerMpd::getState Feb 17 23:32:14 rivo volumio[3331]: verbose: ControllerMpd::sendMpdCommand status Feb 17 23:32:14 rivo volumio[3331]: info: Feb 17 23:32:14 rivo volumio[3331]: ---------------------------- MPD announces state update: player Feb 17 23:32:14 rivo volumio[3331]: info: ControllerMpd::getState Feb 17 23:32:14 rivo volumio[3331]: verbose: ControllerMpd::sendMpdCommand status Feb 17 23:32:14 rivo volumio[3331]: info: sendMpdCommand status took 18 milliseconds Feb 17 23:32:14 rivo volumio[3331]: info: sendMpdCommand stop took 11 milliseconds Feb 17 23:32:14 rivo volumio[3331]: info: sendMpdCommand status took 7 milliseconds Feb 17 23:32:14 rivo volumio[3331]: verbose: ControllerMpd::parseState Feb 17 23:32:14 rivo volumio[3331]: verbose: ControllerMpd::sendMpdCommand playlistinfo Feb 17 23:32:14 rivo volumio[3331]: verbose: ControllerMpd::sendMpdCommand clear Feb 17 23:32:14 rivo volumio[3331]: verbose: ControllerMpd::parseState Feb 17 23:32:14 rivo volumio[3331]: verbose: ControllerMpd::sendMpdCommand playlistinfo Feb 17 23:32:14 rivo volumio[3331]: info: Feb 17 23:32:14 rivo volumio[3331]: ---------------------------- MPD announces system playlist update Feb 17 23:32:14 rivo volumio[3331]: info: Ignoring MPD Status Update Feb 17 23:32:14 rivo volumio[3331]: info: sendMpdCommand status took 14 milliseconds Feb 17 23:32:14 rivo volumio[3331]: info: sendMpdCommand playlistinfo took 8 milliseconds Feb 17 23:32:14 rivo volumio[3331]: info: sendMpdCommand clear took 8 milliseconds Feb 17 23:32:14 rivo volumio[3331]: info: sendMpdCommand playlistinfo took 7 milliseconds Feb 17 23:32:14 rivo volumio[3331]: verbose: ControllerMpd::parseState Feb 17 23:32:14 rivo volumio[3331]: verbose: ControllerMpd::sendMpdCommand playlistinfo Feb 17 23:32:14 rivo volumio[3331]: verbose: ControllerMpd::parseTrackInfo Feb 17 23:32:14 rivo volumio[3331]: verbose: ControllerMpd::sendMpdCommand load "http://127.0.0.1:3245?data=qobuz://song/163677067" Feb 17 23:32:14 rivo volumio[3331]: verbose: ControllerMpd::parseTrackInfo Feb 17 23:32:14 rivo volumio[3331]: info: ControllerMpd::pushState Feb 17 23:32:14 rivo volumio[3331]: info: CoreCommandRouter::servicePushState Feb 17 23:32:14 rivo volumio[3331]: info: CoreStateMachine::pushState Feb 17 23:32:14 rivo volumio[3331]: info: CorePlayQueue::getTrack 2 Feb 17 23:32:14 rivo volumio[3331]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 17 23:32:14 rivo volumio[3331]: info: CoreCommandRouter::volumioPushState Feb 17 23:32:14 rivo volumio[3331]: info: CoreCommandRouter::volumioGetState Feb 17 23:32:14 rivo volumio[3331]: info: CorePlayQueue::getTrack 2 Feb 17 23:32:14 rivo volumio[3331]: info: MRS: Pushing multiroomSync output update for this device Feb 17 23:32:14 rivo volumio[3331]: info: MRS: Pushing multiroomSync output Feb 17 23:32:14 rivo volumio[3331]: info: CorePlayQueue::getTrack 2 Feb 17 23:32:14 rivo volumio[3331]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current qobuz Received mpd Feb 17 23:32:14 rivo volumio[3331]: error: ControllerMpd::pushError: TypeError: Cannot read property 'split' of undefined Feb 17 23:32:14 rivo volumio[3331]: STREAMING PROXY: Handling url /?data=qobuz://song/163677067 Feb 17 23:32:14 rivo volumio5-onboarding[4218]: time=2026-02-17T23:32:14.381+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.150:48512 @ 0x20a1260" state=STATUS_STOPPED positionMs=0 volume=100 Feb 17 23:32:14 rivo volumio5-onboarding[4218]: time=2026-02-17T23:32:14.382+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.150:48512 @ 0x20a1260" id=qobuz://song/163677067 title="Los Chicos Tristes" Feb 17 23:32:14 rivo volumio[3331]: info: ------------------------------ 82ms Feb 17 23:32:14 rivo volumio[3331]: info: ------------------------------ 70ms Feb 17 23:32:14 rivo volumio[3331]: info: Feb 17 23:32:14 rivo volumio[3331]: ---------------------------- MPD announces system playlist update Feb 17 23:32:14 rivo volumio[3331]: info: Ignoring MPD Status Update Feb 17 23:32:14 rivo volumio[3331]: info: Feb 17 23:32:14 rivo volumio[3331]: ---------------------------- MPD announces system playlist update Feb 17 23:32:14 rivo volumio[3331]: info: Ignoring MPD Status Update Feb 17 23:32:14 rivo volumio[3331]: error: updateQueue error: null Feb 17 23:32:14 rivo volumio[3331]: info: ------------------------------ 71ms Feb 17 23:32:14 rivo volumio[3331]: info: sendMpdCommand playlistinfo took 66 milliseconds Feb 17 23:32:14 rivo volumio[3331]: verbose: ControllerMpd::parseTrackInfo Feb 17 23:32:14 rivo volumio[3331]: error: ControllerMpd::pushError: TypeError: Cannot read property 'split' of undefined Feb 17 23:32:14 rivo volumio[3331]: info: ------------------------------ 88ms Feb 17 23:32:14 rivo volumio[3331]: info: MCU Signalled Playback Inactive Feb 17 23:32:14 rivo volumio[3331]: info: Executing endpoint getStreamUrlqobuz Feb 17 23:32:14 rivo volumio[3331]: info: CoreCommandRouter::executeOnPlugin: qobuz , getStreamUrlAPI Feb 17 23:32:14 rivo volumio[3331]: info: getStreamUrl took 301 milliseconds Feb 17 23:32:14 rivo volumio[3331]: STREAMING PROXY: Got real url: https://streaming-qobuz-std.akamaized.net/file?uid=4637524&eid=163677067&fmt=7&profile=raw&app_id=539451548&cid=3766108&etsp=1771363934&hmac=-zwF0U1XNNq2RfD8f_VYljgFid4 Feb 17 23:32:14 rivo volumio[3331]: STREAMING PROXY: Requesting upstream with range: none Feb 17 23:32:16 rivo volumio[3331]: STREAMING PROXY: Upstream status code: 200 Feb 17 23:32:16 rivo volumio[3331]: STREAMING PROXY: Client closed connection Feb 17 23:32:16 rivo volumio[3331]: STREAMING PROXY: Upstream closed. Received 15642 bytes Feb 17 23:32:16 rivo volumio[3331]: STREAMING PROXY: Incomplete transfer. Expected 43777602, got 15642 Feb 17 23:32:16 rivo volumio[3331]: STREAMING PROXY: Retrying with range: bytes=15642- (attempt 1) Feb 17 23:32:16 rivo volumio[3331]: verbose: ControllerMpd::sendMpdCommand add "http://127.0.0.1:3245?data=qobuz://song/163677067" Feb 17 23:32:16 rivo volumio[3331]: error: updateQueue error: null Feb 17 23:32:16 rivo volumio[3331]: error: updateQueue error: null Feb 17 23:32:16 rivo volumio[3331]: info: Feb 17 23:32:16 rivo volumio[3331]: ---------------------------- MPD announces system playlist update Feb 17 23:32:16 rivo volumio[3331]: info: Ignoring MPD Status Update Feb 17 23:32:16 rivo volumio[3331]: info: ------------------------------ 1786ms Feb 17 23:32:16 rivo volumio[3331]: info: ------------------------------ 1785ms Feb 17 23:32:16 rivo volumio[3331]: info: sendMpdCommand add "http://127.0.0.1:3245?data=qobuz://song/163677067" took 4 milliseconds Feb 17 23:32:16 rivo volumio[3331]: info: CoreStateMachine::setConsumeUpdateService mpd Feb 17 23:32:16 rivo volumio[3331]: verbose: ControllerMpd::sendMpdCommand play Feb 17 23:32:16 rivo volumio[3331]: info: Feb 17 23:32:16 rivo volumio[3331]: ---------------------------- MPD announces system playlist update Feb 17 23:32:16 rivo volumio[3331]: info: Ignoring MPD Status Update Feb 17 23:32:16 rivo volumio[3331]: STREAMING PROXY: Handling url /?data=qobuz://song/163677067 Feb 17 23:32:16 rivo volumio[3331]: info: Feb 17 23:32:16 rivo volumio[3331]: ---------------------------- MPD announces system playlist update Feb 17 23:32:16 rivo volumio[3331]: info: Ignoring MPD Status Update Feb 17 23:32:16 rivo volumio[3331]: info: ------------------------------ 10ms Feb 17 23:32:16 rivo volumio[3331]: info: sendMpdCommand play took 8 milliseconds Feb 17 23:32:16 rivo volumio[3331]: info: ------------------------------ 6ms Feb 17 23:32:16 rivo volumio[3331]: info: ------------------------------ 5ms Feb 17 23:32:16 rivo volumio[3331]: info: Executing endpoint getStreamUrlqobuz Feb 17 23:32:16 rivo volumio[3331]: info: CoreCommandRouter::executeOnPlugin: qobuz , getStreamUrlAPI Feb 17 23:32:16 rivo volumio[3331]: info: getStreamUrl took 296 milliseconds Feb 17 23:32:16 rivo volumio[3331]: STREAMING PROXY: Got real url: https://streaming-qobuz-std.akamaized.net/file?uid=4637524&eid=163677067&fmt=7&profile=raw&app_id=539451548&cid=3766108&etsp=1771363936&hmac=LfFyY-C6HKRwWu4gEebd-sian6E Feb 17 23:32:16 rivo volumio[3331]: STREAMING PROXY: Requesting upstream with range: none Feb 17 23:32:16 rivo volumio[3331]: STREAMING PROXY: Upstream status code: 200 Feb 17 23:32:16 rivo volumio[3331]: info: Feb 17 23:32:16 rivo volumio[3331]: ---------------------------- MPD announces state update: player Feb 17 23:32:16 rivo volumio[3331]: info: ControllerMpd::getState Feb 17 23:32:16 rivo volumio[3331]: verbose: ControllerMpd::sendMpdCommand status Feb 17 23:32:16 rivo volumio[3331]: info: Feb 17 23:32:16 rivo volumio[3331]: ---------------------------- MPD announces state update: player Feb 17 23:32:16 rivo volumio[3331]: info: ControllerMpd::getState Feb 17 23:32:16 rivo volumio[3331]: verbose: ControllerMpd::sendMpdCommand status Feb 17 23:32:16 rivo volumio[3331]: info: Feb 17 23:32:16 rivo volumio[3331]: ---------------------------- MPD announces state update: player Feb 17 23:32:16 rivo volumio[3331]: info: ControllerMpd::getState Feb 17 23:32:16 rivo volumio[3331]: verbose: ControllerMpd::sendMpdCommand status Feb 17 23:32:16 rivo volumio[3331]: info: sendMpdCommand status took 11 milliseconds Feb 17 23:32:16 rivo volumio[3331]: verbose: ControllerMpd::parseState Feb 17 23:32:16 rivo volumio[3331]: verbose: ControllerMpd::sendMpdCommand playlistinfo Feb 17 23:32:16 rivo volumio[3331]: info: Feb 17 23:32:16 rivo volumio[3331]: ---------------------------- MPD announces state update: player Feb 17 23:32:16 rivo volumio[3331]: info: ControllerMpd::getState Feb 17 23:32:16 rivo volumio[3331]: verbose: ControllerMpd::sendMpdCommand status Feb 17 23:32:16 rivo volumio[3331]: info: sendMpdCommand status took 16 milliseconds Feb 17 23:32:16 rivo volumio[3331]: info: sendMpdCommand status took 15 milliseconds Feb 17 23:32:16 rivo volumio[3331]: info: sendMpdCommand playlistinfo took 6 milliseconds Feb 17 23:32:16 rivo volumio[3331]: verbose: ControllerMpd::parseState Feb 17 23:32:16 rivo volumio[3331]: verbose: ControllerMpd::sendMpdCommand playlistinfo Feb 17 23:32:16 rivo volumio[3331]: verbose: ControllerMpd::parseState Feb 17 23:32:16 rivo volumio[3331]: verbose: ControllerMpd::sendMpdCommand playlistinfo Feb 17 23:32:16 rivo volumio[3331]: verbose: ControllerMpd::parseTrackInfo Feb 17 23:32:16 rivo volumio[3331]: info: ControllerMpd::pushState Feb 17 23:32:16 rivo volumio[3331]: info: CoreCommandRouter::servicePushState Feb 17 23:32:16 rivo volumio[3331]: info: CorePlayQueue::getTrack 2 Feb 17 23:32:16 rivo volumio[3331]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":229,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"163677067","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=qobuz://song/163677067","trackType":"qobuz"} Feb 17 23:32:16 rivo volumio[3331]: verbose: CURRENT POSITION 2 Feb 17 23:32:16 rivo volumio[3331]: info: CoreStateMachine::syncState stateService play Feb 17 23:32:16 rivo volumio[3331]: info: CoreStateMachine::syncState currentStatus stop Feb 17 23:32:16 rivo volumio[3331]: info: ------------------------------ 28ms Feb 17 23:32:16 rivo volumio[3331]: info: Feb 17 23:32:16 rivo volumio[3331]: ---------------------------- MPD announces state update: player Feb 17 23:32:16 rivo volumio[3331]: info: ControllerMpd::getState Feb 17 23:32:16 rivo volumio[3331]: verbose: ControllerMpd::sendMpdCommand status Feb 17 23:32:16 rivo volumio[3331]: info: Feb 17 23:32:16 rivo volumio[3331]: ---------------------------- MPD announces state update: player Feb 17 23:32:16 rivo volumio[3331]: info: ControllerMpd::getState Feb 17 23:32:16 rivo volumio[3331]: verbose: ControllerMpd::sendMpdCommand status Feb 17 23:32:16 rivo volumio[3331]: info: sendMpdCommand status took 18 milliseconds Feb 17 23:32:16 rivo volumio[3331]: info: sendMpdCommand playlistinfo took 16 milliseconds Feb 17 23:32:16 rivo volumio[3331]: info: sendMpdCommand playlistinfo took 15 milliseconds Feb 17 23:32:16 rivo volumio[3331]: info: sendMpdCommand status took 10 milliseconds Feb 17 23:32:16 rivo volumio[3331]: info: sendMpdCommand status took 9 milliseconds Feb 17 23:32:16 rivo volumio[3331]: verbose: ControllerMpd::parseState Feb 17 23:32:16 rivo volumio[3331]: verbose: ControllerMpd::sendMpdCommand playlistinfo Feb 17 23:32:16 rivo volumio[3331]: verbose: ControllerMpd::parseTrackInfo Feb 17 23:32:16 rivo volumio[3331]: verbose: ControllerMpd::parseTrackInfo Feb 17 23:32:16 rivo volumio[3331]: verbose: ControllerMpd::parseState Feb 17 23:32:16 rivo volumio[3331]: verbose: ControllerMpd::sendMpdCommand playlistinfo Feb 17 23:32:16 rivo volumio[3331]: verbose: ControllerMpd::parseState Feb 17 23:32:16 rivo volumio[3331]: verbose: ControllerMpd::sendMpdCommand playlistinfo Feb 17 23:32:16 rivo volumio[3331]: info: ControllerMpd::pushState Feb 17 23:32:16 rivo volumio[3331]: info: CoreCommandRouter::servicePushState Feb 17 23:32:16 rivo volumio[3331]: info: CorePlayQueue::getTrack 2 Feb 17 23:32:16 rivo volumio[3331]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":229,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"163677067","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=qobuz://song/163677067","trackType":"qobuz"} Feb 17 23:32:16 rivo volumio[3331]: verbose: CURRENT POSITION 2 Feb 17 23:32:16 rivo volumio[3331]: info: CoreStateMachine::syncState stateService play Feb 17 23:32:16 rivo volumio[3331]: info: CoreStateMachine::syncState currentStatus play Feb 17 23:32:16 rivo volumio[3331]: info: Received an update from plugin. extracting info from payload Feb 17 23:32:16 rivo volumio[3331]: info: CoreStateMachine::pushState Feb 17 23:32:16 rivo volumio[3331]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 17 23:32:16 rivo volumio[3331]: info: CoreCommandRouter::volumioPushState Feb 17 23:32:16 rivo volumio[3331]: info: CoreCommandRouter::volumioGetState Feb 17 23:32:16 rivo volumio[3331]: info: MRS: Pushing multiroomSync output update for this device Feb 17 23:32:16 rivo volumio[3331]: info: MRS: Pushing multiroomSync output Feb 17 23:32:16 rivo volumio[3331]: info: CoreStateMachine::pushState Feb 17 23:32:16 rivo volumio[3331]: info: CoreCommandRouter::volumioPushState Feb 17 23:32:16 rivo volumio[3331]: info: CoreCommandRouter::volumioGetState Feb 17 23:32:16 rivo volumio[3331]: info: MRS: Pushing multiroomSync output update for this device Feb 17 23:32:16 rivo volumio[3331]: info: MRS: Pushing multiroomSync output Feb 17 23:32:16 rivo volumio[3331]: info: ControllerMpd::pushState Feb 17 23:32:16 rivo volumio[3331]: info: CoreCommandRouter::servicePushState Feb 17 23:32:16 rivo volumio[3331]: info: CorePlayQueue::getTrack 2 Feb 17 23:32:16 rivo volumio[3331]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":229,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"163677067","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=qobuz://song/163677067","trackType":"qobuz"} Feb 17 23:32:16 rivo volumio[3331]: verbose: CURRENT POSITION 2 Feb 17 23:32:16 rivo volumio[3331]: info: CoreStateMachine::syncState stateService play Feb 17 23:32:16 rivo volumio[3331]: info: CoreStateMachine::syncState currentStatus play Feb 17 23:32:16 rivo volumio[3331]: info: Received an update from plugin. extracting info from payload Feb 17 23:32:16 rivo volumio[3331]: info: CoreStateMachine::pushState Feb 17 23:32:16 rivo volumio[3331]: info: CoreCommandRouter::volumioPushState Feb 17 23:32:16 rivo volumio[3331]: info: CoreCommandRouter::volumioGetState Feb 17 23:32:16 rivo volumio[3331]: info: MRS: Pushing multiroomSync output update for this device Feb 17 23:32:16 rivo volumio[3331]: info: MRS: Pushing multiroomSync output Feb 17 23:32:16 rivo volumio[3331]: info: CoreStateMachine::pushState Feb 17 23:32:16 rivo volumio[3331]: info: CoreCommandRouter::volumioPushState Feb 17 23:32:16 rivo volumio[3331]: info: CoreCommandRouter::volumioGetState Feb 17 23:32:16 rivo volumio[3331]: info: MRS: Pushing multiroomSync output update for this device Feb 17 23:32:16 rivo volumio[3331]: info: MRS: Pushing multiroomSync output Feb 17 23:32:16 rivo volumio5-onboarding[4218]: time=2026-02-17T23:32:16.718+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.150:48512 @ 0x20a1260" state=STATUS_PLAYING positionMs=0 volume=100 Feb 17 23:32:16 rivo volumio5-onboarding[4218]: time=2026-02-17T23:32:16.718+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.150:48512 @ 0x20a1260" id=qobuz://song/163677067 title="Los Chicos Tristes" Feb 17 23:32:16 rivo volumio5-onboarding[4218]: time=2026-02-17T23:32:16.720+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.150:48512 @ 0x20a1260" state=STATUS_PLAYING positionMs=0 volume=100 Feb 17 23:32:16 rivo volumio5-onboarding[4218]: time=2026-02-17T23:32:16.720+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.150:48512 @ 0x20a1260" id=qobuz://song/163677067 title="Los Chicos Tristes" Feb 17 23:32:16 rivo volumio5-onboarding[4218]: time=2026-02-17T23:32:16.722+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.150:48512 @ 0x20a1260" state=STATUS_PLAYING positionMs=0 volume=100 Feb 17 23:32:16 rivo volumio5-onboarding[4218]: time=2026-02-17T23:32:16.722+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.150:48512 @ 0x20a1260" id=qobuz://song/163677067 title="Los Chicos Tristes" Feb 17 23:32:16 rivo volumio5-onboarding[4218]: time=2026-02-17T23:32:16.723+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.150:48512 @ 0x20a1260" state=STATUS_PLAYING positionMs=0 volume=100 Feb 17 23:32:16 rivo volumio5-onboarding[4218]: time=2026-02-17T23:32:16.724+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.150:48512 @ 0x20a1260" id=qobuz://song/163677067 title="Los Chicos Tristes" Feb 17 23:32:16 rivo volumio[3331]: info: ------------------------------ 123ms Feb 17 23:32:16 rivo volumio[3331]: info: ------------------------------ 122ms Feb 17 23:32:16 rivo volumio[3331]: info: sendMpdCommand playlistinfo took 89 milliseconds Feb 17 23:32:16 rivo volumio[3331]: info: sendMpdCommand playlistinfo took 89 milliseconds Feb 17 23:32:16 rivo volumio[3331]: info: sendMpdCommand playlistinfo took 89 milliseconds Feb 17 23:32:16 rivo volumio[3331]: verbose: ControllerMpd::parseTrackInfo Feb 17 23:32:16 rivo volumio[3331]: verbose: ControllerMpd::parseTrackInfo Feb 17 23:32:16 rivo volumio[3331]: verbose: ControllerMpd::parseTrackInfo Feb 17 23:32:16 rivo volumio[3331]: info: ControllerMpd::pushState Feb 17 23:32:16 rivo volumio[3331]: info: CoreCommandRouter::servicePushState Feb 17 23:32:16 rivo volumio[3331]: info: CorePlayQueue::getTrack 2 Feb 17 23:32:16 rivo volumio[3331]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":229,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"163677067","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=qobuz://song/163677067","trackType":"qobuz"} Feb 17 23:32:16 rivo volumio[3331]: verbose: CURRENT POSITION 2 Feb 17 23:32:16 rivo volumio[3331]: info: CoreStateMachine::syncState stateService play Feb 17 23:32:16 rivo volumio[3331]: info: CoreStateMachine::syncState currentStatus play Feb 17 23:32:16 rivo volumio[3331]: info: Received an update from plugin. extracting info from payload Feb 17 23:32:16 rivo volumio[3331]: info: CoreStateMachine::pushState Feb 17 23:32:16 rivo volumio[3331]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 17 23:32:16 rivo volumio[3331]: info: CoreCommandRouter::volumioPushState Feb 17 23:32:16 rivo volumio[3331]: info: CoreCommandRouter::volumioGetState Feb 17 23:32:16 rivo volumio[3331]: info: MRS: Pushing multiroomSync output update for this device Feb 17 23:32:16 rivo volumio[3331]: info: MRS: Pushing multiroomSync output Feb 17 23:32:16 rivo volumio[3331]: info: CoreStateMachine::pushState Feb 17 23:32:16 rivo volumio[3331]: info: CoreCommandRouter::volumioPushState Feb 17 23:32:16 rivo volumio[3331]: info: CoreCommandRouter::volumioGetState Feb 17 23:32:16 rivo volumio[3331]: info: MRS: Pushing multiroomSync output update for this device Feb 17 23:32:16 rivo volumio[3331]: info: MRS: Pushing multiroomSync output Feb 17 23:32:16 rivo volumio[3331]: info: ControllerMpd::pushState Feb 17 23:32:16 rivo volumio[3331]: info: CoreCommandRouter::servicePushState Feb 17 23:32:16 rivo volumio[3331]: info: CorePlayQueue::getTrack 2 Feb 17 23:32:16 rivo volumio[3331]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":229,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"163677067","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=qobuz://song/163677067","trackType":"qobuz"} Feb 17 23:32:16 rivo volumio[3331]: verbose: CURRENT POSITION 2 Feb 17 23:32:16 rivo volumio[3331]: info: CoreStateMachine::syncState stateService play Feb 17 23:32:16 rivo volumio[3331]: info: CoreStateMachine::syncState currentStatus play Feb 17 23:32:16 rivo volumio[3331]: info: Received an update from plugin. extracting info from payload Feb 17 23:32:16 rivo volumio[3331]: info: CoreStateMachine::pushState Feb 17 23:32:16 rivo volumio[3331]: info: CoreCommandRouter::volumioPushState Feb 17 23:32:16 rivo volumio[3331]: info: CoreCommandRouter::volumioGetState Feb 17 23:32:16 rivo volumio[3331]: info: MRS: Pushing multiroomSync output update for this device Feb 17 23:32:16 rivo volumio[3331]: info: MRS: Pushing multiroomSync output Feb 17 23:32:16 rivo volumio[3331]: info: CoreStateMachine::pushState Feb 17 23:32:16 rivo volumio[3331]: info: CoreCommandRouter::volumioPushState Feb 17 23:32:16 rivo volumio[3331]: info: CoreCommandRouter::volumioGetState Feb 17 23:32:16 rivo volumio[3331]: info: MRS: Pushing multiroomSync output update for this device Feb 17 23:32:16 rivo volumio[3331]: info: MRS: Pushing multiroomSync output Feb 17 23:32:16 rivo volumio[3331]: info: ControllerMpd::pushState Feb 17 23:32:16 rivo volumio[3331]: info: CoreCommandRouter::servicePushState Feb 17 23:32:16 rivo volumio[3331]: info: CorePlayQueue::getTrack 2 Feb 17 23:32:16 rivo volumio[3331]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":229,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"163677067","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=qobuz://song/163677067","trackType":"qobuz"} Feb 17 23:32:16 rivo volumio[3331]: verbose: CURRENT POSITION 2 Feb 17 23:32:16 rivo volumio[3331]: info: CoreStateMachine::syncState stateService play Feb 17 23:32:16 rivo volumio[3331]: info: CoreStateMachine::syncState currentStatus play Feb 17 23:32:16 rivo volumio[3331]: info: Received an update from plugin. extracting info from payload Feb 17 23:32:16 rivo volumio[3331]: info: CoreStateMachine::pushState Feb 17 23:32:16 rivo volumio[3331]: info: CoreCommandRouter::volumioPushState Feb 17 23:32:16 rivo volumio[3331]: info: CoreCommandRouter::volumioGetState Feb 17 23:32:16 rivo volumio[3331]: info: MRS: Pushing multiroomSync output update for this device Feb 17 23:32:16 rivo volumio[3331]: info: MRS: Pushing multiroomSync output Feb 17 23:32:16 rivo volumio[3331]: info: CoreStateMachine::pushState Feb 17 23:32:16 rivo volumio[3331]: info: CoreCommandRouter::volumioPushState Feb 17 23:32:16 rivo volumio[3331]: info: CoreCommandRouter::volumioGetState Feb 17 23:32:16 rivo volumio[3331]: info: MRS: Pushing multiroomSync output update for this device Feb 17 23:32:16 rivo volumio[3331]: info: MRS: Pushing multiroomSync output Feb 17 23:32:16 rivo volumio5-onboarding[4218]: time=2026-02-17T23:32:16.841+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.150:48512 @ 0x20a1260" state=STATUS_PLAYING positionMs=194 volume=100 Feb 17 23:32:16 rivo volumio5-onboarding[4218]: time=2026-02-17T23:32:16.841+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.150:48512 @ 0x20a1260" id=qobuz://song/163677067 title="Los Chicos Tristes" Feb 17 23:32:16 rivo volumio5-onboarding[4218]: time=2026-02-17T23:32:16.850+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.150:48512 @ 0x20a1260" state=STATUS_PLAYING positionMs=194 volume=100 Feb 17 23:32:16 rivo volumio5-onboarding[4218]: time=2026-02-17T23:32:16.851+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.150:48512 @ 0x20a1260" id=qobuz://song/163677067 title="Los Chicos Tristes" Feb 17 23:32:16 rivo volumio5-onboarding[4218]: time=2026-02-17T23:32:16.852+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.150:48512 @ 0x20a1260" state=STATUS_PLAYING positionMs=194 volume=100 Feb 17 23:32:16 rivo volumio5-onboarding[4218]: time=2026-02-17T23:32:16.853+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.150:48512 @ 0x20a1260" id=qobuz://song/163677067 title="Los Chicos Tristes" Feb 17 23:32:16 rivo volumio5-onboarding[4218]: time=2026-02-17T23:32:16.853+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.150:48512 @ 0x20a1260" state=STATUS_PLAYING positionMs=194 volume=100 Feb 17 23:32:16 rivo volumio5-onboarding[4218]: time=2026-02-17T23:32:16.854+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.150:48512 @ 0x20a1260" id=qobuz://song/163677067 title="Los Chicos Tristes" Feb 17 23:32:16 rivo volumio5-onboarding[4218]: time=2026-02-17T23:32:16.855+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.150:48512 @ 0x20a1260" state=STATUS_PLAYING positionMs=194 volume=100 Feb 17 23:32:16 rivo volumio5-onboarding[4218]: time=2026-02-17T23:32:16.855+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.150:48512 @ 0x20a1260" id=qobuz://song/163677067 title="Los Chicos Tristes" Feb 17 23:32:16 rivo volumio5-onboarding[4218]: time=2026-02-17T23:32:16.856+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.150:48512 @ 0x20a1260" state=STATUS_PLAYING positionMs=194 volume=100 Feb 17 23:32:16 rivo volumio5-onboarding[4218]: time=2026-02-17T23:32:16.856+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.150:48512 @ 0x20a1260" id=qobuz://song/163677067 title="Los Chicos Tristes" Feb 17 23:32:16 rivo volumio[3331]: info: ------------------------------ 258ms Feb 17 23:32:16 rivo volumio[3331]: info: ------------------------------ 248ms Feb 17 23:32:16 rivo volumio[3331]: info: ------------------------------ 249ms Feb 17 23:32:16 rivo volumio[3331]: info: Signalling Playback active due to playback status change Feb 17 23:32:16 rivo volumio[3331]: info: [LastFM] Current track has sufficient metadata: title (Los Chicos Tristes) and artist (Hermanos Gutierrez) passed on explicitly Feb 17 23:32:17 rivo volumio[3331]: info: MCU Signalled Playback Active Feb 17 23:32:17 rivo volumio[3331]: STREAMING PROXY: Resuming with range: bytes=15642- Feb 17 23:32:17 rivo volumio[3331]: info: [LastFM] track info: {"success":true,"trackInfo":{"name":"Los Chicos Tristes","url":"https://www.last.fm/music/Hermanos+Gutierrez/_/Los+Chicos+Tristes","duration":"0","streamable":{"#":"0","@":{"fulltrack":"0"}},"listeners":"918","playcount":"3260","artist":{"name":"Hermanos Gutierrez","url":"https://www.last.fm/music/Hermanos+Gutierrez"},"userplaycount":"0","userloved":"0","toptags":""}} Feb 17 23:32:17 rivo volumio[3331]: STREAMING PROXY: Resume upstream status code: 206 Feb 17 23:32:28 rivo volumio[3331]: info: CoreCommandRouter::volumioPause Feb 17 23:32:28 rivo volumio[3331]: info: CoreStateMachine::pause Feb 17 23:32:28 rivo volumio[3331]: info: CoreStateMachine::stPlaybackTimer Feb 17 23:32:28 rivo volumio[3331]: info: CoreStateMachine::servicePause Feb 17 23:32:28 rivo volumio[3331]: info: CorePlayQueue::getTrack 2 Feb 17 23:32:28 rivo volumio[3331]: info: CoreCommandRouter::servicePause Feb 17 23:32:28 rivo volumio[3331]: info: [1771360348486] ControllerQobuz::pause Feb 17 23:32:28 rivo volumio[3331]: info: CoreStateMachine::setConsumeUpdateService mpd Feb 17 23:32:28 rivo volumio[3331]: info: ControllerMpd::pause Feb 17 23:32:28 rivo volumio[3331]: verbose: ControllerMpd::sendMpdCommand pause Feb 17 23:32:28 rivo volumio[3331]: info: Feb 17 23:32:28 rivo volumio[3331]: ---------------------------- MPD announces state update: player Feb 17 23:32:28 rivo volumio[3331]: info: sendMpdCommand pause took 5 milliseconds Feb 17 23:32:28 rivo volumio[3331]: info: ControllerMpd::getState Feb 17 23:32:28 rivo volumio[3331]: verbose: ControllerMpd::sendMpdCommand status Feb 17 23:32:28 rivo volumio[3331]: info: Feb 17 23:32:28 rivo volumio[3331]: ---------------------------- MPD announces state update: player Feb 17 23:32:28 rivo volumio[3331]: info: ControllerMpd::getState Feb 17 23:32:28 rivo volumio[3331]: verbose: ControllerMpd::sendMpdCommand status Feb 17 23:32:28 rivo volumio[3331]: info: sendMpdCommand status took 4 milliseconds Feb 17 23:32:28 rivo volumio[3331]: info: sendMpdCommand status took 1 milliseconds Feb 17 23:32:28 rivo volumio[3331]: verbose: ControllerMpd::parseState Feb 17 23:32:28 rivo volumio[3331]: verbose: ControllerMpd::sendMpdCommand playlistinfo Feb 17 23:32:28 rivo volumio[3331]: verbose: ControllerMpd::parseState Feb 17 23:32:28 rivo volumio[3331]: verbose: ControllerMpd::sendMpdCommand playlistinfo Feb 17 23:32:28 rivo volumio[3331]: info: Feb 17 23:32:28 rivo volumio[3331]: ---------------------------- MPD announces state update: player Feb 17 23:32:28 rivo volumio[3331]: info: ControllerMpd::getState Feb 17 23:32:28 rivo volumio[3331]: verbose: ControllerMpd::sendMpdCommand status Feb 17 23:32:28 rivo volumio[3331]: info: sendMpdCommand playlistinfo took 4 milliseconds Feb 17 23:32:28 rivo volumio[3331]: info: sendMpdCommand playlistinfo took 5 milliseconds Feb 17 23:32:28 rivo volumio[3331]: info: sendMpdCommand status took 2 milliseconds Feb 17 23:32:28 rivo volumio[3331]: verbose: ControllerMpd::parseTrackInfo Feb 17 23:32:28 rivo volumio[3331]: verbose: ControllerMpd::parseTrackInfo Feb 17 23:32:28 rivo volumio[3331]: verbose: ControllerMpd::parseState Feb 17 23:32:28 rivo volumio[3331]: verbose: ControllerMpd::sendMpdCommand playlistinfo Feb 17 23:32:28 rivo volumio[3331]: info: ControllerMpd::pushState Feb 17 23:32:28 rivo volumio[3331]: info: CoreCommandRouter::servicePushState Feb 17 23:32:28 rivo volumio[3331]: info: CorePlayQueue::getTrack 2 Feb 17 23:32:28 rivo volumio[3331]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":2771,"duration":229,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"1441 Kbps","isStreaming":false,"title":"163677067","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=qobuz://song/163677067","trackType":"qobuz"} Feb 17 23:32:28 rivo volumio[3331]: verbose: CURRENT POSITION 2 Feb 17 23:32:28 rivo volumio[3331]: info: CoreStateMachine::syncState stateService pause Feb 17 23:32:28 rivo volumio[3331]: info: CoreStateMachine::syncState currentStatus pause Feb 17 23:32:28 rivo volumio[3331]: info: CoreStateMachine::pushState Feb 17 23:32:28 rivo volumio[3331]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 17 23:32:28 rivo volumio[3331]: info: CoreCommandRouter::volumioPushState Feb 17 23:32:28 rivo volumio[3331]: info: CoreCommandRouter::volumioGetState Feb 17 23:32:28 rivo volumio[3331]: info: MRS: Pushing multiroomSync output update for this device Feb 17 23:32:28 rivo volumio[3331]: info: MRS: Pushing multiroomSync output Feb 17 23:32:28 rivo volumio[3331]: info: CoreStateMachine::stPlaybackTimer Feb 17 23:32:28 rivo volumio[3331]: info: ControllerMpd::pushState Feb 17 23:32:28 rivo volumio[3331]: info: CoreCommandRouter::servicePushState Feb 17 23:32:28 rivo volumio[3331]: info: CorePlayQueue::getTrack 2 Feb 17 23:32:28 rivo volumio[3331]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":2771,"duration":229,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"1441 Kbps","isStreaming":false,"title":"163677067","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=qobuz://song/163677067","trackType":"qobuz"} Feb 17 23:32:28 rivo volumio[3331]: verbose: CURRENT POSITION 2 Feb 17 23:32:28 rivo volumio[3331]: info: CoreStateMachine::syncState stateService pause Feb 17 23:32:28 rivo volumio[3331]: info: CoreStateMachine::syncState currentStatus pause Feb 17 23:32:28 rivo volumio[3331]: info: CoreStateMachine::pushState Feb 17 23:32:28 rivo volumio[3331]: info: CoreCommandRouter::volumioPushState Feb 17 23:32:28 rivo volumio[3331]: info: CoreCommandRouter::volumioGetState Feb 17 23:32:28 rivo volumio[3331]: info: MRS: Pushing multiroomSync output update for this device Feb 17 23:32:28 rivo volumio[3331]: info: MRS: Pushing multiroomSync output Feb 17 23:32:28 rivo volumio[3331]: info: CoreStateMachine::stPlaybackTimer Feb 17 23:32:28 rivo volumio5-onboarding[4218]: time=2026-02-17T23:32:28.532+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.150:48512 @ 0x20a1260" state=STATUS_PAUSED positionMs=11718 volume=100 Feb 17 23:32:28 rivo volumio5-onboarding[4218]: time=2026-02-17T23:32:28.533+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.150:48512 @ 0x20a1260" id=qobuz://song/163677067 title="Los Chicos Tristes" Feb 17 23:32:28 rivo volumio5-onboarding[4218]: time=2026-02-17T23:32:28.534+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.150:48512 @ 0x20a1260" state=STATUS_PAUSED positionMs=11718 volume=100 Feb 17 23:32:28 rivo volumio5-onboarding[4218]: time=2026-02-17T23:32:28.535+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.150:48512 @ 0x20a1260" id=qobuz://song/163677067 title="Los Chicos Tristes" Feb 17 23:32:28 rivo volumio[3331]: info: ------------------------------ 56ms Feb 17 23:32:28 rivo volumio[3331]: info: ------------------------------ 54ms Feb 17 23:32:28 rivo volumio[3331]: info: sendMpdCommand playlistinfo took 50 milliseconds Feb 17 23:32:28 rivo volumio[3331]: verbose: ControllerMpd::parseTrackInfo Feb 17 23:32:28 rivo volumio[3331]: info: ControllerMpd::pushState Feb 17 23:32:28 rivo volumio[3331]: info: CoreCommandRouter::servicePushState Feb 17 23:32:28 rivo volumio[3331]: info: CorePlayQueue::getTrack 2 Feb 17 23:32:28 rivo volumio[3331]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":2771,"duration":229,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"1441 Kbps","isStreaming":false,"title":"163677067","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=qobuz://song/163677067","trackType":"qobuz"} Feb 17 23:32:28 rivo volumio[3331]: verbose: CURRENT POSITION 2 Feb 17 23:32:28 rivo volumio[3331]: info: CoreStateMachine::syncState stateService pause Feb 17 23:32:28 rivo volumio[3331]: info: CoreStateMachine::syncState currentStatus pause Feb 17 23:32:28 rivo volumio[3331]: info: CoreStateMachine::pushState Feb 17 23:32:28 rivo volumio[3331]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 17 23:32:28 rivo volumio[3331]: info: CoreCommandRouter::volumioPushState Feb 17 23:32:28 rivo volumio[3331]: info: CoreCommandRouter::volumioGetState Feb 17 23:32:28 rivo volumio[3331]: info: MRS: Pushing multiroomSync output update for this device Feb 17 23:32:28 rivo volumio[3331]: info: MRS: Pushing multiroomSync output Feb 17 23:32:28 rivo volumio[3331]: info: CoreStateMachine::stPlaybackTimer Feb 17 23:32:28 rivo volumio5-onboarding[4218]: time=2026-02-17T23:32:28.578+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.150:48512 @ 0x20a1260" state=STATUS_PAUSED positionMs=12248 volume=100 Feb 17 23:32:28 rivo volumio5-onboarding[4218]: time=2026-02-17T23:32:28.579+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.150:48512 @ 0x20a1260" id=qobuz://song/163677067 title="Los Chicos Tristes" Feb 17 23:32:28 rivo volumio[3331]: info: ------------------------------ 93ms Feb 17 23:32:28 rivo volumio[3331]: info: MCU Signalled Playback Inactive Feb 17 23:32:32 rivo volumio[3331]: STREAMING PROXY: Upstream closed. Received 498458 bytes Feb 17 23:32:32 rivo volumio[3331]: STREAMING PROXY: Incomplete transfer. Expected 43777602, got 498458 Feb 17 23:32:32 rivo volumio[3331]: STREAMING PROXY: Retrying with range: bytes=498458- (attempt 1) Feb 17 23:32:33 rivo volumio[3331]: STREAMING PROXY: Resuming with range: bytes=498458- Feb 17 23:32:34 rivo volumio[3331]: STREAMING PROXY: Resume upstream status code: 206 Feb 17 23:32:37 rivo volumio5-onboarding[4218]: time=2026-02-17T23:32:37.337+03:00 level=ERROR msg="failed to read message" component=conn/ws remoteAddr=192.168.1.150:48512 error="websocket: close 1006 (abnormal closure): unexpected EOF" Feb 17 23:32:37 rivo volumio5-onboarding[4218]: time=2026-02-17T23:32:37.338+03:00 level=INFO msg="WebSocket connection closed" component=conn/ws remoteAddr=192.168.1.150:48512 Feb 17 23:32:37 rivo volumio5-onboarding[4218]: time=2026-02-17T23:32:37.338+03:00 level=INFO msg="connection to address closed" component=conn/multi addr=192.168.1.150:48512 Feb 17 23:33:07 rivo volumio[3331]: info: MRS: Found cast device: Haier-MatrixTV-AR-7520ed9daf883e7d30ee5d9ae3d1aa64 Feb 17 23:33:15 rivo qobuz-connect[3908]: 20260217 23:33:15.706 [3908.6088] INFO SampleApp: API endpoint invoked: get-display-info Feb 17 23:33:15 rivo qobuz-connect[3908]: 20260217 23:33:15.737 [3908.6088] INFO SampleApp: API endpoint invoked: get-connect-info Feb 17 23:33:17 rivo qobuz-connect[3908]: 20260217 23:33:17.331 [3908.6088] INFO SampleApp: API endpoint invoked: connect-to-qconnect Feb 17 23:33:17 rivo qobuz-connect[3908]: 20260217 23:33:17.331 [3908.3908] INFO EndpointManager: [0xac33eae0]: Updating API endpoint Feb 17 23:33:17 rivo qobuz-connect[3908]: 20260217 23:33:17.331 [3908.3908] INFO EndpointManager: [0xac33eae0]: Updating QConnect endpoint Feb 17 23:33:17 rivo qobuz-connect[3908]: 20260217 23:33:17.331 [3908.3908] INFO ActiveStateManager: [0xac33daf8]: Setting new active state: active Feb 17 23:33:17 rivo qobuz-connect[3908]: 20260217 23:33:17.331 [3908.3908] INFO PlaybackSessionManager: [0xac33eed0]: Starting playback session maintenance Feb 17 23:33:17 rivo qobuz-connect[3908]: 20260217 23:33:17.331 [3908.3908] INFO HttpDownloader: [0xac33f0c0]: Downloading content from: https://www.qobuz.com/api.json/0.2/session/start Feb 17 23:33:17 rivo qobuz-connect[3908]: 20260217 23:33:17.331 [3908.3908] INFO CloudClient: [0xac33f740]: Connecting to the cloud Feb 17 23:33:17 rivo qobuz-connect[3908]: 20260217 23:33:17.332 [3908.3908] INFO SampleApp: Renderer is now active Feb 17 23:33:17 rivo qobuz-connect[3908]: 20260217 23:33:17.691 [3908.3908] INFO PlaybackSessionManager: [0xac33eed0]: Playback session has been refreshed Feb 17 23:33:17 rivo qobuz-connect[3908]: 20260217 23:33:17.734 [3908.3908] INFO CloudClient: [0xac33f740]: Connection established Feb 17 23:33:17 rivo qobuz-connect[3908]: 20260217 23:33:17.734 [3908.3908] INFO QwspMessageSender: [0xac37b4a8]: Sending Authenticate message Feb 17 23:33:17 rivo qobuz-connect[3908]: 20260217 23:33:17.734 [3908.3908] INFO QwspMessageSender: [0xac37b4a8]: Sending Subscribe message Feb 17 23:33:17 rivo qobuz-connect[3908]: 20260217 23:33:17.734 [3908.3908] INFO QConnectMessageSender: [0xac34b2b8]: Sending JoinSession message Feb 17 23:33:17 rivo qobuz-connect[3908]: 20260217 23:33:17.734 [3908.3908] INFO QConnectMessageSender: [0xac34b2b8]: Sending VolumeChanged message Feb 17 23:33:17 rivo qobuz-connect[3908]: 20260217 23:33:17.734 [3908.3908] INFO QConnectMessageSender: [0xac34b2b8]: Sending VolumeMuted message Feb 17 23:33:17 rivo qobuz-connect[3908]: 20260217 23:33:17.734 [3908.3908] INFO QConnectMessageSender: [0xac34b2b8]: Sending MaxAudioQualityChanged message Feb 17 23:33:17 rivo qobuz-connect[3908]: 20260217 23:33:17.735 [3908.3908] INFO QwspMessageSender: [0xac37b4a8]: Sending Payload message Feb 17 23:33:17 rivo qobuz-connect[3908]: 20260217 23:33:17.852 [3908.3908] INFO ProtocolHandler: [0xac33f8a8]: Received SetActive message: active Feb 17 23:33:17 rivo qobuz-connect[3908]: 20260217 23:33:17.852 [3908.3908] INFO ProtocolHandler: [0xac33f8a8]: Received SetState message: Feb 17 23:33:17 rivo qobuz-connect[3908]: 20260217 23:33:17.852 [3908.3908] INFO ProtocolHandler: [0xac33f8a8]: Playing state: Playing Feb 17 23:33:17 rivo qobuz-connect[3908]: 20260217 23:33:17.852 [3908.3908] INFO ProtocolHandler: [0xac33f8a8]: Playback position: 9377 Feb 17 23:33:17 rivo qobuz-connect[3908]: 20260217 23:33:17.853 [3908.3908] INFO ProtocolHandler: [0xac33f8a8]: Queue version: 1.1 Feb 17 23:33:17 rivo qobuz-connect[3908]: 20260217 23:33:17.853 [3908.3908] INFO ProtocolHandler: [0xac33f8a8]: Current track: TID: 163677066, QID: 1, Context UUID: edb50a89-3534-45ab-9cd6-c9cf599e1b20 Feb 17 23:33:17 rivo qobuz-connect[3908]: 20260217 23:33:17.853 [3908.3908] INFO ProtocolHandler: [0xac33f8a8]: Next track: TID: 163677067, QID: 2, Context UUID: edb50a89-3534-45ab-9cd6-c9cf599e1b20 Feb 17 23:33:17 rivo qobuz-connect[3908]: 20260217 23:33:17.853 [3908.3908] INFO MediaEngine: [0xac33f168]: Stopping playback, clearing tracks Feb 17 23:33:17 rivo qobuz-connect[3908]: 20260217 23:33:17.853 [3908.3908] INFO MediaEngine: [0xac33f168]: Initiating playback Feb 17 23:33:17 rivo qobuz-connect[3908]: 20260217 23:33:17.853 [3908.3908] INFO RendererActionAvailabilityManager: [0xac33f7f8]: Renderer action 'Next' is available Feb 17 23:33:17 rivo qobuz-connect[3908]: 20260217 23:33:17.853 [3908.3908] INFO ProtocolHandler: [0xac33f8a8]: Received SetLoopMode message: Off Feb 17 23:33:17 rivo qobuz-connect[3908]: 20260217 23:33:17.853 [3908.3908] INFO PlaybackControlsManager: [0xac33f540]: Setting new loop mode: Off Feb 17 23:33:17 rivo qobuz-connect[3908]: 20260217 23:33:17.853 [3908.3908] INFO MediaEngine: [0xac33f168]: Setting current track: 163677066, initial offset: 9377ms Feb 17 23:33:17 rivo qobuz-connect[3908]: 20260217 23:33:17.853 [3908.3908] INFO AudioStreamManager: [0xac33f250]: Clearing all streams Feb 17 23:33:17 rivo qobuz-connect[3908]: 20260217 23:33:17.853 [3908.3908] INFO AudioStreamManager: [0xac33f250]: New stream: 1 Feb 17 23:33:17 rivo qobuz-connect[3908]: 20260217 23:33:17.853 [3908.3908] INFO HttpDownloader: [0xac34b230]: Downloading content from: https://www.qobuz.com/api.json/0.2/track/getFileUrl?format_id=27&request_sig=41df3d94806d65be22d816c83a7e8655&request_ts=1771360397&track_id=163677066 Feb 17 23:33:17 rivo qobuz-connect[3908]: 20260217 23:33:17.853 [3908.3908] INFO HttpDownloader: [0xac37b368]: Downloading content from: https://www.qobuz.com/api.json/0.2/track/get?track_id=163677066 Feb 17 23:33:17 rivo qobuz-connect[3908]: 20260217 23:33:17.854 [3908.3908] INFO HttpDownloader: [0xac345b90]: Downloading content from: https://www.qobuz.com/api.json/0.2/file/url?format_id=27&intent=stream&request_sig=43c38b08085b3e26732ab0ff35dd5c82&request_ts=1771360397&track_id=163677066 Feb 17 23:33:17 rivo qobuz-connect[3908]: 20260217 23:33:17.854 [3908.3908] INFO AudioStreamManager: [0xac33f250]: [Stream 1]: Running audio stream Feb 17 23:33:17 rivo qobuz-connect[3908]: 20260217 23:33:17.854 [3908.3908] INFO ProtocolHandler: [0xac33f8a8]: Received SetShuffleMode message: disabled Feb 17 23:33:17 rivo qobuz-connect[3908]: 20260217 23:33:17.854 [3908.3908] INFO PlaybackControlsManager: [0xac33f540]: Setting new shuffle mode: disabled Feb 17 23:33:17 rivo qobuz-connect[3908]: 20260217 23:33:17.854 [3908.3908] INFO MediaEngine: [0xac33f168]: Setting next track: 163677067 Feb 17 23:33:17 rivo qobuz-connect[3908]: 20260217 23:33:17.854 [3908.3908] INFO AudioStreamManager: [0xac33f250]: New stream: 2 Feb 17 23:33:17 rivo qobuz-connect[3908]: 20260217 23:33:17.854 [3908.3908] INFO HttpDownloader: [0xac349688]: Downloading content from: https://www.qobuz.com/api.json/0.2/track/getFileUrl?format_id=27&request_sig=f09a7022a96a3ea0f505577d4ba1025b&request_ts=1771360397&track_id=163677067 Feb 17 23:33:17 rivo qobuz-connect[3908]: 20260217 23:33:17.854 [3908.3908] INFO HttpDownloader: [0xac34a6b8]: Downloading content from: https://www.qobuz.com/api.json/0.2/track/get?track_id=163677067 Feb 17 23:33:17 rivo qobuz-connect[3908]: 20260217 23:33:17.854 [3908.3908] INFO HttpDownloader: [0xac34a9f8]: Downloading content from: https://www.qobuz.com/api.json/0.2/file/url?format_id=27&intent=stream&request_sig=4faeb292e5c40d51aad48ee281aa35b8&request_ts=1771360397&track_id=163677067 Feb 17 23:33:17 rivo qobuz-connect[3908]: 20260217 23:33:17.857 [3908.3908] INFO MediaEngine: [0xac33f168]: Waiting for current stream to start before starting audio renderer Feb 17 23:33:17 rivo qobuz-connect[3908]: 20260217 23:33:17.979 [3908.3908] INFO AudioStreamManager: [0xac33f250]: [Stream 1]: track URL resolved to: https://streaming-qobuz-std.akamaized.net/file?uid=4637524&eid=163677066&fmt=7&profile=raw&app_id=174516466&cid=3766108&etsp=1771363997&hmac=2wa47Kls-S5ENvD2oXj2mVpqlaY Feb 17 23:33:18 rivo qobuz-connect[3908]: 20260217 23:33:18.028 [3908.3908] INFO AudioStreamManager: [0xac33f250]: [Stream 2]: stream information have been fetched Feb 17 23:33:18 rivo qobuz-connect[3908]: 20260217 23:33:18.066 [3908.3908] INFO AudioStreamManager: [0xac33f250]: [Stream 2]: track URL resolved to: https://streaming-qobuz-std.akamaized.net/file?uid=4637524&eid=163677067&fmt=7&profile=raw&app_id=174516466&cid=3766108&etsp=1771363998&hmac=03he_YV2XxeivYI8DR0cPc3wxvA Feb 17 23:33:18 rivo qobuz-connect[3908]: 20260217 23:33:18.071 [3908.3908] INFO AudioStreamManager: [0xac33f250]: [Stream 2]: Metadata became available: Feb 17 23:33:18 rivo qobuz-connect[3908]: 20260217 23:33:18.071 [3908.3908] INFO AudioStreamManager: [0xac33f250]: Title: Los Chicos Tristes Feb 17 23:33:18 rivo qobuz-connect[3908]: 20260217 23:33:18.071 [3908.3908] INFO AudioStreamManager: [0xac33f250]: Artist: Hermanos Gutierrez Feb 17 23:33:18 rivo qobuz-connect[3908]: 20260217 23:33:18.071 [3908.3908] INFO AudioStreamManager: [0xac33f250]: Album: El Bueno Y El Malo Feb 17 23:33:18 rivo qobuz-connect[3908]: 20260217 23:33:18.071 [3908.3908] INFO AudioStreamManager: [0xac33f250]: Album art URL: https://static.qobuz.com/images/covers/0b/qa/kvetrucgdqa0b_600.jpg Feb 17 23:33:18 rivo qobuz-connect[3908]: 20260217 23:33:18.132 [3908.3908] INFO AudioStreamManager: [0xac33f250]: [Stream 1]: Metadata became available: Feb 17 23:33:18 rivo qobuz-connect[3908]: 20260217 23:33:18.132 [3908.3908] INFO AudioStreamManager: [0xac33f250]: Title: Hermosa Drive Feb 17 23:33:18 rivo qobuz-connect[3908]: 20260217 23:33:18.132 [3908.3908] INFO AudioStreamManager: [0xac33f250]: Artist: Hermanos Gutierrez Feb 17 23:33:18 rivo qobuz-connect[3908]: 20260217 23:33:18.133 [3908.3908] INFO AudioStreamManager: [0xac33f250]: Album: El Bueno Y El Malo Feb 17 23:33:18 rivo qobuz-connect[3908]: 20260217 23:33:18.133 [3908.3908] INFO AudioStreamManager: [0xac33f250]: Album art URL: https://static.qobuz.com/images/covers/0b/qa/kvetrucgdqa0b_600.jpg Feb 17 23:33:18 rivo qobuz-connect[3908]: 20260217 23:33:18.145 [3908.3908] INFO AudioStreamManager: [0xac33f250]: [Stream 1]: stream information have been fetched Feb 17 23:33:18 rivo qobuz-connect[3908]: 20260217 23:33:18.146 [3908.3908] INFO UrlAudioSource: [0xac4bc3a0]: Starting URL audio source, initial position: 9377ms, URL: https://streaming-qobuz-std.akamaized.net/file?uid=4637524&eid=163677066&fmt=7&profile=raw&app_id=174516466&cid=3766108&etsp=1771363997&hmac=2wa47Kls-S5ENvD2oXj2mVpqlaY Feb 17 23:33:18 rivo qobuz-connect[3908]: 20260217 23:33:18.146 [3908.3908] INFO ContentFetcher: [0xac4e8430]: Fetching content from: https://streaming-qobuz-std.akamaized.net/file?uid=4637524&eid=163677066&fmt=7&profile=raw&app_id=174516466&cid=3766108&etsp=1771363997&hmac=2wa47Kls-S5ENvD2oXj2mVpqlaY, offset: 0 Feb 17 23:33:18 rivo qobuz-connect[3908]: 20260217 23:33:18.146 [3908.3908] INFO AudioRenderer: [0xac33f388]: Starting audio renderer, initial playback state: Playing Feb 17 23:33:18 rivo qobuz-connect[3908]: 20260217 23:33:18.146 [3908.3908] INFO SampleApp: [Stream 1]: New audio stream (starting from 9377ms) Feb 17 23:33:18 rivo qobuz-connect[3908]: 20260217 23:33:18.149 [3908.3908] INFO SampleApp: [Stream 1]: Stream metadata became available: Feb 17 23:33:18 rivo qobuz-connect[3908]: 20260217 23:33:18.149 [3908.3908] INFO SampleApp: Title: Hermosa Drive Feb 17 23:33:18 rivo qobuz-connect[3908]: 20260217 23:33:18.149 [3908.3908] INFO SampleApp: Artist: Hermanos Gutierrez Feb 17 23:33:18 rivo qobuz-connect[3908]: 20260217 23:33:18.149 [3908.3908] INFO SampleApp: Album: El Bueno Y El Malo Feb 17 23:33:18 rivo qobuz-connect[3908]: 20260217 23:33:18.149 [3908.3908] INFO SampleApp: Album art URL: https://static.qobuz.com/images/covers/0b/qa/kvetrucgdqa0b_600.jpg Feb 17 23:33:18 rivo volumio[3331]: info: CoreCommandRouter::volumioGetState Feb 17 23:33:18 rivo volumio[3331]: info: CoreCommandRouter::volumioGetState Feb 17 23:33:18 rivo volumio[3331]: info: QobuzConnect: setActiveState() Feb 17 23:33:18 rivo volumio[3331]: info: CoreCommandRouter::volumioGetState Feb 17 23:33:18 rivo volumio[3331]: info: QobuzConnect: Set Qobuz connect default volume to 100 Feb 17 23:33:18 rivo volumio[3331]: info: CoreCommandRouter::volumioGetState Feb 17 23:33:18 rivo volumio[3331]: info: CoreCommandRouter::volumioGetState Feb 17 23:33:18 rivo volumio[3331]: info: QobuzConnect: Stopping currently active service Feb 17 23:33:18 rivo volumio[3331]: info: CoreCommandRouter::volumioStop Feb 17 23:33:18 rivo volumio[3331]: info: CoreStateMachine::stop Feb 17 23:33:18 rivo volumio[3331]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 17 23:33:18 rivo volumio[3331]: info: CoreStateMachine::updateTrackBlock Feb 17 23:33:18 rivo volumio[3331]: info: CorePlayQueue::getTrackBlock Feb 17 23:33:18 rivo qobuz-connect[3908]: 20260217 23:33:18.162 [3908.3908] INFO VolumeManager: [0xac33f5d0]: Setting new playback volume: 100 Feb 17 23:33:18 rivo volumio[3331]: info: CoreStateMachine::stPlaybackTimer Feb 17 23:33:18 rivo volumio[3331]: info: CoreStateMachine::pushState Feb 17 23:33:18 rivo volumio[3331]: info: CorePlayQueue::getTrack 2 Feb 17 23:33:18 rivo volumio[3331]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 17 23:33:18 rivo volumio[3331]: info: CoreCommandRouter::volumioPushState Feb 17 23:33:18 rivo volumio[3331]: info: CoreCommandRouter::volumioGetState Feb 17 23:33:18 rivo volumio[3331]: info: CorePlayQueue::getTrack 2 Feb 17 23:33:18 rivo volumio[3331]: info: MRS: Pushing multiroomSync output update for this device Feb 17 23:33:18 rivo volumio[3331]: info: MRS: Pushing multiroomSync output Feb 17 23:33:18 rivo volumio[3331]: info: CoreStateMachine::serviceStop Feb 17 23:33:18 rivo volumio[3331]: info: CorePlayQueue::getTrack 2 Feb 17 23:33:18 rivo volumio[3331]: info: CoreCommandRouter::serviceStop Feb 17 23:33:18 rivo volumio[3331]: info: [1771360398177] ControllerQobuz::stop Feb 17 23:33:18 rivo volumio[3331]: info: CoreStateMachine::setConsumeUpdateService mpd Feb 17 23:33:18 rivo volumio[3331]: info: ControllerMpd::stop Feb 17 23:33:18 rivo volumio[3331]: verbose: ControllerMpd::sendMpdCommand stop Feb 17 23:33:18 rivo volumio[3331]: STREAMING PROXY: Client closed connection Feb 17 23:33:18 rivo volumio[3331]: STREAMING PROXY: Client closed connection during resume Feb 17 23:33:18 rivo volumio[3331]: info: Feb 17 23:33:18 rivo volumio[3331]: ---------------------------- MPD announces state update: player Feb 17 23:33:18 rivo volumio[3331]: info: sendMpdCommand stop took 33 milliseconds Feb 17 23:33:18 rivo volumio[3331]: info: ControllerMpd::getState Feb 17 23:33:18 rivo volumio[3331]: verbose: ControllerMpd::sendMpdCommand status Feb 17 23:33:18 rivo volumio[3331]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 17 23:33:18 rivo volumio[3331]: info: CoreCommandRouter::servicePushState Feb 17 23:33:18 rivo volumio[3331]: info: CoreStateMachine::pushState Feb 17 23:33:18 rivo volumio[3331]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 17 23:33:18 rivo volumio[3331]: info: CoreCommandRouter::volumioPushState Feb 17 23:33:18 rivo volumio[3331]: info: CoreCommandRouter::volumioGetState Feb 17 23:33:18 rivo volumio[3331]: info: MRS: Pushing multiroomSync output update for this device Feb 17 23:33:18 rivo volumio[3331]: info: MRS: Pushing multiroomSync output Feb 17 23:33:18 rivo volumio[3331]: info: CorePlayQueue::getTrack 2 Feb 17 23:33:18 rivo volumio[3331]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current qobuz Received qobuzconnect Feb 17 23:33:18 rivo volumio[3331]: info: QobuzConnect: setActiveState(): setting Volatile state to qobuzconnect Feb 17 23:33:18 rivo volumio[3331]: info: QobuzConnect: setActiveState() completed, send playback confirmation Feb 17 23:33:18 rivo volumio[3331]: error: Failed to parse state for serial connection: TypeError: Cannot read property 'toUpperCase' of undefined Feb 17 23:33:18 rivo volumio[3331]: info: sendMpdCommand status took 92 milliseconds Feb 17 23:33:18 rivo volumio[3331]: verbose: ControllerMpd::parseState Feb 17 23:33:18 rivo volumio[3331]: verbose: ControllerMpd::sendMpdCommand playlistinfo Feb 17 23:33:18 rivo volumio[3331]: info: Feb 17 23:33:18 rivo volumio[3331]: ---------------------------- MPD announces state update: player Feb 17 23:33:18 rivo volumio[3331]: info: ControllerMpd::getState Feb 17 23:33:18 rivo volumio[3331]: verbose: ControllerMpd::sendMpdCommand status Feb 17 23:33:18 rivo volumio[3331]: info: Feb 17 23:33:18 rivo volumio[3331]: ---------------------------- MPD announces state update: player Feb 17 23:33:18 rivo volumio[3331]: info: ControllerMpd::getState Feb 17 23:33:18 rivo volumio[3331]: verbose: ControllerMpd::sendMpdCommand status Feb 17 23:33:18 rivo volumio[3331]: info: sendMpdCommand playlistinfo took 13 milliseconds Feb 17 23:33:18 rivo volumio[3331]: info: sendMpdCommand status took 10 milliseconds Feb 17 23:33:18 rivo volumio[3331]: info: sendMpdCommand status took 7 milliseconds Feb 17 23:33:18 rivo volumio[3331]: verbose: ControllerMpd::parseTrackInfo Feb 17 23:33:18 rivo volumio[3331]: verbose: ControllerMpd::parseState Feb 17 23:33:18 rivo volumio[3331]: verbose: ControllerMpd::sendMpdCommand playlistinfo Feb 17 23:33:18 rivo volumio[3331]: verbose: ControllerMpd::parseState Feb 17 23:33:18 rivo volumio[3331]: verbose: ControllerMpd::sendMpdCommand playlistinfo Feb 17 23:33:18 rivo volumio[3331]: info: ControllerMpd::pushState Feb 17 23:33:18 rivo volumio[3331]: info: CoreCommandRouter::servicePushState Feb 17 23:33:18 rivo volumio[3331]: info: CoreStateMachine::pushState Feb 17 23:33:18 rivo volumio[3331]: info: CoreCommandRouter::volumioPushState Feb 17 23:33:18 rivo volumio[3331]: info: CoreCommandRouter::volumioGetState Feb 17 23:33:18 rivo volumio[3331]: info: MRS: Pushing multiroomSync output update for this device Feb 17 23:33:18 rivo volumio[3331]: info: MRS: Pushing multiroomSync output Feb 17 23:33:18 rivo volumio[3331]: info: CorePlayQueue::getTrack 2 Feb 17 23:33:18 rivo volumio[3331]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current qobuz Received mpd Feb 17 23:33:18 rivo volumio[3331]: info: ------------------------------ 152ms Feb 17 23:33:18 rivo volumio[3331]: info: sendMpdCommand playlistinfo took 36 milliseconds Feb 17 23:33:18 rivo volumio[3331]: info: sendMpdCommand playlistinfo took 35 milliseconds Feb 17 23:33:18 rivo volumio[3331]: verbose: ControllerMpd::parseTrackInfo Feb 17 23:33:18 rivo volumio[3331]: verbose: ControllerMpd::parseTrackInfo Feb 17 23:33:18 rivo volumio[3331]: info: ControllerMpd::pushState Feb 17 23:33:18 rivo volumio[3331]: info: CoreCommandRouter::servicePushState Feb 17 23:33:18 rivo volumio[3331]: info: CoreStateMachine::pushState Feb 17 23:33:18 rivo volumio[3331]: info: CoreCommandRouter::volumioPushState Feb 17 23:33:18 rivo volumio[3331]: info: CoreCommandRouter::volumioGetState Feb 17 23:33:18 rivo volumio[3331]: info: MRS: Pushing multiroomSync output update for this device Feb 17 23:33:18 rivo volumio[3331]: info: MRS: Pushing multiroomSync output Feb 17 23:33:18 rivo volumio[3331]: info: CorePlayQueue::getTrack 2 Feb 17 23:33:18 rivo volumio[3331]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current qobuz Received mpd Feb 17 23:33:18 rivo volumio[3331]: info: ControllerMpd::pushState Feb 17 23:33:18 rivo volumio[3331]: info: CoreCommandRouter::servicePushState Feb 17 23:33:18 rivo volumio[3331]: info: CoreStateMachine::pushState Feb 17 23:33:18 rivo volumio[3331]: info: CoreCommandRouter::volumioPushState Feb 17 23:33:18 rivo qobuz-connect[3908]: 20260217 23:33:18.389 [3908.3908] INFO SampleApp: Playback volume changed: 100 Feb 17 23:33:18 rivo qobuz-connect[3908]: 20260217 23:33:18.389 [3908.3908] INFO ProtocolHandler: [0xac33f8a8]: Volume changed: 100 Feb 17 23:33:18 rivo qobuz-connect[3908]: 20260217 23:33:18.389 [3908.3908] INFO QConnectMessageSender: [0xac34b2b8]: Sending VolumeChanged message Feb 17 23:33:18 rivo qobuz-connect[3908]: 20260217 23:33:18.389 [3908.3908] INFO SampleApp: Initiating playback, initial state: Playing Feb 17 23:33:18 rivo volumio[3331]: info: CoreCommandRouter::volumioGetState Feb 17 23:33:18 rivo volumio[3331]: info: MRS: Pushing multiroomSync output update for this device Feb 17 23:33:18 rivo volumio[3331]: info: MRS: Pushing multiroomSync output Feb 17 23:33:18 rivo volumio[3331]: info: CorePlayQueue::getTrack 2 Feb 17 23:33:18 rivo volumio[3331]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current qobuz Received mpd Feb 17 23:33:18 rivo volumio[3331]: info: ------------------------------ 102ms Feb 17 23:33:18 rivo volumio[3331]: info: ------------------------------ 99ms Feb 17 23:33:18 rivo volumio[3331]: error: Failed to parse state for serial connection: TypeError: Cannot read property 'toUpperCase' of undefined Feb 17 23:33:18 rivo volumio[3331]: error: Failed to parse state for serial connection: TypeError: Cannot read property 'toUpperCase' of undefined Feb 17 23:33:18 rivo volumio[3331]: error: Failed to parse state for serial connection: TypeError: Cannot read property 'toUpperCase' of undefined Feb 17 23:33:18 rivo volumio[3331]: info: CoreCommandRouter::volumioGetState Feb 17 23:33:18 rivo qobuz-connect[3908]: 20260217 23:33:18.504 [3908.3908] INFO QwspMessageSender: [0xac37b4a8]: Sending Payload message Feb 17 23:33:18 rivo qobuz-connect[3908]: 20260217 23:33:18.505 [3908.3908] INFO SampleApp: Playback state changed: Playing Feb 17 23:33:18 rivo qobuz-connect[3908]: 20260217 23:33:18.506 [3908.3908] INFO StreamingEventReporter: [0xac33fcc0]: Reporting streaming started event Feb 17 23:33:18 rivo qobuz-connect[3908]: 20260217 23:33:18.506 [3908.3908] INFO HttpDownloader: [0xac33fd18]: Downloading content from: https://www.qobuz.com/api.json/0.2/track/reportStreamingStart Feb 17 23:33:18 rivo qobuz-connect[3908]: 20260217 23:33:18.506 [3908.3908] INFO ProtocolHandler: [0xac33f8a8]: Need to send state update Feb 17 23:33:18 rivo qobuz-connect[3908]: 20260217 23:33:18.506 [3908.3908] INFO QConnectMessageSender: [0xac34b2b8]: Sending StateUpdated message Feb 17 23:33:18 rivo qobuz-connect[3908]: 20260217 23:33:18.507 [3908.3908] INFO QwspMessageSender: [0xac37b4a8]: Sending Payload message Feb 17 23:33:18 rivo qobuz-connect[3908]: 20260217 23:33:18.508 [3908.3908] INFO QConnectMessageSender: [0xac34b2b8]: Sending FileAudioQualityChanged message Feb 17 23:33:18 rivo qobuz-connect[3908]: 20260217 23:33:18.508 [3908.3908] INFO QwspMessageSender: [0xac37b4a8]: Sending Payload message Feb 17 23:33:18 rivo volumio[3331]: info: CoreCommandRouter::volumioGetState Feb 17 23:33:18 rivo qobuz-connect[3908]: 20260217 23:33:18.508 [3908.3908] INFO QConnectMessageSender: [0xac34b2b8]: Sending DeviceAudioQualityChanged message Feb 17 23:33:18 rivo qobuz-connect[3908]: 20260217 23:33:18.508 [3908.3908] INFO QwspMessageSender: [0xac37b4a8]: Sending Payload message Feb 17 23:33:18 rivo volumio[3331]: info: CoreCommandRouter::servicePushState Feb 17 23:33:18 rivo volumio[3331]: info: CoreStateMachine::pushState Feb 17 23:33:18 rivo volumio[3331]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 17 23:33:18 rivo volumio[3331]: info: CoreCommandRouter::volumioPushState Feb 17 23:33:18 rivo volumio[3331]: info: CoreCommandRouter::volumioGetState Feb 17 23:33:18 rivo qobuz-connect[3908]: 20260217 23:33:18.525 [3908.3908] INFO VolumeManager: [0xac33f5d0]: Setting new playback volume: 100 Feb 17 23:33:18 rivo qobuz-connect[3908]: 20260217 23:33:18.527 [3908.3908] INFO VolumeManager: [0xac33f5d0]: Setting new mute state: 0 Feb 17 23:33:18 rivo volumio[3331]: info: MRS: Pushing multiroomSync output update for this device Feb 17 23:33:18 rivo volumio[3331]: info: MRS: Pushing multiroomSync output Feb 17 23:33:18 rivo volumio[3331]: info: CoreCommandRouter::volumioGetState Feb 17 23:33:18 rivo volumio[3331]: info: CoreCommandRouter::servicePushState Feb 17 23:33:18 rivo volumio[3331]: info: CoreStateMachine::pushState Feb 17 23:33:18 rivo volumio[3331]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 17 23:33:18 rivo volumio[3331]: info: CoreCommandRouter::volumioPushState Feb 17 23:33:18 rivo volumio[3331]: info: CoreCommandRouter::volumioGetState Feb 17 23:33:18 rivo volumio[3331]: info: MRS: Pushing multiroomSync output update for this device Feb 17 23:33:18 rivo volumio[3331]: info: MRS: Pushing multiroomSync output Feb 17 23:33:18 rivo volumio[3331]: info: CoreCommandRouter::volumioGetState Feb 17 23:33:18 rivo volumio[3331]: info: CoreCommandRouter::servicePushState Feb 17 23:33:18 rivo volumio[3331]: info: CoreStateMachine::pushState Feb 17 23:33:18 rivo volumio[3331]: info: CoreCommandRouter::volumioPushState Feb 17 23:33:18 rivo volumio[3331]: info: CoreCommandRouter::volumioGetState Feb 17 23:33:18 rivo volumio[3331]: info: MRS: Pushing multiroomSync output update for this device Feb 17 23:33:18 rivo volumio[3331]: info: MRS: Pushing multiroomSync output Feb 17 23:33:18 rivo volumio[3331]: info: Signalling Playback active due to playback status change Feb 17 23:33:18 rivo volumio[3331]: info: [LastFM] Current track has sufficient metadata: title (Hermosa Drive) and artist (Hermanos Gutierrez) passed on explicitly Feb 17 23:33:18 rivo volumio[3331]: info: MCU Signalled Playback Active Feb 17 23:33:18 rivo volumio[3331]: info: [LastFM] track info: {"success":true,"trackInfo":{"name":"Hermosa Drive","url":"https://www.last.fm/music/Hermanos+Gutierrez/_/Hermosa+Drive","duration":"0","streamable":{"#":"0","@":{"fulltrack":"0"}},"listeners":"1291","playcount":"4043","artist":{"name":"Hermanos Gutierrez","url":"https://www.last.fm/music/Hermanos+Gutierrez"},"userplaycount":"0","userloved":"0","toptags":""}} Feb 17 23:33:20 rivo volumio[3331]: info: Executing endpoint metavolumio Feb 17 23:33:20 rivo volumio[3331]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Feb 17 23:33:20 rivo qobuz-connect[3908]: 20260217 23:33:20.700 [3908.3908] INFO UrlAudioSource: [0xac4bc3a0]: Content info extracted Feb 17 23:33:20 rivo qobuz-connect[3908]: 20260217 23:33:20.700 [3908.3908] INFO UrlAudioSource: [0xac4bc3a0]: Size: 44577891 Feb 17 23:33:20 rivo qobuz-connect[3908]: 20260217 23:33:20.709 [3908.6112] INFO AudioDecoder: [0xac5c06f0]: Stream info: Feb 17 23:33:20 rivo qobuz-connect[3908]: 20260217 23:33:20.709 [3908.6112] INFO AudioDecoder: [0xac5c06f0]: Total samples: 11233826 Feb 17 23:33:20 rivo qobuz-connect[3908]: 20260217 23:33:20.709 [3908.6112] INFO AudioDecoder: [0xac5c06f0]: Sample rate: 48000 Feb 17 23:33:20 rivo qobuz-connect[3908]: 20260217 23:33:20.710 [3908.6112] INFO AudioDecoder: [0xac5c06f0]: Channel count: 2 Feb 17 23:33:20 rivo qobuz-connect[3908]: 20260217 23:33:20.710 [3908.6112] INFO AudioDecoder: [0xac5c06f0]: Bits per sample: 24 Feb 17 23:33:20 rivo qobuz-connect[3908]: 20260217 23:33:20.710 [3908.6112] INFO AudioDecoder: [0xac5c06f0]: Duration: 234038 Feb 17 23:33:20 rivo qobuz-connect[3908]: 20260217 23:33:20.712 [3908.3908] INFO UrlAudioSource: [0xac4bc3a0]: Audio properties have changed Feb 17 23:33:20 rivo qobuz-connect[3908]: 20260217 23:33:20.712 [3908.3908] INFO UrlAudioSource: [0xac4bc3a0]: Seeking input stream to byte offset: 1721926 Feb 17 23:33:20 rivo qobuz-connect[3908]: 20260217 23:33:20.712 [3908.3908] INFO ContentFetcher: [0xac4e8430]: Adjusting download offset to: 1721926 Feb 17 23:33:20 rivo volumio[3331]: info: Executing endpoint metavolumio Feb 17 23:33:20 rivo volumio[3331]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Feb 17 23:33:20 rivo volumio[3331]: info: Executing endpoint metavolumio Feb 17 23:33:20 rivo volumio[3331]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Feb 17 23:33:24 rivo qobuz-connect[3908]: 20260217 23:33:24.912 [3908.3908] ERROR HttpClient: [0xac4ef360]: Client finished: Transferred a partial file (18) Feb 17 23:33:24 rivo qobuz-connect[3908]: 20260217 23:33:24.913 [3908.3908] ERROR UrlAudioSource: [0xac4bc3a0]: Content fetcher has encountered an error Feb 17 23:33:24 rivo qobuz-connect[3908]: 20260217 23:33:24.913 [3908.3908] INFO ContentFetcher: [0xac4e8430]: Canceling download Feb 17 23:33:24 rivo qobuz-connect[3908]: 20260217 23:33:24.913 [3908.3908] ERROR AudioStreamManager: [0xac33f250]: [Stream 1]: Audio stream has encountered an error Feb 17 23:33:24 rivo qobuz-connect[3908]: 20260217 23:33:24.913 [3908.3908] ERROR MediaEngine: [0xac33f168]: Current stream has encountered an error Feb 17 23:33:24 rivo qobuz-connect[3908]: 20260217 23:33:24.913 [3908.3908] INFO QConnectMessageSender: [0xac34b2b8]: Sending PlaybackError message Feb 17 23:33:24 rivo qobuz-connect[3908]: 20260217 23:33:24.913 [3908.3908] INFO MediaEngine: [0xac33f168]: Stopping playback, clearing tracks Feb 17 23:33:24 rivo qobuz-connect[3908]: 20260217 23:33:24.914 [3908.3908] INFO QwspMessageSender: [0xac37b4a8]: Sending Payload message Feb 17 23:33:24 rivo qobuz-connect[3908]: 20260217 23:33:24.914 [3908.3908] INFO SampleApp: Playback state changed: Stopped Feb 17 23:33:24 rivo qobuz-connect[3908]: 20260217 23:33:24.914 [3908.3908] INFO StreamingEventReporter: [0xac33fcc0]: Reporting streaming ended event Feb 17 23:33:24 rivo qobuz-connect[3908]: 20260217 23:33:24.916 [3908.3908] INFO HttpDownloader: [0xac33fd18]: Downloading content from: https://www.qobuz.com/api.json/0.2/track/reportStreamingEndJson Feb 17 23:33:24 rivo qobuz-connect[3908]: 20260217 23:33:24.916 [3908.3908] INFO ProtocolHandler: [0xac33f8a8]: Need to send state update Feb 17 23:33:24 rivo qobuz-connect[3908]: 20260217 23:33:24.917 [3908.3908] INFO QConnectMessageSender: [0xac34b2b8]: Sending StateUpdated message Feb 17 23:33:24 rivo qobuz-connect[3908]: 20260217 23:33:24.917 [3908.3908] INFO AudioRenderer: [0xac33f388]: Stopping audio renderer Feb 17 23:33:24 rivo volumio[3331]: info: CoreCommandRouter::volumioGetState Feb 17 23:33:24 rivo volumio[3331]: info: CoreCommandRouter::servicePushState Feb 17 23:33:24 rivo volumio[3331]: info: CoreStateMachine::pushState Feb 17 23:33:24 rivo volumio[3331]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 17 23:33:24 rivo volumio[3331]: info: CoreCommandRouter::volumioPushState Feb 17 23:33:24 rivo qobuz-connect[3908]: 20260217 23:33:24.918 [3908.3908] INFO QwspMessageSender: [0xac37b4a8]: Sending Payload message Feb 17 23:33:24 rivo qobuz-connect[3908]: 20260217 23:33:24.919 [3908.3908] INFO SampleApp: Stopping playback Feb 17 23:33:24 rivo volumio[3331]: info: CoreCommandRouter::volumioGetState Feb 17 23:33:24 rivo volumio[3331]: info: MRS: Pushing multiroomSync output update for this device Feb 17 23:33:24 rivo volumio[3331]: info: MRS: Pushing multiroomSync output Feb 17 23:33:24 rivo volumio[3331]: info: CoreCommandRouter::volumioGetState Feb 17 23:33:24 rivo volumio[3331]: info: CoreCommandRouter::servicePushState Feb 17 23:33:24 rivo volumio[3331]: info: CoreStateMachine::pushState Feb 17 23:33:24 rivo volumio[3331]: info: CoreCommandRouter::volumioPushState Feb 17 23:33:24 rivo volumio[3331]: info: CoreCommandRouter::volumioGetState Feb 17 23:33:24 rivo volumio[3331]: info: MRS: Pushing multiroomSync output update for this device Feb 17 23:33:24 rivo volumio[3331]: info: MRS: Pushing multiroomSync output Feb 17 23:33:25 rivo qobuz-connect[3908]: 20260217 23:33:25.029 [3908.3908] INFO ProtocolHandler: [0xac33f8a8]: Received SetState message: Feb 17 23:33:25 rivo qobuz-connect[3908]: 20260217 23:33:25.029 [3908.3908] INFO ProtocolHandler: [0xac33f8a8]: Playing state: Playing Feb 17 23:33:25 rivo qobuz-connect[3908]: 20260217 23:33:25.029 [3908.3908] INFO ProtocolHandler: [0xac33f8a8]: Playback position: 0 Feb 17 23:33:25 rivo qobuz-connect[3908]: 20260217 23:33:25.029 [3908.3908] INFO ProtocolHandler: [0xac33f8a8]: Queue version: 1.1 Feb 17 23:33:25 rivo qobuz-connect[3908]: 20260217 23:33:25.029 [3908.3908] INFO ProtocolHandler: [0xac33f8a8]: Current track: TID: 163677067, QID: 2, Context UUID: edb50a89-3534-45ab-9cd6-c9cf599e1b20 Feb 17 23:33:25 rivo qobuz-connect[3908]: 20260217 23:33:25.030 [3908.3908] INFO ProtocolHandler: [0xac33f8a8]: Next track: TID: 163677068, QID: 3, Context UUID: edb50a89-3534-45ab-9cd6-c9cf599e1b20 Feb 17 23:33:25 rivo qobuz-connect[3908]: 20260217 23:33:25.030 [3908.3908] INFO MediaEngine: [0xac33f168]: Reseting Feb 17 23:33:25 rivo qobuz-connect[3908]: 20260217 23:33:25.030 [3908.3908] INFO MediaEngine: [0xac33f168]: Stopping playback, clearing tracks Feb 17 23:33:25 rivo qobuz-connect[3908]: 20260217 23:33:25.030 [3908.3908] INFO MediaEngine: [0xac33f168]: Initiating playback Feb 17 23:33:25 rivo qobuz-connect[3908]: 20260217 23:33:25.030 [3908.3908] INFO ProtocolHandler: [0xac33f8a8]: Need to send state update Feb 17 23:33:25 rivo qobuz-connect[3908]: 20260217 23:33:25.030 [3908.3908] INFO QConnectMessageSender: [0xac34b2b8]: Sending StateUpdated message Feb 17 23:33:25 rivo qobuz-connect[3908]: 20260217 23:33:25.030 [3908.3908] INFO QwspMessageSender: [0xac37b4a8]: Sending Payload message Feb 17 23:33:25 rivo qobuz-connect[3908]: 20260217 23:33:25.030 [3908.3908] INFO MediaEngine: [0xac33f168]: Setting current track: 163677067, initial offset: 0ms Feb 17 23:33:25 rivo qobuz-connect[3908]: 20260217 23:33:25.030 [3908.3908] INFO AudioStreamManager: [0xac33f250]: Clearing all streams Feb 17 23:33:25 rivo qobuz-connect[3908]: 20260217 23:33:25.030 [3908.3908] INFO AudioStreamManager: [0xac33f250]: [Stream 1]: Disposing of audio stream Feb 17 23:33:25 rivo qobuz-connect[3908]: 20260217 23:33:25.031 [3908.3908] INFO AudioStreamManager: [0xac33f250]: New stream: 3 Feb 17 23:33:25 rivo qobuz-connect[3908]: 20260217 23:33:25.031 [3908.3908] INFO HttpDownloader: [0xac349688]: Downloading content from: https://www.qobuz.com/api.json/0.2/track/getFileUrl?format_id=27&request_sig=0928746cca17869d07b8d839274b7d07&request_ts=1771360405&track_id=163677067 Feb 17 23:33:25 rivo qobuz-connect[3908]: 20260217 23:33:25.031 [3908.3908] INFO HttpDownloader: [0xac5ba358]: Downloading content from: https://www.qobuz.com/api.json/0.2/track/get?track_id=163677067 Feb 17 23:33:25 rivo qobuz-connect[3908]: 20260217 23:33:25.031 [3908.3908] INFO HttpDownloader: [0xac378308]: Downloading content from: https://www.qobuz.com/api.json/0.2/file/url?format_id=27&intent=stream&request_sig=953e3e5419fa727d30b0dbbea64e8c28&request_ts=1771360405&track_id=163677067 Feb 17 23:33:25 rivo qobuz-connect[3908]: 20260217 23:33:25.031 [3908.3908] INFO AudioStreamManager: [0xac33f250]: [Stream 3]: Running audio stream Feb 17 23:33:25 rivo volumio[3331]: info: CoreCommandRouter::volumioGetState Feb 17 23:33:25 rivo volumio[3331]: info: CoreCommandRouter::servicePushState Feb 17 23:33:25 rivo volumio[3331]: info: CoreStateMachine::pushState Feb 17 23:33:25 rivo volumio[3331]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 17 23:33:25 rivo volumio[3331]: info: CoreCommandRouter::volumioPushState Feb 17 23:33:25 rivo volumio[3331]: info: CoreCommandRouter::volumioGetState Feb 17 23:33:25 rivo volumio[3331]: info: MRS: Pushing multiroomSync output update for this device Feb 17 23:33:25 rivo volumio[3331]: info: MRS: Pushing multiroomSync output Feb 17 23:33:25 rivo qobuz-connect[3908]: 20260217 23:33:25.036 [3908.3908] INFO SampleApp: [Stream 1]: Audio stream has been disposed of Feb 17 23:33:25 rivo qobuz-connect[3908]: 20260217 23:33:25.037 [3908.3908] INFO MediaEngine: [0xac33f168]: Setting next track: 163677068 Feb 17 23:33:25 rivo qobuz-connect[3908]: 20260217 23:33:25.037 [3908.3908] INFO AudioStreamManager: [0xac33f250]: New stream: 4 Feb 17 23:33:25 rivo qobuz-connect[3908]: 20260217 23:33:25.037 [3908.3908] INFO HttpDownloader: [0xac345510]: Downloading content from: https://www.qobuz.com/api.json/0.2/track/getFileUrl?format_id=27&request_sig=916ebae3d0a0abb441b3e329fc0496ac&request_ts=1771360405&track_id=163677068 Feb 17 23:33:25 rivo qobuz-connect[3908]: 20260217 23:33:25.037 [3908.3908] INFO HttpDownloader: [0xac36a900]: Downloading content from: https://www.qobuz.com/api.json/0.2/track/get?track_id=163677068 Feb 17 23:33:25 rivo qobuz-connect[3908]: 20260217 23:33:25.037 [3908.3908] INFO HttpDownloader: [0xac507a30]: Downloading content from: https://www.qobuz.com/api.json/0.2/file/url?format_id=27&intent=stream&request_sig=fb648531cadc1931cc81ae11096678b7&request_ts=1771360405&track_id=163677068 Feb 17 23:33:25 rivo qobuz-connect[3908]: 20260217 23:33:25.040 [3908.3908] INFO MediaEngine: [0xac33f168]: Waiting for current stream to start before starting audio renderer Feb 17 23:33:25 rivo volumio[3331]: info: MCU Signalled Playback Inactive Feb 17 23:33:25 rivo qobuz-connect[3908]: 20260217 23:33:25.163 [3908.3908] INFO AudioStreamManager: [0xac33f250]: [Stream 3]: track URL resolved to: https://streaming-qobuz-std.akamaized.net/file?uid=4637524&eid=163677067&fmt=7&profile=raw&app_id=174516466&cid=3766108&etsp=1771364005&hmac=H4dq6-MvFzMWn0PF0k1w4ure5wc Feb 17 23:33:25 rivo qobuz-connect[3908]: 20260217 23:33:25.209 [3908.3908] INFO AudioStreamManager: [0xac33f250]: [Stream 4]: Metadata became available: Feb 17 23:33:25 rivo qobuz-connect[3908]: 20260217 23:33:25.209 [3908.3908] INFO AudioStreamManager: [0xac33f250]: Title: Thunderbird Feb 17 23:33:25 rivo qobuz-connect[3908]: 20260217 23:33:25.209 [3908.3908] INFO AudioStreamManager: [0xac33f250]: Artist: Hermanos Gutierrez Feb 17 23:33:25 rivo qobuz-connect[3908]: 20260217 23:33:25.209 [3908.3908] INFO AudioStreamManager: [0xac33f250]: Album: El Bueno Y El Malo Feb 17 23:33:25 rivo qobuz-connect[3908]: 20260217 23:33:25.209 [3908.3908] INFO AudioStreamManager: [0xac33f250]: Album art URL: https://static.qobuz.com/images/covers/0b/qa/kvetrucgdqa0b_600.jpg Feb 17 23:33:25 rivo qobuz-connect[3908]: 20260217 23:33:25.209 [3908.3908] INFO AudioStreamManager: [0xac33f250]: [Stream 3]: stream information have been fetched Feb 17 23:33:25 rivo qobuz-connect[3908]: 20260217 23:33:25.209 [3908.3908] INFO UrlAudioSource: [0xac34b2e0]: Starting URL audio source, initial position: 0ms, URL: https://streaming-qobuz-std.akamaized.net/file?uid=4637524&eid=163677067&fmt=7&profile=raw&app_id=174516466&cid=3766108&etsp=1771364005&hmac=H4dq6-MvFzMWn0PF0k1w4ure5wc Feb 17 23:33:25 rivo qobuz-connect[3908]: 20260217 23:33:25.209 [3908.3908] INFO ContentFetcher: [0xac56b0d0]: Fetching content from: https://streaming-qobuz-std.akamaized.net/file?uid=4637524&eid=163677067&fmt=7&profile=raw&app_id=174516466&cid=3766108&etsp=1771364005&hmac=H4dq6-MvFzMWn0PF0k1w4ure5wc, offset: 0 Feb 17 23:33:25 rivo qobuz-connect[3908]: 20260217 23:33:25.210 [3908.3908] INFO AudioRenderer: [0xac33f388]: Starting audio renderer, initial playback state: Playing Feb 17 23:33:25 rivo qobuz-connect[3908]: 20260217 23:33:25.210 [3908.3908] INFO SampleApp: [Stream 3]: New audio stream (starting from 0ms) Feb 17 23:33:25 rivo volumio[3331]: info: CoreCommandRouter::volumioGetState Feb 17 23:33:25 rivo volumio[3331]: info: QobuzConnect: alread currrent service, send playback confirmation Feb 17 23:33:25 rivo qobuz-connect[3908]: 20260217 23:33:25.213 [3908.3908] INFO SampleApp: Initiating playback, initial state: Playing Feb 17 23:33:25 rivo qobuz-connect[3908]: 20260217 23:33:25.224 [3908.3908] INFO SampleApp: Playback state changed: Playing Feb 17 23:33:25 rivo qobuz-connect[3908]: 20260217 23:33:25.224 [3908.3908] INFO StreamingEventReporter: [0xac33fcc0]: Reporting streaming started event Feb 17 23:33:25 rivo qobuz-connect[3908]: 20260217 23:33:25.224 [3908.3908] INFO HttpDownloader: [0xac33fd18]: Downloading content from: https://www.qobuz.com/api.json/0.2/track/reportStreamingStart Feb 17 23:33:25 rivo qobuz-connect[3908]: 20260217 23:33:25.225 [3908.3908] INFO ProtocolHandler: [0xac33f8a8]: Need to send state update Feb 17 23:33:25 rivo qobuz-connect[3908]: 20260217 23:33:25.225 [3908.3908] INFO QConnectMessageSender: [0xac34b2b8]: Sending StateUpdated message Feb 17 23:33:25 rivo qobuz-connect[3908]: 20260217 23:33:25.225 [3908.3908] INFO QwspMessageSender: [0xac37b4a8]: Sending Payload message Feb 17 23:33:25 rivo volumio[3331]: info: CoreCommandRouter::volumioGetState Feb 17 23:33:25 rivo volumio[3331]: info: CoreCommandRouter::servicePushState Feb 17 23:33:25 rivo volumio[3331]: info: CoreStateMachine::pushState Feb 17 23:33:25 rivo qobuz-connect[3908]: 20260217 23:33:25.226 [3908.3908] INFO QConnectMessageSender: [0xac34b2b8]: Sending FileAudioQualityChanged message Feb 17 23:33:25 rivo qobuz-connect[3908]: 20260217 23:33:25.226 [3908.3908] INFO QwspMessageSender: [0xac37b4a8]: Sending Payload message Feb 17 23:33:25 rivo volumio[3331]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 17 23:33:25 rivo volumio[3331]: info: CoreCommandRouter::volumioPushState Feb 17 23:33:25 rivo volumio[3331]: info: CoreCommandRouter::volumioGetState Feb 17 23:33:25 rivo volumio[3331]: info: MRS: Pushing multiroomSync output update for this device Feb 17 23:33:25 rivo volumio[3331]: info: MRS: Pushing multiroomSync output Feb 17 23:33:25 rivo volumio[3331]: info: CoreCommandRouter::servicePushState Feb 17 23:33:25 rivo volumio[3331]: info: CoreStateMachine::pushState Feb 17 23:33:25 rivo volumio[3331]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 17 23:33:25 rivo volumio[3331]: info: CoreCommandRouter::volumioPushState Feb 17 23:33:25 rivo volumio[3331]: info: CoreCommandRouter::volumioGetState Feb 17 23:33:25 rivo volumio[3331]: info: MRS: Pushing multiroomSync output update for this device Feb 17 23:33:25 rivo volumio[3331]: info: MRS: Pushing multiroomSync output Feb 17 23:33:25 rivo volumio[3331]: info: CoreCommandRouter::volumioGetState Feb 17 23:33:25 rivo volumio[3331]: info: CoreCommandRouter::servicePushState Feb 17 23:33:25 rivo volumio[3331]: info: CoreStateMachine::pushState Feb 17 23:33:25 rivo volumio[3331]: info: CoreCommandRouter::volumioPushState Feb 17 23:33:25 rivo volumio[3331]: info: CoreCommandRouter::volumioGetState Feb 17 23:33:25 rivo volumio[3331]: info: MRS: Pushing multiroomSync output update for this device Feb 17 23:33:25 rivo volumio[3331]: info: MRS: Pushing multiroomSync output Feb 17 23:33:25 rivo volumio[3331]: info: CoreCommandRouter::volumioGetState Feb 17 23:33:25 rivo volumio[3331]: info: CoreCommandRouter::servicePushState Feb 17 23:33:25 rivo volumio[3331]: info: CoreStateMachine::pushState Feb 17 23:33:25 rivo volumio[3331]: info: CoreCommandRouter::volumioPushState Feb 17 23:33:25 rivo volumio[3331]: info: CoreCommandRouter::volumioGetState Feb 17 23:33:25 rivo volumio[3331]: info: MRS: Pushing multiroomSync output update for this device Feb 17 23:33:25 rivo volumio[3331]: info: MRS: Pushing multiroomSync output Feb 17 23:33:25 rivo volumio[3331]: info: Signalling Playback active due to playback status change Feb 17 23:33:25 rivo qobuz-connect[3908]: 20260217 23:33:25.354 [3908.3908] INFO AudioStreamManager: [0xac33f250]: [Stream 4]: stream information have been fetched Feb 17 23:33:25 rivo qobuz-connect[3908]: 20260217 23:33:25.354 [3908.3908] INFO AudioStreamManager: [0xac33f250]: [Stream 4]: track URL resolved to: https://streaming-qobuz-std.akamaized.net/file?uid=4637524&eid=163677068&fmt=7&profile=raw&app_id=174516466&cid=3766108&etsp=1771364005&hmac=vlV5BHxHPd9wDXobWbqE_ygN9VA Feb 17 23:33:25 rivo qobuz-connect[3908]: 20260217 23:33:25.354 [3908.3908] INFO AudioStreamManager: [0xac33f250]: [Stream 3]: Metadata became available: Feb 17 23:33:25 rivo qobuz-connect[3908]: 20260217 23:33:25.354 [3908.3908] INFO AudioStreamManager: [0xac33f250]: Title: Los Chicos Tristes Feb 17 23:33:25 rivo qobuz-connect[3908]: 20260217 23:33:25.354 [3908.3908] INFO AudioStreamManager: [0xac33f250]: Artist: Hermanos Gutierrez Feb 17 23:33:25 rivo qobuz-connect[3908]: 20260217 23:33:25.354 [3908.3908] INFO AudioStreamManager: [0xac33f250]: Album: El Bueno Y El Malo Feb 17 23:33:25 rivo qobuz-connect[3908]: 20260217 23:33:25.354 [3908.3908] INFO AudioStreamManager: [0xac33f250]: Album art URL: https://static.qobuz.com/images/covers/0b/qa/kvetrucgdqa0b_600.jpg Feb 17 23:33:25 rivo qobuz-connect[3908]: 20260217 23:33:25.355 [3908.3908] INFO SampleApp: [Stream 3]: Stream metadata became available: Feb 17 23:33:25 rivo qobuz-connect[3908]: 20260217 23:33:25.355 [3908.3908] INFO SampleApp: Title: Los Chicos Tristes Feb 17 23:33:25 rivo qobuz-connect[3908]: 20260217 23:33:25.355 [3908.3908] INFO SampleApp: Artist: Hermanos Gutierrez Feb 17 23:33:25 rivo qobuz-connect[3908]: 20260217 23:33:25.355 [3908.3908] INFO SampleApp: Album: El Bueno Y El Malo Feb 17 23:33:25 rivo qobuz-connect[3908]: 20260217 23:33:25.355 [3908.3908] INFO SampleApp: Album art URL: https://static.qobuz.com/images/covers/0b/qa/kvetrucgdqa0b_600.jpg Feb 17 23:33:25 rivo volumio[3331]: info: [LastFM] Current track does not have sufficient metadata: Missing artist. Not a composite title! Feb 17 23:33:25 rivo volumio[3331]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 17 23:33:25 rivo volumio[3331]: TypeError: Cannot read property 'indexOf' of undefined Feb 17 23:33:25 rivo volumio[3331]: at ControllerLastFM.formatScrobbleData (/data/plugins/user_interface/lastfm/index.js:873:25) Feb 17 23:33:25 rivo volumio[3331]: at ControllerLastFM.checkStateUpdate (/data/plugins/user_interface/lastfm/index.js:825:26) Feb 17 23:33:25 rivo volumio[3331]: at Socket. (/data/plugins/user_interface/lastfm/index.js:110:52) Feb 17 23:33:25 rivo volumio[3331]: at Socket.Emitter.emit (/data/plugins/user_interface/lastfm/node_modules/component-emitter/index.js:133:20) Feb 17 23:33:25 rivo volumio[3331]: at Socket.onevent (/data/plugins/user_interface/lastfm/node_modules/socket.io-client/lib/socket.js:270:10) Feb 17 23:33:25 rivo volumio[3331]: at Socket.onpacket (/data/plugins/user_interface/lastfm/node_modules/socket.io-client/lib/socket.js:228:12) Feb 17 23:33:25 rivo volumio[3331]: at Manager. (/data/plugins/user_interface/lastfm/node_modules/component-bind/index.js:21:15) Feb 17 23:33:25 rivo volumio[3331]: at Manager.Emitter.emit (/data/plugins/user_interface/lastfm/node_modules/component-emitter/index.js:133:20) Feb 17 23:33:25 rivo volumio[3331]: at Manager.ondecoded (/data/plugins/user_interface/lastfm/node_modules/socket.io-client/lib/manager.js:332:8) Feb 17 23:33:25 rivo volumio[3331]: at Decoder. (/data/plugins/user_interface/lastfm/node_modules/component-bind/index.js:21:15) Feb 17 23:33:25 rivo volumio[3331]: at Decoder.Emitter.emit (/data/plugins/user_interface/lastfm/node_modules/socket.io-parser/node_modules/component-emitter/index.js:134:20) Feb 17 23:33:25 rivo volumio[3331]: at Decoder.add (/data/plugins/user_interface/lastfm/node_modules/socket.io-parser/index.js:246:12) Feb 17 23:33:25 rivo volumio[3331]: at Manager.ondata (/data/plugins/user_interface/lastfm/node_modules/socket.io-client/lib/manager.js:322:16) Feb 17 23:33:25 rivo volumio[3331]: at Socket. (/data/plugins/user_interface/lastfm/node_modules/component-bind/index.js:21:15) Feb 17 23:33:25 rivo volumio[3331]: at Socket.Emitter.emit (/data/plugins/user_interface/lastfm/node_modules/component-emitter/index.js:133:20) Feb 17 23:33:25 rivo volumio[3331]: at Socket.onPacket (/data/plugins/user_interface/lastfm/node_modules/engine.io-client/lib/socket.js:451:14) Feb 17 23:33:25 rivo volumio[3331]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 17 23:33:25 rivo qobuz-connect[3908]: 20260217 23:33:25.723 [3908.3908] INFO UrlAudioSource: [0xac34b2e0]: Content info extracted Feb 17 23:33:25 rivo qobuz-connect[3908]: 20260217 23:33:25.723 [3908.3908] INFO UrlAudioSource: [0xac34b2e0]: Size: 43777602 Feb 17 23:33:25 rivo qobuz-connect[3908]: 20260217 23:33:25.726 [3908.6121] INFO AudioDecoder: [0xac572a20]: Stream info: Feb 17 23:33:25 rivo qobuz-connect[3908]: 20260217 23:33:25.726 [3908.6121] INFO AudioDecoder: [0xac572a20]: Total samples: 11011499 Feb 17 23:33:25 rivo qobuz-connect[3908]: 20260217 23:33:25.726 [3908.6121] INFO AudioDecoder: [0xac572a20]: Sample rate: 48000 Feb 17 23:33:25 rivo qobuz-connect[3908]: 20260217 23:33:25.726 [3908.6121] INFO AudioDecoder: [0xac572a20]: Channel count: 2 Feb 17 23:33:25 rivo qobuz-connect[3908]: 20260217 23:33:25.726 [3908.6121] INFO AudioDecoder: [0xac572a20]: Bits per sample: 24 Feb 17 23:33:25 rivo qobuz-connect[3908]: 20260217 23:33:25.726 [3908.6121] INFO AudioDecoder: [0xac572a20]: Duration: 229406 Feb 17 23:33:25 rivo qobuz-connect[3908]: 20260217 23:33:25.728 [3908.3908] INFO UrlAudioSource: [0xac34b2e0]: Audio properties have changed Feb 17 23:33:26 rivo sudo[6140]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2026-02-17 23:32 Feb 17 23:33:26 rivo sudo[6140]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Debian GNU/Linux 10 (buster)" NAME="Debian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster 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="e9612ec5034fb2e958508aaefbca2962fd6f6654" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="c1ffe93b2136013fc1b5903a4ed7e3f34e0a7bec" VOLUMIO_ARCH="armv7" VOLUMIO_VARIANT="rivo" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Thu 05 Feb 2026 02:25:23 PM CET" VOLUMIO_VERSION="3.908" VOLUMIO_HARDWARE="mp1" VOLUMIO_DEVICENAME="Volumio MP1" VOLUMIO_VENDOR_MODEL="Volumio Rivo" VOLUMIO_VENDOR="Volumio" VOLUMIO_MODEL="Rivo" VOLUMIO_HASH="ab3f2fa07b5f7b8b5e7143217bee70a8"