AltBeacon / android-beacon-library

Allows Android apps to interact with BLE beacons
Apache License 2.0
2.84k stars 836 forks source link

Frequent random exit/enter region events triggered #982

Open OutWestSys opened 4 years ago

OutWestSys commented 4 years ago

Expected behavior

Exit region is only triggered when beacon is actually out of range.

Actual behavior

Even with a beacon just a couple of feet away multiple exit/enter region events occur at random intervals. Below is an example of the behavior. This was obtained using the BeaconReferenceApplication. The scan period was set to five seconds in this case.

Entered Region | Tue Jun 16 13:29:32 MDT 2020 Exited Region | Tue Jun 16 14:01:42 MDT 2020 Entered Region | Tue Jun 16 14:01:55 MDT 2020 Exited Region | Tue Jun 16 14:02:57 MDT 2020 Entered Region | Tue Jun 16 14:03:13 MDT 2020 Exited Region | Tue Jun 16 14:04:17 MDT 2020 Entered Region | Tue Jun 16 14:04:31 MDT 2020 Exited Region | Tue Jun 16 14:05:32 MDT 2020 Entered Region | Tue Jun 16 14:07:08 MDT 2020 Exited Region | Tue Jun 16 14:08:08 MDT 2020 Entered Region | Tue Jun 16 14:08:26 MDT 2020

The issue occurs if the app is in the foreground or background and with power connected or not connected. The screen being off seems to trigger the issue though it is pretty random when it starts. Sometimes the enter region event fires within seconds, other times it can take 20 minutes or more to fire.

Steps to reproduce this behavior

Install the BeaconReferenceApplication on a Samsung phone. A Galaxy S6 with Android 7 seems most prone to this problem, but it can happen on other phones running Android 7 to Android 10. We used a slightly modified BeaconReferenceApplication.java file as attached below. Changes to the code are flagged with comments. Changes made were to add a logging file and to set it up as foreground service.

BeaconReferenceApplication_Edited.zip

Run the app with monitoring enabled. Ranging can be left off. Leave the phone near the beacon for an hour or two, or even overnight.

We are using a MOKO beacon set up as an iBeacon with a 1 second advertising period. Testing with the scan period set to the default value all the way up to 60 seconds per scan has no significant change in the behavior.

Mobile device model and OS version

Samsung Galaxy S6/Android 7 or Samsung Galaxy S8/Android 9

Android Beacon Library version

2.17.1

davidgyoung commented 4 years ago

@OutWestSys, sorry for the trouble. Thank you for the detailed report.

Can you tell me whether your app has applied this setting here? That setting is not widely publicized because it can be easily abused.

The modifications you describe making to the BeaconReferenceApplication are not trivial -- the changes effectively turn on constant scanning at a 100% duty cycle in a way that will have serious impact on battery. Android 7 intentionally introduced a block against doing this for more than 30 minutes. There are ways to circumvent that OS restriction, and the link above describes how to do so. But this library intentionally does not make that super easy to prevent casual users from accidentally causing problems.

Please let me know if you think this may be the cause of this issue. If you have already applied that setting, then there must be a different explanation for what you are seeing. If this is the case, I would ask that you set beaconManager.setDebug(true); and capture a long LogCat file that covers 30 minutes before the unexpected region exit and 30 minutes after the subsequent region entry.

OutWestSys commented 4 years ago

@davidgyoung We are using the setting to bypass the 30 minute restriction, both in our app and in the BeaconReferenceApplication app. Attached is the logcat file covering an hour and the log showing the enter/exit events that occurred over this period. This test was done with the screen off and phone just sitting on table. The BeaconReferenceApplication was set to trigger exit region after 60 seconds. Not sure if that is a factor, but it appears each exit region happened 60 seconds roughly after the enter region event. Thanks.

Issue982.zip

davidgyoung commented 4 years ago

Quick analysis of that ~1 hour log file from 14:05:04 to 15:07:00

