• State Not Answered
  • +1 person also asked this people also asked this
  • Replies 5 replies
  • Subscribers 67 subscribers
  • Views 3648 views
  • Users 0 members are here
Attachments (1) Download All
Nordic Case Info
  • Case ID: 213473
Options
This post is older than 2 years and might not be relevant anymore
More Info: Consider searching for newer posts

Android Automatically Unbonding on Reconnection

hammerfet

We seem to be having an issue on several Android devices, where reconnecting sometimes triggers an erroneous GATT_INSUF_AUTHORIZATION. This then causes Android to automatically delete the bond information on the phone, meaning our device needs repairing.

Our application uses the same pairing strategy as the ANCS examples found in SDKs 14 and 15. This is easily reproducible using Android nRF connect along with ble_app_ancs_c_pca10040_s132.hex.

The phones that we can reproduce this on so far:

Huawei P10 Lite (Android 7.0)
Pixel (Android 8.0)
Nexus X5, Nokia 6.1 and Pixel (Android 8.1)

So what's going on here that causes this issue? Is there a potential solution?

Android Log:

nRF Connect, 2018-09-06
ANCS (C2:C9:8C:56:D1:0D)
V	10:33:12.318	Connecting to C2:C9:8C:56:D1:0D...
D	10:33:12.318	gatt = device.connectGatt(autoConnect = true, TRANSPORT_LE, preferred PHY = LE 1M)
D	10:33:12.332	[Callback] Connection state changed with status: 0 and new state: CONNECTED (2)
I	10:33:12.332	Connected to C2:C9:8C:56:D1:0D
D	10:33:12.333	wait(1600ms)
V	10:33:13.935	Discovering services...
D	10:33:13.935	gatt.discoverServices()
D	10:33:13.969	[Callback] Services discovered with status: 0
I	10:33:13.969	Services discovered
V	10:33:13.983	Generic Access (0x1800)
- Device Name [R W] (0x2A00)
- Appearance [R] (0x2A01)
- Peripheral Preferred Connection Parameters [R] (0x2A04)
- Central Address Resolution [R] (0x2AA6)
Generic Attribute (0x1801)
D	10:36:03.929	[Callback] Connection state changed with status: 8 and new state: DISCONNECTED (0)
E	10:36:03.929	Error 8 (0x8): GATT CONN TIMEOUT
I	10:36:03.929	Disconnected
D	10:36:03.985	[Broadcast] Action received: android.bluetooth.device.action.ACL_DISCONNECTED
D	10:36:18.163	[Broadcast] Action received: android.bluetooth.device.action.ACL_CONNECTED
D	10:36:18.163	[Callback] Connection state changed with status: 0 and new state: CONNECTED (2)
I	10:36:18.163	Connected to C2:C9:8C:56:D1:0D
D	10:36:18.253	wait(1600ms)
I	10:36:19.584	Connection parameters updated (interval: 7.5ms, latency: 0, timeout: 5000ms)
V	10:36:19.854	Discovering services...
D	10:36:19.854	gatt.discoverServices()
D	10:36:24.555	[Callback] Connection state changed with status: 8 and new state: DISCONNECTED (0)
E	10:36:24.555	Error 8 (0x8): GATT CONN TIMEOUT
I	10:36:24.555	Disconnected
D	10:36:24.600	[Broadcast] Action received: android.bluetooth.device.action.ACL_DISCONNECTED
D	10:36:30.930	[Callback] Connection state changed with status: 0 and new state: CONNECTED (2)
D	10:36:30.930	[Broadcast] Action received: android.bluetooth.device.action.ACL_CONNECTED
D	10:36:30.930	gatt.close()
I	10:36:30.966	Connected to C2:C9:8C:56:D1:0D
D	10:36:30.966	wait(200)
D	10:36:30.980	wait(1600ms)
V	10:36:31.168	Connecting to C2:C9:8C:56:D1:0D...
D	10:36:31.169	gatt = device.connectGatt(autoConnect = true, TRANSPORT_LE, preferred PHY = LE 1M)
D	10:36:31.193	[Callback] Connection state changed with status: 0 and new state: CONNECTED (2)
I	10:36:31.193	Connected to C2:C9:8C:56:D1:0D
D	10:36:31.195	wait(1600ms)
I	10:36:31.368	Connection parameters updated (interval: 7.5ms, latency: 0, timeout: 5000ms)
I	10:36:31.638	Connection parameters updated (interval: 45.0ms, latency: 0, timeout: 5000ms)
V	10:36:32.582	Discovering services...
D	10:36:32.582	gatt.discoverServices()
D	10:36:32.610	[Callback] Services discovered with status: 0
I	10:36:32.610	Services discovered
V	10:36:32.625	Generic Access (0x1800)
- Device Name [R W] (0x2A00)
- Appearance [R] (0x2A01)
- Peripheral Preferred Connection Parameters [R] (0x2A04)
- Central Address Resolution [R] (0x2AA6)
Generic Attribute (0x1801)
V	10:36:32.795	Discovering services...
D	10:36:32.795	gatt.discoverServices()
D	10:36:32.816	[Callback] Services discovered with status: 0
I	10:36:32.816	Services discovered
V	10:36:32.836	Generic Access (0x1800)
- Device Name [R W] (0x2A00)
- Appearance [R] (0x2A01)
- Peripheral Preferred Connection Parameters [R] (0x2A04)
- Central Address Resolution [R] (0x2AA6)
Generic Attribute (0x1801)
I	10:36:37.846	Connection parameters updated (interval: 997.5ms, latency: 0, timeout: 4000ms)
D	10:36:49.032	[Callback] Connection state changed with status: 8 and new state: DISCONNECTED (0)
E	10:36:49.032	Error 8 (0x8): GATT CONN TIMEOUT
I	10:36:49.032	Disconnected
D	10:36:49.091	[Broadcast] Action received: android.bluetooth.device.action.ACL_DISCONNECTED
D	10:36:53.291	[Broadcast] Action received: android.bluetooth.device.action.ACL_CONNECTED
D	10:36:53.291	gatt.close()
D	10:36:53.309	wait(200)
V	10:36:53.511	Connecting to C2:C9:8C:56:D1:0D...
D	10:36:53.512	gatt = device.connectGatt(autoConnect = true, TRANSPORT_LE, preferred PHY = LE 1M)
D	10:36:53.541	[Callback] Connection state changed with status: 0 and new state: CONNECTED (2)
I	10:36:53.541	Connected to C2:C9:8C:56:D1:0D
D	10:36:53.544	wait(1600ms)
I	10:36:54.273	Connection parameters updated (interval: 7.5ms, latency: 0, timeout: 5000ms)
I	10:36:54.452	Connection parameters updated (interval: 45.0ms, latency: 0, timeout: 5000ms)
V	10:36:55.144	Discovering services...
D	10:36:55.144	gatt.discoverServices()
D	10:36:55.167	[Callback] Services discovered with status: 0
I	10:36:55.167	Services discovered
V	10:36:55.173	Generic Access (0x1800)
- Device Name [R W] (0x2A00)
- Appearance [R] (0x2A01)
- Peripheral Preferred Connection Parameters [R] (0x2A04)
- Central Address Resolution [R] (0x2AA6)
Generic Attribute (0x1801)
I	10:36:58.780	Connection parameters updated (interval: 997.5ms, latency: 0, timeout: 4000ms)
D	10:37:10.723	[Callback] Connection state changed with status: 8 and new state: DISCONNECTED (0)
D	10:37:10.723	[Broadcast] Action received: android.bluetooth.device.action.ACL_DISCONNECTED
E	10:37:10.724	Error 8 (0x8): GATT CONN TIMEOUT
I	10:37:10.724	Disconnected
D	10:37:14.623	[Broadcast] Action received: android.bluetooth.device.action.ACL_CONNECTED
D	10:37:14.623	[Callback] Connection state changed with status: 0 and new state: CONNECTED (2)
I	10:37:14.623	Connected to C2:C9:8C:56:D1:0D
D	10:37:14.653	wait(1600ms)
V	10:37:16.255	Discovering services...
D	10:37:16.255	gatt.discoverServices()
D	10:37:16.290	[Callback] Services discovered with status: 0
I	10:37:16.290	Services discovered
V	10:37:16.325	Generic Access (0x1800)
- Device Name [R W] (0x2A00)
- Appearance [R] (0x2A01)
- Peripheral Preferred Connection Parameters [R] (0x2A04)
- Central Address Resolution [R] (0x2AA6)
Generic Attribute (0x1801)
W	10:37:23.811	Connection parameters update failed with status 8 (interval: 45.0ms, latency: 0, timeout: 5000ms)
E	10:37:23.811	Error 8 (0x8): GATT INSUF AUTHORIZATION
D	10:37:23.911	[Callback] Connection state changed with status: 8 and new state: DISCONNECTED (0)
D	10:37:23.911	[Broadcast] Action received: android.bluetooth.device.action.BOND_STATE_CHANGED, bond state changed to: BOND_NONE (10)
E	10:37:23.911	Error 8 (0x8): GATT CONN TIMEOUT
I	10:37:23.911	Disconnected
I	10:37:23.911	Bond information deleted
D	10:37:23.911	[Broadcast] Action received: android.bluetooth.device.action.ACL_DISCONNECTED

