search

dariuszseweryn / RxAndroidBle

An Android Bluetooth Low Energy (BLE) Library with RxJava3 interface
http://polidea.github.io/RxAndroidBle/
Apache License 2.0
3.43k stars 583 forks source link

Rapid connect/disconnect sequence fails to properly disconnect from BLE device #483

Open binaryfields opened 6 years ago

binaryfields commented 6 years ago

Summary

Rapid connect/disconnect sequence fails to properly disconnect from BLE device.

When creating subscription to RxBleDevice.establishConnection() and cancelling it prior to connection being established, the physical BLE device remains in connected state (verified through JLink debugger output). This only happens when unsubscribe is called prior to fully establishing connection. If delay is inserted between subscribe/unsubscribe calls, then connect and disconnect sequence works properly.

Library version

implementation "com.polidea.rxandroidble:rxandroidble:1.6.0"

Preconditions

Steps to reproduce actual result

  1. Create subscription to rxbledevice.establishConnection()
  2. Wait 0.2s
  3. Call subscription.unsubscribe()
  4. On Android: app log shows connection and disconnect operations completing successfully.
  5. On BLE Device: JLink debugger output shows that device is still connected.

Minimum code snippet reproducing the issue

Logs from the application running with setting RxBleLog.setLogLevel(RxBleLog.VERBOSE)

09-18 12:48:54.670 17038-17173/com.livindi.resident I/RxBle#CancellableSubscription: Scan operation is requested to stop.
09-18 12:48:54.673 17038-17173/com.livindi.resident D/BluetoothAdapter: isLeEnabled(): ON

    --------- beginning of system
09-18 12:48:54.702 17038-17096/com.livindi.resident D/RxBle#ClientOperationQueue: QUEUED   ScanOperationApi21(185464561)
09-18 12:48:54.703 17038-17092/com.livindi.resident D/RxBle#ClientOperationQueue: STARTED  ScanOperationApi21(185464561)
09-18 12:48:54.704 17038-17173/com.livindi.resident I/RxBle#QueueOperation: Scan operation is requested to start.
09-18 12:48:54.706 17038-17173/com.livindi.resident D/BluetoothAdapter: isLeEnabled(): ON
09-18 12:48:54.709 17038-17051/com.livindi.resident D/BluetoothLeScanner: onScannerRegistered() - status=0 scannerId=7 mScannerId=0
09-18 12:48:54.715 17038-17092/com.livindi.resident D/RxBle#ClientOperationQueue: FINISHED ScanOperationApi21(185464561) in 12 ms
09-18 12:48:54.733 17038-17173/com.livindi.resident I/RxBle#CancellableSubscription: Scan operation is requested to stop.
09-18 12:48:54.734 17038-17173/com.livindi.resident D/BluetoothAdapter: isLeEnabled(): ON
09-18 12:48:54.885 17038-17197/com.livindi.resident D/RxBle#ClientOperationQueue: QUEUED   ConnectOperation(237633332)
09-18 12:48:54.885 17038-17092/com.livindi.resident D/RxBle#ClientOperationQueue: STARTED  ConnectOperation(237633332)
09-18 12:48:54.888 17038-17173/com.livindi.resident V/RxBle#BleConnectionCompat: Connecting without reflection
09-18 12:48:54.889 17038-17173/com.livindi.resident D/BluetoothGatt: connect() - device: DC:C5:05:C6:9E:0E, auto: false
    registerApp()
    registerApp() - UUID=bf9c3cc7-0ee0-4e7d-8221-6ec65bab636e
