search

JuulLabs / kable

Kotlin Asynchronous Bluetooth Low-Energy
https://juullabs.github.io/kable
Apache License 2.0
829 stars 83 forks source link

OutOfOrderGattCallbackException: Unexpected response type OnCharacteristicWrite received #497

Closed egmazur closed 1 month ago

egmazur commented 1 year ago

I work on Android. Have been using this lib for more than one year. And now I got the case when I catch OutOfOrderGattCallbackException. The full text is OutOfOrderGattCallbackException: Unexpected response type OnCharacteristicWrite received. The scenario is pretty simple: there are two characteristics. One I use to write byte arrays on a device, the second one is read the status of this "writing". And in one moment I get this exception. I found it is source code but its cause is not clear for me. Why do I get it?

twyatt commented 1 year ago

What version of Kable are you using?

OutOfOrderGattCallbackException occurs when the underlying bluetooth callback provided Kable with an unexpected response.

More specifically, Kable ensures that every I/O operation happens within a lock. For example, when a write request is initiated, the lock prevents other I/O operations until Kable gets a write response. If an unexpected response is received, i.e. receiving a read response callback when we had just performed a write request, then OutOfOrderGattCallbackException would be thrown.

In most cases, this should not occur. I haven't seen the Android system giving unexpected responses, but that is what that exception is intended to inform you of (that failure case).

There is some complexity around cancellation handling, so it is possible that the internal Kable bookkeeping has a bug.

I would need more detailed logs to know more, and to help further.

grabbe-bryghtlabs commented 6 months ago

We came upon this issue with version 0.23.0.

twyatt commented 6 months ago

@grabbe-bryghtlabs can you provide logs to help debug the issue?

grabbe-bryghtlabs commented 6 months ago

This is a snippet

2024-04-09 11:24:35.854 28595-28632 oplus_bt_s..._ble_event com.android.bluetooth                I  report_stack_ble_gatt_read_write_operation_event enter
2024-04-09 11:24:35.854 28595-28632 BtGatt.GattService      com.android.bluetooth                D  onWriteCharacteristic() - increasing permit for address=DC:DA:0C:15:1F:A6
2024-04-09 11:24:35.855 28595-28632 oplus_bt_s..._ble_event com.android.bluetooth                I  stack_ble_gatt_read_write_operation_event_report address=dc:**:**:**:1f:a6
2024-04-09 11:24:36.062 28595-28916 BtGatt.GattService      com.android.bluetooth                D  writeCharacteristic() - trying to acquire permit.
2024-04-09 11:24:36.100 28595-28795 bt_bta_gattc            com.android.bluetooth                D  Handling write response type: 2: handle 0x000c
2024-04-09 11:24:36.100 28595-28632 oplus_bt_s..._ble_event com.android.bluetooth                I  report_stack_ble_gatt_read_write_operation_event enter
2024-04-09 11:24:36.101 28595-28632 BtGatt.GattService      com.android.bluetooth                D  onWriteCharacteristic() - increasing permit for address=DC:DA:0C:15:1F:A6
2024-04-09 11:24:36.103 28595-28632 oplus_bt_s..._ble_event com.android.bluetooth                I  stack_ble_gatt_read_write_operation_event_report address=dc:**:**:**:1f:a6
2024-04-09 11:24:38.906  1299-6353  ANDR-PERF-LM            ven...qti.hardware.perf@2.2-service  E  AdaptiveLaunch: writeToDataBase() 64: Meter aborted or could not get meter data for this run
2024-04-09 11:24:41.413  1299-1358  ANDR-PERF-LM            ven...qti.hardware.perf@2.2-service  W  FeatureState: writeState() 188: GameOptimization: State transition not allowed
2024-04-09 11:24:42.440  1299-6353  ANDR-PERF-LM            ven...qti.hardware.perf@2.2-service  E  AdaptiveLaunch: writeToDataBase() 64: Meter aborted or could not get meter data for this run
2024-04-09 11:24:44.800  1299-1358  ANDR-PERF-LM            ven...qti.hardware.perf@2.2-service  W  FeatureState: writeState() 188: GameOptimization: State transition not allowed
2024-04-09 11:24:45.012  1299-1358  ANDR-PERF-LM            ven...qti.hardware.perf@2.2-service  W  FeatureState: writeState() 188: GameOptimization: State transition not allowed
2024-04-09 11:24:46.051  1299-1358  ANDR-PERF-LM            ven...qti.hardware.perf@2.2-service  W  FeatureState: writeState() 188: GameOptimization: State transition not allowed
2024-04-09 11:24:48.988 17668-17668 BLEBoard                usap64                               E  Failed to send data, timeout
                                                                                                    com.juul.kable.GattRequestRejectedException
                                                                                                        at com.juul.kable.BluetoothDeviceAndroidPeripheral$write$$inlined$execute$1.invokeSuspend(Connection.kt:80)
                                                                                                        at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:33)
                                                                                                        at kotlinx.coroutines.DispatchedTask.run(DispatchedTask.kt:106)
                                                                                                        at android.os.Handler.handleCallback(Handler.java:958)
                                                                                                        at android.os.Handler.dispatchMessage(Handler.java:99)
                                                                                                        at android.os.Looper.loopOnce(Looper.java:257)
                                                                                                        at android.os.Looper.loop(Looper.java:368)
                                                                                                        at android.os.HandlerThread.run(HandlerThread.java:67)
twyatt commented 6 months ago

@grabbe-bryghtlabs thanks! I'll also need Kable logs leading up to the issue. With level Events or Data.

grabbe-bryghtlabs commented 6 months ago

@grabbe-bryghtlabs thanks! I'll also need Kable logs leading up to the issue. With level Events or Data.

This should be capturing the Events in the logger

2024-04-09 14:35:27.116 12898-13689 Kable/Peripheral        com.bryghtlabs.chessup               D  DC:DA:0C:15:1F:A6 write
                                                                                                    service: 6e400001-b5a3-f393-e0a9-e50e24dcca9e
                                                                                                    characteristic: 6e400002-b5a3-f393-e0a9-e50e24dcca9e
                                                                                                    writeType: WithResponse
