May 31 23:23:01 bedroom volumio[1352]: info: Getting current volume May 31 23:23:01 bedroom volumio[1352]: info: CoreCommandRouter::volumioGetState May 31 23:23:01 bedroom volumio[1352]: info: Current volume is 100 May 31 23:23:01 bedroom volumio[1352]: info: Increasing volume by 1: setting volume to 100 May 31 23:23:01 bedroom volumio[1352]: info: Sending REST command to localhost:3000/api/v1/commands/?cmd=volume&volume=100 May 31 23:23:01 bedroom volumio[1352]: info: May 31 23:23:01 bedroom volumio[1352]: ---------------------------- Client requests Volume 100 May 31 23:23:01 bedroom volumio[1352]: info: VolumeController::SetAlsaVolume100 May 31 23:23:01 bedroom volumio[1352]: info: CoreStateMachine::pushState May 31 23:23:01 bedroom volumio[1352]: info: CoreCommandRouter::volumioPushState May 31 23:23:01 bedroom volumio[1352]: info: MRS: Pushing multiroomSync output update for this device May 31 23:23:01 bedroom volumio[1352]: info: MRS: Pushing multiroomSync output May 31 23:23:01 bedroom volumio[1352]: info: CoreCommandRouter::volumioGetState May 31 23:23:01 bedroom volumio5-onboarding[2136]: time=2026-05-31T23:23:01.260+02:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%01,192.168.188.115:49702 @ 0x1cdf500" state=STATUS_PAUSED positionMs=17773 volume=100 May 31 23:23:01 bedroom volumio5-onboarding[2136]: time=2026-05-31T23:23:01.261+02:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.188.115:49702 @ 0x1c9a2d0" state=STATUS_PAUSED positionMs=17773 volume=100 May 31 23:23:01 bedroom volumio5-onboarding[2136]: time=2026-05-31T23:23:01.261+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%01,192.168.188.115:49702 @ 0x1cdf500" id=qobuz://song/104009422 title="Hope Has a Place" May 31 23:23:01 bedroom volumio[1352]: info: Received response: {"time":1780262581248,"response":"volume Success"} May 31 23:23:01 bedroom volumio[1352]: info: Volume set to 100 May 31 23:23:01 bedroom volumio5-onboarding[2136]: time=2026-05-31T23:23:01.264+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.188.115:49702 @ 0x1c9a2d0" id=qobuz://song/104009422 title="Hope Has a Place" May 31 23:23:07 bedroom volumio[1352]: info: Getting current volume May 31 23:23:07 bedroom volumio[1352]: info: CoreCommandRouter::volumioGetState May 31 23:23:07 bedroom volumio[1352]: info: Current volume is 100 May 31 23:23:07 bedroom volumio[1352]: info: Increasing volume by 1: setting volume to 100 May 31 23:23:07 bedroom volumio[1352]: info: Sending REST command to localhost:3000/api/v1/commands/?cmd=volume&volume=100 May 31 23:23:07 bedroom volumio[1352]: info: May 31 23:23:07 bedroom volumio[1352]: ---------------------------- Client requests Volume 100 May 31 23:23:07 bedroom volumio[1352]: info: VolumeController::SetAlsaVolume100 May 31 23:23:07 bedroom volumio[1352]: info: CoreStateMachine::pushState May 31 23:23:07 bedroom volumio[1352]: info: CoreCommandRouter::volumioPushState May 31 23:23:07 bedroom volumio[1352]: info: MRS: Pushing multiroomSync output update for this device May 31 23:23:07 bedroom volumio[1352]: info: MRS: Pushing multiroomSync output May 31 23:23:07 bedroom volumio[1352]: info: CoreCommandRouter::volumioGetState May 31 23:23:07 bedroom volumio5-onboarding[2136]: time=2026-05-31T23:23:07.284+02:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%01,192.168.188.115:49702 @ 0x1cdf500" state=STATUS_PAUSED positionMs=17773 volume=100 May 31 23:23:07 bedroom volumio5-onboarding[2136]: time=2026-05-31T23:23:07.285+02:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.188.115:49702 @ 0x1c9a2d0" state=STATUS_PAUSED positionMs=17773 volume=100 May 31 23:23:07 bedroom volumio5-onboarding[2136]: time=2026-05-31T23:23:07.288+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%01,192.168.188.115:49702 @ 0x1cdf500" id=qobuz://song/104009422 title="Hope Has a Place" May 31 23:23:07 bedroom volumio5-onboarding[2136]: time=2026-05-31T23:23:07.288+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.188.115:49702 @ 0x1c9a2d0" id=qobuz://song/104009422 title="Hope Has a Place" May 31 23:23:07 bedroom volumio[1352]: info: Received response: {"time":1780262587271,"response":"volume Success"} May 31 23:23:07 bedroom volumio[1352]: info: Volume set to 100 May 31 23:23:13 bedroom volumio[1352]: info: Getting current volume May 31 23:23:13 bedroom volumio[1352]: info: CoreCommandRouter::volumioGetState May 31 23:23:13 bedroom volumio[1352]: info: Current volume is 100 May 31 23:23:13 bedroom volumio[1352]: info: Increasing volume by 1: setting volume to 100 May 31 23:23:13 bedroom volumio[1352]: info: Sending REST command to localhost:3000/api/v1/commands/?cmd=volume&volume=100 May 31 23:23:13 bedroom volumio[1352]: info: May 31 23:23:13 bedroom volumio[1352]: ---------------------------- Client requests Volume 100 May 31 23:23:13 bedroom volumio[1352]: info: VolumeController::SetAlsaVolume100 May 31 23:23:13 bedroom volumio[1352]: info: CoreStateMachine::pushState May 31 23:23:13 bedroom volumio[1352]: info: CoreCommandRouter::volumioPushState May 31 23:23:13 bedroom volumio[1352]: info: MRS: Pushing multiroomSync output update for this device May 31 23:23:13 bedroom volumio[1352]: info: MRS: Pushing multiroomSync output May 31 23:23:13 bedroom volumio[1352]: info: CoreCommandRouter::volumioGetState May 31 23:23:13 bedroom volumio5-onboarding[2136]: time=2026-05-31T23:23:13.310+02:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%01,192.168.188.115:49702 @ 0x1cdf500" state=STATUS_PAUSED positionMs=17773 volume=100 May 31 23:23:13 bedroom volumio5-onboarding[2136]: time=2026-05-31T23:23:13.310+02:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.188.115:49702 @ 0x1c9a2d0" state=STATUS_PAUSED positionMs=17773 volume=100 May 31 23:23:13 bedroom volumio5-onboarding[2136]: time=2026-05-31T23:23:13.310+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%01,192.168.188.115:49702 @ 0x1cdf500" id=qobuz://song/104009422 title="Hope Has a Place" May 31 23:23:13 bedroom volumio5-onboarding[2136]: time=2026-05-31T23:23:13.310+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.188.115:49702 @ 0x1c9a2d0" id=qobuz://song/104009422 title="Hope Has a Place" May 31 23:23:13 bedroom volumio[1352]: info: Received response: {"time":1780262593298,"response":"volume Success"} May 31 23:23:13 bedroom volumio[1352]: info: Volume set to 100 May 31 23:23:19 bedroom volumio[1352]: info: Getting current volume May 31 23:23:19 bedroom volumio[1352]: info: CoreCommandRouter::volumioGetState May 31 23:23:19 bedroom volumio[1352]: info: Current volume is 100 May 31 23:23:19 bedroom volumio[1352]: info: Increasing volume by 1: setting volume to 100 May 31 23:23:19 bedroom volumio[1352]: info: Sending REST command to localhost:3000/api/v1/commands/?cmd=volume&volume=100 May 31 23:23:19 bedroom volumio[1352]: info: May 31 23:23:19 bedroom volumio[1352]: ---------------------------- Client requests Volume 100 May 31 23:23:19 bedroom volumio[1352]: info: VolumeController::SetAlsaVolume100 May 31 23:23:19 bedroom volumio[1352]: info: CoreStateMachine::pushState May 31 23:23:19 bedroom volumio[1352]: info: CoreCommandRouter::volumioPushState May 31 23:23:19 bedroom volumio[1352]: info: MRS: Pushing multiroomSync output update for this device May 31 23:23:19 bedroom volumio[1352]: info: MRS: Pushing multiroomSync output May 31 23:23:19 bedroom volumio[1352]: info: CoreCommandRouter::volumioGetState May 31 23:23:19 bedroom volumio5-onboarding[2136]: time=2026-05-31T23:23:19.332+02:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%01,192.168.188.115:49702 @ 0x1cdf500" state=STATUS_PAUSED positionMs=17773 volume=100 May 31 23:23:19 bedroom volumio5-onboarding[2136]: time=2026-05-31T23:23:19.332+02:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.188.115:49702 @ 0x1c9a2d0" state=STATUS_PAUSED positionMs=17773 volume=100 May 31 23:23:19 bedroom volumio5-onboarding[2136]: time=2026-05-31T23:23:19.333+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%01,192.168.188.115:49702 @ 0x1cdf500" id=qobuz://song/104009422 title="Hope Has a Place" May 31 23:23:19 bedroom volumio5-onboarding[2136]: time=2026-05-31T23:23:19.333+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.188.115:49702 @ 0x1c9a2d0" id=qobuz://song/104009422 title="Hope Has a Place" May 31 23:23:19 bedroom volumio[1352]: info: Received response: {"time":1780262599321,"response":"volume Success"} May 31 23:23:19 bedroom volumio[1352]: info: Volume set to 100 May 31 23:23:25 bedroom volumio[1352]: info: SleepWakePlugin - Volume increase complete. May 31 23:23:25 bedroom volumio[1352]: info: SleepWakePlugin - onStart May 31 23:23:25 bedroom volumio[1352]: info: SleepWakePlugin - Sleep scheduled in -2676145340 milliseconds May 31 23:23:25 bedroom volumio[1352]: info: SleepWakePlugin - Wake scheduled in -2644105340 milliseconds May 31 23:23:25 bedroom volumio[1352]: info: SleepWakePlugin - Sleep timer triggered May 31 23:23:25 bedroom volumio[1352]: info: SleepWakePlugin - Starting fade out volume May 31 23:23:25 bedroom volumio[1352]: info: Getting current volume May 31 23:23:25 bedroom volumio[1352]: info: SleepWakePlugin - Wake timer triggered May 31 23:23:25 bedroom volumio[1352]: info: SleepWakePlugin - Interrupting sleep to start wake-up. May 31 23:23:25 bedroom volumio[1352]: info: SleepWakePlugin - Starting playlist May 31 23:23:25 bedroom volumio[1352]: info: Sending REST command to localhost:3000/api/v1/commands/?cmd=volume&volume=20 May 31 23:23:25 bedroom volumio[1352]: info: CoreCommandRouter::volumioGetState May 31 23:23:25 bedroom volumio[1352]: info: Current volume is 100 May 31 23:23:25 bedroom volumio[1352]: info: Decreasing volume by 1: setting volume to 99 May 31 23:23:25 bedroom volumio[1352]: info: Sending REST command to localhost:3000/api/v1/commands/?cmd=volume&volume=99 May 31 23:23:25 bedroom volumio[1352]: info: May 31 23:23:25 bedroom volumio[1352]: ---------------------------- Client requests Volume 20 May 31 23:23:25 bedroom volumio[1352]: info: VolumeController::SetAlsaVolume20 May 31 23:23:25 bedroom volumio[1352]: info: CoreStateMachine::pushState May 31 23:23:25 bedroom volumio[1352]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 31 23:23:25 bedroom volumio[1352]: info: CoreCommandRouter::volumioPushState May 31 23:23:25 bedroom volumio[1352]: info: MRS: Pushing multiroomSync output update for this device May 31 23:23:25 bedroom volumio[1352]: info: MRS: Pushing multiroomSync output May 31 23:23:25 bedroom volumio[1352]: info: CoreCommandRouter::volumioGetState May 31 23:23:25 bedroom volumio5-onboarding[2136]: time=2026-05-31T23:23:25.366+02:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%01,192.168.188.115:49702 @ 0x1cdf500" state=STATUS_PAUSED positionMs=17773 volume=20 May 31 23:23:25 bedroom volumio5-onboarding[2136]: time=2026-05-31T23:23:25.366+02:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.188.115:49702 @ 0x1c9a2d0" state=STATUS_PAUSED positionMs=17773 volume=20 May 31 23:23:25 bedroom volumio5-onboarding[2136]: time=2026-05-31T23:23:25.366+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%01,192.168.188.115:49702 @ 0x1cdf500" id=qobuz://song/104009422 title="Hope Has a Place" May 31 23:23:25 bedroom volumio5-onboarding[2136]: time=2026-05-31T23:23:25.366+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.188.115:49702 @ 0x1c9a2d0" id=qobuz://song/104009422 title="Hope Has a Place" May 31 23:23:25 bedroom volumio[1352]: info: Received response: {"time":1780262605349,"response":"volume Success"} May 31 23:23:25 bedroom volumio[1352]: info: Initial volume set to 20 May 31 23:23:25 bedroom volumio[1352]: info: Sending REST command to localhost:3000/api/v1/commands/?cmd=playplaylist&name=M May 31 23:23:25 bedroom volumio[1352]: info: May 31 23:23:25 bedroom volumio[1352]: ---------------------------- Client requests Volumio Play Playlist M May 31 23:23:25 bedroom volumio[1352]: info: Play playlist M May 31 23:23:25 bedroom volumio[1352]: info: May 31 23:23:25 bedroom volumio[1352]: ---------------------------- Client requests Volume 99 May 31 23:23:25 bedroom volumio[1352]: info: VolumeController::SetAlsaVolume99 May 31 23:23:25 bedroom volumio[1352]: info: CoreStateMachine::pushState May 31 23:23:25 bedroom volumio[1352]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 31 23:23:25 bedroom volumio[1352]: info: CoreCommandRouter::volumioPushState May 31 23:23:25 bedroom volumio[1352]: info: MRS: Pushing multiroomSync output update for this device May 31 23:23:25 bedroom volumio[1352]: info: MRS: Pushing multiroomSync output May 31 23:23:25 bedroom volumio[1352]: info: CoreCommandRouter::volumioGetState May 31 23:23:25 bedroom volumio5-onboarding[2136]: time=2026-05-31T23:23:25.388+02:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%01,192.168.188.115:49702 @ 0x1cdf500" state=STATUS_PAUSED positionMs=17773 volume=99 May 31 23:23:25 bedroom volumio5-onboarding[2136]: time=2026-05-31T23:23:25.388+02:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.188.115:49702 @ 0x1c9a2d0" state=STATUS_PAUSED positionMs=17773 volume=99 May 31 23:23:25 bedroom volumio5-onboarding[2136]: time=2026-05-31T23:23:25.389+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%01,192.168.188.115:49702 @ 0x1cdf500" id=qobuz://song/104009422 title="Hope Has a Place" May 31 23:23:25 bedroom volumio5-onboarding[2136]: time=2026-05-31T23:23:25.389+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.188.115:49702 @ 0x1c9a2d0" id=qobuz://song/104009422 title="Hope Has a Place" May 31 23:23:25 bedroom volumio[1352]: info: Received response: {"time":1780262605376,"response":"volume Success"} May 31 23:23:25 bedroom volumio[1352]: info: Volume set to 99 May 31 23:23:25 bedroom volumio[1352]: info: CoreCommandRouter::volumioClearQueue May 31 23:23:25 bedroom volumio[1352]: info: CoreStateMachine::ClearQueue May 31 23:23:25 bedroom volumio[1352]: info: CoreStateMachine::stop May 31 23:23:25 bedroom volumio[1352]: info: CoreStateMachine::setConsumeUpdateService undefined May 31 23:23:25 bedroom volumio[1352]: info: CoreStateMachine::updateTrackBlock May 31 23:23:25 bedroom volumio[1352]: info: CorePlayQueue::getTrackBlock May 31 23:23:25 bedroom volumio[1352]: info: CoreStateMachine::stPlaybackTimer May 31 23:23:25 bedroom volumio[1352]: info: CoreStateMachine::pushState May 31 23:23:25 bedroom volumio[1352]: info: CorePlayQueue::getTrack 0 May 31 23:23:25 bedroom volumio[1352]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 31 23:23:25 bedroom volumio[1352]: info: CoreCommandRouter::volumioPushState May 31 23:23:25 bedroom volumio[1352]: info: MRS: Pushing multiroomSync output update for this device May 31 23:23:25 bedroom volumio[1352]: info: MRS: Pushing multiroomSync output May 31 23:23:25 bedroom volumio[1352]: info: CoreCommandRouter::volumioGetState May 31 23:23:25 bedroom volumio[1352]: info: CorePlayQueue::getTrack 0 May 31 23:23:25 bedroom volumio[1352]: info: CoreStateMachine::serviceStop May 31 23:23:25 bedroom volumio[1352]: info: CorePlayQueue::getTrack 0 May 31 23:23:25 bedroom volumio[1352]: info: CoreCommandRouter::serviceStop May 31 23:23:25 bedroom volumio[1352]: info: [1780262605401] ControllerQobuz::stop May 31 23:23:25 bedroom volumio[1352]: info: CoreStateMachine::setConsumeUpdateService mpd May 31 23:23:25 bedroom volumio[1352]: info: ControllerMpd::stop May 31 23:23:25 bedroom volumio[1352]: verbose: ControllerMpd::sendMpdCommand stop May 31 23:23:25 bedroom volumio[1352]: info: CorePlayQueue::clearPlayQueue May 31 23:23:25 bedroom volumio[1352]: info: CorePlayQueue::saveQueue May 31 23:23:25 bedroom volumio[1352]: info: CoreCommandRouter::volumioPushState May 31 23:23:25 bedroom volumio[1352]: info: MRS: Pushing multiroomSync output update for this device May 31 23:23:25 bedroom volumio[1352]: info: MRS: Pushing multiroomSync output May 31 23:23:25 bedroom volumio[1352]: info: CoreCommandRouter::volumioGetState May 31 23:23:25 bedroom volumio[1352]: info: CoreCommandRouter::volumioPushQueue May 31 23:23:25 bedroom volumio[1352]: info: CoreCommandRouter::volumioAddQueueItems May 31 23:23:25 bedroom volumio[1352]: info: CoreStateMachine::addQueueItems May 31 23:23:25 bedroom volumio[1352]: info: CorePlayQueue::addQueueItems May 31 23:23:25 bedroom volumio[1352]: info: Preload queue cleared May 31 23:23:25 bedroom volumio[1352]: info: Adding Item to queue: qobuz://playlist/44959050 May 31 23:23:25 bedroom volumio[1352]: info: Using cached record of: qobuz://playlist/44959050 May 31 23:23:25 bedroom volumio5-onboarding[2136]: time=2026-05-31T23:23:25.417+02:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%01,192.168.188.115:49702 @ 0x1cdf500" state=STATUS_STOPPED positionMs=0 volume=99 May 31 23:23:25 bedroom volumio5-onboarding[2136]: time=2026-05-31T23:23:25.417+02:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.188.115:49702 @ 0x1c9a2d0" state=STATUS_STOPPED positionMs=0 volume=99 May 31 23:23:25 bedroom volumio5-onboarding[2136]: time=2026-05-31T23:23:25.417+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%01,192.168.188.115:49702 @ 0x1cdf500" id=qobuz://song/104009422 title="Hope Has a Place" May 31 23:23:25 bedroom volumio5-onboarding[2136]: time=2026-05-31T23:23:25.417+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.188.115:49702 @ 0x1c9a2d0" id=qobuz://song/104009422 title="Hope Has a Place" May 31 23:23:25 bedroom volumio5-onboarding[2136]: time=2026-05-31T23:23:25.418+02:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%01,192.168.188.115:49702 @ 0x1cdf500" state=STATUS_STOPPED positionMs=0 volume=99 May 31 23:23:25 bedroom volumio5-onboarding[2136]: time=2026-05-31T23:23:25.418+02:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.188.115:49702 @ 0x1c9a2d0" state=STATUS_STOPPED positionMs=0 volume=99 May 31 23:23:25 bedroom volumio5-onboarding[2136]: time=2026-05-31T23:23:25.418+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%01,192.168.188.115:49702 @ 0x1cdf500" id= title= May 31 23:23:25 bedroom volumio5-onboarding[2136]: time=2026-05-31T23:23:25.418+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.188.115:49702 @ 0x1c9a2d0" id= title= May 31 23:23:25 bedroom volumio[1352]: info: CoreCommandRouter::volumioPushQueue May 31 23:23:25 bedroom volumio[1352]: info: CorePlayQueue::saveQueue May 31 23:23:25 bedroom volumio[1352]: info: CoreStateMachine::updateTrackBlock May 31 23:23:25 bedroom volumio[1352]: info: CorePlayQueue::getTrackBlock May 31 23:23:25 bedroom volumio[1352]: info: CoreCommandRouter::volumioGetState May 31 23:23:25 bedroom volumio[1352]: info: CoreCommandRouter::executeOnPlugin: play , [object Object] May 31 23:23:25 bedroom volumio[1352]: info: CoreCommandRouter::volumioPlay May 31 23:23:25 bedroom volumio[1352]: info: CoreStateMachine::play index 0 May 31 23:23:25 bedroom volumio[1352]: info: CoreStateMachine::setConsumeUpdateService undefined May 31 23:23:25 bedroom volumio[1352]: info: CoreStateMachine::stop May 31 23:23:25 bedroom volumio[1352]: info: CoreStateMachine::setConsumeUpdateService undefined May 31 23:23:25 bedroom volumio[1352]: info: CoreStateMachine::play index undefined May 31 23:23:25 bedroom volumio[1352]: info: CoreStateMachine::setConsumeUpdateService undefined May 31 23:23:25 bedroom volumio[1352]: info: CorePlayQueue::getTrack 0 May 31 23:23:25 bedroom volumio[1352]: info: CoreStateMachine::startPlaybackTimer May 31 23:23:25 bedroom volumio[1352]: info: CorePlayQueue::getTrack 0 May 31 23:23:25 bedroom volumio[1352]: info: [1780262605424] ControllerQobuz::clearAddPlayTrack May 31 23:23:25 bedroom volumio[1352]: info: May 31 23:23:25 bedroom volumio[1352]: ---------------------------- MPD announces state update: player May 31 23:23:25 bedroom volumio[1352]: info: sendMpdCommand stop took 33 milliseconds May 31 23:23:25 bedroom volumio[1352]: info: ControllerMpd::getState May 31 23:23:25 bedroom volumio[1352]: verbose: ControllerMpd::sendMpdCommand status May 31 23:23:25 bedroom volumio[1352]: info: Received response: {"time":1780262605374,"response":"playplaylist Success"} May 31 23:23:25 bedroom volumio[1352]: info: Playlist "M" started. May 31 23:23:25 bedroom volumio[1352]: info: Getting current volume May 31 23:23:25 bedroom volumio[1352]: info: sendMpdCommand status took 1 milliseconds May 31 23:23:25 bedroom volumio[1352]: verbose: ControllerMpd::parseState May 31 23:23:25 bedroom volumio[1352]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 31 23:23:25 bedroom volumio[1352]: info: sendMpdCommand playlistinfo took 0 milliseconds May 31 23:23:25 bedroom volumio[1352]: verbose: ControllerMpd::parseTrackInfo May 31 23:23:25 bedroom volumio[1352]: info: ControllerMpd::pushState May 31 23:23:25 bedroom volumio[1352]: info: CoreCommandRouter::servicePushState May 31 23:23:25 bedroom volumio[1352]: info: CoreStateMachine::pushState May 31 23:23:25 bedroom volumio[1352]: info: CorePlayQueue::getTrack 0 May 31 23:23:25 bedroom volumio[1352]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 31 23:23:25 bedroom volumio[1352]: info: CoreCommandRouter::volumioPushState May 31 23:23:25 bedroom volumio[1352]: info: MRS: Pushing multiroomSync output update for this device May 31 23:23:25 bedroom volumio[1352]: info: MRS: Pushing multiroomSync output May 31 23:23:25 bedroom volumio[1352]: info: CoreCommandRouter::volumioGetState May 31 23:23:25 bedroom volumio[1352]: info: CorePlayQueue::getTrack 0 May 31 23:23:25 bedroom volumio[1352]: info: CorePlayQueue::getTrack 0 May 31 23:23:25 bedroom volumio[1352]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current qobuz Received mpd May 31 23:23:25 bedroom volumio5-onboarding[2136]: time=2026-05-31T23:23:25.442+02:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%01,192.168.188.115:49702 @ 0x1cdf500" state=STATUS_STOPPED positionMs=0 volume=99 May 31 23:23:25 bedroom volumio5-onboarding[2136]: time=2026-05-31T23:23:25.442+02:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.188.115:49702 @ 0x1c9a2d0" state=STATUS_STOPPED positionMs=0 volume=99 May 31 23:23:25 bedroom volumio5-onboarding[2136]: time=2026-05-31T23:23:25.442+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%01,192.168.188.115:49702 @ 0x1cdf500" id=qobuz://song/104009422 title="Hope Has a Place" May 31 23:23:25 bedroom volumio5-onboarding[2136]: time=2026-05-31T23:23:25.442+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.188.115:49702 @ 0x1c9a2d0" id=qobuz://song/104009422 title="Hope Has a Place" May 31 23:23:25 bedroom volumio[1352]: info: ------------------------------ 8ms May 31 23:23:25 bedroom volumio[1352]: info: CoreCommandRouter::volumioGetState May 31 23:23:25 bedroom volumio[1352]: info: CorePlayQueue::getTrack 0 May 31 23:23:25 bedroom volumio[1352]: info: Current volume is 99 May 31 23:23:25 bedroom volumio[1352]: info: Increasing volume by 1: setting volume to 100 May 31 23:23:25 bedroom volumio[1352]: info: Sending REST command to localhost:3000/api/v1/commands/?cmd=volume&volume=100 May 31 23:23:25 bedroom volumio[1352]: info: May 31 23:23:25 bedroom volumio[1352]: ---------------------------- Client requests Volume 100 May 31 23:23:25 bedroom volumio[1352]: info: VolumeController::SetAlsaVolume100 May 31 23:23:25 bedroom volumio[1352]: info: CoreStateMachine::pushState May 31 23:23:25 bedroom volumio[1352]: info: CorePlayQueue::getTrack 0 May 31 23:23:25 bedroom volumio[1352]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 31 23:23:25 bedroom volumio[1352]: info: CoreCommandRouter::volumioPushState May 31 23:23:25 bedroom volumio[1352]: info: MRS: Pushing multiroomSync output update for this device May 31 23:23:25 bedroom volumio[1352]: info: MRS: Pushing multiroomSync output May 31 23:23:25 bedroom volumio[1352]: info: CoreCommandRouter::volumioGetState May 31 23:23:25 bedroom volumio[1352]: info: CorePlayQueue::getTrack 0 May 31 23:23:25 bedroom volumio5-onboarding[2136]: time=2026-05-31T23:23:25.462+02:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%01,192.168.188.115:49702 @ 0x1cdf500" state=STATUS_STOPPED positionMs=0 volume=100 May 31 23:23:25 bedroom volumio5-onboarding[2136]: time=2026-05-31T23:23:25.462+02:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.188.115:49702 @ 0x1c9a2d0" state=STATUS_STOPPED positionMs=0 volume=100 May 31 23:23:25 bedroom volumio5-onboarding[2136]: time=2026-05-31T23:23:25.462+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%01,192.168.188.115:49702 @ 0x1cdf500" id=qobuz://song/104009422 title="Hope Has a Place" May 31 23:23:25 bedroom volumio5-onboarding[2136]: time=2026-05-31T23:23:25.462+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.188.115:49702 @ 0x1c9a2d0" id=qobuz://song/104009422 title="Hope Has a Place" May 31 23:23:25 bedroom volumio[1352]: info: Received response: {"time":1780262605454,"response":"volume Success"} May 31 23:23:25 bedroom volumio[1352]: info: Volume set to 100 May 31 23:23:29 bedroom volumio[1352]: info: getStreamUrl took 4364 milliseconds May 31 23:23:29 bedroom volumio[1352]: verbose: ControllerMpd::sendMpdCommand stop May 31 23:23:29 bedroom volumio[1352]: info: sendMpdCommand stop took 1 milliseconds May 31 23:23:29 bedroom volumio[1352]: verbose: ControllerMpd::sendMpdCommand clear May 31 23:23:29 bedroom volumio[1352]: info: sendMpdCommand clear took 0 milliseconds May 31 23:23:29 bedroom volumio[1352]: verbose: ControllerMpd::sendMpdCommand load "https://streaming-qobuz-std.akamaized.net/file?uid=2719172&eid=104009422&fmt=6&profile=raw&app_id=539451548&cid=3144915&etsp=1780266209&hmac=1IUi5_09qk77MDE0fFBdFr7uTv0" May 31 23:23:29 bedroom volumio[1352]: info: May 31 23:23:29 bedroom volumio[1352]: ---------------------------- MPD announces system playlist update May 31 23:23:29 bedroom volumio[1352]: info: Ignoring MPD Status Update May 31 23:23:29 bedroom volumio[1352]: verbose: ControllerMpd::sendMpdCommand add "https://streaming-qobuz-std.akamaized.net/file?uid=2719172&eid=104009422&fmt=6&profile=raw&app_id=539451548&cid=3144915&etsp=1780266209&hmac=1IUi5_09qk77MDE0fFBdFr7uTv0" May 31 23:23:29 bedroom volumio[1352]: error: updateQueue error: null May 31 23:23:29 bedroom volumio[1352]: info: ------------------------------ 17ms May 31 23:23:29 bedroom volumio[1352]: info: May 31 23:23:29 bedroom volumio[1352]: ---------------------------- MPD announces system playlist update May 31 23:23:29 bedroom volumio[1352]: info: Ignoring MPD Status Update May 31 23:23:29 bedroom volumio[1352]: info: sendMpdCommand add "https://streaming-qobuz-std.akamaized.net/file?uid=2719172&eid=104009422&fmt=6&profile=raw&app_id=539451548&cid=3144915&etsp=1780266209&hmac=1IUi5_09qk77MDE0fFBdFr7uTv0" took 1 milliseconds May 31 23:23:29 bedroom volumio[1352]: info: CoreStateMachine::setConsumeUpdateService mpd May 31 23:23:29 bedroom volumio[1352]: verbose: ControllerMpd::sendMpdCommand play May 31 23:23:29 bedroom volumio[1352]: info: ------------------------------ 1ms May 31 23:23:29 bedroom volumio[1352]: info: sendMpdCommand play took 1 milliseconds May 31 23:23:29 bedroom volumio[1352]: info: May 31 23:23:29 bedroom volumio[1352]: ---------------------------- MPD announces state update: player May 31 23:23:29 bedroom volumio[1352]: info: ControllerMpd::getState May 31 23:23:29 bedroom volumio[1352]: verbose: ControllerMpd::sendMpdCommand status May 31 23:23:30 bedroom volumio[1352]: info: May 31 23:23:30 bedroom volumio[1352]: ---------------------------- MPD announces state update: player May 31 23:23:30 bedroom volumio[1352]: info: sendMpdCommand status took 205 milliseconds May 31 23:23:30 bedroom volumio[1352]: info: ControllerMpd::getState May 31 23:23:30 bedroom volumio[1352]: verbose: ControllerMpd::sendMpdCommand status May 31 23:23:30 bedroom volumio[1352]: verbose: ControllerMpd::parseState May 31 23:23:30 bedroom volumio[1352]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 31 23:23:30 bedroom volumio[1352]: info: sendMpdCommand status took 0 milliseconds May 31 23:23:30 bedroom volumio[1352]: info: sendMpdCommand playlistinfo took 0 milliseconds May 31 23:23:30 bedroom volumio[1352]: verbose: ControllerMpd::parseState May 31 23:23:30 bedroom volumio[1352]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 31 23:23:30 bedroom volumio[1352]: verbose: ControllerMpd::parseTrackInfo May 31 23:23:30 bedroom volumio[1352]: info: ControllerMpd::pushState May 31 23:23:30 bedroom volumio[1352]: info: CoreCommandRouter::servicePushState May 31 23:23:30 bedroom volumio[1352]: info: CorePlayQueue::getTrack 0 May 31 23:23:30 bedroom volumio[1352]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":285,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"file?uid=2719172&eid=104009422&fmt=6&profile=raw&app_id=539451548&cid=3144915&etsp=1780266209&hmac=1IUi5_09qk77MDE0fFBdFr7uTv0","artist":null,"album":null,"uri":"https://streaming-qobuz-std.akamaized.net/file?uid=2719172&eid=104009422&fmt=6&profile=raw&app_id=539451548&cid=3144915&etsp=1780266209&hmac=1IUi5_09qk77MDE0fFBdFr7uTv0","trackType":"qobuz"} May 31 23:23:30 bedroom volumio[1352]: verbose: CURRENT POSITION 0 May 31 23:23:30 bedroom volumio[1352]: info: CoreStateMachine::syncState stateService play May 31 23:23:30 bedroom volumio[1352]: info: CoreStateMachine::syncState currentStatus stop May 31 23:23:30 bedroom volumio[1352]: info: ------------------------------ 206ms May 31 23:23:30 bedroom volumio[1352]: info: sendMpdCommand playlistinfo took 1 milliseconds May 31 23:23:30 bedroom volumio[1352]: verbose: ControllerMpd::parseTrackInfo May 31 23:23:30 bedroom volumio[1352]: info: ControllerMpd::pushState May 31 23:23:30 bedroom volumio[1352]: info: CoreCommandRouter::servicePushState May 31 23:23:30 bedroom volumio[1352]: info: CorePlayQueue::getTrack 0 May 31 23:23:30 bedroom volumio[1352]: verbose: STATE SERVICE {"status":"play","position":0,"seek":1215,"duration":285,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"483 Kbps","isStreaming":false,"title":"file?uid=2719172&eid=104009422&fmt=6&profile=raw&app_id=539451548&cid=3144915&etsp=1780266209&hmac=1IUi5_09qk77MDE0fFBdFr7uTv0","artist":null,"album":null,"uri":"https://streaming-qobuz-std.akamaized.net/file?uid=2719172&eid=104009422&fmt=6&profile=raw&app_id=539451548&cid=3144915&etsp=1780266209&hmac=1IUi5_09qk77MDE0fFBdFr7uTv0","trackType":"qobuz"} May 31 23:23:30 bedroom volumio[1352]: verbose: CURRENT POSITION 0 May 31 23:23:30 bedroom volumio[1352]: info: CoreStateMachine::syncState stateService play May 31 23:23:30 bedroom volumio[1352]: info: CoreStateMachine::syncState currentStatus play May 31 23:23:30 bedroom volumio[1352]: info: Received an update from plugin. extracting info from payload May 31 23:23:30 bedroom volumio[1352]: info: CoreStateMachine::pushState May 31 23:23:30 bedroom volumio[1352]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 31 23:23:30 bedroom volumio[1352]: info: CoreCommandRouter::volumioPushState May 31 23:23:30 bedroom volumio[1352]: info: MRS: Pushing multiroomSync output update for this device May 31 23:23:30 bedroom volumio[1352]: info: MRS: Pushing multiroomSync output May 31 23:23:30 bedroom volumio[1352]: info: CoreCommandRouter::volumioGetState May 31 23:23:30 bedroom volumio[1352]: info: CoreStateMachine::pushState May 31 23:23:30 bedroom volumio[1352]: info: CoreCommandRouter::volumioPushState May 31 23:23:30 bedroom volumio[1352]: info: MRS: Pushing multiroomSync output update for this device May 31 23:23:30 bedroom volumio[1352]: info: MRS: Pushing multiroomSync output May 31 23:23:30 bedroom volumio[1352]: info: CoreCommandRouter::volumioGetState May 31 23:23:30 bedroom volumio5-onboarding[2136]: time=2026-05-31T23:23:30.175+02:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%01,192.168.188.115:49702 @ 0x1cdf500" state=STATUS_PLAYING positionMs=0 volume=100 May 31 23:23:30 bedroom volumio5-onboarding[2136]: time=2026-05-31T23:23:30.175+02:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.188.115:49702 @ 0x1c9a2d0" state=STATUS_PLAYING positionMs=0 volume=100 May 31 23:23:30 bedroom volumio5-onboarding[2136]: time=2026-05-31T23:23:30.175+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%01,192.168.188.115:49702 @ 0x1cdf500" id=qobuz://song/104009422 title="Hope Has a Place" May 31 23:23:30 bedroom volumio5-onboarding[2136]: time=2026-05-31T23:23:30.175+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.188.115:49702 @ 0x1c9a2d0" id=qobuz://song/104009422 title="Hope Has a Place" May 31 23:23:30 bedroom volumio5-onboarding[2136]: time=2026-05-31T23:23:30.176+02:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%01,192.168.188.115:49702 @ 0x1cdf500" state=STATUS_PLAYING positionMs=0 volume=100 May 31 23:23:30 bedroom volumio5-onboarding[2136]: time=2026-05-31T23:23:30.176+02:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.188.115:49702 @ 0x1c9a2d0" state=STATUS_PLAYING positionMs=0 volume=100 May 31 23:23:30 bedroom volumio5-onboarding[2136]: time=2026-05-31T23:23:30.176+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%01,192.168.188.115:49702 @ 0x1cdf500" id=qobuz://song/104009422 title="Hope Has a Place" May 31 23:23:30 bedroom volumio5-onboarding[2136]: time=2026-05-31T23:23:30.176+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.188.115:49702 @ 0x1c9a2d0" id=qobuz://song/104009422 title="Hope Has a Place" May 31 23:23:30 bedroom volumio[1352]: info: ------------------------------ 16ms May 31 23:23:31 bedroom volumio[1352]: info: Getting current volume May 31 23:23:31 bedroom volumio[1352]: info: CoreCommandRouter::volumioGetState May 31 23:23:31 bedroom volumio[1352]: info: Current volume is 100 May 31 23:23:31 bedroom volumio[1352]: info: Increasing volume by 1: setting volume to 100 May 31 23:23:31 bedroom volumio[1352]: info: Sending REST command to localhost:3000/api/v1/commands/?cmd=volume&volume=100 May 31 23:23:31 bedroom volumio[1352]: info: May 31 23:23:31 bedroom volumio[1352]: ---------------------------- Client requests Volume 100 May 31 23:23:31 bedroom volumio[1352]: info: VolumeController::SetAlsaVolume100 May 31 23:23:31 bedroom volumio[1352]: info: CoreStateMachine::pushState May 31 23:23:31 bedroom volumio[1352]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 31 23:23:31 bedroom volumio[1352]: info: CoreCommandRouter::volumioPushState May 31 23:23:31 bedroom volumio[1352]: info: MRS: Pushing multiroomSync output update for this device May 31 23:23:31 bedroom volumio[1352]: info: MRS: Pushing multiroomSync output May 31 23:23:31 bedroom volumio[1352]: info: CoreCommandRouter::volumioGetState May 31 23:23:31 bedroom volumio5-onboarding[2136]: time=2026-05-31T23:23:31.486+02:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%01,192.168.188.115:49702 @ 0x1cdf500" state=STATUS_PLAYING positionMs=1501 volume=100 May 31 23:23:31 bedroom volumio5-onboarding[2136]: time=2026-05-31T23:23:31.486+02:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.188.115:49702 @ 0x1c9a2d0" state=STATUS_PLAYING positionMs=1501 volume=100 May 31 23:23:31 bedroom volumio5-onboarding[2136]: time=2026-05-31T23:23:31.486+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%01,192.168.188.115:49702 @ 0x1cdf500" id=qobuz://song/104009422 title="Hope Has a Place" May 31 23:23:31 bedroom volumio5-onboarding[2136]: time=2026-05-31T23:23:31.486+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.188.115:49702 @ 0x1c9a2d0" id=qobuz://song/104009422 title="Hope Has a Place" May 31 23:23:31 bedroom volumio[1352]: info: Received response: {"time":1780262611474,"response":"volume Success"} May 31 23:23:31 bedroom volumio[1352]: info: Volume set to 100 May 31 23:23:37 bedroom volumio[1352]: info: Getting current volume May 31 23:23:37 bedroom volumio[1352]: info: CoreCommandRouter::volumioGetState May 31 23:23:37 bedroom volumio[1352]: info: Current volume is 100 May 31 23:23:37 bedroom volumio[1352]: info: Increasing volume by 1: setting volume to 100 May 31 23:23:37 bedroom volumio[1352]: info: Sending REST command to localhost:3000/api/v1/commands/?cmd=volume&volume=100 May 31 23:23:37 bedroom volumio[1352]: info: May 31 23:23:37 bedroom volumio[1352]: ---------------------------- Client requests Volume 100 May 31 23:23:37 bedroom volumio[1352]: info: VolumeController::SetAlsaVolume100 May 31 23:23:37 bedroom volumio[1352]: info: CoreStateMachine::pushState May 31 23:23:37 bedroom volumio[1352]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 31 23:23:37 bedroom volumio[1352]: info: CoreCommandRouter::volumioPushState May 31 23:23:37 bedroom volumio[1352]: info: MRS: Pushing multiroomSync output update for this device May 31 23:23:37 bedroom volumio[1352]: info: MRS: Pushing multiroomSync output May 31 23:23:37 bedroom volumio[1352]: info: CoreCommandRouter::volumioGetState May 31 23:23:37 bedroom volumio5-onboarding[2136]: time=2026-05-31T23:23:37.517+02:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%01,192.168.188.115:49702 @ 0x1cdf500" state=STATUS_PLAYING positionMs=7506 volume=100 May 31 23:23:37 bedroom volumio5-onboarding[2136]: time=2026-05-31T23:23:37.518+02:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.188.115:49702 @ 0x1c9a2d0" state=STATUS_PLAYING positionMs=7506 volume=100 May 31 23:23:37 bedroom volumio5-onboarding[2136]: time=2026-05-31T23:23:37.518+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%01,192.168.188.115:49702 @ 0x1cdf500" id=qobuz://song/104009422 title="Hope Has a Place" May 31 23:23:37 bedroom volumio5-onboarding[2136]: time=2026-05-31T23:23:37.518+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.188.115:49702 @ 0x1c9a2d0" id=qobuz://song/104009422 title="Hope Has a Place" May 31 23:23:37 bedroom volumio[1352]: info: Received response: {"time":1780262617501,"response":"volume Success"} May 31 23:23:37 bedroom volumio[1352]: info: Volume set to 100 May 31 23:23:43 bedroom volumio[1352]: info: Getting current volume May 31 23:23:43 bedroom volumio[1352]: info: CoreCommandRouter::volumioGetState May 31 23:23:43 bedroom volumio[1352]: info: Current volume is 100 May 31 23:23:43 bedroom volumio[1352]: info: Increasing volume by 1: setting volume to 100 May 31 23:23:43 bedroom volumio[1352]: info: Sending REST command to localhost:3000/api/v1/commands/?cmd=volume&volume=100 May 31 23:23:43 bedroom volumio[1352]: info: May 31 23:23:43 bedroom volumio[1352]: ---------------------------- Client requests Volume 100 May 31 23:23:43 bedroom volumio[1352]: info: VolumeController::SetAlsaVolume100 May 31 23:23:43 bedroom volumio[1352]: info: CoreStateMachine::pushState May 31 23:23:43 bedroom volumio[1352]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 31 23:23:43 bedroom volumio[1352]: info: CoreCommandRouter::volumioPushState May 31 23:23:43 bedroom volumio[1352]: info: MRS: Pushing multiroomSync output update for this device May 31 23:23:43 bedroom volumio[1352]: info: MRS: Pushing multiroomSync output May 31 23:23:43 bedroom volumio[1352]: info: CoreCommandRouter::volumioGetState May 31 23:23:43 bedroom volumio5-onboarding[2136]: time=2026-05-31T23:23:43.541+02:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%01,192.168.188.115:49702 @ 0x1cdf500" state=STATUS_PLAYING positionMs=13513 volume=100 May 31 23:23:43 bedroom volumio5-onboarding[2136]: time=2026-05-31T23:23:43.541+02:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.188.115:49702 @ 0x1c9a2d0" state=STATUS_PLAYING positionMs=13513 volume=100 May 31 23:23:43 bedroom volumio5-onboarding[2136]: time=2026-05-31T23:23:43.541+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%01,192.168.188.115:49702 @ 0x1cdf500" id=qobuz://song/104009422 title="Hope Has a Place" May 31 23:23:43 bedroom volumio5-onboarding[2136]: time=2026-05-31T23:23:43.541+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.188.115:49702 @ 0x1c9a2d0" id=qobuz://song/104009422 title="Hope Has a Place" May 31 23:23:43 bedroom volumio[1352]: info: Received response: {"time":1780262623529,"response":"volume Success"} May 31 23:23:43 bedroom volumio[1352]: info: Volume set to 100 May 31 23:23:49 bedroom volumio[1352]: info: Getting current volume May 31 23:23:49 bedroom volumio[1352]: info: CoreCommandRouter::volumioGetState May 31 23:23:49 bedroom volumio[1352]: info: Current volume is 100 May 31 23:23:49 bedroom volumio[1352]: info: Increasing volume by 1: setting volume to 100 May 31 23:23:49 bedroom volumio[1352]: info: Sending REST command to localhost:3000/api/v1/commands/?cmd=volume&volume=100 May 31 23:23:49 bedroom volumio[1352]: info: May 31 23:23:49 bedroom volumio[1352]: ---------------------------- Client requests Volume 100 May 31 23:23:49 bedroom volumio[1352]: info: VolumeController::SetAlsaVolume100 May 31 23:23:49 bedroom volumio[1352]: info: CoreStateMachine::pushState May 31 23:23:49 bedroom volumio[1352]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 31 23:23:49 bedroom volumio[1352]: info: CoreCommandRouter::volumioPushState May 31 23:23:49 bedroom volumio[1352]: info: MRS: Pushing multiroomSync output update for this device May 31 23:23:49 bedroom volumio[1352]: info: MRS: Pushing multiroomSync output May 31 23:23:49 bedroom volumio[1352]: info: CoreCommandRouter::volumioGetState May 31 23:23:49 bedroom volumio5-onboarding[2136]: time=2026-05-31T23:23:49.563+02:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%01,192.168.188.115:49702 @ 0x1cdf500" state=STATUS_PLAYING positionMs=19517 volume=100 May 31 23:23:49 bedroom volumio5-onboarding[2136]: time=2026-05-31T23:23:49.564+02:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.188.115:49702 @ 0x1c9a2d0" state=STATUS_PLAYING positionMs=19517 volume=100 May 31 23:23:49 bedroom volumio5-onboarding[2136]: time=2026-05-31T23:23:49.564+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%01,192.168.188.115:49702 @ 0x1cdf500" id=qobuz://song/104009422 title="Hope Has a Place" May 31 23:23:49 bedroom volumio5-onboarding[2136]: time=2026-05-31T23:23:49.564+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.188.115:49702 @ 0x1c9a2d0" id=qobuz://song/104009422 title="Hope Has a Place" May 31 23:23:49 bedroom volumio[1352]: info: Received response: {"time":1780262629550,"response":"volume Success"} May 31 23:23:49 bedroom volumio[1352]: info: Volume set to 100 May 31 23:23:54 bedroom volumio[1352]: info: CoreCommandRouter::volumioPause May 31 23:23:54 bedroom volumio[1352]: info: CoreStateMachine::pause May 31 23:23:54 bedroom volumio[1352]: info: CoreStateMachine::stPlaybackTimer May 31 23:23:54 bedroom volumio[1352]: info: CoreStateMachine::servicePause May 31 23:23:54 bedroom volumio[1352]: info: CorePlayQueue::getTrack 0 May 31 23:23:54 bedroom volumio[1352]: info: CoreCommandRouter::servicePause May 31 23:23:54 bedroom volumio[1352]: info: [1780262634269] ControllerQobuz::pause May 31 23:23:54 bedroom volumio[1352]: info: CoreStateMachine::setConsumeUpdateService mpd May 31 23:23:54 bedroom volumio[1352]: info: ControllerMpd::pause May 31 23:23:54 bedroom volumio[1352]: verbose: ControllerMpd::sendMpdCommand pause May 31 23:23:54 bedroom volumio[1352]: info: May 31 23:23:54 bedroom volumio[1352]: ---------------------------- MPD announces state update: player May 31 23:23:54 bedroom volumio[1352]: info: sendMpdCommand pause took 1 milliseconds May 31 23:23:54 bedroom volumio[1352]: info: ControllerMpd::getState May 31 23:23:54 bedroom volumio[1352]: verbose: ControllerMpd::sendMpdCommand status May 31 23:23:54 bedroom volumio[1352]: info: sendMpdCommand status took 0 milliseconds May 31 23:23:54 bedroom volumio[1352]: verbose: ControllerMpd::parseState May 31 23:23:54 bedroom volumio[1352]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 31 23:23:54 bedroom volumio[1352]: info: sendMpdCommand playlistinfo took 0 milliseconds May 31 23:23:54 bedroom volumio[1352]: verbose: ControllerMpd::parseTrackInfo May 31 23:23:54 bedroom volumio[1352]: info: ControllerMpd::pushState May 31 23:23:54 bedroom volumio[1352]: info: CoreCommandRouter::servicePushState May 31 23:23:54 bedroom volumio[1352]: info: CorePlayQueue::getTrack 0 May 31 23:23:54 bedroom volumio[1352]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":25469,"duration":285,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"648 Kbps","isStreaming":false,"title":"file?uid=2719172&eid=104009422&fmt=6&profile=raw&app_id=539451548&cid=3144915&etsp=1780266209&hmac=1IUi5_09qk77MDE0fFBdFr7uTv0","artist":null,"album":null,"uri":"https://streaming-qobuz-std.akamaized.net/file?uid=2719172&eid=104009422&fmt=6&profile=raw&app_id=539451548&cid=3144915&etsp=1780266209&hmac=1IUi5_09qk77MDE0fFBdFr7uTv0","trackType":"qobuz"} May 31 23:23:54 bedroom volumio[1352]: verbose: CURRENT POSITION 0 May 31 23:23:54 bedroom volumio[1352]: info: CoreStateMachine::syncState stateService pause May 31 23:23:54 bedroom volumio[1352]: info: CoreStateMachine::syncState currentStatus pause May 31 23:23:54 bedroom volumio[1352]: info: CoreStateMachine::pushState May 31 23:23:54 bedroom volumio[1352]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 31 23:23:54 bedroom volumio[1352]: info: CoreCommandRouter::volumioPushState May 31 23:23:54 bedroom volumio[1352]: info: MRS: Pushing multiroomSync output update for this device May 31 23:23:54 bedroom volumio[1352]: info: MRS: Pushing multiroomSync output May 31 23:23:54 bedroom volumio[1352]: info: CoreCommandRouter::volumioGetState May 31 23:23:54 bedroom volumio[1352]: info: CoreStateMachine::stPlaybackTimer May 31 23:23:54 bedroom volumio5-onboarding[2136]: time=2026-05-31T23:23:54.280+02:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%01,192.168.188.115:49702 @ 0x1cdf500" state=STATUS_PAUSED positionMs=24273 volume=100 May 31 23:23:54 bedroom volumio5-onboarding[2136]: time=2026-05-31T23:23:54.281+02:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.188.115:49702 @ 0x1c9a2d0" state=STATUS_PAUSED positionMs=24273 volume=100 May 31 23:23:54 bedroom volumio5-onboarding[2136]: time=2026-05-31T23:23:54.281+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%01,192.168.188.115:49702 @ 0x1cdf500" id=qobuz://song/104009422 title="Hope Has a Place" May 31 23:23:54 bedroom volumio5-onboarding[2136]: time=2026-05-31T23:23:54.281+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.188.115:49702 @ 0x1c9a2d0" id=qobuz://song/104009422 title="Hope Has a Place" May 31 23:23:54 bedroom volumio[1352]: info: ------------------------------ 12ms May 31 23:23:54 bedroom volumio[1352]: info: CoreCommandRouter::volumioGetQueue May 31 23:23:54 bedroom volumio[1352]: info: CoreStateMachine::getQueue May 31 23:23:54 bedroom volumio[1352]: info: CorePlayQueue::getQueue May 31 23:23:55 bedroom volumio[1352]: info: Getting current volume May 31 23:23:55 bedroom volumio[1352]: info: CoreCommandRouter::volumioGetState May 31 23:23:55 bedroom volumio[1352]: info: Current volume is 100 May 31 23:23:55 bedroom volumio[1352]: info: Increasing volume by 1: setting volume to 100 May 31 23:23:55 bedroom volumio[1352]: info: Sending REST command to localhost:3000/api/v1/commands/?cmd=volume&volume=100 May 31 23:23:55 bedroom volumio[1352]: info: May 31 23:23:55 bedroom volumio[1352]: ---------------------------- Client requests Volume 100 May 31 23:23:55 bedroom volumio[1352]: info: VolumeController::SetAlsaVolume100 May 31 23:23:55 bedroom volumio[1352]: info: CoreStateMachine::pushState May 31 23:23:55 bedroom volumio[1352]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 31 23:23:55 bedroom volumio[1352]: info: CoreCommandRouter::volumioPushState May 31 23:23:55 bedroom volumio[1352]: info: MRS: Pushing multiroomSync output update for this device May 31 23:23:55 bedroom volumio[1352]: info: MRS: Pushing multiroomSync output May 31 23:23:55 bedroom volumio[1352]: info: CoreCommandRouter::volumioGetState May 31 23:23:55 bedroom volumio5-onboarding[2136]: time=2026-05-31T23:23:55.588+02:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%01,192.168.188.115:49702 @ 0x1cdf500" state=STATUS_PAUSED positionMs=24523 volume=100 May 31 23:23:55 bedroom volumio5-onboarding[2136]: time=2026-05-31T23:23:55.588+02:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.188.115:49702 @ 0x1c9a2d0" state=STATUS_PAUSED positionMs=24523 volume=100 May 31 23:23:55 bedroom volumio5-onboarding[2136]: time=2026-05-31T23:23:55.588+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%01,192.168.188.115:49702 @ 0x1cdf500" id=qobuz://song/104009422 title="Hope Has a Place" May 31 23:23:55 bedroom volumio5-onboarding[2136]: time=2026-05-31T23:23:55.588+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.188.115:49702 @ 0x1c9a2d0" id=qobuz://song/104009422 title="Hope Has a Place" May 31 23:23:55 bedroom volumio[1352]: info: Received response: {"time":1780262635574,"response":"volume Success"} May 31 23:23:55 bedroom volumio[1352]: info: Volume set to 100 May 31 23:23:58 bedroom volumio[1352]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus May 31 23:23:58 bedroom volumio[1352]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken May 31 23:24:01 bedroom volumio[1352]: info: Getting current volume May 31 23:24:01 bedroom volumio[1352]: info: CoreCommandRouter::volumioGetState May 31 23:24:01 bedroom volumio[1352]: info: Current volume is 100 May 31 23:24:01 bedroom volumio[1352]: info: Increasing volume by 1: setting volume to 100 May 31 23:24:01 bedroom volumio[1352]: info: Sending REST command to localhost:3000/api/v1/commands/?cmd=volume&volume=100 May 31 23:24:01 bedroom volumio[1352]: info: May 31 23:24:01 bedroom volumio[1352]: ---------------------------- Client requests Volume 100 May 31 23:24:01 bedroom volumio[1352]: info: VolumeController::SetAlsaVolume100 May 31 23:24:01 bedroom volumio[1352]: info: CoreStateMachine::pushState May 31 23:24:01 bedroom volumio[1352]: info: CoreCommandRouter::volumioPushState May 31 23:24:01 bedroom volumio[1352]: info: MRS: Pushing multiroomSync output update for this device May 31 23:24:01 bedroom volumio[1352]: info: MRS: Pushing multiroomSync output May 31 23:24:01 bedroom volumio[1352]: info: CoreCommandRouter::volumioGetState May 31 23:24:01 bedroom volumio5-onboarding[2136]: time=2026-05-31T23:24:01.608+02:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%01,192.168.188.115:49702 @ 0x1cdf500" state=STATUS_PAUSED positionMs=24523 volume=100 May 31 23:24:01 bedroom volumio5-onboarding[2136]: time=2026-05-31T23:24:01.608+02:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.188.115:49702 @ 0x1c9a2d0" state=STATUS_PAUSED positionMs=24523 volume=100 May 31 23:24:01 bedroom volumio5-onboarding[2136]: time=2026-05-31T23:24:01.608+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%01,192.168.188.115:49702 @ 0x1cdf500" id=qobuz://song/104009422 title="Hope Has a Place" May 31 23:24:01 bedroom volumio5-onboarding[2136]: time=2026-05-31T23:24:01.608+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.188.115:49702 @ 0x1c9a2d0" id=qobuz://song/104009422 title="Hope Has a Place" May 31 23:24:01 bedroom volumio[1352]: info: Received response: {"time":1780262641597,"response":"volume Success"} May 31 23:24:01 bedroom volumio[1352]: info: Volume set to 100 May 31 23:24:05 bedroom volumio[1352]: info: Starting Uninstall of plugin system_controller - SleepWakePlugin May 31 23:24:05 bedroom volumio[1352]: info: Uninstalling plugin SleepWakePlugin May 31 23:24:05 bedroom volumio5-onboarding[2136]: time=2026-05-31T23:24:05.496+02:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state May 31 23:24:05 bedroom volumio[1352]: info: Disabling plugin SleepWakePlugin May 31 23:24:05 bedroom volumio5-onboarding[2136]: time=2026-05-31T23:24:05.498+02:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state May 31 23:24:05 bedroom volumio[1352]: info: Checking if uninstall.sh is present May 31 23:24:05 bedroom volumio[1352]: info: Executing uninstall.sh May 31 23:24:05 bedroom sudo[2720]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/sh /data/plugins/system_controller/SleepWakePlugin/uninstall.sh May 31 23:24:05 bedroom sudo[2720]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 31 23:24:05 bedroom sudo[2720]: pam_unix(sudo:session): session closed for user root May 31 23:24:05 bedroom volumio[1352]: info: Uninstall script completed May 31 23:24:05 bedroom volumio5-onboarding[2136]: time=2026-05-31T23:24:05.537+02:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state May 31 23:24:05 bedroom volumio[1352]: info: Removing plugin SleepWakePlugin from configuration May 31 23:24:05 bedroom volumio[1352]: info: Successfully removed SleepWakePlugin configuration files May 31 23:24:05 bedroom volumio5-onboarding[2136]: time=2026-05-31T23:24:05.559+02:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state May 31 23:24:05 bedroom volumio[1352]: info: Plugin folders cleanup May 31 23:24:05 bedroom volumio[1352]: info: Scanning into folder /volumio/app/plugins/ May 31 23:24:05 bedroom volumio[1352]: info: Scanning category audio_interface May 31 23:24:05 bedroom volumio[1352]: info: Scanning category miscellanea May 31 23:24:05 bedroom volumio[1352]: info: Scanning category music_service May 31 23:24:05 bedroom volumio[1352]: info: Scanning category plugins.json May 31 23:24:05 bedroom volumio[1352]: info: Scanning category system_controller May 31 23:24:05 bedroom volumio[1352]: info: Scanning category user_interface May 31 23:24:05 bedroom volumio[1352]: info: Scanning into folder /data/plugins/ May 31 23:24:05 bedroom volumio[1352]: info: Scanning category system_controller May 31 23:24:05 bedroom volumio[1352]: info: Cleaning folder for SleepWakePlugin May 31 23:24:05 bedroom volumio[1352]: info: Plugin folders cleanup completed May 31 23:24:05 bedroom volumio5-onboarding[2136]: time=2026-05-31T23:24:05.589+02:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state May 31 23:24:05 bedroom volumio[1352]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus May 31 23:24:05 bedroom volumio[1352]: info: [] May 31 23:24:05 bedroom volumio[1352]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken May 31 23:24:07 bedroom volumio[1352]: info: Getting current volume May 31 23:24:07 bedroom volumio[1352]: error: SleepWakePlugin - Error in increaseVolume: Error: ENOENT: no such file or directory, open '/data/plugins/system_controller/SleepWakePlugin/sleep-wake-plugin.log' May 31 23:24:07 bedroom volumio[1352]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 31 23:24:07 bedroom volumio[1352]: Error: ENOENT: no such file or directory, open '/data/plugins/system_controller/SleepWakePlugin/sleep-wake-plugin.log' May 31 23:24:07 bedroom volumio[1352]: at Object.openSync (node:fs:602:3) May 31 23:24:07 bedroom volumio[1352]: at Object.writeFileSync (node:fs:2334:35) May 31 23:24:07 bedroom volumio[1352]: at Object.appendFileSync (node:fs:2396:6) May 31 23:24:07 bedroom volumio[1352]: at SleepWakePlugin.writeLog (/data/plugins/system_controller/SleepWakePlugin/index.js:827:6) May 31 23:24:07 bedroom volumio[1352]: at Timeout.increaseVolume [as _onTimeout] (/data/plugins/system_controller/SleepWakePlugin/index.js:802:12) May 31 23:24:07 bedroom volumio[1352]: at listOnTimeout (node:internal/timers:573:17) May 31 23:24:07 bedroom volumio[1352]: at process.processTimers (node:internal/timers:514:7) { May 31 23:24:07 bedroom volumio[1352]: errno: -2, May 31 23:24:07 bedroom volumio[1352]: syscall: 'open', May 31 23:24:07 bedroom volumio[1352]: code: 'ENOENT', May 31 23:24:07 bedroom volumio[1352]: path: '/data/plugins/system_controller/SleepWakePlugin/sleep-wake-plugin.log' May 31 23:24:07 bedroom volumio[1352]: } May 31 23:24:07 bedroom volumio[1352]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 31 23:24:07 bedroom sudo[2742]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-05-31 23:23' May 31 23:24:07 bedroom sudo[2742]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) PRETTY_NAME="Raspbian GNU/Linux 12 (bookworm)" NAME="Raspbian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm 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="18952480e8d8c63f22208e9007a0f47a9563eae6" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="0e58f1861fa88e02087981b8d91f7511f0e7011b" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue Mar 24 17:20:52 UTC 2026" VOLUMIO_VERSION="4.119" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="d0c2fd9dbc5e70e58c32413c12353563"