-- Logs begin at Fri 2026-03-06 03:13:27 JST, end at Sun 2026-03-29 16:50:06 JST. -- Mar 29 16:49:00 rivoplus volumio5-onboarding[4570]: time=2026-03-29T16:49:00.892+09:00 level=INFO msg="new address was allocated" component=ble/conn old=32 new=33 Mar 29 16:49:01 rivoplus dbus-daemon[2834]: [system] Rejected send message, 1 matched rules; type="error", sender=":1.54" (uid=0 pid=4570 comm="/usr/bin/volumio5-onboarding " label="kernel") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.7" (uid=0 pid=3313 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap,hostn" label="kernel") Mar 29 16:49:01 rivoplus dbus-daemon[2834]: [system] Rejected send message, 1 matched rules; type="error", sender=":1.54" (uid=0 pid=4570 comm="/usr/bin/volumio5-onboarding " label="kernel") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.7" (uid=0 pid=3313 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap,hostn" label="kernel") Mar 29 16:49:05 rivoplus volumio5-onboarding[4570]: time=2026-03-29T16:49:05.003+09:00 level=INFO msg="new address was allocated" component=ble/conn old=33 new=34 Mar 29 16:49:05 rivoplus dbus-daemon[2834]: [system] Rejected send message, 1 matched rules; type="error", sender=":1.54" (uid=0 pid=4570 comm="/usr/bin/volumio5-onboarding " label="kernel") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.7" (uid=0 pid=3313 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap,hostn" label="kernel") Mar 29 16:49:05 rivoplus dbus-daemon[2834]: [system] Rejected send message, 1 matched rules; type="error", sender=":1.54" (uid=0 pid=4570 comm="/usr/bin/volumio5-onboarding " label="kernel") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.7" (uid=0 pid=3313 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap,hostn" label="kernel") Mar 29 16:49:08 rivoplus volumio5-onboarding[4570]: time=2026-03-29T16:49:08.992+09:00 level=INFO msg="new address was allocated" component=ble/conn old=34 new=35 Mar 29 16:49:09 rivoplus dbus-daemon[2834]: [system] Rejected send message, 1 matched rules; type="error", sender=":1.54" (uid=0 pid=4570 comm="/usr/bin/volumio5-onboarding " label="kernel") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.7" (uid=0 pid=3313 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap,hostn" label="kernel") Mar 29 16:49:09 rivoplus dbus-daemon[2834]: [system] Rejected send message, 1 matched rules; type="error", sender=":1.54" (uid=0 pid=4570 comm="/usr/bin/volumio5-onboarding " label="kernel") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.7" (uid=0 pid=3313 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap,hostn" label="kernel") Mar 29 16:49:12 rivoplus volumio[3182]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Mar 29 16:49:12 rivoplus volumio[3182]: info: Received Get System Info Mar 29 16:49:12 rivoplus volumio[3182]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 29 16:49:12 rivoplus volumio[3182]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 29 16:49:12 rivoplus volumio[3182]: info: Discovery: Getting this device information Mar 29 16:49:12 rivoplus volumio[3182]: info: CoreCommandRouter::volumioGetState Mar 29 16:49:12 rivoplus volumio[3182]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 29 16:49:13 rivoplus volumio5-onboarding[4570]: time=2026-03-29T16:49:13.035+09:00 level=INFO msg="new address was allocated" component=ble/conn old=35 new=36 Mar 29 16:49:13 rivoplus dbus-daemon[2834]: [system] Rejected send message, 1 matched rules; type="error", sender=":1.54" (uid=0 pid=4570 comm="/usr/bin/volumio5-onboarding " label="kernel") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.7" (uid=0 pid=3313 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap,hostn" label="kernel") Mar 29 16:49:13 rivoplus dbus-daemon[2834]: [system] Rejected send message, 1 matched rules; type="error", sender=":1.54" (uid=0 pid=4570 comm="/usr/bin/volumio5-onboarding " label="kernel") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.7" (uid=0 pid=3313 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap,hostn" label="kernel") Mar 29 16:49:13 rivoplus volumio[3182]: info: Mar 29 16:49:13 rivoplus volumio[3182]: ---------------------------- MPD announces state update: player Mar 29 16:49:13 rivoplus volumio[3182]: info: ControllerMpd::getState Mar 29 16:49:13 rivoplus volumio[3182]: verbose: ControllerMpd::sendMpdCommand status Mar 29 16:49:13 rivoplus volumio[3182]: info: Mar 29 16:49:13 rivoplus volumio[3182]: ---------------------------- MPD announces state update: player Mar 29 16:49:13 rivoplus volumio[3182]: info: ControllerMpd::getState Mar 29 16:49:13 rivoplus volumio[3182]: verbose: ControllerMpd::sendMpdCommand status Mar 29 16:49:13 rivoplus volumio[3182]: info: sendMpdCommand status took 5 milliseconds Mar 29 16:49:13 rivoplus volumio[3182]: info: sendMpdCommand status took 3 milliseconds Mar 29 16:49:13 rivoplus volumio[3182]: verbose: ControllerMpd::parseState Mar 29 16:49:13 rivoplus volumio[3182]: verbose: ControllerMpd::parseState Mar 29 16:49:13 rivoplus volumio[3182]: info: ControllerMpd::pushState Mar 29 16:49:13 rivoplus volumio[3182]: info: CoreCommandRouter::servicePushState Mar 29 16:49:13 rivoplus volumio[3182]: info: CoreStateMachine::pushState Mar 29 16:49:13 rivoplus volumio[3182]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 29 16:49:13 rivoplus volumio[3182]: info: CoreCommandRouter::volumioPushState Mar 29 16:49:13 rivoplus volumio[3182]: info: CoreCommandRouter::volumioGetState Mar 29 16:49:13 rivoplus volumio[3182]: info: MRS: Pushing multiroomSync output update for this device Mar 29 16:49:13 rivoplus volumio[3182]: info: MRS: Pushing multiroomSync output Mar 29 16:49:13 rivoplus volumio[3182]: info: CorePlayQueue::getTrack 0 Mar 29 16:49:13 rivoplus volumio[3182]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Mar 29 16:49:13 rivoplus volumio[3182]: verbose: CURRENT POSITION 0 Mar 29 16:49:13 rivoplus volumio[3182]: info: CoreStateMachine::syncState stateService stop Mar 29 16:49:13 rivoplus volumio[3182]: info: CoreStateMachine::syncState currentStatus play Mar 29 16:49:13 rivoplus volumio[3182]: info: CoreStateMachine::play index undefined Mar 29 16:49:13 rivoplus volumio[3182]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 29 16:49:13 rivoplus volumio[3182]: info: CoreStateMachine::pushState Mar 29 16:49:13 rivoplus volumio[3182]: info: CorePlayQueue::getTrack 1 Mar 29 16:49:13 rivoplus volumio[3182]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 29 16:49:13 rivoplus volumio[3182]: info: CoreCommandRouter::volumioPushState Mar 29 16:49:13 rivoplus volumio[3182]: info: CoreCommandRouter::volumioGetState Mar 29 16:49:13 rivoplus volumio[3182]: info: CorePlayQueue::getTrack 1 Mar 29 16:49:13 rivoplus volumio[3182]: info: MRS: Pushing multiroomSync output update for this device Mar 29 16:49:13 rivoplus volumio[3182]: info: MRS: Pushing multiroomSync output Mar 29 16:49:13 rivoplus volumio[3182]: info: ControllerMpd::pushState Mar 29 16:49:13 rivoplus volumio[3182]: info: CoreCommandRouter::servicePushState Mar 29 16:49:13 rivoplus volumio[3182]: info: CoreStateMachine::pushState Mar 29 16:49:13 rivoplus volumio[3182]: info: CorePlayQueue::getTrack 1 Mar 29 16:49:13 rivoplus volumio[3182]: info: CoreCommandRouter::volumioPushState Mar 29 16:49:13 rivoplus volumio[3182]: info: CoreCommandRouter::volumioGetState Mar 29 16:49:13 rivoplus volumio[3182]: info: CorePlayQueue::getTrack 1 Mar 29 16:49:13 rivoplus volumio[3182]: info: MRS: Pushing multiroomSync output update for this device Mar 29 16:49:13 rivoplus volumio[3182]: info: MRS: Pushing multiroomSync output Mar 29 16:49:13 rivoplus volumio[3182]: info: CorePlayQueue::getTrack 1 Mar 29 16:49:13 rivoplus volumio[3182]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current qobuz Received mpd Mar 29 16:49:13 rivoplus volumio5-onboarding[4570]: time=2026-03-29T16:49:13.993+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.104.226:63231 @ 0x22e4b40" state=STATUS_PLAYING positionMs=29794 volume=100 Mar 29 16:49:13 rivoplus volumio5-onboarding[4570]: time=2026-03-29T16:49:13.994+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.104.226:63231 @ 0x22e4b40" id=qobuz://song/291519744 title="Home At Last (Down By The Salley Gardens) (96kHz/24bit)" Mar 29 16:49:13 rivoplus volumio5-onboarding[4570]: time=2026-03-29T16:49:13.995+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.104.226:63231 @ 0x22e4b40" state=STATUS_STOPPED positionMs= volume=100 Mar 29 16:49:13 rivoplus volumio5-onboarding[4570]: time=2026-03-29T16:49:13.995+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.104.226:63231 @ 0x22e4b40" id=qobuz://song/291519745 title="Lullabye (Goodnight, My Angel) (96kHz/24bit)" Mar 29 16:49:13 rivoplus volumio5-onboarding[4570]: time=2026-03-29T16:49:13.996+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.104.226:63231 @ 0x22e4b40" state=STATUS_STOPPED positionMs= volume=100 Mar 29 16:49:13 rivoplus volumio5-onboarding[4570]: time=2026-03-29T16:49:13.997+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.104.226:63231 @ 0x22e4b40" id=qobuz://song/291519745 title="Lullabye (Goodnight, My Angel) (96kHz/24bit)" Mar 29 16:49:14 rivoplus volumio[3182]: info: CorePlayQueue::getTrack 1 Mar 29 16:49:14 rivoplus volumio[3182]: info: CoreStateMachine::startPlaybackTimer Mar 29 16:49:14 rivoplus volumio[3182]: info: CorePlayQueue::getTrack 1 Mar 29 16:49:14 rivoplus volumio[3182]: info: [1774770554012] ControllerQobuz::clearAddPlayTrack Mar 29 16:49:14 rivoplus volumio[3182]: info: ------------------------------ 107ms Mar 29 16:49:14 rivoplus volumio[3182]: info: ------------------------------ 105ms Mar 29 16:49:14 rivoplus volumio[3182]: verbose: ControllerMpd::sendMpdCommand stop Mar 29 16:49:14 rivoplus volumio[3182]: info: CoreStateMachine::pushState Mar 29 16:49:14 rivoplus volumio[3182]: info: CorePlayQueue::getTrack 1 Mar 29 16:49:14 rivoplus volumio[3182]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 29 16:49:14 rivoplus volumio[3182]: info: CoreCommandRouter::volumioPushState Mar 29 16:49:14 rivoplus volumio[3182]: info: CoreCommandRouter::volumioGetState Mar 29 16:49:14 rivoplus volumio[3182]: info: CorePlayQueue::getTrack 1 Mar 29 16:49:14 rivoplus volumio[3182]: info: MRS: Pushing multiroomSync output update for this device Mar 29 16:49:14 rivoplus volumio[3182]: info: MRS: Pushing multiroomSync output Mar 29 16:49:14 rivoplus volumio5-onboarding[4570]: time=2026-03-29T16:49:14.051+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.104.226:63231 @ 0x22e4b40" state=STATUS_STOPPED positionMs=0 volume=100 Mar 29 16:49:14 rivoplus volumio5-onboarding[4570]: time=2026-03-29T16:49:14.051+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.104.226:63231 @ 0x22e4b40" id=qobuz://song/291519745 title="Lullabye (Goodnight, My Angel) (96kHz/24bit)" Mar 29 16:49:14 rivoplus volumio[3182]: info: sendMpdCommand stop took 40 milliseconds Mar 29 16:49:14 rivoplus volumio[3182]: verbose: ControllerMpd::sendMpdCommand clear Mar 29 16:49:14 rivoplus volumio[3182]: info: Mar 29 16:49:14 rivoplus volumio[3182]: ---------------------------- MPD announces system playlist update Mar 29 16:49:14 rivoplus volumio[3182]: info: Ignoring MPD Status Update Mar 29 16:49:14 rivoplus volumio[3182]: info: sendMpdCommand clear took 39 milliseconds Mar 29 16:49:14 rivoplus volumio[3182]: verbose: ControllerMpd::sendMpdCommand load "http://127.0.0.1:3245?data=qobuz://song/291519745" Mar 29 16:49:14 rivoplus volumio[3182]: info: Mar 29 16:49:14 rivoplus volumio[3182]: ---------------------------- MPD announces system playlist update Mar 29 16:49:14 rivoplus volumio[3182]: info: Ignoring MPD Status Update Mar 29 16:49:14 rivoplus volumio[3182]: error: updateQueue error: null Mar 29 16:49:14 rivoplus volumio[3182]: STREAMING PROXY: Handling url /?data=qobuz://song/291519745 Mar 29 16:49:14 rivoplus volumio[3182]: info: ------------------------------ 9ms Mar 29 16:49:14 rivoplus volumio[3182]: info: Executing endpoint getStreamUrlqobuz Mar 29 16:49:14 rivoplus volumio[3182]: info: CoreCommandRouter::executeOnPlugin: qobuz , getStreamUrlAPI Mar 29 16:49:14 rivoplus volumio[3182]: info: MCU Signalled Playback Inactive Mar 29 16:49:15 rivoplus volumio[3182]: info: getStreamUrl took 1123 milliseconds Mar 29 16:49:15 rivoplus volumio[3182]: STREAMING PROXY: Got real url: https://streaming-qobuz-std.akamaized.net/file?uid=4459666&eid=291519745&fmt=7&profile=raw&range=20-30&app_id=539451548&cid=2756239&etsp=1774856954&hmac=p0xTlwoYmqawA0DBvHMFRm5K3Tw Mar 29 16:49:15 rivoplus volumio[3182]: STREAMING PROXY: Requesting upstream with range: none Mar 29 16:49:15 rivoplus volumio[3182]: STREAMING PROXY: Upstream status code: 200 Mar 29 16:49:15 rivoplus volumio[3182]: STREAMING PROXY: Client closed connection Mar 29 16:49:15 rivoplus volumio[3182]: error: updateQueue error: null Mar 29 16:49:15 rivoplus volumio[3182]: verbose: ControllerMpd::sendMpdCommand add "http://127.0.0.1:3245?data=qobuz://song/291519745" Mar 29 16:49:15 rivoplus volumio[3182]: info: ------------------------------ 1735ms Mar 29 16:49:15 rivoplus volumio[3182]: STREAMING PROXY: Upstream closed. Received 100 bytes Mar 29 16:49:15 rivoplus volumio[3182]: STREAMING PROXY: Incomplete transfer. Expected 9630438, got 100 Mar 29 16:49:15 rivoplus volumio[3182]: STREAMING PROXY: Retrying with range: bytes=100- (attempt 1) Mar 29 16:49:15 rivoplus volumio[3182]: info: Mar 29 16:49:15 rivoplus volumio[3182]: ---------------------------- MPD announces system playlist update Mar 29 16:49:15 rivoplus volumio[3182]: info: Ignoring MPD Status Update Mar 29 16:49:15 rivoplus volumio[3182]: info: sendMpdCommand add "http://127.0.0.1:3245?data=qobuz://song/291519745" took 3 milliseconds Mar 29 16:49:15 rivoplus volumio[3182]: info: CoreStateMachine::setConsumeUpdateService mpd Mar 29 16:49:15 rivoplus volumio[3182]: verbose: ControllerMpd::sendMpdCommand play Mar 29 16:49:15 rivoplus volumio[3182]: info: ------------------------------ 5ms Mar 29 16:49:15 rivoplus volumio[3182]: info: sendMpdCommand play took 2 milliseconds Mar 29 16:49:15 rivoplus volumio[3182]: info: Mar 29 16:49:15 rivoplus volumio[3182]: ---------------------------- MPD announces system playlist update Mar 29 16:49:15 rivoplus volumio[3182]: STREAMING PROXY: Handling url /?data=qobuz://song/291519745 Mar 29 16:49:15 rivoplus volumio[3182]: info: Ignoring MPD Status Update Mar 29 16:49:15 rivoplus volumio[3182]: info: ------------------------------ 8ms Mar 29 16:49:15 rivoplus volumio[3182]: info: Executing endpoint getStreamUrlqobuz Mar 29 16:49:15 rivoplus volumio[3182]: info: CoreCommandRouter::executeOnPlugin: qobuz , getStreamUrlAPI Mar 29 16:49:16 rivoplus volumio[3182]: STREAMING PROXY: Resuming with range: bytes=100- Mar 29 16:49:16 rivoplus volumio[3182]: STREAMING PROXY: Resume upstream status code: 206 Mar 29 16:49:17 rivoplus volumio5-onboarding[4570]: time=2026-03-29T16:49:17.152+09:00 level=INFO msg="new address was allocated" component=ble/conn old=36 new=37 Mar 29 16:49:17 rivoplus volumio[3182]: info: getStreamUrl took 1418 milliseconds Mar 29 16:49:17 rivoplus volumio[3182]: STREAMING PROXY: Got real url: https://streaming-qobuz-std.akamaized.net/file?uid=4459666&eid=291519745&fmt=7&profile=raw&range=20-30&app_id=539451548&cid=2756239&etsp=1774856956&hmac=FNq5Ec76nssXcy1mzefucbRp8N8 Mar 29 16:49:17 rivoplus volumio[3182]: STREAMING PROXY: Requesting upstream with range: none Mar 29 16:49:17 rivoplus volumio[3182]: STREAMING PROXY: Upstream status code: 200 Mar 29 16:49:17 rivoplus volumio[3182]: info: Mar 29 16:49:17 rivoplus volumio[3182]: ---------------------------- MPD announces state update: player Mar 29 16:49:17 rivoplus volumio[3182]: info: ControllerMpd::getState Mar 29 16:49:17 rivoplus volumio[3182]: verbose: ControllerMpd::sendMpdCommand status Mar 29 16:49:17 rivoplus volumio[3182]: info: Mar 29 16:49:17 rivoplus volumio[3182]: ---------------------------- MPD announces state update: player Mar 29 16:49:17 rivoplus volumio[3182]: info: ControllerMpd::getState Mar 29 16:49:17 rivoplus volumio[3182]: verbose: ControllerMpd::sendMpdCommand status Mar 29 16:49:17 rivoplus volumio[3182]: info: sendMpdCommand status took 23 milliseconds Mar 29 16:49:17 rivoplus volumio[3182]: verbose: ControllerMpd::parseState Mar 29 16:49:17 rivoplus volumio[3182]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 29 16:49:17 rivoplus volumio[3182]: info: Mar 29 16:49:17 rivoplus volumio[3182]: ---------------------------- MPD announces state update: player Mar 29 16:49:17 rivoplus volumio[3182]: info: ControllerMpd::getState Mar 29 16:49:17 rivoplus volumio[3182]: verbose: ControllerMpd::sendMpdCommand status Mar 29 16:49:17 rivoplus volumio[3182]: info: sendMpdCommand status took 21 milliseconds Mar 29 16:49:17 rivoplus volumio[3182]: info: sendMpdCommand playlistinfo took 8 milliseconds Mar 29 16:49:17 rivoplus volumio[3182]: verbose: ControllerMpd::parseState Mar 29 16:49:17 rivoplus volumio[3182]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 29 16:49:17 rivoplus volumio[3182]: verbose: ControllerMpd::parseTrackInfo Mar 29 16:49:17 rivoplus volumio[3182]: info: ControllerMpd::pushState Mar 29 16:49:17 rivoplus volumio[3182]: info: CoreCommandRouter::servicePushState Mar 29 16:49:17 rivoplus volumio[3182]: info: CorePlayQueue::getTrack 1 Mar 29 16:49:17 rivoplus volumio[3182]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":30,"samplerate":"96 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"291519745","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=qobuz://song/291519745","trackType":"qobuz"} Mar 29 16:49:17 rivoplus volumio[3182]: verbose: CURRENT POSITION 1 Mar 29 16:49:17 rivoplus volumio[3182]: info: CoreStateMachine::syncState stateService play Mar 29 16:49:17 rivoplus volumio[3182]: info: CoreStateMachine::syncState currentStatus stop Mar 29 16:49:17 rivoplus volumio[3182]: info: ------------------------------ 54ms Mar 29 16:49:17 rivoplus volumio[3182]: info: Mar 29 16:49:17 rivoplus volumio[3182]: ---------------------------- MPD announces state update: player Mar 29 16:49:17 rivoplus volumio[3182]: info: ControllerMpd::getState Mar 29 16:49:17 rivoplus volumio[3182]: verbose: ControllerMpd::sendMpdCommand status Mar 29 16:49:17 rivoplus volumio[3182]: info: sendMpdCommand status took 29 milliseconds Mar 29 16:49:17 rivoplus volumio[3182]: info: sendMpdCommand playlistinfo took 24 milliseconds Mar 29 16:49:17 rivoplus volumio[3182]: info: sendMpdCommand status took 8 milliseconds Mar 29 16:49:17 rivoplus volumio[3182]: verbose: ControllerMpd::parseState Mar 29 16:49:17 rivoplus volumio[3182]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 29 16:49:17 rivoplus volumio[3182]: verbose: ControllerMpd::parseTrackInfo Mar 29 16:49:17 rivoplus volumio[3182]: verbose: ControllerMpd::parseState Mar 29 16:49:17 rivoplus volumio[3182]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 29 16:49:17 rivoplus volumio[3182]: info: ControllerMpd::pushState Mar 29 16:49:17 rivoplus volumio[3182]: info: CoreCommandRouter::servicePushState Mar 29 16:49:17 rivoplus volumio[3182]: info: CorePlayQueue::getTrack 1 Mar 29 16:49:17 rivoplus volumio[3182]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":30,"samplerate":"96 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"291519745","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=qobuz://song/291519745","trackType":"qobuz"} Mar 29 16:49:17 rivoplus volumio[3182]: verbose: CURRENT POSITION 1 Mar 29 16:49:17 rivoplus volumio[3182]: info: CoreStateMachine::syncState stateService play Mar 29 16:49:17 rivoplus volumio[3182]: info: CoreStateMachine::syncState currentStatus play Mar 29 16:49:17 rivoplus volumio[3182]: info: Received an update from plugin. extracting info from payload Mar 29 16:49:17 rivoplus volumio[3182]: info: CoreStateMachine::pushState Mar 29 16:49:17 rivoplus volumio[3182]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 29 16:49:17 rivoplus volumio[3182]: info: CoreCommandRouter::volumioPushState Mar 29 16:49:17 rivoplus volumio[3182]: info: CoreCommandRouter::volumioGetState Mar 29 16:49:17 rivoplus volumio[3182]: info: MRS: Pushing multiroomSync output update for this device Mar 29 16:49:17 rivoplus dbus-daemon[2834]: [system] Rejected send message, 1 matched rules; type="error", sender=":1.54" (uid=0 pid=4570 comm="/usr/bin/volumio5-onboarding " label="kernel") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.7" (uid=0 pid=3313 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap,hostn" label="kernel") Mar 29 16:49:17 rivoplus volumio[3182]: info: MRS: Pushing multiroomSync output Mar 29 16:49:17 rivoplus volumio[3182]: info: CoreStateMachine::pushState Mar 29 16:49:17 rivoplus volumio[3182]: info: CoreCommandRouter::volumioPushState Mar 29 16:49:17 rivoplus volumio[3182]: info: CoreCommandRouter::volumioGetState Mar 29 16:49:17 rivoplus volumio[3182]: info: MRS: Pushing multiroomSync output update for this device Mar 29 16:49:17 rivoplus volumio[3182]: info: MRS: Pushing multiroomSync output Mar 29 16:49:17 rivoplus volumio5-onboarding[4570]: time=2026-03-29T16:49:17.528+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.104.226:63231 @ 0x22e4b40" state=STATUS_PLAYING positionMs=118 volume=100 Mar 29 16:49:17 rivoplus volumio5-onboarding[4570]: time=2026-03-29T16:49:17.528+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.104.226:63231 @ 0x22e4b40" id=qobuz://song/291519745 title="Lullabye (Goodnight, My Angel) (96kHz/24bit)" Mar 29 16:49:17 rivoplus volumio5-onboarding[4570]: time=2026-03-29T16:49:17.531+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.104.226:63231 @ 0x22e4b40" state=STATUS_PLAYING positionMs=118 volume=100 Mar 29 16:49:17 rivoplus volumio5-onboarding[4570]: time=2026-03-29T16:49:17.532+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.104.226:63231 @ 0x22e4b40" id=qobuz://song/291519745 title="Lullabye (Goodnight, My Angel) (96kHz/24bit)" Mar 29 16:49:17 rivoplus volumio[3182]: info: ------------------------------ 216ms Mar 29 16:49:17 rivoplus volumio[3182]: info: sendMpdCommand playlistinfo took 160 milliseconds Mar 29 16:49:17 rivoplus volumio[3182]: info: sendMpdCommand playlistinfo took 159 milliseconds Mar 29 16:49:17 rivoplus volumio[3182]: verbose: ControllerMpd::parseTrackInfo Mar 29 16:49:17 rivoplus volumio[3182]: info: ControllerMpd::pushState Mar 29 16:49:17 rivoplus volumio[3182]: info: CoreCommandRouter::servicePushState Mar 29 16:49:17 rivoplus volumio[3182]: info: CorePlayQueue::getTrack 1 Mar 29 16:49:17 rivoplus volumio[3182]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":30,"samplerate":"96 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"291519745","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=qobuz://song/291519745","trackType":"qobuz"} Mar 29 16:49:17 rivoplus volumio[3182]: verbose: CURRENT POSITION 1 Mar 29 16:49:17 rivoplus volumio[3182]: info: CoreStateMachine::syncState stateService play Mar 29 16:49:17 rivoplus volumio[3182]: info: CoreStateMachine::syncState currentStatus play Mar 29 16:49:17 rivoplus volumio[3182]: info: Received an update from plugin. extracting info from payload Mar 29 16:49:17 rivoplus volumio[3182]: info: CoreStateMachine::pushState Mar 29 16:49:17 rivoplus volumio[3182]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 29 16:49:17 rivoplus volumio[3182]: info: CoreCommandRouter::volumioPushState Mar 29 16:49:17 rivoplus volumio[3182]: info: CoreCommandRouter::volumioGetState Mar 29 16:49:17 rivoplus volumio[3182]: info: MRS: Pushing multiroomSync output update for this device Mar 29 16:49:17 rivoplus volumio[3182]: info: MRS: Pushing multiroomSync output Mar 29 16:49:17 rivoplus volumio[3182]: info: CoreStateMachine::pushState Mar 29 16:49:17 rivoplus volumio[3182]: info: CoreCommandRouter::volumioPushState Mar 29 16:49:17 rivoplus volumio[3182]: info: CoreCommandRouter::volumioGetState Mar 29 16:49:17 rivoplus volumio[3182]: info: MRS: Pushing multiroomSync output update for this device Mar 29 16:49:17 rivoplus volumio[3182]: info: MRS: Pushing multiroomSync output Mar 29 16:49:17 rivoplus volumio[3182]: info: ControllerMpd::pushState Mar 29 16:49:17 rivoplus volumio[3182]: info: CoreCommandRouter::servicePushState Mar 29 16:49:17 rivoplus volumio[3182]: info: CorePlayQueue::getTrack 1 Mar 29 16:49:17 rivoplus volumio[3182]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":30,"samplerate":"96 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"291519745","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=qobuz://song/291519745","trackType":"qobuz"} Mar 29 16:49:17 rivoplus volumio[3182]: verbose: CURRENT POSITION 1 Mar 29 16:49:17 rivoplus volumio[3182]: info: CoreStateMachine::syncState stateService play Mar 29 16:49:17 rivoplus volumio[3182]: info: CoreStateMachine::syncState currentStatus play Mar 29 16:49:17 rivoplus volumio[3182]: info: Received an update from plugin. extracting info from payload Mar 29 16:49:17 rivoplus volumio[3182]: info: CoreStateMachine::pushState Mar 29 16:49:17 rivoplus volumio[3182]: info: CoreCommandRouter::volumioPushState Mar 29 16:49:17 rivoplus volumio[3182]: info: CoreCommandRouter::volumioGetState Mar 29 16:49:17 rivoplus volumio[3182]: info: MRS: Pushing multiroomSync output update for this device Mar 29 16:49:17 rivoplus volumio[3182]: info: MRS: Pushing multiroomSync output Mar 29 16:49:17 rivoplus volumio[3182]: info: CoreStateMachine::pushState Mar 29 16:49:17 rivoplus volumio[3182]: info: CoreCommandRouter::volumioPushState Mar 29 16:49:17 rivoplus volumio[3182]: info: CoreCommandRouter::volumioGetState Mar 29 16:49:17 rivoplus volumio[3182]: info: MRS: Pushing multiroomSync output update for this device Mar 29 16:49:17 rivoplus volumio[3182]: info: MRS: Pushing multiroomSync output Mar 29 16:49:17 rivoplus volumio5-onboarding[4570]: time=2026-03-29T16:49:17.761+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.104.226:63231 @ 0x22e4b40" state=STATUS_PLAYING positionMs=287 volume=100 Mar 29 16:49:17 rivoplus volumio5-onboarding[4570]: time=2026-03-29T16:49:17.761+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.104.226:63231 @ 0x22e4b40" id=qobuz://song/291519745 title="Lullabye (Goodnight, My Angel) (96kHz/24bit)" Mar 29 16:49:17 rivoplus volumio5-onboarding[4570]: time=2026-03-29T16:49:17.762+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.104.226:63231 @ 0x22e4b40" state=STATUS_PLAYING positionMs=287 volume=100 Mar 29 16:49:17 rivoplus volumio5-onboarding[4570]: time=2026-03-29T16:49:17.763+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.104.226:63231 @ 0x22e4b40" id=qobuz://song/291519745 title="Lullabye (Goodnight, My Angel) (96kHz/24bit)" Mar 29 16:49:17 rivoplus volumio5-onboarding[4570]: time=2026-03-29T16:49:17.764+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.104.226:63231 @ 0x22e4b40" state=STATUS_PLAYING positionMs=287 volume=100 Mar 29 16:49:17 rivoplus volumio5-onboarding[4570]: time=2026-03-29T16:49:17.765+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.104.226:63231 @ 0x22e4b40" id=qobuz://song/291519745 title="Lullabye (Goodnight, My Angel) (96kHz/24bit)" Mar 29 16:49:17 rivoplus volumio5-onboarding[4570]: time=2026-03-29T16:49:17.766+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.104.226:63231 @ 0x22e4b40" state=STATUS_PLAYING positionMs=287 volume=100 Mar 29 16:49:17 rivoplus volumio5-onboarding[4570]: time=2026-03-29T16:49:17.766+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.104.226:63231 @ 0x22e4b40" id=qobuz://song/291519745 title="Lullabye (Goodnight, My Angel) (96kHz/24bit)" Mar 29 16:49:17 rivoplus volumio[3182]: info: ------------------------------ 408ms Mar 29 16:49:17 rivoplus volumio[3182]: info: ------------------------------ 387ms Mar 29 16:49:17 rivoplus volumio[3182]: info: Signalling Playback active due to playback status change Mar 29 16:49:17 rivoplus dbus-daemon[2834]: [system] Rejected send message, 1 matched rules; type="error", sender=":1.54" (uid=0 pid=4570 comm="/usr/bin/volumio5-onboarding " label="kernel") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.7" (uid=0 pid=3313 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap,hostn" label="kernel") Mar 29 16:49:17 rivoplus volumio[3182]: info: MCU Signalled Playback Active Mar 29 16:49:17 rivoplus volumio[3182]: STREAMING PROXY: Resume ended. Received 9630338 bytes Mar 29 16:49:18 rivoplus volumio[3182]: STREAMING PROXY: Upstream closed. Received 9630438 bytes Mar 29 16:49:18 rivoplus volumio[3182]: STREAMING PROXY: Client closed connection Mar 29 16:49:21 rivoplus volumio5-onboarding[4570]: time=2026-03-29T16:49:21.314+09:00 level=INFO msg="new address was allocated" component=ble/conn old=37 new=38 Mar 29 16:49:21 rivoplus dbus-daemon[2834]: [system] Rejected send message, 1 matched rules; type="error", sender=":1.54" (uid=0 pid=4570 comm="/usr/bin/volumio5-onboarding " label="kernel") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.7" (uid=0 pid=3313 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap,hostn" label="kernel") Mar 29 16:49:21 rivoplus dbus-daemon[2834]: [system] Rejected send message, 1 matched rules; type="error", sender=":1.54" (uid=0 pid=4570 comm="/usr/bin/volumio5-onboarding " label="kernel") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.7" (uid=0 pid=3313 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap,hostn" label="kernel") Mar 29 16:49:25 rivoplus volumio[3182]: info: CoreCommandRouter::volumioPause Mar 29 16:49:25 rivoplus volumio[3182]: info: CoreStateMachine::pause Mar 29 16:49:25 rivoplus volumio[3182]: info: CoreStateMachine::stPlaybackTimer Mar 29 16:49:25 rivoplus volumio[3182]: info: CoreStateMachine::servicePause Mar 29 16:49:25 rivoplus volumio[3182]: info: CorePlayQueue::getTrack 1 Mar 29 16:49:25 rivoplus volumio[3182]: info: CoreCommandRouter::servicePause Mar 29 16:49:25 rivoplus volumio[3182]: info: [1774770565576] ControllerQobuz::pause Mar 29 16:49:25 rivoplus volumio[3182]: info: CoreStateMachine::setConsumeUpdateService mpd Mar 29 16:49:25 rivoplus volumio[3182]: info: ControllerMpd::pause Mar 29 16:49:25 rivoplus volumio[3182]: verbose: ControllerMpd::sendMpdCommand pause Mar 29 16:49:25 rivoplus volumio[3182]: info: Mar 29 16:49:25 rivoplus volumio[3182]: ---------------------------- MPD announces state update: player Mar 29 16:49:25 rivoplus volumio[3182]: info: sendMpdCommand pause took 7 milliseconds Mar 29 16:49:25 rivoplus volumio[3182]: info: ControllerMpd::getState Mar 29 16:49:25 rivoplus volumio[3182]: verbose: ControllerMpd::sendMpdCommand status Mar 29 16:49:25 rivoplus volumio[3182]: info: Mar 29 16:49:25 rivoplus volumio[3182]: ---------------------------- MPD announces state update: player Mar 29 16:49:25 rivoplus volumio[3182]: info: ControllerMpd::getState Mar 29 16:49:25 rivoplus volumio[3182]: verbose: ControllerMpd::sendMpdCommand status Mar 29 16:49:25 rivoplus volumio[3182]: info: sendMpdCommand status took 6 milliseconds Mar 29 16:49:25 rivoplus volumio[3182]: info: sendMpdCommand status took 3 milliseconds Mar 29 16:49:25 rivoplus volumio[3182]: verbose: ControllerMpd::parseState Mar 29 16:49:25 rivoplus volumio[3182]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 29 16:49:25 rivoplus volumio[3182]: verbose: ControllerMpd::parseState Mar 29 16:49:25 rivoplus volumio[3182]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 29 16:49:25 rivoplus volumio[3182]: info: sendMpdCommand playlistinfo took 3 milliseconds Mar 29 16:49:25 rivoplus volumio[3182]: info: sendMpdCommand playlistinfo took 2 milliseconds Mar 29 16:49:25 rivoplus volumio[3182]: verbose: ControllerMpd::parseTrackInfo Mar 29 16:49:25 rivoplus volumio[3182]: verbose: ControllerMpd::parseTrackInfo Mar 29 16:49:25 rivoplus volumio[3182]: info: ControllerMpd::pushState Mar 29 16:49:25 rivoplus volumio[3182]: info: CoreCommandRouter::servicePushState Mar 29 16:49:25 rivoplus volumio[3182]: info: CorePlayQueue::getTrack 1 Mar 29 16:49:25 rivoplus volumio[3182]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":9492,"duration":30,"samplerate":"96 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"2613 Kbps","isStreaming":false,"title":"291519745","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=qobuz://song/291519745","trackType":"qobuz"} Mar 29 16:49:25 rivoplus volumio[3182]: verbose: CURRENT POSITION 1 Mar 29 16:49:25 rivoplus volumio[3182]: info: CoreStateMachine::syncState stateService pause Mar 29 16:49:25 rivoplus volumio[3182]: info: CoreStateMachine::syncState currentStatus pause Mar 29 16:49:25 rivoplus volumio[3182]: info: CoreStateMachine::pushState Mar 29 16:49:25 rivoplus volumio[3182]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 29 16:49:25 rivoplus volumio[3182]: info: CoreCommandRouter::volumioPushState Mar 29 16:49:25 rivoplus volumio[3182]: info: CoreCommandRouter::volumioGetState Mar 29 16:49:25 rivoplus volumio[3182]: info: MRS: Pushing multiroomSync output update for this device Mar 29 16:49:25 rivoplus volumio[3182]: info: MRS: Pushing multiroomSync output Mar 29 16:49:25 rivoplus volumio[3182]: info: CoreStateMachine::stPlaybackTimer Mar 29 16:49:25 rivoplus volumio[3182]: info: ControllerMpd::pushState Mar 29 16:49:25 rivoplus volumio[3182]: info: CoreCommandRouter::servicePushState Mar 29 16:49:25 rivoplus volumio[3182]: info: CorePlayQueue::getTrack 1 Mar 29 16:49:25 rivoplus volumio[3182]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":9492,"duration":30,"samplerate":"96 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"2613 Kbps","isStreaming":false,"title":"291519745","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=qobuz://song/291519745","trackType":"qobuz"} Mar 29 16:49:25 rivoplus volumio[3182]: verbose: CURRENT POSITION 1 Mar 29 16:49:25 rivoplus volumio[3182]: info: CoreStateMachine::syncState stateService pause Mar 29 16:49:25 rivoplus volumio[3182]: info: CoreStateMachine::syncState currentStatus pause Mar 29 16:49:25 rivoplus volumio[3182]: info: CoreStateMachine::pushState Mar 29 16:49:25 rivoplus volumio[3182]: info: CoreCommandRouter::volumioPushState Mar 29 16:49:25 rivoplus volumio[3182]: info: CoreCommandRouter::volumioGetState Mar 29 16:49:25 rivoplus volumio[3182]: info: MRS: Pushing multiroomSync output update for this device Mar 29 16:49:25 rivoplus volumio[3182]: info: MRS: Pushing multiroomSync output Mar 29 16:49:25 rivoplus volumio[3182]: info: CoreStateMachine::stPlaybackTimer Mar 29 16:49:25 rivoplus volumio5-onboarding[4570]: time=2026-03-29T16:49:25.635+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.104.226:63231 @ 0x22e4b40" state=STATUS_PAUSED positionMs=8084 volume=100 Mar 29 16:49:25 rivoplus volumio5-onboarding[4570]: time=2026-03-29T16:49:25.636+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.104.226:63231 @ 0x22e4b40" id=qobuz://song/291519745 title="Lullabye (Goodnight, My Angel) (96kHz/24bit)" Mar 29 16:49:25 rivoplus volumio5-onboarding[4570]: time=2026-03-29T16:49:25.637+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.104.226:63231 @ 0x22e4b40" state=STATUS_PAUSED positionMs=8084 volume=100 Mar 29 16:49:25 rivoplus volumio5-onboarding[4570]: time=2026-03-29T16:49:25.637+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.104.226:63231 @ 0x22e4b40" id=qobuz://song/291519745 title="Lullabye (Goodnight, My Angel) (96kHz/24bit)" Mar 29 16:49:25 rivoplus volumio[3182]: info: ------------------------------ 64ms Mar 29 16:49:25 rivoplus volumio[3182]: info: ------------------------------ 60ms Mar 29 16:49:25 rivoplus volumio[3182]: info: MCU Signalled Playback Inactive Mar 29 16:49:27 rivoplus volumio5-onboarding[4570]: time=2026-03-29T16:49:27.269+09:00 level=INFO msg="new address was allocated" component=ble/conn old=38 new=39 Mar 29 16:49:27 rivoplus dbus-daemon[2834]: [system] Rejected send message, 1 matched rules; type="error", sender=":1.54" (uid=0 pid=4570 comm="/usr/bin/volumio5-onboarding " label="kernel") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.7" (uid=0 pid=3313 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap,hostn" label="kernel") Mar 29 16:49:27 rivoplus dbus-daemon[2834]: [system] Rejected send message, 1 matched rules; type="error", sender=":1.54" (uid=0 pid=4570 comm="/usr/bin/volumio5-onboarding " label="kernel") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.7" (uid=0 pid=3313 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap,hostn" label="kernel") Mar 29 16:49:31 rivoplus volumio5-onboarding[4570]: time=2026-03-29T16:49:31.252+09:00 level=INFO msg="new address was allocated" component=ble/conn old=39 new=40 Mar 29 16:49:31 rivoplus dbus-daemon[2834]: [system] Rejected send message, 1 matched rules; type="error", sender=":1.54" (uid=0 pid=4570 comm="/usr/bin/volumio5-onboarding " label="kernel") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.7" (uid=0 pid=3313 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap,hostn" label="kernel") Mar 29 16:49:31 rivoplus dbus-daemon[2834]: [system] Rejected send message, 1 matched rules; type="error", sender=":1.54" (uid=0 pid=4570 comm="/usr/bin/volumio5-onboarding " label="kernel") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.7" (uid=0 pid=3313 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap,hostn" label="kernel") Mar 29 16:49:35 rivoplus volumio5-onboarding[4570]: time=2026-03-29T16:49:35.182+09:00 level=INFO msg="new address was allocated" component=ble/conn old=40 new=41 Mar 29 16:49:35 rivoplus dbus-daemon[2834]: [system] Rejected send message, 1 matched rules; type="error", sender=":1.54" (uid=0 pid=4570 comm="/usr/bin/volumio5-onboarding " label="kernel") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.7" (uid=0 pid=3313 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap,hostn" label="kernel") Mar 29 16:49:35 rivoplus dbus-daemon[2834]: [system] Rejected send message, 1 matched rules; type="error", sender=":1.54" (uid=0 pid=4570 comm="/usr/bin/volumio5-onboarding " label="kernel") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.7" (uid=0 pid=3313 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap,hostn" label="kernel") Mar 29 16:49:39 rivoplus volumio5-onboarding[4570]: time=2026-03-29T16:49:39.232+09:00 level=INFO msg="new address was allocated" component=ble/conn old=41 new=42 Mar 29 16:49:39 rivoplus dbus-daemon[2834]: [system] Rejected send message, 1 matched rules; type="error", sender=":1.54" (uid=0 pid=4570 comm="/usr/bin/volumio5-onboarding " label="kernel") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.7" (uid=0 pid=3313 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap,hostn" label="kernel") Mar 29 16:49:39 rivoplus dbus-daemon[2834]: [system] Rejected send message, 1 matched rules; type="error", sender=":1.54" (uid=0 pid=4570 comm="/usr/bin/volumio5-onboarding " label="kernel") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.7" (uid=0 pid=3313 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap,hostn" label="kernel") Mar 29 16:49:40 rivoplus volumio[3182]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Mar 29 16:49:40 rivoplus volumio[3182]: info: Preload queue cleared Mar 29 16:49:41 rivoplus volumio[3182]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Mar 29 16:49:42 rivoplus volumio[3182]: info: Preload queue cleared Mar 29 16:49:44 rivoplus volumio5-onboarding[4570]: time=2026-03-29T16:49:44.505+09:00 level=INFO msg="new address was allocated" component=ble/conn old=42 new=43 Mar 29 16:49:44 rivoplus dbus-daemon[2834]: [system] Rejected send message, 1 matched rules; type="error", sender=":1.54" (uid=0 pid=4570 comm="/usr/bin/volumio5-onboarding " label="kernel") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.7" (uid=0 pid=3313 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap,hostn" label="kernel") Mar 29 16:49:45 rivoplus dbus-daemon[2834]: [system] Rejected send message, 1 matched rules; type="error", sender=":1.54" (uid=0 pid=4570 comm="/usr/bin/volumio5-onboarding " label="kernel") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.7" (uid=0 pid=3313 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap,hostn" label="kernel") Mar 29 16:49:47 rivoplus volumio[3182]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Mar 29 16:49:48 rivoplus volumio[3182]: info: Preload queue cleared Mar 29 16:49:48 rivoplus volumio[3182]: An internal error occurred while serving an albumart. Details: Error: ENOENT: no such file or directory, stat '/volumio/app/plugins/miscellanea/albumart/icons/none.svg' Mar 29 16:49:49 rivoplus volumio5-onboarding[4570]: time=2026-03-29T16:49:49.290+09:00 level=INFO msg="new address was allocated" component=ble/conn old=43 new=44 Mar 29 16:49:49 rivoplus dbus-daemon[2834]: [system] Rejected send message, 1 matched rules; type="error", sender=":1.54" (uid=0 pid=4570 comm="/usr/bin/volumio5-onboarding " label="kernel") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.7" (uid=0 pid=3313 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap,hostn" label="kernel") Mar 29 16:49:49 rivoplus dbus-daemon[2834]: [system] Rejected send message, 1 matched rules; type="error", sender=":1.54" (uid=0 pid=4570 comm="/usr/bin/volumio5-onboarding " label="kernel") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.7" (uid=0 pid=3313 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap,hostn" label="kernel") Mar 29 16:49:52 rivoplus volumio[3182]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Mar 29 16:49:52 rivoplus volumio[3182]: info: Preload queue cleared Mar 29 16:49:52 rivoplus volumio[3182]: An internal error occurred while serving an albumart. Details: Error: ENOENT: no such file or directory, stat '/volumio/app/plugins/miscellanea/albumart/icons/none.svg' Mar 29 16:49:52 rivoplus volumio[3182]: An internal error occurred while serving an albumart. Details: Error: ENOENT: no such file or directory, stat '/volumio/app/plugins/miscellanea/albumart/icons/none.svg' Mar 29 16:49:52 rivoplus volumio[3182]: An internal error occurred while serving an albumart. Details: Error: ENOENT: no such file or directory, stat '/volumio/app/plugins/miscellanea/albumart/icons/none.svg' Mar 29 16:49:52 rivoplus volumio[3182]: An internal error occurred while serving an albumart. Details: Error: ENOENT: no such file or directory, stat '/volumio/app/plugins/miscellanea/albumart/icons/none.svg' Mar 29 16:49:52 rivoplus volumio[3182]: An internal error occurred while serving an albumart. Details: Error: ENOENT: no such file or directory, stat '/volumio/app/plugins/miscellanea/albumart/icons/none.svg' Mar 29 16:49:53 rivoplus volumio[3182]: An internal error occurred while serving an albumart. Details: Error: ENOENT: no such file or directory, stat '/volumio/app/plugins/miscellanea/albumart/icons/none.svg' Mar 29 16:49:53 rivoplus volumio[3182]: An internal error occurred while serving an albumart. Details: Error: ENOENT: no such file or directory, stat '/volumio/app/plugins/miscellanea/albumart/icons/none.svg' Mar 29 16:49:53 rivoplus volumio[3182]: An internal error occurred while serving an albumart. Details: Error: ENOENT: no such file or directory, stat '/volumio/app/plugins/miscellanea/albumart/icons/none.svg' Mar 29 16:49:53 rivoplus volumio[3182]: An internal error occurred while serving an albumart. Details: Error: ENOENT: no such file or directory, stat '/volumio/app/plugins/miscellanea/albumart/icons/none.svg' Mar 29 16:49:53 rivoplus volumio[3182]: An internal error occurred while serving an albumart. Details: Error: ENOENT: no such file or directory, stat '/volumio/app/plugins/miscellanea/albumart/icons/none.svg' Mar 29 16:49:53 rivoplus volumio[3182]: An internal error occurred while serving an albumart. Details: Error: ENOENT: no such file or directory, stat '/volumio/app/plugins/miscellanea/albumart/icons/none.svg' Mar 29 16:49:53 rivoplus volumio[3182]: An internal error occurred while serving an albumart. Details: Error: ENOENT: no such file or directory, stat '/volumio/app/plugins/miscellanea/albumart/icons/none.svg' Mar 29 16:49:53 rivoplus volumio[3182]: An internal error occurred while serving an albumart. Details: Error: ENOENT: no such file or directory, stat '/volumio/app/plugins/miscellanea/albumart/icons/none.svg' Mar 29 16:49:53 rivoplus volumio[3182]: An internal error occurred while serving an albumart. Details: Error: ENOENT: no such file or directory, stat '/volumio/app/plugins/miscellanea/albumart/icons/none.svg' Mar 29 16:49:53 rivoplus volumio[3182]: An internal error occurred while serving an albumart. Details: Error: ENOENT: no such file or directory, stat '/volumio/app/plugins/miscellanea/albumart/icons/none.svg' Mar 29 16:49:54 rivoplus volumio[3182]: An internal error occurred while serving an albumart. Details: Error: ENOENT: no such file or directory, stat '/volumio/app/plugins/miscellanea/albumart/icons/none.svg' Mar 29 16:49:54 rivoplus volumio[3182]: An internal error occurred while serving an albumart. Details: Error: ENOENT: no such file or directory, stat '/volumio/app/plugins/miscellanea/albumart/icons/none.svg' Mar 29 16:49:54 rivoplus volumio[3182]: An internal error occurred while serving an albumart. Details: Error: ENOENT: no such file or directory, stat '/volumio/app/plugins/miscellanea/albumart/icons/none.svg' Mar 29 16:49:54 rivoplus volumio[3182]: An internal error occurred while serving an albumart. Details: Error: ENOENT: no such file or directory, stat '/volumio/app/plugins/miscellanea/albumart/icons/none.svg' Mar 29 16:49:54 rivoplus volumio[3182]: An internal error occurred while serving an albumart. Details: Error: ENOENT: no such file or directory, stat '/volumio/app/plugins/miscellanea/albumart/icons/none.svg' Mar 29 16:49:55 rivoplus volumio5-onboarding[4570]: time=2026-03-29T16:49:55.042+09:00 level=INFO msg="new address was allocated" component=ble/conn old=44 new=45 Mar 29 16:49:55 rivoplus dbus-daemon[2834]: [system] Rejected send message, 1 matched rules; type="error", sender=":1.54" (uid=0 pid=4570 comm="/usr/bin/volumio5-onboarding " label="kernel") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.7" (uid=0 pid=3313 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap,hostn" label="kernel") Mar 29 16:49:55 rivoplus dbus-daemon[2834]: [system] Rejected send message, 1 matched rules; type="error", sender=":1.54" (uid=0 pid=4570 comm="/usr/bin/volumio5-onboarding " label="kernel") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.7" (uid=0 pid=3313 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap,hostn" label="kernel") Mar 29 16:49:57 rivoplus volumio[3182]: An internal error occurred while serving an albumart. Details: Error: ENOENT: no such file or directory, stat '/volumio/app/plugins/miscellanea/albumart/icons/none.svg' Mar 29 16:49:57 rivoplus volumio[3182]: An internal error occurred while serving an albumart. Details: Error: ENOENT: no such file or directory, stat '/volumio/app/plugins/miscellanea/albumart/icons/none.svg' Mar 29 16:49:57 rivoplus volumio[3182]: An internal error occurred while serving an albumart. Details: Error: ENOENT: no such file or directory, stat '/volumio/app/plugins/miscellanea/albumart/icons/none.svg' Mar 29 16:49:57 rivoplus volumio[3182]: An internal error occurred while serving an albumart. Details: Error: ENOENT: no such file or directory, stat '/volumio/app/plugins/miscellanea/albumart/icons/none.svg' Mar 29 16:49:57 rivoplus volumio[3182]: An internal error occurred while serving an albumart. Details: Error: ENOENT: no such file or directory, stat '/volumio/app/plugins/miscellanea/albumart/icons/none.svg' Mar 29 16:49:57 rivoplus volumio[3182]: An internal error occurred while serving an albumart. Details: Error: ENOENT: no such file or directory, stat '/volumio/app/plugins/miscellanea/albumart/icons/none.svg' Mar 29 16:49:59 rivoplus volumio5-onboarding[4570]: time=2026-03-29T16:49:59.355+09:00 level=INFO msg="new address was allocated" component=ble/conn old=45 new=46 Mar 29 16:49:59 rivoplus dbus-daemon[2834]: [system] Rejected send message, 1 matched rules; type="error", sender=":1.54" (uid=0 pid=4570 comm="/usr/bin/volumio5-onboarding " label="kernel") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.7" (uid=0 pid=3313 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap,hostn" label="kernel") Mar 29 16:50:00 rivoplus dbus-daemon[2834]: [system] Rejected send message, 1 matched rules; type="error", sender=":1.54" (uid=0 pid=4570 comm="/usr/bin/volumio5-onboarding " label="kernel") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.7" (uid=0 pid=3313 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap,hostn" label="kernel") Mar 29 16:50:01 rivoplus volumio[3182]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Mar 29 16:50:01 rivoplus volumio[3182]: info: Preload queue cleared Mar 29 16:50:03 rivoplus volumio5-onboarding[4570]: time=2026-03-29T16:50:03.397+09:00 level=INFO msg="new address was allocated" component=ble/conn old=46 new=47 Mar 29 16:50:03 rivoplus dbus-daemon[2834]: [system] Rejected send message, 1 matched rules; type="error", sender=":1.54" (uid=0 pid=4570 comm="/usr/bin/volumio5-onboarding " label="kernel") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.7" (uid=0 pid=3313 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap,hostn" label="kernel") Mar 29 16:50:04 rivoplus dbus-daemon[2834]: [system] Rejected send message, 1 matched rules; type="error", sender=":1.54" (uid=0 pid=4570 comm="/usr/bin/volumio5-onboarding " label="kernel") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.7" (uid=0 pid=3313 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap,hostn" label="kernel") Mar 29 16:50:05 rivoplus volumio[3182]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 29 16:50:05 rivoplus volumio[3182]: TypeError: Cannot read property 'slice' of null Mar 29 16:50:05 rivoplus volumio[3182]: at download (/volumio/app/plugins/miscellanea/albumart/albumart.js:718:41) Mar 29 16:50:05 rivoplus volumio[3182]: at ClientRequest. (/volumio/app/plugins/miscellanea/albumart/albumart.js:728:7) Mar 29 16:50:05 rivoplus volumio[3182]: at Object.onceWrapper (events.js:520:26) Mar 29 16:50:05 rivoplus volumio[3182]: at ClientRequest.emit (events.js:400:28) Mar 29 16:50:05 rivoplus volumio[3182]: at HTTPParser.parserOnIncomingClient [as onIncoming] (_http_client.js:647:27) Mar 29 16:50:05 rivoplus volumio[3182]: at HTTPParser.parserOnHeadersComplete (_http_common.js:127:17) Mar 29 16:50:05 rivoplus volumio[3182]: at TLSSocket.socketOnData (_http_client.js:515:22) Mar 29 16:50:05 rivoplus volumio[3182]: at TLSSocket.emit (events.js:400:28) Mar 29 16:50:05 rivoplus volumio[3182]: at addChunk (internal/streams/readable.js:293:12) Mar 29 16:50:05 rivoplus volumio[3182]: at readableAddChunk (internal/streams/readable.js:267:9) Mar 29 16:50:05 rivoplus volumio[3182]: at TLSSocket.Readable.push (internal/streams/readable.js:206:10) Mar 29 16:50:05 rivoplus volumio[3182]: at TLSWrap.onStreamRead (internal/stream_base_commons.js:188:23) Mar 29 16:50:05 rivoplus volumio[3182]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 29 16:50:06 rivoplus sudo[5510]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2026-03-29 16:49 Mar 29 16:50:06 rivoplus sudo[5510]: 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="e9612ec5034fb2e958508aaefbca2962fd6f6654" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="464fc672d77d3df6ee72b331d36cdf1fa936e1ec" VOLUMIO_ARCH="armv7" VOLUMIO_VARIANT="rivoplus" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri 27 Feb 2026 11:19:27 AM CET" VOLUMIO_VERSION="3.912" VOLUMIO_HARDWARE="mp1" VOLUMIO_DEVICENAME="Volumio MP1" VOLUMIO_VENDOR_MODEL="Volumio Rivo Plus" VOLUMIO_VENDOR="Volumio" VOLUMIO_MODEL="Rivo Plus" VOLUMIO_HASH="a7285124ffc88c43265bb2db03526f6a"