nrf52840 S140 Central DFU Bluetooth Zephyr 2.0.0 nrf52840 peripheral

[DavidKaplan]

We have nrf52840 S140 BLE Central device that currently connects to TI based sensors. I have implemented code that can upgrade those TI sensors' firmware using the TI BLE protocol.

Now we are developing our own BLE peripheral sensors also based on the nrf52840 but now using the newly supported Zephyr 2.0.0. RF connect stuff. I can update the sensors using the Nordic Android program (unauthenticated for now) and now need to implement upgrading BLE DFU using our central device which connects to a cellular gateway.

I do not want to reinvent the wheel, writing existing code, like I had to do with the TI sensors.

Could you point me to code that allows a Central device to update a peripheral device BLE DFU?

If not where can I look to reinvent another wheel?

Thanks David

[Sigurd Hellesvik]

Hi David,

I did not change Simons list function.

It worked as is. But I have not tried to upload a new image yet, meaning only 1 image lives on the device.
It only lists 1 slot in this case. I suspect it will list 2 slots if I upload an image to the secondary slot.

I will let you know when I have tested this.

Regards,
Sigurd Hellesvik

[Sigurd Hellesvik]

I am able to use Simons sample to upload images in v2.0.0.

However, it fails in v2.2.0, and I have not been able to figure out why yet.

Regards,
Sigurd Hellesvik

[Sigurd Hellesvik]

DavidKaplan said:

Almost always I got some messages dropped.

This is related to the Zephyr Logging module. If you lof too fast, some of the logs will get dropped. You can fix this by tweaking Logging configurations.

On to the DFU issue:

Since DFU works using mobile but not the SMP Client, I figure it must be the SMP Client with the error.
So I added some logging to the mcumgr receiving end to compare messages received from mobile vs SMP Client:

diff --git a/subsys/mgmt/mcumgr/lib/cmd/img_mgmt/src/img_mgmt.c b/subsys/mgmt/mcumgr/lib/cmd/img_mgmt/src/img_mgmt.c
index 8c7dc330db..c5b7818bb8 100644
--- a/subsys/mgmt/mcumgr/lib/cmd/img_mgmt/src/img_mgmt.c
+++ b/subsys/mgmt/mcumgr/lib/cmd/img_mgmt/src/img_mgmt.c
@@ -371,6 +371,20 @@ img_mgmt_upload(struct mgmt_ctxt *ctxt)
        ok = zcbor_map_decode_bulk(zsd, image_upload_decode,
                ARRAY_SIZE(image_upload_decode), &decoded) == 0;
 