2024-04-09 14:35:27.121 28595-1939  BtGatt.GattService      com.android.bluetooth                D  writeCharacteristic() - trying to acquire permit.
2024-04-09 14:35:27.125 12898-13807 BLEBoard                com.bryghtlabs.chessup               E  Failed to send data, timeout
                                                                                                    com.juul.kable.OutOfOrderGattCallbackException: Unexpected response type OnDescriptorWrite received
                                                                                                        at com.juul.kable.BluetoothDeviceAndroidPeripheral.write(BluetoothDeviceAndroidPeripheral.kt:715)
                                                                                                        at com.juul.kable.BluetoothDeviceAndroidPeripheral$write$1.invokeSuspend(Unknown Source:15)
                                                                                                        at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:33)
                                                                                                        at kotlinx.coroutines.DispatchedTask.run(DispatchedTask.kt:104)
                                                                                                        at kotlinx.coroutines.internal.LimitedDispatcher$Worker.run(LimitedDispatcher.kt:111)
                                                                                                        at kotlinx.coroutines.scheduling.TaskImpl.run(Tasks.kt:99)
                                                                                                        at kotlinx.coroutines.scheduling.CoroutineScheduler.runSafely(CoroutineScheduler.kt:585)
                                                                                                        at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.executeTask(CoroutineScheduler.kt:802)
                                                                                                        at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.runWorker(CoroutineScheduler.kt:706)
                                                                                                        at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.run(CoroutineScheduler.kt:693)
2024-04-09 14:35:27.125 12898-13807 <no-tag>                com.bryghtlabs.chessup               D  ******* blewrite exception: com.juul.kable.OutOfOrderGattCallbackException: Unexpected response type OnDescriptorWrite received
2024-04-09 14:35:27.205 28595-28795 bt_stack                com.android.bluetooth                E  [ERROR:gatt_cl.cc(624)] value resp op_code = ATT_RSP_PREPARE_WRITE len = 249
2024-04-09 14:35:27.258 28595-28795 bt_stack                com.android.bluetooth                E  [ERROR:gatt_cl.cc(624)] value resp op_code = ATT_RSP_PREPARE_WRITE len = 9
2024-04-09 14:35:27.318 28595-28795 bt_bta_gattc            com.android.bluetooth                D  Handling write response type: 2: handle 0x000c
2024-04-09 14:35:27.318 28595-28632 BtGatt.GattService      com.android.bluetooth                D  onWriteCharacteristic() - increasing permit for address=DC:DA:0C:15:1F:A6
2024-04-09 14:35:27.319 12898-13797 Kable/Callback          com.bryghtlabs.chessup               D  DC:DA:0C:15:1F:A6 onCharacteristicWrite
                                                                                                    service: 6e400001-b5a3-f393-e0a9-e50e24dcca9e
                                                                                                    characteristic: 6e400002-b5a3-f393-e0a9-e50e24dcca9e
                                                                                                    status: GATT_SUCCESS(0)
2024-04-09 14:35:27.326 12898-13807 Kable/Peripheral        com.bryghtlabs.chessup               D  DC:DA:0C:15:1F:A6 write
                                                                                                    service: 6e400001-b5a3-f393-e0a9-e50e24dcca9e
                                                                                                    characteristic: 6e400002-b5a3-f393-e0a9-e50e24dcca9e
                                                                                                    writeType: WithResponse
2024-04-09 14:35:27.328 28595-1939  BtGatt.GattService      com.android.bluetooth                D  writeCharacteristic() - trying to acquire permit.
2024-04-09 14:35:27.409 28595-28795 bt_bta_gattc            com.android.bluetooth                D  Handling write response type: 2: handle 0x000c
2024-04-09 14:35:27.409 28595-28632 oplus_bt_s..._ble_event com.android.bluetooth                I  report_stack_ble_gatt_read_write_operation_event enter
2024-04-09 14:35:27.410 28595-28632 BtGatt.GattService      com.android.bluetooth                D  onWriteCharacteristic() - increasing permit for address=DC:DA:0C:15:1F:A6
2024-04-09 14:35:27.414 28595-28632 oplus_bt_s..._ble_event com.android.bluetooth                I  stack_ble_gatt_read_write_operation_event_report address=dc:**:**:**:1f:a6
2024-04-09 14:35:27.415 12898-13797 Kable/Callback          com.bryghtlabs.chessup               D  DC:DA:0C:15:1F:A6 onCharacteristicWrite
                                                                                                    service: 6e400001-b5a3-f393-e0a9-e50e24dcca9e
                                                                                                    characteristic: 6e400002-b5a3-f393-e0a9-e50e24dcca9e
                                                                                                    status: GATT_SUCCESS(0)
2024-04-09 14:35:27.731 12898-13689 Kable/Peripheral        com.bryghtlabs.chessup               D  DC:DA:0C:15:1F:A6 write
                                                                                                    service: 6e400001-b5a3-f393-e0a9-e50e24dcca9e
                                                                                                    characteristic: 6e400002-b5a3-f393-e0a9-e50e24dcca9e
                                                                                                    writeType: WithResponse
2024-04-09 14:35:27.734 28595-1939  BtGatt.GattService      com.android.bluetooth                D  writeCharacteristic() - trying to acquire permit.
2024-04-09 14:35:27.770 28595-28795 bt_bta_gattc            com.android.bluetooth                D  Handling write response type: 2: handle 0x000c
2024-04-09 14:35:27.770 28595-28632 oplus_bt_s..._ble_event com.android.bluetooth                I  report_stack_ble_gatt_read_write_operation_event enter
2024-04-09 14:35:27.771 28595-28632 BtGatt.GattService      com.android.bluetooth                D  onWriteCharacteristic() - increasing permit for address=DC:DA:0C:15:1F:A6
2024-04-09 14:35:27.771 28595-28632 oplus_bt_s..._ble_event com.android.bluetooth                I  stack_ble_gatt_read_write_operation_event_report address=dc:**:**:**:1f:a6
2024-04-09 14:35:27.773 12898-13797 Kable/Callback          com.bryghtlabs.chessup               D  DC:DA:0C:15:1F:A6 onCharacteristicWrite
                                                                                                    service: 6e400001-b5a3-f393-e0a9-e50e24dcca9e
                                                                                                    characteristic: 6e400002-b5a3-f393-e0a9-e50e24dcca9e
                                                                                                    status: GATT_SUCCESS(0)
