Repeatingly STATE_ON and onClientRegistered()

aloz77 commented 6 years ago

Expected behavior

Ranging the iBeacons with didRangeBeaconsInRegion()

Actual behavior

When starting the app these lines appear repeatingly on logcat for some seconds or even minutes before the beacons are detected by didRangeBeaconsInRegion().

07-29 13:29:29.801 18315-18327/com.my.app D/BluetoothLeScanner: onClientRegistered() - status=0 clientIf=5
07-29 13:29:30.901 18315-18620/com.my.app D/BluetoothAdapter: STATE_ON
07-29 13:29:30.904 18315-18620/com.my.app D/BluetoothAdapter: STATE_ON
07-29 13:29:30.907 18315-18327/com.my.app D/BluetoothLeScanner: onClientRegistered() - status=0 clientIf=5
07-29 13:29:32.009 18315-18620/com.my.app D/BluetoothAdapter: STATE_ON
07-29 13:29:32.013 18315-18620/com.my.app D/BluetoothAdapter: STATE_ON

Steps to reproduce this behavior

Mobile device model and OS version

Nexus 7 2013, Android 6.0.1

Android Beacon Library version

Latest

aloz77 commented 6 years ago

The same issue happens on the reference app. Here are the cycling log entries with additional debug info:

07-29 14:09:02.658 5538-5538/org.altbeacon.beaconreference D/CycledLeScanner: Scan started
07-29 14:09:02.658 5538-5666/org.altbeacon.beaconreference D/BluetoothAdapter: STATE_ON
07-29 14:09:02.661 5538-5550/org.altbeacon.beaconreference D/BluetoothLeScanner: onClientRegistered() - status=0 clientIf=5
07-29 14:09:02.667 5538-7148/org.altbeacon.beaconreference D/BeaconIntentProcessor: got an intent to process
07-29 14:09:02.668 5538-7148/org.altbeacon.beaconreference D/BeaconIntentProcessor: got ranging data
07-29 14:09:03.658 5538-5538/org.altbeacon.beaconreference D/CycledLeScanner: Waiting to stop scan cycle for another 99 milliseconds
07-29 14:09:03.758 5538-5538/org.altbeacon.beaconreference D/CycledLeScanner: Done with scan cycle
07-29 14:09:03.758 5538-5538/org.altbeacon.beaconreference D/BeaconService: Calling ranging callback
07-29 14:09:03.758 5538-5538/org.altbeacon.beaconreference D/Callback: attempting callback via intent: ComponentInfo{org.altbeacon.beaconreference/org.altbeacon.beacon.BeaconIntentProcessor}
07-29 14:09:03.761 5538-5538/org.altbeacon.beaconreference D/CycledLeScanner: stopping bluetooth le scan
07-29 14:09:03.761 5538-5538/org.altbeacon.beaconreference D/CycledLeScannerForLollipop: Stopping scan
07-29 14:09:03.762 5538-5666/org.altbeacon.beaconreference D/CycledLeScannerForLollipop: Stopping LE scan on scan handler
07-29 14:09:03.762 5538-5538/org.altbeacon.beaconreference D/CycledLeScanner: starting a new scan cycle
07-29 14:09:03.763 5538-5666/org.altbeacon.beaconreference D/BluetoothAdapter: STATE_ON
07-29 14:09:03.766 5538-5538/org.altbeacon.beaconreference D/CycledLeScanner: starting a new bluetooth le scan
07-29 14:09:03.767 5538-5538/org.altbeacon.beaconreference D/CycledLeScannerForLollipop: starting non-filtered scan in SCAN_MODE_LOW_LATENCY
07-29 14:09:03.767 5538-5538/org.altbeacon.beaconreference D/CycledLeScanner: Waiting to stop scan cycle for another 1100 milliseconds

davidgyoung commented 6 years ago

These log lines are output by Android Bluetooth stack classes when a new scan is started. There is no way to control that these appear in the logs. They appear repeatedly because the library initiates scans on a regular cycle.

The lines to add noise to the log, but Android unfortunately provides no way to control this. Unless there is a more serious problem I am missing, I think this is simply expected.

aloz77 commented 6 years ago

There IS a serious problem. As long as these lines are cycling each 1100 ms no beacons are detected. As soon as they stop didRangeBeaconsInRegion() reports beacons (at least with my app own app, not yet found the difference to the reference app which keep showing these log lines forever).

davidgyoung commented 6 years ago

OK, Understood. So the core problem is that you are not getting beacon detections for some period of time after scanning starts. The log lines are simply a marker of what is happening.

