search

NordicSemiconductor / Android-BLE-Library

A library that makes working with Bluetooth LE on Android a pleasure. Seriously.
BSD 3-Clause "New" or "Revised" License
1.99k stars 415 forks source link

Error: (0x85): GATT ERROR - Connection attempt timed out #170

Closed antoniovillanova closed 4 years ago

antoniovillanova commented 4 years ago

Hi,

As shown in the title, i've an issue related to random connection timeouts that cause the user of our application to wait too long for a successful connection attempt, that hopefully happens after 10/20 seconds.

Every BLE connection it's done from the main thread as suggested in your documentation. Things i want to understand is:

Here the log i see from logcat:

2020-03-25 10:52:49.974 18680-18680/com.vimar.viewblepro V/BleManager: Connecting...
2020-03-25 10:52:49.977 18680-18680/com.vimar.viewblepro I/ExecuteGatt$gattCallback: Device connecting: A4:CF:12:9C:16:F2
2020-03-25 10:52:49.977 18680-18680/com.vimar.viewblepro D/BleManager: gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE, LE 1M)
2020-03-25 10:52:49.979 18680-18680/com.vimar.viewblepro D/BluetoothGatt: connect() - device: A4:CF:12:9C:16:F2, auto: false
2020-03-25 10:52:49.979 18680-18680/com.vimar.viewblepro D/BluetoothGatt: registerApp()
2020-03-25 10:52:49.979 18680-18680/com.vimar.viewblepro D/BluetoothGatt: registerApp() - UUID=6c84e616-7eb9-4e39-aea1-8e3026c9a587
2020-03-25 10:52:49.983 18680-19150/com.vimar.viewblepro D/BluetoothGatt: onClientRegistered() - status=0 clientIf=8
2020-03-25 10:52:53.858 18680-19150/com.vimar.viewblepro D/BluetoothGatt: onClientConnectionState() - status=133 clientIf=8 device=A4:CF:12:9C:16:F2
2020-03-25 10:52:53.858 18680-18680/com.vimar.viewblepro D/BleManager: [Callback] Connection state changed with status: 133 and new state: 0 (DISCONNECTED)
2020-03-25 10:52:53.859 18680-18680/com.vimar.viewblepro W/BleManager: Error: (0x85): GATT ERROR
2020-03-25 10:52:53.859 18680-18680/com.vimar.viewblepro W/BleManager: Connection attempt timed out
2020-03-25 10:52:53.868 18680-18680/com.vimar.viewblepro V/BleManager: Refreshing device cache...
2020-03-25 10:52:53.869 18680-18680/com.vimar.viewblepro D/BleManager: gatt.refresh() (hidden)
2020-03-25 10:52:53.869 18680-18680/com.vimar.viewblepro D/BluetoothGatt: refresh() - device: A4:CF:12:9C:16:F2
2020-03-25 10:52:53.874 18680-18680/com.vimar.viewblepro I/BleManager: Cache refreshed
2020-03-25 10:52:53.874 18680-18680/com.vimar.viewblepro D/BleManager: gatt.close()
2020-03-25 10:52:53.874 18680-18680/com.vimar.viewblepro D/BluetoothGatt: close()
2020-03-25 10:52:53.874 18680-18680/com.vimar.viewblepro D/BluetoothGatt: unregisterApp() - mClientIf=8
2020-03-25 10:52:53.879 18680-18680/com.vimar.viewblepro D/ExecuteGatt$gattCallback: device disconnected.
2020-03-25 10:52:53.880 18680-18680/com.vimar.viewblepro E/ExecuteGatt$gattCallback: Error on connection state change

Let me know if i can add some code snipper that may be helpful.

Thank you.

philips77 commented 4 years ago

Regarding connection issues, you may use retry(int, long) method in the ConnectRequest. https://github.com/NordicSemiconductor/Android-BLE-Library/blob/e95a814f4c0ecd08a75e5f0e53c68e2b8dbdf70c/ble/src/main/java/no/nordicsemi/android/ble/ConnectRequest.java#L146-L165 Have a look at nRF Blinky: https://github.com/NordicSemiconductor/Android-nRF-Blinky/blob/3b615a2a1822bbef3b82262b6541cb3bb4cc1758/app/src/main/java/no/nordicsemi/android/blinky/viewmodels/BlinkyViewModel.java#L115

Connection may end with 133 error because of multiple reasons. For example, the Connection Indication Request might have been missed by the peripheral, so it fails to respond to central's commands, and after around 4 seconds (like in your case) it aborts with 133. By using retry method you make the lib to retry in this case.

