NordicSemiconductor/Android-nRF-Connect-Device-Manager

Firmware Upgrade "Connection timed out" in 1.4.0 example app

gte1 opened this issue · 23 comments

gte1 commented

Using smp_svr example from nRFConnect SDK 2.0.0, with overlay-bt.conf (which should have improved DFU speed)
Android 10 (Huawei P20 pro), nRF52840dk

Expected: Firmware upgrade works
Actual: Firmware upgrade "Connection timed out". Sometimed on Validate step, sometimes at start of Uploading step

Similar to iOS version?

philips77 commented

Hello,
Please post here relevant logs that you get from the manager or BLE transport.

gte1 commented

I am using the nRFConnect Device Manager 1.4.0 from Google Play. Is there any way to retrieve logs from that one? I cannot find a menu item for logs.

gte1 commented

Just to inform. We tried again using another phone, Google Pixel 6 with Android 12, and saw no problems there (and got a very fast firmware update speed)
So maybe the problem is that the Device Manager app is not completely compatible with older Android 10 and/or Huawei P20 pro

philips77 commented

Is there any way to retrieve logs from that one?

You may install nRF Logger app and you'll see the logs there.

gte1 commented

Log from Android 10 phone that FAILS

Could the following from the below log be caused by some Android permission issue when running on Android 10?
W 14:40:58.689 [e] PHY read failed with status 6

Device Manager, 2022-07-04
Zephyr (Device Manager)
V	14:40:57.176	[j] Starting DFU, mode: TEST_AND_CONFIRM
I	14:40:57.770	[e] Connected to D4:12:A7:99:E8:BD
I	14:40:58.088	[e] Connection parameters updated (interval: 7.5ms, latency: 0, timeout: 5000ms)
I	14:40:58.156	[e] PHY updated (TX: LE 2M, RX: LE 2M)
I	14:40:58.310	[e] Services discovered
I	14:40:58.373	[e] Connection parameters updated (interval: 48.75ms, latency: 0, timeout: 5000ms)
I	14:40:58.423	[e] MTU changed to: 498
I	14:40:58.519	[e] Data written to descr. 00002902-0000-1000-8000-00805f9b34fb, value: (0x) 01-00
I	14:40:58.531	[e] Notifications enabled
I	14:40:58.545	[e] Data written to da2e7828-fbce-4e01-ae9e-261174997c48, value: (0x) 00-00-00-01-00-00-00-06-A0
I	14:40:58.615	[e] Notification received from da2e7828-fbce-4e01-ae9e-261174997c48, value: (0x) 01-00-00-19-00-00-00-06-BF-68-62-75-66-5F-73-69-7A-65-19-09-AB-69-62-75-66-5F-63-6F-75-6E-74-04-FF
I	14:40:58.640	[e] Received Header (Op: 1, Flags: 0, Len: 25, Group: 0, Seq: 0, Command: 6) CBOR {"buf_size":2475,"buf_count":4}
I	14:40:58.682	[e] SMP reassembly supported with buffer size: 2475 bytes and count: 4
W	14:40:58.689	[e] PHY read failed with status 6
I	14:40:58.708	[e] Sending (10 bytes) Header (Op: 0, Flags: 0, Len: 2, Group: 1, Seq: 0, Command: 0) CBOR {}
I	14:40:58.911	[e] Data written to da2e7828-fbce-4e01-ae9e-261174997c48, value: (0x) 00-00-00-02-00-01-00-00-BF-FF
I	14:40:58.927	[e] Sending (10 bytes) Header (Op: 0, Flags: 0, Len: 2, Group: 0, Seq: 1, Command: 6) CBOR {}
I	14:40:58.942	[e] Data written to da2e7828-fbce-4e01-ae9e-261174997c48, value: (0x) 00-00-00-02-00-00-01-06-BF-FF
I	14:40:59.005	[e] 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-5C-F4-DA-8F-47-29-E9-6D-11-3F-0A-FB-59-72-EE-3C-DC-89-D8-38-A2-C2-E7-6C-48-A5-6A-71-0E-55-70-04-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
I	14:40:59.029	[e] Received Header (Op: 1, Flags: 0, Len: 134, Group: 1, Seq: 0, Command: 0) CBOR {"images":[{"slot":0,"version":"0.0.0","hash":"XPTaj0cp6W0RPwr7WXLuPNyJ2DiiwudsSKVqcQ5VcAQ=","bootable":true,"pending":false,"confirmed":true,"active":true,"permanent":false}],"splitStatus":0}
V	14:40:59.071	[k] Validation response: {"images":[{"slot":0,"version":"0.0.0","hash":"XPTaj0cp6W0RPwr7WXLuPNyJ2DiiwudsSKVqcQ5VcAQ=","bootable":true,"pending":false,"confirmed":true,"active":true,"permanent":false}],"splitStatus":0}
V	14:40:59.087	[j] Moving from state VALIDATE to state UPLOAD
I	14:40:59.099	Uploading firmware...
W	14:41:00.144	[Uploader] Uploader write failure for chunk with offset=0: Transaction 2 timed out without receiving a response
W	14:41:01.190	[Uploader] Uploader write failure for chunk with offset=0: Transaction 3 timed out without receiving a response
W	14:41:02.229	[Uploader] Uploader write failure for chunk with offset=0: Transaction 4 timed out without receiving a response
W	14:41:03.253	[Uploader] Uploader write failure for chunk with offset=0: Transaction 5 timed out without receiving a response
W	14:41:04.278	[Uploader] Uploader write failure for chunk with offset=0: Transaction 6 timed out without receiving a response
E	14:41:04.301	[ImageUploader] Upload failed
Transaction 6 timed out without receiving a response
	at r2.e$b.b(Unknown Source:20)
	at s2.f.h(Unknown Source:10)
	at s2.f.b(Unknown Source:0)
	at s2.c.run(Unknown Source:4)
	at android.os.Handler.handleCallback(Handler.java:888)
	at android.os.Handler.dispatchMessage(Handler.java:100)
	at android.os.Looper.loop(Looper.java:213)
	at android.os.HandlerThread.run(HandlerThread.java:67)
Caused by: Transaction 6 timed out without receiving a response
	at s2.b$h.j(Unknown Source:76)
	at b4.a.r(Unknown Source:11)
	at p4.r0.run(Unknown Source:88)
	at kotlinx.coroutines.scheduling.a.l(Unknown Source:0)
	at kotlinx.coroutines.scheduling.a$c.d(Unknown Source:14)
	at kotlinx.coroutines.scheduling.a$c.n(Unknown Source:28)
	at kotlinx.coroutines.scheduling.a$c.run(Unknown Source:0)

E	14:41:04.316	Upgrade failed
Transaction 6 timed out without receiving a response
	at r2.e$b.b(Unknown Source:20)
	at s2.f.h(Unknown Source:10)
	at s2.f.b(Unknown Source:0)
	at s2.c.run(Unknown Source:4)
	at android.os.Handler.handleCallback(Handler.java:888)
	at android.os.Handler.dispatchMessage(Handler.java:100)
	at android.os.Looper.loop(Looper.java:213)
	at android.os.HandlerThread.run(HandlerThread.java:67)
