FOTA

[Vitaliy Freidovich]

Hi,

I'm trying to implement a simple FOTA BLE with MCUBOOT following the instructions in the documentation.

I'm using Visual Studio Code NRF extensions as an IDE, and NRF Connect for Mobile app to do the actual FOTA.

I see that Visual Studio Code is flashing successfully the merged.hex file on the device,

but when I try to do the FOTA of app_update.bin file via the NRF Connect for Mobile app I observe  the following behavior:

1. First FOTA attempt: The file is successfully uploaded, but connection gets disconnected during the validation phase

2. Following FOTA attempts: the connection is disconnected almost immediately, before the file is uploaded.

App prj.conf is:

CONFIG_SYSTEM_WORKQUEUE_STACK_SIZE=4096
CONFIG_BT=y
CONFIG_BT_DEBUG_LOG=y
CONFIG_BT_SMP=y
CONFIG_BT_SIGNING=y
CONFIG_BT_PERIPHERAL=y
CONFIG_BT_DIS=n
CONFIG_BT_ATT_PREPARE_COUNT=5
CONFIG_BT_BAS=n
CONFIG_BT_HRS=n
CONFIG_BT_PRIVACY=y
CONFIG_BT_DEVICE_NAME="Dride-4K"
CONFIG_BT_DEVICE_APPEARANCE=833
CONFIG_BT_DEVICE_NAME_DYNAMIC=y
CONFIG_BT_DEVICE_NAME_MAX=256
CONFIG_BT_KEYS_OVERWRITE_OLDEST=y
CONFIG_BT_SETTINGS=y

CONFIG_BT_L2CAP_TX_MTU=512
CONFIG_BT_BUF_ACL_RX_SIZE=512

CONFIG_FLASH=y
CONFIG_FLASH_PAGE_LAYOUT=y
CONFIG_FLASH_MAP=y
CONFIG_NVS=y
CONFIG_SETTINGS=y

CONFIG_PRINTK=y
CONFIG_LOG=y
#CONFIG_LOG_PRINTK=y
CONFIG_LOG_MODE_IMMEDIATE=y

CONFIG_BOOTLOADER_MCUBOOT=y
CONFIG_SECURE_BOOT=y
CONFIG_BUILD_S1_VARIANT=y
CONFIG_MCUMGR=y
CONFIG_MCUMGR_CMD_OS_MGMT=y
CONFIG_MCUMGR_CMD_IMG_MGMT=y
CONFIG_MCUMGR_SMP_BT=y
CONFIG_MCUMGR_SMP_BT_AUTHEN=n
CONFIG_IMG_MANAGER=y
CONFIG_MCUBOOT_IMG_MANAGER=y

zephyr's prj.conf is:

CONFIG_CONSOLE_HANDLER=y
CONFIG_SYSTEM_CLOCK_DISABLE=y
CONFIG_SYS_POWER_MANAGEMENT=n

CONFIG_MAIN_STACK_SIZE=10240
CONFIG_MBEDTLS_CFG_FILE="mcuboot-mbedtls-cfg.h"

CONFIG_BOOT_SWAP_SAVE_ENCTLV=n
CONFIG_BOOT_ENCRYPT_RSA=n
CONFIG_BOOT_ENCRYPT_EC256=n
CONFIG_BOOT_ENCRYPT_X25519=n

CONFIG_BOOT_UPGRADE_ONLY=n
CONFIG_BOOT_BOOTSTRAP=n

### mbedTLS has its own heap
# CONFIG_HEAP_MEM_POOL_SIZE is not set

### We never want Zephyr's copy of tinycrypt.  If tinycrypt is needed,
### MCUboot has its own copy in tree.
# CONFIG_TINYCRYPT is not set
# CONFIG_TINYCRYPT_ECC_DSA is not set
# CONFIG_TINYCRYPT_SHA256 is not set

CONFIG_FLASH=y
CONFIG_FPROTECT=y

### Various Zephyr boards enable features that we don't want.
# CONFIG_BT is not set
# CONFIG_BT_CTLR is not set
# CONFIG_I2C is not set

CONFIG_LOG=y
CONFIG_PRINTK=y
CONFIG_LOG=y
#CONFIG_LOG_MODE_MINIMAL=y # former CONFIG_MODE_MINIMAL
### Ensure Zephyr logging changes don't use more resources
#CONFIG_LOG_DEFAULT_LEVEL=0
### Decrease footprint by ~4 KB in comparison to CBPRINTF_COMPLETE=y
#CONFIG_CBPRINTF_NANO=y

CONFIG_BOOT_SIGNATURE_KEY_FILE="/path/to/key/file/file.pem"
CONFIG_BOOT_SIGNATURE_TYPE_ECDSA_P256=y

main.c:

...

void enable_fota() {
	os_mgmt_register_group();
	img_mgmt_register_group();
	smp_bt_register();
}

void main(void)
{
	int result;

	result = bt_enable(NULL);
	if (result) {
		printk("Bluetooth init failed (err %d)\n", result);
		return;
	}

	enable_fota();

	...

	while (1) {
		k_sleep(K_SECONDS(1));
		...
	}
}

