Android 5 LE Scan in background "not working" and background scan periods seems random when phone locked & battery powered

cha67 commented 7 years ago

Hello,

I'm testing the library with your android-beacon-library-reference app slightly modified (scanners added, scan periods set, 2 regions by UUID, didEnterRegion and didExitRegion shows a notification instead of launch the main activity) You can find it here : https://pastebin.com/RtYkRQBY

Below, when I speak about didEnterRegion, I state that I got all didExitRegion events on the 2 different UUID from my 2 test beacons before powering on again one of them. So, there is always only 1 beacon nearby at the same time.

Expected behavior

Reading the library doc, I would have thought that Android 5 Low energy scanning is made for the background.

But when the app is launched foreground, the Android 5 continuous scanning is used (immediate didEnterRegion notification when I power on a beacon), and when the app loses the foreground (push on Home key or app swap in the Android switcher), the "Android 4" scanning is used

Actual behavior

When the app is foreground, I instantly have didEnterRegion notification, but when in background with phone screen powered on, I see it up to BackgroundBetweenScanPeriod : 10sec in my case. It's the same when the screen is off, with USB cable connected / [or when ADB is connected by Wifi and phone battery powered].

But when the phone is battery powered and screen off without ADB connected by Wifi, it can take up to 1min30 to have the didEnterRegion, in spite of I set the BackgroundBetweenScanPeriod to 10sec. When Wifi is connected, it's a bit random, sometime, it takes up to 10 sec as I set, sometimes up to 1min30.

But when I power off the Wifi (phone is battery powered, screen off), the didEnterRegion delay is very often up to 1min30. didExitRegion events are, in the same manner in late in the same conditions (when app is foreground, it take always 15sec to have the event)

When I say "up to 1min30", it's an average. Sometimes, it can be more, like 2minutes, or less like 50sec.

Strange fact, when the phone is battery powered and screen off and when the didEnterRegion is in late compared to the 10sec I set, if I power on the screen with the hardware button of the phone, the didEnterRegion comes instantly ! Immediately after, while the screen is powered on, if I power on my second beacon, it take exactly 10sec to have didEnterRegion, so it seems Android 4 scan mode is still used.

It's seems important to note that there are other Bluetooth devices nearby (my neighbor ...), but they seems not to be beacons because when the app is foreground, didEnterRegion are immediate with my beacons (the doc states that Android 4 scan mode is used as soon as 1 beacon is nearby)

To summarize, I think I have 2 problems, maybe related:

Android 5 LE scan not used as soon as the app is in background
When the phone is battery powered and screen powered off, background scan periods seems random

What do you think ? Thank you :)

Mobile device model and OS version

Landvo XM200 Pro, Android 6.0

Android Beacon Library version

org.altbeacon-android-beacon-library-2.11-1-g16fac9d_14cc021e6de8dc4f83dd0ef6fdef6e5382e50a72

davidgyoung commented 7 years ago

I suspect this device may have a modified ROM that adds extra power saving modes on top of Android open source functions. We may be able to figure out what it is doing if you add the following code, then capture a LogCat excerpt between the time the app is put to the background and when you get the delayed detection.

beaconManager.setDebug(true);

cha67 commented 7 years ago

Hello, Thanks for the quick anwser. I'have send you a mail at tech@davidgyoung.com with the log (it's a full log which may contains sensitive informations, password is "beacon"). The app got in background around 18:22:00, a beacon was powered on around 18:22:40, and the notification came around 18:23:40. Thank you :)

Edit : don't hesitate to tell me if you need something more accurate with filtering

davidgyoung commented 7 years ago

Analyzing the 5 minute log, I see that:

The between scan period is 10000 milliseconds.
The scan period is 3000 milliseconds.
The library is in background mode and low-power scanning is used between cycles.
Bluetooth devices are detected regularly in the scans, but I never see a detection during low-power scans

When you turned on the beacon at 18:22:40, the library was in a between scan cycle (which started at 18:22:34), and a filtered low power scan was set up with a proper filter for your beacon type. But it never triggered. Only once the full scan cycle started at 18:23:40 did it detect.

Unfortunately, it looks like either the Landvo XM200 Pro does not support scan filters with low power scans, or for some reason they are unavailable during your test.

