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

[bjorn-spockeli]

Do you get the same behaviour when using one of the DFU test images from SDK v16.0.0?

Looking at the Android DFU Library code, I find it odd that the log does not contain a log message stating that the Checksum has been received, i.e. Checksum received (Offset = %d, CRC = %08X) when the Command object sent (CRC = %08X) is printed to the log, see https://github.com/NordicSemiconductor/Android-DFU-Library/blob/ebd769c55ce5ef072aaba5b1b14d60c8d5a38d58/dfu/src/main/java/no/nordicsemi/android/dfu/SecureDfuImpl.java#L432

Will run it by the Android developer responsible for the DFU library. 

Best regards

Bjørn

[Aleksander Nowakowski]

The last line should say: Data written to 8ec90001-f315-4f60-9fb8-838830daea50,v (0x): 03

And should be followed by: Notification received from 8ec90001-f315-4f60-9fb8-838830daea50, value (0x): 60-03-01-10-00-00-00-B5-6A-06-61

Seems like the notification was received so quickly, that during logging the written data was already replaced by received, and the library has missed the notification. This indeed is a library issue, but as a workaround you may delay this notification a bit, or longer connection interval. Did you modify the bootloader? What SDK is it from and what phone are you using? How often this error happens?

[miktr112]

At this point I haven't tried with any other images since I never got passed transferring the init package. 

[miktr112]

I was also expecting the "Notification received" log entry but this behavior is constant, it is not something that happens randomly. 

I'm using a Samsung Galaxy S8.  (Runnning nRF Connect for Mobile 15.11.2019 - version 4.23.0)
On the server side I'm not using the SDK from Nordic since I'm implementing for another microcontroller (esp32), but I'm reading the specs from 1.6.  

I've left the office but will try first thing tomorrow to add a short delay before sending the response message with the calculated CRC. 

[miktr112]

We saw the log entry "Checksum received (Offset = %d, CRC = %08X)" once on a Galaxy S7, but we can't reproduce this as it seems independent of log level.