NRF Connect for Mobile first FOTA attempt log:

Fullscreen Log-First-FOTA.txt Download

nRF Connect, 2021-12-23
80:E6:D0:BF:E1:01 (59:80:E6:D0:BF:E1)
I	15:24:52.477	[Server] Server started
V	15:24:52.493	Heart Rate (0x180D)
- Heart Rate Measurement [N] (0x2A37)
   Client Characteristic Configuration (0x2902)
- Body Sensor Location [R] (0x2A38)
- Heart Rate Control Point [W] (0x2A39)
Unknown Service (0000aaa0-0000-1000-8000-aabbccddeeff)
- Unknown Characteristic [N R] (0000aaa1-0000-1000-8000-aabbccddeeff)
   Client Characteristic Configuration (0x2902)
   Unknown Descriptor (0000aab0-0000-1000-8000-aabbccddeeff)
   Characteristic User Description (0x2901)
   Characteristic Presentation Format (0x2904)
- Unknown Characteristic [I W WNR] (0000aaa2-0000-1000-8000-aabbccddeeff)
   Client Characteristic Configuration (0x2902)
User Data (0x181C)
- First Name [R W] (0x2A8A)
- Last Name [R W] (0x2A90)
- Gender [R W] (0x2A8C)
V	15:24:52.797	Connecting to 59:80:E6:D0:BF:E1...
D	15:24:52.797	gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE, preferred PHY = LE 1M)
D	15:24:53.225	[Server callback] Connection state changed with status: 0 and new state: CONNECTED (2)
I	15:24:53.225	[Server] Device with address 59:80:E6:D0:BF:E1 connected
D	15:24:53.279	[Broadcast] Action received: android.bluetooth.device.action.ACL_CONNECTED
D	15:24:53.314	[Callback] Connection state changed with status: 0 and new state: CONNECTED (2)
I	15:24:53.314	Connected to 59:80:E6:D0:BF:E1
V	15:24:53.336	Discovering services...
D	15:24:53.336	gatt.discoverServices()
I	15:24:53.648	Connection parameters updated (interval: 7.5ms, latency: 0, timeout: 5000ms)
I	15:24:53.711	[Server] PHY updated (TX: LE 2M, RX: LE 2M)
I	15:24:53.722	PHY updated (TX: LE 2M, RX: LE 2M)
D	15:24:53.872	[Callback] Services discovered with status: 0
I	15:24:53.872	Services discovered
V	15:24:53.881	Generic Attribute (0x1801)
- Service Changed [I] (0x2A05)
   Client Characteristic Configuration (0x2902)
- Client Supported Features [R W] (0x2B29)
- Database Hash [R] (0x2B2A)
Generic Access (0x1800)
- Device Name [R W] (0x2A00)
- Appearance [R] (0x2A01)
- Peripheral Preferred Connection Parameters [R] (0x2A04)
Current Time Service (0x1805)
- Current Time [N R] (0x2A2B)
SMP Service (8d53dc1d-1db7-4cd3-868b-8a527460aa84)
- SMP Characteristic [N WNR] (da2e7828-fbce-4e01-ae9e-261174997c48)
   Client Characteristic Configuration (0x2902)
