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,

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.