Unexpected disconnect after BluetoothGatt.discoverServices() (Android)

[michael]

Hello,

Setup: Android 4.4.2 (LG G2), nRF51822 peripherial.

I noticed that once in a while when trying to connect to my nRF51 based device it won't connect and what is worse the device gets removed from the list of bonded devices on the android phone. So I wrote an android test app that repeats the following steps (pseudo code):

BluetoothDevice.connectGatt()
wait for onConnectionSateChanged..
if BluetoothProfile.STATE_CONNECTED call BluetoothGatt.discoverServices()
wait for onServicesDiscovered()
if BluetoothGatt.GATT_SUCCESS waits for 500ms
call BluetoothGatt.disconnect()
wait for onConnectionSateChanged	
if BluetoothProfile.STATE_DISCONNECTED call BluetoothGatt.close()
wait for 500ms

Usually after repeating this 10-100 times I end up getting a disconnect right after service discovery completed. In addition the device is removed from the list of bonded devices (a ACTION_BOND_STATE_CHANGED broadcast is issued by the system).

This is the corresponding log. The disconnect happens at 33.313

....
06-05 09:23:33.193    2519-2546/? D/BtGatt.btif? btif_gattc_get_descriptor
06-05 09:23:33.193    2519-2546/? D/BtGatt.btif? btgattc_handle_event: Event 1009
06-05 09:23:33.193    2519-2546/? D/BtGatt.GattService? onGetDescriptor() - address=DA:88:2C:42:63:10, status=133, descUuid=00002902-0000-1000-8000-00805f9b34fb
06-05 09:23:33.193  27932-27945/com.me.test D/BluetoothGatt? onSearchComplete() = Device=DA:88:2C:42:63:10 Status=0
06-05 09:23:33.313    2519-2744/? E/bt-btm? btm_sec_disconnected - Clearing Pending flag
06-05 09:23:33.313    2519-2744/? W/bt-btif? bta_dm_act no entry for connected service cbs
06-05 09:23:33.313    2519-2546/? D/BtGatt.btif? btif_gattc_upstreams_evt: Event 5
06-05 09:23:33.313    2519-2546/? D/BtGatt.GattService? onDisconnected() - clientIf=5, connId=261, address=DA:88:2C:42:63:10
06-05 09:23:33.313  27932-28117/com.me.test D/BluetoothGatt? onClientConnectionState() - status=0 clientIf=5 device=DA:88:2C:42:63:10
....

Any idea what the problem might be or hints how to debug this? I'm not sure if the problem is on the nRF51 device side or Android side. The nRF51 Software doesn't seem to do anything unusual (doesn't hang, no reset etc.). Capturing the event using the sniffer also doesn't reveal anything to me:

Thanks!

[Hung Bui]

@michael : I'm suspecting the issue is from Android side. We used to have some similar issue but it was with earlier Android versions, on Android v4.3 and 4.4.0

What happens if you don't bond to the device ?

Could you try to test with our nRFMaster Control Panel ?

Have you tried with another phone ?

Could you uploade a full snifer trace so I can have a look ?

[michael]

@Hung Bui: Thank you for looking into this! In fact, I think you are right, the problem seems to be on the Android side. In the mean time we did the same tests using iOS without seeing these problems. I noticed that your Master Control Panel is not showing this problem, also. I then tried to figure out what you are doing different on the Master Control Panel by looking at the Android logcat and the major difference is that you seem to call gatt.close() right before a connect, while I was calling close() right after I received the onConnectionSateChanged (disconnect) event. So I changed my code to the way you are doing this and everything is working much more stable now! I don't know why, but it made major difference.

[michael]

@Hung Bui: While inspecting the logcat I noticed that upon disconnect you are calling gatt.refresh(). This is not a public method, could you elaborate how (reflection?) and why are doing this?

06-10 09:19:19.365 2519-6053/? D/BtGatt.GattService? onDisconnected() - clientIf=5, connId=5, address=EE:08:DB:5E:BE:9B 06-10 09:19:19.365 29761-29772/? D/BluetoothGatt? onClientConnectionState() - status=0 clientIf=5 device=EE:08:DB:5E:BE:9B 06-10 09:19:19.405 29761-29772/? D/BluetoothGatt? refresh() - device: EE:08:DB:5E:BE:9B 06-10 09:19:19.405 2519-6053/? D/BtGatt.GattService? refreshDevice() - address=EE:08:DB:5E:BE:9B

[Hung Bui]

@michael: What we did in Master Control Panel is just to be sure gatt is closed when we start a connection. We don't do re-connection with MCP but try to have fresh gatt every time we do connection.

I'm not sure why it made your app more stable, because there is nothing wrong to close the gatt when you have disconnection and subscribe a new one when you do connect.

The refresh() function is an internal Android Bluetooth function. We use that to clear the cached ATT table stored on Android device. So that Android will do a service discovery every time we connect to the device.

You can have a look here.