Skip to content
New issue

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

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

Already on GitHub? Sign in to your account

Fix intermittent scans #489

Merged
merged 2 commits into from
Apr 10, 2017
Merged

Fix intermittent scans #489

merged 2 commits into from
Apr 10, 2017

Conversation

cupakromer
Copy link
Contributor

Using the prior scan end time to calculate when we can stop the current scan cycle causes an immediate scan stop under two conditions:

  • this is the first scan cycle
  • scanning has been stopped for longer than 6 seconds (a more generalized case of the first scan cycle)

The simple solution is to always check the scan start time. It will always be true, since only one scan can happen at a time, that the previous stop value is less than the start value. Thus the start value plus the minimum Android N scan time will always be greater than the last stop time equivalent. This guarantees that with normal continuous scan cycling there will be no more than five scans.

All of the other time trackers in `CycledLeScanner` use the elapsed
time. I think it was simply an oversight when the change was made to
guard against the Android N (Android 7, API 24+) behavior of limiting
scan starts to only five every thirty seconds.

However, using the system time causes an issue where the scan will never
stop. This happens when the time is changed to the past or was set to
the future then return to normal or past time. Once `mLastScanStopTime`
is set if the system time ever goes backwards the calculation `now -
mLastScanStopTime` will always be negative. Thus it will always be less
than the `ANDROID_N_MIN_SCAN_CYCLE_MILLIS` prevent a natural stop.
@davidgyoung
Copy link
Member

Yes, not using SystemClock.elapsedRealtime() was an oversight.

I think the change to use the start scan time is correct, I'll do some tests on my Android 7.x device to verify this has the desired effect for me as well.

@davidgyoung
Copy link
Member

Doing some tests with this today on a Nexus 9 with Android 7.0, I agree there is a problem.

Logs before this change. Note an extra scan stop and restart at 12:15:19.451/12:15:19.459, which pushes the number of scans in 30 seconds over the Android N maximum resulting in a blocked scan at 12:15:26.167.

adb logcat | grep -E 'bluetooth le scan|Android N|beaconService version|scanning too frequently'

04-08 12:15:18.055  9926  9926 I BeaconService: beaconService version 2.9.2-19-gb7c5229-SNAPSHOT is starting up
04-08 12:15:18.345  9926  9926 D CycledLeScanner: starting a new bluetooth le scan
04-08 12:15:19.451  9926  9926 D CycledLeScanner: stopping bluetooth le scan
04-08 12:15:19.459  9926  9926 D CycledLeScanner: starting a new bluetooth le scan
04-08 12:15:20.567  9926  9926 D CycledLeScanner: Not stopping scan because this is Android N and we keep scanning for a minimum of 6 seconds at a time. We will stop in 4884 millisconds.
04-08 12:15:21.674  9926  9926 D CycledLeScanner: Not stopping scan because this is Android N and we keep scanning for a minimum of 6 seconds at a time. We will stop in 3777 millisconds.
04-08 12:15:22.776  9926  9926 D CycledLeScanner: Not stopping scan because this is Android N and we keep scanning for a minimum of 6 seconds at a time. We will stop in 2675 millisconds.
04-08 12:15:23.940  9926  9926 D CycledLeScanner: Not stopping scan because this is Android N and we keep scanning for a minimum of 6 seconds at a time. We will stop in 1511 millisconds.
04-08 12:15:25.041  9926  9926 D CycledLeScanner: Not stopping scan because this is Android N and we keep scanning for a minimum of 6 seconds at a time. We will stop in 410 millisconds.
04-08 12:15:26.144  9926  9926 D CycledLeScanner: stopping bluetooth le scan
04-08 12:15:26.147  9926  9926 D CycledLeScanner: starting a new bluetooth le scan
04-08 12:15:26.167  7692  7848 E BtGatt.GattService: App 'org.altbeacon.beaconreference' is scanning too frequently

Logs after this change. Note there is no extra scan stop and no blocked scan.

adb logcat | grep -E 'bluetooth le scan|Android N|beaconService version|scanning too frequently'

