MCUboot loses pending update image in slot 1 after reset

I'm trying to download and flash an MCUboot image at runtime. All goes well, the image is flashed to the secondary slot, confirmed, and marked for upgrade. The secondary slot is in external spi flash.

On reboot MCUboot has no knowledge of the secondary image and boots back into the primary image. What could be going wrong here?

Stack trace BEFORE reset:

I: Image index: 0, Swap type: none
D: mcuboot_swap_type: 1
D: writing magic; fa_id=1 off=0xd7ff0 (0xd7ff0)
D: writing swap_info; fa_id=1 off=0xd7fd8 (0xd7fd8), swap_type=0x2 image_num=0x0
D: 
Image info: mcuboot_primary
I: Image index: 0, Swap type: test
I: MCUboot swap type: 2
I: Image Version 0.3.0-0
I: Image is confirmed OK
D: 
Image info: mcuboot_secondary
I: Image index: 0, Swap type: test
I: MCUboot swap type: 2
I: Image Version 0.3.1-0
I: Image is confirmed OK

`mcumgr image list` BEFORE reset:

Images:
 image=0 slot=0
    version: 0.3.0
    bootable: true
    flags: active confirmed
    hash: 649999195e98cbc94b74be313c406478d4932a42c2fc22e622e4f480b4e9806f
 image=0 slot=1
    version: 0.3.1
    bootable: true
    flags: pending
    hash: 777ed754b4bac05b53a5763ecf0cb37c2a66320d7e0226fe8fa5c2c8a7291443
Split status: N/A (0)

Stack trace AFTER reset:

*** Booting nRF Connect SDK v2.5.2 ***
I: Reset Reason 2, Flags:
W: RESET_SOFTWARE
D: 
Image info: mcuboot_primary
I: Image index: 0, Swap type: none
I: MCUboot swap type: 1
I: Image Version 0.3.0-0
I: Image is confirmed OK
D: 
Image info: mcuboot_secondary
I: Image index: 0, Swap type: none
I: MCUboot swap type: 1
I: Image Version 76.146.8194-224105
I: Image is confirmed OK

`mcumgr image list` AFTER reset:

Images:
 image=0 slot=0
    version: 0.3.0
    bootable: true
    flags: active confirmed
    hash: 649999195e98cbc94b74be313c406478d4932a42c2fc22e622e4f480b4e9806f
Split status: N/A (0)

My `mcuboot.conf`:

#core should be on a clean state when TF-M starts
CONFIG_MCUBOOT_CLEANUP_ARM_CORE=y

# Increase MCUboot stack size
CONFIG_BOOT_MAX_IMG_SECTORS=256
CONFIG_PM_PARTITION_SIZE_MCUBOOT=0x20000

CONFIG_BOOT_SIGNATURE_KEY_FILE="../keys/private/boot-ecdsa-p256.pem"
CONFIG_BOOT_SIGNATURE_TYPE_ECDSA_P256=y
CONFIG_BOOT_ECDSA_CC310=y
# CONFIG_BOOT_SWAP_USING_MOVE=y
# CONFIG_BOOT_SWAP_SAVE_ENCTLV=y

# SPI Flash
CONFIG_SPI=y
CONFIG_NVS=y
CONFIG_PM_EXTERNAL_FLASH_BASE=0x0
CONFIG_PM_PARTITION_REGION_NVS_STORAGE_EXTERNAL=y
CONFIG_SPI_NOR=y
CONFIG_SPI_NOR_FLASH_LAYOUT_PAGE_SIZE=4096
CONFIG_PM_EXTERNAL_FLASH_MCUBOOT_SECONDARY=y
CONFIG_PM_OVERRIDE_EXTERNAL_DRIVER_CHECK=y

CONFIG_UART_CONSOLE=n

# Enable ech command
CONFIG_BOOT_MGMT_ECHO=y

# Enable flash operations
CONFIG_FLASH=y

