BluetoothPeripheral Command queue stuck after bonding succeed

ceduliocezar commented 3 years ago

What I'm going to describe here does not happen always, from my tests it is happening twice every ten tries, therefore 20% of the time.

Im running blessed on two android phones, one is the peripheral(PhoneA) and the other is acting as central(PhoneB).

After BluetoothPeripheralCallback.onServicesDiscovered is called on PhoneB, an write command to an encrypted characteristic of PhoneA is queued and the pairing process starts.

After acepting the pairing process on both phones the callback BluetoothPeripheralCallback.onBondingSucceeded is executed.

Most of time after BluetoothPeripheralCallback.onBondingSucceeded the write command is executed again and the write arrives on PhoneA.

Sometimes After BluetoothPeripheralCallback.onBondingSucceeded the write command is not executed, if additional commands are added to the queue it returns true but it never gets executed because commandQueueBusy is set to true., more specifically this check https://github.com/weliem/blessed-android/blob/b1252417318fdbf30ee6d325008cc4b556586b29/blessed/src/main/java/com/welie/blessed/BluetoothPeripheral.java#L1675

Steps to reproduce

Remove paired devices on both phones.
Install the app on both phones.
Start the peripheral server and advertisement on PhoneA.
Start the central server and scan on PhoneB.
Establish the connection between PhoneB and PhoneA.
Wait until PhoneB discover the services of PhoneA.
Request an write to an encrypted characteristic.
Accepted the pairing on both phones.
Check if the command was executed after bond succed.
Write command doesnt get executed.
Issue new write commands.
New write commands never gets executed.

Like I said 20% of the time this is happening so to me it seems to be concurrency problems.

Legal Imprint (Mandatory for business reasons, sorry for that) Cedulio Silva cedulio.silva@daimler.com, MBition GmbH, imprint

ceduliocezar commented 3 years ago

Forgot to mention but I'm using a Pixel 4 XL with Android 11 as peripheral and a Pixel 4a with Android 11 as Central.

ceduliocezar commented 3 years ago

Peripheral Logs

2021-07-07 16:22:20.465 2414-2414/com.sample D/BluetoothGattServer: registerCallback()
2021-07-07 16:22:20.466 2414-2414/com.sample D/BluetoothGattServer: registerCallback() - UUID=d5167ed2-ca8e-417f-abb1-827b2c684524
2021-07-07 16:22:20.469 2414-2437/com.sample D/BluetoothGattServer: onServerRegistered() - status=0 serverIf=9
2021-07-07 16:22:20.475 2414-2414/com.sample D/BluetoothGattServer: addService() - service: 0000180d-0000-1000-8000-00805f9b34fb
2021-07-07 16:22:20.479 2414-2437/com.sample D/BluetoothGattServer: onServiceAdded() - handle=40 uuid=0000180d-0000-1000-8000-00805f9b34fb status=0
2021-07-07 16:22:20.480 2414-2414/com.sample D/BluetoothGattServer: addService() - service: cb1de472-f720-4e4d-94bd-94b5586c6e55
2021-07-07 16:22:20.482 2414-2437/com.sample D/BluetoothGattServer: onServiceAdded() - handle=46 uuid=cb1de472-f720-4e4d-94bd-94b5586c6e55 status=0
2021-07-07 16:22:20.483 2414-2414/com.sample D/BluetoothGattServer: addService() - service: 646f2c2b-b965-4911-ab12-114e1eaeb4d1
2021-07-07 16:22:20.485 2414-2437/com.sample D/BluetoothGattServer: onServiceAdded() - handle=50 uuid=646f2c2b-b965-4911-ab12-114e1eaeb4d1 status=0
2021-07-07 16:22:20.995 2414-2414/com.sample D/BluetoothAdapter: isLeEnabled(): ON
2021-07-07 16:22:20.995 2414-2414/com.sample D/BluetoothAdapter: isLeEnabled(): ON
2021-07-07 16:22:21.063 2414-2414/com.sample I/BluetoothPeripheralManager: advertising started
2021-07-07 16:22:25.099 2414-2437/com.sample D/BluetoothGattServer: onServerConnectionState() - status=0 serverIf=9 device=MAC-ADDRESS_OMMITED
2021-07-07 16:22:25.100 2414-2437/com.sample D/BluetoothGattServer: connect() - device: MAC-ADDRESS_OMMITED, auto: false
2021-07-07 16:22:25.106 2414-2437/com.sample I/BluetoothPeripheralManager: Central 'null' (MAC-ADDRESS_OMMITED) connected
2021-07-07 16:22:25.773 2414-2437/com.sample D/BluetoothGattServer: onConnectionUpdated() - Device=MAC-ADDRESS_OMMITED interval=6 latency=0 timeout=500 status=0
2021-07-07 16:22:26.395 2414-2437/com.sample D/BluetoothGattServer: onMtuChanged() - device=MAC-ADDRESS_OMMITED, mtu=100
2021-07-07 16:22:26.396 2414-2437/com.sample I/BluetoothPeripheralManager: new MTU: 100
2021-07-07 16:22:26.494 2414-2437/com.sample D/BluetoothGattServer: onConnectionUpdated() - Device=MAC-ADDRESS_OMMITED interval=36 latency=0 timeout=500 status=0

Central Log