+    static int once = 1;
+    if(once){
+        once = 0;
+        printk("ARRAY_SIZE(image_upload_decode): [%d]\n",ARRAY_SIZE(image_upload_decode));
+        printk("req.off [%d]\n", req.off);
+        printk("req.size [%ld]\n", req.size);
+        printk("req.upgrade [%d]\n", req.upgrade);
+        printk("req.image [%d]\n", req.image);
+        printk("req.img_data.len [%d]\n", req.img_data.len);
+        printk("req.img_data.value [%d]\n", req.img_data.value);
+        printk("req.data_sha.len [%d]\n", req.data_sha.len);
+        printk("req.data_sha.value [%d]\n", req.data_sha.value);
+    }
+
        IMG_MGMT_UPLOAD_ACTION_SET_RC_RSN(&action, NULL);
 
        if (!ok) {

I found that the upload size/len in the smp message is the most significant difference here.

So I changed this in the SMP Client to use the actual size and not Simon's static number.
Now DFU works from the SMP Client to your sample:

*** Booting Zephyr OS build v3.2.99-ncs1 ***
I: Starting bootloader
I: Primary image: magic=good, swap_type=0x2, copy_done=0x1, image_ok=0x1
I: Secondary image: magic=good, swap_type=0x2, copy_done=0x3, image_ok=0x3
I: Boot source: none
I: Swap type: test
I: Starting swap using move algorithm.
I: Bootloader chainload address offset: 0xc000
*** Booting Zephyr OS build v3.2.99-ncs1 ***
[00:00:00.000,610] <inf> mcumgr_zephyr_grp: zephyr_basic_mgmt_init: Registering Zephyr basic mgmt group
FFFFFFFFFFFFFFFFFFFFF
00/00/0000 00:00:00[ami_main.c: 635] Startup
00/00/0000 00:00:00[ami_cfg.c: 256] DeviceID:0
00/00/0000 00:00:00[ami_main.c: 448] MainInitErr:4096
[00:00:00.106,719] <inf> bt_hci_core: hci_vs_init: HW Platform: Nordic Semiconductor (0x0002)
--- 3 messages dropped ---
[00:00:00.106,750] <inf> bt_hci_core: hci_vs_init: HW Variant: nRF52x (0x0002)

I put the change that I made in git:

https://github.com/hellesvik-nordic/samples_for_nrf_connect_sdk/commit/f593bf073f609d76038f2b668783e5b0f485138e

Can you try this change and see if it also fixes the DFU for you?

Regards,
Sigurd Hellesvik

[DavidKaplan]

I tried to duplicate your changes in my central code, but it did not help for some reason.

So, I changed this in the SMP Client to use the actual size and not Simon's static number.

In your code you use the constant slot start & end addresses from the pm.

The flash_read() function will return, I think, when there is nothing more to read from the actual image.

The upload_chunk is not changed from  UPLOAD_CHUNK during the upload.

The length you write seems to be the size of the slot and not the image size.

I could be wrong here.

In any case doing something similar did not give an error but did not work.

I did not add anything in the sensor code to try to see what is happening in the log yet.

I changed only the central code.

I hope to continue on this tomorrow.

So I should use the slot size or the image size in the first packet?

In the last packet show which is not divisible by upload_chunk, should I pad it by 0xFFs or 0x00 or does it matter?

Thank you, David

if(off == 0){
  zcbor_tstr_put_lit(zse, "len");
  zcbor_uint64_put(zse, (uint64_t)last_addr-start_addr);

  // ?!? 

  //  PM_MCUBOOT_SECONDARY_END_ADDRESS- PM_MCUBOOT_SECONDARY_ADDRESS
}

int last_addr = PM_MCUBOOT_SECONDARY_END_ADDRESS;
int start_addr = PM_MCUBOOT_SECONDARY_ADDRESS;

[Sigurd Hellesvik]

DavidKaplan said:

So I should use the slot size or the image size in the first packet?

From SMP: Image upload:

"“len”: optional length of an image, it only appears in the first packet of request, where “off” is 0"

DavidKaplan said:

So, I changed this in the SMP Client to use the actual size and not Simon's static number.

Yes, I think that is how we want to do it in the end. For now, I just set len to the entire length of the Secondary Slot (PM_MCUBOOT_SECONDARY_END_ADDRESS - PM_MCUBOOT_SECONDARY_ADDRESS), in case there is some footer set at the end of the slot.
Then when we get the full upload to work, we can try decreasing the length.

DavidKaplan said:

In the last packet show which is not divisible by upload_chunk, should I pad it by 0xFFs or 0x00 or does it matter?

I think this is handled by the code already?

		if(curr_addr+UPLOAD_CHUNK > last_addr){
			upload_chunk = last_addr - curr_addr;
			update_complete = true;
		}

Regards,
Sigurd Hellesvik

[DavidKaplan]

OK, you are of course correct about the last block and upload_chuck being updated.

My Central code reports that the DFU goes well but the nRF9160-DK and my custom end units still do not upgrade.

 The image checksum compared to my harddrive is the same.

[ami_smp.c: 676] DFU:317200/319026
[ami_smp.c: 676] DFU:317600/319026
[ami_smp.c: 676] DFU:318000/319026
[ami_smp.c: 676] DFU:318400/319026
[ami_smp.c: 676] DFU:318800/319026
[ami_smp.c: 777] ImageChecksum AF3A0C7A
[ami_smp.c: 911] SMP UploadOK
[ami_smp.c:1192] ImageList

-----------PRIMARY IMAGE-----------
      slot: 0
      version: 0.0.0
      hash: 0x76d196d413b84fe1177ba6c33a79744f579a07298a6a282d97ffd7a73d82ee6
      bootable: true
      pending: false
      confirmed: true
      active: true
      permanent: false

-----------SECONDARY IMAGE-----------
      slot: 1
      version: 0.0.0
      hash: 0x4165b6dabeb5dfab85e276b4e927b2e32358d38f1ef8d698617c5f449a095
      bootable: true
      pending: false
      confirmed: false
      active: false
      permanent: false
[ami_smp.c:1195] ImageTest

-----------PRIMARY IMAGE-----------
      slot: 0
      version: 0.0.0
      hash: 0x76d196d413b84fe1177ba6c33a79744f579a07298a6a282d97ffd7a73d82ee6
      bootable: true
      pending: false
      confirmed: true
      active: true
      permanent: false

-----------SECONDARY IMAGE-----------
      slot: 1
      version: 0.0.0
      hash: 0x4165b6dabeb5dfab85e276b4e927b2e32358d38f1ef8d698617c5f449a095
      bootable: true
      pending: true
      confirmed: false
      active: false
      permanent: false
[ami_smp.c:1198] ImageReset
22/02/2023 20:49:50[ami_ble.c: 861] Disconnected: C0:F1:EE:C6:31:44 (random) (reason 8)
[ami_ble.c:2639] DFUConnectFinishedErr:0

#define UPLOAD_CHUNK		400 // (50 worked) This has to be at least 32 bytes, since first it has to send the whole header (which is 32 bytes)
void send_upload2(void)
{
        uint8_t       data[UPLOAD_CHUNK+1]; // One more byte, to store '/0'
	    zcbor_state_t zse[2];
  	    size_t        payload_len;
		int           start_addr   = 0; // AMI_VIBEBT_PM_MCUBOOT_SECONDARY_ADDRESS; 
		int           last_addr    = 0; // AMI_VIBEBT_PM_MCUBOOT_SECONDARY_ADDRESS+ami_state->dfu.ImageSize.ulong; 
		int           curr_addr    = 0; // AMI_VIBEBT_PM_MCUBOOT_SECONDARY_ADDRESS;
		int           upload_chunk = UPLOAD_CHUNK;
		int           err;
        uint64_t      off = 0;
	    bool          update_complete = false;
        uint8_t       encode_len;

		ami_state->DFUErr                 = AMI_SMP_DFU_ERR_OK;
        ami_state->dfu.uAddChecksum.word  = 0;
        ami_state->dfu.uXORChecksum       = 0;
		while (!update_complete){
			struct smp_buffer smp_cmd;
			zcbor_new_encode_state(zse, ARRAY_SIZE(zse), smp_cmd.payload,sizeof(smp_cmd.payload), 0);
			//-----------------------------------------------------------------
			// Wait until response is received until sending the next chunk
			//-----------------------------------------------------------------
			// ?!? err = k_sem_take(&upload_sem, K_MSEC(AMI_DFU_MAX_SEND_ACK_MS));		    
			k_sem_take(&upload_sem, K_FOREVER);
			last_addr    = ami_state->dfu.ImageSize.ulong;
            err = 0;
			if (ami_state->DFUErr){
			  d_printf(LINE_INFO,kDbg_Error|kDbg_Host,"SMPErr:%u",ami_state->DFUErr);
			  update_complete = true;
			  break;
			}
			//-------------------------------------------------------
			// Disconnected?
			//-------------------------------------------------------
			if (!atomic_get(&ble_connected)){
			  ami_state->DFUErr = AMI_DFU_ERR_DISCONNECTED;
			  update_complete = true;
			  break;
			}
			//-----------------------------------------------------------------
			// No Error but semiphore times out!
			//-----------------------------------------------------------------
			if (err){
			  ami_state->DFUErr = AMI_SMP_DFU_ERR_LOOP_TIMEOUT;
			  update_complete = true;
			  break;
			}
			//-----------------------------------------------------------------
			// Last block?
			//-----------------------------------------------------------------
			if ((curr_addr+UPLOAD_CHUNK) > last_addr){
				upload_chunk = last_addr - curr_addr;
				update_complete = true;
			}
			progress_print(curr_addr-start_addr,last_addr-start_addr);
			//-----------------------------------------------------------------
			// Get the data block from ringbuffer
			//-----------------------------------------------------------------
			ami_state->DFUErr = ami_smp_RetDataBlock(data,upload_chunk);
			if (ami_state->DFUErr){ 
			  update_complete = true;
			  break;
			}
			//-----------------------------------------------------------------
			// First block add image size
			//-----------------------------------------------------------------
			off = curr_addr - start_addr;
			if (off == 0){
				encode_len = 8;
			} else {
				encode_len = 6;
			}
			data[upload_chunk] = '\0';
			zse->constant_state->stop_on_error = true;
			zcbor_map_start_encode(zse, encode_len);
			zcbor_tstr_put_lit(zse, "image");
			zcbor_int64_put(zse, 0);
			zcbor_tstr_put_lit(zse, "data");
			zcbor_bstr_put_lit(zse, data);
			if(off == 0){
				zcbor_tstr_put_lit(zse, "len");
				zcbor_uint64_put(zse, (uint64_t)last_addr-start_addr);
			}
			zcbor_tstr_put_lit(zse, "off");
			zcbor_uint64_put(zse, off);
			if(off == 0){
				zcbor_tstr_put_lit(zse, "sha");
				zcbor_bstr_put_lit(zse, "12345");
			}
			zcbor_tstr_put_lit(zse, "upgrade");
			zcbor_bool_put(zse, false);
			zcbor_map_end_encode(zse, encode_len);

			if (!zcbor_check_error(zse)) {
				d_printf(LINE_INFO,kDbg_Error|kDbg_Host,"Failed to encode SMP test packet, err: %d", zcbor_pop_error(zse));
				ami_state->DFUErr = AMI_SMP_DFU_ERR_UPLOAD_ENCODE;
				break;
			}
			curr_addr+=upload_chunk;
			payload_len = (size_t)(zse->payload - smp_cmd.payload);
			smp_cmd.header.op = 2; /* write request */
			smp_cmd.header.flags = 0;
			smp_cmd.header.len_h8 = (uint8_t)((payload_len >> 8) & 0xFF);
			smp_cmd.header.len_l8 = (uint8_t)((payload_len >> 0) & 0xFF);
			smp_cmd.header.group_h8 = 0;
			smp_cmd.header.group_l8 = 1; /* IMAGE */
			smp_cmd.header.seq = 0;
			smp_cmd.header.id  = 1; /* UPLOAD */
			//-----------------------------------------------------------------
			// ZCBOR error?
			//-----------------------------------------------------------------
			err = bt_dfu_smp_command(&dfu_smp,smp_upload_rsp_proc,sizeof(smp_cmd.header)+payload_len,&smp_cmd); 
			if (err){
			  d_printf(LINE_INFO,kDbg_Error|kDbg_Host,"bt_dfu_smp_command failed with %d", err);
			  ami_state->DFUErr = AMI_SMP_DFU_ERR_SEND;
			  break;
			}
		} // while
		if (!ami_state->DFUErr){
		  ami_smp_PrintChecksums();
		  d_printf(LINE_INFO,kDbg_General|kDbg_Host,"SMP UploadOK");
		}
  	    atomic_set(&smp_finished,true);
} // send_upload2

Could you please send me your nRF9160-Dk or other board's child mcuboot.conf file and the prg.conf file that you tested?

Is the child mcuboot.conf file just additions to the default mcuboot prog.conf file?

 I still can't get the bootloader to output anything in the sensor's RTT log, but I see the additional printks

00> ARRAY_SIZE(image_upload_decode): [6]
00> req.off [0]
00> req.size [319026]
00> req.upgrade [0]
00> req.image [0]
00> req.img_data.len [400]
00> req.img_data.value [536969252]
00> req.data_sha.len [5]
00> req.data_sha.value [536969671]

(Connection lost)
00> SEGGER J-Link V7.66a - Real time terminal output
00> J-Link OB-K22-NordicSemi compiled Nov  7 2022 16:21:34 V1.0, SN=960005601
00> Process: JLinkGDBServerCL.exe
00> [00:00:00.035,827] <err> LSM6DSL: lsm6dsl_init: Failed to initialize chip
00> *** Booting Zephyr OS build v3.2.99-ncs1 ***
00> [00:00:00.036,529] <inf> mcumgr_zephyr_grp: zephyr_basic_mgmt_init: Registering Zephyr basic mgmt group
00> 00/00/0000 00:00:00[ami_main.c: 631] Startup
00> 00/00/0000 00:00:00[ami_cfg.c: 256] DeviceID:0
00> 00/00/0000 00:00:00[ami_main.c: 448] MainInitErr:4096
00> 00/00/0000 00:00:00[ami_main.c: 657] VaporBLE#0 23-Feb-2023 v1.0.0 1.0 2.23
00> build time: Feb 23 2023 08:27:22
00> [00:00:00.141,448] <inf> sdc_hci_driver: hci_driver_open: SoftDevice Controller build revision:
00>                                          6d 90 41 2a 38 e8 ad 17  29 a5 03 38 39 27 d7 85 |m.A*8... )..89'..
00>                                          1f 85 d8 e1                                      |....
00> [00:00:00.145,721] <inf> bt_hci_core: hci_vs_init: HW Platform: Nordic Semiconductor (0x0002)
00> [00:00:00.146,240] <inf> bt_hci_core: hci_vs_init: HW Variant: nRF52x (0x0002)
00> [00:00:00.146,728] <inf> bt_hci_core: hci_vs_init: Firmware: Standard Bluetooth controller (0x00) Version 109.16784 Build 2917677098
00> [00:00:00.147,827] <inf> bt_hci_core: bt_init: No ID address. App must call settings_load()
00> 00/00/0000 00:00:00[ami_ble.c: 506] ActualTxPwr:8
00> 00/00/0000 00:00:00[ami_ble.c: 788] Bluetooth initialized
00> [00:00:00.149,383] <wrn> bt_hci_core: bt_set_name: Unable to store name
00> [00:00:00.150,299] <inf> bt_hci_core: bt_dev_show_info: Identity: C0:F1:EE:C6:31:44 (random)
00> [00:00:00.150,817] <inf> bt_hci_core: bt_dev_show_info: HCI: version 5.3 (0x0c) revision 0x11fa, manufacturer 0x0059
00> [00:00:00.151,458] <inf> bt_hci_core: bt_dev_show_info: LMP: version 5.3 (0x0c) subver 0x11fa
00> [00:00:00.152,191] <wrn> bt_hci_core: bt_set_name: Unable to store name
00> 00/00/0000 00:00:00[ami_ble.c: 555] UpdateAdv x:0 y:0 z:0 Tmp:0 F:0x20
00> 00/00/0000 00:00:00[ami_ble.c: 593] AdvertisingStarted
00> 00/00/0000 00:00:00[ami_main.c: 676] BootConfirmed
00> 00/00/0000 00:00:00[ami_main.c: 683] ResetCause:1
00> [00:00:00.169,036] <err> bt_gatt: db_hash_store: Failed to save Database Hash (err -2)
00> 01/01/2004 00:00:01[ami_adc.c: 470] RdLSM6DSLThread
00> 01/01/2004 00:00:26[ami_main.c: 143] Connected
00> 01/01/2004 00:00:26[ami_main.c: 198] LE PHY updated: TX PHY LE 2M, RX PHY LE 2M
00> 01/01/2004 00:00:31[ami_main.c: 175] Connection parameters updated.
00>  interval: 40, latency: 0, timeout: 42
00> 01/01/2004 00:00:34[ami_main_serv.c:  58] Received data, handle 0, conn 0x20002860
00> 22/02/2023 20:30:10[ami_main.c: 153] Disconnected reason:19
00> 22/02/2023 20:30:10[ami_ble.c: 555] UpdateAdv x:0 y:0 z:0 Tmp:0 F:0x0
00> 22/02/2023 20:30:10[ami_ble.c: 593] AdvertisingStarted
00> 22/02/2023 20:30:11[ami_ble.c: 555] UpdateAdv x:0 y:0 z:0 Tmp:0 F:0x0
00> 22/02/2023 20:30:35[ami_main.c: 601] NewMin
00> 22/02/2023 20:31:24[ami_main.c: 143] Connected
00> 22/02/2023 20:31:25[ami_main.c: 198] LE PHY updated: TX PHY LE 2M, RX PHY LE 2M
00> 22/02/2023 20:31:29[ami_main.c: 175] Connection parameters updated.
00>  interval: 40, latency: 0, timeout: 42
00> ARRAY_SIZE(image_upload_decode): [6]
00> req.off [0]
00> req.size [319026]
00> req.upgrade [0]
00> req.image [0]
00> req.img_data.len [400]
00> req.img_data.value [536969252]
00> req.data_sha.len [5]
00> req.data_sha.value [536969671]
00> 22/02/2023 20:31:34[ami_main.c: 175] Connection parameters updated.
00>  interval: 9, latency: 0, timeout: 42
00> 22/02/2023 20:31:35[ami_main.c: 601] NewMin
00> 22/02/2023 20:32:35[ami_main.c: 601] NewMin
00> [00:00:00.035,827] <err> LSM6DSL: lsm6dsl_init: Failed to initialize chip
00> *** Booting Zephyr OS build v3.2.99-ncs1 ***
00> [00:00:00.036,499] <inf> mcumgr_zephyr_grp: zephyr_basic_mgmt_init: Registering Zephyr basic mgmt group
00> 00/00/0000 00:00:00[ami_main.c: 631] Startup
00> 00/00/0000 00:00:00[ami_cfg.c: 256] DeviceID:0
00> 00/00/0000 00:00:00[ami_main.c: 448] MainInitErr:4096
00> 00/00/0000 00:00:00[ami_main.c: 657] VaporBLE#0 23-Feb-2023 v1.0.0 1.0 2.23
00> build time: Feb 23 2023 08:27:22
00> [00:00:00.141,448] <inf> sdc_hci_driver: hci_driver_open: SoftDevice Controller build revision:
00>                                          6d 90 41 2a 38 e8 ad 17  29 a5 03 38 39 27 d7 85 |m.A*8... )..89'..
00>                                          1f 85 d8 e1                                      |....
00> [00:00:00.145,721] <inf> bt_hci_core: hci_vs_init: HW Platform: Nordic Semiconductor (0x0002)
00> [00:00:00.146,240] <inf> bt_hci_core: hci_vs_init: HW Variant: nRF52x (0x0002)
00> [00:00:00.146,728] <inf> bt_hci_core: hci_vs_init: Firmware: Standard Bluetooth controller (0x00) Version 109.16784 Build 2917677098
00> [00:00:00.147,827] <inf> bt_hci_core: bt_init: No ID address. App must call settings_load()
00> 00/00/0000 00:00:00[ami_ble.c: 506] ActualTxPwr:8
00> 00/00/0000 00:00:00[ami_ble.c: 788] Bluetooth initialized
00> [00:00:00.149,383] <wrn> bt_hci_core: bt_set_name: Unable to store name
00> [00:00:00.150,299] <inf> bt_hci_core: bt_dev_show_info: Identity: C0:F1:EE:C6:31:44 (random)
00> [00:00:00.150,817] <inf> bt_hci_core: bt_dev_show_info: HCI: version 5.3 (0x0c) revision 0x11fa, manufacturer 0x0059
00> [00:00:00.151,458] <inf> bt_hci_core: bt_dev_show_info: LMP: version 5.3 (0x0c) subver 0x11fa
00> [00:00:00.152,191] <wrn> bt_hci_core: bt_set_name: Unable to store name
00> 00/00/0000 00:00:00[ami_ble.c: 555] UpdateAdv x:0 y:0 z:0 Tmp:0 F:0x20
00> 00/00/0000 00:00:00[ami_ble.c: 593] AdvertisingStarted
00> 00/00/0000 00:00:00[ami_main.c: 676] BootConfirmed
00> 00/00/0000 00:00:00[ami_main.c: 683] ResetCause:1
00> [00:00:00.169,036] <err> bt_gatt: db_hash_store: Failed to save Database Hash (err -2)
00> 01/01/2004 00:00:01[ami_adc.c: 470] RdLSM6DSLThread

 

