-- Logs begin at Fri 2024-07-12 17:43:06 CEST, end at Fri 2024-07-12 18:05:46 CEST. -- Jul 12 18:04:02 rivowoonkamer volumio[3092]: info: Jul 12 18:04:02 rivowoonkamer volumio[3092]: ---------------------------- MPD announces state update: player Jul 12 18:04:02 rivowoonkamer volumio[3092]: info: ControllerMpd::getState Jul 12 18:04:02 rivowoonkamer volumio[3092]: verbose: ControllerMpd::sendMpdCommand status Jul 12 18:04:02 rivowoonkamer volumio[3092]: info: sendMpdCommand status took 2 milliseconds Jul 12 18:04:02 rivowoonkamer volumio[3092]: verbose: ControllerMpd::parseState Jul 12 18:04:02 rivowoonkamer volumio[3092]: info: ControllerMpd::pushState Jul 12 18:04:02 rivowoonkamer volumio[3092]: info: CoreCommandRouter::servicePushState Jul 12 18:04:02 rivowoonkamer volumio[3092]: info: CoreStateMachine::pushState Jul 12 18:04:02 rivowoonkamer volumio[3092]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 12 18:04:02 rivowoonkamer volumio[3092]: info: CoreCommandRouter::volumioPushState Jul 12 18:04:02 rivowoonkamer volumio[3092]: info: MRS: Pushing multiroomSync output update for this device Jul 12 18:04:02 rivowoonkamer volumio[3092]: info: MRS: Pushing multiroomSync output Jul 12 18:04:02 rivowoonkamer volumio[3092]: info: CorePlayQueue::getTrack 0 Jul 12 18:04:02 rivowoonkamer volumio[3092]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Jul 12 18:04:02 rivowoonkamer volumio[3092]: verbose: CURRENT POSITION 0 Jul 12 18:04:02 rivowoonkamer volumio[3092]: info: CoreStateMachine::syncState stateService stop Jul 12 18:04:02 rivowoonkamer volumio[3092]: info: CoreStateMachine::syncState currentStatus play Jul 12 18:04:02 rivowoonkamer volumio[3092]: info: CoreStateMachine::play index undefined Jul 12 18:04:02 rivowoonkamer volumio[3092]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 12 18:04:02 rivowoonkamer volumio[3092]: info: CoreStateMachine::pushState Jul 12 18:04:02 rivowoonkamer volumio[3092]: info: CorePlayQueue::getTrack 1 Jul 12 18:04:02 rivowoonkamer volumio[3092]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 12 18:04:02 rivowoonkamer volumio[3092]: info: CoreCommandRouter::volumioPushState Jul 12 18:04:02 rivowoonkamer volumio[3092]: info: MRS: Pushing multiroomSync output update for this device Jul 12 18:04:02 rivowoonkamer volumio[3092]: info: MRS: Pushing multiroomSync output Jul 12 18:04:02 rivowoonkamer volumio[3092]: info: CorePlayQueue::getTrack 1 Jul 12 18:04:02 rivowoonkamer volumio[3092]: info: CoreStateMachine::startPlaybackTimer Jul 12 18:04:02 rivowoonkamer volumio[3092]: info: CorePlayQueue::getTrack 1 Jul 12 18:04:02 rivowoonkamer volumio[3092]: info: [1720800242698] ControllerQobuz::clearAddPlayTrack Jul 12 18:04:02 rivowoonkamer volumio[3092]: info: ------------------------------ 41ms Jul 12 18:04:02 rivowoonkamer volumio[3092]: verbose: ControllerMpd::sendMpdCommand stop Jul 12 18:04:02 rivowoonkamer volumio[3092]: info: CoreStateMachine::pushState Jul 12 18:04:02 rivowoonkamer volumio[3092]: info: CorePlayQueue::getTrack 1 Jul 12 18:04:02 rivowoonkamer volumio[3092]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 12 18:04:02 rivowoonkamer volumio[3092]: info: CoreCommandRouter::volumioPushState Jul 12 18:04:02 rivowoonkamer volumio[3092]: info: MRS: Pushing multiroomSync output update for this device Jul 12 18:04:02 rivowoonkamer volumio[3092]: info: MRS: Pushing multiroomSync output Jul 12 18:04:02 rivowoonkamer volumio[3092]: info: sendMpdCommand stop took 16 milliseconds Jul 12 18:04:02 rivowoonkamer volumio[3092]: verbose: ControllerMpd::sendMpdCommand clear Jul 12 18:04:02 rivowoonkamer volumio[3092]: info: Signalling Playback active due to playback status change Jul 12 18:04:02 rivowoonkamer volumio[3092]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jul 12 18:04:02 rivowoonkamer volumio[3092]: info: Updating RAAT Signal Path Jul 12 18:04:02 rivowoonkamer volumio[3092]: info: Jul 12 18:04:02 rivowoonkamer volumio[3092]: ---------------------------- MPD announces system playlist update Jul 12 18:04:02 rivowoonkamer volumio[3092]: info: Ignoring MPD Status Update Jul 12 18:04:02 rivowoonkamer volumio[3092]: info: sendMpdCommand clear took 14 milliseconds Jul 12 18:04:02 rivowoonkamer volumio[3092]: verbose: ControllerMpd::sendMpdCommand load "http://127.0.0.1:3245?data=qobuz://song/101995181" Jul 12 18:04:02 rivowoonkamer volumio[3092]: STREAMING PROXY: Handling url /?data=qobuz://song/101995181 Jul 12 18:04:02 rivowoonkamer volumio[3092]: error: updateQueue error: null Jul 12 18:04:02 rivowoonkamer volumio[3092]: info: ------------------------------ 14ms Jul 12 18:04:02 rivowoonkamer volumio[3092]: info: Executing endpoint getStreamUrlqobuz Jul 12 18:04:02 rivowoonkamer volumio[3092]: info: CoreCommandRouter::executeOnPlugin: qobuz , getStreamUrlAPI Jul 12 18:04:02 rivowoonkamer volumio[3092]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jul 12 18:04:02 rivowoonkamer volumio[3092]: info: Updating RAAT Signal Path Jul 12 18:04:02 rivowoonkamer volumio[3092]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jul 12 18:04:02 rivowoonkamer volumio[3092]: info: Updating RAAT Signal Path Jul 12 18:04:02 rivowoonkamer volumio[3092]: info: MCU Signalled Playback Inactive Jul 12 18:04:03 rivowoonkamer volumio[3092]: info: getStreamUrl took 240 milliseconds Jul 12 18:04:03 rivowoonkamer volumio[3092]: STREAMING PROXY: Got real url: http://streaming-qobuz-std.akamaized.net:80/file?uid=619379&eid=101995181&fmt=7&profile=raw&range=20-30&app_id=539451548&etsp=1720803842&hmac=8ZQnzTcw3BFXGHeX2s6rkccSRqk Jul 12 18:04:03 rivowoonkamer volumio[3092]: STREAMING PROXY: Response: 200, length: 5140681 Jul 12 18:04:03 rivowoonkamer volumio[3092]: STREAMING PROXY: Client dropped request, destroying Jul 12 18:04:03 rivowoonkamer volumio[3092]: verbose: ControllerMpd::sendMpdCommand add "http://127.0.0.1:3245?data=qobuz://song/101995181" Jul 12 18:04:03 rivowoonkamer volumio[3092]: info: Jul 12 18:04:03 rivowoonkamer volumio[3092]: ---------------------------- MPD announces system playlist update Jul 12 18:04:03 rivowoonkamer volumio[3092]: info: Ignoring MPD Status Update Jul 12 18:04:03 rivowoonkamer volumio[3092]: info: sendMpdCommand add "http://127.0.0.1:3245?data=qobuz://song/101995181" took 2 milliseconds Jul 12 18:04:03 rivowoonkamer volumio[3092]: info: CoreStateMachine::setConsumeUpdateService mpd Jul 12 18:04:03 rivowoonkamer volumio[3092]: verbose: ControllerMpd::sendMpdCommand play Jul 12 18:04:03 rivowoonkamer volumio[3092]: info: ------------------------------ 4ms Jul 12 18:04:03 rivowoonkamer volumio[3092]: info: sendMpdCommand play took 2 milliseconds Jul 12 18:04:03 rivowoonkamer volumio[3092]: STREAMING PROXY: Handling url /?data=qobuz://song/101995181 Jul 12 18:04:03 rivowoonkamer volumio[3092]: info: Executing endpoint getStreamUrlqobuz Jul 12 18:04:03 rivowoonkamer volumio[3092]: info: CoreCommandRouter::executeOnPlugin: qobuz , getStreamUrlAPI Jul 12 18:04:03 rivowoonkamer volumio[3092]: info: getStreamUrl took 229 milliseconds Jul 12 18:04:03 rivowoonkamer volumio[3092]: STREAMING PROXY: Got real url: http://streaming-qobuz-std.akamaized.net:80/file?uid=619379&eid=101995181&fmt=7&profile=raw&range=20-30&app_id=539451548&etsp=1720803843&hmac=r4dFjoSxWv8_E5O7wM_kFk2WUEQ Jul 12 18:04:03 rivowoonkamer volumio[3092]: STREAMING PROXY: Response: 200, length: 5140681 Jul 12 18:04:03 rivowoonkamer volumio[3092]: info: Jul 12 18:04:03 rivowoonkamer volumio[3092]: ---------------------------- MPD announces state update: player Jul 12 18:04:03 rivowoonkamer volumio[3092]: info: ControllerMpd::getState Jul 12 18:04:03 rivowoonkamer volumio[3092]: verbose: ControllerMpd::sendMpdCommand status Jul 12 18:04:03 rivowoonkamer volumio[3092]: info: sendMpdCommand status took 21 milliseconds Jul 12 18:04:03 rivowoonkamer volumio[3092]: verbose: ControllerMpd::parseState Jul 12 18:04:03 rivowoonkamer volumio[3092]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jul 12 18:04:03 rivowoonkamer volumio[3092]: info: Jul 12 18:04:03 rivowoonkamer volumio[3092]: ---------------------------- MPD announces state update: player Jul 12 18:04:03 rivowoonkamer volumio[3092]: info: ControllerMpd::getState Jul 12 18:04:03 rivowoonkamer volumio[3092]: verbose: ControllerMpd::sendMpdCommand status Jul 12 18:04:03 rivowoonkamer volumio[3092]: info: sendMpdCommand playlistinfo took 9 milliseconds Jul 12 18:04:03 rivowoonkamer volumio[3092]: verbose: ControllerMpd::parseTrackInfo Jul 12 18:04:03 rivowoonkamer volumio[3092]: info: ControllerMpd::pushState Jul 12 18:04:03 rivowoonkamer volumio[3092]: info: CoreCommandRouter::servicePushState Jul 12 18:04:03 rivowoonkamer volumio[3092]: info: CorePlayQueue::getTrack 1 Jul 12 18:04:03 rivowoonkamer volumio[3092]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":30,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"101995181","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=qobuz://song/101995181","trackType":"qobuz"} Jul 12 18:04:03 rivowoonkamer volumio[3092]: verbose: CURRENT POSITION 1 Jul 12 18:04:03 rivowoonkamer volumio[3092]: info: CoreStateMachine::syncState stateService play Jul 12 18:04:03 rivowoonkamer volumio[3092]: info: CoreStateMachine::syncState currentStatus stop Jul 12 18:04:03 rivowoonkamer volumio[3092]: info: ------------------------------ 48ms Jul 12 18:04:03 rivowoonkamer volumio[3092]: info: sendMpdCommand status took 16 milliseconds Jul 12 18:04:03 rivowoonkamer volumio[3092]: verbose: ControllerMpd::parseState Jul 12 18:04:03 rivowoonkamer volumio[3092]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jul 12 18:04:03 rivowoonkamer volumio[3092]: info: sendMpdCommand playlistinfo took 2 milliseconds Jul 12 18:04:03 rivowoonkamer volumio[3092]: verbose: ControllerMpd::parseTrackInfo Jul 12 18:04:03 rivowoonkamer volumio[3092]: info: ControllerMpd::pushState Jul 12 18:04:03 rivowoonkamer volumio[3092]: info: CoreCommandRouter::servicePushState Jul 12 18:04:03 rivowoonkamer volumio[3092]: info: CorePlayQueue::getTrack 1 Jul 12 18:04:03 rivowoonkamer volumio[3092]: verbose: STATE SERVICE {"status":"play","position":0,"seek":1238,"duration":30,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"1277 Kbps","isStreaming":false,"title":"101995181","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=qobuz://song/101995181","trackType":"qobuz"} Jul 12 18:04:03 rivowoonkamer volumio[3092]: verbose: CURRENT POSITION 1 Jul 12 18:04:03 rivowoonkamer volumio[3092]: info: CoreStateMachine::syncState stateService play Jul 12 18:04:03 rivowoonkamer volumio[3092]: info: CoreStateMachine::syncState currentStatus play Jul 12 18:04:03 rivowoonkamer volumio[3092]: info: Received an update from plugin. extracting info from payload Jul 12 18:04:03 rivowoonkamer volumio[3092]: info: CoreStateMachine::pushState Jul 12 18:04:03 rivowoonkamer volumio[3092]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 12 18:04:03 rivowoonkamer volumio[3092]: info: CoreCommandRouter::volumioPushState Jul 12 18:04:03 rivowoonkamer volumio[3092]: info: MRS: Pushing multiroomSync output update for this device Jul 12 18:04:03 rivowoonkamer volumio[3092]: info: MRS: Pushing multiroomSync output Jul 12 18:04:03 rivowoonkamer volumio[3092]: info: CoreStateMachine::pushState Jul 12 18:04:03 rivowoonkamer volumio[3092]: info: CoreCommandRouter::volumioPushState Jul 12 18:04:03 rivowoonkamer volumio[3092]: info: MRS: Pushing multiroomSync output update for this device Jul 12 18:04:03 rivowoonkamer volumio[3092]: info: MRS: Pushing multiroomSync output Jul 12 18:04:03 rivowoonkamer volumio[3092]: info: ------------------------------ 73ms Jul 12 18:04:03 rivowoonkamer volumio[3092]: info: Signalling Playback active due to playback status change Jul 12 18:04:03 rivowoonkamer volumio[3092]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jul 12 18:04:03 rivowoonkamer volumio[3092]: info: Updating RAAT Signal Path Jul 12 18:04:03 rivowoonkamer volumio[3092]: STREAMING PROXY: Client dropped request, destroying Jul 12 18:04:03 rivowoonkamer volumio[3092]: info: Signalling Playback active due to playback status change Jul 12 18:04:03 rivowoonkamer volumio[3092]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jul 12 18:04:03 rivowoonkamer volumio[3092]: info: Updating RAAT Signal Path Jul 12 18:04:03 rivowoonkamer volumio[3092]: info: MCU Signalled Playback Active Jul 12 18:04:20 rivowoonkamer volumio[3092]: info: CoreCommandRouter::executeOnPlugin: qobuz , handleBrowseUri Jul 12 18:04:21 rivowoonkamer volumio[3092]: info: handleBrowseUri took 522 milliseconds Jul 12 18:04:21 rivowoonkamer volumio[3092]: info: Preload queue cleared Jul 12 18:04:21 rivowoonkamer volumio[3092]: info: Preloading song: qobuz://song/161150239 Jul 12 18:04:21 rivowoonkamer volumio[3092]: info: Preloading song: qobuz://song/161150240 Jul 12 18:04:21 rivowoonkamer volumio[3092]: info: Preloading song: qobuz://song/161150241 Jul 12 18:04:21 rivowoonkamer volumio[3092]: info: Preloading song: qobuz://song/161150242 Jul 12 18:04:21 rivowoonkamer volumio[3092]: info: Preloading song: qobuz://song/161150243 Jul 12 18:04:21 rivowoonkamer volumio[3092]: info: Preloading song: qobuz://song/161150244 Jul 12 18:04:21 rivowoonkamer volumio[3092]: info: Preloading song: qobuz://song/161150245 Jul 12 18:04:21 rivowoonkamer volumio[3092]: info: Preloading song: qobuz://song/161150246 Jul 12 18:04:21 rivowoonkamer volumio[3092]: info: Preloading song: qobuz://song/161150247 Jul 12 18:04:21 rivowoonkamer volumio[3092]: info: Preloading song: qobuz://song/161150248 Jul 12 18:04:21 rivowoonkamer volumio[3092]: info: Preloading song: qobuz://song/161150249 Jul 12 18:04:21 rivowoonkamer volumio[3092]: info: Preloading song: qobuz://song/161150250 Jul 12 18:04:21 rivowoonkamer volumio[3092]: info: Exploding uri qobuz://song/161150239 in service qobuz Jul 12 18:04:21 rivowoonkamer volumio[3092]: info: Exploding uri qobuz://song/161150240 in service qobuz Jul 12 18:04:21 rivowoonkamer volumio[3092]: info: Executing endpoint getSimilarAlbums Jul 12 18:04:21 rivowoonkamer volumio[3092]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getSimilarAlbums Jul 12 18:04:21 rivowoonkamer volumio[3092]: info: Exploding uri qobuz://song/161150241 in service qobuz Jul 12 18:04:21 rivowoonkamer volumio[3092]: info: Exploding uri qobuz://song/161150242 in service qobuz Jul 12 18:04:21 rivowoonkamer volumio[3092]: info: Executing endpoint metavolumio Jul 12 18:04:21 rivowoonkamer volumio[3092]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Jul 12 18:04:21 rivowoonkamer volumio[3092]: info: Executing endpoint metavolumio Jul 12 18:04:21 rivowoonkamer volumio[3092]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Jul 12 18:04:21 rivowoonkamer volumio[3092]: info: Exploding uri qobuz://song/161150243 in service qobuz Jul 12 18:04:21 rivowoonkamer volumio[3092]: info: Exploding uri qobuz://song/161150244 in service qobuz Jul 12 18:04:21 rivowoonkamer volumio[3092]: info: Exploding uri qobuz://song/161150245 in service qobuz Jul 12 18:04:21 rivowoonkamer volumio[3092]: info: explodeUri took 315 milliseconds Jul 12 18:04:21 rivowoonkamer volumio[3092]: info: Exploding uri qobuz://song/161150246 in service qobuz Jul 12 18:04:21 rivowoonkamer volumio[3092]: info: explodeUri took 316 milliseconds Jul 12 18:04:21 rivowoonkamer volumio[3092]: info: Exploding uri qobuz://song/161150247 in service qobuz Jul 12 18:04:21 rivowoonkamer volumio[3092]: info: explodeUri took 346 milliseconds Jul 12 18:04:21 rivowoonkamer volumio[3092]: info: Exploding uri qobuz://song/161150248 in service qobuz Jul 12 18:04:21 rivowoonkamer volumio[3092]: info: explodeUri took 313 milliseconds Jul 12 18:04:21 rivowoonkamer volumio[3092]: info: Exploding uri qobuz://song/161150249 in service qobuz Jul 12 18:04:21 rivowoonkamer volumio[3092]: info: explodeUri took 286 milliseconds Jul 12 18:04:21 rivowoonkamer volumio[3092]: info: Exploding uri qobuz://song/161150250 in service qobuz Jul 12 18:04:21 rivowoonkamer volumio[3092]: info: explodeUri took 365 milliseconds Jul 12 18:04:21 rivowoonkamer volumio[3092]: info: explodeUri took 336 milliseconds Jul 12 18:04:21 rivowoonkamer volumio[3092]: info: explodeUri took 249 milliseconds Jul 12 18:04:22 rivowoonkamer volumio[3092]: info: explodeUri took 365 milliseconds Jul 12 18:04:22 rivowoonkamer volumio[3092]: info: explodeUri took 295 milliseconds Jul 12 18:04:22 rivowoonkamer volumio[3092]: info: explodeUri took 378 milliseconds Jul 12 18:04:22 rivowoonkamer volumio[3092]: info: explodeUri took 368 milliseconds Jul 12 18:04:24 rivowoonkamer volumio[3092]: info: Preload queue cleared Jul 12 18:04:24 rivowoonkamer volumio[3092]: info: CoreCommandRouter::volumioReplaceandPlayItems Jul 12 18:04:24 rivowoonkamer volumio[3092]: info: CoreStateMachine::ClearQueue Jul 12 18:04:24 rivowoonkamer volumio[3092]: info: CoreStateMachine::stop Jul 12 18:04:24 rivowoonkamer volumio[3092]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 12 18:04:24 rivowoonkamer volumio[3092]: info: CoreStateMachine::stPlaybackTimer Jul 12 18:04:24 rivowoonkamer volumio[3092]: info: CoreStateMachine::updateTrackBlock Jul 12 18:04:24 rivowoonkamer volumio[3092]: info: CorePlayQueue::getTrackBlock Jul 12 18:04:24 rivowoonkamer volumio[3092]: info: CoreStateMachine::pushState Jul 12 18:04:24 rivowoonkamer volumio[3092]: info: CorePlayQueue::getTrack 1 Jul 12 18:04:24 rivowoonkamer volumio[3092]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 12 18:04:24 rivowoonkamer volumio[3092]: info: CoreCommandRouter::volumioPushState Jul 12 18:04:24 rivowoonkamer volumio[3092]: info: MRS: Pushing multiroomSync output update for this device Jul 12 18:04:24 rivowoonkamer volumio[3092]: info: MRS: Pushing multiroomSync output Jul 12 18:04:24 rivowoonkamer volumio[3092]: info: CoreStateMachine::serviceStop Jul 12 18:04:24 rivowoonkamer volumio[3092]: info: CorePlayQueue::getTrack 1 Jul 12 18:04:24 rivowoonkamer volumio[3092]: info: CoreCommandRouter::serviceStop Jul 12 18:04:24 rivowoonkamer volumio[3092]: info: [1720800264024] ControllerQobuz::stop Jul 12 18:04:24 rivowoonkamer volumio[3092]: info: CoreStateMachine::setConsumeUpdateService mpd Jul 12 18:04:24 rivowoonkamer volumio[3092]: info: ControllerMpd::stop Jul 12 18:04:24 rivowoonkamer volumio[3092]: verbose: ControllerMpd::sendMpdCommand stop Jul 12 18:04:24 rivowoonkamer volumio[3092]: info: CorePlayQueue::clearPlayQueue Jul 12 18:04:24 rivowoonkamer volumio[3092]: info: CorePlayQueue::saveQueue Jul 12 18:04:24 rivowoonkamer volumio[3092]: info: CoreCommandRouter::volumioPushQueue Jul 12 18:04:24 rivowoonkamer volumio[3092]: info: CoreStateMachine::addQueueItems Jul 12 18:04:24 rivowoonkamer volumio[3092]: info: CorePlayQueue::addQueueItems Jul 12 18:04:24 rivowoonkamer volumio[3092]: info: Preload queue cleared Jul 12 18:04:24 rivowoonkamer volumio[3092]: info: Adding Item to queue: qobuz://song/161150239 Jul 12 18:04:24 rivowoonkamer volumio[3092]: info: Using cached record of: qobuz://song/161150239 Jul 12 18:04:24 rivowoonkamer volumio[3092]: info: Adding Item to queue: qobuz://song/161150240 Jul 12 18:04:24 rivowoonkamer volumio[3092]: info: Using cached record of: qobuz://song/161150240 Jul 12 18:04:24 rivowoonkamer volumio[3092]: info: Adding Item to queue: qobuz://song/161150241 Jul 12 18:04:24 rivowoonkamer volumio[3092]: info: Using cached record of: qobuz://song/161150241 Jul 12 18:04:24 rivowoonkamer volumio[3092]: info: Adding Item to queue: qobuz://song/161150242 Jul 12 18:04:24 rivowoonkamer volumio[3092]: info: Using cached record of: qobuz://song/161150242 Jul 12 18:04:24 rivowoonkamer volumio[3092]: info: Adding Item to queue: qobuz://song/161150243 Jul 12 18:04:24 rivowoonkamer volumio[3092]: info: Using cached record of: qobuz://song/161150243 Jul 12 18:04:24 rivowoonkamer volumio[3092]: info: Adding Item to queue: qobuz://song/161150244 Jul 12 18:04:24 rivowoonkamer volumio[3092]: info: Using cached record of: qobuz://song/161150244 Jul 12 18:04:24 rivowoonkamer volumio[3092]: info: Adding Item to queue: qobuz://song/161150245 Jul 12 18:04:24 rivowoonkamer volumio[3092]: info: Using cached record of: qobuz://song/161150245 Jul 12 18:04:24 rivowoonkamer volumio[3092]: info: Adding Item to queue: qobuz://song/161150246 Jul 12 18:04:24 rivowoonkamer volumio[3092]: info: Using cached record of: qobuz://song/161150246 Jul 12 18:04:24 rivowoonkamer volumio[3092]: info: Adding Item to queue: qobuz://song/161150247 Jul 12 18:04:24 rivowoonkamer volumio[3092]: info: Using cached record of: qobuz://song/161150247 Jul 12 18:04:24 rivowoonkamer volumio[3092]: info: Adding Item to queue: qobuz://song/161150248 Jul 12 18:04:24 rivowoonkamer volumio[3092]: info: Using cached record of: qobuz://song/161150248 Jul 12 18:04:24 rivowoonkamer volumio[3092]: info: Adding Item to queue: qobuz://song/161150249 Jul 12 18:04:24 rivowoonkamer volumio[3092]: info: Using cached record of: qobuz://song/161150249 Jul 12 18:04:24 rivowoonkamer volumio[3092]: info: Adding Item to queue: qobuz://song/161150250 Jul 12 18:04:24 rivowoonkamer volumio[3092]: info: Using cached record of: qobuz://song/161150250 Jul 12 18:04:24 rivowoonkamer volumio[3092]: info: CoreCommandRouter::volumioPushQueue Jul 12 18:04:24 rivowoonkamer volumio[3092]: info: CorePlayQueue::saveQueue Jul 12 18:04:24 rivowoonkamer volumio[3092]: info: CoreStateMachine::updateTrackBlock Jul 12 18:04:24 rivowoonkamer volumio[3092]: info: CorePlayQueue::getTrackBlock Jul 12 18:04:24 rivowoonkamer volumio[3092]: info: CoreCommandRouter::volumioPlay Jul 12 18:04:24 rivowoonkamer volumio[3092]: info: CoreStateMachine::play index 0 Jul 12 18:04:24 rivowoonkamer volumio[3092]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 12 18:04:24 rivowoonkamer volumio[3092]: info: CoreStateMachine::stop Jul 12 18:04:24 rivowoonkamer volumio[3092]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 12 18:04:24 rivowoonkamer volumio[3092]: info: CoreStateMachine::play index undefined Jul 12 18:04:24 rivowoonkamer volumio[3092]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 12 18:04:24 rivowoonkamer volumio[3092]: info: CorePlayQueue::getTrack 0 Jul 12 18:04:24 rivowoonkamer volumio[3092]: info: CoreStateMachine::startPlaybackTimer Jul 12 18:04:24 rivowoonkamer volumio[3092]: info: CorePlayQueue::getTrack 0 Jul 12 18:04:24 rivowoonkamer volumio[3092]: info: [1720800264059] ControllerQobuz::clearAddPlayTrack Jul 12 18:04:24 rivowoonkamer volumio[3092]: verbose: ControllerMpd::sendMpdCommand stop Jul 12 18:04:24 rivowoonkamer volumio[3092]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jul 12 18:04:24 rivowoonkamer volumio[3092]: info: Updating RAAT Signal Path Jul 12 18:04:24 rivowoonkamer volumio[3092]: info: Jul 12 18:04:24 rivowoonkamer volumio[3092]: ---------------------------- MPD announces state update: player Jul 12 18:04:24 rivowoonkamer volumio[3092]: info: sendMpdCommand stop took 46 milliseconds Jul 12 18:04:24 rivowoonkamer volumio[3092]: info: ControllerMpd::getState Jul 12 18:04:24 rivowoonkamer volumio[3092]: verbose: ControllerMpd::sendMpdCommand status Jul 12 18:04:24 rivowoonkamer volumio[3092]: info: sendMpdCommand stop took 13 milliseconds Jul 12 18:04:24 rivowoonkamer volumio[3092]: verbose: ControllerMpd::sendMpdCommand clear Jul 12 18:04:24 rivowoonkamer volumio[3092]: info: Jul 12 18:04:24 rivowoonkamer volumio[3092]: ---------------------------- MPD announces system playlist update Jul 12 18:04:24 rivowoonkamer volumio[3092]: info: Ignoring MPD Status Update Jul 12 18:04:24 rivowoonkamer volumio[3092]: info: sendMpdCommand status took 17 milliseconds Jul 12 18:04:24 rivowoonkamer volumio[3092]: info: sendMpdCommand clear took 16 milliseconds Jul 12 18:04:24 rivowoonkamer volumio[3092]: verbose: ControllerMpd::parseState Jul 12 18:04:24 rivowoonkamer volumio[3092]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jul 12 18:04:24 rivowoonkamer volumio[3092]: verbose: ControllerMpd::sendMpdCommand load "http://127.0.0.1:3245?data=qobuz://song/161150239" Jul 12 18:04:24 rivowoonkamer volumio[3092]: STREAMING PROXY: Handling url /?data=qobuz://song/161150239 Jul 12 18:04:24 rivowoonkamer volumio[3092]: error: updateQueue error: null Jul 12 18:04:24 rivowoonkamer volumio[3092]: info: ------------------------------ 15ms Jul 12 18:04:24 rivowoonkamer volumio[3092]: info: sendMpdCommand playlistinfo took 12 milliseconds Jul 12 18:04:24 rivowoonkamer volumio[3092]: verbose: ControllerMpd::parseTrackInfo Jul 12 18:04:24 rivowoonkamer volumio[3092]: error: ControllerMpd::pushError: TypeError: Cannot read property 'split' of undefined Jul 12 18:04:24 rivowoonkamer volumio[3092]: info: ------------------------------ 35ms Jul 12 18:04:24 rivowoonkamer volumio[3092]: info: Executing endpoint getStreamUrlqobuz Jul 12 18:04:24 rivowoonkamer volumio[3092]: info: CoreCommandRouter::executeOnPlugin: qobuz , getStreamUrlAPI Jul 12 18:04:24 rivowoonkamer volumio[3092]: info: MCU Signalled Playback Inactive Jul 12 18:04:24 rivowoonkamer volumio[3092]: info: getStreamUrl took 235 milliseconds Jul 12 18:04:24 rivowoonkamer volumio[3092]: STREAMING PROXY: Got real url: http://streaming-qobuz-std.akamaized.net:80/file?uid=619379&eid=161150239&fmt=27&profile=raw&app_id=539451548&oid=37964950&olid=1&etsp=1720803864&hmac=gE-09D5_kBgnZ_3x4SM3GYo94uI Jul 12 18:04:24 rivowoonkamer volumio[3092]: STREAMING PROXY: Response: 200, length: 211850546 Jul 12 18:04:24 rivowoonkamer volumio[3092]: verbose: ControllerMpd::sendMpdCommand add "http://127.0.0.1:3245?data=qobuz://song/161150239" Jul 12 18:04:24 rivowoonkamer volumio[3092]: STREAMING PROXY: Client dropped request, destroying Jul 12 18:04:24 rivowoonkamer volumio[3092]: info: Jul 12 18:04:24 rivowoonkamer volumio[3092]: ---------------------------- MPD announces system playlist update Jul 12 18:04:24 rivowoonkamer volumio[3092]: info: Ignoring MPD Status Update Jul 12 18:04:24 rivowoonkamer volumio[3092]: info: sendMpdCommand add "http://127.0.0.1:3245?data=qobuz://song/161150239" took 2 milliseconds Jul 12 18:04:24 rivowoonkamer volumio[3092]: info: CoreStateMachine::setConsumeUpdateService mpd Jul 12 18:04:24 rivowoonkamer volumio[3092]: verbose: ControllerMpd::sendMpdCommand play Jul 12 18:04:24 rivowoonkamer volumio[3092]: STREAMING PROXY: Handling url /?data=qobuz://song/161150239 Jul 12 18:04:24 rivowoonkamer volumio[3092]: info: ------------------------------ 5ms Jul 12 18:04:24 rivowoonkamer volumio[3092]: info: sendMpdCommand play took 7 milliseconds Jul 12 18:04:24 rivowoonkamer volumio[3092]: info: Executing endpoint getStreamUrlqobuz Jul 12 18:04:24 rivowoonkamer volumio[3092]: info: CoreCommandRouter::executeOnPlugin: qobuz , getStreamUrlAPI Jul 12 18:04:24 rivowoonkamer volumio[3092]: info: getStreamUrl took 254 milliseconds Jul 12 18:04:24 rivowoonkamer volumio[3092]: STREAMING PROXY: Got real url: http://streaming-qobuz-std.akamaized.net:80/file?uid=619379&eid=161150239&fmt=27&profile=raw&app_id=539451548&oid=37964950&olid=1&etsp=1720803864&hmac=gE-09D5_kBgnZ_3x4SM3GYo94uI Jul 12 18:04:24 rivowoonkamer volumio[3092]: STREAMING PROXY: Response: 200, length: 211850546 Jul 12 18:04:24 rivowoonkamer volumio[3092]: info: Jul 12 18:04:24 rivowoonkamer volumio[3092]: ---------------------------- MPD announces state update: player Jul 12 18:04:24 rivowoonkamer volumio[3092]: info: ControllerMpd::getState Jul 12 18:04:24 rivowoonkamer volumio[3092]: verbose: ControllerMpd::sendMpdCommand status Jul 12 18:04:25 rivowoonkamer volumio[3092]: info: Jul 12 18:04:25 rivowoonkamer volumio[3092]: ---------------------------- MPD announces state update: player Jul 12 18:04:25 rivowoonkamer volumio[3092]: info: sendMpdCommand status took 536 milliseconds Jul 12 18:04:25 rivowoonkamer volumio[3092]: info: ControllerMpd::getState Jul 12 18:04:25 rivowoonkamer volumio[3092]: verbose: ControllerMpd::sendMpdCommand status Jul 12 18:04:25 rivowoonkamer volumio[3092]: verbose: ControllerMpd::parseState Jul 12 18:04:25 rivowoonkamer volumio[3092]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jul 12 18:04:25 rivowoonkamer volumio[3092]: info: sendMpdCommand status took 2 milliseconds Jul 12 18:04:25 rivowoonkamer volumio[3092]: info: sendMpdCommand playlistinfo took 3 milliseconds Jul 12 18:04:25 rivowoonkamer volumio[3092]: verbose: ControllerMpd::parseState Jul 12 18:04:25 rivowoonkamer volumio[3092]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jul 12 18:04:25 rivowoonkamer volumio[3092]: verbose: ControllerMpd::parseTrackInfo Jul 12 18:04:25 rivowoonkamer volumio[3092]: info: ControllerMpd::pushState Jul 12 18:04:25 rivowoonkamer volumio[3092]: info: CoreCommandRouter::servicePushState Jul 12 18:04:25 rivowoonkamer volumio[3092]: info: CorePlayQueue::getTrack 0 Jul 12 18:04:25 rivowoonkamer volumio[3092]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":349,"samplerate":"192 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"161150239","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=qobuz://song/161150239","trackType":"qobuz"} Jul 12 18:04:25 rivowoonkamer volumio[3092]: verbose: CURRENT POSITION 0 Jul 12 18:04:25 rivowoonkamer volumio[3092]: info: CoreStateMachine::syncState stateService play Jul 12 18:04:25 rivowoonkamer volumio[3092]: info: CoreStateMachine::syncState currentStatus stop Jul 12 18:04:25 rivowoonkamer volumio[3092]: info: ------------------------------ 548ms Jul 12 18:04:25 rivowoonkamer volumio[3092]: info: sendMpdCommand playlistinfo took 6 milliseconds Jul 12 18:04:25 rivowoonkamer volumio[3092]: verbose: ControllerMpd::parseTrackInfo Jul 12 18:04:25 rivowoonkamer volumio[3092]: info: ControllerMpd::pushState Jul 12 18:04:25 rivowoonkamer volumio[3092]: info: CoreCommandRouter::servicePushState Jul 12 18:04:25 rivowoonkamer volumio[3092]: info: CorePlayQueue::getTrack 0 Jul 12 18:04:25 rivowoonkamer volumio[3092]: verbose: STATE SERVICE {"status":"play","position":0,"seek":850,"duration":349,"samplerate":"192 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"4214 Kbps","isStreaming":false,"title":"161150239","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=qobuz://song/161150239","trackType":"qobuz"} Jul 12 18:04:25 rivowoonkamer volumio[3092]: verbose: CURRENT POSITION 0 Jul 12 18:04:25 rivowoonkamer volumio[3092]: info: CoreStateMachine::syncState stateService play Jul 12 18:04:25 rivowoonkamer volumio[3092]: info: CoreStateMachine::syncState currentStatus play Jul 12 18:04:25 rivowoonkamer volumio[3092]: info: Received an update from plugin. extracting info from payload Jul 12 18:04:25 rivowoonkamer volumio[3092]: info: CoreStateMachine::pushState Jul 12 18:04:25 rivowoonkamer volumio[3092]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 12 18:04:25 rivowoonkamer volumio[3092]: info: CoreCommandRouter::volumioPushState Jul 12 18:04:25 rivowoonkamer volumio[3092]: info: MRS: Pushing multiroomSync output update for this device Jul 12 18:04:25 rivowoonkamer volumio[3092]: info: MRS: Pushing multiroomSync output Jul 12 18:04:25 rivowoonkamer volumio[3092]: info: CoreStateMachine::pushState Jul 12 18:04:25 rivowoonkamer volumio[3092]: info: CoreCommandRouter::volumioPushState Jul 12 18:04:25 rivowoonkamer volumio[3092]: info: MRS: Pushing multiroomSync output update for this device Jul 12 18:04:25 rivowoonkamer volumio[3092]: info: MRS: Pushing multiroomSync output Jul 12 18:04:25 rivowoonkamer volumio[3092]: info: ------------------------------ 54ms Jul 12 18:04:25 rivowoonkamer volumio[3092]: info: Signalling Playback active due to playback status change Jul 12 18:04:25 rivowoonkamer volumio[3092]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jul 12 18:04:25 rivowoonkamer volumio[3092]: info: Updating RAAT Signal Path Jul 12 18:04:25 rivowoonkamer volumio[3092]: info: Signalling Playback active due to playback status change Jul 12 18:04:25 rivowoonkamer volumio[3092]: info: Updating RAAT Signal Path Jul 12 18:04:25 rivowoonkamer volumio[3092]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jul 12 18:04:25 rivowoonkamer volumio[3092]: info: MCU Signalled Playback Active Jul 12 18:04:28 rivowoonkamer volumio[3092]: error: Failed request for metavolumio API Jul 12 18:04:28 rivowoonkamer volumio[3092]: error: Failed request for metavolumio API Jul 12 18:04:37 rivowoonkamer volumio[3092]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jul 12 18:04:37 rivowoonkamer volumio[3092]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jul 12 18:04:37 rivowoonkamer volumio[3092]: info: Discovery: Getting this device information Jul 12 18:04:37 rivowoonkamer volumio[3092]: info: CoreCommandRouter::volumioGetState Jul 12 18:04:37 rivowoonkamer volumio[3092]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jul 12 18:04:37 rivowoonkamer volumio[3092]: verbose: New Socket.io Connection to 192.168.178.30 from 192.168.178.176 UA: unknown Engine version: 3 Transport: websocket Total Clients: 8 Jul 12 18:04:37 rivowoonkamer volumio[3092]: info: CoreCommandRouter::volumioGetState Jul 12 18:04:37 rivowoonkamer volumio[3092]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Jul 12 18:04:37 rivowoonkamer volumio[3092]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: Preload queue cleared Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: CoreCommandRouter::volumioReplaceandPlayItems Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: CoreStateMachine::ClearQueue Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: CoreStateMachine::stop Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: CoreStateMachine::stPlaybackTimer Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: CoreStateMachine::updateTrackBlock Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: CorePlayQueue::getTrackBlock Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: CoreStateMachine::pushState Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: CorePlayQueue::getTrack 0 Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: CoreCommandRouter::volumioPushState Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: MRS: Pushing multiroomSync output update for this device Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: MRS: Pushing multiroomSync output Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: CoreStateMachine::serviceStop Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: CorePlayQueue::getTrack 0 Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: CoreCommandRouter::serviceStop Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: [1720800295292] ControllerQobuz::stop Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: CoreStateMachine::setConsumeUpdateService mpd Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: ControllerMpd::stop Jul 12 18:04:55 rivowoonkamer volumio[3092]: verbose: ControllerMpd::sendMpdCommand stop Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: CorePlayQueue::clearPlayQueue Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: CorePlayQueue::saveQueue Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: CoreCommandRouter::volumioPushQueue Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: CoreStateMachine::addQueueItems Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: CorePlayQueue::addQueueItems Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: Preload queue cleared Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: Adding Item to queue: qobuz://song/161150239 Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: Using cached record of: qobuz://song/161150239 Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: Adding Item to queue: qobuz://song/161150240 Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: Using cached record of: qobuz://song/161150240 Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: Adding Item to queue: qobuz://song/161150241 Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: Using cached record of: qobuz://song/161150241 Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: Adding Item to queue: qobuz://song/161150242 Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: Using cached record of: qobuz://song/161150242 Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: Adding Item to queue: qobuz://song/161150243 Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: Using cached record of: qobuz://song/161150243 Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: Adding Item to queue: qobuz://song/161150244 Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: Using cached record of: qobuz://song/161150244 Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: Adding Item to queue: qobuz://song/161150245 Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: Using cached record of: qobuz://song/161150245 Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: Adding Item to queue: qobuz://song/161150246 Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: Using cached record of: qobuz://song/161150246 Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: Adding Item to queue: qobuz://song/161150247 Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: Using cached record of: qobuz://song/161150247 Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: Adding Item to queue: qobuz://song/161150248 Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: Using cached record of: qobuz://song/161150248 Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: Adding Item to queue: qobuz://song/161150249 Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: Using cached record of: qobuz://song/161150249 Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: Adding Item to queue: qobuz://song/161150250 Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: Using cached record of: qobuz://song/161150250 Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: CoreCommandRouter::volumioPushQueue Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: CorePlayQueue::saveQueue Jul 12 18:04:55 rivowoonkamer volumio[3092]: STREAMING PROXY: Client dropped request, destroying Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: CoreStateMachine::updateTrackBlock Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: CorePlayQueue::getTrackBlock Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: CoreCommandRouter::volumioPlay Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: CoreStateMachine::play index 4 Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: CoreStateMachine::stop Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: CoreStateMachine::play index undefined Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: CorePlayQueue::getTrack 4 Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: CoreStateMachine::startPlaybackTimer Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: CorePlayQueue::getTrack 4 Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: [1720800295322] ControllerQobuz::clearAddPlayTrack Jul 12 18:04:55 rivowoonkamer volumio[3092]: verbose: ControllerMpd::sendMpdCommand stop Jul 12 18:04:55 rivowoonkamer volumio[3092]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: Updating RAAT Signal Path Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: Jul 12 18:04:55 rivowoonkamer volumio[3092]: ---------------------------- MPD announces state update: player Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: sendMpdCommand stop took 40 milliseconds Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: ControllerMpd::getState Jul 12 18:04:55 rivowoonkamer volumio[3092]: verbose: ControllerMpd::sendMpdCommand status Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: sendMpdCommand stop took 11 milliseconds Jul 12 18:04:55 rivowoonkamer volumio[3092]: verbose: ControllerMpd::sendMpdCommand clear Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: Jul 12 18:04:55 rivowoonkamer volumio[3092]: ---------------------------- MPD announces system playlist update Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: Ignoring MPD Status Update Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: sendMpdCommand status took 10 milliseconds Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: sendMpdCommand clear took 9 milliseconds Jul 12 18:04:55 rivowoonkamer volumio[3092]: verbose: ControllerMpd::parseState Jul 12 18:04:55 rivowoonkamer volumio[3092]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jul 12 18:04:55 rivowoonkamer volumio[3092]: verbose: ControllerMpd::sendMpdCommand load "http://127.0.0.1:3245?data=qobuz://song/161150243" Jul 12 18:04:55 rivowoonkamer volumio[3092]: error: updateQueue error: null Jul 12 18:04:55 rivowoonkamer volumio[3092]: STREAMING PROXY: Handling url /?data=qobuz://song/161150243 Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: ------------------------------ 11ms Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: sendMpdCommand playlistinfo took 9 milliseconds Jul 12 18:04:55 rivowoonkamer volumio[3092]: verbose: ControllerMpd::parseTrackInfo Jul 12 18:04:55 rivowoonkamer volumio[3092]: error: ControllerMpd::pushError: TypeError: Cannot read property 'split' of undefined Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: ------------------------------ 24ms Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: Executing endpoint getStreamUrlqobuz Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: CoreCommandRouter::executeOnPlugin: qobuz , getStreamUrlAPI Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: MCU Signalled Playback Inactive Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: getStreamUrl took 189 milliseconds Jul 12 18:04:55 rivowoonkamer volumio[3092]: STREAMING PROXY: Got real url: http://streaming-qobuz-std.akamaized.net:80/file?uid=619379&eid=161150243&fmt=27&profile=raw&app_id=539451548&oid=37964950&olid=1&etsp=1720803895&hmac=Xa3NgiCI3shKjwKvW2QRu-xoxXY Jul 12 18:04:55 rivowoonkamer volumio[3092]: STREAMING PROXY: Response: 200, length: 333414878 Jul 12 18:04:55 rivowoonkamer volumio[3092]: STREAMING PROXY: Client dropped request, destroying Jul 12 18:04:55 rivowoonkamer volumio[3092]: verbose: ControllerMpd::sendMpdCommand add "http://127.0.0.1:3245?data=qobuz://song/161150243" Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: Jul 12 18:04:55 rivowoonkamer volumio[3092]: ---------------------------- MPD announces system playlist update Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: Ignoring MPD Status Update Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: sendMpdCommand add "http://127.0.0.1:3245?data=qobuz://song/161150243" took 2 milliseconds Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: CoreStateMachine::setConsumeUpdateService mpd Jul 12 18:04:55 rivowoonkamer volumio[3092]: verbose: ControllerMpd::sendMpdCommand play Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: ------------------------------ 3ms Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: sendMpdCommand play took 3 milliseconds Jul 12 18:04:55 rivowoonkamer volumio[3092]: STREAMING PROXY: Handling url /?data=qobuz://song/161150243 Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: Executing endpoint getStreamUrlqobuz Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: CoreCommandRouter::executeOnPlugin: qobuz , getStreamUrlAPI Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: getStreamUrl took 201 milliseconds Jul 12 18:04:55 rivowoonkamer volumio[3092]: STREAMING PROXY: Got real url: http://streaming-qobuz-std.akamaized.net:80/file?uid=619379&eid=161150243&fmt=27&profile=raw&app_id=539451548&oid=37964950&olid=1&etsp=1720803895&hmac=Xa3NgiCI3shKjwKvW2QRu-xoxXY Jul 12 18:04:55 rivowoonkamer volumio[3092]: STREAMING PROXY: Response: 200, length: 333414878 Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: Jul 12 18:04:55 rivowoonkamer volumio[3092]: ---------------------------- MPD announces state update: player Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: ControllerMpd::getState Jul 12 18:04:55 rivowoonkamer volumio[3092]: verbose: ControllerMpd::sendMpdCommand status Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: Jul 12 18:04:55 rivowoonkamer volumio[3092]: ---------------------------- MPD announces state update: player Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: sendMpdCommand status took 18 milliseconds Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: ControllerMpd::getState Jul 12 18:04:55 rivowoonkamer volumio[3092]: verbose: ControllerMpd::sendMpdCommand status Jul 12 18:04:55 rivowoonkamer volumio[3092]: verbose: ControllerMpd::parseState Jul 12 18:04:55 rivowoonkamer volumio[3092]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: sendMpdCommand status took 3 milliseconds Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: sendMpdCommand playlistinfo took 2 milliseconds Jul 12 18:04:55 rivowoonkamer volumio[3092]: verbose: ControllerMpd::parseState Jul 12 18:04:55 rivowoonkamer volumio[3092]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jul 12 18:04:55 rivowoonkamer volumio[3092]: verbose: ControllerMpd::parseTrackInfo Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: ControllerMpd::pushState Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: CoreCommandRouter::servicePushState Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: CorePlayQueue::getTrack 4 Jul 12 18:04:55 rivowoonkamer volumio[3092]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":492,"samplerate":"192 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"161150243","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=qobuz://song/161150243","trackType":"qobuz"} Jul 12 18:04:55 rivowoonkamer volumio[3092]: verbose: CURRENT POSITION 4 Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: CoreStateMachine::syncState stateService play Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: CoreStateMachine::syncState currentStatus stop Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: ------------------------------ 29ms Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: sendMpdCommand playlistinfo took 4 milliseconds Jul 12 18:04:55 rivowoonkamer volumio[3092]: verbose: ControllerMpd::parseTrackInfo Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: ControllerMpd::pushState Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: CoreCommandRouter::servicePushState Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: CorePlayQueue::getTrack 4 Jul 12 18:04:55 rivowoonkamer volumio[3092]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":492,"samplerate":"192 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"161150243","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=qobuz://song/161150243","trackType":"qobuz"} Jul 12 18:04:55 rivowoonkamer volumio[3092]: verbose: CURRENT POSITION 4 Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: CoreStateMachine::syncState stateService play Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: CoreStateMachine::syncState currentStatus play Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: Received an update from plugin. extracting info from payload Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: CoreStateMachine::pushState Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: CoreCommandRouter::volumioPushState Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: MRS: Pushing multiroomSync output update for this device Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: MRS: Pushing multiroomSync output Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: CoreStateMachine::pushState Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: CoreCommandRouter::volumioPushState Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: MRS: Pushing multiroomSync output update for this device Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: MRS: Pushing multiroomSync output Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: ------------------------------ 43ms Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: Signalling Playback active due to playback status change Jul 12 18:04:55 rivowoonkamer volumio[3092]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: Updating RAAT Signal Path Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: Signalling Playback active due to playback status change Jul 12 18:04:55 rivowoonkamer volumio[3092]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jul 12 18:04:55 rivowoonkamer volumio[3092]: info: Updating RAAT Signal Path Jul 12 18:04:56 rivowoonkamer volumio[3092]: info: MCU Signalled Playback Active Jul 12 18:05:01 rivowoonkamer volumio[3092]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Jul 12 18:05:01 rivowoonkamer volumio[3092]: info: Preload queue cleared Jul 12 18:05:02 rivowoonkamer volumio[3092]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Jul 12 18:05:02 rivowoonkamer volumio[3092]: info: Preload queue cleared Jul 12 18:05:04 rivowoonkamer volumio[3092]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Jul 12 18:05:04 rivowoonkamer volumio[3092]: info: Preload queue cleared Jul 12 18:05:05 rivowoonkamer volumio[3092]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Jul 12 18:05:05 rivowoonkamer volumio[3092]: info: Preload queue cleared Jul 12 18:05:08 rivowoonkamer volumio[3092]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Jul 12 18:05:13 rivowoonkamer volumio[3092]: info: Preload queue cleared Jul 12 18:05:18 rivowoonkamer volumio[3092]: Searching plugin music_service/upnp_browser Jul 12 18:05:18 rivowoonkamer volumio[3092]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , search Jul 12 18:05:18 rivowoonkamer volumio[3092]: info: All search sources collected, pushing search results Jul 12 18:05:20 rivowoonkamer volumio[3092]: Searching plugin music_service/upnp_browser Jul 12 18:05:20 rivowoonkamer volumio[3092]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , search Jul 12 18:05:20 rivowoonkamer volumio[3092]: info: All search sources collected, pushing search results Jul 12 18:05:33 rivowoonkamer volumio[3092]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Jul 12 18:05:33 rivowoonkamer volumio[3092]: info: Preload queue cleared Jul 12 18:05:44 rivowoonkamer ntpd[3264]: 37.1.205.111 local addr 192.168.178.30 -> Jul 12 18:05:45 rivowoonkamer volumio[3092]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Jul 12 18:05:45 rivowoonkamer volumio[3092]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jul 12 18:05:45 rivowoonkamer volumio[3092]: TypeError: Cannot read property 'length' of undefined Jul 12 18:05:45 rivowoonkamer volumio[3092]: at /volumio/app/plugins/music_service/upnp_browser/index.js:341:25 Jul 12 18:05:45 rivowoonkamer volumio[3092]: at /volumio/app/plugins/music_service/upnp_browser/dlna-browser.js:131:13 Jul 12 18:05:45 rivowoonkamer volumio[3092]: at Parser. (/volumio/node_modules/xml2js/lib/parser.js:304:18) Jul 12 18:05:45 rivowoonkamer volumio[3092]: at Parser.emit (events.js:400:28) Jul 12 18:05:45 rivowoonkamer volumio[3092]: at SAXParser.onclosetag (/volumio/node_modules/xml2js/lib/parser.js:262:26) Jul 12 18:05:45 rivowoonkamer volumio[3092]: at emit (/volumio/node_modules/sax/lib/sax.js:624:35) Jul 12 18:05:45 rivowoonkamer volumio[3092]: at emitNode (/volumio/node_modules/sax/lib/sax.js:629:5) Jul 12 18:05:45 rivowoonkamer volumio[3092]: at closeTag (/volumio/node_modules/sax/lib/sax.js:889:7) Jul 12 18:05:45 rivowoonkamer volumio[3092]: at SAXParser.write (/volumio/node_modules/sax/lib/sax.js:1436:13) Jul 12 18:05:45 rivowoonkamer volumio[3092]: at Parser.exports.Parser.Parser.parseString (/volumio/node_modules/xml2js/lib/parser.js:323:31) Jul 12 18:05:45 rivowoonkamer volumio[3092]: at Parser.parseString (/volumio/node_modules/xml2js/lib/parser.js:5:59) Jul 12 18:05:45 rivowoonkamer volumio[3092]: at Object.exports.parseString (/volumio/node_modules/xml2js/lib/parser.js:369:19) Jul 12 18:05:45 rivowoonkamer volumio[3092]: at IncomingMessage. (/volumio/app/plugins/music_service/upnp_browser/dlna-browser.js:92:15) Jul 12 18:05:45 rivowoonkamer volumio[3092]: at IncomingMessage.emit (events.js:412:35) Jul 12 18:05:45 rivowoonkamer volumio[3092]: at endReadableNT (internal/streams/readable.js:1333:12) Jul 12 18:05:45 rivowoonkamer volumio[3092]: at processTicksAndRejections (internal/process/task_queues.js:82:21) Jul 12 18:05:45 rivowoonkamer volumio[3092]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jul 12 18:05:46 rivowoonkamer sudo[5070]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-07-12 18:04 Jul 12 18:05:46 rivowoonkamer sudo[5070]: 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="4b122b2365bb8c09786cd63b50d1ea6db780eb4e" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="49f98390f2d84c6549f33dc85b694fbd99e4c720" VOLUMIO_ARCH="armv7" VOLUMIO_VARIANT="rivo" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue 04 Jun 2024 09:27:25 PM CEST" VOLUMIO_VERSION="3.703" VOLUMIO_HARDWARE="mp1" VOLUMIO_DEVICENAME="Volumio MP1" VOLUMIO_VENDOR_MODEL="Volumio Rivo" VOLUMIO_VENDOR="Volumio" VOLUMIO_MODEL="Rivo" VOLUMIO_HASH="891b8adfc94c7cc44424972b60e8e09c"