D	15:24:53.881	gatt.setCharacteristicNotification(00002a05-0000-1000-8000-00805f9b34fb, true)
I	15:24:53.947	Connection parameters updated (interval: 48.75ms, latency: 0, timeout: 5000ms)
I	15:24:58.426	Connection parameters updated (interval: 48.75ms, latency: 0, timeout: 420ms)
V	15:25:04.398	[McuMgr] Connecting...
D	15:25:04.407	[McuMgr] gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE, LE 1M)
D	15:25:04.450	[McuMgr] [Callback] Connection state changed with status: 0 and new state: 2 (CONNECTED)
I	15:25:04.467	[McuMgr] Connected to 59:80:E6:D0:BF:E1
D	15:25:04.479	[McuMgr] wait(300)
V	15:25:04.790	[McuMgr] Discovering services...
D	15:25:04.801	[McuMgr] gatt.discoverServices()
I	15:25:04.814	[McuMgr] Services discovered
V	15:25:04.824	[McuMgr] Primary service found
V	15:25:04.833	[McuMgr] Requesting new MTU...
D	15:25:04.843	[McuMgr] gatt.requestMtu(515)
I	15:25:04.957	[McuMgr] MTU changed to: 252
D	15:25:04.979	[McuMgr] gatt.setCharacteristicNotification(da2e7828-fbce-4e01-ae9e-261174997c48, true)
V	15:25:05.000	[McuMgr] Enabling notifications for da2e7828-fbce-4e01-ae9e-261174997c48
D	15:25:05.011	[McuMgr] gatt.writeDescriptor(00002902-0000-1000-8000-00805f9b34fb, value=0x01-00)
I	15:25:05.153	[McuMgr] Data written to descr. 00002902-0000-1000-8000-00805f9b34fb, value: (0x) 01-00
I	15:25:05.172	[McuMgr] Notifications enabled
V	15:25:05.196	[McuMgr] Writing characteristic da2e7828-fbce-4e01-ae9e-261174997c48 (WRITE COMMAND)
D	15:25:05.209	[McuMgr] gatt.writeCharacteristic(da2e7828-fbce-4e01-ae9e-261174997c48)
I	15:25:05.226	[McuMgr] Data written to da2e7828-fbce-4e01-ae9e-261174997c48, value: (0x) 00-00-00-02-00-01-00-00-BF-FF
A	15:25:05.247	[McuMgr] "Operation: READ
Flags: 0
Length: 2
Group Id: 1 (IMAGE)
Sequence Num: 0
Command Id: 0 (STATE)
Message: {}" sent
I	15:25:05.300	[McuMgr] Notification received from da2e7828-fbce-4e01-ae9e-261174997c48, value: (0x) 01-00-00-86-00-01-00-00-BF-66-69-6D-61-67-65-73-9F-BF-64-73-6C-6F-74-00-67-76-65-72-73-69-6F-6E-65-30-2E-30-2E-30-64-68-61-73-68-58-20-0E-97-CF-2F-48-50-1F-D4-DC-0C-B7-20-A3-B7-FC-04-27-89-25-38-4F-09-EF-23-99-AB-0D-59-28-71-8D-85-68-62-6F-6F-74-61-62-6C-65-F5-67-70-65-6E-64-69-6E-67-F4-69-63-6F-6E-66-69-72-6D-65-64-F5-66-61-63-74-69-76-65-F5-69-70-65-72-6D-61-6E-65-6E-74-F4-FF-FF-6B-73-70-6C-69-74-53-74-61-74-75-73-00-FF
A	15:25:05.321	[McuMgr] "{"images":[{"slot":0,"version":"0.0.0","hash":"DpfPL0hQH9TcDLcgo7f8BCeJJThPCe8jmasNWShxjYU=","bootable":true,"pending":false,"confirmed":true,"active":true,"permanent":false}],"splitStatus":0}" received
V	15:25:05.337	[McuMgr] Uploading firmware...
V	15:27:04.122	[McuMgr] Writing characteristic da2e7828-fbce-4e01-ae9e-261174997c48 (WRITE COMMAND)
D	15:27:04.138	[McuMgr] gatt.writeCharacteristic(da2e7828-fbce-4e01-ae9e-261174997c48)
I	15:27:04.159	[McuMgr] Data written to da2e7828-fbce-4e01-ae9e-261174997c48, value: (0x) 02-00-00-32-00-01-00-00-BF-67-63-6F-6E-66-69-72-6D-F4-64-68-61-73-68-58-20-62-F1-98-0E-B7-EA-9C-C3-30-84-E2-19-BD-62-7C-89-F6-CD-E0-0D-3D-5F-64-CA-8F-07-DA-09-66-2C-8D-E2-FF
A	15:27:04.179	[McuMgr] "Operation: WRITE
Flags: 0
Length: 50
Group Id: 1 (IMAGE)
Sequence Num: 0
Command Id: 0 (STATE)
Message: {"confirm":false,"hash":"YvGYDrfqnMMwhOIZvWJ8ifbN4A09X2TKjwfaCWYsjeI="}" sent
I	15:27:04.256	[McuMgr] Notification received from da2e7828-fbce-4e01-ae9e-261174997c48, value: (0x) 03-00-00-F4-00-01-00-00-BF-66-69-6D-61-67-65-73-9F-BF-64-73-6C-6F-74-00-67-76-65-72-73-69-6F-6E-65-30-2E-30-2E-30-64-68-61-73-68-58-20-0E-97-CF-2F-48-50-1F-D4-DC-0C-B7-20-A3-B7-FC-04-27-89-25-38-4F-09-EF-23-99-AB-0D-59-28-71-8D-85-68-62-6F-6F-74-61-62-6C-65-F5-67-70-65-6E-64-69-6E-67-F4-69-63-6F-6E-66-69-72-6D-65-64-F5-66-61-63-74-69-76-65-F5-69-70-65-72-6D-61-6E-65-6E-74-F4-FF-BF-64-73-6C-6F-74-01-67-76-65-72-73-69-6F-6E-65-30-2E-30-2E-30-64-68-61-73-68-58-20-62-F1-98-0E-B7-EA-9C-C3-30-84-E2-19-BD-62-7C-89-F6-CD-E0-0D-3D-5F-64-CA-8F-07-DA-09-66-2C-8D-E2-68-62-6F-6F-74-61-62-6C-65-F5-67-70-65-6E-64-69-6E-67-F5-69-63-6F-6E-66-69-72-6D-65-64-F4-66-61-63-74-69-76-65-F4-69-70-65-72-6D-61-6E-65-6E-74-F4-FF-FF-6B-73-70-6C-69-74-53-74-61-74-75
I	15:27:04.276	[McuMgr] Notification received from da2e7828-fbce-4e01-ae9e-261174997c48, value: (0x) 73-00-FF
A	15:27:04.304	[McuMgr] "{"images":[{"slot":0,"version":"0.0.0","hash":"DpfPL0hQH9TcDLcgo7f8BCeJJThPCe8jmasNWShxjYU=","bootable":true,"pending":false,"confirmed":true,"active":true,"permanent":false},{"slot":1,"version":"0.0.0","hash":"YvGYDrfqnMMwhOIZvWJ8ifbN4A09X2TKjwfaCWYsjeI=","bootable":true,"pending":true,"confirmed":false,"active":false,"permanent":false}],"splitStatus":0}" received
V	15:27:04.321	[McuMgr] Writing characteristic da2e7828-fbce-4e01-ae9e-261174997c48 (WRITE COMMAND)
D	15:27:04.329	[McuMgr] gatt.writeCharacteristic(da2e7828-fbce-4e01-ae9e-261174997c48)
I	15:27:04.347	[McuMgr] Data written to da2e7828-fbce-4e01-ae9e-261174997c48, value: (0x) 02-00-00-02-00-00-00-05-BF-FF
A	15:27:04.361	[McuMgr] "Operation: WRITE
Flags: 0
Length: 2
Group Id: 0 (OS)
Sequence Num: 0
Command Id: 5 (RESET)
Message: {}" sent
I	15:27:04.444	[McuMgr] Notification received from da2e7828-fbce-4e01-ae9e-261174997c48, value: (0x) 03-00-00-02-00-00-00-05-BF-FF
A	15:27:04.468	[McuMgr] "{}" received
D	15:27:05.090	[Server callback] Connection state changed with status: 0 and new state: DISCONNECTED (0)
I	15:27:05.090	[Server] Device disconnected
D	15:27:05.137	[Callback] Connection state changed with status: 8 and new state: DISCONNECTED (0)
D	15:27:05.138	[McuMgr] [Callback] Connection state changed with status: 8 and new state: 0 (DISCONNECTED)
E	15:27:05.138	Error 8 (0x8): GATT CONN TIMEOUT
I	15:27:05.138	Disconnected
W	15:27:05.226	[McuMgr] Error: (0x8): GATT CONN TIMEOUT
D	15:27:05.226	[Broadcast] Action received: android.bluetooth.device.action.ACL_DISCONNECTED
I	15:27:05.253	[McuMgr] Disconnected
D	15:27:05.268	[McuMgr] gatt.close()
V	15:27:05.283	[McuMgr] Connecting...
D	15:27:05.292	[McuMgr] gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE, LE 1M)
D	15:27:10.323	[Server callback] Connection state changed with status: 0 and new state: DISCONNECTED (0)
I	15:27:10.323	[Server] Device disconnected
D	15:27:10.336	[McuMgr] [Callback] Connection state changed with status: 133 and new state: 0 (DISCONNECTED)
W	15:27:10.399	[McuMgr] Error: (0x85): GATT ERROR
D	15:27:10.411	[McuMgr] wait(100)
D	15:27:10.530	[McuMgr] gatt.close()
D	15:27:10.548	[McuMgr] wait(200)
V	15:27:10.766	[McuMgr] Retrying...
D	15:27:10.784	[McuMgr] gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE, LE 1M)
D	15:27:15.827	[Server callback] Connection state changed with status: 0 and new state: DISCONNECTED (0)
I	15:27:15.827	[Server] Device disconnected
D	15:27:15.894	[McuMgr] [Callback] Connection state changed with status: 133 and new state: 0 (DISCONNECTED)
W	15:27:15.912	[McuMgr] Error: (0x85): GATT ERROR
D	15:27:15.936	[McuMgr] wait(100)
D	15:27:16.054	[McuMgr] gatt.close()
D	15:27:16.080	[McuMgr] wait(200)
V	15:27:16.295	[McuMgr] Retrying...
D	15:27:16.317	[McuMgr] gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE, LE 1M)
D	15:27:21.368	[Server callback] Connection state changed with status: 0 and new state: DISCONNECTED (0)
I	15:27:21.368	[Server] Device disconnected
D	15:27:21.410	[McuMgr] [Callback] Connection state changed with status: 133 and new state: 0 (DISCONNECTED)
W	15:27:21.433	[McuMgr] Error: (0x85): GATT ERROR
D	15:27:21.458	[McuMgr] wait(100)
D	15:27:21.576	[McuMgr] gatt.close()
D	15:27:21.597	[McuMgr] wait(200)
V	15:27:21.812	[McuMgr] Retrying...
D	15:27:21.834	[McuMgr] gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE, LE 1M)
D	15:27:26.880	[Server callback] Connection state changed with status: 0 and new state: DISCONNECTED (0)
I	15:27:26.880	[Server] Device disconnected
D	15:27:26.916	[McuMgr] [Callback] Connection state changed with status: 133 and new state: 0 (DISCONNECTED)
W	15:27:26.935	[McuMgr] Error: (0x85): GATT ERROR
W	15:27:26.960	[McuMgr] Connection attempt timed out
D	15:27:26.977	[McuMgr] gatt.close()
D	15:27:27.002	gatt.close()
D	15:27:27.008	wait(200)
V	15:27:27.210	Connecting to 59:80:E6:D0:BF:E1...
D	15:27:27.210	gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE, preferred PHY = LE 1M)
D	15:27:32.252	[Server callback] Connection state changed with status: 0 and new state: DISCONNECTED (0)
I	15:27:32.252	[Server] Device disconnected
D	15:27:32.295	[Callback] Connection state changed with status: 133 and new state: DISCONNECTED (0)
E	15:27:32.296	Error 133 (0x85): GATT ERROR
I	15:27:32.296	Disconnected

