Aug 29 14:53:00 primo volumio[3543]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 29 14:53:00 primo volumio[3543]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 29 14:53:00 primo volumio[3543]: info: Discovery: Getting this device information Aug 29 14:53:00 primo volumio[3543]: info: CoreCommandRouter::volumioGetState Aug 29 14:53:00 primo volumio[3543]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 29 14:53:00 primo volumio[3543]: verbose: New Socket.io Connection to 192.168.1.10:3000 from 192.168.1.11 UA: Dart/3.12 (dart:io) Engine version: 3 Transport: websocket Total Clients: 9 Aug 29 14:53:00 primo volumio[3543]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Aug 29 14:53:00 primo volumio[3543]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Aug 29 14:53:01 primo volumio[3543]: info: CoreCommandRouter::volumioGetState Aug 29 14:53:03 primo volumio[3543]: info: Executing endpoint metavolumio Aug 29 14:53:03 primo volumio[3543]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Aug 29 14:53:03 primo volumio[3543]: info: Executing endpoint metavolumio Aug 29 14:53:03 primo volumio[3543]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Aug 29 14:53:03 primo volumio[3543]: info: Executing endpoint metavolumio Aug 29 14:53:03 primo volumio[3543]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Aug 29 14:53:03 primo volumio5-onboarding[3811]: time=2026-08-29T14:53:03.153+03:00 level=INFO msg="WebSocket connection closed" component=conn/ws remoteAddr=192.168.1.11:55467 Aug 29 14:53:03 primo volumio5-onboarding[3811]: time=2026-08-29T14:53:03.153+03:00 level=INFO msg="connection to address closed" component=conn/multi addr=192.168.1.11:55467 Aug 29 14:53:03 primo volumio5-onboarding[3811]: time=2026-08-29T14:53:03.169+03:00 level=INFO msg="established new WebSocket connection" component=conn/ws remoteAddr=192.168.1.11:55589 Aug 29 14:53:03 primo volumio5-onboarding[3811]: time=2026-08-29T14:53:03.217+03:00 level=INFO msg="device data request" component=server type=REQUEST_TYPE_DEVICE_DATA peer="192.168.1.11:55589 @ 0x1d52450" latency=65.488263ms timeout=20s Aug 29 14:53:03 primo volumio5-onboarding[3811]: time=2026-08-29T14:53:03.217+03:00 level=INFO msg="emitting device capabilities changed event" component=server peer="192.168.1.11:55589 @ 0x1d52450" Aug 29 14:53:03 primo volumio[3543]: info: Received Get System Info Aug 29 14:53:03 primo volumio[3543]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 29 14:53:03 primo volumio[3543]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 29 14:53:03 primo volumio[3543]: info: Discovery: Getting this device information Aug 29 14:53:03 primo volumio[3543]: info: CoreCommandRouter::volumioGetState Aug 29 14:53:03 primo volumio[3543]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 29 14:53:03 primo volumio5-onboarding[3811]: time=2026-08-29T14:53:03.225+03:00 level=INFO msg="emitting device name changed event" component=server peer="192.168.1.11:55589 @ 0x1d52450" name=Primo Aug 29 14:53:03 primo volumio5-onboarding[3811]: time=2026-08-29T14:53:03.226+03:00 level=INFO msg="emitting device language changed event" component=server peer="192.168.1.11:55589 @ 0x1d52450" language=tr Aug 29 14:53:03 primo volumio[3543]: info: CoreCommandRouter::executeOnPlugin: system , getCurrentTimezone Aug 29 14:53:03 primo volumio5-onboarding[3811]: time=2026-08-29T14:53:03.232+03:00 level=INFO msg="emitting device timezone changed event" component=server peer="192.168.1.11:55589 @ 0x1d52450" timezone=Europe/Istanbul Aug 29 14:53:03 primo volumio5-onboarding[3811]: time=2026-08-29T14:53:03.233+03:00 level=INFO msg="emitting ethernet info changed event" component=server peer="192.168.1.11:55589 @ 0x1d52450" available=true connected=true macAddress=02:00:00:10:18:01 ip4Address=192.168.1.10/24 ip6Address= Aug 29 14:53:03 primo volumio5-onboarding[3811]: time=2026-08-29T14:53:03.234+03:00 level=INFO msg="check connectivity" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.11:55589 @ 0x1d52450" latency=66.720573ms timeout=10s Aug 29 14:53:03 primo volumio5-onboarding[3811]: time=2026-08-29T14:53:03.239+03:00 level=INFO msg="emitting wifi info changed event" component=server peer="192.168.1.11:55589 @ 0x1d52450" available=true connected=false macAddress= ip4Address= ip6Address= ssid= Aug 29 14:53:03 primo volumio5-onboarding[3811]: time=2026-08-29T14:53:03.240+03:00 level=INFO msg="emitting device setup status changed event" component=server peer="192.168.1.11:55589 @ 0x1d52450" setupComplete=true Aug 29 14:53:03 primo volumio[3543]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getExtendedOutputDevices Aug 29 14:53:03 primo volumio[3543]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions Aug 29 14:53:03 primo volumio[3543]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 29 14:53:03 primo volumio[3543]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Aug 29 14:53:03 primo volumio5-onboarding[3811]: time=2026-08-29T14:53:03.276+03:00 level=INFO msg="emitting audio outputs changed event" component=server peer="192.168.1.11:55589 @ 0x1d52450" selectedOutputId=0,0 Aug 29 14:53:03 primo volumio5-onboarding[3811]: time=2026-08-29T14:53:03.277+03:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.11:55589 @ 0x1d52450" latency=66.720573ms timeout=10s endpoint=http://pushupdates.volumio.org duration=40.862283ms Aug 29 14:53:03 primo volumio5-onboarding[3811]: time=2026-08-29T14:53:03.277+03:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.11:55589 @ 0x1d52450" latency=66.720573ms timeout=10s endpoint=https://browsing-performer.dfs.volumio.org duration=42.370668ms Aug 29 14:53:03 primo volumio5-onboarding[3811]: time=2026-08-29T14:53:03.299+03:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.11:55589 @ 0x1d52450" latency=66.720573ms timeout=10s endpoint=https://radio-directory.firebaseapp.com duration=64.287714ms Aug 29 14:53:03 primo volumio5-onboarding[3811]: time=2026-08-29T14:53:03.302+03:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.11:55589 @ 0x1d52450" latency=66.720573ms timeout=10s endpoint=https://oauth-performer.dfs.volumio.org duration=66.342518ms Aug 29 14:53:03 primo volumio[3543]: info: Received Get System Info Aug 29 14:53:03 primo volumio[3543]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 29 14:53:03 primo volumio[3543]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 29 14:53:03 primo volumio[3543]: info: Discovery: Getting this device information Aug 29 14:53:03 primo volumio[3543]: info: CoreCommandRouter::volumioGetState Aug 29 14:53:03 primo volumio[3543]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 29 14:53:03 primo volumio5-onboarding[3811]: time=2026-08-29T14:53:03.308+03:00 level=INFO msg="emitting software info changed event" component=server peer="192.168.1.11:55589 @ 0x1d52450" currentVersion=4.158 latestVersion=4.158 Aug 29 14:53:03 primo volumio5-onboarding[3811]: time=2026-08-29T14:53:03.308+03:00 level=INFO msg="emitting software update progress event" component=server peer="192.168.1.11:55589 @ 0x1d52450" status=UPDATE_STATUS_NONE progress=0 Aug 29 14:53:03 primo volumio5-onboarding[3811]: time=2026-08-29T14:53:03.309+03:00 level=INFO msg="emitting user changed event" component=server peer="192.168.1.11:55589 @ 0x1d52450" userId= Aug 29 14:53:03 primo volumio5-onboarding[3811]: time=2026-08-29T14:53:03.309+03:00 level=INFO msg="emitting music providers changed event" component=server peer="192.168.1.11:55589 @ 0x1d52450" providers=3 Aug 29 14:53:03 primo volumio5-onboarding[3811]: time=2026-08-29T14:53:03.309+03:00 level=INFO msg="emitting plugins changed event" component=server peer="192.168.1.11:55589 @ 0x1d52450" plugins=24 Aug 29 14:53:03 primo volumio[3543]: info: CoreCommandRouter::volumioGetState Aug 29 14:53:03 primo volumio5-onboarding[3811]: time=2026-08-29T14:53:03.317+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.11:55589 @ 0x1d52450" state=STATUS_PLAYING positionMs=200618 volume=100 Aug 29 14:53:03 primo volumio5-onboarding[3811]: time=2026-08-29T14:53:03.317+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.11:55589 @ 0x1d52450" id=qobuz://song/54319180 title=Temptation Aug 29 14:53:03 primo volumio5-onboarding[3811]: time=2026-08-29T14:53:03.352+03:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.11:55589 @ 0x1d52450" latency=66.720573ms timeout=10s endpoint=https://www.googleapis.com duration=117.315778ms Aug 29 14:53:03 primo volumio5-onboarding[3811]: time=2026-08-29T14:53:03.396+03:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.11:55589 @ 0x1d52450" latency=66.720573ms timeout=10s endpoint=https://securetoken.googleapis.com duration=160.479034ms Aug 29 14:53:03 primo volumio5-onboarding[3811]: time=2026-08-29T14:53:03.409+03:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.11:55589 @ 0x1d52450" latency=66.720573ms timeout=10s endpoint=https://myvolumio.firebaseio.com duration=174.018989ms Aug 29 14:53:03 primo volumio5-onboarding[3811]: time=2026-08-29T14:53:03.424+03:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.11:55589 @ 0x1d52450" latency=66.720573ms timeout=10s endpoint=https://database.volumio.cloud duration=188.229073ms Aug 29 14:53:03 primo volumio5-onboarding[3811]: time=2026-08-29T14:53:03.426+03:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.11:55589 @ 0x1d52450" latency=66.720573ms timeout=10s endpoint=https://functions.volumio.cloud duration=189.905125ms Aug 29 14:53:03 primo volumio5-onboarding[3811]: time=2026-08-29T14:53:03.430+03:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.11:55589 @ 0x1d52450" latency=66.720573ms timeout=10s endpoint=https://functions.volumio.cloud duration=194.704111ms Aug 29 14:53:03 primo volumio5-onboarding[3811]: time=2026-08-29T14:53:03.471+03:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.11:55589 @ 0x1d52450" latency=66.720573ms timeout=10s endpoint=http://cddb.volumio.org duration=236.119982ms Aug 29 14:53:03 primo volumio5-onboarding[3811]: time=2026-08-29T14:53:03.619+03:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.11:55589 @ 0x1d52450" latency=66.720573ms timeout=10s endpoint=http://plugins.volumio.org duration=382.777226ms Aug 29 14:53:03 primo volumio5-onboarding[3811]: time=2026-08-29T14:53:03.644+03:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.11:55589 @ 0x1d52450" latency=66.720573ms timeout=10s endpoint=https://google.com duration=409.539176ms Aug 29 14:53:16 primo volumio5-onboarding[3811]: time=2026-08-29T14:53:16.711+03:00 level=INFO msg="check connectivity" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.11:55589 @ 0x1d52450" latency=73.300485ms timeout=10s Aug 29 14:53:16 primo volumio5-onboarding[3811]: time=2026-08-29T14:53:16.752+03:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.11:55589 @ 0x1d52450" latency=73.300485ms timeout=10s endpoint=http://pushupdates.volumio.org duration=40.008321ms Aug 29 14:53:16 primo volumio5-onboarding[3811]: time=2026-08-29T14:53:16.754+03:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.11:55589 @ 0x1d52450" latency=73.300485ms timeout=10s endpoint=https://browsing-performer.dfs.volumio.org duration=41.546538ms Aug 29 14:53:16 primo volumio5-onboarding[3811]: time=2026-08-29T14:53:16.774+03:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.11:55589 @ 0x1d52450" latency=73.300485ms timeout=10s endpoint=https://oauth-performer.dfs.volumio.org duration=62.337577ms Aug 29 14:53:16 primo volumio5-onboarding[3811]: time=2026-08-29T14:53:16.776+03:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.11:55589 @ 0x1d52450" latency=73.300485ms timeout=10s endpoint=https://radio-directory.firebaseapp.com duration=64.41134ms Aug 29 14:53:16 primo volumio5-onboarding[3811]: time=2026-08-29T14:53:16.834+03:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.11:55589 @ 0x1d52450" latency=73.300485ms timeout=10s endpoint=https://www.googleapis.com duration=122.326892ms Aug 29 14:53:16 primo volumio5-onboarding[3811]: time=2026-08-29T14:53:16.875+03:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.11:55589 @ 0x1d52450" latency=73.300485ms timeout=10s endpoint=https://securetoken.googleapis.com duration=163.562386ms Aug 29 14:53:16 primo volumio5-onboarding[3811]: time=2026-08-29T14:53:16.885+03:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.11:55589 @ 0x1d52450" latency=73.300485ms timeout=10s endpoint=https://myvolumio.firebaseio.com duration=174.120948ms Aug 29 14:53:16 primo volumio5-onboarding[3811]: time=2026-08-29T14:53:16.901+03:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.11:55589 @ 0x1d52450" latency=73.300485ms timeout=10s endpoint=https://database.volumio.cloud duration=188.652992ms Aug 29 14:53:16 primo volumio5-onboarding[3811]: time=2026-08-29T14:53:16.903+03:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.11:55589 @ 0x1d52450" latency=73.300485ms timeout=10s endpoint=https://functions.volumio.cloud duration=191.274966ms Aug 29 14:53:16 primo volumio5-onboarding[3811]: time=2026-08-29T14:53:16.904+03:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.11:55589 @ 0x1d52450" latency=73.300485ms timeout=10s endpoint=https://functions.volumio.cloud duration=192.565766ms Aug 29 14:53:16 primo volumio5-onboarding[3811]: time=2026-08-29T14:53:16.948+03:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.11:55589 @ 0x1d52450" latency=73.300485ms timeout=10s endpoint=http://cddb.volumio.org duration=236.495526ms Aug 29 14:53:17 primo volumio5-onboarding[3811]: time=2026-08-29T14:53:17.100+03:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.11:55589 @ 0x1d52450" latency=73.300485ms timeout=10s endpoint=http://plugins.volumio.org duration=388.093007ms Aug 29 14:53:17 primo volumio5-onboarding[3811]: time=2026-08-29T14:53:17.116+03:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.11:55589 @ 0x1d52450" latency=73.300485ms timeout=10s endpoint=https://google.com duration=404.855148ms Aug 29 14:53:17 primo volumio[3543]: verbose: New Socket.io Connection to 192.168.1.10 from 192.168.1.11 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 29 14:53:17 primo volumio[3543]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Aug 29 14:53:18 primo volumio[3543]: info: CoreCommandRouter::volumioGetVisibleSources Aug 29 14:53:18 primo volumio[3543]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 29 14:53:18 primo volumio[3543]: info: CoreCommandRouter::volumioGetState Aug 29 14:53:18 primo volumio[3543]: info: CoreCommandRouter::volumioGetState Aug 29 14:53:18 primo volumio[3543]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Aug 29 14:53:18 primo volumio[3543]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Aug 29 14:53:18 primo volumio[3543]: info: Error : CoreCommandRouter::executeOnPlugin: No method [getMultiroom] in plugin multiroom Aug 29 14:53:18 primo volumio[3543]: info: Received Get System Info Aug 29 14:53:18 primo volumio[3543]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 29 14:53:18 primo volumio[3543]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 29 14:53:18 primo volumio[3543]: info: Discovery: Getting this device information Aug 29 14:53:18 primo volumio[3543]: info: CoreCommandRouter::volumioGetState Aug 29 14:53:18 primo volumio[3543]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 29 14:53:18 primo volumio[3543]: info: CoreCommandRouter::volumioGetState Aug 29 14:53:18 primo volumio[3543]: info: Listing playlists Aug 29 14:53:18 primo volumio[3543]: info: CoreCommandRouter::volumioGetQueue Aug 29 14:53:18 primo volumio[3543]: info: CoreStateMachine::getQueue Aug 29 14:53:18 primo volumio[3543]: info: CorePlayQueue::getQueue Aug 29 14:53:18 primo volumio[3543]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Aug 29 14:53:19 primo volumio[3543]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 29 14:53:19 primo volumio[3543]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 29 14:53:19 primo volumio[3543]: info: Discovery: Getting this device information Aug 29 14:53:19 primo volumio[3543]: info: CoreCommandRouter::volumioGetState Aug 29 14:53:19 primo volumio[3543]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 29 14:53:19 primo volumio[3543]: verbose: New Socket.io Connection to 192.168.1.10:3000 from 192.168.1.11 UA: Dart/3.12 (dart:io) Engine version: 3 Transport: websocket Total Clients: 9 Aug 29 14:53:19 primo volumio[3543]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Aug 29 14:53:19 primo volumio[3543]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Aug 29 14:53:20 primo volumio[3543]: info: Executing endpoint metavolumio Aug 29 14:53:20 primo volumio[3543]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Aug 29 14:53:20 primo volumio[3543]: info: Executing endpoint metavolumio Aug 29 14:53:20 primo volumio[3543]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Aug 29 14:53:20 primo volumio[3543]: info: Executing endpoint metavolumio Aug 29 14:53:20 primo volumio[3543]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Aug 29 14:53:21 primo volumio[3543]: info: CoreCommandRouter::volumioGetState Aug 29 14:53:23 primo volumio[3543]: info: CoreCommandRouter::getUIConfigOnPlugin Aug 29 14:53:23 primo volumio[3543]: info: CoreCommandRouter::getUIConfigOnPlugin Aug 29 14:53:23 primo volumio[3543]: info: Retrieving Cloud Streaming UI Aug 29 14:53:23 primo volumio[3543]: info: Getting Tidal Cloud Configuration Aug 29 14:53:23 primo volumio[3543]: info: CoreCommandRouter::getUIConfigOnPlugin Aug 29 14:53:23 primo volumio[3543]: info: Getting Qobuz Cloud Configuration Aug 29 14:53:23 primo volumio[3543]: info: Asking plugin for UI Config Aug 29 14:53:23 primo volumio[3543]: info: CoreCommandRouter::getUIConfigOnPlugin Aug 29 14:53:23 primo volumio[3543]: info: Getting Spotify Cloud Configuration Aug 29 14:53:23 primo volumio[3543]: info: Asking plugin for UI Config Aug 29 14:53:23 primo volumio[3543]: info: CoreCommandRouter::getUIConfigOnPlugin Aug 29 14:53:23 primo volumio[3543]: info: Saving Spotify Acccount Aug 29 14:53:23 primo volumio[3543]: info: Got it Aug 29 14:53:23 primo volumio[3543]: error: Could not retrieve Spotify Config from plugin Spotify: no section found Aug 29 14:53:23 primo volumio[3543]: info: Got Tidal Cloud Configuration Aug 29 14:53:23 primo volumio[3543]: info: Got it Aug 29 14:53:23 primo volumio[3543]: info: CoreCommandRouter::getUIConfigOnPlugin Aug 29 14:53:23 primo volumio[3543]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus Aug 29 14:53:23 primo volumio[3543]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Aug 29 14:53:23 primo volumio[3543]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Aug 29 14:53:23 primo volumio[3543]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Aug 29 14:53:23 primo volumio[3543]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 29 14:53:23 primo volumio[3543]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 29 14:53:23 primo volumio[3543]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 29 14:53:23 primo volumio[3543]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 29 14:53:23 primo volumio[3543]: info: CoreCommandRouter::volumioGetBrowseSources Aug 29 14:53:23 primo volumio[3543]: info: CoreCommandRouter::volumioGetBrowseSources Aug 29 14:53:23 primo volumio[3543]: info: CoreCommandRouter::volumioGetBrowseSources Aug 29 14:53:23 primo volumio[3543]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Aug 29 14:53:23 primo volumio[3543]: info: CoreCommandRouter::executeOnPlugin: networkfs , listShares Aug 29 14:53:23 primo volumio[3543]: info: Executing endpoint metavolumio Aug 29 14:53:23 primo volumio[3543]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Aug 29 14:53:24 primo volumio[3543]: info: Executing endpoint metavolumio Aug 29 14:53:24 primo volumio[3543]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Aug 29 14:53:24 primo volumio[3543]: info: Executing endpoint metavolumio Aug 29 14:53:24 primo volumio[3543]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Aug 29 14:53:27 primo volumio[3543]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Aug 29 14:53:31 primo volumio[3543]: info: CoreCommandRouter::volumioGetState Aug 29 14:53:34 primo volumio[3543]: info: Executing endpoint metavolumio Aug 29 14:53:34 primo volumio[3543]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Aug 29 14:53:34 primo volumio[3543]: info: Executing endpoint metavolumio Aug 29 14:53:34 primo volumio[3543]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Aug 29 14:53:34 primo volumio[3543]: info: Executing endpoint metavolumio Aug 29 14:53:34 primo volumio[3543]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Aug 29 14:53:47 primo volumio[3543]: info: Preload queue cleared Aug 29 14:53:47 primo volumio[3543]: info: CoreCommandRouter::volumioReplaceandPlayItems Aug 29 14:53:47 primo volumio[3543]: info: CoreStateMachine::ClearQueue Aug 29 14:53:47 primo volumio[3543]: info: CoreStateMachine::stop Aug 29 14:53:47 primo volumio[3543]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 29 14:53:47 primo volumio[3543]: info: CoreStateMachine::stPlaybackTimer Aug 29 14:53:47 primo volumio[3543]: info: CoreStateMachine::updateTrackBlock Aug 29 14:53:47 primo volumio[3543]: info: CorePlayQueue::getTrackBlock Aug 29 14:53:47 primo volumio[3543]: info: CoreStateMachine::pushState Aug 29 14:53:47 primo volumio[3543]: info: CorePlayQueue::getTrack 0 Aug 29 14:53:47 primo volumio[3543]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 29 14:53:47 primo volumio[3543]: info: CoreCommandRouter::volumioPushState Aug 29 14:53:47 primo volumio[3543]: info: CoreCommandRouter::volumioGetState Aug 29 14:53:47 primo volumio[3543]: info: CorePlayQueue::getTrack 0 Aug 29 14:53:47 primo volumio[3543]: info: MRS: Pushing multiroomSync output update for this device Aug 29 14:53:47 primo volumio[3543]: info: MRS: Pushing multiroomSync output Aug 29 14:53:47 primo volumio[3543]: info: CoreStateMachine::serviceStop Aug 29 14:53:47 primo volumio[3543]: info: CorePlayQueue::getTrack 0 Aug 29 14:53:47 primo volumio[3543]: info: CoreCommandRouter::serviceStop Aug 29 14:53:47 primo volumio[3543]: info: [1788004427874] ControllerQobuz::stop Aug 29 14:53:47 primo volumio[3543]: info: CoreStateMachine::setConsumeUpdateService mpd Aug 29 14:53:47 primo volumio[3543]: info: ControllerMpd::stop Aug 29 14:53:47 primo volumio[3543]: verbose: ControllerMpd::sendMpdCommand stop Aug 29 14:53:47 primo volumio[3543]: info: CorePlayQueue::clearPlayQueue Aug 29 14:53:47 primo volumio[3543]: info: CorePlayQueue::saveQueue Aug 29 14:53:47 primo volumio[3543]: info: CoreCommandRouter::volumioPushQueue Aug 29 14:53:47 primo volumio[3543]: info: CoreStateMachine::addQueueItems Aug 29 14:53:47 primo volumio[3543]: info: CorePlayQueue::addQueueItems Aug 29 14:53:47 primo volumio[3543]: info: Preload queue cleared Aug 29 14:53:47 primo volumio[3543]: info: Adding Item to queue: qobuz://song/99758250 Aug 29 14:53:47 primo volumio[3543]: info: Exploding uri qobuz://song/99758250 in service qobuz Aug 29 14:53:47 primo volumio[3543]: https://prod.vlmapi.io/v2/qobuz/explodeUri Aug 29 14:53:47 primo volumio5-onboarding[3811]: time=2026-08-29T14:53:47.883+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.11:55589 @ 0x1d52450" state=STATUS_STOPPED positionMs=0 volume=100 Aug 29 14:53:47 primo volumio5-onboarding[3811]: time=2026-08-29T14:53:47.884+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.11:55589 @ 0x1d52450" id=qobuz://song/54319180 title=Temptation Aug 29 14:53:47 primo volumio[3543]: info: Updating RAAT Signal Path Aug 29 14:53:47 primo kernel: asoc-aml-card auge_sound: tdm playback stop Aug 29 14:53:47 primo kernel: spdif_a is set to disable Aug 29 14:53:47 primo kernel: audio_ddr_mngr: frddr_set_sharebuffer_enable sel:1, dst_src:3 Aug 29 14:53:47 primo kernel: aml_dai_tdm_hw_free(), disable mclk for TDM-B Aug 29 14:53:47 primo kernel: tdm playback mute: 1, lane_cnt = 8 Aug 29 14:53:47 primo kernel: audio_ddr_mngr: frddrs[0] released by device ff660000.audiobus:tdm@1 Aug 29 14:53:47 primo volumio[3543]: info: sendMpdCommand stop took 48 milliseconds Aug 29 14:53:47 primo volumio[3543]: info: Aug 29 14:53:47 primo volumio[3543]: ---------------------------- MPD announces state update: player Aug 29 14:53:47 primo volumio[3543]: info: ControllerMpd::getState Aug 29 14:53:47 primo volumio[3543]: verbose: ControllerMpd::sendMpdCommand status Aug 29 14:53:47 primo volumio[3543]: info: Aug 29 14:53:47 primo volumio[3543]: ---------------------------- MPD announces state update: player Aug 29 14:53:47 primo volumio[3543]: info: ControllerMpd::getState Aug 29 14:53:47 primo volumio[3543]: verbose: ControllerMpd::sendMpdCommand status Aug 29 14:53:47 primo volumio[3543]: info: Aug 29 14:53:47 primo volumio[3543]: ---------------------------- MPD announces state update: player Aug 29 14:53:47 primo volumio[3543]: info: ControllerMpd::getState Aug 29 14:53:47 primo volumio[3543]: verbose: ControllerMpd::sendMpdCommand status Aug 29 14:53:47 primo volumio[3543]: info: sendMpdCommand status took 5 milliseconds Aug 29 14:53:47 primo volumio[3543]: info: sendMpdCommand status took 4 milliseconds Aug 29 14:53:47 primo volumio[3543]: info: sendMpdCommand status took 3 milliseconds Aug 29 14:53:47 primo volumio[3543]: verbose: ControllerMpd::parseState Aug 29 14:53:47 primo volumio[3543]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 29 14:53:47 primo volumio[3543]: verbose: ControllerMpd::parseState Aug 29 14:53:47 primo volumio[3543]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 29 14:53:47 primo volumio[3543]: verbose: ControllerMpd::parseState Aug 29 14:53:47 primo volumio[3543]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 29 14:53:47 primo volumio[3543]: info: sendMpdCommand playlistinfo took 2 milliseconds Aug 29 14:53:47 primo volumio[3543]: info: sendMpdCommand playlistinfo took 2 milliseconds Aug 29 14:53:47 primo volumio[3543]: info: sendMpdCommand playlistinfo took 3 milliseconds Aug 29 14:53:47 primo volumio[3543]: verbose: ControllerMpd::parseTrackInfo Aug 29 14:53:47 primo volumio[3543]: verbose: ControllerMpd::parseTrackInfo Aug 29 14:53:47 primo volumio[3543]: verbose: ControllerMpd::parseTrackInfo Aug 29 14:53:47 primo volumio[3543]: info: ControllerMpd::pushState Aug 29 14:53:47 primo volumio[3543]: info: CoreCommandRouter::servicePushState Aug 29 14:53:47 primo volumio[3543]: info: CoreStateMachine::pushState Aug 29 14:53:47 primo volumio[3543]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 29 14:53:47 primo volumio[3543]: info: CoreCommandRouter::volumioPushState Aug 29 14:53:47 primo volumio[3543]: info: CoreCommandRouter::volumioGetState Aug 29 14:53:47 primo volumio[3543]: info: MRS: Pushing multiroomSync output update for this device Aug 29 14:53:47 primo volumio[3543]: info: MRS: Pushing multiroomSync output Aug 29 14:53:47 primo volumio[3543]: info: CorePlayQueue::getTrack 0 Aug 29 14:53:47 primo volumio[3543]: verbose: STATE SERVICE {"status":"stop","position":0,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"file?uid=1174654&eid=54319180&fmt=7&profile=raw&app_id=539451548&cid=1209898&etsp=1788007781&hmac=VVeQcXWSnXe6IWnBnWAJx5TzRMc","artist":null,"album":null,"uri":"https://streaming-qobuz-std.akamaized.net/file?uid=1174654&eid=54319180&fmt=7&profile=raw&app_id=539451548&cid=1209898&etsp=1788007781&hmac=VVeQcXWSnXe6IWnBnWAJx5TzRMc","trackType":"qobuz"} Aug 29 14:53:47 primo volumio[3543]: verbose: CURRENT POSITION 0 Aug 29 14:53:47 primo volumio[3543]: info: CoreStateMachine::syncState stateService stop Aug 29 14:53:47 primo volumio[3543]: info: CoreStateMachine::syncState currentStatus stop Aug 29 14:53:47 primo volumio[3543]: info: CoreStateMachine::pushState Aug 29 14:53:47 primo volumio[3543]: info: CoreCommandRouter::volumioPushState Aug 29 14:53:47 primo volumio[3543]: info: CoreCommandRouter::volumioGetState Aug 29 14:53:47 primo volumio[3543]: info: MRS: Pushing multiroomSync output update for this device Aug 29 14:53:47 primo volumio[3543]: info: MRS: Pushing multiroomSync output Aug 29 14:53:47 primo volumio[3543]: info: No code Aug 29 14:53:47 primo volumio[3543]: info: CoreStateMachine::pushState Aug 29 14:53:47 primo volumio[3543]: info: CoreCommandRouter::volumioPushState Aug 29 14:53:47 primo volumio[3543]: info: CoreCommandRouter::volumioGetState Aug 29 14:53:47 primo volumio[3543]: info: MRS: Pushing multiroomSync output update for this device Aug 29 14:53:47 primo volumio[3543]: info: MRS: Pushing multiroomSync output Aug 29 14:53:47 primo volumio[3543]: info: ControllerMpd::pushState Aug 29 14:53:47 primo volumio[3543]: info: CoreCommandRouter::servicePushState Aug 29 14:53:47 primo volumio[3543]: info: CoreStateMachine::pushState Aug 29 14:53:47 primo volumio[3543]: info: CoreCommandRouter::volumioPushState Aug 29 14:53:47 primo volumio[3543]: info: CoreCommandRouter::volumioGetState Aug 29 14:53:47 primo volumio[3543]: info: MRS: Pushing multiroomSync output update for this device Aug 29 14:53:47 primo volumio[3543]: info: MRS: Pushing multiroomSync output Aug 29 14:53:47 primo volumio[3543]: info: CorePlayQueue::getTrack 0 Aug 29 14:53:47 primo volumio[3543]: verbose: STATE SERVICE {"status":"stop","position":0,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"file?uid=1174654&eid=54319180&fmt=7&profile=raw&app_id=539451548&cid=1209898&etsp=1788007781&hmac=VVeQcXWSnXe6IWnBnWAJx5TzRMc","artist":null,"album":null,"uri":"https://streaming-qobuz-std.akamaized.net/file?uid=1174654&eid=54319180&fmt=7&profile=raw&app_id=539451548&cid=1209898&etsp=1788007781&hmac=VVeQcXWSnXe6IWnBnWAJx5TzRMc","trackType":"qobuz"} Aug 29 14:53:47 primo volumio[3543]: verbose: CURRENT POSITION 0 Aug 29 14:53:47 primo volumio[3543]: info: CoreStateMachine::syncState stateService stop Aug 29 14:53:47 primo volumio[3543]: info: CoreStateMachine::syncState currentStatus stop Aug 29 14:53:47 primo volumio[3543]: info: CoreStateMachine::pushState Aug 29 14:53:47 primo volumio[3543]: info: CoreCommandRouter::volumioPushState Aug 29 14:53:47 primo volumio[3543]: info: CoreCommandRouter::volumioGetState Aug 29 14:53:47 primo volumio[3543]: info: MRS: Pushing multiroomSync output update for this device Aug 29 14:53:47 primo volumio[3543]: info: MRS: Pushing multiroomSync output Aug 29 14:53:47 primo volumio[3543]: info: No code Aug 29 14:53:47 primo volumio[3543]: info: CoreStateMachine::pushState Aug 29 14:53:47 primo volumio[3543]: info: CoreCommandRouter::volumioPushState Aug 29 14:53:47 primo volumio[3543]: info: CoreCommandRouter::volumioGetState Aug 29 14:53:47 primo volumio[3543]: info: MRS: Pushing multiroomSync output update for this device Aug 29 14:53:47 primo volumio[3543]: info: MRS: Pushing multiroomSync output Aug 29 14:53:47 primo volumio[3543]: info: ControllerMpd::pushState Aug 29 14:53:47 primo volumio[3543]: info: CoreCommandRouter::servicePushState Aug 29 14:53:47 primo volumio[3543]: info: CoreStateMachine::pushState Aug 29 14:53:47 primo volumio[3543]: info: CoreCommandRouter::volumioPushState Aug 29 14:53:47 primo volumio[3543]: info: CoreCommandRouter::volumioGetState Aug 29 14:53:47 primo volumio[3543]: info: MRS: Pushing multiroomSync output update for this device Aug 29 14:53:47 primo volumio[3543]: info: MRS: Pushing multiroomSync output Aug 29 14:53:47 primo volumio[3543]: info: CorePlayQueue::getTrack 0 Aug 29 14:53:47 primo volumio[3543]: verbose: STATE SERVICE {"status":"stop","position":0,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"file?uid=1174654&eid=54319180&fmt=7&profile=raw&app_id=539451548&cid=1209898&etsp=1788007781&hmac=VVeQcXWSnXe6IWnBnWAJx5TzRMc","artist":null,"album":null,"uri":"https://streaming-qobuz-std.akamaized.net/file?uid=1174654&eid=54319180&fmt=7&profile=raw&app_id=539451548&cid=1209898&etsp=1788007781&hmac=VVeQcXWSnXe6IWnBnWAJx5TzRMc","trackType":"qobuz"} Aug 29 14:53:47 primo volumio[3543]: verbose: CURRENT POSITION 0 Aug 29 14:53:47 primo volumio[3543]: info: CoreStateMachine::syncState stateService stop Aug 29 14:53:47 primo volumio[3543]: info: CoreStateMachine::syncState currentStatus stop Aug 29 14:53:47 primo volumio[3543]: info: CoreStateMachine::pushState Aug 29 14:53:47 primo volumio[3543]: info: CoreCommandRouter::volumioPushState Aug 29 14:53:47 primo volumio[3543]: info: CoreCommandRouter::volumioGetState Aug 29 14:53:47 primo volumio[3543]: info: MRS: Pushing multiroomSync output update for this device Aug 29 14:53:47 primo volumio[3543]: info: MRS: Pushing multiroomSync output Aug 29 14:53:47 primo volumio[3543]: info: No code Aug 29 14:53:47 primo volumio[3543]: info: CoreStateMachine::pushState Aug 29 14:53:47 primo volumio[3543]: info: CoreCommandRouter::volumioPushState Aug 29 14:53:47 primo volumio[3543]: info: CoreCommandRouter::volumioGetState Aug 29 14:53:47 primo volumio[3543]: info: MRS: Pushing multiroomSync output update for this device Aug 29 14:53:47 primo volumio[3543]: info: MRS: Pushing multiroomSync output Aug 29 14:53:47 primo volumio5-onboarding[3811]: time=2026-08-29T14:53:47.992+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.11:55589 @ 0x1d52450" state=STATUS_PLAYING positionMs=266 volume=100 Aug 29 14:53:47 primo volumio5-onboarding[3811]: time=2026-08-29T14:53:47.992+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.11:55589 @ 0x1d52450" id=qobuz://song/54319180 title=Temptation Aug 29 14:53:47 primo volumio5-onboarding[3811]: time=2026-08-29T14:53:47.993+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.11:55589 @ 0x1d52450" state=STATUS_PLAYING positionMs=266 volume=100 Aug 29 14:53:47 primo volumio5-onboarding[3811]: time=2026-08-29T14:53:47.993+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.11:55589 @ 0x1d52450" id=qobuz://song/54319180 title=Temptation Aug 29 14:53:47 primo volumio5-onboarding[3811]: time=2026-08-29T14:53:47.993+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.11:55589 @ 0x1d52450" state=STATUS_PLAYING positionMs=266 volume=100 Aug 29 14:53:47 primo volumio5-onboarding[3811]: time=2026-08-29T14:53:47.994+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.11:55589 @ 0x1d52450" id=qobuz://song/54319180 title=Temptation Aug 29 14:53:47 primo volumio5-onboarding[3811]: time=2026-08-29T14:53:47.994+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.11:55589 @ 0x1d52450" state=STATUS_PLAYING positionMs=266 volume=100 Aug 29 14:53:47 primo volumio5-onboarding[3811]: time=2026-08-29T14:53:47.994+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.11:55589 @ 0x1d52450" id=qobuz://song/54319180 title=Temptation Aug 29 14:53:47 primo volumio5-onboarding[3811]: time=2026-08-29T14:53:47.995+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.11:55589 @ 0x1d52450" state=STATUS_PLAYING positionMs=266 volume=100 Aug 29 14:53:47 primo volumio5-onboarding[3811]: time=2026-08-29T14:53:47.995+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.11:55589 @ 0x1d52450" state=STATUS_PLAYING positionMs=266 volume=100 Aug 29 14:53:48 primo volumio5-onboarding[3811]: time=2026-08-29T14:53:47.995+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.11:55589 @ 0x1d52450" id=qobuz://song/54319180 title=Temptation Aug 29 14:53:48 primo volumio5-onboarding[3811]: time=2026-08-29T14:53:47.996+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.11:55589 @ 0x1d52450" id=qobuz://song/54319180 title=Temptation Aug 29 14:53:48 primo volumio5-onboarding[3811]: time=2026-08-29T14:53:47.997+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.11:55589 @ 0x1d52450" state=STATUS_PLAYING positionMs=266 volume=100 Aug 29 14:53:48 primo volumio5-onboarding[3811]: time=2026-08-29T14:53:47.997+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.11:55589 @ 0x1d52450" id=qobuz://song/54319180 title=Temptation Aug 29 14:53:48 primo volumio5-onboarding[3811]: time=2026-08-29T14:53:47.997+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.11:55589 @ 0x1d52450" state=STATUS_PLAYING positionMs=266 volume=100 Aug 29 14:53:48 primo volumio5-onboarding[3811]: time=2026-08-29T14:53:47.998+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.11:55589 @ 0x1d52450" id=qobuz://song/54319180 title=Temptation Aug 29 14:53:48 primo volumio5-onboarding[3811]: time=2026-08-29T14:53:47.998+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.11:55589 @ 0x1d52450" state=STATUS_PLAYING positionMs=266 volume=100 Aug 29 14:53:48 primo volumio5-onboarding[3811]: time=2026-08-29T14:53:47.999+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.11:55589 @ 0x1d52450" id=qobuz://song/54319180 title=Temptation Aug 29 14:53:48 primo volumio[3543]: info: ------------------------------ 94ms Aug 29 14:53:48 primo volumio[3543]: info: ------------------------------ 94ms Aug 29 14:53:48 primo volumio[3543]: info: ------------------------------ 94ms Aug 29 14:53:48 primo volumio[3543]: info: Signalling Playback active due to playback status change Aug 29 14:53:48 primo volumio[3543]: info: Signalling Playback active due to playback status change Aug 29 14:53:48 primo volumio[3543]: info: Signalling Playback active due to playback status change Aug 29 14:53:48 primo volumio[3543]: info: Signalling Playback active due to playback status change Aug 29 14:53:48 primo volumio[3543]: info: Signalling Playback active due to playback status change Aug 29 14:53:48 primo volumio[3543]: info: Signalling Playback active due to playback status change Aug 29 14:53:48 primo volumio[3543]: info: Signalling Playback active due to playback status change Aug 29 14:53:48 primo volumio[3543]: info: Signalling Playback active due to playback status change Aug 29 14:53:48 primo volumio[3543]: info: Signalling Playback active due to playback status change Aug 29 14:53:48 primo volumio[3543]: info: Updating RAAT Signal Path Aug 29 14:53:48 primo volumio[3543]: info: Updating RAAT Signal Path Aug 29 14:53:48 primo volumio[3543]: info: Updating RAAT Signal Path Aug 29 14:53:48 primo volumio[3543]: info: Updating RAAT Signal Path Aug 29 14:53:48 primo volumio[3543]: info: Updating RAAT Signal Path Aug 29 14:53:48 primo volumio[3543]: info: Updating RAAT Signal Path Aug 29 14:53:48 primo volumio[3543]: info: Updating RAAT Signal Path Aug 29 14:53:48 primo volumio[3543]: info: Updating RAAT Signal Path Aug 29 14:53:48 primo volumio[3543]: info: Updating RAAT Signal Path Aug 29 14:53:48 primo volumio[3543]: info: MCU Signalled Playback Inactive Aug 29 14:53:48 primo volumio[3543]: info: MCU Signalled Playback Active Aug 29 14:53:48 primo volumio[3543]: info: explodeUri took 657 milliseconds Aug 29 14:53:48 primo volumio[3543]: info: CoreCommandRouter::volumioPushQueue Aug 29 14:53:48 primo volumio[3543]: info: CorePlayQueue::saveQueue Aug 29 14:53:48 primo volumio[3543]: info: CoreStateMachine::updateTrackBlock Aug 29 14:53:48 primo volumio[3543]: info: CorePlayQueue::getTrackBlock Aug 29 14:53:48 primo volumio[3543]: info: CoreCommandRouter::volumioGetState Aug 29 14:53:48 primo volumio[3543]: info: CoreCommandRouter::executeOnPlugin: play , [object Object] Aug 29 14:53:48 primo volumio[3543]: info: CoreCommandRouter::volumioPlay Aug 29 14:53:48 primo volumio[3543]: info: CoreStateMachine::play index 0 Aug 29 14:53:48 primo volumio[3543]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 29 14:53:48 primo volumio[3543]: info: CoreStateMachine::stop Aug 29 14:53:48 primo volumio[3543]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 29 14:53:48 primo volumio[3543]: info: CoreStateMachine::play index undefined Aug 29 14:53:48 primo volumio[3543]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 29 14:53:48 primo volumio[3543]: info: CorePlayQueue::getTrack 0 Aug 29 14:53:48 primo volumio[3543]: info: CoreStateMachine::startPlaybackTimer Aug 29 14:53:48 primo volumio[3543]: info: CorePlayQueue::getTrack 0 Aug 29 14:53:48 primo volumio[3543]: info: CoreCommandRouter::volumioGetVisibleSources Aug 29 14:53:48 primo volumio[3543]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 29 14:53:48 primo volumio[3543]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Aug 29 14:53:48 primo volumio[3543]: info: [1788004428544] ControllerQobuz::clearAddPlayTrack Aug 29 14:53:48 primo volumio[3543]: info: getStreamUrl took 288 milliseconds Aug 29 14:53:48 primo volumio[3543]: verbose: ControllerMpd::sendMpdCommand stop Aug 29 14:53:48 primo volumio[3543]: info: sendMpdCommand stop took 1 milliseconds Aug 29 14:53:48 primo volumio[3543]: verbose: ControllerMpd::sendMpdCommand clear Aug 29 14:53:48 primo volumio[3543]: info: Aug 29 14:53:48 primo volumio[3543]: ---------------------------- MPD announces system playlist update Aug 29 14:53:48 primo volumio[3543]: info: Ignoring MPD Status Update Aug 29 14:53:48 primo volumio[3543]: info: sendMpdCommand clear took 2 milliseconds Aug 29 14:53:48 primo volumio[3543]: verbose: ControllerMpd::sendMpdCommand load "https://streaming-qobuz-std.akamaized.net/file?uid=1174654&eid=99758250&fmt=7&profile=raw&app_id=539451548&cid=1209898&etsp=1788008028&hmac=Q6oaDRTCEd9N3gbDPyk9dUmodI0" Aug 29 14:53:48 primo volumio[3543]: info: Aug 29 14:53:48 primo volumio[3543]: ---------------------------- MPD announces system playlist update Aug 29 14:53:48 primo volumio[3543]: info: Ignoring MPD Status Update Aug 29 14:53:48 primo volumio[3543]: info: Aug 29 14:53:48 primo volumio[3543]: ---------------------------- MPD announces system playlist update Aug 29 14:53:48 primo volumio[3543]: info: Ignoring MPD Status Update Aug 29 14:53:49 primo volumio[3543]: error: updateQueue error: null Aug 29 14:53:49 primo volumio[3543]: error: updateQueue error: null Aug 29 14:53:49 primo volumio[3543]: error: updateQueue error: null Aug 29 14:53:49 primo volumio[3543]: info: ------------------------------ 916ms Aug 29 14:53:49 primo volumio[3543]: verbose: ControllerMpd::sendMpdCommand add "https://streaming-qobuz-std.akamaized.net/file?uid=1174654&eid=99758250&fmt=7&profile=raw&app_id=539451548&cid=1209898&etsp=1788008028&hmac=Q6oaDRTCEd9N3gbDPyk9dUmodI0" Aug 29 14:53:49 primo volumio[3543]: info: ------------------------------ 913ms Aug 29 14:53:49 primo volumio[3543]: info: ------------------------------ 912ms Aug 29 14:53:49 primo volumio[3543]: info: Aug 29 14:53:49 primo volumio[3543]: ---------------------------- MPD announces system playlist update Aug 29 14:53:49 primo volumio[3543]: info: Ignoring MPD Status Update Aug 29 14:53:49 primo volumio[3543]: info: sendMpdCommand add "https://streaming-qobuz-std.akamaized.net/file?uid=1174654&eid=99758250&fmt=7&profile=raw&app_id=539451548&cid=1209898&etsp=1788008028&hmac=Q6oaDRTCEd9N3gbDPyk9dUmodI0" took 6 milliseconds Aug 29 14:53:49 primo volumio[3543]: info: CoreStateMachine::setConsumeUpdateService mpd Aug 29 14:53:49 primo volumio[3543]: verbose: ControllerMpd::sendMpdCommand play Aug 29 14:53:49 primo volumio[3543]: info: Aug 29 14:53:49 primo volumio[3543]: ---------------------------- MPD announces system playlist update Aug 29 14:53:49 primo volumio[3543]: info: Ignoring MPD Status Update Aug 29 14:53:49 primo volumio[3543]: info: Aug 29 14:53:49 primo volumio[3543]: ---------------------------- MPD announces system playlist update Aug 29 14:53:49 primo volumio[3543]: info: Ignoring MPD Status Update Aug 29 14:53:49 primo volumio[3543]: info: ------------------------------ 9ms Aug 29 14:53:49 primo volumio[3543]: info: sendMpdCommand play took 6 milliseconds Aug 29 14:53:49 primo volumio[3543]: info: ------------------------------ 5ms Aug 29 14:53:49 primo volumio[3543]: info: ------------------------------ 3ms Aug 29 14:53:50 primo volumio[3543]: info: Aug 29 14:53:50 primo volumio[3543]: ---------------------------- MPD announces state update: player Aug 29 14:53:50 primo volumio[3543]: info: ControllerMpd::getState Aug 29 14:53:50 primo volumio[3543]: verbose: ControllerMpd::sendMpdCommand status Aug 29 14:53:50 primo volumio[3543]: info: Aug 29 14:53:50 primo volumio[3543]: ---------------------------- MPD announces state update: player Aug 29 14:53:50 primo kernel: aml_tdm_open Aug 29 14:53:50 primo kernel: Not init audio effects Aug 29 14:53:50 primo volumio[3543]: info: ControllerMpd::getState Aug 29 14:53:50 primo volumio[3543]: verbose: ControllerMpd::sendMpdCommand status Aug 29 14:53:50 primo volumio[3543]: info: Aug 29 14:53:50 primo volumio[3543]: ---------------------------- MPD announces state update: player Aug 29 14:53:50 primo volumio[3543]: info: ControllerMpd::getState Aug 29 14:53:50 primo volumio[3543]: verbose: ControllerMpd::sendMpdCommand status Aug 29 14:53:50 primo kernel: audio_ddr_mngr: frddrs[0] registered by device ff660000.audiobus:tdm@1 Aug 29 14:53:50 primo kernel: aml_dai_set_tdm_sysclk(), mpll no change, keep clk Aug 29 14:53:50 primo kernel: aml_dai_set_tdm_sysclk(), mclk no change, keep clk Aug 29 14:53:50 primo kernel: set mclk:24576000, mpll:49152000, get mclk:24575987, mpll:49151974 Aug 29 14:53:50 primo kernel: asoc aml_dai_set_tdm_fmt, 0x4001, ffffffc03d2fe018, id(1), clksel(1) Aug 29 14:53:50 primo kernel: aml_dai_set_tdm_fmt(), fmt not change Aug 29 14:53:50 primo kernel: dump_pcm_setting(ffffffc03d2fe018) Aug 29 14:53:50 primo kernel: pcm_mode(1) Aug 29 14:53:50 primo kernel: sysclk(24576000) Aug 29 14:53:50 primo kernel: sysclk_bclk_ratio(4) Aug 29 14:53:50 primo kernel: bclk(6144000) Aug 29 14:53:50 primo kernel: bclk_lrclk_ratio(64) Aug 29 14:53:50 primo kernel: lrclk(96000) Aug 29 14:53:50 primo kernel: tx_mask(0x3) Aug 29 14:53:50 primo kernel: rx_mask(0x3) Aug 29 14:53:50 primo kernel: slots(2) Aug 29 14:53:50 primo kernel: slot_width(32) Aug 29 14:53:50 primo kernel: lane_mask_in(0x2) Aug 29 14:53:50 primo kernel: lane_mask_out(0x1) Aug 29 14:53:50 primo kernel: lane_oe_mask_in(0x0) Aug 29 14:53:50 primo kernel: lane_oe_mask_out(0x0) Aug 29 14:53:50 primo kernel: lane_lb_mask_in(0x0) Aug 29 14:53:50 primo kernel: aml_dai_set_tdm_sysclk(), mpll no change, keep clk Aug 29 14:53:50 primo kernel: aml_dai_set_tdm_sysclk(), mclk no change, keep clk Aug 29 14:53:50 primo kernel: set mclk:24576000, mpll:49152000, get mclk:24575987, mpll:49151974 Aug 29 14:53:50 primo kernel: aml_dai_set_clkdiv, div 4, clksel(1) Aug 29 14:53:50 primo kernel: aml_dai_set_bclk_ratio, select I2S mode Aug 29 14:53:50 primo kernel: aml_dai_tdm_hw_params(), enable mclk for TDM-B Aug 29 14:53:50 primo kernel: aml_tdm_prepare(), reset fddr Aug 29 14:53:50 primo kernel: spdif_a fifo ctrl, frddr:0 type:4, 24 bits, chmask 0x3, swap 0x10 Aug 29 14:53:50 primo kernel: spdif_info: rate: 96000, channel status ch0_l:0x100, ch0_r:0x100, ch1_l:0xa00, ch1_r:0xa00 Aug 29 14:53:50 primo kernel: audio_ddr_mngr: frddr_set_sharebuffer_enable sel:1, dst_src:3 Aug 29 14:53:50 primo kernel: tdm playback mute: 0, lane_cnt = 8 Aug 29 14:53:50 primo kernel: aml_tdm_prepare(), reset fddr Aug 29 14:53:50 primo kernel: spdif_a fifo ctrl, frddr:0 type:4, 24 bits, chmask 0x3, swap 0x10 Aug 29 14:53:50 primo kernel: spdif_info: rate: 96000, channel status ch0_l:0x100, ch0_r:0x100, ch1_l:0xa00, ch1_r:0xa00 Aug 29 14:53:50 primo kernel: audio_ddr_mngr: frddr_set_sharebuffer_enable sel:1, dst_src:3 Aug 29 14:53:50 primo kernel: tdm playback mute: 0, lane_cnt = 8 Aug 29 14:53:50 primo volumio[3543]: info: sendMpdCommand status took 10 milliseconds Aug 29 14:53:50 primo volumio[3543]: verbose: ControllerMpd::parseState Aug 29 14:53:50 primo volumio[3543]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 29 14:53:50 primo volumio[3543]: info: Aug 29 14:53:50 primo volumio[3543]: ---------------------------- MPD announces state update: player Aug 29 14:53:50 primo volumio[3543]: info: ControllerMpd::getState Aug 29 14:53:50 primo volumio[3543]: verbose: ControllerMpd::sendMpdCommand status Aug 29 14:53:50 primo volumio[3543]: info: sendMpdCommand status took 13 milliseconds Aug 29 14:53:50 primo volumio[3543]: info: sendMpdCommand status took 11 milliseconds Aug 29 14:53:50 primo volumio[3543]: info: sendMpdCommand playlistinfo took 3 milliseconds Aug 29 14:53:50 primo volumio[3543]: verbose: ControllerMpd::parseState Aug 29 14:53:50 primo volumio[3543]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 29 14:53:50 primo volumio[3543]: verbose: ControllerMpd::parseState Aug 29 14:53:50 primo volumio[3543]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 29 14:53:50 primo volumio[3543]: verbose: ControllerMpd::parseTrackInfo Aug 29 14:53:50 primo volumio[3543]: info: ControllerMpd::pushState Aug 29 14:53:50 primo volumio[3543]: info: CoreCommandRouter::servicePushState Aug 29 14:53:50 primo volumio[3543]: info: CorePlayQueue::getTrack 0 Aug 29 14:53:50 primo volumio[3543]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":273,"samplerate":"96 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"file?uid=1174654&eid=99758250&fmt=7&profile=raw&app_id=539451548&cid=1209898&etsp=1788008028&hmac=Q6oaDRTCEd9N3gbDPyk9dUmodI0","artist":null,"album":null,"uri":"https://streaming-qobuz-std.akamaized.net/file?uid=1174654&eid=99758250&fmt=7&profile=raw&app_id=539451548&cid=1209898&etsp=1788008028&hmac=Q6oaDRTCEd9N3gbDPyk9dUmodI0","trackType":"qobuz"} Aug 29 14:53:50 primo volumio[3543]: verbose: CURRENT POSITION 0 Aug 29 14:53:50 primo volumio[3543]: info: CoreStateMachine::syncState stateService play Aug 29 14:53:50 primo volumio[3543]: info: CoreStateMachine::syncState currentStatus stop Aug 29 14:53:50 primo volumio[3543]: info: ------------------------------ 19ms Aug 29 14:53:50 primo volumio[3543]: info: Aug 29 14:53:50 primo volumio[3543]: ---------------------------- MPD announces state update: player Aug 29 14:53:50 primo volumio[3543]: info: ControllerMpd::getState Aug 29 14:53:50 primo volumio[3543]: verbose: ControllerMpd::sendMpdCommand status Aug 29 14:53:50 primo volumio[3543]: info: Aug 29 14:53:50 primo volumio[3543]: ---------------------------- MPD announces state update: player Aug 29 14:53:50 primo volumio[3543]: info: ControllerMpd::getState Aug 29 14:53:50 primo volumio[3543]: verbose: ControllerMpd::sendMpdCommand status Aug 29 14:53:50 primo volumio[3543]: info: sendMpdCommand status took 10 milliseconds Aug 29 14:53:50 primo volumio[3543]: info: sendMpdCommand playlistinfo took 8 milliseconds Aug 29 14:53:50 primo volumio[3543]: info: sendMpdCommand playlistinfo took 8 milliseconds Aug 29 14:53:50 primo volumio[3543]: info: sendMpdCommand status took 4 milliseconds Aug 29 14:53:50 primo volumio[3543]: info: sendMpdCommand status took 3 milliseconds Aug 29 14:53:50 primo volumio[3543]: verbose: ControllerMpd::parseState Aug 29 14:53:50 primo volumio[3543]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 29 14:53:50 primo volumio[3543]: verbose: ControllerMpd::parseTrackInfo Aug 29 14:53:50 primo volumio[3543]: verbose: ControllerMpd::parseTrackInfo Aug 29 14:53:50 primo volumio[3543]: verbose: ControllerMpd::parseState Aug 29 14:53:50 primo volumio[3543]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 29 14:53:50 primo volumio[3543]: verbose: ControllerMpd::parseState Aug 29 14:53:50 primo volumio[3543]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 29 14:53:50 primo volumio[3543]: info: ControllerMpd::pushState Aug 29 14:53:50 primo volumio[3543]: info: CoreCommandRouter::servicePushState Aug 29 14:53:50 primo volumio[3543]: info: CorePlayQueue::getTrack 0 Aug 29 14:53:50 primo volumio[3543]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":273,"samplerate":"96 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"file?uid=1174654&eid=99758250&fmt=7&profile=raw&app_id=539451548&cid=1209898&etsp=1788008028&hmac=Q6oaDRTCEd9N3gbDPyk9dUmodI0","artist":null,"album":null,"uri":"https://streaming-qobuz-std.akamaized.net/file?uid=1174654&eid=99758250&fmt=7&profile=raw&app_id=539451548&cid=1209898&etsp=1788008028&hmac=Q6oaDRTCEd9N3gbDPyk9dUmodI0","trackType":"qobuz"} Aug 29 14:53:50 primo volumio[3543]: verbose: CURRENT POSITION 0 Aug 29 14:53:50 primo volumio[3543]: info: CoreStateMachine::syncState stateService play Aug 29 14:53:50 primo volumio[3543]: info: CoreStateMachine::syncState currentStatus play Aug 29 14:53:50 primo volumio[3543]: info: Received an update from plugin. extracting info from payload Aug 29 14:53:50 primo volumio[3543]: info: CoreStateMachine::pushState Aug 29 14:53:50 primo volumio[3543]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 29 14:53:50 primo volumio[3543]: info: CoreCommandRouter::volumioPushState Aug 29 14:53:50 primo volumio[3543]: info: CoreCommandRouter::volumioGetState Aug 29 14:53:50 primo volumio[3543]: info: MRS: Pushing multiroomSync output update for this device Aug 29 14:53:50 primo volumio[3543]: info: MRS: Pushing multiroomSync output Aug 29 14:53:50 primo volumio[3543]: info: CoreStateMachine::pushState Aug 29 14:53:50 primo volumio[3543]: info: CoreCommandRouter::volumioPushState Aug 29 14:53:50 primo volumio[3543]: info: CoreCommandRouter::volumioGetState Aug 29 14:53:50 primo volumio[3543]: info: MRS: Pushing multiroomSync output update for this device Aug 29 14:53:50 primo volumio[3543]: info: MRS: Pushing multiroomSync output Aug 29 14:53:50 primo volumio[3543]: info: ControllerMpd::pushState Aug 29 14:53:50 primo volumio[3543]: info: CoreCommandRouter::servicePushState Aug 29 14:53:50 primo volumio[3543]: info: CorePlayQueue::getTrack 0 Aug 29 14:53:50 primo volumio[3543]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":273,"samplerate":"96 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"file?uid=1174654&eid=99758250&fmt=7&profile=raw&app_id=539451548&cid=1209898&etsp=1788008028&hmac=Q6oaDRTCEd9N3gbDPyk9dUmodI0","artist":null,"album":null,"uri":"https://streaming-qobuz-std.akamaized.net/file?uid=1174654&eid=99758250&fmt=7&profile=raw&app_id=539451548&cid=1209898&etsp=1788008028&hmac=Q6oaDRTCEd9N3gbDPyk9dUmodI0","trackType":"qobuz"} Aug 29 14:53:50 primo volumio[3543]: verbose: CURRENT POSITION 0 Aug 29 14:53:50 primo volumio[3543]: info: CoreStateMachine::syncState stateService play Aug 29 14:53:50 primo volumio[3543]: info: CoreStateMachine::syncState currentStatus play Aug 29 14:53:50 primo volumio[3543]: info: Received an update from plugin. extracting info from payload Aug 29 14:53:50 primo volumio[3543]: info: CoreStateMachine::pushState Aug 29 14:53:50 primo volumio[3543]: info: CoreCommandRouter::volumioPushState Aug 29 14:53:50 primo volumio[3543]: info: CoreCommandRouter::volumioGetState Aug 29 14:53:50 primo volumio[3543]: info: MRS: Pushing multiroomSync output update for this device Aug 29 14:53:50 primo volumio[3543]: info: MRS: Pushing multiroomSync output Aug 29 14:53:50 primo volumio[3543]: info: CoreStateMachine::pushState Aug 29 14:53:50 primo volumio[3543]: info: CoreCommandRouter::volumioPushState Aug 29 14:53:50 primo volumio[3543]: info: CoreCommandRouter::volumioGetState Aug 29 14:53:50 primo volumio[3543]: info: MRS: Pushing multiroomSync output update for this device Aug 29 14:53:50 primo volumio[3543]: info: MRS: Pushing multiroomSync output Aug 29 14:53:50 primo volumio5-onboarding[3811]: time=2026-08-29T14:53:50.321+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.11:55589 @ 0x1d52450" state=STATUS_PLAYING positionMs=0 volume=100 Aug 29 14:53:50 primo volumio5-onboarding[3811]: time=2026-08-29T14:53:50.321+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.11:55589 @ 0x1d52450" id=qobuz://song/99758250 title="Tokyo Dance" Aug 29 14:53:50 primo volumio5-onboarding[3811]: time=2026-08-29T14:53:50.322+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.11:55589 @ 0x1d52450" state=STATUS_PLAYING positionMs=0 volume=100 Aug 29 14:53:50 primo volumio5-onboarding[3811]: time=2026-08-29T14:53:50.323+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.11:55589 @ 0x1d52450" id=qobuz://song/99758250 title="Tokyo Dance" Aug 29 14:53:50 primo volumio5-onboarding[3811]: time=2026-08-29T14:53:50.323+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.11:55589 @ 0x1d52450" state=STATUS_PLAYING positionMs=0 volume=100 Aug 29 14:53:50 primo volumio5-onboarding[3811]: time=2026-08-29T14:53:50.323+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.11:55589 @ 0x1d52450" id=qobuz://song/99758250 title="Tokyo Dance" Aug 29 14:53:50 primo volumio5-onboarding[3811]: time=2026-08-29T14:53:50.323+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.11:55589 @ 0x1d52450" state=STATUS_PLAYING positionMs=0 volume=100 Aug 29 14:53:50 primo volumio5-onboarding[3811]: time=2026-08-29T14:53:50.324+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.11:55589 @ 0x1d52450" id=qobuz://song/99758250 title="Tokyo Dance" Aug 29 14:53:50 primo volumio[3543]: info: ------------------------------ 81ms Aug 29 14:53:50 primo volumio[3543]: info: ------------------------------ 80ms Aug 29 14:53:50 primo volumio[3543]: info: sendMpdCommand playlistinfo took 63 milliseconds Aug 29 14:53:50 primo volumio[3543]: info: sendMpdCommand playlistinfo took 62 milliseconds Aug 29 14:53:50 primo volumio[3543]: info: sendMpdCommand playlistinfo took 62 milliseconds Aug 29 14:53:50 primo volumio[3543]: verbose: ControllerMpd::parseTrackInfo Aug 29 14:53:50 primo volumio[3543]: verbose: ControllerMpd::parseTrackInfo Aug 29 14:53:50 primo volumio[3543]: verbose: ControllerMpd::parseTrackInfo Aug 29 14:53:50 primo volumio[3543]: info: ControllerMpd::pushState Aug 29 14:53:50 primo volumio[3543]: info: CoreCommandRouter::servicePushState Aug 29 14:53:50 primo volumio[3543]: info: CorePlayQueue::getTrack 0 Aug 29 14:53:50 primo volumio[3543]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":273,"samplerate":"96 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"file?uid=1174654&eid=99758250&fmt=7&profile=raw&app_id=539451548&cid=1209898&etsp=1788008028&hmac=Q6oaDRTCEd9N3gbDPyk9dUmodI0","artist":null,"album":null,"uri":"https://streaming-qobuz-std.akamaized.net/file?uid=1174654&eid=99758250&fmt=7&profile=raw&app_id=539451548&cid=1209898&etsp=1788008028&hmac=Q6oaDRTCEd9N3gbDPyk9dUmodI0","trackType":"qobuz"} Aug 29 14:53:50 primo volumio[3543]: verbose: CURRENT POSITION 0 Aug 29 14:53:50 primo volumio[3543]: info: CoreStateMachine::syncState stateService play Aug 29 14:53:50 primo volumio[3543]: info: CoreStateMachine::syncState currentStatus play Aug 29 14:53:50 primo volumio[3543]: info: Received an update from plugin. extracting info from payload Aug 29 14:53:50 primo volumio[3543]: info: CoreStateMachine::pushState Aug 29 14:53:50 primo volumio[3543]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 29 14:53:50 primo volumio[3543]: info: CoreCommandRouter::volumioPushState Aug 29 14:53:50 primo volumio[3543]: info: CoreCommandRouter::volumioGetState Aug 29 14:53:50 primo volumio[3543]: info: MRS: Pushing multiroomSync output update for this device Aug 29 14:53:50 primo volumio[3543]: info: MRS: Pushing multiroomSync output Aug 29 14:53:50 primo volumio[3543]: info: CoreStateMachine::pushState Aug 29 14:53:50 primo kernel: asoc-aml-card auge_sound: tdm playback enable Aug 29 14:53:50 primo kernel: spdif_a is set to enable Aug 29 14:53:50 primo volumio[3543]: info: CoreCommandRouter::volumioPushState Aug 29 14:53:50 primo volumio[3543]: info: CoreCommandRouter::volumioGetState Aug 29 14:53:50 primo volumio[3543]: info: MRS: Pushing multiroomSync output update for this device Aug 29 14:53:50 primo volumio[3543]: info: MRS: Pushing multiroomSync output Aug 29 14:53:50 primo volumio[3543]: info: ControllerMpd::pushState Aug 29 14:53:50 primo volumio[3543]: info: CoreCommandRouter::servicePushState Aug 29 14:53:50 primo volumio[3543]: info: CorePlayQueue::getTrack 0 Aug 29 14:53:50 primo volumio[3543]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":273,"samplerate":"96 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"file?uid=1174654&eid=99758250&fmt=7&profile=raw&app_id=539451548&cid=1209898&etsp=1788008028&hmac=Q6oaDRTCEd9N3gbDPyk9dUmodI0","artist":null,"album":null,"uri":"https://streaming-qobuz-std.akamaized.net/file?uid=1174654&eid=99758250&fmt=7&profile=raw&app_id=539451548&cid=1209898&etsp=1788008028&hmac=Q6oaDRTCEd9N3gbDPyk9dUmodI0","trackType":"qobuz"} Aug 29 14:53:50 primo volumio[3543]: verbose: CURRENT POSITION 0 Aug 29 14:53:50 primo volumio[3543]: info: CoreStateMachine::syncState stateService play Aug 29 14:53:50 primo volumio[3543]: info: CoreStateMachine::syncState currentStatus play Aug 29 14:53:50 primo volumio[3543]: info: Received an update from plugin. extracting info from payload Aug 29 14:53:50 primo volumio[3543]: info: CoreStateMachine::pushState Aug 29 14:53:50 primo volumio[3543]: info: CoreCommandRouter::volumioPushState Aug 29 14:53:50 primo volumio[3543]: info: CoreCommandRouter::volumioGetState Aug 29 14:53:50 primo volumio[3543]: info: MRS: Pushing multiroomSync output update for this device Aug 29 14:53:50 primo volumio[3543]: info: MRS: Pushing multiroomSync output Aug 29 14:53:50 primo volumio[3543]: info: CoreStateMachine::pushState Aug 29 14:53:50 primo volumio[3543]: info: CoreCommandRouter::volumioPushState Aug 29 14:53:50 primo volumio[3543]: info: CoreCommandRouter::volumioGetState Aug 29 14:53:50 primo volumio[3543]: info: MRS: Pushing multiroomSync output update for this device Aug 29 14:53:50 primo volumio[3543]: info: MRS: Pushing multiroomSync output Aug 29 14:53:50 primo volumio[3543]: info: ControllerMpd::pushState Aug 29 14:53:50 primo volumio[3543]: info: CoreCommandRouter::servicePushState Aug 29 14:53:50 primo volumio[3543]: info: CorePlayQueue::getTrack 0 Aug 29 14:53:50 primo volumio[3543]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":273,"samplerate":"96 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"file?uid=1174654&eid=99758250&fmt=7&profile=raw&app_id=539451548&cid=1209898&etsp=1788008028&hmac=Q6oaDRTCEd9N3gbDPyk9dUmodI0","artist":null,"album":null,"uri":"https://streaming-qobuz-std.akamaized.net/file?uid=1174654&eid=99758250&fmt=7&profile=raw&app_id=539451548&cid=1209898&etsp=1788008028&hmac=Q6oaDRTCEd9N3gbDPyk9dUmodI0","trackType":"qobuz"} Aug 29 14:53:50 primo volumio[3543]: verbose: CURRENT POSITION 0 Aug 29 14:53:50 primo volumio[3543]: info: CoreStateMachine::syncState stateService play Aug 29 14:53:50 primo volumio[3543]: info: CoreStateMachine::syncState currentStatus play Aug 29 14:53:50 primo volumio[3543]: info: Received an update from plugin. extracting info from payload Aug 29 14:53:50 primo volumio[3543]: info: CoreStateMachine::pushState Aug 29 14:53:50 primo volumio[3543]: info: CoreCommandRouter::volumioPushState Aug 29 14:53:50 primo volumio[3543]: info: CoreCommandRouter::volumioGetState Aug 29 14:53:50 primo volumio[3543]: info: MRS: Pushing multiroomSync output update for this device Aug 29 14:53:50 primo volumio[3543]: info: MRS: Pushing multiroomSync output Aug 29 14:53:50 primo volumio[3543]: info: CoreStateMachine::pushState Aug 29 14:53:50 primo volumio[3543]: info: CoreCommandRouter::volumioPushState Aug 29 14:53:50 primo volumio[3543]: info: CoreCommandRouter::volumioGetState Aug 29 14:53:50 primo volumio[3543]: info: MRS: Pushing multiroomSync output update for this device Aug 29 14:53:50 primo volumio[3543]: info: MRS: Pushing multiroomSync output Aug 29 14:53:50 primo volumio5-onboarding[3811]: time=2026-08-29T14:53:50.392+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.11:55589 @ 0x1d52450" state=STATUS_PLAYING positionMs=298 volume=100 Aug 29 14:53:50 primo volumio5-onboarding[3811]: time=2026-08-29T14:53:50.392+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.11:55589 @ 0x1d52450" id=qobuz://song/99758250 title="Tokyo Dance" Aug 29 14:53:50 primo volumio5-onboarding[3811]: time=2026-08-29T14:53:50.393+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.11:55589 @ 0x1d52450" state=STATUS_PLAYING positionMs=298 volume=100 Aug 29 14:53:50 primo volumio5-onboarding[3811]: time=2026-08-29T14:53:50.393+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.11:55589 @ 0x1d52450" id=qobuz://song/99758250 title="Tokyo Dance" Aug 29 14:53:50 primo volumio5-onboarding[3811]: time=2026-08-29T14:53:50.393+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.11:55589 @ 0x1d52450" state=STATUS_PLAYING positionMs=298 volume=100 Aug 29 14:53:50 primo volumio5-onboarding[3811]: time=2026-08-29T14:53:50.394+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.11:55589 @ 0x1d52450" id=qobuz://song/99758250 title="Tokyo Dance" Aug 29 14:53:50 primo volumio5-onboarding[3811]: time=2026-08-29T14:53:50.394+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.11:55589 @ 0x1d52450" state=STATUS_PLAYING positionMs=298 volume=100 Aug 29 14:53:50 primo volumio5-onboarding[3811]: time=2026-08-29T14:53:50.394+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.11:55589 @ 0x1d52450" id=qobuz://song/99758250 title="Tokyo Dance" Aug 29 14:53:50 primo volumio5-onboarding[3811]: time=2026-08-29T14:53:50.395+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.11:55589 @ 0x1d52450" state=STATUS_PLAYING positionMs=298 volume=100 Aug 29 14:53:50 primo volumio5-onboarding[3811]: time=2026-08-29T14:53:50.395+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.11:55589 @ 0x1d52450" id=qobuz://song/99758250 title="Tokyo Dance" Aug 29 14:53:50 primo volumio5-onboarding[3811]: time=2026-08-29T14:53:50.395+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.11:55589 @ 0x1d52450" state=STATUS_PLAYING positionMs=298 volume=100 Aug 29 14:53:50 primo volumio5-onboarding[3811]: time=2026-08-29T14:53:50.396+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.11:55589 @ 0x1d52450" id=qobuz://song/99758250 title="Tokyo Dance" Aug 29 14:53:50 primo volumio[3543]: info: ------------------------------ 147ms Aug 29 14:53:50 primo volumio[3543]: info: ------------------------------ 141ms Aug 29 14:53:50 primo volumio[3543]: info: ------------------------------ 141ms Aug 29 14:53:50 primo volumio[3543]: info: Signalling Playback active due to playback status change Aug 29 14:53:50 primo volumio[3543]: info: Signalling Playback active due to playback status change Aug 29 14:53:50 primo volumio[3543]: info: Signalling Playback active due to playback status change Aug 29 14:53:50 primo volumio[3543]: info: Signalling Playback active due to playback status change Aug 29 14:53:50 primo volumio[3543]: info: Signalling Playback active due to playback status change Aug 29 14:53:50 primo volumio[3543]: info: Signalling Playback active due to playback status change Aug 29 14:53:50 primo volumio[3543]: info: Signalling Playback active due to playback status change Aug 29 14:53:50 primo volumio[3543]: info: Signalling Playback active due to playback status change Aug 29 14:53:50 primo volumio[3543]: info: Signalling Playback active due to playback status change Aug 29 14:53:50 primo volumio[3543]: info: Signalling Playback active due to playback status change Aug 29 14:53:50 primo volumio[3543]: info: Updating RAAT Signal Path Aug 29 14:53:50 primo volumio[3543]: info: Updating RAAT Signal Path Aug 29 14:53:50 primo volumio[3543]: info: Updating RAAT Signal Path Aug 29 14:53:50 primo volumio[3543]: info: Updating RAAT Signal Path Aug 29 14:53:50 primo volumio[3543]: info: Updating RAAT Signal Path Aug 29 14:53:50 primo volumio[3543]: info: Updating RAAT Signal Path Aug 29 14:53:50 primo volumio[3543]: info: Updating RAAT Signal Path Aug 29 14:53:50 primo volumio[3543]: info: Updating RAAT Signal Path Aug 29 14:53:50 primo volumio[3543]: info: Updating RAAT Signal Path Aug 29 14:53:50 primo volumio[3543]: info: Updating RAAT Signal Path Aug 29 14:54:00 primo volumio[3543]: info: Preload queue cleared Aug 29 14:54:00 primo volumio[3543]: info: CoreCommandRouter::volumioReplaceandPlayItems Aug 29 14:54:00 primo volumio[3543]: info: CoreStateMachine::ClearQueue Aug 29 14:54:00 primo volumio[3543]: info: CoreStateMachine::stop Aug 29 14:54:00 primo volumio[3543]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 29 14:54:00 primo volumio[3543]: info: CoreStateMachine::stPlaybackTimer Aug 29 14:54:00 primo volumio[3543]: info: CoreStateMachine::updateTrackBlock Aug 29 14:54:00 primo volumio[3543]: info: CorePlayQueue::getTrackBlock Aug 29 14:54:00 primo volumio[3543]: info: CoreStateMachine::pushState Aug 29 14:54:00 primo volumio[3543]: info: CorePlayQueue::getTrack 0 Aug 29 14:54:00 primo volumio[3543]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 29 14:54:00 primo volumio[3543]: info: CoreCommandRouter::volumioPushState Aug 29 14:54:00 primo volumio[3543]: info: CoreCommandRouter::volumioGetState Aug 29 14:54:00 primo volumio[3543]: info: CorePlayQueue::getTrack 0 Aug 29 14:54:00 primo volumio[3543]: info: MRS: Pushing multiroomSync output update for this device Aug 29 14:54:00 primo volumio[3543]: info: MRS: Pushing multiroomSync output Aug 29 14:54:00 primo volumio[3543]: info: CoreStateMachine::serviceStop Aug 29 14:54:00 primo volumio[3543]: info: CorePlayQueue::getTrack 0 Aug 29 14:54:00 primo volumio[3543]: info: CoreCommandRouter::serviceStop Aug 29 14:54:00 primo volumio[3543]: info: [1788004440495] ControllerQobuz::stop Aug 29 14:54:00 primo volumio[3543]: info: CoreStateMachine::setConsumeUpdateService mpd Aug 29 14:54:00 primo volumio[3543]: info: ControllerMpd::stop Aug 29 14:54:00 primo volumio[3543]: verbose: ControllerMpd::sendMpdCommand stop Aug 29 14:54:00 primo volumio[3543]: info: CorePlayQueue::clearPlayQueue Aug 29 14:54:00 primo volumio[3543]: info: CorePlayQueue::saveQueue Aug 29 14:54:00 primo volumio[3543]: info: CoreCommandRouter::volumioPushQueue Aug 29 14:54:00 primo volumio[3543]: info: CoreStateMachine::addQueueItems Aug 29 14:54:00 primo volumio[3543]: info: CorePlayQueue::addQueueItems Aug 29 14:54:00 primo volumio[3543]: info: Preload queue cleared Aug 29 14:54:00 primo volumio[3543]: info: Adding Item to queue: qobuz://song/99758256 Aug 29 14:54:00 primo volumio[3543]: info: Exploding uri qobuz://song/99758256 in service qobuz Aug 29 14:54:00 primo volumio[3543]: https://prod.vlmapi.io/v2/qobuz/explodeUri Aug 29 14:54:00 primo volumio5-onboarding[3811]: time=2026-08-29T14:54:00.502+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.11:55589 @ 0x1d52450" state=STATUS_STOPPED positionMs=0 volume=100 Aug 29 14:54:00 primo volumio5-onboarding[3811]: time=2026-08-29T14:54:00.503+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.11:55589 @ 0x1d52450" id=qobuz://song/99758250 title="Tokyo Dance" Aug 29 14:54:00 primo volumio[3543]: info: Updating RAAT Signal Path Aug 29 14:54:00 primo volumio[3543]: info: sendMpdCommand stop took 50 milliseconds Aug 29 14:54:00 primo kernel: asoc-aml-card auge_sound: tdm playback stop Aug 29 14:54:00 primo kernel: spdif_a is set to disable Aug 29 14:54:00 primo kernel: audio_ddr_mngr: frddr_set_sharebuffer_enable sel:1, dst_src:3 Aug 29 14:54:00 primo kernel: aml_dai_tdm_hw_free(), disable mclk for TDM-B Aug 29 14:54:00 primo kernel: tdm playback mute: 1, lane_cnt = 8 Aug 29 14:54:00 primo kernel: audio_ddr_mngr: frddrs[0] released by device ff660000.audiobus:tdm@1 Aug 29 14:54:00 primo volumio[3543]: info: Aug 29 14:54:00 primo volumio[3543]: ---------------------------- MPD announces state update: player Aug 29 14:54:00 primo volumio[3543]: info: ControllerMpd::getState Aug 29 14:54:00 primo volumio[3543]: verbose: ControllerMpd::sendMpdCommand status Aug 29 14:54:00 primo volumio[3543]: info: Aug 29 14:54:00 primo volumio[3543]: ---------------------------- MPD announces state update: player Aug 29 14:54:00 primo volumio[3543]: info: ControllerMpd::getState Aug 29 14:54:00 primo volumio[3543]: verbose: ControllerMpd::sendMpdCommand status Aug 29 14:54:00 primo volumio[3543]: info: Aug 29 14:54:00 primo volumio[3543]: ---------------------------- MPD announces state update: player Aug 29 14:54:00 primo volumio[3543]: info: ControllerMpd::getState Aug 29 14:54:00 primo volumio[3543]: verbose: ControllerMpd::sendMpdCommand status Aug 29 14:54:00 primo volumio[3543]: info: sendMpdCommand status took 4 milliseconds Aug 29 14:54:00 primo volumio[3543]: info: sendMpdCommand status took 3 milliseconds Aug 29 14:54:00 primo volumio[3543]: info: sendMpdCommand status took 2 milliseconds Aug 29 14:54:00 primo volumio[3543]: verbose: ControllerMpd::parseState Aug 29 14:54:00 primo volumio[3543]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 29 14:54:00 primo volumio[3543]: verbose: ControllerMpd::parseState Aug 29 14:54:00 primo volumio[3543]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 29 14:54:00 primo volumio[3543]: verbose: ControllerMpd::parseState Aug 29 14:54:00 primo volumio[3543]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 29 14:54:00 primo volumio[3543]: info: sendMpdCommand playlistinfo took 5 milliseconds Aug 29 14:54:00 primo volumio[3543]: info: sendMpdCommand playlistinfo took 4 milliseconds Aug 29 14:54:00 primo volumio[3543]: info: sendMpdCommand playlistinfo took 4 milliseconds Aug 29 14:54:00 primo volumio[3543]: verbose: ControllerMpd::parseTrackInfo Aug 29 14:54:00 primo volumio[3543]: verbose: ControllerMpd::parseTrackInfo Aug 29 14:54:00 primo volumio[3543]: verbose: ControllerMpd::parseTrackInfo Aug 29 14:54:00 primo volumio[3543]: info: ControllerMpd::pushState Aug 29 14:54:00 primo volumio[3543]: info: CoreCommandRouter::servicePushState Aug 29 14:54:00 primo volumio[3543]: info: CoreStateMachine::pushState Aug 29 14:54:00 primo volumio[3543]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 29 14:54:00 primo volumio[3543]: info: CoreCommandRouter::volumioPushState Aug 29 14:54:00 primo volumio[3543]: info: CoreCommandRouter::volumioGetState Aug 29 14:54:00 primo volumio[3543]: info: MRS: Pushing multiroomSync output update for this device Aug 29 14:54:00 primo volumio[3543]: info: MRS: Pushing multiroomSync output Aug 29 14:54:00 primo volumio[3543]: info: CorePlayQueue::getTrack 0 Aug 29 14:54:00 primo volumio[3543]: verbose: STATE SERVICE {"status":"stop","position":0,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"file?uid=1174654&eid=99758250&fmt=7&profile=raw&app_id=539451548&cid=1209898&etsp=1788008028&hmac=Q6oaDRTCEd9N3gbDPyk9dUmodI0","artist":null,"album":null,"uri":"https://streaming-qobuz-std.akamaized.net/file?uid=1174654&eid=99758250&fmt=7&profile=raw&app_id=539451548&cid=1209898&etsp=1788008028&hmac=Q6oaDRTCEd9N3gbDPyk9dUmodI0","trackType":"qobuz"} Aug 29 14:54:00 primo volumio[3543]: verbose: CURRENT POSITION 0 Aug 29 14:54:00 primo volumio[3543]: info: CoreStateMachine::syncState stateService stop Aug 29 14:54:00 primo volumio[3543]: info: CoreStateMachine::syncState currentStatus stop Aug 29 14:54:00 primo volumio[3543]: info: CoreStateMachine::pushState Aug 29 14:54:00 primo volumio[3543]: info: CoreCommandRouter::volumioPushState Aug 29 14:54:00 primo volumio[3543]: info: CoreCommandRouter::volumioGetState Aug 29 14:54:00 primo volumio[3543]: info: MRS: Pushing multiroomSync output update for this device Aug 29 14:54:00 primo volumio[3543]: info: MRS: Pushing multiroomSync output Aug 29 14:54:00 primo volumio[3543]: info: No code Aug 29 14:54:00 primo volumio[3543]: info: CoreStateMachine::pushState Aug 29 14:54:00 primo volumio[3543]: info: CoreCommandRouter::volumioPushState Aug 29 14:54:00 primo volumio[3543]: info: CoreCommandRouter::volumioGetState Aug 29 14:54:00 primo volumio[3543]: info: MRS: Pushing multiroomSync output update for this device Aug 29 14:54:00 primo volumio[3543]: info: MRS: Pushing multiroomSync output Aug 29 14:54:00 primo volumio[3543]: info: ControllerMpd::pushState Aug 29 14:54:00 primo volumio[3543]: info: CoreCommandRouter::servicePushState Aug 29 14:54:00 primo volumio[3543]: info: CoreStateMachine::pushState Aug 29 14:54:00 primo volumio[3543]: info: CoreCommandRouter::volumioPushState Aug 29 14:54:00 primo volumio[3543]: info: CoreCommandRouter::volumioGetState Aug 29 14:54:00 primo volumio[3543]: info: MRS: Pushing multiroomSync output update for this device Aug 29 14:54:00 primo volumio[3543]: info: MRS: Pushing multiroomSync output Aug 29 14:54:00 primo volumio[3543]: info: CorePlayQueue::getTrack 0 Aug 29 14:54:00 primo volumio[3543]: verbose: STATE SERVICE {"status":"stop","position":0,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"file?uid=1174654&eid=99758250&fmt=7&profile=raw&app_id=539451548&cid=1209898&etsp=1788008028&hmac=Q6oaDRTCEd9N3gbDPyk9dUmodI0","artist":null,"album":null,"uri":"https://streaming-qobuz-std.akamaized.net/file?uid=1174654&eid=99758250&fmt=7&profile=raw&app_id=539451548&cid=1209898&etsp=1788008028&hmac=Q6oaDRTCEd9N3gbDPyk9dUmodI0","trackType":"qobuz"} Aug 29 14:54:00 primo volumio[3543]: verbose: CURRENT POSITION 0 Aug 29 14:54:00 primo volumio[3543]: info: CoreStateMachine::syncState stateService stop Aug 29 14:54:00 primo volumio[3543]: info: CoreStateMachine::syncState currentStatus stop Aug 29 14:54:00 primo volumio[3543]: info: CoreStateMachine::pushState Aug 29 14:54:00 primo volumio[3543]: info: CoreCommandRouter::volumioPushState Aug 29 14:54:00 primo volumio[3543]: info: CoreCommandRouter::volumioGetState Aug 29 14:54:00 primo volumio[3543]: info: MRS: Pushing multiroomSync output update for this device Aug 29 14:54:00 primo volumio[3543]: info: MRS: Pushing multiroomSync output Aug 29 14:54:00 primo volumio[3543]: info: No code Aug 29 14:54:00 primo volumio[3543]: info: CoreStateMachine::pushState Aug 29 14:54:00 primo volumio[3543]: info: CoreCommandRouter::volumioPushState Aug 29 14:54:00 primo volumio[3543]: info: CoreCommandRouter::volumioGetState Aug 29 14:54:00 primo volumio[3543]: info: MRS: Pushing multiroomSync output update for this device Aug 29 14:54:00 primo volumio[3543]: info: MRS: Pushing multiroomSync output Aug 29 14:54:00 primo volumio[3543]: info: ControllerMpd::pushState Aug 29 14:54:00 primo volumio[3543]: info: CoreCommandRouter::servicePushState Aug 29 14:54:00 primo volumio[3543]: info: CoreStateMachine::pushState Aug 29 14:54:00 primo volumio[3543]: info: CoreCommandRouter::volumioPushState Aug 29 14:54:00 primo volumio[3543]: info: CoreCommandRouter::volumioGetState Aug 29 14:54:00 primo volumio[3543]: info: MRS: Pushing multiroomSync output update for this device Aug 29 14:54:00 primo volumio[3543]: info: MRS: Pushing multiroomSync output Aug 29 14:54:00 primo volumio[3543]: info: CorePlayQueue::getTrack 0 Aug 29 14:54:00 primo volumio[3543]: verbose: STATE SERVICE {"status":"stop","position":0,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"file?uid=1174654&eid=99758250&fmt=7&profile=raw&app_id=539451548&cid=1209898&etsp=1788008028&hmac=Q6oaDRTCEd9N3gbDPyk9dUmodI0","artist":null,"album":null,"uri":"https://streaming-qobuz-std.akamaized.net/file?uid=1174654&eid=99758250&fmt=7&profile=raw&app_id=539451548&cid=1209898&etsp=1788008028&hmac=Q6oaDRTCEd9N3gbDPyk9dUmodI0","trackType":"qobuz"} Aug 29 14:54:00 primo volumio[3543]: verbose: CURRENT POSITION 0 Aug 29 14:54:00 primo volumio[3543]: info: CoreStateMachine::syncState stateService stop Aug 29 14:54:00 primo volumio[3543]: info: CoreStateMachine::syncState currentStatus stop Aug 29 14:54:00 primo volumio[3543]: info: CoreStateMachine::pushState Aug 29 14:54:00 primo volumio[3543]: info: CoreCommandRouter::volumioPushState Aug 29 14:54:00 primo volumio[3543]: info: CoreCommandRouter::volumioGetState Aug 29 14:54:00 primo volumio[3543]: info: MRS: Pushing multiroomSync output update for this device Aug 29 14:54:00 primo volumio[3543]: info: MRS: Pushing multiroomSync output Aug 29 14:54:00 primo volumio[3543]: info: No code Aug 29 14:54:00 primo volumio[3543]: info: CoreStateMachine::pushState Aug 29 14:54:00 primo volumio[3543]: info: CoreCommandRouter::volumioPushState Aug 29 14:54:00 primo volumio[3543]: info: CoreCommandRouter::volumioGetState Aug 29 14:54:00 primo volumio[3543]: info: MRS: Pushing multiroomSync output update for this device Aug 29 14:54:00 primo volumio[3543]: info: MRS: Pushing multiroomSync output Aug 29 14:54:00 primo volumio5-onboarding[3811]: time=2026-08-29T14:54:00.609+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.11:55589 @ 0x1d52450" state=STATUS_PLAYING positionMs=0 volume=100 Aug 29 14:54:00 primo volumio5-onboarding[3811]: time=2026-08-29T14:54:00.610+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.11:55589 @ 0x1d52450" id=qobuz://song/99758250 title="Tokyo Dance" Aug 29 14:54:00 primo volumio5-onboarding[3811]: time=2026-08-29T14:54:00.611+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.11:55589 @ 0x1d52450" state=STATUS_PLAYING positionMs=0 volume=100 Aug 29 14:54:00 primo volumio5-onboarding[3811]: time=2026-08-29T14:54:00.612+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.11:55589 @ 0x1d52450" id=qobuz://song/99758250 title="Tokyo Dance" Aug 29 14:54:00 primo volumio5-onboarding[3811]: time=2026-08-29T14:54:00.613+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.11:55589 @ 0x1d52450" state=STATUS_PLAYING positionMs=0 volume=100 Aug 29 14:54:00 primo volumio5-onboarding[3811]: time=2026-08-29T14:54:00.613+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.11:55589 @ 0x1d52450" id=qobuz://song/99758250 title="Tokyo Dance" Aug 29 14:54:00 primo volumio5-onboarding[3811]: time=2026-08-29T14:54:00.614+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.11:55589 @ 0x1d52450" state=STATUS_PLAYING positionMs=0 volume=100 Aug 29 14:54:00 primo volumio5-onboarding[3811]: time=2026-08-29T14:54:00.614+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.11:55589 @ 0x1d52450" id=qobuz://song/99758250 title="Tokyo Dance" Aug 29 14:54:00 primo volumio5-onboarding[3811]: time=2026-08-29T14:54:00.616+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.11:55589 @ 0x1d52450" state=STATUS_PLAYING positionMs=0 volume=100 Aug 29 14:54:00 primo volumio5-onboarding[3811]: time=2026-08-29T14:54:00.616+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.11:55589 @ 0x1d52450" id=qobuz://song/99758250 title="Tokyo Dance" Aug 29 14:54:00 primo volumio5-onboarding[3811]: time=2026-08-29T14:54:00.617+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.11:55589 @ 0x1d52450" state=STATUS_PLAYING positionMs=0 volume=100 Aug 29 14:54:00 primo volumio5-onboarding[3811]: time=2026-08-29T14:54:00.617+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.11:55589 @ 0x1d52450" id=qobuz://song/99758250 title="Tokyo Dance" Aug 29 14:54:00 primo volumio5-onboarding[3811]: time=2026-08-29T14:54:00.618+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.11:55589 @ 0x1d52450" state=STATUS_PLAYING positionMs=0 volume=100 Aug 29 14:54:00 primo volumio5-onboarding[3811]: time=2026-08-29T14:54:00.619+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.11:55589 @ 0x1d52450" state=STATUS_PLAYING positionMs=0 volume=100 Aug 29 14:54:00 primo volumio5-onboarding[3811]: time=2026-08-29T14:54:00.619+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.11:55589 @ 0x1d52450" id=qobuz://song/99758250 title="Tokyo Dance" Aug 29 14:54:00 primo volumio5-onboarding[3811]: time=2026-08-29T14:54:00.620+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.11:55589 @ 0x1d52450" state=STATUS_PLAYING positionMs=0 volume=100 Aug 29 14:54:00 primo volumio5-onboarding[3811]: time=2026-08-29T14:54:00.620+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.11:55589 @ 0x1d52450" id=qobuz://song/99758250 title="Tokyo Dance" Aug 29 14:54:00 primo volumio5-onboarding[3811]: time=2026-08-29T14:54:00.620+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.11:55589 @ 0x1d52450" id=qobuz://song/99758250 title="Tokyo Dance" Aug 29 14:54:00 primo volumio[3543]: info: ------------------------------ 84ms Aug 29 14:54:00 primo volumio[3543]: info: ------------------------------ 83ms Aug 29 14:54:00 primo volumio[3543]: info: ------------------------------ 83ms Aug 29 14:54:00 primo volumio[3543]: info: Signalling Playback active due to playback status change Aug 29 14:54:00 primo volumio[3543]: info: Signalling Playback active due to playback status change Aug 29 14:54:00 primo volumio[3543]: info: Signalling Playback active due to playback status change Aug 29 14:54:00 primo volumio[3543]: info: Signalling Playback active due to playback status change Aug 29 14:54:00 primo volumio[3543]: info: Signalling Playback active due to playback status change Aug 29 14:54:00 primo volumio[3543]: info: Signalling Playback active due to playback status change Aug 29 14:54:00 primo volumio[3543]: info: Signalling Playback active due to playback status change Aug 29 14:54:00 primo volumio[3543]: info: Signalling Playback active due to playback status change Aug 29 14:54:00 primo volumio[3543]: info: Signalling Playback active due to playback status change Aug 29 14:54:00 primo volumio[3543]: info: Updating RAAT Signal Path Aug 29 14:54:00 primo volumio[3543]: info: Updating RAAT Signal Path Aug 29 14:54:00 primo volumio[3543]: info: Updating RAAT Signal Path Aug 29 14:54:00 primo volumio[3543]: info: Updating RAAT Signal Path Aug 29 14:54:00 primo volumio[3543]: info: Updating RAAT Signal Path Aug 29 14:54:00 primo volumio[3543]: info: Updating RAAT Signal Path Aug 29 14:54:00 primo volumio[3543]: info: Updating RAAT Signal Path Aug 29 14:54:00 primo volumio[3543]: info: Updating RAAT Signal Path Aug 29 14:54:00 primo volumio[3543]: info: Updating RAAT Signal Path Aug 29 14:54:00 primo volumio[3543]: info: MCU Signalled Playback Inactive Aug 29 14:54:00 primo volumio[3543]: info: MCU Signalled Playback Active Aug 29 14:54:01 primo volumio[3543]: info: explodeUri took 624 milliseconds Aug 29 14:54:01 primo volumio[3543]: info: CoreCommandRouter::volumioPushQueue Aug 29 14:54:01 primo volumio[3543]: info: CorePlayQueue::saveQueue Aug 29 14:54:01 primo volumio[3543]: info: CoreStateMachine::updateTrackBlock Aug 29 14:54:01 primo volumio[3543]: info: CorePlayQueue::getTrackBlock Aug 29 14:54:01 primo volumio[3543]: info: CoreCommandRouter::volumioGetState Aug 29 14:54:01 primo volumio[3543]: info: CoreCommandRouter::executeOnPlugin: play , [object Object] Aug 29 14:54:01 primo volumio[3543]: info: CoreCommandRouter::volumioPlay Aug 29 14:54:01 primo volumio[3543]: info: CoreStateMachine::play index 0 Aug 29 14:54:01 primo volumio[3543]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 29 14:54:01 primo volumio[3543]: info: CoreStateMachine::stop Aug 29 14:54:01 primo volumio[3543]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 29 14:54:01 primo volumio[3543]: info: CoreStateMachine::play index undefined Aug 29 14:54:01 primo volumio[3543]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 29 14:54:01 primo volumio[3543]: info: CorePlayQueue::getTrack 0 Aug 29 14:54:01 primo volumio[3543]: info: CoreStateMachine::startPlaybackTimer Aug 29 14:54:01 primo volumio[3543]: info: CorePlayQueue::getTrack 0 Aug 29 14:54:01 primo volumio[3543]: info: CoreCommandRouter::volumioGetVisibleSources Aug 29 14:54:01 primo volumio[3543]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 29 14:54:01 primo volumio[3543]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Aug 29 14:54:01 primo volumio[3543]: info: [1788004441131] ControllerQobuz::clearAddPlayTrack Aug 29 14:54:01 primo volumio[3543]: info: getStreamUrl took 305 milliseconds Aug 29 14:54:01 primo volumio[3543]: verbose: ControllerMpd::sendMpdCommand stop Aug 29 14:54:01 primo volumio[3543]: info: sendMpdCommand stop took 1 milliseconds Aug 29 14:54:01 primo volumio[3543]: verbose: ControllerMpd::sendMpdCommand clear Aug 29 14:54:01 primo volumio[3543]: info: Aug 29 14:54:01 primo volumio[3543]: ---------------------------- MPD announces system playlist update Aug 29 14:54:01 primo volumio[3543]: info: Ignoring MPD Status Update Aug 29 14:54:01 primo volumio[3543]: info: sendMpdCommand clear took 1 milliseconds Aug 29 14:54:01 primo volumio[3543]: verbose: ControllerMpd::sendMpdCommand load "https://streaming-qobuz-std.akamaized.net/file?uid=1174654&eid=99758256&fmt=7&profile=raw&app_id=539451548&cid=1209898&etsp=1788008041&hmac=JLKlA-ebbB-_O-u3AiNdMS6JUkw" Aug 29 14:54:01 primo volumio[3543]: info: Aug 29 14:54:01 primo volumio[3543]: ---------------------------- MPD announces system playlist update Aug 29 14:54:01 primo volumio[3543]: info: Ignoring MPD Status Update Aug 29 14:54:01 primo volumio[3543]: info: Aug 29 14:54:01 primo volumio[3543]: ---------------------------- MPD announces system playlist update Aug 29 14:54:01 primo volumio[3543]: info: Ignoring MPD Status Update Aug 29 14:54:01 primo volumio[3543]: error: updateQueue error: null Aug 29 14:54:01 primo volumio[3543]: info: ------------------------------ 5ms Aug 29 14:54:02 primo volumio[3543]: error: updateQueue error: null Aug 29 14:54:02 primo volumio[3543]: error: updateQueue error: null Aug 29 14:54:02 primo volumio[3543]: verbose: ControllerMpd::sendMpdCommand add "https://streaming-qobuz-std.akamaized.net/file?uid=1174654&eid=99758256&fmt=7&profile=raw&app_id=539451548&cid=1209898&etsp=1788008041&hmac=JLKlA-ebbB-_O-u3AiNdMS6JUkw" Aug 29 14:54:02 primo volumio[3543]: info: ------------------------------ 891ms Aug 29 14:54:02 primo volumio[3543]: info: ------------------------------ 890ms Aug 29 14:54:02 primo volumio[3543]: info: sendMpdCommand add "https://streaming-qobuz-std.akamaized.net/file?uid=1174654&eid=99758256&fmt=7&profile=raw&app_id=539451548&cid=1209898&etsp=1788008041&hmac=JLKlA-ebbB-_O-u3AiNdMS6JUkw" took 4 milliseconds Aug 29 14:54:02 primo volumio[3543]: info: CoreStateMachine::setConsumeUpdateService mpd Aug 29 14:54:02 primo volumio[3543]: verbose: ControllerMpd::sendMpdCommand play Aug 29 14:54:02 primo volumio[3543]: info: Aug 29 14:54:02 primo volumio[3543]: ---------------------------- MPD announces system playlist update Aug 29 14:54:02 primo volumio[3543]: info: Ignoring MPD Status Update Aug 29 14:54:02 primo volumio[3543]: info: Aug 29 14:54:02 primo volumio[3543]: ---------------------------- MPD announces system playlist update Aug 29 14:54:02 primo volumio[3543]: info: Ignoring MPD Status Update Aug 29 14:54:02 primo volumio[3543]: info: Aug 29 14:54:02 primo volumio[3543]: ---------------------------- MPD announces system playlist update Aug 29 14:54:02 primo volumio[3543]: info: Ignoring MPD Status Update Aug 29 14:54:02 primo volumio[3543]: info: sendMpdCommand play took 7 milliseconds Aug 29 14:54:02 primo volumio[3543]: info: ------------------------------ 7ms Aug 29 14:54:02 primo volumio[3543]: info: ------------------------------ 3ms Aug 29 14:54:02 primo volumio[3543]: info: ------------------------------ 2ms Aug 29 14:54:02 primo volumio[3543]: info: Aug 29 14:54:02 primo volumio[3543]: ---------------------------- MPD announces state update: player Aug 29 14:54:02 primo volumio[3543]: info: ControllerMpd::getState Aug 29 14:54:02 primo volumio[3543]: verbose: ControllerMpd::sendMpdCommand status Aug 29 14:54:02 primo volumio[3543]: info: Aug 29 14:54:02 primo volumio[3543]: ---------------------------- MPD announces state update: player Aug 29 14:54:02 primo kernel: aml_tdm_open Aug 29 14:54:02 primo kernel: Not init audio effects Aug 29 14:54:02 primo kernel: audio_ddr_mngr: frddrs[0] registered by device ff660000.audiobus:tdm@1 Aug 29 14:54:02 primo volumio[3543]: info: ControllerMpd::getState Aug 29 14:54:02 primo volumio[3543]: verbose: ControllerMpd::sendMpdCommand status Aug 29 14:54:02 primo volumio[3543]: info: Aug 29 14:54:02 primo volumio[3543]: ---------------------------- MPD announces state update: player Aug 29 14:54:02 primo volumio[3543]: info: ControllerMpd::getState Aug 29 14:54:02 primo volumio[3543]: verbose: ControllerMpd::sendMpdCommand status Aug 29 14:54:02 primo kernel: aml_dai_set_tdm_sysclk(), mpll no change, keep clk Aug 29 14:54:02 primo kernel: aml_dai_set_tdm_sysclk(), mclk no change, keep clk Aug 29 14:54:02 primo kernel: set mclk:24576000, mpll:49152000, get mclk:24575987, mpll:49151974 Aug 29 14:54:02 primo kernel: asoc aml_dai_set_tdm_fmt, 0x4001, ffffffc03d2fe018, id(1), clksel(1) Aug 29 14:54:02 primo kernel: aml_dai_set_tdm_fmt(), fmt not change Aug 29 14:54:02 primo kernel: dump_pcm_setting(ffffffc03d2fe018) Aug 29 14:54:02 primo kernel: pcm_mode(1) Aug 29 14:54:02 primo kernel: sysclk(24576000) Aug 29 14:54:02 primo kernel: sysclk_bclk_ratio(4) Aug 29 14:54:02 primo kernel: bclk(6144000) Aug 29 14:54:02 primo kernel: bclk_lrclk_ratio(64) Aug 29 14:54:02 primo kernel: lrclk(96000) Aug 29 14:54:02 primo kernel: tx_mask(0x3) Aug 29 14:54:02 primo kernel: rx_mask(0x3) Aug 29 14:54:02 primo kernel: slots(2) Aug 29 14:54:02 primo kernel: slot_width(32) Aug 29 14:54:02 primo kernel: lane_mask_in(0x2) Aug 29 14:54:02 primo kernel: lane_mask_out(0x1) Aug 29 14:54:02 primo kernel: lane_oe_mask_in(0x0) Aug 29 14:54:02 primo kernel: lane_oe_mask_out(0x0) Aug 29 14:54:02 primo kernel: lane_lb_mask_in(0x0) Aug 29 14:54:02 primo kernel: aml_dai_set_tdm_sysclk(), mpll no change, keep clk Aug 29 14:54:02 primo kernel: aml_dai_set_tdm_sysclk(), mclk no change, keep clk Aug 29 14:54:02 primo kernel: set mclk:24576000, mpll:49152000, get mclk:24575987, mpll:49151974 Aug 29 14:54:02 primo kernel: aml_dai_set_clkdiv, div 4, clksel(1) Aug 29 14:54:02 primo kernel: aml_dai_set_bclk_ratio, select I2S mode Aug 29 14:54:02 primo kernel: aml_dai_tdm_hw_params(), enable mclk for TDM-B Aug 29 14:54:02 primo kernel: aml_tdm_prepare(), reset fddr Aug 29 14:54:02 primo kernel: spdif_a fifo ctrl, frddr:0 type:4, 24 bits, chmask 0x3, swap 0x10 Aug 29 14:54:02 primo kernel: spdif_info: rate: 96000, channel status ch0_l:0x100, ch0_r:0x100, ch1_l:0xa00, ch1_r:0xa00 Aug 29 14:54:02 primo kernel: audio_ddr_mngr: frddr_set_sharebuffer_enable sel:1, dst_src:3 Aug 29 14:54:02 primo kernel: tdm playback mute: 0, lane_cnt = 8 Aug 29 14:54:02 primo kernel: aml_tdm_prepare(), reset fddr Aug 29 14:54:02 primo kernel: spdif_a fifo ctrl, frddr:0 type:4, 24 bits, chmask 0x3, swap 0x10 Aug 29 14:54:02 primo kernel: spdif_info: rate: 96000, channel status ch0_l:0x100, ch0_r:0x100, ch1_l:0xa00, ch1_r:0xa00 Aug 29 14:54:02 primo kernel: audio_ddr_mngr: frddr_set_sharebuffer_enable sel:1, dst_src:3 Aug 29 14:54:02 primo kernel: tdm playback mute: 0, lane_cnt = 8 Aug 29 14:54:02 primo volumio[3543]: info: Aug 29 14:54:02 primo volumio[3543]: ---------------------------- MPD announces state update: player Aug 29 14:54:02 primo volumio[3543]: info: sendMpdCommand status took 10 milliseconds Aug 29 14:54:02 primo volumio[3543]: info: sendMpdCommand status took 8 milliseconds Aug 29 14:54:02 primo volumio[3543]: info: sendMpdCommand status took 8 milliseconds Aug 29 14:54:02 primo volumio[3543]: info: ControllerMpd::getState Aug 29 14:54:02 primo volumio[3543]: verbose: ControllerMpd::sendMpdCommand status Aug 29 14:54:02 primo volumio[3543]: verbose: ControllerMpd::parseState Aug 29 14:54:02 primo volumio[3543]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 29 14:54:02 primo volumio[3543]: verbose: ControllerMpd::parseState Aug 29 14:54:02 primo volumio[3543]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 29 14:54:02 primo volumio[3543]: verbose: ControllerMpd::parseState Aug 29 14:54:02 primo volumio[3543]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 29 14:54:02 primo volumio[3543]: info: Aug 29 14:54:02 primo volumio[3543]: ---------------------------- MPD announces state update: player Aug 29 14:54:02 primo volumio[3543]: info: ControllerMpd::getState Aug 29 14:54:02 primo volumio[3543]: verbose: ControllerMpd::sendMpdCommand status Aug 29 14:54:02 primo volumio[3543]: info: Aug 29 14:54:02 primo volumio[3543]: ---------------------------- MPD announces state update: player Aug 29 14:54:02 primo volumio[3543]: info: ControllerMpd::getState Aug 29 14:54:02 primo volumio[3543]: verbose: ControllerMpd::sendMpdCommand status Aug 29 14:54:02 primo volumio[3543]: info: sendMpdCommand status took 10 milliseconds Aug 29 14:54:02 primo volumio[3543]: info: sendMpdCommand playlistinfo took 9 milliseconds Aug 29 14:54:02 primo volumio[3543]: info: sendMpdCommand playlistinfo took 10 milliseconds Aug 29 14:54:02 primo volumio[3543]: info: sendMpdCommand playlistinfo took 9 milliseconds Aug 29 14:54:02 primo volumio[3543]: info: sendMpdCommand status took 7 milliseconds Aug 29 14:54:02 primo volumio[3543]: info: sendMpdCommand status took 4 milliseconds Aug 29 14:54:02 primo volumio[3543]: verbose: ControllerMpd::parseState Aug 29 14:54:02 primo volumio[3543]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 29 14:54:02 primo volumio[3543]: verbose: ControllerMpd::parseTrackInfo Aug 29 14:54:02 primo volumio[3543]: verbose: ControllerMpd::parseTrackInfo Aug 29 14:54:02 primo volumio[3543]: verbose: ControllerMpd::parseTrackInfo Aug 29 14:54:02 primo volumio[3543]: verbose: ControllerMpd::parseState Aug 29 14:54:02 primo volumio[3543]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 29 14:54:02 primo volumio[3543]: verbose: ControllerMpd::parseState Aug 29 14:54:02 primo volumio[3543]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 29 14:54:02 primo volumio[3543]: info: ControllerMpd::pushState Aug 29 14:54:02 primo volumio[3543]: info: CoreCommandRouter::servicePushState Aug 29 14:54:02 primo volumio[3543]: info: CorePlayQueue::getTrack 0 Aug 29 14:54:02 primo volumio[3543]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":322,"samplerate":"96 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"file?uid=1174654&eid=99758256&fmt=7&profile=raw&app_id=539451548&cid=1209898&etsp=1788008041&hmac=JLKlA-ebbB-_O-u3AiNdMS6JUkw","artist":null,"album":null,"uri":"https://streaming-qobuz-std.akamaized.net/file?uid=1174654&eid=99758256&fmt=7&profile=raw&app_id=539451548&cid=1209898&etsp=1788008041&hmac=JLKlA-ebbB-_O-u3AiNdMS6JUkw","trackType":"qobuz"} Aug 29 14:54:02 primo volumio[3543]: verbose: CURRENT POSITION 0 Aug 29 14:54:02 primo volumio[3543]: info: CoreStateMachine::syncState stateService play Aug 29 14:54:02 primo volumio[3543]: info: CoreStateMachine::syncState currentStatus stop Aug 29 14:54:02 primo volumio[3543]: info: ControllerMpd::pushState Aug 29 14:54:02 primo volumio[3543]: info: CoreCommandRouter::servicePushState Aug 29 14:54:02 primo volumio[3543]: info: CorePlayQueue::getTrack 0 Aug 29 14:54:02 primo volumio[3543]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":322,"samplerate":"96 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"file?uid=1174654&eid=99758256&fmt=7&profile=raw&app_id=539451548&cid=1209898&etsp=1788008041&hmac=JLKlA-ebbB-_O-u3AiNdMS6JUkw","artist":null,"album":null,"uri":"https://streaming-qobuz-std.akamaized.net/file?uid=1174654&eid=99758256&fmt=7&profile=raw&app_id=539451548&cid=1209898&etsp=1788008041&hmac=JLKlA-ebbB-_O-u3AiNdMS6JUkw","trackType":"qobuz"} Aug 29 14:54:02 primo volumio[3543]: verbose: CURRENT POSITION 0 Aug 29 14:54:02 primo volumio[3543]: info: CoreStateMachine::syncState stateService play Aug 29 14:54:02 primo volumio[3543]: info: CoreStateMachine::syncState currentStatus play Aug 29 14:54:02 primo volumio[3543]: info: Received an update from plugin. extracting info from payload Aug 29 14:54:02 primo volumio[3543]: info: CoreStateMachine::pushState Aug 29 14:54:02 primo volumio[3543]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 29 14:54:02 primo volumio[3543]: info: CoreCommandRouter::volumioPushState Aug 29 14:54:02 primo volumio[3543]: info: CoreCommandRouter::volumioGetState Aug 29 14:54:02 primo volumio[3543]: info: MRS: Pushing multiroomSync output update for this device Aug 29 14:54:02 primo volumio[3543]: info: MRS: Pushing multiroomSync output Aug 29 14:54:02 primo volumio[3543]: info: CoreStateMachine::pushState Aug 29 14:54:02 primo volumio[3543]: info: CoreCommandRouter::volumioPushState Aug 29 14:54:02 primo volumio[3543]: info: CoreCommandRouter::volumioGetState Aug 29 14:54:02 primo volumio[3543]: info: MRS: Pushing multiroomSync output update for this device Aug 29 14:54:02 primo volumio[3543]: info: MRS: Pushing multiroomSync output Aug 29 14:54:02 primo volumio[3543]: info: ControllerMpd::pushState Aug 29 14:54:02 primo volumio[3543]: info: CoreCommandRouter::servicePushState Aug 29 14:54:02 primo volumio[3543]: info: CorePlayQueue::getTrack 0 Aug 29 14:54:02 primo volumio[3543]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":322,"samplerate":"96 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"file?uid=1174654&eid=99758256&fmt=7&profile=raw&app_id=539451548&cid=1209898&etsp=1788008041&hmac=JLKlA-ebbB-_O-u3AiNdMS6JUkw","artist":null,"album":null,"uri":"https://streaming-qobuz-std.akamaized.net/file?uid=1174654&eid=99758256&fmt=7&profile=raw&app_id=539451548&cid=1209898&etsp=1788008041&hmac=JLKlA-ebbB-_O-u3AiNdMS6JUkw","trackType":"qobuz"} Aug 29 14:54:02 primo volumio[3543]: verbose: CURRENT POSITION 0 Aug 29 14:54:02 primo volumio[3543]: info: CoreStateMachine::syncState stateService play Aug 29 14:54:02 primo volumio[3543]: info: CoreStateMachine::syncState currentStatus play Aug 29 14:54:02 primo volumio[3543]: info: Received an update from plugin. extracting info from payload Aug 29 14:54:02 primo volumio[3543]: info: CoreStateMachine::pushState Aug 29 14:54:02 primo volumio[3543]: info: CoreCommandRouter::volumioPushState Aug 29 14:54:02 primo volumio[3543]: info: CoreCommandRouter::volumioGetState Aug 29 14:54:02 primo volumio[3543]: info: MRS: Pushing multiroomSync output update for this device Aug 29 14:54:02 primo volumio[3543]: info: MRS: Pushing multiroomSync output Aug 29 14:54:02 primo volumio[3543]: info: CoreStateMachine::pushState Aug 29 14:54:02 primo volumio[3543]: info: CoreCommandRouter::volumioPushState Aug 29 14:54:02 primo volumio[3543]: info: CoreCommandRouter::volumioGetState Aug 29 14:54:02 primo volumio[3543]: info: MRS: Pushing multiroomSync output update for this device Aug 29 14:54:02 primo volumio[3543]: info: MRS: Pushing multiroomSync output Aug 29 14:54:02 primo volumio[3543]: info: ------------------------------ 63ms Aug 29 14:54:02 primo volumio5-onboarding[3811]: time=2026-08-29T14:54:02.977+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.11:55589 @ 0x1d52450" state=STATUS_PLAYING positionMs=0 volume=100 Aug 29 14:54:02 primo volumio5-onboarding[3811]: time=2026-08-29T14:54:02.977+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.11:55589 @ 0x1d52450" id=qobuz://song/99758256 title="Arabic Slow Dance" Aug 29 14:54:02 primo volumio5-onboarding[3811]: time=2026-08-29T14:54:02.978+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.11:55589 @ 0x1d52450" state=STATUS_PLAYING positionMs=0 volume=100 Aug 29 14:54:02 primo volumio5-onboarding[3811]: time=2026-08-29T14:54:02.978+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.11:55589 @ 0x1d52450" id=qobuz://song/99758256 title="Arabic Slow Dance" Aug 29 14:54:02 primo volumio5-onboarding[3811]: time=2026-08-29T14:54:02.978+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.11:55589 @ 0x1d52450" state=STATUS_PLAYING positionMs=0 volume=100 Aug 29 14:54:02 primo volumio5-onboarding[3811]: time=2026-08-29T14:54:02.979+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.11:55589 @ 0x1d52450" id=qobuz://song/99758256 title="Arabic Slow Dance" Aug 29 14:54:02 primo volumio5-onboarding[3811]: time=2026-08-29T14:54:02.979+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.11:55589 @ 0x1d52450" state=STATUS_PLAYING positionMs=0 volume=100 Aug 29 14:54:02 primo volumio5-onboarding[3811]: time=2026-08-29T14:54:02.980+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.11:55589 @ 0x1d52450" id=qobuz://song/99758256 title="Arabic Slow Dance" Aug 29 14:54:02 primo volumio[3543]: info: ------------------------------ 81ms Aug 29 14:54:02 primo volumio[3543]: info: ------------------------------ 81ms Aug 29 14:54:02 primo volumio[3543]: info: sendMpdCommand playlistinfo took 60 milliseconds Aug 29 14:54:02 primo volumio[3543]: info: sendMpdCommand playlistinfo took 59 milliseconds Aug 29 14:54:02 primo volumio[3543]: info: sendMpdCommand playlistinfo took 58 milliseconds Aug 29 14:54:02 primo volumio[3543]: verbose: ControllerMpd::parseTrackInfo Aug 29 14:54:02 primo volumio[3543]: verbose: ControllerMpd::parseTrackInfo Aug 29 14:54:02 primo volumio[3543]: verbose: ControllerMpd::parseTrackInfo Aug 29 14:54:02 primo volumio[3543]: info: ControllerMpd::pushState Aug 29 14:54:02 primo volumio[3543]: info: CoreCommandRouter::servicePushState Aug 29 14:54:02 primo volumio[3543]: info: CorePlayQueue::getTrack 0 Aug 29 14:54:02 primo volumio[3543]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":322,"samplerate":"96 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"file?uid=1174654&eid=99758256&fmt=7&profile=raw&app_id=539451548&cid=1209898&etsp=1788008041&hmac=JLKlA-ebbB-_O-u3AiNdMS6JUkw","artist":null,"album":null,"uri":"https://streaming-qobuz-std.akamaized.net/file?uid=1174654&eid=99758256&fmt=7&profile=raw&app_id=539451548&cid=1209898&etsp=1788008041&hmac=JLKlA-ebbB-_O-u3AiNdMS6JUkw","trackType":"qobuz"} Aug 29 14:54:02 primo volumio[3543]: verbose: CURRENT POSITION 0 Aug 29 14:54:02 primo volumio[3543]: info: CoreStateMachine::syncState stateService play Aug 29 14:54:02 primo volumio[3543]: info: CoreStateMachine::syncState currentStatus play Aug 29 14:54:02 primo volumio[3543]: info: Received an update from plugin. extracting info from payload Aug 29 14:54:02 primo volumio[3543]: info: CoreStateMachine::pushState Aug 29 14:54:03 primo volumio[3543]: info: CoreCommandRouter::volumioPushState Aug 29 14:54:03 primo volumio[3543]: info: CoreCommandRouter::volumioGetState Aug 29 14:54:03 primo volumio[3543]: info: MRS: Pushing multiroomSync output update for this device Aug 29 14:54:03 primo volumio[3543]: info: MRS: Pushing multiroomSync output Aug 29 14:54:03 primo volumio[3543]: info: CoreStateMachine::pushState Aug 29 14:54:03 primo volumio[3543]: info: CoreCommandRouter::volumioPushState Aug 29 14:54:03 primo volumio[3543]: info: CoreCommandRouter::volumioGetState Aug 29 14:54:03 primo volumio[3543]: info: MRS: Pushing multiroomSync output update for this device Aug 29 14:54:03 primo volumio[3543]: info: MRS: Pushing multiroomSync output Aug 29 14:54:03 primo volumio[3543]: info: ControllerMpd::pushState Aug 29 14:54:03 primo volumio[3543]: info: CoreCommandRouter::servicePushState Aug 29 14:54:03 primo volumio[3543]: info: CorePlayQueue::getTrack 0 Aug 29 14:54:03 primo volumio[3543]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":322,"samplerate":"96 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"file?uid=1174654&eid=99758256&fmt=7&profile=raw&app_id=539451548&cid=1209898&etsp=1788008041&hmac=JLKlA-ebbB-_O-u3AiNdMS6JUkw","artist":null,"album":null,"uri":"https://streaming-qobuz-std.akamaized.net/file?uid=1174654&eid=99758256&fmt=7&profile=raw&app_id=539451548&cid=1209898&etsp=1788008041&hmac=JLKlA-ebbB-_O-u3AiNdMS6JUkw","trackType":"qobuz"} Aug 29 14:54:03 primo volumio[3543]: verbose: CURRENT POSITION 0 Aug 29 14:54:03 primo volumio[3543]: info: CoreStateMachine::syncState stateService play Aug 29 14:54:03 primo volumio[3543]: info: CoreStateMachine::syncState currentStatus play Aug 29 14:54:03 primo volumio[3543]: info: Received an update from plugin. extracting info from payload Aug 29 14:54:03 primo volumio[3543]: info: CoreStateMachine::pushState Aug 29 14:54:03 primo volumio[3543]: info: CoreCommandRouter::volumioPushState Aug 29 14:54:03 primo kernel: asoc-aml-card auge_sound: tdm playback enable Aug 29 14:54:03 primo kernel: spdif_a is set to enable Aug 29 14:54:03 primo volumio[3543]: info: CoreCommandRouter::volumioGetState Aug 29 14:54:03 primo volumio[3543]: info: MRS: Pushing multiroomSync output update for this device Aug 29 14:54:03 primo volumio[3543]: info: MRS: Pushing multiroomSync output Aug 29 14:54:03 primo volumio[3543]: info: CoreStateMachine::pushState Aug 29 14:54:03 primo volumio[3543]: info: CoreCommandRouter::volumioPushState Aug 29 14:54:03 primo volumio[3543]: info: CoreCommandRouter::volumioGetState Aug 29 14:54:03 primo volumio[3543]: info: MRS: Pushing multiroomSync output update for this device Aug 29 14:54:03 primo volumio[3543]: info: MRS: Pushing multiroomSync output Aug 29 14:54:03 primo volumio[3543]: info: ControllerMpd::pushState Aug 29 14:54:03 primo volumio[3543]: info: CoreCommandRouter::servicePushState Aug 29 14:54:03 primo volumio[3543]: info: CorePlayQueue::getTrack 0 Aug 29 14:54:03 primo volumio[3543]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":322,"samplerate":"96 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"file?uid=1174654&eid=99758256&fmt=7&profile=raw&app_id=539451548&cid=1209898&etsp=1788008041&hmac=JLKlA-ebbB-_O-u3AiNdMS6JUkw","artist":null,"album":null,"uri":"https://streaming-qobuz-std.akamaized.net/file?uid=1174654&eid=99758256&fmt=7&profile=raw&app_id=539451548&cid=1209898&etsp=1788008041&hmac=JLKlA-ebbB-_O-u3AiNdMS6JUkw","trackType":"qobuz"} Aug 29 14:54:03 primo volumio[3543]: verbose: CURRENT POSITION 0 Aug 29 14:54:03 primo volumio[3543]: info: CoreStateMachine::syncState stateService play Aug 29 14:54:03 primo volumio[3543]: info: CoreStateMachine::syncState currentStatus play Aug 29 14:54:03 primo volumio[3543]: info: Received an update from plugin. extracting info from payload Aug 29 14:54:03 primo volumio[3543]: info: CoreStateMachine::pushState Aug 29 14:54:03 primo volumio[3543]: info: CoreCommandRouter::volumioPushState Aug 29 14:54:03 primo volumio[3543]: info: CoreCommandRouter::volumioGetState Aug 29 14:54:03 primo volumio[3543]: info: MRS: Pushing multiroomSync output update for this device Aug 29 14:54:03 primo volumio[3543]: info: MRS: Pushing multiroomSync output Aug 29 14:54:03 primo volumio[3543]: info: CoreStateMachine::pushState Aug 29 14:54:03 primo volumio[3543]: info: CoreCommandRouter::volumioPushState Aug 29 14:54:03 primo volumio[3543]: info: CoreCommandRouter::volumioGetState Aug 29 14:54:03 primo volumio[3543]: info: MRS: Pushing multiroomSync output update for this device Aug 29 14:54:03 primo volumio[3543]: info: MRS: Pushing multiroomSync output Aug 29 14:54:03 primo volumio5-onboarding[3811]: time=2026-08-29T14:54:03.038+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.11:55589 @ 0x1d52450" state=STATUS_PLAYING positionMs=0 volume=100 Aug 29 14:54:03 primo volumio5-onboarding[3811]: time=2026-08-29T14:54:03.039+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.11:55589 @ 0x1d52450" id=qobuz://song/99758256 title="Arabic Slow Dance" Aug 29 14:54:03 primo volumio5-onboarding[3811]: time=2026-08-29T14:54:03.039+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.11:55589 @ 0x1d52450" state=STATUS_PLAYING positionMs=0 volume=100 Aug 29 14:54:03 primo volumio5-onboarding[3811]: time=2026-08-29T14:54:03.040+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.11:55589 @ 0x1d52450" state=STATUS_PLAYING positionMs=0 volume=100 Aug 29 14:54:03 primo volumio5-onboarding[3811]: time=2026-08-29T14:54:03.040+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.11:55589 @ 0x1d52450" id=qobuz://song/99758256 title="Arabic Slow Dance" Aug 29 14:54:03 primo volumio5-onboarding[3811]: time=2026-08-29T14:54:03.040+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.11:55589 @ 0x1d52450" id=qobuz://song/99758256 title="Arabic Slow Dance" Aug 29 14:54:03 primo volumio5-onboarding[3811]: time=2026-08-29T14:54:03.040+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.11:55589 @ 0x1d52450" state=STATUS_PLAYING positionMs=0 volume=100 Aug 29 14:54:03 primo volumio5-onboarding[3811]: time=2026-08-29T14:54:03.041+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.11:55589 @ 0x1d52450" state=STATUS_PLAYING positionMs=0 volume=100 Aug 29 14:54:03 primo volumio5-onboarding[3811]: time=2026-08-29T14:54:03.041+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.11:55589 @ 0x1d52450" id=qobuz://song/99758256 title="Arabic Slow Dance" Aug 29 14:54:03 primo volumio5-onboarding[3811]: time=2026-08-29T14:54:03.041+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.11:55589 @ 0x1d52450" id=qobuz://song/99758256 title="Arabic Slow Dance" Aug 29 14:54:03 primo volumio5-onboarding[3811]: time=2026-08-29T14:54:03.042+03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.11:55589 @ 0x1d52450" state=STATUS_PLAYING positionMs=0 volume=100 Aug 29 14:54:03 primo volumio5-onboarding[3811]: time=2026-08-29T14:54:03.042+03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.11:55589 @ 0x1d52450" id=qobuz://song/99758256 title="Arabic Slow Dance" Aug 29 14:54:03 primo volumio[3543]: info: ------------------------------ 137ms Aug 29 14:54:03 primo volumio[3543]: info: ------------------------------ 132ms Aug 29 14:54:03 primo volumio[3543]: info: ------------------------------ 132ms Aug 29 14:54:03 primo volumio[3543]: info: Signalling Playback active due to playback status change Aug 29 14:54:03 primo volumio[3543]: info: Signalling Playback active due to playback status change Aug 29 14:54:03 primo volumio[3543]: info: Signalling Playback active due to playback status change Aug 29 14:54:03 primo volumio[3543]: info: Signalling Playback active due to playback status change Aug 29 14:54:03 primo volumio[3543]: info: Signalling Playback active due to playback status change Aug 29 14:54:03 primo volumio[3543]: info: Signalling Playback active due to playback status change Aug 29 14:54:03 primo volumio[3543]: info: Signalling Playback active due to playback status change Aug 29 14:54:03 primo volumio[3543]: info: Signalling Playback active due to playback status change Aug 29 14:54:03 primo volumio[3543]: info: Signalling Playback active due to playback status change Aug 29 14:54:03 primo volumio[3543]: info: Signalling Playback active due to playback status change Aug 29 14:54:03 primo volumio[3543]: info: Updating RAAT Signal Path Aug 29 14:54:03 primo volumio[3543]: info: Updating RAAT Signal Path Aug 29 14:54:03 primo volumio[3543]: info: Updating RAAT Signal Path Aug 29 14:54:03 primo volumio[3543]: info: Updating RAAT Signal Path Aug 29 14:54:03 primo volumio[3543]: info: Updating RAAT Signal Path Aug 29 14:54:03 primo volumio[3543]: info: Updating RAAT Signal Path Aug 29 14:54:03 primo volumio[3543]: info: Updating RAAT Signal Path Aug 29 14:54:03 primo volumio[3543]: info: Updating RAAT Signal Path Aug 29 14:54:03 primo volumio[3543]: info: Updating RAAT Signal Path Aug 29 14:54:03 primo volumio[3543]: info: Updating RAAT Signal Path Aug 29 14:54:12 primo volumio[3543]: Searching all installed plugins Aug 29 14:54:12 primo volumio[3543]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 29 14:54:12 primo volumio[3543]: info: CoreCommandRouter::executeOnPlugin: , search Aug 29 14:54:12 primo volumio[3543]: info: CoreCommandRouter::executeOnPlugin: mpd , search Aug 29 14:54:12 primo volumio[3543]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , search Aug 29 14:54:12 primo volumio[3543]: info: CoreCommandRouter::executeOnPlugin: last_100 , search Aug 29 14:54:12 primo volumio[3543]: info: Error : CoreCommandRouter::executeOnPlugin: No method [search] in plugin last_100 Aug 29 14:54:12 primo volumio[3543]: info: CoreCommandRouter::executeOnPlugin: webradio , search Aug 29 14:54:12 primo volumio[3543]: info: CoreCommandRouter::executeOnPlugin: qobuz , search Aug 29 14:54:13 primo volumio[3543]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 29 14:54:13 primo volumio[3543]: XMLStructuredError: Premature end of data in tag br line 187 (Line: 195, Column: 7) Aug 29 14:54:13 primo volumio[3543]: at new XMLStructuredError (/volumio/node_modules/libxmljs/dist/lib/types.js:23:28) Aug 29 14:54:13 primo volumio[3543]: at /volumio/node_modules/libxmljs/dist/lib/parse.js:190:23 Aug 29 14:54:13 primo volumio[3543]: at Object.parseXml (/volumio/node_modules/libxmljs/dist/lib/parse.js:185:49) Aug 29 14:54:13 primo volumio[3543]: at /volumio/app/plugins/music_service/webradio/index.js:962:31 Aug 29 14:54:13 primo volumio[3543]: at process.processTicksAndRejections (node:internal/process/task_queues:95:5) { Aug 29 14:54:13 primo volumio[3543]: domain: 1, Aug 29 14:54:13 primo volumio[3543]: code: 77, Aug 29 14:54:13 primo volumio[3543]: level: 3, Aug 29 14:54:13 primo volumio[3543]: column: 7, Aug 29 14:54:13 primo volumio[3543]: file: '', Aug 29 14:54:13 primo volumio[3543]: line: 195, Aug 29 14:54:13 primo volumio[3543]: str1: 'br', Aug 29 14:54:13 primo volumio[3543]: str2: undefined, Aug 29 14:54:13 primo volumio[3543]: str3: undefined, Aug 29 14:54:13 primo volumio[3543]: int1: 187 Aug 29 14:54:13 primo volumio[3543]: } Aug 29 14:54:13 primo volumio[3543]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 29 14:54:14 primo sudo[27269]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-08-29 14:53' Aug 29 14:54:14 primo sudo[27269]: 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"