search

dotintent / FlutterBleLib

Bluetooth Low Energy library for Flutter with support for simulating peripherals
Apache License 2.0
535 stars 197 forks source link

Trouble starting peripheral scan right after stopping it #503

Open tlongeri opened 4 years ago

tlongeri commented 4 years ago

Before I describe more specifically what my issue is, I'd like to illustrate what I'm trying to do with a simplified example (and it is quite simple, I think).

Suppose you have a "Scan" button that should scan for 10 seconds. If it is pressed again while the scan is ongoing, it should refresh the duration. If it is pressed after the scan has finished, it should start scanning for 10 seconds again.

I could call startPeripheralScan when the button is first pressed and then stopPeripheralScan after 10 seconds (or more, if it was refreshed). Suppose the user presses the button right when the time runs out, after stopPeripheralScan is called. I want to cleanly restart scanning by using startPeripheralScan.

Given that stopPeripheralScan returns a future, one would expect to need to wait for its completion before calling startPeripheralScan. I could use a callback to check a shouldRestart condition after the future completes. Unfortunately, this does not always work (due to race conditions, apparently, although I can't always explain it).

At first I actually tried doing using setting onDone when calling listen on the Stream returned by startPeripheralScan. I would have preferred to use this since it means stopPeripheralScan can be called from anywhere, and the button doesn't have to "own" scanning. I found a reason it doesn't work in the scanning_mixin.dart file (I expect there are other problems related to what I will describe further down). This is stopDeviceScan from that file:

Future<void> stopDeviceScan() async {
  await _methodChannel.invokeMethod(MethodName.stopDeviceScan);
  _scanEvents = null;
  return;
}

The problem is that the onDone callback is called before the await completes and _scanEvents is set to null. This causes the calls to startDeviceScan to subscribe to the previous stream, which either has already finished or is about to finish.

Next, I should mention I tried awaiting the future returned by StreamSubscription.cancel on the subscription returned by startPeripheralScan, only to realize it always returned a null future.

I also found something seemed wrong about startDeviceScan in scanning_mixin.dart:

StreamController<ScanResult> streamController = StreamController.broadcast(
    onListen: () => _methodChannel.invokeMethod(
    MethodName.startDeviceScan,
    <String, dynamic>{
        ArgumentName.scanMode: scanMode,
        ArgumentName.callbackType: callbackType,
        ArgumentName.uuids: uuids,
        ArgumentName.allowDuplicates: allowDuplicates,
    },
    ),
    onCancel: () => stopDeviceScan(),
);

I'm not sure if this is intended (I don't think so), but a call to stopDeviceScan will cause all streams to finish and call onCancel, leading to additional calls to stopDeviceScan. This means that when the future returned by stopPeripheralScan completes, there may still be additional calls to stopDeviceScan which have not completed yet (I'm not really sure of the implications but, at the very least, it could incorrectly set _scanEvents to null).

I tried commenting out the onCancel line and try awaiting the future returned by stopPeripheralScan. This made my calls to startPeripheralScan (when used in the callback) go from "usually unsuccessful" to "usually successful", but not to "always successful".

I know that I could probably use a timer to avoid what is likely some race conditions, but I'd be much happier with a cleaner solution.

Here are two cases from my console (Android - with default logging level, I think? I'm new to Flutter / mobile development) where startPeripheralScan wasn't successful. They are both similar in that I never saw Start Scan being logged (which I do see in successful attempts), and they just hanged:

/BluetoothAdapter(  763): STATE_ON
D/BluetoothLeScanner(  763): onClientRegistered() - status=0 clientIf=7 mClientIf=0
D/ScanRecord(  763): parseFromBytes
D/com.polidea.flutter_ble_lib.FlutterBleLibPlugin(  763): on native side observed method: observeConnectionState
D/ScanRecord(  763): parseFromBytes
D/ViewRootImpl@bf09744[MainActivity](  763): ViewPostImeInputStage processPointer 0
D/ViewRootImpl@bf09744[MainActivity](  763): ViewPostImeInputStage processPointer 1
D/com.polidea.flutter_ble_lib.FlutterBleLibPlugin(  763): on native side observed method: stopDeviceScan
D/BluetoothAdapter(  763): STATE_ON
D/BluetoothAdapter(  763): STATE_ON
D/BluetoothAdapter(  763): STATE_ON
D/BluetoothAdapter(  763): STATE_ON
D/BluetoothLeScanner(  763): Stop Scan
I/art     (  763): Do partial code cache collection, code=29KB, data=28KB
I/art     (  763): After code cache collection, code=29KB, data=28KB
I/art     (  763): Increasing code cache capacity to 128KB
D/com.polidea.flutter_ble_lib.FlutterBleLibPlugin(  763): on native side observed method: startDeviceScan
D/BluetoothLeScanner( 6071): Start Scan
D/BluetoothAdapter( 6071): STATE_ON
D/BluetoothAdapter( 6071): STATE_ON
D/BluetoothAdapter( 6071): STATE_ON
D/BluetoothAdapter( 6071): STATE_ON
D/BluetoothLeScanner( 6071): onClientRegistered() - status=0 clientIf=7 mClientIf=0
D/ScanRecord( 6071): parseFromBytes
D/com.polidea.flutter_ble_lib.FlutterBleLibPlugin( 6071): on native side observed method: observeConnectionState
D/ScanRecord( 6071): parseFromBytes
D/ViewRootImpl@bf09744[MainActivity]( 6071): ViewPostImeInputStage processPointer 0
D/ViewRootImpl@bf09744[MainActivity]( 6071): ViewPostImeInputStage processPointer 1
D/com.polidea.flutter_ble_lib.FlutterBleLibPlugin( 6071): on native side observed method: stopDeviceScan
D/BluetoothAdapter( 6071): STATE_ON
D/BluetoothAdapter( 6071): STATE_ON
D/com.polidea.flutter_ble_lib.FlutterBleLibPlugin( 6071): on native side observed method: startDeviceScan
D/BluetoothAdapter( 6071): STATE_ON
D/BluetoothAdapter( 6071): STATE_ON
D/BluetoothLeScanner( 6071): Stop Scan

I imagine there is some kind of race condition in the native FlutterBleLibPlugin.

mikolak commented 4 years ago

It's actually deeper IIRC. Our native backend is our library called Multiplatform Ble Adapter, the issue might be in its design or implementation.

Start/stop scan are operations changing the state of the radio and they have certain inertia which cannot be avoided. What might be wrong here is that an error is not coming through correctly, possibly it's emitted before subscription to the event channel.

Nulling of the _scanEvents shouldn't matter in the current implementation, since it was supposedly added to the stream controller already.

I think the easiest workaround would be to not stop the scan, but drop incoming results while user does not want to scan and stop the operation after they leave the screen.

Are those logs done after setting the library's log level to Verbose?

tlongeri commented 4 years ago

Nulling of the _scanEvents shouldn't matter in the current implementation, since it was supposedly added to the stream controller already.

I might be wrong, but my concern was that if _scanEvents is left null, a second call to startDeviceScan will trigger _prepareScanEventsStream and a second call to EventChannel.receiveBroadcastStream will cause the previous stream to be dropped/cancelled (if it didn't matter, why have _scanEvents at all?). I believe the normal behavior is to end up with two subscriptions receiving scan results.

Are those logs done after setting the library's log level to Verbose?

They were not. Here's how one unsuccessful case looked like with verbose (again, it hanged after this). It seems to have a couple more lines from "RxBle":

D/BluetoothLeScanner(18617): Start Scan
D/BluetoothAdapter(18617): STATE_ON
D/BluetoothAdapter(18617): STATE_ON
D/BluetoothAdapter(18617): STATE_ON
D/BluetoothAdapter(18617): STATE_ON
D/BluetoothLeScanner(18617): onClientRegistered() - status=0 clientIf=7 mClientIf=0
D/RxBle#ClientOperationQueue(18617): FINISHED ScanOperationApi21(193185401) in 133 ms
D/ViewRootImpl@f8d45f1[MainActivity](18617): ViewPostImeInputStage processPointer 0
D/ViewRootImpl@f8d45f1[MainActivity](18617): ViewPostImeInputStage processPointer 1
D/com.polidea.flutter_ble_lib.FlutterBleLibPlugin(18617): on native side observed method: stopDeviceScan
I/RxBle#CancellableSubscription(18617): Scan operation is requested to stop.
D/BluetoothAdapter(18617): STATE_ON
D/BluetoothAdapter(18617): STATE_ON
D/BluetoothAdapter(18617): STATE_ON
D/BluetoothAdapter(18617): STATE_ON
D/BluetoothLeScanner(18617): Stop Scan
D/com.polidea.flutter_ble_lib.FlutterBleLibPlugin(18617): on native side observed method: startDeviceScan

Also, for convenience, here's an example of a successful attempt:

D/BluetoothLeScanner(18617): Start Scan
D/BluetoothAdapter(18617): STATE_ON
D/BluetoothAdapter(18617): STATE_ON
D/BluetoothAdapter(18617): STATE_ON
D/BluetoothAdapter(18617): STATE_ON
D/BluetoothLeScanner(18617): onClientRegistered() - status=0 clientIf=8 mClientIf=0
D/RxBle#ClientOperationQueue(18617): FINISHED ScanOperationApi21(179742209) in 126 ms
D/ViewRootImpl@f8d45f1[MainActivity](18617): ViewPostImeInputStage processPointer 0
D/ViewRootImpl@f8d45f1[MainActivity](18617): ViewPostImeInputStage processPointer 1
D/com.polidea.flutter_ble_lib.FlutterBleLibPlugin(18617): on native side observed method: stopDeviceScan
I/RxBle#CancellableSubscription(18617): Scan operation is requested to stop.
D/BluetoothAdapter(18617): STATE_ON
D/com.polidea.flutter_ble_lib.FlutterBleLibPlugin(18617): on native side observed method: startDeviceScan
D/BluetoothAdapter(18617): STATE_ON
D/BluetoothAdapter(18617): STATE_ON
D/BluetoothAdapter(18617): STATE_ON
D/BluetoothLeScanner(18617): Stop Scan
D/RxBle#ClientOperationQueue(18617): QUEUED   ScanOperationApi21(119608377)
D/RxBle#ClientOperationQueue(18617): STARTED  ScanOperationApi21(119608377)
I/RxBle#QueueOperation(18617): Scan operation is requested to start.
D/BluetoothAdapter(18617): STATE_ON
D/BluetoothAdapter(18617): STATE_ON
D/BluetoothLeScanner(18617): Start Scan
D/BluetoothAdapter(18617): STATE_ON
D/BluetoothAdapter(18617): STATE_ON

All of this was done with scanning_mixin.dart's onCancel line commented out as mentioned in my original post, as that seemed to significantly improve my success rates.

tlongeri commented 4 years ago

I just realized there was some unfinished error handling code that was hiding the exception. That was dumb of me, I'm really sorry.

E/flutter (21583): [ERROR:flutter/lib/ui/ui_dart_state.cc(157)] Unhandled Exception: BleError (Error code: 600, ATT error code: null, iOS error code: null, Android error code: null, reason: Undocumented scan throttle (code 2147483646), suggested retry date is Wed Jul 29 16:26:26 GMT-04:00 2020, internal message: null, device ID: null, service UUID: null, characteristic UUID: null, descriptor UUID: null)

I hope I didn't worry you too much with my mistake. I can probably use this to simply retry on error. Still, if I don't comment out the onCancel line it doesn't work correctly, because apparently the not-yet-completed stopDeviceScan calls, aside from setting _scanEvents to null, will call the native-side stopDeviceScan after my call to startDeviceScan (sometimes). I'd say that still needs fixing (but it doesn't seem as bad a problem):

D/com.polidea.flutter_ble_lib.FlutterBleLibPlugin(31470): on native side observed method: stopDeviceScan
D/com.polidea.flutter_ble_lib.FlutterBleLibPlugin(31470): on native side observed method: startDeviceScan
D/RxBle#ClientOperationQueue(31470): QUEUED   ScanOperationApi21(202788908)
D/RxBle#ClientOperationQueue(31470): STARTED  ScanOperationApi21(202788908)
D/com.polidea.flutter_ble_lib.FlutterBleLibPlugin(31470): on native side observed method: stopDeviceScan
I/RxBle#QueueOperation(31470): Scan operation is requested to start.
D/BluetoothAdapter(31470): STATE_ON
D/BluetoothAdapter(31470): STATE_ON
D/BluetoothLeScanner(31470): Start Scan
D/BluetoothAdapter(31470): STATE_ON
D/BluetoothAdapter(31470): STATE_ON
D/BluetoothAdapter(31470): STATE_ON
D/BluetoothAdapter(31470): STATE_ON
D/BluetoothLeScanner(31470): onClientRegistered() - status=0 clientIf=8 mClientIf=0
D/RxBle#ClientOperationQueue(31470): FINISHED ScanOperationApi21(202788908) in 126 ms
I/RxBle#CancellableSubscription(31470): Scan operation is requested to stop.
D/BluetoothAdapter(31470): STATE_ON
D/BluetoothAdapter(31470): STATE_ON
D/BluetoothAdapter(31470): STATE_ON
D/BluetoothAdapter(31470): STATE_ON
D/BluetoothLeScanner(31470): Stop Scan