Search code examples
androidserviceibeaconibeacon-android

Why Android Beacon Library didRangeBeaconsInRegion is sometimes triggered twice?


This is a question regarding Android Beacon Library.

The Setup

The app uses BootstrapNotifier to do background scanning continuously.
Once a matched beacon is detected (i.e. didEnterRegion is triggered),
This background scanning will be disabled, and start a foreground service that starts to range beacons.

(You may refer to this post for more background)

You can also refer to this repository for this atomic testing project.

BeaconApplication is responsible for continuous background scanning.
SelfBeaconService is responsible for active foreground ranging.

(If you have a beacon at hand and want to build and test, you need to change the identifier filter to null or your own identifier.)

The Problem

Sometimes (I say sometimes because I don't know how to 100% reproduce), in SelfBeaconService, didRangeBeaconsInRegion is triggered twice at the same time, but I have only configured one region.

And below is the log that records double triggers.
Note that I have set the scanning interval to 4 seconds.

03-07 10:46:31.811 (...) I/selfBeacon: Bootstrap didEnterRegion
03-07 10:46:31.812 (...) I/BeaconService: stop monitoring received
03-07 10:46:31.820 (...) I/selfBeacon: Service start commanded
03-07 10:46:31.831 (...) I/BeaconService: unbinding
03-07 10:46:31.832 (...) E/BeaconService: onDestroy()
03-07 10:46:31.834 (...) I/BeaconService: onDestroy called.  stopping scanning
03-07 10:46:31.838 (...) I/selfBeaconService: onCreate
03-07 10:46:31.839 (...) I/selfBeaconService: onStartCommand
03-07 10:46:31.929 (...) I/CycledLeScanner: This is Android 5.0.  We are using new scanning APIs
03-07 10:46:31.951 (...) I/BeaconService: beaconService version 2.13.1 is starting up on the main process
03-07 10:46:31.954 (...) W/ModelSpecificDistanceCalculator: App has no android.permission.INTERNET permission.  Cannot check for distance model updates
03-07 10:46:31.958 (...) W/ModelSpecificDistanceCalculator: Cannot find match for this device.  Using default
03-07 10:46:31.959 (...) W/ModelSpecificDistanceCalculator: Cannot find match for this device.  Using default
03-07 10:46:31.960 (...) I/BeaconService: binding
03-07 10:46:31.979 (...) I/selfBeaconService: onBeaconServiceConnect
03-07 10:46:31.980 (...) I/BeaconService: start ranging received
03-07 10:46:32.168 (...) I/art: Do partial code cache collection, code=10KB, data=24KB
03-07 10:46:32.169 (...) I/art: After code cache collection, code=10KB, data=24KB
03-07 10:46:32.169 (...) I/art: Increasing code cache capacity to 128KB
03-07 10:46:33.065 (...) I/ScanHelper: Non-distinct packets detected in a single scan.  Restarting scans unecessary.
03-07 10:46:33.106 (...) I/selfBeaconService: didRangeBeaconsInRegion, the closest beacon is about 3.4581850922412523 meters away.
03-07 10:46:36.726 (...) I/selfBeaconService: didRangeBeaconsInRegion, the closest beacon is about 3.4581850922412523 meters away.
03-07 10:46:40.726 (...) I/selfBeaconService: didRangeBeaconsInRegion, the closest beacon is about 3.6056118574381157 meters away.
03-07 10:46:41.285 (...) I/art: Debugger is no longer active
03-07 10:46:41.285 (...) I/art: Starting a blocking GC Instrumentation
03-07 10:46:42.392 (...) I/CycledLeScanner: This is Android 5.0.  We are using new scanning APIs
03-07 10:46:42.401 (...) I/ScanJob: Using immediateScanJobId from manifest: 208352939
03-07 10:46:42.401 (...) I/ScanJob: Running immediate scan job: instance is org.altbeacon.beacon.service.ScanJob@398f59c
03-07 10:46:42.402 (...) I/ScanJob: scanJob version 2.13.1 is starting up on the main process
03-07 10:46:42.402 (...) W/ModelSpecificDistanceCalculator: App has no android.permission.INTERNET permission.  Cannot check for distance model updates
03-07 10:46:42.404 (...) W/ModelSpecificDistanceCalculator: Cannot find match for this device.  Using default
03-07 10:46:42.404 (...) W/ModelSpecificDistanceCalculator: Cannot find match for this device.  Using default
03-07 10:46:42.409 (...) I/ScanJob: Scan job running for 300000 millis
03-07 10:46:43.528 (...) I/ScanHelper: Non-distinct packets detected in a single scan.  Restarting scans unecessary.
03-07 10:46:44.434 (...) I/selfBeaconService: didRangeBeaconsInRegion, the closest beacon is about 2.92768959654115 meters away.
03-07 10:46:44.727 (...) I/selfBeaconService: didRangeBeaconsInRegion, the closest beacon is about 3.4996718323492226 meters away.
03-07 10:46:46.451 (...) I/selfBeaconService: didRangeBeaconsInRegion, the closest beacon is about 3.181513412080198 meters away.
03-07 10:46:48.737 (...) I/selfBeaconService: didRangeBeaconsInRegion, the closest beacon is about 4.135957968665044 meters away.
03-07 10:46:48.743 (...) I/selfBeaconService: didRangeBeaconsInRegion, the closest beacon is about 3.4581850922412523 meters away.
03-07 10:46:52.732 (...) I/selfBeaconService: didRangeBeaconsInRegion, the closest beacon is about 7.408179588037119 meters away.
03-07 10:46:52.735 (...) I/selfBeaconService: didRangeBeaconsInRegion, the closest beacon is about 11.306160864298167 meters away.
03-07 10:46:56.736 (...) I/selfBeaconService: didRangeBeaconsInRegion, the closest beacon is about 5.632619096507348 meters away.
03-07 10:46:56.740 (...) I/selfBeaconService: didRangeBeaconsInRegion, the closest beacon is about 9.280517536034091 meters away.
03-07 10:47:00.728 (...) I/selfBeaconService: didRangeBeaconsInRegion, the closest beacon is about 9.280517536034091 meters away.
03-07 10:47:00.733 (...) I/selfBeaconService: didRangeBeaconsInRegion, the closest beacon is about 9.280517536034091 meters away.
03-07 10:47:04.729 (...) I/selfBeaconService: didRangeBeaconsInRegion, the closest beacon is about 8.917299181373306 meters away.
03-07 10:47:04.733 (...) I/selfBeaconService: didRangeBeaconsInRegion, the closest beacon is about 8.917299181373306 meters away.

As you can see from 10:46:33 to 10:46:40, it is working correctly at 4 seconds interval. After that, suddenly a bunch of log messages kicked in, and looks like something (such as ScanJob) of Android Beacon Library is restarted.
And since then, the callbacks from 10:46:44 are triggered twice every 4 seconds.

So the question is... What happened, or why?


Solution

  • Quick context summary: This project is a case where the author seeks to optimize uninterrupted ranging on Android 8 by starting a foreground service to do the ranging when a beacon is detected. When beacons are not detected the default job scheduler scans will be used on Android 8.

    Based on the log, it appears that the excerpt taken after a foreground service started constant ranging. Then the job scheduler kicked in and started a ScanJob at the same time the service is already scanning. This likely is producing double callbacks because two different threads are doing cycled scanning at the same time and reporting ranging results to the same delegate. Thus, the app gets double callbacks.

    The root problem here is that if scheduled jobs are used for scanning, calling beaconManager.unbind(...) does not unschedule previously scheduled jobs. The library should do this but it does not as of version 2.31.1. This will need to be a new issue addressed with the library. I have logged an issue here

    In the interim, it is possible to cancel the jobs manually. (Caution: This uses private library APIs so it may break in a future version. It is best to use such code only temporarily until the issue is fixed in the library.)

    With the above warning in place, you should be able to manually cancel the jobs after an unbind with:

    JobScheduler jobScheduler = (JobScheduler) 
      context.getSystemService(Context.JOB_SCHEDULER_SERVICE);
    jobScheduler.cancel(ScanJob.getImmediateScanJobId(context));
    jobScheduler.cancel(ScanJob.getPeriodicScanJobId(context));