search

AltBeacon / android-beacon-library

Allows Android apps to interact with BLE beacons
Apache License 2.0
2.84k stars 836 forks source link

Fix Android 14 foreground service start after BOOT_COMPLETED #1165

Closed davidgyoung closed 11 months ago

davidgyoung commented 11 months ago

Android 14 introduced a change that restricts foreground service starts after BOOT_COMPLETED to only be allowed after the broadcast receiver event for BOOT_COMPLETED fires for the app.

Because of this, any app that tries to start beacon scanning with a foreground service enabled from Application.onCreate will fail, and the library will detect this and fall back to using the Job Scheduler. This did not happen on Android 12/13. As of those OS versions, starting up a foreground service after boot from Application.onCreate worked fine.

This change makes it so that the library will check for the previous failure to start the foreground service when handling the BOOT_COMPLETED event, and retry starting up the foreground service at that time.

I tested this on a Pixel 7 / Android 14 with the Kotlin reference app configured to use a foreground service. I rebooted the phone and captured the LogCat output, and visually confirmed the foreground service notification was displayed.

As you can see from the log below, the initial attempt to start the foreground service fails, 11:24:35.861 17785 17785 W BeaconManager: Foreground service blocked by ServiceStartNotAllowedException. Falling back to job scheduler and the retry from the BroadcastReceiver succeeds. 11:24:36.006 17785 17785 I BeaconManager: successfully started foreground beacon scanning service.

