Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

BleGattCallbackTimeoutException when writing a characteristic with different data payload many times in a short period of time. #855

Open
dquand91 opened this issue Jun 19, 2024 · 18 comments
Labels
awaiting feedback bug-model specific Bug that is caused by a flawed, model specific BLE stack implementation

Comments

@dquand91
Copy link

dquand91 commented Jun 19, 2024

Describe the bug

I have a BLE device with several characteristics and all of them are working.

But when I try to write 1 characteristic many times with different data payload in a short period of time (for 10 request in 5 seconds) by using com.polidea.rxandroidble2:rxandroidble:1.18.1 library on Android, it leads to BleGattCallbackTimeoutException and then automatically disconnect bluetooth with device. But I have an IOS application connects to the same BLE device, it still works as expected in the same scenario.

To Reproduce
Steps to reproduce the behavior:

  1. Application on Android connects to BLE device.
  2. Write 1 characteristic many times by method "rxBleConnection.createNewLongWriteBuilder()". Please refer to source code below:
Disposable writeDisposable = connectionObservable.flatMap(rxBleConnection ->
  rxBleConnection.createNewLongWriteBuilder()
    .setCharacteristicUuid(UUID.fromString(characteristic))
    .setBytes(data)
    .setMaxBatchSize(MAX_PACKET_LENGTH)
    .build())
  .doOnError(throwable ->
  {
      throwable.printStackTrace();
  })
  .subscribe(bytes -> onWriteSuccess(characteristic, bytes), this::onWriteFailure);

Expected behavior

  • It should not disconnect the bluetooth
  • Do we have any workaround solution or tips in case of writing 1 characteristic many times in a short period of time?

Smartphone (please complete the following information):

  • Device: Samsung S23, S23 Ultra
  • OS: Android 13
  • Library version: 1.18.1

Logs from the application when bug occurs (this will greatly help in quick understanding the problem)
To turn on logs use:

57:53.574 26010-26010 RxBle#ConnectionOperationQueue  D  QUEUED   CharacteristicLongWriteOperation(91963927)
57:53.577 26010-32587 RxBle#ConnectionOperationQueue  D  STARTED  CharacteristicLongWriteOperation(91963927)

57:53.577 26010-26010 RxBle#ConnectionOperationQueue  D  QUEUED   CharacteristicLongWriteOperation(163186669)
57:53.580 26010-26010 RxBle#ConnectionOperationQueue  D  QUEUED   CharacteristicLongWriteOperation(132638899)
57:53.582 26010-26010 RxBle#ConnectionOperationQueue  D  QUEUED   CharacteristicLongWriteOperation(205922926)
57:53.590 26010-26010 RxBle#ConnectionOperationQueue  D  QUEUED   CharacteristicLongWriteOperation(49439132)
57:55.708 26010-26010 RxBle#ConnectionOperationQueue  D  QUEUED   CharacteristicLongWriteOperation(154431849)
57:58.596 26010-26010 RxBle#ConnectionOperationQueue  D  QUEUED   CharacteristicLongWriteOperation(35002628)
57:58.598 26010-26010 RxBle#ConnectionOperationQueue  D  QUEUED   CharacteristicLongWriteOperation(109101346)
57:58.600 26010-26010 RxBle#ConnectionOperationQueue  D  QUEUED   CharacteristicLongWriteOperation(241025392)
57:58.604 26010-26010 RxBle#ConnectionOperationQueue  D  QUEUED   CharacteristicLongWriteOperation(126733678)