2024-04-09 14:35:30.223  1299-1358  ANDR-PERF-LM            ven...qti.hardware.perf@2.2-service  W  FeatureState: writeState() 188: GameOptimization: State transition not allowed
2024-04-09 14:35:31.234  1299-6353  ANDR-PERF-LM            ven...qti.hardware.perf@2.2-service  E  AdaptiveLaunch: writeToDataBase() 64: Meter aborted or could not get meter data for this run
2024-04-09 14:35:34.827  1299-1358  ANDR-PERF-LM            ven...qti.hardware.perf@2.2-service  W  FeatureState: writeState() 188: GameOptimization: State transition not allowed
2024-04-09 14:35:34.877  1299-1358  ANDR-PERF-LM            ven...qti.hardware.perf@2.2-service  W  FeatureState: writeState() 188: GameOptimization: State transition not allowed
2024-04-09 14:35:35.262  1299-1358  ANDR-PERF-LM            ven...qti.hardware.perf@2.2-service  W  FeatureState: writeState() 188: GameOptimization: State transition not allowed
2024-04-09 14:35:36.320  1299-1358  ANDR-PERF-LM            ven...qti.hardware.perf@2.2-service  W  FeatureState: writeState() 188: GameOptimization: State transition not allowed
2024-04-09 14:35:38.576  1299-1358  ANDR-PERF-LM            ven...qti.hardware.perf@2.2-service  W  FeatureState: writeState() 188: GameOptimization: State transition not allowed
2024-04-09 14:35:39.346 12898-12898 Kable/Peripheral        com.bryghtlabs.chessup               D  DC:DA:0C:15:1F:A6 write
                                                                                                    service: 6e400001-b5a3-f393-e0a9-e50e24dcca9e
                                                                                                    characteristic: 6e400002-b5a3-f393-e0a9-e50e24dcca9e
                                                                                                    writeType: WithResponse
2024-04-09 14:35:39.352 28595-28916 BtGatt.GattService      com.android.bluetooth                D  writeCharacteristic() - trying to acquire permit.
2024-04-09 14:35:39.439 28595-28632 oplus_bt_s..._ble_event com.android.bluetooth                I  report_stack_ble_gatt_read_write_operation_event enter
2024-04-09 14:35:39.440 28595-28795 bt_bta_gattc            com.android.bluetooth                D  Handling write response type: 2: handle 0x000c
2024-04-09 14:35:39.440 28595-28632 oplus_bt_s..._ble_event com.android.bluetooth                I  stack_ble_gatt_read_write_operation_event_report address=dc:**:**:**:1f:a6
2024-04-09 14:35:39.440 28595-28632 BtGatt.GattService      com.android.bluetooth                D  onWriteCharacteristic() - increasing permit for address=DC:DA:0C:15:1F:A6
2024-04-09 14:35:39.442 12898-13797 Kable/Callback          com.bryghtlabs.chessup               D  DC:DA:0C:15:1F:A6 onCharacteristicWrite
                                                                                                    service: 6e400001-b5a3-f393-e0a9-e50e24dcca9e
                                                                                                    characteristic: 6e400002-b5a3-f393-e0a9-e50e24dcca9e
                                                                                                    status: GATT_SUCCESS(0)
2024-04-09 14:35:39.555 12898-12898 Kable/Peripheral        com.bryghtlabs.chessup               D  DC:DA:0C:15:1F:A6 write
                                                                                                    service: 6e400001-b5a3-f393-e0a9-e50e24dcca9e
                                                                                                    characteristic: 6e400002-b5a3-f393-e0a9-e50e24dcca9e
                                                                                                    writeType: WithResponse
2024-04-09 14:35:39.559 28595-28916 BtGatt.GattService      com.android.bluetooth                D  writeCharacteristic() - trying to acquire permit.
2024-04-09 14:35:39.619 28595-28632 oplus_bt_s..._ble_event com.android.bluetooth                I  report_stack_ble_gatt_read_write_operation_event enter
2024-04-09 14:35:39.620 28595-28632 oplus_bt_s..._ble_event com.android.bluetooth                I  stack_ble_gatt_read_write_operation_event_report address=dc:**:**:**:1f:a6
2024-04-09 14:35:39.621 28595-28795 bt_bta_gattc            com.android.bluetooth                D  Handling write response type: 2: handle 0x000c
2024-04-09 14:35:39.622 28595-28632 BtGatt.GattService      com.android.bluetooth                D  onWriteCharacteristic() - increasing permit for address=DC:DA:0C:15:1F:A6
2024-04-09 14:35:39.625 12898-13797 Kable/Callback          com.bryghtlabs.chessup               D  DC:DA:0C:15:1F:A6 onCharacteristicWrite
                                                                                                    service: 6e400001-b5a3-f393-e0a9-e50e24dcca9e
                                                                                                    characteristic: 6e400002-b5a3-f393-e0a9-e50e24dcca9e
                                                                                                    status: GATT_SUCCESS(0)
2024-04-09 14:35:40.141  1299-1358  ANDR-PERF-LM            ven...qti.hardware.perf@2.2-service  W  FeatureState: writeState() 188: GameOptimization: State transition not allowed
2024-04-09 14:35:40.338  1299-1358  ANDR-PERF-LM            ven...qti.hardware.perf@2.2-service  W  FeatureState: writeState() 188: GameOptimization: State transition not allowed
2024-04-09 14:35:42.234  1299-6353  ANDR-PERF-LM            ven...qti.hardware.perf@2.2-service  E  AdaptiveLaunch: writeToDataBase() 64: Meter aborted or could not get meter data for this run
2024-04-09 14:35:43.638  1299-1358  ANDR-PERF-LM            ven...qti.hardware.perf@2.2-service  W  FeatureState: writeState() 188: GameOptimization: State transition not allowed
2024-04-09 14:35:43.860  1299-1358  ANDR-PERF-LM            ven...qti.hardware.perf@2.2-service  W  FeatureState: writeState() 188: GameOptimization: State transition not allowed
2024-04-09 14:35:44.550  1299-1358  ANDR-PERF-LM            ven...qti.hardware.perf@2.2-service  W  FeatureState: writeState() 188: GameOptimization: State transition not allowed
2024-04-09 14:35:47.551 13356-13356 Kable/Peripheral        usap64                               D  DC:DA:0C:15:1F:A6 write
                                                                                                    service: 6e400001-b5a3-f393-e0a9-e50e24dcca9e
                                                                                                    characteristic: 6e400002-b5a3-f393-e0a9-e50e24dcca9e
                                                                                                    writeType: WithResponse
