Frequent GATT errors

[sjmerel]

Information
This GitHub Issue page is for reporting issues or asking questions regarding the iOS DFU library. For general DFU questions, SDK questions, etc, please check our DevZone.
Make sure you are using the latest version of the library:
Also, before creating a new issue, make sure similar issue isn't already opened in open or closed issues.

DFU Bootloader version (please complete the following information):

• SDK version: don't know; the firmware was provided by a 3rd party.
• Bonding used: no
• Library version: 1.11.1

Device information (please complete the following information):

• Device: various (including Pixel 2, OnePlus 3)
• OS: various (including 9.0, 11.0)

Describe the bug
Firmware updates frequently fail on some devices, when using library version 1.11.1.
DfuProgressListener.onError() is called with error=133, errorType=1, message="GATT ERROR"

This happens more frequently on some devices than on others. Note that this seems to be a new issue in library version 1.11.1; I have not been able to reproduce it with versions 1.11.0 or 1.10.4.

I ran multiple firmware updates one after the other on several devices to test:
On a Pixel 2, the error happened 5/10 times.
On a OnePlus 3, it happened 1/12 times.
One a Samsung Galaxy S10 it happened 0/10 times.

Logs

In the log below, note the line:

Scanning for new address finished with: null

The address is only null when the error occurs.

