Android O - Failed attempting to start service: BeaconIntentProcessor

[daniel-pulseid]

Expected behavior

Using "android-beacon-library-reference" app on Nexus 5X running with Android 8.0.0
Using the library : android-beacon-library-2.12-beta2.aar

Click "Start Ranging" button -->> display Beacon information near me
Change app's status to background and wait until app starts ranging near me again.

I want to see the beacon information near me when app is background. In other words, I am expecting the following callback should be invoked :

public void onBeaconServiceConnect() {
Log.i("Log","The first beacon " + firstBeacon.toString() + " is about " + firstBeacon.getDistance() + " meters away.");
}

Actual behavior

10~15 minutes later after app went background mode, I was able to see a lot logs being display, scanning beacon near me, but the callback function (i.e. onBeaconServiceConnect()) was not called because there was an error :

2184-2184/org.altbeacon.beaconreference E/Callback: Failed attempting to start service: org.altbeacon.beaconreference/org.altbeacon.beacon.BeaconIntentProcessor

Steps to reproduce this behavior

Download : android-beacon-library-reference" app
Import the latest library : android-beacon-library-2.12-beta2.aar

a. Changes :
BeaconReferenceApplication.java

onCreate{
beaconManager.getBeaconParsers().clear();
beaconManager.getBeaconParsers().add(new BeaconParser().
setBeaconLayout("m:2-3=0215,i:4-19,i:20-21,i:22-23,p:24-24,d:25-25"));
beaconManager.setEnableScheduledScanJobs(true);
}

RangingActivity.java

@OverRide
onCreate {
beaconManager.bind(this);
beaconManager.setDebug(true); // add this to see logs
}

@Override 
protected void onDestroy() {
    super.onDestroy();
    //beaconManager.unbind(this);  // block this to prevent "beaconManager.unbind(this)"
}

b. Results : Fail

10~15 minutes later after app went background mode, I was able to see a lot logs being display, scanning several beacons near me, but the callback function (i.e. onBeaconServiceConnect()) was not called because there was an error :

2184-2184/org.altbeacon.beaconreference E/Callback: Failed attempting to start service: org.altbeacon.beaconreference/org.altbeacon.beacon.BeaconIntentProcessor

c. Logcat :
It shows the logs that beacons near me were scanned but it failed to attempt to start service:

