Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

gatt Error when searching for device when location is not active #480

Open
eshan-gr opened this issue Dec 10, 2024 · 3 comments
Open

gatt Error when searching for device when location is not active #480

eshan-gr opened this issue Dec 10, 2024 · 3 comments
Labels
bug

Comments

@eshan-gr
Copy link

eshan-gr commented Dec 10, 2024 •
edited
Loading

Where do you suspect the issue?

Issue in DFU library, e.g. upload stops in the middle

Version

2.8.0 (Latest)

Describe the issue

@philips77 Firstly sorry for tagging and pinging but we are on a time constraint and this issue is just unique.
Our BLE device is a custom device which transmits data in json for most of the commands and has a dedicated DFU mode. And it does not support bonding of any sort, When we try to bond we get a popup in phone but android system shows a toast that it cannot be proceeded without PIN or a passkey so we cannot bond the device. Here is the log when flashing the firmware

DfuBaseService   I  DFU service created. Version: 2.8.0
19:47:55.066 25469-25636 DfuBaseService   W  Foreground service disabled. Android Oreo or newer may kill a background service few moments after user closes the application.
                                             Consider enabling foreground service using DfuServiceInitiator#setForeground(boolean)
19:47:55.108 25469-25636 DfuBaseService   I  Connecting to the device...
19:47:55.110 25469-25636 BluetoothGatt    D  connect() - device: C0:6B:DE:F6:DC:1E, auto: false
19:47:55.110 25469-25636 BluetoothGatt    D  registerApp()
19:47:55.111 25469-25636 BluetoothGatt    D  registerApp() - UUID=86be05aa-5910-4b8d-8fc4-11446034a1bc
19:47:55.113 25469-25485 BluetoothGatt    D  onClientRegistered() - status=0 clientIf=6
19:48:14.971 25469-25469 DFU              D  onPause: UNREGISTERING DFU progress listener
19:48:15.241 25469-25469 APP_CRITICAL     W  ! SYSTEM IS TRIMMING MEMORY !
19:48:25.118 25469-25675 BluetoothGatt    D  onClientConnectionState() - status=133 clientIf=6 device=C0:6B:DE:F6:DC:1E
19:48:25.120 25469-25675 DfuBaseService   E  Connection state change error: 133 newState: 0
19:48:25.120 25469-25636 DfuBaseService   I  Connection error after: 30014 ms
19:48:25.121 25469-25636 DfuBaseService   E  Device not reachable. Check if the device with address C0:6B:DE:F6:DC:1E is in range, is advertising and is connectable
19:48:25.121 25469-25636 DfuBaseService   I  Retrying... (attempt 2 / 3)
19:48:25.122 25469-25636 BluetoothGatt    D  refresh() - device: C0:6B:DE:F6:DC:1E
19:48:25.126 25469-25636 DfuBaseService   I  Refreshing result: true
19:48:25.126 25469-25636 DfuBaseService   I  Cleaning up...
19:48:25.127 25469-25636 BluetoothGatt    D  cancelOpen() - device: C0:6B:DE:F6:DC:1E
19:48:25.131 25469-25636 BluetoothGatt    D  close()
19:48:25.131 25469-25636 BluetoothGatt    D  unregisterApp() - mClientIf=6
19:48:25.135 25469-25636 DfuBaseService   I  Restarting the service
19:48:25.143 25469-25636 DfuBaseService   W  Foreground service disabled. Android Oreo or newer may kill a background service few moments after user closes the application.
                                             Consider enabling foreground service using DfuServiceInitiator#setForeground(boolean)
19:48:25.144 25469-25636 DfuBaseService   I  Connecting to the device...
19:48:25.146 25469-25636 BluetoothGatt    D  connect() - device: C0:6B:DE:F6:DC:1E, auto: false
19:48:25.146 25469-25636 BluetoothGatt    D  registerApp()
19:48:25.147 25469-25636 BluetoothGatt    D  registerApp() - UUID=b9c0884c-0017-449a-9759-52846293b166
19:48:25.150 25469-25623 BluetoothGatt    D  onClientRegistered() - status=0 clientIf=6

!!!!!!!!!!!!!!!!!!!! I WENT TO NRF CONNECT AND CONNECTED MANUALLY WHILE MY APP FIRMWARE FRAGMENT WAS INITIATING DFU, AND THEN BELOW LOG APPEARED !!!!!!!!!!!!!!!

19:48:25.227 25469-25623 BluetoothGatt    D  onClientConnectionState() - status=0 clientIf=6 device=C0:6B:DE:F6:DC:1E
19:48:25.227 25469-25623 DfuBaseService   I  Connected to GATT server
19:48:25.231 25469-25623 BluetoothGatt    D  discoverServices() - device: C0:6B:DE:F6:DC:1E
19:48:25.233 25469-25623 DfuBaseService   I  Attempting to start service discovery... succeed
19:48:25.239 25469-25469 DfuBaseService   I  Action received: android.bluetooth.device.action.ACL_CONNECTED
19:48:26.070 25469-25623 BluetoothGatt    D  onPhyUpdate() - status=0 address=C0:6B:DE:F6:DC:1E txPhy=2 rxPhy=2
19:48:26.611 25469-25623 BluetoothGatt    D  onConnectionUpdated() - Device=C0:6B:DE:F6:DC:1E interval=12 latency=0 timeout=600 status=0
19:48:26.660 25469-25623 BluetoothGatt    D  onSearchComplete() = Device=C0:6B:DE:F6:DC:1E Status=0
19:48:26.660 25469-25623 DfuBaseService   I  Services discovered
19:48:26.663 25469-25636 DfuImpl          W  Secure DFU bootloader found
19:48:26.663 25469-25636 DfuImpl          I  Enabling notifications...
19:48:26.664 25469-25636 BluetoothGatt    D  setCharacteristicNotification() - uuid: 8ec90001-f315-4f60-9fb8-838830daea50 enable: true
19:48:26.729 25469-25636 DfuImpl          I  Requesting high connection priority
19:48:26.729 25469-25636 BluetoothGatt    D  requestConnectionPriority() - params: 1
19:48:26.732 25469-25636 DfuImpl          I  Setting object to Command (Op Code = 6, Type = 1)
19:48:26.791 25469-25623 BluetoothGatt    D  onConnectionUpdated() - Device=C0:6B:DE:F6:DC:1E interval=6 latency=0 timeout=500 status=0
19:48:26.793 25469-25636 DfuImpl          I  Command object info received (Max size = 512, Offset = 0, CRC = 00000000)
19:48:26.794 25469-25636 DfuImpl          I  Sending the number of packets before notifications (Op Code = 2, Value = 0)
19:48:26.813 25469-25636 DfuImpl          I  Creating Init packet object (Op Code = 1, Type = 1, Size = 141)
19:48:26.850 25469-25636 DfuImpl          I  Sending 141 bytes of init packet...

