This post is older than 2 years and might not be relevant anymore
More Info: Consider searching for newer posts

Android Secure DFU and bonds

We've been having issues getting DFU to complete consistently with Android devices when using a two-step DFU package (BL+SD and App). Some devices seem to have far less trouble than others. The newer Samsung devices tend to work pretty reliably for us, but Pixel devices are particularly bad.
We initate DFU through the DfuServiceInitiator and setKeepBond(true) and are using the SecureDfu implementation.
On all devices we tend to see pretty regular errors: DEVICE DISCONNECTED, GATT INVALID HANDLE, GATT WRITE NOT PERMIT. Often, retrying a couple of times will fix the problem but on the Pixel devices the GATT WRITE NOT PERMIT does not resolve itself. The only way we've been able to successfully fix it is to call the BluetoothDevice.removeBond() function via reflection.
After removing the bond we can pretty consistently initate the DFU of the bootloader. As the device switches from bootloader over to app we often start seeing the GATT WRITE NOT PERMIT errors again. If we removeBonds again
then we are able to successfully complete the DFU.
We also tried forcing a BluetoothGatt.refresh() (through reflection) to see if that resolved the issue but we didn't see any improved behavior. The only thing that lets us successfully DFU is removeBond().
How can we avoid removing the bonds every time we DFU?
We are using DFU library 1.7, and the issue happened with 1.6 as well. We notice that the latest nRF Connect app seems much more stable (often completes with clean logs), is it based on a newer library?
On the firmware side, we see this issue with SDK14 and SDK15, secure buttonless bootloader, with supports-bonds in app, and requires-bonds in bootloader.
Thanks,
Brian
Parents
  • Hi Brian, 

    I suspect it may have something to do with the Service Changed characteristic. First, both the application and the bootloader need to have this characteristic enabled (check sdk_config.h ). Second, the service changed indication should be sent by the application when the GATT attributable table changed. And then the phone should follow the spec to do a service discovery after that to update the attribute table cache. 

    If it's failed to do so, and when there is a command to write to a characteristic (which is not exist in the older attributable , or doesn't support write), the phone will throw GATT WRITE NOT PERMIT.

    I would need to see a sniffer trace to be able to tell if it's actually the case with your setup. 

  • Hi Hung Bui,

    Thank you for the reply. Does the Android application need to receive the service changed indication and do a service discovery, or should that be handled for us in the Nordic DFU library by way of the configuration of the DfuServiceInitiator?

    Regarding the sniffer trace, I will capture one hopefully today.

    Meanwhile, yes we are setting the service changed notification in firmware: here is some firmware log output from the bootloader from a successful DFU, which includes the service changed logs.

    <debug> app: In nrf_bootloader_init
    <debug> app: in weak nrf_dfu_init_user
    <debug> app: In real nrf_dfu_init
    <debug> nrf_dfu_settings: Running nrf_dfu_settings_init(sd_irq_initialized=false).
    <debug> nrf_dfu_flash: Calling nrf_dfu_flash_init(sd_irq_initialized=false)...
    <debug> nrf_dfu_flash: Initializing nrf_fstorage_nvmc backend.
    <debug> app: Initializing the clock.
    <debug> app: Enter nrf_dfu_continue
    <debug> app: Valid App
    <debug> app: Application sent bootloader request
    <debug> app: In nrf_dfu_transports_init
    <debug> app: num transports: 1
    <debug> app: Initializing BLE DFU transport
    <debug> app: Copying peer data
    <debug> app: vector table: 0x00073000
    <debug> app: vector table: 0x00073000
    <debug> app: Error code - sd_softdevice_vector_table_base_set: 0x00000000
    <debug> app: Running Service Changed config
    <debug> app: Finished running Service Changed config
    <debug> app: Enabling SoftDevice.
    <debug> app: SoftDevice enabled.
    <debug> app: Regular adv name
    <debug> app: ##### Setting adv with peer data ####
    <debug> app: ##### IRK Found. Setting whitelist ####
    <debug> app: Finished initializing BLE DFU transport
    <debug> app: After nrf_dfu_transports_init
    <debug> nrf_dfu_flash: Calling nrf_dfu_flash_init(sd_irq_initialized=true)...
    <debug> nrf_dfu_flash: Initializing nrf_fstorage_sd backend.
    <debug> app: Waiting for events
    <debug> app: PHY update request.
    <debug> app: == conn sec update request
    <debug> app: Sending Service Changed indication
    <debug> app: == We are finished handling conn sec update
    <debug> app: Service Changed was handled
    <debug> app: Received: BLE_GAP_EVT_CONN_PARAM_UPDATE
    <debug> app: conn_sup_timeout: 2000max_conn_interval: 6
    min_conn_interval: 6
    slave_latency 0
    <debug> app: Received: BLE_GAP_EVT_CONN_PARAM_UPDATE
    <debug> app: conn_sup_timeout: 2000
    max_conn_interval: 39
    min_conn_interval: 39
    slave_latency 0
    <debug> app: Received select object
    <info> bl_dfu_req_handling: Valid Command: NRF_DFU_OBJECT_OP_SELECT
    <debug> app: Sending Object Info: [0x60, 0x06, 0x01 max: 0:x00000100 0:x00000000, CRC:0x00000000]
    <debug> app: Set receipt notif
    <debug> app: Sending Response: [0x2, 0x1]
    <debug> app: Received create object
    <info> bl_dfu_req_handling: Before OP create command
    <info> bl_dfu_req_handling: Valid Command Create
    <debug> app: Sending Response: [0x1, 0x1]
    <info> bl_dfu_req_handling: Before OP write command
    <info> bl_dfu_req_handling: Before OP write command
    <info> bl_dfu_req_handling: Before OP write command
    <info> bl_dfu_req_handling: Before OP write command
    <info> bl_dfu_req_handling: Before OP write command
    <info> bl_dfu_req_handling: Before OP write command
    <info> bl_dfu_req_handling: Before OP write command
    <debug> app: Received calculate CRC
    <info> bl_dfu_req_handling: Valid Command CRC
    <debug> app: Sending CRC: [0x60, 0x03, 0x01, 0:x00000089, CRC:0x2C2E0880]
    <debug> app: Received execute object
    <info> bl_dfu_req_handling: Before OP execute command
    <info> bl_dfu_req_handling: Valid command execute
    <info> bl_dfu_req_handling: PB: Init packet data len: 60
    <info> bl_dfu_req_handling: Handling signed command
    <info> bl_dfu_req_handling: Req version: 4, Expected: 4
    <info> bl_dfu_req_handling: Skipping DFU version validations
    <info> bl_dfu_req_handling: Calculating init packet hash
    <info> bl_dfu_req_handling: Verify signature
    <info> bl_dfu_req_handling: Image verified
    <info> bl_dfu_req_handling: Running hash check
    <debug> app: Enter nrf_dfu_find_cache
    <debug> app: Bank content
    <debug> app: Bank type: 0
    <debug> app: Bank 0 code: 0x01: Size: 126860
    <debug> app: Bank 1 code: 0x00: Size: 0
    <debug> app: free_size before bank select: 311296
    <debug> app: free_size: 184320, size_req: 176432
    <debug> app: Using second bank
    <info> bl_dfu_req_handling: Write address set to 0x00042000
    <info> bl_dfu_req_handling: DFU prevalidate SUCCESSFUL!
    <info> bl_dfu_req_handling: Prevalidate OK.
    <info> bl_dfu_req_handling: Saving init command...
    <debug> nrf_dfu_settings: Writing settings...
    <debug> nrf_dfu_settings: Erasing old settings at: 0x0007F000
    <debug> nrf_dfu_flash: nrf_fstorage_erase(addr=0x0x0007F000, len=1 pages), queue usage: 1
    <debug> nrf_dfu_flash: nrf_fstorage_write(addr=0x0007F000, len=0x1B8 bytes), queue usage: 2
    <info> bl_dfu_req_handling: Setting DFU flag to initialized
    <debug> app: Sending Response: [0x4, 0x1]
    <debug> app: Received select object
    <info> bl_dfu_req_handling: Valid Data Read info
    <debug> app: Sending Object Info: [0x60, 0x06, 0x01 max: 0:x00001000 0:x00000000, CRC:0x00000000]
    <debug> nrf_dfu_flash: Flash erase success: addr=0x0007F000, pending 1
    <debug> nrf_dfu_flash: Flash write success: addr=0x0007F000, pending 0
    <debug> app: Received create object

  • Regarding sniffer trace, since the connection is encrypted will I see the services changed exchange at all? I'm not sure what to look for to post a useful capture. I do believe the services changed is happening from looking at firmware logs.

    ** Perhaps there is a timing issue on some Android devices?

    Below is a log from nRF Connect 4.20.2 on Android Pixel XL for a DFU that failed to start (two tries). Firmware is SDK14.2 with SD 5.0. The device shows bonded in BlueTooth settings. DFU settings: pkt rcpt notification on, # of packets 10, keep bond info on, mbr size 4096. DFU package has all components for that log, but an app-only package has the same results.

    ** Our Android app deletes and re-pairs/bonds after  GATT WRITE NOT PERMIT, but we think this is not a good solution, and it can sometimes take 15 minutes of retries to complete the full DFU.

    nRF Connect, 2018-09-24
    OsRiAp8j (E3:9F:02:62:C4:3A)
    V 16:28:15.830 Connecting to E3:9F:02:62:C4:3A...
    D 16:28:15.830 gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE, preferred PHY = LE 1M)
    D 16:28:17.433 [Broadcast] Action received: android.bluetooth.device.action.ACL_CONNECTED
    D 16:28:17.433 [Callback] Connection state changed with status: 0 and new state: CONNECTED (2)
    I 16:28:17.433 Connected to E3:9F:02:62:C4:3A
    D 16:28:17.460 wait(1600ms)
    V 16:28:19.063 Discovering services...
    D 16:28:19.064 gatt.discoverServices()
    D 16:28:19.091 [Callback] Services discovered with status: 0
    I 16:28:19.091 Services discovered
    V 16:28:19.123 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)
    Secure DFU Service (0xFE59)
    - DFU Packet [WNR] (8ec90002-f315-4f60-9fb8-838830daea50)
    - DFU Control Point [N W] (8ec90001-f315-4f60-9fb8-838830daea50)
       Client Characteristic Configuration (0x2902)
    D 16:28:19.123 gatt.setCharacteristicNotification(00002a05-0000-1000-8000-00805f9b34fb, true)
    D 16:28:19.128 gatt.setCharacteristicNotification(8ec90001-f315-4f60-9fb8-838830daea50, true)
    I 16:28:22.555 Connection parameters updated (interval: 60.0ms, latency: 30, timeout: 6000ms)
    V 16:28:26.245 [DFU] DFU service started
    V 16:28:26.245 [DFU] Opening file...
    I 16:28:26.264 [DFU] Firmware file opened successfully
    V 16:28:26.264 [DFU] Connecting to DFU target...
    D 16:28:26.268 [DFU] gatt = device.connectGatt(autoConnect = false)
    I 16:28:26.272 [DFU] Connected to E3:9F:02:62:C4:3A
    D 16:28:26.274 [DFU] wait(1600)
    V 16:28:27.876 [DFU] Discovering services...
    D 16:28:27.876 [DFU] gatt.discoverServices()
    I 16:28:27.888 [DFU] Services discovered
    W 16:28:27.890 [DFU] Sending system components
    V 16:28:27.892 [DFU] Reading Service Changed CCCD value...
    D 16:28:27.892 [DFU] gatt.readDescriptor(00002902-0000-1000-8000-00805f9b34fb)
    I 16:28:30.163 [DFU] Read Response received from descr.00002a05-0000-1000-8000-00805f9b34fb, value (0x): 02-00
    A 16:28:30.164 [DFU] Service Changed indications enabled
    D 16:28:30.202 [DFU] wait(1000)
    V 16:28:31.187 [DFU] Requesting new MTU...
    D 16:28:31.187 [DFU] gatt.requestMtu(517)
    I 16:28:34.069 [DFU] MTU changed to: 23
    V 16:28:34.070 [DFU] Enabling notifications for 8ec90001-f315-4f60-9fb8-838830daea50
    D 16:28:34.070 [DFU] gatt.setCharacteristicNotification(8ec90001-f315-4f60-9fb8-838830daea50, true)
    D 16:28:34.074 [DFU] gatt.writeDescriptor(00002902-0000-1000-8000-00805f9b34fb, value=0x01-00)
    E 16:28:36.165 [DFU] Error (0x03): GATT WRITE NOT PERMIT
    V 16:28:36.165 [DFU] Disconnecting...
    D 16:28:36.206 [DFU] gatt.disconnect()
    I 16:28:36.210 [DFU] Disconnected
    D 16:28:36.212 [DFU] gatt.close()
    D 16:28:36.216 [DFU] wait(600)
    V 16:28:50.873 [DFU] DFU service started
    V 16:28:50.873 [DFU] Opening file...
    I 16:28:50.889 [DFU] Firmware file opened successfully
    V 16:28:50.889 [DFU] Connecting to DFU target...
    D 16:28:50.890 [DFU] gatt = device.connectGatt(autoConnect = false)
    I 16:28:50.893 [DFU] Connected to E3:9F:02:62:C4:3A
    D 16:28:50.894 [DFU] wait(1600)
    V 16:28:52.495 [DFU] Discovering services...
    D 16:28:52.495 [DFU] gatt.discoverServices()
    I 16:28:52.505 [DFU] Services discovered
    W 16:28:52.507 [DFU] Sending system components
    V 16:28:52.511 [DFU] Reading Service Changed CCCD value...
    D 16:28:52.511 [DFU] gatt.readDescriptor(00002902-0000-1000-8000-00805f9b34fb)
    I 16:28:54.947 [DFU] Read Response received from descr.00002a05-0000-1000-8000-00805f9b34fb, value (0x): 02-00
    A 16:28:54.948 [DFU] Service Changed indications enabled
    D 16:28:54.972 [DFU] wait(1000)
    V 16:28:55.972 [DFU] Requesting new MTU...
    D 16:28:55.972 [DFU] gatt.requestMtu(517)
    V 16:28:58.901 [DFU] Enabling notifications for 8ec90001-f315-4f60-9fb8-838830daea50
    D 16:28:58.901 [DFU] gatt.setCharacteristicNotification(8ec90001-f315-4f60-9fb8-838830daea50, true)
    D 16:28:58.904 [DFU] gatt.writeDescriptor(00002902-0000-1000-8000-00805f9b34fb, value=0x01-00)
    E 16:28:59.022 [DFU] Error (0x03): GATT WRITE NOT PERMIT
    V 16:28:59.023 [DFU] Disconnecting...
    D 16:28:59.052 [DFU] gatt.disconnect()
    I 16:28:59.053 [DFU] Disconnected
    D 16:28:59.053 [DFU] gatt.close()
    D 16:28:59.053 [DFU] wait(600)

