DFU abort() midway zip upload never exits DFU mode

[cesarferreira]

DFU Bootloader version:

• SDK version: 29
• Bonding used: yes
• Library version: 1.10.3

Device information:

• Device: Pixel 3
• OS: Android 10

Your question When I abort (at 16% as shown on the logs below), the device stays in DFU mode forever (I've left it overnight and it never leaves it). If I remove the batteries, still doesnt reboot into the old app. The only way to make it work again is to use the NRFConnect app and force a DFU.zip to make it exit.

And according to the documentation:

/** * Aborts the upload. The service does not need to be paused before. * After sending {link #BROADCAST_ACTION} with extra {link #EXTRA_ACTION} set to this value * the DFU bootloader will restore the old application (if there was already an application). * Be aware, that uploading the Soft Device will erase the application in order to make space * in the memory. In case there is no application, or the application has been removed, the * DFU bootloader will be started and user may try to send the application again. * The bootloader may advertise with the address incremented by 1 to prevent caching services. */ public static final int ACTION_ABORT = 2;

the DFU bootloader will restore the old application I was expecting this to happen. Am I not doing something correctly?

Thanks in advance

Logs

2020-07-22 15:40:33.526 I/[DeviceOperatorViewModel.upgradeGL05 @ line:293]: upgradeGL05FirmwareTo: /storage/emulated/0/dfu.zip
2020-07-22 15:40:33.528 D/[GlueLockV2Firmware.upgradeGL05FirmwareTo @ line:465]: enterDFUMode
2020-07-22 15:40:36.721 I/[GlueLockV2Firmware$handleOperationStates.accept @ line:141]: DFUEntered
2020-07-22 15:40:36.722 I/[GlueLockV2Firmware$handleOperationStates.accept @ line:161]: DFULookingForLock
2020-07-22 15:40:36.723 D/[DeviceActivity.reportLockOperationState @ line:274]: DFUEntered
2020-07-22 15:40:36.725 D/[DeviceActivity.reportLockOperationState @ line:274]: DFULookingForLock
2020-07-22 15:40:36.727 D/[DeviceLocator.findMacAddressByScanning @ line:15]: Going to scan: DFGlue
2020-07-22 15:40:36.737 D/BluetoothAdapter: isLeEnabled(): ON
2020-07-22 15:40:36.742 D/BluetoothLeScanner: onScannerRegistered() - status=0 scannerId=12 mScannerId=0
2020-07-22 15:40:38.897 D/BluetoothAdapter: isLeEnabled(): ON
2020-07-22 15:40:38.897 I/[DeviceLocator$findMacAddressByScanning.accept @ line:17]: BLE Scanning: I found: DFGlue
2020-07-22 15:40:38.923 D/[BLEScanner.getBleDeviceFromMacAddress @ line:34]: getBleDeviceFromMacAddress: E6:48:3A:74:38:6D
2020-07-22 15:40:38.926 I/[GlueLockV2Firmware$handleOperationStates.accept @ line:163]: DFULockFound
2020-07-22 15:40:38.937 D/[DeviceActivity.reportLockOperationState @ line:274]: DFULockFound(deviceName=DFGlue, macAddress=E6:48:3A:74:38:6D)
2020-07-22 15:40:39.007 D/BluetoothGatt: connect() - device: E6:48:3A:74:38:6D, auto: false
2020-07-22 15:40:39.007 D/BluetoothGatt: registerApp()
2020-07-22 15:40:39.007 D/BluetoothGatt: registerApp() - UUID=25578e12-b4c5-4a0a-a34a-8a32ac992c83
2020-07-22 15:40:39.009 D/BluetoothGatt: onClientRegistered() - status=0 clientIf=12
2020-07-22 15:40:39.064 D/BluetoothGatt: onClientConnectionState() - status=0 clientIf=12 device=E6:48:3A:74:38:6D
2020-07-22 15:40:39.066 D/BluetoothGatt: discoverServices() - device: E6:48:3A:74:38:6D
2020-07-22 15:40:39.934 D/BluetoothGatt: onPhyUpdate() - status=0 address=E6:48:3A:74:38:6D txPhy=2 rxPhy=2
2020-07-22 15:40:40.380 D/BluetoothGatt: onSearchComplete() = Device=E6:48:3A:74:38:6D Status=0
2020-07-22 15:40:40.421 D/BluetoothGatt: onConnectionUpdated() - Device=E6:48:3A:74:38:6D interval=12 latency=0 timeout=600 status=0
2020-07-22 15:40:41.398 D/BluetoothGatt: configureMTU() - device: E6:48:3A:74:38:6D mtu: 517
2020-07-22 15:40:41.455 D/BluetoothGatt: onConfigureMTU() - Device=E6:48:3A:74:38:6D mtu=247 status=0
2020-07-22 15:40:41.456 D/BluetoothGatt: setCharacteristicNotification() - uuid: 8ec90001-f315-4f60-9fb8-838830daea50 enable: true
2020-07-22 15:40:42.283 D/BluetoothGatt: onClientConnectionState() - status=8 clientIf=11 device=E6:48:3A:74:38:6C
2020-07-22 15:40:42.296 D/BluetoothGatt: setCharacteristicNotification() - uuid: e4b264d7-4e56-424f-8b5c-d4089ea216ef enable: false
2020-07-22 15:40:42.298 D/BluetoothGatt: close()
2020-07-22 15:40:42.298 D/BluetoothGatt: unregisterApp() - mClientIf=11
2020-07-22 15:40:42.806 D/BluetoothGatt: connect() - device: E6:48:3A:74:38:6C, auto: false
2020-07-22 15:40:42.806 D/BluetoothGatt: registerApp()
2020-07-22 15:40:42.807 D/BluetoothGatt: registerApp() - UUID=cc7073af-2420-4296-b1eb-a1780fce45a7
2020-07-22 15:40:42.811 D/BluetoothGatt: onClientRegistered() - status=0 clientIf=11
2020-07-22 15:40:42.964 D/[DeviceActivity.reportLockOperationState @ line:274]: DFUProgress(percentage=0, speed=0.0, avgSpeed=0.0)
2020-07-22 15:40:43.105 D/[DeviceActivity.reportLockOperationState @ line:274]: DFUProgress(percentage=1, speed=16.94, avgSpeed=16.94)
2020-07-22 15:40:43.506 D/[DeviceActivity.reportLockOperationState @ line:274]: DFUProgress(percentage=2, speed=5.43, avgSpeed=8.5)
2020-07-22 15:40:43.523 D/[DeviceActivity.reportLockOperationState @ line:274]: DFUProgress(percentage=3, speed=129.18, avgSpeed=12.19)
2020-07-22 15:40:43.888 D/[DeviceActivity.reportLockOperationState @ line:274]: DFUProgress(percentage=4, speed=6.49, avgSpeed=9.92)
2020-07-22 15:40:43.917 D/[DeviceActivity.reportLockOperationState @ line:274]: DFUProgress(percentage=5, speed=99.82, avgSpeed=12.01)
2020-07-22 15:40:44.299 D/[DeviceActivity.reportLockOperationState @ line:274]: DFUProgress(percentage=6, speed=5.48, avgSpeed=10.1)
2020-07-22 15:40:44.318 D/[DeviceActivity.reportLockOperationState @ line:274]: DFUProgress(percentage=7, speed=128.42, avgSpeed=11.76)
2020-07-22 15:40:44.723 D/[DeviceActivity.reportLockOperationState @ line:274]: DFUProgress(percentage=8, speed=5.44, avgSpeed=10.34)
2020-07-22 15:40:44.738 D/[DeviceActivity.reportLockOperationState @ line:274]: DFUProgress(percentage=9, speed=122.0, avgSpeed=11.48)
2020-07-22 15:40:45.114 D/[DeviceActivity.reportLockOperationState @ line:274]: DFUProgress(percentage=10, speed=6.23, avgSpeed=10.54)
2020-07-22 15:40:45.511 D/[DeviceActivity.reportLockOperationState @ line:274]: DFUProgress(percentage=11, speed=5.4, avgSpeed=9.74)
2020-07-22 15:40:45.530 D/[DeviceActivity.reportLockOperationState @ line:274]: DFUProgress(percentage=12, speed=109.8, avgSpeed=10.52)
2020-07-22 15:40:45.961 D/[DeviceActivity.reportLockOperationState @ line:274]: DFUProgress(percentage=13, speed=5.54, avgSpeed=9.8)
2020-07-22 15:40:45.978 D/[DeviceActivity.reportLockOperationState @ line:274]: DFUProgress(percentage=14, speed=137.25, avgSpeed=10.48)
2020-07-22 15:40:46.363 D/[DeviceActivity.reportLockOperationState @ line:274]: DFUProgress(percentage=15, speed=5.58, avgSpeed=9.93)
2020-07-22 15:40:46.394 D/[DeviceActivity.reportLockOperationState @ line:274]: DFUProgress(percentage=16, speed=78.71, avgSpeed=10.55)
2020-07-22 15:40:46.670 D/BluetoothGatt: cancelOpen() - device: E6:48:3A:74:38:6D
2020-07-22 15:40:46.673 D/BluetoothGatt: onClientConnectionState() - status=0 clientIf=12 device=E6:48:3A:74:38:6D
2020-07-22 15:40:46.674 W/toolkit.stagin: Accessing hidden method Landroid/bluetooth/BluetoothGatt;->refresh()Z (greylist, reflection, allowed)
2020-07-22 15:40:46.674 D/BluetoothGatt: refresh() - device: E6:48:3A:74:38:6D
2020-07-22 15:40:46.675 D/BluetoothGatt: close()
2020-07-22 15:40:46.675 D/BluetoothGatt: unregisterApp() - mClientIf=12
2020-07-22 15:40:47.278 I/[GlueLockV2Firmware$handleOperationStates.accept @ line:196]: DFUProblem
2020-07-22 15:40:47.284 D/[DeviceActivity.reportLockOperationState @ line:274]: DFUProblem(exception=DFUException: Error upgrading: DFU aborted)

[philips77]

It is up to your bootloader to reset itself to app mode after some time of inactivity, not the library. Which SDK (Nordic SDK, not Android SDK) is your DFU bootloader based on? Do you update only the app, or the SoftDevice as well? Are you using double-bank update?

[cesarferreira]

• We use SDK v15.2.0 and the secure bootloader
• We currently only update the app, not the SoftDevice nor the bootloader itself
• We use double-bank update

thanks for the reply

[teodf]

Hi @cesarferreira, you have found a solution because I have the same problem

[ghost]

Hello, I have the same problem. I realized that in IOS, this problems not occurs. In fact, the DFU led indications are turned off immediately after launching the abort() operation. I searched the IOS DFUServiceController and it seems similar to DfuServiceController Android I got that NDK reset the device after 15 seconds sometimes. But most of times, I have to reinstall the firmware manually due to the NDK stays in DFU mode forever.

[teodf]

Thank you for you advice @Juan-GS but you update just the application or APP + BL + SD ? With IOS app example from Nordic my board never go back on the application it stay in DFU Mode but i can see my board advertise with bootloader name. You have add something in you bootloader for the transition to the application after abort ?

[ghost]

Hi @teodf, we only update the APP and we don't add anything to our bootloader after aborting.

[philips77]

In nRF5 SDK version 15 a new command "Abort" have been added, which should reset the device to app mode, but this library was designed before that and is not using it at the moment, relying on a timeout on the device side, like I wrote before. Shall we add it?

[teodf]

Yes I think it can be good to add the command, if it is developed in the SDK you might as well add it to the library.

[teodf]

If we use single-bank the command "abort" just stop the DFU and the nRF stays in DFU mode ? Or he has a solution to get back in the original application/firmware ?

[philips77]

With single back you can't restore the original fw. It'll stay in the bootloader mode, as there's no app available.

[soldag]

@philips77 Any chance this command will be added to the library?

[philips77]

I've added it to the backlog but can't promise any deadline.

[soldag]

Ok, thanks for the update