18:21:32.134 I/DfuBaseService: DFU service created. Version: 1.11.1
18:21:32.153 I/DfuBaseService: Starting DFU service in foreground
18:21:32.160 W/DfuBaseService: getNotificationTarget() should not return null if the service is to be started as a foreground service
18:21:32.238 I/DfuBaseService: Connecting to the device...
18:21:32.239 D/BluetoothGatt: connect() - device: EC:5E:29:62:B5:E8, auto: false
18:21:32.239 D/BluetoothGatt: registerApp()
18:21:32.240 D/BluetoothGatt: registerApp() - UUID=cd0731c0-ae04-40cf-be2c-4f897b4cff57
18:21:32.242 D/BluetoothGatt: onClientRegistered() - status=0 clientIf=10
18:21:32.243 D/BluetoothGatt: onClientConnectionState() - status=0 clientIf=10 device=EC:5E:29:62:B5:E8
18:21:32.243 I/DfuBaseService: Connected to GATT server
18:21:32.244 D/BluetoothGatt: discoverServices() - device: EC:5E:29:62:B5:E8
18:21:32.245 I/DfuBaseService: Attempting to start service discovery... succeed
18:21:32.249 D/BluetoothGatt: onSearchComplete() = Device=EC:5E:29:62:B5:E8 Status=0
18:21:32.249 I/DfuBaseService: Services discovered
18:21:32.252 I/DfuImpl: Buttonless service without bond sharing found -> SDK 13 or newer
18:21:33.257 I/DfuImpl: Enabling indications...
18:21:33.267 D/BluetoothGatt: setCharacteristicNotification() - uuid: 8ec90003-f315-4f60-9fb8-838830daea50 enable: true
18:21:34.263 D/BluetoothGatt: onConnectionUpdated() - Device=FA:E2:8E:ED:62:77 interval=18 latency=0 timeout=400 status=0
18:21:34.302 I/DfuImpl: Sending Enter Bootloader (Op Code = 1)
18:21:34.352 I/DfuImpl: Response received (Op Code = 1, Status = 1)
18:21:35.860 V/FA: Inactivity, disconnecting from the service
18:21:38.384 D/BluetoothGatt: onClientConnectionState() - status=8 clientIf=10 device=EC:5E:29:62:B5:E8
18:21:38.385 W/DfuBaseService: Target device disconnected with status: 8
18:21:38.386 D/BluetoothGatt: onClientConnectionState() - status=8 clientIf=11 device=EC:5E:29:62:B5:E8
18:21:38.389 W/focusmotion.tk: Accessing hidden method Landroid/bluetooth/BluetoothGatt;->refresh()Z (greylist, reflection, allowed)
18:21:38.389 D/BluetoothGatt: refresh() - device: EC:5E:29:62:B5:E8
18:21:38.391 D/BluetoothGatt: setCharacteristicNotification() - uuid: 1cac0003-656e-696c-4b5f-6e6572726157 enable: false
18:21:38.391 I/DfuBaseService: Refreshing result: true
18:21:38.391 I/DfuBaseService: Cleaning up...
18:21:38.395 D/BluetoothGatt: cancelOpen() - device: EC:5E:29:62:B5:E8
18:21:38.397 I/FM: FM INFO: io.focusmotion.ptsdk.Device$Companion: "Sensoria-C1-1D43" connected: false
18:21:38.400 D/BluetoothGatt: close()
18:21:38.400 D/BluetoothGatt: unregisterApp() - mClientIf=10
18:21:38.401 I/DfuImpl: Restarting to bootloader mode
18:21:38.402 I/FM: FM INFO: DeviceService: DeviceService: device 0: Sensoria-C1-1D43
18:21:38.407 I/FM: FM INFO: DeviceService:   storing serial DE35017C12E84212
18:21:38.411 D/BluetoothAdapter: isLeEnabled(): ON
18:21:38.411 I/FM: FM INFO: DeviceService: DeviceService: device 1: Sensoria-C1-A0A1
18:21:38.413 D/BluetoothLeScanner: onScannerRegistered() - status=0 scannerId=10 mScannerId=0
18:21:38.414 I/FM: FM INFO: DeviceService:   storing serial 3FE44A921EBC570C
18:21:38.417 I/DfuBaseService: Action received: android.bluetooth.device.action.ACL_DISCONNECTED
18:21:38.539 D/BluetoothGatt: cancelOpen() - device: EC:5E:29:62:B5:E8
18:21:38.541 D/BluetoothGatt: close()
18:21:38.541 D/BluetoothGatt: unregisterApp() - mClientIf=11
18:21:43.411 D/BluetoothAdapter: isLeEnabled(): ON
18:21:43.419 I/DfuImpl: Scanning for new address finished with: null
18:21:43.444 I/DfuBaseService: Starting DFU service in foreground
18:21:43.445 W/DfuBaseService: getNotificationTarget() should not return null if the service is to be started as a foreground service
18:21:45.465 I/DfuBaseService: Connecting to the device...
18:21:45.472 D/BluetoothGatt: connect() - device: EC:5E:29:62:B5:E8, auto: false
18:21:45.474 D/BluetoothGatt: registerApp()
18:21:45.477 D/BluetoothGatt: registerApp() - UUID=770bfdbf-ef2d-4c88-bb52-83059fa322bf
18:21:45.480 D/BluetoothGatt: onClientRegistered() - status=0 clientIf=11
18:22:15.488 D/BluetoothGatt: onClientConnectionState() - status=133 clientIf=11 device=EC:5E:29:62:B5:E8
18:22:15.489 E/DfuBaseService: Connection state change error: 133 newState: 0
18:22:15.490 I/DfuBaseService: Connection error after: 30025 ms
18:22:15.490 E/DfuBaseService: Device not reachable. Check if the device with address EC:5E:29:62:B5:E8 is in range, is advertising and is connectable
18:22:15.491 I/DfuBaseService: Attempt: 1
18:22:15.493 D/BluetoothGatt: refresh() - device: EC:5E:29:62:B5:E8
18:22:15.495 I/DfuBaseService: Refreshing result: true
18:22:15.495 I/DfuBaseService: Cleaning up...
18:22:15.497 D/BluetoothGatt: cancelOpen() - device: EC:5E:29:62:B5:E8
18:22:15.500 D/BluetoothGatt: close()
18:22:15.500 D/BluetoothGatt: unregisterApp() - mClientIf=11
18:22:15.502 I/DfuBaseService: Restarting the service
18:22:15.515 I/DfuBaseService: Starting DFU service in foreground
18:22:15.516 W/DfuBaseService: getNotificationTarget() should not return null if the service is to be started as a foreground service
18:22:17.531 I/DfuBaseService: Connecting to the device...
18:22:17.537 D/BluetoothGatt: connect() - device: EC:5E:29:62:B5:E8, auto: false
18:22:17.537 D/BluetoothGatt: registerApp()
18:22:17.541 D/BluetoothGatt: registerApp() - UUID=55fcb7bf-8046-4c28-8bc1-b9c1a6645d28
18:22:17.547 D/BluetoothGatt: onClientRegistered() - status=0 clientIf=10
18:22:47.552 D/BluetoothGatt: onClientConnectionState() - status=133 clientIf=10 device=EC:5E:29:62:B5:E8
18:22:47.553 E/DfuBaseService: Connection state change error: 133 newState: 0
18:22:47.554 I/DfuBaseService: Connection error after: 30023 ms
18:22:47.554 E/DfuBaseService: Device not reachable. Check if the device with address EC:5E:29:62:B5:E8 is in range, is advertising and is connectable
18:22:47.555 I/DfuBaseService: Attempt: 2
18:22:47.557 D/BluetoothGatt: refresh() - device: EC:5E:29:62:B5:E8
18:22:47.559 I/DfuBaseService: Refreshing result: true
18:22:47.559 I/DfuBaseService: Cleaning up...
18:22:47.561 D/BluetoothGatt: cancelOpen() - device: EC:5E:29:62:B5:E8
18:22:47.562 D/BluetoothGatt: close()
18:22:47.563 D/BluetoothGatt: unregisterApp() - mClientIf=10
18:22:47.563 I/DfuBaseService: Restarting the service
18:22:47.579 I/DfuBaseService: Starting DFU service in foreground
18:22:47.580 W/DfuBaseService: getNotificationTarget() should not return null if the service is to be started as a foreground service
18:22:49.598 I/DfuBaseService: Connecting to the device...
18:22:49.603 D/BluetoothGatt: connect() - device: EC:5E:29:62:B5:E8, auto: false
18:22:49.605 D/BluetoothGatt: registerApp()
18:22:49.608 D/BluetoothGatt: registerApp() - UUID=3cd80b94-97e9-4637-8f20-204c4d187d2e
18:22:49.616 D/BluetoothGatt: onClientRegistered() - status=0 clientIf=10
18:23:19.620 D/BluetoothGatt: onClientConnectionState() - status=133 clientIf=10 device=EC:5E:29:62:B5:E8
18:23:19.620 E/DfuBaseService: Connection state change error: 133 newState: 0
18:23:19.620 I/DfuBaseService: Connection error after: 30024 ms
18:23:19.621 E/DfuBaseService: Device not reachable. Check if the device with address EC:5E:29:62:B5:E8 is in range, is advertising and is connectable
18:23:19.621 I/DfuBaseService: Attempt: 3
18:23:19.623 D/BluetoothGatt: refresh() - device: EC:5E:29:62:B5:E8
18:23:19.623 I/DfuBaseService: Refreshing result: true
18:23:19.623 I/DfuBaseService: Cleaning up...
18:23:19.624 D/BluetoothGatt: cancelOpen() - device: EC:5E:29:62:B5:E8
18:23:19.625 D/BluetoothGatt: close()
18:23:19.625 D/BluetoothGatt: unregisterApp() - mClientIf=10
18:23:20.301 8831-8831/io.focusmotion.tkr I/DfuBaseService: DFU service destroyed