09-18 12:48:54.891 17038-17051/com.livindi.resident D/BluetoothGatt: onClientRegistered() - status=0 clientIf=7
09-18 12:48:55.555 17038-17095/com.livindi.resident D/RxBle#ClientOperationQueue: QUEUED   ScanOperationApi21(167195673)
09-18 12:48:55.911 17038-17197/com.livindi.resident D/RxBle#ClientOperationQueue: QUEUED   DisconnectOperation(217206097)
09-18 12:48:55.912 17038-17197/com.livindi.resident I/RxBle#ConnectionOperationQueue: Connection operations queue to be terminated (DC:C5:05:C6:9E:0E)
09-18 12:48:55.913 17038-17196/com.livindi.resident D/RxBle#Executors$RunnableAdapter: Terminated.
09-18 12:48:55.915 17038-17092/com.livindi.resident D/RxBle#ClientOperationQueue: FINISHED ConnectOperation(237633332) in 1029 ms
09-18 12:48:55.916 17038-17092/com.livindi.resident D/RxBle#ClientOperationQueue: STARTED  ScanOperationApi21(167195673)
09-18 12:48:55.918 17038-17173/com.livindi.resident I/RxBle#QueueOperation: Scan operation is requested to start.
09-18 12:48:55.920 17038-17173/com.livindi.resident D/BluetoothAdapter: isLeEnabled(): ON
09-18 12:48:55.925 17038-17051/com.livindi.resident D/BluetoothLeScanner: onScannerRegistered() - status=0 scannerId=8 mScannerId=0
09-18 12:48:55.930 17038-17092/com.livindi.resident D/RxBle#ClientOperationQueue: FINISHED ScanOperationApi21(167195673) in 14 ms
09-18 12:48:55.932 17038-17092/com.livindi.resident D/RxBle#ClientOperationQueue: STARTED  DisconnectOperation(217206097)
09-18 12:48:55.933 17038-17173/com.livindi.resident D/BluetoothManager: getConnectionState()
    getConnectedDevices
09-18 12:48:55.939 17038-17173/com.livindi.resident D/BluetoothGatt: close()
    unregisterApp() - mClientIf=7
09-18 12:48:55.941 17038-17092/com.livindi.resident D/RxBle#ClientOperationQueue: FINISHED DisconnectOperation(217206097) in 10 ms

Actual result

BLE Device indicates it is still in connected state and never receives DISCONNECTED event. INFO [main] on_ble_evt: CONNECTED

Expected result

BLE Device receives DISCONNECTED event INFO [ble] on_ble_evt: DISCONNECTED. Reason: 0x13

[Edit @dariuszseweryn] Notes:

Related bug on Google's Issue Tracker: https://issuetracker.google.com/issues/37121223

dariuszseweryn commented 6 years ago

Hello,

This seems to be an Android BLE stack issue — could you share phone model / OS version?

Best Regards

binaryfields commented 6 years ago

Phone Model: Google Nexus 6P OS Version: Android 8.1.0 (Patch level: September 5, 2018)

I'll have code snippet to repro the issue in a few minutes too.

binaryfields commented 6 years ago

Here is the code sample that reproduces the issue. You may have to vary the timeout based on how long it takes to establish connection with your BLE device.

  private void connect() {
    Subscription sub = rxBleClient.getBleDevice(device.hwId)
      .establishConnection(false)
      .subscribeOn(Schedulers.io())
      .observeOn(Schedulers.io())
      .subscribe(
        conn -> Timber.tag("BleTest").v("BLE connected"),
        throwable -> Timber.tag("BleTest").e(throwable, "BLE connection failed")
      );
    Observable.timer(250, TimeUnit.MILLISECONDS)
      .subscribeOn(Schedulers.io())
      .observeOn(Schedulers.io())
      .subscribe(value -> {
        Timber.tag("BleTest").v("BLE cancelling connection");
        sub.unsubscribe();
      });
  }
binaryfields commented 6 years ago

If timeout is > then amount of time needed to establish connection, everything works properly. Here is the corresponding log output:

Cancel Subscription after 3000ms

App Log