// After about 30007 mili-seconds, it leads to timeout exception.
58:23.583 26010-26763 BLEManager                      E  write long error: GATT exception from MAC address XX:XX:XX:XX:XX:XX, with type BleGattOperation{description='CHARACTERISTIC_LONG_WRITE'}
58:23.585 26010-32587 RxBle#ConnectionOperationQueue  D  FINISHED CharacteristicLongWriteOperation(91963927) in 30007 ms
58:23.586 26010-26763 System.err                      W  com.polidea.rxandroidble2.exceptions.BleGattCallbackTimeoutException: GATT exception from MAC address XX:XX:XX:XX:XX:XX, with type BleGattOperation{description='CHARACTERISTIC_LONG_WRITE'}
58:23.586 26010-26763 System.err                      W  	at com.polidea.rxandroidble2.internal.operations.CharacteristicLongWriteOperation.protectedRun(CharacteristicLongWriteOperation.java:87)
58:23.587 26010-26763 System.err                      W  	at com.polidea.rxandroidble2.internal.QueueOperation$1.subscribe(QueueOperation.java:41)
58:23.587 26010-26763 System.err                      W  	at io.reactivex.internal.operators.observable.ObservableCreate.subscribeActual(ObservableCreate.java:40)
58:23.587 26010-26763 System.err                      W  	at io.reactivex.Observable.subscribe(Observable.java:12284)
58:23.587 26010-26763 System.err                      W  	at io.reactivex.internal.operators.observable.ObservableUnsubscribeOn.subscribeActual(ObservableUnsubscribeOn.java:32)
58:23.587 26010-26763 System.err                      W  	at io.reactivex.Observable.subscribe(Observable.java:12284)
58:23.587 26010-26763 System.err                      W  	at com.polidea.rxandroidble2.internal.serialization.FIFORunnableEntry$1.run(FIFORunnableEntry.java:56)
58:23.587 26010-26763 System.err                      W  	at io.reactivex.internal.schedulers.ScheduledDirectTask.call(ScheduledDirectTask.java:38)
58:23.587 26010-26763 System.err                      W  	at io.reactivex.internal.schedulers.ScheduledDirectTask.call(ScheduledDirectTask.java:26)
58:23.587 26010-26763 System.err                      W  	at java.util.concurrent.FutureTask.run(FutureTask.java:264)
58:23.587 26010-26763 System.err                      W  	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
58:23.588 26010-26763 System.err                      W  	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:644)
58:23.588 26010-32587 RxBle#ConnectionOperationQueue  D  STARTED  CharacteristicLongWriteOperation(163186669)
58:23.588 26010-26763 System.err                      W  	at java.lang.Thread.run(Thread.java:1012)
58:23.588 26010-26763 BLEManager                      E  BLECharacteristic write failed: GATT exception from MAC address XX:XX:XX:XX:XX:XX, with type BleGattOperation{description='CHARACTERISTIC_LONG_WRITE'}
58:23.588 26010-32587 RxBle#ConnectionOperationQueue  I  RUNNING  CharacteristicLongWriteOperation{MAC='XX:XX:XX:XX:XX:XX', characteristic=[uuid='...'], maxBatchSize=20}
58:23.589 26010-26763 System.err                      W  com.polidea.rxandroidble2.exceptions.BleGattCallbackTimeoutException: GATT exception from MAC address XX:XX:XX:XX:XX:XX, with type BleGattOperation{description='CHARACTERISTIC_LONG_WRITE'}
58:23.589 26010-26763 System.err                      W  	at com.polidea.rxandroidble2.internal.operations.CharacteristicLongWriteOperation.protectedRun(CharacteristicLongWriteOperation.java:87)
58:23.589 26010-26763 System.err                      W  	at com.polidea.rxandroidble2.internal.QueueOperation$1.subscribe(QueueOperation.java:41)
58:23.589 26010-26763 System.err                      W  	at io.reactivex.internal.operators.observable.ObservableCreate.subscribeActual(ObservableCreate.java:40)
58:23.590 26010-26763 System.err                      W  	at io.reactivex.Observable.subscribe(Observable.java:12284)
58:23.590 26010-26763 System.err                      W  	at io.reactivex.internal.operators.observable.ObservableUnsubscribeOn.subscribeActual(ObservableUnsubscribeOn.java:32)
58:23.590 26010-26763 System.err                      W  	at io.reactivex.Observable.subscribe(Observable.java:12284)
58:23.590 26010-26763 System.err                      W  	at com.polidea.rxandroidble2.internal.serialization.FIFORunnableEntry$1.run(FIFORunnableEntry.java:56)
58:23.590 26010-26763 System.err                      W  	at io.reactivex.internal.schedulers.ScheduledDirectTask.call(ScheduledDirectTask.java:38)
58:23.590 26010-26517 RxBle#Characte...riteOperation  D  Writing batch #0000: [...]
58:23.590 26010-26763 System.err                      W  	at io.reactivex.internal.schedulers.ScheduledDirectTask.call(ScheduledDirectTask.java:26)
58:23.590 26010-26763 System.err                      W  	at java.util.concurrent.FutureTask.run(FutureTask.java:264)
58:23.590 26010-26763 System.err                      W  	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
58:23.590 26010-26763 System.err                      W  	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:644)
58:23.590 26010-26763 System.err                      W  	at java.lang.Thread.run(Thread.java:1012)
58:23.592 26010-26517 BLEManager                      E  write long error: GATT exception from MAC address XX:XX:XX:XX:XX:XX, with type BleGattOperation{description='CHARACTERISTIC_LONG_WRITE'}
58:23.592 26010-32587 RxBle#ConnectionOperationQueue  D  FINISHED CharacteristicLongWriteOperation(163186669) in 6 ms
58:23.594 26010-32587 RxBle#ConnectionOperationQueue  D  STARTED  CharacteristicLongWriteOperation(132638899)
58:23.594 26010-26517 System.err                      W  com.polidea.rxandroidble2.exceptions.BleGattCannotStartException: GATT exception from MAC address XX:XX:XX:XX:XX:XX, with type BleGattOperation{description='CHARACTERISTIC_LONG_WRITE'}
58:23.594 26010-26517 System.err                      W  	at com.polidea.rxandroidble2.internal.operations.CharacteristicLongWriteOperation.writeData(CharacteristicLongWriteOperation.java:190)
58:23.594 26010-26517 System.err                      W  	at com.polidea.rxandroidble2.internal.operations.CharacteristicLongWriteOperation$3.subscribe(CharacteristicLongWriteOperation.java:165)
58:23.594 26010-26517 System.err                      W  	at io.reactivex.internal.operators.observable.ObservableCreate.subscribeActual(ObservableCreate.java:40)
58:23.594 26010-26517 System.err                      W  	at io.reactivex.Observable.subscribe(Observable.java:12284)
58:23.594 26010-26517 System.err                      W  	at io.reactivex.internal.operators.observable.ObservableSubscribeOn$SubscribeTask.run(ObservableSubscribeOn.java:96)
58:23.594 26010-26517 System.err                      W  	at io.reactivex.internal.schedulers.ScheduledDirectTask.call(ScheduledDirectTask.java:38)
58:23.594 26010-26517 System.err                      W  	at io.reactivex.internal.schedulers.ScheduledDirectTask.call(ScheduledDirectTask.java:26)
58:23.595 26010-26517 System.err                      W  	at java.util.concurrent.FutureTask.run(FutureTask.java:264)
58:23.595 26010-26517 System.err                      W  	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
58:23.595 26010-32587 RxBle#ConnectionOperationQueue  I  RUNNING  CharacteristicLongWriteOperation{MAC='XX:XX:XX:XX:XX:XX', characteristic=[uuid='...'], maxBatchSize=20}
58:23.595 26010-26517 System.err                      W  	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:644)
58:23.595 26010-26517 System.err                      W  	at java.lang.Thread.run(Thread.java:1012)
58:23.595 26010-26517 BLEManager                      E  BLECharacteristic write failed: GATT exception from MAC address XX:XX:XX:XX:XX:XX, with type BleGattOperation{description='CHARACTERISTIC_LONG_WRITE'}
58:23.596 26010-26517 System.err                      W  com.polidea.rxandroidble2.exceptions.BleGattCannotStartException: GATT exception from MAC address XX:XX:XX:XX:XX:XX, with type BleGattOperation{description='CHARACTERISTIC_LONG_WRITE'}
58:23.596 26010-26517 System.err                      W  	at com.polidea.rxandroidble2.internal.operations.CharacteristicLongWriteOperation.writeData(CharacteristicLongWriteOperation.java:190)
58:23.596 26010-26517 System.err                      W  	at com.polidea.rxandroidble2.internal.operations.CharacteristicLongWriteOperation$3.subscribe(CharacteristicLongWriteOperation.java:165)
58:23.596 26010-26517 System.err                      W  	at io.reactivex.internal.operators.observable.ObservableCreate.subscribeActual(ObservableCreate.java:40)
58:23.596 26010-26517 System.err                      W  	at io.reactivex.Observable.subscribe(Observable.java:12284)
58:23.596 26010-26517 System.err                      W  	at io.reactivex.internal.operators.observable.ObservableSubscribeOn$SubscribeTask.run(ObservableSubscribeOn.java:96)
58:23.596 26010-26517 System.err                      W  	at io.reactivex.internal.schedulers.ScheduledDirectTask.call(ScheduledDirectTask.java:38)
58:23.596 26010-26517 System.err                      W  	at io.reactivex.internal.schedulers.ScheduledDirectTask.call(ScheduledDirectTask.java:26)
58:23.596 26010-26517 System.err                      W  	at java.util.concurrent.FutureTask.run(FutureTask.java:264)
58:23.596 26010-26517 System.err                      W  	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
58:23.596 26010-26517 System.err                      W  	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:644)
58:23.596 26010-26517 System.err                      W  	at java.lang.Thread.run(Thread.java:1012)
58:23.597 26010-26517 RxBle#Characte...riteOperation  D  Writing batch #0000: [...]
58:23.598 26010-26517 BLEManager                      E  write long error: GATT exception from MAC address XX:XX:XX:XX:XX:XX, with type BleGattOperation{description='CHARACTERISTIC_LONG_WRITE'}
58:23.598 26010-32587 RxBle#ConnectionOperationQueue  D  FINISHED CharacteristicLongWriteOperation(132638899) in 6 ms



