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.

[Einar Thorsrud]

Hi,

Problem 1: This is the exact same issue. But remember that this needs to work both in the application and in the bootloader. Have you done anything with this issue in the bootloader?

Problem 2: I see. Then I suggest you debug on the nRF side to see what happens before printing the "bootloader mode failed asynchronously" error message, as there are several issues that can lead to this being printed.

[AntonHellbe]

Hi,

Problem 1: This is the exact same issue. But remember that this needs to work both in the application and in the bootloader. Have you done anything with this issue in the bootloader?

- No I have not modified the bootloader source. I can try to debug it and see if It successfully sends Service Changed Notifications before I do any modifications. In general I dont like to modify SDK files since it becomes hard to keep track of the changes which could be dangerous in the long run, especially if I do the changes myself (perhaps poor solutions).

Problem 2:

I will try to debug it further on the nRF side

[AntonHellbe]

Update regarding problem 1:

Logs indicate that the Service Changed notifications are working correctly in the bootloader:

<debug> nrf_dfu_ble: Connected
<debug> nrf_dfu_ble: Received BLE_GAP_EVT_DATA_LENGTH_UPDATE_REQUEST.
<debug> nrf_dfu_ble: Received BLE_GAP_EVT_DATA_LENGTH_UPDATE (27, max_rx_time 328).
<debug> nrf_dfu_ble: Received BLE_GAP_EVT_PHY_UPDATE_REQUEST.
<debug> nrf_dfu_ble: Received BLE_GAP_EVT_PHY_UPDATE (RX:2, TX:2, status:0)
<debug> nrf_dfu_ble: Received BLE_GAP_EVT_CONN_PARAM_UPDATE
<debug> nrf_dfu_ble: max_conn_interval: 12
<debug> nrf_dfu_ble: min_conn_interval: 12
<debug> nrf_dfu_ble: slave_latency: 0
<debug> nrf_dfu_ble: conn_sup_timeout: 600
<debug> nrf_dfu_ble: Received BLE_GAP_EVT_SEC_INFO_REQUEST
<debug> nrf_dfu_ble: Received BLE_GAP_EVT_CONN_SEC_UPDATE
<debug> nrf_dfu_ble: Received BLE_GATTS_EVT_SYS_ATTR_MISSING
<debug> nrf_dfu_ble: Sending Service Changed indication
<debug> nrf_dfu_ble: Service changed notification returned err_code: 0
<debug> nrf_dfu_ble: Finished handling conn sec update
<debug> nrf_dfu_ble: Received BLE_GAP_EVT_CONN_PARAM_UPDATE
<debug> nrf_dfu_ble: max_conn_interval: 6
<debug> nrf_dfu_ble: min_conn_interval: 6
<debug> nrf_dfu_ble: slave_latency: 0
<debug> nrf_dfu_ble: conn_sup_timeout: 500
<debug> nrf_dfu_ble: Received BLE_GAP_EVT_CONN_PARAM_UPDATE
<debug> nrf_dfu_ble: max_conn_interval: 12
<debug> nrf_dfu_ble: min_conn_interval: 12
<debug> nrf_dfu_ble: slave_latency: 0
<debug> nrf_dfu_ble: conn_sup_timeout: 600
<debug> nrf_dfu_ble: Received BLE_GAP_EVT_CONN_PARAM_UPDATE
<debug> nrf_dfu_ble: max_conn_interval: 6
<debug> nrf_dfu_ble: min_conn_interval: 6
<debug> nrf_dfu_ble: slave_latency: 0
<debug> nrf_dfu_ble: conn_sup_timeout: 500
<debug> nrf_dfu_ble: Received BLE_GAP_EVT_CONN_PARAM_UPDATE
<debug> nrf_dfu_ble: max_conn_interval: 12
<debug> nrf_dfu_ble: min_conn_interval: 12
<debug> nrf_dfu_ble: slave_latency: 0
<debug> nrf_dfu_ble: conn_sup_timeout: 600

Edit:
Another intresting observation. According to Google Play nRF Connect uses:

- DFU Library 1.9.1 (improved DFU performance with devices based on SDK 15.x and 16)

Using nRF Connect DFU I received GATT ERROR (0x85)

Then I tried upgrading using nRF Toolbox which uses DFU Library 1.9.0 which went successfully without any issues.

[AntonHellbe]

Update on problem 2:

<info> app: Retriving Peer data returned err_code: 0
<info> app: Setting peer data for bootloader returned err_code: 8
<error> app: Request to enter bootloader mode failed asynchroneously.

[AntonHellbe]

Hi,

So I just finished a longer test session.

It seems like the GATT Service changed notifications is not working properly in the bootloader.

If I take these steps:

1. In the application, write to the DFU characteristic to enter bootloader
2. Enters bootloader
3. Reconnect
4. Still shows the attribute table from the application. Logs indicate that the Indication was sent successfully (returns NRF_SUCCESS inside nrf_dfu_ble.c)
5. Disconnect and then reconnect. Now displays the DFU service/characteristic (Sometimes requires more than one disconnect/reconnect in order to display the new attribute table).
6. Start FW upload

With the above sequence DFU was successful 10 out of 10 tries.

Automatic DFU from the application fails on either GATT_INVALID_HANDLE or GATT_ERROR which can be explained by the behavior above.

[Einar Thorsrud]

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.

For problem 2 to you get a return value 8, which is NRF_ERROR_INVALID_STATE. From which function?

[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;