09-18 13:26:49.546 20164-20291/com.livindi.resident I/RxBle#CancellableSubscription: Scan operation is requested to stop.
09-18 13:26:49.614 20164-20213/com.livindi.resident D/RxBle#ClientOperationQueue: QUEUED   ScanOperationApi21(165476656)
09-18 13:26:49.616 20164-20211/com.livindi.resident D/RxBle#ClientOperationQueue: STARTED  ScanOperationApi21(165476656)
09-18 13:26:49.619 20164-20291/com.livindi.resident I/RxBle#QueueOperation: Scan operation is requested to start.
09-18 13:26:49.629 20164-20211/com.livindi.resident D/RxBle#ClientOperationQueue: FINISHED ScanOperationApi21(165476656) in 13 ms
09-18 13:26:49.644 20164-20291/com.livindi.resident I/RxBle#CancellableSubscription: Scan operation is requested to stop.
09-18 13:26:49.917 20164-20324/com.livindi.resident D/RxBle#ClientOperationQueue: QUEUED   ConnectOperation(61110714)
09-18 13:26:49.918 20164-20211/com.livindi.resident D/RxBle#ClientOperationQueue: STARTED  ConnectOperation(61110714)
09-18 13:26:49.925 20164-20291/com.livindi.resident V/RxBle#BleConnectionCompat: Connecting without reflection
09-18 13:26:50.381 20164-20287/com.livindi.resident D/RxBle#BluetoothGatt$1: onConnectionStateChange newState=2 status=0
09-18 13:26:50.392 20164-20211/com.livindi.resident D/RxBle#ClientOperationQueue: FINISHED ConnectOperation(61110714) in 472 ms
09-18 13:26:50.411 20164-20289/com.livindi.resident V/BleTest: BLE connected
09-18 13:26:52.892 20164-20321/com.livindi.resident V/BleTest: BLE cancelling connection
09-18 13:26:52.901 20164-20324/com.livindi.resident I/RxBle#ConnectionOperationQueue: Connection operations queue to be terminated (DC:C5:05:C6:9E:0E)
09-18 13:26:52.903 20164-20323/com.livindi.resident D/RxBle#Executors$RunnableAdapter: Terminated.
09-18 13:26:52.905 20164-20324/com.livindi.resident D/RxBle#ClientOperationQueue: QUEUED   DisconnectOperation(247951482)
09-18 13:26:52.909 20164-20211/com.livindi.resident D/RxBle#ClientOperationQueue: STARTED  DisconnectOperation(247951482)
09-18 13:26:52.932 20164-20287/com.livindi.resident D/RxBle#BluetoothGatt$1: onConnectionStateChange newState=0 status=0
09-18 13:26:52.952 20164-20211/com.livindi.resident D/RxBle#ClientOperationQueue: FINISHED DisconnectOperation(247951482) in 42 ms

BLE Device Log

INFO [env] Starting
INFO [ble] on_ble_evt: CONNECTED
INFO [main] on_ble_evt: CONNECTED 
INFO [ui] Setting led mode to 1 
INFO [ui] Mode: OFF 
INFO [ble] on_ble_evt: evt_id 0x21
INFO [ble] on_ble_evt: DATA_LENGTH_UPDATE_REQUEST
INFO [ble] on_ble_evt: evt_id 0x22
INFO [ble] on_ble_evt: DATA_LENGTH_UPDATE
INFO [ble] on_ble_evt: SEC_INFO_REQUEST
INFO [ble] on_ble_evt: CONN_SEC_UPDATE
INFO [ble] on_pm_evt: CONN_SEC_SUCCEEDED
INFO [ble] on_pm_evt: Connection secured: role: 1, conn_handle: 0x0, procedure: 0. 
INFO [ble] on_ble_evt: CONN_PARAM_UPDATE
INFO [ble] on_conn_params_evt: SUCCEEDED
INFO [ble] on_ble_evt: DISCONNECTED
INFO [env] Stopping
INFO [motion2] Stopping
INFO [motion2] Stopping motion sensor ...
INFO [ble] on_ble_evt: DISCONNECTED. Reason: 0x13 
INFO [main] on_ble_evt: DISCONNECTED 
INFO [ble] Init adv, sec_mode 1
INFO [ble] Whitelist set with 1 peers
INFO [ui] Setting led mode to 3 
INFO [ui] Mode: OFF 
INFO [ble] Starting adv
INFO [ble] on_adv_evt: WHITELIST_REQUEST
INFO [ble] on_adv_evt: FAST_WHITELIST
binaryfields commented 6 years ago

If timeout is < connection establishment time, then disconnect event is never received by BLE device

