Disconnection during DFU upload

[QuentinFarizon]

On a 52811, SD s112 v7.0.1, we get a disconnection during DFU upload, and the DFU fails.

Excerpt:

A	17:17:53.330	[DFU] Data object (2/14) created
D	17:17:53.330	[DFU] wait(400)
A	17:17:53.731	[DFU] Uploading firmware...
V	17:17:53.731	[DFU] Sending firmware to characteristic 8ec90002-f315-4f60-9fb8-838830daea50...
V	17:17:53.795	[DFU] Writing to characteristic 8ec90001-f315-4f60-9fb8-838830daea50
D	17:17:53.795	[DFU] gatt.writeCharacteristic(8ec90001-f315-4f60-9fb8-838830daea50)
E	17:17:59.426	[DFU] Device has disconnected
D	17:17:59.426	[DFU] gatt.disconnect()
D	17:17:59.433	[DFU] gatt.close()
V	17:17:59.446	[DFU] DFU service started
I	17:17:59.449	[DFU] Firmware file opened successfully

I don't understand what happens

Full log :

nRF Connect, 2023-01-27
E6DE1492AB6 (E6:DE:14:92:AB:6C)
V	17:17:32.037	Connecting to E6:DE:14:92:AB:6C...
D	17:17:32.037	gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE, preferred PHY = LE 1M)
D	17:17:32.265	[Callback] Connection state changed with status: 0 and new state: CONNECTED (2)
I	17:17:32.265	Connected to E6:DE:14:92:AB:6C
V	17:17:32.271	Discovering services...
D	17:17:32.271	gatt.discoverServices()
I	17:17:32.271	MTU changed to: 40
V	17:17:32.283	Discovering services...
D	17:17:32.283	gatt.discoverServices()
I	17:17:32.758	Connection parameters updated (interval: 7.5ms, latency: 0, timeout: 5000ms)
D	17:17:33.145	[Callback] Services discovered with status: 0
I	17:17:33.145	Services discovered
V	17:17:33.149	Generic Access (0x1800)
- Device Name [R W] (0x2A00)
- Appearance [R] (0x2A01)
- Peripheral Preferred Connection Parameters [R] (0x2A04)
- Central Address Resolution [R] (0x2AA6)
Generic Attribute (0x1801)
- Service Changed [I] (0x2A05)
   Client Characteristic Configuration (0x2902)
Unknown Service (a7630001-f491-4f21-95ea-846ba586e361)
- Unknown Characteristic [W WNR] (a7630002-f491-4f21-95ea-846ba586e361)
- Unknown Characteristic [N R] (00000004-0000-1000-8000-00805f9b34fb)
   Client Characteristic Configuration (0x2902)
- Unknown Characteristic [N] (a7630003-f491-4f21-95ea-846ba586e361)
   Client Characteristic Configuration (0x2902)
Secure DFU Service (0xFE59)
- Buttonless DFU [I W] (8ec90003-f315-4f60-9fb8-838830daea50)
   Client Characteristic Configuration (0x2902)
Battery Service (0x180F)
- Battery Level [N R] (0x2A19)
   Client Characteristic Configuration (0x2902)