2024-04-09 14:35:47.553 28595-5722  BtGatt.GattService      com.android.bluetooth                D  writeCharacteristic() - trying to acquire permit.
2024-04-09 14:35:47.559 13356-13356 Kable/Peripheral        usap64                               D  DC:DA:0C:15:1F:A6 write
                                                                                                    service: 6e400001-b5a3-f393-e0a9-e50e24dcca9e
                                                                                                    characteristic: 6e400003-b5a3-f393-e0a9-e50e24dcca9e
                                                                                                    descriptor: 00002902-0000-1000-8000-00805f9b34fb
2024-04-09 14:35:47.560 13356-13356 Kable/Peripheral        usap64                               D  DC:DA:0C:15:1F:A6 write
                                                                                                    service: 0000180f-0000-1000-8000-00805f9b34fb
                                                                                                    characteristic: 00002a19-0000-1000-8000-00805f9b34fb
                                                                                                    descriptor: 00002902-0000-1000-8000-00805f9b34fb
2024-04-09 14:35:47.569 28595-28795 bt_bta_gattc            com.android.bluetooth                D  Handling write response type: 2: handle 0x000c
2024-04-09 14:35:47.570 28595-28632 oplus_bt_s..._ble_event com.android.bluetooth                I  report_stack_ble_gatt_read_write_operation_event enter
2024-04-09 14:35:47.570 28595-28632 BtGatt.GattService      com.android.bluetooth                D  onWriteCharacteristic() - increasing permit for address=DC:DA:0C:15:1F:A6
2024-04-09 14:35:47.570 28595-28632 oplus_bt_s..._ble_event com.android.bluetooth                I  stack_ble_gatt_read_write_operation_event_report address=dc:**:**:**:1f:a6
2024-04-09 14:35:47.573 13356-15530 Kable/Callback          usap64                               D  DC:DA:0C:15:1F:A6 onCharacteristicWrite
                                                                                                    service: 6e400001-b5a3-f393-e0a9-e50e24dcca9e
                                                                                                    characteristic: 6e400002-b5a3-f393-e0a9-e50e24dcca9e
                                                                                                    status: GATT_SUCCESS(0)
2024-04-09 14:35:47.692 28595-28795 bt_bta_gattc            com.android.bluetooth                D  Handling write response type: 2: handle 0x000f
2024-04-09 14:35:47.693 28595-28632 oplus_bt_s..._ble_event com.android.bluetooth                I  report_stack_ble_gatt_read_write_operation_event enter
2024-04-09 14:35:47.694 28595-28632 oplus_bt_s..._ble_event com.android.bluetooth                I  stack_ble_gatt_read_write_operation_event_report address=dc:**:**:**:1f:a6
2024-04-09 14:35:47.695 13356-15530 Kable/Callback          usap64                               D  DC:DA:0C:15:1F:A6 onDescriptorWrite
                                                                                                    service: 6e400001-b5a3-f393-e0a9-e50e24dcca9e
                                                                                                    characteristic: 6e400003-b5a3-f393-e0a9-e50e24dcca9e
                                                                                                    descriptor: 00002902-0000-1000-8000-00805f9b34fb
                                                                                                    status: GATT_SUCCESS(0)
2024-04-09 14:35:47.781 28595-28795 bt_bta_gattc            com.android.bluetooth                D  Handling write response type: 2: handle 0x0013
2024-04-09 14:35:47.782 28595-28632 oplus_bt_s..._ble_event com.android.bluetooth                I  report_stack_ble_gatt_read_write_operation_event enter
2024-04-09 14:35:47.783 28595-28632 oplus_bt_s..._ble_event com.android.bluetooth                I  stack_ble_gatt_read_write_operation_event_report address=dc:**:**:**:1f:a6
2024-04-09 14:35:47.784 13356-15530 Kable/Callback          usap64                               D  DC:DA:0C:15:1F:A6 onDescriptorWrite
                                                                                                    service: 0000180f-0000-1000-8000-00805f9b34fb
                                                                                                    characteristic: 00002a19-0000-1000-8000-00805f9b34fb
                                                                                                    descriptor: 00002902-0000-1000-8000-00805f9b34fb
                                                                                                    status: GATT_SUCCESS(0)
twyatt commented 6 months ago

Thanks! The very first line of those logs show a write to a characteristic but then shortly after you see the exception from Kable stating that it received a descriptor response.

Is there any chance you can provide more of the logs leading up to the exception? I'm trying to understand what data was sent to Android and what sequence Android is responding in. Thanks again.

grabbe-bryghtlabs commented 6 months ago

Thanks! The very first line of those logs show a write to a characteristic but then shortly after you see the exception from Kable stating that it received a descriptor response.

Is there any chance you can provide more of the logs leading up to the exception? I'm trying to understand what data was sent to Android and what sequence Android is responding in. Thanks again.

Here is a log starting with the device connection:

