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!

[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 have looked a bit more into this, and using your changed on the DK (with on modification which is to trigger DFU mode on pin reset and reducing the timeout to 60 seconds to save some time). I did see the same issue.

Jose Cazarin said:

Can the softdevice be disabled at runtime?

Yes, and that happens then the BLE transport is disabled. Specifically ble_dfu_transport_close() calls nrf_sdh_disable_request() which in turn disabled the SoftDevice.

I did look into the error message you get. The on_rx_complete() function in components\libraries\bootloader\serial_dfu\nrf_dfu_serial_usb.c calls nrf_dfu_transports_close() for every request that is handled (). This calls ble_dfu_transport_close(), which succeeds the first time, as you can see from this line in the log:

00> <debug> nrf_dfu_ble: BLE transport shut down.

However it is called for every subsequent request, and then it fails, as the SoftDevice has allready been disabled, and you get this line for every subsequent call:

00> <debug> app: Failed to shutdown transport 1, error 8

You can for instance fix this like this, so that the SoftDevice is only disabled once:

Fullscreen 2210.nrf_dfu_ble.c.diff Download

diff --git a/components/libraries/bootloader/ble_dfu/nrf_dfu_ble.c b/components/libraries/bootloader/ble_dfu/nrf_dfu_ble.c
index b8b6d47..4f91aff 100644
--- a/components/libraries/bootloader/ble_dfu/nrf_dfu_ble.c
+++ b/components/libraries/bootloader/ble_dfu/nrf_dfu_ble.c
@@ -1208,7 +1208,11 @@ static uint32_t ble_dfu_transport_close(nrf_dfu_transport_t const * p_exception)
 {
     uint32_t err_code = NRF_SUCCESS;
 
-    if ((m_flags & DFU_BLE_FLAG_INITIALIZED) && (p_exception != &ble_dfu_transport))
+    if (!nrf_sdh_is_enabled())
+    {
+        NRF_LOG_DEBUG("BLE transport allready disabled.");
+    }
+    else if ((m_flags & DFU_BLE_FLAG_INITIALIZED) && (p_exception != &ble_dfu_transport))
     {
         NRF_LOG_DEBUG("Shutting down BLE transport.");
 

I notised something interesting while doing this, when I accidentally never disabled the SoftDevice. In that case, the timeout worked as expected. That made me think of an old issue, which I believe holds the explanation. Disabling the SoftDevice also disabled the 32.768 kHz LFCLK, which is the clock source for the RTC used for the timeout. So if you disable the SoftDevice you need to re-enable the LFCLK. This is described in this thread.

[Jose Cazarin]

Thanks! Was able to remove both the error messages when trying to disable the SD and also got the timer to work
I fixed that by changing the sd_state_evt_handler  in the nrf_drv_clock.c

There's a switch case in that function, and when it handles the case NRF_SDH_EVT_STATE_DISABLED it calls nrf_drv_clock_lfclk_release

For some reason, the said timer is not being counted as a request for the LFCLK. So when the nrf_drv_clock_lfclk_release function is called it thinks that there are no more requests and stops the LFCLOCK

So I just removed the call to nrf_drv_clock_lfclk_release  in that switch statement and everything is fine now

Thank you so much for your help during this whole week!

[Einar Thorsrud]

Hi Jose,

Jose Cazarin said:

So I just removed the call to nrf_drv_clock_lfclk_release  in that switch statement and everything is fine now

I am glad to hear it works. Thank you for updating and letting us know.

Jose Cazarin said:

For some reason, the said timer is not being counted as a request for the LFCLK. So when the nrf_drv_clock_lfclk_release function is called it thinks that there are no more requests and stops the LFCLOCK

The app_timer library does not request the LFCLK, though it is required, so it makes sense that it works like this, though it is not ideal. (I believe this is for historic reasons as the clock driver is newer than the app_timer module.)

[Jose Cazarin]

So, should this be filed as a bug? Or, was that fixed already in the newer versions of the SDK?

[Einar Thorsrud]

Hi,

This is not fixed in any nRF5 SDK release. I have reported this as a bug, but I cannot say when it will be fixed.