DFU errors (DFU_DEVICE_DISCONNECTED, REMOTE_DFU_OPERATION_FAILED)

[andrey_kin]

With a NRF51802 based product, we see DFU errors on Android devices in the field.

Our config is:
- nrf51802 with s130_nrf51_2.0.1_softdevice and nRF5_SDK_11.0.0_89a8197.
- external 16 MHz xtal and use the internal RC oscillator for the LFCLK source.
    #define NRF_CLOCK_LFCLKSRC_RC      {.source        = NRF_CLOCK_LF_SRC_RC, .rc_ctiv = 16, .rc_temp_ctiv = 2, .xtal_accuracy = NRF_CLOCK_LF_XTAL_ACCURACY_20_PPM}

- Connection intervals:
    In the Application: Min = 7.5ms, Max = 1000ms
    In the DFU: Min = 15ms,  Max = 30ms

- mobile app with nordic DFU library 1.3.0 integrated.



In the field we see: 4096 DFU DEVICE DISCONNECTED and 9198 REMOTE DFU OPERATION FAILED errors.
Most affected devices so far are Samsung Galaxy S7 (SM-G930V, SM-G930A), Samsung Galaxy S7 Edge (SM-G935A). But there are some Motorola and LG phones affected by this issue as well.

Day 1:
We've been able to reproduce issue in a lab using (set #1)[Samsung Galaxy S6 Edge (Android OS 6.0.1, SAMSUNG-SM-G925A) + device (NRF51802 based) + nRF Toolbox ver.2.6.0 app] .
This set consistently fails to do DFU reporting error 4096 DFU DEVICE DISCONNECTED. Seems like it's related to android BLE GATT error 0x85 (133).
It worth to mention that we don't have any issues in a lab doing DFU update  with (set #2)[the same device (NRF51802 based) + another android phone (Samsung Galaxy S7 (Android OS 6.0.1, SAMSUNG-SM-G930A)) + nRF Toolbox ver.2.6.0 app].

Day 2:
Today set #1 works just fine.
But set #2 consistently fails to do DFU with DFU_DEVICE_DISCONNECTED error.

 
Given that we see this errors using reference nordic nRF Toolbox app, I wonder if you saw such behavior on android as well.
Is there anything we can do on our side (mobile software or device firmware, or may be device hardware) to mitigate amount of DFU errors we see in the field (make DFU more robust in general on Android)?
I'm happy to provide any additional info.

After connection params for DFU have been adjusted to 7.5ms, 1000ms Samsung Galaxy S7 still fails to do DFU with DFU_DEVICE_DISCONNECTED error:

04-17 15:17:59.792 12709-12709/no.nordicsemi.android.nrftoolbox I/DfuBaseService: DFU service created. Version: 1.6.1
04-17 15:17:59.832 12709-19362/no.nordicsemi.android.nrftoolbox I/DfuBaseService: Connecting to the device...
04-17 15:17:59.832 12709-19362/no.nordicsemi.android.nrftoolbox D/BluetoothGatt: connect() - device: E3:9E:2B:B0:C7:AD, auto: false
    registerApp()
    registerApp() - UUID=c3fa8631-0f3a-4e3c-bcd3-78ba4ef5d1a0
