[NRF91] B0 + MCUBOOT (+ SPM + APP) -> updating MCUBoot over fota results in bootloop

[Jelmer]

After figuring out why MCUBoot wasn't updating my application (https://devzone.nordicsemi.com/f/nordic-q-a/74145/nrf91-b0-mcuboot-app---mcuboot-not-actually-updating-app-after-fota) I'm now trying to get B0 to update MCUBoot with fota in my application.

I have the same setup based op the asset_tracker_v2 example: B0 + MCUBoot + SPM + App.

I'm trying to update MCUBoot over FOTA.

In `./child_image/mcuboot.conf` I have the following config:

CONFIG_BOOT_SIGNATURE_KEY_FILE="/hard/coded/path/to/priv.pem"
CONFIG_FW_INFO_FIRMWARE_VERSION=1

I'm compiling both S0 and S1 versions of mcuboot. And copying `signed_by_mcuboot_and_b0_s0_image_update.bin` and `signed_by_mcuboot_and_b0_s1_image_update.bin` to AWS S3.

When flashing my application to my device (with --erase) I get following logs:

*** Booting Zephyr OS build zephyr-v2.5.0-1102-g6a1d340b632e  ***
Attempting to boot slot 0.
Attempting to boot from address 0x8200.
Verifying signature against key 0.
Hash: 0xff...a8
Firmware signature verified.
Firmware version 1
Setting monotonic counter (version: 1, slot: 0)
*** Booting Zephyr OS build zephyr-v2.5.0-1102-g6a1d340b632e  ***
I: Starting bootloader V1
I: Primary image: magic=unset, swap_type=0x1, copy_done=0x3, image_ok=0x3
I: Secondary image: magic=unset, swap_type=0x1, copy_done=0x3, image_ok=0x3
I: Boot source: none
I: Swap type: none
I: Primary image: magic=unset, swap_type=0x1, copy_done=0x3, image_ok=0x3
I: Secondary image: magic=unset, swap_type=0x1, copy_done=0x3, image_ok=0x3
I: Boot source: none
I: Swap type: none
I: Bootloader chainload address offset: 0x28000
�*** Booting Zephyr OS build zephyr-v2.5.0-1102-g6a1d340b632e  ***
Flash regions		Domain		Permissions
00 06 0x00000 0x38000 	Secure		rwxl
07 31 0x38000 0x100000 	Non-Secure	rwxl

Non-secure callable region 0 placed in flash region 5 with size 32.

SRAM region		Domain		Permissions
00 07 0x00000 0x10000 	Secure		rwxl
08 31 0x10000 0x40000 	Non-Secure	rwxl

Peripheral		Domain		Status
00 NRF_P0               Non-Secure	OK
01 NRF_CLOCK            Non-Secure	OK
02 NRF_RTC0             Non-Secure	OK
03 NRF_RTC1             Non-Secure	OK
04 NRF_NVMC             Non-Secure	OK
05 NRF_UARTE1           Non-Secure	OK
06 NRF_UARTE2           Secure		SKIP
07 NRF_TWIM2            Non-Secure	OK
08 NRF_SPIM3            Non-Secure	OK
09 NRF_TIMER0           Non-Secure	OK
10 NRF_TIMER1           Non-Secure	OK
11 NRF_TIMER2           Non-Secure	OK
12 NRF_SAADC            Non-Secure	OK
13 NRF_PWM0             Non-Secure	OK
14 NRF_PWM1             Non-Secure	OK
15 NRF_PWM2             Non-Secure	OK
16 NRF_PWM3             Non-Secure	OK
17 NRF_WDT              Non-Secure	OK
18 NRF_IPC              Non-Secure	OK
19 NRF_VMC              Non-Secure	OK
20 NRF_FPU              Non-Secure	OK
21 NRF_EGU1             Non-Secure	OK
22 NRF_EGU2             Non-Secure	OK
23 NRF_DPPIC            Non-Secure	OK
24 NRF_REGULATORS       Non-Secure	OK
25 NRF_PDM              Non-Secure	OK
26 NRF_I2S              Non-Secure	OK
27 NRF_GPIOTE1          Non-Secure	OK

SPM: NS image at 0x38200
SPM: NS MSP at 0x2002b9d0
SPM: NS reset vector at 0x45bd1
SPM: prepare to jump to Non-Secure image.
*** Booting Zephyr OS build zephyr-v2.5.0-1102-g6a1d340b632e  ***
[00:00:00.214,202] <dbg> cloud_module.state_set: State: STATE_LTE_DISCONNECTED
--> continues booting app