2021-07-07 16:22:25.347 18376-18376/com.sample D/BluetoothAdapter: isLeEnabled(): ON
2021-07-07 16:22:25.353 18376-18396/com.sample D/BluetoothLeScanner: onScannerRegistered() - status=0 scannerId=14 mScannerId=0
2021-07-07 16:22:25.362 18376-18376/com.sample I/BluetoothCentralManager: scan started
2021-07-07 16:22:25.518 18376-18376/com.sample D/BluetoothAdapter: isLeEnabled(): ON
2021-07-07 16:22:25.522 18376-18376/com.sample I/BluetoothCentralManager: scan stopped
2021-07-07 16:22:26.169 18376-18376/com.sample W/BluetoothCentralManager: peripheral with address 'MAC-ADDRESS_OMMITED' is not in the Bluetooth cache, hence connection may fail
2021-07-07 16:22:26.271 18376-18376/com.sample I/BluetoothPeripheral: connect to '' (MAC-ADDRESS_OMMITED) using TRANSPORT_LE
2021-07-07 16:22:26.274 18376-18376/com.sample D/BluetoothGatt: connect() - device: MAC-ADDRESS_OMMITED, auto: false
2021-07-07 16:22:26.274 18376-18376/com.sample D/BluetoothGatt: registerApp()
2021-07-07 16:22:26.274 18376-18376/com.sample D/BluetoothGatt: registerApp() - UUID=b59752ba-63af-42e0-8c3d-b84f0fb19834
2021-07-07 16:22:26.277 18376-18396/com.sample D/BluetoothGatt: onClientRegistered() - status=0 clientIf=14
2021-07-07 16:22:26.757 18376-18396/com.sample D/BluetoothGatt: onClientConnectionState() - status=0 clientIf=14 device=MAC-ADDRESS_OMMITED
2021-07-07 16:22:26.761 18376-18396/com.sample I/BluetoothPeripheral: connected to '' (NONE) in 0.5s
2021-07-07 16:22:26.764 18376-18376/com.sample D/BluetoothPeripheral: discovering services of '' with delay of 0 ms
2021-07-07 16:22:26.764 18376-18376/com.sample D/BluetoothGatt: discoverServices() - device: MAC-ADDRESS_OMMITED
2021-07-07 16:22:27.430 18376-18396/com.sample D/BluetoothGatt: onConnectionUpdated() - Device=MAC-ADDRESS_OMMITED interval=6 latency=0 timeout=500 status=0
2021-07-07 16:22:27.442 18376-18396/com.sample D/BluetoothPeripheral: connection parameters: interval=7.5ms latency=0 timeout=5s
2021-07-07 16:22:28.029 18376-18396/com.sample D/BluetoothGatt: onSearchComplete() = Device=MAC-ADDRESS_OMMITED Status=0
2021-07-07 16:22:28.032 18376-18396/com.sample I/BluetoothPeripheral: discovered 5 services for ''
2021-07-07 16:22:28.041 18376-18376/com.sample D/BluetoothGatt: configureMTU() - device: MAC-ADDRESS_OMMITED mtu: 100
2021-07-07 16:22:28.043 18376-18376/com.sample I/BluetoothPeripheral: requesting MTU of 100
2021-07-07 16:22:28.065 18376-18396/com.sample D/BluetoothGatt: onConfigureMTU() - Device=MAC-ADDRESS_OMMITED mtu=100 status=0
2021-07-07 16:22:28.148 18376-18396/com.sample D/BluetoothGatt: onConnectionUpdated() - Device=MAC-ADDRESS_OMMITED interval=36 latency=0 timeout=500 status=0
2021-07-07 16:22:28.149 18376-18396/com.sample D/BluetoothPeripheral: connection parameters: interval=45.0ms latency=0 timeout=5s
2021-07-07 16:22:30.434 18376-18376/com.sample D/BluetoothPeripheral: writing <01> to characteristic <00002a39-0000-1000-8000-00805f9b34fb>
2021-07-07 16:22:34.196 18376-18376/com.sample D/BluetoothPeripheral: starting bonding with 'Pixel 4 XL' (MAC-ADDRESS_OMMITED)
2021-07-07 16:22:34.208 18376-18376/com.sample D/BluetoothPeripheral: pairing request received: PAIRING_VARIANT_PASSKEY_CONFIRMATION (2)
2021-07-07 16:22:40.378 18376-18376/com.sample D/BluetoothPeripheral: bonded with 'Pixel 4 XL' (MAC-ADDRESS_OMMITED)

weliem commented 3 years ago

What I see in the log is that the write (<01>) never seems to complete. Hence the queue is stuck. Only on completion of the write is the commandQueueBusy flag cleared.

The normal behavior on Android is that Android should retry the write after bonding completes. That doesn't seem to happen in all cases. I don't know why it sometimes works and sometimes not. I guess that when it works, the write is successfully completed.

ceduliocezar commented 3 years ago

I was investigating based on what you said and indeed the method BluetoothGattCallback.onCharacteristicWrite is not being triggered after bonding even though bluetoothGatt.writeCharacteristic(characteristic) returns true.

Now the question might be, is this bug happening inside Android SDK or is it inside of blessed peripheral implementation that is not acknowledge some parameter after bonding.

Perhaps we can comeup with an strategy to try to unblock the queue, first command might be lost but at least we make the queue usable again.

weliem / blessed-android

BluetoothPeripheral Command queue stuck after bonding succeed #103