Parents
  • 0

    I've also seen this a number of times but cannot reliably reproduce the issue.

    The only way I've been able to reproduce on occasion is the following setup:

    • Bond to a target device (In our case an nRF52840 with S140)
    • Use Android nRF Connect and connect with Autoconnect turned on.
    • Move Android device and target device apart so that the are at the limit of connection range.
    • BLE connection drops out and Android phone attempts to reconnect to target.
    • After reconnection, bonding information is sometimes deleted from the phone.

    The following Android nRF Connect log shows an example of this occurring on a Samsung S6, Android 70

    As seen from this log, it appears as though the Android phone is attempting to discover services on the target (not really sure why, as the services should already be available for a device which as already been bonded).

    My suspicion is that the Android BLE stack automatically removes bonding information for a device if it cannot successfully discover services after the initial bonding key exchange has been completed.  i.e. If the BLE connection is good enough to allow key exchange, but then there are packets lost during BLE service discovery, the Android BLE subsystems sets the device state as unbonded.

    I 11:55:14.038 Notification received from 001c0005-99f7-af8f-6b4e-1e1624b9d72e, value: (0x) 00-00-0F-AD-FF-FF-FF-E9
A 11:55:14.038 "(0x) 00-00-0F-AD-FF-FF-FF-E9" received
I 11:55:59.056 Notification received from 001c0005-99f7-af8f-6b4e-1e1624b9d72e, value: (0x) 00-00-0F-AD-FF-FF-FF-EF
A 11:55:59.056 "(0x) 00-00-0F-AD-FF-FF-FF-EF" received
I 11:55:59.058 Notification received from 001c0005-99f7-af8f-6b4e-1e1624b9d72e, value: (0x) 00-00-0F-AE-00-00-0F-54
A 11:55:59.058 "(0x) 00-00-0F-AE-00-00-0F-54" received
D 11:56:35.047 [Server callback] Connection state changed with status: 0 and new state: DISCONNECTED (0)
I 11:56:35.047 [Server] Device disconnected
D 11:56:35.085 [Callback] Connection state changed with status: 8 and new state: DISCONNECTED (0)
E 11:56:35.086 Error 8 (0x8): GATT CONN TIMEOUT
I 11:56:35.086 Disconnected
D 11:56:35.120 [Broadcast] Action received: android.bluetooth.device.action.ACL_DISCONNECTED
D 11:58:11.392 [Server callback] Connection state changed with status: 0 and new state: CONNECTED (2)
I 11:58:11.392 [Server] Device with address E1:FB:ED:C3:13:E7 connected
V 11:58:11.392 [Server] Creating server connection...
D 11:58:11.392 server.connect(device, autoConnect = true)
V 11:58:11.404 Connecting to E1:FB:ED:C3:13:E7...
D 11:58:11.404 gatt.connect()
D 11:58:11.508 [Broadcast] Action received: android.bluetooth.device.action.ACL_CONNECTED
D 11:58:11.514 [Callback] Connection state changed with status: 0 and new state: CONNECTED (2)
I 11:58:11.514 Connected to E1:FB:ED:C3:13:E7
D 11:58:11.518 wait(1600ms)
D 11:58:11.539 [Callback] Connection state changed with status: 0 and new state: CONNECTED (2)
V 11:58:13.123 Discovering services...
D 11:58:13.123 gatt.discoverServices()
D 11:58:32.061 [Server callback] Connection state changed with status: 0 and new state: DISCONNECTED (0)
I 11:58:32.061 [Server] Device disconnected
D 11:58:32.171 [Broadcast] Action received: android.bluetooth.device.action.BOND_STATE_CHANGED, bond state changed to: BOND_NONE (10)
I 11:58:32.171 Bond information deleted
D 11:58:32.187 [Callback] Connection state changed with status: 8 and new state: DISCONNECTED (0)
E 11:58:32.187 Error 8 (0x8): GATT CONN TIMEOUT
I 11:58:32.187 Disconnected
D 11:58:32.235 [Broadcast] Action received: android.bluetooth.device.action.ACL_DISCONNECTED
D 16:05:34.028 gatt.close()
D 16:05:34.031 wait(200)
V 16:05:34.234 Connecting to E1:FB:ED:C3:13:E7...
D 16:05:34.235 gatt = device.connectGatt(autoConnect = true, TRANSPORT_LE)
D 16:05:46.070 [Server callback] Connection state changed with status: 0 and new state: CONNECTED (2)
I 16:05:46.070 [Server] Device with address E1:FB:ED:C3:13:E7 connected
V 16:05:46.070 [Server] Creating server connection...
D 16:05:46.071 server.connect(device, autoConnect = true)
D 16:05:46.144 [Callback] Connection state changed with status: 0 and new state: CONNECTED (2)
I 16:05:46.144 Connected to E1:FB:ED:C3:13:E7
D 16:05:46.148 [Broadcast] Action received: android.bluetooth.device.action.ACL_CONNECTED
V 16:05:46.161 Discovering services...
D 16:05:46.161 gatt.discoverServices()
D 16:05:46.865 [Broadcast] Action received: android.bluetooth.device.action.BOND_STATE_CHANGED, bond state changed to: BOND_BONDING (11)
D 16:05:46.924 [Server callback] Connection state changed with status: 0 and new state: DISCONNECTED (0)
I 16:05:46.924 [Server] Device disconnected
D 16:05:46.927 [Broadcast] Action received: android.bluetooth.device.action.BOND_STATE_CHANGED, bond state changed to: BOND_NONE (10)
I 16:05:46.930 Bonding failed
D 16:05:46.931 [Callback] Connection state changed with status: 19 and new state: DISCONNECTED (0)
W 16:05:46.931 Connection terminated by peer (status 19)
I 16:05:46.931 Disconnected
D 16:05:47.042 [Broadcast] Action received: android.bluetooth.device.action.ACL_DISCONNECTED

    I have also seen logs similar to your with failure occurring after a GATT INSUF AUTHORIZATION message (See attached log)

    bonding-removed-nrf-connect-log.txt

    I haven't had a chance to test, but you could try using the Android HCI snoop log to get more information about what is happening at the BLE HCI layer when this happens.

    http://www.fte.com/WebHelp/BPA600/Content/Documentation/WhitePapers/BPA600/Encryption/GettingAndroidLinkKey/RetrievingHCIlog.htm

