Azure FOTA issue: MCUboot does not load new image from secondary slot

[Tonja Joseph]

Hi,

I am trying to implement Azure FOTA using your libraries. My source code is a combination of the Azure iot sample and the Azure fota sample + some necessary alterations due to my application. 

To provoke the firmware ugrade over the air (FOTA) I am adding the following JSON block under the "desired"-section in the device twin code og my Axure IoT Hub device

        "desired": {
            "firmware": {
                "fwVersion": "1.0.1",
                "jobId": "job32",
                "fwLocation": {
                    "host": "<hostname>.blob.core.windows.net",
                    "path": "fota/app_update.bin"
                },
                "fwFragmentSize": 1800
            },

  

I am iterating the job ID for each attempt.  When I am saving this change to the Device twin, my device detects the request and starts downloading the new firmware. The entire download process seems to finish successfully without errors. The MCUboot bootloader also reports that an upgrade is scheduled and will be made by the next reboot. I wait 5 second before rebooting after reaching  AZURE_IOT_HUB_EVT_FOTA_DONE. 

However, my problem is that the same image is uploaded during reboot. It seems to me like the new firmware, that I guess is successfully stored in the secondary memory slot, newer gets swapped with the active image in the primary slot. What may be the reason for this?

Here is my prj.conf file:

 

# General config
CONFIG_LOG=y
CONFIG_LOG_DEFAULT_LEVEL=3
CONFIG_REBOOT=y

# MCUBOOT
CONFIG_BOOTLOADER_MCUBOOT=y
# CONFIG_MCUBOOT_SIGNATURE_KEY_FILE="C:\ncs\bootloader\mcuboot\enc-ec256-priv.pem"
CONFIG_IMG_MANAGER=y
CONFIG_IMG_ERASE_PROGRESSIVELY=y

# Flash
CONFIG_FLASH=y

# Settings for console printout
CONFIG_CONSOLE=y
CONFIG_CONSOLE_SUBSYS=y
CONFIG_CONSOLE_GETLINE=n
CONFIG_STDOUT_CONSOLE=y
CONFIG_UART_CONSOLE=y
CONFIG_NATIVE_UART_0_ON_STDINOUT=y
CONFIG_SERIAL=y
CONFIG_UART_INTERRUPT_DRIVEN=y

# WATCHDOG
CONFIG_RESET_ON_FATAL_ERROR=n
CONFIG_WATCHDOG=y
CONFIG_FEATHER_WATCHDOG_TIMEOUT_MSEC=3000
CONFIG_WATCHDOG_LOG_LEVEL=3

# NEWLIB C
CONFIG_NEWLIB_LIBC=y

# Network
CONFIG_NETWORKING=y
CONFIG_NET_NATIVE=n

# LTE link control
CONFIG_LTE_LINK_CONTROL=y
CONFIG_LTE_NETWORK_MODE_LTE_M=y
CONFIG_LTE_AUTO_INIT_AND_CONNECT=n

# Modem library
CONFIG_NRF_MODEM_LIB=y

# AT Host
CONFIG_AT_HOST_LIBRARY=n
CONFIG_AT_CMD_THREAD_STACK_SIZE=2048

# Azure IoT Hub library
CONFIG_AZURE_IOT_HUB=y
CONFIG_AZURE_IOT_HUB_DEVICE_ID="<my-devide-id>"
# CONFIG_AZURE_IOT_HUB_DEVICE_ID_APP=y
# Host name must be configured if DPS is not used
CONFIG_AZURE_IOT_HUB_HOSTNAME="<my-hostname>"
# Change the security tag to the tag where Azure IoT Hub certificates
# are provisioned
CONFIG_AZURE_IOT_HUB_SEC_TAG=10

# Uncomment and configure the options below to use DPS for device provisioning
# CONFIG_AZURE_IOT_HUB_DPS=y
# CONFIG_AZURE_IOT_HUB_DPS_ID_SCOPE=""

# Uncomment to get more verbose logging when debugging
CONFIG_AZURE_IOT_HUB_LOG_LEVEL_DBG=y

# MQTT - Maximum MQTT keepalive timeout specified by Azure IoT Hub
CONFIG_MQTT_KEEPALIVE=900

# LED control
CONFIG_DK_LIBRARY=y
CONFIG_DK_LIBRARY_INVERT_LEDS=n

# Heap and stacks
CONFIG_HEAP_MEM_POOL_SIZE=4096


# cJSON
CONFIG_CJSON_LIB=y

# Settings, needed for Azure Device Provisioning Service
CONFIG_FLASH_MAP=y
CONFIG_FCB=y
CONFIG_SETTINGS=y
CONFIG_SETTINGS_FCB=y
CONFIG_MPU_ALLOW_FLASH_WRITE=y

CONFIG_CLOUD_API_LOG_LEVEL=4

# I2C
CONFIG_I2C=y

CONFIG_NET_LOG=n
CONFIG_MQTT_LOG_LEVEL_DBG=n
CONFIG_AZURE_IOT_HUB_LOG_LEVEL_DBG=n

# Azure FOTA config
CONFIG_AZURE_FOTA=y
CONFIG_AZURE_FOTA_APP_VERSION="1.0.0"
CONFIG_AZURE_FOTA_TLS=y
CONFIG_AZURE_FOTA_SEC_TAG=10
# Uncomment the below line to get more debug logging
CONFIG_AZURE_FOTA_LOG_LEVEL_DBG=y

# FOTA Download
CONFIG_FOTA_DOWNLOAD=y
CONFIG_FOTA_DOWNLOAD_PROGRESS_EVT=y

# Download Client
CONFIG_DOWNLOAD_CLIENT=y
CONFIG_DOWNLOAD_CLIENT_HTTP_FRAG_SIZE_1024=y
CONFIG_DOWNLOAD_CLIENT_STACK_SIZE=4096
CONFIG_DOWNLOAD_CLIENT_LOG_LEVEL_INF=y
CONFIG_DOWNLOAD_CLIENT_BUF_SIZE=2300

CONFIG_DFU_TARGET=y
# CONFIG_DFU_TARGET_MCUBOOT=y

# Settings, needed for Azure Device Provisioning Service
CONFIG_FLASH=y
CONFIG_FCB=y
CONFIG_SETTINGS=y
CONFIG_SETTINGS_FCB=y
CONFIG_MPU_ALLOW_FLASH_WRITE=y


CONFIG_LOG_MODE_IMMEDIATE=y

Here is my output log

[00:00:05.599,395] <inf> cloud: AZURE_IOT_HUB_EVT_CONNECTED

[00:00:05.728,790] <dbg> azure_iot_hub.mqtt_evt_handler: MQTT_EVT_SUBACK: id = 5587 result = 0
[00:00:05.730,865] <dbg> azure_iot_hub.azure_iot_hub_send: Publishing to topic: $iothub/twin/GET/?$rid=5730
[00:00:05.733,886] <dbg> azure_iot_hub.device_twin_request: Device twin requested
[00:00:05.735,626] <inf> cloud: AZURE_IOT_HUB_EVT_READY

[00:00:05.736,938] <inf> cloud: Connected to cloud!

[00:00:05.738,220] <inf> cloud: boot_write_img_confirmed() successful
[00:00:05.914,459] <dbg> azure_iot_hub.on_publish: MQTT_EVT_PUBLISH: id = 0, len = 334
[00:00:05.916,503] <dbg> azure_iot_hub_topic.azure_iot_hub_topic_parse: Dynamic value: 200
[00:00:05.918,457] <dbg> azure_iot_hub_topic.get_next_prop_bag: Key: $rid
[00:00:05.920,074] <dbg> azure_iot_hub_topic.get_next_prop_bag: Value: 5730
[00:00:05.921,722] <dbg> azure_iot_hub.on_publish: Device twin data received
[00:00:05.924,468] <dbg> azure_fota.parse_reported_status: Currently reported 'fwUpdateStatus' in device twin: error
[00:00:05.926,849] <dbg> azure_fota.parse_reported_status: Currently reported 'currentFwVersion' in device twin: 1.0.0
[00:00:05.929,290] <dbg> azure_fota.parse_reported_status: Currently reported 'pendingFwVersion' in device twin: 1.0.1
[00:00:05.931,732] <dbg> azure_fota.reported_status_process: Status "error" was reported, no update will be sent
[00:00:05.935,485] <dbg> azure_fota.extract_fw_details: Incoming firmware version: 1.0.1
[00:00:05.937,377] <dbg> azure_fota.extract_fw_details: Job ID: job34
[00:00:05.939,331] <wrn> azure_fota: Update job (ID: job34) was already attempted, aborting
AZURE_IOT_HUB_EVT_TWIN_RECEIVED
[00:00:06.739,807] <inf> resani_main: Connected
[00:00:14.825,225] <inf> cloud: RRC mode: Idle

[00:00:25.145,751] <inf> cloud: RRC mode: Connected

[00:00:25.311,065] <dbg> azure_iot_hub.on_publish: MQTT_EVT_PUBLISH: id = 0, len = 186
[00:00:25.313,110] <dbg> azure_iot_hub_topic.get_next_prop_bag: Key: $version
[00:00:25.314,788] <dbg> azure_iot_hub_topic.get_next_prop_bag: Value: 76
[00:00:25.316,986] <dbg> azure_fota.parse_reported_status: No 'reported' object found
[00:00:25.319,580] <dbg> azure_fota.extract_fw_details: No 'desired' object found, assuming it's root object
[00:00:25.321,868] <dbg> azure_fota.extract_fw_details: Incoming firmware version: 1.0.1
[00:00:25.323,760] <dbg> azure_fota.extract_fw_details: Job ID: job35
[00:00:25.325,531] <dbg> azure_fota.state_set: State transition: STATE_INIT --> STATE_DOWNLOADING
[00:00:25.327,606] <inf> azure_fota: Attempting to download firmware (version '1.0.1') from stmessconfshareddevnorwa.blob.core.windows.net/fota/app_update.bin
[00:00:25.570,465] <inf> download_client: Setting up TLS credentials, tag 10
[00:00:25.572,265] <inf> download_client: Configuring socket timeout (30 s)
[00:00:25.573,944] <inf> download_client: Connecting to stmessconfshareddevnorwa.blob.core.windows.net
[00:00:27.372,406] <inf> download_client: Downloading: fota/app_update.bin [0]
[00:00:27.374,298] <dbg> azure_fota.create_report: Created FOTA report: {"firmware":{"fwUpdateStatus":"downloading","currentFwVersion":"1.0.0","pendingFwVersion":"1.0.1","jobId":"job35"}}
[00:00:27.378,021] <dbg> azure_iot_hub.fota_evt_handler: AZURE_FOTA_EVT_START
[00:00:27.379,791] <dbg> azure_iot_hub.azure_iot_hub_send: Publishing to topic: $iothub/twin/PATCH/properties/reported/?$rid=27379
[00:00:27.384,094] <dbg> azure_iot_hub.fota_report_send: FOTA report sent
AZURE_IOT_HUB_EVT_FOTA_START
[00:00:27.386,260] <dbg> azure_iot_hub.on_publish: Device twin update handled (FOTA)
AZURE_IOT_HUB_EVT_TWIN_DESIRED_RECEIVED
Desired device property: {"firmware":{"fwVersion":"1.0.1","jobId":"job35","fwLocation":{"host":"stmessconfshareddevnorwa.blob.core.windows.net","path":"fota/app_update.bin"},"fwFragmentSize":1800},"$version":76}
[00:00:27.615,997] <inf> download_client: Downloaded 1800/209835 bytes (0%)
[00:00:27.837,432] <dbg> azure_iot_hub.on_publish: MQTT_EVT_PUBLISH: id = 0, len = 0
[00:00:27.839,324] <dbg> azure_iot_hub_topic.azure_iot_hub_topic_parse: Dynamic value: 204
[00:00:27.841,278] <dbg> azure_iot_hub_topic.get_next_prop_bag: Key: $rid
[00:00:27.842,864] <dbg> azure_iot_hub_topic.get_next_prop_bag: Value: 27379
[00:00:27.844,573] <dbg> azure_iot_hub_topic.get_next_prop_bag: Key: $version
[00:00:27.846,252] <dbg> azure_iot_hub_topic.get_next_prop_bag: Value: 348
[00:00:27.847,900] <dbg> azure_iot_hub.on_publish: Device twin data received
AZURE_IOT_HUB_EVT_TWIN_RESULT_SUCCESS, ID: 27379
[00:00:27.980,895] <inf> download_client: Downloaded 3600/209835 bytes (1%)
[00:00:28.187,438] <inf> download_client: Downloaded 5400/209835 bytes (2%)
[00:00:28.507,080] <inf> download_client: Downloaded 7200/209835 bytes (3%)
[00:00:28.736,968] <inf> download_client: Downloaded 9000/209835 bytes (4%)
[00:00:29.041,137] <inf> download_client: Downloaded 10800/209835 bytes (5%)
[00:00:29.192,901] <inf> download_client: Downloaded 12600/209835 bytes (6%)
[00:00:29.352,905] <inf> download_client: Downloaded 14400/209835 bytes (6%)
[00:00:29.592,834] <inf> download_client: Downloaded 16200/209835 bytes (7%)
[00:00:29.752,899] <inf> download_client: Downloaded 18000/209835 bytes (8%)
[00:00:30.002,960] <inf> download_client: Downloaded 19800/209835 bytes (9%)
[00:00:30.152,923] <inf> download_client: Downloaded 21600/209835 bytes (10%)
[00:00:30.392,913] <inf> download_client: Downloaded 23400/209835 bytes (11%)
[00:00:30.552,917] <inf> download_client: Downloaded 25200/209835 bytes (12%)
[00:00:30.792,938] <inf> download_client: Downloaded 27000/209835 bytes (12%)
[00:00:30.952,941] <inf> download_client: Downloaded 28800/209835 bytes (13%)
[00:00:31.112,945] <inf> download_client: Downloaded 30600/209835 bytes (14%)
[00:00:31.352,874] <inf> download_client: Downloaded 32400/209835 bytes (15%)
[00:00:31.512,939] <inf> download_client: Downloaded 34200/209835 bytes (16%)
[00:00:31.752,960] <inf> download_client: Downloaded 36000/209835 bytes (17%)
[00:00:31.912,963] <inf> download_client: Downloaded 37800/209835 bytes (18%)
[00:00:32.152,954] <inf> download_client: Downloaded 39600/209835 bytes (18%)
[00:00:32.312,957] <inf> download_client: Downloaded 41400/209835 bytes (19%)
[00:00:32.472,961] <inf> download_client: Downloaded 43200/209835 bytes (20%)
[00:00:32.712,982] <inf> download_client: Downloaded 45000/209835 bytes (21%)
[00:00:32.872,985] <inf> download_client: Downloaded 46800/209835 bytes (22%)
[00:00:33.112,976] <inf> download_client: Downloaded 48600/209835 bytes (23%)
[00:00:33.272,979] <inf> download_client: Downloaded 50400/209835 bytes (24%)
[00:00:33.513,000] <inf> download_client: Downloaded 52200/209835 bytes (24%)
[00:00:33.673,004] <inf> download_client: Downloaded 54000/209835 bytes (25%)
[00:00:33.912,994] <inf> download_client: Downloaded 55800/209835 bytes (26%)
[00:00:34.072,998] <inf> download_client: Downloaded 57600/209835 bytes (27%)
[00:00:34.233,001] <inf> download_client: Downloaded 59400/209835 bytes (28%)
[00:00:34.472,991] <inf> download_client: Downloaded 61200/209835 bytes (29%)
[00:00:34.633,026] <inf> download_client: Downloaded 63000/209835 bytes (30%)
[00:00:34.873,016] <inf> download_client: Downloaded 64800/209835 bytes (30%)
[00:00:35.033,020] <inf> download_client: Downloaded 66600/209835 bytes (31%)
[00:00:35.273,040] <inf> download_client: Downloaded 68400/209835 bytes (32%)
[00:00:35.433,044] <inf> download_client: Downloaded 70200/209835 bytes (33%)
[00:00:35.673,034] <inf> download_client: Downloaded 72000/209835 bytes (34%)
[00:00:35.833,038] <inf> download_client: Downloaded 73800/209835 bytes (35%)
[00:00:35.993,041] <inf> download_client: Downloaded 75600/209835 bytes (36%)
[00:00:36.233,062] <inf> download_client: Downloaded 77400/209835 bytes (36%)
[00:00:36.393,066] <inf> download_client: Downloaded 79200/209835 bytes (37%)
[00:00:36.633,056] <inf> download_client: Downloaded 81000/209835 bytes (38%)
[00:00:36.793,090] <inf> download_client: Downloaded 82800/209835 bytes (39%)
[00:00:37.033,081] <inf> download_client: Downloaded 84600/209835 bytes (40%)
[00:00:37.193,084] <inf> download_client: Downloaded 86400/209835 bytes (41%)
[00:00:37.353,088] <inf> download_client: Downloaded 88200/209835 bytes (42%)
[00:00:37.593,017] <inf> download_client: Downloaded 90000/209835 bytes (42%)
[00:00:37.753,082] <inf> download_client: Downloaded 91800/209835 bytes (43%)
[00:00:37.993,103] <inf> download_client: Downloaded 93600/209835 bytes (44%)
[00:00:38.153,106] <inf> download_client: Downloaded 95400/209835 bytes (45%)
[00:00:38.393,096] <inf> download_client: Downloaded 97200/209835 bytes (46%)
[00:00:38.563,140] <inf> download_client: Downloaded 99000/209835 bytes (47%)
[00:00:38.873,107] <inf> download_client: Downloaded 100800/209835 bytes (48%)
[00:00:39.033,111] <inf> download_client: Downloaded 102600/209835 bytes (48%)
[00:00:39.193,115] <inf> download_client: Downloaded 104400/209835 bytes (49%)
[00:00:39.433,135] <inf> download_client: Downloaded 106200/209835 bytes (50%)
[00:00:39.593,078] <inf> download_client: Downloaded 108000/209835 bytes (51%)
[00:00:39.833,129] <inf> download_client: Downloaded 109800/209835 bytes (52%)
[00:00:40.003,143] <inf> download_client: Downloaded 111600/209835 bytes (53%)
[00:00:40.233,154] <inf> download_client: Downloaded 113400/209835 bytes (54%)
[00:00:40.393,127] <inf> download_client: Downloaded 115200/209835 bytes (54%)
[00:00:40.633,148] <inf> download_client: Downloaded 117000/209835 bytes (55%)
[00:00:40.793,151] <inf> download_client: Downloaded 118800/209835 bytes (56%)
[00:00:40.953,155] <inf> download_client: Downloaded 120600/209835 bytes (57%)
[00:00:41.193,145] <inf> download_client: Downloaded 122400/209835 bytes (58%)
[00:00:41.353,118] <inf> download_client: Downloaded 124200/209835 bytes (59%)
[00:00:41.593,170] <inf> download_client: Downloaded 126000/209835 bytes (60%)
[00:00:41.753,173] <inf> download_client: Downloaded 127800/209835 bytes (60%)
[00:00:41.993,194] <inf> download_client: Downloaded 129600/209835 bytes (61%)
[00:00:42.153,198] <inf> download_client: Downloaded 131400/209835 bytes (62%)
[00:00:42.313,171] <inf> download_client: Downloaded 133200/209835 bytes (63%)
[00:00:42.553,192] <inf> download_client: Downloaded 135000/209835 bytes (64%)
[00:00:42.713,195] <inf> download_client: Downloaded 136800/209835 bytes (65%)
[00:00:42.953,216] <inf> download_client: Downloaded 138600/209835 bytes (66%)
[00:00:43.113,220] <inf> download_client: Downloaded 140400/209835 bytes (66%)
[00:00:43.353,179] <inf> download_client: Downloaded 142200/209835 bytes (67%)
[00:00:43.513,244] <inf> download_client: Downloaded 144000/209835 bytes (68%)
[00:00:43.753,204] <inf> download_client: Downloaded 145800/209835 bytes (69%)
[00:00:43.913,238] <inf> download_client: Downloaded 147600/209835 bytes (70%)
[00:00:44.073,242] <inf> download_client: Downloaded 149400/209835 bytes (71%)
[00:00:44.313,232] <inf> download_client: Downloaded 151200/209835 bytes (72%)
[00:00:44.473,236] <inf> download_client: Downloaded 153000/209835 bytes (72%)
[00:00:44.713,256] <inf> download_client: Downloaded 154800/209835 bytes (73%)
[00:00:44.873,229] <inf> download_client: Downloaded 156600/209835 bytes (74%)
[00:00:45.113,220] <inf> download_client: Downloaded 158400/209835 bytes (75%)
[00:00:45.273,254] <inf> download_client: Downloaded 160200/209835 bytes (76%)
[00:00:45.433,227] <inf> download_client: Downloaded 162000/209835 bytes (77%)
[00:00:45.673,248] <inf> download_client: Downloaded 163800/209835 bytes (78%)
[00:00:45.833,251] <inf> download_client: Downloaded 165600/209835 bytes (78%)
[00:00:46.073,242] <inf> download_client: Downloaded 167400/209835 bytes (79%)
[00:00:46.233,276] <inf> download_client: Downloaded 169200/209835 bytes (80%)
[00:00:46.473,297] <inf> download_client: Downloaded 171000/209835 bytes (81%)
[00:00:46.633,300] <inf> download_client: Downloaded 172800/209835 bytes (82%)
[00:00:46.873,291] <inf> download_client: Downloaded 174600/209835 bytes (83%)
[00:00:47.033,294] <inf> download_client: Downloaded 176400/209835 bytes (84%)
[00:00:47.193,298] <inf> download_client: Downloaded 178200/209835 bytes (84%)
[00:00:47.433,288] <inf> download_client: Downloaded 180000/209835 bytes (85%)
[00:00:47.593,231] <inf> download_client: Downloaded 181800/209835 bytes (86%)
[00:00:47.833,282] <inf> download_client: Downloaded 183600/209835 bytes (87%)
[00:00:47.993,316] <inf> download_client: Downloaded 185400/209835 bytes (88%)
[00:00:48.233,306] <inf> download_client: Downloaded 187200/209835 bytes (89%)
[00:00:48.393,310] <inf> download_client: Downloaded 189000/209835 bytes (90%)
[00:00:48.633,361] <inf> download_client: Downloaded 190800/209835 bytes (90%)
[00:00:48.793,334] <inf> download_client: Downloaded 192600/209835 bytes (91%)
[00:00:48.953,338] <inf> download_client: Downloaded 194400/209835 bytes (92%)
[00:00:49.193,328] <inf> download_client: Downloaded 196200/209835 bytes (93%)
[00:00:49.353,332] <inf> download_client: Downloaded 198000/209835 bytes (94%)
[00:00:49.593,292] <inf> download_client: Downloaded 199800/209835 bytes (95%)
[00:00:49.753,356] <inf> download_client: Downloaded 201600/209835 bytes (96%)
[00:00:49.993,347] <inf> download_client: Downloaded 203400/209835 bytes (96%)
[00:00:50.153,381] <inf> download_client: Downloaded 205200/209835 bytes (97%)
[00:00:50.313,354] <inf> download_client: Downloaded 207000/209835 bytes (98%)
[00:00:50.553,375] <inf> download_client: Downloaded 208800/209835 bytes (99%)
[00:00:50.695,678] <inf> download_client: Downloaded 209835/209835 bytes (100%)
[00:00:50.796,783] <inf> download_client: Download complete
[00:00:50.890,991] <inf> dfu_target_mcuboot: MCUBoot image upgrade scheduled. Reset device to apply
[00:00:50.894,775] <dbg> azure_fota.fota_dl_handler: FOTA download completed evt received
[00:00:50.896,697] <dbg> azure_fota.state_set: State transition: STATE_DOWNLOADING --> STATE_INIT
[00:00:50.898,895] <dbg> azure_fota.create_report: Created FOTA report: {"firmware":{"fwUpdateStatus":"applying","currentFwVersion":"1.0.0","pendingFwVersion":"1.0.1","jobId":"job35"}}
[00:00:50.902,557] <dbg> azure_iot_hub.fota_evt_handler: AZURE_FOTA_EVT_DONE
[00:00:50.904,296] <dbg> azure_iot_hub.azure_iot_hub_send: Publishing to topic: $iothub/twin/PATCH/properties/reported/?$rid=50904
[00:00:50.908,599] <dbg> azure_iot_hub.fota_report_send: FOTA report sent
AZURE_IOT_HUB_EVT_FOTA_DONE
The device will reboot in 5 seconds to apply update
[00:00:51.274,963] <dbg> azure_iot_hub.on_publish: MQTT_EVT_PUBLISH: id = 0, len = 0
[00:00:51.276,855] <dbg> azure_iot_hub_topic.azure_iot_hub_topic_parse: Dynamic value: 204
[00:00:51.278,808] <dbg> azure_iot_hub_topic.get_next_prop_bag: Key: $rid
[00:00:51.280,426] <dbg> azure_iot_hub_topic.get_next_prop_bag: Value: 50904
[00:00:51.282,104] <dbg> azure_iot_hub_topic.get_next_prop_bag: Key: $version
[00:00:51.283,782] <dbg> azure_iot_hub_topic.get_next_prop_bag: Value: 349
[00:00:51.285,430] <dbg> azure_iot_hub.on_publish: Device twin data received
AZURE_IOT_HUB_EVT_TWIN_RESULT_SUCCESS, ID: 50904
*** Booting Zephyr OS build v2.6.0-rc1-ncs1  ***
Flash regions           Domain          Permissions
00 03 0x00000 0x20000   Secure          rwxl
04 31 0x20000 0x100000  Non-Secure      rwxl

Non-secure callable region 0 placed in flash region 3 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 0x20200
SPM: NS MSP at 0x2001f2f8
SPM: NS reset vector at 0x25eb9
SPM: prepare to jump to Non-Secure image.
*** Booting Zephyr OS build v2.6.0-rc1-ncs1  ***
[00:00:00.202,514] <inf> resani_main: test
[00:00:00.203,613] <inf> watchdog: Watchdog timeout installed. Timeout: 3000
[00:00:00.205,291] <inf> watchdog: Watchdog started
[00:00:00.206,512] <inf> watchdog: Watchdog feed enabled. Timeout: 1500
[00:00:00.208,129] <inf> cloud: Cloud init started
[00:00:00.209,289] <inf> cloud: This may take a while if a modem firmware update is pending
[00:00:00.211,212] <inf> cloud: Modem dfu no error: 0
[00:00:00.212,493] <dbg> azure_fota.state_set: State transition: STATE_UNINIT --> STATE_INIT
[00:00:00.214,447] <inf> azure_fota: Current firmware version: 1.0.0
[00:00:00.215,942] <dbg> azure_iot_hub.azure_iot_hub_init: Azure FOTA initialized
[00:00:00.217,712] <dbg> azure_iot_hub.connection_state_set: New connection state: STATE_INIT
[00:00:00.219,696] <wrn> at_notif: Already initialized. Nothing to do
[00:00:00.221,282] <inf> cloud: Successfully initialized and configured AT
[00:00:00.236,999] <inf> cloud: Successfully initialized and configured modem
[00:00:00.338,745] <inf> resani_main: Cloud connect pin high

[00:00:00.340,148] <inf> resani_main: Establishing connection
[00:00:00.384,002] <inf> cloud: Connecting to LTE network...
[00:00:01.335,174] <inf> cloud: LTE cell changed: Cell ID: 52050178, Tracking area: 31201

[00:00:01.383,026] <inf> cloud: RRC mode: Connected

[00:00:02.388,397] <inf> cloud: Network registration status: Connected - home network

[00:00:02.390,258] <inf> cloud: Connected to LTE network

[00:00:02.391,571] <dbg> azure_iot_hub.connection_state_set: New connection state: STATE_CONNECTING
[00:00:02.393,768] <inf> cloud: LTE cell changed: Cell ID: 52050178, Tracking area: 31201

[00:00:02.395,812] <inf> cloud: PSM parameter update: TAU: 9000, Active time: -1

[00:00:02.600,280] <dbg> azure_iot_hub.broker_init: IPv4 Address found 20.50.65.134
[00:00:02.602,081] <inf> cloud: AZURE_IOT_HUB_EVT_CONNECTING

[00:00:05.576,721] <dbg> azure_iot_hub.connect_client: Using send socket timeout of 60 seconds
[00:00:05.741,607] <dbg> azure_iot_hub.connection_state_set: New connection state: STATE_CONNECTED
[00:00:05.743,682] <dbg> azure_iot_hub.mqtt_evt_handler: MQTT client connected
[00:00:05.745,422] <dbg> azure_iot_hub.topic_subscribe: Subscribing to: devices/vidar-embedded/messages/devicebound/#
[00:00:05.747,863] <dbg> azure_iot_hub.topic_subscribe: Subscribing to: $iothub/twin/PATCH/properties/desired/#
[00:00:05.750,152] <dbg> azure_iot_hub.topic_subscribe: Subscribing to: $iothub/twin/res/#
[00:00:05.752,075] <dbg> azure_iot_hub.topic_subscribe: Subscribing to: $iothub/methods/POST/#
[00:00:05.755,126] <dbg> azure_iot_hub.topic_subscribe: Successfully subscribed to default topics
[00:00:05.757,171] <inf> cloud: AZURE_IOT_HUB_EVT_CONNECTED

[00:00:05.889,617] <dbg> azure_iot_hub.mqtt_evt_handler: MQTT_EVT_SUBACK: id = 5745 result = 0
[00:00:05.891,693] <dbg> azure_iot_hub.azure_iot_hub_send: Publishing to topic: $iothub/twin/GET/?$rid=5891
[00:00:05.894,683] <dbg> azure_iot_hub.device_twin_request: Device twin requested
[00:00:05.896,453] <inf> cloud: AZURE_IOT_HUB_EVT_READY

[00:00:05.897,735] <inf> cloud: Connected to cloud!

[00:00:05.899,017] <inf> cloud: boot_write_img_confirmed() successful
[00:00:06.075,286] <dbg> azure_iot_hub.on_publish: MQTT_EVT_PUBLISH: id = 0, len = 337
[00:00:06.077,331] <dbg> azure_iot_hub_topic.azure_iot_hub_topic_parse: Dynamic value: 200
[00:00:06.079,254] <dbg> azure_iot_hub_topic.get_next_prop_bag: Key: $rid
[00:00:06.080,871] <dbg> azure_iot_hub_topic.get_next_prop_bag: Value: 5891
[00:00:06.082,519] <dbg> azure_iot_hub.on_publish: Device twin data received
[00:00:06.085,266] <dbg> azure_fota.parse_reported_status: Currently reported 'fwUpdateStatus' in device twin: applying
[00:00:06.087,707] <dbg> azure_fota.parse_reported_status: Currently reported 'currentFwVersion' in device twin: 1.0.0
[00:00:06.090,148] <dbg> azure_fota.parse_reported_status: Currently reported 'pendingFwVersion' in device twin: 1.0.1
[00:00:06.092,590] <wrn> azure_fota: FOTA image was not applied, rolled back
[00:00:06.094,268] <inf> azure_fota: get_current_version() = 1.0.0
[00:00:06.095,764] <inf> azure_fota: current_fw = 1.0.0
[00:00:06.097,015] <dbg> azure_fota.parse_reported_status: Reported status was "applying", reporting back "rolledback"
[00:00:06.099,914] <dbg> azure_fota.create_report: Created FOTA report: {"firmware":{"fwUpdateStatus":"rolledback","currentFwVersion":"1.0.0"}}
[00:00:06.102,813] <dbg> azure_iot_hub.fota_evt_handler: AZURE_FOTA_EVT_REPORT
[00:00:06.104,614] <dbg> azure_iot_hub.azure_iot_hub_send: Publishing to topic: $iothub/twin/PATCH/properties/reported/?$rid=6104
[00:00:06.108,337] <dbg> azure_iot_hub.fota_report_send: FOTA report sent
[00:00:06.111,022] <dbg> azure_fota.extract_fw_details: Incoming firmware version: 1.0.1
[00:00:06.112,915] <dbg> azure_fota.extract_fw_details: Job ID: job35
[00:00:06.114,868] <wrn> azure_fota: Update job (ID: job35) was already attempted, aborting
AZURE_IOT_HUB_EVT_TWIN_RECEIVED
[00:00:06.344,757] <dbg> azure_iot_hub.on_publish: MQTT_EVT_PUBLISH: id = 0, len = 0
[00:00:06.346,649] <dbg> azure_iot_hub_topic.azure_iot_hub_topic_parse: Dynamic value: 204
[00:00:06.348,571] <dbg> azure_iot_hub_topic.get_next_prop_bag: Key: $rid
[00:00:06.350,189] <dbg> azure_iot_hub_topic.get_next_prop_bag: Value: 6104
[00:00:06.351,837] <dbg> azure_iot_hub_topic.get_next_prop_bag: Key: $version
[00:00:06.353,515] <dbg> azure_iot_hub_topic.get_next_prop_bag: Value: 350
[00:00:06.355,163] <dbg> azure_iot_hub.on_publish: Device twin data received
AZURE_IOT_HUB_EVT_TWIN_RESULT_SUCCESS, ID: 6104
[00:00:06.900,604] <inf> resani_main: Connected

Do you have any idea about what the problem might be? I am confirming my image using boot_write_img_confirmed().
I would really appreciate any suggestions for what to try :) I also tried to copy the memory partiotions into pm_static.yaml in the project root directory to make them static, but it did not have any effect.  