04-17 15:17:59.882 12709-16151/no.nordicsemi.android.nrftoolbox D/BluetoothGatt: onClientRegistered() - status=0 clientIf=8
04-17 15:18:00.232 12709-12721/no.nordicsemi.android.nrftoolbox D/BluetoothGatt: onClientConnectionState() - status=0 clientIf=8 device=E3:9E:2B:B0:C7:AD
04-17 15:18:00.242 12709-12709/no.nordicsemi.android.nrftoolbox I/DfuBaseService: Action received: android.bluetooth.device.action.ACL_CONNECTED
04-17 15:18:00.252 12709-12721/no.nordicsemi.android.nrftoolbox I/DfuBaseService: Connected to GATT server
04-17 15:18:00.252 12709-12721/no.nordicsemi.android.nrftoolbox D/BluetoothGatt: discoverServices() - device: E3:9E:2B:B0:C7:AD
04-17 15:18:00.262 12709-12721/no.nordicsemi.android.nrftoolbox I/DfuBaseService: Attempting to start service discovery... succeed
04-17 15:18:00.652 12709-12721/no.nordicsemi.android.nrftoolbox D/BluetoothGatt: onClientConnParamsChanged() - Device=E3:9E:2B:B0:C7:AD interval=6 status=0
04-17 15:18:00.992 12709-12721/no.nordicsemi.android.nrftoolbox D/BluetoothGatt: onSearchComplete() = Device=E3:9E:2B:B0:C7:AD Status=0
04-17 15:18:00.992 12709-12721/no.nordicsemi.android.nrftoolbox I/DfuBaseService: Services discovered
04-17 15:18:01.052 12709-13865/no.nordicsemi.android.nrftoolbox D/BluetoothGatt: onClientConnParamsChanged() - Device=E3:9E:2B:B0:C7:AD interval=39 status=0
04-17 15:18:02.012 12709-19362/no.nordicsemi.android.nrftoolbox I/DfuImpl: Reading DFU version number...
04-17 15:18:02.122 12709-19362/no.nordicsemi.android.nrftoolbox I/DfuImpl: Version number read: 0.1 -> Application with Legacy buttonless update from SDK 7.0 or newer
04-17 15:18:02.122 12709-19362/no.nordicsemi.android.nrftoolbox W/DfuImpl: Application with legacy buttonless update found
04-17 15:18:02.122 12709-19362/no.nordicsemi.android.nrftoolbox I/DfuImpl: Enabling notifications...
04-17 15:18:02.122 12709-19362/no.nordicsemi.android.nrftoolbox D/BluetoothGatt: setCharacteristicNotification() - uuid: 00001531-1212-efde-1523-785feabcd123 enable: true
04-17 15:18:03.262 12709-19362/no.nordicsemi.android.nrftoolbox I/DfuImpl: Sending Start DFU command (Op Code = 1, Upload Mode = 4)
04-17 15:18:03.642 12709-14419/no.nordicsemi.android.nrftoolbox D/BluetoothGatt: onClientConnectionState() - status=19 clientIf=8 device=E3:9E:2B:B0:C7:AD
04-17 15:18:03.652 12709-14419/no.nordicsemi.android.nrftoolbox W/DfuBaseService: Target device disconnected with status: 19
04-17 15:18:03.652 12709-19362/no.nordicsemi.android.nrftoolbox D/BluetoothGatt: refresh() - device: E3:9E:2B:B0:C7:AD
04-17 15:18:03.662 12709-19362/no.nordicsemi.android.nrftoolbox I/DfuBaseService: Refreshing result: true
    Cleaning up...
04-17 15:18:03.662 12709-19362/no.nordicsemi.android.nrftoolbox D/BluetoothGatt: close()
    unregisterApp() - mClientIf=8
04-17 15:18:03.662 12709-19362/no.nordicsemi.android.nrftoolbox I/DfuImpl: Starting service that will connect to the DFU bootloader
04-17 15:18:03.682 12709-12709/no.nordicsemi.android.nrftoolbox I/DfuBaseService: Action received: android.bluetooth.device.action.ACL_DISCONNECTED
04-17 15:18:05.762 12709-19362/no.nordicsemi.android.nrftoolbox I/DfuBaseService: Connecting to the device...
04-17 15:18:05.772 12709-19362/no.nordicsemi.android.nrftoolbox D/BluetoothGatt: connect() - device: E3:9E:2B:B0:C7:AD, auto: false
    registerApp()
    registerApp() - UUID=c9c2cacc-44d4-4851-ad65-842e9761ed9c
04-17 15:18:05.822 12709-12721/no.nordicsemi.android.nrftoolbox D/BluetoothGatt: onClientRegistered() - status=0 clientIf=8
04-17 15:18:06.172 12709-13865/no.nordicsemi.android.nrftoolbox D/BluetoothGatt: onClientConnectionState() - status=133 clientIf=8 device=E3:9E:2B:B0:C7:AD
04-17 15:18:06.172 12709-13865/no.nordicsemi.android.nrftoolbox E/DfuBaseService: Connection state change error: 133 newState: 0
04-17 15:18:06.172 12709-19362/no.nordicsemi.android.nrftoolbox E/DfuBaseService: Device not reachable. Check if the device with address E3:9E:2B:B0:C7:AD is in range, is advertising and is connectable
04-17 15:18:06.182 12709-19362/no.nordicsemi.android.nrftoolbox D/BluetoothGatt: refresh() - device: E3:9E:2B:B0:C7:AD
04-17 15:18:06.182 12709-19362/no.nordicsemi.android.nrftoolbox I/DfuBaseService: Refreshing result: true
    Cleaning up...
04-17 15:18:06.182 12709-19362/no.nordicsemi.android.nrftoolbox D/BluetoothGatt: close()
    unregisterApp() - mClientIf=8
