Establish connection does not close operation on the specified timeout

[remonh87]

Summary

When I add a timeout to establishConnection the operation is not timed out within the specified time but will throw a BleDisconnectedException with error code 133 instead.

Library version

1.9.0

Preconditions

Have an existing bonding with a device and make sure you turn the bledevice off so it will not respond to the call.

Reproduced the issue on a Google Pixel (Android P) .

Steps to reproduce actual result

1. Make sure the device is switched off

2. Start the app and wait around 6 seconds to establish connection

Minimum code snippet reproducing the issue

    fun connectToDevice(deviceId: String): Observable<RxBleConnection> {
        Timber.d("RXBLE connecting with device $deviceId")
        return rxBleClient.getBleDevice(deviceId)
                .establishConnection(false, Timeout(6000, TimeUnit.MILLISECONDS))
                .doOnError {
                    Timber.d("RXBLE WHOOPS error connecting device: $deviceId error:( $it) ")
                }
                .doOnTerminate{
                    Timber.d("RXBLE terminator establish conn to device: $deviceId terminated ")
                }
    }

Logs from the application running with setting

2019-03-25 18:53:15.830 24619-24619/com.remonh87 D/MyBleClient: RXBLE connecting with device 12:34:55:66:77:88
2019-03-25 18:53:15.899 24619-24680/com.remonh87 D/RxBle#ClientOperationQueue: QUEUED   ConnectOperation(137016935)
2019-03-25 18:53:15.901 24619-24667/com.remonh87 D/RxBle#ClientOperationQueue: STARTED  ConnectOperation(137016935)
2019-03-25 18:53:15.902 24619-24667/com.remonh87 I/RxBle#ClientOperationQueue: RUNNING  ConnectOperation{MAC='12:34:55:66:77:88', autoConnect=false}
2019-03-25 18:53:15.918 24619-24682/com.remonh87 V/RxBle#BleConnectionCompat: Connecting without reflection
2019-03-25 18:53:37.154 24619-24637/com.remonh87 I/RxBle#GattCallback: MAC='12:34:55:66:77:88'  onConnectionStateChange(), status=133, value=0
2019-03-25 18:53:37.174 24619-24637/com.remonh87 D/RxBle#ConnectionOperationQueue: Connection operations queue to be terminated (MAC='12:34:55:66:77:88')
    com.polidea.rxandroidble2.exceptions.BleDisconnectedException: Disconnected from MAC='12:34:55:66:77:88' with status 133 (GATT_ERROR)
        at com.polidea.rxandroidble2.internal.connection.RxBleGattCallback$2.onConnectionStateChange(RxBleGattCallback.java:77)
        at android.bluetooth.BluetoothGatt$1$4.run(BluetoothGatt.java:262)
        at android.bluetooth.BluetoothGatt.runOrQueueCallback(BluetoothGatt.java:770)
        at android.bluetooth.BluetoothGatt.access$200(BluetoothGatt.java:39)
        at android.bluetooth.BluetoothGatt$1.onClientConnectionState(BluetoothGatt.java:257)
        at android.bluetooth.IBluetoothGattCallback$Stub.onTransact(IBluetoothGattCallback.java:71)
        at android.os.Binder.execTransact(Binder.java:731)
2019-03-25 18:53:37.180 24619-24679/com.remonh87 V/RxBle#Executors: Terminated (MAC='12:34:55:66:77:88')
2019-03-25 18:53:37.181 24619-24637/com.remonh87 D/MyBleClient$connectToDevice: RXBLE WHOOPS error connecting device: 12:34:55:66:77:88 error:( com.polidea.rxandroidble2.exceptions.BleDisconnectedException: Disconnected from MAC='12:34:55:66:77:88' with status 133 (GATT_ERROR)) 
2019-03-25 18:53:37.184 24619-24637/com.remonh87 D/MyBleClient$connectToDevice: RXBLE terminator establish conn to device: 12:34:55:66:77:88 terminated 

Actual result

Operation will be terminated after approx 22 seconds

Expected result

Establishconnection should fail on the desired timeout of 6 seconds

[dariuszseweryn]

Thank you for pointing this out.

Yup. It seems that the documentation is indeed misleading:

 * @param operationTimeout Timeout configuration after which the operation will be considered as broken. Eventually the operation
*                         will be canceled and removed from queue. Keep in mind that it will cancel the library's operation
*                         only and may leave Android's BLE stack in an inconsistent state.

It should be something like the below to match the current behaviour:

* @param operationTimeout Timeout configuration for operations scheduled using {@link RxBleConnection} emitted from this observable.
*                         Those operations will be considered broken after the specified timeout. Keep in mind that after the timeout
*                         those operations will canceled and may leave Android's BLE stack in an inconsistent state.

To have Establishconnection should fail on the desired timeout of 6 seconds one may simply use device.establishConnection(autoConnect).timeout(6, TimeUnit.SECONDS) — there is no need to bake it into the library API

What do you think?

[remonh87]

Thanks for the quick reply: yes II think that would match the current behavior better.

I also implemented the Rxjava timeout operator but I was hoping the timeout in RxBLE would somehow trigger resetting the android ble stack or the internal queue. At the moment I suffer from the fact that connecting to multiple devices hang when one device is switched off). I will dig further into this problem and create another ticket in case I see an issue in the library.

[dariuszseweryn]

I will keep this opened until the Javadoc fix will be in the master branch.

As for your issue — connecting may be cancelled by the user externally (e.g. by using .timeout() operator) and the next connect may then proceed. Just keep in mind that there is an Android OS bug that may show itself then

[werediver]

I believe the proper link to the "Android OS bug" is #483

Thank you for mentioning it, by the way.

[dariuszseweryn]

Fixed the link