Restart health services if no updates received in 30 minutes

[dshokouhi]

Summary

This is an attempt to fix #3112 by keeping track of the last update received and restarting health services if its been 30 minutes since an update. I feel 30 minutes will be a good time period as there are really no other ways to detect the updates stopping. More than likely if a user only has User Activity State they will probably see the callback registering more frequently as a result of this change. I suspect when this issue occurs it impacts all things registered with the callback so best to include activity state.

Screenshots

Link to pull request in Documentation repository

Documentation: home-assistant/companion.home-assistant#

Any other notes

[dshokouhi]

I feel for this PR we should get some feedback from users but at the same time we know restart logic like this works pretty well since we do something similar with location updates and other sensors. At least in my own experience I have yet to see the updates stop like the users are mentioning. Will leave as a draft for now to see if we can get some feedback otherwise will mark as ready for review (unless we feel this is good enough to add anyways then lets just move forward with ensuring we are getting updates).

[dshokouhi]

I think I finally managed to catch this issue. What it appears to be happening is that health services crashes, once it recovers it seems to register back but not all data is restored.

2022-12-02 09:44:03.465 22349-22349 HealthServices          pid-22349                            D  New data point received: [DataType(name=Daily Distance, timeType=INTERVAL, class=Double, isAggregate=false)]
2022-12-02 09:44:03.466 22349-22349 HealthServices          pid-22349                            D  Data for Daily Distance index: 0 with value: 484.1484375 end time: 1670003043340
2022-12-02 09:44:03.466 22349-22349 HealthServices          pid-22349                            D  daily_distance data index: 0 with value: 484.1484375 end time: 1670003043341
2022-12-02 09:44:20.202 27988-3881  ServiceConnection       pid-27988                            W  Binder died for client:HealthServicesVersionClient
2022-12-02 09:44:20.247 27988-3881  ServiceConnection       pid-27988                            W  WCS SDK Client 'HealthServicesVersionClient' disconnected, retrying connection. Retry attempt: 0
                                                                                                    java.util.concurrent.CancellationException
                                                                                                    	at androidx.health.services.client.impl.ipc.internal.ServiceConnection.lambda$cleanOnDeath$0$androidx-health-services-client-impl-ipc-internal-ServiceConnection(PG:2)
                                                                                                    	at androidx.health.services.client.impl.ipc.internal.ServiceConnection$$ExternalSyntheticLambda0.binderDied(Unknown Source:2)
                                                                                                    	at android.os.IBinder$DeathRecipient.binderDied(IBinder.java:305)
                                                                                                    	at android.os.BinderProxy.sendDeathNotice(BinderProxy.java:685)
2022-12-02 09:44:25.744 27988-28028 WHS_Passiv...Dispatcher pid-27988                            W  Dispatching data points to passive monitoring callback failed.
                                                                                                    android.os.DeadObjectException
                                                                                                    	at android.os.BinderProxy.transactNative(Native Method)
                                                                                                    	at android.os.BinderProxy.transact(BinderProxy.java:571)
                                                                                                    	at aah.transactOneway(PG:1)
                                                                                                    	at androidx.health.services.client.impl.IPassiveListenerCallback$Stub$Proxy.onPassiveListenerEvent(PG:3)
                                                                                                    	at com.google.android.wearable.healthservices.passivemonitoring.dispatcher.PassiveListenerCallbackDispatcher.dispatch(PG:56)
                                                                                                    	at com.google.android.wearable.healthservices.passivemonitoring.dispatcher.ListenerManager.dispatchPassiveMonitoringData(PG:4)
                                                                                                    	at com.google.android.wearable.healthservices.passivemonitoring.dispatcher.ListenerManager.onPassiveMonitoringData(PG:4)
                                                                                                    	at com.google.android.wearable.healthservices.passivemonitoring.dispatcher.SettableDataListener.lambda$onPassiveMonitoringData$1(PG:1)
                                                                                                    	at com.google.android.wearable.healthservices.passivemonitoring.dispatcher.SettableDataListener$$ExternalSyntheticLambda2.accept(Unknown Source:4)
                                                                                                    	at j$.util.Optional.ifPresent(Unknown Source:4)
                                                                                                    	at com.google.android.wearable.healthservices.passivemonitoring.dispatcher.SettableDataListener.onPassiveMonitoringData(PG:1)
                                                                                                    	at com.google.android.wearable.healthservices.common.listener.MultiDataListener.onPassiveMonitoringData(PG:2)
                                                                                                    	at com.google.android.wearable.healthservices.tracker.defaultmanager.SimpleTrackerProfileManager.lambda$onPassiveData$51$com-google-android-wearable-healthservices-tracker-defaultmanager-SimpleTrackerProfileManager(PG:2)
                                                                                                    	at com.google.android.wearable.healthservices.tracker.defaultmanager.SimpleTrackerProfileManager$$ExternalSyntheticLambda71.run(Unknown Source:4)
                                                                                                    	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:923)