Cancel Subscription after 250ms

App Log

09-18 13:28:15.620 20508-20637/com.livindi.resident I/RxBle#CancellableSubscription: Scan operation is requested to stop.
09-18 13:28:15.668 20508-20559/com.livindi.resident D/RxBle#ClientOperationQueue: QUEUED   ScanOperationApi21(80771164)
09-18 13:28:15.669 20508-20555/com.livindi.resident D/RxBle#ClientOperationQueue: STARTED  ScanOperationApi21(80771164)
09-18 13:28:15.670 20508-20637/com.livindi.resident I/RxBle#QueueOperation: Scan operation is requested to start.
09-18 13:28:15.684 20508-20555/com.livindi.resident D/RxBle#ClientOperationQueue: FINISHED ScanOperationApi21(80771164) in 14 ms
09-18 13:28:15.698 20508-20637/com.livindi.resident I/RxBle#CancellableSubscription: Scan operation is requested to stop.
09-18 13:28:15.948 20508-20664/com.livindi.resident D/RxBle#ClientOperationQueue: QUEUED   ConnectOperation(168945735)
09-18 13:28:15.948 20508-20555/com.livindi.resident D/RxBle#ClientOperationQueue: STARTED  ConnectOperation(168945735)
09-18 13:28:15.954 20508-20637/com.livindi.resident V/RxBle#BleConnectionCompat: Connecting without reflection
09-18 13:28:16.171 20508-20661/com.livindi.resident V/BleTest: BLE cancelling connection
09-18 13:28:16.175 20508-20664/com.livindi.resident D/RxBle#ClientOperationQueue: QUEUED   DisconnectOperation(53408412)
09-18 13:28:16.178 20508-20664/com.livindi.resident I/RxBle#ConnectionOperationQueue: Connection operations queue to be terminated (DC:C5:05:C6:9E:0E)
09-18 13:28:16.178 20508-20663/com.livindi.resident D/RxBle#Executors$RunnableAdapter: Terminated.
09-18 13:28:16.181 20508-20555/com.livindi.resident D/RxBle#ClientOperationQueue: FINISHED ConnectOperation(168945735) in 232 ms
    STARTED  DisconnectOperation(53408412)
09-18 13:28:16.192 20508-20555/com.livindi.resident D/RxBle#ClientOperationQueue: FINISHED DisconnectOperation(53408412) in 11 ms

BLE Device Log

INFO [env] Starting
INFO [ble] on_ble_evt: CONNECTED
INFO [main] on_ble_evt: CONNECTED 
INFO [ui] Setting led mode to 1 
INFO [ui] Mode: OFF 
INFO [ble] on_ble_evt: evt_id 0x21
INFO [ble] on_ble_evt: DATA_LENGTH_UPDATE_REQUEST
INFO [ble] on_ble_evt: evt_id 0x22
INFO [ble] on_ble_evt: DATA_LENGTH_UPDATE
INFO [ble] on_ble_evt: CONN_PARAM_UPDATE
INFO [ble] on_conn_params_evt: SUCCEEDED
binaryfields commented 6 years ago

The same behavior can also be reproduced with RxJava2 and latest RxAndroidBle 1.7.0.

Here is isolated and standalone repro code:

package com.example.bletest;

import android.annotation.SuppressLint;
import android.os.Bundle;
import android.support.design.widget.FloatingActionButton;
import android.support.design.widget.Snackbar;
import android.support.v7.app.AppCompatActivity;
import android.support.v7.widget.Toolbar;
import android.util.Log;
import android.view.View;
import android.view.Menu;
import android.view.MenuItem;

import com.polidea.rxandroidble2.RxBleClient;
import com.polidea.rxandroidble2.internal.RxBleLog;

import java.util.concurrent.TimeUnit;

import io.reactivex.Observable;
import io.reactivex.disposables.Disposable;
import io.reactivex.schedulers.Schedulers;

public class MainActivity extends AppCompatActivity {

  private static final String TAG = "BleTest";

  private RxBleClient rxBleClient;