To clean the queue you can call cancelQueue() on the manager. But usually you add the requests when you're connected, so there may be nothing to cancel before connection.

antoniovillanova commented 4 years ago

Thank you for your quick answer! Actually i'm already using retry to handle random 133 that somehow fixes the use case i shown. May i ask you if there is some cases in your tests that required you to increase retry count and/or timeout to achieve better performances?

Futhermore, sadly i'm still noticing some 133 that are out of the scope of the retry method suggested. The scenario is when a connection is correctly enstablished, so the peripheral responds on the connection attempt at first (and the ConnectRequest gest unqueued), but then when android tries to update connection parameters for the discovery, sometimes it results in 

2020-03-26 12:46:43.577 30206-30206/com.vimar.viewblepro W/BleManager: Connection parameters update failed with status 19 (interval: 7.5ms, latency: 0, timeout: 5000ms)
2020-03-26 12:46:43.577 30206-30206/com.vimar.viewblepro E/NrfMeshRepository: Error: Error on connection priority request Error Code: 19 Device: D5:37:55:78:0D:FE

Usually, this happens when reconnecting to the proxy service when provisioning finish correctly. I solved the case by manually reconnecting in NrfMeshRepository callbacks handling discovery result accordingly with a proper reconnect handler. Resulting in this logcat:

2020-03-26 12:46:41.401 30206-30206/com.vimar.viewblepro D/BluetoothGatt: connect() - device: D5:37:55:78:0D:FE, auto: false
2020-03-26 12:46:41.401 30206-30206/com.vimar.viewblepro D/BluetoothGatt: registerApp()
2020-03-26 12:46:41.402 30206-30206/com.vimar.viewblepro D/BluetoothGatt: registerApp() - UUID=47fa9424-9ee6-4580-b898-892169985377
2020-03-26 12:46:41.405 30206-30236/com.vimar.viewblepro D/BluetoothGatt: onClientRegistered() - status=0 clientIf=8
2020-03-26 12:46:41.406 30206-30206/com.vimar.viewblepro I/DevicesConfigurationFragment$startProvisioning: CONNECTION STATE - Connecting....
2020-03-26 12:46:41.741 30206-30236/com.vimar.viewblepro D/BluetoothGatt: onClientConnectionState() - status=0 clientIf=8 device=D5:37:55:78:0D:FE
2020-03-26 12:46:41.742 30206-30206/com.vimar.viewblepro D/BleManager: [Callback] Connection state changed with status: 0 and new state: 2 (CONNECTED)
2020-03-26 12:46:41.742 30206-30206/com.vimar.viewblepro I/BleManager: Connected to D5:37:55:78:0D:FE
2020-03-26 12:46:41.745 30206-30206/com.vimar.viewblepro D/BleManager: wait(300)
2020-03-26 12:46:41.748 30206-30206/com.vimar.viewblepro I/DevicesConfigurationFragment$startProvisioning: CONNECTION STATE - Discovering services....
2020-03-26 12:46:42.049 30206-30206/com.vimar.viewblepro V/BleManager: Discovering services...
2020-03-26 12:46:42.050 30206-30206/com.vimar.viewblepro D/BleManager: gatt.discoverServices()
2020-03-26 12:46:42.050 30206-30206/com.vimar.viewblepro D/BluetoothGatt: discoverServices() - device: D5:37:55:78:0D:FE
2020-03-26 12:46:42.256 30206-30236/com.vimar.viewblepro D/BluetoothGatt: onPhyUpdate() - status=0 address=D5:37:55:78:0D:FE txPhy=2 rxPhy=2
2020-03-26 12:46:42.257 30206-30206/com.vimar.viewblepro I/BleManager: PHY updated (TX: LE 2M, RX: LE 2M)
2020-03-26 12:46:42.824 30206-30236/com.vimar.viewblepro D/BluetoothGatt: onConnectionUpdated() - Device=D5:37:55:78:0D:FE interval=120 latency=0 timeout=400 status=0
2020-03-26 12:46:42.826 30206-30206/com.vimar.viewblepro I/BleManager: Connection parameters updated (interval: 150.0ms, latency: 0, timeout: 4000ms)
2020-03-26 12:46:43.575 30206-30236/com.vimar.viewblepro D/BluetoothGatt: onConnectionUpdated() - Device=D5:37:55:78:0D:FE interval=6 latency=0 timeout=500 status=19
2020-03-26 12:46:43.576 30206-30206/com.vimar.viewblepro E/BleManager: onConnectionUpdated received status: 19, interval: 6, latency: 0, timeout: 500
2020-03-26 12:46:43.577 30206-30206/com.vimar.viewblepro W/BleManager: Connection parameters update failed with status 19 (interval: 7.5ms, latency: 0, timeout: 5000ms)
2020-03-26 12:46:43.577 30206-30206/com.vimar.viewblepro E/NrfMeshRepository: Error: Error on connection priority request Error Code: 19 Device: D5:37:55:78:0D:FE
2020-03-26 12:46:43.581 30206-30206/com.vimar.viewblepro I/DevicesConfigurationFragment$startProvisioning: CONNECTION STATE - Error on connection priority request
2020-03-26 12:46:43.584 30206-30236/com.vimar.viewblepro D/BluetoothGatt: onClientConnectionState() - status=19 clientIf=8 device=D5:37:55:78:0D:FE
2020-03-26 12:46:43.585 30206-30206/com.vimar.viewblepro D/BleManager: [Callback] Connection state changed with status: 19 and new state: 0 (DISCONNECTED)
2020-03-26 12:46:43.586 30206-30206/com.vimar.viewblepro W/BleManager: Error: (0x13): GATT CONN TERMINATE PEER USER
2020-03-26 12:46:43.586 30206-30206/com.vimar.viewblepro I/BleManager: Disconnected
2020-03-26 12:46:43.595 30206-30206/com.vimar.viewblepro V/BleManager: Refreshing device cache...
2020-03-26 12:46:43.595 30206-30206/com.vimar.viewblepro D/BleManager: gatt.refresh() (hidden)
2020-03-26 12:46:43.596 30206-30206/com.vimar.viewblepro D/BluetoothGatt: refresh() - device: D5:37:55:78:0D:FE
2020-03-26 12:46:43.597 30206-30206/com.vimar.viewblepro I/BleManager: Cache refreshed
2020-03-26 12:46:43.597 30206-30206/com.vimar.viewblepro D/BleManager: gatt.close()
2020-03-26 12:46:43.597 30206-30206/com.vimar.viewblepro D/BluetoothGatt: close()
2020-03-26 12:46:43.597 30206-30206/com.vimar.viewblepro D/BluetoothGatt: unregisterApp() - mClientIf=8
2020-03-26 12:46:43.599 30206-30206/com.vimar.viewblepro V/NrfMeshRepository: Disconnected
2020-03-26 12:46:43.601 30206-30206/com.vimar.viewblepro I/DevicesConfigurationFragment$startProvisioning: CONNECTION STATE - Disconnected
2020-03-26 12:46:46.605 30206-30206/com.vimar.viewblepro I/NrfMeshRepository: RECONNECTING FOR PRIORITY REQUEST ERROR
2020-03-26 12:46:46.617 30206-30206/com.vimar.viewblepro V/BleManager: Connecting...
2020-03-26 12:46:46.617 30206-30206/com.vimar.viewblepro D/BleManager: gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE, LE 1M)
2020-03-26 12:46:46.617 30206-30206/com.vimar.viewblepro D/BluetoothGatt: connect() - device: D5:37:55:78:0D:FE, auto: false
2020-03-26 12:46:46.618 30206-30206/com.vimar.viewblepro D/BluetoothGatt: registerApp()
2020-03-26 12:46:46.618 30206-30206/com.vimar.viewblepro D/BluetoothGatt: registerApp() - UUID=f2e952ef-807c-40ce-8272-b0a3d3d3fcf2
2020-03-26 12:46:46.621 30206-30236/com.vimar.viewblepro D/BluetoothGatt: onClientRegistered() - status=0 clientIf=8
2020-03-26 12:46:46.622 30206-30206/com.vimar.viewblepro I/DevicesConfigurationFragment$startProvisioning: CONNECTION STATE - Connecting....
2020-03-26 12:46:51.715 30206-30236/com.vimar.viewblepro D/BluetoothGatt: onClientConnectionState() - status=0 clientIf=8 device=D5:37:55:78:0D:FE
2020-03-26 12:46:51.715 30206-30206/com.vimar.viewblepro D/BleManager: [Callback] Connection state changed with status: 0 and new state: 2 (CONNECTED)
2020-03-26 12:46:51.716 30206-30206/com.vimar.viewblepro I/BleManager: Connected to D5:37:55:78:0D:FE
2020-03-26 12:46:51.718 30206-30206/com.vimar.viewblepro D/BleManager: wait(300)
2020-03-26 12:46:51.722 30206-30206/com.vimar.viewblepro I/DevicesConfigurationFragment$startProvisioning: CONNECTION STATE - Discovering services....
2020-03-26 12:46:52.022 30206-30206/com.vimar.viewblepro V/BleManager: Discovering services...
2020-03-26 12:46:52.022 30206-30206/com.vimar.viewblepro D/BleManager: gatt.discoverServices()
2020-03-26 12:46:52.022 30206-30206/com.vimar.viewblepro D/BluetoothGatt: discoverServices() - device: D5:37:55:78:0D:FE
2020-03-26 12:46:52.231 30206-30236/com.vimar.viewblepro D/BluetoothGatt: onPhyUpdate() - status=0 address=D5:37:55:78:0D:FE txPhy=2 rxPhy=2
2020-03-26 12:46:52.232 30206-30206/com.vimar.viewblepro I/BleManager: PHY updated (TX: LE 2M, RX: LE 2M)
2020-03-26 12:46:52.718 30206-30236/com.vimar.viewblepro D/BluetoothGatt: onConnectionUpdated() - Device=D5:37:55:78:0D:FE interval=120 latency=0 timeout=400 status=0
2020-03-26 12:46:52.719 30206-30206/com.vimar.viewblepro I/BleManager: Connection parameters updated (interval: 150.0ms, latency: 0, timeout: 4000ms)
2020-03-26 12:46:54.220 30206-30236/com.vimar.viewblepro D/BluetoothGatt: onConnectionUpdated() - Device=D5:37:55:78:0D:FE interval=6 latency=0 timeout=500 status=0
2020-03-26 12:46:54.221 30206-30206/com.vimar.viewblepro I/BleManager: Connection parameters updated (interval: 7.5ms, latency: 0, timeout: 5000ms)
2020-03-26 12:46:54.248 30206-30236/com.vimar.viewblepro D/BluetoothGatt: onSearchComplete() = Device=D5:37:55:78:0D:FE Status=0
2020-03-26 12:46:54.249 30206-30206/com.vimar.viewblepro I/BleManager: Services discovered
2020-03-26 12:46:54.250 30206-30206/com.vimar.viewblepro V/BleManager: Primary service found
2020-03-26 12:46:54.251 30206-30206/com.vimar.viewblepro I/NrfMeshRepository: CONN PRIORITY REQUEST DONE