// After a lot of exceptions, the Bluetooth is disconnected.
58:23.662 26010-26789 RxBle#GattCallback              I  MAC='XX:XX:XX:XX:XX:XX'    onCharacteristicWrite(), status=133, value=[uuid='...']
58:23.662 26010-26789 BluetoothGatt                   D  onClientConnectionState() - status=22 clientIf=6 device=XX:XX:XX:XX:XX:XX
58:23.669 26010-26789 RxBle#GattCallback              I  MAC='XX:XX:XX:XX:XX:XX'  onConnectionStateChange(), status=22, value=0
58:23.671 26010-26789 RxBle#ConnectionOperationQueue  D  Connection operations queue to be terminated (MAC='XX:XX:XX:XX:XX:XX')
                                                                       com.polidea.rxandroidble2.exceptions.BleDisconnectedException: Disconnected from MAC='XX:XX:XX:XX:XX:XX' with status 22 (GATT_CONN_TERMINATE_LOCAL_HOST)
                                                                       	at com.polidea.rxandroidble2.internal.connection.RxBleGattCallback$2.onConnectionStateChange(RxBleGattCallback.java:85)
                                                                       	at android.bluetooth.BluetoothGatt$1$4.run(BluetoothGatt.java:381)
                                                                       	at android.bluetooth.BluetoothGatt.runOrQueueCallback(BluetoothGatt.java:1068)
                                                                       	at android.bluetooth.BluetoothGatt.-$$Nest$mrunOrQueueCallback(Unknown Source:0)
                                                                       	at android.bluetooth.BluetoothGatt$1.onClientConnectionState(BluetoothGatt.java:376)
                                                                       	at android.bluetooth.IBluetoothGattCallback$Stub.onTransact(IBluetoothGattCallback.java:226)
                                                                       	at android.os.Binder.execTransactInternal(Binder.java:1380)
                                                                       	at android.os.Binder.execTransact(Binder.java:1311)
