GATT_INVALID_PDU can trigger between rapid disconnect/connect cycles on Android

[djweber]

Hey there. Just wanted to say awesome work on the library -- works very well so far.

So far, I've observed one interesting behavior around MTU requests: I wired up a simple connect/disconnect button in a test app for connecting to a device with an nRF chipset. This app is running on Android 13. Both connect and disconnect work fine in almost all cases. I was doing an MTU request in the onServicesDiscovered callback per the docs:

onServicesDiscovered {
    try {
        // Android 14 automatically requests this value on its initial connection
        requestMtu(Connector.TARGET_MTU) // 517
    } catch (e: GattStatusException) {
        Timber.e(e, "MTU request failed")
    }
}
 
autoConnectIf {
  true
}

Successful MTU Request (~1.5 seconds between attempts):

2023-12-01 01:33:44.238 E9:78:90:01:32:9B Disconnected
2023-12-01 01:33:44.239 E9:78:90:01:32:9B Disconnect detected 
                               state: Disconnected(null)
2023-12-01 01:33:46.067 E9:78:90:01:32:9B Connecting
2023-12-01 01:33:46.451 E9:78:90:01:32:9B discoverServices
2023-12-01 01:33:47.695 E9:78:90:01:32:9B Discovered 9 services
2023-12-01 01:33:47.695 E9:78:90:01:32:9B requestMtu
                                mtu: 517
2023-12-01 configureMTU() - device: E97890_B mtu: 517
2023-12-01 onConfigureMTU() - Device=E97890_B mtu=247 status=0
2023-12-01 E9:78:90:01:32:9B onMtuChanged
                                mtu: 247
                                status: GATT_SUCCESS(0)
2023-12-01 V  E9:78:90:01:32:9B Configuring characteristic observations
2023-12-01 I  E9:78:90:01:32:9B Connected

MTU Request Failure(~0.5 seconds between attempts):

2023-12-01 01:37:23.585 E9:78:90:01:32:9B Disconnect detected
                               state: Disconnected(null)
2023-12-01 01:37:23.586 E9:78:90:01:32:9B Disconnected
2023-12-01 01:37:24.009 E9:78:90:01:32:9B Connecting
2023-12-01 01:37:24.033 E9:78:90:01:32:9B discoverServices
2023-12-01 01:37:26.384 E9:78:90:01:32:9B Discovered 9 services
2023-12-01 01:37:26.384 E9:78:90:01:32:9B requestMtu
                               mtu: 517
2023-12-01 01:37:26.385 configureMTU() - device: E97890_B mtu: 517
2023-12-01 01:37:26.400 onConfigureMTU() - Device=E97890_B mtu=23 status=4
2023-12-01 01:37:26.400 E9:78:90:01:32:9B onMtuChanged
                               mtu: 23
                               status: GATT_INVALID_PDU(4)
2023-12-01 01:37:26.402 MTU request failed. This is most likely due to trying to re-request the MTU too quickly after a disconnect
                               com.juul.kable.GattStatusException: OnMtuChanged(mtu=23, status=GATT_INVALID_PDU(4))
                                      at com.juul.kable.Connection.requestMtu(Connection.kt:122)
                                      at com.juul.kable.Connection$requestMtu$1.invokeSuspend(Unknown Source:15)
                                      at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:33)
                                      at kotlinx.coroutines.DispatchedTask.run(DispatchedTask.kt:108)
                                      at kotlinx.coroutines.scheduling.CoroutineScheduler.runSafely(CoroutineScheduler.kt:584)
                                      at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.executeTask(CoroutineScheduler.kt:793)
                                      at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.runWorker(CoroutineScheduler.kt:697)
                                      at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.run(CoroutineScheduler.kt:684)
2023-12-01 01:37:26.403 E9:78:90:01:32:9B Configuring characteristic observations
2023-12-01 01:37:26.403 E9:78:90:01:32:9B Connected

I noticed that if I attempt to reconnect to the device within roughly 1 second of the peripheral state reporting a disconnect, I'll get the GATT_INVALID_PDU error. If I wait roughly 2 seconds or more, it successfully re-requests the MTU. Almost seems like there is a tiny ~1-second window between Kable reporting the disconnection state and the BLE peripheral actually being fully disconnected. I haven't gotten to test if this happens with other BLE peripherals just yet. Could very well be a nuance with Android Bluetooth / GATT or Nordic, but just thought I'd point it out.

[twyatt]

Hey there. Just wanted to say awesome work on the library -- works very well so far.

Thanks! ❤️

I noticed that if I attempt to reconnect to the device within roughly 1 second of the peripheral state reporting a disconnect, I'll get the GATT_INVALID_PDU error. If I wait roughly 2 seconds or more, it successfully re-requests the MTU.

Yikes, and thanks for reporting this issue with such a detailed report.

Almost seems like there is tiny ~1-second window between Kable reporting the disconnection state and the BLE peripheral actually being fully disconnected.

The StateFlow that provides the state on the Peripheral.state is passed along to the Callback:

kable/core/src/androidMain/kotlin/BluetoothDeviceAndroidPeripheral.kt

Line 125 in f5bf08b

_state,

Then updated from the Callback (which is Android's BluetoothGattCallback):

kable/core/src/androidMain/kotlin/gatt/Callback.kt

Lines 108 to 113 in f5bf08b

	when (newState) {
	STATE_CONNECTING -> state.value = State.Connecting.Bluetooth
	STATE_CONNECTED -> state.value = State.Connecting.Services
	STATE_DISCONNECTING -> state.value = State.Disconnecting
	STATE_DISCONNECTED -> state.value = State.Disconnected(status.disconnectedConnectionStatus)
	}

Any delay in propagating that state from Peripheral.state StateFlow would either be from a delay in the StateFlow value updating or Android system simply lagging to call BluetoothGattCallback's onConnectionStateChange function; I think it is more likely the latter.
It is also possible that the logging of the connection state could take some time (although I suspect/hope that is not the case):

kable/core/src/androidMain/kotlin/gatt/Callback.kt

Lines 100 to 104 in f5bf08b

	logger.debug {
	message = "onConnectionStateChange"
	detail("status", status.disconnectedConnectionStatusString)
	detail("newState", newState.connectionStateString)
	}

Perhaps it is another quark of the Android BLE system where if you reconnect too quickly that Android doesn't reset it's internal timer for allowing successive calls of requestMtu?

Ultimately, something I'd like to look into further, but it is unlikely I'll have to time to prioritize this in the near future.
If you happen to dig deeper and find additional evidence as to what is going on, let me know. 😄

[djweber]

Thank you for the response. I'll let you know if I observe anything else around this. 👍