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

[Einar Thorsrud]

Hi,

Jose Cazarin said:

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

These error codes could make sense, as 2 = NRF_ERROR_SOFTDEVICE_NOT_ENABLED, and 8 = NRF_ERROR_INVALID_STATE, as you have noted. Is the SoftDevice enabled at this point? These are the return values you would expect if the SoftDevice is not enabled.

Jose Cazarin said:

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

I am not sure what is going on, but clearly the bootloader is not in a good state, and it looks like the SoftDevice is not enabled. Is it possible to upload your bootloader code here? Does it run on a DK?

[Jose Cazarin]

It runs on a custom board that uses the NRF52840. Is it possible for the softdevice to not be enabled and the DFU through BLE still works? Because I can do a BLE DFU with this bootloader with no problems.
There are no major changes to the SDK code other than some code that was added to use a LED as a visual hint of what's going on.
I started with the USB secure bootloader example and added the BLE transport layer by adjusting the Makefile and sdk_config.h
I can share the makefile, sdk_config.h and the linker script that I'm using.

I just removed the defines/flags used for our custom board from it, so now it is compiling for the default PCA10056 board

I'm attaching the three files ble_and_serial_bl.zip

[Einar Thorsrud]

Hi,

Jose Cazarin said:

Is it possible for the softdevice to not be enabled and the DFU through BLE still works?

No. The SoftDevice is the BLE stack, and there can be no BLE working without it enabled. Perhaps it was disabled before? I am just speculating at this point, but the return codes you get are a strong indication that the SoftDevice is not enabled at that point.

Jose Cazarin said:

I just removed the defines/flags used for our custom board from it, so now it is compiling for the default PCA10056 board

I see. I dropping the Makefile and linker script into <SDK 15.2>\examples\dfu\open_bootloader\pca10059_usb\armgcc\ and the sdk_config.h into <SDK 15.2>\examples\dfu\open_bootloader\pca10059_usb\config\, but was not able to build it. Can you upload a project that reproduce the issue and that you have verified that builds with an unmodified SDK 15.2, along with any instructions if needed so that I can test on my side?

[Jose Cazarin]

Einar Thorsrud said:

No. The SoftDevice is the BLE stack, and there can be no BLE working without it enabled. Perhaps it was disabled before? I am just speculating at this point, but the return codes you get are a strong indication that the SoftDevice is not enabled at that point.

Can the softdevice be disabled at runtime? I thought it was enabled at build time, and since the DFU through BLE is working with this bootloader, I thought that there's no way it could be disabled.

Sorry, there was a mistake in my Makefile, some flags were not necessary and they break the SDK build

I tested it with an unmodified version of the SDK and it compiled fine now. But I'm using the secure bootloader, so you should put the makefile and the linker in the folder:
15.2>\examples\dfu\secure_bootloader\pca10056_usb_debug\armgcc\
And the sdk_confih.g in the: 
15.2>\examples\dfu\secure_bootloader\pca10056_usb_debug\config\

I'm attaching the new version. I've tested it on my custom board and the same problem happens. I wasn't able to test it on an actual NRF52840 dev kit though.

Let me know about the results! Thanks!

1581.ble_and_serial_bl_v2.zip

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