# Enable serial recovery
CONFIG_MCUBOOT_SERIAL=y
CONFIG_BOOT_SERIAL_UART=y
CONFIG_MCUBOOT_SERIAL_DIRECT_IMAGE_UPLOAD=y
CONFIG_BOOT_SERIAL_WAIT_FOR_DFU=y
CONFIG_BOOT_SERIAL_WAIT_FOR_DFU_TIMEOUT=1000
CONFIG_BOOT_SERIAL_IMG_GRP_IMAGE_STATE=y
CONFIG_BOOT_ERASE_PROGRESSIVELY=y

My overlay:

&uart0 {
  status = "okay";
  compatible = "nordic,nrf-uarte";
  current-speed = <1000000>;
  pinctrl-0 = <&uart0_default>;
  pinctrl-1 = <&uart0_sleep>;
  pinctrl-names = "default", "sleep";
  hw-flow-control;
};

/delete-node/ &boot_partition;
/delete-node/ &slot0_partition;
/delete-node/ &slot1_partition;
// /delete-node/ &scratch_partition;

&flash0 {
  partitions {
    boot_partition: partition@0 {
      label = "mcuboot";
      reg = <0x00000000 0x10000>;
    };
    slot0_partition: partition@10000 {
      label = "image-0";
      reg = <0x000010000 0x0000e8000>;
    };
  };
};

&w25q32jv {
  partitions {
    compatible = "fixed-partitions";
    #address-cells = <1>;
    #size-cells = <1>;

    slot1_partition: partition@0 {
      label = "image-1";
      reg = <0x00000000 0x0000d8000>;
    };
  };
};

/ {
  chosen {
    nordic,pm-ext-flash = &w25q32jv;
    zephyr,console = &uart0;
    zephyr,shell-uart = &uart0;
    zephyr,uart-mcumgr = &uart0;
  };
};

My `partitions.yml`:

EMPTY_0:
  address: 0xfa000
  end_address: 0x100000
  placement:
    after:
    - settings_storage
  region: flash_primary
  size: 0x6000
app:
  address: 0x28000
  end_address: 0xf8000
  region: flash_primary
  size: 0xd0000
external_flash:
  address: 0xde000
  end_address: 0x400000
  region: external_flash
  size: 0x322000
mcuboot:
  address: 0x0
  end_address: 0x20000
  placement:
    before:
    - mcuboot_primary
  region: flash_primary
  size: 0x20000
mcuboot_pad:
  address: 0x20000
  end_address: 0x20200
  placement:
    align:
      start: 0x8000
    before:
    - mcuboot_primary_app
  region: flash_primary
  size: 0x200
mcuboot_primary:
  address: 0x20000
  end_address: 0xf8000
  orig_span: &id001
  - mcuboot_pad
  - app
  - tfm
  region: flash_primary
  size: 0xd8000
  span: *id001
mcuboot_primary_app:
  address: 0x20200
  end_address: 0xf8000
  orig_span: &id002
  - app
  - tfm
  region: flash_primary
  size: 0xd7e00
  span: *id002
mcuboot_secondary:
  address: 0x0
  device: DT_CHOSEN(nordic_pm_ext_flash)
  end_address: 0xd8000
  placement:
    align:
      start: 0x4
  region: external_flash
  share_size:
  - mcuboot_primary
  size: 0xd8000
mcuboot_sram:
  address: 0x20000000
  end_address: 0x20008000
  orig_span: &id003
  - tfm_sram
  region: sram_primary
  size: 0x8000
  span: *id003
nonsecure_storage:
  address: 0xf8000
  end_address: 0xfa000
  orig_span: &id004
  - settings_storage
  region: flash_primary
  size: 0x2000
  span: *id004
nrf_modem_lib_ctrl:
  address: 0x20008000
  end_address: 0x200084e8
  inside:
  - sram_nonsecure
  placement:
    after:
    - tfm_sram
    - start
  region: sram_primary
  size: 0x4e8
nrf_modem_lib_rx:
  address: 0x2000a568
  end_address: 0x2000c568
  inside:
  - sram_nonsecure
  placement:
    after:
    - nrf_modem_lib_tx
  region: sram_primary
  size: 0x2000