04-17 15:18:06.822 12709-12709/no.nordicsemi.android.nrftoolbox D/TextView: setTypeface with style : 0
04-17 15:18:06.862 12709-12709/no.nordicsemi.android.nrftoolbox I/DfuBaseService: DFU service destroyed

[andrey_kin]

Here are logs when DFU_DEVICE_DISCONNECTED error happens:

log #1

04-17 13:56:15.600 12709-12709/no.nordicsemi.android.nrftoolbox D/BluetoothLeScanner: Stop Scan
04-17 13:56:15.790 12709-12709/no.nordicsemi.android.nrftoolbox D/ViewRootImpl: ViewPostImeInputStage processPointer 0
04-17 13:56:16.170 12709-12709/no.nordicsemi.android.nrftoolbox D/ViewRootImpl: ViewPostImeInputStage processPointer 1
04-17 13:56:16.810 12709-12709/no.nordicsemi.android.nrftoolbox D/ViewRootImpl: ViewPostImeInputStage processPointer 0
04-17 13:56:16.890 12709-12709/no.nordicsemi.android.nrftoolbox D/ViewRootImpl: ViewPostImeInputStage processPointer 1
04-17 13:56:16.970 12709-12709/no.nordicsemi.android.nrftoolbox D/ViewRootImpl: #3 mView = null
04-17 13:56:17.010 12709-12709/no.nordicsemi.android.nrftoolbox E/ViewRootImpl: sendUserActionEvent() mView == null
04-17 13:56:17.690 12709-12709/no.nordicsemi.android.nrftoolbox D/ViewRootImpl: ViewPostImeInputStage processPointer 0
04-17 13:56:17.740 12709-12709/no.nordicsemi.android.nrftoolbox D/ViewRootImpl: ViewPostImeInputStage processPointer 1
04-17 13:56:17.780 12709-12709/no.nordicsemi.android.nrftoolbox I/DfuBaseService: DFU service created. Version: 1.6.1
04-17 13:56:17.880 12709-14052/no.nordicsemi.android.nrftoolbox I/DfuBaseService: Connecting to the device...
04-17 13:56:17.890 12709-14052/no.nordicsemi.android.nrftoolbox D/BluetoothGatt: connect() - device: E2:21:7E:59:01:7F, auto: false
    registerApp()
    registerApp() - UUID=d2532aca-a924-4d9d-b27d-98e42f4e05bd
04-17 13:56:17.930 12709-12720/no.nordicsemi.android.nrftoolbox D/BluetoothGatt: onClientRegistered() - status=0 clientIf=9
04-17 13:56:18.720 12709-13865/no.nordicsemi.android.nrftoolbox D/BluetoothGatt: onClientConnectionState() - status=133 clientIf=9 device=E2:21:7E:59:01:7F
04-17 13:56:18.730 12709-13865/no.nordicsemi.android.nrftoolbox E/DfuBaseService: Connection state change error: 133 newState: 0
04-17 13:56:18.730 12709-14052/no.nordicsemi.android.nrftoolbox E/DfuBaseService: Device not reachable. Check if the device with address E2:21:7E:59:01:7F is in range, is advertising and is connectable
04-17 13:56:18.730 12709-14052/no.nordicsemi.android.nrftoolbox D/BluetoothGatt: refresh() - device: E2:21:7E:59:01:7F
04-17 13:56:18.740 12709-14052/no.nordicsemi.android.nrftoolbox I/DfuBaseService: Refreshing result: true
    Cleaning up...
04-17 13:56:18.740 12709-14052/no.nordicsemi.android.nrftoolbox D/BluetoothGatt: close()
    unregisterApp() - mClientIf=9
04-17 13:56:19.390 12709-12709/no.nordicsemi.android.nrftoolbox D/TextView: setTypeface with style : 0
04-17 13:56:19.440 12709-12709/no.nordicsemi.android.nrftoolbox I/DfuBaseService: DFU service destroyed
04-17 13:56:19.450 12709-12709/no.nordicsemi.android.nrftoolbox D/ViewRootImpl: #1 mView = android.widget.LinearLayout{89fcb75 V.E...... ......I. 0,0-0,0}
04-17 13:56:19.500 12709-12709/no.nordicsemi.android.nrftoolbox W/DisplayListCanvas: DisplayListCanvas is started on unbinded RenderNode (without mOwningView)
04-17 13:56:19.530 12709-12866/no.nordicsemi.android.nrftoolbox V/RenderScript: 0x7f82507000 Launching thread(s), CPUs 4
04-17 13:56:19.550 12709-12709/no.nordicsemi.android.nrftoolbox D/ViewRootImpl: MSG_RESIZED_REPORT: ci=Rect(0, 0 - 0, 0) vi=Rect(0, 0 - 0, 0) or=1
04-17 13:56:21.430 12709-12709/no.nordicsemi.android.nrftoolbox D/ViewRootImpl: #3 mView = null

