Bootloader inactivity timeout not triggering when interrupting USB DFU

[Jose Cazarin]

Hello! I'm using SDK 15.2

I have a bootloader that has both BLE and USB DFU capabilities

Everything is working fine, the inactivity timeout of bootloader triggers in all of the expected situations but one: when the USB DFU process is interrupted while the device is being programmed

I'm using NRFUtil to test this and while the progress bar is being shown I kill the process with a CTRL+C and then the bootloader hangs, it never resets.

I have a snippet of the output while the DFU process is happening:

00> <debug> app: restarting timer
00> <debug> app: timer_stop (0x200057D4)
00> <debug> app: timer_start
00> <debug> app: timer_activate (0x200057D4)
00> <debug> app: Shutting down transports (found: 2)
00> <debug> nrf_dfu_ble: Shutting down BLE transport.
00> <debug> app: Failed to shutdown transport 1, error 8
00> <debug> nrf_dfu_serial_usb: Allocated buffer 200062B4
00> <debug> nrf_dfu_req_handler: Handle NRF_DFU_OP_OBJECT_CREATE (data)
00> <debug> nrf_dfu_flash: nrf_fstorage_erase(addr=0x0x0008A000, len=1 pages), queue usage: 1
00> <debug> nrf_dfu_flash: Flash erase success: addr=0x0008A000, pending 0
00> <debug> nrf_dfu_req_handler: Creating object with size: 4096. Offset: 0x0000D000, CRC: 0xEE501589
00> <debug> nrf_dfu_req_handler: Request handling complete. Result: 0x1
00> <debug> nrf_dfu_serial: Sending Response: [0x1, 0x1]
00> <debug> app: Shutting down transports (found: 2)
00> <debug> nrf_dfu_ble: Shutting down BLE transport.
00> <debug> app: Failed to shutdown transport 1, error 8
00> <debug> nrf_dfu_serial_usb: Allocated buffer 20005AB0
00> <debug> nrf_dfu_req_handler: Handle NRF_DFU_OP_OBJECT_WRITE (data)
00> <debug> nrf_dfu_flash: nrf_fstorage_write(addr=0x0008A000, src=0x200062B8, len=1024 bytes), queue usage: 1
00> <debug> nrf_dfu_flash: Flash write success: addr=0x0008A000, pending 0
00> <debug> nrf_dfu_req_handler: Request handling complete. Result: 0x1
00> <debug> app: Shutting down transports (found: 2)
00> <debug> nrf_dfu_ble: Shutting down BLE transport.
00> <debug> app: Failed to shutdown transport 1, error 8
00> <debug> nrf_dfu_serial_usb: Allocated buffer 200062B4
00> <debug> nrf_dfu_req_handler: Handle NRF_DFU_OP_OBJECT_WRITE (data)
00> <debug> nrf_dfu_flash: nrf_fstorage_write(addr=0x0008A400, src=0x20005AB4, len=1024 bytes), queue usage: 1
00> <debug> nrf_dfu_flash: Flash write success: addr=0x0008A400, pending 0
00> <debug> nrf_dfu_req_handler: Request handling complete. Result: 0x1
00> <debug> app: Shutting down transports (found: 2)
00> <debug> nrf_dfu_ble: Shutting down BLE transport.
00> <debug> app: Failed to shutdown transport 1, error 8
00> <debug> nrf_dfu_serial_usb: Allocated buffer 20005AB0
00> <debug> nrf_dfu_req_handler: Handle NRF_DFU_OP_OBJECT_WRITE (data)
00> <debug> nrf_dfu_flash: nrf_fstorage_write(addr=0x0008A800, src=0x200062B8, len=1024 bytes), queue usage: 1
00> <debug> nrf_dfu_flash: Flash write success: addr=0x0008A800, pending 0
00> <debug> nrf_dfu_req_handler: Request handling complete. Result: 0x1
00> <debug> app: Shutting down transports (found: 2)
00> <debug> nrf_dfu_ble: Shutting down BLE transport.
00> <debug> app: Failed to shutdown transport 1, error 8
00> <debug> nrf_dfu_serial_usb: Allocated buffer 200062B4
00> <debug> nrf_dfu_req_handler: Handle NRF_DFU_OP_OBJECT_WRITE (data)
00> <debug> nrf_dfu_flash: nrf_fstorage_write(addr=0x0008AC00, src=0x20005AB4, len=1024 bytes), queue usage: 1
00> <debug> nrf_dfu_flash: Flash write success: addr=0x0008AC00, pending 0
00> <debug> nrf_dfu_req_handler: Request handling complete. Result: 0x1
00> <debug> app: Shutting down transports (found: 2)
00> <debug> nrf_dfu_ble: Shutting down BLE transport.
00> <debug> app: Failed to shutdown transport 1, error 8
00> <debug> nrf_dfu_serial_usb: Allocated buffer 200062B4
00> <debug> nrf_dfu_req_handler: Handle NRF_DFU_OP_CRC_GET (data)
00> <debug> nrf_dfu_req_handler: Offset:57344, CRC:0x6A58AE2A
00> <debug> nrf_dfu_req_handler: Request handling complete. Result: 0x1
00> <debug> nrf_dfu_serial: Sending Response: [0x3, 0x1]
00> <debug> app: Shutting down transports (found: 2)
00> <debug> nrf_dfu_ble: Shutting down BLE transport.
00> <debug> app: Failed to shutdown transport 1, error 8
00> <debug> nrf_dfu_serial_usb: Allocated buffer 200062B4
00> <debug> nrf_dfu_req_handler: Handle NRF_DFU_OP_OBJECT_EXECUTE (data)
00> <debug> nrf_dfu_serial: Sending Response: [0x4, 0x1]
00> <debug> nrf_dfu_req_handler: Request handling complete. Result: 0x1
00> <debug> app: restarting timer
00> <debug> app: timer_stop (0x200057D4)
00> <debug> app: timer_start
00> <debug> app: timer_activate (0x200057D4)
00> <debug> app: Shutting down transports (found: 2)
00> <debug> nrf_dfu_ble: Shutting down BLE transport.
00> <debug> app: Failed to shutdown transport 1, error 8
00> <debug> nrf_dfu_serial_usb: Allocated buffer 200062B4
00> <debug> nrf_dfu_req_handler: Handle NRF_DFU_OP_OBJECT_CREATE (data)
00> <debug> nrf_dfu_flash: nrf_fstorage_erase(addr=0x0x0008B000, len=1 pages), queue usage: 1
00> <debug> nrf_dfu_flash: Flash erase success: addr=0x0008B000, pending 0
00> <debug> nrf_dfu_req_handler: Creating object with size: 4096. Offset: 0x0000E000, CRC: 0x6A58AE2A
00> <debug> nrf_dfu_req_handler: Request handling complete. Result: 0x1
00> <debug> nrf_dfu_serial: Sending Response: [0x1, 0x1]

