nRF52840 reset during image_copy in nrf_bootloader_fw_activation.c

[Daniel Fedai Larsen]

Hi,

I'm working on a project with the nRF52840 using nRF5 SDK v15.3.0 and have been working on enabling dual-bank DFU in the bootloader. During this process I made several captures of the MCU's reset behavior when installing DFU packages (either with only application images or both bootloader and SoftDevice images) transferred over BLE. My understanding of the installation process is as follows:

• Application image only:
  • To start the download the MCU resets and the bootloader enters DFU mod
  • After the download is complete the MCU resets and the bootloader starts activating the image in the DFU package
  • After the new image has been copied from bank 1 to bank 0 the MCU resets into the bootloader and boots the new application image
• Bootloader + SoftDevice:
  • To start the download the MCU resets and the bootloader enters DFU mode
  • After the download is complete the MCU resets and the bootloader starts activating the images in the DFU package
    • The new SoftDevice is copied and overwrites the old one
    • The SD_MBR_COMMAND_COPY_BL command is submitted, the MCU resets and the MBR copies the new bootloader and overwrites the old one
    • The MCU boots into the new bootloader and the activation continues
  • After the activation is finished the MCU resets into the bootloader and boots the application image

In the described scenarios there's going to be 3 and 4 resets respectively for the installation to complete. However, from my testing I'm consistently seeing 1 additional reset in both scenarios. The additional reset happens during the image_copy function in nrf_bootloader_fw_activation.c (which is called when copying the new application image and when copying the new SoftDevice image). The additional reset happens consistently, and in the same place. The image_copy function is called with arguments that at most allows it to copy 8*4KiB=32KiB at a time, and it's during the 4th of these copies (the 4th iteration of the while-loop in the function) that the reset happens. In both cases the MCU reset an additional time and continues the copying and finishes the whole installation process.

Below are some Saleae captures I hope help illustrate what I'm seeing. The signal POWER_ON indicates MCU resets, with it going low meaning the MCU reset and it going high meaning the bootloader has started running. I've then added additional toggling of the same signal to indicate loops in image_copy.

• Base capture without additional toggling of POWER_ON
  
  
• Capture with additional toggling of POWER_ON
  
  

It's not visible in the captures, but I can tell the difference between my toggles and MCU resets by how long POWER_ON stays low (my toggles holds POWER_ON low for 300ns while MCU resets holds it low for 700us).

I've tried moving the extra toggling of POWER_ON to after the other function calls in image_copy (nrf_dfu_flash_erase, nrf_dfu_flash_store and nrf_dfu_settings_write_and_backup), but I see the same number of toggles and the behavior is still present. To me this means it's not one of the functions failing. In image_copy there's this line:

//Firmware copying is time consuming operation thus watchdog handling is started
nrf_bootloader_wdt_init();

Could there be an issue wrt. the watchdog that's "fixed" when a reset happens and the MCU continues with the same process/code? The above captures are from updating the bootloader+SoftDevice, so the amount of copying isn't that large, but when updating the application there's substantially more data being copied after the additional reset than before, so I don't think it's simply the amount of time spent copying that's potentially resulting in the watchdog timing out.

Unfortunately I don't have logs from the bootloader as building with logs exceeds the amount of flash the bootloader can occupy.

As a whole the update process works, so I'm mostly interested to understand why the additional reset is there.

Thanks,
Daniel

[Edvin]

Hello Daniel,

Thank you for the detailed report!

Let us look into the first case for now, application update, where you also see one additional reset compared to the description.

I must be honest. It has been a long time since I looked deep into the bootloader behavior in the nRF5 SDK, so I can't tell from the top of my head whether your description is correct, or if what you see is actually one additional reset.

First, does the DFU work? Even with the additional reset, is the DFU a success, and it does eventually start the new application?

I think the first thing we should look into is the logs, and the reset reason (which we can print to the log). 