Caused by: Transaction 6 timed out without receiving a response
	at s2.b$h.j(Unknown Source:76)
	at b4.a.r(Unknown Source:11)
	at p4.r0.run(Unknown Source:88)
	at kotlinx.coroutines.scheduling.a.l(Unknown Source:0)
	at kotlinx.coroutines.scheduling.a$c.d(Unknown Source:14)
	at kotlinx.coroutines.scheduling.a$c.n(Unknown Source:28)
	at kotlinx.coroutines.scheduling.a$c.run(Unknown Source:0)

I	14:41:08.808	[e] Notification received from da2e7828-fbce-4e01-ae9e-261174997c48, value: (0x) 03-00-00-0D-00-01-02-01-BF-62-72-63-00-63-6F-66-66-19-09-80-FF
I	14:41:08.823	[e] Notification received from da2e7828-fbce-4e01-ae9e-261174997c48, value: (0x) 03-00-00-0D-00-01-03-01-BF-62-72-63-00-63-6F-66-66-19-09-80-FF
I	14:41:08.836	[e] Received Header (Op: 3, Flags: 0, Len: 13, Group: 1, Seq: 2, Command: 1) CBOR {"rc":0,"off":2432}
I	14:41:08.850	[e] Received Header (Op: 3, Flags: 0, Len: 13, Group: 1, Seq: 3, Command: 1) CBOR {"rc":0,"off":2432}
I	14:41:09.249	[e] Connection parameters updated (interval: 11.25ms, latency: 0, timeout: 420ms)
I	14:41:09.340	[e] Connection parameters updated (interval: 48.75ms, latency: 0, timeout: 420ms)
I	14:41:11.538	[e] Notification received from da2e7828-fbce-4e01-ae9e-261174997c48, value: (0x) 03-00-00-0D-00-01-04-01-BF-62-72-63-00-63-6F-66-66-19-09-80-FF
I	14:41:11.555	[e] Received Header (Op: 3, Flags: 0, Len: 13, Group: 1, Seq: 4, Command: 1) CBOR {"rc":0,"off":2432}
I	14:41:13.197	[e] Connection parameters updated (interval: 11.25ms, latency: 0, timeout: 420ms)
I	14:41:14.059	[e] Notification received from da2e7828-fbce-4e01-ae9e-261174997c48, value: (0x) 03-00-00-0D-00-01-05-01-BF-62-72-63-00-63-6F-66-66-19-09-80-FF
I	14:41:14.070	[e] Received Header (Op: 3, Flags: 0, Len: 13, Group: 1, Seq: 5, Command: 1) CBOR {"rc":0,"off":2432}
I	14:41:15.178	[e] Notification received from da2e7828-fbce-4e01-ae9e-261174997c48, value: (0x) 03-00-00-0D-00-01-06-01-BF-62-72-63-00-63-6F-66-66-19-09-80-FF
I	14:41:15.191	[e] Received Header (Op: 3, Flags: 0, Len: 13, Group: 1, Seq: 6, Command: 1) CBOR {"rc":0,"off":2432}
I	14:41:19.384	[e] Connection parameters updated (interval: 48.75ms, latency: 0, timeout: 420ms)
gte1 commented

Android 12, Google Pixel 6 that works OK