  @Override
  protected void onCreate(Bundle savedInstanceState) {
    super.onCreate(savedInstanceState);
    setContentView(R.layout.activity_main);
    Toolbar toolbar = (Toolbar) findViewById(R.id.toolbar);
    setSupportActionBar(toolbar);
    rxBleClient = RxBleClient.create(this);
    RxBleClient.setLogLevel(RxBleLog.VERBOSE);

    FloatingActionButton fab = (FloatingActionButton) findViewById(R.id.fab);
    fab.setOnClickListener(new View.OnClickListener() {
      @Override
      public void onClick(View view) {
        connect();
        Snackbar.make(view, "Replace with your own action", Snackbar.LENGTH_LONG)
          .setAction("Action", null).show();
      }
    });
  }

  @Override
  public boolean onCreateOptionsMenu(Menu menu) {
    // Inflate the menu; this adds items to the action bar if it is present.
    getMenuInflater().inflate(R.menu.menu_main, menu);
    return true;
  }

  @Override
  public boolean onOptionsItemSelected(MenuItem item) {
    // Handle action bar item clicks here. The action bar will
    // automatically handle clicks on the Home/Up button, so long
    // as you specify a parent activity in AndroidManifest.xml.
    int id = item.getItemId();

    //noinspection SimplifiableIfStatement
    if (id == R.id.action_settings) {
      return true;
    }

    return super.onOptionsItemSelected(item);
  }

  @SuppressLint("CheckResult")
  private void connect() {
    Disposable sub = rxBleClient.getBleDevice("DC:C5:05:C6:9E:0E")
      .establishConnection(false)
      .subscribeOn(Schedulers.io())
      .observeOn(Schedulers.io())
      .subscribe(
        conn -> Log.v(TAG, "BLE connected"),
        throwable -> Log.e(TAG, "BLE connection failed", throwable),
        () -> Log.v(TAG, "BLE completed")
      );
    Observable.timer(250, TimeUnit.MILLISECONDS)
      .subscribeOn(Schedulers.io())
      .observeOn(Schedulers.io())
      .subscribe(value -> {
        Log.v(TAG, "BLE cancelling connection");
        sub.dispose();
      });
  }
}
binaryfields commented 6 years ago

Here is application log corresponding to the most recent sample code:

09-18 14:51:44.146 31075-31075/? I/zygote64: Late-enabling -Xcheck:jni
09-18 14:51:44.190 31075-31082/? I/zygote64: Debugger is no longer active
09-18 14:51:44.481 31075-31075/? I/InstantRun: starting instant run server: is main process
09-18 14:51:44.806 31075-31101/? D/OpenGLRenderer: HWUI GL Pipeline
09-18 14:51:44.873 31075-31101/? I/Adreno: QUALCOMM build                   : 8e59954, I0be83d0d26
    Build Date                       : 09/22/17
    OpenGL ES Shader Compiler Version: EV031.21.02.00
    Local Branch                     : O17A
    Remote Branch                    : 
    Remote Branch                    : 
    Reconstruct Branch               : 
09-18 14:51:44.876 31075-31101/? D/vndksupport: Loading /vendor/lib64/hw/gralloc.msm8994.so from current namespace instead of sphal namespace.
09-18 14:51:44.885 31075-31101/? I/Adreno: PFP: 0x00000000, ME: 0x00000000
09-18 14:51:44.891 31075-31101/? I/zygote64: android::hardware::configstore::V1_0::ISurfaceFlingerConfigs::hasWideColorDisplay retrieved: 0
09-18 14:51:44.893 31075-31101/? I/OpenGLRenderer: Initialized EGL, version 1.4
09-18 14:51:44.893 31075-31101/? D/OpenGLRenderer: Swap behavior 2
09-18 14:51:44.949 31075-31101/? D/vndksupport: Loading /vendor/lib64/hw/android.hardware.graphics.mapper@2.0-impl.so from current namespace instead of sphal namespace.
09-18 14:51:44.951 31075-31101/? D/vndksupport: Loading /vendor/lib64/hw/gralloc.msm8994.so from current namespace instead of sphal namespace.
09-18 14:51:57.389 31075-31119/com.example.bletest D/RxBle#ClientOperationQueue: QUEUED   ConnectOperation(219252011)
09-18 14:51:57.391 31075-31100/com.example.bletest D/RxBle#ClientOperationQueue: STARTED  ConnectOperation(219252011)
09-18 14:51:57.412 31075-31121/com.example.bletest V/RxBle#BleConnectionCompat: Connecting without reflection
09-18 14:51:57.413 31075-31121/com.example.bletest D/BluetoothGatt: connect() - device: DC:C5:05:C6:9E:0E, auto: false
    registerApp()
    registerApp() - UUID=fb50d77f-10ea-4a1a-acdb-18f191cd0e90