There were only 76 beacon packet detections during that hour (see below), with many gaps between detections of several minutes. However, the library detected other BLE detections (that did not match iBeacon) much more frequently -- 7361 times in the log file, pretty regularly, too. You can see cases like this in the log with lines like:

06-18 14:06:04.028 10600 10634 D BeaconParser: This is not a matching Beacon advertisement. (Was expecting 02 15.  The bytes I see are: 0201060aff4c0010050c1896c950000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000

If you look in the log, you see these lines throughout the file, indicating that the device and library are detecting BLE packets.

To summarize:

  1. There ARE NOT any long dropouts in getting BLE scan results to the Android Beacon Library.
  2. There ARE long dropouts in detecting this particular transmission.

Without evidence to the contrary, the simplest explanation is that the transmitting beacon actually is not transmitting at those times. I'd suggest you run a test to confirm this -- wait for a region exit event on the phone, the use a second phone with an off-the-shelf app like BeaconScope to look to see if you can confirm the beacon is actually transmitting at that time. Perhaps something is causing that beacon to stop transmitting at times.

Here are the times a beacon was detected:

06-18 14:05:04.361 29534 29620 D ScanHelper: beacon detected : id1: 9a3ff512-cd06-446a-bade-4d1a79b29393 id2: 51 id3: 1
06-18 14:05:06.363 29534 29624 D ScanHelper: beacon detected : id1: 9a3ff512-cd06-446a-bade-4d1a79b29393 id2: 51 id3: 1
06-18 14:05:08.367 29534 29621 D ScanHelper: beacon detected : id1: 9a3ff512-cd06-446a-bade-4d1a79b29393 id2: 51 id3: 1
06-18 14:05:10.366 29534 29625 D ScanHelper: beacon detected : id1: 9a3ff512-cd06-446a-bade-4d1a79b29393 id2: 51 id3: 1
06-18 14:05:12.382 29534 29621 D ScanHelper: beacon detected : id1: 9a3ff512-cd06-446a-bade-4d1a79b29393 id2: 51 id3: 1
06-18 14:05:14.359 29534 29624 D ScanHelper: beacon detected : id1: 9a3ff512-cd06-446a-bade-4d1a79b29393 id2: 51 id3: 1
06-18 14:05:16.355 29534 29618 D ScanHelper: beacon detected : id1: 9a3ff512-cd06-446a-bade-4d1a79b29393 id2: 51 id3: 1
06-18 14:05:18.364 29534 29623 D ScanHelper: beacon detected : id1: 9a3ff512-cd06-446a-bade-4d1a79b29393 id2: 51 id3: 1
06-18 14:05:20.355 29534 29622 D ScanHelper: beacon detected : id1: 9a3ff512-cd06-446a-bade-4d1a79b29393 id2: 51 id3: 1
06-18 14:05:22.375 29534 29617 D ScanHelper: beacon detected : id1: 9a3ff512-cd06-446a-bade-4d1a79b29393 id2: 51 id3: 1
06-18 14:05:24.370 29534 29621 D ScanHelper: beacon detected : id1: 9a3ff512-cd06-446a-bade-4d1a79b29393 id2: 51 id3: 1
06-18 14:05:26.358 29534 29617 D ScanHelper: beacon detected : id1: 9a3ff512-cd06-446a-bade-4d1a79b29393 id2: 51 id3: 1
06-18 14:05:28.375 29534 29621 D ScanHelper: beacon detected : id1: 9a3ff512-cd06-446a-bade-4d1a79b29393 id2: 51 id3: 1
06-18 14:05:30.359 29534 29617 D ScanHelper: beacon detected : id1: 9a3ff512-cd06-446a-bade-4d1a79b29393 id2: 51 id3: 1
06-18 14:05:32.351 29534 29624 D ScanHelper: beacon detected : id1: 9a3ff512-cd06-446a-bade-4d1a79b29393 id2: 51 id3: 1
06-18 14:05:34.373 29534 29619 D ScanHelper: beacon detected : id1: 9a3ff512-cd06-446a-bade-4d1a79b29393 id2: 51 id3: 1
06-18 14:05:36.351 29534 29617 D ScanHelper: beacon detected : id1: 9a3ff512-cd06-446a-bade-4d1a79b29393 id2: 51 id3: 1
06-18 14:05:38.370 29534 29623 D ScanHelper: beacon detected : id1: 9a3ff512-cd06-446a-bade-4d1a79b29393 id2: 51 id3: 1
06-18 14:05:40.350 29534 29625 D ScanHelper: beacon detected : id1: 9a3ff512-cd06-446a-bade-4d1a79b29393 id2: 51 id3: 1
06-18 14:05:42.379 29534 29617 D ScanHelper: beacon detected : id1: 9a3ff512-cd06-446a-bade-4d1a79b29393 id2: 51 id3: 1
06-18 14:05:44.383 29534 29619 D ScanHelper: beacon detected : id1: 9a3ff512-cd06-446a-bade-4d1a79b29393 id2: 51 id3: 1
06-18 14:05:46.378 29534 29617 D ScanHelper: beacon detected : id1: 9a3ff512-cd06-446a-bade-4d1a79b29393 id2: 51 id3: 1
06-18 14:05:48.364 29534 29623 D ScanHelper: beacon detected : id1: 9a3ff512-cd06-446a-bade-4d1a79b29393 id2: 51 id3: 1
06-18 14:05:50.355 29534 29621 D ScanHelper: beacon detected : id1: 9a3ff512-cd06-446a-bade-4d1a79b29393 id2: 51 id3: 1
06-18 14:05:52.355 29534 29618 D ScanHelper: beacon detected : id1: 9a3ff512-cd06-446a-bade-4d1a79b29393 id2: 51 id3: 1
06-18 14:05:54.369 29534 29617 D ScanHelper: beacon detected : id1: 9a3ff512-cd06-446a-bade-4d1a79b29393 id2: 51 id3: 1
06-18 14:06:08.369 10600 10634 D ScanHelper: beacon detected : id1: 9a3ff512-cd06-446a-bade-4d1a79b29393 id2: 51 id3: 1
06-18 14:06:10.370 10600 10682 D ScanHelper: beacon detected : id1: 9a3ff512-cd06-446a-bade-4d1a79b29393 id2: 51 id3: 1
06-18 14:06:12.357 10600 10685 D ScanHelper: beacon detected : id1: 9a3ff512-cd06-446a-bade-4d1a79b29393 id2: 51 id3: 1
06-18 14:06:14.358 10600 10631 D ScanHelper: beacon detected : id1: 9a3ff512-cd06-446a-bade-4d1a79b29393 id2: 51 id3: 1
06-18 14:06:16.363 10600 10633 D ScanHelper: beacon detected : id1: 9a3ff512-cd06-446a-bade-4d1a79b29393 id2: 51 id3: 1
06-18 14:09:02.367 10600 10683 D ScanHelper: beacon detected : id1: 9a3ff512-cd06-446a-bade-4d1a79b29393 id2: 51 id3: 1
06-18 14:09:04.381 10600 10683 D ScanHelper: beacon detected : id1: 9a3ff512-cd06-446a-bade-4d1a79b29393 id2: 51 id3: 1
06-18 14:09:06.376 10600 10682 D ScanHelper: beacon detected : id1: 9a3ff512-cd06-446a-bade-4d1a79b29393 id2: 51 id3: 1
06-18 14:09:08.374 10600 10632 D ScanHelper: beacon detected : id1: 9a3ff512-cd06-446a-bade-4d1a79b29393 id2: 51 id3: 1
06-18 14:09:10.377 10600 10632 D ScanHelper: beacon detected : id1: 9a3ff512-cd06-446a-bade-4d1a79b29393 id2: 51 id3: 1
06-18 14:25:36.446 10600 10631 D ScanHelper: beacon detected : id1: 9a3ff512-cd06-446a-bade-4d1a79b29393 id2: 51 id3: 1
06-18 14:25:38.465 10600 10682 D ScanHelper: beacon detected : id1: 9a3ff512-cd06-446a-bade-4d1a79b29393 id2: 51 id3: 1
06-18 14:25:40.468 10600 10632 D ScanHelper: beacon detected : id1: 9a3ff512-cd06-446a-bade-4d1a79b29393 id2: 51 id3: 1
06-18 14:25:42.441 10600 10636 D ScanHelper: beacon detected : id1: 9a3ff512-cd06-446a-bade-4d1a79b29393 id2: 51 id3: 1
06-18 14:36:12.535 10600 10631 D ScanHelper: beacon detected : id1: 9a3ff512-cd06-446a-bade-4d1a79b29393 id2: 51 id3: 1
06-18 14:37:30.505 10600 10685 D ScanHelper: beacon detected : id1: 9a3ff512-cd06-446a-bade-4d1a79b29393 id2: 51 id3: 1
06-18 14:38:48.527 10600 10636 D ScanHelper: beacon detected : id1: 9a3ff512-cd06-446a-bade-4d1a79b29393 id2: 51 id3: 1
06-18 14:40:06.542 10600 10631 D ScanHelper: beacon detected : id1: 9a3ff512-cd06-446a-bade-4d1a79b29393 id2: 51 id3: 1
06-18 14:41:24.552 10600 10632 D ScanHelper: beacon detected : id1: 9a3ff512-cd06-446a-bade-4d1a79b29393 id2: 51 id3: 1
06-18 14:42:42.521 10600 10632 D ScanHelper: beacon detected : id1: 9a3ff512-cd06-446a-bade-4d1a79b29393 id2: 51 id3: 1
06-18 14:52:16.589 10600 10682 D ScanHelper: beacon detected : id1: 9a3ff512-cd06-446a-bade-4d1a79b29393 id2: 51 id3: 1
06-18 14:53:34.624 10600 10633 D ScanHelper: beacon detected : id1: 9a3ff512-cd06-446a-bade-4d1a79b29393 id2: 51 id3: 1
06-18 14:54:52.623 10600 10632 D ScanHelper: beacon detected : id1: 9a3ff512-cd06-446a-bade-4d1a79b29393 id2: 51 id3: 1
06-18 15:01:48.628 10600 10685 D ScanHelper: beacon detected : id1: 9a3ff512-cd06-446a-bade-4d1a79b29393 id2: 51 id3: 1
06-18 15:02:08.641 10600 10632 D ScanHelper: beacon detected : id1: 9a3ff512-cd06-446a-bade-4d1a79b29393 id2: 51 id3: 1
06-18 15:02:48.630 10600 10636 D ScanHelper: beacon detected : id1: 9a3ff512-cd06-446a-bade-4d1a79b29393 id2: 51 id3: 1
06-18 15:02:58.654 10600 10631 D ScanHelper: beacon detected : id1: 9a3ff512-cd06-446a-bade-4d1a79b29393 id2: 51 id3: 1
06-18 15:03:08.641 10600 10685 D ScanHelper: beacon detected : id1: 9a3ff512-cd06-446a-bade-4d1a79b29393 id2: 51 id3: 1
06-18 15:03:18.658 10600 10633 D ScanHelper: beacon detected : id1: 9a3ff512-cd06-446a-bade-4d1a79b29393 id2: 51 id3: 1
06-18 15:03:28.645 10600 10682 D ScanHelper: beacon detected : id1: 9a3ff512-cd06-446a-bade-4d1a79b29393 id2: 51 id3: 1
06-18 15:03:38.634 10600 10683 D ScanHelper: beacon detected : id1: 9a3ff512-cd06-446a-bade-4d1a79b29393 id2: 51 id3: 1
06-18 15:03:48.636 10600 10685 D ScanHelper: beacon detected : id1: 9a3ff512-cd06-446a-bade-4d1a79b29393 id2: 51 id3: 1
06-18 15:03:58.627 10600 10632 D ScanHelper: beacon detected : id1: 9a3ff512-cd06-446a-bade-4d1a79b29393 id2: 51 id3: 1
06-18 15:04:08.661 10600 10633 D ScanHelper: beacon detected : id1: 9a3ff512-cd06-446a-bade-4d1a79b29393 id2: 51 id3: 1
06-18 15:04:18.630 10600 10631 D ScanHelper: beacon detected : id1: 9a3ff512-cd06-446a-bade-4d1a79b29393 id2: 51 id3: 1
06-18 15:04:28.671 10600 10635 D ScanHelper: beacon detected : id1: 9a3ff512-cd06-446a-bade-4d1a79b29393 id2: 51 id3: 1
06-18 15:04:38.643 10600 10634 D ScanHelper: beacon detected : id1: 9a3ff512-cd06-446a-bade-4d1a79b29393 id2: 51 id3: 1
06-18 15:04:48.645 10600 10635 D ScanHelper: beacon detected : id1: 9a3ff512-cd06-446a-bade-4d1a79b29393 id2: 51 id3: 1
06-18 15:04:58.634 10600 10633 D ScanHelper: beacon detected : id1: 9a3ff512-cd06-446a-bade-4d1a79b29393 id2: 51 id3: 1
06-18 15:05:08.666 10600 10631 D ScanHelper: beacon detected : id1: 9a3ff512-cd06-446a-bade-4d1a79b29393 id2: 51 id3: 1
06-18 15:05:18.662 10600 10633 D ScanHelper: beacon detected : id1: 9a3ff512-cd06-446a-bade-4d1a79b29393 id2: 51 id3: 1
06-18 15:05:28.644 10600 10633 D ScanHelper: beacon detected : id1: 9a3ff512-cd06-446a-bade-4d1a79b29393 id2: 51 id3: 1
06-18 15:05:38.649 10600 10682 D ScanHelper: beacon detected : id1: 9a3ff512-cd06-446a-bade-4d1a79b29393 id2: 51 id3: 1
06-18 15:05:48.650 10600 10682 D ScanHelper: beacon detected : id1: 9a3ff512-cd06-446a-bade-4d1a79b29393 id2: 51 id3: 1
06-18 15:05:58.637 10600 10685 D ScanHelper: beacon detected : id1: 9a3ff512-cd06-446a-bade-4d1a79b29393 id2: 51 id3: 1
06-18 15:06:08.642 10600 10634 D ScanHelper: beacon detected : id1: 9a3ff512-cd06-446a-bade-4d1a79b29393 id2: 51 id3: 1
06-18 15:06:18.643 10600 10682 D ScanHelper: beacon detected : id1: 9a3ff512-cd06-446a-bade-4d1a79b29393 id2: 51 id3: 1
06-18 15:06:28.654 10600 10685 D ScanHelper: beacon detected : id1: 9a3ff512-cd06-446a-bade-4d1a79b29393 id2: 51 id3: 1
06-18 15:06:38.638 10600 10634 D ScanHelper: beacon detected : id1: 9a3ff512-cd06-446a-bade-4d1a79b29393 id2: 51 id3: 1
06-18 15:06:48.644 10600 10634 D ScanHelper: beacon detected : id1: 9a3ff512-cd06-446a-bade-4d1a79b29393 id2: 51 id3: 1
OutWestSys commented 4 years ago

I'm running the BeaconReferenceApplicaton on a Samsung S6/OS 7 and on a Google Pixel 3/OS 10 at the same time. Turning on ranging shows the Pixel 3 reporting the beacon every few seconds. The Samsung reports the beacon occasionally with long pauses between reports. In fact, it has been several minutes since the S6 reported the beacon while the Pixel continues to show range reports every few seconds.

So it looks like the beacon is transmitting as expected, but the Samsung is not detecting most of the transmissions.

Both phones have the app in the foreground, with the screen on and power connected.

Thanks for the help.

davidgyoung commented 4 years ago

Funny thing is that the logs shows the Samsung detecting other BLE devices. If that beacon is transmitting then something is filtering out its detections on the Samsung device.

I should add that I have done lots of testing on Samsung devices even with pre-Android 8 OS versions, and I really ave not seen behavior like this before. Something is funny about the behavior of those Samsung phones, and I do not think it is the models or OS versions as they are pretty common. I wonder if some other app or unusual configuration of the phones is at play.

OutWestSys commented 4 years ago

The issue seems like it might be tied to the screen being off. I know there was an issue with the Samsung screen off state that was fixed in 2.16. Maybe this is related.

I found an easy to way track the beacon reports. From the logcat window, enter 'beacon detected' in the text search box. You can then watch the match count in the title bar to track how often a beacon is detected.

image

With the Samsung when the screen is on I see a detection about every 8 seconds. I turn off the screen and the detection rate drops to a consistent ~77 seconds between detections. Turn screen on and it goes back to every 8 seconds. With the Pixel detections happen around every 2 seconds regardless of the screen being on or off.

This Samsung S6 is a fresh out of box phone used only for testing.

davidgyoung commented 4 years ago

Samsung added a custom change as of Android 8.1+ to require a non-empty bluetooth scan filter when the screen is off. The library already covers that, but this can't be what is going on here because this is an earlier OS version and because there are other BLE detections happening. Try searching for "This is not a matching Beacon advertisement" and you will see a bunch.

Perhaps Samsung is not returning duplicate scan results (e.g. a second detection of the same packet) when the screen is off? To test this theory you might change your betweenScanPeriod to 100ms, just to see if stopping a scan and restarting it causes results to come. I will say that I am not sure I have ever tried constant never-ending scans on Samsung with the screen off.

OutWestSys commented 4 years ago

Changed the between scan period to 100ms, but that did not help. I've attached a zip with two logcat files from the Samsung S6. One with the screen on and one with the screen off. Maybe you can see some difference between the two pointing to the issue? It definitely seems tied to the screen state.

With the screen on detections show up every couple seconds. Turn screen off, and detections change to anywhere from 8 to 80 seconds between detections. Turn screen back on and detections go back to every couple seconds. Thanks.

Issue982Logs.zip

davidgyoung commented 4 years ago

ScreenOn log:

ScreenOff log

So assuming about the same number of packets are visible in both tests, this suggests that this device is detecting only 3/187 = ~2% of the packets it would otherwise detect if the screen were on. By default, Android is supposed to force SCAN_MODE_LOW_POWER when the screen is off, but with open source Android, this is supposed to be about a 10% duty cycle -- certainly not 2 percent. I suppose it is possible that this Samsung firmware version has reduced that further.

While your results are not consistent with my use of Samsung devices, I cannot argue with what I see in the logs. I am not sure what it is about this device in the conditions under test that causes this behavior. Perhaps there is some resonance between your beacon's relatively infrequent advertising rate and the scan on times of the scan duty cycle that is causing this problem. It appears to me that even with the screen on, your beacon is never detected more than once every 2 seconds. So I do not think it is advertising at 1Hz. Sounds like closer to 2 Hz -- I certainly would never recommend such a low transmission rate. This could be the problem, in combination with some kind of resonance with the SCAN_MODE_LOW_POWER duty cycle.

I suggest you increase the advertising rate of your beacon. The iBeacon spec actually requires a 10Hz transmission rate. You may find with this transmission rate this problem simply goes away. If you really need a lower transmission rate, you may find that you have to significantly increase (further) the region exit period so you have more opportunities to detect it to avoid a region exit.

These are all tradeoffs. Beacon manufacturers want to reduce advertising rates to extend battery life. Phone manufacturers want to reduce scan duty cycles to save phone battery App developers want fast detections despite these other two limitations. There is no free lunch -- you may pick any two of the following, but you cannot have all three:

OutWestSys commented 4 years ago

Using a 10Hz advertising rate results in exit region events still being triggered, but the enter region event happens within one second or so after the exit. This would be acceptable but for the concerns of reducing the beacon life. Sounds like we are going to have to just work around this issue by finding the best combination of settings we can that still meets our requirements.

On the positive side, it seems like the newer the phone model the less of an issue this is. On a Google Pixel 3 running OS 10, for example, it appears to be virtually a non-issue.

Thanks for your in-depth analysis and help with this issue.