2024-04-10 08:25:16.605  4177-4288  PeripheralProximity     com.bryghtlabs.chessup               D  getProximity: rssi=-51 -> Immediate
2024-04-10 08:25:16.609  4177-4288  BLEBoard                com.bryghtlabs.chessup               D  peripheral Created
2024-04-10 08:25:16.614  4177-4286  BLEBoard                com.bryghtlabs.chessup               D  observePeripheralStatus - Disconnected(null)
2024-04-10 08:25:16.614  4177-4177  BLEBoard                com.bryghtlabs.chessup               D  stopScanning
2024-04-10 08:25:16.616  4177-4286  BluetoothAdapter        com.bryghtlabs.chessup               D  isLeEnabled(): ON
2024-04-10 08:25:16.618  4177-4177  Kable/Peripheral        com.bryghtlabs.chessup               I  EB:86:28:7F:C5:04 Connecting
2024-04-10 08:25:16.620  4177-4177  BluetoothGatt           com.bryghtlabs.chessup               D  connect() - device: EB:86:28:7F:C5:04, auto: false, eattSupport: false
2024-04-10 08:25:16.621  4177-4177  BluetoothGatt           com.bryghtlabs.chessup               D  registerApp()
2024-04-10 08:25:16.621  4177-4177  BluetoothGatt           com.bryghtlabs.chessup               D  registerApp() - UUID=5cd77baf-62d7-4190-92f8-23b260e48423
2024-04-10 08:25:16.627  4177-4197  BluetoothGatt           com.bryghtlabs.chessup               D  onClientRegistered() - status=0 clientIf=13
2024-04-10 08:25:16.628  4177-4177  Kable/Scanner           com.bryghtlabs.chessup               W  Unable to deliver scan result due to failure in flow or premature closing.
2024-04-10 08:25:17.277  4177-4190  BluetoothGatt           com.bryghtlabs.chessup               D  onClientConnectionState() - status=0 clientIf=13 device=EB:86:28:7F:C5:04
2024-04-10 08:25:17.278  4177-4727  Kable/Callback          com.bryghtlabs.chessup               D  EB:86:28:7F:C5:04 onConnectionStateChange
                                                                                                    status: Success
                                                                                                    newState: Connected
2024-04-10 08:25:17.279  4177-4177  Kable/Peripheral        com.bryghtlabs.chessup               V  EB:86:28:7F:C5:04 discoverServices
2024-04-10 08:25:17.280  4177-4727  BluetoothGatt           com.bryghtlabs.chessup               D  discoverServices() - device: EB:86:28:7F:C5:04
2024-04-10 08:25:17.627  4177-4729  BLEBoard                com.bryghtlabs.chessup               D  try startScanning
2024-04-10 08:25:17.628  4177-4729  BLEBoard                com.bryghtlabs.chessup               D  startScanning approved
2024-04-10 08:25:17.628  4177-4729  BLEBoard                com.bryghtlabs.chessup               D  observePeripheralStatus - Connecting.Services
2024-04-10 08:25:17.631  4177-4729  BLEBoard                com.bryghtlabs.chessup               D  scanningJobBody running
2024-04-10 08:25:17.632  4177-4286  BluetoothAdapter        com.bryghtlabs.chessup               D  isLeEnabled(): ON
2024-04-10 08:25:17.637  4177-4190  BluetoothLeScanner      com.bryghtlabs.chessup               D  onScannerRegistered() - status=0 scannerId=12 mScannerId=0
2024-04-10 08:25:17.901  4177-4190  BluetoothGatt           com.bryghtlabs.chessup               D  onConnectionUpdated() - Device=EB:86:28:7F:C5:04 interval=6 latency=0 timeout=500 status=0
2024-04-10 08:25:18.039  4177-4190  BluetoothGatt           com.bryghtlabs.chessup               D  onSearchComplete() = Device=EB:86:28:7F:C5:04 Status=0
2024-04-10 08:25:18.040  4177-4727  Kable/Callback          com.bryghtlabs.chessup               D  EB:86:28:7F:C5:04 onServicesDiscovered
                                                                                                    status: GATT_SUCCESS(0)
2024-04-10 08:25:18.043  4177-4177  Kable/Peripheral        com.bryghtlabs.chessup               V  EB:86:28:7F:C5:04 Discovered 5 services
2024-04-10 08:25:18.043  4177-4177  Kable/Peripheral        com.bryghtlabs.chessup               D  EB:86:28:7F:C5:04 requestMtu
                                                                                                    mtu: 250
2024-04-10 08:25:18.044  4177-4727  BluetoothGatt           com.bryghtlabs.chessup               D  configureMTU() - device: EB:86:28:7F:C5:04 mtu: 250
2024-04-10 08:25:18.052  4177-4190  BluetoothGatt           com.bryghtlabs.chessup               D  onConfigureMTU() - Device=EB:86:28:7F:C5:04 mtu=247 status=0
2024-04-10 08:25:18.053  4177-4727  Kable/Callback          com.bryghtlabs.chessup               D  EB:86:28:7F:C5:04 onMtuChanged
                                                                                                    mtu: 247
                                                                                                    status: GATT_SUCCESS(0)
2024-04-10 08:25:18.054  4177-4177  <no-tag>                com.bryghtlabs.chessup               D  ***** mtuSize: 247
2024-04-10 08:25:18.055  4177-4177  Kable/Peripheral        com.bryghtlabs.chessup               V  EB:86:28:7F:C5:04 Configuring characteristic observations
2024-04-10 08:25:18.055  4177-4177  Kable/Peripheral        com.bryghtlabs.chessup               I  EB:86:28:7F:C5:04 Connected
2024-04-10 08:25:18.055  4177-4729  BLEBoard                com.bryghtlabs.chessup               D  observePeripheralStatus - Connecting.Observes
2024-04-10 08:25:18.055  4177-4729  BLEBoard                com.bryghtlabs.chessup               D  observePeripheralStatus - Connected
2024-04-10 08:25:18.055  4177-4729  BLEBoard                com.bryghtlabs.chessup               D  stopScanning
2024-04-10 08:25:18.056  4177-4177  BLEBoard                com.bryghtlabs.chessup               D  Connected
2024-04-10 08:25:18.057  4177-4286  BluetoothAdapter        com.bryghtlabs.chessup               D  isLeEnabled(): ON
2024-04-10 08:25:18.057  4177-4177  BLEBoard                com.bryghtlabs.chessup               D  peripheralUpdatedEvent received
2024-04-10 08:25:18.062  4177-4177  Kable/Peripheral        com.bryghtlabs.chessup               D  EB:86:28:7F:C5:04 setCharacteristicNotification
                                                                                                    service: 6e400001-b5a3-f393-e0a9-e50e24dcca9e
                                                                                                    characteristic: 6e400003-b5a3-f393-e0a9-e50e24dcca9e
                                                                                                    value: true
