-- Logs begin at Sat 2024-05-11 17:57:16 CEST, end at Sat 2024-05-11 18:05:18 CEST. -- May 11 18:04:36 rivo volumio[5577]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 11 18:04:36 rivo volumio[5577]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 11 18:04:36 rivo volumio[5577]: info: Discovery: Getting this device information May 11 18:04:36 rivo volumio[5577]: info: CoreCommandRouter::volumioGetState May 11 18:04:36 rivo volumio[5577]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 11 18:04:36 rivo volumio[5577]: verbose: New Socket.io Connection to 192.168.1.123 from 192.168.1.111 UA: unknown Total Clients: 7 May 11 18:04:36 rivo volumio[5577]: info: CoreCommandRouter::volumioGetState May 11 18:04:36 rivo volumio[5577]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard May 11 18:04:36 rivo volumio[5577]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard May 11 18:04:41 rivo sudo[7303]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 May 11 18:04:41 rivo sudo[7303]: pam_unix(sudo:session): session opened for user root by (uid=0) May 11 18:04:41 rivo sudo[7303]: pam_unix(sudo:session): session closed for user root May 11 18:04:41 rivo sudo[7306]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 May 11 18:04:41 rivo sudo[7306]: pam_unix(sudo:session): session opened for user root by (uid=0) May 11 18:04:41 rivo sudo[7306]: pam_unix(sudo:session): session closed for user root May 11 18:04:41 rivo volumio[5577]: verbose: New Socket.io Connection to 192.168.1.123 from 192.168.1.111 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 16_7_7 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Total Clients: 8 May 11 18:04:42 rivo volumio[5577]: info: CoreCommandRouter::volumioGetState May 11 18:04:42 rivo volumio[5577]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom May 11 18:04:42 rivo volumio[5577]: info: Error : CoreCommandRouter::executeOnPlugin: No method [getMultiroom] in plugin multiroom May 11 18:04:42 rivo volumio[5577]: info: Listing playlists May 11 18:04:42 rivo volumio[5577]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings May 11 18:04:42 rivo volumio[5577]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard May 11 18:04:42 rivo volumio[5577]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard May 11 18:04:42 rivo volumio[5577]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings May 11 18:04:46 rivo volumio[5577]: info: CoreCommandRouter::volumioPlay May 11 18:04:46 rivo volumio[5577]: info: CoreStateMachine::play index undefined May 11 18:04:46 rivo volumio[5577]: info: CoreStateMachine::setConsumeUpdateService undefined May 11 18:04:46 rivo volumio[5577]: info: CorePlayQueue::getTrack 0 May 11 18:04:46 rivo volumio[5577]: info: CoreStateMachine::startPlaybackTimer May 11 18:04:46 rivo volumio[5577]: info: CorePlayQueue::getTrack 0 May 11 18:04:46 rivo volumio[5577]: info: [1715443486209] ControllerQobuz::resume May 11 18:04:46 rivo volumio[5577]: info: CoreStateMachine::setConsumeUpdateService mpd May 11 18:04:46 rivo volumio[5577]: info: ControllerMpd::resume May 11 18:04:46 rivo volumio[5577]: verbose: ControllerMpd::sendMpdCommand play May 11 18:04:46 rivo volumio[5577]: info: May 11 18:04:46 rivo volumio[5577]: ---------------------------- MPD announces state update: player May 11 18:04:46 rivo volumio[5577]: info: sendMpdCommand play took 40 milliseconds May 11 18:04:46 rivo volumio[5577]: info: ControllerMpd::getState May 11 18:04:46 rivo volumio[5577]: verbose: ControllerMpd::sendMpdCommand status May 11 18:04:46 rivo volumio[5577]: info: May 11 18:04:46 rivo volumio[5577]: ---------------------------- MPD announces state update: player May 11 18:04:46 rivo volumio[5577]: info: ControllerMpd::getState May 11 18:04:46 rivo volumio[5577]: verbose: ControllerMpd::sendMpdCommand status May 11 18:04:46 rivo volumio[5577]: info: May 11 18:04:46 rivo volumio[5577]: ---------------------------- MPD announces state update: player May 11 18:04:46 rivo volumio[5577]: info: ControllerMpd::getState May 11 18:04:46 rivo volumio[5577]: verbose: ControllerMpd::sendMpdCommand status May 11 18:04:46 rivo volumio[5577]: info: sendMpdCommand status took 19 milliseconds May 11 18:04:46 rivo volumio[5577]: info: sendMpdCommand status took 13 milliseconds May 11 18:04:46 rivo volumio[5577]: info: sendMpdCommand status took 8 milliseconds May 11 18:04:46 rivo volumio[5577]: verbose: ControllerMpd::parseState May 11 18:04:46 rivo volumio[5577]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 11 18:04:46 rivo volumio[5577]: verbose: ControllerMpd::parseState May 11 18:04:46 rivo volumio[5577]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 11 18:04:46 rivo volumio[5577]: verbose: ControllerMpd::parseState May 11 18:04:46 rivo volumio[5577]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 11 18:04:46 rivo volumio[5577]: error: Upnp client error: Error: This socket has been ended by the other party May 11 18:04:46 rivo volumio[5577]: info: sendMpdCommand playlistinfo took 8 milliseconds May 11 18:04:46 rivo volumio[5577]: info: sendMpdCommand playlistinfo took 8 milliseconds May 11 18:04:46 rivo volumio[5577]: info: sendMpdCommand playlistinfo took 7 milliseconds May 11 18:04:46 rivo volumio[5577]: verbose: ControllerMpd::parseTrackInfo May 11 18:04:46 rivo volumio[5577]: verbose: ControllerMpd::parseTrackInfo May 11 18:04:46 rivo volumio[5577]: verbose: ControllerMpd::parseTrackInfo May 11 18:04:46 rivo volumio[5577]: info: ControllerMpd::pushState May 11 18:04:46 rivo volumio[5577]: info: CoreCommandRouter::servicePushState May 11 18:04:46 rivo volumio[5577]: info: CorePlayQueue::getTrack 0 May 11 18:04:46 rivo volumio[5577]: verbose: STATE SERVICE {"status":"play","position":0,"seek":251616,"duration":1455,"samplerate":"96 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"2862 Kbps","isStreaming":false,"title":"246596465","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=qobuz://song/246596465","trackType":"qobuz"} May 11 18:04:46 rivo volumio[5577]: verbose: CURRENT POSITION 0 May 11 18:04:46 rivo volumio[5577]: info: CoreStateMachine::syncState stateService play May 11 18:04:46 rivo volumio[5577]: info: CoreStateMachine::syncState currentStatus pause May 11 18:04:46 rivo volumio[5577]: info: CoreStateMachine::pushState May 11 18:04:46 rivo volumio[5577]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 11 18:04:46 rivo volumio[5577]: info: CoreCommandRouter::volumioPushState May 11 18:04:46 rivo volumio[5577]: info: MRS: Pushing multiroomSync output update for this device May 11 18:04:46 rivo volumio[5577]: info: MRS: Pushing multiroomSync output May 11 18:04:46 rivo volumio[5577]: info: ControllerMpd::pushState May 11 18:04:46 rivo volumio[5577]: info: CoreCommandRouter::servicePushState May 11 18:04:46 rivo volumio[5577]: info: CorePlayQueue::getTrack 0 May 11 18:04:46 rivo volumio[5577]: verbose: STATE SERVICE {"status":"play","position":0,"seek":251616,"duration":1455,"samplerate":"96 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"2862 Kbps","isStreaming":false,"title":"246596465","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=qobuz://song/246596465","trackType":"qobuz"} May 11 18:04:46 rivo volumio[5577]: verbose: CURRENT POSITION 0 May 11 18:04:46 rivo volumio[5577]: info: CoreStateMachine::syncState stateService play May 11 18:04:46 rivo volumio[5577]: info: CoreStateMachine::syncState currentStatus play May 11 18:04:46 rivo volumio[5577]: info: Received an update from plugin. extracting info from payload May 11 18:04:46 rivo volumio[5577]: info: CoreStateMachine::pushState May 11 18:04:46 rivo volumio[5577]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 11 18:04:46 rivo volumio[5577]: info: CoreCommandRouter::volumioPushState May 11 18:04:46 rivo volumio[5577]: info: MRS: Pushing multiroomSync output update for this device May 11 18:04:46 rivo volumio[5577]: info: MRS: Pushing multiroomSync output May 11 18:04:46 rivo volumio[5577]: info: CoreStateMachine::pushState May 11 18:04:46 rivo volumio[5577]: info: CoreCommandRouter::volumioPushState May 11 18:04:46 rivo volumio[5577]: info: MRS: Pushing multiroomSync output update for this device May 11 18:04:46 rivo volumio[5577]: info: MRS: Pushing multiroomSync output May 11 18:04:46 rivo volumio[5577]: info: ControllerMpd::pushState May 11 18:04:46 rivo volumio[5577]: info: CoreCommandRouter::servicePushState May 11 18:04:46 rivo volumio[5577]: info: CorePlayQueue::getTrack 0 May 11 18:04:46 rivo volumio[5577]: verbose: STATE SERVICE {"status":"play","position":0,"seek":251616,"duration":1455,"samplerate":"96 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"2862 Kbps","isStreaming":false,"title":"246596465","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=qobuz://song/246596465","trackType":"qobuz"} May 11 18:04:46 rivo volumio[5577]: verbose: CURRENT POSITION 0 May 11 18:04:46 rivo volumio[5577]: info: CoreStateMachine::syncState stateService play May 11 18:04:46 rivo volumio[5577]: info: CoreStateMachine::syncState currentStatus play May 11 18:04:46 rivo volumio[5577]: info: Received an update from plugin. extracting info from payload May 11 18:04:46 rivo volumio[5577]: info: CoreStateMachine::pushState May 11 18:04:46 rivo volumio[5577]: info: CoreCommandRouter::volumioPushState May 11 18:04:46 rivo volumio[5577]: info: MRS: Pushing multiroomSync output update for this device May 11 18:04:46 rivo volumio[5577]: info: MRS: Pushing multiroomSync output May 11 18:04:46 rivo volumio[5577]: info: CoreStateMachine::pushState May 11 18:04:46 rivo volumio[5577]: info: CoreCommandRouter::volumioPushState May 11 18:04:46 rivo volumio[5577]: info: MRS: Pushing multiroomSync output update for this device May 11 18:04:46 rivo volumio[5577]: info: MRS: Pushing multiroomSync output May 11 18:04:46 rivo volumio[5577]: info: ------------------------------ 110ms May 11 18:04:46 rivo volumio[5577]: info: ------------------------------ 107ms May 11 18:04:46 rivo volumio[5577]: info: ------------------------------ 103ms May 11 18:04:46 rivo volumio[5577]: info: Signalling Playback active due to playback status change May 11 18:04:46 rivo volumio[5577]: info: Updating RAAT Signal Path May 11 18:04:46 rivo volumio[5577]: info: Signalling Playback active due to playback status change May 11 18:04:46 rivo volumio[5577]: info: Updating RAAT Signal Path May 11 18:04:46 rivo volumio[5577]: info: MCU Signalled Playback Active May 11 18:04:46 rivo volumio[5577]: info: MCU Signalled Sleep Mode Disabled May 11 18:04:46 rivo volumio[5577]: info: Signalling Playback active due to playback status change May 11 18:04:46 rivo volumio[5577]: info: Signalling Playback active due to playback status change May 11 18:04:46 rivo volumio[5577]: info: Signalling Playback active due to playback status change May 11 18:04:46 rivo volumio[5577]: info: Updating RAAT Signal Path May 11 18:04:46 rivo volumio[5577]: info: Updating RAAT Signal Path May 11 18:04:46 rivo volumio[5577]: info: Updating RAAT Signal Path May 11 18:04:46 rivo sudo[7311]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/bin/xset dpms force on May 11 18:04:46 rivo sudo[7311]: pam_unix(sudo:session): session opened for user root by (uid=0) May 11 18:04:46 rivo sudo[7311]: pam_unix(sudo:session): session closed for user root May 11 18:04:46 rivo sudo[7314]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/bin/xset dpms 0 0 0 May 11 18:04:46 rivo sudo[7314]: pam_unix(sudo:session): session opened for user root by (uid=0) May 11 18:04:46 rivo sudo[7314]: pam_unix(sudo:session): session closed for user root May 11 18:04:59 rivo volumio[5577]: verbose: New Socket.io Connection to 192.168.1.123 from 192.168.1.111 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 16_7_7 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Total Clients: 8 May 11 18:04:59 rivo volumio[5577]: info: CoreCommandRouter::volumioGetState May 11 18:04:59 rivo volumio[5577]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom May 11 18:04:59 rivo volumio[5577]: info: Error : CoreCommandRouter::executeOnPlugin: No method [getMultiroom] in plugin multiroom May 11 18:04:59 rivo volumio[5577]: info: Listing playlists May 11 18:05:00 rivo volumio[5577]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings May 11 18:05:00 rivo volumio[5577]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined May 11 18:05:00 rivo volumio[5577]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates May 11 18:05:00 rivo volumio[5577]: info: Received Get System Version May 11 18:05:00 rivo volumio[5577]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 11 18:05:00 rivo volumio[5577]: info: Received Get System Info May 11 18:05:00 rivo volumio[5577]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 11 18:05:00 rivo volumio[5577]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 11 18:05:00 rivo volumio[5577]: info: Discovery: Getting this device information May 11 18:05:00 rivo volumio[5577]: info: CoreCommandRouter::volumioGetState May 11 18:05:00 rivo volumio[5577]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 11 18:05:09 rivo volumio[5577]: info: CoreCommandRouter::executeOnPlugin: system , getHwuuid May 11 18:05:09 rivo volumio[5577]: info: Pausing Remote Device: http://192.168.1.123 May 11 18:05:09 rivo volumio[5577]: info: May 11 18:05:09 rivo volumio[5577]: ---------------------------- Client requests Volumio pause May 11 18:05:09 rivo volumio[5577]: info: CoreCommandRouter::volumioPause May 11 18:05:09 rivo volumio[5577]: info: CoreStateMachine::pause May 11 18:05:09 rivo volumio[5577]: info: CoreStateMachine::stPlaybackTimer May 11 18:05:09 rivo volumio[5577]: info: CoreStateMachine::servicePause May 11 18:05:09 rivo volumio[5577]: info: CorePlayQueue::getTrack 0 May 11 18:05:09 rivo volumio[5577]: info: CoreCommandRouter::servicePause May 11 18:05:09 rivo volumio[5577]: info: [1715443509699] ControllerQobuz::pause May 11 18:05:09 rivo volumio[5577]: info: CoreStateMachine::setConsumeUpdateService mpd May 11 18:05:09 rivo volumio[5577]: info: ControllerMpd::pause May 11 18:05:09 rivo volumio[5577]: verbose: ControllerMpd::sendMpdCommand pause May 11 18:05:09 rivo volumio[5577]: info: May 11 18:05:09 rivo volumio[5577]: ---------------------------- MPD announces state update: player May 11 18:05:09 rivo volumio[5577]: info: sendMpdCommand pause took 8 milliseconds May 11 18:05:09 rivo volumio[5577]: info: ControllerMpd::getState May 11 18:05:09 rivo volumio[5577]: verbose: ControllerMpd::sendMpdCommand status May 11 18:05:09 rivo volumio[5577]: info: May 11 18:05:09 rivo volumio[5577]: ---------------------------- MPD announces state update: player May 11 18:05:09 rivo volumio[5577]: info: ControllerMpd::getState May 11 18:05:09 rivo volumio[5577]: verbose: ControllerMpd::sendMpdCommand status May 11 18:05:09 rivo volumio[5577]: info: May 11 18:05:09 rivo volumio[5577]: ---------------------------- MPD announces state update: player May 11 18:05:09 rivo volumio[5577]: info: ControllerMpd::getState May 11 18:05:09 rivo volumio[5577]: verbose: ControllerMpd::sendMpdCommand status May 11 18:05:09 rivo volumio[5577]: info: sendMpdCommand status took 11 milliseconds May 11 18:05:09 rivo volumio[5577]: info: sendMpdCommand status took 5 milliseconds May 11 18:05:09 rivo volumio[5577]: info: sendMpdCommand status took 3 milliseconds May 11 18:05:09 rivo volumio[5577]: verbose: ControllerMpd::parseState May 11 18:05:09 rivo volumio[5577]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 11 18:05:09 rivo volumio[5577]: verbose: ControllerMpd::parseState May 11 18:05:09 rivo volumio[5577]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 11 18:05:09 rivo volumio[5577]: verbose: ControllerMpd::parseState May 11 18:05:09 rivo volumio[5577]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 11 18:05:09 rivo volumio[5577]: info: Done pausing: May 11 18:05:09 rivo volumio[5577]: info: sendMpdCommand playlistinfo took 8 milliseconds May 11 18:05:09 rivo volumio[5577]: info: sendMpdCommand playlistinfo took 7 milliseconds May 11 18:05:09 rivo volumio[5577]: info: sendMpdCommand playlistinfo took 8 milliseconds May 11 18:05:09 rivo volumio[5577]: verbose: ControllerMpd::parseTrackInfo May 11 18:05:09 rivo volumio[5577]: verbose: ControllerMpd::parseTrackInfo May 11 18:05:09 rivo volumio[5577]: verbose: ControllerMpd::parseTrackInfo May 11 18:05:09 rivo volumio[5577]: info: ControllerMpd::pushState May 11 18:05:09 rivo volumio[5577]: info: CoreCommandRouter::servicePushState May 11 18:05:09 rivo volumio[5577]: info: CorePlayQueue::getTrack 0 May 11 18:05:09 rivo volumio[5577]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":275241,"duration":1455,"samplerate":"96 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"2361 Kbps","isStreaming":false,"title":"246596465","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=qobuz://song/246596465","trackType":"qobuz"} May 11 18:05:09 rivo volumio[5577]: verbose: CURRENT POSITION 0 May 11 18:05:09 rivo volumio[5577]: info: CoreStateMachine::syncState stateService pause May 11 18:05:09 rivo volumio[5577]: info: CoreStateMachine::syncState currentStatus pause May 11 18:05:09 rivo volumio[5577]: info: CoreStateMachine::pushState May 11 18:05:09 rivo volumio[5577]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 11 18:05:09 rivo volumio[5577]: info: CoreCommandRouter::volumioPushState May 11 18:05:09 rivo volumio[5577]: info: MRS: Pushing multiroomSync output update for this device May 11 18:05:09 rivo volumio[5577]: info: MRS: Pushing multiroomSync output May 11 18:05:09 rivo volumio[5577]: info: CoreStateMachine::stPlaybackTimer May 11 18:05:09 rivo volumio[5577]: info: ControllerMpd::pushState May 11 18:05:09 rivo volumio[5577]: info: CoreCommandRouter::servicePushState May 11 18:05:09 rivo volumio[5577]: info: CorePlayQueue::getTrack 0 May 11 18:05:09 rivo volumio[5577]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":275241,"duration":1455,"samplerate":"96 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"2361 Kbps","isStreaming":false,"title":"246596465","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=qobuz://song/246596465","trackType":"qobuz"} May 11 18:05:09 rivo volumio[5577]: verbose: CURRENT POSITION 0 May 11 18:05:09 rivo volumio[5577]: info: CoreStateMachine::syncState stateService pause May 11 18:05:09 rivo volumio[5577]: info: CoreStateMachine::syncState currentStatus pause May 11 18:05:09 rivo volumio[5577]: info: CoreStateMachine::pushState May 11 18:05:09 rivo volumio[5577]: info: CoreCommandRouter::volumioPushState May 11 18:05:09 rivo volumio[5577]: info: MRS: Pushing multiroomSync output update for this device May 11 18:05:09 rivo volumio[5577]: info: MRS: Pushing multiroomSync output May 11 18:05:09 rivo volumio[5577]: info: CoreStateMachine::stPlaybackTimer May 11 18:05:09 rivo volumio[5577]: info: ControllerMpd::pushState May 11 18:05:09 rivo volumio[5577]: info: CoreCommandRouter::servicePushState May 11 18:05:09 rivo volumio[5577]: info: CorePlayQueue::getTrack 0 May 11 18:05:09 rivo volumio[5577]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":275241,"duration":1455,"samplerate":"96 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"2361 Kbps","isStreaming":false,"title":"246596465","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=qobuz://song/246596465","trackType":"qobuz"} May 11 18:05:09 rivo volumio[5577]: verbose: CURRENT POSITION 0 May 11 18:05:09 rivo volumio[5577]: info: CoreStateMachine::syncState stateService pause May 11 18:05:09 rivo volumio[5577]: info: CoreStateMachine::syncState currentStatus pause May 11 18:05:09 rivo volumio[5577]: info: CoreStateMachine::pushState May 11 18:05:09 rivo volumio[5577]: info: CoreCommandRouter::volumioPushState May 11 18:05:09 rivo volumio[5577]: info: MRS: Pushing multiroomSync output update for this device May 11 18:05:09 rivo volumio[5577]: info: MRS: Pushing multiroomSync output May 11 18:05:09 rivo volumio[5577]: info: CoreStateMachine::stPlaybackTimer May 11 18:05:09 rivo volumio[5577]: info: ------------------------------ 69ms May 11 18:05:09 rivo volumio[5577]: info: ------------------------------ 62ms May 11 18:05:09 rivo volumio[5577]: info: ------------------------------ 61ms May 11 18:05:09 rivo volumio[5577]: info: Updating RAAT Signal Path May 11 18:05:09 rivo volumio[5577]: info: Updating RAAT Signal Path May 11 18:05:09 rivo volumio[5577]: info: Updating RAAT Signal Path May 11 18:05:09 rivo volumio[5577]: info: MCU Signalled Playback Inactive May 11 18:05:12 rivo volumio[5577]: info: CoreCommandRouter::executeOnPlugin: system , getHwuuid May 11 18:05:12 rivo volumio[5577]: info: Playing Remote Device: http://192.168.1.123 May 11 18:05:12 rivo volumio[5577]: info: May 11 18:05:12 rivo volumio[5577]: ---------------------------- Client requests Volumio play May 11 18:05:12 rivo volumio[5577]: info: CoreCommandRouter::volumioPlay May 11 18:05:12 rivo volumio[5577]: info: CoreStateMachine::play index undefined May 11 18:05:12 rivo volumio[5577]: info: CoreStateMachine::setConsumeUpdateService undefined May 11 18:05:12 rivo volumio[5577]: info: CorePlayQueue::getTrack 0 May 11 18:05:12 rivo volumio[5577]: info: CoreStateMachine::startPlaybackTimer May 11 18:05:12 rivo volumio[5577]: info: CorePlayQueue::getTrack 0 May 11 18:05:12 rivo volumio[5577]: info: [1715443512545] ControllerQobuz::resume May 11 18:05:12 rivo volumio[5577]: info: CoreStateMachine::setConsumeUpdateService mpd May 11 18:05:12 rivo volumio[5577]: info: ControllerMpd::resume May 11 18:05:12 rivo volumio[5577]: verbose: ControllerMpd::sendMpdCommand play May 11 18:05:12 rivo volumio[5577]: info: Done playing: May 11 18:05:12 rivo volumio[5577]: info: sendMpdCommand play took 37 milliseconds May 11 18:05:12 rivo volumio[5577]: info: May 11 18:05:12 rivo volumio[5577]: ---------------------------- MPD announces state update: player May 11 18:05:12 rivo volumio[5577]: info: ControllerMpd::getState May 11 18:05:12 rivo volumio[5577]: verbose: ControllerMpd::sendMpdCommand status May 11 18:05:12 rivo volumio[5577]: info: May 11 18:05:12 rivo volumio[5577]: ---------------------------- MPD announces state update: player May 11 18:05:12 rivo volumio[5577]: info: ControllerMpd::getState May 11 18:05:12 rivo volumio[5577]: verbose: ControllerMpd::sendMpdCommand status May 11 18:05:12 rivo volumio[5577]: info: May 11 18:05:12 rivo volumio[5577]: ---------------------------- MPD announces state update: player May 11 18:05:12 rivo volumio[5577]: info: ControllerMpd::getState May 11 18:05:12 rivo volumio[5577]: verbose: ControllerMpd::sendMpdCommand status May 11 18:05:12 rivo volumio[5577]: info: sendMpdCommand status took 6 milliseconds May 11 18:05:12 rivo volumio[5577]: info: sendMpdCommand status took 4 milliseconds May 11 18:05:12 rivo volumio[5577]: info: sendMpdCommand status took 3 milliseconds May 11 18:05:12 rivo volumio[5577]: verbose: ControllerMpd::parseState May 11 18:05:12 rivo volumio[5577]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 11 18:05:12 rivo volumio[5577]: verbose: ControllerMpd::parseState May 11 18:05:12 rivo volumio[5577]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 11 18:05:12 rivo volumio[5577]: verbose: ControllerMpd::parseState May 11 18:05:12 rivo volumio[5577]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 11 18:05:12 rivo volumio[5577]: info: sendMpdCommand playlistinfo took 5 milliseconds May 11 18:05:12 rivo volumio[5577]: info: sendMpdCommand playlistinfo took 4 milliseconds May 11 18:05:12 rivo volumio[5577]: verbose: ControllerMpd::parseTrackInfo May 11 18:05:12 rivo volumio[5577]: verbose: ControllerMpd::parseTrackInfo May 11 18:05:12 rivo volumio[5577]: verbose: ControllerMpd::parseTrackInfo May 11 18:05:12 rivo volumio[5577]: info: ControllerMpd::pushState May 11 18:05:12 rivo volumio[5577]: info: CoreCommandRouter::servicePushState May 11 18:05:12 rivo volumio[5577]: info: CorePlayQueue::getTrack 0 May 11 18:05:12 rivo volumio[5577]: verbose: STATE SERVICE {"status":"play","position":0,"seek":275462,"duration":1455,"samplerate":"96 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"2362 Kbps","isStreaming":false,"title":"246596465","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=qobuz://song/246596465","trackType":"qobuz"} May 11 18:05:12 rivo volumio[5577]: verbose: CURRENT POSITION 0 May 11 18:05:12 rivo volumio[5577]: info: CoreStateMachine::syncState stateService play May 11 18:05:12 rivo volumio[5577]: info: CoreStateMachine::syncState currentStatus pause May 11 18:05:12 rivo volumio[5577]: info: CoreStateMachine::pushState May 11 18:05:12 rivo volumio[5577]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 11 18:05:12 rivo volumio[5577]: info: CoreCommandRouter::volumioPushState May 11 18:05:12 rivo volumio[5577]: info: MRS: Pushing multiroomSync output update for this device May 11 18:05:12 rivo volumio[5577]: info: MRS: Pushing multiroomSync output May 11 18:05:12 rivo volumio[5577]: info: ControllerMpd::pushState May 11 18:05:12 rivo volumio[5577]: info: CoreCommandRouter::servicePushState May 11 18:05:12 rivo volumio[5577]: info: CorePlayQueue::getTrack 0 May 11 18:05:12 rivo volumio[5577]: verbose: STATE SERVICE {"status":"play","position":0,"seek":275577,"duration":1455,"samplerate":"96 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"2365 Kbps","isStreaming":false,"title":"246596465","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=qobuz://song/246596465","trackType":"qobuz"} May 11 18:05:12 rivo volumio[5577]: verbose: CURRENT POSITION 0 May 11 18:05:12 rivo volumio[5577]: info: CoreStateMachine::syncState stateService play May 11 18:05:12 rivo volumio[5577]: info: CoreStateMachine::syncState currentStatus play May 11 18:05:12 rivo volumio[5577]: info: Received an update from plugin. extracting info from payload May 11 18:05:12 rivo volumio[5577]: info: CoreStateMachine::pushState May 11 18:05:12 rivo volumio[5577]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 11 18:05:12 rivo volumio[5577]: info: CoreCommandRouter::volumioPushState May 11 18:05:12 rivo volumio[5577]: info: MRS: Pushing multiroomSync output update for this device May 11 18:05:12 rivo volumio[5577]: info: MRS: Pushing multiroomSync output May 11 18:05:12 rivo volumio[5577]: info: CoreStateMachine::pushState May 11 18:05:12 rivo volumio[5577]: info: CoreCommandRouter::volumioPushState May 11 18:05:12 rivo volumio[5577]: info: MRS: Pushing multiroomSync output update for this device May 11 18:05:12 rivo volumio[5577]: info: MRS: Pushing multiroomSync output May 11 18:05:12 rivo volumio[5577]: info: ControllerMpd::pushState May 11 18:05:12 rivo volumio[5577]: info: CoreCommandRouter::servicePushState May 11 18:05:12 rivo volumio[5577]: info: CorePlayQueue::getTrack 0 May 11 18:05:12 rivo volumio[5577]: verbose: STATE SERVICE {"status":"play","position":0,"seek":275656,"duration":1455,"samplerate":"96 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"2364 Kbps","isStreaming":false,"title":"246596465","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=qobuz://song/246596465","trackType":"qobuz"} May 11 18:05:12 rivo volumio[5577]: verbose: CURRENT POSITION 0 May 11 18:05:12 rivo volumio[5577]: info: CoreStateMachine::syncState stateService play May 11 18:05:12 rivo volumio[5577]: info: CoreStateMachine::syncState currentStatus play May 11 18:05:12 rivo volumio[5577]: info: Received an update from plugin. extracting info from payload May 11 18:05:12 rivo volumio[5577]: info: CoreStateMachine::pushState May 11 18:05:12 rivo volumio[5577]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 11 18:05:12 rivo volumio[5577]: info: CoreCommandRouter::volumioPushState May 11 18:05:12 rivo volumio[5577]: info: MRS: Pushing multiroomSync output update for this device May 11 18:05:12 rivo volumio[5577]: info: MRS: Pushing multiroomSync output May 11 18:05:12 rivo volumio[5577]: info: CoreStateMachine::pushState May 11 18:05:12 rivo volumio[5577]: info: CoreCommandRouter::volumioPushState May 11 18:05:12 rivo volumio[5577]: info: MRS: Pushing multiroomSync output update for this device May 11 18:05:12 rivo volumio[5577]: info: MRS: Pushing multiroomSync output May 11 18:05:12 rivo volumio[5577]: info: ------------------------------ 84ms May 11 18:05:12 rivo volumio[5577]: info: ------------------------------ 83ms May 11 18:05:12 rivo volumio[5577]: info: ------------------------------ 82ms May 11 18:05:12 rivo volumio[5577]: info: Signalling Playback active due to playback status change May 11 18:05:12 rivo volumio[5577]: info: Updating RAAT Signal Path May 11 18:05:12 rivo volumio[5577]: info: Signalling Playback active due to playback status change May 11 18:05:12 rivo volumio[5577]: info: Updating RAAT Signal Path May 11 18:05:12 rivo volumio[5577]: info: MCU Signalled Playback Active May 11 18:05:12 rivo volumio[5577]: info: Signalling Playback active due to playback status change May 11 18:05:12 rivo volumio[5577]: info: Signalling Playback active due to playback status change May 11 18:05:12 rivo volumio[5577]: info: Updating RAAT Signal Path May 11 18:05:12 rivo volumio[5577]: info: Updating RAAT Signal Path May 11 18:05:12 rivo volumio[5577]: info: Signalling Playback active due to playback status change May 11 18:05:12 rivo volumio[5577]: info: Updating RAAT Signal Path May 11 18:05:16 rivo volumio[5577]: info: CoreCommandRouter::executeOnPlugin: system , getHwuuid May 11 18:05:16 rivo volumio[5577]: info: Pausing Remote Device: http://192.168.1.123 May 11 18:05:16 rivo volumio[5577]: info: May 11 18:05:16 rivo volumio[5577]: ---------------------------- Client requests Volumio pause May 11 18:05:16 rivo volumio[5577]: info: CoreCommandRouter::volumioPause May 11 18:05:16 rivo volumio[5577]: info: CoreStateMachine::pause May 11 18:05:16 rivo volumio[5577]: info: CoreStateMachine::stPlaybackTimer May 11 18:05:16 rivo volumio[5577]: info: CoreStateMachine::servicePause May 11 18:05:16 rivo volumio[5577]: info: CorePlayQueue::getTrack 0 May 11 18:05:16 rivo volumio[5577]: info: CoreCommandRouter::servicePause May 11 18:05:16 rivo volumio[5577]: info: [1715443516293] ControllerQobuz::pause May 11 18:05:16 rivo volumio[5577]: info: CoreStateMachine::setConsumeUpdateService mpd May 11 18:05:16 rivo volumio[5577]: info: ControllerMpd::pause May 11 18:05:16 rivo volumio[5577]: verbose: ControllerMpd::sendMpdCommand pause May 11 18:05:16 rivo volumio[5577]: info: sendMpdCommand pause took 3 milliseconds May 11 18:05:16 rivo volumio[5577]: info: May 11 18:05:16 rivo volumio[5577]: ---------------------------- MPD announces state update: player May 11 18:05:16 rivo volumio[5577]: info: ControllerMpd::getState May 11 18:05:16 rivo volumio[5577]: verbose: ControllerMpd::sendMpdCommand status May 11 18:05:16 rivo volumio[5577]: info: May 11 18:05:16 rivo volumio[5577]: ---------------------------- MPD announces state update: player May 11 18:05:16 rivo volumio[5577]: info: ControllerMpd::getState May 11 18:05:16 rivo volumio[5577]: verbose: ControllerMpd::sendMpdCommand status May 11 18:05:16 rivo volumio[5577]: info: May 11 18:05:16 rivo volumio[5577]: ---------------------------- MPD announces state update: player May 11 18:05:16 rivo volumio[5577]: info: ControllerMpd::getState May 11 18:05:16 rivo volumio[5577]: verbose: ControllerMpd::sendMpdCommand status May 11 18:05:16 rivo volumio[5577]: info: Done pausing: May 11 18:05:16 rivo volumio[5577]: info: sendMpdCommand status took 11 milliseconds May 11 18:05:16 rivo volumio[5577]: info: sendMpdCommand status took 8 milliseconds May 11 18:05:16 rivo volumio[5577]: info: sendMpdCommand status took 6 milliseconds May 11 18:05:16 rivo volumio[5577]: verbose: ControllerMpd::parseState May 11 18:05:16 rivo volumio[5577]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 11 18:05:16 rivo volumio[5577]: verbose: ControllerMpd::parseState May 11 18:05:16 rivo volumio[5577]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 11 18:05:16 rivo volumio[5577]: verbose: ControllerMpd::parseState May 11 18:05:16 rivo volumio[5577]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 11 18:05:16 rivo volumio[5577]: info: sendMpdCommand playlistinfo took 5 milliseconds May 11 18:05:16 rivo volumio[5577]: info: sendMpdCommand playlistinfo took 4 milliseconds May 11 18:05:16 rivo volumio[5577]: info: sendMpdCommand playlistinfo took 5 milliseconds May 11 18:05:16 rivo volumio[5577]: verbose: ControllerMpd::parseTrackInfo May 11 18:05:16 rivo volumio[5577]: verbose: ControllerMpd::parseTrackInfo May 11 18:05:16 rivo volumio[5577]: verbose: ControllerMpd::parseTrackInfo May 11 18:05:16 rivo volumio[5577]: info: ControllerMpd::pushState May 11 18:05:16 rivo volumio[5577]: info: CoreCommandRouter::servicePushState May 11 18:05:16 rivo volumio[5577]: info: CorePlayQueue::getTrack 0 May 11 18:05:16 rivo volumio[5577]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":280365,"duration":1455,"samplerate":"96 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"2585 Kbps","isStreaming":false,"title":"246596465","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=qobuz://song/246596465","trackType":"qobuz"} May 11 18:05:16 rivo volumio[5577]: verbose: CURRENT POSITION 0 May 11 18:05:16 rivo volumio[5577]: info: CoreStateMachine::syncState stateService pause May 11 18:05:16 rivo volumio[5577]: info: CoreStateMachine::syncState currentStatus pause May 11 18:05:16 rivo volumio[5577]: info: CoreStateMachine::pushState May 11 18:05:16 rivo volumio[5577]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 11 18:05:16 rivo volumio[5577]: info: CoreCommandRouter::volumioPushState May 11 18:05:16 rivo volumio[5577]: info: MRS: Pushing multiroomSync output update for this device May 11 18:05:16 rivo volumio[5577]: info: MRS: Pushing multiroomSync output May 11 18:05:16 rivo volumio[5577]: info: CoreStateMachine::stPlaybackTimer May 11 18:05:16 rivo volumio[5577]: info: ControllerMpd::pushState May 11 18:05:16 rivo volumio[5577]: info: CoreCommandRouter::servicePushState May 11 18:05:16 rivo volumio[5577]: info: CorePlayQueue::getTrack 0 May 11 18:05:16 rivo volumio[5577]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":280365,"duration":1455,"samplerate":"96 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"2585 Kbps","isStreaming":false,"title":"246596465","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=qobuz://song/246596465","trackType":"qobuz"} May 11 18:05:16 rivo volumio[5577]: verbose: CURRENT POSITION 0 May 11 18:05:16 rivo volumio[5577]: info: CoreStateMachine::syncState stateService pause May 11 18:05:16 rivo volumio[5577]: info: CoreStateMachine::syncState currentStatus pause May 11 18:05:16 rivo volumio[5577]: info: CoreStateMachine::pushState May 11 18:05:16 rivo volumio[5577]: info: CoreCommandRouter::volumioPushState May 11 18:05:16 rivo volumio[5577]: info: MRS: Pushing multiroomSync output update for this device May 11 18:05:16 rivo volumio[5577]: info: MRS: Pushing multiroomSync output May 11 18:05:16 rivo volumio[5577]: info: CoreStateMachine::stPlaybackTimer May 11 18:05:16 rivo volumio[5577]: info: ControllerMpd::pushState May 11 18:05:16 rivo volumio[5577]: info: CoreCommandRouter::servicePushState May 11 18:05:16 rivo volumio[5577]: info: CorePlayQueue::getTrack 0 May 11 18:05:16 rivo volumio[5577]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":280365,"duration":1455,"samplerate":"96 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"2585 Kbps","isStreaming":false,"title":"246596465","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=qobuz://song/246596465","trackType":"qobuz"} May 11 18:05:16 rivo volumio[5577]: verbose: CURRENT POSITION 0 May 11 18:05:16 rivo volumio[5577]: info: CoreStateMachine::syncState stateService pause May 11 18:05:16 rivo volumio[5577]: info: CoreStateMachine::syncState currentStatus pause May 11 18:05:16 rivo volumio[5577]: info: CoreStateMachine::pushState May 11 18:05:16 rivo volumio[5577]: info: CoreCommandRouter::volumioPushState May 11 18:05:16 rivo volumio[5577]: info: MRS: Pushing multiroomSync output update for this device May 11 18:05:16 rivo volumio[5577]: info: MRS: Pushing multiroomSync output May 11 18:05:16 rivo volumio[5577]: info: CoreStateMachine::stPlaybackTimer May 11 18:05:16 rivo volumio[5577]: info: ------------------------------ 65ms May 11 18:05:16 rivo volumio[5577]: info: ------------------------------ 62ms May 11 18:05:16 rivo volumio[5577]: info: ------------------------------ 59ms May 11 18:05:16 rivo volumio[5577]: info: Updating RAAT Signal Path May 11 18:05:16 rivo volumio[5577]: info: MCU Signalled Playback Inactive May 11 18:05:16 rivo volumio[5577]: info: Updating RAAT Signal Path May 11 18:05:16 rivo volumio[5577]: info: Updating RAAT Signal Path May 11 18:05:17 rivo volumio[5577]: info: CoreCommandRouter::executeOnPlugin: multiroom , audioOutputPlay May 11 18:05:17 rivo volumio[5577]: info: Error : CoreCommandRouter::executeOnPlugin: No method [audioOutputPlay] in plugin multiroom May 11 18:05:17 rivo volumio[5577]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 11 18:05:17 rivo volumio[5577]: TypeError: Cannot read property 'then' of undefined May 11 18:05:17 rivo volumio[5577]: at outputs.audioOutputPlay (/volumio/app/plugins/audio_interface/outputs/index.js:367:9) May 11 18:05:17 rivo volumio[5577]: at CoreCommandRouter.audioOutputPlay (/volumio/app/index.js:2249:30) May 11 18:05:17 rivo volumio[5577]: at Socket. (/volumio/app/plugins/user_interface/websocket/index.js:1414:26) May 11 18:05:17 rivo volumio[5577]: at Socket.emit (events.js:400:28) May 11 18:05:17 rivo volumio[5577]: at /volumio/node_modules/socket.io/lib/socket.js:503:12 May 11 18:05:17 rivo volumio[5577]: at processTicksAndRejections (internal/process/task_queues.js:77:11) May 11 18:05:17 rivo volumio[5577]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 11 18:05:18 rivo sudo[7388]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-05-11 18:04 May 11 18:05:18 rivo sudo[7388]: 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="e7445fab547cd22e23d9bef72406cfb610bc1d7d" VOLUMIO_FE_VERSION="5d5e99f8f803b3ec5fc5e8ca13bb4023600f3eee" VOLUMIO_FE3_VERSION="a6ae210575eae1ff43f06ab71e1cd17576840623" VOLUMIO_BE_VERSION="a9e1e1dd6072ffb15c0fcb8938d9ea0d8900c0da" VOLUMIO_ARCH="armv7" VOLUMIO_VARIANT="rivo" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Wed 24 Apr 2024 02:56:04 PM CEST" VOLUMIO_VERSION="3.661" VOLUMIO_HARDWARE="mp1" VOLUMIO_DEVICENAME="Volumio MP1" VOLUMIO_VENDOR_MODEL="Volumio Rivo" VOLUMIO_VENDOR="Volumio" VOLUMIO_MODEL="Rivo" VOLUMIO_HASH="4aa444b01074e57a72574e89142e3734"