DFU issues on Android 10

[AntonHellbe]

Hi,

We are currently testing DFU upgrades on Android. In my current setup I have two different phones, a Sony one running Android 8 and a OnePlus running Android 10.

The bootloader uses bonds and the application uses the buttonless DFU service.

Entering the bootloader and performing a DFU upgrade through the nRFConnect App on the Sony phone works fine. No failures there.

However on the OnePlus there are some issues. The first issue is that when trigger a DFU with the new FW zip file the nRF52832 enters the bootloader, the OnePlus connects again, but at reconnect it receives "GATT_INVALID_HANDLE", like it does not receive the GATT_SERVICE_CHANGED notification or that it receives it too late.

The second issue is that sometime the application cannot enter the bootloader from the buttonless DFU service, these are the logs from the application when I'm writing to the characteristic from the OnePlus:

<info> app: Read/Write Authorization request.
<info> app: Writing peer data to the bootloader...
<error> app: Request to enter bootloader mode failed asynchroneously.
<info> app: Handle Value Confirmation
<info> app: Read/Write Authorization request.
<info> app: Writing peer data to the bootloader...
<error> app: Request to enter bootloader mode failed asynchroneously.
<info> app: Handle Value Confirmation
<info> app: Read/Write Authorization request.
<info> app: Writing peer data to the bootloader...
<error> app: Request to enter bootloader mode failed asynchroneously.
<info> app: Handle Value Confirmation
<info> app: Read/Write Authorization request.
<info> app: Writing peer data to the bootloader...
<error> app: Request to enter bootloader mode failed asynchroneously.
<info> app: Handle Value Confirmation

Hardware: nRF52832 PCA10040

SDK: v15.0

Softdevice: v6.0.0

Edit: added screenshots from LOG

[Einar Thorsrud]

Hi,

Both these issues could be explained by missing service changed. Have you made sure the NRF_SDH_BLE_SERVICE_CHANGED is set to the same value in both the applications and bootloaders sdk_config.h? What is it?

[AntonHellbe]

Hi again,

Here is another screenshot from my OnePlus 5 running Android 9, attempting DFU through the NRF Connect App.

I've never had any issues on this phone before.

[AntonHellbe]

Hi,

I see. We could confirm with a sniffer trace, but your tests strengthen the theory of a timing difference. Different mobile devices, operating systems, SW/DFU library changes, all affect timing slightly. The fix is probably to do the same workaround as you did in your application in the bootloader as well.

- In the application I currently trigger pm_local_database_has_changed() in the peer manager event handler when we get the event CACHE_APPLY_FAILED, If I understand you correctly I should implement the same in the bootloader?

Currently the bootloader does not make use of the Peer Manager.

[Einar Thorsrud]

Hi,

The service changed indication in the bootloader in SDK 15.0 is sent by the call to service_changed_send() on line 882 in nrf_dfu_ble.c.

[AntonHellbe]

I will implement the fix and see what happens.

Regarding problem 2:

ret = nrf_dfu_set_peer_data(&m_peer_data);

is the function that returns INVALID_STATE, row 178 in ble_dfu_bonded.c

[AntonHellbe]

Here's the changes I made to nrf_dfu_ble.c. I copied the service_changed_cccd function and In case the softdevice call to service_changed fails I call that function. If I understand the code in gatt_cache_manager.c that's how it works there aswell.

It does not seem to help.

static ret_code_t service_changed_cccd(uint16_t conn_handle, uint16_t * p_cccd)
{
    bool       sc_found = false;
    uint16_t   end_handle;

    ret_code_t err_code = sd_ble_gatts_initial_user_handle_get(&end_handle);
    ASSERT(err_code == NRF_SUCCESS);

    for (uint16_t handle = 1; handle < end_handle; handle++)
    {
        ble_uuid_t uuid;
        ble_gatts_value_t value = {.p_value = (uint8_t *)&uuid.uuid, .len = 2, .offset = 0};

        err_code = sd_ble_gatts_attr_get(handle, &uuid, NULL);
        if (err_code != NRF_SUCCESS)
        {
            return err_code;
        }
        else if (!sc_found && (uuid.uuid == BLE_UUID_GATT_CHARACTERISTIC_SERVICE_CHANGED))
        {
            sc_found = true;
        }
        else if (sc_found && (uuid.uuid == BLE_UUID_DESCRIPTOR_CLIENT_CHAR_CONFIG))
        {
            value.p_value = (uint8_t *)p_cccd;
            return sd_ble_gatts_value_get(conn_handle, handle, &value);
        }
    }
    return NRF_ERROR_NOT_FOUND;
}