[sjmerel]

Is this library actively maintained? Seems like there hasn't been much response to the most recent bug reports. @philips77 ?

[mkotzjan]

Error 133 does happen frequently on android, it's a known issue. See here for some more informations: https://devzone.nordicsemi.com/f/nordic-q-a/33313/android-gatt-133-error

[philips77]

Hi, sorry for the delay. The library is maintained, but I'm busy with other tasks, so it waits for its time...

Looks like the issue is related to how the phone filters scan packets. Have a look at this change in the latest version: 72c0175#diff-da467c50d8806bbe969e81aba215e9b1fc4b34735e13aa46f665fb7ff565aaf6R97
I'm surprised it works only sometimes. It may be, that with the device address set as filter the phone scans for public MAC addresses. This is actually explicitly stated in Android 12: https://android.googlesource.com/platform/frameworks/base/+/master/core/java/android/bluetooth/le/ScanFilter.java#590
For me it looks, like if the device has been scanned before, Android will know the device type, so it may set type random. If it hadn't, it will assume public type and scan will fail.

[philips77]

Error 133 does happen frequently on android, it's a known issue. See here for some more informations: https://devzone.nordicsemi.com/f/nordic-q-a/33313/android-gatt-133-error

This 133 here happens after 30+ sec, so it's a timeout. Android scans for public device address, not random, so it ignores the advertising bootloader.