Device Manager, 2022-07-04
Zephyr (Device Manager)
V	14:48:05.578	[j] Starting DFU, mode: TEST_AND_CONFIRM
I	14:48:06.009	[e] Connected to D4:12:A7:99:E8:BD
I	14:48:07.189	[e] Connection parameters updated (interval: 7.5ms, latency: 0, timeout: 5000ms)
I	14:48:07.289	[e] Services discovered
I	14:48:07.321	[e] MTU changed to: 498
I	14:48:07.389	[e] Data written to descr. 00002902-0000-1000-8000-00805f9b34fb, value: (0x) 01-00
I	14:48:07.392	[e] Notifications enabled
I	14:48:07.394	[e] Connection parameters updated (interval: 45.0ms, latency: 0, timeout: 5000ms)
I	14:48:07.396	[e] Data written to da2e7828-fbce-4e01-ae9e-261174997c48, value: (0x) 00-00-00-01-00-00-00-06-A0
I	14:48:07.572	[e] Notification received from da2e7828-fbce-4e01-ae9e-261174997c48, value: (0x) 01-00-00-19-00-00-00-06-BF-68-62-75-66-5F-73-69-7A-65-19-09-AB-69-62-75-66-5F-63-6F-75-6E-74-04-FF
I	14:48:07.583	[e] Received Header (Op: 1, Flags: 0, Len: 25, Group: 0, Seq: 0, Command: 6) CBOR {"buf_size":2475,"buf_count":4}
I	14:48:07.602	[e] SMP reassembly supported with buffer size: 2475 bytes and count: 4
I	14:48:07.605	[e] PHY read (TX: LE 1M, RX: LE 1M)
I	14:48:07.611	[e] Sending (10 bytes) Header (Op: 0, Flags: 0, Len: 2, Group: 1, Seq: 0, Command: 0) CBOR {}
I	14:48:07.814	[e] Sending (10 bytes) Header (Op: 0, Flags: 0, Len: 2, Group: 0, Seq: 1, Command: 6) CBOR {}
I	14:48:07.817	[e] Data written to da2e7828-fbce-4e01-ae9e-261174997c48, value: (0x) 00-00-00-02-00-01-00-00-BF-FF
I	14:48:07.821	[e] Data written to da2e7828-fbce-4e01-ae9e-261174997c48, value: (0x) 00-00-00-02-00-00-01-06-BF-FF
I	14:48:07.886	[e] 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-5C-F4-DA-8F-47-29-E9-6D-11-3F-0A-FB-59-72-EE-3C-DC-89-D8-38-A2-C2-E7-6C-48-A5-6A-71-0E-55-70-04-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
I	14:48:07.890	[e] Notification received from da2e7828-fbce-4e01-ae9e-261174997c48, value: (0x) 01-00-00-19-00-00-01-06-BF-68-62-75-66-5F-73-69-7A-65-19-09-AB-69-62-75-66-5F-63-6F-75-6E-74-04-FF
I	14:48:07.905	[e] Received Header (Op: 1, Flags: 0, Len: 134, Group: 1, Seq: 0, Command: 0) CBOR {"images":[{"slot":0,"version":"0.0.0","hash":"XPTaj0cp6W0RPwr7WXLuPNyJ2DiiwudsSKVqcQ5VcAQ=","bootable":true,"pending":false,"confirmed":true,"active":true,"permanent":false}],"splitStatus":0}
I	14:48:07.916	[e] Received Header (Op: 1, Flags: 0, Len: 25, Group: 0, Seq: 1, Command: 6) CBOR {"buf_size":2475,"buf_count":4}
V	14:48:07.922	[k] Validation response: {"images":[{"slot":0,"version":"0.0.0","hash":"XPTaj0cp6W0RPwr7WXLuPNyJ2DiiwudsSKVqcQ5VcAQ=","bootable":true,"pending":false,"confirmed":true,"active":true,"permanent":false}],"splitStatus":0}
V	14:48:07.939	[j] Moving from state VALIDATE to state UPLOAD
I	14:48:07.943	Uploading firmware...
I	14:48:17.425	[ImageUploader] Upload completed. 267818 bytes sent in 9471 ms with avg speed: 28.274704 kBytes/s
I	14:48:17.434	Image (267818 bytes) sent in 9365 ms (avg speed: 28.597757 kB/s)
V	14:48:17.463	[c] Erase storage response: {}
V	14:48:17.468	[j] Moving from state UPLOAD to state TEST
I	14:48:17.475	[e] Sending (58 bytes) Header (Op: 2, Flags: 0, Len: 50, Group: 1, Seq: 113, Command: 0) CBOR {"confirm":false,"hash":"hYTBLeYCv1dwwByuMgnabuvjXIpAtQK3uggGOXLj9/I="}
I	14:48:17.480	[e] Data written to da2e7828-fbce-4e01-ae9e-261174997c48, value: (0x) 02-00-00-32-00-01-71-00-BF-67-63-6F-6E-66-69-72-6D-F4-64-68-61-73-68-58-20-85-84-C1-2D-E6-02-BF-57-70-C0-1C-AE-32-09-DA-6E-EB-E3-5C-8A-40-B5-02-B7-BA-08-06-39-72-E3-F7-F2-FF
I	14:48:17.507	[e] Notification received from da2e7828-fbce-4e01-ae9e-261174997c48, value: (0x) 03-00-00-F4-00-01-71-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-5C-F4-DA-8F-47-29-E9-6D-11-3F-0A-FB-59-72-EE-3C-DC-89-D8-38-A2-C2-E7-6C-48-A5-6A-71-0E-55-70-04-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-85-84-C1-2D-E6-02-BF-57-70-C0-1C-AE-32-09-DA-6E-EB-E3-5C-8A-40-B5-02-B7-BA-08-06-39-72-E3-F7-F2-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-73-00-FF
I	14:48:17.511	[e] Received Header (Op: 3, Flags: 0, Len: 244, Group: 1, Seq: 113, Command: 0) CBOR {"images":[{"slot":0,"version":"0.0.0","hash":"XPTaj0cp6W0RPwr7WXLuPNyJ2DiiwudsSKVqcQ5VcAQ=","bootable":true,"pending":false,"confirmed":true,"active":true,"permanent":false},{"slot":1,"version":"0.0.0","hash":"hYTBLeYCv1dwwByuMgnabuvjXIpAtQK3uggGOXLj9/I=","bootable":true,"pending":true,"confirmed":false,"active":false,"permanent":false}],"splitStatus":0}
V	14:48:17.519	[i] Test response: {"images":[{"slot":0,"version":"0.0.0","hash":"XPTaj0cp6W0RPwr7WXLuPNyJ2DiiwudsSKVqcQ5VcAQ=","bootable":true,"pending":false,"confirmed":true,"active":true,"permanent":false},{"slot":1,"version":"0.0.0","hash":"hYTBLeYCv1dwwByuMgnabuvjXIpAtQK3uggGOXLj9/I=","bootable":true,"pending":true,"confirmed":false,"active":false,"permanent":false}],"splitStatus":0}
V	14:48:17.522	[j] Moving from state TEST to state RESET
I	14:48:17.529	[e] Sending (10 bytes) Header (Op: 2, Flags: 0, Len: 2, Group: 0, Seq: 114, Command: 5) CBOR {}
I	14:48:17.535	[e] Data written to da2e7828-fbce-4e01-ae9e-261174997c48, value: (0x) 02-00-00-02-00-00-72-05-BF-FF
I	14:48:17.561	[e] Notification received from da2e7828-fbce-4e01-ae9e-261174997c48, value: (0x) 03-00-00-02-00-00-72-05-BF-FF
I	14:48:17.567	[e] Received Header (Op: 3, Flags: 0, Len: 2, Group: 0, Seq: 114, Command: 5) CBOR {}
V	14:48:17.572	[g] Reset request success. Waiting for disconnect...
I	14:48:18.221	[e] Disconnected
I	14:48:18.227	[g] Device disconnected
V	14:48:18.231	[g] Waiting remaining 9342 ms for the swap operation to complete
V	14:48:27.590	[j] Moving from state RESET to state CONFIRM
I	14:48:44.682	[e] Connected to D4:12:A7:99:E8:BD
I	14:48:45.112	[e] Connection parameters updated (interval: 7.5ms, latency: 0, timeout: 5000ms)
I	14:48:45.176	[e] PHY updated (TX: LE 2M, RX: LE 2M)
I	14:48:45.326	[e] Services discovered
I	14:48:45.357	[e] MTU changed to: 498
I	14:48:45.418	[e] Connection parameters updated (interval: 45.0ms, latency: 0, timeout: 5000ms)
I	14:48:45.508	[e] Data written to descr. 00002902-0000-1000-8000-00805f9b34fb, value: (0x) 01-00
I	14:48:45.515	[e] Notifications enabled
I	14:48:45.520	[e] Data written to da2e7828-fbce-4e01-ae9e-261174997c48, value: (0x) 00-00-00-01-00-00-00-06-A0
I	14:48:45.596	[e] Notification received from da2e7828-fbce-4e01-ae9e-261174997c48, value: (0x) 01-00-00-19-00-00-00-06-BF-68-62-75-66-5F-73-69-7A-65-19-09-AB-69-62-75-66-5F-63-6F-75-6E-74-04-FF
I	14:48:45.604	[e] Received Header (Op: 1, Flags: 0, Len: 25, Group: 0, Seq: 0, Command: 6) CBOR {"buf_size":2475,"buf_count":4}
I	14:48:45.610	[e] SMP reassembly supported with buffer size: 2475 bytes and count: 4
I	14:48:45.613	[e] PHY read (TX: LE 2M, RX: LE 2M)
I	14:48:45.619	[e] Sending (58 bytes) Header (Op: 2, Flags: 0, Len: 50, Group: 1, Seq: 0, Command: 0) CBOR {"confirm":true,"hash":"hYTBLeYCv1dwwByuMgnabuvjXIpAtQK3uggGOXLj9/I="}
I	14:48:45.624	[e] Sending (10 bytes) Header (Op: 0, Flags: 0, Len: 2, Group: 0, Seq: 1, Command: 6) CBOR {}
I	14:48:45.626	[e] 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-F5-64-68-61-73-68-58-20-85-84-C1-2D-E6-02-BF-57-70-C0-1C-AE-32-09-DA-6E-EB-E3-5C-8A-40-B5-02-B7-BA-08-06-39-72-E3-F7-F2-FF
I	14:48:45.631	[e] Data written to da2e7828-fbce-4e01-ae9e-261174997c48, value: (0x) 00-00-00-02-00-00-01-06-BF-FF
I	14:48:45.689	[e] 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-85-84-C1-2D-E6-02-BF-57-70-C0-1C-AE-32-09-DA-6E-EB-E3-5C-8A-40-B5-02-B7-BA-08-06-39-72-E3-F7-F2-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-5C-F4-DA-8F-47-29-E9-6D-11-3F-0A-FB-59-72-EE-3C-DC-89-D8-38-A2-C2-E7-6C-48-A5-6A-71-0E-55-70-04-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-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-73-00-FF
I	14:48:45.694	[e] Notification received from da2e7828-fbce-4e01-ae9e-261174997c48, value: (0x) 01-00-00-19-00-00-01-06-BF-68-62-75-66-5F-73-69-7A-65-19-09-AB-69-62-75-66-5F-63-6F-75-6E-74-04-FF
I	14:48:45.697	[e] Received Header (Op: 3, Flags: 0, Len: 244, Group: 1, Seq: 0, Command: 0) CBOR {"images":[{"slot":0,"version":"0.0.0","hash":"hYTBLeYCv1dwwByuMgnabuvjXIpAtQK3uggGOXLj9/I=","bootable":true,"pending":false,"confirmed":true,"active":true,"permanent":false},{"slot":1,"version":"0.0.0","hash":"XPTaj0cp6W0RPwr7WXLuPNyJ2DiiwudsSKVqcQ5VcAQ=","bootable":true,"pending":false,"confirmed":false,"active":false,"permanent":false}],"splitStatus":0}
I	14:48:45.698	[e] Received Header (Op: 1, Flags: 0, Len: 25, Group: 0, Seq: 1, Command: 6) CBOR {"buf_size":2475,"buf_count":4}
V	14:48:45.703	[a] Confirm response: {"images":[{"slot":0,"version":"0.0.0","hash":"hYTBLeYCv1dwwByuMgnabuvjXIpAtQK3uggGOXLj9/I=","bootable":true,"pending":false,"confirmed":true,"active":true,"permanent":false},{"slot":1,"version":"0.0.0","hash":"XPTaj0cp6W0RPwr7WXLuPNyJ2DiiwudsSKVqcQ5VcAQ=","bootable":true,"pending":false,"confirmed":false,"active":false,"permanent":false}],"splitStatus":0}
I	14:48:45.706	Upgrade complete
I	14:48:49.883	[e] Connection parameters updated (interval: 11.25ms, latency: 0, timeout: 420ms)
I	14:48:50.777	[e] Connection parameters updated (interval: 45.0ms, latency: 0, timeout: 420ms)
I	14:49:45.403	[e] Disconnected
hubpav commented