08-03 18:22:34.370 24453 24453 D CycledLeScannerForLollipop: This is Android L. Doing a filtered scan for the background.
08-03 18:22:34.372 24453 24453 D CycledLeScannerForLollipop: starting filtered scan in SCAN_MODE_LOW_POWER
08-03 18:22:34.372 24453 24453 D ScanFilterUtils: Set up a scan filter: BluetoothLeScanFilter [mDeviceName=null, mDeviceAddress=null, mUuid=null, mUuidMask=null, mServiceDataUuid=null, mServiceData=null, mServiceDataMask=null, mManufacturerId=76, mManufacturerData=[2, 21], mManufacturerDataMask=[-1, -1]]
...
08-03 18:23:40.045 24453 24453 D CycledLeScanner: starting a new scan cycle
08-03 18:23:40.370 24453 24453 D CycledLeScannerForLollipop: got record
08-03 18:23:40.370 24453 24490 D BeaconParser: This is a recognized beacon advertisement -- 4c 00 02 15 seen
08-03 18:23:40.670 24453 24453 D CycledLeScannerForLollipop: got record
08-03 18:23:40.671 24453 24486 D BeaconParser: This is a recognized beacon advertisement -- 4c 00 02 15 seen
08-03 18:23:40.891 24453 24453 D CycledLeScannerForLollipop: got record
08-03 18:23:40.892 24453 24489 D BeaconParser: This is a recognized beacon advertisement -- 4c 00 02 15 seen
08-03 18:23:40.999 24453 24453 D CycledLeScannerForLollipop: got record
08-03 18:23:41.003 24453 24488 D BeaconParser: This is a recognized beacon advertisement -- 4c 00 02 15 seen
08-03 18:23:41.420 24453 24453 D CycledLeScannerForLollipop: got record
08-03 18:23:41.422 24453 24487 D BeaconParser: This is a recognized beacon advertisement -- 4c 00 02 15 seen
08-03 18:23:41.729 24453 24453 D CycledLeScannerForLollipop: got record
08-03 18:23:41.731 24453 24490 D BeaconParser: This is a recognized beacon advertisement -- 4c 00 02 15 seen
08-03 18:23:42.057 24453 24453 D CycledLeScannerForLollipop: got record
08-03 18:23:42.059 24453 24486 D BeaconParser: This is a recognized beacon advertisement -- 4c 00 02 15 seen
08-03 18:23:42.502 24453 24453 D CycledLeScannerForLollipop: got record
08-03 18:23:42.512 24453 24489 D BeaconParser: This is a recognized beacon advertisement -- 4c 00 02 15 seen
08-03 18:23:42.691 24453 24453 D CycledLeScannerForLollipop: got record
08-03 18:23:42.693 24453 24488 D BeaconParser: This is a recognized beacon advertisement -- 4c 00 02 15 seen
08-03 18:23:42.862 24453 24453 D CycledLeScannerForLollipop: got record
08-03 18:23:42.900 24453 24453 D CycledLeScannerForLollipop: got record
08-03 18:23:42.902 24453 24490 D BeaconParser: This is a recognized beacon advertisement -- 4c 00 02 15 seen
08-03 18:23:43.075 24453 24453 D CycledLeScanner: Done with scan cycle

cha67 commented 7 years ago

Hello, Thanks for watching. I think I understand what you mean, that Low Energy Scan may not work on that device. But those lines aren't strange for you, about periods ?

08-03 18:22:03.401 24453 24453 D CycledLeScanner: starting a new scan cycle 08-03 18:22:26.013 24453 24453 D CycledLeScanner: starting a new scan cycle 08-03 18:22:31.340 24453 24453 D CycledLeScanner: starting a new scan cycle 08-03 18:23:40.045 24453 24453 D CycledLeScanner: starting a new scan cycle 08-03 18:23:40.381 24453 7872 D BeaconReferenceApp: Got a didEnterRegion call b9407f30-f5f8-466e-aff9-25556b57fe6d

The cycles period seems to be 23 seconds 5 seconds 69 seconds

And on this last scan, here is the delay I observed for the notification.

davidgyoung commented 7 years ago

I believe those irregular scan times are caused by something adjusting the system clock:

See these lines:

08-03 18:22:31.340 24453 24453 D CycledLeScanner: Normalizing between scan period from 10000 to -1950
08-03 18:22:34.370 24453 24453 D CycledLeScanner: Normalizing between scan period from 10000 to 8021
08-03 18:23:43.086 24453 24453 D CycledLeScanner: Normalizing between scan period from 10000 to 4305

Normally, the library will only slightly adjust the scan cycles to keep them on even time boundaries consistent with the total of the scan period / between scan period. The purpose of this is to make it so that if multiple apps are running with the library and use the default scan rates, they will scan simultaneously and save battery.

But those lines indicate something is not returning consistent results from the clock. Here are the lines of code that do this:

        long fullScanCycle = mScanPeriod + mBetweenScanPeriod;
        long normalizedBetweenScanPeriod = mBetweenScanPeriod-(SystemClock.elapsedRealtime() % fullScanCycle);
        LogManager.d(TAG, "Normalizing between scan period from %s to %s", mBetweenScanPeriod,
                normalizedBetweenScanPeriod);

As you can see, the SystemClock.elapsedRealtime() might be giving inconsistent results at this time. It's not sure why that might be true. But to troubleshoot it further, you might try directly logging SystemClock.elapsedRealtime() in your app at a periodic rate and see what it says.

dang-ng commented 10 months ago

hi, i had the same issue and after searched the internet i found your issue exactly as mine, i'm using a Chinese phone android 7.1, but i managed to fix it by using:

val wakeLock = (getSystemService(Context.POWER_SERVICE) as PowerManager).newWakeLock(PowerManager.PARTIAL_WAKE_LOCK, "name")
wakelock.aquire()

dont know why but i guess this will keep the CPU awake to calculate the time and continue scanning in next interval.

AltBeacon / android-beacon-library