Device Information (0x180A)
- Manufacturer Name String [R] (0x2A29)
- Model Number String [R] (0x2A24)
- Serial Number String [R] (0x2A25)
- Firmware Revision String [R] (0x2A26)
- Software Revision String [R] (0x2A28)
D	17:17:33.149	gatt.setCharacteristicNotification(00002a05-0000-1000-8000-00805f9b34fb, true)
D	17:17:33.152	gatt.setCharacteristicNotification(00000004-0000-1000-8000-00805f9b34fb, true)
D	17:17:33.153	gatt.setCharacteristicNotification(a7630003-f491-4f21-95ea-846ba586e361, true)
D	17:17:33.153	gatt.setCharacteristicNotification(00002a19-0000-1000-8000-00805f9b34fb, true)
I	17:17:33.252	Connection parameters updated (interval: 45.0ms, latency: 0, timeout: 5000ms)
I	17:17:42.392	PHY updated (TX: LE 2M, RX: LE 2M)
V	17:17:43.052	[DFU] DFU service started
V	17:17:43.052	[DFU] Opening file...
I	17:17:44.438	[DFU] Firmware file opened successfully
V	17:17:44.438	[DFU] Connecting to DFU target...
D	17:17:44.439	[DFU] gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE, preferredPhy = LE_1M | LE_2M)
I	17:17:44.455	[DFU] Connected to E6:DE:14:92:AB:6C
V	17:17:44.456	[DFU] Discovering services...
D	17:17:44.456	[DFU] gatt.discoverServices()
I	17:17:44.459	[DFU] Services discovered
D	17:17:44.467	[DFU] wait(1000)
W	17:17:45.474	[DFU] Application with buttonless update found
V	17:17:45.474	[DFU] Jumping to the DFU Bootloader...
V	17:17:45.474	[DFU] Enabling indications for 8ec90003-f315-4f60-9fb8-838830daea50
D	17:17:45.474	[DFU] gatt.setCharacteristicNotification(8ec90003-f315-4f60-9fb8-838830daea50, true)
D	17:17:45.474	[DFU] gatt.writeDescriptor(00002902-0000-1000-8000-00805f9b34fb, value=0x02-00)
I	17:17:45.539	[DFU] Data written to descr.8ec90003-f315-4f60-9fb8-838830daea50, value (0x): 02-00
V	17:17:45.539	[DFU] Notifications enabled for 8ec90003-f315-4f60-9fb8-838830daea50
A	17:17:45.539	[DFU] Indications enabled
D	17:17:45.539	[DFU] wait(1000)
V	17:17:46.565	[DFU] Writing to characteristic 8ec90003-f315-4f60-9fb8-838830daea50
D	17:17:46.565	[DFU] gatt.writeCharacteristic(8ec90003-f315-4f60-9fb8-838830daea50)
I	17:17:46.625	[DFU] Notification received from 8ec90003-f315-4f60-9fb8-838830daea50, value (0x): 20-01-01
A	17:17:46.625	[DFU] Enter bootloader sent (Op Code = 1)
A	17:17:46.625	[DFU] Response received (Op Code = 1, Status = 1)
D	17:17:46.626	[DFU] gatt.refresh() (hidden)
D	17:17:46.628	[DFU] gatt.disconnect()
D	17:17:46.630	[DFU] gatt.close()
V	17:17:46.631	[DFU] Scanning for the DFU Bootloader... (timeout 5000 ms)
I	17:17:47.067	Connection parameters updated (interval: 7.5ms, latency: 0, timeout: 5000ms)
I	17:17:47.205	[DFU] DFU Bootloader found with address E6:DE:14:92:AB:6D
V	17:17:47.224	[DFU] DFU service started
I	17:17:47.224	[DFU] Firmware file opened successfully
D	17:17:47.224	[DFU] wait(1000)
D	17:17:48.239	[DFU] wait(1000)
V	17:17:49.225	[DFU] Connecting to DFU target...
D	17:17:49.246	[DFU] gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE, preferredPhy = LE_1M | LE_2M)
I	17:17:49.283	[DFU] Connected to E6:DE:14:92:AB:6D
V	17:17:49.287	[DFU] Discovering services...
D	17:17:49.287	[DFU] gatt.discoverServices()
I	17:17:49.962	[DFU] Services discovered
D	17:17:49.983	[DFU] wait(1000)
V	17:17:50.966	[DFU] Requesting new MTU...
D	17:17:50.966	[DFU] gatt.requestMtu(517)
I	17:17:51.018	[DFU] MTU changed to: 247
V	17:17:51.018	[DFU] Enabling notifications for 8ec90001-f315-4f60-9fb8-838830daea50
D	17:17:51.018	[DFU] gatt.setCharacteristicNotification(8ec90001-f315-4f60-9fb8-838830daea50, true)
D	17:17:51.020	[DFU] gatt.writeDescriptor(00002902-0000-1000-8000-00805f9b34fb, value=0x01-00)
I	17:17:51.047	[DFU] Data written to descr.8ec90001-f315-4f60-9fb8-838830daea50, value (0x): 01-00
V	17:17:51.047	[DFU] Notifications enabled for 8ec90001-f315-4f60-9fb8-838830daea50
A	17:17:51.047	[DFU] Notifications enabled
D	17:17:51.047	[DFU] wait(1000)
V	17:17:52.048	[DFU] Writing to characteristic 8ec90001-f315-4f60-9fb8-838830daea50
D	17:17:52.048	[DFU] gatt.writeCharacteristic(8ec90001-f315-4f60-9fb8-838830daea50)
D	17:17:52.077	[Callback] Connection state changed with status: 8 and new state: DISCONNECTED (0)
E	17:17:52.078	Error 8 (0x8): GATT CONN TIMEOUT
I	17:17:52.078	Disconnected
I	17:17:52.088	[DFU] Notification received from 8ec90001-f315-4f60-9fb8-838830daea50, value (0x): 60-06-01-00-02-00-00-00-00-00-00-00-00-00-00
I	17:17:52.088	[DFU] Data written to 8ec90001-f315-4f60-9fb8-838830daea50, value (0x): 60-06-01-00-02-00-00-00-00-00-00-00-00-00-00
A	17:17:52.088	[DFU] Command object info received (Max size = 512, Offset = 0, CRC = 00000000)
V	17:17:52.088	[DFU] Writing to characteristic 8ec90001-f315-4f60-9fb8-838830daea50
D	17:17:52.088	[DFU] gatt.writeCharacteristic(8ec90001-f315-4f60-9fb8-838830daea50)
I	17:17:52.128	[DFU] Data written to 8ec90001-f315-4f60-9fb8-838830daea50, value (0x): 02-00-00
I	17:17:52.128	[DFU] Notification received from 8ec90001-f315-4f60-9fb8-838830daea50, value (0x): 60-02-01
A	17:17:52.128	[DFU] Packet Receipt Notif disabled (Op Code = 2, Value = 0)
V	17:17:52.128	[DFU] Writing to characteristic 8ec90001-f315-4f60-9fb8-838830daea50
D	17:17:52.128	[DFU] gatt.writeCharacteristic(8ec90001-f315-4f60-9fb8-838830daea50)
I	17:17:52.141	[DFU] Data written to 8ec90001-f315-4f60-9fb8-838830daea50, value (0x): 01-01-8F-00-00-00
I	17:17:52.144	[DFU] Notification received from 8ec90001-f315-4f60-9fb8-838830daea50, value (0x): 60-01-01
A	17:17:52.144	[DFU] Command object created
V	17:17:52.144	[DFU] Writing to characteristic 8ec90002-f315-4f60-9fb8-838830daea50
D	17:17:52.144	[DFU] gatt.writeCharacteristic(8ec90002-f315-4f60-9fb8-838830daea50)
I	17:17:52.147	[DFU] Data written to 8ec90002-f315-4f60-9fb8-838830daea50, value (0x): 12-8C-01-0A-46-08-01-12-42-08-A8-B9-02-10-34-1A-02-CD-01-20-00-28-00-30-00-38-D0-BB-03-42-24-08-03-12-20-C1-99-0E-9B-04-4A-58-AC-17-AA-54-55-90-B7-B3-3B-1E-3E-FE-D8-23-A1-58-AE-15-EE-0D-D7-5F-84-26-A9-48-00-52-04-08-01-12-00-10-00-1A-40-84-4B-BD-CA-56-0D-C2-52-AA-71-E5-FA-2B-DB-7E-EE-7A-23-CB-C0-74-37-76-E5-99-70-4D-2C-DF-AD-8C-E0-40-C4-9E-0E-EC-FC-1A-87-01-F3-68-F8-93-D7-92-4F-24-68-54-69-D6-3B-08-36-57-48-92-B9-0A-C0-65-98
A	17:17:52.147	[DFU] Command object sent (CRC = A6A8FDB4)
V	17:17:52.147	[DFU] Writing to characteristic 8ec90001-f315-4f60-9fb8-838830daea50
D	17:17:52.147	[DFU] gatt.writeCharacteristic(8ec90001-f315-4f60-9fb8-838830daea50)
I	17:17:52.201	[DFU] Data written to 8ec90001-f315-4f60-9fb8-838830daea50, value (0x): 03
I	17:17:52.202	[DFU] Notification received from 8ec90001-f315-4f60-9fb8-838830daea50, value (0x): 60-03-01-8F-00-00-00-B4-FD-A8-A6
A	17:17:52.202	[DFU] Checksum received (Offset = 143, CRC = A6A8FDB4)
V	17:17:52.203	[DFU] Writing to characteristic 8ec90001-f315-4f60-9fb8-838830daea50
D	17:17:52.203	[DFU] gatt.writeCharacteristic(8ec90001-f315-4f60-9fb8-838830daea50)
I	17:17:52.232	[DFU] Data written to 8ec90001-f315-4f60-9fb8-838830daea50, value (0x): 04
I	17:17:52.383	[DFU] Notification received from 8ec90001-f315-4f60-9fb8-838830daea50, value (0x): 60-04-01
A	17:17:52.384	[DFU] Command object executed
V	17:17:52.384	[DFU] Writing to characteristic 8ec90001-f315-4f60-9fb8-838830daea50
D	17:17:52.384	[DFU] gatt.writeCharacteristic(8ec90001-f315-4f60-9fb8-838830daea50)
I	17:17:52.412	[DFU] Data written to 8ec90001-f315-4f60-9fb8-838830daea50, value (0x): 06-02
I	17:17:52.419	[DFU] Notification received from 8ec90001-f315-4f60-9fb8-838830daea50, value (0x): 60-06-01-00-10-00-00-00-00-00-00-00-00-00-00
A	17:17:52.420	[DFU] Data object info received (Max size = 4096, Offset = 0, CRC = 00000000)
V	17:17:52.446	[DFU] Writing to characteristic 8ec90001-f315-4f60-9fb8-838830daea50
D	17:17:52.446	[DFU] gatt.writeCharacteristic(8ec90001-f315-4f60-9fb8-838830daea50)
I	17:17:52.551	[DFU] Notification received from 8ec90001-f315-4f60-9fb8-838830daea50, value (0x): 60-01-01
I	17:17:52.551	[DFU] Data written to 8ec90001-f315-4f60-9fb8-838830daea50, value (0x): 60-01-01
A	17:17:52.551	[DFU] Data object (1/14) created
D	17:17:52.551	[DFU] wait(400)
A	17:17:52.952	[DFU] Uploading firmware...
V	17:17:52.952	[DFU] Sending firmware to characteristic 8ec90002-f315-4f60-9fb8-838830daea50...
V	17:17:53.002	[DFU] Writing to characteristic 8ec90001-f315-4f60-9fb8-838830daea50
D	17:17:53.002	[DFU] gatt.writeCharacteristic(8ec90001-f315-4f60-9fb8-838830daea50)
I	17:17:53.270	[DFU] Data written to 8ec90001-f315-4f60-9fb8-838830daea50, value (0x): 03
I	17:17:53.270	[DFU] Notification received from 8ec90001-f315-4f60-9fb8-838830daea50, value (0x): 60-03-01-00-10-00-00-71-E6-EE-CB
A	17:17:53.270	[DFU] Checksum received (Offset = 4096, CRC = CBEEE671)
V	17:17:53.270	[DFU] Writing to characteristic 8ec90001-f315-4f60-9fb8-838830daea50
D	17:17:53.270	[DFU] gatt.writeCharacteristic(8ec90001-f315-4f60-9fb8-838830daea50)
I	17:17:53.299	[DFU] Data written to 8ec90001-f315-4f60-9fb8-838830daea50, value (0x): 04
I	17:17:53.299	[DFU] Notification received from 8ec90001-f315-4f60-9fb8-838830daea50, value (0x): 60-04-01
A	17:17:53.299	[DFU] Data object executed
V	17:17:53.299	[DFU] Writing to characteristic 8ec90001-f315-4f60-9fb8-838830daea50
D	17:17:53.299	[DFU] gatt.writeCharacteristic(8ec90001-f315-4f60-9fb8-838830daea50)
I	17:17:53.328	[DFU] Data written to 8ec90001-f315-4f60-9fb8-838830daea50, value (0x): 01-02-00-10-00-00
I	17:17:53.330	[DFU] Notification received from 8ec90001-f315-4f60-9fb8-838830daea50, value (0x): 60-01-01
A	17:17:53.330	[DFU] Data object (2/14) created
D	17:17:53.330	[DFU] wait(400)
A	17:17:53.731	[DFU] Uploading firmware...
V	17:17:53.731	[DFU] Sending firmware to characteristic 8ec90002-f315-4f60-9fb8-838830daea50...
V	17:17:53.795	[DFU] Writing to characteristic 8ec90001-f315-4f60-9fb8-838830daea50
D	17:17:53.795	[DFU] gatt.writeCharacteristic(8ec90001-f315-4f60-9fb8-838830daea50)
E	17:17:59.426	[DFU] Device has disconnected
D	17:17:59.426	[DFU] gatt.disconnect()
D	17:17:59.433	[DFU] gatt.close()
V	17:17:59.446	[DFU] DFU service started
I	17:17:59.449	[DFU] Firmware file opened successfully
D	17:17:59.457	[DFU] wait(1000)
D	17:18:00.483	[DFU] wait(1000)
V	17:18:01.459	[DFU] Connecting to DFU target...
D	17:18:01.498	[DFU] gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE, preferredPhy = LE_1M | LE_2M)