[philips77]

As filter is not mandatory to scan in background, I think the only thing that could be done is set a different filter. That means we may need to use the "alternative advertising name" feature made with iOS in mind (DFU from SDK 14+). Or set a different filter, e.g. with Secure DFU Service UUID, but that would need to be user configurable setting.

[sjmerel]

Background scanning seems like it's probably not a very common requirement, whereas the behavior with the current scan filter breaks DFU updates on some devices, so requiring some configuration to support background scanning seems like a reasonable tradeoff.

[sjmerel]

For what it's worth, in my own Bluetooth code I had found that scan filters worked unreliably on some of my testing devices, so I stopped using them (though again, we don't need to scan in the background).

[philips77]

Yes, we know it's unreliable. I'll check if adding an empty filter works in bg.

[QuentinFarizon]

Hello @philips77 , any news on this ? Encountering this also on some customer phones (Oppo, Xiaomi, ...)

[mattgraham1]

I was about to open a new issue, but searched for ScanFilter and found this so I'm going to add my notes here as well. As @philips77 pointed out v1.11.1 added the ability to call startScan(filters, ...) with filters on the BluetoothLeScanner, which in our scenario wouldn't find the device advertising in DFU mode (address incremented). I was able to clone the DFU code and build it within our project and found within the BootloaderScannerLollipop.java line 96 is where the filters are being added, and by commenting out lines 98/99 this issue was not reproducible, but then it also doesn't add any filters to the startScan() call. For now we are rolling back to v1.11.0 which doesn't have these filters added, but hoping this issue gets attention and also adding a ticket to our teams backlog to come back to this in the future.

The other thing I'd like to note is when I would roll back to v1.11.0 things would work fine during a firmware upgrade, but when upgrading back to v1.11.1 I was expecting it to fail again but found that it continued working just fine. However, if I powered off the Redmi phone and started a firmware upgrade process again (DFU Mode) it would more than likely, 95% always fail finding the incremented address during the DFU mode scanning. I also noticed while looking at the BootloaderScannerLollipop.java code it looks like we only scan for 5 seconds and if we timeout after 30seconds it doesn't perform another scan. This is probably a bigger change than this issue, but I feel it may be better to allow scanning for longer than 5 seconds, and at a minimum after each 30 second timeout perform another scan. Almost feels like we may want to scan for the whole connect attempt duration, which I believe is 30 seconds, and when that duration limit is reached call stopScan(). Then repeat the process for X number of attempts.

Lastly I use the nRF Toolbar app and noticed that app only uses version v1.10.3 of the DFU library. Is there any reason this app doesn't use the latest DFU library version? Reason I ask is one version considered more stable that the most recent release, or maybe its not having enough time to update all the apps utilizing this library.

Mobile Device:
Manufacturer: Redmi Note 9 Pro
OS: Android 10 QKQ1.191215.002
MIUI: MIUI Global 11.0.8

[QuentinFarizon]

I've rollbacked to 1.11.0 since mid-august and did not encounter any customer issue since.
In particular it fixed the issue on a customer's Oppo phone.

[philips77]

The scan filter was added, so that scanning was possible in background. Without fillers, scan doesn't return results. I'll release an updated version of this lib soon and will look into this issue.

Is there any reason this app doesn't use the latest DFU library version? Reason I ask is one version considered more stable that the most recent release, or maybe its not having enough time to update all the apps utilizing this library.

We're working on a new version, written in kotlin. Perhaps we'll extract dfu from nRF Toolbox and move it to a standalone app, eg. a sample app for dfu project, to make releasing own apps easier. But yes, we just don't have resources to develop new things and maintain all older apps :(

[QuentinFarizon]

@philips77 Any news about this ? Does the 1.12.0 fixes it ?