BUT strangely while in this process and if i Open the NRF Connect app and then try to manually connect the device which is named "DFU" in its dfu mode then what happens that nrf connect while connecting uses some location data as i can see the green location button usage in my notification bar (A13) and then i open my app from recents and firmware process starts.
I tried adding fine location and granting it but doesnt work, so what does NRF Connect app does with the location that too in above android 12.
My dfu config is this

 val incrementedMacAddress = incrementMacAddress(deviceAddress ?: return)
        Log.d(TAG, "startDFU: Incremented MAC :FROM: $deviceAddress :TO: $incrementedMacAddress")

        dfuServiceInitiator = DfuServiceInitiator(incrementedMacAddress)
            .setForeground(false)
            .setDisableNotification(true)
            .setDeviceName("DFU")
            .setForceDfu(false)
            .setRebootTime(30000L)
            .setScanTimeout(10000L)
            .setMtu(23)
            .disableMtuRequest()
            .setKeepBond(false)
            //.setNumberOfRetries(1)
            .setPrepareDataObjectDelay(300L)
            .setPacketsReceiptNotificationsEnabled(true)
            .setPacketsReceiptNotificationsValue(5)
            .setForceScanningForNewAddressInLegacyDfu(true)
            .setUnsafeExperimentalButtonlessServiceInSecureDfuEnabled(true)
            .setZip(zip.absolutePath)

i have tried experimenting with reboot times, experimental unsafe, mtu, disable mtu, etc

Relevant log output

No response
@eshan-gr eshan-gr added the bug label Dec 10, 2024
@philips77
Copy link
Member

Hello,

As far as I understand, your issue is that your app cannot connect to a device unless you open nRF Connect.

One problem that I have with it, is the following log:

19:48:25.150 25469-25623 BluetoothGatt    D  onClientRegistered() - status=0 clientIf=6

!!!!!!!!!!!!!!!!!!!! I WENT TO NRF CONNECT AND CONNECTED MANUALLY WHILE MY APP FIRMWARE FRAGMENT WAS INITIATING DFU, AND THEN BELOW LOG APPEARED !!!!!!!!!!!!!!!

19:48:25.227 25469-25623 BluetoothGatt    D  onClientConnectionState() - status=0 clientIf=6 device=C0:6B:DE:F6:DC:1E

The time between these events is just 77ms, which is too low for opening nRF Connect and starting scanning.