10-20 11:24:35.831 17785 17785 I BeaconManager: BeaconManager started up on pid 17785 named 'org.altbeacon.beaconreference' for application package 'org.altbeacon.beaconreference'.  isMainProcess=true
10-20 11:24:35.834 17785 17785 D BeaconParser: Parsing beacon layout: m:2-3=beac,i:4-19,i:20-21,i:22-23,p:24-24,d:25-25
10-20 11:24:35.835 17785 17785 D BeaconParser: API setBeaconLayout m:2-3=0215,i:4-19,i:20-21,i:22-23,p:24-24
10-20 11:24:35.835 17785 17785 D BeaconParser: Parsing beacon layout: m:2-3=0215,i:4-19,i:20-21,i:22-23,p:24-24
10-20 11:24:35.850 17785 17785 D BeaconManager: API Beacon parsers changed
10-20 11:24:35.850 17785 17785 D BeaconManager: API applySettings
10-20 11:24:35.850 17785 17785 D BeaconManager: Not synchronizing settings to service, as it has not started up yet
10-20 11:24:35.851 17785 17785 D CompatibilityChangeReporter: Compat change id reported: 160794467; UID 10276; state: ENABLED
10-20 11:24:35.853 17785 17785 D BeaconReference: Calling enableForegroundServiceScanning
10-20 11:24:35.853 17785 17785 D BeaconManager: API enableForegroundServiceScanning Notification(channel=beacon-ref-notification-id shortcut=null contentView=null vibrate=null sound=null defaults=0x0 flags=0x0 color=0x00000000 vis=PRIVATE)
10-20 11:24:35.853 17785 17785 D BeaconManager: API setEnableScheduledScanJobs false
10-20 11:24:35.853 17785 17785 W BeaconManager: Disabling ScanJobs on Android 8+ may disable delivery of beacon callbacks in the background unless a foreground service is active.
10-20 11:24:35.855 17785 17785 I ScanJob : Using immediateScanJobId from manifest: 208352939
10-20 11:24:35.856 17785 17785 I ScanJob : Using periodicScanJobId from manifest: 208352940
10-20 11:24:35.856 17785 17785 D BeaconReference: Back from  enableForegroundServiceScanning
10-20 11:24:35.856 17785 17785 D BeaconManager: API setEnableScheduledScanJobs false
10-20 11:24:35.856 17785 17785 W BeaconManager: Disabling ScanJobs on Android 8+ may disable delivery of beacon callbacks in the background unless a foreground service is active.
10-20 11:24:35.857 17785 17785 I ScanJob : Using immediateScanJobId from manifest: 208352939
10-20 11:24:35.857 17785 17785 I ScanJob : Using periodicScanJobId from manifest: 208352940
10-20 11:24:35.857 17785 17785 D BeaconManager: API setBackgroundBetweenScanPeriod 0
10-20 11:24:35.857 17785 17785 W BeaconManager: Setting a short backgroundBetweenScanPeriod has no effect on Android 8+, which is limited to scanning every ~15 minutes
10-20 11:24:35.857 17785 17785 D BeaconManager: API setBackgroundScanPeriod 1100
10-20 11:24:35.857 17785 17785 D BeaconManager: API startMonitoring id1: null id2: null id3: null
10-20 11:24:35.858 17785 17785 I BackgroundPowerSaver: We have inferred by application.onCreate in the call stack that we are in the background.
10-20 11:24:35.858 17785 17785 D BeaconManager: API setBackgroundModeIternal true
10-20 11:24:35.858 17785 17785 D BeaconManager: API updateScanPeriods
10-20 11:24:35.858 17785 17785 D BeaconManager: updating background flag to true
10-20 11:24:35.859 17785 17785 D BeaconManager: updating scan periods to 1100, 0
10-20 11:24:35.859 17785 17785 D BeaconManager: This consumer is not bound.  Binding now: org.altbeacon.beacon.BeaconManager$3@9d6823d
10-20 11:24:35.859 17785 17785 D BeaconManager: Binding to service
10-20 11:24:35.859 17785 17785 D BeaconManager: Running SDK 34? true.  Targeting SDK 34? true
10-20 11:24:35.859 17785 17785 D BeaconManager: Checking fine location permission as required for foreground service
10-20 11:24:35.859 17785 17785 I BeaconManager: Attempting to starting foreground beacon scanning service.
10-20 11:24:35.861 17785 17785 W BeaconManager: Foreground service blocked by ServiceStartNotAllowedException.  Falling back to job scheduler
10-20 11:24:35.861 17785 17785 D ScanJobScheduler: Applying settings to ScanJob
10-20 11:24:35.911 17785 17785 D MonitoringStatus: Not restoring monitoring state because it was recorded too many milliseconds ago: 2401139
10-20 11:24:35.911 17785 17785 D ScanState: Scan state restore regions: monitored=0 ranged=1
10-20 11:24:35.911 17785 17785 D ScanState: ranged regions: old=1 new=0
10-20 11:24:35.911 17785 17785 D ScanState: monitored regions: old=0 new=0
10-20 11:24:35.911 17785 17785 D ScanState: Stopping ranging region: id1: null id2: null id3: null
10-20 11:24:35.911 17785 17785 D ScanState: Updated state with 0 ranging regions and 0 monitoring regions.
10-20 11:24:35.919 17785 17785 D ScanState: Temp file is /data/user/0/org.altbeacon.beaconreference/files/android-beacon-library-scan-state-temp
10-20 11:24:35.919 17785 17785 D ScanState: Perm file is /data/user/0/org.altbeacon.beaconreference/files/android-beacon-library-scan-state
10-20 11:24:35.919 17785 17785 D MonitoringStatus: saveMonitoringStatusIfOn()
10-20 11:24:35.920 17785 17785 D ScanJobScheduler: Applying scan job settings with background mode true
10-20 11:24:35.920 17785 17785 D ScanJobScheduler: This is the first time we schedule a job and we are in background, set immediate scan flag to true in order to trigger the HW filter install.
10-20 11:24:35.920 17785 17785 D BeaconLocalBroadcastProcessor: Register calls: global=1
10-20 11:24:35.920 17785 17785 D ScanState: ScanState says background mode for ScanJob is true
10-20 11:24:35.920 17785 17785 D ScanJobScheduler: We just woke up in the background based on a new scan result or first run of the app. Start scan job immediately.
10-20 11:24:35.920 17785 17785 D ScanJobScheduler: We are not monitoring or ranging any regions.  We are going to cancel all scan jobs.
10-20 11:24:35.921 17785 17785 I ScanJob : Using immediateScanJobId from manifest: 208352939
10-20 11:24:35.921 17785 17785 I ScanJob : Using periodicScanJobId from manifest: 208352940
10-20 11:24:35.922 17785 17785 D ScanHelper: new ScanHelper
10-20 11:24:35.923 17785 17785 D CompatibilityChangeReporter: Compat change id reported: 263076149; UID 10276; state: ENABLED
10-20 11:24:35.928 17785 17785 D BluetoothAdapter: isLeEnabled(): ON
10-20 11:24:35.931 17785 17785 D BeaconManager: API startRangingBeacons id1: null id2: null id3: null
10-20 11:24:35.931 17785 17785 D BeaconManager: startRanging
10-20 11:24:35.931 17785 17785 D BeaconManager: API startRangingBeaconsInRegion id1: null id2: null id3: null
10-20 11:24:35.931 17785 17785 D BeaconManager: startRangingBeaconsInRegion
10-20 11:24:35.931 17785 17785 D ScanJobScheduler: Applying settings to ScanJob
10-20 11:24:35.944 17785 17785 D ScanState: Scan state restore regions: monitored=0 ranged=0
10-20 11:24:35.944 17785 17785 D ScanState: ranged regions: old=0 new=1
10-20 11:24:35.945 17785 17785 D ScanState: monitored regions: old=0 new=0
10-20 11:24:35.945 17785 17785 D ScanState: Starting ranging region: id1: null id2: null id3: null
10-20 11:24:35.945 17785 17785 D ScanState: Updated state with 1 ranging regions and 0 monitoring regions.
10-20 11:24:35.952 17785 17785 D ScanState: Temp file is /data/user/0/org.altbeacon.beaconreference/files/android-beacon-library-scan-state-temp
10-20 11:24:35.952 17785 17785 D ScanState: Perm file is /data/user/0/org.altbeacon.beaconreference/files/android-beacon-library-scan-state
10-20 11:24:35.952 17785 17785 D MonitoringStatus: saveMonitoringStatusIfOn()
10-20 11:24:35.953 17785 17785 D ScanJobScheduler: Applying scan job settings with background mode true
10-20 11:24:35.953 17785 17785 D ScanJobScheduler: This is the first time we schedule a job and we are in background, set immediate scan flag to true in order to trigger the HW filter install.
10-20 11:24:35.953 17785 17785 D BeaconLocalBroadcastProcessor: Register calls: global=1
10-20 11:24:35.953 17785 17785 D ScanState: ScanState says background mode for ScanJob is true
10-20 11:24:35.953 17785 17785 D ScanJobScheduler: We just woke up in the background based on a new scan result or first run of the app. Start scan job immediately.
10-20 11:24:35.953 17785 17785 D ScanJobScheduler: Scheduling immediate ScanJob to run in 0 millis
10-20 11:24:35.954 17785 17785 I ScanJob : Using immediateScanJobId from manifest: 208352939
10-20 11:24:35.954 17785 17785 D CompatibilityChangeReporter: Compat change id reported: 194532703; UID 10276; state: ENABLED
10-20 11:24:35.954 17785 17785 D CompatibilityChangeReporter: Compat change id reported: 253665015; UID 10276; state: ENABLED
10-20 11:24:35.956 17785 17785 D ScanJobScheduler: First immediate scan job scheduled successful, change the flag to false.
10-20 11:24:35.956 17785 17785 I ScanJob : Using periodicScanJobId from manifest: 208352940
10-20 11:24:35.956 17785 17785 W JobInfo : Requested interval +5m0s0ms for job 208352940 is too small; raising to +15m0s0ms
10-20 11:24:35.956 17785 17785 W JobInfo : Requested flex 0 for job 208352940 is too small; raising to +5m0s0ms
10-20 11:24:35.957 17785 17785 D ScanJobScheduler: Scheduling periodic ScanJob (job:208352940/org.altbeacon.beaconreference/org.altbeacon.beacon.service.ScanJob) to run every 300000 millis
10-20 11:24:35.991 17785 17785 D StartupBroadcastReceiver: onReceive called in startup broadcast receiver
10-20 11:24:35.991 17785 17785 I StartupBroadcastReceiver: Android Beacon Library restarted via ACTION_BOOT_COMPLETED
10-20 11:24:35.991 17785 17785 I StartupBroadcastReceiver: Foreground service startup failure detected.  We will retry starting now that we have received a BOOT_COMPLETED action.
10-20 11:24:35.991 17785 17785 I BeaconManager: unbinding all consumers for stategy failover
10-20 11:24:35.992 17785 17785 D BeaconManager: Unbinding
10-20 11:24:35.992 17785 17785 D BeaconManager: Not unbinding from scanning service as we are using scan jobs.
10-20 11:24:35.992 17785 17785 D BeaconManager: Before unbind, consumer count is 1
10-20 11:24:35.992 17785 17785 D BeaconManager: After unbind, consumer count is 0
10-20 11:24:35.992 17785 17785 I BeaconManager: Cancelling scheduled jobs after unbind of last consumer.
10-20 11:24:35.994 17785 17785 I ScanJob : Using immediateScanJobId from manifest: 208352939
10-20 11:24:35.996 17785 17785 I ScanJob : Using periodicScanJobId from manifest: 208352940
10-20 11:24:35.999 17785 17785 I BeaconManager: binding all consumers for strategy failover
10-20 11:24:36.000 17785 17785 D BeaconManager: Need to rebind for switch to foreground service
10-20 11:24:36.000 17785 17785 D BeaconManager: Binding to service
10-20 11:24:36.001 17785 17785 D BeaconManager: Running SDK 34? true.  Targeting SDK 34? true
10-20 11:24:36.001 17785 17785 D BeaconManager: Checking fine location permission as required for foreground service
10-20 11:24:36.001 17785 17785 I BeaconManager: Attempting to starting foreground beacon scanning service.
10-20 11:24:36.006 17785 17785 I BeaconManager: successfully started foreground beacon scanning service.
10-20 11:24:36.010 17785 17785 D BeaconManager: consumer count is now: 1
10-20 11:24:36.010 17785 17785 I BeaconManager: Done with failover
davidgyoung commented 11 months ago

@stephenruda can you please take look at this change and let me know your thoughts? I know you said your app already starts up the foreground service outside Application.onCreate so this is not an issue for you. But I would like your thoughts on the general approach. It would also be good to confirm this won't cause any trouble for your app.

Once I can get this merged I will roll a new library release with your change and this change.

stephenruda commented 11 months ago

@davidgyoung I think this is a nice solution. My application has battery optimizations disabled, which is an additional exemption for starting a foreground service from the background. So for me it didn't matter if I started the service in the Application.onCreate() before the BOOT_COMPLETE event because I was already exempt.

I did test your branch in my app under all conditions I could think of...

Everything is working exactly as expected. If I don't have battery optimizations disabled (so getting rid of my additional exemption), I see the exact same logs as you. It fails to start the service in the onCreate() and it successfully retries after the BOOT_COMPLETE event.

I think this does a good job of solving the problem and I don't see any issues - so I would say it is good to go!