2024-04-10 08:25:18.062  4177-4177  BluetoothGatt           com.bryghtlabs.chessup               D  setCharacteristicNotification() - uuid: 6e400003-b5a3-f393-e0a9-e50e24dcca9e enable: true
2024-04-10 08:25:18.063  4177-4177  Kable/Peripheral        com.bryghtlabs.chessup               V  EB:86:28:7F:C5:04 Writing ENABLE_NOTIFICATION_VALUE to CCCD
                                                                                                    service: 6e400001-b5a3-f393-e0a9-e50e24dcca9e
                                                                                                    characteristic: 6e400003-b5a3-f393-e0a9-e50e24dcca9e
                                                                                                    descriptor: 00002902-0000-1000-8000-00805f9b34fb
2024-04-10 08:25:18.064  4177-4177  Kable/Peripheral        com.bryghtlabs.chessup               D  EB:86:28:7F:C5:04 write
                                                                                                    service: 6e400001-b5a3-f393-e0a9-e50e24dcca9e
                                                                                                    characteristic: 6e400003-b5a3-f393-e0a9-e50e24dcca9e
                                                                                                    descriptor: 00002902-0000-1000-8000-00805f9b34fb
2024-04-10 08:25:18.065  4177-4177  Kable/Peripheral        com.bryghtlabs.chessup               D  EB:86:28:7F:C5:04 setCharacteristicNotification
                                                                                                    service: 0000180f-0000-1000-8000-00805f9b34fb
                                                                                                    characteristic: 00002a19-0000-1000-8000-00805f9b34fb
                                                                                                    value: true
2024-04-10 08:25:18.065  4177-4177  BluetoothGatt           com.bryghtlabs.chessup               D  setCharacteristicNotification() - uuid: 00002a19-0000-1000-8000-00805f9b34fb enable: true
2024-04-10 08:25:18.067  4177-4177  Kable/Peripheral        com.bryghtlabs.chessup               V  EB:86:28:7F:C5:04 Writing ENABLE_NOTIFICATION_VALUE to CCCD
                                                                                                    service: 0000180f-0000-1000-8000-00805f9b34fb
                                                                                                    characteristic: 00002a19-0000-1000-8000-00805f9b34fb
                                                                                                    descriptor: 00002902-0000-1000-8000-00805f9b34fb
2024-04-10 08:25:18.068  4177-4177  Kable/Peripheral        com.bryghtlabs.chessup               D  EB:86:28:7F:C5:04 write
                                                                                                    service: 0000180f-0000-1000-8000-00805f9b34fb
                                                                                                    characteristic: 00002a19-0000-1000-8000-00805f9b34fb
                                                                                                    descriptor: 00002902-0000-1000-8000-00805f9b34fb
2024-04-10 08:25:18.071  4177-4177  BLEBoard                com.bryghtlabs.chessup               D  board request message sending started com.bryghlabs.chessup.ble.request.BoardRequestMessage$GetBoardInfo@8ec20ce
2024-04-10 08:25:18.072  4177-4177  Kable/Peripheral        com.bryghtlabs.chessup               D  EB:86:28:7F:C5:04 write
                                                                                                    service: 6e400001-b5a3-f393-e0a9-e50e24dcca9e
                                                                                                    characteristic: 6e400002-b5a3-f393-e0a9-e50e24dcca9e
                                                                                                    writeType: WithResponse
2024-04-10 08:25:18.075  4177-4177  Kable/Peripheral        com.bryghtlabs.chessup               D  EB:86:28:7F:C5:04 setCharacteristicNotification
                                                                                                    service: 6e400001-b5a3-f393-e0a9-e50e24dcca9e
                                                                                                    characteristic: 6e400003-b5a3-f393-e0a9-e50e24dcca9e
                                                                                                    value: true
2024-04-10 08:25:18.075  4177-4177  BluetoothGatt           com.bryghtlabs.chessup               D  setCharacteristicNotification() - uuid: 6e400003-b5a3-f393-e0a9-e50e24dcca9e enable: true
2024-04-10 08:25:18.075  4177-4727  Kable/Callback          com.bryghtlabs.chessup               D  EB:86:28:7F:C5:04 onDescriptorWrite
                                                                                                    service: 6e400001-b5a3-f393-e0a9-e50e24dcca9e
                                                                                                    characteristic: 6e400003-b5a3-f393-e0a9-e50e24dcca9e
                                                                                                    descriptor: 00002902-0000-1000-8000-00805f9b34fb
                                                                                                    status: GATT_SUCCESS(0)
2024-04-10 08:25:18.078  4177-4177  Kable/Peripheral        com.bryghtlabs.chessup               V  EB:86:28:7F:C5:04 Writing ENABLE_NOTIFICATION_VALUE to CCCD
                                                                                                    service: 6e400001-b5a3-f393-e0a9-e50e24dcca9e
                                                                                                    characteristic: 6e400003-b5a3-f393-e0a9-e50e24dcca9e
                                                                                                    descriptor: 00002902-0000-1000-8000-00805f9b34fb
2024-04-10 08:25:18.079  4177-4177  Kable/Peripheral        com.bryghtlabs.chessup               D  EB:86:28:7F:C5:04 write
                                                                                                    service: 6e400001-b5a3-f393-e0a9-e50e24dcca9e
                                                                                                    characteristic: 6e400003-b5a3-f393-e0a9-e50e24dcca9e
                                                                                                    descriptor: 00002902-0000-1000-8000-00805f9b34fb
2024-04-10 08:25:18.081  4177-4177  Kable/Peripheral        com.bryghtlabs.chessup               D  EB:86:28:7F:C5:04 setCharacteristicNotification
                                                                                                    service: 0000180f-0000-1000-8000-00805f9b34fb
                                                                                                    characteristic: 00002a19-0000-1000-8000-00805f9b34fb
                                                                                                    value: true