Subsequent attempts log:

Fullscreen Log-subsequent-FOTA.txt Download

nRF Connect, 2021-12-23
18:58:81:8B:91:01 (51:18:58:81:8B:91)
I	15:35:07.529	[Server] Server started
V	15:35:07.541	Heart Rate (0x180D)
- Heart Rate Measurement [N] (0x2A37)
   Client Characteristic Configuration (0x2902)
- Body Sensor Location [R] (0x2A38)
- Heart Rate Control Point [W] (0x2A39)
Unknown Service (0000aaa0-0000-1000-8000-aabbccddeeff)
- Unknown Characteristic [N R] (0000aaa1-0000-1000-8000-aabbccddeeff)
   Client Characteristic Configuration (0x2902)
   Unknown Descriptor (0000aab0-0000-1000-8000-aabbccddeeff)
   Characteristic User Description (0x2901)
   Characteristic Presentation Format (0x2904)
- Unknown Characteristic [I W WNR] (0000aaa2-0000-1000-8000-aabbccddeeff)
   Client Characteristic Configuration (0x2902)
User Data (0x181C)
- First Name [R W] (0x2A8A)
- Last Name [R W] (0x2A90)
- Gender [R W] (0x2A8C)
V	15:35:07.769	Connecting to 51:18:58:81:8B:91...
D	15:35:07.769	gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE, preferred PHY = LE 1M)
D	15:35:07.967	[Server callback] Connection state changed with status: 0 and new state: CONNECTED (2)
I	15:35:07.967	[Server] Device with address 51:18:58:81:8B:91 connected
D	15:35:07.991	[Callback] Connection state changed with status: 0 and new state: CONNECTED (2)
I	15:35:07.991	Connected to 51:18:58:81:8B:91
D	15:35:08.019	[Broadcast] Action received: android.bluetooth.device.action.ACL_CONNECTED
V	15:35:08.027	Discovering services...
D	15:35:08.027	gatt.discoverServices()
I	15:35:08.404	Connection parameters updated (interval: 7.5ms, latency: 0, timeout: 5000ms)
I	15:35:08.468	[Server] PHY updated (TX: LE 2M, RX: LE 2M)
I	15:35:08.485	PHY updated (TX: LE 2M, RX: LE 2M)
D	15:35:08.631	[Callback] Services discovered with status: 0
I	15:35:08.631	Services discovered
V	15:35:08.652	Generic Attribute (0x1801)
- Service Changed [I] (0x2A05)
   Client Characteristic Configuration (0x2902)
