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

DFU stuck at 'Sending Enter Bootloader (Op Code = 1)' on random occasions

Hi

I am integrating your Android DFU library with our mobile app to do FOTA to our Nordic device nRF52832. We are using SDK 14.2 and doing the firmware update using zip file.

In 1 out of 7 times, firmware update gets stuck just after sending `Sending Enter Bootloader (Op Code = 1)`, because the device is not responding with `Response received (Op Code = 1, Status = 1)`. On other occasions the DFU succeeds without issue.

Log during failed DFU:


09-06 15:33:22.837 I/DfuBaseService(26281): DFU service created. Version: 1.7.0
09-06 15:33:22.939 D/BluetoothGatt(26281): onConnectionUpdated() - Device=CA:03:09:F7:A7:F5 interval=6 latency=0 timeout=500 status=0
09-06 15:33:22.999 I/DfuBaseService(26281): Connecting to the device...
09-06 15:33:23.000 D/BluetoothGatt(26281): connect() - device: CA:03:09:F7:A7:F5, auto: false
09-06 15:33:23.000 D/BluetoothGatt(26281): registerApp()
09-06 15:33:23.001 D/BluetoothGatt(26281): registerApp() - UUID=fc8345b1-8afd-4152-a5cd-3a685a29e74d
09-06 15:33:23.003 D/BluetoothGatt(26281): onClientRegistered() - status=0 clientIf=11
09-06 15:33:23.006 D/BluetoothGatt(26281): onClientConnectionState() - status=0 clientIf=11 device=CA:03:09:F7:A7:F5
09-06 15:33:23.006 I/DfuBaseService(26281): Connected to GATT server
09-06 15:33:23.007 D/BluetoothGatt(26281): discoverServices() - device: CA:03:09:F7:A7:F5
09-06 15:33:23.009 I/DfuBaseService(26281): Attempting to start service discovery... succeed
09-06 15:33:23.714 D/BluetoothGatt(26281): onSearchComplete() = Device=CA:03:09:F7:A7:F5 Status=0
09-06 15:33:23.715 I/DfuBaseService(26281): Services discovered
09-06 15:33:23.722 I/DfuImpl (26281): Buttonless service without bond sharing found -> SDK 13 or newer
09-06 15:33:23.737 I/DfuImpl (26281): Enabling indications...
09-06 15:33:23.739 D/BluetoothGatt(26281): setCharacteristicNotification() - uuid: 8ec90003-f315-4f60-9fb8-838830daea50 enable: true
09-06 15:33:23.755 D/BluetoothGatt(26281): onConnectionUpdated() - Device=CA:03:09:F7:A7:F5 interval=36 latency=0 timeout=500 status=0
09-06 15:33:23.755 D/BluetoothGatt(26281): onConnectionUpdated() - Device=CA:03:09:F7:A7:F5 interval=36 latency=0 timeout=500 status=0
09-06 15:33:23.802 I/DfuImpl (26281): Sending Enter Bootloader (Op Code = 1)
DFU\DfuProgressListenerAdapter.cs;OnDeviceConnected;44;20180906T223323Z;INFO;OnDeviceConnected: CA:03:09:F7:A7:F5
DFU\DfuProgressListenerAdapter.cs;OnDfuProcessStarting;26;20180906T223323Z;INFO;OnDfuProcessStarting: CA:03:09:F7:A7:F5
DFU\DfuProgressListenerAdapter.cs;OnEnablingDfuMode;68;20180906T223323Z;INFO;OnEnablingDfuMode: CA:03:09:F7:A7:F5

Log during successful DFU:

09-06 15:15:05.382 I/DfuBaseService(21681): DFU service created. Version: 1.7.0
09-06 15:15:05.495 I/DfuBaseService(21681): Connecting to the device...
09-06 15:15:05.497 D/BluetoothGatt(21681): connect() - device: CA:03:09:F7:A7:F5, auto: false
09-06 15:15:05.497 D/BluetoothGatt(21681): registerApp()
09-06 15:15:05.498 D/BluetoothGatt(21681): registerApp() - UUID=c904ece0-c2ba-4378-8e77-064b32051111
09-06 15:15:05.500 D/BluetoothGatt(21681): onClientRegistered() - status=0 clientIf=11
09-06 15:15:05.503 D/BluetoothGatt(21681): onClientConnectionState() - status=0 clientIf=11 device=CA:03:09:F7:A7:F5
09-06 15:15:05.504 I/DfuBaseService(21681): Connected to GATT server
09-06 15:15:05.505 D/BluetoothGatt(21681): discoverServices() - device: CA:03:09:F7:A7:F5
09-06 15:15:05.507 I/DfuBaseService(21681): Attempting to start service discovery... succeed
09-06 15:15:05.606 D/BluetoothGatt(21681): onConnectionUpdated() - Device=CA:03:09:F7:A7:F5 interval=6 latency=0 timeout=500 status=0
09-06 15:15:05.606 D/BluetoothGatt(21681): onConnectionUpdated() - Device=CA:03:09:F7:A7:F5 interval=6 latency=0 timeout=500 status=0
09-06 15:15:06.283 D/BluetoothGatt(21681): onSearchComplete() = Device=CA:03:09:F7:A7:F5 Status=0
09-06 15:15:06.283 I/DfuBaseService(21681): Services discovered
09-06 15:15:06.289 I/DfuImpl (21681): Buttonless service without bond sharing found -> SDK 13 or newer
09-06 15:15:06.301 I/DfuImpl (21681): Enabling indications...
09-06 15:15:06.303 D/BluetoothGatt(21681): setCharacteristicNotification() - uuid: 8ec90003-f315-4f60-9fb8-838830daea50 enable: true
09-06 15:15:06.333 D/BluetoothGatt(21681): onConnectionUpdated() - Device=CA:03:09:F7:A7:F5 interval=36 latency=0 timeout=500 status=0
09-06 15:15:06.356 D/BluetoothGatt(21681): onConnectionUpdated() - Device=CA:03:09:F7:A7:F5 interval=36 latency=0 timeout=500 status=0
DFU\DfuProgressListenerAdapter.cs;OnDeviceConnected;44;20180906T221506Z;INFO;OnDeviceConnected: CA:03:09:F7:A7:F5
09-06 15:15:06.364 I/DfuImpl (21681): Sending Enter Bootloader (Op Code = 1)
DFU\DfuProgressListenerAdapter.cs;OnDfuProcessStarting;26;20180906T221506Z;INFO;OnDfuProcessStarting: CA:03:09:F7:A7:F5
DFU\DfuProgressListenerAdapter.cs;OnEnablingDfuMode;68;20180906T221506Z;INFO;OnEnablingDfuMode: CA:03:09:F7:A7:F5
09-06 15:15:06.463 I/DfuImpl (21681): Response received (Op Code = 1, Status = 1)
09-06 15:15:11.478 D/BluetoothGatt(21681): onClientConnectionState() - status=8 clientIf=10 device=CA:03:09:F7:A7:F5
09-06 15:15:11.480 D/BluetoothGatt(21681): onClientConnectionState() - status=8 clientIf=11 device=CA:03:09:F7:A7:F5
09-06 15:15:11.480 W/DfuBaseService(21681): Target device disconnected with status: 8
09-06 15:15:11.482 D/BluetoothGatt(21681): refresh() - device: CA:03:09:F7:A7:F5
09-06 15:15:11.485 I/DfuBaseService(21681): Refreshing result: true
09-06 15:15:11.485 I/DfuBaseService(21681): Cleaning up...
09-06 15:15:11.485 D/BluetoothGatt(21681): close()
09-06 15:15:11.486 D/BluetoothGatt(21681): unregisterApp() - mClientIf=11
09-06 15:15:11.494 I/DfuImpl (21681): Restarting to bootloader mode
09-06 15:15:11.507 D/BluetoothAdapter(21681): isLeEnabled(): ON
09-06 15:15:11.511 I/DfuBaseService(21681): Action received: android.bluetooth.device.action.ACL_DISCONNECTED
09-06 15:15:11.516 D/BluetoothLeScanner(21681): onScannerRegistered() - status=0 scannerId=11 mScannerId=0
09-06 15:15:11.612 D/BluetoothAdapter(21681): isLeEnabled(): ON
09-06 15:15:11.614 I/DfuImpl (21681): Scanning for new address finished with: CA:03:09:F7:A7:F6
... (proceeds to success)

Here is the code I am using:

_dfuProgressListener = new DfuProgressListenerAdapter(_progressListener, _loggingService);
DfuServiceListenerHelper.RegisterProgressListener(_context, _dfuProgressListener);

DfuServiceInitiator starter = new DfuServiceInitiator(device.DeviceId)
.SetDeviceName(device.Name)
//.SetKeepBond(true)
.SetDisableNotification(true)
.SetPacketsReceiptNotificationsEnabled(true)
.SetPacketsReceiptNotificationsValue(18)
.SetUnsafeExperimentalButtonlessServiceInSecureDfuEnabled(true);

starter.SetZip(zipFilePath);

_controller = starter.Start(_context, Class.FromType(typeof(DfuAndroidService)));



What could I be missing? This random failure is not happening when using your nRF Connect Android app to do the DFU.

I am using One+3 mobile with Android 8.0, but it is happening using other Android mobile devices too.

Thanks
Jagan

Parents
  • Hi,

    Do you get any logging information out of the nRF52 device?

    Are you using a custom bootloader and application? Is this reproducible with the examples in the SDK?

    Can you provide a sniffer log? If you have an extra Nordic dev kit to spare you can use our nRF Bluetooth Sniffer solution. You can also use the HCI snoop log from Android:

    1. Disable Bluetooth on the phone,
    2. Go to Settings -> (System->) Developer Options -> Enable HCI log
    3. Turn on Bluetooth
    4. Perform experiment
    5. On Android 7+ (?):
      1. When the bug happened, go to Settings -> (System->) Developer Options -> Take bug report
      2. Check the notification and when the bug report is done, click and send the bugreport to email.
      3. Open bugreport….zip and got to FS\data\misc\bluetooth\logs where the btsnoop_hci.log file is located.
      4. Open it in Wireshark
    6. On older:
      1. Check btsnoop_hci.log file on sdcard, copy it to PC and open in Wireshark.

    I was wondering about the 1/7 failure rate. That seems oddly specific. Is it every 7th time or just happening ~1 in 7 times?

  • Hi Martin

    Thanks for getting back. It is roughly (~) 1 out of 7 times. Smiley

    Bootloader code is mostly Nordic provided code. Application is custom.

    I will try to collect the logs and get back to you in a few days.

    Thanks

    Jagan

Reply Children
No Data
Related