2024-04-10 08:25:18.081  4177-4177  BluetoothGatt           com.bryghtlabs.chessup               D  setCharacteristicNotification() - uuid: 00002a19-0000-1000-8000-00805f9b34fb enable: true
2024-04-10 08:25:18.083  4177-4177  Kable/Peripheral        com.bryghtlabs.chessup               V  EB:86:28:7F:C5:04 Writing ENABLE_NOTIFICATION_VALUE to CCCD
                                                                                                    service: 0000180f-0000-1000-8000-00805f9b34fb
                                                                                                    characteristic: 00002a19-0000-1000-8000-00805f9b34fb
                                                                                                    descriptor: 00002902-0000-1000-8000-00805f9b34fb
2024-04-10 08:25:18.083  4177-4177  Kable/Peripheral        com.bryghtlabs.chessup               D  EB:86:28:7F:C5:04 write
                                                                                                    service: 0000180f-0000-1000-8000-00805f9b34fb
                                                                                                    characteristic: 00002a19-0000-1000-8000-00805f9b34fb
                                                                                                    descriptor: 00002902-0000-1000-8000-00805f9b34fb
2024-04-10 08:25:18.146  4177-4190  BluetoothGatt           com.bryghtlabs.chessup               D  onConnectionUpdated() - Device=EB:86:28:7F:C5:04 interval=39 latency=0 timeout=500 status=0
2024-04-10 08:25:18.158  4177-4177  BLEBoard                com.bryghtlabs.chessup               E  Failed to send data, timeout
                                                                                                    com.juul.kable.OutOfOrderGattCallbackException: Unexpected response type OnDescriptorWrite received
                                                                                                        at com.juul.kable.BluetoothDeviceAndroidPeripheral.write(BluetoothDeviceAndroidPeripheral.kt:715)
                                                                                                        at com.juul.kable.BluetoothDeviceAndroidPeripheral$write$1.invokeSuspend(Unknown Source:15)
                                                                                                        at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:33)
                                                                                                        at kotlinx.coroutines.DispatchedTask.run(DispatchedTask.kt:104)
                                                                                                        at android.os.Handler.handleCallback(Handler.java:978)
                                                                                                        at android.os.Handler.dispatchMessage(Handler.java:104)
                                                                                                        at android.os.Looper.loopOnce(Looper.java:238)
                                                                                                        at android.os.Looper.loop(Looper.java:357)
                                                                                                        at android.app.ActivityThread.main(ActivityThread.java:8103)
                                                                                                        at java.lang.reflect.Method.invoke(Native Method)
                                                                                                        at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:548)
                                                                                                        at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:1026)
2024-04-10 08:25:18.158  4177-4177  <no-tag>                com.bryghtlabs.chessup               D  ******* blewrite exception: com.juul.kable.OutOfOrderGattCallbackException: Unexpected response type OnDescriptorWrite received
2024-04-10 08:25:18.158  4177-4177  BLEBoard                com.bryghtlabs.chessup               D  board request message sent com.bryghlabs.chessup.ble.request.BoardRequestMessage$GetBoardInfo@8ec20ce
2024-04-10 08:25:18.163  4177-4177  Kable/Observation       com.bryghtlabs.chessup               V  EB:86:28:7F:C5:04 Suppressed failure: com.juul.kable.GattRequestRejectedException
2024-04-10 08:25:18.164  4177-4177  Kable/Observation       com.bryghtlabs.chessup               V  EB:86:28:7F:C5:04 Suppressed failure: com.juul.kable.GattRequestRejectedException
2024-04-10 08:25:18.195  4177-4727  Kable/Callback          com.bryghtlabs.chessup               D  EB:86:28:7F:C5:04 onCharacteristicWrite
                                                                                                    service: 6e400001-b5a3-f393-e0a9-e50e24dcca9e
                                                                                                    characteristic: 6e400002-b5a3-f393-e0a9-e50e24dcca9e
                                                                                                    status: GATT_SUCCESS(0)
2024-04-10 08:25:20.440  4177-4727  Kable/Callback          com.bryghtlabs.chessup               D  EB:86:28:7F:C5:04 onCharacteristicChanged
                                                                                                    service: 6e400001-b5a3-f393-e0a9-e50e24dcca9e
                                                                                                    characteristic: 6e400003-b5a3-f393-e0a9-e50e24dcca9e
2024-04-10 08:25:20.442  4177-4727  Kable/Callback          com.bryghtlabs.chessup               D  EB:86:28:7F:C5:04 onCharacteristicChanged
                                                                                                    service: 6e400001-b5a3-f393-e0a9-e50e24dcca9e
                                                                                                    characteristic: 6e400003-b5a3-f393-e0a9-e50e24dcca9e
2024-04-10 08:25:20.443  4177-4177  BoardHeaders            com.bryghtlabs.chessup               D  fromValue: 178
2024-04-10 08:25:20.444  4177-4177  BLEBoard                com.bryghtlabs.chessup               I  board response message received BoardInfo(rawData=UByteArray(storage=[-78, 0, 9, 0, 5, 1, 0, 0, 13, -43, -68, 36, 1, 4, 0, 1]), boardInfo=BleBoardInfo(chessUpBoardSerialNumber=232111140, sameD45FirmwareVersion=9.0.5, nordicFirmwareVersion=1.0.0, bootloaderVersion=1.4.0, boardModelNumber=1)) ?: [-78, 0, 9, 0, 5, 1, 0, 0, 13, -43, -68, 36, 1, 4, 0, 1]
2024-04-10 08:25:20.447  4177-4177  BoardHeaders            com.bryghtlabs.chessup               D  fromValue: 49
2024-04-10 08:25:20.447  4177-4177  BLEBoard                com.bryghtlabs.chessup               I  board response message received BatteryStatus(charging=true) ?: [49, 1]
2024-04-10 08:25:21.903  4177-4727  Kable/Callback          com.bryghtlabs.chessup               D  EB:86:28:7F:C5:04 onCharacteristicChanged
                                                                                                    service: 6e400001-b5a3-f393-e0a9-e50e24dcca9e
                                                                                                    characteristic: 6e400003-b5a3-f393-e0a9-e50e24dcca9e