07-19 14:50:18.884 2184-12484/org.altbeacon.beaconreference D/RangeState: adding id1: 25359ac6-acfe-8fe5-92c7-a70f234704aa id2: 63593 id3: 63593 to existing range for: org.altbeacon.beacon.service.RangedBeacon@6b84a9a
07-19 14:50:18.903 2184-2184/org.altbeacon.beaconreference D/CycledLeScannerForLollipop: got record
07-19 14:50:18.904 2184-12482/org.altbeacon.beaconreference D/BeaconParser: Ignoring pdu type 01
07-19 14:50:18.904 2184-12482/org.altbeacon.beaconreference D/BeaconParser: Processing pdu type FF: 02011a1aff4c00021525359ac6acfe8fe592c7a70f234704aaf869f869c50000000000000000000000000000000000000000000000000000000000000000 with startIndex: 5, endIndex: 29
07-19 14:50:18.904 2184-12482/org.altbeacon.beaconreference D/BeaconParser: This is a recognized beacon advertisement -- 02 15 seen
07-19 14:50:18.904 2184-12482/org.altbeacon.beaconreference D/BeaconParser: Bytes are: 02011a1aff4c00021525359ac6acfe8fe592c7a70f234704aaf869f869c50000000000000000000000000000000000000000000000000000000000000000
07-19 14:50:18.906 2184-12482/org.altbeacon.beaconreference D/ScanHelper: Beacon packet detected for: id1: 25359ac6-acfe-8fe5-92c7-a70f234704aa id2: 63593 id3: 63593 with rssi -78
07-19 14:50:18.907 2184-12482/org.altbeacon.beaconreference D/ScanHelper: beacon detected : id1: 25359ac6-acfe-8fe5-92c7-a70f234704aa id2: 63593 id3: 63593
07-19 14:50:18.907 2184-12482/org.altbeacon.beaconreference D/ScanHelper: looking for ranging region matches for this beacon
07-19 14:50:18.907 2184-12482/org.altbeacon.beaconreference D/ScanHelper: matches ranging region: id1: null id2: null id3: null
07-19 14:50:18.908 2184-12482/org.altbeacon.beaconreference D/RangeState: adding id1: 25359ac6-acfe-8fe5-92c7-a70f234704aa id2: 63593 id3: 63593 to existing range for: org.altbeacon.beacon.service.RangedBeacon@6b84a9a
07-19 14:50:18.915 2184-2184/org.altbeacon.beaconreference D/CycledLeScannerForLollipop: got record
07-19 14:50:18.916 2184-12483/org.altbeacon.beaconreference D/BeaconParser: Ignoring pdu type 01
07-19 14:50:18.916 2184-12483/org.altbeacon.beaconreference D/BeaconParser: Processing pdu type FF: 02010607ff4c0010020b00000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000 with startIndex: 5, endIndex: 10
07-19 14:50:18.916 2184-12483/org.altbeacon.beaconreference D/BeaconParser: This is not a matching Beacon advertisement. (Was expecting 02 15. The bytes I see are: 02010607ff4c0010020b00000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000
07-19 14:50:18.924 2184-2184/org.altbeacon.beaconreference D/CycledLeScannerForLollipop: got record
07-19 14:50:18.925 2184-12480/org.altbeacon.beaconreference D/BeaconParser: Ignoring pdu type 01
07-19 14:50:18.925 2184-12480/org.altbeacon.beaconreference D/BeaconParser: Processing pdu type FF: 0201001aff4c000215c9bb8af20317492688f05796bbdc2f3200160017c80000000000000000000000000000000000000000000000000000000000000000 with startIndex: 5, endIndex: 29
07-19 14:50:18.925 2184-12480/org.altbeacon.beaconreference D/BeaconParser: This is a recognized beacon advertisement -- 02 15 seen
07-19 14:50:18.925 2184-12480/org.altbeacon.beaconreference D/BeaconParser: Bytes are: 0201001aff4c000215c9bb8af20317492688f05796bbdc2f3200160017c80000000000000000000000000000000000000000000000000000000000000000
07-19 14:50:18.927 2184-12480/org.altbeacon.beaconreference D/ScanHelper: Beacon packet detected for: id1: c9bb8af2-0317-4926-88f0-5796bbdc2f32 id2: 22 id3: 23 with rssi -62
07-19 14:50:18.927 2184-12480/org.altbeacon.beaconreference D/ScanHelper: beacon detected : id1: c9bb8af2-0317-4926-88f0-5796bbdc2f32 id2: 22 id3: 23
07-19 14:50:18.928 2184-12480/org.altbeacon.beaconreference D/ScanHelper: looking for ranging region matches for this beacon
07-19 14:50:18.928 2184-12480/org.altbeacon.beaconreference D/ScanHelper: matches ranging region: id1: null id2: null id3: null
07-19 14:50:18.928 2184-12480/org.altbeacon.beaconreference D/RangeState: adding id1: c9bb8af2-0317-4926-88f0-5796bbdc2f32 id2: 22 id3: 23 to existing range for: org.altbeacon.beacon.service.RangedBeacon@4edfcb
07-19 14:50:18.971 2184-2184/org.altbeacon.beaconreference D/CycledLeScannerForLollipop: got record
07-19 14:50:18.972 2184-12479/org.altbeacon.beaconreference D/BeaconParser: Ignoring pdu type 01
07-19 14:50:18.973 2184-12479/org.altbeacon.beaconreference D/BeaconParser: Processing pdu type FF: 02011a1aff4c00021525359ac6acfe8fe592c7a70f234704aaf869f869c50000000000000000000000000000000000000000000000000000000000000000 with startIndex: 5, endIndex: 29
07-19 14:50:18.973 2184-12479/org.altbeacon.beaconreference D/BeaconParser: This is a recognized beacon advertisement -- 02 15 seen
07-19 14:50:18.973 2184-12479/org.altbeacon.beaconreference D/BeaconParser: Bytes are: 02011a1aff4c00021525359ac6acfe8fe592c7a70f234704aaf869f869c50000000000000000000000000000000000000000000000000000000000000000
07-19 14:50:18.977 2184-12479/org.altbeacon.beaconreference D/ScanHelper: Beacon packet detected for: id1: 25359ac6-acfe-8fe5-92c7-a70f234704aa id2: 63593 id3: 63593 with rssi -78
07-19 14:50:18.978 2184-12479/org.altbeacon.beaconreference D/ScanHelper: beacon detected : id1: 25359ac6-acfe-8fe5-92c7-a70f234704aa id2: 63593 id3: 63593
07-19 14:50:18.979 2184-12479/org.altbeacon.beaconreference D/ScanHelper: looking for ranging region matches for this beacon
07-19 14:50:18.980 2184-12479/org.altbeacon.beaconreference D/ScanHelper: matches ranging region: id1: null id2: null id3: null
07-19 14:50:18.981 2184-12479/org.altbeacon.beaconreference D/RangeState: adding id1: 25359ac6-acfe-8fe5-92c7-a70f234704aa id2: 63593 id3: 63593 to existing range for: org.altbeacon.beacon.service.RangedBeacon@6b84a9a
07-19 14:50:18.989 2184-2184/org.altbeacon.beaconreference I/ScanJob: Scan job runtime expired
07-19 14:50:18.990 2184-2184/org.altbeacon.beaconreference D/CycledLeScanner: stop called
07-19 14:50:18.990 2184-2184/org.altbeacon.beaconreference D/CycledLeScanner: disabling scan
07-19 14:50:18.993 2184-2184/org.altbeacon.beaconreference D/CycledLeScanner: Done with scan cycle
07-19 14:50:18.994 2184-2184/org.altbeacon.beaconreference D/ScanHelper: Calling ranging callback
07-19 14:50:18.995 2184-2184/org.altbeacon.beaconreference D/RunningAverageRssiFilter: Running average mRssi based on 1 measurements: -94.0
07-19 14:50:18.995 2184-2184/org.altbeacon.beaconreference D/RangedBeacon: calculated new runningAverageRssi: -94.0
07-19 14:50:18.996 2184-12478/org.altbeacon.beaconreference D/CycledLeScannerForLollipop: Stopping LE scan on scan handler
07-19 14:50:18.999 2184-12478/org.altbeacon.beaconreference D/BluetoothAdapter: isLeEnabled(): ON
07-19 14:50:19.006 2184-2184/org.altbeacon.beaconreference D/RunningAverageRssiFilter: Running average mRssi based on 68 measurements: -62.351851851851855
07-19 14:50:19.007 2184-2184/org.altbeacon.beaconreference D/RangedBeacon: calculated new runningAverageRssi: -62.351851851851855
07-19 14:50:19.010 2184-2184/org.altbeacon.beaconreference D/RunningAverageRssiFilter: Running average mRssi based on 1 measurements: -85.0
07-19 14:50:19.010 2184-2184/org.altbeacon.beaconreference D/RangedBeacon: calculated new runningAverageRssi: -85.0
07-19 14:50:19.012 2184-2184/org.altbeacon.beaconreference D/RunningAverageRssiFilter: Running average mRssi based on 2 measurements: -72.5
07-19 14:50:19.013 2184-2184/org.altbeacon.beaconreference D/RangedBeacon: calculated new runningAverageRssi: -72.5
07-19 14:50:19.017 2184-2184/org.altbeacon.beaconreference D/RunningAverageRssiFilter: Running average mRssi based on 147 measurements: -81.47863247863248
07-19 14:50:19.017 2184-2184/org.altbeacon.beaconreference D/RangedBeacon: calculated new runningAverageRssi: -81.47863247863248
07-19 14:50:19.020 2184-2184/org.altbeacon.beaconreference D/RunningAverageRssiFilter: Running average mRssi based on 2 measurements: -76.0
07-19 14:50:19.021 2184-2184/org.altbeacon.beaconreference D/RangedBeacon: calculated new runningAverageRssi: -76.0
07-19 14:50:19.022 2184-2184/org.altbeacon.beaconreference D/Callback: attempting callback via intent: ComponentInfo{org.altbeacon.beaconreference/org.altbeacon.beacon.BeaconIntentProcessor}
07-19 14:50:19.025 2184-2184/org.altbeacon.beaconreference D/CurveFittedDistanceCalculator: calculating distance based on mRssi of -94.0 and txPower of -59
07-19 14:50:19.025 2184-2184/org.altbeacon.beaconreference D/CurveFittedDistanceCalculator: avg mRssi: -94.0 distance: 11.253807081163577
07-19 14:50:19.027 2184-2184/org.altbeacon.beaconreference D/CurveFittedDistanceCalculator: calculating distance based on mRssi of -62.351851851851855 and txPower of -56
07-19 14:50:19.028 2184-2184/org.altbeacon.beaconreference D/CurveFittedDistanceCalculator: avg mRssi: -62.351851851851855 distance: 1.4378814927006
07-19 14:50:19.030 2184-2184/org.altbeacon.beaconreference D/CurveFittedDistanceCalculator: calculating distance based on mRssi of -85.0 and txPower of -74
07-19 14:50:19.030 2184-2184/org.altbeacon.beaconreference D/CurveFittedDistanceCalculator: avg mRssi: -85.0 distance: 1.6523893176312807
07-19 14:50:19.031 2184-2184/org.altbeacon.beaconreference D/CurveFittedDistanceCalculator: calculating distance based on mRssi of -72.5 and txPower of -64
07-19 14:50:19.031 2184-2184/org.altbeacon.beaconreference D/CurveFittedDistanceCalculator: avg mRssi: -72.5 distance: 1.5510217638214505
07-19 14:50:19.031 2184-2184/org.altbeacon.beaconreference D/CurveFittedDistanceCalculator: calculating distance based on mRssi of -81.47863247863248 and txPower of -59
07-19 14:50:19.031 2184-2184/org.altbeacon.beaconreference D/CurveFittedDistanceCalculator: avg mRssi: -81.47863247863248 distance: 4.51457928344807
07-19 14:50:19.032 2184-2184/org.altbeacon.beaconreference D/CurveFittedDistanceCalculator: calculating distance based on mRssi of -76.0 and txPower of -52
07-19 14:50:19.032 2184-2184/org.altbeacon.beaconreference D/CurveFittedDistanceCalculator: avg mRssi: -76.0 distance: 6.428136301754578
07-19 14:50:19.034 2184-2184/org.altbeacon.beaconreference E/Callback: Failed attempting to start service: org.altbeacon.beaconreference/org.altbeacon.beacon.BeaconIntentProcessor
07-19 14:50:19.034 2184-2184/org.altbeacon.beaconreference D/CycledLeScanner: Scanning disabled.
07-19 14:50:19.034 2184-2184/org.altbeacon.beaconreference D/CycledLeScanner: cancel wakeup alarm: PendingIntent{be3df8d: android.os.BinderProxy@12e60ab}
07-19 14:50:19.036 2184-2184/org.altbeacon.beaconreference D/CycledLeScanner: Set a wakeup alarm to go off in 9223372036837285964 ms: PendingIntent{be3df8d: android.os.BinderProxy@12e60ab}
07-19 14:50:19.036 2184-2184/org.altbeacon.beaconreference D/CycledLeScanner: Destroying
07-19 14:50:19.037 2184-12478/org.altbeacon.beaconreference D/CycledLeScanner: Quitting scan thread
07-19 14:50:19.038 2184-2184/org.altbeacon.beaconreference D/ScanJob: Scanning stopped
07-19 14:50:19.099 2184-2184/org.altbeacon.beaconreference D/MonitoringStatus: saveMonitoringStatusIfOn()
07-19 14:50:19.101 2184-2184/org.altbeacon.beaconreference D/ScanJob: Checking to see if we need to start a passive scan
07-19 14:50:19.106 2184-2184/org.altbeacon.beaconreference I/ScanJob: We are inside a beacon region. We will not scan between cycles.
07-19 14:50:19.113 2184-2191/org.altbeacon.beaconreference I/zygote64: Waiting for a blocking GC ObjectsAllocated
07-19 14:50:19.129 2184-2191/org.altbeacon.beaconreference I/zygote64: WaitForGcToComplete blocked for 16.132ms for cause ObjectsAllocated

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.

[davidgyoung]

@daniel-pulseid, thank you for this report. A few questions:

• What is the build number of you Android O install?
• For this test, how long was the app running in the background?
• Were beacons always transmitting in the vicinity while the app was in the background?
• Did you ever get detections in your app during this test run, either in the foreground or the background?

[daniel-pulseid]

@davidgyoung

I have already described the information on "Expected Behaviour" and "Actual Behaviour".

• What is the build number of you Android O install?
  Android 8.0.0 on Nexus5X device
• For this test, how long was the app running in the background?
  About 15 minutes
• Were beacons always transmitting in the vicinity while the app was in the background?
  Yes, Beacon was always transmitting its signal
• Did you ever get detections in your app during this test run, either in the foreground or the background?
  Yes, I used "android-beacon-library-reference" app from (https://github.com/AltBeacon/android-beacon-library-reference) and this app was ranging beacons around me in RangingActivity.java when app is foreground.Also, as you could see the logs, ScanHelper was able to scan a beacon,c9bb8af2-0317-4926-88f0-5796bbdc2f32 id2: 22 id3: 23, as below when app is background, but it failed attempting to start service ::

07-19 14:50:18.927 2184-12480/org.altbeacon.beaconreference D/ScanHelper: Beacon packet detected for: id1: c9bb8af2-0317-4926-88f0-5796bbdc2f32 id2: 22 id3: 23 with rssi -62
07-19 14:50:18.927 2184-12480/org.altbeacon.beaconreference D/ScanHelper: beacon detected : id1: c9bb8af2-0317-4926-88f0-5796bbdc2f32 id2: 22 id3: 23
07-19 14:50:18.928 2184-12480/org.altbeacon.beaconreference D/ScanHelper: looking for ranging region matches for this beacon
07-19 14:50:19.034 2184-2184/org.altbeacon.beaconreference E/Callback: Failed attempting to start service: org.altbeacon.beaconreference/org.altbeacon.beacon.BeaconIntentProcessor

[davidgyoung]

This problem appears to be caused by Android blocking the creation of an IntentService called BeaconIntentProcrssor when the app has been in the background for some period of time. I have not seen this problem using Android O developer preview 3 for the Nexus Player (fugu-opp3.170518.006-factory-d98a9a5c). However, the behavior seems consistent with the docs for the changes in Android O, so ai am unsure why I cannot reproduce.. I believe I have a workaround that I will post in a binary update later today.

[davidgyoung]

@daniel-pulseid and @Ch3D, please try this release to see if it makes this exception go away:

https://github.com/AltBeacon/android-beacon-library/releases/tag/2.12-beta3

The change uses a local broadcast intent to convert detections into notifier callbacks instead of a global broadcast intent and an IntentService, which appears to be blocked from running in some background cases. As I have not been able to reproduce this problem, please do confirm if it solves it for you.

See change details here: 16fb444

[Ch3D]

@davidgyoung thank you! I will try it later today

[daniel-pulseid]

@davidgyoung
Thank you for the new release (i.e. 2.12-beta3).
I have been testing this on Nexus 5X (Android 8.0.0) several times when app is in the foreground as well as background modes.
This version was able to able to scan beacons near me in both modes.
Thank you!

[Ch3D]

@davidgyoung I can confirm as well, it's working fine now on my Nexus 6P DP4
Thanks!

[davidgyoung]

Confirmed fixed per 16fb444

Perhaps the reason I could not reproduce is because I was still running developer preview 3. When I checked on Thursday, this was still the latest available, but I now see a preview 4 has been posted.