[Tonja Joseph]

Hi,

I added the following two lines to C:\ncs\bootloader\mcuboot\boot\zephyr\prj.conf

CONFIG_MCUBOOT_LOG_LEVEL_DBG=y
CONFIG_MCUBOOT_UTIL_LOG_LEVEL_DBG=y

But no additional logging appears. Do I need to do something more?

[Sigurd Hellesvik]

Hi,

When you run the azure_fota sample, can you see the following at the start of your log?

*** Booting Zephyr OS build v2.7.0-ncs1  ***
I: Starting bootloader
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: 0x10000
*** Booting Zephyr OS build v2.7.0-ncs1  ***

If you can, this means that the bootloader log is working.

Regards,
Sigurd Hellesvik

[Tonja Joseph]

Hi

Thanks for the reply! :) 
I am using sdk version 1.7. Strange... I was not able to run the samples with the  nrf9160dk_nrf9160ns boardfile on the Sparkfun thing plus board. The boradfile I am using for my own program is circuitdojo_feather_nrf9160ns. Could this be the issue? Something with the UART configuration?

Best regards
Tonja

[Tonja Joseph]

I tried to enable CONFIG_BOOTLOADER_MCUBOOT in the prj.conf file of the Hello World sample. Building the sample with circuitdojo_feather_nrf9160ns and flashing onto the sparkfun thing plus still did not give me any logging from MCUboot. I tried both with and without the changes in bootloader/mcuboot/boot/zephyr/prj.conf. 