log #2

04-17 13:57:50.020 12709-12709/no.nordicsemi.android.nrftoolbox D/ViewRootImpl: ViewPostImeInputStage processPointer 0
04-17 13:57:50.100 12709-12709/no.nordicsemi.android.nrftoolbox D/ViewRootImpl: ViewPostImeInputStage processPointer 1
04-17 13:57:50.130 12709-12709/no.nordicsemi.android.nrftoolbox I/DfuBaseService: DFU service created. Version: 1.6.1
04-17 13:57:50.190 12709-14177/no.nordicsemi.android.nrftoolbox I/DfuBaseService: Connecting to the device...
04-17 13:57:50.200 12709-14177/no.nordicsemi.android.nrftoolbox D/BluetoothGatt: connect() - device: E2:21:7E:59:01:7F, auto: false
    registerApp()
    registerApp() - UUID=19c13ce2-747a-4f18-a7a6-114766a32ea9
04-17 13:57:50.240 12709-13865/no.nordicsemi.android.nrftoolbox D/BluetoothGatt: onClientRegistered() - status=0 clientIf=9
04-17 13:57:50.520 12709-12721/no.nordicsemi.android.nrftoolbox D/BluetoothGatt: onClientConnectionState() - status=0 clientIf=9 device=E2:21:7E:59:01:7F
04-17 13:57:50.520 12709-12709/no.nordicsemi.android.nrftoolbox I/DfuBaseService: Action received: android.bluetooth.device.action.ACL_CONNECTED
04-17 13:57:50.550 12709-12721/no.nordicsemi.android.nrftoolbox I/DfuBaseService: Connected to GATT server
04-17 13:57:50.550 12709-12721/no.nordicsemi.android.nrftoolbox D/BluetoothGatt: discoverServices() - device: E2:21:7E:59:01:7F
04-17 13:57:50.550 12709-12721/no.nordicsemi.android.nrftoolbox I/DfuBaseService: Attempting to start service discovery... succeed
04-17 13:57:50.850 12709-12720/no.nordicsemi.android.nrftoolbox D/BluetoothGatt: onClientConnParamsChanged() - Device=E2:21:7E:59:01:7F interval=6 status=0
04-17 13:57:51.140 12709-13865/no.nordicsemi.android.nrftoolbox D/BluetoothGatt: onSearchComplete() = Device=E2:21:7E:59:01:7F Status=0
04-17 13:57:51.140 12709-13865/no.nordicsemi.android.nrftoolbox I/DfuBaseService: Services discovered
04-17 13:57:51.210 12709-12721/no.nordicsemi.android.nrftoolbox D/BluetoothGatt: onClientConnParamsChanged() - Device=E2:21:7E:59:01:7F interval=39 status=0
04-17 13:57:52.180 12709-14177/no.nordicsemi.android.nrftoolbox I/DfuImpl: Reading DFU version number...
04-17 13:57:52.290 12709-14177/no.nordicsemi.android.nrftoolbox I/DfuImpl: Version number read: 0.1 -> Application with Legacy buttonless update from SDK 7.0 or newer
04-17 13:57:52.290 12709-14177/no.nordicsemi.android.nrftoolbox W/DfuImpl: Application with legacy buttonless update found
04-17 13:57:52.290 12709-14177/no.nordicsemi.android.nrftoolbox I/DfuImpl: Enabling notifications...
04-17 13:57:52.290 12709-14177/no.nordicsemi.android.nrftoolbox D/BluetoothGatt: setCharacteristicNotification() - uuid: 00001531-1212-efde-1523-785feabcd123 enable: true
04-17 13:57:53.440 12709-14177/no.nordicsemi.android.nrftoolbox I/DfuImpl: Sending Start DFU command (Op Code = 1, Upload Mode = 4)
04-17 13:57:53.800 12709-12721/no.nordicsemi.android.nrftoolbox D/BluetoothGatt: onClientConnectionState() - status=19 clientIf=9 device=E2:21:7E:59:01:7F
04-17 13:57:53.810 12709-12721/no.nordicsemi.android.nrftoolbox W/DfuBaseService: Target device disconnected with status: 19
04-17 13:57:53.810 12709-14177/no.nordicsemi.android.nrftoolbox D/BluetoothGatt: refresh() - device: E2:21:7E:59:01:7F
04-17 13:57:53.820 12709-14177/no.nordicsemi.android.nrftoolbox I/DfuBaseService: Refreshing result: true
    Cleaning up...