#if (NRF_DFU_BLE_REQUIRES_BONDS)
static uint32_t service_changed_send(void)
{
    uint32_t err_code;

    NRF_LOG_DEBUG("Sending Service Changed indication");

    err_code = sd_ble_gatts_sys_attr_set(m_conn_handle,
                                         m_peer_data.sys_serv_attr,
                                         sizeof(m_peer_data.sys_serv_attr),
                                         BLE_GATTS_SYS_ATTR_FLAG_SYS_SRVCS);
    VERIFY_SUCCESS(err_code);

    err_code = sd_ble_gatts_sys_attr_set(m_conn_handle,
                                         NULL,
                                         0,
                                         BLE_GATTS_SYS_ATTR_FLAG_USR_SRVCS);
    VERIFY_SUCCESS(err_code);

    err_code = sd_ble_gatts_service_changed(m_conn_handle, m_dfu.service_handle, 0xFFFF);

    if (   (err_code == BLE_ERROR_INVALID_CONN_HANDLE)
        || (err_code == NRF_ERROR_INVALID_STATE)
        || (err_code == NRF_ERROR_BUSY))
    {
        uint16_t cccd;
        err_code = service_changed_cccd(m_conn_handle, &cccd);
        if ((err_code == NRF_SUCCESS) && cccd)
        {
            NRF_LOG_DEBUG("Service changed cccd returned err_code: %d", err_code);
            // Possible ATT_MTU exchange ongoing.
            // Do nothing, treat as busy.
            return err_code;
        }
        else
        {
            if (err_code != NRF_SUCCESS)
            {
                NRF_LOG_WARNING("Client did not have the Service Changed indication set to enabled."
                        "Error: 0x%08x", err_code);
                err_code = NRF_SUCCESS;

                //NRF_LOG_DEBUG("Unexpected error when looking for service changed CCCD: %s",
                //              nrf_strerror_get(err_code));
            }
            // CCCDs not enabled or an error happened. Drop indication.
            // Fallthrough.
        }
        /* These errors can be expected when trying to send a Service Changed indication */
        /* if the CCCD is not set to indicate. Thus, set the returning error code to success. */
    }

    return err_code;
}
#endif

The service changed notification is still sent from the events (no changes there):

case BLE_GAP_EVT_CONN_SEC_UPDATE:
case BLE_GATTS_EVT_SYS_ATTR_MISSING:
    {
        #if (NRF_DFU_BLE_REQUIRES_BONDS)
            err_code = service_changed_send();
        #else
            err_code = sd_ble_gatts_sys_attr_set(p_gap->conn_handle, NULL, 0, 0);
        #endif
        APP_ERROR_CHECK(err_code);
        NRF_LOG_DEBUG("Finished handling conn sec update");
    } break;

[Einar Thorsrud]

Hi,

I see. Then I think it would be very useful with a sniffer trace and a log from the bootloader to know exactly what is going on (we have based it on assumptions up to now).

Regarding problem 2, that is also a bit of a mystery. We may get a bit close if you look at the implementation in components\libraries\bootloader\dfu\nrf_dfu_svci_handler.c, an put breakpoints on all conditions that cause a NRF_ERROR_INVALID_STATE return value. I fail to see the reason, but reading this thread might suggest a link with problem 1.

[AntonHellbe]

2816.sniffer.pcapng

Hi,

Here's the sniffer trace from wireshark. At package 6130 the connection to the bootloader starts.

Hopefully you can read the data, I'm not very experienced with wireshark so I dont know if this is the correct way to do it.

The sequence is here is write to DFU characteristic to "manually" put it in bootloader and then connect.

[Einar Thorsrud]

Hi,

Thanks. All looks good here as far as I can see. I am wondering if there could be a timing issue in the Android DFU library itself, as you suggested earlier. Perhaps fixed by this. I am checking with the library developer and will get back to you.

[Einar Thorsrud]

Hi,

Looking more closely at this with one of our Android developers he commented hat from the log is seems like the phone did receive SC indication, as it switched to 7.5 ms connection interval (which it does for service discovery), but it did receive it too late. The DFU service has already received cached services from the system and tries to use them. Service discovery was delayed 1.6 sec, but that seems not to be enough for the device, as 300 ms later the SC indication comes. Had it come earlier, the system would have cleared the cache, performed service discovery and returned the new services to the DFU library.

You can try to fix this in your app by including the library as a module, not from jcenter, and modify this line to be > 2000 ms. You can also try fixing in the bootloader by always sending a service changed indication earlier (if enabled), i.e. before getting the BLE_GATTS_EVT_SYS_ATTR_MISSING or BLE_GAP_EVT_CONN_SEC_UPDATE event.

[AntonHellbe]

Hi Einar,

Thanks for the update. We will try both solutions and see what works best.

Regarding sending a service changed indication earlier than BLE_GATTS_EVT_SYS_ATTR_MISSING or BLE_GAP_EVT_CONN_SEC_UPDATE, do you have any suggestions on what event would be appropriate to use for sending the service changed indication?

Br,
Anton

[Einar Thorsrud]

Hi Anton,

Good question. It is not logical in my mind to send it before BLE_GAP_EVT_CONN_SEC_UPDATE, since that is when we know we are connected to a known peer (which has hopefully enabled service changed indications). You could try to send it before, but it anyway should not be before the peer has enabled indication (since you cannot know it is the same old peer before the link is encrypted). You could try to send in on the BLE_GAP_EVT_CONNECTED, or start an app_timer to send it a certain delay after.

I am surprised that the phone handles it like this. It would be interesting to know why this is so slow on the phone side, but no progress there yet.