- Client Supported Features [R W] (0x2B29)
- Database Hash [R] (0x2B2A)
Generic Access (0x1800)
- Device Name [R W] (0x2A00)
- Appearance [R] (0x2A01)
- Peripheral Preferred Connection Parameters [R] (0x2A04)
Current Time Service (0x1805)
- Current Time [N R] (0x2A2B)
SMP Service (8d53dc1d-1db7-4cd3-868b-8a527460aa84)
- SMP Characteristic [N WNR] (da2e7828-fbce-4e01-ae9e-261174997c48)
   Client Characteristic Configuration (0x2902)
D	15:35:08.652	gatt.setCharacteristicNotification(00002a05-0000-1000-8000-00805f9b34fb, true)
I	15:35:08.704	Connection parameters updated (interval: 48.75ms, latency: 0, timeout: 5000ms)
I	15:35:13.183	Connection parameters updated (interval: 48.75ms, latency: 0, timeout: 420ms)
V	15:35:48.834	[McuMgr] Connecting...
D	15:35:48.843	[McuMgr] gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE, LE 1M)
D	15:35:48.866	[McuMgr] [Callback] Connection state changed with status: 0 and new state: 2 (CONNECTED)
I	15:35:48.874	[McuMgr] Connected to 51:18:58:81:8B:91
D	15:35:48.882	[McuMgr] wait(300)
V	15:35:49.193	[McuMgr] Discovering services...
D	15:35:49.203	[McuMgr] gatt.discoverServices()
I	15:35:49.215	[McuMgr] Services discovered
V	15:35:49.221	[McuMgr] Primary service found
V	15:35:49.231	[McuMgr] Requesting new MTU...
D	15:35:49.239	[McuMgr] gatt.requestMtu(515)
I	15:35:49.357	[McuMgr] MTU changed to: 252
D	15:35:49.381	[McuMgr] gatt.setCharacteristicNotification(da2e7828-fbce-4e01-ae9e-261174997c48, true)
V	15:35:49.405	[McuMgr] Enabling notifications for da2e7828-fbce-4e01-ae9e-261174997c48
D	15:35:49.424	[McuMgr] gatt.writeDescriptor(00002902-0000-1000-8000-00805f9b34fb, value=0x01-00)
I	15:35:49.554	[McuMgr] Data written to descr. 00002902-0000-1000-8000-00805f9b34fb, value: (0x) 01-00
I	15:35:49.573	[McuMgr] Notifications enabled
V	15:35:49.592	[McuMgr] Writing characteristic da2e7828-fbce-4e01-ae9e-261174997c48 (WRITE COMMAND)
D	15:35:49.609	[McuMgr] gatt.writeCharacteristic(da2e7828-fbce-4e01-ae9e-261174997c48)
I	15:35:49.628	[McuMgr] Data written to da2e7828-fbce-4e01-ae9e-261174997c48, value: (0x) 00-00-00-02-00-01-00-00-BF-FF
A	15:35:49.646	[McuMgr] "Operation: READ
Flags: 0
Length: 2
Group Id: 1 (IMAGE)
Sequence Num: 0
Command Id: 0 (STATE)
Message: {}" sent
I	15:35:49.703	[McuMgr] Notification received from da2e7828-fbce-4e01-ae9e-261174997c48, value: (0x) 01-00-00-F4-00-01-00-00-BF-66-69-6D-61-67-65-73-9F-BF-64-73-6C-6F-74-00-67-76-65-72-73-69-6F-6E-65-30-2E-30-2E-30-64-68-61-73-68-58-20-0E-97-CF-2F-48-50-1F-D4-DC-0C-B7-20-A3-B7-FC-04-27-89-25-38-4F-09-EF-23-99-AB-0D-59-28-71-8D-85-68-62-6F-6F-74-61-62-6C-65-F5-67-70-65-6E-64-69-6E-67-F4-69-63-6F-6E-66-69-72-6D-65-64-F5-66-61-63-74-69-76-65-F5-69-70-65-72-6D-61-6E-65-6E-74-F4-FF-BF-64-73-6C-6F-74-01-67-76-65-72-73-69-6F-6E-65-30-2E-30-2E-30-64-68-61-73-68-58-20-62-F1-98-0E-B7-EA-9C-C3-30-84-E2-19-BD-62-7C-89-F6-CD-E0-0D-3D-5F-64-CA-8F-07-DA-09-66-2C-8D-E2-68-62-6F-6F-74-61-62-6C-65-F5-67-70-65-6E-64-69-6E-67-F5-69-63-6F-6E-66-69-72-6D-65-64-F4-66-61-63-74-69-76-65-F4-69-70-65-72-6D-61-6E-65-6E-74-F4-FF-FF-6B-73-70-6C-69-74-53-74-61-74-75
I	15:35:49.719	[McuMgr] Notification received from da2e7828-fbce-4e01-ae9e-261174997c48, value: (0x) 73-00-FF
A	15:35:49.741	[McuMgr] "{"images":[{"slot":0,"version":"0.0.0","hash":"DpfPL0hQH9TcDLcgo7f8BCeJJThPCe8jmasNWShxjYU=","bootable":true,"pending":false,"confirmed":true,"active":true,"permanent":false},{"slot":1,"version":"0.0.0","hash":"YvGYDrfqnMMwhOIZvWJ8ifbN4A09X2TKjwfaCWYsjeI=","bootable":true,"pending":true,"confirmed":false,"active":false,"permanent":false}],"splitStatus":0}" received
V	15:35:49.767	[McuMgr] Disconnecting...
D	15:35:49.781	[McuMgr] gatt.disconnect()
D	15:35:49.809	[McuMgr] [Callback] Connection state changed with status: 0 and new state: 0 (DISCONNECTED)
I	15:35:49.820	[McuMgr] Disconnected
D	15:35:49.840	[McuMgr] gatt.close()
V	15:35:59.165	[McuMgr] Connecting...
D	15:35:59.173	[McuMgr] gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE, LE 1M)
D	15:35:59.192	[McuMgr] [Callback] Connection state changed with status: 0 and new state: 2 (CONNECTED)
I	15:35:59.204	[McuMgr] Connected to 51:18:58:81:8B:91
D	15:35:59.213	[McuMgr] wait(300)
I	15:35:59.226	[McuMgr] MTU changed to: 252
V	15:35:59.527	[McuMgr] Discovering services...
D	15:35:59.537	[McuMgr] gatt.discoverServices()
I	15:35:59.548	[McuMgr] Services discovered
V	15:35:59.558	[McuMgr] Primary service found
V	15:35:59.566	[McuMgr] Requesting new MTU...
D	15:35:59.575	[McuMgr] gatt.requestMtu(515)
I	15:35:59.692	[McuMgr] MTU changed to: 252
D	15:35:59.708	[McuMgr] gatt.setCharacteristicNotification(da2e7828-fbce-4e01-ae9e-261174997c48, true)
V	15:35:59.726	[McuMgr] Enabling notifications for da2e7828-fbce-4e01-ae9e-261174997c48
D	15:35:59.740	[McuMgr] gatt.writeDescriptor(00002902-0000-1000-8000-00805f9b34fb, value=0x01-00)
I	15:35:59.839	[McuMgr] Data written to descr. 00002902-0000-1000-8000-00805f9b34fb, value: (0x) 01-00
I	15:35:59.855	[McuMgr] Notifications enabled
V	15:35:59.872	[McuMgr] Writing characteristic da2e7828-fbce-4e01-ae9e-261174997c48 (WRITE COMMAND)
D	15:35:59.885	[McuMgr] gatt.writeCharacteristic(da2e7828-fbce-4e01-ae9e-261174997c48)
I	15:35:59.899	[McuMgr] Data written to da2e7828-fbce-4e01-ae9e-261174997c48, value: (0x) 00-00-00-02-00-01-00-00-BF-FF
A	15:35:59.919	[McuMgr] "Operation: READ
Flags: 0
Length: 2
Group Id: 1 (IMAGE)
Sequence Num: 0
Command Id: 0 (STATE)
Message: {}" sent
I	15:35:59.992	[McuMgr] Notification received from da2e7828-fbce-4e01-ae9e-261174997c48, value: (0x) 01-00-00-F4-00-01-00-00-BF-66-69-6D-61-67-65-73-9F-BF-64-73-6C-6F-74-00-67-76-65-72-73-69-6F-6E-65-30-2E-30-2E-30-64-68-61-73-68-58-20-0E-97-CF-2F-48-50-1F-D4-DC-0C-B7-20-A3-B7-FC-04-27-89-25-38-4F-09-EF-23-99-AB-0D-59-28-71-8D-85-68-62-6F-6F-74-61-62-6C-65-F5-67-70-65-6E-64-69-6E-67-F4-69-63-6F-6E-66-69-72-6D-65-64-F5-66-61-63-74-69-76-65-F5-69-70-65-72-6D-61-6E-65-6E-74-F4-FF-BF-64-73-6C-6F-74-01-67-76-65-72-73-69-6F-6E-65-30-2E-30-2E-30-64-68-61-73-68-58-20-62-F1-98-0E-B7-EA-9C-C3-30-84-E2-19-BD-62-7C-89-F6-CD-E0-0D-3D-5F-64-CA-8F-07-DA-09-66-2C-8D-E2-68-62-6F-6F-74-61-62-6C-65-F5-67-70-65-6E-64-69-6E-67-F5-69-63-6F-6E-66-69-72-6D-65-64-F4-66-61-63-74-69-76-65-F4-69-70-65-72-6D-61-6E-65-6E-74-F4-FF-FF-6B-73-70-6C-69-74-53-74-61-74-75
I	15:36:00.024	[McuMgr] Notification received from da2e7828-fbce-4e01-ae9e-261174997c48, value: (0x) 73-00-FF
A	15:36:00.047	[McuMgr] "{"images":[{"slot":0,"version":"0.0.0","hash":"DpfPL0hQH9TcDLcgo7f8BCeJJThPCe8jmasNWShxjYU=","bootable":true,"pending":false,"confirmed":true,"active":true,"permanent":false},{"slot":1,"version":"0.0.0","hash":"YvGYDrfqnMMwhOIZvWJ8ifbN4A09X2TKjwfaCWYsjeI=","bootable":true,"pending":true,"confirmed":false,"active":false,"permanent":false}],"splitStatus":0}" received
V	15:36:00.069	[McuMgr] Writing characteristic da2e7828-fbce-4e01-ae9e-261174997c48 (WRITE COMMAND)
D	15:36:00.083	[McuMgr] gatt.writeCharacteristic(da2e7828-fbce-4e01-ae9e-261174997c48)
I	15:36:00.099	[McuMgr] Data written to da2e7828-fbce-4e01-ae9e-261174997c48, value: (0x) 02-00-00-02-00-00-00-05-BF-FF
A	15:36:00.114	[McuMgr] "Operation: WRITE
Flags: 0
Length: 2
Group Id: 0 (OS)
Sequence Num: 0
Command Id: 5 (RESET)
Message: {}" sent
I	15:36:00.179	[McuMgr] Notification received from da2e7828-fbce-4e01-ae9e-261174997c48, value: (0x) 03-00-00-02-00-00-00-05-BF-FF
A	15:36:00.201	[McuMgr] "{}" received
D	15:36:00.824	[Server callback] Connection state changed with status: 0 and new state: DISCONNECTED (0)
I	15:36:00.824	[Server] Device disconnected
D	15:36:00.857	[McuMgr] [Callback] Connection state changed with status: 8 and new state: 0 (DISCONNECTED)
D	15:36:00.859	[Callback] Connection state changed with status: 8 and new state: DISCONNECTED (0)
E	15:36:00.860	Error 8 (0x8): GATT CONN TIMEOUT
I	15:36:00.860	Disconnected
W	15:36:00.931	[McuMgr] Error: (0x8): GATT CONN TIMEOUT
D	15:36:00.931	[Broadcast] Action received: android.bluetooth.device.action.ACL_DISCONNECTED
I	15:36:00.967	[McuMgr] Disconnected
D	15:36:00.980	[McuMgr] gatt.close()
V	15:36:01.006	[McuMgr] Connecting...
D	15:36:01.025	[McuMgr] gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE, LE 1M)
D	15:36:06.055	[Server callback] Connection state changed with status: 0 and new state: DISCONNECTED (0)
I	15:36:06.055	[Server] Device disconnected
D	15:36:06.106	[McuMgr] [Callback] Connection state changed with status: 133 and new state: 0 (DISCONNECTED)
W	15:36:06.126	[McuMgr] Error: (0x85): GATT ERROR
D	15:36:06.150	[McuMgr] wait(100)
D	15:36:06.273	[McuMgr] gatt.close()
D	15:36:06.303	[McuMgr] wait(200)
V	15:36:06.522	[McuMgr] Retrying...
D	15:36:06.539	[McuMgr] gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE, LE 1M)
D	15:36:11.580	[Server callback] Connection state changed with status: 0 and new state: DISCONNECTED (0)
I	15:36:11.580	[Server] Device disconnected
D	15:36:11.615	[McuMgr] [Callback] Connection state changed with status: 133 and new state: 0 (DISCONNECTED)
W	15:36:11.629	[McuMgr] Error: (0x85): GATT ERROR
D	15:36:11.651	[McuMgr] wait(100)
D	15:36:11.770	[McuMgr] gatt.close()
D	15:36:11.797	[McuMgr] wait(200)
V	15:36:12.011	[McuMgr] Retrying...
D	15:36:12.026	[McuMgr] gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE, LE 1M)
D	15:36:17.082	[Server callback] Connection state changed with status: 0 and new state: DISCONNECTED (0)
I	15:36:17.082	[Server] Device disconnected
D	15:36:17.127	[McuMgr] [Callback] Connection state changed with status: 133 and new state: 0 (DISCONNECTED)
W	15:36:17.148	[McuMgr] Error: (0x85): GATT ERROR
D	15:36:17.168	[McuMgr] wait(100)
D	15:36:17.288	[McuMgr] gatt.close()
D	15:36:17.316	[McuMgr] wait(200)
V	15:36:17.531	[McuMgr] Retrying...
D	15:36:17.540	[McuMgr] gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE, LE 1M)
D	15:36:22.557	[Server callback] Connection state changed with status: 0 and new state: DISCONNECTED (0)
I	15:36:22.557	[Server] Device disconnected
D	15:36:22.574	[McuMgr] [Callback] Connection state changed with status: 133 and new state: 0 (DISCONNECTED)
W	15:36:22.584	[McuMgr] Error: (0x85): GATT ERROR
W	15:36:22.592	[McuMgr] Connection attempt timed out
D	15:36:22.603	[McuMgr] gatt.close()
D	15:36:22.617	gatt.close()
D	15:36:22.620	wait(200)
V	15:36:22.822	Connecting to 51:18:58:81:8B:91...
D	15:36:22.822	gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE, preferred PHY = LE 1M)
D	15:36:27.838	[Server callback] Connection state changed with status: 0 and new state: DISCONNECTED (0)
I	15:36:27.838	[Server] Device disconnected
D	15:36:27.852	[Callback] Connection state changed with status: 133 and new state: DISCONNECTED (0)
E	15:36:27.852	Error 133 (0x85): GATT ERROR
I	15:36:27.852	Disconnected