04-17 13:57:53.820 12709-14177/no.nordicsemi.android.nrftoolbox D/BluetoothGatt: close()
    unregisterApp() - mClientIf=9
04-17 13:57:53.830 12709-14177/no.nordicsemi.android.nrftoolbox I/DfuImpl: Starting service that will connect to the DFU bootloader
04-17 13:57:53.840 12709-12709/no.nordicsemi.android.nrftoolbox I/DfuBaseService: Action received: android.bluetooth.device.action.ACL_DISCONNECTED
04-17 13:57:55.970 12709-14177/no.nordicsemi.android.nrftoolbox I/DfuBaseService: Connecting to the device...
04-17 13:57:55.970 12709-14177/no.nordicsemi.android.nrftoolbox D/BluetoothGatt: connect() - device: E2:21:7E:59:01:7F, auto: false
    registerApp()
    registerApp() - UUID=0a95f982-07cd-4857-a8ba-fbf01de9acc0
04-17 13:57:56.020 12709-13865/no.nordicsemi.android.nrftoolbox D/BluetoothGatt: onClientRegistered() - status=0 clientIf=9
04-17 13:57:56.360 12709-12720/no.nordicsemi.android.nrftoolbox D/BluetoothGatt: onClientConnectionState() - status=133 clientIf=9 device=E2:21:7E:59:01:7F
04-17 13:57:56.360 12709-12720/no.nordicsemi.android.nrftoolbox E/DfuBaseService: Connection state change error: 133 newState: 0
04-17 13:57:56.370 12709-14177/no.nordicsemi.android.nrftoolbox E/DfuBaseService: Device not reachable. Check if the device with address E2:21:7E:59:01:7F is in range, is advertising and is connectable
04-17 13:57:56.370 12709-14177/no.nordicsemi.android.nrftoolbox D/BluetoothGatt: refresh() - device: E2:21:7E:59:01:7F
04-17 13:57:56.380 12709-14177/no.nordicsemi.android.nrftoolbox I/DfuBaseService: Refreshing result: true
    Cleaning up...
04-17 13:57:56.380 12709-14177/no.nordicsemi.android.nrftoolbox D/BluetoothGatt: close()
    unregisterApp() - mClientIf=9
04-17 13:57:57.000 12709-12709/no.nordicsemi.android.nrftoolbox D/TextView: setTypeface with style : 0
04-17 13:57:57.050 12709-12709/no.nordicsemi.android.nrftoolbox D/ViewRootImpl: #1 mView = android.widget.LinearLayout{d635a91 V.E...... ......I. 0,0-0,0}
04-17 13:57:57.060 12709-12709/no.nordicsemi.android.nrftoolbox I/DfuBaseService: DFU service destroyed
04-17 13:57:57.090 12709-12709/no.nordicsemi.android.nrftoolbox W/DisplayListCanvas: DisplayListCanvas is started on unbinded RenderNode (without mOwningView)
04-17 13:57:57.110 12709-12709/no.nordicsemi.android.nrftoolbox D/ViewRootImpl: MSG_RESIZED_REPORT: ci=Rect(0, 0 - 0, 0) vi=Rect(0, 0 - 0, 0) or=1
04-17 13:57:59.050 12709-12709/no.nordicsemi.android.nrftoolbox D/ViewRootImpl: #3 mView = null

[Aleksander Nowakowski]

The DFU bootlaoder from  SDK 11 should restart into bootloader mode and start advertising with the same address, and from the logs looks like it does it. The time from the second connect attempt to receiving 133 is short. Otherwise it would take 20 seconds.

I guess problem may lay in your bootloader firmware. Did you do any changes? Did you try with the samples from SDK and have similar problems?

Do you have a BLE sniffer and could check what's going wrong there?

After disconnecting form the app mode I added 2 seconds of delay before a connection attempt, this can be seen here:

04-17 13:57:53.840 12709-12709/no.nordicsemi.android.nrftoolbox I/DfuBaseService: Action received: android.bluetooth.device.action.ACL_DISCONNECTED
04-17 13:57:55.970 12709-14177/no.nordicsemi.android.nrftoolbox I/DfuBaseService: Connecting to the device...

but maybe that's to short for your bootloader/phones. For some unknown reason the phone can't connect too quickly.