(The last line of that log corresponds to the last line printed in the RTT viewer after I kill the NRFUtil process)

I can see that there's an error when the code tries to shut down the BLE transport layer. Can that be related to the problem that I have?

Thank you so much!

[Jose Cazarin]

Some new info

I realized that when I kill the NRFUtil program the event APP_USBD_CDC_ACM_USER_EVT_PORT_CLOSE is handled in the bootloader

So in nrf_dfu_serial_usb.c in the function cdc_acm_user_ev_handler inside the switch case that handles the events I added:

        case APP_USBD_CDC_ACM_USER_EVT_PORT_CLOSE:

        {

            nrf_bootloader_dfu_inactivity_timer_restart(

                NRF_BOOTLOADER_MS_TO_TICKS(NRF_BL_DFU_INACTIVITY_TIMEOUT_MS),

                inactivity_timeout);

        } break;


And I can see in the RTT output log the timer functions being called right after I kill the NRFUtil. But after the timeout expires, the callback that resets the board is not called
This leads me to believe that some code that runs when a DFU is being done over USB is keeping the timer from working properly and calling the callback

[Einar Thorsrud]

Hi,

What is the value of NRF_BL_DFU_INACTIVITY_TIMEOUT_MS in your bootlaoder's sdk_config.h file?

[Jose Cazarin]

It's the default:

#define NRF_BL_DFU_INACTIVITY_TIMEOUT_MS 120000

And like I said, it works in any other situation. If I don't do anything after entering the BL it reboots, if start a BLE DFU and stop it, it reboots as well. It doesn't work only when I try to do a DFU through USB

[Einar Thorsrud]

Hi,