Any help appreciated!

Vitaliy

[Hung Bui]

Hi Vitaliy, 

Could you let me know which SDK version you are using ? 
I would suggest to test without the immutable Bootloader (remove CONFIG_SECURE_BOOT=y
CONFIG_BUILD_S1_VARIANT=y).

If you simply test the \zephyr\samples\subsys\mgmt\mcumgr\smp_svr (configured with Bluetooth support) example do you see the same issue ? 

[Vitaliy Freidovich]

Hi Hung,

1. I'm using SDK 1.7.1

2. Same behavior observed without secure boot

3. Same behavior observed with smp_svr

However not it seems to be working! I only played with the state of the switches on the dev board, and now it seems to be working! And I cannot reproduce the previous state where it failed. Is there any HW switch which can effect the DFU process? Perhaps write protects partially flash or anything similar?

I will continue testing to make sure that the issue is resolved, would appreciate your feedback on what might have caused it, to make sure it will not happen again in production :)

[Hung Bui]

Hi Vitaliy, 
I was suspecting that if you update the exact same image and if the image is already stored in one of the slot the bootloader will skip the image. It's what I have observed. But in my case the image is updated on the first time and run properly and if I tried to update same image again the connection immediately disconnect after the hash is sent. 

[Vitaliy Freidovich]

This is the behaviour I observe now as well.

Do you think that the HW switches configuration on the board might have caused the original problem?

Any HW switch effecting flash writes?

BTW, Test and Confirm seems faulty in the app, I have to do each separately to get the desired result.

[Hung Bui]

Hi Vitaliy, 
I can't think of any reason modifying HW configuration can cause MCUboot to fail. If you test with the example in the SDK (SMP_SVR for example) would you see the same problem of test and confirm ?