No "Execute Command" after "Calculate CRC Response

[miktr112]

I'm implementing the device side of the DFU-protocol (v16) (Control Point & Packet) using the nFR Connect Mobile as DFU Controller.

In the app I select Application as file type, then my .bin-file and as init packet I select the blinky_s110_v7_1_0_ext_init.dat (16 B just as a dummy file to test with).
My problem is that everything works fine up to the point where the controller recieves the "Calculate CRC" response.

After this nothing happens - I expect to get the "Execute Command."

The log from nRF Connect Mobile is as below where the last line is the response from my device sending the response to the "Calculate CRC Request". 

Any ideas?

V    10:57:30.766    [DFU] DFU service started
V    10:57:30.766    [DFU] Opening file...
I    10:57:31.076    [DFU] Firmware file opened successfully
V    10:57:31.077    [DFU] Connecting to DFU target...
D    10:57:31.078    [DFU] gatt = device.connectGatt(autoConnect = false)
I    10:57:31.111    [DFU] Connected to 24:0A:C4:10:03:3E
D    10:57:31.113    [DFU] wait(1600)
V    10:57:32.713    [DFU] Discovering services...
D    10:57:32.713    [DFU] gatt.discoverServices()
I    10:57:32.738    [DFU] Services discovered
V    10:57:32.742    [DFU] Reading Service Changed CCCD value...
D    10:57:32.743    [DFU] gatt.readDescriptor(00002902-0000-1000-8000-00805f9b34fb)
I    10:57:32.788    [DFU] Read Response received from descr.00002a05-0000-1000-8000-00805f9b34fb, value (0x): 00-00
V    10:57:32.789    [DFU] Enabling indications for 00002a05-0000-1000-8000-00805f9b34fb
D    10:57:32.789    [DFU] gatt.setCharacteristicNotification(00002a05-0000-1000-8000-00805f9b34fb, true)
D    10:57:32.791    [DFU] gatt.writeDescriptor(00002902-0000-1000-8000-00805f9b34fb, value=0x02-00)
I    10:57:32.846    [DFU] Data written to descr.00002a05-0000-1000-8000-00805f9b34fb, value (0x): 02-00
V    10:57:32.846    [DFU] Indications enabled for 00002a05-0000-1000-8000-00805f9b34fb
A    10:57:32.846    [DFU] Service Changed indications enabled
D    10:57:32.869    [DFU] wait(1000)
V    10:57:33.854    [DFU] Requesting new MTU...
D    10:57:33.854    [DFU] gatt.requestMtu(517)
I    10:57:33.957    [DFU] MTU changed to: 517
V    10:57:33.958    [DFU] Enabling notifications for 8ec90001-f315-4f60-9fb8-838830daea50
D    10:57:33.958    [DFU] gatt.setCharacteristicNotification(8ec90001-f315-4f60-9fb8-838830daea50, true)
D    10:57:33.961    [DFU] gatt.writeDescriptor(00002902-0000-1000-8000-00805f9b34fb, value=0x01-00)
I    10:57:34.104    [DFU] Data written to descr.8ec90001-f315-4f60-9fb8-838830daea50, value (0x): 01-00
V    10:57:34.105    [DFU] Notifications enabled for 8ec90001-f315-4f60-9fb8-838830daea50
A    10:57:34.105    [DFU] Notifications enabled
D    10:57:34.105    [DFU] wait(1000)
V    10:57:35.106    [DFU] Writing to characteristic 8ec90001-f315-4f60-9fb8-838830daea50
D    10:57:35.106    [DFU] gatt.writeCharacteristic(8ec90001-f315-4f60-9fb8-838830daea50)
I    10:57:35.185    [DFU] Notification received from 8ec90001-f315-4f60-9fb8-838830daea50, value (0x): 60-06-01-14-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00
I    10:57:35.186    [DFU] Data written to 8ec90001-f315-4f60-9fb8-838830daea50, value (0x): 60-06-01-14-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00
A    10:57:35.187    [DFU] Command object info received (Max size = 20, Offset = 0, CRC = 00000000)
V    10:57:35.187    [DFU] Writing to characteristic 8ec90001-f315-4f60-9fb8-838830daea50
D    10:57:35.187    [DFU] gatt.writeCharacteristic(8ec90001-f315-4f60-9fb8-838830daea50)
I    10:57:35.277    [DFU] Notification received from 8ec90001-f315-4f60-9fb8-838830daea50, value (0x): 60-02-01-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00
I    10:57:35.278    [DFU] Data written to 8ec90001-f315-4f60-9fb8-838830daea50, value (0x): 60-02-01-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00
A    10:57:35.278    [DFU] Packet Receipt Notif disabled (Op Code = 2, Value = 0)
V    10:57:35.278    [DFU] Writing to characteristic 8ec90001-f315-4f60-9fb8-838830daea50
D    10:57:35.278    [DFU] gatt.writeCharacteristic(8ec90001-f315-4f60-9fb8-838830daea50)
I    10:57:35.366    [DFU] Notification received from 8ec90001-f315-4f60-9fb8-838830daea50, value (0x): 60-01-01-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00
I    10:57:35.367    [DFU] Data written to 8ec90001-f315-4f60-9fb8-838830daea50, value (0x): 60-01-01-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00
A    10:57:35.367    [DFU] Command object created
V    10:57:35.372    [DFU] Writing to characteristic 8ec90002-f315-4f60-9fb8-838830daea50
D    10:57:35.372    [DFU] gatt.writeCharacteristic(8ec90002-f315-4f60-9fb8-838830daea50)
I    10:57:35.376    [DFU] Data written to 8ec90002-f315-4f60-9fb8-838830daea50, value (0x): FF-FF-FF-FF-FF-FF-FF-FF-02-00-4F-00-5A-00-B2-63
A    10:57:35.377    [DFU] Command object sent (CRC = 61066AB5)
V    10:57:35.377    [DFU] Writing to characteristic 8ec90001-f315-4f60-9fb8-838830daea50
D    10:57:35.377    [DFU] gatt.writeCharacteristic(8ec90001-f315-4f60-9fb8-838830daea50)
I    10:57:35.516    [DFU] Data written to 8ec90001-f315-4f60-9fb8-838830daea50, value (0x): 60-03-01-10-00-00-00-B5-6A-06-61