where RECONNECTING FOR PRIORITY REQUEST ERROR indicates that my trigger was notified, and CONN PRIORITY REQUEST DONE meaning that discovery has completed successfully (so android managed to successfully update connection parameters).

Let me know if you would like to check my NrfMeshRepository implementation for more investigation.

I can also tell you, for instance, that on our BT peripherals connection parameters are set in the firmware as:

MIN_CONNECTION_INTERVAL 150ms MAX_CONNECTION_INTERVAL 250ms

Thank you again for your support.

philips77 commented 4 years ago

May i ask you if there is some cases in your tests that required you to increase retry count and/or timeout to achieve better performances?

So far I found 3 retries sufficient. But you may easily put there 10 or more, as this only matters in case the device is in range and fails to connect, so eventually it should.

I can also tell you, for instance, that on our BT peripherals connection parameters are set in the firmware as: MIN_CONNECTION_INTERVAL 150ms MAX_CONNECTION_INTERVAL 250ms

Remember, that Android will switch to connection interval 7.5 ms for service discovery (and then switch back to negotiated value. This should be handled correctly by your device.

philips77 commented 4 years ago

Error 19 refers to this https://android.googlesource.com/platform/external/bluetooth/bluedroid/+/5738f83aeb59361a0a2eda2460113f6dc9194271/stack/include/hcidefs.h#426 error. The remote device has disconnected. Check if you handle connection interval 7.5 ms correctly.

antoniovillanova commented 3 years ago

We still see some 133 errore that requires the user to perform annoying operations such as:

to make sure BT connections start to work again. Does upgrade to the latest version solve this issue 100%?

Thank you.

philips77 commented 3 years ago

No, unfortunately not. Those error are reported by the system and often not much can be done. During connection we can retry, and that is pretty much all. This needs to be fixed on the OS level, or a root cause of such problem needs to be evaluated (sometimes it is wrong connection parameter, or some timing issue, etc, and with detailed analysis this can be fixed on the fw side, but also there is no warranty that it will fail on another phone).