[Sigurd Hellesvik]

Hi

After you build, you can check the mcuboot uart configuration in build/mcuboot/zephyr/zephyr.dts.
Does this use the same pins as the application, build/zephyr/zephyr.dts?

Regards,
Sigurd Hellesvik

[Tonja Joseph]

Hi,

Good idea! However, it seems like the same pins are used...

build/mcuboot/zephyr/zephyr.dts:



build/zephyr/zephyr.dts:


However I am using the following overlay file with another speed. May this introduce any issues?



Thank you so much for your help

Best regards
Tonja

[Tonja Joseph]

Just to be sure :) 

This is my log during reboot. SPM seems to log properly, but I am nit sure if the other logging is from mcuboot? I guess not?

*** Booting Zephyr OS build v2.6.0-rc1-ncs1  ***
Flash regions           Domain          Permissions
00 03 0x00000 0x20000   Secure          rwxl
04 31 0x20000 0x100000  Non-Secure      rwxl

Non-secure callable region 0 placed in flash region 3 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 0x20200
SPM: NS MSP at 0x2001f718
SPM: NS reset vector at 0x26405
SPM: prepare to jump to Non-Secure image.
*** Booting Zephyr OS build v2.6.0-rc1-ncs1  ***
[00:00:00.202,514] <inf> resani_main: test
[00:00:00.202,575] <inf> watchdog: Watchdog timeout installed. Timeout: 3000
[00:00:00.202,606] <inf> watchdog: Watchdog started
[00:00:00.202,606] <inf> watchdog: Watchdog feed enabled. Timeout: 1500
[00:00:00.202,667] <inf> cloud: Cloud init started
[00:00:00.202,667] <inf> cloud: This may take a while if a modem firmware update                                             is pending
[00:00:00.202,667] <inf> cloud: Modem dfu no error: 0
[00:00:00.202,697] <inf> azure_fota: Current firmware version: 1.0.0
[00:00:00.202,697] <dbg> azure_iot_hub.azure_iot_hub_init: Azure FOTA initialize                                            d
[00:00:00.202,728] <dbg> azure_iot_hub.connection_state_set: New connection stat                                            e: STATE_INIT
[00:00:00.202,728] <wrn> at_notif: Already initialized. Nothing to do
[00:00:00.202,758] <inf> cloud: Successfully initialized and configured AT
[00:00:00.204,376] <inf> cloud: Successfully initialized and configured modem
[00:00:00.304,473] <inf> resani_main: Cloud connect pin low