Note firmware version 1 recognized by B0, and corresponding `I: Starting bootloader V1` debug output by MCUBoot (version printout added by me in MCUBoot code).

Afterwards I recompile the project with `CONFIG_FW_INFO_FIRMWARE_VERSION` of MCUBoot bumped to 2 and manually changed the print out in main.c to say V2.

Then I upload both S0 and S1 versions to AWS S3 and initiate a FOTA update of MCUBoot via AWS jobs:

[00:02:45.868,743] <dbg> aws_fota.on_publish_evt: Received topic: $aws/things/352656105128063/jobs/notify-next
[00:02:45.879,150] <dbg> aws_fota.on_publish_evt: Checking for an available job
[00:02:45.887,084] <dbg> aws_fota.get_job_execution: Job doc: {"timestamp":1619420012,"execution":{"jobId":"test_fota_352656105128063_1619420010","status":"QUEUED","queuedAt":1619420012,"lastUpdatedAt":1619420012,"versionNumber":1,"executionNumber":1,"jobDocument":{"operation":"mcuboot_fw_update","fwversion":"v0.0.0","size":1,"location":{"protocol":"http:","host":"*****.s3-eu-west-1.amazonaws.com","path":"fota/mcuboot/signed_by_mcuboot_and_b0_s0_image_update.bin fota/mcuboot/signed_by_mcuboot_and_b0_s1_image_update.bin"}}}}
[00:02:45.936,431] <dbg> aws_fota.get_job_execution: Job ID: test_fota_352656105128063_1619420010
[00:02:45.945,678] <dbg> aws_fota.get_job_execution: hostname: *****.s3-eu-west-1.amazonaws.com
[00:02:45.955,780] <dbg> aws_fota.get_job_execution: file_path fota/mcuboot/signed_by_mcuboot_and_b0_s0_image_update.bin fota/mcuboot/signed_by_mcuboot_and_b0_s1_image_update.bin
[00:02:45.972,137] <dbg> aws_fota.get_job_execution: execution_version_number: 1
[00:02:45.981,201] <dbg> aws_fota.get_job_execution: Subscribed to FOTA update topic $aws/things/352656105128063/jobs/test_fota_352656105128063_1619420010/update/#
[00:02:46.212,371] <dbg> aws_fota.update_job_execution: update_job_execution, state: 1, version_number: 1
[00:02:46.778,411] <dbg> aws_iot.mqtt_evt_handler: MQTT_EVT_PUBACK: id = 7291 result = 0
[00:02:46.787,109] <dbg> aws_fota.on_publish_evt: Received topic: $aws/things/352656105128063/jobs/test_fota_352656105128063_1619420010/update/accepted
[00:02:46.801,147] <dbg> aws_fota.job_update_accepted: Start downloading firmware from ****.s3-eu-west-1.amazonaws.com/fota/mcuboot/signed_by_mcuboot_and_b0_s0_image_update.bin fota/mcuboot/signed_by_mcuboot_and_b0_s1_image_update.bin
[00:02:46.823,455] <inf> fota_download: B1 update, selected file:
fota/mcuboot/signed_by_mcuboot_and_b0_s1_image_update.bin

Note that the S1 version is being downloaded.

After downloading and rebooting:

*** Booting Zephyr OS build zephyr-v2.5.0-1102-g6a1d340b632e  ***
Attempting to boot slot 0.
Attempting to boot from address 0x8200.
Verifying signature against key 0.
Hash: 0xff...a8
Firmware signature verified.
Firmware version 1
*** Booting Zephyr OS build zephyr-v2.5.0-1102-g6a1d340b632e  ***
I: Starting bootloader V1
I: Primary image: magic=unset, swap_type=0x1, copy_done=0x3, image_ok=0x3
I: Secondary image: magic=good, swap_type=0x2, copy_done=0x3, image_ok=0x3
I: Boot source: none
I: Primary image: magic=unset, swap_type=0x1, copy_done=0x3, image_ok=0x3
I: Secondary image: magic=good, swap_type=0x2, copy_done=0x3, image_ok=0x3
I: Boot source: none
I: Swap type: test
D: erasing trailer; fa_id=7
D: initializing status; fa_id=7
D: writing swap_info; fa_id=7 off=0xc1d8 (0x241d8), swap_type=0x2 image_num=0x1
D: writing swap_size; fa_id=7 off=0xc1d0 (0x241d0)
D: writing magic; fa_id=7 off=0xc1f0 (0x241f0)
D: erasing trailer; fa_id=17
D: writing copy_done; fa_id=7 off=0xc1e0 (0x241e0)
I: Bootloader chainload address offset: 0x28000
�*** Booting Zephyr OS build zephyr-v2.5.0-1102-g6a1d340b632e  ***
Flash regions		Domain		Permissions
00 06 0x00000 0x38000 	Secure		rwxl
07 31 0x38000 0x100000 	Non-Secure	rwxl

