Unable to run Secure DFU boot loader update using SDK 17.1

[KTM]

Hello

In the past I was able to run DFU on both SDK 17 and SDK 14.

Now I am developing over SDK 17.1.0 a new application and attempted to run secure DFU Bootloader using BLE transport.

I have generated private and public keys and replaced dfu_public_key.c content with the generated public key

I installed soft device and run secure_bootloader_ble_s140_pca10056.ewp (compiled it prior of course)

I created my own application package by running nrfutil:

nrfutil pkg generate --hw-version 52 --application-version 1 --application ble_app_uart_pca10040_s132.hex --sd-req 0x101 --key-file private.key oxitone_dfu_package.zip

I run secure_bootloader_ble

Using DFU app on Samsung Galaxy A21s and always getting a GATT error:

NRF Log shows:

DFU, 2022-08-16
DFU (EA:A8:49:2F:C2:3B)
V  13:52:01.708   [DFU] DFU service started
V  13:52:01.720   [DFU] Opening file...
I  13:52:01.730   [DFU] Firmware file opened successfully
V  13:52:01.740   [DFU] Connecting to DFU target...
D  13:52:01.751   [DFU] gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE, preferredPhy = LE_1M | LE_2M)
I  13:52:01.765   [DFU] Connected to EA:A8:49:2F:C2:3B
V  13:52:01.779   [DFU] Discovering services...
D  13:52:01.792   [DFU] gatt.discoverServices()
D  13:52:01.815   [DFU] [Broadcast] Action received: android.bluetooth.device.action.ACL_CONNECTED
I  13:52:02.248   [DFU] Services discovered
D  13:52:02.261   [DFU] wait(1000)
V  13:52:03.257   [DFU] Requesting new MTU...
D  13:52:03.268   [DFU] gatt.requestMtu(517)
I  13:52:03.289   [DFU] MTU changed to: 247
V  13:52:03.300   [DFU] Enabling notifications for 8ec90001-f315-4f60-9fb8-838830daea50
D  13:52:03.314   [DFU] gatt.setCharacteristicNotification(8ec90001-f315-4f60-9fb8-838830daea50, true)
D  13:52:03.328   [DFU] gatt.writeDescriptor(00002902-0000-1000-8000-00805f9b34fb, value=0x01-00)
I  13:52:03.351   [DFU] Data written to descr.8ec90001-f315-4f60-9fb8-838830daea50, value (0x): 01-00
V  13:52:03.364   [DFU] Notifications enabled for 8ec90001-f315-4f60-9fb8-838830daea50
A  13:52:03.377   [DFU] Notifications enabled
D  13:52:03.389   [DFU] wait(1000)
V  13:52:04.355   [DFU] Writing to characteristic 8ec90001-f315-4f60-9fb8-838830daea50
D  13:52:04.374   [DFU] gatt.writeCharacteristic(8ec90001-f315-4f60-9fb8-838830daea50)
I  13:52:04.388   [DFU] Data written to 8ec90001-f315-4f60-9fb8-838830daea50, value (0x): 06-01
I  13:52:04.401   [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
A  13:52:04.416   [DFU] Command object info received (Max size = 512, Offset = 0, CRC = 00000000)
V  13:52:04.431   [DFU] Writing to characteristic 8ec90001-f315-4f60-9fb8-838830daea50
D  13:52:04.445   [DFU] gatt.writeCharacteristic(8ec90001-f315-4f60-9fb8-838830daea50)
I  13:52:04.457   [DFU] Data written to 8ec90001-f315-4f60-9fb8-838830daea50, value (0x): 02-00-00
I  13:52:04.471   [DFU] Notification received from 8ec90001-f315-4f60-9fb8-838830daea50, value (0x): 60-02-01
A  13:52:04.483   [DFU] Packet Receipt Notif disabled (Op Code = 2, Value = 0)
V  13:52:04.494   [DFU] Writing to characteristic 8ec90001-f315-4f60-9fb8-838830daea50
D  13:52:04.507   [DFU] gatt.writeCharacteristic(8ec90001-f315-4f60-9fb8-838830daea50)
I  13:52:04.518   [DFU] Data written to 8ec90001-f315-4f60-9fb8-838830daea50, value (0x): 01-01-8D-00-00-00
I  13:52:04.530   [DFU] Notification received from 8ec90001-f315-4f60-9fb8-838830daea50, value (0x): 60-01-01
A  13:52:04.541   [DFU] Command object created
V  13:52:04.555   [DFU] Writing to characteristic 8ec90002-f315-4f60-9fb8-838830daea50
D  13:52:04.570   [DFU] gatt.writeCharacteristic(8ec90002-f315-4f60-9fb8-838830daea50)
I  13:52:04.584   [DFU] Data written to 8ec90002-f315-4f60-9fb8-838830daea50, value (0x): 12-8A-01-0A-44-08-01-12-40-08-01-10-34-1A-02-80-02-20-00-28-00-30-00-38-C0-FD-0A-42-24-08-03-12-20-65-95-01-D4-F3-65-15-EE-7C-FA-68-C0-E7-A5-69-6C-3E-88-27-CF-7C-69-1C-E8-81-88-66-53-73-A8-CB-79-48-00-52-04-08-01-12-00-10-00-1A-40-69-A8-18-D9-AC-65-70-45-CD-81-20-7D-63-23-17-5A-9D-2E-50-13-F6-A3-64-AF-B9-A6-49-CA-59-F1-1D-B0-EC-5A-C0-6E-91-F3-FB-78-44-80-DA-57-F5-EA-45-83-90-E5-0F-14-DD-A4-9F-B3-76-14-FE-DE-0E-93-73-9B
A  13:52:04.596   [DFU] Command object sent (CRC = 7BE3B6A8)
V  13:52:04.609   [DFU] Writing to characteristic 8ec90001-f315-4f60-9fb8-838830daea50
D  13:52:04.623   [DFU] gatt.writeCharacteristic(8ec90001-f315-4f60-9fb8-838830daea50)
I  13:52:04.635   [DFU] Data written to 8ec90001-f315-4f60-9fb8-838830daea50, value (0x): 03
I  13:52:04.648   [DFU] Notification received from 8ec90001-f315-4f60-9fb8-838830daea50, value (0x): 60-03-01-8D-00-00-00-A8-B6-E3-7B
A  13:52:04.664   [DFU] Checksum received (Offset = 141, CRC = 7BE3B6A8)
V  13:52:04.687   [DFU] Writing to characteristic 8ec90001-f315-4f60-9fb8-838830daea50
D  13:52:04.716   [DFU] gatt.writeCharacteristic(8ec90001-f315-4f60-9fb8-838830daea50)
E  13:52:10.541   [DFU] Error (0x85): GATT ERROR
V  13:52:10.555   [DFU] Disconnecting...
D  13:52:10.567   [DFU] gatt.disconnect()
I  13:52:10.598   [DFU] Disconnected
D  13:52:10.610   [DFU] gatt.refresh() (hidden)
D  13:52:10.627   [DFU] gatt.disconnect()
D  13:52:10.643   [DFU] gatt.close()
D  13:52:10.655   [DFU] wait(600)
D  13:52:10.672   [DFU] [Broadcast] Action received: android.bluetooth.device.action.ACL_DISCONNECTED

I have tried using iOS device but on it I am also getting error
what am I doing wrong? What I have missed?

[Hung Bui]

Hi again Igor, 

You may want to test using the _debug version of the bootloader. The original version has flash size restriction that won't allow you to add logging. 

[KTM]

Hi

I have tried the same thing that you suggested with debug version and able to observe logs. (BTW I replaced libnrf_cc310_bl_0.9.13 from original to the nRF5_SDK_17.1.0_ddde560\nRF5_SDK_17.1.0_ddde560\external\nrf_cc310_bl\lib\cortex-m4\hard-float\no-interrupts\ library since i use IAR 8 and hit wchar error on linkage).

Here is a device side Log (From RTT):

<debug> nrf_dfu_settings: Erasing old settings at: 0x000FF000

<debug> nrf_dfu_flash: nrf_fstorage_erase(addr=0x0x000FF000, len=1 pages), queue usage: 0

<debug> nrf_dfu_flash: Flash erase success: addr=0x000FF000, pending 0

<debug> nrf_dfu_flash: nrf_fstorage_write(addr=0x000FF000, src=0x2000A298, len=896 bytes), queue usage: 1

<debug> nrf_dfu_flash: Flash write success: addr=0x000FF000, pending 0

<info> nrf_dfu_settings: Backing up settings page to address 0xFE000.

<debug> nrf_dfu_settings: Writing settings...

<debug> nrf_dfu_settings: Erasing old settings at: 0x000FE000

<debug> nrf_dfu_flash: nrf_fstorage_erase(addr=0x0x000FE000, len=1 pages), queue usage: 1

<debug> nrf_dfu_flash: Flash erase success: addr=0x000FE000, pending 0

<debug> nrf_dfu_flash: nrf_fstorage_write(addr=0x000FE000, src=0x20005A1C, len=896 bytes), queue usage: 1

<debug> nrf_dfu_flash: Flash write success: addr=0x000FE000, pending 0

<debug> app: Enter nrf_bootloader_fw_activate

<info> app: No firmware to activate.

<info> app: Boot validation failed. No valid app to boot.

<debug> app: DFU mode because app is not valid.

<info> nrf_bootloader_wdt: WDT is not enabled

<debug> app: in weak nrf_dfu_init_user

<debug> app: timer_stop (0x20005978)

<debug> app: timer_activate (0x20005978)

<info> app: Entering DFU mode.

<debug> app: Initializing transports (found: 1)

<debug> nrf_dfu_ble: Initializing BLE DFU transport

<debug> nrf_dfu_ble: Setting up vector table: 0x000F1000

<debug> nrf_dfu_ble: Enabling SoftDevice.

<debug> nrf_dfu_ble: Configuring BLE stack.

<debug> nrf_dfu_ble: Enabling the BLE stack.

<debug> nrf_dfu_ble: No advertising name found

<debug> nrf_dfu_ble: Using default advertising name

<debug> nrf_dfu_ble: Advertising...

<debug> nrf_dfu_ble: BLE DFU transport initialized.

<debug> nrf_dfu_flash: Initializing nrf_fstorage_sd backend.

<debug> app: Enter main loop

<debug> nrf_dfu_ble: Connected

<debug> nrf_dfu_ble: Received BLE_GAP_EVT_CONN_PARAM_UPDATE

<debug> nrf_dfu_ble: max_conn_interval: 12

<debug> nrf_dfu_ble: min_conn_interval: 12

<debug> nrf_dfu_ble: slave_latency: 0

<debug> nrf_dfu_ble: conn_sup_timeout: 600

<debug> nrf_dfu_ble: Received BLE_GAP_EVT_CONN_PARAM_UPDATE

<debug> nrf_dfu_ble: max_conn_interval: 6

<debug> nrf_dfu_ble: min_conn_interval: 6

<debug> nrf_dfu_ble: slave_latency: 0

<debug> nrf_dfu_ble: conn_sup_timeout: 500

<debug> nrf_dfu_ble: Received BLE_GAP_EVT_CONN_PARAM_UPDATE

<debug> nrf_dfu_ble: max_conn_interval: 12

<debug> nrf_dfu_ble: min_conn_interval: 12

<debug> nrf_dfu_ble: slave_latency: 0

<debug> nrf_dfu_ble: conn_sup_timeout: 600

<debug> nrf_dfu_ble: Received BLE_GATTS_EVT_EXCHANGE_MTU_REQUEST (request: 517, reply: 247).

<debug> nrf_dfu_ble: Received BLE_GAP_EVT_DATA_LENGTH_UPDATE_REQUEST.

<debug> nrf_dfu_ble: Received BLE_GAP_EVT_DATA_LENGTH_UPDATE (27, max_rx_time 2120).

<debug> nrf_dfu_req_handler: Handle NRF_DFU_OP_OBJECT_SELECT (command)

<debug> nrf_dfu_req_handler: Request handling complete. Result: 0x1

<debug> nrf_dfu_ble: Set receipt notif

<debug> nrf_dfu_req_handler: Handle NRF_DFU_OP_RECEIPT_NOTIF_SET

<debug> nrf_dfu_req_handler: Request handling complete. Result: 0x1

<debug> app: Shutting down transports (found: 1)

<debug> nrf_dfu_req_handler: Handle NRF_DFU_OP_OBJECT_CREATE (command)

<debug> app: timer_stop (0x20005978)

<debug> app: timer_activate (0x20005978)

<debug> nrf_dfu_req_handler: Request handling complete. Result: 0x1

<debug> nrf_dfu_ble: Buffer 0x20006EC4 acquired, len 141 (244)

<debug> nrf_dfu_req_handler: Handle NRF_DFU_OP_OBJECT_WRITE (command)

<debug> nrf_dfu_ble: Freeing buffer 0x20006EC4

<debug> nrf_dfu_req_handler: Request handling complete. Result: 0x1

<debug> nrf_dfu_req_handler: Handle NRF_DFU_OP_CRC_GET (command)

<debug> nrf_dfu_req_handler: Request handling complete. Result: 0x1

Here is a log from Android device:

DFU, 2022-08-18
DFU (EA:A8:49:2F:C2:3B)
V 11:01:57.503 [DFU] DFU service started
V 11:01:57.515 [DFU] Opening file...
I 11:01:57.527 [DFU] Firmware file opened successfully
V 11:01:57.540 [DFU] Connecting to DFU target...
D 11:01:57.563 [DFU] gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE, preferredPhy = LE_1M | LE_2M)
I 11:01:57.574 [DFU] Connected to EA:A8:49:2F:C2:3B
V 11:01:57.588 [DFU] Discovering services...
D 11:01:57.599 [DFU] gatt.discoverServices()
D 11:01:57.628 [DFU] [Broadcast] Action received: android.bluetooth.device.action.ACL_CONNECTED
I 11:01:58.137 [DFU] Services discovered
D 11:01:58.151 [DFU] wait(1000)
V 11:01:59.149 [DFU] Requesting new MTU...
D 11:01:59.166 [DFU] gatt.requestMtu(517)
I 11:01:59.183 [DFU] MTU changed to: 247
V 11:01:59.196 [DFU] Enabling notifications for 8ec90001-f315-4f60-9fb8-838830daea50
D 11:01:59.210 [DFU] gatt.setCharacteristicNotification(8ec90001-f315-4f60-9fb8-838830daea50, true)
D 11:01:59.230 [DFU] gatt.writeDescriptor(00002902-0000-1000-8000-00805f9b34fb, value=0x01-00)
I 11:01:59.254 [DFU] Data written to descr.8ec90001-f315-4f60-9fb8-838830daea50, value (0x): 01-00
V 11:01:59.272 [DFU] Notifications enabled for 8ec90001-f315-4f60-9fb8-838830daea50
A 11:01:59.297 [DFU] Notifications enabled
D 11:01:59.321 [DFU] wait(1000)
V 11:02:00.229 [DFU] Writing to characteristic 8ec90001-f315-4f60-9fb8-838830daea50
D 11:02:00.260 [DFU] gatt.writeCharacteristic(8ec90001-f315-4f60-9fb8-838830daea50)
I 11:02:00.295 [DFU] Data written to 8ec90001-f315-4f60-9fb8-838830daea50, value (0x): 06-01
I 11:02:00.310 [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
A 11:02:00.323 [DFU] Command object info received (Max size = 512, Offset = 0, CRC = 00000000)
V 11:02:00.335 [DFU] Writing to characteristic 8ec90001-f315-4f60-9fb8-838830daea50
D 11:02:00.349 [DFU] gatt.writeCharacteristic(8ec90001-f315-4f60-9fb8-838830daea50)
I 11:02:00.364 [DFU] Data written to 8ec90001-f315-4f60-9fb8-838830daea50, value (0x): 02-00-00
I 11:02:00.377 [DFU] Notification received from 8ec90001-f315-4f60-9fb8-838830daea50, value (0x): 60-02-01
A 11:02:00.389 [DFU] Packet Receipt Notif disabled (Op Code = 2, Value = 0)
V 11:02:00.407 [DFU] Writing to characteristic 8ec90001-f315-4f60-9fb8-838830daea50
D 11:02:00.417 [DFU] gatt.writeCharacteristic(8ec90001-f315-4f60-9fb8-838830daea50)
I 11:02:00.427 [DFU] Data written to 8ec90001-f315-4f60-9fb8-838830daea50, value (0x): 01-01-8D-00-00-00
I 11:02:00.441 [DFU] Notification received from 8ec90001-f315-4f60-9fb8-838830daea50, value (0x): 60-01-01
A 11:02:00.455 [DFU] Command object created
V 11:02:00.465 [DFU] Writing to characteristic 8ec90002-f315-4f60-9fb8-838830daea50
D 11:02:00.476 [DFU] gatt.writeCharacteristic(8ec90002-f315-4f60-9fb8-838830daea50)
I 11:02:00.489 [DFU] Data written to 8ec90002-f315-4f60-9fb8-838830daea50, value (0x): 12-8A-01-0A-44-08-01-12-40-08-01-10-34-1A-02-80-02-20-00-28-00-30-00-38-C0-FD-0A-42-24-08-03-12-20-65-95-01-D4-F3-65-15-EE-7C-FA-68-C0-E7-A5-69-6C-3E-88-27-CF-7C-69-1C-E8-81-88-66-53-73-A8-CB-79-48-00-52-04-08-01-12-00-10-00-1A-40-69-A8-18-D9-AC-65-70-45-CD-81-20-7D-63-23-17-5A-9D-2E-50-13-F6-A3-64-AF-B9-A6-49-CA-59-F1-1D-B0-EC-5A-C0-6E-91-F3-FB-78-44-80-DA-57-F5-EA-45-83-90-E5-0F-14-DD-A4-9F-B3-76-14-FE-DE-0E-93-73-9B
A 11:02:00.502 [DFU] Command object sent (CRC = 7BE3B6A8)
V 11:02:00.514 [DFU] Writing to characteristic 8ec90001-f315-4f60-9fb8-838830daea50
D 11:02:00.525 [DFU] gatt.writeCharacteristic(8ec90001-f315-4f60-9fb8-838830daea50)
I 11:02:00.536 [DFU] Data written to 8ec90001-f315-4f60-9fb8-838830daea50, value (0x): 03
I 11:02:00.551 [DFU] Notification received from 8ec90001-f315-4f60-9fb8-838830daea50, value (0x): 60-03-01-8D-00-00-00-A8-B6-E3-7B
A 11:02:00.563 [DFU] Checksum received (Offset = 141, CRC = 7BE3B6A8)
V 11:02:00.575 [DFU] Writing to characteristic 8ec90001-f315-4f60-9fb8-838830daea50
D 11:02:00.585 [DFU] gatt.writeCharacteristic(8ec90001-f315-4f60-9fb8-838830daea50)
E 11:02:06.445 [DFU] Error (0x85): GATT ERROR
V 11:02:06.474 [DFU] Disconnecting...
D 11:02:06.495 [DFU] gatt.disconnect()
I 11:02:06.506 [DFU] Disconnected
D 11:02:06.518 [DFU] gatt.refresh() (hidden)
D 11:02:06.531 [DFU] gatt.disconnect()
D 11:02:06.542 [DFU] gatt.close()
D 11:02:06.565 [DFU] wait(600)
D 11:02:06.577 [DFU] [Broadcast] Action received: android.bluetooth.device.action.ACL_DISCONNECTED

[KTM]

and here is an air trace (btt file) that is related to the my today's reply (logs from device and Android phone)dfu.btt

[KTM]

I continued a debug and finally managed to upload through a DFU an application...The problem was that i used libnrf_cc310_bl_0.9.13 from no-interrupts folder and used the following command line:

nrfutil pkg generate --hw-version 52 --application-version 1 --application ble_app_uart_pca10040_s132.hex --sd-req 0x101 --key-file private.key oxitone_dfu_package.zip

While the correct command is:

nrfutil pkg generate --hw-version 52 --application-version 1 --application ble_app_uart_pca10040_s132.hex --sd-req 0x100 --key-file private.key oxitone_dfu_package.zip

However still have a problem.

After a download an application is not running since probably SD is erased - i read a memory through NRF programmer and SD does not appear to be there at all...

Does above command line generates an application package only ?

[Hung Bui]

Hi Igor, 
Thanks for the information and the sniffer trace. 
From what I can see in the log and the trace, I suspect that the bootloader crashed at some point right after the execute command (0x04) from the central when the init packet is sent. You can see the sequence here: 
https://infocenter.nordicsemi.com/topic/sdk_nrf5_v17.1.0/lib_dfu_transport_ble.html?cp=8_1_3_5_2_2_3_0#lib_dfu_transport_msc_init

In the sniffer trace you can see that there was no response after the command (0x04) : 

Because there was no response after the write request, you receives a GATT ERROR. 

What you can do is to check if the same problem can be reproduced on the stock bootloader example. Please try to test without the application, only softdevice  + bootloader. 

Do you use WDT in your application ? If you do have there could be a chance that the WDT was not handled properly in the bootloader and cause a reset. 

If you can reproduce the issue on an unmodified bootloader (test without application ) we can test here and check if there is any problem with it. Please also do a cross check with the unmodified bootloader from SDK v17.0 .