[Sigurd Hellesvik]

Hi

Tonja Joseph said:

This is my log during reboot. SPM seems to log properly, but I am nit sure if the other logging is from mcuboot? I guess not?

Yep, this is the same kind of log as I get when I build for the circuitdojo_feather_nrf9160ns on the nRF9160DK.
There is no MCUBoot log in the one you sent.

While I have not confirmed it, I suspect the logging issue is due to the bootloader using the serial interface for programming.
Since you want to program the board using the bootloader, it would be unwise to disable this.

How do you program your board?

Are you able to use the tools mcumgr or newtmgr?

Regards,
Sigurd Hellesvik

[Tonja Joseph]

Hi,

I am programming the board using newtmgr! 

Sigurd Hellesvik said:

While I have not confirmed it, I suspect the logging issue is due to the bootloader using the serial interface for programming.
Since you want to program the board using the bootloader, it would be unwise to disable this.

I am not sure if I understood what you mean by this. Could you explain me further? :) May the problem be that I am using newtmgr for programming?

Thank you so much for good answers and for looking into my problem

Best regards
Tonja

[Tonja Joseph]

If it is an issue, I can try to get hold of the right programming cable for my connector in order to program the board without using the USB line

[Sigurd Hellesvik]

Tonja Joseph said:

I am not sure if I understood what you mean by this. Could you explain me further?

When programming the board, newmgr communicate with mcumgr using the serial interface.
Therefore, the serial interface is reserved for newtmgr, and can not be used for logging.

If you had the cable, you could disable this, and log using the serial interface instead.
However, let us see if we can debug the issue another way first.

I am thinking maybe we can get some information from the newtmgr.
First, I suggest to see if you can get anything useful from:

newtmgr image list

[Tonja Joseph]

Ah, I understand! Thanks a lot. That makes sense. Hmm, would be great to figure other ways to debug the problem. 

newtmgr image listgave me this:


This seems a little strange to me...?

Best regards
Tonja