09-18 14:51:57.415 31075-31087/com.example.bletest D/BluetoothGatt: onClientRegistered() - status=0 clientIf=7
09-18 14:51:57.600 31075-31123/com.example.bletest V/BleTest: BLE cancelling connection
09-18 14:51:57.602 31075-31100/com.example.bletest D/RxBle#ClientOperationQueue: FINISHED ConnectOperation(219252011) in 211 ms
09-18 14:51:57.603 31075-31119/com.example.bletest I/RxBle#ConnectionOperationQueue: Connection operations queue to be terminated (DC:C5:05:C6:9E:0E)
09-18 14:51:57.604 31075-31118/com.example.bletest D/RxBle#Executors$RunnableAdapter: Terminated.
09-18 14:51:57.604 31075-31119/com.example.bletest D/RxBle#ClientOperationQueue: QUEUED   DisconnectOperation(152628690)
09-18 14:51:57.606 31075-31100/com.example.bletest D/RxBle#ClientOperationQueue: STARTED  DisconnectOperation(152628690)
09-18 14:51:57.607 31075-31121/com.example.bletest D/BluetoothManager: getConnectionState()
    getConnectedDevices
09-18 14:51:57.609 31075-31121/com.example.bletest D/BluetoothGatt: close()
    unregisterApp() - mClientIf=7
09-18 14:51:57.611 31075-31100/com.example.bletest D/RxBle#ClientOperationQueue: FINISHED DisconnectOperation(152628690) in 5 ms
09-18 14:54:05.746 31075-31080/com.example.bletest I/zygote64: Do partial code cache collection, code=30KB, data=27KB
09-18 14:54:05.747 31075-31080/com.example.bletest I/zygote64: After code cache collection, code=30KB, data=27KB
    Increasing code cache capacity to 128KB
binaryfields commented 6 years ago

This seems to be an Android BLE stack issue — could you share phone model / OS

@dariuszseweryn I tested this issue on another Android device and was able to reproduce this behavior so the problem does not look to be specific to Phone/Android OS combination. Here is hardware I tested on:

Hardware: Asus Tablet Model P00C OS: Android 7.0

dariuszseweryn commented 6 years ago

This may not be related to a specific phone/OS mix but a general Android BLE stack issue. I can recall a similar issue with autoConnect=true where a well timed disconnect/close creates a race condition which makes the OS keep the connection indefinitely without any signs on the surface.

I think I have found a bug report for this exact case. In this situation calling BluetoothGatt.disconnect() before BluetoothGatt.close() could potentially workaround this issue.

binaryfields commented 6 years ago

Google's bug report does indeed fit the pattern so at least on my side I will put in a workaround to mitigate this issue. It doesn't seem like Google is eager to fix the issue though based on when the issue was filed. Sigh...

Thanks for the clarification and help.

dariuszseweryn commented 6 years ago

Feel free to share how did you implemented the workaround and if it helped

binaryfields commented 6 years ago

The workaround used is less than ideal but it works for my use case.

Before cancelling subscription (forcing disconnect), I added an optional delay of 1-2 seconds if the connection is still being established.

Something along the lines of:

Observable.just(connectionSubscription)
        .delay(1000, TimeUnit.MILLISECONDS)
        .subscribe(sub -> sub.unsubscribe());
dariuszseweryn commented 6 years ago

I am afraid that if the device will get connected after the connectionSubscription will get unsubscribed the problem will surface anyway.