Non-secure callable region 0 placed in flash region 5 with size 32.

SRAM region		Domain		Permissions
00 07 0x00000 0x10000 	Secure		rwxl
08 31 0x10000 0x40000 	Non-Secure	rwxl

Peripheral		Domain		Status
00 NRF_P0               Non-Secure	OK
01 NRF_CLOCK            Non-Secure	OK
02 NRF_RTC0             Non-Secure	OK
03 NRF_RTC1             Non-Secure	OK
04 NRF_NVMC             Non-Secure	OK
05 NRF_UARTE1           Non-Secure	OK
06 NRF_UARTE2           Secure		SKIP
07 NRF_TWIM2            Non-Secure	OK
08 NRF_SPIM3            Non-Secure	OK
09 NRF_TIMER0           Non-Secure	OK
10 NRF_TIMER1           Non-Secure	OK
11 NRF_TIMER2           Non-Secure	OK
12 NRF_SAADC            Non-Secure	OK
13 NRF_PWM0             Non-Secure	OK
14 NRF_PWM1             Non-Secure	OK
15 NRF_PWM2             Non-Secure	OK
16 NRF_PWM3             Non-Secure	OK
17 NRF_WDT              Non-Secure	OK
18 NRF_IPC              Non-Secure	OK
19 NRF_VMC              Non-Secure	OK
20 NRF_FPU              Non-Secure	OK
21 NRF_EGU1             Non-Secure	OK
22 NRF_EGU2             Non-Secure	OK
23 NRF_DPPIC            Non-Secure	OK
24 NRF_REGULATORS       Non-Secure	OK
25 NRF_PDM              Non-Secure	OK
26 NRF_I2S              Non-Secure	OK
27 NRF_GPIOTE1          Non-Secure	OK

SPM: NS image at 0x38200
SPM: NS MSP at 0x2002b9d0
SPM: NS reset vector at 0x45bd1
SPM: prepare to jump to Non-Secure image.
*** Booting Zephyr OS build zephyr-v2.5.0-1102-g6a1d340b632e  ***
[00:00:00.214,202] <dbg> cloud_module.state_set: State: STATE_LTE_DI

Note that B0 is still booting from slot 0 and MCUBoot firmware version isn't bumped to V2 -> MCUBoot isn't updated. Looks like B0 isn't selecting the downloaded version in S1.

After this, I retry the FOTA process without changing anything to the compiled binaries. So no re-compiling or bumping versions:

[00:01:00.817,565] <dbg> aws_fota.on_publish_evt: Checking for an available job
[00:01:00.825,500] <dbg> aws_fota.get_job_execution: Job doc: {"timestamp":1619420123,"execution":{"jobId":"test_fota_352656105128063_1619420122","status":"QUEUED","queuedAt":1619420122,"lastUpdatedAt":1619420122,"versionNumber":1,"executionNumber":1,"jobDocument":{"operation":"mcuboot_fw_update","fwversion":"v0.0.0","size":1,"location":{"protocol":"http:","host":"*****.s3-eu-west-1.amazonaws.com","path":"fota/mcuboot/signed_by_mcuboot_and_b0_s0_image_update.bin fota/mcuboot/signed_by_mcuboot_and_b0_s1_image_update.bin"}}}}
[00:01:00.874,877] <dbg> aws_fota.get_job_execution: Job ID: test_fota_352656105128063_1619420122
[00:01:00.884,124] <dbg> aws_fota.get_job_execution: hostname: *****.s3-eu-west-1.amazonaws.com
[00:01:00.894,226] <dbg> aws_fota.get_job_execution: file_path fota/mcuboot/signed_by_mcuboot_and_b0_s0_image_update.bin fota/mcuboot/signed_by_mcuboot_and_b0_s1_image_update.bin
[00:01:00.910,583] <dbg> aws_fota.get_job_execution: execution_version_number: 1
[00:01:00.919,616] <dbg> aws_fota.get_job_execution: Subscribed to FOTA update topic $aws/things/352656105128063/jobs/test_fota_352656105128063_1619420122/update/#
[00:01:01.185,882] <dbg> aws_fota.update_job_execution: update_job_execution, state: 1, version_number: 1
[00:01:01.715,881] <dbg> aws_iot.mqtt_evt_handler: MQTT_EVT_PUBACK: id = 39191 result = 0
[00:01:01.740,722] <dbg> aws_fota.on_publish_evt: Received topic: $aws/things/352656105128063/jobs/test_fota_352656105128063_1619420122/update/accepted
[00:01:01.754,760] <dbg> aws_fota.job_update_accepted: Start downloading firmware from *****.s3-eu-west-1.amazonaws.com/fota/mcuboot/signed_by_mcuboot_and_b0_s0_image_update.bin fota/mcuboot/signed_by_mcuboot_and_b0_s1_image_update.bin
[00:01:01.777,038] <inf> fota_download: B1 update, selected file:
fota/mcuboot/signed_by_mcuboot_and_b0_s0_image_update.bin
[00:01:02.025,177] <inf> download_client: Configuring socket timeout (30 s)
[00:01:02.032,531] <inf> download_client: Connecting to *****.s3-eu-west-1.amazonaws.com
[00:01:02.251,159] <inf> download_client: Downloading: fota/mcuboot/signed_by_mcuboot_and_b0_s0_image_update.bin [0]
[00:01:02.262,054] <dbg> aws_iot.aws_fota_cb_handler: AWS_FOTA_EVT_START
[00:01:02.269,195] <dbg> aws_iot_integration.aws_iot_event_handler: AWS_IOT_EVT_FOTA_START
[00:01:02.277,923] <dbg> cloud_module.cloud_wrap_event_handler: CLOUD_WRAP_EVT_FOTA_START
[00:01:02.577,819] <inf> download_client: Downloaded 1024/37443 bytes (2%)
[00:01:03.050,628] <inf> download_client: Downloaded 2048/37443 bytes (5%)