Reply
  • 0

    I've also seen this a number of times but cannot reliably reproduce the issue.

    The only way I've been able to reproduce on occasion is the following setup:

    • Bond to a target device (In our case an nRF52840 with S140)
    • Use Android nRF Connect and connect with Autoconnect turned on.
    • Move Android device and target device apart so that the are at the limit of connection range.
    • BLE connection drops out and Android phone attempts to reconnect to target.
    • After reconnection, bonding information is sometimes deleted from the phone.

    The following Android nRF Connect log shows an example of this occurring on a Samsung S6, Android 70

    As seen from this log, it appears as though the Android phone is attempting to discover services on the target (not really sure why, as the services should already be available for a device which as already been bonded).

    My suspicion is that the Android BLE stack automatically removes bonding information for a device if it cannot successfully discover services after the initial bonding key exchange has been completed.  i.e. If the BLE connection is good enough to allow key exchange, but then there are packets lost during BLE service discovery, the Android BLE subsystems sets the device state as unbonded.

    I 11:55:14.038 Notification received from 001c0005-99f7-af8f-6b4e-1e1624b9d72e, value: (0x) 00-00-0F-AD-FF-FF-FF-E9
A 11:55:14.038 "(0x) 00-00-0F-AD-FF-FF-FF-E9" received
I 11:55:59.056 Notification received from 001c0005-99f7-af8f-6b4e-1e1624b9d72e, value: (0x) 00-00-0F-AD-FF-FF-FF-EF
A 11:55:59.056 "(0x) 00-00-0F-AD-FF-FF-FF-EF" received
I 11:55:59.058 Notification received from 001c0005-99f7-af8f-6b4e-1e1624b9d72e, value: (0x) 00-00-0F-AE-00-00-0F-54
A 11:55:59.058 "(0x) 00-00-0F-AE-00-00-0F-54" received
D 11:56:35.047 [Server callback] Connection state changed with status: 0 and new state: DISCONNECTED (0)
I 11:56:35.047 [Server] Device disconnected
D 11:56:35.085 [Callback] Connection state changed with status: 8 and new state: DISCONNECTED (0)
E 11:56:35.086 Error 8 (0x8): GATT CONN TIMEOUT
I 11:56:35.086 Disconnected
D 11:56:35.120 [Broadcast] Action received: android.bluetooth.device.action.ACL_DISCONNECTED
D 11:58:11.392 [Server callback] Connection state changed with status: 0 and new state: CONNECTED (2)
I 11:58:11.392 [Server] Device with address E1:FB:ED:C3:13:E7 connected
V 11:58:11.392 [Server] Creating server connection...
D 11:58:11.392 server.connect(device, autoConnect = true)
V 11:58:11.404 Connecting to E1:FB:ED:C3:13:E7...
D 11:58:11.404 gatt.connect()
D 11:58:11.508 [Broadcast] Action received: android.bluetooth.device.action.ACL_CONNECTED
D 11:58:11.514 [Callback] Connection state changed with status: 0 and new state: CONNECTED (2)
I 11:58:11.514 Connected to E1:FB:ED:C3:13:E7
D 11:58:11.518 wait(1600ms)
D 11:58:11.539 [Callback] Connection state changed with status: 0 and new state: CONNECTED (2)
V 11:58:13.123 Discovering services...
D 11:58:13.123 gatt.discoverServices()
D 11:58:32.061 [Server callback] Connection state changed with status: 0 and new state: DISCONNECTED (0)
I 11:58:32.061 [Server] Device disconnected
D 11:58:32.171 [Broadcast] Action received: android.bluetooth.device.action.BOND_STATE_CHANGED, bond state changed to: BOND_NONE (10)
I 11:58:32.171 Bond information deleted
D 11:58:32.187 [Callback] Connection state changed with status: 8 and new state: DISCONNECTED (0)
E 11:58:32.187 Error 8 (0x8): GATT CONN TIMEOUT
I 11:58:32.187 Disconnected
D 11:58:32.235 [Broadcast] Action received: android.bluetooth.device.action.ACL_DISCONNECTED
D 16:05:34.028 gatt.close()
D 16:05:34.031 wait(200)
V 16:05:34.234 Connecting to E1:FB:ED:C3:13:E7...
D 16:05:34.235 gatt = device.connectGatt(autoConnect = true, TRANSPORT_LE)
D 16:05:46.070 [Server callback] Connection state changed with status: 0 and new state: CONNECTED (2)
I 16:05:46.070 [Server] Device with address E1:FB:ED:C3:13:E7 connected
V 16:05:46.070 [Server] Creating server connection...
D 16:05:46.071 server.connect(device, autoConnect = true)
D 16:05:46.144 [Callback] Connection state changed with status: 0 and new state: CONNECTED (2)
I 16:05:46.144 Connected to E1:FB:ED:C3:13:E7
D 16:05:46.148 [Broadcast] Action received: android.bluetooth.device.action.ACL_CONNECTED
V 16:05:46.161 Discovering services...
D 16:05:46.161 gatt.discoverServices()
D 16:05:46.865 [Broadcast] Action received: android.bluetooth.device.action.BOND_STATE_CHANGED, bond state changed to: BOND_BONDING (11)
D 16:05:46.924 [Server callback] Connection state changed with status: 0 and new state: DISCONNECTED (0)
I 16:05:46.924 [Server] Device disconnected
D 16:05:46.927 [Broadcast] Action received: android.bluetooth.device.action.BOND_STATE_CHANGED, bond state changed to: BOND_NONE (10)
I 16:05:46.930 Bonding failed
D 16:05:46.931 [Callback] Connection state changed with status: 19 and new state: DISCONNECTED (0)
W 16:05:46.931 Connection terminated by peer (status 19)
I 16:05:46.931 Disconnected
D 16:05:47.042 [Broadcast] Action received: android.bluetooth.device.action.ACL_DISCONNECTED

    I have also seen logs similar to your with failure occurring after a GATT INSUF AUTHORIZATION message (See attached log)

    bonding-removed-nrf-connect-log.txt

    I haven't had a chance to test, but you could try using the Android HCI snoop log to get more information about what is happening at the BLE HCI layer when this happens.

    http://www.fte.com/WebHelp/BPA600/Content/Documentation/WhitePapers/BPA600/Encryption/GettingAndroidLinkKey/RetrievingHCIlog.htm

Children
No Data
Related

core_v2_widget.Hide()