Aug 26 08:21:36 primo volumio[3536]: info: CoreCommandRouter::servicePushState Aug 26 08:21:36 primo volumio[3536]: info: CoreStateMachine::pushState Aug 26 08:21:36 primo volumio[3536]: info: CoreCommandRouter::volumioPushState Aug 26 08:21:36 primo volumio[3536]: info: CoreCommandRouter::volumioGetState Aug 26 08:21:36 primo volumio[3536]: info: MRS: Pushing multiroomSync output update for this device Aug 26 08:21:36 primo volumio[3536]: info: MRS: Pushing multiroomSync output Aug 26 08:21:36 primo volumio[3536]: info: CoreCommandRouter::servicePushState Aug 26 08:21:36 primo volumio[3536]: info: CoreStateMachine::pushState Aug 26 08:21:36 primo volumio[3536]: info: CoreCommandRouter::volumioPushState Aug 26 08:21:36 primo volumio[3536]: info: CoreCommandRouter::volumioGetState Aug 26 08:21:36 primo volumio[3536]: info: MRS: Pushing multiroomSync output update for this device Aug 26 08:21:36 primo volumio[3536]: info: MRS: Pushing multiroomSync output Aug 26 08:21:36 primo volumio[3536]: info: CoreCommandRouter::servicePushState Aug 26 08:21:36 primo volumio[3536]: info: CoreStateMachine::pushState Aug 26 08:21:36 primo volumio[3536]: info: CoreCommandRouter::volumioPushState Aug 26 08:21:36 primo volumio[3536]: info: CoreCommandRouter::volumioGetState Aug 26 08:21:36 primo volumio[3536]: info: MRS: Pushing multiroomSync output update for this device Aug 26 08:21:36 primo volumio[3536]: info: MRS: Pushing multiroomSync output Aug 26 08:21:36 primo volumio[3536]: info: CoreCommandRouter::servicePushState Aug 26 08:21:36 primo volumio[3536]: info: CoreStateMachine::pushState Aug 26 08:21:36 primo volumio[3536]: info: CoreCommandRouter::volumioPushState Aug 26 08:21:36 primo volumio[3536]: info: CoreCommandRouter::volumioGetState Aug 26 08:21:36 primo volumio[3536]: info: MRS: Pushing multiroomSync output update for this device Aug 26 08:21:36 primo volumio[3536]: info: MRS: Pushing multiroomSync output Aug 26 08:21:36 primo volumio[3536]: info: CoreCommandRouter::servicePushState Aug 26 08:21:36 primo volumio[3536]: info: CoreStateMachine::pushState Aug 26 08:21:36 primo volumio[3536]: info: CoreCommandRouter::volumioPushState Aug 26 08:21:36 primo volumio[3536]: info: CoreCommandRouter::volumioGetState Aug 26 08:21:36 primo volumio[3536]: info: MRS: Pushing multiroomSync output update for this device Aug 26 08:21:36 primo volumio[3536]: info: MRS: Pushing multiroomSync output Aug 26 08:21:36 primo volumio[3536]: info: CoreCommandRouter::servicePushState Aug 26 08:21:36 primo volumio[3536]: info: CoreStateMachine::pushState Aug 26 08:21:36 primo volumio[3536]: info: CoreCommandRouter::volumioPushState Aug 26 08:21:36 primo volumio[3536]: info: CoreCommandRouter::volumioGetState Aug 26 08:21:36 primo volumio[3536]: info: MRS: Pushing multiroomSync output update for this device Aug 26 08:21:36 primo volumio[3536]: info: MRS: Pushing multiroomSync output Aug 26 08:21:36 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:36.655+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" state=STATUS_PLAYING positionMs= volume=33 Aug 26 08:21:36 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:36.656+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" id= title="Extra Time On You (feat. Portia Monique)" Aug 26 08:21:36 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:36.657+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" state=STATUS_PLAYING positionMs= volume=33 Aug 26 08:21:36 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:36.658+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" state=STATUS_PLAYING positionMs= volume=33 Aug 26 08:21:36 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:36.659+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" state=STATUS_PLAYING positionMs= volume=33 Aug 26 08:21:36 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:36.660+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" id= title="Extra Time On You (feat. Portia Monique)" Aug 26 08:21:36 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:36.660+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" id= title="Extra Time On You (feat. Portia Monique)" Aug 26 08:21:36 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:36.661+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" state=STATUS_PLAYING positionMs= volume=33 Aug 26 08:21:36 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:36.662+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" id= title="Extra Time On You (feat. Portia Monique)" Aug 26 08:21:36 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:36.662+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" id= title="Extra Time On You (feat. Portia Monique)" Aug 26 08:21:36 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:36.663+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" state=STATUS_PLAYING positionMs= volume=33 Aug 26 08:21:36 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:36.664+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" id= title="Extra Time On You (feat. Portia Monique)" Aug 26 08:21:36 primo volumio[3536]: info: CoreCommandRouter::servicePushState Aug 26 08:21:36 primo volumio[3536]: info: CoreStateMachine::pushState Aug 26 08:21:36 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 26 08:21:36 primo volumio[3536]: info: CoreCommandRouter::volumioPushState Aug 26 08:21:36 primo volumio[3536]: info: CoreCommandRouter::volumioGetState Aug 26 08:21:36 primo volumio[3536]: info: MRS: Pushing multiroomSync output update for this device Aug 26 08:21:36 primo volumio[3536]: info: MRS: Pushing multiroomSync output Aug 26 08:21:36 primo volumio[3536]: info: CoreCommandRouter::servicePushState Aug 26 08:21:36 primo volumio[3536]: info: CoreStateMachine::pushState Aug 26 08:21:36 primo volumio[3536]: info: CoreCommandRouter::volumioPushState Aug 26 08:21:36 primo volumio[3536]: info: CoreCommandRouter::volumioGetState Aug 26 08:21:36 primo volumio[3536]: info: MRS: Pushing multiroomSync output update for this device Aug 26 08:21:36 primo volumio[3536]: info: MRS: Pushing multiroomSync output Aug 26 08:21:36 primo volumio[3536]: info: CoreCommandRouter::servicePushState Aug 26 08:21:36 primo volumio[3536]: info: CoreStateMachine::pushState Aug 26 08:21:36 primo volumio[3536]: info: CoreCommandRouter::volumioPushState Aug 26 08:21:36 primo volumio[3536]: info: CoreCommandRouter::volumioGetState Aug 26 08:21:36 primo volumio[3536]: info: MRS: Pushing multiroomSync output update for this device Aug 26 08:21:36 primo volumio[3536]: info: MRS: Pushing multiroomSync output Aug 26 08:21:36 primo volumio[3536]: info: CoreCommandRouter::servicePushState Aug 26 08:21:36 primo volumio[3536]: info: CoreStateMachine::pushState Aug 26 08:21:36 primo volumio[3536]: info: CoreCommandRouter::volumioPushState Aug 26 08:21:36 primo volumio[3536]: info: CoreCommandRouter::volumioGetState Aug 26 08:21:36 primo volumio[3536]: info: MRS: Pushing multiroomSync output update for this device Aug 26 08:21:36 primo volumio[3536]: info: MRS: Pushing multiroomSync output Aug 26 08:21:36 primo volumio[3536]: info: CoreCommandRouter::servicePushState Aug 26 08:21:36 primo volumio[3536]: info: CoreStateMachine::pushState Aug 26 08:21:36 primo volumio[3536]: info: CoreCommandRouter::volumioPushState Aug 26 08:21:36 primo volumio[3536]: info: CoreCommandRouter::volumioGetState Aug 26 08:21:36 primo volumio[3536]: info: MRS: Pushing multiroomSync output update for this device Aug 26 08:21:36 primo volumio[3536]: info: MRS: Pushing multiroomSync output Aug 26 08:21:36 primo volumio[3536]: info: CoreCommandRouter::servicePushState Aug 26 08:21:36 primo volumio[3536]: info: CoreStateMachine::pushState Aug 26 08:21:36 primo volumio[3536]: info: CoreCommandRouter::volumioPushState Aug 26 08:21:36 primo volumio[3536]: info: CoreCommandRouter::volumioGetState Aug 26 08:21:36 primo volumio[3536]: info: MRS: Pushing multiroomSync output update for this device Aug 26 08:21:36 primo volumio[3536]: info: MRS: Pushing multiroomSync output Aug 26 08:21:36 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:36.719+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" state=STATUS_PLAYING positionMs=233000 volume=33 Aug 26 08:21:36 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:36.719+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" id= title="Extra Time On You (feat. Portia Monique)" Aug 26 08:21:36 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:36.719+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" state=STATUS_PLAYING positionMs=233000 volume=33 Aug 26 08:21:36 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:36.720+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" state=STATUS_PLAYING positionMs=233000 volume=33 Aug 26 08:21:36 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:36.720+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" id= title="Extra Time On You (feat. Portia Monique)" Aug 26 08:21:36 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:36.721+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" id= title="Extra Time On You (feat. Portia Monique)" Aug 26 08:21:36 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:36.721+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" state=STATUS_PLAYING positionMs=233000 volume=33 Aug 26 08:21:36 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:36.721+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" state=STATUS_PLAYING positionMs=233000 volume=33 Aug 26 08:21:36 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:36.722+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" id= title="Extra Time On You (feat. Portia Monique)" Aug 26 08:21:36 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:36.722+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" state=STATUS_PLAYING positionMs=233000 volume=33 Aug 26 08:21:36 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:36.727+03:00 level=INFO msg="navigate to next page" component=server type=REQUEST_TYPE_CONTINUE_NAVIGATION peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" latency=28.838593ms timeout=10s from=APP_PAGE_ROOT to=APP_PAGE_LEGACY_DEVICE Aug 26 08:21:36 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:36.722+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" id= title="Extra Time On You (feat. Portia Monique)" Aug 26 08:21:36 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:36.730+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" id= title="Extra Time On You (feat. Portia Monique)" Aug 26 08:21:36 primo volumio[3536]: info: CoreCommandRouter::servicePushState Aug 26 08:21:36 primo volumio[3536]: info: CoreStateMachine::pushState Aug 26 08:21:36 primo volumio[3536]: info: CoreCommandRouter::volumioPushState Aug 26 08:21:36 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:36.749+03:00 level=INFO msg="check connectivity" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" latency=28.59282ms timeout=10s Aug 26 08:21:36 primo volumio[3536]: info: CoreCommandRouter::volumioGetState Aug 26 08:21:36 primo volumio[3536]: info: MRS: Pushing multiroomSync output update for this device Aug 26 08:21:36 primo volumio[3536]: info: MRS: Pushing multiroomSync output Aug 26 08:21:36 primo volumio[3536]: info: CoreCommandRouter::servicePushState Aug 26 08:21:36 primo volumio[3536]: info: CoreStateMachine::pushState Aug 26 08:21:36 primo volumio[3536]: info: CoreCommandRouter::volumioPushState Aug 26 08:21:36 primo volumio[3536]: info: CoreCommandRouter::volumioGetState Aug 26 08:21:36 primo volumio[3536]: info: MRS: Pushing multiroomSync output update for this device Aug 26 08:21:36 primo volumio[3536]: info: MRS: Pushing multiroomSync output Aug 26 08:21:36 primo volumio[3536]: info: CoreCommandRouter::servicePushState Aug 26 08:21:36 primo volumio[3536]: info: CoreStateMachine::pushState Aug 26 08:21:36 primo volumio[3536]: info: CoreCommandRouter::volumioPushState Aug 26 08:21:36 primo volumio[3536]: info: CoreCommandRouter::volumioGetState Aug 26 08:21:36 primo volumio[3536]: info: MRS: Pushing multiroomSync output update for this device Aug 26 08:21:36 primo volumio[3536]: info: MRS: Pushing multiroomSync output Aug 26 08:21:36 primo volumio[3536]: info: CoreCommandRouter::servicePushState Aug 26 08:21:36 primo volumio[3536]: info: CoreStateMachine::pushState Aug 26 08:21:36 primo volumio[3536]: info: CoreCommandRouter::volumioPushState Aug 26 08:21:36 primo volumio[3536]: info: CoreCommandRouter::volumioGetState Aug 26 08:21:36 primo volumio[3536]: info: MRS: Pushing multiroomSync output update for this device Aug 26 08:21:36 primo volumio[3536]: info: MRS: Pushing multiroomSync output Aug 26 08:21:36 primo volumio[3536]: info: CoreCommandRouter::servicePushState Aug 26 08:21:36 primo volumio[3536]: info: CoreStateMachine::pushState Aug 26 08:21:36 primo volumio[3536]: info: CoreCommandRouter::volumioPushState Aug 26 08:21:36 primo volumio[3536]: info: CoreCommandRouter::volumioGetState Aug 26 08:21:36 primo volumio[3536]: info: MRS: Pushing multiroomSync output update for this device Aug 26 08:21:36 primo volumio[3536]: info: MRS: Pushing multiroomSync output Aug 26 08:21:36 primo volumio[3536]: info: CoreCommandRouter::servicePushState Aug 26 08:21:36 primo volumio[3536]: info: CoreStateMachine::pushState Aug 26 08:21:36 primo volumio[3536]: info: CoreCommandRouter::volumioPushState Aug 26 08:21:36 primo volumio[3536]: info: CoreCommandRouter::volumioGetState Aug 26 08:21:36 primo volumio[3536]: info: MRS: Pushing multiroomSync output update for this device Aug 26 08:21:36 primo volumio[3536]: info: MRS: Pushing multiroomSync output Aug 26 08:21:36 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:36.787+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" state=STATUS_PLAYING positionMs=233000 volume=33 Aug 26 08:21:36 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:36.787+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" id= title="Extra Time On You (feat. Portia Monique)" Aug 26 08:21:36 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:36.788+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" state=STATUS_PLAYING positionMs=233000 volume=33 Aug 26 08:21:36 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:36.788+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" state=STATUS_PLAYING positionMs=233000 volume=33 Aug 26 08:21:36 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:36.788+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" id= title="Extra Time On You (feat. Portia Monique)" Aug 26 08:21:36 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:36.789+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" id= title="Extra Time On You (feat. Portia Monique)" Aug 26 08:21:36 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:36.789+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" state=STATUS_PLAYING positionMs=233000 volume=33 Aug 26 08:21:36 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:36.789+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" state=STATUS_PLAYING positionMs=233000 volume=33 Aug 26 08:21:36 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:36.790+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" id= title="Extra Time On You (feat. Portia Monique)" Aug 26 08:21:36 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:36.786+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" state=STATUS_PLAYING positionMs=233000 volume=33 Aug 26 08:21:36 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:36.790+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" id= title="Extra Time On You (feat. Portia Monique)" Aug 26 08:21:36 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:36.791+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" id= title="Extra Time On You (feat. Portia Monique)" Aug 26 08:21:36 primo volumio[3536]: info: Signalling Playback active due to playback status change Aug 26 08:21:36 primo volumio[3536]: info: Signalling Playback active due to playback status change Aug 26 08:21:36 primo volumio[3536]: info: Signalling Playback active due to playback status change Aug 26 08:21:36 primo volumio[3536]: info: Signalling Playback active due to playback status change Aug 26 08:21:36 primo volumio[3536]: info: Signalling Playback active due to playback status change Aug 26 08:21:36 primo volumio[3536]: info: Signalling Playback active due to playback status change Aug 26 08:21:36 primo volumio[3536]: info: Signalling Playback active due to playback status change Aug 26 08:21:36 primo volumio[3536]: info: Signalling Playback active due to playback status change Aug 26 08:21:36 primo volumio[3536]: info: Signalling Playback active due to playback status change Aug 26 08:21:36 primo volumio[3536]: info: Signalling Playback active due to playback status change Aug 26 08:21:36 primo volumio[3536]: info: Signalling Playback active due to playback status change Aug 26 08:21:36 primo volumio[3536]: info: Signalling Playback active due to playback status change Aug 26 08:21:36 primo volumio[3536]: info: Signalling Playback active due to playback status change Aug 26 08:21:36 primo volumio[3536]: info: Signalling Playback active due to playback status change Aug 26 08:21:36 primo volumio[3536]: info: Signalling Playback active due to playback status change Aug 26 08:21:36 primo volumio[3536]: info: Signalling Playback active due to playback status change Aug 26 08:21:36 primo volumio[3536]: info: Signalling Playback active due to playback status change Aug 26 08:21:36 primo volumio[3536]: info: Signalling Playback active due to playback status change Aug 26 08:21:36 primo volumio[3536]: info: Updating RAAT Signal Path Aug 26 08:21:36 primo volumio[3536]: info: Updating RAAT Signal Path Aug 26 08:21:36 primo volumio[3536]: info: Updating RAAT Signal Path Aug 26 08:21:36 primo volumio[3536]: info: Updating RAAT Signal Path Aug 26 08:21:36 primo volumio[3536]: info: Updating RAAT Signal Path Aug 26 08:21:36 primo volumio[3536]: info: Updating RAAT Signal Path Aug 26 08:21:36 primo volumio[3536]: info: Updating RAAT Signal Path Aug 26 08:21:36 primo volumio[3536]: info: Updating RAAT Signal Path Aug 26 08:21:36 primo volumio[3536]: info: Updating RAAT Signal Path Aug 26 08:21:36 primo volumio[3536]: info: Updating RAAT Signal Path Aug 26 08:21:36 primo volumio[3536]: info: Updating RAAT Signal Path Aug 26 08:21:36 primo volumio[3536]: info: Updating RAAT Signal Path Aug 26 08:21:36 primo volumio[3536]: info: Updating RAAT Signal Path Aug 26 08:21:36 primo volumio[3536]: info: Updating RAAT Signal Path Aug 26 08:21:36 primo volumio[3536]: info: Updating RAAT Signal Path Aug 26 08:21:36 primo volumio[3536]: info: Updating RAAT Signal Path Aug 26 08:21:36 primo volumio[3536]: info: Updating RAAT Signal Path Aug 26 08:21:36 primo volumio[3536]: info: Updating RAAT Signal Path Aug 26 08:21:36 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:36.991+03:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" latency=28.59282ms timeout=10s endpoint=https://radio-directory.firebaseapp.com duration=239.935998ms Aug 26 08:21:37 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:37.031+03:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" latency=28.59282ms timeout=10s endpoint=http://pushupdates.volumio.org duration=279.586517ms Aug 26 08:21:37 primo sudo[5194]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Aug 26 08:21:37 primo sudo[5194]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 26 08:21:37 primo sudo[5196]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Aug 26 08:21:37 primo sudo[5196]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 26 08:21:37 primo sudo[5194]: pam_unix(sudo:session): session closed for user root Aug 26 08:21:37 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:37.311+03:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" latency=28.59282ms timeout=10s endpoint=https://myvolumio.firebaseio.com duration=559.698577ms Aug 26 08:21:37 primo sudo[5196]: pam_unix(sudo:session): session closed for user root Aug 26 08:21:37 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:37.339+03:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" latency=28.59282ms timeout=10s endpoint=http://cddb.volumio.org duration=588.923298ms Aug 26 08:21:37 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:37.349+03:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" latency=28.59282ms timeout=10s endpoint=https://www.googleapis.com duration=599.700222ms Aug 26 08:21:37 primo volumio[3536]: verbose: New Socket.io Connection to 192.168.2.6 from 192.168.2.9 UA: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/605.1.15 (KHTML, like Gecko) Engine version: 3 Transport: polling Total Clients: 8 Aug 26 08:21:37 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:37.390+03:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" latency=28.59282ms timeout=10s endpoint=https://oauth-performer.dfs.volumio.org duration=640.525581ms Aug 26 08:21:37 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:37.392+03:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" latency=28.59282ms timeout=10s endpoint=https://securetoken.googleapis.com duration=641.235667ms Aug 26 08:21:37 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Aug 26 08:21:37 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:37.431+03:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" latency=28.59282ms timeout=10s endpoint=https://browsing-performer.dfs.volumio.org duration=681.552398ms Aug 26 08:21:37 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:37.439+03:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" latency=28.59282ms timeout=10s endpoint=https://functions.volumio.cloud duration=689.277308ms Aug 26 08:21:37 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:37.440+03:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" latency=28.59282ms timeout=10s endpoint=https://functions.volumio.cloud duration=689.149058ms Aug 26 08:21:37 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:37.475+03:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" latency=28.59282ms timeout=10s endpoint=http://plugins.volumio.org duration=723.974888ms Aug 26 08:21:37 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:37.549+03:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" latency=28.59282ms timeout=10s endpoint=https://google.com duration=799.453532ms Aug 26 08:21:37 primo sudo[5202]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Aug 26 08:21:37 primo sudo[5202]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 26 08:21:37 primo sudo[5204]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Aug 26 08:21:37 primo sudo[5204]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 26 08:21:37 primo sudo[5202]: pam_unix(sudo:session): session closed for user root Aug 26 08:21:37 primo sudo[5204]: pam_unix(sudo:session): session closed for user root Aug 26 08:21:37 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Aug 26 08:21:37 primo volumio[3536]: verbose: New Socket.io Connection to 192.168.2.6 from 192.168.2.9 UA: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/605.1.15 (KHTML, like Gecko) Engine version: 3 Transport: polling Total Clients: 8 Aug 26 08:21:37 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:37.607+03:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" latency=28.59282ms timeout=10s endpoint=https://database.volumio.cloud duration=856.146298ms Aug 26 08:21:37 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Aug 26 08:21:37 primo volumio[3536]: info: CoreCommandRouter::volumioGetVisibleSources Aug 26 08:21:37 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 26 08:21:37 primo volumio[3536]: info: CoreCommandRouter::volumioGetState Aug 26 08:21:37 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Aug 26 08:21:37 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Aug 26 08:21:37 primo volumio[3536]: info: Error : CoreCommandRouter::executeOnPlugin: No method [getMultiroom] in plugin multiroom Aug 26 08:21:37 primo volumio[3536]: info: Received Get System Info Aug 26 08:21:37 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 26 08:21:37 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 26 08:21:37 primo volumio[3536]: info: Discovery: Getting this device information Aug 26 08:21:37 primo volumio[3536]: info: CoreCommandRouter::volumioGetState Aug 26 08:21:37 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 26 08:21:37 primo volumio[3536]: info: CoreCommandRouter::volumioGetState Aug 26 08:21:37 primo volumio[3536]: info: Listing playlists Aug 26 08:21:37 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Aug 26 08:21:37 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Aug 26 08:21:37 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Aug 26 08:21:38 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 26 08:21:38 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 26 08:21:38 primo volumio[3536]: info: Discovery: Getting this device information Aug 26 08:21:38 primo volumio[3536]: info: CoreCommandRouter::volumioGetState Aug 26 08:21:38 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 26 08:21:38 primo volumio[3536]: verbose: New Socket.io Connection to 192.168.2.6:3000 from 192.168.2.9 UA: Dart/3.12 (dart:io) Engine version: 3 Transport: websocket Total Clients: 9 Aug 26 08:21:38 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Aug 26 08:21:38 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Aug 26 08:21:38 primo volumio[3536]: info: CoreCommandRouter::volumioGetState Aug 26 08:21:39 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Aug 26 08:21:39 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 26 08:21:39 primo volumio[3536]: info: Received Get System Info Aug 26 08:21:39 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 26 08:21:39 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 26 08:21:39 primo volumio[3536]: info: Discovery: Getting this device information Aug 26 08:21:39 primo volumio[3536]: info: CoreCommandRouter::volumioGetState Aug 26 08:21:39 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 26 08:21:40 primo volumio[3536]: info: Executing endpoint metavolumio Aug 26 08:21:40 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Aug 26 08:21:40 primo volumio[3536]: info: Executing endpoint metavolumio Aug 26 08:21:40 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Aug 26 08:21:40 primo volumio[3536]: info: Executing endpoint metavolumio Aug 26 08:21:40 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Aug 26 08:21:40 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 26 08:21:40 primo volumio[3536]: info: Received Get System Info Aug 26 08:21:40 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 26 08:21:40 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 26 08:21:40 primo volumio[3536]: info: Discovery: Getting this device information Aug 26 08:21:40 primo volumio[3536]: info: CoreCommandRouter::volumioGetState Aug 26 08:21:40 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 26 08:21:41 primo volumio[3536]: info: CoreCommandRouter::getUIConfigOnPlugin Aug 26 08:21:41 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions Aug 26 08:21:41 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 26 08:21:41 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Aug 26 08:21:41 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 26 08:21:41 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 26 08:21:41 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 26 08:21:41 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 26 08:21:41 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 26 08:21:41 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 26 08:21:41 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 26 08:21:41 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: mpd , getPlaybackMode Aug 26 08:21:41 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus Aug 26 08:21:41 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: raat , getAdditionalUiSection Aug 26 08:21:41 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: inputs , getAdditionalUiSection Aug 26 08:21:41 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:41 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:44 primo volumio[3536]: info: CALLMETHOD: audio_interface alsa_controller saveAlsaOptions [object Object] Aug 26 08:21:44 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , saveAlsaOptions Aug 26 08:21:44 primo volumio[3536]: info: Preparing to save Alsa Options, stopping services first Aug 26 08:21:44 primo volumio[3536]: info: CoreCommandRouter::volumioGetState Aug 26 08:21:44 primo volumio[3536]: info: CoreCommandRouter::volumioPause Aug 26 08:21:44 primo volumio[3536]: info: CoreStateMachine::pause Aug 26 08:21:44 primo volumio[3536]: info: CoreStateMachine::stPlaybackTimer Aug 26 08:21:44 primo volumio[3536]: info: CoreStateMachine::servicePause Aug 26 08:21:44 primo volumio[3536]: info: CoreCommandRouter::servicePause Aug 26 08:21:44 primo volumio[3536]: info: Airplay Pause with DBUS Call Aug 26 08:21:44 primo volumio[3536]: info: Saving Audio Output to: {"output_device":{"value":"0,0","label":"Analog Outputs"}} Aug 26 08:21:44 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Aug 26 08:21:44 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Aug 26 08:21:44 primo volumio[3536]: info: Setting mixer Audio hdmi-out mute for card Analog Outputs Aug 26 08:21:44 primo volumio[3536]: info: QobuzConnect: setDeactiveState invoked Aug 26 08:21:44 primo volumio[3536]: info: CoreCommandRouter::volumioGetState Aug 26 08:21:44 primo volumio[3536]: info: Reconfiguring and Restarting RAAT Plugin due to audio path changes Aug 26 08:21:44 primo vtcs[4593]: [2026-08-26 08:21:44.810] [tisoc] [warning] [SessionManagerImpl.cpp:240] Illegal State: IDLE Aug 26 08:21:44 primo vtcs[4593]: [2026-08-26 08:21:44.810] [tisoc] [error] [SpkconServer.cpp:378] recv error. socket disconnected Aug 26 08:21:44 primo sudo[5222]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service Aug 26 08:21:44 primo sudo[5222]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 26 08:21:44 primo volumio[3536]: info: Applying Volume Override Aug 26 08:21:44 primo volumio[3536]: info: CoreCommandRouter::volumioUpdateVolumeSettings Aug 26 08:21:44 primo volumio[3536]: info: Updating Volume Controller Parameters: Device: 0,0 Name: Analog Outputs Mixer: Audio hdmi-out mute Max Vol: 100 Vol Curve; logarithmic Vol Steps: 1 Aug 26 08:21:44 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , setExternalVolume Aug 26 08:21:44 primo volumio[3536]: info: Enabling external Volume Control Aug 26 08:21:44 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: inputs , updateVolumeSettings Aug 26 08:21:44 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: inputs , retrievevolume Aug 26 08:21:44 primo volumio[3536]: info: CoreCommandRouter::getUIConfigOnPlugin Aug 26 08:21:44 primo volumio[3536]: info: CoreStateMachine::pushState Aug 26 08:21:44 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 26 08:21:44 primo volumio[3536]: info: CoreCommandRouter::volumioPushState Aug 26 08:21:44 primo volumio[3536]: info: CoreCommandRouter::volumioGetState Aug 26 08:21:44 primo volumio[3536]: info: MRS: Pushing multiroomSync output update for this device Aug 26 08:21:44 primo volumio[3536]: info: MRS: Pushing multiroomSync output Aug 26 08:21:44 primo volumio[3536]: info: CoreStateMachine::pushState Aug 26 08:21:44 primo volumio[3536]: info: CoreCommandRouter::volumioPushState Aug 26 08:21:44 primo volumio[3536]: info: CoreCommandRouter::volumioGetState Aug 26 08:21:44 primo volumio[3536]: info: MRS: Pushing multiroomSync output update for this device Aug 26 08:21:44 primo volumio[3536]: info: MRS: Pushing multiroomSync output Aug 26 08:21:44 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:44.876+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" state=STATUS_PLAYING positionMs=241000 volume=33 Aug 26 08:21:44 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:44.877+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" state=STATUS_PLAYING positionMs=241000 volume=33 Aug 26 08:21:44 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:44.878+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" id= title="Extra Time On You (feat. Portia Monique)" Aug 26 08:21:44 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:44.878+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" id= title="Extra Time On You (feat. Portia Monique)" Aug 26 08:21:44 primo volumio[3536]: info: Preparing to generate the ALSA configuration file Aug 26 08:21:44 primo systemd[1]: Stopping vtcs.service - Volumio Tidal Connect Service... Aug 26 08:21:44 primo systemd[1]: vtcs.service: Deactivated successfully. Aug 26 08:21:44 primo systemd[1]: Stopped vtcs.service - Volumio Tidal Connect Service. Aug 26 08:21:44 primo sudo[5222]: pam_unix(sudo:session): session closed for user root Aug 26 08:21:44 primo sudo[5227]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service Aug 26 08:21:44 primo sudo[5227]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 26 08:21:44 primo volumio[3536]: info: The plugin multiroom has an ALSA contribution file volumioMultiRoomServer.postMultiRoom.1000.conf Aug 26 08:21:44 primo volumio[3536]: info: Reading ALSA contributions from plugins. Aug 26 08:21:44 primo volumio[3536]: info: Signalling Playback active due to playback status change Aug 26 08:21:44 primo volumio[3536]: info: Signalling Playback active due to playback status change Aug 26 08:21:44 primo volumio[3536]: info: Updating RAAT Signal Path Aug 26 08:21:44 primo sudo[5234]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl reset-failed qobuz-connect.service Aug 26 08:21:44 primo sudo[5234]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 26 08:21:44 primo volumio[3536]: info: Updating RAAT Signal Path Aug 26 08:21:44 primo volumio[3536]: error: Serial API: Failed to decode command: MAXVOL, message: 100 Aug 26 08:21:45 primo sudo[5227]: pam_unix(sudo:session): session closed for user root Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Aug 26 08:21:45 primo sudo[5234]: pam_unix(sudo:session): session closed for user root Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 26 08:21:45 primo sudo[5240]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart qobuz-connect.service Aug 26 08:21:45 primo sudo[5240]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: mpd , getPlaybackMode Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: raat , getAdditionalUiSection Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: inputs , getAdditionalUiSection Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:45 primo volumio[3536]: info: Asound.conf file unchanged, so no further update is needed Aug 26 08:21:45 primo volumio[3536]: info: Output device has changed, restarting MPD Aug 26 08:21:45 primo systemd[1]: Stopping qobuz-connect.service - Volumio Qobuz Connect Service... Aug 26 08:21:45 primo qobuz-connect[4616]: 20260826 08:21:45.124 [4616.4616] INFO SampleApp: Stopping Local configuration server Aug 26 08:21:45 primo volumio[3536]: info: Output device has changed, restarting Shairport Sync Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 26 08:21:45 primo sudo[5244]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Aug 26 08:21:45 primo sudo[5244]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 26 08:21:45 primo sudo[5244]: pam_unix(sudo:session): session closed for user root Aug 26 08:21:45 primo sudo[5246]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Aug 26 08:21:45 primo sudo[5246]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 26 08:21:45 primo volumio[3536]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Aug 26 08:21:45 primo volumio[3536]: info: MRS: Audio Device Changed, rebuilding Multiroom Configuration Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:45 primo volumio[3536]: info: QobuzConnect: setDeactiveState invoked Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::volumioGetState Aug 26 08:21:45 primo volumio[3536]: info: Reconfiguring and Restarting RAAT Plugin due to audio device changes Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:45 primo systemd[1]: Stopping mpd.service - Music Player Daemon... Aug 26 08:21:45 primo sudo[5255]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service Aug 26 08:21:45 primo sudo[5255]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 26 08:21:45 primo sudo[5257]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service Aug 26 08:21:45 primo sudo[5257]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 26 08:21:45 primo volumio[3536]: error: Failed to parse min max audio card capabilities, sending default vales: TypeError: Cannot read properties of undefined (reading 'split') Aug 26 08:21:45 primo systemd[1]: mpd.service: Deactivated successfully. Aug 26 08:21:45 primo systemd[1]: Stopped mpd.service - Music Player Daemon. Aug 26 08:21:45 primo volumio[3536]: info: MPD Permissions set Aug 26 08:21:45 primo volumio[3536]: info: CoreStateMachine::pushState Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::volumioPushState Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::volumioGetState Aug 26 08:21:45 primo volumio[3536]: info: MRS: Pushing multiroomSync output update for this device Aug 26 08:21:45 primo volumio[3536]: info: MRS: Pushing multiroomSync output Aug 26 08:21:45 primo sudo[5264]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl reset-failed qobuz-connect.service Aug 26 08:21:45 primo systemd[1]: mpd.socket: Deactivated successfully. Aug 26 08:21:45 primo volumio[3536]: info: CoreStateMachine::pushState Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::volumioPushState Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::volumioGetState Aug 26 08:21:45 primo volumio[3536]: info: MRS: Pushing multiroomSync output update for this device Aug 26 08:21:45 primo volumio[3536]: info: MRS: Pushing multiroomSync output Aug 26 08:21:45 primo volumio[3536]: info: Signalling Playback active due to playback status change Aug 26 08:21:45 primo volumio[3536]: info: Signalling Playback active due to playback status change Aug 26 08:21:45 primo volumio[3536]: info: Updating RAAT Signal Path Aug 26 08:21:45 primo volumio[3536]: info: Updating RAAT Signal Path Aug 26 08:21:45 primo sudo[5264]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 26 08:21:45 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:45.290+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" state=STATUS_PLAYING positionMs=242000 volume=33 Aug 26 08:21:45 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:45.290+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" id= title="Extra Time On You (feat. Portia Monique)" Aug 26 08:21:45 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:45.307+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" state=STATUS_PLAYING positionMs=242000 volume=33 Aug 26 08:21:45 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:45.307+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" id= title="Extra Time On You (feat. Portia Monique)" Aug 26 08:21:45 primo systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Aug 26 08:21:45 primo systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Aug 26 08:21:45 primo systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Aug 26 08:21:45 primo systemd[1]: Starting mpd.service - Music Player Daemon... Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 26 08:21:45 primo volumio[3536]: info: Not Reporting Auto name since its the default one Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: system , getCPUCoresNumber Aug 26 08:21:45 primo sudo[5264]: pam_unix(sudo:session): session closed for user root Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::servicePushState Aug 26 08:21:45 primo volumio[3536]: info: CoreStateMachine::pushState Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::volumioPushState Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::volumioGetState Aug 26 08:21:45 primo volumio[3536]: info: MRS: Pushing multiroomSync output update for this device Aug 26 08:21:45 primo volumio[3536]: info: MRS: Pushing multiroomSync output Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::servicePushState Aug 26 08:21:45 primo volumio[3536]: info: CoreStateMachine::pushState Aug 26 08:21:45 primo sudo[5287]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart qobuz-connect.service Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::volumioPushState Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::volumioGetState Aug 26 08:21:45 primo volumio[3536]: info: MRS: Pushing multiroomSync output update for this device Aug 26 08:21:45 primo volumio[3536]: info: MRS: Pushing multiroomSync output Aug 26 08:21:45 primo sudo[5287]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::servicePushState Aug 26 08:21:45 primo volumio[3536]: info: CoreStateMachine::pushState Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::volumioPushState Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::volumioGetState Aug 26 08:21:45 primo volumio[3536]: info: MRS: Pushing multiroomSync output update for this device Aug 26 08:21:45 primo volumio[3536]: info: MRS: Pushing multiroomSync output Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::servicePushState Aug 26 08:21:45 primo volumio[3536]: info: CoreStateMachine::pushState Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::volumioPushState Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::volumioGetState Aug 26 08:21:45 primo volumio[3536]: info: MRS: Pushing multiroomSync output update for this device Aug 26 08:21:45 primo volumio[3536]: info: MRS: Pushing multiroomSync output Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::servicePushState Aug 26 08:21:45 primo volumio[3536]: info: CoreStateMachine::pushState Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::volumioPushState Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::volumioGetState Aug 26 08:21:45 primo volumio[3536]: info: MRS: Pushing multiroomSync output update for this device Aug 26 08:21:45 primo sudo[5255]: pam_unix(sudo:session): session closed for user root Aug 26 08:21:45 primo volumio[3536]: info: MRS: Pushing multiroomSync output Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::servicePushState Aug 26 08:21:45 primo volumio[3536]: info: CoreStateMachine::pushState Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::volumioPushState Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::volumioGetState Aug 26 08:21:45 primo volumio[3536]: info: MRS: Pushing multiroomSync output update for this device Aug 26 08:21:45 primo volumio[3536]: info: MRS: Pushing multiroomSync output Aug 26 08:21:45 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:45.481+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" state=STATUS_PAUSED positionMs=242000 volume=33 Aug 26 08:21:45 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:45.482+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" id= title="Extra Time On You (feat. Portia Monique)" Aug 26 08:21:45 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:45.482+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" state=STATUS_PAUSED positionMs=242000 volume=33 Aug 26 08:21:45 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:45.482+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" id= title="Extra Time On You (feat. Portia Monique)" Aug 26 08:21:45 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:45.483+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" state=STATUS_PAUSED positionMs=242000 volume=33 Aug 26 08:21:45 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:45.483+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" state=STATUS_PAUSED positionMs=242000 volume=33 Aug 26 08:21:45 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:45.483+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" id= title="Extra Time On You (feat. Portia Monique)" Aug 26 08:21:45 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:45.484+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" id= title="Extra Time On You (feat. Portia Monique)" Aug 26 08:21:45 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:45.484+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" state=STATUS_PAUSED positionMs=242000 volume=33 Aug 26 08:21:45 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:45.485+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" id= title="Extra Time On You (feat. Portia Monique)" Aug 26 08:21:45 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:45.486+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" state=STATUS_PAUSED positionMs=242000 volume=33 Aug 26 08:21:45 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:45.487+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" id= title="Extra Time On You (feat. Portia Monique)" Aug 26 08:21:45 primo sudo[5257]: pam_unix(sudo:session): session closed for user root Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::servicePushState Aug 26 08:21:45 primo volumio[3536]: info: CoreStateMachine::pushState Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::volumioPushState Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::volumioGetState Aug 26 08:21:45 primo volumio[3536]: info: MRS: Pushing multiroomSync output update for this device Aug 26 08:21:45 primo volumio[3536]: info: MRS: Pushing multiroomSync output Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::servicePushState Aug 26 08:21:45 primo volumio[3536]: info: CoreStateMachine::pushState Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::volumioPushState Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::volumioGetState Aug 26 08:21:45 primo volumio[3536]: info: MRS: Pushing multiroomSync output update for this device Aug 26 08:21:45 primo volumio[3536]: info: MRS: Pushing multiroomSync output Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::servicePushState Aug 26 08:21:45 primo volumio[3536]: info: CoreStateMachine::pushState Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::volumioPushState Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::volumioGetState Aug 26 08:21:45 primo volumio[3536]: info: MRS: Pushing multiroomSync output update for this device Aug 26 08:21:45 primo volumio[3536]: info: MRS: Pushing multiroomSync output Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::servicePushState Aug 26 08:21:45 primo volumio[3536]: info: CoreStateMachine::pushState Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::volumioPushState Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::volumioGetState Aug 26 08:21:45 primo volumio[3536]: info: MRS: Pushing multiroomSync output update for this device Aug 26 08:21:45 primo volumio[3536]: info: MRS: Pushing multiroomSync output Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::servicePushState Aug 26 08:21:45 primo volumio[3536]: info: CoreStateMachine::pushState Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::volumioPushState Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::volumioGetState Aug 26 08:21:45 primo volumio[3536]: info: MRS: Pushing multiroomSync output update for this device Aug 26 08:21:45 primo volumio[3536]: info: MRS: Pushing multiroomSync output Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::servicePushState Aug 26 08:21:45 primo volumio[3536]: info: CoreStateMachine::pushState Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::volumioPushState Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::volumioGetState Aug 26 08:21:45 primo volumio[3536]: info: MRS: Pushing multiroomSync output update for this device Aug 26 08:21:45 primo volumio[3536]: info: MRS: Pushing multiroomSync output Aug 26 08:21:45 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:45.546+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" state=STATUS_PLAYING positionMs=242000 volume=33 Aug 26 08:21:45 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:45.547+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" id= title="Extra Time On You (feat. Portia Monique)" Aug 26 08:21:45 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:45.547+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" state=STATUS_PLAYING positionMs=242000 volume=33 Aug 26 08:21:45 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:45.548+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" id= title="Extra Time On You (feat. Portia Monique)" Aug 26 08:21:45 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:45.549+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" state=STATUS_PLAYING positionMs=242000 volume=33 Aug 26 08:21:45 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:45.550+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" state=STATUS_PLAYING positionMs=242000 volume=33 Aug 26 08:21:45 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:45.551+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" state=STATUS_PLAYING positionMs=242000 volume=33 Aug 26 08:21:45 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:45.552+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" id= title="Extra Time On You (feat. Portia Monique)" Aug 26 08:21:45 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:45.552+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" id= title="Extra Time On You (feat. Portia Monique)" Aug 26 08:21:45 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:45.554+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" state=STATUS_PLAYING positionMs=242000 volume=33 Aug 26 08:21:45 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:45.554+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" id= title="Extra Time On You (feat. Portia Monique)" Aug 26 08:21:45 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:45.556+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" id= title="Extra Time On You (feat. Portia Monique)" Aug 26 08:21:45 primo volumio[3536]: info: Signalling Playback active due to playback status change Aug 26 08:21:45 primo volumio[3536]: info: Signalling Playback active due to playback status change Aug 26 08:21:45 primo volumio[3536]: info: Signalling Playback active due to playback status change Aug 26 08:21:45 primo volumio[3536]: info: Signalling Playback active due to playback status change Aug 26 08:21:45 primo volumio[3536]: info: Signalling Playback active due to playback status change Aug 26 08:21:45 primo volumio[3536]: info: Signalling Playback active due to playback status change Aug 26 08:21:45 primo volumio[3536]: info: Updating RAAT Signal Path Aug 26 08:21:45 primo volumio[3536]: info: Updating RAAT Signal Path Aug 26 08:21:45 primo volumio[3536]: info: Updating RAAT Signal Path Aug 26 08:21:45 primo volumio[3536]: info: Updating RAAT Signal Path Aug 26 08:21:45 primo volumio[3536]: info: Updating RAAT Signal Path Aug 26 08:21:45 primo volumio[3536]: info: Updating RAAT Signal Path Aug 26 08:21:45 primo volumio[3536]: info: Updating RAAT Signal Path Aug 26 08:21:45 primo volumio[3536]: info: Updating RAAT Signal Path Aug 26 08:21:45 primo volumio[3536]: info: Updating RAAT Signal Path Aug 26 08:21:45 primo volumio[3536]: info: Updating RAAT Signal Path Aug 26 08:21:45 primo volumio[3536]: info: Updating RAAT Signal Path Aug 26 08:21:45 primo volumio[3536]: info: Updating RAAT Signal Path Aug 26 08:21:45 primo volumio[3536]: info: Starting Shairport Sync Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkCurrentAudioDeviceAvailable Aug 26 08:21:45 primo sudo[5293]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Aug 26 08:21:45 primo sudo[5293]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 26 08:21:45 primo systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Aug 26 08:21:45 primo systemd[1]: shairport-sync.service: Deactivated successfully. Aug 26 08:21:45 primo kernel: asoc-aml-card auge_sound: tdm playback stop Aug 26 08:21:45 primo kernel: spdif_a is set to disable Aug 26 08:21:45 primo kernel: audio_ddr_mngr: frddr_set_sharebuffer_enable sel:1, dst_src:3 Aug 26 08:21:45 primo kernel: aml_dai_tdm_hw_free(), disable mclk for TDM-B Aug 26 08:21:45 primo kernel: tdm playback mute: 1, lane_cnt = 8 Aug 26 08:21:45 primo kernel: audio_ddr_mngr: frddrs[0] released by device ff660000.audiobus:tdm@1 Aug 26 08:21:45 primo systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 26 08:21:45 primo sudo[5298]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl reset-failed raat-daemon.service Aug 26 08:21:45 primo sudo[5298]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 26 08:21:45 primo systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 26 08:21:45 primo sudo[5293]: pam_unix(sudo:session): session closed for user root Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 26 08:21:45 primo volumio[3536]: info: Not Reporting Auto name since its the default one Aug 26 08:21:45 primo volumio[3536]: info: Preparing to generate the ALSA configuration file Aug 26 08:21:45 primo sudo[5298]: pam_unix(sudo:session): session closed for user root Aug 26 08:21:45 primo sudo[5271]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Aug 26 08:21:45 primo sudo[5271]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Aug 26 08:21:45 primo volumio[3536]: info: Shairport-Sync Started Aug 26 08:21:45 primo volumio[3536]: info: The plugin multiroom has an ALSA contribution file volumioMultiRoomServer.postMultiRoom.1000.conf Aug 26 08:21:45 primo volumio[3536]: info: Reading ALSA contributions from plugins. Aug 26 08:21:45 primo volumio[3536]: info: MCU Signalled Playback Inactive Aug 26 08:21:45 primo volumio[3536]: info: MCU Signalled Playback Active Aug 26 08:21:45 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkCurrentAudioDeviceAvailable Aug 26 08:21:45 primo sudo[5271]: pam_unix(sudo:session): session closed for user root Aug 26 08:21:45 primo sudo[5306]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart raat-daemon.service Aug 26 08:21:45 primo sudo[5306]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 26 08:21:45 primo volumio[3536]: info: Asound.conf file written Aug 26 08:21:45 primo systemd[1]: Stopping raat-daemon.service - RAAT DAEMON... Aug 26 08:21:45 primo systemd[1]: raat-daemon.service: Deactivated successfully. Aug 26 08:21:45 primo systemd[1]: Stopped raat-daemon.service - RAAT DAEMON. Aug 26 08:21:45 primo sudo[5326]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl reset-failed raat-daemon.service Aug 26 08:21:45 primo sudo[5326]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 26 08:21:45 primo systemd[1]: Started raat-daemon.service - RAAT DAEMON. Aug 26 08:21:45 primo sudo[5306]: pam_unix(sudo:session): session closed for user root Aug 26 08:21:46 primo kernel: aml_tdm_open Aug 26 08:21:46 primo kernel: Not init audio effects Aug 26 08:21:46 primo kernel: audio_ddr_mngr: frddrs[0] registered by device ff660000.audiobus:tdm@1 Aug 26 08:21:46 primo kernel: tdm playback mute: 1, lane_cnt = 8 Aug 26 08:21:46 primo kernel: audio_ddr_mngr: frddrs[0] released by device ff660000.audiobus:tdm@1 Aug 26 08:21:46 primo kernel: aml_tdm_open Aug 26 08:21:46 primo kernel: Not init audio effects Aug 26 08:21:46 primo kernel: audio_ddr_mngr: frddrs[0] registered by device ff660000.audiobus:tdm@1 Aug 26 08:21:46 primo sudo[5329]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mv /home/volumio/.asoundrc /etc/asound.conf Aug 26 08:21:46 primo sudo[5329]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 26 08:21:46 primo kernel: tdm playback mute: 1, lane_cnt = 8 Aug 26 08:21:46 primo kernel: audio_ddr_mngr: frddrs[0] released by device ff660000.audiobus:tdm@1 Aug 26 08:21:46 primo sudo[5326]: pam_unix(sudo:session): session closed for user root Aug 26 08:21:46 primo sudo[5329]: pam_unix(sudo:session): session closed for user root Aug 26 08:21:46 primo kernel: Fine tdm clk setting range (0~2000000), 11289593 Aug 26 08:21:46 primo kernel: Fine spdif sysclk setting range(0~2000000), 5644797 Aug 26 08:21:46 primo kernel: out of value, fixed it Aug 26 08:21:46 primo kernel: id=0 set inskew=0 Aug 26 08:21:46 primo volumio[3536]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:0 use case configuration -2 Aug 26 08:21:46 primo volumio[3536]: /usr/sbin/alsactl: set_control:1475: Cannot write control '2:0:0:eARC_TX CDS:0' : Operation not permitted Aug 26 08:21:46 primo volumio[3536]: /usr/sbin/alsactl: set_control:1475: Cannot write control '2:0:0:I2SIn CLK:0' : Operation not permitted Aug 26 08:21:46 primo volumio[3536]: /usr/sbin/alsactl: set_control:1475: Cannot write control '2:0:0:SPDIFIN audio samplerate:0' : Operation not permitted Aug 26 08:21:46 primo volumio[3536]: /usr/sbin/alsactl: set_control:1475: Cannot write control '2:0:0:SPDIFIN Audio Type:0' : Operation not permitted Aug 26 08:21:46 primo volumio[3536]: info: Output device has changed, restarting MPD Aug 26 08:21:46 primo sudo[5345]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart raat-daemon.service Aug 26 08:21:46 primo sudo[5345]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 26 08:21:46 primo volumio[3536]: info: Output device has changed, restarting Shairport Sync Aug 26 08:21:46 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:46 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 26 08:21:46 primo sudo[5347]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Aug 26 08:21:46 primo sudo[5347]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 26 08:21:46 primo sudo[5347]: pam_unix(sudo:session): session closed for user root Aug 26 08:21:46 primo volumio[3536]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Aug 26 08:21:46 primo volumio[3536]: info: MRS: Audio Device Changed, rebuilding Multiroom Configuration Aug 26 08:21:46 primo sudo[5351]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Aug 26 08:21:46 primo sudo[5351]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 26 08:21:46 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:46 primo systemd[1]: Stopping raat-daemon.service - RAAT DAEMON... Aug 26 08:21:46 primo systemd[1]: raat-daemon.service: Deactivated successfully. Aug 26 08:21:46 primo systemd[1]: Stopped raat-daemon.service - RAAT DAEMON. Aug 26 08:21:46 primo volumio[3536]: info: QobuzConnect: setDeactiveState invoked Aug 26 08:21:46 primo volumio[3536]: info: CoreCommandRouter::volumioGetState Aug 26 08:21:46 primo volumio[3536]: info: Reconfiguring and Restarting RAAT Plugin due to audio device changes Aug 26 08:21:46 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:46 primo kernel: aml_tdm_open Aug 26 08:21:46 primo kernel: Not init audio effects Aug 26 08:21:46 primo kernel: audio_ddr_mngr: frddrs[0] registered by device ff660000.audiobus:tdm@1 Aug 26 08:21:46 primo kernel: tdm playback mute: 1, lane_cnt = 8 Aug 26 08:21:46 primo kernel: audio_ddr_mngr: frddrs[0] released by device ff660000.audiobus:tdm@1 Aug 26 08:21:46 primo sudo[5361]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service Aug 26 08:21:46 primo sudo[5361]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 26 08:21:46 primo systemd[1]: Started raat-daemon.service - RAAT DAEMON. Aug 26 08:21:46 primo sudo[5345]: pam_unix(sudo:session): session closed for user root Aug 26 08:21:46 primo sudo[5363]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service Aug 26 08:21:46 primo sudo[5363]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 26 08:21:46 primo kernel: aml_tdm_open Aug 26 08:21:46 primo kernel: Not init audio effects Aug 26 08:21:46 primo kernel: audio_ddr_mngr: frddrs[0] registered by device ff660000.audiobus:tdm@1 Aug 26 08:21:46 primo kernel: tdm playback mute: 1, lane_cnt = 8 Aug 26 08:21:46 primo kernel: audio_ddr_mngr: frddrs[0] released by device ff660000.audiobus:tdm@1 Aug 26 08:21:46 primo kernel: aml_tdm_open Aug 26 08:21:46 primo kernel: Not init audio effects Aug 26 08:21:46 primo kernel: audio_ddr_mngr: frddrs[0] registered by device ff660000.audiobus:tdm@1 Aug 26 08:21:46 primo kernel: tdm playback mute: 1, lane_cnt = 8 Aug 26 08:21:46 primo kernel: audio_ddr_mngr: frddrs[0] released by device ff660000.audiobus:tdm@1 Aug 26 08:21:46 primo volumio[3536]: info: CALLMETHOD: audio_interface alsa_controller saveAlsaOptions [object Object] Aug 26 08:21:46 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , saveAlsaOptions Aug 26 08:21:46 primo volumio[3536]: info: Preparing to save Alsa Options, stopping services first Aug 26 08:21:46 primo volumio[3536]: info: CoreCommandRouter::volumioGetState Aug 26 08:21:46 primo volumio[3536]: info: CoreCommandRouter::volumioPause Aug 26 08:21:46 primo volumio[3536]: info: CoreStateMachine::pause Aug 26 08:21:46 primo volumio[3536]: info: CoreStateMachine::stPlaybackTimer Aug 26 08:21:46 primo volumio[3536]: info: CoreStateMachine::servicePause Aug 26 08:21:46 primo volumio[3536]: info: CoreCommandRouter::servicePause Aug 26 08:21:46 primo volumio[3536]: info: Airplay Pause with DBUS Call Aug 26 08:21:46 primo volumio[3536]: info: Saving Audio Output to: {"output_device":{"value":"0,0","label":"Analog Outputs"}} Aug 26 08:21:46 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Aug 26 08:21:46 primo sudo[5381]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl reset-failed qobuz-connect.service Aug 26 08:21:46 primo sudo[5381]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 26 08:21:46 primo systemd[1]: mpd.service: Deactivated successfully. Aug 26 08:21:46 primo systemd[1]: Stopped mpd.service - Music Player Daemon. Aug 26 08:21:46 primo systemd[1]: mpd.socket: Deactivated successfully. Aug 26 08:21:46 primo systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Aug 26 08:21:46 primo systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Aug 26 08:21:46 primo systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Aug 26 08:21:46 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Aug 26 08:21:46 primo systemd[1]: Starting mpd.service - Music Player Daemon... Aug 26 08:21:46 primo volumio[3536]: info: Setting mixer Audio hdmi-out mute for card Analog Outputs Aug 26 08:21:46 primo volumio[3536]: info: QobuzConnect: setDeactiveState invoked Aug 26 08:21:46 primo volumio[3536]: info: CoreCommandRouter::volumioGetState Aug 26 08:21:46 primo volumio[3536]: info: Reconfiguring and Restarting RAAT Plugin due to audio path changes Aug 26 08:21:46 primo sudo[5361]: pam_unix(sudo:session): session closed for user root Aug 26 08:21:46 primo sudo[5396]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service Aug 26 08:21:46 primo sudo[5396]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 26 08:21:46 primo sudo[5363]: pam_unix(sudo:session): session closed for user root Aug 26 08:21:46 primo sudo[5381]: pam_unix(sudo:session): session closed for user root Aug 26 08:21:46 primo volumio[3536]: info: Applying Volume Override Aug 26 08:21:46 primo volumio[3536]: info: CoreCommandRouter::volumioUpdateVolumeSettings Aug 26 08:21:46 primo volumio[3536]: info: Updating Volume Controller Parameters: Device: 0,0 Name: Analog Outputs Mixer: Audio hdmi-out mute Max Vol: 100 Vol Curve; logarithmic Vol Steps: 1 Aug 26 08:21:46 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , setExternalVolume Aug 26 08:21:46 primo volumio[3536]: info: Enabling external Volume Control Aug 26 08:21:46 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: inputs , updateVolumeSettings Aug 26 08:21:46 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: inputs , retrievevolume Aug 26 08:21:46 primo volumio[3536]: info: CoreCommandRouter::getUIConfigOnPlugin Aug 26 08:21:46 primo volumio[3536]: info: CoreStateMachine::pushState Aug 26 08:21:46 primo volumio[3536]: info: CoreCommandRouter::volumioPushState Aug 26 08:21:46 primo volumio[3536]: info: CoreCommandRouter::volumioGetState Aug 26 08:21:46 primo volumio[3536]: info: MRS: Pushing multiroomSync output update for this device Aug 26 08:21:46 primo volumio[3536]: info: MRS: Pushing multiroomSync output Aug 26 08:21:46 primo volumio[3536]: info: CoreStateMachine::pushState Aug 26 08:21:46 primo volumio[3536]: info: CoreCommandRouter::volumioPushState Aug 26 08:21:46 primo volumio[3536]: info: CoreCommandRouter::volumioGetState Aug 26 08:21:46 primo sudo[5402]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart qobuz-connect.service Aug 26 08:21:46 primo sudo[5402]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 26 08:21:46 primo volumio[3536]: info: MRS: Pushing multiroomSync output update for this device Aug 26 08:21:46 primo volumio[3536]: info: MRS: Pushing multiroomSync output Aug 26 08:21:46 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:46.622+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" state=STATUS_PLAYING positionMs=242000 volume=33 Aug 26 08:21:46 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:46.623+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" state=STATUS_PLAYING positionMs=242000 volume=33 Aug 26 08:21:46 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:46.624+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" id= title="Extra Time On You (feat. Portia Monique)" Aug 26 08:21:46 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:46.624+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" id= title="Extra Time On You (feat. Portia Monique)" Aug 26 08:21:46 primo qobuz-connect[4616]: 20260826 08:21:46.625 [4616.4616] INFO SampleApp: shat down connection on UNIX socket Aug 26 08:21:46 primo volumio[3536]: info: Preparing to generate the ALSA configuration file Aug 26 08:21:46 primo systemd[1]: qobuz-connect.service: Deactivated successfully. Aug 26 08:21:46 primo systemd[1]: Stopped qobuz-connect.service - Volumio Qobuz Connect Service. Aug 26 08:21:46 primo sudo[5396]: pam_unix(sudo:session): session closed for user root Aug 26 08:21:46 primo systemd[1]: Started qobuz-connect.service - Volumio Qobuz Connect Service. Aug 26 08:21:46 primo sudo[5407]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service Aug 26 08:21:46 primo sudo[5407]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 26 08:21:46 primo sudo[5287]: pam_unix(sudo:session): session closed for user root Aug 26 08:21:46 primo sudo[5240]: pam_unix(sudo:session): session closed for user root Aug 26 08:21:46 primo sudo[5402]: pam_unix(sudo:session): session closed for user root Aug 26 08:21:46 primo volumio[3536]: info: MPD Permissions set Aug 26 08:21:46 primo volumio[3536]: info: Raat Daemon started successfully Aug 26 08:21:46 primo volumio[3536]: info: Raat Daemon started successfully Aug 26 08:21:46 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:46 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:46 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:46 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:46 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:46 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:46 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:46 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:46 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 26 08:21:46 primo volumio[3536]: info: Not Reporting Auto name since its the default one Aug 26 08:21:46 primo volumio[3536]: info: CoreStateMachine::pushState Aug 26 08:21:46 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 26 08:21:46 primo volumio[3536]: info: CoreCommandRouter::volumioPushState Aug 26 08:21:46 primo sudo[5413]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl reset-failed qobuz-connect.service Aug 26 08:21:46 primo sudo[5413]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 26 08:21:46 primo volumio[3536]: info: CoreCommandRouter::volumioGetState Aug 26 08:21:46 primo volumio[3536]: info: MRS: Pushing multiroomSync output update for this device Aug 26 08:21:46 primo volumio[3536]: info: MRS: Pushing multiroomSync output Aug 26 08:21:46 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:46.857+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" state=STATUS_PLAYING positionMs=243000 volume=33 Aug 26 08:21:46 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:46.858+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" id= title="Extra Time On You (feat. Portia Monique)" Aug 26 08:21:46 primo volumio[3536]: info: The plugin multiroom has an ALSA contribution file volumioMultiRoomServer.postMultiRoom.1000.conf Aug 26 08:21:46 primo volumio[3536]: info: Reading ALSA contributions from plugins. Aug 26 08:21:46 primo sudo[5407]: pam_unix(sudo:session): session closed for user root Aug 26 08:21:46 primo volumio[3536]: info: Signalling Playback active due to playback status change Aug 26 08:21:46 primo volumio[3536]: info: Signalling Playback active due to playback status change Aug 26 08:21:46 primo volumio[3536]: info: Signalling Playback active due to playback status change Aug 26 08:21:46 primo volumio[3536]: info: Updating RAAT Signal Path Aug 26 08:21:46 primo sudo[5413]: pam_unix(sudo:session): session closed for user root Aug 26 08:21:46 primo volumio[3536]: info: Updating RAAT Signal Path Aug 26 08:21:46 primo volumio[3536]: info: Updating RAAT Signal Path Aug 26 08:21:46 primo volumio[3536]: info: Executing endpoint restartRAATSocket Aug 26 08:21:46 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: raat , establishDaemonConnection Aug 26 08:21:46 primo volumio[3536]: info: QobuzConnect: Qobuz Connect client [object Object] disconnected Aug 26 08:21:46 primo volumio[3536]: info: QobuzConnect: setDeactiveState invoked Aug 26 08:21:46 primo volumio[3536]: info: CoreCommandRouter::volumioGetState Aug 26 08:21:46 primo volumio[3536]: info: CoreStateMachine::pushState Aug 26 08:21:46 primo volumio[3536]: info: CoreCommandRouter::volumioPushState Aug 26 08:21:46 primo volumio[3536]: info: CoreCommandRouter::volumioGetState Aug 26 08:21:46 primo volumio[3536]: info: MRS: Pushing multiroomSync output update for this device Aug 26 08:21:46 primo volumio[3536]: info: MRS: Pushing multiroomSync output Aug 26 08:21:46 primo volumio[3536]: error: Serial API: Failed to decode command: MAXVOL, message: 100 Aug 26 08:21:46 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:46.971+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" state=STATUS_PLAYING positionMs=243000 volume=33 Aug 26 08:21:46 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:46.971+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" id= title="Extra Time On You (feat. Portia Monique)" Aug 26 08:21:46 primo sudo[5420]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart qobuz-connect.service Aug 26 08:21:46 primo sudo[5420]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 26 08:21:46 primo volumio[3536]: info: Executing endpoint restartRAATSocket Aug 26 08:21:46 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: raat , establishDaemonConnection Aug 26 08:21:47 primo sudo[5391]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Aug 26 08:21:47 primo sudo[5391]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Aug 26 08:21:47 primo sudo[5391]: pam_unix(sudo:session): session closed for user root Aug 26 08:21:47 primo systemd[1]: Stopping qobuz-connect.service - Volumio Qobuz Connect Service... Aug 26 08:21:47 primo systemd[1]: qobuz-connect.service: Deactivated successfully. Aug 26 08:21:47 primo systemd[1]: Stopped qobuz-connect.service - Volumio Qobuz Connect Service. Aug 26 08:21:47 primo systemd[1]: Started qobuz-connect.service - Volumio Qobuz Connect Service. Aug 26 08:21:47 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:47 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:47 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:47 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:47 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:47 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:47 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:47 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:47 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 26 08:21:47 primo volumio[3536]: info: Not Reporting Auto name since its the default one Aug 26 08:21:47 primo sudo[5420]: pam_unix(sudo:session): session closed for user root Aug 26 08:21:47 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:47 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:47 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:47 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:47 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:47 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:47 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:47 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:47 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 26 08:21:47 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: system , getCPUCoresNumber Aug 26 08:21:47 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:47 primo volumio[3536]: info: Signalling Playback active due to playback status change Aug 26 08:21:47 primo volumio[3536]: info: Executing endpoint qc_getconfig Aug 26 08:21:47 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: qobuzconnect , onGetConfig Aug 26 08:21:47 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions Aug 26 08:21:47 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 26 08:21:47 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Aug 26 08:21:47 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 26 08:21:47 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 26 08:21:47 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 26 08:21:47 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 26 08:21:47 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 26 08:21:47 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 26 08:21:47 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 26 08:21:47 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: mpd , getPlaybackMode Aug 26 08:21:47 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus Aug 26 08:21:47 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: raat , getAdditionalUiSection Aug 26 08:21:47 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: inputs , getAdditionalUiSection Aug 26 08:21:47 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkCurrentAudioDeviceAvailable Aug 26 08:21:47 primo volumio[3536]: info: Executing endpoint qc_getconfig Aug 26 08:21:47 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: qobuzconnect , onGetConfig Aug 26 08:21:47 primo sudo[5463]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl reset-failed raat-daemon.service Aug 26 08:21:47 primo sudo[5463]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 26 08:21:47 primo qobuz-connect[5428]: 20260826 08:21:47.393 [5428.5428] INFO SampleApp: Started connection to /tmp/qbz-connect.socket UNIX socket Aug 26 08:21:47 primo volumio[3536]: info: Starting Shairport Sync Aug 26 08:21:47 primo qobuz-connect[5428]: 20260826 08:21:47.400 [5428.5428] INFO VolumeManager: [0xabe42058]: Setting new playback volume: 75 Aug 26 08:21:47 primo qobuz-connect[5428]: 20260826 08:21:47.401 [5428.5428] INFO VolumeManager: [0xabe42058]: Setting new mute state: 0 Aug 26 08:21:47 primo qobuz-connect[5428]: 20260826 08:21:47.401 [5428.5428] INFO AudioStreamManager: [0xabe41db0]: Setting new audio download buffer size: 1048576 Aug 26 08:21:47 primo qobuz-connect[5428]: 20260826 08:21:47.402 [5428.5428] INFO QobuzConnect: [0xabe42920]: Client initialized! Aug 26 08:21:47 primo qobuz-connect[5428]: 20260826 08:21:47.402 [5428.5428] INFO SampleApp: Starting Avahi advertising, name: Primo, service name: _qobuz-connect._tcp Aug 26 08:21:47 primo qobuz-connect[5428]: 20260826 08:21:47.418 [5428.5428] INFO LocalConfigManager: [0xabe41ad8]: Starting Local Configuration server Aug 26 08:21:47 primo qobuz-connect[5428]: 20260826 08:21:47.418 [5428.5428] INFO SampleApp: Starting Local configuration server Aug 26 08:21:47 primo qobuz-connect[5428]: 20260826 08:21:47.419 [5428.5428] INFO SampleApp: Connected to UNIX socket client 0xabe2c8f8 Aug 26 08:21:47 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkCurrentAudioDeviceAvailable Aug 26 08:21:47 primo sudo[5463]: pam_unix(sudo:session): session closed for user root Aug 26 08:21:47 primo sudo[5468]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Aug 26 08:21:47 primo sudo[5468]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 26 08:21:47 primo sudo[5471]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart raat-daemon.service Aug 26 08:21:47 primo sudo[5471]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 26 08:21:47 primo volumio[3536]: info: QobuzConnect: Qobuz Connect socket /tmp/qbz-connect.socket connected to client [object Object] Aug 26 08:21:47 primo volumio[3536]: info: QobuzConnect: QOBUZ Connect daemon connected Aug 26 08:21:47 primo volumio[3536]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Aug 26 08:21:47 primo volumio[3536]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 9 Aug 26 08:21:47 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:47 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:47 primo sudo[5477]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl reset-failed raat-daemon.service Aug 26 08:21:47 primo sudo[5477]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 26 08:21:47 primo systemd[1]: Stopping raat-daemon.service - RAAT DAEMON... Aug 26 08:21:47 primo volumio[3536]: info: Asound.conf file unchanged, so no further update is needed Aug 26 08:21:47 primo volumio[3536]: info: Output device has changed, restarting MPD Aug 26 08:21:47 primo systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Aug 26 08:21:47 primo qobuz-connect[5428]: 20260826 08:21:47.542 [5428.5428] INFO SampleApp: Playback volume changed: 75 Aug 26 08:21:47 primo systemd[1]: shairport-sync.service: Deactivated successfully. Aug 26 08:21:47 primo systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 26 08:21:47 primo volumio[3536]: info: Output device has changed, restarting Shairport Sync Aug 26 08:21:47 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:47 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 26 08:21:47 primo systemd[1]: raat-daemon.service: Deactivated successfully. Aug 26 08:21:47 primo systemd[1]: Stopped raat-daemon.service - RAAT DAEMON. Aug 26 08:21:47 primo volumio[3536]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Aug 26 08:21:47 primo volumio[3536]: info: MRS: Audio Device Changed, rebuilding Multiroom Configuration Aug 26 08:21:47 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:47 primo sudo[5483]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Aug 26 08:21:47 primo sudo[5483]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 26 08:21:47 primo sudo[5481]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Aug 26 08:21:47 primo sudo[5481]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 26 08:21:47 primo systemd[1]: Started raat-daemon.service - RAAT DAEMON. Aug 26 08:21:47 primo sudo[5471]: pam_unix(sudo:session): session closed for user root Aug 26 08:21:47 primo kernel: aml_tdm_open Aug 26 08:21:47 primo kernel: Not init audio effects Aug 26 08:21:47 primo kernel: audio_ddr_mngr: frddrs[0] registered by device ff660000.audiobus:tdm@1 Aug 26 08:21:47 primo kernel: tdm playback mute: 1, lane_cnt = 8 Aug 26 08:21:47 primo kernel: audio_ddr_mngr: frddrs[0] released by device ff660000.audiobus:tdm@1 Aug 26 08:21:47 primo kernel: aml_tdm_open Aug 26 08:21:47 primo kernel: Not init audio effects Aug 26 08:21:47 primo kernel: audio_ddr_mngr: frddrs[0] registered by device ff660000.audiobus:tdm@1 Aug 26 08:21:47 primo sudo[5481]: pam_unix(sudo:session): session closed for user root Aug 26 08:21:47 primo kernel: tdm playback mute: 1, lane_cnt = 8 Aug 26 08:21:47 primo kernel: audio_ddr_mngr: frddrs[0] released by device ff660000.audiobus:tdm@1 Aug 26 08:21:47 primo volumio[3536]: info: QobuzConnect: setDeactiveState invoked Aug 26 08:21:47 primo volumio[3536]: info: CoreCommandRouter::volumioGetState Aug 26 08:21:47 primo volumio[3536]: info: Reconfiguring and Restarting RAAT Plugin due to audio device changes Aug 26 08:21:47 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:47 primo systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 26 08:21:47 primo volumio[3536]: info: Preparing to generate the ALSA configuration file Aug 26 08:21:47 primo kernel: aml_tdm_open Aug 26 08:21:47 primo kernel: Not init audio effects Aug 26 08:21:47 primo sudo[5468]: pam_unix(sudo:session): session closed for user root Aug 26 08:21:47 primo kernel: audio_ddr_mngr: frddrs[0] registered by device ff660000.audiobus:tdm@1 Aug 26 08:21:47 primo kernel: tdm playback mute: 1, lane_cnt = 8 Aug 26 08:21:47 primo kernel: audio_ddr_mngr: frddrs[0] released by device ff660000.audiobus:tdm@1 Aug 26 08:21:47 primo sudo[5477]: pam_unix(sudo:session): session closed for user root Aug 26 08:21:47 primo sudo[5508]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service Aug 26 08:21:47 primo sudo[5508]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 26 08:21:47 primo sudo[5509]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart raat-daemon.service Aug 26 08:21:47 primo sudo[5509]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 26 08:21:47 primo sudo[5511]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service Aug 26 08:21:47 primo sudo[5511]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 26 08:21:47 primo systemd[1]: mpd.service: Deactivated successfully. Aug 26 08:21:47 primo systemd[1]: Stopped mpd.service - Music Player Daemon. Aug 26 08:21:47 primo volumio[3536]: info: The plugin multiroom has an ALSA contribution file volumioMultiRoomServer.postMultiRoom.1000.conf Aug 26 08:21:47 primo volumio[3536]: info: Reading ALSA contributions from plugins. Aug 26 08:21:47 primo volumio[3536]: info: CoreCommandRouter::volumioGetState Aug 26 08:21:47 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Aug 26 08:21:47 primo volumio[3536]: info: MPD Permissions set Aug 26 08:21:47 primo volumio[3536]: info: Shairport-Sync Started Aug 26 08:21:47 primo volumio[3536]: info: Raat Daemon started successfully Aug 26 08:21:47 primo volumio[3536]: info: CoreStateMachine::pushState Aug 26 08:21:47 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 26 08:21:47 primo volumio[3536]: info: CoreCommandRouter::volumioPushState Aug 26 08:21:47 primo volumio[3536]: info: CoreCommandRouter::volumioGetState Aug 26 08:21:47 primo sudo[5519]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl reset-failed qobuz-connect.service Aug 26 08:21:47 primo sudo[5519]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 26 08:21:47 primo volumio[3536]: info: MRS: Pushing multiroomSync output update for this device Aug 26 08:21:47 primo volumio[3536]: info: MRS: Pushing multiroomSync output Aug 26 08:21:47 primo systemd[1]: mpd.socket: Deactivated successfully. Aug 26 08:21:47 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:47.911+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" state=STATUS_PLAYING positionMs=244000 volume=33 Aug 26 08:21:47 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:47.912+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" id= title="Extra Time On You (feat. Portia Monique)" Aug 26 08:21:47 primo systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Aug 26 08:21:47 primo systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Aug 26 08:21:47 primo volumio[3536]: info: Executing endpoint restartRAATSocket Aug 26 08:21:47 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: raat , establishDaemonConnection Aug 26 08:21:47 primo volumio[3536]: info: CoreStateMachine::pushState Aug 26 08:21:47 primo volumio[3536]: info: CoreCommandRouter::volumioPushState Aug 26 08:21:47 primo volumio[3536]: info: CoreCommandRouter::volumioGetState Aug 26 08:21:47 primo volumio[3536]: info: MRS: Pushing multiroomSync output update for this device Aug 26 08:21:47 primo volumio[3536]: info: MRS: Pushing multiroomSync output Aug 26 08:21:47 primo systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Aug 26 08:21:47 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:47.963+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" state=STATUS_PLAYING positionMs=244000 volume=33 Aug 26 08:21:47 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:47.965+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" id= title="Extra Time On You (feat. Portia Monique)" Aug 26 08:21:47 primo systemd[1]: Stopping raat-daemon.service - RAAT DAEMON... Aug 26 08:21:47 primo volumio[3536]: info: Signalling Playback active due to playback status change Aug 26 08:21:47 primo volumio[3536]: info: Signalling Playback active due to playback status change Aug 26 08:21:47 primo systemd[1]: Starting mpd.service - Music Player Daemon... Aug 26 08:21:48 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:48 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:48 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:48 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:48 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:48 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:48 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:48 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:48 primo systemd[1]: raat-daemon.service: Deactivated successfully. Aug 26 08:21:48 primo systemd[1]: Stopped raat-daemon.service - RAAT DAEMON. Aug 26 08:21:48 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 26 08:21:48 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: system , getCPUCoresNumber Aug 26 08:21:48 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:48 primo sudo[5508]: pam_unix(sudo:session): session closed for user root Aug 26 08:21:48 primo volumio[3536]: info: TidalConnect service stoped! Aug 26 08:21:48 primo volumio[3536]: info: TidalConnect service stoped! Aug 26 08:21:48 primo volumio[3536]: info: Starting Shairport Sync Aug 26 08:21:48 primo sudo[5511]: pam_unix(sudo:session): session closed for user root Aug 26 08:21:48 primo sudo[5519]: pam_unix(sudo:session): session closed for user root Aug 26 08:21:48 primo volumio[3536]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 9 Aug 26 08:21:48 primo systemd[1]: Started raat-daemon.service - RAAT DAEMON. Aug 26 08:21:48 primo sudo[5509]: pam_unix(sudo:session): session closed for user root Aug 26 08:21:48 primo sudo[5552]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Aug 26 08:21:48 primo sudo[5552]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 26 08:21:48 primo sudo[5551]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart qobuz-connect.service Aug 26 08:21:48 primo sudo[5551]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 26 08:21:48 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:48 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:48 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:48 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:48 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:48 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:48 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:48 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:48 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 26 08:21:48 primo volumio[3536]: info: Not Reporting Auto name since its the default one Aug 26 08:21:48 primo kernel: aml_tdm_open Aug 26 08:21:48 primo kernel: Not init audio effects Aug 26 08:21:48 primo kernel: audio_ddr_mngr: frddrs[0] registered by device ff660000.audiobus:tdm@1 Aug 26 08:21:48 primo kernel: tdm playback mute: 1, lane_cnt = 8 Aug 26 08:21:48 primo kernel: audio_ddr_mngr: frddrs[0] released by device ff660000.audiobus:tdm@1 Aug 26 08:21:48 primo kernel: aml_tdm_open Aug 26 08:21:48 primo kernel: Not init audio effects Aug 26 08:21:48 primo volumio[3536]: info: Raat Daemon started successfully Aug 26 08:21:48 primo kernel: audio_ddr_mngr: frddrs[0] registered by device ff660000.audiobus:tdm@1 Aug 26 08:21:48 primo kernel: tdm playback mute: 1, lane_cnt = 8 Aug 26 08:21:48 primo kernel: audio_ddr_mngr: frddrs[0] released by device ff660000.audiobus:tdm@1 Aug 26 08:21:48 primo systemd[1]: Stopping qobuz-connect.service - Volumio Qobuz Connect Service... Aug 26 08:21:48 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkCurrentAudioDeviceAvailable Aug 26 08:21:48 primo qobuz-connect[5428]: 20260826 08:21:48.330 [5428.5428] INFO SampleApp: Stopping Local configuration server Aug 26 08:21:48 primo systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Aug 26 08:21:48 primo systemd[1]: shairport-sync.service: Deactivated successfully. Aug 26 08:21:48 primo systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 26 08:21:48 primo volumio[3536]: info: Asound.conf file written Aug 26 08:21:48 primo systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 26 08:21:48 primo sudo[5577]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl reset-failed raat-daemon.service Aug 26 08:21:48 primo sudo[5577]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 26 08:21:48 primo sudo[5552]: pam_unix(sudo:session): session closed for user root Aug 26 08:21:48 primo sudo[5580]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mv /home/volumio/.asoundrc /etc/asound.conf Aug 26 08:21:48 primo sudo[5580]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 26 08:21:48 primo sudo[5580]: pam_unix(sudo:session): session closed for user root Aug 26 08:21:48 primo sudo[5577]: pam_unix(sudo:session): session closed for user root Aug 26 08:21:48 primo kernel: Fine tdm clk setting range (0~2000000), 11289593 Aug 26 08:21:48 primo kernel: Fine spdif sysclk setting range(0~2000000), 5644797 Aug 26 08:21:48 primo kernel: out of value, fixed it Aug 26 08:21:48 primo kernel: id=0 set inskew=0 Aug 26 08:21:48 primo volumio[3536]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:0 use case configuration -2 Aug 26 08:21:48 primo volumio[3536]: /usr/sbin/alsactl: set_control:1475: Cannot write control '2:0:0:eARC_TX CDS:0' : Operation not permitted Aug 26 08:21:48 primo volumio[3536]: /usr/sbin/alsactl: set_control:1475: Cannot write control '2:0:0:I2SIn CLK:0' : Operation not permitted Aug 26 08:21:48 primo volumio[3536]: /usr/sbin/alsactl: set_control:1475: Cannot write control '2:0:0:SPDIFIN audio samplerate:0' : Operation not permitted Aug 26 08:21:48 primo volumio[3536]: /usr/sbin/alsactl: set_control:1475: Cannot write control '2:0:0:SPDIFIN Audio Type:0' : Operation not permitted Aug 26 08:21:48 primo volumio[3536]: info: Output device has changed, restarting MPD Aug 26 08:21:48 primo sudo[5593]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart raat-daemon.service Aug 26 08:21:48 primo sudo[5593]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 26 08:21:48 primo sudo[5537]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Aug 26 08:21:48 primo volumio[3536]: info: Output device has changed, restarting Shairport Sync Aug 26 08:21:48 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:48 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 26 08:21:48 primo sudo[5537]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Aug 26 08:21:48 primo sudo[5537]: pam_unix(sudo:session): session closed for user root Aug 26 08:21:48 primo sudo[5603]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Aug 26 08:21:48 primo sudo[5603]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 26 08:21:48 primo sudo[5603]: pam_unix(sudo:session): session closed for user root Aug 26 08:21:48 primo volumio[3536]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Aug 26 08:21:48 primo volumio[3536]: info: MRS: Audio Device Changed, rebuilding Multiroom Configuration Aug 26 08:21:48 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:48 primo sudo[5606]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Aug 26 08:21:48 primo sudo[5606]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 26 08:21:48 primo volumio[3536]: info: QobuzConnect: setDeactiveState invoked Aug 26 08:21:48 primo volumio[3536]: info: CoreCommandRouter::volumioGetState Aug 26 08:21:48 primo volumio[3536]: info: Reconfiguring and Restarting RAAT Plugin due to audio device changes Aug 26 08:21:48 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:48 primo systemd[1]: Stopping raat-daemon.service - RAAT DAEMON... Aug 26 08:21:48 primo systemd[1]: raat-daemon.service: Deactivated successfully. Aug 26 08:21:48 primo systemd[1]: Stopped raat-daemon.service - RAAT DAEMON. Aug 26 08:21:48 primo kernel: aml_tdm_open Aug 26 08:21:48 primo kernel: Not init audio effects Aug 26 08:21:48 primo kernel: audio_ddr_mngr: frddrs[0] registered by device ff660000.audiobus:tdm@1 Aug 26 08:21:48 primo kernel: tdm playback mute: 1, lane_cnt = 8 Aug 26 08:21:48 primo kernel: audio_ddr_mngr: frddrs[0] released by device ff660000.audiobus:tdm@1 Aug 26 08:21:48 primo sudo[5617]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service Aug 26 08:21:48 primo sudo[5617]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 26 08:21:48 primo systemd[1]: Started raat-daemon.service - RAAT DAEMON. Aug 26 08:21:48 primo sudo[5619]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service Aug 26 08:21:48 primo sudo[5619]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 26 08:21:48 primo kernel: aml_tdm_open Aug 26 08:21:48 primo kernel: Not init audio effects Aug 26 08:21:48 primo volumio[3536]: info: Updating tc_getconfig REST Endpoint for plugin: music_service/tidalconnect Aug 26 08:21:48 primo volumio[3536]: info: Updating tc_connect REST Endpoint for plugin: music_service/tidalconnect Aug 26 08:21:48 primo sudo[5593]: pam_unix(sudo:session): session closed for user root Aug 26 08:21:48 primo kernel: audio_ddr_mngr: frddrs[0] registered by device ff660000.audiobus:tdm@1 Aug 26 08:21:48 primo kernel: tdm playback mute: 1, lane_cnt = 8 Aug 26 08:21:48 primo kernel: audio_ddr_mngr: frddrs[0] released by device ff660000.audiobus:tdm@1 Aug 26 08:21:48 primo kernel: aml_tdm_open Aug 26 08:21:48 primo kernel: Not init audio effects Aug 26 08:21:48 primo kernel: audio_ddr_mngr: frddrs[0] registered by device ff660000.audiobus:tdm@1 Aug 26 08:21:48 primo volumio[3536]: info: RAAT: Requesting Headphone Status Aug 26 08:21:48 primo kernel: tdm playback mute: 1, lane_cnt = 8 Aug 26 08:21:48 primo kernel: audio_ddr_mngr: frddrs[0] released by device ff660000.audiobus:tdm@1 Aug 26 08:21:48 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: inputs , getHeadphoneStatus Aug 26 08:21:48 primo sudo[5631]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl reset-failed qobuz-connect.service Aug 26 08:21:48 primo sudo[5631]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 26 08:21:48 primo volumio[3536]: info: Executing endpoint restartRAATSocket Aug 26 08:21:48 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: raat , establishDaemonConnection Aug 26 08:21:48 primo volumio[3536]: info: MPD Permissions set Aug 26 08:21:48 primo volumio[3536]: info: Raat Daemon started successfully Aug 26 08:21:48 primo volumio[3536]: info: TidalConnect service stoped! Aug 26 08:21:48 primo volumio[3536]: info: TidalConnect service stoped! Aug 26 08:21:48 primo volumio[3536]: info: Shairport-Sync Started Aug 26 08:21:48 primo volumio[3536]: info: CoreStateMachine::pushState Aug 26 08:21:48 primo volumio[3536]: info: CoreCommandRouter::volumioPushState Aug 26 08:21:48 primo volumio[3536]: info: CoreCommandRouter::volumioGetState Aug 26 08:21:48 primo volumio[3536]: info: MRS: Pushing multiroomSync output update for this device Aug 26 08:21:48 primo volumio[3536]: info: MRS: Pushing multiroomSync output Aug 26 08:21:48 primo sudo[5638]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start vtcs.service Aug 26 08:21:48 primo sudo[5638]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 26 08:21:48 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:48.818+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" state=STATUS_PLAYING positionMs=244000 volume=33 Aug 26 08:21:48 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:48.818+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" id= title="Extra Time On You (feat. Portia Monique)" Aug 26 08:21:48 primo volumio[3536]: info: CoreStateMachine::pushState Aug 26 08:21:48 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 26 08:21:48 primo volumio[3536]: info: CoreCommandRouter::volumioPushState Aug 26 08:21:48 primo volumio[3536]: info: CoreCommandRouter::volumioGetState Aug 26 08:21:48 primo volumio[3536]: info: MRS: Pushing multiroomSync output update for this device Aug 26 08:21:48 primo volumio[3536]: info: MRS: Pushing multiroomSync output Aug 26 08:21:48 primo volumio[3536]: info: MCU Signalled Headphone Mode Disabled Aug 26 08:21:48 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: raat , reportHeadphoneState Aug 26 08:21:48 primo volumio[3536]: info: Reporting Headphone State: false Aug 26 08:21:48 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:48 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:48 primo volumio[3536]: info: Updating RAAT Signal Path Aug 26 08:21:48 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:48.853+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" state=STATUS_PLAYING positionMs=245000 volume=33 Aug 26 08:21:48 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:48.853+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" id= title="Extra Time On You (feat. Portia Monique)" Aug 26 08:21:48 primo volumio[3536]: info: Signalling Playback active due to playback status change Aug 26 08:21:48 primo volumio[3536]: info: Signalling Playback active due to playback status change Aug 26 08:21:48 primo volumio[3536]: info: CoreCommandRouter::volumioRetrieveVolumeLevels Aug 26 08:21:48 primo volumio[3536]: info: CoreStateMachine::getcurrentVolume Aug 26 08:21:48 primo volumio[3536]: info: CoreCommandRouter::volumioRetrievevolume Aug 26 08:21:48 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: inputs , retrievevolume Aug 26 08:21:48 primo volumio[3536]: info: CoreStateMachine::pushState Aug 26 08:21:48 primo volumio[3536]: info: CoreCommandRouter::volumioPushState Aug 26 08:21:48 primo volumio[3536]: info: CoreCommandRouter::volumioGetState Aug 26 08:21:48 primo volumio[3536]: info: MRS: Pushing multiroomSync output update for this device Aug 26 08:21:48 primo volumio[3536]: info: MRS: Pushing multiroomSync output Aug 26 08:21:48 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:48.886+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" state=STATUS_PLAYING positionMs=245000 volume=33 Aug 26 08:21:48 primo volumio5-onboarding[3817]: time=2026-08-26T08:21:48.887+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.2.9:49693,00:00:00:00:00:00%01 @ 0x2cc2c60" id= title="Extra Time On You (feat. Portia Monique)" Aug 26 08:21:48 primo sudo[5631]: pam_unix(sudo:session): session closed for user root Aug 26 08:21:48 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:48 primo sudo[5619]: pam_unix(sudo:session): session closed for user root Aug 26 08:21:48 primo sudo[5617]: pam_unix(sudo:session): session closed for user root Aug 26 08:21:48 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:48 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:48 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:48 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:48 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:48 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:48 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:48 primo systemd[1]: Started vtcs.service - Volumio Tidal Connect Service. Aug 26 08:21:48 primo sudo[5638]: pam_unix(sudo:session): session closed for user root Aug 26 08:21:48 primo sudo[5645]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart qobuz-connect.service Aug 26 08:21:48 primo sudo[5645]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 26 08:21:48 primo systemd[1]: mpd.service: Deactivated successfully. Aug 26 08:21:48 primo systemd[1]: Stopped mpd.service - Music Player Daemon. Aug 26 08:21:48 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 26 08:21:48 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: system , getCPUCoresNumber Aug 26 08:21:48 primo systemd[1]: mpd.socket: Deactivated successfully. Aug 26 08:21:49 primo systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Aug 26 08:21:49 primo systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Aug 26 08:21:49 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 26 08:21:49 primo systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Aug 26 08:21:49 primo volumio[3536]: info: Signalling Playback active due to playback status change Aug 26 08:21:49 primo volumio[3536]: info: Executing endpoint restartRAATSocket Aug 26 08:21:49 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: raat , establishDaemonConnection Aug 26 08:21:49 primo volumio[3536]: info: RAAT: Requesting Headphone Status Aug 26 08:21:49 primo volumio[3536]: info: CoreCommandRouter::executeOnPlugin: inputs , getHeadphoneStatus Aug 26 08:21:49 primo systemd[1]: Starting mpd.service - Music Player Daemon... Aug 26 08:21:49 primo volumio[3536]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 26 08:21:49 primo volumio[3536]: Error: Command failed: /usr/bin/sudo /bin/systemctl stop vtcs.service && sleep 3 Aug 26 08:21:49 primo volumio[3536]: Job for vtcs.service canceled. Aug 26 08:21:49 primo volumio[3536]: at ChildProcess.exithandler (node:child_process:421:12) Aug 26 08:21:49 primo volumio[3536]: at ChildProcess.emit (node:events:514:28) Aug 26 08:21:49 primo volumio[3536]: at maybeClose (node:internal/child_process:1105:16) Aug 26 08:21:49 primo volumio[3536]: at Socket. (node:internal/child_process:457:11) Aug 26 08:21:49 primo volumio[3536]: at Socket.emit (node:events:514:28) Aug 26 08:21:49 primo volumio[3536]: at Pipe. (node:net:337:12) { Aug 26 08:21:49 primo volumio[3536]: code: 1, Aug 26 08:21:49 primo volumio[3536]: killed: false, Aug 26 08:21:49 primo volumio[3536]: signal: null, Aug 26 08:21:49 primo volumio[3536]: cmd: '/usr/bin/sudo /bin/systemctl stop vtcs.service && sleep 3', Aug 26 08:21:49 primo volumio[3536]: stdout: '', Aug 26 08:21:49 primo volumio[3536]: stderr: 'Job for vtcs.service canceled.\n' Aug 26 08:21:49 primo volumio[3536]: } Aug 26 08:21:49 primo volumio[3536]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 26 08:21:49 primo qobuz-connect[5428]: 20260826 08:21:49.428 [5428.5428] INFO SampleApp: shat down connection on UNIX socket Aug 26 08:21:49 primo systemd[1]: qobuz-connect.service: Deactivated successfully. Aug 26 08:21:49 primo systemd[1]: Stopped qobuz-connect.service - Volumio Qobuz Connect Service. Aug 26 08:21:49 primo systemd[1]: Started qobuz-connect.service - Volumio Qobuz Connect Service. Aug 26 08:21:49 primo sudo[5551]: pam_unix(sudo:session): session closed for user root Aug 26 08:21:49 primo sudo[5645]: pam_unix(sudo:session): session closed for user root Aug 26 08:21:49 primo sudo[5662]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Aug 26 08:21:49 primo sudo[5662]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Aug 26 08:21:49 primo sudo[5662]: pam_unix(sudo:session): session closed for user root Aug 26 08:21:50 primo sudo[5675]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-08-26 08:20' Aug 26 08:21:50 primo sudo[5675]: 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="9ccd1247f8cab3c5d64c23a96d243f6bfa34d032" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="9938d7179e3b7c4e41f3e2d60c255985cff08fee" VOLUMIO_ARCH="armv7" VOLUMIO_VARIANT="primo2rev2" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Sun May 17 17:32:08 UTC 2026" VOLUMIO_VERSION="4.158" VOLUMIO_HARDWARE="mp1" VOLUMIO_DEVICENAME="Volumio MP1" VOLUMIO_VENDOR_MODEL="Volumio Primo" VOLUMIO_VENDOR="Volumio" VOLUMIO_MODEL="Primo" VOLUMIO_HASH="43d420a3aa41c50690ebfe378df38e2b"