Open zukopvd opened 7 years ago
@zukopvd, can you please attach a LogCat excerpt showing this message as well as the previous 60 seconds? I'd like to see how the scan cycles are actually running. I don't think you should see this error if you have it set up as described.
@davidgyoung here it is. I've replaced host app package name with "my_package_name"
It looks like from those logs that something is starting scanning really often -- like every 8 milliseconds! See excerpt below, and note the lines with BTA_DmBleScanFilterSetup
that are 8ms apart.
8-0300:48:34.672 5409-5463/? I/bt_btif: BTA_DmBleScanFilterSetup: 0
08-0300:48:34.672 5409-5540/? I/bt_btm: BTM_BleAdvFilterParamSetup
08-0300:48:34.672 5409-5540/? I/bt_btm: BTM: BTM_VendorSpecificCommand: Opcode: 0xFD57, ParamLen: 18.
08-0300:48:34.676 5409-5463/? W/bt_btif: HAL bt_gatt_callbacks->client->scan_filter_param_cb
08-0300:48:34.676 5409-5463/? I/bt_btif: BTA_DmBleCfgFilterCondition: 0, 2
08-0300:48:34.676 5409-5540/? I/bt_btm: BTM_BleCfgFilterCondition action:0, cond_type:2, index:11
08-0300:48:34.677 5409-5540/? I/bt_btm: BTM: BTM_VendorSpecificCommand: Opcode: 0xFD57, ParamLen: 7.
08-0300:48:34.680 5409-5463/? W/bt_btif: HAL bt_gatt_callbacks->client->scan_filter_cfg_cb
08-0300:48:34.680 5409-5463/? I/bt_btif: BTA_DmBleScanFilterSetup: 0
08-0300:48:34.680 5409-5540/? I/bt_btm: BTM_BleAdvFilterParamSetup
08-0300:48:34.680 5409-5540/? I/bt_btm: BTM: BTM_VendorSpecificCommand: Opcode: 0xFD57, ParamLen: 18.
I don't think it is the Android Beacon Library that is doing this (unless you actually set the scan period to 8 millis). To confirm, can you caputure another log excerpt after adding this line of code:
BeaconManager.setDebug(true);
Yes, I saw that waterfall of these messages and actually was wondered. Here is my full manager configuration, may be something wrong here:
BeaconManager.setDebug(true); // this line just added
beaconManager = BeaconManager.getInstanceForApplication(this.getApplicationContext());
beaconManager.getBeaconParsers().add(new BeaconParser().
setBeaconLayout(BeaconParser.EDDYSTONE_UID_LAYOUT));
beaconManager.getBeaconParsers().add(new BeaconParser().setBeaconLayout(BeaconParser.URI_BEACON_LAYOUT));
beaconManager.setRegionStatePeristenceEnabled(false);
beaconManager.setForegroundScanPeriod(1000L);
beaconManager.setForegroundBetweenScanPeriod(2000L);
beaconManager.setBackgroundMode(true);
beaconManager.setBackgroundScanPeriod(5000L);
beaconManager.setBackgroundBetweenScanPeriod(30000L);
And here is new log excerpt
Annotating that log excerpt, I see:
# background full power scan for 5 secs
08-03 01:44:29.469 26456-26456/my_package_name D/CycledLeScanner: starting a new scan cycle
08-03 01:44:34.510 26456-26456/my_package_name D/CycledLeScanner: stopping bluetooth le scan
# low power scan for 30 secs
08-030 1:44:34.514 26456-26456/my_package_name D/CycledLeScannerForLollipop: This is Android L. Doing a filtered scan for the background.
# background full power scan for 5 secs
08-03 01:45:04.462 26456-26456/my_package_name D/CycledLeScanner: starting a new scan cycle
08-03 01:45:09.493 26456-26675/my_package_name D/CycledLeScannerForLollipop: Stopping LE scan on scan handler
#Starts background scan:
08-03 01:45:09.496 26456-26456/my_package_name D/CycledLeScannerForLollipop: starting filtered scan in SCAN_MODE_LOW_POWER
# OS Blocks scan
08-03 01:45:09.539 5409-5421/? E/Bth: G.GattService:App 'my_package_name' is scanning too frequently on screen off
So there are not 5 scans happening in 30 seconds.
The error message is "G.GattService:App 'my_package_name' is scanning too frequently on screen off" which is not the same as the error message in the Android Open Source code:
So I now wonder if this is a custom ROM modification made by Huawei that adds an additional restriction when the screen is off.
Question: Can you try using different backgroundBeteweenScanPeriod values to see if a longer value makes the error go away?
Currently I cant escape this error even if I use following configuration:
beaconManager.setBackgroundScanPeriod(2000L);
beaconManager.setBackgroundBetweenScanPeriod(600000L);
I'll try to use more extremal values until it gone. By the way, on Nexus 5X running Android 7.1 with lib version 2.11 everything works fine.
So... I have the same issue with beaconManager.setBackgroundBetweenScanPeriod(1800000L)
and beaconManager.setBackgroundBetweenScanPeriod(3600000L)
as well.
Is it make sense to try 2 and more hours? Actually, with large periods the error appears on second scanning iteration after the first waiting period.
Well, we don't know what the criteria are to trigger this:
E/Bth: G.GattService:App 'my_package_name' is scanning too frequently on screen off
Again, this debug line does not appear in the open source code, so it must be a customization by Huawei or Samsung (Do you really see this debug line on both devices?) Unfortunately, if it is a closed source modification, there is no way to know the criteria that trigger it without reverse engineering it somehow. Perhaps it Is triggered when you start a scan in the background even once, regardless of the length of time.
My guess is that it is some variation on the AOSP algorithm for 7.0, which is to only allow 5 scan starts per app in a 30 second window. The customization might kick in when the screen is off, and restrict it to different values of X scan starts per app in a Y second window. If I am right about this, we need to find out the values of X and Y through experimentation before we can do anything about this.
@davidgyoung I still can't find proper values to avoid this error. But now I really worried about that often-scanning that you've mentioned (the one that happens every ~8 milliseconds). Actually that flood starts right after launching of regions monitoring via AltBeacon library.
I am facing same behavior in both foreground and background modes.
Furthermore, using foreground mode I can see original E/Bth: G.GattService:App 'my_package_name' is scanning too frequently
(without words "screen off") error with following configuration:
BeaconManager.setDebug(true);
beaconManager = BeaconManager.getInstanceForApplication(this.getApplicationContext());
beaconManager.getBeaconParsers().add(new BeaconParser().
setBeaconLayout(BeaconParser.EDDYSTONE_UID_LAYOUT));
beaconManager.getBeaconParsers().add(new BeaconParser().setBeaconLayout(BeaconParser.URI_BEACON_LAYOUT));
beaconManager.setForegroundScanPeriod(1000L);
beaconManager.setForegroundBetweenScanPeriod(3000L);
beaconManager.setBackgroundScanPeriod(2000L);
beaconManager.setBackgroundBetweenScanPeriod(30000L);
beaconManager.setRegionStatePeristenceEnabled(false);
Here is some logs attached. I've tried to capture as much logs before the first appearance of this error as possible. But in fact it takes about 10 seconds after starting of monitoring in foreground mode.
I think that the first issue can be caused because of that too. Earlier I was needed only background scanning so I've never tried foreground mode before but, as I can see, the only difference is the scan period time and the time between scanning periods.
UPD
Here is another log of the manager initialization that shows binding, regions registration etc. Hope it will be useful - maybe the initialization flow is wrong on my side.
In this case, you appear to have uncovered a bug in the library for foreground scan settings with a non-zero between scan period.
Two problems:
As can be seen by the first code block below, the library is supposed to switch to low power scanning when the main cycle is not active. But because it also checks against the mBackgroundFlag, it ends up simply restarting the full scan in this case. Unfortunately, it appears that setting a betweenScanPeriod > 0 is currently broken in recent library versions. A possible solution is to remove the mBackgroundFlag
from the if statement.
The logic in the library that attempts to avoid the "is scanning too frequently" error from Android 7, will not work when the betweenScanPeriod > 0 and betweenScanPeriod+scanPeriod < 6 seconds. The logic will need to be augmented to avoid this error (perhaps by simply not scanning at all in the betweenScanPeriod if the length of this period < 6 seconds)
The practical effects of problem 2 above in your case are relatively minor. Other than seeing the error message about "scanning too frequently", the only result will be that you won't get any detections in your between scan period, something that my proposed fix to avoid the error message would ensure anyway.
Bottom line: While this causes noise in your log, I don't believe it is causing you any significant problems. You can avoid the error message by changing your cycle to be at least 6 seconds long if you have a nonzero between scan period, perhaps:
beaconManager.setForegroundScanPeriod(1000L);
beaconManager.setForegroundBetweenScanPeriod(5000L);
For the record, here is the problematic library code mentioned above:
if (mBackgroundFlag && !mMainScanCycleActive) {
LogManager.d(TAG, "starting filtered scan in SCAN_MODE_LOW_POWER");
settings = (new ScanSettings.Builder().setScanMode(ScanSettings.SCAN_MODE_LOW_POWER)).build();
filters = new ScanFilterUtils().createScanFiltersForBeaconParsers(
mBeaconManager.getBeaconParsers());
} else {
LogManager.d(TAG, "starting non-filtered scan in SCAN_MODE_LOW_LATENCY");
settings = (new ScanSettings.Builder().setScanMode(ScanSettings.SCAN_MODE_LOW_LATENCY)).build();
}
It's strange but I was able to avoid the foreground issue only using LOW_POWER or BALANCED scan mode with following settings:
beaconManager.setForegroundScanPeriod(5000L);
beaconManager.setForegroundBetweenScanPeriod(15000L);
I've noticed, that you are calling the scanLeDevice
method right after finishing a scan cycle, so BLE scan executes twice during the scan period. Could it cause any unexpected problems?
The second scan is intended to start a low power scan between scan cycles. This is intended, but it does cause the problem described in my last comment.
Is there simple way to try not to scan in betweenScanPeriod just to check if it solve the initial issue?
@zukopvd, here is a test release: https://github.com/AltBeacon/android-beacon-library/releases/tag/between-scan-limits
Not sure, but looks like works in similar way - at least both issues remains. Configuration:
beaconManager.setForegroundScanPeriod(1000L);
beaconManager.setForegroundBetweenScanPeriod(5000L);
beaconManager.setBackgroundScanPeriod(2000L);
beaconManager.setBackgroundBetweenScanPeriod(35000L);
@zukopvd, I have made a second change to that test release and verified that this time the scans remain off on the between scan cycle if the betweenScanPeriod < 6000 millis. When you test, make sure you re-download the aar file and change your gradle file to have the updated hash version here:
android-beacon-library:2.12-3-g4bf2d9f@aar
Looks better now. Here are the logs for the same configurations. With these configuration the foreground issue appears more rarely and I can avoid it in general just by changing values to 2000 and 6000.
Regarding the background issue: sometimes it takes more than 1 cycle to get the error but increasing of betweenScanPeriod doesn't make any improvements.
What about using the SCAN_MODE_BALANCED during background scanning periods? I've noticed that it much less intensive.
Glad to hear that makes a difference, @zukopvd.
My understanding of SCAN_MODE_BALANCED is that it simply cycles scanning on and off at a more rapid rate at the OS-level. And I doubt it would make a difference in blocking scans in the background as I have no reason to think the mode affects this blocking algorithm, but you ware welcome to try.
Since I don't have a this device to test with (is this the Huawei or Samsung device?), I would certainly appreciate it if you could experiment with some different settings to see if you can find a combination to solve the background problem.
If we could somehow figure out how to detect devices that behave this way, one option might be to never start more than one new scan in the background, and instead simply start a SCAN_MODE_LOW_POWER scan once when you first go to the background that lasts forever. But I have no idea how to detect such a device. Perhaps it is all Huawei devices with 6.0+?
In general, all of the code you probably want to change would be in CycledLeScannerForLollipop.java
Here are instructions for generating your own build.
You can bring down a copy of the library repo with:
git@github.com:AltBeacon/android-beacon-library.git
Then you can do a build by going into the android-beacon-library directory and running:
$ ./gradlew release -Prelease -x text
Then you can access the generated aar file for testing with your app at:
$ ls build/outputs/aar/*
@davidgyoung thanks a lot for your help! Hope I'll find the solution. Could you please share the source code for the latest test release (g4bf2d9f)? I think it should be a better start point for experiments.
By the way, all the logs I posted here are from Huawei - haven't an access to that Samsung for now.
Source code for the test release is here #558
@davidgyoung Hello. Just to update the progress. After different experiments I still have this issue. Even if I set the scanning to the LOW_POWER mode and never touch the scanner and BT adapter the error appears after 2-3 minutes of scanning. And I can't predict or catch this error anyhow.
It is hardly possible, but maybe Huawei EMUI developers support will reveal their background scanning rules.
Have you thought more about it lately? Any new suggestions?
So you are saying that you get the error message not just when you start scanning, but when scanning is turned on and left on for a period of time?
Yes, exactly. This is the most interesting thing I've discovered recently.
You might be able to reverse-engineer the algorithm by running a number of tests in a custom app doing a low latency BLE scan that starts as soon as the screen goes off by listening for Intent.ACTION_SCREEN_OFF. You can then log something to LogCat when scanning starts and watch the log for how long it takes for E/BtGatt.GattService: App 'package_name' is scanning too frequently on screen off
to appear.
I'd run this perhaps 5 times per scanning configuration to see if there is consistency. The goal woudl be a table that looks something like this:
EXAMPLE DATA ONLY. THESE ARE NOT REAL MEASUREMENTS:
Test run # Scan Periods Seconds before error seen
---------- ------------- ------------------
1 3000000/0 40
2 3000000/0 42
3 3000000/0 50
4 3000000/0 30
5 3000000/0 10
6 1100/0 50
7 1100/0 50
8 1100/0 30
9 1100/0 32
10 1100/0 50
...
Any progress on this issue? Has anyone tested this with the code from the pull request 450?
To my knowledge nobody with a Huawei device has done tests described above to help reverse engineering the algorithm. (Help would be appreciated!)
Scanning only when screen is on is an interesting workaround, but may not work on Android 8+ which limits broadcast intents for this event for apps not running.
I have duplicated this issue on another Huawei P9 Lite VNS-L21 with Android 7.0 and build number VNS-L21C432B380.
10-26 18:10:36.220 13378 13378 D CycledLeScannerForLollipop: starting non-filtered scan in SCAN_MODE_LOW_LATENCY
10-26 18:10:36.220 15419 15447 D BluetoothAdapter: STATE_ON
10-26 18:10:36.220 13378 13378 D CycledLeScanner: Waiting to stop scan cycle for another 10000 milliseconds
10-26 18:10:36.227 13378 13466 D BluetoothAdapter: STATE_ON
10-26 18:10:36.227 1618 2116 I bt_att : GATT_Deregister gatt_if=7
10-26 18:10:36.227 1618 2116 I bt_att : GATT_Listen gatt_if=7
10-26 18:10:36.227 1618 2116 I bt_btm : BTM_BleUpdateAdvFilterPolicy
10-26 18:10:36.227 1618 2116 I bt_btm : BTM_ReadConnectability
10-26 18:10:36.227 1618 2116 I bt_btm : btm_ble_set_connectability mode=0x0 combined_mode=0x1
10-26 18:10:36.228 1866 1975 I BluetoothState: inactive bluetooth uid: 10126, pid:15419, reason:BLE_SCAN
10-26 18:10:36.229 1866 1975 I BluetoothState: inactive bluetooth uid: 10126, pid:15419, reason:BLE_CONNECT
10-26 18:10:36.229 1866 1975 I BluetoothState: inactive bluetooth uid: 10126, pid:15419, reason:BLE_CONNECT
10-26 18:10:36.229 1866 1975 D BluetoothState: not find active bluetooth for inactive event uid: 10126, pid:15419, reason:BLE_CONNECT
10-26 18:10:36.230 13378 13378 D CycledLeScanner: Set a wakeup alarm to go off in 300000 ms: PendingIntent{81b0a2f: android.os.BinderProxy@ff7d83c}
10-26 18:10:36.230 13378 13378 D CycledLeScanner: Scan started
10-26 18:10:36.237 1866 1975 I BluetoothState: new active bluetooth uid: 10074, pid:13378, reason:BLE_CONNECT
10-26 18:10:36.237 1306 1517 W AlarmManager: mIsScreenOn is: false, WAKEUP alarm talarm.operation == null,package name is: android listenerTag is: *job.delay* creator uid is: 1000
10-26 18:10:36.238 1618 2078 I SendBroadcastPermission: action:android.bluetooth.GET_BLE_APP_NAME, mPermissionType:0
10-26 18:10:36.239 1306 1306 V AlarmManager: Received TIME_TICK alarm; rescheduling
10-26 18:10:36.240 1306 2756 W ActivityManager: Sending non-protected broadcast android.bluetooth.GET_BLE_APP_NAME from system 1618:com.android.bluetooth/1002 pkg com.android.bluetooth
10-26 18:10:36.249 1618 2078 D BtBLEAppInfoCollector: reportBLEAppInfo enter for ble app:DEAULT_STR
10-26 18:10:36.256 1618 1618 E Bth : BigDataReceiver:intent or context is null.
10-26 18:10:36.262 1618 2078 I BtGatt.JNI: gattClientRegisterAppNative(L997): gattClientRegisterAppNative, register_client begin
10-26 18:10:36.262 1618 2078 I BtGatt.JNI: gattClientRegisterAppNative(L1003): gattClientRegisterAppNative, register_client
10-26 18:10:36.262 1618 2078 I BtGatt.JNI: gattClientRegisterAppNative(L1005): gattClientRegisterAppNative, register_client finish
10-26 18:10:36.262 1618 2116 I bt_att : GATT_Register
10-26 18:10:36.262 1618 2116 D bt_att : UUID=[0x6594c906601843a386ff45c42f5fc6cf]
10-26 18:10:36.262 1618 2116 I bt_att : GATT_Register: allocated gatt_if=5
10-26 18:10:36.262 1618 2116 I bt_att : GATT_StartIf gatt_if=5
10-26 18:10:36.262 1618 2116 D bt_att : gatt_find_the_connected_bda start_idx=0
10-26 18:10:36.262 1618 2116 D bt_att : gatt_find_the_connected_bda found=0 found_idx=7
10-26 18:10:36.262 1618 1751 W bt_btif : HAL bt_gatt_callbacks->client->register_client_cb
10-26 18:10:36.265 1866 1975 I BluetoothState: new active bluetooth uid: 10074, pid:13378, reason:BLE_CONNECT
10-26 18:10:36.270 13378 13518 D BluetoothLeScanner: onClientRegistered() - status=0 clientIf=5 mClientIf=0
10-26 18:10:36.277 2614 3885 I Places : Converted 0 out of 7 WiFi scans
10-26 18:10:36.279 1618 2269 E Bth : G.GattService:App 'org.altbeacon.beaconreference' is scanning too frequently on screen off
Below are logs running tests with the reference app with no beacons transmitting in the vicinity.
Logs are filtered with: $ adb logcat | grep -e "CycledLeScannerForLollipop: starting" -e "is scanning too frequently on screen off" -e "BackgroundPowerSaver"
.
When you see the log line, BackgroundPowerSaver: setting background mode
that indicates I have turned the screen off on the Huawei device.
Test run with backgroundBetweenScanPeriod set to 10000 ms:
10-26 19:01:39.381 25569 25569 D BackgroundPowerSaver: activity paused: org.altbeacon.beaconreference.MonitoringActivity@e6c633e active activities: 0
10-26 19:01:39.381 25569 25569 D BackgroundPowerSaver: setting background mode
10-26 19:01:39.576 25569 25569 D CycledLeScannerForLollipop: starting filtered scan in SCAN_MODE_LOW_POWER
10-26 19:01:46.230 25569 25569 D CycledLeScannerForLollipop: starting non-filtered scan in SCAN_MODE_LOW_LATENCY
10-26 19:01:56.275 25569 25569 D CycledLeScannerForLollipop: starting filtered scan in SCAN_MODE_LOW_POWER
10-26 19:02:06.221 25569 25569 D CycledLeScannerForLollipop: starting non-filtered scan in SCAN_MODE_LOW_LATENCY
10-26 19:02:16.250 25569 25569 D CycledLeScannerForLollipop: starting filtered scan in SCAN_MODE_LOW_POWER
10-26 19:02:26.230 25569 25569 D CycledLeScannerForLollipop: starting non-filtered scan in SCAN_MODE_LOW_LATENCY
10-26 19:02:36.277 25569 25569 D CycledLeScannerForLollipop: starting filtered scan in SCAN_MODE_LOW_POWER
10-26 19:02:36.312 1618 1635 E Bth : G.GattService:App 'org.altbeacon.beaconreference' is scanning too frequently on screen off
10-26 19:02:46.229 25569 25569 D CycledLeScannerForLollipop: starting non-filtered scan in SCAN_MODE_LOW_LATENCY
10-26 19:02:46.269 1618 1634 E Bth : G.GattService:App 'org.altbeacon.beaconreference' is scanning too frequently on screen off
Test run with backgroundBetweenScanPeriod set to 30000 ms:
10-26 18:47:02.158 22709 22709 D BackgroundPowerSaver: setting background mode
10-26 18:47:03.035 22709 22709 D CycledLeScannerForLollipop: starting filtered scan in SCAN_MODE_LOW_POWER
10-26 18:47:06.244 22709 22709 D CycledLeScannerForLollipop: starting non-filtered scan in SCAN_MODE_LOW_LATENCY
10-26 18:47:16.276 22709 22709 D CycledLeScannerForLollipop: starting filtered scan in SCAN_MODE_LOW_POWER
10-26 18:47:46.226 22709 22709 D CycledLeScannerForLollipop: starting non-filtered scan in SCAN_MODE_LOW_LATENCY
10-26 18:47:56.272 22709 22709 D CycledLeScannerForLollipop: starting filtered scan in SCAN_MODE_LOW_POWER
10-26 18:48:26.234 22709 22709 D CycledLeScannerForLollipop: starting non-filtered scan in SCAN_MODE_LOW_LATENCY
10-26 18:48:36.277 22709 22709 D CycledLeScannerForLollipop: starting filtered scan in SCAN_MODE_LOW_POWER
10-26 18:48:36.311 1618 2078 E Bth : G.GattService:App 'org.altbeacon.beaconreference' is scanning too frequently on screen off
10-26 18:49:06.236 22709 22709 D CycledLeScannerForLollipop: starting non-filtered scan in SCAN_MODE_LOW_LATENCY
10-26 18:49:06.280 1618 1634 E Bth : G.GattService:App 'org.altbeacon.beaconreference' is scanning too frequently on screen off
10-26 18:49:16.274 22709 22709 D CycledLeScannerForLollipop: starting filtered scan in SCAN_MODE_LOW_POWER
10-26 18:49:16.326 1618 2269 E Bth : G.GattService:App 'org.altbeacon.beaconreference' is scanning too frequently on screen off
10-26 18:49:46.223 22709 22709 D CycledLeScannerForLollipop: starting non-filtered scan in SCAN_MODE_LOW_LATENCY
10-26 18:49:46.252 1618 18098 E Bth : G.GattService:App 'org.altbeacon.beaconreference' is scanning too frequently on screen off
10-26 18:49:56.245 22709 22709 D CycledLeScannerForLollipop: starting filtered scan in SCAN_MODE_LOW_POWER
10-26 18:49:56.275 1618 1634 E Bth : G.GattService:App 'org.altbeacon.beaconreference' is scanning too frequently on screen off
10-26 18:50:26.232 22709 22709 D CycledLeScannerForLollipop: starting non-filtered scan in SCAN_MODE_LOW_LATENCY
10-26 18:50:26.266 1618 2269 E Bth : G.GattService:App 'org.altbeacon.beaconreference' is scanning too frequently on screen off
Test run with backgroundBetweenScanPeriod set to 60000 ms:
10-26 18:54:24.953 24434 24434 D BackgroundPowerSaver: activity paused: org.altbeacon.beaconreference.MonitoringActivity@e6c633e active activities: 0
10-26 18:54:24.953 24434 24434 D BackgroundPowerSaver: setting background mode
10-26 18:54:25.761 24434 24434 D CycledLeScannerForLollipop: starting filtered scan in SCAN_MODE_LOW_POWER
10-26 18:54:56.229 24434 24434 D CycledLeScannerForLollipop: starting non-filtered scan in SCAN_MODE_LOW_LATENCY
10-26 18:55:06.279 24434 24434 D CycledLeScannerForLollipop: starting filtered scan in SCAN_MODE_LOW_POWER
10-26 18:56:06.232 24434 24434 D CycledLeScannerForLollipop: starting non-filtered scan in SCAN_MODE_LOW_LATENCY
10-26 18:56:16.275 24434 24434 D CycledLeScannerForLollipop: starting filtered scan in SCAN_MODE_LOW_POWER
10-26 18:57:16.231 24434 24434 D CycledLeScannerForLollipop: starting non-filtered scan in SCAN_MODE_LOW_LATENCY
10-26 18:57:16.273 1618 18098 E Bth : G.GattService:App 'org.altbeacon.beaconreference' is scanning too frequently on screen off
10-26 18:57:26.275 24434 24434 D CycledLeScannerForLollipop: starting filtered scan in SCAN_MODE_LOW_POWER
10-26 18:57:26.324 1618 1634 E Bth : G.GattService:App 'org.altbeacon.beaconreference' is scanning too frequently on screen off
10-26 18:58:26.235 24434 24434 D CycledLeScannerForLollipop: starting non-filtered scan in SCAN_MODE_LOW_LATENCY
10-26 18:58:26.269 1618 2269 E Bth : G.GattService:App 'org.altbeacon.beaconreference' is scanning too frequently on screen off
10-26 18:58:36.288 24434 24434 D CycledLeScannerForLollipop: starting filtered scan in SCAN_MODE_LOW_POWER
10-26 18:58:36.328 1618 18098 E Bth : G.GattService:App 'org.altbeacon.beaconreference' is scanning too frequently on screen off
Test run with backgroundBetweenScanPeriod set to 300000 ms (library default):
10-26 19:04:35.155 26209 26209 D BackgroundPowerSaver: activity paused: org.altbeacon.beaconreference.MonitoringActivity@e6c633e active activities: 0
10-26 19:04:35.155 26209 26209 D BackgroundPowerSaver: setting background mode
10-26 19:04:35.361 26209 26209 D CycledLeScannerForLollipop: starting filtered scan in SCAN_MODE_LOW_POWER
10-26 19:07:26.234 26209 26209 D CycledLeScannerForLollipop: starting non-filtered scan in SCAN_MODE_LOW_LATENCY
10-26 19:07:26.268 1618 1635 E Bth : G.GattService:App 'org.altbeacon.beaconreference' is scanning too frequently on screen off
10-26 19:07:36.280 26209 26209 D CycledLeScannerForLollipop: starting filtered scan in SCAN_MODE_LOW_POWER
10-26 19:07:36.303 1618 1634 E Bth : G.GattService:App 'com.commmutyble.commutyble' is scanning too frequently on screen off
10-26 19:07:36.316 1618 18098 E Bth : G.GattService:App 'org.altbeacon.beaconreference' is scanning too frequently on screen off
Based on the tests in the previous comment, I can conclude the following about the Huawei BLE scan limiting algorithm:
Based on subsequent tests, I also believe that the block on an app doing BLE scans can be cleared and counters/timers reset by turning the screen on. The phone does not have to be unlocked and the app doing the scanning does not have to be in the foreground.
A few other observations on Huawei-specific BLE scanning behaviors:
Thanks for replying to my question in Stackoverflow David. During my tests I came to about the same results. Basically you can say that Background Beacon Scanning is not possible with Huawei devices, right? Or do you see any hope in finding a workaround?
There is certainly an imperfect solution to his issue, the trick (for this library at least) is to find a strategy for dealing with this that is best for the most typical use case, and possibly offer configuration options for making it work differently for more specific use cases. The key part of a work-around is to limit the number of scans that can be started with the screen off (or the app being in the background, which is always true of the screen is off.)
One work-around strategy I tested so far is to detect if no beacons are currently in the vicinity, and if so, start a single filtered LOW_POWER scan in the background, leaving this single scan running forever until either the app comes back to the foreground (meaning that the screen must be on) or a beacon is detected. This strategy can be enabled in the Android Beacon Library on Huawei devices with these lines of code:
if (android.os.Build.MANUFACTURER.equalsIgnoreCase("Huawei")) {
Log.d(TAG, "Huawei device detected. Reducing background scan period to prevent blocking scans.");
beaconManager.setBackgroundBetweenScanPeriod(Long.MAX_VALUE);
}
The above works because the library automatically employs a LOW_POWER scan when between scan periods are in place in the background when no beacons are around, and the code above just makes that last forever.
The advantage of this approach is that beacon scans will continue forever in the background with this strategy in a way that does not use too much power, allowing detection of a beacon if one appears.
The disadvantages of this approach are:
On the Huawei test device I have (Huawei P9 Lite VNS-L21 with Android 7.0 and build number VNS-L21C432B380), detections in LOW_POWER mode are not quick at all. I have seen minutes pass before detections, although they are quick if you turn on the screen from a dark state.
This strategy won't help at all if beacons are around. Even when scanning in LOW_POWER mode, processing constant beacon detections in the background will use lots of battery, so it really cannot be employed for most use cases.
I did some tests with my Huawei Honor 9. I used a 100 ms Beacon and let a Foreground Background Service scan for several hours. These are the results:
Balanced Mode:
Low Power Mode:
Y-Axis: Time length last found X-Axis: Time
It seems for me that Huawei bind bluetooth scanning together with idle mode and it starts scanning for a moment on idle maintenance phase.
For my purpose this behaviour is really bad and makes Huawei devices completely not usable for my App.
Thanks for these data, @Fintasys. For these tests, did you start a single scan at time 0:00:00 let it run for hours? Or were you restarting scans repeatedly?
@davidgyoung I did scan continuously without restarting, so that I dont get blocked by any restrictions from Huawei because of too many restarts. I think about repeating these tests with restarting to see if there is a difference.
@Fintasys, please see this issue: https://github.com/AltBeacon/android-beacon-library/issues/526
If you are testing on Android 7, you may be having scans blocked by a different standard Android behavior. That one is not Huawei-specific.
@davidgyoung wow thank you, didn't came across that yet. I will definitely repeat my tests with restart scanning!
So I tested it again with balanced mode and restart scanning every 15 minutes. The result is really great!
So that means for example restart every 30 seconds is too often for Huawei and permanent scanning will be blocked by Android 7 after around 30 minutes.
Could you figure out what the minimum restarting time is about at Huawei?
By the way, actually I also tested Samsung Galaxy & Sony Devices before and I couldn't find the behaviour of Android 7 which you describe in #526
Wow. I am surprised to see these results. In my Huawei tests, I always saw scanning blocked in the background when restarting at rates of 10 sec/30 sec /60 sec/ 5 min. I will repeat will 15 min to see if I can reproduce.
One difference in my tests with the library is that it actually switches back and forth between LOW_LATENCY and LOW_POWER scans on the cycle above as it goes from scan period to between scan period. (So the number of scans started is effectively doubled). I will also test if a scanPeriod/betweenScanPeriod 15 min/15min can reproduce your results.
On the Samsung Galaxy & Sony Devices you tested, are you sure they has Android 7+ and not Android 6.x?
Unfortunately, I cannot reproduce the results of @Fintasys posted yesterday where background scans restarted every 15 minutes ran successfully.
If I use the reference app with the following mods:
beaconManager.setBackgroundBetweenScanPeriod(30*60*1000l);
beaconManager.setBackgroundScanPeriod(10*1000l);
Then run it on the phone, and quickly turn off the screen I see from the logs that the first scan started immediately after going into the background starts successfully, but the next one 30 minutes later (at 17:55:43) is blocked.
@Fintasys, are you sure your testing is even reproducing the "scanning too frequently on screen off" problem if you try to start scans more often in the background?
$ adb logcat | grep -e "CycledLeScannerForLollipop: starting" -e "is scanning too frequently on screen off" -e "BackgroundPowerSaver"
11-08 17:25:37.587 21822 21822 D BackgroundPowerSaver: activity paused: org.altbeacon.beaconreference.MonitoringActivity@7a4b875 active activities: 0
11-08 17:25:37.587 21822 21822 D BackgroundPowerSaver: setting background mode
11-08 17:25:38.394 21822 21822 D CycledLeScannerForLollipop: starting filtered scan in SCAN_MODE_LOW_POWER
11-08 17:25:38.885 21822 21822 D BackgroundPowerSaver: activity resumed: org.altbeacon.beaconreference.MonitoringActivity@7a4b875 active activities: 1
11-08 17:25:39.408 21822 21822 D CycledLeScannerForLollipop: starting non-filtered scan in SCAN_MODE_LOW_LATENCY
11-08 17:25:43.071 21822 21822 D BackgroundPowerSaver: activity paused: org.altbeacon.beaconreference.MonitoringActivity@7a4b875 active activities: 0
11-08 17:25:43.071 21822 21822 D BackgroundPowerSaver: setting background mode
11-08 17:25:43.857 21822 21822 D CycledLeScannerForLollipop: starting filtered scan in SCAN_MODE_LOW_POWER
11-08 17:55:43.886 21822 21822 D CycledLeScannerForLollipop: starting non-filtered scan in SCAN_MODE_LOW_LATENCY
11-08 17:55:43.935 11438 11503 E Bth : G.GattService:App 'org.altbeacon.beaconreference' is scanning too frequently on screen off
11-08 17:55:53.953 21822 21822 D CycledLeScannerForLollipop: starting filtered scan in SCAN_MODE_LOW_POWER
11-08 17:55:53.982 11438 11449 E Bth : G.GattService:App 'org.altbeacon.beaconreference' is scanning too frequently on screen off
Letting this test run a bit longer, I see the next two scans were allowed to start:
11-08 18:25:53.977 21822 21822 D CycledLeScannerForLollipop: starting non-filtered scan in SCAN_MODE_LOW_LATENCY
11-08 18:26:04.028 21822 21822 D CycledLeScannerForLollipop: starting filtered scan in SCAN_MODE_LOW_POWER
I waited 30 minutes more but the app was not running. The Huawei ActivityManager had killed it. Nice. This is a separate issue, so I won't focus on it too much here, but it appears a custom mod is killing an app running in the background for some reason. In this case, this happened after about 80 minutes in the background.
$ adb logcat | grep 21822
11-08 18:34:40.885 1297 4623 I ActivityManager: Killing 21822:org.altbeacon.beaconreference/u0a129 (adj 0): stop org.altbeacon.beaconreferencefrom pid 31708by app
11-08 18:34:40.887 1297 4623 D ActivityManager: cleanUpApplicationRecord -- 21822
@davidgyoung seems we have a different testing environment. Actually I'm not using the beacon library for testing, just a a plain background service which I make foreground to not to be killed by any cleaning app or OS. Also I don't have my phone somehow plugged in to any cable. I just scanning for beacons and when my beacon is found I write an entry into a log file on the sdcard. I didn't check the logcat entries during these tests.
Regarding Samsung and Sony tests on Android 7, I'm sorry I mistaked. I tested it with restarting every 30 seconds, so I couldn't notice it to be blocked after 30 minutes.
That is quite different. I wonder if the foreground service makes it immune from this Huawei screen off optimization. You can look at LogCat over WiFi so you can run your tests without a cable connected. Could you try this with a more rapid scan cycle and see if you ever get the "is scanning too frequently on screen off" message? If you can't see it, then we are comparing apples and oranges here.
http://stuffandtech.blogspot.co.at/2012/03/android-quick-tip-adb-over-wifi.html
Of course I got the message with "scanning too frequently on screen off" that was the reason why I started to investigate about Huawei devices and was looking for help on Stackoverflow. My regular interval was 30 seconds back then. I'm currently repeating the the test with 5 seconds and 3 seconds beacon. I will let you know once I've got the results.
Thank you for the hint with remote debugging, didn't know it's build in meanwhile!
So, sorry for late answer. I did a lot of testing too make sure my results are correct.
I will stop investigating more about the "too frequently" message since it's working for me now.
Hello, I'm in the same situation, but I'm using a foreground service. I need low latency, so I'm using this configuration:
beaconManager.setForegroundBetweenScanPeriod(25 * 1000L);
beaconManager.setForegroundScanPeriod(5 * 1000L);
I get always the 'scanning too frequently' message. No solution?
I suspect the best workaround is to simply not restart scanning. Either set the betweeenScanPeriod to max long, or the scanPeriod to max long. This will leave scanning on constantly (either in low power mode for the between scan period) or high power mode for the scan period. It is switching back and forth that causes trouble on Huawei.
You will still get at least one callback on first beacon detection in the between scan period, so this could work.
@davidgyoung It's not working.. Always the same message
@Salvatore-Giordano, could you link to a logcat excerpt that shows your test results?
If you have a use case that allows a foreground service, I have verified that #663 will resolve this issue on the Huawei P9 Lite.
Hi @davidgyoung - would you be able to share the sample code that you used to verify that #663 solves the issue on the Huawei P9 Lite? Running into similar issues for another device, and it would be better to test with the same ref app.
Many thanks in advance,
Expected behavior
An application should be able to detect beacon region exit or entrance regardless of the application state: either foreground or background.
Actual behavior
When an application is in the background mode and screen is locked after some iterations of BeaconManager's scanning you can see the following error in logs:
E/BtGatt.GattService: App 'package_name' is scanning too frequently on screen off
After that each subsequent iteration causes the same error. After first appearance of this error exit from beacon's region may happen (if was entered previously) and no more any region entrance can be detected.
Steps to reproduce this behavior
Configure the BeaconManager for background scanning like that:
Start the application
Go to the background using "Home" button
Lock the device's screen
See device's logs by tag "scan" without package filters
Mobile device model and OS version
Samsung Galaxy S7 (Android 7.0) Huawei Honor 8 (Android 7.0)
Android Beacon Library version
2.11
As I know it is a quite common issue related to Android's N DOZE mode. Some other beacon manufacturers (kontaktio, estimote) faced the same issue (with exact same case and error) lately. Mostly, the following official restriction mentioned: "Since Nougat, every application is allowed to start/stop BLE scan a maximum of 5 times per 30s." but with the AltBeacon library the issue occurs even if I configure the BeaconManager like that:
I've read issues #506, #509 and #512 but didn't found working solution. I really like AltBeacon library, it works so great but this issue totally confused me. Please, help. Maybe I missed something.
Thank you!
IMPORTANT: This forum is reserved for feature requests or reproducible bugs with the library itself. If you need help with using the library with your project, please open a new question on StackOverflow.com.