Aug 26 15:55:10 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:10.472+04:00 level=INFO msg="established new WebSocket connection" component=conn/ws remoteAddr=192.168.100.4:50332 Aug 26 15:55:10 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:10.494+04:00 level=INFO msg="device data request" component=server type=REQUEST_TYPE_DEVICE_DATA peer="192.168.100.4:50332 @ 0x20a0480" latency=-378.815658ms timeout=20s Aug 26 15:55:10 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:10.494+04:00 level=INFO msg="emitting device capabilities changed event" component=server peer="192.168.100.4:50332 @ 0x20a0480" Aug 26 15:55:10 primo volumio[3266]: info: Received Get System Info Aug 26 15:55:10 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 26 15:55:10 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 26 15:55:10 primo volumio[3266]: info: Discovery: Getting this device information Aug 26 15:55:10 primo volumio[3266]: info: CoreCommandRouter::volumioGetState Aug 26 15:55:10 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 26 15:55:10 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:10.499+04:00 level=INFO msg="emitting device name changed event" component=server peer="192.168.100.4:50332 @ 0x20a0480" name=Primo Aug 26 15:55:10 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:10.500+04:00 level=INFO msg="emitting device language changed event" component=server peer="192.168.100.4:50332 @ 0x20a0480" language=ru Aug 26 15:55:10 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: system , getCurrentTimezone Aug 26 15:55:10 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:10.502+04:00 level=INFO msg="emitting device timezone changed event" component=server peer="192.168.100.4:50332 @ 0x20a0480" timezone=Asia/Tbilisi Aug 26 15:55:10 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:10.504+04:00 level=INFO msg="emitting ethernet info changed event" component=server peer="192.168.100.4:50332 @ 0x20a0480" available=true connected=true macAddress=02:00:00:0d:1d:01 ip4Address=192.168.100.5/24 ip6Address= Aug 26 15:55:10 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:10.507+04:00 level=INFO msg="emitting wifi info changed event" component=server peer="192.168.100.4:50332 @ 0x20a0480" available=true connected=false macAddress= ip4Address= ip6Address= ssid= Aug 26 15:55:10 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:10.508+04:00 level=INFO msg="emitting device setup status changed event" component=server peer="192.168.100.4:50332 @ 0x20a0480" setupComplete=true Aug 26 15:55:10 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getExtendedOutputDevices Aug 26 15:55:10 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions Aug 26 15:55:10 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 26 15:55:10 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Aug 26 15:55:10 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:10.548+04:00 level=INFO msg="emitting audio outputs changed event" component=server peer="192.168.100.4:50332 @ 0x20a0480" selectedOutputId=0,0 Aug 26 15:55:10 primo volumio[3266]: info: Received Get System Info Aug 26 15:55:10 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 26 15:55:10 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 26 15:55:10 primo volumio[3266]: info: Discovery: Getting this device information Aug 26 15:55:10 primo volumio[3266]: info: CoreCommandRouter::volumioGetState Aug 26 15:55:10 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 26 15:55:10 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:10.595+04:00 level=INFO msg="emitting software info changed event" component=server peer="192.168.100.4:50332 @ 0x20a0480" currentVersion=4.158 latestVersion=4.158 Aug 26 15:55:10 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:10.595+04:00 level=INFO msg="emitting software update progress event" component=server peer="192.168.100.4:50332 @ 0x20a0480" status=UPDATE_STATUS_NONE progress=0 Aug 26 15:55:10 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:10.596+04:00 level=INFO msg="emitting user changed event" component=server peer="192.168.100.4:50332 @ 0x20a0480" userId=Cy4OQuN95phW8cgIMJtoddMF8IM2 Aug 26 15:55:10 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:10.596+04:00 level=INFO msg="emitting music providers changed event" component=server peer="192.168.100.4:50332 @ 0x20a0480" providers=9 Aug 26 15:55:10 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:10.596+04:00 level=INFO msg="emitting plugins changed event" component=server peer="192.168.100.4:50332 @ 0x20a0480" plugins=24 Aug 26 15:55:10 primo volumio[3266]: info: CoreCommandRouter::volumioGetState Aug 26 15:55:10 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:10.600+04:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.100.4:50332 @ 0x20a0480" state=STATUS_PAUSED positionMs=40378000 volume=100 Aug 26 15:55:10 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:10.600+04:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.4:50332 @ 0x20a0480" id= title="Смотреть сериал Ходячие мертвецы: Выжившие 1 сезон 2 серия онлайн бесплатно в хорошем качестве" Aug 26 15:55:11 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:11.273+04:00 level=INFO msg="navigate to next page" component=server type=REQUEST_TYPE_CONTINUE_NAVIGATION peer="192.168.100.4:50332 @ 0x20a0480" latency=-377.600116ms timeout=10s from=APP_PAGE_ROOT to=APP_PAGE_LEGACY_DEVICE Aug 26 15:55:11 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:11.292+04:00 level=INFO msg="check connectivity" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.100.4:50332 @ 0x20a0480" latency=-377.275032ms timeout=10s Aug 26 15:55:11 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:11.581+04:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.100.4:50332 @ 0x20a0480" latency=-377.275032ms timeout=10s endpoint=http://pushupdates.volumio.org duration=286.578667ms Aug 26 15:55:11 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:11.713+04:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.100.4:50332 @ 0x20a0480" latency=-377.275032ms timeout=10s endpoint=https://radio-directory.firebaseapp.com duration=421.179375ms Aug 26 15:55:11 primo sudo[10763]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Aug 26 15:55:11 primo sudo[10763]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 26 15:55:11 primo sudo[10765]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Aug 26 15:55:11 primo sudo[10765]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 26 15:55:11 primo sudo[10763]: pam_unix(sudo:session): session closed for user root Aug 26 15:55:11 primo sudo[10765]: pam_unix(sudo:session): session closed for user root Aug 26 15:55:11 primo volumio[3266]: verbose: New Socket.io Connection to 192.168.100.5 from 192.168.100.4 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_7 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Engine version: 3 Transport: polling Total Clients: 9 Aug 26 15:55:11 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:11.859+04:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.100.4:50332 @ 0x20a0480" latency=-377.275032ms timeout=10s endpoint=https://www.googleapis.com duration=567.129583ms Aug 26 15:55:11 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:11.922+04:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.100.4:50332 @ 0x20a0480" latency=-377.275032ms timeout=10s endpoint=https://myvolumio.firebaseio.com duration=625.448542ms Aug 26 15:55:11 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:11.947+04:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.100.4:50332 @ 0x20a0480" latency=-377.275032ms timeout=10s endpoint=https://securetoken.googleapis.com duration=652.1975ms Aug 26 15:55:11 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:11.964+04:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.100.4:50332 @ 0x20a0480" latency=-377.275032ms timeout=10s endpoint=https://browsing-performer.dfs.volumio.org duration=672.404251ms Aug 26 15:55:12 primo sudo[10771]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Aug 26 15:55:12 primo sudo[10771]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 26 15:55:12 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:12.011+04:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.100.4:50332 @ 0x20a0480" latency=-377.275032ms timeout=10s endpoint=https://oauth-performer.dfs.volumio.org duration=713.801667ms Aug 26 15:55:12 primo sudo[10773]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Aug 26 15:55:12 primo sudo[10773]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 26 15:55:12 primo sudo[10771]: pam_unix(sudo:session): session closed for user root Aug 26 15:55:12 primo sudo[10773]: pam_unix(sudo:session): session closed for user root Aug 26 15:55:12 primo volumio[3266]: verbose: New Socket.io Connection to 192.168.100.5 from 192.168.100.4 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_7 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Engine version: 3 Transport: polling Total Clients: 9 Aug 26 15:55:12 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Aug 26 15:55:12 primo volumio[3266]: info: CoreCommandRouter::volumioGetVisibleSources Aug 26 15:55:12 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 26 15:55:12 primo volumio[3266]: info: CoreCommandRouter::volumioGetState Aug 26 15:55:12 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Aug 26 15:55:12 primo volumio[3266]: info: CoreCommandRouter::volumioGetQueue Aug 26 15:55:12 primo volumio[3266]: info: CoreStateMachine::getQueue Aug 26 15:55:12 primo volumio[3266]: info: CorePlayQueue::getQueue Aug 26 15:55:12 primo volumio[3266]: info: Listing playlists Aug 26 15:55:12 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Aug 26 15:55:12 primo volumio[3266]: info: Received Get System Info Aug 26 15:55:12 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 26 15:55:12 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 26 15:55:12 primo volumio[3266]: info: Discovery: Getting this device information Aug 26 15:55:12 primo volumio[3266]: info: CoreCommandRouter::volumioGetState Aug 26 15:55:12 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 26 15:55:12 primo volumio[3266]: info: CoreCommandRouter::volumioGetState Aug 26 15:55:12 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Aug 26 15:55:12 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Aug 26 15:55:12 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:12.130+04:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.100.4:50332 @ 0x20a0480" latency=-377.275032ms timeout=10s endpoint=http://cddb.volumio.org duration=837.513417ms Aug 26 15:55:12 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Aug 26 15:55:12 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:12.406+04:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.100.4:50332 @ 0x20a0480" latency=-377.275032ms timeout=10s endpoint=https://google.com duration=1.114128542s Aug 26 15:55:12 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:12.428+04:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.100.4:50332 @ 0x20a0480" latency=-377.275032ms timeout=10s endpoint=https://functions.volumio.cloud duration=1.133410083s Aug 26 15:55:12 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:12.456+04:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.100.4:50332 @ 0x20a0480" latency=-377.275032ms timeout=10s endpoint=https://functions.volumio.cloud duration=1.159155625s Aug 26 15:55:12 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:12.470+04:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.100.4:50332 @ 0x20a0480" latency=-377.275032ms timeout=10s endpoint=https://database.volumio.cloud duration=1.175565125s Aug 26 15:55:12 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:12.562+04:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.100.4:50332 @ 0x20a0480" latency=-377.275032ms timeout=10s endpoint=http://plugins.volumio.org duration=1.269200917s Aug 26 15:55:13 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 26 15:55:13 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 26 15:55:13 primo volumio[3266]: info: Discovery: Getting this device information Aug 26 15:55:13 primo volumio[3266]: info: CoreCommandRouter::volumioGetState Aug 26 15:55:13 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 26 15:55:13 primo volumio[3266]: verbose: New Socket.io Connection to 192.168.100.5:3000 from 192.168.100.4 UA: Dart/3.12 (dart:io) Engine version: 3 Transport: websocket Total Clients: 10 Aug 26 15:55:13 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Aug 26 15:55:13 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Aug 26 15:55:13 primo bluealsa[3483]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_63_58_4D_70_3E_F7, ...) Aug 26 15:55:13 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Aug 26 15:55:13 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 26 15:55:13 primo volumio[3266]: info: Received Get System Info Aug 26 15:55:13 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 26 15:55:13 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 26 15:55:13 primo volumio[3266]: info: Discovery: Getting this device information Aug 26 15:55:13 primo volumio[3266]: info: CoreCommandRouter::volumioGetState Aug 26 15:55:13 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 26 15:55:15 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 26 15:55:15 primo volumio[3266]: info: Received Get System Info Aug 26 15:55:15 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 26 15:55:15 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 26 15:55:15 primo volumio[3266]: info: Discovery: Getting this device information Aug 26 15:55:15 primo volumio[3266]: info: CoreCommandRouter::volumioGetState Aug 26 15:55:15 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 26 15:55:15 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: rp2 , handleBrowseUri Aug 26 15:55:15 primo volumio[3266]: info: [rp2] Session data loaded successfully Aug 26 15:55:15 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:15.943+04:00 level=INFO msg="WebSocket connection closed" component=conn/ws remoteAddr=192.168.100.4:50332 Aug 26 15:55:15 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:15.943+04:00 level=INFO msg="connection to address closed" component=conn/multi addr=192.168.100.4:50332 Aug 26 15:55:15 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:15.950+04:00 level=INFO msg="established new WebSocket connection" component=conn/ws remoteAddr=192.168.100.4:50459 Aug 26 15:55:15 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:15.964+04:00 level=INFO msg="check connectivity" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.100.4:50459 @ 0x2680150" latency=-379.605655ms timeout=10s Aug 26 15:55:15 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:15.965+04:00 level=INFO msg="device data request" component=server type=REQUEST_TYPE_DEVICE_DATA peer="192.168.100.4:50459 @ 0x2680150" latency=-378.516905ms timeout=20s Aug 26 15:55:15 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:15.965+04:00 level=INFO msg="emitting device capabilities changed event" component=server peer="192.168.100.4:50459 @ 0x2680150" Aug 26 15:55:16 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:16.023+04:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.100.4:50459 @ 0x2680150" latency=-379.605655ms timeout=10s endpoint=https://radio-directory.firebaseapp.com duration=58.722292ms Aug 26 15:55:16 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:16.037+04:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.100.4:50459 @ 0x2680150" latency=-379.605655ms timeout=10s endpoint=http://pushupdates.volumio.org duration=70.164208ms Aug 26 15:55:16 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:16.037+04:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.100.4:50459 @ 0x2680150" latency=-379.605655ms timeout=10s endpoint=https://browsing-performer.dfs.volumio.org duration=70.443166ms Aug 26 15:55:16 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:16.046+04:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.100.4:50459 @ 0x2680150" latency=-379.605655ms timeout=10s endpoint=https://oauth-performer.dfs.volumio.org duration=79.263458ms Aug 26 15:55:16 primo volumio[3266]: info: Received Get System Info Aug 26 15:55:16 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 26 15:55:16 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 26 15:55:16 primo volumio[3266]: info: Discovery: Getting this device information Aug 26 15:55:16 primo volumio[3266]: info: CoreCommandRouter::volumioGetState Aug 26 15:55:16 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 26 15:55:16 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:16.067+04:00 level=INFO msg="emitting device name changed event" component=server peer="192.168.100.4:50459 @ 0x2680150" name=Primo Aug 26 15:55:16 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:16.068+04:00 level=INFO msg="emitting device language changed event" component=server peer="192.168.100.4:50459 @ 0x2680150" language=ru Aug 26 15:55:16 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: system , getCurrentTimezone Aug 26 15:55:16 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:16.077+04:00 level=INFO msg="emitting device timezone changed event" component=server peer="192.168.100.4:50459 @ 0x2680150" timezone=Asia/Tbilisi Aug 26 15:55:16 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:16.078+04:00 level=INFO msg="emitting ethernet info changed event" component=server peer="192.168.100.4:50459 @ 0x2680150" available=true connected=true macAddress=02:00:00:0d:1d:01 ip4Address=192.168.100.5/24 ip6Address= Aug 26 15:55:16 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:16.080+04:00 level=INFO msg="emitting wifi info changed event" component=server peer="192.168.100.4:50459 @ 0x2680150" available=true connected=false macAddress= ip4Address= ip6Address= ssid= Aug 26 15:55:16 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:16.081+04:00 level=INFO msg="emitting device setup status changed event" component=server peer="192.168.100.4:50459 @ 0x2680150" setupComplete=true Aug 26 15:55:16 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getExtendedOutputDevices Aug 26 15:55:16 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:16.108+04:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.100.4:50459 @ 0x2680150" latency=-379.605655ms timeout=10s endpoint=https://www.googleapis.com duration=142.988917ms Aug 26 15:55:16 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions Aug 26 15:55:16 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 26 15:55:16 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Aug 26 15:55:16 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:16.123+04:00 level=INFO msg="emitting audio outputs changed event" component=server peer="192.168.100.4:50459 @ 0x2680150" selectedOutputId=0,0 Aug 26 15:55:16 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:16.147+04:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.100.4:50459 @ 0x2680150" latency=-379.605655ms timeout=10s endpoint=https://myvolumio.firebaseio.com duration=180.491042ms Aug 26 15:55:16 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:16.159+04:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.100.4:50459 @ 0x2680150" latency=-379.605655ms timeout=10s endpoint=https://securetoken.googleapis.com duration=193.431042ms Aug 26 15:55:16 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:16.161+04:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.100.4:50459 @ 0x2680150" latency=-379.605655ms timeout=10s endpoint=https://database.volumio.cloud duration=193.891167ms Aug 26 15:55:16 primo volumio[3266]: info: Received Get System Info Aug 26 15:55:16 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 26 15:55:16 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 26 15:55:16 primo volumio[3266]: info: Discovery: Getting this device information Aug 26 15:55:16 primo volumio[3266]: info: CoreCommandRouter::volumioGetState Aug 26 15:55:16 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 26 15:55:16 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:16.171+04:00 level=INFO msg="emitting software info changed event" component=server peer="192.168.100.4:50459 @ 0x2680150" currentVersion=4.158 latestVersion=4.158 Aug 26 15:55:16 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:16.171+04:00 level=INFO msg="emitting software update progress event" component=server peer="192.168.100.4:50459 @ 0x2680150" status=UPDATE_STATUS_NONE progress=0 Aug 26 15:55:16 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:16.172+04:00 level=INFO msg="emitting user changed event" component=server peer="192.168.100.4:50459 @ 0x2680150" userId=Cy4OQuN95phW8cgIMJtoddMF8IM2 Aug 26 15:55:16 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:16.172+04:00 level=INFO msg="emitting music providers changed event" component=server peer="192.168.100.4:50459 @ 0x2680150" providers=9 Aug 26 15:55:16 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:16.172+04:00 level=INFO msg="emitting plugins changed event" component=server peer="192.168.100.4:50459 @ 0x2680150" plugins=24 Aug 26 15:55:16 primo volumio[3266]: info: CoreCommandRouter::volumioGetState Aug 26 15:55:16 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:16.176+04:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.100.4:50459 @ 0x2680150" state=STATUS_PAUSED positionMs=40378000 volume=100 Aug 26 15:55:16 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:16.177+04:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.4:50459 @ 0x2680150" id= title="Смотреть сериал Ходячие мертвецы: Выжившие 1 сезон 2 серия онлайн бесплатно в хорошем качестве" Aug 26 15:55:16 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:16.256+04:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.100.4:50459 @ 0x2680150" latency=-379.605655ms timeout=10s endpoint=http://cddb.volumio.org duration=290.038667ms Aug 26 15:55:16 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:16.372+04:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.100.4:50459 @ 0x2680150" latency=-379.605655ms timeout=10s endpoint=http://plugins.volumio.org duration=405.286376ms Aug 26 15:55:16 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:16.402+04:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.100.4:50459 @ 0x2680150" latency=-379.605655ms timeout=10s endpoint=https://functions.volumio.cloud duration=435.165334ms Aug 26 15:55:16 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:16.404+04:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.100.4:50459 @ 0x2680150" latency=-379.605655ms timeout=10s endpoint=https://google.com duration=438.899251ms Aug 26 15:55:16 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:16.425+04:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.100.4:50459 @ 0x2680150" latency=-379.605655ms timeout=10s endpoint=https://functions.volumio.cloud duration=458.779417ms Aug 26 15:55:18 primo volumio[3266]: info: Preload queue cleared Aug 26 15:55:19 primo volumio[3266]: info: Preload queue cleared Aug 26 15:55:19 primo volumio[3266]: info: CoreCommandRouter::volumioReplaceandPlayItems Aug 26 15:55:19 primo volumio[3266]: info: CoreStateMachine::ClearQueue Aug 26 15:55:19 primo volumio[3266]: info: CoreStateMachine::stop Aug 26 15:55:19 primo volumio[3266]: info: CoreStateMachine::serviceStop Aug 26 15:55:19 primo volumio[3266]: info: CoreCommandRouter::serviceStop Aug 26 15:55:19 primo volumio[3266]: info: Airplay Stop Aug 26 15:55:19 primo volumio[3266]: info: Stopping Airplay Playback and sending pause command to client via USR2 Aug 26 15:55:19 primo volumio[3266]: info: CorePlayQueue::clearPlayQueue Aug 26 15:55:19 primo volumio[3266]: info: CorePlayQueue::saveQueue Aug 26 15:55:19 primo volumio[3266]: info: CoreCommandRouter::volumioPushQueue Aug 26 15:55:19 primo volumio[3266]: info: CoreStateMachine::addQueueItems Aug 26 15:55:19 primo volumio[3266]: info: CorePlayQueue::addQueueItems Aug 26 15:55:19 primo volumio[3266]: info: Preload queue cleared Aug 26 15:55:19 primo volumio[3266]: info: Adding Item to queue: rp2/channel@qi=%7B%22service%22%3A%22rp2%22%2C%22uri%22%3A%22rp2%2Fchannel%40id%3D1%22%2C%22name%22%3A%22Mellow%20Mix%22%2C%22title%22%3A%22Mellow%20Mix%22%2C%22artist%22%3A%22Radio%20Paradise%22%2C%22albumart%22%3A%22https%3A%2F%2Fimg.radioparadise.com%2Fchannels%2F0%2F1%2Fcover_512x512%2F0.jpg%22%7D Aug 26 15:55:19 primo volumio[3266]: info: Exploding uri rp2/channel@qi=%7B%22service%22%3A%22rp2%22%2C%22uri%22%3A%22rp2%2Fchannel%40id%3D1%22%2C%22name%22%3A%22Mellow%20Mix%22%2C%22title%22%3A%22Mellow%20Mix%22%2C%22artist%22%3A%22Radio%20Paradise%22%2C%22albumart%22%3A%22https%3A%2F%2Fimg.radioparadise.com%2Fchannels%2F0%2F1%2Fcover_512x512%2F0.jpg%22%7D in service rp2 Aug 26 15:55:19 primo volumio[3266]: info: CoreCommandRouter::volumioPushQueue Aug 26 15:55:19 primo volumio[3266]: info: CorePlayQueue::saveQueue Aug 26 15:55:19 primo volumio[3266]: info: CoreStateMachine::updateTrackBlock Aug 26 15:55:19 primo volumio[3266]: info: CorePlayQueue::getTrackBlock Aug 26 15:55:19 primo volumio[3266]: info: CoreCommandRouter::volumioGetState Aug 26 15:55:19 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: play , [object Object] Aug 26 15:55:19 primo volumio[3266]: info: CoreCommandRouter::volumioPlay Aug 26 15:55:19 primo volumio[3266]: verbose: UNSET VOLATILE: Service: airplay_emulation Aug 26 15:55:19 primo volumio[3266]: info: Stopping Airplay Playback and sending pause command to client via USR2 Aug 26 15:55:19 primo volumio[3266]: info: CoreStateMachine::play index 0 Aug 26 15:55:19 primo volumio[3266]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 26 15:55:19 primo volumio[3266]: info: CoreStateMachine::stop Aug 26 15:55:19 primo volumio[3266]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 26 15:55:19 primo volumio[3266]: info: CoreStateMachine::updateTrackBlock Aug 26 15:55:19 primo volumio[3266]: info: CorePlayQueue::getTrackBlock Aug 26 15:55:19 primo volumio[3266]: info: CoreStateMachine::stPlaybackTimer Aug 26 15:55:19 primo volumio[3266]: info: CoreStateMachine::pushState Aug 26 15:55:19 primo volumio[3266]: info: CorePlayQueue::getTrack 0 Aug 26 15:55:19 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 26 15:55:19 primo volumio[3266]: info: CoreCommandRouter::volumioPushState Aug 26 15:55:19 primo volumio[3266]: info: CoreCommandRouter::volumioGetState Aug 26 15:55:19 primo volumio[3266]: info: CorePlayQueue::getTrack 0 Aug 26 15:55:19 primo volumio[3266]: info: CoreStateMachine::serviceStop Aug 26 15:55:19 primo volumio[3266]: info: CorePlayQueue::getTrack 0 Aug 26 15:55:19 primo volumio[3266]: info: CoreCommandRouter::serviceStop Aug 26 15:55:19 primo volumio[3266]: warn: [rp2] Already stopped Aug 26 15:55:19 primo sudo[10802]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/kill -USR2 3818 Aug 26 15:55:19 primo sudo[10802]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 26 15:55:19 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:19.632+04:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.100.4:50459 @ 0x2680150" state=STATUS_STOPPED positionMs=0 volume=100 Aug 26 15:55:19 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:19.632+04:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.4:50459 @ 0x2680150" id="rp2/channel@id=1" title="Mellow Mix" Aug 26 15:55:19 primo volumio[3266]: info: CoreStateMachine::play index undefined Aug 26 15:55:19 primo volumio[3266]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 26 15:55:19 primo volumio[3266]: info: CorePlayQueue::getTrack 0 Aug 26 15:55:19 primo volumio[3266]: info: CoreStateMachine::startPlaybackTimer Aug 26 15:55:19 primo volumio[3266]: info: CorePlayQueue::getTrack 0 Aug 26 15:55:19 primo volumio[3266]: info: CoreCommandRouter::volumioGetVisibleSources Aug 26 15:55:19 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 26 15:55:19 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Aug 26 15:55:19 primo volumio[3266]: info: [rp2] clearAddPlayTrack: rp2/channel@id=1 Aug 26 15:55:19 primo sudo[10802]: pam_unix(sudo:session): session closed for user root Aug 26 15:55:19 primo kernel: asoc-aml-card auge_sound: tdm playback stop Aug 26 15:55:19 primo kernel: spdif_a is set to disable Aug 26 15:55:19 primo kernel: audio_ddr_mngr: frddr_set_sharebuffer_enable sel:1, dst_src:3 Aug 26 15:55:19 primo kernel: aml_dai_tdm_hw_free(), disable mclk for TDM-B Aug 26 15:55:19 primo kernel: tdm playback mute: 1, lane_cnt = 8 Aug 26 15:55:19 primo kernel: audio_ddr_mngr: frddrs[0] released by device ff660000.audiobus:tdm@1 Aug 26 15:55:19 primo shairport-sync[32225]: {"time":1787739482995,"response":"startAirplayPlayback Success"} Aug 26 15:55:19 primo systemd[1]: shairport-sync.service: Main process exited, code=killed, status=12/USR2 Aug 26 15:55:19 primo systemd[1]: shairport-sync.service: Failed with result 'signal'. Aug 26 15:55:19 primo sudo[10805]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/kill -USR2 3818 Aug 26 15:55:19 primo sudo[10805]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 26 15:55:19 primo volumio[3266]: info: Updating RAAT Signal Path Aug 26 15:55:19 primo sudo[10805]: pam_unix(sudo:session): session closed for user root Aug 26 15:55:19 primo volumio[3266]: info: Shairport-Sync paused with USR2 Aug 26 15:55:19 primo volumio[3266]: info: Cannot execute Shairport-sync USR2 kill: Error: Command failed: /usr/bin/sudo /bin/kill -USR2 $(pidof shairport-sync) Aug 26 15:55:19 primo volumio[3266]: /bin/kill: (3818): No such process Aug 26 15:55:19 primo volumio[3266]: info: MCU Signalled Playback Inactive Aug 26 15:55:20 primo volumio[3266]: info: Preload queue cleared Aug 26 15:55:20 primo volumio[3266]: info: CoreCommandRouter::volumioReplaceandPlayItems Aug 26 15:55:20 primo volumio[3266]: info: CoreStateMachine::ClearQueue Aug 26 15:55:20 primo volumio[3266]: info: CoreStateMachine::stop Aug 26 15:55:20 primo volumio[3266]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 26 15:55:20 primo volumio[3266]: info: CorePlayQueue::clearPlayQueue Aug 26 15:55:20 primo volumio[3266]: info: CorePlayQueue::saveQueue Aug 26 15:55:20 primo volumio[3266]: info: CoreCommandRouter::volumioPushQueue Aug 26 15:55:20 primo volumio[3266]: info: CoreStateMachine::addQueueItems Aug 26 15:55:20 primo volumio[3266]: info: CorePlayQueue::addQueueItems Aug 26 15:55:20 primo volumio[3266]: info: Preload queue cleared Aug 26 15:55:20 primo volumio[3266]: info: Adding Item to queue: rp2/channel@qi=%7B%22service%22%3A%22rp2%22%2C%22uri%22%3A%22rp2%2Fchannel%40id%3D0%22%2C%22name%22%3A%22The%20Main%20Mix%22%2C%22title%22%3A%22The%20Main%20Mix%22%2C%22artist%22%3A%22Radio%20Paradise%22%2C%22albumart%22%3A%22https%3A%2F%2Fimg.radioparadise.com%2Fchannels%2F0%2F0%2Fcover_512x512%2F0.jpg%22%7D Aug 26 15:55:20 primo volumio[3266]: info: Exploding uri rp2/channel@qi=%7B%22service%22%3A%22rp2%22%2C%22uri%22%3A%22rp2%2Fchannel%40id%3D0%22%2C%22name%22%3A%22The%20Main%20Mix%22%2C%22title%22%3A%22The%20Main%20Mix%22%2C%22artist%22%3A%22Radio%20Paradise%22%2C%22albumart%22%3A%22https%3A%2F%2Fimg.radioparadise.com%2Fchannels%2F0%2F0%2Fcover_512x512%2F0.jpg%22%7D in service rp2 Aug 26 15:55:20 primo volumio[3266]: info: CoreCommandRouter::volumioPushQueue Aug 26 15:55:20 primo volumio[3266]: info: CorePlayQueue::saveQueue Aug 26 15:55:20 primo volumio[3266]: info: CoreStateMachine::updateTrackBlock Aug 26 15:55:20 primo volumio[3266]: info: CorePlayQueue::getTrackBlock Aug 26 15:55:20 primo volumio[3266]: info: CoreCommandRouter::volumioGetState Aug 26 15:55:20 primo volumio[3266]: info: CorePlayQueue::getTrack 0 Aug 26 15:55:20 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: play , [object Object] Aug 26 15:55:20 primo volumio[3266]: info: CoreCommandRouter::volumioPlay Aug 26 15:55:20 primo volumio[3266]: info: CoreStateMachine::play index 0 Aug 26 15:55:20 primo volumio[3266]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 26 15:55:20 primo volumio[3266]: info: CoreStateMachine::stop Aug 26 15:55:20 primo volumio[3266]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 26 15:55:20 primo volumio[3266]: info: CoreStateMachine::play index undefined Aug 26 15:55:20 primo volumio[3266]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 26 15:55:20 primo volumio[3266]: info: CorePlayQueue::getTrack 0 Aug 26 15:55:20 primo volumio[3266]: info: CoreStateMachine::startPlaybackTimer Aug 26 15:55:20 primo volumio[3266]: info: CorePlayQueue::getTrack 0 Aug 26 15:55:20 primo volumio[3266]: info: CoreCommandRouter::volumioGetVisibleSources Aug 26 15:55:20 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 26 15:55:20 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Aug 26 15:55:20 primo volumio[3266]: info: [rp2] clearAddPlayTrack: rp2/channel@id=0 Aug 26 15:55:20 primo volumio[3266]: info: Restarting Shairport-Sync after stop Aug 26 15:55:20 primo sudo[10809]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Aug 26 15:55:20 primo sudo[10809]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 26 15:55:20 primo systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 26 15:55:20 primo sudo[10809]: pam_unix(sudo:session): session closed for user root Aug 26 15:55:20 primo volumio[3266]: info: Shairport-Sync retarted Aug 26 15:55:21 primo volumio[3266]: verbose: [rp2] API: https://api.radioparadise.com/api/play?source=24&event=0&elapsed=0&bitrate=4&action=start&player_id=********&info=true&chan=0&audio_type= Aug 26 15:55:22 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Aug 26 15:55:22 primo volumio[3266]: info: Preload queue cleared Aug 26 15:55:22 primo volumio[3266]: info: CoreCommandRouter::volumioReplaceandPlayItems Aug 26 15:55:22 primo volumio[3266]: info: CoreStateMachine::ClearQueue Aug 26 15:55:22 primo volumio[3266]: info: CoreStateMachine::stop Aug 26 15:55:22 primo volumio[3266]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 26 15:55:22 primo volumio[3266]: info: CorePlayQueue::clearPlayQueue Aug 26 15:55:22 primo volumio[3266]: info: CorePlayQueue::saveQueue Aug 26 15:55:22 primo volumio[3266]: info: CoreCommandRouter::volumioPushQueue Aug 26 15:55:22 primo volumio[3266]: info: CoreStateMachine::addQueueItems Aug 26 15:55:22 primo volumio[3266]: info: CorePlayQueue::addQueueItems Aug 26 15:55:22 primo volumio[3266]: info: Preload queue cleared Aug 26 15:55:22 primo volumio[3266]: info: Adding Item to queue: rp2/channel@qi=%7B%22service%22%3A%22rp2%22%2C%22uri%22%3A%22rp2%2Fchannel%40id%3D0%22%2C%22name%22%3A%22The%20Main%20Mix%22%2C%22title%22%3A%22The%20Main%20Mix%22%2C%22artist%22%3A%22Radio%20Paradise%22%2C%22albumart%22%3A%22https%3A%2F%2Fimg.radioparadise.com%2Fchannels%2F0%2F0%2Fcover_512x512%2F0.jpg%22%7D Aug 26 15:55:22 primo volumio[3266]: info: Using cached record of: rp2/channel@qi=%7B%22service%22%3A%22rp2%22%2C%22uri%22%3A%22rp2%2Fchannel%40id%3D0%22%2C%22name%22%3A%22The%20Main%20Mix%22%2C%22title%22%3A%22The%20Main%20Mix%22%2C%22artist%22%3A%22Radio%20Paradise%22%2C%22albumart%22%3A%22https%3A%2F%2Fimg.radioparadise.com%2Fchannels%2F0%2F0%2Fcover_512x512%2F0.jpg%22%7D Aug 26 15:55:22 primo volumio[3266]: info: CoreCommandRouter::volumioPushQueue Aug 26 15:55:22 primo volumio[3266]: info: CorePlayQueue::saveQueue Aug 26 15:55:22 primo volumio[3266]: info: CoreStateMachine::updateTrackBlock Aug 26 15:55:22 primo volumio[3266]: info: CorePlayQueue::getTrackBlock Aug 26 15:55:22 primo volumio[3266]: info: CoreCommandRouter::volumioGetState Aug 26 15:55:22 primo volumio[3266]: info: CorePlayQueue::getTrack 0 Aug 26 15:55:22 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: play , [object Object] Aug 26 15:55:22 primo volumio[3266]: info: CoreCommandRouter::volumioPlay Aug 26 15:55:22 primo volumio[3266]: info: CoreStateMachine::play index 0 Aug 26 15:55:22 primo volumio[3266]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 26 15:55:22 primo volumio[3266]: info: CoreStateMachine::stop Aug 26 15:55:22 primo volumio[3266]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 26 15:55:22 primo volumio[3266]: info: CoreStateMachine::play index undefined Aug 26 15:55:22 primo volumio[3266]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 26 15:55:22 primo volumio[3266]: info: CorePlayQueue::getTrack 0 Aug 26 15:55:22 primo volumio[3266]: info: CoreStateMachine::startPlaybackTimer Aug 26 15:55:22 primo volumio[3266]: info: CorePlayQueue::getTrack 0 Aug 26 15:55:22 primo volumio[3266]: info: CoreCommandRouter::volumioGetVisibleSources Aug 26 15:55:22 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 26 15:55:22 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Aug 26 15:55:22 primo volumio[3266]: info: [rp2] clearAddPlayTrack: rp2/channel@id=0 Aug 26 15:55:22 primo volumio[3266]: verbose: [rp2] API: https://api.radioparadise.com/api/play?source=24&event=0&elapsed=0&bitrate=4&action=start&player_id=********&info=true&chan=0&audio_type= Aug 26 15:55:23 primo volumio[3266]: info: [rp2] Obtained block for channel "0" Aug 26 15:55:23 primo volumio[3266]: info: [rp2] ------------- Aug 26 15:55:23 primo volumio[3266]: info: [rp2] Block summary Aug 26 15:55:23 primo volumio[3266]: info: [rp2] ------------- Aug 26 15:55:23 primo volumio[3266]: info: [rp2] Stream URL: https://audio.radioparadise.stream/audio/blocks/0/x/1558/4/b/1558-0.flac Aug 26 15:55:23 primo volumio[3266]: info: [rp2] Tracks: Aug 26 15:55:23 primo volumio[3266]: info: [rp2] 0. Naked Air (5:31 | elapsed: 9m 56s) Aug 26 15:55:23 primo volumio[3266]: info: [rp2] 1. Starry Eyes (4:14 | elapsed: 15m 28s) Aug 26 15:55:23 primo volumio[3266]: info: [rp2] 2. Ghosts Again (3:54 | elapsed: 19m 42s) Aug 26 15:55:23 primo volumio[3266]: info: [rp2] 3. BODYSCANNER (5:05 | elapsed: 23m 36s) Aug 26 15:55:23 primo volumio[3266]: info: [rp2] Aug 26 15:55:23 primo volumio[3266]: verbose: [rp2] Current track scheduled playback vs. current time: 8/26/2026, 3:54:59 PM <-> 8/26/2026, 3:55:23 PM Aug 26 15:55:23 primo volumio[3266]: info: [rp2] Going to start playback of current track at 0:24 (track position in stream: 9:56) Aug 26 15:55:23 primo volumio[3266]: info: [rp2] Starting mpv Aug 26 15:55:25 primo volumio[3266]: info: [rp2] [mpv] mpv version: 0.35.1 Aug 26 15:55:25 primo volumio[3266]: info: [rp2] [mpv] mpv process spawned Aug 26 15:55:25 primo volumio[3266]: verbose: [rp2] Waiting for player event "playing"... Aug 26 15:55:26 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Started (IPC socket: /tmp/volumio_mpv_socket_a8dbc079-12b0-4494-a6ad-e8640c649862) Aug 26 15:55:26 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Send IPC command: {"command":["observe_property",1,"pause"],"request_id":0} Aug 26 15:55:26 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Send IPC command: {"command":["observe_property",2,"duration"],"request_id":1} Aug 26 15:55:26 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Send IPC command: {"command":["observe_property",3,"idle-active"],"request_id":2} Aug 26 15:55:26 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Send IPC command: {"command":["observe_property",4,"volume"],"request_id":3} Aug 26 15:55:26 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Send IPC command: {"command":["observe_property",5,"mute"],"request_id":4} Aug 26 15:55:26 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Send IPC command: {"command":["observe_property",6,"audio-params"],"request_id":5} Aug 26 15:55:26 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Send IPC command: {"command":["observe_property",7,"audio-codec-name"],"request_id":6} Aug 26 15:55:26 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Send IPC command: {"command":["observe_property",8,"media-title"],"request_id":7} Aug 26 15:55:26 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Send IPC command: {"command":["observe_property",9,"metadata"],"request_id":8} Aug 26 15:55:26 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Send IPC command: {"command":["observe_property",10,"time-pos"],"request_id":9} Aug 26 15:55:26 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Send IPC command: {"command":["observe_property",11,"playback-restart"],"request_id":10} Aug 26 15:55:26 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Send IPC command: {"command":["observe_property",12,"seeking"],"request_id":11} Aug 26 15:55:26 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Got response for command #0: {"request_id":0,"error":"success"} Aug 26 15:55:26 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Got response for command #1: {"request_id":1,"error":"success"} Aug 26 15:55:26 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Got response for command #2: {"request_id":2,"error":"success"} Aug 26 15:55:26 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Got response for command #3: {"request_id":3,"error":"success"} Aug 26 15:55:26 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Got response for command #4: {"request_id":4,"error":"success"} Aug 26 15:55:26 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Got response for command #5: {"request_id":5,"error":"success"} Aug 26 15:55:26 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Got response for command #6: {"request_id":6,"error":"success"} Aug 26 15:55:26 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Got response for command #7: {"request_id":7,"error":"success"} Aug 26 15:55:26 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Got response for command #8: {"request_id":8,"error":"success"} Aug 26 15:55:26 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Got response for command #9: {"request_id":9,"error":"success"} Aug 26 15:55:26 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Got response for command #10: {"request_id":10,"error":"success"} Aug 26 15:55:26 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Got response for command #11: {"request_id":11,"error":"success"} Aug 26 15:55:26 primo volumio[3266]: info: CoreCommandRouter::volumioGetState Aug 26 15:55:26 primo volumio[3266]: info: CorePlayQueue::getTrack 0 Aug 26 15:55:26 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Stopping playback by current service... Aug 26 15:55:26 primo volumio[3266]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 26 15:55:26 primo volumio[3266]: info: CoreCommandRouter::volumioStop Aug 26 15:55:26 primo volumio[3266]: info: CoreStateMachine::stop Aug 26 15:55:26 primo volumio[3266]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 26 15:55:26 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Setting ourselves as the current service... Aug 26 15:55:26 primo volumio[3266]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 26 15:55:26 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Send IPC command: {"command":["set_property","loop-file","no"],"request_id":12} Aug 26 15:55:26 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Got response for command #12: {"request_id":12,"error":"success"} Aug 26 15:55:26 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Status update -> property-change events: [{"subscriptionId":1,"prop":"pause","data":false},{"subscriptionId":2,"prop":"duration"},{"subscriptionId":3,"prop":"idle-active","data":true},{"subscriptionId":4,"prop":"volume","data":100},{"subscriptionId":5,"prop":"mute","data":false},{"subscriptionId":6,"prop":"audio-params"},{"subscriptionId":7,"prop":"audio-codec-name"},{"subscriptionId":8,"prop":"media-title"},{"subscriptionId":9,"prop":"metadata"}] Aug 26 15:55:26 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Player status "stopped" - skip unset volatile because unset condition is "manual" Aug 26 15:55:26 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Player status "stopped" - skip unset volatile because unset condition is "manual" Aug 26 15:55:26 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Push Volumio state: {"status":"pause","albumart":"https://img.radioparadise.com/covers/l/28000.jpg","uri":"rp2/channel@id=0","seek":0,"duration":331.441,"service":"rp2","stream":false,"repeat":false,"repeatSingle":false,"random":false,"volume":100,"mute":false,"disableVolumeControl":false,"title":"Naked Air","artist":"The Bevis Frond","album":"Horrorful Heights","codec":"flac","trackType":"The Main Mix"} Aug 26 15:55:26 primo volumio[3266]: info: CoreCommandRouter::servicePushState Aug 26 15:55:26 primo volumio[3266]: info: CoreStateMachine::pushState Aug 26 15:55:26 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 26 15:55:26 primo volumio[3266]: info: CoreCommandRouter::volumioPushState Aug 26 15:55:26 primo volumio[3266]: info: CoreCommandRouter::volumioGetState Aug 26 15:55:26 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Send IPC command: {"command":["loadfile","https://audio.radioparadise.stream/audio/blocks/0/x/1558/4/b/1558-0.flac","replace","start=620.77"],"request_id":13} Aug 26 15:55:26 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:26.427+04:00 level=ERROR msg="failed to unmarshal pushState event" component=volumio/socket error="json: cannot unmarshal number 331.441 into Go struct field State.duration of type int" Aug 26 15:55:26 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Got response for command #13: {"data":{"playlist_entry_id":1},"request_id":13,"error":"success"} Aug 26 15:55:26 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Status update -> property-change events: [{"subscriptionId":3,"prop":"idle-active","data":false},{"subscriptionId":8,"prop":"media-title","data":"1558-0.flac"}] Aug 26 15:55:26 primo volumio[3266]: info: CoreCommandRouter::volumioGetState Aug 26 15:55:26 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Send IPC command: {"command":["set_property","pause",false],"request_id":14} Aug 26 15:55:26 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Push Volumio state: {"status":"play","uri":"rp2/channel@id=0","title":"Naked Air","artist":"The Bevis Frond","album":"Horrorful Heights","albumart":"https://img.radioparadise.com/covers/l/28000.jpg","trackType":"The Main Mix","duration":331.441,"service":"rp2","seek":0,"stream":false,"repeat":false,"repeatSingle":false,"random":false,"volume":100,"mute":false,"disableVolumeControl":false,"codec":"flac"} Aug 26 15:55:26 primo volumio[3266]: info: CoreCommandRouter::servicePushState Aug 26 15:55:26 primo volumio[3266]: info: CoreStateMachine::pushState Aug 26 15:55:26 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 26 15:55:26 primo volumio[3266]: info: CoreCommandRouter::volumioPushState Aug 26 15:55:26 primo volumio[3266]: info: CoreCommandRouter::volumioGetState Aug 26 15:55:26 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:26.447+04:00 level=ERROR msg="failed to unmarshal pushState event" component=volumio/socket error="json: cannot unmarshal number 331.441 into Go struct field State.duration of type int" Aug 26 15:55:26 primo volumio[3266]: info: Signalling Playback active due to playback status change Aug 26 15:55:26 primo volumio[3266]: info: Updating RAAT Signal Path Aug 26 15:55:26 primo volumio[3266]: info: Updating RAAT Signal Path Aug 26 15:55:26 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Got response for command #14: {"request_id":14,"error":"success"} Aug 26 15:55:26 primo volumio[3266]: info: MCU Signalled Playback Active Aug 26 15:55:27 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) (+) Audio --aid=1 (flac 2ch 44100Hz) Aug 26 15:55:27 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Status update -> property-change events: [{"subscriptionId":2,"prop":"duration","data":1722.506009},{"subscriptionId":7,"prop":"audio-codec-name","data":"flac"},{"subscriptionId":9,"prop":"metadata","data":{}}] Aug 26 15:55:27 primo volumio[3266]: info: CoreCommandRouter::volumioGetState Aug 26 15:55:29 primo kernel: aml_tdm_open Aug 26 15:55:29 primo kernel: Not init audio effects Aug 26 15:55:29 primo kernel: audio_ddr_mngr: frddrs[0] registered by device ff660000.audiobus:tdm@1 Aug 26 15:55:29 primo kernel: aml_dai_set_tdm_sysclk(), mpll no change, keep clk Aug 26 15:55:29 primo kernel: aml_dai_set_tdm_sysclk(), mclk no change, keep clk Aug 26 15:55:29 primo kernel: set mclk:11289600, mpll:22579200, get mclk:11289593, mpll:22579186 Aug 26 15:55:29 primo kernel: asoc aml_dai_set_tdm_fmt, 0x4001, ffffffc03d365e18, id(1), clksel(1) Aug 26 15:55:29 primo kernel: aml_dai_set_tdm_fmt(), fmt not change Aug 26 15:55:29 primo kernel: dump_pcm_setting(ffffffc03d365e18) Aug 26 15:55:29 primo kernel: pcm_mode(1) Aug 26 15:55:29 primo kernel: sysclk(11289600) Aug 26 15:55:29 primo kernel: sysclk_bclk_ratio(4) Aug 26 15:55:29 primo kernel: bclk(2822400) Aug 26 15:55:29 primo kernel: bclk_lrclk_ratio(64) Aug 26 15:55:29 primo kernel: lrclk(44100) Aug 26 15:55:29 primo kernel: tx_mask(0x3) Aug 26 15:55:29 primo kernel: rx_mask(0x3) Aug 26 15:55:29 primo kernel: slots(2) Aug 26 15:55:29 primo kernel: slot_width(32) Aug 26 15:55:29 primo kernel: lane_mask_in(0x2) Aug 26 15:55:29 primo kernel: lane_mask_out(0x1) Aug 26 15:55:29 primo kernel: lane_oe_mask_in(0x0) Aug 26 15:55:29 primo kernel: lane_oe_mask_out(0x0) Aug 26 15:55:29 primo kernel: lane_lb_mask_in(0x0) Aug 26 15:55:29 primo kernel: aml_dai_set_tdm_sysclk(), mpll no change, keep clk Aug 26 15:55:29 primo kernel: aml_dai_set_tdm_sysclk(), mclk no change, keep clk Aug 26 15:55:29 primo kernel: set mclk:11289600, mpll:22579200, get mclk:11289593, mpll:22579186 Aug 26 15:55:29 primo kernel: aml_dai_set_clkdiv, div 4, clksel(1) Aug 26 15:55:29 primo kernel: aml_dai_set_bclk_ratio, select I2S mode Aug 26 15:55:29 primo kernel: aml_dai_tdm_hw_params(), enable mclk for TDM-B Aug 26 15:55:29 primo kernel: aml_tdm_prepare(), reset fddr Aug 26 15:55:29 primo kernel: spdif_a fifo ctrl, frddr:0 type:1, 16 bits, chmask 0x3, swap 0x10 Aug 26 15:55:29 primo kernel: spdif_info: rate: 44100, channel status ch0_l:0x100, ch0_r:0x100, ch1_l:0x0, ch1_r:0x0 Aug 26 15:55:29 primo kernel: audio_ddr_mngr: frddr_set_sharebuffer_enable sel:1, dst_src:3 Aug 26 15:55:29 primo kernel: tdm playback mute: 0, lane_cnt = 8 Aug 26 15:55:29 primo kernel: aml_tdm_prepare(), reset fddr Aug 26 15:55:29 primo kernel: spdif_a fifo ctrl, frddr:0 type:1, 16 bits, chmask 0x3, swap 0x10 Aug 26 15:55:29 primo kernel: spdif_info: rate: 44100, channel status ch0_l:0x100, ch0_r:0x100, ch1_l:0x0, ch1_r:0x0 Aug 26 15:55:29 primo kernel: audio_ddr_mngr: frddr_set_sharebuffer_enable sel:1, dst_src:3 Aug 26 15:55:29 primo kernel: tdm playback mute: 0, lane_cnt = 8 Aug 26 15:55:29 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) AO: [alsa] 44100Hz stereo 2ch s16 Aug 26 15:55:29 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Status update -> property-change events: [{"subscriptionId":6,"prop":"audio-params","data":{"samplerate":44100,"channel-count":2,"channels":"stereo","hr-channels":"stereo","format":"s16"}}] Aug 26 15:55:29 primo volumio[3266]: info: CoreCommandRouter::volumioGetState Aug 26 15:55:29 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Push Volumio state: {"status":"play","uri":"rp2/channel@id=0","title":"Naked Air","artist":"The Bevis Frond","album":"Horrorful Heights","albumart":"https://img.radioparadise.com/covers/l/28000.jpg","trackType":"The Main Mix - ","duration":331.441,"samplerate":"44.1 kHz","bitdepth":"16-bit","channels":2,"service":"rp2","seek":24016,"stream":false,"repeat":false,"repeatSingle":false,"random":false,"volume":100,"mute":false,"disableVolumeControl":false,"codec":"flac"} Aug 26 15:55:29 primo volumio[3266]: info: CoreCommandRouter::servicePushState Aug 26 15:55:29 primo volumio[3266]: info: CoreStateMachine::pushState Aug 26 15:55:29 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 26 15:55:29 primo volumio[3266]: info: CoreCommandRouter::volumioPushState Aug 26 15:55:29 primo kernel: asoc-aml-card auge_sound: tdm playback enable Aug 26 15:55:29 primo kernel: spdif_a is set to enable Aug 26 15:55:29 primo volumio[3266]: info: CoreCommandRouter::volumioGetState Aug 26 15:55:29 primo volumio[3266]: verbose: [rp2] Received player event "playing"... Aug 26 15:55:29 primo volumio[3266]: info: [rp2] Started playback of "Naked Air" - estimated finish time: 8/26/2026, 4:00:36 PM Aug 26 15:55:29 primo volumio[3266]: info: CoreCommandRouter::volumioGetState Aug 26 15:55:29 primo volumio[3266]: verbose: [rp2] After "Naked Air", the next track will start in 5m 7s (8/26/2026, 4:00:36 PM) Aug 26 15:55:29 primo volumio[3266]: verbose: [rp2] API: https://api.radioparadise.com/api/update_history?source=24&song_id=62627&chan=0&player_id=********&event=2915245&type=M&slice_num=2&episode_id=0&time_relative=-25&play_position_millis=24016&playtime_secs=1787745330 Aug 26 15:55:29 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:29.530+04:00 level=ERROR msg="failed to unmarshal pushState event" component=volumio/socket error="json: cannot unmarshal number 331.441 into Go struct field State.duration of type int" Aug 26 15:55:29 primo volumio[3266]: info: CoreCommandRouter::volumioGetState Aug 26 15:55:29 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Push Volumio state: {"status":"play","uri":"rp2/channel@id=0","title":"Naked Air","artist":"The Bevis Frond","album":"Horrorful Heights","albumart":"https://img.radioparadise.com/covers/l/28000.jpg","trackType":"The Main Mix - ","duration":331.441,"samplerate":"44.1 kHz","bitdepth":"16-bit","channels":2,"service":"rp2","seek":24033.415000000037,"stream":false,"repeat":false,"repeatSingle":false,"random":false,"volume":100,"mute":false,"disableVolumeControl":false,"codec":"flac"} Aug 26 15:55:29 primo volumio[3266]: info: CoreCommandRouter::servicePushState Aug 26 15:55:29 primo volumio[3266]: info: CoreStateMachine::pushState Aug 26 15:55:29 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 26 15:55:29 primo volumio[3266]: info: CoreCommandRouter::volumioPushState Aug 26 15:55:29 primo volumio[3266]: info: CoreCommandRouter::volumioGetState Aug 26 15:55:29 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:29.546+04:00 level=ERROR msg="failed to unmarshal pushState event" component=volumio/socket error="json: cannot unmarshal number 24033.415000000037 into Go struct field State.seek of type int" Aug 26 15:55:29 primo volumio[3266]: info: Signalling Playback active due to playback status change Aug 26 15:55:29 primo volumio[3266]: info: Signalling Playback active due to playback status change Aug 26 15:55:29 primo volumio[3266]: info: Updating RAAT Signal Path Aug 26 15:55:29 primo volumio[3266]: info: Updating RAAT Signal Path Aug 26 15:55:31 primo volumio[3266]: verbose: [rp2] Checking if next track interval requires adjusting (1/5)... Aug 26 15:55:31 primo volumio[3266]: verbose: [rp2] Next track interval is accurate Aug 26 15:55:31 primo volumio[3266]: info: Preload queue cleared Aug 26 15:55:31 primo volumio[3266]: info: CoreCommandRouter::volumioReplaceandPlayItems Aug 26 15:55:31 primo volumio[3266]: info: CoreStateMachine::ClearQueue Aug 26 15:55:31 primo volumio[3266]: info: CoreStateMachine::stop Aug 26 15:55:31 primo volumio[3266]: info: CoreStateMachine::serviceStop Aug 26 15:55:31 primo volumio[3266]: info: CoreCommandRouter::serviceStop Aug 26 15:55:31 primo volumio[3266]: info: CoreStateMachine::stPlaybackTimer Aug 26 15:55:31 primo volumio[3266]: info: CoreStateMachine::updateTrackBlock Aug 26 15:55:31 primo volumio[3266]: info: CorePlayQueue::getTrackBlock Aug 26 15:55:31 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Send IPC command: {"command":["stop"],"request_id":15} Aug 26 15:55:31 primo volumio[3266]: verbose: [rp2] Waiting for player event "stopped"... Aug 26 15:55:31 primo volumio[3266]: info: CorePlayQueue::clearPlayQueue Aug 26 15:55:31 primo kernel: asoc-aml-card auge_sound: tdm playback stop Aug 26 15:55:31 primo kernel: spdif_a is set to disable Aug 26 15:55:31 primo kernel: aml_tdm_prepare(), reset fddr Aug 26 15:55:31 primo kernel: spdif_a fifo ctrl, frddr:0 type:1, 16 bits, chmask 0x3, swap 0x10 Aug 26 15:55:31 primo kernel: spdif_info: rate: 44100, channel status ch0_l:0x100, ch0_r:0x100, ch1_l:0x0, ch1_r:0x0 Aug 26 15:55:31 primo kernel: audio_ddr_mngr: frddr_set_sharebuffer_enable sel:1, dst_src:3 Aug 26 15:55:31 primo kernel: tdm playback mute: 0, lane_cnt = 8 Aug 26 15:55:31 primo volumio[3266]: info: CorePlayQueue::saveQueue Aug 26 15:55:31 primo volumio[3266]: info: CoreCommandRouter::volumioPushQueue Aug 26 15:55:31 primo volumio[3266]: info: CoreStateMachine::addQueueItems Aug 26 15:55:31 primo volumio[3266]: info: CorePlayQueue::addQueueItems Aug 26 15:55:31 primo volumio[3266]: info: Preload queue cleared Aug 26 15:55:31 primo volumio[3266]: info: Adding Item to queue: rp2/channel@qi=%7B%22service%22%3A%22rp2%22%2C%22uri%22%3A%22rp2%2Fchannel%40id%3D1%22%2C%22name%22%3A%22Mellow%20Mix%22%2C%22title%22%3A%22Mellow%20Mix%22%2C%22artist%22%3A%22Radio%20Paradise%22%2C%22albumart%22%3A%22https%3A%2F%2Fimg.radioparadise.com%2Fchannels%2F0%2F1%2Fcover_512x512%2F0.jpg%22%7D Aug 26 15:55:31 primo volumio[3266]: info: Using cached record of: rp2/channel@qi=%7B%22service%22%3A%22rp2%22%2C%22uri%22%3A%22rp2%2Fchannel%40id%3D1%22%2C%22name%22%3A%22Mellow%20Mix%22%2C%22title%22%3A%22Mellow%20Mix%22%2C%22artist%22%3A%22Radio%20Paradise%22%2C%22albumart%22%3A%22https%3A%2F%2Fimg.radioparadise.com%2Fchannels%2F0%2F1%2Fcover_512x512%2F0.jpg%22%7D Aug 26 15:55:31 primo volumio[3266]: info: CoreCommandRouter::volumioPushQueue Aug 26 15:55:31 primo volumio[3266]: info: CorePlayQueue::saveQueue Aug 26 15:55:31 primo volumio[3266]: info: CoreStateMachine::updateTrackBlock Aug 26 15:55:31 primo volumio[3266]: info: CorePlayQueue::getTrackBlock Aug 26 15:55:31 primo volumio[3266]: info: CoreCommandRouter::volumioGetState Aug 26 15:55:31 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: play , [object Object] Aug 26 15:55:31 primo volumio[3266]: info: CoreCommandRouter::volumioPlay Aug 26 15:55:31 primo volumio[3266]: verbose: UNSET VOLATILE: Service: rp2 Aug 26 15:55:31 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Volatile state unset, stopping playback (if any)... Aug 26 15:55:31 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Push Volumio state: {"status":"stop","albumart":"https://img.radioparadise.com/covers/l/28000.jpg","uri":"rp2/channel@id=0","seek":26163.84600000002,"duration":331.441,"service":"rp2","stream":false,"repeat":false,"repeatSingle":false,"random":false,"volume":100,"mute":false,"disableVolumeControl":false,"title":"Naked Air","artist":"The Bevis Frond","album":"Horrorful Heights","codec":"flac","trackType":"The Main Mix"} Aug 26 15:55:31 primo volumio[3266]: info: CoreCommandRouter::servicePushState Aug 26 15:55:31 primo volumio[3266]: info: CoreStateMachine::pushState Aug 26 15:55:31 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 26 15:55:31 primo volumio[3266]: info: CoreCommandRouter::volumioPushState Aug 26 15:55:31 primo volumio[3266]: info: CoreCommandRouter::volumioGetState Aug 26 15:55:31 primo volumio[3266]: info: CorePlayQueue::getTrack 0 Aug 26 15:55:31 primo volumio[3266]: verbose: STATE SERVICE {"status":"stop","albumart":"https://img.radioparadise.com/covers/l/28000.jpg","uri":"rp2/channel@id=0","seek":26163.84600000002,"duration":331.441,"service":"rp2","stream":false,"repeat":false,"repeatSingle":false,"random":false,"volume":100,"mute":false,"disableVolumeControl":false,"title":"Naked Air","artist":"The Bevis Frond","album":"Horrorful Heights","codec":"flac","trackType":"The Main Mix"} Aug 26 15:55:31 primo volumio[3266]: verbose: CURRENT POSITION 0 Aug 26 15:55:31 primo volumio[3266]: info: CoreStateMachine::syncState stateService stop Aug 26 15:55:31 primo volumio[3266]: info: CoreStateMachine::syncState currentStatus stop Aug 26 15:55:31 primo volumio[3266]: info: CoreStateMachine::pushState Aug 26 15:55:31 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 26 15:55:31 primo volumio[3266]: info: CoreCommandRouter::volumioPushState Aug 26 15:55:31 primo volumio[3266]: info: CoreCommandRouter::volumioGetState Aug 26 15:55:31 primo volumio[3266]: info: No code Aug 26 15:55:31 primo volumio[3266]: info: CoreStateMachine::pushState Aug 26 15:55:31 primo volumio[3266]: info: CoreCommandRouter::volumioPushState Aug 26 15:55:31 primo volumio[3266]: info: CoreCommandRouter::volumioGetState Aug 26 15:55:31 primo volumio[3266]: MPVPlayer onunsetVolatile called Aug 26 15:55:31 primo volumio[3266]: MPVPlayer calling onunsetVolatile callbacks Aug 26 15:55:31 primo volumio[3266]: verbose: [rp2] Waiting for player event "stopped"... Aug 26 15:55:31 primo volumio[3266]: info: CoreStateMachine::play index 0 Aug 26 15:55:31 primo volumio[3266]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 26 15:55:31 primo kernel: audio_ddr_mngr: frddr_set_sharebuffer_enable sel:1, dst_src:3 Aug 26 15:55:31 primo kernel: aml_dai_tdm_hw_free(), disable mclk for TDM-B Aug 26 15:55:31 primo kernel: tdm playback mute: 1, lane_cnt = 8 Aug 26 15:55:31 primo kernel: audio_ddr_mngr: frddrs[0] released by device ff660000.audiobus:tdm@1 Aug 26 15:55:31 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:31.723+04:00 level=ERROR msg="failed to unmarshal pushState event" component=volumio/socket error="json: cannot unmarshal number 26163.84600000002 into Go struct field State.seek of type int" Aug 26 15:55:31 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:31.724+04:00 level=ERROR msg="failed to unmarshal pushState event" component=volumio/socket error="json: cannot unmarshal number 26163.84600000002 into Go struct field State.seek of type int" Aug 26 15:55:31 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:31.724+04:00 level=ERROR msg="failed to unmarshal pushState event" component=volumio/socket error="json: cannot unmarshal number 26163.84600000002 into Go struct field State.seek of type int" Aug 26 15:55:31 primo volumio[3266]: info: CoreStateMachine::stop Aug 26 15:55:31 primo volumio[3266]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 26 15:55:31 primo volumio[3266]: info: CoreStateMachine::play index undefined Aug 26 15:55:31 primo volumio[3266]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 26 15:55:31 primo volumio[3266]: info: CorePlayQueue::getTrack 0 Aug 26 15:55:31 primo volumio[3266]: info: CoreStateMachine::startPlaybackTimer Aug 26 15:55:31 primo volumio[3266]: info: CorePlayQueue::getTrack 0 Aug 26 15:55:31 primo volumio[3266]: info: CoreCommandRouter::volumioGetVisibleSources Aug 26 15:55:31 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 26 15:55:31 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Aug 26 15:55:31 primo volumio[3266]: info: [rp2] clearAddPlayTrack: rp2/channel@id=1 Aug 26 15:55:31 primo volumio[3266]: verbose: [rp2] Received player event "stopped"... Aug 26 15:55:31 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Got response for command #15: {"data":null,"request_id":15,"error":"success"} Aug 26 15:55:31 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Status update -> property-change events: [{"subscriptionId":6,"prop":"audio-params"},{"subscriptionId":7,"prop":"audio-codec-name"},{"subscriptionId":2,"prop":"duration"},{"subscriptionId":3,"prop":"idle-active","data":true},{"subscriptionId":8,"prop":"media-title"},{"subscriptionId":9,"prop":"metadata"}] Aug 26 15:55:31 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Player status "stopped" - unsetting ourselves as current service... Aug 26 15:55:31 primo volumio[3266]: info: Signalling Playback active due to playback status change Aug 26 15:55:31 primo volumio[3266]: info: Signalling Playback active due to playback status change Aug 26 15:55:31 primo volumio[3266]: info: Signalling Playback active due to playback status change Aug 26 15:55:31 primo volumio[3266]: info: Updating RAAT Signal Path Aug 26 15:55:31 primo volumio[3266]: info: Updating RAAT Signal Path Aug 26 15:55:31 primo volumio[3266]: info: Updating RAAT Signal Path Aug 26 15:55:31 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Aug 26 15:55:31 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Aug 26 15:55:31 primo volumio[3266]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Aug 26 15:55:31 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Aug 26 15:55:31 primo volumio[3266]: info: Received Get System Version Aug 26 15:55:31 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 26 15:55:31 primo volumio[3266]: info: Received Get System Info Aug 26 15:55:31 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 26 15:55:31 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 26 15:55:31 primo volumio[3266]: info: Discovery: Getting this device information Aug 26 15:55:31 primo volumio[3266]: info: CoreCommandRouter::volumioGetState Aug 26 15:55:31 primo volumio[3266]: info: CorePlayQueue::getTrack 0 Aug 26 15:55:31 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 26 15:55:31 primo volumio[3266]: verbose: [rp2] API: https://api.radioparadise.com/api/play?source=24&event=0&elapsed=0&bitrate=4&action=start&player_id=********&info=true&chan=1&audio_type= Aug 26 15:55:32 primo volumio[3266]: info: [rp2] Obtained block for channel "1" Aug 26 15:55:32 primo volumio[3266]: info: [rp2] ------------- Aug 26 15:55:32 primo volumio[3266]: info: [rp2] Block summary Aug 26 15:55:32 primo volumio[3266]: info: [rp2] ------------- Aug 26 15:55:32 primo volumio[3266]: info: [rp2] Stream URL: https://audio.radioparadise.stream/audio/blocks/1/x/1195/4/b/1195-0.flac Aug 26 15:55:32 primo volumio[3266]: info: [rp2] Tracks: Aug 26 15:55:32 primo volumio[3266]: info: [rp2] 0. Wherever You Are (4:33 | elapsed: 7m 21s) Aug 26 15:55:32 primo volumio[3266]: info: [rp2] 1. I Dream of Spring (3:53 | elapsed: 11m 55s) Aug 26 15:55:32 primo volumio[3266]: info: [rp2] 2. The River (6:17 | elapsed: 15m 48s) Aug 26 15:55:32 primo volumio[3266]: info: [rp2] 3. Traveling Alone (4:20 | elapsed: 22m 6s) Aug 26 15:55:32 primo volumio[3266]: info: [rp2] 4. Poetry Man (4:31 | elapsed: 26m 26s) Aug 26 15:55:32 primo volumio[3266]: info: [rp2] Aug 26 15:55:32 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Player status "stopped" - skip unset volatile because unset condition is "manual" Aug 26 15:55:32 primo volumio[3266]: verbose: [rp2] Current track scheduled playback vs. current time: 8/26/2026, 3:54:08 PM <-> 8/26/2026, 3:55:32 PM Aug 26 15:55:32 primo volumio[3266]: info: [rp2] Going to start playback of current track at 1:24 (track position in stream: 7:21) Aug 26 15:55:32 primo volumio[3266]: verbose: [rp2] Waiting for player event "playing"... Aug 26 15:55:32 primo volumio[3266]: info: CoreCommandRouter::volumioGetState Aug 26 15:55:32 primo volumio[3266]: info: CorePlayQueue::getTrack 0 Aug 26 15:55:32 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Stopping playback by current service... Aug 26 15:55:32 primo volumio[3266]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 26 15:55:32 primo volumio[3266]: info: CoreCommandRouter::volumioStop Aug 26 15:55:32 primo volumio[3266]: info: CoreStateMachine::stop Aug 26 15:55:32 primo volumio[3266]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 26 15:55:32 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Setting ourselves as the current service... Aug 26 15:55:32 primo volumio[3266]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 26 15:55:32 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Send IPC command: {"command":["set_property","loop-file","no"],"request_id":16} Aug 26 15:55:32 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Got response for command #16: {"request_id":16,"error":"success"} Aug 26 15:55:32 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Push Volumio state: {"status":"pause","albumart":"https://img.radioparadise.com/covers/l/19824.jpg","uri":"rp2/channel@id=1","seek":0,"duration":273.875,"service":"rp2","stream":false,"repeat":false,"repeatSingle":false,"random":false,"volume":100,"mute":false,"disableVolumeControl":false,"title":"Wherever You Are","artist":"Neil Finn","album":"One Nil","codec":"flac","trackType":"Mellow Mix"} Aug 26 15:55:32 primo volumio[3266]: info: CoreCommandRouter::servicePushState Aug 26 15:55:32 primo volumio[3266]: info: CoreStateMachine::pushState Aug 26 15:55:32 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 26 15:55:32 primo volumio[3266]: info: CoreCommandRouter::volumioPushState Aug 26 15:55:32 primo volumio[3266]: info: CoreCommandRouter::volumioGetState Aug 26 15:55:32 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Send IPC command: {"command":["loadfile","https://audio.radioparadise.stream/audio/blocks/1/x/1195/4/b/1195-0.flac","replace","start=525.851"],"request_id":17} Aug 26 15:55:32 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:32.779+04:00 level=ERROR msg="failed to unmarshal pushState event" component=volumio/socket error="json: cannot unmarshal number 273.875 into Go struct field State.duration of type int" Aug 26 15:55:32 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Got response for command #17: {"data":{"playlist_entry_id":2},"request_id":17,"error":"success"} Aug 26 15:55:32 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Status update -> property-change events: [{"subscriptionId":3,"prop":"idle-active","data":false},{"subscriptionId":8,"prop":"media-title","data":"1195-0.flac"}] Aug 26 15:55:32 primo volumio[3266]: info: CoreCommandRouter::volumioGetState Aug 26 15:55:32 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Send IPC command: {"command":["set_property","pause",false],"request_id":18} Aug 26 15:55:32 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Push Volumio state: {"status":"play","uri":"rp2/channel@id=1","title":"Wherever You Are","artist":"Neil Finn","album":"One Nil","albumart":"https://img.radioparadise.com/covers/l/19824.jpg","trackType":"Mellow Mix","duration":273.875,"service":"rp2","seek":0,"stream":false,"repeat":false,"repeatSingle":false,"random":false,"volume":100,"mute":false,"disableVolumeControl":false,"codec":"flac"} Aug 26 15:55:32 primo volumio[3266]: info: CoreCommandRouter::servicePushState Aug 26 15:55:32 primo volumio[3266]: info: CoreStateMachine::pushState Aug 26 15:55:32 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 26 15:55:32 primo volumio[3266]: info: CoreCommandRouter::volumioPushState Aug 26 15:55:32 primo volumio[3266]: info: CoreCommandRouter::volumioGetState Aug 26 15:55:32 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:32.799+04:00 level=ERROR msg="failed to unmarshal pushState event" component=volumio/socket error="json: cannot unmarshal number 273.875 into Go struct field State.duration of type int" Aug 26 15:55:32 primo volumio[3266]: info: Signalling Playback active due to playback status change Aug 26 15:55:32 primo volumio[3266]: info: Updating RAAT Signal Path Aug 26 15:55:32 primo volumio[3266]: info: Updating RAAT Signal Path Aug 26 15:55:32 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Got response for command #18: {"request_id":18,"error":"success"} Aug 26 15:55:32 primo volumio[3266]: info: MCU Signalled Playback Inactive Aug 26 15:55:32 primo volumio[3266]: info: MCU Signalled Playback Active Aug 26 15:55:33 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) (+) Audio --aid=1 (flac 2ch 44100Hz) Aug 26 15:55:33 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Status update -> property-change events: [{"subscriptionId":2,"prop":"duration","data":1858.722993},{"subscriptionId":7,"prop":"audio-codec-name","data":"flac"},{"subscriptionId":9,"prop":"metadata","data":{}}] Aug 26 15:55:33 primo volumio[3266]: info: CoreCommandRouter::volumioGetState Aug 26 15:55:33 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Push Volumio state: {"status":"play","uri":"rp2/channel@id=1","title":"Wherever You Are","artist":"Neil Finn","album":"One Nil","albumart":"https://img.radioparadise.com/covers/l/19824.jpg","trackType":"Mellow Mix","duration":273.875,"service":"rp2","seek":84552,"stream":false,"repeat":false,"repeatSingle":false,"random":false,"volume":100,"mute":false,"disableVolumeControl":false,"codec":"flac"} Aug 26 15:55:33 primo volumio[3266]: info: CoreCommandRouter::servicePushState Aug 26 15:55:33 primo volumio[3266]: info: CoreStateMachine::pushState Aug 26 15:55:33 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 26 15:55:33 primo volumio[3266]: info: CoreCommandRouter::volumioPushState Aug 26 15:55:33 primo volumio[3266]: info: CoreCommandRouter::volumioGetState Aug 26 15:55:33 primo volumio[3266]: verbose: [rp2] Received player event "playing"... Aug 26 15:55:33 primo volumio[3266]: info: [rp2] Started playback of "Wherever You Are" - estimated finish time: 8/26/2026, 3:58:42 PM Aug 26 15:55:33 primo volumio[3266]: info: CoreCommandRouter::volumioGetState Aug 26 15:55:33 primo volumio[3266]: verbose: [rp2] After "Wherever You Are", the next track will start in 3m 9s (8/26/2026, 3:58:42 PM) Aug 26 15:55:33 primo volumio[3266]: verbose: [rp2] API: https://api.radioparadise.com/api/update_history?source=24&song_id=33232&chan=1&player_id=********&event=2927580&type=M&slice_num=2&episode_id=0&time_relative=-85&play_position_millis=84552&playtime_secs=1787745334 Aug 26 15:55:33 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:33.203+04:00 level=ERROR msg="failed to unmarshal pushState event" component=volumio/socket error="json: cannot unmarshal number 273.875 into Go struct field State.duration of type int" Aug 26 15:55:33 primo volumio[3266]: info: Signalling Playback active due to playback status change Aug 26 15:55:33 primo volumio[3266]: info: Updating RAAT Signal Path Aug 26 15:55:35 primo volumio[3266]: verbose: [rp2] Checking if next track interval requires adjusting (1/5)... Aug 26 15:55:35 primo volumio[3266]: verbose: [rp2] Recalculated next track interval exceeds current by 2001ms. Going to re-adjust. Aug 26 15:55:36 primo kernel: aml_tdm_open Aug 26 15:55:36 primo kernel: Not init audio effects Aug 26 15:55:36 primo kernel: audio_ddr_mngr: frddrs[0] registered by device ff660000.audiobus:tdm@1 Aug 26 15:55:36 primo kernel: aml_dai_set_tdm_sysclk(), mpll no change, keep clk Aug 26 15:55:36 primo kernel: aml_dai_set_tdm_sysclk(), mclk no change, keep clk Aug 26 15:55:36 primo kernel: set mclk:11289600, mpll:22579200, get mclk:11289593, mpll:22579186 Aug 26 15:55:36 primo kernel: asoc aml_dai_set_tdm_fmt, 0x4001, ffffffc03d365e18, id(1), clksel(1) Aug 26 15:55:36 primo kernel: aml_dai_set_tdm_fmt(), fmt not change Aug 26 15:55:36 primo kernel: dump_pcm_setting(ffffffc03d365e18) Aug 26 15:55:36 primo kernel: pcm_mode(1) Aug 26 15:55:36 primo kernel: sysclk(11289600) Aug 26 15:55:36 primo kernel: sysclk_bclk_ratio(4) Aug 26 15:55:36 primo kernel: bclk(2822400) Aug 26 15:55:36 primo kernel: bclk_lrclk_ratio(64) Aug 26 15:55:36 primo kernel: lrclk(44100) Aug 26 15:55:36 primo kernel: tx_mask(0x3) Aug 26 15:55:36 primo kernel: rx_mask(0x3) Aug 26 15:55:36 primo kernel: slots(2) Aug 26 15:55:36 primo kernel: slot_width(32) Aug 26 15:55:36 primo kernel: lane_mask_in(0x2) Aug 26 15:55:36 primo kernel: lane_mask_out(0x1) Aug 26 15:55:36 primo kernel: lane_oe_mask_in(0x0) Aug 26 15:55:36 primo kernel: lane_oe_mask_out(0x0) Aug 26 15:55:36 primo kernel: lane_lb_mask_in(0x0) Aug 26 15:55:36 primo kernel: aml_dai_set_tdm_sysclk(), mpll no change, keep clk Aug 26 15:55:36 primo kernel: aml_dai_set_tdm_sysclk(), mclk no change, keep clk Aug 26 15:55:36 primo kernel: set mclk:11289600, mpll:22579200, get mclk:11289593, mpll:22579186 Aug 26 15:55:36 primo kernel: aml_dai_set_clkdiv, div 4, clksel(1) Aug 26 15:55:36 primo kernel: aml_dai_set_bclk_ratio, select I2S mode Aug 26 15:55:36 primo kernel: aml_dai_tdm_hw_params(), enable mclk for TDM-B Aug 26 15:55:36 primo kernel: aml_tdm_prepare(), reset fddr Aug 26 15:55:36 primo kernel: spdif_a fifo ctrl, frddr:0 type:1, 16 bits, chmask 0x3, swap 0x10 Aug 26 15:55:36 primo kernel: spdif_info: rate: 44100, channel status ch0_l:0x100, ch0_r:0x100, ch1_l:0x0, ch1_r:0x0 Aug 26 15:55:36 primo kernel: audio_ddr_mngr: frddr_set_sharebuffer_enable sel:1, dst_src:3 Aug 26 15:55:36 primo kernel: tdm playback mute: 0, lane_cnt = 8 Aug 26 15:55:36 primo kernel: aml_tdm_prepare(), reset fddr Aug 26 15:55:36 primo kernel: spdif_a fifo ctrl, frddr:0 type:1, 16 bits, chmask 0x3, swap 0x10 Aug 26 15:55:36 primo kernel: spdif_info: rate: 44100, channel status ch0_l:0x100, ch0_r:0x100, ch1_l:0x0, ch1_r:0x0 Aug 26 15:55:36 primo kernel: audio_ddr_mngr: frddr_set_sharebuffer_enable sel:1, dst_src:3 Aug 26 15:55:36 primo kernel: tdm playback mute: 0, lane_cnt = 8 Aug 26 15:55:36 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) AO: [alsa] 44100Hz stereo 2ch s16 Aug 26 15:55:36 primo kernel: asoc-aml-card auge_sound: tdm playback enable Aug 26 15:55:36 primo kernel: spdif_a is set to enable Aug 26 15:55:36 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Status update -> property-change events: [{"subscriptionId":6,"prop":"audio-params","data":{"samplerate":44100,"channel-count":2,"channels":"stereo","hr-channels":"stereo","format":"s16"}}] Aug 26 15:55:36 primo volumio[3266]: info: CoreCommandRouter::volumioGetState Aug 26 15:55:36 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Push Volumio state: {"status":"play","uri":"rp2/channel@id=1","title":"Wherever You Are","artist":"Neil Finn","album":"One Nil","albumart":"https://img.radioparadise.com/covers/l/19824.jpg","trackType":"Mellow Mix - ","duration":273.875,"samplerate":"44.1 kHz","bitdepth":"16-bit","channels":2,"service":"rp2","seek":84552,"stream":false,"repeat":false,"repeatSingle":false,"random":false,"volume":100,"mute":false,"disableVolumeControl":false,"codec":"flac"} Aug 26 15:55:36 primo volumio[3266]: info: CoreCommandRouter::servicePushState Aug 26 15:55:36 primo volumio[3266]: info: CoreStateMachine::pushState Aug 26 15:55:36 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 26 15:55:36 primo volumio[3266]: info: CoreCommandRouter::volumioPushState Aug 26 15:55:36 primo volumio[3266]: info: CoreCommandRouter::volumioGetState Aug 26 15:55:36 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:36.066+04:00 level=ERROR msg="failed to unmarshal pushState event" component=volumio/socket error="json: cannot unmarshal number 273.875 into Go struct field State.duration of type int" Aug 26 15:55:36 primo volumio[3266]: info: Signalling Playback active due to playback status change Aug 26 15:55:36 primo volumio[3266]: info: Updating RAAT Signal Path Aug 26 15:55:37 primo volumio[3266]: verbose: [rp2] Checking if next track interval requires adjusting (2/5)... Aug 26 15:55:37 primo volumio[3266]: verbose: [rp2] Recalculated next track interval exceeds current by 874.3830000000307ms. Going to re-adjust. Aug 26 15:55:39 primo volumio[3266]: verbose: [rp2] Checking if next track interval requires adjusting (3/5)... Aug 26 15:55:39 primo volumio[3266]: verbose: [rp2] Next track interval is accurate Aug 26 15:55:41 primo volumio[3266]: verbose: [rp2] Checking if next track interval requires adjusting (4/5)... Aug 26 15:55:41 primo volumio[3266]: verbose: [rp2] Next track interval is accurate Aug 26 15:55:43 primo volumio[3266]: verbose: [rp2] Checking if next track interval requires adjusting (5/5)... Aug 26 15:55:43 primo volumio[3266]: verbose: [rp2] Next track interval is accurate Aug 26 15:55:44 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:44.212+04:00 level=INFO msg="check connectivity" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.100.4:50459 @ 0x2680150" latency=-374.027642ms timeout=10s Aug 26 15:55:44 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:44.281+04:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.100.4:50459 @ 0x2680150" latency=-374.027642ms timeout=10s endpoint=https://radio-directory.firebaseapp.com duration=69.264709ms Aug 26 15:55:44 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:44.296+04:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.100.4:50459 @ 0x2680150" latency=-374.027642ms timeout=10s endpoint=https://browsing-performer.dfs.volumio.org duration=81.741958ms Aug 26 15:55:44 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:44.299+04:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.100.4:50459 @ 0x2680150" latency=-374.027642ms timeout=10s endpoint=http://pushupdates.volumio.org duration=81.227959ms Aug 26 15:55:44 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:44.306+04:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.100.4:50459 @ 0x2680150" latency=-374.027642ms timeout=10s endpoint=https://oauth-performer.dfs.volumio.org duration=92.317792ms Aug 26 15:55:44 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:44.383+04:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.100.4:50459 @ 0x2680150" latency=-374.027642ms timeout=10s endpoint=https://www.googleapis.com duration=169.987958ms Aug 26 15:55:44 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:44.407+04:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.100.4:50459 @ 0x2680150" latency=-374.027642ms timeout=10s endpoint=https://myvolumio.firebaseio.com duration=193.502208ms Aug 26 15:55:44 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:44.422+04:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.100.4:50459 @ 0x2680150" latency=-374.027642ms timeout=10s endpoint=https://functions.volumio.cloud duration=208.333875ms Aug 26 15:55:44 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:44.425+04:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.100.4:50459 @ 0x2680150" latency=-374.027642ms timeout=10s endpoint=https://securetoken.googleapis.com duration=212.69ms Aug 26 15:55:44 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:44.426+04:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.100.4:50459 @ 0x2680150" latency=-374.027642ms timeout=10s endpoint=https://database.volumio.cloud duration=208.539834ms Aug 26 15:55:44 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:44.560+04:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.100.4:50459 @ 0x2680150" latency=-374.027642ms timeout=10s endpoint=https://functions.volumio.cloud duration=342.857833ms Aug 26 15:55:44 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:44.673+04:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.100.4:50459 @ 0x2680150" latency=-374.027642ms timeout=10s endpoint=https://google.com duration=461.038042ms Aug 26 15:55:44 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:44.783+04:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.100.4:50459 @ 0x2680150" latency=-374.027642ms timeout=10s endpoint=http://cddb.volumio.org duration=568.658208ms Aug 26 15:55:44 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:44.894+04:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.100.4:50459 @ 0x2680150" latency=-374.027642ms timeout=10s endpoint=http://plugins.volumio.org duration=677.110667ms Aug 26 15:55:45 primo volumio[3266]: info: Preload queue cleared Aug 26 15:55:45 primo volumio[3266]: info: CoreCommandRouter::volumioReplaceandPlayItems Aug 26 15:55:45 primo volumio[3266]: info: CoreStateMachine::ClearQueue Aug 26 15:55:45 primo volumio[3266]: info: CoreStateMachine::stop Aug 26 15:55:45 primo volumio[3266]: info: CoreStateMachine::serviceStop Aug 26 15:55:45 primo volumio[3266]: info: CoreCommandRouter::serviceStop Aug 26 15:55:45 primo volumio[3266]: info: CoreStateMachine::stPlaybackTimer Aug 26 15:55:45 primo volumio[3266]: info: CoreStateMachine::updateTrackBlock Aug 26 15:55:45 primo volumio[3266]: info: CorePlayQueue::getTrackBlock Aug 26 15:55:45 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Send IPC command: {"command":["stop"],"request_id":19} Aug 26 15:55:45 primo volumio[3266]: verbose: [rp2] Waiting for player event "stopped"... Aug 26 15:55:45 primo volumio[3266]: info: CorePlayQueue::clearPlayQueue Aug 26 15:55:45 primo volumio[3266]: info: CorePlayQueue::saveQueue Aug 26 15:55:45 primo volumio[3266]: info: CoreCommandRouter::volumioPushQueue Aug 26 15:55:45 primo kernel: asoc-aml-card auge_sound: tdm playback stop Aug 26 15:55:45 primo kernel: spdif_a is set to disable Aug 26 15:55:45 primo kernel: aml_tdm_prepare(), reset fddr Aug 26 15:55:45 primo kernel: spdif_a fifo ctrl, frddr:0 type:1, 16 bits, chmask 0x3, swap 0x10 Aug 26 15:55:45 primo kernel: spdif_info: rate: 44100, channel status ch0_l:0x100, ch0_r:0x100, ch1_l:0x0, ch1_r:0x0 Aug 26 15:55:45 primo kernel: audio_ddr_mngr: frddr_set_sharebuffer_enable sel:1, dst_src:3 Aug 26 15:55:45 primo kernel: tdm playback mute: 0, lane_cnt = 8 Aug 26 15:55:45 primo volumio[3266]: info: CoreStateMachine::addQueueItems Aug 26 15:55:45 primo volumio[3266]: info: CorePlayQueue::addQueueItems Aug 26 15:55:45 primo volumio[3266]: info: Preload queue cleared Aug 26 15:55:45 primo volumio[3266]: info: Adding Item to queue: rp2/channel@qi=%7B%22service%22%3A%22rp2%22%2C%22uri%22%3A%22rp2%2Fchannel%40id%3D2%22%2C%22name%22%3A%22RockIt!%22%2C%22title%22%3A%22RockIt!%22%2C%22artist%22%3A%22Radio%20Paradise%22%2C%22albumart%22%3A%22https%3A%2F%2Fimg.radioparadise.com%2Fchannels%2F0%2F2%2Fcover_512x512%2F0.jpg%22%7D Aug 26 15:55:45 primo volumio[3266]: info: Exploding uri rp2/channel@qi=%7B%22service%22%3A%22rp2%22%2C%22uri%22%3A%22rp2%2Fchannel%40id%3D2%22%2C%22name%22%3A%22RockIt!%22%2C%22title%22%3A%22RockIt!%22%2C%22artist%22%3A%22Radio%20Paradise%22%2C%22albumart%22%3A%22https%3A%2F%2Fimg.radioparadise.com%2Fchannels%2F0%2F2%2Fcover_512x512%2F0.jpg%22%7D in service rp2 Aug 26 15:55:45 primo volumio[3266]: info: CoreCommandRouter::volumioPushQueue Aug 26 15:55:45 primo volumio[3266]: info: CorePlayQueue::saveQueue Aug 26 15:55:45 primo volumio[3266]: info: CoreStateMachine::updateTrackBlock Aug 26 15:55:45 primo volumio[3266]: info: CorePlayQueue::getTrackBlock Aug 26 15:55:45 primo volumio[3266]: info: CoreCommandRouter::volumioGetState Aug 26 15:55:45 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: play , [object Object] Aug 26 15:55:45 primo volumio[3266]: info: CoreCommandRouter::volumioPlay Aug 26 15:55:45 primo volumio[3266]: verbose: UNSET VOLATILE: Service: rp2 Aug 26 15:55:45 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Volatile state unset, stopping playback (if any)... Aug 26 15:55:45 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Push Volumio state: {"status":"stop","albumart":"https://img.radioparadise.com/covers/l/19824.jpg","uri":"rp2/channel@id=1","seek":93934.31099999999,"duration":273.875,"service":"rp2","stream":false,"repeat":false,"repeatSingle":false,"random":false,"volume":100,"mute":false,"disableVolumeControl":false,"title":"Wherever You Are","artist":"Neil Finn","album":"One Nil","codec":"flac","trackType":"Mellow Mix"} Aug 26 15:55:45 primo volumio[3266]: info: CoreCommandRouter::servicePushState Aug 26 15:55:45 primo volumio[3266]: info: CoreStateMachine::pushState Aug 26 15:55:45 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 26 15:55:45 primo volumio[3266]: info: CoreCommandRouter::volumioPushState Aug 26 15:55:45 primo volumio[3266]: info: CoreCommandRouter::volumioGetState Aug 26 15:55:45 primo volumio[3266]: info: CorePlayQueue::getTrack 0 Aug 26 15:55:45 primo volumio[3266]: verbose: STATE SERVICE {"status":"stop","albumart":"https://img.radioparadise.com/covers/l/19824.jpg","uri":"rp2/channel@id=1","seek":93934.31099999999,"duration":273.875,"service":"rp2","stream":false,"repeat":false,"repeatSingle":false,"random":false,"volume":100,"mute":false,"disableVolumeControl":false,"title":"Wherever You Are","artist":"Neil Finn","album":"One Nil","codec":"flac","trackType":"Mellow Mix"} Aug 26 15:55:45 primo volumio[3266]: verbose: CURRENT POSITION 0 Aug 26 15:55:45 primo volumio[3266]: info: CoreStateMachine::syncState stateService stop Aug 26 15:55:45 primo volumio[3266]: info: CoreStateMachine::syncState currentStatus stop Aug 26 15:55:45 primo volumio[3266]: info: CoreStateMachine::pushState Aug 26 15:55:45 primo volumio[3266]: info: CoreCommandRouter::volumioPushState Aug 26 15:55:45 primo volumio[3266]: info: CoreCommandRouter::volumioGetState Aug 26 15:55:45 primo volumio[3266]: info: No code Aug 26 15:55:45 primo volumio[3266]: info: CoreStateMachine::pushState Aug 26 15:55:45 primo volumio[3266]: info: CoreCommandRouter::volumioPushState Aug 26 15:55:45 primo volumio[3266]: info: CoreCommandRouter::volumioGetState Aug 26 15:55:45 primo volumio[3266]: MPVPlayer onunsetVolatile called Aug 26 15:55:45 primo volumio[3266]: MPVPlayer calling onunsetVolatile callbacks Aug 26 15:55:45 primo volumio[3266]: verbose: [rp2] Waiting for player event "stopped"... Aug 26 15:55:45 primo volumio[3266]: info: CoreStateMachine::play index 0 Aug 26 15:55:45 primo volumio[3266]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 26 15:55:45 primo volumio[3266]: info: CoreStateMachine::stop Aug 26 15:55:45 primo volumio[3266]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 26 15:55:45 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:45.495+04:00 level=ERROR msg="failed to unmarshal pushState event" component=volumio/socket error="json: cannot unmarshal number 93934.31099999999 into Go struct field State.seek of type int" Aug 26 15:55:45 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:45.496+04:00 level=ERROR msg="failed to unmarshal pushState event" component=volumio/socket error="json: cannot unmarshal number 93934.31099999999 into Go struct field State.seek of type int" Aug 26 15:55:45 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:45.497+04:00 level=ERROR msg="failed to unmarshal pushState event" component=volumio/socket error="json: cannot unmarshal number 93934.31099999999 into Go struct field State.seek of type int" Aug 26 15:55:45 primo volumio[3266]: info: CoreStateMachine::play index undefined Aug 26 15:55:45 primo volumio[3266]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 26 15:55:45 primo volumio[3266]: info: CorePlayQueue::getTrack 0 Aug 26 15:55:45 primo volumio[3266]: info: CoreStateMachine::startPlaybackTimer Aug 26 15:55:45 primo volumio[3266]: info: CorePlayQueue::getTrack 0 Aug 26 15:55:45 primo volumio[3266]: info: CoreCommandRouter::volumioGetVisibleSources Aug 26 15:55:45 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 26 15:55:45 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Aug 26 15:55:45 primo volumio[3266]: info: [rp2] clearAddPlayTrack: rp2/channel@id=2 Aug 26 15:55:45 primo volumio[3266]: verbose: [rp2] Received player event "stopped"... Aug 26 15:55:45 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Got response for command #19: {"data":null,"request_id":19,"error":"success"} Aug 26 15:55:45 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Status update -> property-change events: [{"subscriptionId":6,"prop":"audio-params"},{"subscriptionId":7,"prop":"audio-codec-name"}] Aug 26 15:55:45 primo volumio[3266]: info: Signalling Playback active due to playback status change Aug 26 15:55:45 primo kernel: audio_ddr_mngr: frddr_set_sharebuffer_enable sel:1, dst_src:3 Aug 26 15:55:45 primo kernel: aml_dai_tdm_hw_free(), disable mclk for TDM-B Aug 26 15:55:45 primo kernel: tdm playback mute: 1, lane_cnt = 8 Aug 26 15:55:45 primo kernel: audio_ddr_mngr: frddrs[0] released by device ff660000.audiobus:tdm@1 Aug 26 15:55:45 primo volumio[3266]: info: Signalling Playback active due to playback status change Aug 26 15:55:45 primo volumio[3266]: info: Signalling Playback active due to playback status change Aug 26 15:55:45 primo volumio[3266]: info: Updating RAAT Signal Path Aug 26 15:55:45 primo volumio[3266]: info: Updating RAAT Signal Path Aug 26 15:55:45 primo volumio[3266]: info: Updating RAAT Signal Path Aug 26 15:55:45 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Status update -> property-change events: [{"subscriptionId":2,"prop":"duration"},{"subscriptionId":3,"prop":"idle-active","data":true},{"subscriptionId":8,"prop":"media-title"},{"subscriptionId":9,"prop":"metadata"}] Aug 26 15:55:45 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Player status "stopped" - unsetting ourselves as current service... Aug 26 15:55:45 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Aug 26 15:55:46 primo volumio[3266]: verbose: [rp2] API: https://api.radioparadise.com/api/play?source=24&event=0&elapsed=0&bitrate=4&action=start&player_id=********&info=true&chan=2&audio_type= Aug 26 15:55:46 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 26 15:55:46 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 26 15:55:46 primo volumio[3266]: info: Discovery: Getting this device information Aug 26 15:55:46 primo volumio[3266]: info: CoreCommandRouter::volumioGetState Aug 26 15:55:46 primo volumio[3266]: info: CorePlayQueue::getTrack 0 Aug 26 15:55:46 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 26 15:55:46 primo volumio[3266]: verbose: New Socket.io Connection to 192.168.100.5:3000 from 192.168.100.4 UA: Dart/3.12 (dart:io) Engine version: 3 Transport: websocket Total Clients: 10 Aug 26 15:55:46 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Aug 26 15:55:46 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Aug 26 15:55:47 primo volumio[3266]: info: [rp2] Obtained block for channel "2" Aug 26 15:55:47 primo volumio[3266]: info: [rp2] ------------- Aug 26 15:55:47 primo volumio[3266]: info: [rp2] Block summary Aug 26 15:55:47 primo volumio[3266]: info: [rp2] ------------- Aug 26 15:55:47 primo volumio[3266]: info: [rp2] Stream URL: https://audio.radioparadise.stream/audio/blocks/2/x/1144/4/b/1144-0.flac Aug 26 15:55:47 primo volumio[3266]: info: [rp2] Tracks: Aug 26 15:55:47 primo volumio[3266]: info: [rp2] 0. Shine A Little Light (3:11 | elapsed: 25m 7s) Aug 26 15:55:47 primo volumio[3266]: info: [rp2] Aug 26 15:55:47 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Player status "stopped" - skip unset volatile because unset condition is "manual" Aug 26 15:55:47 primo volumio[3266]: verbose: [rp2] Current track scheduled playback vs. current time: 8/26/2026, 3:52:36 PM <-> 8/26/2026, 3:55:47 PM Aug 26 15:55:47 primo volumio[3266]: info: [rp2] Going to start playback of current track at 3:11 (track position in stream: 25:07) Aug 26 15:55:47 primo volumio[3266]: verbose: [rp2] Waiting for player event "playing"... Aug 26 15:55:47 primo volumio[3266]: info: CoreCommandRouter::volumioGetState Aug 26 15:55:47 primo volumio[3266]: info: CorePlayQueue::getTrack 0 Aug 26 15:55:47 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Stopping playback by current service... Aug 26 15:55:47 primo volumio[3266]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 26 15:55:47 primo volumio[3266]: info: CoreCommandRouter::volumioStop Aug 26 15:55:47 primo volumio[3266]: info: CoreStateMachine::stop Aug 26 15:55:47 primo volumio[3266]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 26 15:55:47 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Setting ourselves as the current service... Aug 26 15:55:47 primo volumio[3266]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 26 15:55:47 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Send IPC command: {"command":["set_property","loop-file","no"],"request_id":20} Aug 26 15:55:47 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Got response for command #20: {"request_id":20,"error":"success"} Aug 26 15:55:47 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Push Volumio state: {"status":"pause","albumart":"https://img.radioparadise.com/covers/l/17932.jpg","uri":"rp2/channel@id=2","seek":0,"duration":191.823,"service":"rp2","stream":false,"repeat":false,"repeatSingle":false,"random":false,"volume":100,"mute":false,"disableVolumeControl":false,"title":"Shine A Little Light","artist":"The Black Keys","album":"“Let’s Rock”","codec":"flac","trackType":"RockIt!"} Aug 26 15:55:47 primo volumio[3266]: info: CoreCommandRouter::servicePushState Aug 26 15:55:47 primo volumio[3266]: info: CoreStateMachine::pushState Aug 26 15:55:47 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 26 15:55:47 primo volumio[3266]: info: CoreCommandRouter::volumioPushState Aug 26 15:55:47 primo volumio[3266]: info: CoreCommandRouter::volumioGetState Aug 26 15:55:47 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Send IPC command: {"command":["loadfile","https://audio.radioparadise.stream/audio/blocks/2/x/1144/4/b/1144-0.flac","replace","start=1698.538"],"request_id":21} Aug 26 15:55:47 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:47.043+04:00 level=ERROR msg="failed to unmarshal pushState event" component=volumio/socket error="json: cannot unmarshal number 191.823 into Go struct field State.duration of type int" Aug 26 15:55:47 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Got response for command #21: {"data":{"playlist_entry_id":3},"request_id":21,"error":"success"} Aug 26 15:55:47 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Status update -> property-change events: [{"subscriptionId":3,"prop":"idle-active","data":false},{"subscriptionId":8,"prop":"media-title","data":"1144-0.flac"}] Aug 26 15:55:47 primo volumio[3266]: info: CoreCommandRouter::volumioGetState Aug 26 15:55:47 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Send IPC command: {"command":["set_property","pause",false],"request_id":22} Aug 26 15:55:47 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Push Volumio state: {"status":"play","uri":"rp2/channel@id=2","title":"Shine A Little Light","artist":"The Black Keys","album":"“Let’s Rock”","albumart":"https://img.radioparadise.com/covers/l/17932.jpg","trackType":"RockIt!","duration":191.823,"service":"rp2","seek":0,"stream":false,"repeat":false,"repeatSingle":false,"random":false,"volume":100,"mute":false,"disableVolumeControl":false,"codec":"flac"} Aug 26 15:55:47 primo volumio[3266]: info: CoreCommandRouter::servicePushState Aug 26 15:55:47 primo volumio[3266]: info: CoreStateMachine::pushState Aug 26 15:55:47 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 26 15:55:47 primo volumio[3266]: info: CoreCommandRouter::volumioPushState Aug 26 15:55:47 primo volumio[3266]: info: CoreCommandRouter::volumioGetState Aug 26 15:55:47 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:47.061+04:00 level=ERROR msg="failed to unmarshal pushState event" component=volumio/socket error="json: cannot unmarshal number 191.823 into Go struct field State.duration of type int" Aug 26 15:55:47 primo volumio[3266]: info: Signalling Playback active due to playback status change Aug 26 15:55:47 primo volumio[3266]: info: Updating RAAT Signal Path Aug 26 15:55:47 primo volumio[3266]: info: Updating RAAT Signal Path Aug 26 15:55:47 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Got response for command #22: {"request_id":22,"error":"success"} Aug 26 15:55:47 primo volumio[3266]: info: MCU Signalled Playback Inactive Aug 26 15:55:47 primo volumio[3266]: info: MCU Signalled Playback Active Aug 26 15:55:47 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) (+) Audio --aid=1 (flac 2ch 44100Hz) Aug 26 15:55:47 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Status update -> property-change events: [{"subscriptionId":2,"prop":"duration","data":1699.34},{"subscriptionId":7,"prop":"audio-codec-name","data":"flac"},{"subscriptionId":9,"prop":"metadata","data":{}}] Aug 26 15:55:47 primo volumio[3266]: info: CoreCommandRouter::volumioGetState Aug 26 15:55:47 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Push Volumio state: {"status":"play","uri":"rp2/channel@id=2","title":"Shine A Little Light","artist":"The Black Keys","album":"“Let’s Rock”","albumart":"https://img.radioparadise.com/covers/l/17932.jpg","trackType":"RockIt!","duration":191.823,"service":"rp2","seek":191022,"stream":false,"repeat":false,"repeatSingle":false,"random":false,"volume":100,"mute":false,"disableVolumeControl":false,"codec":"flac"} Aug 26 15:55:47 primo volumio[3266]: info: CoreCommandRouter::servicePushState Aug 26 15:55:47 primo volumio[3266]: info: CoreStateMachine::pushState Aug 26 15:55:47 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 26 15:55:47 primo volumio[3266]: info: CoreCommandRouter::volumioPushState Aug 26 15:55:47 primo volumio[3266]: info: CoreCommandRouter::volumioGetState Aug 26 15:55:47 primo volumio[3266]: verbose: [rp2] Received player event "playing"... Aug 26 15:55:47 primo volumio[3266]: info: [rp2] Started playback of "Shine A Little Light" - estimated finish time: 8/26/2026, 3:55:48 PM Aug 26 15:55:47 primo volumio[3266]: info: CoreCommandRouter::volumioGetState Aug 26 15:55:47 primo volumio[3266]: verbose: [rp2] After "Shine A Little Light", prepare to fetch the next block in 0s (8/26/2026, 3:55:48 PM) Aug 26 15:55:47 primo volumio[3266]: verbose: [rp2] API: https://api.radioparadise.com/api/update_history?source=24&song_id=45008&chan=2&player_id=********&event=2824549&type=M&slice_num=7&episode_id=0&time_relative=-192&play_position_millis=191022&playtime_secs=1787745348 Aug 26 15:55:47 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:47.470+04:00 level=ERROR msg="failed to unmarshal pushState event" component=volumio/socket error="json: cannot unmarshal number 191.823 into Go struct field State.duration of type int" Aug 26 15:55:47 primo volumio[3266]: info: Signalling Playback active due to playback status change Aug 26 15:55:47 primo volumio[3266]: info: Updating RAAT Signal Path Aug 26 15:55:48 primo volumio[3266]: info: [rp2] About to reach end of stream in current block. Going to obtain next block. Aug 26 15:55:48 primo volumio[3266]: verbose: [rp2] Waiting for player to stop before fetching next block... Aug 26 15:55:48 primo volumio[3266]: verbose: [rp2] Waiting for player event "stopped"... Aug 26 15:55:48 primo kernel: aml_tdm_open Aug 26 15:55:48 primo kernel: Not init audio effects Aug 26 15:55:48 primo kernel: audio_ddr_mngr: frddrs[0] registered by device ff660000.audiobus:tdm@1 Aug 26 15:55:48 primo kernel: aml_dai_set_tdm_sysclk(), mpll no change, keep clk Aug 26 15:55:48 primo kernel: aml_dai_set_tdm_sysclk(), mclk no change, keep clk Aug 26 15:55:48 primo kernel: set mclk:11289600, mpll:22579200, get mclk:11289593, mpll:22579186 Aug 26 15:55:48 primo kernel: asoc aml_dai_set_tdm_fmt, 0x4001, ffffffc03d365e18, id(1), clksel(1) Aug 26 15:55:48 primo kernel: aml_dai_set_tdm_fmt(), fmt not change Aug 26 15:55:48 primo kernel: dump_pcm_setting(ffffffc03d365e18) Aug 26 15:55:48 primo kernel: pcm_mode(1) Aug 26 15:55:48 primo kernel: sysclk(11289600) Aug 26 15:55:48 primo kernel: sysclk_bclk_ratio(4) Aug 26 15:55:48 primo kernel: bclk(2822400) Aug 26 15:55:48 primo kernel: bclk_lrclk_ratio(64) Aug 26 15:55:48 primo kernel: lrclk(44100) Aug 26 15:55:48 primo kernel: tx_mask(0x3) Aug 26 15:55:48 primo kernel: rx_mask(0x3) Aug 26 15:55:48 primo kernel: slots(2) Aug 26 15:55:48 primo kernel: slot_width(32) Aug 26 15:55:48 primo kernel: lane_mask_in(0x2) Aug 26 15:55:48 primo kernel: lane_mask_out(0x1) Aug 26 15:55:48 primo kernel: lane_oe_mask_in(0x0) Aug 26 15:55:48 primo kernel: lane_oe_mask_out(0x0) Aug 26 15:55:48 primo kernel: lane_lb_mask_in(0x0) Aug 26 15:55:48 primo kernel: aml_dai_set_tdm_sysclk(), mpll no change, keep clk Aug 26 15:55:48 primo kernel: aml_dai_set_tdm_sysclk(), mclk no change, keep clk Aug 26 15:55:48 primo kernel: set mclk:11289600, mpll:22579200, get mclk:11289593, mpll:22579186 Aug 26 15:55:48 primo kernel: aml_dai_set_clkdiv, div 4, clksel(1) Aug 26 15:55:48 primo kernel: aml_dai_set_bclk_ratio, select I2S mode Aug 26 15:55:48 primo kernel: aml_dai_tdm_hw_params(), enable mclk for TDM-B Aug 26 15:55:48 primo kernel: aml_tdm_prepare(), reset fddr Aug 26 15:55:48 primo kernel: spdif_a fifo ctrl, frddr:0 type:1, 16 bits, chmask 0x3, swap 0x10 Aug 26 15:55:48 primo kernel: spdif_info: rate: 44100, channel status ch0_l:0x100, ch0_r:0x100, ch1_l:0x0, ch1_r:0x0 Aug 26 15:55:48 primo kernel: audio_ddr_mngr: frddr_set_sharebuffer_enable sel:1, dst_src:3 Aug 26 15:55:48 primo kernel: tdm playback mute: 0, lane_cnt = 8 Aug 26 15:55:48 primo kernel: aml_tdm_prepare(), reset fddr Aug 26 15:55:48 primo kernel: spdif_a fifo ctrl, frddr:0 type:1, 16 bits, chmask 0x3, swap 0x10 Aug 26 15:55:48 primo kernel: spdif_info: rate: 44100, channel status ch0_l:0x100, ch0_r:0x100, ch1_l:0x0, ch1_r:0x0 Aug 26 15:55:48 primo kernel: audio_ddr_mngr: frddr_set_sharebuffer_enable sel:1, dst_src:3 Aug 26 15:55:48 primo kernel: tdm playback mute: 0, lane_cnt = 8 Aug 26 15:55:48 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) AO: [alsa] 44100Hz stereo 2ch s16 Aug 26 15:55:48 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Status update -> property-change events: [{"subscriptionId":6,"prop":"audio-params","data":{"samplerate":44100,"channel-count":2,"channels":"stereo","hr-channels":"stereo","format":"s16"}}] Aug 26 15:55:48 primo volumio[3266]: info: CoreCommandRouter::volumioGetState Aug 26 15:55:48 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Push Volumio state: {"status":"play","uri":"rp2/channel@id=2","title":"Shine A Little Light","artist":"The Black Keys","album":"“Let’s Rock”","albumart":"https://img.radioparadise.com/covers/l/17932.jpg","trackType":"RockIt! - ","duration":191.823,"samplerate":"44.1 kHz","bitdepth":"16-bit","channels":2,"service":"rp2","seek":191022,"stream":false,"repeat":false,"repeatSingle":false,"random":false,"volume":100,"mute":false,"disableVolumeControl":false,"codec":"flac"} Aug 26 15:55:48 primo volumio[3266]: info: CoreCommandRouter::servicePushState Aug 26 15:55:48 primo volumio[3266]: info: CoreStateMachine::pushState Aug 26 15:55:48 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 26 15:55:48 primo volumio[3266]: info: CoreCommandRouter::volumioPushState Aug 26 15:55:48 primo volumio[3266]: info: CoreCommandRouter::volumioGetState Aug 26 15:55:48 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:48.954+04:00 level=ERROR msg="failed to unmarshal pushState event" component=volumio/socket error="json: cannot unmarshal number 191.823 into Go struct field State.duration of type int" Aug 26 15:55:48 primo volumio[3266]: info: CoreCommandRouter::volumioGetState Aug 26 15:55:48 primo volumio[3266]: info: Signalling Playback active due to playback status change Aug 26 15:55:48 primo kernel: asoc-aml-card auge_sound: tdm playback enable Aug 26 15:55:48 primo kernel: spdif_a is set to enable Aug 26 15:55:48 primo volumio[3266]: info: Updating RAAT Signal Path Aug 26 15:55:49 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Status update -> property-change events: [{"subscriptionId":6,"prop":"audio-params"},{"subscriptionId":7,"prop":"audio-codec-name"}] Aug 26 15:55:49 primo volumio[3266]: info: CoreCommandRouter::volumioGetState Aug 26 15:55:49 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Push Volumio state: {"status":"play","uri":"rp2/channel@id=2","title":"Shine A Little Light","artist":"The Black Keys","album":"“Let’s Rock”","albumart":"https://img.radioparadise.com/covers/l/17932.jpg","trackType":"RockIt!","duration":191.823,"service":"rp2","seek":191457.3559999999,"stream":false,"repeat":false,"repeatSingle":false,"random":false,"volume":100,"mute":false,"disableVolumeControl":false,"codec":"flac"} Aug 26 15:55:49 primo volumio[3266]: info: CoreCommandRouter::servicePushState Aug 26 15:55:49 primo volumio[3266]: info: CoreStateMachine::pushState Aug 26 15:55:49 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 26 15:55:49 primo volumio[3266]: info: CoreCommandRouter::volumioPushState Aug 26 15:55:49 primo volumio[3266]: info: CoreCommandRouter::volumioGetState Aug 26 15:55:49 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:49.405+04:00 level=ERROR msg="failed to unmarshal pushState event" component=volumio/socket error="json: cannot unmarshal number 191457.3559999999 into Go struct field State.seek of type int" Aug 26 15:55:49 primo volumio[3266]: info: Signalling Playback active due to playback status change Aug 26 15:55:49 primo volumio[3266]: info: Updating RAAT Signal Path Aug 26 15:55:49 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Aug 26 15:55:49 primo kernel: asoc-aml-card auge_sound: tdm playback stop Aug 26 15:55:49 primo kernel: spdif_a is set to disable Aug 26 15:55:49 primo kernel: aml_tdm_prepare(), reset fddr Aug 26 15:55:49 primo kernel: spdif_a fifo ctrl, frddr:0 type:1, 16 bits, chmask 0x3, swap 0x10 Aug 26 15:55:49 primo kernel: spdif_info: rate: 44100, channel status ch0_l:0x100, ch0_r:0x100, ch1_l:0x0, ch1_r:0x0 Aug 26 15:55:49 primo kernel: audio_ddr_mngr: frddr_set_sharebuffer_enable sel:1, dst_src:3 Aug 26 15:55:49 primo kernel: tdm playback mute: 0, lane_cnt = 8 Aug 26 15:55:49 primo kernel: aml_tdm_prepare(), reset fddr Aug 26 15:55:49 primo kernel: spdif_a fifo ctrl, frddr:0 type:1, 16 bits, chmask 0x3, swap 0x10 Aug 26 15:55:49 primo kernel: spdif_info: rate: 44100, channel status ch0_l:0x100, ch0_r:0x100, ch1_l:0x0, ch1_r:0x0 Aug 26 15:55:49 primo kernel: audio_ddr_mngr: frddr_set_sharebuffer_enable sel:1, dst_src:3 Aug 26 15:55:49 primo kernel: tdm playback mute: 0, lane_cnt = 8 Aug 26 15:55:49 primo kernel: audio_ddr_mngr: frddr_set_sharebuffer_enable sel:1, dst_src:3 Aug 26 15:55:49 primo kernel: aml_dai_tdm_hw_free(), disable mclk for TDM-B Aug 26 15:55:49 primo kernel: tdm playback mute: 1, lane_cnt = 8 Aug 26 15:55:49 primo kernel: audio_ddr_mngr: frddrs[0] released by device ff660000.audiobus:tdm@1 Aug 26 15:55:49 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Status update -> property-change events: [{"subscriptionId":2,"prop":"duration"},{"subscriptionId":3,"prop":"idle-active","data":true}] Aug 26 15:55:49 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Player status "stopped" - skip unset volatile because unset condition is "manual" Aug 26 15:55:49 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Player status "stopped" - skip unset volatile because unset condition is "manual" Aug 26 15:55:49 primo volumio[3266]: verbose: [rp2] Received player event "stopped"... Aug 26 15:55:49 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Player status "stopped" - skip unset volatile because unset condition is "manual" Aug 26 15:55:49 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Player status "stopped" - skip unset volatile because unset condition is "manual" Aug 26 15:55:49 primo volumio[3266]: verbose: [rp2] API: https://api.radioparadise.com/api/play?source=24&event=2824549&elapsed=1&bitrate=4&action=play&player_id=********&info=true&chan=2&slice_num=7&episode_id=0&audio_type=M Aug 26 15:55:49 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Status update -> property-change events: [{"subscriptionId":8,"prop":"media-title"},{"subscriptionId":9,"prop":"metadata"}] Aug 26 15:55:49 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Player status "stopped" - skip unset volatile because unset condition is "manual" Aug 26 15:55:50 primo volumio[3266]: info: [rp2] Obtained updated block Aug 26 15:55:50 primo volumio[3266]: info: [rp2] ------------- Aug 26 15:55:50 primo volumio[3266]: info: [rp2] Block summary Aug 26 15:55:50 primo volumio[3266]: info: [rp2] ------------- Aug 26 15:55:50 primo volumio[3266]: info: [rp2] Stream URL: https://audio.radioparadise.stream/audio/promos/2/4/288.flac?2824550 Aug 26 15:55:50 primo volumio[3266]: info: [rp2] Tracks: Aug 26 15:55:50 primo volumio[3266]: info: [rp2] 0. Listener-supported (0:03 | elapsed: 0s) Aug 26 15:55:50 primo volumio[3266]: info: [rp2] Aug 26 15:55:50 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Player status "stopped" - skip unset volatile because unset condition is "manual" Aug 26 15:55:50 primo volumio[3266]: info: [rp2] Going to start playback of current track Aug 26 15:55:50 primo volumio[3266]: verbose: [rp2] Waiting for player event "playing"... Aug 26 15:55:50 primo volumio[3266]: info: CoreCommandRouter::volumioGetState Aug 26 15:55:50 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Send IPC command: {"command":["set_property","loop-file","no"],"request_id":23} Aug 26 15:55:50 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Got response for command #23: {"request_id":23,"error":"success"} Aug 26 15:55:50 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Push Volumio state: {"status":"pause","albumart":"https://img.radioparadise.com/covers/l/103.jpg","uri":"rp2/channel@id=2","seek":0,"duration":3.273,"service":"rp2","stream":false,"repeat":false,"repeatSingle":false,"random":false,"volume":100,"mute":false,"disableVolumeControl":false,"title":"Listener-supported","artist":"Commercial-free","codec":"flac","trackType":"RockIt!"} Aug 26 15:55:50 primo volumio[3266]: info: CoreCommandRouter::servicePushState Aug 26 15:55:50 primo volumio[3266]: info: CoreStateMachine::pushState Aug 26 15:55:50 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 26 15:55:50 primo volumio[3266]: info: CoreCommandRouter::volumioPushState Aug 26 15:55:50 primo volumio[3266]: info: CoreCommandRouter::volumioGetState Aug 26 15:55:50 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Send IPC command: {"command":["loadfile","https://audio.radioparadise.stream/audio/promos/2/4/288.flac?2824550","replace","start=0"],"request_id":24} Aug 26 15:55:50 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:50.082+04:00 level=ERROR msg="failed to unmarshal pushState event" component=volumio/socket error="json: cannot unmarshal number 3.273 into Go struct field State.duration of type int" Aug 26 15:55:50 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Got response for command #24: {"data":{"playlist_entry_id":4},"request_id":24,"error":"success"} Aug 26 15:55:50 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Status update -> property-change events: [{"subscriptionId":3,"prop":"idle-active","data":false},{"subscriptionId":8,"prop":"media-title","data":"288.flac?2824550"}] Aug 26 15:55:50 primo volumio[3266]: info: CoreCommandRouter::volumioGetState Aug 26 15:55:50 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Send IPC command: {"command":["set_property","pause",false],"request_id":25} Aug 26 15:55:50 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Push Volumio state: {"status":"play","uri":"rp2/channel@id=2","title":"Listener-supported","artist":"Commercial-free","albumart":"https://img.radioparadise.com/covers/l/103.jpg","trackType":"RockIt!","duration":3.273,"service":"rp2","seek":0,"stream":false,"repeat":false,"repeatSingle":false,"random":false,"volume":100,"mute":false,"disableVolumeControl":false,"codec":"flac"} Aug 26 15:55:50 primo volumio[3266]: info: CoreCommandRouter::servicePushState Aug 26 15:55:50 primo volumio[3266]: info: CoreStateMachine::pushState Aug 26 15:55:50 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 26 15:55:50 primo volumio[3266]: info: CoreCommandRouter::volumioPushState Aug 26 15:55:50 primo volumio[3266]: info: CoreCommandRouter::volumioGetState Aug 26 15:55:50 primo volumio[3266]: verbose: [rp2] Received player event "playing"... Aug 26 15:55:50 primo volumio[3266]: info: [rp2] Started playback of "Listener-supported" - estimated finish time: 8/26/2026, 3:55:53 PM Aug 26 15:55:50 primo volumio[3266]: info: CoreCommandRouter::volumioGetState Aug 26 15:55:50 primo volumio[3266]: verbose: [rp2] After "Listener-supported", prepare to fetch the next block in 3s (8/26/2026, 3:55:53 PM) Aug 26 15:55:50 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:50.104+04:00 level=ERROR msg="failed to unmarshal pushState event" component=volumio/socket error="json: cannot unmarshal number 3.273 into Go struct field State.duration of type int" Aug 26 15:55:50 primo volumio[3266]: info: Signalling Playback active due to playback status change Aug 26 15:55:50 primo volumio[3266]: info: Updating RAAT Signal Path Aug 26 15:55:50 primo volumio[3266]: info: Updating RAAT Signal Path Aug 26 15:55:50 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Got response for command #25: {"request_id":25,"error":"success"} Aug 26 15:55:50 primo volumio[3266]: info: MCU Signalled Playback Inactive Aug 26 15:55:50 primo volumio[3266]: info: MCU Signalled Playback Active Aug 26 15:55:50 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) (+) Audio --aid=1 (flac 2ch 44100Hz) Aug 26 15:55:50 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Status update -> property-change events: [{"subscriptionId":2,"prop":"duration","data":3.272653}] Aug 26 15:55:50 primo volumio[3266]: info: CoreCommandRouter::volumioGetState Aug 26 15:55:50 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Status update -> property-change events: [{"subscriptionId":7,"prop":"audio-codec-name","data":"flac"},{"subscriptionId":9,"prop":"metadata","data":{}}] Aug 26 15:55:50 primo volumio[3266]: info: CoreCommandRouter::volumioGetState Aug 26 15:55:50 primo kernel: aml_tdm_open Aug 26 15:55:50 primo kernel: Not init audio effects Aug 26 15:55:50 primo kernel: audio_ddr_mngr: frddrs[0] registered by device ff660000.audiobus:tdm@1 Aug 26 15:55:50 primo kernel: aml_dai_set_tdm_sysclk(), mpll no change, keep clk Aug 26 15:55:50 primo kernel: aml_dai_set_tdm_sysclk(), mclk no change, keep clk Aug 26 15:55:50 primo kernel: set mclk:11289600, mpll:22579200, get mclk:11289593, mpll:22579186 Aug 26 15:55:50 primo kernel: asoc aml_dai_set_tdm_fmt, 0x4001, ffffffc03d365e18, id(1), clksel(1) Aug 26 15:55:50 primo kernel: aml_dai_set_tdm_fmt(), fmt not change Aug 26 15:55:50 primo kernel: dump_pcm_setting(ffffffc03d365e18) Aug 26 15:55:50 primo kernel: pcm_mode(1) Aug 26 15:55:50 primo kernel: sysclk(11289600) Aug 26 15:55:50 primo kernel: sysclk_bclk_ratio(4) Aug 26 15:55:50 primo kernel: bclk(2822400) Aug 26 15:55:50 primo kernel: bclk_lrclk_ratio(64) Aug 26 15:55:50 primo kernel: lrclk(44100) Aug 26 15:55:50 primo kernel: tx_mask(0x3) Aug 26 15:55:50 primo kernel: rx_mask(0x3) Aug 26 15:55:50 primo kernel: slots(2) Aug 26 15:55:50 primo kernel: slot_width(32) Aug 26 15:55:50 primo kernel: lane_mask_in(0x2) Aug 26 15:55:50 primo kernel: lane_mask_out(0x1) Aug 26 15:55:50 primo kernel: lane_oe_mask_in(0x0) Aug 26 15:55:50 primo kernel: lane_oe_mask_out(0x0) Aug 26 15:55:50 primo kernel: lane_lb_mask_in(0x0) Aug 26 15:55:50 primo kernel: aml_dai_set_tdm_sysclk(), mpll no change, keep clk Aug 26 15:55:50 primo kernel: aml_dai_set_tdm_sysclk(), mclk no change, keep clk Aug 26 15:55:50 primo kernel: set mclk:11289600, mpll:22579200, get mclk:11289593, mpll:22579186 Aug 26 15:55:50 primo kernel: aml_dai_set_clkdiv, div 4, clksel(1) Aug 26 15:55:50 primo kernel: aml_dai_set_bclk_ratio, select I2S mode Aug 26 15:55:50 primo kernel: aml_dai_tdm_hw_params(), enable mclk for TDM-B Aug 26 15:55:50 primo kernel: aml_tdm_prepare(), reset fddr Aug 26 15:55:50 primo kernel: spdif_a fifo ctrl, frddr:0 type:1, 16 bits, chmask 0x3, swap 0x10 Aug 26 15:55:50 primo kernel: spdif_info: rate: 44100, channel status ch0_l:0x100, ch0_r:0x100, ch1_l:0x0, ch1_r:0x0 Aug 26 15:55:50 primo kernel: audio_ddr_mngr: frddr_set_sharebuffer_enable sel:1, dst_src:3 Aug 26 15:55:50 primo kernel: tdm playback mute: 0, lane_cnt = 8 Aug 26 15:55:50 primo kernel: aml_tdm_prepare(), reset fddr Aug 26 15:55:50 primo kernel: spdif_a fifo ctrl, frddr:0 type:1, 16 bits, chmask 0x3, swap 0x10 Aug 26 15:55:50 primo kernel: spdif_info: rate: 44100, channel status ch0_l:0x100, ch0_r:0x100, ch1_l:0x0, ch1_r:0x0 Aug 26 15:55:50 primo kernel: audio_ddr_mngr: frddr_set_sharebuffer_enable sel:1, dst_src:3 Aug 26 15:55:50 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) AO: [alsa] 44100Hz stereo 2ch s16 Aug 26 15:55:50 primo kernel: tdm playback mute: 0, lane_cnt = 8 Aug 26 15:55:50 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Status update -> property-change events: [{"subscriptionId":6,"prop":"audio-params","data":{"samplerate":44100,"channel-count":2,"channels":"stereo","hr-channels":"stereo","format":"s16"}}] Aug 26 15:55:50 primo volumio[3266]: info: CoreCommandRouter::volumioGetState Aug 26 15:55:50 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Push Volumio state: {"status":"play","uri":"rp2/channel@id=2","title":"Listener-supported","artist":"Commercial-free","albumart":"https://img.radioparadise.com/covers/l/103.jpg","trackType":"RockIt! - ","duration":3.273,"samplerate":"44.1 kHz","bitdepth":"16-bit","channels":2,"service":"rp2","seek":0,"stream":false,"repeat":false,"repeatSingle":false,"random":false,"volume":100,"mute":false,"disableVolumeControl":false,"codec":"flac"} Aug 26 15:55:50 primo kernel: asoc-aml-card auge_sound: tdm playback enable Aug 26 15:55:50 primo kernel: spdif_a is set to enable Aug 26 15:55:50 primo volumio[3266]: info: CoreCommandRouter::servicePushState Aug 26 15:55:50 primo volumio[3266]: info: CoreStateMachine::pushState Aug 26 15:55:50 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 26 15:55:50 primo volumio[3266]: info: CoreCommandRouter::volumioPushState Aug 26 15:55:50 primo volumio[3266]: info: CoreCommandRouter::volumioGetState Aug 26 15:55:50 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:50.596+04:00 level=ERROR msg="failed to unmarshal pushState event" component=volumio/socket error="json: cannot unmarshal number 3.273 into Go struct field State.duration of type int" Aug 26 15:55:50 primo volumio[3266]: info: Signalling Playback active due to playback status change Aug 26 15:55:50 primo volumio[3266]: info: Updating RAAT Signal Path Aug 26 15:55:52 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri Aug 26 15:55:52 primo volumio[3266]: info: CURURI: music-library Aug 26 15:55:53 primo volumio[3266]: info: Preload queue cleared Aug 26 15:55:53 primo volumio[3266]: info: [rp2] About to reach end of stream in current block. Going to obtain next block. Aug 26 15:55:53 primo volumio[3266]: verbose: [rp2] Waiting for player to stop before fetching next block... Aug 26 15:55:53 primo volumio[3266]: verbose: [rp2] Waiting for player event "stopped"... Aug 26 15:55:53 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Status update -> property-change events: [{"subscriptionId":6,"prop":"audio-params"},{"subscriptionId":7,"prop":"audio-codec-name"}] Aug 26 15:55:53 primo volumio[3266]: info: CoreCommandRouter::volumioGetState Aug 26 15:55:53 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Push Volumio state: {"status":"play","uri":"rp2/channel@id=2","title":"Listener-supported","artist":"Commercial-free","albumart":"https://img.radioparadise.com/covers/l/103.jpg","trackType":"RockIt!","duration":3.273,"service":"rp2","seek":2993.9230000000002,"stream":false,"repeat":false,"repeatSingle":false,"random":false,"volume":100,"mute":false,"disableVolumeControl":false,"codec":"flac"} Aug 26 15:55:53 primo volumio[3266]: info: CoreCommandRouter::servicePushState Aug 26 15:55:53 primo volumio[3266]: info: CoreStateMachine::pushState Aug 26 15:55:53 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 26 15:55:53 primo volumio[3266]: info: CoreCommandRouter::volumioPushState Aug 26 15:55:53 primo volumio[3266]: info: CoreCommandRouter::volumioGetState Aug 26 15:55:53 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:53.587+04:00 level=ERROR msg="failed to unmarshal pushState event" component=volumio/socket error="json: cannot unmarshal number 2993.9230000000002 into Go struct field State.seek of type int" Aug 26 15:55:53 primo volumio[3266]: info: Signalling Playback active due to playback status change Aug 26 15:55:53 primo volumio[3266]: info: Updating RAAT Signal Path Aug 26 15:55:53 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Aug 26 15:55:53 primo kernel: asoc-aml-card auge_sound: tdm playback stop Aug 26 15:55:53 primo kernel: spdif_a is set to disable Aug 26 15:55:53 primo kernel: aml_tdm_prepare(), reset fddr Aug 26 15:55:53 primo kernel: spdif_a fifo ctrl, frddr:0 type:1, 16 bits, chmask 0x3, swap 0x10 Aug 26 15:55:53 primo kernel: spdif_info: rate: 44100, channel status ch0_l:0x100, ch0_r:0x100, ch1_l:0x0, ch1_r:0x0 Aug 26 15:55:53 primo kernel: audio_ddr_mngr: frddr_set_sharebuffer_enable sel:1, dst_src:3 Aug 26 15:55:53 primo kernel: tdm playback mute: 0, lane_cnt = 8 Aug 26 15:55:53 primo kernel: aml_tdm_prepare(), reset fddr Aug 26 15:55:53 primo kernel: spdif_a fifo ctrl, frddr:0 type:1, 16 bits, chmask 0x3, swap 0x10 Aug 26 15:55:53 primo kernel: spdif_info: rate: 44100, channel status ch0_l:0x100, ch0_r:0x100, ch1_l:0x0, ch1_r:0x0 Aug 26 15:55:53 primo kernel: audio_ddr_mngr: frddr_set_sharebuffer_enable sel:1, dst_src:3 Aug 26 15:55:53 primo kernel: tdm playback mute: 0, lane_cnt = 8 Aug 26 15:55:53 primo kernel: audio_ddr_mngr: frddr_set_sharebuffer_enable sel:1, dst_src:3 Aug 26 15:55:53 primo kernel: aml_dai_tdm_hw_free(), disable mclk for TDM-B Aug 26 15:55:53 primo kernel: tdm playback mute: 1, lane_cnt = 8 Aug 26 15:55:53 primo kernel: audio_ddr_mngr: frddrs[0] released by device ff660000.audiobus:tdm@1 Aug 26 15:55:53 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Status update -> property-change events: [{"subscriptionId":2,"prop":"duration"},{"subscriptionId":3,"prop":"idle-active","data":true}] Aug 26 15:55:53 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Player status "stopped" - skip unset volatile because unset condition is "manual" Aug 26 15:55:53 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Player status "stopped" - skip unset volatile because unset condition is "manual" Aug 26 15:55:53 primo volumio[3266]: verbose: [rp2] Received player event "stopped"... Aug 26 15:55:53 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Player status "stopped" - skip unset volatile because unset condition is "manual" Aug 26 15:55:53 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Player status "stopped" - skip unset volatile because unset condition is "manual" Aug 26 15:55:53 primo volumio[3266]: verbose: [rp2] API: https://api.radioparadise.com/api/play?source=24&event=2824550&elapsed=1&bitrate=4&action=play&player_id=********&info=true&chan=2&slice_num=0&episode_id=0&audio_type=P Aug 26 15:55:53 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Status update -> property-change events: [{"subscriptionId":8,"prop":"media-title"},{"subscriptionId":9,"prop":"metadata"}] Aug 26 15:55:53 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Player status "stopped" - skip unset volatile because unset condition is "manual" Aug 26 15:55:54 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri Aug 26 15:55:54 primo volumio[3266]: info: CURURI: music-library/USB Aug 26 15:55:54 primo volumio[3266]: info: Preload queue cleared Aug 26 15:55:54 primo volumio[3266]: info: [rp2] Obtained updated block Aug 26 15:55:54 primo volumio[3266]: info: [rp2] ------------- Aug 26 15:55:54 primo volumio[3266]: info: [rp2] Block summary Aug 26 15:55:54 primo volumio[3266]: info: [rp2] ------------- Aug 26 15:55:54 primo volumio[3266]: info: [rp2] Stream URL: https://audio.radioparadise.stream/audio/blocks/2/x/1145/4/b/1145-0.flac Aug 26 15:55:54 primo volumio[3266]: info: [rp2] Tracks: Aug 26 15:55:54 primo volumio[3266]: info: [rp2] 0. A Hard Way To Go (2:12 | elapsed: 0s) Aug 26 15:55:54 primo volumio[3266]: info: [rp2] 1. House (5:02 | elapsed: 2m 12s) Aug 26 15:55:54 primo volumio[3266]: info: [rp2] 2. Optimist (4:29 | elapsed: 7m 15s) Aug 26 15:55:54 primo volumio[3266]: info: [rp2] 3. Dance With Me (2:35 | elapsed: 11m 44s) Aug 26 15:55:54 primo volumio[3266]: info: [rp2] 4. New Hampshire (5:00 | elapsed: 14m 19s) Aug 26 15:55:54 primo volumio[3266]: info: [rp2] 5. She's So Cold (4:06 | elapsed: 19m 20s) Aug 26 15:55:54 primo volumio[3266]: info: [rp2] 6. Standing In the Shower... Thinking (3:02 | elapsed: 23m 26s) Aug 26 15:55:54 primo volumio[3266]: info: [rp2] Aug 26 15:55:54 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Player status "stopped" - skip unset volatile because unset condition is "manual" Aug 26 15:55:54 primo volumio[3266]: info: [rp2] Going to start playback of current track Aug 26 15:55:54 primo volumio[3266]: verbose: [rp2] Waiting for player event "playing"... Aug 26 15:55:54 primo volumio[3266]: info: CoreCommandRouter::volumioGetState Aug 26 15:55:54 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Send IPC command: {"command":["set_property","loop-file","no"],"request_id":26} Aug 26 15:55:54 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Got response for command #26: {"request_id":26,"error":"success"} Aug 26 15:55:54 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Push Volumio state: {"status":"pause","albumart":"https://img.radioparadise.com/covers/l/9697.jpg","uri":"rp2/channel@id=2","seek":0,"duration":132.66,"service":"rp2","stream":false,"repeat":false,"repeatSingle":false,"random":false,"volume":100,"mute":false,"disableVolumeControl":false,"title":"A Hard Way To Go","artist":"Savoy Brown","album":"Raw Sienna","codec":"flac","trackType":"RockIt!"} Aug 26 15:55:54 primo volumio[3266]: info: CoreCommandRouter::servicePushState Aug 26 15:55:54 primo volumio[3266]: info: CoreStateMachine::pushState Aug 26 15:55:54 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 26 15:55:54 primo volumio[3266]: info: CoreCommandRouter::volumioPushState Aug 26 15:55:54 primo volumio[3266]: info: CoreCommandRouter::volumioGetState Aug 26 15:55:54 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Send IPC command: {"command":["loadfile","https://audio.radioparadise.stream/audio/blocks/2/x/1145/4/b/1145-0.flac","replace","start=0"],"request_id":27} Aug 26 15:55:54 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:54.926+04:00 level=ERROR msg="failed to unmarshal pushState event" component=volumio/socket error="json: cannot unmarshal number 132.66 into Go struct field State.duration of type int" Aug 26 15:55:54 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Got response for command #27: {"data":{"playlist_entry_id":5},"request_id":27,"error":"success"} Aug 26 15:55:54 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Status update -> property-change events: [{"subscriptionId":3,"prop":"idle-active","data":false},{"subscriptionId":8,"prop":"media-title","data":"1145-0.flac"}] Aug 26 15:55:54 primo volumio[3266]: info: CoreCommandRouter::volumioGetState Aug 26 15:55:54 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Send IPC command: {"command":["set_property","pause",false],"request_id":28} Aug 26 15:55:54 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Push Volumio state: {"status":"play","uri":"rp2/channel@id=2","title":"A Hard Way To Go","artist":"Savoy Brown","album":"Raw Sienna","albumart":"https://img.radioparadise.com/covers/l/9697.jpg","trackType":"RockIt!","duration":132.66,"service":"rp2","seek":0,"stream":false,"repeat":false,"repeatSingle":false,"random":false,"volume":100,"mute":false,"disableVolumeControl":false,"codec":"flac"} Aug 26 15:55:54 primo volumio[3266]: info: CoreCommandRouter::servicePushState Aug 26 15:55:54 primo volumio[3266]: info: CoreStateMachine::pushState Aug 26 15:55:54 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 26 15:55:54 primo volumio[3266]: info: CoreCommandRouter::volumioPushState Aug 26 15:55:54 primo volumio[3266]: info: CoreCommandRouter::volumioGetState Aug 26 15:55:54 primo volumio[3266]: verbose: [rp2] Received player event "playing"... Aug 26 15:55:54 primo volumio[3266]: info: [rp2] Started playback of "A Hard Way To Go" - estimated finish time: 8/26/2026, 3:58:07 PM Aug 26 15:55:54 primo volumio[3266]: info: CoreCommandRouter::volumioGetState Aug 26 15:55:54 primo volumio[3266]: verbose: [rp2] After "A Hard Way To Go", the next track will start in 2m 12s (8/26/2026, 3:58:07 PM) Aug 26 15:55:54 primo volumio[3266]: verbose: [rp2] API: https://api.radioparadise.com/api/update_history?source=24&song_id=2089&chan=2&player_id=********&event=2824551&type=M&slice_num=0&episode_id=0&time_relative=-0&play_position_millis=0&playtime_secs=1787745355 Aug 26 15:55:54 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:54.950+04:00 level=ERROR msg="failed to unmarshal pushState event" component=volumio/socket error="json: cannot unmarshal number 132.66 into Go struct field State.duration of type int" Aug 26 15:55:54 primo volumio[3266]: info: Signalling Playback active due to playback status change Aug 26 15:55:54 primo volumio[3266]: info: Updating RAAT Signal Path Aug 26 15:55:54 primo volumio[3266]: info: Updating RAAT Signal Path Aug 26 15:55:54 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Got response for command #28: {"request_id":28,"error":"success"} Aug 26 15:55:55 primo volumio[3266]: info: MCU Signalled Playback Inactive Aug 26 15:55:55 primo volumio[3266]: info: MCU Signalled Playback Active Aug 26 15:55:55 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) (+) Audio --aid=1 (flac 2ch 44100Hz) Aug 26 15:55:55 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Status update -> property-change events: [{"subscriptionId":2,"prop":"duration","data":1588.520998},{"subscriptionId":7,"prop":"audio-codec-name","data":"flac"},{"subscriptionId":9,"prop":"metadata","data":{}}] Aug 26 15:55:55 primo volumio[3266]: info: CoreCommandRouter::volumioGetState Aug 26 15:55:55 primo kernel: aml_tdm_open Aug 26 15:55:55 primo kernel: Not init audio effects Aug 26 15:55:55 primo kernel: audio_ddr_mngr: frddrs[0] registered by device ff660000.audiobus:tdm@1 Aug 26 15:55:55 primo kernel: aml_dai_set_tdm_sysclk(), mpll no change, keep clk Aug 26 15:55:55 primo kernel: aml_dai_set_tdm_sysclk(), mclk no change, keep clk Aug 26 15:55:55 primo kernel: set mclk:11289600, mpll:22579200, get mclk:11289593, mpll:22579186 Aug 26 15:55:55 primo kernel: asoc aml_dai_set_tdm_fmt, 0x4001, ffffffc03d365e18, id(1), clksel(1) Aug 26 15:55:55 primo kernel: aml_dai_set_tdm_fmt(), fmt not change Aug 26 15:55:55 primo kernel: dump_pcm_setting(ffffffc03d365e18) Aug 26 15:55:55 primo kernel: pcm_mode(1) Aug 26 15:55:55 primo kernel: sysclk(11289600) Aug 26 15:55:55 primo kernel: sysclk_bclk_ratio(4) Aug 26 15:55:55 primo kernel: bclk(2822400) Aug 26 15:55:55 primo kernel: bclk_lrclk_ratio(64) Aug 26 15:55:55 primo kernel: lrclk(44100) Aug 26 15:55:55 primo kernel: tx_mask(0x3) Aug 26 15:55:55 primo kernel: rx_mask(0x3) Aug 26 15:55:55 primo kernel: slots(2) Aug 26 15:55:55 primo kernel: slot_width(32) Aug 26 15:55:55 primo kernel: lane_mask_in(0x2) Aug 26 15:55:55 primo kernel: lane_mask_out(0x1) Aug 26 15:55:55 primo kernel: lane_oe_mask_in(0x0) Aug 26 15:55:55 primo kernel: lane_oe_mask_out(0x0) Aug 26 15:55:55 primo kernel: lane_lb_mask_in(0x0) Aug 26 15:55:55 primo kernel: aml_dai_set_tdm_sysclk(), mpll no change, keep clk Aug 26 15:55:55 primo kernel: aml_dai_set_tdm_sysclk(), mclk no change, keep clk Aug 26 15:55:55 primo kernel: set mclk:11289600, mpll:22579200, get mclk:11289593, mpll:22579186 Aug 26 15:55:55 primo kernel: aml_dai_set_clkdiv, div 4, clksel(1) Aug 26 15:55:55 primo kernel: aml_dai_set_bclk_ratio, select I2S mode Aug 26 15:55:55 primo kernel: aml_dai_tdm_hw_params(), enable mclk for TDM-B Aug 26 15:55:55 primo kernel: aml_tdm_prepare(), reset fddr Aug 26 15:55:55 primo kernel: spdif_a fifo ctrl, frddr:0 type:1, 16 bits, chmask 0x3, swap 0x10 Aug 26 15:55:55 primo kernel: spdif_info: rate: 44100, channel status ch0_l:0x100, ch0_r:0x100, ch1_l:0x0, ch1_r:0x0 Aug 26 15:55:55 primo kernel: audio_ddr_mngr: frddr_set_sharebuffer_enable sel:1, dst_src:3 Aug 26 15:55:55 primo kernel: tdm playback mute: 0, lane_cnt = 8 Aug 26 15:55:55 primo kernel: aml_tdm_prepare(), reset fddr Aug 26 15:55:55 primo kernel: spdif_a fifo ctrl, frddr:0 type:1, 16 bits, chmask 0x3, swap 0x10 Aug 26 15:55:55 primo kernel: spdif_info: rate: 44100, channel status ch0_l:0x100, ch0_r:0x100, ch1_l:0x0, ch1_r:0x0 Aug 26 15:55:55 primo kernel: audio_ddr_mngr: frddr_set_sharebuffer_enable sel:1, dst_src:3 Aug 26 15:55:55 primo kernel: tdm playback mute: 0, lane_cnt = 8 Aug 26 15:55:55 primo kernel: asoc-aml-card auge_sound: tdm playback enable Aug 26 15:55:55 primo kernel: spdif_a is set to enable Aug 26 15:55:55 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) AO: [alsa] 44100Hz stereo 2ch s16 Aug 26 15:55:55 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Status update -> property-change events: [{"subscriptionId":6,"prop":"audio-params","data":{"samplerate":44100,"channel-count":2,"channels":"stereo","hr-channels":"stereo","format":"s16"}}] Aug 26 15:55:55 primo volumio[3266]: info: CoreCommandRouter::volumioGetState Aug 26 15:55:55 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Push Volumio state: {"status":"play","uri":"rp2/channel@id=2","title":"A Hard Way To Go","artist":"Savoy Brown","album":"Raw Sienna","albumart":"https://img.radioparadise.com/covers/l/9697.jpg","trackType":"RockIt! - ","duration":132.66,"samplerate":"44.1 kHz","bitdepth":"16-bit","channels":2,"service":"rp2","seek":0,"stream":false,"repeat":false,"repeatSingle":false,"random":false,"volume":100,"mute":false,"disableVolumeControl":false,"codec":"flac"} Aug 26 15:55:55 primo volumio[3266]: info: CoreCommandRouter::servicePushState Aug 26 15:55:55 primo volumio[3266]: info: CoreStateMachine::pushState Aug 26 15:55:55 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 26 15:55:55 primo volumio[3266]: info: CoreCommandRouter::volumioPushState Aug 26 15:55:55 primo volumio[3266]: info: CoreCommandRouter::volumioGetState Aug 26 15:55:55 primo volumio5-onboarding[4033]: time=2026-08-26T15:55:55.346+04:00 level=ERROR msg="failed to unmarshal pushState event" component=volumio/socket error="json: cannot unmarshal number 132.66 into Go struct field State.duration of type int" Aug 26 15:55:55 primo volumio[3266]: info: CoreCommandRouter::volumioGetState Aug 26 15:55:55 primo volumio[3266]: info: Signalling Playback active due to playback status change Aug 26 15:55:55 primo volumio[3266]: info: Updating RAAT Signal Path Aug 26 15:55:56 primo volumio[3266]: verbose: [rp2] Checking if next track interval requires adjusting (1/5)... Aug 26 15:55:56 primo volumio[3266]: verbose: [rp2] Next track interval is accurate Aug 26 15:55:58 primo volumio[3266]: verbose: [rp2] Checking if next track interval requires adjusting (2/5)... Aug 26 15:55:58 primo volumio[3266]: verbose: [rp2] Next track interval is accurate Aug 26 15:55:59 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri Aug 26 15:55:59 primo volumio[3266]: info: CURURI: genres:// Aug 26 15:55:59 primo volumio[3266]: info: Preload queue cleared Aug 26 15:55:59 primo volumio[3266]: An internal error occurred while serving an albumart. Details: Error: ENOENT: no such file or directory, stat '/volumio/app/plugins/miscellanea/albumart/icons/fa-tags.svg' Aug 26 15:56:00 primo volumio[3266]: verbose: [rp2] Checking if next track interval requires adjusting (3/5)... Aug 26 15:56:00 primo volumio[3266]: verbose: [rp2] Next track interval is accurate Aug 26 15:56:02 primo volumio[3266]: verbose: [rp2] Checking if next track interval requires adjusting (4/5)... Aug 26 15:56:02 primo volumio[3266]: verbose: [rp2] Next track interval is accurate Aug 26 15:56:04 primo volumio[3266]: verbose: [rp2] Checking if next track interval requires adjusting (5/5)... Aug 26 15:56:04 primo volumio[3266]: verbose: [rp2] Next track interval is accurate Aug 26 15:56:10 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri Aug 26 15:56:10 primo volumio[3266]: info: CURURI: genres://Psy%20-%20Full%20On Aug 26 15:56:10 primo volumio[3266]: info: Preload queue cleared Aug 26 15:56:10 primo volumio[3266]: info: Preload queue cleared Aug 26 15:56:12 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri Aug 26 15:56:12 primo volumio[3266]: info: CURURI: genres://Psy%20-%20Full%20On/Tropical%20Bleyage/Static%20EP Aug 26 15:56:12 primo volumio[3266]: info: Preload queue cleared Aug 26 15:56:12 primo volumio[3266]: info: Preloading song: music-library/USB/SSDSumsung/LossLessMusic/MUSIQUE DE TRANSE/Tropical Bleyage/Tropical Bleyage - Static EP (DACRU Records 2011)/01. Tropical Bleyage – Zora.flac Aug 26 15:56:12 primo volumio[3266]: info: Preloading song: music-library/USB/SSDSumsung/LossLessMusic/MUSIQUE DE TRANSE/Tropical Bleyage/Tropical Bleyage - Static EP (DACRU Records 2011)/02. Tropical Bleyage – Static.flac Aug 26 15:56:12 primo volumio[3266]: info: Preloading song: music-library/USB/SSDSumsung/LossLessMusic/MUSIQUE DE TRANSE/Tropical Bleyage/Tropical Bleyage - Static EP (DACRU Records 2011)/03. Tropical Bleyage – Soul Train.flac Aug 26 15:56:12 primo volumio[3266]: info: Exploding uri music-library/USB/SSDSumsung/LossLessMusic/MUSIQUE DE TRANSE/Tropical Bleyage/Tropical Bleyage - Static EP (DACRU Records 2011)/01. Tropical Bleyage – Zora.flac in service mpd Aug 26 15:56:12 primo volumio[3266]: info: ALBUMART /albumart?cacheid=880&web=Tropical%20Bleyage/Static%20EP/extralarge&path=%2Fmnt%2FUSB%2FSSDSumsung%2FLossLessMusic%2FMUSIQUE%20DE%20TRANSE%2FTropical%20Bleyage%2FTropical%20Bleyage%20-%20Static%20EP%20(DACRU%20Records%202011)%2F01.%20Tropical%20Bleyage%20%E2%80%93%20Zora.flac&metadata=false Aug 26 15:56:12 primo volumio[3266]: info: URI /mnt/USB/SSDSumsung/LossLessMusic/MUSIQUE DE TRANSE/Tropical Bleyage/Tropical Bleyage - Static EP (DACRU Records 2011)/01. Tropical Bleyage – Zora.flac Aug 26 15:56:12 primo volumio[3266]: info: Executing endpoint getSimilarAlbums Aug 26 15:56:12 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getSimilarAlbums Aug 26 15:56:12 primo volumio[3266]: info: Exploding uri music-library/USB/SSDSumsung/LossLessMusic/MUSIQUE DE TRANSE/Tropical Bleyage/Tropical Bleyage - Static EP (DACRU Records 2011)/02. Tropical Bleyage – Static.flac in service mpd Aug 26 15:56:12 primo volumio[3266]: info: ALBUMART /albumart?cacheid=880&web=Tropical%20Bleyage/Static%20EP/extralarge&path=%2Fmnt%2FUSB%2FSSDSumsung%2FLossLessMusic%2FMUSIQUE%20DE%20TRANSE%2FTropical%20Bleyage%2FTropical%20Bleyage%20-%20Static%20EP%20(DACRU%20Records%202011)%2F02.%20Tropical%20Bleyage%20%E2%80%93%20Static.flac&metadata=false Aug 26 15:56:12 primo volumio[3266]: info: URI /mnt/USB/SSDSumsung/LossLessMusic/MUSIQUE DE TRANSE/Tropical Bleyage/Tropical Bleyage - Static EP (DACRU Records 2011)/02. Tropical Bleyage – Static.flac Aug 26 15:56:12 primo volumio[3266]: info: Exploding uri music-library/USB/SSDSumsung/LossLessMusic/MUSIQUE DE TRANSE/Tropical Bleyage/Tropical Bleyage - Static EP (DACRU Records 2011)/03. Tropical Bleyage – Soul Train.flac in service mpd Aug 26 15:56:12 primo volumio[3266]: info: ALBUMART /albumart?cacheid=880&web=Tropical%20Bleyage/Static%20EP/extralarge&path=%2Fmnt%2FUSB%2FSSDSumsung%2FLossLessMusic%2FMUSIQUE%20DE%20TRANSE%2FTropical%20Bleyage%2FTropical%20Bleyage%20-%20Static%20EP%20(DACRU%20Records%202011)%2F03.%20Tropical%20Bleyage%20%E2%80%93%20Soul%20Train.flac&metadata=false Aug 26 15:56:12 primo volumio[3266]: info: URI /mnt/USB/SSDSumsung/LossLessMusic/MUSIQUE DE TRANSE/Tropical Bleyage/Tropical Bleyage - Static EP (DACRU Records 2011)/03. Tropical Bleyage – Soul Train.flac Aug 26 15:56:12 primo volumio[3266]: info: Executing endpoint metavolumio Aug 26 15:56:12 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Aug 26 15:56:12 primo volumio[3266]: info: Executing endpoint metavolumio Aug 26 15:56:12 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Aug 26 15:56:16 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri Aug 26 15:56:16 primo volumio[3266]: info: CURURI: genres://Psy%20-%20Full%20On/Tropical%20Bleyage Aug 26 15:56:16 primo volumio[3266]: info: Preload queue cleared Aug 26 15:56:16 primo volumio[3266]: info: Preload queue cleared Aug 26 15:56:16 primo volumio[3266]: info: Executing endpoint getSimilarArtists Aug 26 15:56:16 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getSimilarArtists Aug 26 15:56:16 primo volumio[3266]: info: Executing endpoint metavolumio Aug 26 15:56:16 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Aug 26 15:56:18 primo volumio[3266]: info: Preload queue cleared Aug 26 15:56:18 primo volumio[3266]: info: CoreCommandRouter::volumioReplaceandPlayItems Aug 26 15:56:18 primo volumio[3266]: info: CoreStateMachine::ClearQueue Aug 26 15:56:18 primo volumio[3266]: info: CoreStateMachine::stop Aug 26 15:56:18 primo volumio[3266]: info: CoreStateMachine::serviceStop Aug 26 15:56:18 primo volumio[3266]: info: CoreCommandRouter::serviceStop Aug 26 15:56:18 primo volumio[3266]: info: CoreStateMachine::stPlaybackTimer Aug 26 15:56:18 primo volumio[3266]: info: CoreStateMachine::updateTrackBlock Aug 26 15:56:18 primo volumio[3266]: info: CorePlayQueue::getTrackBlock Aug 26 15:56:18 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Send IPC command: {"command":["stop"],"request_id":29} Aug 26 15:56:18 primo volumio[3266]: verbose: [rp2] Waiting for player event "stopped"... Aug 26 15:56:18 primo volumio[3266]: info: CorePlayQueue::clearPlayQueue Aug 26 15:56:18 primo volumio[3266]: info: CorePlayQueue::saveQueue Aug 26 15:56:18 primo kernel: asoc-aml-card auge_sound: tdm playback stop Aug 26 15:56:18 primo kernel: spdif_a is set to disable Aug 26 15:56:18 primo kernel: aml_tdm_prepare(), reset fddr Aug 26 15:56:18 primo kernel: spdif_a fifo ctrl, frddr:0 type:1, 16 bits, chmask 0x3, swap 0x10 Aug 26 15:56:18 primo kernel: spdif_info: rate: 44100, channel status ch0_l:0x100, ch0_r:0x100, ch1_l:0x0, ch1_r:0x0 Aug 26 15:56:18 primo kernel: audio_ddr_mngr: frddr_set_sharebuffer_enable sel:1, dst_src:3 Aug 26 15:56:18 primo kernel: tdm playback mute: 0, lane_cnt = 8 Aug 26 15:56:18 primo volumio[3266]: info: CoreCommandRouter::volumioPushQueue Aug 26 15:56:18 primo volumio[3266]: info: CoreStateMachine::addQueueItems Aug 26 15:56:18 primo volumio[3266]: info: CorePlayQueue::addQueueItems Aug 26 15:56:18 primo volumio[3266]: info: Preload queue cleared Aug 26 15:56:18 primo volumio[3266]: info: Adding Item to queue: music-library/USB/SSDSumsung/LossLessMusic/MUSIQUE DE TRANSE/Tropical Bleyage/Tropical Bleyage - Static EP (DACRU Records 2011)/01. Tropical Bleyage – Zora.flac Aug 26 15:56:18 primo volumio[3266]: info: Using cached record of: music-library/USB/SSDSumsung/LossLessMusic/MUSIQUE DE TRANSE/Tropical Bleyage/Tropical Bleyage - Static EP (DACRU Records 2011)/01. Tropical Bleyage – Zora.flac Aug 26 15:56:18 primo volumio[3266]: info: CoreCommandRouter::volumioPushQueue Aug 26 15:56:18 primo volumio[3266]: info: CorePlayQueue::saveQueue Aug 26 15:56:18 primo volumio[3266]: info: CoreStateMachine::updateTrackBlock Aug 26 15:56:18 primo volumio[3266]: info: CorePlayQueue::getTrackBlock Aug 26 15:56:18 primo volumio[3266]: info: CoreCommandRouter::volumioGetState Aug 26 15:56:18 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: play , [object Object] Aug 26 15:56:18 primo volumio[3266]: info: CoreCommandRouter::volumioPlay Aug 26 15:56:18 primo volumio[3266]: verbose: UNSET VOLATILE: Service: rp2 Aug 26 15:56:18 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Volatile state unset, stopping playback (if any)... Aug 26 15:56:18 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Push Volumio state: {"status":"stop","albumart":"https://img.radioparadise.com/covers/l/9697.jpg","uri":"rp2/channel@id=2","seek":23484.082000000002,"duration":132.66,"service":"rp2","stream":false,"repeat":false,"repeatSingle":false,"random":false,"volume":100,"mute":false,"disableVolumeControl":false,"title":"A Hard Way To Go","artist":"Savoy Brown","album":"Raw Sienna","codec":"flac","trackType":"RockIt!"} Aug 26 15:56:18 primo volumio[3266]: info: CoreCommandRouter::servicePushState Aug 26 15:56:18 primo volumio[3266]: info: CoreStateMachine::pushState Aug 26 15:56:18 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 26 15:56:18 primo volumio[3266]: info: CoreCommandRouter::volumioPushState Aug 26 15:56:18 primo volumio[3266]: info: CoreCommandRouter::volumioGetState Aug 26 15:56:18 primo volumio[3266]: info: CorePlayQueue::getTrack 0 Aug 26 15:56:18 primo volumio[3266]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current mpd Received rp2 Aug 26 15:56:18 primo volumio[3266]: MPVPlayer onunsetVolatile called Aug 26 15:56:18 primo volumio[3266]: MPVPlayer calling onunsetVolatile callbacks Aug 26 15:56:18 primo volumio[3266]: verbose: [rp2] Waiting for player event "stopped"... Aug 26 15:56:18 primo volumio[3266]: info: CoreStateMachine::play index 0 Aug 26 15:56:18 primo volumio[3266]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 26 15:56:18 primo volumio[3266]: info: CoreStateMachine::addQueueItems Aug 26 15:56:18 primo volumio[3266]: info: CorePlayQueue::addQueueItems Aug 26 15:56:18 primo volumio[3266]: info: Preload queue cleared Aug 26 15:56:18 primo volumio[3266]: info: Adding Item to queue: music-library/USB/SSDSumsung/LossLessMusic/MUSIQUE DE TRANSE/Tropical Bleyage/Tropical Bleyage - Static EP (DACRU Records 2011)/02. Tropical Bleyage – Static.flac Aug 26 15:56:18 primo volumio[3266]: info: Using cached record of: music-library/USB/SSDSumsung/LossLessMusic/MUSIQUE DE TRANSE/Tropical Bleyage/Tropical Bleyage - Static EP (DACRU Records 2011)/02. Tropical Bleyage – Static.flac Aug 26 15:56:18 primo volumio[3266]: info: Adding Item to queue: music-library/USB/SSDSumsung/LossLessMusic/MUSIQUE DE TRANSE/Tropical Bleyage/Tropical Bleyage - Static EP (DACRU Records 2011)/03. Tropical Bleyage – Soul Train.flac Aug 26 15:56:18 primo volumio[3266]: info: Using cached record of: music-library/USB/SSDSumsung/LossLessMusic/MUSIQUE DE TRANSE/Tropical Bleyage/Tropical Bleyage - Static EP (DACRU Records 2011)/03. Tropical Bleyage – Soul Train.flac Aug 26 15:56:18 primo volumio5-onboarding[4033]: time=2026-08-26T15:56:18.909+04:00 level=ERROR msg="failed to unmarshal pushState event" component=volumio/socket error="json: cannot unmarshal number 23484.082000000002 into Go struct field State.seek of type int" Aug 26 15:56:18 primo volumio[3266]: info: CoreStateMachine::stop Aug 26 15:56:18 primo volumio[3266]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 26 15:56:18 primo volumio[3266]: info: CoreCommandRouter::volumioPushQueue Aug 26 15:56:18 primo volumio[3266]: info: CorePlayQueue::saveQueue Aug 26 15:56:18 primo volumio[3266]: info: CoreStateMachine::play index undefined Aug 26 15:56:18 primo volumio[3266]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 26 15:56:18 primo volumio[3266]: info: CoreStateMachine::updateTrackBlock Aug 26 15:56:18 primo volumio[3266]: info: CorePlayQueue::getTrackBlock Aug 26 15:56:18 primo volumio[3266]: info: CorePlayQueue::getTrack 0 Aug 26 15:56:18 primo volumio[3266]: info: CoreStateMachine::startPlaybackTimer Aug 26 15:56:18 primo volumio[3266]: info: CorePlayQueue::getTrack 0 Aug 26 15:56:18 primo volumio[3266]: verbose: ControllerMpd::clearAddPlayTracks USB/SSDSumsung/LossLessMusic/MUSIQUE DE TRANSE/Tropical Bleyage/Tropical Bleyage - Static EP (DACRU Records 2011)/01. Tropical Bleyage – Zora.flac Aug 26 15:56:18 primo volumio[3266]: verbose: ControllerMpd::sendMpdCommand stop Aug 26 15:56:18 primo volumio[3266]: verbose: [rp2] Received player event "stopped"... Aug 26 15:56:18 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Got response for command #29: {"data":null,"request_id":29,"error":"success"} Aug 26 15:56:18 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Status update -> property-change events: [{"subscriptionId":6,"prop":"audio-params"},{"subscriptionId":7,"prop":"audio-codec-name"}] Aug 26 15:56:18 primo volumio[3266]: info: Signalling Playback active due to playback status change Aug 26 15:56:18 primo volumio[3266]: info: Updating RAAT Signal Path Aug 26 15:56:18 primo volumio[3266]: info: sendMpdCommand stop took 47 milliseconds Aug 26 15:56:18 primo volumio[3266]: verbose: ControllerMpd::sendMpdCommand clear Aug 26 15:56:18 primo volumio[3266]: info: Aug 26 15:56:18 primo volumio[3266]: ---------------------------- MPD announces system playlist update Aug 26 15:56:18 primo volumio[3266]: info: Ignoring MPD Status Update Aug 26 15:56:18 primo volumio[3266]: info: sendMpdCommand clear took 4 milliseconds Aug 26 15:56:18 primo volumio[3266]: verbose: ControllerMpd::sendMpdCommand add "USB/SSDSumsung/LossLessMusic/MUSIQUE DE TRANSE/Tropical Bleyage/Tropical Bleyage - Static EP (DACRU Records 2011)/01. Tropical Bleyage – Zora.flac" Aug 26 15:56:18 primo volumio[3266]: info: Aug 26 15:56:18 primo volumio[3266]: ---------------------------- MPD announces system playlist update Aug 26 15:56:18 primo volumio[3266]: info: Ignoring MPD Status Update Aug 26 15:56:18 primo volumio[3266]: info: Aug 26 15:56:18 primo volumio[3266]: ---------------------------- MPD announces system playlist update Aug 26 15:56:18 primo volumio[3266]: info: Ignoring MPD Status Update Aug 26 15:56:18 primo volumio[3266]: error: updateQueue error: null Aug 26 15:56:18 primo volumio[3266]: info: Aug 26 15:56:18 primo volumio[3266]: ---------------------------- MPD announces system playlist update Aug 26 15:56:18 primo volumio[3266]: info: Ignoring MPD Status Update Aug 26 15:56:18 primo volumio[3266]: info: ------------------------------ 16ms Aug 26 15:56:18 primo volumio[3266]: info: sendMpdCommand add "USB/SSDSumsung/LossLessMusic/MUSIQUE DE TRANSE/Tropical Bleyage/Tropical Bleyage - Static EP (DACRU Records 2011)/01. Tropical Bleyage – Zora.flac" took 13 milliseconds Aug 26 15:56:18 primo volumio[3266]: info: ------------------------------ 11ms Aug 26 15:56:18 primo volumio[3266]: info: ------------------------------ 9ms Aug 26 15:56:18 primo volumio[3266]: verbose: ControllerMpd::sendMpdCommand play Aug 26 15:56:18 primo volumio[3266]: info: Aug 26 15:56:18 primo volumio[3266]: ---------------------------- MPD announces system playlist update Aug 26 15:56:19 primo volumio[3266]: info: Ignoring MPD Status Update Aug 26 15:56:19 primo volumio[3266]: info: Aug 26 15:56:19 primo volumio[3266]: ---------------------------- MPD announces system playlist update Aug 26 15:56:19 primo volumio[3266]: info: Ignoring MPD Status Update Aug 26 15:56:19 primo kernel: audio_ddr_mngr: frddr_set_sharebuffer_enable sel:1, dst_src:3 Aug 26 15:56:19 primo kernel: aml_dai_tdm_hw_free(), disable mclk for TDM-B Aug 26 15:56:19 primo kernel: tdm playback mute: 1, lane_cnt = 8 Aug 26 15:56:19 primo kernel: audio_ddr_mngr: frddrs[0] released by device ff660000.audiobus:tdm@1 Aug 26 15:56:19 primo volumio[3266]: info: ------------------------------ 14ms Aug 26 15:56:19 primo volumio[3266]: info: sendMpdCommand play took 10 milliseconds Aug 26 15:56:19 primo volumio[3266]: info: ------------------------------ 9ms Aug 26 15:56:19 primo volumio[3266]: info: ------------------------------ 8ms Aug 26 15:56:19 primo kernel: aml_tdm_open Aug 26 15:56:19 primo kernel: Not init audio effects Aug 26 15:56:19 primo kernel: audio_ddr_mngr: frddrs[0] registered by device ff660000.audiobus:tdm@1 Aug 26 15:56:19 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Aug 26 15:56:19 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Status update -> property-change events: [{"subscriptionId":2,"prop":"duration"},{"subscriptionId":3,"prop":"idle-active","data":true},{"subscriptionId":8,"prop":"media-title"},{"subscriptionId":9,"prop":"metadata"}] Aug 26 15:56:19 primo volumio[3266]: info: [rp2] [mpv] (PID: 10835) Player status "stopped" - unsetting ourselves as current service... Aug 26 15:56:19 primo volumio[3266]: info: Aug 26 15:56:19 primo volumio[3266]: ---------------------------- MPD announces state update: player Aug 26 15:56:19 primo volumio[3266]: info: ControllerMpd::getState Aug 26 15:56:19 primo volumio[3266]: verbose: ControllerMpd::sendMpdCommand status Aug 26 15:56:19 primo volumio[3266]: info: Aug 26 15:56:19 primo volumio[3266]: ---------------------------- MPD announces state update: player Aug 26 15:56:19 primo volumio[3266]: info: ControllerMpd::getState Aug 26 15:56:19 primo volumio[3266]: verbose: ControllerMpd::sendMpdCommand status Aug 26 15:56:19 primo volumio[3266]: info: Aug 26 15:56:19 primo volumio[3266]: ---------------------------- MPD announces state update: player Aug 26 15:56:19 primo volumio[3266]: info: ControllerMpd::getState Aug 26 15:56:19 primo volumio[3266]: verbose: ControllerMpd::sendMpdCommand status Aug 26 15:56:19 primo kernel: set mclk:49152000, mpll:98304000, get mclk:49151901, mpll:98303801 Aug 26 15:56:19 primo kernel: asoc aml_dai_set_tdm_fmt, 0x4001, ffffffc03d365e18, id(1), clksel(1) Aug 26 15:56:19 primo kernel: aml_dai_set_tdm_fmt(), fmt not change Aug 26 15:56:19 primo kernel: dump_pcm_setting(ffffffc03d365e18) Aug 26 15:56:19 primo kernel: pcm_mode(1) Aug 26 15:56:19 primo kernel: sysclk(49152000) Aug 26 15:56:19 primo kernel: sysclk_bclk_ratio(4) Aug 26 15:56:19 primo kernel: bclk(12288000) Aug 26 15:56:19 primo kernel: bclk_lrclk_ratio(64) Aug 26 15:56:19 primo kernel: lrclk(192000) Aug 26 15:56:19 primo kernel: tx_mask(0x3) Aug 26 15:56:19 primo kernel: rx_mask(0x3) Aug 26 15:56:19 primo kernel: slots(2) Aug 26 15:56:19 primo kernel: slot_width(32) Aug 26 15:56:19 primo kernel: lane_mask_in(0x2) Aug 26 15:56:19 primo kernel: lane_mask_out(0x1) Aug 26 15:56:19 primo kernel: lane_oe_mask_in(0x0) Aug 26 15:56:19 primo kernel: lane_oe_mask_out(0x0) Aug 26 15:56:19 primo kernel: lane_lb_mask_in(0x0) Aug 26 15:56:19 primo kernel: aml_dai_set_tdm_sysclk(), mpll no change, keep clk Aug 26 15:56:19 primo kernel: aml_dai_set_tdm_sysclk(), mclk no change, keep clk Aug 26 15:56:19 primo kernel: set mclk:49152000, mpll:98304000, get mclk:49151901, mpll:98303801 Aug 26 15:56:19 primo kernel: aml_dai_set_clkdiv, div 4, clksel(1) Aug 26 15:56:19 primo kernel: aml_dai_set_bclk_ratio, select I2S mode Aug 26 15:56:19 primo kernel: aml_dai_tdm_hw_params(), enable mclk for TDM-B Aug 26 15:56:19 primo kernel: aml_tdm_prepare(), reset fddr Aug 26 15:56:19 primo kernel: spdif_a fifo ctrl, frddr:0 type:3, 32 bits, chmask 0x3, swap 0x10 Aug 26 15:56:19 primo kernel: spdif_info: rate: 192000, channel status ch0_l:0x100, ch0_r:0x100, ch1_l:0xe00, ch1_r:0xe00 Aug 26 15:56:19 primo kernel: audio_ddr_mngr: frddr_set_sharebuffer_enable sel:1, dst_src:3 Aug 26 15:56:19 primo kernel: tdm playback mute: 0, lane_cnt = 8 Aug 26 15:56:19 primo volumio[3266]: info: Aug 26 15:56:19 primo volumio[3266]: ---------------------------- MPD announces state update: player Aug 26 15:56:19 primo volumio[3266]: info: sendMpdCommand status took 25 milliseconds Aug 26 15:56:19 primo volumio[3266]: info: ControllerMpd::getState Aug 26 15:56:19 primo volumio[3266]: verbose: ControllerMpd::sendMpdCommand status Aug 26 15:56:19 primo volumio[3266]: verbose: ControllerMpd::parseState Aug 26 15:56:19 primo volumio[3266]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 26 15:56:19 primo volumio[3266]: info: sendMpdCommand status took 29 milliseconds Aug 26 15:56:19 primo volumio[3266]: info: sendMpdCommand status took 27 milliseconds Aug 26 15:56:19 primo volumio[3266]: info: sendMpdCommand status took 6 milliseconds Aug 26 15:56:19 primo volumio[3266]: info: sendMpdCommand playlistinfo took 4 milliseconds Aug 26 15:56:19 primo volumio[3266]: verbose: ControllerMpd::parseState Aug 26 15:56:19 primo volumio[3266]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 26 15:56:19 primo volumio[3266]: verbose: ControllerMpd::parseState Aug 26 15:56:19 primo volumio[3266]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 26 15:56:19 primo volumio[3266]: verbose: ControllerMpd::parseState Aug 26 15:56:19 primo volumio[3266]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 26 15:56:19 primo volumio[3266]: verbose: ControllerMpd::parseTrackInfo Aug 26 15:56:19 primo volumio[3266]: info: ControllerMpd::pushState Aug 26 15:56:19 primo volumio[3266]: info: CoreCommandRouter::servicePushState Aug 26 15:56:19 primo volumio[3266]: info: CorePlayQueue::getTrack 0 Aug 26 15:56:19 primo volumio[3266]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":487,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"Zora","artist":"Tropical Bleyage","album":"Static EP","uri":"USB/SSDSumsung/LossLessMusic/MUSIQUE DE TRANSE/Tropical Bleyage/Tropical Bleyage - Static EP (DACRU Records 2011)/01. Tropical Bleyage – Zora.flac","trackType":"flac"} Aug 26 15:56:19 primo volumio[3266]: verbose: CURRENT POSITION 0 Aug 26 15:56:19 primo volumio[3266]: info: CoreStateMachine::syncState stateService play Aug 26 15:56:19 primo volumio[3266]: info: CoreStateMachine::syncState currentStatus stop Aug 26 15:56:19 primo volumio[3266]: info: ------------------------------ 50ms Aug 26 15:56:19 primo volumio[3266]: info: Aug 26 15:56:19 primo volumio[3266]: ---------------------------- MPD announces state update: player Aug 26 15:56:19 primo volumio[3266]: info: ControllerMpd::getState Aug 26 15:56:19 primo volumio[3266]: verbose: ControllerMpd::sendMpdCommand status Aug 26 15:56:19 primo volumio[3266]: info: Aug 26 15:56:19 primo volumio[3266]: ---------------------------- MPD announces state update: player Aug 26 15:56:19 primo volumio[3266]: info: ControllerMpd::getState Aug 26 15:56:19 primo volumio[3266]: verbose: ControllerMpd::sendMpdCommand status Aug 26 15:56:19 primo volumio[3266]: info: sendMpdCommand playlistinfo took 18 milliseconds Aug 26 15:56:19 primo volumio[3266]: info: sendMpdCommand playlistinfo took 17 milliseconds Aug 26 15:56:19 primo volumio[3266]: info: sendMpdCommand playlistinfo took 16 milliseconds Aug 26 15:56:19 primo volumio[3266]: info: sendMpdCommand status took 8 milliseconds Aug 26 15:56:19 primo volumio[3266]: info: sendMpdCommand status took 4 milliseconds Aug 26 15:56:19 primo volumio[3266]: verbose: ControllerMpd::parseTrackInfo Aug 26 15:56:19 primo volumio[3266]: verbose: ControllerMpd::parseTrackInfo Aug 26 15:56:19 primo volumio[3266]: verbose: ControllerMpd::parseTrackInfo Aug 26 15:56:19 primo volumio[3266]: verbose: ControllerMpd::parseState Aug 26 15:56:19 primo volumio[3266]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 26 15:56:19 primo volumio[3266]: verbose: ControllerMpd::parseState Aug 26 15:56:19 primo volumio[3266]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 26 15:56:19 primo volumio[3266]: info: ControllerMpd::pushState Aug 26 15:56:19 primo volumio[3266]: info: CoreCommandRouter::servicePushState Aug 26 15:56:19 primo volumio[3266]: info: CorePlayQueue::getTrack 0 Aug 26 15:56:19 primo volumio[3266]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":487,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"578 Kbps","isStreaming":false,"title":"Zora","artist":"Tropical Bleyage","album":"Static EP","uri":"USB/SSDSumsung/LossLessMusic/MUSIQUE DE TRANSE/Tropical Bleyage/Tropical Bleyage - Static EP (DACRU Records 2011)/01. Tropical Bleyage – Zora.flac","trackType":"flac"} Aug 26 15:56:19 primo volumio[3266]: verbose: CURRENT POSITION 0 Aug 26 15:56:19 primo volumio[3266]: info: CoreStateMachine::syncState stateService play Aug 26 15:56:19 primo volumio[3266]: info: CoreStateMachine::syncState currentStatus play Aug 26 15:56:19 primo volumio[3266]: info: Received an update from plugin. extracting info from payload Aug 26 15:56:19 primo volumio[3266]: info: CoreStateMachine::pushState Aug 26 15:56:19 primo volumio[3266]: info: CorePlayQueue::getTrack 0 Aug 26 15:56:19 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 26 15:56:19 primo volumio[3266]: info: CoreCommandRouter::volumioPushState Aug 26 15:56:19 primo volumio[3266]: info: CoreCommandRouter::volumioGetState Aug 26 15:56:19 primo volumio[3266]: info: CorePlayQueue::getTrack 0 Aug 26 15:56:19 primo volumio[3266]: info: CoreStateMachine::pushState Aug 26 15:56:19 primo volumio[3266]: info: CorePlayQueue::getTrack 0 Aug 26 15:56:19 primo volumio[3266]: info: CoreCommandRouter::volumioPushState Aug 26 15:56:19 primo volumio[3266]: info: CoreCommandRouter::volumioGetState Aug 26 15:56:19 primo volumio[3266]: info: CorePlayQueue::getTrack 0 Aug 26 15:56:19 primo volumio[3266]: info: ControllerMpd::pushState Aug 26 15:56:19 primo volumio[3266]: info: CoreCommandRouter::servicePushState Aug 26 15:56:19 primo volumio[3266]: info: CorePlayQueue::getTrack 0 Aug 26 15:56:19 primo volumio[3266]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":487,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"578 Kbps","isStreaming":false,"title":"Zora","artist":"Tropical Bleyage","album":"Static EP","uri":"USB/SSDSumsung/LossLessMusic/MUSIQUE DE TRANSE/Tropical Bleyage/Tropical Bleyage - Static EP (DACRU Records 2011)/01. Tropical Bleyage – Zora.flac","trackType":"flac"} Aug 26 15:56:19 primo volumio[3266]: verbose: CURRENT POSITION 0 Aug 26 15:56:19 primo volumio[3266]: info: CoreStateMachine::syncState stateService play Aug 26 15:56:19 primo volumio[3266]: info: CoreStateMachine::syncState currentStatus play Aug 26 15:56:19 primo volumio[3266]: info: Received an update from plugin. extracting info from payload Aug 26 15:56:19 primo volumio[3266]: info: CoreStateMachine::pushState Aug 26 15:56:19 primo volumio[3266]: info: CorePlayQueue::getTrack 0 Aug 26 15:56:19 primo volumio[3266]: info: CoreCommandRouter::volumioPushState Aug 26 15:56:19 primo volumio[3266]: info: CoreCommandRouter::volumioGetState Aug 26 15:56:19 primo volumio[3266]: info: CorePlayQueue::getTrack 0 Aug 26 15:56:19 primo volumio[3266]: info: CoreStateMachine::pushState Aug 26 15:56:19 primo volumio[3266]: info: CorePlayQueue::getTrack 0 Aug 26 15:56:19 primo volumio[3266]: info: CoreCommandRouter::volumioPushState Aug 26 15:56:19 primo volumio[3266]: info: CoreCommandRouter::volumioGetState Aug 26 15:56:19 primo volumio[3266]: info: CorePlayQueue::getTrack 0 Aug 26 15:56:19 primo volumio[3266]: info: ControllerMpd::pushState Aug 26 15:56:19 primo volumio[3266]: info: CoreCommandRouter::servicePushState Aug 26 15:56:19 primo volumio[3266]: info: CorePlayQueue::getTrack 0 Aug 26 15:56:19 primo volumio[3266]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":487,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"578 Kbps","isStreaming":false,"title":"Zora","artist":"Tropical Bleyage","album":"Static EP","uri":"USB/SSDSumsung/LossLessMusic/MUSIQUE DE TRANSE/Tropical Bleyage/Tropical Bleyage - Static EP (DACRU Records 2011)/01. Tropical Bleyage – Zora.flac","trackType":"flac"} Aug 26 15:56:19 primo volumio[3266]: verbose: CURRENT POSITION 0 Aug 26 15:56:19 primo volumio[3266]: info: CoreStateMachine::syncState stateService play Aug 26 15:56:19 primo volumio[3266]: info: CoreStateMachine::syncState currentStatus play Aug 26 15:56:19 primo volumio[3266]: info: Received an update from plugin. extracting info from payload Aug 26 15:56:19 primo volumio[3266]: info: CoreStateMachine::pushState Aug 26 15:56:19 primo volumio[3266]: info: CorePlayQueue::getTrack 0 Aug 26 15:56:19 primo volumio[3266]: info: CoreCommandRouter::volumioPushState Aug 26 15:56:19 primo volumio[3266]: info: CoreCommandRouter::volumioGetState Aug 26 15:56:19 primo volumio[3266]: info: CorePlayQueue::getTrack 0 Aug 26 15:56:19 primo volumio[3266]: info: CoreStateMachine::pushState Aug 26 15:56:19 primo volumio[3266]: info: CorePlayQueue::getTrack 0 Aug 26 15:56:19 primo volumio[3266]: info: CoreCommandRouter::volumioPushState Aug 26 15:56:19 primo volumio[3266]: info: CoreCommandRouter::volumioGetState Aug 26 15:56:19 primo volumio[3266]: info: CorePlayQueue::getTrack 0 Aug 26 15:56:19 primo volumio5-onboarding[4033]: time=2026-08-26T15:56:19.135+04:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.100.4:50459 @ 0x2680150" state=STATUS_PLAYING positionMs=0 volume=100 Aug 26 15:56:19 primo volumio5-onboarding[4033]: time=2026-08-26T15:56:19.135+04:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.4:50459 @ 0x2680150" id="mnt/USB/SSDSumsung/LossLessMusic/MUSIQUE DE TRANSE/Tropical Bleyage/Tropical Bleyage - Static EP (DACRU Records 2011)/01. Tropical Bleyage – Zora.flac" title=Zora Aug 26 15:56:19 primo volumio5-onboarding[4033]: time=2026-08-26T15:56:19.136+04:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.100.4:50459 @ 0x2680150" state=STATUS_PLAYING positionMs=0 volume=100 Aug 26 15:56:19 primo volumio5-onboarding[4033]: time=2026-08-26T15:56:19.137+04:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.4:50459 @ 0x2680150" id="mnt/USB/SSDSumsung/LossLessMusic/MUSIQUE DE TRANSE/Tropical Bleyage/Tropical Bleyage - Static EP (DACRU Records 2011)/01. Tropical Bleyage – Zora.flac" title=Zora Aug 26 15:56:19 primo volumio5-onboarding[4033]: time=2026-08-26T15:56:19.138+04:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.100.4:50459 @ 0x2680150" state=STATUS_PLAYING positionMs=0 volume=100 Aug 26 15:56:19 primo volumio5-onboarding[4033]: time=2026-08-26T15:56:19.138+04:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.4:50459 @ 0x2680150" id="mnt/USB/SSDSumsung/LossLessMusic/MUSIQUE DE TRANSE/Tropical Bleyage/Tropical Bleyage - Static EP (DACRU Records 2011)/01. Tropical Bleyage – Zora.flac" title=Zora Aug 26 15:56:19 primo volumio5-onboarding[4033]: time=2026-08-26T15:56:19.140+04:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.100.4:50459 @ 0x2680150" state=STATUS_PLAYING positionMs=0 volume=100 Aug 26 15:56:19 primo volumio5-onboarding[4033]: time=2026-08-26T15:56:19.140+04:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.4:50459 @ 0x2680150" id="mnt/USB/SSDSumsung/LossLessMusic/MUSIQUE DE TRANSE/Tropical Bleyage/Tropical Bleyage - Static EP (DACRU Records 2011)/01. Tropical Bleyage – Zora.flac" title=Zora Aug 26 15:56:19 primo volumio5-onboarding[4033]: time=2026-08-26T15:56:19.140+04:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.100.4:50459 @ 0x2680150" state=STATUS_PLAYING positionMs=0 volume=100 Aug 26 15:56:19 primo volumio5-onboarding[4033]: time=2026-08-26T15:56:19.139+04:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.100.4:50459 @ 0x2680150" state=STATUS_PLAYING positionMs=0 volume=100 Aug 26 15:56:19 primo volumio5-onboarding[4033]: time=2026-08-26T15:56:19.141+04:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.4:50459 @ 0x2680150" id="mnt/USB/SSDSumsung/LossLessMusic/MUSIQUE DE TRANSE/Tropical Bleyage/Tropical Bleyage - Static EP (DACRU Records 2011)/01. Tropical Bleyage – Zora.flac" title=Zora Aug 26 15:56:19 primo volumio5-onboarding[4033]: time=2026-08-26T15:56:19.141+04:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.4:50459 @ 0x2680150" id="mnt/USB/SSDSumsung/LossLessMusic/MUSIQUE DE TRANSE/Tropical Bleyage/Tropical Bleyage - Static EP (DACRU Records 2011)/01. Tropical Bleyage – Zora.flac" title=Zora Aug 26 15:56:19 primo volumio[3266]: info: ------------------------------ 134ms Aug 26 15:56:19 primo volumio[3266]: info: ------------------------------ 133ms Aug 26 15:56:19 primo volumio[3266]: info: ------------------------------ 114ms Aug 26 15:56:19 primo volumio[3266]: info: sendMpdCommand playlistinfo took 75 milliseconds Aug 26 15:56:19 primo volumio[3266]: info: sendMpdCommand playlistinfo took 75 milliseconds Aug 26 15:56:19 primo volumio[3266]: verbose: ControllerMpd::parseTrackInfo Aug 26 15:56:19 primo volumio[3266]: verbose: ControllerMpd::parseTrackInfo Aug 26 15:56:19 primo volumio[3266]: info: ControllerMpd::pushState Aug 26 15:56:19 primo volumio[3266]: info: CoreCommandRouter::servicePushState Aug 26 15:56:19 primo volumio[3266]: info: CorePlayQueue::getTrack 0 Aug 26 15:56:19 primo volumio[3266]: verbose: STATE SERVICE {"status":"play","position":0,"seek":45,"duration":487,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"640 Kbps","isStreaming":false,"title":"Zora","artist":"Tropical Bleyage","album":"Static EP","uri":"USB/SSDSumsung/LossLessMusic/MUSIQUE DE TRANSE/Tropical Bleyage/Tropical Bleyage - Static EP (DACRU Records 2011)/01. Tropical Bleyage – Zora.flac","trackType":"flac"} Aug 26 15:56:19 primo volumio[3266]: verbose: CURRENT POSITION 0 Aug 26 15:56:19 primo volumio[3266]: info: CoreStateMachine::syncState stateService play Aug 26 15:56:19 primo volumio[3266]: info: CoreStateMachine::syncState currentStatus play Aug 26 15:56:19 primo volumio[3266]: info: Received an update from plugin. extracting info from payload Aug 26 15:56:19 primo volumio[3266]: info: CoreStateMachine::pushState Aug 26 15:56:19 primo volumio[3266]: info: CorePlayQueue::getTrack 0 Aug 26 15:56:19 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 26 15:56:19 primo volumio[3266]: info: CoreCommandRouter::volumioPushState Aug 26 15:56:19 primo volumio[3266]: info: CoreCommandRouter::volumioGetState Aug 26 15:56:19 primo volumio[3266]: info: CorePlayQueue::getTrack 0 Aug 26 15:56:19 primo volumio[3266]: info: CoreStateMachine::pushState Aug 26 15:56:19 primo volumio[3266]: info: CorePlayQueue::getTrack 0 Aug 26 15:56:19 primo volumio[3266]: info: CoreCommandRouter::volumioPushState Aug 26 15:56:19 primo volumio[3266]: info: CoreCommandRouter::volumioGetState Aug 26 15:56:19 primo volumio[3266]: info: CorePlayQueue::getTrack 0 Aug 26 15:56:19 primo volumio[3266]: info: ControllerMpd::pushState Aug 26 15:56:19 primo volumio[3266]: info: CoreCommandRouter::servicePushState Aug 26 15:56:19 primo volumio[3266]: info: CorePlayQueue::getTrack 0 Aug 26 15:56:19 primo volumio[3266]: verbose: STATE SERVICE {"status":"play","position":0,"seek":45,"duration":487,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"640 Kbps","isStreaming":false,"title":"Zora","artist":"Tropical Bleyage","album":"Static EP","uri":"USB/SSDSumsung/LossLessMusic/MUSIQUE DE TRANSE/Tropical Bleyage/Tropical Bleyage - Static EP (DACRU Records 2011)/01. Tropical Bleyage – Zora.flac","trackType":"flac"} Aug 26 15:56:19 primo volumio[3266]: verbose: CURRENT POSITION 0 Aug 26 15:56:19 primo volumio[3266]: info: CoreStateMachine::syncState stateService play Aug 26 15:56:19 primo volumio[3266]: info: CoreStateMachine::syncState currentStatus play Aug 26 15:56:19 primo volumio[3266]: info: Received an update from plugin. extracting info from payload Aug 26 15:56:19 primo volumio[3266]: info: CoreStateMachine::pushState Aug 26 15:56:19 primo volumio[3266]: info: CorePlayQueue::getTrack 0 Aug 26 15:56:19 primo volumio[3266]: info: CoreCommandRouter::volumioPushState Aug 26 15:56:19 primo volumio[3266]: info: CoreCommandRouter::volumioGetState Aug 26 15:56:19 primo volumio[3266]: info: CorePlayQueue::getTrack 0 Aug 26 15:56:19 primo volumio[3266]: info: CoreStateMachine::pushState Aug 26 15:56:19 primo volumio[3266]: info: CorePlayQueue::getTrack 0 Aug 26 15:56:19 primo volumio[3266]: info: CoreCommandRouter::volumioPushState Aug 26 15:56:19 primo volumio[3266]: info: CoreCommandRouter::volumioGetState Aug 26 15:56:19 primo volumio[3266]: info: CorePlayQueue::getTrack 0 Aug 26 15:56:19 primo kernel: asoc-aml-card auge_sound: tdm playback enable Aug 26 15:56:19 primo kernel: spdif_a is set to enable Aug 26 15:56:19 primo volumio5-onboarding[4033]: time=2026-08-26T15:56:19.205+04:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.100.4:50459 @ 0x2680150" state=STATUS_PLAYING positionMs=45 volume=100 Aug 26 15:56:19 primo volumio5-onboarding[4033]: time=2026-08-26T15:56:19.206+04:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.4:50459 @ 0x2680150" id="mnt/USB/SSDSumsung/LossLessMusic/MUSIQUE DE TRANSE/Tropical Bleyage/Tropical Bleyage - Static EP (DACRU Records 2011)/01. Tropical Bleyage – Zora.flac" title=Zora Aug 26 15:56:19 primo volumio5-onboarding[4033]: time=2026-08-26T15:56:19.209+04:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.100.4:50459 @ 0x2680150" state=STATUS_PLAYING positionMs=45 volume=100 Aug 26 15:56:19 primo volumio5-onboarding[4033]: time=2026-08-26T15:56:19.210+04:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.4:50459 @ 0x2680150" id="mnt/USB/SSDSumsung/LossLessMusic/MUSIQUE DE TRANSE/Tropical Bleyage/Tropical Bleyage - Static EP (DACRU Records 2011)/01. Tropical Bleyage – Zora.flac" title=Zora Aug 26 15:56:19 primo volumio5-onboarding[4033]: time=2026-08-26T15:56:19.210+04:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.100.4:50459 @ 0x2680150" state=STATUS_PLAYING positionMs=45 volume=100 Aug 26 15:56:19 primo volumio5-onboarding[4033]: time=2026-08-26T15:56:19.211+04:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.4:50459 @ 0x2680150" id="mnt/USB/SSDSumsung/LossLessMusic/MUSIQUE DE TRANSE/Tropical Bleyage/Tropical Bleyage - Static EP (DACRU Records 2011)/01. Tropical Bleyage – Zora.flac" title=Zora Aug 26 15:56:19 primo volumio5-onboarding[4033]: time=2026-08-26T15:56:19.212+04:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.100.4:50459 @ 0x2680150" state=STATUS_PLAYING positionMs=45 volume=100 Aug 26 15:56:19 primo volumio5-onboarding[4033]: time=2026-08-26T15:56:19.212+04:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.4:50459 @ 0x2680150" id="mnt/USB/SSDSumsung/LossLessMusic/MUSIQUE DE TRANSE/Tropical Bleyage/Tropical Bleyage - Static EP (DACRU Records 2011)/01. Tropical Bleyage – Zora.flac" title=Zora Aug 26 15:56:19 primo volumio[3266]: info: ------------------------------ 148ms Aug 26 15:56:19 primo volumio[3266]: info: ------------------------------ 148ms Aug 26 15:56:19 primo volumio[3266]: info: Signalling Playback active due to playback status change Aug 26 15:56:19 primo volumio[3266]: info: Signalling Playback active due to playback status change Aug 26 15:56:19 primo volumio[3266]: info: Signalling Playback active due to playback status change Aug 26 15:56:19 primo volumio[3266]: info: Signalling Playback active due to playback status change Aug 26 15:56:19 primo volumio[3266]: info: Signalling Playback active due to playback status change Aug 26 15:56:19 primo volumio[3266]: info: Signalling Playback active due to playback status change Aug 26 15:56:19 primo volumio[3266]: info: Signalling Playback active due to playback status change Aug 26 15:56:19 primo volumio[3266]: info: Signalling Playback active due to playback status change Aug 26 15:56:19 primo volumio[3266]: info: Signalling Playback active due to playback status change Aug 26 15:56:19 primo volumio[3266]: info: Signalling Playback active due to playback status change Aug 26 15:56:19 primo volumio[3266]: info: Updating RAAT Signal Path Aug 26 15:56:19 primo volumio[3266]: info: Updating RAAT Signal Path Aug 26 15:56:19 primo volumio[3266]: info: Updating RAAT Signal Path Aug 26 15:56:19 primo volumio[3266]: info: Updating RAAT Signal Path Aug 26 15:56:19 primo volumio[3266]: info: Updating RAAT Signal Path Aug 26 15:56:19 primo volumio[3266]: info: Updating RAAT Signal Path Aug 26 15:56:19 primo volumio[3266]: info: Updating RAAT Signal Path Aug 26 15:56:19 primo volumio[3266]: info: Updating RAAT Signal Path Aug 26 15:56:19 primo volumio[3266]: info: Updating RAAT Signal Path Aug 26 15:56:19 primo volumio[3266]: info: Updating RAAT Signal Path Aug 26 15:56:24 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri Aug 26 15:56:24 primo volumio[3266]: info: CURURI: music-library Aug 26 15:56:24 primo volumio[3266]: info: Preload queue cleared Aug 26 15:56:25 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri Aug 26 15:56:25 primo volumio[3266]: info: CURURI: music-library/USB Aug 26 15:56:25 primo volumio[3266]: info: Preload queue cleared Aug 26 15:56:25 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri Aug 26 15:56:25 primo volumio[3266]: info: CURURI: music-library/USB/SSDSumsung Aug 26 15:56:25 primo volumio[3266]: info: Preload queue cleared Aug 26 15:56:26 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri Aug 26 15:56:26 primo volumio[3266]: info: CURURI: music-library/USB/SSDSumsung/LossLessMusic Aug 26 15:56:26 primo volumio[3266]: info: Preload queue cleared Aug 26 15:56:33 primo volumio[3266]: info: Preload queue cleared Aug 26 15:56:33 primo volumio[3266]: info: CoreCommandRouter::volumioReplaceandPlayItems Aug 26 15:56:33 primo volumio[3266]: info: CoreStateMachine::ClearQueue Aug 26 15:56:33 primo volumio[3266]: info: CoreStateMachine::stop Aug 26 15:56:33 primo volumio[3266]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 26 15:56:33 primo volumio[3266]: info: CoreStateMachine::stPlaybackTimer Aug 26 15:56:33 primo volumio[3266]: info: CoreStateMachine::updateTrackBlock Aug 26 15:56:33 primo volumio[3266]: info: CorePlayQueue::getTrackBlock Aug 26 15:56:33 primo volumio[3266]: info: CoreStateMachine::pushState Aug 26 15:56:33 primo volumio[3266]: info: CorePlayQueue::getTrack 0 Aug 26 15:56:33 primo volumio[3266]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 26 15:56:33 primo volumio[3266]: info: CoreCommandRouter::volumioPushState Aug 26 15:56:33 primo volumio[3266]: info: CoreCommandRouter::volumioGetState Aug 26 15:56:33 primo volumio[3266]: info: CorePlayQueue::getTrack 0 Aug 26 15:56:33 primo volumio[3266]: info: CoreStateMachine::serviceStop Aug 26 15:56:33 primo volumio[3266]: info: CorePlayQueue::getTrack 0 Aug 26 15:56:33 primo volumio[3266]: info: CoreCommandRouter::serviceStop Aug 26 15:56:33 primo volumio[3266]: info: ControllerMpd::stop Aug 26 15:56:33 primo volumio[3266]: verbose: ControllerMpd::sendMpdCommand stop Aug 26 15:56:33 primo volumio[3266]: info: CorePlayQueue::clearPlayQueue Aug 26 15:56:33 primo volumio[3266]: info: CorePlayQueue::saveQueue Aug 26 15:56:33 primo volumio[3266]: info: CoreCommandRouter::volumioPushQueue Aug 26 15:56:33 primo volumio[3266]: info: CoreStateMachine::addQueueItems Aug 26 15:56:33 primo volumio[3266]: info: CorePlayQueue::addQueueItems Aug 26 15:56:33 primo volumio[3266]: info: Preload queue cleared Aug 26 15:56:33 primo volumio[3266]: info: Adding Item to queue: music-library/USB/SSDSumsung/LossLessMusic/MUSIQUE DE TRANSE Aug 26 15:56:33 primo volumio[3266]: info: Exploding uri music-library/USB/SSDSumsung/LossLessMusic/MUSIQUE DE TRANSE in service mpd Aug 26 15:56:35 primo volumio5-onboarding[4033]: time=2026-08-26T15:56:35.358+04:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.100.4:50459 @ 0x2680150" state=STATUS_STOPPED positionMs=0 volume=100 Aug 26 15:56:35 primo volumio5-onboarding[4033]: time=2026-08-26T15:56:35.358+04:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.100.4:50459 @ 0x2680150" id="mnt/USB/SSDSumsung/LossLessMusic/MUSIQUE DE TRANSE/Tropical Bleyage/Tropical Bleyage - Static EP (DACRU Records 2011)/01. Tropical Bleyage – Zora.flac" title=Zora Aug 26 15:56:35 primo kernel: asoc-aml-card auge_sound: tdm playback stop Aug 26 15:56:35 primo kernel: spdif_a is set to disable Aug 26 15:56:35 primo kernel: audio_ddr_mngr: frddr_set_sharebuffer_enable sel:1, dst_src:3 Aug 26 15:56:35 primo kernel: aml_dai_tdm_hw_free(), disable mclk for TDM-B Aug 26 15:56:35 primo kernel: tdm playback mute: 1, lane_cnt = 8 Aug 26 15:56:35 primo kernel: audio_ddr_mngr: frddrs[0] released by device ff660000.audiobus:tdm@1 Aug 26 15:56:35 primo volumio[3266]: info: Updating RAAT Signal Path Aug 26 15:56:35 primo volumio[3266]: info: Aug 26 15:56:35 primo volumio[3266]: ---------------------------- MPD announces state update: player Aug 26 15:56:35 primo volumio[3266]: info: ALBUMART /albumart?cacheid=880&web=1200%20Micrograms/1200%20Micrograms%20Remixes/extralarge&path=%2Fmnt%2FUSB%2FSSDSumsung%2FLossLessMusic%2FMUSIQUE%20DE%20TRANSE%2F1200%20Micrograms%20-%20Remixes%2F1200%20Micrograms%20-%201200%20Micrograms%20Remixes%20-%2001%20-%20High%20Paradise.flac&metadata=false Aug 26 15:56:35 primo volumio[3266]: info: URI /mnt/USB/SSDSumsung/LossLessMusic/MUSIQUE DE TRANSE/1200 Micrograms - Remixes/1200 Micrograms - 1200 Micrograms Remixes - 01 - High Paradise.flac Aug 26 15:56:35 primo volumio[3266]: info: ALBUMART /albumart?cacheid=880&web=Astrix/1200%20Micrograms%20Remixes/extralarge&path=%2Fmnt%2FUSB%2FSSDSumsung%2FLossLessMusic%2FMUSIQUE%20DE%20TRANSE%2F1200%20Micrograms%20-%20Remixes%2FAstrix%20-%201200%20Micrograms%20Remixes%20-%2002%20-%20Mescaline.flac&metadata=false Aug 26 15:56:35 primo volumio[3266]: info: URI /mnt/USB/SSDSumsung/LossLessMusic/MUSIQUE DE TRANSE/1200 Micrograms - Remixes/Astrix - 1200 Micrograms Remixes - 02 - Mescaline.flac Aug 26 15:56:35 primo volumio[3266]: info: ALBUMART /albumart?cacheid=880&web=Atomic%20Pulse/1200%20Micrograms%20Remixes/extralarge&path=%2Fmnt%2FUSB%2FSSDSumsung%2FLossLessMusic%2FMUSIQUE%20DE%20TRANSE%2F1200%20Micrograms%20-%20Remixes%2FAtomic%20Pulse%20-%201200%20Micrograms%20Remixes%20-%2004%20-%20Hashish.flac&metadata=false Aug 26 15:56:35 primo volumio[3266]: info: URI /mnt/USB/SSDSumsung/LossLessMusic/MUSIQUE DE TRANSE/1200 Micrograms - Remixes/Atomic Pulse - 1200 Micrograms Remixes - 04 - Hashish.flac Aug 26 15:56:35 primo volumio[3266]: info: ALBUMART /albumart?cacheid=880&web=Deedrah/1200%20Micrograms%20Remixes/extralarge&path=%2Fmnt%2FUSB%2FSSDSumsung%2FLossLessMusic%2FMUSIQUE%20DE%20TRANSE%2F1200%20Micrograms%20-%20Remixes%2FDeedrah%20-%201200%20Micrograms%20Remixes%20-%2009%20-%20Ecstacy.flac&metadata=false Aug 26 15:56:35 primo volumio[3266]: info: URI /mnt/USB/SSDSumsung/LossLessMusic/MUSIQUE DE TRANSE/1200 Micrograms - Remixes/Deedrah - 1200 Micrograms Remixes - 09 - Ecstacy.flac Aug 26 15:56:35 primo volumio[3266]: info: ALBUMART /albumart?cacheid=880&web=Eat%20Static/1200%20Micrograms%20Remixes/extralarge&path=%2Fmnt%2FUSB%2FSSDSumsung%2FLossLessMusic%2FMUSIQUE%20DE%20TRANSE%2F1200%20Micrograms%20-%20Remixes%2FEat%20Static%20-%201200%20Micrograms%20Remixes%20-%2008%20-%20Egypt.flac&metadata=false Aug 26 15:56:35 primo volumio[3266]: info: URI /mnt/USB/SSDSumsung/LossLessMusic/MUSIQUE DE TRANSE/1200 Micrograms - Remixes/Eat Static - 1200 Micrograms Remixes - 08 - Egypt.flac Aug 26 15:56:35 primo volumio[3266]: info: ALBUMART /albumart?cacheid=880&web=Hujaboy/1200%20Micrograms%20Remixes/extralarge&path=%2Fmnt%2FUSB%2FSSDSumsung%2FLossLessMusic%2FMUSIQUE%20DE%20TRANSE%2F1200%20Micrograms%20-%20Remixes%2FHujaboy%20-%201200%20Micrograms%20Remixes%20-%2006%20-%20Language%20Of%20The%20Future.flac&metadata=false Aug 26 15:56:35 primo volumio[3266]: info: URI /mnt/USB/SSDSumsung/LossLessMusic/MUSIQUE DE TRANSE/1200 Micrograms - Remixes/Hujaboy - 1200 Micrograms Remixes - 06 - Language Of The Future.flac Aug 26 15:56:35 primo volumio[3266]: info: ALBUMART /albumart?cacheid=880&web=Save%20The%20Robot/1200%20Micrograms%20Remixes/extralarge&path=%2Fmnt%2FUSB%2FSSDSumsung%2FLossLessMusic%2FMUSIQUE%20DE%20TRANSE%2F1200%20Micrograms%20-%20Remixes%2FSave%20The%20Robot%20-%201200%20Micrograms%20Remixes%20-%2005%20-%20Greece.flac&metadata=false Aug 26 15:56:35 primo volumio[3266]: info: URI /mnt/USB/SSDSumsung/LossLessMusic/MUSIQUE DE TRANSE/1200 Micrograms - Remixes/Save The Robot - 1200 Micrograms Remixes - 05 - Greece.flac Aug 26 15:56:35 primo volumio[3266]: info: ALBUMART /albumart?cacheid=880&web=Shanti/1200%20Micrograms%20Remixes/extralarge&path=%2Fmnt%2FUSB%2FSSDSumsung%2FLossLessMusic%2FMUSIQUE%20DE%20TRANSE%2F1200%20Micrograms%20-%20Remixes%2FShanti%20-%201200%20Micrograms%20Remixes%20-%2003%20-%20E%3Dmc%C2%B2.flac&metadata=false Aug 26 15:56:35 primo volumio[3266]: info: URI /mnt/USB/SSDSumsung/LossLessMusic/MUSIQUE DE TRANSE/1200 Micrograms - Remixes/Shanti - 1200 Micrograms Remixes - 03 - E=mc².flac Aug 26 15:56:35 primo volumio[3266]: info: ALBUMART /albumart?cacheid=880&web=Xerox%20%26%20Illumination/1200%20Micrograms%20Remixes/extralarge&path=%2Fmnt%2FUSB%2FSSDSumsung%2FLossLessMusic%2FMUSIQUE%20DE%20TRANSE%2F1200%20Micrograms%20-%20Remixes%2FXerox%20%26%20Illumination%20-%201200%20Micrograms%20Remixes%20-%2007%20-%20India.flac&metadata=false Aug 26 15:56:35 primo volumio[3266]: info: URI /mnt/USB/SSDSumsung/LossLessMusic/MUSIQUE DE TRANSE/1200 Micrograms - Remixes/Xerox & Illumination - 1200 Micrograms Remixes - 07 - India.flac Aug 26 15:56:35 primo volumio[3266]: info: ALBUMART /albumart?cacheid=880&web=1200%20Micrograms/Remixes/extralarge&path=%2Fmnt%2FUSB%2FSSDSumsung%2FLossLessMusic%2FMUSIQUE%20DE%20TRANSE%2F1200%20micrograms%2F1200%20%20%20micrograms%2F1200%20Micrograms.cue&metadata=false Aug 26 15:56:35 primo volumio[3266]: info: URI /mnt/USB/SSDSumsung/LossLessMusic/MUSIQUE DE TRANSE/1200 micrograms/1200 micrograms/1200 Micrograms.cue Aug 26 15:56:35 primo volumio[3266]: info: ALBUMART /albumart?cacheid=880&web=1200%20Micrograms/Remixes/extralarge&path=%2Fmnt%2FUSB%2FSSDSumsung%2FLossLessMusic%2FMUSIQUE%20DE%20TRANSE%2F1200%20micrograms%2F1200%20%20%20micrograms%2F1200%20Micrograms.cue&metadata=false Aug 26 15:56:35 primo volumio[3266]: info: URI /mnt/USB/SSDSumsung/LossLessMusic/MUSIQUE DE TRANSE/1200 micrograms/1200 micrograms/1200 Micrograms.cue Aug 26 15:56:35 primo volumio[3266]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 26 15:56:35 primo volumio[3266]: Error: Unable to resolve or reject the same promise twice Aug 26 15:56:35 primo volumio[3266]: at Promise.resolve (/volumio/node_modules/kew/kew.js:140:43) Aug 26 15:56:35 primo volumio[3266]: at /volumio/app/plugins/music_service/mpd/index.js:2582:21 Aug 26 15:56:35 primo volumio[3266]: at MpdClient.handleMessage (/volumio/app/plugins/music_service/mpd/lib/mpd.js:77:3) Aug 26 15:56:35 primo volumio[3266]: at MpdClient.receive (/volumio/app/plugins/music_service/mpd/lib/mpd.js:68:12) Aug 26 15:56:35 primo volumio[3266]: at Socket. (/volumio/app/plugins/music_service/mpd/lib/mpd.js:43:12) Aug 26 15:56:35 primo volumio[3266]: at Socket.emit (node:events:514:28) Aug 26 15:56:35 primo volumio[3266]: at addChunk (node:internal/streams/readable:343:12) Aug 26 15:56:35 primo volumio[3266]: at readableAddChunk (node:internal/streams/readable:312:11) Aug 26 15:56:35 primo volumio[3266]: at Readable.push (node:internal/streams/readable:253:10) Aug 26 15:56:35 primo volumio[3266]: at Pipe.onStreamRead (node:internal/stream_base_commons:190:23) Aug 26 15:56:35 primo volumio[3266]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 26 15:56:36 primo sudo[11042]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-08-26 15:55' Aug 26 15:56:36 primo sudo[11042]: 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"