58:23.672 26010-32587 RxBle#ConnectionOperationQueue  V  Terminated (MAC='XX:XX:XX:XX:XX:XX')
58:23.672 26010-26789 RxBle#ClientOperationQueue      D  QUEUED   DisconnectOperation(23872671)
58:23.673 26010-26762 BLEManager                      E  notification error: Disconnected from MAC='XX:XX:XX:XX:XX:XX' with status 22 (GATT_CONN_TERMINATE_LOCAL_HOST)
58:23.673 26010-26147 RxBle#ClientOperationQueue      D  STARTED  DisconnectOperation(23872671)
58:23.673 26010-26789 BluetoothGatt                   D  setCharacteristicNotification() - uuid: 2738cac5-a508-82b7-8c48-4356f52c4720 enable: false
58:23.673 26010-26147 RxBle#ClientOperationQueue      I  RUNNING  DisconnectOperation{MAC='XX:XX:XX:XX:XX:XX'}
58:23.674 26010-26762 System.err                      W  com.polidea.rxandroidble2.exceptions.BleDisconnectedException: Disconnected from MAC='XX:XX:XX:XX:XX:XX' with status 22 (GATT_CONN_TERMINATE_LOCAL_HOST)
58:23.674 26010-26762 System.err                      W  	at com.polidea.rxandroidble2.internal.connection.RxBleGattCallback$2.onConnectionStateChange(RxBleGattCallback.java:85)
58:23.674 26010-26762 System.err                      W  	at android.bluetooth.BluetoothGatt$1$4.run(BluetoothGatt.java:381)
58:23.674 26010-26762 System.err                      W  	at android.bluetooth.BluetoothGatt.runOrQueueCallback(BluetoothGatt.java:1068)
58:23.674 26010-26762 System.err                      W  	at android.bluetooth.BluetoothGatt.-$$Nest$mrunOrQueueCallback(Unknown Source:0)
58:23.674 26010-26762 System.err                      W  	at android.bluetooth.BluetoothGatt$1.onClientConnectionState(BluetoothGatt.java:376)
58:23.674 26010-26762 System.err                      W  	at android.bluetooth.IBluetoothGattCallback$Stub.onTransact(IBluetoothGattCallback.java:226)
58:23.674 26010-26762 System.err                      W  	at android.os.Binder.execTransactInternal(Binder.java:1380)
58:23.674 26010-26762 System.err                      W  	at android.os.Binder.execTransact(Binder.java:1311)