The Connection Timeout message in the nRF Device Manager app happens with my Google Pixel 3a XL as well. Repeated attempts to upload the image will succeed.

Device Manager, 2022-07-05
CHESTER 2155872512 (Device Manager)
V 22:00:19.505 [j] Starting DFU, mode: TEST_AND_CONFIRM
I 22:00:21.535 [e] Connected to D1:2B:96:3E:6F:17
I 22:00:21.945 [e] Connection parameters updated (interval: 7.5ms, latency: 0, timeout: 5000ms)
I 22:00:22.426 [e] Services discovered
I 22:00:22.456 [e] MTU changed to: 247
I 22:00:22.486 [e] Data written to descr. 00002902-0000-1000-8000-00805f9b34fb, value: (0x) 01-00
I 22:00:22.493 [e] Notifications enabled
I 22:00:22.503 [e] Data written to da2e7828-fbce-4e01-ae9e-261174997c48, value: (0x) 00-00-00-01-00-00-00-06-A0
I 22:00:22.532 [e] Connection parameters updated (interval: 45.0ms, latency: 0, timeout: 5000ms)
I 22:00:22.624 [e] Notification received from da2e7828-fbce-4e01-ae9e-261174997c48, value: (0x) 01-00-00-06-00-00-00-06-BF-62-72-63-08-FF
I 22:00:22.643 [e] Received Header (Op: 1, Flags: 0, Len: 6, Group: 0, Seq: 0, Command: 6) CBOR {"rc":8}
I 22:00:22.650 [e] PHY read (TX: LE 2M, RX: LE 2M)
I 22:00:22.661 [e] Sending (10 bytes) Header (Op: 0, Flags: 0, Len: 2, Group: 1, Seq: 0, Command: 0) CBOR {}
I 22:00:22.867 [e] Sending (10 bytes) Header (Op: 0, Flags: 0, Len: 2, Group: 0, Seq: 1, Command: 6) CBOR {}
I 22:00:22.877 [e] Data written to da2e7828-fbce-4e01-ae9e-261174997c48, value: (0x) 00-00-00-02-00-01-00-00-BF-FF
I 22:00:22.886 [e] Data written to da2e7828-fbce-4e01-ae9e-261174997c48, value: (0x) 00-00-00-02-00-00-01-06-BF-FF
I 22:00:22.939 [e] 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-6C-11-52-23-8B-79-4D-F3-47-CC-AA-EF-A5-4F-49-35-D7-05-AC-D0-ED-3D-5C-C9-33-9D-72-EB-12-96-B3-53-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-67-8D-5A-9C-C2-49-23-06-D2-3A-7F-8D-46-84-54-F7-46-78-58-E6-FA-D1-28-BB-6C-E6-A1-9D-61-6D-07-E1-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-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
I 22:00:22.952 [e] Notification received from da2e7828-fbce-4e01-ae9e-261174997c48, value: (0x) 53-74-61-74-75-73-00-FF
I 22:00:22.958 [e] Notification received from da2e7828-fbce-4e01-ae9e-261174997c48, value: (0x) 01-00-00-06-00-00-01-06-BF-62-72-63-08-FF
I 22:00:22.966 [e] Received Header (Op: 1, Flags: 0, Len: 244, Group: 1, Seq: 0, Command: 0) CBOR {"images":[{"slot":0,"version":"0.0.0","hash":"bBFSI4t5TfNHzKrvpU9JNdcFrNDtPVzJM51y6xKWs1M=","bootable":true,"pending":false,"confirmed":true,"active":true,"permanent":false},{"slot":1,"version":"0.0.0","hash":"Z41anMJJIwbSOn+NRoRU90Z4WOb60Si7bOahnWFtB+E=","bootable":true,"pending":false,"confirmed":false,"active":false,"permanent":false}],"splitStatus":0}
I 22:00:22.973 [e] Received Header (Op: 1, Flags: 0, Len: 6, Group: 0, Seq: 1, Command: 6) CBOR {"rc":8}
V 22:00:22.988 [k] Validation response: {"images":[{"slot":0,"version":"0.0.0","hash":"bBFSI4t5TfNHzKrvpU9JNdcFrNDtPVzJM51y6xKWs1M=","bootable":true,"pending":false,"confirmed":true,"active":true,"permanent":false},{"slot":1,"version":"0.0.0","hash":"Z41anMJJIwbSOn+NRoRU90Z4WOb60Si7bOahnWFtB+E=","bootable":true,"pending":false,"confirmed":false,"active":false,"permanent":false}],"splitStatus":0}
V 22:00:22.993 [j] Moving from state VALIDATE to state UPLOAD
I 22:00:23.000 Uploading firmware...
W 22:00:24.013 [Uploader] Uploader write failure for chunk with offset=0: Transaction 2 timed out without receiving a response
W 22:00:25.030 [Uploader] Uploader write failure for chunk with offset=0: Transaction 3 timed out without receiving a response
W 22:00:26.047 [Uploader] Uploader write failure for chunk with offset=0: Transaction 4 timed out without receiving a response
W 22:00:27.061 [Uploader] Uploader write failure for chunk with offset=0: Transaction 5 timed out without receiving a response
W 22:00:28.073 [Uploader] Uploader write failure for chunk with offset=0: Transaction 6 timed out without receiving a response
E 22:00:28.086 [ImageUploader] Upload failed
Transaction 6 timed out without receiving a response
at r2.e$b.b(Unknown Source:20)
at s2.f.h(Unknown Source:10)
at s2.f.b(Unknown Source:0)
at s2.c.run(Unknown Source:4)
at android.os.Handler.handleCallback(Handler.java:938)
at android.os.Handler.dispatchMessage(Handler.java:99)
at android.os.Looper.loopOnce(Looper.java:201)
at android.os.Looper.loop(Looper.java:288)
at android.os.HandlerThread.run(HandlerThread.java:67)
Caused by: Transaction 6 timed out without receiving a response
at s2.b$h.j(Unknown Source:76)
at b4.a.r(Unknown Source:11)
at p4.r0.run(Unknown Source:88)
at kotlinx.coroutines.scheduling.a.l(Unknown Source:0)
at kotlinx.coroutines.scheduling.a$c.d(Unknown Source:14)
at kotlinx.coroutines.scheduling.a$c.n(Unknown Source:28)
at kotlinx.coroutines.scheduling.a$c.run(Unknown Source:0)