nrf_modem_lib_sram:
  address: 0x20008000
  end_address: 0x2000c568
  orig_span: &id005
  - nrf_modem_lib_ctrl
  - nrf_modem_lib_tx
  - nrf_modem_lib_rx
  region: sram_primary
  size: 0x4568
  span: *id005
nrf_modem_lib_tx:
  address: 0x200084e8
  end_address: 0x2000a568
  inside:
  - sram_nonsecure
  placement:
    after:
    - nrf_modem_lib_ctrl
  region: sram_primary
  size: 0x2080
nvs_storage:
  address: 0xd8000
  device: DT_CHOSEN(nordic_pm_ext_flash)
  end_address: 0xde000
  placement:
    before:
    - tfm_storage
    - end
  region: external_flash
  size: 0x6000
otp:
  address: 0xff8108
  end_address: 0xff83fc
  region: otp
  size: 0x2f4
settings_storage:
  address: 0xf8000
  end_address: 0xfa000
  inside:
  - nonsecure_storage
  placement:
    align:
      start: 0x8000
    before:
    - end
  region: flash_primary
  size: 0x2000
sram_nonsecure:
  address: 0x20008000
  end_address: 0x20040000
  orig_span: &id006
  - sram_primary
  - nrf_modem_lib_ctrl
  - nrf_modem_lib_tx
  - nrf_modem_lib_rx
  region: sram_primary
  size: 0x38000
  span: *id006
sram_primary:
  address: 0x2000c568
  end_address: 0x20040000
  region: sram_primary
  size: 0x33a98
sram_secure:
  address: 0x20000000
  end_address: 0x20008000
  orig_span: &id007
  - tfm_sram
  region: sram_primary
  size: 0x8000
  span: *id007
tfm:
  address: 0x20200
  end_address: 0x28000
  inside:
  - mcuboot_primary_app
  placement:
    before:
    - app
  region: flash_primary
  size: 0x7e00
tfm_nonsecure:
  address: 0x28000
  end_address: 0xf8000
  orig_span: &id008
  - app
  region: flash_primary
  size: 0xd0000
  span: *id008
tfm_secure:
  address: 0x20000
  end_address: 0x28000
  orig_span: &id009
  - mcuboot_pad
  - tfm
  region: flash_primary
  size: 0x8000
  span: *id009
tfm_sram:
  address: 0x20000000
  end_address: 0x20008000
  inside:
  - sram_secure
  placement:
    after:
    - start
  region: sram_primary
  size: 0x8000

The code:

#include "fota.h"

#include <zephyr/device.h>
#include <zephyr/dfu/flash_img.h>
#include <zephyr/dfu/mcuboot.h>
#include <zephyr/kernel.h>
#include <zephyr/logging/log.h>
#include <zephyr/stats/stats.h>
#include <zephyr/storage/flash_map.h>

#include "custom_http_client.h"
#include "pm_config.h"

LOG_MODULE_REGISTER(fota, LOG_LEVEL_DBG);

#define STRINGIZE(arg) #arg
#define STRINGIZE_VALUE(arg) STRINGIZE(arg)
#define PM_MCUBOOT_PRIMARY_STRING STRINGIZE_VALUE(PM_MCUBOOT_PRIMARY_NAME)
#define PM_MCUBOOT_SECONDARY_STRING STRINGIZE_VALUE(PM_MCUBOOT_SECONDARY_NAME)

BUILD_ASSERT(
    FIXED_PARTITION_EXISTS(PM_MCUBOOT_SECONDARY_NAME),
    "Missing " PM_MCUBOOT_SECONDARY_STRING
    " fixed partition. Secondary slot partition is required!"
);

struct flash_img_context ctx;

/*
 * Copyright (c) 2023 Nordic Semiconductor ASA
 *
 * SPDX-License-Identifier: LicenseRef-Nordic-5-Clause
 */

