I'm trying to diagnose frequent (80%) DFU failures that I'm seeing with our Android application using Buttonless mode.
Our target can be 100% reliably updated with our app on IOS, nRF Connect on IOS and nRF Connect on Android. Unfortunately, it is not reliable with nRF Toolbox on Android or with our app which uses Nordic's DFU library version 1.11.0.
With our app, the DFU process starts normally, but randomly gets the dreaded Bluetooth error 133 at random points in the process. Usually, the 133 error occurs shortly after the initial reboot into bootloader command.
Because the DFU is 100% reliable with the same phone and target when I use Nordic's nRF Connect tool, I am very interested in understanding any code differences between nrf Connect (Android) and nRF Toolbox (Android) since the former works perfectly and the later works with the same failure rate as our custom app. Is it possible to get access to the nRF Connect codebase related to DFU updates?
FWIW, here is a sample log file from our application when it fails. Any help would be greatly appreciated.
2020-11-19 14:08:22.101 22994-22994/com.soovu.app I/DfuBaseService: DFU service created. Version: 1.11.0
2020-11-19 14:08:22.116 22994-25429/com.soovu.app I/DfuBaseService: Starting DFU service in foreground
2020-11-19 14:08:22.117 22994-25245/com.soovu.app D/AWSMobileClient: Inspecting user state details
2020-11-19 14:08:22.160 22994-25429/com.soovu.app I/DfuBaseService: Connecting to the device...
2020-11-19 14:08:22.160 22994-25429/com.soovu.app D/BluetoothAdapter: STATE_ON
2020-11-19 14:08:22.161 22994-25429/com.soovu.app D/BluetoothGatt: connect() - device: D1:49:63:0C:90:5E, auto: false
2020-11-19 14:08:22.162 22994-25429/com.soovu.app D/BluetoothAdapter: isSecureModeEnabled
2020-11-19 14:08:22.162 22994-25429/com.soovu.app D/BluetoothGatt: registerApp()
2020-11-19 14:08:22.162 22994-25429/com.soovu.app D/BluetoothGatt: registerApp() - UUID=3858ce05-7930-49f1-86ba-ef7d4675f172
2020-11-19 14:08:22.164 22994-25231/com.soovu.app D/BluetoothGatt: onClientRegistered() - status=0 clientIf=15
2020-11-19 14:08:22.168 22994-25231/com.soovu.app D/BluetoothGatt: onClientConnectionState() - status=0 clientIf=15 device=D1:49:63:0C:90:5E
2020-11-19 14:08:22.171 22994-25231/com.soovu.app I/DfuBaseService: Connected to GATT server
2020-11-19 14:08:22.172 22994-25231/com.soovu.app I/DfuBaseService: Waiting 1600 ms for a possible Service Changed indication...
2020-11-19 14:08:22.459 22994-25245/com.soovu.app D/AWSMobileClient: hasFederatedToken: true provider: cognito-idp.us-west-2.amazonaws.com/us-west-2_QQh5uQhs3
2020-11-19 14:08:22.459 22994-25245/com.soovu.app D/AWSMobileClient: waitForSignIn: userState:SIGNED_IN
2020-11-19 14:08:23.774 22994-25231/com.soovu.app D/BluetoothGatt: discoverServices() - device: D1:49:63:0C:90:5E
2020-11-19 14:08:23.776 22994-25231/com.soovu.app I/DfuBaseService: Attempting to start service discovery... succeed
2020-11-19 14:08:23.791 22994-25231/com.soovu.app D/BluetoothGatt: onSearchComplete() = Device=D1:49:63:0C:90:5E Status=0
2020-11-19 14:08:23.792 22994-25231/com.soovu.app I/DfuBaseService: Services discovered
2020-11-19 14:08:23.796 22994-25429/com.soovu.app I/DfuImpl: Reading Service Changed CCCD value...
2020-11-19 14:08:23.882 22994-25429/com.soovu.app I/DfuImpl: Service Changed indications enabled
2020-11-19 14:08:23.882 22994-25429/com.soovu.app I/DfuImpl: Buttonless service with bond sharing found -> SDK 14 or newer
2020-11-19 14:08:23.886 22994-22994/com.soovu.app E/JP: DFU: onDeviceConnected(D1:49:63:0C:90:5E)
2020-11-19 14:08:23.927 22994-22994/com.soovu.app E/JP: DFU: onProcessStarting(D1:49:63:0C:90:5E)
2020-11-19 14:08:23.932 22994-22994/com.soovu.app D/Dialog: mIsSamsungBasicInteraction = false
2020-11-19 14:08:23.932 22994-22994/com.soovu.app D/Dialog: mIsSamsungBasicInteraction = false, isMetaDataInActivity = false
2020-11-19 14:08:23.943 22994-22994/com.soovu.app I/MultiWindowDecorSupport: [INFO] isPopOver = false
2020-11-19 14:08:23.943 22994-22994/com.soovu.app I/MultiWindowDecorSupport: updateCaptionType >> DecorView@33164c9[], isFloating: true, isApplication: true, hasWindowDecorCaption: false, hasWindowControllerCallback: false
2020-11-19 14:08:23.943 22994-22994/com.soovu.app D/MultiWindowDecorSupport: setCaptionType = 0, DecorView = DecorView@33164c9[]
2020-11-19 14:08:24.017 22994-22994/com.soovu.app D/ScrollView: initGoToTop
2020-11-19 14:08:24.097 22994-22994/com.soovu.app I/ViewRootImpl@1105aa8[MainActivity]: setView = com.android.internal.policy.DecorView@33164c9 TM=true MM=false
2020-11-19 14:08:24.184 22994-22994/com.soovu.app I/ViewRootImpl@1105aa8[MainActivity]: Relayout returned: old=(0,112,1080,2241) new=(28,847,1052,1393) req=(1024,546)0 dur=11 res=0x7 s={true 477064548352} ch=true
2020-11-19 14:08:24.186 22994-25102/com.soovu.app D/OpenGLRenderer: createReliableSurface : 0x6f23a3b440(0x6f13435000)
2020-11-19 14:08:24.187 22994-25102/com.soovu.app D/OpenGLRenderer: eglCreateWindowSurface : 0x6f23a38880
2020-11-19 14:08:24.218 22994-22994/com.soovu.app E/DecorView: mWindow.mActivityCurrentConfig is null
2020-11-19 14:08:24.228 22994-25102/com.soovu.app D/OpenGLRenderer: makeCurrent EglSurface : 0x6f78a0a000 -> 0x6f23a38880
2020-11-19 14:08:24.234 22994-22994/com.soovu.app I/ViewRootImpl@1105aa8[MainActivity]: MSG_WINDOW_FOCUS_CHANGED 1 1
2020-11-19 14:08:24.249 22994-22994/com.soovu.app I/ViewRootImpl@b640220[MainActivity]: MSG_WINDOW_FOCUS_CHANGED 0 1
2020-11-19 14:08:24.250 22994-22994/com.soovu.app D/InputMethodManager: prepareNavigationBarInfo() DecorView@6bacee5[MainActivity]
2020-11-19 14:08:24.250 22994-22994/com.soovu.app D/InputMethodManager: getNavigationBarColor() -855310
2020-11-19 14:08:24.261 22994-22994/com.soovu.app I/ViewRootImpl@1105aa8[MainActivity]: MSG_RESIZED: frame=(28,847,1052,1393) ci=(0,0,0,0) vi=(0,0,0,0) or=1
2020-11-19 14:08:24.268 22994-25102/com.soovu.app D/OpenGLRenderer: makeCurrent EglSurface : 0x6f23a38880 -> 0x6f78a0a000
2020-11-19 14:08:24.274 22994-25102/com.soovu.app D/OpenGLRenderer: makeCurrent EglSurface : 0x6f78a0a000 -> 0x6f23a38880
2020-11-19 14:08:24.914 22994-25429/com.soovu.app I/DfuImpl: Enabling indications...
2020-11-19 14:08:24.916 22994-25429/com.soovu.app D/BluetoothGatt: setCharacteristicNotification() - uuid: 8ec90004-f315-4f60-9fb8-838830daea50 enable: true
2020-11-19 14:08:26.007 22994-22994/com.soovu.app E/JP: DFU: onEnablingDfuMode(D1:49:63:0C:90:5E)
2020-11-19 14:08:26.029 22994-25429/com.soovu.app I/DfuImpl: Sending Enter Bootloader (Op Code = 1)
2020-11-19 14:08:26.125 22994-25429/com.soovu.app I/DfuImpl: Response received (Op Code = 1, Status = 1)
2020-11-19 14:08:31.199 22994-25282/com.soovu.app D/BluetoothGatt: onClientConnectionState() - status=8 clientIf=15 device=D1:49:63:0C:90:5E
2020-11-19 14:08:31.209 22994-25282/com.soovu.app W/DfuBaseService: Target device disconnected with status: 8
2020-11-19 14:08:31.213 22994-25429/com.soovu.app I/DfuBaseService: Cleaning up...
2020-11-19 14:08:31.213 22994-25429/com.soovu.app D/BluetoothGatt: cancelOpen() - device: D1:49:63:0C:90:5E
2020-11-19 14:08:31.222 22994-22994/com.soovu.app I/DfuBaseService: Action received: android.bluetooth.device.action.ACL_DISCONNECTED
2020-11-19 14:08:31.249 22994-25429/com.soovu.app D/BluetoothGatt: close()
2020-11-19 14:08:31.260 22994-25429/com.soovu.app D/BluetoothGatt: unregisterApp() - mClientIf=15
2020-11-19 14:08:31.264 22994-25429/com.soovu.app I/DfuImpl: Restarting to bootloader mode
2020-11-19 14:08:31.296 22994-25429/com.soovu.app I/DfuBaseService: Starting DFU service in foreground
2020-11-19 14:08:33.325 22994-22994/com.soovu.app E/JP: DFU: onDeviceConnecting(D1:49:63:0C:90:5E)
2020-11-19 14:08:33.348 22994-25429/com.soovu.app I/DfuBaseService: Connecting to the device...
2020-11-19 14:08:33.349 22994-25429/com.soovu.app D/BluetoothAdapter: STATE_ON
2020-11-19 14:08:33.352 22994-25429/com.soovu.app D/BluetoothGatt: connect() - device: D1:49:63:0C:90:5E, auto: false
2020-11-19 14:08:33.352 22994-25429/com.soovu.app D/BluetoothAdapter: isSecureModeEnabled
2020-11-19 14:08:33.353 22994-25429/com.soovu.app D/BluetoothGatt: registerApp()
2020-11-19 14:08:33.353 22994-25429/com.soovu.app D/BluetoothGatt: registerApp() - UUID=bb7c6576-79df-46e2-bc8e-d7f0a7dfac8a
2020-11-19 14:08:33.357 22994-25282/com.soovu.app D/BluetoothGatt: onClientRegistered() - status=0 clientIf=15
2020-11-19 14:08:33.449 22994-25282/com.soovu.app D/BluetoothGatt: onClientConnectionState() - status=0 clientIf=15 device=D1:49:63:0C:90:5E
2020-11-19 14:08:33.460 22994-25282/com.soovu.app I/DfuBaseService: Connected to GATT server
2020-11-19 14:08:33.462 22994-25282/com.soovu.app I/DfuBaseService: Waiting 1600 ms for a possible Service Changed indication...
2020-11-19 14:08:33.480 22994-22994/com.soovu.app I/DfuBaseService: Action received: android.bluetooth.device.action.ACL_CONNECTED
2020-11-19 14:08:35.064 22994-25282/com.soovu.app D/BluetoothGatt: discoverServices() - device: D1:49:63:0C:90:5E
2020-11-19 14:08:35.067 22994-25282/com.soovu.app I/DfuBaseService: Attempting to start service discovery... succeed
2020-11-19 14:08:35.068 22994-25282/com.soovu.app D/BluetoothGatt: onConnectionUpdated() - Device=D1:49:63:0C:90:5E interval=12 latency=0 timeout=600 status=0
2020-11-19 14:08:35.068 22994-25282/com.soovu.app D/BluetoothGatt: onConnectionUpdated() - Device=D1:49:63:0C:90:5E interval=6 latency=0 timeout=500 status=0
2020-11-19 14:08:35.069 22994-25282/com.soovu.app D/BluetoothGatt: onConnectionUpdated() - Device=D1:49:63:0C:90:5E interval=12 latency=0 timeout=600 status=0
2020-11-19 14:08:35.076 22994-25282/com.soovu.app D/BluetoothGatt: onSearchComplete() = Device=D1:49:63:0C:90:5E Status=0
2020-11-19 14:08:35.077 22994-25282/com.soovu.app I/DfuBaseService: Services discovered
2020-11-19 14:08:35.082 22994-25429/com.soovu.app I/DfuImpl: Reading Service Changed CCCD value...
2020-11-19 14:08:35.120 22994-25429/com.soovu.app I/DfuImpl: Service Changed indications enabled
2020-11-19 14:08:35.121 22994-25429/com.soovu.app W/DfuImpl: Secure DFU bootloader found
2020-11-19 14:08:35.123 22994-22994/com.soovu.app E/JP: DFU: onDeviceConnected(D1:49:63:0C:90:5E)
2020-11-19 14:08:35.123 22994-22994/com.soovu.app E/JP: DFU: onProcessStarting(D1:49:63:0C:90:5E)
2020-11-19 14:08:36.146 22994-25429/com.soovu.app I/DfuImpl: Requesting MTU = 517
2020-11-19 14:08:36.147 22994-25429/com.soovu.app D/BluetoothGatt: configureMTU() - device: D1:49:63:0C:90:5E mtu: 517
2020-11-19 14:08:36.182 22994-25282/com.soovu.app D/BluetoothGatt: onConfigureMTU() - Device=D1:49:63:0C:90:5E mtu=247 status=0
2020-11-19 14:08:36.183 22994-25282/com.soovu.app I/DfuImpl: MTU changed to: 247
2020-11-19 14:08:36.184 22994-25429/com.soovu.app I/DfuImpl: Enabling notifications...
2020-11-19 14:08:36.187 22994-25429/com.soovu.app D/BluetoothGatt: setCharacteristicNotification() - uuid: 8ec90001-f315-4f60-9fb8-838830daea50 enable: true
2020-11-19 14:08:37.247 22994-25429/com.soovu.app I/DfuImpl: Resume feature disabled. Performing fresh DFU
2020-11-19 14:08:37.248 22994-25429/com.soovu.app I/DfuImpl: Setting object to Command (Op Code = 6, Type = 1)
2020-11-19 14:08:42.445 22994-25282/com.soovu.app E/DfuImpl: Characteristic write error: 133
2020-11-19 14:08:42.446 22994-25231/com.soovu.app D/BluetoothGatt: onClientConnectionState() - status=8 clientIf=15 device=D1:49:63:0C:90:5E
2020-11-19 14:08:42.451 22994-25429/com.soovu.app E/DfuBaseService: Unable to write Op Code 6 (error 133)
2020-11-19 14:08:42.457 22994-22994/com.soovu.app E/JP: DFU: onDeviceDisconnecting(D1:49:63:0C:90:5E)
2020-11-19 14:08:42.461 22994-25231/com.soovu.app W/DfuBaseService: Target device disconnected with status: 8
2020-11-19 14:08:42.471 22994-22994/com.soovu.app I/DfuBaseService: Action received: android.bluetooth.device.action.ACL_DISCONNECTED
2020-11-19 14:08:42.485 22994-25429/com.soovu.app I/DfuBaseService: Disconnecting from the device...
2020-11-19 14:08:42.485 22994-25429/com.soovu.app D/BluetoothGatt: cancelOpen() - device: D1:49:63:0C:90:5E
2020-11-19 14:08:42.505 22994-25429/com.soovu.app I/DfuBaseService: Cleaning up...
2020-11-19 14:08:42.506 22994-25429/com.soovu.app D/BluetoothGatt: cancelOpen() - device: D1:49:63:0C:90:5E
2020-11-19 14:08:42.517 22994-25429/com.soovu.app D/BluetoothGatt: close()
2020-11-19 14:08:42.520 22994-25429/com.soovu.app D/BluetoothGatt: unregisterApp() - mClientIf=15
2020-11-19 14:08:43.126 22994-22994/com.soovu.app E/JP: DFU: onDeviceDisconnected(D1:49:63:0C:90:5E)
2020-11-19 14:08:43.126 22994-22994/com.soovu.app E/JP: DFU: onError(D1:49:63:0C:90:5E)