E 22:00:28.095 Upgrade failed
Transaction 6 timed out without receiving a response
at r2.e$b.b(Unknown Source:20)
at s2.f.h(Unknown Source:10)
at s2.f.b(Unknown Source:0)
at s2.c.run(Unknown Source:4)
at android.os.Handler.handleCallback(Handler.java:938)
at android.os.Handler.dispatchMessage(Handler.java:99)
at android.os.Looper.loopOnce(Looper.java:201)
at android.os.Looper.loop(Looper.java:288)
at android.os.HandlerThread.run(HandlerThread.java:67)
Caused by: Transaction 6 timed out without receiving a response
at s2.b$h.j(Unknown Source:76)
at b4.a.r(Unknown Source:11)
at p4.r0.run(Unknown Source:88)
at kotlinx.coroutines.scheduling.a.l(Unknown Source:0)
at kotlinx.coroutines.scheduling.a$c.d(Unknown Source:14)
at kotlinx.coroutines.scheduling.a$c.n(Unknown Source:28)
at kotlinx.coroutines.scheduling.a$c.run(Unknown Source:0)

I 22:00:32.954 [e] Notification received from da2e7828-fbce-4e01-ae9e-261174997c48, value: (0x) 03-00-00-0C-00-01-02-01-BF-62-72-63-00-63-6F-66-66-18-CC-FF
I 22:00:32.958 [e] Notification received from da2e7828-fbce-4e01-ae9e-261174997c48, value: (0x) 03-00-00-0C-00-01-03-01-BF-62-72-63-00-63-6F-66-66-18-CC-FF
I 22:00:32.961 [e] Notification received from da2e7828-fbce-4e01-ae9e-261174997c48, value: (0x) 03-00-00-0C-00-01-04-01-BF-62-72-63-00-63-6F-66-66-18-CC-FF
I 22:00:32.965 [e] Received Header (Op: 3, Flags: 0, Len: 12, Group: 1, Seq: 2, Command: 1) CBOR {"rc":0,"off":204}
I 22:00:32.971 [e] Received Header (Op: 3, Flags: 0, Len: 12, Group: 1, Seq: 3, Command: 1) CBOR {"rc":0,"off":204}
I 22:00:32.975 [e] Received Header (Op: 3, Flags: 0, Len: 12, Group: 1, Seq: 4, Command: 1) CBOR {"rc":0,"off":204}
I 22:00:33.092 [e] Connection parameters updated (interval: 11.25ms, latency: 0, timeout: 4000ms)
gte1 commented

Samsung Galaxy S9, Android 10: Fails on first try, but success on retry