[QuentinFarizon]

As this project had a working DFU before (for a few years without issues), I git-bisected to find the culprit commit.
It is a commit that only modifies applicative code (no change on RAM placement, SDK configuration, build variables, project options, build settings, ....)

I don't understand how it can cause a DFU upload of a build with this new code.

I reproduce it 100% of the times, always succeeding before this commit, always failing after this commit.

[Vidar Berg]

Hi,

So, this commit did not change anything in the bootloader code, only in the app? The log shows the disconnect occurring in the bootloader, so I wanted to double check.

Best regards,

Vidar

[QuentinFarizon]

No change on the bootloader, and the zip is a for a DFU of app only.

Moreover, applying this commit N on a board with firmware N-1 fails.
But applying a DFU of N-1 on board with N-1 succeeds.

So it is an issue with the incoming DFU zip, not of the receiving bootloader installed

[QuentinFarizon]

Retrying today, same scenario, I got this time an "insufficient resources" error, which makes more sens. Reducing application code size fixed the issue.

I'm not sure why the last time I didn't get the correct error message and instead a disconnections, doznes of times.

[Vidar Berg]

Thanks for the update. It is good to hear that you found the problem now.

QuentinFarizon said:

I'm not sure why the last time I didn't get the correct error message and instead a disconnections, doznes of times.