Additional context
Add any other context about the problem here.

@dquand91 dquand91 added the bug Bug that is caused by the library label Jun 19, 2024
@dariuszseweryn
Copy link
Owner

Hey, thanks for using the library!

This looks like an Android BLE stack error/unhandled situation. Most probably a HCI log would have hints on what is going on.

Are those long writes you make related somehow to configuring your peripheral's BLE configuration?

@dquand91
Copy link
Author

dquand91 commented Jun 22, 2024

Are those long writes you make related somehow to configuring your peripheral's BLE configuration?

Thanks for your replying.

Yes, I use long writes the characteristic with different data payload to configuring my peripheral's BLE.
The BLE connection is automatically disconnect after the BleGattCallbackTimeoutException.

Could you guide me some tips to workaround this issue?
Can we refresh the Gatt cache or do something in case of exception instead of disconnect the BLE?

@dariuszseweryn
Copy link
Owner

First of all – what configuration are you setting specifically? Maybe it's not needed or timed wrong?

As for the refresh, there is a topic about it already — it's possible

@dquand91
Copy link
Author

Thanks for your tips.
I think I should optimize the way to configuring peripheral device. Instead of writing many time in a short period of time, I will try to write sequentially.

@dariuszseweryn
Copy link
Owner

I don't think queuing these writes sequentially will help as they are executed sequentially FIFO anyway.

If you could share what these individual writes are configuring it could help understand what is going on.

Additional questions:

  1. How many bytes have the individual commands?
  2. Are these writes scheduled right after the connection is established or later?
  3. Is the peripheral paired/bonded?
@dquand91
Copy link
Author

If you could share what these individual writes are configuring it could help understand what is going on.

It is a feature called feature A of the peripheral device, when the application start or resume (move from background to foreground), I try to write/read configurations of this feature A, for example: get/set volume, get/set status (on or off),...

1.How many bytes have the individual commands?

There are 5 different commands with data payload from 2 to 9 bytes.

  1. Are these writes scheduled right after the connection is established or later?

No, I just try to write/read when the connection already is established. I also checked the BLE connection is connected or not before write/read.

  1. Is the peripheral paired/bonded?

It is already paired/bonded


I am trying to write/read 5 different BLE commands when the application moves from background to foreground. The app and peripheral are always paired/bonded while app is in background.
If I try to repeat the steps to move the app from background to foreground 10 times. There is at least 1 time that I observe the issue BLE disconnect.

@dariuszseweryn
Copy link
Owner

It is a feature called feature A of the peripheral device, when the application start or resume (move from background to foreground), I try to write/read configurations of this feature A, for example: get/set volume, get/set status (on or off),...