Device Manager, 2022-07-06
Zephyr (Device Manager)
V	11:16:08.166	[j] Starting DFU, mode: TEST_AND_CONFIRM
I	11:16:08.540	[e] Connected to D4:12:A7:99:E8:BD
I	11:16:08.957	[e] Connection parameters updated (interval: 7.5ms, latency: 0, timeout: 5000ms)
I	11:16:09.024	[e] PHY updated (TX: LE 2M, RX: LE 2M)
I	11:16:09.144	[e] Services discovered
I	11:16:09.205	[e] Connection parameters updated (interval: 48.75ms, latency: 0, timeout: 5000ms)
I	11:16:09.246	[e] MTU changed to: 498
I	11:16:09.446	[e] Data written to descr. 00002902-0000-1000-8000-00805f9b34fb, value: (0x) 01-00
I	11:16:09.465	[e] Notifications enabled
I	11:16:09.488	[e] Data written to da2e7828-fbce-4e01-ae9e-261174997c48, value: (0x) 00-00-00-01-00-00-00-06-A0
I	11:16:09.543	[e] Notification received from da2e7828-fbce-4e01-ae9e-261174997c48, value: (0x) 01-00-00-19-00-00-00-06-BF-68-62-75-66-5F-73-69-7A-65-19-09-AB-69-62-75-66-5F-63-6F-75-6E-74-04-FF
I	11:16:09.580	[e] Received Header (Op: 1, Flags: 0, Len: 25, Group: 0, Seq: 0, Command: 6) CBOR {"buf_size":2475,"buf_count":4}
I	11:16:09.613	[e] SMP reassembly supported with buffer size: 2475 bytes and count: 4
I	11:16:09.628	[e] PHY read (TX: LE 2M, RX: LE 2M)
I	11:16:09.655	[e] Sending (10 bytes) Header (Op: 0, Flags: 0, Len: 2, Group: 1, Seq: 0, Command: 0) CBOR {}
I	11:16:09.857	[e] Sending (10 bytes) Header (Op: 0, Flags: 0, Len: 2, Group: 0, Seq: 1, Command: 6) CBOR {}
I	11:16:09.877	[e] Data written to da2e7828-fbce-4e01-ae9e-261174997c48, value: (0x) 00-00-00-02-00-01-00-00-BF-FF
I	11:16:09.902	[e] Data written to da2e7828-fbce-4e01-ae9e-261174997c48, value: (0x) 00-00-00-02-00-00-01-06-BF-FF
I	11:16:09.940	[e] 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-85-84-C1-2D-E6-02-BF-57-70-C0-1C-AE-32-09-DA-6E-EB-E3-5C-8A-40-B5-02-B7-BA-08-06-39-72-E3-F7-F2-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-5C-F4-DA-8F-47-29-E9-6D-11-3F-0A-FB-59-72-EE-3C-DC-89-D8-38-A2-C2-E7-6C-48-A5-6A-71-0E-55-70-04-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-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-73-00-FF
I	11:16:09.961	[e] Notification received from da2e7828-fbce-4e01-ae9e-261174997c48, value: (0x) 01-00-00-19-00-00-01-06-BF-68-62-75-66-5F-73-69-7A-65-19-09-AB-69-62-75-66-5F-63-6F-75-6E-74-04-FF
I	11:16:09.983	[e] Received Header (Op: 1, Flags: 0, Len: 244, Group: 1, Seq: 0, Command: 0) CBOR {"images":[{"slot":0,"version":"0.0.0","hash":"hYTBLeYCv1dwwByuMgnabuvjXIpAtQK3uggGOXLj9/I=","bootable":true,"pending":false,"confirmed":true,"active":true,"permanent":false},{"slot":1,"version":"0.0.0","hash":"XPTaj0cp6W0RPwr7WXLuPNyJ2DiiwudsSKVqcQ5VcAQ=","bootable":true,"pending":false,"confirmed":false,"active":false,"permanent":false}],"splitStatus":0}
I	11:16:09.996	[e] Received Header (Op: 1, Flags: 0, Len: 25, Group: 0, Seq: 1, Command: 6) CBOR {"buf_size":2475,"buf_count":4}
I	11:16:10.010	[e] Connection parameters updated (interval: 15.0ms, latency: 0, timeout: 5000ms)
V	11:16:10.036	[k] Validation response: {"images":[{"slot":0,"version":"0.0.0","hash":"hYTBLeYCv1dwwByuMgnabuvjXIpAtQK3uggGOXLj9/I=","bootable":true,"pending":false,"confirmed":true,"active":true,"permanent":false},{"slot":1,"version":"0.0.0","hash":"XPTaj0cp6W0RPwr7WXLuPNyJ2DiiwudsSKVqcQ5VcAQ=","bootable":true,"pending":false,"confirmed":false,"active":false,"permanent":false}],"splitStatus":0}
V	11:16:10.045	[j] Moving from state VALIDATE to state UPLOAD
I	11:16:10.054	Uploading firmware...
W	11:16:11.109	[Uploader] Uploader write failure for chunk with offset=0: Transaction 2 timed out without receiving a response
W	11:16:12.166	[Uploader] Uploader write failure for chunk with offset=0: Transaction 3 timed out without receiving a response
W	11:16:13.220	[Uploader] Uploader write failure for chunk with offset=0: Transaction 4 timed out without receiving a response
W	11:16:14.276	[Uploader] Uploader write failure for chunk with offset=0: Transaction 5 timed out without receiving a response
W	11:16:15.319	[Uploader] Uploader write failure for chunk with offset=0: Transaction 6 timed out without receiving a response
E	11:16:15.349	[ImageUploader] Upload failed
Transaction 6 timed out without receiving a response
	at r2.e$b.b(Unknown Source:20)
	at s2.f.h(Unknown Source:10)
	at s2.f.b(Unknown Source:0)
	at s2.c.run(Unknown Source:4)
	at android.os.Handler.handleCallback(Handler.java:883)
	at android.os.Handler.dispatchMessage(Handler.java:100)
	at android.os.Looper.loop(Looper.java:237)
	at android.os.HandlerThread.run(HandlerThread.java:67)
Caused by: Transaction 6 timed out without receiving a response
	at s2.b$h.j(Unknown Source:76)
	at b4.a.r(Unknown Source:11)
	at p4.r0.run(Unknown Source:88)
	at kotlinx.coroutines.scheduling.a.l(Unknown Source:0)
	at kotlinx.coroutines.scheduling.a$c.d(Unknown Source:14)
	at kotlinx.coroutines.scheduling.a$c.n(Unknown Source:28)
	at kotlinx.coroutines.scheduling.a$c.run(Unknown Source:0)

E	11:16:15.370	Upgrade failed
Transaction 6 timed out without receiving a response
	at r2.e$b.b(Unknown Source:20)
	at s2.f.h(Unknown Source:10)
	at s2.f.b(Unknown Source:0)
	at s2.c.run(Unknown Source:4)
	at android.os.Handler.handleCallback(Handler.java:883)
	at android.os.Handler.dispatchMessage(Handler.java:100)
	at android.os.Looper.loop(Looper.java:237)
	at android.os.HandlerThread.run(HandlerThread.java:67)
Caused by: Transaction 6 timed out without receiving a response
	at s2.b$h.j(Unknown Source:76)
	at b4.a.r(Unknown Source:11)
	at p4.r0.run(Unknown Source:88)
	at kotlinx.coroutines.scheduling.a.l(Unknown Source:0)
	at kotlinx.coroutines.scheduling.a$c.d(Unknown Source:14)
	at kotlinx.coroutines.scheduling.a$c.n(Unknown Source:28)
	at kotlinx.coroutines.scheduling.a$c.run(Unknown Source:0)

