-- Logs begin at Sat 2024-03-30 12:00:52 CET, end at Sun 2024-03-31 19:27:48 CEST. -- Mar 31 19:26:29 rivo volumio[5432]: info: Preload queue cleared Mar 31 19:26:29 rivo volumio[5432]: info: CoreCommandRouter::volumioReplaceandPlayItems Mar 31 19:26:29 rivo volumio[5432]: info: CoreStateMachine::ClearQueue Mar 31 19:26:29 rivo volumio[5432]: info: CoreStateMachine::stop Mar 31 19:26:29 rivo volumio[5432]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 31 19:26:29 rivo volumio[5432]: info: CoreStateMachine::stPlaybackTimer Mar 31 19:26:29 rivo volumio[5432]: info: CoreStateMachine::updateTrackBlock Mar 31 19:26:29 rivo volumio[5432]: info: CorePlayQueue::getTrackBlock Mar 31 19:26:29 rivo volumio[5432]: info: CoreStateMachine::pushState Mar 31 19:26:29 rivo volumio[5432]: info: CorePlayQueue::getTrack 23 Mar 31 19:26:29 rivo volumio[5432]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 31 19:26:29 rivo volumio[5432]: info: CoreCommandRouter::volumioPushState Mar 31 19:26:29 rivo volumio[5432]: info: MRS: Pushing multiroomSync output update for this device Mar 31 19:26:29 rivo volumio[5432]: info: MRS: Pushing multiroomSync output Mar 31 19:26:29 rivo volumio[5432]: info: CoreStateMachine::serviceStop Mar 31 19:26:29 rivo volumio[5432]: info: CorePlayQueue::getTrack 23 Mar 31 19:26:29 rivo volumio[5432]: info: CoreCommandRouter::serviceStop Mar 31 19:26:29 rivo volumio[5432]: info: [1711905989339] ControllerQobuz::stop Mar 31 19:26:29 rivo volumio[5432]: info: CoreStateMachine::setConsumeUpdateService mpd Mar 31 19:26:29 rivo volumio[5432]: info: ControllerMpd::stop Mar 31 19:26:29 rivo volumio[5432]: verbose: ControllerMpd::sendMpdCommand stop Mar 31 19:26:29 rivo volumio[5432]: info: CorePlayQueue::clearPlayQueue Mar 31 19:26:29 rivo volumio[5432]: info: CorePlayQueue::saveQueue Mar 31 19:26:29 rivo volumio[5432]: info: CoreCommandRouter::volumioPushQueue Mar 31 19:26:29 rivo volumio[5432]: info: CoreStateMachine::addQueueItems Mar 31 19:26:29 rivo volumio[5432]: info: CorePlayQueue::addQueueItems Mar 31 19:26:29 rivo volumio[5432]: info: Preload queue cleared Mar 31 19:26:29 rivo volumio[5432]: info: Adding Item to queue: qobuz://song/1013077 Mar 31 19:26:29 rivo volumio[5432]: info: Exploding uri qobuz://song/1013077 in service qobuz Mar 31 19:26:29 rivo volumio[5432]: info: Adding Item to queue: qobuz://song/1013071 Mar 31 19:26:29 rivo volumio[5432]: info: Exploding uri qobuz://song/1013071 in service qobuz Mar 31 19:26:29 rivo volumio[5432]: info: Adding Item to queue: qobuz://song/1013078 Mar 31 19:26:29 rivo volumio[5432]: info: Exploding uri qobuz://song/1013078 in service qobuz Mar 31 19:26:29 rivo volumio[5432]: info: Adding Item to queue: qobuz://song/1013079 Mar 31 19:26:29 rivo volumio[5432]: info: Exploding uri qobuz://song/1013079 in service qobuz Mar 31 19:26:29 rivo volumio[5432]: info: Adding Item to queue: qobuz://song/1013080 Mar 31 19:26:29 rivo volumio[5432]: info: Exploding uri qobuz://song/1013080 in service qobuz Mar 31 19:26:29 rivo volumio[5432]: info: Updating RAAT Signal Path Mar 31 19:26:29 rivo volumio[5432]: info: Mar 31 19:26:29 rivo volumio[5432]: ---------------------------- MPD announces state update: player Mar 31 19:26:29 rivo volumio[5432]: info: sendMpdCommand stop took 53 milliseconds Mar 31 19:26:29 rivo volumio[5432]: info: ControllerMpd::getState Mar 31 19:26:29 rivo volumio[5432]: verbose: ControllerMpd::sendMpdCommand status Mar 31 19:26:29 rivo volumio[5432]: info: sendMpdCommand status took 15 milliseconds Mar 31 19:26:29 rivo volumio[5432]: verbose: ControllerMpd::parseState Mar 31 19:26:29 rivo volumio[5432]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 31 19:26:29 rivo volumio[5432]: info: sendMpdCommand playlistinfo took 2 milliseconds Mar 31 19:26:29 rivo volumio[5432]: verbose: ControllerMpd::parseTrackInfo Mar 31 19:26:29 rivo volumio[5432]: info: ControllerMpd::pushState Mar 31 19:26:29 rivo volumio[5432]: info: CoreCommandRouter::servicePushState Mar 31 19:26:29 rivo volumio[5432]: info: CoreStateMachine::pushState Mar 31 19:26:29 rivo volumio[5432]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 31 19:26:29 rivo volumio[5432]: info: CoreCommandRouter::volumioPushState Mar 31 19:26:29 rivo volumio[5432]: info: MRS: Pushing multiroomSync output update for this device Mar 31 19:26:29 rivo volumio[5432]: info: MRS: Pushing multiroomSync output Mar 31 19:26:29 rivo volumio[5432]: info: CorePlayQueue::getTrack 23 Mar 31 19:26:29 rivo volumio[5432]: verbose: STATE SERVICE {"status":"stop","position":0,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"1235206","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=qobuz://song/1235206","trackType":"qobuz"} Mar 31 19:26:29 rivo volumio[5432]: verbose: CURRENT POSITION 23 Mar 31 19:26:29 rivo volumio[5432]: info: CoreStateMachine::syncState stateService stop Mar 31 19:26:29 rivo volumio[5432]: info: CoreStateMachine::syncState currentStatus stop Mar 31 19:26:29 rivo volumio[5432]: info: CoreStateMachine::pushState Mar 31 19:26:29 rivo volumio[5432]: info: CoreCommandRouter::volumioPushState Mar 31 19:26:29 rivo volumio[5432]: info: MRS: Pushing multiroomSync output update for this device Mar 31 19:26:29 rivo volumio[5432]: info: MRS: Pushing multiroomSync output Mar 31 19:26:29 rivo volumio[5432]: info: No code Mar 31 19:26:29 rivo volumio[5432]: info: CoreStateMachine::pushState Mar 31 19:26:29 rivo volumio[5432]: info: CoreCommandRouter::volumioPushState Mar 31 19:26:29 rivo volumio[5432]: info: MRS: Pushing multiroomSync output update for this device Mar 31 19:26:29 rivo volumio[5432]: info: MRS: Pushing multiroomSync output Mar 31 19:26:29 rivo volumio[5432]: info: ------------------------------ 49ms Mar 31 19:26:29 rivo volumio[5432]: info: MCU Signalled Playback Inactive Mar 31 19:26:29 rivo volumio[5432]: info: Signalling Playback active due to playback status change Mar 31 19:26:29 rivo volumio[5432]: info: Updating RAAT Signal Path Mar 31 19:26:29 rivo volumio[5432]: info: Signalling Playback active due to playback status change Mar 31 19:26:29 rivo volumio[5432]: info: Signalling Playback active due to playback status change Mar 31 19:26:29 rivo volumio[5432]: info: Updating RAAT Signal Path Mar 31 19:26:29 rivo volumio[5432]: info: Updating RAAT Signal Path Mar 31 19:26:29 rivo volumio[5432]: info: MCU Signalled Playback Active Mar 31 19:26:29 rivo volumio[5432]: info: explodeUri took 439 milliseconds Mar 31 19:26:29 rivo volumio[5432]: info: explodeUri took 481 milliseconds Mar 31 19:26:29 rivo volumio[5432]: info: explodeUri took 486 milliseconds Mar 31 19:26:29 rivo volumio[5432]: info: explodeUri took 494 milliseconds Mar 31 19:26:29 rivo volumio[5432]: info: explodeUri took 500 milliseconds Mar 31 19:26:29 rivo volumio[5432]: info: CoreCommandRouter::volumioPushQueue Mar 31 19:26:29 rivo volumio[5432]: info: CorePlayQueue::saveQueue Mar 31 19:26:29 rivo volumio[5432]: info: CoreStateMachine::updateTrackBlock Mar 31 19:26:29 rivo volumio[5432]: info: CorePlayQueue::getTrackBlock Mar 31 19:26:29 rivo volumio[5432]: info: CoreCommandRouter::volumioPlay Mar 31 19:26:29 rivo volumio[5432]: info: CoreStateMachine::play index 0 Mar 31 19:26:29 rivo volumio[5432]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 31 19:26:29 rivo volumio[5432]: info: CoreStateMachine::stop Mar 31 19:26:29 rivo volumio[5432]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 31 19:26:29 rivo volumio[5432]: info: CoreStateMachine::play index undefined Mar 31 19:26:29 rivo volumio[5432]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 31 19:26:29 rivo volumio[5432]: info: CorePlayQueue::getTrack 0 Mar 31 19:26:29 rivo volumio[5432]: info: CoreStateMachine::startPlaybackTimer Mar 31 19:26:29 rivo volumio[5432]: info: CorePlayQueue::getTrack 0 Mar 31 19:26:29 rivo volumio[5432]: info: [1711905989858] ControllerQobuz::clearAddPlayTrack Mar 31 19:26:29 rivo volumio[5432]: verbose: ControllerMpd::sendMpdCommand stop Mar 31 19:26:29 rivo volumio[5432]: info: sendMpdCommand stop took 3 milliseconds Mar 31 19:26:29 rivo volumio[5432]: verbose: ControllerMpd::sendMpdCommand clear Mar 31 19:26:29 rivo volumio[5432]: info: Mar 31 19:26:29 rivo volumio[5432]: ---------------------------- MPD announces system playlist update Mar 31 19:26:29 rivo volumio[5432]: info: Ignoring MPD Status Update Mar 31 19:26:29 rivo volumio[5432]: info: sendMpdCommand clear took 4 milliseconds Mar 31 19:26:29 rivo volumio[5432]: verbose: ControllerMpd::sendMpdCommand load "http://127.0.0.1:3245?data=qobuz://song/1013077" Mar 31 19:26:29 rivo volumio[5432]: error: updateQueue error: null Mar 31 19:26:29 rivo volumio[5432]: info: ------------------------------ 4ms Mar 31 19:26:29 rivo volumio[5432]: STREAMING PROXY: Handling url /?data=qobuz://song/1013077 Mar 31 19:26:29 rivo volumio[5432]: info: Executing endpoint getStreamUrlqobuz Mar 31 19:26:29 rivo volumio[5432]: info: CoreCommandRouter::executeOnPlugin: qobuz , getStreamUrlAPI Mar 31 19:26:30 rivo volumio[5432]: info: getStreamUrl took 302 milliseconds Mar 31 19:26:30 rivo volumio[5432]: STREAMING PROXY: Got real url: http://streaming-qobuz-std.akamaized.net:80/file?uid=2801117&eid=1013077&fmt=6&profile=raw&app_id=539451548&cid=1966015&etsp=1711909590&hmac=iJZOjNzTSf1BwgC8Bd0lS0mtx_o Mar 31 19:26:30 rivo volumio[5432]: STREAMING PROXY: Response: 200, length: 13245063 Mar 31 19:26:30 rivo volumio[5432]: STREAMING PROXY: Client dropped request, destroying Mar 31 19:26:30 rivo volumio[5432]: verbose: ControllerMpd::sendMpdCommand add "http://127.0.0.1:3245?data=qobuz://song/1013077" Mar 31 19:26:30 rivo volumio[5432]: info: Mar 31 19:26:30 rivo volumio[5432]: ---------------------------- MPD announces system playlist update Mar 31 19:26:30 rivo volumio[5432]: info: Ignoring MPD Status Update Mar 31 19:26:30 rivo volumio[5432]: info: sendMpdCommand add "http://127.0.0.1:3245?data=qobuz://song/1013077" took 2 milliseconds Mar 31 19:26:30 rivo volumio[5432]: info: CoreStateMachine::setConsumeUpdateService mpd Mar 31 19:26:30 rivo volumio[5432]: verbose: ControllerMpd::sendMpdCommand play Mar 31 19:26:30 rivo volumio[5432]: info: ------------------------------ 3ms Mar 31 19:26:30 rivo volumio[5432]: info: sendMpdCommand play took 2 milliseconds Mar 31 19:26:30 rivo volumio[5432]: STREAMING PROXY: Handling url /?data=qobuz://song/1013077 Mar 31 19:26:30 rivo volumio[5432]: info: Executing endpoint getStreamUrlqobuz Mar 31 19:26:30 rivo volumio[5432]: info: CoreCommandRouter::executeOnPlugin: qobuz , getStreamUrlAPI Mar 31 19:26:30 rivo volumio[5432]: info: getStreamUrl took 309 milliseconds Mar 31 19:26:30 rivo volumio[5432]: STREAMING PROXY: Got real url: http://streaming-qobuz-std.akamaized.net:80/file?uid=2801117&eid=1013077&fmt=6&profile=raw&app_id=539451548&cid=1966015&etsp=1711909590&hmac=iJZOjNzTSf1BwgC8Bd0lS0mtx_o Mar 31 19:26:30 rivo volumio[5432]: STREAMING PROXY: Response: 200, length: 13245063 Mar 31 19:26:30 rivo volumio[5432]: info: Mar 31 19:26:30 rivo volumio[5432]: ---------------------------- MPD announces state update: player Mar 31 19:26:30 rivo volumio[5432]: info: ControllerMpd::getState Mar 31 19:26:30 rivo volumio[5432]: verbose: ControllerMpd::sendMpdCommand status Mar 31 19:26:30 rivo volumio[5432]: info: sendMpdCommand status took 26 milliseconds Mar 31 19:26:30 rivo volumio[5432]: verbose: ControllerMpd::parseState Mar 31 19:26:30 rivo volumio[5432]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 31 19:26:30 rivo volumio[5432]: info: Mar 31 19:26:30 rivo volumio[5432]: ---------------------------- MPD announces state update: player Mar 31 19:26:30 rivo volumio[5432]: info: ControllerMpd::getState Mar 31 19:26:30 rivo volumio[5432]: verbose: ControllerMpd::sendMpdCommand status Mar 31 19:26:30 rivo volumio[5432]: info: sendMpdCommand playlistinfo took 4 milliseconds Mar 31 19:26:30 rivo volumio[5432]: verbose: ControllerMpd::parseTrackInfo Mar 31 19:26:30 rivo volumio[5432]: info: ControllerMpd::pushState Mar 31 19:26:30 rivo volumio[5432]: info: CoreCommandRouter::servicePushState Mar 31 19:26:30 rivo volumio[5432]: info: CorePlayQueue::getTrack 0 Mar 31 19:26:30 rivo volumio[5432]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":179,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"1013077","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=qobuz://song/1013077","trackType":"qobuz"} Mar 31 19:26:30 rivo volumio[5432]: verbose: CURRENT POSITION 0 Mar 31 19:26:30 rivo volumio[5432]: info: CoreStateMachine::syncState stateService play Mar 31 19:26:30 rivo volumio[5432]: info: CoreStateMachine::syncState currentStatus stop Mar 31 19:26:30 rivo volumio[5432]: info: ------------------------------ 42ms Mar 31 19:26:30 rivo volumio[5432]: info: sendMpdCommand status took 9 milliseconds Mar 31 19:26:30 rivo volumio[5432]: verbose: ControllerMpd::parseState Mar 31 19:26:30 rivo volumio[5432]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 31 19:26:30 rivo volumio[5432]: info: sendMpdCommand playlistinfo took 2 milliseconds Mar 31 19:26:30 rivo volumio[5432]: verbose: ControllerMpd::parseTrackInfo Mar 31 19:26:30 rivo volumio[5432]: info: ControllerMpd::pushState Mar 31 19:26:30 rivo volumio[5432]: info: CoreCommandRouter::servicePushState Mar 31 19:26:30 rivo volumio[5432]: info: CorePlayQueue::getTrack 0 Mar 31 19:26:30 rivo volumio[5432]: verbose: STATE SERVICE {"status":"play","position":0,"seek":1212,"duration":179,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"605 Kbps","isStreaming":false,"title":"1013077","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=qobuz://song/1013077","trackType":"qobuz"} Mar 31 19:26:30 rivo volumio[5432]: verbose: CURRENT POSITION 0 Mar 31 19:26:30 rivo volumio[5432]: info: CoreStateMachine::syncState stateService play Mar 31 19:26:30 rivo volumio[5432]: info: CoreStateMachine::syncState currentStatus play Mar 31 19:26:30 rivo volumio[5432]: info: Received an update from plugin. extracting info from payload Mar 31 19:26:30 rivo volumio[5432]: info: CoreStateMachine::pushState Mar 31 19:26:30 rivo volumio[5432]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 31 19:26:30 rivo volumio[5432]: info: CoreCommandRouter::volumioPushState Mar 31 19:26:30 rivo volumio[5432]: info: MRS: Pushing multiroomSync output update for this device Mar 31 19:26:30 rivo volumio[5432]: info: MRS: Pushing multiroomSync output Mar 31 19:26:30 rivo volumio[5432]: info: CoreStateMachine::pushState Mar 31 19:26:30 rivo volumio[5432]: info: CoreCommandRouter::volumioPushState Mar 31 19:26:30 rivo volumio[5432]: info: MRS: Pushing multiroomSync output update for this device Mar 31 19:26:30 rivo volumio[5432]: info: MRS: Pushing multiroomSync output Mar 31 19:26:30 rivo volumio[5432]: info: ------------------------------ 59ms Mar 31 19:26:30 rivo volumio[5432]: info: Signalling Playback active due to playback status change Mar 31 19:26:30 rivo volumio[5432]: info: Updating RAAT Signal Path Mar 31 19:26:30 rivo volumio[5432]: info: Signalling Playback active due to playback status change Mar 31 19:26:30 rivo volumio[5432]: info: Updating RAAT Signal Path Mar 31 19:26:32 rivo volumio[5432]: STREAMING PROXY: Client dropped request, destroying Mar 31 19:26:33 rivo volumio[5432]: info: Executing endpoint metavolumio Mar 31 19:26:33 rivo volumio[5432]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Mar 31 19:26:33 rivo volumio[5432]: info: Executing endpoint metavolumio Mar 31 19:26:33 rivo volumio[5432]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Mar 31 19:26:33 rivo volumio[5432]: info: Executing endpoint metavolumio Mar 31 19:26:33 rivo volumio[5432]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Mar 31 19:26:44 rivo volumio[5432]: info: CorePlayQueue::getTrack 0 Mar 31 19:26:44 rivo volumio[5432]: info: CoreCommandRouter::executeOnPlugin: qobuz , goto Mar 31 19:26:45 rivo volumio[5432]: info: explodeUri took 272 milliseconds Mar 31 19:26:45 rivo volumio[5432]: info: handleBrowseUri took 682 milliseconds Mar 31 19:26:45 rivo volumio[5432]: info: Executing endpoint getSimilarAlbums Mar 31 19:26:45 rivo volumio[5432]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getSimilarAlbums Mar 31 19:26:45 rivo volumio[5432]: info: Executing endpoint getSimilarAlbums Mar 31 19:26:45 rivo volumio[5432]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getSimilarAlbums Mar 31 19:26:46 rivo volumio[5432]: info: Executing endpoint metavolumio Mar 31 19:26:46 rivo volumio[5432]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Mar 31 19:26:46 rivo volumio[5432]: info: Executing endpoint metavolumio Mar 31 19:26:46 rivo volumio[5432]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Mar 31 19:26:46 rivo volumio[5432]: info: Executing endpoint metavolumio Mar 31 19:26:46 rivo volumio[5432]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Mar 31 19:26:46 rivo volumio[5432]: info: Executing endpoint metavolumio Mar 31 19:26:46 rivo volumio[5432]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Mar 31 19:26:52 rivo volumio[5432]: info: Preload queue cleared Mar 31 19:26:52 rivo volumio[5432]: info: CoreCommandRouter::volumioReplaceandPlayItems Mar 31 19:26:52 rivo volumio[5432]: info: CoreStateMachine::ClearQueue Mar 31 19:26:52 rivo volumio[5432]: info: CoreStateMachine::stop Mar 31 19:26:52 rivo volumio[5432]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 31 19:26:52 rivo volumio[5432]: info: CoreStateMachine::stPlaybackTimer Mar 31 19:26:52 rivo volumio[5432]: info: CoreStateMachine::updateTrackBlock Mar 31 19:26:52 rivo volumio[5432]: info: CorePlayQueue::getTrackBlock Mar 31 19:26:52 rivo volumio[5432]: info: CoreStateMachine::pushState Mar 31 19:26:52 rivo volumio[5432]: info: CorePlayQueue::getTrack 0 Mar 31 19:26:52 rivo volumio[5432]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 31 19:26:52 rivo volumio[5432]: info: CoreCommandRouter::volumioPushState Mar 31 19:26:52 rivo volumio[5432]: info: MRS: Pushing multiroomSync output update for this device Mar 31 19:26:52 rivo volumio[5432]: info: MRS: Pushing multiroomSync output Mar 31 19:26:52 rivo volumio[5432]: info: CoreStateMachine::serviceStop Mar 31 19:26:52 rivo volumio[5432]: info: CorePlayQueue::getTrack 0 Mar 31 19:26:52 rivo volumio[5432]: info: CoreCommandRouter::serviceStop Mar 31 19:26:52 rivo volumio[5432]: info: [1711906012787] ControllerQobuz::stop Mar 31 19:26:52 rivo volumio[5432]: info: CoreStateMachine::setConsumeUpdateService mpd Mar 31 19:26:52 rivo volumio[5432]: info: ControllerMpd::stop Mar 31 19:26:52 rivo volumio[5432]: verbose: ControllerMpd::sendMpdCommand stop Mar 31 19:26:52 rivo volumio[5432]: info: CorePlayQueue::clearPlayQueue Mar 31 19:26:52 rivo volumio[5432]: info: CorePlayQueue::saveQueue Mar 31 19:26:52 rivo volumio[5432]: info: CoreCommandRouter::volumioPushQueue Mar 31 19:26:52 rivo volumio[5432]: info: CoreStateMachine::addQueueItems Mar 31 19:26:52 rivo volumio[5432]: info: CorePlayQueue::addQueueItems Mar 31 19:26:52 rivo volumio[5432]: info: Preload queue cleared Mar 31 19:26:52 rivo volumio[5432]: info: Adding Item to queue: qobuz://album/0724354536656 Mar 31 19:26:52 rivo volumio[5432]: info: Exploding uri qobuz://album/0724354536656 in service qobuz Mar 31 19:26:52 rivo volumio[5432]: info: Updating RAAT Signal Path Mar 31 19:26:52 rivo volumio[5432]: info: Mar 31 19:26:52 rivo volumio[5432]: ---------------------------- MPD announces state update: player Mar 31 19:26:52 rivo volumio[5432]: info: sendMpdCommand stop took 53 milliseconds Mar 31 19:26:52 rivo volumio[5432]: info: ControllerMpd::getState Mar 31 19:26:52 rivo volumio[5432]: verbose: ControllerMpd::sendMpdCommand status Mar 31 19:26:52 rivo volumio[5432]: info: sendMpdCommand status took 3 milliseconds Mar 31 19:26:52 rivo volumio[5432]: verbose: ControllerMpd::parseState Mar 31 19:26:52 rivo volumio[5432]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 31 19:26:52 rivo volumio[5432]: info: sendMpdCommand playlistinfo took 2 milliseconds Mar 31 19:26:52 rivo volumio[5432]: verbose: ControllerMpd::parseTrackInfo Mar 31 19:26:52 rivo volumio[5432]: info: ControllerMpd::pushState Mar 31 19:26:52 rivo volumio[5432]: info: CoreCommandRouter::servicePushState Mar 31 19:26:52 rivo volumio[5432]: info: CoreStateMachine::pushState Mar 31 19:26:52 rivo volumio[5432]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 31 19:26:52 rivo volumio[5432]: info: CoreCommandRouter::volumioPushState Mar 31 19:26:52 rivo volumio[5432]: info: MRS: Pushing multiroomSync output update for this device Mar 31 19:26:52 rivo volumio[5432]: info: MRS: Pushing multiroomSync output Mar 31 19:26:52 rivo volumio[5432]: info: CorePlayQueue::getTrack 0 Mar 31 19:26:52 rivo volumio[5432]: verbose: STATE SERVICE {"status":"stop","position":0,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"1013077","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=qobuz://song/1013077","trackType":"qobuz"} Mar 31 19:26:52 rivo volumio[5432]: verbose: CURRENT POSITION 0 Mar 31 19:26:52 rivo volumio[5432]: info: CoreStateMachine::syncState stateService stop Mar 31 19:26:52 rivo volumio[5432]: info: CoreStateMachine::syncState currentStatus stop Mar 31 19:26:52 rivo volumio[5432]: info: CoreStateMachine::pushState Mar 31 19:26:52 rivo volumio[5432]: info: CoreCommandRouter::volumioPushState Mar 31 19:26:52 rivo volumio[5432]: info: MRS: Pushing multiroomSync output update for this device Mar 31 19:26:52 rivo volumio[5432]: info: MRS: Pushing multiroomSync output Mar 31 19:26:52 rivo volumio[5432]: info: No code Mar 31 19:26:52 rivo volumio[5432]: info: CoreStateMachine::pushState Mar 31 19:26:52 rivo volumio[5432]: info: CoreCommandRouter::volumioPushState Mar 31 19:26:52 rivo volumio[5432]: info: MRS: Pushing multiroomSync output update for this device Mar 31 19:26:52 rivo volumio[5432]: info: MRS: Pushing multiroomSync output Mar 31 19:26:52 rivo volumio[5432]: info: ------------------------------ 52ms Mar 31 19:26:52 rivo volumio[5432]: info: Signalling Playback active due to playback status change Mar 31 19:26:52 rivo volumio[5432]: info: Updating RAAT Signal Path Mar 31 19:26:52 rivo volumio[5432]: info: MCU Signalled Playback Inactive Mar 31 19:26:52 rivo volumio[5432]: info: MCU Signalled Playback Active Mar 31 19:26:52 rivo volumio[5432]: info: Signalling Playback active due to playback status change Mar 31 19:26:52 rivo volumio[5432]: info: Signalling Playback active due to playback status change Mar 31 19:26:52 rivo volumio[5432]: info: Updating RAAT Signal Path Mar 31 19:26:52 rivo volumio[5432]: info: Updating RAAT Signal Path Mar 31 19:26:53 rivo volumio[5432]: error: Failed request for metavolumio API Mar 31 19:26:53 rivo volumio[5432]: error: Failed request for metavolumio API Mar 31 19:26:53 rivo volumio[5432]: info: explodeUri took 477 milliseconds Mar 31 19:26:53 rivo volumio[5432]: info: CoreCommandRouter::volumioPushQueue Mar 31 19:26:53 rivo volumio[5432]: info: CorePlayQueue::saveQueue Mar 31 19:26:53 rivo volumio[5432]: info: CoreStateMachine::updateTrackBlock Mar 31 19:26:53 rivo volumio[5432]: info: CorePlayQueue::getTrackBlock Mar 31 19:26:53 rivo volumio[5432]: info: CoreCommandRouter::volumioPlay Mar 31 19:26:53 rivo volumio[5432]: info: CoreStateMachine::play index 0 Mar 31 19:26:53 rivo volumio[5432]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 31 19:26:53 rivo volumio[5432]: info: CoreStateMachine::stop Mar 31 19:26:53 rivo volumio[5432]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 31 19:26:53 rivo volumio[5432]: info: CoreStateMachine::play index undefined Mar 31 19:26:53 rivo volumio[5432]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 31 19:26:53 rivo volumio[5432]: info: CorePlayQueue::getTrack 0 Mar 31 19:26:53 rivo volumio[5432]: info: CoreStateMachine::startPlaybackTimer Mar 31 19:26:53 rivo volumio[5432]: info: CorePlayQueue::getTrack 0 Mar 31 19:26:53 rivo volumio[5432]: info: [1711906013298] ControllerQobuz::clearAddPlayTrack Mar 31 19:26:53 rivo volumio[5432]: verbose: ControllerMpd::sendMpdCommand stop Mar 31 19:26:53 rivo volumio[5432]: info: sendMpdCommand stop took 6 milliseconds Mar 31 19:26:53 rivo volumio[5432]: verbose: ControllerMpd::sendMpdCommand clear Mar 31 19:26:53 rivo volumio[5432]: info: Mar 31 19:26:53 rivo volumio[5432]: ---------------------------- MPD announces system playlist update Mar 31 19:26:53 rivo volumio[5432]: info: Ignoring MPD Status Update Mar 31 19:26:53 rivo volumio[5432]: info: sendMpdCommand clear took 14 milliseconds Mar 31 19:26:53 rivo volumio[5432]: verbose: ControllerMpd::sendMpdCommand load "http://127.0.0.1:3245?data=qobuz://song/1013071" Mar 31 19:26:53 rivo volumio[5432]: STREAMING PROXY: Handling url /?data=qobuz://song/1013071 Mar 31 19:26:53 rivo volumio[5432]: error: updateQueue error: null Mar 31 19:26:53 rivo volumio[5432]: info: ------------------------------ 4ms Mar 31 19:26:53 rivo volumio[5432]: info: Executing endpoint getStreamUrlqobuz Mar 31 19:26:53 rivo volumio[5432]: info: CoreCommandRouter::executeOnPlugin: qobuz , getStreamUrlAPI Mar 31 19:26:53 rivo volumio[5432]: info: getStreamUrl took 368 milliseconds Mar 31 19:26:53 rivo volumio[5432]: STREAMING PROXY: Got real url: http://streaming-qobuz-std.akamaized.net:80/file?uid=2801117&eid=1013071&fmt=6&profile=raw&app_id=539451548&cid=1966015&etsp=1711909613&hmac=8W0TVGMQpYBvo8zacyFNr3rJYGE Mar 31 19:26:53 rivo volumio[5432]: STREAMING PROXY: Response: 200, length: 13521734 Mar 31 19:26:54 rivo volumio[5432]: STREAMING PROXY: Client dropped request, destroying Mar 31 19:26:54 rivo volumio[5432]: verbose: ControllerMpd::sendMpdCommand add "http://127.0.0.1:3245?data=qobuz://song/1013071" Mar 31 19:26:54 rivo volumio[5432]: info: Mar 31 19:26:54 rivo volumio[5432]: ---------------------------- MPD announces system playlist update Mar 31 19:26:54 rivo volumio[5432]: info: Ignoring MPD Status Update Mar 31 19:26:54 rivo volumio[5432]: info: sendMpdCommand add "http://127.0.0.1:3245?data=qobuz://song/1013071" took 2 milliseconds Mar 31 19:26:54 rivo volumio[5432]: info: CoreStateMachine::setConsumeUpdateService mpd Mar 31 19:26:54 rivo volumio[5432]: verbose: ControllerMpd::sendMpdCommand play Mar 31 19:26:54 rivo volumio[5432]: info: ------------------------------ 4ms Mar 31 19:26:54 rivo volumio[5432]: info: sendMpdCommand play took 2 milliseconds Mar 31 19:26:54 rivo volumio[5432]: STREAMING PROXY: Handling url /?data=qobuz://song/1013071 Mar 31 19:26:54 rivo volumio[5432]: info: Executing endpoint getStreamUrlqobuz Mar 31 19:26:54 rivo volumio[5432]: info: CoreCommandRouter::executeOnPlugin: qobuz , getStreamUrlAPI Mar 31 19:26:54 rivo volumio[5432]: info: getStreamUrl took 296 milliseconds Mar 31 19:26:54 rivo volumio[5432]: STREAMING PROXY: Got real url: http://streaming-qobuz-std.akamaized.net:80/file?uid=2801117&eid=1013071&fmt=6&profile=raw&app_id=539451548&cid=1966015&etsp=1711909614&hmac=VjqejpuITk3lqHV7cXx49agdBaM Mar 31 19:26:54 rivo volumio[5432]: STREAMING PROXY: Response: 200, length: 13521734 Mar 31 19:26:54 rivo volumio[5432]: info: Mar 31 19:26:54 rivo volumio[5432]: ---------------------------- MPD announces state update: player Mar 31 19:26:54 rivo volumio[5432]: info: ControllerMpd::getState Mar 31 19:26:54 rivo volumio[5432]: verbose: ControllerMpd::sendMpdCommand status Mar 31 19:26:54 rivo volumio[5432]: info: Mar 31 19:26:54 rivo volumio[5432]: ---------------------------- MPD announces state update: player Mar 31 19:26:54 rivo volumio[5432]: info: sendMpdCommand status took 21 milliseconds Mar 31 19:26:54 rivo volumio[5432]: info: ControllerMpd::getState Mar 31 19:26:54 rivo volumio[5432]: verbose: ControllerMpd::sendMpdCommand status Mar 31 19:26:54 rivo volumio[5432]: verbose: ControllerMpd::parseState Mar 31 19:26:54 rivo volumio[5432]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 31 19:26:54 rivo volumio[5432]: info: sendMpdCommand status took 5 milliseconds Mar 31 19:26:54 rivo volumio[5432]: info: sendMpdCommand playlistinfo took 4 milliseconds Mar 31 19:26:54 rivo volumio[5432]: verbose: ControllerMpd::parseState Mar 31 19:26:54 rivo volumio[5432]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 31 19:26:54 rivo volumio[5432]: verbose: ControllerMpd::parseTrackInfo Mar 31 19:26:54 rivo volumio[5432]: info: ControllerMpd::pushState Mar 31 19:26:54 rivo volumio[5432]: info: CoreCommandRouter::servicePushState Mar 31 19:26:54 rivo volumio[5432]: info: CorePlayQueue::getTrack 0 Mar 31 19:26:54 rivo volumio[5432]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":159,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"1013071","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=qobuz://song/1013071","trackType":"qobuz"} Mar 31 19:26:54 rivo volumio[5432]: verbose: CURRENT POSITION 0 Mar 31 19:26:54 rivo volumio[5432]: info: CoreStateMachine::syncState stateService play Mar 31 19:26:54 rivo volumio[5432]: info: CoreStateMachine::syncState currentStatus stop Mar 31 19:26:54 rivo volumio[5432]: info: ------------------------------ 36ms Mar 31 19:26:54 rivo volumio[5432]: info: sendMpdCommand playlistinfo took 6 milliseconds Mar 31 19:26:54 rivo volumio[5432]: verbose: ControllerMpd::parseTrackInfo Mar 31 19:26:54 rivo volumio[5432]: info: ControllerMpd::pushState Mar 31 19:26:54 rivo volumio[5432]: info: CoreCommandRouter::servicePushState Mar 31 19:26:54 rivo volumio[5432]: info: CorePlayQueue::getTrack 0 Mar 31 19:26:54 rivo volumio[5432]: verbose: STATE SERVICE {"status":"play","position":0,"seek":1212,"duration":159,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"758 Kbps","isStreaming":false,"title":"1013071","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=qobuz://song/1013071","trackType":"qobuz"} Mar 31 19:26:54 rivo volumio[5432]: verbose: CURRENT POSITION 0 Mar 31 19:26:54 rivo volumio[5432]: info: CoreStateMachine::syncState stateService play Mar 31 19:26:54 rivo volumio[5432]: info: CoreStateMachine::syncState currentStatus play Mar 31 19:26:54 rivo volumio[5432]: info: Received an update from plugin. extracting info from payload Mar 31 19:26:54 rivo volumio[5432]: info: CoreStateMachine::pushState Mar 31 19:26:54 rivo volumio[5432]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 31 19:26:54 rivo volumio[5432]: info: CoreCommandRouter::volumioPushState Mar 31 19:26:54 rivo volumio[5432]: info: MRS: Pushing multiroomSync output update for this device Mar 31 19:26:54 rivo volumio[5432]: info: MRS: Pushing multiroomSync output Mar 31 19:26:54 rivo volumio[5432]: info: CoreStateMachine::pushState Mar 31 19:26:54 rivo volumio[5432]: info: CoreCommandRouter::volumioPushState Mar 31 19:26:54 rivo volumio[5432]: info: MRS: Pushing multiroomSync output update for this device Mar 31 19:26:54 rivo volumio[5432]: info: MRS: Pushing multiroomSync output Mar 31 19:26:54 rivo volumio[5432]: info: ------------------------------ 53ms Mar 31 19:26:54 rivo volumio[5432]: info: Signalling Playback active due to playback status change Mar 31 19:26:54 rivo volumio[5432]: info: Updating RAAT Signal Path Mar 31 19:26:54 rivo volumio[5432]: info: Signalling Playback active due to playback status change Mar 31 19:26:54 rivo volumio[5432]: info: Updating RAAT Signal Path Mar 31 19:26:55 rivo volumio[5432]: STREAMING PROXY: Client dropped request, destroying Mar 31 19:27:47 rivo volumio[5432]: info: CoreCommandRouter::executeOnPlugin: qobuz , explodeUri Mar 31 19:27:48 rivo volumio[5432]: info: explodeUri took 300 milliseconds Mar 31 19:27:48 rivo volumio[5432]: info: Saving Cloud item A. Scarlatti Stabat Mater Mar 31 19:27:48 rivo volumio[5432]: info: CoreCommandRouter::executeOnPlugin: my_volumio , saveCloudItem Mar 31 19:27:48 rivo volumio[5432]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 31 19:27:48 rivo volumio[5432]: Error: Reference.child failed: First argument was an invalid path = "/user_data/HChUTMmKbaa2hksy3Jz8ffWfeeU2/myPlaylists/A. Scarlatti Stabat Mater". Paths must be non-empty strings and can't contain ".", "#", "$", "[", or "]" Mar 31 19:27:48 rivo volumio[5432]: at validatePathString (/volumio/node_modules/@firebase/database/dist/index.node.cjs.js:1667:15) Mar 31 19:27:48 rivo volumio[5432]: at validateRootPathString (/volumio/node_modules/@firebase/database/dist/index.node.cjs.js:1679:5) Mar 31 19:27:48 rivo volumio[5432]: at Reference.child (/volumio/node_modules/@firebase/database/dist/index.node.cjs.js:13737:17) Mar 31 19:27:48 rivo volumio[5432]: at Database.ref (/volumio/node_modules/@firebase/database/dist/index.node.cjs.js:15115:48) Mar 31 19:27:48 rivo volumio[5432]: at myVolumio.syncJSONToCloud (/myvolumio/plugins/system_controller/my_volumio/my_volumio_real:1:28817) Mar 31 19:27:48 rivo volumio[5432]: at myVolumio.saveCloudMyPlaylist (/myvolumio/plugins/system_controller/my_volumio/my_volumio_real:1:23840) Mar 31 19:27:48 rivo volumio[5432]: at myVolumio.saveCloudItem (/myvolumio/plugins/system_controller/my_volumio/my_volumio_real:1:18337) Mar 31 19:27:48 rivo volumio[5432]: at CoreCommandRouter.executeOnPlugin (/volumio/app/index.js:1077:32) Mar 31 19:27:48 rivo volumio[5432]: at PlaylistManager.saveJSONFile (/volumio/app/playlistManager.js:613:31) Mar 31 19:27:48 rivo volumio[5432]: at /volumio/app/playlistManager.js:588:20 Mar 31 19:27:48 rivo volumio[5432]: at /volumio/node_modules/jsonfile/index.js:46:5 Mar 31 19:27:48 rivo volumio[5432]: at /volumio/node_modules/graceful-fs/graceful-fs.js:123:16 Mar 31 19:27:48 rivo volumio[5432]: at FSReqCallback.readFileAfterClose [as oncomplete] (internal/fs/read_file_context.js:71:3) Mar 31 19:27:48 rivo volumio[5432]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 31 19:27:48 rivo sudo[6752]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-03-31 19:26 Mar 31 19:27:48 rivo sudo[6752]: 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="7f9f1bf001add7a8b19a4516e3c74ef598b2730d" VOLUMIO_FE_VERSION="614d7b13ffdcb0cc5a6072e7d06f59d52e323e71" VOLUMIO_FE3_VERSION="570aaed971c1346d45d1172dc445b086b258c6d1" VOLUMIO_BE_VERSION="e831866afe2db61aee9333a8f5ba9d9fd36609c7" VOLUMIO_ARCH="armv7" VOLUMIO_VARIANT="rivo" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Sun 18 Feb 2024 11:41:55 AM CET" VOLUMIO_VERSION="3.629" VOLUMIO_HARDWARE="mp1" VOLUMIO_DEVICENAME="Volumio MP1" VOLUMIO_VENDOR_MODEL="Volumio Rivo" VOLUMIO_VENDOR="Volumio" VOLUMIO_MODEL="Rivo" VOLUMIO_HASH="b0437c7088d6645a661a49f6d9fa596a"