Based on what I see in the logs, the Android bluetooth stack is actually not detecting any bluetooth devices during these scans. If it were, additional log lines would show up. Is it correct that the beacon devices that you detect later actually are transmitting during this period? Can you confirm with a second device?

aloz77 commented 6 years ago

Thank you, David! I tried it with Android 5.1 and Android 7 devices. On both devices the Reference App can't detect my beacons (blukii) at all.

I tried another Beacon Scanner apps. Some of them can detect my beacons after some time on Android 5 and 6. On Android 7 (Samsung S7) the detection works pretty fast and reliable.

I'm already using the layout setting like this:

beaconManager.getBeaconParsers().add(new BeaconParser().setBeaconLayout("m:2-3=0215,i:4-19,i:20-21,i:22-23,p:24-24"));

Are there any other tweaks for the altbeacon library to try in such a case?

davidgyoung commented 6 years ago

@aloz77, I just can't think of anything that would cause this that is specific to the library. For what you are seeing It is really very straightforward -- if the operating system sees a BLE packet, it reports it to the library, which is supposed to parse it if it matches a pattern, you get a callback.

The logs indicate the the operating system is not seeing any BLE packets for the period of time you captured.

I really doubt this has anything to do with the library, application code, or the OS version. It sounds to me like it is either a hardware issue on the phones where you see the problem, a custom operating system "enhancement" by the Android hardware manufacturer, or (much less likely) something about the beacon advertisement that makes it so the Samsung's bluetooth chip can detect it but the other devices' chips cannot.

aloz77 commented 6 years ago

Thank you, David! It looks like I can make the reference app finding at least some beacons by increasing the scan period.

beaconManager.setForegroundScanPeriod(3000);

Then I can see some of the beacons found each 3 seconds. May be too much radio noise? I'm just wondering the other apps like Beacon Scanner can provide better results on the same device and show changes each second for the most beacons.

aloz77 commented 6 years ago

Hi David! Setting a longer scantime seems to help significantly to detect some beacons. Would it be possible to start a permanent/endless scan and get beacons by didRangeBeaconsInRegion() as soon as they appear?

davidgyoung commented 6 years ago

Starting with version 2.10, if you set the between scan period to 0, once scanning goes on it stays on for any device capable of multiple non-distinct advertisements PR scan. Results are delivered every scan period, or 1.1 secs by default. Do you have the between scan period set to 0?

aloz77 commented 6 years ago

I didn't set the period between scans explicitely. The default value is 0 in foreground mode, isn't it?

davidgyoung commented 6 years ago

Yes, it is zero by default.

Actually, I missed the point that you are using the Nexus 7 2013 edition -- that is an important factor.

The Nexus 7 2013 edition is incapable of detecting multiple beacon advertisements in a single scan (I know this because I used to have one!) So once you detect a beacon you have to stop scanning and restart in order to detect it again. The change in version 2.10 mentioned in my last comment won't work on this device, because the device will automatically detect that only one packet can be detected per scan cycle, and the library will keep starting and stopping scanning at the rate of each scan period on the Nexus 7.

It is unclear why the Nexus 7 cannot detect your blukii beacon reliably in a 1.1 second cycle. A few possibilities:

Perhaps the blukii bacon is only transmitting once every few seconds to save battery?
Perhaps the beacon transmission radio power level is very low, making many of the signals lost to noise, and having only a low percentage of them received successfully. Even high power beacon packets are only received about 90% of the time.

The design of the library is to deliver beacon ranging results at the end of the scan cycle and not immediately when the packet is received. Other apps that use raw BLE scanning and deliver matching packets immediately (without waiting for a scan to end) will show faster results. So I understand that setting a longer cycle of 3 seconds or more will slow down your results. Unfortunately, this is a design constraint of the library -- it is really made two work with the default 1.1 second cycle, which works well with most beacons and devices. It may not work well with the combination of the Nexus 7 and the blukii setup you have.

aloz77 commented 6 years ago

Thank you, David! I'm now on ver. 2.11 of the library. Nexus 7 indeed detects mostly only one iBeacon per scan cycle. Sometimes however it detects two per cycle. Sometimes however it detects nothing for minutes. Sometimes stopping&starting Bluetooth helps to get it to work again immediately. Btw Blukii beacons are set to transmit each 500 ms. Strange behavior, but thank you, I think it's Nexus 7 2013 issue.

davidgyoung commented 6 years ago

Well, to be clear, the Nexus 7 can detect two different beacon identifiers in the same scan cycle. But it just will never tell you about two copies of the same advertisement (same beacon identifiers) detected in the same scan cycle. And the logic added in 2.10 I described above looks for this ever happening as a way of knowing that it is safe to leave the scanning on all the time.

AltBeacon / android-beacon-library