Buttonless DFU SDK 14.2 DFU failed with error:

[Andreas Ascher]

Hello Forum,

I am now working for a year with the nrf52832 and whenever I had a software problem I found a solution in this forum so thank s for that :).

However now I started with DFU some problems with it.

Our Setup:

1. SDK 14.2
2. Development Kit PCA10028 operated with nRF Connect v2.3.0
3. Custom board without buttons and LEDs
4. Programming Environment: Eclpise Oxygen
5. Debugger: Segger

So our main goal is to run a Central operation on the custom board, but we still want to be able to perform a OTA-DFU.

To accomplish this as a template we used the experimental application ble_app_hrs_rscs_relay and merged it with the ble_app_uart_c and the ble_app_buttonless_dfu.
The BLE services hrs and rscs where discarded and deleted from the template.

For the bootloader we used the standard  bootloader_secure_ble example given in the SDK compiled with our own generated public keys like shown in Getting Started with Nordics secure dfu bootloader.

The bootloader works fine since I use nRF util tool to:

1. erase the chip
2. flash the soft device  (s132_nrf52_5.0.0_softdevice.hex)
3. at last I flash the bootloader and reset the chip.

With that done the application can be transferred to the chip via DFU. The application advertises normally as shown in the picture below.

Sorry for the long intro, but here is my problem. When I try to use the DFU option again to upload the same application after some time it gives me the following error:

Attribute value changed, handle: 0x11, value (0x): 02-00

Attribute value changed, handle: 0x10, value (0x): 01

Attribute value changed, handle: 0x10, value (0x): 20-01-01

DFU failed with error: Timed out when waiting for target device to disconnect.

I suspect I my  mistake is located in the following code part:

static void ble_dfu_evt_handler(ble_dfu_buttonless_evt_type_t event)
{
	ret_code_t            err_code;

    switch (event)
    {
        case BLE_DFU_EVT_BOOTLOADER_ENTER_PREPARE:
            NRF_LOG_INFO("Device is preparing to enter bootloader mode.");
            // YOUR_JOB: Disconnect all bonded devices that currently are connected.
            //           This is required to receive a service changed indication
            //           on bootup after a successful (or aborted) Device Firmware Update.
            break;

The problem is I don't have any bonded devices since I am using ble_dfu_unbonde.c and also the ble nus_c.c is not bonding to its peripheral.

Thanks in advance for your time and support.

Andreas

[Einar Thorsrud]

Hi,

You should not have to do anything when you handle the BLE_DFU_EVT_BOOTLOADER_ENTER_PREPARE in this case. A few questions:

• Do you have logging in the bootloader and application? If so, can you upload the logs?
• After you get this error message, can you then connect again and do the DFU successfully (the device should still be in bootloader mode provided you connect before the DFU timeout)? 
• Do you use a watchdog? If so, can you test without enabling the watchdog in your application?

[Andreas Ascher]

Hello Einar Thorsrud,

thank you for your answer. To your questions:

• Yes I have the logging function enabled the following part contains the logging at the end I will also include the whole file.

<debug> nrf_dfu_flash: Flash write success: addr=0x00037F00, pending 0
<debug> nrf_dfu_flash: nrf_fstorage_write(addr=0x00037F80, len=0x80 bytes), queue usage: 1
<info> dfu_req_handling: Storing 128 bytes at: 0x00037F80
<debug> nrf_dfu_flash: Flash write success: addr=0x00037F80, pending 0
<debug> app: Received calculate CRC
<info> dfu_req_handling: Before OP crc
<debug> app: Sending CRC: [0x60, 0x03, 0x01, 0:x00015000, CRC:0xE0A15EE0]
<debug> app: Received execute object
<info> dfu_req_handling: Before OP execute
<info> dfu_req_handling: Valid Data Execute
<debug> nrf_dfu_settings: Writing settings...
<debug> nrf_dfu_settings: Erasing old settings at: 0x0007F000
<debug> nrf_dfu_flash: nrf_fstorage_erase(addr=0x0x0007F000, len=1 pages), queue usage: 1
<debug> nrf_dfu_flash: nrf_fstorage_write(addr=0x0007F000, len=0x1B8 bytes), queue usage: 2
<debug> app: Sending Response: [0x4, 0x1]
<debug> app: Received create object
<info> dfu_req_handling: Before OP create
<info> dfu_req_handling: Valid Data Create
<debug> nrf_dfu_flash: nrf_fstorage_erase(addr=0x0x00038000, len=1 pages), queue usage: 3
<info> dfu_req_handling: Creating object with size: 564. Offset: 0x00015000, CRC: 0xE0A15EE0
<debug> app: Sending Response: [0x1, 0x1]
<debug> nrf_dfu_flash: Flash erase success: addr=0x0007F000, pending 2
<debug> nrf_dfu_flash: Flash write success: addr=0x0007F000, pending 1
<debug> nrf_dfu_flash: Flash erase success: addr=0x00038000, pending 0
<debug> nrf_dfu_flash: nrf_fstorage_write(addr=0x00038000, len=0x80 bytes), queue usage: 1
<info> dfu_req_handling: Storing 128 bytes at: 0x00038000
<debug> nrf_dfu_flash: Flash write success: addr=0x00038000, pending 0
<debug> nrf_dfu_flash: nrf_fstorage_write(addr=0x00038080, len=0x80 bytes), queue usage: 1
<info> dfu_req_handling: Storing 128 bytes at: 0x00038080
<debug> nrf_dfu_flash: Flash write success: addr=0x00038080, pending 0
<debug> nrf_dfu_flash: nrf_fstorage_write(addr=0x00038100, len=0x80 bytes), queue usage: 1
<info> dfu_req_handling: Storing 128 bytes at: 0x00038100
<debug> nrf_dfu_flash: Flash write success: addr=0x00038100, pending 0
<debug> nrf_dfu_flash: nrf_fstorage_write(addr=0x00038180, len=0x80 bytes), queue usage: 1
<info> dfu_req_handling: Storing 128 bytes at: 0x00038180
<debug> nrf_dfu_flash: Flash write success: addr=0x00038180, pending 0
<debug> nrf_dfu_flash: nrf_fstorage_write(addr=0x00038200, len=0x34 bytes), queue usage: 1
<info> dfu_req_handling: Storing 52 bytes at: 0x00038200
<debug> nrf_dfu_flash: Flash write success: addr=0x00038200, pending 0
<debug> app: Received calculate CRC
<info> dfu_req_handling: Before OP crc
<debug> app: Sending CRC: [0x60, 0x03, 0x01, 0:x00015234, CRC:0x27D2E6A9]
<debug> app: Received execute object
<info> dfu_req_handling: Before OP execute
<info> dfu_req_handling: Valid Data Execute
<debug> nrf_dfu_settings: Writing settings...
<debug> nrf_dfu_settings: Erasing old settings at: 0x0007F000
<debug> nrf_dfu_flash: nrf_fstorage_erase(addr=0x0x0007F000, len=1 pages), queue usage: 1
<debug> nrf_dfu_flash: nrf_fstorage_write(addr=0x0007F000, len=0x1B8 bytes), queue usage: 2
<info> dfu_req_handling: Doing postvalidate
<info> dfu_req_handling: Current bank is bank 0
<info> dfu_req_handling: Running SD version check ============== 
<info> dfu_req_handling: Successfully ran the postvalidation check!
<debug> nrf_dfu_settings: Writing settings...
<debug> nrf_dfu_settings: Erasing old settings at: 0x0007F000
<debug> nrf_dfu_flash: nrf_fstorage_erase(addr=0x0x0007F000, len=1 pages), queue usage: 3
<debug> nrf_dfu_flash: nrf_fstorage_write(addr=0x0007F000, len=0x1B8 bytes), queue usage: 4
<debug> app: Sending Response: [0x4, 0x1]
<debug> nrf_dfu_flash: Flash erase success: addr=0x0007F000, pending 3
<debug> dfu_req_handling: Response sent.
<debug> nrf_dfu_flash: Flash write success: addr=0x0007F000, pending 2
<debug> nrf_dfu_flash: Flash erase success: addr=0x0007F000, pending 1
<debug> nrf_dfu_flash: Flash write success: addr=0x0007F000, pending 0
<debug> nrf_dfu_flash: This operation had a callback, calling back to 0x00074A7D.
<debug> dfu_req_handling: All flash operations have completed.
<debug> dfu_req_handling: Starting reset timer.
<debug> dfu_req_handling: Attempting to reset the device.
<debug> app: In nrf_dfu_transports_close
<debug> app: num transports: 1
<debug> app: Shutting down BLE transport.
<debug> app: Disconnecting.
<debug> app: BLE transport shut down.
<debug> app: After nrf_dfu_transports_init
<debug> dfu_req_handling: Reset.
<info> app: Inside main
<debug> app: In nrf_bootloader_init
<debug> app: in weak nrf_dfu_init_user
<debug> app: In real nrf_dfu_init
<debug> nrf_dfu_settings: Running nrf_dfu_settings_init(sd_irq_initialized=false).
<debug> nrf_dfu_flash: Calling nrf_dfu_flash_init(sd_irq_initialized=false)...
<debug> nrf_dfu_flash: Initializing nrf_fstorage_nvmc backend.
<debug> app: Initializing the clock.
<debug> app: Enter nrf_dfu_continue
<debug> app: Valid App
<debug> app: Enter nrf_dfu_app_is_valid
<debug> app: Return true. App was valid
<debug> nrf_dfu_settings_svci: Erasing settings page additional data.
<debug> app: Enter nrf_dfu_app_is_valid
<info> app: Setting vector table to bootloader: 0x00073000
<info> app: Setting vector table to main app: 0x00023000
<debug> app: ble_dfu_buttonless_async_svci_init returned 0.
<debug> app: ble_dfu_buttonless_init returned 0.
<info> app: Fast advertising.
<info> app: Relay example started.
<info> app: Received indication state 1
<info> app: Received indication state 1
<error> app: Request to send a response to client failed.
<info> app: Fast advertising.
<info> app: Peripheral disconnected

• After the error message I can connect again yes, but I get the same error. In my opinion the relay does not start into the bootloader.
• No I don't have a watchdog enabled.

Here is the complete Log file from JLinkRTTViewer.

Bootloader_and_MultiRoleDevice.log

[Einar Thorsrud]

Hi,

I see you get the error "Request to send a response to client failed", which I assume is printed from your application when there is a BLE_DFU_EVT_RESPONSE_SEND_ERROR event (this is the case for the buttonless example application). Can you check (for instance with breakpoints or debug printouts) from which of the four possible locations in ble_dfu_unbonded.c this is originates?

[Andreas Ascher]

Hello Einar Thorsrud,

Thank you very much for your help. I found the problem was the ble_dfu_buttonless_on_ctrl_pt_write function in the file ble_dfu_unbonded.c.  With debugging lines I could figure out that the sd_ble_gatts_hvx, which is used by ble_dfu_buttonless_resp_send, always had the error code 17 (NRF_ERROR_BUSY). I solved it by encapsulating the function in a do while loop.

do
{
	err_code = sd_ble_gatts_hvx(m_dfu.conn_handle, &hvx_params);
}
while(err_code == NRF_ERROR_BUSY);

The time until the DFU process starts takes roughly 2 seconds longer, but it works fine.

Thanks again for your support.

Andreas

[rich_l]

I too am seeing this exact same issue.  I am using the secure bootloader on the nrf52810 with SDK15.3.0 and NRFConnect 4.22.3 on Android.  When I attempt to initiate the bootloader from the app, I enable notifications on the control point and write the value '0x01' to it.  I then get the same error because sd_ble_gatts_hvx returns busy and the device fails to jump to the bootloader.  The do-while workaround explained above fixes the issue.  However, I di not like to rely on modified SDK code so would like to know from Nordic, given my scenario described earlier writing to the control point, what would cause the SDK to return NRF_ERROR_BUSY?

[rich_l]

ok, I found what the issue was.  The BLE DFU event handler, ble_dfu_buttonless_on_ble_evt() was being called twice.  Once because it is registered as a BLE observer in ble_dfu.c and also from my app where my registered BLE handler dispatched events to the DFU service.  Essentially there were 2 indications trying to be sent instead of just one. I  believe the workaround fixes this because it waits for the first notification to be sent before sending the second.