2024-04-10 08:25:21.905  4177-4727  Kable/Callback          com.bryghtlabs.chessup               D  EB:86:28:7F:C5:04 onCharacteristicChanged
                                                                                                    service: 6e400001-b5a3-f393-e0a9-e50e24dcca9e
                                                                                                    characteristic: 6e400003-b5a3-f393-e0a9-e50e24dcca9e
2024-04-10 08:25:21.906  4177-4177  BoardHeaders            com.bryghtlabs.chessup               D  fromValue: 100
2024-04-10 08:25:21.906  4177-4177  BLEBoard                com.bryghtlabs.chessup               I  board response message received null ?: [100]
2024-04-10 08:25:21.908  4177-4177  BoardHeaders            com.bryghtlabs.chessup               D  fromValue: 103
2024-04-10 08:25:21.920  4177-4177  BLEBoard                com.bryghtlabs.chessup               I  board response message received FenString(fenString=rnbqkbnr/pppppppp/8/8/8/8/PPPPPPPP/RNBQKBNR w KQkq - 0 0) ?: [103, 1, 2, 3, 4, 5, 3, 2, 1, 0, 0, 0, 0, 0, 0, 0, 0, 64, 64, 64, 64, 64, 64, 64, 64, 64, 64, 64, 64, 64, 64, 64, 64, 64, 64, 64, 64, 64, 64, 64, 64, 64, 64, 64, 64, 64, 64, 64, 64, 8, 8, 8, 8, 8, 8, 8, 8, 9, 10, 11, 12, 13, 11, 10, 9, 0, 1, 1, 1, 1, 64, 0, 0]
grabbe-bryghtlabs commented 6 months ago

This is after updating to 0.31.0

twyatt commented 6 months ago

I have a vague suspicion that maybe you have two separate Peripheral objects for the same connection?

Can you look through how you're creating the peripheral and if there is a way you possibly have multiple separate objects representing the same peripheral (rather than multiple references to the same peripheral object). I'm guessing that is why multiple I/O operations are occurring at once.

If you're having trouble isolating such a situation in your code, let me know, and I can add additional logging that will confirm/deny my suspicion.

grabbe-bryghtlabs commented 6 months ago

The way it is built out we have a single scan job and one instance of a peripheral. I don't think that would be the case. If there is a way that I can provide more logging, please let me know. I can run through the same scenario in an isolated environment this evening.

twyatt commented 6 months ago

I have some theories of what might be going wrong. I'll try to add some necessary logging to validate soon. Thanks for being patient.

grabbe-bryghtlabs commented 6 months ago

Just let me know what I can do. I appreciate your attentiveness

djweber commented 5 months ago

Just wanted to confirm that I've seen this happen to around 6 of our customers. There are several thousand using the latest build, so the volume is relatively low.

Fatal Exception: com.juul.kable.OutOfOrderGattCallbackException: Unexpected response type OnCharacteristicWrite received
       at com.juul.kable.BluetoothDeviceAndroidPeripheral.read(BluetoothDeviceAndroidPeripheral.kt:782)
       at com.juul.kable.BluetoothDeviceAndroidPeripheral$read$1.invokeSuspend(:15)
       at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:33)
       at kotlinx.coroutines.DispatchedTask.run(DispatchedTask.kt:104)
       at kotlinx.coroutines.internal.LimitedDispatcher$Worker.run(LimitedDispatcher.kt:111)
       at kotlinx.coroutines.scheduling.TaskImpl.run(Tasks.kt:99)
       at kotlinx.coroutines.scheduling.CoroutineScheduler.runSafely(CoroutineScheduler.kt:584)
       at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.executeTask(CoroutineScheduler.kt:811)
       at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.runWorker(CoroutineScheduler.kt:715)
       at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.run(CoroutineScheduler.kt:702)

Our current setup has peripherals cached in a map by their advertisement identifier (mac address), so there shouldn't be a case where we are using the same peripheral in two different spots. For what it's worth, our peripherals are generally connected to and disconnected from throughout the day. In either case, I can try to put some defense around our I/O operations. Would it be preferable to just reconnect the peripheral if this happens, or is this a recoverable scenario during a connection?

grabbe-bryghtlabs commented 5 months ago

Just wanted to confirm that I've seen this happen to around 6 of our customers. There are several thousand using the latest build, so the volume is relatively low.

Fatal Exception: com.juul.kable.OutOfOrderGattCallbackException: Unexpected response type OnCharacteristicWrite received
       at com.juul.kable.BluetoothDeviceAndroidPeripheral.read(BluetoothDeviceAndroidPeripheral.kt:782)
       at com.juul.kable.BluetoothDeviceAndroidPeripheral$read$1.invokeSuspend(:15)
       at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:33)
       at kotlinx.coroutines.DispatchedTask.run(DispatchedTask.kt:104)
       at kotlinx.coroutines.internal.LimitedDispatcher$Worker.run(LimitedDispatcher.kt:111)
       at kotlinx.coroutines.scheduling.TaskImpl.run(Tasks.kt:99)
       at kotlinx.coroutines.scheduling.CoroutineScheduler.runSafely(CoroutineScheduler.kt:584)
       at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.executeTask(CoroutineScheduler.kt:811)
       at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.runWorker(CoroutineScheduler.kt:715)
       at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.run(CoroutineScheduler.kt:702)

Our current setup has peripherals cached in a map by their advertisement identifier (mac address), so there shouldn't be a case where we are using the same peripheral in two different spots. For what it's worth, our peripherals are generally connected to and disconnected from throughout the day. In either case, I can try to put some defense around our I/O operations. Would it be preferable to just reconnect the peripheral if this happens, or is this a recoverable scenario during a connection?

Not sure about your scenario, but I've had this come up when updating firmware on a BLE device and it's unusable. We have another process to force our firmware to update, but it's a bit cumbersome and it would be nice to figure out why it's happening and if I can do anything to guard against it. We also have the peripheral in memory in a singleton. For general calls I have things wrapped in a retry with delay.

twyatt commented 1 month ago

I don't have a reliable way of reproducing this, but #749 should fix this (and it slated to be included in the upcoming 0.35.0 release).