What does it change from the Bluetooth perspective? Are there changes in the bluetooth services available? Connection timings change?

There are 5 different commands with data payload from 2 to 9 bytes.

If so, I see no need in using rxBleConnection.createNewLongWriteBuilder(), standard rxBleConnection.writeCharacteristic() should work since no command exceeds the default 20 byte payload size (unless you concatenate multiple commands in one write). Or rather not work as I suspect the problem you face to be either a BLE stack related or a Peripheral implementation issue.

@dquand91
Copy link
Author

dquand91 commented Jun 24, 2024

Thanks for your support.
I have changed from the .createNewLongWriteBuilder() to .writeCharacteristic() for any commands less than 20 bytes payload size. It works as expected in my environment. But I am waiting for testers to confirm in their environment.

@dquand91
Copy link
Author

dquand91 commented Jun 28, 2024

Thanks @dariuszseweryn.
The change to use .writeCharacteristic() does not work in the testers environment. They still receive the same error about BleGattCallbackTimeoutException.
But the error is not always observed. They tried 10 times, there are 2 times observe the error.

Their phone are: Samsung S23, S23 Ultra. Both are running Android 13.

After the timeout exception, the bluetooth is disconnected automatically with either:

  • Disconnected from MAC='XX:XX:XX:XX:XX:XX' with status 0 (GATT_SUCCESS)
  • Or Disconnected from MAC='XX:XX:XX:XX:XX:XX' with status 22 (GATT_CONN_TERMINATE_LOCAL_HOST)

I wonder why the library automatically disconnect bluetooth in this case? Why don't we keep the connection and the application can handle the connection by itself?

@dariuszseweryn
Copy link
Owner

The change to use .writeCharacteristic() does not work in the testers environment. They still receive the same error about BleGattCallbackTimeoutException.
But the error is not always observed. They tried 10 times, there are 2 times observe the error.

That was expected.

I wonder why the library automatically disconnect bluetooth in this case? Why don't we keep the connection and the application can handle the connection by itself?

The library does not disconnect by itself but only reports what the Android BLE Stack is doing.

You still did not share what Bluetooth connection configuration can change with those 5 commands you write so I cannot give you more suggestions apart of looking into the BLE Stack. To get more insight on what the Android BLE Stack is doing (or rather what it is not handling correctly) you would need to check the Bluetooth HCI Log.

@dariuszseweryn dariuszseweryn added awaiting feedback and removed bug Bug that is caused by the library labels Jun 28, 2024
@dquand91
Copy link
Author

Sorry for making you confuse about the changing of BLE connection configuration by those 5 commands I write to the BLE device. The 5 commands just change settings for a function in the device that doesn't relate to Bluetooth configuration.

What does it change from the Bluetooth perspective? Are there changes in the bluetooth services available? Connection timings change?

The commands don't change anything relate to Bluetooth.

@dquand91
Copy link
Author

Now, the tester report that we are facing the BleGattCallbackTimeoutException on all BLE write commands that we send to device randomly. That means if we write a BLE command to device 10 times, each command 1 second apart, we can observe the timeout exception at least 1 time (1/10 tries).

But it is odd that the bug is only observed in testers's environment with their Samsung S23 and S23 Ultra.
I tried to reproduce with my Samsung S22 Ultra and Google Pixel 7A, but I don't observe the issue.

I think I should check bluetooth HCI log on their phone.

@dquand91
Copy link
Author

dquand91 commented Jul 3, 2024

HI @dariuszseweryn ,
I have received Bluetooth HCI log from the tester and analyzed it.
But I think the issue come from the Android BLE Stack. Because when the timeout was observed, the peripheral device did not receive any command from the phone.
The HCI log are:

// The normal flow
26325	6893.223687	SamsungElect_98:70:f8 (My S23)	Peripheral_Device_00:00:45 (Tester)	ATT	32	Sent Write Request, Handle: 0x0020 (Unknown: Unknown)
26326	6893.255955	controller	host	HCI_EVT	8	Rcvd Number of Completed Packets
26327	6893.285384	Peripheral_Device_00:00:45 (Tester)	SamsungElect_98:70:f8 (My S23)	ATT	10	Rcvd Write Response, Handle: 0x0020 (Unknown: Unknown)