I	11:16:18.220	[e] Notification received from da2e7828-fbce-4e01-ae9e-261174997c48, value: (0x) 03-00-00-0D-00-01-02-01-BF-62-72-63-00-63-6F-66-66-19-09-80-FF
I	11:16:18.231	[e] Notification received from da2e7828-fbce-4e01-ae9e-261174997c48, value: (0x) 03-00-00-0D-00-01-03-01-BF-62-72-63-00-63-6F-66-66-19-09-80-FF
I	11:16:18.239	[e] Notification received from da2e7828-fbce-4e01-ae9e-261174997c48, value: (0x) 03-00-00-0D-00-01-04-01-BF-62-72-63-00-63-6F-66-66-19-09-80-FF
I	11:16:18.248	[e] Received Header (Op: 3, Flags: 0, Len: 13, Group: 1, Seq: 2, Command: 1) CBOR {"rc":0,"off":2432}
I	11:16:18.256	[e] Received Header (Op: 3, Flags: 0, Len: 13, Group: 1, Seq: 3, Command: 1) CBOR {"rc":0,"off":2432}
I	11:16:18.264	[e] Received Header (Op: 3, Flags: 0, Len: 13, Group: 1, Seq: 4, Command: 1) CBOR {"rc":0,"off":2432}
I	11:16:18.603	[e] Connection parameters updated (interval: 11.25ms, latency: 0, timeout: 420ms)
I	11:16:18.708	[e] Connection parameters updated (interval: 48.75ms, latency: 0, timeout: 420ms)
V	11:16:19.430	[j] Starting DFU, mode: TEST_AND_CONFIRM
I	11:16:19.635	[e] Sending (10 bytes) Header (Op: 0, Flags: 0, Len: 2, Group: 1, Seq: 7, Command: 0) CBOR {}
I	11:16:19.650	[e] Data written to da2e7828-fbce-4e01-ae9e-261174997c48, value: (0x) 00-00-00-02-00-01-07-00-BF-FF
I	11:16:19.736	[e] Notification received from da2e7828-fbce-4e01-ae9e-261174997c48, value: (0x) 01-00-00-86-00-01-07-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-85-84-C1-2D-E6-02-BF-57-70-C0-1C-AE-32-09-DA-6E-EB-E3-5C-8A-40-B5-02-B7-BA-08-06-39-72-E3-F7-F2-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
I	11:16:19.747	[e] Connection parameters updated (interval: 15.0ms, latency: 0, timeout: 5000ms)
I	11:16:19.757	[e] Received Header (Op: 1, Flags: 0, Len: 134, Group: 1, Seq: 7, Command: 0) CBOR {"images":[{"slot":0,"version":"0.0.0","hash":"hYTBLeYCv1dwwByuMgnabuvjXIpAtQK3uggGOXLj9/I=","bootable":true,"pending":false,"confirmed":true,"active":true,"permanent":false}],"splitStatus":0}
V	11:16:19.781	[k] Validation response: {"images":[{"slot":0,"version":"0.0.0","hash":"hYTBLeYCv1dwwByuMgnabuvjXIpAtQK3uggGOXLj9/I=","bootable":true,"pending":false,"confirmed":true,"active":true,"permanent":false}],"splitStatus":0}
V	11:16:19.790	[j] Moving from state VALIDATE to state UPLOAD
I	11:16:19.805	Uploading firmware...
I	11:16:27.230	[ImageUploader] Upload completed. 267818 bytes sent in 7419 ms with avg speed: 36.09407 kBytes/s
I	11:16:27.255	Image (267818 bytes) sent in 7373 ms (avg speed: 36.324154 kB/s)
V	11:16:27.321	[c] Erase storage response: {}
V	11:16:27.339	[j] Moving from state UPLOAD to state TEST
I	11:16:27.369	[e] Sending (58 bytes) Header (Op: 2, Flags: 0, Len: 50, Group: 1, Seq: 119, Command: 0) CBOR {"confirm":false,"hash":"xFuFDIIDgwZO4t1Nu0Cf+usBDUO+zcH3LnkczXzdPLc="}
I	11:16:27.393	[e] Data written to da2e7828-fbce-4e01-ae9e-261174997c48, value: (0x) 02-00-00-32-00-01-77-00-BF-67-63-6F-6E-66-69-72-6D-F4-64-68-61-73-68-58-20-C4-5B-85-0C-82-03-83-06-4E-E2-DD-4D-BB-40-9F-FA-EB-01-0D-43-BE-CD-C1-F7-2E-79-1C-CD-7C-DD-3C-B7-FF
I	11:16:27.412	[e] Notification received from da2e7828-fbce-4e01-ae9e-261174997c48, value: (0x) 03-00-00-F4-00-01-77-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-85-84-C1-2D-E6-02-BF-57-70-C0-1C-AE-32-09-DA-6E-EB-E3-5C-8A-40-B5-02-B7-BA-08-06-39-72-E3-F7-F2-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-C4-5B-85-0C-82-03-83-06-4E-E2-DD-4D-BB-40-9F-FA-EB-01-0D-43-BE-CD-C1-F7-2E-79-1C-CD-7C-DD-3C-B7-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-73-00-FF
I	11:16:27.428	[e] Received Header (Op: 3, Flags: 0, Len: 244, Group: 1, Seq: 119, Command: 0) CBOR {"images":[{"slot":0,"version":"0.0.0","hash":"hYTBLeYCv1dwwByuMgnabuvjXIpAtQK3uggGOXLj9/I=","bootable":true,"pending":false,"confirmed":true,"active":true,"permanent":false},{"slot":1,"version":"0.0.0","hash":"xFuFDIIDgwZO4t1Nu0Cf+usBDUO+zcH3LnkczXzdPLc=","bootable":true,"pending":true,"confirmed":false,"active":false,"permanent":false}],"splitStatus":0}
V	11:16:27.463	[i] Test response: {"images":[{"slot":0,"version":"0.0.0","hash":"hYTBLeYCv1dwwByuMgnabuvjXIpAtQK3uggGOXLj9/I=","bootable":true,"pending":false,"confirmed":true,"active":true,"permanent":false},{"slot":1,"version":"0.0.0","hash":"xFuFDIIDgwZO4t1Nu0Cf+usBDUO+zcH3LnkczXzdPLc=","bootable":true,"pending":true,"confirmed":false,"active":false,"permanent":false}],"splitStatus":0}
V	11:16:27.481	[j] Moving from state TEST to state RESET
I	11:16:27.501	[e] Sending (10 bytes) Header (Op: 2, Flags: 0, Len: 2, Group: 0, Seq: 120, Command: 5) CBOR {}
I	11:16:27.522	[e] Data written to da2e7828-fbce-4e01-ae9e-261174997c48, value: (0x) 02-00-00-02-00-00-78-05-BF-FF
I	11:16:27.543	[e] Notification received from da2e7828-fbce-4e01-ae9e-261174997c48, value: (0x) 03-00-00-02-00-00-78-05-BF-FF
I	11:16:27.559	[e] Received Header (Op: 3, Flags: 0, Len: 2, Group: 0, Seq: 120, Command: 5) CBOR {}
V	11:16:27.584	[g] Reset request success. Waiting for disconnect...
W	11:16:28.224	[e] Error: (0x8): GATT CONN TIMEOUT
I	11:16:28.281	[e] Disconnected
I	11:16:28.363	[g] Device disconnected
V	11:16:28.379	[g] Waiting remaining 9202 ms for the swap operation to complete
V	11:16:37.621	[j] Moving from state RESET to state CONFIRM
W	11:16:42.727	[e] Error: (0x85): GATT ERROR
W	11:16:48.541	[e] Error: (0x85): GATT ERROR
W	11:16:54.333	[e] Error: (0x85): GATT ERROR
I	11:16:55.455	[e] Connected to D4:12:A7:99:E8:BD
I	11:16:55.813	[e] Connection parameters updated (interval: 7.5ms, latency: 0, timeout: 5000ms)
I	11:16:55.879	[e] PHY updated (TX: LE 2M, RX: LE 2M)
I	11:16:55.998	[e] Services discovered
I	11:16:56.045	[e] MTU changed to: 498
I	11:16:56.096	[e] Connection parameters updated (interval: 48.75ms, latency: 0, timeout: 5000ms)
I	11:16:56.141	[e] Data written to descr. 00002902-0000-1000-8000-00805f9b34fb, value: (0x) 01-00
I	11:16:56.158	[e] Notifications enabled
I	11:16:56.184	[e] Data written to da2e7828-fbce-4e01-ae9e-261174997c48, value: (0x) 00-00-00-01-00-00-00-06-A0
I	11:16:56.288	[e] Notification received from da2e7828-fbce-4e01-ae9e-261174997c48, value: (0x) 01-00-00-19-00-00-00-06-BF-68-62-75-66-5F-73-69-7A-65-19-09-AB-69-62-75-66-5F-63-6F-75-6E-74-04-FF
I	11:16:56.320	[e] Received Header (Op: 1, Flags: 0, Len: 25, Group: 0, Seq: 0, Command: 6) CBOR {"buf_size":2475,"buf_count":4}
I	11:16:56.345	[e] SMP reassembly supported with buffer size: 2475 bytes and count: 4
I	11:16:56.360	[e] PHY read (TX: LE 2M, RX: LE 2M)
I	11:16:56.384	[e] Sending (58 bytes) Header (Op: 2, Flags: 0, Len: 50, Group: 1, Seq: 0, Command: 0) CBOR {"confirm":true,"hash":"xFuFDIIDgwZO4t1Nu0Cf+usBDUO+zcH3LnkczXzdPLc="}
I	11:16:56.402	[e] Sending (10 bytes) Header (Op: 0, Flags: 0, Len: 2, Group: 0, Seq: 1, Command: 6) CBOR {}
I	11:16:56.413	[e] 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-F5-64-68-61-73-68-58-20-C4-5B-85-0C-82-03-83-06-4E-E2-DD-4D-BB-40-9F-FA-EB-01-0D-43-BE-CD-C1-F7-2E-79-1C-CD-7C-DD-3C-B7-FF
I	11:16:56.429	[e] Data written to da2e7828-fbce-4e01-ae9e-261174997c48, value: (0x) 00-00-00-02-00-00-01-06-BF-FF
I	11:16:56.485	[e] 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-C4-5B-85-0C-82-03-83-06-4E-E2-DD-4D-BB-40-9F-FA-EB-01-0D-43-BE-CD-C1-F7-2E-79-1C-CD-7C-DD-3C-B7-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-85-84-C1-2D-E6-02-BF-57-70-C0-1C-AE-32-09-DA-6E-EB-E3-5C-8A-40-B5-02-B7-BA-08-06-39-72-E3-F7-F2-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-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-73-00-FF
I	11:16:56.503	[e] Notification received from da2e7828-fbce-4e01-ae9e-261174997c48, value: (0x) 01-00-00-19-00-00-01-06-BF-68-62-75-66-5F-73-69-7A-65-19-09-AB-69-62-75-66-5F-63-6F-75-6E-74-04-FF
I	11:16:56.519	[e] Received Header (Op: 3, Flags: 0, Len: 244, Group: 1, Seq: 0, Command: 0) CBOR {"images":[{"slot":0,"version":"0.0.0","hash":"xFuFDIIDgwZO4t1Nu0Cf+usBDUO+zcH3LnkczXzdPLc=","bootable":true,"pending":false,"confirmed":true,"active":true,"permanent":false},{"slot":1,"version":"0.0.0","hash":"hYTBLeYCv1dwwByuMgnabuvjXIpAtQK3uggGOXLj9/I=","bootable":true,"pending":false,"confirmed":false,"active":false,"permanent":false}],"splitStatus":0}
I	11:16:56.537	[e] Received Header (Op: 1, Flags: 0, Len: 25, Group: 0, Seq: 1, Command: 6) CBOR {"buf_size":2475,"buf_count":4}
V	11:16:56.569	[a] Confirm response: {"images":[{"slot":0,"version":"0.0.0","hash":"xFuFDIIDgwZO4t1Nu0Cf+usBDUO+zcH3LnkczXzdPLc=","bootable":true,"pending":false,"confirmed":true,"active":true,"permanent":false},{"slot":1,"version":"0.0.0","hash":"hYTBLeYCv1dwwByuMgnabuvjXIpAtQK3uggGOXLj9/I=","bootable":true,"pending":false,"confirmed":false,"active":false,"permanent":false}],"splitStatus":0}
I	11:16:56.587	Upgrade complete
I	11:17:00.594	[e] Connection parameters updated (interval: 11.25ms, latency: 0, timeout: 420ms)
I	11:17:01.597	[e] Connection parameters updated (interval: 48.75ms, latency: 0, timeout: 420ms)
philips77 commented

