search

AltBeacon / android-beacon-library

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

ANR on using notification for background scans. #1009

Closed felipesaruhashi closed 3 years ago

felipesaruhashi commented 3 years ago

Expected behavior

Use notification background service without crashes(ANR).

Actual behavior

ANR in com.* PID: 6801 Reason: Context.startForegroundService() did not then call Service.startForeground(): ServiceRecord{82c695e u0 com.**/org.altbeacon.beacon.service.BeaconService

Steps to reproduce this behavior

public Notification makeNotification(Context context) {
   Intent stopIntent = new Intent(this, ActionStopLocationReceiver.class);
   PendingIntent stopPendingIntent = null;
   stopIntent.setAction(ActionStopLocationReceiver.ACTION_STOP);
   stopPendingIntent = PendingIntent.getBroadcast(this, 1, stopIntent, PendingIntent.FLAG_UPDATE_CURRENT);
   stopIntent.putExtra(ActionStopLocationReceiver.ACTION, ActionStopLocationReceiver.ACTION_STOP);

   Intent intent = new Intent(context, MainActivity.class);
   PendingIntent pendingIntent = PendingIntent.getActivity(context, 0, intent, PendingIntent.FLAG_UPDATE_CURRENT);

   NotificationCompat.Action stopAction = new NotificationCompat.Action.Builder(R.drawable.ic_stop_black_24dp, "stop", stopPendingIntent).build();

   if (Build.VERSION.SDK_INT >= Build.VERSION_CODES.O) {

     NotificationCompat.Builder builder = new NotificationCompat.Builder(this, NOTIFICATION_CHANNEL_ID)
       .setSmallIcon(R.drawable.ic_location_on_black_24dp)
       .setContentTitle("title")
       .setContentText("notification text")
       .setStyle(new NotificationCompat.BigTextStyle().bigText( "notification text" ))
       .addAction(stopAction)
       .setOngoing(true)
       .setAutoCancel(true);

     NotificationChannel channel = new NotificationChannel(NOTIFICATION_CHANNEL_ID, NOTIFICATION_CHANNEL_NAME, NotificationManager.IMPORTANCE_DEFAULT);
     channel.setDescription(NOTIFICATION_CHANNEL_DESCRIPTION);

     NotificationManager notificationManager = (NotificationManager) context.getSystemService(Context.NOTIFICATION_SERVICE);
     notificationManager.createNotificationChannel(channel);

     builder.setChannelId(channel.getId());

     return builder.build();
   } else {
     NotificationCompat.Builder mBuilder = new NotificationCompat.Builder(this, NOTIFICATION_CHANNEL_ID)
       .setSmallIcon(R.drawable.ic_location_on_black_24dp)
       .setOngoing(true)
       .setContentIntent(pendingIntent)
       .setContentTitle(this.getString(R.string.location_notification_title))
       .setStyle(new NotificationCompat.BigTextStyle().bigText(this.getString(R.string.location_notification_text)))
       .addAction(stopAction);

     return mBuilder.build();
   }
 }

public void startScanning() {
   if (beaconManager.getMonitoredRegions().size() == 0) {
     Notification notification = makeNotification(this);
     beaconManager.enableForegroundServiceScanning(notification, BEACON_NOTIFICATION_ID);

     beaconManager.setEnableScheduledScanJobs(false);

     beaconManager.setBackgroundBetweenScanPeriod(1000);
     beaconManager.setBackgroundScanPeriod(1000);

     backgroundPowerSaver = new BackgroundPowerSaver(this);

     region = new Region("backgroundRegion", null, null, null);
     regionBootstrap = new RegionBootstrap(this, region);
   }
 }

Mobile device model and OS version

Device: OnePlus 5T android: 10

Android Beacon Library version

2.17.1

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 commented 3 years ago

A similar issue #816 was found and fixed in early 2019, which is in the 2.17.1 release. It is unclear why you are still seeing this.

Can you please change your code to set beaconManager.setDebug(true); then capture a LogCat excerpt for 30 seconds prior to the crash?

felipesaruhashi commented 3 years ago

Hi! This bug is quite intermittent, took me a while to reproduce it.

Here is the log:

error_alt_beacon_log.txt.zip

davidgyoung commented 3 years ago

@felipesaruhashi, thank you for the log. Unfortuantely, the log does not contain any timestamps, so I cannot tell the timings of when things are happening. However, it appears that something in your custom app is starting and stopping beacon scanning repeatedly binding and unbinding to the beacon scanning service causing it to start up and shut down repeatedly. See below.

I see that two different classes are used to initiate scanning: RegionBootstrap (a built-in library class) and com.testing.location.LocationEngine. The crash looks like it is caused because a scan is started (triggering the foreground service to start), and then quickly stopped before it has a chance to register the foreground service with the operating system. The operating system then crashes the app because it failed to register the foreground service in a timely manner. This only happens because the scanning service was shut down so quickly after starting.

I believe the reason your app is experiencing this issue is that this is a very unusual use of the APIs, and the library just isn't designed to handle such rapid start/stop operations on the scanning service. A good rule of thumb is that you should not stop/start the scanning service (by starting/stopping monitoring or binding to the library or enabling/disabling RegionBootstrap) more than every ~30 seconds. If you start and stop more often you will likely see problems like this.

In theory we could fix the library to handle this more elegantly, but that is surprisingly hard to do given the asynchronous nature of starting and stopping Android services.

I'd recommend you review how your app starts and stops scanning and add code to prevent it from doing so more often than every ~30 seconds. Since the specifics of how your app is designed is a custom app programming issue, the proper forum for assistance with troubleshooting your app is on StackOverflow.com. Please reserve this issue for how the library behaves when the APIs are used in this manner.

$ grep -C 3  binding  error_alt_beacon_log.txt
com.testing.app.debug D/BeaconParser: Processing pdu type FF: 02011a020a0c0cff4c001007091f63adc4a71800000000000000000000000000000000000000000000000000000000000000000000000000000000000000 with startIndex: 8, endIndex: 18
com.testing.app.debug D/BeaconParser: This is not a matching Beacon advertisement. (Was expecting 4c 00 02 15.  The bytes I see are: 02011a020a0c0cff4c001007091f63adc4a71800000000000000000000000000000000000000000000000000000000000000000000000000000000000000
com.testing.app.debug D/BeaconParser: Ignoring pdu type 01
com.testing.app.debug D/BeaconManager: Unbinding
com.testing.app.debug D/BeaconParser: Ignoring pdu type 0A
com.testing.app.debug D/BeaconParser: Processing pdu type FF: 02011a020a0c0cff4c001007091f63adc4a71800000000000000000000000000000000000000000000000000000000000000000000000000000000000000 with startIndex: 8, endIndex: 18
com.testing.app.debug D/BeaconParser: This is not a matching Beacon advertisement. Was expecting aa fe at offset 8 and 00 at offset 10.  The bytes I see are: 02011a020a0c0cff4c001007091f63adc4a71800000000000000000000000000000000000000000000000000000000000000000000000000000000000000
--
--
? I/hwservicemanager: getTransport: Cannot find entry vendor.qti.hardware.servicetracker@1.0::IServicetracker/default in either framework or device manifest.
com.testing.app.debug D/BeaconManager: Before unbind, consumer count is 2
com.testing.app.debug D/BeaconManager: After unbind, consumer count is 1
com.testing.app.debug D/BeaconManager: Unbinding
com.testing.app.debug D/BeaconManager: Before unbind, consumer count is 1
com.testing.app.debug D/BeaconManager: After unbind, consumer count is 0
? D/NotificationListener: onNotificationRemoved# hash: 121573583
--
--
com.testing.app.debug D/BluetoothLeScanner: could not find callback wrapper
com.testing.app.debug D/CycledLeScanner: Set a wakeup alarm to go off in 9223372035548721603 ms: PendingIntent{ea20162: android.os.BinderProxy@226aef6}
com.testing.app.debug I/CycledLeScanner: Adjusted scanStopTime to be 1306052855
com.testing.app.debug I/BeaconService: unbinding so destroying self
com.testing.app.debug E/BeaconService: onDestroy()
com.testing.app.debug I/BeaconService: onDestroy called.  stopping scanning
com.testing.app.debug D/CycledLeScanner: stop called
--
--
com.testing.app.debug I/BeaconService: starting with intent Intent { cmp=com.testing.app.debug/org.altbeacon.beacon.service.BeaconService }
com.testing.app.debug E/SensorManager: registerListenerImpl sensorName:BMI160 Accelerometer,isWakeUpSensor:false,callingApp: com.testing.app.debug,callingPid:11973,callingUid:11150
com.testing.app.debug I/BeaconService: starting with intent Intent { cmp=com.testing.app.debug/org.altbeacon.beacon.service.BeaconService }
com.testing.app.debug I/BeaconService: binding
com.testing.app.debug D/BeaconManager: we have a connection to the service now
com.testing.app.debug D/BeaconManager: Not synchronizing settings to service, as it is in the same process
com.testing.app.debug D/AppStarter: Activating background region monitoring
--
--
? D/AudioFlinger: AudioFlinger::setRecordSilenced(uid:10048, silenced:0)
com.testing.app.debug D/BeaconManager: callback packageName: com.testing.app.debug
? D/AudioFlinger: AudioFlinger::setRecordSilenced(uid:10048, silenced:0)
com.testing.app.debug D/BeaconManager: Unbinding
? I/hwservicemanager: getTransport: Cannot find entry vendor.qti.hardware.servicetracker@1.0::IServicetracker/default in either framework or device manifest.
? I/hwservicemanager: getTransport: Cannot find entry vendor.qti.hardware.servicetracker@1.0::IServicetracker/default in either framework or device manifest.
com.testing.app.debug D/BeaconManager: Before unbind, consumer count is 2
--
--
? I/hwservicemanager: getTransport: Cannot find entry vendor.qti.hardware.servicetracker@1.0::IServicetracker/default in either framework or device manifest.
com.testing.app.debug D/BeaconManager: Before unbind, consumer count is 2
com.testing.app.debug D/BeaconManager: After unbind, consumer count is 1
com.testing.app.debug D/BeaconManager: Unbinding
com.testing.app.debug D/BeaconManager: Before unbind, consumer count is 1
com.testing.app.debug D/BeaconManager: After unbind, consumer count is 0
com.testing.app.debug I/BeaconService: stop monitoring received
--
--
? D/OpPreventModeCtrl: onPanelExpandedChange expandtrue mPreventModeActive:false
com.testing.app.debug D/CycledLeScanner: Set a wakeup alarm to go off in 9223372035548717398 ms: PendingIntent{e9fcbe5: android.os.BinderProxy@226aef6}
com.testing.app.debug I/CycledLeScanner: Adjusted scanStopTime to be 1306056477
com.testing.app.debug I/BeaconService: unbinding so destroying self
? I/BtGatt.ScanManager: msg.what = 1
? D/vendor.qti.bluetooth@1.0-ibs_handler: SerialClockVote: vote for UART CLK ON
? I/vendor.qti.bluetooth@1.0-ibs_handler: DeviceWakeUp: Writing IBS_WAKE_IND
--
--
com.testing.app.debug D/BeaconManager: This consumer is not bound.  Binding now: com.testing.location.LocationEngine@547e3de
com.testing.app.debug D/BeaconManager: Binding to service
com.testing.app.debug I/BeaconManager: Starting foreground beacon scanning service.
com.testing.app.debug I/BeaconService: binding
com.testing.app.debug D/BeaconManager: consumer count is now: 2
com.testing.app.debug I/BeaconService: starting with intent Intent { cmp=com.testing.app.debug/org.altbeacon.beacon.service.BeaconService }
com.testing.app.debug D/BeaconManager: we have a connection to the service now
--
--
? I/APM_AudioPolicyManager: getNewOutputDevices selected devices {type:0x2,@:}
? D/APM_AudioPolicyManager: startOutput()-- newDevice={type:0x2,@:}
com.testing.app.debug D/BeaconManager: callback packageName: com.testing.app.debug
com.testing.app.debug D/BeaconManager: Unbinding
? I/hwservicemanager: getTransport: Cannot find entry vendor.qti.hardware.servicetracker@1.0::IServicetracker/default in either framework or device manifest.
? W/ActivityManager: Bringing down service while still waiting for start foreground: ServiceRecord{58b3224 u0 com.testing.app.debug/org.altbeacon.beacon.service.BeaconService}
? I/hwservicemanager: getTransport: Cannot find entry vendor.qti.hardware.servicetracker@1.0::IServicetracker/default in either framework or device manifest.
--
--
? I/hwservicemanager: getTransport: Cannot find entry vendor.qti.hardware.servicetracker@1.0::IServicetracker/default in either framework or device manifest.
com.testing.app.debug D/BeaconManager: Before unbind, consumer count is 2
com.testing.app.debug D/BeaconManager: After unbind, consumer count is 1
com.testing.app.debug D/BeaconManager: Unbinding
com.testing.app.debug D/BeaconManager: Before unbind, consumer count is 1
com.testing.app.debug D/BeaconManager: After unbind, consumer count is 0
com.testing.app.debug I/BeaconService: stop monitoring received
--
--
? D/vendor.qti.bluetooth@1.0-ibs_handler: SerialClockVote: vote for UART CLK OFF
com.testing.app.debug D/CycledLeScanner: Set a wakeup alarm to go off in 9223372035548711213 ms: PendingIntent{8052db: android.os.BinderProxy@226aef6}
com.testing.app.debug I/CycledLeScanner: Adjusted scanStopTime to be 1306060648
com.testing.app.debug I/BeaconService: unbinding so destroying self
? D/NotificationListener: onNotificationRemoved# hash: 121573583
? D/NotificationListener: onNotificationRemoved# sbn: 68632927, package = com.testing.app.debug
com.testing.app.debug E/BeaconService: onDestroy()
felipesaruhashi commented 3 years ago

Thanks for the response @davidgyoung ! I will consider that to handle that...

To reproduce the bug I had to stop/restart quite often in a short period of time.

felipesaruhashi commented 3 years ago

Since this specific flow, it is out of the library scope, I will close the issue.