26328	6893.289968	SamsungElect_98:70:f8 (My S23)	Peripheral_Device_00:00:45 (Tester)	ATT	15	Sent Write Request, Handle: 0x0020 (Unknown: Unknown)
26329	6893.315779	controller	host	HCI_EVT	8	Rcvd Number of Completed Packets
26330	6893.345345	Peripheral_Device_00:00:45 (Tester)	SamsungElect_98:70:f8 (My S23)	ATT	10	Rcvd Write Response, Handle: 0x0020 (Unknown: Unknown)

26331	6893.353423	SamsungElect_98:70:f8 (My S23)	Peripheral_Device_00:00:45 (Tester)	ATT	32	Sent Write Request, Handle: 0x0020 (Unknown: Unknown)
26332	6893.375894	controller	host	HCI_EVT	8	Rcvd Number of Completed Packets
26333	6893.405442	Peripheral_Device_00:00:45 (Tester)	SamsungElect_98:70:f8 (My S23)	ATT	10	Rcvd Write Response, Handle: 0x0020 (Unknown: Unknown)

26334	6893.410812	SamsungElect_98:70:f8 (My S23)	Peripheral_Device_00:00:45 (Tester)	ATT	32	Sent Write Request, Handle: 0x0020 (Unknown: Unknown)
26335	6893.437157	controller	host	HCI_EVT	8	Rcvd Number of Completed Packets
26336	6893.437374	remote ()	SamsungElect_98:70:f8 (My S23)	L2CAP	489	Rcvd Connection oriented channel
26337	6893.465926	Peripheral_Device_00:00:45 (Tester)	SamsungElect_98:70:f8 (My S23)	ATT	10	Rcvd Write Response, Handle: 0x0020 (Unknown: Unknown)

26338	6893.472595	SamsungElect_98:70:f8 (My S23)	Peripheral_Device_00:00:45 (Tester)	ATT	32	Sent Write Request, Handle: 0x0020 (Unknown: Unknown)
26339	6893.495650	controller	host	HCI_EVT	8	Rcvd Number of Completed Packets
26340	6893.525569	Peripheral_Device_00:00:45 (Tester)	SamsungElect_98:70:f8 (My S23)	ATT	10	Rcvd Write Response, Handle: 0x0020 (Unknown: Unknown)

26341	6893.530448	SamsungElect_98:70:f8 (My S23)	Peripheral_Device_00:00:45 (Tester)	ATT	16	Sent Write Request, Handle: 0x0020 (Unknown: Unknown)
26342	6893.555489	controller	host	HCI_EVT	8	Rcvd Number of Completed Packets
26343	6893.585602	Peripheral_Device_00:00:45 (Tester)	SamsungElect_98:70:f8 (My S23)	ATT	10	Rcvd Write Response, Handle: 0x0020 (Unknown: Unknown)

26344	6893.586548	Peripheral_Device_00:00:45 (Tester)	SamsungElect_98:70:f8 (My S23)	ATT	18	Rcvd Handle Value Notification, Handle: 0x0022 (Unknown: Unknown)
26345	6893.587030	Peripheral_Device_00:00:45 (Tester)	SamsungElect_98:70:f8 (My S23)	ATT	15	Rcvd Handle Value Notification, Handle: 0x0022 (Unknown: Unknown)

----------------------------------------------------------------------------------------
// ERROR FROM HERE
// The error flow, the Timeout Exception is observed after this command without any Response
26675	6972.433380	SamsungElect_98:70:f8 (My S23)	Peripheral_Device_00:00:45 (Tester)	ATT	32	Sent Write Request, Handle: 0x0020 (Unknown: Unknown)
26676	6972.463480	controller	host	HCI_EVT	8	Rcvd Number of Completed Packets