void image_validation(uint8_t area_id) {
  int rc;
  char buf[BOOT_IMG_VER_STRLEN_MAX];
  struct mcuboot_img_header header;

  boot_read_bank_header(area_id, &header, sizeof(header));
  snprintk(
      buf, sizeof(buf), "%d.%d.%d-%d", header.h.v1.sem_ver.major,
      header.h.v1.sem_ver.minor, header.h.v1.sem_ver.revision,
      header.h.v1.sem_ver.build_num
  );
  LOG_INF("Booting image: build time: " __DATE__ " " __TIME__);
  LOG_INF("Image Version: %s", buf);
  LOG_INF("Image size: %d", header.h.v1.image_size);
  rc = boot_is_img_confirmed();
  LOG_INF("Image is%s confirmed", rc ? "" : " not");
  if (!rc) {
    if (boot_write_img_confirmed()) {
      LOG_ERR("Failed to confirm image");
    } else {
      LOG_INF("Marked image as OK");
    }
  }
}

void image_info(uint8_t area_id) {
  int rc;
  char buf[BOOT_IMG_VER_STRLEN_MAX];
  struct mcuboot_img_header header;

  boot_read_bank_header(area_id, &header, sizeof(header));
  snprintk(
      buf, sizeof(buf), "%d.%d.%d-%d", header.h.v1.sem_ver.major,
      header.h.v1.sem_ver.minor, header.h.v1.sem_ver.revision,
      header.h.v1.sem_ver.build_num
  );
  LOG_INF("MCUboot swap type: %d", mcuboot_swap_type());
  LOG_INF("Image Version %s", buf);
  rc = boot_is_img_confirmed();
  LOG_INF("Image is%s confirmed OK", rc ? "" : " not");
}

int write_buffer_to_flash(char *data, size_t len, _Bool flush) {
  int rc;
  if (flush) {
    rc = flash_img_buffered_write(&ctx, data, len, true);
  } else {
    rc = flash_img_buffered_write(&ctx, data, len, false);
  }

  LOG_DBG("Flash img bytes written: %d", flash_img_bytes_written(&ctx));

  return rc;
}

void download_update(void) {
  int rc;

  char headers_buf[1024];
  char write_buf[CONFIG_IMG_BLOCK_BUF_SIZE];

  //   struct flash_img_check fic {
  // 	const uint8_t *match;		/** Match vector data */
  // 	size_t clen;			/** Content to be compared */
  // };

  rc = flash_img_init_id(&ctx, PM_MCUBOOT_SECONDARY_ID);
  if (rc < 0) {
    LOG_ERR("Failed to init stream flash");
  }

  (void)http_get_firmware(
      write_buf, sizeof(write_buf), headers_buf, sizeof(headers_buf)
  );

  LOG_DBG("mcuboot_swap_type: %d", mcuboot_swap_type());

  rc = boot_request_upgrade(BOOT_UPGRADE_TEST);
  if (rc < 0) {
    LOG_ERR("Failed to REQUEST FIRMWARE UPGRADE");
  }

  LOG_DBG("\nImage info: " PM_MCUBOOT_PRIMARY_STRING);
  (void)image_info(PM_MCUBOOT_PRIMARY_ID);

  LOG_DBG("\nImage info: " PM_MCUBOOT_SECONDARY_STRING);
  (void)image_info(PM_MCUBOOT_SECONDARY_ID);
}

