-- Logs begin at Fri 2023-10-20 23:06:54 CST, end at Mon 2026-02-09 14:06:30 CST. -- Feb 09 14:05:05 primo volumio5-onboarding[3639]: time=2026-02-09T14:05:05.890+08:00 level=INFO msg="new address was allocated" component=conn/ble old=189 new=190 Feb 09 14:05:06 primo dbus-daemon[2837]: [system] Rejected send message, 1 matched rules; type="error", sender=":1.13" (uid=0 pid=3639 comm="/usr/bin/volumio5-onboarding " label="kernel") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.5" (uid=0 pid=3195 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap,hostn" label="kernel") Feb 09 14:05:06 primo dbus-daemon[2837]: [system] Rejected send message, 1 matched rules; type="error", sender=":1.13" (uid=0 pid=3639 comm="/usr/bin/volumio5-onboarding " label="kernel") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.5" (uid=0 pid=3195 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap,hostn" label="kernel") Feb 09 14:05:11 primo volumio5-onboarding[3639]: time=2026-02-09T14:05:11.290+08:00 level=INFO msg="new address was allocated" component=conn/ble old=190 new=191 Feb 09 14:05:11 primo dbus-daemon[2837]: [system] Rejected send message, 1 matched rules; type="error", sender=":1.13" (uid=0 pid=3639 comm="/usr/bin/volumio5-onboarding " label="kernel") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.5" (uid=0 pid=3195 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap,hostn" label="kernel") Feb 09 14:05:12 primo dbus-daemon[2837]: [system] Rejected send message, 1 matched rules; type="error", sender=":1.13" (uid=0 pid=3639 comm="/usr/bin/volumio5-onboarding " label="kernel") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.5" (uid=0 pid=3195 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap,hostn" label="kernel") Feb 09 14:05:13 primo volumio[3256]: info: MCU Signalled Sleep Mode Disabled Feb 09 14:05:14 primo volumio[3256]: info: CoreStateMachine::pushState Feb 09 14:05:14 primo volumio[3256]: info: CorePlayQueue::getTrack 0 Feb 09 14:05:14 primo volumio[3256]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 09 14:05:14 primo volumio[3256]: info: CoreCommandRouter::volumioPushState Feb 09 14:05:14 primo volumio[3256]: info: CoreCommandRouter::volumioGetState Feb 09 14:05:14 primo volumio[3256]: info: CorePlayQueue::getTrack 0 Feb 09 14:05:14 primo volumio[3256]: info: MRS: Pushing multiroomSync output update for this device Feb 09 14:05:14 primo volumio[3256]: info: MRS: Pushing multiroomSync output Feb 09 14:05:14 primo volumio[3256]: info: CoreStateMachine::pushState Feb 09 14:05:14 primo volumio[3256]: info: CorePlayQueue::getTrack 0 Feb 09 14:05:14 primo volumio[3256]: info: CoreCommandRouter::volumioPushState Feb 09 14:05:14 primo volumio[3256]: info: CoreCommandRouter::volumioGetState Feb 09 14:05:14 primo volumio[3256]: info: CorePlayQueue::getTrack 0 Feb 09 14:05:14 primo volumio[3256]: info: MRS: Pushing multiroomSync output update for this device Feb 09 14:05:14 primo volumio[3256]: info: MRS: Pushing multiroomSync output Feb 09 14:05:14 primo sudo[5328]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/bin/xset dpms force on Feb 09 14:05:14 primo sudo[5328]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 09 14:05:14 primo volumio5-onboarding[3639]: time=2026-02-09T14:05:14.038+08:00 level=ERROR msg="failed to send event" component=server dst="192.168.100.142:63996 @ 0x27f7b90" event=SERVER_EVENT_TYPE_PLAYER_STATE_CHANGED error="no WebSocket connection found for address: 192.168.100.142:63996" Feb 09 14:05:14 primo volumio5-onboarding[3639]: time=2026-02-09T14:05:14.039+08:00 level=ERROR msg="failed to send event" component=server dst="192.168.100.142:64390 @ 0x2800060" event=SERVER_EVENT_TYPE_PLAYER_STATE_CHANGED error="no WebSocket connection found for address: 192.168.100.142:64390" Feb 09 14:05:14 primo volumio5-onboarding[3639]: time=2026-02-09T14:05:14.039+08:00 level=ERROR msg="failed to send event" component=server dst="192.168.100.142:64841 @ 0x2401c50" event=SERVER_EVENT_TYPE_PLAYER_STATE_CHANGED error="no WebSocket connection found for address: 192.168.100.142:64841" Feb 09 14:05:14 primo volumio5-onboarding[3639]: time=2026-02-09T14:05:14.040+08:00 level=ERROR msg="failed to send event" component=server dst="192.168.100.142:65009 @ 0x2800750" event=SERVER_EVENT_TYPE_PLAYER_STATE_CHANGED error="no WebSocket connection found for address: 192.168.100.142:65009" Feb 09 14:05:14 primo volumio5-onboarding[3639]: time=2026-02-09T14:05:14.040+08:00 level=ERROR msg="failed to send event" component=server dst="192.168.100.142:65194 @ 0x276d440" event=SERVER_EVENT_TYPE_PLAYER_STATE_CHANGED error="no WebSocket connection found for address: 192.168.100.142:65194" Feb 09 14:05:14 primo sudo[5328]: pam_unix(sudo:session): session closed for user root Feb 09 14:05:14 primo volumio[3256]: info: Updating RAAT Signal Path Feb 09 14:05:14 primo volumio[3256]: info: Updating RAAT Signal Path Feb 09 14:05:14 primo volumio[3256]: error: Serial API: Failed to decode command: LEDCOLOR, message: 2 Feb 09 14:05:14 primo sudo[5331]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/bin/xset dpms 0 0 0 Feb 09 14:05:14 primo sudo[5331]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 09 14:05:14 primo sudo[5331]: pam_unix(sudo:session): session closed for user root Feb 09 14:05:14 primo volumio[3256]: info: CoreStateMachine::pushState Feb 09 14:05:14 primo volumio[3256]: info: CorePlayQueue::getTrack 0 Feb 09 14:05:14 primo volumio[3256]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 09 14:05:14 primo volumio[3256]: info: CoreCommandRouter::volumioPushState Feb 09 14:05:14 primo volumio[3256]: info: CoreCommandRouter::volumioGetState Feb 09 14:05:14 primo volumio[3256]: info: CorePlayQueue::getTrack 0 Feb 09 14:05:14 primo volumio[3256]: info: MRS: Pushing multiroomSync output update for this device Feb 09 14:05:14 primo volumio[3256]: info: MRS: Pushing multiroomSync output Feb 09 14:05:14 primo volumio[3256]: info: Updating RAAT Signal Path Feb 09 14:05:14 primo volumio[3256]: info: MCU Signalled Sleep Mode Active Feb 09 14:05:14 primo sudo[5334]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/bin/xset dpms force off Feb 09 14:05:14 primo sudo[5334]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 09 14:05:14 primo volumio[3256]: error: Serial API: Failed to decode command: LEDCOLOR, message: 8 Feb 09 14:05:14 primo sudo[5334]: pam_unix(sudo:session): session closed for user root Feb 09 14:05:15 primo volumio[3256]: info: MCU Signalled Sleep Mode Disabled Feb 09 14:05:15 primo volumio[3256]: info: CoreStateMachine::pushState Feb 09 14:05:15 primo volumio[3256]: info: CorePlayQueue::getTrack 0 Feb 09 14:05:15 primo volumio[3256]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 09 14:05:15 primo volumio[3256]: info: CoreCommandRouter::volumioPushState Feb 09 14:05:15 primo volumio[3256]: info: CoreCommandRouter::volumioGetState Feb 09 14:05:15 primo volumio[3256]: info: CorePlayQueue::getTrack 0 Feb 09 14:05:15 primo volumio[3256]: info: MRS: Pushing multiroomSync output update for this device Feb 09 14:05:15 primo volumio[3256]: info: MRS: Pushing multiroomSync output Feb 09 14:05:15 primo volumio[3256]: info: CoreStateMachine::pushState Feb 09 14:05:15 primo volumio[3256]: info: CorePlayQueue::getTrack 0 Feb 09 14:05:15 primo volumio[3256]: info: CoreCommandRouter::volumioPushState Feb 09 14:05:15 primo volumio[3256]: info: CoreCommandRouter::volumioGetState Feb 09 14:05:15 primo volumio[3256]: info: CorePlayQueue::getTrack 0 Feb 09 14:05:15 primo volumio[3256]: info: MRS: Pushing multiroomSync output update for this device Feb 09 14:05:15 primo volumio[3256]: info: MRS: Pushing multiroomSync output Feb 09 14:05:15 primo sudo[5339]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/bin/xset dpms force on Feb 09 14:05:15 primo sudo[5339]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 09 14:05:15 primo sudo[5339]: pam_unix(sudo:session): session closed for user root Feb 09 14:05:15 primo volumio[3256]: info: Updating RAAT Signal Path Feb 09 14:05:15 primo volumio[3256]: info: Updating RAAT Signal Path Feb 09 14:05:15 primo volumio[3256]: error: Serial API: Failed to decode command: LEDCOLOR, message: 2 Feb 09 14:05:16 primo sudo[5342]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/bin/xset dpms 0 0 0 Feb 09 14:05:16 primo sudo[5342]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 09 14:05:16 primo sudo[5342]: pam_unix(sudo:session): session closed for user root Feb 09 14:05:16 primo volumio5-onboarding[3639]: time=2026-02-09T14:05:16.961+08:00 level=INFO msg="new address was allocated" component=conn/ble old=191 new=192 Feb 09 14:05:17 primo dbus-daemon[2837]: [system] Rejected send message, 1 matched rules; type="error", sender=":1.13" (uid=0 pid=3639 comm="/usr/bin/volumio5-onboarding " label="kernel") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.5" (uid=0 pid=3195 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap,hostn" label="kernel") Feb 09 14:05:17 primo dbus-daemon[2837]: [system] Rejected send message, 1 matched rules; type="error", sender=":1.13" (uid=0 pid=3639 comm="/usr/bin/volumio5-onboarding " label="kernel") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.5" (uid=0 pid=3195 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap,hostn" label="kernel") Feb 09 14:05:24 primo volumio5-onboarding[3639]: time=2026-02-09T14:05:24.521+08:00 level=INFO msg="new address was allocated" component=conn/ble old=192 new=193 Feb 09 14:05:24 primo dbus-daemon[2837]: [system] Rejected send message, 1 matched rules; type="error", sender=":1.13" (uid=0 pid=3639 comm="/usr/bin/volumio5-onboarding " label="kernel") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.5" (uid=0 pid=3195 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap,hostn" label="kernel") Feb 09 14:05:25 primo dbus-daemon[2837]: [system] Rejected send message, 1 matched rules; type="error", sender=":1.13" (uid=0 pid=3639 comm="/usr/bin/volumio5-onboarding " label="kernel") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.5" (uid=0 pid=3195 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap,hostn" label="kernel") Feb 09 14:05:29 primo volumio5-onboarding[3639]: time=2026-02-09T14:05:29.111+08:00 level=INFO msg="new address was allocated" component=conn/ble old=193 new=194 Feb 09 14:05:29 primo dbus-daemon[2837]: [system] Rejected send message, 1 matched rules; type="error", sender=":1.13" (uid=0 pid=3639 comm="/usr/bin/volumio5-onboarding " label="kernel") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.5" (uid=0 pid=3195 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap,hostn" label="kernel") Feb 09 14:05:29 primo dbus-daemon[2837]: [system] Rejected send message, 1 matched rules; type="error", sender=":1.13" (uid=0 pid=3639 comm="/usr/bin/volumio5-onboarding " label="kernel") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.5" (uid=0 pid=3195 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap,hostn" label="kernel") Feb 09 14:05:35 primo volumio5-onboarding[3639]: time=2026-02-09T14:05:35.186+08:00 level=INFO msg="new address was allocated" component=conn/ble old=194 new=195 Feb 09 14:05:35 primo dbus-daemon[2837]: [system] Rejected send message, 1 matched rules; type="error", sender=":1.13" (uid=0 pid=3639 comm="/usr/bin/volumio5-onboarding " label="kernel") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.5" (uid=0 pid=3195 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap,hostn" label="kernel") Feb 09 14:05:35 primo dbus-daemon[2837]: [system] Rejected send message, 1 matched rules; type="error", sender=":1.13" (uid=0 pid=3639 comm="/usr/bin/volumio5-onboarding " label="kernel") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.5" (uid=0 pid=3195 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap,hostn" label="kernel") Feb 09 14:05:41 primo volumio5-onboarding[3639]: time=2026-02-09T14:05:41.261+08:00 level=INFO msg="new address was allocated" component=conn/ble old=195 new=196 Feb 09 14:05:41 primo dbus-daemon[2837]: [system] Rejected send message, 1 matched rules; type="error", sender=":1.13" (uid=0 pid=3639 comm="/usr/bin/volumio5-onboarding " label="kernel") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.5" (uid=0 pid=3195 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap,hostn" label="kernel") Feb 09 14:05:42 primo dbus-daemon[2837]: [system] Rejected send message, 1 matched rules; type="error", sender=":1.13" (uid=0 pid=3639 comm="/usr/bin/volumio5-onboarding " label="kernel") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.5" (uid=0 pid=3195 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap,hostn" label="kernel") Feb 09 14:05:56 primo volumio5-onboarding[3639]: time=2026-02-09T14:05:56.449+08:00 level=INFO msg="new address was allocated" component=conn/ble old=196 new=197 Feb 09 14:05:56 primo dbus-daemon[2837]: [system] Rejected send message, 1 matched rules; type="error", sender=":1.13" (uid=0 pid=3639 comm="/usr/bin/volumio5-onboarding " label="kernel") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.5" (uid=0 pid=3195 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap,hostn" label="kernel") Feb 09 14:05:56 primo volumio5-onboarding[3639]: time=2026-02-09T14:05:56.977+08:00 level=INFO msg="continue navigation request" component=server type=REQUEST_TYPE_CONTINUE_NAVIGATION peer="192.168.100.142:49228 @ 0x2516a50" latency=61.867588ms timeout=10s from=APP_PAGE_ROOT Feb 09 14:05:57 primo volumio5-onboarding[3639]: time=2026-02-09T14:05:57.291+08:00 level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=196 Feb 09 14:05:57 primo sudo[5549]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Feb 09 14:05:57 primo sudo[5549]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 09 14:05:57 primo sudo[5549]: pam_unix(sudo:session): session closed for user root Feb 09 14:05:57 primo sudo[5553]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Feb 09 14:05:57 primo sudo[5553]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 09 14:05:57 primo sudo[5553]: pam_unix(sudo:session): session closed for user root Feb 09 14:05:57 primo volumio[3256]: verbose: New Socket.io Connection to 192.168.100.233 from 192.168.100.142 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: 7 Feb 09 14:05:57 primo volumio[3256]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Feb 09 14:05:57 primo volumio[3256]: info: CoreCommandRouter::volumioGetVisibleSources Feb 09 14:05:57 primo volumio[3256]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 09 14:05:57 primo volumio[3256]: info: CoreCommandRouter::volumioGetState Feb 09 14:05:57 primo volumio[3256]: info: CorePlayQueue::getTrack 0 Feb 09 14:05:57 primo volumio[3256]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Feb 09 14:05:57 primo volumio[3256]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Feb 09 14:05:57 primo volumio[3256]: info: Error : CoreCommandRouter::executeOnPlugin: No method [getMultiroom] in plugin multiroom Feb 09 14:05:57 primo volumio[3256]: info: Received Get System Info Feb 09 14:05:57 primo volumio[3256]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Feb 09 14:05:57 primo volumio[3256]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Feb 09 14:05:57 primo volumio[3256]: info: Discovery: Getting this device information Feb 09 14:05:57 primo volumio[3256]: info: CoreCommandRouter::volumioGetState Feb 09 14:05:57 primo volumio[3256]: info: CorePlayQueue::getTrack 0 Feb 09 14:05:57 primo volumio[3256]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 09 14:05:57 primo volumio[3256]: info: CoreCommandRouter::volumioGetState Feb 09 14:05:57 primo volumio[3256]: info: CorePlayQueue::getTrack 0 Feb 09 14:05:57 primo volumio[3256]: info: Listing playlists Feb 09 14:05:57 primo sudo[5559]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Feb 09 14:05:57 primo sudo[5559]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 09 14:05:57 primo sudo[5559]: pam_unix(sudo:session): session closed for user root Feb 09 14:05:57 primo sudo[5562]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Feb 09 14:05:57 primo sudo[5562]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 09 14:05:57 primo sudo[5562]: pam_unix(sudo:session): session closed for user root Feb 09 14:05:57 primo volumio[3256]: verbose: New Socket.io Connection to 192.168.100.233 from 192.168.100.142 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: 7 Feb 09 14:05:57 primo volumio[3256]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Feb 09 14:05:57 primo volumio[3256]: info: CoreCommandRouter::volumioGetVisibleSources Feb 09 14:05:57 primo volumio[3256]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 09 14:05:57 primo volumio[3256]: info: CoreCommandRouter::volumioGetState Feb 09 14:05:57 primo volumio[3256]: info: CorePlayQueue::getTrack 0 Feb 09 14:05:57 primo volumio[3256]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Feb 09 14:05:57 primo volumio[3256]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Feb 09 14:05:57 primo volumio[3256]: info: Error : CoreCommandRouter::executeOnPlugin: No method [getMultiroom] in plugin multiroom Feb 09 14:05:57 primo volumio[3256]: info: Received Get System Info Feb 09 14:05:57 primo volumio[3256]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Feb 09 14:05:57 primo volumio[3256]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Feb 09 14:05:57 primo volumio[3256]: info: Discovery: Getting this device information Feb 09 14:05:57 primo volumio[3256]: info: CoreCommandRouter::volumioGetState Feb 09 14:05:57 primo volumio[3256]: info: CorePlayQueue::getTrack 0 Feb 09 14:05:57 primo volumio[3256]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 09 14:05:57 primo volumio[3256]: info: CoreCommandRouter::volumioGetState Feb 09 14:05:57 primo volumio[3256]: info: CorePlayQueue::getTrack 0 Feb 09 14:05:57 primo volumio[3256]: info: Listing playlists Feb 09 14:05:57 primo volumio[3256]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Feb 09 14:05:57 primo volumio[3256]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Feb 09 14:05:59 primo volumio[3256]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Feb 09 14:05:59 primo volumio[3256]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Feb 09 14:05:59 primo volumio[3256]: info: Received Get System Info Feb 09 14:05:59 primo volumio[3256]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Feb 09 14:05:59 primo volumio[3256]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Feb 09 14:05:59 primo volumio[3256]: info: Discovery: Getting this device information Feb 09 14:05:59 primo volumio[3256]: info: CoreCommandRouter::volumioGetState Feb 09 14:05:59 primo volumio[3256]: info: CorePlayQueue::getTrack 0 Feb 09 14:05:59 primo volumio[3256]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 09 14:05:59 primo volumio[3256]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Feb 09 14:06:00 primo volumio5-onboarding[3639]: time=2026-02-09T14:06:00.769+08:00 level=WARN msg="received acknowledgment for source with no pending writes" component=conn/ble data=c400 addr=196 Feb 09 14:06:01 primo volumio5-onboarding[3639]: time=2026-02-09T14:06:01.205+08:00 level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=196 Feb 09 14:06:01 primo volumio5-onboarding[3639]: time=2026-02-09T14:06:01.543+08:00 level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=196 Feb 09 14:06:01 primo volumio[3256]: info: CoreCommandRouter::volumioGetQueue Feb 09 14:06:01 primo volumio[3256]: info: CoreStateMachine::getQueue Feb 09 14:06:01 primo volumio[3256]: info: CorePlayQueue::getQueue Feb 09 14:06:02 primo volumio5-onboarding[3639]: time=2026-02-09T14:06:02.321+08:00 level=WARN msg="received acknowledgment for source with no pending writes" component=conn/ble data=c400 addr=196 Feb 09 14:06:02 primo volumio[3256]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Feb 09 14:06:02 primo volumio[3256]: info: Received Get System Info Feb 09 14:06:02 primo volumio[3256]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Feb 09 14:06:02 primo volumio[3256]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Feb 09 14:06:02 primo volumio[3256]: info: Discovery: Getting this device information Feb 09 14:06:02 primo volumio[3256]: info: CoreCommandRouter::volumioGetState Feb 09 14:06:02 primo volumio[3256]: info: CorePlayQueue::getTrack 0 Feb 09 14:06:02 primo volumio[3256]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 09 14:06:04 primo volumio[3256]: info: CoreCommandRouter::executeOnPlugin: tidal , handleBrowseUri Feb 09 14:06:04 primo volumio[3256]: info: Refreshing TIDAL token Feb 09 14:06:06 primo volumio[3256]: info: browseTIDALUri took 660 milliseconds Feb 09 14:06:06 primo volumio[3256]: info: Preload queue cleared Feb 09 14:06:06 primo volumio[3256]: info: Preload queue cleared Feb 09 14:06:07 primo volumio[3256]: info: CoreCommandRouter::executeOnPlugin: tidal , handleBrowseUri Feb 09 14:06:07 primo volumio[3256]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Feb 09 14:06:09 primo volumio5-onboarding[3639]: time=2026-02-09T14:06:09.207+08:00 level=WARN msg="received acknowledgment for source with no pending writes" component=conn/ble data=c400 addr=196 Feb 09 14:06:09 primo volumio[3256]: info: browseTIDALUri took 1562 milliseconds Feb 09 14:06:09 primo volumio[3256]: info: Preload queue cleared Feb 09 14:06:09 primo volumio[3256]: info: Preload queue cleared Feb 09 14:06:12 primo volumio5-onboarding[3639]: time=2026-02-09T14:06:12.883+08:00 level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=196 Feb 09 14:06:13 primo volumio5-onboarding[3639]: time=2026-02-09T14:06:13.220+08:00 level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=196 Feb 09 14:06:13 primo volumio5-onboarding[3639]: time=2026-02-09T14:06:13.391+08:00 level=WARN msg="received acknowledgment for source with no pending writes" component=conn/ble data=c400 addr=196 Feb 09 14:06:13 primo volumio5-onboarding[3639]: time=2026-02-09T14:06:13.662+08:00 level=WARN msg="received acknowledgment for source with no pending writes" component=conn/ble data=c400 addr=196 Feb 09 14:06:17 primo volumio[3256]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Feb 09 14:06:17 primo volumio[3256]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Feb 09 14:06:17 primo volumio[3256]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Feb 09 14:06:17 primo volumio[3256]: info: Received Get System Version Feb 09 14:06:17 primo volumio[3256]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Feb 09 14:06:17 primo volumio[3256]: info: Received Get System Info Feb 09 14:06:17 primo volumio[3256]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Feb 09 14:06:17 primo volumio[3256]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Feb 09 14:06:17 primo volumio[3256]: info: Discovery: Getting this device information Feb 09 14:06:17 primo volumio[3256]: info: CoreCommandRouter::volumioGetState Feb 09 14:06:17 primo volumio[3256]: info: CorePlayQueue::getTrack 0 Feb 09 14:06:17 primo volumio[3256]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 09 14:06:20 primo volumio[3256]: info: CoreCommandRouter::volumioPlay Feb 09 14:06:20 primo volumio[3256]: info: CoreStateMachine::play index undefined Feb 09 14:06:20 primo volumio[3256]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 09 14:06:20 primo volumio[3256]: info: CorePlayQueue::getTrack 0 Feb 09 14:06:20 primo volumio[3256]: info: CoreStateMachine::startPlaybackTimer Feb 09 14:06:20 primo volumio[3256]: info: CorePlayQueue::getTrack 0 Feb 09 14:06:20 primo volumio[3256]: info: [1770617180527] ControllerTidal::clearAddPlayTrack Feb 09 14:06:20 primo volumio[3256]: info: Getting stream with soundQuality LOSSLESS Feb 09 14:06:20 primo volumio[3256]: verbose: ControllerMpd::sendMpdCommand stop Feb 09 14:06:20 primo volumio[3256]: info: sendMpdCommand stop took 2 milliseconds Feb 09 14:06:20 primo volumio[3256]: verbose: ControllerMpd::sendMpdCommand clear Feb 09 14:06:20 primo volumio[3256]: info: Feb 09 14:06:20 primo volumio[3256]: ---------------------------- MPD announces system playlist update Feb 09 14:06:20 primo volumio[3256]: info: Ignoring MPD Status Update Feb 09 14:06:20 primo volumio[3256]: info: sendMpdCommand clear took 2 milliseconds Feb 09 14:06:20 primo volumio[3256]: verbose: ControllerMpd::sendMpdCommand add "http://127.0.0.1:3245?data=tidal://song/2809486&soundQuality=LOSSLESS" Feb 09 14:06:20 primo volumio[3256]: error: updateQueue error: null Feb 09 14:06:20 primo volumio[3256]: info: Feb 09 14:06:20 primo volumio[3256]: ---------------------------- MPD announces system playlist update Feb 09 14:06:20 primo volumio[3256]: info: Ignoring MPD Status Update Feb 09 14:06:20 primo volumio[3256]: info: ------------------------------ 4ms Feb 09 14:06:20 primo volumio[3256]: info: sendMpdCommand add "http://127.0.0.1:3245?data=tidal://song/2809486&soundQuality=LOSSLESS" took 3 milliseconds Feb 09 14:06:20 primo volumio[3256]: info: CoreStateMachine::setConsumeUpdateService mpd Feb 09 14:06:20 primo volumio[3256]: verbose: ControllerMpd::sendMpdCommand play Feb 09 14:06:20 primo volumio[3256]: info: ------------------------------ 2ms Feb 09 14:06:20 primo volumio[3256]: STREAMING PROXY: Handling url /?data=tidal://song/2809486&soundQuality=LOSSLESS Feb 09 14:06:20 primo volumio[3256]: info: sendMpdCommand play took 6 milliseconds Feb 09 14:06:20 primo volumio[3256]: info: Executing endpoint getStreamUrltidal Feb 09 14:06:20 primo volumio[3256]: info: CoreCommandRouter::executeOnPlugin: tidal , getStreamUrlAPI Feb 09 14:06:21 primo volumio[3256]: info: getStreamUrl took 649 milliseconds Feb 09 14:06:21 primo volumio[3256]: STREAMING PROXY: Got real url: http://lgf.audio.tidal.com/mediatracks/CAEaKwgDEic0ZDhjZmY5ZTMzNTUxZTcxOTQwYzYwYTgyZWY3OWE2ZF82MS5tcDQ/0.flac?token=1770620781~MmYxNWE4Mjc0M2E3YWI5YzE4YWFiNjJlMWM5YThiNTU2ZjNjMjU1Nw== Feb 09 14:06:21 primo volumio[3256]: STREAMING PROXY: Response: 200, length: 41441365 Feb 09 14:06:21 primo kernel: aml_tdm_open Feb 09 14:06:21 primo kernel: Not init audio effects Feb 09 14:06:21 primo kernel: audio_ddr_mngr: frddrs[0] registered by device ff660000.audiobus:tdm@1 Feb 09 14:06:21 primo kernel: aml_dai_set_tdm_sysclk(), mpll no change, keep clk Feb 09 14:06:21 primo kernel: aml_dai_set_tdm_sysclk(), mclk no change, keep clk Feb 09 14:06:21 primo kernel: set mclk:11289600, mpll:22579200, get mclk:11289593, mpll:22579186 Feb 09 14:06:21 primo kernel: asoc aml_dai_set_tdm_fmt, 0x4001, ffffffc03d316418, id(1), clksel(1) Feb 09 14:06:21 primo kernel: aml_dai_set_tdm_fmt(), fmt not change Feb 09 14:06:21 primo kernel: dump_pcm_setting(ffffffc03d316418) Feb 09 14:06:21 primo kernel: pcm_mode(1) Feb 09 14:06:21 primo kernel: sysclk(11289600) Feb 09 14:06:21 primo kernel: sysclk_bclk_ratio(4) Feb 09 14:06:21 primo kernel: bclk(2822400) Feb 09 14:06:21 primo kernel: bclk_lrclk_ratio(64) Feb 09 14:06:21 primo kernel: lrclk(44100) Feb 09 14:06:21 primo kernel: tx_mask(0x3) Feb 09 14:06:21 primo kernel: rx_mask(0x3) Feb 09 14:06:21 primo kernel: slots(2) Feb 09 14:06:21 primo kernel: slot_width(32) Feb 09 14:06:21 primo kernel: lane_mask_in(0x2) Feb 09 14:06:21 primo kernel: lane_mask_out(0x1) Feb 09 14:06:21 primo kernel: lane_oe_mask_in(0x0) Feb 09 14:06:21 primo kernel: lane_oe_mask_out(0x0) Feb 09 14:06:21 primo kernel: lane_lb_mask_in(0x0) Feb 09 14:06:21 primo kernel: aml_dai_set_tdm_sysclk(), mpll no change, keep clk Feb 09 14:06:21 primo kernel: aml_dai_set_tdm_sysclk(), mclk no change, keep clk Feb 09 14:06:21 primo kernel: set mclk:11289600, mpll:22579200, get mclk:11289593, mpll:22579186 Feb 09 14:06:21 primo kernel: aml_dai_set_clkdiv, div 4, clksel(1) Feb 09 14:06:21 primo kernel: aml_dai_set_bclk_ratio, select I2S mode Feb 09 14:06:21 primo kernel: aml_dai_tdm_hw_params(), enable mclk for TDM-B Feb 09 14:06:21 primo kernel: aml_tdm_prepare(), reset fddr Feb 09 14:06:21 primo kernel: spdif_a fifo ctrl, frddr:0 type:1, 16 bits, chmask 0x3, swap 0x10 Feb 09 14:06:21 primo kernel: spdif_info: rate: 44100, channel status ch0_l:0x100, ch0_r:0x100, ch1_l:0x0, ch1_r:0x0 Feb 09 14:06:21 primo kernel: audio_ddr_mngr: frddr_set_sharebuffer_enable sel:1, dst_src:3 Feb 09 14:06:21 primo kernel: tdm playback mute: 0, lane_cnt = 8 Feb 09 14:06:21 primo kernel: aml_tdm_prepare(), reset fddr Feb 09 14:06:21 primo kernel: spdif_a fifo ctrl, frddr:0 type:1, 16 bits, chmask 0x3, swap 0x10 Feb 09 14:06:21 primo kernel: spdif_info: rate: 44100, channel status ch0_l:0x100, ch0_r:0x100, ch1_l:0x0, ch1_r:0x0 Feb 09 14:06:21 primo kernel: audio_ddr_mngr: frddr_set_sharebuffer_enable sel:1, dst_src:3 Feb 09 14:06:21 primo kernel: tdm playback mute: 0, lane_cnt = 8 Feb 09 14:06:21 primo volumio[3256]: info: Feb 09 14:06:21 primo volumio[3256]: ---------------------------- MPD announces state update: player Feb 09 14:06:21 primo volumio[3256]: info: ControllerMpd::getState Feb 09 14:06:21 primo volumio[3256]: verbose: ControllerMpd::sendMpdCommand status Feb 09 14:06:21 primo volumio[3256]: info: Feb 09 14:06:21 primo volumio[3256]: ---------------------------- MPD announces state update: player Feb 09 14:06:21 primo volumio[3256]: info: ControllerMpd::getState Feb 09 14:06:21 primo volumio[3256]: verbose: ControllerMpd::sendMpdCommand status Feb 09 14:06:21 primo volumio[3256]: info: sendMpdCommand status took 3 milliseconds Feb 09 14:06:21 primo volumio[3256]: verbose: ControllerMpd::parseState Feb 09 14:06:21 primo volumio[3256]: verbose: ControllerMpd::sendMpdCommand playlistinfo Feb 09 14:06:21 primo volumio[3256]: info: sendMpdCommand status took 4 milliseconds Feb 09 14:06:21 primo volumio[3256]: info: sendMpdCommand playlistinfo took 2 milliseconds Feb 09 14:06:21 primo volumio[3256]: verbose: ControllerMpd::parseState Feb 09 14:06:21 primo volumio[3256]: verbose: ControllerMpd::sendMpdCommand playlistinfo Feb 09 14:06:21 primo volumio[3256]: verbose: ControllerMpd::parseTrackInfo Feb 09 14:06:21 primo volumio[3256]: info: ControllerMpd::pushState Feb 09 14:06:21 primo volumio[3256]: info: CoreCommandRouter::servicePushState Feb 09 14:06:21 primo volumio[3256]: info: CorePlayQueue::getTrack 0 Feb 09 14:06:21 primo volumio[3256]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":404,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"2809486&soundQuality=LOSSLESS","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=tidal://song/2809486&soundQuality=LOSSLESS","trackType":"tidal"} Feb 09 14:06:21 primo volumio[3256]: verbose: CURRENT POSITION 0 Feb 09 14:06:21 primo volumio[3256]: info: CoreStateMachine::syncState stateService play Feb 09 14:06:21 primo volumio[3256]: info: CoreStateMachine::syncState currentStatus stop Feb 09 14:06:21 primo volumio[3256]: info: ------------------------------ 13ms Feb 09 14:06:21 primo volumio[3256]: info: sendMpdCommand playlistinfo took 5 milliseconds Feb 09 14:06:21 primo volumio[3256]: verbose: ControllerMpd::parseTrackInfo Feb 09 14:06:21 primo volumio[3256]: info: ControllerMpd::pushState Feb 09 14:06:21 primo volumio[3256]: info: CoreCommandRouter::servicePushState Feb 09 14:06:21 primo volumio[3256]: info: CorePlayQueue::getTrack 0 Feb 09 14:06:21 primo volumio[3256]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":404,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"2809486&soundQuality=LOSSLESS","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=tidal://song/2809486&soundQuality=LOSSLESS","trackType":"tidal"} Feb 09 14:06:21 primo volumio[3256]: verbose: CURRENT POSITION 0 Feb 09 14:06:21 primo volumio[3256]: info: CoreStateMachine::syncState stateService play Feb 09 14:06:21 primo volumio[3256]: info: CoreStateMachine::syncState currentStatus play Feb 09 14:06:21 primo volumio[3256]: info: Received an update from plugin. extracting info from payload Feb 09 14:06:21 primo volumio[3256]: info: CoreStateMachine::pushState Feb 09 14:06:21 primo volumio[3256]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 09 14:06:21 primo volumio[3256]: info: CoreCommandRouter::volumioPushState Feb 09 14:06:21 primo volumio[3256]: info: CoreCommandRouter::volumioGetState Feb 09 14:06:21 primo volumio[3256]: info: MRS: Pushing multiroomSync output update for this device Feb 09 14:06:21 primo volumio[3256]: info: MRS: Pushing multiroomSync output Feb 09 14:06:21 primo volumio[3256]: info: CoreStateMachine::pushState Feb 09 14:06:21 primo volumio[3256]: info: CoreCommandRouter::volumioPushState Feb 09 14:06:21 primo volumio[3256]: info: CoreCommandRouter::volumioGetState Feb 09 14:06:21 primo volumio[3256]: info: MRS: Pushing multiroomSync output update for this device Feb 09 14:06:21 primo volumio[3256]: info: MRS: Pushing multiroomSync output Feb 09 14:06:21 primo volumio[3256]: info: ------------------------------ 38ms Feb 09 14:06:21 primo volumio[3256]: info: Signalling Playback active due to playback status change Feb 09 14:06:21 primo volumio[3256]: info: Signalling Playback active due to playback status change Feb 09 14:06:21 primo volumio[3256]: info: Updating RAAT Signal Path Feb 09 14:06:21 primo volumio[3256]: info: Updating RAAT Signal Path Feb 09 14:06:21 primo volumio[3256]: info: MCU Signalled Playback Active Feb 09 14:06:21 primo kernel: asoc-aml-card auge_sound: tdm playback enable Feb 09 14:06:21 primo kernel: spdif_a is set to enable Feb 09 14:06:23 primo volumio[3256]: STREAMING PROXY: Client dropped request, destroying Feb 09 14:06:29 primo volumio[3256]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 09 14:06:29 primo volumio[3256]: [t [Error]: A network error (such as timeout, interrupted connection or unreachable host) has occurred.] { Feb 09 14:06:29 primo volumio[3256]: code: 'auth/network-request-failed', Feb 09 14:06:29 primo volumio[3256]: a: null Feb 09 14:06:29 primo volumio[3256]: } Feb 09 14:06:29 primo volumio[3256]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 09 14:06:30 primo sudo[5696]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2026-02-09 14:05 Feb 09 14:06:30 primo sudo[5696]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Debian GNU/Linux 10 (buster)" NAME="Debian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=debian HOME_URL="https://www.debian.org/" SUPPORT_URL="https://www.debian.org/support" BUG_REPORT_URL="https://bugs.debian.org/" VOLUMIO_BUILD_VERSION="b43c85cc0006d3f1efecba101311ec96e334d1fd" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="2f25e1a98e53e2dbc4f3878604e250b0379f3ea4" VOLUMIO_ARCH="armv7" VOLUMIO_VARIANT="primo2rev2" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Thu 11 Dec 2025 07:52:21 PM CET" VOLUMIO_VERSION="3.886" VOLUMIO_HARDWARE="mp1" VOLUMIO_DEVICENAME="Volumio MP1" VOLUMIO_VENDOR_MODEL="Volumio Primo" VOLUMIO_VENDOR="Volumio" VOLUMIO_MODEL="Primo" VOLUMIO_HASH="060c5b31331b90c840ee52059a8e3db0"