Thanks David

[Sigurd Hellesvik]

DavidKaplan said:

Could you please send me your nRF9160-Dk or other board's child mcuboot.conf file and the prg.conf file that you tested?

For the SMP Server, I used code supplied by you,

I used my Bluetooth: Central SMP Client DFU sample for the SMP Client. The only change was the UUID to make it connect to your device.
This sample is an edited version of Simon's example.

DavidKaplan said:

Is the child mcuboot.conf file just additions to the default mcuboot prog.conf file?

Yes. child_image/mcuboot.conf is added as extra configurations to the MCUboot default prj.conf.
However, if you use child_image/mcuboot/prj.conf, it will overwrite the MCUboot configuration. I do not recommend using child_image/mcuboot/prj.conf.

Regards,
Sigurd Hellesvik

[DavidKaplan]

I understand the mcuboot configuration as you explained, mcuboot.conf are additions and prj.conf override.

Then you say that you used my project definitions and get mcuboot information on the peripheral without any changes in the RTT log?

I cannot see any bootloader mcuboot  information in the nRF9160 RTT log.

So How did you get it? 

What am I doing wrong?

Your log:

*** Booting Zephyr OS build v3.2.99-ncs1 ***
I: Starting bootloader
I: Primary image: magic=good, swap_type=0x2, copy_done=0x1, image_ok=0x1
I: Secondary image: magic=good, swap_type=0x2, copy_done=0x3, image_ok=0x3
I: Boot source: none
I: Swap type: test
I: Starting swap using move algorithm.
I: Bootloader chainload address offset: 0xc000
*** Booting Zephyr OS build v3.2.99-ncs1 ***
[00:00:00.000,610] <inf> mcumgr_zephyr_grp: zephyr_basic_mgmt_init: Registering Zephyr basic mgmt group
FFFFFFFFFFFFFFFFFFFFF