Parents
  • Hi!

    I would have expected MCUboot to swap here.

    My `mcuboot.conf`:

    Could you try to enable logging for MCUboot ? The MCUboot log should hopefully be able to tell us more about what is happening.

    # Enable logging
    CONFIG_LOG=y
    CONFIG_LOG_DEFAULT_LEVEL=4

  • It took me a bit to get MCUboot logging working, but I finally saw a useful message: mcuboot: Image in the secondary slot is not valid!

    It isn't obvious to me why the image isn't valid.

    Here's (part of) the stack trace:

    [00:00:10.471,740] ␛[0m<dbg> spi_nrfx_spim: spi_context_buffers_setup: tx_bufs 0x20005130 - rx_bufs 0x20005138 - 1␛[0m
    [00:00:10.473,358] ␛[0m<dbg> spi_nrfx_spim: spi_context_buffers_setup: current_tx 0x20005140 (2), current_rx 0x20005140 (2), tx buf/len 0x20005128/1, rx buf/len 0x20005128/1␛[0m
    [00:00:10.475,769] ␛[0m<dbg> spi_nrfx_spim: spi_context_update_tx: tx buf/len 0x20005177/1␛[0m
    [00:00:10.476,989] ␛[0m<dbg> spi_nrfx_spim: spi_context_update_rx: rx buf/len 0x20005177/1␛[0m
    [00:00:10.478,179] ␛[0m<dbg> spi_nrfx_spim: spi_context_update_tx: tx buf/len (nil)/0␛[0m
    [00:00:10.479,339] ␛[0m<dbg> spi_nrfx_spim: spi_context_update_rx: rx buf/len (nil)/0␛[0m
    [00:00:10.480,468] ␛[0m<dbg> spi_nrfx_spim: finish_transaction: Transaction finished with status 0␛[0m
    [00:00:10.481,781] ␛[0m<dbg> spi_nrfx_spim: spi_context_buffers_setup: tx_bufs 0x20005130 - rx_bufs 0x20005138 - 1␛[0m
    [00:00:10.483,428] ␛[0m<dbg> spi_nrfx_spim: spi_context_buffers_setup: current_tx 0x20005140 (2), current_rx 0x20005140 (2), tx buf/len 0x20005128/1, rx buf/len 0x20005128/1␛[0m
    [00:00:10.485,839] ␛[0m<dbg> spi_nrfx_spim: spi_context_update_tx: tx buf/len 0x20005177/1␛[0m
    [00:00:10.487,030] ␛[0m<dbg> spi_nrfx_spim: spi_context_update_rx: rx buf/len 0x20005177/1␛[0m
    [00:00:10.488,250] ␛[0m<dbg> spi_nrfx_spim: spi_context_update_tx: tx buf/len (nil)/0␛[0m
    [00:00:10.489,379] ␛[0m<dbg> spi_nrfx_spim: spi_context_update_rx: rx buf/len (nil)/0␛[0m
    [00:00:10.490,539] ␛[0m<dbg> spi_nrfx_spim: finish_transaction: Transaction finished with status 0␛[0m
    [00:00:10.491,851] ␛[0m<dbg> spi_nrfx_spim: spi_context_buffers_setup: tx_bufs 0x20005130 - rx_bufs 0x20005138 - 1␛[0m
    [00:00:10.493,499] ␛[0m<dbg> spi_nrfx_spim: spi_context_buffers_setup: current_tx 0x20005140 (2), current_rx 0x20005140 (2), tx buf/len 0x20005128/1, rx buf/len 0x20005128/1␛[0m
    [00:00:10.495,910] ␛[0m<dbg> spi_nrfx_spim: spi_context_update_tx: tx buf/len 0x20005177/1␛[0m
    [00:00:10.497,100] ␛[0m<dbg> spi_nrfx_spim: spi_context_update_rx: rx buf/len 0x20005177/1␛[0m
    [00:00:10.498,321] ␛[0m<dbg> spi_nrfx_spim: spi_context_update_tx: tx buf/len (nil)/0␛[0m
    [00:00:10.499,450] ␛[0m<dbg> spi_nrfx_spim: spi_context_update_rx: rx buf/len (nil)/0␛[0m
    [00:00:10.500,610] ␛[0m<dbg> spi_nrfx_spim: finish_transaction: Transaction finished with status 0␛[0m
    [00:00:10.501,922] ␛[0m<dbg> spi_nrfx_spim: spi_context_buffers_setup: tx_bufs 0x20005130 - rx_bufs 0x20005138 - 1␛[0m
    [00:00:10.503,570] ␛[0m<dbg> spi_nrfx_spim: spi_context_buffers_setup: current_tx 0x20005140 (2), current_rx 0x20005140 (2), tx buf/len 0x20005128/1, rx buf/len 0x20005128/1␛[0m
    [00:00:10.505,950] ␛[0m<dbg> spi_nrfx_spim: spi_context_update_tx: tx buf/len 0x20005177/1␛[0m
    [00:00:10.507,171] ␛[0m<dbg> spi_nrfx_spim: spi_context_update_rx: rx buf/len 0x20005177/1␛[0m
    [00:00:10.508,392] ␛[0m<dbg> spi_nrfx_spim: spi_context_update_tx: tx buf/len (nil)/0␛[0m
    [00:00:10.509,521] ␛[0m<dbg> spi_nrfx_spim: spi_context_update_rx: rx buf/len (nil)/0␛[0m
    [00:00:10.510,681] ␛[0m<dbg> spi_nrfx_spim: finish_transaction: Transaction finished with status 0␛[0m
    [00:00:10.511,993] ␛[0m<dbg> spi_nrfx_spim: spi_context_buffers_setup: tx_bufs 0x20005130 - rx_bufs 0x20005138 - 1␛[0m
    [00:00:10.513,610] ␛[0m<dbg> spi_nrfx_spim: spi_context_buffers_setup: current_tx 0x20005140 (2), current_rx 0x20005140 (2), tx buf/len 0x20005128/1, rx buf/len 0x20005128/1␛[0m
    [00:00:10.516,021] ␛[0m<dbg> spi_nrfx_spim: spi_context_update_tx: tx buf/len 0x20005177/1␛[0m
    [00:00:10.517,211] ␛[0m<dbg> spi_nrfx_spim: spi_context_update_rx: rx buf/len 0x20005177/1␛[0m
    [00:00:10.518,432] ␛[0m<dbg> spi_nrfx_spim: spi_context_update_tx: tx buf/len (nil)/0␛[0m
    [00:00:10.519,592] ␛[0m<dbg> spi_nrfx_spim: spi_context_update_rx: rx buf/len (nil)/0␛[0m
    [00:00:10.520,721] ␛[0m<dbg> spi_nrfx_spim: finish_transaction: Transaction finished with status 0␛[0m
    [00:00:10.522,033] ␛[0m<dbg> spi_nrfx_spim: spi_context_buffers_setup: tx_bufs 0x20005140 - rx_bufs (nil) - 1␛[0m
    [00:00:10.523,620] ␛[0m<dbg> spi_nrfx_spim: spi_context_buffers_setup: current_tx 0x20005150 (1), current_rx (nil) (0), tx buf/len 0x20005138/1, rx buf/len (nil)/0␛[0m
    [00:00:10.525,878] ␛[0m<dbg> spi_nrfx_spim: spi_context_update_tx: tx buf/len (nil)/0␛[0m
    [00:00:10.527,038] ␛[0m<dbg> spi_nrfx_spim: finish_transaction: Transaction finished with status 0␛[0m
    [00:00:10.528,320] ␛[1;31m<err> mcuboot: Image in the secondary slot is not valid!␛[0m
    [00:00:10.583,068] ␛[0m<inf> mcuboot: Bootloader chainload address offset: 0x20000␛[0m
    [00:00:10.584,259] ␛[0m<inf> mcuboot: Jumping to the first image slot␛[0m

  • Here's a less verbose log:

    <inf> mcuboot: Starting bootloader
    <inf> mcuboot: Primary image: magic=unset, swap_type=0x1, copy_done=0x3, image_ok=0x3
    <inf> mcuboot: Secondary image: magic=good, swap_type=0x3, copy_done=0x3, image_ok=0x1
    <inf> mcuboot: Boot source: none
    <inf> mcuboot: Image index: 0, Swap type: perm
    <err> mcuboot: Image in the secondary slot is not valid!
    <inf> mcuboot: Bootloader chainload address offset: 0x20000
    <inf> mcuboot: Jumping to the first image slot

  • It turns out the image actually isn't valid. Something must be different about the CI build env.

Reply Children
  • I have confirmed the issue was due to an improperly signed image generated by the CI.

    The image wasn't signed correctly because I forgot to ensure the correct NRF python dependencies were installed.

    I'm using the zephyrproject-rtos/ci-base which has the Zephyr python dependencies preinstalled but not the dependencies required for Nordic's version of MCUboot.

    Adding this to the image solved my issue:

    - name: Update Python dependencies
        run: |
          pip install -r zephyr/scripts/requirements.txt
          pip install -r nrf/scripts/requirements.txt
          pip install -r bootloader/mcuboot/scripts/requirements.txt

Related