-- Logs begin at Thu 2025-12-11 19:47:33 EET, end at Fri 2025-12-19 02:09:56 EET. -- Dec 19 02:08:00 prrevo go-librespot[9538]: time="2025-12-19T02:08:00+02:00" level=debug msg="fetched chunk 9/16, size: 524288" uri="spotify:track:5a8tOynxc0BoTESRjK2L9j" Dec 19 02:08:01 prrevo volumio5-onboarding[3723]: time=2025-12-19T02:08:01.741+02:00 level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=1 Dec 19 02:08:01 prrevo volumio5-onboarding[3723]: time=2025-12-19T02:08:01.914+02:00 level=WARN msg="received acknowledgment for source with no pending writes" component=conn/ble data=0100 addr=1 Dec 19 02:08:02 prrevo dbus-daemon[2825]: [system] Rejected send message, 1 matched rules; type="error", sender=":1.15" (uid=0 pid=3723 comm="/usr/bin/volumio5-onboarding " label="kernel") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.7" (uid=0 pid=3315 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap,hostn" label="kernel") Dec 19 02:08:06 prrevo volumio5-onboarding[3723]: time=2025-12-19T02:08:06.843+02:00 level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=1 Dec 19 02:08:07 prrevo volumio5-onboarding[3723]: time=2025-12-19T02:08:07.144+02:00 level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=1 Dec 19 02:08:07 prrevo volumio5-onboarding[3723]: time=2025-12-19T02:08:07.446+02:00 level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=1 Dec 19 02:08:07 prrevo volumio5-onboarding[3723]: time=2025-12-19T02:08:07.747+02:00 level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=1 Dec 19 02:08:08 prrevo volumio5-onboarding[3723]: time=2025-12-19T02:08:08.048+02:00 level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=1 Dec 19 02:08:08 prrevo volumio5-onboarding[3723]: time=2025-12-19T02:08:08.348+02:00 level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=1 Dec 19 02:08:08 prrevo volumio5-onboarding[3723]: time=2025-12-19T02:08:08.650+02:00 level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=1 Dec 19 02:08:08 prrevo volumio5-onboarding[3723]: time=2025-12-19T02:08:08.951+02:00 level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=1 Dec 19 02:08:09 prrevo volumio5-onboarding[3723]: time=2025-12-19T02:08:09.252+02:00 level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=1 Dec 19 02:08:09 prrevo volumio5-onboarding[3723]: time=2025-12-19T02:08:09.553+02:00 level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=1 Dec 19 02:08:09 prrevo volumio5-onboarding[3723]: time=2025-12-19T02:08:09.854+02:00 level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=1 Dec 19 02:08:09 prrevo volumio5-onboarding[3723]: time=2025-12-19T02:08:09.854+02:00 level=ERROR msg="pending write exceeded maximum retries, dropping" component=conn/ble addr=1 chunks=1 index=0 Dec 19 02:08:13 prrevo go-librespot[9538]: time="2025-12-19T02:08:13+02:00" level=debug msg="fetched chunk 10/16, size: 524288" uri="spotify:track:5a8tOynxc0BoTESRjK2L9j" Dec 19 02:08:15 prrevo go-librespot[9538]: time="2025-12-19T02:08:15+02:00" level=trace msg="sent dealer ping" Dec 19 02:08:15 prrevo go-librespot[9538]: time="2025-12-19T02:08:15+02:00" level=trace msg="received dealer pong" Dec 19 02:08:28 prrevo go-librespot[9538]: time="2025-12-19T02:08:28+02:00" level=debug msg="fetched chunk 11/16, size: 524288" uri="spotify:track:5a8tOynxc0BoTESRjK2L9j" Dec 19 02:08:41 prrevo go-librespot[9538]: time="2025-12-19T02:08:41+02:00" level=debug msg="fetched chunk 12/16, size: 524288" uri="spotify:track:5a8tOynxc0BoTESRjK2L9j" Dec 19 02:08:45 prrevo go-librespot[9538]: time="2025-12-19T02:08:45+02:00" level=trace msg="received accesspoint ping" Dec 19 02:08:45 prrevo go-librespot[9538]: time="2025-12-19T02:08:45+02:00" level=trace msg="received accesspoint pong ack" Dec 19 02:08:45 prrevo go-librespot[9538]: time="2025-12-19T02:08:45+02:00" level=trace msg="sent dealer ping" Dec 19 02:08:45 prrevo go-librespot[9538]: time="2025-12-19T02:08:45+02:00" level=trace msg="received dealer pong" Dec 19 02:08:48 prrevo go-librespot[9538]: time="2025-12-19T02:08:48+02:00" level=debug msg="update volume requested to 63568/65535" Dec 19 02:08:48 prrevo go-librespot[9538]: time="2025-12-19T02:08:48+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Dec 19 02:08:48 prrevo go-librespot[9538]: time="2025-12-19T02:08:48+02:00" level=trace msg="emitting websocket event: volume" Dec 19 02:08:48 prrevo go-librespot[9538]: time="2025-12-19T02:08:48+02:00" level=debug msg="update volume requested to 49151/65535" Dec 19 02:08:48 prrevo volumio[5780]: SPOTIFY: received: {"type":"volume","data":{"value":97,"max":100}} Dec 19 02:08:48 prrevo volumio[5780]: SPOTIFY: RECEIVED SPOTIFY VOLUME 97 Dec 19 02:08:48 prrevo volumio[5780]: info: Setting Volumio Volume from Spotify: 97 Dec 19 02:08:48 prrevo volumio[5780]: info: VolumeController::SetAlsaVolume97 Dec 19 02:08:48 prrevo volumio[5780]: info: CoreStateMachine::pushState Dec 19 02:08:48 prrevo volumio[5780]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 19 02:08:48 prrevo volumio[5780]: info: CoreCommandRouter::volumioPushState Dec 19 02:08:48 prrevo volumio[5780]: info: CoreCommandRouter::volumioGetState Dec 19 02:08:48 prrevo volumio[5780]: info: MRS: Pushing multiroomSync output update for this device Dec 19 02:08:48 prrevo volumio[5780]: info: MRS: Pushing multiroomSync output Dec 19 02:08:48 prrevo volumio[5780]: SPOTIFY: received: {"type":"volume","data":{"value":97,"max":100}} Dec 19 02:08:48 prrevo volumio[5780]: SPOTIFY: RECEIVED SPOTIFY VOLUME 97 Dec 19 02:08:48 prrevo volumio[5780]: info: Signalling Playback active due to playback status change Dec 19 02:08:48 prrevo volumio[5780]: info: Updating RAAT Signal Path Dec 19 02:08:48 prrevo volumio[5780]: info: Updating RAAT Signal Path Dec 19 02:08:48 prrevo go-librespot[9538]: time="2025-12-19T02:08:48+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Dec 19 02:08:48 prrevo go-librespot[9538]: time="2025-12-19T02:08:48+02:00" level=trace msg="emitting websocket event: volume" Dec 19 02:08:48 prrevo go-librespot[9538]: time="2025-12-19T02:08:48+02:00" level=debug msg="update volume requested to 43253/65535" Dec 19 02:08:48 prrevo volumio[5780]: SPOTIFY: received: {"type":"volume","data":{"value":75,"max":100}} Dec 19 02:08:48 prrevo volumio[5780]: SPOTIFY: RECEIVED SPOTIFY VOLUME 75 Dec 19 02:08:48 prrevo volumio[5780]: info: Setting Volumio Volume from Spotify: 75 Dec 19 02:08:48 prrevo volumio[5780]: info: VolumeController::SetAlsaVolume75 Dec 19 02:08:48 prrevo volumio[5780]: info: CoreStateMachine::pushState Dec 19 02:08:48 prrevo volumio[5780]: info: CoreCommandRouter::volumioPushState Dec 19 02:08:48 prrevo volumio[5780]: info: CoreCommandRouter::volumioGetState Dec 19 02:08:48 prrevo volumio[5780]: info: MRS: Pushing multiroomSync output update for this device Dec 19 02:08:48 prrevo volumio[5780]: info: MRS: Pushing multiroomSync output Dec 19 02:08:48 prrevo volumio[5780]: SPOTIFY: received: {"type":"volume","data":{"value":75,"max":100}} Dec 19 02:08:48 prrevo volumio[5780]: SPOTIFY: RECEIVED SPOTIFY VOLUME 75 Dec 19 02:08:48 prrevo volumio[5780]: info: Signalling Playback active due to playback status change Dec 19 02:08:48 prrevo volumio[5780]: info: Updating RAAT Signal Path Dec 19 02:08:48 prrevo volumio[5780]: info: Updating RAAT Signal Path Dec 19 02:08:48 prrevo go-librespot[9538]: time="2025-12-19T02:08:48+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Dec 19 02:08:48 prrevo go-librespot[9538]: time="2025-12-19T02:08:48+02:00" level=trace msg="emitting websocket event: volume" Dec 19 02:08:48 prrevo volumio[5780]: SPOTIFY: received: {"type":"volume","data":{"value":66,"max":100}} Dec 19 02:08:48 prrevo volumio[5780]: SPOTIFY: RECEIVED SPOTIFY VOLUME 66 Dec 19 02:08:48 prrevo volumio[5780]: info: Setting Volumio Volume from Spotify: 66 Dec 19 02:08:48 prrevo volumio[5780]: info: VolumeController::SetAlsaVolume66 Dec 19 02:08:48 prrevo volumio[5780]: info: CoreStateMachine::pushState Dec 19 02:08:48 prrevo volumio[5780]: info: CoreCommandRouter::volumioPushState Dec 19 02:08:48 prrevo volumio[5780]: info: CoreCommandRouter::volumioGetState Dec 19 02:08:48 prrevo volumio[5780]: info: MRS: Pushing multiroomSync output update for this device Dec 19 02:08:48 prrevo volumio[5780]: info: MRS: Pushing multiroomSync output Dec 19 02:08:48 prrevo volumio[5780]: SPOTIFY: received: {"type":"volume","data":{"value":66,"max":100}} Dec 19 02:08:48 prrevo volumio[5780]: SPOTIFY: RECEIVED SPOTIFY VOLUME 66 Dec 19 02:08:48 prrevo volumio[5780]: info: Signalling Playback active due to playback status change Dec 19 02:08:48 prrevo volumio[5780]: info: Updating RAAT Signal Path Dec 19 02:08:48 prrevo volumio[5780]: info: Updating RAAT Signal Path Dec 19 02:08:48 prrevo go-librespot[9538]: time="2025-12-19T02:08:48+02:00" level=debug msg="update volume requested to 38665/65535" Dec 19 02:08:49 prrevo go-librespot[9538]: time="2025-12-19T02:08:49+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Dec 19 02:08:49 prrevo go-librespot[9538]: time="2025-12-19T02:08:49+02:00" level=trace msg="emitting websocket event: volume" Dec 19 02:08:49 prrevo volumio[5780]: SPOTIFY: received: {"type":"volume","data":{"value":59,"max":100}} Dec 19 02:08:49 prrevo volumio[5780]: SPOTIFY: RECEIVED SPOTIFY VOLUME 59 Dec 19 02:08:49 prrevo volumio[5780]: info: Setting Volumio Volume from Spotify: 59 Dec 19 02:08:49 prrevo volumio[5780]: info: VolumeController::SetAlsaVolume59 Dec 19 02:08:49 prrevo volumio[5780]: info: CoreStateMachine::pushState Dec 19 02:08:49 prrevo volumio[5780]: info: CoreCommandRouter::volumioPushState Dec 19 02:08:49 prrevo volumio[5780]: info: CoreCommandRouter::volumioGetState Dec 19 02:08:49 prrevo volumio[5780]: info: MRS: Pushing multiroomSync output update for this device Dec 19 02:08:49 prrevo volumio[5780]: info: MRS: Pushing multiroomSync output Dec 19 02:08:49 prrevo volumio[5780]: SPOTIFY: received: {"type":"volume","data":{"value":59,"max":100}} Dec 19 02:08:49 prrevo volumio[5780]: SPOTIFY: RECEIVED SPOTIFY VOLUME 59 Dec 19 02:08:49 prrevo volumio[5780]: info: Signalling Playback active due to playback status change Dec 19 02:08:49 prrevo volumio[5780]: info: Updating RAAT Signal Path Dec 19 02:08:49 prrevo volumio[5780]: info: Updating RAAT Signal Path Dec 19 02:08:50 prrevo go-librespot[9538]: time="2025-12-19T02:08:50+02:00" level=debug msg="update volume requested to 39321/65535" Dec 19 02:08:51 prrevo go-librespot[9538]: time="2025-12-19T02:08:51+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Dec 19 02:08:51 prrevo go-librespot[9538]: time="2025-12-19T02:08:51+02:00" level=trace msg="emitting websocket event: volume" Dec 19 02:08:51 prrevo volumio[5780]: SPOTIFY: received: {"type":"volume","data":{"value":60,"max":100}} Dec 19 02:08:51 prrevo volumio[5780]: SPOTIFY: RECEIVED SPOTIFY VOLUME 60 Dec 19 02:08:51 prrevo volumio[5780]: info: Setting Volumio Volume from Spotify: 60 Dec 19 02:08:51 prrevo volumio[5780]: info: VolumeController::SetAlsaVolume60 Dec 19 02:08:51 prrevo volumio[5780]: info: CoreStateMachine::pushState Dec 19 02:08:51 prrevo volumio[5780]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 19 02:08:51 prrevo volumio[5780]: info: CoreCommandRouter::volumioPushState Dec 19 02:08:51 prrevo volumio[5780]: info: CoreCommandRouter::volumioGetState Dec 19 02:08:51 prrevo volumio[5780]: info: MRS: Pushing multiroomSync output update for this device Dec 19 02:08:51 prrevo volumio[5780]: info: MRS: Pushing multiroomSync output Dec 19 02:08:51 prrevo volumio[5780]: SPOTIFY: received: {"type":"volume","data":{"value":60,"max":100}} Dec 19 02:08:51 prrevo volumio[5780]: SPOTIFY: RECEIVED SPOTIFY VOLUME 60 Dec 19 02:08:51 prrevo volumio[5780]: info: Signalling Playback active due to playback status change Dec 19 02:08:51 prrevo volumio[5780]: info: Updating RAAT Signal Path Dec 19 02:08:51 prrevo volumio[5780]: info: Updating RAAT Signal Path Dec 19 02:08:51 prrevo go-librespot[9538]: time="2025-12-19T02:08:51+02:00" level=debug msg="update volume requested to 44563/65535" Dec 19 02:08:51 prrevo go-librespot[9538]: time="2025-12-19T02:08:51+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Dec 19 02:08:51 prrevo go-librespot[9538]: time="2025-12-19T02:08:51+02:00" level=trace msg="emitting websocket event: volume" Dec 19 02:08:51 prrevo volumio[5780]: SPOTIFY: received: {"type":"volume","data":{"value":68,"max":100}} Dec 19 02:08:51 prrevo volumio[5780]: SPOTIFY: RECEIVED SPOTIFY VOLUME 68 Dec 19 02:08:51 prrevo volumio[5780]: info: Setting Volumio Volume from Spotify: 68 Dec 19 02:08:51 prrevo volumio[5780]: info: VolumeController::SetAlsaVolume68 Dec 19 02:08:51 prrevo volumio[5780]: info: CoreStateMachine::pushState Dec 19 02:08:51 prrevo volumio[5780]: info: CoreCommandRouter::volumioPushState Dec 19 02:08:51 prrevo volumio[5780]: info: CoreCommandRouter::volumioGetState Dec 19 02:08:51 prrevo volumio[5780]: info: MRS: Pushing multiroomSync output update for this device Dec 19 02:08:51 prrevo volumio[5780]: info: MRS: Pushing multiroomSync output Dec 19 02:08:51 prrevo volumio[5780]: SPOTIFY: received: {"type":"volume","data":{"value":68,"max":100}} Dec 19 02:08:51 prrevo volumio[5780]: SPOTIFY: RECEIVED SPOTIFY VOLUME 68 Dec 19 02:08:51 prrevo volumio[5780]: info: Signalling Playback active due to playback status change Dec 19 02:08:51 prrevo volumio[5780]: info: Updating RAAT Signal Path Dec 19 02:08:51 prrevo volumio[5780]: info: Updating RAAT Signal Path Dec 19 02:08:51 prrevo go-librespot[9538]: time="2025-12-19T02:08:51+02:00" level=debug msg="update volume requested to 43908/65535" Dec 19 02:08:51 prrevo go-librespot[9538]: time="2025-12-19T02:08:51+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Dec 19 02:08:51 prrevo go-librespot[9538]: time="2025-12-19T02:08:51+02:00" level=trace msg="emitting websocket event: volume" Dec 19 02:08:51 prrevo volumio[5780]: SPOTIFY: received: {"type":"volume","data":{"value":67,"max":100}} Dec 19 02:08:51 prrevo volumio[5780]: SPOTIFY: RECEIVED SPOTIFY VOLUME 67 Dec 19 02:08:51 prrevo volumio[5780]: info: Setting Volumio Volume from Spotify: 67 Dec 19 02:08:51 prrevo volumio[5780]: info: VolumeController::SetAlsaVolume67 Dec 19 02:08:51 prrevo volumio[5780]: info: CoreStateMachine::pushState Dec 19 02:08:51 prrevo volumio[5780]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 19 02:08:51 prrevo volumio[5780]: info: CoreCommandRouter::volumioPushState Dec 19 02:08:51 prrevo volumio[5780]: info: CoreCommandRouter::volumioGetState Dec 19 02:08:51 prrevo volumio[5780]: info: MRS: Pushing multiroomSync output update for this device Dec 19 02:08:51 prrevo volumio[5780]: info: MRS: Pushing multiroomSync output Dec 19 02:08:51 prrevo volumio[5780]: SPOTIFY: received: {"type":"volume","data":{"value":67,"max":100}} Dec 19 02:08:51 prrevo volumio[5780]: SPOTIFY: RECEIVED SPOTIFY VOLUME 67 Dec 19 02:08:51 prrevo volumio[5780]: info: Signalling Playback active due to playback status change Dec 19 02:08:51 prrevo volumio[5780]: info: Updating RAAT Signal Path Dec 19 02:08:51 prrevo volumio[5780]: info: Updating RAAT Signal Path Dec 19 02:08:51 prrevo go-librespot[9538]: time="2025-12-19T02:08:51+02:00" level=debug msg="update volume requested to 47840/65535" Dec 19 02:08:51 prrevo go-librespot[9538]: time="2025-12-19T02:08:51+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Dec 19 02:08:51 prrevo go-librespot[9538]: time="2025-12-19T02:08:51+02:00" level=trace msg="emitting websocket event: volume" Dec 19 02:08:51 prrevo volumio[5780]: SPOTIFY: received: {"type":"volume","data":{"value":73,"max":100}} Dec 19 02:08:51 prrevo volumio[5780]: SPOTIFY: RECEIVED SPOTIFY VOLUME 73 Dec 19 02:08:51 prrevo volumio[5780]: info: Setting Volumio Volume from Spotify: 73 Dec 19 02:08:51 prrevo volumio[5780]: info: VolumeController::SetAlsaVolume73 Dec 19 02:08:51 prrevo volumio[5780]: info: CoreStateMachine::pushState Dec 19 02:08:51 prrevo volumio[5780]: info: CoreCommandRouter::volumioPushState Dec 19 02:08:51 prrevo go-librespot[9538]: time="2025-12-19T02:08:51+02:00" level=debug msg="update volume requested to 51117/65535" Dec 19 02:08:51 prrevo volumio[5780]: info: CoreCommandRouter::volumioGetState Dec 19 02:08:51 prrevo volumio[5780]: info: MRS: Pushing multiroomSync output update for this device Dec 19 02:08:51 prrevo volumio[5780]: info: MRS: Pushing multiroomSync output Dec 19 02:08:51 prrevo volumio[5780]: SPOTIFY: received: {"type":"volume","data":{"value":73,"max":100}} Dec 19 02:08:51 prrevo volumio[5780]: SPOTIFY: RECEIVED SPOTIFY VOLUME 73 Dec 19 02:08:51 prrevo volumio[5780]: info: Signalling Playback active due to playback status change Dec 19 02:08:51 prrevo volumio[5780]: info: Updating RAAT Signal Path Dec 19 02:08:51 prrevo volumio[5780]: info: Updating RAAT Signal Path Dec 19 02:08:52 prrevo go-librespot[9538]: time="2025-12-19T02:08:52+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Dec 19 02:08:52 prrevo go-librespot[9538]: time="2025-12-19T02:08:52+02:00" level=trace msg="emitting websocket event: volume" Dec 19 02:08:52 prrevo volumio[5780]: SPOTIFY: received: {"type":"volume","data":{"value":78,"max":100}} Dec 19 02:08:52 prrevo volumio[5780]: SPOTIFY: RECEIVED SPOTIFY VOLUME 78 Dec 19 02:08:52 prrevo volumio[5780]: info: Setting Volumio Volume from Spotify: 78 Dec 19 02:08:52 prrevo volumio[5780]: info: VolumeController::SetAlsaVolume78 Dec 19 02:08:52 prrevo volumio[5780]: info: CoreStateMachine::pushState Dec 19 02:08:52 prrevo volumio[5780]: info: CoreCommandRouter::volumioPushState Dec 19 02:08:52 prrevo volumio[5780]: info: CoreCommandRouter::volumioGetState Dec 19 02:08:52 prrevo volumio[5780]: info: MRS: Pushing multiroomSync output update for this device Dec 19 02:08:52 prrevo volumio[5780]: info: MRS: Pushing multiroomSync output Dec 19 02:08:52 prrevo volumio[5780]: SPOTIFY: received: {"type":"volume","data":{"value":78,"max":100}} Dec 19 02:08:52 prrevo volumio[5780]: SPOTIFY: RECEIVED SPOTIFY VOLUME 78 Dec 19 02:08:52 prrevo volumio[5780]: info: Signalling Playback active due to playback status change Dec 19 02:08:52 prrevo volumio[5780]: info: Updating RAAT Signal Path Dec 19 02:08:52 prrevo volumio[5780]: info: Updating RAAT Signal Path Dec 19 02:08:52 prrevo go-librespot[9538]: time="2025-12-19T02:08:52+02:00" level=debug msg="update volume requested to 57015/65535" Dec 19 02:08:52 prrevo go-librespot[9538]: time="2025-12-19T02:08:52+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Dec 19 02:08:52 prrevo go-librespot[9538]: time="2025-12-19T02:08:52+02:00" level=trace msg="emitting websocket event: volume" Dec 19 02:08:52 prrevo volumio[5780]: SPOTIFY: received: {"type":"volume","data":{"value":87,"max":100}} Dec 19 02:08:52 prrevo volumio[5780]: SPOTIFY: RECEIVED SPOTIFY VOLUME 87 Dec 19 02:08:52 prrevo volumio[5780]: info: Setting Volumio Volume from Spotify: 87 Dec 19 02:08:52 prrevo volumio[5780]: info: VolumeController::SetAlsaVolume87 Dec 19 02:08:52 prrevo volumio[5780]: info: CoreStateMachine::pushState Dec 19 02:08:52 prrevo volumio[5780]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 19 02:08:52 prrevo volumio[5780]: info: CoreCommandRouter::volumioPushState Dec 19 02:08:52 prrevo volumio[5780]: info: CoreCommandRouter::volumioGetState Dec 19 02:08:52 prrevo volumio[5780]: info: MRS: Pushing multiroomSync output update for this device Dec 19 02:08:52 prrevo volumio[5780]: info: MRS: Pushing multiroomSync output Dec 19 02:08:52 prrevo volumio[5780]: SPOTIFY: received: {"type":"volume","data":{"value":87,"max":100}} Dec 19 02:08:52 prrevo volumio[5780]: SPOTIFY: RECEIVED SPOTIFY VOLUME 87 Dec 19 02:08:52 prrevo volumio[5780]: info: Signalling Playback active due to playback status change Dec 19 02:08:52 prrevo volumio[5780]: info: Updating RAAT Signal Path Dec 19 02:08:52 prrevo volumio[5780]: info: Updating RAAT Signal Path Dec 19 02:08:55 prrevo go-librespot[9538]: time="2025-12-19T02:08:55+02:00" level=debug msg="fetched chunk 13/16, size: 524288" uri="spotify:track:5a8tOynxc0BoTESRjK2L9j" Dec 19 02:09:09 prrevo go-librespot[9538]: time="2025-12-19T02:09:09+02:00" level=debug msg="fetched chunk 14/16, size: 524288" uri="spotify:track:5a8tOynxc0BoTESRjK2L9j" Dec 19 02:09:15 prrevo go-librespot[9538]: time="2025-12-19T02:09:15+02:00" level=trace msg="sent dealer ping" Dec 19 02:09:15 prrevo go-librespot[9538]: time="2025-12-19T02:09:15+02:00" level=trace msg="received dealer pong" Dec 19 02:09:23 prrevo go-librespot[9538]: time="2025-12-19T02:09:23+02:00" level=debug msg="fetched chunk 15/16, size: 524288" uri="spotify:track:5a8tOynxc0BoTESRjK2L9j" Dec 19 02:09:37 prrevo go-librespot[9538]: time="2025-12-19T02:09:37+02:00" level=debug msg="fetched chunk 16/16, size: 354251" uri="spotify:track:5a8tOynxc0BoTESRjK2L9j" Dec 19 02:09:45 prrevo go-librespot[9538]: time="2025-12-19T02:09:45+02:00" level=trace msg="sent dealer ping" Dec 19 02:09:45 prrevo go-librespot[9538]: time="2025-12-19T02:09:45+02:00" level=trace msg="received dealer pong" Dec 19 02:09:55 prrevo volumio[5780]: info: CorePlayQueue::getTrack 0 Dec 19 02:09:55 prrevo volumio[5780]: info: CorePlayQueue::getTrack 1 Dec 19 02:09:55 prrevo volumio[5780]: info: Prefetching next song Dec 19 02:09:55 prrevo volumio[5780]: info: [1766102995351] ControllerTidal::prefetch Dec 19 02:09:55 prrevo volumio[5780]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 19 02:09:55 prrevo volumio[5780]: TypeError: Cannot read property 'type' of null Dec 19 02:09:55 prrevo volumio[5780]: at ControllerTidal.getProperSoundQuality (/volumio/app/plugins/music_service/tidal/tidal_real:1:19792) Dec 19 02:09:55 prrevo volumio[5780]: at ControllerTidal.prefetch (/volumio/app/plugins/music_service/tidal/tidal_real:1:20287) Dec 19 02:09:55 prrevo volumio[5780]: at CoreStateMachine.increasePlaybackTimer (/volumio/app/statemachine.js:464:18) Dec 19 02:09:55 prrevo volumio[5780]: at listOnTimeout (internal/timers.js:557:17) Dec 19 02:09:55 prrevo volumio[5780]: at processTimers (internal/timers.js:500:7) Dec 19 02:09:55 prrevo volumio[5780]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 19 02:09:56 prrevo sudo[10117]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-12-19 02:08 Dec 19 02:09:56 prrevo sudo[10117]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Debian GNU/Linux 10 (buster)" NAME="Debian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=debian HOME_URL="https://www.debian.org/" SUPPORT_URL="https://www.debian.org/support" BUG_REPORT_URL="https://bugs.debian.org/" VOLUMIO_BUILD_VERSION="b43c85cc0006d3f1efecba101311ec96e334d1fd" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="2f25e1a98e53e2dbc4f3878604e250b0379f3ea4" VOLUMIO_ARCH="armv7" VOLUMIO_VARIANT="rivoplus" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Thu 11 Dec 2025 06:47:33 PM CET" VOLUMIO_VERSION="3.886" VOLUMIO_HARDWARE="mp1" VOLUMIO_DEVICENAME="Volumio MP1" VOLUMIO_VENDOR_MODEL="Volumio Rivo Plus" VOLUMIO_VENDOR="Volumio" VOLUMIO_MODEL="Rivo Plus" VOLUMIO_HASH="9e8aa5d6afb5e5d87a87bafae7aa5647"