Anyway, I see one possible reason. Are you scanning in your app before starting the DFU? Where do you get the BluetoothDevice object from? Could you ensure, that your device is in fact advertising which the library tries to connect (le't say with another phone running nRF Connect?
Also, are you able to repeat the DFU again (if the device doesn't change the MAC addresses) after one successful try?
It may be, that Android is "looking for" a public MAC address type for the connection, and if your device is advertising with a random address, the connection never gets initiated. When you start scanning with nRF Connect Android scans it, saves the MAC type (public/random) and as there's a new connection to "stored MAC" it knows its type, therefore the connection succeeds.

In short:

  1. Does your device rotate MAC address?
  2. Is it a random type MAC: static / private resolvable / private non-resolvalbe?
  3. Are you scanning before starting DFU? Are you able to connect to the same device in your app before starting DFU?

@eshan-gr
Copy link
Author

Thanks for pointing, although this log is slightly old version of the same problem, The device doesn't rotates any address never, It has a fixed mac where last char is incremented while in DFU, and our phones and any nordic app can discover it, Our firmware process is allowed to user after a connection, So we first connect to the one with local pairing mode using datastore

suspend fun scanForDeviceByMac(targetMacAddress: String): BluetoothDevice? {
        val autoCallback = object : ScanCallback() {
            override fun onScanResult(callbackType: Int, result: ScanResult?) {
                result?.device?.let { device ->
                    if (device.address.equals(targetMacAddress, ignoreCase = true)) {
                        stopAutoScanner(this)  // Stop scanning once we find the device
                        foundPairedDevice.complete(device)
                        Log.d(TAG, "Device found with MAC: $targetMacAddress")
                    }
                }
            }

            override fun onScanFailed(errorCode: Int) {
                Log.e(TAG, "Scan failed with error code: $errorCode")
                stopAutoScanner(this)
                foundPairedDevice.complete(null)
            }
        }

        try {
            scanner?.startScan(mutableListOf(deviceFilter), scanSettingsAndConditions, autoCallback)
            Log.d(TAG, "Scanning for device with MAC: $targetMacAddress")

            // Await for the scan to complete or timeout
            withTimeout(10000) { // Timeout after 10 seconds
                return@withTimeout foundPairedDevice.await()
            }
        } catch (t: Throwable) {
            Log.e(TAG, "Scan timed out or failed unexpectedly")
            logError(t)
            stopAutoScanner(autoCallback)
            return null
        } finally {
            stopAutoScanner(autoCallback) // Ensure we always stop scanning, even on exceptions
        }
        return foundPairedDevice.await()
    }

and pass it to the connection initializer to connectGatt and also whole logic happens succesfully , be it parsing battery or other data etc, and update button appears in a screen where if pressed then we close the scanner, callback and disconnect and then device enters dfu mode with a bright led for that mode and the dfu initiator starts in a next fragment.

I will attach a video and log after clearing some private logs and app screens.

@eshan-gr
Copy link
Author

eshan-gr commented Dec 11, 2024 •
edited
Loading

@philips77
Here is the video and the logcat of same.

media_20241211_135402_2510946124743464541.1.mp4

-----------------LOGCAT---------

20:18:31.061  6736-6736  DeviceFrag       I  Navigating to add device
20:18:31.066  6736-6736  DeviceFragment   D  Try Catching DeviceFragment$$ExternalSyntheticLambda1
20:18:31.177  6736-6736  Compat...porter  D  Compat change id reported: 78294732; UID 10707; state: ENABLED
20:18:31.180  6736-6778  Blueto...dapter  D  isLeEnabled(): ON
20:18:31.185  6736-6749  Blueto...canner  D  onScannerRegistered() - status=0 scannerId=4 mScannerId=0
20:18:31.188  6736-6778  BLEScanner       D  Scanning for device with MAC: C0:6B:DE:F6:DC:1D
20:18:31.208  6736-6736  Choreographer    W  Frame time is 0.045738 ms in the future!  Check that graphics HAL is generating vsync timestamps using the correct timebase.
20:18:31.272  6736-6736  BLEScanner       I  Automatic Stopping Scanner stopped.
20:18:31.272  6736-6736  Blueto...dapter  D  isLeEnabled(): ON
20:18:31.285  6736-6736  Blueto...dapter  D  isLeEnabled(): ON
20:18:31.285  6736-6736  BLEScanner       I  Automatic Device Scanning Stopped!
20:18:31.286  6736-6736  BLEScanner       D  Device found with MAC: C0:6B:DE:F6:DC:1D
20:18:31.286  6736-6778  BLEScanner       I  Automatic Stopping Scanner stopped.
20:18:31.286  6736-6778  BLEScanner       I  Automatic Device Scanning Stopped!
20:18:31.297  6736-6778  DF               D  Matching device found: SECRET
20:18:31.302  6736-6778  BLEManager       D  Registering GATT event receiver
20:18:31.305  6736-6778  BLEDev...ection  D  Connecting to C0:6B:DE:F6:DC:1D
20:18:31.306  6736-6778  BluetoothGatt    D  connect() - device: C0:6B:DE:F6:DC:1D, auto: false
20:18:31.306  6736-6778  BluetoothGatt    D  registerApp()
20:18:31.308  6736-6778  BluetoothGatt    D  registerApp() - UUID=a1c47485-50d2-4f7f-b138-5ef25f7d7fc7
20:18:31.313  6736-6749  BluetoothGatt    D  onClientRegistered() - status=0 clientIf=6
20:18:31.625  6736-6749  BluetoothGatt    D  onClientConnectionState() - status=0 clientIf=6 device=C0:6B:DE:F6:DC:1D
20:18:31.626  6736-6749  BLEDev...ection  I  Connected to GATT server.
20:18:31.628  6736-6749  BLEDev...ection  D  Connection state updated: true
20:18:31.629  6736-6749  BLEDev...ection  D  Sending GATT Connected broadcast
20:18:31.630  6736-6736  DeviceFragment   D  CONNECTION STATUS: true

20:18:31.647  6736-6736  D8               D  CONNECTION STATUS: true

20:18:31.667  6736-6904  okhttp...Client  I  Content-Type: application/json; charset=utf-8
20:18:31.668  6736-6904  okhttp...Client  I  Content-Length: 79

20:18:31.668  6736-6904  okhttp...Client  I  --> END POST (79-byte body)

20:18:31.685  6736-6736  BLEManager       D  Received broadcast with action: ACTION_GATT_CONNECTED
20:18:31.686  6736-6736  BLEManager       D  GATT Connected action received, requesting PHY update

20:18:31.953  6736-6904  okhttp...Client  I  Server: nginx/1.18.0 (Ubuntu)
20:18:31.953  6736-6904  okhttp...Client  I  Content-Type: application/json
20:18:31.953  6736-6904  okhttp...Client  I  Transfer-Encoding: chunked
20:18:31.953  6736-6904  okhttp...Client  I  Connection: keep-alive
20:18:31.953  6736-6904  okhttp...Client  I  Cache-Control: no-cache, private
20:18:31.953  6736-6904  okhttp...Client  I  Date: Tue, 10 Dec 2024 14:48:32 GMT
20:18:31.953  6736-6904  okhttp...Client  I  Access-Control-Allow-Origin: *

20:18:31.955  6736-6904  okhttp...Client  I  <-- END HTTP (684-byte body)
20:18:32.189  6736-6736  reques...Update  D  Received broadcast for phy
20:18:32.199  6736-6749  BluetoothGatt    D  onPhyRead() - status=0 address=C0:6B:DE:F6:DC:1D txPhy=1 rxPhy=1
20:18:32.428  6736-6749  BluetoothGatt    D  onPhyUpdate() - status=0 address=C0:6B:DE:F6:DC:1D txPhy=2 rxPhy=2
20:18:32.429  6736-6749  BLEDev...ection  I  PHY update success. TX PHY: 2, RX PHY: 2
20:18:32.432  6736-6736  BLEManager       D  Received broadcast with actio ACTION_PHY_UPDATED
20:18:32.432  6736-6736  BLEManager       D  PHY updated action received, requesting MTU change
20:18:32.878  6736-6787  BluetoothGatt    D  onConnectionUpdated() - Device=C0:6B:DE:F6:DC:1D interval=6 latency=0 timeout=500 status=0
20:18:32.935  6736-6736  BluetoothGatt    D  configureMTU() - device: C0:6B:DE:F6:DC:1D mtu: 517
20:18:32.956  6736-6787  BluetoothGatt    D  onConfigureMTU() - Device=C0:6B:DE:F6:DC:1D mtu=247 status=0
20:18:32.957  6736-6787  BLEDev...ection  I  MTU successfully changed to 247
20:18:32.960  6736-6736  BLEManager       D  Received broadcast with action: ACTION_MTU_CHANGED
20:18:32.960  6736-6736  BLEManager       D  MTU changed action received, discovering services
20:18:32.962  6736-6787  BluetoothGatt    D  onConnectionUpdated() - Device=C0:6B:DE:F6:DC:1D interval=9 latency=0 timeout=400 status=0
20:18:33.462  6736-6736  BluetoothGatt    D  discoverServices() - device: C0:6B:DE:F6:DC:1D
20:18:33.468  6736-6787  BluetoothGatt    D  onSearchComplete() = Device=C0:6B:DE:F6:DC:1D Status=0
20:18:33.468  6736-6787  onServ...overed  I  Services discovered.
20:18:33.470  6736-6787  BluetoothGatt    D  setCharacteristicNotification() - uuid: 8db61101-71e4-4d80-b0e8-4a5e689fd9ee enable: true
20:18:33.472  6736-6787  BluetoothGatt    D  setCharacteristicNotification() - uuid: 8db61101-71e4-4d80-b0e8-4a5e689fd9ee enable: true
20:18:33.477  6736-6787  BLEDev...ection  I  Service 00001800-0000-1000-8000-00805f9b34fb:
                                             |--00002a00-0000-1000-8000-00805f9b34fb
                                             |--00002a01-0000-1000-8000-00805f9b34fb
                                             |--00002a04-0000-1000-8000-00805f9b34fb
                                             |--00002aa6-0000-1000-8000-00805f9b34fb
20:18:33.477  6736-6787  BLEDev...ection  I  Service 00001801-0000-1000-8000-00805f9b34fb:
                                             |--
20:18:33.478  6736-6787  BLEDev...ection  I  Service 8db61100-71e4-4d80-b0e8-4a5e689fd9ee:
                                             |--8db61101-71e4-4d80-b0e8-4a5e689fd9ee
20:18:33.478  6736-6736  BLEManager       D  Received broadcast with action: ACTION_SERVICES_DISCOVERED
20:18:33.478  6736-6736  BLEManager       D  Services discovered action received, sending password command

20:18:34.026  6736-6749  BLEDev...ection  I  Password set successfully.
20:18:34.027  6736-6749  BLEDev...ection  I  PASSWORD_UPDATE_SUCCESS Broadcast sent!
20:18:34.027  6736-6736  in JSON          D  {
                                             "password": true
                                             }
20:18:34.030  6736-6736  BLEManager       D  Received broadcast with action: PASSWORD_UPDATE_SUCCESS
20:18:34.030  6736-6736  GattBr...ceiver  D  Password update success, sending info charger command
20:18:34.103  6736-6787  BluetoothGatt    D  onConnectionUpdated() - Device=C0:6B:DE:F6:DC:1D interval=9 latency=0 timeout=400 status=0
20:18:34.531  6736-6736  BLEDev...ection  D  Sending JSON command: { something }
20:18:49.482  6736-6736  BLEManager       D  Received broadcast with action: SHOULD_ENTER_DFU_MODE
20:18:49.483  6736-6736  BLEManager       D  onReceive: sending dfu command
20:18:49.784  6736-6736  BLEDev...ection  D  Sending JSON command: { dfu command }
20:18:49.815  6736-6787  BLEDev...ection  I  !! SECRET ENTERED INTO DFU MODE !!
20:18:49.815  6736-6736  InputD...owJAVA  D  Speed = 0
20:18:49.815  6736-6787  BLEDev...ection  I  ENTERED_IN_DFU_FLASH_FW Broadcast sent!
20:18:49.815  6736-6736  in JSON          D  {
                                             ENTERED IN DFU
                                             }
20:18:49.817  6736-6736  DeviceFragment   I  onReceive: ENTERED_IN_DFU_FLASH_FW Broadcast received
20:18:49.824  6736-6736  BLEDev...ection  I  Disconnecting from C0:6B:DE:F6:DC:1D
20:18:49.825  6736-6736  apppackage |  W  Accessing hidden method Landroid/bluetooth/BluetoothGatt;->refresh()Z (unsupported, reflection, allowed)
20:18:49.825  6736-6736  BluetoothGatt    D  refresh() - device: C0:6B:DE:F6:DC:1D
20:18:49.828  6736-6736  BLEDev...ection  I  refreshDeviceCache: true
20:18:49.828  6736-6736  BLEManager       D  Unregistering GATT event receiver
20:18:49.829  6736-6736  BLEScanner       I  BLEScanner has been destroyed and all resources released.
20:18:49.831  6736-6736  DeviceFragment   D  CONNECTION STATUS: false
20:18:49.843  6736-6736  Navigation       D  Navigating to fragment: 2131296353
20:18:49.888  6736-6736  Naviga...otNULL  D  Navigating to fragment: 2131296353
20:18:49.889  6736-6736  BluetoothGatt    D  refresh() - device: C0:6B:DE:F6:DC:1D
20:18:49.892  6736-6736  BLEDev...ection  I  refreshDeviceCache: true
20:18:49.892  6736-6736  BluetoothGatt    D  cancelOpen() - device: C0:6B:DE:F6:DC:1D
20:18:49.896  6736-6736  BluetoothGatt    D  close()
20:18:49.896  6736-6736  BluetoothGatt    D  unregisterApp() - mClientIf=6
20:18:49.898  6736-6736  BLEDev...ection  D  Connection state updated: false
20:18:49.912  6736-6736  DeviceFragment   D  Unregistering DFU STATE receiver
20:18:49.916  6736-6736  printBundle      I  macAddress: C0:6B:DE:F6:DC:1D
20:18:49.916  6736-6736  FW_UPDATE_FRAG   I  Arguments Received: macAddress = C0:6B:DE:F6:DC:1D
20:18:49.955  6736-6736  FW_UPDATE_FRAG   D  Progress Listener Registered
20:18:49.962  6736-6736  DFU              D  onResume: REGISTERING DFU progress listener
20:18:49.998  6736-6736  D8               D  CONNECTION STATUS: false
20:18:52.273  6736-6736  FW_UPDATE_FRAG   D  startDFU: StartDFU function called!
20:18:52.283  6736-6736  FW_UPDATE_FRAG   D  Retrieved FW-Package /data/user/0/PACKAGENAME/cache/FirmwareFILE.zip :FROM: /data/user/0cache/FirmwareFILE.zip :FOR: C0:6B:DE:F6:DC:1D
20:18:52.283  6736-6736  MAIN             D  incrementMacAddress: C0:6B:DE:F6:DC:1D
20:18:52.284  6736-6736  MAIN             D  MAC Incremented: C0:6B:DE:F6:DC:1E
20:18:52.284  6736-6736  FW_UPDATE_FRAG   D  startDFU: Incremented MAC :FROM: C0:6B:DE:F6:DC:1D :TO: C0:6B:DE:F6:DC:1E
20:18:52.285  6736-6736  FW_UPDATE_FRAG   D  DFU Starter started.
20:18:52.286  6736-6736  FW_UPDATE_FRAG   D  Injecting Firmware /data/user/0//cache/Firmware_FILEzip :FROM: /data/user/0/cache/Firmware_FILE.zip
20:18:52.322  6736-6736  DfuBaseService   I  DFU service created. Version: 2.8.0
20:18:52.329  6736-7259  DfuBaseService   W  Foreground service disabled. Android Oreo or newer may kill a background service few moments after user closes the application.
                                             Consider enabling foreground service using DfuServiceInitiator#setForeground(boolean)
20:18:52.388  6736-7259  DfuBaseService   I  Connecting to the device...
20:18:52.389  6736-7259  BluetoothGatt    D  connect() - device: C0:6B:DE:F6:DC:1E, auto: false
20:18:52.389  6736-7259  BluetoothGatt    D  registerApp()
20:18:52.390  6736-7259  BluetoothGatt    D  registerApp() - UUID=eb27417c-7354-4dd4-8802-9f6cca2de5a0
20:18:52.392  6736-6787  BluetoothGatt    D  onClientRegistered() - status=0 clientIf=6
20:18:57.383  6736-6736  DFU              D  onPause: UNREGISTERING DFU progress listener
20:18:57.676  6736-6736  APP_CRITICAL     W  ! SYSTEM IS TRIMMING MEMORY !

20:19:12.386  6736-6736  DFU              D  onResume: REGISTERING DFU progress listener
20:19:12.404  6736-6771  OpenGLRenderer   E  Unable to match the desired swap behavior.
20:19:12.711  6736-7040  BranchSDK        D  lastResponseMessage OK
20:19:14.558  6736-6736  DFU              D  onPause: UNREGISTERING DFU progress listener
20:19:14.985  6736-6736  APP_CRITICAL     W  ! SYSTEM IS TRIMMING MEMORY !
20:19:22.398  6736-6749  BluetoothGatt    D  onClientConnectionState() - status=133 clientIf=6 device=C0:6B:DE:F6:DC:1E
20:19:22.399  6736-6749  DfuBaseService   E  Connection state change error: 133 newState: 0
20:19:22.399  6736-7259  DfuBaseService   I  Connection error after: 30011 ms
20:19:22.399  6736-7259  DfuBaseService   E  Device not reachable. Check if the device with address C0:6B:DE:F6:DC:1E is in range, is advertising and is connectable
20:19:22.399  6736-7259  DfuBaseService   I  Retrying... (attempt 2 / 3)
20:19:22.400  6736-7259  BluetoothGatt    D  refresh() - device: C0:6B:DE:F6:DC:1E
20:19:22.402  6736-7259  DfuBaseService   I  Refreshing result: true
20:19:22.402  6736-7259  DfuBaseService   I  Cleaning up...
20:19:22.402  6736-7259  BluetoothGatt    D  cancelOpen() - device: C0:6B:DE:F6:DC:1E
20:19:22.407  6736-7259  BluetoothGatt    D  close()
20:19:22.407  6736-7259  BluetoothGatt    D  unregisterApp() - mClientIf=6
20:19:22.409  6736-7259  DfuBaseService   I  Restarting the service
20:19:22.416  6736-7259  DfuBaseService   W  Foreground service disabled. Android Oreo or newer may kill a background service few moments after user closes the application.
                                             Consider enabling foreground service using DfuServiceInitiator#setForeground(boolean)
20:19:22.417  6736-7259  DfuBaseService   I  Connecting to the device...
20:19:22.418  6736-7259  BluetoothGatt    D  connect() - device: C0:6B:DE:F6:DC:1E, auto: false
20:19:22.418  6736-7259  BluetoothGatt    D  registerApp()
20:19:22.419  6736-7259  BluetoothGatt    D  registerApp() - UUID=5b1a1be9-ef3b-46a1-af35-0eb3c59d11f3
20:19:22.421  6736-6787  BluetoothGatt    D  onClientRegistered() - status=0 clientIf=6
20:19:22.556  6736-6787  BluetoothGatt    D  onClientConnectionState() - status=0 clientIf=6 device=C0:6B:DE:F6:DC:1E
20:19:22.557  6736-6787  DfuBaseService   I  Connected to GATT server
20:19:22.567  6736-6787  BluetoothGatt    D  discoverServices() - device: C0:6B:DE:F6:DC:1E
20:19:22.568  6736-6736  DfuBaseService   I  Action received: android.bluetooth.device.action.ACL_CONNECTED
20:19:22.582  6736-6787  DfuBaseService   I  Attempting to start service discovery... succeed
20:19:23.453  6736-6787  BluetoothGatt    D  onPhyUpdate() - status=0 address=C0:6B:DE:F6:DC:1E txPhy=2 rxPhy=2
20:19:23.770  6736-6787  BluetoothGatt    D  onSearchComplete() = Device=C0:6B:DE:F6:DC:1E Status=0
20:19:23.771  6736-6787  DfuBaseService   I  Services discovered
20:19:23.777  6736-7259  DfuImpl          W  Secure DFU bootloader found
20:19:23.778  6736-7259  DfuImpl          I  Requesting MTU = 517
20:19:23.778  6736-7259  BluetoothGatt    D  configureMTU() - device: C0:6B:DE:F6:DC:1E mtu: 517
20:19:23.858  6736-6787  BluetoothGatt    D  onConfigureMTU() - Device=C0:6B:DE:F6:DC:1E mtu=247 status=0
20:19:23.859  6736-6787  DfuImpl          I  MTU changed to: 247
20:19:23.860  6736-7259  DfuImpl          I  Enabling notifications...
20:19:23.862  6736-7259  BluetoothGatt    D  setCharacteristicNotification() - uuid: 8ec90001-f315-4f60-9fb8-838830daea50 enable: true
20:19:23.904  6736-6787  BluetoothGatt    D  onConnectionUpdated() - Device=C0:6B:DE:F6:DC:1E interval=12 latency=0 timeout=600 status=0
20:19:23.918  6736-7259  DfuImpl          I  Requesting high connection priority
20:19:23.918  6736-7259  BluetoothGatt    D  requestConnectionPriority() - params: 1
20:19:23.925  6736-7259  DfuImpl          I  Setting object to Command (Op Code = 6, Type = 1)
20:19:24.010  6736-7259  DfuImpl          I  Command object info received (Max size = 512, Offset = 0, CRC = 00000000)
20:19:24.011  6736-7259  DfuImpl          I  Sending the number of packets before notifications (Op Code = 2, Value = 0)
20:19:24.039  6736-7259  DfuImpl          I  Creating Init packet object (Op Code = 1, Type = 1, Size = 141)
20:19:24.069  6736-7259  DfuImpl          I  Sending 141 bytes of init packet...
20:19:24.070  6736-7259  DfuImpl          I  Sending init packet (size: 141, value: 0x12-8A-01-0A-44-08-01-12-40-08-01-10-34-1A-02-82-02-20-00-28-00-30-00-38-B4-FC-04-42-24-08-03-12-20-B1-B1-30-C8-10-12-58-C7-75-98-F7-E7-47-49-C7-92-69-31-4D-0A-B3-07-F0-DE-E0-64-BA-1C-D5-BB-86-BA-48-00-52-04-08-01-12-00-10-00-1A-40-F3-CA-7F-9B-CD-4F-27-04-7A-D3-5A-C5-A2-7C-01-C1-3A-26-84-77-27-A9-06-A8-14-0A-77-E8-48-AB-C0-FB-62-AB-69-09-69-A2-D1-EF-39-89-A5-EC-31-2D-4F-2A-30-4E-23-20-62-5F-2F-1F-E6-A1-11-20-4E-32-FC-D6)
20:19:24.076  6736-7259  DfuImpl          I  Sending Calculate Checksum command (Op Code = 3)
20:19:24.117  6736-7259  DfuImpl          I  Checksum received (Offset = 141, CRC = 26F2449F)
20:19:24.117  6736-7259  DfuImpl          I  Executing init packet (Op Code = 4)
20:19:24.159  6736-6787  BluetoothGatt    D  onConnectionUpdated() - Device=C0:6B:DE:F6:DC:1E interval=12 latency=0 timeout=500 status=0
20:19:24.308  6736-7259  DfuImpl          I  Sending the number of packets before notifications (Op Code = 2, Value = 5)
20:19:24.353  6736-7259  DfuImpl          I  Setting object to Data (Op Code = 6, Type = 2)
20:19:24.504  6736-7259  DfuImpl          I  Data object info received (Max size = 4096, Offset = 0, CRC = 00000000)
20:19:24.505  6736-7259  DfuImpl          I  Creating Data object (Op Code = 1, Type = 2, Size = 4096) (1/20)
20:19:24.849  6736-7259  DfuImpl          I  Uploading firmware...
20:19:25.048  6736-7259  DfuImpl          I  Sending Calculate Checksum command (Op Code = 3)
20:19:25.072  6736-7259  DfuImpl          I  Checksum received (Offset = 4096, CRC = DFA634FB)
20:19:25.072  6736-7259  DfuImpl          I  Executing data object (Op Code = 4)
20:19:25.111  6736-6736  BranchSDK        D  Attempt to invoke virtual method 'java.lang.String android.net.Uri.toString()' on a null object reference
20:19:25.121  6736-6736  BranchSDK        D  Creating io.branch.referral.ServerRequestRegisterOpen@919a758 from init on thread main
20:19:25.121  6736-6736  BranchSDK        W  Warning: You are using your test app's Branch Key. Remember to change it to live Branch Key during deployment.
20:19:25.123  6736-6736  BranchSDK        D  processNextQueueItem, req io.branch.referral.ServerRequestRegisterOpen@919a758
20:19:25.130  6736-6736  DFU              D  onResume: REGISTERING DFU progress listener
20:19:25.153  6736-6771  OpenGLRenderer   E  Unable to match the desired swap behavior.
20:19:25.179  6736-7259  DfuImpl          I  Creating Data object (Op Code = 1, Type = 2, Size = 4096) (2/20)
20:19:25.506  6736-7040  BranchSDK        D  lastResponseMessage OK
20:19:25.510  6736-7259  DfuImpl          I  Uploading firmware...
20:19:25.521  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=6, speed=2.0461216, avgSpeed=4.992126, currentPart=1, partsTotal=1
20:19:25.555  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=7, speed=21.529411, avgSpeed=5.527619, currentPart=1, partsTotal=1
20:19:25.575  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=8, speed=56.307693, avgSpeed=6.148636, currentPart=1, partsTotal=1
20:19:25.650  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=9, speed=11.902439, avgSpeed=6.5606985, currentPart=1, partsTotal=1
20:19:25.691  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=10, speed=16.585365, avgSpeed=6.9072514, currentPart=1, partsTotal=1
20:19:25.696  6736-7259  DfuImpl          I  Sending Calculate Checksum command (Op Code = 3)
20:19:25.720  6736-7259  DfuImpl          I  Checksum received (Offset = 8192, CRC = 2C64A409)
20:19:25.720  6736-7259  DfuImpl          I  Executing data object (Op Code = 4)
20:19:25.823  6736-7259  DfuImpl          I  Creating Data object (Op Code = 1, Type = 2, Size = 4096) (3/20)
20:19:26.154  6736-7259  DfuImpl          I  Uploading firmware...
20:19:26.169  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=11, speed=2.041841, avgSpeed=5.5096154, currentPart=1, partsTotal=1
20:19:26.219  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=12, speed=14.64, avgSpeed=5.775963, currentPart=1, partsTotal=1
20:19:26.229  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=13, speed=73.2, avgSpeed=6.167053, currentPart=1, partsTotal=1
20:19:26.300  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=14, speed=13.746479, avgSpeed=6.466852, currentPart=1, partsTotal=1
20:19:26.335  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=15, speed=19.428572, avgSpeed=6.714754, currentPart=1, partsTotal=1
20:19:26.340  6736-7259  DfuImpl          I  Sending Calculate Checksum command (Op Code = 3)
20:19:26.378  6736-7259  DfuImpl          I  Checksum received (Offset = 12288, CRC = 7F33D7EC)
20:19:26.378  6736-7259  DfuImpl          I  Executing data object (Op Code = 4)
20:19:26.470  6736-7259  DfuImpl          I  Creating Data object (Op Code = 1, Type = 2, Size = 4096) (4/20)
20:19:26.801  6736-7259  DfuImpl          I  Uploading firmware...
20:19:26.814  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=16, speed=2.0333333, avgSpeed=5.7419915, currentPart=1, partsTotal=1
20:19:26.876  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=17, speed=12.0, avgSpeed=5.9029946, currentPart=1, partsTotal=1
20:19:26.894  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=18, speed=56.307693, avgSpeed=6.177852, currentPart=1, partsTotal=1
20:19:26.930  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=19, speed=23.804878, avgSpeed=6.4758763, currentPart=1, partsTotal=1
20:19:26.984  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=20, speed=12.592592, avgSpeed=6.6091166, currentPart=1, partsTotal=1
20:19:26.987  6736-7259  DfuImpl          I  Sending Calculate Checksum command (Op Code = 3)
20:19:27.026  6736-7259  DfuImpl          I  Checksum received (Offset = 16384, CRC = 83BF1471)
20:19:27.026  6736-7259  DfuImpl          I  Executing data object (Op Code = 4)
20:19:27.129  6736-7259  DfuImpl          I  Creating Data object (Op Code = 1, Type = 2, Size = 4096) (5/20)
20:19:27.458  6736-7259  DfuImpl          I  Uploading firmware...
20:19:27.469  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=21, speed=1.5092783, avgSpeed=5.774629, currentPart=1, partsTotal=1
20:19:27.524  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=22, speed=17.745455, avgSpeed=5.992713, currentPart=1, partsTotal=1
20:19:27.544  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=23, speed=56.307693, avgSpeed=6.208443, currentPart=1, partsTotal=1
20:19:27.571  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=24, speed=21.529411, avgSpeed=6.378343, currentPart=1, partsTotal=1
20:19:27.614  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=25, speed=22.0, avgSpeed=6.5894465, currentPart=1, partsTotal=1
20:19:27.618  6736-7259  DfuImpl          I  Sending Calculate Checksum command (Op Code = 3)
20:19:27.654  6736-7259  DfuImpl          I  Checksum received (Offset = 20480, CRC = 9790BA33)
20:19:27.654  6736-7259  DfuImpl          I  Executing data object (Op Code = 4)
20:19:27.804  6736-7259  DfuImpl          I  Creating Data object (Op Code = 1, Type = 2, Size = 4096) (6/20)
20:19:28.133  6736-7259  DfuImpl          I  Uploading firmware...
20:19:28.141  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=26, speed=1.3863636, avgSpeed=5.8338833, currentPart=1, partsTotal=1
20:19:28.202  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=27, speed=16.266666, avgSpeed=6.003247, currentPart=1, partsTotal=1
20:19:28.212  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=28, speed=66.545456, avgSpeed=6.182897, currentPart=1, partsTotal=1
20:19:28.243  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=29, speed=23.612904, avgSpeed=6.327448, currentPart=1, partsTotal=1
20:19:28.320  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=30, speed=12.0, avgSpeed=6.44194, currentPart=1, partsTotal=1
20:19:28.324  6736-7259  DfuImpl          I  Sending Calculate Checksum command (Op Code = 3)
20:19:28.358  6736-7259  DfuImpl          I  Checksum received (Offset = 24576, CRC = E95FA1ED)
20:19:28.358  6736-7259  DfuImpl          I  Executing data object (Op Code = 4)
20:19:28.494  6736-7259  DfuImpl          I  Creating Data object (Op Code = 1, Type = 2, Size = 4096) (7/20)
20:19:28.825  6736-7259  DfuImpl          I  Uploading firmware...
20:19:28.834  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=31, speed=1.4241245, avgSpeed=5.8461537, currentPart=1, partsTotal=1
20:19:28.886  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=32, speed=18.76923, avgSpeed=5.9995437, currentPart=1, partsTotal=1
20:19:28.896  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=33, speed=81.333336, avgSpeed=6.1539865, currentPart=1, partsTotal=1
20:19:28.939  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=34, speed=16.636364, avgSpeed=6.258006, currentPart=1, partsTotal=1
20:19:28.978  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=35, speed=24.31579, avgSpeed=6.411449, currentPart=1, partsTotal=1
20:19:28.981  6736-7259  DfuImpl          I  Sending Calculate Checksum command (Op Code = 3)
20:19:29.004  6736-7259  DfuImpl          I  Checksum received (Offset = 28672, CRC = 9C157933)
20:19:29.004  6736-7259  DfuImpl          I  Executing data object (Op Code = 4)
20:19:29.140  6736-7259  DfuImpl          I  Creating Data object (Op Code = 1, Type = 2, Size = 4096) (8/20)
20:19:29.469  6736-7259  DfuImpl          I  Uploading firmware...
20:19:29.479  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=36, speed=1.4581673, avgSpeed=5.91154, currentPart=1, partsTotal=1
20:19:29.531  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=37, speed=18.76923, avgSpeed=6.044568, currentPart=1, partsTotal=1
20:19:29.545  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=38, speed=81.333336, avgSpeed=6.179146, currentPart=1, partsTotal=1
20:19:29.583  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=39, speed=17.023256, avgSpeed=6.2709727, currentPart=1, partsTotal=1
20:19:29.667  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=40, speed=11.0, avgSpeed=6.347927, currentPart=1, partsTotal=1
20:19:29.669  6736-7259  DfuImpl          I  Sending Calculate Checksum command (Op Code = 3)
20:19:29.722  6736-7259  DfuImpl          I  Checksum received (Offset = 32768, CRC = B25B3CB9)
20:19:29.723  6736-7259  DfuImpl          I  Executing data object (Op Code = 4)
20:19:29.828  6736-7259  DfuImpl          I  Creating Data object (Op Code = 1, Type = 2, Size = 4096) (9/20)
20:19:30.310  6736-7259  DfuImpl          I  Uploading firmware...
20:19:30.320  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=41, speed=1.1209801, avgSpeed=5.760963, currentPart=1, partsTotal=1
20:19:30.352  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=42, speed=22.875, avgSpeed=5.854626, currentPart=1, partsTotal=1
20:19:30.371  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=43, speed=51.36842, avgSpeed=6.001023, currentPart=1, partsTotal=1
20:19:30.406  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=44, speed=20.914286, avgSpeed=6.090493, currentPart=1, partsTotal=1
20:19:30.443  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=45, speed=19.783783, avgSpeed=6.1758165, currentPart=1, partsTotal=1
20:19:30.452  6736-7259  DfuImpl          I  Sending Calculate Checksum command (Op Code = 3)
20:19:30.474  6736-7259  DfuImpl          I  Checksum received (Offset = 36864, CRC = 132FC979)
20:19:30.474  6736-7259  DfuImpl          I  Executing data object (Op Code = 4)
20:19:30.653  6736-7259  DfuImpl          I  Creating Data object (Op Code = 1, Type = 2, Size = 4096) (10/20)
20:19:30.984  6736-7259  DfuImpl          I  Uploading firmware...
20:19:30.995  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=46, speed=1.673913, avgSpeed=5.792912, currentPart=1, partsTotal=1
20:19:31.043  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=47, speed=15.25, avgSpeed=5.8623433, currentPart=1, partsTotal=1
20:19:31.065  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=48, speed=61.0, avgSpeed=5.9969482, currentPart=1, partsTotal=1
20:19:31.127  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=49, speed=10.764706, avgSpeed=6.0459075, currentPart=1, partsTotal=1
20:19:31.184  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=50, speed=13.071428, avgSpeed=6.1048217, currentPart=1, partsTotal=1
20:19:31.189  6736-7259  DfuImpl          I  Sending Calculate Checksum command (Op Code = 3)
20:19:31.223  6736-7259  DfuImpl          I  Checksum received (Offset = 40960, CRC = 645C32DD)
20:19:31.223  6736-7259  DfuImpl          I  Executing data object (Op Code = 4)
20:19:31.313  6736-7259  DfuImpl          I  Creating Data object (Op Code = 1, Type = 2, Size = 4096) (11/20)
20:19:31.658  6736-7259  DfuImpl          I  Uploading firmware...
20:19:31.667  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=51, speed=1.9090909, avgSpeed=5.821279, currentPart=1, partsTotal=1
20:19:31.704  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=52, speed=19.783783, avgSpeed=5.8930407, currentPart=1, partsTotal=1
20:19:31.716  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=53, speed=81.333336, avgSpeed=6.018583, currentPart=1, partsTotal=1
20:19:31.755  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=54, speed=18.76923, avgSpeed=6.0871725, currentPart=1, partsTotal=1
20:19:31.792  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=55, speed=19.783783, avgSpeed=6.1567173, currentPart=1, partsTotal=1
20:19:31.804  6736-7259  DfuImpl          I  Sending Calculate Checksum command (Op Code = 3)
20:19:31.852  6736-7259  DfuImpl          I  Checksum received (Offset = 45056, CRC = B8586540)
20:19:31.854  6736-7259  DfuImpl          I  Executing data object (Op Code = 4)
20:19:31.973  6736-7259  DfuImpl          I  Creating Data object (Op Code = 1, Type = 2, Size = 4096) (12/20)
20:19:32.318  6736-7259  DfuImpl          I  Uploading firmware...
20:19:32.329  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=56, speed=1.7206703, avgSpeed=5.8522496, currentPart=1, partsTotal=1
20:19:32.366  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=57, speed=19.783783, avgSpeed=5.9178224, currentPart=1, partsTotal=1
20:19:32.380  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=58, speed=73.2, avgSpeed=6.003303, currentPart=1, partsTotal=1
20:19:32.429  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=59, speed=18.415094, avgSpeed=6.08632, currentPart=1, partsTotal=1
20:19:32.468  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=60, speed=18.76923, avgSpeed=6.1484365, currentPart=1, partsTotal=1
20:19:32.475  6736-7259  DfuImpl          I  Sending Calculate Checksum command (Op Code = 3)
20:19:32.499  6736-7259  DfuImpl          I  Checksum received (Offset = 49152, CRC = 79704306)
20:19:32.499  6736-7259  DfuImpl          I  Executing data object (Op Code = 4)
20:19:32.635  6736-7259  DfuImpl          I  Creating Data object (Op Code = 1, Type = 2, Size = 4096) (13/20)
20:19:32.979  6736-7259  DfuImpl          I  Uploading firmware...
20:19:32.989  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=61, speed=1.7735125, avgSpeed=5.8797736, currentPart=1, partsTotal=1
20:19:33.022  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=62, speed=22.181818, avgSpeed=5.942938, currentPart=1, partsTotal=1
20:19:33.035  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=63, speed=56.307693, avgSpeed=6.0196953, currentPart=1, partsTotal=1
20:19:33.078  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=64, speed=22.697674, avgSpeed=6.103348, currentPart=1, partsTotal=1
20:19:33.114  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=65, speed=20.333334, avgSpeed=6.162853, currentPart=1, partsTotal=1
20:19:33.119  6736-7259  DfuImpl          I  Sending Calculate Checksum command (Op Code = 3)
20:19:33.143  6736-7259  DfuImpl          I  Checksum received (Offset = 53248, CRC = 06B880D9)
20:19:33.144  6736-7259  DfuImpl          I  Executing data object (Op Code = 4)
20:19:33.340  6736-7259  DfuImpl          I  Creating Data object (Op Code = 1, Type = 2, Size = 4096) (14/20)
20:19:33.669  6736-7259  DfuImpl          I  Uploading firmware...
20:19:33.680  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=66, speed=1.6325089, avgSpeed=5.883379, currentPart=1, partsTotal=1
20:19:33.819  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=67, speed=5.266187, avgSpeed=5.874168, currentPart=1, partsTotal=1
20:19:33.834  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=68, speed=48.8, avgSpeed=5.9431877, currentPart=1, partsTotal=1
20:19:33.871  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=69, speed=25.68421, avgSpeed=6.023273, currentPart=1, partsTotal=1
20:19:33.924  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=70, speed=13.81132, avgSpeed=6.0670915, currentPart=1, partsTotal=1
20:19:33.931  6736-7259  DfuImpl          I  Sending Calculate Checksum command (Op Code = 3)
20:19:33.967  6736-7259  DfuImpl          I  Checksum received (Offset = 57344, CRC = FECBE53C)
20:19:33.968  6736-7259  DfuImpl          I  Executing data object (Op Code = 4)
20:19:34.044  6736-7259  DfuImpl          I  Creating Data object (Op Code = 1, Type = 2, Size = 4096) (15/20)
20:19:34.373  6736-7259  DfuImpl          I  Uploading firmware...
20:19:34.383  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=71, speed=2.0218818, avgSpeed=5.879328, currentPart=1, partsTotal=1
20:19:34.433  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=72, speed=14.3529415, avgSpeed=5.923449, currentPart=1, partsTotal=1
20:19:34.446  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=73, speed=56.307693, avgSpeed=5.989337, currentPart=1, partsTotal=1
20:19:34.500  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=74, speed=18.074074, avgSpeed=6.0546274, currentPart=1, partsTotal=1
20:19:34.539  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=75, speed=18.76923, avgSpeed=6.1040463, currentPart=1, partsTotal=1
20:19:34.546  6736-7259  DfuImpl          I  Sending Calculate Checksum command (Op Code = 3)
20:19:34.570  6736-7259  DfuImpl          I  Checksum received (Offset = 61440, CRC = A366469C)
20:19:34.571  6736-7259  DfuImpl          I  Executing data object (Op Code = 4)
20:19:34.704  6736-7259  DfuImpl          I  Creating Data object (Op Code = 1, Type = 2, Size = 4096) (16/20)
20:19:35.038  6736-7259  DfuImpl          I  Uploading firmware...
20:19:35.043  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=76, speed=1.3492063, avgSpeed=5.876637, currentPart=1, partsTotal=1
20:19:35.093  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=77, speed=19.52, avgSpeed=5.9410653, currentPart=1, partsTotal=1
20:19:35.115  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=78, speed=91.5, avgSpeed=6.0056624, currentPart=1, partsTotal=1
20:19:35.145  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=79, speed=17.023256, avgSpeed=6.050193, currentPart=1, partsTotal=1
20:19:35.197  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=80, speed=18.074074, avgSpeed=6.1109138, currentPart=1, partsTotal=1
20:19:35.207  6736-7259  DfuImpl          I  Sending Calculate Checksum command (Op Code = 3)
20:19:35.245  6736-7259  DfuImpl          I  Checksum received (Offset = 65536, CRC = 3577D135)
20:19:35.245  6736-7259  DfuImpl          I  Executing data object (Op Code = 4)
20:19:35.364  6736-7259  DfuImpl          I  Creating Data object (Op Code = 1, Type = 2, Size = 4096) (17/20)
20:19:35.694  6736-7259  DfuImpl          I  Uploading firmware...
20:19:35.698  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=81, speed=1.36, avgSpeed=5.898687, currentPart=1, partsTotal=1
20:19:35.769  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=82, speed=13.746479, avgSpeed=5.9481535, currentPart=1, partsTotal=1
20:19:35.780  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=83, speed=73.2, avgSpeed=6.0078053, currentPart=1, partsTotal=1
20:19:35.815  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=84, speed=20.333334, avgSpeed=6.053404, currentPart=1, partsTotal=1
20:19:35.859  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=85, speed=22.181818, avgSpeed=6.1159062, currentPart=1, partsTotal=1
20:19:35.867  6736-7259  DfuImpl          I  Sending Calculate Checksum command (Op Code = 3)
20:19:35.889  6736-7259  DfuImpl          I  Checksum received (Offset = 69632, CRC = 6B6DE5E1)
20:19:35.890  6736-7259  DfuImpl          I  Executing data object (Op Code = 4)
20:19:36.024  6736-7259  DfuImpl          I  Creating Data object (Op Code = 1, Type = 2, Size = 4096) (18/20)
20:19:36.389  6736-7259  DfuImpl          I  Uploading firmware...
20:19:36.394  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=86, speed=1.271028, avgSpeed=5.8978887, currentPart=1, partsTotal=1
20:19:36.443  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=87, speed=19.918367, avgSpeed=5.955436, currentPart=1, partsTotal=1
20:19:36.463  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=88, speed=73.2, avgSpeed=6.0117173, currentPart=1, partsTotal=1
20:19:36.514  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=89, speed=12.2, avgSpeed=6.0426383, currentPart=1, partsTotal=1
20:19:36.581  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=90, speed=14.567164, avgSpeed=6.0899377, currentPart=1, partsTotal=1
20:19:36.587  6736-7259  DfuImpl          I  Sending Calculate Checksum command (Op Code = 3)
20:19:36.625  6736-7259  DfuImpl          I  Checksum received (Offset = 73728, CRC = B1B07584)
20:19:36.625  6736-7259  DfuImpl          I  Executing data object (Op Code = 4)
20:19:36.714  6736-7259  DfuImpl          I  Creating Data object (Op Code = 1, Type = 2, Size = 4096) (19/20)
20:19:37.045  6736-7259  DfuImpl          I  Uploading firmware...
20:19:37.048  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=91, speed=1.4529915, avgSpeed=5.916926, currentPart=1, partsTotal=1
20:19:37.066  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=92, speed=73.2, avgSpeed=5.970525, currentPart=1, partsTotal=1
20:19:37.134  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=93, speed=12.842105, avgSpeed=6.0118775, currentPart=1, partsTotal=1
20:19:37.198  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=94, speed=11.4375, avgSpeed=6.039234, currentPart=1, partsTotal=1
20:19:37.214  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=95, speed=73.2, avgSpeed=6.0921044, currentPart=1, partsTotal=1
20:19:37.256  6736-7259  DfuImpl          I  Sending Calculate Checksum command (Op Code = 3)
20:19:37.312  6736-7259  DfuImpl          I  Checksum received (Offset = 77824, CRC = 8E083571)
20:19:37.312  6736-7259  DfuImpl          I  Executing data object (Op Code = 4)
20:19:37.373  6736-7259  DfuImpl          I  Creating Data object (Op Code = 1, Type = 2, Size = 3636) (20/20)
20:19:37.737  6736-7259  DfuImpl          I  Uploading firmware...
20:19:37.743  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=96, speed=1.7271028, avgSpeed=5.915697, currentPart=1, partsTotal=1
20:19:37.764  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=97, speed=43.058823, avgSpeed=5.9633346, currentPart=1, partsTotal=1
20:19:37.822  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=98, speed=15.741936, avgSpeed=6.008861, currentPart=1, partsTotal=1
20:19:37.873  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=99, speed=14.3529415, avgSpeed=6.040694, currentPart=1, partsTotal=1
20:19:37.889  6736-6736  FW_UPDATE_FRAG   D  onProgressChanged: deviceAddress=C0:6B:DE:F6:DC:1E, percent=100, speed=44.25, avgSpeed=6.086372, currentPart=1, partsTotal=1
20:19:37.947  6736-7259  DfuImpl          I  Sending Calculate Checksum command (Op Code = 3)
20:19:37.973  6736-7259  DfuImpl          I  Checksum received (Offset = 81460, CRC = 2EC671C0)
20:19:37.973  6736-7259  DfuImpl          I  Executing data object (Op Code = 4)
20:19:38.605  6736-7259  DfuImpl          I  Transfer of 81460 bytes has taken 14100 ms
20:19:38.605  6736-6736  FW_UPDATE_FRAG   D  onDeviceDisconnecting: deviceAddress=C0:6B:DE:F6:DC:1E
20:19:39.010  6736-7386  BluetoothGatt    D  onClientConnectionState() - status=0 clientIf=6 device=C0:6B:DE:F6:DC:1E
20:19:39.011  6736-7386  DfuBaseService   I  Disconnected from GATT server
20:19:39.012  6736-7259  BluetoothGatt    D  refresh() - device: C0:6B:DE:F6:DC:1E
20:19:39.016  6736-7259  DfuBaseService   I  Refreshing result: true
20:19:39.016  6736-7259  DfuBaseService   I  Cleaning up...
20:19:39.016  6736-7259  BluetoothGatt    D  cancelOpen() - device: C0:6B:DE:F6:DC:1E
20:19:39.020  6736-7259  BluetoothGatt    D  close()
20:19:39.020  6736-7259  BluetoothGatt    D  unregisterApp() - mClientIf=6
20:19:39.023  6736-6736  FW_UPDATE_FRAG   D  onDeviceDisconnected: deviceAddress=C0:6B:DE:F6:DC:1E
20:19:39.026  6736-6736  FW_UPDATE_FRAG   D  onDfuCompleted: deviceAddress=C0:6B:DE:F6:DC:1E
20:19:39.034  6736-6736  DfuBaseService   I  DFU service destroyed
20:19:39.086  6736-6736  popFragment      D  Destroying Fragment

after user connects we show him connected screen where he can press button to go to update firmware that pushes the device in dfu mode and then dfu starts, everything works but only if connect manually or search from nrf connect app as you can see in video otherwise i receive gatt 133

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@philips77 @eshan-gr