I see. I have not been able to reproduce this error using the USB DFU bootloader example only modified to enable timeout (NRF_BL_DFU_INACTIVITY_TIMEOUT_MS is set to 0 in the open USB DFU bootloader example by default), no matter when I terminate nrfutil. But I have not tested with your modified bootloader that use both BLE and USB transport (which should not be a problem).

I do not immediately see what could cause the problem, and it is a bit difficult as I have not reproduced it. I see that closing the USB transport cannot fail. See implementation:

static uint32_t usb_dfu_transport_close(nrf_dfu_transport_t const * p_exception)
{
    return NRF_SUCCESS;
}

So it must be ble_dfu_transport_close() that returns an error. The return value of nrf_dfu_transports_close() is ignored by all callers, but it could be a problem that it breaks out of the loop when  closing the transport, which may not be a good idea when you have two transports. What happens if you remove the break statement on line 86 in components\libraries\bootloader\dfu\nrf_dfu_transport.c?

[Jose Cazarin]

It is indeed the nrf_dfu_tranports_close function that returns an error. But removing the break that you mentioned doesn't fix the problem

I've added some logs to the ble_dfu_transport_close  function. Heres what I got:

00> <debug> nrf_dfu_req_handler: Handle NRF_DFU_OP_OBJECT_WRITE (data)
00> <debug> nrf_dfu_flash: nrf_fstorage_write(addr=0x0008F800, src=0x200062B8, len=1024 bytes), queue usage: 1
00> <debug> nrf_dfu_flash: Flash write success: addr=0x0008F800, pending 0
00> <debug> nrf_dfu_req_handler: Request handling complete. Result: 0x1
00> <debug> app: Shutting down transports (found: 2)
00> <debug> nrf_dfu_ble: Shutting down BLE transport.
00> <debug> nrf_dfu_ble: sd_ble_gap_adv_stop ret value = 2
00> <debug> nrf_dfu_ble: nrf_sdh_disable_request ret value = 8
00> <debug> app: Failed to shutdown transport 1, error 8
00> <debug> nrf_dfu_serial_usb: Allocated buffer 200062B4
00> <debug> nrf_dfu_req_handler: Handle NRF_DFU_OP_OBJECT_WRITE (data)
00> <debug> nrf_dfu_flash: nrf_fstorage_write(addr=0x0008FC00, src=0x20005AB4, len=1024 bytes), queue usage: 1
00> <debug> nrf_dfu_flash: Flash write success: addr=0x0008FC00, pending 0
00> <debug> nrf_dfu_req_handler: Request handling complete. Result: 0x1
00> <debug> app: Shutting down transports (found: 2)
00> <debug> nrf_dfu_ble: Shutting down BLE transport.
00> <debug> nrf_dfu_ble: sd_ble_gap_adv_stop ret value = 2
00> <debug> nrf_dfu_ble: nrf_sdh_disable_request ret value = 8
00> <debug> app: Failed to shutdown transport 1, error 8

The bold lines represent the logs that I've added

So it looks like that both sd_ble_gap_adv_stop  and nrf_sdh_disable_request are returning errors

But it is strange that sd_ble_gap_adv_stop returns the error code 2 because it looks it can't return that value. From the ble_gap.h (using softdevice s140 6.1.1 ):

/**@brief Stop advertising (GAP Discoverable, Connectable modes, Broadcast Procedure).
*
* @mscs
* @mmsc{@ref BLE_GAP_ADV_MSC}
* @mmsc{@ref BLE_GAP_WL_SHARE_MSC}
* @endmscs
*
* @param[in] adv_handle The advertising handle that should stop advertising.
*
* @retval ::NRF_SUCCESS The BLE stack has stopped advertising.
* @retval ::BLE_ERROR_INVALID_ADV_HANDLE Invalid advertising handle.
* @retval ::NRF_ERROR_INVALID_STATE The advertising handle is not advertising.
*/
SVCALL(SD_BLE_GAP_ADV_STOP, uint32_t, sd_ble_gap_adv_stop(uint8_t adv_handle));

None of those values can be 2

And the error code for nrf_sdh_disable_request  is 8 which is NRF_ERROR_INVALID_STATE

Could that be problem? Maybe for some reason, the unsuccessful shutdown of the BLE transport is keeping the timer from working properly?

Thank you so much for your help so far