Reply
  • Regarding sniffer trace, since the connection is encrypted will I see the services changed exchange at all? I'm not sure what to look for to post a useful capture. I do believe the services changed is happening from looking at firmware logs.

    ** Perhaps there is a timing issue on some Android devices?

    Below is a log from nRF Connect 4.20.2 on Android Pixel XL for a DFU that failed to start (two tries). Firmware is SDK14.2 with SD 5.0. The device shows bonded in BlueTooth settings. DFU settings: pkt rcpt notification on, # of packets 10, keep bond info on, mbr size 4096. DFU package has all components for that log, but an app-only package has the same results.

    ** Our Android app deletes and re-pairs/bonds after  GATT WRITE NOT PERMIT, but we think this is not a good solution, and it can sometimes take 15 minutes of retries to complete the full DFU.

    nRF Connect, 2018-09-24
    OsRiAp8j (E3:9F:02:62:C4:3A)
    V 16:28:15.830 Connecting to E3:9F:02:62:C4:3A...
    D 16:28:15.830 gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE, preferred PHY = LE 1M)
    D 16:28:17.433 [Broadcast] Action received: android.bluetooth.device.action.ACL_CONNECTED
    D 16:28:17.433 [Callback] Connection state changed with status: 0 and new state: CONNECTED (2)
    I 16:28:17.433 Connected to E3:9F:02:62:C4:3A
    D 16:28:17.460 wait(1600ms)
    V 16:28:19.063 Discovering services...
    D 16:28:19.064 gatt.discoverServices()
    D 16:28:19.091 [Callback] Services discovered with status: 0
    I 16:28:19.091 Services discovered
    V 16:28:19.123 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)
    Secure DFU Service (0xFE59)
    - DFU Packet [WNR] (8ec90002-f315-4f60-9fb8-838830daea50)
    - DFU Control Point [N W] (8ec90001-f315-4f60-9fb8-838830daea50)
       Client Characteristic Configuration (0x2902)
    D 16:28:19.123 gatt.setCharacteristicNotification(00002a05-0000-1000-8000-00805f9b34fb, true)
    D 16:28:19.128 gatt.setCharacteristicNotification(8ec90001-f315-4f60-9fb8-838830daea50, true)
    I 16:28:22.555 Connection parameters updated (interval: 60.0ms, latency: 30, timeout: 6000ms)
    V 16:28:26.245 [DFU] DFU service started
    V 16:28:26.245 [DFU] Opening file...
    I 16:28:26.264 [DFU] Firmware file opened successfully
    V 16:28:26.264 [DFU] Connecting to DFU target...
    D 16:28:26.268 [DFU] gatt = device.connectGatt(autoConnect = false)
    I 16:28:26.272 [DFU] Connected to E3:9F:02:62:C4:3A
    D 16:28:26.274 [DFU] wait(1600)
    V 16:28:27.876 [DFU] Discovering services...
    D 16:28:27.876 [DFU] gatt.discoverServices()
    I 16:28:27.888 [DFU] Services discovered
    W 16:28:27.890 [DFU] Sending system components
    V 16:28:27.892 [DFU] Reading Service Changed CCCD value...
    D 16:28:27.892 [DFU] gatt.readDescriptor(00002902-0000-1000-8000-00805f9b34fb)
    I 16:28:30.163 [DFU] Read Response received from descr.00002a05-0000-1000-8000-00805f9b34fb, value (0x): 02-00
    A 16:28:30.164 [DFU] Service Changed indications enabled
    D 16:28:30.202 [DFU] wait(1000)
    V 16:28:31.187 [DFU] Requesting new MTU...
    D 16:28:31.187 [DFU] gatt.requestMtu(517)
    I 16:28:34.069 [DFU] MTU changed to: 23
    V 16:28:34.070 [DFU] Enabling notifications for 8ec90001-f315-4f60-9fb8-838830daea50
    D 16:28:34.070 [DFU] gatt.setCharacteristicNotification(8ec90001-f315-4f60-9fb8-838830daea50, true)
    D 16:28:34.074 [DFU] gatt.writeDescriptor(00002902-0000-1000-8000-00805f9b34fb, value=0x01-00)
    E 16:28:36.165 [DFU] Error (0x03): GATT WRITE NOT PERMIT
    V 16:28:36.165 [DFU] Disconnecting...
    D 16:28:36.206 [DFU] gatt.disconnect()
    I 16:28:36.210 [DFU] Disconnected
    D 16:28:36.212 [DFU] gatt.close()
    D 16:28:36.216 [DFU] wait(600)
    V 16:28:50.873 [DFU] DFU service started
    V 16:28:50.873 [DFU] Opening file...
    I 16:28:50.889 [DFU] Firmware file opened successfully
    V 16:28:50.889 [DFU] Connecting to DFU target...
    D 16:28:50.890 [DFU] gatt = device.connectGatt(autoConnect = false)
    I 16:28:50.893 [DFU] Connected to E3:9F:02:62:C4:3A
    D 16:28:50.894 [DFU] wait(1600)
    V 16:28:52.495 [DFU] Discovering services...
    D 16:28:52.495 [DFU] gatt.discoverServices()
    I 16:28:52.505 [DFU] Services discovered
    W 16:28:52.507 [DFU] Sending system components
    V 16:28:52.511 [DFU] Reading Service Changed CCCD value...
    D 16:28:52.511 [DFU] gatt.readDescriptor(00002902-0000-1000-8000-00805f9b34fb)
    I 16:28:54.947 [DFU] Read Response received from descr.00002a05-0000-1000-8000-00805f9b34fb, value (0x): 02-00
    A 16:28:54.948 [DFU] Service Changed indications enabled
    D 16:28:54.972 [DFU] wait(1000)
    V 16:28:55.972 [DFU] Requesting new MTU...
    D 16:28:55.972 [DFU] gatt.requestMtu(517)
    V 16:28:58.901 [DFU] Enabling notifications for 8ec90001-f315-4f60-9fb8-838830daea50
    D 16:28:58.901 [DFU] gatt.setCharacteristicNotification(8ec90001-f315-4f60-9fb8-838830daea50, true)
    D 16:28:58.904 [DFU] gatt.writeDescriptor(00002902-0000-1000-8000-00805f9b34fb, value=0x01-00)
    E 16:28:59.022 [DFU] Error (0x03): GATT WRITE NOT PERMIT
    V 16:28:59.023 [DFU] Disconnecting...
    D 16:28:59.052 [DFU] gatt.disconnect()
    I 16:28:59.053 [DFU] Disconnected
    D 16:28:59.053 [DFU] gatt.close()
    D 16:28:59.053 [DFU] wait(600)

Children
No Data
Related