A valid workarounds without changing the library internals would be:

  1. Use autoConnect=true — in this situation the mentioned bug does not surface. The other bug may happen though... Additionally the connection time may be longer than while using autoConnect=false
  2. When using autoConnect=false — do not unsubscribe from RxBleDevice.establishConnection() until it will throw (~30 second tops)
AnDrOiD73dd commented 5 years ago

I have the same issue on: implementation 'com.polidea.rxandroidble2:rxandroidble:1.7.1' autoconnect=false Google Nexus 5 - Android 6.0.1, Build M4B30Z Samsung J5 (2016) - Android 7.1.1, Build NMF26x.J510FNXXS2BRA1 Xiaomi Mi5 - Android 8.0.0, Build OPR1.170623.032 Xiaomi MiA2 - Android 8.1.0, Build OPM1.171019.011.V9.6.15.0.ODIMIFE OnePlus 6 - Android 9.0, Build ONEPLUS A6003_22_181026

aptly-io commented 5 years ago

@digitalstreamio @DariuszAniszewski @AnDrOiD73dd This makes me think about my case #530 . Maybe try adding a step waiting for the connection state to become DISCONNECTED, only then allow to reopen? It is more deterministic, then next you can still at a delay(1000) ... what I also might do ...

AnDrOiD73dd commented 5 years ago

@aptly-io, another case is described here. There is no question of reconnection. But you are right that a delay is required when reconnecting, otherwise we will get a connection error.

weliem commented 5 years ago

What I see in the code of RxAndroidBle is that only close() is called. That unregisters your callback so you will never receive the disconnected event! This is not an Android bug.

If you want to stop a connection attempt or disconnect while connected you must first call disconnect(). Then wait for the disconnected state to come in and then call close().

dariuszseweryn commented 5 years ago

@weliem I have performed tests with also .disconnect() being called before .close() even if the device is not connected at the time of disposal — it yielded the same effect.

weliem commented 5 years ago

@dariuszseweryn , I'll do some tests as well. But assuming you are right, I suspect the issue is related to the asynchronous nature of connectGatt, disconnect and close...if you call them too quickly they will be in the middle of executing and the next call may not work as expected. Android is not queueing them up....so anything might happen!

Still wondering though why you'd want to cancel a connection after 0.2 seconds of issuing it....? @digitalstreamio , any comments?

weliem commented 5 years ago

Ok, I just did a small test:

2019-04-01 17:07:34.571 24229-24229/com.welie.blessedexample I/BluetoothPeripheral: connect to 'Systo MC 300' (CF:A9:BA:D9:62:9E) using TRANSPORT_LE
2019-04-01 17:07:34.572 24229-24229/com.welie.blessedexample D/BluetoothGatt: connect() - device: CF:A9:BA:D9:62:9E, auto: false
2019-04-01 17:07:34.572 24229-24229/com.welie.blessedexample D/BluetoothGatt: registerApp()
2019-04-01 17:07:34.573 24229-24229/com.welie.blessedexample D/BluetoothGatt: registerApp() - UUID=376d590d-886b-4574-9f1c-b80e23085292
2019-04-01 17:07:34.577 24229-24229/com.welie.blessedexample I/BluetoothHandler: Cancelling connection
2019-04-01 17:07:34.577 24229-24244/com.welie.blessedexample D/BluetoothGatt: onClientRegistered() - status=0 clientIf=8
2019-04-01 17:07:34.662 24229-24229/com.welie.blessedexample I/BluetoothPeripheral: force disconnect 'Systo MC 300' (CF:A9:BA:D9:62:9E)
2019-04-01 17:07:34.662 24229-24229/com.welie.blessedexample D/BluetoothGatt: cancelOpen() - device: CF:A9:BA:D9:62:9E
2019-04-01 17:07:34.664 24229-24229/com.welie.blessedexample D/BluetoothGatt: close()
2019-04-01 17:07:34.665 24229-24229/com.welie.blessedexample D/BluetoothGatt: unregisterApp() - mClientIf=8
2019-04-01 17:07:34.674 24229-24229/com.welie.blessedexample I/BluetoothHandler: disconnected 'Systo MC 300' with status 0