Try sending erase command before uploading the image.

As the slot it full, the first packet with fw will erase the slot. This takes time, up to 30 sec. But in version 1.4.0 we decreased the timeout for upload command to 1 second. I'll fix it in the next version.

  • 👍2
philips77 commented

You may also create a PR.
In the Validate task in DFU performer enqueue an Erase task if hashes don't match.

gte1 commented

Erase command works as you proposed on Galaxy S9, Android 10
On Huawei P20 Pro, Android 10, this did not help, probably due to the "PHY read failed with status 6" issue
I am a firmware developer and have no experience with Android development, so a PR from me will probably not happen.

gte1 commented

Try sending erase command before uploading the image.

As the slot it full, the first packet with fw will erase the slot. This takes time, up to 30 sec. But I'm version 1.4.0 we decreased the timeout for upload command to 1 second. I'll fix it in the next version.

Maybe this timeout can be a setting in the app?

philips77 commented

There are 3 options:

  • a timeout for image upload may be increased to 30 sec, like it was before (but that was causing another issues)
  • a timeout for the first image upload command, where off=0, can be set to 30 sec, but that's unclear and would have to be documented
  • a new Erase command added to erase the slot if needed.
gte1 commented

There are 3 options:

  • a timeout for image upload may be increased to 30 sec, like it was before (but that was causing another issues)
  • a timeout for the first image upload command, where off=0, can be set to 30 sec, but that's unclear and would have to be documented
  • a new Erase command added to erase the slot if needed.

Seems like the last option ( a new Erase command added to erase the slot if needed) is the best one for now.

  • 👍1
gte1 commented

Huawei P20 LITE, Android 9, works in advanced mode (with manual Erase step), even if this device also logs "PHY read failed with status 6". Approx 7 KB/s. Sometimes, I have to retry clicking Upload button, if "Connection timed out" message appeared

philips77 commented

Yes, that is another thing. As the manager connects automatically on request, after decreasing timeouts to 1 second, it may be not enough for the connection to happen. But there's connect method in the McuMgrTransport interface, that can be called before starting dfu.

Actually, the 1 sec timeout is for the request only. Connection is done before the request starts.

gte1 commented

But that 'connect method' would not be accessible if using the sample app from Google Play?
Maybe the 1 second connect timeout could be a setting in the sample app?

philips77 commented

Right, but there you can simply connect by sending Hello echo command, erase using Advanced mode on Image tab.

gte1 commented

I did that on Huawei P20 PRO, Android 10. I still get "Connection timed out", even if I pre-connected via sending Hello. Retry does not work on that phone.
Slot 1, was already erased from earlier attempt. Are there other timeouts that could lead to this message, even if pre-connected via sending "Hello"?

See log
Log 2022-07-12 09_13_20.txt

gte1 commented

On Huawei P20 Lite, Android 10, pre-connecting via sending "Hello" did not help. Still have to retry there after getting "Connection timed out" first time, but succeeds after retry.

Dimitris-P commented

I can confirm I have the same "Connection timed out" issue on my Huawei P20 Pro.

philips77 commented

Hi,
I've started working on this lib and will add the Erase command. Also, have a look at #70. Perhaps that fixed your issue?

gte1 commented

I will check as soon as 1.4.1 is on Google Play

  • 👍1