-- Logs begin at Thu 2019-02-14 05:11:59 EST, end at Mon 2024-05-13 18:37:08 EDT. -- May 13 18:36:00 volumioraspi4 volumio[760]: info: CoreCommandRouter::executeOnPlugin: qobuz , handleBrowseUri May 13 18:36:01 volumioraspi4 volumio[760]: info: handleBrowseUri took 1339 milliseconds May 13 18:36:01 volumioraspi4 volumio[760]: info: Preload queue cleared May 13 18:36:04 volumioraspi4 volumio[760]: info: CoreCommandRouter::executeOnPlugin: qobuz , handleBrowseUri May 13 18:36:05 volumioraspi4 volumio[760]: info: handleBrowseUri took 857 milliseconds May 13 18:36:05 volumioraspi4 volumio[760]: info: Preload queue cleared May 13 18:36:05 volumioraspi4 volumio[760]: info: Preloading song: qobuz://song/239022325 May 13 18:36:05 volumioraspi4 volumio[760]: info: Preloading song: qobuz://song/239022326 May 13 18:36:05 volumioraspi4 volumio[760]: info: Preloading song: qobuz://song/239022327 May 13 18:36:05 volumioraspi4 volumio[760]: info: Preloading song: qobuz://song/239022328 May 13 18:36:05 volumioraspi4 volumio[760]: info: Preloading song: qobuz://song/239022329 May 13 18:36:05 volumioraspi4 volumio[760]: info: Preloading song: qobuz://song/239022330 May 13 18:36:05 volumioraspi4 volumio[760]: info: Preloading song: qobuz://song/239022331 May 13 18:36:05 volumioraspi4 volumio[760]: info: Preloading song: qobuz://song/239022332 May 13 18:36:05 volumioraspi4 volumio[760]: info: Preloading song: qobuz://song/239022333 May 13 18:36:05 volumioraspi4 volumio[760]: info: Preloading song: qobuz://song/239022334 May 13 18:36:05 volumioraspi4 volumio[760]: info: Preloading song: qobuz://song/239022335 May 13 18:36:05 volumioraspi4 volumio[760]: info: Preloading song: qobuz://song/239022336 May 13 18:36:05 volumioraspi4 volumio[760]: info: Exploding uri qobuz://song/239022325 in service qobuz May 13 18:36:05 volumioraspi4 volumio[760]: info: Exploding uri qobuz://song/239022326 in service qobuz May 13 18:36:05 volumioraspi4 volumio[760]: info: Executing endpoint getSimilarAlbums May 13 18:36:05 volumioraspi4 volumio[760]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getSimilarAlbums May 13 18:36:05 volumioraspi4 volumio[760]: info: Executing endpoint getSimilarAlbums May 13 18:36:05 volumioraspi4 volumio[760]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getSimilarAlbums May 13 18:36:05 volumioraspi4 volumio[760]: info: Executing endpoint getSimilarAlbums May 13 18:36:05 volumioraspi4 volumio[760]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getSimilarAlbums May 13 18:36:05 volumioraspi4 volumio[760]: info: Executing endpoint getSimilarAlbums May 13 18:36:05 volumioraspi4 volumio[760]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getSimilarAlbums May 13 18:36:05 volumioraspi4 volumio[760]: info: Exploding uri qobuz://song/239022327 in service qobuz May 13 18:36:05 volumioraspi4 volumio[760]: info: Executing endpoint metavolumio May 13 18:36:05 volumioraspi4 volumio[760]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio May 13 18:36:05 volumioraspi4 volumio[760]: info: Executing endpoint metavolumio May 13 18:36:05 volumioraspi4 volumio[760]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio May 13 18:36:05 volumioraspi4 volumio[760]: info: Exploding uri qobuz://song/239022328 in service qobuz May 13 18:36:05 volumioraspi4 volumio[760]: info: Exploding uri qobuz://song/239022329 in service qobuz May 13 18:36:05 volumioraspi4 volumio[760]: info: Exploding uri qobuz://song/239022330 in service qobuz May 13 18:36:08 volumioraspi4 volumio[760]: info: Exploding uri qobuz://song/239022331 in service qobuz May 13 18:36:08 volumioraspi4 volumio[760]: info: Exploding uri qobuz://song/239022332 in service qobuz May 13 18:36:08 volumioraspi4 volumio[760]: info: Exploding uri qobuz://song/239022333 in service qobuz May 13 18:36:08 volumioraspi4 volumio[760]: info: Exploding uri qobuz://song/239022334 in service qobuz May 13 18:36:08 volumioraspi4 volumio[760]: info: Exploding uri qobuz://song/239022335 in service qobuz May 13 18:36:08 volumioraspi4 volumio[760]: info: Exploding uri qobuz://song/239022336 in service qobuz May 13 18:36:08 volumioraspi4 volumio[760]: info: Preload queue cleared May 13 18:36:08 volumioraspi4 volumio[760]: info: CoreCommandRouter::volumioReplaceandPlayItems May 13 18:36:08 volumioraspi4 volumio[760]: info: CoreStateMachine::ClearQueue May 13 18:36:08 volumioraspi4 volumio[760]: info: CoreStateMachine::stop May 13 18:36:08 volumioraspi4 volumio[760]: info: CoreStateMachine::setConsumeUpdateService undefined May 13 18:36:08 volumioraspi4 volumio[760]: info: CorePlayQueue::clearPlayQueue May 13 18:36:08 volumioraspi4 volumio[760]: info: CorePlayQueue::saveQueue May 13 18:36:08 volumioraspi4 volumio[760]: info: CoreCommandRouter::volumioPushQueue May 13 18:36:08 volumioraspi4 volumio[760]: info: CoreStateMachine::addQueueItems May 13 18:36:08 volumioraspi4 volumio[760]: info: CorePlayQueue::addQueueItems May 13 18:36:08 volumioraspi4 volumio[760]: info: Preload queue cleared May 13 18:36:08 volumioraspi4 volumio[760]: info: Adding Item to queue: qobuz://album/o1i3b22uh1qtb May 13 18:36:08 volumioraspi4 volumio[760]: info: Exploding uri qobuz://album/o1i3b22uh1qtb in service qobuz May 13 18:36:08 volumioraspi4 volumio[760]: info: Executing endpoint metavolumio May 13 18:36:08 volumioraspi4 volumio[760]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio May 13 18:36:08 volumioraspi4 volumio[760]: info: Executing endpoint metavolumio May 13 18:36:08 volumioraspi4 volumio[760]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio May 13 18:36:08 volumioraspi4 volumio[760]: info: Executing endpoint metavolumio May 13 18:36:08 volumioraspi4 volumio[760]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio May 13 18:36:08 volumioraspi4 volumio[760]: info: Executing endpoint metavolumio May 13 18:36:08 volumioraspi4 volumio[760]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio May 13 18:36:10 volumioraspi4 volumio[760]: info: Executing endpoint metavolumio May 13 18:36:10 volumioraspi4 volumio[760]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio May 13 18:36:10 volumioraspi4 volumio[760]: info: Executing endpoint metavolumio May 13 18:36:10 volumioraspi4 volumio[760]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio May 13 18:36:10 volumioraspi4 volumio[760]: info: explodeUri took 4731 milliseconds May 13 18:36:10 volumioraspi4 volumio[760]: info: explodeUri took 4682 milliseconds May 13 18:36:10 volumioraspi4 volumio[760]: info: explodeUri took 4900 milliseconds May 13 18:36:10 volumioraspi4 volumio[760]: info: explodeUri took 4944 milliseconds May 13 18:36:10 volumioraspi4 volumio[760]: info: explodeUri took 5001 milliseconds May 13 18:36:10 volumioraspi4 volumio[760]: info: explodeUri took 4852 milliseconds May 13 18:36:10 volumioraspi4 volumio[760]: info: explodeUri took 1951 milliseconds May 13 18:36:10 volumioraspi4 volumio[760]: info: explodeUri took 1980 milliseconds May 13 18:36:10 volumioraspi4 volumio[760]: info: explodeUri took 1986 milliseconds May 13 18:36:10 volumioraspi4 volumio[760]: info: explodeUri took 2013 milliseconds May 13 18:36:10 volumioraspi4 volumio[760]: info: explodeUri took 2107 milliseconds May 13 18:36:10 volumioraspi4 volumio[760]: info: CoreCommandRouter::volumioPushQueue May 13 18:36:10 volumioraspi4 volumio[760]: info: CorePlayQueue::saveQueue May 13 18:36:10 volumioraspi4 volumio[760]: info: CoreStateMachine::updateTrackBlock May 13 18:36:10 volumioraspi4 volumio[760]: info: CorePlayQueue::getTrackBlock May 13 18:36:10 volumioraspi4 volumio[760]: info: CoreCommandRouter::volumioPlay May 13 18:36:10 volumioraspi4 volumio[760]: info: CoreStateMachine::play index 0 May 13 18:36:10 volumioraspi4 volumio[760]: info: CoreStateMachine::setConsumeUpdateService undefined May 13 18:36:10 volumioraspi4 volumio[760]: info: CoreStateMachine::stop May 13 18:36:10 volumioraspi4 volumio[760]: info: CoreStateMachine::setConsumeUpdateService undefined May 13 18:36:10 volumioraspi4 volumio[760]: info: CoreStateMachine::play index undefined May 13 18:36:10 volumioraspi4 volumio[760]: info: CoreStateMachine::setConsumeUpdateService undefined May 13 18:36:10 volumioraspi4 volumio[760]: info: CorePlayQueue::getTrack 0 May 13 18:36:10 volumioraspi4 volumio[760]: info: CoreStateMachine::startPlaybackTimer May 13 18:36:10 volumioraspi4 volumio[760]: info: CorePlayQueue::getTrack 0 May 13 18:36:10 volumioraspi4 volumio[760]: info: [1715639770909] ControllerQobuz::clearAddPlayTrack May 13 18:36:10 volumioraspi4 volumio[760]: verbose: ControllerMpd::sendMpdCommand stop May 13 18:36:10 volumioraspi4 volumio[760]: info: sendMpdCommand stop took 1 milliseconds May 13 18:36:10 volumioraspi4 volumio[760]: verbose: ControllerMpd::sendMpdCommand clear May 13 18:36:10 volumioraspi4 volumio[760]: info: May 13 18:36:10 volumioraspi4 volumio[760]: ---------------------------- MPD announces system playlist update May 13 18:36:10 volumioraspi4 volumio[760]: info: Ignoring MPD Status Update May 13 18:36:10 volumioraspi4 volumio[760]: info: sendMpdCommand clear took 2 milliseconds May 13 18:36:10 volumioraspi4 volumio[760]: verbose: ControllerMpd::sendMpdCommand load "http://127.0.0.1:3245?data=qobuz://song/239022325" May 13 18:36:10 volumioraspi4 volumio[760]: STREAMING PROXY: Handling url /?data=qobuz://song/239022325 May 13 18:36:10 volumioraspi4 volumio[760]: info: May 13 18:36:10 volumioraspi4 volumio[760]: ---------------------------- MPD announces system playlist update May 13 18:36:10 volumioraspi4 volumio[760]: info: Ignoring MPD Status Update May 13 18:36:10 volumioraspi4 volumio[760]: info: May 13 18:36:10 volumioraspi4 volumio[760]: ---------------------------- MPD announces system playlist update May 13 18:36:10 volumioraspi4 volumio[760]: info: Ignoring MPD Status Update May 13 18:36:10 volumioraspi4 volumio[760]: error: updateQueue error: null May 13 18:36:10 volumioraspi4 volumio[760]: info: ------------------------------ 5ms May 13 18:36:10 volumioraspi4 volumio[760]: info: Executing endpoint getStreamUrlqobuz May 13 18:36:10 volumioraspi4 volumio[760]: info: CoreCommandRouter::executeOnPlugin: qobuz , getStreamUrlAPI May 13 18:36:10 volumioraspi4 volumio[760]: info: explodeUri took 2191 milliseconds May 13 18:36:10 volumioraspi4 volumio[760]: info: explodeUri took 2222 milliseconds May 13 18:36:11 volumioraspi4 volumio[760]: info: getStreamUrl took 661 milliseconds May 13 18:36:11 volumioraspi4 volumio[760]: STREAMING PROXY: Got real url: http://streaming-qobuz-std.akamaized.net:80/file?uid=2489067&eid=239022325&fmt=27&profile=raw&app_id=539451548&cid=1749371&etsp=1715643371&hmac=d8Nd1pm5NnN18CNgyavhAbRZzXg May 13 18:36:11 volumioraspi4 volumio[760]: STREAMING PROXY: Response: 200, length: 175232524 May 13 18:36:11 volumioraspi4 volumio[760]: STREAMING PROXY: Client dropped request, destroying May 13 18:36:11 volumioraspi4 volumio[760]: error: updateQueue error: null May 13 18:36:11 volumioraspi4 volumio[760]: error: updateQueue error: null May 13 18:36:11 volumioraspi4 volumio[760]: verbose: ControllerMpd::sendMpdCommand add "http://127.0.0.1:3245?data=qobuz://song/239022325" May 13 18:36:11 volumioraspi4 volumio[760]: info: ------------------------------ 845ms May 13 18:36:11 volumioraspi4 volumio[760]: info: ------------------------------ 845ms May 13 18:36:11 volumioraspi4 volumio[760]: info: May 13 18:36:11 volumioraspi4 volumio[760]: ---------------------------- MPD announces system playlist update May 13 18:36:11 volumioraspi4 volumio[760]: info: Ignoring MPD Status Update May 13 18:36:11 volumioraspi4 volumio[760]: info: sendMpdCommand add "http://127.0.0.1:3245?data=qobuz://song/239022325" took 2 milliseconds May 13 18:36:11 volumioraspi4 volumio[760]: info: CoreStateMachine::setConsumeUpdateService mpd May 13 18:36:11 volumioraspi4 volumio[760]: verbose: ControllerMpd::sendMpdCommand play May 13 18:36:11 volumioraspi4 volumio[760]: info: May 13 18:36:11 volumioraspi4 volumio[760]: ---------------------------- MPD announces system playlist update May 13 18:36:11 volumioraspi4 volumio[760]: info: Ignoring MPD Status Update May 13 18:36:11 volumioraspi4 volumio[760]: STREAMING PROXY: Handling url /?data=qobuz://song/239022325 May 13 18:36:11 volumioraspi4 volumio[760]: info: May 13 18:36:11 volumioraspi4 volumio[760]: ---------------------------- MPD announces system playlist update May 13 18:36:11 volumioraspi4 volumio[760]: info: Ignoring MPD Status Update May 13 18:36:11 volumioraspi4 volumio[760]: info: ------------------------------ 5ms May 13 18:36:11 volumioraspi4 volumio[760]: info: sendMpdCommand play took 5 milliseconds May 13 18:36:11 volumioraspi4 volumio[760]: info: ------------------------------ 3ms May 13 18:36:11 volumioraspi4 volumio[760]: info: ------------------------------ 2ms May 13 18:36:11 volumioraspi4 volumio[760]: info: Executing endpoint getStreamUrlqobuz May 13 18:36:11 volumioraspi4 volumio[760]: info: CoreCommandRouter::executeOnPlugin: qobuz , getStreamUrlAPI May 13 18:36:12 volumioraspi4 volumio[760]: info: getStreamUrl took 681 milliseconds May 13 18:36:12 volumioraspi4 volumio[760]: STREAMING PROXY: Got real url: http://streaming-qobuz-std.akamaized.net:80/file?uid=2489067&eid=239022325&fmt=27&profile=raw&app_id=539451548&cid=1749371&etsp=1715643372&hmac=QIBlNkfGrH5edPtb6kA-l_042qU May 13 18:36:12 volumioraspi4 volumio[760]: STREAMING PROXY: Response: 200, length: 175232524 May 13 18:36:12 volumioraspi4 volumio[760]: info: May 13 18:36:12 volumioraspi4 volumio[760]: ---------------------------- MPD announces state update: player May 13 18:36:12 volumioraspi4 volumio[760]: info: ControllerMpd::getState May 13 18:36:12 volumioraspi4 volumio[760]: verbose: ControllerMpd::sendMpdCommand status May 13 18:36:12 volumioraspi4 kernel: bcm2835-i2s fe203000.i2s: I2S SYNC error! May 13 18:36:12 volumioraspi4 volumio[760]: info: May 13 18:36:12 volumioraspi4 volumio[760]: ---------------------------- MPD announces state update: player May 13 18:36:12 volumioraspi4 volumio[760]: info: ControllerMpd::getState May 13 18:36:12 volumioraspi4 volumio[760]: verbose: ControllerMpd::sendMpdCommand status May 13 18:36:12 volumioraspi4 volumio[760]: info: May 13 18:36:12 volumioraspi4 volumio[760]: ---------------------------- MPD announces state update: player May 13 18:36:12 volumioraspi4 volumio[760]: info: ControllerMpd::getState May 13 18:36:12 volumioraspi4 volumio[760]: verbose: ControllerMpd::sendMpdCommand status May 13 18:36:12 volumioraspi4 volumio[760]: info: May 13 18:36:12 volumioraspi4 volumio[760]: ---------------------------- MPD announces state update: player May 13 18:36:12 volumioraspi4 volumio[760]: info: sendMpdCommand status took 6 milliseconds May 13 18:36:12 volumioraspi4 volumio[760]: info: ControllerMpd::getState May 13 18:36:12 volumioraspi4 volumio[760]: verbose: ControllerMpd::sendMpdCommand status May 13 18:36:12 volumioraspi4 volumio[760]: info: sendMpdCommand status took 4 milliseconds May 13 18:36:12 volumioraspi4 volumio[760]: info: sendMpdCommand status took 2 milliseconds May 13 18:36:12 volumioraspi4 volumio[760]: verbose: ControllerMpd::parseState May 13 18:36:12 volumioraspi4 volumio[760]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 13 18:36:12 volumioraspi4 volumio[760]: verbose: ControllerMpd::parseState May 13 18:36:12 volumioraspi4 volumio[760]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 13 18:36:12 volumioraspi4 volumio[760]: verbose: ControllerMpd::parseState May 13 18:36:12 volumioraspi4 volumio[760]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 13 18:36:12 volumioraspi4 volumio[760]: info: May 13 18:36:12 volumioraspi4 volumio[760]: ---------------------------- MPD announces state update: player May 13 18:36:12 volumioraspi4 volumio[760]: info: ControllerMpd::getState May 13 18:36:12 volumioraspi4 volumio[760]: verbose: ControllerMpd::sendMpdCommand status May 13 18:36:12 volumioraspi4 volumio[760]: info: May 13 18:36:12 volumioraspi4 volumio[760]: ---------------------------- MPD announces state update: player May 13 18:36:12 volumioraspi4 volumio[760]: info: ControllerMpd::getState May 13 18:36:12 volumioraspi4 volumio[760]: verbose: ControllerMpd::sendMpdCommand status May 13 18:36:12 volumioraspi4 volumio[760]: info: sendMpdCommand status took 8 milliseconds May 13 18:36:12 volumioraspi4 volumio[760]: info: sendMpdCommand playlistinfo took 7 milliseconds May 13 18:36:12 volumioraspi4 volumio[760]: info: sendMpdCommand playlistinfo took 6 milliseconds May 13 18:36:12 volumioraspi4 volumio[760]: info: sendMpdCommand playlistinfo took 6 milliseconds May 13 18:36:12 volumioraspi4 volumio[760]: info: sendMpdCommand status took 4 milliseconds May 13 18:36:12 volumioraspi4 volumio[760]: info: sendMpdCommand status took 2 milliseconds May 13 18:36:12 volumioraspi4 volumio[760]: verbose: ControllerMpd::parseState May 13 18:36:12 volumioraspi4 volumio[760]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 13 18:36:12 volumioraspi4 volumio[760]: verbose: ControllerMpd::parseTrackInfo May 13 18:36:12 volumioraspi4 volumio[760]: verbose: ControllerMpd::parseTrackInfo May 13 18:36:12 volumioraspi4 volumio[760]: verbose: ControllerMpd::parseTrackInfo May 13 18:36:12 volumioraspi4 volumio[760]: verbose: ControllerMpd::parseState May 13 18:36:12 volumioraspi4 volumio[760]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 13 18:36:12 volumioraspi4 volumio[760]: verbose: ControllerMpd::parseState May 13 18:36:12 volumioraspi4 volumio[760]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 13 18:36:12 volumioraspi4 volumio[760]: info: ControllerMpd::pushState May 13 18:36:12 volumioraspi4 volumio[760]: info: CoreCommandRouter::servicePushState May 13 18:36:12 volumioraspi4 volumio[760]: info: CorePlayQueue::getTrack 0 May 13 18:36:12 volumioraspi4 volumio[760]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":245,"samplerate":"192 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"239022325","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=qobuz://song/239022325","trackType":"qobuz"} May 13 18:36:12 volumioraspi4 volumio[760]: verbose: CURRENT POSITION 0 May 13 18:36:12 volumioraspi4 volumio[760]: info: CoreStateMachine::syncState stateService play May 13 18:36:12 volumioraspi4 volumio[760]: info: CoreStateMachine::syncState currentStatus stop May 13 18:36:12 volumioraspi4 volumio[760]: info: ControllerMpd::pushState May 13 18:36:12 volumioraspi4 volumio[760]: info: CoreCommandRouter::servicePushState May 13 18:36:12 volumioraspi4 volumio[760]: info: CorePlayQueue::getTrack 0 May 13 18:36:12 volumioraspi4 volumio[760]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":245,"samplerate":"192 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"239022325","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=qobuz://song/239022325","trackType":"qobuz"} May 13 18:36:12 volumioraspi4 volumio[760]: verbose: CURRENT POSITION 0 May 13 18:36:12 volumioraspi4 volumio[760]: info: CoreStateMachine::syncState stateService play May 13 18:36:12 volumioraspi4 volumio[760]: info: CoreStateMachine::syncState currentStatus play May 13 18:36:12 volumioraspi4 volumio[760]: info: Received an update from plugin. extracting info from payload May 13 18:36:12 volumioraspi4 volumio[760]: info: CoreStateMachine::pushState May 13 18:36:12 volumioraspi4 volumio[760]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 13 18:36:12 volumioraspi4 volumio[760]: info: CoreCommandRouter::volumioPushState May 13 18:36:12 volumioraspi4 volumio[760]: info: MRS: Pushing multiroomSync output update for this device May 13 18:36:12 volumioraspi4 volumio[760]: info: MRS: Pushing multiroomSync output May 13 18:36:12 volumioraspi4 volumio[760]: info: CoreStateMachine::pushState May 13 18:36:12 volumioraspi4 volumio[760]: info: CoreCommandRouter::volumioPushState May 13 18:36:12 volumioraspi4 volumio[760]: info: MRS: Pushing multiroomSync output update for this device May 13 18:36:12 volumioraspi4 volumio[760]: info: MRS: Pushing multiroomSync output May 13 18:36:12 volumioraspi4 volumio[760]: info: ControllerMpd::pushState May 13 18:36:12 volumioraspi4 volumio[760]: info: CoreCommandRouter::servicePushState May 13 18:36:12 volumioraspi4 volumio[760]: info: CorePlayQueue::getTrack 0 May 13 18:36:12 volumioraspi4 volumio[760]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":245,"samplerate":"192 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"239022325","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=qobuz://song/239022325","trackType":"qobuz"} May 13 18:36:12 volumioraspi4 volumio[760]: verbose: CURRENT POSITION 0 May 13 18:36:12 volumioraspi4 volumio[760]: info: CoreStateMachine::syncState stateService play May 13 18:36:12 volumioraspi4 volumio[760]: info: CoreStateMachine::syncState currentStatus play May 13 18:36:12 volumioraspi4 volumio[760]: info: Received an update from plugin. extracting info from payload May 13 18:36:12 volumioraspi4 volumio[760]: info: CoreStateMachine::pushState May 13 18:36:12 volumioraspi4 volumio[760]: info: CoreCommandRouter::volumioPushState May 13 18:36:12 volumioraspi4 volumio[760]: info: MRS: Pushing multiroomSync output update for this device May 13 18:36:12 volumioraspi4 volumio[760]: info: MRS: Pushing multiroomSync output May 13 18:36:12 volumioraspi4 volumio[760]: info: CoreStateMachine::pushState May 13 18:36:12 volumioraspi4 volumio[760]: info: CoreCommandRouter::volumioPushState May 13 18:36:12 volumioraspi4 volumio[760]: info: MRS: Pushing multiroomSync output update for this device May 13 18:36:12 volumioraspi4 volumio[760]: info: MRS: Pushing multiroomSync output May 13 18:36:12 volumioraspi4 volumio[760]: info: ------------------------------ 52ms May 13 18:36:12 volumioraspi4 volumio[760]: info: ------------------------------ 55ms May 13 18:36:12 volumioraspi4 volumio[760]: info: ------------------------------ 55ms May 13 18:36:12 volumioraspi4 volumio[760]: info: sendMpdCommand playlistinfo took 41 milliseconds May 13 18:36:12 volumioraspi4 volumio[760]: info: sendMpdCommand playlistinfo took 38 milliseconds May 13 18:36:12 volumioraspi4 volumio[760]: info: sendMpdCommand playlistinfo took 36 milliseconds May 13 18:36:12 volumioraspi4 volumio[760]: verbose: ControllerMpd::parseTrackInfo May 13 18:36:12 volumioraspi4 volumio[760]: verbose: ControllerMpd::parseTrackInfo May 13 18:36:12 volumioraspi4 volumio[760]: verbose: ControllerMpd::parseTrackInfo May 13 18:36:12 volumioraspi4 volumio[760]: info: ControllerMpd::pushState May 13 18:36:12 volumioraspi4 volumio[760]: info: CoreCommandRouter::servicePushState May 13 18:36:12 volumioraspi4 volumio[760]: info: CorePlayQueue::getTrack 0 May 13 18:36:12 volumioraspi4 volumio[760]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":245,"samplerate":"192 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"239022325","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=qobuz://song/239022325","trackType":"qobuz"} May 13 18:36:12 volumioraspi4 volumio[760]: verbose: CURRENT POSITION 0 May 13 18:36:12 volumioraspi4 volumio[760]: info: CoreStateMachine::syncState stateService play May 13 18:36:12 volumioraspi4 volumio[760]: info: CoreStateMachine::syncState currentStatus play May 13 18:36:12 volumioraspi4 volumio[760]: info: Received an update from plugin. extracting info from payload May 13 18:36:12 volumioraspi4 volumio[760]: info: CoreStateMachine::pushState May 13 18:36:12 volumioraspi4 volumio[760]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 13 18:36:12 volumioraspi4 volumio[760]: info: CoreCommandRouter::volumioPushState May 13 18:36:12 volumioraspi4 volumio[760]: info: MRS: Pushing multiroomSync output update for this device May 13 18:36:12 volumioraspi4 volumio[760]: info: MRS: Pushing multiroomSync output May 13 18:36:12 volumioraspi4 volumio[760]: info: CoreStateMachine::pushState May 13 18:36:12 volumioraspi4 volumio[760]: info: CoreCommandRouter::volumioPushState May 13 18:36:12 volumioraspi4 volumio[760]: info: MRS: Pushing multiroomSync output update for this device May 13 18:36:12 volumioraspi4 volumio[760]: info: MRS: Pushing multiroomSync output May 13 18:36:12 volumioraspi4 volumio[760]: info: ControllerMpd::pushState May 13 18:36:12 volumioraspi4 volumio[760]: info: CoreCommandRouter::servicePushState May 13 18:36:12 volumioraspi4 volumio[760]: info: CorePlayQueue::getTrack 0 May 13 18:36:12 volumioraspi4 volumio[760]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":245,"samplerate":"192 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"239022325","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=qobuz://song/239022325","trackType":"qobuz"} May 13 18:36:12 volumioraspi4 volumio[760]: verbose: CURRENT POSITION 0 May 13 18:36:12 volumioraspi4 volumio[760]: info: CoreStateMachine::syncState stateService play May 13 18:36:12 volumioraspi4 volumio[760]: info: CoreStateMachine::syncState currentStatus play May 13 18:36:12 volumioraspi4 volumio[760]: info: Received an update from plugin. extracting info from payload May 13 18:36:12 volumioraspi4 volumio[760]: info: CoreStateMachine::pushState May 13 18:36:12 volumioraspi4 volumio[760]: info: CoreCommandRouter::volumioPushState May 13 18:36:12 volumioraspi4 volumio[760]: info: MRS: Pushing multiroomSync output update for this device May 13 18:36:12 volumioraspi4 volumio[760]: info: MRS: Pushing multiroomSync output May 13 18:36:12 volumioraspi4 volumio[760]: info: CoreStateMachine::pushState May 13 18:36:12 volumioraspi4 volumio[760]: info: CoreCommandRouter::volumioPushState May 13 18:36:12 volumioraspi4 volumio[760]: info: MRS: Pushing multiroomSync output update for this device May 13 18:36:12 volumioraspi4 volumio[760]: info: MRS: Pushing multiroomSync output May 13 18:36:12 volumioraspi4 volumio[760]: info: ControllerMpd::pushState May 13 18:36:12 volumioraspi4 volumio[760]: info: CoreCommandRouter::servicePushState May 13 18:36:12 volumioraspi4 volumio[760]: info: CorePlayQueue::getTrack 0 May 13 18:36:12 volumioraspi4 volumio[760]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":245,"samplerate":"192 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"239022325","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=qobuz://song/239022325","trackType":"qobuz"} May 13 18:36:12 volumioraspi4 volumio[760]: verbose: CURRENT POSITION 0 May 13 18:36:12 volumioraspi4 volumio[760]: info: CoreStateMachine::syncState stateService play May 13 18:36:12 volumioraspi4 volumio[760]: info: CoreStateMachine::syncState currentStatus play May 13 18:36:12 volumioraspi4 volumio[760]: info: Received an update from plugin. extracting info from payload May 13 18:36:12 volumioraspi4 volumio[760]: info: CoreStateMachine::pushState May 13 18:36:12 volumioraspi4 volumio[760]: info: CoreCommandRouter::volumioPushState May 13 18:36:12 volumioraspi4 volumio[760]: info: MRS: Pushing multiroomSync output update for this device May 13 18:36:12 volumioraspi4 volumio[760]: info: MRS: Pushing multiroomSync output May 13 18:36:12 volumioraspi4 volumio[760]: info: CoreStateMachine::pushState May 13 18:36:12 volumioraspi4 volumio[760]: info: CoreCommandRouter::volumioPushState May 13 18:36:12 volumioraspi4 volumio[760]: info: MRS: Pushing multiroomSync output update for this device May 13 18:36:12 volumioraspi4 volumio[760]: info: MRS: Pushing multiroomSync output May 13 18:36:12 volumioraspi4 volumio[760]: info: ------------------------------ 79ms May 13 18:36:12 volumioraspi4 volumio[760]: info: ------------------------------ 74ms May 13 18:36:12 volumioraspi4 volumio[760]: info: ------------------------------ 72ms May 13 18:36:13 volumioraspi4 volumio[760]: info: Preload queue cleared May 13 18:36:13 volumioraspi4 volumio[760]: info: CoreCommandRouter::volumioReplaceandPlayItems May 13 18:36:13 volumioraspi4 volumio[760]: info: CoreStateMachine::ClearQueue May 13 18:36:13 volumioraspi4 volumio[760]: info: CoreStateMachine::stop May 13 18:36:13 volumioraspi4 volumio[760]: info: CoreStateMachine::setConsumeUpdateService undefined May 13 18:36:13 volumioraspi4 volumio[760]: info: CoreStateMachine::stPlaybackTimer May 13 18:36:13 volumioraspi4 volumio[760]: info: CoreStateMachine::updateTrackBlock May 13 18:36:13 volumioraspi4 volumio[760]: info: CorePlayQueue::getTrackBlock May 13 18:36:13 volumioraspi4 volumio[760]: info: CoreStateMachine::pushState May 13 18:36:13 volumioraspi4 volumio[760]: info: CorePlayQueue::getTrack 0 May 13 18:36:13 volumioraspi4 volumio[760]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 13 18:36:13 volumioraspi4 volumio[760]: info: CoreCommandRouter::volumioPushState May 13 18:36:13 volumioraspi4 volumio[760]: info: MRS: Pushing multiroomSync output update for this device May 13 18:36:13 volumioraspi4 volumio[760]: info: MRS: Pushing multiroomSync output May 13 18:36:13 volumioraspi4 volumio[760]: info: CoreStateMachine::serviceStop May 13 18:36:13 volumioraspi4 volumio[760]: info: CorePlayQueue::getTrack 0 May 13 18:36:13 volumioraspi4 volumio[760]: info: CoreCommandRouter::serviceStop May 13 18:36:13 volumioraspi4 volumio[760]: info: [1715639773869] ControllerQobuz::stop May 13 18:36:13 volumioraspi4 volumio[760]: info: CoreStateMachine::setConsumeUpdateService mpd May 13 18:36:13 volumioraspi4 volumio[760]: info: ControllerMpd::stop May 13 18:36:13 volumioraspi4 volumio[760]: verbose: ControllerMpd::sendMpdCommand stop May 13 18:36:13 volumioraspi4 volumio[760]: info: CorePlayQueue::clearPlayQueue May 13 18:36:13 volumioraspi4 volumio[760]: info: CorePlayQueue::saveQueue May 13 18:36:13 volumioraspi4 volumio[760]: info: CoreCommandRouter::volumioPushQueue May 13 18:36:13 volumioraspi4 volumio[760]: info: CoreStateMachine::addQueueItems May 13 18:36:13 volumioraspi4 volumio[760]: info: CorePlayQueue::addQueueItems May 13 18:36:13 volumioraspi4 volumio[760]: info: Preload queue cleared May 13 18:36:13 volumioraspi4 volumio[760]: info: Adding Item to queue: qobuz://song/239022325 May 13 18:36:13 volumioraspi4 volumio[760]: info: Using cached record of: qobuz://song/239022325 May 13 18:36:13 volumioraspi4 volumio[760]: info: Adding Item to queue: qobuz://song/239022326 May 13 18:36:13 volumioraspi4 volumio[760]: info: Using cached record of: qobuz://song/239022326 May 13 18:36:13 volumioraspi4 volumio[760]: info: Adding Item to queue: qobuz://song/239022327 May 13 18:36:13 volumioraspi4 volumio[760]: info: Using cached record of: qobuz://song/239022327 May 13 18:36:13 volumioraspi4 volumio[760]: info: Adding Item to queue: qobuz://song/239022328 May 13 18:36:13 volumioraspi4 volumio[760]: info: Using cached record of: qobuz://song/239022328 May 13 18:36:13 volumioraspi4 volumio[760]: info: Adding Item to queue: qobuz://song/239022329 May 13 18:36:13 volumioraspi4 volumio[760]: info: Using cached record of: qobuz://song/239022329 May 13 18:36:13 volumioraspi4 volumio[760]: info: Adding Item to queue: qobuz://song/239022330 May 13 18:36:13 volumioraspi4 volumio[760]: info: Using cached record of: qobuz://song/239022330 May 13 18:36:13 volumioraspi4 volumio[760]: info: Adding Item to queue: qobuz://song/239022331 May 13 18:36:13 volumioraspi4 volumio[760]: info: Using cached record of: qobuz://song/239022331 May 13 18:36:13 volumioraspi4 volumio[760]: info: Adding Item to queue: qobuz://song/239022332 May 13 18:36:13 volumioraspi4 volumio[760]: info: Using cached record of: qobuz://song/239022332 May 13 18:36:13 volumioraspi4 volumio[760]: info: Adding Item to queue: qobuz://song/239022333 May 13 18:36:13 volumioraspi4 volumio[760]: info: Using cached record of: qobuz://song/239022333 May 13 18:36:13 volumioraspi4 volumio[760]: info: Adding Item to queue: qobuz://song/239022334 May 13 18:36:13 volumioraspi4 volumio[760]: info: Using cached record of: qobuz://song/239022334 May 13 18:36:13 volumioraspi4 volumio[760]: info: Adding Item to queue: qobuz://song/239022335 May 13 18:36:13 volumioraspi4 volumio[760]: info: Using cached record of: qobuz://song/239022335 May 13 18:36:13 volumioraspi4 volumio[760]: info: Adding Item to queue: qobuz://song/239022336 May 13 18:36:13 volumioraspi4 volumio[760]: info: Using cached record of: qobuz://song/239022336 May 13 18:36:13 volumioraspi4 volumio[760]: info: CoreCommandRouter::volumioPushQueue May 13 18:36:13 volumioraspi4 volumio[760]: info: CorePlayQueue::saveQueue May 13 18:36:13 volumioraspi4 volumio[760]: STREAMING PROXY: Client dropped request, destroying May 13 18:36:13 volumioraspi4 volumio[760]: info: CoreStateMachine::updateTrackBlock May 13 18:36:13 volumioraspi4 volumio[760]: info: CorePlayQueue::getTrackBlock May 13 18:36:13 volumioraspi4 volumio[760]: info: CoreCommandRouter::volumioPlay May 13 18:36:13 volumioraspi4 volumio[760]: info: CoreStateMachine::play index 0 May 13 18:36:13 volumioraspi4 volumio[760]: info: CoreStateMachine::setConsumeUpdateService undefined May 13 18:36:13 volumioraspi4 volumio[760]: info: CoreStateMachine::stop May 13 18:36:13 volumioraspi4 volumio[760]: info: CoreStateMachine::setConsumeUpdateService undefined May 13 18:36:13 volumioraspi4 volumio[760]: info: CoreStateMachine::play index undefined May 13 18:36:13 volumioraspi4 volumio[760]: info: CoreStateMachine::setConsumeUpdateService undefined May 13 18:36:13 volumioraspi4 volumio[760]: info: CorePlayQueue::getTrack 0 May 13 18:36:13 volumioraspi4 volumio[760]: info: CoreStateMachine::startPlaybackTimer May 13 18:36:13 volumioraspi4 volumio[760]: info: CorePlayQueue::getTrack 0 May 13 18:36:13 volumioraspi4 volumio[760]: info: [1715639773889] ControllerQobuz::clearAddPlayTrack May 13 18:36:13 volumioraspi4 volumio[760]: verbose: ControllerMpd::sendMpdCommand stop May 13 18:36:13 volumioraspi4 volumio[760]: info: May 13 18:36:13 volumioraspi4 volumio[760]: ---------------------------- MPD announces state update: player May 13 18:36:13 volumioraspi4 volumio[760]: info: sendMpdCommand stop took 24 milliseconds May 13 18:36:13 volumioraspi4 volumio[760]: info: ControllerMpd::getState May 13 18:36:13 volumioraspi4 volumio[760]: verbose: ControllerMpd::sendMpdCommand status May 13 18:36:13 volumioraspi4 volumio[760]: info: sendMpdCommand stop took 5 milliseconds May 13 18:36:13 volumioraspi4 volumio[760]: verbose: ControllerMpd::sendMpdCommand clear May 13 18:36:13 volumioraspi4 volumio[760]: info: May 13 18:36:13 volumioraspi4 volumio[760]: ---------------------------- MPD announces state update: player May 13 18:36:13 volumioraspi4 volumio[760]: info: ControllerMpd::getState May 13 18:36:13 volumioraspi4 volumio[760]: verbose: ControllerMpd::sendMpdCommand status May 13 18:36:13 volumioraspi4 volumio[760]: info: May 13 18:36:13 volumioraspi4 volumio[760]: ---------------------------- MPD announces state update: player May 13 18:36:13 volumioraspi4 volumio[760]: info: ControllerMpd::getState May 13 18:36:13 volumioraspi4 volumio[760]: verbose: ControllerMpd::sendMpdCommand status May 13 18:36:13 volumioraspi4 volumio[760]: info: May 13 18:36:13 volumioraspi4 volumio[760]: ---------------------------- MPD announces system playlist update May 13 18:36:13 volumioraspi4 volumio[760]: info: Ignoring MPD Status Update May 13 18:36:13 volumioraspi4 volumio[760]: info: sendMpdCommand status took 14 milliseconds May 13 18:36:13 volumioraspi4 volumio[760]: info: sendMpdCommand clear took 14 milliseconds May 13 18:36:13 volumioraspi4 volumio[760]: info: sendMpdCommand status took 12 milliseconds May 13 18:36:13 volumioraspi4 volumio[760]: info: sendMpdCommand status took 7 milliseconds May 13 18:36:13 volumioraspi4 volumio[760]: verbose: ControllerMpd::parseState May 13 18:36:13 volumioraspi4 volumio[760]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 13 18:36:13 volumioraspi4 volumio[760]: verbose: ControllerMpd::sendMpdCommand load "http://127.0.0.1:3245?data=qobuz://song/239022325" May 13 18:36:13 volumioraspi4 volumio[760]: verbose: ControllerMpd::parseState May 13 18:36:13 volumioraspi4 volumio[760]: verbose: ControllerMpd::parseState May 13 18:36:13 volumioraspi4 volumio[760]: info: ControllerMpd::pushState May 13 18:36:13 volumioraspi4 volumio[760]: info: CoreCommandRouter::servicePushState May 13 18:36:13 volumioraspi4 volumio[760]: STREAMING PROXY: Handling url /?data=qobuz://song/239022325 May 13 18:36:13 volumioraspi4 volumio[760]: info: CoreStateMachine::pushState May 13 18:36:13 volumioraspi4 volumio[760]: info: CorePlayQueue::getTrack 0 May 13 18:36:13 volumioraspi4 volumio[760]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 13 18:36:13 volumioraspi4 volumio[760]: info: CoreCommandRouter::volumioPushState May 13 18:36:13 volumioraspi4 volumio[760]: info: MRS: Pushing multiroomSync output update for this device May 13 18:36:13 volumioraspi4 volumio[760]: info: MRS: Pushing multiroomSync output May 13 18:36:13 volumioraspi4 volumio[760]: info: CorePlayQueue::getTrack 0 May 13 18:36:13 volumioraspi4 volumio[760]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current qobuz Received mpd May 13 18:36:13 volumioraspi4 volumio[760]: info: ControllerMpd::pushState May 13 18:36:13 volumioraspi4 volumio[760]: info: CoreCommandRouter::servicePushState May 13 18:36:13 volumioraspi4 volumio[760]: info: CoreStateMachine::pushState May 13 18:36:13 volumioraspi4 volumio[760]: info: CorePlayQueue::getTrack 0 May 13 18:36:13 volumioraspi4 volumio[760]: info: CoreCommandRouter::volumioPushState May 13 18:36:13 volumioraspi4 volumio[760]: info: MRS: Pushing multiroomSync output update for this device May 13 18:36:13 volumioraspi4 volumio[760]: info: MRS: Pushing multiroomSync output May 13 18:36:13 volumioraspi4 volumio[760]: info: CorePlayQueue::getTrack 0 May 13 18:36:13 volumioraspi4 volumio[760]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current qobuz Received mpd May 13 18:36:13 volumioraspi4 volumio[760]: info: ------------------------------ 25ms May 13 18:36:13 volumioraspi4 volumio[760]: info: ------------------------------ 25ms May 13 18:36:13 volumioraspi4 volumio[760]: info: May 13 18:36:13 volumioraspi4 volumio[760]: ---------------------------- MPD announces system playlist update May 13 18:36:13 volumioraspi4 volumio[760]: info: Ignoring MPD Status Update May 13 18:36:13 volumioraspi4 volumio[760]: info: May 13 18:36:13 volumioraspi4 volumio[760]: ---------------------------- MPD announces system playlist update May 13 18:36:13 volumioraspi4 volumio[760]: info: Ignoring MPD Status Update May 13 18:36:13 volumioraspi4 volumio[760]: error: updateQueue error: null May 13 18:36:13 volumioraspi4 volumio[760]: info: ------------------------------ 18ms May 13 18:36:13 volumioraspi4 volumio[760]: info: sendMpdCommand playlistinfo took 14 milliseconds May 13 18:36:13 volumioraspi4 volumio[760]: verbose: ControllerMpd::parseTrackInfo May 13 18:36:13 volumioraspi4 volumio[760]: error: ControllerMpd::pushError: TypeError: Cannot read property 'split' of undefined May 13 18:36:13 volumioraspi4 volumio[760]: info: ------------------------------ 33ms May 13 18:36:13 volumioraspi4 volumio[760]: info: Executing endpoint getStreamUrlqobuz May 13 18:36:13 volumioraspi4 volumio[760]: info: CoreCommandRouter::executeOnPlugin: qobuz , getStreamUrlAPI May 13 18:36:14 volumioraspi4 volumio[760]: info: getStreamUrl took 652 milliseconds May 13 18:36:14 volumioraspi4 volumio[760]: STREAMING PROXY: Got real url: http://streaming-qobuz-std.akamaized.net:80/file?uid=2489067&eid=239022325&fmt=27&profile=raw&app_id=539451548&cid=1749371&etsp=1715643374&hmac=3INXnSazLJzZgyDBCwTZLPxh4Ro May 13 18:36:14 volumioraspi4 volumio[760]: STREAMING PROXY: Response: 200, length: 175232524 May 13 18:36:14 volumioraspi4 volumio[760]: STREAMING PROXY: Client dropped request, destroying May 13 18:36:14 volumioraspi4 volumio[760]: error: updateQueue error: null May 13 18:36:14 volumioraspi4 volumio[760]: error: updateQueue error: null May 13 18:36:14 volumioraspi4 volumio[760]: verbose: ControllerMpd::sendMpdCommand add "http://127.0.0.1:3245?data=qobuz://song/239022325" May 13 18:36:14 volumioraspi4 volumio[760]: info: ------------------------------ 781ms May 13 18:36:14 volumioraspi4 volumio[760]: info: ------------------------------ 780ms May 13 18:36:14 volumioraspi4 volumio[760]: info: May 13 18:36:14 volumioraspi4 volumio[760]: ---------------------------- MPD announces system playlist update May 13 18:36:14 volumioraspi4 volumio[760]: info: Ignoring MPD Status Update May 13 18:36:14 volumioraspi4 volumio[760]: info: sendMpdCommand add "http://127.0.0.1:3245?data=qobuz://song/239022325" took 3 milliseconds May 13 18:36:14 volumioraspi4 volumio[760]: info: CoreStateMachine::setConsumeUpdateService mpd May 13 18:36:14 volumioraspi4 volumio[760]: verbose: ControllerMpd::sendMpdCommand play May 13 18:36:14 volumioraspi4 volumio[760]: info: May 13 18:36:14 volumioraspi4 volumio[760]: ---------------------------- MPD announces system playlist update May 13 18:36:14 volumioraspi4 volumio[760]: info: Ignoring MPD Status Update May 13 18:36:14 volumioraspi4 volumio[760]: STREAMING PROXY: Handling url /?data=qobuz://song/239022325 May 13 18:36:14 volumioraspi4 volumio[760]: info: May 13 18:36:14 volumioraspi4 volumio[760]: ---------------------------- MPD announces system playlist update May 13 18:36:14 volumioraspi4 volumio[760]: info: Ignoring MPD Status Update May 13 18:36:14 volumioraspi4 volumio[760]: info: ------------------------------ 5ms May 13 18:36:14 volumioraspi4 volumio[760]: info: sendMpdCommand play took 3 milliseconds May 13 18:36:14 volumioraspi4 volumio[760]: info: ------------------------------ 4ms May 13 18:36:14 volumioraspi4 volumio[760]: info: ------------------------------ 2ms May 13 18:36:14 volumioraspi4 volumio[760]: info: Executing endpoint getStreamUrlqobuz May 13 18:36:14 volumioraspi4 volumio[760]: info: CoreCommandRouter::executeOnPlugin: qobuz , getStreamUrlAPI May 13 18:36:15 volumioraspi4 volumio[760]: info: getStreamUrl took 654 milliseconds May 13 18:36:15 volumioraspi4 volumio[760]: STREAMING PROXY: Got real url: http://streaming-qobuz-std.akamaized.net:80/file?uid=2489067&eid=239022325&fmt=27&profile=raw&app_id=539451548&cid=1749371&etsp=1715643375&hmac=45WBPPCzi0K1ndSd-J2fDH3vua0 May 13 18:36:16 volumioraspi4 volumio[760]: STREAMING PROXY: Response: 200, length: 175232524 May 13 18:36:16 volumioraspi4 volumio[760]: info: May 13 18:36:16 volumioraspi4 volumio[760]: ---------------------------- MPD announces state update: player May 13 18:36:16 volumioraspi4 volumio[760]: info: ControllerMpd::getState May 13 18:36:16 volumioraspi4 volumio[760]: verbose: ControllerMpd::sendMpdCommand status May 13 18:36:16 volumioraspi4 volumio[760]: info: May 13 18:36:16 volumioraspi4 volumio[760]: ---------------------------- MPD announces state update: player May 13 18:36:16 volumioraspi4 volumio[760]: info: ControllerMpd::getState May 13 18:36:16 volumioraspi4 volumio[760]: verbose: ControllerMpd::sendMpdCommand status May 13 18:36:16 volumioraspi4 volumio[760]: info: May 13 18:36:16 volumioraspi4 volumio[760]: ---------------------------- MPD announces state update: player May 13 18:36:16 volumioraspi4 volumio[760]: info: sendMpdCommand status took 3 milliseconds May 13 18:36:16 volumioraspi4 volumio[760]: info: ControllerMpd::getState May 13 18:36:16 volumioraspi4 volumio[760]: verbose: ControllerMpd::sendMpdCommand status May 13 18:36:16 volumioraspi4 volumio[760]: info: sendMpdCommand status took 2 milliseconds May 13 18:36:16 volumioraspi4 volumio[760]: verbose: ControllerMpd::parseState May 13 18:36:16 volumioraspi4 volumio[760]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 13 18:36:16 volumioraspi4 volumio[760]: verbose: ControllerMpd::parseState May 13 18:36:16 volumioraspi4 volumio[760]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 13 18:36:16 volumioraspi4 volumio[760]: info: May 13 18:36:16 volumioraspi4 volumio[760]: ---------------------------- MPD announces state update: player May 13 18:36:16 volumioraspi4 volumio[760]: info: ControllerMpd::getState May 13 18:36:16 volumioraspi4 volumio[760]: verbose: ControllerMpd::sendMpdCommand status May 13 18:36:16 volumioraspi4 volumio[760]: info: May 13 18:36:16 volumioraspi4 volumio[760]: ---------------------------- MPD announces state update: player May 13 18:36:16 volumioraspi4 volumio[760]: info: ControllerMpd::getState May 13 18:36:16 volumioraspi4 volumio[760]: verbose: ControllerMpd::sendMpdCommand status May 13 18:36:16 volumioraspi4 volumio[760]: info: sendMpdCommand status took 5 milliseconds May 13 18:36:16 volumioraspi4 volumio[760]: info: sendMpdCommand playlistinfo took 5 milliseconds May 13 18:36:16 volumioraspi4 volumio[760]: info: sendMpdCommand playlistinfo took 4 milliseconds May 13 18:36:16 volumioraspi4 volumio[760]: info: sendMpdCommand status took 3 milliseconds May 13 18:36:16 volumioraspi4 volumio[760]: info: sendMpdCommand status took 2 milliseconds May 13 18:36:16 volumioraspi4 volumio[760]: verbose: ControllerMpd::parseState May 13 18:36:16 volumioraspi4 volumio[760]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 13 18:36:16 volumioraspi4 volumio[760]: verbose: ControllerMpd::parseTrackInfo May 13 18:36:16 volumioraspi4 volumio[760]: verbose: ControllerMpd::parseTrackInfo May 13 18:36:16 volumioraspi4 volumio[760]: verbose: ControllerMpd::parseState May 13 18:36:16 volumioraspi4 volumio[760]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 13 18:36:16 volumioraspi4 volumio[760]: verbose: ControllerMpd::parseState May 13 18:36:16 volumioraspi4 volumio[760]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 13 18:36:16 volumioraspi4 volumio[760]: info: ControllerMpd::pushState May 13 18:36:16 volumioraspi4 volumio[760]: info: CoreCommandRouter::servicePushState May 13 18:36:16 volumioraspi4 volumio[760]: info: CorePlayQueue::getTrack 0 May 13 18:36:16 volumioraspi4 volumio[760]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":245,"samplerate":"192 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"239022325","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=qobuz://song/239022325","trackType":"qobuz"} May 13 18:36:16 volumioraspi4 volumio[760]: verbose: CURRENT POSITION 0 May 13 18:36:16 volumioraspi4 volumio[760]: info: CoreStateMachine::syncState stateService play May 13 18:36:16 volumioraspi4 volumio[760]: info: CoreStateMachine::syncState currentStatus stop May 13 18:36:16 volumioraspi4 volumio[760]: info: ControllerMpd::pushState May 13 18:36:16 volumioraspi4 volumio[760]: info: CoreCommandRouter::servicePushState May 13 18:36:16 volumioraspi4 volumio[760]: info: CorePlayQueue::getTrack 0 May 13 18:36:16 volumioraspi4 volumio[760]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":245,"samplerate":"192 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"239022325","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=qobuz://song/239022325","trackType":"qobuz"} May 13 18:36:16 volumioraspi4 volumio[760]: verbose: CURRENT POSITION 0 May 13 18:36:16 volumioraspi4 volumio[760]: info: CoreStateMachine::syncState stateService play May 13 18:36:16 volumioraspi4 volumio[760]: info: CoreStateMachine::syncState currentStatus play May 13 18:36:16 volumioraspi4 volumio[760]: info: Received an update from plugin. extracting info from payload May 13 18:36:16 volumioraspi4 volumio[760]: info: CoreStateMachine::pushState May 13 18:36:16 volumioraspi4 volumio[760]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 13 18:36:16 volumioraspi4 volumio[760]: info: CoreCommandRouter::volumioPushState May 13 18:36:16 volumioraspi4 volumio[760]: info: MRS: Pushing multiroomSync output update for this device May 13 18:36:16 volumioraspi4 volumio[760]: info: MRS: Pushing multiroomSync output May 13 18:36:16 volumioraspi4 volumio[760]: info: CoreStateMachine::pushState May 13 18:36:16 volumioraspi4 volumio[760]: info: CoreCommandRouter::volumioPushState May 13 18:36:16 volumioraspi4 volumio[760]: info: MRS: Pushing multiroomSync output update for this device May 13 18:36:16 volumioraspi4 volumio[760]: info: MRS: Pushing multiroomSync output May 13 18:36:16 volumioraspi4 volumio[760]: info: ------------------------------ 28ms May 13 18:36:16 volumioraspi4 volumio[760]: info: ------------------------------ 30ms May 13 18:36:16 volumioraspi4 volumio[760]: info: May 13 18:36:16 volumioraspi4 volumio[760]: ---------------------------- MPD announces state update: player May 13 18:36:16 volumioraspi4 volumio[760]: info: ControllerMpd::getState May 13 18:36:16 volumioraspi4 volumio[760]: verbose: ControllerMpd::sendMpdCommand status May 13 18:36:16 volumioraspi4 volumio[760]: info: sendMpdCommand playlistinfo took 21 milliseconds May 13 18:36:16 volumioraspi4 volumio[760]: info: sendMpdCommand playlistinfo took 21 milliseconds May 13 18:36:16 volumioraspi4 volumio[760]: info: sendMpdCommand playlistinfo took 21 milliseconds May 13 18:36:16 volumioraspi4 volumio[760]: info: sendMpdCommand status took 2 milliseconds May 13 18:36:16 volumioraspi4 volumio[760]: verbose: ControllerMpd::parseTrackInfo May 13 18:36:16 volumioraspi4 volumio[760]: verbose: ControllerMpd::parseTrackInfo May 13 18:36:16 volumioraspi4 volumio[760]: verbose: ControllerMpd::parseTrackInfo May 13 18:36:16 volumioraspi4 volumio[760]: verbose: ControllerMpd::parseState May 13 18:36:16 volumioraspi4 volumio[760]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 13 18:36:16 volumioraspi4 volumio[760]: info: ControllerMpd::pushState May 13 18:36:16 volumioraspi4 volumio[760]: info: CoreCommandRouter::servicePushState May 13 18:36:16 volumioraspi4 volumio[760]: info: CorePlayQueue::getTrack 0 May 13 18:36:16 volumioraspi4 volumio[760]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":245,"samplerate":"192 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"239022325","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=qobuz://song/239022325","trackType":"qobuz"} May 13 18:36:16 volumioraspi4 volumio[760]: verbose: CURRENT POSITION 0 May 13 18:36:16 volumioraspi4 volumio[760]: info: CoreStateMachine::syncState stateService play May 13 18:36:16 volumioraspi4 volumio[760]: info: CoreStateMachine::syncState currentStatus play May 13 18:36:16 volumioraspi4 volumio[760]: info: Received an update from plugin. extracting info from payload May 13 18:36:16 volumioraspi4 volumio[760]: info: CoreStateMachine::pushState May 13 18:36:16 volumioraspi4 volumio[760]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 13 18:36:16 volumioraspi4 volumio[760]: info: CoreCommandRouter::volumioPushState May 13 18:36:16 volumioraspi4 volumio[760]: info: MRS: Pushing multiroomSync output update for this device May 13 18:36:16 volumioraspi4 volumio[760]: info: MRS: Pushing multiroomSync output May 13 18:36:16 volumioraspi4 volumio[760]: info: CoreStateMachine::pushState May 13 18:36:16 volumioraspi4 volumio[760]: info: CoreCommandRouter::volumioPushState May 13 18:36:16 volumioraspi4 volumio[760]: info: MRS: Pushing multiroomSync output update for this device May 13 18:36:16 volumioraspi4 volumio[760]: info: MRS: Pushing multiroomSync output May 13 18:36:16 volumioraspi4 volumio[760]: info: ControllerMpd::pushState May 13 18:36:16 volumioraspi4 volumio[760]: info: CoreCommandRouter::servicePushState May 13 18:36:16 volumioraspi4 volumio[760]: info: CorePlayQueue::getTrack 0 May 13 18:36:16 volumioraspi4 volumio[760]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":245,"samplerate":"192 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"239022325","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=qobuz://song/239022325","trackType":"qobuz"} May 13 18:36:16 volumioraspi4 volumio[760]: verbose: CURRENT POSITION 0 May 13 18:36:16 volumioraspi4 volumio[760]: info: CoreStateMachine::syncState stateService play May 13 18:36:16 volumioraspi4 volumio[760]: info: CoreStateMachine::syncState currentStatus play May 13 18:36:16 volumioraspi4 volumio[760]: info: Received an update from plugin. extracting info from payload May 13 18:36:16 volumioraspi4 volumio[760]: info: CoreStateMachine::pushState May 13 18:36:16 volumioraspi4 volumio[760]: info: CoreCommandRouter::volumioPushState May 13 18:36:16 volumioraspi4 volumio[760]: info: MRS: Pushing multiroomSync output update for this device May 13 18:36:16 volumioraspi4 volumio[760]: info: MRS: Pushing multiroomSync output May 13 18:36:16 volumioraspi4 volumio[760]: info: CoreStateMachine::pushState May 13 18:36:16 volumioraspi4 volumio[760]: info: CoreCommandRouter::volumioPushState May 13 18:36:16 volumioraspi4 volumio[760]: info: MRS: Pushing multiroomSync output update for this device May 13 18:36:16 volumioraspi4 volumio[760]: info: MRS: Pushing multiroomSync output May 13 18:36:16 volumioraspi4 volumio[760]: info: ControllerMpd::pushState May 13 18:36:16 volumioraspi4 volumio[760]: info: CoreCommandRouter::servicePushState May 13 18:36:16 volumioraspi4 volumio[760]: info: CorePlayQueue::getTrack 0 May 13 18:36:16 volumioraspi4 volumio[760]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":245,"samplerate":"192 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"239022325","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=qobuz://song/239022325","trackType":"qobuz"} May 13 18:36:16 volumioraspi4 volumio[760]: verbose: CURRENT POSITION 0 May 13 18:36:16 volumioraspi4 volumio[760]: info: CoreStateMachine::syncState stateService play May 13 18:36:16 volumioraspi4 volumio[760]: info: CoreStateMachine::syncState currentStatus play May 13 18:36:16 volumioraspi4 volumio[760]: info: Received an update from plugin. extracting info from payload May 13 18:36:16 volumioraspi4 volumio[760]: info: CoreStateMachine::pushState May 13 18:36:16 volumioraspi4 volumio[760]: info: CoreCommandRouter::volumioPushState May 13 18:36:16 volumioraspi4 volumio[760]: info: MRS: Pushing multiroomSync output update for this device May 13 18:36:16 volumioraspi4 volumio[760]: info: MRS: Pushing multiroomSync output May 13 18:36:16 volumioraspi4 volumio[760]: info: CoreStateMachine::pushState May 13 18:36:16 volumioraspi4 volumio[760]: info: CoreCommandRouter::volumioPushState May 13 18:36:16 volumioraspi4 volumio[760]: info: MRS: Pushing multiroomSync output update for this device May 13 18:36:16 volumioraspi4 volumio[760]: info: MRS: Pushing multiroomSync output May 13 18:36:16 volumioraspi4 volumio[760]: info: ------------------------------ 56ms May 13 18:36:16 volumioraspi4 volumio[760]: info: ------------------------------ 54ms May 13 18:36:16 volumioraspi4 volumio[760]: info: ------------------------------ 53ms May 13 18:36:16 volumioraspi4 volumio[760]: info: sendMpdCommand playlistinfo took 29 milliseconds May 13 18:36:16 volumioraspi4 volumio[760]: verbose: ControllerMpd::parseTrackInfo May 13 18:36:16 volumioraspi4 volumio[760]: info: ControllerMpd::pushState May 13 18:36:16 volumioraspi4 volumio[760]: info: CoreCommandRouter::servicePushState May 13 18:36:16 volumioraspi4 volumio[760]: info: CorePlayQueue::getTrack 0 May 13 18:36:16 volumioraspi4 volumio[760]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":245,"samplerate":"192 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"239022325","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=qobuz://song/239022325","trackType":"qobuz"} May 13 18:36:16 volumioraspi4 volumio[760]: verbose: CURRENT POSITION 0 May 13 18:36:16 volumioraspi4 volumio[760]: info: CoreStateMachine::syncState stateService play May 13 18:36:16 volumioraspi4 volumio[760]: info: CoreStateMachine::syncState currentStatus play May 13 18:36:16 volumioraspi4 volumio[760]: info: Received an update from plugin. extracting info from payload May 13 18:36:16 volumioraspi4 volumio[760]: info: CoreStateMachine::pushState May 13 18:36:16 volumioraspi4 volumio[760]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 13 18:36:16 volumioraspi4 volumio[760]: info: CoreCommandRouter::volumioPushState May 13 18:36:16 volumioraspi4 volumio[760]: info: MRS: Pushing multiroomSync output update for this device May 13 18:36:16 volumioraspi4 volumio[760]: info: MRS: Pushing multiroomSync output May 13 18:36:16 volumioraspi4 volumio[760]: info: CoreStateMachine::pushState May 13 18:36:16 volumioraspi4 volumio[760]: info: CoreCommandRouter::volumioPushState May 13 18:36:16 volumioraspi4 volumio[760]: info: MRS: Pushing multiroomSync output update for this device May 13 18:36:16 volumioraspi4 volumio[760]: info: MRS: Pushing multiroomSync output May 13 18:36:16 volumioraspi4 volumio[760]: info: ------------------------------ 43ms May 13 18:37:07 volumioraspi4 volumio[760]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 13 18:37:07 volumioraspi4 volumio[760]: Error: connect ETIMEDOUT 151.101.126.79:80 May 13 18:37:07 volumioraspi4 volumio[760]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) { May 13 18:37:07 volumioraspi4 volumio[760]: errno: -110, May 13 18:37:07 volumioraspi4 volumio[760]: code: 'ETIMEDOUT', May 13 18:37:07 volumioraspi4 volumio[760]: syscall: 'connect', May 13 18:37:07 volumioraspi4 volumio[760]: address: '151.101.126.79', May 13 18:37:07 volumioraspi4 volumio[760]: port: 80 May 13 18:37:07 volumioraspi4 volumio[760]: } May 13 18:37:07 volumioraspi4 volumio[760]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 13 18:37:08 volumioraspi4 sudo[28043]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-05-13 18:36 May 13 18:37:08 volumioraspi4 sudo[28043]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Raspbian GNU/Linux 10 (buster)" NAME="Raspbian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="e7445fab547cd22e23d9bef72406cfb610bc1d7d" VOLUMIO_FE_VERSION="5d5e99f8f803b3ec5fc5e8ca13bb4023600f3eee" VOLUMIO_FE3_VERSION="a6ae210575eae1ff43f06ab71e1cd17576840623" VOLUMIO_BE_VERSION="a9e1e1dd6072ffb15c0fcb8938d9ea0d8900c0da" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Wed 24 Apr 2024 02:10:14 PM CEST" VOLUMIO_VERSION="3.661" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="5bdefd4af4423fd17aacb83a8538bf1f"