This post is older than 2 years and might not be relevant anymore
More Info: Consider searching for newer posts

Secure DFU race condition

I have an iOS App which is just designed for updating our device firmware OTA. It uses the Nordic DFU library, updated to the latest cocoapod. It connects to our device, and then starts DFU with the library.

In the firmware I'm using S132 v7.0.1 SDK 16.0.0 on nRF52832.

Because the device has not connected before, when the library writes the enter bootloader command the device starts a new bond. This is written to flash on the device, but it seems that sometimes the buttonless DFU library attempts to set the bond info in the bootloader before the peer manager has finished writing to flash.

The log:

Fullscreen
1
2
3
4
5
6
7
8
9
10
11
12
13
<info> nrf_ble_lesc: Calling sd_ble_gap_lesc_dhkey_reply on conn_handle: 0
<info> peer_manager_handler: Connection secured: role: Peripheral, conn_handle: 0, procedure: Bonding
<info> app: Paired
<info> peer_manager_handler: Peer data updated in flash: peer_id: 0, data_id: Bonding data, action: Update
<info> app: New Bond
<info> peer_manager_handler: Peer data updated in flash: peer_id: 0, data_id: Peer rank, action: Update
<info> peer_manager_handler: Peer data updated in flash: peer_id: 0, data_id: Local database, action: Update
<info> peer_manager_handler: Peer data updated in flash: peer_id: 0, data_id: Local database, action: Update
<info> NRF_DFU_BLE_BONDED: Writing peer data to the bootloader... 1
<error> NRF_DFU_BLE_BONDED: Failed to set peer data: 0011
<error> NRF_DFU_BLE_BONDED: Failed to enter bootloader: 0006
<error> app: Request to enter bootloader mode failed asynchroneously.
<info> peer_manager_handler: Peer data updated in flash: peer_id: 0, data_id: Central address resolution, action: Update
XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX

I have added some additional logs here that are not in the buttonless DFU by default to print the relevant error codes. Stepping through what is happening:

  1. Bonding occurs
  2. The buttonless lib attempts to write peer data to bootloader (1 = svci state = initialized)
  3. As state is initialized, in nrf_dfu_svci_handler.c line 84 peer data write is attempted
  4. In nrf_dfu_settings_svci.c line 83 sd_flash_write returns NRF_ERROR_BUSY
  5. This is returned to buttonless lib (failed to set peer data error 0x11 == 17 == NRF_ERROR_BUSY)
  6. Peer manager handler indicates peer data write is complete (central address resolution)

Is there any way to prevent this? It seems like it is something that should be handled in the SDK.

Parents
  • Here is a patch for my workaround, which uses app_timer to delay by 10ms until peer data set does not return busy. I don't think there is a way to determine if all the peer manager operations are complete but if there is that would be preferable to this solution.

    Fullscreen
    1
    2
    3
    4
    5
    6
    7
    8
    9
    10
    11
    12
    13
    14
    15
    16
    17
    18
    19
    20
    21
    diff -Naur -x '*.DS_Store' -x '*.elf' -x '*.hex' -x '*.map' -x '*.o' -x '*.bin' -x _build -x Output -x '*.emSession' -x micro-ecc -x dfu_public_key.c nRF5_SDK_16.0.0_98a08e2_vanilla/components/ble/ble_services/ble_dfu/ble_dfu.c nRF5_SDK_16.0.0_98a08e2/components/ble/ble_services/ble_dfu/ble_dfu.c
    --- nRF5_SDK_16.0.0_98a08e2_vanilla/components/ble/ble_services/ble_dfu/ble_dfu.c 2019-10-18 21:22:36.000000000 +0100
    +++ nRF5_SDK_16.0.0_98a08e2/components/ble/ble_services/ble_dfu/ble_dfu.c 2020-04-25 15:57:42.000000000 +0100
    @@ -50,7 +50,6 @@
    #include "nrf_nvic.h"
    #include "nrf_sdm.h"
    #include "nrf_soc.h"
    -#include "nrf_log.h"
    #include "nrf_dfu_ble_svci_bond_sharing.h"
    #include "nrf_bootloader_info.h"
    #include "nrf_svci_async_function.h"
    @@ -59,6 +58,17 @@
    #include "gatts_cache_manager.h"
    #include "peer_id.h"
    +#define NRF_LOG_MODULE_NAME NRF_DFU_BLE
    +#if NRF_DFU_BLE_CONFIG_LOG_ENABLED
    +#define NRF_LOG_LEVEL NRF_DFU_BLE_CONFIG_LOG_LEVEL
    +#define NRF_LOG_INFO_COLOR NRF_DFU_BLE_CONFIG_INFO_COLOR
    +#define NRF_LOG_DEBUG_COLOR NRF_DFU_BLE_CONFIG_DEBUG_COLOR
    +#else
    XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX

    The new log:

    Fullscreen
    1
    2
    3
    4
    5
    6
    7
    8
    9
    10
    11
    12
    13
    14
    15
    <debug> app: PHY update request.
    <debug> nrf_ble_lesc: BLE_GAP_EVT_LESC_DHKEY_REQUEST
    <info> nrf_ble_lesc: Calling sd_ble_gap_lesc_dhkey_reply on conn_handle: 0
    <info> peer_manager_handler: Connection secured: role: Peripheral, conn_handle: 0, procedure: Bonding
    <info> app: Paired
    <info> peer_manager_handler: Peer data updated in flash: peer_id: 0, data_id: Bonding data, action: Update
    <info> app: New Bond
    <info> peer_manager_handler: Peer data updated in flash: peer_id: 0, data_id: Peer rank, action: Update
    <info> peer_manager_handler: Peer data updated in flash: peer_id: 0, data_id: Local database, action: Update
    <info> peer_manager_handler: Peer data updated in flash: peer_id: 0, data_id: Local database, action: Update
    <info> NRF_DFU_BLE_BONDED: Writing peer data to the bootloader, svci state: 1
    <debug> NRF_DFU_BLE_BONDED: system attribute table len: 8
    <debug> NRF_DFU_BLE_BONDED: Set peer data failed due to busy, will retry
    <info> peer_manager_handler: Peer data updated in flash: peer_id: 0, data_id: Central address resolution, action: Update
    <debug> NRF_DFU_BLE_BONDED: Successfully initiated peer data set after retry
    XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX

  • Thanks for reporting and for providing a fix. I have reported this internally. It may be an idea to also call nrf_fstorage_is_busy() from the app timer callback to check that there are no pending flash operations.

Reply
  • Thanks for reporting and for providing a fix. I have reported this internally. It may be an idea to also call nrf_fstorage_is_busy() from the app timer callback to check that there are no pending flash operations.

Children
No Data