Unfortunately I don't have logs from the bootloader as building with logs exceeds the amount of flash the bootloader can occupy.

For a simple test, you can try to replicate this behavior using the debug version of the bootloader. It is identical to the normal bootloader, except logging is enabled and the start address is moved to fit the logging.

You are using SDK15.3.0, but I don't know what IDE you are using. Please let me know if you don't find where to change the start address.

Looking comparing these two:

SDK15.3.0\examples\dfu\secure_bootloader\pca10056_ble

SDK15.3.0\examples\dfu\secure_bootloader\pca10056_ble_debug

You should see that they are quite similar, but if we compare the beginning of the armgcc\secure_bootloader_gcc_nrf52.ld from the two:

"normal":

MEMORY
{
  FLASH (rx) : ORIGIN = 0xf8000, LENGTH = 0x6000
  RAM (rwx) :  ORIGIN = 0x200057b8, LENGTH = 0x3a848
  uicr_bootloader_start_address (r) : ORIGIN = 0x00000FF8, LENGTH = 0x4
  bootloader_settings_page (r) : ORIGIN = 0x000FF000, LENGTH = 0x1000
  uicr_mbr_params_page (r) : ORIGIN = 0x00000FFC, LENGTH = 0x4
  mbr_params_page (r) : ORIGIN = 0x000FE000, LENGTH = 0x1000
}

_debug:

MEMORY
{
  FLASH (rx) : ORIGIN = 0xf1000, LENGTH = 0xd000
  RAM (rwx) :  ORIGIN = 0x200057b8, LENGTH = 0x3a848
  uicr_bootloader_start_address (r) : ORIGIN = 0x00000FF8, LENGTH = 0x4
  bootloader_settings_page (r) : ORIGIN = 0x000FF000, LENGTH = 0x1000
  uicr_mbr_params_page (r) : ORIGIN = 0x00000FFC, LENGTH = 0x4
  mbr_params_page (r) : ORIGIN = 0x000FE000, LENGTH = 0x1000
}

We can see that the _debug version has a different FLASH ORIGN and LENGTH. The rest should be identical.

If you are using an IDE (Keil/Segger Embedded Studio/IAR), then this are settings in the IDE's project settings, but you should be able to use the flash start address and length similar to the ones in the _debug project. Then you should be able to enable logging in the bootloader. Try doing this, enable logging in your bootloader, and see if you can see what is going on without modifying anything else. If that doesn't tell us what is happening, try to add this to the beginning of the bootloader's main() function:

    uint32_t reset_reason = NRF_POWER->RESETREAS;
    NRF_LOG_INFO("booting up. Reset reason: %08x", reset_reason);
    NRF_POWER->RESETREAS = reset_reason;

Like this:

This should print something like "booting up. Reset reason 0x00000001"

Then compare the reset reason to the reset reason register:

(Source)

What are the causes of the resets? We would expect it to be mostly SREQ (0x00000100), but are one of them from e.g. "DOG" (0x00000010)?

Best regards,

Edvin

[Daniel Fedai Larsen]

Hi Edvin,

Thanks for your quick response. Answering the simple questions first:

• Yes, the DFU works, which is why I we've not noticed this behavior before (it's probably always been there)
• We're using IAR with VS Code

I'll try changing the start address and report back

[Daniel Fedai Larsen]

Hi,

I've been able to enable logging by moving the bootloader as you suggested, and have attached the log from performing an application-only DFU.

Searching for "Inside main" there are 4 hits: 1) enter DFU mode, 2) after download is finished to start activation, 3) during copying and 4) final boot. The 3rd boot is during the following copy:

<debug> app: Copying 0x82000 to 0x36000, size: 0x8000

log_rtt_dual_bank_app_dfu.txt

Any thoughts?

[Edvin]

I can't see any loggings about the reset reason. Can you please try to add that, to see if it could possibly be a watchdog reset, or something else?

BR,

Edvin