My log:

00> SEGGER J-Link V7.66a - Real time terminal output
00> J-Link OB-K22-NordicSemi compiled Nov  7 2022 16:21:34 V1.0, SN=960005601
00> Process: JLinkGDBServerCL.exe
00> [00:00:00.035,827] <err> LSM6DSL: lsm6dsl_init: Failed to initialize chip
00> *** Booting Zephyr OS build v3.2.99-ncs1 ***
00> [00:00:00.036,529] <inf> mcumgr_zephyr_grp: zephyr_basic_mgmt_init: Registering Zephyr basic mgmt group
00> 00/00/0000 00:00:00[ami_main.c: 631] Startup

When I upload does the peripheral information seem OK?

00> 22/02/2023 20:31:29[ami_main.c: 175] Connection parameters updated.
00>  interval: 40, latency: 0, timeout: 42
00> ARRAY_SIZE(image_upload_decode): [6]
00> req.off [0]
00> req.size [319026]
00> req.upgrade [0]
00> req.image [0]
00> req.img_data.len [400]
00> req.img_data.value [536969252]
00> req.data_sha.len [5]
00> req.data_sha.value [536969671]

Thanks, and have a good weekend, David

[Sigurd Hellesvik]

DavidKaplan said:

I cannot see any bootloader mcuboot  information in the nRF9160 RTT log.

So How did you get it? 

What am I doing wrong?

Aha, this was a misunderstanding.

Since working with the Development Kit, I used UART for logging.

I have used RTT for logging from the Bootloader before, but I remember it to be unstable.
Whether you want to continue trying to make Bootloader RTT work is up to you.

Have you been able to update the peripheral using the changes I made to the SMP Client?

Regards,
Sigurd Hellesvik

[DavidKaplan]

Sorry but for some reason I could not get the nRF9160-Dk 's nrf52840 to output anything on its uart.

According to the documentation, it should output on VCOM1 using uart TX P0.3 & RX P0.5.

# ----------------------------------------
# USE Uart Instead of RTT
# ----------------------------------------
CONFIG_UART_CONSOLE=y
CONFIG_LOG_BACKEND_UART=y
CONFIG_SERIAL=y
# ----------------------------------------
# Enable UART console, for printk()
# ----------------------------------------
CONFIG_CONSOLE_HANDLER=n
CONFIG_CONSOLE=y
CONFIG_PRINTK=y

# ----------------------------------------
# USE RTT  Instead of Uart
# ----------------------------------------
#CONFIG_CONSOLE=y
#CONFIG_RTT_CONSOLE=y
#CONFIG_USE_SEGGER_RTT=y
#CONFIG_LOG_BACKEND_RTT=y

What am I missing?

Could you just post your board files?

Also, on my central zephyr v2.2.0 complains about not using pin ctrl for the uart.

I added the ms88sf2-pinctrl.dtsi file which I included in ms88sf2.dts

&uart1 {
	status = "okay";
	current-speed = <115200>;
	pinctrl-0 = <&uart1_default>;
	pinctrl-1 = <&uart1_sleep>;
	pinctrl-names = "default", "sleep";
};

&pinctrl {
	uart1_default: uart1_default {
		group1 {
			psels = <NRF_PSEL(UART_TX, 0, 3)>,
				<NRF_PSEL(UART_RTS, 1, 8)>;
		};
		group2 {
			psels = <NRF_PSEL(UART_RX, 0, 5)>,
				<NRF_PSEL(UART_CTS, 0, 7)>;
			bias-pull-up;
		};
	};

	uart1_sleep: uart1_sleep {
		group1 {
			psels = <NRF_PSEL(UART_TX, 0, 3)>,
				<NRF_PSEL(UART_RX, 0, 5)>,
				<NRF_PSEL(UART_RTS, 1, 8)>,
				<NRF_PSEL(UART_CTS, 0, 7)>;
			low-power-enable;
		};
	};

};

                 from C:\ncs\v2.2.0\zephyr\drivers\serial\uart_nrfx_uarte.c:11:
C:\ncs\v2.2.0\zephyr\include\zephyr\toolchain\gcc.h:77:36: error: static assertion failed: "/soc/uart@40028000 defined without required pin configuration"
   77 | #define BUILD_ASSERT(EXPR, MSG...) _Static_assert(EXPR, "" MSG)
      |                                    ^~~~~~~~~~~~~~
c:\ncs\v2.2.0\zephyr\soc\arm\nordic_nrf\common\soc_nrf_common.h:218:9: note: in expansion of macro 'BUILD_ASSERT'
  218 |         BUILD_ASSERT((IS_ENABLED(CONFIG_PINCTRL) &&                     \
      |         ^~~~~~~~~~~~
C:\ncs\v2.2.0\zephyr\drivers\serial\uart_nrfx_uarte.c:2080:9: note: in expansion of macro 'NRF_DT_CHECK_PIN_ASSIGNMENTS'
 2080 |         NRF_DT_CHECK_PIN_ASSIGNMENTS(UARTE(idx), 1,                            \
      |         ^~~~~~~~~~~~~~~~~~~~~~~~~~~~
C:\ncs\v2.2.0\zephyr\drivers\serial\uart_nrfx_uarte.c:2189:1: note: in expansion of macro 'UART_NRF_UARTE_DEVICE'
 2189 | UART_NRF_UARTE_DEVICE(1);
      | ^~~~~~~~~~~~~~~~~~~~~
C:\ncs\v2.2.0\zephyr\include\zephyr\toolchain\gcc.h:77:36: error: static assertion failed: "/soc/uart@40028000 has pinctrl states defined although PINCTRL is not enabled"
   77 | #define BUILD_ASSERT(EXPR, MSG...) _Static_assert(EXPR, "" MSG)
      |                                    ^~~~~~~~~~~~~~
c:\ncs\v2.2.0\zephyr\soc\arm\nordic_nrf\common\soc_nrf_common.h:234:9: note: in expansion of macro 'BUILD_ASSERT'
  234 |         BUILD_ASSERT(IS_ENABLED(CONFIG_PINCTRL) ||                      \
      |         ^~~~~~~~~~~~
C:\ncs\v2.2.0\zephyr\drivers\serial\uart_nrfx_uarte.c:2080:9: note: in expansion of macro 'NRF_DT_CHECK_PIN_ASSIGNMENTS'
 2080 |         NRF_DT_CHECK_PIN_ASSIGNMENTS(UARTE(idx), 1,                            \
      |         ^~~~~~~~~~~~~~~~~~~~~~~~~~~~
C:\ncs\v2.2.0\zephyr\drivers\serial\uart_nrfx_uarte.c:2189:1: note: in expansion of macro 'UART_NRF_UARTE_DEVICE'
 2189 | UART_NRF_UARTE_DEVICE(1);
      | ^~~~~~~~~~~~~~~~~~~~~

[Sigurd Hellesvik]

DavidKaplan said:

What am I missing?

To test UART logging from the nRF52840 on the nRF9160, do the following:

1. Go to zephyr/samples/hello_world.
2. Build for "nrf9160dk_nrf52840".
3. Flip the switch on nRF9160DK to nRF52.
4. Program.
5. Connect a serial terminal to VCOM1 and see it log "Hello World ..."

I did this, and it printed for me.

DavidKaplan said:

Could you just post your board files?

I just used the default board files for the DKs; see Zephyr arm boards.
For the nRF52840DK, I used nrf52840dk_nrf52840.

Regards,
Sigurd Hellesvik

[DavidKaplan]

OK, I flashed my sensor code using the "nrf9160dk_nrf52840" build and then tried to DFU from my Central with the image streamed and the Central got OK from the nRF9160 dk sensor as I received before.

Central log:

02-28 11:23 28/02/2023 09:23:36 |  27/02/2023 23:23:14[.ami_vibe.c:1941] ...[ami_smp.c: 675] DFU:317200/319026 400
02-28 11:23 28/02/2023 09:23:36 |  27/02/2023 23:23:14[.ami_vibe.c:1941] ...[ami_smp.c: 675] DFU:317600/319026 400
02-28 11:23 28/02/2023 09:23:36 |  27/02/2023 23:23:14[.ami_vibe.c:1941] ...[ami_smp.c: 675] DFU:318000/319026 400
02-28 11:23 28/02/2023 09:23:36 |  27/02/2023 23:23:14[.ami_vibe.c:1941] ...[ami_smp.c: 675] DFU:318400/319026 400
02-28 11:23 28/02/2023 09:23:36 |  27/02/2023 23:23:14[.ami_vibe.c:1941] ...[ami_smp.c: 675] DFU:318800/319026 226
02-28 11:23 28/02/2023 09:23:37 |  27/02/2023 23:23:14[.ami_vibe.c:1941] ...[ami_smp.c: 789] ImageChecksum AF3A0C7A
02-28 11:23 28/02/2023 09:23:37 |  27/02/2023 23:23:14[.ami_vibe.c:1941] ...[ami_smp.c: 927] SMP UploadOK
02-28 11:23 28/02/2023 09:23:37 |  27/02/2023 23:23:14[.ami_vibe.c:1941] ...[ami_smp.c:1208] ImageList
02-28 11:23 28/02/2023 09:23:37 |  27/02/2023 23:23:14[.ami_vibe.c:1941] ...[ami_smp.c:1211] ImageTest
02-28 11:23 28/02/2023 09:23:38 |  27/02/2023 23:23:15[.ami_vibe.c:1941] ...[ami_smp.c:1214] ImageReset
02-28 11:23 28/02/2023 09:23:38 |  27/02/2023 23:23:16[.ami_vibe.c:1941] ...[ami_ble.c:2639] DFUConnectFinishedErr:0

nRF9160-DK log where I used the programmer at the start to perform a reset.

[00:01:38.147,705] <ESC><err> mpsl_init: m_assert_handler: MPSL ASSERT: 112, 2195<ESC><CR><LF>
[00:01:38.155,456] <ESC><err> os: hard_fault: ***** HARD FAULT *****<ESC><CR><LF>
[00:01:38.162,109] <ESC><err> os: hard_fault:   Fault escalation (see below)<ESC><CR><LF>
[00:01:38.169,433] <ESC><err> os: hard_fault: ARCH_EXCEPT with reason 3<LF>
<ESC><CR><LF>
[00:01:38.176,452] <ESC><err> os: esf_dump: r0/a1:  0x00000003  r1/a2:  0x00000000  r2/a3:  0x00000000<ESC><CR><LF>
[00:01:38.186,065] <ESC><err> os: esf_dump: r3/a4:  0x20003f54 r12/ip:  0x00000000 r14/lr:  0x0003a413<ESC><CR><LF>
[00:01:38.195,678] <ESC><err> os: esf_dump:  xpsr:  0x41000018<ESC><CR><LF>
[00:01:38.201,843] <ESC><err> os: esf_dump: s[ 0]:  0x00000000  s[ 1]:  0x00000000  s[ 2]:  0x00000000  s[ 3]:  0x00000000<ESC><CR><LF>
[00:01:38.213,226] <ESC><err> os: esf_dump: s[ 4]:  0x00000000  s[ 5]:  0x00000000  s[ 6]:  0x00000000  s[ 7]:  0x00000000<ESC><CR><LF>
[00:01:38.224,609] <ESC><err> os: esf_dump: s[ 8]:  0x00000000  s[ 9]:  0x00000000  s[10]:  0x00000000  s[11]:  0x00000000<ESC><CR><LF>
[00:01:38.235,992] <ESC><err> os: esf_dump: s[12]:  0x00000000  s[13]:  0x00000002  s[14]:  0x00000000  s[15]:  0x00000000<ESC><CR><LF>
[00:01:38.247,344] <ESC><err> os: esf_dump: fpscr:  0x00000100<ESC><CR><LF>
[00:01:38.253,479] <ESC><err> os: esf_dump: Faulting instruction address (r15/pc): 0x0002f618<ESC><CR><LF>
[00:01:38.262,298] <ESC><err> os: z_fatal_error: >>> ZEPHYR FATAL ERROR 3: Kernel oops on CPU 0<ESC><CR><LF>
[00:01:38.271,331] <ESC><err> os: z_fatal_error: Fault during interrupt handling<LF>
<ESC><CR><LF>
[00:01:38.279,113] <ESC><err> os: z_fatal_error: Current thread: 0x20002ca8 (unknown)<ESC><CR><LF>
[00:01:38.287,261] <ESC><err> fatal_error: k_sys_fatal_error_handler: Resetting system<ESC><CR>
[00:00:00.252,288] <ESC><inf> board_control: vcom0_pins_routing is ENABLED<ESC><CR><LF>
[00:00:00.259,155] <ESC><inf> board_control: vcom2_pins_routing is ENABLED<ESC><CR><LF>
[00:00:00.266,052] <ESC><inf> board_control: led1_pin_routing is ENABLED<ESC><CR><LF>
[00:00:00.272,796] <ESC><inf> board_control: led2_pin_routing is ENABLED<ESC><CR><LF>
[00:00:00.279,541] <ESC><inf> board_control: led3_pin_routing is ENABLED<ESC><CR><LF>
[00:00:00.286,254] <ESC><inf> board_control: led4_pin_routing is ENABLED<ESC><CR><LF>
[00:00:00.292,999] <ESC><inf> board_control: switch1_pin_routing is ENABLED<ESC><CR><LF>
[00:00:00.299,987] <ESC><inf> board_control: switch2_pin_routing is ENABLED<ESC><CR><LF>
[00:00:00.306,976] <ESC><inf> board_control: button1_pin_routing is ENABLED<ESC><CR><LF>
[00:00:00.313,995] <ESC><inf> board_control: button2_pin_routing is ENABLED<ESC><CR><LF>
[00:00:00.320,983] <ESC><inf> board_control: nrf_interface_pins_0_2_routing is disabled<ESC><CR><LF>
[00:00:00.329,040] <ESC><inf> board_control: nrf_interface_pins_3_5_routing is disabled<ESC><CR><LF>
[00:00:00.337,097] <ESC><inf> board_control: nrf_interface_pins_6_8_routing is disabled<ESC><CR><LF>
[00:00:00.345,123] <ESC><inf> board_control: Board configured.<ESC><CR><LF>
*** Booting Zephyr OS build v3.2.99-ncs1 ***<CR><LF>
[00:00:00.355,041] <ESC><inf> mcuboot: Starting bootloader<ESC><CR><LF>
[00:00:00.360,992] <ESC><inf> mcuboot: Primary image: magic=unset, swap_type=0x1, copy_done=0x3, image_ok=0x3<ESC><CR><LF>
[00:00:00.370,971] <ESC><inf> mcuboot: Secondary image: magic=unset, swap_type=0x1, copy_done=0x3, image_ok=0x3<ESC><CR><LF>
[00:00:00.381,072] <ESC><inf> mcuboot: Boot source: none<ESC><CR><LF>
[00:00:00.386,474] <ESC><inf> mcuboot: Swap type: none<ESC><CR><LF>
[00:00:00.460,571] <ESC><inf> mcuboot: Bootloader chainload address offset: 0xc000<ESC><CR><LF>
[00:00:00.468,139] <ESC><inf> mcuboot: Jumping to the first image slot<ESC><CR>
ÿ[00:00:00.000,152] <ESC><inf> board_control: init: vcom0_pins_routing is ENABLED<ESC><CR><LF>
[00:00:00.007,568] <ESC><inf> board_control: init: vcom2_pins_routing is ENABLED<ESC><CR><LF>
[00:00:00.015,014] <ESC><inf> board_control: init: led1_pin_routing is ENABLED<ESC><CR><LF>
[00:00:00.022,277] <ESC><inf> board_control: init: led2_pin_routing is ENABLED<ESC><CR><LF>
[00:00:00.029,541] <ESC><inf> board_control: init: led3_pin_routing is ENABLED<ESC><CR><LF>
[00:00:00.036,804] <ESC><inf> board_control: init: led4_pin_routing is ENABLED<ESC><CR><LF>
[00:00:00.044,067] <ESC><inf> board_control: init: switch1_pin_routing is ENABLED<ESC><CR><LF>
[00:00:00.051,605] <ESC><inf> board_control: init: switch2_pin_routing is ENABLED<ESC><CR><LF>
[00:00:00.059,143] <ESC><inf> board_control: init: button1_pin_routing is ENABLED<ESC><CR><LF>
[00:00:00.066,650] <ESC><inf> board_control: init: button2_pin_routing is ENABLED<ESC><CR><LF>
[00:00:00.074,188] <ESC><inf> board_control: init: nrf_interface_pins_0_2_routing is disabled<ESC><CR><LF>
[00:00:00.082,763] <ESC><inf> board_control: init: nrf_interface_pins_3_5_routing is disabled<ESC><CR><LF>
[00:00:00.091,339] <ESC><inf> board_control: init: nrf_interface_pins_6_8_routing is disabled<ESC><CR><LF>
[00:00:00.099,914] <ESC><inf> board_control: init: Board configured.<ESC><CR><LF>
*** Booting Zephyr OS build v3.2.99-ncs1 ***<CR><LF>
[00:00:00.110,412] <ESC><inf> mcumgr_zephyr_grp: zephyr_basic_mgmt_init: Registering Zephyr basic mgmt group<ESC><CR><LF>
00/00/0000 00:00:00[ami_main.c: 631] Startup<CR><LF>
00/00/0000 00:00:00[ami_cfg.c: 256] DeviceID:0<CR><LF>
00/00/0000 00:00:00[ami_main.c: 448] MainInitErr:4096<CR><LF>
00/00/0000 00:00:00[ami_main.c: 657] VaporBLE#0 26-Feb-2023 v1.0.0 1.0 2.26<CR><LF>
build time: Feb 28 2023 11:08:57<CR><LF>
[00:00:00.245,910] <ESC><inf> sdc_hci_driver: hci_driver_open: SoftDevice Controller build revision: <CR><LF>
                                         6d 90 41 2a 38 e8 ad 17  29 a5 03 38 39 27 d7 85 |m.A*8... )..89'..<CR><LF>
                                         1f 85 d8 e1                                      |....             <ESC><CR><LF>
[00:00:00.276,824] <ESC><inf> bt_hci_core: hci_vs_init: HW Platform: Nordic Semiconductor (0x0002)<ESC><CR><LF>
[00:00:00.285,797] <ESC><inf> bt_hci_core: hci_vs_init: HW Variant: nRF52x (0x0002)<ESC><CR><LF>
[00:00:00.293,518] <ESC><inf> bt_hci_core: hci_vs_init: Firmware: Standard Bluetooth controller (0x00) Version 109.16784 Build 2917677098<ESC><CR><LF>
[00:00:00.306,365] <ESC><inf> bt_hci_core: bt_init: No ID address. App must call settings_load()<ESC><CR><LF>
00/00/0000 00:00:00[ami_ble.c: 506] ActualTxPwr:8<CR><LF>
00/00/0000 00:00:00[ami_ble.c: 788] Bluetooth initialized<CR><LF>
[00:00:00.325,286] <ESC><wrn> bt_hci_core: bt_set_name: Unable to store name<ESC><CR><LF>
[00:00:00.333,099] <ESC><inf> bt_hci_core: bt_dev_show_info: Identity: C0:F1:EE:C6:31:44 (random)<ESC><CR><LF>
[00:00:00.342,010] <ESC><inf> bt_hci_core: bt_dev_show_info: HCI: version 5.3 (0x0c) revision 0x11fa, manufacturer 0x0059<ESC><CR><LF>
[00:00:00.353,057] <ESC><inf> bt_hci_core: bt_dev_show_info: LMP: version 5.3 (0x0c) subver 0x11fa<ESC><CR><LF>
[00:00:00.362,243] <ESC><wrn> bt_hci_core: bt_set_name: Unable to store name<ESC><CR><LF>
00/00/0000 00:00:00[ami_ble.c: 555] UpdateAdv x:0 y:0 z:0 Tmp:0 F:0x20<CR><LF>
00/00/0000 00:00:00[ami_ble.c: 593] AdvertisingStarted<CR><LF>
00/00/0000 00:00:00[ami_main.c: 676] BootConfirmed<CR><LF>
00/00/0000 00:00:00[ami_main.c: 683] ResetCause:1<CR><LF>
[00:00:00.404,693] <ESC><err> bt_gatt: db_hash_store: Failed to save Database Hash (err -2)<ESC><CR><LF>
[00:00:00.252,288] <ESC><inf> board_control: vcom0_pins_routing is ENABLED<ESC><CR><LF>
[00:00:00.259,155] <ESC><inf> board_control: vcom2_pins_routing is ENABLED<ESC><CR><LF>
[00:00:00.266,082] <ESC><inf> board_control: led1_pin_routing is ENABLED<ESC><CR><LF>
[00:00:00.272,796] <ESC><inf> board_control: led2_pin_routing is ENABLED<ESC><CR><LF>
[00:00:00.279,541] <ESC><inf> board_control: led3_pin_routing is ENABLED<ESC><CR><LF>
[00:00:00.286,285] <ESC><inf> board_control: led4_pin_routing is ENABLED<ESC><CR><LF>
[00:00:00.293,029] <ESC><inf> board_control: switch1_pin_routing is ENABLED<ESC><CR><LF>
[00:00:00.300,048] <ESC><inf> board_control: switch2_pin_routing is ENABLED<ESC><CR><LF>
[00:00:00.307,037] <ESC><inf> board_control: button1_pin_routing is ENABLED<ESC><CR><LF>
[00:00:00.314,025] <ESC><inf> board_control: button2_pin_routing is ENABLED<ESC><CR><LF>
[00:00:00.321,044] <ESC><inf> board_control: nrf_interface_pins_0_2_routing is disabled<ESC><CR><LF>
[00:00:00.329,101] <ESC><inf> board_control: nrf_interface_pins_3_5_routing is disabled<ESC><CR><LF>
[00:00:00.337,158] <ESC><inf> board_control: nrf_interface_pins_6_8_routing is disabled<ESC><CR><LF>
[00:00:00.345,214] <ESC><inf> board_control: Board configured.<ESC><CR><LF>
*** Booting Zephyr OS build v3.2.99-ncs1 ***<CR><LF>
[00:00:00.355,102] <ESC><inf> mcuboot: Starting bootloader<ESC><CR><LF>
[00:00:00.361,083] <ESC><inf> mcuboot: Primary image: magic=unset, swap_type=0x1, copy_done=0x3, image_ok=0x3<ESC><CR><LF>
[00:00:00.371,063] <ESC><inf> mcuboot: Secondary image: magic=unset, swap_type=0x1, copy_done=0x3, image_ok=0x3<ESC><CR><LF>
[00:00:00.381,164] <ESC><inf> mcuboot: Boot source: none<ESC><CR><LF>
[00:00:00.386,566] <ESC><inf> mcuboot: Swap type: none<ESC><CR><LF>
[00:00:00.460,662] <ESC><inf> mcuboot: Bootloader chainload address offset: 0xc000<ESC><CR><LF>
[00:00:00.468,231] <ESC><inf> mcuboot: Jumping to the first image slot<ESC><CR>
ÿ[00:00:00.000,152] <ESC><inf> board_control: init: vcom0_pins_routing is ENABLED<ESC><CR><LF>
[00:00:00.007,568] <ESC><inf> board_control: init: vcom2_pins_routing is ENABLED<ESC><CR><LF>
[00:00:00.014,984] <ESC><inf> board_control: init: led1_pin_routing is ENABLED<ESC><CR><LF>
[00:00:00.022,247] <ESC><inf> board_control: init: led2_pin_routing is ENABLED<ESC><CR><LF>
[00:00:00.029,510] <ESC><inf> board_control: init: led3_pin_routing is ENABLED<ESC><CR><LF>
[00:00:00.036,773] <ESC><inf> board_control: init: led4_pin_routing is ENABLED<ESC><CR><LF>
[00:00:00.044,067] <ESC><inf> board_control: init: switch1_pin_routing is ENABLED<ESC><CR><LF>
[00:00:00.051,574] <ESC><inf> board_control: init: switch2_pin_routing is ENABLED<ESC><CR><LF>
[00:00:00.059,112] <ESC><inf> board_control: init: button1_pin_routing is ENABLED<ESC><CR><LF>
[00:00:00.066,650] <ESC><inf> board_control: init: button2_pin_routing is ENABLED<ESC><CR><LF>
[00:00:00.074,188] <ESC><inf> board_control: init: nrf_interface_pins_0_2_routing is disabled<ESC><CR><LF>
[00:00:00.082,763] <ESC><inf> board_control: init: nrf_interface_pins_3_5_routing is disabled<ESC><CR><LF>
[00:00:00.091,339] <ESC><inf> board_control: init: nrf_interface_pins_6_8_routing is disabled<ESC><CR><LF>
[00:00:00.099,914] <ESC><inf> board_control: init: Board configured.<ESC><CR><LF>
*** Booting Zephyr OS build v3.2.99-ncs1 ***<CR><LF>
[00:00:00.110,412] <ESC><inf> mcumgr_zephyr_grp: zephyr_basic_mgmt_init: Registering Zephyr basic mgmt group<ESC><CR><LF>
00/00/0000 00:00:00[ami_main.c: 631] Startup<CR><LF>
00/00/0000 00:00:00[ami_cfg.c: 256] DeviceID:0<CR><LF>
00/00/0000 00:00:00[ami_main.c: 448] MainInitErr:4096<CR><LF>
00/00/0000 00:00:00[ami_main.c: 657] VaporBLE#0 26-Feb-2023 v1.0.0 1.0 2.26<CR><LF>
build time: Feb 28 2023 11:08:57<CR><LF>
[00:00:00.245,971] <ESC><inf> sdc_hci_driver: hci_driver_open: SoftDevice Controller build revision: <CR><LF>
                                         6d 90 41 2a 38 e8 ad 17  29 a5 03 38 39 27 d7 85 |m.A*8... )..89'..<CR><LF>
                                         1f 85 d8 e1                                      |....             <ESC><CR><LF>
[00:00:00.276,916] <ESC><inf> bt_hci_core: hci_vs_init: HW Platform: Nordic Semiconductor (0x0002)<ESC><CR><LF>
[00:00:00.285,888] <ESC><inf> bt_hci_core: hci_vs_init: HW Variant: nRF52x (0x0002)<ESC><CR><LF>
[00:00:00.293,640] <ESC><inf> bt_hci_core: hci_vs_init: Firmware: Standard Bluetooth controller (0x00) Version 109.16784 Build 2917677098<ESC><CR><LF>
[00:00:00.306,488] <ESC><inf> bt_hci_core: bt_init: No ID address. App must call settings_load()<ESC><CR><LF>
00/00/0000 00:00:00[ami_ble.c: 506] ActualTxPwr:8<CR><LF>
00/00/0000 00:00:00[ami_ble.c: 788] Bluetooth initialized<CR><LF>
[00:00:00.325,408] <ESC><wrn> bt_hci_core: bt_set_name: Unable to store name<ESC><CR><LF>
[00:00:00.333,251] <ESC><inf> bt_hci_core: bt_dev_show_info: Identity: C0:F1:EE:C6:31:44 (random)<ESC><CR><LF>
[00:00:00.342,132] <ESC><inf> bt_hci_core: bt_dev_show_info: HCI: version 5.3 (0x0c) revision 0x11fa, manufacturer 0x0059<ESC><CR><LF>
[00:00:00.353,179] <ESC><inf> bt_hci_core: bt_dev_show_info: LMP: version 5.3 (0x0c) subver 0x11fa<ESC><CR><LF>
[00:00:00.362,365] <ESC><wrn> bt_hci_core: bt_set_name: Unable to store name<ESC><CR><LF>
00/00/0000 00:00:00[ami_ble.c: 555] UpdateAdv x:0 y:0 z:0 Tmp:0 F:0x20<CR><LF>
00/00/0000 00:00:00[ami_ble.c: 593] AdvertisingStarted<CR><LF>
00/00/0000 00:00:00[ami_main.c: 676] BootConfirmed<CR><LF>
00/00/0000 00:00:00[ami_main.c: 683] ResetCause:1<CR><LF>
[00:00:00.404,815] <ESC><err> bt_gatt: db_hash_store: Failed to save Database Hash (err -2)<ESC><CR><LF>
01/01/2004 00:01:00[ami_main.c: 601] NewMin<CR><LF>
01/01/2004 00:02:00[ami_main.c: 601] NewMin<CR><LF>
01/01/2004 00:03:00[ami_main.c: 601] NewMin<CR><LF>
01/01/2004 00:04:00[ami_main.c: 601] NewMin<CR><LF>

It does not look that the bootloader showed anything different between the programmer reset and the SMP reset.

*** Booting Zephyr OS build v3.2.99-ncs1 ***<CR><LF>
[00:00:00.355,041] <ESC><inf> mcuboot: Starting bootloader<ESC><CR><LF>
[00:00:00.360,992] <ESC><inf> mcuboot: Primary image: magic=unset, swap_type=0x1, copy_done=0x3, image_ok=0x3<ESC><CR><LF>
[00:00:00.370,971] <ESC><inf> mcuboot: Secondary image: magic=unset, swap_type=0x1, copy_done=0x3, image_ok=0x3<ESC><CR><LF>
[00:00:00.381,072] <ESC><inf> mcuboot: Boot source: none<ESC><CR><LF>
[00:00:00.386,474] <ESC><inf> mcuboot: Swap type: none<ESC><CR><LF>
[00:00:00.460,571] <ESC><inf> mcuboot: Bootloader chainload address offset: 0xc000<ESC><CR><LF>
[00:00:00.468,139] <ESC><inf> mcuboot: Jumping to the first image slot<ESC><CR>
======================================================================
*** Booting Zephyr OS build v3.2.99-ncs1 ***<CR><LF>
[00:00:00.355,102] <ESC><inf> mcuboot: Starting bootloader<ESC><CR><LF>
[00:00:00.361,083] <ESC><inf> mcuboot: Primary image: magic=unset, swap_type=0x1, copy_done=0x3, image_ok=0x3<ESC><CR><LF>
[00:00:00.371,063] <ESC><inf> mcuboot: Secondary image: magic=unset, swap_type=0x1, copy_done=0x3, image_ok=0x3<ESC><CR><LF>
[00:00:00.381,164] <ESC><inf> mcuboot: Boot source: none<ESC><CR><LF>
[00:00:00.386,566] <ESC><inf> mcuboot: Swap type: none<ESC><CR><LF>
[00:00:00.460,662] <ESC><inf> mcuboot: Bootloader chainload address offset: 0xc000<ESC><CR><LF>
[00:00:00.468,231] <ESC><inf> mcuboot: Jumping to the first image slot<ESC><CR>

Next, I tried to use my nRF52840-DK as the Central with your code and my nRF9160-DK as the sensor.

After using the JFlash.ex flash program to upload the app_update.bin file to 0x86000 not 0x50000 and

changing the connection UUID to the one I use, the Central connected.

I pressed button#1 and got a list with only one slot the first time and the second time two slots.

(Both times the upload failed).

When pressed button#2 and saw that the central tries to upload all of second slot and not just the image size.

Is this what you saw too?

Maybe I should upload with my code the entire slot instead of just the app_update.bin file size?

Should the padded data be zero or 0xFF?

In any case, I got an error at almost the end of the upload from the end unit:

*** Booting Zephyr OS build v3.2.99-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: 0xc000
*** Booting Zephyr OS build v3.2.99-ncs1 ***
Starting Bluetooth Central SMP Client example
I: SoftDevice Controller build revision:
I: 6d 90 41 2a 38 e8 ad 17 |m.A*8...
I: 29 a5 03 38 39 27 d7 85 |)..89'..
I: 1f 85 d8 e1             |....
I: HW Platform: Nordic Semiconductor (0x0002)
I: HW Variant: nRF52x (0x0002)
I: Firmware: Standard Bluetooth controller (0x00) Version 109.16784 Build 2917677098
I: Identity: DF:EE:12:96:B1:89 (random)
I: HCI: version 5.3 (0x0c) revision 0x11fa, manufacturer 0x0059
I: LMP: version 5.3 (0x0c) subver 0x11fa
Bluetooth initialized
Scanning successfully started
Filters matched. Address: C0:F1:EE:C6:31:44 (random) connectable: yes
Image list command send error (err: -6)
Connected: C0:F1:EE:C6:31:44 (random)
MTU exchange pending
E: pairing failed (peer reason 0x3)
Security failed: C0:F1:EE:C6:31:44 (random) level 1 err 4
MTU exchange successful
Current MTU: 498
The discovery procedure succeeded

-----------PRIMARY IMAGE-----------
      slot: 0
      version: 0.0.0
      hash: 0x67fb72f73a0fda917c78ad444dbdbc7955e1b12842a66a1222f4ca95a6f0
      bootable: true
      pending: false
      confirmed: true
      active: true
      permanent: false

-----------SECONDARY IMAGE-----------
      slot: 1
      version: 0.0.0
      hash: 0x67fb72f73a0fda917c78ad444dbdbc7955e1b12842a66a1222f4ca95a6f0
      bootable: true
      pending: false
      confirmed: false
      active: false
      permanent: false
[  95% ] |===============================================   | (474900/499712 bytes)Error in image upload response: 1

I tried the nRF52840 Central updating my custom sensor and got the same error:

[ 95% ] |=============================================== | (474900/499712 bytes)Error in image upload response: 1

So, I can't reproduce a DFU successfully like you, so it is evident that I am doing more than one thing wrong.

Thanks David