I managed to get down to 100 ms for issuing a disconnect. So essentially, connectGatt takes around 100 ms to complete on my phone (Nokia 8 Sirocco with Android 9 which is quite fast). After that you can issue a disconnect but if you do it earlier it indeed doesn't work. So when I tried 80ms I did not see 'cancelOpen' in the log and the phone indeed still connected to the device....

weliem commented 5 years ago

Here is another test on a Samsung S5 running Android 6

04-01 17:48:42.736 13112-13112/com.welie.blessedexample I/BluetoothPeripheral: connect to 'Systo MC 300' (CF:A9:BA:D9:62:9E) using TRANSPORT_LE
04-01 17:48:42.736 13112-13112/com.welie.blessedexample D/BluetoothGatt: connect() - device: CF:A9:BA:D9:62:9E, auto: false
04-01 17:48:42.736 13112-13112/com.welie.blessedexample D/BluetoothGatt: registerApp()
04-01 17:48:42.736 13112-13112/com.welie.blessedexample D/BluetoothGatt: registerApp() - UUID=e4294b88-5070-4f72-9717-5e2266347061
04-01 17:48:42.786 13112-13112/com.welie.blessedexample I/BluetoothHandler: Cancelling connection
04-01 17:48:42.786 13112-13112/com.welie.blessedexample I/BluetoothPeripheral: force disconnect 'Systo MC 300' (CF:A9:BA:D9:62:9E)
04-01 17:48:42.786 13112-13112/com.welie.blessedexample D/BluetoothGatt: cancelOpen() - device: CF:A9:BA:D9:62:9E
04-01 17:48:42.786 13112-13320/com.welie.blessedexample D/BluetoothGatt: onClientRegistered() - status=0 clientIf=7
04-01 17:48:42.786 13112-13112/com.welie.blessedexample I/Timeline: Timeline: Activity_idle id: android.os.BinderProxy@c7ae308 time:1152557
04-01 17:48:42.836 13112-13112/com.welie.blessedexample D/BluetoothGatt: close()
04-01 17:48:42.836 13112-13112/com.welie.blessedexample D/BluetoothGatt: unregisterApp() - mClientIf=7
04-01 17:48:42.836 13112-13112/com.welie.blessedexample I/BluetoothHandler: disconnected 'Systo MC 300' with status 0

As you can see, there is no major difference in timing. So the bottomline is that connectGatt simply needs to complete before you can cancel the connection by calling disconnect. Seems to be around 80-100 ms.

dariuszseweryn commented 5 years ago

Thing is that the fast issued disconnect it is probably easiest to way to reproduce this bug. There is probably a race condition where a connection process with a well timed disconect/close will leave the Java part of the API oblivious to a fact that the BT controller is connected to the peripheral with no way to connect/disconnect.

SpicyCactuar commented 5 years ago

@digitalstreamio @dariuszseweryn I faced the issue of the connection not being disposed with a Nexus 6P as well. The only thing different from @digitalstreamio 's case is that I retrieved the device from a scan instead of using its MAC address.

In my case, I'm also forcing the bonding before connecting. Don't know enough about Bluetooth to determine if this is relevant but the information may help shed some light. The nasty workaround I found to work is to call BluetoothDevice#removeBond through reflection as described in this SO post. I know, it sucks but I can't keep the connection alive. 🙈

ntimesc commented 3 years ago

I am afraid that if the device will get connected after the connectionSubscription will get unsubscribed the problem will surface anyway.

A valid workarounds without changing the library internals would be:

  1. Use autoConnect=true — in this situation the mentioned bug does not surface. The other bug may happen though... Additionally the connection time may be longer than while using autoConnect=false
  2. When using autoConnect=false — do not unsubscribe from RxBleDevice.establishConnection() until it will throw (~30 second tops)

I am facing this issue due to race condition. I dispose connection before calling establish connection function. But sometimes app crashed so how would I add a delay before establishing connection to dispose connection.

I am using establishedConnection (false)