Note that now the S0 version is downloaded.

And after the reset:

*** Booting Zephyr OS build zephyr-v2.5.0-1102-g6a1d340b632e  ***
Attempting to boot slot 1.
Attempting to boot from address 0x18200.
Verifying signature against key 0.
Hash: 0xff...a8
Firmware signature verified.
Firmware version 2
Setting monotonic counter (version: 2, slot: 1)
E: >>> ZEPHYR FATAL ERROR 1: Unhandled interrupt on CPU 0
E: Current thread: (nil) (unknown)
*** Booting Zephyr OS build zephyr-v2.5.0-1102-g6a1d340b632e  ***
Attempting to boot slot 1.
Attempting to boot from address 0x18200.
Verifying signature against key 0.
Hash: 0xff...a8
Firmware signature verified.
Firmware version 2
E: >>> ZEPHYR FATAL ERROR 1: Unhandled interrupt on CPU 0
E: Current thread: (nil) (unknown)
*** Booting Zephyr OS build zephyr-v2.5.0-1102-g6a1d340b632e  ***
Attempting to boot slot 1.
Attempting to boot from address 0x18200.
Verifying signature against key 0.
Hash: 0xff...a8
Firmware signature verified.
Firmware version 2
E: >>> ZEPHYR FATAL ERROR 1: Unhandled interrupt on CPU 0
E: Current thread: (nil) (unknown)

Now B0 does select slot 1 and firmware version 2, but when jumping to S1 I get a fatal error. And a boot-loop ensues. 

It seems some of the logic in B0 isn't selecting the correct slot after the first time the FOTA is ran.

I have set both 

CONFIG_SB_SIGNING_KEY_FILE="keys/priv.pem"
CONFIG_SB_PUBLIC_KEY_FILES="keys/publ1.pem,keys/publ2.pem,keys/publ3.pem"

What am I / is B0 doing wrong?

Thanks!

[Simon]

Hello Jelmer.

Sorry for the delay on this, I'll look into it the next days.

BR,

Simon

[Jelmer]

Thanks Simon

[Simon]

It seems like this check: https://github.com/nrfconnect/sdk-nrf/blob/v1.5.0/samples/bootloader/src/main.c#L62 evaluates to true, which will make the bootloader check S0 first. The bootloader then finds a valid image in S0 and will boot that.

In your case, either s1_info is set to NULL, which means the magic value was not found, or the firmware version of S0 was greater or equal than the firmware version of S1. Could you add some printk's and figure out what's the case?

I may also be useful to take a look at the file signed_by_mcuboot_and_b0_s1_image_update.bin, e.g. by opening it up in HEX Editor Neo. The fw info struct (which contains the firmware version and the magic value) should be stored inside the signed_by_mcuboot_and_b0_s1_image_update.bin file at the offset specified by CONFIG_FW_INFO_OFFSET (Take a look at <application>\build\mcuboot\zephyr\.config), to see what CONFIG_FW_INFO_OFFSET is equal to.

If anything is unclear, please tell me and I will try to elaborate.

Best regards,

Simon