04-08 12:21:01.975 10378 10378 I BeaconService: beaconService version 2.9.2-22-g549b656-SNAPSHOT is starting up
04-08 12:21:02.333 10378 10378 D CycledLeScanner: starting a new bluetooth le scan
04-08 12:21:03.442 10378 10378 D CycledLeScanner: Not stopping scan because this is Android N and we keep scanning for a minimum of 6 seconds at a time. We will stop in 4897 millisconds.
04-08 12:21:04.546 10378 10378 D CycledLeScanner: Not stopping scan because this is Android N and we keep scanning for a minimum of 6 seconds at a time. We will stop in 3792 millisconds.
04-08 12:21:05.653 10378 10378 D CycledLeScanner: Not stopping scan because this is Android N and we keep scanning for a minimum of 6 seconds at a time. We will stop in 2685 millisconds.
04-08 12:21:06.759 10378 10378 D CycledLeScanner: Not stopping scan because this is Android N and we keep scanning for a minimum of 6 seconds at a time. We will stop in 1580 millisconds.
04-08 12:21:07.864 10378 10378 D CycledLeScanner: Not stopping scan because this is Android N and we keep scanning for a minimum of 6 seconds at a time. We will stop in 475 millisconds.
04-08 12:21:08.966 10378 10378 D CycledLeScanner: stopping bluetooth le scan
04-08 12:21:08.967 10378 10378 D CycledLeScanner: starting a new bluetooth le scan
04-08 12:21:10.070 10378 10378 D CycledLeScanner: Not stopping scan because this is Android N and we keep scanning for a minimum of 6 seconds at a time. We will stop in 4898 millisconds.

The consequences of this bug (using default library settings) are that there would be a 1.1 second dropout in beacon detections every time ranging/monitoring was started up, or an app moved from the background to the foreground.

To make this consequence clear, perhaps the change log description should be "Fix bug causing brief scan dropouts on startup or background-foreground transition due to Android N scan limits"

Using the prior scan end time to calculate when we can stop the current
scan cycle causes an immediate scan stop under two conditions:

- this is the first scan cycle
- scanning has been stopped for longer than 6 seconds (a more
  generalized case of the first scan cycle)

Notation
--------

- current elapsed time in milliseconds: `𝜀`
- minimum Android N scan interval in milliseconds (i.e. 6000): `𝛮`
- elapsed last scan stop time in milliseconds: `𝛾`
- elapsed current scan start time in milliseconds: `𝛼`

Preconditions
-------------

Under normal conditions the current elapsed time will always be greater
than the minimum Android N scan interval of `6000` (i.e. the device has
been running for longer than 6 seconds). All values are also assumed to
be natural numbers (positive integers including 0).

Case 1: First Scan Cycle
------------------------

When the first scan is initiated the last scan cycle stop time will be
zero. Since the elapsed time is greater than the minimum Android N
interval the bounds check will fail.

    Given 𝜀 > 𝛮 and 𝛾 = 0, then 𝜀 - 𝛾 > 𝛮.

    Proof:

          𝜀 > 𝛮
      𝜀 - 𝛾 > 𝛮 - 𝛾
      𝜀 - 𝛾 > 𝛮 - 0
      𝜀 - 𝛾 > 𝛮

Thus a stop will happen after the first scan period. When scanning
continue it will have to start a new scan, exceeding the five per thirty
seconds.

Case 2: Long Scan Stopped
-------------------------

When scanning has been stopped for longer than 6 seconds we are
essentially in a "first scan cycle" situation. This is nothing more than
a generalization of the first scan cycle case.

    Given 𝛾 > 𝛮 and 𝛾 < 𝜀 when 𝛾 + 𝛮 < 𝜀, then 𝜀 - 𝛾 > 𝛮.

    Proof:

                  𝛾 < 𝜀
      𝛾 > 𝛮 ≣ 𝛮 < 𝛾
              𝛮 < 𝛾 < 𝜀

    When 𝛾 + 𝛮 < 𝜀 this still holds

                𝛾 + 𝛮 < 𝜀
            𝛾 < 𝛾 + 𝛮 < 𝜀
        𝛮 < 𝛾 < 𝛾 + 𝛮 < 𝜀

    ∴   𝛮 < 𝜀 - 𝛾 ≣ 𝜀 - 𝛾 > 𝛮

So once the first scan period is complete we'll immediately stop it.

Solution
--------

The simple solution is to always check the scan start time. It will
always be true, since only one scan can happen at a time, that the
previous stop value is less than the start value. Thus the start value
plus the minimum Android N scan time will always be greater than the
last stop time equivalent. This guarantees that with normal continuous
scan cycling there will be no more than five scans.

Caveat
------

However, there's nothing stopping someone from starting and stopping the
scans manually. Checking the last scan stop time won't help as normal
scanning cycles start and stop scans repeatedly without a delay. This
final case requires more investigation as there are several potential
solutions but all require significant code changes.
@cupakromer
Copy link
Contributor Author

Changelog updated

@davidgyoung davidgyoung merged commit 016bb44 into master Apr 10, 2017
@cupakromer cupakromer deleted the fix-intermittent-scans branch April 10, 2017 14:53
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

2 participants