onServicesDiscovered() not called if requestMtu() and discoverServices() called together when connecting to peripheral that initiates MTU negotiation
I am running into a BLE interoperability issue between an Android central/client (compileSDK=35) connecting to a peripheral/server that initiates its own MTU negotiation: service discovery appears to get stuck and onServicesDiscovered() is never called.
AFAIK, it is typically the central/client device that initiates MTU negotiation, and in Android this is done by a call to BluetoothGatt.requestMtu() after the device connects. In the case of this particular BLE device, even when nominally configured as a peripheral/server, it also acts as a central/client and initiates MTU negotiation.
The relevant part of the BluetoothGattCallback code looks like this:
override fun onConnectionStateChange(gatt: BluetoothGatt, status: Int, newState: Int) {
if (status == BluetoothGatt.GATT_SUCCESS) {
when (newState) {
BluetoothProfile.STATE_CONNECTED -> {
// initiate MTU negotiation and service discovery
gatt.requestMtu(512)
gatt.discoverServices()
}
BluetoothProfile.STATE_DISCONNECTED -> {
// Disconnected from device
}
}
}
}
override fun onServicesDiscovered(gatt: BluetoothGatt, status: Int) {
if (status == BluetoothGatt.GATT_SUCCESS) {
// Services discovered, enable notifications if needed
.
.
.
}
}
If I remove the call to BluetoothGatt.requestMtu() then no problem, but obviously that will not work with other BLE devices that don't initiate MTU negotiation. If I disable the MTU negotiation initiated by the peripheral then no problem.
Here is a trace from the AndroidStudio console that shows the problem - onSearchComplete/onServicesDiscovered is not logged:
| Date/Time | PID-TID | Tag | Log Level | Message | | -- | -- | -- | -- | -- | | 2025-07-11 17:47:49.116 | 8165-8165 | BluetoothAdapter | D | getBleEnabledArray(): ON | | 2025-07-11 17:47:49.118 | 8165-8165 | BluetoothGatt | D | connect() - device: XX:XX:XX:XX:77:30, auto: false | | 2025-07-11 17:47:49.118 | 8165-8165 | BluetoothGatt | D | registerApp() | | 2025-07-11 17:47:49.119 | 8165-8165 | BluetoothGatt | D | registerApp() - UUID=a616f277-dd9b-4d9c-87c9-199cafe1cfc8 | | 2025-07-11 17:47:49.124 | 8165-9333 | BluetoothGatt | D | onClientRegistered() - status=0 clientIf=12 | | 2025-07-11 17:47:49.126 | 8165-9333 | BluetoothAdapter | D | getBleEnabledArray(): ON | | 2025-07-11 17:47:50.596 | 8165-9333 | BluetoothGatt | D | onClientConnectionState() - status=0 clientIf=12 device=XX:XX:XX:XX:77:30 | | 2025-07-11 17:47:50.600 | 8165-9333 | BluetoothGatt | D | configureMTU() - device: XX:XX:XX:XX:77:30 mtu: 512 | | 2025-07-11 17:47:50.603 | 8165-9333 | BluetoothGatt | D | discoverServices() - device: XX:XX:XX:XX:77:30 | | 2025-07-11 17:47:51.120 | 8165-9333 | BluetoothGatt | D | onConnectionUpdated() - Device=XX:XX:XX:XX:77:30 interval=6 latency=0 timeout=500 status=0 | | 2025-07-11 17:47:51.494 | 8165-9333 | BluetoothGatt | D | onConfigureMTU() - Device=XX:XX:XX:XX:77:30 mtu=247 status=0 | | 2025-07-11 17:47:51.569 | 8165-9333 | BluetoothGatt | D | onConnectionUpdated() - Device=XX:XX:XX:XX:77:30 interval=36 latency=0 timeout=500 status=0 |
And the same thing but with the peripheral initiated MTU negotiation disabled:
| Date/Time | PID-TID | Tag | Log Level | Message | | -- | -- | -- | -- | -- | | 2025-07-11 17:52:18.055 | 8165-8165 | BluetoothAdapter | D | getBleEnabledArray(): ON | | 2025-07-11 17:52:18.058 | 8165-8165 | BluetoothGatt | D | connect() - device: XX:XX:XX:XX:77:30, auto: false | | 2025-07-11 17:52:18.058 | 8165-8165 | BluetoothGatt | D | registerApp() | | 2025-07-11 17:52:18.058 | 8165-8165 | BluetoothGatt | D | registerApp() - UUID=c055ae54-e1d1-4f45-a276-9281537e3e2f | | 2025-07-11 17:52:18.063 | 8165-8181 | BluetoothGatt | D | onClientRegistered() - status=0 clientIf=13 | | 2025-07-11 17:52:18.065 | 8165-8181 | BluetoothAdapter | D | getBleEnabledArray(): ON | | 2025-07-11 17:52:18.480 | 8165-8181 | BluetoothGatt | D | onClientConnectionState() - status=0 clientIf=13 device=XX:XX:XX:XX:77:30 | | 2025-07-11 17:52:18.482 | 8165-8181 | BluetoothGatt | D | configureMTU() - device: XX:XX:XX:XX:77:30 mtu: 512 | | 2025-07-11 17:52:18.484 | 8165-8181 | BluetoothGatt | D | discoverServices() - device: XX:XX:XX:XX:77:30 | | 2025-07-11 17:52:19.001 | 8165-8181 | BluetoothGatt | D | onConnectionUpdated() - Device=XX:XX:XX:XX:77:30 interval=6 latency=0 timeout=500 status=0 | | 2025-07-11 17:52:19.423 | 8165-8181 | BluetoothGatt | D | onConfigureMTU() - Device=XX:XX:XX:XX:77:30 mtu=247 status=0 | | 2025-07-11 17:52:19.425 | 8165-8181 | BluetoothGatt | D | onSearchComplete() = Device=XX:XX:XX:XX:77:30 Status=0 | | 2025-07-11 17:52:19.425 | 8165-8181 | BluetoothGatt | D | setCharacteristicNotification() - uuid: 85fc567e-31d9-4185-87c6-339924d1c5be enable: true | | 2025-07-11 17:52:19.496 | 8165-8181 | BluetoothGatt | D | onConnectionUpdated() - Device=XX:XX:XX:XX:77:30 interval=36 latency=0 timeout=500 status=0 |
After capturing these traces I learned that if I stage the call of requestMtu() from onServicesDiscovered() then no problem:
override fun onConnectionStateChange(gatt: BluetoothGatt, status: Int, newState: Int) {
if (status == BluetoothGatt.GATT_SUCCESS) {
when (newState) {
BluetoothProfile.STATE_CONNECTED -> {
// initiate service discovery
gatt.discoverServices()
}
BluetoothProfile.STATE_DISCONNECTED -> {
// Disconnected from device
}
}
}
}
override fun onServicesDiscovered(gatt: BluetoothGatt, status: Int) {
if (status == BluetoothGatt.GATT_SUCCESS) {
// now initiate MTU negotiation
gatt.requestMtu(512)
}
}
override fun onMtuChanged(gatt: BluetoothGatt, mtu: Int, status: Int) {
if (status == BluetoothGatt.GATT_SUCCESS) {
// services discovered and MTU negotiated, enable notifications if needed
.
.
.
}
}
I also learned that back-to-back calls to discoverServices() then requestMtu() is OK:
override fun onConnectionStateChange(gatt: BluetoothGatt, status: Int, newState: Int) {
if (status == BluetoothGatt.GATT_SUCCESS) {
when (newState) {
BluetoothProfile.STATE_CONNECTED -> {
// initiate MTU negotiation and service discovery
gatt.discoverServices()
gatt.requestMtu(512)
}
BluetoothProfile.STATE_DISCONNECTED -> {
// Disconnected from device
}
}
}
}
override fun onServicesDiscovered(gatt: BluetoothGatt, status: Int) {
if (status == BluetoothGatt.GATT_SUCCESS) {
// Services discovered, enable notifications if needed
.
.
.
}
}
With debug logging for the Bluetooth stack enabled I think it's clear where things are going sideways. Because the calls are issued back-to-back the command for service discovery is queued for later:
| Date/Time | PID-TID | Tag | Log Level | Message | | -- | -- | -- | -- | -- | | 2025-07-14 09:50:22.846 | 1110-1125 | BluetoothGatt | D | onClientConnectionState() - status=0 clientIf=5 connected=true device=XX:XX:XX:XX:77:30 | | 2025-07-14 09:50:22.855 | 1110-1125 | BluetoothGatt | D | configureMTU() - device: XX:XX:XX:XX:77:30 mtu: 517 | | 2025-07-14 09:50:22.863 | 3180-3986 | bt_btif_gattc | D | system/btif/src/btif_gatt_client.cc:780 btif_gattc_configure_mtu: | | 2025-07-14 09:50:22.865 | 1110-1125 | BluetoothGatt | D | discoverServices() - device: XX:XX:XX:XX:77:30 | | 2025-07-14 09:50:22.867 | 3180-3986 | bt_btif_gattc | D | system/btif/src/btif_gatt_client.cc:561 btif_gattc_search_service: | | 2025-07-14 09:50:22.880 | 3180-3328 | bt_bta_gattc | I | system/bta/gatt/bta_gattc_utils.cc:473 bta_gattc_enqueue: Already has a pending command to executer. Queuing for later xx:xx:xx:xx:77:30 conn id=0x0005 |
And later, when service discovery is complete, the callback to onConfigureMtu() is scheduled (BTA_GATTC_CFG_MTU_EVT) but the callback to onSearchComplete() is not (BTA_GATTC_SEARCH_CMPL_EVT), even though the Gatt client thinks it's done:
| Date/Time | PID-TID | Tag | Log Level | Message | | -- | -- | -- | -- | -- | | 2025-07-14 09:50:23.721 | 3180-3328 | bt_bta_gattc | D | system/bta/gatt/bta_gattc_cache.cc:337 bta_gattc_explore_srvc_finished: service discovery succeed, reset count to zero, conn_id=0x0005 | | ... | | | | | | 2025-07-14 09:50:23.721 | 3180-3328 | gatt_api | I | system/stack/gatt/gatt_api.cc:782 GATTC_TryMtuRequest: xx:xx:xx:xx:77:30 conn_id=0x0005 | | 2025-07-14 09:50:23.721 | 3180-3328 | gatt_api | I | system/stack/gatt/gatt_api.cc:831 GATTC_UpdateUserAttMtuIfNeeded: xx:xx:xx:xx:77:30, mtu=517 | | 2025-07-14 09:50:23.721 | 3180-3328 | gatt_api | I | system/stack/gatt/gatt_api.cc:838 GATTC_UpdateUserAttMtuIfNeeded: xx:xx:xx:xx:77:30, current mtu: 247, max_user_mtu:0, user_mtu: 517 | | 2025-07-14 09:50:23.721 | 3180-3328 | gatt_api | I | system/stack/gatt/gatt_api.cc:842 GATTC_UpdateUserAttMtuIfNeeded: User requested more than what GATT can handle. Trim it. | | 2025-07-14 09:50:23.721 | 3180-3328 | ble_sec | W | system/stack/btm/btm_ble_sec.cc:581 BTM_SetBleDataLength: bd_addr:xx:xx:xx:xx:77:30, tx_pdu_length:247 | | 2025-07-14 09:50:23.721 | 3180-3328 | ble_sec | W | system/stack/btm/btm_ble_sec.cc:595 BTM_SetBleDataLength: Suggested TX octect already set to controller 251 >= 247 | | 2025-07-14 09:50:23.721 | 3180-3328 | bt_btif_gattc | D | system/btif/src/btif_gatt_client.cc:331 bta_gattc_cback: gatt client callback event:BTA_GATTC_CFG_MTU_EVT [18] | | 2025-07-14 09:50:23.721 | 3180-3328 | bt_btif_gattc | D | system/btif/src/btif_gatt_client.cc:331 bta_gattc_cback: gatt client callback event:BTA_GATTC_SRVC_DISC_DONE_EVT [8] |
For reference, a normal finish to service discover looks like this:
| Date/Time | PID-TID | Tag | Log Level | Message | | -- | -- | -- | -- | -- | | 2025-07-14 09:55:06.023 | 3180-3328 | bt_bta_gattc | D | system/bta/gatt/bta_gattc_cache.cc:337 bta_gattc_explore_srvc_finished: service discovery succeed, reset count to zero, conn_id=0x0005 | | ... | | | | | | 2025-07-14 09:55:06.024 | 3180-3328 | bt_btif_gattc | D | system/btif/src/btif_gatt_client.cc:331 bta_gattc_cback: gatt client callback event:BTA_GATTC_SEARCH_RES_EVT [7] | | 2025-07-14 09:55:06.024 | 3180-3328 | bt_btif_gattc | D | system/btif/src/btif_gatt_client.cc:331 bta_gattc_cback: gatt client callback event:BTA_GATTC_SEARCH_RES_EVT [7] | | 2025-07-14 09:55:06.024 | 3180-3328 | bt_btif_gattc | D | system/btif/src/btif_gatt_client.cc:331 bta_gattc_cback: gatt client callback event:BTA_GATTC_SEARCH_RES_EVT [7] | | 2025-07-14 09:55:06.024 | 3180-3328 | bt_btif_gattc | D | system/btif/src/btif_gatt_client.cc:331 bta_gattc_cback: gatt client callback event:BTA_GATTC_SEARCH_RES_EVT [7] | | 2025-07-14 09:55:06.024 | 3180-3328 | bt_btif_gattc | D | system/btif/src/btif_gatt_client.cc:331 bta_gattc_cback: gatt client callback event:BTA_GATTC_SEARCH_CMPL_EVT [6] | | 2025-07-14 09:55:06.024 | 3180-3328 | bt_btif_gattc | D | system/btif/src/btif_gatt_client.cc:331 bta_gattc_cback: gatt client callback event:BTA_GATTC_SRVC_DISC_DONE_EVT [8] |
Anyone else think this is this a bug?
Accepted Answer
In general, you should make sure to do only one operation at a time. All operations are asynchronous and you should wait for completion before you start the next operation. That is why all Android BLE libraries queue operations.
Martijn van Welie