// After 30 seconds, it leads to disconnect BLE. 
26796	7002.434506	host	controller	HCI_CMD	7	Sent Disconnect
26797	7002.450666	controller	host	HCI_EVT	7	Rcvd Command Status (Disconnect)
26798	7002.450860	remote ()	SamsungElect_98:70:f8 (My S23)	L2CAP	485	Rcvd Connection oriented channel
26799	7002.450982	remote ()	SamsungElect_98:70:f8 (My S23)	L2CAP	482	Rcvd Connection oriented channel
26800	7002.451075	remote ()	SamsungElect_98:70:f8 (My S23)	L2CAP	485	Rcvd Connection oriented channel
26801	7002.451244	remote ()	SamsungElect_98:70:f8 (My S23)	L2CAP	489	Rcvd Connection oriented channel
26802	7002.453561	remote ()	SamsungElect_98:70:f8 (My S23)	L2CAP	495	Rcvd Connection oriented channel
26803	7002.453714	remote ()	SamsungElect_98:70:f8 (My S23)	L2CAP	486	Rcvd Connection oriented channel
26804	7002.456320	controller	host	HCI_EVT	7	Rcvd Disconnect Complete
@dariuszseweryn
Copy link
Owner

How do you verify that the peripheral did not received the write request?

Is the write request successful in the HCI log?

If yes, you could verify that the packet is actually (not) sent using a BLE sniffer.

@dquand91
Copy link
Author

dquand91 commented Jul 3, 2024

How do you verify that the peripheral did not received the write request?

There are not any log line from the peripheral device's log when the write request is sent from the app via BLE.

Is the write request successful in the HCI log?

From my understanding, the HCI log about write request is successful be like:

26675	6972.433380	SamsungElect_98:70:f8 (My S23)	Peripheral_Device_00:00:45 (Tester)	ATT	32	Sent Write Request, Handle: 0x0020 (Unknown: Unknown)
26676	6972.463480	controller	host	HCI_EVT	8	Rcvd Number of Completed Packets

If yes, you could verify that the packet is actually (not) sent using a BLE sniffer.

It is hard for me to sniff the BLE packets. Because I don't have the Samsung S23 phone.

Anyway, What do you think if I do a trick to command read characteristic before a command write? To make sure that the Gatt client is working.

@dariuszseweryn
Copy link
Owner

dariuszseweryn commented Jul 3, 2024

There are not any log line from the peripheral device's log when the write request is sent from the app via BLE.

Depending on the log level (stack/driver vs application) this may not be a decisive proof. i.e. it is possible the peripheral could receive the request but either stack failed on delivering the request to the application or the application itself did fail to create a log due to some silent failure.

I haven't seen so far the issue you're experiencing therefore I am inclined to think that the problem lies in peripheral's firmware (I have seen a lot of them).

Anyway, What do you think if I do a trick to command read characteristic before a command write? To make sure that the Gatt client is working.

This could help if the problem is somehow related to timing of commands — it is rather a blind shot, though.

It is hard for me to sniff the BLE packets. Because I don't have the Samsung S23 phone.

If you (or some tester) would be able to sniff BLE (I usually used an nRF dev-kit based solution) you could have a very concrete proof if the Android Stack is the problem or the peripheral side. If the Android would be the problem you could file a bug to Samsung. If the peripheral you would be sure that the firmware needs to be fixed (or peripheral's MCU vendor [TI, nRF, etc.] needs to fix their stack)

Have you tested with other Android phone vendors? Google Pixels, etc.?

@dquand91
Copy link
Author

dquand91 commented Jul 3, 2024

I haven't seen so far the issue you're experiencing therefore I am inclined to think that the problem lies in peripheral's firmware (I have seen a lot of them).

But the tester reported that they did not observe the issue on IOS (My application is running on Android and IOS).

Have you tested with other Android phone vendors? Google Pixels, etc.?

I also checked with other Android phones like: Google Pixel 7A, Samsung A52, Samsung S22 Ultra. But I didn't observe the issue.

@dariuszseweryn
Copy link
Owner

iOS has a completely different BLE stack and does implicitly different things than Android so it's hard to compare the behaviour between them.

If extensive testing on other vendors's phones did not show the problem it seems that its model specific.

HCI log you posted lacks a bit in the context of the requests that happened right before the failed one. You could compare if the only difference is the lack of the response or there is something more there.

@dariuszseweryn dariuszseweryn added the bug-model specific Bug that is caused by a flawed, model specific BLE stack implementation label Jul 5, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
awaiting feedback bug-model specific Bug that is caused by a flawed, model specific BLE stack implementation
2 participants