android
android copied to clipboard
home-assistant
Unable to (re)start WebsocketManager on screen on due to background restrictions
Home Assistant Android version: beta-1944-6994eacf
Android version: 12
Phone model: Google Pixel 4a
Home Assistant version: Core 2021.12.10
Last working Home Assistant release (if known): n/a, new feature
Description of problem: I upgraded to the beta version directly from the latest stable release (2022.1.1). No settings changed for websocket notifications (so: connect while screen is on). I noticed that the notification that the app was connected didn't come up after picking up my phone again. Logcat shows an error (see below) which is caused by the Android 12 background start restrictions.
Traceback (if applicable, to get the logs you may refer to: https://companion.home-assistant.io/docs/troubleshooting/faqs/#android-crash-logs):
Slightly edited to start when the screen turns on, and to include a message from the ActivityManager
2022-01-19 21:04:29.999 9988-9988/? D/SensorReceiver: Sensor is_interactive corresponding to received event android.intent.action.SCREEN_ON is disabled, skipping sensors update
2022-01-19 21:04:30.002 9988-9988/? D/ButtonWidget: Broadcast received:
Broadcast action: android.intent.action.SCREEN_ON
AppWidgetId: -1
2022-01-19 21:04:30.002 9988-9988/? D/ButtonWidget: Updating all widgets
2022-01-19 21:04:30.048 9988-9988/? D/UrlRepository: localUrl is: true and usesInternalSsid is: true
2022-01-19 21:04:30.058 9988-9988/? D/MediaPlayCtrlsWidget: Broadcast received:
Broadcast action: android.intent.action.SCREEN_ON
AppWidgetId: -1
2022-01-19 21:04:30.063 9988-9988/? D/UrlRepository: localUrl is: true and usesInternalSsid is: true
2022-01-19 21:04:30.071 9988-9988/? D/UrlRepository: localUrl is: true and usesInternalSsid is: true
2022-01-19 21:04:30.093 9988-10057/? D/WebSockManager: Starting to listen to Websocket
2022-01-19 21:04:30.098 9988-10073/? I/WM-Processor: Moving WorkSpec (2698abf6-4e72-456d-b0bd-09ec4047eb87) to the foreground
2022-01-19 21:04:30.114 9988-10069/? E/WM-WorkerWrapper: Work [ id=2698abf6-4e72-456d-b0bd-09ec4047eb87, tags={ io.homeassistant.companion.android.websocket.WebsocketManager } ] failed because it threw an exception/error
java.util.concurrent.ExecutionException: android.app.ForegroundServiceStartNotAllowedException: startForegroundService() not allowed due to mAllowStartForeground false: service io.homeassistant.companion.android/androidx.work.impl.foreground.SystemForegroundService
at androidx.work.impl.utils.futures.AbstractFuture.getDoneValue(AbstractFuture.java:516)
at androidx.work.impl.utils.futures.AbstractFuture.get(AbstractFuture.java:475)
at androidx.work.impl.WorkerWrapper$2.run(WorkerWrapper.java:311)
at androidx.work.impl.utils.SerialExecutor$Task.run(SerialExecutor.java:91)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1167)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641)
at java.lang.Thread.run(Thread.java:920)
Caused by: android.app.ForegroundServiceStartNotAllowedException: startForegroundService() not allowed due to mAllowStartForeground false: service io.homeassistant.companion.android/androidx.work.impl.foreground.SystemForegroundService
at android.app.ForegroundServiceStartNotAllowedException$1.createFromParcel(ForegroundServiceStartNotAllowedException.java:54)
at android.app.ForegroundServiceStartNotAllowedException$1.createFromParcel(ForegroundServiceStartNotAllowedException.java:50)
at android.os.Parcel.readParcelable(Parcel.java:3333)
at android.os.Parcel.createExceptionOrNull(Parcel.java:2420)
at android.os.Parcel.createException(Parcel.java:2409)
at android.os.Parcel.readException(Parcel.java:2392)
at android.os.Parcel.readException(Parcel.java:2334)
at android.app.IActivityManager$Stub$Proxy.startService(IActivityManager.java:5971)
at android.app.ContextImpl.startServiceCommon(ContextImpl.java:1847)
at android.app.ContextImpl.startForegroundService(ContextImpl.java:1823)
at android.content.ContextWrapper.startForegroundService(ContextWrapper.java:779)
at androidx.core.content.ContextCompat$Api26Impl.startForegroundService(ContextCompat.java:931)
at androidx.core.content.ContextCompat.startForegroundService(ContextCompat.java:703)
at androidx.work.impl.Processor.startForeground(Processor.java:161)
at androidx.work.impl.utils.WorkForegroundUpdater$1.run(WorkForegroundUpdater.java:100)
at androidx.work.impl.utils.SerialExecutor$Task.run(SerialExecutor.java:91)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1167)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641)
at java.lang.Thread.run(Thread.java:920)
Caused by: android.os.RemoteException: Remote stack trace:
at com.android.server.am.ActiveServices.startServiceLocked(ActiveServices.java:691)
at com.android.server.am.ActiveServices.startServiceLocked(ActiveServices.java:616)
at com.android.server.am.ActivityManagerService.startService(ActivityManagerService.java:11850)
at android.app.IActivityManager$Stub.onTransact(IActivityManager.java:2519)
at com.android.server.am.ActivityManagerService.onTransact(ActivityManagerService.java:2498)
2022-01-19 21:04:30.115 9988-10069/? I/WM-WorkerWrapper: Worker result FAILURE for Work [ id=2698abf6-4e72-456d-b0bd-09ec4047eb87, tags={ io.homeassistant.companion.android.websocket.WebsocketManager } ]
2022-01-19 21:04:30.118 1740-2686/? W/ActivityManager: Background start not allowed: service Intent { act=ACTION_STOP_FOREGROUND cmp=io.homeassistant.companion.android/androidx.work.impl.foreground.SystemForegroundService } to io.homeassistant.companion.android/androidx.work.impl.foreground.SystemForegroundService from pid=9988 uid=10365 pkg=io.homeassistant.companion.android startFg?=false
2022-01-19 21:04:30.118 9988-10069/? E/WM-Processor: Unable to stop foreground service
android.app.BackgroundServiceStartNotAllowedException: Not allowed to start service Intent { act=ACTION_STOP_FOREGROUND cmp=io.homeassistant.companion.android/androidx.work.impl.foreground.SystemForegroundService }: app is in background uid UidRecord{f43bc62 u0a365 TRNB idle procs:0 seq(0,0,0)}
at android.app.ContextImpl.startServiceCommon(ContextImpl.java:1861)
at android.app.ContextImpl.startService(ContextImpl.java:1817)
at android.content.ContextWrapper.startService(ContextWrapper.java:774)
at androidx.work.impl.Processor.stopForegroundService(Processor.java:318)
at androidx.work.impl.Processor.stopForeground(Processor.java:224)
at androidx.work.impl.WorkerWrapper.resolve(WorkerWrapper.java:460)
at androidx.work.impl.WorkerWrapper.resetPeriodicAndResolve(WorkerWrapper.java:571)
at androidx.work.impl.WorkerWrapper.handleResult(WorkerWrapper.java:490)
at androidx.work.impl.WorkerWrapper.onWorkFinished(WorkerWrapper.java:354)
at androidx.work.impl.WorkerWrapper$2.run(WorkerWrapper.java:331)
at androidx.work.impl.utils.SerialExecutor$Task.run(SerialExecutor.java:91)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1167)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641)
at java.lang.Thread.run(Thread.java:920)
Screenshot of problem:
Additional information:
Looking at the possible exemptions I think the only reasonable option is to catch this error and show a notification asking the user to disable battery optimizations for the app?
Hmm we do normally ask users to grant the app background access otherwise location and sensor updates can fail, we should probably require it as part of websockets?
We can check for battery optimizations and just open a notification with 2 actions.
- Disable Battery Optimizations for app
- Open setting for websocket so user can disable.
Do we change the default based on that setting as well then?
Do we change the default based on that setting as well then?
good question, I am honestly not sure because its almost like a troubleshooting step but also a requirement for notifications to work properly.
I like the notification with actions idea :)
Hmm we do normally ask users to grant the app background access otherwise location and sensor updates can fail
Just set up a new install of the app and (at least with a local build) it only asks me this when enabling location tracking, not always. Definitely something that should be added when running on Android 12+ if we want to enable websocket notifications by default.
We can check for battery optimizations and just open a notification with 2 actions. (...)
A notification is also nice in case the user changes the setting (or updates the app and doesn't see onboarding again) so they know it isn't working.
Do we change the default based on that setting as well then?
It might be nice to change the setting to never if the app receives a ForegroundServiceStartNotAllowedException multiple times? If it is just once the user will need time (and the notication to remind them) to fix it, but if it happens 5 times in a row the user is likely not going to change it in the Android settings.
Definitely something that should be added when running on Android 12+ if we want to enable websocket notifications by default.
yea we should probably consider adding it to onboarding for all builds/versions because its also important for sensors even if a user doesn't want location tracking enabled and now with notifications its more important. What I meant earlier was that when it comes to troubleshooting thats usually the issue when things stop communicating.
It might be nice to change the setting to never if the app receives a
ForegroundServiceStartNotAllowedExceptionmultiple times? If it is just once the user will need time (and the notication to remind them) to fix it, but if it happens 5 times in a row the user is likely not going to change it in the Android settings.
its probably best to reflect it in the settings page in case a user is curious why its not working properly so we can just let them know. That should be the first place a user looks to troubleshoot issues.
Looking at Sentry I can see this issue is impacting a good chunk of users (~36k) generating a few hundred thousand events. Maybe we should avoid calling setForeground when we don't have permissions and maybe post a notification so the user can grant background access to restore supported behavior?
That is a lot of users! I guess most of those people don't even know the feature is on (so from the initial 2022.2 release)?
It looks like we can catch this exception, working on catching it -> show a notification -> direct users to settings where they can turn it off or grant unrestricted background access.
(so from the initial 2022.2 release)?
first occurrence
beta-1576-e1cc6c8
Right, this probably also applies to the Sensorworker on Android 12. That one can work without unrestricted background permissions, just less reliably, so a check like you suggested makes more sense for that use case.
(High accuracy location should be fine because that is always in response to geofence / high priority FCM messages / Bluetooth intents which are exempted.)
(High accuracy location should be fine because that is always in response to geofence / high priority FCM messages / Bluetooth intents which are exempted.)
yup and also safe to assume in those cases user had already granted background permissions as we request them with enabling location tracking.
I've submitted two PRs to handle this issue. In testing catching the exceptions seems to work.
However I've also found a related issue in WorkManager which suggests that some of these crashes might be from inside the library, out of our control. So while testing, catching the exceptions seems to work but it may not solve 100% of the reports? A fix has been merged a few days ago.
@dshokouhi You could compare the stack traces in Sentry to confirm if those 36k users are experiencing the same issue as I originally reported in January or the one in the Google issue tracker. This issue is originating in android.app.ContextImpl.startForegroundService, the Google issue tracker one in androidx.work.impl.foreground.SystemForegroundService -> android.app.Service.startForeground.
@dshokouhi You could compare the stack traces in Sentry to confirm if those 36k users are experiencing the same issue as I originally reported in January or the one in the Google issue tracker. This issue is originating in
android.app.ContextImpl.startForegroundService, the Google issue tracker one inandroidx.work.impl.foreground.SystemForegroundService -> android.app.Service.startForeground.
yup looks to be the same from the google issue tracker:
android.app.ForegroundServiceStartNotAllowedException: Service.startForeground() not allowed due to mAllowStartForeground false: service io.homeassistant.companion.android/androidx.work.impl.foreground.SystemForegroundService
at android.app.ForegroundServiceStartNotAllowedException$1.createFromParcel(ForegroundServiceStartNotAllowedException.java:54)
at android.app.ForegroundServiceStartNotAllowedException$1.createFromParcel(ForegroundServiceStartNotAllowedException.java:50)
at android.os.Parcel.readParcelable(Parcel.java:3334)
at android.os.Parcel.createExceptionOrNull(Parcel.java:2421)
at android.os.Parcel.createException(Parcel.java:2410)
at android.os.Parcel.readException(Parcel.java:2393)
at android.os.Parcel.readException(Parcel.java:2335)
at android.app.IActivityManager$Stub$Proxy.setServiceForeground(IActivityManager.java:7158)
at android.app.Service.startForeground(Service.java:790)
at androidx.work.impl.foreground.SystemForegroundService$1.run(SystemForegroundService.java:124)
at android.os.Handler.handleCallback(Handler.java:938)
at android.os.Handler.dispatchMessage(Handler.java:99)
at android.os.Looper.loopOnce(Looper.java:201)
at android.os.Looper.loop(Looper.java:288)
at android.app.ActivityThread.main(ActivityThread.java:7870)
at java.lang.reflect.Method.invoke(Method.java)
at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:548)
at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:1003)