I am afraid I can't explain this either. The image size from the init packet is checked during the pre-validation step before the transfer is started, so it should not be possible to start a transfer if the update is too big to fit in flash.

[RVM]

I am seeing similar symptoms as Quentin and am wonderingif our use case too is caught in this trap.

However, I do not have a history of ever getting the DFU to work on the new board with nRF52840. So my question is: How can I get better logging (and is it even possible) than what I am currently obtaining using my android phone and nrf Connect running on it.

Also, every log I have captured so far indicates that the nRF Connect quits the transfer after it attempts to discover the characteristics of the DFU target (I am assuming this is the 'DfuTarg' device) and the target responds with a disconnect sequence (wonder why the target gave up at this stage)

[Vidar Berg]

Please create a new ticket where you include the DFU log from nRF connect. To get logs from DFU target (these are usually more helpful), you may consider testing with the debug bootloader (pca100xx_sxxx_xxx_debug) which have logging over RTT enabled.

[RVM]

Hi Vidar,

Thanks for following up on this...

I was able to figure out what the issue was with my boot loader workflow. It looks like the boot loader was somehow NOT able to figure out that it has been asked to reboot into 'DFU mode' -- instead it would jump straight into the previously installed application.

I was able to narrow the root cause to one of two quirks in my firmware as listed below:

1. The application was set up to use GPREGRET to signal to the boot loader to go into DFU mode. However, the boot loader was set up to mimic the 'BUTTONLESS_DFU' mode. My fix was to make them both use GPREGRET to execute the handshake.

2. The UICR was not being programmed properly. I realized that this is due to the fact that my linker script was missing the section placements for the MBR Parameters and Boot Loader settings inside the UICR register space. This was an oversight on my part and is done correctly in the Secure DFU Bootloader example included in SDK 17.1.0.

Resolving the two items above allows my application to now successfully execute a BLE DFU from a remote client such as an Android phone running the nRF Connect toolkit.