Oct 17 01:58:00 rivo volumio5-onboarding[3870]: time=2026-10-17T01:58:00.101+01:00 level=INFO msg="new address was allocated" component=ble/conn old=14 new=15 Oct 17 01:58:00 rivo dbus-daemon[2941]: [system] Rejected send message, 0 matched rules; type="error", sender=":1.16" (uid=0 pid=3870 comm="/usr/bin/volumio5-onboarding" label="kernel") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.6" (uid=0 pid=3333 comm="/usr/libexec/bluetooth/bluetoothd --noplugin=sap,b" label="kernel") Oct 17 01:58:01 rivo bluealsa[3334]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_6C_81_F4_8D_09_64/service0001, ...) Oct 17 01:58:01 rivo bluealsa[3334]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_6C_81_F4_8D_09_64/service0001/char0002, ...) Oct 17 01:58:01 rivo bluealsa[3334]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_6C_81_F4_8D_09_64/service0001/char0004, ...) Oct 17 01:58:01 rivo bluealsa[3334]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_6C_81_F4_8D_09_64/service0006, ...) Oct 17 01:58:01 rivo bluealsa[3334]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_6C_81_F4_8D_09_64/service0006/char0007, ...) Oct 17 01:58:01 rivo bluealsa[3334]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_6C_81_F4_8D_09_64/service0006/char0007/desc0009, ...) Oct 17 01:58:01 rivo bluealsa[3334]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_6C_81_F4_8D_09_64/service000a, ...) Oct 17 01:58:01 rivo bluealsa[3334]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_6C_81_F4_8D_09_64/service000a/char000b, ...) Oct 17 01:58:01 rivo bluealsa[3334]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_6C_81_F4_8D_09_64/service000a/char000d, ...) Oct 17 01:58:01 rivo bluealsa[3334]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_6C_81_F4_8D_09_64/service000f, ...) Oct 17 01:58:01 rivo bluealsa[3334]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_6C_81_F4_8D_09_64/service000f/char0010, ...) Oct 17 01:58:01 rivo bluealsa[3334]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_6C_81_F4_8D_09_64/service000f/char0010/desc0012, ...) Oct 17 01:58:01 rivo bluealsa[3334]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_6C_81_F4_8D_09_64/service000f/char0010/desc0013, ...) Oct 17 01:58:01 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Oct 17 01:58:01 rivo volumio[3520]: info: Received Get System Info Oct 17 01:58:01 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 17 01:58:01 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 17 01:58:01 rivo volumio[3520]: info: Discovery: Getting this device information Oct 17 01:58:01 rivo volumio[3520]: info: CoreCommandRouter::volumioGetState Oct 17 01:58:01 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 17 01:58:01 rivo bluealsa[3334]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_6C_81_F4_8D_09_64/service0014, ...) Oct 17 01:58:01 rivo bluealsa[3334]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_6C_81_F4_8D_09_64/service0014/char0015, ...) Oct 17 01:58:01 rivo bluealsa[3334]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_6C_81_F4_8D_09_64/service0014/char0015/desc0017, ...) Oct 17 01:58:01 rivo bluealsa[3334]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_6C_81_F4_8D_09_64/service0014/char0015/desc0018, ...) Oct 17 01:58:01 rivo bluealsa[3334]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_6C_81_F4_8D_09_64/service0019, ...) Oct 17 01:58:01 rivo bluealsa[3334]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_6C_81_F4_8D_09_64/service0019/char001a, ...) Oct 17 01:58:01 rivo bluealsa[3334]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_6C_81_F4_8D_09_64/service0019/char001a/desc001c, ...) Oct 17 01:58:01 rivo bluealsa[3334]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_6C_81_F4_8D_09_64/service001d, ...) Oct 17 01:58:01 rivo bluealsa[3334]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_6C_81_F4_8D_09_64/service001d/char001e, ...) Oct 17 01:58:01 rivo bluealsa[3334]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_6C_81_F4_8D_09_64/service001d/char001e/desc0020, ...) Oct 17 01:58:01 rivo bluealsa[3334]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_6C_81_F4_8D_09_64/service001d/char0021, ...) Oct 17 01:58:01 rivo bluealsa[3334]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_6C_81_F4_8D_09_64/service0023, ...) Oct 17 01:58:01 rivo bluealsa[3334]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_6C_81_F4_8D_09_64/service0023/char0024, ...) Oct 17 01:58:01 rivo bluealsa[3334]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_6C_81_F4_8D_09_64/service0023/char0024/desc0026, ...) Oct 17 01:58:01 rivo bluealsa[3334]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_6C_81_F4_8D_09_64/service0023/char0027, ...) Oct 17 01:58:01 rivo bluealsa[3334]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_6C_81_F4_8D_09_64/service0023/char0027/desc0029, ...) Oct 17 01:58:01 rivo bluealsa[3334]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_6C_81_F4_8D_09_64/service0023/char002a, ...) Oct 17 01:58:01 rivo bluealsa[3334]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_6C_81_F4_8D_09_64/service0023/char002a/desc002c, ...) Oct 17 01:58:01 rivo bluealsa[3334]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_6C_81_F4_8D_09_64/service002d, ...) Oct 17 01:58:01 rivo bluealsa[3334]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_6C_81_F4_8D_09_64/service002d/char002e, ...) Oct 17 01:58:01 rivo bluealsa[3334]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_6C_81_F4_8D_09_64/service002d/char002e/desc0030, ...) Oct 17 01:58:01 rivo bluealsa[3334]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_6C_81_F4_8D_09_64/service002d/char002e/desc0031, ...) Oct 17 01:58:01 rivo bluealsa[3334]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_6C_81_F4_8D_09_64/service002d/char0032, ...) Oct 17 01:58:01 rivo bluealsa[3334]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_6C_81_F4_8D_09_64/service002d/char0032/desc0034, ...) Oct 17 01:58:01 rivo bluealsa[3334]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_6C_81_F4_8D_09_64/service002d/char0032/desc0035, ...) Oct 17 01:58:01 rivo bluealsa[3334]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_6C_81_F4_8D_09_64/service002d/char0036, ...) Oct 17 01:58:01 rivo bluealsa[3334]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_6C_81_F4_8D_09_64/service002d/char0036/desc0038, ...) Oct 17 01:58:02 rivo volumio5-onboarding[3870]: time=2026-10-17T01:58:02.516+01:00 level=WARN msg="pending write exceeded maximum retries, dropping" component=ble/conn addr=13 chunks=1 index=0 tries=11 Oct 17 01:58:02 rivo volumio5-onboarding[3870]: time=2026-10-17T01:58:02.516+01:00 level=ERROR msg="failed to send event" component=server dst="00:00:00:00:00:00%0d @ 0x1d76090" event=SERVER_EVENT_TYPE_PLAYER_STATE_CHANGED error="peer is gone" Oct 17 01:58:02 rivo volumio5-onboarding[3870]: time=2026-10-17T01:58:02.517+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.222:53361,00:00:00:00:00:00%0e @ 0x1d3edb0" id= title= Oct 17 01:58:02 rivo volumio[3520]: info: CoreCommandRouter::volumioGetQueue Oct 17 01:58:02 rivo volumio[3520]: info: CoreStateMachine::getQueue Oct 17 01:58:02 rivo volumio[3520]: info: CorePlayQueue::getQueue Oct 17 01:58:05 rivo volumio5-onboarding[3870]: time=2026-10-17T01:58:05.910+01:00 level=WARN msg="pending write exceeded maximum retries, dropping" component=ble/conn addr=13 chunks=1 index=0 tries=11 Oct 17 01:58:05 rivo volumio5-onboarding[3870]: time=2026-10-17T01:58:05.910+01:00 level=ERROR msg="failed to send event" component=server dst="00:00:00:00:00:00%0d @ 0x1d76090" event=SERVER_EVENT_TYPE_PLAYER_STATE_CHANGED error="peer is gone" Oct 17 01:58:05 rivo volumio5-onboarding[3870]: time=2026-10-17T01:58:05.910+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.222:53361,00:00:00:00:00:00%0e @ 0x1d3edb0" id= title= Oct 17 01:58:07 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Oct 17 01:58:09 rivo volumio5-onboarding[3870]: time=2026-10-17T01:58:09.435+01:00 level=WARN msg="pending write exceeded maximum retries, dropping" component=ble/conn addr=13 chunks=1 index=0 tries=11 Oct 17 01:58:09 rivo volumio5-onboarding[3870]: time=2026-10-17T01:58:09.435+01:00 level=ERROR msg="failed to send event" component=server dst="00:00:00:00:00:00%0d @ 0x1d76090" event=SERVER_EVENT_TYPE_PLAYER_STATE_CHANGED error="peer is gone" Oct 17 01:58:09 rivo volumio5-onboarding[3870]: time=2026-10-17T01:58:09.435+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.222:53361,00:00:00:00:00:00%0e @ 0x1d3edb0" id= title= Oct 17 01:58:12 rivo volumio5-onboarding[3870]: time=2026-10-17T01:58:12.987+01:00 level=WARN msg="pending write exceeded maximum retries, dropping" component=ble/conn addr=13 chunks=1 index=0 tries=11 Oct 17 01:58:12 rivo volumio5-onboarding[3870]: time=2026-10-17T01:58:12.987+01:00 level=ERROR msg="failed to send event" component=server dst="00:00:00:00:00:00%0d @ 0x1d76090" event=SERVER_EVENT_TYPE_PLAYER_STATE_CHANGED error="peer is gone" Oct 17 01:58:12 rivo volumio5-onboarding[3870]: time=2026-10-17T01:58:12.988+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.222:53361,00:00:00:00:00:00%0e @ 0x1d3edb0" id= title= Oct 17 01:58:14 rivo volumio[3520]: info: Preload queue cleared Oct 17 01:58:14 rivo volumio[3520]: info: CoreCommandRouter::volumioReplaceandPlayItems Oct 17 01:58:14 rivo volumio[3520]: info: CoreStateMachine::ClearQueue Oct 17 01:58:14 rivo volumio[3520]: info: CoreStateMachine::stop Oct 17 01:58:14 rivo volumio[3520]: info: CoreStateMachine::serviceStop Oct 17 01:58:14 rivo volumio[3520]: info: CoreCommandRouter::serviceStop Oct 17 01:58:14 rivo volumio[3520]: info: Airplay Stop Oct 17 01:58:14 rivo volumio[3520]: info: Stopping Airplay Playback and sending pause command to client via USR2 Oct 17 01:58:14 rivo volumio[3520]: info: CorePlayQueue::clearPlayQueue Oct 17 01:58:14 rivo volumio[3520]: info: CorePlayQueue::saveQueue Oct 17 01:58:14 rivo volumio[3520]: info: CoreCommandRouter::volumioPushQueue Oct 17 01:58:14 rivo volumio[3520]: info: CoreStateMachine::addQueueItems Oct 17 01:58:14 rivo volumio[3520]: info: CorePlayQueue::addQueueItems Oct 17 01:58:14 rivo volumio[3520]: info: Preload queue cleared Oct 17 01:58:14 rivo volumio[3520]: info: Adding Item to queue: tidal://mymusic/albums/az/68735571 Oct 17 01:58:14 rivo volumio[3520]: info: Exploding uri tidal://mymusic/albums/az/68735571 in service tidal Oct 17 01:58:14 rivo volumio[3520]: info: Refreshing TIDAL token Oct 17 01:58:14 rivo sudo[30495]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/kill -USR2 32651 Oct 17 01:58:14 rivo sudo[30495]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 17 01:58:14 rivo sudo[30495]: pam_unix(sudo:session): session closed for user root Oct 17 01:58:14 rivo shairport-sync[30420]: {"time":1792198669125,"response":"airplayInactive Success"} Oct 17 01:58:14 rivo systemd[1]: shairport-sync.service: Main process exited, code=killed, status=12/USR2 Oct 17 01:58:14 rivo systemd[1]: shairport-sync.service: Failed with result 'signal'. Oct 17 01:58:15 rivo volumio[3520]: info: Shairport-Sync paused with USR2 Oct 17 01:58:15 rivo volumio[3520]: info: explodeTIDALUri took 602 milliseconds Oct 17 01:58:15 rivo volumio[3520]: info: CoreCommandRouter::volumioPushQueue Oct 17 01:58:15 rivo volumio[3520]: info: CorePlayQueue::saveQueue Oct 17 01:58:15 rivo volumio[3520]: info: CoreStateMachine::updateTrackBlock Oct 17 01:58:15 rivo volumio[3520]: info: CorePlayQueue::getTrackBlock Oct 17 01:58:15 rivo volumio[3520]: info: CoreCommandRouter::volumioGetState Oct 17 01:58:15 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: play , [object Object] Oct 17 01:58:15 rivo volumio[3520]: info: CoreCommandRouter::volumioPlay Oct 17 01:58:15 rivo volumio[3520]: verbose: UNSET VOLATILE: Service: airplay_emulation Oct 17 01:58:15 rivo volumio[3520]: info: Stopping Airplay Playback and sending pause command to client via USR2 Oct 17 01:58:15 rivo volumio[3520]: info: CoreStateMachine::play index 0 Oct 17 01:58:15 rivo volumio[3520]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 17 01:58:15 rivo volumio[3520]: info: CoreStateMachine::stop Oct 17 01:58:15 rivo volumio[3520]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 17 01:58:15 rivo volumio[3520]: info: CoreStateMachine::play index undefined Oct 17 01:58:15 rivo volumio[3520]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 17 01:58:15 rivo volumio[3520]: info: CorePlayQueue::getTrack 0 Oct 17 01:58:15 rivo volumio[3520]: info: CoreStateMachine::startPlaybackTimer Oct 17 01:58:15 rivo volumio[3520]: info: CorePlayQueue::getTrack 0 Oct 17 01:58:15 rivo volumio[3520]: info: [1792198695826] ControllerTidal::clearAddPlayTrack Oct 17 01:58:15 rivo volumio[3520]: info: Getting stream with soundQuality HI_RES Oct 17 01:58:15 rivo sudo[30517]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/kill -USR2 Oct 17 01:58:15 rivo sudo[30517]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 17 01:58:15 rivo sudo[30517]: pam_unix(sudo:session): session closed for user root Oct 17 01:58:15 rivo volumio[3520]: info: Cannot execute Shairport-sync USR2 kill: Error: Command failed: /usr/bin/sudo /bin/kill -USR2 $(pidof shairport-sync) Oct 17 01:58:15 rivo volumio[3520]: Usage: Oct 17 01:58:15 rivo volumio[3520]: kill [options] [...] Oct 17 01:58:15 rivo volumio[3520]: Options: Oct 17 01:58:15 rivo volumio[3520]: [...] send signal to every listed Oct 17 01:58:15 rivo volumio[3520]: -, -s, --signal Oct 17 01:58:15 rivo volumio[3520]: specify the to be sent Oct 17 01:58:15 rivo volumio[3520]: -q, --queue integer value to be sent with the signal Oct 17 01:58:15 rivo volumio[3520]: -l, --list=[] list all signal names, or convert one to a name Oct 17 01:58:15 rivo volumio[3520]: -L, --table list all signal names in a nice table Oct 17 01:58:15 rivo volumio[3520]: -h, --help display this help and exit Oct 17 01:58:15 rivo volumio[3520]: -V, --version output version information and exit Oct 17 01:58:15 rivo volumio[3520]: For more details see kill(1). Oct 17 01:58:15 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Oct 17 01:58:15 rivo volumio[3520]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Oct 17 01:58:15 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Oct 17 01:58:15 rivo volumio[3520]: info: Received Get System Version Oct 17 01:58:15 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 17 01:58:15 rivo volumio[3520]: info: Received Get System Info Oct 17 01:58:15 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 17 01:58:15 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 17 01:58:15 rivo volumio[3520]: info: Discovery: Getting this device information Oct 17 01:58:15 rivo volumio[3520]: info: CoreCommandRouter::volumioGetState Oct 17 01:58:15 rivo volumio[3520]: info: CorePlayQueue::getTrack 0 Oct 17 01:58:15 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 17 01:58:16 rivo volumio[3520]: info: getStreamUrl took 178 milliseconds Oct 17 01:58:16 rivo volumio[3520]: verbose: ControllerMpd::sendMpdCommand stop Oct 17 01:58:16 rivo volumio[3520]: info: Restarting Shairport-Sync after stop Oct 17 01:58:16 rivo volumio[3520]: info: sendMpdCommand stop took 12 milliseconds Oct 17 01:58:16 rivo volumio[3520]: verbose: ControllerMpd::sendMpdCommand clear Oct 17 01:58:16 rivo volumio[3520]: info: Oct 17 01:58:16 rivo volumio[3520]: ---------------------------- MPD announces system playlist update Oct 17 01:58:16 rivo volumio[3520]: info: Ignoring MPD Status Update Oct 17 01:58:16 rivo volumio[3520]: info: sendMpdCommand clear took 1 milliseconds Oct 17 01:58:16 rivo volumio[3520]: verbose: ControllerMpd::sendMpdCommand add "http://lgf.audio.tidal.com/mediatracks/CAEaKwgDEidmZDAxMzFiYWZjMmMyYzg1ZmI0YmE5YTVhMDZmMGZlZl82Mi5tcDQ/0.flac?token=1792202295~MzNlZTc1MTg2YjY2NGJhYzYxZTkxMzA2MDNjYTIxYmIwMzk0NDU3Zg==" Oct 17 01:58:16 rivo volumio[3520]: error: updateQueue error: null Oct 17 01:58:16 rivo volumio[3520]: info: ------------------------------ 2ms Oct 17 01:58:16 rivo volumio[3520]: info: Oct 17 01:58:16 rivo volumio[3520]: ---------------------------- MPD announces system playlist update Oct 17 01:58:16 rivo volumio[3520]: info: Ignoring MPD Status Update Oct 17 01:58:16 rivo volumio[3520]: info: sendMpdCommand add "http://lgf.audio.tidal.com/mediatracks/CAEaKwgDEidmZDAxMzFiYWZjMmMyYzg1ZmI0YmE5YTVhMDZmMGZlZl82Mi5tcDQ/0.flac?token=1792202295~MzNlZTc1MTg2YjY2NGJhYzYxZTkxMzA2MDNjYTIxYmIwMzk0NDU3Zg==" took 1 milliseconds Oct 17 01:58:16 rivo volumio[3520]: info: CoreStateMachine::setConsumeUpdateService mpd Oct 17 01:58:16 rivo volumio[3520]: verbose: ControllerMpd::sendMpdCommand play Oct 17 01:58:16 rivo volumio[3520]: info: ------------------------------ 2ms Oct 17 01:58:16 rivo volumio[3520]: info: sendMpdCommand play took 1 milliseconds Oct 17 01:58:16 rivo sudo[30521]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 17 01:58:16 rivo sudo[30521]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 17 01:58:16 rivo systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Oct 17 01:58:16 rivo sudo[30521]: pam_unix(sudo:session): session closed for user root Oct 17 01:58:16 rivo volumio[3520]: info: Shairport-Sync retarted Oct 17 01:58:16 rivo volumio[3520]: info: Oct 17 01:58:16 rivo volumio[3520]: ---------------------------- MPD announces state update: player Oct 17 01:58:16 rivo volumio[3520]: info: ControllerMpd::getState Oct 17 01:58:16 rivo volumio[3520]: verbose: ControllerMpd::sendMpdCommand status Oct 17 01:58:16 rivo volumio[3520]: info: Oct 17 01:58:16 rivo volumio[3520]: ---------------------------- MPD announces state update: player Oct 17 01:58:16 rivo volumio[3520]: info: sendMpdCommand status took 87 milliseconds Oct 17 01:58:16 rivo volumio[3520]: info: ControllerMpd::getState Oct 17 01:58:16 rivo volumio[3520]: verbose: ControllerMpd::sendMpdCommand status Oct 17 01:58:16 rivo volumio[3520]: verbose: ControllerMpd::parseState Oct 17 01:58:16 rivo volumio[3520]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 17 01:58:16 rivo volumio[3520]: info: sendMpdCommand status took 3 milliseconds Oct 17 01:58:16 rivo volumio[3520]: info: sendMpdCommand playlistinfo took 2 milliseconds Oct 17 01:58:16 rivo volumio[3520]: verbose: ControllerMpd::parseState Oct 17 01:58:16 rivo volumio[3520]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 17 01:58:16 rivo volumio[3520]: verbose: ControllerMpd::parseTrackInfo Oct 17 01:58:16 rivo volumio[3520]: info: ControllerMpd::pushState Oct 17 01:58:16 rivo volumio[3520]: info: CoreCommandRouter::servicePushState Oct 17 01:58:16 rivo volumio[3520]: info: CorePlayQueue::getTrack 0 Oct 17 01:58:16 rivo volumio[3520]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":218,"samplerate":"192 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"0.flac?token=1792202295~MzNlZTc1MTg2YjY2NGJhYzYxZTkxMzA2MDNjYTIxYmIwMzk0NDU3Zg==","artist":null,"album":null,"uri":"http://lgf.audio.tidal.com/mediatracks/CAEaKwgDEidmZDAxMzFiYWZjMmMyYzg1ZmI0YmE5YTVhMDZmMGZlZl82Mi5tcDQ/0.flac?token=1792202295~MzNlZTc1MTg2YjY2NGJhYzYxZTkxMzA2MDNjYTIxYmIwMzk0NDU3Zg==","trackType":"tidal"} Oct 17 01:58:16 rivo volumio[3520]: verbose: CURRENT POSITION 0 Oct 17 01:58:16 rivo volumio[3520]: info: CoreStateMachine::syncState stateService play Oct 17 01:58:16 rivo volumio[3520]: info: CoreStateMachine::syncState currentStatus stop Oct 17 01:58:16 rivo volumio[3520]: info: ------------------------------ 94ms Oct 17 01:58:16 rivo volumio[3520]: info: sendMpdCommand playlistinfo took 3 milliseconds Oct 17 01:58:16 rivo volumio[3520]: verbose: ControllerMpd::parseTrackInfo Oct 17 01:58:16 rivo volumio[3520]: info: ControllerMpd::pushState Oct 17 01:58:16 rivo volumio[3520]: info: CoreCommandRouter::servicePushState Oct 17 01:58:16 rivo volumio[3520]: info: CorePlayQueue::getTrack 0 Oct 17 01:58:16 rivo volumio[3520]: verbose: STATE SERVICE {"status":"play","position":0,"seek":105,"duration":218,"samplerate":"192 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"5200 Kbps","isStreaming":false,"title":"0.flac?token=1792202295~MzNlZTc1MTg2YjY2NGJhYzYxZTkxMzA2MDNjYTIxYmIwMzk0NDU3Zg==","artist":null,"album":null,"uri":"http://lgf.audio.tidal.com/mediatracks/CAEaKwgDEidmZDAxMzFiYWZjMmMyYzg1ZmI0YmE5YTVhMDZmMGZlZl82Mi5tcDQ/0.flac?token=1792202295~MzNlZTc1MTg2YjY2NGJhYzYxZTkxMzA2MDNjYTIxYmIwMzk0NDU3Zg==","trackType":"tidal"} Oct 17 01:58:16 rivo volumio[3520]: verbose: CURRENT POSITION 0 Oct 17 01:58:16 rivo volumio[3520]: info: CoreStateMachine::syncState stateService play Oct 17 01:58:16 rivo volumio[3520]: info: CoreStateMachine::syncState currentStatus play Oct 17 01:58:16 rivo volumio[3520]: info: Received an update from plugin. extracting info from payload Oct 17 01:58:16 rivo volumio[3520]: info: CoreStateMachine::pushState Oct 17 01:58:16 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 17 01:58:16 rivo volumio[3520]: info: CoreCommandRouter::volumioPushState Oct 17 01:58:16 rivo volumio[3520]: info: CoreCommandRouter::volumioGetState Oct 17 01:58:16 rivo volumio[3520]: info: MRS: Pushing multiroomSync output update for this device Oct 17 01:58:16 rivo volumio[3520]: info: MRS: Pushing multiroomSync output Oct 17 01:58:16 rivo volumio[3520]: info: CoreStateMachine::pushState Oct 17 01:58:16 rivo volumio[3520]: info: CoreCommandRouter::volumioPushState Oct 17 01:58:16 rivo volumio[3520]: info: CoreCommandRouter::volumioGetState Oct 17 01:58:16 rivo volumio[3520]: info: MRS: Pushing multiroomSync output update for this device Oct 17 01:58:16 rivo volumio[3520]: info: MRS: Pushing multiroomSync output Oct 17 01:58:16 rivo volumio5-onboarding[3870]: time=2026-10-17T01:58:16.246+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.222:53361,00:00:00:00:00:00%0e @ 0x1d3edb0" state=STATUS_PLAYING positionMs=0 volume=33 Oct 17 01:58:16 rivo volumio5-onboarding[3870]: time=2026-10-17T01:58:16.247+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.222:53361,00:00:00:00:00:00%0e @ 0x1d3edb0" id=tidal://song/68735572 title="Changes (2015 Remaster)" Oct 17 01:58:16 rivo volumio5-onboarding[3870]: time=2026-10-17T01:58:16.247+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.222:53361,00:00:00:00:00:00%0e @ 0x1d3edb0" state=STATUS_PLAYING positionMs=0 volume=33 Oct 17 01:58:16 rivo volumio5-onboarding[3870]: time=2026-10-17T01:58:16.247+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.222:53361,00:00:00:00:00:00%0e @ 0x1d3edb0" id=tidal://song/68735572 title="Changes (2015 Remaster)" Oct 17 01:58:16 rivo volumio[3520]: info: ------------------------------ 39ms Oct 17 01:58:16 rivo volumio[3520]: info: Signalling Playback active due to playback status change Oct 17 01:58:16 rivo volumio[3520]: info: Signalling Playback active due to playback status change Oct 17 01:58:16 rivo volumio[3520]: info: Updating RAAT Signal Path Oct 17 01:58:16 rivo volumio[3520]: info: Updating RAAT Signal Path Oct 17 01:58:16 rivo volumio5-onboarding[3870]: time=2026-10-17T01:58:16.375+01:00 level=WARN msg="pending write exceeded maximum retries, dropping" component=ble/conn addr=13 chunks=1 index=0 tries=11 Oct 17 01:58:16 rivo volumio5-onboarding[3870]: time=2026-10-17T01:58:16.376+01:00 level=ERROR msg="failed to send event" component=server dst="00:00:00:00:00:00%0d @ 0x1d76090" event=SERVER_EVENT_TYPE_PLAYER_STATE_CHANGED error="peer is gone" Oct 17 01:58:16 rivo volumio5-onboarding[3870]: time=2026-10-17T01:58:16.377+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.222:53361,00:00:00:00:00:00%0e @ 0x1d3edb0" id= title= Oct 17 01:58:20 rivo volumio5-onboarding[3870]: time=2026-10-17T01:58:20.718+01:00 level=WARN msg="pending write exceeded maximum retries, dropping" component=ble/conn addr=13 chunks=1 index=0 tries=11 Oct 17 01:58:20 rivo volumio5-onboarding[3870]: time=2026-10-17T01:58:20.719+01:00 level=ERROR msg="failed to send event" component=server dst="00:00:00:00:00:00%0d @ 0x1d76090" event=SERVER_EVENT_TYPE_PLAYER_STATE_CHANGED error="peer is gone" Oct 17 01:58:20 rivo volumio5-onboarding[3870]: time=2026-10-17T01:58:20.719+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.222:53361,00:00:00:00:00:00%0e @ 0x1d3edb0" id= title= Oct 17 01:58:24 rivo volumio5-onboarding[3870]: time=2026-10-17T01:58:24.149+01:00 level=WARN msg="pending write exceeded maximum retries, dropping" component=ble/conn addr=13 chunks=1 index=0 tries=11 Oct 17 01:58:24 rivo volumio5-onboarding[3870]: time=2026-10-17T01:58:24.149+01:00 level=ERROR msg="failed to send event" component=server dst="00:00:00:00:00:00%0d @ 0x1d76090" event=SERVER_EVENT_TYPE_PLAYER_STATE_CHANGED error="peer is gone" Oct 17 01:58:24 rivo volumio5-onboarding[3870]: time=2026-10-17T01:58:24.150+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.222:53361,00:00:00:00:00:00%0e @ 0x1d3edb0" id= title= Oct 17 01:58:27 rivo volumio5-onboarding[3870]: time=2026-10-17T01:58:27.586+01:00 level=WARN msg="pending write exceeded maximum retries, dropping" component=ble/conn addr=13 chunks=1 index=0 tries=11 Oct 17 01:58:27 rivo volumio5-onboarding[3870]: time=2026-10-17T01:58:27.588+01:00 level=ERROR msg="failed to send event" component=server dst="00:00:00:00:00:00%0d @ 0x1d76090" event=SERVER_EVENT_TYPE_PLAYER_STATE_CHANGED error="peer is gone" Oct 17 01:58:27 rivo volumio5-onboarding[3870]: time=2026-10-17T01:58:27.588+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.222:53361,00:00:00:00:00:00%0e @ 0x1d3edb0" id= title= Oct 17 01:58:31 rivo volumio5-onboarding[3870]: time=2026-10-17T01:58:31.073+01:00 level=WARN msg="pending write exceeded maximum retries, dropping" component=ble/conn addr=13 chunks=1 index=0 tries=11 Oct 17 01:58:31 rivo volumio5-onboarding[3870]: time=2026-10-17T01:58:31.076+01:00 level=ERROR msg="failed to send event" component=server dst="00:00:00:00:00:00%0d @ 0x1d76090" event=SERVER_EVENT_TYPE_PLAYER_STATE_CHANGED error="peer is gone" Oct 17 01:58:31 rivo volumio5-onboarding[3870]: time=2026-10-17T01:58:31.076+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.222:53361,00:00:00:00:00:00%0e @ 0x1d3edb0" id= title= Oct 17 01:58:34 rivo volumio5-onboarding[3870]: time=2026-10-17T01:58:34.594+01:00 level=WARN msg="pending write exceeded maximum retries, dropping" component=ble/conn addr=13 chunks=1 index=0 tries=11 Oct 17 01:58:34 rivo volumio5-onboarding[3870]: time=2026-10-17T01:58:34.597+01:00 level=ERROR msg="failed to send event" component=server dst="00:00:00:00:00:00%0d @ 0x1d76090" event=SERVER_EVENT_TYPE_PLAYER_STATE_CHANGED error="peer is gone" Oct 17 01:58:34 rivo volumio5-onboarding[3870]: time=2026-10-17T01:58:34.598+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.222:53361,00:00:00:00:00:00%0e @ 0x1d3edb0" id= title= Oct 17 01:58:38 rivo volumio5-onboarding[3870]: time=2026-10-17T01:58:38.238+01:00 level=WARN msg="pending write exceeded maximum retries, dropping" component=ble/conn addr=13 chunks=1 index=0 tries=11 Oct 17 01:58:38 rivo volumio5-onboarding[3870]: time=2026-10-17T01:58:38.239+01:00 level=ERROR msg="failed to send event" component=server dst="00:00:00:00:00:00%0d @ 0x1d76090" event=SERVER_EVENT_TYPE_PLAYER_STATE_CHANGED error="peer is gone" Oct 17 01:58:38 rivo volumio5-onboarding[3870]: time=2026-10-17T01:58:38.239+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.222:53361,00:00:00:00:00:00%0e @ 0x1d3edb0" id= title= Oct 17 01:58:41 rivo volumio5-onboarding[3870]: time=2026-10-17T01:58:41.649+01:00 level=WARN msg="pending write exceeded maximum retries, dropping" component=ble/conn addr=13 chunks=1 index=0 tries=11 Oct 17 01:58:41 rivo volumio5-onboarding[3870]: time=2026-10-17T01:58:41.650+01:00 level=ERROR msg="failed to send event" component=server dst="00:00:00:00:00:00%0d @ 0x1d76090" event=SERVER_EVENT_TYPE_PLAYER_STATE_CHANGED error="peer is gone" Oct 17 01:58:41 rivo volumio5-onboarding[3870]: time=2026-10-17T01:58:41.650+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.222:53361,00:00:00:00:00:00%0e @ 0x1d3edb0" id= title= Oct 17 01:58:45 rivo volumio5-onboarding[3870]: time=2026-10-17T01:58:45.173+01:00 level=WARN msg="pending write exceeded maximum retries, dropping" component=ble/conn addr=13 chunks=1 index=0 tries=11 Oct 17 01:58:45 rivo volumio5-onboarding[3870]: time=2026-10-17T01:58:45.174+01:00 level=ERROR msg="failed to send event" component=server dst="00:00:00:00:00:00%0d @ 0x1d76090" event=SERVER_EVENT_TYPE_PLAYER_STATE_CHANGED error="peer is gone" Oct 17 01:58:45 rivo volumio5-onboarding[3870]: time=2026-10-17T01:58:45.174+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.222:53361,00:00:00:00:00:00%0e @ 0x1d3edb0" id= title= Oct 17 01:58:48 rivo volumio5-onboarding[3870]: time=2026-10-17T01:58:48.658+01:00 level=WARN msg="pending write exceeded maximum retries, dropping" component=ble/conn addr=13 chunks=1 index=0 tries=11 Oct 17 01:58:48 rivo volumio5-onboarding[3870]: time=2026-10-17T01:58:48.660+01:00 level=ERROR msg="failed to send event" component=server dst="00:00:00:00:00:00%0d @ 0x1d76090" event=SERVER_EVENT_TYPE_PLAYER_STATE_CHANGED error="peer is gone" Oct 17 01:58:48 rivo volumio5-onboarding[3870]: time=2026-10-17T01:58:48.661+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.222:53361,00:00:00:00:00:00%0e @ 0x1d3edb0" id= title= Oct 17 01:58:52 rivo volumio5-onboarding[3870]: time=2026-10-17T01:58:52.058+01:00 level=WARN msg="pending write exceeded maximum retries, dropping" component=ble/conn addr=13 chunks=1 index=0 tries=11 Oct 17 01:58:52 rivo volumio5-onboarding[3870]: time=2026-10-17T01:58:52.059+01:00 level=ERROR msg="failed to send event" component=server dst="00:00:00:00:00:00%0d @ 0x1d76090" event=SERVER_EVENT_TYPE_PLAYER_STATE_CHANGED error="peer is gone" Oct 17 01:58:52 rivo volumio5-onboarding[3870]: time=2026-10-17T01:58:52.059+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.222:53361,00:00:00:00:00:00%0e @ 0x1d3edb0" id= title= Oct 17 01:58:55 rivo volumio5-onboarding[3870]: time=2026-10-17T01:58:55.631+01:00 level=WARN msg="pending write exceeded maximum retries, dropping" component=ble/conn addr=13 chunks=1 index=0 tries=11 Oct 17 01:58:55 rivo volumio5-onboarding[3870]: time=2026-10-17T01:58:55.632+01:00 level=ERROR msg="failed to send event" component=server dst="00:00:00:00:00:00%0d @ 0x1d76090" event=SERVER_EVENT_TYPE_PLAYER_STATE_CHANGED error="peer is gone" Oct 17 01:58:55 rivo volumio5-onboarding[3870]: time=2026-10-17T01:58:55.632+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.222:53361,00:00:00:00:00:00%0e @ 0x1d3edb0" id= title= Oct 17 01:58:55 rivo volumio[3520]: info: CoreCommandRouter::getUIConfigOnPlugin Oct 17 01:58:55 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions Oct 17 01:58:55 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 17 01:58:55 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Oct 17 01:58:55 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 17 01:58:55 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 17 01:58:55 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 17 01:58:55 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 17 01:58:55 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 17 01:58:55 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 17 01:58:55 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 17 01:58:55 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: mpd , getPlaybackMode Oct 17 01:58:55 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus Oct 17 01:58:55 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: raat , getAdditionalUiSection Oct 17 01:58:55 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:58:55 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:58:59 rivo volumio5-onboarding[3870]: time=2026-10-17T01:58:59.157+01:00 level=WARN msg="pending write exceeded maximum retries, dropping" component=ble/conn addr=13 chunks=1 index=0 tries=11 Oct 17 01:58:59 rivo volumio5-onboarding[3870]: time=2026-10-17T01:58:59.157+01:00 level=ERROR msg="failed to send event" component=server dst="00:00:00:00:00:00%0d @ 0x1d76090" event=SERVER_EVENT_TYPE_PLAYER_STATE_CHANGED error="peer is gone" Oct 17 01:58:59 rivo volumio5-onboarding[3870]: time=2026-10-17T01:58:59.157+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.222:53361,00:00:00:00:00:00%0e @ 0x1d3edb0" id= title= Oct 17 01:59:02 rivo volumio5-onboarding[3870]: time=2026-10-17T01:59:02.674+01:00 level=WARN msg="pending write exceeded maximum retries, dropping" component=ble/conn addr=13 chunks=1 index=0 tries=11 Oct 17 01:59:02 rivo volumio5-onboarding[3870]: time=2026-10-17T01:59:02.676+01:00 level=ERROR msg="failed to send event" component=server dst="00:00:00:00:00:00%0d @ 0x1d76090" event=SERVER_EVENT_TYPE_PLAYER_STATE_CHANGED error="peer is gone" Oct 17 01:59:02 rivo volumio5-onboarding[3870]: time=2026-10-17T01:59:02.676+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.222:53361,00:00:00:00:00:00%0e @ 0x1d3edb0" id= title= Oct 17 01:59:03 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 17 01:59:03 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 17 01:59:03 rivo volumio[3520]: info: Discovery: Getting this device information Oct 17 01:59:03 rivo volumio[3520]: info: CoreCommandRouter::volumioGetState Oct 17 01:59:03 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 17 01:59:03 rivo volumio[3520]: verbose: New Socket.io Connection to 192.168.1.96:3000 from 192.168.1.222 UA: Dart/3.12 (dart:io) Engine version: 3 Transport: websocket Total Clients: 10 Oct 17 01:59:03 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Oct 17 01:59:03 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Oct 17 01:59:05 rivo volumio5-onboarding[3870]: time=2026-10-17T01:59:05.987+01:00 level=WARN msg="pending write exceeded maximum retries, dropping" component=ble/conn addr=13 chunks=1 index=0 tries=11 Oct 17 01:59:05 rivo volumio5-onboarding[3870]: time=2026-10-17T01:59:05.988+01:00 level=ERROR msg="failed to send event" component=server dst="00:00:00:00:00:00%0d @ 0x1d76090" event=SERVER_EVENT_TYPE_PLAYER_STATE_CHANGED error="peer is gone" Oct 17 01:59:05 rivo volumio5-onboarding[3870]: time=2026-10-17T01:59:05.988+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.222:53361,00:00:00:00:00:00%0e @ 0x1d3edb0" id= title= Oct 17 01:59:09 rivo volumio5-onboarding[3870]: time=2026-10-17T01:59:09.639+01:00 level=WARN msg="pending write exceeded maximum retries, dropping" component=ble/conn addr=13 chunks=1 index=0 tries=11 Oct 17 01:59:09 rivo volumio5-onboarding[3870]: time=2026-10-17T01:59:09.639+01:00 level=ERROR msg="failed to send event" component=server dst="00:00:00:00:00:00%0d @ 0x1d76090" event=SERVER_EVENT_TYPE_PLAYER_STATE_CHANGED error="peer is gone" Oct 17 01:59:09 rivo volumio5-onboarding[3870]: time=2026-10-17T01:59:09.639+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.222:53361,00:00:00:00:00:00%0e @ 0x1d3edb0" id= title= Oct 17 01:59:12 rivo volumio5-onboarding[3870]: time=2026-10-17T01:59:12.948+01:00 level=WARN msg="pending write exceeded maximum retries, dropping" component=ble/conn addr=13 chunks=1 index=0 tries=11 Oct 17 01:59:12 rivo volumio5-onboarding[3870]: time=2026-10-17T01:59:12.948+01:00 level=ERROR msg="failed to send event" component=server dst="00:00:00:00:00:00%0d @ 0x1d76090" event=SERVER_EVENT_TYPE_PLAYER_STATE_CHANGED error="peer is gone" Oct 17 01:59:12 rivo volumio5-onboarding[3870]: time=2026-10-17T01:59:12.948+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.222:53361,00:00:00:00:00:00%0e @ 0x1d3edb0" id= title= Oct 17 01:59:16 rivo volumio5-onboarding[3870]: time=2026-10-17T01:59:16.254+01:00 level=WARN msg="pending write exceeded maximum retries, dropping" component=ble/conn addr=13 chunks=1 index=0 tries=11 Oct 17 01:59:16 rivo volumio5-onboarding[3870]: time=2026-10-17T01:59:16.254+01:00 level=ERROR msg="failed to send event" component=server dst="00:00:00:00:00:00%0d @ 0x1d76090" event=SERVER_EVENT_TYPE_PLAYER_STATE_CHANGED error="peer is gone" Oct 17 01:59:16 rivo volumio5-onboarding[3870]: time=2026-10-17T01:59:16.255+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.222:53361,00:00:00:00:00:00%0e @ 0x1d3edb0" id= title= Oct 17 01:59:18 rivo volumio[3520]: info: CALLMETHOD: audio_interface alsa_controller saveVolumeOptions [object Object] Oct 17 01:59:18 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , saveVolumeOptions Oct 17 01:59:18 rivo volumio[3520]: info: CoreCommandRouter::volumioGetState Oct 17 01:59:18 rivo volumio[3520]: info: Restoring Previous Volume level: 33 false false Oct 17 01:59:18 rivo volumio[3520]: info: Volume configurations have been set Oct 17 01:59:18 rivo volumio[3520]: info: QobuzConnect: setDeactiveState invoked Oct 17 01:59:18 rivo volumio[3520]: info: CoreCommandRouter::volumioGetState Oct 17 01:59:18 rivo volumio[3520]: info: Reconfiguring and Restarting RAAT Plugin due to audio path changes Oct 17 01:59:18 rivo vtcs[32733]: [2026-10-17 01:59:18.175] [tisoc] [warning] [SessionManagerImpl.cpp:240] Illegal State: IDLE Oct 17 01:59:18 rivo vtcs[32733]: [2026-10-17 01:59:18.175] [tisoc] [error] [SpkconServer.cpp:378] recv error. socket disconnected Oct 17 01:59:18 rivo sudo[30658]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service Oct 17 01:59:18 rivo sudo[30658]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 17 01:59:18 rivo volumio[3520]: info: CoreCommandRouter::volumioUpdateVolumeSettings Oct 17 01:59:18 rivo volumio[3520]: info: Updating Volume Controller Parameters: Device: 5 Name: Volumio Preciso Mixer: PCM Max Vol: 100 Vol Curve; logarithmic Vol Steps: 1 Oct 17 01:59:18 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , setExternalVolume Oct 17 01:59:18 rivo volumio[3520]: info: Disabling external Volume Control Oct 17 01:59:18 rivo volumio[3520]: info: CoreCommandRouter::getUIConfigOnPlugin Oct 17 01:59:18 rivo systemd[1]: Stopping vtcs.service - Volumio Tidal Connect Service... Oct 17 01:59:18 rivo systemd[1]: vtcs.service: Deactivated successfully. Oct 17 01:59:18 rivo systemd[1]: Stopped vtcs.service - Volumio Tidal Connect Service. Oct 17 01:59:18 rivo sudo[30664]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service Oct 17 01:59:18 rivo sudo[30664]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 17 01:59:18 rivo sudo[30658]: pam_unix(sudo:session): session closed for user root Oct 17 01:59:18 rivo volumio[3520]: info: VolumeController:: alsactl monitor closed, code: 0 Oct 17 01:59:18 rivo volumio[3520]: info: VolumeController:: Starting alsactl monitor Oct 17 01:59:18 rivo sudo[30672]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl reset-failed qobuz-connect.service Oct 17 01:59:18 rivo sudo[30672]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 17 01:59:18 rivo sudo[30664]: pam_unix(sudo:session): session closed for user root Oct 17 01:59:18 rivo sudo[30672]: pam_unix(sudo:session): session closed for user root Oct 17 01:59:18 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions Oct 17 01:59:18 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 17 01:59:18 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Oct 17 01:59:18 rivo sudo[30678]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart qobuz-connect.service Oct 17 01:59:18 rivo sudo[30678]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 17 01:59:18 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 17 01:59:18 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 17 01:59:18 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 17 01:59:18 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 17 01:59:18 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 17 01:59:18 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 17 01:59:18 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 17 01:59:18 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: mpd , getPlaybackMode Oct 17 01:59:18 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus Oct 17 01:59:18 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: raat , getAdditionalUiSection Oct 17 01:59:18 rivo volumio[3520]: info: VolumeController:: Volume=33 Mute =false Oct 17 01:59:18 rivo volumio[3520]: info: CoreStateMachine::pushState Oct 17 01:59:18 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 17 01:59:18 rivo volumio[3520]: info: CoreCommandRouter::volumioPushState Oct 17 01:59:18 rivo volumio[3520]: info: CoreCommandRouter::volumioGetState Oct 17 01:59:18 rivo volumio[3520]: info: MRS: Pushing multiroomSync output update for this device Oct 17 01:59:18 rivo volumio[3520]: info: MRS: Pushing multiroomSync output Oct 17 01:59:18 rivo volumio5-onboarding[3870]: time=2026-10-17T01:59:18.473+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.222:53361,00:00:00:00:00:00%0e @ 0x1d3edb0" state=STATUS_PLAYING positionMs=62083 volume=33 Oct 17 01:59:18 rivo volumio5-onboarding[3870]: time=2026-10-17T01:59:18.474+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.222:53361,00:00:00:00:00:00%0e @ 0x1d3edb0" id=tidal://song/68735572 title="Changes (2015 Remaster)" Oct 17 01:59:18 rivo volumio[3520]: info: Signalling Playback active due to playback status change Oct 17 01:59:18 rivo volumio[3520]: info: Updating RAAT Signal Path Oct 17 01:59:18 rivo systemd[1]: Stopping qobuz-connect.service - Volumio Qobuz Connect Service... Oct 17 01:59:18 rivo qobuz-connect[32715]: 20261017 01:59:18.493 [32715.32715] INFO SampleApp: Stopping Local configuration server Oct 17 01:59:18 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:18 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:18 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:18 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:18 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:18 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:18 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:18 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:18 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:18 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:18 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 17 01:59:18 rivo volumio[3520]: info: Not Reporting Auto name since its the default one Oct 17 01:59:18 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkCurrentAudioDeviceAvailable Oct 17 01:59:18 rivo sudo[30689]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl reset-failed raat-daemon.service Oct 17 01:59:18 rivo sudo[30689]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 17 01:59:18 rivo sudo[30689]: pam_unix(sudo:session): session closed for user root Oct 17 01:59:18 rivo sudo[30691]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart raat-daemon.service Oct 17 01:59:18 rivo sudo[30691]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 17 01:59:18 rivo systemd[1]: Stopping raat-daemon.service - RAAT DAEMON... Oct 17 01:59:18 rivo systemd[1]: raat-daemon.service: Deactivated successfully. Oct 17 01:59:18 rivo systemd[1]: Stopped raat-daemon.service - RAAT DAEMON. Oct 17 01:59:18 rivo systemd[1]: Started raat-daemon.service - RAAT DAEMON. Oct 17 01:59:18 rivo sudo[30691]: pam_unix(sudo:session): session closed for user root Oct 17 01:59:18 rivo volumio[3520]: info: Raat Daemon started successfully Oct 17 01:59:18 rivo volumio[3520]: info: Executing endpoint restartRAATSocket Oct 17 01:59:18 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: raat , establishDaemonConnection Oct 17 01:59:19 rivo volumio[3520]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 9 Oct 17 01:59:19 rivo volumio5-onboarding[3870]: time=2026-10-17T01:59:19.674+01:00 level=WARN msg="pending write exceeded maximum retries, dropping" component=ble/conn addr=13 chunks=1 index=0 tries=11 Oct 17 01:59:19 rivo volumio5-onboarding[3870]: time=2026-10-17T01:59:19.675+01:00 level=ERROR msg="failed to send event" component=server dst="00:00:00:00:00:00%0d @ 0x1d76090" event=SERVER_EVENT_TYPE_PLAYER_STATE_CHANGED error="peer is gone" Oct 17 01:59:19 rivo volumio5-onboarding[3870]: time=2026-10-17T01:59:19.675+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.222:53361,00:00:00:00:00:00%0e @ 0x1d3edb0" id= title= Oct 17 01:59:20 rivo qobuz-connect[32715]: 20261017 01:59:20.288 [32715.32715] INFO SampleApp: shat down connection on UNIX socket Oct 17 01:59:20 rivo volumio[3520]: info: QobuzConnect: Qobuz Connect client [object Object] disconnected Oct 17 01:59:20 rivo volumio[3520]: info: QobuzConnect: setDeactiveState invoked Oct 17 01:59:20 rivo volumio[3520]: info: CoreCommandRouter::volumioGetState Oct 17 01:59:20 rivo systemd[1]: qobuz-connect.service: Deactivated successfully. Oct 17 01:59:20 rivo systemd[1]: Stopped qobuz-connect.service - Volumio Qobuz Connect Service. Oct 17 01:59:20 rivo systemd[1]: Started qobuz-connect.service - Volumio Qobuz Connect Service. Oct 17 01:59:20 rivo sudo[30678]: pam_unix(sudo:session): session closed for user root Oct 17 01:59:20 rivo volumio[3520]: info: Executing endpoint qc_getconfig Oct 17 01:59:20 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: qobuzconnect , onGetConfig Oct 17 01:59:20 rivo qobuz-connect[30711]: 20261017 01:59:20.421 [30711.30711] INFO SampleApp: Started connection to /tmp/qbz-connect.socket UNIX socket Oct 17 01:59:20 rivo volumio[3520]: info: QobuzConnect: Qobuz Connect socket /tmp/qbz-connect.socket connected to client [object Object] Oct 17 01:59:20 rivo volumio[3520]: info: QobuzConnect: QOBUZ Connect daemon connected Oct 17 01:59:20 rivo qobuz-connect[30711]: 20261017 01:59:20.427 [30711.30711] INFO VolumeManager: [0xabb2b3c8]: Setting new playback volume: 75 Oct 17 01:59:20 rivo qobuz-connect[30711]: 20261017 01:59:20.428 [30711.30711] INFO VolumeManager: [0xabb2b3c8]: Setting new mute state: 0 Oct 17 01:59:20 rivo qobuz-connect[30711]: 20261017 01:59:20.428 [30711.30711] INFO AudioStreamManager: [0xabb2b120]: Setting new audio download buffer size: 1048576 Oct 17 01:59:20 rivo qobuz-connect[30711]: 20261017 01:59:20.428 [30711.30711] INFO QobuzConnect: [0xabb2bc90]: Client initialized! Oct 17 01:59:20 rivo qobuz-connect[30711]: 20261017 01:59:20.428 [30711.30711] INFO SampleApp: Starting Avahi advertising, name: Rivo, service name: _qobuz-connect._tcp Oct 17 01:59:20 rivo qobuz-connect[30711]: 20261017 01:59:20.442 [30711.30711] INFO LocalConfigManager: [0xabb2ae48]: Starting Local Configuration server Oct 17 01:59:20 rivo qobuz-connect[30711]: 20261017 01:59:20.442 [30711.30711] INFO SampleApp: Starting Local configuration server Oct 17 01:59:20 rivo qobuz-connect[30711]: 20261017 01:59:20.443 [30711.30711] INFO SampleApp: Connected to UNIX socket client 0xabb15908 Oct 17 01:59:20 rivo qobuz-connect[30711]: 20261017 01:59:20.570 [30711.30711] INFO SampleApp: Playback volume changed: 75 Oct 17 01:59:20 rivo volumio[3520]: info: CoreCommandRouter::volumioGetState Oct 17 01:59:21 rivo volumio[3520]: info: TidalConnect service stoped! Oct 17 01:59:21 rivo volumio[3520]: info: TidalConnect service stoped! Oct 17 01:59:21 rivo volumio[3520]: info: Updating tc_getconfig REST Endpoint for plugin: music_service/tidalconnect Oct 17 01:59:21 rivo volumio[3520]: info: Updating tc_connect REST Endpoint for plugin: music_service/tidalconnect Oct 17 01:59:21 rivo sudo[30727]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start vtcs.service Oct 17 01:59:21 rivo sudo[30727]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 17 01:59:21 rivo systemd[1]: Started vtcs.service - Volumio Tidal Connect Service. Oct 17 01:59:21 rivo sudo[30727]: pam_unix(sudo:session): session closed for user root Oct 17 01:59:21 rivo volumio[3520]: info: RAAT: Requesting Headphone Status Oct 17 01:59:21 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: inputs , getHeadphoneStatus Oct 17 01:59:21 rivo volumio[3520]: info: MCU Signalled Headphone Mode Disabled Oct 17 01:59:21 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: raat , reportHeadphoneState Oct 17 01:59:21 rivo volumio[3520]: info: Reporting Headphone State: false Oct 17 01:59:21 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:21 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:21 rivo volumio[3520]: info: Updating RAAT Signal Path Oct 17 01:59:21 rivo volumio[3520]: info: Executing endpoint tc_getconfig Oct 17 01:59:21 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: tidalconnect , onGetConfig Oct 17 01:59:21 rivo vtcs[30730]: STARTING TidalConnect services, version: 1.6.1 Oct 17 01:59:21 rivo vtcs[30730]: STARTED TidalConnect services. Oct 17 01:59:21 rivo volumio[3520]: info: Executing endpoint tc_connect Oct 17 01:59:21 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: tidalconnect , onConnect Oct 17 01:59:21 rivo volumio[3520]: info: Connecting to TidalConnect Oct 17 01:59:21 rivo volumio[3520]: info: CoreCommandRouter::servicePushState Oct 17 01:59:21 rivo volumio[3520]: info: CorePlayQueue::getTrack 0 Oct 17 01:59:21 rivo volumio[3520]: info: CONSUME SERVICE: Received update from a service different from the one supposed to be playing music. Skipping notification. Current mpd Received tidalconnect Oct 17 01:59:21 rivo volumio[3520]: info: CoreCommandRouter::servicePushState Oct 17 01:59:21 rivo volumio[3520]: info: CorePlayQueue::getTrack 0 Oct 17 01:59:21 rivo volumio[3520]: info: CONSUME SERVICE: Received update from a service different from the one supposed to be playing music. Skipping notification. Current mpd Received tidalconnect Oct 17 01:59:22 rivo volumio[3520]: info: VolumeController::SetAlsaVolume33 Oct 17 01:59:22 rivo volumio[3520]: info: CoreStateMachine::pushState Oct 17 01:59:22 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 17 01:59:22 rivo volumio[3520]: info: CoreCommandRouter::volumioPushState Oct 17 01:59:22 rivo volumio[3520]: info: CoreCommandRouter::volumioGetState Oct 17 01:59:22 rivo volumio[3520]: info: MRS: Pushing multiroomSync output update for this device Oct 17 01:59:22 rivo volumio[3520]: info: MRS: Pushing multiroomSync output Oct 17 01:59:22 rivo volumio5-onboarding[3870]: time=2026-10-17T01:59:22.693+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.222:53361,00:00:00:00:00:00%0e @ 0x1d3edb0" state=STATUS_PLAYING positionMs=66416 volume=33 Oct 17 01:59:22 rivo volumio5-onboarding[3870]: time=2026-10-17T01:59:22.693+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.222:53361,00:00:00:00:00:00%0e @ 0x1d3edb0" id=tidal://song/68735572 title="Changes (2015 Remaster)" Oct 17 01:59:22 rivo volumio[3520]: info: Signalling Playback active due to playback status change Oct 17 01:59:22 rivo volumio[3520]: info: Updating RAAT Signal Path Oct 17 01:59:23 rivo volumio5-onboarding[3870]: time=2026-10-17T01:59:23.207+01:00 level=WARN msg="pending write exceeded maximum retries, dropping" component=ble/conn addr=13 chunks=1 index=0 tries=11 Oct 17 01:59:23 rivo volumio5-onboarding[3870]: time=2026-10-17T01:59:23.207+01:00 level=ERROR msg="failed to send event" component=server dst="00:00:00:00:00:00%0d @ 0x1d76090" event=SERVER_EVENT_TYPE_PLAYER_STATE_CHANGED error="peer is gone" Oct 17 01:59:23 rivo volumio5-onboarding[3870]: time=2026-10-17T01:59:23.208+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.222:53361,00:00:00:00:00:00%0e @ 0x1d3edb0" id= title= Oct 17 01:59:24 rivo volumio[3520]: info: TidalConnect service started! Oct 17 01:59:26 rivo volumio5-onboarding[3870]: time=2026-10-17T01:59:26.870+01:00 level=WARN msg="pending write exceeded maximum retries, dropping" component=ble/conn addr=13 chunks=1 index=0 tries=11 Oct 17 01:59:26 rivo volumio5-onboarding[3870]: time=2026-10-17T01:59:26.871+01:00 level=ERROR msg="failed to send event" component=server dst="00:00:00:00:00:00%0d @ 0x1d76090" event=SERVER_EVENT_TYPE_PLAYER_STATE_CHANGED error="peer is gone" Oct 17 01:59:26 rivo volumio5-onboarding[3870]: time=2026-10-17T01:59:26.871+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.222:53361,00:00:00:00:00:00%0e @ 0x1d3edb0" id= title= Oct 17 01:59:30 rivo volumio5-onboarding[3870]: time=2026-10-17T01:59:30.315+01:00 level=WARN msg="pending write exceeded maximum retries, dropping" component=ble/conn addr=13 chunks=1 index=0 tries=11 Oct 17 01:59:30 rivo volumio5-onboarding[3870]: time=2026-10-17T01:59:30.316+01:00 level=ERROR msg="failed to send event" component=server dst="00:00:00:00:00:00%0d @ 0x1d76090" event=SERVER_EVENT_TYPE_PLAYER_STATE_CHANGED error="peer is gone" Oct 17 01:59:30 rivo volumio5-onboarding[3870]: time=2026-10-17T01:59:30.316+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.222:53361,00:00:00:00:00:00%0e @ 0x1d3edb0" id= title= Oct 17 01:59:31 rivo volumio[3520]: info: CALLMETHOD: audio_interface alsa_controller saveVolumeOptions [object Object] Oct 17 01:59:31 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , saveVolumeOptions Oct 17 01:59:31 rivo volumio[3520]: info: CoreCommandRouter::volumioGetState Oct 17 01:59:31 rivo volumio[3520]: info: Restoring Previous Volume level: 33 false true Oct 17 01:59:31 rivo volumio[3520]: info: VolumeController::SetAlsaVolume100 Oct 17 01:59:31 rivo volumio[3520]: info: Enable softmixer device for audio device number 5 Oct 17 01:59:31 rivo volumio[3520]: info: CoreCommandRouter::volumioStop Oct 17 01:59:31 rivo volumio[3520]: info: CoreStateMachine::stop Oct 17 01:59:31 rivo volumio[3520]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 17 01:59:31 rivo volumio[3520]: info: CoreStateMachine::stPlaybackTimer Oct 17 01:59:31 rivo volumio[3520]: info: CoreStateMachine::updateTrackBlock Oct 17 01:59:31 rivo volumio[3520]: info: CorePlayQueue::getTrackBlock Oct 17 01:59:31 rivo volumio[3520]: info: CoreStateMachine::pushState Oct 17 01:59:31 rivo volumio[3520]: info: CorePlayQueue::getTrack 0 Oct 17 01:59:31 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 17 01:59:31 rivo volumio[3520]: info: CoreCommandRouter::volumioPushState Oct 17 01:59:31 rivo volumio[3520]: info: CoreCommandRouter::volumioGetState Oct 17 01:59:31 rivo volumio[3520]: info: CorePlayQueue::getTrack 0 Oct 17 01:59:31 rivo volumio[3520]: info: MRS: Pushing multiroomSync output update for this device Oct 17 01:59:31 rivo volumio[3520]: info: MRS: Pushing multiroomSync output Oct 17 01:59:31 rivo volumio[3520]: info: CoreStateMachine::serviceStop Oct 17 01:59:31 rivo volumio[3520]: info: CorePlayQueue::getTrack 0 Oct 17 01:59:31 rivo volumio[3520]: info: CoreCommandRouter::serviceStop Oct 17 01:59:31 rivo volumio[3520]: info: [1792198771036] ControllerTidal::stop Oct 17 01:59:31 rivo volumio[3520]: info: CoreStateMachine::setConsumeUpdateService mpd Oct 17 01:59:31 rivo volumio[3520]: info: ControllerMpd::stop Oct 17 01:59:31 rivo volumio[3520]: verbose: ControllerMpd::sendMpdCommand stop Oct 17 01:59:31 rivo volumio[3520]: info: Enable softmixer device for audio device undefined Oct 17 01:59:31 rivo volumio[3520]: info: Output device has changed, restarting MPD Oct 17 01:59:31 rivo volumio[3520]: info: Output device has changed, restarting Shairport Sync Oct 17 01:59:31 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:31 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 17 01:59:31 rivo sudo[30769]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 17 01:59:31 rivo sudo[30769]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 17 01:59:31 rivo sudo[30769]: pam_unix(sudo:session): session closed for user root Oct 17 01:59:31 rivo sudo[30771]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 17 01:59:31 rivo sudo[30771]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 17 01:59:31 rivo volumio[3520]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 17 01:59:31 rivo volumio[3520]: info: MRS: Audio Device Changed, rebuilding Multiroom Configuration Oct 17 01:59:31 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:31 rivo volumio[3520]: info: QobuzConnect: setDeactiveState invoked Oct 17 01:59:31 rivo volumio[3520]: info: CoreCommandRouter::volumioGetState Oct 17 01:59:31 rivo volumio[3520]: info: Reconfiguring and Restarting RAAT Plugin due to audio device changes Oct 17 01:59:31 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:31 rivo vtcs[30730]: [2026-10-17 01:59:31.117] [tisoc] [warning] [SessionManagerImpl.cpp:240] Illegal State: IDLE Oct 17 01:59:31 rivo vtcs[30730]: [2026-10-17 01:59:31.120] [tisoc] [error] [SpkconServer.cpp:383] recv error. client fd=5 errorno=104 error=Connection reset by peer Oct 17 01:59:31 rivo vtcs[30730]: [2026-10-17 01:59:31.120] [tisoc] [error] [SpkconServer.cpp:378] recv error. socket disconnected Oct 17 01:59:31 rivo volumio[3520]: info: Volume configurations have been set Oct 17 01:59:31 rivo volumio[3520]: info: QobuzConnect: setDeactiveState invoked Oct 17 01:59:31 rivo volumio[3520]: info: CoreCommandRouter::volumioGetState Oct 17 01:59:31 rivo volumio[3520]: info: Reconfiguring and Restarting RAAT Plugin due to audio path changes Oct 17 01:59:31 rivo systemd[1]: Stopping mpd.service - Music Player Daemon... Oct 17 01:59:31 rivo sudo[30780]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service Oct 17 01:59:31 rivo sudo[30780]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 17 01:59:31 rivo sudo[30782]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service Oct 17 01:59:31 rivo sudo[30782]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 17 01:59:31 rivo volumio[3520]: info: CoreCommandRouter::volumioUpdateVolumeSettings Oct 17 01:59:31 rivo volumio[3520]: info: Updating Volume Controller Parameters: Device: 5 Name: Volumio Preciso Mixer: PCM Max Vol: 100 Vol Curve; logarithmic Vol Steps: 1 Oct 17 01:59:31 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , setExternalVolume Oct 17 01:59:31 rivo volumio[3520]: info: Disabling external Volume Control Oct 17 01:59:31 rivo volumio[3520]: info: CoreCommandRouter::getUIConfigOnPlugin Oct 17 01:59:31 rivo volumio[3520]: info: CoreStateMachine::pushState Oct 17 01:59:31 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 17 01:59:31 rivo volumio[3520]: info: CoreCommandRouter::volumioPushState Oct 17 01:59:31 rivo volumio[3520]: info: CoreCommandRouter::volumioGetState Oct 17 01:59:31 rivo volumio[3520]: info: MRS: Pushing multiroomSync output update for this device Oct 17 01:59:31 rivo volumio[3520]: info: MRS: Pushing multiroomSync output Oct 17 01:59:31 rivo volumio5-onboarding[3870]: time=2026-10-17T01:59:31.225+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.222:53361,00:00:00:00:00:00%0e @ 0x1d3edb0" state=STATUS_STOPPED positionMs=0 volume=33 Oct 17 01:59:31 rivo volumio5-onboarding[3870]: time=2026-10-17T01:59:31.225+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.222:53361,00:00:00:00:00:00%0e @ 0x1d3edb0" id=tidal://song/68735572 title="Changes (2015 Remaster)" Oct 17 01:59:31 rivo volumio5-onboarding[3870]: time=2026-10-17T01:59:31.227+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.222:53361,00:00:00:00:00:00%0e @ 0x1d3edb0" state=STATUS_PLAYING positionMs=0 volume=100 Oct 17 01:59:31 rivo volumio5-onboarding[3870]: time=2026-10-17T01:59:31.227+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.222:53361,00:00:00:00:00:00%0e @ 0x1d3edb0" id=tidal://song/68735572 title="Changes (2015 Remaster)" Oct 17 01:59:31 rivo systemd[1]: Stopping vtcs.service - Volumio Tidal Connect Service... Oct 17 01:59:31 rivo systemd[1]: mpd.service: Deactivated successfully. Oct 17 01:59:31 rivo systemd[1]: Stopped mpd.service - Music Player Daemon. Oct 17 01:59:31 rivo systemd[1]: vtcs.service: Deactivated successfully. Oct 17 01:59:31 rivo systemd[1]: Stopped vtcs.service - Volumio Tidal Connect Service. Oct 17 01:59:31 rivo volumio[3520]: error: MPD error: Error: write EPIPE Oct 17 01:59:31 rivo volumio[3520]: error: write EPIPE {"code":"EPIPE","errno":-32,"syscall":"write"} Oct 17 01:59:31 rivo sudo[30780]: pam_unix(sudo:session): session closed for user root Oct 17 01:59:31 rivo sudo[30795]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service Oct 17 01:59:31 rivo sudo[30795]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 17 01:59:31 rivo sudo[30782]: pam_unix(sudo:session): session closed for user root Oct 17 01:59:31 rivo sudo[30797]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service Oct 17 01:59:31 rivo sudo[30797]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 17 01:59:31 rivo systemd[1]: mpd.socket: Deactivated successfully. Oct 17 01:59:31 rivo systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Oct 17 01:59:31 rivo systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Oct 17 01:59:31 rivo systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Oct 17 01:59:31 rivo systemd[1]: Starting mpd.service - Music Player Daemon... Oct 17 01:59:31 rivo sudo[30807]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl reset-failed qobuz-connect.service Oct 17 01:59:31 rivo sudo[30807]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 17 01:59:31 rivo volumio[3520]: info: Signalling Playback active due to playback status change Oct 17 01:59:31 rivo volumio[3520]: info: Updating RAAT Signal Path Oct 17 01:59:31 rivo volumio[3520]: info: Updating RAAT Signal Path Oct 17 01:59:31 rivo sudo[30822]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl reset-failed qobuz-connect.service Oct 17 01:59:31 rivo sudo[30822]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 17 01:59:31 rivo volumio[3520]: info: CoreStateMachine::pushState Oct 17 01:59:31 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 17 01:59:31 rivo volumio[3520]: info: CoreCommandRouter::volumioPushState Oct 17 01:59:31 rivo volumio[3520]: info: CoreCommandRouter::volumioGetState Oct 17 01:59:31 rivo volumio[3520]: info: MRS: Pushing multiroomSync output update for this device Oct 17 01:59:31 rivo volumio[3520]: info: MRS: Pushing multiroomSync output Oct 17 01:59:31 rivo sudo[30795]: pam_unix(sudo:session): session closed for user root Oct 17 01:59:31 rivo volumio5-onboarding[3870]: time=2026-10-17T01:59:31.454+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.222:53361,00:00:00:00:00:00%0e @ 0x1d3edb0" state=STATUS_PLAYING positionMs=385 volume=100 Oct 17 01:59:31 rivo volumio5-onboarding[3870]: time=2026-10-17T01:59:31.454+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.222:53361,00:00:00:00:00:00%0e @ 0x1d3edb0" id=tidal://song/68735572 title="Changes (2015 Remaster)" Oct 17 01:59:31 rivo volumio[3520]: error: Failed to parse min max audio card capabilities, sending default vales: TypeError: Cannot read properties of undefined (reading 'split') Oct 17 01:59:31 rivo volumio[3520]: info: MPD Permissions set Oct 17 01:59:31 rivo volumio[3520]: info: VolumeController:: alsactl monitor closed, code: 0 Oct 17 01:59:31 rivo sudo[30797]: pam_unix(sudo:session): session closed for user root Oct 17 01:59:31 rivo volumio[3520]: info: Software Volume ALSA configuration written Oct 17 01:59:31 rivo volumio[3520]: info: Preparing to generate the ALSA configuration file Oct 17 01:59:31 rivo volumio[3520]: info: The plugin alsa_controller has an ALSA contribution file softvolume.postVolume.conf Oct 17 01:59:31 rivo volumio[3520]: info: The plugin multiroom has an ALSA contribution file volumioMultiRoomServer.postMultiRoom.1000.conf Oct 17 01:59:31 rivo sudo[30807]: pam_unix(sudo:session): session closed for user root Oct 17 01:59:31 rivo volumio[3520]: info: Reading ALSA contributions from plugins. Oct 17 01:59:31 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:31 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:31 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:31 rivo sudo[30822]: pam_unix(sudo:session): session closed for user root Oct 17 01:59:31 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:31 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:31 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:31 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:31 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:31 rivo sudo[30826]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart qobuz-connect.service Oct 17 01:59:31 rivo sudo[30827]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart qobuz-connect.service Oct 17 01:59:31 rivo sudo[30827]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 17 01:59:31 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 17 01:59:31 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: system , getCPUCoresNumber Oct 17 01:59:31 rivo sudo[30826]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 17 01:59:31 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:31 rivo systemd[1]: Stopping qobuz-connect.service - Volumio Qobuz Connect Service... Oct 17 01:59:31 rivo qobuz-connect[30711]: 20261017 01:59:31.598 [30711.30711] INFO SampleApp: Stopping Local configuration server Oct 17 01:59:31 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions Oct 17 01:59:31 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 17 01:59:31 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Oct 17 01:59:31 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 17 01:59:31 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 17 01:59:31 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 17 01:59:31 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 17 01:59:31 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 17 01:59:31 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 17 01:59:31 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 17 01:59:31 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: mpd , getPlaybackMode Oct 17 01:59:31 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus Oct 17 01:59:31 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: raat , getAdditionalUiSection Oct 17 01:59:31 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:31 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:31 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:31 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:31 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:31 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:31 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:31 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:31 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 17 01:59:31 rivo volumio[3520]: info: Not Reporting Auto name since its the default one Oct 17 01:59:31 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:31 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:31 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:31 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:31 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:31 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:31 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:31 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:31 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 17 01:59:31 rivo volumio[3520]: info: Not Reporting Auto name since its the default one Oct 17 01:59:31 rivo volumio[3520]: info: MCU Signalled Playback Inactive Oct 17 01:59:31 rivo volumio[3520]: info: MCU Signalled Playback Active Oct 17 01:59:31 rivo volumio[3520]: info: Starting Shairport Sync Oct 17 01:59:31 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:31 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:31 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkCurrentAudioDeviceAvailable Oct 17 01:59:31 rivo sudo[30849]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 17 01:59:31 rivo sudo[30849]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 17 01:59:31 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkCurrentAudioDeviceAvailable Oct 17 01:59:31 rivo systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Oct 17 01:59:31 rivo systemd[1]: shairport-sync.service: Deactivated successfully. Oct 17 01:59:31 rivo systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Oct 17 01:59:31 rivo sudo[30854]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl reset-failed raat-daemon.service Oct 17 01:59:31 rivo systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Oct 17 01:59:31 rivo sudo[30854]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 17 01:59:31 rivo sudo[30849]: pam_unix(sudo:session): session closed for user root Oct 17 01:59:31 rivo sudo[30809]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Oct 17 01:59:31 rivo sudo[30809]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Oct 17 01:59:31 rivo volumio[3520]: info: Shairport-Sync Started Oct 17 01:59:31 rivo sudo[30809]: pam_unix(sudo:session): session closed for user root Oct 17 01:59:31 rivo volumio[3520]: info: Asound.conf file written Oct 17 01:59:31 rivo sudo[30854]: pam_unix(sudo:session): session closed for user root Oct 17 01:59:31 rivo sudo[30860]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl reset-failed raat-daemon.service Oct 17 01:59:31 rivo sudo[30860]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 17 01:59:31 rivo sudo[30864]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart raat-daemon.service Oct 17 01:59:31 rivo sudo[30863]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mv /home/volumio/.asoundrc /etc/asound.conf Oct 17 01:59:31 rivo sudo[30863]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 17 01:59:31 rivo sudo[30864]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 17 01:59:31 rivo sudo[30860]: pam_unix(sudo:session): session closed for user root Oct 17 01:59:31 rivo sudo[30863]: pam_unix(sudo:session): session closed for user root Oct 17 01:59:31 rivo sudo[30883]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart raat-daemon.service Oct 17 01:59:31 rivo sudo[30883]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 17 01:59:32 rivo systemd[1]: Stopping raat-daemon.service - RAAT DAEMON... Oct 17 01:59:32 rivo systemd[1]: raat-daemon.service: Deactivated successfully. Oct 17 01:59:32 rivo systemd[1]: Stopped raat-daemon.service - RAAT DAEMON. Oct 17 01:59:32 rivo kernel: Fine tdm clk setting range (0~2000000), 12287994 Oct 17 01:59:32 rivo kernel: Err: can not set rate to 4250967296! Oct 17 01:59:32 rivo kernel: Range[3920000 - 500000000] Oct 17 01:59:32 rivo kernel: out of value, fixed it Oct 17 01:59:32 rivo kernel: id=0 set inskew=0 Oct 17 01:59:32 rivo systemd[1]: Started raat-daemon.service - RAAT DAEMON. Oct 17 01:59:32 rivo volumio[3520]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:0 use case configuration -2 Oct 17 01:59:32 rivo volumio[3520]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:0 use case configuration -2 Oct 17 01:59:32 rivo volumio[3520]: Found hardware: "AML-AUGESOUND-M" "" "" "" "" Oct 17 01:59:32 rivo volumio[3520]: Hardware is initialized using a generic method Oct 17 01:59:32 rivo volumio[3520]: /usr/sbin/alsactl: set_control:1475: Cannot write control '2:0:0:eARC_TX CDS:0' : Operation not permitted Oct 17 01:59:32 rivo volumio[3520]: /usr/sbin/alsactl: set_control:1475: Cannot write control '2:0:0:I2SIn CLK:0' : Operation not permitted Oct 17 01:59:32 rivo volumio[3520]: /usr/sbin/alsactl: set_control:1475: Cannot write control '2:0:0:SPDIFIN audio samplerate:0' : Operation not permitted Oct 17 01:59:32 rivo volumio[3520]: /usr/sbin/alsactl: set_control:1475: Cannot write control '2:0:0:SPDIFIN Audio Type:0' : Operation not permitted Oct 17 01:59:32 rivo volumio[3520]: /usr/sbin/alsactl: set_control:1475: Cannot write control '2:0:0:Clock Source 5 Validity:0' : Operation not permitted Oct 17 01:59:32 rivo volumio[3520]: info: Output device has changed, restarting MPD Oct 17 01:59:32 rivo sudo[30864]: pam_unix(sudo:session): session closed for user root Oct 17 01:59:32 rivo systemd[1]: Stopping raat-daemon.service - RAAT DAEMON... Oct 17 01:59:32 rivo systemd[1]: raat-daemon.service: Deactivated successfully. Oct 17 01:59:32 rivo systemd[1]: Stopped raat-daemon.service - RAAT DAEMON. Oct 17 01:59:32 rivo volumio[3520]: info: Output device has changed, restarting Shairport Sync Oct 17 01:59:32 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:32 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 17 01:59:32 rivo systemd[1]: Started raat-daemon.service - RAAT DAEMON. Oct 17 01:59:32 rivo sudo[30883]: pam_unix(sudo:session): session closed for user root Oct 17 01:59:32 rivo sudo[30894]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 17 01:59:32 rivo sudo[30894]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 17 01:59:32 rivo sudo[30894]: pam_unix(sudo:session): session closed for user root Oct 17 01:59:32 rivo sudo[30898]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 17 01:59:32 rivo sudo[30898]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 17 01:59:32 rivo volumio[3520]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 17 01:59:32 rivo volumio[3520]: info: MRS: Audio Device Changed, rebuilding Multiroom Configuration Oct 17 01:59:32 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:32 rivo volumio[3520]: info: QobuzConnect: setDeactiveState invoked Oct 17 01:59:32 rivo volumio[3520]: info: CoreCommandRouter::volumioGetState Oct 17 01:59:32 rivo volumio[3520]: info: Reconfiguring and Restarting RAAT Plugin due to audio device changes Oct 17 01:59:32 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:32 rivo volumio[3520]: info: Preparing to generate the ALSA configuration file Oct 17 01:59:32 rivo sudo[30910]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service Oct 17 01:59:32 rivo sudo[30910]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 17 01:59:32 rivo volumio[3520]: ALSA lib pcm.c:2666:(snd_pcm_open_noupdate) Unknown PCM volumioMultiRoomServer Oct 17 01:59:32 rivo volumio[3520]: aplay: main:831: audio open error: No such file or directory Oct 17 01:59:32 rivo kernel: Fine tdm clk setting range (0~2000000), 12287994 Oct 17 01:59:32 rivo kernel: Err: can not set rate to 4246967296! Oct 17 01:59:32 rivo kernel: Range[3920000 - 500000000] Oct 17 01:59:32 rivo kernel: out of value, fixed it Oct 17 01:59:32 rivo kernel: id=0 set inskew=0 Oct 17 01:59:32 rivo volumio[3520]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:0 use case configuration -2 Oct 17 01:59:32 rivo volumio[3520]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:0 use case configuration -2 Oct 17 01:59:32 rivo volumio[3520]: Found hardware: "AML-AUGESOUND-M" "" "" "" "" Oct 17 01:59:32 rivo volumio[3520]: Hardware is initialized using a generic method Oct 17 01:59:32 rivo volumio[3520]: /usr/sbin/alsactl: set_control:1475: Cannot write control '2:0:0:eARC_TX CDS:0' : Operation not permitted Oct 17 01:59:32 rivo volumio[3520]: /usr/sbin/alsactl: set_control:1475: Cannot write control '2:0:0:I2SIn CLK:0' : Operation not permitted Oct 17 01:59:32 rivo volumio[3520]: /usr/sbin/alsactl: set_control:1475: Cannot write control '2:0:0:SPDIFIN audio samplerate:0' : Operation not permitted Oct 17 01:59:32 rivo volumio[3520]: /usr/sbin/alsactl: set_control:1475: Cannot write control '2:0:0:SPDIFIN Audio Type:0' : Operation not permitted Oct 17 01:59:32 rivo volumio[3520]: /usr/sbin/alsactl: set_control:1475: Cannot write control '2:0:0:Clock Source 5 Validity:0' : Operation not permitted Oct 17 01:59:32 rivo volumio[3520]: info: QobuzConnect: setDeactiveState invoked Oct 17 01:59:32 rivo volumio[3520]: info: CoreCommandRouter::volumioGetState Oct 17 01:59:32 rivo volumio[3520]: info: Reconfiguring and Restarting RAAT Plugin due to audio path changes Oct 17 01:59:32 rivo volumio[3520]: info: Output device has changed, restarting MPD Oct 17 01:59:32 rivo sudo[30910]: pam_unix(sudo:session): session closed for user root Oct 17 01:59:32 rivo volumio[3520]: info: Output device has changed, restarting Shairport Sync Oct 17 01:59:32 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:32 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 17 01:59:32 rivo systemd[1]: mpd.service: Deactivated successfully. Oct 17 01:59:32 rivo systemd[1]: Stopped mpd.service - Music Player Daemon. Oct 17 01:59:32 rivo sudo[30918]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service Oct 17 01:59:32 rivo sudo[30918]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 17 01:59:32 rivo systemd[1]: mpd.socket: Deactivated successfully. Oct 17 01:59:32 rivo systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Oct 17 01:59:32 rivo systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Oct 17 01:59:32 rivo sudo[30921]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 17 01:59:32 rivo sudo[30921]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 17 01:59:32 rivo sudo[30922]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 17 01:59:32 rivo sudo[30922]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 17 01:59:32 rivo sudo[30921]: pam_unix(sudo:session): session closed for user root Oct 17 01:59:32 rivo qobuz-connect[30711]: 20261017 01:59:32.481 [30711.30711] INFO SampleApp: shat down connection on UNIX socket Oct 17 01:59:32 rivo systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Oct 17 01:59:32 rivo volumio[3520]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 17 01:59:32 rivo volumio[3520]: info: MRS: Audio Device Changed, rebuilding Multiroom Configuration Oct 17 01:59:32 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:32 rivo volumio[3520]: info: QobuzConnect: setDeactiveState invoked Oct 17 01:59:32 rivo volumio[3520]: info: CoreCommandRouter::volumioGetState Oct 17 01:59:32 rivo volumio[3520]: info: Reconfiguring and Restarting RAAT Plugin due to audio device changes Oct 17 01:59:32 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:32 rivo systemd[1]: Starting mpd.service - Music Player Daemon... Oct 17 01:59:32 rivo systemd[1]: qobuz-connect.service: Deactivated successfully. Oct 17 01:59:32 rivo systemd[1]: Stopped qobuz-connect.service - Volumio Qobuz Connect Service. Oct 17 01:59:32 rivo sudo[30934]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service Oct 17 01:59:32 rivo sudo[30934]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 17 01:59:32 rivo volumio[3520]: info: CoreCommandRouter::volumioUpdateVolumeSettings Oct 17 01:59:32 rivo volumio[3520]: info: Updating Volume Controller Parameters: Device: 5 Name: softvolume Mixer: SoftMaster Max Vol: 100 Vol Curve; logarithmic Vol Steps: 1 Oct 17 01:59:32 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , setExternalVolume Oct 17 01:59:32 rivo volumio[3520]: info: Disabling external Volume Control Oct 17 01:59:32 rivo systemd[1]: Started qobuz-connect.service - Volumio Qobuz Connect Service. Oct 17 01:59:32 rivo sudo[30826]: pam_unix(sudo:session): session closed for user root Oct 17 01:59:32 rivo sudo[30827]: pam_unix(sudo:session): session closed for user root Oct 17 01:59:32 rivo sudo[30947]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service Oct 17 01:59:32 rivo sudo[30949]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service Oct 17 01:59:32 rivo sudo[30949]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 17 01:59:32 rivo sudo[30947]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 17 01:59:32 rivo sudo[30934]: pam_unix(sudo:session): session closed for user root Oct 17 01:59:32 rivo systemd[1]: mpd.service: Deactivated successfully. Oct 17 01:59:32 rivo sudo[30952]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service Oct 17 01:59:32 rivo sudo[30952]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 17 01:59:33 rivo systemd[1]: Stopped mpd.service - Music Player Daemon. Oct 17 01:59:33 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:33 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:33 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:33 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:33 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:33 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:33 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:33 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:33 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 17 01:59:33 rivo volumio[3520]: info: Not Reporting Auto name since its the default one Oct 17 01:59:32 rivo sudo[30959]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl reset-failed qobuz-connect.service Oct 17 01:59:32 rivo sudo[30959]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 17 01:59:33 rivo volumio5-onboarding[3870]: time=2026-10-17T01:59:33.085+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.222:53361,00:00:00:00:00:00%0e @ 0x1d3edb0" state=STATUS_PLAYING positionMs=385 volume=100 Oct 17 01:59:33 rivo volumio5-onboarding[3870]: time=2026-10-17T01:59:33.085+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.222:53361,00:00:00:00:00:00%0e @ 0x1d3edb0" id=tidal://song/68735572 title="Changes (2015 Remaster)" Oct 17 01:59:33 rivo qobuz-connect[30940]: 20261017 01:59:33.221 [30940.30940] INFO SampleApp: Started connection to /tmp/qbz-connect.socket UNIX socket Oct 17 01:59:33 rivo qobuz-connect[30940]: 20261017 01:59:33.231 [30940.30940] INFO VolumeManager: [0xab9933c8]: Setting new playback volume: 75 Oct 17 01:59:33 rivo qobuz-connect[30940]: 20261017 01:59:33.231 [30940.30940] INFO VolumeManager: [0xab9933c8]: Setting new mute state: 0 Oct 17 01:59:33 rivo qobuz-connect[30940]: 20261017 01:59:33.231 [30940.30940] INFO AudioStreamManager: [0xab993120]: Setting new audio download buffer size: 1048576 Oct 17 01:59:33 rivo qobuz-connect[30940]: 20261017 01:59:33.231 [30940.30940] INFO QobuzConnect: [0xab993c90]: Client initialized! Oct 17 01:59:33 rivo qobuz-connect[30940]: 20261017 01:59:33.231 [30940.30940] INFO SampleApp: Starting Avahi advertising, name: Rivo, service name: _qobuz-connect._tcp Oct 17 01:59:33 rivo qobuz-connect[30940]: 20261017 01:59:33.255 [30940.30940] INFO LocalConfigManager: [0xab992e48]: Starting Local Configuration server Oct 17 01:59:33 rivo qobuz-connect[30940]: 20261017 01:59:33.255 [30940.30940] INFO SampleApp: Starting Local configuration server Oct 17 01:59:33 rivo qobuz-connect[30940]: 20261017 01:59:33.256 [30940.30940] INFO SampleApp: Connected to UNIX socket client 0xab97d908 Oct 17 01:59:33 rivo qobuz-connect[30940]: 20261017 01:59:33.370 [30940.30940] INFO SampleApp: Playback volume changed: 75 Oct 17 01:59:33 rivo systemd[1]: mpd.socket: Deactivated successfully. Oct 17 01:59:32 rivo sudo[30967]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl reset-failed qobuz-connect.service Oct 17 01:59:33 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:33 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:33 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:33 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:33 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:33 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:33 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:33 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:33 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 17 01:59:33 rivo volumio[3520]: info: Not Reporting Auto name since its the default one Oct 17 01:59:33 rivo volumio[3520]: info: The plugin alsa_controller has an ALSA contribution file softvolume.postVolume.conf Oct 17 01:59:33 rivo volumio[3520]: info: The plugin multiroom has an ALSA contribution file volumioMultiRoomServer.postMultiRoom.1000.conf Oct 17 01:59:33 rivo volumio[3520]: info: Reading ALSA contributions from plugins. Oct 17 01:59:33 rivo volumio[3520]: info: CoreStateMachine::pushState Oct 17 01:59:33 rivo volumio[3520]: info: CoreCommandRouter::volumioPushState Oct 17 01:59:33 rivo volumio[3520]: info: CoreCommandRouter::volumioGetState Oct 17 01:59:33 rivo volumio[3520]: info: MRS: Pushing multiroomSync output update for this device Oct 17 01:59:33 rivo volumio[3520]: info: MRS: Pushing multiroomSync output Oct 17 01:59:33 rivo volumio[3520]: error: Failed to parse min max audio card capabilities, sending default vales: TypeError: Cannot read properties of undefined (reading 'split') Oct 17 01:59:33 rivo volumio[3520]: info: MPD Permissions set Oct 17 01:59:33 rivo volumio[3520]: error: Failed to parse min max audio card capabilities, sending default vales: TypeError: Cannot read properties of undefined (reading 'split') Oct 17 01:59:33 rivo volumio[3520]: info: MPD Permissions set Oct 17 01:59:33 rivo volumio[3520]: info: QobuzConnect: Qobuz Connect client [object Object] disconnected Oct 17 01:59:33 rivo volumio[3520]: info: QobuzConnect: setDeactiveState invoked Oct 17 01:59:33 rivo volumio[3520]: info: CoreCommandRouter::volumioGetState Oct 17 01:59:33 rivo volumio[3520]: info: Raat Daemon started successfully Oct 17 01:59:33 rivo volumio[3520]: info: Raat Daemon started successfully Oct 17 01:59:33 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:33 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:33 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:33 rivo systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Oct 17 01:59:32 rivo sudo[30967]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 17 01:59:33 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:33 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:33 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:33 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:33 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:33 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 17 01:59:33 rivo volumio[3520]: info: Not Reporting Auto name since its the default one Oct 17 01:59:33 rivo volumio[3520]: info: Executing endpoint qc_getconfig Oct 17 01:59:33 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: qobuzconnect , onGetConfig Oct 17 01:59:33 rivo volumio[3520]: info: QobuzConnect: Qobuz Connect socket /tmp/qbz-connect.socket connected to client [object Object] Oct 17 01:59:33 rivo volumio[3520]: info: QobuzConnect: QOBUZ Connect daemon connected Oct 17 01:59:33 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:33 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:33 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:33 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:33 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:33 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:33 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:33 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:33 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 17 01:59:33 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: system , getCPUCoresNumber Oct 17 01:59:33 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:33 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:33 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:33 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:33 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:33 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:33 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:33 rivo systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Oct 17 01:59:32 rivo sudo[30972]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl reset-failed qobuz-connect.service Oct 17 01:59:33 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:33 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:33 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 17 01:59:33 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: system , getCPUCoresNumber Oct 17 01:59:33 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:33 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkCurrentAudioDeviceAvailable Oct 17 01:59:33 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkCurrentAudioDeviceAvailable Oct 17 01:59:33 rivo sudo[30972]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 17 01:59:33 rivo sudo[30918]: pam_unix(sudo:session): session closed for user root Oct 17 01:59:33 rivo sudo[30959]: pam_unix(sudo:session): session closed for user root Oct 17 01:59:33 rivo sudo[30967]: pam_unix(sudo:session): session closed for user root Oct 17 01:59:33 rivo sudo[30972]: pam_unix(sudo:session): session closed for user root Oct 17 01:59:33 rivo sudo[30987]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart qobuz-connect.service Oct 17 01:59:33 rivo sudo[30987]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 17 01:59:33 rivo sudo[30990]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart qobuz-connect.service Oct 17 01:59:33 rivo sudo[30990]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 17 01:59:33 rivo sudo[30988]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart qobuz-connect.service Oct 17 01:59:33 rivo sudo[30988]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 17 01:59:33 rivo systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Oct 17 01:59:33 rivo sudo[31014]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl reset-failed raat-daemon.service Oct 17 01:59:33 rivo sudo[31014]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 17 01:59:33 rivo systemd[1]: Starting mpd.service - Music Player Daemon... Oct 17 01:59:33 rivo volumio[3520]: info: CoreCommandRouter::volumioGetState Oct 17 01:59:33 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkCurrentAudioDeviceAvailable Oct 17 01:59:33 rivo sudo[31024]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl reset-failed raat-daemon.service Oct 17 01:59:33 rivo sudo[31024]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 17 01:59:33 rivo volumio[3520]: info: Starting Shairport Sync Oct 17 01:59:33 rivo volumio[3520]: info: Starting Shairport Sync Oct 17 01:59:33 rivo sudo[31029]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl reset-failed raat-daemon.service Oct 17 01:59:33 rivo sudo[31029]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 17 01:59:33 rivo sudo[30947]: pam_unix(sudo:session): session closed for user root Oct 17 01:59:33 rivo volumio[3520]: info: Executing endpoint restartRAATSocket Oct 17 01:59:33 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: raat , establishDaemonConnection Oct 17 01:59:33 rivo sudo[30952]: pam_unix(sudo:session): session closed for user root Oct 17 01:59:33 rivo sudo[31031]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 17 01:59:33 rivo sudo[31031]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 17 01:59:33 rivo volumio[3520]: info: Asound.conf file written Oct 17 01:59:33 rivo sudo[30949]: pam_unix(sudo:session): session closed for user root Oct 17 01:59:33 rivo sudo[31034]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 17 01:59:33 rivo sudo[31034]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 17 01:59:33 rivo sudo[31044]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mv /home/volumio/.asoundrc /etc/asound.conf Oct 17 01:59:33 rivo sudo[31044]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 17 01:59:33 rivo sudo[31044]: pam_unix(sudo:session): session closed for user root Oct 17 01:59:33 rivo sudo[31014]: pam_unix(sudo:session): session closed for user root Oct 17 01:59:33 rivo kernel: Fine tdm clk setting range (0~2000000), 12287994 Oct 17 01:59:33 rivo kernel: Err: can not set rate to 4242967296! Oct 17 01:59:33 rivo kernel: Range[3920000 - 500000000] Oct 17 01:59:33 rivo kernel: out of value, fixed it Oct 17 01:59:33 rivo kernel: id=0 set inskew=0 Oct 17 01:59:33 rivo sudo[31024]: pam_unix(sudo:session): session closed for user root Oct 17 01:59:33 rivo volumio[3520]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:0 use case configuration -2 Oct 17 01:59:33 rivo volumio[3520]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:0 use case configuration -2 Oct 17 01:59:33 rivo volumio[3520]: Found hardware: "AML-AUGESOUND-M" "" "" "" "" Oct 17 01:59:33 rivo volumio[3520]: Hardware is initialized using a generic method Oct 17 01:59:33 rivo volumio[3520]: /usr/sbin/alsactl: set_control:1475: Cannot write control '2:0:0:eARC_TX CDS:0' : Operation not permitted Oct 17 01:59:33 rivo volumio[3520]: /usr/sbin/alsactl: set_control:1475: Cannot write control '2:0:0:I2SIn CLK:0' : Operation not permitted Oct 17 01:59:33 rivo volumio[3520]: /usr/sbin/alsactl: set_control:1475: Cannot write control '2:0:0:SPDIFIN audio samplerate:0' : Operation not permitted Oct 17 01:59:33 rivo volumio[3520]: /usr/sbin/alsactl: set_control:1475: Cannot write control '2:0:0:SPDIFIN Audio Type:0' : Operation not permitted Oct 17 01:59:33 rivo volumio[3520]: /usr/sbin/alsactl: set_control:1475: Cannot write control '2:0:0:Clock Source 5 Validity:0' : Operation not permitted Oct 17 01:59:33 rivo volumio[3520]: info: Output device has changed, restarting MPD Oct 17 01:59:33 rivo sudo[31048]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart raat-daemon.service Oct 17 01:59:33 rivo sudo[31048]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 17 01:59:33 rivo sudo[31029]: pam_unix(sudo:session): session closed for user root Oct 17 01:59:33 rivo sudo[31049]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart raat-daemon.service Oct 17 01:59:33 rivo sudo[31049]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 17 01:59:33 rivo volumio[3520]: info: Output device has changed, restarting Shairport Sync Oct 17 01:59:33 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:33 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 17 01:59:33 rivo sudo[31053]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 17 01:59:33 rivo sudo[31053]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 17 01:59:33 rivo sudo[31052]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart raat-daemon.service Oct 17 01:59:33 rivo sudo[31052]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 17 01:59:33 rivo sudo[31053]: pam_unix(sudo:session): session closed for user root Oct 17 01:59:33 rivo systemd[1]: Stopping raat-daemon.service - RAAT DAEMON... Oct 17 01:59:33 rivo qobuz-connect[30940]: 20261017 01:59:33.858 [30940.30940] INFO SampleApp: Stopping Local configuration server Oct 17 01:59:33 rivo systemd[1]: Stopping qobuz-connect.service - Volumio Qobuz Connect Service... Oct 17 01:59:33 rivo systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Oct 17 01:59:33 rivo sudo[31056]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 17 01:59:33 rivo sudo[31056]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 17 01:59:33 rivo volumio[3520]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 17 01:59:33 rivo volumio[3520]: info: MRS: Audio Device Changed, rebuilding Multiroom Configuration Oct 17 01:59:33 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:33 rivo systemd[1]: shairport-sync.service: Deactivated successfully. Oct 17 01:59:33 rivo systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Oct 17 01:59:33 rivo systemd[1]: raat-daemon.service: Deactivated successfully. Oct 17 01:59:33 rivo systemd[1]: Stopped raat-daemon.service - RAAT DAEMON. Oct 17 01:59:33 rivo volumio[3520]: info: QobuzConnect: setDeactiveState invoked Oct 17 01:59:33 rivo volumio[3520]: info: CoreCommandRouter::volumioGetState Oct 17 01:59:33 rivo volumio[3520]: info: Reconfiguring and Restarting RAAT Plugin due to audio device changes Oct 17 01:59:33 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:33 rivo sudo[31066]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service Oct 17 01:59:33 rivo sudo[31066]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 17 01:59:33 rivo sudo[31069]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service Oct 17 01:59:33 rivo sudo[31069]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 17 01:59:34 rivo systemd[1]: Started raat-daemon.service - RAAT DAEMON. Oct 17 01:59:34 rivo sudo[31052]: pam_unix(sudo:session): session closed for user root Oct 17 01:59:34 rivo sudo[31048]: pam_unix(sudo:session): session closed for user root Oct 17 01:59:34 rivo sudo[31049]: pam_unix(sudo:session): session closed for user root Oct 17 01:59:34 rivo volumio[3520]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Oct 17 01:59:34 rivo systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Oct 17 01:59:34 rivo sudo[31031]: pam_unix(sudo:session): session closed for user root Oct 17 01:59:34 rivo sudo[31034]: pam_unix(sudo:session): session closed for user root Oct 17 01:59:34 rivo sudo[31082]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl reset-failed qobuz-connect.service Oct 17 01:59:34 rivo sudo[31082]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 17 01:59:34 rivo systemd[1]: mpd.service: Deactivated successfully. Oct 17 01:59:34 rivo systemd[1]: Stopped mpd.service - Music Player Daemon. Oct 17 01:59:34 rivo volumio[3520]: info: MPD Permissions set Oct 17 01:59:34 rivo volumio[3520]: info: Raat Daemon started successfully Oct 17 01:59:34 rivo volumio[3520]: info: Raat Daemon started successfully Oct 17 01:59:34 rivo volumio[3520]: info: Raat Daemon started successfully Oct 17 01:59:34 rivo volumio[3520]: info: Shairport-Sync Started Oct 17 01:59:34 rivo volumio[3520]: info: Shairport-Sync Started Oct 17 01:59:34 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:34 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:34 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:34 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:34 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:34 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:34 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:34 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:34 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 17 01:59:34 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: system , getCPUCoresNumber Oct 17 01:59:34 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:34 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: mpd , restartMpd Oct 17 01:59:34 rivo sudo[31082]: pam_unix(sudo:session): session closed for user root Oct 17 01:59:34 rivo systemd[1]: mpd.socket: Deactivated successfully. Oct 17 01:59:34 rivo systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Oct 17 01:59:34 rivo systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Oct 17 01:59:34 rivo sudo[31091]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart qobuz-connect.service Oct 17 01:59:34 rivo sudo[31091]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 17 01:59:34 rivo volumio[3520]: info: Starting Shairport Sync Oct 17 01:59:34 rivo systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Oct 17 01:59:34 rivo sudo[31106]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 17 01:59:34 rivo sudo[31106]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 17 01:59:34 rivo systemd[1]: Starting mpd.service - Music Player Daemon... Oct 17 01:59:34 rivo sudo[31111]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 17 01:59:34 rivo sudo[31111]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 17 01:59:34 rivo volumio[3520]: info: TidalConnect service stoped! Oct 17 01:59:34 rivo volumio[3520]: info: TidalConnect service stoped! Oct 17 01:59:34 rivo volumio[3520]: info: Preparing to generate the ALSA configuration file Oct 17 01:59:34 rivo volumio5-onboarding[3870]: time=2026-10-17T01:59:34.399+01:00 level=WARN msg="pending write exceeded maximum retries, dropping" component=ble/conn addr=13 chunks=1 index=0 tries=11 Oct 17 01:59:34 rivo volumio5-onboarding[3870]: time=2026-10-17T01:59:34.400+01:00 level=ERROR msg="failed to send event" component=server dst="00:00:00:00:00:00%0d @ 0x1d76090" event=SERVER_EVENT_TYPE_PLAYER_STATE_CHANGED error="peer is gone" Oct 17 01:59:34 rivo volumio5-onboarding[3870]: time=2026-10-17T01:59:34.400+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.222:53361,00:00:00:00:00:00%0e @ 0x1d3edb0" id= title= Oct 17 01:59:34 rivo volumio[3520]: info: The plugin alsa_controller has an ALSA contribution file softvolume.postVolume.conf Oct 17 01:59:34 rivo volumio[3520]: info: The plugin multiroom has an ALSA contribution file volumioMultiRoomServer.postMultiRoom.1000.conf Oct 17 01:59:34 rivo volumio[3520]: info: Reading ALSA contributions from plugins. Oct 17 01:59:34 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:34 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:34 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:34 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:34 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:34 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:34 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:34 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:34 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 17 01:59:34 rivo volumio[3520]: info: Not Reporting Auto name since its the default one Oct 17 01:59:34 rivo volumio[3520]: info: TidalConnect service stoped! Oct 17 01:59:34 rivo sudo[31066]: pam_unix(sudo:session): session closed for user root Oct 17 01:59:34 rivo volumio[3520]: info: TidalConnect service stoped! Oct 17 01:59:34 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkCurrentAudioDeviceAvailable Oct 17 01:59:34 rivo sudo[31069]: pam_unix(sudo:session): session closed for user root Oct 17 01:59:34 rivo sudo[31132]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl reset-failed raat-daemon.service Oct 17 01:59:34 rivo volumio[3520]: info: Asound.conf file written Oct 17 01:59:34 rivo sudo[31132]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 17 01:59:34 rivo systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Oct 17 01:59:34 rivo systemd[1]: shairport-sync.service: Deactivated successfully. Oct 17 01:59:34 rivo systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Oct 17 01:59:34 rivo sudo[31143]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mv /home/volumio/.asoundrc /etc/asound.conf Oct 17 01:59:34 rivo sudo[31143]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 17 01:59:34 rivo systemd[1]: mpd.service: Deactivated successfully. Oct 17 01:59:34 rivo systemd[1]: Stopped mpd.service - Music Player Daemon. Oct 17 01:59:34 rivo sudo[31143]: pam_unix(sudo:session): session closed for user root Oct 17 01:59:34 rivo systemd[1]: mpd.socket: Deactivated successfully. Oct 17 01:59:34 rivo kernel: Fine tdm clk setting range (0~2000000), 12287994 Oct 17 01:59:34 rivo kernel: Err: can not set rate to 4238967296! Oct 17 01:59:34 rivo kernel: Range[3920000 - 500000000] Oct 17 01:59:34 rivo kernel: out of value, fixed it Oct 17 01:59:34 rivo kernel: id=0 set inskew=0 Oct 17 01:59:34 rivo volumio[3520]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:0 use case configuration -2 Oct 17 01:59:34 rivo volumio[3520]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:0 use case configuration -2 Oct 17 01:59:34 rivo volumio[3520]: Found hardware: "AML-AUGESOUND-M" "" "" "" "" Oct 17 01:59:34 rivo volumio[3520]: Hardware is initialized using a generic method Oct 17 01:59:34 rivo volumio[3520]: /usr/sbin/alsactl: set_control:1475: Cannot write control '2:0:0:eARC_TX CDS:0' : Operation not permitted Oct 17 01:59:34 rivo volumio[3520]: /usr/sbin/alsactl: set_control:1475: Cannot write control '2:0:0:I2SIn CLK:0' : Operation not permitted Oct 17 01:59:34 rivo volumio[3520]: /usr/sbin/alsactl: set_control:1475: Cannot write control '2:0:0:SPDIFIN audio samplerate:0' : Operation not permitted Oct 17 01:59:34 rivo volumio[3520]: /usr/sbin/alsactl: set_control:1475: Cannot write control '2:0:0:SPDIFIN Audio Type:0' : Operation not permitted Oct 17 01:59:34 rivo volumio[3520]: /usr/sbin/alsactl: set_control:1475: Cannot write control '2:0:0:Clock Source 5 Validity:0' : Operation not permitted Oct 17 01:59:34 rivo volumio[3520]: info: Output device has changed, restarting MPD Oct 17 01:59:34 rivo systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Oct 17 01:59:34 rivo systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Oct 17 01:59:34 rivo volumio[3520]: info: Output device has changed, restarting Shairport Sync Oct 17 01:59:34 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:34 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 17 01:59:34 rivo systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Oct 17 01:59:34 rivo sudo[31148]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 17 01:59:34 rivo sudo[31148]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 17 01:59:34 rivo volumio[3520]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 17 01:59:34 rivo volumio[3520]: info: MRS: Audio Device Changed, rebuilding Multiroom Configuration Oct 17 01:59:34 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:34 rivo sudo[31148]: pam_unix(sudo:session): session closed for user root Oct 17 01:59:34 rivo sudo[31152]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 17 01:59:34 rivo sudo[31152]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 17 01:59:34 rivo volumio[3520]: info: QobuzConnect: setDeactiveState invoked Oct 17 01:59:34 rivo volumio[3520]: info: CoreCommandRouter::volumioGetState Oct 17 01:59:34 rivo volumio[3520]: info: Reconfiguring and Restarting RAAT Plugin due to audio device changes Oct 17 01:59:34 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:34 rivo systemd[1]: Starting mpd.service - Music Player Daemon... Oct 17 01:59:34 rivo systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Oct 17 01:59:34 rivo sudo[31111]: pam_unix(sudo:session): session closed for user root Oct 17 01:59:35 rivo sudo[31162]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service Oct 17 01:59:35 rivo sudo[31164]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service Oct 17 01:59:35 rivo sudo[31162]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 17 01:59:35 rivo sudo[31164]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 17 01:59:35 rivo sudo[31132]: pam_unix(sudo:session): session closed for user root Oct 17 01:59:35 rivo sudo[31170]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart raat-daemon.service Oct 17 01:59:35 rivo sudo[31170]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 17 01:59:35 rivo volumio[3520]: info: RAAT: Requesting Headphone Status Oct 17 01:59:35 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: inputs , getHeadphoneStatus Oct 17 01:59:35 rivo volumio[3520]: info: RAAT: Requesting Headphone Status Oct 17 01:59:35 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: inputs , getHeadphoneStatus Oct 17 01:59:35 rivo kernel: meson-remote ff808040.rc: invalid custom:0x197a1cfb Oct 17 01:59:35 rivo kernel: meson-remote ff808040.rc: cur_custom is nulll Oct 17 01:59:35 rivo kernel: meson-remote ff808040.rc: no valid key to handle Oct 17 01:59:35 rivo volumio[3520]: error: Failed to parse min max audio card capabilities, sending default vales: TypeError: Cannot read properties of undefined (reading 'split') Oct 17 01:59:35 rivo volumio[3520]: info: MPD Permissions set Oct 17 01:59:35 rivo volumio[3520]: info: Shairport-Sync Started Oct 17 01:59:35 rivo volumio[3520]: info: Updating tc_getconfig REST Endpoint for plugin: music_service/tidalconnect Oct 17 01:59:35 rivo volumio[3520]: info: Updating tc_connect REST Endpoint for plugin: music_service/tidalconnect Oct 17 01:59:35 rivo sudo[31184]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl reset-failed qobuz-connect.service Oct 17 01:59:35 rivo sudo[31184]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 17 01:59:35 rivo volumio[3520]: info: Updating tc_getconfig REST Endpoint for plugin: music_service/tidalconnect Oct 17 01:59:35 rivo volumio[3520]: info: Updating tc_connect REST Endpoint for plugin: music_service/tidalconnect Oct 17 01:59:35 rivo volumio[3520]: info: MCU Signalled Headphone Mode Disabled Oct 17 01:59:35 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: raat , reportHeadphoneState Oct 17 01:59:35 rivo volumio[3520]: info: Reporting Headphone State: false Oct 17 01:59:35 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:35 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:35 rivo volumio[3520]: info: Updating RAAT Signal Path Oct 17 01:59:35 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:35 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:35 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:35 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:35 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:35 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:35 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:35 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:35 rivo sudo[31191]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start vtcs.service Oct 17 01:59:35 rivo sudo[31191]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 17 01:59:35 rivo sudo[31193]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start vtcs.service Oct 17 01:59:35 rivo sudo[31193]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 17 01:59:35 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 17 01:59:35 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: system , getCPUCoresNumber Oct 17 01:59:35 rivo sudo[31184]: pam_unix(sudo:session): session closed for user root Oct 17 01:59:35 rivo qobuz-connect[30940]: 20261017 01:59:35.275 [30940.30940] INFO SampleApp: shat down connection on UNIX socket Oct 17 01:59:35 rivo systemd[1]: qobuz-connect.service: Deactivated successfully. Oct 17 01:59:35 rivo systemd[1]: Stopped qobuz-connect.service - Volumio Qobuz Connect Service. Oct 17 01:59:35 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:35 rivo sudo[31201]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart qobuz-connect.service Oct 17 01:59:35 rivo sudo[31201]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 17 01:59:35 rivo volumio[3520]: info: QobuzConnect: Qobuz Connect client [object Object] disconnected Oct 17 01:59:35 rivo volumio[3520]: info: QobuzConnect: setDeactiveState invoked Oct 17 01:59:35 rivo volumio[3520]: info: CoreCommandRouter::volumioGetState Oct 17 01:59:35 rivo volumio[3520]: info: MCU Signalled Headphone Mode Disabled Oct 17 01:59:35 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: raat , reportHeadphoneState Oct 17 01:59:35 rivo volumio[3520]: info: Reporting Headphone State: false Oct 17 01:59:35 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:35 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:35 rivo volumio[3520]: info: Updating RAAT Signal Path Oct 17 01:59:35 rivo volumio[3520]: info: Starting Shairport Sync Oct 17 01:59:35 rivo sudo[31162]: pam_unix(sudo:session): session closed for user root Oct 17 01:59:35 rivo volumio[3520]: info: Preparing to generate the ALSA configuration file Oct 17 01:59:35 rivo sudo[31164]: pam_unix(sudo:session): session closed for user root Oct 17 01:59:35 rivo sudo[31209]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 17 01:59:35 rivo sudo[31209]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 17 01:59:35 rivo systemd[1]: Stopping raat-daemon.service - RAAT DAEMON... Oct 17 01:59:35 rivo systemd[1]: Started qobuz-connect.service - Volumio Qobuz Connect Service. Oct 17 01:59:35 rivo sudo[30988]: pam_unix(sudo:session): session closed for user root Oct 17 01:59:35 rivo sudo[30987]: pam_unix(sudo:session): session closed for user root Oct 17 01:59:35 rivo sudo[31091]: pam_unix(sudo:session): session closed for user root Oct 17 01:59:35 rivo sudo[30990]: pam_unix(sudo:session): session closed for user root Oct 17 01:59:35 rivo systemd[1]: Started vtcs.service - Volumio Tidal Connect Service. Oct 17 01:59:35 rivo sudo[31191]: pam_unix(sudo:session): session closed for user root Oct 17 01:59:35 rivo sudo[31193]: pam_unix(sudo:session): session closed for user root Oct 17 01:59:35 rivo systemd[1]: raat-daemon.service: Deactivated successfully. Oct 17 01:59:35 rivo systemd[1]: Stopped raat-daemon.service - RAAT DAEMON. Oct 17 01:59:35 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:35 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:35 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:35 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:35 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:35 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:35 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:35 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 01:59:35 rivo volumio[3520]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 17 01:59:35 rivo volumio[3520]: info: Not Reporting Auto name since its the default one Oct 17 01:59:35 rivo volumio[3520]: info: The plugin alsa_controller has an ALSA contribution file softvolume.postVolume.conf Oct 17 01:59:35 rivo volumio[3520]: info: The plugin multiroom has an ALSA contribution file volumioMultiRoomServer.postMultiRoom.1000.conf Oct 17 01:59:35 rivo systemd[1]: mpd.service: Deactivated successfully. Oct 17 01:59:35 rivo volumio[3520]: info: Reading ALSA contributions from plugins. Oct 17 01:59:35 rivo systemd[1]: Stopped mpd.service - Music Player Daemon. Oct 17 01:59:35 rivo volumio[3520]: info: TidalConnect service stoped! Oct 17 01:59:35 rivo volumio[3520]: error: Error starting TidalConnect Command failed: /usr/bin/sudo /bin/systemctl stop vtcs.service && sleep 3 Oct 17 01:59:35 rivo volumio[3520]: Job for vtcs.service canceled. Oct 17 01:59:35 rivo volumio[3520]: {"cmd":"/usr/bin/sudo /bin/systemctl stop vtcs.service && sleep 3","code":1,"killed":false,"signal":null,"stack":"Error: Command failed: /usr/bin/sudo /bin/systemctl stop vtcs.service && sleep 3\nJob for vtcs.service canceled.\n\n at ChildProcess.exithandler (node:child_process:421:12)\n at ChildProcess.emit (node:events:514:28)\n at maybeClose (node:internal/child_process:1105:16)\n at Socket. (node:internal/child_process:457:11)\n at Socket.emit (node:events:514:28)\n at Pipe. (node:net:337:12)","stderr":"Job for vtcs.service canceled.\n","stdout":""} Oct 17 01:59:35 rivo volumio[3520]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 17 01:59:35 rivo volumio[3520]: Error: Command failed: /usr/bin/sudo /bin/systemctl stop vtcs.service && sleep 3 Oct 17 01:59:35 rivo volumio[3520]: Job for vtcs.service canceled. Oct 17 01:59:35 rivo volumio[3520]: at ChildProcess.exithandler (node:child_process:421:12) Oct 17 01:59:35 rivo volumio[3520]: at ChildProcess.emit (node:events:514:28) Oct 17 01:59:35 rivo volumio[3520]: at maybeClose (node:internal/child_process:1105:16) Oct 17 01:59:35 rivo volumio[3520]: at Socket. (node:internal/child_process:457:11) Oct 17 01:59:35 rivo volumio[3520]: at Socket.emit (node:events:514:28) Oct 17 01:59:35 rivo volumio[3520]: at Pipe. (node:net:337:12) { Oct 17 01:59:35 rivo volumio[3520]: code: 1, Oct 17 01:59:35 rivo volumio[3520]: killed: false, Oct 17 01:59:35 rivo volumio[3520]: signal: null, Oct 17 01:59:35 rivo volumio[3520]: cmd: '/usr/bin/sudo /bin/systemctl stop vtcs.service && sleep 3', Oct 17 01:59:35 rivo volumio[3520]: stdout: '', Oct 17 01:59:35 rivo volumio[3520]: stderr: 'Job for vtcs.service canceled.\n' Oct 17 01:59:35 rivo volumio[3520]: } Oct 17 01:59:35 rivo volumio[3520]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 17 01:59:35 rivo sudo[31201]: pam_unix(sudo:session): session closed for user root Oct 17 01:59:35 rivo systemd[1]: mpd.socket: Deactivated successfully. Oct 17 01:59:35 rivo systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Oct 17 01:59:35 rivo systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Oct 17 01:59:35 rivo systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Oct 17 01:59:35 rivo systemd[1]: Started raat-daemon.service - RAAT DAEMON. Oct 17 01:59:35 rivo sudo[31170]: pam_unix(sudo:session): session closed for user root Oct 17 01:59:35 rivo systemd[1]: Starting mpd.service - Music Player Daemon... Oct 17 01:59:35 rivo systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Oct 17 01:59:35 rivo systemd[1]: shairport-sync.service: Deactivated successfully. Oct 17 01:59:35 rivo systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Oct 17 01:59:35 rivo systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Oct 17 01:59:35 rivo sudo[31209]: pam_unix(sudo:session): session closed for user root Oct 17 01:59:36 rivo sudo[31230]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Oct 17 01:59:36 rivo sudo[31230]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Oct 17 01:59:36 rivo sudo[31230]: pam_unix(sudo:session): session closed for user root Oct 17 01:59:36 rivo sudo[31271]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-10-17 01:58' Oct 17 01:59:36 rivo sudo[31271]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) PRETTY_NAME="Debian GNU/Linux 12 (bookworm)" NAME="Debian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm 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="8ed05bf20f96eb8557ed5652c420f84f39d66325" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="0a52c1fb90959ba1872a2fb0225e56fe615b19ac" VOLUMIO_ARCH="armv7" VOLUMIO_VARIANT="rivo" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Wed Sep 16 16:27:36 UTC 2026" VOLUMIO_VERSION="4.208" VOLUMIO_HARDWARE="mp1" VOLUMIO_DEVICENAME="Volumio MP1" VOLUMIO_VENDOR_MODEL="Volumio Rivo" VOLUMIO_VENDOR="Volumio" VOLUMIO_MODEL="Rivo" VOLUMIO_HASH="be0c94671215c2b1bf2440825a1e4211"