2022-12-02 09:45:00.043 30848-30848 ServiceConnection       pid-30848                            D  onServiceConnected(), componentName = ComponentInfo{com.google.android.wearable.healthservices/com.google.android.wearable.healthservices.passivemonitoring.client.PassiveMonitoringApiService}
2022-12-02 09:45:00.084 30848-30848 HealthServices          pid-30848                            D  Health services callback successfully registered for the following data types: [DataType(name=Daily Floors, timeType=INTERVAL, class=Double, isAggregate=false), DataType(name=Daily Distance, timeType=INTERVAL, class=Double, isAggregate=false), DataType(name=Daily Calories, timeType=INTERVAL, class=Double, isAggregate=false), DataType(name=Daily Steps, timeType=INTERVAL, class=Long, isAggregate=false)] User Activity Info: true Health Events: []
2022-12-02 09:45:00.092 30848-30848 HealthServices          pid-30848                            D  User activity state: USER_ACTIVITY_PASSIVE
2022-12-02 09:45:00.119 30848-30848 HealthServices          pid-30848                            D  User activity state: USER_ACTIVITY_PASSIVE

After this no log statements were printed for daily calories which updates once per minute on a Pixel Watch. So this intended fix should be good here. Not entirely sure how to reproduce this as in this case teh issue happened moving my watch off and on charger.

[dshokouhi]

I have tried to replicate this issue by force stopping Health Services however the call back is restored properly then and data continues to flow in. This crash of health services must be occurring elsewhere. The restart logic should take care of this.

2022-12-02 10:22:26.877 30848-30911 ServiceConnection       pid-30848                            D  Listeners for service HealthServicesPassiveMonitoringClient are registered, reconnecting.

[dshokouhi]

submitted a bug to the library as well, hopefully they can reproduce it 🤞

https://issuetracker.google.com/issues/261119535

For now I think for us the proper path forward is to use this restart logic like we do elsewhere.

[dshokouhi]

Been running this debug build for several days to see if I can catch a moment where production stops and debug continues. The only time I saw it happen was after an app update (as strange as that sounds) where I needed to force stop the app and open it again. The debug build was able to recover on its own without interference. I am not sure what happens during an app update where updates seemingly stop, maybe its similar to the above issue where Health Services attempts to restore the connection and it fails? At the same time we also attempt to register with health services, either way if there is a conflict its good that we correct it on our end.

So the only real concern here would be if a user only has activity state enabled because in those cases we will probably re-register the callback often. That may potentially also impact any of the daily sensors that don't report often either. There is no harm in registering and unregistering the callback so its good to keep things current like we do with location updates on the phone.

[jpelgrom]

So the only real concern here would be if a user only has activity state enabled because in those cases we will probably re-register the callback often.

Does re-registering also deliver new activity info to the app? If so, if I understand it correctly, it will basically force an update of the sensors every 30 min which seems wasteful and a check should be added to see if the value changed before attempting to push an update in onUserActivityInfoReceived (here).

[dshokouhi]

So the only real concern here would be if a user only has activity state enabled because in those cases we will probably re-register the callback often.

Does re-registering also deliver new activity info to the app?

Yes we do get an update immediately for this sensor

If so, if I understand it correctly, it will basically force an update of the sensors every 30 min which seems wasteful and a check should be added to see if the value changed before attempting to push an update in onUserActivityInfoReceived (here).

So we actually keep track of the callback registration to prevent a loop. The issue I was trying to explain was that Activity state only updates when the state changes and this sensor really only updates 2-3 times a day, maybe more if a user is exercising. So about every 30 minutes we will be re-registering the callback if only this sensor is enabled, the other health services sensors seem to report a little more frequently.

[jpelgrom]

So we actually keep track of the callback registration to prevent a loop.

This is good, but I wasn't suggesting there is a loop, just unnecessary updates.

Yes we do get an update immediately for this sensor

So about every 30 minutes we will be re-registering the callback if only this sensor is enabled, the other health services sensors seem to report a little more frequently.

An immediate update + re-registering every 30 minutes if only the activity state sensor is enabled for health services (because it does not update frequently enough) means that a new value is delivered to onUserActivityInfoReceived on every reregistration/every 30 minutes. This in turn means it pushes updates for all sensors every 30 minutes because that function ends with SensorReceiver.updateAllSensors(latestContext) regardless of whether there was a new state or not.

Because re-registering happens because of the sensor worker this means two updates shortly after another, one of which likely doesn't have any differences.

[dshokouhi]

Ah yes I see what you mean, ok I will add a check to determine if an update needs to be sent immediately or not since we do force an update when exercise type changes too.

[jpelgrom]

Can't do full testing without a real watch, but the code looks good to me and it follows the same approach as used for making sure other callbacks don't get stuck.

[SkechyWolf]

I've been testing this the past few days (since Dec 1st) and all has been good even seemed to help the main version to keep updating I uninstalled the debug version yesterday (12/05/22) and overnight the Main HA app stopped pushing activity state updates