[miktr112]

I've captured the frames using the sniffer now, the dfu sequence of the init packet can be seen at the very end of the file.

dfu_log_2019-12-05_filtered.pcapng

[bjorn-spockeli]

Hi Mike, 
so in the log from November 22nd you added a 5 second delay it seems

A    16:24:59.576    [DFU] Command object sent (CRC = 61066AB5)
V    16:24:59.576    [DFU] Writing to characteristic 8ec90001-f315-4f60-9fb8-838830daea50
D    16:24:59.576    [DFU] gatt.writeCharacteristic(8ec90001-f315-4f60-9fb8-838830daea50)
I    16:25:04.732    [DFU] Data written to 8ec90001-f315-4f60-9fb8-838830daea50, value (0x): 60-03-01-20-00-00-00-CC-4E-91-35

and in the Wireshark trace its about 1 second between the Master sending the Calculate CRC request and the Slave replying with the CRC value in the notification. So neither the 1 second and 5 second delay resolved the issue. Correct?

And you have also filtered out empty PDUs right?

Aleksander Nowakowski: Any ideas?

[miktr112]

Correct, after testing with several different delays I removed them since I didn't notice any difference.
And the empty PDU are filtered out, if they can help I saved the complete log as well.

[Aleksander Nowakowski]

Hello,

If you're using the Secure DFU from SDK 16 you should also prepare a valid binaries to be uploaded. The files you have chosen (blinky_s110_v7_1_0_ext_init.dat (16 B just as a dummy file to test with)) is not compatible with Secure DFU. It's an old, legacy DFU dat file, with very different content.

If you want to test DFU, you may find example HEX and ZIP files (ZIP contains BIN+DAT+manifest.json) in SDK in nRF5_SDK_16.0.0_98a08e2\examples\dfu\secure_dfu_test_images\ble\[BOARD].

Flash the biggest HEX files onto your DK and then try sending one of the ZIP files from the same folder. For start I would recommend without bonds versions.

Regarding the issue, why the DFU just hangs. I've noticed, that the notification (with CRC) is sent before Write Request was acknowledged. Have a look at packet 359: sending write request 0x03, followed by a notification with crc in 360, and then in 361 comes Rcvd Write Response. That should not matter for the DFU library, but in my opinion 360 and 361 should be sent in the opposite order.

Also, I don't know why the 357 and 358 are duplicated, but perhaps one of them was not received and the phone repeated. The reported size of init packet is 16, so only 1 packet was actually processed on the peripheral side.

[Aleksander Nowakowski]

As you're not using our SDK, but writing your own bootloader, you should decide to use either legacy or secure DFU and prepare binaries that are compatible with it. You may use nrf util https://github.com/NordicSemiconductor/pc-nrfutil to generate valid zip files for secure DFU. For legacy DFU use branch 0.5.x instead.